Auxio crashes on any playback with android.app.ForegroundServiceStartNotAllowedException: Service.startForeground() not allowed

[foss-]

Describe the Bug/Crash

1. play any track
2. auxio reproducibly crashes

This is a new problem, at least for me, which did not happen in 3.5.0 and earlier.

Describe the intended behavior

no crash

What android version do you use?

Android 13

What device model do you use?

lisa, ArrowOS 13.1
Auxio 3.5.2

Provide a sample file

N/A

Bug report

android.app.ForegroundServiceStartNotAllowedException: Service.startForeground() not allowed due to mAllowStartForeground false: service org.oxycblt.auxio/.AuxioService
	at android.app.ForegroundServiceStartNotAllowedException$1.createFromParcel(ForegroundServiceStartNotAllowedException.java:54)
	at android.app.ForegroundServiceStartNotAllowedException$1.createFromParcel(ForegroundServiceStartNotAllowedException.java:50)
	at android.os.Parcel.readParcelableInternal(Parcel.java:4816)
	at android.os.Parcel.readParcelable(Parcel.java:4778)
	at android.os.Parcel.createExceptionOrNull(Parcel.java:3006)
	at android.os.Parcel.createException(Parcel.java:2995)
	at android.os.Parcel.readException(Parcel.java:2978)
	at android.os.Parcel.readException(Parcel.java:2920)
	at android.app.IActivityManager$Stub$Proxy.setServiceForeground(IActivityManager.java:6114)
	at android.app.Service.startForeground(Service.java:743)
	at org.oxycblt.auxio.AuxioService.updateForeground(SourceFile:232)
	at org.oxycblt.auxio.music.service.IndexerServiceFragment.onIndexingStateChanged(SourceFile:9)
	at org.oxycblt.auxio.music.MusicRepositoryImpl.emitIndexingProgress(Unknown Source:94)
	at org.oxycblt.auxio.music.MusicRepositoryImpl$emitIndexingProgress$1.invokeSuspend(SourceFile:13)
	at kotlin.coroutines.jvm.internal.BaseContinuationImpl.resumeWith(Unknown Source:8)
	at kotlinx.coroutines.DispatchedTask.run(Unknown Source:94)
	at androidx.core.app.ActivityRecreator$1.run(SourceFile:40)
	at kotlinx.coroutines.scheduling.TaskImpl.run(Unknown Source:2)
	at kotlinx.coroutines.scheduling.CoroutineScheduler$Worker.run(SourceFile:92)

Duplicates

• I have checked the Troubleshooting page.
• I have checked this issue for duplicates.
• I have checked that this issue occurs on the lastest version.
• I agree to the Contribution Guidelines.

[OxygenCobalt]

Okay. I'll try to investigate this. The weird part is that I've not changed really anything, so it's OEMs doing weird stuff.

[foss-]

Then the change causing the crashes was by Google. ArrowOS is currently stale and has not seen an update since several months.

[foss-]

What I find surprising, that this does not seem to affect many users. For me Auxio is bearly unusable in 3.5.2. I see frequent crashes. What does seem to reliably trigger a crash is when using the shuffle button.

After a crash I am greeted with the Retry | More dialog.

[shashankmunda]

@foss- Is the app in background state when this issue occurs? I probably suspect that is the case, because the above error you highlighted is caused due to starting a foreground service from background(which is not permissible on Android 12 and above)

[foss-]

I don't think the app is in the background when it crashes. I closed the app and open it, press shuffle and a track starts playing. I press shuffle 2 or 3 times more and Auxio crashes with

android.app.ForegroundServiceStartNotAllowedException: Service.startForeground() not allowed due to mAllowStartForeground false: service org.oxycblt.auxio/.AuxioService
	at android.app.ForegroundServiceStartNotAllowedException$1.createFromParcel(ForegroundServiceStartNotAllowedException.java:54)
	at android.app.ForegroundServiceStartNotAllowedException$1.createFromParcel(ForegroundServiceStartNotAllowedException.java:50)
	at android.os.Parcel.readParcelableInternal(Parcel.java:4816)
	at android.os.Parcel.readParcelable(Parcel.java:4778)
	at android.os.Parcel.createExceptionOrNull(Parcel.java:3006)
	at android.os.Parcel.createException(Parcel.java:2995)
	at android.os.Parcel.readException(Parcel.java:2978)
	at android.os.Parcel.readException(Parcel.java:2920)
	at android.app.IActivityManager$Stub$Proxy.setServiceForeground(IActivityManager.java:6114)
	at android.app.Service.startForeground(Service.java:743)
	at org.oxycblt.auxio.AuxioService.updateForeground(SourceFile:232)
	at org.oxycblt.auxio.music.service.IndexerServiceFragment.onIndexingStateChanged(SourceFile:9)
	at org.oxycblt.auxio.music.MusicRepositoryImpl.emitIndexingProgress(Unknown Source:94)
	at org.oxycblt.auxio.music.MusicRepositoryImpl$emitIndexingProgress$1.invokeSuspend(SourceFile:13)
	at kotlin.coroutines.jvm.internal.BaseContinuationImpl.resumeWith(Unknown Source:8)
	at kotlinx.coroutines.DispatchedTask.run(Unknown Source:94)
	at androidx.core.app.ActivityRecreator$1.run(SourceFile:40)
	at kotlinx.coroutines.scheduling.TaskImpl.run(Unknown Source:2)
	at kotlinx.coroutines.scheduling.CoroutineScheduler$Worker.run(SourceFile:92)

The app was not closed or in background during the test.

[OxygenCobalt]

My theory @foss- is that this is a weird race condition, that I either start music loading/playback after Android OK's the service to go foreground and all is well, or before and it fails, but I have zero clue how it's happening since the lifecycle didn't meaningfully change. Maybe there's something dumb and fiddly that Android does with MediaBrowserServices in particular (started using that in 3.5.0), that would make sense since it's insane behavior and undocumented.

[OxygenCobalt]

Can you try this out at all @foss-? No guarantees this will actually work in prod, but I delayed the start of indexing until after the bind/start-command stage, so hopefully your ROM will tolerate me going foreground so quickly.

Auxio_DelayFG.zip

Also pinging @nitinsooni since they had this issue.

[foss-]

Thanks for looking into this.

Tested this. Noticed on first launch that while Loading your music library… while there still is a progress bar, there no longer is the info that x/ y tracks have been loaded.

The first scan failed and I tapped Retry. Ran into a failed scan again. More output shows:

java.lang.Exception: DeviceLibrary creation failed: java.lang.IllegalArgumentException: Comparison method violates its general contract!
	at java.util.TimSort.mergeHi(TimSort.java:903)
	at java.util.TimSort.mergeAt(TimSort.java:520)
	at java.util.TimSort.mergeCollapse(TimSort.java:448)
	at java.util.TimSort.sort(TimSort.java:245)
	at java.util.Arrays.sort(Arrays.java:1495)
	at java.util.ArrayList.sort(ArrayList.java:1470)
	at java.util.Collections.sort(Collections.java:206)
	at kotlin.collections.CollectionsKt__MutableCollectionsJVMKt.sortWith(Unknown Source:12)
	at org.oxycblt.auxio.list.sort.Sort$Mode$ByAlbum.sortSongs(SourceFile:76)
	at org.oxycblt.auxio.list.sort.Sort.songs(SourceFile:14)
	at org.oxycblt.auxio.image.extractor.Cover$Companion.order(SourceFile:8)
	at org.oxycblt.auxio.music.device.ArtistImpl.<init>(SourceFile:381)
	at timber.log.Timber$Forest.create(SourceFile:351)
	at org.oxycblt.auxio.music.device.DeviceLibraryFactoryImpl$create$1.invokeSuspend(Unknown Source:16)
	at kotlin.coroutines.jvm.internal.BaseContinuationImpl.resumeWith(Unknown Source:8)
	at kotlinx.coroutines.internal.ScopeCoroutine.afterResume(Unknown Source:6)
	at kotlinx.coroutines.AbstractCoroutine.resumeWith(SourceFile:23)
	at kotlin.coroutines.jvm.internal.BaseContinuationImpl.resumeWith(Unknown Source:31)
	at kotlinx.coroutines.DispatchedTask.run(Unknown Source:94)
	at kotlinx.coroutines.scheduling.CoroutineScheduler$Worker.run(SourceFile:92)

	at org.oxycblt.auxio.music.MusicRepositoryImpl$indexImpl$deviceLibraryJob$1.invokeSuspend(SourceFile:88)
	at kotlin.coroutines.jvm.internal.BaseContinuationImpl.resumeWith(Unknown Source:8)
	at kotlinx.coroutines.internal.ScopeCoroutine.afterResume(Unknown Source:6)
	at kotlinx.coroutines.AbstractCoroutine.resumeWith(SourceFile:23)
	at kotlin.coroutines.jvm.internal.BaseContinuationImpl.resumeWith(Unknown Source:31)
	at kotlinx.coroutines.DispatchedTask.run(Unknown Source:94)
	at kotlinx.coroutines.scheduling.CoroutineScheduler$Worker.run(SourceFile:92)

[OxygenCobalt]

Sorry @foss-, forgot to merge some critical 3.5.2 changes into the branch. Try this?

Auxio_DelayFG2.zip

The lack of (X/NNN) indicator in the loading screen is intended, it turns out to have taken up a lot of CPU and I wanted to avoid that.

[foss-]

Thanks for the new test version and elaborating on why the counter was removed.

The test build crashed when I tried playing a song before I could hear any audio. After re-opening Auxio, the library is reloaded.

I was then able to play a few tracks. Auxio skipped to the next track as expected. Leaving the app opening other apps works and music keeps playing.

What reliably seems to still trigger a crash is using shuffle. This is true for using shuffle in Songs or Artists or Albums. After sicj a crash the initial loading of the library happens, which takes a few minutes for large libraries.

In another test round Auxio crashed a few seconds after playing a track - no shuffle involved.

[OxygenCobalt]

Can you please take a new bug report when the crash happens @foss-?

[foss-]

That bug report method included a few too many sensitive details. But I created a logcat and this is the output:

16:52:00 tap shuffle
~16:52:04 crash

logcat (1 month): https://bin.disroot.org/?60dbd5822626b2eb#8eHmRim39xXJ26yXwJ8SuwwmGjeuKMnkzDN1ctMPQ9a

error is: 08-02 16:52:04.449 16567 16567 W g.oxycblt.auxio: Throwing OutOfMemoryError "Failed to allocate a 32 byte allocation with 1247864 free bytes and 1218KB until OOM, target footprint 268435456, growth limit 268435456; giving up on allocation because <1% of heap free after GC." (VmSize 7666648 kB)

Hope this is helpful. If you need more/other info let me know.

[OxygenCobalt]

That bug report method included a few too many sensitive details. But I created a logcat and this is the output:

16:52:00 tap shuffle
~16:52:04 crash

logcat (1 month): https://bin.disroot.org/?60dbd5822626b2eb#8eHmRim39xXJ26yXwJ8SuwwmGjeuKMnkzDN1ctMPQ9a

error is: 08-02 16:52:04.449 16567 16567 W g.oxycblt.auxio: Throwing OutOfMemoryError "Failed to allocate a 32 byte allocation with 1247864 free bytes and 1218KB until OOM, target footprint 268435456, growth limit 268435456; giving up on allocation because <1% of heap free after GC." (VmSize 7666648 kB)

Hope this is helpful. If you need more/other info let me know.

How many songs do you have in your library? @foss-

I think the issue is Media3. I was aware of it being inefficient before, but I thought it just if I used it in the UI. This is the second OOM I've encountered so far and I think at this point it just flat out CANNOT work with large playlists. I need to rip out all of the internals and go back to the old versions.

[OxygenCobalt]

Can you see what happens if you play something smaller like an album @foss-?

[foss-]

~35k songs, guess that's qualifies as somewhat large library. There seems to be very active development around Media3.

What I am wondering, since this is still Android 13, if this issue would happen also on Android 14. The rom I am using is abandonware, so I'll need to switch to something else anyways. But I need to find the time for a proper migration, which won't be happening near term. So if the issue is limited to old Android 13, not sure if bothering is worth it. I may be able to test Android 14 on another device.

Oh and also: the music library resides on an SD-card so maybe that is a major factor of the trouble I am seeing, although it did work reliable I'd say in the past with Auxio.

Re: playing something smaller like an album: Playing from album section seems to work reliable, very interesting. Wasn't aware and that's a good workaround.

[OxygenCobalt]

~35k songs, guess that's qualifies as somewhat large library. There seems to be very active development around Media3.

What I am wondering, since this is still Android 13, if this issue would happen also on Android 14. The rom I am using is abandonware, so I'll need to switch to something else anyways. But I need to find the time for a proper migration, which won't be happening near term. So if the issue is limited to old Android 13, not sure if bothering is worth it. I may be able to test Android 14 on another device.

Oh and also: the music library resides on an SD-card so maybe that is a major factor of the trouble I am seeing, although it did work reliable I'd say in the past with Auxio.

Re: playing something smaller like an album: Playing from album section seems to work reliable, very interesting. Wasn't aware and that's a good workaround.

Okay, yeah I'd see how Media3 might choke on a 35k song playlist.

There are some longstanding issues on how Media3 dispatches queue updates, it can be EXTREMELY slow (largely from serialization) and the work is duplicated quite a lot. So it could probably be easy to OOM too.

Im going to send a pre-Media3 and post-Media3 build and see if the issue can be definitively traced to that. If it isn't, it's my fault (yay!), otherwise, I have to rip out basically all of the work done in 3.5.0 and revert to using the old way of doing android auto stuff. Sigh...

@foss-

[OxygenCobalt]

Here's a really old pre-media3 build @foss-, it might crash in some weird way, no idea: Auxio_DelayFG3.zip

[foss-]

Gave Auxio_DelayFG3.zip a spin. Still crashing when playing tracks from Song category. Playing from Albums category works fine.

Am I understanding correctly that the crashes would be unexpected as this is a pre media3 build?

As for the Media3 issues - are there open issues you can link (just curious)?

[OxygenCobalt]

Gave Auxio_DelayFG3.zip a spin. Still crashing when playing tracks from Song category. Playing from Albums category works fine.

Am I understanding correctly that the crashes would be unexpected as this is a pre media3 build?

As for the Media3 issues - are there open issues you can link (just curious)?

Yeah, so it's a deeper issue, strangely.

Will send another even earlier build @foss-

[dreamsyntax]

Not sure if this applies to this project, but wanted to mention if you are using any sort of Job delay when calling startForeground or startService, Android will throw the error reported. Even in situations that Google considers "exempt" fail if done with a delay.

[OxygenCobalt]

Sorry, what you mean by a Job delay @dreamsyntax?

[OxygenCobalt]

Considering this fixed and moving the memory problem into #842

[OxygenCobalt]

Officially shipped in 3.5.3. @foss-