1148980 - Sync and ReadingList logs should write error logs whenever an error is logged.

Status: RESOLVED FIXED

(Firefox :: Sync, defect)

Description

[Mark Hammond [:markh] [:mhammond]]

Currently we write an "error" log only when Sync fails. However, there are other situations where an error has been found, but it is handled (well, ignored in the hope other things can still succeed), causing Sync to "partially fail" but still complete. Having error logs for these cases would probably help diagnosis of subtle errors.

I propose that if any of the logs have a Log.Level.ERROR record written we should create an error log.  We'd also ensure that if Sync failed we'd write an explicit error entry to guarantee a failure causes an error log.

The worst-case is that this would cause error-* files to be written where they currently are not - but users are unlikely to notice this unless they go to about:sync-logs

The above also applies to readinglist as it uses the same "log manager" as sync.

Richard, what do you think?

Comment 1

[Richard Newman [:rnewman]]

Seems like a good idea to me.

Comment 2

[Mark Hammond [:markh] [:mhammond]]

Attachment: 0004-Bug-1148980-have-success-and-error-log-files-for-Syn.patch

This patch still allows callers to specify if they want "success" or "error" handling, but if not specified it defaults to whether there is an Error entry written. Note that Sync still specified .REASON_ERROR in cases where it has observed an error notification, but uses null otherwise.

Comment 3

[Mark Hammond [:markh] [:mhammond]]

Attachment: 0004-Bug-1148980-have-success-and-error-log-files-for-Syn.patch

From bug 1149023:

> 1427704765716    readinglist.sync    WARN    Failed to add a new item from server record {"archived":false,"marked_read_on":null,"favorite":true,"title":"1078653 -

I think those .warn() logs I added recently are a great example for why this bug exists - but obviously they need to be .error() calls instead ;)

Same as before but adjusting Sync.jsm's .warn to .error

Comment 4

[Mark Hammond [:markh] [:mhammond]]

Comment on attachment 8585372 [details] [diff] [review]
0004-Bug-1148980-have-success-and-error-log-files-for-Syn.patch

Review of attachment 8585372 [details] [diff] [review]:
-----------------------------------------------------------------

::: browser/components/readinglist/Sync.jsm
@@ +383,5 @@
>        let localRecord = localRecordFromServerRecord(serverRecord);
>        try {
>          yield this.list.addItem(localRecord);
>        } catch (ex) {
> +        log.error("Failed to add a new item from server record ${serverRecord}: ${ex}",

(that is, assuming I've fixed the indentation in this file ;)

Comment 5

[Richard Newman [:rnewman]]

Comment on attachment 8585372 [details] [diff] [review]
0004-Bug-1148980-have-success-and-error-log-files-for-Syn.patch

Review of attachment 8585372 [details] [diff] [review]:
-----------------------------------------------------------------

::: services/common/logmanager.js
@@ +45,5 @@
>  // A set of all preference roots used by all instances.
>  let allBranches = new Set();
>  
> +// An appender object that exists only to know when an ERROR record was
> +// written to our logs.

I see why you're doing this -- the file appender class is inside Log.jsm, and doesn't know anything about the flushing policy in this file, so this is an easy way to inject a watcher into the stream.

But it's probably not quite right, no? Each appender can have its own log levels, and it's kinda weird to introduce a fake appender.

So why not simply define a subclass of StorageStreamAppender in this file, then later do

  if (this._fileAppender.sawError)

?

Going even further, I kinda feel like moving most of resetFileLog into a method on that, our own LogManagedStorageAppender, would be clearer. rFL already 'owns' the innards of the file appender (getInputStream, reset), and also constructs it in the first place, so there's already a kind of delegation relationship here.

Comment 6

[Mark Hammond [:markh] [:mhammond]]

Attachment: 0004-Bug-1148980-have-success-and-error-log-files-for-Syn.patch

(In reply to Richard Newman [:rnewman] from comment #5)
> Going even further, I kinda feel like moving most of resetFileLog into a
> method on that, our own LogManagedStorageAppender, would be clearer. rFL
> already 'owns' the innards of the file appender (getInputStream, reset), and
> also constructs it in the first place, so there's already a kind of
> delegation relationship here.

I didn't go quite that far, as the LogManager (IMO) owns the policies such as when to flush, what directory/filename to flush to, when to rotate and what preferences control this.

So this patch uses a FlushableStorageAppender which still maintains a .sawError property and has a method flushToFile() which takes a filename.  The decision about when to call this and what filename to use remains in the log manager, but the actual mechanics used are in the appender.

Comment 7

[Richard Newman [:rnewman]]

Comment on attachment 8585832 [details] [diff] [review]
0004-Bug-1148980-have-success-and-error-log-files-for-Syn.patch

Review of attachment 8585832 [details] [diff] [review]:
-----------------------------------------------------------------

LGTM with the noted change. Feel free to consider this r+ if you've tested this on more than one platform.

::: browser/components/readinglist/Scheduler.jsm
@@ +316,5 @@
>        this.state = err.message == fxAccountsCommon.ERROR_AUTH_ERROR ?
>                     this.STATE_ERROR_AUTHENTICATION : this.STATE_ERROR_OTHER;
>        this.log.error("Sync failed, now in state '${state}': ${err}",
>                       {state: this.state, err});
> +      this._logManager.resetFileLog();

I think this should still be REASON_ERROR. Even if no errors were logged, we still want an error log to be created.

Comment 8

[Mark Hammond [:markh] [:mhammond]]

(In reply to Richard Newman [:rnewman] from comment #7)
> Comment on attachment 8585832 [details] [diff] [review]
> 0004-Bug-1148980-have-success-and-error-log-files-for-Syn.patch
> 
> Review of attachment 8585832 [details] [diff] [review]:
> -----------------------------------------------------------------
> 
> LGTM with the noted change. Feel free to consider this r+ if you've tested
> this on more than one platform.
> 
> ::: browser/components/readinglist/Scheduler.jsm
> @@ +316,5 @@
> >        this.state = err.message == fxAccountsCommon.ERROR_AUTH_ERROR ?
> >                     this.STATE_ERROR_AUTHENTICATION : this.STATE_ERROR_OTHER;
> >        this.log.error("Sync failed, now in state '${state}': ${err}",
> >                       {state: this.state, err});
> > +      this._logManager.resetFileLog();
> 
> I think this should still be REASON_ERROR. Even if no errors were logged, we
> still want an error log to be created.

But the line above is explicitly writing an error log!

Comment 9

[Mark Hammond [:markh] [:mhammond]]

Comment on attachment 8585832 [details] [diff] [review]
0004-Bug-1148980-have-success-and-error-log-files-for-Syn.patch

Review of attachment 8585832 [details] [diff] [review]:
-----------------------------------------------------------------

> I think this should still be REASON_ERROR. Even if no errors were logged, we still want an error log to be created.

Note that the line above this explicitly writes an error log.  So I'd actually prefer to go the other way here, eg:

::: services/sync/modules/policies.js
@@ +642,5 @@
>          }
>  
>          if (Status.service == SYNC_FAILED_PARTIAL) {
> +          this._log.error("Some engines did not sync correctly.");
> +          this.resetFileLog();

note that this line has the same basic effect - no "reason" is specified, but the .error() call guarantees such a log.

I wouldn't mind using the same pattern everywhere .resetFileLog() is called in this file, which would allow us to remove those REASON constants completely.  In short, I don't see a good reason to have the .error() semantics *and* force the behaviour with the REASON constants.

How would you feel about that instead?

Comment 10

[Richard Newman [:rnewman]]

Comment on attachment 8585832 [details] [diff] [review]
0004-Bug-1148980-have-success-and-error-log-files-for-Syn.patch

That would work for me! Guarantees no empty log files :)

Comment 11

[Mark Hammond [:markh] [:mhammond]]

Attachment: 0001-Bug-1148980-have-success-and-error-log-files-for-Syn.patch

This patch removes the REASON_* values and param completely. However, there are 2 different constants (SUCCESS_LOG_WRITTEN, ERROR_LOG_WRITTEN) which are now *returned* by resetFileLog() - that return value isn't used here, but is by the patch in bug 1148980.

Comment 12

[Mark Hammond [:markh] [:mhammond]]

(In reply to Mark Hammond [:markh] from comment #11)
> by the patch in bug 1148980.

oops - make that bug 1152116.

Comment 13

[Mark Hammond [:markh] [:mhammond]]

Comment on attachment 8603214 [details] [diff] [review]
0001-Bug-1148980-have-success-and-error-log-files-for-Syn.patch

Review of attachment 8603214 [details] [diff] [review]:
-----------------------------------------------------------------

::: services/sync/modules/policies.js
@@ +684,5 @@
>     * Generate a log file for the sync that just completed
>     * and refresh the input & output streams.
>     *
>     * @param reason
>     *        A constant from the LogManager that indicates the reason for the

doh! I've removed this @param comment locally.

Comment 14

[Richard Newman [:rnewman]]

Comment on attachment 8603214 [details] [diff] [review]
0001-Bug-1148980-have-success-and-error-log-files-for-Syn.patch

Review of attachment 8603214 [details] [diff] [review]:
-----------------------------------------------------------------

lgtm. You are on a quest to have blame on the entirety of services/common :)

::: services/common/logmanager.js
@@ +90,5 @@
> +
> +  /**
> +   * Copy an input stream to the named file, doing everything off the main
> +   * thread.
> +   * outputFile is an nsIFile, but is used only for the name.

Comment no longer matches the arglist.

@@ +103,5 @@
> +    let binaryStream = Cc["@mozilla.org/binaryinputstream;1"].createInstance(Ci.nsIBinaryInputStream);
> +    binaryStream.setInputStream(inputStream);
> +
> +    let profd = FileUtils.getDir("ProfD", []);
> +    let outputFile = FileUtils.getDir("ProfD", subdirArray);

Can you use OS.Path.join(OS.Constants.Path.profileDir, …) here?

Comment 15

[Pulsebot]

https://hg.mozilla.org/integration/fx-team/rev/4fd3b39a8058

Comment 16

[Wes Kocher (:KWierso) (Not reading bugmail; email directly if needed)]

https://hg.mozilla.org/mozilla-central/rev/4fd3b39a8058