E2E test for checking relayer fast startup

[daniel-savu]

Problem

With hook indexing recently merged, if the relayer is already synced to the tip and restarts, the message processor will see new messages as soon as the indexer adds them to the db. We should however add e2e to make sure this is the case.

We have the get_matching_lines utility to find lines that match a string, and can use it to:

• first, extend it to extract the timestamp from the logs. Since they're ANSI formatted, the logs are noisy but the timestamps are ISO formatted. Example:

"\u{1b}[2m2024-06-11T15:05:36.790507Z\u{1b}[0m \u{1b}[34mDEBUG\u{1b}[0m \u{1b}[1msubmit_task\u{1b}[0m: \u{1b}[2mrelayer::msg::gas_payment\u{1b}[0m\u{1b}[2m:\u{1b}[0m Recording gas expenditure for message \u{1b}[3mmsg\u{1b}[0m\u{1b}[2m=\u{1b}[0mHyperlaneMessage { id: 0x9a0892baa0b970fc5929ff4f759f8eb33a2fed1c9a8880d0d0ea68ae36852b06, nonce: 0, .. } \u{1b}[3moutcome\u{1b}[0m\u{1b}[2m=\u{1b}[0mTxOutcome { transaction_id: 0x00000000000000000000000000000000000000000000000000000000000000003bca8ad22ece28e0894b5a1733d20b13281c2f7dc78d24d5361b8ac9cf032ef0, executed: true, gas_used: 125552, gas_price: FixedPointNumber(BigDecimal(\"1500000018\")) } \u{1b}[2m\u{1b}[3mdomain\u{1b}[0m\u{1b}[2m=\u{1b}[0mtest2\u{1b}[0m", "\u{1b}[2m2024-06-11T15:05:36.791513Z\u{1b}[0m \u{1b}[34mDEBUG\u{1b}[0m \u{1b}[1msubmit_task\u{1b}[0m: \u{1b}[2mrelayer::msg::gas_payment\u{1b}[0m\u{1b}[2m:\u{1b}[0m Recording gas expenditure for message \u{1b}[3mmsg\u{1b}[0m\u{1b}[2m=\u{1b}[0mHyperlaneMessage { id: 0x61dc3982b1268bb17f9f61772f64d30b081a33306ba62a56a7ac177642a92313, nonce: 1, .. } \u{1b}[3moutcome\u{1b}[0m\u{1b}[2m=\u{1b}[0mTxOutcome { transaction_id: 0x00000000000000000000000000000000000000000000000000000000000000003bca8ad22ece28e0894b5a1733d20b13281c2f7dc78d24d5361b8ac9cf032ef0, executed: true, gas_used: 125578, gas_price: FixedPointNumber(BigDecimal(\"1500000018\")) } \u{1b}[2m\u{1b}[3mdomain\u{1b}[0m\u{1b}[2m=\u{1b}[0mtest2\u{1b}[0m", "\u{1b}[2m2024-06-11T15:05:36.792166Z\u{1b}[0m \u{1b}[34mDEBUG\u{1b}[0m \u{1b}[1msubmit_task\u{1b}[0m: \u{1b}[2mrelayer::msg::gas_payment\u{1b}[0m\u{1b}[2m:\u{1b}[0m Recording gas expenditure for message \u{1b}[3mmsg\u{1b}[0m\u{1b}[2m=\u{1b}[0mHyperlaneMessage { id: 0x121909039e54501cca92afe93882a2c60612ccddf1b30c5c4b78c5ff46a713d7, nonce: 4, .. } \u{1b}[3moutcome\u{1b}[0m\u{1b}[2m=\u{1b}[0mTxOutcome { transaction_id: 0x00000000000000000000000000000000000000000000000000000000000000003bca8ad22ece28e0894b5a1733d20b13281c2f7dc78d24d5361b8ac9cf032ef0, executed: true, gas_used: 125584, gas_price: FixedPointNumber(BigDecimal(\"1500000018\")) } \u{1b}[2m\u{1b}[3mdomain\u{1b}[0m\u{1b}[2m=\u{1b}[0mtest2\u{1b}[0m"

• there's already a WIP pr that shuts the relayer down, sends some messages, waits for the validators to sign checkpoints, then spins the relayer back up: wip: fast relayer startup test #3950. We can build on top of this:
  • to test the processor, make sure it sees the message (Sending message to submitter) very shortly after the indexer finds it and writes to the DB (Storing new message in db). Though this is blocked on: Agent debug logs should always be present when configured #3915
  • to the test submitter, make sure there are no Could not fetch metadata after the messages are sent to the submitter, but before all 5 Operation confirmed logs are printed. This shows that the relayer also indexed merkle insertions (because it knows which validator sigs to query), and is not bound by anything on submission.