search

cocoa-mhlw / cocoa

Mozilla Public License 2.0
990 stars 113 forks source link

Androidで接触確認の履歴のキーの数に0が表示される #202

Open zaruudon opened 3 years ago

zaruudon commented 3 years ago

不具合の内容 / Describe the bug

OSの「確認内容の詳細」で通常は受信したキーの数が表示される「キーの数」が0になっていました。 未受信のキーがある状態でアプリを起動してlogcatすると "Invalid input for initNative, scan records is empty" と出ていたので検索してみると同様の事例がありました。

https://github.com/corona-warn-app/cwa-app-android/issues/1752

その後端末を再起動すると翌日は正常な状態に戻っていました。

再現手順 / Steps to reproduce

発生条件は不明です。5月20日まで正常に動作していたようです。

期待される挙動 / Expected behavior

受信したキーの数が表示される。

スクリーンショット / Screenshots

Screenshot_2021-05-28-20-46-43

動作環境 / Environments

Internal Tracking ID: BUG 2096

kvaluation commented 3 years ago

cocoa_logでは、zipがダウンロードされた記録が残っているのでしょうか。 5/28配信は、zip番号が4427 - 4439, 合計692キーと思います。

zaruudon commented 3 years ago

ログではちゃんと動いているようにしか見えませんでした。 https://gist.github.com/zaruudon/be916809e23745f3f288b7f0b0bfe794

受信で失敗していたとすればハッシュが変わるはずではないかと思います。 この日の分はわからないのですが、次の日は他の端末のものと一致していました。

zaruudon commented 3 years ago

出力されたOSのログを素直に読むとRPIが全くないので照合が行われなかったということだと考えられるのですが、上述のケースではRPIは蓄積されていたと思っています。しかし確認する方法はありません。 単にRPIがないというだけで事象が発生するのであれば、

という手順で再現できるはずです。 それで試していたのですが、再現しました。

kvaluation commented 3 years ago

@zaruudon さん cocoa_logありがとうございました。しかもGistで見やすくて感動です。

1. zipダウンロード

https://gist.github.com/zaruudon/be916809e23745f3f288b7f0b0bfe794#file-cocoa_log_20210528-csv-L136 重複もなく、正常ですね。

私のAndroid 10で、この日の「確認内容の詳細」でのハッシュも692件に対応するであろう FYZ6Vrt ....でした。zipダウンロードとハッシュ計算は正常動作したと私も考えます。

TEKの処理か、その表示処理が正常でなかったと思われます。

2. 照合が数日ぶりであったこと

Deleted 'cocoa_log_20210427.csv'

cocoa_log_xxx.csvの削除は、毎日cocoaを起動していると毎日行われるところ、24ファイル削除されているので、最も単純に考えると、23日間程度起動せず、23日-24日ぶりにcocoaが起動された可能性があると思われます。久しぶりの起動の初日に何らかの不整合が出る事例は、うろ覚えですが、多少あり、しかし、次の日から毎日zipをダウンロードすると正常化していくケースが大半と思われます。 ＜久しぶり起動＞の不具合の態様や、原因は分析できていません。キー０件表示に接したのは私は本件が始めてです。

複雑に考えると、cocoa を毎日起動していてもでる不具合で、キー0件の表示日と、cocoa_log_xxx.csvの大量削除日が同日になる可能性もあるかも知れませんが、ロジックを思いつけません。

3. Downloaded files: 0

一度正常にzipをダウンロードしたのに、その後のダウンロード処理で0件に上書きされた可能性、なさそうな気がしました。 Handler.cs 260行 260行のDownloaded files: 0で、キーの数の表示が0になっていない（正常な）logは他で見たことがあります。(Android版1.2.3, Android 10)

Handler.cs 158行 158行含め4箇所のDownloaded files: 0, newCreated: 1622127613707 (2021/05/28 0:00:14JST?) で、やはり、キーの数の表示が0になっていない（正常な）logは他で見たことがあります。(Android版1.2.3, Android 10)

Downloaded files: 0と、キーの数0の表示は相関していないように思われます。

4. RPIがない場合

　2020年7月ごろまでは、RPIがなさそうだと、TEKが入っているzipのダウンロードをしにいかないような振る舞いが手元の端末でありましたが、その後はRPIの有無に応じた振る舞いの違いは発見できていないです。 　RPIの有無もキーの数0の表示と相関していなさそうという分析に賛成です。

根拠のない「なんとなく」ですが、もしこのケースで、一致した数が1以上であれば、キーの数も正常に表示されたかも、と思いました。

keiji commented 3 years ago

ありがとうございます。 corona-warn-appのIssueにも目を通しましたが、EN側が原因の可能性もありますね。Googleへの問い合わせを検討中です。

@zaruudon お手数ですが、発生した端末のGoogle開発者サービスのバージョンを教えてもらえると助かります。

zaruudon commented 3 years ago

開発者サービスのバージョンは21.18.16です。

zaruudon commented 3 years ago

cocoa_log_xxx.csvの削除は、毎日cocoaを起動していると毎日行われるところ、24ファイル削除されているので、最も単純に考えると、23日間程度起動せず、23日-24日ぶりにcocoaが起動された可能性があると思われます。

この端末では以前海外のアプリを入れていて、1.2.3がリリースされた4月21日にCOCOAに切り替えました。その後アプリは起動していませんでした。 4月21日のログが削除されているのでそれまで一度も削除されていなかったことになります。 AlarmManagerによるログの削除は動いていなかったようです。以前に見た時はアプリを起動してから3日ぐらいで止まっていました。 TEKの取得は毎日実行されるようになっていました。

i-maruyama commented 3 years ago

logcat を初めて知ったので、勉強がてら @zaruudon さんのご指示通り OS のRPIリセットをしたら「キー数０」になりました。RPI の有無で ExposureNotificationJniのログが変わります。Sharp aquos sense3lite (Google 開発者サービス ver 21.18.16)

あと私は下記のケースも疑っています。が、実証する術がないですね。

kvaluation commented 3 years ago

RPIなし & 新TEKあり → キー数０（ただしハッシュは同じ) こんな現象があるのですね。想定外でした。ありがとうございます。

Warningによるとこのあたりでしょうか。 https://github.com/google/exposure-notifications-internals/blob/aaada6ce5cad0ea1493930591557f8053ef4f113/exposurenotification/src/main/cpp/matchingjni.cc#L36

i-maruyama commented 3 years ago

Warningによるとこのあたりでしょうか。

そのようですね。私も探してみたのですが、探しきれなかったところです。ありがとうございます。

vaubaehn commented 3 years ago

Thanks for your investigations. This helped to find some plausible answers for our issue in https://github.com/corona-warn-app/cwa-app-android/issues/1752.

vaubaehn commented 3 years ago

@keiji Please allow me one off-topic question: are you still able to access/receive logcat messages from ENS? In Europe they had been disabled some time ago for privacy reasons, which makes debugging a bit hard in some cases...

keiji commented 3 years ago

@vaubaehn I am not able to see detail from logcat.

2021-08-31 08:49:01.497 1095-1177/? D/VSC: @ 126615.006: [WO] rejected by isOrientationAngleAcceptable
2021-08-31 08:49:01.939 28945-28945/? I/BgTaskExecutorImpl: Starting EXCLUSIVE background task CHIME_NOTIFICATION_ACTION_UPLOADER.
2021-08-31 08:49:02.209 3851-13634/? I/ExposureNotificationJni: Matching with /data/user/0/com.google.android.gms/app_en_diagnosis_keys/1630367342127/export0.bin
2021-08-31 08:49:02.209 3851-13634/? I/ExposureNotificationJni: Created iterator for /data/user/0/com.google.android.gms/app_en_diagnosis_keys/1630367342127/export0.bin (process_revised_keys = 1)
2021-08-31 08:49:02.209 3851-13634/? I/ExposureNotificationJni: Matching with /data/user/0/com.google.android.gms/app_en_diagnosis_keys/1630367342127/export1.bin
2021-08-31 08:49:02.209 3851-13634/? I/ExposureNotificationJni: Created iterator for /data/user/0/com.google.android.gms/app_en_diagnosis_keys/1630367342127/export1.bin (process_revised_keys = 1)
2021-08-31 08:49:02.210 3851-13634/? I/ExposureNotificationJni: Matching with /data/user/0/com.google.android.gms/app_en_diagnosis_keys/1630367342127/export2.bin
2021-08-31 08:49:02.210 3851-13634/? I/ExposureNotificationJni: Created iterator for /data/user/0/com.google.android.gms/app_en_diagnosis_keys/1630367342127/export2.bin (process_revised_keys = 1)
2021-08-31 08:49:02.346 4986-5017/? D/DeviceStateHelper: Audo mode: 0
2021-08-31 08:48:59.373 1628-2766/? I/chatty: uid=1000(system) ConnectivitySer identical 1 line
2021-08-31 08:49:02.380 1628-2766/? D/ConnectivityService: NetReassign [no changes]
2021-08-31 08:49:02.541 1628-1691/? I/ActivityManager: Waited long enough for: ServiceRecord{dbdb4f2 u0 com.google.android.gms/.cast.service.CastSocketMultiplexerLifeCycleService}
vaubaehn commented 2 years ago

@keiji Thanks for your response. Actually you have a logcat with detailed ENS log entries from what I can see in your post - in Europe they have been terminated completely due to privacy reasons. ENS is a black box for us now, making debugging even harder. Anyway, thanks again, good luck with your project - and stay healthy!