Why is Android keymaster logging DROPBOX_ENTRY_ADDED events in Android 9?

Question

I'm working with an Android app that handles some sensitive data and, as such, relies heavily on encryption any time I write to or read from storage. In Android API 27 and below, this works fine and is very fast. However, I've noticed that in API 28 (Android 9, Pie) decrypt operations are significantly slower.

Looking at my logcat, I notice a new message being spammed hundreds of times:

2018-12-19 16:20:10.564 1233-1260 W/BroadcastQueue: Background execution not allowed: receiving Intent { act=android.intent.action.DROPBOX_ENTRY_ADDED flg=0x10 (has extras) } to com.google.android.gms/.stats.service.DropBoxEntryAddedReceiver
2018-12-19 16:20:10.565 1233-1260 W/BroadcastQueue: Background execution not allowed: receiving Intent { act=android.intent.action.DROPBOX_ENTRY_ADDED flg=0x10 (has extras) } to com.google.android.gms/.chimera.GmsIntentOperationService$PersistentTrustedReceiver
2018-12-19 16:20:10.588 1233-1260 W/BroadcastQueue: Background execution not allowed: receiving Intent { act=android.intent.action.DROPBOX_ENTRY_ADDED flg=0x10 (has extras) } to com.google.android.gms/.stats.service.DropBoxEntryAddedReceiver
2018-12-19 16:20:10.588 1233-1260 W/BroadcastQueue: Background execution not allowed: receiving Intent { act=android.intent.action.DROPBOX_ENTRY_ADDED flg=0x10 (has extras) } to com.google.android.gms/.chimera.GmsIntentOperationService$PersistentTrustedReceiver
2018-12-19 16:22:54.580 1233-1260 W/BroadcastQueue: Background execution not allowed: receiving Intent { act=android.intent.action.DROPBOX_ENTRY_ADDED flg=0x10 (has extras) } to com.google.android.gms/.stats.service.DropBoxEntryAddedReceiver
2018-12-19 16:22:54.580 1233-1260 W/BroadcastQueue: Background execution not allowed: receiving Intent { act=android.intent.action.DROPBOX_ENTRY_ADDED flg=0x10 (has extras) } to com.google.android.gms/.chimera.GmsIntentOperationService$PersistentTrustedReceiver

It looks like every decrypt operation generates a android.intent.action.DROPBOX_ENTRY_ADDED broadcast, which both com.google.android.gms/.stats.service.DropBoxEntryAddedReceiver and com.google.android.gms/.chimera.GmsIntentOperationService$PersistentTrustedReceiver attempt to handle. This appears to be taking significant amounts of time, and was not a problem before Android Pie. To quantify, I benchmarked these same decrypt operations in API23 and the average op time was around 3ms. The exact same code on Android Pie takes 60ms-90ms, 20-30x slower. Crazy. This is especially noticeable when my app starts, because it needs to decrypt a few hundred small strings in order load some user data. On Android Pie, my app startup time now takes about 10 full seconds, all the while this message is being spammed in logcat.

I generated a bugreport and looked for anything interesting, and I see this:

  Service com.google.android.gms.stats.service.DropBoxEntryAddedService:
    Process: com.google.android.gms
    Running op count 34:
      SOn /Norm: +12s205ms
          TOTAL: +12s205ms
    Started op count 17:
      SOn /Norm: +12s118ms
          TOTAL: +12s118ms
    Executing op count 652:
      SOn /Norm: +2s737ms
          TOTAL: +2s737ms

I'm not exactly sure how to read this output, but coincidentally (or not) the total runtime for this service is almost exactly the amount of time my app now takes to start.

Next, I wanted to see what was in these messages, so I ran it on a rooted emulator and performed a dumpsys dropbox keymaster --print:

========================================
2018-12-19 18:32:04 keymaster (data, 52 bytes)
/data/system/dropbox/keymaster@1545262324865.dat

========================================
2018-12-19 18:32:04 keymaster (data, 52 bytes)
/data/system/dropbox/keymaster@1545262324880.dat

========================================
2018-12-19 18:32:05 keymaster (data, 53 bytes)
/data/system/dropbox/keymaster@1545262325142.dat

There are hundreds of these entries in dropbox. Looking at the actual files generated, I see the first few seem to be reasonable: getting providers, loading AndroidKeystore, generating my key, and then hundreds and hundreds of the exact same event:

AES�IMPORTED2NONEBCTRHRdecrypt

It's a non-ASCII record, so the hexdump looks like this:

0000000 0a 03 41 45 53 10 80 01 1a 08 49 4d 50 4f 52 54
0000010 45 44 32 04 4e 4f 4e 45 42 03 43 54 52 48 01 52
0000020 07 64 65 63 72 79 70 74                        
0000028

However interesting this may be, it brings me no closer to the actual problem, or a solution. Why is this happening in Android 9? What's the point in broadcasting a seemingly useless message every time a decrypt operation is performed? How can I prevent it? Has anyone else experienced this?

To add a few more details:

Using AndroidKeystore for key storage
Using CipherInputStream and CipherOutputStream with AES/CTR/NoPadding for the implementation
The AES SecretKey is generated the first time the user launches the app, using KeyGenParameterSpec.Builder and then KeyGenerator.generateKey()
Subsequent app launches load the key from the AndroidKeystore using the key alias
The SecretKey entry reference is held by the encryption helper class. It is not loaded for every encrypt/decrypt operation
A new cipher is created for each encrypt operation, using the SecretKey reference above and a Cipher instance of AES/CTR/NoPadding

I'll be glad to answer any follow-up questions. This is a serious problem for me and the Google documentation on this "feature" is absolutely useless.

Why is Android keymaster logging DROPBOX_ENTRY_ADDED events in Android 9?

0 Answers