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

…ntime (informalsystems#1017)

.github/workflows/rust.yml

@@ -81,7 +81,7 @@ jobs:
       - uses: actions-rs/cargo@v1
         with:
           command: test
-          args: --all-features --no-fail-fast
+          args: --all-features --no-fail-fast -- --nocapture
 
   # test-coverage:
   #   runs-on: ubuntu-latest

.gitignore

@@ -20,3 +20,5 @@ data
 # Ignore Python artifacts
 .mypy_cache/
 __pycache__/
+
+.modelator

relayer/Cargo.toml

@@ -71,6 +71,9 @@ version = "=0.19.0"
 
 [dev-dependencies]
 serial_test = "0.5.0"
+env_logger = "0.8.3"
+tracing-subscriber = "0.2.18"
+test-env-log = { version = "0.2.7", features = ["trace"] }
 ibc = { version = "0.3.2", path = "../modules", features = ["mocks"] }
 
 # Needed for generating (synthetic) light blocks.

relayer/src/chain/mock.rs

@@ -42,7 +42,7 @@ use ibc_proto::ibc::core::connection::v1::{
 use crate::chain::Chain;
 use crate::config::ChainConfig;
 use crate::error::{Error, Kind};
-use crate::event::monitor::EventReceiver;
+use crate::event::monitor::{EventReceiver, EventSender};
 use crate::keyring::{KeyEntry, KeyRing};
 use crate::light_client::{mock::LightClient as MockLightClient, LightClient};
 
@@ -53,6 +53,10 @@ use crate::light_client::{mock::LightClient as MockLightClient, LightClient};
 pub struct MockChain {
     config: ChainConfig,
     context: MockContext,
+
+    // keep a reference to event sender to prevent it from being dropped
+    _event_sender: EventSender,
+    event_receiver: EventReceiver,
 }
 
 impl Chain for MockChain {
@@ -62,6 +66,7 @@ impl Chain for MockChain {
     type ClientState = TendermintClientState;
 
     fn bootstrap(config: ChainConfig, _rt: Arc<Runtime>) -> Result<Self, Error> {
+        let (sender, receiver) = channel::unbounded();
         Ok(MockChain {
             config: config.clone(),
             context: MockContext::new(
@@ -70,6 +75,8 @@ impl Chain for MockChain {
                 50,
                 Height::new(config.id.version(), 20),
             ),
+            _event_sender: sender,
+            event_receiver: receiver,
         })
     }
 
@@ -81,8 +88,7 @@ impl Chain for MockChain {
         &self,
         _rt: Arc<Runtime>,
     ) -> Result<(EventReceiver, Option<thread::JoinHandle<()>>), Error> {
-        let (_, rx) = channel::unbounded();
-        Ok((rx, None))
+        Ok((self.event_receiver.clone(), None))
     }
 
     fn id(&self) -> &ChainId {

relayer/src/chain/runtime.rs

@@ -170,7 +170,10 @@ impl<C: Chain + Send + 'static> ChainRuntime<C> {
                                 .broadcast(Arc::new(event_batch))
                                 .map_err(Kind::channel)?;
                         },
-                        Err(e) => error!("received error via event bus: {}", e),
+                        Err(e) => {
+                            error!("received error via event bus: {}", e);
+                            return Err(Kind::Channel.into());
+                        },
                     }
                 },
                 recv(self.request_receiver) -> event => {

relayer/src/config.rs

@@ -166,6 +166,7 @@ pub(crate) fn store_writer(config: &Config, mut writer: impl Write) -> Result<()
 #[cfg(test)]
 mod tests {
     use super::{parse, store_writer};
+    use test_env_log::test;
 
     #[test]
     fn parse_valid_config() {

relayer/src/event/bus.rs

@@ -44,6 +44,7 @@ mod tests {
 
     use serial_test::serial;
     use std::sync::atomic::{AtomicUsize, Ordering};
+    use test_env_log::test;
 
     static COUNTER: AtomicUsize = AtomicUsize::new(0);
 

relayer/src/event/monitor.rs

@@ -90,6 +90,7 @@ type SubscriptionStream = dyn Stream<Item = SubscriptionResult> + Send + Sync +
 
 pub type Result<T> = std::result::Result<T, Error>;
 
+pub type EventSender = channel::Sender<Result<EventBatch>>;
 pub type EventReceiver = channel::Receiver<Result<EventBatch>>;
 
 /// Connect to a Tendermint node, subscribe to a set of queries,

relayer/src/foreign_client.rs

@@ -935,6 +935,7 @@ mod test {
     use std::str::FromStr;
     use std::sync::Arc;
 
+    use test_env_log::test;
     use tokio::runtime::Runtime as TokioRuntime;
 
     use ibc::events::IbcEvent;

relayer/src/util/retry.rs

@@ -76,6 +76,7 @@ pub fn clamp_total(
 #[cfg(test)]
 mod tests {
     use super::*;
+    use test_env_log::test;
 
     const CONST_STRATEGY: ConstantGrowth =
         ConstantGrowth::new(Duration::from_secs(1), Duration::from_millis(500));

relayer/src/util/stream.rs

@@ -50,6 +50,7 @@ where
 mod tests {
     use super::group_while;
     use futures::{executor::block_on, stream, StreamExt};
+    use test_env_log::test;
 
     #[test]
     fn group_while_non_empty() {