Closed Bug 694728 Opened 8 years ago Closed 8 years ago

Sync: Log Status transitions

Categories

(Firefox :: Sync, defect)

defect
Not set

Tracking

()

RESOLVED FIXED
mozilla10

People

(Reporter: rnewman, Assigned: rnewman)

Details

(Whiteboard: [verified in services])

Attachments

(1 file, 1 obsolete file)

It's amazing that the Sync Status object doesn't log its state transitions. Here we go!
Attached patch Proposed patch. v1 (obsolete) — Splinter Review
Had to fix a test, too.
Assignee: nobody → rnewman
Status: NEW → ASSIGNED
Attachment #567250 - Flags: review?(philipp)
Example log output:

1318652256285	Sync.Status	DEBUG	Status.service: error.sync.failed => success.status_ok
1318652256285	Sync.Status	DEBUG	Status.login: success.login => error.login.reason.no_recoverykey
1318652256285	Sync.Status	DEBUG	Status.service: success.status_ok => service.client_not_configured
1318652256286	Sync.SyncScheduler	DEBUG	Clearing sync triggers.
Comment on attachment 567250 [details] [diff] [review]
Proposed patch. v1

>-// Initialize various status values
>+// Initialize various status values.
> Status.resetBackoff();
> Status.resetSync();
>+
>+// Logger setup.
>+let logPref = PREFS_BRANCH + "log.logger.status";
>+let logLevel = "Trace";
>+try {
>+  logLevel = Services.prefs.getCharPref(logPref);
>+} catch (ex) {
>+  // Use default.
>+}
>+Status._log.level = Log4Moz.Level[logLevel];

I feel like we should create a Status.reset() method that calls resetBackoff() and resetSync() and does this stuff. We can then also call that from Service.startOver().

>+// Do this because adding a logger prevents JSON printing of Status (cyclic
>+// object value).

??? Is this supposed to be an explanation for why toString isn't declared within the Status object literal? In either case, I don't get the comment.

>+Status.toString = function () {
>+  return "<Status: " +
>+         Status.login + ", " +
>+         Status.service + ", " +
>+         Status.sync + ", " +
>+         Status.partial + ">";
>+};

Can we move this to within the Status object literal? Also, I suggest making the output slightly more readable:

  return "<Status: login: " + Status.login +
         ", service: " + Status.service +
         ", sync: " + Status.sync + ">";

I'm excluding Status.partial here since we don't actually use it anywhere anymore.

Speaking of not using things anymore, in the long run Status needs to DIAF. It's about the poorest way to pass error states around that I can think of. It's mostly a whiteboard for ErrorHandler and the UI to scribble on and read things from. We can get rid of much of that indirection in bug 682954.
Attachment #567250 - Flags: review?(philipp) → review-
(In reply to Philipp von Weitershausen [:philikon] from comment #3)

> I feel like we should create a Status.reset() method that calls
> resetBackoff() and resetSync() and does this stuff. We can then also call
> that from Service.startOver().

Sure.

> ??? Is this supposed to be an explanation for why toString isn't declared
> within the Status object literal? In either case, I don't get the comment.

No, it's an explanation of why we need a toString method at all. It can live inside the literal, sure.

> Can we move this to within the Status object literal? Also, I suggest making
> the output slightly more readable:

Sure.

> Speaking of not using things anymore, in the long run Status needs to DIAF.

Indeed, albeit not something I want to address here!
Not combining into `reset`, as discussed on IRC.

Instead, have moved logging setup into resetSync, which is called on startup.

Other comments addressed.
Attachment #567250 - Attachment is obsolete: true
Attachment #567303 - Flags: review?(philipp)
Attachment #567303 - Flags: review?(philipp) → review+
https://hg.mozilla.org/services/services-central/rev/47950c8ae523

A teensy bit of QA wouldn't hurt; in the course of verifying other scenarios, make sure that the Sync log shows messages like

  1318718054057	Sync.Status	DEBUG	Status.service: error.sync.failed => success.status_ok

This will occur in routine operation.
Whiteboard: [fixed in services]
Mozilla/5.0 (Windows NT 6.1; rv:10.0a1) Gecko/20111017 Firefox/10.0a1
Mozilla/5.0 (X11; Linux i686; rv:10.0a1) Gecko/20111017 Firefox/10.0a1
Mozilla/5.0 (Macintosh; Intel Mac OS X 10.6; rv:10.0a1) Gecko/20111017 Firefox/10.0a1
Mozilla/5.0 (Android; Linux armv7l; rv:10.0a1) Gecko/20111017 Firefox/10.0a1 Fennec/10.0a1

Verified the change on above builds: status transitions are logged

Examples:
1319388822847	Sync.Status	DEBUG	Status.service: error.sync.failed_partial => success.status_ok
1319388822850	Sync.Status	DEBUG	Status.service: success.status_ok => success.status_ok
1319388816434	Sync.SyncScheduler	DEBUG	Clearing sync triggers.
1319389267488	Sync.Status	DEBUG	Status.login: success.login => error.login.reason.no_recoverykey
1319389267488	Sync.Status	DEBUG	Status.service: success.status_ok => service.client_not_configured
1319571667313 Sync.Status DEBUG Status.service: error.sync.failed => success.status_ok
1319571656930 Sync.Status DEBUG Status.service: success.status_ok => success.status_ok
1319129937072 Sync.Status DEBUG Status.service: service.client_not_configured => service.client_not_configured
1319129937071 Sync.Status DEBUG Status.login: error.login.reason.no_recoverykey => error.login.reason.no_recoverykey
1319129937072 Sync.Status DEBUG Status.service: service.client_not_configured => service.client_not_configured
Whiteboard: [fixed in services] → [verified in services]
https://hg.mozilla.org/mozilla-central/rev/47950c8ae523
Status: ASSIGNED → RESOLVED
Closed: 8 years ago
Resolution: --- → FIXED
Target Milestone: --- → mozilla10
Component: Firefox Sync: Backend → Sync
Product: Cloud Services → Firefox
You need to log in before you can comment on or make changes to this bug.