search

MaterializeInc / materialize

The data warehouse for operational workloads.
https://materialize.com
Other
5.67k stars 458 forks source link

test_balancer: Failed to start test Server: error communicating with the server: bytes remaining on stream #26676

Open def- opened 3 months ago

def- commented 3 months ago

What version of Materialize are you using?

114280ffe2c6

What is the issue?

thread 'test_balancer' panicked at src/environmentd/src/test_util.rs:159:32:
Failed to start test Server: error communicating with the server: bytes remaining on stream

Caused by:
    bytes remaining on stream

Stack backtrace:
   0: <core::result::Result<mz_environmentd::test_util::TestServer, anyhow::Error> as core::ops::try_trait::FromResidual<core::result::Result<core::convert::Infallible, tokio_postgres::error::Error>>>::from_residual
             at /rustc/aedd173a2c086e558c2b66d3743b344f977621a7/library/core/src/result.rs:1959:27
   1: <mz_environmentd::test_util::Listeners>::serve_with_trigger::{closure#0}
             at /var/lib/buildkite-agent/builds/buildkite-builders-aarch64-585fc7f-i-0da88c5a005ae364f-1/materialize/test/src/environmentd/src/test_util.rs:351:34
   2: <mz_environmentd::test_util::TestHarness>::try_start_with_trigger::{closure#0}
             at /var/lib/buildkite-agent/builds/buildkite-builders-aarch64-585fc7f-i-0da88c5a005ae364f-1/materialize/test/src/environmentd/src/test_util.rs:181:58
   3: <mz_environmentd::test_util::TestHarness>::try_start::{closure#0}
             at /var/lib/buildkite-agent/builds/buildkite-builders-aarch64-585fc7f-i-0da88c5a005ae364f-1/materialize/test/src/environmentd/src/test_util.rs:172:14
   4: <mz_environmentd::test_util::TestHarness>::start::{closure#0}
             at /var/lib/buildkite-agent/builds/buildkite-builders-aarch64-585fc7f-i-0da88c5a005ae364f-1/materialize/test/src/environmentd/src/test_util.rs:159:26
   5: server::test_balancer::{closure#0}::test_impl::{closure#0}
             at ./tests/server.rs:111:38
   6: server::test_balancer::{closure#0}
             at ./tests/server.rs:39:1
   7: <core::pin::Pin<&mut dyn core::future::future::Future<Output = ()>> as core::future::future::Future>::poll
             at /rustc/aedd173a2c086e558c2b66d3743b344f977621a7/library/core/src/future/future.rs:124:9
   8: <tracing::instrument::Instrumented<core::pin::Pin<&mut dyn core::future::future::Future<Output = ()>>> as core::future::future::Future>::poll
             at /cargo/registry/src/index.crates.io-6f17d22bba15001f/tracing-0.1.37/src/instrument.rs:272:9
   9: <tokio::runtime::park::CachedParkThread>::block_on::<tracing::instrument::Instrumented<core::pin::Pin<&mut dyn core::future::future::Future<Output = ()>>>>::{closure#0}
             at /cargo/registry/src/index.crates.io-6f17d22bba15001f/tokio-1.32.0/src/runtime/park.rs:282:63
  10: <tokio::runtime::park::CachedParkThread>::block_on::<tracing::instrument::Instrumented<core::pin::Pin<&mut dyn core::future::future::Future<Output = ()>>>>
             at /cargo/registry/src/index.crates.io-6f17d22bba15001f/tokio-1.32.0/src/runtime/coop.rs:107:5
  11: <tokio::runtime::context::blocking::BlockingRegionGuard>::block_on::<tracing::instrument::Instrumented<core::pin::Pin<&mut dyn core::future::future::Future<Output = ()>>>>
             at /cargo/registry/src/index.crates.io-6f17d22bba15001f/tokio-1.32.0/src/runtime/context/blocking.rs:66:9
  12: <tokio::runtime::scheduler::multi_thread::MultiThread>::block_on::<tracing::instrument::Instrumented<core::pin::Pin<&mut dyn core::future::future::Future<Output = ()>>>>::{closure#0}
             at /cargo/registry/src/index.crates.io-6f17d22bba15001f/tokio-1.32.0/src/runtime/scheduler/multi_thread/mod.rs:87:13
  13: tokio::runtime::context::runtime::enter_runtime::<<tokio::runtime::scheduler::multi_thread::MultiThread>::block_on<tracing::instrument::Instrumented<core::pin::Pin<&mut dyn core::future::future::Future<Output = ()>>>>::{closure#0}, ()>
             at /cargo/registry/src/index.crates.io-6f17d22bba15001f/tokio-1.32.0/src/runtime/context/runtime.rs:65:16
  14: <tokio::runtime::scheduler::multi_thread::MultiThread>::block_on::<tracing::instrument::Instrumented<core::pin::Pin<&mut dyn core::future::future::Future<Output = ()>>>>
             at /cargo/registry/src/index.crates.io-6f17d22bba15001f/tokio-1.32.0/src/runtime/scheduler/multi_thread/mod.rs:86:9
  15: <tokio::runtime::runtime::Runtime>::block_on::<core::pin::Pin<&mut dyn core::future::future::Future<Output = ()>>>
             at /cargo/registry/src/index.crates.io-6f17d22bba15001f/tokio-1.32.0/src/runtime/runtime.rs:349:45
  16: server::test_balancer
             at ./tests/server.rs:39:1
  17: server::test_balancer::{closure#0}
             at ./tests/server.rs:39:74
  18: <server::test_balancer::{closure#0} as core::ops::function::FnOnce<()>>::call_once
             at /rustc/aedd173a2c086e558c2b66d3743b344f977621a7/library/core/src/ops/function.rs:250:5
  19: core::ops::function::FnOnce::call_once
             at /rustc/aedd173a2c086e558c2b66d3743b344f977621a7/library/core/src/ops/function.rs:250:5
      test::__rust_begin_short_backtrace
             at /rustc/aedd173a2c086e558c2b66d3743b344f977621a7/library/test/src/lib.rs:621:18
  20: test::run_test_in_process::{{closure}}
             at /rustc/aedd173a2c086e558c2b66d3743b344f977621a7/library/test/src/lib.rs:644:60
      <core::panic::unwind_safe::AssertUnwindSafe<F> as core::ops::function::FnOnce<()>>::call_once
             at /rustc/aedd173a2c086e558c2b66d3743b344f977621a7/library/core/src/panic/unwind_safe.rs:272:9
      std::panicking::try::do_call
             at /rustc/aedd173a2c086e558c2b66d3743b344f977621a7/library/std/src/panicking.rs:554:40
      std::panicking::try
             at /rustc/aedd173a2c086e558c2b66d3743b344f977621a7/library/std/src/panicking.rs:518:19
      std::panic::catch_unwind
             at /rustc/aedd173a2c086e558c2b66d3743b344f977621a7/library/std/src/panic.rs:142:14
      test::run_test_in_process
             at /rustc/aedd173a2c086e558c2b66d3743b344f977621a7/library/test/src/lib.rs:644:27
      test::run_test::{{closure}}
             at /rustc/aedd173a2c086e558c2b66d3743b344f977621a7/library/test/src/lib.rs:567:43
  21: test::run_test::{{closure}}
             at /rustc/aedd173a2c086e558c2b66d3743b344f977621a7/library/test/src/lib.rs:595:41
      std::sys_common::backtrace::__rust_begin_short_backtrace
             at /rustc/aedd173a2c086e558c2b66d3743b344f977621a7/library/std/src/sys_common/backtrace.rs:155:18
  22: std::thread::Builder::spawn_unchecked_::{{closure}}::{{closure}}
             at /rustc/aedd173a2c086e558c2b66d3743b344f977621a7/library/std/src/thread/mod.rs:529:17
      <core::panic::unwind_safe::AssertUnwindSafe<F> as core::ops::function::FnOnce<()>>::call_once
             at /rustc/aedd173a2c086e558c2b66d3743b344f977621a7/library/core/src/panic/unwind_safe.rs:272:9
      std::panicking::try::do_call
             at /rustc/aedd173a2c086e558c2b66d3743b344f977621a7/library/std/src/panicking.rs:554:40
      std::panicking::try
             at /rustc/aedd173a2c086e558c2b66d3743b344f977621a7/library/std/src/panicking.rs:518:19
      std::panic::catch_unwind
             at /rustc/aedd173a2c086e558c2b66d3743b344f977621a7/library/std/src/panic.rs:142:14
      std::thread::Builder::spawn_unchecked_::{{closure}}
             at /rustc/aedd173a2c086e558c2b66d3743b344f977621a7/library/std/src/thread/mod.rs:528:30
      core::ops::function::FnOnce::call_once{{vtable.shim}}
             at /rustc/aedd173a2c086e558c2b66d3743b344f977621a7/library/core/src/ops/function.rs:250:5
  23: <alloc::boxed::Box<F,A> as core::ops::function::FnOnce<Args>>::call_once
             at /rustc/aedd173a2c086e558c2b66d3743b344f977621a7/library/alloc/src/boxed.rs:2015:9
      <alloc::boxed::Box<F,A> as core::ops::function::FnOnce<Args>>::call_once
             at /rustc/aedd173a2c086e558c2b66d3743b344f977621a7/library/alloc/src/boxed.rs:2015:9
      std::sys::pal::unix::thread::Thread::new::thread_start
             at /rustc/aedd173a2c086e558c2b66d3743b344f977621a7/library/std/src/sys/pal/unix/thread.rs:108:17
  24: start_thread
             at ./nptl/./nptl/pthread_create.c:444:8
  25: thread_start
             at ./misc/../sysdeps/unix/sysv/linux/aarch64/clone.S:79
stack backtrace:
   0: rust_begin_unwind
             at /rustc/aedd173a2c086e558c2b66d3743b344f977621a7/library/std/src/panicking.rs:647:5
   1: core::panicking::panic_fmt
             at /rustc/aedd173a2c086e558c2b66d3743b344f977621a7/library/core/src/panicking.rs:72:14
   2: core::result::unwrap_failed
             at /rustc/aedd173a2c086e558c2b66d3743b344f977621a7/library/core/src/result.rs:1649:5
   3: <core::result::Result<mz_environmentd::test_util::TestServer, anyhow::Error>>::expect
             at /rustc/aedd173a2c086e558c2b66d3743b344f977621a7/library/core/src/result.rs:1030:23
   4: {async_fn#0}
             at /var/lib/buildkite-agent/builds/buildkite-builders-aarch64-585fc7f-i-0da88c5a005ae364f-1/materialize/test/src/environmentd/src/test_util.rs:159:9
   5: {async_fn#0}
             at ./tests/server.rs:111:38
   6: {async_block#0}
             at ./tests/server.rs:39:1
   7: poll<&mut dyn core::future::future::Future<Output=()>>
             at /rustc/aedd173a2c086e558c2b66d3743b344f977621a7/library/core/src/future/future.rs:124:9
   8: poll<core::pin::Pin<&mut dyn core::future::future::Future<Output=()>>>
             at /cargo/registry/src/index.crates.io-6f17d22bba15001f/tracing-0.1.37/src/instrument.rs:272:9
   9: {closure#0}<tracing::instrument::Instrumented<core::pin::Pin<&mut dyn core::future::future::Future<Output=()>>>>
             at /cargo/registry/src/index.crates.io-6f17d22bba15001f/tokio-1.32.0/src/runtime/park.rs:282:63
  10: with_budget<core::task::poll::Poll<()>, tokio::runtime::park::{impl#4}::block_on::{closure_env#0}<tracing::instrument::Instrumented<core::pin::Pin<&mut dyn core::future::future::Future<Output=()>>>>>
             at /cargo/registry/src/index.crates.io-6f17d22bba15001f/tokio-1.32.0/src/runtime/coop.rs:107:5
  11: budget<core::task::poll::Poll<()>, tokio::runtime::park::{impl#4}::block_on::{closure_env#0}<tracing::instrument::Instrumented<core::pin::Pin<&mut dyn core::future::future::Future<Output=()>>>>>
             at /cargo/registry/src/index.crates.io-6f17d22bba15001f/tokio-1.32.0/src/runtime/coop.rs:73:5
  12: block_on<tracing::instrument::Instrumented<core::pin::Pin<&mut dyn core::future::future::Future<Output=()>>>>
             at /cargo/registry/src/index.crates.io-6f17d22bba15001f/tokio-1.32.0/src/runtime/park.rs:282:31
  13: <tokio::runtime::context::blocking::BlockingRegionGuard>::block_on::<tracing::instrument::Instrumented<core::pin::Pin<&mut dyn core::future::future::Future<Output = ()>>>>
             at /cargo/registry/src/index.crates.io-6f17d22bba15001f/tokio-1.32.0/src/runtime/context/blocking.rs:66:9
  14: <tokio::runtime::scheduler::multi_thread::MultiThread>::block_on::<tracing::instrument::Instrumented<core::pin::Pin<&mut dyn core::future::future::Future<Output = ()>>>>::{closure#0}
             at /cargo/registry/src/index.crates.io-6f17d22bba15001f/tokio-1.32.0/src/runtime/scheduler/multi_thread/mod.rs:87:13
  15: tokio::runtime::context::runtime::enter_runtime::<<tokio::runtime::scheduler::multi_thread::MultiThread>::block_on<tracing::instrument::Instrumented<core::pin::Pin<&mut dyn core::future::future::Future<Output = ()>>>>::{closure#0}, ()>
             at /cargo/registry/src/index.crates.io-6f17d22bba15001f/tokio-1.32.0/src/runtime/context/runtime.rs:65:16
  16: <tokio::runtime::scheduler::multi_thread::MultiThread>::block_on::<tracing::instrument::Instrumented<core::pin::Pin<&mut dyn core::future::future::Future<Output = ()>>>>
             at /cargo/registry/src/index.crates.io-6f17d22bba15001f/tokio-1.32.0/src/runtime/scheduler/multi_thread/mod.rs:86:9
  17: <tokio::runtime::runtime::Runtime>::block_on::<core::pin::Pin<&mut dyn core::future::future::Future<Output = ()>>>
             at /cargo/registry/src/index.crates.io-6f17d22bba15001f/tokio-1.32.0/src/runtime/runtime.rs:349:45
  18: test_balancer
             at ./tests/server.rs:39:1
  19: server::test_balancer::{closure#0}
             at ./tests/server.rs:39:74
  20: <server::test_balancer::{closure#0} as core::ops::function::FnOnce<()>>::call_once
             at /rustc/aedd173a2c086e558c2b66d3743b344f977621a7/library/core/src/ops/function.rs:250:5
  21: core::ops::function::FnOnce::call_once
             at /rustc/aedd173a2c086e558c2b66d3743b344f977621a7/library/core/src/ops/function.rs:250:5
note: Some details are omitted, run with `RUST_BACKTRACE=full` for a verbose backtrace.

Seen in https://buildkite.com/materialize/test/builds/80778#018ee717-5516-4157-9fcd-bba10c8375e8

ci-regexp: test_balancer.*Failed to start test Server: error communicating with the server: bytes remaining on stream

maddyblue commented 3 months ago

The error message bytes remaining on stream shows up in various tokio network io issues around the internet. Reading through them didn't give me any ideas. Running ./bin/buildkite-annotation-search --max-build-fetches 1000 test 'bytes remaining on stream' didn't find any others (I'm not sure that command even would find them since it didn't appear to find even the failure above, but reporting in case it's correct). I'm not going to look into this more until we start seeing it more.