improved processing of structured logs

[travi]

I recently got @google-cloud/logging-bunyan working in a hapi app (leveraging good-bunyan) after a very helpful conversation with @ofrobots.

This got us to a much better state of logging than our previous use of good-console to simply write to stdout. However, the log events that are sent to Stackdriver are still not tokenized nearly as well as the logs that we have for some other (non-node) apps we have running in the standard environment.

It appears that the events sent through @google-cloud/logging-bunyan are structured in the bunyan recommended formats, rather than the Stackdriver format. If I understand the docs correctly, Stackdriver would automatically process these better if they were transformed to meet the formats like:

• https://cloud.google.com/logging/docs/reference/v1beta3/rest/v1beta3/RequestLog
• https://cloud.google.com/logging/docs/reference/v1beta3/rest/v1beta3/LogLine

I have not looked very deeply into trying to perform any transformations myself because I wanted to see if the team agreed that it made more sense to be part of the @google-cloud/logging-bunyan library directly. It seems like that would be the most helpful place so that each consumer doesn't need to build the transformations themselves (if event possible).

Would it be reasonable to add this type of transformation into the library to support better log tokenization?

[ofrobots]

Hi @travi, I think it would be a good idea to have more structured request logs. The challenge is that, unlike the standard environment, there are too many combinations of web frameworks and logging middleware involved, each with their own way of formatting log entries. In the Node.js case, hapi + good seems to have very specific way of formatting log entries. Restify is entirely different. Users may configure and/or modify these formatters making it hard to predict how the data would be structured.

In other words, it is quite difficult to predict if the userAgent is available through req.headers['user-agent] (raw http request), response.source.userAgent (hapi + good), or is not available at all (restify doesn't provide headers by default). It is very hard (error prone) to build structure out of unstructured input.

One way to deal with this would be:

• If the bunyan logging record contains a httpRequest property, we will report it as HttpRequest field of the LogEntry (as opposed to leaving it as part of the unstructured payload).
• Users would be responsible for formatting the request log entries to provide a well formatted HttpRequest property.

It should be possible to put the latter into independent npm modules.

In the hapi + good case, I think you will need the following formatter in the your good-bunyan configuration:

          bunyan: [
            {
              module: 'good-bunyan',
              args: [
                {response: '*', log: '*'},
                {
                  logger: logger,
                  levels: {
                    response: 'info',
                  },
                  formatters: {
                    response: (payload) => {
                      const nanos = payload.responseTime * 1e6;
                      const latency = {
                        seconds: Math.floor(nanos / 1e9),
                        nanos: Math.floor(nanos % 1e9)
                      };
                      return {
                        httpRequest: {
                          requestMethod: payload.method,
                          requestUrl: payload.path,
                          status: payload.statusCode,
                          remoteIp: payload.source.remoteAddress,
                          referer: payload.source.referer,
                          userAgent: payload.source.userAgent,
                          latency: latency,
                        }
                      };
                    }
                  }
                }
              ]
            }
          ],

Of course this needs to go along with a corresponding change in @google-cloud/logging-bunyan that promotes httpRequest.

Let me know what you think about this.

[travi]

Gotcha. I guess I was hoping that the bunyan and winston output would be standard enough to have some built in mappings. If that isn't the case, then what you suggest sounds like the best alternative. Is there specific feedback you are looking for, or just agreement that this is a reasonable path forward? If the latter, I'd say lets do it.

We have several apps that we would want to apply this to, so we would certainly be pulling the formatters out to an npm package, which shouldn't be too bad since these would be simple functions.

We would likely open source the package, but my only concern would be discoverability of this type of capability in the first place. I have had a hard time piecing together the various necessary parts to get to a good state with logging. Is there anything I can provide as far as feedback that might help shape tutorials for logging so that others might not have to struggle as much to get things going?

[ofrobots]

Hi @travi: with #2325 we now accept a structured HttpRequest property as part of the winston provided log metadata.

You do have a reasonable concern about discoverability of 'recipes' on how to integrate Stackdriver logging into various combinations of web framework (restify, hapi, koa, express, etc.) + logging middleware (e.g. good) + logging framework (bunyan, winston). One idea would be for us to include internal or external links to samples / modules with recipes to work with a specific combination. Would that be useful?

[travi]

the main struggle i had with getting logging working was understanding what options were available and would actually work for sending logs to stackdriver. it actually took me quite some time to even find that logging was supported in google-cloud-node because the docs about logging in the flexible environment suggested several other configurations than using google-cloud-node and were even inconsistent. trying some of those options did not yield success for me.

knowing hapi and good as well as i do, i was able to figure out use of bunyan and good-bunyan on my own once i learned of @google-cloud/logging-bunyan. if the docs for the flex environment had made the @google-cloud/logging-bunyan or @google-cloud/logging-winston options more clear, i think that alone would have made it far simpler to get to a working state.

while that is the bigger blocker in my mind, i do think having some examples of how to get various frameworks to format in a way that is compatible with the structured HttpRequest would be very helpful once someone finds there way here. since logging isn't something you end up configuring often, helping shorten the time to understand what is needed would be great, even for someone that knows the layers like hapi and good in my case.

[ofrobots]

@travi Thanks for the feedback. That is very useful. The state of docs is indeed not as great as it ought to be and we are taking a look at making it better.

A question for the specific issue for request logging for hapi at hand: If we provided a hapi plugin (rather than a good plugin), would that be useful?

[travi]

sorry for the delayed response. i lost track of the notification and just remembered this morning that i still owed you a response on this.

i dont think i follow exactly what you mean by a hapi plugin over a good plugin. are you suggesting a plugin that would be used in place of good?

my first reaction is that that would be less ideal since i still use good (with good-console) for local logging. i currently just conditionally load different reporters based on the environment. that gives me lots of control around what gets logged, and configuring further than the basics is simply an additional stream transform.

however, with stackdriver, i probably just want to send basically everything that stackdriver would understand, so i probably wouldnt need that level of control if things just worked out of the box with a hapi plugin. my config would obviously have to change, but i could conditionally load your plugin instead of good depending on environment, assuming that is what you meant.

i think my initial searches would have been specifically looking for a good plugin, but when it comes down to it, i think either should work fine.

[ofrobots]

The question is about the integration point for structured logs. As you have noticed, by default good and/or bunyan logs aren't structured enough for Stackdriver to provide you an App Engine Standard -like user experience. I am thinking about how we can make that better, and one way to do that would be to provide middleware/plugins for web frameworks: express, restify, hapi, etc. The middleware would be responsible for automatically generated well structured request logs and (possibly) adding support for request bundling of application logs.

I am not familiar enough with the hapi / good ecosystems to know whether the hapi plugin would be useful by itself, or if people think the integration should be with good rather than hapi.

i dont think i follow exactly what you mean by a hapi plugin over a good plugin. are you suggesting a plugin that would be used in place of good?

I don't think it would be an either/or. You could continue using good in addition to the hapi plugin. The console logs you get from good will have less structure, but will have the filtering etc. and other controls that you might on the console. The hapi plugin would additionally send structured logs to Stackdriver, providing you with integrations with the various Stackdriver features.

Based on your response, I think it seems like you think a hapi plugin could have value – so I will continue to explore that. Thanks a lot for your response!

[travi]

Thanks for the follow up explanation. Knowing your goal gives me enough info that I might be able to help you understand the hapi/good relationship a bit better.

The main thing to be aware of with good is that it is not only useful for logging. good by itself is a process monitor that listens to the event stream produced by the hapi server. It is very common to use good for logging, but that is only enabled by using a plugin that transforms the stream into a format and then writes them somewhere. good-console, for example, is only a transform. you still need to define where to write to, which can be stdout (most common) or a file, etc.

From the good readme:

It listens for events emitted by hapi server instances and pushes standardized events to a collection of streams.

I mainly want to point all of that out because I think good is likely your best spot to hook into hapi for the "middleware" like behavior that you are talking about. My use of bunyan, good-bunyan, and @google-cloud/logging-bunyan are really just a hack around the lack of a direct transform/reporter that outputs directly to the stackdriver api instead of stdout or a file.

If you are looking to add a hapi integration, I think your best best is to hook into the good stream directly and apply some combination of a transform to make the structure match what stackdriver can tokenize and a reporter to send the output to the stackdriver api. I could see that packaged as a singe good plugin, or broken into three parts, which is the more typical approach for hapi/good. You could expect the consumer to handle identifying the topics they want to send using good-squeeze, then wire that to a transform provided by you to get the appropriate format, and finally wire that to a stackdriver reporter that you provide. This would also have the side-benefit of being able to debug the output by swapping the reporter for stdout etc.