How to add custom JSON properties

[optikalefx]

Hello dear sir,

We would like to use AwesomeLog to log the GCP traceId of cloud-run. From Googles perspective, they want you to add a field to the JSON of the log.

https://cloud.google.com/run/docs/logging#writing_structured_logs

The only way I can tell to add something to the logEntry JSON is to use a beforeWrite hook. The problem with that, is that that is configuration level. I don't have the traceId until i'm in the middleware of Express

So my present way of doing this, which is very ugly, is to delay starting AwesomeLog until AFTER the middleware has run, so that when the hook is defined, I have the value.

let gcpTrace = '';
const app = express();
app.use(express.json());
app.use((req, res, next) => {
	const traceHeader = req.header('X-Cloud-Trace-Context');
	const [trace] = traceHeader.split('/');
	gcpTrace = `projects/${ConfigService.get('gcp.projectId')}/traces/${trace}`;
	next();
});

config.hooks = {
	beforeWrite: (logEntry) => {
		logEntry['logging.googleapis.com/trace'] = gcpTrace;
	},
};
Log.init(config).start();

Is there any cleaner way to add a custom field to the JSON, something on Log that can be adjusted in that middleware? Something like Log.customFields['logging.googleapis.com/trace'] = gcpTrace instead of having to define this in the configuration.

Thanks!

[arei]

Unfortunately there is not currently a way to do what you are looking for, nor do I think we could easily add a way into AL. The problem lies in that a call to Log.log() (which things like Log.info() and Log.error() are just wrappers for) has no facility to pass that information since all of the arguments after the first one are generally treated as log info.

Furthermore, I think the solution you are proposing has a severe limitation... Because you are setting the gcpTrace as a variable you are wildly opening yourself up to a race condition, especially if you put your express app under pressure. gcpTrace would easily get changed out from under you when the various requests are processed "simultaneously" especially if you are using async/await at all in your request handlers.

As I see it, the problem is two-fold... How do you get the gcpTrace value out of the context and then how do you hand it to AwesomeLog. And unfortuantely I dont have a better answer on either of those. I will think some more on how the second part could be done with AL, but you still have to solve the first part in a meaningful way.

That said, I think your best bet, knowing your specific code base as I do, would be for you to just send the trace context value as an argument in the log message args, and then in DataDog, alias that into the field you need it to be. DD is good at things like that.

Log.info('hello world',{
  gcpTrace,
}

But I think you want to extract the trace context value out in the request handler, not in some middleware, if you want to avoid the race condition stuff.

router.get('/blah',(ctx) => {
  const gcpTrace = getTraceFromContext(ctx);
  Log.info('hello world',{
    gcpTrace,
  }
});

You could also consider creating a WhiteboxLog wrapper around AwesomeLog that could wrap the Log.blah() calls, and if the first argument in a ctx object, extract the trace out of that. Would be more work for you to change all the require statements, but might actually be the way to go here. Then you can just call Log.blah(ctx,"message", arg1, arg2) etc.

[arei]

Actually was just looking at the code and you might be able to do this...

  Log.log({
    gcpToken,
    level: "error",
    text: "my log message",
    args: [ ... any arg objects ... ],
  });

So basically you are just calling Log.log() directly and providing the base LogEntry object which is what is passed around internally. Log.error() and the like are just wrappers around Log.log(). You might couple this with the note above about creating your own wrapper.

[optikalefx]

You've hit the nail on the head with the race condition. Because the logger is global, and the request is not, the global logger will never be able to log the traceId.

Even with a wrapper, you still have the problem. Your second comment there is also correct, that does work. But of course making sure the developer 1) has access to the token everywhere, and 2) changing the way it's called.

I think the best solution i've come up with, is to use req.log.info('my log here') and because this is "on the request" we can have middleware add the gcp trace bits.

The problem remains though, if you have any classes, they somehow need access to the request, which you really don't want common classes to have know about a request.

Not great solutions as far as I can tell.

[arei]

Well you are essentially just moving the wrapper logic I suggest to the request context, but thats fine. I’d still avoid doing any work in the middleware and instead just try to inline it. some frameworks “thread” the middleware stuff so you could be right back in the race condition boat.

As for the nested/dependent class/code stuff, yea, that’s gonna be a problem. One idea might be to have a call that essentially creates a log transaction, and then you can hand the transaction around, but you, the end user of AL would still be responsible for passing the transaction everywhere. Not ideal.

I’ll think on it some more but I’m not optimistic.

[arei]

I have an idea for a partial solution on my end... you will still need to solve the problem on you end though.

From AwesomeLog's side... I can create a new class called LogEntryOverride which takes an object during construction. You can then pass an instance of LogEntryOverride into the Log.error() call and if one of these is in that call, it will merge the LogEntryOverride object details into the LogEntry object that was created and remove it from the args passed to the log message.

This thus lets you mutate a LogEntry on a one off approach, as opposed to the hooks approach which is more global.

Example...

  const override = new LogEntryOverride({
    gcpTrace: myGcpTraceValue,
  });
  Log.error(ex,override);

[arei]

I have published v4.4.0 with the above LogEntryOverride included. Let me know if that helps.

Please, please, please test this version before putting into production. v4.3.0 and v4.4.0 have changes that could potentially cause issues for your system.

[optikalefx]

@arei I was able to figure all this out. It was complicated. But basically, I needed a tracing tool first. I used OpenTelemetry for that. Then, I was able to, using the beforeWriteHook, get the active trace & span, and inject that into the log. B/c the tracer is global, it doesn't have to be in the http context.

export const instrumentLogger = (logEntry) => {
	const span = trace.getSpan(context.active());
	if (span) {
		const spanContext = trace.getSpanContext(context.active());
		logEntry.spanId = spanContext.spanId;
		logEntry.traceId = spanContext.traceId;
	}
};

The only thing we have left to deal with, is that the Whitebox ConigService cannot be overridden to take the beforeWrite hook, but that's easily modified.

Just wanted to update you on the saga. Thanks for helping out with it as well!

[optikalefx]

As an aside, if you wanted to, the other big logging libraries have built-ins for openTelemetry.

npm install @opentelemetry/instrumentation-bunyan
npm install @opentelemetry/instrumentation-pino
npm install @opentelemetry/instrumentation-winston

These look too complicated for me to make one on my own, but it's something you could offer one day if you wanted to.