Zebra port conflict in the first zebrad process in CI

[teor2345]

Next Steps

Wait for this failure to happen again, so we can see the diagnostics we added in #1766 and #1770.

Version

Zebra main, after #1736, commit a2e5715.

Platform

Windows CI

Description

The tracing_conflict and metrics_conflict tests sometimes fail because the first zebrad process encounters a port conflict. Increasing the timeout in #1736 didn't fix this issue.

Commands

zebrad start with the tracing_conflict or metrics_conflict test configs.

Logs

Opening tracing endpoint listener 127.0.0.1:49710 failed: hyper::Error(Listen, Os { code: 10013, kind: PermissionDenied, message: "An attempt was made to access a socket in a way forbidden by its access permissions." }). 

Match Regex:
   "Opened tracing endpoint at 127.0.0.1:49710"

Error: 
   0: stdout of command did not contain any matches for the given regex

Location:
   D:\a\zebra\zebra\zebra-test\src\command.rs:371

Command:
   "D:\\a\\zebra\\zebra\\target\\debug\\zebrad.exe" "-c" "C:\\Users\\RUNNER~1\\AppData\\Local\\Temp\\zebrad_tests.X8ySDa639u4m\\zebrad.toml" "start"

Exit Status:
   command exited unsuccessfully with status code 1

Stdout:
   Feb 17 00:37:40.527  INFO {zebrad="a2e5715b" net="Main"}: zebrad::commands::start: Starting zebrad
   Feb 17 00:37:40.528  INFO {zebrad="a2e5715b" net="Main"}: zebrad::commands::start: config=ZebradConfig { consensus: Config { checkpoint_sync: false }, metrics: MetricsSection { endpoint_addr: None }, network: Config { listen_addr: 127.0.0.1:0, network: Mainnet, initial_mainnet_peers: {"dnsseed.str4d.xyz:8233", "mainnet.is.yolo.money:8233", "dnsseed.z.cash:8233", "mainnet.seeder.zfnd.org:8233"}, initial_testnet_peers: {"dnsseed.testnet.z.cash:18233", "testnet.is.yolo.money:18233", "testnet.seeder.zfnd.org:18233"}, peerset_initial_target_size: 50, new_peer_interval: 60s }, state: Config { cache_dir: "C:\\Users\\runneradmin\\AppData\\Local\\zebra", ephemeral: true, debug_stop_at_height: None }, tracing: TracingSection { use_color: true, filter: None, endpoint_addr: Some(127.0.0.1:49710), flamegraph: None }, sync: SyncSection { max_concurrent_block_requests: 50, lookahead_limit: 2000 } }
   Feb 17 00:37:40.528  INFO {zebrad="a2e5715b" net="Main"}: zebrad::commands::start: initializing node state
   Feb 17 00:37:40.529  INFO {zebrad="a2e5715b" net="Main"}: zebra_state::config: assuming Zebra can open a minimum number of files min_limit=512 ideal_limit=1024
   Feb 17 00:37:40.739  INFO {zebrad="a2e5715b" net="Main"}: zebra_state::service::finalized_state: Opened Zebra state cache at C:\Users\RUNNER~1\AppData\Local\Temp\zebra-state-v4-mainnet.YR2e1MWUpyuF
   Feb 17 00:37:40.739  INFO {zebrad="a2e5715b" net="Main"}: zebrad::commands::start: initializing chain verifier
   Feb 17 00:37:40.763  INFO {zebrad="a2e5715b" net="Main"}:init{config=Config { checkpoint_sync: false } network=Mainnet}: zebra_consensus::chain: initializing chain verifier tip=None max_checkpoint_height=Height(419581)
   Feb 17 00:37:40.763  INFO {zebrad="a2e5715b" net="Main"}: zebrad::commands::start: initializing network
   Feb 17 00:37:40.763  INFO {zebrad="a2e5715b" net="Main"}: zebra_network::peer_set::initialize: Sending initial request for peers
   Feb 17 00:37:40.765  INFO listen{addr=127.0.0.1:0}: zebra_network::peer_set::initialize: Opened Zcash protocol endpoint at 127.0.0.1:51879
   Feb 17 00:37:40.773  INFO add_initial_peers: zebra_network::peer_set::initialize: Connecting to initial peer set initial_peers={161.53.201.181:8233, 46.165.221.209:8233, 116.202.170.226:8233, 173.249.20.4:8233, 184.72.241.255:8233, 34.67.71.42:8233, 139.196.121.177:8233, 13.209.30.221:8233, 5.135.140.215:8233, 158.69.25.32:8233, 94.156.174.100:8233, 47.253.0.14:8233, 172.104.127.76:8233, 172.104.189.59:8233, 85.15.179.171:8233, 54.37.81.148:8233, 135.181.20.223:8233, 39.99.44.175:8233, 8.135.7.215:8233, 82.194.206.173:8233, 47.254.176.240:8233, 75.152.21.54:8233, 88.80.28.3:8233, 213.239.201.46:8233, 47.94.92.186:8233, 135.181.79.230:8233, 165.22.76.97:8233, 93.51.53.177:8233, 18.182.25.219:8233, 161.97.68.118:8233, 51.77.64.61:8233, 46.4.65.10:8233, 193.198.68.181:8233, 3.139.233.192:8233, 45.79.223.173:8233, 213.136.78.68:8233, 135.181.49.198:8233, 151.80.96.105:8233, 45.73.44.86:8233, 5.133.65.82:8233, 165.232.125.107:8233, 116.202.129.35:8233, 47.254.179.213:8233, 67.183.29.123:8233, 37.59.57.96:8233, 3.91.227.122:8233, 104.131.113.161:8233, 35.221.131.27:8233, 195.201.11.54:8233, 47.253.8.99:8233, 47.90.200.114:8233, 65.21.5.186:8233, 120.78.77.73:8233, 157.230.41.45:8233, 161.53.201.188:8233, 138.201.252.11:8233, 109.167.229.52:8233, 174.34.52.100:8233, 51.210.188.3:8233, 47.93.194.27:8233, 91.206.16.214:8233, 139.162.73.35:8233, 77.93.223.9:8233, 139.162.138.168:8233, 149.56.135.165:8233, 39.97.178.10:8233, 47.252.80.131:8233, 172.104.106.153:8233, 118.24.175.14:8233, 172.104.180.119:8233, 116.202.13.16:8233, 163.172.89.154:8233}
   Feb 17 00:37:46.825  INFO {zebrad="a2e5715b" net="Main"}: zebrad::commands::start: initializing syncer
   Feb 17 00:37:46.832  INFO {zebrad="a2e5715b" net="Main"}:sync: zebrad::components::sync: starting genesis block download and verify
   

Stderr:
   The application panicked (crashed).
   Message:  Opening tracing endpoint listener 127.0.0.1:49710 failed: hyper::Error(Listen, Os { code: 10013, kind: PermissionDenied, message: "An attempt was made to access a socket in a way forbidden by its access permissions." }). Hint: Check if another zebrad or zcashd process is running. Try changing the tracing endpoint_addr in the Zebra config.
   Location: zebrad\src\components\tracing\endpoint.rs:60
   
   Metadata:
   version: 1.0.0-alpha.2
   git commit: a2e5715b
   Zcash network: Mainnet
   
     ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ BACKTRACE ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━
                                   ⋮ 11 frames hidden ⋮                              
     12: zebrad::components::tracing::endpoint::{{impl}}::init_tokio::{{closure}}<unknown>
         at D:\a\zebra\zebra\zebrad\src\components\tracing\endpoint.rs:60
           58 │                         s
           59 │                     }
           60 >                     Err(e) => panic!(
           61 │                         "Opening tracing endpoint listener {:?} failed: {:?}. \
           62 │                          Hint: Check if another zebrad or zcashd process is running. \
     13: core::future::from_generator::{{impl}}::poll<generator-1><unknown>
         at /rustc/14b27555a03f4abf9b8d80ea34f59144e2ded5e4\library\core\src\future\mod.rs:80
     14: tracing::instrument::{{impl}}::poll<core::future::from_generator::GenFuture<generator-1>><unknown>
         at C:\Users\runneradmin\.cargo\registry\src\github.com-1ecc6299db9ec823\tracing-0.1.23\src\instrument.rs:151
          149 │         let this = self.project();
          150 │         let _enter = this.span.enter();
          151 >         this.inner.poll(cx)
          152 │     }
          153 │ }
     15: tokio::runtime::task::core::{{impl}}::poll::{{closure}}<tracing::instrument::Instrumented<core::future::from_generator::GenFuture<generator-1>>,alloc::sync::Arc<tokio::runtime::thread_pool::worker::Worker>><unknown>
         at C:\Users\runneradmin\.cargo\registry\src\github.com-1ecc6299db9ec823\tokio-0.3.6\src\runtime\task\core.rs:173
          171 │                 let mut cx = Context::from_waker(&*waker_ref);
          172 │ 
          173 >                 future.poll(&mut cx)
          174 │             })
          175 │         };
     16: tokio::loom::std::unsafe_cell::UnsafeCell<tokio::runtime::task::core::Stage<tracing::instrument::Instrumented<core::future::from_generator::GenFuture<generator-1>>>>::with_mut<tokio::runtime::task::core::Stage<tracing::instrument::Instrumented<core::futur<unknown>
         at C:\Users\runneradmin\.cargo\registry\src\github.com-1ecc6299db9ec823\tokio-0.3.6\src\loom\std\unsafe_cell.rs:14
           12 │ 
           13 │     pub(crate) fn with_mut<R>(&self, f: impl FnOnce(*mut T) -> R) -> R {
           14 >         f(self.0.get())
           15 │     }
           16 │ }
     17: tokio::runtime::task::core::Core<tracing::instrument::Instrumented<core::future::from_generator::GenFuture<generator-1>>, alloc::sync::Arc<tokio::runtime::thread_pool::worker::Worker>>::poll<tracing::instrument::Instrumented<core::future::from_generator::<unknown>
         at C:\Users\runneradmin\.cargo\registry\src\github.com-1ecc6299db9ec823\tokio-0.3.6\src\runtime\task\core.rs:158
          156 │     pub(super) fn poll(&self, header: &Header) -> Poll<T::Output> {
          157 │         let res = {
          158 >             self.stage.with_mut(|ptr| {
          159 │                 // Safety: The caller ensures mutual exclusion to the field.
          160 │                 let future = match unsafe { &mut *ptr } {
     18: tokio::runtime::task::harness::{{impl}}::poll::{{closure}}<tracing::instrument::Instrumented<core::future::from_generator::GenFuture<generator-1>>,alloc::sync::Arc<tokio::runtime::thread_pool::worker::Worker>><unknown>
         at C:\Users\runneradmin\.cargo\registry\src\github.com-1ecc6299db9ec823\tokio-0.3.6\src\runtime\task\harness.rs:107
          105 │ 

Match Regex:
   "Opened tracing endpoint at 127.0.0.1:49710"

  ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ BACKTRACE ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━
                                ⋮ 9 frames hidden ⋮                               
  10: zebra_test::command::TestOutput<tempdir::TempDir>::stdout_contains<tempdir::TempDir><unknown>
      at D:\a\zebra\zebra\zebra-test\src\command.rs:371
       369 │         }
       370 │ 
       371 >         Err(eyre!(
       372 │             "stdout of command did not contain any matches for the given regex"
       373 │         ))
  11: acceptance::check_config_conflict<tempdir::TempDir,tempdir::TempDir><unknown>
      at D:\a\zebra\zebra\zebrad\tests\acceptance.rs:1219
      1217 │     // In node1 we want to check for the success regex
      1218 │     let output1 = node1.wait_with_output()?;
      1219 >     output1.stdout_contains(first_stdout_regex)?;
      1220 │     output1
      1221 │         .assert_was_killed()
  12: acceptance::zebra_tracing_conflict<unknown>
      at D:\a\zebra\zebra\zebrad\tests\acceptance.rs:1136
      1134 │     let dir2 = TempDir::new("zebrad_tests")?.with_config(&mut config)?;
      1135 │ 
      1136 >     check_config_conflict(dir1, regex1.as_str(), dir2, PORT_IN_USE_ERROR.as_str())?;
      1137 │ 
      1138 │     Ok(())
  13: acceptance::zebra_tracing_conflict::{{closure}}<unknown>
      at D:\a\zebra\zebra\zebrad\tests\acceptance.rs:1118
      1116 │ /// conflict hint added in #1535.
      1117 │ #[test]
      1118 > fn zebra_tracing_conflict() -> Result<()> {
      1119 │     zebra_test::init();
      1120 │ 
                                ⋮ 2 frames hidden ⋮                               
  16: test::__rust_begin_short_backtrace<fn()><unknown>
      at /rustc/14b27555a03f4abf9b8d80ea34f59144e2ded5e4\/library\test\src\lib.rs:556
  17: alloc::boxed::{{impl}}::call_once<unknown>
      at /rustc/14b27555a03f4abf9b8d80ea34f59144e2ded5e4\library\alloc\src\boxed.rs:1521
                                ⋮ 20 frames hidden ⋮                              

Run with COLORBT_SHOW_HIDDEN=1 environment variable to disable frame filtering.
---- end of test output ----

  ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ BACKTRACE ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━
                                ⋮ 12 frames hidden ⋮                              
  13: acceptance::zebra_tracing_conflict::{{closure}}<unknown>
      at D:\a\zebra\zebra\zebrad\tests\acceptance.rs:1118
      1116 │ /// conflict hint added in #1535.
      1117 │ #[test]
      1118 > fn zebra_tracing_conflict() -> Result<()> {
      1119 │     zebra_test::init();
      1120 │ 
                                ⋮ 2 frames hidden ⋮                               
  16: test::__rust_begin_short_backtrace<fn()><unknown>
      at /rustc/14b27555a03f4abf9b8d80ea34f59144e2ded5e4\/library\test\src\lib.rs:556
  17: alloc::boxed::{{impl}}::call_once<unknown>
      at /rustc/14b27555a03f4abf9b8d80ea34f59144e2ded5e4\library\alloc\src\boxed.rs:1521
                                ⋮ 20 frames hidden ⋮                              

https://github.com/ZcashFoundation/zebra/pull/1760/checks?check_run_id=1914900180#step:8:1585

Also see the logs in #1736.

[mpguerra]

This seems to be happening again

[mpguerra]

I haven't see this for a while, closing