How to get entire request / response message in hook?

[neguse]

I'm using twirp on protobuf rpc server. I want to log entire request / response message on each rpc call. Twirp has ServerHooks called on each rpc call. But in ServerHooks, User can access only ctx object which is including neither request nor responce object. I think if ctx is including request and response object, I can json.Marshal() them and output to stdout on hook function. How can I do this?

[mfridman]

To get access at the original request within the hooks, use http middleware to inject the body and pass it around with a request context.

E.g., I have a middleware that looks like this..

func Middleware(next http.Handler) http.Handler {
    return http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) {

where we check the body, read it, restore it, and make it available through a context key

if r.Body == nil {
    next.ServeHTTP(w, r)
    return
}

by, err := ioutil.ReadAll(r.Body)
if err != nil {
        // fail hard or continue execution, depends on your application
}

// restore
r.Body = ioutil.NopCloser(bytes.NewBuffer(by))

// put the bytes into context with a unique key
ctx = withContextBody(r.Context(), by)
next.ServeHTTP(w, r.WithContext(ctx))

the setter/getter would look something like this...

func withContextBody(ctx context.Context, body []byte) context.Context {
    return context.WithValue(ctx, ctxBody, body)
}

func FromContextBody(ctx context.Context) ([]byte, bool) {
    by, ok := ctx.Value(ctxBody).([]byte)
    return by, ok
}

then in your hooks call something like request.FromContextBody(ctx) which returns the original bytes body that can be unmarshalled into whatever you're expecting.

depends where you want to handle your errors, you could also unmarshal way up the stack..

[neguse]

@mfridman Thanks for advice! But I think this solution looks not suite for my situation by some reasons.

hooks don't know how to unmarshal request

In this solution, hooks can access the request content bytes. I want to proto.Unmarshal() and json.Marshal() it for logging as string representation. But proto.Marshal() requires the message type of this request, and I think there is no way to detect the type of request. So, I want to access proto.Unmarshal()'ed request message in hooks.

duplication of effort for unmarshal request

In previous reason, Even if the method of detect the type of request in hooks exists, twirp does proto.Unmarshal() already. So, it is a duplication of effort for proto.Unmarshal().

how to apply for response?

This solution shows how to access request bytes. But how about response? I found a solution inspecting response body. https://stackoverflow.com/questions/43021058/golang-read-request-body/43021236#43021236 I think the same method can be applied.

[spenczar]

Twirp doesn't have a way to do this in any automatic, wide blast radius way. If you want to log the complete request and response in each of your methods, you'll need to add code to each of your methods.

This is an intentional design choice. ServerHooks are not middleware, and have limited power, because putting lots of behavior into side effects makes code confusing. That is important for keeping Twirp services easy to read and understand. Thick stacks of middleware have caused too much pain for Rails and Django developers for us to repeat that mistake.

[mfridman]

@neguse I'd strongly agree with @spenczar that service hooks aren't middleware.

We ended up injecting the entire body into the context once, for a very specific and narrow use-case. This was an exception and not the norm.

The nice thing about Twirp is the separation of concerns, which is, as Spencer mentioned, a deliberate choice not to expose the request and response.

---

It sounds like you're trying to write an http Logger middleware that logs the entry point and hooks into the response writer.

This can be done outside the twirp service, in the http middelware, with something like this..

https://github.com/go-chi/chi/blob/master/middleware/wrap_writer.go

ww := middleware.NewWrapResponseWriter(w, r.ProtoMajor)

defer func(){
        // you can grab logger or tracer here from the ctx and decorate it
        // as the stack gets unwinded
}()

// call next in the chain with the wrapped response writer, 
// putting the logger or tracer into the ctx

next.ServeHTTP(ww, r.WithContext(ctx))

^ that's just a high-level idea for you to explore, if I'm understanding correctly what you're trying to accomplish.

the "wrapped" response writer will expose Header, Status, BytesWritten, etc.

EDIT: if you need granular logging, you're better off doing this in the method itself.

[neguse]

@spenczar Thanks for answer! OK! I understood twirp's design philosophy.

@mfridman Thanks for advice again! Certainly, it's able to implement http logging middleware that logs request and response. But there are some unresolved problems I previously wrote. e.g. proto.Unmarshal needs type information.

I found related issue #184 and shouichi shows the method of generating validator/authenticator and chaining service. I will try this method.

[hexdigest]

@neguse

JFYI: I ended up writing a twirp_validate template for GoWrap middleware generation tool.