log plugin

[hnakamur]

First of all, thanks for creating and sharing a nice software!

I would like to have log plugin which will log requests and responses using github.com/go-kit/kig/log.Logger interface.

I tried to create such a plugin myself, but I'm stuck now.

Here is an example usage.

package main

import (
        "log"
        "os"

        kitlog "github.com/go-kit/kit/log"
        "github.com/h2non/gentleman"
        "github.com/h2non/gentleman/plugins/auth"
        genlog "github.com/hnakamur/gentleman-log"
)

func main() {
        logger := kitlog.NewLogfmtLogger(os.Stdout)
        host := "http://localhost:8529"
        user := "root"
        password := "root"
        cli := gentleman.New()
        cli.Use(genlog.Logger(logger))
        cli.URL(host)
        cli.Use(auth.Basic(user, password))
        resp, err := cli.Request().Path("/_db/_system/_api/version").Send()
        if err != nil {
                log.Printf("got error. err=%v", err)
        }
        if !resp.Ok {
                log.Printf("bad status. status=%v", resp.StatusCode)
        }
}

Here is my plugin code.

package log

import (
        kitlog "github.com/go-kit/kit/log"
        c "gopkg.in/h2non/gentleman.v1/context"
        p "gopkg.in/h2non/gentleman.v1/plugin"
)
func Logger(logger kitlog.Logger) p.Plugin {
        return p.NewResponsePlugin(func(ctx *c.Context, h c.Handler) {
                h.Next(ctx)
                req := ctx.Request
                res := ctx.Response
                // payload := ... // request body
                // body := ... // response body
                logger.Log("method", req.Method, "url", req.URL, "payload", payload, "status", res.StatusCode, "body", body)
        })
}

Could you tell me how to retrieve the request body and the response body?

[h2non]

Basically, you've to read and cache both bodies io.ReadCloser streams before they are processed by its final consumers, in this case the HTTP package itself. Given the design efficient nature of the streams in Go (an many other languages), once a stream consumer reads a chunk of data, the data itself is flushed and it will be available for GC free.

In certain scenarios you have to do some pre/post processing of steams data, so the typical strategy would be reading the whole stream, caching it and create a new stream to replace the original, already used one.

You can achieve this via ioutil.ReadAll(). I do this multiple times in gentleman codebase. I use this helper function when I want to create a new io.ReadCloser stream from a buffer or string.

Also, in order to read the response body data, you should perform all of this process before the h.Next(ctx) call. To read the request body, I would suggest writing a simple middleware handler function for the request phase responsible of reading the whole request body and exposing it via context.Set("req.body", buf). You should do this in the request phase before the HTTP dispatcher process the Request instance.

I hope this help.

[hnakamur]

Thanks for your detailed explanation. I helps me a lot!
I can read the response body now, but I cannot read the request body.

package main

import (
        "bytes"
        "io/ioutil"
        "log"
        "os"
        "reflect"

        kitlog "github.com/go-kit/kit/log"
        "github.com/h2non/gentleman"
        "github.com/h2non/gentleman/plugins/auth"
        genlog "github.com/hnakamur/gentleman-log"
        c "gopkg.in/h2non/gentleman.v1/context"
)

func main() {
        logger := kitlog.NewLogfmtLogger(os.Stdout)
        host := "http://localhost:8529"
        user := "root"
        password := "root"
        cli := gentleman.New()
        reqKey := "req.body"
        //cli.Use(genlog.RequestSaver(reqKey))
        cli.UseHandler("request", func(ctx *c.Context, h c.Handler) {
                var body []byte
                log.Printf("RequestSaver. ctx.Request.Body=%v, body type=%v", ctx.Request.Body, reflect.ValueOf(ctx.Request.Body).Type())
                if ctx.Request.Body != nil {
                        var err error
                        body, err = ioutil.ReadAll(ctx.Request.Body)
                        if err != nil {
                                h.Error(ctx, err)
                                return
                        }
                        ctx.Request.Body = ioutil.NopCloser(bytes.NewBuffer(body))
                }
                log.Printf("RequestSaver. body=%s", string(body))
                ctx.Set(reqKey, body)

                h.Next(ctx)
        })
        cli.Use(genlog.Logger(logger, reqKey))
        cli.URL(host)
        cli.Use(auth.Basic(user, password))
        //resp, err := cli.Request().Path("/_db/_system/_api/version").JSON(map[string]string{"dummy": "not_used"}).Send()
        resp, err := cli.Request().Path("/_db/_system/_api/version").BodyString(`{"dummy":"not_used"}`).Send()
        if err != nil {
                log.Printf("got error. err=%v", err)
        }
        if !resp.Ok {
                log.Printf("bad status. status=%v", resp.StatusCode)
        }
}

package log

import (
        "bytes"
        "io/ioutil"
        "log"
        "reflect"

        kitlog "github.com/go-kit/kit/log"
        c "gopkg.in/h2non/gentleman.v1/context"
        p "gopkg.in/h2non/gentleman.v1/plugin"
)       

func RequestSaver(reqKey string) p.Plugin {
        return p.NewRequestPlugin(func(ctx *c.Context, h c.Handler) {
                var body []byte
                log.Printf("RequestSaver. ctx.Request.Body=%v, body type=%v", ctx.Request.Body, reflect.ValueOf(ctx.Request.Body).Type())
                if ctx.Request.Body != nil {
                        var err error
                        body, err = ioutil.ReadAll(ctx.Request.Body)
                        if err != nil {
                                h.Error(ctx, err)
                                return
                        }
                        ctx.Request.Body = ioutil.NopCloser(bytes.NewBuffer(body))
                }
                log.Printf("RequestSaver. body=%s", string(body))
                ctx.Set(reqKey, body)

                h.Next(ctx)
        })              
}                               

func Logger(logger kitlog.Logger, reqKey string) p.Plugin {
        return p.NewResponsePlugin(func(ctx *c.Context, h c.Handler) {
                req := ctx.Request
                res := ctx.Response
                var reqBody []byte
                reqBodyVal := ctx.Get(reqKey)
                if reqBodyVal != nil {
                        reqBody = reqBodyVal.([]byte)
                }

                var resBody []byte
                if res.Body != nil {
                        var err error
                        resBody, err = ioutil.ReadAll(res.Body)
                        if err != nil {
                                h.Error(ctx, err)
                                return
                        }
                        res.Body = ioutil.NopCloser(bytes.NewBuffer(resBody))
                }
                h.Next(ctx)
                logger.Log("method", req.Method, "url", req.URL, "payload", string(reqBody), "status", res.StatusCode, "body", string(resBody))
        })
}

I don't know the difference between middlewares and plugins, so I tried both. The plugin case is comment-outed above at the line //cli.Use(genlog.RequestSaver(reqKey)).
The output for both cases was the same.

$ go run main.go
2016/07/18 19:19:02 RequestSaver. ctx.Request.Body=&{{} map[$phase:request]}, body type=*context.contextReadCloser
2016/07/18 19:19:02 RequestSaver. body=
method=POST url=http://localhost:8529/_db/_system/_api/version payload= status=200 body="{\"server\":\"arango\",\"version\":\"3.0.2\"}"

Could you give me advice?
Thanks!

[h2non]

I don't know the difference between middlewares and plugins.

gentleman is plugin-driven, but plugins require a bit of interface overhead, so middleware handlers are the simplified version of a phase-specific plugin without constructor/interface overhead, just define the phase name and function to execute. This is simply provided for convenience, but behind the scenes all are plugins.

You code is fine. The problem is due the plugin registration priority. Effectively, gentleman has no explicit plugin priority as sort of priority queue structure, so the execution order is defined by the developer, behaving as a simple FIFO queue. Since gentleman is fully plugin-driven, this affects to the whole library.

In this case you're registering the request log plugin before the body is defined to the Request instance, so that's why you can't read it.

Solutions:

• You can follow the same approach, but registering the request log plugin after the body definition. This is not always great due to boilerplate. Example:

cli.Request().
  Path("/_db/_system/_api/version").
  BodyString(`{"dummy":"not_used"}`).
  Use(genlog.RequestSaver(reqKey)).
  Send()

• Alternatively, you can write your own plugin to define the Body and cache it via Context, making it available for the response phase.
• Or you can even simply expose the Request body via Context directly in the Request instance:

body := `{"dummy":"not_used"}`
req := cli.Request()
req.Path("/_db/_system/_api/version")
req.Context.Set("req.body", body)
req.Body(body)
req.Send()

There are other approaches, but I think less convenient.

[hnakamur]

Thanks again for your detailed explanation!
This time I can read the request body successfully using your first solution.
I've not tried your other solutions, but I think I found a better alternative, a "before dial" phase plugin.

package main

import (
        "log"
        "os"

        kitlog "github.com/go-kit/kit/log"
        "github.com/h2non/gentleman"
        "github.com/h2non/gentleman/plugins/auth"
        genlog "github.com/hnakamur/gentleman-log"
)       

func main() {   
        logger := kitlog.NewLogfmtLogger(os.Stdout)
        host := "http://localhost:8529"
        user := "root"  
        password := "root"      
        cli := gentleman.New()  
        reqKey := "req.body"
        cli.Use(genlog.RequestSaver(reqKey))
        cli.Use(genlog.Logger(logger, reqKey))
        cli.URL(host)
        cli.Use(auth.Basic(user, password))
        resp, err := cli.Request().Path("/_db/_system/_api/version").BodyString(`{"dummy":"not_used"}`).Send()
        if err != nil {
                log.Printf("got error. err=%v", err)
        }
        if !resp.Ok {
                log.Printf("bad status. status=%v", resp.StatusCode) 
        }       
}   

package log

import (
        "bytes"
        "io/ioutil"

        kitlog "github.com/go-kit/kit/log"
        c "gopkg.in/h2non/gentleman.v1/context"
        p "gopkg.in/h2non/gentleman.v1/plugin"
)       

func RequestSaver(reqKey string) p.Plugin {
        return p.NewPhasePlugin("before dial", func(ctx *c.Context, h c.Handler) {
                var body []byte
                if ctx.Request.Body != nil {
                        var err error
                        body, err = ioutil.ReadAll(ctx.Request.Body)
                        if err != nil {
                                h.Error(ctx, err)
                                return
                        }
                        ctx.Request.Body = ioutil.NopCloser(bytes.NewBuffer(body))
                }
                ctx.Set(reqKey, body)

                h.Next(ctx)
        })
}       

func Logger(logger kitlog.Logger, reqKey string) p.Plugin {
        return p.NewResponsePlugin(func(ctx *c.Context, h c.Handler) {
                req := ctx.Request
                res := ctx.Response
                var reqBody []byte
                reqBodyVal := ctx.Get(reqKey)
                if reqBodyVal != nil {
                        reqBody = reqBodyVal.([]byte)
                }

                var resBody []byte
                if res.Body != nil {
                        var err error
                        resBody, err = ioutil.ReadAll(res.Body)
                        if err != nil {
                                h.Error(ctx, err)
                                return
                        }
                        res.Body = ioutil.NopCloser(bytes.NewBuffer(resBody))
                }
                h.Next(ctx)
                logger.Log("method", req.Method, "url", req.URL, "payload", string(reqBody), "status", res.StatusCode, "body", string(resBody))
        })
}

The output.

$ go run main.go
method=POST url=http://localhost:8529/_db/_system/_api/version payload="{\"dummy\":\"not_used\"}" status=200 body="{\"server\":\"arango\",\"version\":\"3.0.2\"}"

Could you tell me what do you think?

[h2non]

That's the perfect one. I completely forget about the before dialphase :(

If you even want to have a cleaner and more elegant solution, you can write a generic log plugin who will trigger in both phases: before dial and response without registering both plugins twice. You can take a look to existent plugins and plugin package to have a better idea of the implementation details.

[h2non]

Also, if you want to contribute and you're open to, you can create an open source log plugin with a structured, modular design, giving the ability to developers to register its own log handlers, responsible of writing logs events to different outputs, such as stdout, HTTP, statsd, logstash or whatever. That would be awesome!

[hnakamur]

Thanks for your comment.
I updated my implementation.

A sample program.

package main

import (
        "log"
        "net/http"
        "os"

        kitlog "github.com/go-kit/kit/log"
        "github.com/h2non/gentleman"
        "github.com/h2non/gentleman/plugins/auth"
        genlog "github.com/hnakamur/gentleman-log"
        c "gopkg.in/h2non/gentleman.v1/context"
)

func main() {
        logger := kitlog.NewLogfmtLogger(os.Stdout)
        host := "http://localhost:8529"
        user := "root"
        password := "root"
        cli := gentleman.New()
        reqKey := "req.body"
        resKey := "res.body"
        cli.Use(auth.Basic(user, password))
        cli.Use(genlog.SaveBody(reqKey, resKey))
        cli.Use(genlog.Log(reqKey, resKey, func(ctx *c.Context, req *http.Request, res *http.Response, reqBody, resBody []byte) error {
                keyvals := []interface{}{
                        "method", req.Method, "url", req.URL,
                }
                for k, v := range req.Header {
                        for _, vv := range v {
                                keyvals = append(keyvals, "reqHeader."+k, vv)
                        }
                }
                keyvals = append(keyvals,
                        "payload", string(reqBody), "status", res.StatusCode)
                for k, v := range res.Header {
                        for _, vv := range v {
                                keyvals = append(keyvals, "resHeader."+k, vv)
                        }
                }
                keyvals = append(keyvals,
                        "body", string(resBody))
                logger.Log(keyvals...)
                return nil
        }))
        cli.URL(host)
        resp, err := cli.Request().Path("/_db/_system/_api/version").BodyString(`{"dummy":"not_used"}`).Send()
        if err != nil {
                log.Printf("got error. err=%v", err)
        }
        if !resp.Ok {
                log.Printf("bad status. status=%v", resp.StatusCode)
        }
}

log plugin.

package log

import (
        "bytes"
        "io/ioutil"
        "net/http"

        c "gopkg.in/h2non/gentleman.v1/context"
        p "gopkg.in/h2non/gentleman.v1/plugin"
)

func SaveBody(reqKey, resKey string) p.Plugin {
        handleBeforeDial := func(ctx *c.Context, h c.Handler) {
                var body []byte
                if ctx.Request.Body != nil {
                        var err error
                        body, err = ioutil.ReadAll(ctx.Request.Body)
                        if err != nil {
                                h.Error(ctx, err)
                                return
                        }
                        ctx.Request.Body = ioutil.NopCloser(bytes.NewBuffer(body))
                }
                ctx.Set(reqKey, body)

                h.Next(ctx)
        } 
        handleResponse := func(ctx *c.Context, h c.Handler) {
                var body []byte
                if ctx.Response.Body != nil {
                        var err error
                        body, err = ioutil.ReadAll(ctx.Response.Body)
                        if err != nil {
                                h.Error(ctx, err)
                                return
                        }
                        ctx.Response.Body = ioutil.NopCloser(bytes.NewBuffer(body))
                }
                ctx.Set(resKey, body)

                h.Next(ctx)
        }               
        handlers := p.Handlers{
                "before dial": handleBeforeDial,
                "response":    handleResponse,
        }                       
        return &p.Layer{Handlers: handlers}
}

func Log(reqKey, resKey string, logFunc func(ctx *c.Context, req *http.Request, res *http.Response, reqBody, resBody []byte) error) p.Plugin {
        return p.NewResponsePlugin(func(ctx *c.Context, h c.Handler) {
                var reqBody []byte
                reqBodyVal := ctx.Get(reqKey)
                if reqBodyVal != nil {
                        reqBody = reqBodyVal.([]byte)
                }

                var resBody []byte
                resBodyVal := ctx.Get(resKey)
                if resBodyVal != nil {
                        resBody = resBodyVal.([]byte)
                }

                err := logFunc(ctx, ctx.Request, ctx.Response, reqBody, resBody)
                if err != nil {
                        h.Error(ctx, err)
                }

                h.Next(ctx)
        })
}

example output.

$ go run main.go
method=POST url=http://localhost:8529/_db/_system/_api/version reqHeader.User-Agent=gentleman/1.0.0 reqHeader.Authorization="Basic cm9vdDpyb290" payload="{\"dummy\":\"not_used\"}" status=200 resHeader.Server=ArangoDB resHeader.Connection=Keep-Alive resHeader.Content-Typ
e="application/json; charset=utf-8" resHeader.Content-Length=37 body="{\"server\":\"arango\",\"version\":\"3.0.2\"}"

I made two separated plugins SaveBody and Log since users want to save the request body and the response body for other uses than logging.

And yes, I want to contribute this log plugin. Can I send a pull request to create the github.com/h2non/gentleman/plugins/log package?

Could you tell me what do you think?

[h2non]

Thanks for sharing the code.

I would suggest the following points:

• Create just one plugin to do all the required job, instead of two plugins.
• Make things configurable in the Go idiomatic way, for instance passing a struct as config with all the supported log behavior configuration instead of explicit arguments to he plugin constructor.
• Create your custom log package in your personal Github account. Since gentleman is very modular, there is not need to place things in the same repository. You can simply import your custom package URI. If the package is more mature in the future, I can consider supporting it as core plugin.

[h2non]

I wrote a simple Apache-like HTTP logger for the server side that you can take a reference, however it's pretty simple not designed for versatility, just log things as Apache does:
https://github.com/h2non/apachelog

[hnakamur]

Thanks for your suggestions.
I created my custom log package at
https://github.com/hnakamur/gentleman-log

Thanks again for you help!

[h2non]

That's nice. If you want to evolve it in the future, I would suggest to take an eye apex/log structured implemented as design reference point:
https://github.com/apex/log

Once the package is mature and versatile enough, you can make a PR request to add it to the list of plugins.