1422548 - IMAP Logging does not work, unless "sync" is specified

Status: REOPENED

(Thunderbird :: General, defect)

Description

[mirh]

User Agent: Mozilla/5.0 (Windows NT 6.1; WOW64; rv:58.0) Gecko/20100101 Firefox/58.0
Build ID: 20171130160223

Steps to reproduce:

1. Set MOZ_LOG=timestamp,IMAP:5
2. Set some MOZ_LOG_FILE
(can also be done from about:networking)
3. Start/log-in thunderbird


Actual results:

Log is empty. 


Expected results:

Behave just like 52
Instead, I seemingly need to add ,sync to finally get some result

Comment 1

[Wayne Mery (:wsmwk)]

I know other people are recently using imap logging without problems, but don't know which versions. 
A few recent changes are bug 1391314, bug 1353143.
What is your log file location and if you enable something other than imap (like networking) do you get a log?

Comment 2

[Jorg K (CEST = GMT+2)]

Logging still works, however, it appears to be different from logging in TB 52.
In the first place, the options are now case-sensitive. We have bug 1353919 on file to straighten out those options.
Also, you need to take care when specifying a file name, on Linux you need to use quotes, see bug 1371498 comment #4.

In summary, we won't action this, particularly given that the logging module is Mozilla core software.

Comment 3

[mirh]

I was using linux, yes, but I know how pesky spaces can be, so I purposely avoided them. 
Networking seems to works as expected then, or at least nsHttp:5 did. 

I'm still not sure how all of this can explain or justify this sync-imap oddity though. 

Also, thanks for pinging the capitalization thread. Was gonna ask the same. 
Didn't I found in source code the right LazyLogModule names, I'd have gone mad.

Comment 4

[Wayne Mery (:wsmwk)]

> In summary, we won't action this, particularly given that the logging module is Mozilla core software.

Whether we (Thunderbird) action or not isn't relevant - there's either a bug in which case the report gets moved to another product, or there isn't a bug and the resolution is WFM.  I don't see anything wrong with what mirh has specified, so reopening. (not sure why I had put this in account manager)

Comment 5

[Wayne Mery (:wsmwk)]

Attachment: tb about-networking.png

I tested 58.0b1 on windows without sync, starting thunderbird from command prompt, and I got an imap log just fine. 
set MOZ_LOG=IMAP:5,timestamp

But I also got log entries that I didn't ask for: D/nsHttp, D/nsSocketTransport, D/nsStreamPump. That seems wrong. [1]

For grins I had a look at about:networking which has which seems to confirm my settings so I don't understand why non-imap stuff is in my log.
"Current Log Modules:
IMAP:5,timestamp"


[1] 2017-12-05 12:20:22.285000 UTC - [Main Thread]: D/nsStreamPump   OnStateStart [this=17338380]
2017-12-05 12:20:22.285000 UTC - [Main Thread]: D/nsStreamPump   OnStateTransfer [this=17338380]
2017-12-05 12:20:22.285000 UTC - [Main Thread]: D/nsStreamPump   Available returned [stream=1731FF60 rv=0 avail=5141]
2017-12-05 12:20:22.285000 UTC - [Main Thread]: D/nsStreamPump   calling OnDataAvailable [offset=0 count=5141(5141)]
...
2017-12-05 12:20:22.435000 UTC - [Main Thread]: D/nsStreamPump   OnStateStop [this=1AA3FA80 status=0]
2017-12-05 12:20:23.220000 UTC - [Main Thread]: D/nsHttp NS_CompareLoadInfoAndLoadContext - loadInfo: 0, 0, 0; loadContext: 0 0, 0. [channel=1D7B43F0]
2017-12-05 12:20:23.220000 UTC - [Main Thread]: D/nsStreamPump nsInputStreamPump::Suspend [this=1D213900]

Comment 6

[Wayne Mery (:wsmwk)]

getting back to mirh, you don't see anything faulty in what you specified, correct?

Do you get the same results if you use beta?
http://www.mozilla.org/en-US/thunderbird/channel/

Comment 7

[:aceman]

I tested IMAP logging a few days ago and it definitely works on Linux, even without 'sync'.
I just noticed it does buffering, so a lot of the output isn't immediately visible in the output file (where I redirect it).

So are you sure you had enough output done so that something should appear (in the order of several KBs).
Logging into the IMAP server and checking a folder should be enough.

Also, when you close TB, does the log output appear then? The buffers should get flushed and any remaining output sent to the console/file.

Comment 8

[Jorg K (CEST = GMT+2)]

I closed the bug with "WONTFIX" based on comment #0: "Behave just like 52".
That's clearly a WONTFIX, since things are now case-sensitive, etc.
WORKSFORME is another option since IMAP logging clearly works.

However, a little hidden (but now exposed) there was the suggestion that Linux "sync" is required to get the log content into the file. Eric, can you clarify that for us please.

Comment 9

[Wayne Mery (:wsmwk)]

> I closed the bug with "WONTFIX" based on comment #0: "Behave just like 52".
> That's clearly a WONTFIX, since things are now case-sensitive, etc.

But mirh specified IMAP all upper case, which is correct in both 59 (case sensitive) and prior (eg. 52 where it is not case sensitive), no?

I tried ldap:5 with 52.5.0 and still got lots of nsSocketTransport and other entries.

Comment 10

[mirh]

Behave like 52 ==> Not need sync to work

Anyway, for some undisclosed reason, today env vars behaved like expected (I mean, at least on close as mentioned in comment 7). 
About:networking on the other hand is so over the place I wouldn't even know where to start. 
On one hand, logs are really empty without sync (whatever I press 'stop logging' before closing or not). 
On the other:
- tested TB58
- about:networking was already mysteriously pre-filled with my setting
- I press start logging
- "current log modules" get actually from god knows where nshttp:5,nssockettransport[1] etc etc
- but *actual* log for IMAP finally appears in place
- WTF

[1] which seems like some sort of default entry?

p.s. I was expecting bug 1353919 to acknowledge case sensitivity is bad, among other things?

Comment 11

[Eric Rahm [:erahm]]

(In reply to Wayne Mery (:wsmwk) from comment #5)
> Created attachment 8934501 [details]
> tb about-networking.png
> 
> I tested 58.0b1 on windows without sync, starting thunderbird from command
> prompt, and I got an imap log just fine. 
> set MOZ_LOG=IMAP:5,timestamp
> 
> But I also got log entries that I didn't ask for: D/nsHttp,
> D/nsSocketTransport, D/nsStreamPump. That seems wrong. [1]
> 
> For grins I had a look at about:networking which has which seems to confirm
> my settings so I don't understand why non-imap stuff is in my log.
> "Current Log Modules:
> IMAP:5,timestamp"
> 

It's possible you enabled them previously via about:config, you can check under the "logging." prefix.

Comment 12

[Wayne Mery (:wsmwk)]

That does appear to be the case
logging.nsHostResolver 5
logging.nsHttp 5
logging.nsSocketTransport
logging.nsStreamPump

Given these settings, is faulty that the tab cites "Current Log Modules: ldap:5,sync,timestamp" as I wrote in the previous comment?

Also, I had assumed logging was inactive, because both Start Logging and Stop Logging are greyed out in the Logging tab in about:networking

Comment 13

[Eric Rahm [:erahm]]

(In reply to mirh from comment #10)
> Behave like 52 ==> Not need sync to work
> 
> Anyway, for some undisclosed reason, today env vars behaved like expected (I
> mean, at least on close as mentioned in comment 7). 

Good to hear! 

> About:networking on the other hand is so over the place I wouldn't even know
> where to start.

This is probably related to sandboxing where enabling at startup works, but enabling at runtime does not work for content processes (bug 1344778).

> On one hand, logs are really empty without sync (whatever I press 'stop
> logging' before closing or not). 
> On the other:
> - tested TB58
> - about:networking was already mysteriously pre-filled with my setting

I believe it uses prefs, Valentin would know best.

> - I press start logging
> - "current log modules" get actually from god knows where
> nshttp:5,nssockettransport[1] etc etc

Yes, it has defaults: https://searchfox.org/mozilla-central/rev/ba2b0cf4d16711d37d4bf4d267b187c9a27f6638/toolkit/content/aboutNetworking.xhtml#240

> - but *actual* log for IMAP finally appears in place
> - WTF
> 
> [1] which seems like some sort of default entry?
> 
> p.s. I was expecting bug 1353919 to acknowledge case sensitivity is bad,
> among other things?

We don't currently plan to change from being case sensitive but feel free to file a bug.

Comment 14

[Eric Rahm [:erahm]]

(In reply to Jorg K (GMT+1) from comment #8)
> I closed the bug with "WONTFIX" based on comment #0: "Behave just like 52".
> That's clearly a WONTFIX, since things are now case-sensitive, etc.
> WORKSFORME is another option since IMAP logging clearly works.
> 
> However, a little hidden (but now exposed) there was the suggestion that
> Linux "sync" is required to get the log content into the file. Eric, can you
> clarify that for us please.

I'm not sure why sync would be necessary, it just does an fflush after each fprintf_stderr [1]. It might be necessary on some systems with a large output buffer if you want immediate results.

[1] https://searchfox.org/mozilla-central/rev/ba2b0cf4d16711d37d4bf4d267b187c9a27f6638/xpcom/base/Logging.cpp#444-446

Comment 15

[Eric Rahm [:erahm]]

(In reply to Wayne Mery (:wsmwk) from comment #12)
> That does appear to be the case
> logging.nsHostResolver 5
> logging.nsHttp 5
> logging.nsSocketTransport
> logging.nsStreamPump
> 
> Given these settings, is faulty that the tab cites "Current Log Modules:
> ldap:5,sync,timestamp" as I wrote in the previous comment?

It is a bit misleading, the logger uses env vars and about:config entries under the "logging." prefix. about:networking builds on top of that but probably doesn't check for entries under the "logging." prefix to build up it's list. You can file a networking bug for this and ni Valentin if you find it confusing.

> Also, I had assumed logging was inactive, because both Start Logging and
> Stop Logging are greyed out in the Logging tab in about:networking

about:networking only lets you start/stop logging at runtime if logging env vars aren't already set [1]. I suppose they could add a note about that, again feel free to file a networking bug for this.

[1] https://searchfox.org/mozilla-central/rev/2e08acdf8862e68b13166970e17809a3b5d6a555/toolkit/content/aboutNetworking.js#270-279

Comment 16

[mirh]

(In reply to Eric Rahm [:erahm] (please no mozreview requests) from comment #13)

My hats off for the whole informative comment. 
So.. Bug 1344778 possibly explaining everything (we'll see when it lands), and waiting for Jorg to come back with a comment on case sensitivity (I got the impression he sees this as an improvement, a feature?)..

I guess I'll leave the scene to Wayne's "reporting" now.