Jormungandr: Crash on Jormungandr 0.6.0 on Mac OSX Catalina

[rickymac68]

Oct 15 03:19:04.372 ERRO Error while accepting connection on 0.0.0.0:3100: Os { code: 22, kind: InvalidInput, message: "Invalid argument" }, task: network
thread 'network9' panicked at 'Box', jormungandr/src/main.rs:225:30
note: run with RUST_BACKTRACE=1 environment variable to display a backtrace.

Oct 15 04:31:30.659 ERRO Error while accepting connection on 0.0.0.0:3100: Os { code: 22, kind: InvalidInput, message: "Invalid argument" }, task: network
thread 'network2' panicked at 'Box', jormungandr/src/main.rs:225:30
note: run with RUST_BACKTRACE=1 environment variable to display a backtrace.

This is my crash output while running Mac OSX Catalina 10.15 and using zsh for a shell vice bash since Catalina uses zsh by default. 12 Core Xeon processor with 64 GB RAM. The node crashed after about 5 hours of run time, then again after 1 hour and 12 minutes. Was running solid for days on 0.5.6.

[NicolasDP]

The invalid argument I think are related to some nodes still running on 0.5.6 trying to connect to you. Now I have a feeling that the connections are actually not all close properly, what do you think @mzabaluev ?

[rickymac68]

Upload of entire log in .rtf format renamed .rtf to .txt
jorm-0-6-0-crashOnMac.txt

[rickymac68]

Upload of the output from ./jcli rest v0 network stats get --output-format json -h http://127.0.0.1:3101/api

This is another .rtf file renamed as .txt you may have to rename the extension back to .rtf
Jorm-0-6-0-network-stats.txt

[mzabaluev]

@rickymac68 Thank you. It would save us some time if the files were actually in plain text, as captured directly from the output.

[rickymac68]

I was using ulimit -n 12400

[rickymac68]

jorm-0-6-0-crashOnMac.txt
Jorm-0-6-0-network-stats.txt

[rickymac68]

trying again with max_connections: 256 which I did not use before

[rickymac68]

Oct 19 17:53:28.764 INFO incoming P2P connection on 192.168.1.116:3100, peer_addr: 51.158.110.166:42272, task: network
Oct 19 17:53:31.181 INFO failed to connect to peer, reason: connection failed: HTTP/2.0 connection error, node_id: 1d2186433886b22af29db318f722a4122ccbd1b6567ade41b9d4c4fc5223c272, peer_addr: 83.20.249.50:3333, task: network
Oct 19 17:53:31.452 INFO incoming P2P HTTP/2 connection error, reason: connection error: Operation timed out (os error 60), peer_addr: 3.115.194.22:42884, task: network
Oct 19 17:53:31.452 ERRO Error while accepting connection on 0.0.0.0:3100: Os { code: 22, kind: InvalidInput, message: "Invalid argument" }, task: network
thread 'network11' panicked at 'Box', jormungandr/src/main.rs:226:30
stack backtrace:
0: 0x10e703132 - std::panicking::default_hook::{{closure}}::h3f994bbc901f9889
1: 0x10e702dfd - std::panicking::default_hook::h6c261b7dad1af707
2: 0x10e703870 - std::panicking::rust_panic_with_hook::hd3c20890ac648923
3: 0x10e740581 - std::panicking::begin_panic::h7dc27dda1266d182
4: 0x10def3040 - jormungandr::start_services::{{closure}}::{{closure}}::h3c9bb9cc584aaa04
5: 0x10df143d2 - std::panicking::try::do_call::h68ec82fc0e4eb4a0
6: 0x10e70762f - __rust_maybe_catch_panic
7: 0x10de645b2 - as futures::future::Future>::poll::h1f83f19bffe48979
8: 0x10ded0308 - as futures::future::Future>::poll::h8cf7808cb93005f0
9: 0x10e6e24ad - futures::task_impl::std::set::hda2c7b9ea9214c05
10: 0x10e6e1f66 - std::panicking::try::do_call::h172639c983c6b588
11: 0x10e70762f - __rust_maybe_catch_panic
12: 0x10e6e1bdc - tokio_threadpool::task::Task::run::h80fa21fff9b5f56d
13: 0x10e6dc802 - tokio_threadpool::worker::Worker::run_task::hf9d8648420de78b7
14: 0x10e6dbe73 - tokio_threadpool::worker::Worker::run::h27964cc88f9462a6
15: 0x10e6bf47d - std::thread::local::LocalKey::with::h052a9b7dce1e542c
16: 0x10e6bf743 - std::thread::local::LocalKey::with::h67c7b19c6f710629
17: 0x10e6bf5f5 - std::thread::local::LocalKey::with::h32cc21945bfb518c
18: 0x10e6c1331 - tokio::runtime::threadpool::builder::Builder::build::{{closure}}::h87eb1396ad6e8f9a
19: 0x10e6df06b - std::thread::local::LocalKey::with::h1244f1e7da250c30
20: 0x10e6dee6b - std::thread::local::LocalKey::with::h056b4e3c6dfbdec3
21: 0x10e6d8670 - std::sys_common::backtrace::__rust_begin_short_backtrace::h1597f692f0c54ff8
22: 0x10e6e1fd0 - std::panicking::try::do_call::hecd64633e6c54ec9
23: 0x10e70762f - __rust_maybe_catch_panic
24: 0x10e6da137 - core::ops::function::FnOnce::call_once{{vtable.shim}}::hbd4a7afb9d6ae8c3
25: 0x10e6f431e - as core::ops::function::FnOnce>::call_once::h04257f365502db2d
26: 0x10e706b4e - std::sys::unix::thread::Thread::new::thread_start::haec1a494f7a7ae67
27: 0x7fff724b1d76 - _pthread_start
Rick@macpro jormungandr %

[rickymac68]

This was a crash with max_connections: set to 92 but I do not know if that is relevant. I am going to try again with max_connections: set to 40. If I set the number too low like 16 it seems as though the blocks never synchronize but I have no idea how this is supposed to work. Good luck!

Oct 19 21:58:06.257 INFO incoming P2P HTTP/2 connection error, reason: connection error: Connection reset by peer (os error 54), peer_addr: 95.217.43.44:57618, task: network
Oct 19 21:58:06.258 ERRO Error while accepting connection on 0.0.0.0:3100: Os { code: 22, kind: InvalidInput, message: "Invalid argument" }, task: network
thread 'network17' panicked at 'Box', jormungandr/src/main.rs:226:30
stack backtrace:
Oct 19 21:58:06.272 INFO failed to connect to peer, reason: protocol handshake failed: unknown error, node_id: 1d7bc27f49260cbabe52df17c5498a9e5d36cdd561b16e0eff91e586538812f1, peer_addr: 96.248.209.37:3100, task: network
0: 0x105cdf132 - std::panicking::default_hook::{{closure}}::h3f994bbc901f9889
1: 0x105cdedfd - std::panicking::default_hook::h6c261b7dad1af707
2: 0x105cdf870 - std::panicking::rust_panic_with_hook::hd3c20890ac648923
3: 0x105d1c581 - std::panicking::begin_panic::h7dc27dda1266d182
4: 0x1054cf040 - jormungandr::start_services::{{closure}}::{{closure}}::h3c9bb9cc584aaa04
5: 0x1054f03d2 - std::panicking::try::do_call::h68ec82fc0e4eb4a0
6: 0x105ce362f - __rust_maybe_catch_panic
7: 0x1054405b2 - as futures::future::Future>::poll::h1f83f19bffe48979
8: 0x1054ac308 - as futures::future::Future>::poll::h8cf7808cb93005f0
9: 0x105cbe4ad - futures::task_impl::std::set::hda2c7b9ea9214c05
10: 0x105cbdf66 - std::panicking::try::do_call::h172639c983c6b588
11: 0x105ce362f - __rust_maybe_catch_panic
12: 0x105cbdbdc - tokio_threadpool::task::Task::run::h80fa21fff9b5f56d
13: 0x105cb8802 - tokio_threadpool::worker::Worker::run_task::hf9d8648420de78b7
14: 0x105cb7e73 - tokio_threadpool::worker::Worker::run::h27964cc88f9462a6
15: 0x105c9b47d - std::thread::local::LocalKey::with::h052a9b7dce1e542c
16: 0x105c9b743 - std::thread::local::LocalKey::with::h67c7b19c6f710629
17: 0x105c9b5f5 - std::thread::local::LocalKey::with::h32cc21945bfb518c
18: 0x105c9d331 - tokio::runtime::threadpool::builder::Builder::build::{{closure}}::h87eb1396ad6e8f9a
19: 0x105cbb06b - std::thread::local::LocalKey::with::h1244f1e7da250c30
20: 0x105cbae6b - std::thread::local::LocalKey::with::h056b4e3c6dfbdec3
21: 0x105cb4670 - std::sys_common::backtrace::__rust_begin_short_backtrace::h1597f692f0c54ff8
22: 0x105cbdfd0 - std::panicking::try::do_call::hecd64633e6c54ec9
23: 0x105ce362f - __rust_maybe_catch_panic
24: 0x105cb6137 - core::ops::function::FnOnce::call_once{{vtable.shim}}::hbd4a7afb9d6ae8c3
25: 0x105cd031e - as core::ops::function::FnOnce>::call_once::h04257f365502db2d
26: 0x105ce2b4e - std::sys::unix::thread::Thread::new::thread_start::haec1a494f7a7ae67
27: 0x7fff724b1d76 - _pthread_start
Rick@macpro jormungandr %

[rickymac68]

This is the backtrace with max_connections: set to 40 so maybe that's not the issue. But I will try lowering it to 28.

Oct 19 23:21:41.818 INFO incoming P2P connection closed, peer_addr: 92.222.83.198:45650, task: network
Oct 19 23:21:41.818 ERRO Error while accepting connection on 0.0.0.0:3100: Os { code: 22, kind: InvalidInput, message: "Invalid argument" }, task: network
thread 'network6' panicked at 'Box', jormungandr/src/main.rs:226:30
stack backtrace:
0: 0x10eff5132 - std::panicking::default_hook::{{closure}}::h3f994bbc901f9889
1: 0x10eff4dfd - std::panicking::default_hook::h6c261b7dad1af707
2: 0x10eff5870 - std::panicking::rust_panic_with_hook::hd3c20890ac648923
3: 0x10f032581 - std::panicking::begin_panic::h7dc27dda1266d182
4: 0x10e7e5040 - jormungandr::start_services::{{closure}}::{{closure}}::h3c9bb9cc584aaa04
5: 0x10e8063d2 - std::panicking::try::do_call::h68ec82fc0e4eb4a0
6: 0x10eff962f - __rust_maybe_catch_panic
7: 0x10e7565b2 - as futures::future::Future>::poll::h1f83f19bffe48979
8: 0x10e7c2308 - as futures::future::Future>::poll::h8cf7808cb93005f0
9: 0x10efd44ad - futures::task_impl::std::set::hda2c7b9ea9214c05
10: 0x10efd3f66 - std::panicking::try::do_call::h172639c983c6b588
11: 0x10eff962f - __rust_maybe_catch_panic
12: 0x10efd3bdc - tokio_threadpool::task::Task::run::h80fa21fff9b5f56d
13: 0x10efce802 - tokio_threadpool::worker::Worker::run_task::hf9d8648420de78b7
14: 0x10efcde73 - tokio_threadpool::worker::Worker::run::h27964cc88f9462a6
15: 0x10efb147d - std::thread::local::LocalKey::with::h052a9b7dce1e542c
16: 0x10efb1743 - std::thread::local::LocalKey::with::h67c7b19c6f710629
17: 0x10efb15f5 - std::thread::local::LocalKey::with::h32cc21945bfb518c
18: 0x10efb3331 - tokio::runtime::threadpool::builder::Builder::build::{{closure}}::h87eb1396ad6e8f9a
19: 0x10efd106b - std::thread::local::LocalKey::with::h1244f1e7da250c30
20: 0x10efd0e6b - std::thread::local::LocalKey::with::h056b4e3c6dfbdec3
21: 0x10efca670 - std::sys_common::backtrace::__rust_begin_short_backtrace::h1597f692f0c54ff8
22: 0x10efd3fd0 - std::panicking::try::do_call::hecd64633e6c54ec9
23: 0x10eff962f - __rust_maybe_catch_panic
24: 0x10efcc137 - core::ops::function::FnOnce::call_once{{vtable.shim}}::hbd4a7afb9d6ae8c3
25: 0x10efe631e - as core::ops::function::FnOnce>::call_once::h04257f365502db2d
26: 0x10eff8b4e - std::sys::unix::thread::Thread::new::thread_start::haec1a494f7a7ae67
27: 0x7fff724b1d76 - _pthread_start
Rick@macpro jormungandr %

[mzabaluev]

Looks like accept errors out with EINVAL for some reason which might be specific to Mac OS X. I can't see why would this happen on Linux on a socket that's owned by the TcpListener.

[rickymac68]

I don't know if this is relevant to the same error, but on several occasions I got this error where my node tried to contact its self.

Oct 22 21:42:17.800 ERRO Error while accepting connection on 0.0.0.0:3100: Os { code: 22, kind: InvalidInput, message: "Invalid argument" }, task: network
Oct 22 21:42:17.815 INFO failed to connect to peer, reason: protocol handshake failed: unknown error, node_id: 134b2c9211d2d73c9d18ccd12598dec410e9eb54693d6361b889c4a35481c760, peer_addr: 96.248.209.37:3100, task: network
thread 'network16' panicked at 'Box', jormungandr/src/main.rs:226:30
note: run with RUST_BACKTRACE=1 environment variable to display a backtrace.
Rick@macpro jormungandr % RUST_BACKTRACE=full

The peer_addr: 96.248.209.37 is my own node's IP address.

[mzabaluev]

I got this error where my node tried to contact its self.

This might begin to explain it; we should avoid this on the client, too.
Does your node have public_address configured?

[rickymac68]

@mzabaluev Yes, public_address is configured

Rick@macpro jormungandr % cat node-config.yaml
log:
format: "plain"
level: "info"
output: "stderr"
p2p:
listen_address: "/ip4/0.0.0.0/tcp/3100"
public_address: "/ip4/96.248.209.37/tcp/3100"
topics_of_interest:
blocks: "high"
messages: "high"
trusted_peers:
- address: "/ip4/3.115.194.22/tcp/3000"
id: ed25519_pk1npsal4j9p9nlfs0fsmfjyga9uqk5gcslyuvxy6pexxr0j34j83rsf98wl2
- address: "/ip4/13.113.10.64/tcp/3000"
id: ed25519_pk16pw2st5wgx4558c6temj8tzv0pqc37qqjpy53fstdyzwxaypveys3qcpfl
- address: "/ip4/52.57.214.174/tcp/3000"
id: ed25519_pk1v4cj0edgmp8f2m5gex85jglrs2ruvu4z7xgy8fvhr0ma2lmyhtyszxtejz
- address: "/ip4/3.120.96.93/tcp/3000"
id: ed25519_pk10gmg0zkxpuzkghxc39n3a646pdru6xc24rch987cgw7zq5pmytmszjdmvh
- address: "/ip4/52.28.134.8/tcp/3000"
id: ed25519_pk1unu66eej6h6uxv4j4e9crfarnm6jknmtx9eknvq5vzsqpq6a9vxqr78xrw
- address: "/ip4/13.52.208.132/tcp/3000"
id: ed25519_pk15ppd5xlg6tylamskqkxh4rzum26w9acph8gzg86w4dd9a88qpjms26g5q9
- address: "/ip4/54.153.19.202/tcp/3000"
id: ed25519_pk1j9nj2u0amlg28k27pw24hre0vtyp3ge0xhq6h9mxwqeur48u463s0crpfk
rest:
listen: "127.0.0.1:3101"
explorer:
enabled: true

[NicolasDP]

We should not see this happening as this is prevented by the poldercast update/policy. However, @rickymac68 , please feel free to reopen this issue if it is still appearing for you in rc4 or next releases.

[carloslodelar]

Dec 16 20:04:17.043 ERRO Error while accepting connection on 0.0.0.0:3000: Os { code: 22, kind: InvalidInput, message: "Invalid argument" }, task: network
Dec 16 20:04:17.048 INFO service finished with error, task: network
Dec 16 20:04:17.048 CRIT Service has terminated with an error
A service has terminated with an error

./jormungandr -V
jormungandr 0.8.2

MACOS Mojave 10.14.6

[babelitconsulting]

ERRO Error while accepting connection on 0.0.0.0:3001: Os { code: 24, kind: Other, message: "Too many open files" }, task: network
Jan 07 09:59:58.733 INFO service finished with error, task: network
Jan 07 09:59:58.733 CRIT Service has terminated with an error

version: jormungandr 0.8.5-3db06807