We can do better than we do now, even if we can't entirely handle the problem.

Build: http://people.mozilla.com/~rnewman/time.apk

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

Reviewed by nalexander: https://github.com/mozilla-services/android-sync/pull/292

Tracy, if you could get this done this week, I'd much appreciate it.

jr, the stage environment is down again. I can't verify this 'til it is back up. Can you take a look at stage?

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?

(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.

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.