ExportWorker gets killed by Android 14 due to new excessive binder call tracker feature #129
Description
On Android 14 (Google Pixel stock firmware), the scheduled exports seem to be crashing, even though exports done manually via the UI work fine. When ExportWorker tries it run, it fails during the message export phase with a binder error:
--------- beginning of main
2023-10-21 00:03:56.047852 -0400 I/hub.tmo1.sms_ie(12068): Using CollectorTypeCC GC.
2023-10-21 00:03:56.054832 -0400 E/hub.tmo1.sms_ie(12068): Not starting debugger since process cannot load the jdwp agent.
2023-10-21 00:03:56.071151 -0400 D/CompatibilityChangeReporter(12068): Compat change id reported: 171979766; UID 10302; state: ENABLED
2023-10-21 00:03:56.071324 -0400 D/CompatibilityChangeReporter(12068): Compat change id reported: 242716250; UID 10302; state: ENABLED
2023-10-21 00:03:56.079462 -0400 D/ApplicationLoaders(12068): Returning zygote-cached class loader: /system_ext/framework/androidx.window.extensions.jar
2023-10-21 00:03:56.079519 -0400 D/ApplicationLoaders(12068): Returning zygote-cached class loader: /system_ext/framework/androidx.window.sidecar.jar
2023-10-21 00:03:56.091642 -0400 D/nativeloader(12068): Configuring clns-6 for other apk /data/app/~~-0i8XvqMvE7-tBm7q61ghw==/com.github.tmo1.sms_ie-YdWZ4xiIg2BCTfZVOeQIKQ==/base.apk. target_sdk_version=34, uses_libraries=, library_path=/data/app/~~-0i8XvqMvE7-tBm7q61ghw==/com.github.tmo1.sms_ie-YdWZ4xiIg2BCTfZVOeQIKQ==/lib/arm64, permitted_path=/data:/mnt/expand:/data/user/0/com.github.tmo1.sms_ie
2023-10-21 00:03:56.104880 -0400 V/GraphicsEnvironment(12068): Currently set values for:
2023-10-21 00:03:56.105009 -0400 V/GraphicsEnvironment(12068): angle_gl_driver_selection_pkgs=[]
2023-10-21 00:03:56.105040 -0400 V/GraphicsEnvironment(12068): angle_gl_driver_selection_values=[]
2023-10-21 00:03:56.105567 -0400 V/GraphicsEnvironment(12068): ANGLE GameManagerService for com.github.tmo1.sms_ie: false
2023-10-21 00:03:56.105675 -0400 V/GraphicsEnvironment(12068): com.github.tmo1.sms_ie is not listed in per-application setting
2023-10-21 00:03:56.105793 -0400 V/GraphicsEnvironment(12068): Neither updatable production driver nor prerelease driver is supported.
2023-10-21 00:03:56.161398 -0400 D/CompatibilityChangeReporter(12068): Compat change id reported: 160794467; UID 10302; state: ENABLED
2023-10-21 00:03:56.175046 -0400 D/CompatibilityChangeReporter(12068): Compat change id reported: 263076149; UID 10302; state: ENABLED
2023-10-21 00:03:56.226278 -0400 I/WM-WorkerWrapper(12068): Work [ id=48895fe2-ca9c-4a5a-956b-9ab885fb34ea, tags={ com.github.tmo1.sms_ie.ExportWorker, export } ] was cancelled
2023-10-21 00:03:56.226278 -0400 I/WM-WorkerWrapper(12068): java.util.concurrent.CancellationException: Task was cancelled.
2023-10-21 00:03:56.226278 -0400 I/WM-WorkerWrapper(12068): at y1.h.e(SourceFile:33)
2023-10-21 00:03:56.226278 -0400 I/WM-WorkerWrapper(12068): at y1.h.get(Unknown Source:21)
2023-10-21 00:03:56.226278 -0400 I/WM-WorkerWrapper(12068): at androidx.appcompat.widget.j.run(SourceFile:125)
2023-10-21 00:03:56.226278 -0400 I/WM-WorkerWrapper(12068): at androidx.appcompat.widget.j.a(SourceFile:1)
2023-10-21 00:03:56.226278 -0400 I/WM-WorkerWrapper(12068): at androidx.appcompat.widget.j.run(SourceFile:10)
2023-10-21 00:03:56.226278 -0400 I/WM-WorkerWrapper(12068): at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1145)
2023-10-21 00:03:56.226278 -0400 I/WM-WorkerWrapper(12068): at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:644)
2023-10-21 00:03:56.226278 -0400 I/WM-WorkerWrapper(12068): at java.lang.Thread.run(Thread.java:1012)
2023-10-21 00:03:56.248936 -0400 D/CompatibilityChangeReporter(12068): Compat change id reported: 194532703; UID 10302; state: ENABLED
2023-10-21 00:03:56.249372 -0400 D/CompatibilityChangeReporter(12068): Compat change id reported: 253665015; UID 10302; state: ENABLED
2023-10-21 00:03:56.295989 -0400 I/SMSIE (12068): Beginning messages export ...
2023-10-21 00:03:56.380188 -0400 E/JavaBinder(12068): !!! FAILED BINDER TRANSACTION !!! (parcel size = 352)
--------- beginning of system
2023-10-21 00:03:56.380548 -0400 I/ActivityThread(12068): Removing dead content provider:android.content.ContentProviderProxy@4cf8418
2023-10-21 00:03:56.380592 -0400 I/ActivityThread(12068): Removing dead content provider:android.content.ContentProviderProxy@4cf8418
Manually triggering with scheduled job with the following command also results in the same crash:
adb shell cmd jobscheduler run -f com.github.tmo1.sms_ie 8When the crash occurs, it leaves behind a partially written zip file with just the local zip entry header for messages.ndjson:
❯ zipdetails -vv --walk messages-2023-10-21.zip
00000 00003 00004 50 4B 03 04 LOCAL HEADER #1 04034B50 (67324752)
00004 00004 00001 14 Extract Zip Spec 14 (20) '2.0'
00005 00005 00001 00 Extract OS 00 (0) 'MS-DOS'
00006 00007 00002 08 08 General Purpose Flag 0808 (2056)
[Bits 1-2] 0 'Normal Compression'
[Bit 3] 1 'Streamed'
[Bit 11] 1 'Language Encoding'
00008 00009 00002 08 00 Compression Method 0008 (8) 'Deflated'
0000A 0000D 00004 7C 00 55 57 Last Mod Time 5755007C (1465188476) 'Fri Oct 20 20:03:56 2023'
0000E 00011 00004 00 00 00 00 CRC 00000000 (0)
00012 00015 00004 00 00 00 00 Compressed Length 00000000 (0)
00016 00019 00004 00 00 00 00 Uncompressed Length 00000000 (0)
0001A 0001B 00002 0F 00 Filename Length 000F (15)
0001C 0001D 00002 00 00 Extra Length 0000 (0)
0001E 0002C 0000F 6D 65 73 73 Filename 'messages.ndjson'
61 67 65 73
2E 6E 64 6A
73 6F 6E
#
# ERROR: Local Directory exists, but Central Directory not found
#
# Error Count: 1
#
# Done
I'm not sure why this is happening yet. I'll see if I can reproduce the problem this weekend with a debug build to get a better stack trace. (The logs above are from the precompiled 2.2.0 APK from the Github release page.)