[gcp_pubsub - source] 'vector-worker' panicked at 'internal error: entered unreachable code: request stream never closes', src/sources/gcp_pubsub.rs

[pjamenaja]

A note for the community

• Please vote on this issue by adding a 👍 reaction to the original issue to help the community and maintainers prioritize this request
• If you are interested in working on this issue or have submitted a pull request, please leave a comment

Problem

Hi,

I'm using Vector to pull the message from GCP pub/sub, there are 8 Vector containers run currently run to pull the messages from the same subscription. What I found is, there are a lot of error log below shown below.

thread 'vector-worker' panicked at 'internal error: entered unreachable code: request stream never closes', src/sources/gcp_pubsub.rs:557:41

Notes:

• I'm still able to consume the messages from pub/sub done by Vector even there are many logs as shown above.
• Not sure if this relevant or not. I notice in the GCP console it shows that there are a lot of unacknowledged messages.

Thanks

Configuration

sources:
      pubsub_cloud_log:
        type: gcp_pubsub
        credentials_path: "/secrets/gcp-sa-file.json"
        project: "this-is-my-project-id"
        subscription: "auditlog-remote-sink-sub"

Version

"timberio/vector:0.23.3-distroless-libc" - It is running in K8S environment

Debug Output

2022-08-16 10:38:44 
2022-08-16T03:38:44.000794581Z stderr F note: Some details are omitted, run with `RUST_BACKTRACE=full` for a verbose backtrace.
2022-08-16 10:38:44 
2022-08-16T03:38:44.000774432Z stderr F    6: tokio::runtime::task::raw::poll
2022-08-16 10:38:44 
2022-08-16T03:38:44.000752955Z stderr F    5: tokio::runtime::thread_pool::worker::Context::run_task
2022-08-16 10:38:44 
2022-08-16T03:38:44.000691518Z stderr F    4: tokio::runtime::task::raw::poll
2022-08-16 10:38:44 
2022-08-16T03:38:44.000109584Z stderr F    3: tokio::runtime::task::harness::poll_future
2022-08-16 10:38:44 
2022-08-16T03:38:44.000088462Z stderr F    2: vector::sources::gcp_pubsub::PubsubSource::run_once::{{closure}}
2022-08-16 10:38:44 
2022-08-16T03:38:44.000026914Z stderr F              at ./rustc/fe5b13d681f25ee6474be29d748c65adcd91f69e/library/core/src/panicking.rs:143:14
2022-08-16 10:38:44 
2022-08-16T03:38:43.999935033Z stderr F    1: core::panicking::panic_fmt
2022-08-16 10:38:44 
2022-08-16T03:38:43.999136Z stderr F              at ./rustc/fe5b13d681f25ee6474be29d748c65adcd91f69e/library/std/src/panicking.rs:584:5
2022-08-16 10:38:44 
2022-08-16T03:38:43.999121801Z stderr F    0: rust_begin_unwind
2022-08-16 10:38:44 
2022-08-16T03:38:43.999082949Z stderr F stack backtrace:
2022-08-16 10:38:44 
2022-08-16T03:38:43.999025862Z stderr F thread 'vector-worker' panicked at 'internal error: entered unreachable code: request stream never closes', src/sources/gcp_pubsub.rs:557:41

Example Data

No response

Additional Context

No response

References

No response

[pjamenaja]

This is the logs with "full" option.

  |   | 2022-08-16 10:55:59 | 2022-08-16T03:55:59.46239321Z stderr F                                at /rustc/fe5b13d681f25ee6474be29d748c65adcd91f69e/library/std/src/sys/unix/thread.rs:108:17
  |   | 2022-08-16 10:55:59 | 2022-08-16T03:55:59.462383313Z stderr F   24:     0x557874326095 - std::sys::unix::thread::Thread::new::thread_start::h9f8e3d72b1f7662f
  |   | 2022-08-16 10:55:59 | 2022-08-16T03:55:59.462372649Z stderr F                                at /rustc/fe5b13d681f25ee6474be29d748c65adcd91f69e/library/alloc/src/boxed.rs:1861:9
  |   | 2022-08-16 10:55:59 | 2022-08-16T03:55:59.462342376Z stderr F   23:     0x557874326095 - <alloc::boxed::Box<F,A> as core::ops::function::FnOnce<Args>>::call_once::ha39aea1c57e28a15
  |   | 2022-08-16 10:55:59 | 2022-08-16T03:55:59.462307793Z stderr F                                at /rustc/fe5b13d681f25ee6474be29d748c65adcd91f69e/library/alloc/src/boxed.rs:1861:9
  |   | 2022-08-16 10:55:59 | 2022-08-16T03:55:59.460467556Z stderr F   22:     0x557874326095 - <alloc::boxed::Box<F,A> as core::ops::function::FnOnce<Args>>::call_once::ha99802c2c52ada61
  |   | 2022-08-16 10:55:59 | 2022-08-16T03:55:59.459060526Z stderr F   21:     0x5578743433d0 - core::ops::function::FnOnce::call_once{{vtable.shim}}::had6ce1bc24b82214
  |   | 2022-08-16 10:55:59 | 2022-08-16T03:55:59.45904741Z stderr F   20:     0x557874343687 - std::sys_common::backtrace::__rust_begin_short_backtrace::h3a7c77c7d51a1f9e
  |   | 2022-08-16 10:55:59 | 2022-08-16T03:55:59.458924771Z stderr F   19:     0x55787435d39d - tokio::runtime::task::raw::poll::h9736a719cd7cffe3
  |   | 2022-08-16 10:55:59 | 2022-08-16T03:55:59.458914128Z stderr F   18:     0x55787435f26b - tokio::runtime::thread_pool::worker::Context::run_task::hed375639022a2c00
  |   | 2022-08-16 10:55:59 | 2022-08-16T03:55:59.45888632Z stderr F   17:     0x55787521bad4 - tokio::runtime::task::raw::poll::heb8422fb0cf9490a
  |   | 2022-08-16 10:55:59 | 2022-08-16T03:55:59.457530238Z stderr F   16:     0x55787521c808 - tokio::runtime::task::harness::poll_future::hafa925bb31691766
  |   | 2022-08-16 10:55:59 | 2022-08-16T03:55:59.455396139Z stderr F   15:     0x55787522dc2a - vector::sources::gcp_pubsub::PubsubSource::run_once::{{closure}}::h91f7a00e2381e565
  |   | 2022-08-16 10:55:59 | 2022-08-16T03:55:59.452679907Z stderr F                                at /rustc/fe5b13d681f25ee6474be29d748c65adcd91f69e/library/core/src/panicking.rs:143:14
  |   | 2022-08-16 10:55:59 | 2022-08-16T03:55:59.4504659Z stderr F   14:     0x5578736426d2 - core::panicking::panic_fmt::h366d3a309ae17c94
  |   | 2022-08-16 10:55:59 | 2022-08-16T03:55:59.448051673Z stderr F                                at /rustc/fe5b13d681f25ee6474be29d748c65adcd91f69e/library/std/src/panicking.rs:584:5
  |   | 2022-08-16 10:55:59 | 2022-08-16T03:55:59.44481195Z stderr F   13:     0x557874323a42 - rust_begin_unwind
  |   | 2022-08-16 10:55:59 | 2022-08-16T03:55:59.444801551Z stderr F                                at /rustc/fe5b13d681f25ee6474be29d748c65adcd91f69e/library/std/src/sys_common/backtrace.rs:138:18
  |   | 2022-08-16 10:55:59 | 2022-08-16T03:55:59.444791515Z stderr F   12:     0x557874323a86 - std::sys_common::backtrace::__rust_end_short_backtrace::ha48b94ab49b30915
  |   | 2022-08-16 10:55:59 | 2022-08-16T03:55:59.444781258Z stderr F                                at /rustc/fe5b13d681f25ee6474be29d748c65adcd91f69e/library/std/src/panicking.rs:588:13
  |   | 2022-08-16 10:55:59 | 2022-08-16T03:55:59.444771278Z stderr F   11:     0x557874323b12 - std::panicking::begin_panic_handler::{{closure}}::he054b2a83a51d2cd
  |   | 2022-08-16 10:55:59 | 2022-08-16T03:55:59.444761694Z stderr F                                at /rustc/fe5b13d681f25ee6474be29d748c65adcd91f69e/library/std/src/panicking.rs:698:17
  |   | 2022-08-16 10:55:59 | 2022-08-16T03:55:59.444751731Z stderr F   10:     0x557874323f9a - std::panicking::rust_panic_with_hook::habfdcc2e90f9fd4c
  |   | 2022-08-16 10:55:59 | 2022-08-16T03:55:59.44474027Z stderr F                                at /rustc/fe5b13d681f25ee6474be29d748c65adcd91f69e/library/std/src/panicking.rs:314:9
  |   | 2022-08-16 10:55:59 | 2022-08-16T03:55:59.444730603Z stderr F    9:     0x557874323f9a - std::panicking::default_hook::h2e88d02087fae196
  |   | 2022-08-16 10:55:59 | 2022-08-16T03:55:59.444720538Z stderr F                                at /rustc/fe5b13d681f25ee6474be29d748c65adcd91f69e/library/std/src/panicking.rs:295:22
  |   | 2022-08-16 10:55:59 | 2022-08-16T03:55:59.444710749Z stderr F    8:     0x557874323205 - std::panicking::default_hook::{{closure}}::hc9a76eed0b18f82b
  |   | 2022-08-16 10:55:59 | 2022-08-16T03:55:59.444696873Z stderr F                                at /rustc/fe5b13d681f25ee6474be29d748c65adcd91f69e/library/std/src/sys_common/backtrace.rs:35:9
  |   | 2022-08-16 10:55:59 | 2022-08-16T03:55:59.444678405Z stderr F    7:     0x557874323205 - std::sys_common::backtrace::print::h426700d6240cdcc2
  |   | 2022-08-16 10:55:59 | 2022-08-16T03:55:59.444668469Z stderr F                                at /rustc/fe5b13d681f25ee6474be29d748c65adcd91f69e/library/std/src/sys_common/backtrace.rs:48:5
  |   | 2022-08-16 10:55:59 | 2022-08-16T03:55:59.444658209Z stderr F    6:     0x557874323205 - std::sys_common::backtrace::_print::h63c8b24acdd8e8ce
  |   | 2022-08-16 10:55:59 | 2022-08-16T03:55:59.444647398Z stderr F                                at /rustc/fe5b13d681f25ee6474be29d748c65adcd91f69e/library/std/src/io/mod.rs:1655:15
  |   | 2022-08-16 10:55:59 | 2022-08-16T03:55:59.444617971Z stderr F    5:     0x5578742f4710 - std::io::Write::write_fmt::heb73de6e02cfabed
  |   | 2022-08-16 10:55:59 | 2022-08-16T03:55:59.444587079Z stderr F                                at /rustc/fe5b13d681f25ee6474be29d748c65adcd91f69e/library/core/src/fmt/mod.rs:1194:17
  |   | 2022-08-16 10:55:59 | 2022-08-16T03:55:59.441889287Z stderr F    4:     0x557873b0c57c - core::fmt::write::hba4337c43d992f49
  |   | 2022-08-16 10:55:59 | 2022-08-16T03:55:59.44187636Z stderr F                                at /rustc/fe5b13d681f25ee6474be29d748c65adcd91f69e/library/std/src/sys_common/backtrace.rs:45:22
  |   | 2022-08-16 10:55:59 | 2022-08-16T03:55:59.441849126Z stderr F    3:     0x5578743226f0 - <std::sys_common::backtrace::_print::DisplayBacktrace as core::fmt::Display>::fmt::h9c2a9d2774d81873
  |   | 2022-08-16 10:55:59 | 2022-08-16T03:55:59.440237076Z stderr F                                at /rustc/fe5b13d681f25ee6474be29d748c65adcd91f69e/library/std/src/sys_common/backtrace.rs:66:5
  |   | 2022-08-16 10:55:59 | 2022-08-16T03:55:59.437562544Z stderr F    2:     0x5578743226f0 - std::sys_common::backtrace::_print_fmt::he497d8a0ec903793
  |   | 2022-08-16 10:55:59 | 2022-08-16T03:55:59.435328004Z stderr F                                at /rustc/fe5b13d681f25ee6474be29d748c65adcd91f69e/library/std/src/../../backtrace/src/backtrace/mod.rs:66:5
  |   | 2022-08-16 10:55:59 | 2022-08-16T03:55:59.432923932Z stderr F    1:     0x5578743226f0 - std::backtrace_rs::backtrace::trace_unsynchronized::h29c3bc6f9e91819d
  |   | 2022-08-16 10:55:59 | 2022-08-16T03:55:59.430769151Z stderr F                                at /rustc/fe5b13d681f25ee6474be29d748c65adcd91f69e/library/std/src/../../backtrace/src/backtrace/libunwind.rs:93:5
  |   | 2022-08-16 10:55:59 | 2022-08-16T03:55:59.427725339Z stderr F    0:     0x5578743226f0 - std::backtrace_rs::backtrace::libunwind::trace::h22893a5306c091b4
  |   | 2022-08-16 10:55:59 | 2022-08-16T03:55:59.358753963Z stderr F stack backtrace:
  |   | 2022-08-16 10:55:59 | 2022-08-16T03:55:59.358699987Z stderr F thread 'vector-worker' panicked at 'internal error: entered unreachable code: request stream never closes', src/sources/gcp_pubsub.rs:557:41

[bruceg]

I think I see what is going on. The request stream holds on to a receiver for which the sending end is dropped when the connection is retried. No more requests are read after that drop, but a race could cause the error. This should be harmless, but don't quote me on that. I'll make handling this more intelligent.

[zpriddy]

Im starting to see this exact issue.. it seems like after the error, it never re-connects to pub/sub to start pulling more logs..

Is there any suggested fixes to try for this?