1239686 - Add ability to set log file at runtime

Status: RESOLVED FIXED

(Core :: Networking, defect)

Description

[Valentin Gosu [:valentin] (he/him)]

Setting environment variables or even prefs to turn on logging is a bit cumbersome for non-technical users.
A bit better would be a section in about:networking with a button to turn on logging, and maybe a few checkboxes to enable/disable common necko modules.

Use case:
Go to about:networking
Click on Logging tab
Enable required modules
Click on Start Logging
Reproduce bug
Click on Stop Logging
Upload logs to bug.

Comment 1

[Valentin Gosu [:valentin] (he/him)]

Attachment: Add method to set logging file at runtime

Comment 2

[Valentin Gosu [:valentin] (he/him)]

Attachment: Add UI to about:networking to turn on logging modules at runtime

Comment 3

[Jared Wein [:jaws] (please needinfo? me)]

Comment on attachment 8709103 [details] [diff] [review]
Add UI to about:networking to turn on logging modules at runtime

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

r- because 36 checkboxes doesn't scale. We'll need a more usable UI if we want to add this to make this page more approachable for non-Gecko devs.

::: toolkit/content/aboutNetworking.js
@@ +10,5 @@
>  
>  const gDashboard = Cc['@mozilla.org/network/dashboard;1'].
>    getService(Ci.nsIDashboard);
> +const gPrefs = Cc["@mozilla.org/preferences-service;1"]
> +                 .getService(Ci.nsIPrefService).getBranch("");

I would prefer if you used Services.prefs.* here instead of the root pref branch of nsIPrefService.

@@ +216,5 @@
> +  for (let i in gNetLogModules) {
> +    if (i % 3 == 0) {
> +      tr = document.createElement("tr");
> +    }
> +    let td = document.createElement("td");

We need a better UI than 36 checkboxes for the different types of logs. If this UI that you are adding is supposed to make about:networking easier to use non-technical users then it needs to group some of these logs in to some categories.

How is a non-technical user supposed to know the difference between nsRtspChild and nsRtsp for example? What is the difference between "proxy" and "nsRequestObserverProxy"?

This should be broken in to at most 7 different categories, and they need to be generic names not specific to the Gecko codebase. I don't know enough about what each one does here to help you with this exercise.

@@ +223,5 @@
> +    input.type = "checkbox";
> +    input.name = gNetLogModules[i].name;
> +    input.classList.add("logModule");
> +    if (gNetLogModules[i].checked) {
> +      input.checked = true;

Should these checkboxes be persisted so that on the next load of this page the user won't have to select which items they want logged again?

@@ +246,5 @@
> +
> +  disableLogging();
> +}
> +
> +function getenv(name) {

This function is empty and should be removed.

@@ +259,5 @@
> +    gPrefs.clearUserPref("logging."+prefName);
> +  }
> +  gLogging = false;
> +  let button = document.getElementById("logButton");
> +  button.textContent = "Start Logging";

This string should be localized, along with "Log path:" and "Stop Logging".

@@ +291,5 @@
> +  }
> +
> +  if (logFile) {
> +    let logPathElement = document.getElementById("log_path");
> +    logPathElement.textContent = "Log path: "+logFile.path;

nit, space around binary operators.

::: toolkit/content/aboutNetworking.xhtml
@@ +31,5 @@
>              <button class="menu" value="sockets">&aboutNetworking.sockets;</button>
>              <button class="menu" value="dns">&aboutNetworking.dns;</button>
>              <button class="menu" value="websockets">&aboutNetworking.websockets;</button>
>              <hr/>
> +            &aboutNetworking.diagnostics;:

The colon should be part of the localized string.

@@ +102,5 @@
>              </table>
>          </div>
> +
> +        <div id="logging" class="tab" hidden="true">
> +            <button id="logButton" style="float:left"> Start Logging </button>

This inline style should be moved to a style sheet, and the button text should be in the DTD file.

Comment 4

[Valentin Gosu [:valentin] (he/him)]

(In reply to Jared Wein [:jaws] (please needinfo? me) from comment #3)
> Comment on attachment 8709103 [details] [diff] [review]
> Add UI to about:networking to turn on logging modules at runtime
> 
> Review of attachment 8709103 [details] [diff] [review]:
> -----------------------------------------------------------------
> 
> r- because 36 checkboxes doesn't scale. We'll need a more usable UI if we
> want to add this to make this page more approachable for non-Gecko devs.
> 
> We need a better UI than 36 checkboxes for the different types of logs. If
> this UI that you are adding is supposed to make about:networking easier to
> use non-technical users then it needs to group some of these logs in to some
> categories.
> 

What would you suggest for a better UI?
Already this is much better than https://developer.mozilla.org/en-US/docs/Mozilla/Debugging/HTTP_logging
which involves setting env variables.
Your average user will just have to click the button, and then upload the logs.
When instructed by a Gecko dev, he might also check some of the other log modules.

> How is a non-technical user supposed to know the difference between
> nsRtspChild and nsRtsp for example? What is the difference between "proxy"
> and "nsRequestObserverProxy"?
> 
> This should be broken in to at most 7 different categories, and they need to
> be generic names not specific to the Gecko codebase. I don't know enough
> about what each one does here to help you with this exercise.

By definition, the names are specific to the Gecko codebase. I don't know if what every module does needs to be clear to the user.
Also, we the ability to select each module individually is quite important.

Comment 5

[Eric Rahm [:erahm]]

Comment on attachment 8709102 [details] [diff] [review]
Add method to set logging file at runtime

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

This is a great start and I'm excited to see this feature, I think it'll be really helpful for debugging end-user issues.

There are a few points we should discuss before settling on an implementation, I added notes inline for most of those.

I have an overall concern that a user might enable network logging, close the browser, and forget they have it enabled. Then we'll end up filling their disk with logs (and generally impact performance). We might be able to mitigate that by adding a shutdown observer in the network config code that gets registered when enabling logging. Then when shutting down we could clear the prefs that were changed and clear the log file name as well. Perhaps there's a better way to handle this, let me know what you think.

::: xpcom/base/LogModulePrefWatcher.cpp
@@ +34,5 @@
>  
>    int32_t prefLevel = 0;
>    nsAutoCString prefStr;
>  
> +  if (strncmp(aName, "logging.LOG_FILE", 16) == 0) {

|strcmp| is more appropriate (we don't want to match "logging.LOG_FILE_FOO").

I can imagine other configuration options being necessary in the future, perhaps we should nest all options under the "logging.config." prefix?

@@ +37,5 @@
>  
> +  if (strncmp(aName, "logging.LOG_FILE", 16) == 0) {
> +    if (Preferences::GetCString(aName, &prefStr) == NS_OK) {
> +      if (XRE_IsContentProcess()) {
> +        prefStr.Append(".child-");

This differs a little bit from what we do in |GeckoChildProcessHost| [1] where we increment an integer to differentiate child logs.

That code runs in the parent process where there isn't a child pid yet so there's not much choice. On the other hand for this branch we're already in the child so we don't have access to that number AFAICT. It's possible that could be forwarded with an env var or a command-line param, but I'm not sure it's worth the effort to have parity.

If we stick with the PID we should make a note that it differs slightly from the |NSPR_LOG_FILE=foo| case.

[1] https://dxr.mozilla.org/mozilla-central/rev/8cb42e7a16b42162c9930f37b9e1f820c2eb126b/ipc/glue/GeckoChildProcessHost.cpp#486-503

@@ +42,5 @@
> +#ifdef XP_PC
> +        prefStr.AppendInt(_getpid());
> +#else
> +        prefStr.AppendInt(getpid());
> +#endif

If we go this route let's just use |base::GetCurrentProcId()| from "base/process_util.h"

@@ +45,5 @@
> +        prefStr.AppendInt(getpid());
> +#endif
> +      }
> +
> +      LogModule::SetLogFile(prefStr.BeginReading(), true, true);

nit: Add a comment to the bool args, ie: /* append = */ true.

I'm a little concerned defaulting to append. For the networking use case the logs are quite verbose and we could end up with *huge* files after a few sessions. I don't think it would be obvious to end user who is clicking a button how large these really would be.

It might be better to nest the choice to turn on appending and timestamping under the "logging.config." namespace and parse them out. That could be a follow up if you'd like, in that case lets default to false for now.

::: xpcom/base/Logging.cpp
@@ +121,5 @@
>      const char* logFile = PR_GetEnv("NSPR_LOG_FILE");
> +    SetLogFile(logFile, shouldAppend, addTimestamp);
> +  }
> +
> +  bool SetLogFile(const char* aFilename, bool aShouldAppend, bool aAddTimestamp)

Rather than passing a param, we should just set |mAddTimestamp| separately with new setter, ie |LogModuleManager::SetAddTimestamp|.

We'll need to make mAddTimestamp |Atomic| as well.

@@ +130,5 @@
>      }
> +
> +    // Open the output file.
> +    if (aFilename && aFilename[0]) {
> +      mOutFile = fopen(aFilename, aShouldAppend ? "a" : "w");

We'll need to make |mOutFile| Atomic.

::: xpcom/base/Logging.h
@@ +79,5 @@
> +   * already set.
> +   */
> +  static bool SetLogFile(const char* aFilename,
> +                         bool aShouldAppend = false,
> +                         bool aAddTimestamp = false);

See note above about |aAddTimestamp|.

Comment 6

[Valentin Gosu [:valentin] (he/him)]

(In reply to Eric Rahm [:erahm] from comment #5)
> I have an overall concern that a user might enable network logging, close
> the browser, and forget they have it enabled. Then we'll end up filling
> their disk with logs (and generally impact performance). We might be able to
> mitigate that by adding a shutdown observer in the network config code that
> gets registered when enabling logging. Then when shutting down we could
> clear the prefs that were changed and clear the log file name as well.
> Perhaps there's a better way to handle this, let me know what you think.
> 

That's a very good point. Even so, I think a shutdown observer might not be enough, in case a crash happens while user logging is enabled.
Maybe we could clear the prefs at startup? Or set logging.config.clear_on_startup which causes the modules be cleared on startup?

> I can imagine other configuration options being necessary in the future,
> perhaps we should nest all options under the "logging.config." prefix?

I agree, this seems much better.

> > +        prefStr.Append(".child-");
> 
> This differs a little bit from what we do in |GeckoChildProcessHost| [1]
> where we increment an integer to differentiate child logs.
> 
> That code runs in the parent process where there isn't a child pid yet so
> there's not much choice. On the other hand for this branch we're already in
> the child so we don't have access to that number AFAICT. It's possible that
> could be forwarded with an env var or a command-line param, but I'm not sure
> it's worth the effort to have parity.
> 
> If we stick with the PID we should make a note that it differs slightly from
> the |NSPR_LOG_FILE=foo| case.

Right. We could in fact append .pid-1234 instead of .child-1234 to emphasize the difference.
Or we could set another env var with the process index when creating the process. That's sounds like a fair solution. I'll stick with the PID for now, and leave that for a follow-up bug if we decide it's worth it.

> It might be better to nest the choice to turn on appending and timestamping
> under the "logging.config." namespace and parse them out. That could be a
> follow up if you'd like, in that case lets default to false for now.

Very good points. Sounds much better that way.

Thanks for the feedback. Very helpful.

Comment 7

[Jared Wein [:jaws] (please needinfo? me)]

(In reply to Valentin Gosu [:valentin] from comment #4)
> (In reply to Jared Wein [:jaws] (please needinfo? me) from comment #3)
> > Comment on attachment 8709103 [details] [diff] [review]
> > Add UI to about:networking to turn on logging modules at runtime
> > 
> > Review of attachment 8709103 [details] [diff] [review]:
> > -----------------------------------------------------------------
> > 
> > r- because 36 checkboxes doesn't scale. We'll need a more usable UI if we
> > want to add this to make this page more approachable for non-Gecko devs.
> > 
> > We need a better UI than 36 checkboxes for the different types of logs. If
> > this UI that you are adding is supposed to make about:networking easier to
> > use non-technical users then it needs to group some of these logs in to some
> > categories.
> > 
> 
> What would you suggest for a better UI?
> Already this is much better than
> https://developer.mozilla.org/en-US/docs/Mozilla/Debugging/HTTP_logging
> which involves setting env variables.
> Your average user will just have to click the button, and then upload the
> logs.
> When instructed by a Gecko dev, he might also check some of the other log
> modules.

One way to make this a better UI would be to only show the options that are enabled by default. I count four logs (nsStreamPump, nsSocketTransport, nsHostResolver, and nsHttp) that are enabled by default. Those four should be visible with a checkbox next to them. The rest of the logs should be hidden behind a "Advanced options" which when clicked on shows the rest of them. Further, they should all be alphabetically sorted. If I was really dreaming, they would have consistent naming schemes so we wouldn't e mixing "nsFoo", "FooBar", and "foo" naming conventions.

A different way to make this better UI would be to categorize the logs in to seven groups, as described in my review. Each group could have a checkbox for the group that enables all of the logging for that group, or the ability to enable individual logs within the group. The individual logs of the group would be hidden unless the category is expanded.
 
> > How is a non-technical user supposed to know the difference between
> > nsRtspChild and nsRtsp for example? What is the difference between "proxy"
> > and "nsRequestObserverProxy"?
> > 
> > This should be broken in to at most 7 different categories, and they need to
> > be generic names not specific to the Gecko codebase. I don't know enough
> > about what each one does here to help you with this exercise.
> 
> By definition, the names are specific to the Gecko codebase. I don't know if
> what every module does needs to be clear to the user.
> Also, we the ability to select each module individually is quite important.

I understand that to a developer it may be nice if the names are specific to the Gecko codebase, but I don't think it is important to surface these names as-is to end-users. We could create a simple conversion method that would make these all have a consistent naming convention. It could look like this:
function convergeName(name) {
  if (name.startsWith("ns")) {
    name = name.slice(2);
  }
  return name[0].toUpperCase() + name.slice(1);
}
We could keep set the `title` attribute on the label to the original name.

(In reply to Eric Rahm [:erahm] from comment #5)
> I have an overall concern that a user might enable network logging, close
> the browser, and forget they have it enabled. Then we'll end up filling
> their disk with logs (and generally impact performance). We might be able to
> mitigate that by adding a shutdown observer in the network config code that
> gets registered when enabling logging. Then when shutting down we could
> clear the prefs that were changed and clear the log file name as well.
> Perhaps there's a better way to handle this, let me know what you think.

We shouldn't be adding things to do on shutdown and probably not on start-up either. Maybe a delayed startup task may work though.

This question brings up a good point though. What type of size limit do these logs have? What happens when that limit is reached? These logs should probably be circular buffers, only keeping the last X megabytes of data (5mb may be plenty). We could allow a user to override the limit with their own value, but choose a sensible value for 80% of users.

Comment 8

[Valentin Gosu [:valentin] (he/him)]

https://treeherder.mozilla.org/#/jobs?repo=try&revision=55a81eda06e1

Comment 9

[Valentin Gosu [:valentin] (he/him)]

Eric, I ran into some issues with my plan for clearing the prefs at startup. It turns out that at startup the preferences aren't actually loaded, but they're updated when the observer is called.
So LoadExistingPrefs() in LogModulePrefWatcher doesn't really do anything, and we can remove it.
I'm now trying to find a different way of not logging after restart, in cases such as a crash, etc.
Do you think deferring the logPrefWatcher until browser-delayed-startup-finished or xpcom-startup is a good idea?

Comment 10

[Eric Rahm [:erahm]]

(In reply to Jared Wein [:jaws] (please needinfo? me) from comment #7)
> 
> We shouldn't be adding things to do on shutdown and probably not on start-up
> either. Maybe a delayed startup task may work though.

Perhaps I'm missing something, but why not? In this case we're just talking about clearing a pref.

> This question brings up a good point though. What type of size limit do
> these logs have? What happens when that limit is reached? These logs should
> probably be circular buffers, only keeping the last X megabytes of data (5mb
> may be plenty). We could allow a user to override the limit with their own
> value, but choose a sensible value for 80% of users.

There currently is no limit. This sounds like a reasonable request, could you file a bug? I think it would help to measure the actual size of the log file when network logging is enabled. My guess is that it's much larger than 5MB.

Comment 11

[Eric Rahm [:erahm]]

(In reply to Valentin Gosu [:valentin] from comment #9)
> Eric, I ran into some issues with my plan for clearing the prefs at startup.
> It turns out that at startup the preferences aren't actually loaded, but
> they're updated when the observer is called.
> So LoadExistingPrefs() in LogModulePrefWatcher doesn't really do anything,
> and we can remove it.

For content processes I believe LoadExistingPrefs actually does something, of course we should probably verify that. I'm not sure about B2G.

> I'm now trying to find a different way of not logging after restart, in
> cases such as a crash, etc.
> Do you think deferring the logPrefWatcher until
> browser-delayed-startup-finished or xpcom-startup is a good idea?

This gets tricky. Is there a startup path in the logging config we could use to clear it? I don't think it would be the end of the world if we logged a bit extra during startup after a crash. Combined with :jaws suggestion of limiting log file sizes this might be enough.

Comment 12

[Jared Wein [:jaws] (please needinfo? me)]

(In reply to Eric Rahm [:erahm] from comment #10)
> (In reply to Jared Wein [:jaws] (please needinfo? me) from comment #7)
> > 
> > We shouldn't be adding things to do on shutdown and probably not on start-up
> > either. Maybe a delayed startup task may work though.
> 
> Perhaps I'm missing something, but why not? In this case we're just talking
> about clearing a pref.

Sorry, I misread your comment #5 and thought you were implying we should clear the log on shutdown. Re-reading it, you were just saying clear the pref and the log file name.

Comment 13

[Jared Wein [:jaws] (please needinfo? me)]

(In reply to Eric Rahm [:erahm] from comment #10)
> > This question brings up a good point though. What type of size limit do
> > these logs have? What happens when that limit is reached? These logs should
> > probably be circular buffers, only keeping the last X megabytes of data (5mb
> > may be plenty). We could allow a user to override the limit with their own
> > value, but choose a sensible value for 80% of users.
> 
> There currently is no limit. This sounds like a reasonable request, could
> you file a bug? I think it would help to measure the actual size of the log
> file when network logging is enabled. My guess is that it's much larger than
> 5MB.

Filed bug 1244306.

Comment 14

[Valentin Gosu [:valentin] (he/him)]

Attachment: Add method to set logging file at runtime

Comment 15

[Eric Rahm [:erahm]]

(In reply to Valentin Gosu [:valentin] from comment #14)
> Created attachment 8717320 [details] [diff] [review]
> Add method to set logging file at runtime

Sorry for the delay, I'll get to this today. I have a high level concern that we need to be careful about closing the log handle when clearing the log after restart (atomicity might not be enough). I'll take a closer look in a bit.

Comment 16

[Eric Rahm [:erahm]]

Comment on attachment 8717320 [details] [diff] [review]
Add method to set logging file at runtime

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

::: modules/libpref/init/all.js
@@ +130,5 @@
>  pref("dom.fileHandle.enabled", true);
>  
> +// Whether changes to prefs in the logging
> +// branch should be persisted after restarting.
> +pref("logging.config.persist_restart", false);

I think we might want the default to be true. As a dev I wouldn't want to reset this each time I launch.

On the other hand as a dev I could probably just use env vars, so I don't feel to strongly about this. We'll just have to make sure we document it clearly (once we add actual docs for logging).

::: xpcom/base/LogModulePrefWatcher.cpp
@@ +81,5 @@
> +      bool addTimestamp = Preferences::GetBool(aName, false);
> +      LogModule::SetAddTimestamp(addTimestamp);
> +    } else if (prefName.EqualsLiteral(kLoggingPrefShouldAppend)) {
> +      bool shouldAppend = Preferences::GetBool(aName, false);
> +      LogModule::SetShouldAppend(shouldAppend);

So we get into a possible race with |SetLogFile| here, |ShouldAppend| needs to be called first. I can't think of a particularly graceful way around this other than just adding a modifier to the log file string. For example if "+" is at the end of log file we would open in append mode, so:
  my_log_file.txt+ <== append mode
  my_log_file.txt  <== overwrite

I don't have a strong opinion on the format, just that it needs to be grouped.

::: xpcom/base/Logging.cpp
@@ +103,5 @@
> +  }
> +
> +  void CloseLogFile()
> +  {
> +    if (mOutFile) {

Synchronization might be a problem here. If we have thread A closing the log file and thread B logging we can get into several weird situation where:

#1 - thread A closes the handle
   - thread B grabs a copy of the now closed handle, uses it
   - thread A clears the handle

#2 - thread B grabs a copy of the handle
   - thread A closes the handle
   - thread B uses its copy of the now closed handle

Which is all to say, I think Atomic probably won't suffice here and we'll need to lock if we want to support changing the log file at runtime.

So roughly we could do:
thread A:
  Lock(logFile) {
    fclose(logFile);
    logFile = nullptr;
  }

thread B:
  copy_of_fd;
  Lock(logFile) {
    copy_of_fd = dup(fileno(logfile));
  }

  // do stuff with copy
  fclose(copy_of_fd) 

Let me know if that doesn't make sense.

@@ +144,5 @@
>      const char* logFile = PR_GetEnv("NSPR_LOG_FILE");
> +    SetLogFile(logFile);
> +  }
> +
> +  bool SetLogFile(const char* aFilename)

This should include the append flag as a param as well.

@@ +190,5 @@
> +  {
> +    mAddTimestamp = aAddTimestamp;
> +  }
> +
> +  void SetShouldAppend(bool aShouldAppend)

As noted above, I think we should just fold this into SetLogFile.

@@ +303,3 @@
>    PRThread *mMainThread;
> +
> +  Atomic<FILE*> mOutFile;

If we add a lock this wouldn't need to be Atomic.

@@ +303,5 @@
>    PRThread *mMainThread;
> +
> +  Atomic<FILE*> mOutFile;
> +  Atomic<bool>  mAddTimestamp;
> +  Atomic<bool>  mShouldAppend;

We probably don't need to keep this as a member if we fold it into |SetLogFile|.

@@ +305,5 @@
> +  Atomic<FILE*> mOutFile;
> +  Atomic<bool>  mAddTimestamp;
> +  Atomic<bool>  mShouldAppend;
> +  Atomic<char*> mLogPath;
> +  Atomic<bool>  mIsSync;

The remaining Atomics can probably be Relaxed, but lets focus on the other parts first.

::: xpcom/base/Logging.h
@@ +83,5 @@
> +
> +  /**
> +   * Returns a new string containing the previously set logging file.
> +   */
> +  static char * GetLogFile();

This probably isn't needed.

Comment 17

[Valentin Gosu [:valentin] (he/him)]

(In reply to Eric Rahm [:erahm] (Out until 3/10) from comment #16)
> Which is all to say, I think Atomic probably won't suffice here and we'll
> need to lock if we want to support changing the log file at runtime.
> 
> So roughly we could do:
> thread A:
>   Lock(logFile) {
>     fclose(logFile);
>     logFile = nullptr;
>   }
> 
> thread B:
>   copy_of_fd;
>   Lock(logFile) {
>     copy_of_fd = dup(fileno(logfile));
>   }
> 
>   // do stuff with copy
>   fclose(copy_of_fd) 
> 
> Let me know if that doesn't make sense.

Wouldn't this mean dup-ing for every call to ::Print() ?
And then closing copy_of_fd would mean yet another system call. And the extra mutex may also add a bit of overhead.
Wouldn't it be easier just to leak the fd when changing the logfile?

Comment 18

[Valentin Gosu [:valentin] (he/him)]

Attachment: Add method to set logging file at runtime

So, I changed the patch so we would leak the FILE* object when changing logging at runtime. I guess that shouldn't be a problem since regular users wouldn't be doing that.
I also noticed that even without my patch, logging for the child process is sent to stdout instead of another log file. Is this because of a recent change?

Comment 19

[Eric Rahm [:erahm]]

Comment on attachment 8751176 [details] [diff] [review]
Add method to set logging file at runtime

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

I'm going to hold of on r+'ing this for now, I'm a little wary of leaking the file pointer. Lets see what our fearless module owner thinks. Nathan, do you think its reasonable to leak the log file pointer on shutdown if a log file is requested? This lets us avoid locking and dup'ing the file handle in the |Print| function.

Comment 20

[Nathan Froyd [:froydnj]]

Comment on attachment 8751176 [details] [diff] [review]
Add method to set logging file at runtime

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

This is actually leaking every log file that we set via MOZ_LOG_FILE or about:networking, right?  That seems not so great...can we not at least leak only one log file by asynchronously closing the current log file when a new one is set?

We could probably live with leaking a couple log files, but if we expect people to be setting several log files over the course of a session, we should make some effort to clean up after ourselves.

::: xpcom/base/LogModulePrefWatcher.cpp
@@ +14,4 @@
>  
>  static const char kLoggingPrefPrefix[] = "logging.";
> +static const char kLoggingConfigPrefPrefix[] = "logging.config";
> +static const int  kLoggingConfigPrefixLen = strlen(kLoggingConfigPrefPrefix);

Please use sizeof(kLoggingConfigPrefPrefix) - 1 instead.

Comment 21

[Valentin Gosu [:valentin] (he/him)]

Attachment: Add method to set logging file at runtime

* Only allows setting the log file at runtime if not set by an Env Var
* LogModulePrefWatcher will watch logging.config. prefs and call into Logging.cpp to set the log file, sync or timestamp
* Log files set by pref will have a -main.PID or -child.PID suffix
* If the logging.config.persist_restart pref is not set, prefs will be reset upon restart.
MozReview-Commit-ID: CWJujX4jm2A

Comment 22

[Nathan Froyd [:froydnj]]

Comment on attachment 8777798 [details] [diff] [review]
Add method to set logging file at runtime

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

Seems mostly reasonable, some comments below.

::: modules/libpref/init/all.js
@@ +133,5 @@
>  pref("dom.fileHandle.enabled", true);
>  
> +// Whether changes to prefs in the logging
> +// branch should be persisted after restarting.
> +pref("logging.config.persist_restart", false);

How about we call this logging.config.clear_on_startup (flipping the default and any tests that depend on this), because that's really what the underlying code is doing, right?  persist_restart (and the comment) make me think that the preferences are going to be saved in some way, which isn't really accurate.

It's probably worth saying something about why we do this by default here, too.

::: xpcom/base/LogModulePrefWatcher.cpp
@@ +71,5 @@
> +        return;
> +      }
> +
> +      // If the pref value doesn't have a PID placeholder, append the pid to the
> +      // end of the file.

The code is a little more extensive than the comment.  I think this is a good idea and we should probably add the main/child annotations to the %PID case as well.

Please change the comment to match the code.

::: xpcom/base/Logging.cpp
@@ +263,5 @@
> +    static const char kPIDToken[] = "%PID";
> +    const char* pidTokenPtr = strstr(filename, kPIDToken);
> +    char buf[2048];
> +    if (pidTokenPtr &&
> +        snprintf_literal(buf, "%.*s%d%s",

This will need to be updated to SprintfLiteral.

It would also be great to separate this out into a:

const char* ExpandPIDMarker(const char* aFilename, const char (&buffer)[2048]);

function so we could share the logic with LogModuleManager::Init.

@@ +278,5 @@
> +
> +    // Exchange mOutFile and set it to be released once all the writes are done.
> +    detail::LogFile* newFile = OpenFile(false, 0);
> +    detail::LogFile* oldFile = mOutFile.exchange(newFile);
> +    mToReleaseFile.exchange(oldFile);

Do you actually want to chain oldFile onto mToReleaseFile here?  (cf. "the trick" in LogModuleManager::Printf:

https://dxr.mozilla.org/mozilla-central/source/xpcom/base/Logging.cpp?q=LogModuleManager&redirect_type=direct#379

Or are you deliberately leaking the contents of mToReleaseFile?  If we're choosing to leak, please add a comment about the leak and explaining why we're doing that.

@@ +507,5 @@
> +  sLogModuleManager->SetLogFile(aFilename);
> +}
> +
> +uint32_t
> +LogModule::GetLogFile(char *aBuffer, size_t aLength)

This function (and associated machinery) doesn't seem to be called at all; can we get rid of it?

Comment 23

[Valentin Gosu [:valentin] (he/him)]

Attachment: Add method to set logging file at runtime

* Only allows setting the log file at runtime if not set by an Env Var
* LogModulePrefWatcher will watch logging.config. prefs and call into Logging.cpp to set the log file, sync or timestamp
* Log files set by pref will have a -main.PID or -child.PID suffix
* If the logging.config.clear_on_startup pref is true, prefs will be reset upon restart.
MozReview-Commit-ID: CWJujX4jm2A

Comment 24

[Valentin Gosu [:valentin] (he/him)]

Attachment: Add method to set logging file at runtime

* Only allows setting the log file at runtime if not set by an Env Var
* LogModulePrefWatcher will watch logging.config. prefs and call into Logging.cpp to set the log file, sync or timestamp
* Log files set by pref will have a -main.PID or -child.PID suffix
* If the logging.config.clear_on_startup pref is true, prefs will be reset upon restart.
MozReview-Commit-ID: CWJujX4jm2A

Comment 25

[Valentin Gosu [:valentin] (he/him)]

(In reply to Nathan Froyd [:froydnj] from comment #22)
> Comment on attachment 8777798 [details] [diff] [review]
> 
> Or are you deliberately leaking the contents of mToReleaseFile?  If we're
> choosing to leak, please add a comment about the leak and explaining why
> we're doing that.

We're actually not leaking, since we don't allow setting the log file at runtime if MOZ_LOG_FILE is set.
So there is no chance we are using rotating logs, so mToReleaseFile will always be 0.

> > +uint32_t
> > +LogModule::GetLogFile(char *aBuffer, size_t aLength)
> 
> This function (and associated machinery) doesn't seem to be called at all;
> can we get rid of it?

I'll be using it in the other (UI) patch, so I'd like to keep this.

Comment 26

[Nathan Froyd [:froydnj]]

Comment on attachment 8792008 [details] [diff] [review]
Add method to set logging file at runtime

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

Thanks for the fast turnaround.  r=me with the change below.

::: xpcom/base/Logging.cpp
@@ +271,5 @@
> +    detail::LogFile* oldFile = mOutFile.exchange(newFile);
> +
> +    // Since we don't allow changing the logfile if MOZ_LOG_FILE is already set,
> +    // and we don't allow log rotation when setting it at runtime, mToReleaseFile
> +    // will be null, so we're not leaking.

Thanks for the clarifying comment.  Can we MOZ_ASSERT that the result of exchanging into mToReleaseFile is null, then?

Comment 27

[Valentin Gosu [:valentin] (he/him)]

https://treeherder.mozilla.org/#/jobs?repo=try&revision=38898023eb95

Comment 28

[Valentin Gosu [:valentin] (he/him)]

Moving the UI patch to bug 1303762.

Comment 29

[Valentin Gosu [:valentin] (he/him)]

https://hg.mozilla.org/integration/mozilla-inbound/rev/d6809e466fe6c6cdeebeebe8878ee0d03e59d4f6
Bug 1239686 - Add method to set logging file at runtime r=nfroyd

Comment 30

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

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