We should dump the in-memory to disk when sync fails and delete it otherwise. This way users can still get logs when things fail, without having set a pref beforehand. We can then also get rid of the log rotation.

Here's a WIP patch I salvaged from my instrumentation changes and cleaned up a little bit. It's lacking any sort of testing (manual + automated). I would also like to add pref observers for all logging prefs so that we no longer require restarts when these prefs change. Furthermore, the plan is to turn about:sync-log into a page that looks a bit like about:crashes, displaying a list of log files dumped by Sync (sorted by date presumably).

Would like to use FileUtils here, but not until it opens streams with DEFER_OPEN (bug 644680), so depending on that.

Part 1: Add StorageStreamAppender to log4moz.js and refactor the existing stream-based appenders a bit. I started thinking about generic async stream appenders, but that got pretty hairy. Sync will only use the in-memory StorageStreamAppender anyway and then write the resulting data to disk asynchronously (see part 2).

Part 2 (v1): Dump log to disk on failure and optionally on success, too. Using the same directory as before, each sync failure (and/or success) will now create a separate log file (<timestamp>.log). This is written asynchronously. about:sync-log is now mapped to the directory, so users will simply see a list of files there. Files are generally listed in alphabetical, thus chronological order, so the last log file will be the last sync failure (or success). I'm not addressing clean up for those log files. By default we only log on errors anyway, and it's not much data we're accumulating. We could address this in a follow-up. I'm also not implementing a new UI for about:sync-log. I think we should eventually do something here a la about:crashes to replace the crude filesystem view. I would like to do that in a follow-up too.

Comment on attachment 538292 [details] [diff] [review] Part 1 (v1): Add StorageStreamAppender to log4moz.js Review of attachment 538292 [details] [diff] [review]: ----------------------------------------------------------------- Gonna r- this for now, because there are quite a few comments to which I'd like a response. Still, hooray for improved logging code! ::: services/sync/modules/log4moz.js @@ +105,5 @@ > get Appender() { return Appender; }, > get DumpAppender() { return DumpAppender; }, > get ConsoleAppender() { return ConsoleAppender; }, > + get StreamAppender() { return StreamAppender; }, > + get StorageStreamAppender() { return StorageStreamAppender; }, Oh, Java, how you have polluted our minds. Any particular reason not to bring this up to modern JS versions: get Appender() Appender, , or use direct attributes instead: Appender: Appender, ? @@ +107,5 @@ > get ConsoleAppender() { return ConsoleAppender; }, > + get StreamAppender() { return StreamAppender; }, > + get StorageStreamAppender() { return StorageStreamAppender; }, > + > + // Deprecated Micro-nit: missing full-stop :) @@ -422,5 @@ > */ > > function ConsoleAppender(formatter) { > this._name = "ConsoleAppender"; > - this._formatter = formatter; Wow, glad you're touching these busted lines! @@ +451,5 @@ > > +/** > + * Base implementation for stream based appenders. > + * > + * Caution: This writes to the output stream synchronously! I'd like to see this comment (and maybe the class!) expanded. Firstly, the comment doesn't really provide any advice or alternatives to go with the warning: "use AsyncStreamAppender instead", or "implement your own buffered logging", for example. If there is no alternative, then "caution" isn't that helpful. Secondly, you're relying on people reading the comment to know that it blocks! I might be tempted to call this BlockingStreamAppender, or something like that, and (now or later) implement (NonBlocking)StreamAppender. Thirdly, what's the precise definition of "synchronously" here? I can think of three characteristics that I'd want to know about before using this: 1. All the work that the JS function does takes place before it returns, and 2. All of the file IO that the work entails is done before the function returns, and 3. All of the work that the filesystem does to achieve durability is done before the function returns. I'm guessing you mean 1 and 2, not 3, but it would help to clarify in the comment; for some purposes, 3 is desirable, and for some it's not (fsync is expensive). If the definition of "synchronously" depends on the subclass's choice of output stream, then say that. @@ +463,5 @@ > + > + _outputStream: null, > + get outputStream() { > + if (!this._outputStream) { > + let rawStream = this.newOutputStream(); It's possible for newOutputStream() to return null (e.g., in the FileAppender implementation). You should probably check here, rather than continuing. @@ +474,5 @@ > + return this._outputStream; > + }, > + > + newOutputStream: function newOutputStream() { > + throw "Not implemented."; Perhaps "newOutputStream must be overridden in subclass."? @@ -441,0 +452,39 @@ > > +/** > > + * Base implementation for stream based appenders. > > + * > > + * Caution: This writes to the output stream synchronously! NaN more ... This guard will pass through undefined, which is probably not what you want. @@ +598,2 @@ > > for (let i = this.maxBackups - 1; i > 0; i--){ Nit: space between ) and {. @@ +598,5 @@ > > for (let i = this.maxBackups - 1; i > 0; i--){ > let backup = this._file.parent.clone(); > backup.append(this._file.leafName + "." + i); > if (backup.exists()) {}. ::: services/sync/tests/unit/test_log4moz.js @@ +64,5 @@ > + > + run_next_test(); > +}); > + > +add_test(function test_StorageStreamAppender() { I'd like to see a minimal test for what happens when creating one of the components (e.g., opening a file for the file appender) fails...

Comment on attachment 538294 [details] [diff] [review] Part 2 (v1): Dump log to disk on failure Review of attachment 538294 [details] [diff] [review]: ----------------------------------------------------------------- Looks good, modulo comments. Clearing review flag, though. ::: services/sync/Weave.js @@ +87,5 @@ > }, > > newChannel: function(aURI) { > + let dir = FileUtils.getDir("ProfD", ["weave", "logs"], true); > + let ch = Services.io.newChannel(ios.newFileURI(file).spec, null, null); Err, this doesn't make sense. file hasn't been defined at this point, unless I'm going crazy. Are you missing a line? ::: services/sync/modules/service.js @@ +456,5 @@ > + Svc.Prefs.set("services.sync.log.appender.file.level", logLevel); > + } > + if (Svc.Prefs.get("log.appender.debugLog.enabled")) { > + Svc.Prefs.set("services.sync.log.appender.file.logOnSuccess"); > + } \o/ @@ +497,5 @@ > dapp.level = Log4Moz.Level[Svc.Prefs.get("log.appender.dump")]; > root.addAppender(dapp); > > + let fapp = this._logAppender = new Log4Moz.StorageStreamAppender(formatter); > + fapp.level = Log4Moz.Level[Svc.Prefs.get("log.appender.file.level")]; WARNING! We've reached Fapp Level CRITICAL! @@ +503,3 @@ > }, > > + _clearFileLog: function clearFileLog(flushToFile) { Would "resetFileLog" be a better name here? "Clear" has connotations of clearing files, and the verb for the appender is "reset". @@ +507,5 @@ > + this._logAppender.reset(); > + if (flushToFile) { > + let filename = Date.now() + ".log"; > + let file = FileUtils.getFile("ProfD", ["weave", "logs", filename]); > + let outStream = FileUtils.openFileOutputStream(file); What happens if these operations fail? As far as I can see, a thrown exception will just shoot right up the stack, which probably isn't ideal... ::: services/sync/tests/unit/test_service_filelog.js @@ +36,5 @@ > + > + Svc.Obs.add("weave:service:cleared-file-log", function onClearedFileLog() { > + Svc.Obs.remove("weave:service:cleared-file-log", onClearedFileLog); > + > + // Exactly one log file was written. Can you check that "this WILL show up" has been written to the file, please? This test won't catch regressions in actually writing to the stream! @@ +96,5 @@ > + try { > + logfile.remove(false); > + } catch(ex) { > + dump("Couldn't delete file: " + ex + "\n"); > + // Stupid Windows box. :D

(In reply to comment #4) > I'm not addressing clean up for those log files. By default we only log on > errors anyway, and it's not much data we're accumulating. We could address > this in a follow-up. Fine by me. > I'm also not implementing a new UI for about:sync-log. I think we should > eventually do something here a la about:crashes to replace the crude > filesystem view. I would like to do that in a follow-up too. Also fine by me. I will file both of these.

(In reply to comment #7) > Also fine by me. I will file both of these. Filed Bug 663181, Bug 663182.

One other thing comes to mind: it would be nice if initTestLogging set things up in such a way that it still logged during test runs...

(In reply to comment #5) > Any particular reason not to bring this up to modern JS versions: > > get Appender() Appender, > > , or use direct attributes instead: > > Appender: Appender, Oh my, log4moz needs some serious JS style unfucking. Mossop provided some great API feedback in bug 451283 already... which got greatly ignored. My plan is to address that soon. > > +/** > > + * Base implementation for stream based appenders. > > + * > > + * Caution: This writes to the output stream synchronously! > > I'd like to see this comment (and maybe the class!) expanded. > > Firstly, the comment doesn't really provide any advice or alternatives to go > with the warning: "use AsyncStreamAppender instead", or "implement your own > buffered logging", for example. If there is no alternative, then "caution" > isn't that helpful. Disagree. Caution is helpful because it makes people aware. If I said "don't use this", *that* would be helpful. > Secondly, you're relying on people reading the comment to know that it > blocks! I might be tempted to call this BlockingStreamAppender, or something > like that, and (now or later) implement (NonBlocking)StreamAppender. Yup, BlockingStreamAppender seems like a good name for that base class. > Thirdly, what's the precise definition of "synchronously" here? I can think > of three characteristics that I'd want to know about before using this: > > 1. All the work that the JS function does takes place before it returns, and > 2. All of the file IO that the work entails is done before the function > returns, and > 3. All of the work that the filesystem does to achieve durability is done > before the function returns. > > I'm guessing you mean 1 and 2, not 3, Correct. > but it would help to clarify in the > comment; for some purposes, 3 is desirable, and for some it's not (fsync is > expensive). That's why I'm using a regular nsIOutputStream and not an nsISafeOutputStream. The latter ensures fsyncs. > If the definition of "synchronously" depends on the subclass's > choice of output stream, then say that. Fair enough. > @@ -441,0 +452,39 @@ > > > +/** > > > + * Base implementation for stream based appenders. > > > + * > > > + * Caution: This writes to the output stream synchronously! > NaN more ... > > This guard will pass through undefined, which is probably not what you want. Sorry, it seems like you meant to attach this comment to a different line? Will address all the other comments. Thanks for the thorough review!

> > + _clearFileLog: function clearFileLog(flushToFile) { > > Would "resetFileLog" be a better name here? "Clear" has connotations of > clearing files, and the verb for the appender is "reset". Yes, good point. > @@ +507,5 @@ > > + this._logAppender.reset(); > > + if (flushToFile) { > > + let filename = Date.now() + ".log"; > > + let file = FileUtils.getFile("ProfD", ["weave", "logs", filename]); > > + let outStream = FileUtils.openFileOutputStream(file); > > What happens if these operations fail? As far as I can see, a thrown > exception will just shoot right up the stack, which probably isn't ideal... It will shoot up the stack to the observer which means nothing will actually be hindered since nsIObserverService catches exceptions thrown by observers. But yeah, you're right, we should make this function bullet proof. Logging failures shouldn't throw anywhere.

> > > > + * Caution: This writes to the output stream synchronously! > > NaN more ... > > > > This guard will pass through undefined, which is probably not what you want. > > Sorry, it seems like you meant to attach this comment to a different line? Splinter fail! I particularly love the "NaN more". This is the right part: + doAppend: function doAppend(message) { + if (message === null || message.length <= 0) { + return; + } message = undefined will skip through that guard. > Will address all the other comments. Thanks for the thorough review! Of course!

Addressed rnewman's review comments.

Addressed rnewman's review comment.

Forgot to qref... This now also fixes about:sync-log.

Actually, about:sync-log wasn't quit working yet, splitting that out to Part 3 (so this is like v2.1, just without the about:sync-log changes.)

This makes about:sync-log a directory listing for $ProfD/weave/logs. The tricky bit is getting the security principal right so that the page doesn't render with about: but file: privileges. Otherwise one wouldn't be able to actually open a file from the listing.

Comment on attachment 538544 [details] [diff] [review] Part 3 (v1): about:sync-log Roping in mconnor for an additional review on the security bits.

Comment on attachment 538516 [details] [diff] [review] Part 0 (v1): Get rid of useless getters Review of attachment 538516 [details] [diff] [review]: -----------------------------------------------------------------

Comment on attachment 538517 [details] [diff] [review] Part 1 (v2): Add StorageStreamAppender to log4moz.js Review of attachment 538517 [details] [diff] [review]: ----------------------------------------------------------------- \o/ ::: services/sync/tests/unit/test_log4moz.js @@ +120,5 @@ > + let logger = Log4Moz.repository.getLogger("test.FileAppender"); > + logger.addAppender(appender); > + logger.info("OHAI"); > + > + // The file will be written Once the directory leading up to the file exists. Nit: s/Once/once.

Comment on attachment 538543 [details] [diff] [review] Part 2 (v2.2): Dump log to disk on failure Review of attachment 538543 [details] [diff] [review]: -----------------------------------------------------------------

Comment on attachment 538544 [details] [diff] [review] Part 3 (v1): about:sync-log Review of attachment 538544 [details] [diff] [review]: ----------------------------------------------------------------- This looks OK to me.

http://hg.mozilla.org/services/services-central/rev/22e6300188a7 http://hg.mozilla.org/services/services-central/rev/8c12fe7c8eaf http://hg.mozilla.org/services/services-central/rev/cc5b24792910 http://hg.mozilla.org/services/services-central/rev/ef04efcc4fb3

STRs for QA: * about:sync-log is now a directory listing for $profile/weave/logs * Upon a sync error, a log file will be dumped to that directory. This can be turned off by setting 'services.sync.log.appender.file.logOnError' to false (is true by default). * Optionally, every successful sync can cause a log to be written, if the 'services.sync.log.appender.file.logOnSuccess' pref is set to true (false by default). * The various services.sync.log.appender.debugLog.* preferences are now defunct. They don't exist as default prefs anymore. * If 'services.sync.log.appender.debugLog.enabled' was previously set to true, 'services.sync.log.appender.file.logOnSuccess' is set to true. The value for 'services.sync.log.appender.debugLog' is migrated to 'services.sync.log.appender.file.level'

new logging verified with latest s-c builds

http://hg.mozilla.org/mozilla-central/rev/22e6300188a7 http://hg.mozilla.org/mozilla-central/rev/8c12fe7c8eaf http://hg.mozilla.org/mozilla-central/rev/cc5b24792910 http://hg.mozilla.org/mozilla-central/rev/ef04efcc4fb3

Verified fix on Trunk Nightly. Mozilla/5.0 (Macintosh; Intel Mac OS X 10.6; rv:7.0a1) Gecko/20110617 Firefox/7.0a1