Session logging for mail/news

From MozillaZine Knowledge Base
Jump to navigationJump to search

This article is about troubleshooting techniques for advanced users who are investigating problems with servers. It applies to all of the server types that Thunderbird connects to:

POP3  For getting mail
IMAP  For getting mail
SMTP  For sending mail
NNTP  For usenet news
HTTP  For RSS feeds
LDAP  For address books

These methods are only useful for investigating problems that occur after Thunderbird establishes a connection to a server. If Thunderbird cannot connect to the server, then it is pointless trying to log the connection—in these cases, see: Network tools for server connections

To use these methods for investigating secure authentication, you will need additional tools depending on the authentication method.

Methods for logging

There are three methods for logging server connections:

  • Thunderbird itself
  • A logging proxy
  • A packet sniffer

Using Thunderbird

Thunderbird can create a log file for the server types POP3, IMAP, SMTP, NNTP and HTTP, and MIME and LDAP protocols.

When you use Thunderbird to log a connection:

  • You do not see all the authentication information, so you might not be able to investigate authentication problems in detail.
  • You can log secure (SSL and TLS) connections.

To create the log file, follow the instructions on the Mozilla web page linked below. Use log level 5, and remember to specify POP3:5, IMAP:5, SMTP:5, NNTP:5, nsHttp:5, MIME:5 or LDAP:5, depending on which type of server or protocol you are investigating. (The module nsHttp is not mentioned on the linked page.)

MailNews Logging

Exiting Thunderbird usually does not close any existing connections to a mail server, it can take 5-10 minutes for them to time out. It's much easier to debug a problem when you can also log it making a new connection. For example, if you enabled IMAP logging and the connection to the AIM mail server was still open you would see something roughly like:

0[34988]: 2310cc0:imap.cs.com:NA:SetupWithUrl: clearing IMAP_CONNECTION_IS_OPEN

If the log file is empty that normally means you either didn't configure the logging correctly (you need to specify POP3:5 , not POP:5 for example) or you couldn't make a TCP-IP connection to the mail server for some reason. You could use netstat to list your connections. Run it from a console window/DOS box.

Its recommended that you add a timestamp. A combination like

MOZ_LOG=imap:5,timestamp

would add the time of an event to each entry.

Sample batch files for Windows

The environmental variables NSPR_LOG_MODULES and NSPR_LOG_FILE are being replaced with MOZ_LOG and MOZ_LOG_FILE starting with Thunderbird 55.0a1. These sample batch files use both so that they should work with any version.

To enable logging for a IMAP account create a imap.bat file at %APPDATA%\Thunderbird\Profiles (enter that string in the Windows search box and press Enter to go there using Windows Explorer) using a text editor such as Notepad. This is the default location that profiles are created in (as child directories). The log file will be created in the same directory as the imap.bat file.

Double click on the batch file and it will start Thunderbird with IMAP logging enabled. Duplicate the problem and exit Thunderbird. Afterwards open the imap.log log file with a text editor to view the log. The log file is usually too long to post in the forums. If you are asking for help in the forums it is suggested that you log into https://pastebin.com , https://www.dropbox.com or https://docs.google.com/document/ , upload the log file and then post a link to it in the forum. The log file does not contain passwords. It will contain some strings that use portions of your email address but it is garbled, so that spammers using a spider to collect email addresses should ignore it.

For a IMAP account create the following imap.bat file:

set MOZ_LOG=IMAP:5,timestamp
set MOZ_LOG_FILE=%APPDATA%\Thunderbird\Profiles\imap.log
set NSPR_LOG_MODULES=IMAP:5,timestamp
set NSPR_LOG_FILE=%APPDATA%\Thunderbird\Profiles\imap.log
"%ProgramFiles(x86)%\Mozilla Thunderbird\thunderbird.exe"

For a POP account create the following pop.bat file instead:

set MOZ_LOG=POP3:5,timestamp
set MOZ_LOG_FILE=%APPDATA%\Thunderbird\Profiles\pop.log
set NSPR_LOG_MODULES=POP3:5,timestamp
set NSPR_LOG_FILE=%APPDATA%\Thunderbird\Profiles\pop.log
"%ProgramFiles(x86)%\Mozilla Thunderbird\thunderbird.exe"

To log sending a email message (SMTP) create the following smtp.bat file instead:

set MOZ_LOG=SMTP:5,timestamp
set MOZ_LOG_FILE=%APPDATA%\Thunderbird\Profiles\smtp.log
set NSPR_LOG_MODULES=SMTP:5,timestamp
set NSPR_LOG_FILE=%APPDATA%\Thunderbird\Profiles\smtp.log
"%ProgramFiles(x86)%\Mozilla Thunderbird\thunderbird.exe"

You can replace %APPDATA%\Thunderbird\Profiles with %USERPROFILE%\Desktop if you want to display the log file on your desktop instead. Or replace it with any path you want.

The logging is not account specific, it will log everything for that type of account. It is usually a good idea to temporarily disable checking for new mail in the other accounts by unchecking "check for new mail on startup" etc. before using the batch file, and not selecting any of the other accounts folders in the folder pane while duplicating the problem. Otherwise not only will it log everything for every account of that type, but it may intermingle the logging (making it much harder to read).

Other types of problems you can solve

You can also log memory usage using MSGDB:5 to help diagnose memory usage problems. If you build a debug version of Thunderbird there are other logging options such as MAPI, msgcompose, imapoffline etc. that may be useful for debugging.

Using a proxy

A logging proxy is an additional program that logs a specific connection.

When you use a proxy:

  • You can log any server type.
  • You do not see Thunderbird's connection states. This simplifies the log, but it might make some problems more difficult to discover.
  • You see the raw data with no explanatory information.
  • You see all the authentication information. However, investigating secure authentication requires additional tools.
  • You cannot successfully log a secure (SSL) connection, nor a TLS connection after the initial negotiation.

To configure a proxy, either change Thunderbird's server settings, or use Thunderbird's proxy settings to specify localhost (your own computer, where the proxy is running) as the proxy server. By changing settings in Thunderbird, you risk changing the nature of the problem that you are investigating. If possible, check the proxy configuration with a working server before you use it with the server you are investigating.

To change Thunderbird's server settings, point Thunderbird at the server localhost and point the logging proxy at the real server.

To change Thunderbird's proxy settings, choose: Tools – Options... – General – Connection Settings..., choose "Manual proxy configuration", set the HTTP proxy to localhost, and check the box "Use this proxy server for all protocols". Use whatever port you have configured in the proxy—for example, 80. Point the logging proxy at the real server and port.

Some examples of logging proxies that you can download are:

Using a packet sniffer

A packet sniffer is an additional program that logs network traffic. You usually configure the packet sniffer to filter the log, so that you only see the parts that interest you. The resulting log contains information similar to a proxy log, but it might be presented in a much more complex way, depending on the sniffer and on how you configure it.

When you use a packet sniffer:

  • You can log any server type.
  • You do not change any settings in Thunderbird.
  • You see the raw data with no explanatory information.
  • You do not see Thunderbird's connection states. This simplifies the log, but it might make some problems more difficult to discover.
  • You see all the authentication information. However, investigating secure authentication requires additional tools.
  • You cannot successfully log a secure (SSL) connection, nor a TLS connection after the initial negotiation.

Configuring a packet sniffer depends on the sniffer.

Some examples of packet sniffers that you can download are:

Interpreting a connection log

To interpret a connection log, you need to understand something about how the server works and how Thunderbird works.

The server specifications are Internet standards published as RFCs. There are some links to them in the External links section below.

For POP3, SMTP and NNTP, Thunderbird works by computing a connection state that tells it what to expect from the server and what to do next. These connection states are internal to Thunderbird. They might be different in different releases of Thunderbird. To understand the connection states in detail, you might have to read Thunderbird's C++ source code.

POP3 connection states

 0 READ_PASSWORD 
 1 START_CONNECT 
 2 FINISH_CONNECT 
  3 WAIT_FOR_RESPONSE 
  4 WAIT_FOR_START_OF_CONNECTION_RESPONSE 
  5 SEND_USERNAME 
  6 SEND_PASSWORD 
  7 SEND_STAT 
 8 GET_STAT 
 9 SEND_LIST 
10 GET_LIST 
11 SEND_UIDL_LIST 
12 GET_UIDL_LIST 
13 SEND_XTND_XLST_MSGID 
14 GET_XTND_XLST_MSGID 
15 GET_MSG 
16 SEND_TOP 
17 TOP_RESPONSE 
18 SEND_RETR 
19 RETR_RESPONSE 
20 SEND_DELE 
21 DELE_RESPONSE 
22 SEND_QUIT 
23 DONE 
24 ERROR_DONE 
25 FREE 
26 START_USE_TOP_FOR_FAKE_UIDL 
27 SEND_FAKE_UIDL_TOP 
28 GET_FAKE_UIDL_TOP 
29 SEND_AUTH 
30 AUTH_RESPONSE 
31 SEND_CAPA 
32 CAPA_RESPONSE 
33 PROCESS_AUTH 
34 AUTH_FALLBACK 
35 AUTH_LOGIN 
36 AUTH_LOGIN_RESPONSE 
37 AUTH_NTLM 
38 AUTH_NTLM_RESPONSE 
39 SEND_XSENDER 
40 XSENDER_RESPONSE 
41 SEND_GURL 
42 GURL_RESPONSE 
43 QUIT_RESPONSE 
44 INTERRUPTED 
45 TLS_RESPONSE 
46 AUTH_GSSAPI 
47 AUTH_GSSAPI_FIRST 
48 AUTH_GSSAPI_STEP 

SMTP connection states

 0 RESPONSE
 1 START_CONNECT
 2 FINISH_CONNECT
 3 SEND_HELO_RESPONSE
 4 SEND_EHLO_RESPONSE
 5 SEND_VRFY_RESPONSE
 6 SEND_MAIL_RESPONSE
 7 SEND_RCPT_RESPONSE
 8 SEND_DATA_RESPONSE
 9 SEND_POST_DATA
10 SEND_MESSAGE_RESPONSE
11 DONE
12 ERROR_DONE
13 FREE
14 AUTH_LOGIN_STEP0_RESPONSE
15 EXTN_LOGIN_RESPONSE
16 SEND_AUTH_LOGIN_STEP0
17 SEND_AUTH_LOGIN_STEP1
18 SEND_AUTH_LOGIN_STEP2
19 AUTH_LOGIN_RESPONSE
20 TLS_RESPONSE
21 AUTH_EXTERNAL_RESPONSE
22 AUTH_PROCESS_STATE
23 AUTH_CRAM_MD5_CHALLENGE_RESPONSE
24 SEND_AUTH_GSSAPI_FIRST
25 SEND_AUTH_GSSAPI_STEP

NNTP connection states

 0 RESPONSE
 1 CONNECT
 2 CONNECT_WAIT
 3 LOGIN_RESPONSE
 4 SEND_MODE_READER
 5 SEND_MODE_READER_RESPONSE
 6 SEND_LIST_EXTENSIONS
 7 SEND_LIST_EXTENSIONS_RESPONSE
 8 SEND_LIST_SEARCHES
 9 SEND_LIST_SEARCHES_RESPONSE
10 LIST_SEARCH_HEADERS
11 LIST_SEARCH_HEADERS_RESPONSE
12 GET_PROPERTIES
13 GET_PROPERTIES_RESPONSE
14 SEND_LIST_SUBSCRIPTIONS
15 SEND_LIST_SUBSCRIPTIONS_RESPONSE
16 SEND_FIRST_NNTP_COMMAND
17 SEND_FIRST_NNTP_COMMAND_RESPONSE
18 SETUP_NEWS_STREAM
29 BEGIN_AUTHORIZE
20 AUTHORIZE_RESPONSE
21 PASSWORD_RESPONSE
22 READ_LIST_BEGIN
23 READ_LIST
24 DISPLAY_NEWSGROUPS
25 NEWGROUPS_BEGIN
26 NEWGROUPS
27 BEGIN_ARTICLE
28 READ_ARTICLE
29 XOVER_BEGIN
30 FIGURE_NEXT_CHUNK
31 XOVER_SEND
32 XOVER_RESPONSE
33 XOVER
34 PROCESS_XOVER
35 READ_GROUP
36 READ_GROUP_RESPONSE
37 READ_GROUP_BODY
38 SEND_GROUP_FOR_ARTICLE
39 SEND_GROUP_FOR_ARTICLE_RESPONSE
40 PROFILE_ADD
41 PROFILE_ADD_RESPONSE
42 PROFILE_DELETE
43 PROFILE_DELETE_RESPONSE
44 SEND_ARTICLE_NUMBER
45 PROCESS_BODIES
46 PRINT_ARTICLE_HEADERS
47 SEND_POST_DATA
48 SEND_POST_DATA_RESPONSE
49 CHECK_FOR_MESSAGE
50 NEWS_RC_POST
51 DISPLAY_NEWS_RC
52 DISPLAY_NEWS_RC_RESPONSE
53 START_CANCEL
54 DO_CANCEL
55 XPAT_SEND
56 XPAT_RESPONSE
57 SEARCH
58 SEARCH_RESPONSE
59 SEARCH_RESULTS
60 LIST_PRETTY_NAMES
61 LIST_PRETTY_NAMES_RESPONSE
62 LIST_XACTIVE
63 LIST_XACTIVE_RESPONSE
64 LIST_GROUP
65 LIST_GROUP_RESPONSE
66 NEWS_DONE
67 NEWS_POST_DONE
68 NEWS_ERROR
69 ERROR
70 NEWS_FREE
71 NEWS_FINISHED

Examples

Here is a proxy log of a connection to a POP3 server. There are no messages on the server:

+OK Hello there.
AUTH
-ERR Invalid command.
CAPA
+OK Here's what I can do:
SASL LOGIN CRAM-MD5 CRAM-SHA1
TOP
USER
LOGIN-DELAY 10
PIPELINING
UIDL
IMPLEMENTATION Courier Mail Server
.
AUTH LOGIN
+ VXNlcm5hbWU6
anVzdC50ZXN0aW5nQGV4YW1wbGUubmV0DQo=
+ UGFzc3dvcmQ6
Zm9vYmFyMTIzDQo=
+OK logged in.
STAT
+OK 0 0
QUIT
+OK Bye-bye.

The base64 strings that you see are:

VXNlcm5hbWU6 Username:
anVzdC50ZXN0aW5nQGV4YW1wbGUubmV0DQo=   just.testing@example.net (the username)
UGFzc3dvcmQ6 Password:
Zm9vYmFyMTIzDQo= foobar123 (the password)

Here is a Thunderbird log of the same connection:

0[ef1790]: Entering NET_ProcessPop3 18
0[ef1790]: POP3: Entering state: 1
0[ef1790]: POP3: Entering state: 2
0[ef1790]: POP3: Entering state: 4
0[ef1790]: RECV: +OK Hello there.
0[ef1790]: POP3: Entering state: 29
0[ef1790]: SEND: AUTH

0[ef1790]: Entering NET_ProcessPop3 23
0[ef1790]: POP3: Entering state: 3
0[ef1790]: RECV: -ERR Invalid command.
0[ef1790]: POP3: Entering state: 30
0[ef1790]: POP3: Entering state: 31
0[ef1790]: SEND: CAPA

0[ef1790]: Entering NET_ProcessPop3 142
0[ef1790]: POP3: Entering state: 3
0[ef1790]: RECV: +OK Here's what I can do:
0[ef1790]: POP3: Entering state: 32
0[ef1790]: RECV: SASL LOGIN CRAM-MD5 CRAM-SHA1
0[ef1790]: POP3: Entering state: 32
0[ef1790]: RECV: TOP
0[ef1790]: POP3: Entering state: 32
0[ef1790]: RECV: USER
0[ef1790]: POP3: Entering state: 32
0[ef1790]: RECV: LOGIN-DELAY 10
0[ef1790]: POP3: Entering state: 32
0[ef1790]: RECV: PIPELINING
0[ef1790]: POP3: Entering state: 32
0[ef1790]: RECV: UIDL
0[ef1790]: POP3: Entering state: 32
0[ef1790]: RECV: IMPLEMENTATION Courier Mail Server
0[ef1790]: POP3: Entering state: 32
0[ef1790]: RECV: .
0[ef1790]: POP3: Entering state: 33
0[ef1790]: POP3: Entering state: 35
0[ef1790]: SEND: AUTH LOGIN

0[ef1790]: Entering NET_ProcessPop3 16
0[ef1790]: POP3: Entering state: 3
0[ef1790]: RECV: + VXNlcm5hbWU6
0[ef1790]: POP3: Entering state: 36
0[ef1790]: POP3: Entering state: 5
0[ef1790]: SEND: anVzdC50ZXN0aW5nQGV4YW1wbGUubmV0DQo=

0[ef1790]: Entering NET_ProcessPop3 16
0[ef1790]: POP3: Entering state: 3
0[ef1790]: RECV: + UGFzc3dvcmQ6
0[ef1790]: POP3: Entering state: 34
0[ef1790]: POP3: Entering state: 6
0[ef1790]: Logging suppressed for this command (it probably contained authentication information)
0[ef1790]: Entering NET_ProcessPop3 16
0[ef1790]: POP3: Entering state: 3
0[ef1790]: RECV: +OK logged in.
0[ef1790]: POP3: Entering state: 34
0[ef1790]: POP3: Entering state: 7
0[ef1790]: SEND: STAT

0[ef1790]: Entering NET_ProcessPop3 9
0[ef1790]: POP3: Entering state: 3
0[ef1790]: RECV: +OK 0 0
0[ef1790]: POP3: Entering state: 8
0[ef1790]: POP3: Entering state: 22
0[ef1790]: SEND: QUIT

0[ef1790]: Entering NET_ProcessPop3 14
0[ef1790]: POP3: Entering state: 3
0[ef1790]: RECV: +OK Bye-bye.
0[ef1790]: POP3: Entering state: 43
0[ef1790]: POP3: Entering state: 23
0[ef1790]: POP3: Entering state: 25

Rich logging using Gloda

The global database (gloda) has been enhanced to support additional logging and context information. Logsploder is a XULRunner application that supports using these features. See logsploder, circa a year+ ago for more information. This functionality isn't useful for most users, its intended mainly to support unit testing.

See also

External links

Wikipedia articles (including links to RFCs):

Protocol guides (they focus on the actual commands and which RFC applies to a specific protocol command):

Sometimes its useful to compare session logs for another email client and Thunderbird.

Additional information on how the logging works: