Closed Bug 1341017 Opened 3 years ago Closed 3 years ago

Crash in mozilla::LogModuleManager::Print with LoadGroup:5

Categories

(Core :: XPCOM, defect, critical)

x86
Windows 10
defect
Not set
critical

Tracking

()

RESOLVED FIXED
mozilla54
Tracking Status
firefox52 --- unaffected
firefox53 --- unaffected
firefox54 --- fixed

People

(Reporter: mayhemer, Assigned: mayhemer)

References

(Blocks 1 open bug)

Details

(Keywords: crash)

Crash Data

Attachments

(1 file, 3 obsolete files)

This bug was filed from the Socorro interface and is 
report bp-83d9e44d-26e0-4066-b0e5-0cfd62170219.
=============================================================

  void Print(const char* aName, LogLevel aLevel, const char* aFmt, va_list aArgs)
  {
    const size_t kBuffSize = 1024;
    char buff[kBuffSize];

    char* buffToWrite = buff;

    // For backwards compat we need to use the NSPR format string versions
    // of sprintf and friends and then hand off to printf.
    va_list argsCopy;
    va_copy(argsCopy, aArgs);
    size_t charsWritten = VsprintfLiteral(buff, aFmt, argsCopy);
    va_end(argsCopy);

    if (charsWritten == kBuffSize - 1) {
      // We may have maxed out, allocate a buffer instead.
      buffToWrite = mozilla::Vsmprintf(aFmt, aArgs);
      charsWritten = strlen(buffToWrite);
    }

    // Determine if a newline needs to be appended to the message.
    const char* newline = "";
>   if (charsWritten == 0 || buffToWrite[charsWritten - 1] != '\n') {


this is on windows. charsWritten == 33059, string len in buff is 1023 (excluding the \0). Apparently size_t is a type mismatch, should be int.  according [1], when the formatted data don't fit the buffer, the function returns size of the output as it WOULD BE if the buffer was sufficient and the output is written truncated to the given buffer (in this case 1024 long).

also, when there is a formatting error, this function returns -1.  there is no handling for that in the logging code.

[1] https://msdn.microsoft.com/en-us//library/1kt27hek.aspx#Return%20Value
Attached patch v1 (obsolete) — Splinter Review
Assignee: nobody → honzab.moz
Status: NEW → ASSIGNED
Attachment #8839144 - Flags: review?(nfroyd)
Comment on attachment 8839144 [details] [diff] [review]
v1

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

::: xpcom/base/Logging.cpp
@@ +370,5 @@
>  
> +    if (charsWritten == -1) {
> +      // Print out at least something.  We must copy to the local buff,
> +      // can't just assign aFmt to buffToWrite, since when
> +      // buffToWrite != buff, we try to release it.

Two questions:

1. Why do we have to print something?  To ensure that the user doesn't think log messages are being dropped?
2. Printing something like "vsnprintf returned an error" seems a little more informative than printing the uninterpreted format string.  WDYT?  I guess printing the format string might give a better idea about where the logging messages are coming from.
Attachment #8839144 - Flags: review?(nfroyd) → review+
(In reply to Nathan Froyd [:froydnj] from comment #2)

Thanks.

> 1. Why do we have to print something?  To ensure that the user doesn't think
> log messages are being dropped?

If I, as a negligent developer, screw the formatting string, reviewer doesn't catch it, log gets to a release branch and I receive a log to analyze a problem, I would be confused - the log is not there, hence the code is apparently not called.  Pretty bad!  Rather show the formatting string w/o values than nothing.  My opinion.

> 2. Printing something like "vsnprintf returned an error" seems a little more
> informative than printing the uninterpreted format string.  WDYT?  

As said above - no :)  We could do both, but who will notice such error message before the values are needed?  I'd rather maybe NS_ERROR or MOZ_ASSERT(false) here to throw.  That could kick the negligent developer better, wdyt?

> I guess
> printing the format string might give a better idea about where the logging
> messages are coming from.

Yep, and may give at least some information, even just incomplete.
Attachment #8839144 - Attachment is obsolete: true
Attachment #8839629 - Flags: review+
Comment on attachment 8839904 [details] [diff] [review]
v1.2 (assert + build issue fix)

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

Honza, it might make sense to make a few more updates in here while you're fixing things.

::: xpcom/base/Logging.cpp
@@ +361,5 @@
>  
>      char* buffToWrite = buff;
>  
>      // For backwards compat we need to use the NSPR format string versions
>      // of sprintf and friends and then hand off to printf.

I'm guessing this comment isn't true anymore...

@@ +380,2 @@
>        // We may have maxed out, allocate a buffer instead.
>        buffToWrite = mozilla::Vsmprintf(aFmt, aArgs);

This seems like it's probably wrong now, before we had |PR_vsnprintf| above and |PR_vsmprintf| here (so both NSPR impls doing whatever non-standard NSPR things they did).

It seems like now we should just match |vsnprintf| with |vsnprintf| rather than |vsnprintf| (posix) and |mozilla::Vsmprintf| (mozilla thing) since we know the length of the buffer ahead of time.

ie:

> buffToWrite = moz_xmalloc(charsWritten + 1);
> charsWritten = Vsprintfliteral(buff, aFmt, aArgs);

and then below we'd just use |free|.

But really thinking about it, I don't think we should be using |VsprintfLiteral| at all as that doesn't support our wonky extensions.
(In reply to Eric Rahm [:erahm] from comment #7)
> But really thinking about it, I don't think we should be using
> |VsprintfLiteral| at all as that doesn't support our wonky extensions.

Nathan, you did the reviews in bug 1060419, what do you think?
Flags: needinfo?(nfroyd)
(In reply to Honza Bambas (:mayhemer) from comment #6)
> Created attachment 8839904 [details] [diff] [review]
> v1.2 (assert + build issue fix)
> 
> Fixed a build issue.
> 
> https://treeherder.mozilla.org/#/
> jobs?repo=try&revision=b145a38be9caac21cf4321adaa9ef621da9cc775

Note: green as grass during a summer morning.
(In reply to Eric Rahm [:erahm] from comment #7)
> Comment on attachment 8839904 [details] [diff] [review]
> v1.2 (assert + build issue fix)
> 
> Review of attachment 8839904 [details] [diff] [review]:
> -----------------------------------------------------------------
> 
> Honza, it might make sense to make a few more updates in here while you're
> fixing things.
> 
> ::: xpcom/base/Logging.cpp
> @@ +361,5 @@
> >  
> >      char* buffToWrite = buff;
> >  
> >      // For backwards compat we need to use the NSPR format string versions
> >      // of sprintf and friends and then hand off to printf.
> 
> I'm guessing this comment isn't true anymore...

Probably not, will look at it.

> 
> @@ +380,2 @@
> >        // We may have maxed out, allocate a buffer instead.
> >        buffToWrite = mozilla::Vsmprintf(aFmt, aArgs);
> 
> This seems like it's probably wrong now, before we had |PR_vsnprintf| above
> and |PR_vsmprintf| here (so both NSPR impls doing whatever non-standard NSPR
> things they did).
> 
> It seems like now we should just match |vsnprintf| with |vsnprintf| rather
> than |vsnprintf| (posix) and |mozilla::Vsmprintf| (mozilla thing) since we
> know the length of the buffer ahead of time.

Hmm.. but that goes against bug 1060419, see the changes set at https://hg.mozilla.org/mozilla-central/rev/495b8a307555#l212.1

> 
> ie:
> 
> > buffToWrite = moz_xmalloc(charsWritten + 1);
> > charsWritten = Vsprintfliteral(buff, aFmt, aArgs);
> 
> and then below we'd just use |free|.

I was thinking of this too, let's see what's Nathan's opinion.

> 
> But really thinking about it, I don't think we should be using
> |VsprintfLiteral| at all as that doesn't support our wonky extensions.
(In reply to Honza Bambas (:mayhemer) from comment #10)
> > It seems like now we should just match |vsnprintf| with |vsnprintf| rather
> > than |vsnprintf| (posix) and |mozilla::Vsmprintf| (mozilla thing) since we
> > know the length of the buffer ahead of time.
> 
> Hmm.. but that goes against bug 1060419, see the changes set at
> https://hg.mozilla.org/mozilla-central/rev/495b8a307555#l212.1

Eric, what do you think?
Flags: needinfo?(erahm)
(In reply to Honza Bambas (:mayhemer) from comment #11)
> (In reply to Honza Bambas (:mayhemer) from comment #10)
> > > It seems like now we should just match |vsnprintf| with |vsnprintf| rather
> > > than |vsnprintf| (posix) and |mozilla::Vsmprintf| (mozilla thing) since we
> > > know the length of the buffer ahead of time.
> > 
> > Hmm.. but that goes against bug 1060419, see the changes set at
> > https://hg.mozilla.org/mozilla-central/rev/495b8a307555#l212.1
> 
> Eric, what do you think?

We should either change the PR_LogModule* version to use vsnprintf or just not use it all. I'm leaning towards not using it due to our Mozilla/nspr formatting extensions (I assume those still exist). I'm not sure what the equivalent Mozilla version of PR_vsnprintf is (we appear to mozilla::Vsmprintf but not mozilla::Vsnprintf).
Flags: needinfo?(erahm)
I started a discussion in bug 1060419, comment #594 about this. It sounds like formatting is a non-issue, but there might be a remaining problem with handling of null strings.
Thank you for doing this.  I'm sorry for introducing the bug here; and feel free to
ping me if I can be of any help.
Guys, this is starting to crash for me even with nsHttp:5, which is vital for my work.  Could we land the patch as is and file followups?  This seems to be a long run and I really need to work.

Thanks.
Flags: needinfo?(erahm)
Attached patch v1.3Splinter Review
Just removed the comment.
Attachment #8839904 - Attachment is obsolete: true
Attachment #8842401 - Flags: review+
Blocks: 1343514
I'm landing this now.  I filed bug 1343514 for the issues with which version of printf to use here.
Flags: needinfo?(nfroyd)
Flags: needinfo?(erahm)
Keywords: checkin-needed
Pushed by ryanvm@gmail.com:
https://hg.mozilla.org/integration/mozilla-inbound/rev/1bea491fae96
Fix XPCOM logging to work correctly with vsnprintf results. r=froydnj
Keywords: checkin-needed
https://hg.mozilla.org/mozilla-central/rev/1bea491fae96
Status: ASSIGNED → RESOLVED
Closed: 3 years ago
Resolution: --- → FIXED
Target Milestone: --- → mozilla54
You need to log in before you can comment on or make changes to this bug.