jakobmoellerdev
commented
4 years ago Hi. Could you provide us with more Information of the Context, App Version and when this occured?
Closed stefan-sys closed 4 years ago
jakobmoellerdev
commented
4 years ago Hi. Could you provide us with more Information of the Context, App Version and when this occured?
gitbrueck
commented
4 years ago I have the same problem. I have it now. I have App version 1.0.4
jakobmoellerdev
commented
4 years ago Hi. Thanks for pointing out your issue, however we would really need more detailed information on the context of your devices, your setup and your installation. Otherwise it is extremely hard for us to correctly identify the issue. Thanks so much for your understanding.
Important Info:
JProof
commented
4 years ago @jakobmoellersap have the same problem after restart the phone. Do you need detailed informations?
BranKohlschreiber
commented
4 years ago got the same bug, app has been installed for a couple of days and already displayed "Niedriges Risiko" before. When i close the error report it shows the green display "niedriges risiko" again
this occures reproducable after each startup (including after a restart of the phone)
App Version 1.0.4
Android Version 6.0
Device Model and Manufacturer ALE-L21 Huawei
Latest OS Update Kernel Version 3.10.86-g33ff982
Latest Update of CWA idk
Installation Date of CWA 20.6.2020
Date/Time of the error 10:34 25.6.2020 (every time i open the app, started this morning)URSACHE: 3 Etwas ist schief gelaufen.
jakobmoellerdev
commented
4 years ago @gitbrueck please refer to the other issues referencing error 3 like #499 and #508
jakobmoellerdev
commented
4 years ago Just as a headsup: This means that key files are actually sent to the API, so most likely the concern is (as discussed in #642) a security API problem within certain devices from certain manufacturers together with the applied security providers.
On the bright side: You do get the keys of the server onto your device, however the security handling is broken apparently.
Martin-Luft
commented
4 years ago Same here Honor 7 Premium 32 GB (Android 6). The problem popped up yesterday morning but after a few hours it disappeared.
gitbrueck
commented
4 years ago @gitbrueck please refer to the other issues referencing error 3 like #499 and #508
I cleared data and cache of Google Play Store. I restarted the device. Now everything works. Hard to say what really solved the problem.
Maybe like @Martin-Wegner just wait and see.
DanielSWolf
commented
4 years ago Same problem with a Huawei P8.
duichwer
commented
4 years ago Same on Huawei ALE-L21 Build Number ALE-L21C432B634 Emui 4.0.3 Android 6.0
aurisnoctis
commented
4 years ago Same error occurred on my phone today 25 June 2020 in the morning. App seems running fine now - don't know if everything indeed works as it should in the background (?).
Update:
I checked the Google > Exposure Notification entry in the Android menu. Information about last check Letzte Überprüfung auf eine mögliche Begegnung mit einer infizierten Person am heute um 09:03.
jakobmoellerdev
commented
4 years ago It would be extremely helpful if anyone that experiences this error can submit a proper bug report to us via adb as seen here: https://developer.android.com/studio/debug/bug-report
DanielSWolf
commented
4 years ago I took a bug report, but I'm hesitant to share it publicly. Is there any way for me to share it privately?
Martin-Luft
commented
4 years ago I took a bug report via my smartphone as well.
jakobmoellerdev
commented
4 years ago Can you guys take a look at #642 and see whether you have matching reports or similar problems in your report? The errors seem to correlate
Martin-Luft
commented
4 years ago Here is my filtered log:
06-26 10:43:01.178 4512 4512 I HwSecImmHelper: mSecurityInputMethodService is null
06-26 10:43:01.277 4512 4512 W ResourceType: No known package when getting name for resource number 0x9c020402
06-26 10:43:01.286 4443 4443 I K3V3CpuGovernorPolicy: set scene Hmp policy : 300 , 150
06-26 10:43:01.340 27740 27740 I : power log dlsym ok
06-26 10:43:01.389 4443 5184 W PGApi_client: recv actoionId = 10000, action = com.huawei.pgmng.PGAction@705a9f8 actionId =10000 pkg =de.rki.coronawarnapp extend1 =1782 extend2 = flag =3 type =1
06-26 10:43:01.389 4443 5184 W PGMiddleWare: in handleAction method, action = 10000
06-26 10:43:01.389 4443 5184 W PGMiddleWare: in handleAction, invoke client = com.huawei.pgmng.middleware.AudioEffectLowPowerImpl@c4db6b0, action = com.huawei.pgmng.PGAction@705a9f8 actionId =10000 pkg =de.rki.coronawarnapp extend1 =1782 extend2 = flag =3 type =1
06-26 10:43:01.397 3892 4033 I HwSystemManager: NotificationGuideService:handle MSG_ACTIVIY_FOREGROUND, uid:10145
06-26 10:43:01.401 27740 27752 E linker : readlink('/proc/self/fd/20') failed: Permission denied [fd=20]
06-26 10:43:01.401 27740 27752 E linker : warning: unable to get realpath for the library "/system/lib64/hw/gralloc.hi3635.so". Will use given name.
06-26 10:43:01.402 27740 27752 E linker : readlink('/proc/self/fd/20') failed: Permission denied [fd=20]
06-26 10:43:01.402 27740 27752 E linker : warning: unable to get realpath for the library "libion.so". Will use given name.
06-26 10:43:01.403 27740 27752 E HAL : load: id=gralloc != hmi->id=gralloc
06-26 10:43:01.858 27740 27740 I art : Rejecting re-init on previously-failed class java.lang.Class<org.conscrypt.Java7ExtendedSSLSession>
06-26 10:43:01.858 27740 27740 I art : Rejecting re-init on previously-failed class java.lang.Class<org.conscrypt.Java7ExtendedSSLSession>
06-26 10:43:01.859 27740 27740 I art : Rejecting re-init on previously-failed class java.lang.Class<org.conscrypt.Java8ExtendedSSLSession>
06-26 10:43:01.859 27740 27740 I art : Rejecting re-init on previously-failed class java.lang.Class<org.conscrypt.Java8ExtendedSSLSession>
06-26 10:43:01.931 27740 27740 I HwCust : Constructor found for class android.app.HwCustHwWallpaperManagerImpl
06-26 10:43:02.094 4443 4443 I K3V3CpuGovernorPolicy: close previously scene Hmp policy : 300 , 150
06-26 10:43:02.121 27740 27740 I HwSecImmHelper: mSecurityInputMethodService is null
06-26 10:43:02.161 27740 27761 E HAL : load: id=gralloc != hmi->id=gralloc
06-26 10:43:02.162 27740 27761 I OpenGLRenderer: Initialized EGL, version 1.4
06-26 10:43:02.168 27740 27761 E linker : readlink('/proc/self/fd/39') failed: Permission denied [fd=39]
06-26 10:43:02.168 27740 27761 E linker : warning: unable to get realpath for the library "libhwaps.so". Will use given name.
06-26 10:43:02.184 27740 27761 E linker : readlink('/proc/self/fd/40') failed: Permission denied [fd=40]
06-26 10:43:02.184 27740 27761 E linker : warning: unable to get realpath for the library "/system/lib64/libhwuibp.so". Will use given name.
06-26 10:43:02.195 27740 27762 I System : core_booster, getBoosterConfig = false
06-26 10:43:02.211 27740 27740 I HwSecImmHelper: mSecurityInputMethodService is null
06-26 10:43:02.216 8205 8205 I GoogleInputMethodServic: GoogleInputMethodService.onFinishInput():3138
06-26 10:43:02.218 8205 8205 I GoogleInputMethodServic: GoogleInputMethodService.onStartInput():1808
06-26 10:43:02.249 3394 3416 I ActivityManager: Displayed de.rki.coronawarnapp/.ui.LauncherActivity: +925ms
06-26 10:43:02.314 27740 27762 I System : core_booster, getBoosterConfig = false
06-26 10:43:03.186 27740 27740 I EngineFactory: Provider GmsCore_OpenSSL not available
06-26 10:43:03.703 3394 3415 I Bluetooth_framework: BluetoothManagerService:Message: 20
06-26 10:43:03.703 3394 3415 I Bluetooth_framework: BluetoothManagerService:Added callback: android.bluetooth.IBluetoothManagerCallback$Stub$Proxy@a2e0602:true pid = 27740
06-26 10:43:04.009 27740 27740 I HwSecImmHelper: mSecurityInputMethodService is null
06-26 10:43:04.011 3394 3416 I ActivityManager: Displayed de.rki.coronawarnapp/.ui.main.MainActivity: +797ms
06-26 10:43:04.012 8205 8205 I GoogleInputMethodServic: GoogleInputMethodService.onFinishInput():3138
06-26 10:43:04.013 8205 8205 I GoogleInputMethodServic: GoogleInputMethodService.onStartInput():1808
06-26 10:43:04.429 3394 3747 W AlarmManager: WAKEUP alarm trigger action = com.android.bluetooth.btservice.action.ALARM_WAKEUP elapsed = 39886791
06-26 10:43:04.796 27740 27804 I System : core_booster, getBoosterConfig = false
06-26 10:43:04.798 27740 27805 I System : core_booster, getBoosterConfig = false
06-26 10:43:05.007 27740 27805 I System : core_booster, getBoosterConfig = false
06-26 10:43:05.007 27740 27804 I System : core_booster, getBoosterConfig = false
06-26 10:43:05.301 4875 19518 I SendBroadcastPermission: action:com.google.android.libraries.storage.protostore.SIGNAL_ACTION, mPermissionType:0
06-26 10:43:05.301 4875 19518 I SendBroadcastPermission: action:com.google.android.libraries.storage.protostore.SIGNAL_ACTION, mPermissionType:0
06-26 10:43:05.327 4875 23874 E AsyncOperation: serviceID=236, operation=ProvideDiagnosisKeysOperation
06-26 10:43:05.327 4875 23874 E AsyncOperation: OperationException[Status{statusCode=Unable to validate key file signature: Pipe is closed, resolution=null}]
06-26 10:43:05.327 4875 23874 E AsyncOperation: at bnt.a(:com.google.android.gms.policy_nearby@202304013@202304013031.315351686.315351686:187)
06-26 10:43:05.327 4875 23874 E AsyncOperation: at azi.run(:com.google.android.gms.policy_nearby@202304013@202304013031.315351686.315351686:11)
06-26 10:43:05.327 4875 23874 E AsyncOperation: at ddp.run(:com.google.android.gms.policy_nearby@202304013@202304013031.315351686.315351686:2)
06-26 10:43:05.327 4875 23874 E AsyncOperation: at avl.b(:com.google.android.gms.policy_nearby@202304013@202304013031.315351686.315351686:12)
06-26 10:43:05.327 4875 23874 E AsyncOperation: at avl.run(:com.google.android.gms.policy_nearby@202304013@202304013031.315351686.315351686:7)
06-26 10:43:05.327 4875 23874 E AsyncOperation: at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1113)
06-26 10:43:05.327 4875 23874 E AsyncOperation: at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:588)
06-26 10:43:05.327 4875 23874 E AsyncOperation: at stk.run(:com.google.android.gms@202117021@20.21.17 (040408-316502805):0)
06-26 10:43:05.327 4875 23874 E AsyncOperation: at java.lang.Thread.run(Thread.java:833)
06-26 10:43:05.379 27740 27740 W System.err: com.google.android.gms.common.api.ApiException: 10: Unable to validate key file signature: Pipe is closed
06-26 10:43:05.380 27740 27740 W System.err: at android.support.v4.media.MediaDescriptionCompatApi21$Builder.setResultOrApiException(MediaDescriptionCompatApi21.java:3)
06-26 10:43:05.380 27740 27740 W System.err: at com.google.android.gms.internal.nearby.zzae.onResult(com.google.android.gms:play-services-nearby@@18.0.2-eap:2)
06-26 10:43:05.380 27740 27740 W System.err: at com.google.android.gms.common.api.internal.IStatusCallback$Stub.zaa(com.google.android.gms:play-services-base@@17.3.0:2)
06-26 10:43:05.380 27740 27740 W System.err: at com.google.android.gms.internal.base.zaa.onTransact(com.google.android.gms:play-services-base@@17.3.0:3)
06-26 10:43:05.380 27740 27740 W System.err: at android.os.Binder.execTransact(Binder.java:453)
06-26 10:43:05.885 3394 3822 I QosMonitor: postEventFromNative: msg=100,arg1=0,arg2=9
06-26 10:43:06.687 27740 27740 I HwSecImmHelper: mSecurityInputMethodService is null
06-26 10:43:07.745 27740 27740 I HwSecImmHelper: mSecurityInputMethodService is null
06-26 10:43:07.880 27740 27740 I HwSecImmHelper: mSecurityInputMethodService is null
06-26 10:43:08.708 4443 4443 I K3V3CpuGovernorPolicy: set scene Hmp policy : 300 , 150
06-26 10:43:08.714 2860 9512 W SurfaceFlinger: FB is protected: PERMISSION_DENIED
06-26 10:43:08.734 4443 5184 W PGApi_client: recv actoionId = 10010, action = com.huawei.pgmng.PGAction@5031ed1 actionId =10010 pkg =com.huawei.android.launcher extend1 =1785 extend2 = flag =3 type =1
06-26 10:43:08.734 4443 5184 W PGMiddleWare: in handleAction method, action = 10010
06-26 10:43:08.734 4443 5184 W PGMiddleWare: in handleAction, invoke client = com.huawei.pgmng.middleware.AudioEffectLowPowerImpl@c4db6b0, action = com.huawei.pgmng.PGAction@5031ed1 actionId =10010 pkg =com.huawei.android.launcher extend1 =1785 extend2 = flag =3 type =1
Tj20
commented
4 years ago Same problem here on Android 6.0. The app worked fine for the last week until it started showing this error message around yesterday:
URSACHE: 3 Etwas ist schief gelaufen. Fehler bei Kommunikation mit Google API(10) Ursache: com.google.android.gms.common.api.ApiException: 10: Unable to validate key file signature: Pipe is closed at ...
App Version: 1.0.4
Android Version: 6.0
Device Model and Manufacturer: Vernee Thor (2016)
Latest OS Update: Oct 2016
Latest Update of CWA: 20 June 2020
Installation Date of CWA: 16 June 2020
Date/Time of the error:
Noticed it yesterday (25th June) for the first time in the morning at around 9:00 while manually
starting the app. Today the same thing happened after manually starting the app at around 9:00.
The app itself says: "Niedriges Risiko, Bisher keine Risiko-Begegnungen, 10 von 14 Tagen aktiv,
Aktualisiert: Gestern, 07:19, tägliche Aktualisierung". ("yesterday, 7:19" - so I guess that means: no update today yet)Afterwards, there's a new error:
URSACHE: 3 Etwas ist schief gelaufen. Fehler bei Kommunikation mit Google API(39508) Ursache: com.google.android.gms.common.api.ApiException: 39508: at: ...
After getting rid of the error messages by clicking "okay" the app seems to be working fine. "Risiko-Ermittlung aktiv, niedriges Risiko".
However after leaving the app via back-button and entering it again via clicking the link on the home screen, the 2nd error message is back (Google API(39508)).
Can you guys take a look at #642 and see whether you have matching reports or similar problems in your report? The errors seem to correlate
As far as I remember, I've never seen that error ("9002, file is not a database: , while compiling: select count(*) from sqlite_master;") before.
jakobmoellerdev
commented
4 years ago 39508 is rate-limiting since the API Call is done twice but the Submission in the API is failing and detected by the transaction, which in turn rolls back and then thinks the call never came through. This is also the reason why the rate-limiting appeared in the first place.
jakobmoellerdev
commented
4 years ago @Tj20 can you give us a device model so that we can check whether this correlates?
Tj20
commented
4 years ago It's a Vernee Thor (2016), model number: "thor", Android 6.0, latest OS update: Oct 2016 (thor_20161008), Kernel 3.18.19
jakobmoellerdev
commented
4 years ago Okay, could you give us some more details of your devices via ADB? Concretely, we would like to know the GMS Version.
this can be retrieved via the following command:
adb shell dumpsys activity provider com.google.android.gms.chimera.container.GmsModuleProvider | grep 'nearby_en\|\[Container\]'
aurisnoctis
commented
4 years ago Update for https://github.com/corona-warn-app/cwa-app-android/issues/737#issuecomment-649702108: Same error happened today on
Here my heavily filtered log - hope I didn't remove relevant lines:
jakobmoellerdev
commented
4 years ago 06-26 09:48:27.960 13871 4874 W System.err: stat failed: ENOENT (No such file or directory) : /data/user/0/com.google.android.gms/app_en_diagnosis_keys/1593157707970/export0.bin 06-26 09:48:27.980 13871 4874 E AsyncOperation: serviceID=236, operation=ProvideDiagnosisKeysOperation
this would indicate an error during the GMS Operation as they somehow have no export file anymore.
Tj20
commented
4 years ago I used adb only once or twice on my Vernee Thor (Android 6.0), but I downloaded the latest version (platform-tools_r30.0.3-windows) for my Win 10 and tried it. Not much luck because I barely know what I'm doing, but maybe others can help. If I should try something else, let me know.
adb devices works and shows that my device is connected.
adb shell dumpsys activity provider com.google.android.gms.chimera.container.GmsModuleProvider | grep 'nearby_en\|\[Container\]'doesn't work. It says "Der Befehl "grep" ist entweder falsch geschrieben oder konnte nicht gefunden werden."
adb bugreport D:\adb-reportdoesn't work (I made sure to create a directory with that name). It says: Failed to get bugreportz version: 'bugreportz -v' returned '/system/bin/sh: bugreportz: not found' (code 0). If the device does not run Android 7.0 or above, try 'adb bugreport' instead.
adb bugreport spams a million lines of text on the screen, but it doesn't get saved to a file anywhere as far as I can see, and when reaching the end, you can't scroll back far enough to read or copy the beginning in the cmd box.
edit: Thanks, @aurisnoctis As advised, I did it without the grep command and searched manually, and got this:
com.google.android.gms [202117020] [20.21.17 (040406-316502805)] [Container]
com.google.android.gms.nearby_en [v202304013]
kryops
commented
4 years ago Same issue on the Honor 6: com.google.android.gms.common.api.ApiException: 10: Unable to validate key file signature: Pipe is closed
Appeared once yesterday but was able to recover after an app restart; since today the error occurs at every app start. Reinstalling didn't help.
Edit: Output of adb shell dumpsys activity provider com.google.android.gms.chimera.container.GmsModuleProvider | grep 'nearby_en\|\[Container\]'
com.google.android.gms [202117018] [20.21.17 (040308-316502805)] [Container]
com.google.android.gms.nearby_en [v202304013]My (roughly cleaned up) output of adb logcat *:V: https://gist.github.com/kryops/49a96808e16c7bb22678e978f0373140
DanielSWolf
commented
4 years ago Okay, could you give us some more details of your devices via ADB? Concretely, we would like to know the GMS Version.
com.google.android.gms [202117021] [20.21.17 (040408-316502805)] [Container]
com.google.android.gms.nearby_en [v202304013]GMS version and Google Play Services version see Update in comment https://github.com/corona-warn-app/cwa-app-android/issues/737#issuecomment-650144069
aurisnoctis
commented
4 years ago @Tj20
"Der Befehl "grep" ist entweder falsch geschrieben oder konnte nicht gefunden werden."
grep is a standard shell command in Linux. I cannot help you with a replacement in Windows for grep, but all that grep does is search through text so you could omit it and just execute the command without grep:
adb shell dumpsys activity provider com.google.android.gms.chimera.container.GmsModuleProvider
Without grep I get about 700 lines of text as output. Transfer the text to any text editor and search for two lines:
nearby_en[Container]aurisnoctis
commented
4 years ago @jakobmoellersap Thank you for your brief analysis.
06-26 09:48:27.960 13871 4874 W System.err: stat failed: ENOENT (No such file or directory) : /data/user/0/com.google.android.gms/app_en_diagnosis_keys/1593157707970/export0.bin 06-26 09:48:27.980 13871 4874 E AsyncOperation: serviceID=236, operation=ProvideDiagnosisKeysOperation
this would indicate an error during the GMS Operation as they somehow have no export file anymore.
Which means you have to contact Google about it?
kbobrowski
commented
4 years ago @jakobmoellersap @aurisnoctis can confirm that when this error occurs there is not enough export files created internally in GMS.
root@titan_umtsds:/data/data/com.google.android.gms/app_en_diagnosis_keys #
ls -la | tail
drwx------ u0_a16 u0_a16 2020-06-26 17:22 1593184957172
drwx------ u0_a16 u0_a16 2020-06-26 17:22 1593184957368
drwx------ u0_a16 u0_a16 2020-06-26 17:22 1593184957559
drwx------ u0_a16 u0_a16 2020-06-26 17:23 1593185019079
drwx------ u0_a16 u0_a16 2020-06-26 17:23 1593185019294
drwx------ u0_a16 u0_a16 2020-06-26 17:23 1593185019493
drwx------ u0_a16 u0_a16 2020-06-26 17:36 1593185793108
drwx------ u0_a16 u0_a16 2020-06-26 17:36 1593185793401
drwx------ u0_a16 u0_a16 2020-06-26 17:36 1593185793530
drwx------ u0_a16 u0_a16 2020-06-26 17:40 1593186001570This is after 3 successful queries to EN framework, and 1 failed with error 10. For the first 3 there are 3 directories, and for the failed one there is only one directory created.
kbobrowski
commented
4 years ago When the error 10 occurs the app cache is empty, despite it making 3 successful calls to /date endpoint (as monitored with mitm):
root@titan_umtsds:/data/data/de.rki.coronawarnapp/cache/key-export # ls
root@titan_umtsds:/data/data/de.rki.coronawarnapp/cache/key-export #When there is no error the files actually exist:
root@titan_umtsds:/data/data/de.rki.coronawarnapp/cache/key-export # ls -la
-rw------- u0_a130 u0_a130 21543 2020-06-26 18:03 0adc8815-f8a0-39cc-a022-f366c51819f9.zip
-rw------- u0_a130 u0_a130 9768 2020-06-26 18:03 1c3216d6-c5c5-3727-86f5-7ce6bcd16060.zip
-rw------- u0_a130 u0_a130 13631 2020-06-26 18:03 81a2d7a0-6d15-31eb-b89b-8b648347aaaa.zipCould it be that Android cleans up this cache before EN framework has a chance to digest it (I have about 4GB of space free)? Or maybe paths land in internal DB which holds these paths, but files are not actually written to key-export? Would it be a good idea to check if files exist before calling provideDiagnosisKeys?
jakobmoellerdev
commented
4 years ago @kbobrowski Thanks for pointing that out. As far as I can tell, we actually do check if the file references exist before giving them into the API. The main logic to retrieve files is located in https://github.com/corona-warn-app/cwa-app-android/blob/dev/Corona-Warn-App/src/main/java/de/rki/coronawarnapp/util/CachedKeyFileHolder.kt
There we can see that file references are loaded in only if the File exists, as getFilesFromEntries explicitly checks for the File Existence to ensure this never happens in https://github.com/corona-warn-app/cwa-app-android/blob/dev/Corona-Warn-App/src/main/java/de/rki/coronawarnapp/storage/keycache/KeyCacheRepository.kt
Also in before retrieving the files, we do deleteOutdatedEntries which should ensure no file reference is given to the API that is invalid.
The Files out of this Call are later used for provideDiagnosisKeys. What is also interesting is that technically the files in GMS should be different from the files we provide as we only give in ZIP Files while GMS handles the binary data.
kbobrowski
commented
4 years ago @jakobmoellersap this is strange error then, it seems to have something to do with missing files in key-export, but if there is a file missing then provideDiagnosisKeys should throw 39506...
creating default exposure configuration
looking for en instance
found en instance
provideDiagnosisKeys(
keys=[/data/local/tmp/some-fake-path.zip]
conf=ExposureConfiguration<minimumRiskScore: 4, attenuationScores: [4, 4, 4, 4, 4, 4, 4, 4], attenuationWeight: 50, daysSinceLastExposureScores: [4, 4, 4, 4, 4, 4, 4, 4], daysSinceLastExposureWeight: 50, durationScores: [4, 4, 4, 4, 4, 4, 4, 4], durationWeight: 50, transmissionRiskScores: [4, 4, 4, 4, 4, 4, 4, 4], transmissionRiskWeight: 50, durationAtAttenuationThresholds: [50, 74]>
token=rrandomtoken1337
)
on failure listener: com.google.android.gms.common.api.ApiException: 39506: No such file or directoryExactly my thought. I think at the time the files are given to the API, the files exist (at least they formally exist if we can trust File.exists()). I would expect either a proper GMS Error Code or a file related error, but no SSL Pipe Breakdown because the Security Provider doesn't find a file to run a Public Key Verification on. Really strange behavior together with your observation. Could it have something to do with the permissions for reading files in the App Sandbox?
This is also not strictly security-related as this should instead result in a read SecurityException (https://developer.android.com/reference/java/io/File#exists())
kbobrowski
commented
4 years ago Files shortly appear, but they are quickly deleted (they exist less than 1 second), so I guess File::exists returns true but they are being deleted as EN framework is in the process of unpacking it and validating signature... error 10 follows
root@titan_umtsds:/data/data/de.rki.coronawarnapp # ls cache/key-export/
root@titan_umtsds:/data/data/de.rki.coronawarnapp # ls cache/key-export/
root@titan_umtsds:/data/data/de.rki.coronawarnapp # ls cache/key-export/
0adc8815-f8a0-39cc-a022-f366c51819f9.zip
1c3216d6-c5c5-3727-86f5-7ce6bcd16060.zip
81a2d7a0-6d15-31eb-b89b-8b648347aaaa.zip
root@titan_umtsds:/data/data/de.rki.coronawarnapp # ls cache/key-export/
root@titan_umtsds:/data/data/de.rki.coronawarnapp # ls cache/key-export/
root@titan_umtsds:/data/data/de.rki.coronawarnapp # ls cache/key-export/by the way: this deletion happens rarely, every couple of runs
kbobrowski
commented
4 years ago Could Android be messing something up here? I don't see a place in the code which could delete it, especially since I'm starting from empty key-export. From the docs of [getCacheDir](https://developer.android.com/reference/android/content/Context#getCacheDir()):
The system will automatically delete files in this directory as disk space is needed elsewhere on the device. The system will always delete older files first, as reported by File#lastModified(). If desired, you can exert more control over how files are deleted using StorageManager#setCacheBehaviorGroup(File, boolean) and StorageManager#setCacheBehaviorTombstone(File, boolean).
Apps are strongly encouraged to keep their usage of cache space below the quota returned by StorageManager#getCacheQuotaBytes(java.util.UUID). If your app goes above this quota, your cached files will be some of the first to be deleted when additional disk space is needed. Conversely, if your app stays under this quota, your cached files will be some of the last to be deleted when additional disk space is needed.
Note that your cache quota will change over time depending on how frequently the user interacts with your app, and depending on how much system-wide disk space is used.
Adding this to implementation would be really useful to debug these issues: setCacheBehaviorTombstone - if the file gets deleted by the system then it will still exist but with zero bytes, and then we have a way to check if this behavior occurred
kbobrowski
commented
4 years ago de.rki.coronawarnapp is removing these files. It happens sometimes, if it does not happen then there is no error
/* TID 0x4ebe */
33115 ms open(pathname="/data/user/0/de.rki.coronawarnapp/cache/key-export/81a2d7a0-6d15-31eb-b89b-8b648347aaaa.zip", flags=0x241)
/* TID 0x50ef */
33116 ms open(pathname="/data/user/0/de.rki.coronawarnapp/cache/key-export/0adc8815-f8a0-39cc-a022-f366c51819f9.zip", flags=0x241)
/* TID 0x4ebf */
33116 ms open(pathname="/data/user/0/de.rki.coronawarnapp/cache/key-export/1c3216d6-c5c5-3727-86f5-7ce6bcd16060.zip", flags=0x241)
/* TID 0x4fc1 */
33311 ms open(pathname="/data/user/0/de.rki.coronawarnapp/cache/key-export/81a2d7a0-6d15-31eb-b89b-8b648347aaaa.zip", flags=0x0)
33783 ms open(pathname="/data/user/0/de.rki.coronawarnapp/cache/key-export/1c3216d6-c5c5-3727-86f5-7ce6bcd16060.zip", flags=0x0)
/* TID 0x4e7b */
33877 ms remove(pathname="/data/user/0/de.rki.coronawarnapp/cache/key-export/81a2d7a0-6d15-31eb-b89b-8b648347aaaa.zip")
33878 ms remove(pathname="/data/user/0/de.rki.coronawarnapp/cache/key-export/1c3216d6-c5c5-3727-86f5-7ce6bcd16060.zip")
33878 ms remove(pathname="/data/user/0/de.rki.coronawarnapp/cache/key-export/0adc8815-f8a0-39cc-a022-f366c51819f9.zip")We can see here that 3 files are open for writing - this is downloading, then EN framework opens 2 files for reading, this is also reflected in the fact that only 2 internal dirs are created:
root@titan_umtsds:/data/data/com.google.android.gms/app_en_diagnosis_keys #
ls -la | tail -n 3
drwx------ u0_a16 u0_a16 2020-06-26 20:00 1593194401632
drwx------ u0_a16 u0_a16 2020-06-26 20:14 1593195242205
drwx------ u0_a16 u0_a16 2020-06-26 20:14 1593195242709Then removing kicks and error is thrown
jakobmoellerdev
commented
4 years ago Okay, this will take a bit to verify. But from what we can see here, either we should move to data store instead of cache as an implementation detail to make sure this never happens (as we do our own "caching" behavior) or we manage to find out the root cause why the files are deleted so fast in the first place. Your insight is extremely valuable @kbobrowski, thank you!
kbobrowski
commented
4 years ago I've hooked into File.delete() and printed stack trace of a call which deletes Diagnosis Keys, looks like it is triggered by KeyCacheRepository.clear():
dalvik.system.VMStack.getThreadStackTrace(Native Method)
java.lang.Thread.getStackTrace(Thread.java:580)
java.io.File.delete(Native Method)
de.rki.coronawarnapp.storage.keycache.KeyCacheRepository.clear(KeyCacheRepository.kt:10)
de.rki.coronawarnapp.storage.keycache.KeyCacheRepository$clear$1.invokeSuspend(KeyCacheRepository.kt)
kotlin.coroutines.jvm.internal.BaseContinuationImpl.resumeWith(ContinuationImpl.kt:2)
kotlinx.coroutines.DispatchedTask.run(DispatchedTask.kt:18)
android.os.Handler.handleCallback(Handler.java:746)
android.os.Handler.dispatchMessage(Handler.java:95)
android.os.Looper.loop(Looper.java:148)
android.app.ActivityThread.main(ActivityThread.java:5443)
java.lang.reflect.Method.invoke(Native Method)
com.android.internal.os.ZygoteInit$MethodAndArgsCaller.run(ZygoteInit.java:728)
com.android.internal.os.ZygoteInit.main(ZygoteInit.java:618)in the end this deleting of files may be completely unrelated to the source of the problem - If I understand this correctly in case some error is raised by EN framework then rollback() in the transaction will be called, which will delete all files, calling KeyCacheRepository.clear()
jakobmoellerdev
commented
4 years ago Again, correct. If the behavior is as we expect the CWA clear should only happen after the files are actually deleted by the cache operation. Our clear also removes them from our cached references which should prevent an API call with these files.
kbobrowski
commented
4 years ago yes, I've modified File.delete() so it does not delete diagnosis keys under any circumstances and they are still there after the error, so definitely unrelated
kbobrowski
commented
4 years ago Was able to isolate this problem only to provideDiagnosisKeys, fails randomly:
provideDiagnosisKeys(keys=[/data/local/tmp/key-export/81a2d7a0-6d15-31eb-b89b-8b648347aaaa.zip])
provideDiagnosisKeys(keys=[/data/local/tmp/key-export/0adc8815-f8a0-39cc-a022-f366c51819f9.zip])
provideDiagnosisKeys(keys=[/data/local/tmp/key-export/1c3216d6-c5c5-3727-86f5-7ce6bcd16060.zip])
on success listener: null
on success listener: null
on success listener: null
provideDiagnosisKeys(keys=[/data/local/tmp/key-export/81a2d7a0-6d15-31eb-b89b-8b648347aaaa.zip])
provideDiagnosisKeys(keys=[/data/local/tmp/key-export/0adc8815-f8a0-39cc-a022-f366c51819f9.zip])
provideDiagnosisKeys(keys=[/data/local/tmp/key-export/1c3216d6-c5c5-3727-86f5-7ce6bcd16060.zip])
on success listener: null
on success listener: null
on success listener: null
provideDiagnosisKeys(keys=[/data/local/tmp/key-export/81a2d7a0-6d15-31eb-b89b-8b648347aaaa.zip])
provideDiagnosisKeys(keys=[/data/local/tmp/key-export/0adc8815-f8a0-39cc-a022-f366c51819f9.zip])
provideDiagnosisKeys(keys=[/data/local/tmp/key-export/1c3216d6-c5c5-3727-86f5-7ce6bcd16060.zip])
on success listener: null
on success listener: null
on failure listener: com.google.android.gms.common.api.ApiException: 10: Unable to validate key file signature: Pipe is closed
provideDiagnosisKeys(keys=[/data/local/tmp/key-export/81a2d7a0-6d15-31eb-b89b-8b648347aaaa.zip])
provideDiagnosisKeys(keys=[/data/local/tmp/key-export/0adc8815-f8a0-39cc-a022-f366c51819f9.zip])
provideDiagnosisKeys(keys=[/data/local/tmp/key-export/1c3216d6-c5c5-3727-86f5-7ce6bcd16060.zip])
on failure listener: com.google.android.gms.common.api.ApiException: 10: Unable to validate key file signature: Pipe is closed
on success listener: null
on success listener: nullBetween each run app is re-spawned, files are not touched. Will let Google know since it seems to be unrelated to CWA.
Possible workaround seems to be to just retry calling provideDiagnosisKeys in case of this exception - hopefully if the exception is raised then quota is not taken. It's quite serious issue since if this frequency is typical (1 exception per 6 calls on average), then soon on some devices this exception will be raised with almost every batch of files being submitted.
benekuehn
commented
4 years ago Same on P8 lite of my mom. Android 6.0. I am not an android user, so I do not know how to provide further infos. however, I wanted to let you know that the bug occurred. Attached all infos and stats I could found. If I can help with providing any further info, please ket me now.
Error message
System information
MichaDo
commented
4 years ago The error occurs every morning with every start of the app until the daily connection to get the current keys is finished. After that I have silence for the rest of the day.
06-27 08:49:02.601 7808-6806/? I/ExposureNotification: ThreadSafeLevelDbWrapper:en-matching-request-db instance btz@2042710 created [CONTEXT service_id=236 ]
06-27 08:49:02.605 7808-6806/? I/ExposureNotification: ThreadSafeLevelDbWrapper:en-matching-request-db instance btz@2042710 closed [CONTEXT service_id=236 ]
06-27 08:49:02.629 7808-6806/? I/ExposureNotification: ThreadSafeLevelDbWrapper: do close LevelDb en-matching-request-db [CONTEXT service_id=236 ]
06-27 08:49:02.668 7808-7808/? I/ExposureNotification: ThreadSafeLevelDbWrapper: do open LevelDb en-matching-request-db [CONTEXT service_id=236 ]
06-27 08:49:02.668 7808-7808/? I/ExposureNotification: ThreadSafeLevelDbWrapper:en-matching-request-db instance btz@f2fbc0e created [CONTEXT service_id=236 ]
06-27 08:49:02.671 7808-7808/? I/ExposureNotification: ThreadSafeLevelDbWrapper:en-matching-request-db instance btz@f2fbc0e closed [CONTEXT service_id=236 ]
06-27 08:49:02.672 7808-7808/? I/ExposureNotification: ThreadSafeLevelDbWrapper: do close LevelDb en-matching-request-db [CONTEXT service_id=236 ]
06-27 08:49:02.677 7808-7468/? I/ExposureNotification: [MatchingTracer: requestId=1593240542518, package=...rki.coronawarnapp] Starting matching job. [CONTEXT service_id=236 ]
06-27 08:49:02.678 7808-7468/? I/ExposureNotification: [MatchingTracer: requestId=1593240542518, package=...rki.coronawarnapp] Java pre-filter started. [CONTEXT service_id=236 ]
06-27 08:49:02.678 7808-7468/? I/ExposureNotification: ThreadSafeLevelDbWrapper:contact-tracing-contact-record-db instance btz@32f8b1a created [CONTEXT service_id=236 ]
06-27 08:49:02.751 7808-10217/? I/ExposureNotification: ThreadSafeLevelDbWrapper: do open LevelDb en-matching-request-db [CONTEXT service_id=236 ]
06-27 08:49:02.751 7808-10217/? I/ExposureNotification: ThreadSafeLevelDbWrapper:en-matching-request-db instance btz@7bc564b created [CONTEXT service_id=236 ]
06-27 08:49:02.751 7808-10217/? I/ExposureNotification: ThreadSafeLevelDbWrapper:en-matching-request-db instance btz@7bc564b closed [CONTEXT service_id=236 ]
06-27 08:49:02.752 7808-10217/? I/ExposureNotification: ThreadSafeLevelDbWrapper: do close LevelDb en-matching-request-db [CONTEXT service_id=236 ]
06-27 08:49:02.790 7808-6806/? E/AsyncOperation: serviceID=236, operation=ProvideDiagnosisKeysOperation
OperationException[Status{statusCode=Unable to validate key file signature: Pipe is closed, resolution=null}]
at bnt.a(:com.google.android.gms.policy_nearby@202304013@202304013031.315351686.315351686:187)
at azi.run(:com.google.android.gms.policy_nearby@202304013@202304013031.315351686.315351686:11)
at ddp.run(:com.google.android.gms.policy_nearby@202304013@202304013031.315351686.315351686:2)
at avl.b(:com.google.android.gms.policy_nearby@202304013@202304013031.315351686.315351686:12)
at avl.run(:com.google.android.gms.policy_nearby@202304013@202304013031.315351686.315351686:7)
at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1113)
at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:588)
at stk.run(:com.google.android.gms@202117021@20.21.17 (040408-316502805):0)
at java.lang.Thread.run(Thread.java:818)
06-27 08:49:02.791 7808-7808/? I/ExposureNotification: ThreadSafeLevelDbWrapper: do open LevelDb en-matching-request-db [CONTEXT service_id=236 ]
06-27 08:49:02.791 7808-7808/? I/ExposureNotification: ThreadSafeLevelDbWrapper:en-matching-request-db instance btz@d7a9941 created [CONTEXT service_id=236 ]
06-27 08:49:02.794 7808-7808/? I/ExposureNotification: ThreadSafeLevelDbWrapper:en-matching-request-db instance btz@d7a9941 closed [CONTEXT service_id=236 ]
06-27 08:49:02.794 7808-7808/? I/ExposureNotification: ThreadSafeLevelDbWrapper: do close LevelDb en-matching-request-db [CONTEXT service_id=236 ]
06-27 08:49:02.799 7808-7817/? I/art: Background sticky concurrent mark sweep GC freed 231980(14MB) AllocSpace objects, 67(1336KB) LOS objects, 29% free, 33MB/46MB, paused 2.251ms total 106.113ms
06-27 08:49:02.843 25436-25436/? W/System.err: com.google.android.gms.common.api.ApiException: 10: Unable to validate key file signature: Pipe is closed
06-27 08:49:02.844 25436-25436/? W/System.err: at android.support.v4.media.MediaDescriptionCompatApi21$Builder.setResultOrApiException(MediaDescriptionCompatApi21.java:3)
06-27 08:49:02.844 25436-25436/? W/System.err: at com.google.android.gms.internal.nearby.zzae.onResult(com.google.android.gms:play-services-nearby@@18.0.2-eap:2)
06-27 08:49:02.844 25436-25436/? W/System.err: at com.google.android.gms.common.api.internal.IStatusCallback$Stub.zaa(com.google.android.gms:play-services-base@@17.3.0:2)
06-27 08:49:02.844 25436-25436/? W/System.err: at com.google.android.gms.internal.base.zaa.onTransact(com.google.android.gms:play-services-base@@17.3.0:3)
06-27 08:49:02.844 25436-25436/? W/System.err: at android.os.Binder.execTransact(Binder.java:453)Possible workaround is to simply retry calling provideDiagnosisKeys until it succeeds:
provideDiagnosisKeys(keys=[/data/local/tmp/key-export/81a2d7a0-6d15-31eb-b89b-8b648347aaaa.zip])
provideDiagnosisKeys(keys=[/data/local/tmp/key-export/0adc8815-f8a0-39cc-a022-f366c51819f9.zip])
provideDiagnosisKeys(keys=[/data/local/tmp/key-export/1c3216d6-c5c5-3727-86f5-7ce6bcd16060.zip])
on success listener: null
on success listener: null
on failure listener: com.google.android.gms.common.api.ApiException: 10: Unable to validate key file signature: Pipe is closed
retrying provideDiagnosisKeys(keys=[/data/local/tmp/key-export/81a2d7a0-6d15-31eb-b89b-8b648347aaaa.zip])
on failure listener: com.google.android.gms.common.api.ApiException: 10: Unable to validate key file signature: Pipe is closed
retrying provideDiagnosisKeys(keys=[/data/local/tmp/key-export/81a2d7a0-6d15-31eb-b89b-8b648347aaaa.zip])
on success listener: nullWe are in contact with Google about this and will update here once we decided on the way forward. This is not gonna affect your key generation inside EN and will lead to temporary failures of the Risk Status Resolvement. We hope to have this fixed in the next week.
gitbrueck
commented
4 years ago We are in contact with Google about this and will update here once we decided on the way forward. This is not gonna affect your key generation inside EN and will lead to temporary failures of the Risk Status Resolvement. We hope to have this fixed in the next week.
I appreciate your open communication in this Issue. What do you think about communicating with Google via a linked Github Issue?
jakobmoellerdev
commented
4 years ago @kbobrowski With the way the current API call is behaving, it is hard to differentiate the error cause of an API Exception. Also as of right now, your proposed PR is only checking for an API Exception which could in theory be anything (not just 10). Also while this workaround might be a "solution" for now, we have to think of a way forward. This should never be the default behavior of the API and simply retrying can and will lead to more problems due to tech debt and maybe this even results in Quota failure as a call to provideDiagnosisKeys should in theory always result in quota reduction as far as I understand the API. I do agree that the issue is getting more and more pressing with each day a key package is present, up to 14 packages max.
@gitbrueck we first want to achieve a common idea of what we want to achieve and resolve before going for public communication in this matter, as any information that we share here could mislead users.
Auf Gerät mit Android 6.0
Scan 24.06.2020.pdf
Internal Tracking ID: EXPOSUREAPP-1714