How to log RPC requests properly?

[kochetkov-av]

So far I've implemented a logger call inside each handler, which doesn't look like the best idea.

I think the best place to log requests is right after the parser, so it's really nice to have some kind of middleware support.

Probably somewhere in here?

jsonrpc/handler.go

Lines 45 to 53 in 352acaa

	resp := make([]*Response, len(rs))
	for i := range rs {
	resp[i] = mr.InvokeMethod(r.Context(), rs[i])
	}
	if err := SendResponse(w, resp, batch); err != nil {
	fmt.Fprint(w, "Failed to encode result objects")
	w.WriteHeader(http.StatusInternalServerError)
	}

[osamingo]

Thanks for your comment.
Maybe you need to create a Hook feature?

[kochetkov-av]

Yep hook sounds great!
I could create a PR with a draft, what do you think?

[osamingo]

Share, I welcome your PR.
If you have free time, can you lightly list when to hook timings?

[kochetkov-av]

Great, will work on it!
Not sure that I understand your last question.

I think about at least 2 hooks, before handling and after response. At the first hook, it should be possible to save the start timestamp to context. Then logger inserted in "after" hook gonna be able to track response time.

[alexus1024]

You can implement middleware to log queries

var LoggingMiddleware = func(next jsonrpc.HandlerFunc) jsonrpc.HandlerFunc {
	// one time scope setup area for middleware
	return func(c context.Context, params *fastjson.RawMessage) (result interface{}, err *jsonrpc.Error) {
           // here get logger from context, also get additional info with jsonrpc.RequestID(), GetMetadata() and MethodName()
        }

next, during launch-time use jsonrpc.BuildChain() to wrap your handler with middlewares and then call MethodRepository.RegisterMethod to register your wrapped handler

[alexus1024]

Of course you can implement usual http middlewares to you http.ServeMux, around jsonrpc handler. But they will not be able to access jsonrpc method name without additional parsing

[kochetkov-av]

I will test LoggingMiddleware, looks like a promising approach!

Logger on HTTP mux level is not an option - it would require manipulation with the copiing of request.Body ReaderCloser and duplicated body parsing, which is already done in the package.

[kochetkov-av]

Ok, so finally what I've got:
In router part:
_ = mr.RegisterMethod("Method.Test", LoggingMiddleware(Test, logger), nil, nil)

this part is not ideal, so it would be nice to have something like
mr.UseMiddleware(LoggingMiddleware)
to apply for every method

and this is my logger implementation:

func LoggingMiddleware(next jsonrpc.HandlerFunc, logger *zap.Logger) jsonrpc.HandlerFunc {
	return func(c context.Context, params *fastjson.RawMessage) (result interface{}, err *jsonrpc.Error) {
		start := time.Now()

		result, err = next(c, params)

		latency := time.Now().Sub(start)

		var p []byte
		if params != nil {
			p, _ = params.MarshalJSON()
		}
		requestID, _ := jsonrpc.RequestID(c).MarshalJSON()

		logger.Info("RPC request",
			zap.String("method", jsonrpc.MethodName(c)),
			zap.ByteString("params", p),
			zap.Duration("latency", latency),
			zap.ByteString("requestID", requestID),
		)

		return result, err
	}
}

[alexus1024]

Yes, middleware support can be better in this library.
In my project I implemented descriptors - just plain structs holding operations info - name, handler, required middlewares, grouping by endpoints and so on. And then wrote a code to process this descriptors into RegisterMethod calls.
But this code is pretty specific, I can't add it here.