Add Server logging

[glbrntt]

Motivation:

We only have client side logging at the moment, we should also have logs
on the server.

Modifications:

Add logging for server components. Also add explicit 'self' in a number
of places where it was missing.

Result:

More server logging.

[MrMage]

Looks good overall. A few notes:

1. My recollection was that the client-side logging relied a bit more on "dependency injecting" loggers. This seems to be less the case on the server-side — any specific reasoning behind that?
2. As with the client, would you mind providing a sample log dump?
3. I have not checked the logs for completeness, i.e. whether all things that should be logged are logged.

[MrMage]

Should we try attaching , metadata: ["path": "\(requestHead.uri)"] to all log statements relevant to a specific call?

Also, should we have one dedicated canonical "access log" statement that serves a similar purpose as e.g. Apache/nginx access logs? Preferably including request path, response status, and the overall time the request handler took. (Let me know if I missed one you have for that.)

[glbrntt]

Should we try attaching , metadata: ["path": "\(requestHead.uri)"] to all log statements relevant to a specific call?

How about just a uuid so we can reuse the logger across different handlers?

It may be worth creating a CallHandlerContext and passing that to handleMethod and then the *CallHandlers (instead of the method name, request head, channel, error delegate, and logger) so we can avoid breaking the generated code so often.

Also, should we have one dedicated canonical "access log" statement that serves a similar purpose as e.g. Apache/nginx access logs? Preferably including request path, response status, and the overall time the request handler took. (Let me know if I missed one you have for that.)

We should!

[glbrntt]

info level server logs from a bidi call:

2019-08-15T10:55:03+0100 info: making server bootstrap with event loop group of type MultiThreadedEventLoopGroup
2019-08-15T10:55:12+0100 info: channel_handler=HTTPProtocolSwitcher determining http protocol version
2019-08-15T10:55:12+0100 info: channel_handler=HTTPProtocolSwitcher state changed from 'notConfigured' to 'configuring'
2019-08-15T10:55:12+0100 info: channel_handler=HTTPProtocolSwitcher buffering data NIOAny { ByteBuffer { readerIndex: 0, writerIndex: 45, readableBytes: 45, capacity: 1024, slice: _ByteBufferSlice { 0..<1024 }, storage: 0x00007fc66b000000 (1024 bytes) } }
2019-08-15T10:55:12+0100 info: channel_handler=HTTPProtocolSwitcher http_version=http2 determined http version
2019-08-15T10:55:12+0100 info: channel_handler=HTTPProtocolSwitcher unbuffering data
2019-08-15T10:55:12+0100 info: channel_handler=HTTPProtocolSwitcher state changed from 'configuring' to 'configured'
2019-08-15T10:55:12+0100 info: request_id=7D338862-CE30-40DC-B216-A88E8C9FD168 path=/echo.Echo/Update method=POST version=HTTP/2.0 rpc call started
2019-08-15T10:55:12+0100 info: channel_handler=GRPCChannelHandler request_id=7D338862-CE30-40DC-B216-A88E8C9FD168 path=/echo.Echo/Update making call handler
2019-08-15T10:55:12+0100 info: channel_handler=GRPCChannelHandler request_id=7D338862-CE30-40DC-B216-A88E8C9FD168 received request head, configuring pipeline
2019-08-15T10:55:12+0100 info: channel_handler=GRPCChannelHandler request_id=7D338862-CE30-40DC-B216-A88E8C9FD168 adding handler GRPCServerCodec<Echo_EchoRequest, Echo_EchoResponse> to pipeline
2019-08-15T10:55:12+0100 info: channel_handler=GRPCChannelHandler request_id=7D338862-CE30-40DC-B216-A88E8C9FD168 removed GRPCChannelHandler from pipeline
2019-08-15T10:55:12+0100 info: request_id=7D338862-CE30-40DC-B216-A88E8C9FD168 observerState changed from pendingCreation((Function)) to created(NIO.EventLoopFuture<(GRPC.StreamEvent<Echo.Echo_EchoRequest>) -> ()>)
2019-08-15T10:55:12+0100 info: request_id=7D338862-CE30-40DC-B216-A88E8C9FD168 channel_handler=HTTP1ToRawGRPCServerCodec outbound state changed from expectingHeaders to expectingBodyOrStatus
2019-08-15T10:55:12+0100 info: request_id=7D338862-CE30-40DC-B216-A88E8C9FD168 channel_handler=HTTP1ToRawGRPCServerCodec inbound state changed from expectingHeaders to expectingBody
2019-08-15T10:55:12+0100 info: request_id=7D338862-CE30-40DC-B216-A88E8C9FD168 appending 14 bytes to buffer
2019-08-15T10:55:12+0100 info: request_id=7D338862-CE30-40DC-B216-A88E8C9FD168 read length-prefixed message
2019-08-15T10:55:12+0100 info: request_id=7D338862-CE30-40DC-B216-A88E8C9FD168 appending 8 bytes to buffer
2019-08-15T10:55:12+0100 info: request_id=7D338862-CE30-40DC-B216-A88E8C9FD168 read length-prefixed message
2019-08-15T10:55:12+0100 info: request_id=7D338862-CE30-40DC-B216-A88E8C9FD168 appending 8 bytes to buffer
2019-08-15T10:55:12+0100 info: request_id=7D338862-CE30-40DC-B216-A88E8C9FD168 read length-prefixed message
2019-08-15T10:55:12+0100 info: request_id=7D338862-CE30-40DC-B216-A88E8C9FD168 appending 8 bytes to buffer
2019-08-15T10:55:12+0100 info: request_id=7D338862-CE30-40DC-B216-A88E8C9FD168 read length-prefixed message
2019-08-15T10:55:12+0100 info: request_id=7D338862-CE30-40DC-B216-A88E8C9FD168 channel_handler=HTTP1ToRawGRPCServerCodec inbound state changed from expectingBody to ignore
2019-08-15T10:55:12+0100 info: request_id=7D338862-CE30-40DC-B216-A88E8C9FD168 observerState changed from created(NIO.EventLoopFuture<(GRPC.StreamEvent<Echo.Echo_EchoRequest>) -> ()>) to notRequired
2019-08-15T10:55:12+0100 info: duration_ms=2 request_id=7D338862-CE30-40DC-B216-A88E8C9FD168 status_code=0 rpc call finished
2019-08-15T10:55:12+0100 info: request_id=7D338862-CE30-40DC-B216-A88E8C9FD168 channel_handler=HTTP1ToRawGRPCServerCodec outbound state changed from expectingBodyOrStatus to ignore

[MrMage]

LGTM