Sonatype server products have features that send email messages using SMTP.
A server administrator might need a way to perform low level diagnosis of issues encountered sending these messages, from within our products.
Enabling Sonatype Server SMTP Logging
Sonatype server products send email using using Java Mail APIs. These APIs have a standard mechanism to turn on low level logging using system properties.
The general steps to enable this logging are:
- Configure Java system properties and restart the Sonatype product.
The following JavaMail system properties take boolean values: "true" or "false":
Name Description mail.debug The initial debug mode. Default is false. mail.debug.auth Include protocol authentication commands (including usernames and passwords) in the debug output. Default is false. mail.debug.auth.username Include the user name in non-protocol debug output. Default is true. mail.debug.auth.password Include the password in non-protocol debug output. Default is false.
IMPORTANT: If you set the system property mail.debug.auth.password=true, then that this can actually log the plain text password the SMTP request is sending to your mail server into the Sonatype server application log.
System properties are specified as part of the "java" command used to launch the product.java -Dmail.debug=true ...
See product help on how to set Java system properties:
Setting Java system properties in Repository 3
Setting Java system properties in Repository 2: Edit the wrapper.java.additional.n properties in bin/jsw/conf/wrapper.conf
Setting Java system properties in IQ Server - After restart, set the com.sun.mail logger level to TRACE level.
How to change Logger Levels in Repository 3
How to change Logger Levels in Repository 2
How to change Logger Levels in IQ Server - Trigger an action that triggers a mail message send attempt using SMTP - using the in-product test feature is easiest.
Test Email Configuration in Repository 3
Test Email Configuration in Repository 2
Test Email Configuration in IQ Server - Examine the application log files for messages from com.sun.mail* loggers.
Example output from IQ Server:
2021-12-02 14:17:09,438-0400 DEBUG [dw-102] org.apache.shiro.web.servlet.SimpleCookie - Found 'CLMSESSIONID' cookie value [7e8afd57b74c414c9924690ed7a86ed8]
2021-12-02 14:17:09,439-0400 DEBUG [dw-102] org.apache.shiro.web.servlet.OncePerRequestFilter - Filter 'reverseProxy' is not enabled for the current request. Proceeding without invoking this filter.
2021-12-02 14:17:09,455-0400 DEBUG [dw-102 - POST /api/v2/config/mail/test/test%40example.com?timestamp=1638469029434] admin com.sonatype.insight.brain.service.InsightMail - Sending mail to test@example.com using server 127.0.0.1:1025.
2021-12-02 14:17:09,514-0400 DEBUG [dw-102 - POST /api/v2/config/mail/test/test%40example.com?timestamp=1638469029434] admin com.sun.mail.smtp - need username and password for authentication
2021-12-02 14:17:09,514-0400 DEBUG [dw-102 - POST /api/v2/config/mail/test/test%40example.com?timestamp=1638469029434] admin com.sun.mail.smtp - protocolConnect returning false, host=127.0.0.1, user=plynch, password=null
2021-12-02 14:17:09,514-0400 DEBUG [dw-102 - POST /api/v2/config/mail/test/test%40example.com?timestamp=1638469029434] admin com.sun.mail.smtp - useEhlo true, useAuth true
2021-12-02 14:17:09,515-0400 DEBUG [dw-102 - POST /api/v2/config/mail/test/test%40example.com?timestamp=1638469029434] admin com.sun.mail.smtp - trying to connect to host "127.0.0.1", port 1025, isSSL false
2021-12-02 14:17:09,519-0400 DEBUG [dw-102 - POST /api/v2/config/mail/test/test%40example.com?timestamp=1638469029434] admin com.sun.mail.util.socket - getSocket, host 127.0.0.1, port 1025, prefix mail.smtp, useSSL false
2021-12-02 14:17:09,519-0400 TRACE [dw-102 - POST /api/v2/config/mail/test/test%40example.com?timestamp=1638469029434] admin com.sun.mail.util.socket - create socket: prefix mail.smtp, localaddr null, localport 0, host 127.0.0.1, port 1025, connection timeout 60000, timeout 60000, socket factory null, useSSL false
2021-12-02 14:17:09,520-0400 TRACE [dw-102 - POST /api/v2/config/mail/test/test%40example.com?timestamp=1638469029434] admin com.sun.mail.util.socket - set socket read timeout 60000
2021-12-02 14:17:09,520-0400 TRACE [dw-102 - POST /api/v2/config/mail/test/test%40example.com?timestamp=1638469029434] admin com.sun.mail.util.socket - connecting...
2021-12-02 14:17:09,520-0400 TRACE [dw-102 - POST /api/v2/config/mail/test/test%40example.com?timestamp=1638469029434] admin com.sun.mail.util.socket - success!
2021-12-02 14:17:09,524-0400 TRACE [dw-102 - POST /api/v2/config/mail/test/test%40example.com?timestamp=1638469029434] admin com.sun.mail.smtp.protocol - 220 mailhog.example ESMTP MailHog
2021-12-02 14:17:09,524-0400 DEBUG [dw-102 - POST /api/v2/config/mail/test/test%40example.com?timestamp=1638469029434] admin com.sun.mail.smtp - connected to host "127.0.0.1", port: 1025
2021-12-02 14:17:09,527-0400 TRACE [dw-102 - POST /api/v2/config/mail/test/test%40example.com?timestamp=1638469029434] admin com.sun.mail.smtp.protocol - EHLO localhost
2021-12-02 14:17:09,530-0400 TRACE [dw-102 - POST /api/v2/config/mail/test/test%40example.com?timestamp=1638469029434] admin com.sun.mail.smtp.protocol - 250-Hello localhost
2021-12-02 14:17:09,530-0400 TRACE [dw-102 - POST /api/v2/config/mail/test/test%40example.com?timestamp=1638469029434] admin com.sun.mail.smtp.protocol - 250-PIPELINING
2021-12-02 14:17:09,530-0400 TRACE [dw-102 - POST /api/v2/config/mail/test/test%40example.com?timestamp=1638469029434] admin com.sun.mail.smtp.protocol - 250 AUTH PLAIN
2021-12-02 14:17:09,530-0400 DEBUG [dw-102 - POST /api/v2/config/mail/test/test%40example.com?timestamp=1638469029434] admin com.sun.mail.smtp - Found extension "PIPELINING", arg ""
2021-12-02 14:17:09,531-0400 DEBUG [dw-102 - POST /api/v2/config/mail/test/test%40example.com?timestamp=1638469029434] admin com.sun.mail.smtp - Found extension "AUTH", arg "PLAIN"
2021-12-02 14:17:09,531-0400 DEBUG [dw-102 - POST /api/v2/config/mail/test/test%40example.com?timestamp=1638469029434] admin com.sun.mail.smtp - protocolConnect login, host=127.0.0.1, user=admin, password=admin123
2021-12-02 14:17:09,531-0400 DEBUG [dw-102 - POST /api/v2/config/mail/test/test%40example.com?timestamp=1638469029434] admin com.sun.mail.smtp - Attempt to authenticate using mechanisms: LOGIN PLAIN DIGEST-MD5 NTLM XOAUTH2
2021-12-02 14:17:09,531-0400 DEBUG [dw-102 - POST /api/v2/config/mail/test/test%40example.com?timestamp=1638469029434] admin com.sun.mail.smtp - mechanism LOGIN not supported by server
2021-12-02 14:17:09,532-0400 DEBUG [dw-102 - POST /api/v2/config/mail/test/test%40example.com?timestamp=1638469029434] admin com.sun.mail.smtp - Using mechanism PLAIN
2021-12-02 14:17:09,532-0400 TRACE [dw-102 - POST /api/v2/config/mail/test/test%40example.com?timestamp=1638469029434] admin com.sun.mail.smtp.protocol - AUTH PLAIN YWRtaW4AYWRtaW4AYWRtaW4xMjM=
2021-12-02 14:17:09,535-0400 TRACE [dw-102 - POST /api/v2/config/mail/test/test%40example.com?timestamp=1638469029434] admin com.sun.mail.smtp.protocol - 235 Authentication successful
2021-12-02 14:17:09,536-0400 DEBUG [dw-102 - POST /api/v2/config/mail/test/test%40example.com?timestamp=1638469029434] admin com.sun.mail.smtp - use8bit false
2021-12-02 14:17:09,536-0400 TRACE [dw-102 - POST /api/v2/config/mail/test/test%40example.com?timestamp=1638469029434] admin com.sun.mail.smtp.protocol - MAIL FROM:<nexus@iqserver>
2021-12-02 14:17:09,539-0400 TRACE [dw-102 - POST /api/v2/config/mail/test/test%40example.com?timestamp=1638469029434] admin com.sun.mail.smtp.protocol - 250 Sender nexus@iqserver ok
2021-12-02 14:17:09,540-0400 TRACE [dw-102 - POST /api/v2/config/mail/test/test%40example.com?timestamp=1638469029434] admin com.sun.mail.smtp.protocol - RCPT TO:<test@example.com>
2021-12-02 14:17:09,542-0400 TRACE [dw-102 - POST /api/v2/config/mail/test/test%40example.com?timestamp=1638469029434] admin com.sun.mail.smtp.protocol - 250 Recipient test@example.com ok
2021-12-02 14:17:09,542-0400 DEBUG [dw-102 - POST /api/v2/config/mail/test/test%40example.com?timestamp=1638469029434] admin com.sun.mail.smtp - Verified Addresses
2021-12-02 14:17:09,543-0400 DEBUG [dw-102 - POST /api/v2/config/mail/test/test%40example.com?timestamp=1638469029434] admin com.sun.mail.smtp - test@example.com
2021-12-02 14:17:09,543-0400 TRACE [dw-102 - POST /api/v2/config/mail/test/test%40example.com?timestamp=1638469029434] admin com.sun.mail.smtp.protocol - DATA
2021-12-02 14:17:09,545-0400 TRACE [dw-102 - POST /api/v2/config/mail/test/test%40example.com?timestamp=1638469029434] admin com.sun.mail.smtp.protocol - 354 End data with <CR><LF>.<CR><LF>
2021-12-02 14:17:09,547-0400 TRACE [dw-102 - POST /api/v2/config/mail/test/test%40example.com?timestamp=1638469029434] admin com.sun.mail.smtp.protocol - Date: Thu, 2 Dec 2021 14:17:09 -0400 (AST)
2021-12-02 14:17:09,548-0400 TRACE [dw-102 - POST /api/v2/config/mail/test/test%40example.com?timestamp=1638469029434] admin com.sun.mail.smtp.protocol - From: Nexus IQ Server <nexus@iqserver>
2021-12-02 14:17:09,548-0400 TRACE [dw-102 - POST /api/v2/config/mail/test/test%40example.com?timestamp=1638469029434] admin com.sun.mail.smtp.protocol - To: test@example.com
2021-12-02 14:17:09,548-0400 TRACE [dw-102 - POST /api/v2/config/mail/test/test%40example.com?timestamp=1638469029434] admin com.sun.mail.smtp.protocol - Message-ID: c9abc13b-773f-4d9b-938e-4ff777339568
2021-12-02 14:17:09,548-0400 TRACE [dw-102 - POST /api/v2/config/mail/test/test%40example.com?timestamp=1638469029434] admin com.sun.mail.smtp.protocol - Subject: Test Email Configuration
2021-12-02 14:17:09,549-0400 TRACE [dw-102 - POST /api/v2/config/mail/test/test%40example.com?timestamp=1638469029434] admin com.sun.mail.smtp.protocol - MIME-Version: 1.0
2021-12-02 14:17:09,549-0400 TRACE [dw-102 - POST /api/v2/config/mail/test/test%40example.com?timestamp=1638469029434] admin com.sun.mail.smtp.protocol - Content-Type: multipart/mixed;
2021-12-02 14:17:09,549-0400 TRACE [dw-102 - POST /api/v2/config/mail/test/test%40example.com?timestamp=1638469029434] admin com.sun.mail.smtp.protocol - boundary="----=_Part_0_305000881.1638469029471"
2021-12-02 14:17:09,549-0400 TRACE [dw-102 - POST /api/v2/config/mail/test/test%40example.com?timestamp=1638469029434] admin com.sun.mail.smtp.protocol -
2021-12-02 14:17:09,550-0400 TRACE [dw-102 - POST /api/v2/config/mail/test/test%40example.com?timestamp=1638469029434] admin com.sun.mail.smtp.protocol - ------=_Part_0_305000881.1638469029471
2021-12-02 14:17:09,550-0400 TRACE [dw-102 - POST /api/v2/config/mail/test/test%40example.com?timestamp=1638469029434] admin com.sun.mail.smtp.protocol - Content-Type: text/html; charset=us-ascii
2021-12-02 14:17:09,550-0400 TRACE [dw-102 - POST /api/v2/config/mail/test/test%40example.com?timestamp=1638469029434] admin com.sun.mail.smtp.protocol - Content-Transfer-Encoding: 7bit
2021-12-02 14:17:09,550-0400 TRACE [dw-102 - POST /api/v2/config/mail/test/test%40example.com?timestamp=1638469029434] admin com.sun.mail.smtp.protocol -
2021-12-02 14:17:09,551-0400 TRACE [dw-102 - POST /api/v2/config/mail/test/test%40example.com?timestamp=1638469029434] admin com.sun.mail.smtp.protocol - Success! This is a test mail from http://localhost:8070/
2021-12-02 14:17:09,551-0400 TRACE [dw-102 - POST /api/v2/config/mail/test/test%40example.com?timestamp=1638469029434] admin com.sun.mail.smtp.protocol - ------=_Part_0_305000881.1638469029471--
2021-12-02 14:17:09,551-0400 TRACE [dw-102 - POST /api/v2/config/mail/test/test%40example.com?timestamp=1638469029434] admin com.sun.mail.smtp.protocol - .
2021-12-02 14:17:09,554-0400 TRACE [dw-102 - POST /api/v2/config/mail/test/test%40example.com?timestamp=1638469029434] admin com.sun.mail.smtp.protocol - 250 Ok: queued as 9GHiSjT253r4ZTNwf6qb1QOxuKUVzE0W1Xqz6TdvsJ8=@mailhog.example
2021-12-02 14:17:09,554-0400 DEBUG [dw-102 - POST /api/v2/config/mail/test/test%40example.com?timestamp=1638469029434] admin com.sun.mail.smtp - message successfully delivered to mail server
2021-12-02 14:17:09,555-0400 TRACE [dw-102 - POST /api/v2/config/mail/test/test%40example.com?timestamp=1638469029434] admin com.sun.mail.smtp.protocol - QUIT
2021-12-02 14:17:09,559-0400 TRACE [dw-102 - POST /api/v2/config/mail/test/test%40example.com?timestamp=1638469029434] admin com.sun.mail.smtp.protocol - 221 Bye
2021-12-02 14:17:09,559-0400 DEBUG [dw-102 - POST /api/v2/config/mail/test/test%40example.com?timestamp=1638469029434] admin com.sonatype.insight.brain.service.InsightMail - Sent mail to test@example.com in 104 ms.
0 Comments