Read/write chat logs asynchronously

RESOLVED FIXED in 1.6

Status

Chat Core
General
--
enhancement
RESOLVED FIXED
4 years ago
3 years ago

People

(Reporter: wnayes, Assigned: nhnt11)

Tracking

Dependency tree / graph

Firefox Tracking Flags

(Not tracked)

Details

Attachments

(7 attachments, 53 obsolete attachments)

10.53 KB, text/plain
Details
1.02 KB, application/x-javascript
Details
5.88 KB, text/plain
Details
10.21 KB, patch
nhnt11
: review+
Details | Diff | Splinter Review
16.89 KB, patch
nhnt11
: review+
Details | Diff | Splinter Review
50.09 KB, patch
florian
: review+
Details | Diff | Splinter Review
13.61 KB, patch
nhnt11
: review+
Details | Diff | Splinter Review
(Reporter)

Description

4 years ago
*** Original post on bio 1859 at 2012-12-20 17:40:00 UTC ***

Log messages are currently being written with synchronous streams from the logger. It could be an improvement to have these writes happen asynchronously.
(Reporter)

Comment 1

4 years ago
Created attachment 8353938 [details] [diff] [review]
A potential refactoring that could be useful.

*** Original post on bio 1859 as attmnt 2176 at 2012-12-20 17:42:00 UTC ***

This is a simple refactoring of the logger code to remove duplication of the log writing code from ConversationLog and SystemLog in logger.js - it could be committed standalone or be used as a basis for making the logger write asynchronously.
(Reporter)

Comment 2

4 years ago
Created attachment 8353939 [details] [diff] [review]
Attempt at asynchronous writes with NetUtil.asyncCopy

*** Original post on bio 1859 as attmnt 2177 at 2012-12-20 17:47:00 UTC ***

This is my attempt at making the logger write asynchronously. It uses the NetUtil.asyncCopy method to send the new message string to disk. A downside I see is that the stream needs to be repeatedly opened since asyncCopy closes the streams after completion. I am not sure whether that would significantly impact performance or not.

OS.File seems to be coming in later Mozilla releases, and could come in handy. There is also the String Encoding API that could replace the nsIScriptableUnicodeConverter.
Attachment #8353939 - Flags: review?(florian)
Comment on attachment 8353938 [details] [diff] [review]
A potential refactoring that could be useful.

*** Original change on bio 1859 attmnt 2176 at 2012-12-20 20:51:10 UTC ***

>   close: function cl_close() {
>     if (this._log) {
>-      this._log.close();
>-      this._log = null;
>-      this.file = null;
>+      this._logWriter.close();
>+      this._logWriter = null;
>     }
>   }

This won't work.
I don't think changing _log to _logWriter everywhere was a great idea (especially because it makes that kind of mistakes easy), but I won't ask you to revert all these changes now.

Looks good otherwise.
Attachment #8353938 - Flags: review-
Comment on attachment 8353939 [details] [diff] [review]
Attempt at asynchronous writes with NetUtil.asyncCopy

*** Original change on bio 1859 attmnt 2177 at 2012-12-20 21:09:14 UTC ***

I dislike that this closes the file after each message. It seems silly, especially if we are writing several messages to the log at once.

There seems to be an example of another solution in http://mxr.mozilla.org/comm-central/source/mozilla/dom/network/src/TCPSocket.js using nsIAsyncStreamCopier directly, with the help of nsIStringInputStream and nsIMultiplexInputStream.
Attachment #8353939 - Flags: review?(florian) → review-
(Assignee)

Comment 5

3 years ago
Created attachment 8426564 [details] [diff] [review]
WIP

Here's a WIP that uses OS.File to make things async.
This needs more comments and tests, but I will be doing those tomorrow and thought I'd upload whatever I have right now anyway.

I haven't tested the code at all. Stuff is likely broken, but the approach should be clear.
Assignee: nobody → nhnt11
Status: NEW → ASSIGNED
Attachment #8426564 - Flags: feedback?
(Assignee)

Comment 6

3 years ago
Created attachment 8426568 [details] [diff] [review]
WIP 2

Fixed a few obvious mistakes.
Attachment #8426564 - Attachment is obsolete: true
Attachment #8426564 - Flags: feedback?
Attachment #8426568 - Flags: feedback?

Comment 7

3 years ago
Comment on attachment 8426568 [details] [diff] [review]
WIP 2

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

Great progress :)

What's completely missing so far (understandably) is error handling. Note errors automatically get passed along a promise chain so it might be feasible to write an error handler that detects OS.File errors and just catch at the end of a task.

Please add some tests for this before adding too many further features from the todo list, so that we can ensure the refinements (like closing a log file on inactivity) don't break anything. I recommend you load logger.js into the scope of the test rather than trying to test it only "from the outside".

::: chat/components/src/logger.js
@@ +54,5 @@
> +  return Task.spawn(function* () {
> +    let path = OS.Path.join(logDir, aAccount.protocol.normalizedName,
> +                            encodeName(aAccount.normalizedName)
> +    if (aCreate)
> +      yield OS.File.makeDir(path, {ignoreExisting: true, from: logDir});

Nice simplification through "from"!

@@ +93,1 @@
>    _init: function cl_init() {

Can we call this _initNewLog for clarity? _init()s usually get called by constructors...

@@ +102,5 @@
> +      yield OS.File.makeDir(path, {ignoreExisting: true});
> +      if (Services.prefs.getCharPref("purple.logging.format") == "json")
> +        this.format = "json";
> +      path = OS.Path.join(path, getNewLogFileName(this.format, this._conv.startDate));
> +      this.path = path;

Please put all the preceding code into a getLogFileForConv function (or getLogPath or whatever, similar to getLogFolderForAccount).

@@ +159,5 @@
> +    return this._logMessagePromise = Task.spawn(function* () {
> +      if (prevPromise)
> +        yield prevPromise;
> +      return this.queuedLogMessage(aMessage);
> +    }.bind(this));

How about 

if (!this.logMessagePromise)
  this.logMessagePromise = this.initNewLog();
this.logMessagePromise = this.logMessagePromise.then(() => this.queuedLogMessage(aMessage));

(Afaik then() passes a promise returned by a handler through as its return value.)

@@ +163,5 @@
> +    }.bind(this));
> +  },
> +  // Returns a Promise that resolves to true when the write is complete.
> +  queuedLogMessage: function cl_queuedLogMessage(aMessage) {
> +    return Task.spawn(function* () {

No need for a Task here if the this.init call is in logMessage. Simply return the promise.

@@ +186,1 @@
>  

Let's make this easier to read by removing the return true in the preceding {..} and then continue with 
else {/* text log */ ...} (including a comment)

@@ +209,5 @@
>      if (this._log) {
> +      return this._log.close().then(function() {
> +        this._log = null;
> +        this.path = null;
> +      }.bind(this));

To avoid bind(this), you can use arrow functions like () => {this.blabla...}

@@ +245,5 @@
>    delete gConversationLogs[id];
>  }
>  
>  /* System logs stuff */
>  function SystemLog(aAccount)

I've not looked in detail at this yet as I assume it's similar to the log writing above.
Attachment #8426568 - Flags: feedback? → feedback+
(Assignee)

Comment 8

3 years ago
Created attachment 8428085 [details] [diff] [review]
WIP 3

I've addressed aleth's feedback and tested it on a live instance of Instantbird (on a new profile). The code is now working - my conversations are being logged and nothing seems to be broken. Error handling is still absent. I've written tests (included in the patch) but haven't been able to get them to run. This patch needs more polish, but I figured I would upload what I've got.
Attachment #8426568 - Attachment is obsolete: true
Attachment #8428085 - Flags: feedback?
(Assignee)

Comment 9

3 years ago
By the way, the reason logDirPath and getLogFolderPathForAccount are separate from logDir and getLogFolderForAccount respectively is because these functions are used for reading the logs, which hasn't been made async yet.

Comment 10

3 years ago
Comment on attachment 8428085 [details] [diff] [review]
WIP 3

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

Coming along nicely.

::: chat/components/src/logger.js
@@ +184,5 @@
> +      this._logMessagePromise = this._initNewLog();
> +    // Log the message after the current Promise resolves.
> +    // This happens immediately if it has already resolved.
> +    return this._logMessagePromise =
> +      this._logMessagePromise.then(() => this.queuedLogMessage(aMessage));

What's the return value for?

::: chat/components/src/test/test_logger.js
@@ +12,5 @@
> +Services.scriptloader.loadSubScript("resource:///components/logger.js", logger);
> +
> +XPCOMUtils.defineLazyGetter(this, "logDirPath", function()
> +  OS.Path.join(OS.Constants.Path.profileDir, "logs")
> +);

Doesn't this get loaded with logger.js?

@@ +122,5 @@
> +                                logger.encodeName(dummyAccount.normalizedName)), path);
> +      Assert.equal((yield OS.File.exists(path)), true);
> +    } catch (ex if ex instanceof OS.File.Error) {
> +      do_throw(ex);
> +    }

What's the logic of the catch here? We catch only to re-throw, is that needed? Or are we expecting errors here?
Attachment #8428085 - Flags: feedback? → feedback+
Comment on attachment 8428085 [details] [diff] [review]
WIP 3

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

Looks very promising. Looking forward to seeing the log reading part :-).

::: chat/components/src/logger.js
@@ +17,5 @@
>    return file;
>  });
>  
> +XPCOMUtils.defineLazyGetter(this, "logDirPath", function()
> +  OS.Path.join(OS.Constants.Path.profileDir, "logs")

I don't think this is expensive, and it seems only used in getLogFolderPathForAccount so I would suggest inlining it.

Also, OS.Constants.Path.profileDir is used there too, so you can save some duplication.

@@ +120,5 @@
>    this._conv = aConversation;
>  }
>  ConversationLog.prototype = {
>    _log: null,
> +  path: null,

What is this used for?

@@ +125,4 @@
>    format: "txt",
> +  encoder: new TextEncoder(),
> +  _initNewLog: function cl_initNewLog() {
> +    return Task.spawn(function* () {

Is there a reason why this isn't done in the constructor, with this._logMessagePromise = Task.spawn... ?

@@ +129,5 @@
> +      if (this._logMessagePromise)
> +        return;
> +      if (Services.prefs.getCharPref("purple.logging.format") == "json")
> +        this.format = "json";
> +      this.path = yield getLogFilePathForConversation(this._conv, this.format, true);

Are we in trouble if the conversation is closed before we are done creating the account folder asynchronously?

@@ +175,5 @@
>      }});
>      return encoder.encodeToString();
>    },
> +  // Will be either the Promise for an ongoing write operation, or true if
> +  // at least one message has been logged (i.e. _initNewLog has been called).

I don't see anything setting this to true.

@@ +205,3 @@
>      }
>  
> +    // Text log.

I'm just so tempted to say it's time to get rid of text logging :-]. Do we think anybody would be rightfully upset if we scrapped that part of the code now?

@@ +225,4 @@
>    },
>  
>    close: function cl_close() {
>      if (this._log) {

Won't this be null if we are still in the process of opening the log file? I would expect the this._log.close() to be done after this._logMessagePromise resolves.

@@ +263,5 @@
>    gConversationLogs[id].close();
>    delete gConversationLogs[id];
>  }
>  
>  /* System logs stuff */

Note: I haven't really looked at this part, but I assume the logic is similar to what you did for conversation logs.

@@ +292,3 @@
>    logEvent: function sl_logEvent(aString) {
> +    // If the Promise doesn't exist yet, init a new log file.
> +    if (!this._logEventPromise)

How can it not exist when it's the first thing set in the constructor?
Attachment #8428085 - Flags: feedback+

Comment 12

3 years ago
(In reply to Florian Quèze [:florian] [:flo] from comment #11)
> > +    // Text log.
> 
> I'm just so tempted to say it's time to get rid of text logging :-]. Do we
> think anybody would be rightfully upset if we scrapped that part of the code
> now?

I'm tempted too, but while we have to support reading text logs, we may as well keep this writing code too.

When wnayes log importer lands, maybe we can auto-convert old text logs? That would be a great way to drop this code.
(Assignee)

Comment 13

3 years ago
Created attachment 8428898 [details] [diff] [review]
WIP 4

This makes log reading async as well. Note that consumers have not yet been modified to make use of the new API which returns Promises - this is untested code.
I'm working on updating consumers to work with this, and will upload a new patch after that's done and stuff is working.

Parts of this patch may be confusing (I was frequently confused while reading the existing code) and need more comments.
Attachment #8353938 - Attachment is obsolete: true
Attachment #8353939 - Attachment is obsolete: true
Attachment #8428085 - Attachment is obsolete: true
Attachment #8428898 - Flags: feedback?
(Assignee)

Comment 14

3 years ago
Created attachment 8428900 [details]
IRC conversation with Yoric about write strategy

This is a conversation I had with Yoric on #perf about the strategy I'm using to write the logs - i.e. keeping an OS.File instance open and using write() repeatedly to append messages to it.

Conclusion: The appending mechanism is acceptable within our limits of tolerance for losing messages (if the user has had time to see a message, it should get logged).
(Assignee)

Comment 15

3 years ago
Also, the current patch does not yet do proper error handling, and does not close open files after a period of inactivity.
Summary: Write log messages asynchronously → Read/write chat logs asynchronously
(Assignee)

Comment 16

3 years ago
Created attachment 8429188 [details] [diff] [review]
WIP 5

This patch updates the Instantbird log viewer to use the new API. I'm able to view my logs with no problems. There is a slight delay when viewing the log for a conversation with a large amount of log files, maybe we want a throbber?

Todo: Error handling, close file after arbitrary period of inactivity.
Attachment #8428898 - Attachment is obsolete: true
Attachment #8428898 - Flags: feedback?
Attachment #8429188 - Flags: feedback?

Comment 17

3 years ago
Comment on attachment 8429188 [details] [diff] [review]
WIP 5

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

First pass, I ran out of time ;)

::: chat/components/src/logger.js
@@ +9,5 @@
>  Cu.import("resource:///modules/imXPCOMUtils.jsm");
>  Cu.import("resource:///modules/jsProtoHelper.jsm");
> +Cu.import("resource://gre/modules/osfile.jsm");
> +Cu.import("resource://gre/modules/Task.jsm");
> +Cu.import("resource://gre/modules/Promise.jsm");

You shouldn't import Promise.jsm now promises are in ES6.

@@ +111,5 @@
>      aFormat = "txt";
>    return dateTime + twoDigits(offset) + twoDigits(minutes) + "." + aFormat;
>  }
>  
>  /* Conversation logs stuff */

Improve this comment a bit. Putting the log file creation in the constructor means this object is for writing new logs only, so why not call it ConversationLogWriter or something like that?

@@ +297,4 @@
>    }
>  };
>  
>  const dummySystemLog = {

Is this used? It's not compatible with the new code that returns promises e.g. in close().

@@ +380,5 @@
> +        if (!nextLine)
> +          break;
> +        try {
> +          messages.push(JSON.parse(nextLine));
> +        } catch (e) {

I think you want to keep the comment here which explains why we catch and do nothing.

@@ +428,5 @@
>      return enumerator;
>    }
>  };
>  
>  /* Generic log enumeration stuff */

Please improve all these comments while you are at it ;)

@@ -451,5 @@
> -      // If the file contains some junk (invalid JSON), the
> -      // LogConversation code will still read the messages it can parse.
> -      // If the first line of meta data is corrupt, there's really no
> -      // useful data we can extract from the file so the
> -      // LogConversation constructor will throw.

I don't like that you're dropping comments that actually already exist that explain the idea behind how we handle errors. Keep them and improve them ;)

@@ +587,2 @@
>  }
>  LogCluster.prototype = {

What do you think about getting rid of LogCluster and making Log handle both cases? Does anything speak against this? 

It would also allow inlining the shared createLogConversationFromFiles which seems to do most of the work.

::: chat/components/src/test/test_logger.js
@@ +101,5 @@
> +  "file%26",
> +  "file%25"
> +];
> +
> +function run_test() {

I guess you know this, but this needs some tests where a log is written and read ;)

::: im/content/conversation.xml
@@ +1569,5 @@
>                return item;
>              }
>              let showLogsItem = createMenuItem("contextShowLogs", function() conv.showLogs());
> +            showLogsItem.disabled = true;
> +            this.hasLogs().then((aHasLogs) => {

nit: you don't need the brackets around aHasLogs for a single argument

::: im/content/viewlog.js
@@ +73,5 @@
>  
>      let deck = document.getElementById("browserDeck");
>      let findbar = document.getElementById("findbar");
>      if (log.format == "json") {
> +      log.getConversation().then((aConv) => {

You said on IRC this call was the slow part. Do we have a noticeable lag here *every time* a different log is selected or only when first showing the log window? If the latter, why?
Attachment #8429188 - Flags: feedback? → feedback+
(Assignee)

Comment 18

3 years ago
Created attachment 8429574 [details] [diff] [review]
WIP 6

Adds error handling and better comments. Squashed various bugs. Some cleanup.

>::: im/content/viewlog.js
>@@ +73,5 @@
>  
>      let deck = document.getElementById("browserDeck");
>      let findbar = document.getElementById("findbar");
>      if (log.format == "json") {
> +      log.getConversation().then((aConv) => {
> 
>You said on IRC this call was the slow part. Do we have a noticeable lag here *every time* a different log is selected or only when first showing the log window? If the latter, why?

It's the former. Optimization is certainly possible (by returning messages in batches as they're read), but we'll save that for a follow up, shall we?

>@@ +587,2 @@
>  }
>  LogCluster.prototype = {
> 
>What do you think about getting rid of LogCluster and making Log handle both cases? Does anything speak against this? 
> 
>It would also allow inlining the shared createLogConversationFromFiles which seems to do most of the work.

I haven't done this yet in this patch.


>@@ +297,4 @@
>    }
>  };
>  
>  const dummySystemLog = {
> 
>Is this used? It's not compatible with the new code that returns promises e.g. >in close().

As I said on IRC, close() did not need to return anything and I've modified it accordingly. The dummy is used when the purple.logging.log_system pref isn't set.

I dropped those comments by mistake. I've added them back in this patch (but possibly in different places with slightly modified wording)
Attachment #8429188 - Attachment is obsolete: true
Attachment #8429574 - Flags: feedback?
Comment on attachment 8429574 [details] [diff] [review]
WIP 6

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

::: chat/components/src/logger.js
@@ +8,5 @@
>  Cu.import("resource:///modules/imServices.jsm");
>  Cu.import("resource:///modules/imXPCOMUtils.jsm");
>  Cu.import("resource:///modules/jsProtoHelper.jsm");
> +Cu.import("resource://gre/modules/osfile.jsm");
> +Cu.import("resource://gre/modules/Task.jsm");

Can we make these 2 lazy getters? If logs are disabled, they won't be used, right?

@@ +90,5 @@
>    return dateTime + twoDigits(offset) + twoDigits(minutes) + "." + aFormat;
>  }
>  
> +// Opens a file and repeatedly and asynchronously appends logs messages to it.
> +function ConversationLogWriter(aConversation)

This is a looong name. What about s/ConversationLogWriter/LogWriter/g?
Attachment #8429574 - Flags: feedback? → feedback?(aleth)

Comment 20

3 years ago
Comment on attachment 8429574 [details] [diff] [review]
WIP 6

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

Such async, very progress ;) I need to take another look at the tail end of this, but here's some feedback.

::: chat/components/src/logger.js
@@ +101,5 @@
> +      let path = yield getLogFilePathForConversation(this._conv, this.format, true);
> +      this.path = path;
> +      this._log = yield OS.File.open(path, {create: true});
> +      yield this._log.write(this.encoder.encode(this._getHeader()));
> +    } catch (aError) {

Will this also catch errors that happen within getLogFilePathForConversation? i.e. do errors there propagate correctly to a failed promise?

@@ +175,5 @@
>        };
>        let alias = aMessage.alias;
>        if (alias && alias != msg.who)
>          msg.alias = alias;
> +      return this._log.write(this.encoder.encode(JSON.stringify(msg) + "\n"));

You've forgotten the error handling here. If you'd followed my earlier suggestion of putting the text log case in an else {} and writing and returning only after that, you wouldn't have ;)

@@ +205,5 @@
>  
>    close: function cl_close() {
>      if (this._log) {
> +      this._logMessagePromise = this._logMessagePromise
> +        .then(() => this._log.close())

Wasn't it part of the discussion with Yoric that people usually forget to check for errors on close? ;)

@@ +220,5 @@
>    logMessage: function() {},
>    close: function() {}
>  };
>  
> +var gConversationLogWriters = { };

This wants to be a Map. (If you want to experiment with JS features, you could even make it a Proxy for a Map and override the get and delete to handle the following two functions, but that may be a distraction ;) )

@@ +225,1 @@
>  function getLogForConversation(aConversation)

Rename this to make it clear it only refers to log writing (i.e. make the naming of functions and objects a bit more sane and consistent).

@@ +553,5 @@
>    QueryInterface: XPCOMUtils.generateQI([Ci.nsISimpleEnumerator])
>  };
>  
> +// imILog implementation. Stores the log's path, format, and time for use with
> +// enumerators. Consumers call getConversation on this to get an actual conversation.

To pick up on the earlier suggestion: a Log is a LogCluster for a single file, right? I still think it could be a simplification to just give Log the capability to handle multiple files.

@@ +619,4 @@
>    _getLogArray: function logger__getLogArray(aAccount, aNormalizedName) {
> +    return Task.spawn(function* () {
> +      let path = OS.Path.join((yield getLogFolderPathForAccount(aAccount)),
> +                              encodeName(aNormalizedName));

What if this fails?

@@ +619,5 @@
>    _getLogArray: function logger__getLogArray(aAccount, aNormalizedName) {
> +    return Task.spawn(function* () {
> +      let path = OS.Path.join((yield getLogFolderPathForAccount(aAccount)),
> +                              encodeName(aNormalizedName));
> +      if ((yield OS.File.exists(path))) {

Are the extra brackets needed?

@@ +640,3 @@
>      if (aGroupByDay)
> +      return this._getDailyLogFromFile(aFilePath);
> +    return Task.spawn(() => new Log(aFilePath));

I think you want to make a promise directly here, no need for a task container.

::: im/content/conversation.xml
@@ +1569,5 @@
>                return item;
>              }
>              let showLogsItem = createMenuItem("contextShowLogs", function() conv.showLogs());
> +            // Start disabled, then enable if we have logs.
> +            showLogsItem.setAttribute("disabled", true);

Thanks for catching this! There was a similar issue in context menus once.
Attachment #8429574 - Flags: feedback?(aleth) → feedback+
(Assignee)

Comment 21

3 years ago
Created attachment 8430328 [details] [diff] [review]
WIP 8

This addresses feedback comments and squashes a few bugs. I've split the tests and UI code into separate patches (to be attached) since this was growing quite big already.

I realized that OS.File.Error.operation is something like "open" which isn't very useful - we want to be printing aError directly.

I've merged Logs and LogClusters.

I spoke with Yoric regarding race conditions between reading and writing. He said, "OS.File uses a single I/O thread, so you will never have a race between a read() and a write()."

He also warned me, however, that Windows may not like it if I open a file for reading, while it's already opened for writing (in general opening a file twice simultaneously). One solution for this would be to open the file whenever a message needs to be appended and close it immediately instead of keeping it open. He hasn't yet responded to my question of whether this is expensive.

I've implemented in this patch a Map of path->promise, where the promise would be obtained by |OS.File.open(...).then(<do some writing>).then(<close the file>).catch(<handle errors>). The helper function safelyDoFileOperation queues operations on a given file using this Map, ensuring we don't try to read a file before it's closed or whatever.

I haven't implemented the closing of files after arbitrary periods of inactivity because it may not be needed if we open/close files every time we write.

Unfortunately I haven't yet written more tests, and hope to work on this tomorrow. :(
Attachment #8429574 - Attachment is obsolete: true
Attachment #8430328 - Flags: feedback?(aleth)
(Assignee)

Comment 22

3 years ago
Created attachment 8430330 [details] [diff] [review]
Update Instantbird UI

This patch updates the Instantbird log viewer to work with the new async API.
Requesting review because this part is pretty much complete and likely won't change.
Attachment #8430330 - Flags: review?(aleth)
(Assignee)

Comment 23

3 years ago
Created attachment 8430332 [details] [diff] [review]
Tests

This adds tests for logger.js. Not requesting feedback/review since whatever is in this patch has already received feedback.
(Assignee)

Comment 24

3 years ago
Created attachment 8430463 [details] [diff] [review]
Patch

Yoric confirmed that the open->write->immediately close strategy would not be very expensive, so I've implemented that in this patch.

I've also accounted for the race condition problem when we're reading and writing to the same file. I/O operations to files are queued using the Map and promise chaining - see safelyDoFileOperation.

I couldn't think of any other major additions pending for this patch so I'm requesting review. I've tested it on a live Instantbird instance and things seem to be working well (including error handling). The testing I did was not exhaustive though and I do not expect this to be bug free - though I don't think it would ever completely destroy your logs ;)
Attachment #8430328 - Attachment is obsolete: true
Attachment #8430328 - Flags: feedback?(aleth)
Attachment #8430463 - Flags: review?(aleth)
(Assignee)

Comment 25

3 years ago
Created attachment 8430512 [details] [diff] [review]
Patch v2

- Fixed a few nits, improved a few comments.
- Added null check for aOpenOptions in safelyAppendToFile.
- Define lazy module getters for osfile.jsm and Task.jsm since they're not used if logging is disabled.
Attachment #8430463 - Attachment is obsolete: true
Attachment #8430463 - Flags: review?(aleth)
Attachment #8430512 - Flags: review?(aleth)
(Assignee)

Comment 26

3 years ago
Created attachment 8430808 [details]
Benchmark for the write strategies

This benchmark writes "Test string!" 1k times to a file, using two strategies - open->write 1k times->close, and (open->write once->close) 1k times. The latter strategy is about 4 times slower, but the absolute values are small enough that the overhead is negligible for our use case (~2 seconds vs ~0.5 seconds on my system).
(Assignee)

Comment 27

3 years ago
Created attachment 8430810 [details]
IRC conversation with avih about write strategy

avih gave me some nice insight on how OSes handle opening/closing of files on #perf. The conclusion of the discussion was that the simplicity of the solution for ensuring safety on Windows is more valuable than the (negligible) performance gain from keeping the file open instead of opening/closing every time.

Comment 28

3 years ago
Comment on attachment 8430512 [details] [diff] [review]
Patch v2

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

Can you run your benchmark on an USB 2.0 thumbdrive, to check what it would be like for a portable IB install, and to get the data for a slow NTFS drive?

A problem with your current safelyDo* implementation is that it is leaky. For any path we ever touch, a promise (and everything it refers to, whatever that is) is retained in memory forever.
(Would it help to have a Map of paths to objects which have read/append/... methods? I'm not sure.)

Make sure to include corrupt log files and empty log folders in your tests. One type of corruption that is common is a length-zero log file, from the data loss bug.

::: chat/components/public/imILogger.idl
@@ +44,5 @@
>    readonly attribute AUTF8String path;
>    readonly attribute PRTime time;
>    readonly attribute AUTF8String format;
> +  // Returns a promise that resolves to an imILogConversation instance, or null
> +  // if the log format isn't JSON.

It should only resolve to null if there is no log.

::: chat/components/src/logger.js
@@ +19,4 @@
>  
> +// Maps promises returned by OS.File operations to the path of the file being
> +// operated on. This is so that a file can be read after a pending write operation
> +// completes and vice versa.

Please add a sentence explaining why you are doing this so nobody has to go find this bug in the future (eg "we must ensure for Windows we don't access an open file twice", "prevent XYZ race conditon" or whatever)

@@ +19,5 @@
>  
> +// Maps promises returned by OS.File operations to the path of the file being
> +// operated on. This is so that a file can be read after a pending write operation
> +// completes and vice versa.
> +var gOSFilePromisesByPath = new Map();

How about shortening this to gFilePromises or gPathPromises?

@@ +22,5 @@
> +// completes and vice versa.
> +var gOSFilePromisesByPath = new Map();
> +
> +// Uses above map to queue operations on a file.
> +function safelyDoFileOperation(aPath, aOperation) {

eg. fileAction() or fileOperation() would be shorter.

@@ +34,5 @@
> +  return promise;
> +}
> +
> +// Convenience method to append to a file using the above queue system. If any of
> +// the I/O operations reject, the returned promise will reject with the same reason.

Explain why the file is opened and closed on each operation.

@@ +37,5 @@
> +// Convenience method to append to a file using the above queue system. If any of
> +// the I/O operations reject, the returned promise will reject with the same reason.
> +function safelyAppendToFile(aPath, aEncodedLine, aOpenOptions) {
> +  if (!aOpenOptions)
> +    aOpenOptions = {};

You can put aOpenOptions = {} into the parameter definition as a default value.

@@ +44,5 @@
> +    let file = yield OS.File.open(aPath, aOpenOptions);
> +    try {
> +      yield file.write(aEncodedLine);
> +    }
> +    finally {

Nice way to ensure the file always gets closed.

Can't you insert a catch(e) {Cu.reportError(e);} to make sure a write error gets written to the error console? Hope is not a plan ;) (test it by manually rejecting a promise in try {})

@@ +199,5 @@
> +  },
> +  _queuedLogMessage: function cl_queuedLogMessage(aMessage) {
> +    if (!this.path) {
> +      Cu.reportError("Aborting logMessage for " + this._conv.normalizedName +
> +                     " because initialization failed.");

This is going to really spam the error console if messages keep coming in, and we already have the relevant error in the error console, so no need for this.

@@ +200,5 @@
> +  _queuedLogMessage: function cl_queuedLogMessage(aMessage) {
> +    if (!this.path) {
> +      Cu.reportError("Aborting logMessage for " + this._conv.normalizedName +
> +                     " because initialization failed.");
> +      return Promise.resolve();

You don't have to return a promise if there is nothing to wait for ;)

@@ +257,5 @@
>    close: function() {}
>  };
>  
> +var gLogWritersById = new Map();
> +function getLogWriterForConversation(aConversation)

getLogWriter()

@@ +273,3 @@
>  }
>  
>  function closeLogForConversation(aConversation)

closeLogWriter

@@ +282,3 @@
>  }
>  
> +// LogWriter for system logs.

Not reviewed yet - I assume it's effectively the same as the above.

@@ +379,5 @@
> + * Reads a set of log files asynchronously and returns a promise that resolves to
> + * a LogConversation instance. Even if a file contains some junk (invalid JSON),
> + * messages that are valid will be read. If the first line of metadata is corrupt
> + * however, the data isn't useful and the promise will resolve to null.
> + */

At some point before this lands, pick a commenting style for this file and make it consistent. But thanks for adding the comments!

@@ +391,5 @@
> +    let decoder = new TextDecoder();
> +    for (let path of aPaths) {
> +      let lines;
> +      try {
> +        let fileContents = safelyDoFileOperation(path, () => OS.File.read(path));

Misleading. Maybe put the yield on this line?

@@ +407,5 @@
> +        flags: ["noLog", "notification"]
> +      }
> +      if (!nextLine) {
> +        // Bad log file.
> +        sessionMsg.text = bundle.formatStringFromName("badLogFile", [filename], 1);

How about using l10nHelper instead of the bundle getter, that way we don't have to use the ugly formatStringFromName in this file ever again.

@@ +541,2 @@
>    QueryInterface: XPCOMUtils.generateQI([Ci.nsISimpleEnumerator])
>  };

Can we, to help legibility, generally in this file have two blank lines between the various object definitions, like here.

@@ +546,3 @@
>    this._entries = {};
>  
> +  for each (let entries in aEntriesArray) {

for ... of while you are at it (for each is deprecated)

@@ +656,3 @@
>        return null;
> +    let paths = [entry.path for each (entry in this._entries)];
> +    return createLogConversationFromFiles(paths);

You can inline this function now.

@@ +688,2 @@
>      if (aGroupByDay)
> +      return this._getDailyLogFromFile(aFilePath);

It seems this is the only place _getDailyLogFromFile gets called. Inline it. You probably want to swap the order and do if (!GroupByDay).

@@ +702,3 @@
>      let relevantEntries = [];
> +    return iterator.forEach(function(aEntry) {
> +      let path = aEntry.path;

Why can you drop the check that this path is actually a file?

@@ +742,5 @@
> +        entries.push(yield this._getLogArray(accountBuddy.account,
> +                                             accountBuddy.normalizedName));
> +      }
> +      return entries;
> +    }).then(aEntries => this._getEnumerator(aEntries, aGroupByDay));

Why the .then?

@@ +756,3 @@
>        }
> +      return entries;
> +    }).then(aEntries => this._getEnumerator(aEntries, aGroupByDay));

ditto
Attachment #8430512 - Flags: review?(aleth) → review-
(Assignee)

Comment 29

3 years ago
Created attachment 8432141 [details] [diff] [review]
Patch v3

Address review comments, use Task.async instead of Task.spawn in a few places for readability (http://dxr.mozilla.org/mozilla-central/source/toolkit/modules/Task.jsm#142).
Attachment #8430512 - Attachment is obsolete: true
Attachment #8432141 - Flags: review?(aleth)

Comment 30

3 years ago
Comment on attachment 8432141 [details] [diff] [review]
Patch v3

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

Looks like this is getting close to finished :)

::: chat/components/src/logger.js
@@ +20,4 @@
>  
> +/*
> + * Maps promises returned by OS.File operations to the path of the file being
> + * operated on. This is so that a file can be read after a pending write operation

"Maps paths... to promises" ;)

@@ +34,5 @@
> +    gFilePromises.set(aPath, Promise.resolve());
> +
> +  let promise = gFilePromises.get(aPath).then(aOperation);
> +  gFilePromises.set(aPath, promise);
> +  promise.then(() => {

This is a nice solution, but you also have to use it if the promise rejects. Make sure that as you do this, you don't change the state of the promise back to "success".

@@ +40,5 @@
> +    if (gFilePromises.get(aPath) == promise)
> +      gFilePromises.delete(aPath);
> +  });
> +  return promise;
> +}

It would be nice to have a test for this function (using dummy operation functions).

@@ +63,5 @@
> +       * If both the write() above and the close() below throw, and we don't
> +       * handle the close error here, the promise will be rejected with the close
> +       * error and the write error will be dropped. To avoid this, we log any
> +       * close error here so that any write error will be propagated.
> +       */

You were right, it just needed a better comment that matched what the code was doing :)

@@ +213,5 @@
>      return encoder.encodeToString();
>    },
>    logMessage: function cl_logMessage(aMessage) {
> +    return this._logMessagePromise =
> +      this._logMessagePromise.then(() => this._queuedLogMessage(aMessage));

Do we actually need to return anything here?

@@ +527,3 @@
>  /**
> + * A Log object represents one or more log files. The constructor expects one
> + * argument, which is either a single path to a log file or an array of objects

Mention in the comment that for a single file, the precise time will be used, whereas for an array of objects, only the day is relevant.

@@ +533,3 @@
>   */
> +function Log(aEntries) {
> +  if (!Array.isArray(aEntries)) {

You've dropped the check that the array is nonempty.

@@ +533,4 @@
>   */
> +function Log(aEntries) {
> +  if (!Array.isArray(aEntries)) {
> +    if (typeof aEntries != "string")

You can simplify by 
if (typeof aEntries == "string") {...return;}
if (!aEntries.length) throw...

@@ +577,5 @@
>    format: "json",
> +  getConversation: function() {
> +    if (this.format != "json")
> +      return null;
> +    let paths = [entry.path for (entry of this._entries)];

If you move this inside the spawned function you can use Task.async here.

Why are you storing this._entries in the constructor if all you ever need is paths? Seems simpler to make a this._paths in the constructor.

@@ +661,5 @@
> +  get buddy() null,
> +  get account() ({
> +    alias: "",
> +    name: this._accountName,
> +    normalizedName: this._accountName,

Shouldn't this be the normalized account name, or is _accountName normalized already?
Attachment #8432141 - Flags: review?(aleth) → review-
(Assignee)

Comment 31

3 years ago
Created attachment 8432646 [details] [diff] [review]
Patch v4
Attachment #8432141 - Attachment is obsolete: true
Attachment #8432646 - Flags: review?(aleth)
(Assignee)

Comment 32

3 years ago
Created attachment 8432735 [details] [diff] [review]
Patch v4

Removed stray semicolon
Attachment #8432646 - Attachment is obsolete: true
Attachment #8432646 - Flags: review?(aleth)
Attachment #8432735 - Flags: review?(aleth)

Comment 33

3 years ago
Comment on attachment 8432646 [details] [diff] [review]
Patch v4

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

Overall I think this is very close to r+ now, but until tests exist and pass, it may still change.

::: chat/components/src/logger.js
@@ +42,5 @@
> +    if (gFilePromises.get(aPath) == promise)
> +      gFilePromises.delete(aPath);
> +  };
> +  // Ensure we clear unused promises whether they resolved or rejected.
> +  promise.then(cleanup, cleanup);

Interestingly, only the second promise.then(x,x) would be a use case for a putative Promise.finally(), and the only reason we can use a simple promise.then for that here is that we don't care about the returned promise.

@@ +531,3 @@
>  /**
> + * A Log object represents one or more log files. The constructor expects one
> + * argument, which is either a single path to a log file or an array of objects

... (text or json) log file ...

@@ +531,5 @@
>  /**
> + * A Log object represents one or more log files. The constructor expects one
> + * argument, which is either a single path to a log file or an array of objects
> + * each having two properties:
> + *   path: The full path of the log file it represents

...json log file...

@@ +552,5 @@
> +    }
> +    this.time = date.valueOf() / 1000;
> +    this.format = format;
> +    // Create an entry object and wrap it in an array.
> +    this._entries = [{

this._entryPaths

@@ +656,5 @@
> +  });
> +};
> +
> +
> +function LogConversation(aMessages, aProperties) {

How about moving this object under LogMessage in the file (seems a better ordering)?
Attachment #8432646 - Attachment is obsolete: false

Updated

3 years ago
Attachment #8432735 - Flags: review?(aleth) → review-

Updated

3 years ago
Attachment #8432646 - Attachment is obsolete: true

Comment 34

3 years ago
Comment on attachment 8432735 [details] [diff] [review]
Patch v4

flo: I'd appreciate it if you could take a look at this patch - I think it could benefit from a fresh pair of eyes after all these review cycles, and to double-check the approach taken here.
Attachment #8432735 - Flags: feedback?(florian)
(Assignee)

Comment 35

3 years ago
Created attachment 8433340 [details] [diff] [review]
Patch v5

Addressed review comments, reordered stuff to follow the convention of putting consumers of certain objects under the object definitions.
Attachment #8432735 - Attachment is obsolete: true
Attachment #8432735 - Flags: feedback?(florian)
Attachment #8433340 - Flags: review?(aleth)

Updated

3 years ago
Attachment #8433340 - Flags: review?(florian)

Updated

3 years ago
Attachment #8433340 - Flags: review?(florian) → feedback?(florian)
(Assignee)

Comment 36

3 years ago
Created attachment 8433647 [details] [diff] [review]
Patch v6

Address review comments and fix a couple of bugs found thanks to tests :)
Attachment #8433340 - Attachment is obsolete: true
Attachment #8433340 - Flags: review?(aleth)
Attachment #8433340 - Flags: feedback?(florian)
Attachment #8433647 - Flags: review?(aleth)
(Assignee)

Comment 37

3 years ago
Created attachment 8433650 [details] [diff] [review]
Tests v2

Added tests for the promise queue, also a test to write a log and then read it again. Also, made these tests actually work ;)
Attachment #8430332 - Attachment is obsolete: true
Attachment #8433650 - Flags: feedback?(aleth)
(Assignee)

Comment 38

3 years ago
Created attachment 8433651 [details] [diff] [review]
Update Instantbird UI v2

Updates blist.js and nsContextMenu.js.
Attachment #8430330 - Attachment is obsolete: true
Attachment #8430330 - Flags: review?(aleth)
Attachment #8433651 - Flags: review?(aleth)
(Assignee)

Comment 39

3 years ago
Created attachment 8433653 [details] [diff] [review]
Update Thunderbird UI and Gloda

Update Thunderbird. Not sure if what I've done for gloda indexing works/is acceptable. I also haven't tested any of this yet as I don't have a Tb build at the moment.
Attachment #8433653 - Flags: review?(florian)
Attachment #8433653 - Flags: review?(aleth)
(Assignee)

Updated

3 years ago
Attachment #8433647 - Flags: feedback?(florian)
(Assignee)

Comment 40

3 years ago
Created attachment 8433659 [details] [diff] [review]
Update Instantbird UI v2

Accidentally uploaded the tb patch twice, sorry. This is the real one.
Attachment #8433651 - Attachment is obsolete: true
Attachment #8433651 - Flags: review?(aleth)
Attachment #8433659 - Flags: review?(aleth)

Updated

3 years ago
Attachment #8433653 - Flags: review?(aleth)

Comment 41

3 years ago
Comment on attachment 8433659 [details] [diff] [review]
Update Instantbird UI v2

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

::: im/content/nsContextMenu.js
@@ +162,5 @@
>      let isTwitter = this.conv.account.protocol.id == "prpl-twitter";
>  
>      addAction("OpenConv", this.onNick && !isTwitter);
> +    this.getLogsForNick(nick).then(aLogs => {
> +      addAction("ShowLogs", this.onNick && aLogs && aLogs.hasMoreElements());

addAction is a helper function in this scope. I doubt this code still works as intended if it's called after actions is returned/used.
Attachment #8433659 - Flags: review?(aleth) → review-
Comment on attachment 8433647 [details] [diff] [review]
Patch v6

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

::: chat/components/public/imILogger.idl
@@ +52,5 @@
>  [scriptable, uuid(327ba58c-ee9c-4d1c-9216-fd505c45a3e0)]
>  interface imILogger: nsISupports {
> +  // Returns a promise that resolves to an imILog instance.
> +  jsval getLogFromFile(in string aFilePath, [optional] in boolean aGroupByDay);
> +  string getLogFileForOngoingConversation(in prplIConversation aConversation);

"string" is not the return type you want, "AUTF8String" is more likely what you meant (if you are sure the string is UTF8).

@@ +59,4 @@
>  
>    // Get logs for a username that may not be in the contact list.
> +  jsval getLogsForAccountAndName(in imIAccount aAccount,
> +                                 in string aNormalizedName,

Looks like this was wrong before already, but please also change it here.

::: chat/components/src/logger.js
@@ +34,5 @@
> +
> +  // Ensure the operation is queued regardless of whether the last one succeeded.
> +  // This is safe since the promise is returned and consumers are expected to
> +  // handle any errors.
> +  let promise = gFilePromises.get(aPath).then(aOperation, aOperation);

why not just gFilePromises.get(aPath) || Promise.resolve() here to avoid setting dummy promises in gFilePromises above?

@@ +38,5 @@
> +  let promise = gFilePromises.get(aPath).then(aOperation, aOperation);
> +  gFilePromises.set(aPath, promise);
> +  let cleanup = () => {
> +    // If no further operations have been queued, remove the reference from the map.
> +    if (gFilePromises.get(aPath) == promise)

doesn't this need to be === ?

@@ +42,5 @@
> +    if (gFilePromises.get(aPath) == promise)
> +      gFilePromises.delete(aPath);
> +  };
> +  // Ensure we clear unused promises whether they resolved or rejected.
> +  promise.then(cleanup, cleanup);

Should you |return promise.then(cleanup, cleanup);| here? (note: I don't know the answer)

@@ +51,5 @@
> + * Convenience method to append to a file using the above queue system. If any of
> + * the I/O operations reject, the returned promise will reject with the same reason.
> + * We open the file, append, and close it immediately. The alternative is to keep
> + * it open and append as required, but we want to make sure we don't open a file
> + * for reading while it's already open for writing, so we close it every time

Are you really saying that you are opening and closing the file for each line you write to it?

Would it work to close the file only when you are about to open it for reading?

@@ +78,3 @@
>  // This function checks names against OS naming conventions and alters them
>  // accordingly so that they can be used as file/folder names.
> +function encodeName(aName) {

I see no reason for this change, the coding style in the file seemed consistent.

@@ +119,5 @@
> +    path = OS.Path.join(path, encodeName(name));
> +    if (aCreate) {
> +      yield queueFileOperation(path, () =>
> +        OS.File.makeDir(path, {ignoreExisting: true,
> +                        from: OS.Constants.Path.profileDir}));

wrong indent here.

@@ +169,5 @@
>    _log: null,
> +  path: null,
> +  // Store the Promise for an ongoing operation (or its resolved value)
> +  // so that the next operation can be queued in then().
> +  _logMessagePromise: null,

Isn't this redundant with the gFilePromises map?

@@ +617,5 @@
>        let dateForID = new Date(logDate);
>        let dayID;
>        if (logFormat == "json") {
> +        /*
> +         * We want to cluster all of the logs that occur on the same day

what's the point of changing the comment style here?

@@ +747,4 @@
>    getLogsForAccountAndName: function logger_getLogsForAccountAndName(aAccount,
>                                         aNormalizedName, aGroupByDay) {
> +    return this._getLogArray(aAccount, aNormalizedName)
> +               .then(aEntries => this._getEnumerator([aEntries], aGroupByDay));

Why [aEntries] and not just aEntries? I thought _getLogArray already returned an array.

@@ +758,3 @@
>      let entries = [];
>      for (let accountBuddy of aBuddy.getAccountBuddies()) {
> +      entries.push(yield this._getLogArray(accountBuddy.account,

Why the concat -> push change?

@@ +766,4 @@
>      let entries = [];
>      for (let buddy of aContact.getBuddies()) {
>        for (let accountBuddy of buddy.getAccountBuddies()) {
> +        entries.push(yield this._getLogArray(accountBuddy.account,

same here.

@@ +784,5 @@
> +  getSimilarLogs: Task.async(function* (aLog, aGroupByDay) {
> +    let iterator = new OS.File.DirectoryIterator(OS.Path.dirname(aLog.path));
> +    let entries = [];
> +    try {
> +      entries.push(yield iterator.nextBatch());

entries = yield iterator.nextBatch() ?
Attachment #8433647 - Flags: feedback?(florian) → feedback+
Comment on attachment 8433653 [details] [diff] [review]
Update Thunderbird UI and Gloda

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

::: mail/components/im/content/chat-messenger-overlay.js
@@ +550,5 @@
>  
>      if (item.getAttribute("id") == "searchResultConv") {
>        let path = "logs/" + item.log.path;
>        let file = FileUtils.getFile("ProfD", path.split("/"));
> +      imServices.logs.getLogFromFile(file, true).then(aLog => {

Can't we change this code to avoid having to create an nsIFile and use the path stored in the database directly?

@@ +552,5 @@
>        let path = "logs/" + item.log.path;
>        let file = FileUtils.getFile("ProfD", path.split("/"));
> +      imServices.logs.getLogFromFile(file, true).then(aLog => {
> +        document.getElementById("goToConversation").hidden = true;
> +        document.getElementById("contextPane").removeAttribute("chat");

aren't these 2 lines something that should execute immediately, rather than once we get the file content?

@@ +564,5 @@
> +          cti.removeAttribute("status");
> +          cti.removeAttribute("statusTypeTooltiptext");
> +          cti.removeAttribute("statusTooltiptext");
> +          cti.removeAttribute("topicEditable");
> +          cti.removeAttribute("noTopic");

I'm wondering if we should do all these .removeAttribute before getting the file content.

@@ +567,5 @@
> +          cti.removeAttribute("topicEditable");
> +          cti.removeAttribute("noTopic");
> +          imServices.logs.getSimilarLogs(aLog, true).then(aSimilarLogs => {
> +            this._showLogList(aSimilarLogs, aLog);
> +            this.observedContact = null;

this.observedContact = null; seems unrelated to getting the list of similar logs.

@@ +593,5 @@
>        item.convView.updateConvStatus();
>        item.update();
>  
> +      imServices.logs.getLogsForConversation(item.conv, true).then(aLogs => {
> +        this._showLogList(aLogs);

|this._showLogList(aLogs);| here seems the only line that depends on getting the logs for the conversation.

::: mail/components/im/modules/index_im.js
@@ +326,5 @@
>      }
>  
> +    let conv = this._knownConversations[convId];
> +    Services.logs.getLogFromFile(conv.logFile).then(aLog => {
> +      aLog.getConversation().then(aConv => {

I'm wondering if there's a risk that we would be putting all conversations in memory before the indexIMConversation jobs are actually executed.

@@ +433,5 @@
>        glodaConv = aGlodaConv.value;
>        glodaConv._content = content;
>      }
>      else {
> +      glodaConv = new GlodaIMConversation(aLogConv.title, aLog.time, path, content);

Isn't .time also part of aLogConv? That would let you avoid the aLog parameter.
Attachment #8433653 - Flags: review?(florian) → review-

Comment 44

3 years ago
Comment on attachment 8433650 [details] [diff] [review]
Tests v2

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

::: chat/components/src/test/test_logger.js
@@ +26,5 @@
> +}
> +
> +let dummyTwitterAccount = {
> +  name: "dummy-twitter",
> +  normalizedName: "dummy-twitter-normalized",

iirc twitter's normalize strips hyphens ;)

@@ +60,5 @@
> +  account: dummyTwitterAccount,
> +  id: 2,
> +  title: "Dummy Twitter Conv",
> +  normalizedName: "dummy-twitter-conv",
> +  get name() this.normalizedName,

see above.

@@ +67,5 @@
> +}
> +
> +let test_convs = [dummyConv, dummyMUC, dummyTwitterConv];
> +
> +let encodeName_input = [

Can we add a couple of realistic examples here? Looks like we're just testing the edge cases.

@@ +125,5 @@
> +
> +  // Immediately after calling qFO, "path1" should be mapped to p1.
> +  // After yielding, the reference should be cleared from the map.
> +  let p1 =  qFO("path1", dummyResolvedOperation);
> +  Assert.ok(gFP.get("path1") == p1);

Drop the Assert everywhere.
Assert.equal is better for this.

@@ +133,5 @@
> +  // Repeat above test for a rejected promise.
> +  let p2 = qFO("path2", dummyRejectedOperation);
> +  Assert.ok(gFP.get("path2") == p2);
> +  // This will throw since p2 rejected. Drop the error.
> +  yield p2.catch(() => {});

Or yield p2.then(() => ok(false), () => ok(true)); if you wanted. Maybe overkill ;)

@@ +139,5 @@
> +
> +  onPromiseComplete = (aPromise, aHandler) => {
> +    return aPromise.then(aHandler, aHandler);
> +  }
> +  let test_queueOrder = (aOperationA, aOperationB) => {

Would it be useful to also test this with dummy operations that resolve/reject after a timeout? Or doesn't that really matter?

@@ +146,5 @@
> +    onPromiseComplete(promiseA, () => firstOperationComplete = true);
> +    let promiseB = qFO("queueOrderPathB", aOperationB);
> +    return onPromiseComplete(promiseB, () => {
> +      Assert.ok(firstOperationComplete);
> +    });

I don't understand this test, why is there any expected order for pathA != pathB? Two different queues.

For pathA == pathB, shouldn't you be asserting ok at the end only if promiseB resolves/rejects correctly? You can also move the firstOperationComplete check into qFO(..., () = ( ok(firstOperationComplete); return aOperationB();}

@@ +155,5 @@
> +  yield test_queueOrder(dummyRejectedOperation, dummyResolvedOperation);
> +  yield test_queueOrder(dummyRejectedOperation, dummyRejectedOperation);
> +}
> +
> +let test_getLogFolderPathForAccount = function* () {

Needs a comment, or better message, explaining this tests log folder creation.

@@ +207,5 @@
> +  let path = OS.Path.join(OS.Constants.Path.profileDir, "testFile.txt");
> +  let encodedString = (new TextEncoder()).encode(kStringToWrite);
> +  yield gLogger.appendToFile(path, encodedString, {truncate: true});
> +  yield gLogger.appendToFile(path, encodedString);
> +  let text = (new TextDecoder).decode(yield OS.File.read(path));

for consistency, why not use the same queue for the OS.File.read that appendToFile uses?

@@ +244,5 @@
> +    }
> +  ];
> +  let logWriter = gLogger.getLogWriter(dummyConv);
> +  for (let message of messagesToLog)
> +    yield logWriter.logMessage(message);

Why the yield here?

@@ +261,5 @@
> +        Assert.equal(expectedMessage[prop], message[prop]);
> +      }
> +    }
> +  }
> +  do_throw();

Can we also test obtaining clustered (daily) logs containing say 1-2 sessions? With the sessions being permutations of: the above conv, a zero-length log file, and an invalid JSON log file?

@@ +275,5 @@
> +  ok(!gLogger.convIsRealMUC(dummyTwitterConv));
> +  ok(gLogger.convIsRealMUC(dummyMUC));
> +
> +  //add_task(test_getLogFolderPathForAccount);
> +  //

Commented out for testing purposes? If the test output is hard to understand, maybe adding some info messages would help?
Attachment #8433650 - Flags: feedback?(aleth) → feedback+
(Assignee)

Comment 45

3 years ago
Created attachment 8435318 [details] [diff] [review]
Patch v7

Address review comments.
Attachment #8433647 - Attachment is obsolete: true
Attachment #8433647 - Flags: review?(aleth)
Attachment #8435318 - Flags: review?(florian)
(Assignee)

Comment 46

3 years ago
Created attachment 8435326 [details] [diff] [review]
Patch v8

Updated a comment and fixed a couple of nits.
Attachment #8435318 - Attachment is obsolete: true
Attachment #8435318 - Flags: review?(florian)
Attachment #8435326 - Flags: review?(florian)
(Assignee)

Comment 47

3 years ago
Created attachment 8435330 [details] [diff] [review]
Update Thunderbird UI and Gloda v2

Implement a promise queue to ensure we don't load the logs for all conversations at once, and address review comments.
Attachment #8433653 - Attachment is obsolete: true
Attachment #8435330 - Flags: review?(florian)
(Assignee)

Comment 48

3 years ago
Comment on attachment 8435330 [details] [diff] [review]
Update Thunderbird UI and Gloda v2

Quite a few more changes are required, the review request was premature. Cancelling it for now.
Attachment #8435330 - Flags: review?(florian)
(Assignee)

Comment 49

3 years ago
Created attachment 8436253 [details] [diff] [review]
Update Thunderbird UI and Gloda v3

I've tested these changes and everything seems to work - log viewing UI (including search), and gloda indexing.
Attachment #8435330 - Attachment is obsolete: true
Attachment #8436253 - Flags: review?(florian)
(Assignee)

Comment 50

3 years ago
Created attachment 8437459 [details] [diff] [review]
Tests v3

Added tests for daily logs, with a zero-length file and a file with non-JSON content.

I don't think we need to test Promises that resolve after a timeout (we handle all the cases already don't we?) but I'm not entirely sure and haven't looked at it thoroughly. Concentrated on the daily logs stuff for this patch.

>@@ +244,5 @@
>> +    }
>> +  ];
>> +  let logWriter = gLogger.getLogWriter(dummyConv);
>> +  for (let message of messagesToLog)
>> +    yield logWriter.logMessage(message);
>
>Why the yield here?

In the version of the patch you commented on, the reason is because when we do getLogsForConversation, the files wouldn't have been created yet, and so it returns an EmptyEnumerator. In this new version (also refer to the new logger.js patch I am about to attach), if we don't yield on logMessage, when we close the writer on the next line we unset its path and cause it to fail when it's finally called. Since we're both creating the logWriter and closing it from the same code, I strongly suggest we just yield on every message. Queuing has already been tested above anyway. Maybe we want to have a proper test to ensure the writing/reading queuing as well, but I need to get some sleep now :)
Attachment #8433650 - Attachment is obsolete: true
Attachment #8437459 - Flags: review?(aleth)
(Assignee)

Comment 51

3 years ago
Created attachment 8437461 [details] [diff] [review]
Patch v9

Various fixes for bugs/errors I've found from writing tests :)
Attachment #8435326 - Attachment is obsolete: true
Attachment #8435326 - Flags: review?(florian)
Attachment #8437461 - Flags: review?(florian)
(Assignee)

Comment 52

3 years ago
Created attachment 8437465 [details] [diff] [review]
Patch v10

Adds comments above the various time/startDate definitions to indicate units.
Attachment #8437461 - Attachment is obsolete: true
Attachment #8437461 - Flags: review?(florian)
Attachment #8437465 - Flags: review?(florian)

Comment 53

3 years ago
Comment on attachment 8437465 [details] [diff] [review]
Patch v10

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

::: chat/components/src/logger.js
@@ +217,5 @@
>      }});
>      return encoder.encodeToString();
>    },
> +  logMessage: Task.async(function* (aMessage) {
> +    yield this._initialized;

I have a nagging sense this could be simplified. This is currently synchronous code with a bunch of overhead unless we're waiting on initialization to complete.

If we could always use the path queue we wouldn't need to wait... and the only problem with that is the first steps of initialization.

Is there a clever way around this?

@@ +220,5 @@
> +  logMessage: Task.async(function* (aMessage) {
> +    yield this._initialized;
> +    if (!this.path) {
> +      // Initialization failed.
> +      return Promise.reject(new Error("Calling _queuedLogMessage on uninitialized" +

Change the error string

@@ +279,5 @@
>  };
>  
> +
> +let gLogWritersById = new Map();
> +function getLogWriter(aConversation) {

It *seems* (see below) this is only called in one place in a situation where it would actually need to create a logWriter rather than just use .get on the map. So we could get rid of this function by inlining this code there.

@@ +294,3 @@
>  }
>  
> +function closeLogWriter(aConversation) {

Also only called in one place, so we can get rid of it (if you agree this is a simplification).

@@ +565,5 @@
> +        let data;
> +        try {
> +          data = JSON.parse(nextLine);
> +        } catch(aError) {
> +          continue;

Good catch, this does need the try. But if the header is wrong and we therefore skip the entire file, we need to handle it as a bad log file (see comment a couple of lines up).

@@ +742,5 @@
>      let enumerator = aGroupByDay ? DailyLogEnumerator : LogEnumerator;
>      return aLogArray.length ? new enumerator(aLogArray) : EmptyEnumerator;
>    },
>    getLogFileForOngoingConversation: function logger_getLogFileForOngoingConversation(aConversation)
> +    getLogWriter(aConversation).path,

What if path isn't set? Do the consumers handle this correctly?

Is this ever called when no conversation log already exists for the conversation (i.e. and this call will end up making one)?

@@ +806,5 @@
>         "account-buddy-status-changed"].forEach(function(aEvent) {
>          Services.obs.addObserver(this, aEvent, false);
>        }, this);
>        break;
>      case "new-text":

This isn't great (we could observe this from the logWriter) but I guess the benefit is that we don't create a log file until we actually have messages to log.
Attachment #8437465 - Flags: review?(florian) → review-

Comment 54

3 years ago
Comment on attachment 8437459 [details] [diff] [review]
Tests v3

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

Looks close to finished :)

::: chat/components/src/test/test_logger.js
@@ +203,5 @@
> +    let promise = qFO("queueOrderPath", aOperation);
> +    let firstOperationComplete = false;
> +    onPromiseComplete(promise, () => firstOperationComplete = true);
> +    return qFO("queueOrderPath", () => {
> +      ok(firstOperationComplete);

This isn't actually going to fail if the second operation doesn't happen. Is that intentional?

@@ +314,5 @@
> +  // Ensure two different files for the different dates.
> +  let logMessagesForConv = Task.async(function* (aConv, aMessages) {
> +    let logWriter = gLogger.getLogWriter(aConv);
> +    for (let message of aMessages)
> +      yield logWriter.logMessage(message);

I don't like this yield. It's not there in production code (we call logMessage immediately on new-text).

@@ +337,5 @@
> +  yield createBadFiles(dummyConv);
> +  yield createBadFiles(dummyConv2);
> +
> +  let testMsgs = function (aMsgs, aExpectedMsgs) {
> +    // Discard session messages, etc.

Can't we test that the correct number of session messages have been added?

@@ +398,5 @@
> +  add_task(test_getLogFolderPathForAccount);
> +
> +  add_task(test_getLogFilePathForConversation);
> +
> +  add_task(test_getLogFilePathForMUC);

How easy to read is the test output if something fails somewhere, especially given this is async? Is it easy to identify which particular ok/equal failed? Maybe it would be a good idea to add some comment messages to the output (note they won't be written anyway unless something fails).
Attachment #8437459 - Flags: review?(aleth) → review-
(Assignee)

Comment 55

3 years ago
Created attachment 8438811 [details] [diff] [review]
Patch v11

I've made the getLogFolder/Fileblabla functions empty of any file I/O, so they can now be synchronous. The log headers are now written in the first logMessage/Event call. I hope this answers "Is there a clever way around this?" :)

Regarding inlining getLogWriter and closeLogWriter, I'd rather keep them - it's organized and obvious to a reader that these are lazy getters. If you think this isn't that bad for readability, I'll inline it in the next patch.
Attachment #8437465 - Attachment is obsolete: true
Attachment #8438811 - Flags: review?(aleth)
(Assignee)

Comment 56

3 years ago
Created attachment 8438834 [details] [diff] [review]
Patch v12

Fixed a few things I overlooked.
Attachment #8438811 - Attachment is obsolete: true
Attachment #8438811 - Flags: review?(aleth)
Attachment #8438834 - Flags: review?(aleth)

Comment 57

3 years ago
Comment on attachment 8438834 [details] [diff] [review]
Patch v12

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

Nice simplification! :)

::: chat/components/src/logger.js
@@ +196,5 @@
> +        Cu.reportError("Failed to initialize log file:\n" + aError);
> +        closeLogWriter(this._conv);
> +        return Promise.reject();
> +      }
> +    }

I don't think this prevents trying to write the header multiple times if we are unlucky and logMessage is called rapidly in succession. The closeLogWriter also doesn't do much as the next new-text is simply going to reopen a new one.

How about moving this appendToFile call to the constructor (with a .catch() to handle errors there) ? Then we can get rid of the Task.async and the initialized check in logMessage, as creating the file will always already be queued. Trying to append to a file that doesn't exist will cause errors anyway, which can be handled.

I'm not sure about the goal you had for error handling here should things go wrong. Is it to try to create the file again? When? Each time we try to write?

@@ +242,2 @@
>  
>    close: function cl_close() {

Looks like this method can be safely removed.

@@ +701,5 @@
>      let enumerator = aGroupByDay ? DailyLogEnumerator : LogEnumerator;
>      return aLogArray.length ? new enumerator(aLogArray) : EmptyEnumerator;
>    },
>    getLogFileForOngoingConversation: function logger_getLogFileForOngoingConversation(aConversation)
> +    getLogWriter(aConversation).path,

You didn't quite answer my question about this. Are you sure this should involve logWriters at all? What calls this and do the callers assume the returned path exists?
Attachment #8438834 - Flags: review?(aleth) → review-
(Assignee)

Comment 58

3 years ago
Created attachment 8439536 [details] [diff] [review]
Patch v13

Hopefully this clears up those issues :)
If writing the header fails, we don't try to log any messages. If there was an I/O error, there is slim (maybe no) chance that writing the pending messages would succeed anyway.

I forgot to mention in the last comment that I thought the getLogFileForOngoingConversation problem "fixed itself" since the log writer's path is now set synchronously in the constructor. I think it makes sense that once a consumer requests the file for a conversation, we should ready that file for writing - but if that's just me, we can change it to just fetch the path and return it without creating a log writer object.
Attachment #8438834 - Attachment is obsolete: true
Attachment #8439536 - Flags: review?(aleth)
(Assignee)

Comment 59

3 years ago
Adding to the above comment, there's only one consumer for the function at this point - gloda indexing - and it has been updated to be async in the Tb patch. I do think that we want to create this file if it doesn't exist, since gloda certainly expects it to exist. Maybe gloda shouldn't expect this, I'll wait for your opinion :)
(Assignee)

Comment 60

3 years ago
Created attachment 8439698 [details] [diff] [review]
Patch v14

Fixed syntax errors (:]) and squashed a bug with txt logs.
Attachment #8439536 - Attachment is obsolete: true
Attachment #8439536 - Flags: review?(aleth)
Attachment #8439698 - Flags: review?(aleth)
(Assignee)

Comment 61

3 years ago
Created attachment 8439875 [details] [diff] [review]
Patch v15

Fix a couple of session message bugs, update a comment.
Attachment #8439698 - Attachment is obsolete: true
Attachment #8439698 - Flags: review?(aleth)
Attachment #8439875 - Flags: review?(aleth)
(Assignee)

Comment 62

3 years ago
Created attachment 8439885 [details] [diff] [review]
Tests v4
Attachment #8437459 - Attachment is obsolete: true
Attachment #8439885 - Flags: review?(aleth)
(Assignee)

Comment 63

3 years ago
Created attachment 8439887 [details] [diff] [review]
Tests v5

Removed some trailing commas, sorry.
Attachment #8439885 - Attachment is obsolete: true
Attachment #8439885 - Flags: review?(aleth)
Attachment #8439887 - Flags: review?(aleth)

Comment 64

3 years ago
Comment on attachment 8439875 [details] [diff] [review]
Patch v15

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

::: chat/components/src/logger.js
@@ +228,5 @@
> +    lineToWrite = this.encoder.encode(lineToWrite);
> +    queueFileOperation(this.path, () => {
> +      // If writing the header failed, return without writing anything.
> +      if (!this._initialized)
> +        return;

Do we actually need this check? If the header writing failed, the file won't exist, so won't the append fail anyway?

Updated

3 years ago
Attachment #8439887 - Flags: review?(aleth) → review+

Comment 65

3 years ago
Comment on attachment 8439875 [details] [diff] [review]
Patch v15

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

::: chat/components/public/imILogger.idl
@@ +55,4 @@
>  interface imILogger: nsISupports {
> +  // Returns a promise that resolves to an imILog instance.
> +  jsval getLogFromFile(in AUTF8String aFilePath, [optional] in boolean aGroupByDay);
> +  AUTF8String getLogFileForOngoingConversation(in prplIConversation aConversation);

Please add a comment here explaining that the file will be created by this if it does not already exist.
Attachment #8439875 - Flags: review?(aleth) → review-
(Assignee)

Comment 66

3 years ago
Created attachment 8440223 [details] [diff] [review]
Patch v16

I didn't think it made any sense to return a path and queue an operation to create the file, with no guarantee of when the file would exist. So now getLogFileForOngoingConversation (maybe this name should be shortened) returns a promise that will resolve to the path /after the file exists/ or if initializing the log file failed, reject with the same error.

This does not break existing tests, but I'm adding a test for the function in the next Tests patch. Also coming is an updated Tb patch to accommodate this.
Attachment #8439875 - Attachment is obsolete: true
Attachment #8440223 - Flags: review?(aleth)
(Assignee)

Comment 67

3 years ago
Created attachment 8440224 [details] [diff] [review]
Tests v6

Add test for getLogFileForOngoingConversation
Attachment #8439887 - Attachment is obsolete: true
Attachment #8440224 - Flags: review?(aleth)
(Assignee)

Comment 68

3 years ago
Created attachment 8440225 [details] [diff] [review]
Update Thunderbird UI and Gloda v4

Update to accommodate for getLogFileForOngoingConversation now being async.
Attachment #8436253 - Attachment is obsolete: true
Attachment #8436253 - Flags: review?(florian)
Attachment #8440225 - Flags: review?(florian)
(Assignee)

Comment 69

3 years ago
Created attachment 8440229 [details] [diff] [review]
Update Instantbird UI v3

This sets the ShowLogs action's visibility to false first, and asynchronously updates this after getting logs. Seems to work fine, I hope the solution is okay.
Attachment #8433659 - Attachment is obsolete: true
Attachment #8440229 - Flags: review?(aleth)
(Assignee)

Updated

3 years ago
Blocks: 1025464

Comment 70

3 years ago
Comment on attachment 8440223 [details] [diff] [review]
Patch v16

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

::: chat/components/src/logger.js
@@ +147,1 @@
>  }

The behaviour of this is now: if we couldn't write the header, never log anything for this session.

Would it be better to do the following:
1) In the catch on writing the header, after the error message, close the log writer.
2) No this._initialized check (logMessage will fail to write the message if the file doesn't exist)
The behaviour then being that if we fail to write the header, we keep trying. We'll lose some messages but possibly not all (e.g. if a network drive comes back online).

Thoughts?

@@ +273,5 @@
> +  let header = "System log for account " + aAccount.name +
> +               " (" + aAccount.protocol.normalizedName +
> +               ") connected at " +
> +               (new Date()).toLocaleFormat("%c") + kLineBreak;
> +  appendToFile(this.path, this.encoder.encode(header), {create: true}).then(

May need changes to match LogWriter.

@@ +683,5 @@
> +  getLogFileForOngoingConversation: function logger_getLogFileForOngoingConversation(aConversation) {
> +    let writer = getLogWriter(aConversation);
> +    // Wait for the log header to be written if needed.
> +    // If writing the log header failed, this will reject with the same error.
> +    return writer._initialized.then(() => writer.path);

You can use the path queue here if you do decide to drop _initialized.

Alternatively just return the path (synchronous), don't create the log file, and add a check to the gloda file open (to check the file exists). This may be cleanest, but then I haven't looked at the gloda code.

Comment 71

3 years ago
Comment on attachment 8440229 [details] [diff] [review]
Update Instantbird UI v3

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

::: im/content/blist.js
@@ +72,5 @@
>    }
>    else {
> +    let showLogsItem = document.getElementById("context-showlogs");
> +    // Start disabled, then enable if we have logs.
> +    showLogsItem.disabled = true;

Use setAttribute in case the binding doesn't exist yet.

::: im/content/nsContextMenu.js
@@ +167,5 @@
>      // Special-case twitter. XXX Drop this when twitter DMs work.
>      let isTwitter = this.conv.account.protocol.id == "prpl-twitter";
>  
>      addAction("OpenConv", this.onNick && !isTwitter);
> +    addAction("ShowLogs", false);

I'd prefer it if the behaviour was:
1) Add a showLogs item (only) if we're over a nick. Disable it by default
2) Enable it if logs exist (this can then be async as elsewhere)

I think that's more consistent with how we display the show logs menuitem in other context menus.
Attachment #8440229 - Flags: review?(aleth) → review-
(Assignee)

Comment 72

3 years ago
Created attachment 8440276 [details] [diff] [review]
Patch v17

Made changes as discussed on IRC:
- Left the LogWriter stuff as is. No solution seems to be "perfect", this one works for most cases and avoids spamming the error console.
- Made SystemLogWriter consistent with LogWriter on the _initialized stuff.
- Kept getLogFileForOngoingConversation as it is - it makes sense that a consumer that wanted a log file would want it to exist. Also it uses _initialized over the promise queue because we don't want to wait on all pending writes and reads before returning the path.
Attachment #8440223 - Attachment is obsolete: true
Attachment #8440223 - Flags: review?(aleth)
Attachment #8440276 - Flags: review?(aleth)

Comment 73

3 years ago
Comment on attachment 8440276 [details] [diff] [review]
Patch v17

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

Thanks!
Attachment #8440276 - Flags: review?(florian)
Attachment #8440276 - Flags: review?(aleth)
Attachment #8440276 - Flags: review+
(Assignee)

Comment 74

3 years ago
Created attachment 8440280 [details] [diff] [review]
Update Instantbird UI v4

Address review comments.
Attachment #8440229 - Attachment is obsolete: true
Attachment #8440280 - Flags: review?(aleth)
(Assignee)

Comment 75

3 years ago
Created attachment 8440281 [details] [diff] [review]
Update Instantbird UI v5

Add a "Start disabled, then enable if we have logs." in nsContextMenu.js too.
Attachment #8440280 - Attachment is obsolete: true
Attachment #8440280 - Flags: review?(aleth)
Attachment #8440281 - Flags: review?(aleth)

Updated

3 years ago
Attachment #8440224 - Flags: review?(aleth) → review+

Updated

3 years ago
Attachment #8440281 - Flags: review?(aleth) → review+
(Assignee)

Updated

3 years ago
Blocks: 1025522
Comment on attachment 8440276 [details] [diff] [review]
Patch v17

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

r-, but next time I'll only check that my comments have been answered/addressed; not look at the whole diff again.

In some areas I haven't reviewed in details because:
- I assume aleth has already looked
- I assume there's tests covering the behavior.
- The code seemed to just have been moved around without much change.
- I may have already looked during my previous review pass.

::: chat/components/public/imILogger.idl
@@ +56,5 @@
> +  // Returns a promise that resolves to an imILog instance.
> +  jsval getLogFromFile(in AUTF8String aFilePath, [optional] in boolean aGroupByDay);
> +  // If the file doesn't exist, it will be created asynchronously. The promise
> +  // returned will resolve to the file path, or if creating the file failed,
> +  // reject with the same error.

"same error"? Same as what? Maybe you just meant "reject with the error"?

@@ +57,5 @@
> +  jsval getLogFromFile(in AUTF8String aFilePath, [optional] in boolean aGroupByDay);
> +  // If the file doesn't exist, it will be created asynchronously. The promise
> +  // returned will resolve to the file path, or if creating the file failed,
> +  // reject with the same error.
> +  jsval getLogFileForOngoingConversation(in prplIConversation aConversation);

Shouldn't this be named getLogPathForConversation?

What's a use case where "If the file doesn't exist, it will be created asynchronously." is the behavior the caller wants?

::: chat/components/src/logger.js
@@ +55,5 @@
> + * (opening a file multiple times concurrently may fail on Windows).
> + * Note: This function creates parent directories if required.
> + */
> +function appendToFile(aPath, aEncodedString, aOpenOptions = {}) {
> +  aOpenOptions.write = aOpenOptions.append = true;

It may be surprising to callers to find that the aOpenOptions object they passed is modified.
Should we just take a aCreate boolean instead?

@@ +81,3 @@
>  // This function checks names against OS naming conventions and alters them
>  // accordingly so that they can be used as file/folder names.
> +function encodeName(aName) {

Please revert this change throughout the file, and avoid changing the coding style in files that were consistent. Note: already requested in comment 42.

@@ +96,5 @@
>    return aName.replace(/[<>:"\/\\|?*&%]/g, encodeReservedChars);
>  }
>  
> +function getLogFolderPathForAccount(aAccount) {
> +    return OS.Path.join(OS.Constants.Path.profileDir,

wrong indent.

@@ +231,3 @@
>      }
> +    lineToWrite = this.encoder.encode(lineToWrite);
> +    this._initialized.then(() => {

If writing the header takes a while, are we sure that all these functions waiting for this._initialized to resolve will be called in the correct order?

@@ +325,2 @@
>      return;
> +  gSystemLogWritersById.delete(id);

Do you actually need the .has check before a .delete on a Map? If you don't you can simplify this whole function to:
gSystemLogWritersById.delete(aAccount.id);

Same comment for the closeLogWriter function.

@@ +492,5 @@
> +        who: "sessionstart",
> +        date: getDateFromFilename(filename)[0],
> +        text: "",
> +        flags: ["noLog", "notification"]
> +      }

Missing ;
Attachment #8440276 - Flags: review?(florian) → review-
Comment on attachment 8440224 [details] [diff] [review]
Tests v6

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

::: chat/components/src/test/test_logger.js
@@ +22,5 @@
> +  protocol: {
> +    normalizedName: "dummy",
> +    id: "prpl-dummy"
> +  }
> +}

nit: missing ;

Happens several times later too (dummyConv = ..., etc...)

@@ +214,5 @@
> +
> +let test_getLogFolderPathForAccount = function* () {
> +  let path = gLogger.getLogFolderPathForAccount(dummyAccount);
> +  equal(OS.Path.join(logDirPath, dummyAccount.protocol.normalizedName,
> +                            gLogger.encodeName(dummyAccount.normalizedName)), path);

indent.

@@ +220,5 @@
> +
> +let test_getLogFilePathForConversation = function* () {
> +  let path = gLogger.getLogFilePathForConversation(dummyConv, "format");
> +  let expectedPath =  OS.Path.join(logDirPath, dummyAccount.protocol.normalizedName,
> +                              gLogger.encodeName(dummyAccount.normalizedName));

indent

@@ +225,5 @@
> +  expectedPath = OS.Path.join(expectedPath,
> +                              gLogger.encodeName(dummyConv.normalizedName));
> +  expectedPath = OS.Path.join(expectedPath,
> +                              gLogger.getNewLogFileName("format",
> +                                                       dummyConv.startDate));

indent

Note: same indent errors in test_getLogFilePathForMUC and test_getLogFilePathForTwitterConv. Looks like there was an unfinished search & replace.
Comment on attachment 8440225 [details] [diff] [review]
Update Thunderbird UI and Gloda v4

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

::: mail/components/im/modules/index_im.js
@@ +344,5 @@
> +      let fileInfo = yield OS.File.stat(conv.logFile);
> +      let lastModifiedTime = fileInfo.lastModificationDate.valueOf();
> +      if (Object.prototype.hasOwnProperty.call(cache, fileName) &&
> +          cache[fileName] == lastModifiedTime)
> +          return;

wrong indent here.

@@ +471,3 @@
>                                     aJob.conversation.convObj, glodaConv);
> +    // Resolve the promise for this job.
> +    this._indexingJobCallbacks.get(aJob.conversation.id)();

shouldn't you this._indexingJobCallbacks.delete here?
Attachment #8440225 - Flags: review?(florian) → review+
Comment on attachment 8440225 [details] [diff] [review]
Update Thunderbird UI and Gloda v4

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

::: mail/components/im/modules/index_im.js
@@ +276,5 @@
>  
>    _knownConversations: {},
> +  // Promise queue for indexing jobs. The next indexing job is queued using this
> +  // promise's then() to ensure we only load logs for one conv at a time.
> +  _indexingJobPromise: null,

Please ensure this is correctly cleaned up (reset to null) when no longer needed.
(Assignee)

Comment 80

3 years ago
> What's a use case where "If the file doesn't exist, it will be created
> asynchronously." is the behavior the caller wants?

aleth and I discussed this, here are my reasons:
a) If the caller wants the file, it likely has no use for it if the log header hasn't been written yet.
b) If we decide to just return the path synchronously, we could obtain a path without creating a log writer, but this is useless since when a log writer is created, the path that it will use will be different (since the filename is time-dependent). If we do create the log writer, it will create the file anyway, so it makes sense IMO to give it to the consumer after that's done.

> @@ +81,3 @@
> >  // This function checks names against OS naming conventions and alters them
> >  // accordingly so that they can be used as file/folder names.
> > +function encodeName(aName) {
> Please revert this change throughout the file, and avoid changing the coding
> style in files that were consistent. Note: already requested in comment 42.

Sorry, I forgot to respond to this. FYI though, the coding style wasn't consistent (https://mxr.mozilla.org/comm-central/source/chat/components/src/logger.js#473, 488, #509, #576) so I figured I'd go with the convention that we follow now. Please let me know if you still want me to make it consistently "brace on new line" everywhere.

> @@ +231,3 @@
> >      }
> > +    lineToWrite = this.encoder.encode(lineToWrite);
> > +    this._initialized.then(() => {
> 
> If writing the header takes a while, are we sure that all these functions
> waiting for this._initialized to resolve will be called in the correct order?

As per the Promises/A+ spec, callbacks added using then() will be called in the order that they were added. So yes, we're sure. (https://promises-aplus.github.io/promises-spec/#point-37)

Comment 81

3 years ago
(In reply to Florian Quèze [:florian] [:flo] from comment #76)
> > +  jsval getLogFileForOngoingConversation(in prplIConversation aConversation);
> 
> Shouldn't this be named getLogPathForConversation?

FYI this annoying function is only used by the gloda indexing code.
(Assignee)

Comment 82

3 years ago
Created attachment 8440430 [details] [diff] [review]
Patch v18

Address review comments.
Attachment #8440276 - Attachment is obsolete: true
Attachment #8440430 - Flags: review?(florian)
(Assignee)

Comment 83

3 years ago
Created attachment 8440434 [details] [diff] [review]
Tests v7

Address review comments
Attachment #8440224 - Attachment is obsolete: true
Attachment #8440434 - Flags: review?(florian)
(Assignee)

Comment 84

3 years ago
Created attachment 8440437 [details] [diff] [review]
Update Thunderbird UI and Gloda v5

Address review comments.
Re. http://log.bezut.info/instantbird/140615/#m463, that's executed outside of the Task so another one isn't needed as far as I can tell.
Attachment #8440225 - Attachment is obsolete: true
Attachment #8440437 - Flags: review?(florian)
(Assignee)

Comment 85

3 years ago
Created attachment 8440876 [details] [diff] [review]
Patch v19

The return statement in the previous patch wouldn't work because just "return" was in its own line - so the function would always return undefined. This fixes the issue.
Attachment #8440430 - Attachment is obsolete: true
Attachment #8440430 - Flags: review?(florian)
Attachment #8440876 - Flags: review?(florian)
(Assignee)

Comment 86

3 years ago
Created attachment 8440877 [details] [diff] [review]
Tests v8

Update to accommodate for getLogFileForOngoingConversation -> getLogPathForConversation. Sorry I missed this.
Attachment #8440434 - Attachment is obsolete: true
Attachment #8440434 - Flags: review?(florian)
Attachment #8440877 - Flags: review?(florian)
(Assignee)

Comment 87

3 years ago
Created attachment 8441340 [details] [diff] [review]
Update Instantbird UI v6

This patch got bitrotted. I just had to manually add back a few lines from the diff so carrying forward the r+.
Attachment #8440281 - Attachment is obsolete: true
Attachment #8441340 - Flags: review+
Comment on attachment 8440876 [details] [diff] [review]
Patch v19

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

::: chat/components/src/logger.js
@@ +54,5 @@
> + * for reading while it's already open for writing, so we close it every time
> + * (opening a file multiple times concurrently may fail on Windows).
> + * Note: This function creates parent directories if required.
> + */
> +function appendToFile(aPath, aEncodedString, aCreate) {

I would make aCreate's default value false. Or does OS.File.open expect undefined?
Attachment #8440876 - Flags: review?(florian) → review+
Comment on attachment 8440877 [details] [diff] [review]
Tests v8

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

I haven't done an actual review of this test, but I'm happy for it to land with aleth's review.

::: chat/components/src/test/test_logger.js
@@ +183,5 @@
> +  let qFO = gLogger.queueFileOperation;
> +
> +  // Immediately after calling qFO, "path1" should be mapped to p1.
> +  // After yielding, the reference should be cleared from the map.
> +  let p1 =  qFO("path1", dummyResolvedOperation);

nit: double space here.

@@ +220,5 @@
> +
> +// Tests the global function getLogFilePathForConversation in logger.js.
> +let test_getLogFilePathForConversation = function* () {
> +  let path = gLogger.getLogFilePathForConversation(dummyConv, "format");
> +  let expectedPath =  OS.Path.join(logDirPath, dummyAccount.protocol.normalizedName,

double space here.
Attachment #8440877 - Flags: review?(florian) → feedback+
Comment on attachment 8440437 [details] [diff] [review]
Update Thunderbird UI and Gloda v5

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

Thanks!

::: mail/components/im/modules/index_im.js
@@ +369,3 @@
>      // Now clear the job, so we can index in the future.
>      this._knownConversations[convId].scheduledIndex = null;
> +

Is there a reason to add an empty line here?
Attachment #8440437 - Flags: review?(florian) → review+
(Assignee)

Comment 91

3 years ago
Created attachment 8441783 [details] [diff] [review]
Tests v8.1

Fix double-spaces, carrying forward the r+.
Attachment #8440877 - Attachment is obsolete: true
Attachment #8441783 - Flags: review+
(Assignee)

Comment 92

3 years ago
Created attachment 8441784 [details] [diff] [review]
Update Thunderbird UI and Gloda v5.1

Remove extra newline, update commit message.
Attachment #8440437 - Attachment is obsolete: true
Attachment #8441784 - Flags: review+
(Assignee)

Comment 93

3 years ago
Created attachment 8441785 [details] [diff] [review]
Patch v19.1

Updated commit message, carrying forward the r+.
Attachment #8440876 - Attachment is obsolete: true
Attachment #8441785 - Flags: review+
(Assignee)

Comment 94

3 years ago
Created attachment 8445003 [details] [diff] [review]
Patch v20

Ensure that we sort the entries in the constructor of a Log. Discovered from running tests on try that we cannot depend on DirectoryIterator to enumerate entries in any particular order.
This also removes a stray redundant line that crept up somewhere around patch 10 or 11.
Attachment #8441785 - Attachment is obsolete: true
Attachment #8445003 - Flags: review?(florian)
(Assignee)

Comment 95

3 years ago
Created attachment 8445006 [details] [diff] [review]
Tests v9

Discovered a flaw from running tests on try - because we weren't waiting for logWriter._initialized, we were guaranteed only that the log header had been written when reading the logs.
Attachment #8441783 - Attachment is obsolete: true
Attachment #8445006 - Flags: review?(florian)

Comment 96

3 years ago
Comment on attachment 8445003 [details] [diff] [review]
Patch v20

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

Good catch :)
Attachment #8445003 - Flags: review?(florian) → review+

Comment 97

3 years ago
Comment on attachment 8445006 [details] [diff] [review]
Tests v9

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

Thanks for fixing this. You can carry the r+ forward when you improve the comment.
Attachment #8445006 - Flags: review?(florian) → review+
(Assignee)

Comment 98

3 years ago
Created attachment 8445380 [details] [diff] [review]
Patch v21

This waits for all queued I/O promises during AsyncShutdown.
Sorry for missing this in the previous patches.
Attachment #8445003 - Attachment is obsolete: true
Attachment #8445380 - Flags: review?(aleth)
(Assignee)

Comment 99

3 years ago
Created attachment 8445404 [details] [diff] [review]
Patch v21.1

Change async shutdown blocker name, fix comment, make a couple of always-used imports non-lazy
Attachment #8445380 - Attachment is obsolete: true
Attachment #8445380 - Flags: review?(aleth)
Attachment #8445404 - Flags: review?(florian)
Comment on attachment 8445404 [details] [diff] [review]
Patch v21.1

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

Ship it! :-)
Attachment #8445404 - Flags: review?(florian) → review+
(Assignee)

Comment 101

3 years ago
Created attachment 8446463 [details] [diff] [review]
Tests v9.1

Update a comment, carrying forward the r+.
Attachment #8445006 - Attachment is obsolete: true
Attachment #8446463 - Flags: review+
(Assignee)

Updated

3 years ago
Keywords: checkin-needed

Comment 102

3 years ago
(In reply to Nihanth Subramanya [:nhnt11] from comment #98)
> This waits for all queued I/O promises during AsyncShutdown.
> Sorry for missing this in the previous patches.

Good catch! We discussed this right at the beginning and then forgot about it as OS.File takes care of itself...
(Assignee)

Comment 103

3 years ago
https://hg.mozilla.org/comm-central/rev/1c2ff401d92a
https://hg.mozilla.org/comm-central/rev/3d0f06e04096
https://hg.mozilla.org/comm-central/rev/347ed18a5866
https://hg.mozilla.org/comm-central/rev/946e17f54a95
Target Milestone: --- → 1.6
(Assignee)

Updated

3 years ago
Status: ASSIGNED → RESOLVED
Last Resolved: 3 years ago
Keywords: checkin-needed
Resolution: --- → FIXED

Updated

3 years ago
Duplicate of this bug: 1024982
(Assignee)

Updated

3 years ago
Depends on: 1135291
You need to log in before you can comment on or make changes to this bug.