616568 - Better log message when sync already in progress

Status: RESOLVED FIXED

(Firefox :: Sync, enhancement, P5)

Description

[Richard Newman [:rnewman]]

Particularly during an outage recovery, sync is slow. No log messages are arriving, but things are actually happening. If you try to force the issue with "Sync Now", you'll get this log message:

2010-12-03 12:26:47	Service.Main         DEBUG	Exception: Could not acquire lock No traceback available

It'd be nice to print something more helpful, like "could not acquire lock: sync already in progress?".

Comment 1

[Richard Newman [:rnewman]]

Attachment: Watch for the lock exception and log. v1

Here's a quick stab at this, with test.

Comment 2

[Philipp von Weitershausen [:philikon]]

Comment on attachment 497357 [details] [diff] [review]
Watch for the lock exception and log. v1

>+  // Call _lockedSync with a specialized variant of Utils.catch.

Where's that "specialized variant of Utils.catch"? Do you mean the try/catch block? :p This feels like a "Set x to 1" comment (=useless).

>+  // This provides a more informative error message when we're already syncing:
>+  // see Bug 616568.
>+  sync: function sync() {
>+    try {
>+      return this._lockedSync();
>+    } catch (ex) {
>+      this._log.debug("Exception: " + Utils.exceptionStr(ex));
>+      if (Utils.isLockException(ex)) {
>+        // This only happens if we're syncing already.
>+        this._log.info("Cannot start sync: already syncing?");
>+      }

Perhaps do

      if (Utils.isLockException(ex)) {
        // This only happens if we're syncing already.
        this._log.info("Cannot start sync: already syncing?");
      } else {
        this._log.debug("Exception: " + Utils.exceptionStr(ex));
      }

here?

Comment 3

[Richard Newman [:rnewman]]

(In reply to comment #2)

> Where's that "specialized variant of Utils.catch"? Do you mean the try/catch
> block? :p This feels like a "Set x to 1" comment (=useless).

I was leaving a breadcrumb trail back to the original code that spawned this -- it wasn't worth writing a separate Utils.lockedSyncCatch method, but I also didn't feel right just copy-and-changing that method.

> Perhaps do ...

I did that to start with, but changed it to always log the exception string. The lock exception carries with it an additional message, so I thought that logging it (at DEBUG) would be better than muffling.

Comment 4

[Richard Newman [:rnewman]]

Pushed:

http://hg.mozilla.org/services/fx-sync/rev/e9c8e429d84a

Comment 5

[Richard Newman [:rnewman]]

Apparently the test didn't make it. Pushed:

http://hg.mozilla.org/services/fx-sync/rev/15ec1ddd259b