Feat/improve log

[torives]

Closes #308.

[endersonmaia]

When I start the node, I expect all CARTESI_ variables to be printed so I can see what was used.

Maybe we should treat all the same and redact what is sensitive data.

Also, why these 2 first lines are different from the following?

node-1  | time=2024-02-15T10:43:08.825Z level=INFO msg="read environment variable" env=CARTESI_LOG_LEVEL value=info
node-1  | time=2024-02-15T10:43:08.825Z level=INFO msg="read environment variable" env=CARTESI_LOG_PRETTY value=true
node-1  | Feb 15 10:43:08.825 INF starting Cartesi Rollups Node version=devel
node-1  | Feb 15 10:43:08.825 INF read environment variable env=CARTESI_HTTP_PORT value=10000
node-1  | Feb 15 10:43:08.825 INF read environment variable env=CARTESI_BLOCKCHAIN_ID value=31337
node-1  | Feb 15 10:43:08.825 INF read environment variable env=CARTESI_CONTRACTS_APPLICATION_ADDRESS value=0x180763470853cAF642Df79a908F9282c61692A45
node-1  | Feb 15 10:43:08.826 INF read environment variable env=CARTESI_CONTRACTS_INPUT_BOX_DEPLOYMENT_BLOCK_NUMBER value=17
node-1  | Feb 15 10:43:08.826 INF read environment variable env=CARTESI_BLOCKCHAIN_FINALITY_OFFSET value=1
node-1  | Feb 15 10:43:08.826 INF read environment variable env=CARTESI_BLOCKCHAIN_WS_ENDPOINT value=ws://devnet:8545
node-1  | Feb 15 10:43:08.826 INF read environment variable env=CARTESI_BLOCKCHAIN_HTTP_ENDPOINT value=http://devnet:8545
node-1  | Feb 15 10:43:08.826 INF read environment variable env=CARTESI_FEATURE_HOST_MODE value=false
node-1  | Feb 15 10:43:08.826 INF read environment variable env=CARTESI_FEATURE_DISABLE_CLAIMER value=false
node-1  | Feb 15 10:43:08.826 INF read environment variable env=CARTESI_BLOCKCHAIN_IS_LEGACY value=false
node-1  | Feb 15 10:43:08.826 INF read environment variable env=CARTESI_CONTRACTS_HISTORY_ADDRESS value=0xbCc4067dfdeE8274E531951f0968EC895f397A44
node-1  | Feb 15 10:43:08.826 INF read environment variable env=CARTESI_CONTRACTS_AUTHORITY_ADDRESS value=0xb090149a3cA43000681B74875500854B54355496
node-1  | Feb 15 10:43:08.826 INF read environment variable env=CARTESI_CONTRACTS_INPUT_BOX_ADDRESS value=0xCf7Ed3AccA5a467e9e704C703E8D87F634fB0Fc9
node-1  | Feb 15 10:43:08.826 INF read environment variable env=CARTESI_SNAPSHOT_DIR value=/usr/share/cartesi/snapshot
node-1  | Feb 15 10:43:08.826 INF read environment variable env=CARTESI_CONTRACTS_APPLICATION_DEPLOYMENT_BLOCK_NUMBER value=17
node-1  | Feb 15 10:43:08.826 INF read environment variable env=CARTESI_EPOCH_DURATION value=120
node-1  | Feb 15 10:43:08.826 INF read environment variable env=CARTESI_HTTP_ADDRESS value=0.0.0.0

[omidasadpour]

Also the logs should not print senstitve data like CARTESI_AUTH_AWS_KMS_KEY_ID. (I've changed the key id and put a fake key ID in the logs)

INFO authority-claimer:  INFO log: Starting Authority Claimer (version=1.3.0, git ref=N/A, git hash=N/A) with config Config { authority_claimer_config: AuthorityClaimerConfig { tx_manager_config: TxManagerConfig { default_confirmations: 1, provider_http_endpoint: "https://eth-sepolia.g.alchemy.com/v2/nuDbqy5ApW0s9E9igbuHROSivczxsEAk", chain_id: 11155111, chain_is_legacy: false, database_path: "./default_tx_database", gas_oracle_api_key: "" }, tx_signing_config: Aws { key_id: "2478723487384-752b-4787-bddf-lksdlksldklskd", region: UsEast1 }, tx_manager_priority: Normal, broker_config: BrokerConfig { redis_endpoint: Single(redis://127.0.0.1:10011), consume_timeout: 5000, backoff: ExponentialBackoff { current_interval: 500ms, initial_interval: 500ms, randomization_factor: 0.5, multiplier: 1.5, max_interval: 60s, start_time: Instant { tv_sec: 100069, tv_nsec: 289874501 }, max_elapsed_time: Some(120s), clock: SystemClock } }, log_config: LogConfig { enable_timestamp: false, enable_color: false }, contracts_config: ContractsConfig { history_address: 76f4dcac0920826541ee718214eee4be07346cee, authority_address: 5827ec9365d3a9b27bf1db982d258ad234d37242 }, genesis_block: 3963384 }, http_server_config: HttpServerConfig { port: 10002 } }

It prints the key_id :

2478723487384-752b-4787-bddf-lksdlksldklskd

[endersonmaia]

Also the logs should not print senstitve data like CARTESI_AUTH_AWS_KMS_KEY_ID. (I've changed the key id and put a fake key ID in the logs)

INFO authority-claimer:  INFO log: Starting Authority Claimer (version=1.3.0, git ref=N/A, git hash=N/A) with config Config { authority_claimer_config: AuthorityClaimerConfig { tx_manager_config: TxManagerConfig { default_confirmations: 1, provider_http_endpoint: "https://eth-sepolia.g.alchemy.com/v2/nuDbqy5ApW0s9E9igbuHROSivczxsEAk", chain_id: 11155111, chain_is_legacy: false, database_path: "./default_tx_database", gas_oracle_api_key: "" }, tx_signing_config: Aws { key_id: "2478723487384-752b-4787-bddf-lksdlksldklskd", region: UsEast1 }, tx_manager_priority: Normal, broker_config: BrokerConfig { redis_endpoint: Single(redis://127.0.0.1:10011), consume_timeout: 5000, backoff: ExponentialBackoff { current_interval: 500ms, initial_interval: 500ms, randomization_factor: 0.5, multiplier: 1.5, max_interval: 60s, start_time: Instant { tv_sec: 100069, tv_nsec: 289874501 }, max_elapsed_time: Some(120s), clock: SystemClock } }, log_config: LogConfig { enable_timestamp: false, enable_color: false }, contracts_config: ContractsConfig { history_address: 76f4dcac0920826541ee718214eee4be07346cee, authority_address: 5827ec9365d3a9b27bf1db982d258ad234d37242 }, genesis_block: 3963384 }, http_server_config: HttpServerConfig { port: 10002 } }

It prints the key_id :

2478723487384-752b-4787-bddf-lksdlksldklskd

I'm not sure how sensitive the kms key id is here, but I know it's essential for debugging and auditing.

[torives]

I'm not sure how sensitive the kms key id is here, but I know it's essential for debugging and auditing.

CARTESI_AUTH_AWS_KMS_KEY_ID and CARTESI_AUTH_AWS_KMS_REGION should be redacted according to the Cargo.toml file so, in principle, @oap75 was right. But now you got me questioning it: should we redact it or not?

Also, why these 2 first lines are different from the following?

This and #319 will be rebased on top of #318 after it is merged, so they'll be gone 😉

[torives]

When I start the node, I expect all CARTESI_ variables to be printed so I can see what was used.

They're currently looking like this (in a local branch):

Feb 15 10:05:52.167 INF Starting Cartesi Rollups Node config.CARTESI_BLOCKCHAIN_BLOCK_TIMEOUT=60 config.CARTESI_BLOCKCHAIN_FINALITY_OFFSET=1 config.CARTESI_BLOCKCHAIN_HTTP_ENDPOINT=http://localhost:8545 config.CARTESI_BLOCKCHAIN_ID=31337 config.CARTESI_BLOCKCHAIN_IS_LEGACY=false config.CARTESI_BLOCKCHAIN_WS_ENDPOINT=ws://localhost:8545 config.CARTESI_CONTRACTS_INPUT_BOX_DEPLOYMENT_BLOCK_NUMBER=17 config.CARTESI_CONTRACTS_APPLICATION_ADDRESS=0x180763470853cAF642Df79a908F9282c61692A45 config.CARTESI_CONTRACTS_APPLICATION_DEPLOYMENT_BLOCK_NUMBER=17 config.CARTESI_CONTRACTS_AUTHORITY_ADDRESS=0xb090149a3cA43000681B74875500854B54355496 config.CARTESI_CONTRACTS_HISTORY_ADDRESS=0xbCc4067dfdeE8274E531951f0968EC895f397A44 config.CARTESI_CONTRACTS_INPUT_BOX_ADDRESS=0xCf7Ed3AccA5a467e9e704C703E8D87F634fB0Fc9 config.CARTESI_EXPERIMENTAL_SUNODO_VALIDATOR_ENABLED=false config.CARTESI_EXPERIMENTAL_SUNODO_VALIDATOR_REDIS_ENDPOINT="" config.CARTESI_FEATURE_DISABLE_CLAIMER=false config.CARTESI_FEATURE_DISABLE_MACHINE_HASH_CHECK=false config.CARTESI_FEATURE_HOST_MODE=false config.CARTESI_HTTP_ADDRESS=127.0.0.1 config.CARTESI_HTTP_PORT=10000 config.CARTESI_LOG_LEVEL=1 config.CARTESI_LOG_PRETTY=true config.CARTESI_EPOCH_DURATION=2m0s config.CARTESI_SNAPSHOT_DIR=/Users/yves/workspace/cartesi/rollups-node/machine-snapshot config.CartesiAuth.Mnemonic=[REDACTED] config.CartesiAuth.AccountIndex=[REDACTED]

@endersonmaia The only change I'm still planning is to change CARTESI_LOG_LEVEL to a string, so it's clearer what it means. Let me know what you think.

[endersonmaia]

When I start the node, I expect all CARTESI_ variables to be printed so I can see what was used.

They're currently looking like this (in a local branch):

Feb 15 10:05:52.167 INF Starting Cartesi Rollups Node config.CARTESI_BLOCKCHAIN_BLOCK_TIMEOUT=60 config.CARTESI_BLOCKCHAIN_FINALITY_OFFSET=1 config.CARTESI_BLOCKCHAIN_HTTP_ENDPOINT=http://localhost:8545 config.CARTESI_BLOCKCHAIN_ID=31337 config.CARTESI_BLOCKCHAIN_IS_LEGACY=false config.CARTESI_BLOCKCHAIN_WS_ENDPOINT=ws://localhost:8545 config.CARTESI_CONTRACTS_INPUT_BOX_DEPLOYMENT_BLOCK_NUMBER=17 config.CARTESI_CONTRACTS_APPLICATION_ADDRESS=0x180763470853cAF642Df79a908F9282c61692A45 config.CARTESI_CONTRACTS_APPLICATION_DEPLOYMENT_BLOCK_NUMBER=17 config.CARTESI_CONTRACTS_AUTHORITY_ADDRESS=0xb090149a3cA43000681B74875500854B54355496 config.CARTESI_CONTRACTS_HISTORY_ADDRESS=0xbCc4067dfdeE8274E531951f0968EC895f397A44 config.CARTESI_CONTRACTS_INPUT_BOX_ADDRESS=0xCf7Ed3AccA5a467e9e704C703E8D87F634fB0Fc9 config.CARTESI_EXPERIMENTAL_SUNODO_VALIDATOR_ENABLED=false config.CARTESI_EXPERIMENTAL_SUNODO_VALIDATOR_REDIS_ENDPOINT="" config.CARTESI_FEATURE_DISABLE_CLAIMER=false config.CARTESI_FEATURE_DISABLE_MACHINE_HASH_CHECK=false config.CARTESI_FEATURE_HOST_MODE=false config.CARTESI_HTTP_ADDRESS=127.0.0.1 config.CARTESI_HTTP_PORT=10000 config.CARTESI_LOG_LEVEL=1 config.CARTESI_LOG_PRETTY=true config.CARTESI_EPOCH_DURATION=2m0s config.CARTESI_SNAPSHOT_DIR=/Users/yves/workspace/cartesi/rollups-node/machine-snapshot config.CartesiAuth.Mnemonic=[REDACTED] config.CartesiAuth.AccountIndex=[REDACTED]

@endersonmaia The only change I'm still planning is to change CARTESI_LOG_LEVEL to a string, so it's clearer what it means. Let me know what you think.

Ok, keep in mind that now, the log is like this:

And since we don't have log level prefix anywhere, it was hard to find the error (I usually filter for err or ERR, for ex.).

CONFIG 2024/02/15 14:37:33 read CARTESI_CONTRACTS_APPLICATION_ADDRESS environment variable: 0x9f12D4365806FC000D6555ACB85c5371b464E506
missing auth environment variables
CONFIG 2024/02/15 14:37:33 read CARTESI_CONTRACTS_INPUT_BOX_DEPLOYMENT_BLOCK_NUMBER environment variable: 3963384

If I got you idea right, you'll put all the config log in a single line, right?

I'd just ask that, if any error is found in any configuration, that we get a single line for it.

And, if we can parse all the config before, and show all the errors, it would be even better. So that I don't get into the loop of fixing one error, and getting another "new" one after the next time I start the rollups-node.

Tell me if you need me to create issues instead of just commenting here.

[torives]

I'd just ask that, if any error is found in any configuration, that we get a single line for it.

@endersonmaia Got it.

And, if we can parse all the config before, and show all the errors, it would be even better. So that I don't get into the loop of fixing one error, and getting another "new" one after the next time I start the rollups-node.

Yeah, this would be better. We were already discussing how to approach config validation, so your input is valuable.

Tell me if you need me to create issues instead of just commenting here.

The context is the same, so there's no need for new issues. I'll include these modifications here as soon as possible. Thanks for the feedback 😉

[endersonmaia]

I just noticed the datetime lack of pattern:

• Feb 15 10:05:52.167
• time=2024-02-15T10:43:08.825Z
• CONFIG 2024/02/16 01:26:06 (I think this is the current/old 1.3.0 version, and not the don't in this PR)

I suggest stick to ISO 8061 (2024-02-15T10:43:08.825Z this one is great).

[torives]

I just noticed the datetime lack of pattern:

• Feb 15 10:05:52.167
• time=2024-02-15T10:43:08.825Z
• CONFIG 2024/02/16 01:26:06 (I think this is the current/old 1.3.0 version, and not the don't in this PR)

I suggest stick to ISO 8061 (2024-02-15T10:43:08.825Z this one is great).

@endersonmaia Would RFC3339 2006-01-02T15:04:05Z07:00 suffice?

[endersonmaia]

I just noticed the datetime lack of pattern:

• Feb 15 10:05:52.167
• time=2024-02-15T10:43:08.825Z
• CONFIG 2024/02/16 01:26:06 (I think this is the current/old 1.3.0 version, and not the don't in this PR)

I suggest stick to ISO 8061 (2024-02-15T10:43:08.825Z this one is great).

@endersonmaia Would RFC3339 2006-01-02T15:04:05Z07:00 suffice?

Can we remove the timezone and get subseconds? If yes, I'm ok with it.

[torives]

I just noticed the datetime lack of pattern:

• Feb 15 10:05:52.167
• time=2024-02-15T10:43:08.825Z
• CONFIG 2024/02/16 01:26:06 (I think this is the current/old 1.3.0 version, and not the don't in this PR)

I suggest stick to ISO 8061 (2024-02-15T10:43:08.825Z this one is great).

@endersonmaia Would RFC3339 2006-01-02T15:04:05Z07:00 suffice?

Can we remove the timezone and get subseconds? If yes, I'm ok with it.

@endersonmaia we do get milliseconds, but to remove the timezone I would have to write a custom log handler to match the format between the default and pretty log styles (yep, it sucks). That's something that I very much would like to avoid.

[endersonmaia]

I just noticed the datetime lack of pattern:

• Feb 15 10:05:52.167
• time=2024-02-15T10:43:08.825Z
• CONFIG 2024/02/16 01:26:06 (I think this is the current/old 1.3.0 version, and not the don't in this PR)

I suggest stick to ISO 8061 (2024-02-15T10:43:08.825Z this one is great).

@endersonmaia Would RFC3339 2006-01-02T15:04:05Z07:00 suffice?

Can we remove the timezone and get subseconds? If yes, I'm ok with it.

@endersonmaia we do get milliseconds, but to remove the timezone I would have to write a custom log handler to match the format between the default and pretty log styles (yep, it sucks). That's something that I very much would like to avoid.

Maybe it gets this configuration from the OS timezone configuration? If we understand how this works, we can control its behavior.

[torives]

I just noticed the datetime lack of pattern:

• Feb 15 10:05:52.167
• time=2024-02-15T10:43:08.825Z
• CONFIG 2024/02/16 01:26:06 (I think this is the current/old 1.3.0 version, and not the don't in this PR)

I suggest stick to ISO 8061 (2024-02-15T10:43:08.825Z this one is great).

@endersonmaia Would RFC3339 2006-01-02T15:04:05Z07:00 suffice?

Can we remove the timezone and get subseconds? If yes, I'm ok with it.

@endersonmaia we do get milliseconds, but to remove the timezone I would have to write a custom log handler to match the format between the default and pretty log styles (yep, it sucks). That's something that I very much would like to avoid.

Maybe it gets this configuration from the OS timezone configuration? If we understand how this works, we can control its behavior.

Got a better solution: not using the default logger. I'll have full control over the time format and the only difference is that now CARTESI_LOG_PRETTY only adds color.

[torives]

Due to the change in scope in #318, #319 has become the new base for this PR.

[torives]

The code in PR #319 was moved to PR #354, which is now merged. So the main branch is the new base.