Skip to content
This repository has been archived by the owner on Jun 20, 2023. It is now read-only.

CWA risk update timestamp different to Google timestamp (by one or two minutes) #948

Closed
3 tasks done
MikeMcC399 opened this issue Jul 30, 2020 · 28 comments
Closed
3 tasks done
Assignees
Labels
bug Something isn't working mirrored-to-jira This item is also tracked internally in JIRA

Comments

@MikeMcC399
Copy link
Contributor

MikeMcC399 commented Jul 30, 2020

Avoid duplicates

  • Bug is not mentioned in the FAQ
  • Bug is specific for Android only, for general issues / questions that apply to iOS and Android please raise them in the documentation repository
  • Bug is not already reported in another issue

Describe the bug

The last update time shown by CWA is sometimes one minute or two minutes earlier or later than the update time shown in the Google ENS UI.

Expected behaviour

This is a minor issue.
The timestamp shown by CWA for the last update should be the same as the timestamp shown in the Google ENS UI in the overview screen and in the exposure checks log.

Steps to reproduce the issue

  1. View CWA risk status
    Note text similar to "Updated: Today, 07:54"
  2. Settings > Google > COVID-19 Exposure Notifications > three-dot icon > Exposure checks
    Note latest timestamp in exposure checks list.

Technical details

  • Mobile device: Samsung Galaxy A5 (2017) SM-A520F
  • Android version: 8.0.0
  • CWA Version: 1.1.1 2.4.2
  • Google Exposure Notifications System Version: 15202902003 v1.8 (212116000)

Edit: Updated steps to reproduce for newer ENS UI, updated software versions and verified that the issue still occasionally occurs in current version of CWA and ENS.


Internal Tracking ID: EXPOSUREAPP-1991

@MikeMcC399 MikeMcC399 added the bug Something isn't working label Jul 30, 2020
@ghost
Copy link

ghost commented Jul 30, 2020

Hello @MikeMcC399,

thanks for pointing this out. I will take this into the discussion with our development team.

Best regards,
LMM

Corona-Warn-App Open Source Team

@ghost ghost added the mirrored-to-jira This item is also tracked internally in JIRA label Jul 30, 2020
@ghost
Copy link

ghost commented Jul 30, 2020

Hello @MikeMcC399 ,

thanks again for your investigation. Our developers have been informed. This bug probably occurs due to different rounding strategies and will be inspected as soon as possible.

Best regards,
LMM

Corona-Warn-App Open Source Team

@ghost ghost assigned JoachimFritsch Aug 6, 2020
@MikeMcC399
Copy link
Contributor Author

I noticed the Google Exposure Notification Framework (Version 15202902003) showing a time one minute into the future.
The text was "Last checked for potential exposure today at 19:49" whilst the system clock was showing the time as 19:48.
It looks like Google ENF may be rounding up the time and so maybe Google will need to make a fix.

Screenshot_20200806-194845_Google Play services

@vaubaehn
Copy link
Contributor

vaubaehn commented Aug 6, 2020

People who already read some of my comments in this repository, may know, that I'm sometimes doing some wild guesses about the source of a problem, sometimes more elaborate, sometimes less... Hope, no-one is bothered about that. If yes, please leave a note.
That being said, here my wild guess about this issue:

May it be, that CWA's timestamp is being set upon beginning checking for exposures, and ENF's timestamp at completion of checks?
As it takes some time for the checks to be performed, an overlap from one minute to the other might occur, and the reported deviation of timestamps might be the result.

Edit: that was the more less elaborate guess...
Now saw the problem clearly in the screenshot... I'm out...

@daimpi
Copy link

daimpi commented Oct 22, 2020

Just some curiosity to report mirrored from over at #1187 (comment)

My CWA status today:

My EN log entry today:
{"timestamp":"22. Oktober 2020, 03:02","keyCount":307304,"matchesCount":0,"appName":"Corona-Warn","hash":"oTbVuBbNBBnFzm25gcZH9lTOjOFRPEViypUZH7h9JzA="}

I.e. my CWA timestamp is one minute after my EN timestamp.

Maybe in my case it's a rounding error by ENF in the other direction? As long as the time difference doesn't exceed 1 min I won't be able to tell for sure I guess but it's also not that important tbh ^^

My device:

  • Samsung Galaxy S8 (Android 9)
  • CWA 1.5.0
  • ENF v. 17203915000

@MikeMcC399 MikeMcC399 changed the title CWA risk update timestamp sometimes one minute earlier than Google timestamp CWA risk update timestamp different to Google timestamp (by one or two minutes) Oct 22, 2020
@MikeMcC399
Copy link
Contributor Author

@daimpi
Thanks for your feedback!

I checked on one device I own and I'm also seeing the CWA timestamp one minute later than the EN timestamp, on another device the timestamps are identical. Both are updated to CWA 1.5.0 and I guess the change in which comes first is due to the version change from 1.3.1 to 1.5.0 and the replacement of 14 entries with just one entry per day (when things are working correctly).

I've therefore updated the title to say the timestamps are different without saying which way around.

@d4rken
Copy link
Member

d4rken commented Oct 23, 2020

The timestamp in the CWA on the card is set after the key retrieval & submission is done by the app.

It's possible that it's a racecondition. Theoretically the ENF can finish calculation before we store the timestamp, and we can also set the timestamp before the ENF does finish calculation. I have not looked into any rounding related issues, but I'm looking into changing the displayed timestamp to be "ENF calculation end" instead of "key provision to the ENF".

The ENF displaying a timestamp newer than the actual device time looks like rounding (on purpose?) on Google's side. Did it exceed 1 minute for anyone?

@vaubaehn
Copy link
Contributor

vaubaehn commented Oct 23, 2020

@d4rken

Did it exceed 1 minute for anyone?

Just for me speaking, on my slow phone, ENF timestamp was always after CWA timestamp. At the moment CWA's timestamp is 2 minutes before ENF's. Snail race condition, imho. ;) Edit: And I never saw device time before ENF timestamp.

but I'm looking into changing the displayed timestamp to be "ENF calculation end" instead of "key provision to the ENF".

Did you already do something concretely? I was thinking about coding a proposal for that as an excercise, maybe till middle/end of next week, depending on my own workload. If you already have a progress on that issue, I'd skip beginning anything.

@d4rken
Copy link
Member

d4rken commented Oct 23, 2020

Just for me speaking, on my slow phone, ENF timestamp was always after CWA timestamp. At the moment CWA's timestamp is 2 minutes before ENF's. Snail race condition, imho. ;) Edit: And I never saw device time before ENF timestamp.

I mean the discrepancy between the ENF log and the device clock (#948 (comment)).

Did you already do something concretely? I was thinking about coding a proposal for that as an excercise, maybe till middle/end of next week, depending on my own workload. If you already have a progress on that issue, I'd skip beginning anything.

I'm already working on a set of classes that will be accessible via the ENFClient class. The idea is to track the ENF submission calls, track all broadcasts from the ENF, and have a timeout mechanism to notice "missing callbacks" to notice issues in the ENF that didn't result in an exception being thrown to us.

I hope to solve 3 issues by making this class available to other parts of the app:

  • Show better timestamps
  • Show a more accurate "something is currently happening" progress indicator
  • Better error handling later know when a calculation failed on Google's end without throwing us an exception

Hope to create a PR today. Feedback on that is welcome 👍.
Currently struggling a bit with a few unit tests for some async behavior 😵, I'll get there ☕ .

@vaubaehn
Copy link
Contributor

Edit: And I never saw device time before ENF timestamp.

I mean the discrepancy between the ENF log and the device clock (#948 (comment)).

Yes, yes, I got it after submitting the comment :)

I'm already working on a set of classes that will be accessible via the ENFClient class.

Ehm, my proposal would have been... let's say, a little bit more simple. Happily awaiting your first class dinner, and skipping to cook a scrambled egg then ;)
Enjoy your coffee!

@MikeMcC399
Copy link
Contributor Author

The issue of slightly differing timestamps is still apparent in CWA Android 1.7.1.

App shows:
Updated: Today, 17:01

Google exposure log shows:
Timestamp
28 November 2020, 17:00

The previous timestamps in the Google exposure log for today were:

28 November 2020, 13:00
28 November 2020, 09:00
28 November 2020, 05:00
28 November 2020, 00:20

@d4rken
Copy link
Member

d4rken commented Nov 29, 2020

Currently still waiting on an answer from Google, previous solutions still were off by a few minutes, so we can't continue on this unless Google tells us what the timestamp represents and how it's calculated on their end 🙁 .

@MikeMcC399
Copy link
Contributor Author

@d4rken

Currently still waiting on an answer from Google, previous solutions still were off by a few minutes, so we can't continue on this unless Google tells us what the timestamp represents and how it's calculated on their end 🙁 .

... or Google extends their API to share their timestamp, so that all UIs are using the same value.

@d4rken d4rken assigned d4rken and unassigned pwoessner Nov 29, 2020
@ndegendogo
Copy link

Just throwing my 2ct in ...

If the root cause is different rounding of the same timestamp, then it would indeed be less confusing to have this aligned.

But if the root cause is that the timestamps refer to different phases in the background check (e.g. Google shows when their API was called / begin of check, and cwa shows when the check was successfully finished) - in such a case different timestamps could give more information for troubleshooting, like: what was the total duration of the check? Was there a check that was started but then aborted?

@daimpi
Copy link

daimpi commented Dec 23, 2020

Just to mirror some info relevant to this issue provided by @d4rken here:

Timestamps

The "last updated" timestamp as of 1.9.1 is "the last time we submitted keys to the ENF":

while this may be off by a few minutes from what Google shows in the system's ENF, I don't have a better solution at the moment. I've tried "time when we submit to the ENF" and "time when the ENF tells us it's done calculating" and neither consistently matched the system's ENF timestamps.

@heinezen
Copy link
Member

@MikeMcC399 Is this beaviour still happening in 2.2 ?


Corona-Warn-App Open Source Team

@MikeMcC399
Copy link
Contributor Author

Is this beaviour still happening in 2.2 ?

Yes, the issue has never been resolved and it still occurs in CWA Android 2.2.1 Probably it would need changes made to the Google interface so that the exact timestamp is passed back to the calling COVID-19 app, such as CWA.

@heinezen
Copy link
Member

Looks like we have to ask Google again for input.

@vaubaehn
Copy link
Contributor

vaubaehn commented Jul 21, 2021

I made two different observations:

  • the timestamp that is displayed in ENS UI is dependent on time that it takes for check of Diagnosis Keys. The validation of the signature of DK packages takes the biggest amount of time. We will likely see the difference between CWA timestamp and ENS timestamp increasing within the next weeks, as the incidence rates are increasing and DK packages grow in size (what for some reason has impact on signature validation).
  • the timestamp in ENS is rounded: today I could clearly observe how ENS set the entry in its UI at 19:46 with a timestamp of 19:47, some seconds before system clock changed to 19:47.

@MikeMcC399
Copy link
Contributor Author

@vaubaehn

the timestamp in ENS is rounded: today I could clearly observe how ENS set the entry in its UI at 19:46 with a timestamp of 19:47, some seconds before system clock changed to 19:47.

Same observation that I made in #948 (comment) almost one year ago, so it looks like Google didn't change anything there.

@ndegendogo
Copy link

@MikeMcC399 why should Google make a fix?
I agree that they could document more details on their timestamp, but, hey, it is their API, so how can we claim that they are doing it 'wrong'.?

@ndegendogo
Copy link

ndegendogo commented Jul 22, 2021

And I have no problems with different timestamps at all. It seems to be confusing, so it should be explained to the users, that the meaning of these timestamps is indeed 'different things'. Something along the lines:

  • cwa risk processing consists of calling the Google ENS API for exposure detection, and a post-processing to calculate the risk level from the detected exposure windows (according to RKI formula and parameters)
  • cwa timestamp shows the time where such a risk calculation was finished successfully
  • Google timestamp shows 'something different', we assume they show the time of call of their API, and we assume they round their timestamp to minutes

@MikeMcC399
Copy link
Contributor Author

@d4rken / @heinezen
Back in Nov 2020:

Currently still waiting on an answer from Google, previous solutions still were off by a few minutes, so we can't continue on this unless Google tells us what the timestamp represents and how it's calculated on their end 🙁 .

Then in May 2021

Looks like we have to ask Google again for input.

Was there ever any effective response from Google on this subject?

It's already been stated that the issue can't be resolved without Google's help, so if there is no expected movement around a discussion with Google then I would suggest closing this issue and writing a short FAQ article explaining that the timestamps in the app and in the Google UI may be different.

@d4rken
Copy link
Member

d4rken commented Jul 22, 2021

I have not heard anything back from Google on this topic.

@vaubaehn
Copy link
Contributor

vaubaehn commented Jul 22, 2021

@MikeMcC399

the timestamp in ENS is rounded: today I could clearly observe how ENS set the entry in its UI at 19:46 with a timestamp of 19:47, some seconds before system clock changed to 19:47.

Same observation that I made in #948 (comment) almost one year ago, so it looks like Google didn't change anything there.

I didn't have that in mind anymore... yes, so nothing changed after one year.

Even this issue might get closed, just one addition for the records:
What I wrote above

the timestamp that is displayed in ENS UI is dependent on time that it takes for check of Diagnosis Keys. The validation of the signature of DK packages takes the biggest amount of time. We will likely see the difference between CWA timestamp and ENS timestamp increasing within the next weeks, as the incidence rates are increasing and DK packages grow in size (what for some reason has impact on signature validation).

seems not to be completely correct, after I checked some old data.
When we look to an old syslog here: #2880 (comment) we can see that the DownloadDIagnosisKeysTask starts at 04-23 08:07:47.045 - at that days it was probably the time used for the CWA timestamp. One of the first duties of the task is to check the the network state (04-23 08:07:47.206) and then to download the Diagnosis Keys Package from TSI server. In the here reported case, that check already took more than 4 seconds. For my phone, it looks like, that checking the network state may trigger a network re-connect, if system decides that network quality should be better (I'm seeing this often on WiFi). This may be one reason that could trouble the whole "download and provide DKs" process in general.
When the Diagnosis Keys Package is handed over to the ENS via API call, then obviously all packages are copied over into ENS' system dir (indicator: Matching with /data/user/0/com.google.android.gms/app_en_diagnosis_keys/1619158071578/export0.bin). And the moment, when "ENS finds the keys", seems to be the moment, for that the ENS UI-timestamp is generated:
04-23 08:07:52.420 3606 26046 I ExposureNotification: Found flag-defined keys de.rki.coronawarnapp:262-v1,MFkwEwYHKoZIz...
Because when this syslog-timestamp is rounded up, it corresponds to the timestamp that was exported from ENS UI here: 20210401-20210518_assembled_all-exposure-checks.txt
{"timestamp":"23. April 2021, 08:08","keyCount":529032,"matchesCount":0,"appName":"Corona-Warn","hash":"rdHRoR9Plhwb97Kq7oaDNmNQCG0Ps+BRtaFiwaPeh3o="}
And ENS finished the signature validation at 04-23 08:09:02.034, and the whole exposure detection at 04-23 08:09:10.473.

So, to be able to align the CWA and ENS timestamp, CWA would need to be able to know, when ENS found the files...

@vaubaehn
Copy link
Contributor

@ndegendogo 😄
But it's like this 😉

@ndegendogo
Copy link

@vaubaehn sure 😁😁

And I am amused how diligently you are analysing the log files
I like this
(could be me...) 😅

@MikeMcC399
Copy link
Contributor Author

Despite @vaubaehn's amazing analysis and detective work, this issue can't be solved without the assistance of Google and according to the comments in this issue Google has not responded in over 9 months.

The best solution would have been for Google to pass back their timestamp via API, so there would have been no guesswork or inaccuracies. I have no hope that this will ever happen though.

So now I'm closing this issue.

Sign up for free to subscribe to this conversation on GitHub. Already have an account? Sign in.
Labels
bug Something isn't working mirrored-to-jira This item is also tracked internally in JIRA
Projects
None yet
Development

No branches or pull requests

9 participants