Skip to content

chore: Cleanup sequencer logs#10407

Closed
spalladino wants to merge 16 commits intopalla/logger-scopesfrom
palla/sequencer-logs
Closed

chore: Cleanup sequencer logs#10407
spalladino wants to merge 16 commits intopalla/logger-scopesfrom
palla/sequencer-logs

Conversation

@spalladino
Copy link
Contributor

@spalladino spalladino commented Dec 4, 2024

Builds on #10404

Sample output of a run with sequencer on debug level:

[19:35:30.751] DEBUG: sequencer:publisher Publishing from address 0xf39Fd6e51aad88F6F4ce6aB8827279cffFb92266
[19:35:31.489] INFO: sequencer Sequencer config set
    transactionPollingIntervalMS: 1000
    maxTxsPerBlock: 32
    minTxsPerBlock: 1
    minSecondsBetweenBlocks: 0
    maxSecondsBetweenBlocks: 0
    acvmWorkingDirectory: "/tmp/d2789769/acvm"
    acvmBinaryPath: "../../noir/noir-repo/target/release/acvm"
    maxBlockSizeInBytes: 1048576
    enforceFees: false
[19:35:31.489] DEBUG: sequencer Transitioning from STOPPED to IDLE
[19:35:31.490] DEBUG: sequencer Transitioning from IDLE to SYNCHRONIZING
[19:35:31.490] INFO: sequencer Sequencer started
[19:35:31.494] DEBUG: sequencer Sequencer sync check succeeded
    worldStateNumber: 0
    worldStateHash: "0x2da55666630fdf8594065c377958c827dc1c130dac91f17c6699b53dce60ef75"
    l2BlockSourceNumber: 0
    p2pNumber: 0
    l1ToL2MessageSourceNumber: 0
[19:35:31.494] DEBUG: sequencer Transitioning from SYNCHRONIZING to PROPOSER_CHECK
[19:35:31.560] DEBUG: sequencer Last block mined at 0 current time is 1733351731 (elapsed 1733351731)
[19:35:31.560] VERBOSE: sequencer Preparing proposal for block 1 at slot 3
    chainTipArchive: "0x0237797d6a2c04d20d4fa06b74482bd970ccd51a43d9b05b57e9b91fa1ae1cae"
    blockNumber: 1
    slot: 3
[19:35:31.560] DEBUG: sequencer Transitioning from PROPOSER_CHECK to WAITING_FOR_TXS
[19:35:31.561] DEBUG: sequencer Last block mined at 0 current time is 1733351731 (elapsed 1733351731)
[19:35:31.561] VERBOSE: sequencer Not creating block because not enough txs in the pool (got 0 min 1)
[19:35:31.561] DEBUG: sequencer Transitioning from WAITING_FOR_TXS to IDLE
[19:35:32.562] DEBUG: sequencer Transitioning from IDLE to SYNCHRONIZING
[19:35:32.565] DEBUG: sequencer Sequencer sync check succeeded
    worldStateNumber: 0
    worldStateHash: "0x2da55666630fdf8594065c377958c827dc1c130dac91f17c6699b53dce60ef75"
    l2BlockSourceNumber: 0
    p2pNumber: 0
    l1ToL2MessageSourceNumber: 0
[19:35:32.565] DEBUG: sequencer Transitioning from SYNCHRONIZING to PROPOSER_CHECK
[19:35:32.576] DEBUG: sequencer Last block mined at 0 current time is 1733351732 (elapsed 1733351732)
[19:35:32.577] VERBOSE: sequencer Preparing proposal for block 1 at slot 3
    chainTipArchive: "0x0237797d6a2c04d20d4fa06b74482bd970ccd51a43d9b05b57e9b91fa1ae1cae"
    blockNumber: 1
    slot: 3
[19:35:32.577] DEBUG: sequencer Transitioning from PROPOSER_CHECK to WAITING_FOR_TXS
[19:35:32.610] DEBUG: sequencer Last block mined at 0 current time is 1733351732 (elapsed 1733351732)
[19:35:32.610] VERBOSE: sequencer Retrieved 1 txs for block 1 with global variables
    chainId: 31337
    version: 1
    blockNumber: 1
    slotNumber: 3
    coinbase: "0x0000000000000000000000000000000000000000"
    feeRecipient: "0x0000000000000000000000000000000000000000000000000000000000000000"
    feePerDaGas: 0
    feePerL2Gas: 54189829560
[19:35:32.616] DEBUG: sequencer Last block mined at 0 current time is 1733351732 (elapsed 1733351732)
[19:35:32.620] DEBUG: sequencer Transitioning from WAITING_FOR_TXS to CREATING_BLOCK
[19:35:32.620] DEBUG: sequencer Requesting L1 to L2 messages from contract for block 1
[19:35:32.620] VERBOSE: sequencer Building block 1
    msgCount: 0
    txCount: 1
    slot: 3
    blockNumber: 1
[19:35:32.621] DEBUG: sequencer Synced to previous block 0
[19:35:32.719] DEBUG: sequencer Last block mined at 0 current time is 1733351732 (elapsed 1733351732)
[19:35:32.745] VERBOSE: sequencer Built block 1
    txEffectsHash: "00245effb4ea9dcd36384e2ec2ba82309797e119e3ee308932e40de749bdb64d"
    eventName: "l2-block-built"
    creator: "0xf39fd6e51aad88f6f4ce6ab8827279cfffb92266"
    duration: 124.95624599605799
    publicProcessDuration: 89.1501849964261
    rollupCircuitsDuration: 119.30786000192165
    txCount: 1
    blockNumber: 1
    blockTimestamp: 1733351922
    unencryptedLogCount: 0
    unencryptedLogSize: 8
    contractClassLogCount: 0
    contractClassLogSize: 8
[19:35:32.745] DEBUG: sequencer Collecting attestations
[19:35:32.747] VERBOSE: sequencer Attesting committee length is 0
[19:35:32.747] VERBOSE: sequencer Collected 0 attestations
[19:35:32.747] DEBUG: sequencer Collecting proof quotes
[19:35:32.750] DEBUG: sequencer No epoch to prove
[19:35:32.750] DEBUG: sequencer Transitioning from CREATING_BLOCK to PUBLISHING_BLOCK
[19:35:32.758] DEBUG: sequencer:publisher Submitting propose transaction
[19:35:32.768] DEBUG: sequencer:publisher Computed gas price
    attempt: 0
    baseFee: "0.179871966"
    maxFeePerGas: "7.686190469"
    maxPriorityFeePerGas: "7.430083706"
[19:35:32.774] VERBOSE: sequencer:publisher Sent L1 transaction 0x761d51931c4f8f1173352ef77b8ae337f7edbe972105bdba5e21013533f8e513
    gasLimit: 12151874
    maxFeePerGas: "7.686190469"
    maxPriorityFeePerGas: "7.430083706"
[19:35:32.777] DEBUG: sequencer:publisher L1 transaction 0x761d51931c4f8f1173352ef77b8ae337f7edbe972105bdba5e21013533f8e513 mined
[19:35:32.779] VERBOSE: sequencer:publisher Published L2 block to L1 rollup contract
    gasPrice: 7587514534
    gasUsed: 461263
    transactionHash: "0x761d51931c4f8f1173352ef77b8ae337f7edbe972105bdba5e21013533f8e513"
    calldataGas: 12684
    calldataSize: 1476
    sender: "0xf39fd6e51aad88f6f4ce6ab8827279cfffb92266"
    txCount: 1
    blockNumber: 1
    blockTimestamp: 1733351922
    unencryptedLogCount: 0
    unencryptedLogSize: 8
    contractClassLogCount: 0
    contractClassLogSize: 8
    eventName: "rollup-published-to-l1"
    slotNumber: 3
    blockHash: "0x0c0fffd81e504b80a195c4c6d0b4da9e5a6463c339286d526a945893f195d53c"
[19:35:32.781] INFO: sequencer Published rollup block 1 with 1 transactions in 125ms
    blockNumber: 1
    blockHash: "0x0c0fffd81e504b80a195c4c6d0b4da9e5a6463c339286d526a945893f195d53c"
    slot: 3
    txCount: 1
    duration: 125
    submitter: "0xf39fd6e51aad88f6f4ce6ab8827279cfffb92266"
[19:35:32.781] DEBUG: sequencer Transitioning from PUBLISHING_BLOCK to IDLE
[19:35:32.781] DEBUG: sequencer Transitioning from IDLE to IDLE
[19:35:33.782] DEBUG: sequencer Transitioning from IDLE to SYNCHRONIZING
[19:35:33.787] DEBUG: sequencer Sequencer sync check succeeded
    worldStateNumber: 1
    worldStateHash: "0x0c0fffd81e504b80a195c4c6d0b4da9e5a6463c339286d526a945893f195d53c"
    l2BlockSourceNumber: 1
    l2BlockSourceHash: "0x0c0fffd81e504b80a195c4c6d0b4da9e5a6463c339286d526a945893f195d53c"
    p2pNumber: 1
    l1ToL2MessageSourceNumber: 1
[19:35:33.787] DEBUG: sequencer Transitioning from SYNCHRONIZING to PROPOSER_CHECK
[19:35:33.792] DEBUG: sequencer Rejected from being able to propose at next block with 0b1e27b24bb50e2861cffb10c8f380c5bc476f347c1e278b7427849ef5f40659: Rollup__SlotAlreadyInChain(3, 3)
[19:35:33.792] DEBUG: sequencer Cannot propose for block 2
[19:35:33.792] DEBUG: sequencer Transitioning from PROPOSER_CHECK to IDLE
[19:35:34.892] DEBUG: sequencer Transitioning from IDLE to SYNCHRONIZING
[19:35:34.894] DEBUG: sequencer Sequencer sync check succeeded
    worldStateNumber: 1
    worldStateHash: "0x0c0fffd81e504b80a195c4c6d0b4da9e5a6463c339286d526a945893f195d53c"
    l2BlockSourceNumber: 1
    l2BlockSourceHash: "0x0c0fffd81e504b80a195c4c6d0b4da9e5a6463c339286d526a945893f195d53c"
    p2pNumber: 1
    l1ToL2MessageSourceNumber: 1
[19:35:34.894] DEBUG: sequencer Transitioning from SYNCHRONIZING to PROPOSER_CHECK
[19:35:34.904] DEBUG: sequencer Last block mined at 1733351922 current time is 1733351734 (elapsed -188)
[19:35:34.904] VERBOSE: sequencer Preparing proposal for block 2 at slot 4
    chainTipArchive: "0x0b1e27b24bb50e2861cffb10c8f380c5bc476f347c1e278b7427849ef5f40659"
    blockNumber: 2
    slot: 4
[19:35:34.904] DEBUG: sequencer Transitioning from PROPOSER_CHECK to WAITING_FOR_TXS
[19:35:34.904] DEBUG: sequencer Last block mined at 1733351922 current time is 1733351734 (elapsed -188)
[19:35:34.904] VERBOSE: sequencer Not creating block because not enough txs in the pool (got 0 min 1)
[19:35:34.904] DEBUG: sequencer Transitioning from WAITING_FOR_TXS to IDLE
[19:35:35.956] DEBUG: sequencer Transitioning from IDLE to SYNCHRONIZING
[19:35:35.959] DEBUG: sequencer Sequencer sync check succeeded
    worldStateNumber: 1
    worldStateHash: "0x0c0fffd81e504b80a195c4c6d0b4da9e5a6463c339286d526a945893f195d53c"
    l2BlockSourceNumber: 1
    l2BlockSourceHash: "0x0c0fffd81e504b80a195c4c6d0b4da9e5a6463c339286d526a945893f195d53c"
    p2pNumber: 1
    l1ToL2MessageSourceNumber: 1
[19:35:35.959] DEBUG: sequencer Transitioning from SYNCHRONIZING to PROPOSER_CHECK
[19:35:35.969] DEBUG: sequencer Last block mined at 1733351922 current time is 1733351735 (elapsed -187)
[19:35:35.969] VERBOSE: sequencer Preparing proposal for block 2 at slot 4
    chainTipArchive: "0x0b1e27b24bb50e2861cffb10c8f380c5bc476f347c1e278b7427849ef5f40659"
    blockNumber: 2
    slot: 4
[19:35:35.969] DEBUG: sequencer Transitioning from PROPOSER_CHECK to WAITING_FOR_TXS
[19:35:35.969] DEBUG: sequencer Last block mined at 1733351922 current time is 1733351735 (elapsed -187)
[19:35:35.969] VERBOSE: sequencer Not creating block because not enough txs in the pool (got 0 min 1)
[19:35:35.969] DEBUG: sequencer Transitioning from WAITING_FOR_TXS to IDLE
[19:35:36.969] DEBUG: sequencer Transitioning from IDLE to SYNCHRONIZING
[19:35:36.971] DEBUG: sequencer Sequencer sync check succeeded
    worldStateNumber: 1
    worldStateHash: "0x0c0fffd81e504b80a195c4c6d0b4da9e5a6463c339286d526a945893f195d53c"
    l2BlockSourceNumber: 1
    l2BlockSourceHash: "0x0c0fffd81e504b80a195c4c6d0b4da9e5a6463c339286d526a945893f195d53c"
    p2pNumber: 1
    l1ToL2MessageSourceNumber: 1
[19:35:36.972] DEBUG: sequencer Transitioning from SYNCHRONIZING to PROPOSER_CHECK
[19:35:36.979] DEBUG: sequencer Last block mined at 1733351922 current time is 1733351736 (elapsed -186)
[19:35:36.979] VERBOSE: sequencer Preparing proposal for block 2 at slot 4
    chainTipArchive: "0x0b1e27b24bb50e2861cffb10c8f380c5bc476f347c1e278b7427849ef5f40659"
    blockNumber: 2
    slot: 4
[19:35:36.979] DEBUG: sequencer Transitioning from PROPOSER_CHECK to WAITING_FOR_TXS
[19:35:36.981] DEBUG: sequencer Last block mined at 1733351922 current time is 1733351736 (elapsed -186)
[19:35:36.981] VERBOSE: sequencer Retrieved 2 txs for block 2 with global variables
    chainId: 31337
    version: 1
    blockNumber: 2
    slotNumber: 4
    coinbase: "0x0000000000000000000000000000000000000000"
    feeRecipient: "0x0000000000000000000000000000000000000000000000000000000000000000"
    feePerDaGas: 0
    feePerL2Gas: 54189829560
[19:35:36.983] DEBUG: sequencer:tx_validator:tx_phases Tx 0x1ef80830ffc53b54c53ab489c7584aca588cd4ff73d7df46dfda1e54ed77d195 does not contain enqueued public functions. Skipping phases validation.
[19:35:36.984] DEBUG: sequencer:tx_validator:tx_phases Tx 0x286c851a99e8f49ed0832fabce2f85583666e594cb00b795d61c38f90a6aa479 does not contain enqueued public functions. Skipping phases validation.
[19:35:36.985] DEBUG: sequencer Last block mined at 1733351922 current time is 1733351736 (elapsed -186)
[19:35:36.989] DEBUG: sequencer Transitioning from WAITING_FOR_TXS to CREATING_BLOCK
[19:35:36.989] DEBUG: sequencer Requesting L1 to L2 messages from contract for block 2
[19:35:36.989] VERBOSE: sequencer Building block 2
    msgCount: 0
    txCount: 2
    slot: 4
    blockNumber: 2
[19:35:36.989] DEBUG: sequencer Synced to previous block 1
[19:35:37.049] DEBUG: sequencer Last block mined at 1733351922 current time is 1733351737 (elapsed -185)
[19:35:37.057] VERBOSE: sequencer Built block 2
    txEffectsHash: "00d9cd152c3af576f1bb97f2b6d907e6cd149130cdd018ace83db03c18f96e52"
    eventName: "l2-block-built"
    creator: "0xf39fd6e51aad88f6f4ce6ab8827279cfffb92266"
    duration: 68.03451900184155
    publicProcessDuration: 42.27969899773598
    rollupCircuitsDuration: 53.46137099713087
    txCount: 2
    blockNumber: 2
    blockTimestamp: 1733351946
    unencryptedLogCount: 0
    unencryptedLogSize: 8
    contractClassLogCount: 0
    contractClassLogSize: 16
[19:35:37.057] DEBUG: sequencer Collecting attestations
[19:35:37.058] VERBOSE: sequencer Attesting committee length is 0
[19:35:37.058] VERBOSE: sequencer Collected 0 attestations
[19:35:37.058] DEBUG: sequencer Collecting proof quotes
[19:35:37.059] DEBUG: sequencer No epoch to prove
[19:35:37.059] DEBUG: sequencer Transitioning from CREATING_BLOCK to PUBLISHING_BLOCK
[19:35:37.063] DEBUG: sequencer:publisher Submitting propose transaction
[19:35:37.079] DEBUG: sequencer:publisher Computed gas price
    attempt: 0
    baseFee: "0.138357117"
    maxFeePerGas: "1.396996753"
    maxPriorityFeePerGas: "1.2"
[19:35:37.085] VERBOSE: sequencer:publisher Sent L1 transaction 0x7a65ebfc7a5a4fe00c7a2f5074c2b1fe1868f4bee64385cd723b15d977fb2487
    gasLimit: 12332304
    maxFeePerGas: "1.396996753"
    maxPriorityFeePerGas: "1.2"
[19:35:37.089] DEBUG: sequencer:publisher L1 transaction 0x7a65ebfc7a5a4fe00c7a2f5074c2b1fe1868f4bee64385cd723b15d977fb2487 mined
[19:35:37.091] VERBOSE: sequencer:publisher Published L2 block to L1 rollup contract
    gasPrice: 1321062478
    gasUsed: 560463
    transactionHash: "0x7a65ebfc7a5a4fe00c7a2f5074c2b1fe1868f4bee64385cd723b15d977fb2487"
    calldataGas: 32676
    calldataSize: 2820
    sender: "0xf39fd6e51aad88f6f4ce6ab8827279cfffb92266"
    txCount: 2
    blockNumber: 2
    blockTimestamp: 1733351946
    unencryptedLogCount: 0
    unencryptedLogSize: 8
    contractClassLogCount: 0
    contractClassLogSize: 16
    eventName: "rollup-published-to-l1"
    slotNumber: 4
    blockHash: "0x0ec8b235ee8b43ca3b150e41231c379ff569fcd2526e72585933025835f7b930"
[19:35:37.091] INFO: sequencer Published rollup block 2 with 2 transactions in 69ms
    blockNumber: 2
    blockHash: "0x0ec8b235ee8b43ca3b150e41231c379ff569fcd2526e72585933025835f7b930"
    slot: 4
    txCount: 2
    duration: 69
    submitter: "0xf39fd6e51aad88f6f4ce6ab8827279cfffb92266"
[19:35:37.092] DEBUG: sequencer Transitioning from PUBLISHING_BLOCK to IDLE
[19:35:37.092] DEBUG: sequencer Transitioning from IDLE to IDLE
[19:35:38.092] DEBUG: sequencer Transitioning from IDLE to SYNCHRONIZING
[19:35:38.100] DEBUG: sequencer Sequencer sync check succeeded
    worldStateNumber: 2
    worldStateHash: "0x0ec8b235ee8b43ca3b150e41231c379ff569fcd2526e72585933025835f7b930"
    l2BlockSourceNumber: 2
    l2BlockSourceHash: "0x0ec8b235ee8b43ca3b150e41231c379ff569fcd2526e72585933025835f7b930"
    p2pNumber: 2
    l1ToL2MessageSourceNumber: 2
[19:35:38.100] DEBUG: sequencer Transitioning from SYNCHRONIZING to PROPOSER_CHECK
[19:35:38.109] DEBUG: sequencer Last block mined at 1733351946 current time is 1733351738 (elapsed -208)
[19:35:38.109] VERBOSE: sequencer Preparing proposal for block 3 at slot 5
    chainTipArchive: "0x204e928bc35b3d9c7e6c19900430dfd755e6c5161fe8becbd3432a22bbb5e424"
    blockNumber: 3
    slot: 5
[19:35:38.109] DEBUG: sequencer Transitioning from PROPOSER_CHECK to WAITING_FOR_TXS
[19:35:38.109] DEBUG: sequencer Last block mined at 1733351946 current time is 1733351738 (elapsed -208)
[19:35:38.109] VERBOSE: sequencer Not creating block because not enough txs in the pool (got 0 min 1)
[19:35:38.109] DEBUG: sequencer Transitioning from WAITING_FOR_TXS to IDLE
[19:35:39.587] DEBUG: sequencer Transitioning from IDLE to SYNCHRONIZING
[19:35:39.590] DEBUG: sequencer Sequencer sync check succeeded
    worldStateNumber: 2
    worldStateHash: "0x0ec8b235ee8b43ca3b150e41231c379ff569fcd2526e72585933025835f7b930"
    l2BlockSourceNumber: 2
    l2BlockSourceHash: "0x0ec8b235ee8b43ca3b150e41231c379ff569fcd2526e72585933025835f7b930"
    p2pNumber: 2
    l1ToL2MessageSourceNumber: 2
[19:35:39.590] DEBUG: sequencer Transitioning from SYNCHRONIZING to PROPOSER_CHECK
[19:35:39.600] DEBUG: sequencer Last block mined at 1733351946 current time is 1733351739 (elapsed -207)
[19:35:39.600] VERBOSE: sequencer Preparing proposal for block 3 at slot 5
    chainTipArchive: "0x204e928bc35b3d9c7e6c19900430dfd755e6c5161fe8becbd3432a22bbb5e424"
    blockNumber: 3
    slot: 5
[19:35:39.600] DEBUG: sequencer Transitioning from PROPOSER_CHECK to WAITING_FOR_TXS
[19:35:39.600] DEBUG: sequencer Last block mined at 1733351946 current time is 1733351739 (elapsed -207)
[19:35:39.600] VERBOSE: sequencer Not creating block because not enough txs in the pool (got 0 min 1)
[19:35:39.600] DEBUG: sequencer Transitioning from WAITING_FOR_TXS to IDLE
[19:35:40.738] DEBUG: sequencer Transitioning from IDLE to SYNCHRONIZING
[19:35:40.740] DEBUG: sequencer Sequencer sync check succeeded
    worldStateNumber: 2
    worldStateHash: "0x0ec8b235ee8b43ca3b150e41231c379ff569fcd2526e72585933025835f7b930"
    l2BlockSourceNumber: 2
    l2BlockSourceHash: "0x0ec8b235ee8b43ca3b150e41231c379ff569fcd2526e72585933025835f7b930"
    p2pNumber: 2
    l1ToL2MessageSourceNumber: 2
[19:35:40.740] DEBUG: sequencer Transitioning from SYNCHRONIZING to PROPOSER_CHECK
[19:35:40.749] DEBUG: sequencer Last block mined at 1733351946 current time is 1733351740 (elapsed -206)
[19:35:40.749] VERBOSE: sequencer Preparing proposal for block 3 at slot 5
    chainTipArchive: "0x204e928bc35b3d9c7e6c19900430dfd755e6c5161fe8becbd3432a22bbb5e424"
    blockNumber: 3
    slot: 5
[19:35:40.749] DEBUG: sequencer Transitioning from PROPOSER_CHECK to WAITING_FOR_TXS
[19:35:40.749] DEBUG: sequencer Last block mined at 1733351946 current time is 1733351740 (elapsed -206)
[19:35:40.749] VERBOSE: sequencer Not creating block because not enough txs in the pool (got 0 min 1)
[19:35:40.749] DEBUG: sequencer Transitioning from WAITING_FOR_TXS to IDLE
[19:35:42.085] DEBUG: sequencer Transitioning from IDLE to SYNCHRONIZING
[19:35:42.088] DEBUG: sequencer Sequencer sync check succeeded
    worldStateNumber: 2
    worldStateHash: "0x0ec8b235ee8b43ca3b150e41231c379ff569fcd2526e72585933025835f7b930"
    l2BlockSourceNumber: 2
    l2BlockSourceHash: "0x0ec8b235ee8b43ca3b150e41231c379ff569fcd2526e72585933025835f7b930"
    p2pNumber: 2
    l1ToL2MessageSourceNumber: 2
[19:35:42.088] DEBUG: sequencer Transitioning from SYNCHRONIZING to PROPOSER_CHECK
[19:35:42.344] DEBUG: sequencer Last block mined at 1733351946 current time is 1733351742 (elapsed -204)
[19:35:42.344] VERBOSE: sequencer Preparing proposal for block 3 at slot 5
    chainTipArchive: "0x204e928bc35b3d9c7e6c19900430dfd755e6c5161fe8becbd3432a22bbb5e424"
    blockNumber: 3
    slot: 5
[19:35:42.344] DEBUG: sequencer Transitioning from PROPOSER_CHECK to WAITING_FOR_TXS
[19:35:42.345] DEBUG: sequencer Last block mined at 1733351946 current time is 1733351742 (elapsed -204)
[19:35:42.345] VERBOSE: sequencer Retrieved 1 txs for block 3 with global variables
    chainId: 31337
    version: 1
    blockNumber: 3
    slotNumber: 5
    coinbase: "0x0000000000000000000000000000000000000000"
    feeRecipient: "0x0000000000000000000000000000000000000000000000000000000000000000"
    feePerDaGas: 0
    feePerL2Gas: 54165518250
[19:35:42.360] DEBUG: sequencer:tx_validator:tx_phases Tx 0x0947c0826f9de10312e87b432776903bdf1436944ef0976cfd86dbe5c160c701 does not contain enqueued public functions. Skipping phases validation.
[19:35:42.368] DEBUG: sequencer Last block mined at 1733351946 current time is 1733351742 (elapsed -204)
[19:35:42.371] DEBUG: sequencer Transitioning from WAITING_FOR_TXS to CREATING_BLOCK
[19:35:42.371] DEBUG: sequencer Requesting L1 to L2 messages from contract for block 3
[19:35:42.371] VERBOSE: sequencer Building block 3
    msgCount: 0
    txCount: 1
    slot: 5
    blockNumber: 3
[19:35:42.371] DEBUG: sequencer Synced to previous block 2
[19:35:42.403] DEBUG: sequencer Last block mined at 1733351946 current time is 1733351742 (elapsed -204)
[19:35:42.427] VERBOSE: sequencer Built block 3
    txEffectsHash: "007e55721ddeddf2f1209c5883d7d3421dc10b54bcb0be47e1b559ca81a8eaf7"
    eventName: "l2-block-built"
    creator: "0xf39fd6e51aad88f6f4ce6ab8827279cfffb92266"
    duration: 55.81142699718475
    publicProcessDuration: 23.273739002645016
    rollupCircuitsDuration: 50.400100000202656
    txCount: 1
    blockNumber: 3
    blockTimestamp: 1733351970
    unencryptedLogCount: 0
    unencryptedLogSize: 4
    contractClassLogCount: 1
    contractClassLogSize: 96208
[19:35:42.427] DEBUG: sequencer Collecting attestations
[19:35:42.428] VERBOSE: sequencer Attesting committee length is 0
[19:35:42.428] VERBOSE: sequencer Collected 0 attestations
[19:35:42.428] DEBUG: sequencer Collecting proof quotes
[19:35:42.429] DEBUG: sequencer No epoch to prove
[19:35:42.429] DEBUG: sequencer Transitioning from CREATING_BLOCK to PUBLISHING_BLOCK
[19:35:42.439] DEBUG: sequencer:publisher Submitting propose transaction
[19:35:42.459] DEBUG: sequencer:publisher Computed gas price
    attempt: 0
    baseFee: "0.106495094"
    maxFeePerGas: "1.351630708"
    maxPriorityFeePerGas: "1.2"
[19:35:42.476] VERBOSE: sequencer:publisher Sent L1 transaction 0xf3c1c1c9e78e5deedfc1eeb403c25e53cefb4fecf4ec794f3bfc27036fdc51e0
    gasLimit: 12916863
    maxFeePerGas: "1.351630708"
    maxPriorityFeePerGas: "1.2"
[19:35:42.481] DEBUG: sequencer:publisher L1 transaction 0xf3c1c1c9e78e5deedfc1eeb403c25e53cefb4fecf4ec794f3bfc27036fdc51e0 mined
[19:35:42.528] VERBOSE: sequencer:publisher Published L2 block to L1 rollup contract
    gasPrice: 1293183208
    gasUsed: 1046355
    transactionHash: "0xf3c1c1c9e78e5deedfc1eeb403c25e53cefb4fecf4ec794f3bfc27036fdc51e0"
    calldataGas: 476468
    calldataSize: 98756
    sender: "0xf39fd6e51aad88f6f4ce6ab8827279cfffb92266"
    txCount: 1
    blockNumber: 3
    blockTimestamp: 1733351970
    unencryptedLogCount: 0
    unencryptedLogSize: 4
    contractClassLogCount: 1
    contractClassLogSize: 96208
    eventName: "rollup-published-to-l1"
    slotNumber: 5
    blockHash: "0x189e29fe5832db7e9c8d040812b928863fa9b978675dcc10d4d50bdcf1f2a750"
[19:35:42.528] INFO: sequencer Published rollup block 3 with 1 transactions in 56ms
    blockNumber: 3
    blockHash: "0x189e29fe5832db7e9c8d040812b928863fa9b978675dcc10d4d50bdcf1f2a750"
    slot: 5
    txCount: 1
    duration: 56
    submitter: "0xf39fd6e51aad88f6f4ce6ab8827279cfffb92266"
[19:35:42.528] DEBUG: sequencer Transitioning from PUBLISHING_BLOCK to IDLE
[19:35:42.528] DEBUG: sequencer Transitioning from IDLE to IDLE
[19:35:43.529] DEBUG: sequencer Transitioning from IDLE to SYNCHRONIZING
[19:35:43.534] DEBUG: sequencer Sequencer sync check succeeded
    worldStateNumber: 3
    worldStateHash: "0x189e29fe5832db7e9c8d040812b928863fa9b978675dcc10d4d50bdcf1f2a750"
    l2BlockSourceNumber: 3
    l2BlockSourceHash: "0x189e29fe5832db7e9c8d040812b928863fa9b978675dcc10d4d50bdcf1f2a750"
    p2pNumber: 3
    l1ToL2MessageSourceNumber: 3
[19:35:43.534] DEBUG: sequencer Transitioning from SYNCHRONIZING to PROPOSER_CHECK
[19:35:43.541] DEBUG: sequencer Last block mined at 1733351970 current time is 1733351743 (elapsed -227)
[19:35:43.541] VERBOSE: sequencer Preparing proposal for block 4 at slot 6
    chainTipArchive: "0x252dd494d3b98f4ff8d0c2961ebda574a65829d1ca18ad5dc2a5d05c91c15805"
    blockNumber: 4
    slot: 6
[19:35:43.541] DEBUG: sequencer Transitioning from PROPOSER_CHECK to WAITING_FOR_TXS
[19:35:43.541] DEBUG: sequencer Last block mined at 1733351970 current time is 1733351743 (elapsed -227)
[19:35:43.542] VERBOSE: sequencer Not creating block because not enough txs in the pool (got 0 min 1)
[19:35:43.542] DEBUG: sequencer Transitioning from WAITING_FOR_TXS to IDLE
[19:35:44.350] INFO: sequencer Sequencer config set
    transactionPollingIntervalMS: 1000
    maxTxsPerBlock: 32
    minTxsPerBlock: 1
    minSecondsBetweenBlocks: 0
    maxSecondsBetweenBlocks: 0
    acvmWorkingDirectory: "/tmp/d2789769/acvm"
    acvmBinaryPath: "../../noir/noir-repo/target/release/acvm"
    maxBlockSizeInBytes: 1048576
    enforceFees: false
[19:35:44.568] DEBUG: sequencer Transitioning from IDLE to SYNCHRONIZING
[19:35:44.570] DEBUG: sequencer Sequencer sync check succeeded
    worldStateNumber: 3
    worldStateHash: "0x189e29fe5832db7e9c8d040812b928863fa9b978675dcc10d4d50bdcf1f2a750"
    l2BlockSourceNumber: 3
    l2BlockSourceHash: "0x189e29fe5832db7e9c8d040812b928863fa9b978675dcc10d4d50bdcf1f2a750"
    p2pNumber: 3
    l1ToL2MessageSourceNumber: 3
[19:35:44.570] DEBUG: sequencer Transitioning from SYNCHRONIZING to PROPOSER_CHECK
[19:35:44.826] DEBUG: sequencer Last block mined at 1733351970 current time is 1733351744 (elapsed -226)
[19:35:44.826] VERBOSE: sequencer Preparing proposal for block 4 at slot 6
    chainTipArchive: "0x252dd494d3b98f4ff8d0c2961ebda574a65829d1ca18ad5dc2a5d05c91c15805"
    blockNumber: 4
    slot: 6
[19:35:44.826] DEBUG: sequencer Transitioning from PROPOSER_CHECK to WAITING_FOR_TXS
[19:35:44.826] DEBUG: sequencer Last block mined at 1733351970 current time is 1733351744 (elapsed -226)
[19:35:44.826] VERBOSE: sequencer Not creating block because not enough txs in the pool (got 0 min 8)
[19:35:44.826] DEBUG: sequencer Transitioning from WAITING_FOR_TXS to IDLE
[19:35:46.027] DEBUG: sequencer Transitioning from IDLE to SYNCHRONIZING
[19:35:46.029] DEBUG: sequencer Sequencer sync check succeeded
    worldStateNumber: 3
    worldStateHash: "0x189e29fe5832db7e9c8d040812b928863fa9b978675dcc10d4d50bdcf1f2a750"
    l2BlockSourceNumber: 3
    l2BlockSourceHash: "0x189e29fe5832db7e9c8d040812b928863fa9b978675dcc10d4d50bdcf1f2a750"
    p2pNumber: 3
    l1ToL2MessageSourceNumber: 3
[19:35:46.029] DEBUG: sequencer Transitioning from SYNCHRONIZING to PROPOSER_CHECK
[19:35:46.085] DEBUG: sequencer Last block mined at 1733351970 current time is 1733351746 (elapsed -224)
[19:35:46.085] VERBOSE: sequencer Preparing proposal for block 4 at slot 6
    chainTipArchive: "0x252dd494d3b98f4ff8d0c2961ebda574a65829d1ca18ad5dc2a5d05c91c15805"
    blockNumber: 4
    slot: 6
[19:35:46.085] DEBUG: sequencer Transitioning from PROPOSER_CHECK to WAITING_FOR_TXS
[19:35:46.085] DEBUG: sequencer Last block mined at 1733351970 current time is 1733351746 (elapsed -224)
[19:35:46.085] VERBOSE: sequencer Not creating block because not enough txs in the pool (got 0 min 8)
[19:35:46.085] DEBUG: sequencer Transitioning from WAITING_FOR_TXS to IDLE
[19:35:47.279] DEBUG: sequencer Transitioning from IDLE to SYNCHRONIZING
[19:35:47.281] DEBUG: sequencer Sequencer sync check succeeded
    worldStateNumber: 3
    worldStateHash: "0x189e29fe5832db7e9c8d040812b928863fa9b978675dcc10d4d50bdcf1f2a750"
    l2BlockSourceNumber: 3
    l2BlockSourceHash: "0x189e29fe5832db7e9c8d040812b928863fa9b978675dcc10d4d50bdcf1f2a750"
    p2pNumber: 3
    l1ToL2MessageSourceNumber: 3
[19:35:47.281] DEBUG: sequencer Transitioning from SYNCHRONIZING to PROPOSER_CHECK
[19:35:47.293] DEBUG: sequencer Last block mined at 1733351970 current time is 1733351747 (elapsed -223)
[19:35:47.293] VERBOSE: sequencer Preparing proposal for block 4 at slot 6
    chainTipArchive: "0x252dd494d3b98f4ff8d0c2961ebda574a65829d1ca18ad5dc2a5d05c91c15805"
    blockNumber: 4
    slot: 6
[19:35:47.293] DEBUG: sequencer Transitioning from PROPOSER_CHECK to WAITING_FOR_TXS
[19:35:47.293] DEBUG: sequencer Last block mined at 1733351970 current time is 1733351747 (elapsed -223)
[19:35:47.293] VERBOSE: sequencer Not creating block because not enough txs in the pool (got 0 min 8)
[19:35:47.293] DEBUG: sequencer Transitioning from WAITING_FOR_TXS to IDLE
[19:35:48.435] DEBUG: sequencer Transitioning from IDLE to SYNCHRONIZING
[19:35:48.437] DEBUG: sequencer Sequencer sync check succeeded
    worldStateNumber: 3
    worldStateHash: "0x189e29fe5832db7e9c8d040812b928863fa9b978675dcc10d4d50bdcf1f2a750"
    l2BlockSourceNumber: 3
    l2BlockSourceHash: "0x189e29fe5832db7e9c8d040812b928863fa9b978675dcc10d4d50bdcf1f2a750"
    p2pNumber: 3
    l1ToL2MessageSourceNumber: 3
[19:35:48.437] DEBUG: sequencer Transitioning from SYNCHRONIZING to PROPOSER_CHECK
[19:35:48.485] DEBUG: sequencer Last block mined at 1733351970 current time is 1733351748 (elapsed -222)
[19:35:48.485] VERBOSE: sequencer Preparing proposal for block 4 at slot 6
    chainTipArchive: "0x252dd494d3b98f4ff8d0c2961ebda574a65829d1ca18ad5dc2a5d05c91c15805"
    blockNumber: 4
    slot: 6
[19:35:48.485] DEBUG: sequencer Transitioning from PROPOSER_CHECK to WAITING_FOR_TXS
[19:35:48.485] DEBUG: sequencer Last block mined at 1733351970 current time is 1733351748 (elapsed -222)
[19:35:48.485] VERBOSE: sequencer Not creating block because not enough txs in the pool (got 0 min 8)
[19:35:48.485] DEBUG: sequencer Transitioning from WAITING_FOR_TXS to IDLE
[19:35:49.690] DEBUG: sequencer Transitioning from IDLE to SYNCHRONIZING
[19:35:49.692] DEBUG: sequencer Sequencer sync check succeeded
    worldStateNumber: 3
    worldStateHash: "0x189e29fe5832db7e9c8d040812b928863fa9b978675dcc10d4d50bdcf1f2a750"
    l2BlockSourceNumber: 3
    l2BlockSourceHash: "0x189e29fe5832db7e9c8d040812b928863fa9b978675dcc10d4d50bdcf1f2a750"
    p2pNumber: 3
    l1ToL2MessageSourceNumber: 3
[19:35:49.692] DEBUG: sequencer Transitioning from SYNCHRONIZING to PROPOSER_CHECK
[19:35:49.704] DEBUG: sequencer Last block mined at 1733351970 current time is 1733351749 (elapsed -221)
[19:35:49.704] VERBOSE: sequencer Preparing proposal for block 4 at slot 6
    chainTipArchive: "0x252dd494d3b98f4ff8d0c2961ebda574a65829d1ca18ad5dc2a5d05c91c15805"
    blockNumber: 4
    slot: 6
[19:35:49.704] DEBUG: sequencer Transitioning from PROPOSER_CHECK to WAITING_FOR_TXS
[19:35:49.704] DEBUG: sequencer Last block mined at 1733351970 current time is 1733351749 (elapsed -221)
[19:35:49.704] VERBOSE: sequencer Not creating block because not enough txs in the pool (got 0 min 8)
[19:35:49.704] DEBUG: sequencer Transitioning from WAITING_FOR_TXS to IDLE
[19:35:50.924] DEBUG: sequencer Transitioning from IDLE to SYNCHRONIZING
[19:35:50.929] DEBUG: sequencer Sequencer sync check succeeded
    worldStateNumber: 3
    worldStateHash: "0x189e29fe5832db7e9c8d040812b928863fa9b978675dcc10d4d50bdcf1f2a750"
    l2BlockSourceNumber: 3
    l2BlockSourceHash: "0x189e29fe5832db7e9c8d040812b928863fa9b978675dcc10d4d50bdcf1f2a750"
    p2pNumber: 3
    l1ToL2MessageSourceNumber: 3
[19:35:50.930] DEBUG: sequencer Transitioning from SYNCHRONIZING to PROPOSER_CHECK
[19:35:50.996] DEBUG: sequencer Last block mined at 1733351970 current time is 1733351750 (elapsed -220)
[19:35:50.996] VERBOSE: sequencer Preparing proposal for block 4 at slot 6
    chainTipArchive: "0x252dd494d3b98f4ff8d0c2961ebda574a65829d1ca18ad5dc2a5d05c91c15805"
    blockNumber: 4
    slot: 6
[19:35:50.996] DEBUG: sequencer Transitioning from PROPOSER_CHECK to WAITING_FOR_TXS
[19:35:51.007] DEBUG: sequencer Last block mined at 1733351970 current time is 1733351751 (elapsed -219)
[19:35:51.007] VERBOSE: sequencer Not creating block because not enough txs in the pool (got 6 min 8)
[19:35:51.007] DEBUG: sequencer Transitioning from WAITING_FOR_TXS to IDLE
[19:35:52.007] DEBUG: sequencer Transitioning from IDLE to SYNCHRONIZING
[19:35:52.010] DEBUG: sequencer Sequencer sync check succeeded
    worldStateNumber: 3
    worldStateHash: "0x189e29fe5832db7e9c8d040812b928863fa9b978675dcc10d4d50bdcf1f2a750"
    l2BlockSourceNumber: 3
    l2BlockSourceHash: "0x189e29fe5832db7e9c8d040812b928863fa9b978675dcc10d4d50bdcf1f2a750"
    p2pNumber: 3
    l1ToL2MessageSourceNumber: 3
[19:35:52.010] DEBUG: sequencer Transitioning from SYNCHRONIZING to PROPOSER_CHECK
[19:35:52.016] DEBUG: sequencer Last block mined at 1733351970 current time is 1733351752 (elapsed -218)
[19:35:52.016] VERBOSE: sequencer Preparing proposal for block 4 at slot 6
    chainTipArchive: "0x252dd494d3b98f4ff8d0c2961ebda574a65829d1ca18ad5dc2a5d05c91c15805"
    blockNumber: 4
    slot: 6
[19:35:52.016] DEBUG: sequencer Transitioning from PROPOSER_CHECK to WAITING_FOR_TXS
[19:35:52.025] DEBUG: sequencer Last block mined at 1733351970 current time is 1733351752 (elapsed -218)
[19:35:52.025] VERBOSE: sequencer Retrieved 8 txs for block 4 with global variables
    chainId: 31337
    version: 1
    blockNumber: 4
    slotNumber: 6
    coinbase: "0x0000000000000000000000000000000000000000"
    feeRecipient: "0x0000000000000000000000000000000000000000000000000000000000000000"
    feePerDaGas: 0
    feePerL2Gas: 54165518250
[19:35:52.044] DEBUG: sequencer Last block mined at 1733351970 current time is 1733351752 (elapsed -218)
[19:35:52.048] DEBUG: sequencer Transitioning from WAITING_FOR_TXS to CREATING_BLOCK
[19:35:52.048] DEBUG: sequencer Requesting L1 to L2 messages from contract for block 4
[19:35:52.049] VERBOSE: sequencer Building block 4
    msgCount: 0
    txCount: 8
    slot: 6
    blockNumber: 4
[19:35:52.049] DEBUG: sequencer Synced to previous block 3
[19:35:52.585] DEBUG: sequencer Last block mined at 1733351970 current time is 1733351752 (elapsed -218)
[19:35:52.604] VERBOSE: sequencer Built block 4
    txEffectsHash: "002040768b0ae142fbf4e573546d7005c5bfce7f8c485874062e0056de346464"
    eventName: "l2-block-built"
    creator: "0xf39fd6e51aad88f6f4ce6ab8827279cfffb92266"
    duration: 555.711239002645
    publicProcessDuration: 525.4445829987526
    rollupCircuitsDuration: 549.5823439955711
    txCount: 8
    blockNumber: 4
    blockTimestamp: 1733351994
    unencryptedLogCount: 0
    unencryptedLogSize: 64
    contractClassLogCount: 0
    contractClassLogSize: 64
[19:35:52.605] DEBUG: sequencer Collecting attestations
[19:35:52.608] VERBOSE: sequencer Attesting committee length is 0
[19:35:52.608] VERBOSE: sequencer Collected 0 attestations
[19:35:52.608] DEBUG: sequencer Collecting proof quotes
[19:35:52.610] DEBUG: sequencer No epoch to prove
[19:35:52.610] DEBUG: sequencer Transitioning from CREATING_BLOCK to PUBLISHING_BLOCK
[19:35:52.615] DEBUG: sequencer:publisher Submitting propose transaction
[19:35:52.651] DEBUG: sequencer:publisher Computed gas price
    attempt: 0
    baseFee: "0.08234783"
    maxFeePerGas: "1.317249154"
    maxPriorityFeePerGas: "1.2"
[19:35:52.656] VERBOSE: sequencer:publisher Sent L1 transaction 0x1d1e758562f04487a414ed500bdd3b3d44243aaba42a880a800019b7d375e3a3
    gasLimit: 14460607
    maxFeePerGas: "1.317249154"
    maxPriorityFeePerGas: "1.2"
[19:35:52.660] DEBUG: sequencer:publisher L1 transaction 0x1d1e758562f04487a414ed500bdd3b3d44243aaba42a880a800019b7d375e3a3 mined
[19:35:52.662] VERBOSE: sequencer:publisher Published L2 block to L1 rollup contract
    gasPrice: 1272054352
    gasUsed: 2310581
    transactionHash: "0x1d1e758562f04487a414ed500bdd3b3d44243aaba42a880a800019b7d375e3a3"
    calldataGas: 26980
    calldataSize: 3076
    sender: "0xf39fd6e51aad88f6f4ce6ab8827279cfffb92266"
    txCount: 8
    blockNumber: 4
    blockTimestamp: 1733351994
    unencryptedLogCount: 0
    unencryptedLogSize: 64
    contractClassLogCount: 0
    contractClassLogSize: 64
    eventName: "rollup-published-to-l1"
    slotNumber: 6
    blockHash: "0x0c5c87d0e048001ce744df88f654bdf3c89e464429a26902abc270024a5f0e24"
[19:35:52.663] INFO: sequencer Published rollup block 4 with 8 transactions in 556ms
    blockNumber: 4
    blockHash: "0x0c5c87d0e048001ce744df88f654bdf3c89e464429a26902abc270024a5f0e24"
    slot: 6
    txCount: 8
    duration: 556
    submitter: "0xf39fd6e51aad88f6f4ce6ab8827279cfffb92266"
[19:35:52.663] DEBUG: sequencer Transitioning from PUBLISHING_BLOCK to IDLE
[19:35:52.663] DEBUG: sequencer Transitioning from IDLE to IDLE

PhilWindle
PhilWindle approved these changes Dec 5, 2024
View reviewed changes
Copy link
Collaborator

@PhilWindle PhilWindle left a comment

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Looks like a definite improvement to me!

@spalladino
chore: Remove debug and winston in favor of pino
63eee1d
@spalladino
Set up otel pino stream to deliver logs to otel collector
8d2613a
@spalladino
Set up log correlation manually
c5999ce
@spalladino
Downgrade noisy logs to trace
2b0ab81 
The default DEBUG string used to define the following exclusions:

```
-aztec:avm_simulator*,-aztec:libp2p_service*,-aztec:circuits:artifact_hash,-json-rpc*,-aztec:world-state:database,-aztec:l2_block_stream*
```

So we downgrade the noisy logs in those modules to `trace` instead.
@spalladino
Browser support
dcb05b8
@spalladino
Fix package json
7ab1a04
@spalladino
Add migration notes
0a84dc3
@spalladino
Add tty fallback to migration notes
17eedc4
@spalladino
Remove unused dependency
f9773b5
@spalladino
Force colors on pretty output
c6b118d
@spalladino
Log to stderr instead of stdout
8417b29
@spalladino
Remove DEBUG usage
92d5c25
@spalladino
chore: Logger module names
00bd460
@spalladino
Rename modules scopes
d3e12cd
@spalladino
More renames
93ce5cf
@spalladino spalladino force-pushed the palla/sequencer-logs branch from 451dc25 to 8a3dbef Compare December 5, 2024 14:30
@spalladino
Copy link
Contributor Author

spalladino commented Dec 6, 2024

Cherry picked onto #10404 to have one less CI run

@spalladino spalladino closed this Dec 6, 2024
@spalladino spalladino deleted the palla/sequencer-logs branch December 6, 2024 02:21
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment

Reviewers

@PhilWindle PhilWindle PhilWindle approved these changes

@fcarreiro fcarreiro Awaiting requested review from fcarreiro

@dbanks12 dbanks12 Awaiting requested review from dbanks12

Assignees

No one assigned

Labels

None yet

Projects

None yet

Milestone

No milestone

Development

Successfully merging this pull request may close these issues.

2 participants

@spalladino @PhilWindle