1830368 - Fix app.update.log.file

Status: RESOLVED FIXED

(Toolkit :: Application Update, defect)

Description

[Robin Steuber (she/her) [:bytesized]]

We don't use app.update.log.file much, but it seems like it would actually help troubleshoot a problem that a user is currently having. But when I tested it out to make sure that it works the way that I thought it did, it seems to be quite broken. When I turn it on for a couple browser sessions, I seem to end up with, at different points, update_messages.log, update_messages-1.log, and update_messages-2.log. But it seems like update_messages.log is eventually lost completely and I never see update_messages_old.log, like I would expect to from this code.

To make matters substantially worse, update_messages.log seems to contain a comma-separated list of integers rather than log messages. It kinda seems like the integers may correspond to ASCII values encoding a log message? I can get, like, fragments of valid-looking messages by decoding it, but it doesn't seem to be straight-forward enough to allow for a simple translation. It seems like sometimes the issue is that multiple lists were concatenated together with no separator, causing the integers at the ends to run together. I'm suspicious that this isn't the only weirdness going on, but I'm not really able to spend a lot of time figuring out what at the moment.

I believe that the list of integers problem is the result of this encoding:

let encoded = new TextEncoder().encode(string + "\n");

If I open the Browser Console and run

new TextEncoder().encode("Creating UpdateService\n").toString() 

The first bit of the output matches the first bit of what I am seeing in the file. I'm not sure why the whole string doesn't match. Like I said, I think that there may be more weirdness going on here, but it's hard to dig deeper without actually fixing some of this.

Comment 1

[Robin Steuber (she/her) [:bytesized]]

I'm hoping to fix up this issue real quick. I was originally thinking that while I was here, I'd replace the usage of FileUtils.openAtomicFileOutputStream with something from IOUtils. But I asked into it and was told that IOUtils does not allow write handles to be left open and that there is no equivalent to this function. I was advised to simply continue to use FileUtils.openAtomicFileOutputStream.

Comment 2

[Masatoshi Kimura [:emk]]

We will have to create a nsIBinaryOutputStream instance such as https://searchfox.org/mozilla-central/rev/f29deb388a7675b93f040b0e89a37822cdbd8d58/toolkit/mozapps/extensions/internal/XPIInstall.jsm#1079-1085.

Comment 3

[Robin Steuber (she/her) [:bytesized]]

(In reply to Masatoshi Kimura [:emk] from comment #2)

We will have to create a nsIBinaryOutputStream instance such as https://searchfox.org/mozilla-central/rev/f29deb388a7675b93f040b0e89a37822cdbd8d58/toolkit/mozapps/extensions/internal/XPIInstall.jsm#1079-1085.

Why do we need to do that? Is that preferable over the existing FileUtils.openAtomicFileOutputStream call? Does that address the existing issue somehow? I had thought that the issue we were having was with the encode line, not the output line.

Comment 4

[Masatoshi Kimura [:emk]]

FileUtils.openAtomicFileOutputStream will still be used. Pass the return value from FileUtils.openAtomicFileOutputStream to nsIBinaryOutputStream.setStream. Since nsIOutputStream.write takes a string parameter, JS callers cannot pass a string directly without lossy conversion.

Comment 5

[Robin Steuber (she/her) [:bytesized]]

Attachment: Bug 1830368 - Fix app.update.log.file r=nalexander!

This fix ended up being a lot more involved than I hoped because one of the issues with the current code is that it currently tries to open two handles to the same file by just opening the file twice. Which is not the interface works. So I fixed this by centralizing the file access by splitting all of the update logging out into its own module.

Comment 6

[Pulsebot]

Pushed by [e-mail]:
https://hg.mozilla.org/integration/autoland/rev/b45323e4bc6e
Fix app.update.log.file r=nalexander,application-update-reviewers

Comment 7

[Atila Butkovits]

https://hg.mozilla.org/mozilla-central/rev/b45323e4bc6e

Comment 8

[Magnus Melin [:mkmelin]]

Can we uplift this to 115? Was just looking at an update log for 115 ESR, and it's useless due to this bug.

Comment 9

[Robin Steuber (she/her) [:bytesized]]

(In reply to Magnus Melin [:mkmelin] from comment #8)

Can we uplift this to 115? Was just looking at an update log for 115 ESR, and it's useless due to this bug.

Could you explain further why this is needed on ESR? I work on update issues a lot and I still use (or ask others to use) app.update.log.file so rarely that I wouldn't be surprised if it was broken for years before I noticed the problem. Generally app.update.log is sufficient.

Is there a specific bug on ESR115 that would benefit from this feature? Is it a part of some workflow that I'm unfamiliar with?

Comment 10

[Magnus Melin [:mkmelin]]

I'm not looking at it often. This was in context of investigating bug 1866991. It's quite possible that log wouldn't have the info needed, idk.
Why 115 is because Thunderbird is built on esr...

Comment 11

[Robin Steuber (she/her) [:bytesized]]

I don't feel like there is a compelling reason to uplift this. It's a largish patch that doesn't appear to graft cleanly on to ESR. I think that uplift would require some investigation into whether or not the patch would cause any problems on ESR115. And reading Bug 1866991, it seems like the reporter was asked to use app.update.log, used app.update.log.file instead, and eventually figured out on their own how to open the console and get the logs that they needed without this patch.

So, for the time being at least, I'm inclined to say that an uplift is not warranted here.