Android: Context.startForegroundService() did not then call Service.startForeground()

[AndyScherzinger]

Highest number of reports for ANRs since 2.0.0 in the Dev console - Android 8 only - >5K reports in 60 days

Reason I found google-ing: https://stackoverflow.com/questions/44425584/context-startforegroundservice-did-not-then-call-service-startforeground

From Google's docs on Android 8.0 behavior changes:
The system allows apps to call Context.startForegroundService() even while the app is in the background. However, the app must call that service's startForeground() method within five seconds after the service is created.

--> https://developer.android.com/about/versions/oreo/android-8.0-changes.html

*** CAUSE OF ERROR ***

android.app.RemoteServiceException: Context.startForegroundService() did not then call Service.startForeground(): ServiceRecord{fb59be8 u0 com.nextcloud.client/com.owncloud.android.services.OperationsService}
at android.app.ActivityThread$H.handleMessage(ActivityThread.java:1745)
at android.os.Handler.dispatchMessage(Handler.java:106)
at android.os.Looper.loop(Looper.java:193)
at android.app.ActivityThread.main(ActivityThread.java:6718)
at java.lang.reflect.Method.invoke(Native Method)
at com.android.internal.os.RuntimeInit$MethodAndArgsCaller.run(RuntimeInit.java:493)
at com.android.internal.os.ZygoteInit.main(ZygoteInit.java:858)

*** APP INFORMATION ***
ID: com.nextcloud.client
Version: 30080190
Build flavor: generic

*** DEVICE INFORMATION ***
Brand: lge
Device: joan
Model: LG-H932
Id: PQ3A.190605.003
Product: joan_tmo_us

*** FIRMWARE ***
SDK: 28
Release: 9
Incremental: eng.markus.20190610.202830

[paulpv]

https://issuetracker.google.com/issues/76112072

[dark-chocolate]

@AndyScherzinger Have you guys found some solution for this?

[AndyScherzinger]

Not that I am aware of

[stale[bot]]

This request did not receive an update in the last 4 weeks. Please take a look again and update the issue with new details, otherwise the issue will be automatically closed in 2 weeks. Thank you!

[tobiasKaminsky]

Re-opening as there are some new reports, and this is the issue with most background infos.

[tobiasKaminsky]

@all when is this happening?
We use startForegroundService() on

• upload file
• document storage provider
• sync folder
• sync file

[AndyScherzinger]

android.app.RemoteServiceException: Context.startForegroundService() did not then call Service.startForeground(): ServiceRecord{9cb193 u0 com.nextcloud.client/com.owncloud.android.services.OperationsService}
    at android.app.ActivityThread$H.handleMessage(ActivityThread.java:2126)
    at android.os.Handler.dispatchMessage(Handler.java:112)
    at android.os.Looper.loop(Looper.java:216)
    at android.app.ActivityThread.main(ActivityThread.java:7625)
    at java.lang.reflect.Method.invoke(Native Method)
    at com.android.internal.os.RuntimeInit$MethodAndArgsCaller.run(RuntimeInit.java:524)
    at com.android.internal.os.ZygoteInit.main(ZygoteInit.java:987)

************ APP INFORMATION ************
ID: com.nextcloud.client
Version: 30080190
Build flavor: gplay

************ DEVICE INFORMATION ************
Brand: HONOR
Device: HWBKL
Model: BKL-L09
Id: HUAWEIBKL-L09S
Product: BKL-L09

************ FIRMWARE ************
SDK: 28
Release: 9
Incremental: 329C432

[AndyScherzinger]

************ CAUSE OF ERROR ************

android.app.RemoteServiceException: Context.startForegroundService() did not then call Service.startForeground(): ServiceRecord{bd2d535 u0 com.nextcloud.client/com.owncloud.android.services.OperationsService}
at android.app.ActivityThread$H.handleMessage(ActivityThread.java:1855)
at android.os.Handler.dispatchMessage(Handler.java:106)
at android.os.Looper.loop(Looper.java:214)
at android.app.ActivityThread.main(ActivityThread.java:6990)
at java.lang.reflect.Method.invoke(Native Method)
at com.android.internal.os.RuntimeInit$MethodAndArgsCaller.run(RuntimeInit.java:493)
at com.android.internal.os.ZygoteInit.main(ZygoteInit.java:1445)

************ APP INFORMATION ************
ID: com.nextcloud.client
Version: 30080190
Build flavor: gplay

************ DEVICE INFORMATION ************
Brand: samsung
Device: crownlte
Model: SM-N960F
Id: PPR1.180610.011
Product: crownltexx

************ FIRMWARE ************
SDK: 28
Release: 9
Incremental: N960FXXS3CSI5

[AndyScherzinger]

************ CAUSE OF ERROR ************

android.app.RemoteServiceException: Context.startForegroundService() did not then call Service.startForeground(): ServiceRecord{a4dde14 u0 com.nextcloud.client/com.owncloud.android.services.OperationsService}
at android.app.ActivityThread$H.handleMessage(ActivityThread.java:2126)
at android.os.Handler.dispatchMessage(Handler.java:112)
at android.os.Looper.loop(Looper.java:216)
at android.app.ActivityThread.main(ActivityThread.java:7625)
at java.lang.reflect.Method.invoke(Native Method)
at com.android.internal.os.RuntimeInit$MethodAndArgsCaller.run(RuntimeInit.java:524)
at com.android.internal.os.ZygoteInit.main(ZygoteInit.java:987)

************ APP INFORMATION ************
ID: com.nextcloud.client
Version: 30080190
Build flavor: gplay

************ DEVICE INFORMATION ************
Brand: HONOR
Device: HWBKL
Model: BKL-L09
Id: HUAWEIBKL-L09S
Product: BKL-L09

************ FIRMWARE ************
SDK: 28
Release: 9
Incremental: 329C432

[AndyScherzinger]

@tobiasKaminsky I added all remaining issues regarding this stack trace and closed them in favor of this one.

[hao41815w]

So how did you fix this issue?
Can you help me?
This is my code, but it has this issue when the app is running.

~~
@Override
public void onCreate() {
Log.i(TAG, "service create");
startForeground(NOTIFICATION_ID, createNotification(this));
....
if (Build.VERSION.SDK_INT < Build.VERSION_CODES.O) {
ContextCompat.startForegroundService(this, new Intent(this, HideNotificationService.class));
}
}

[AndyScherzinger]

@tobiasKaminsky I added all new issues regarding this stack trace and closed them in favor of this one. Als marked it as high since we keep getting reports for it. Your list of areas https://github.com/nextcloud/android/issues/2010#issuecomment-540008236 seems complete for the moment.

[rcdailey]

I don't think we need a notification per file downloaded either. Just overall progress.

[IgorGanapolsky]

The solution to this issue is to call startForeground in the onCreate() method

[tobiasKaminsky]

https://github.com/nextcloud/android/blob/dd1a192650113bf1238bb674710971e7d2cd5f27/src/main/java/com/owncloud/android/files/services/FileUploader.java#L927-L931

We are explicitly using startForegroundService here.
Doc says:

Similar to startService(Intent), but with an implicit promise that the Service will call startForeground(int, android.app.Notification) once it begins running. The service is given an amount of time comparable to the ANR interval to do this, otherwise the system will automatically stop the service and declare the app ANR.
Unlike the ordinary startService(Intent), this method can be used at any time, regardless of whether the app hosting the service is in a foreground state.

So it "just" seems that time between starting FileUploader via startForegroundService and the real
https://github.com/nextcloud/android/blob/dd1a192650113bf1238bb674710971e7d2cd5f27/src/main/java/com/owncloud/android/files/services/FileUploader.java#L282

is too long.
But onStartCommand seems to be started directly after startForegroundService(…), at least for me.

@IgorGanapolsky onCreate is used only once on app start, as far as I can see.

[InfamousUser]

Still happening on 3.13 RC4, app unusable for months due to an abundance of bugs, crashes and ANRs.

*** CAUSE OF ERROR ***

android.app.RemoteServiceException: Context.startForegroundService() did not then call Service.startForeground(): ServiceRecord{895d5b4 u0 com.nextcloud.client/com.owncloud.android.files.services.FileUploader}
at android.app.ActivityThread$H.handleMessage(ActivityThread.java:1945)
at android.os.Handler.dispatchMessage(Handler.java:107)
at android.os.Looper.loop(Looper.java:214)
at android.app.ActivityThread.main(ActivityThread.java:7356)
at java.lang.reflect.Method.invoke(Native Method)
at com.android.internal.os.RuntimeInit$MethodAndArgsCaller.run(RuntimeInit.java:492)
at com.android.internal.os.ZygoteInit.main(ZygoteInit.java:930)

[InfamousUser]

Any news on this?

[tobiasKaminsky]

Do you know when exactly this is happening?
We have this foreground service in many places

[InfamousUser]

Well I can tell you about one time it happens consistently. If I open up uploads menu, it almost always crashes, but the report dialogue with the error only appears maybe every 5th - 10th time. It lags and freezes and then just crashes. I presume it's the same error.

[tobiasKaminsky]

uploads menu

Do you mean the view where you can see all outstanding/failed uploads?

[InfamousUser]

Yes. A single place in the universe where I can go when I want to guarantee a crash!

[tobiasKaminsky]

So it "just" seems that time between starting FileUploader via startForegroundService and the real

https://github.com/nextcloud/android/blob/dd1a192650113bf1238bb674710971e7d2cd5f27/src/main/java/com/owncloud/android/files/services/FileUploader.java#L282

I tried to trigger this and added 30s delay in onStartCommand(…).
On Android 10 I "only" get a "app not responding", but no crash.

@InfamousUser which device do you use? Maybe I can reproduce it there…

[InfamousUser]

Google Pixel 2. I do get a lot of ANRs and ~app stopped~ in the background when it is uploading. I plug the charger in (which triggers autoupload) and it pops up every so often. I think it slowed down on the last RC1 release or penultimate release, I had the app force stopped for several months because it was unusable so I wasn't paying so much attention anymore. If you need any more details I'm happy to help get this resolved for me and everyone who might be having the same issue.

Edit: It basically always displays homescreen (I assume this is same as "crash") while using the app if I go to uploads and try to scroll around. I should have said that it doesn't always crash if I don't try to scroll. When I scroll it freezes and displays homescreen after maybe 10 seconds, then homescreen is just a picture, none of the on-screen controls work for next 20 or so seconds, then it displays ANR but at this point it has kicked me out of the app, the app isn't usable and phone isn't usable for at least 30 seconds. And then sometimes it displays that crash text on next app start, most often it doesn't (does that mean that it hasn't crash or not idk) but it kicks me out of the app.

Also the uploads take like 10-15 seconds per single file (they're very small files), whole auto-upload seems very slow.

[tobiasKaminsky]

Can you see how many pending uploads you have?
While it can happen that the app does not respond (ANR) it should not kill using rest of your device.
Can you reboot, make sure that none other apps are open and see if this somehow performs better?

[InfamousUser]

There's about 120, there's always around that number, it goes through them one by one. If I keep the uploads menu open, it goes towards zero slowly, it's very slow, I never actually waited more than until maybe 70. But when I'm not on that tab/I'm in the background, it queues the uploads up to around 110-120 queued. Sometimes if I don't touch anything, it keeps showing that screen and slowly uploading (approx. 0.1 item/s), if I try to scroll, it lags/freezes and eventually crashes/doesn't respond.

I tried the following: close all the apps from the recent or overview or whateverItsCalled list, reboot, wait until it fully powers up and starts, then wait 2 mins to make sure it has stabilized, still nothing in recent apps list. I then open Nextcloud, go to uploads, it now "waits to exit power saving mode", I plug the charger in and it goes out of power saving mode and starts uploading -> Nextcloud immediately crashes to begin with. Then I open up Nextcloud and go to uploads menu, it freezes again, whole OS doesn't respond to input, power button will work and fingerprint sensor works to turn off and on the phone, but the touchscreen interface is frozen, after about 20 seconds it unlocks and I get to use my phone again.

I have not turned off any background apps or services, it would be a humongous pain to enumerate and disable (if they can be disabled) all the apps that run without me opening them.

Amusingly it says that Nextcloud has stopped/keeps stopping but I cannot interact with the dialogue box to close it because Nextcloud is keeping the phone from being used for half a minute until it's ready to be used again.

As a side question, as you are developer, is there any way to close and prevent apps from opening by themselves in Android? I mean I can try to close them but some apps turn right back on in the background.

[InfamousUser]

Still happening on 3.14 RC2. Just opened the app to find one file.

[tobiasKaminsky]

There is an APK file in PR #7340, which you can install in parallel to your existing Nextcloud app.
It would be great if you can verify the fix.