Consistently getting "No such file or directory" on OSX

[andrewllyons]

Howdy,

I'm constantly getting a RUST error when running the relay or autorun with a DNS configuration (-d). Appears to be originating from relaylib::relay::connection::Connection::close

Logs are below:

thread 'main' panicked at 'called Result::unwrap() on an Err value: Error { repr: Os { code: 2, message: "No such file or directory" } }', src/libcore/result.rs:916:5
stack backtrace:
0: std::sys::unix::backtrace::tracing::imp::unwind_backtrace
1: std::panicking::default_hook::{{closure}}
2: std::panicking::rust_panic_with_hook
3: std::panicking::begin_panic
4: std::panicking::begin_panic_fmt
5: core::panicking::panic_fmt
6: core::result::unwrap_failed
7: <relaylib::relay::tcp_connection::TcpConnection as relaylib::relay::connection::Connection>::close
8: <relaylib::relay::tcp_connection::TcpConnection as relaylib::relay::connection::Connection>::send_to_network
9: relaylib::relay::router::Router::send_to_network
10: ::on_ready
11: relaylib::relay::relay::Relay::run
12: <gnirehtet::RelayCommand as gnirehtet::Command>::execute
13: gnirehtet::main
14: std::rt::lang_start::{{closure}}
15: main

[rom1v]

Interesting.

On which system (Windows, Linux, Mac OS…)?
What DNS address do you use?
Does it work with the Java version?

[andrewllyons]

As the title suggests it’s on Mac, I haven’t tried the java version yet. Note to make is this is on the latest official release not source distrib.

The DNS is an in-house company DNS so the device can connect to our internal network. I tested the setup on Windows and it was able to access fine, this issue seems to be restricted to Mac. I started the service on each of the android devices then started the relay service on the Mac which crashes consistently. Also starting it from the autorun produces the same results or only starts on one device, any attempt to connect more crashes it.

[rom1v]

As the title suggests it’s on Mac,

Sorry, I missed it. 😉

I tested the setup on Windows and it was able to access fine, this issue seems to be restricted to Mac.

The issue is probably not related to the DNS itself. According to the backtrace, I think it might be related to the Rust/mio backend for MacOS (otherwise, I think it would have happen on other platforms too).

Could you try the latest versoin of Rust/mio, calling:

cargo update

from relay-rust/, please? (and compiling normally)

And also test the java version.

Thank you.

[andrewllyons]

Sorry, I missed it. 😉

No worries!

I haven't been able to test the rust update yet, but can confirm that the Java version is working as expected so I suspect it's isolated to Rust.

[bobaaaaa]

I run into the same issue today. I switched from the rust version to the java version. This works for me 👍

[rom1v]

Did you test v2.2.1 (released for MacOS) or v2.3 (compiled manually because not released for MacOS)?

Since it seems to occur only on MacOS, I suspect a problem with the kqueue backend of Rust mio. Maybe a wrong assumption in gnirehtet which happens to be false on MacOS, or maybe a bug in mio.

Anyway, if you can reproduce easily, I'm interested in the results on current master (and even results after upgrading mio to the latest version).

[bobaaaaa]

I used the 2.2.1 version (rust) and 2.3 (java)

[faithoflifedev]

I'm experiencing this same issue on OSX. I downloaded the gnirehtet source, rust and did a cargo update from relay-rust. After this I ran cargo run run and the problem persisted. The updated version of mio is v0.6.16

[rom1v]

If you can reproduce, could you post the whole connection session (the output of gnirehtet) before this crash, please?

[faithoflifedev]

Running `target/debug/gnirehtet run`
2019-01-23 12:17:40.595 INFO Main: Starting relay server...
2019-01-23 12:17:40.595 INFO Main: Checking gnirehtet client...
2019-01-23 12:17:40.596 INFO Relay: Relay server started
2019-01-23 12:17:40.670 INFO Main: Starting client...
Broadcasting: Intent { act=com.genymobile.gnirehtet.START cmp=com.genymobile.gnirehtet/.GnirehtetControlReceiver }
Broadcast completed: result=0
2019-01-23 12:17:40.804 INFO TunnelServer: Client #0 connected
2019-01-23 12:17:40.821 INFO UdpConnection: 10.0.0.2:16434 -> 8.8.8.8:53 Open
2019-01-23 12:17:40.822 INFO UdpConnection: 10.0.0.2:51489 -> 8.8.8.8:53 Open
2019-01-23 12:17:40.822 INFO UdpConnection: 10.0.0.2:44487 -> 8.8.8.8:53 Open
2019-01-23 12:17:40.892 INFO TcpConnection: 10.0.0.2:42191 -> 172.217.1.170:443 Open
2019-01-23 12:17:40.893 INFO TcpConnection: 10.0.0.2:40867 -> 172.217.1.12:443 Open
2019-01-23 12:17:40.894 INFO TcpConnection: 10.0.0.2:47744 -> 209.85.200.114:80 Open
2019-01-23 12:17:40.987 INFO UdpConnection: 10.0.0.2:1292 -> 8.8.8.8:53 Open
2019-01-23 12:17:41.023 INFO TcpConnection: 10.0.0.2:46566 -> 172.217.1.172:80 Open
2019-01-23 12:17:41.799 INFO UdpConnection: 10.0.0.2:37743 -> 8.8.8.8:53 Open
2019-01-23 12:17:41.799 INFO UdpConnection: 10.0.0.2:61974 -> 8.8.8.8:53 Open
2019-01-23 12:17:41.799 INFO UdpConnection: 10.0.0.2:48359 -> 8.8.8.8:53 Open
2019-01-23 12:17:45.997 INFO TcpConnection: 10.0.0.2:41628 -> 13.92.193.110:443 Open
2019-01-23 12:17:46.368 INFO UdpConnection: 10.0.0.2:46379 -> 8.8.8.8:53 Open
2019-01-23 12:17:46.404 INFO TcpConnection: 10.0.0.2:39174 -> 108.177.121.188:5228 Open
2019-01-23 12:17:51.085 INFO UdpConnection: 10.0.0.2:45761 -> 8.8.8.8:53 Open
2019-01-23 12:17:51.124 INFO TcpConnection: 10.0.0.2:43069 -> 172.217.0.229:443 Open
2019-01-23 12:17:52.565 INFO UdpConnection: 10.0.0.2:53413 -> 8.8.8.8:53 Open
2019-01-23 12:17:52.600 INFO TcpConnection: 10.0.0.2:41065 -> 172.217.1.1:443 Open
2019-01-23 12:17:52.938 INFO TcpConnection: 10.0.0.2:41065 -> 172.217.1.1:443 Close
thread 'main' panicked at 'called `Result::unwrap()` on an `Err` value: Os { code: 2, kind: NotFound, message: "No such file or directory" }', src/libcore/result.rs:1009:5
note: Run with `RUST_BACKTRACE=1` for a backtrace.

The failure does not occur until I attempt to use the browser ion my device.

[rom1v]

Thanks.

Could you apply this patch to get more info about registering/deregistering, and paste the output again, please:

diff --git a/relay-rust/src/relay/tcp_connection.rs b/relay-rust/src/relay/tcp_connection.rs
index 91af24a..3533ed7 100644
--- a/relay-rust/src/relay/tcp_connection.rs
+++ b/relay-rust/src/relay/tcp_connection.rs
@@ -139,7 +139,7 @@ impl TcpConnection {
         ipv4_header: Ipv4Header,
         transport_header: TransportHeader,
     ) -> io::Result<Rc<RefCell<Self>>> {
-        cx_info!(target: TAG, id, "Open");
+        cx_info!(target: TAG, &id, "Open");
         let stream = Self::create_stream(&id)?;
 
         let tcp_header = Self::tcp_header_of_transport(transport_header);
@@ -166,7 +166,7 @@ impl TcpConnection {
         let interests = Ready::writable();
         let rc = Rc::new(RefCell::new(Self {
             self_weak: Weak::new(),
-            id,
+            id: id.clone(),
             client,
             stream,
             interests,
@@ -190,6 +190,7 @@ impl TcpConnection {
                 move |selector: &mut Selector, event| rc2.borrow_mut().on_ready(selector, event);
             let token =
                 selector.register(&self_ref.stream, handler, interests, PollOpt::level())?;
+            cx_info!(target: TAG, &id, "registered {:?}", token);
             self_ref.token = token;
         }
         Ok(rc)
@@ -783,8 +784,9 @@ impl Connection for TcpConnection {
     }
 
     fn close(&mut self, selector: &mut Selector) {
-        cx_info!(target: TAG, self.id, "Close");
+        cx_info!(target: TAG, &self.id, "Close");
         self.closed = true;
+        cx_info!(target: TAG, &self.id, "deregistering {:?}", self.token);
         selector.deregister(&self.stream, self.token).unwrap();
         // socket will be closed by RAII
     }

[faithoflifedev]

I removed some repeating lines to shorten the output:

Finished dev [unoptimized + debuginfo] target(s) in 1.59s
Running `target/debug/gnirehtet run`
2019-01-23 12:47:14.678 INFO Main: Checking gnirehtet client...
2019-01-23 12:47:14.678 INFO Main: Starting relay server...
2019-01-23 12:47:14.679 INFO Relay: Relay server started
2019-01-23 12:47:14.761 INFO Main: Starting client...
Broadcasting: Intent { act=com.genymobile.gnirehtet.START cmp=com.genymobile.gnirehtet/.GnirehtetControlReceiver }
Broadcast completed: result=0
2019-01-23 12:47:14.882 INFO TunnelServer: Client #0 connected
2019-01-23 12:47:14.886 INFO TcpConnection: 10.0.0.2:45664 -> 173.194.197.95:443 Open
2019-01-23 12:47:14.887 INFO TcpConnection: 10.0.0.2:45664 -> 173.194.197.95:443 registered Token(2)
2019-01-23 12:47:14.887 WARN TcpConnection: 10.0.0.2:45664 -> 173.194.197.95:443 Unexpected first packet 2156734700; acking 3770007443; flags=16
2019-01-23 12:47:14.887 INFO TcpConnection: 10.0.0.2:45664 -> 173.194.197.95:443 Close
2019-01-23 12:47:14.887 INFO TcpConnection: 10.0.0.2:45664 -> 173.194.197.95:443 deregistering Token(2)
2019-01-23 12:47:14.895 INFO TcpConnection: 10.0.0.2:40921 -> 172.217.1.12:443 Open
2019-01-23 12:47:14.896 INFO TcpConnection: 10.0.0.2:40921 -> 172.217.1.12:443 registered Token(2)
2019-01-23 12:47:14.896 WARN TcpConnection: 10.0.0.2:40921 -> 172.217.1.12:443 Unexpected first packet 884550499; acking 1879744792; flags=16
2019-01-23 12:47:14.896 INFO TcpConnection: 10.0.0.2:40921 -> 172.217.1.12:443 Close
2019-01-23 12:47:14.896 INFO TcpConnection: 10.0.0.2:40921 -> 172.217.1.12:443 deregistering Token(2)
2019-01-23 12:47:14.896 INFO TcpConnection: 10.0.0.2:40774 -> 173.194.198.114:80 Open
2019-01-23 12:47:14.896 INFO TcpConnection: 10.0.0.2:40774 -> 173.194.198.114:80 registered Token(3)
2019-01-23 12:47:14.896 INFO UdpConnection: 10.0.0.2:34922 -> 8.8.8.8:53 Open
2019-01-23 12:47:14.896 INFO TcpConnection: 10.0.0.2:40775 -> 173.194.198.114:80 Open
2019-01-23 12:47:14.897 INFO TcpConnection: 10.0.0.2:40775 -> 173.194.198.114:80 registered Token(5)
2019-01-23 12:47:14.897 INFO TcpConnection: 10.0.0.2:40776 -> 173.194.198.114:80 Open
2019-01-23 12:47:14.897 INFO TcpConnection: 10.0.0.2:40776 -> 173.194.198.114:80 registered Token(6)

2019-01-23 12:47:14.899 INFO TcpConnection: 10.0.0.2:49077 -> 74.125.202.188:5228 Open
2019-01-23 12:47:14.899 INFO TcpConnection: 10.0.0.2:49077 -> 74.125.202.188:5228 registered Token(19)
2019-01-23 12:47:14.899 WARN TcpConnection: 10.0.0.2:49077 -> 74.125.202.188:5228 Unexpected first packet 3670781719; acking 582072943; flags=16
2019-01-23 12:47:14.899 INFO TcpConnection: 10.0.0.2:49077 -> 74.125.202.188:5228 Close
2019-01-23 12:47:14.899 INFO TcpConnection: 10.0.0.2:49077 -> 74.125.202.188:5228 deregistering Token(19)
2019-01-23 12:47:14.899 INFO TcpConnection: 10.0.0.2:49077 -> 74.125.202.188:5228 Open
2019-01-23 12:47:14.899 INFO TcpConnection: 10.0.0.2:49077 -> 74.125.202.188:5228 registered Token(20)
2019-01-23 12:47:14.899 WARN TcpConnection: 10.0.0.2:49077 -> 74.125.202.188:5228 Unexpected first packet 3670782255; acking 582072943; flags=24
2019-01-23 12:47:14.899 INFO TcpConnection: 10.0.0.2:49077 -> 74.125.202.188:5228 Close
2019-01-23 12:47:14.899 INFO TcpConnection: 10.0.0.2:49077 -> 74.125.202.188:5228 deregistering Token(20)
2019-01-23 12:47:14.899 INFO TcpConnection: 10.0.0.2:49077 -> 74.125.202.188:5228 Open
2019-01-23 12:47:14.899 INFO TcpConnection: 10.0.0.2:49077 -> 74.125.202.188:5228 registered Token(21)
2019-01-23 12:47:14.899 WARN TcpConnection: 10.0.0.2:49077 -> 74.125.202.188:5228 Unexpected first packet 3670781719; acking 582072943; flags=16
2019-01-23 12:47:14.899 INFO TcpConnection: 10.0.0.2:49077 -> 74.125.202.188:5228 Close
2019-01-23 12:47:14.899 INFO TcpConnection: 10.0.0.2:49077 -> 74.125.202.188:5228 deregistering Token(21)
2019-01-23 12:47:14.899 INFO TcpConnection: 10.0.0.2:49077 -> 74.125.202.188:5228 Open
2019-01-23 12:47:14.899 INFO TcpConnection: 10.0.0.2:49077 -> 74.125.202.188:5228 registered Token(22)
2019-01-23 12:47:14.899 WARN TcpConnection: 10.0.0.2:49077 -> 74.125.202.188:5228 Unexpected first packet 3670781719; acking 582072943; flags=16
2019-01-23 12:47:14.900 INFO TcpConnection: 10.0.0.2:49077 -> 74.125.202.188:5228 Close
2019-01-23 12:47:14.900 INFO TcpConnection: 10.0.0.2:49077 -> 74.125.202.188:5228 deregistering Token(22)
2019-01-23 12:47:14.900 INFO UdpConnection: 10.0.0.2:11693 -> 8.8.8.8:53 Open
2019-01-23 12:47:14.900 INFO UdpConnection: 10.0.0.2:22101 -> 8.8.8.8:53 Open
2019-01-23 12:47:14.900 INFO UdpConnection: 10.0.0.2:13352 -> 8.8.8.8:53 Open
2019-01-23 12:47:14.900 INFO UdpConnection: 10.0.0.2:21693 -> 8.8.8.8:53 Open
2019-01-23 12:47:14.900 INFO UdpConnection: 10.0.0.2:6144 -> 8.8.8.8:53 Open
2019-01-23 12:47:14.900 INFO UdpConnection: 10.0.0.2:9459 -> 8.8.8.8:53 Open
2019-01-23 12:47:14.900 INFO TcpConnection: 10.0.0.2:49077 -> 74.125.202.188:5228 Open
2019-01-23 12:47:14.901 INFO TcpConnection: 10.0.0.2:49077 -> 74.125.202.188:5228 registered Token(29)
2019-01-23 12:47:14.901 WARN TcpConnection: 10.0.0.2:49077 -> 74.125.202.188:5228 Unexpected first packet 3670781719; acking 582072943; flags=16
2019-01-23 12:47:14.901 INFO TcpConnection: 10.0.0.2:49077 -> 74.125.202.188:5228 Close
2019-01-23 12:47:14.901 INFO TcpConnection: 10.0.0.2:49077 -> 74.125.202.188:5228 deregistering Token(29)
2019-01-23 12:47:14.901 INFO UdpConnection: 10.0.0.2:24504 -> 8.8.8.8:53 Open
2019-01-23 12:47:14.901 INFO UdpConnection: 10.0.0.2:15931 -> 8.8.8.8:53 Open
2019-01-23 12:47:14.901 INFO UdpConnection: 10.0.0.2:9946 -> 8.8.8.8:53 Open
2019-01-23 12:47:14.901 INFO UdpConnection: 10.0.0.2:7508 -> 8.8.8.8:53 Open
2019-01-23 12:47:14.902 INFO TcpConnection: 10.0.0.2:49077 -> 74.125.202.188:5228 Open
2019-01-23 12:47:14.902 INFO TcpConnection: 10.0.0.2:49077 -> 74.125.202.188:5228 registered Token(34)
2019-01-23 12:47:14.902 WARN TcpConnection: 10.0.0.2:49077 -> 74.125.202.188:5228 Unexpected first packet 3670781719; acking 582072943; flags=16
2019-01-23 12:47:14.902 INFO TcpConnection: 10.0.0.2:49077 -> 74.125.202.188:5228 Close
2019-01-23 12:47:14.902 INFO TcpConnection: 10.0.0.2:49077 -> 74.125.202.188:5228 deregistering Token(34)
2019-01-23 12:47:14.902 INFO UdpConnection: 10.0.0.2:16305 -> 8.8.8.8:53 Open
2019-01-23 12:47:14.903 INFO UdpConnection: 10.0.0.2:19627 -> 8.8.8.8:53 Open
2019-01-23 12:47:14.903 INFO TcpConnection: 10.0.0.2:49077 -> 74.125.202.188:5228 Open
2019-01-23 12:47:14.903 INFO TcpConnection: 10.0.0.2:49077 -> 74.125.202.188:5228 registered Token(37)
2019-01-23 12:47:14.903 WARN TcpConnection: 10.0.0.2:49077 -> 74.125.202.188:5228 Unexpected first packet 3670781719; acking 582072943; flags=16
2019-01-23 12:47:14.903 INFO TcpConnection: 10.0.0.2:49077 -> 74.125.202.188:5228 Close
2019-01-23 12:47:14.903 INFO TcpConnection: 10.0.0.2:49077 -> 74.125.202.188:5228 deregistering Token(37)
2019-01-23 12:47:14.903 INFO UdpConnection: 10.0.0.2:23655 -> 8.8.8.8:53 Open

2019-01-23 12:47:14.906 INFO TcpConnection: 10.0.0.2:40777 -> 173.194.198.114:80 Open
2019-01-23 12:47:14.906 INFO TcpConnection: 10.0.0.2:40777 -> 173.194.198.114:80 registered Token(56)
2019-01-23 12:47:14.906 INFO UdpConnection: 10.0.0.2:54096 -> 8.8.8.8:53 Open
2019-01-23 12:47:14.906 INFO UdpConnection: 10.0.0.2:7151 -> 8.8.8.8:53 Open
2019-01-23 12:47:14.906 INFO UdpConnection: 10.0.0.2:13555 -> 8.8.8.8:53 Open
2019-01-23 12:47:14.906 INFO TcpConnection: 10.0.0.2:49077 -> 74.125.202.188:5228 Open
2019-01-23 12:47:14.906 INFO TcpConnection: 10.0.0.2:49077 -> 74.125.202.188:5228 registered Token(60)
2019-01-23 12:47:14.906 WARN TcpConnection: 10.0.0.2:49077 -> 74.125.202.188:5228 Unexpected first packet 3670781719; acking 582072943; flags=16
2019-01-23 12:47:14.906 INFO TcpConnection: 10.0.0.2:49077 -> 74.125.202.188:5228 Close
2019-01-23 12:47:14.906 INFO TcpConnection: 10.0.0.2:49077 -> 74.125.202.188:5228 deregistering Token(60)
2019-01-23 12:47:14.907 INFO UdpConnection: 10.0.0.2:61766 -> 8.8.8.8:53 Open
2019-01-23 12:47:14.907 INFO UdpConnection: 10.0.0.2:51714 -> 8.8.8.8:53 Open
2019-01-23 12:47:14.907 INFO UdpConnection: 10.0.0.2:57687 -> 8.8.8.8:53 Open
2019-01-23 12:47:14.907 INFO UdpConnection: 10.0.0.2:26116 -> 8.8.8.8:53 Open
2019-01-23 12:47:14.907 INFO UdpConnection: 10.0.0.2:44216 -> 8.8.4.4:53 Open
2019-01-23 12:47:14.907 INFO UdpConnection: 10.0.0.2:36152 -> 8.8.8.8:53 Open
2019-01-23 12:47:14.907 INFO TcpConnection: 10.0.0.2:40778 -> 173.194.198.114:80 Open
2019-01-23 12:47:14.908 INFO TcpConnection: 10.0.0.2:40778 -> 173.194.198.114:80 registered Token(67)

2019-01-23 12:47:14.911 INFO TcpConnection: 10.0.0.2:49077 -> 74.125.202.188:5228 Open
2019-01-23 12:47:14.911 INFO TcpConnection: 10.0.0.2:49077 -> 74.125.202.188:5228 registered Token(88)
2019-01-23 12:47:14.911 WARN TcpConnection: 10.0.0.2:49077 -> 74.125.202.188:5228 Unexpected first packet 3670781719; acking 582072943; flags=16
2019-01-23 12:47:14.911 INFO TcpConnection: 10.0.0.2:49077 -> 74.125.202.188:5228 Close
2019-01-23 12:47:14.911 INFO TcpConnection: 10.0.0.2:49077 -> 74.125.202.188:5228 deregistering Token(88)

2019-01-23 12:47:14.919 INFO TcpConnection: 10.0.0.2:49077 -> 74.125.202.188:5228 Open
2019-01-23 12:47:14.919 INFO TcpConnection: 10.0.0.2:49077 -> 74.125.202.188:5228 registered Token(135)
2019-01-23 12:47:14.919 WARN TcpConnection: 10.0.0.2:49077 -> 74.125.202.188:5228 Unexpected first packet 3670781719; acking 582072943; flags=16
2019-01-23 12:47:14.919 INFO TcpConnection: 10.0.0.2:49077 -> 74.125.202.188:5228 Close
2019-01-23 12:47:14.919 INFO TcpConnection: 10.0.0.2:49077 -> 74.125.202.188:5228 deregistering Token(135)

2019-01-23 12:47:14.929 INFO TcpConnection: 10.0.0.2:40774 -> 173.194.198.114:80 Close
2019-01-23 12:47:14.929 INFO TcpConnection: 10.0.0.2:40774 -> 173.194.198.114:80 deregistering Token(3)
thread 'main' panicked at 'called `Result::unwrap()` on an `Err` value: Os { code: 2, kind: NotFound, message: "No such file or directory" }', src/libcore/result.rs:1009:5
note: Run with `RUST_BACKTRACE=1` for a backtrace.

[rom1v]

Could you try with this additional patch, as suggested here, please?

diff --git a/relay-rust/src/relay/tcp_connection.rs b/relay-rust/src/relay/tcp_connection.rs
index 3533ed7..75b8b9d 100644
--- a/relay-rust/src/relay/tcp_connection.rs
+++ b/relay-rust/src/relay/tcp_connection.rs
@@ -785,6 +785,7 @@ impl Connection for TcpConnection {
 
     fn close(&mut self, selector: &mut Selector) {
         cx_info!(target: TAG, &self.id, "Close");
+        assert!(!self.closed);
         self.closed = true;
         cx_info!(target: TAG, &self.id, "deregistering {:?}", self.token);
         selector.deregister(&self.stream, self.token).unwrap();