Client Request Logging with Winston

[Clay Himmelberger]

Hey actionhero-ers,

Has anyone set up any particular logging scheme to trace a user, or a particular action, through the logs? The idea would be to apply metadata to a logger, like a userId or requestId, that would propagate through actionhero (actions, initializer logic (DB),  etc).  

Any thoughts on something like that? It's handy to have the logging information (or use a transport for loggly or something), but I'm looking for ideas to search the logs for useful data or debugging info.

I've done things like this with Bunyan before, but that has a child logger system, and all our code was ready to accept a child logger.

Thanks,

Clay

[Evan Tahler]

first, you can already add a transport to winston to send *all* log messages to a third-party.  That might already be what you want.

If you want to track more information, use an action post-processer middleware.  You'll have access to the connection, session, etc and you can log whatever you want then 

[Clay Himmelberger]

As more an example, it's using those logs in the 3rd party systems that I'm trying to streamline. Let's say I see an Error message in some DB call or logic structure. If that call logged the client ID or even the request ID that started it, I could use the logging tooling to filter/search for the entire trail of calls (or what else said user was up to before the crash). It's not just at the action entry point, it's down in the (initializer) logic of the system.  

I was thinking along the lines of Bunyan's child logger. Though even that child logger would need passed around or provided in the logic of the system. 

What would be a common thing for actions, the connection object? Just create my own "log meta data" object? I could pass whatever it was to all my internal logic, and then have a custom logging method that also logs the information I want in the logs (client ID, request ID, ...). I suppose metadata on a task could work as well, when logic doesn't start from an action. 

I hope this is making sense. It might end up being a custom thing, just wondering if others ran into similar stuff before.

[Evan Tahler]

I think I get what you are asking...  And I imagine what you want to do is pretty custom.  It seems that you want to instrument logging at many steps within an action, or even deeper down in an initializer/middleware.  To that end, `data`  (and `data.connection`) should always be available... so you can safely key off of objects in that scope. 

[Clay Himmelberger]

That what I ended up doing. Custom, and does affect all the logic, but is getting me what I'm looking for so far. 

Just to recap here for other's reference:

Regarding actions, I created a middleware to store some logging information:

preProcessor: function(data, next) {
        data.log = api.utils.objClone(data.params);
        data.log.clientId = data.connection.username;
        data.log.reqId = api.uuid.v4();
        next();
      }

Then my functions have an options object passed to them as the last argument (or before the callback). Something like this in the action:

api.sessions.subscribeSession( data.params.sessionCode, { logMeta: data.log } )

Inside the initializers/middleware, I call the logs (especially any errors) with:

api.log('Words to log', level, options.logMeta );

My console logs look something like this:

2016-05-18T14:05:25.056Z - info: Get a session. sessionCode=crya accountId=1, sessionCode=crya, action=stopSession, apiVersion=1, clientId=user12, reqId=b630d2b5-a8cd-439b-bdc7-3597cbcd4c13

And Winston says that metadata is tailored for each transport.

Now with a logging service (or even `grep`!), if I see an error I can search the logs for the username to see what they were doing all alone. Or the requestId to know what chain of events blew things up. Or for more analysis, I could filter on the "sessionCode" parameter that all the clients were using for that session to get a more complete picture for that session. 

It took a little groundwork, but so far so good : ) 

[Evan Tahler]

Nice! You've figured out the core of the problem.  

There's a slightly nicer API you can use (and limit the passing of that log data around) if you build it up programmatically as its needed.  Here's a modification: https://gist.github.com/evantahler/75d011647f2a872fbb5f4af2a780bfcb