961430 - Let pid be added to the NSPR log name

Status: RESOLVED FIXED

(Core :: XPCOM, defect)

Description

[Honza Bambas (:mayhemer)]

Attachment: v1

To allow upload of NSPR logs from tryserver runs, the log name must have a '.log' extension.

Comment 1

[Honza Bambas (:mayhemer)]

Hmm.. further testing shows that the patch and approach from bug 534764 has serious problems.

When I set NSPR_LOG_FILE=~/foo.nspr and run e.g. mochitests, then other binaries based on nspr (certutil, ssltunnel, xpcshell...) all try to open and write to the same file.  Spawning gecko child processes has nothing to do with it.

I'm using my local path that, when NSPR_LOG_FILE_MULTIPROCESS=1 set, inserts pid between the log file name and the extension.  So, for NSPR_LOG_FILE=~/foo.nspr the log name will be ~/foo-1234.nspr.

I think to make this 100% work we rather need a solution like that.

Comment 2

[Honza Bambas (:mayhemer)]

Attachment: nspr-log-with-pid.patch

- inserts (optionally) pid to the log file name
- driven by NSPR_LOG_FILE_MULTIPROCESS

Comment 3

[Honza Bambas (:mayhemer)]

(In reply to Honza Bambas (:mayhemer) from comment #1)
> When I set NSPR_LOG_FILE=~/foo.nspr and run e.g. mochitests, then other
> binaries based on nspr (certutil, ssltunnel, xpcshell...) all try to open
> and write to the same file.  Spawning gecko child processes has nothing to
> do with it.

Looks like this was just my local setting (the bash prompt I was running tests from had set the log file path).  When checking env of other test processes I can see they don't have set path to the log file, browserEnv only goes to the browser, not to the utilities.

So, to make bug 961147 work, we don't need this bug.

Still, I think it's useful to have this in the tree.

Comment 4

[Wan-Teh Chang]

Comment on attachment 8362159 [details] [diff] [review]
nspr-log-with-pid.patch

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

Honza:

Thanks for the patch. This change seems useful. I have two
high-level comments.

1. The NSPR_LOG_FILE_MULTIPROCESS variable can be renamed
"NSPR_LOG_FILE_WITH_PID". "Multiprocess" can also be interpreted
as allowing multiple processes to write to the same log file
correctly.

2. I remember I reviewed a similar patch that takes a different
approach. It allows a special token ${PID} in NSPR_LOG_FILE,
which is substituted with the pid by NSPR. However, I can't find
that patch in Bugzilla.

In that approach, you would simply set
    NSPR_LOG_FILE=~/foo-${PID}.nspr

The complication with that approach is to prevent the shell
from substituting ${PID} when you set NSPR_LOG_FILE. So we may
need to use other special characters that do not have a special
meaning in shells, or we may need to use $${PID}.

::: nsprpub/pr/src/io/prlog.c
@@ +11,5 @@
> +#ifdef XP_PC
> +#include <process.h>
> +#else
> +#include <sys/types.h>
> +#include <unistd.h>

Nit: in current versions of Unix, it's no longer necessary to first include <sys/types.h>. See http://pubs.opengroup.org/onlinepubs/009695399/functions/getpid.html

@@ +190,5 @@
>  
>  void _PR_InitLog(void)
>  {
>      char *ev;
> +    int mp = 0;

This variable should be of the PRBool type.

I suggest using a longer variable name, such as "multiProcess".

@@ +253,5 @@
>              return;
>          }
>  #endif /* XP_UNIX */
>  
> +        /* Append pid to the log file name if demanded */

Nit: "demanded" sounds a little strange. I suggest "requested" or "NSPR_LOG_FILE_MULTIPROCES is set".

@@ +262,5 @@
>          if (ev && ev[0]) {
> +            char buf[1024];
> +            char * filename;
> +
> +            if (mp) {

Please add a comment to describe how the pid is added to the base log file name. Give one example for each case (base log file name may or may not have an extension).

@@ +263,5 @@
> +            char buf[1024];
> +            char * filename;
> +
> +            if (mp) {
> +                char * ext = strrchr(ev, '.');

Nit: declare this as "const char *". Remove the space between "*" and "ext".

@@ +272,5 @@
> +                else
> +                    extpos = ext - ev;
> +
> +                filename = buf;
> +                PR_snprintf(buf, 1023, "%*.*s-%u%*.*s",

Why do you pass 1023 instead of 1024?

@@ +278,4 @@
>  #ifdef XP_PC
> +                    _getpid()
> +#else
> +                    getpid()

Nit: add a "(unsigned int)" cast. Place the comma after this line.

@@ +279,5 @@
> +                    _getpid()
> +#else
> +                    getpid()
> +#endif
> +                    , evlen - extpos, evlen - extpos, ext

IMPORTANT: does this work when |ext| is NULL? I am afraid that passing NULL to %s is not portable, even if the width and precision are both 0.

Comment 5

[Honza Bambas (:mayhemer)]

(In reply to Wan-Teh Chang from comment #4)
> Comment on attachment 8362159 [details] [diff] [review]
> nspr-log-with-pid.patch
> 
> 2. I remember I reviewed a similar patch that takes a different
> approach. It allows a special token ${PID} in NSPR_LOG_FILE,
> which is substituted with the pid by NSPR. However, I can't find
> that patch in Bugzilla.
> 
> In that approach, you would simply set
>     NSPR_LOG_FILE=~/foo-${PID}.nspr
> 
> The complication with that approach is to prevent the shell
> from substituting ${PID} when you set NSPR_LOG_FILE. So we may
> need to use other special characters that do not have a special
> meaning in shells, or we may need to use $${PID}.


Thanks Wan-Teh.  It's not clear if you want me to use this approach ($${something}) or the current approach where the pid is added before the extension.

Comment 6

[Wan-Teh Chang]

Honza: sorry I didn't clearly state my preference. I would prefer
the magic ${PID} token approach because it is more flexible.

By the way, I found that $$ is a special built-in variable in shell.
On the other hand, $ can be easily escaped with either single quotes
or a backslash, so it's not that bad.

Comment 7

[Honza Bambas (:mayhemer)]

To sum the idea:

with NSPR_LOG_FILE=my_log_${PID}.log you will be getting files like my_log_8734.log for each process.

Comment 8

[Nathan Froyd [:froydnj]]

(In reply to Honza Bambas (:mayhemer) from comment #7)
> with NSPR_LOG_FILE=my_log_${PID}.log you will be getting files like
> my_log_8734.log for each process.

Seems reasonable; I wonder if that would let us remove the hacks we have in place to make NSPR_LOG_FILE work with e10s?

Comment 9

[Honza Bambas (:mayhemer)]

(In reply to Nathan Froyd [:froydnj] from comment #8)
> (In reply to Honza Bambas (:mayhemer) from comment #7)
> > with NSPR_LOG_FILE=my_log_${PID}.log you will be getting files like
> > my_log_8734.log for each process.
> 
> Seems reasonable; I wonder if that would let us remove the hacks we have in
> place to make NSPR_LOG_FILE work with e10s?

I'm not sure.  This is kinda orthogonal.  Sometimes I use it (the now obsolete patch) when running e.g. xpcshell tests in parallel.  There were times I was using this to separate child/parent logs, but that led to just being polluted with huge number of logs.  What we have now (the hacks) is imo better than this, so I would leave it.

I'm not pushing on this feature right now, I stopped using it, except occasionally since we have "fixed" the child logs.

Comment 10

[Honza Bambas (:mayhemer)]

Attachment: v1

When there is '%PID' token in the file name, it's replaced with the pid of the application.  So for NSPR_LOG_FILE=/mozilla/log/my-%PID.log you get /mozilla/log/my-1234.log, my-1234.log-child1 etc. log files.

I'm not using any more sophisticated tokenizer here, just plain str* functions.  I think you don't want to use nsString in Logging.cpp.

This has one bad effect, there will be empty log files with '%PID' in the name thanks bug 1248565.

Comment 11

[Nathan Froyd [:froydnj]]

Comment on attachment 8719750 [details] [diff] [review]
v1

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

Patch seems reasonable, but I have a few small concerns.  Nit on the reviewer name in the commit message, too. ;)

::: xpcom/base/Logging.cpp
@@ +17,5 @@
>  #include "NSPRLogModulesParser.h"
>  
>  #include "prenv.h"
>  #include "prprf.h"
> +#ifdef XP_PC

Where is XP_PC getting defined?  The only reference I can find is in our moz.build for NSPR; I think we typically use XP_WIN for this sort of thing in Gecko.

@@ +56,5 @@
>  }
>  
> +int log_pid()
> +{
> +#ifdef XP_PC

Here too.

@@ +140,5 @@
>      mIsSync = isSync;
>  
>      const char* logFile = PR_GetEnv("NSPR_LOG_FILE");
>      if (logFile && logFile[0]) {
> +      char const* pidToken = strstr(logFile, "%PID");

|const char*| for consistency with local code, please.

I think we should write this as:

static const char sPIDToken[] = "%PID";
const char* pidTokenPtr = strstr(logFile, sPIDToken);

@@ +144,5 @@
> +      char const* pidToken = strstr(logFile, "%PID");
> +      static size_t const kFileWithPIDBuffer = 2048;
> +      char buf[kFileWithPIDBuffer];
> +
> +      if (pidToken && pidToken - logFile < kFileWithPIDBuffer) {

I applaud this additional check; I wouldn't have thought of doing it.  But this is not quite a sufficient condition for whether we should do the substitution, is it?  Because one could have:

NSPR_LOG_FILE="...2043 characters...%PID.log"

and then this condition would be satisfied, but with a PID of five digits or more, we'd wind up overrunning the bounds of |buf| with the final |strcpy| below.

I think to be really thorough, we'd need to print the PID to a separate temporary buffer, and do additional length checks with the printed PID.

@@ +147,5 @@
> +
> +      if (pidToken && pidToken - logFile < kFileWithPIDBuffer) {
> +        size_t pidPos = pidToken - logFile;
> +        // buf = "/log-file-
> +        strncpy(buf, logFile, pidPos);

Nit: I have a slight preference for |memcpy| here, to make the non-null-termination clearer and to signal that we don't have to care about the pathological cases of |strncpy|.

@@ +152,5 @@
> +        // buf = "/log-file-1234"
> +        int pidSize = snprintf(buf + pidPos, kFileWithPIDBuffer - pidPos,
> +                               "%d", detail::log_pid());
> +        // buf = "/log-file-1234.log"
> +        strcpy(buf + pidPos + pidSize, pidToken + 4);

We can replace this '4' with |strlen(sPIDToken)|, which makes it a little clearer where the '4' is coming from.  Especially since the strings added in the comments ("1234" and ".log") are both of length 4 themselves!

Comment 12

[Honza Bambas (:mayhemer)]

(In reply to Nathan Froyd [:froydnj] from comment #11)
> > +#ifdef XP_PC
> 
> Where is XP_PC getting defined?  

This is nspr stuff.  The patch was originally meant for the nspr logging code.  There is no XP_WIN.  I think XP_WIN will do what's needed.

Comment 13

[Honza Bambas (:mayhemer)]

Attachment: v1.1

A bit nicer approach.

Comment 14

[Nathan Froyd [:froydnj]]

Comment on attachment 8720369 [details] [diff] [review]
v1.1

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

I always forget about %.*.

::: xpcom/base/Logging.cpp
@@ +147,5 @@
> +      const char* pidTokenPtr = strstr(logFile, kPIDToken);
> +      char buf[kFileWithPIDBufferSize];
> +
> +      if (pidTokenPtr &&
> +          snprintf(buf, kFileWithPIDBufferSize, "%.*s%d%s",

I think you need to #include "mozilla/Snprintf.h" so this will work correctly on MSVC 2013 (it's possible we're bootlegging Snprintf.h from another header, and we should just include it here as well).

Comment 15

[Honza Bambas (:mayhemer)]

Attachment: v1.2

- includes Snprintf
- uses snprintf_literal => removed the ugly wordy kFileWithPIDBufferSize const

Comment 16

[Pulsebot]

https://hg.mozilla.org/integration/mozilla-inbound/rev/153e8aa293c5

Comment 17

[Carsten Book [:Tomcat]]

https://hg.mozilla.org/mozilla-central/rev/153e8aa293c5