Log metadata is overwritten in a single-process environment

[dcroote]

Description

When there are multiple Providers specified for a chain, the Airnode logs report incorrect Provider names within the log metadata, see the example below.

Version

Airnode v0.9, v0.10, master.

Present Behaviour

In config.json there are two providers:

     "id": "5",
      "providers": {
        "goerliPublic": {
          "url": "https://rpc.ankr.com/eth_goerli"
        },
        "goerliTestnet1": {
          "url": "${GOERLI_PROVIDER_URL}"
        }

Yet in the logs (in multiple places, below is one example), the metadata Provider is incorrect for one (they both say Provider:goerliTestnet1 at the end of the line on the far right):

2023-04-01 21:29:04 [2023-04-02 04:29:04.067] INFO Initialized EVM provider:goerliPublic                                            Coordinator-ID:ca47f3d2387ced05, Chain-ID:5, Provider:goerliTestnet1
2023-04-01 21:29:04 [2023-04-02 04:29:04.068] INFO Initialized EVM provider:goerliTestnet1                                          Coordinator-ID:ca47f3d2387ced05, Chain-ID:5, Provider:goerliTestnet1

This makes troubleshooting confusing as it is not clear what provider the logs are attributable to.

Expected Behaviour

Log metadata should report the correct Provider names.

Steps to reproduce

Run Airnode with more than one Provider.

[bbenligiray]

~As a note, I'm pretty sure that this is a somewhat new issue because I went through a lot of multi-provider logs a few months ago. Makes me think that this may be related to that v0.10 issue.~ I don't use airnode-client much so ignore this.

[dcroote]

It turns out both are true. The issue doesn't affect Airnode deployed to AWS (v0.9 or v0.10), but does affect airnode-client back to at least v0.9, and including v0.10 and master which I tested when creating the issue.

airnode-client:0.9.2

2023-04-02 11:45:03 [2023-04-02 18:45:03.880] INFO Initialized EVM provider:goerliPublic        Coordinator-ID:6af849d09ace5cb9, Chain-ID:5, Provider:goerliTestnet1
2023-04-02 11:45:03 [2023-04-02 18:45:03.880] INFO Initialized EVM provider:goerliTestnet1      Coordinator-ID:6af849d09ace5cb9, Chain-ID:5, Provider:goerliTestnet1

airnode-deployer:0.9.2 and airnode-deployer:0.10.0

AWS logs: The startCoordinator logs don't have Provider as metadata

INFO [2023-04-02 19:29:11.671] INFO Initialized EVM provider:goerliPublic Coordinator-ID:538bad185ef80309
INFO [2023-04-02 19:29:11.671] INFO Initialized EVM provider:goerliTestnet1 Coordinator-ID:538bad185ef80309

And the run logs depict sets for each of the Providers with the appropriate Provider metadata.

I did notice that among the two run log streams, it seems arbitrary which provider is used for each stream for each cycle. I'm not sure if this is configurable, but it'd be nice if it was a single stream for each provider and rather than intermingled. For example, INFO Pending requests logs for 6 cycles in stream 1 had the following Providers:

Provider:goerliTestnet1
Provider:goerliTestnet1
Provider:goerliPublic
Provider:goerliPublic
Provider:goerliTestnet1
Provider:goerliPublic

And stream 2 had the opposite Providers:

Provider:goerliPublic
Provider:goerliPublic
Provider:goerliTestnet1
Provider:goerliTestnet1
Provider:goerliPublic
Provider:goerliTestnet1

[dcroote]

For unclear reasons, when using the airnode-client the Provider in the log metadata is consistently the last one that is defined. For example, goerliPublic3 is the last one defined in chains[0].providers (where I intentionally use broken provider URLs so initialization fails):

[2023-04-03 05:59:03.146] INFO Forking to initialize providers  Coordinator-ID:c42cc52ca74b1794
[2023-04-03 05:59:06.949] ERROR Failed to initialize provider:goerliPublic0  Coordinator-ID:c42cc52ca74b1794, Chain-ID:5, Provider:goerliPublic3
[2023-04-03 05:59:06.950] ERROR Failed to initialize provider:goerliPublic1  Coordinator-ID:c42cc52ca74b1794, Chain-ID:5, Provider:goerliPublic3
[2023-04-03 05:59:06.950] ERROR Failed to initialize provider:goerliPublic2  Coordinator-ID:c42cc52ca74b1794, Chain-ID:5, Provider:goerliPublic3
[2023-04-03 05:59:06.951] ERROR Failed to initialize provider:goerliPublic3  Coordinator-ID:c42cc52ca74b1794, Chain-ID:5, Provider:goerliPublic3
[2023-04-03 05:59:06.954] INFO Forking to initialize providers complete     Coordinator-ID:c42cc52ca74b1794, Chain-ID:5, Provider:goerliPublic3

[amarthadan]

I presume this is because when running Airnode locally it doesn't really run as multiple processes (as the cloud version). So, when we call logger.addMetadata function to add info about the chain ID and provider, it sets it for one global logger singleton, each call overriding the previous one, resulting in only the last one being used.

[dcroote]

That makes sense, which would imply we need to pass provider and chainId for each log.

[dcroote]

After more work, I recommend pushing this issue to the Airnode release containing the single lambda Airnode.

As @amarthadan mentions above, log metadata e.g. Chain-ID, Provider, Sponsor-Address, etc. gets overwritten in a single-process environment, which is effectively what we'll have when switching from multiple lambdas to a single lambda. Consequently, our current approach to reporting these metadata will break (like how it is broken now for airnode-client) and require an overhaul to the very large proportion of logs that currently contain metadata. I've updated the issue title to reflect this broader scope.

CC @aTeoke, @Siegrift

[dcroote]

This is an issue that needs to be solved when implementing https://github.com/api3dao/airnode/issues/1478