662247 - log4moz: replace sync file I/O appenders with async ones

Status: RESOLVED FIXED

(Cloud Services :: Firefox: Common, defect)

Description

[Philipp von Weitershausen [:philikon]]

Maybe if we get rid of all sync file I/O sdwilsh will come back?

Comment 1

[Allison Naaktgeboren :ally]

I miss my old mentors, sdwilsh & philikon. Maybe if I get rid of the sync sync file i/o, they'll both come back!

Comment 2

[Chris Manchester (limited bugmail, email directly)]

Attachment: Replace synchronous file appenders with async appenders using OS.File

This patch maintains the existing API and behavior to a large degree. Still looking into the implications this may have for marionette, the only in-tree client of the BlockingFileAppender as far as I can see.

Comment 3

[Gregory Szorc [:gps]]

Let's see how Try reactions:

https://tbpl.mozilla.org/?tree=Try&rev=76781e99b502

Comment 4

[Gregory Szorc [:gps]]

Comment on attachment 763041 [details] [diff] [review]
Replace synchronous file appenders with async appenders using OS.File

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

Looking good. I dozed off towards the end of the test change. But, I think I gave you enough to incorporate into the next revision.

::: services/common/log4moz.js
@@ +339,5 @@
>    format: function BF_format(message) {
> +    return message.time + "\t" + 
> +      message.loggerName + "\t" + 
> +      message.counter + "\t" +
> +      message.levelDesc + "\t" + 

Nit: trailing whitespace

@@ +476,3 @@
>    },
>  
> +  doAppend: function doAppend(message) {

Nit: You don't need to name functions that are values in an object or are assigned to variables. You only need to name functions if you are declaring an "anonymous" function. And, you technically don't need to name them. But the names do help with stack traces, etc.

@@ +504,5 @@
> +  this._name = "FileAppender";
> +  this._encoder = new TextEncoder();
> +  this._path = path;
> +  this._file = null;
> +  // used internally to ensure file ready prior to writes

Nit: All comments should start with a capital letter and end with a period. They should be sentences, if possible. This helps non-English speakers translate the comments.

@@ +507,5 @@
> +  this._file = null;
> +  // used internally to ensure file ready prior to writes
> +  this._fileReady = null;
> +  // promise exposed for testing/debugging the logger itself
> +  this.lastWrite = null;

If it's a promise, can you name it lastWritePromise or similar?

@@ +520,5 @@
> +    let deferred = Promise.defer();
> +    if (this._file) {
> +      deferred.resolve(this._file);
> +      return deferred.promise;
> +    } 

You can write this as:

if (this._file) {
  return Promise.resolved(this._file);
}

@@ +522,5 @@
> +      deferred.resolve(this._file);
> +      return deferred.promise;
> +    } 
> +
> +    if (this._fileReady !== null) {

You can probably just write |if (this._fileReady) {|. Unless the variable can assume multiple truthy values, a simple boolean check is often best.

@@ +567,5 @@
> +       let that = this;
> +       this.lastWrite = Task.spawn(function () {
> +         yield that.lastWrite;
> +         yield that.registerWrite(message);
> +       });

We tend to use .bind(this) instead of aliasing "this" to another variable. e.g.

this.lastWrite = Tawk.spawn(function write() {
  yield this.lastWrite;
  yield this.registerWrite(message);
}.bind(this));

@@ +570,5 @@
> +         yield that.registerWrite(message);
> +       });
> +     } else {
> +       this.lastWrite = this.registerWrite(message);
> +     }

So, uh, does this actually work? I guess it must.

The "this.lastWrite = Task.spawn()" + "yield this.lastWrite" is bothering me. I know what you are trying to do: obtain the last write promise and chain onto that. However, the way it is implemented scares me. It seems like we could easily find ourselves in deadlock because a promise cannot wait on itself.

Instead of using tasks everywhere, I'd just call .then() on the promise. When you call .then(), the function specified is chained onto the existing promise and a new promise is returned. This is what you are doing, sure. But, logging is performance sensitive and I'd rather we avoid the overhead of Task.jsm.

@@ +578,5 @@
> +     this.counter = 0;
> +     return this._file.close().then(_ => {
> +       this._file = null;
> +       this._fileReady = null;
> +       OS.File.remove(this._path);

The fact the return from OS.File.remove isn't captured tells me we likely don't have test coverage of this!

@@ +595,5 @@
> +   }
> +
> +   if (maxBackups === undefined) {
> +     maxBackups = 0;
> +   }

Did you know JavaScript can have default argument values?

function RotatingFileAppender(file, formatter, maxSize=ONE_MEGABYTE * 2, maxBackups=0) {

@@ +611,5 @@
> +     let that = this;
> +
> +     return Task.spawn(function () {
> +       yield that.lastWrite;
> +       if (that._file) {

Any time you have a large block like this that is the only large block indented in a function, I tend to favor inverting the conditional and doing an early return. This tends to reduce indentation and makes code easier to read.

@@ +619,5 @@
> +             let oldName = that._path +  "." + i;
> +             let b = yield OS.File.exists(oldName);
> +             if (b) {
> +               yield OS.File.copy(oldName, that._path +  "." + (i + 1)); 
> +               yield OS.File.remove(oldName);

*sigh*. I know this is emulating the old behavior, but as we discussed IRL, that behavior is total crap. If nothing else, you should perform a move/rename instead of copy + remove. Filesystems can rename a file very quickly, often just by updating directory entries. However, a copy does all of thus plus it has to read and write all the bytes in the source file (unless you are on a modern filesystem like ZFS). This can suck performance like no other.

::: services/common/tests/unit/test_log4moz.js
@@ +137,5 @@
> +  
> +  // Reset the appender and log some more.
> +  yield appender.reset();
> +  fExists = yield OS.File.exists(path);
> +  do_check_false(fExists);

do_check_false(yield OS.File.exists(path));

Comment 5

[Chris Manchester (limited bugmail, email directly)]

Attachment: Replace synchronous file appenders with async appenders using OS.File

This patch addresses feedback as well as a few other changes. Try run had consistent failures on windows. It looks like the very first test wasn't able to find the file associated with the logger. I suspect that the way I was exposing a promise associated with the last write to the file was susceptible to a bad interleaving that didn't manifest of filesystems other than windows.

Comment 6

[Gregory Szorc [:gps]]

Comment on attachment 763612 [details] [diff] [review]
Replace synchronous file appenders with async appenders using OS.File

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

::: services/common/log4moz.js
@@ +224,1 @@
>        let appender = appenders[i];

While you are here, you can rewrite this as:

for (let appender of appenders) {

@@ +336,5 @@
>  
>    format: function BF_format(message) {
> +    return message.time + "\t" +
> +      message.loggerName + "\t" +
> +      message.counter + "\t" +

I don't think the counter needs to be added. Does it provide any benefit? It certainly has a drawback: it's backwards incompatible and may break existing parsers.

@@ +509,3 @@
>  
> +  // This is a promise exposed for testing/debugging the logger itself.
> +  this.lastWritePromise = null;

this._lastWritePromise since it's not a public API.

@@ +516,5 @@
> +FileAppender.prototype = {
> +  __proto__: Appender.prototype,
> +
> +  _getFile: function() {
> +    if (this._file !== null) {

if (this._file) {

@@ +532,5 @@
> +      // After initialization, registering a new write should not spawn
> +      // a new task.
> +      return Promise.resolve(this._encoder.encode(message)).then(array => {
> +        return this._file.write(array);
> +      });

You shouldn't need the initial Promise.resolve here. You should be able to write this as:

return this._file.write(this._encoder.encode(message));

@@ +567,1 @@
>      }

I asked Yoric about OS.File semantics and he says that there is a single I/O thread and therefore I/O operations operate as a FIFO queue. If we were to ever change this, there would be a new API for overlapped I/O.

Therefore, all this fancy fake queue management via promises is not necessary! You should be able to rewrite the file available branch as:

this._lastWritePromise = f.write(this._encoder.encode(message));

Comment 7

[Chris Manchester (limited bugmail, email directly)]

Attachment: Replace synchronous file appenders with async appenders using OS.File

This patch abandons the existing RotatingFileAppender for an appender concerned only with limiting the overall size of a log file. 

A counter (or some way to identifier and order messages withing a log) came up in the notes for a new log message format, but this isn't the place to add that.

Comment 8

[Gregory Szorc [:gps]]

Comment on attachment 764225 [details] [diff] [review]
Replace synchronous file appenders with async appenders using OS.File

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

I love the tests!

::: services/common/log4moz.js
@@ +556,5 @@
> + * Bounded File appender
> + *
> + * Writes output to file using OS.File. After the total message size exceeds
> + * maxSize, existing messages will be discarded, and subsequent writes will
> + * be appended to a new log file.

Document what unit maxSize is in (bytes).

::: services/common/tests/unit/test_log4moz.js
@@ +177,5 @@
> +
> +  logger.info("THREE");
> +  logger.info("FOUR");
> +
> +  yield appender._removeFilePromise;

You probably want to assert this promise is defined before waiting on it!

Comment 9

[Gregory Szorc [:gps]]

Oh, try at https://tbpl.mozilla.org/?tree=Try&rev=7c95fe19904f

Comment 10

[Chris Manchester (limited bugmail, email directly)]

Attachment: Replace synchronous file appenders with async appenders using OS.File

Testing on windows locally fixes the errors seen in the last two try runs. The error check was off (file not found and directory not found are discrete errors on windows), and attempts to remove/truncate files without closing appeared to create access violation errors.

Comment 11

[Gregory Szorc [:gps]]

Comment on attachment 764541 [details] [diff] [review]
Replace synchronous file appenders with async appenders using OS.File

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

I'd like to see the final patch before I grant r+.

::: services/common/log4moz.js
@@ +512,3 @@
>  
> +  _openFile: function () {
> +    return Task.spawn(function () {

Nit: Name this function.

@@ +514,5 @@
> +    return Task.spawn(function () {
> +      try {
> +        let f = yield OS.File.open(this._path,
> +                                   {truncate: true},
> +                                   {});

You can leave out the 3rd argument if it's empty.

@@ +515,5 @@
> +      try {
> +        let f = yield OS.File.open(this._path,
> +                                   {truncate: true},
> +                                   {});
> +        this._file = f;

I'd just write this as this._file = yield OS.File.open(...

@@ +585,5 @@
> +    if (!this._removeFilePromise) {
> +      if (this._size < this._maxSize) {
> +        this._size += message.length;
> +        FileAppender.prototype.doAppend.call(this, message);
> +        return;

return FileAppender.prototype.doAppend...

@@ +600,5 @@
> +    let fileClosePromise;
> +    if (this._fileReadyPromise) {
> +      // An attempt to open the file may still be in progress.
> +      fileClosePromise = this._fileReadyPromise.then(_ => {
> +        this._file.close();

Don't you need to return the promise so it is chained properly?

@@ +615,4 @@
>    }
>  };
> +
> +

Nit: extra lines at end of file?

::: services/common/tests/unit/test_log4moz.js
@@ +162,5 @@
> +add_task(function test_BoundedFileAppender() {
> +  let dir = OS.Path.join(do_get_profile().path, "test_log4moz");
> +  let path = OS.Path.join(dir, "test_BoundedFileAppender");
> +  // This appender will hold about two lines at a time.
> +  let appender = new Log4Moz.BoundedFileAppender(path, testFormatter, 40);

You ideally want to check the boundary condition here. But, I'm not too concerned about it and won't hold you to it.

Comment 12

[Chris Manchester (limited bugmail, email directly)]

Attachment: Replace synchronous appenders with async appenders using OS.File;

Comment 13

[Gregory Szorc [:gps]]

Comment on attachment 765581 [details] [diff] [review]
Replace synchronous appenders with async appenders using OS.File;

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

\o/

::: services/common/log4moz.js
@@ +515,5 @@
> +        this._file = yield OS.File.open(this._path,
> +                                        {truncate: true});
> +      } catch (err) {
> +        if (err instanceof OS.File.Error) {
> +          this._file = null;

Just so it's documented somewhere, this could result in an infinite loop of open attempts. Long term, I think we should explore moving this into appender init. Have a function return a promise that resolves to an initialized appender. If the appender can't be initialized (e.g. the file can't be opened), reject the promise. Infinite attempts avoided. Since not many people use FileAppender, I'm not too worried atm.

Comment 14

[Gregory Szorc [:gps]]

Inbound was closed, so:

https://hg.mozilla.org/integration/fx-team/rev/2b9573964077

Comment 15

[Tim Taubert [:ttaubert] (inactive)]

https://hg.mozilla.org/mozilla-central/rev/2b9573964077