Onesignal-android-sdk: ANR at com.onesignal.OneSignalDbHelper.query (OneSignalDbHelper.java:187)

[kovrizhin]

Hello Team,

Thanks for providing a good solution and supporting it.

Description:
I had a look into ANRs in my application report and found some ANR from OneSignal; this ANR happens quite frequently.

The root cause is:
You are trying to take the lock when you query the data to prevent duplicate of notification or something like this, and you do it in the main thread:

   @Override
   public Cursor query(@NonNull String table, @Nullable String[] columns, @Nullable String selection,
                       String[] selectionArgs, @Nullable String groupBy, @Nullable String having,
                       @Nullable String orderBy) {
      synchronized (LOCK) {
         return getSQLiteDatabaseWithRetries().query(table, columns, selection, selectionArgs, groupBy, having, orderBy);
      }
   }

But at the same time you are clean cache in a new thread for the same lock, and this thread starts before previous query:

   @Override
   public void delete(@NonNull String table, @Nullable String whereClause, @Nullable String[] whereArgs) {
      synchronized (LOCK) {
         SQLiteDatabase writableDb = getSQLiteDatabaseWithRetries();
         try {
            writableDb.beginTransaction();
            writableDb.delete(table, whereClause, whereArgs);
            writableDb.setTransactionSuccessful();
         } catch (SQLiteException e) {
            logger.error("Error deleting on table: " + table + " with whereClause: " + whereClause + " and whereArgs: " + whereArgs, e);
         } catch (IllegalStateException e) {
            logger.error("Error under delete transaction under table: " + table + " with whereClause: " + whereClause + " and whereArgs: " + whereArgs, e);
         } finally {
            if (writableDb != null) {
               try {
                  writableDb.endTransaction(); // May throw if transaction was never opened or DB is full.
               } catch (IllegalStateException e) {
                  logger.error("Error closing transaction! ", e);
               } catch (SQLiteException e) {
                  logger.error("Error closing transaction! ", e);
               }
            }
         }
      }
   }

In this case main thread are locked by this new thread which cleaning up the cache and android throw an ANR.

Environment
gradle android sdk
implementation 'com.onesignal:OneSignal:3.15.4'

Steps to Reproduce Issue:
I don't know how to reproduce it, but it fails and I see it in the console

Anything else:
"main" prio=5 tid=1 Blocked
at com.onesignal.OneSignalDbHelper.query (OneSignalDbHelper.java:187)
at com.onesignal.OneSignal.isDuplicateNotification (OneSignal.java:3017)
at com.onesignal.OneSignal.notValidOrDuplicated (OneSignal.java:3038)
at com.onesignal.NotificationBundleProcessor.processBundleFromReceiver (NotificationBundleProcessor.java:443)
at com.onesignal.GcmBroadcastReceiver.processOrderBroadcast (GcmBroadcastReceiver.java:123)
at com.onesignal.GcmBroadcastReceiver.onReceive (GcmBroadcastReceiver.java:70)
at android.app.ActivityThread.handleReceiver (ActivityThread.java:3634)
at android.app.ActivityThread.access$2000 (ActivityThread.java:221)
at android.app.ActivityThread$H.handleMessage (ActivityThread.java:1876)
at android.os.Handler.dispatchMessage (Handler.java:102)
at android.os.Looper.loop (Looper.java:158)
at android.app.ActivityThread.main (ActivityThread.java:7225)
at java.lang.reflect.Method.invoke! (Native method)
at com.android.internal.os.ZygoteInit$MethodAndArgsCaller.run (ZygoteInit.java:1230)
at com.android.internal.os.ZygoteInit.main (ZygoteInit.java:1120)

"OS_DELETE_CACHED_NOTIFICATIONS_THREAD" prio=10 tid=31 Native
#00 pc 00000000000410ec /system/lib/libc.so (fdatasync+12)
#00 pc 00000000000332fd /system/lib/libsqlite.so (???)
#00 pc 0000000000048d99 /system/lib/libsqlite.so (???)
#00 pc 00000000000496d7 /system/lib/libsqlite.so (???)
#00 pc 00000000000498dd /system/lib/libsqlite.so (???)
#00 pc 000000000004bd2b /system/lib/libsqlite.so (???)
#00 pc 00000000000702bd /system/lib/libsqlite.so (???)
#00 pc 000000000007452f /system/lib/libsqlite.so (sqlite3_step+534)
#00 pc 0000000000079895 /system/lib/libandroid_runtime.so (???)
#00 pc 000000000029974b /system/framework/arm/boot.oat (Java_android_database_sqlite_SQLiteConnection_nativeExecute__JJ+102)
at android.database.sqlite.SQLiteConnection.nativeExecute (Native method)
at android.database.sqlite.SQLiteConnection.execute (SQLiteConnection.java:679)
at android.database.sqlite.SQLiteSession.endTransactionUnchecked (SQLiteSession.java:437)
at android.database.sqlite.SQLiteSession.endTransaction (SQLiteSession.java:401)
at android.database.sqlite.SQLiteDatabase.endTransaction (SQLiteDatabase.java:527)
at com.onesignal.OneSignalDbHelper.delete (SourceFile:6)
at com.onesignal.OneSignalCacheCleaner.cleanCachedNotifications (SourceFile:2)
at com.onesignal.OneSignalCacheCleaner.access$000 (SourceFile:1)
at com.onesignal.OneSignalCacheCleaner$1.run (SourceFile:2)
at java.lang.Thread.run (Thread.java:818)

In my practice it is always a pain to call a DB from main thread or make some disk operation, and also always when you have a lock in main thread an ANR... Honestly I don't know how to fix it in you application, because I don't know exactly architecture, but would be good to do not lock and going to db in main thread, I know that is always a pain :)

If you need some addition information please contact me.

Many thanks & Best regards,
Oleg

[kovrizhin]

In 4 version it is the same.

[jkasten2]

@kovrizhin Thanks for reporting and digging into the stack trace. You're right, the DB access should not be done on the main thread here. Also the background clean up stacktrace is definitely making the problem more common.

In 4 version it is the same.

@kovrizhin Could you provide the stack trace for this as well? I know some of the code has changed, would be helpful to have this to when we start working on a fix.

[AndrewTerekhine]

@jkasten2 We have the same problem as @kovrizhin in the latest release v4.2.0 Here is the trace:

"main" prio=5 tid=1 Blocked
at com.onesignal.OneSignalDbHelper.query (OneSignalDbHelper.java:188)
at com.onesignal.OneSignal.isDuplicateNotification (OneSignal.java:2864)
at com.onesignal.OneSignal.notValidOrDuplicated (OneSignal.java:2889)
at com.onesignal.NotificationBundleProcessor.startNotificationProcessing (NotificationBundleProcessor.java:414)
at com.onesignal.NotificationBundleProcessor.processBundleFromReceiver (NotificationBundleProcessor.java:380)
at com.onesignal.FCMBroadcastReceiver.processOrderBroadcast (FCMBroadcastReceiver.java:116)
at com.onesignal.FCMBroadcastReceiver.onReceive (FCMBroadcastReceiver.java:69)
at android.app.ActivityThread.handleReceiver (ActivityThread.java:4003)
at android.app.ActivityThread.access$1500 (ActivityThread.java:232)
at android.app.ActivityThread$H.handleMessage (ActivityThread.java:2025)
at android.os.Handler.dispatchMessage (Handler.java:107)
at android.os.Looper.loop (Looper.java:241)
at android.app.ActivityThread.main (ActivityThread.java:7617)
at java.lang.reflect.Method.invoke (Method.java)
at com.android.internal.os.RuntimeInit$MethodAndArgsCaller.run (RuntimeInit.java:492)
at com.android.internal.os.ZygoteInit.main (ZygoteInit.java:941)

Unfortunately, in v4.2.0 there is no trace for the thread OS_DELETE_CACHED_NOTIFICATIONS_THREAD But I see the same method "delete" with the lock in OneSignalDbHelper.java This delete method is used throughout OneSignal class for example in initWithContext() > setupContextListeners() > cleanOldCachedData() > cleanNotificationCache() > cleanCachedNotifications() > delete() The delete method uses the lock in another threads and causes ANR in the method isDuplicateNotification which calls dbHelper.query with the same lock.

Here is the complete ANR trace for v4.2.0:
https://pastebin.com/FNZRJ0M6

[kovrizhin]

@jkasten2 Thanks for quick replying, unfortunately I have the same problem as @AndrewTerekhine (thanks for posting), and don't find other thread stack, but the code for 3 version and 4 version are more or less the same. the stack which @AndrewTerekhine post is right. And luckily we had both stack in 3 version :) I know that fixing ANR is pain :)

This is how you start firstly clean up the cache in a new thread:
In this line you are start checking if context is exist:
https://github.com/OneSignal/OneSignal-Android-SDK/blob/d786b30c57737c4a59f94d185f8708c39c9b4cec/OneSignalSDK/onesignal/src/main/java/com/onesignal/FCMBroadcastReceiver.java#L68
and after this line:
https://github.com/OneSignal/OneSignal-Android-SDK/blob/d786b30c57737c4a59f94d185f8708c39c9b4cec/OneSignalSDK/onesignal/src/main/java/com/onesignal/OneSignal.java#L645
and in this line you are start clean up cache in new thread:
https://github.com/OneSignal/OneSignal-Android-SDK/blob/d786b30c57737c4a59f94d185f8708c39c9b4cec/OneSignalSDK/onesignal/src/main/java/com/onesignal/OneSignal.java#L779

This is how you start querying for duplication notification in main thread
And in the next line in FCMBroadcastReceiver.onReceive you are starting checking for duplication notification and other staff in parallel with clean up the cache:
https://github.com/OneSignal/OneSignal-Android-SDK/blob/d786b30c57737c4a59f94d185f8708c39c9b4cec/OneSignalSDK/onesignal/src/main/java/com/onesignal/FCMBroadcastReceiver.java#L69
And in this line you are starting check for duplication in db in main thread:
https://github.com/OneSignal/OneSignal-Android-SDK/blob/d786b30c57737c4a59f94d185f8708c39c9b4cec/OneSignalSDK/onesignal/src/main/java/com/onesignal/NotificationBundleProcessor.java#L414
https://github.com/OneSignal/OneSignal-Android-SDK/blob/d786b30c57737c4a59f94d185f8708c39c9b4cec/OneSignalSDK/onesignal/src/main/java/com/onesignal/OneSignal.java#L2915
https://github.com/OneSignal/OneSignal-Android-SDK/blob/d786b30c57737c4a59f94d185f8708c39c9b4cec/OneSignalSDK/onesignal/src/main/java/com/onesignal/OneSignal.java#L2890

Sorry if I write something wrong, what to help you :)

Many thanks & best regards,
Oleg

[Jeasmine]

Hey, @kovrizhin, thanks for all the information! I checked, and we indeed end calling isDuplicateNotification on the main thread. This is not good at all, and we will be working on this one for the next release! Thanks again.

[kovrizhin]

@Jeasmine Thank you so much. Cool!