Assigned
Status Update
No update yet.
Comments
an...@google.com
Successful workaround: Kill the ADB process if it does not return within 120 seconds.
ak...@meta.com
I've seen the same problem on rare occasion -- I believe on both 32-bit and 64-bit machines (all running Ubuntu).
This scenario is from an Amazon EC2 instance running Ubuntu 10.04.
== Long-running processes involved:
* PID 4440 adb (daemon)
* PID 5396 adb -s localhost:52384 install -r MyApp-debug.apk
* PID 5216 emulator -ports 38007,52384 -no-boot-anim -prop persist.sys.language=de -prop persist.sys.country=DE -avd hudson_de-DE_240_WVGA_android-8 -no-window
== Commands run:
* adb daemon was (presumably) already running
* emulator is started as above
* `adb connect localhost:52384`
* `adb logcat -v time` is left running in the background
* `adb install` below is run once emulator is ready
adb -s localhost:52384 install -r MyApp-debug.apk
116 KB/s (57642 bytes in 0.482s)
pkg: /data/local/tmp/MyApp-debug.apk
Success
** hangs here indefinitely without returning (despite "Success") **
== Investigation
* `ps` shows that the hung `adb install` process has PID 5396
root@ip-10-228-211-159:~# strace -p 5396
Process 5396 attached - interrupt to quit
read(4, ^C <unfinished ...>
Process 5396 detached
* adb is blocked reading from FD 4 -- what is that?
root@ip-10-228-211-159:~# ls -l /proc/5396/fd/
total 0
lr-x------ 1 root root 64 2010-09-12 12:26 0 -> pipe:[135089]
l-wx------ 1 root root 64 2010-09-12 12:26 1 -> pipe:[135090]
l-wx------ 1 root root 64 2010-09-12 12:26 2 -> pipe:[135090]
lrwx------ 1 root root 64 2010-09-12 12:26 3 -> socket:[135142]
lrwx------ 1 root root 64 2010-09-12 12:26 4 -> socket:[136177]
root@ip-10-228-211-159:~# lsof | grep 136177
adb 5396 root 4u IPv4 136177 0t0 TCP localhost:51221->localhost:5037 (ESTABLISHED)
root@ip-10-228-211-159:~# netstat -antp | grep LISTEN
tcp 0 0127.0.0.1:5037 0.0.0.0:* LISTEN 4440/adb
tcp 0 00.0.0.0:22 0.0.0.0:* LISTEN 406/sshd
tcp 0 0127.0.0.1:38007 0.0.0.0:* LISTEN 5216/emulator
tcp 0 0127.0.0.1:52384 0.0.0.0:* LISTEN 5216/emulator
* So we're waiting to read from port 5037 -- the adb daemon (PID 4440)?
root@ip-10-228-211-159:~# strace -tt -T -p 4440
Process 4440 attached - interrupt to quit
12:28:55.909470 select(26, [4 5 14 18 25], [], [], NULL^C <unfinished ...>
Process 4440 detached
* It's blocking in select(), waiting for FD 26 to become ready. What's that?
root@ip-10-228-211-159:~# ls -l /proc/4440/fd/
total 0
lr-x------ 1 root root 64 2010-09-12 12:27 0 -> /dev/null
l-wx------ 1 root root 64 2010-09-12 12:27 1 -> /tmp/adb.log
lrwx------ 1 root root 64 2010-09-12 12:27 14 -> socket:[133791]
lrwx------ 1 root root 64 2010-09-12 12:27 15 -> socket:[133790]
lrwx------ 1 root root 64 2010-09-12 12:27 16 -> socket:[133792]
lrwx------ 1 root root 64 2010-09-12 12:27 18 -> socket:[133949]
l-wx------ 1 root root 64 2010-09-12 12:27 2 -> /tmp/adb.log
lrwx------ 1 root root 64 2010-09-12 12:27 25 -> socket:[136178]
lrwx------ 1 root root 64 2010-09-12 12:27 3 -> socket:[127504]
lrwx------ 1 root root 64 2010-09-12 12:27 4 -> socket:[127505]
lrwx------ 1 root root 64 2010-09-12 12:27 5 -> socket:[127506]
lr-x------ 1 root root 64 2010-09-12 12:27 6 -> /dev/null
l-wx------ 1 root root 64 2010-09-12 12:27 7 -> /tmp/adb.log
root@ip-10-228-211-159:~# ls -l /proc/4440/fd/26
ls: cannot access /proc/4440/fd/26: No such file or directory
* Hmm.. it doesn't exist?
* Ok, let's see what the server does when we manually kill the `adb install` process (PID 5396), at time 12:32:50:
root@ip-10-228-211-159:~# strace -tt -T -p 4440
Process 4440 attached - interrupt to quit
12:32:43.366720 select(26, [4 5 14 18 25], [], [], NULL) = 1 (in [25]) <7.274112>
12:32:50.641019 read(25, "", 4096) = 0 <0.000015>
12:32:50.641596 write(14, "\20R\6\t", 4) = 4 <0.000061>
12:32:50.641711 close(25) = 0 <0.000058>
12:32:50.641805 select(26, [4 5 14 18], [], [], NULL) = 1 (in [14]) <0.002506>
12:32:50.644385 read(14, "\20r\6\t", 4) = 4 <0.000025>
12:32:50.644470 select(26, [4 5 14 18], [], [], NULL) = 1 (in [5]) <0.281615>
12:32:50.926206 accept(5, {sa_family=AF_INET, sin_port=htons(44907), sin_addr=inet_addr("127.0.0.1")}, [16]) = 8 <0.000043>
12:32:50.926370 setsockopt(8, SOL_SOCKET, SO_RCVBUF, [65536], 4) = 0 <0.000030>
12:32:50.926477 fcntl64(8, F_SETFL, O_RDONLY|O_NONBLOCK) = 0 <0.000053>
12:32:50.926651 select(26, [4 5 8 14 18], [], [], NULL) = 1 (in [8]) <0.000015>
12:32:50.926727 read(8, "000chost:version", 4096) = 16 <0.000020>
12:32:50.926787 read(8, 0x9067244, 4080) = -1 EAGAIN (Resource temporarily unavailable) <0.000013>
12:32:50.926860 write(8, "OKAY0004001a", 12) = 12 <0.000037>
12:32:50.926943 close(8) = 0 <0.000053>
12:32:50.927031 select(19, [4 5 14 18], [], [], NULL) = 1 (in [5]) <0.000037>
12:32:50.927144 accept(5, {sa_family=AF_INET, sin_port=htons(44908), sin_addr=inet_addr("127.0.0.1")}, [16]) = 8 <0.000035>
12:32:50.927251 setsockopt(8, SOL_SOCKET, SO_RCVBUF, [65536], 4) = 0 <0.000029>
12:32:50.927334 fcntl64(8, F_SETFL, O_RDONLY|O_NONBLOCK) = 0 <0.000029>
12:32:50.927433 select(19, [4 5 8 14 18], [], [], NULL) = 1 (in [8]) <0.000030>
12:32:50.927526 read(8, "001fhost:disconnect:localhost:52"..., 4096) = 35 <0.000033>
12:32:50.927623 read(8, 0x9067257, 4061) = -1 EAGAIN (Resource temporarily unavailable) <0.000028>
12:32:50.927729 shutdown(15, 2 /* send and receive */) = 0 <0.000053>
12:32:50.927825 close(15) = 0 <0.000028>
12:32:50.934829 close(16) = 0 <0.000062>
12:32:50.934959 write(3, "\260\237\5\t\0\0\0\0", 8) = 8 <0.000036>
12:32:50.935064 write(8, "OKAY0000", 8) = 8 <0.000048>
12:32:50.935154 close(8) = 0 <0.000032>
12:32:50.935233 select(19, [4 5 14 18], [], [], NULL) = 2 (in [4 14]) <0.000015>
12:32:50.935290 read(4, "\260\237\5\t\0\0\0\0", 8) = 8 <0.000141>
12:32:50.935470 close(14PANIC: attached pid 4440 exited with 255
<unfinished ... exit status 255>
* Not so good.
This scenario is from an Amazon EC2 instance running Ubuntu 10.04.
== Long-running processes involved:
* PID 4440 adb (daemon)
* PID 5396 adb -s localhost:52384 install -r MyApp-debug.apk
* PID 5216 emulator -ports 38007,52384 -no-boot-anim -prop persist.sys.language=de -prop persist.sys.country=DE -avd hudson_de-DE_240_WVGA_android-8 -no-window
== Commands run:
* adb daemon was (presumably) already running
* emulator is started as above
* `adb connect localhost:52384`
* `adb logcat -v time` is left running in the background
* `adb install` below is run once emulator is ready
adb -s localhost:52384 install -r MyApp-debug.apk
116 KB/s (57642 bytes in 0.482s)
pkg: /data/local/tmp/MyApp-debug.apk
Success
** hangs here indefinitely without returning (despite "Success") **
== Investigation
* `ps` shows that the hung `adb install` process has PID 5396
root@ip-10-228-211-159:~# strace -p 5396
Process 5396 attached - interrupt to quit
read(4, ^C <unfinished ...>
Process 5396 detached
* adb is blocked reading from FD 4 -- what is that?
root@ip-10-228-211-159:~# ls -l /proc/5396/fd/
total 0
lr-x------ 1 root root 64 2010-09-12 12:26 0 -> pipe:[135089]
l-wx------ 1 root root 64 2010-09-12 12:26 1 -> pipe:[135090]
l-wx------ 1 root root 64 2010-09-12 12:26 2 -> pipe:[135090]
lrwx------ 1 root root 64 2010-09-12 12:26 3 -> socket:[135142]
lrwx------ 1 root root 64 2010-09-12 12:26 4 -> socket:[136177]
root@ip-10-228-211-159:~# lsof | grep 136177
adb 5396 root 4u IPv4 136177 0t0 TCP localhost:51221->localhost:5037 (ESTABLISHED)
root@ip-10-228-211-159:~# netstat -antp | grep LISTEN
tcp 0 0
tcp 0 0
tcp 0 0
tcp 0 0
* So we're waiting to read from port 5037 -- the adb daemon (PID 4440)?
root@ip-10-228-211-159:~# strace -tt -T -p 4440
Process 4440 attached - interrupt to quit
12:28:55.909470 select(26, [4 5 14 18 25], [], [], NULL^C <unfinished ...>
Process 4440 detached
* It's blocking in select(), waiting for FD 26 to become ready. What's that?
root@ip-10-228-211-159:~# ls -l /proc/4440/fd/
total 0
lr-x------ 1 root root 64 2010-09-12 12:27 0 -> /dev/null
l-wx------ 1 root root 64 2010-09-12 12:27 1 -> /tmp/adb.log
lrwx------ 1 root root 64 2010-09-12 12:27 14 -> socket:[133791]
lrwx------ 1 root root 64 2010-09-12 12:27 15 -> socket:[133790]
lrwx------ 1 root root 64 2010-09-12 12:27 16 -> socket:[133792]
lrwx------ 1 root root 64 2010-09-12 12:27 18 -> socket:[133949]
l-wx------ 1 root root 64 2010-09-12 12:27 2 -> /tmp/adb.log
lrwx------ 1 root root 64 2010-09-12 12:27 25 -> socket:[136178]
lrwx------ 1 root root 64 2010-09-12 12:27 3 -> socket:[127504]
lrwx------ 1 root root 64 2010-09-12 12:27 4 -> socket:[127505]
lrwx------ 1 root root 64 2010-09-12 12:27 5 -> socket:[127506]
lr-x------ 1 root root 64 2010-09-12 12:27 6 -> /dev/null
l-wx------ 1 root root 64 2010-09-12 12:27 7 -> /tmp/adb.log
root@ip-10-228-211-159:~# ls -l /proc/4440/fd/26
ls: cannot access /proc/4440/fd/26: No such file or directory
* Hmm.. it doesn't exist?
* Ok, let's see what the server does when we manually kill the `adb install` process (PID 5396), at time 12:32:50:
root@ip-10-228-211-159:~# strace -tt -T -p 4440
Process 4440 attached - interrupt to quit
12:32:43.366720 select(26, [4 5 14 18 25], [], [], NULL) = 1 (in [25]) <7.274112>
12:32:50.641019 read(25, "", 4096) = 0 <0.000015>
12:32:50.641596 write(14, "\20R\6\t", 4) = 4 <0.000061>
12:32:50.641711 close(25) = 0 <0.000058>
12:32:50.641805 select(26, [4 5 14 18], [], [], NULL) = 1 (in [14]) <0.002506>
12:32:50.644385 read(14, "\20r\6\t", 4) = 4 <0.000025>
12:32:50.644470 select(26, [4 5 14 18], [], [], NULL) = 1 (in [5]) <0.281615>
12:32:50.926206 accept(5, {sa_family=AF_INET, sin_port=htons(44907), sin_addr=inet_addr("127.0.0.1")}, [16]) = 8 <0.000043>
12:32:50.926370 setsockopt(8, SOL_SOCKET, SO_RCVBUF, [65536], 4) = 0 <0.000030>
12:32:50.926477 fcntl64(8, F_SETFL, O_RDONLY|O_NONBLOCK) = 0 <0.000053>
12:32:50.926651 select(26, [4 5 8 14 18], [], [], NULL) = 1 (in [8]) <0.000015>
12:32:50.926727 read(8, "000chost:version", 4096) = 16 <0.000020>
12:32:50.926787 read(8, 0x9067244, 4080) = -1 EAGAIN (Resource temporarily unavailable) <0.000013>
12:32:50.926860 write(8, "OKAY0004001a", 12) = 12 <0.000037>
12:32:50.926943 close(8) = 0 <0.000053>
12:32:50.927031 select(19, [4 5 14 18], [], [], NULL) = 1 (in [5]) <0.000037>
12:32:50.927144 accept(5, {sa_family=AF_INET, sin_port=htons(44908), sin_addr=inet_addr("127.0.0.1")}, [16]) = 8 <0.000035>
12:32:50.927251 setsockopt(8, SOL_SOCKET, SO_RCVBUF, [65536], 4) = 0 <0.000029>
12:32:50.927334 fcntl64(8, F_SETFL, O_RDONLY|O_NONBLOCK) = 0 <0.000029>
12:32:50.927433 select(19, [4 5 8 14 18], [], [], NULL) = 1 (in [8]) <0.000030>
12:32:50.927526 read(8, "001fhost:disconnect:localhost:52"..., 4096) = 35 <0.000033>
12:32:50.927623 read(8, 0x9067257, 4061) = -1 EAGAIN (Resource temporarily unavailable) <0.000028>
12:32:50.927729 shutdown(15, 2 /* send and receive */) = 0 <0.000053>
12:32:50.927825 close(15) = 0 <0.000028>
12:32:50.934829 close(16) = 0 <0.000062>
12:32:50.934959 write(3, "\260\237\5\t\0\0\0\0", 8) = 8 <0.000036>
12:32:50.935064 write(8, "OKAY0000", 8) = 8 <0.000048>
12:32:50.935154 close(8) = 0 <0.000032>
12:32:50.935233 select(19, [4 5 14 18], [], [], NULL) = 2 (in [4 14]) <0.000015>
12:32:50.935290 read(4, "\260\237\5\t\0\0\0\0", 8) = 8 <0.000141>
12:32:50.935470 close(14PANIC: attached pid 4440 exited with 255
<unfinished ... exit status 255>
* Not so good.
an...@google.com
[Comment deleted]
Description
We are seeing this in production and we would appreciate advice on what to look for in Logcat to debug this or other ideas how to know what could be wrong.
Also, I'd love a code pointer to where this error is fired in Android Source Code, so we know exactly under which conditions
Attached logs from production, but there isn't much there and I couldn't find better one right now
Also attached adb bugreport where I forced repro it by not drawing to Surface attached to MediaRecorder
Here are some of them, would "0 frames to dump timeStamps in Video track" be good candidate to know nothing was drawn to MediaRecorder?
2025-02-26 12:54:08.446 1443-18407 MPEG4Writer mediaserver E The number of recorded samples is 0
2025-02-26 12:54:08.446 1443-18407 MPEG4Writer mediaserver E 0 frames to dump timeStamps in Video track
2025-02-26 12:54:08.446 1443-18407 MediaWriter mediaserver V Track event err/info msg:100, trackId:1, type:100,val:-1007
2025-02-26 12:54:08.446 1443-18407 MPEG4Writer mediaserver I Received total/0-length (0/0) buffers and encoded 0 frames. - Video
2025-02-26 12:54:08.454 1290-4372 ExynosC2H2...cComponent sam...hardware.media.c2@1.2-service I [release] component is released
2025-02-26 12:54:08.455 1443-18384 AidlBufferPool mediaserver D Destruction - bufferpool2 0xb4000079867aebe8 cached: 0/0M, 0/0% in use; allocs: 0, 0% recycled; transfers: 0, 0% unfetched
2025-02-26 12:54:08.456 1290-4372 AidlBufferPool sam...hardware.media.c2@1.2-service D Destruction - bufferpool2 0xb4000072ced68848 cached: 0/0M, 0/0% in use; allocs: 0, 0% recycled; transfers: 0, 0% unfetched
2025-02-26 12:54:08.457 1443-18382 MediaCodecSource mediaserver I encoder (video) stopped
2025-02-26 12:54:08.457 1443-18382 MediaCodecSource mediaserver I source (video) stopped
2025-02-26 12:54:08.457 1443-1443 MPEG4Writer mediaserver D Video track source stopped
2025-02-26 12:54:08.457 1443-1443 MPEG4Writer mediaserver D Video track stopped. Status:-1007. Stop source
2025-02-26 12:54:08.457 1443-1443 MPEG4Writer mediaserver W Condition trackErr == OK failed Video track stopped with an error
2025-02-26 12:54:08.457 1443-1443 MPEG4Writer mediaserver D Audio track stopping. Stop source
2025-02-26 12:54:08.457 1443-1443 MPEG4Writer mediaserver D Audio track source stopping
2025-02-26 12:54:08.457 1443-18382 MediaCodecSource mediaserver I encoder (audio) stopping
2025-02-26 12:54:08.457 1443-18382 MediaCodecSource mediaserver I encoder (audio) already stopped
2025-02-26 12:54:08.457 1443-1443 MPEG4Writer mediaserver D Audio track source stopped
2025-02-26 12:54:08.457 1443-1443 MPEG4Writer mediaserver D Audio track stopped. Status:0. Stop source
2025-02-26 12:54:08.457 1443-1443 MPEG4Writer mediaserver D Duration from tracks range is [0, 2111999] us
2025-02-26 12:54:08.457 1443-18403 MPEG4Writer mediaserver D 0 chunks are written in the last batch
2025-02-26 12:54:08.457 1443-1443 MPEG4Writer mediaserver D WriterThread stopped. Status:0
2025-02-26 12:54:08.457 1443-1443 MPEG4Writer mediaserver I Adjust the moov start time from 5933 us -> 5933 us
2025-02-26 12:54:08.458 1443-1443 MPEG4Writer mediaserver I MOOV atom was written to the file
2025-02-26 12:54:08.458 1443-1443 MPEG4Writer mediaserver D release()
2025-02-26 12:54:08.458 1443-1443 MPEG4Writer mediaserver D ftruncate mPreAllocateFileEndOffset:31829 mOffset:1397 mMdatEndOffset:29177 diff:2652
2025-02-26 12:54:08.462 1443-1443 MPEG4Writer mediaserver D final fsync() takes 4 ms, file size 29177
2025-02-26 12:54:08.462 1290-22461 ECOSession sam...hardware.media.c2@1.2-service I ECOSession destroyed with w: 1072, h: 1920, isCameraRecording: 1
2025-02-26 12:54:08.463 1443-1443 MPEG4Writer mediaserver D MP4WtrCtrlHlpLooper stopped
2025-02-26 12:54:08.463 1443-1443 MPEG4Writer mediaserver D Top 5 write durations(microseconds): #1:73 #2:76 #3:78 #4:88 #5:95
2025-02-26 12:54:08.463 1443-1443 MPEG4Writer mediaserver D reset()
2025-02-26 12:54:08.463 1443-1443 MPEG4Writer mediaserver D Video track stopping. Stop source
2025-02-26 12:54:08.463 1443-1443 MPEG4Writer mediaserver E Stop() called but track is not started or stopped
2025-02-26 12:54:08.463 1443-1443 MPEG4Writer mediaserver D Audio track stopping. Stop source
2025-02-26 12:54:08.463 1443-1443 MPEG4Writer mediaserver E Stop() called but track is not started or stopped
2025-02-26 12:54:08.466 13207-13416 MediaRecorder com.instagram.basel E stop failed: -1007