prevent op-proposer Send tx failure errors & clean up op-proposer logging

[roberto-bayardo]

• proposal transaction errors were commonly being logged due to another esoteric EstimateGas quirk, which this PR cleans up by making sure the head of the L1 chain is sufficiently advanced before submitting the output proposal.

• changes a spammy info log to debug

• changes the warning log message on failure to fetch receipt to info level since this is typical behavior when txs are replaced with increased fees

• documentation added to explain some of the expected logging outcomes

• fixes function name typo

Context: it turns out that "EstimateGas" actually defaults to estimating gas at "Latest" block state instead of "Pending" block state (the godoc in ethclient is outdated, though a PR to update it is here). This means estimate gas will fail with tx revert when the l1BlockNumber == latest, because the contract calls blockhash(l1blocknumber) and this returns "0" instead of the block hash.

[changeset-bot]

⚠️ No Changeset found

Latest commit: 0537c85

Merging this PR will not cause a version bump for any packages. If these changes should not result in a new version, you're good to go. If these changes should result in a version bump, you need to add a changeset.

This PR includes no changesets

When changesets are added to this PR, you'll see the packages that this PR includes changesets for and the associated semver types

Click here to learn what changesets are, and how to add one.

Click here if you're a maintainer who wants to add a changeset to this PR

[netlify]

✅ Deploy Preview for opstack-docs canceled.

Name	Link
🔨 Latest commit	0537c85
🔍 Latest deploy log	https://app.netlify.com/sites/opstack-docs/deploys/64a03a82d1f7aa0008abb72f

[tynes]

Perhaps we should just add a flag so that the blocknumber/blockhash is set to 0 in the output proposals so that these errors can be completely avoided

[roberto-bayardo]

Perhaps we should just add a flag so that the blocknumber/blockhash is set to 0 in the output proposals so that these errors can be completely avoided

That would certainly work, I just wasn't sure how important the hash matching check is. This is turning out to be more invasive than I would like to clean up what is mostly an aesthetic issue with the logging, though I figure we should at least document somewhere in the code what's going on in order to hopefully spare the next poor soul who might follow the error messages down this same rabbit hole.

[roberto-bayardo]

This PR is now eliminating the failed proposer tx errors (at least in normal operation) & reclassifies some noisy info logs as Debug. Resulting Info+ logs are much more manageable.

I can also add a flag to bypass the blocknum/blockhash and related logic if you think it would be useful.

Jun 26 17:50:27.602,opt_proposer_1,proposer tx successfully published
Jun 26 17:50:27.602,opt_proposer_1,Transaction confirmed
Jun 26 17:50:15.569,opt_proposer_1,Transaction successfully published
Jun 26 17:50:15.559,opt_proposer_1,publishing transaction
Jun 26 17:50:15.462,opt_proposer_1,creating tx
Jun 26 17:44:05.568,opt_proposer_1,proposer tx successfully published
Jun 26 17:44:05.568,opt_proposer_1,Transaction confirmed
Jun 26 17:43:53.548,opt_proposer_1,Transaction successfully published
Jun 26 17:43:53.538,opt_proposer_1,publishing transaction
Jun 26 17:43:53.454,opt_proposer_1,creating tx
...
Jun 26 17:06:45.681,opt_proposer_1,proposer tx successfully published
Jun 26 17:06:45.681,opt_proposer_1,Transaction receipt not found.  <-- expected, from the tx that was replaced
Jun 26 17:06:45.680,opt_proposer_1,Transaction confirmed
Jun 26 17:06:21.656,opt_proposer_1,Transaction successfully published
Jun 26 17:06:21.645,opt_proposer_1,publishing transaction
Jun 26 17:06:21.547,opt_proposer_1,bumping gas price for tx        <-- a tx retry w/ fee bump case here
Jun 26 17:05:51.558,opt_proposer_1,Transaction successfully published
Jun 26 17:05:51.547,opt_proposer_1,publishing transaction
Jun 26 17:05:51.457,opt_proposer_1,creating tx
Jun 26 16:59:15.574,opt_proposer_1,proposer tx successfully published
Jun 26 16:59:15.574,opt_proposer_1,Transaction confirmed
Jun 26 16:59:03.552,opt_proposer_1,Transaction successfully published
Jun 26 16:59:03.538,opt_proposer_1,publishing transaction
Jun 26 16:59:03.457,opt_proposer_1,creating tx
Jun 26 16:53:15.755,opt_proposer_1,proposer tx successfully published
Jun 26 16:53:15.755,opt_proposer_1,Transaction confirmed
Jun 26 16:53:03.734,opt_proposer_1,Transaction successfully published
Jun 26 16:53:03.724,opt_proposer_1,publishing transaction
Jun 26 16:53:03.629,opt_proposer_1,creating tx
...

[ajsutton]

Thanks for this.

Probably need to rebase to get some of the tests passing again - there's been a few build improvements lately.

The mocks failure can be fixed by running make generate-mocks in op-service though you'd need to have the right version of mockery installed (v2.28.1). I can run that and push a commit up for you if it's easier.

Otherwise I think this looks good to me. I'll try to track someone a bit more familiar with the proposer to double check the log level changes but the logic makes sense to me. Hopefully rebase and regenerate mocks will get the tests passing but if not we can work through whatever's left.

[trianglesphere]

logging changes + the approach to waiting look good to me.

[roberto-bayardo]

Probably need to rebase to get some of the tests passing again - there's been a few build improvements lately.

done

The mocks failure can be fixed by running make generate-mocks in op-service though you'd need to have the right version of mockery installed (v2.28.1).

done

[ajsutton]

ooo, so close. I was hoping the hive tests would start passing too since they really don't provide much info about what's failing... I'll dig into that and see what I can find out.

[ajsutton]

ok hive is hitting a timeout as part of waiting for withdrawals (the logs in the workspace download have some useful info). Could be affected by this but also using code that isn't calculating the wait period correctly (fixing that in #6193).

I can reproduce the failure locally - had to build the images locally and tag them as us-docker.pkg.dev/oplabs-tools-artifacts/images/op-proposer:latest which is awkward but doable.

[ajsutton]

Not easy but I've pulled those withdrawal timing fixes into hive (many yaks were shaved along the way) and combined with increasing the timeout on one test those hive tests are now passing. So I think it's just that the proposer is slightly slower to submit proposals now and that combined with some bad logic for waiting for withdrawals to finalise was pushing it past the timeout.

[ajsutton]

Ah, with this change op-proposer is constantly falling behind in the hive tests. It has a submission interval of 6 (so every 12 seconds) and L1 blocks happen every 15 seconds. So the test winds up having to wait for a number of proposals to be published rather than just one and that takes quite a while. The current withdrawal waiting logic is incorrectly waiting for multiple output proposals which just makes it worse. We can likely make all the hive tests a lot faster by reducing its L1 block time.

So I think we'll need to merge #6193 then ethereum-optimism/hive#84 and then we can merge this one. Thanks for your patience, it's been a bit crazy how many different issues have all converged around this.

[ajsutton]

@roberto-bayardo Pre-reqs for this are now merged, including #6225 which was a new surprise. :) Could you please rebase this? Hopefully everything should then pass.

[codecov]

Codecov Report

Merging #6138 (0537c85) into develop (8ddf2cd) will increase coverage by 0.04%.
The diff coverage is 3.22%.

Additional details and impacted files

@@             Coverage Diff             @@
##           develop    #6138      +/-   ##
===========================================
+ Coverage    44.16%   44.21%   +0.04%     
===========================================
  Files          436      436              
  Lines        29025    29081      +56     
  Branches       709      709              
===========================================
+ Hits         12818    12857      +39     
- Misses       15126    15145      +19     
+ Partials      1081     1079       -2     

Flag	Coverage Δ
bedrock-go-tests	42.98% <3.22%> (-0.12%)	⬇️
cannon-go-tests	61.78% <ø> (ø)
common-ts-tests	26.82% <ø> (ø)
contracts-bedrock-tests	58.96% <ø> (+4.45%)	⬆️
core-utils-tests	49.06% <ø> (ø)
fault-detector-tests	26.95% <ø> (ø)
sdk-next-tests	42.47% <ø> (ø)
sdk-tests	42.47% <ø> (ø)

Flags with carried forward coverage won't be shown. Click here to find out more.

Impacted Files	Coverage Δ
op-proposer/proposer/l2_output_submitter.go	2.50% <0.00%> (-0.31%)	⬇️
op-service/txmgr/mocks/TxManager.go	0.00% <0.00%> (ø)
op-service/txmgr/txmgr.go	76.54% <25.00%> (-1.20%)	⬇️

... and 9 files with indirect coverage changes

[ajsutton]

LGTM. Thanks for your patience on this.