Random IPs on fresh toolchains

[Cheaterman]

Hi,

Somehow rebuilding the server with fresh toolchains results in random (well not quite random, more like badly ordered, looks like endianness issue...) IPs:

15:47:00 [TRACE] (1) network: [network/src/lib.rs:214] accept_connections: Connect from 2.0.209.200:4524
15:47:00 [TRACE] (1) network: [network/src/lib.rs:224] process_connection: Connect from Some(172.17.0.2) to 2.0.209.200:4524
15:47:03 [TRACE] (13) network: [network/src/lib.rs:214] accept_connections: Connect from 2.0.209.200:4524
15:47:03 [TRACE] (13) network: [network/src/lib.rs:224] process_connection: Connect from Some(172.17.0.2) to 2.0.209.200:4524
[connection] incoming connection: 172.17.0.1:47866 id: 0
[join] Cheaterman has joined the server (0:172.17.0.1)
OnPlayerConnect(playerid=0)
15:47:05 [TRACE] (17) server: [server/src/lib.rs:80] on_player_connect 0 172.17.0.1
15:47:05 [TRACE] (17) server: [server/src/lib.rs:83] allow_connection 0 172.17.0.1
cef_on_player_connect(playerid=0, ip='172.17.0.1'): 1
15:47:05 [TRACE] (17) server: [server/src/lib.rs:80] on_player_connect 0 172.17.0.1
15:47:05 [TRACE] (17) server: [server/src/lib.rs:83] allow_connection 0 172.17.0.1
15:47:05 [TRACE] (13) network: [network/src/lib.rs:214] accept_connections: Connect from 2.0.209.200:4524
15:47:05 [TRACE] (13) network: [network/src/lib.rs:224] process_connection: Connect from Some(172.17.0.2) to 2.0.209.200:4524
15:47:08 [TRACE] (15) network: [network/src/lib.rs:214] accept_connections: Connect from 2.0.209.200:4524
15:47:08 [TRACE] (15) network: [network/src/lib.rs:224] process_connection: Connect from Some(172.17.0.2) to 2.0.209.200:4524
15:47:10 [TRACE] (17) server: [server/src/lib.rs:327] notify_connect(0, false)
OnCefInitialize(playerid=0, success=0)
cef_player_has_plugin(playerid=0): 0
15:47:10 [TRACE] (17) server: [server/src/lib.rs:318] notify_timeout::remove_from_await_list(0) true
15:47:10 [TRACE] (13) network: [network/src/lib.rs:214] accept_connections: Connect from 2.0.209.200:4524
15:47:10 [TRACE] (13) network: [network/src/lib.rs:224] process_connection: Connect from Some(172.17.0.2) to 2.0.209.200:4524
15:47:13 [TRACE] (15) network: [network/src/lib.rs:214] accept_connections: Connect from 2.0.209.200:4524
15:47:13 [TRACE] (15) network: [network/src/lib.rs:224] process_connection: Connect from Some(172.17.0.2) to 2.0.209.200:4524
15:47:15 [TRACE] (15) network: [network/src/lib.rs:214] accept_connections: Connect from 2.0.209.200:4524
15:47:15 [TRACE] (15) network: [network/src/lib.rs:224] process_connection: Connect from Some(172.17.0.2) to 2.0.209.200:4524
15:47:18 [TRACE] (17) server: [server/src/lib.rs:100] remove_connection 0 
[part] Cheaterman has left the server (0:1)
15:47:18 [TRACE] (1) network: [network/src/lib.rs:214] accept_connections: Connect from 2.0.209.200:4524
15:47:18 [TRACE] (1) network: [network/src/lib.rs:224] process_connection: Connect from Some(172.17.0.2) to 2.0.209.200:4524
15:47:20 [TRACE] (1) network: [network/src/lib.rs:237] ERROR while connecting: TimedOut
15:47:23 [TRACE] (1) network: [network/src/lib.rs:237] ERROR while connecting: TimedOut
15:47:25 [TRACE] (1) network: [network/src/lib.rs:237] ERROR while connecting: TimedOut
15:47:28 [TRACE] (13) network: [network/src/lib.rs:237] ERROR while connecting: TimedOut
15:47:28 [TRACE] (1) network: [network/src/lib.rs:237] ERROR while connecting: TimedOut
15:47:28 [TRACE] (15) network: [network/src/lib.rs:237] ERROR while connecting: TimedOut
15:47:30 [TRACE] (1) network: [network/src/lib.rs:237] ERROR while connecting: TimedOut
15:47:30 [TRACE] (15) network: [network/src/lib.rs:237] ERROR while connecting: TimedOut

Meanwhile rebuilding with 1.63.0 toolchain using the command cargo +1.63.0-i686 build --release --package server works:

16:08:09 [TRACE] (1) network: [network/src/lib.rs:214] accept_connections: Connect from 172.17.0.1:36463
16:08:09 [TRACE] (1) network: [network/src/lib.rs:224] process_connection: Connect from Some(172.17.0.2) to 172.17.0.1:36463
16:08:09 [TRACE] (18) server::server: [server/src/server.rs:189] handle_new_connection PeerId(1v1) 172.17.0.1:36463
16:08:09 [TRACE] (18) server::server: [server/src/server.rs:88] socket::disconnect PeerId(1v1)
16:08:09 [TRACE] (18) server::server: [server/src/server.rs:180] handle_timeout PeerId(1v1)
16:08:09 [TRACE] (18) server::server: [server/src/server.rs:183] {}
16:08:09 [TRACE] (18) server::server: [server/src/server.rs:184] {}
16:08:12 [TRACE] (11) network: [network/src/lib.rs:214] accept_connections: Connect from 172.17.0.1:36463
16:08:12 [TRACE] (11) network: [network/src/lib.rs:224] process_connection: Connect from Some(172.17.0.2) to 172.17.0.1:36463
16:08:12 [TRACE] (18) server::server: [server/src/server.rs:189] handle_new_connection PeerId(1v3) 172.17.0.1:36463
16:08:12 [TRACE] (18) server::server: [server/src/server.rs:88] socket::disconnect PeerId(1v3)
16:08:12 [TRACE] (18) server::server: [server/src/server.rs:180] handle_timeout PeerId(1v3)
16:08:12 [TRACE] (18) server::server: [server/src/server.rs:183] {}
16:08:12 [TRACE] (18) server::server: [server/src/server.rs:184] {}
[connection] incoming connection: 172.17.0.1:50020 id: 0
[join] Cheaterman has joined the server (0:172.17.0.1)
OnPlayerConnect(playerid=0)
16:08:13 [TRACE] (17) server: [server/src/lib.rs:80] on_player_connect 0 172.17.0.1
16:08:13 [TRACE] (17) server: [server/src/lib.rs:83] allow_connection 0 172.17.0.1
cef_on_player_connect(playerid=0, ip='172.17.0.1'): 1
16:08:14 [TRACE] (1) network: [network/src/lib.rs:214] accept_connections: Connect from 172.17.0.1:36463
16:08:14 [TRACE] (1) network: [network/src/lib.rs:224] process_connection: Connect from Some(172.17.0.2) to 172.17.0.1:36463
16:08:14 [TRACE] (18) server::server: [server/src/server.rs:189] handle_new_connection PeerId(1v5) 172.17.0.1:36463
16:08:14 [TRACE] (18) server::server: [server/src/server.rs:194] handle_new_connection: ok 0
16:08:14 [TRACE] (18) server::server: [server/src/server.rs:197] handle_new_connection: ok no peer with this id
16:08:14 [TRACE] (17) server: [server/src/lib.rs:388] process_tick::PlayerConnected(0)
16:08:14 [TRACE] (17) server: [server/src/lib.rs:327] notify_connect(0, true)
OnCefInitialize(playerid=0, success=1)
cef_create_browser(playerid=0, browserid=1, url='https://tms-server.com/'): 1
16:08:15 [TRACE] (17) server: [server/src/lib.rs:400] process_tick::BrowserCreated(0)
16:08:15 [TRACE] (17) server: [server/src/lib.rs:336] notify_browser_created(0, 1, 200)
[part] Cheaterman has left the server (0:1)

I looked into tokio and quinn, in fact I tried to update quinn but they have breaking changes in the way they build (or no longer build rather) endpoints, so I didn't push it too much... I really expected the issue to be on the client side hahaha, since I'm cross-building DLLs from Linux etc, but that part actually works, and it turns out it's the pure Linux server that's faulty... 🤦‍♂️

Either way, putting this out there for posterity. Hopefully we're not stuck on old toolchains forever, but right now, I don't see any other workaround...

[Cheaterman]

For anyone curious to get the extra debugging output, here's a rough patch:

diff --git a/cef-sys/build.rs b/cef-sys/build.rs
index a30877a..a1a9159 100644
--- a/cef-sys/build.rs
+++ b/cef-sys/build.rs
@@ -3,5 +3,5 @@ fn main() {
         .expect("No CEF_PATH env variable. It should point to the libcef.lib.");
 
     println!("cargo:rustc-link-search=native={}", cef_redist);
-    println!("cargo:rustc-link-lib=static=libcef");
+    println!("cargo:rustc-link-lib=libcef");
 }
diff --git a/client/src/lib.rs b/client/src/lib.rs
index 1ec3230..554ff42 100644
--- a/client/src/lib.rs
+++ b/client/src/lib.rs
@@ -42,6 +42,7 @@ pub extern "stdcall" fn DllMain(instance: HMODULE, reason: u32, _reserved: u32)
         let config = config
             .add_filter_allow_str("client")
             .add_filter_allow_str("client_api")
+            .add_filter_allow_str("network")
             .set_max_level(LevelFilter::Trace)
             .build();
 
diff --git a/client/src/network.rs b/client/src/network.rs
index b12c7aa..65601a1 100644
--- a/client/src/network.rs
+++ b/client/src/network.rs
@@ -33,8 +33,8 @@ impl NetworkClient {
                 network.run();
             } else {
                 log::trace!("network error ...");
-                std::thread::sleep(Duration::from_secs(2));
                 handle_result(net_tx.send(Event::NetworkError));
+                std::thread::sleep(Duration::from_secs(2));
             }
         });
 
@@ -325,8 +325,7 @@ impl Network {
     fn net_open_connection(&mut self, address: SocketAddr) {
         let peer = self.socket.connect(address);
         self.connection_state = ConnectionState::Auth(address, Instant::now(), peer);
-
-        log::trace!("CEF Network: OpenConnection ({})", address);
+        log::trace!("CEF Network: OpenConnection ({:?})", address);
         log::trace!(
             "CEF Network: Elapsed since Network module created {:?}",
             self.timings.elapsed()
@@ -396,8 +395,8 @@ impl Network {
                         }
                     }
 
-                    SocketEvent::ConnectionError(_) => {
-                        log::trace!("CEF Network: ConnectionError");
+                    SocketEvent::ConnectionError(error) => {
+                        log::trace!("CEF Network: ConnectionError: {:?}", error);
                         handle_result(self.event_tx.send(Event::Timeout));
 
                         if !self.connection_state.is_auth() {
diff --git a/network/Cargo.toml b/network/Cargo.toml
index 24b6f7d..c5e1d6f 100644
--- a/network/Cargo.toml
+++ b/network/Cargo.toml
@@ -6,10 +6,11 @@ edition = "2018"
 [dependencies]
 quinn = "0.7.2"
 futures-util = "0.3.17"
-tokio = { version = "1.11", features = ["full"] }
+tokio = { version = "1.32.0", features = ["full"] }
 rcgen = "0.8.13"
 rustls = { version = "0.19", features = ["dangerous_configuration", "quic"] }
 webpki = "0.21"
 slotmap = "1.0.6"
 anyhow = "1.0.44"
 crossbeam-channel = "0.5.1"
+log = "0.4.14"
diff --git a/network/src/lib.rs b/network/src/lib.rs
index e684a2c..cb72f06 100644
--- a/network/src/lib.rs
+++ b/network/src/lib.rs
@@ -88,9 +88,11 @@ impl Socket {
         let (cmd_tx, cmd_rx) = mpsc::unbounded_channel();
 
         let runtime = Runtime::new().unwrap();
+        log::trace!("Socket.new, addr={:?}, is_listening={:?}", addr, is_listening);
 
         runtime.block_on(async move {
             let (endpoint, incoming) = builder.bind(&addr).unwrap();
+            log::trace!("Local addr: {:?}", endpoint.local_addr());
 
             tokio::spawn(worker_task(
                 endpoint,
@@ -113,6 +115,7 @@ impl Socket {
     pub fn connect(&mut self, addr: SocketAddr) -> PeerId {
         let peer_id = self.peers_id.insert(());
 
+        log::trace!("connect(): addr={:?}", addr);
         let _ = self.cmd_tx.send(Command::Connect(addr, peer_id));
 
         peer_id
@@ -187,6 +190,7 @@ async fn worker_task(
         match cmd {
             Command::Connect(addr, peer_id) => {
                 let connecting = endpoint.connect(&addr, "samp.cef").unwrap();
+                log::trace!("Connect from: {:?} to: {:?}", connecting.local_ip(), addr);
 
                 tokio::spawn(process_connection(
                     connecting,
@@ -207,6 +211,7 @@ async fn accept_connections(
     mut incoming: Incoming, event_tx: crossbeam_channel::Sender<WorkerEvent>,
 ) {
     while let Some(conn) = incoming.next().await {
+        log::trace!("accept_connections: Connect from {:#?}", conn.remote_address());
         let event_tx = event_tx.clone();
         tokio::spawn(process_connection(conn, event_tx, None));
     }
@@ -216,13 +221,24 @@ async fn process_connection(
     connecting: Connecting, event_tx: crossbeam_channel::Sender<WorkerEvent>,
     peer_id: Option<PeerId>,
 ) -> anyhow::Result<()> {
+    log::trace!(
+        "process_connection: Connect from {:?} to {:?}",
+        connecting.local_ip(),
+        connecting.remote_address()
+    );
+
     let NewConnection {
         connection,
         uni_streams,
         ..
     } = match connecting.await {
         Ok(conn) => conn,
-        Err(_) => {
+        Err(error) => {
+            log::trace!(
+                "ERROR while connecting: {:?}",
+                error,
+            );
+
             if let Some(peer_id) = peer_id {
                 let _ = event_tx.send(WorkerEvent::ConnectionError(peer_id));
             }
diff --git a/server/Cargo.toml b/server/Cargo.toml
index 5322167..0fc3bf1 100644
--- a/server/Cargo.toml
+++ b/server/Cargo.toml
@@ -8,7 +8,9 @@ edition = "2018"
 crate-type = ["cdylib"]
 
 [dependencies]
-samp = { git = "https://github.com/zottce/samp-rs.git", branch = "potential-fix", features = ["encoding"] }
+samp-codegen = { path = "/tmp/samp-rs/samp-codegen/" }
+samp-sdk = { path = "/tmp/samp-rs/samp-sdk/", features = ["encoding"] }
+samp = { path = "/tmp/samp-rs/samp/", features = ["encoding"] }
 log = "0.4.6"
 crossbeam-channel = "0.5.1"
 messages = { path = "../messages" }
diff --git a/server/src/lib.rs b/server/src/lib.rs
index 8bc24a3..803bf30 100644
--- a/server/src/lib.rs
+++ b/server/src/lib.rs
@@ -6,7 +6,7 @@ use std::time::{Duration, Instant};
 use crossbeam_channel::Receiver;
 use log::{info, trace};
 use messages::packets::EventValue;
-// use simplelog::{CombinedLogger, LevelFilter, TermLogger, TerminalMode};
+use simplelog::{CombinedLogger, LevelFilter, TermLogger, TerminalMode};
 
 use samp::amx::AmxIdent;
 use samp::args::Args;
@@ -77,6 +77,8 @@ impl CefPlugin {
     ) -> AmxResult<bool> {
         let player_ip = player_ip.to_string();
 
+        trace!("on_player_connect {} {}", player_id, player_ip);
+
         if let Ok(addr) = player_ip.parse::<IpAddr>() {
             trace!("allow_connection {} {:?}", player_id, addr);
 
@@ -331,6 +333,8 @@ impl CefPlugin {
     }
 
     fn notify_browser_created(&self, player_id: i32, browser_id: u32, code: i32) {
+        trace!("notify_browser_created({}, {}, {})", player_id, browser_id, code);
+
         self.amx_list.iter().for_each(|&ident| {
             samp::amx::get(ident)
                 .map(|amx| exec_public!(amx, "OnCefBrowserCreated", player_id, browser_id, code));
@@ -352,6 +356,7 @@ impl SampPlugin for CefPlugin {
     }
 
     fn on_amx_load(&mut self, amx: &Amx) {
+        trace!("Loading amx: {:#?}", amx.ident());
         self.amx_list.push(amx.ident());
     }
 
@@ -396,8 +401,6 @@ impl SampPlugin for CefPlugin {
 
                     self.notify_browser_created(player_id, browser_id, code);
                 }
-
-                _ => (),
             }
         }
 
@@ -429,20 +432,21 @@ initialize_plugin!(
         samp::encoding::set_default_encoding(samp::encoding::WINDOWS_1251);
         let _ = samp::plugin::logger(); // fuck logger
 
-        // let mut config = simplelog::ConfigBuilder::new();
-
-        // let config = config
-        //     .add_filter_allow_str("server")
-        //     .set_max_level(LevelFilter::Trace)
-        //     .build();
-
-        // CombinedLogger::init(vec![TermLogger::new(
-        //     LevelFilter::Trace,
-        //     config,
-        //     TerminalMode::Mixed,
-        //     simplelog::ColorChoice::Always,
-        // )])
-        // .unwrap();
+        let mut config = simplelog::ConfigBuilder::new();
+
+        let config = config
+            .add_filter_allow_str("server")
+            .add_filter_allow_str("network")
+            .set_max_level(LevelFilter::Trace)
+            .build();
+
+        CombinedLogger::init(vec![TermLogger::new(
+            LevelFilter::Trace,
+            config,
+            TerminalMode::Mixed,
+            simplelog::ColorChoice::Always,
+        )])
+        .unwrap();
 
 
         CefPlugin::new()
diff --git a/server/src/server.rs b/server/src/server.rs
index 05d141e..21807c5 100644
--- a/server/src/server.rs
+++ b/server/src/server.rs
@@ -77,7 +77,7 @@ impl Server {
                         server.handle_timeout(peer);
                     }
 
-                    _ => (),
+                    _ => trace!("Other event"),
                 }
             }
 
@@ -122,7 +122,7 @@ impl Server {
                     .map(|packet| self.handle_browser_created(peer, packet));
             }
 
-            _ => (),
+            _ => trace!("Unknown packet"),
         }
     }

[Cheaterman]

Oh BTW, that's not just visual/logs, I'm getting the wrong IPs in wireshark too. Really strange!