Advanced Debugging of SMTP with Sonatype Server Products

 

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:

  1. 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
  2. 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
  3. 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
  4. 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.

 

 

 

Have more questions? Submit a request

0 Comments

Article is closed for comments.