Defend against insane clocks

VERIFIED FIXED in mozilla21

Status

Android Background Services
Product Announcements
VERIFIED FIXED
5 years ago
4 years ago

People

(Reporter: rnewman, Assigned: rnewman)

Tracking

(Blocks: 1 bug)

unspecified
mozilla21
ARM
Android
Dependency tree / graph

Firefox Tracking Flags

(Not tracked)

Details

(Whiteboard: [qa!])

Attachments

(2 attachments)

(Assignee)

Description

5 years ago
We can do better than we do now, even if we can't entirely handle the problem.
(Assignee)

Updated

5 years ago
Depends on: 838464
(Assignee)

Comment 1

5 years ago
Build:

http://people.mozilla.com/~rnewman/time.apk
Assignee: nobody → rnewman
Status: NEW → ASSIGNED
(Assignee)

Comment 2

5 years ago
QA:

This bug attempts to make the product announcements client more robust against phone clock errors.

It does so in two ways.

* When Fennec launches and records its launch timestamp, we ignore the value if:
** The current clock is older than the build timestamp (2013-02-12T0500Z, approx, for this build).
** The time is more than four years since the product was built.

(If the value is older than the previous launch timestamp, we log at DEBUG.)

* When we compute an idle time, we refuse to attach one if:
** The last timestamp was negative or zero.
** The current clock is older than the build timestamp (2013-02-12T0500Z, approx, for this build).
** The current clock is earlier than the last launch timestamp.
** The phone has been apparently idle for more than a year.

The goal of this is to defend against:

* Clock being set to 1970 or 2000 on launch.
* Clock being reset to one of those early dates due to a battery change.
* Odd clock jumps due to network time issues.

You can test these by applying the obvious permutations of the above, changing the system clock and either launching Fennec or waiting for a fetch to be issued. Verify that appropriate WARN and DEBUG logs are printed, and no out-of-range idle parameters are included in the request.


Note that we do *not* yet compare the phone clock to the received date from the server, and probably will not do so. This avoids us shooting ourselves in the foot should we fast-forward server times to avoid record re-fetch problems.

Tracy, please test! :D
Flags: needinfo?(twalker)
(Assignee)

Comment 3

5 years ago
Created attachment 712802 [details] [diff] [review]
Proposed patch. v1

Reviewed by nalexander: https://github.com/mozilla-services/android-sync/pull/292
Attachment #712802 - Flags: review+
(Assignee)

Comment 4

5 years ago
Tracy, if you could get this done this week, I'd much appreciate it.
Whiteboard: [qa+]
jr, the stage environment is down again.  I can't verify this 'til it is back up. Can you take a look at stage?
Flags: needinfo?(twalker) → needinfo?(jrconlin)
QA Contact: twalker
Created attachment 713415 [details]
log of time clock skewed fetch

jr fixed stage.

I've attached a log of the first fetch after the following.

1) set device date to Jan 1, 2000 and left at current local time
2) Installed test build then installed test add-on
3) Set pref to use stage
4) Set pref to fetch every ~15 seconds

noted:

- No crazy idle time in the fetch request
- It fetched the older of two available announcements. it got "test" 8 Jan 2013 vs "TEST THIS THING" 06 Feb 2013
- Should the client have received a record at all?
- The certificate warning seems reasonable
-I'm not sure what log messages you're expecting.  Are they in this log or not?
Flags: needinfo?(jrconlin)
(Assignee)

Comment 7

5 years ago
(In reply to Tracy Walker [:tracy] from comment #6)

> - Should the client have received a record at all?

Yes. The server doesn't know the client time.

> - The certificate warning seems reasonable

Yup, just a nice check that the local time is set!

> -I'm not sure what log messages you're expecting.  Are they in this log or
> not?

You trimmed the log too short -- it's missing startup, when the timestamp is written. You can set GeckoAnnounce to DEBUG, and filter adb logcat to make your life simpler:

  adb shell setprop log.tag.GeckoAnnounce DEBUG
  adb logcat -v time | fgrep GeckoAnnounce


Because the startup timestamp wasn't written, there's no way to calculate an idle, which is not a logged event.

So this verifies the first pair of conditions: clock so wrong that no timestamp is written, no timestamp means no idle.

Now we need to check clock-hopping.
Not sure what you mean by this: * Odd clock jumps due to network time issues. How would I go about testing?

I tried setting date to 2 days into the future (in this case 2/16/2013). I got the following after adding Fennec and test add-on:

02-16 10:33:02.731 D/GeckoAnnounce( 2805): fennec_rnewman :: AnnounceBrSvc :: Broadcast onReceive. Intent is org.mozilla.fennec_rnewman.ANNOUNCEMENTS_PREF
02-16 10:33:02.731 D/GeckoAnnounce( 2805): fennec_rnewman :: AnnounceBrSvc :: GeckoApp/android.not_a_preference.privacy.announcements.enabled = true
02-16 10:33:02.731 I/GeckoAnnounce( 2805): fennec_rnewman :: AnnounceBrSvc :: Registering announcements broadcast receiver...
02-16 10:33:02.761 I/GeckoAnnounce( 2805): fennec_rnewman :: AnnounceBrSvc :: Setting inexact repeating alarm for interval 43200000
02-16 10:35:16.141 D/GeckoAnnounce( 2805): fennec_rnewman :: AnnounceBrSvc :: Broadcast onReceive. Intent is org.mozilla.fennec_rnewman.ANNOUNCEMENTS_PREF
02-16 10:35:16.141 D/GeckoAnnounce( 2805): fennec_rnewman :: AnnounceBrSvc :: GeckoApp/android.not_a_preference.privacy.announcements.enabled = true
02-16 10:35:16.141 I/GeckoAnnounce( 2805): fennec_rnewman :: AnnounceBrSvc :: Registering announcements broadcast receiver...
02-16 10:35:16.151 I/GeckoAnnounce( 2805): fennec_rnewman :: AnnounceBrSvc :: Setting inexact repeating alarm for interval 43200000
02-16 10:35:31.621 D/GeckoAnnounce( 2805): fennec_rnewman :: AnnounceBrSvc :: Broadcast onReceive. Intent is org.mozilla.fennec_rnewman.ANNOUNCEMENTS_PREF
02-16 10:35:31.621 D/GeckoAnnounce( 2805): fennec_rnewman :: AnnounceBrSvc :: GeckoApp/android.not_a_preference.privacy.announcements.enabled = true
02-16 10:35:31.621 I/GeckoAnnounce( 2805): fennec_rnewman :: AnnounceBrSvc :: Registering announcements broadcast receiver...
02-16 10:35:31.631 I/GeckoAnnounce( 2805): fennec_rnewman :: AnnounceBrSvc :: Setting inexact repeating alarm for interval 15000
02-16 10:35:31.651 D/GeckoAnnounce( 2805): fennec_rnewman :: AnnounceService :: Creating AnnouncementsService.
02-16 10:35:31.661 D/GeckoAnnounce( 2805): fennec_rnewman :: AnnounceService :: Running AnnouncementsService.
02-16 10:35:31.661 D/GeckoAnnounce( 2805): fennec_rnewman :: AnnounceFetch :: Fetching announcements. Last launch: 0; now: 1361032531665
02-16 10:35:31.661 D/GeckoAnnounce( 2805): fennec_rnewman :: AnnounceFetch :: Fetch URI: idle for -1 days.
02-16 10:35:31.661 I/GeckoAnnounce( 2805): fennec_rnewman :: AnnounceFetch :: Fetching announcements from http://CampaignManager-Stage-272259297.us-east-1.elb.amazonaws.com/announce/1/android/dev/21.0a1/armeabi-v7a
02-16 10:35:31.671 D/GeckoAnnounce( 2805): fennec_rnewman :: BaseResource :: HTTP GET http://CampaignManager-Stage-272259297.us-east-1.elb.amazonaws.com/announce/1/android/dev/21.0a1/armeabi-v7a
02-16 10:35:32.041 D/GeckoAnnounce( 2805): fennec_rnewman :: BaseResource :: Response: HTTP/1.1 200 OK
02-16 10:35:32.051 D/GeckoAnnounce( 2805): fennec_rnewman :: AnnounceFetchRD :: Got announcements response: 200
02-16 10:35:32.101 I/GeckoAnnounce( 2805): fennec_rnewman :: AnnounceService :: Processing announcements: 1
02-16 10:35:46.641 D/GeckoAnnounce( 2805): fennec_rnewman :: AnnounceStartRec :: AnnouncementsStartReceiver.onReceive().
02-16 10:35:46.651 D/GeckoAnnounce( 2805): fennec_rnewman :: AnnounceService :: Creating AnnouncementsService.
02-16 10:35:46.661 D/GeckoAnnounce( 2805): fennec_rnewman :: AnnounceService :: Running AnnouncementsService.
02-16 10:35:46.681 D/GeckoAnnounce( 2805): fennec_rnewman :: AnnounceService :: Returning: minimum fetch interval of 15000ms not met.
02-16 10:35:46.681 D/GeckoAnnounce( 2805): fennec_rnewman :: AnnounceService :: Not fetching.
then the log starts repeating:

02-16 10:36:01.631 D/GeckoAnnounce( 2805): fennec_rnewman :: AnnounceStartRec :: AnnouncementsStartReceiver.onReceive().
02-16 10:36:01.651 D/GeckoAnnounce( 2805): fennec_rnewman :: AnnounceService :: Creating AnnouncementsService.
02-16 10:36:01.651 D/GeckoAnnounce( 2805): fennec_rnewman :: AnnounceService :: Running AnnouncementsService.
02-16 10:36:01.661 D/GeckoAnnounce( 2805): fennec_rnewman :: AnnounceFetch :: Fetching announcements. Last launch: 0; now: 1361032561670
02-16 10:36:01.671 D/GeckoAnnounce( 2805): fennec_rnewman :: AnnounceFetch :: Fetch URI: idle for -1 days.
02-16 10:36:01.671 I/GeckoAnnounce( 2805): fennec_rnewman :: AnnounceFetch :: Fetching announcements from http://CampaignManager-Stage-272259297.us-east-1.elb.amazonaws.com/announce/1/android/dev/21.0a1/armeabi-v7a
02-16 10:36:01.671 D/GeckoAnnounce( 2805): fennec_rnewman :: BaseResource :: HTTP GET http://CampaignManager-Stage-272259297.us-east-1.elb.amazonaws.com/announce/1/android/dev/21.0a1/armeabi-v7a
02-16 10:36:01.671 I/GeckoAnnounce( 2805): fennec_rnewman :: AnnounceFetchRD :: If-Modified-Since: Thu, 14 Feb 2013 16:35:32 GMT
02-16 10:36:01.971 D/GeckoAnnounce( 2805): fennec_rnewman :: BaseResource :: Response: HTTP/1.1 304 Not Modified
02-16 10:36:01.971 D/GeckoAnnounce( 2805): fennec_rnewman :: AnnounceFetchRD :: Got announcements response: 304
02-16 10:36:01.971 I/GeckoAnnounce( 2805): fennec_rnewman :: AnnounceService :: No new announcements to display.
02-16 10:36:16.641 D/GeckoAnnounce( 2805): fennec_rnewman :: AnnounceStartRec :: AnnouncementsStartReceiver.onReceive().
02-16 10:36:16.651 D/GeckoAnnounce( 2805): fennec_rnewman :: AnnounceService :: Creating AnnouncementsService.
02-16 10:36:16.671 D/GeckoAnnounce( 2805): fennec_rnewman :: AnnounceService :: Running AnnouncementsService.
02-16 10:36:16.681 D/GeckoAnnounce( 2805): fennec_rnewman :: AnnounceService :: Returning: minimum fetch interval of 15000ms not met.
02-16 10:36:16.681 D/GeckoAnnounce( 2805): fennec_rnewman :: AnnounceService :: Not fetching.
(Assignee)

Comment 10

5 years ago
Re

02-16 10:36:16.681 D/GeckoAnnounce( 2805): fennec_rnewman :: AnnounceService :: Returning: minimum fetch interval of 15000ms not met.

Looks like you ended up with two timers running, or otherwise Android is running our listener twice. We have an internal timer to make sure that we don't fetch too frequently, and it's working here.
between discussion in irc and comments here, this looks good to me.
https://hg.mozilla.org/mozilla-central/rev/28f53833ef37
Status: ASSIGNED → RESOLVED
Last Resolved: 5 years ago
Resolution: --- → FIXED
Component: Android: Product Announcements → Product Announcements
Product: Mozilla Services → Android Background Services

Updated

4 years ago
Status: RESOLVED → VERIFIED
Whiteboard: [qa+] → [qa!]

Updated

4 years ago
QA Contact: twalker
You need to log in before you can comment on or make changes to this bug.