Reverse tethering fails intermittently

[d-cui]

I'm experiencing an issue where networking over Gnirehtet fails intermittently (roughly every 7 minutes, but not exactly).

I have an Android tablet connected to a Linux machine over USB. The Linux machine acts as a webserver and serves assets to the tablet at port 8080.

Every second, I use adb shell curl --max-time 1 10.0.2.2:8080 to confirm that networking is still working as intended. However, roughly every 7 minutes (not exactly), networking fails.

I can resolve the issue by restarting Gnirehtet and reloading the webpage on the tablet (I am automating this right now), however this is undesirable as it leads to significant downtime.

Gnirehtet logs always look like this (an invalid packet is dropped every 4-6 seconds). There's no change when networking appears to fail:

[GNIREHTET] 2019-01-22 01:52:27.811 INFO TcpConnection: 10.0.0.2:33336 -> 10.0.2.2:8080 Open
[GNIREHTET] 2019-01-22 01:52:27.861 INFO TcpConnection: 10.0.0.2:33336 -> 10.0.2.2:8080 Close
[GNIREHTET] 2019-01-22 01:52:28.788 INFO TcpConnection: 10.0.0.2:33337 -> 10.0.2.2:8080 Open
[GNIREHTET] 2019-01-22 01:52:28.836 INFO TcpConnection: 10.0.0.2:33337 -> 10.0.2.2:8080 Close
[GNIREHTET] 2019-01-22 01:52:29.821 INFO TcpConnection: 10.0.0.2:33338 -> 10.0.2.2:8080 Open
[GNIREHTET] 2019-01-22 01:52:29.871 INFO TcpConnection: 10.0.0.2:33338 -> 10.0.2.2:8080 Close
[GNIREHTET] 2019-01-22 01:52:30.799 INFO TcpConnection: 10.0.0.2:33339 -> 10.0.2.2:8080 Open
[GNIREHTET] 2019-01-22 01:52:30.851 INFO TcpConnection: 10.0.0.2:33339 -> 10.0.2.2:8080 Close

Logcat doesn't look unusual either, except for the intermittent Gnirehtet restarts. The output of adb logcat *:D | grep gnirehtet is:

01-22 01:41:18.923  3713  3713 D GnirehtetService: Received request com.genymobile.gnirehtet.START_VPN
01-22 01:41:23.389  2616  2616 D StatusBar: onNotificationPosted: StatusBarNotification(pkg=com.genymobile.gnirehtet user=UserHandle{0} id=42 tag=null key=0|com.genymobile.gnirehtet|42|null|10107: Notification(pri=0 contentView=null vibrate=null sound=null defaults=0x0 flags=0x62 color=0x00000000 actions=1 vis=PRIVATE))
01-22 01:48:00.214  2616  2616 D StatusBar: onNotificationPosted: StatusBarNotification(pkg=com.genymobile.gnirehtet user=UserHandle{0} id=42 tag=null key=0|com.genymobile.gnirehtet|42|null|10107: Notification(pri=0 contentView=null vibrate=null sound=null defaults=0x0 flags=0x62 color=0x00000000 actions=1 vis=PRIVATE))
01-22 01:48:00.783  3713  3713 D GnirehtetControlReceiver: Received request com.genymobile.gnirehtet.START
01-22 01:48:00.786  3713  3713 D GnirehtetService: Received request com.genymobile.gnirehtet.START_VPN
01-22 01:48:05.223  2616  2616 D StatusBar: onNotificationPosted: StatusBarNotification(pkg=com.genymobile.gnirehtet user=UserHandle{0} id=42 tag=null key=0|com.genymobile.gnirehtet|42|null|10107: Notification(pri=0 contentView=null vibrate=null sound=null defaults=0x0 flags=0x62 color=0x00000000 actions=1 vis=PRIVATE))
01-22 01:54:40.518  2616  2616 D StatusBar: onNotificationPosted: StatusBarNotification(pkg=com.genymobile.gnirehtet user=UserHandle{0} id=42 tag=null key=0|com.genymobile.gnirehtet|42|null|10107: Notification(pri=0 contentView=null vibrate=null sound=null defaults=0x0 flags=0x62 color=0x00000000 actions=1 vis=PRIVATE))
01-22 01:54:41.062  3713  3713 D GnirehtetControlReceiver: Received request com.genymobile.gnirehtet.START
01-22 01:54:41.065  3713  3713 D GnirehtetService: Received request com.genymobile.gnirehtet.START_VPN
01-22 01:54:45.523  2616  2616 D StatusBar: onNotificationPosted: StatusBarNotification(pkg=com.genymobile.gnirehtet user=UserHandle{0} id=42 tag=null key=0|com.genymobile.gnirehtet|42|null|10107: Notification(pri=0 contentView=null vibrate=null sound=null defaults=0x0 flags=0x62 color=0x00000000 actions=1 vis=PRIVATE))
01-22 02:01:21.731  2616  2616 D StatusBar: onNotificationPosted: StatusBarNotification(pkg=com.genymobile.gnirehtet user=UserHandle{0} id=42 tag=null key=0|com.genymobile.gnirehtet|42|null|10107: Notification(pri=0 contentView=null vibrate=null sound=null defaults=0x0 flags=0x62 color=0x00000000 actions=1 vis=PRIVATE))
01-22 02:01:22.296  3713  3713 D GnirehtetControlReceiver: Received request com.genymobile.gnirehtet.START
01-22 02:01:22.299  3713  3713 D GnirehtetService: Received request com.genymobile.gnirehtet.START_VPN
01-22 02:01:26.731  2616  2616 D StatusBar: onNotificationPosted: StatusBarNotification(pkg=com.genymobile.gnirehtet user=UserHandle{0} id=42 tag=null key=0|com.genymobile.gnirehtet|42|null|10107: Notification(pri=0 contentView=null vibrate=null sound=null defaults=0x0 flags=0x62 color=0x00000000 actions=1 vis=PRIVATE))

I've checked the number of TCP connections formed over Gnirehtet, and it doesn't look like there's a connection leak there. Memory usage of Gnirehtet also appears to be stable in htop.

Any ideas on how to proceed with further debugging? It feels like something is filling up because the timing is so consistent -- possibly some type of logging, data usage, etc?

[rom1v]

Gnirehtet logs always look like this

You should enable debug logs here.

Every second, I use adb shell curl --max-time 1 10.0.2.2:8080 to confirm that networking is still working as intended. However, roughly every 7 minutes (not exactly), networking fails.

When this happens, does curl hang or return with an error?

Gnirehtet logs always look like this (an invalid packet is dropped every 4-6 seconds). There's no change when networking appears to fail:

Do you still see Open/Close connections when it "fails"? What failure do you observe then?

Does this happen both with the Rust and the Java version of gnirhetet?

It feels like something is filling up because the timing is so consistent -- possibly some type of logging, data usage, etc?

I don't know what could cause this.

[d-cui]

Thanks @rom1v ! I think I've figured out a solution to the bug, but am not sure what the underlying cause is.

I recompiled the Rust version of gnirehtet using loglevel Debug. Immediately, the issue started presenting itself with higher frequency. Instead of failing every 6-7 minutes, the networking would fail every 15-20s.

My suspicion is that there is some buffer being overflown when the output to stdout is not read.

Original code (causes intermittent networking failures):

shell_string = os.path.join(
            HOME, "drivers/gnirehtet-rust-linux64/gnirehtet") + " autorun"
        self.gnirehtet_proc = subprocess.Popen(
            shell_string, shell=True, stdout=subprocess.PIPE, stderr=subprocess.STDOUT)

Fix:

        """
        Reads output from the gnirehtet process.
        """
        # Continuously call readline until the output is an empty bytestring
        # This means that stdout has been closed, which happens after the child exits
        for line in iter(self.gnirehtet_proc.stdout.readline, b''):
            rospy.loginfo("[GNIREHTET] {}".format(line))

# Start a new instance of gnirehtet and spy on it
        shell_string = os.path.join(
            HOME, "drivers/gnirehtet-rust-linux64/gnirehtet") + " autorun"
        self.gnirehtet_proc = subprocess.Popen(
            shell_string, shell=True, stdout=subprocess.PIPE, stderr=subprocess.STDOUT)

        reader = threading.Thread(target=self.gnirehtet_reader)
        reader.start()

When the networking "fails," the curl command hangs. Let me know if you have any thoughts!

[rom1v]

My suspicion is that there is some buffer being overflown when the output to stdout is not read.

Ah, yes, the stdout buffer is limited, any write will block once full.

If you don't need logs, just pass stdout=None to subprocess.Popen.