Enable logging in tests and fix error log flooding from mock chain runtime

[soareschen]

Closes: #1018

Description

This PR should cause a large number of error logs to be printed when running cargo tests on foreign_client::tests.

---

For contributor use:

• Updated the Unreleased section of CHANGELOG.md with the issue.
• If applicable: Unit tests written, added test to CI.
• Linked to Github issue with discussion and accepted design OR link to spec that describes this work.
• Updated relevant documentation (docs/) and code comments.
• Re-reviewed Files changed in the Github PR explorer.

[soareschen]

The error log flooding has now been fixed. There are 2 causes for this:

• The MockChain returns an EventReceiver with the sender end being dropped immediately.
• The ChainRuntime's run() method runs in a loop that keeps polling the receivers. Because the sender end is dropped, the receiver end errors out immediately. However the chain runtime merely prints the error message and continue looping. So the number of error messages printed is affected by how long the test itself has run.

The fix is as follows:

• Add the event sender end to the MockChain struct, so that it never gets dropped.
• Make ChainRuntime return from run() if event_receiver is disconnected. This can potentially break the runtime, as subsequent messages for request_receiver are not handled. However in the match arm for request_receiver also returns from the loop when any error happens. So the loop is already not fault tolerant anyway. The error should instead be propagated to the caller through the JoinHandle, and have higher level logic to handle the failure such as respawning the runtime.

[adizere]

I'm not sure we should keep this around. Do you think it would be valuable to have logging enabled in tests going forward?

[soareschen]

Yes, I think they help especially when the tests are failing. Not having them enabled would only make it more inconvenient for contributors to write new tests and fix failing tests. The logging setup for Rust is not very straightforward, and just figuring out how to enable that can waste minutes to hour of a contributor's time.

[adizere]

Hmm I think it is by design that this match arm does not return Err(..) here but instead permits the loop to continue. For context, please see #895 (and follow-up #903). The idea is that the chain runtime would continue polling via select! here even if the monitor's connection to the full node is down (or some other error appears in the event_receiver), and it's the job of the monitor to retry and eventually heal if the connection to the node is re-established.

It would be good if you can verify that your changes do not introduce a regression. Could you please just double-check that? The recipe for testing is in the description of #903 (see "Tested with").

[adizere]

Also, I was trying earlier to test but was not sure how to exercise the Err path here. Any tips?

[soareschen]

I checked the source code of crossbeam, and the only possible error is when the sender end of the channel is dropped, and so it is unrecoverable. We probably never encounter this in production, because if the channel is disconnected, it will also result in the flooding of error messages in the relayer log.

Also, if you check the other branches, each of them are called with ? at the end. This means any error happening in those places will break the loop and return error. We should have another issue to address this by having some way to recover from any error inside the loop.

[adizere]

Thank you for the findings & explanation!

I agree with you that the loop is not fault-tolerant anyway. I originally thought that returning in the Err path here could make the runtime (and the Hermes process in general) exit early (instead of waiting on the monitor to retry). But it seems there is a regression in master (#1026) and that has nothing to do with the changes in this branch.

We should have another issue to address this by having some way to recover from any error inside the loop.

I agree. If you know how to capture this in an issue, could you please handle that? We didn't notice these problems (yet), but it would be good to track this issue and add a general method for handling recovery.

[soareschen]

Sure, filed #1025 for that.