[Bug]: Egregious levels of battery drain on 5.0.3

[isles1217]

What happened?

Since upgrading to OneSignal 5.x.x, we've been noticing egregious levels of battery drain that disappear after reverting back to 4.x.x. Our users have started to notice as well, and we're starting to get slammed with negative reviews on the Play Store because of this. From my observations, I'm seeing up to 20% of my device's battery getting drained AN HOUR, even with my screen off and my app backgrounded. What is going on in this new version?

Steps to reproduce?

1. Install an app running OneSignal 5.0.3
2. Measure battery usage with screen on, off, app in the foreground/background
3. Then pause/uninstall the app. Measure the battery usage.
4. Install the same app running OneSignal 4.x.x. Use the device similary, and measure the battery usage. 

You'll likely see 2-5x increase of battery consumption on 5.x.x

What did you expect to happen?

OneSignal should not eat up my device's battery

OneSignal Android SDK version

5.0.3

Android version

13

Specific Android models

* Issue occurs all devices I've tested (running Android 13, 14)
* Devices the issue was reproduced on: Google Pixel 7, 7a, 5a.

Relevant log output

--------- beginning of main
11:22:31.255  D  [main] ApplicationService.onActivityStopped(2,APP_OPEN): [com.example.application]Activity@6e1ba65
11:24:06.007  D  [main] ApplicationService.onActivityCreated(1,APP_OPEN): [com.example.application]Activity@8831df3
11:24:06.019  D  [main] ApplicationService.onActivityStarted(1,APP_OPEN): [com.example.application]Activity@6e1ba65
11:24:06.084  D  [main] ApplicationService.onActivityResumed(1,APP_OPEN): [com.example.application]Activity@6e1ba65
11:24:06.161  D  [main] InAppMessagesManager.addTrigger(key: home screen active, value: true)
11:24:06.567  D  [main] ApplicationService.onActivityDestroyed(1,APP_OPEN): [com.example.application]Activity@8831df3
11:24:09.129  D  [main] InAppMessagesManager.addTrigger(key: home screen active, value: true)
11:24:09.215  D  [main] InAppMessagesManager.addTrigger(key: home screen active, value: true)
11:24:09.344  D  [main] InAppMessagesManager.addTrigger(key: home screen active, value: true)
11:24:09.401  D  [main] InAppMessagesManager.addTrigger(key: home screen active, value: true)
11:24:18.323  D  [main] ApplicationService.onActivityPaused(1,APP_OPEN): [com.example.application]Activity@6e1ba65
11:24:18.881  D  [main] ApplicationService.onActivityStopped(1,APP_OPEN): [com.example.application]Activity@6e1ba65
11:24:18.881  D  [main] ApplicationService: current activity=null
11:24:18.881  D  [main] ApplicationService.handleLostFocus: application is now out of focus
11:24:18.882  D  [main] LocationController scheduleUpdate not possible, location shared not enabled
11:24:18.882  D  [main] OSBackgroundSync scheduleSyncServiceAsJob:atTime: 30000
11:24:18.884  I  [main] OSBackgroundSync scheduleSyncServiceAsJob:result: 1
11:24:18.884  D  [main] SessionService.onUnfocused()
11:24:26.569  D  [main] ApplicationService.onActivityCreated(0,APP_CLOSE): [com.example.application]Activity@e2efc5d
11:24:26.576  D  [main] ApplicationService.onActivityStarted(0,APP_CLOSE): [com.example.application]Activity@6e1ba65
11:24:26.576  D  [main] ApplicationService: current activity=[com.example.application]Activity@6e1ba65
11:24:26.576  D  [main] ApplicationService.handleFocus: application is now in focus, nextResumeIsFirstActivity=false
11:24:26.576  D  [main] BackgroundManager cancel background sync
11:24:26.577  D  [main] SessionService.onFocus()
11:24:26.577  D  [main] InfluenceManager.attemptSessionUpgrade(entryAction: APP_OPEN, directId: null)
11:24:26.577  D  [main] InfluenceManager.attemptSessionUpgrade: try UNATTRIBUTED to INDIRECT upgrade
11:24:26.577  D  [main] ChannelTracker.getLastReceivedIds: lastChannelObjectReceived: []
11:24:26.577  D  [main] InfluenceManager.attemptSessionUpgrade: Trackers after update attempt: [ChannelTracker{tag=notification_id, influenceType=UNATTRIBUTED, indirectIds=null, directId=null}, ChannelTracker{tag=iam_id, influenceType=INDIRECT, indirectIds=["c0d845f1-00e3-442c-9394-7223688d4d19"], directId=null}]
11:24:26.631  D  [main] ApplicationService.onActivityResumed(1,APP_OPEN): [com.example.application]Activity@6e1ba65
11:24:26.697  D  [main] InAppMessagesManager.addTrigger(key: home screen active, value: true)
11:24:27.119  D  [main] ApplicationService.onActivityDestroyed(1,APP_OPEN): [com.example.application]Activity@e2efc5d
11:24:29.032  D  [main] InAppMessagesManager.addTrigger(key: home screen active, value: true)
11:24:29.066  D  [main] InAppMessagesManager.addTrigger(key: home screen active, value: true)
11:24:29.091  D  [main] InAppMessagesManager.addTrigger(key: home screen active, value: true)
11:24:29.154  D  [main] InAppMessagesManager.addTrigger(key: home screen active, value: true)
11:24:30.180  D  [main] ApplicationService.onActivityPaused(1,APP_OPEN): [com.example.application]Activity@6e1ba65
11:24:30.219  D  [main] ApplicationService.onActivityStopped(1,APP_OPEN): [com.example.application]Activity@6e1ba65
11:24:30.219  D  [main] ApplicationService: current activity=null
11:24:30.220  D  [main] ApplicationService.handleLostFocus: application is now out of focus
11:24:30.220  D  [main] LocationController scheduleUpdate not possible, location shared not enabled
11:24:30.220  D  [main] OSBackgroundSync scheduleSyncServiceAsJob:atTime: 30000
11:24:30.223  I  [main] OSBackgroundSync scheduleSyncServiceAsJob:result: 1
11:24:30.223  D  [main] SessionService.onUnfocused()
11:26:16.211  D  [main] initWithContext(context: com.onesignal.core.services.SyncJobService@daad95, appId: null)
11:26:16.211  D  [main] Retrieving service interface com.onesignal.core.internal.background.IBackgroundManager
11:26:16.211  D  [main] Already instantiated: com.onesignal.core.internal.background.impl.BackgroundManager@fb4c446
11:26:16.212  D  [Thread-89] OSBackground sync, calling initWithContext
11:26:16.212  D  [Thread-89] SessionService.backgroundRun()
11:26:16.213  D  [Thread-89] SessionService: Session ended. activeDuration: 114001
11:26:16.213  D  [Thread-89] OperationRepo.enqueue(operation: {"name":"track-session-end","appId":"REDACTED","onesignalId":"REDACTED","sessionTime":114}, flush: false)
11:26:16.214  D  [Thread-89] LocationController scheduleUpdate not possible, location shared not enabled
11:26:16.214  D  [Thread-89] LollipopSyncRunnable:JobFinished needsJobReschedule: false
11:26:16.217  D  [DefaultDispatcher-worker-8] HttpClient: POST outcomes/measure - {"app_id":"REDACTED","onesignal_id":"REDACTED","subscription":{"id":"REDACTED","type":"AndroidPush"},"id":"os__session_duration","session_time":114}
11:26:16.407  D  [DefaultDispatcher-worker-8] HttpClient: POST outcomes/measure - STATUS: 202 JSON: {"success":true}
11:26:16.409  D  [Thread-91] OutcomeEventsCache.saveUniqueOutcomeEventParams(eventParams: OutcomeEventParams{outcomeId='os__session_duration', outcomeSource=OutcomeSource{directBody=null, indirectBody=OutcomeSourceBody{notificationIds=[], inAppMessagesIds=["c0d845f1-00e3-442c-9394-7223688d4d19"]}}, weight=0.0, timestamp=0, sessionTime=114})
11:26:16.414  D  [OpRepo] UpdateUserOperationExecutor(operation: [{"name":"track-session-end","appId":"REDACTED","onesignalId":"REDACTED","sessionTime":114,"id":"REDACTED"}])
11:26:16.415  D  [DefaultDispatcher-worker-2] HttpClient: PATCH apps/78188df7-d5e0-432d-9b41-373d5b28a4e2/users/by/onesignal_id/835d5039-d383-157a-b941-7402d862f0c1 - {"refresh_device_metadata":false,"deltas":{"session_time":114}}
11:26:16.624  D  [DefaultDispatcher-worker-2] HttpClient: PATCH apps/78188df7-d5e0-432d-9b41-373d5b28a4e2/users/by/onesignal_id/835d5039-d383-157a-b941-7402d862f0c1 - STATUS: 202 JSON: {"properties":{}}
11:26:16.625  D  [OpRepo] OperationRepo: execute response = SUCCESS

Code of Conduct

• I agree to follow this project's Code of Conduct

[emawby]

@isles1217 Thank you for reporting agreed this is high priority we are investigating.

[isles1217]

Thank you!

For added context: due to the nature of our application, our app stays alive in the background (via a foreground service) while our hardware is connected, so this battery drain can go on much longer for users of our app versus others (whereas other apps in the background would get killed by the OS after some time)

[emawby]

@isles1217 If you have any more verbose logs from devices with the battery drain did you notice any failed requests that were continuously retried while the app was in the background?

[isles1217]

@emawby I did look for excessive failure logs after seeing #1830 , but didn't find them. I am seeing a ton of logs that include the following tags:
[main] , [DefaultDispatcher-worker-14], [Thread-94], [WM.task-3], and lots of initWithContext calls, but i'm not sure how dissimilar that is to the behavior of OS 4.x.x

[emawby]

@isles1217 I am surprised about seeing lots of initWithContext calls could you share the logs with those?

[isles1217]

Anecdotally, about ten or so minutes ago, I saw initWithContext get called while my app was in the background five times, all within the span of a minute. I've substituted my app's name with com.example.app.App, but I did not remove the appId (specified here as null)

2023-10-26 11:32:42.160 27352-27352 OneSignal       D  [main] initWithContext(context: com.onesignal.core.services.SyncJobService@e461ca1, appId: null)
2023-10-26 11:32:42.162 27352-31857 OneSignal       D  [Thread-94] OSBackground sync, calling initWithContext
2023-10-26 11:33:46.441 27352-27352 OneSignal       D  [main] initWithContext(context: com.example.app.App@375a548, appId: null)
2023-10-26 11:33:46.475 27352-27352 OneSignal       D  [main] initWithContext(context: com.example.app.App@375a548, appId: null)
2023-10-26 11:33:47.632 27352-27352 OneSignal       D  [main] initWithContext(context: com.example.app.App@375a548, appId: null)
2023-10-26 11:33:47.651 27352-27352 OneSignal       D  [main] initWithContext(context: com.example.app.App@375a548, appId: null)

[emawby]

@isles1217 Do you have any ideas about why the app id is null or why init is being called multiple times in a row? If possible could you share the code that is calling init here?.

[isles1217]

@isles1217 Do you have any ideas about why the app id is null or why init is being called multiple times in a row? If possible could you share the code that is calling init here?.

No idea. We initialize OS once in a singleton. The extraneous calls were happening when the app was in the background and idle. Here's our initialization code, called from the application's onCreate():

    fun initiateOneSignal(applicationContext: Context) {
        OneSignal.setLogLevel(
            // Logcat log level
            if (BuildConfig.DEBUG) OneSignal.LOG_LEVEL.INFO else OneSignal.LOG_LEVEL.NONE,
            // Visual log level
            OneSignal.LOG_LEVEL.NONE,
        )
        OneSignal.initWithContext(applicationContext)
        OneSignal.setAppId(ONE_SIGNAL_APP_ID)
        OneSignal.addSubscriptionObserver(this)
        OneSignal.sendTag(PLATFORM_KEY, PLATFORM_VALUE)
        OneSignal.sendTag(ENVIRONMENT_KEY, environment)
    }

[hannojg]

Just wanting to chip in, and let you know that once we upgraded to 5.0.3 we see a 100% CPU usage of the app from thread called OpRepo, which I believe is from one signal? Right now that's quite the performance killer for our app 😅

[nan-li]

Hi @isles1217,
In these shared logs, did you remove any additional logs between each initWithContext log?

2023-10-26 11:32:42.160 27352-27352 OneSignal       D  [main] initWithContext(context: com.onesignal.core.services.SyncJobService@e461ca1, appId: null)
2023-10-26 11:32:42.162 27352-31857 OneSignal       D  [Thread-94] OSBackground sync, calling initWithContext
2023-10-26 11:33:46.441 27352-27352 OneSignal       D  [main] initWithContext(context: com.example.app.App@375a548, appId: null)
2023-10-26 11:33:46.475 27352-27352 OneSignal       D  [main] initWithContext(context: com.example.app.App@375a548, appId: null)
2023-10-26 11:33:47.632 27352-27352 OneSignal       D  [main] initWithContext(context: com.example.app.App@375a548, appId: null)
2023-10-26 11:33:47.651 27352-27352 OneSignal       D  [main] initWithContext(context: com.example.app.App@375a548, appId: null)

Your initialization code you shared look like it is for v4 of the Android SDK.. Are you doing the exact equivalent in v5?

Is initiateOneSignal() called from Main Application's onCreate() method?

[nan-li]

Hi @hannojg, yes OpRepo is from OneSignal.

• Do you see lots of logs related to OpRepo?

• What is the state of the application when you are seeing the 100% CPU usage? Is it on app startup, when making more OneSignal calls, backgrounded, etc?

[jkasten2]

We made a number of battery improvements in 5.1.7. Could you give 5.1.8 or newer a try and let us know if it helps?