Pending logs are printed with incorrect timestamp

[aTeoke]

Airnode uses a pattern of “pending” logs, which makes functions store the logs and return them to be logged by some higher level function.

This is problematic since, the timestamp gets assigned once the logs are printed https://github.com/api3dao/airnode/blob/minor-examples-improvement/packages/airnode-node/src/logger.ts#L61 .

There are two options:

1. This pattern should be revisited whether there is not a better solution
2. Just add a timestamp to the pending logs and not just by the higher level function

[dcroote]

The above link is broken as the branch was deleted- here is a permalink from a commit on that branch: https://github.com/api3dao/airnode/blob/ee2a5a53708aca2416403f081799611c3ee6ec2a/packages/airnode-node/src/logger.ts#L61

[andreogle]

The reason for the "pending logs" was that I was trying to avoid any and all global variables, as they may have resulted in unexpected/unintended behaviour (e.g. stale cached data). I went with the approach of trying to keep ALL variables within the scope of the specific coordinator cycle so that they would be guaranteed to be fresh. I wasn't familiar with the idiosyncrasies of the different Serverless environments and this felt like the safest approach.

Specifically, I was worried about the logging metadata (coordinator ID, provider name, chain etc.). I also didn't want to pass these additional variables to all of the lower level functions for "cleaner"/simpler functions and easier testing. The functions that log something return a tuple and ESLint makes sure that there are no unused variables. i.e. the first tuple element (the logs) must be used in some way.

I'm aware that this approach has tradeoffs and the reasons are certainly not obvious to new readers of the code. I'm happy for this to be reconsidered, but just wanted to make sure the initial reasons were understood.

[Siegrift]

Thanks @andreogle , I think the implementation is justified and works well for servlerless. Since we plan to refactor Airnode to single lambda in the future we can revert to a more simple approach. Logging is hard and there is some inherent complexity to it:

• Initialization - Logger needs to be initialized (with log options). This was previously done too late, but it's correctly done at the start of the handler (in the deployer package). Every logger will need this since, the log level is part of the config.json...
• Metadata - As the Airnode execution progresses we want to assign metadata to better identify the log. This can be coordinator ID, provider name, RRP request ID and others... These are not global, but bound to some execution context (e.g. Lambda invocation, in which case it's also "global"). When we migrate to a single lambda, we need to be mindful about this...
• Performance - There is a good talk about this from Mateo (nodeJS maintainer, author of Fastify and Pino) https://www.youtube.com/watch?v=Dnx2SPdcDSU
• Flexibility - Our built-in logger just outputs to stdout. This is OK for basic stuff, but usually, loggers have a concept of "transport" which lets you send the logs somewhere else... For example, Airnode might support streaming logs to DataDog or other log services. Modern logging libraries offer multiple options for this.
• What to log and at which level - This is the most complex part tbh... Remember to log, and log at good places and at the most reasonable level. The sad thing is can't tell whether you have good logs, you just know when you don't (and struggle to debug).

Apart from the pending logs timestamp bug, I see other disadvantages of that concept. It's a good feature that we can accumulate the logs from "slaves" and print them by some "master" function, but this is error-prone. The logs need to be merged during accumulation (which is harder to read), and the master needs to remember to print them out (otherwise they are lost). These logs are propagated among many functions and it's hard to reason about this... I think we should just simply log when we need/want to log and let the logger tool process the log. I strongly think we should have structured logs so that we can easily filter/search stuff... (Not sure if we need a special tool for this or the native cloud provider log services are enough)...