search

clockwork-xyz / clockwork

Smart-contract automation on Solana.
https://clockwork.xyz
GNU Affero General Public License v3.0
271 stars 76 forks source link

Geyser plugin crashes validator when running clockwork localnet #125

Closed mcintyre94 closed 1 year ago

mcintyre94 commented 1 year ago

I first mentioned this on Discord, but figured it's worth opening an issue too with the logs etc

Clockwork version: v1.4.0 (15896115a65fdc02605495f31869cbe39f2b2f69) Solana version: solana-cli 1.13.5 (src:91384943; feat:1365939126)

When I run clockwork localnet after building (following instructions in readme), it exits after ~20 seconds with an error status code before processing anything:

$ clockwork localnet
Config File: /Users/callum/.config/solana/cli/config.yml
RPC URL: http://localhost:8899
WebSocket URL: ws://localhost:8900/ (computed)
Keypair Path: /Users/callum/.config/solana/id.json
Commitment: confirmed
Starting test validator
Ledger location: test-ledger
Log: test-ledger/validator.log

$ echo $?
1

The last message in test-ledger/validator.log shows a stack trace:

[2023-01-10T11:31:18.607799000Z INFO  solana_ledger::builtins] BPF JIT is not supported on this target
thread '<unnamed>' panicked at 'Slice must be the same length as a Pubkey: TryFromSliceError(())', /Users/callum/.cargo/registry/src/github.com-1ecc6299db9ec823/solana-program-1.13.5/src/pubkey.rs:135:18
stack backtrace:
   0: rust_begin_unwind
             at /rustc/88c58e3c2c097ebffac425d9e080dcb1aadf790e/library/std/src/panicking.rs:575:5
   1: core::panicking::panic_fmt
             at /rustc/88c58e3c2c097ebffac425d9e080dcb1aadf790e/library/core/src/panicking.rs:64:14
   2: core::result::unwrap_failed
             at /rustc/88c58e3c2c097ebffac425d9e080dcb1aadf790e/library/core/src/result.rs:1790:5
   3: solana_program::pubkey::Pubkey::new
   4: <clockwork_plugin::events::AccountUpdateEvent as core::convert::TryFrom<solana_geyser_plugin_interface::geyser_plugin_interface::ReplicaAccountInfo>>::try_from
   5: <clockwork_plugin::plugin::ClockworkPlugin as solana_geyser_plugin_interface::geyser_plugin_interface::GeyserPlugin>::update_account
   6: solana_geyser_plugin_manager::accounts_update_notifier::AccountsUpdateNotifierImpl::notify_plugins_of_account_update
   7: <solana_geyser_plugin_manager::accounts_update_notifier::AccountsUpdateNotifierImpl as solana_runtime::accounts_update_notifier_interface::AccountsUpdateNotifierInterface>::notify_account_update
   8: solana_runtime::accounts_db::geyser_plugin_utils::<impl solana_runtime::accounts_db::AccountsDb>::notify_account_at_accounts_update
   9: <core::iter::adapters::map::Map<I,F> as core::iter::traits::iterator::Iterator>::fold
  10: solana_runtime::accounts_db::AccountsDb::store
  11: solana_runtime::bank::Bank::new_with_paths
  12: solana_ledger::blockstore_processor::process_blockstore_for_bank_0
  13: solana_ledger::bank_forks_utils::load_bank_forks
  14: solana_core::validator::Validator::new
  15: solana_test_validator::TestValidator::start
  16: solana_test_validator::TestValidatorGenesis::start_with_mint_address
  17: solana_test_validator::main
note: Some details are omitted, run with `RUST_BACKTRACE=full` for a verbose backtrace.

If I manually run the validator as clockwork localnet is but without the geyser plugin it works correctly:

$ solana-test-validator -r --bpf-program F8dKseqmBoAkHx3c58Lmb9TgJv5qeTf3BbtZZSEzYvUa lib/clockwork_network_program.so --bpf-program 3XXuUFfweXBwFgFfYaejLvZE4cGZiHgKiGfMtdxNzYmv lib/clockwork_thread_program.so --bpf-program E7p5KFo8kKCDm6BUnWtnVFkQSYh6ZA6xaGAuvpv8NXTa lib/clockwork_webhook_program.so
Ledger location: test-ledger
Log: test-ledger/validator.log
⠴ Initializing...
⠤ Initializing...
Identity: 3R4L3cb1nUA5W6q1NMMGmL41Rjaioo2W9DV81VDcxWcE
Genesis Hash: C1q1DsGjifQpvM5UEWMp1EF1y4cuZEKhHcrRc2miHBY6
Version: 1.13.5
Shred Version: 13145
Gossip Address: 127.0.0.1:1024
TPU Address: 127.0.0.1:1027
JSON RPC URL: http://127.0.0.1:8899
⠋ 00:01:15 | Processed Slot: 156 | Confirmed Slot: 156 | Finalized Slot: 124 | Full Snapshot Slot: 100 | Incremental Snapshot Slot: - | Transaction

If I do the same but add the plugin back I get the validator's error:

$ solana-test-validator -r --bpf-program F8dKseqmBoAkHx3c58Lmb9TgJv5qeTf3BbtZZSEzYvUa lib/clockwork_network_program.so --bpf-program 3XXuUFfweXBwFgFfYaejLvZE4cGZiHgKiGfMtdxNzYmv lib/clockwork_thread_program.so --bpf-program E7p5KFo8kKCDm6BUnWtnVFkQSYh6ZA6xaGAuvpv8NXTa lib/clockwork_webhook_program.so  --geyser-plugin-config lib/geyser-plugin-config.json
Ledger location: test-ledger
Log: test-ledger/validator.log
[1]    48215 bus error  solana-test-validator -r --bpf-program  lib/clockwork_network_program.so

$ echo $?
138

As expected the validator.log stack trace is the same

Full validator.log with RUST_BACKTRACE=full ``` [2023-01-10T11:32:33.621798000Z INFO solana_test_validator] solana-validator 1.13.5 (src:91384943; feat:1365939126) [2023-01-10T11:32:33.621850000Z INFO solana_test_validator] Starting validator with: ArgsOs { inner: [ "solana-test-validator", "-r", "--bpf-program", "F8dKseqmBoAkHx3c58Lmb9TgJv5qeTf3BbtZZSEzYvUa", "/Users/callum/projects/clockwork/lib/clockwork_network_program.so", "--bpf-program", "3XXuUFfweXBwFgFfYaejLvZE4cGZiHgKiGfMtdxNzYmv", "/Users/callum/projects/clockwork/lib/clockwork_thread_program.so", "--bpf-program", "E7p5KFo8kKCDm6BUnWtnVFkQSYh6ZA6xaGAuvpv8NXTa", "/Users/callum/projects/clockwork/lib/clockwork_webhook_program.so", "--geyser-plugin-config", "/Users/callum/projects/clockwork/lib/geyser-plugin-config.json", ], } [2023-01-10T11:32:33.621899000Z WARN solana_perf] CUDA is disabled [2023-01-10T11:32:33.624742000Z INFO solana_faucet::faucet] Faucet started. Listening on: 0.0.0.0:9900 [2023-01-10T11:32:33.624760000Z INFO solana_faucet::faucet] Faucet account address: 2yzCmECE9P8DcjPPto9hTRKxejcuYMdj4J9ARjKjN4Y5 [2023-01-10T11:32:33.627698000Z INFO solana_ledger::blockstore] Maximum open file descriptors: 500000 [2023-01-10T11:32:33.627712000Z INFO solana_ledger::blockstore] Opening database at "test-ledger/rocksdb" [2023-01-10T11:32:33.748470000Z INFO solana_ledger::blockstore] "test-ledger/rocksdb" open took 120ms [2023-01-10T11:32:33.757125000Z INFO solana_metrics::metrics] metrics disabled: SOLANA_METRICS_CONFIG: environment variable not found [2023-01-10T11:32:33.757159000Z INFO solana_metrics::metrics] datapoint: shred_insert_is_full total_time_ms=0i slot=0i last_index=2i num_repaired=0i num_recovered=0i [2023-01-10T11:32:33.868014000Z INFO solana_runtime::hardened_unpack] Extracting "test-ledger/genesis.tar.bz2"... [2023-01-10T11:32:33.906467000Z INFO solana_runtime::hardened_unpack] unpacked 1 entries total [2023-01-10T11:32:33.906477000Z INFO solana_runtime::hardened_unpack] Extracted "test-ledger/genesis.tar.bz2" in 38.447291ms [2023-01-10T11:32:33.907186000Z WARN solana_core::validator] identity: DkQDKq2zcXQThGCqnFgtNvbDCkC2qrPadU4UKeg2y1Tc [2023-01-10T11:32:33.907195000Z WARN solana_core::validator] vote account: BQ4wUamgv575pGSqx65QUB6XfjiveTekHN9qKY8dHEKm [2023-01-10T11:32:33.907209000Z INFO solana_geyser_plugin_manager::geyser_plugin_service] Starting GeyserPluginService from config files: ["/Users/callum/projects/clockwork/lib/geyser-plugin-config.json"] [2023-01-10T11:32:33.908505000Z INFO clockwork_plugin::plugin] clockwork-plugin crate-info - spec: https://github.com/clockwork-xyz/clockwork/tree/15896115a65fdc02605495f31869cbe39f2b2f69, geyser_interface_version: ~1.13.5 [2023-01-10T11:32:33.908517000Z INFO clockwork_plugin::plugin] Loading snapshot... [2023-01-10T11:32:33.909013000Z INFO solana_geyser_plugin_manager::geyser_plugin_service] Started GeyserPluginService [2023-01-10T11:32:33.909021000Z WARN solana_core::validator] authorized voter: BQ4wUamgv575pGSqx65QUB6XfjiveTekHN9qKY8dHEKm [2023-01-10T11:32:33.909033000Z INFO solana_core::validator] Initializing sigverify... [2023-01-10T11:32:33.909059000Z INFO solana_core::validator] Done. [2023-01-10T11:32:33.909066000Z INFO solana_core::validator] Cleaning accounts paths.. [2023-01-10T11:32:33.909075000Z WARN solana_core::validator] encountered error removing accounts path: "test-ledger/accounts": No such file or directory (os error 2) [2023-01-10T11:32:33.909080000Z INFO solana_core::validator] done. clean_accounts_paths took 11us [2023-01-10T11:32:33.909089000Z INFO solana_core::validator] Geyser plugin: accounts_update_notifier: true transaction_notifier: false [2023-01-10T11:32:33.909094000Z INFO solana_core::system_monitor_service] Starting SystemMonitorService [2023-01-10T11:32:33.909111000Z INFO solana_core::validator] loading ledger from "test-ledger"... [2023-01-10T11:32:33.916778000Z INFO solana_core::validator] genesis hash: 6w7eY8bqvQ39gzvBRtdi2kWK9SaYqeChEhAwtRFCk5n3 [2023-01-10T11:32:33.916793000Z INFO solana_ledger::blockstore] Maximum open file descriptors: 500000 [2023-01-10T11:32:33.916796000Z INFO solana_ledger::blockstore] Opening database at "test-ledger/rocksdb" [2023-01-10T11:32:33.994772000Z INFO solana_ledger::blockstore] "test-ledger/rocksdb" open took 77ms [2023-01-10T11:32:33.995191000Z INFO solana_ledger::bank_forks_utils] Initializing bank snapshot path: test-ledger/snapshot [2023-01-10T11:32:33.995381000Z INFO solana_ledger::bank_forks_utils] No snapshot package available; will load from genesis [2023-01-10T11:32:33.995385000Z INFO solana_ledger::bank_forks_utils] Processing ledger from genesis [2023-01-10T11:32:33.995388000Z INFO solana_ledger::builtins] BPF JIT is not supported on this target thread '' panicked at 'Slice must be the same length as a Pubkey: TryFromSliceError(())', /Users/callum/.cargo/registry/src/github.com-1ecc6299db9ec823/solana-program-1.13.5/src/pubkey.rs:135:18 stack backtrace: 0: 0x106aadc6c - std::backtrace_rs::backtrace::libunwind::trace::h21c842e9f9e3ed61 at /rustc/88c58e3c2c097ebffac425d9e080dcb1aadf790e/library/std/src/../../backtrace/src/backtrace/libunwind.rs:93:5 1: 0x106aadc6c - std::backtrace_rs::backtrace::trace_unsynchronized::h0234a12fe65873d7 at /rustc/88c58e3c2c097ebffac425d9e080dcb1aadf790e/library/std/src/../../backtrace/src/backtrace/mod.rs:66:5 2: 0x106aadc6c - std::sys_common::backtrace::_print_fmt::h604b08b7b51a8c6f at /rustc/88c58e3c2c097ebffac425d9e080dcb1aadf790e/library/std/src/sys_common/backtrace.rs:65:5 3: 0x106aadc6c - ::fmt::h0041893033240978 at /rustc/88c58e3c2c097ebffac425d9e080dcb1aadf790e/library/std/src/sys_common/backtrace.rs:44:22 4: 0x106ac6bcc - core::fmt::write::h7aa346422ea067d1 at /rustc/88c58e3c2c097ebffac425d9e080dcb1aadf790e/library/core/src/fmt/mod.rs:1208:17 5: 0x106aa8ad4 - std::io::Write::write_fmt::hf58e6f129ffddfc2 at /rustc/88c58e3c2c097ebffac425d9e080dcb1aadf790e/library/std/src/io/mod.rs:1682:15 6: 0x106aada80 - std::sys_common::backtrace::_print::h67522c79d1b321e0 at /rustc/88c58e3c2c097ebffac425d9e080dcb1aadf790e/library/std/src/sys_common/backtrace.rs:47:5 7: 0x106aada80 - std::sys_common::backtrace::print::had46fedbaa62f4ea at /rustc/88c58e3c2c097ebffac425d9e080dcb1aadf790e/library/std/src/sys_common/backtrace.rs:34:9 8: 0x106aaf5e0 - std::panicking::default_hook::{{closure}}::he2642b37400ed232 at /rustc/88c58e3c2c097ebffac425d9e080dcb1aadf790e/library/std/src/panicking.rs:267:22 9: 0x106aaf338 - std::panicking::default_hook::hee81a462c6f8b703 at /rustc/88c58e3c2c097ebffac425d9e080dcb1aadf790e/library/std/src/panicking.rs:286:9 10: 0x106aafc2c - as core::ops::function::Fn>::call::h58b5b19d502927da at /rustc/88c58e3c2c097ebffac425d9e080dcb1aadf790e/library/alloc/src/boxed.rs:2032:9 11: 0x106aafc2c - std::panicking::rust_panic_with_hook::h1d92aa7d061156c0 at /rustc/88c58e3c2c097ebffac425d9e080dcb1aadf790e/library/std/src/panicking.rs:692:13 12: 0x106aafa24 - std::panicking::begin_panic_handler::{{closure}}::hccbd7fc95f5c3c7f at /rustc/88c58e3c2c097ebffac425d9e080dcb1aadf790e/library/std/src/panicking.rs:579:13 13: 0x106aae0d4 - std::sys_common::backtrace::__rust_end_short_backtrace::h9f1515e1456dbd78 at /rustc/88c58e3c2c097ebffac425d9e080dcb1aadf790e/library/std/src/sys_common/backtrace.rs:137:18 14: 0x106aaf780 - rust_begin_unwind at /rustc/88c58e3c2c097ebffac425d9e080dcb1aadf790e/library/std/src/panicking.rs:575:5 15: 0x106af17bc - core::panicking::panic_fmt::h376e72616eca036a at /rustc/88c58e3c2c097ebffac425d9e080dcb1aadf790e/library/core/src/panicking.rs:64:14 16: 0x106af1adc - core::result::unwrap_failed::h0dbe5eb66391852a at /rustc/88c58e3c2c097ebffac425d9e080dcb1aadf790e/library/core/src/result.rs:1790:5 17: 0x106a7e694 - solana_program::pubkey::Pubkey::new::h6b8c7ef0fe5037f4 18: 0x10658d95c - >::try_from::h18c086fbcd26a719 19: 0x1065660c0 - ::update_account::h1955928745632fcf 20: 0x102cdc790 - solana_geyser_plugin_manager::accounts_update_notifier::AccountsUpdateNotifierImpl::notify_plugins_of_account_update::h2d71afd93f9c885a 21: 0x102cdc0b8 - ::notify_account_update::h563461c4bac01fc5 22: 0x10389c390 - solana_runtime::accounts_db::geyser_plugin_utils::::notify_account_at_accounts_update::h7857c66ca7eddfb8 23: 0x10379a54c - as core::iter::traits::iterator::Iterator>::fold::h8a2da6a40d049ead 24: 0x1038b49bc - solana_runtime::accounts_db::AccountsDb::store::h55b46062af18735a 25: 0x1037a61b4 - solana_runtime::bank::Bank::new_with_paths::he59a5645600b2b35 26: 0x1031c1950 - solana_ledger::blockstore_processor::process_blockstore_for_bank_0::h6de3c28b37ce3dbd 27: 0x103198a54 - solana_ledger::bank_forks_utils::load_bank_forks::h76c8e65dc309f110 28: 0x102b8c9d4 - solana_core::validator::Validator::new::hef033114d4fe4c96 29: 0x1029cc08c - solana_test_validator::TestValidator::start::h8f1e84c2c72e725a 30: 0x1029c9e34 - solana_test_validator::TestValidatorGenesis::start_with_mint_address::hbd483eb30d3a1279 31: 0x102920928 - solana_test_validator::main::h133a53868e5c5e0f 32: 0x1028f7a58 - std::sys_common::backtrace::__rust_begin_short_backtrace::hcc0d466728a281e8 33: 0x102917fd4 - std::rt::lang_start::{{closure}}::h10ef7b42763b06d5 34: 0x1040446f0 - std::rt::lang_start_internal::h0c28bd035905a2f7 35: 0x102922cf0 - _main ```
nickgarfield commented 1 year ago

Hey @mcintyre94, thanks for flagging this. Are you running on MacOS by chance?

mcintyre94 commented 1 year ago

@nickgarfield Yep, it's MacOS on M1 too if that makes a difference!

mwrites commented 1 year ago

@mcintyre94 could you try cd into the repo and

rm -rf lib/*.dylib rm -rf lib/*.so ./scripts/build-all.sh . clockwork localnet

See if it helps?

mcintyre94 commented 1 year ago

@mwrites Thanks, but unfortunately that doesn't seem to have made any difference. clockwork localnet and solana-test-validator <snip> --geyser-plugin-config lib/geyser-plugin-config.json both behaved the same after that as they did in the initial issue

mcintyre94 commented 1 year ago

I've had another look at this on the latest versions, still seems to be an issue but the errors are a bit different

1.4.4 validator.log ``` [2023-02-21T16:07:25.390389000Z INFO  solana_test_validator] solana-validator 1.14.16 (src:0fb2ffda; feat:3488713414) [2023-02-21T16:07:25.390425000Z INFO  solana_test_validator] Starting validator with: ArgsOs { inner: [ "solana-test-validator", "-r", "--bpf-program", "F8dKseqmBoAkHx3c58Lmb9TgJv5qeTf3BbtZZSEzYvUa", "/Users/callum/projects/clockwork/lib/clockwork_network_program.so", "--bpf-program", "3XXuUFfweXBwFgFfYaejLvZE4cGZiHgKiGfMtdxNzYmv", "/Users/callum/projects/clockwork/lib/clockwork_thread_program.so", "--bpf-program", "E7p5KFo8kKCDm6BUnWtnVFkQSYh6ZA6xaGAuvpv8NXTa", "/Users/callum/projects/clockwork/lib/clockwork_webhook_program.so", "--geyser-plugin-config", "/Users/callum/projects/clockwork/lib/geyser-plugin-config.json", ], } [2023-02-21T16:07:25.390469000Z WARN  solana_perf] CUDA is disabled [2023-02-21T16:07:25.394236000Z INFO  solana_faucet::faucet] Faucet started. Listening on: 0.0.0.0:9900 [2023-02-21T16:07:25.394265000Z INFO  solana_faucet::faucet] Faucet account address: 4NsCZ7rsB3Fpb2eCkZydfqpqg1dLaqsufookvSy6tWr4 [2023-02-21T16:07:25.398759000Z INFO  solana_ledger::blockstore] Maximum open file descriptors: 1000000 [2023-02-21T16:07:25.398776000Z INFO  solana_ledger::blockstore] Opening database at "test-ledger/rocksdb" [2023-02-21T16:07:25.507087000Z INFO  solana_ledger::blockstore] "test-ledger/rocksdb" open took 108ms [2023-02-21T16:07:25.515234000Z INFO  solana_metrics::metrics] metrics disabled: SOLANA_METRICS_CONFIG: environment variable not found [2023-02-21T16:07:25.515286000Z INFO  solana_metrics::metrics] datapoint: shred_insert_is_full total_time_ms=0i slot=0i last_index=3i num_repaired=0i num_recovered=0i [2023-02-21T16:07:25.629348000Z INFO  solana_runtime::hardened_unpack] Extracting "test-ledger/genesis.tar.bz2"... [2023-02-21T16:07:25.670123000Z INFO  solana_runtime::hardened_unpack] unpacked 1 entries total [2023-02-21T16:07:25.670132000Z INFO  solana_runtime::hardened_unpack] Extracted "test-ledger/genesis.tar.bz2" in 40.76875ms [2023-02-21T16:07:25.670981000Z WARN  solana_core::validator] identity: 2QMte5Fb6bpEjPqy8nt75MUqZR6oJXsAz6LEt5TnQyyf [2023-02-21T16:07:25.670990000Z WARN  solana_core::validator] vote account: FUFVRcPqZTRJNXNvLQ8E72xxaqWeYbH8BSEJnER6zjqt [2023-02-21T16:07:25.671002000Z INFO  solana_geyser_plugin_manager::geyser_plugin_service] Starting GeyserPluginService from config files: ["/Users/callum/projects/clockwork/lib/geyser-plugin-config.json"] [2023-02-21T16:07:25.672382000Z INFO clockwork_plugin::plugin] clockwork-plugin crate-info - spec: https://github.com/clockwork-xyz/clockwork/tree/91aedc77d156601c73f8a3f27aab72e211a1e8e1, geyser_interface_version: ~1.14.12 [2023-02-21T16:07:25.672394000Z INFO clockwork_plugin::plugin] Loading snapshot... [2023-02-21T16:07:25.673362000Z INFO  solana_geyser_plugin_manager::geyser_plugin_service] Started GeyserPluginService [2023-02-21T16:07:25.673374000Z WARN  solana_core::validator] authorized voter: FUFVRcPqZTRJNXNvLQ8E72xxaqWeYbH8BSEJnER6zjqt [2023-02-21T16:07:25.673477000Z INFO  solana_core::validator] Initializing sigverify... [2023-02-21T16:07:25.673494000Z INFO  solana_core::validator] Done. [2023-02-21T16:07:25.673499000Z INFO  solana_core::validator] Cleaning accounts paths.. [2023-02-21T16:07:25.673512000Z WARN  solana_core::validator] encountered error removing accounts path: "test-ledger/accounts": No such file or directory (os error 2) [2023-02-21T16:07:25.673521000Z INFO  solana_core::validator] done. clean_accounts_paths took 12us [2023-02-21T16:07:25.673525000Z INFO  solana_core::validator] Geyser plugin: accounts_update_notifier: true transaction_notifier: false [2023-02-21T16:07:25.673529000Z INFO  solana_core::system_monitor_service] Starting SystemMonitorService [2023-02-21T16:07:25.673554000Z INFO  solana_core::validator] loading ledger from "test-ledger"... [2023-02-21T16:07:25.681513000Z INFO  solana_core::validator] genesis hash: J9mpb2YcWH8Xsp8Xrrnwhy2dpMmmJwZfSavqBuXzhXnV [2023-02-21T16:07:25.681532000Z INFO  solana_ledger::blockstore] Maximum open file descriptors: 1000000 [2023-02-21T16:07:25.681534000Z INFO  solana_ledger::blockstore] Opening database at "test-ledger/rocksdb" [2023-02-21T16:07:25.751340000Z INFO  solana_ledger::blockstore] "test-ledger/rocksdb" open took 69ms [2023-02-21T16:07:25.751728000Z INFO  solana_ledger::bank_forks_utils] Initializing bank snapshot path: test-ledger/snapshot [2023-02-21T16:07:25.751916000Z WARN  solana_ledger::bank_forks_utils] No snapshot package found in directory: "test-ledger"; will load from genesis [2023-02-21T16:07:25.751922000Z INFO  solana_ledger::bank_forks_utils] Processing ledger from genesis [2023-02-21T16:07:25.751924000Z INFO  solana_ledger::builtins] BPF JIT is not supported on this target ```

I noticed the "BPF JIT is not supported on this target" on the last line, so I tried running the inner command with --no-bpf-jit added. Unfortunately that just removed that last line but the rest of the error is the same.

I did notice that the command output is different:

solana-test-validator -r --bpf-program <snip> --geyser-plugin-config /Users/callum/projects/clockwork/lib/geyser-plugin-config.json --no-bpf-jit
Ledger location: test-ledger
Log: test-ledger/validator.log
⠚ Initializing...
[1]    88444 segmentation fault  solana-test-validator -r --bpf-program   --bpf-program   --bpf-program

This output is the same if I remove the --no-bpf-jit flag

I also tried 2.0.0-beta:

2.0.0-beta validator.log ``` [2023-02-21T16:15:59.872851000Z INFO  solana_test_validator] solana-validator 1.14.16 (src:0fb2ffda; feat:3488713414) [2023-02-21T16:15:59.872892000Z INFO  solana_test_validator] Starting validator with: ArgsOs { inner: [ "solana-test-validator", "-r", "--bpf-program", "F8dKseqmBoAkHx3c58Lmb9TgJv5qeTf3BbtZZSEzYvUa", "/Users/callum/projects/clockwork/lib/clockwork_network_program.so", "--bpf-program", "CLoCKyJ6DXBJqqu2VWx9RLbgnwwR6BMHHuyasVmfMzBh", "/Users/callum/projects/clockwork/lib/clockwork_thread_program.so", "--bpf-program", "E7p5KFo8kKCDm6BUnWtnVFkQSYh6ZA6xaGAuvpv8NXTa", "/Users/callum/projects/clockwork/lib/clockwork_webhook_program.so", "--geyser-plugin-config", "/Users/callum/projects/clockwork/lib/geyser-plugin-config.json", ], } [2023-02-21T16:15:59.873152000Z WARN  solana_perf] CUDA is disabled [2023-02-21T16:15:59.877644000Z INFO  solana_faucet::faucet] Faucet started. Listening on: 0.0.0.0:9900 [2023-02-21T16:15:59.877661000Z INFO  solana_faucet::faucet] Faucet account address: Ac7bevkrqRigMxiSccvg7wmYjCHHYrccndEFeg1UeGgy [2023-02-21T16:15:59.888007000Z INFO  solana_ledger::blockstore] Maximum open file descriptors: 1000000 [2023-02-21T16:15:59.888190000Z INFO  solana_ledger::blockstore] Opening database at "test-ledger/rocksdb" [2023-02-21T16:15:59.996059000Z INFO  solana_ledger::blockstore] "test-ledger/rocksdb" open took 107ms [2023-02-21T16:16:00.008533000Z INFO  solana_metrics::metrics] metrics disabled: SOLANA_METRICS_CONFIG: environment variable not found [2023-02-21T16:16:00.008767000Z INFO  solana_metrics::metrics] datapoint: shred_insert_is_full total_time_ms=0i slot=0i last_index=3i num_repaired=0i num_recovered=0i [2023-02-21T16:16:00.125948000Z INFO  solana_runtime::hardened_unpack] Extracting "test-ledger/genesis.tar.bz2"... [2023-02-21T16:16:00.167725000Z INFO  solana_runtime::hardened_unpack] unpacked 1 entries total [2023-02-21T16:16:00.167736000Z INFO  solana_runtime::hardened_unpack] Extracted "test-ledger/genesis.tar.bz2" in 41.755875ms [2023-02-21T16:16:00.170114000Z WARN  solana_core::validator] identity: BGYtjwEb4iihUcN1UKsyrsipimhU65xJqjcfjagdWDHT [2023-02-21T16:16:00.170124000Z WARN  solana_core::validator] vote account: 48tJFpJGiNdbPSwZ8gNT2H8BtrfBJbJqirBN4pZoHA4X [2023-02-21T16:16:00.170547000Z INFO  solana_geyser_plugin_manager::geyser_plugin_service] Starting GeyserPluginService from config files: ["/Users/callum/projects/clockwork/lib/geyser-plugin-config.json"] [2023-02-21T16:16:00.476566000Z INFO clockwork_plugin::plugin] clockwork-plugin crate-info - spec: https://github.com/clockwork-xyz/clockwork/tree/7c88ec56ef9f0591bb30ccdd53aa97097de69ef0, geyser_interface_version: ~1.14.12 [2023-02-21T16:16:00.476716000Z INFO clockwork_plugin::plugin] Loading snapshot... [2023-02-21T16:16:00.479160000Z INFO  solana_geyser_plugin_manager::geyser_plugin_service] Started GeyserPluginService [2023-02-21T16:16:00.479184000Z WARN  solana_core::validator] authorized voter: 48tJFpJGiNdbPSwZ8gNT2H8BtrfBJbJqirBN4pZoHA4X [2023-02-21T16:16:00.481581000Z INFO  solana_core::validator] Initializing sigverify... [2023-02-21T16:16:00.481608000Z INFO  solana_core::validator] Done. [2023-02-21T16:16:00.481625000Z INFO  solana_core::validator] Cleaning accounts paths.. [2023-02-21T16:16:00.481684000Z WARN  solana_core::validator] encountered error removing accounts path: "test-ledger/accounts": No such file or directory (os error 2) [2023-02-21T16:16:00.481693000Z INFO  solana_core::validator] done. clean_accounts_paths took 63us [2023-02-21T16:16:00.481698000Z INFO  solana_core::validator] Geyser plugin: accounts_update_notifier: true transaction_notifier: false [2023-02-21T16:16:00.482002000Z INFO  solana_core::system_monitor_service] Starting SystemMonitorService [2023-02-21T16:16:00.482741000Z INFO  solana_core::validator] loading ledger from "test-ledger"... [2023-02-21T16:16:00.495541000Z INFO  solana_core::validator] genesis hash: HhPa18PSG2WiZEGTZ28URxe6um4cfBq9FwyfcoMcpSae [2023-02-21T16:16:00.495561000Z INFO  solana_ledger::blockstore] Maximum open file descriptors: 1000000 [2023-02-21T16:16:00.495564000Z INFO  solana_ledger::blockstore] Opening database at "test-ledger/rocksdb" [2023-02-21T16:16:00.571344000Z INFO  solana_ledger::blockstore] "test-ledger/rocksdb" open took 75ms [2023-02-21T16:16:00.572455000Z INFO  solana_ledger::bank_forks_utils] Initializing bank snapshot path: test-ledger/snapshot [2023-02-21T16:16:00.572768000Z WARN  solana_ledger::bank_forks_utils] No snapshot package found in directory: "test-ledger"; will load from genesis [2023-02-21T16:16:00.572786000Z INFO  solana_ledger::bank_forks_utils] Processing ledger from genesis [2023-02-21T16:16:00.572790000Z INFO  solana_ledger::builtins] BPF JIT is not supported on this target thread '' panicked at 'Slice must be the same length as a Pubkey: TryFromSliceError(())', /Users/callum/.cargo/registry/src/github.com-1ecc6299db9ec823/solana-program-1.14.12/src/pubkey.rs:157:18 stack backtrace: 0: 0x10be74c88 - std::backtrace_rs::backtrace::libunwind::trace::h57300112cb15ada0 at /rustc/ef934d9b632b8ac00276558824664c104b92b5f0/library/std/src/../../backtrace/src/backtrace/libunwind.rs:93:5 1: 0x10be74c88 - std::backtrace_rs::backtrace::trace_unsynchronized::hcf3a248d7a27de6c at /rustc/ef934d9b632b8ac00276558824664c104b92b5f0/library/std/src/../../backtrace/src/backtrace/mod.rs:66:5 2: 0x10be74c88 - std::sys_common::backtrace::_print_fmt::h4a3e441d1cf4cc81 at /rustc/ef934d9b632b8ac00276558824664c104b92b5f0/library/std/src/sys_common/backtrace.rs:65:5 3: 0x10be74c88 - ::fmt::h1d8000cb115ab1b1 at /rustc/ef934d9b632b8ac00276558824664c104b92b5f0/library/std/src/sys_common/backtrace.rs:44:22 4: 0x10be8d4b0 - core::fmt::write::hb4a42c7efd8f1690 at /rustc/ef934d9b632b8ac00276558824664c104b92b5f0/library/core/src/fmt/mod.rs:1232:17 5: 0x10be6fcbc - std::io::Write::write_fmt::h4afe2735edabbc94 at /rustc/ef934d9b632b8ac00276558824664c104b92b5f0/library/std/src/io/mod.rs:1684:15 6: 0x10be74a9c - std::sys_common::backtrace::_print::hb91df33162cf960a at /rustc/ef934d9b632b8ac00276558824664c104b92b5f0/library/std/src/sys_common/backtrace.rs:47:5 7: 0x10be74a9c - std::sys_common::backtrace::print::hff3831971f64cecb at /rustc/ef934d9b632b8ac00276558824664c104b92b5f0/library/std/src/sys_common/backtrace.rs:34:9 8: 0x10be765cc - std::panicking::default_hook::{{closure}}::h71a6ecf250628b79 at /rustc/ef934d9b632b8ac00276558824664c104b92b5f0/library/std/src/panicking.rs:267:22 9: 0x10be76324 - std::panicking::default_hook::hca770bcc00460b96 at /rustc/ef934d9b632b8ac00276558824664c104b92b5f0/library/std/src/panicking.rs:286:9 10: 0x10b0f234c - as core::ops::function::Fn>::call::h615943b0a9271093 at /rustc/ef934d9b632b8ac00276558824664c104b92b5f0/library/alloc/src/boxed.rs:2002:9 11: 0x10b0f1910 - ::setup::{{closure}}::{{closure}}::h94fab62fc78c8f0d at /Users/callum/.cargo/registry/src/github.com-1ecc6299db9ec823/sentry-panic-0.27.0/src/lib.rs:71:17 12: 0x10be76c18 - as core::ops::function::Fn>::call::h5a55c652266c1dcf at /rustc/ef934d9b632b8ac00276558824664c104b92b5f0/library/alloc/src/boxed.rs:2002:9 13: 0x10be76c18 - std::panicking::rust_panic_with_hook::h165d4369c18cfdb9 at /rustc/ef934d9b632b8ac00276558824664c104b92b5f0/library/std/src/panicking.rs:692:13 14: 0x10be76a10 - std::panicking::begin_panic_handler::{{closure}}::h82c7a0871778710b at /rustc/ef934d9b632b8ac00276558824664c104b92b5f0/library/std/src/panicking.rs:579:13 15: 0x10be750f0 - std::sys_common::backtrace::__rust_end_short_backtrace::h5ff2932958f16435 at /rustc/ef934d9b632b8ac00276558824664c104b92b5f0/library/std/src/sys_common/backtrace.rs:137:18 16: 0x10be7676c - rust_begin_unwind at /rustc/ef934d9b632b8ac00276558824664c104b92b5f0/library/std/src/panicking.rs:575:5 17: 0x10beb71c0 - core::panicking::panic_fmt::h526be5af938d8ba5 at /rustc/ef934d9b632b8ac00276558824664c104b92b5f0/library/core/src/panicking.rs:64:14 18: 0x10beb74f8 - core::result::unwrap_failed::h1a82835fc58a7a88 at /rustc/ef934d9b632b8ac00276558824664c104b92b5f0/library/core/src/result.rs:1790:5 19: 0x10bda4bd4 - core::result::Result::expect::h895161145c526310 at /rustc/ef934d9b632b8ac00276558824664c104b92b5f0/library/core/src/result.rs:1069:23 20: 0x10bdb457c - solana_program::pubkey::Pubkey::new::h3f3f9c2afec5db45 at /Users/callum/.cargo/registry/src/github.com-1ecc6299db9ec823/solana-program-1.14.12/src/pubkey.rs:156:13 21: 0x10b0668dc - >::try_from::h113adb702a1add5f at /Users/callum/projects/clockwork/plugin/src/events.rs:25:28 22: 0x10afe9a6c - ::update_account::h988d21f53ea39983 at /Users/callum/projects/clockwork/plugin/src/plugin.rs:91:21 23: 0x1052d167c - solana_geyser_plugin_manager::accounts_update_notifier::AccountsUpdateNotifierImpl::notify_plugins_of_account_update::he438647cf6773873 24: 0x1052d0f90 - ::notify_account_update::hda90fe0cde620f43 25: 0x105ea4490 - solana_runtime::accounts_db::geyser_plugin_utils::::notify_account_at_accounts_update::h13726a0742f64dd3 26: 0x105ed2524 - core::ops::function::impls:: for &mut F>::call_once::he7b7d25c51b1b551 27: 0x105efe620 - as alloc::vec::spec_from_iter::SpecFromIter>::from_iter::hc2633daa889e45b2 28: 0x105ec3e40 - solana_runtime::accounts_db::AccountsDb::store_cached::hf6cc797774c28d40 29: 0x105e7681c - solana_runtime::bank::Bank::store_account::ha9d80693a6f9c7d2 30: 0x105e61b40 - solana_runtime::bank::Bank::new_with_paths::h337abda9378281de 31: 0x1057bfcbc - solana_ledger::blockstore_processor::process_blockstore_for_bank_0::haa8534c9928a31f1 32: 0x1056ea830 - solana_ledger::bank_forks_utils::load_bank_forks::he02a8c8c56df480a 33: 0x10521add0 - solana_core::validator::load_blockstore::h610cb15a86593392 34: 0x10520c5f0 - solana_core::validator::Validator::new::h72128fd58cbb8935 35: 0x105047be0 - solana_test_validator::TestValidator::start::hae7db0156f4e0715 36: 0x10504550c - solana_test_validator::TestValidatorGenesis::start_with_mint_address::h18d720339538665d 37: 0x104faf118 - solana_test_validator::main::hfc78a46f6a1a17e8 38: 0x104f87cd0 - std::sys_common::backtrace::__rust_begin_short_backtrace::hb145820a7ca1a1db 39: 0x104f8e994 - std::rt::lang_start::{{closure}}::hf17af1e57cfc0cbe 40: 0x1067076f0 - std::rt::lang_start_internal::h358b6d58e23c88c7 41: 0x104fb1634 - _main ```

In this case running the inner command seems to have the same error as in my original issue:

$ solana-test-validator -r --bpf-program <snip> --geyser-plugin-config /Users/callum/projects/clockwork/lib/geyser-plugin-config.json --no-bpf-jit
Ledger location: test-ledger
Log: test-ledger/validator.log
[1]    89975 bus error  solana-test-validator -r --bpf-program   --bpf-program   --bpf-program

I'm confused that nobody else seems to have seen this though and not sure what I could be doing wrong

mwrites commented 1 year ago

Sorry we are a bit late on this, this should be fixed by the new localnet: https://github.com/clockwork-xyz/clockwork#local-development

@mcintyre94

mcintyre94 commented 1 year ago

Awesome, seems to be working correctly now! Thanks a lot @mwrites :)