Android App Support crashes after starting because VM runs out of heap

Regardless, with the update to 5.0.0.76, it started it working yet again. Just as with the previous update to 5.0.0.73, although there is no mention of relevant AAS changes for my Xperia 10 V this time.

So, will the issue return in a few weeks? Time will tell. I will mark it as fixed if 5.1 is out and it is all still good. I can keep marking and then unmarking updates as solutions :grimacing:

And the issue is returned! :face_exhaling:
First, I had a few days where AAS would crash during the day, and now it won’t start at all anymore. It is either the system_server or android.bg that encounters a Java OutOfMemoryError exception after which the Android Runtime terminates.
It doesn’t seem like my device really runs out of memory, it has 6 GB.

I probably/maybe should have taken the time to remove some apps that have big background processes that they spin up after AAS has started?

Found out from /opt/appsupport/build.prop that the heapsize limit is indeed 256 MB.
Unfortunately, that file indicates how AAS is built, so no configuration file to change here.
I am pretty sure that it is the issue, but not what causes a lot of memory to be used during start.
A more elaborate log shows how it grows:

# appsupport-attach /system/bin/logcat | grep -E 'system_server|AndroidRuntime'
[...]
03-27 20:27:07.567   221   230 I system_server: Background young concurrent copying GC freed 6788(481KB) AllocSpace objects, 0(0B) LOS objects, 0% free, 69MB/69MB, paused 272us,79us total 121.408ms
03-27 20:27:07.740   221   230 I system_server: Background concurrent copying GC freed 8816(4669KB) AllocSpace objects, 2(104KB) LOS objects, 6% free, 80MB/86MB, paused 1.339ms,456us total 166.545ms
03-27 20:27:07.965   221   230 I system_server: Background concurrent copying GC freed 2106(379KB) AllocSpace objects, 0(0B) LOS objects, 5% free, 113MB/119MB, paused 122us,95us total 135.045ms
03-27 20:27:08.194   221   230 I system_server: Background concurrent copying GC freed 286(3431KB) AllocSpace objects, 6(120KB) LOS objects, 3% free, 148MB/154MB, paused 108us,87us total 150.655ms
03-27 20:27:08.486   221   230 I system_server: Background concurrent copying GC freed 545(4985KB) AllocSpace objects, 2(40KB) LOS objects, 3% free, 170MB/176MB, paused 106us,825us total 206.121ms
03-27 20:27:08.820   221   230 I system_server: Background young concurrent copying GC freed 29902(2228KB) AllocSpace objects, 20(1040KB) LOS objects, 0% free, 187MB/187MB, paused 148us,90us total 137.401ms
03-27 20:27:09.106   221   230 I system_server: Background concurrent copying GC freed 21337(4773KB) AllocSpace objects, 10(520KB) LOS objects, 2% free, 221MB/227MB, paused 136us,90us total 285.856ms
03-27 20:27:09.320   221   246 I system_server: Waiting for a blocking GC Alloc
03-27 20:27:09.507   221   230 I system_server: Clamp target GC heap from 258MB to 256MB
03-27 20:27:09.507   221   230 I system_server: Background concurrent copying GC freed 1535(4045KB) AllocSpace objects, 0(0B) LOS objects, 1% free, 252MB/256MB, paused 82us,61us total 314.401ms
03-27 20:27:09.507   221   246 I system_server: WaitForGcToComplete blocked Alloc on Background for 186.841ms
03-27 20:27:09.507   221   246 I system_server: Starting a blocking GC Alloc
03-27 20:27:09.524   221   246 I system_server: Starting a blocking GC Alloc
03-27 20:27:09.524   221   246 I system_server: Starting a blocking GC Alloc
03-27 20:27:09.547   221   246 I system_server: Alloc young concurrent copying GC freed 0(22KB) AllocSpace objects, 0(0B) LOS objects, 0% free, 254MB/256MB, paused 72us,71us total 23.192ms
03-27 20:27:09.547   221   246 I system_server: Forcing collection of SoftReferences for 4748KB allocation
03-27 20:27:09.547   221   246 I system_server: Starting a blocking GC Alloc
03-27 20:27:09.905   221   235 I system_server: Waiting for a blocking GC Alloc
[...]
03-27 20:27:10.070   221   246 I system_server: Clamp target GC heap from 260MB to 256MB
03-27 20:27:10.070   221   246 I system_server: Alloc concurrent copying GC freed 20220(904KB) AllocSpace objects, 0(0B) LOS objects, 0% free, 254MB/256MB, paused 74us,71us total 522.577ms
03-27 20:27:10.070   221   235 I system_server: WaitForGcToComplete blocked Alloc on Alloc for 165.667ms
03-27 20:27:10.070   221   235 I system_server: Starting a blocking GC Alloc
03-27 20:27:10.070   221   246 W system_server: Throwing OutOfMemoryError "Failed to allocate a 4861960 byte allocation with 1598048 free bytes and 1560KB until OOM, target footprint 268435456, growth limit 268435456" (VmSize 17240904 kB)
03-27 20:27:10.070   221   251 I system_server: WaitForGcToComplete blocked Alloc on Alloc for 163.643ms
03-27 20:27:10.070   221   251 I system_server: Starting a blocking GC Alloc
03-27 20:27:10.071   221   246 E AndroidRuntime: *** FATAL EXCEPTION IN SYSTEM PROCESS: android.bg
03-27 20:27:10.071   221   246 E AndroidRuntime: java.lang.OutOfMemoryError: Failed to allocate a 4861960 byte allocation with 1598048 free bytes and 1560KB until OOM, target footprint 268435456, growth limit 268435456
2 Likes

Hello,
how to debug this? First time after the update everything worked. Now after a reboot the Appsupport shows briefly as started and then starts again.

You can use the terminal or SSH to view the logs when starting. What I do is: start AAS from the Settings app and then call logcat as root (via devel-su) as you can see in the output above.

Let me know if you see the have the same or similar results!

2 Likes

AAS can be configured via config files that are read by scripts that will generate additional config for Android before it starts. I’d be very surprised if there’s no way to override even build.prop values.

1 Like

I don’t know enough about how AAS works on how that should translates to any config.
I cannot find the word heapsize/dalvik anywhere else in /opt nor in /etc.

(Oh and don’t (rip)grep that word in /, it will reboot the phone :sweat_smile:)

1 Like

I think this is what as discussed here, long time ago…
https://forum.sailfishos.org/t/reliable-crash-sfos-through-grep-command/10069/

Thanks for the link, an interesting deep dive.

I managed fixing my AppSupport restart loop. For some reason I had Android Auto (gearhead) installed and that tried to request privileges:
E AndroidRuntime: java.lang.IllegalStateException: Signature|privileged permissions not in privapp-permissions allowlist: {com.google.android.projection.gearhead (/data/app/

Moving that app out of /home/.appsupport/instance/defaultuser/data/app fixed my AppSupport.

2 Likes

I’m having similar issues on two X10iii devices (5.0.0.76). On one device, App Support keeps restarting in a loop. On the other, the issue occurs when using apps such as Firefox or Molly. The problems appeared virtually overnight. The solutions described here in this thread and in the forum have not been successful. Below is an excerpt from the log showing that AppSupport crashes when opening Firefox. Does anyone have any idea how I can fix this problem?


Mär 30 15:26:00 Xperia10III kernel: binder: send failed reply for transaction 968230 to 61209:61209
Mär 30 15:26:00 Xperia10III apkd-bridge-hw[61134]: GNSS Remote died, cleaning up!
Mär 30 15:26:00 Xperia10III d-bridge[58507]: Service alien died! Trying to reconnect
Mär 30 15:26:00 Xperia10III apkd-bridge-hw[61134]: Service alien.connectivity died! Trying to reconnect
Mär 30 15:26:00 Xperia10III d-bridge[58507]: Service appsupport.inputattachservice died! Trying to reconnect
Mär 30 15:26:00 Xperia10III kernel: binder: 58507:58507 BC_DEAD_BINDER_DONE 0000000000000008 not found
Mär 30 15:26:00 Xperia10III kernel: binder: 63964:63964 ioctl 40046210 7ff6b01de0 returned -22
Mär 30 15:26:03 Xperia10III kernel: binder: 60919:60921 transaction failed 29189/-22, size 100-0 line 3103
Mär 30 15:26:03 Xperia10III kernel: [schedu][0x37a5f0f5fb][13:26:03.959020] wlan: [4671:I:OSIF] scan start scan id 41258
Mär 30 15:26:04 Xperia10III kernel: binder: 63229:63269 transaction failed 29189/-22, size 436-16 line 3103
Mär 30 15:26:04 Xperia10III kernel: binder: send failed reply for transaction 911642 to 61041:61089
Mär 30 15:26:04 Xperia10III kernel: binder: 61134:61134 BC_CLEAR_DEATH_NOTIFICATION invalid ref 5
Mär 30 15:26:04 Xperia10III kernel: binder: 61134:61134 BC_CLEAR_DEATH_NOTIFICATION invalid ref 6
Mär 30 15:26:04 Xperia10III kernel: binder: 61049:61049 BC_DEAD_BINDER_DONE 0000000000000001 not found
Mär 30 15:26:05 Xperia10III ofonod[1440]: [gbinder] WARNING! Service manager /dev/hwpuddlejumper has died
Mär 30 15:26:05 Xperia10III kernel: binder: undelivered TRANSACTION_COMPLETE
Mär 30 15:26:05 Xperia10III kernel: binder: undelivered TRANSACTION_ERROR: 29189
Mär 30 15:26:05 Xperia10III kernel: binder_cleanup_transaction: 23 callbacks suppressed
Mär 30 15:26:05 Xperia10III kernel: binder: undelivered transaction 911643, process died.
Mär 30 15:26:05 Xperia10III kernel: binder: undelivered transaction 914635, process died.
Mär 30 15:26:05 Xperia10III appsupport-run[61049]: [gbinder] WARNING: Service manager /dev/puddlejumper has died
Mär 30 15:26:05 Xperia10III kernel: binder: 61134:61134 transaction failed 29189/-22, size 32-0 line 3103
Mär 30 15:26:05 Xperia10III d-bridge[58507]: Service appsupport.contacts died! Trying to reconnect
Mär 30 15:26:05 Xperia10III d-bridge[58507]: Service appsupport.intent.resolver died! Trying to reconnect
Mär 30 15:26:05 Xperia10III d-bridge[58507]: Service appsupport.media.file_observer died! Trying to reconnect
Mär 30 15:26:05 Xperia10III d-bridge[58507]: Service appsupport.audio.control died! Trying to reconnect
Mär 30 15:26:05 Xperia10III d-bridge[58507]: Service appsupport.media.control died! Trying to reconnect
Mär 30 15:26:05 Xperia10III d-bridge[58507]: No callback client
Mär 30 15:26:05 Xperia10III appsupport-init[60874]: Boot completed: 2
Mär 30 15:26:05 Xperia10III appsupport-init[60874]: Waiting for appsupport-prepare to exit…
Mär 30 15:26:05 Xperia10III appsupport-init[60245]: Running hooks from stop-post-hook.d…
Mär 30 15:26:05 Xperia10III appsupport-init[60245]: Running 10-anr-and-logger.sh
Mär 30 15:26:05 Xperia10III appsupport-init[60245]: Running 20-stop-lxc.sh
Mär 30 15:26:05 Xperia10III appsupport-init[60245]: Running 30-umount-rootfs.sh
Mär 30 15:26:05 Xperia10III appsupport-init[60245]: Running 50-stop-supplementary-services.sh
Mär 30 15:26:05 Xperia10III systemd[4059]: selinux: Unknown permission status for class system
Mär 30 15:26:05 Xperia10III appsupport-init[60245]: Stop --user appsupportaudio-output.service
Mär 30 15:26:05 Xperia10III systemd[4059]: selinux: Unknown class service
Mär 30 15:26:05 Xperia10III systemd[4059]: selinux: Unknown class service
Mär 30 15:26:05 Xperia10III systemd[4059]: Stopping AppSupport Audio output Service…
Mär 30 15:26:05 Xperia10III systemd[4059]: selinux: Unknown class service
Mär 30 15:26:05 Xperia10III appsupport-run[60997]: [gbinder] WARNING: Service manager /dev/hwpuddlejumper has died
Mär 30 15:26:05 Xperia10III appsupport-run[60997]: [gbinder] WARNING: Service manager /dev/vndpuddlejumper has died
Mär 30 15:26:05 Xperia10III appsupport-run[60997]: [gbinder] WARNING: Service manager /dev/puddlejumper has died
Mär 30 15:26:05 Xperia10III systemd[4059]: selinux: Unknown class service
Mär 30 15:26:05 Xperia10III systemd[4059]: Stopped AppSupport Audio output Service.
Mär 30 15:26:05 Xperia10III systemd[4059]: selinux: Unknown class service
Mär 30 15:26:05 Xperia10III systemd[4059]: selinux: Unknown class service
Mär 30 15:26:05 Xperia10III systemd[4059]: selinux: Unknown permission status for class system
Mär 30 15:26:05 Xperia10III appsupport-init[60245]: Stop --user appsupportaudio-input.service
Mär 30 15:26:05 Xperia10III systemd[4059]: selinux: Unknown class service
Mär 30 15:26:05 Xperia10III systemd[4059]: selinux: Unknown class service
Mär 30 15:26:05 Xperia10III systemd[4059]: Stopping AppSupport Audio input Service…
Mär 30 15:26:05 Xperia10III appsupportaudio[61022]: Source ID 10 was not found when attempting to remove it
Mär 30 15:26:05 Xperia10III appsupport-run[61022]: [gbinder] WARNING: Service manager /dev/hwpuddlejumper has died
Mär 30 15:26:05 Xperia10III appsupport-run[61022]: [gbinder] WARNING: Service manager /dev/vndpuddlejumper has died
Mär 30 15:26:05 Xperia10III appsupport-run[61022]: [gbinder] WARNING: Service manager /dev/puddlejumper has died
Mär 30 15:26:05 Xperia10III systemd[4059]: selinux: Unknown class service
Mär 30 15:26:05 Xperia10III systemd[4059]: selinux: Unknown class service
Mär 30 15:26:05 Xperia10III systemd[4059]: Stopped AppSupport Audio input Service.
Mär 30 15:26:05 Xperia10III systemd[4059]: selinux: Unknown class service
Mär 30 15:26:05 Xperia10III systemd[4059]: selinux: Unknown class service
Mär 30 15:26:05 Xperia10III systemd[4059]: selinux: Unknown permission status for class system
Mär 30 15:26:05 Xperia10III appsupport-init[60245]: Stop --user appsupportkeyboard.service
Mär 30 15:26:05 Xperia10III systemd[4059]: selinux: Unknown class service
Mär 30 15:26:05 Xperia10III systemd[4059]: selinux: Unknown class service
Mär 30 15:26:05 Xperia10III systemd[4059]: Stopping AppSupport Keyboard Service…
Mär 30 15:26:05 Xperia10III systemd[4059]: Stopped AppSupport Keyboard Service.
Mär 30 15:26:05 Xperia10III systemd[4059]: selinux: Unknown class service
Mär 30 15:26:05 Xperia10III systemd[4059]: selinux: Unknown class service
Mär 30 15:26:05 Xperia10III systemd[4059]: selinux: Unknown permission status for class system
Mär 30 15:26:05 Xperia10III appsupport-init[60245]: Stop --user apkd-bridge.service
Mär 30 15:26:05 Xperia10III systemd[4059]: selinux: Unknown class service
Mär 30 15:26:05 Xperia10III systemd[4059]: selinux: Unknown class service
Mär 30 15:26:05 Xperia10III systemd[4059]: Stopping Bridge native privileged data to AppSupport…
Mär 30 15:26:05 Xperia10III /usr/libexec/mapplauncherd/booster-qt5[4083]: warning: terminating: booster:58507 invoker:61083 socket:18
Mär 30 15:26:05 Xperia10III /usr/libexec/mapplauncherd/booster-qt5[4083]: warning: Daemon: sending exit(1) to invoker(61083)
Mär 30 15:26:05 Xperia10III /usr/libexec/mapplauncherd/booster-qt5[4083]: warning: sending SIGTERM to booster (pid=58507)
Mär 30 15:26:05 Xperia10III systemd[4059]: selinux: Unknown class service
Mär 30 15:26:05 Xperia10III systemd[4059]: Stopped Bridge native privileged data to AppSupport.
Mär 30 15:26:05 Xperia10III systemd[4059]: selinux: Unknown class service
Mär 30 15:26:05 Xperia10III systemd[4059]: selinux: Unknown class service
Mär 30 15:26:05 Xperia10III systemd[4059]: selinux: Unknown class service
Mär 30 15:26:06 Xperia10III booster-qt5[4083]: *** signal=17 pid=4083
Mär 30 15:26:06 Xperia10III systemd[4059]: selinux: Unknown permission status for class system
Mär 30 15:26:06 Xperia10III appsupport-init[60245]: Stop --user apkd-bridge-hw.service
Mär 30 15:26:06 Xperia10III systemd[4059]: selinux: Unknown class service
Mär 30 15:26:06 Xperia10III systemd[4059]: selinux: Unknown class service
Mär 30 15:26:06 Xperia10III systemd[4059]: Stopping Bridge native data to AppSupport…
Mär 30 15:26:06 Xperia10III systemd[4059]: selinux: Unknown class service
Mär 30 15:26:06 Xperia10III systemd[4059]: selinux: Unknown class service
Mär 30 15:26:06 Xperia10III kernel: binder: release 61134:61155 transaction 903989 in, still active
Mär 30 15:26:06 Xperia10III kernel: binder: send failed reply for transaction 903989, target dead
Mär 30 15:26:06 Xperia10III systemd[4059]: Stopped Bridge native data to AppSupport.
Mär 30 15:26:06 Xperia10III systemd[4059]: selinux: Unknown class service
Mär 30 15:26:06 Xperia10III systemd[4059]: selinux: Unknown class service
Mär 30 15:26:06 Xperia10III appsupport-init[60245]: Running 60-stop-lxc-net.sh
Mär 30 15:26:06 Xperia10III systemd[1]: selinux: Unknown class service
Mär 30 15:26:06 Xperia10III systemd[1]: selinux: Unknown class service
Mär 30 15:26:06 Xperia10III systemd[1]: Stopping LXC network bridge setup…
Mär 30 15:26:06 Xperia10III systemd[1]: selinux: Unknown class service
Mär 30 15:26:06 Xperia10III systemd[1]: selinux: Unknown class service
Mär 30 15:26:06 Xperia10III systemd[1]: Stopped LXC network bridge setup.
Mär 30 15:26:06 Xperia10III systemd[1]: selinux: Unknown class service
Mär 30 15:26:06 Xperia10III systemd[1]: selinux: Unknown class service
Mär 30 15:26:06 Xperia10III appsupport-init[60874]: From appsupport-prepare: done
Mär 30 15:26:06 Xperia10III systemd[1]: appsupport@defaultuser.service: Main process exited, code=exited, status=1/FAILURE
Mär 30 15:26:06 Xperia10III systemd[1]: appsupport@defaultuser.service: Failed with result ‘exit-code’.
Mär 30 15:26:06 Xperia10III systemd[1]: Stopped AppSupport prepare.
Mär 30 15:26:06 Xperia10III systemd[1]: selinux: Unknown class service
Mär 30 15:26:06 Xperia10III kernel: rpmh_rsc_send_data: 81 callbacks suppressed
Mär 30 15:26:08 Xperia10III kernel: [schedu][0x37aaf10328][13:26:08.328163] wlan: [4671:I:OSIF] vdev 0, scan id 41258 type COMPLETED(1) reason COMPLETED(1) scan found 7 bss
Mär 30 15:26:09 Xperia10III systemd[1]: appsupport@defaultuser.service: Service hold-off time over, scheduling restart.
Mär 30 15:26:09 Xperia10III systemd[1]: appsupport@defaultuser.service: Scheduled restart job, restart counter is at 1.
Mär 30 15:26:09 Xperia10III systemd[1]: Stopped AppSupport.
Mär 30 15:26:09 Xperia10III systemd[1]: Starting AppSupport prepare…

Could you try the command-line I used above while starting: appsupport-attach /system/bin/logcat | grep -E 'system_server|AndroidRuntime' ?

Also, I disabled the restarting of the runtime because it does not notice these crashes and just uselessly tries to restart without different outcomes (and heavily drains the battery as a result).

To prevent the restarts, do:

# systemctl edit appsupport@defaultuser.service

and then add:

[Service]
Restart=no

(To undo this, edit it again and remove those lines.)

Side note: could you edit your post to use a code block for the logs. It automatically gets folded that way :slight_smile:

1 Like

This results in the following log:


03-31 21:04:54.396   309   337 I DropBoxManagerService: add tag=system_server_wtf isTagEnabled=true flags=0x2
03-31 21:04:54.757   309   309 W ActivityManager: Too early to start/bind service in system_server: Phase=550 ComponentInfo{com.android.server.telecom/com.android.server.telecom.components.TelecomService}
03-31 21:04:54.757   309   309 W ActivityManager: Too early to start/bind service in system_server: Phase=550 ComponentInfo{com.android.server.telecom/com.android.server.telecom.components.TelecomService}
03-31 21:04:55.009   309   309 D ConnectivityModuleConnector: Starting networking module in system_server process
03-31 21:04:55.010   309   309 D ConnectivityModuleConnector: Starting networking module in system_server process
03-31 21:04:55.837   508   508 I AndroidRuntime: VM exiting with result code 0, cleanup skipped.
03-31 21:04:55.882   509   509 I AndroidRuntime: VM exiting with result code 0, cleanup skipped.
03-31 21:04:56.056   309   336 I system_server: Using smaps_rollup for pss collection
03-31 21:04:56.096   309   343 E system_server: Cannot obtain CPU frequency count
03-31 21:04:56.097   309   343 E system_server: Cannot obtain CPU frequency count
03-31 21:04:56.097   309   343 E system_server: Cannot obtain CPU frequency count
03-31 21:04:56.097   309   343 E system_server: Cannot read thread CPU times for PID 309
03-31 21:14:00.895   309   343 E system_server: Cannot obtain CPU frequency count
03-31 21:14:00.896   309   343 E system_server: Cannot obtain CPU frequency count
03-31 21:14:00.897   309   343 E system_server: Cannot obtain CPU frequency count
03-31 21:14:00.898   309   343 E system_server: Cannot read thread CPU times for PID 309
03-31 21:14:05.236   309   309 D AndroidRuntime: Shutting down VM
03-31 21:14:05.237   309   309 E AndroidRuntime: \*\*\* FATAL EXCEPTION IN SYSTEM PROCESS: main
03-31 21:14:05.237   309   309 E AndroidRuntime: java.lang.IllegalArgumentException: event time must not be in the future
03-31 21:14:05.237   309   309 E AndroidRuntime:        at com.android.server.power.PowerManagerService$BinderService.userActivity(PowerManagerService.java:5713)
03-31 21:14:05.237   309   309 E AndroidRuntime:        at android.os.PowerManager.userActivity(PowerManager.java:1401)
03-31 21:14:05.237   309   309 E AndroidRuntime:        at android.os.PowerManager.userActivity(PowerManager.java:1366)
03-31 21:14:05.237   309   309 E AndroidRuntime:        at com.android.server.accessibility.AccessibilityInputFilter.handleMotionEvent(AccessibilityInputFilter.java:360)
03-31 21:14:05.237   309   309 E AndroidRuntime:        at com.android.server.accessibility.AccessibilityInputFilter.processMotionEvent(AccessibilityInputFilter.java:342)
03-31 21:14:05.237   309   309 E AndroidRuntime:        at com.android.server.accessibility.AccessibilityInputFilter.onInputEvent(AccessibilityInputFilter.java:278)
03-31 21:14:05.237   309   309 E AndroidRuntime:        at android.view.InputFilter$H.handleMessage(InputFilter.java:250)
03-31 21:14:05.237   309   309 E AndroidRuntime:        at android.os.Handler.dispatchMessage(Handler.java:106)
03-31 21:14:05.237   309   309 E AndroidRuntime:        at android.os.Looper.loopOnce(Looper.java:201)
03-31 21:14:05.237   309   309 E AndroidRuntime:        at android.os.Looper.loop(Looper.java:288)
03-31 21:14:05.237   309   309 E AndroidRuntime:        at com.android.server.SystemServer.run(SystemServer.java:972)
03-31 21:14:05.237   309   309 E AndroidRuntime:        at com.android.server.SystemServer.main(SystemServer.java:665)
03-31 21:14:05.237   309   309 E AndroidRuntime:        at java.lang.reflect.Method.invoke(Native Method)
03-31 21:14:05.237   309   309 E AndroidRuntime:        at com.android.internal.os.RuntimeInit$MethodAndArgsCaller.run(RuntimeInit.java:555)
03-31 21:14:05.237   309   309 E AndroidRuntime:        at com.android.internal.os.ZygoteInit.main(ZygoteInit.java:914)
03-31 21:14:05.243   309   309 I DropBoxManagerService: add tag=system_server_crash isTagEnabled=true flags=0x2
03-31 21:14:05.356    59    59 E Zygote  : Zygote failed to write to system_server FD: Connection refused
03-31 21:14:05.780  1585  1585 D AndroidRuntime: Shutting down VM
03-31 21:14:05.780  1585  1585 E AndroidRuntime: FATAL EXCEPTION: main
03-31 21:14:05.780  1585  1585 E AndroidRuntime: Process: org.mozilla.firefox, PID: 1585
03-31 21:14:05.780  1585  1585 E AndroidRuntime: DeadSystemException: The system died; earlier logs will point to the root cause
03-31 21:14:06.872   541   541 D AndroidRuntime: Shutting down VM
03-31 21:14:06.872   541   541 E AndroidRuntime: FATAL EXCEPTION: main
03-31 21:14:06.872   541   541 E AndroidRuntime: Process: com.android.phone, PID: 541
03-31 21:14:06.872   541   541 E AndroidRuntime: DeadSystemException: The system died; earlier logs will point to the root cause

For me it looks like app supports time is different from the main OS. But looking in the system settings of app support evrything looks fine and in sync.

That exception is after the VM is already shutting down, there has to be more higher up.

Here is a mor detailed log of death of app support

appsupport-attach /system/bin/logcat | grep -E 'system_server|AndroidRuntime'
03-31 22:18:23.398    62    62 D AndroidRuntime: >>>>>> START com.android.internal.os.ZygoteInit uid 0 <<<<<<
03-31 22:18:23.633    61    61 D AndroidRuntime: >>>>>> START com.android.internal.os.ZygoteInit uid 0 <<<<<<
03-31 22:18:23.997    62    62 I AndroidRuntime: Using default boot image
03-31 22:18:23.997    62    62 I AndroidRuntime: Leaving lock profiling enabled
03-31 22:18:24.089    61    61 I AndroidRuntime: Using default boot image
03-31 22:18:24.089    61    61 I AndroidRuntime: Leaving lock profiling enabled
03-31 22:18:27.593   313   313 W system_server: Failed to upload odrefresh metrics: metrics file '/data/misc/odrefresh/odrefresh-metrics.txt' could not be opened: No such file or directory
03-31 22:18:27.593   313   313 E system_server: Not starting debugger since process cannot load the jdwp agent.
03-31 22:18:28.137   313   313 E system_server: Disallowing getting service: android.hardware.memtrack@1.0::IMemtrack
03-31 22:18:28.211   313   350 E system_server: Cannot obtain CPU frequency count
03-31 22:18:28.212   313   350 E system_server: Cannot obtain CPU frequency count
03-31 22:18:28.212   313   350 E system_server: Cannot obtain CPU frequency count
03-31 22:18:28.213   313   350 E system_server: Cannot read thread CPU times for PID 313
03-31 22:18:28.328   313   350 E system_server: Cannot obtain CPU frequency count
03-31 22:18:28.329   313   350 E system_server: Cannot obtain CPU frequency count
03-31 22:18:28.329   313   350 E system_server: Cannot obtain CPU frequency count
03-31 22:18:28.330   313   350 E system_server: Cannot read thread CPU times for PID 313
03-31 22:18:28.899   313   350 E system_server: Cannot obtain CPU frequency count
03-31 22:18:28.899   313   350 E system_server: Cannot obtain CPU frequency count
03-31 22:18:28.900   313   350 E system_server: Cannot obtain CPU frequency count
03-31 22:18:28.901   313   350 E system_server: Cannot read thread CPU times for PID 313
03-31 22:18:28.902   313   350 E system_server: Cannot obtain CPU frequency count
03-31 22:18:28.903   313   350 E system_server: Cannot obtain CPU frequency count
03-31 22:18:28.904   313   350 E system_server: Cannot obtain CPU frequency count
03-31 22:18:28.905   313   350 E system_server: Cannot read thread CPU times for PID 313
03-31 22:18:29.011   313   313 I system_server: Created attach input device service listener
03-31 22:18:29.204   313   344 I DropBoxManagerService: add tag=system_server_wtf isTagEnabled=true flags=0x2
03-31 22:18:29.317   313   344 I DropBoxManagerService: add tag=system_server_wtf isTagEnabled=true flags=0x2
03-31 22:18:29.321   313   344 I DropBoxManagerService: add tag=system_server_wtf isTagEnabled=true flags=0x2
03-31 22:18:29.327   313   344 I DropBoxManagerService: add tag=system_server_wtf isTagEnabled=true flags=0x2
03-31 22:18:29.330   313   344 I DropBoxManagerService: add tag=system_server_wtf isTagEnabled=true flags=0x2
03-31 22:18:29.331   313   344 I DropBoxManagerService: add tag=system_server_wtf isTagEnabled=true flags=0x2
03-31 22:18:29.654   313   313 I system_server: Waiting for a blocking GC ClassLinker
03-31 22:18:29.672   313   313 I system_server: WaitForGcToComplete blocked ClassLinker on Background for 18.530ms
03-31 22:18:29.737   313   313 W ActivityManager: Too early to start/bind service in system_server: Phase=550 ComponentInfo{com.android.server.telecom/com.android.server.telecom.components.TelecomService}
03-31 22:18:29.738   313   313 W ActivityManager: Too early to start/bind service in system_server: Phase=550 ComponentInfo{com.android.server.telecom/com.android.server.telecom.components.TelecomService}
03-31 22:18:29.910   313   325 W system_server: Suspending all threads took: 5.902ms
03-31 22:18:29.915   313   325 I system_server: Background young concurrent copying GC freed 69396(4768KB) AllocSpace objects, 16(448KB) LOS objects, 27% free, 13MB/17MB, paused 850us,6.148ms total 26.756ms
03-31 22:18:29.998   313   313 D ConnectivityModuleConnector: Starting networking module in system_server process
03-31 22:18:29.999   313   313 D ConnectivityModuleConnector: Starting networking module in system_server process
03-31 22:18:31.053   516   516 I AndroidRuntime: VM exiting with result code 0, cleanup skipped.
03-31 22:18:31.236   517   517 I AndroidRuntime: VM exiting with result code 0, cleanup skipped.
03-31 22:18:31.329   313   343 I system_server: Using smaps_rollup for pss collection
03-31 22:18:31.353   313   350 E system_server: Cannot obtain CPU frequency count
03-31 22:18:31.353   313   350 E system_server: Cannot obtain CPU frequency count
03-31 22:18:31.354   313   350 E system_server: Cannot obtain CPU frequency count
03-31 22:18:31.358   313   350 E system_server: Cannot read thread CPU times for PID 313
03-31 22:18:38.854   313   325 I system_server: Background concurrent copying GC freed 109325(5879KB) AllocSpace objects, 4(96KB) LOS objects, 25% free, 17MB/23MB, paused 101us,216us total 200.613ms
03-31 22:19:24.540   313   350 E system_server: Cannot obtain CPU frequency count
03-31 22:19:24.540   313   350 E system_server: Cannot obtain CPU frequency count
03-31 22:19:24.541   313   350 E system_server: Cannot obtain CPU frequency count
03-31 22:19:24.541   313   350 E system_server: Cannot read thread CPU times for PID 313
03-31 22:20:33.388   313   313 D AndroidRuntime: Shutting down VM
03-31 22:20:33.389   313   313 E AndroidRuntime: *** FATAL EXCEPTION IN SYSTEM PROCESS: main
03-31 22:20:33.389   313   313 E AndroidRuntime: java.lang.IllegalArgumentException: event time must not be in the future
03-31 22:20:33.389   313   313 E AndroidRuntime:        at com.android.server.power.PowerManagerService$BinderService.userActivity(PowerManagerService.java:5713)
03-31 22:20:33.389   313   313 E AndroidRuntime:        at android.os.PowerManager.userActivity(PowerManager.java:1401)
03-31 22:20:33.389   313   313 E AndroidRuntime:        at android.os.PowerManager.userActivity(PowerManager.java:1366)
03-31 22:20:33.389   313   313 E AndroidRuntime:        at com.android.server.accessibility.AccessibilityInputFilter.handleMotionEvent(AccessibilityInputFilter.java:360)
03-31 22:20:33.389   313   313 E AndroidRuntime:        at com.android.server.accessibility.AccessibilityInputFilter.processMotionEvent(AccessibilityInputFilter.java:342)
03-31 22:20:33.389   313   313 E AndroidRuntime:        at com.android.server.accessibility.AccessibilityInputFilter.onInputEvent(AccessibilityInputFilter.java:278)
03-31 22:20:33.389   313   313 E AndroidRuntime:        at android.view.InputFilter$H.handleMessage(InputFilter.java:250)
03-31 22:20:33.389   313   313 E AndroidRuntime:        at android.os.Handler.dispatchMessage(Handler.java:106)
03-31 22:20:33.389   313   313 E AndroidRuntime:        at android.os.Looper.loopOnce(Looper.java:201)
03-31 22:20:33.389   313   313 E AndroidRuntime:        at android.os.Looper.loop(Looper.java:288)
03-31 22:20:33.389   313   313 E AndroidRuntime:        at com.android.server.SystemServer.run(SystemServer.java:972)
03-31 22:20:33.389   313   313 E AndroidRuntime:        at com.android.server.SystemServer.main(SystemServer.java:665)
03-31 22:20:33.389   313   313 E AndroidRuntime:        at java.lang.reflect.Method.invoke(Native Method)
03-31 22:20:33.389   313   313 E AndroidRuntime:        at com.android.internal.os.RuntimeInit$MethodAndArgsCaller.run(RuntimeInit.java:555)
03-31 22:20:33.389   313   313 E AndroidRuntime:        at com.android.internal.os.ZygoteInit.main(ZygoteInit.java:914)
03-31 22:20:33.397   313   313 I DropBoxManagerService: add tag=system_server_crash isTagEnabled=true flags=0x2
03-31 22:20:33.490    61    61 E Zygote  : Zygote failed to write to system_server FD: Connection refused
03-31 22:20:34.446   548   548 D AndroidRuntime: Shutting down VM
03-31 22:20:34.446   548   548 E AndroidRuntime: FATAL EXCEPTION: main
03-31 22:20:34.446   548   548 E AndroidRuntime: Process: com.android.phone, PID: 548
03-31 22:20:34.446   548   548 E AndroidRuntime: DeadSystemException: The system died; earlier logs will point to the root cause
[root@Xperia10III defaultuser]#

What’s the use of the missing file?
/data/misc/odrefresh/odrefresh-metrics.txt
At least the directory odrefresh does not exist.

I checked two other devices one freshly flashed and another updated from late 4.x version to 5.0.0.77 and on any other device the I can find the directory of
/date/misc/odrefresh.

creation of directory and file has no effect

Ok, I see. Yeah, your problem is different than mine. You’d probably be better of filing an different report. I will change the title of this bug report to be more precise.

And yeah… there are some warnings/errors during start up that probably can be ignored. Not having implemented this or being in the weeds causes that is hard to know what is pertinent or not.

1 Like

I have the exact same symptoms on a recently converted X10III.
Tried various tips given here with no success.

I was using only:

  • Signal (with always on background notification)
  • Delta-Chat (also)
  • Fennec (occasionally, once a month)
  • OpenCamera (tried a few times)
  • AndrOBD (tried twice)

For a total of around 10 Android apps installed (just in case).

I did switch from 4G to WiFi soon before I noticed the AAS crash, then bootloop.

It was my main Signal instance (as advised by Whisperfish team) so I really would like to find a solution.

That sucks.

A small update from my side: I still run with the restarting off as written in this post.

Recently, I rebooted my phone for some reason and I occasionally try to open an Android App (since it doesn’t restart, it is low stakes to do so). And suddenly, it started again! I haven’t rebooted since, but it seems that circumstances make it trip (or not) over the VM heap size limit and this happens way more often than not. (I have tried rebooting many times earlier, so I have no clue why it worked now, maybe because of the position of the moon? (no))