Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Log metadata is overwritten in a single-process environment #1708

Open
dcroote opened this issue Apr 2, 2023 · 7 comments
Open

Log metadata is overwritten in a single-process environment #1708

dcroote opened this issue Apr 2, 2023 · 7 comments
Labels
bug Something needs to be fixed
Milestone

Comments

@dcroote
Copy link
Contributor

dcroote commented Apr 2, 2023

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
Copy link
Member

bbenligiray commented Apr 2, 2023

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
Copy link
Contributor Author

dcroote commented Apr 2, 2023

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 dcroote changed the title Wrong Provider name is reported in log metadata Wrong Provider name is reported in airnode-client log metadata Apr 3, 2023
@dcroote
Copy link
Contributor Author

dcroote commented Apr 3, 2023

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
Copy link
Contributor

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
Copy link
Contributor Author

dcroote commented Apr 3, 2023

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

@aTeoke aTeoke added the bug Something needs to be fixed label Apr 12, 2023
@dcroote dcroote self-assigned this Apr 12, 2023
@dcroote dcroote changed the title Wrong Provider name is reported in airnode-client log metadata Log metadata is overwritten in a single-process environment Apr 21, 2023
@dcroote
Copy link
Contributor Author

dcroote commented Apr 21, 2023

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 dcroote added this to the 0.13.0 milestone Apr 25, 2023
@dcroote
Copy link
Contributor Author

dcroote commented May 29, 2023

This is an issue that needs to be solved when implementing #1478

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
bug Something needs to be fixed
Projects
None yet
Development

No branches or pull requests

4 participants