x/mobile/app: app crashes with DeadObjectException on Android

[rakyll]

Applications seem to be throwing an exception during pause, makes them crash on resume. The case is consistently reproducible with the basic example.

1. Launch the basic example on an Android device
2. Press back to pause it
3. Bring app to the foreground

Application crashes with the following log.

W/ActivityManager(  510): Exception thrown during pause
W/ActivityManager(  510): android.os.DeadObjectException
W/ActivityManager(  510):   at android.os.BinderProxy.transactNative(Native Method)
W/ActivityManager(  510):   at android.os.BinderProxy.transact(Binder.java:496)
W/ActivityManager(  510):   at android.app.ApplicationThreadProxy.schedulePauseActivity(ApplicationThreadNative.java:701)
W/ActivityManager(  510):   at com.android.server.am.ActivityStack.startPausingLocked(ActivityStack.java:852)
W/ActivityManager(  510):   at com.android.server.am.ActivityStack.finishActivityLocked(ActivityStack.java:2754)
W/ActivityManager(  510):   at com.android.server.am.ActivityStack.finishTopRunningActivityLocked(ActivityStack.java:2611)
W/ActivityManager(  510):   at com.android.server.am.ActivityStackSupervisor.finishTopRunningActivityLocked(ActivityStackSupervisor.java:2453)
W/ActivityManager(  510):   at com.android.server.am.ActivityManagerService.handleAppCrashLocked(ActivityManagerService.java:11511)
W/ActivityManager(  510):   at com.android.server.am.ActivityManagerService.makeAppCrashingLocked(ActivityManagerService.java:11408)
W/ActivityManager(  510):   at com.android.server.am.ActivityManagerService.crashApplication(ActivityManagerService.java:12087)
W/ActivityManager(  510):   at com.android.server.am.ActivityManagerService.handleApplicationCrashInner(ActivityManagerService.java:11603)
W/ActivityManager(  510):   at com.android.server.am.NativeCrashListener$NativeCrashReporter.run(NativeCrashListener.java:86)

cc/ @crawshaw @hyangah

[crawshaw]

Following your steps does not reproduce the bug on my android device.

[rakyll]

I want to give it another with a fresh install but am blocked by #10760.

[rakyll]

The bug is not reproducible prior to golang/mobile@5cddc14.

[rakyll]

It's coming from fps.Draw from debug.DrawFPS. @nigeltao, can you take a look?

[nigeltao]

I'm really not familiar with the Java binding stuff at all. I think @crawshaw is the best person to look at this.

[crawshaw]

I still can't reproduce this. I need more information.

[rakyll]

Not reproducible against go version devel +0b36e12 Mon May 25 20:53:26 2015 +0000 darwin/amd64, closing.

[rakyll]

This is happening again with the audio example on pause.

W/ActivityManager(  463): Exception thrown during pause
W/ActivityManager(  463): android.os.DeadObjectException
W/ActivityManager(  463):   at android.os.BinderProxy.transactNative(Native Method)
W/ActivityManager(  463):   at android.os.BinderProxy.transact(Binder.java:496)
W/ActivityManager(  463):   at android.app.ApplicationThreadProxy.schedulePauseActivity(ApplicationThreadNative.java:704)
W/ActivityManager(  463):   at com.android.server.am.ActivityStack.startPausingLocked(ActivityStack.java:825)
W/ActivityManager(  463):   at com.android.server.am.ActivityStack.finishActivityLocked(ActivityStack.java:2726)
W/ActivityManager(  463):   at com.android.server.am.ActivityStack.finishTopRunningActivityLocked(ActivityStack.java:2583)
W/ActivityManager(  463):   at com.android.server.am.ActivityStackSupervisor.finishTopRunningActivityLocked(ActivityStackSupervisor.java:2497)
W/ActivityManager(  463):   at com.android.server.am.ActivityManagerService.handleAppCrashLocked(ActivityManagerService.java:11500)
W/ActivityManager(  463):   at com.android.server.am.ActivityManagerService.makeAppCrashingLocked(ActivityManagerService.java:11397)
W/ActivityManager(  463):   at com.android.server.am.ActivityManagerService.crashApplication(ActivityManagerService.java:12081)
W/ActivityManager(  463):   at com.android.server.am.ActivityManagerService.handleApplicationCrashInner(ActivityManagerService.java:11592)
W/ActivityManager(  463):   at com.android.server.am.NativeCrashListener$NativeCrashReporter.run(NativeCrashListener.java:86)

[nigeltao]

I'm still not very familiar with the Java binding stuff. Perhaps @hyangah has ideas on where to start looking?

FYI re fps.Draw, one thing is that some code a little bit earlier than that was taking longer than it should (12ms instead of <1ms). That was fixed in https://go-review.googlesource.com/#/c/11299/

[nigeltao]

BTW what makes you say that it's coming from fps.Draw from debug.DrawFPS? I don't see that in the stack trace.

[hyangah]

It usually happens when the go side has crashed. Often the useful error log (if any) is before the android.os.DeadObjectException.

The audio app crashed in my nexus5 when the app was brought back to foreground again - at least, in my case, it doesn't look like a runtime issue.

W/Adreno-ES20( 3609): : GL_INVALID_VALUE
I/Keyboard.Facilitator(31137): onFinishInput()
I/ActivityManager(  740): Displayed org.golang.todo.audio/android.app.NativeActivity: +96ms
V/PhoneStatusBar(  889): setLightsOn(true)
E/Go      ( 3609): panic: runtime error: index out of range
E/Go      ( 3609): goroutine 10 [running]:
E/Go      ( 3609): golang.org/x/mobile/gl.TexSubImage2D(0xde1, 0x0, 0x0, 0x0, 0x1, 0x1, 0x1908, 0x1401, 0x0, 0x0, ...)
E/Go      ( 3609):      /Users/hakim/Local/gopaths/ws1/src/golang.org/x/mobile/gl/gl.go:1650 +0x84
E/Go      ( 3609): golang.org/x/mobile/gl/glutil.(*Image).Upload(0x941ce330)
E/Go      ( 3609):      /Users/hakim/Local/gopaths/ws1/src/golang.org/x/mobile/gl/glutil/glimage.go:215 +0xc8
E/Go      ( 3609): golang.org/x/mobile/app/debug.DrawFPS(0x0, 0x0, 0x0)
E/Go      ( 3609):      /Users/hakim/Local/gopaths/ws1/src/golang.org/x/mobile/app/debug/fps.go:77 +0x430
E/Go      ( 3609): main.draw(0x0, 0x0, 0x0)
E/Go      ( 3609):      /Users/hakim/Local/gopaths/ws1/src/golang.org/x/mobile/example/audio/main.go:97 +0x174
E/Go      ( 3609): golang.org/x/mobile/app.Run.func1(0xa434b000, 0xa41fa9c8)
E/Go      ( 3609):      /Users/hakim/Local/gopaths/ws1/src/golang.org/x/mobile/app/app.go:168 +0x2c0
E/Go      ( 3609): golang.org/x/mobile/app.main.func1(0x93e74400, 0x93e8a440)
E/Go      ( 3609):      /Users/hakim/Local/gopaths/ws1/src/golang.org/x/mobile/app/android.go:216 +0x64
E/Go      ( 3609): created by golang.org/x/mobile/app.main
E/Go      ( 3609):      /Users/hakim/Local/gopaths/ws1/src/golang.org/x/mobile/app/android.go:218 +0xb4
E/Go      ( 3609): goroutine 8 [running, locked to thread]:
E/Go      ( 3609):      goroutine running on other thread; stack unavailable
E/Go      ( 3609): created by golang.org/x/mobile/app.callMain
E/Go      ( 3609):      /Users/hakim/Local/gopaths/ws1/src/golang.org/x/mobile/app/android.go:80 +0x404
E/Go      ( 3609): goroutine 17 [syscall, locked to thread]:
E/Go      ( 3609): runtime.goexit()
E/Go      ( 3609):      /Users/hakim/Local/goroots/tip/go/src/runtime/asm_arm.s:1016 +0x4
E/Go      ( 3609): goroutine 18 [syscall, locked to thread]:
E/Go      ( 3609): runtime.goexit()
E/Go      ( 3609):      /Users/hakim/Local/goroots/tip/go/src/runtime/asm_arm.s:1016 +0x4
E/Go      ( 3609): goroutine 5 [select]:
E/Go      ( 3609): golang.org/x/mobile/app.pump.func1(0x93e381d0, 0x93e8a140)
E/Go      ( 3609):      /Users/hakim/Local/gopaths/ws1/src/golang.org/x/mobile/app/app.go:106 +0x4ac
E/Go      ( 3609): created by golang.org/x/mobile/app.pump
E/Go      ( 3609):      /Users/hakim/Local/gopaths/ws1/src/golang.org/x/mobile/app/app.go:135 +0x88
E/Go      ( 3609): goroutine 6 [syscall]:
E/Go      ( 3609): syscall.Syscall(0x3, 0x17, 0x93eb6000, 0x400, 0x0, 0x0, 0x0)
E/Go      ( 3609):      /Users/hakim/Local/goroots/tip/go/src/syscall/asm_linux_arm.s:17 +0x8
E/Go      ( 3609): syscall.read(0x17, 0x93eb6000, 0x400, 0x400, 0x0, 0x0, 0x0)
E/Go      ( 3609):      /Users/hakim/Local/goroots/tip/go/src/syscall/zsyscall_linux_arm.go:783 +0x78
E/Go      ( 3609): syscall.Read(0x17, 0x93eb6000, 0x400, 0x400, 0x0, 0x0, 0x0)
E/Go      ( 3609):      /Users/hakim/Local/goroots/tip/go/src/syscall/syscall_unix.go:160 +0x4c
E/Go      ( 3609): os.(*File).read(0x93e381d8, 0x93eb6000, 0x400, 0x400, 0x0, 0x0, 0x0)
E/Go      ( 3609):      /Users/hakim/Local/goroots/tip/go/src/os/file_unix.go:211 +0x54
E/Go      ( 3609): os.(*File).Read(0x93e381d8, 0x93eb6000, 0x400, 0x400, 0x0, 0x0, 0x0)
E/Go      ( 3609):      /Users/hakim/Local/goroots/tip/go/src/os/file.go:95 +0x7c
E/Go      ( 3609): bufio.(*Reader).fill(0x93e4677c)
E/Go      ( 3609):      /Users/hakim/Local/goroots/tip/go/src/bufio/bufio.go:97 +0x1c4
E/Go      ( 3609): bufio.(*Reader).ReadSlice(0x93e4677c, 0x40a, 0x0, 0x0, 0x0, 0x0, 0x0)
E/Go      ( 3609):      /Users/hakim/Local/goroots/tip/go/src/bufio/bufio.go:328 +0x264
E/Go      ( 3609): bufio.(*Reader).ReadLine(0x93e4677c, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0)
E/Go      ( 3609):      /Users/hakim/Local/goroots/tip/go/src/bufio/bufio.go:357 +0x60
E/Go      ( 3609): golang.org/x/mobile/app.lineLog(0x93e381d8, 0x6)
E/Go      ( 3609):      /Users/hakim/Local/gopaths/ws1/src/golang.org/x/mobile/app/stdio_android.go:50 +0xe0
E/Go      ( 3609): created by golang.org/x/mobile/app.init.1
E/Go      ( 3609):      /Users/hakim/Local/gopaths/ws1/src/golang.org/x/mobile/app/stdio_android.go:74 +0x104
E/Go      ( 3609): goroutine 7 [syscall]:
E/Go      ( 3609): syscall.Syscall(0x3, 0x19, 0x93eca000, 0x400, 0x0, 0x0, 0x0)
E/Go      ( 3609):      /Users/hakim/Local/goroots/tip/go/src/syscall/asm_linux_arm.s:17 +0x8
E/Go      ( 3609): syscall.read(0x19, 0x93eca000, 0x400, 0x400, 0x0, 0x0, 0x0)
E/Go      ( 3609):      /Users/hakim/Local/goroots/tip/go/src/syscall/zsyscall_linux_arm.go:783 +0x78
E/Go      ( 3609): syscall.Read(0x19, 0x93eca000, 0x400, 0x400, 0x0, 0x0, 0x0)
E/Go      ( 3609):      /Users/hakim/Local/goroots/tip/go/src/syscall/syscall_unix.go:160 +0x4c
E/Go      ( 3609): os.(*File).read(0x93e381e8, 0x93eca000, 0x400, 0x400, 0x0, 0x0, 0x0)
E/Go      ( 3609):      /Users/hakim/Local/goroots/tip/go/src/os/file_unix.go:211 +0x54
E/Go      ( 3609): os.(*File).Read(0x93e381e8, 0x93eca000, 0x400, 0x400, 0x0, 0x0, 0x0)
E/Go      ( 3609):      /Users/hakim/Local/goroots/tip/go/src/os/file.go:95 +0x7c
E/Go      ( 3609): bufio.(*Reader).fill(0x93e46f7c)
E/Go      ( 3609):      /Users/hakim/Local/goroots/tip/go/src/bufio/bufio.go:97 +0x1c4
E/Go      ( 3609): bufio.(*Reader).ReadSlice(0x93e46f7c, 0x40a, 0x0, 0x0, 0x0, 0x0, 0x0)
E/Go      ( 3609):      /Users/hakim/Local/goroots/tip/go/src/bufio/bufio.go:328 +0x264
E/Go      ( 3609): bufio.(*Reader).ReadLine(0x93e46f7c, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0)
E/Go      ( 3609):      /Users/hakim/Local/goroots/tip/go/src/bufio/bufio.go:357 +0x60
E/Go      ( 3609): golang.org/x/mobile/app.lineLog(0x93e381e8, 0x4)
E/Go      ( 3609):      /Users/hakim/Local/gopaths/ws1/src/golang.org/x/mobile/app/stdio_android.go:50 +0xe0
E/Go      ( 3609): created by golang.org/x/mobile/app.init.1
E/Go      ( 3609):      /Users/hakim/Local/gopaths/ws1/src/golang.org/x/mobile/app/stdio_android.go:81 +0x194
E/Go      ( 3609): goroutine 9 [chan receive]:
E/Go      ( 3609): golang.org/x/mobile/app.Run.func1(0xa434b000, 0xa41fa9c8)
E/Go      ( 3609):      /Users/hakim/Local/gopaths/ws1/src/golang.org/x/mobile/app/app.go:148 +0x8c
E/Go      ( 3609): golang.org/x/mobile/app.main.func1(0x93e743a0, 0x93e8a400)
E/Go      ( 3609):      /Users/hakim/Local/gopaths/ws1/src/golang.org/x/mobile/app/android.go:216 +0x64
E/Go      ( 3609): created by golang.org/x/mobile/app.main
E/Go      ( 3609):      /Users/hakim/Local/gopaths/ws1/src/golang.org/x/mobile/app/android.go:218 +0xb4
E/Go      ( 3609): goroutine 35 [chan receive, locked to thread]:
E/Go      ( 3609): golang.org/x/mobile/app.main(0x93e74400)
E/Go      ( 3609):      /Users/hakim/Local/gopaths/ws1/src/golang.org/x/mobile/app/android.go:220 +0xe4
E/Go      ( 3609): golang.org/x/mobile/app.Main(0x93e74400)
E/Go      ( 3609):      /Users/hakim/Local/gopaths/ws1/src/golang.org/x/mobile/app/app.go:16 +0x1c
E/Go      ( 3609): golang.org/x/mobile/app.Run(0xa416cbe0, 0xa416cbe4, 0xa416cbdc, 0x0, 0x0)
E/Go      ( 3609):      /Users/hakim/Local/gopaths/ws1/src/golang.org/x/mobile/app/app.go:177 +0x7c
E/Go      ( 3609): main.main()
E/Go      ( 3609):      /Users/hakim/Local/gopaths/ws1/src/golang.org/x/mobile/example/audio/main.go:71 +0x50
E/Go      ( 3609): golang.org/x/mobile/app/internal/callfn.CallFn(0xa3fbd6b4)
E/Go      ( 3609):      /Users/hakim/Local/gopaths/ws1/src/golang.org/x/mobile/app/internal/callfn/callfn_arm.s:10 +0x18
E/Go      ( 3609): created by golang.org/x/mobile/app.callMain
E/Go      ( 3609):      /Users/hakim/Local/gopaths/ws1/src/golang.org/x/mobile/app/android.go:80 +0x404

[rakyll]

BTW what makes you say that it's coming from fps.Draw from debug.DrawFPS? I don't see that in the stack trace.

I commented out lines one by one to see it is coming from the debug package. I haven't been able to see any Go trace the way @hyangah did yet.

[nigeltao]

I'm unable to repro this. Does anyone have a reliable repro?

Huh, @hakim's logs says "main.draw(0x0, 0x0, 0x0)" which suggests that the app was sent a 0-width 0-height configuration, which looks suspicious. @hakim, do you know if your logs were before or after https://go-review.googlesource.com/11668 landed, which removed the freetype code from DrawFPS?

Possibly related, or possibly separate, it's OK to pass a nil slice as the final arg to gl.TexImage2D but not for gl.TexSubImage2D, and the latter will panic on "&data[0]". Perhaps @crawshaw would know whether it's meaningful for TexSubImage2D (or indeed any other gl function like BufferData or ReadPixels) to be able to take an empty slice.

[crawshaw]

I'm also unable to reproduce this, but a lot has changed since this bug was filed.

To your (I believe separate question) @nigeltao, in OpenGL ES 2, glTexImage2D can take a nil slice in which case a texture is allocated but not initialized. The same allocation is not (at least conceptually) possible with glTextSubImage2D, so I believe passing in nil data is an error. It's also not documented as supported.

These particular functions get more complex in OpenGL ES 3. If a buffer is bound to GL_PIXEL_UNPACK_BUFFER, then the GLvoid* data is not treated as a pointer. Instead, it is a byte offset. So a zero value for the C data value makes sense for glTexSubImage2D, but the Go []byte is inadequate. It's really impressive how many ways these functions get overloaded.