Occasional Embedded Social SDK crash after updating to target Android 8.0 (API level 26) #933

barbeau · 2018-11-21T16:32:50Z

Summary:

After bumping to targetSdkVersion 26, when restarting the app from Android Studio I'm seeing this relatively frequently:

    Process: com.joulespersecond.seattlebusbot, PID: 21328
    java.lang.RuntimeException: Unable to create application org.onebusaway.android.app.Application: java.lang.IllegalStateException: Not allowed to start service Intent { act=com.joulespersecond.seattlebusbot.BACKGROUND_INIT cmp=com.joulespersecond.seattlebusbot/com.microsoft.embeddedsocial.service.WorkerService (has extras) }: app is in background uid UidRecord{193ccd9 u0a700 CEM  idle procs:1 seq(0,0,0)}
        at android.app.ActivityThread.handleBindApplication(ActivityThread.java:6059)
        at android.app.ActivityThread.-wrap1(Unknown Source:0)
        at android.app.ActivityThread$H.handleMessage(ActivityThread.java:1764)
        at android.os.Handler.dispatchMessage(Handler.java:105)
        at android.os.Looper.loop(Looper.java:164)
        at android.app.ActivityThread.main(ActivityThread.java:6938)
        at java.lang.reflect.Method.invoke(Native Method)
        at com.android.internal.os.Zygote$MethodAndArgsCaller.run(Zygote.java:327)
        at com.android.internal.os.ZygoteInit.main(ZygoteInit.java:1374)
     Caused by: java.lang.IllegalStateException: Not allowed to start service Intent { act=com.joulespersecond.seattlebusbot.BACKGROUND_INIT cmp=com.joulespersecond.seattlebusbot/com.microsoft.embeddedsocial.service.WorkerService (has extras) }: app is in background uid UidRecord{193ccd9 u0a700 CEM  idle procs:1 seq(0,0,0)}
        at android.app.ContextImpl.startServiceCommon(ContextImpl.java:1538)
        at android.app.ContextImpl.startService(ContextImpl.java:1484)
        at android.content.ContextWrapper.startService(ContextWrapper.java:663)
        at com.microsoft.embeddedsocial.base.service.ServiceLauncher.launchService(ServiceLauncher.java:49)
        at com.microsoft.embeddedsocial.base.service.ServiceLauncher.launchService(ServiceLauncher.java:39)
        at com.microsoft.embeddedsocial.sdk.EmbeddedSocial.init(EmbeddedSocial.java:102)
        at org.onebusaway.android.app.Application.setUpSocial(Application.java:581)
        at org.onebusaway.android.app.Application.onCreate(Application.java:111)
        at android.app.Instrumentation.callApplicationOnCreate(Instrumentation.java:1125)
        at android.app.ActivityThread.handleBindApplication(ActivityThread.java:6056)
        at android.app.ActivityThread.-wrap1(Unknown Source:0) 
        at android.app.ActivityThread$H.handleMessage(ActivityThread.java:1764) 
        at android.os.Handler.dispatchMessage(Handler.java:105) 
        at android.os.Looper.loop(Looper.java:164) 
        at android.app.ActivityThread.main(ActivityThread.java:6938) 
        at java.lang.reflect.Method.invoke(Native Method) 
        at com.android.internal.os.Zygote$MethodAndArgsCaller.run(Zygote.java:327) 
        at com.android.internal.os.ZygoteInit.main(ZygoteInit.java:1374)

This crash is related to background executions limits introduced on Oreo:
https://developer.android.com/about/versions/oreo/background

Steps to reproduce:

Use Fix #330 - Change to runtime permissions #930 (or after that PR is merged, the master branch)
Launch the app from Android Studio
Make a code change, and re-launch the app from Android Studio while the app is still running

or

Restart your device
Long-press the OBA icon on your screen and move it around without dropping it

@acrown-msft is investigating to see if this occurs in other direct user-facing cases

Expected behavior:

Not crash

Observed behavior:

Crash

Device and Android version:

Samsung Galaxy S8+ w/ Android 8.0

The text was updated successfully, but these errors were encountered:

barbeau · 2018-11-29T20:13:28Z

Here's another occurrence - if you long press the home screen icon, you'll get this stack trace (EDIT - this isn't always reproducible?):

2018-11-29 15:09:28.682 14940-15033/com.joulespersecond.seattlebusbot I/vndksupport: sphal namespace is not configured for this process. Loading /vendor/lib64/egl/libEGL_adreno.so from the current namespace instead.
2018-11-29 15:09:28.691 14940-15033/com.joulespersecond.seattlebusbot D/libEGL: loaded /vendor/lib64/egl/libEGL_adreno.so
2018-11-29 15:09:28.757 14940-14940/com.joulespersecond.seattlebusbot I/MultiDex: VM with version 2.1.0 has multidex support
2018-11-29 15:09:28.757 14940-14940/com.joulespersecond.seattlebusbot I/MultiDex: Installing application
2018-11-29 15:09:28.757 14940-14940/com.joulespersecond.seattlebusbot I/MultiDex: VM has multidex support, MultiDex support library is disabled.
2018-11-29 15:09:28.766 14940-15033/com.joulespersecond.seattlebusbot I/vndksupport: sphal namespace is not configured for this process. Loading /vendor/lib64/egl/libGLESv1_CM_adreno.so from the current namespace instead.
2018-11-29 15:09:28.769 14940-15033/com.joulespersecond.seattlebusbot D/libEGL: loaded /vendor/lib64/egl/libGLESv1_CM_adreno.so
2018-11-29 15:09:28.955 14940-14940/com.joulespersecond.seattlebusbot D/FirebaseApp: com.google.firebase.auth.FirebaseAuth is not linked. Skipping initialization.
2018-11-29 15:09:28.980 14940-14940/com.joulespersecond.seattlebusbot D/FirebaseApp: com.google.firebase.crash.FirebaseCrash is not linked. Skipping initialization.
2018-11-29 15:09:29.099 14940-14940/com.joulespersecond.seattlebusbot V/FA: Registered activity lifecycle callback
2018-11-29 15:09:29.112 14940-14940/com.joulespersecond.seattlebusbot I/FirebaseInitProvider: FirebaseApp initialization successful
2018-11-29 15:09:29.155 14940-14940/com.joulespersecond.seattlebusbot I/InstantRun: starting instant run server: is main process
2018-11-29 15:09:29.383 14940-14940/com.joulespersecond.seattlebusbot I/System.out: O311C: INFO Log level changed: DEBUG
2018-11-29 15:09:29.384 14940-14940/com.joulespersecond.seattlebusbot I/System.out: O311C: INFO Dry run mode changed: true
2018-11-29 15:09:29.384 14940-14940/com.joulespersecond.seattlebusbot W/Application: Open311 issue reporting is in debug/dry run mode - no issues will be submitted.
2018-11-29 15:09:29.384 14940-14940/com.joulespersecond.seattlebusbot I/System.out: O311C: INFO clearOpen311
2018-11-29 15:09:29.486 14940-15060/com.joulespersecond.seattlebusbot V/FA: Collection enabled
2018-11-29 15:09:29.486 14940-15060/com.joulespersecond.seattlebusbot V/FA: App package, google app id: com.joulespersecond.seattlebusbot, 1:297287630784:android:47d1e05cfc58f0b8
2018-11-29 15:09:29.488 14940-15060/com.joulespersecond.seattlebusbot I/FA: App measurement is starting up, version: 12451
2018-11-29 15:09:29.488 14940-15060/com.joulespersecond.seattlebusbot I/FA: To enable debug logging run: adb shell setprop log.tag.FA VERBOSE
2018-11-29 15:09:29.488 14940-15060/com.joulespersecond.seattlebusbot I/FA: To enable faster debug mode event logging run:
      adb shell setprop debug.firebase.analytics.app com.joulespersecond.seattlebusbot
2018-11-29 15:09:29.488 14940-15060/com.joulespersecond.seattlebusbot D/FA: Debug-level message logging enabled
2018-11-29 15:09:29.704 14940-15060/com.joulespersecond.seattlebusbot V/FA: Connecting to remote service
2018-11-29 15:09:29.850 14940-15060/com.joulespersecond.seattlebusbot V/FA: Connection attempt already in progress
2018-11-29 15:09:30.031 14940-15033/com.joulespersecond.seattlebusbot I/vndksupport: sphal namespace is not configured for this process. Loading /vendor/lib64/egl/libGLESv2_adreno.so from the current namespace instead.
2018-11-29 15:09:30.048 14940-15033/com.joulespersecond.seattlebusbot D/libEGL: loaded /vendor/lib64/egl/libGLESv2_adreno.so
2018-11-29 15:09:30.146 14940-15094/com.joulespersecond.seattlebusbot W/Settings: Setting airplane_mode_on has moved from android.provider.Settings.System to android.provider.Settings.Global, returning read-only value.
2018-11-29 15:09:30.397 14940-14940/com.joulespersecond.seattlebusbot D/AndroidRuntime: Shutting down VM
2018-11-29 15:09:30.403 14940-14940/com.joulespersecond.seattlebusbot E/AndroidRuntime: FATAL EXCEPTION: main
    Process: com.joulespersecond.seattlebusbot, PID: 14940
    java.lang.RuntimeException: Unable to create application org.onebusaway.android.app.Application: java.lang.IllegalStateException: Not allowed to start service Intent { act=com.joulespersecond.seattlebusbot.BACKGROUND_INIT cmp=com.joulespersecond.seattlebusbot/com.microsoft.embeddedsocial.service.WorkerService (has extras) }: app is in background uid UidRecord{2c54c68 u0a735 CEM  idle procs:1 seq(0,0,0)}
        at android.app.ActivityThread.handleBindApplication(ActivityThread.java:6059)
        at android.app.ActivityThread.-wrap1(Unknown Source:0)
        at android.app.ActivityThread$H.handleMessage(ActivityThread.java:1764)
        at android.os.Handler.dispatchMessage(Handler.java:105)
        at android.os.Looper.loop(Looper.java:164)
        at android.app.ActivityThread.main(ActivityThread.java:6938)
        at java.lang.reflect.Method.invoke(Native Method)
        at com.android.internal.os.Zygote$MethodAndArgsCaller.run(Zygote.java:327)
        at com.android.internal.os.ZygoteInit.main(ZygoteInit.java:1374)
     Caused by: java.lang.IllegalStateException: Not allowed to start service Intent { act=com.joulespersecond.seattlebusbot.BACKGROUND_INIT cmp=com.joulespersecond.seattlebusbot/com.microsoft.embeddedsocial.service.WorkerService (has extras) }: app is in background uid UidRecord{2c54c68 u0a735 CEM  idle procs:1 seq(0,0,0)}
        at android.app.ContextImpl.startServiceCommon(ContextImpl.java:1538)
        at android.app.ContextImpl.startService(ContextImpl.java:1484)
        at android.content.ContextWrapper.startService(ContextWrapper.java:663)
        at com.microsoft.embeddedsocial.base.service.ServiceLauncher.launchService(ServiceLauncher.java:49)
        at com.microsoft.embeddedsocial.base.service.ServiceLauncher.launchService(ServiceLauncher.java:39)
        at com.microsoft.embeddedsocial.sdk.EmbeddedSocial.init(EmbeddedSocial.java:102)
        at org.onebusaway.android.app.Application.setUpSocial(Application.java:590)
        at org.onebusaway.android.app.Application.onCreate(Application.java:118)
        at android.app.Instrumentation.callApplicationOnCreate(Instrumentation.java:1125)
        at android.app.ActivityThread.handleBindApplication(ActivityThread.java:6056)
        at android.app.ActivityThread.-wrap1(Unknown Source:0) 
        at android.app.ActivityThread$H.handleMessage(ActivityThread.java:1764) 
        at android.os.Handler.dispatchMessage(Handler.java:105) 
        at android.os.Looper.loop(Looper.java:164) 
        at android.app.ActivityThread.main(ActivityThread.java:6938) 
        at java.lang.reflect.Method.invoke(Native Method) 
        at com.android.internal.os.Zygote$MethodAndArgsCaller.run(Zygote.java:327) 
        at com.android.internal.os.ZygoteInit.main(ZygoteInit.java:1374)

barbeau · 2018-11-29T21:21:04Z

One workaround solution for now would be to check if the Application code is running in the background before initializing ES - for example:
https://stackoverflow.com/a/48767617/937715

We can use the LifecycleOwner to get Lifecycle.getCurrentState()

barbeau · 2018-11-30T14:10:26Z

@acrown-msft is working on a new release of the ES SDK that, IIRC, does lazy initialization of some items, which would avoid these background execution issues. We can test after updating the ES SDK to see if these issues still pop up.

barbeau · 2018-12-01T05:21:21Z

Unfortunately the ES SDK bump didn't seem to solve the crash when moving the icon on the home screen. Reopening...

barbeau · 2018-12-06T20:22:25Z

For future purposes - looks like WorkManager is the best long-term solution for ES SDK.

As a short-term workaround I'm going to try checking to see if the app is running in the background via LifecycleOwner before initializing the ES SDK in our Application object.

barbeau · 2018-12-07T16:24:27Z

@acrown-msft I think I may have figured out a way to consistently reproduce this:

Restart your device
Do NOT tap on the OBA icon to launch the application
Instead, long-press on the OBA application icon and drag it around without dropping it

Here's what I think is happening:

On device restart, we have a BootstrapService that runs to check and see if any reminders need to be registered. This triggers the Application.onCreate() in the background, which executes setUpSocial(); to initialize the ES SDK, but causes the ES Service to crash with the IllegalStateException for running in the background.
In the ES SDK, AbstractProcessingService.onStartCommand() returns START_STICKY, which tells the Android platform to reschedule the service for future execution if it's interrupted before explicitly shutting itself down
Long-pressing the OBA icon causes the Android platform to reschedule the ES Service immediately and try to run it again in the background, which results in another IllegalStateException crash for running in the background.
2 and 3 above continue to loop, with Android occasionally rescheduling the ES Service. If that reschedule happens while the app is still in the background, then another crash occurs and the cycle continues.

@acrown-msft Do you think you could mitigate this issue by returning START_NOT_STICKY from AbstractProcessingService.onStartCommand() instead, and doing another release of the ES SDK?

https://developer.android.com/reference/android/app/Service#START_NOT_STICKY

This way if the ES Service crashes, it won't be launched again unless it's explicitly started by the OBA app code, so we won't get into the infinite crash loop.

barbeau · 2018-12-07T19:57:38Z

To hopefully avoid starting the ES Services in the background at all, I'm moving initialization of ES SDK into a callback that only executes when the app comes into the foreground - implementation in #940.

barbeau · 2018-12-07T19:59:51Z

And, @acrown-msft just implemented the use of START_NOT_STICKY for the ES SDK in #941.

* onStart() gets called for each Activity start, which can execute the init more than once in the App lifecycle. This patch changes to a synchronized method with a boolean flag to ensure ES is only initialized once in the Application lifecycle

barbeau added the bug label Nov 21, 2018

barbeau added this to the v2.3.x milestone Nov 21, 2018

This was referenced Nov 21, 2018

Fix #330 - Change to runtime permissions #930

Merged

Reminders don't reschedule after reboot when targeting Android 8.0 (API level 26) #934

Closed

Google Play warning - app doesn't target API level 26 #884

Closed

barbeau closed this as completed in b57e2b9 Nov 30, 2018

barbeau reopened this Dec 1, 2018

acrown-msft mentioned this issue Dec 7, 2018

Make services not sticky so that they only run when the app is in the… microsoft/EmbeddedSocial-Android-SDK#109

Merged

acrown-msft mentioned this issue Dec 7, 2018

Update ES SDK version so that services are not sticky #941

Merged

3 tasks

barbeau mentioned this issue Dec 7, 2018

Fix #933 - Only initialize ES SDK when app is in foreground #940

Merged

barbeau closed this as completed in b26a973 Dec 7, 2018

acrown-msft mentioned this issue Dec 19, 2018

Bump ES version for AndroidX and newest Firebase libraries #955

Merged

3 tasks

acrown-msft mentioned this issue Apr 8, 2019

Use the newest version of the Embedded Social SDK which removed backg… #971

Closed

3 tasks

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

Occasional Embedded Social SDK crash after updating to target Android 8.0 (API level 26) #933

Occasional Embedded Social SDK crash after updating to target Android 8.0 (API level 26) #933

barbeau commented Nov 21, 2018 •

edited

Loading

barbeau commented Nov 29, 2018 •

edited

Loading

barbeau commented Nov 29, 2018

barbeau commented Nov 30, 2018

barbeau commented Dec 1, 2018

barbeau commented Dec 6, 2018 •

edited

Loading

barbeau commented Dec 7, 2018

barbeau commented Dec 7, 2018

barbeau commented Dec 7, 2018

Occasional Embedded Social SDK crash after updating to target Android 8.0 (API level 26) #933

Occasional Embedded Social SDK crash after updating to target Android 8.0 (API level 26) #933

Comments

barbeau commented Nov 21, 2018 • edited Loading

barbeau commented Nov 29, 2018 • edited Loading

barbeau commented Nov 29, 2018

barbeau commented Nov 30, 2018

barbeau commented Dec 1, 2018

barbeau commented Dec 6, 2018 • edited Loading

barbeau commented Dec 7, 2018

barbeau commented Dec 7, 2018

barbeau commented Dec 7, 2018

barbeau commented Nov 21, 2018 •

edited

Loading

barbeau commented Nov 29, 2018 •

edited

Loading

barbeau commented Dec 6, 2018 •

edited

Loading