Making logging to stdout optional

[cep21]

The generated twirp servers include
import log "log"

They're used in error cases like this:

	if _, err = resp.Write(buf.Bytes()); err != nil {
		log.Printf("errored while writing response to client, but already sent response status code to 200: %s", err)
	}

It would be great if I could provide my own logger of some kind.

One proposed API would be to expose an optional function I could type assert for.

func (s *myServer) SetLogger(logger *log.Logger) {
  s.logger = logger
}

The client code could then call

x := NewMyServer(...)
x.(twirp.Logthingie).SetLogger(myOwnLogger)

If you're ambitious, you could have a specific twirp type logger for more strongly typed information

type TwirpLogger interface {
  ErrorWritingReponse(ctx context.Context, writeErr err)
}

My implementation could then extract the method name from the ctx.

[spenczar]

This is clearly a good idea.

The TwirpLogger-style thing seems marginally better than letting you set a generic logger, I suppose, but it means we have more API surface area to defend, compatibility-wise:

1. If we have a new place where weird errors could occur (like if we add streaming support, Proposal: Support streaming in the Twirp spec #3), then we'd need to add new methods to the interface. That would mean that users would need to add new methods to their logger implementations, which makes upgrading more of a hassle.
2. Similarly, we'd never be able to remove things from that interface - because what if you import a client that was generated a long time ago, and still uses the old hooks?

Using a simpler Printf-style logger avoids those issues, which seems really good.

Hm. I at least want to sleep on the two approaches and/or hear thoughts from others.

[cep21]

Being able to pull out the method name or destination could be useful. I think you would need the ctx to do that. It could just be ...

type Logger interface {
  LogCtx(ctx context.Context, keyvals ...interface{})
}

:) Or a Fprint style args after the ctx(?)
Log(ctx context.Context, msg string, args ... interface{})

[spenczar]

@cep21, yes, providing the context seems important here. I don't think there's going to be a nice way to work in key-values for structured logging, though. How about Log(context.Context, string)? The call sites will do a Sprintf to give a clean message.

[cep21]

That works. Wonder if it's worth sneaking the error in there too?

[spenczar]

If we included the error, we're wandering away from it really being a logger. It's becoming an error handler.

We could ask for something like

type TransportErrorHandler interface {
  // Handle a low-level, unrecoverable error with Twirp's underlying transport: 
  // this can be an error writing a response body, in a server, or an error closing
  // a response body, in a client.
  HandleTransportError(context.Context, error)
}

The default would be to log.Printf the error, but the user could do whatever weirdness they like.

I'm not sure what the advantage is with that though, to be honest. What would someone do with the error value they get? They won't be able to revive the connection or recover from the error in any of these cases. They're just going to log it. Even calling it HandleTransportError is misleading because there's really nothing you can do but log it. The error value isn't going to have any real structure - it's going to pretty much just say "the connection is toast, sorry."

The simpler Log(context.Context, string) API is what I'm landing on, here.

[dividinglimits]

To enable compos-ability with other 3rd party libraries, why not Log(context.Context, error)? Think of maybe in the future enabling "stack traces", or "causes" etc...

[spenczar]

@dividinglimits Fair point, but these errors are not ones that the user controls - they aren't likely to have stack traces or causes like from github.com/pkg/errors. I don't think that's likely to come up, in practice.

I suppose someone could implement their own HTTP stack and use it for Twirp, and then they might benefit from being able to unpack the error, though.

But then, there doesn't seem to be any real downside to Log(context.Context, error), since - by adding the context.Context parameter - we are deviating from more common interfaces like Println(string) anyway. I'm mildly in favor of Log(context.Context, error) as the best we've seen so far, with Log(context.Context, string) in a close second.

This has been a good discussion, so I'll leave it open for a few more days in case more people have good ideas.

[cep21]

Maybe it's not a logger at all. If you reframe it to something that handles errors the API doesn't want to return or throw away, then you don't have to constrain yourself with worrying about a generic logging API.

type ErrorReciever interface {
  OnError(ctx context.Context, err error)
}

The downside here is there's no context about where the error happened, which may motivate a third string parameter.

Another advantage of reframing it, is you can think on and solve the logger problem later.

[huttotw]

In the spirt of @spenczar comment:

They won't be able to revive the connection or recover from the error in any of these cases. They're just going to log it.

I think I am in favor of making this a logger and not an error receiver. However, I think structured logging is important, both for reporting and for expansibility.

I like the Logger interface provided by go-kit.

type Logger interface {
	Log(keyvals ...interface{}) error
}

Adding context.Context we would have:

type Logger interface {
	Log(ctx context.Context, keyvals ...interface{}) error
}

@spenczar what is your concern with the keyvals? What about a standard msg key that can be expected (not the biggest fan of this, but)?

[spenczar]

Oh, believe me, @huttotw, I think structured logging is important too. I'm just uncomfortable with keyvals ...interface{}.

If someone is not using structured logging - like, they are using glog or the standard library, or something - then do they do with the keyvals? Do they just fmt.Sprintf("%v", keyvals), or something?

Your point about a 'standard msg key' kind of shows the difficulty here; we would need to declare standards in documentation instead of in code. My problem is that the signature doesn't actually explain completely how it's supposed to be used, and it's too prescriptive.

I feel that we've gotten to a good place here. I like LogError(context.Context, error). There is one thing left to decide which is whether we use a named interface to describe this behavior. I think this is easiest to explain with code.

---

Proposal 1: Named interface:

We go with this basic structure: The generated structs will include a new method, SetErrorLogger, like this:

func (s *haberdasherServer) SetErrorLogger(l ErrorLogger) {
	s.errorLogger = l
}

func (c *haberdasherJSONClient) SetErrorLogger(l ErrorLogger) {
	c.errorLogger = l
}

func (c *haberdasherProtobufClient) SetErrorLogger(l ErrorLogger) {
	c.errorLogger = l
}

And in the generated code, we'll include this interface definition:

type ErrorLogger interface { 
	LogError(context.Context, error)
}

If users want to configure the logger, they'll need to type-assert into being able to call the method, and then they can set it:

c := haberdasher.NewHaberdasherProtobufClient("http://localhost:8080", http.DefaultClient)
if cc, ok := c.(interface {
	SetErrorLogger(haberdasher.ErrorLogger)
}); ok {
	cc.SetErrorLogger(logAdapter)
}

---

Proposal 2: Anonymous interface

In Proposal 1, because ErrorLogger is defined within the generated code, users wouldn't be able to make a generic set-the-logger function, which is unfortunate. They'd have to copy the interface-asserting snippet around for every service they want to fiddle with instead of putting it in a library.

The simplest way around that is to drop the ErrorLogger interface entirely and make it an anonymous, literal type, like so:

func (s *haberdasherServer) SetErrorLogger(l interface {
	LogError(context.Context, error)
}) {
	s.errorLog = l
}

func (c *haberdasherJSONClient) SetErrorLogger(l interface {
	LogError(context.Context, error)
}) {
	c.errorLog = l
}

func (c *haberdasherProtobufClient) SetErrorLogger(l interface {
	LogError(context.Context, error)
}) {
	c.errorLog = l
}

Anonymous interfaces like this are horrible for readability. But this has a significant advantage - you could write a library like this, which would be the way users would set the logger:

package twirplogrus

import "github.com/sirupsen/logrus"

type logSetter interface {
	SetErrorLogger(l interface {
		LogError(context.Context, error)
	})
}

func SetTwirpLogger(twirpObj logSetter) {
	twirpObj.SetErrorLogger(logrusTwirpAdapter{})
}

type logrusTwirpAdapter struct {}
func (a logrusTwirpAdapter) LogError(_ context.Context, err error) {
	// Don't use this! Just an example:
	logrus.Error(err.Error())
}

That library would be impossible to write in Proposal 1. So, we're weighing library-ability versus readability of the generated code.

---

I like Proposal 2 more. I think that the users of this functionality will be opinionated people who want to enforce a standardized logger across all projects they work on. They'll probably be more happy with making a library once than with going into all their projects and making sure they do the bizarre type assertion.

I'm interested in feedback on these two proposals, and to any other ideas on how to implement LogError(context.Context, error).

Let's consider the discussion of the method signature closed. We got lots of good ideas, and I like LogError(context.Context, error) the most.

[rhysh]

Twirp has a mechanism for calling user code in response to particular events: twirp.ServerHooks. It's a struct, so we can safely add new fields (which we can't do for interfaces). A new field of type func(context.Context, error), maybe called TransportError or NetworkError would fit the bill.

The idea of SetErrorLogger seems like one of strongest proposals in this thread, but it seems similar in spirit to adding a new kind of server hook.

For server errors not associated with a request, the generated code would call the function if set. If the field is not set, the generated code would log as it does today. Same with server errors encountered while writing a response.

For the client, all errors would be reported synchronously. Currently the client will log any error encountered while calling net/http.Request.Body.Close—that can be fixed easily in code without an API design change.

This does mean the generated code would refer to a new field in the twirp package, which would force an upgrade when a recent code generator is used. If necessary, we could avoid this by grabbing the field with reflection.

[earthboundkid]

Anonymous interfaces like this are horrible for readability. But this has a significant advantage - you could write a library like this, which would be the way users would set the logger

You can get the advantage of both named and anonymous interfaces with a type alias. type ErrorLoger = interface { … }.

[spenczar]

@rhysh, your point about clients is really good: we can drop the log usage from the client entirely by restructuring the client's code. That's good! We should probably do that.

I hadn't given hooks much thought because I thought we would need to support clients. I would actually prefer to see us do this through the existing Error hook, so long as we can avoid changing its meaning very much, and can continue to guarantee that ResponseSent is always the last hook fired.

Using the existing Error hook instead of adding a new one is better because it keeps the ServerHooks struct simple and easy to understand, and because it doesn't have any compatibility problems.

The downside is that we change the expand the meaning of the Error hook slightly. It goes from "fired when we respond to a client with an error" to "fired when an error occurs while handling a request."

I actually prefer that new meaning. I think it's clearer - it separates the sending-of-the-response (which is, after all, ResponseSent) from the occurrence of the error

This does mean that the Error hook can fire on 200 status-code responses in some rare cases. We should document this well, but I think that's okay.

It seems we can get away with this without any new APIs, which is just terrific. Good catch that the client error could be returned!

[marioizquierdo]

I like this last approach:

• In the client: do not use the log package, just return rare exceptions as Internal like all other client errors.
• In the server: handle those rare cases with the Error hook. Just make sure to document this.

Right now in some Twirp services I'm using, this rare exceptions are just being lost, because we track errors on statsd and Rollbar, and pretty much ignore the standard logs in our backend. Adding this errors to the Error hook would actually give us better visibility on this issues. And the same thing goes for clients.

What I don't like about the other approaches:

• Set a logger: it makes it look like there's some major logging going on, but that's not true, this would only ever receive logs on very rare exceptions.
• Set an error handler: it makes it look like there's some major error handling going on, but that's not true, this would only ever handle very rare errors. Maybe changing the name to OnRareErrors would be better, but already sounds bizarre.

[spenczar]

Fixed in #66 and #76.