[Bug]: ANRs coming from com.onesignal.common.modeling.Model.initializeFromJson

[isles1217]

What happened?

This is a follow up issue to #2230. A bulk of our ANRs have been fixed following the release of 5.1.26, but I'm still seeing ANRs with one particular stack trace. We really appreciate the work on reducing these ANRs, and I'm hoping this particular trace gets rid of the last major culprit. Thanks for the improvements so far!

Steps to reproduce?

See stack trace / log output

What did you expect to happen?

OneSignal to not block the main thread

OneSignal Android SDK version

5.1.26

Android version

13, 12, 11

Specific Android models

Any

Relevant log output

com.onesignal.common.modeling.Model.initializeFromJson
ANR triggered by slow operations in blamed thread

OpRepo (runnable):
          OpRepo (runnable):tid=57 systid=18118 
#00 pc 0x4a7ee8 libart.so (art::DumpNativeStack(std::__1::basic_ostream<char, std::__1::char_traits<char> >&, int, BacktraceMap*, char const*, art::ArtMethod*, void*, bool) + 140)
#01 pc 0x5b59dc libart.so (art::Thread::DumpStack(std::__1::basic_ostream<char, std::__1::char_traits<char> >&, bool, BacktraceMap*, bool) const + 376)
#02 pc 0x5d2b14 libart.so (art::DumpCheckpoint::Run(art::Thread*) + 924)
#03 pc 0x5b6910 libart.so (art::Thread::RunCheckpointFunction() + 176)
#04 pc 0x6739fc libart.so (art::JniMethodFastEndWithReference(_jobject*, unsigned int, art::Thread*) + 112)
       at java.lang.reflect.Executable.getMethodNameInternal(Native method)
       at java.lang.reflect.Method.getName(Method.java:115)
       at java.lang.reflect.Method$1.compare(Method.java:72)
       at java.lang.reflect.Method$1.compare(Method.java:67)
       at libcore.util.CollectionUtils.removeDuplicates(CollectionUtils.java:89)
       at java.lang.Class.getMethods(Class.java:1493)
       at com.onesignal.common.modeling.Model.initializeFromJson(Model.kt)
       at com.onesignal.core.internal.operations.impl.OperationModelStore.create(OperationModelStore.kt:67)
       at com.onesignal.core.internal.operations.impl.OperationModelStore.create(OperationModelStore.kt:30)
       at com.onesignal.common.modeling.ModelStore.load(ModelStore.kt)
       at com.onesignal.core.internal.operations.impl.OperationModelStore.loadOperations(OperationModelStore.kt)
       at com.onesignal.core.internal.operations.impl.OperationRepo.loadSavedOperations$com_onesignal_core(OperationRepo.kt)
       at com.onesignal.core.internal.operations.impl.OperationRepo$start$1.invokeSuspend(OperationRepo.kt)
       at kotlin.coroutines.jvm.internal.BaseContinuationImpl.resumeWith(ContinuationImpl.kt)
       at kotlinx.coroutines.DispatchedTask.run(DispatchedTask.kt)
       at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:462)
       at java.util.concurrent.FutureTask.run(FutureTask.java:266)
       at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:301)
       at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1167)
       at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:641)
       at java.lang.Thread.run(Thread.java:923)

main (blocked)
tid=1 systid=18010 | waiting to lock <0x059286bb> (java.util.ArrayList) held by thread 57
          main (blocked):tid=1 systid=18010 | waiting to lock <0x059286bb> (java.util.ArrayList) held by thread 57
       at com.onesignal.common.modeling.ModelStore.add(ModelStore.kt:45)
       at com.onesignal.common.modeling.IModelStore$DefaultImpls.add$default(IModelStore.kt:36)
       at com.onesignal.core.internal.operations.impl.OperationRepo.internalEnqueue(OperationRepo.kt)
       at com.onesignal.core.internal.operations.impl.OperationRepo.internalEnqueue$default(OperationRepo.kt)
       at com.onesignal.core.internal.operations.impl.OperationRepo.enqueue(OperationRepo.kt)
       at com.onesignal.session.internal.session.impl.SessionListener.onSessionStarted(SessionListener.kt)
       at com.onesignal.session.internal.session.impl.SessionService$onFocus$1.invoke(SessionService.kt:107)
       at com.onesignal.session.internal.session.impl.SessionService$onFocus$1.invoke(SessionService.kt:107)
       at com.onesignal.common.events.EventProducer.fire(EventProducer.kt)
       at com.onesignal.session.internal.session.impl.SessionService.onFocus(SessionService.kt)
       at com.onesignal.core.internal.application.impl.ApplicationService$handleFocus$1.invoke(ApplicationService.kt:395)
       at com.onesignal.core.internal.application.impl.ApplicationService$handleFocus$1.invoke(ApplicationService.kt:395)
       at com.onesignal.common.events.EventProducer.fire(EventProducer.kt)
       at com.onesignal.core.internal.application.impl.ApplicationService.handleFocus(ApplicationService.kt)
       at com.onesignal.core.internal.application.impl.ApplicationService.onActivityStarted(ApplicationService.kt)
       at android.app.Application.dispatchActivityStarted(Application.java:425)
       at android.app.Activity.dispatchActivityStarted(Activity.java:1382)
       at android.app.Activity.onStart(Activity.java:1873)
       at android.app.Instrumentation.callActivityOnStart(Instrumentation.java:1435)
       at android.app.Activity.performStart(Activity.java:8231)
       at android.app.ActivityThread.handleStartActivity(ActivityThread.java:3872)
       at android.app.servertransaction.TransactionExecutor.performLifecycleSequence(TransactionExecutor.java:221)
       at android.app.servertransaction.TransactionExecutor.cycleToPath(TransactionExecutor.java:201)
       at android.app.servertransaction.TransactionExecutor.executeLifecycleState(TransactionExecutor.java:173)
       at android.app.servertransaction.TransactionExecutor.execute(TransactionExecutor.java:97)
       at android.app.ActivityThread$H.handleMessage(ActivityThread.java:2336)
       at android.os.Handler.dispatchMessage(Handler.java:106)
       at android.os.Looper.loop(Looper.java:246)
       at android.app.ActivityThread.main(ActivityThread.java:8653)
       at java.lang.reflect.Method.invoke(Native method)
       at com.android.internal.os.RuntimeInit$MethodAndArgsCaller.run(RuntimeInit.java:602)
       at com.android.internal.os.ZygoteInit.main(ZygoteInit.java:1130)

Code of Conduct

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

[jinliu9508]

@isles1217 Great to hear that bulks of ANRs have been resolved in our latest release! We are currently investigating this particular stack trace and will provide an update once a new release is available.

[jinliu9508]

@isles1217 The stack trace indicates that the operation is enqueuing and waiting on the main thread. However, the 5.1.26 release has moved this step to the background thread. Could you double-check that this isn't happening in your latest version? Additionally, could you provide another stack trace that includes line numbers for these lines of code?

main (blocked)
tid=1 systid=18010 | waiting to lock <0x059286bb> (java.util.ArrayList) held by thread 57
          main (blocked):tid=1 systid=18010 | waiting to lock <0x059286bb> (java.util.ArrayList) held by thread 57
       at com.onesignal.common.modeling.ModelStore.add(ModelStore.kt:45)
       at com.onesignal.common.modeling.IModelStore$DefaultImpls.add$default(IModelStore.kt:36)
       at com.onesignal.core.internal.operations.impl.OperationRepo.internalEnqueue(OperationRepo.kt)
       at com.onesignal.core.internal.operations.impl.OperationRepo.internalEnqueue$default(OperationRepo.kt)
       at com.onesignal.core.internal.operations.impl.OperationRepo.enqueue(OperationRepo.kt)

[fanwgwg]

@jinliu9508

I'm also seeing this with the latest 5.1.26

Here's the stacktrace:

 "main" tid=1 Blocked
  at com.onesignal.common.modeling.ModelStore.add (ModelStore.kt:45)
  at com.onesignal.common.modeling.IModelStore$DefaultImpls.add$default (IModelStore.kt:36)
  at com.onesignal.core.internal.operations.impl.OperationRepo.internalEnqueue (OperationRepo.kt:153)
  at com.onesignal.core.internal.operations.impl.OperationRepo.internalEnqueue$default (OperationRepo.kt:133)
  at com.onesignal.core.internal.operations.impl.OperationRepo.enqueue (OperationRepo.kt:112)
  at com.onesignal.core.internal.operations.IOperationRepo$DefaultImpls.enqueue$default (IOperationRepo.kt:18)
  at com.onesignal.core.internal.operations.listeners.ModelStoreListener.onModelAdded (ModelStoreListener.kt:40)
  at com.onesignal.common.modeling.ModelStore$addItem$2.invoke (ModelStore.kt:143)
  at com.onesignal.common.modeling.ModelStore$addItem$2.invoke (ModelStore.kt:143)
  at com.onesignal.common.events.EventProducer.fire (EventProducer.kt:50)
  at com.onesignal.common.modeling.ModelStore.addItem (ModelStore.kt:143)
  at com.onesignal.common.modeling.ModelStore.addItem$default (ModelStore.kt:126)
  at com.onesignal.common.modeling.ModelStore.add (ModelStore.kt:51)
  at com.onesignal.common.modeling.IModelStore$DefaultImpls.add$default (IModelStore.kt:36)
  at com.onesignal.user.internal.subscriptions.impl.SubscriptionManager.addSubscriptionToModels (SubscriptionManager.kt:125)
  at com.onesignal.user.internal.subscriptions.impl.SubscriptionManager.addSubscriptionToModels$default (SubscriptionManager.kt:111)
  at com.onesignal.user.internal.subscriptions.impl.SubscriptionManager.addEmailSubscription (SubscriptionManager.kt:69)
  at com.onesignal.user.internal.UserManager.addEmail (UserManager.kt:144)
  at com.yygg.note.app.notification.AppNotificationManager.refreshUserAndSubscription (AppNotificationManager.java:47)
  at com.yygg.note.app.home.HomeViewModel.onResume (HomeViewModel.java:277)
  at androidx.lifecycle.DefaultLifecycleObserverAdapter.onStateChanged (DefaultLifecycleObserverAdapter.kt:26)
  at androidx.lifecycle.LifecycleRegistry$ObserverWithState.dispatchEvent (LifecycleRegistry.jvm.kt:320)
  at androidx.lifecycle.LifecycleRegistry.forwardPass (LifecycleRegistry.java:257)
  at androidx.lifecycle.LifecycleRegistry.sync (LifecycleRegistry.java:293)
  at androidx.lifecycle.LifecycleRegistry.moveToState (LifecycleRegistry.java:142)
  at androidx.lifecycle.LifecycleRegistry.handleLifecycleEvent (LifecycleRegistry.java:124)
  at androidx.fragment.app.Fragment.performResume (Fragment.java:3215)
  at androidx.fragment.app.FragmentStateManager.resume (FragmentStateManager.java:666)
  at androidx.fragment.app.FragmentStateManager.moveToExpectedState (FragmentStateManager.java:310)
  at androidx.fragment.app.SpecialEffectsController$FragmentStateManagerOperation.complete$fragment_release (SpecialEffectsController.kt:823)
  at androidx.fragment.app.SpecialEffectsController.commitEffects$fragment_release (SpecialEffectsController.kt:441)
  at androidx.fragment.app.SpecialEffectsController.executePendingOperations (SpecialEffectsController.kt:283)
  at androidx.fragment.app.FragmentManager.executeOpsTogether (FragmentManager.java:2227)
  at androidx.fragment.app.FragmentManager.removeRedundantOperationsAndExecute (FragmentManager.java:2115)
  at androidx.fragment.app.FragmentManager.execPendingActions (FragmentManager.java:2052)
  at androidx.fragment.app.FragmentManager$5.run (FragmentManager.java:703)
  at android.os.Handler.handleCallback (Handler.java:958)
  at android.os.Handler.dispatchMessage (Handler.java:99)
  at android.os.Looper.loopOnce (Looper.java:230)
  at android.os.Looper.loop (Looper.java:319)
  at android.app.ActivityThread.main (ActivityThread.java:8934)
  at java.lang.reflect.Method.invoke (Native method)
  at com.android.internal.os.RuntimeInit$MethodAndArgsCaller.run (RuntimeInit.java:578)