Inject trace ids into paperplane logs

[flintinatux]

What does this PR do?

Adds support for log injection in paperplane.

Motivation

When I first made the plugin for paperplane, I followed the examples of express and hapi. Those don't have built-in logging, but paperplane does, and I totally overlooked it. We'd like our logs to be correlated with traces in APM, so this PR aims to enable that.

Plugin Checklist

• Unit tests.
• TypeScript definitions.
• TypeScript tests.
• API documentation.
• CircleCI jobs/workflows.
• Plugin is exported.

Additional Notes

This does bump the supported version of paperplane to v2.3.1. That's because log injection on error logs doesn't work before that version.

[rochdev]

Linting is failing because of the console.* statement. Feel free to disable this ESLint rule on the block since these are necessary for the tests.

[rochdev]

Why the version bump?

[flintinatux]

Because this was needed to make log injection work for errors:
articulate/paperplane#46

[rochdev]

Support for 2.3.0 could be kept but would just be missing log injection.

[flintinatux]

You know, that's a good point. Let me see if I can make that work (probably on Monday). When I do, should I document that difference somewhere?

[rochdev]

Let me see if I can make that work

You can find a good example of different feature support by version in the hapi plugin.

When I do, should I document that difference somewhere?

I would say to add a note in the docs, or simply add paperplane to the list of supported loggers with >=2.3.1 as the version.

[flintinatux]

@rochdev, thanks for the heads up on the linting. I ran yarn lint when I was spiking out the code, but forgot to do it again after I finished up the tests. 😅

[flintinatux]

@rochdev, we realized that patching the logger properly required an internal refactor to make monkey-patching with shimmer work correctly. Otherwise, exported functions like logger that are reused by other functions wouldn't be patched internally. Consequently, we've bumped paperplane yet again to v2.3.2.

However, I was able to continue support for v2.3.0-2.3.1, just without log injection, as you suggested. Please let me know what you think. Thanks!

[rochdev]

@flintinatux Is it supported to use the logger outside the scope of paperplane? For example using it as the logger for the tracer like this: tracer.init({ logger: paperplane.logger }).

For that to work, the logger (and thus paperplane) needs to be imported before the tracer, which wouldn't work with the current approach if I'm not mistaken.

[flintinatux]

That wasn't really an intended use case for us, mostly because I always thought you had to require the tracer before anything else that you wanted to be patched.

Are there plugins that can patch after-the-fact like that?

[flintinatux]

Oh, but the answer to your first question: yes, we do use paperplane.logger as a general use logger outside of the paperplane request cycle. It helps serialize POJO's and Error's as JSON for parsing with log aggregators like Datadog, etc.

[rochdev]

Are there plugins that can patch after-the-fact like that?

Loggers mostly 😅. It can work in some cases with other plugins as well, but the ones that we explicitly tested were loggers since to use them with the tracer they have to be imported beforehand.

Do you think there's a way this could work with paperplane as well? I'll still merge this PR anyway regardless, but if it can be handled, it would definitely be nice to have it. Otherwise users will have to choose between using the built-in logger with the tracer, or having log injection.

[rochdev]

I wonder if some kind of check could be added if the logger was already patched, and patch it otherwise, in both the public API and the internal one. This would technically result in 2 different logger instances when patched after the fact, but in general that wouldn't cause issues.

@flintinatux Do you think that would work? Another option could be to proxy the call in the index, so that it's just delegating to the underlying logger 🤔 Something like exports.logger = record => logger.logger(record).

[flintinatux]

If I had to guess, it works for other loggers because they are OOP, so they can patch the prototype after-the-fact, and it swaps out the underlying implementation, even for existing instances.

That won't work for paperplane since it's 💯 FP. All of its functions are first class, not prototype methods. And since functions are passed by reference, swapping out the export after-the-fact wouldn't affect existing references.

However, I think you could work around it with the magic of javascript variable scoping:

// wrap it as a custom logger
const myLogger = x =>
  paperplane.logger(x)

// init with your custom logger
const tracer = require('dd-trace').init({ logger: myLogger })

// then require paperplane after it's been patched
const paperplane = require('paperplane')

[rochdev]

Makes sense. This won't work for anything logged while the tracer is initializing, but I think that's a reasonable limitation. We could always solve this in the tracer by deferring the actual call to the logger to the next tick.