187084 - PR_LOG buffering is broken

Status: NEW

(NSPR :: NSPR, defect)

Description

[Michal Kluka]

User-Agent:       Mozilla/4.0 (compatible; MSIE 6.0; Windows NT 5.0; T312461)
Build Identifier: 2002122104

According http://www.mozilla.org/projects/nspr/reference/html/prlog.html#25266 
you can force unbuffered logging by including module name sync in 
NSPR_LOG_MODULES env variable. (e.g. set NSPR_LOG_MODULES=all:5
). There is apparent mistake in 
http://lxr.mozilla.org/mozilla/source/nsprpub/pr/src/io/prlog.c#240 that will 
set buffer size to zero when module sync is *not* included in NSPR_LOG_MODULES 
and when it is included size is set to nonzero value.
Line now is like: PR_SetLogBuffering(isSync ? bufSize : 0);
but should be: PR_SetLogBuffering(isSync ?  0: bufSize );
There is another mistake at 
http://lxr.mozilla.org/mozilla/source/nsprpub/pr/src/io/prlog.c#464 . This will 
flush buffer when there is nonzero characters in it. Because this is called 
from PR_LOG - every log entry is immediately written to file --> NO BUFFERING.
But unfortunately that is not all. On NT the fputs is used to write log entry 
to the file. It expects null terminated string to write into file. 
Unfortunately we do not clear buffer after write so in case of buffered output 
we write correct entry and than a lot of garbage. How much depends on previous 
log entries.
Example of this:
******
SET NSPR_LOG_MODULES=nsHttp:5,sync:0
SET NSPR_LOG_FILE=c:\mozilla.log
mozilla.exe
******
0[2344e0]: Creating nsHttpHandler [this=eaa320].
0[2344e0]: nsHttpHandler::Init
er [this=eaa320].
0[2344e0]: nsHttpHandler::PrefsChanged [pref=(null)]
0[2344e0]: nsHttpAuthCache::Init
anged [pref=(null)]
0[2344e0]: nsHttpHandler::BuildUserAgent
ref=(null)]
0[2344e0]: nsHttpHandler::Observe [topic="nsPref:changed")]
0[2344e0]: nsHttpHandler::PrefsChanged [pref=general.useragent.contentlocale]
0[2344e0]: nsHttpHandler::Observe [topic="nsPref:changed")]
nt.contentlocale]
0[2344e0]: nsHttpHandler::PrefsChanged [pref=network.http.max-connections]
e]
0[2344e0]: nsHttpHandler::Observe [topic="nsPref:changed")]
x-connections]
e]
******
See on 3rd line: it contains part of the 1st line that was longer than the 
first line.

And finally: _PR_LogCleanup is called from PR_Cleanup and this is not used in 
current version. So if we remove  PR_LogFlush() from PR_LOG() some items may 
stay in buffer (they won't be written to file) on shutdown.


Reproducible: Always

Steps to Reproduce:

Comment 1

[Wan-Teh Chang]

All the problems you described look like bugs.

Comment 2

[Christophe Ravel]

The target milestone is already released. Resetting target milestone.

Comment 3

[BugBot [:suhaib / :marco/ :calixte]]

The bug assignee didn't login in Bugzilla in the last 7 months and this bug has severity 'major'.
:KaiE, could you have a look please?
For more information, please visit auto_nag documentation.