694728 - Sync: Log Status transitions

Status: RESOLVED FIXED

(Firefox :: Sync, defect)

Description

[Richard Newman [:rnewman]]

It's amazing that the Sync Status object doesn't log its state transitions. Here we go!

Comment 1

[Richard Newman [:rnewman]]

Attachment: Proposed patch. v1

Had to fix a test, too.

Comment 2

[Richard Newman [:rnewman]]

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 3

[Philipp von Weitershausen [:philikon]]

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.

Comment 4

[Richard Newman [:rnewman]]

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

Comment 5

[Richard Newman [:rnewman]]

Attachment: Proposed patch. v2

Not combining into `reset`, as discussed on IRC.

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

Other comments addressed.

Comment 6

[Richard Newman [:rnewman]]

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.

Comment 7

[Mihaela Velimiroviciu (:mihaelav)]

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

Comment 8

[Richard Newman [:rnewman]]

https://hg.mozilla.org/mozilla-central/rev/47950c8ae523