Android: FileObserverService: use startForegroundService on Oreo and later

[jesmrec]

Actual behaviour

The ownCloud Android app crashes

Expected behaviour

The ownCloud Android app shouldn't crash

Steps to reproduce

1. Install the ownCloud Android app.
2. Login.
3. Restart the device.
4. Wait 10-15 seconds.

Can this problem be reproduced with the official owncloud server?
Yes

Environment data

Android version: 8.0.0

Device model: Nexus 5X

Stock or customized system: Stock

ownCloud app version: 2.6.0

Research by @invisiblek:

In API 26 and higher, startForegroundService needs to be used. This fixes the following crash upon device boot:

AndroidRuntime: java.lang.RuntimeException: Unable to start receiver com.owncloud.android.broadcastreceivers.BootupBroadcastReceiver: java.lang.IllegalStateException: Not allowed to start service Intent
{ act=com.owncloud.android.services.observer.FileObserverService.action.START_OBSERVATION cmp=com.owncloud.android/.services.observer.FileObserverService }:
app is in background uid UidRecord{783d156 u0a93 RCVR idle change:uncached procs:1 seq(0,0,0)}

Reference: https://developer.android.com/about/versions/oreo/background.html#migration

Related: https://github.com/owncloud/android/pull/2110

[davigonz]

Hi @jesmrec , have you tried this out? Do we have steps to reproduce?

[jesmrec]

not yet

[davigonz]

As @invisiblek mentioned here , avoiding this crash is not so easy since is related to the current implementation of available offline feature.

Most part of the code involved in available offline feature belongs to FileObserverService, a service we try to keep alive as long as possible to watch for local
changes in favorite files and try to synchronize them with the OC server as soon as possible.

Taking into account what I explained above and that latest versions of Android should be killing the FileObserverService at some point, I'm wondering whether available offline is working fine in latest Android versions.

We could fix the crash described here by using startForegroundService and startForeground with a notification, but since we are keeping alive FileObserverService and not stopping it, the notification will not disappear.

So, I suspect we have to replace the current available offline implementation with jobs, as we did with instant upload and camera upload feature, since favourite files synchronization cannot be triggered as soon as possible if FileObserverService is killed.

Anyway, @jesmrec have you noticed any strange behaviour with available offline feature in latest Android versions? Thanks.

[jesmrec]

anything wrong detected in the version in which we adapt to Android O. But i will perform a sanity to the av. offline feature using Android O and N.

[davigonz]

anything wrong detected in the version in which we adapt to Android O. But i will perform a sanity to the av. offline feature using Android O and N.

@jesmrec Ok thanks, please put the focus on keeping the app in background and changing favourite files locally, to see if they are automatically synchronized with the OC server.

[jesmrec]

i have checked this issue with a Nexus device with Android 8 and i could not reproduce the problem, including files or folders with offline availability. More clues are welcome...

[davigonz]

Trying to reproduce this again...

[ghost]

Same issue on honor 9 under oreo 8.1 AOSP treble. On reboot the app crash everytime. Is it possible to make owncloud autostart off on boot ? App version 2.7.0 thanks

[davigonz]

Same issue on honor 9 under oreo 8.1 AOSP treble. On reboot the app crash everytime. Is it possible to make owncloud autostart off on boot ?

Hi @AqwelF , thanks for reporting this, are you using available offline feature? If so, have you noticed any strange behaviour while using it?

[ghost]

How could i know if i use it ? I only install owncloud from fdroid, add my server, reboot phone, crash... Do you want a catlog or something else ?

Log :

07-05 15:44:00.456 W/SyncManager(865): Failure adding authority: account=owncloud auth=org.dmfs.tasks enabled=false syncable=0
07-05 15:47:16.023 E/SyncManager(865): Couldn't find backoff values for owncloud/org.dmfs.tasks:u0
07-05 15:47:22.193 I/AppUpdateStatusService(2230): com.owncloud.android:20700000 is NOT pending install, probably just left over from a previous install.
07-05 15:47:22.270 I/ActivityManager(865): Start proc 2365:com.owncloud.android/u0a70 for broadcast com.owncloud.android/.broadcastreceivers.BootupBroadcastReceiver
07-05 15:47:22.486 W/ActivityManager(865): Background start not allowed: service Intent { act=com.owncloud.android.services.observer.FileObserverService.action.START_OBSERVATION cmp=com.owncloud.android/.services.observer.FileObserverService } to com.owncloud.android/.services.observer.FileObserverService from pid=2365 uid=10070 pkg=com.owncloud.android
07-05 15:47:22.500 E/AndroidRuntime(2365): Process: com.owncloud.android, PID: 2365
07-05 15:47:22.500 E/AndroidRuntime(2365): java.lang.RuntimeException: Unable to start receiver com.owncloud.android.broadcastreceivers.BootupBroadcastReceiver: java.lang.IllegalStateException: Not allowed to start service Intent { act=com.owncloud.android.services.observer.FileObserverService.action.START_OBSERVATION cmp=com.owncloud.android/.services.observer.FileObserverService }: app is in background uid UidRecord{b63984b u0a70 RCVR idle change:uncached procs:1 seq(0,0,0)}
07-05 15:47:22.500 E/AndroidRuntime(2365): Caused by: java.lang.IllegalStateException: Not allowed to start service Intent { act=com.owncloud.android.services.observer.FileObserverService.action.START_OBSERVATION cmp=com.owncloud.android/.services.observer.FileObserverService }: app is in background uid UidRecord{b63984b u0a70 RCVR idle change:uncached procs:1 seq(0,0,0)}
07-05 15:47:22.500 E/AndroidRuntime(2365):  at com.owncloud.android.services.observer.FileObserverService.initialize(FileObserverService.java:102)
07-05 15:47:22.500 E/AndroidRuntime(2365):  at com.owncloud.android.broadcastreceivers.BootupBroadcastReceiver.onReceive(BootupBroadcastReceiver.java:55)
07-05 15:47:22.574 I/ActivityManager(865): Showing crash dialog for package com.owncloud.android u0
07-05 15:47:22.582 D/ThumbnailsCacheManager(2365): create dir: /storage/emulated/0/#/data/com.owncloud.android/cache/thumbnailCache
07-05 15:47:26.201 I/ActivityManager(865): Killing 2365:com.owncloud.android/u0a70 (adj 904): crash

[theScrabi]

if you mark a file as offline available then you use it. The file will have a yellow down arrow attached to it.

[ghost]

Its work fine if i do so, no probleme with download file or sync offline file.

The prob appears only on reboot after 7 to 10 sec the app crash.

[jesmrec]

i reproduced the problem by adding an URL to setup.xml file, building and installing the app / rebooting the device

Stracktrace when installing:

08-14 17:36:17.795 23260-23260/com.owncloud.android.debug E/AndroidRuntime: FATAL EXCEPTION: main
    Process: com.owncloud.android.debug, PID: 23260
    java.lang.IllegalStateException: Can not perform this action after onSaveInstanceState
        at android.support.v4.app.FragmentManagerImpl.checkStateLoss(FragmentManager.java:2053)
        at android.support.v4.app.FragmentManagerImpl.enqueueAction(FragmentManager.java:2079)
        at android.support.v4.app.BackStackRecord.commitInternal(BackStackRecord.java:678)
        at android.support.v4.app.BackStackRecord.commit(BackStackRecord.java:632)
        at android.support.v4.app.DialogFragment.show(DialogFragment.java:160)
        at com.owncloud.android.authentication.AuthenticatorActivity.showUntrustedCertDialog(AuthenticatorActivity.java:1978)
        at com.owncloud.android.authentication.AuthenticatorActivity.onGetServerInfoFinish(AuthenticatorActivity.java:1265)
        at com.owncloud.android.authentication.AuthenticatorActivity.onRemoteOperationFinish(AuthenticatorActivity.java:1159)
        at com.owncloud.android.services.OperationsService$1.run(OperationsService.java:809)
        at android.os.Handler.handleCallback(Handler.java:790)
        at android.os.Handler.dispatchMessage(Handler.java:99)
        at android.os.Looper.loop(Looper.java:164)
        at android.app.ActivityThread.main(ActivityThread.java:6494)
        at java.lang.reflect.Method.invoke(Native Method)
        at com.android.internal.os.RuntimeInit$MethodAndArgsCaller.run(RuntimeInit.java:438)
        at com.android.internal.os.ZygoteInit.main(ZygoteInit.java:807)

Stracktrace when rebooting the device:

08-14 17:42:04.489 6058-6058/com.owncloud.android.debug E/AndroidRuntime: FATAL EXCEPTION: main
    Process: com.owncloud.android.debug, PID: 6058
    java.lang.RuntimeException: Unable to start receiver com.owncloud.android.broadcastreceivers.BootupBroadcastReceiver: java.lang.IllegalStateException: Not allowed to start service Intent { act=com.owncloud.android.services.observer.FileObserverService.action.START_OBSERVATION cmp=com.owncloud.android.debug/com.owncloud.android.services.observer.FileObserverService }: app is in background uid UidRecord{c2b1975 u0a1427 RCVR idle change:uncached procs:1 seq(0,0,0)}
        at android.app.ActivityThread.handleReceiver(ActivityThread.java:3194)
        at android.app.ActivityThread.-wrap17(Unknown Source:0)
        at android.app.ActivityThread$H.handleMessage(ActivityThread.java:1672)
        at android.os.Handler.dispatchMessage(Handler.java:106)
        at android.os.Looper.loop(Looper.java:164)
        at android.app.ActivityThread.main(ActivityThread.java:6494)
        at java.lang.reflect.Method.invoke(Native Method)
        at com.android.internal.os.RuntimeInit$MethodAndArgsCaller.run(RuntimeInit.java:438)
        at com.android.internal.os.ZygoteInit.main(ZygoteInit.java:807)
     Caused by: java.lang.IllegalStateException: Not allowed to start service Intent { act=com.owncloud.android.services.observer.FileObserverService.action.START_OBSERVATION cmp=com.owncloud.android.debug/com.owncloud.android.services.observer.FileObserverService }: app is in background uid UidRecord{c2b1975 u0a1427 RCVR idle change:uncached procs:1 seq(0,0,0)}
        at android.app.ContextImpl.startServiceCommon(ContextImpl.java:1521)
        at android.app.ContextImpl.startService(ContextImpl.java:1477)
        at android.content.ContextWrapper.startService(ContextWrapper.java:650)
        at android.content.ContextWrapper.startService(ContextWrapper.java:650)
        at com.owncloud.android.services.observer.FileObserverService.initialize(FileObserverService.java:102)
        at com.owncloud.android.broadcastreceivers.BootupBroadcastReceiver.onReceive(BootupBroadcastReceiver.java:55)
        at android.app.ActivityThread.handleReceiver(ActivityThread.java:3187)
        at android.app.ActivityThread.-wrap17(Unknown Source:0) 
        at android.app.ActivityThread$H.handleMessage(ActivityThread.java:1672) 
        at android.os.Handler.dispatchMessage(Handler.java:106) 
        at android.os.Looper.loop(Looper.java:164) 
        at android.app.ActivityThread.main(ActivityThread.java:6494) 
        at java.lang.reflect.Method.invoke(Native Method) 
        at com.android.internal.os.RuntimeInit$MethodAndArgsCaller.run(RuntimeInit.java:438) 
        at com.android.internal.os.ZygoteInit.main(ZygoteInit.java:807) 

[Patriack]

Hi,
I have this issue at this moment. Have you made some progress?
Thank.

[jesmrec]

@Patriack it is in our minds to be fixed asap.

[Patriack]

So,
I find a fix, but my issue come from firebase. I hope that can help you, but I not expect that so much.
The issue was caused by firebase, who's got an update who avoid to set an boot completed service. So my fix was ​​to not start the service for any android version up from marshmallow.

[fmkaiser]

@davigonz As discussed here is one of the traces from our branded clients

Aug 25, 10:31 AM on app version 20800000
Sony Xperia X Compact (F5321), Android 8.0
Report 1 of 2
java.lang.RuntimeException: 
  at android.app.ActivityThread.handleReceiver (ActivityThread.java:3267)
  at android.app.ActivityThread.-wrap17 (Unknown Source)
  at android.app.ActivityThread$H.handleMessage (ActivityThread.java:1685)
  at android.os.Handler.dispatchMessage (Handler.java:105)
  at android.os.Looper.loop (Looper.java:251)
  at android.app.ActivityThread.main (ActivityThread.java:6589)
  at java.lang.reflect.Method.invoke (Native Method)
  at com.android.internal.os.Zygote$MethodAndArgsCaller.run (Zygote.java:240)
  at com.android.internal.os.ZygoteInit.main (ZygoteInit.java:767)
Caused by: java.lang.IllegalStateException: 
  at android.app.ContextImpl.startServiceCommon (ContextImpl.java:1512)
  at android.app.ContextImpl.startService (ContextImpl.java:1468)
  at android.content.ContextW
rapper.startService (ContextWrapper.java:644)
  at android.content.ContextWrapper.startService (ContextWrapper.java:644)
  at de.mpg.mpcdf.datashare.android.services.observer.FileObserverService.initialize (FileObserverService.java:102)
  at de.mpg.mpcdf.datashare.android.broadcastreceivers.BootupBroadcastReceiver.onReceive (BootupBroadcastReceiver.java:55)
  at android.app.ActivityThread.handleReceiver (ActivityThread.java:3260)

As you can see we haven't rolled out 2.8 to production yet because we experienced the same crashes during testing. Eagerly waiting for the fix in 2.9 ;) Crashes happen a lot more frequently - pretty much a few seconds after launching the app - compared to the unbranded client.

I just had another look at a crash that happened on my Sony Xperia X / Android 8 / ownCloud (branded) 2.8.0 that does look somewhat different:

(... lot's of "removing file xxx" ...)
09-18 14:56:32.533 22903 22936 D FileContentProvider: Removing FILE 04743505525fae5733169
09-18 14:56:32.538 22903 22936 D FileContentProvider: Removing FILE 04743508525fae5733169
09-18 14:56:32.543 22903 22936 D FileContentProvider: Removing FILE 04743511525fae5733169
09-18 14:56:32.588 22903 22936 E CursorWindow: Failed to read row 1765, column 20 from a CursorWindow which has 1175 rows, 24 columns.
09-18 14:56:32.654 22903 22936 E AndroidRuntime: FATAL EXCEPTION: Thread-2
09-18 14:56:32.654 22903 22936 E AndroidRuntime: Process: de.mpg.mpcdf.datashare.android, PID: 22903
09-18 14:56:32.654 22903 22936 E AndroidRuntime: java.lang.IllegalStateException: Couldn't read row 1765, col 20 from CursorWindow.  Make sure the Cursor is initialized correctly before accessing data from it.
09-18 14:56:32.654 22903 22936 E AndroidRuntime:        at android.database.CursorWindow.nativeGetLong(Native Method)
09-18 14:56:32.654 22903 22936 E AndroidRuntime:        at android.database.CursorWindow.getLong(CursorWindow.java:511)
09-18 14:56:32.654 22903 22936 E AndroidRuntime:        at android.database.AbstractWindowedCursor.getLong(AbstractWindowedCursor.java:75)
09-18 14:56:32.654 22903 22936 E AndroidRuntime:        at de.mpg.mpcdf.datashare.android.providers.FileContentProvider.delete(FileContentProvider.java:261)
09-18 14:56:32.654 22903 22936 E AndroidRuntime:        at de.mpg.mpcdf.datashare.android.providers.FileContentProvider.delete(FileContentProvider.java:266)
09-18 14:56:32.654 22903 22936 E AndroidRuntime:        at de.mpg.mpcdf.datashare.android.providers.FileContentProvider.delete(FileContentProvider.java:224)
09-18 14:56:32.654 22903 22936 E AndroidRuntime:        at android.content.ContentProviderOperation.apply(ContentProviderOperation.java:311)
09-18 14:56:32.654 22903 22936 E AndroidRuntime:        at de.mpg.mpcdf.datashare.android.providers.FileContentProvider.applyBatch(FileContentProvider.java:692)
09-18 14:56:32.654 22903 22936 E AndroidRuntime:        at android.content.ContentProvider$Transport.applyBatch(ContentProvider.java:319)
09-18 14:56:32.654 22903 22936 E AndroidRuntime:        at android.content.ContentProviderClient.applyBatch(ContentProviderClient.java:465)
09-18 14:56:32.654 22903 22936 E AndroidRuntime:        at android.content.ContentResolver.applyBatch(ContentResolver.java:1581)
09-18 14:56:32.654 22903 22936 E AndroidRuntime:        at de.mpg.mpcdf.datashare.android.datamodel.FileDataStorageManager.saveFolder(FileDataStorageManager.java:429)
09-18 14:56:32.654 22903 22936 E AndroidRuntime:        at de.mpg.mpcdf.datashare.android.operations.SynchronizeFolderOperation.mergeRemoteFolder(SynchronizeFolderOperation.java:380)
09-18 14:56:32.654 22903 22936 E AndroidRuntime:        at de.mpg.mpcdf.datashare.android.operations.SynchronizeFolderOperation.run(SynchronizeFolderOperation.java:211)
09-18 14:56:32.654 22903 22936 E AndroidRuntime:        at de.mpg.mpcdf.datashare.android.lib.common.operations.RemoteOperation.runOperation(RemoteOperation.java:266)
09-18 14:56:32.654 22903 22936 E AndroidRuntime:        at de.mpg.mpcdf.datashare.android.lib.common.operations.RemoteOperation.execute(RemoteOperation.java:142)
09-18 14:56:32.654 22903 22936 E AndroidRuntime:        at de.mpg.mpcdf.datashare.android.operations.common.SyncOperation.execute(SyncOperation.java:91)
09-18 14:56:32.654 22903 22936 E AndroidRuntime:        at de.mpg.mpcdf.datashare.android.operations.RefreshFolderOperation.run(RefreshFolderOperation.java:144)
09-18 14:56:32.654 22903 22936 E AndroidRuntime:        at de.mpg.mpcdf.datashare.android.lib.common.operations.RemoteOperation.runOperation(RemoteOperation.java:266)
09-18 14:56:32.654 22903 22936 E AndroidRuntime:        at de.mpg.mpcdf.datashare.android.lib.common.operations.RemoteOperation.run(RemoteOperation.java:232)
09-18 14:56:32.654 22903 22936 E AndroidRuntime:        at java.lang.Thread.run(Thread.java:764)
09-18 14:56:32.657  2253  5118 D ActivityManager: New dropbox entry: de.mpg.mpcdf.datashare.android, data_app_crash, e701fc5f-c854-4037-85cc-48d15dc0a413
09-18 14:56:32.659  2253  5118 W ActivityManager:   Force finishing activity de.mpg.mpcdf.datashare.android/.ui.activity.FileDisplayActivity

Not sure if that's actually the same issue, the background service seems to get killed after a few seconds maybe be cause it is not started in the properly?

I'll be at the Nuremberg conference today and tomorrow in case a look at the device is helpful.

[davigonz]

This will be fixed in https://github.com/owncloud/android/issues/2304 so please follow up there

[davigonz]

Hi @AqwelF, @Patriack and @fmkaiser , we have just released ownCloud 2.9 beta 2 for Android in PlayStore, can you please try it out and tell us if the crashes are still present? Thanks

[PVince81]

I usually had a single crash when booting the phone. With this new version I did not see a crash.

[davigonz]

I usually had a single crash when booting the phone. With this new version I did not see a crash

Yes, that's one of the crashes we have fixed, glad to hear that, thanks for testing it 😊

[fmkaiser]

I can also confirm that the crash after booting the phone is gone on my Xperia X Compact with Android 8.0 in 2.9b2.

Looking forward to the final release of the branded version. Subjectively, we had those crashes there a lot more often than with the vanilla version. I don't suppose there is a beta for that as well?

[davigonz]

I can also confirm that the crash after booting the phone is gone on my Xperia X Compact with Android 8.0 in 2.9b2.

Looking forward to the final release of the branded version. Subjectively, we had those crashes there a lot more often than with the vanilla version. I don't suppose there is a beta for that as well?

Thanks for testing it @fmkaiser

We have fixed the crash related to the first log you reported in https://github.com/owncloud/android/issues/2124#issuecomment-422386177 , which is the most frequent in your crashes reports and what this issue is about. The fix will be included in the final 2.9 release, so you can use it in your branded version.

Regarding the second one, it might be triggered because of some kind of error when removing ownCloud files from an external app, could you collect some steps to reproduce and open a new issue with that?

[jesmrec]

To be released in 2.9.0.

Thanks all for your contributions here. Hoping for your feedback once the version is out there.

[davigonz]

@AqwelF @Patriack @fmkaiser Have you tried 2.9.0 or 2.9.1? The crash shouldn't be there anymore.

[fmkaiser]

@davigonz As mentioned wrt. the beta earlier, I can confirm that the crash doesn't happen anymore on my phone with with 2.9.0 or 2.9.1 either. We are still waiting for the 2.9 release in in ownBrander.

[jesmrec]

@AqwelF @Patriack 2.9.x versions fixed the problem. If you think the problem persists or something similar, feel free to reopen.

Thanks all for you collaboration.