Investigate broken inet peering
On the current tag ratman-0.3.1
inet peering seems to be broken for unknown reasons. Announcements are not making it across the network. Opening this issue to track the bug investigation.
Logs
Machine A
❤ (tempest) ~/P/i/irdest> cargo run --bin ratmand --all-features -- --no-discovery --accept-unknown-peers -v trace lorri-keep-env-hack-irdest-dev
warning: /home/Projects/irdest/irdest/clients/irdest-proxy/Cargo.toml: unused manifest key: dependencies.serde.feature
Finished dev [unoptimized + debuginfo] target(s) in 0.08s
Running `target/debug/ratmand --no-discovery --accept-unknown-peers -v trace`
Jan 26 08:55:54.927 INFO ratman::daemon: Initialised logger: welcome to ratmand!
Jan 26 08:55:54.928 INFO new{bind="[::]:9000" name="ratmand" mode=Dynamic}: netmod_inet: Initialising Tcp backend
Jan 26 08:55:54.928 INFO ratman::daemon: Listening for API connections on socket 127.0.0.1:9020
Jan 26 08:55:54.928 TRACE ratman::daemon::state: Ensure data directory exists: "/home/.local/share/ratmand"
Jan 26 08:55:54.928 INFO netmod_inet::server: Listening on Ok([::]:9000) for incoming connections
Jan 26 08:55:54.928 DEBUG ratman::daemon::state: Loading registered users from file "/home/.local/share/ratmand/users.json"
Jan 26 08:55:54.928 TRACE completed: ratman::core::collector::state: No new frames; registering waker
Jan 26 08:55:57.198 DEBUG netmod_inet::server: Accepting new connection...
Jan 26 08:55:57.199 TRACE open{dst=[::ffff:127.0.0.1]:10000 port=10000 _type=Bidirect}: netmod_inet::peer: Start peer handler for [::ffff:127.0.0.1]:10000
Jan 26 08:55:57.199 DEBUG open{dst=[::ffff:127.0.0.1]:10000 port=10000 _type=Bidirect}: netmod_inet::peer: Running IO sender
Jan 26 08:55:57.199 TRACE netmod_inet::server: Upgrading RX stream by sending Hello packet...
Jan 26 08:55:57.199 TRACE netmod_inet::peer: Queued packet Hello { port: 10000, _type: Bidirect }
Jan 26 08:55:57.199 TRACE netmod_inet::peer: Sender is None, opening a connection first...
Jan 26 08:55:57.199 DEBUG netmod_inet::peer: : Attempting to connect to peer `[::ffff:127.0.0.1]:10000`
Jan 26 08:55:57.199 INFO netmod_inet::peer: Successfully connected to peer `[::ffff:127.0.0.1]:10000`
Jan 26 08:55:57.199 TRACE netmod_inet::peer: Sending HELLO to [::
Machine B
❤ (tempest) ~/P/i/irdest> env XDG_DATA_HOME=(mktemp -d) cargo run --bin ratmand --all-features -- --no-discovery --peers 'inet#127.0.0.1:9000' -v trace --inet 0.0.0.0:10000 --bind "0.0.0.0:10001" --accept-unknown-peers
warning: /home/Projects/irdest/irdest/clients/irdest-proxy/Cargo.toml: unused manifest key: dependencies.serde.feature
Finished dev [unoptimized + debuginfo] target(s) in 0.08s
Running `target/debug/ratmand --no-discovery --peers 'inet#127.0.0.1:9000' -v trace --inet '0.0.0.0:10000' --bind '0.0.0.0:10001' --accept-unknown-peers`
Jan 26 08:55:57.197 INFO ratman::daemon: Initialised logger: welcome to ratmand!
Jan 26 08:55:57.197 INFO new{bind="0.0.0.0:10000" name="ratmand" mode=Dynamic}: netmod_inet: Initialising Tcp backend
Jan 26 08:55:57.197 DEBUG ratmand: Initialising peering session with: 'inet#127.0.0.1:9000'
Jan 26 08:55:57.198 TRACE netmod_inet: Adding peer: 127.0.0.1:9000 ()
Jan 26 08:55:57.197 INFO netmod_inet::server: Listening on Ok(0.0.0.0:10000) for incoming connections
Jan 26 08:55:57.198 TRACE open{dst=127.0.0.1:9000 port=10000 _type=Bidirect}: netmod_inet::peer: Start peer handler for 127.0.0.1:9000
Jan 26 08:55:57.198 DEBUG open{dst=127.0.0.1:9000 port=10000 _type=Bidirect}: netmod_inet::peer: Running IO sender
Jan 26 08:55:57.198 TRACE netmod_inet::peer: Queued packet Hello { port: 10000, _type: Bidirect }
Jan 26 08:55:57.198 INFO ratman::daemon: Listening for API connections on socket 0.0.0.0:10001
Jan 26 08:55:57.198 TRACE ratman::daemon::state: Ensure data directory exists: "/tmp/tmp.xFzeJxg4Q0/ratmand"
Jan 26 08:55:57.198 TRACE netmod_inet::peer: Sender is None, opening a connection first...
Jan 26 08:55:57.198 DEBUG netmod_inet::peer: : Attempting to connect to peer `127.0.0.1:9000`
Jan 26 08:55:57.198 DEBUG ratman::daemon::state: Loading registered users from file "/tmp/tmp.xFzeJxg4Q0/ratmand/users.json"
Jan 26 08:55:57.198 INFO netmod_inet::peer: Successfully connected to peer `127.0.0.1:9000`
Jan 26 08:55:57.198 TRACE completed: ratman::core::collector::state: No new frames; registering waker
Jan 26 08:55:57.198 TRACE netmod_inet::peer: Sending HELLO to 127.0.0.1:9000
Jan 26 08:55:57.199 TRACE netmod_inet::peer: Received an ACK.
Jan 26 08:55:57.199 DEBUG netmod_inet::server: Accepting new connection...
Jan 26 08:55:57.200 TRACE open{dst=127.0.0.1:10000 port=10000 _type=Bidirect}: netmod_inet::peer: Start peer handler for 127.0.0.1:10000
Jan 26 08:55:57.200 DEBUG open{dst=127.0.0.1:10000 port=10000 _type=Bidirect}: netmod_inet::peer: Running IO sender
Jan 26 08:55:57.200 TRACE netmod_inet::peer: Queued packet Hello { port: 10000, _type: Bidirect }
Jan 26 08:55:57.200 TRACE netmod_inet::server: Upgrading RX stream by sending Hello packet...
Jan 26 08:55:57.200 TRACE netmod_inet::peer: Sender is None, opening a connection first...
Jan 26 08:55:57.200 DEBUG netmod_inet::peer: : Attempting to connect to peer `127.0.0.1:10000`
Jan 26 08:55:57.200 DEBUG netmod_inet::server: Accepting new connection...
Jan 26 08:55:57.200 INFO netmod_inet::peer: Successfully connected to peer `127.0.0.1:10000`
Jan 26 08:55:57.201 TRACE netmod_inet::peer: Sending HELLO to 127.0.0.1:10000
Jan 26 08:55:57.201 TRACE netmod_inet::routes: Upgrading peer 2 with SRC address
Jan 26 08:55:57.201 TRACE netmod_inet::server: I don't really know what we are doing here...
Jan 26 08:55:57.201 TRACE netmod_inet::peer: Received an ACK.
Jan 26 08:55:59.201 TRACE netmod_inet::peer: Queued packet Hello { port: 10000, _type: Bidirect }
Jan 26 08:55:59.202 TRACE netmod_inet::peer: Sending HELLO to 127.0.0.1:10000
thread 'async-std/runtime' panicked at 'Invalid packet mode: Duplex Dynamic Some(2)', netmods/netmod-inet/src/server.rs:230:33
note: run with `RUST_BACKTRACE=1` environment variable to display a backtrace
Jan 26 08:55:59.202 ERROR netmod_inet::peer: Failed to read ACK from sender stream
Jan 26 08:56:07.198 WARN netmod_inet::peer: [10 second timeout] Peering with 'Some(127.0.0.1:9000)' has not resulted in a DUPLEX link. Is a valid connection present?