search

solana-labs / solana

Web-Scale Blockchain for fast, secure, scalable, decentralized apps and marketplaces.
https://solanalabs.com
Apache License 2.0
13.02k stars 4.19k forks source link

rpc node restarts with dead subscription encountered in SubscriptionControl #21948

Closed stakeconomy closed 2 years ago

stakeconomy commented 2 years ago

Problem

Today one of our RPC nodes restarted with status=1/FAILURE dead subscription encountered in SubscriptionControl

Dec 16 11:18:34 tyo7 solana-rpc.sh[41407]: [2021-12-16T11:18:34.172300617Z INFO  solana_metrics::metrics] datapoint: rpc_pubsub_total_subscriptions count=602i
Dec 16 11:18:34 tyo7 solana-rpc.sh[41407]: [2021-12-16T11:18:34.172302971Z INFO  solana_metrics::metrics] datapoint: shred_fetch_tvu_forwards index_overrun=0i shred_count=5428i slot_bad_deserialize=0i index_bad_deserialize=0i index_out_of_bounds=0i slot_out_of_range=0i duplicate_shred=2294i
Dec 16 11:18:34 tyo7 solana-rpc.sh[41407]:    0: rust_begin_unwind
Dec 16 11:18:34 tyo7 solana-rpc.sh[41407]:              at /rustc/9bc8c42bb2f19e745a63f3445f1ac248fb015e53/library/std/src/panicking.rs:493:5
Dec 16 11:18:34 tyo7 solana-rpc.sh[41407]:    1: core::panicking::panic_fmt
Dec 16 11:18:34 tyo7 solana-rpc.sh[41407]:              at /rustc/9bc8c42bb2f19e745a63f3445f1ac248fb015e53/library/core/src/panicking.rs:92:14
Dec 16 11:18:34 tyo7 solana-rpc.sh[41407]:    2: core::option::expect_failed
Dec 16 11:18:34 tyo7 solana-rpc.sh[41407]:              at /rustc/9bc8c42bb2f19e745a63f3445f1ac248fb015e53/library/core/src/option.rs:1321:5
Dec 16 11:18:34 tyo7 solana-rpc.sh[41407]:    3: solana_rpc::rpc_subscription_tracker::SubscriptionControl::subscribe
Dec 16 11:18:34 tyo7 solana-rpc.sh[41407]:    4: solana_rpc::rpc_pubsub::RpcSolPubSubImpl::subscribe
Dec 16 11:18:34 tyo7 solana-rpc.sh[41407]:    5: <solana_rpc::rpc_pubsub::RpcSolPubSubImpl as solana_rpc::rpc_pubsub::internal::rpc_impl_RpcSolPubSubInternal::gen_server::RpcSolPubSubInternal>::program_subscribe
Dec 16 11:18:34 tyo7 solana-rpc.sh[41407]:    6: <jsonrpc_core::delegates::DelegateAsyncMethod<T,F> as jsonrpc_core::calls::RpcMethod<M>>::call
Dec 16 11:18:34 tyo7 solana-rpc.sh[41407]:    7: jsonrpc_core::middleware::Middleware::on_call
Dec 16 11:18:34 tyo7 solana-rpc.sh[41407]:    8: jsonrpc_core::io::IoHandler<M>::handle_request
Dec 16 11:18:34 tyo7 solana-rpc.sh[41407]:    9: <core::future::from_generator::GenFuture<T> as core::future::future::Future>::poll
Dec 16 11:18:34 tyo7 solana-rpc.sh[41407]:   10: <std::panic::AssertUnwindSafe<F> as core::ops::function::FnOnce<()>>::call_once
Dec 16 11:18:34 tyo7 solana-rpc.sh[41407]:   11: tokio::runtime::task::harness::poll_future
Dec 16 11:18:34 tyo7 solana-rpc.sh[41407]:   12: tokio::runtime::task::harness::Harness<T,S>::poll
Dec 16 11:18:34 tyo7 solana-rpc.sh[41407]:   13: std::thread::local::LocalKey<T>::with
Dec 16 11:18:34 tyo7 solana-rpc.sh[41407]:   14: tokio::runtime::thread_pool::worker::Context::run_task
Dec 16 11:18:34 tyo7 solana-rpc.sh[41407]:   15: tokio::runtime::thread_pool::worker::Context::run
Dec 16 11:18:34 tyo7 solana-rpc.sh[41407]:   16: tokio::macros::scoped_tls::ScopedKey<T>::set
Dec 16 11:18:34 tyo7 solana-rpc.sh[41407]:   17: tokio::runtime::thread_pool::worker::run
Dec 16 11:18:34 tyo7 solana-rpc.sh[41407]:   18: tokio::loom::std::unsafe_cell::UnsafeCell<T>::with_mut
Dec 16 11:18:34 tyo7 solana-rpc.sh[41407]:   19: std::panicking::try
Dec 16 11:18:34 tyo7 solana-rpc.sh[41407]:   20: tokio::runtime::task::harness::Harness<T,S>::poll
Dec 16 11:18:34 tyo7 solana-rpc.sh[41407]:   21: tokio::runtime::blocking::pool::Inner::run
Dec 16 11:18:34 tyo7 solana-rpc.sh[41407]: note: Some details are omitted, run with `RUST_BACKTRACE=full` for a verbose backtrace.
Dec 16 11:18:34 tyo7 solana-rpc.sh[41407]: [2021-12-16T11:18:34.248212226Z ERROR solana_metrics::metrics] datapoint: panic program="validator" thread="tokio-runtime-worker" one=1i message="panicked at 'dead subscription encountered in SubscriptionControl', rpc/src/rpc_subscription_tracker.rs:203:22" location="rpc/s>
Dec 16 11:18:34 tyo7 solana-rpc.sh[41407]: [2021-12-16T11:18:34.248265046Z INFO  solana_metrics::metrics] submitting 298 points
Dec 16 11:18:34 tyo7 solana-rpc.sh[41407]: [2021-12-16T11:18:34.297606101Z INFO  solana_metrics::metrics] datapoint: optimistic_slot_elapsed average_elapsed_ms=482i
Dec 16 11:18:34 tyo7 solana-rpc.sh[41407]: [2021-12-16T11:18:34.297630487Z INFO  solana_metrics::metrics] datapoint: optimistic_slot slot=111799900i
Dec 16 11:18:42 tyo7 systemd[2793]: solana-rpc.service: Main process exited, code=exited, status=1/FAILURE
Dec 16 11:18:42 tyo7 systemd[2793]: solana-rpc.service: Failed with result 'exit-code'.
Dec 16 11:18:44 tyo7 systemd[2793]: solana-rpc.service: Scheduled restart job, restart counter is at 2.
stakeconomy commented 2 years ago

message (42).txt

Lusitaniae commented 2 years ago

Another one 

Dec 28 15:11:05 nyc33 solana-rpc.sh[9808]: thread 'tokio-runtime-worker' panicked at 'dead subscription encountered in SubscriptionControl', rpc/src/rpc_subscription_tracker.rs:203:22
Dec 28 15:11:05 nyc33 solana-rpc.sh[9808]: stack backtrace:
Dec 28 15:11:05 nyc33 solana-rpc.sh[9808]: [2021-12-28T15:11:04.640959521Z INFO  solana_metrics::metrics] datapoint: shred_fetch_tvu_forwards index_overrun=0i shred_count=4949i slot_bad_deserialize=0i index_bad_deserialize=0i index_out_of_bounds=0i slot_out_of_range=1i duplicate_shred=1972i
Dec 28 15:11:05 nyc33 solana-rpc.sh[9808]:    0: rust_begin_unwind
Dec 28 15:11:05 nyc33 solana-rpc.sh[9808]:              at /rustc/9bc8c42bb2f19e745a63f3445f1ac248fb015e53/library/std/src/panicking.rs:493:5
Dec 28 15:11:05 nyc33 solana-rpc.sh[9808]:    1: core::panicking::panic_fmt
Dec 28 15:11:05 nyc33 solana-rpc.sh[9808]:              at /rustc/9bc8c42bb2f19e745a63f3445f1ac248fb015e53/library/core/src/panicking.rs:92:14
Dec 28 15:11:05 nyc33 solana-rpc.sh[9808]:    2: core::option::expect_failed
Dec 28 15:11:05 nyc33 solana-rpc.sh[9808]:              at /rustc/9bc8c42bb2f19e745a63f3445f1ac248fb015e53/library/core/src/option.rs:1321:5
Dec 28 15:11:05 nyc33 solana-rpc.sh[9808]:    3: solana_rpc::rpc_subscription_tracker::SubscriptionControl::subscribe
Dec 28 15:11:05 nyc33 solana-rpc.sh[9808]:    4: solana_rpc::rpc_pubsub::RpcSolPubSubImpl::subscribe
Dec 28 15:11:05 nyc33 solana-rpc.sh[9808]:    5: <solana_rpc::rpc_pubsub::RpcSolPubSubImpl as solana_rpc::rpc_pubsub::internal::rpc_impl_RpcSolPubSubInternal::gen_server::RpcSolPubSubInternal>::program_subscribe
Dec 28 15:11:05 nyc33 solana-rpc.sh[9808]:    6: <jsonrpc_core::delegates::DelegateAsyncMethod<T,F> as jsonrpc_core::calls::RpcMethod<M>>::call
Dec 28 15:11:05 nyc33 solana-rpc.sh[9808]:    7: jsonrpc_core::middleware::Middleware::on_call
Dec 28 15:11:05 nyc33 solana-rpc.sh[9808]:    8: jsonrpc_core::io::IoHandler<M>::handle_request
Dec 28 15:11:05 nyc33 solana-rpc.sh[9808]:    9: <core::future::from_generator::GenFuture<T> as core::future::future::Future>::poll
Dec 28 15:11:05 nyc33 solana-rpc.sh[9808]:   10: <std::panic::AssertUnwindSafe<F> as core::ops::function::FnOnce<()>>::call_once
Dec 28 15:11:05 nyc33 solana-rpc.sh[9808]:   11: tokio::runtime::task::harness::poll_future
Dec 28 15:11:05 nyc33 solana-rpc.sh[9808]:   12: tokio::runtime::task::harness::Harness<T,S>::poll
Dec 28 15:11:05 nyc33 solana-rpc.sh[9808]:   13: std::thread::local::LocalKey<T>::with
Dec 28 15:11:05 nyc33 solana-rpc.sh[9808]:   14: tokio::runtime::thread_pool::worker::Context::run_task
Dec 28 15:11:05 nyc33 solana-rpc.sh[9808]:   15: tokio::runtime::thread_pool::worker::Context::run
Dec 28 15:11:05 nyc33 solana-rpc.sh[9808]:   16: tokio::macros::scoped_tls::ScopedKey<T>::set
Dec 28 15:11:05 nyc33 solana-rpc.sh[9808]:   17: tokio::runtime::thread_pool::worker::run
Dec 28 15:11:05 nyc33 solana-rpc.sh[9808]:   18: tokio::loom::std::unsafe_cell::UnsafeCell<T>::with_mut
Dec 28 15:11:05 nyc33 solana-rpc.sh[9808]:   19: std::panicking::try
Dec 28 15:11:05 nyc33 solana-rpc.sh[9808]:   20: tokio::runtime::task::harness::Harness<T,S>::poll
Dec 28 15:11:05 nyc33 solana-rpc.sh[9808]:   21: tokio::runtime::blocking::pool::Inner::run
Dec 28 15:11:05 nyc33 solana-rpc.sh[9808]: note: Some details are omitted, run with `RUST_BACKTRACE=full` for a verbose backtrace.
Dec 28 15:11:05 nyc33 solana-rpc.sh[9808]: [2021-12-28T15:11:04.677089364Z ERROR solana_metrics::metrics] datapoint: panic program="validator" thread="tokio-runtime-worker" one=1i message="panicked at 'dead subscription encountered in SubscriptionControl', rpc/src/rpc_subscription_tracker.rs:203:22" location="rpc/src/rpc_subscription_tracker.rs:203:22"

System data

uname -a
Linux nyc33 5.4.0-89-generic #100-Ubuntu SMP Fri Sep 24 14:50:10 UTC 2021 x86_64 x86_64 x86_64 GNU/Linux

solana --version
solana-cli 1.8.11 (src:423a4d65; feat:2385070269)

cat /etc/*release*
DISTRIB_ID=Ubuntu
DISTRIB_RELEASE=20.04
DISTRIB_CODENAME=focal
DISTRIB_DESCRIPTION="Ubuntu 20.04.3 LTS"
Lusitaniae commented 2 years ago

Another one

Jan 02 06:55:51 sg51 solana-rpc.sh[35852]: [2022-01-02T06:55:51.550716742Z INFO  solana_metrics::metrics] datapoint: rpc_subscriptions source="bank" num_account_subscriptions=107i num_account_pubkeys_notified=0i num_logs_subscriptions=0i num_logs_notified=0i num_program_subscriptions=8i num_programs_notified=5i num_signature_subscriptions=0i num_signatures_notified=0i notifications_time=1392i
Jan 02 06:55:51 sg51 solana-rpc.sh[35852]: [2022-01-02T06:55:51.577194669Z INFO  solana_metrics::metrics] datapoint: bank-new_from_parent-heights slot_height=114429065i block_height=103210593i parent_slot_height=114429064i
Jan 02 06:55:51 sg51 solana-rpc.sh[35852]: [2022-01-02T06:55:51.578350830Z INFO  solana_metrics::metrics] datapoint: bank-timestamp get_timestamp_estimate_us=926i
Jan 02 06:55:51 sg51 solana-rpc.sh[35852]: [2022-01-02T06:55:51.578359105Z INFO  solana_metrics::metrics] datapoint: bank-timestamp-correction slot=114429065i from_genesis=1630140566i corrected=1641106551i ancestor_timestamp=1641106550i
Jan 02 06:55:51 sg51 solana-rpc.sh[35852]: [2022-01-02T06:55:51.589204976Z INFO  solana_metrics::metrics] datapoint: poh-service ticks=183i hashes=2302336i elapsed_us=351025i total_sleep_us=816941i total_tick_time_us=62i total_lock_time_us=1296i total_hash_time_us=163962i total_record_time_us=0i
Jan 02 06:55:51 sg51 solana-rpc.sh[35852]: [2022-01-02T06:55:51.602334735Z INFO  solana_metrics::metrics] datapoint: rpc_pubsub_total_subscriptions count=219i
Jan 02 06:55:51 sg51 solana-rpc.sh[35852]: [2022-01-02T06:55:51.602343401Z INFO  solana_metrics::metrics] datapoint: rpc_pubsub_total_subscriptions count=219i
Jan 02 06:55:51 sg51 solana-rpc.sh[35852]: [2022-01-02T06:55:51.602364481Z INFO  solana_metrics::metrics] datapoint: rpc_pubsub_total_subscriptions count=217i
Jan 02 06:55:51 sg51 solana-rpc.sh[35852]: [2022-01-02T06:55:51.602374810Z INFO  solana_metrics::metrics] datapoint: rpc_pubsub_total_subscriptions count=216i
Jan 02 06:55:51 sg51 solana-rpc.sh[35852]: [2022-01-02T06:55:51.602377365Z INFO  solana_metrics::metrics] datapoint: rpc_pubsub_total_subscriptions count=216i
Jan 02 06:55:51 sg51 solana-rpc.sh[35852]: thread 'tokio-runtime-worker' panicked at 'dead subscription encountered in SubscriptionControl', rpc/src/rpc_subscription_tracker.rs:203:22
Jan 02 06:55:51 sg51 solana-rpc.sh[35852]: stack backtrace:
Jan 02 06:55:51 sg51 solana-rpc.sh[35852]: [2022-01-02T06:55:51.603305978Z INFO  solana_metrics::metrics] datapoint: rpc_pubsub_total_subscriptions count=214i
Jan 02 06:55:51 sg51 solana-rpc.sh[35852]: [2022-01-02T06:55:51.603314344Z INFO  solana_metrics::metrics] datapoint: rpc_pubsub_total_subscriptions count=213i
Jan 02 06:55:51 sg51 solana-rpc.sh[35852]: [2022-01-02T06:55:51.603316949Z INFO  solana_metrics::metrics] datapoint: rpc_pubsub_total_subscriptions count=212i
Jan 02 06:55:51 sg51 solana-rpc.sh[35852]: [2022-01-02T06:55:51.603318973Z INFO  solana_metrics::metrics] datapoint: rpc_pubsub_total_subscriptions count=213i
Jan 02 06:55:51 sg51 solana-rpc.sh[35852]: [2022-01-02T06:55:51.603320736Z INFO  solana_metrics::metrics] datapoint: rpc_pubsub_total_subscriptions count=214i
Jan 02 06:55:51 sg51 solana-rpc.sh[35852]: [2022-01-02T06:55:51.603322359Z INFO  solana_metrics::metrics] datapoint: rpc-subscription total=117i
Jan 02 06:55:51 sg51 solana-rpc.sh[35852]: [2022-01-02T06:55:51.603324343Z INFO  solana_metrics::metrics] datapoint: rpc-subscription total=117i
Jan 02 06:55:51 sg51 solana-rpc.sh[35852]: [2022-01-02T06:55:51.603325926Z INFO  solana_metrics::metrics] datapoint: rpc_pubsub_total_subscriptions count=213i
Jan 02 06:55:51 sg51 solana-rpc.sh[35852]: [2022-01-02T06:55:51.611793211Z INFO  solana_metrics::metrics] datapoint: shred_insert_is_full total_time_ms=443i slot=114429065i last_index=1003i num_repaired=0i num_recovered=452i
Jan 02 06:55:51 sg51 solana-rpc.sh[35852]: [2022-01-02T06:55:51.633420913Z INFO  solana_metrics::metrics] datapoint: banking_stage-loop-stats id=1i process_packets_count=0i new_tx_count=0i dropped_packet_batches_count=0i dropped_packets_count=0i dropped_duplicated_packets_count=0i newly_buffered_packets_count=0i current_buffered_packet_batches_count=0i current_buffered_packets_count=0i rebuffered_packets_count=0i consumed_buffered_packets_count=0i cost_tracker_check_count=0i cost_forced_retry_transactions_count=0i consume_buffered_packets_elapsed=0i process_packets_elapsed=0i handle_retryable_packets_elapsed=0i filter_pending_packets_elapsed=0i packet_duplicate_check_elapsed=0i packet_conversion_elapsed=0i unprocessed_packet_conversion_elapsed=0i transaction_processing_elapsed=0i cost_tracker_update_elapsed=0i cost_tracker_clone_elapsed=0i cost_tracker_check_elapsed=0i
Jan 02 06:55:51 sg51 solana-rpc.sh[35852]:    0: rust_begin_unwind
Jan 02 06:55:51 sg51 solana-rpc.sh[35852]:              at /rustc/9bc8c42bb2f19e745a63f3445f1ac248fb015e53/library/std/src/panicking.rs:493:5
Jan 02 06:55:51 sg51 solana-rpc.sh[35852]:    1: core::panicking::panic_fmt
Jan 02 06:55:51 sg51 solana-rpc.sh[35852]:              at /rustc/9bc8c42bb2f19e745a63f3445f1ac248fb015e53/library/core/src/panicking.rs:92:14
Jan 02 06:55:51 sg51 solana-rpc.sh[35852]:    2: core::option::expect_failed
Jan 02 06:55:51 sg51 solana-rpc.sh[35852]:              at /rustc/9bc8c42bb2f19e745a63f3445f1ac248fb015e53/library/core/src/option.rs:1321:5
Jan 02 06:55:51 sg51 solana-rpc.sh[35852]:    3: solana_rpc::rpc_subscription_tracker::SubscriptionControl::subscribe
Jan 02 06:55:51 sg51 solana-rpc.sh[35852]:    4: solana_rpc::rpc_pubsub::RpcSolPubSubImpl::subscribe
Jan 02 06:55:51 sg51 solana-rpc.sh[35852]:    5: <solana_rpc::rpc_pubsub::RpcSolPubSubImpl as solana_rpc::rpc_pubsub::internal::rpc_impl_RpcSolPubSubInternal::gen_server::RpcSolPubSubInternal>::program_subscribe
Jan 02 06:55:51 sg51 solana-rpc.sh[35852]:    6: <jsonrpc_core::delegates::DelegateAsyncMethod<T,F> as jsonrpc_core::calls::RpcMethod<M>>::call
Jan 02 06:55:51 sg51 solana-rpc.sh[35852]:    7: jsonrpc_core::middleware::Middleware::on_call
Jan 02 06:55:51 sg51 solana-rpc.sh[35852]:    8: jsonrpc_core::io::IoHandler<M>::handle_request
Jan 02 06:55:51 sg51 solana-rpc.sh[35852]:    9: <core::future::from_generator::GenFuture<T> as core::future::future::Future>::poll
Jan 02 06:55:51 sg51 solana-rpc.sh[35852]:   10: <std::panic::AssertUnwindSafe<F> as core::ops::function::FnOnce<()>>::call_once
Jan 02 06:55:51 sg51 solana-rpc.sh[35852]:   11: tokio::runtime::task::harness::poll_future
Jan 02 06:55:51 sg51 solana-rpc.sh[35852]:   12: tokio::runtime::task::harness::Harness<T,S>::poll
Jan 02 06:55:51 sg51 solana-rpc.sh[35852]:   13: std::thread::local::LocalKey<T>::with
Jan 02 06:55:51 sg51 solana-rpc.sh[35852]:   14: tokio::runtime::thread_pool::worker::Context::run_task
Jan 02 06:55:51 sg51 solana-rpc.sh[35852]:   15: tokio::runtime::thread_pool::worker::Context::run
Jan 02 06:55:51 sg51 solana-rpc.sh[35852]:   16: tokio::macros::scoped_tls::ScopedKey<T>::set
Jan 02 06:55:51 sg51 solana-rpc.sh[35852]:   17: tokio::runtime::thread_pool::worker::run
Jan 02 06:55:51 sg51 solana-rpc.sh[35852]:   18: tokio::loom::std::unsafe_cell::UnsafeCell<T>::with_mut
Jan 02 06:55:51 sg51 solana-rpc.sh[35852]:   19: std::panicking::try
Jan 02 06:55:51 sg51 solana-rpc.sh[35852]:   20: tokio::runtime::task::harness::Harness<T,S>::poll
Jan 02 06:55:51 sg51 solana-rpc.sh[35852]:   21: tokio::runtime::blocking::pool::Inner::run
Jan 02 06:55:51 sg51 solana-rpc.sh[35852]: note: Some details are omitted, run with `RUST_BACKTRACE=full` for a verbose backtrace.
Jan 02 06:55:51 sg51 solana-rpc.sh[35852]: [2022-01-02T06:55:51.647720858Z ERROR solana_metrics::metrics] datapoint: panic program="validator" thread="tokio-runtime-worker" one=1i message="panicked at 'dead subscription encountered in SubscriptionControl', rpc/src/rpc_subscription_tracker.rs:203:22" location="rpc/src/rpc_subscription_tracker.rs:203:22"
Jan 02 06:55:51 sg51 solana-rpc.sh[35852]: [2022-01-02T06:55:51.648340511Z WARN  solana_metrics::metrics] max submission rate of 4000 datapoints per second exceeded.  only the
Jan 02 06:55:51 sg51 solana-rpc.sh[35852]:                         first 40000 of 42473 points will be submitted
Jan 02 06:55:51 sg51 solana-rpc.sh[35852]: [2022-01-02T06:55:51.648973219Z INFO  solana_metrics::metrics] submitting 40000 points
Jan 02 06:55:51 sg51 solana-rpc.sh[35852]: [2022-01-02T06:55:51.816688792Z INFO  solana_metrics::metrics] datapoint: receive_window_stats num_packets=13669i num_shreds=8027i num_repairs=48i elapsed_micros=202067i
Jan 02 06:55:51 sg51 solana-rpc.sh[35852]: [2022-01-02T06:55:51.816703801Z INFO  solana_metrics::metrics] datapoint: receive_window_num_slot_shreds slot=114429062i num_shreds=1253i
Jan 02 06:55:51 sg51 solana-rpc.sh[35852]: [2022-01-02T06:55:51.816706105Z INFO  solana_metrics::metrics] datapoint: receive_window_num_slot_shreds slot=114429061i num_shreds=342i
Jan 02 06:55:51 sg51 solana-rpc.sh[35852]: [2022-01-02T06:55:51.816713248Z INFO  solana_metrics::metrics] datapoint: receive_window_num_slot_shreds slot=114429064i num_shreds=2417i
Jan 02 06:55:51 sg51 solana-rpc.sh[35852]: [2022-01-02T06:55:51.816715082Z INFO  solana_metrics::metrics] datapoint: receive_window_num_slot_shreds slot=114429063i num_shreds=1990i
Jan 02 06:55:51 sg51 solana-rpc.sh[35852]: [2022-01-02T06:55:51.816716735Z INFO  solana_metrics::metrics] datapoint: receive_window_num_slot_shreds slot=114429065i num_shreds=2021i
Jan 02 06:55:51 sg51 solana-rpc.sh[35852]: [2022-01-02T06:55:51.816718067Z INFO  solana_metrics::metrics] datapoint: receive_window_num_slot_shreds slot=114429060i num_shreds=4i
Jan 02 06:55:51 sg51 solana-rpc.sh[35852]: [2022-01-02T06:55:51.816779973Z INFO  solana_core::window_service] num addresses: 0, top packets by source: [(54.155.170.210:8007, 54), (52.210.8.106:8007, 49), (35.73.132.20:8007, 49), (54.150.88.59:8007, 48), (5.83.175.225:8006, 47)]
Jan 02 06:55:51 sg51 solana-rpc.sh[35852]: [2022-01-02T06:55:51.817875140Z INFO  solana_metrics::metrics] datapoint: retransmit-first-shred slot=114429066i
Jan 02 06:55:51 sg51 solana-rpc.sh[35852]: [2022-01-02T06:55:51.843774460Z INFO  solana_metrics::counter] COUNTER:{"name": "bank-process_transactions", "counts": 442101947, "samples": 129077000,  "now": 1641106551843, "events": 1}
Jan 02 06:55:51 sg51 solana-rpc.sh[35852]: [2022-01-02T06:55:51.877883874Z INFO  solana_metrics::counter] COUNTER:{"name": "vote-native", "counts": 326652001, "samples": 326652000,  "now": 1641106551877, "events": 1}
Lusitaniae commented 2 years ago 
Jan 03 16:36:09 ams12 solana-rpc.sh[2675]: [2022-01-03T16:36:09.907117286Z INFO  solana_metrics::metrics] datapoint: rpc_pubsub_connections count=464i
Jan 03 16:36:09 ams12 solana-rpc.sh[2675]: [2022-01-03T16:36:09.908939048Z INFO  solana_metrics::metrics] datapoint: rpc_pubsub_total_subscriptions count=2142i
Jan 03 16:36:09 ams12 solana-rpc.sh[2675]: [2022-01-03T16:36:09.908960548Z INFO  solana_metrics::metrics] datapoint: rpc_pubsub_total_subscriptions count=2143i
Jan 03 16:36:09 ams12 solana-rpc.sh[2675]: [2022-01-03T16:36:09.908975667Z INFO  solana_metrics::metrics] datapoint: rpc-subscription total=1622i
Jan 03 16:36:09 ams12 solana-rpc.sh[2675]: [2022-01-03T16:36:09.908980246Z INFO  solana_metrics::metrics] datapoint: rpc_pubsub_total_subscriptions count=2144i
Jan 03 16:36:09 ams12 solana-rpc.sh[2675]: [2022-01-03T16:36:09.908983672Z INFO  solana_metrics::metrics] datapoint: rpc_pubsub_total_subscriptions count=2142i
Jan 03 16:36:09 ams12 solana-rpc.sh[2675]: [2022-01-03T16:36:09.908987840Z INFO  solana_metrics::metrics] datapoint: rpc_pubsub_total_subscriptions count=2142i
Jan 03 16:36:09 ams12 solana-rpc.sh[2675]: [2022-01-03T16:36:09.908991026Z INFO  solana_metrics::metrics] datapoint: rpc_pubsub_total_subscriptions count=2141i
Jan 03 16:36:09 ams12 solana-rpc.sh[2675]: [2022-01-03T16:36:09.908993631Z INFO  solana_metrics::metrics] datapoint: rpc-subscription total=1623i
Jan 03 16:36:09 ams12 solana-rpc.sh[2675]: [2022-01-03T16:36:09.908997108Z INFO  solana_metrics::metrics] datapoint: rpc-subscription total=1622i
Jan 03 16:36:09 ams12 solana-rpc.sh[2675]: [2022-01-03T16:36:09.909000354Z INFO  solana_metrics::metrics] datapoint: rpc_pubsub_total_subscriptions count=2140i
Jan 03 16:36:09 ams12 solana-rpc.sh[2675]: thread 'tokio-runtime-worker' panicked at 'dead subscription encountered in SubscriptionControl', rpc/src/rpc_subscription_tracker.rs:203:22
Jan 03 16:36:09 ams12 solana-rpc.sh[2675]: stack backtrace:
Jan 03 16:36:09 ams12 solana-rpc.sh[2675]: [2022-01-03T16:36:09.931613644Z INFO  solana_metrics::metrics] datapoint: rpc_pubsub_connections count=465i
Jan 03 16:36:09 ams12 solana-rpc.sh[2675]:    0: rust_begin_unwind
Jan 03 16:36:09 ams12 solana-rpc.sh[2675]:              at /rustc/9bc8c42bb2f19e745a63f3445f1ac248fb015e53/library/std/src/panicking.rs:493:5
Jan 03 16:36:09 ams12 solana-rpc.sh[2675]:    1: core::panicking::panic_fmt
Jan 03 16:36:09 ams12 solana-rpc.sh[2675]:              at /rustc/9bc8c42bb2f19e745a63f3445f1ac248fb015e53/library/core/src/panicking.rs:92:14
Jan 03 16:36:09 ams12 solana-rpc.sh[2675]:    2: core::option::expect_failed
Jan 03 16:36:09 ams12 solana-rpc.sh[2675]:              at /rustc/9bc8c42bb2f19e745a63f3445f1ac248fb015e53/library/core/src/option.rs:1321:5
Jan 03 16:36:09 ams12 solana-rpc.sh[2675]:    3: solana_rpc::rpc_subscription_tracker::SubscriptionControl::subscribe
Jan 03 16:36:09 ams12 solana-rpc.sh[2675]:    4: solana_rpc::rpc_pubsub::RpcSolPubSubImpl::subscribe
Jan 03 16:36:09 ams12 solana-rpc.sh[2675]:    5: <solana_rpc::rpc_pubsub::RpcSolPubSubImpl as solana_rpc::rpc_pubsub::internal::rpc_impl_RpcSolPubSubInternal::gen_server::RpcSolPubSubInternal>::account_subscribe
Jan 03 16:36:09 ams12 solana-rpc.sh[2675]:    6: <jsonrpc_core::delegates::DelegateAsyncMethod<T,F> as jsonrpc_core::calls::RpcMethod<M>>::call
Jan 03 16:36:09 ams12 solana-rpc.sh[2675]:    7: jsonrpc_core::middleware::Middleware::on_call
Jan 03 16:36:09 ams12 solana-rpc.sh[2675]:    8: <core::iter::adapters::map::Map<I,F> as core::iter::traits::iterator::Iterator>::fold
Jan 03 16:36:09 ams12 solana-rpc.sh[2675]:    9: alloc::vec::source_iter_marker::<impl alloc::vec::spec_from_iter::SpecFromIter<T,I> for alloc::vec::Vec<T>>::from_iter
Jan 03 16:36:09 ams12 solana-rpc.sh[2675]:   10: jsonrpc_core::io::IoHandler<M>::handle_request
Jan 03 16:36:09 ams12 solana-rpc.sh[2675]:   11: <core::future::from_generator::GenFuture<T> as core::future::future::Future>::poll
Jan 03 16:36:09 ams12 solana-rpc.sh[2675]:   12: <std::panic::AssertUnwindSafe<F> as core::ops::function::FnOnce<()>>::call_once
Jan 03 16:36:09 ams12 solana-rpc.sh[2675]:   13: tokio::runtime::task::harness::poll_future
Jan 03 16:36:09 ams12 solana-rpc.sh[2675]:   14: tokio::runtime::task::harness::Harness<T,S>::poll
Jan 03 16:36:09 ams12 solana-rpc.sh[2675]:   15: std::thread::local::LocalKey<T>::with
Jan 03 16:36:09 ams12 solana-rpc.sh[2675]:   16: tokio::runtime::thread_pool::worker::Context::run_task
Jan 03 16:36:09 ams12 solana-rpc.sh[2675]:   17: tokio::runtime::thread_pool::worker::Context::run
Jan 03 16:36:09 ams12 solana-rpc.sh[2675]:   18: tokio::macros::scoped_tls::ScopedKey<T>::set
Jan 03 16:36:09 ams12 solana-rpc.sh[2675]:   19: tokio::runtime::thread_pool::worker::run
Jan 03 16:36:09 ams12 solana-rpc.sh[2675]:   20: tokio::loom::std::unsafe_cell::UnsafeCell<T>::with_mut
Jan 03 16:36:09 ams12 solana-rpc.sh[2675]:   21: std::panicking::try
Jan 03 16:36:09 ams12 solana-rpc.sh[2675]:   22: tokio::runtime::task::harness::Harness<T,S>::poll
Jan 03 16:36:09 ams12 solana-rpc.sh[2675]:   23: tokio::runtime::blocking::pool::Inner::run
Jan 03 16:36:09 ams12 solana-rpc.sh[2675]: note: Some details are omitted, run with `RUST_BACKTRACE=full` for a verbose backtrace.
Jan 03 16:36:09 ams12 solana-rpc.sh[2675]: [2022-01-03T16:36:09.975317588Z ERROR solana_metrics::metrics] datapoint: panic program="validator" thread="tokio-runtime-worker" one=1i message="panicked at 'dead subscription encountered in SubscriptionControl', rpc/src/rpc_subscription_tracker.rs:203:22" location="rpc/src/rpc_subscription_tracker.rs:203:22"
Jan 03 16:36:09 ams12 solana-rpc.sh[2675]: [2022-01-03T16:36:09.975557252Z INFO  solana_metrics::metrics] submitting 2685 points
Jan 03 16:36:10 ams12 solana-rpc.sh[2675]: [2022-01-03T16:36:10.047879205Z INFO  solana_metrics::metrics] datapoint: banking_stage-loop-stats id=1i process_packets_count=0i new_tx_count=0i dropped_packet_batches_count=0i dropped_packets_count=0i dropped_duplicated_packets_count=0i newly_buffered_packets_count=0i current_buffered_packet_batches_count=0i current_buffered_packets_count=0i rebuffered_packets_count=0i consumed_buffered_packets_count=0i cost_tracker_check_count=0i cost_forced_retry_transactions_count=0i consume_buffered_packets_elapsed=0i process_packets_elapsed=0i handle_retryable_packets_elapsed=0i filter_pending_packets_elapsed=0i packet_duplicate_check_elapsed=0i packet_conversion_elapsed=0i unprocessed_packet_conversion_elapsed=0i transaction_processing_elapsed=0i cost_tracker_update_elapsed=0i cost_tracker_clone_elapsed=0i cost_tracker_check_elapsed=0i
Jan 03 16:36:10 ams12 solana-rpc.sh[2675]: [2022-01-03T16:36:10.047895766Z INFO  solana_metrics::metrics] datapoint: shred_fetch index_overrun=0i shred_count=7i slot_bad_deserialize=0i index_bad_deserialize=0i index_out_of_bounds=0i slot_out_of_range=0i duplicate_shred=0i
Jan 03 16:36:10 ams12 solana-rpc.sh[2675]: [2022-01-03T16:36:10.047945981Z INFO  solana_metrics::metrics] datapoint: shred_fetch_tvu_forwards index_overrun=0i shred_count=2611i slot_bad_deserialize=0i index_bad_deserialize=0i index_out_of_bounds=0i slot_out_of_range=0i duplicate_shred=1029i
Jan 03 16:36:22 ams12 systemd[1946]: solana-rpc.service: Main process exited, code=exited, status=1/FAILURE
Jan 03 16:36:22 ams12 systemd[1946]: solana-rpc.service: Failed with result 'exit-code'.
t-nelson commented 2 years ago

We have enough stack traces and logs for this issue. Thanks!

github-actions[bot] commented 2 years ago

This issue has been automatically locked since there has not been any activity in past 7 days after it was closed. Please open a new issue for related bugs.