03-02-2021 01:41 PM
This is both a bug report and possibly a pointer to a relatively simple fix for what is quite an annoying problem. Hopefully the devs read this!
My Quest: Quest 1, latest OS (25.0.0.77)
My laptop: Manjaro Linux 20.2.1, kernel 5.10.18
What I'm trying to do: I have a WebXR app running on port 3000 on my laptop. I want to use adb reverse over WiFi to go to localhost:3000 in Oculus Browser and debug the app.
What works:
- connecting with adb and running "adb reverse tcp:3000 tcp:3000" over USB
- connecting with adb over WiFi and using adb shell, etc, to interact with the device over WiFi
What doesn't work:
- running "adb reverse tcp:3000 tcp:3000" when the Quest is only connected over WiFi
- running the command, even with USB transport explicitly specified, whenever I'm connected to the Quest over USB and WiFi simultaneously
In both cases, the error I get is "more than one device/emulator" - but I believe this is not due to my setup, but rather a bug in the adb daemon on Quest (see below for my analysis and potential fix)
Unless there's some other explanation I'm missing, this error makes it impossible to debug WebXR apps over WiFi, which you'll admit is a bit annoying given that this is a standalone VR headset! Would be amazing if someone could look into this and figure out if a fix can be deployed.
Explanation:
The error message was initially confusing (I definitely don't have any more devices/emulators), but after some debugging it turned out that the error message is actually sent back from adbd on Quest rather than generated locally on my laptop.
My analysis is based on looking through Android 7 adb source in the official repos - assuming adb wasn't heavily modified by Facebook, the problem I found in the base code might still be there, which would explain what I'm seeing.
Let's say I am connected to the Quest with both USB and WiFi. I want to run adb reverse, so I need to explicitly specify one of the two adb devices.
Given that the USB connection has transport ID 1, I run:
adb -t 1 reverse tcp:3000 tcp:3000
and I get
adb: error: more than one device/emulator
The logs (see below) suggest that the command is sent, but then the error appears on the Quest side and is sent back as a fail.
What happens on the device side that causes the error? Based on the Android 7 source, the reverse service accepts the command, but then calls handle_forward_request with transport type set to kTransportAny - essentially discarding the information about which transport channel the request came through. Compare this with the newer adb reverse service on Android 11 which accepts a transport channel and passes it further.
If the transport type is dropped like this, but there is a connection over both USB and WiFi, then even though I managed to send the reverse command to the Quest, the adbd on the device has two connections to choose from to establish the tunnel, and consequently generates the error in acquire_one_transport .
The last question is: why does it also fail after I unplug the USB cable and try to run the reverse over WiFi? I'm guessing there might be some software/hardware handling the USB port on the Oculus that makes it seem to adbd that it's always connected to something over USB, and hence - even if for me it seems like the only connection between Quest and laptop is WiFi, the USB transport never disappears on the Quest side and adbd still struggles to decide which channel to choose for the forward command. This would explain why the reverse starts erroring whenever there's a WiFi connection - no matter which channel I use to send the command.
Fix?
The solution would be seemingly simple - change the adb code in these three lines:
service_to_fd() - reverse_service call
- to pass the incoming transport type and transport serial to handle_forward_request - adbd should then use the same channel the request came on, whether that's USB or WiFi.
Debug logs:
This is the trace output from the adb host server running on my laptop, after I run the adb reverse command.
adb D 03-01 22:11:30 256230 256230 fdevent_epoll.cpp:174] (fdevent 2: fd 9 R) got events 0x1
adb D 03-01 22:11:30 256230 256230 sockets.cpp:399] LS(37): created (fd=3)
adb D 03-01 22:11:30 256230 256230 sockets.cpp:903] Connecting to smart socket
adb D 03-01 22:11:30 256230 256230 sockets.cpp:891] Creating smart socket
adb D 03-01 22:11:30 256230 256230 sockets.cpp:898] SS(0)
adb D 03-01 22:11:30 256230 256230 fdevent_epoll.cpp:174] (fdevent 76: fd 3 R) got events 0x1
adb D 03-01 22:11:30 256230 256230 sockets.cpp:353] LS(37): event_func(fd=3(==3), ev=0001)
adb D 03-01 22:11:30 256230 256230 sockets.cpp:164] LS(37): post adb_read(fd=3,...) r=16 (errno=0) avail=1048576
adb D 03-01 22:11:30 256230 256230 sockets.cpp:164] LS(37): post adb_read(fd=3,...) r=-1 (errno=11) avail=1048560
adb D 03-01 22:11:30 256230 256230 sockets.cpp:180] LS(37): fd=3 post avail loop. r=-1 is_eof=0 forced_eof=0
adb D 03-01 22:11:30 256230 256230 sockets.cpp:722] SS(0): enqueue 16
adb D 03-01 22:11:30 256230 256230 sockets.cpp:742] SS(0): len is 12
adb D 03-01 22:11:30 256230 256230 sockets.cpp:751] SS(0): 'host:version'
adb D 03-01 22:11:30 256230 256230 adb.cpp:1099] handle_host_request(version)
adb D 03-01 22:11:30 256230 256230 adb_io.cpp:107] writex: fd=3 len=4 4f4b4159 OKAY
adb D 03-01 22:11:30 256230 256230 adb_io.cpp:107] writex: fd=3 len=8 3030303430303239 00040029
adb V 03-01 22:11:30 256230 256230 sockets.cpp:792] SS(0): handled host service 'version'
adb D 03-01 22:11:30 256230 256230 sockets.cpp:881] SS(0): closed
adb D 03-01 22:11:30 256230 256230 sockets.cpp:314] entered local_socket_close. LS(37) fd=3
adb D 03-01 22:11:30 256230 256230 sockets.cpp:300] LS(37): destroying fde.fd=3
adb D 03-01 22:11:30 256230 256230 sockets.cpp:336] LS(37): closed
adb D 03-01 22:11:30 256230 256230 sockets.cpp:190] LS(37): fd=3 post peer->enqueue(). r=-1
adb D 03-01 22:11:30 256230 256230 fdevent_epoll.cpp:174] (fdevent 77: fd 3 R) got events 0x5
adb D 03-01 22:11:30 256230 256230 fdevent_epoll.cpp:174] (fdevent 2: fd 9 R) got events 0x1
adb D 03-01 22:11:30 256230 256230 sockets.cpp:399] LS(38): created (fd=3)
adb D 03-01 22:11:30 256230 256230 sockets.cpp:903] Connecting to smart socket
adb D 03-01 22:11:30 256230 256230 sockets.cpp:891] Creating smart socket
adb D 03-01 22:11:30 256230 256230 sockets.cpp:898] SS(0)
adb D 03-01 22:11:30 256230 256230 fdevent_epoll.cpp:174] (fdevent 78: fd 3 R) got events 0x1
adb D 03-01 22:11:30 256230 256230 sockets.cpp:353] LS(38): event_func(fd=3(==3), ev=0001)
adb D 03-01 22:11:30 256230 256230 sockets.cpp:164] LS(38): post adb_read(fd=3,...) r=23 (errno=0) avail=1048576
adb D 03-01 22:11:30 256230 256230 sockets.cpp:164] LS(38): post adb_read(fd=3,...) r=-1 (errno=11) avail=1048553
adb D 03-01 22:11:30 256230 256230 sockets.cpp:180] LS(38): fd=3 post avail loop. r=-1 is_eof=0 forced_eof=0
adb D 03-01 22:11:30 256230 256230 sockets.cpp:722] SS(0): enqueue 23
adb D 03-01 22:11:30 256230 256230 sockets.cpp:742] SS(0): len is 19
adb D 03-01 22:11:30 256230 256230 sockets.cpp:751] SS(0): 'host:transport-id:1'
adb D 03-01 22:11:30 256230 256230 adb.cpp:1099] handle_host_request(transport-id:1)
adb D 03-01 22:11:30 256230 256230 adb_io.cpp:107] writex: fd=3 len=4 4f4b4159 OKAY
adb D 03-01 22:11:30 256230 256230 sockets.cpp:796] SS(0): okay transport
adb D 03-01 22:11:30 256230 256230 sockets.cpp:190] LS(38): fd=3 post peer->enqueue(). r=0
adb D 03-01 22:11:30 256230 256230 fdevent_epoll.cpp:174] (fdevent 78: fd 3 R) got events 0x1
adb D 03-01 22:11:30 256230 256230 sockets.cpp:353] LS(38): event_func(fd=3(==3), ev=0001)
adb D 03-01 22:11:30 256230 256230 sockets.cpp:164] LS(38): post adb_read(fd=3,...) r=37 (errno=0) avail=262144
adb D 03-01 22:11:30 256230 256230 sockets.cpp:164] LS(38): post adb_read(fd=3,...) r=-1 (errno=11) avail=262107
adb D 03-01 22:11:30 256230 256230 sockets.cpp:180] LS(38): fd=3 post avail loop. r=-1 is_eof=0 forced_eof=0
adb D 03-01 22:11:30 256230 256230 sockets.cpp:722] SS(0): enqueue 37
adb D 03-01 22:11:30 256230 256230 sockets.cpp:742] SS(0): len is 33
adb D 03-01 22:11:30 256230 256230 sockets.cpp:751] SS(0): 'reverse:forward:tcp:3000;tcp:3000'
adb D 03-01 22:11:30 256230 256230 sockets.cpp:504] Connect_to_remote call RS(38) fd=3
adb V 03-01 22:11:30 256230 256230 sockets.cpp:507] LS(38: connect(reverse:forward:tcp:3000;tcp:3000)
adb D 03-01 22:11:30 256230 256230 transport.cpp:557] 192.168.178.31:5555: to remote: [OPEN] arg0=38 arg1=0 (len=34) 726576657273653a666f72776172643a reverse:forward: [truncated]
adb D 03-01 22:11:30 256230 256230 sockets.cpp:881] SS(0): closed
adb D 03-01 22:11:30 256230 256230 sockets.cpp:190] LS(38): fd=3 post peer->enqueue(). r=1
adb D 03-01 22:11:30 256230 256530 adb_io.cpp:107] writex: fd=13 len=24 4f50454e260000000000000022000000 OPEN&......."... [truncated]
adb D 03-01 22:11:30 256230 256530 adb_io.cpp:107] writex: fd=13 len=34 726576657273653a666f72776172643a reverse:forward: [truncated]
adb D 03-01 22:11:30 256230 256529 adb_io.cpp:97] readx: fd=13 wanted=24 got=24 4f4b4159180000002600000000000000 OKAY....&....... [truncated]
adb D 03-01 22:11:30 256230 256529 adb_io.cpp:81] readx: fd=13 wanted=0
adb D 03-01 22:11:30 256230 256529 adb_io.cpp:97] readx: fd=13 wanted=0 got=0
adb D 03-01 22:11:30 256230 256529 transport.cpp:802] 192.168.178.31:5555: from remote: [OKAY] arg0=24 arg1=38 (len=0)
adb D 03-01 22:11:30 256230 256529 adb_io.cpp:81] readx: fd=13 wanted=24
adb D 03-01 22:11:30 256230 256230 fdevent_epoll.cpp:174] (fdevent 0: fd 7 R) got events 0x1
adb D 03-01 22:11:30 256230 256230 adb.cpp:347] handle_packet() OKAY
adb D 03-01 22:11:30 256230 256230 sockets.cpp:499] RS(24): created
adb D 03-01 22:11:30 256230 256230 adb_io.cpp:107] writex: fd=3 len=4 4f4b4159 OKAY
adb D 03-01 22:11:30 256230 256529 adb_io.cpp:97] readx: fd=13 wanted=24 got=24 57525445180000002600000025000000 WRTE....&...%... [truncated]
adb D 03-01 22:11:30 256230 256529 adb_io.cpp:81] readx: fd=13 wanted=37
adb D 03-01 22:11:30 256230 256529 adb_io.cpp:97] readx: fd=13 wanted=37 got=37 4641494c303031646d6f726520746861 FAIL001dmore tha [truncated]
adb D 03-01 22:11:30 256230 256529 transport.cpp:802] 192.168.178.31:5555: from remote: [WRTE] arg0=24 arg1=38 (len=37) 4641494c303031646d6f726520746861 FAIL001dmore tha [truncated]
adb D 03-01 22:11:30 256230 256529 adb_io.cpp:81] readx: fd=13 wanted=24
adb D 03-01 22:11:30 256230 256529 adb_io.cpp:97] readx: fd=13 wanted=24 got=24 434c5345180000002600000000000000 CLSE....&....... [truncated]
adb D 03-01 22:11:30 256230 256529 adb_io.cpp:81] readx: fd=13 wanted=0
adb D 03-01 22:11:30 256230 256529 adb_io.cpp:97] readx: fd=13 wanted=0 got=0
adb D 03-01 22:11:30 256230 256529 transport.cpp:802] 192.168.178.31:5555: from remote: [CLSE] arg0=24 arg1=38 (len=0)
adb D 03-01 22:11:30 256230 256529 adb_io.cpp:81] readx: fd=13 wanted=24
adb D 03-01 22:11:30 256230 256230 fdevent_epoll.cpp:174] (fdevent 0: fd 7 R) got events 0x1
adb D 03-01 22:11:30 256230 256230 adb.cpp:347] handle_packet() WRTE
adb D 03-01 22:11:30 256230 256230 sockets.cpp:222] LS(38): enqueue 37
adb D 03-01 22:11:30 256230 256230 adb.cpp:483] Enqueue the socket
adb D 03-01 22:11:30 256230 256230 adb.cpp:181] Calling send_ready
adb D 03-01 22:11:30 256230 256230 transport.cpp:557] 192.168.178.31:5555: to remote: [OKAY] arg0=38 arg1=24 (len=0)
adb D 03-01 22:11:30 256230 256230 adb.cpp:347] handle_packet() CLSE
adb D 03-01 22:11:30 256230 256230 sockets.cpp:314] entered local_socket_close. LS(38) fd=3
adb D 03-01 22:11:30 256230 256230 sockets.cpp:317] LS(38): closing peer. peer->id=24 peer->fd=-1
adb D 03-01 22:11:30 256230 256230 sockets.cpp:461] entered remote_socket_shutdown RS(24) CLOSE fd=-1 peer->fd=3
adb D 03-01 22:11:30 256230 256230 transport.cpp:557] 192.168.178.31:5555: to remote: [CLSE] arg0=38 arg1=24 (len=0)
adb D 03-01 22:11:30 256230 256230 sockets.cpp:478] entered remote_socket_close RS(24) CLOSE fd=-1 peer->fd=-1
adb D 03-01 22:11:30 256230 256230 sockets.cpp:479] RS(24): closed
adb D 03-01 22:11:30 256230 256530 adb_io.cpp:107] writex: fd=13 len=24 4f4b4159260000001800000000000000 OKAY&........... [truncated]
adb D 03-01 22:11:30 256230 256230 sockets.cpp:300] LS(38): destroying fde.fd=3
adb D 03-01 22:11:30 256230 256530 adb_io.cpp:107] writex: fd=13 len=24 434c5345260000001800000000000000 CLSE&........... [truncated]
adb D 03-01 22:11:30 256230 256230 sockets.cpp:336] LS(38): closed
adb D 03-01 22:11:30 256230 256230 fdevent_epoll.cpp:174] (fdevent 79: fd 3 R) got events 0x5
adb D 03-01 22:11:30 256230 256529 adb_io.cpp:97] readx: fd=13 wanted=24 got=24 434c5345180000002600000000000000 CLSE....&....... [truncated]
adb D 03-01 22:11:30 256230 256529 adb_io.cpp:81] readx: fd=13 wanted=0
adb D 03-01 22:11:30 256230 256529 adb_io.cpp:97] readx: fd=13 wanted=0 got=0
adb D 03-01 22:11:30 256230 256529 transport.cpp:802] 192.168.178.31:5555: from remote: [CLSE] arg0=24 arg1=38 (len=0)
adb D 03-01 22:11:30 256230 256529 adb_io.cpp:81] readx: fd=13 wanted=24
adb D 03-01 22:11:30 256230 256230 fdevent_epoll.cpp:174] (fdevent 0: fd 7 R) got events 0x1
adb D 03-01 22:11:30 256230 256230 adb.cpp:347] handle_packet() CLSE
Note the line:
adb D 03-01 22:11:30 256230 256529 transport.cpp:802] 192.168.178.31:5555: from remote: [WRTE] arg0=24 arg1=38 (len=37) 4641494c303031646d6f726520746861 FAIL001dmore tha [truncated]
And particularly the last bits "FAIL001dmore tha [truncated]" - the adbd on the Quest sends back this error.
03-02-2021 01:47 PM
I actually stumbled upon the bug ticket in original Android where this issue was fixed: https://issuetracker.google.com/issues/37066218
Hopefully that's useful - the changeset is indeed quite small