Logback SMTPAppender not sending email

Question

I am attempting to use Logback for logging in my java application. I believe I have it correctly configured, but when an error is logged

INFO in ch.qos.logback.classic.net.SMTPAppender[EMAIL] - About to send out SMTP message "Testing Main" to [[email protected]]

is printed to the console, nothing else is printed after that, and the email is never received. If I enter an invalid smtp host or username/password in the config it fails immediately on attempting to send, so it is establishing a connection.

My POM:

 <repositories>
    <repository>
    <id>Java.Net</id>
    <url>http://download.java.net/maven/2/</url>
    </repository>
  </repositories>
  <dependencies>

            <dependency>
                <groupId>javax.activation</groupId>
                <artifactId>activation</artifactId>
                <version>1.1.1</version>
            </dependency>


             <dependency>
                 <groupId>javax.mail</groupId>
                 <artifactId>mail</artifactId>
                 <version>1.4.7</version>
             </dependency>

            <dependency>
                <groupId>ch.qos.logback</groupId>
                <artifactId>logback-core</artifactId>
                <version>1.1.1</version>
            </dependency>
            <dependency>
                <groupId>ch.qos.logback</groupId>
                <artifactId>logback-classic</artifactId>
                <version>1.1.1</version>
            </dependency>
            <dependency>
                <groupId>org.slf4j</groupId>
                <artifactId>slf4j-api</artifactId>
                <version>1.7.6</version>
            </dependency>


            <dependency>
                <groupId>org.slf4j</groupId>
                <artifactId>jcl-over-slf4j</artifactId>
                <version>1.7.6</version>
            </dependency>


         </dependencies>

logback.xml

<configuration>
    <!-- dump status message on the console as they arrive -->
    <statusListener class="ch.qos.logback.core.status.OnConsoleStatusListener" />

    <appender name="EMAIL" class="ch.qos.logback.classic.net.SMTPAppender">
        <smtpHost>mail.optonline.net</smtpHost>
        <username>xxxxx</username>
        <password>xxxxxx</password>
        <smtpPort>587</smtpPort>
        <to>[email protected]</to>
        <from>[email protected]</from>
        <subject>Testing %logger
        {20}

        - %m</subject>

        <layout class="ch.qos.logback.classic.PatternLayout">
            <pattern>%d
                {HH:mm:ss.SSS}

                [%thread] %-5level %logger
                {1}

                -%msg%n
            </pattern>
        </layout>
    </appender>

    <root level="info">
        <appender-ref ref="EMAIL" />
    </root>
</configuration>

The console

10:45:44,596 |-INFO in ch.qos.logback.classic.LoggerContext[default] - Could NOT find resource [logback.groovy]
10:45:44,596 |-INFO in ch.qos.logback.classic.LoggerContext[default] - Could NOT find resource [logback-test.xml]
10:45:44,596 |-INFO in ch.qos.logback.classic.LoggerContext[default] - Found resource [logback.xml] at [file:/C:/Users/xxxxx/workspace/logback-test/target/classes/logback.xml]
10:45:44,650 |-INFO in ch.qos.logback.classic.joran.action.ConfigurationAction - debug attribute not set
10:45:44,658 |-INFO in ch.qos.logback.core.joran.action.StatusListenerAction - Added status listener of type [ch.qos.logback.core.status.OnConsoleStatusListener]
10:45:44,673 |-INFO in ch.qos.logback.core.joran.action.AppenderAction - About to instantiate appender of type [ch.qos.logback.classic.net.SMTPAppender]
10:45:44,688 |-INFO in ch.qos.logback.core.joran.action.AppenderAction - Naming appender as [EMAIL]
10:45:44,765 |-INFO in ch.qos.logback.classic.joran.action.RootLoggerAction - Setting level of ROOT logger to INFO
10:45:44,765 |-INFO in ch.qos.logback.core.joran.action.AppenderRefAction - Attaching appender named [EMAIL] to Logger[ROOT]
10:45:44,766 |-INFO in ch.qos.logback.classic.joran.action.ConfigurationAction - End of configuration.
10:45:44,767 |-INFO in ch.qos.logback.classic.joran.JoranConfigurator@ddc652f - Registering current configuration as safe fallback point
10:45:44,774 |-INFO in ch.qos.logback.classic.net.SMTPAppender[EMAIL] - SMTPAppender [EMAIL] is tracking [1] buffers
exiting
10:45:44,791 |-INFO in ch.qos.logback.classic.net.SMTPAppender[EMAIL] - About to send out SMTP message "Testing Main" to [[email protected]]
10:45:44,791 |-INFO in ch.qos.logback.classic.net.SMTPAppender[EMAIL] - About to send out SMTP message "Testing Main" to [[email protected]]

This is the code that is running to produce my test errors

logger.error("Entering app");
logger.error("exiting app");

System.out.println("exiting");

Any help debugging this issue would be greatly appreciated Thank you

Elixir

Do you have access to the logs of the smtp server sending the mails? It might be that the error occurs on that sytem. – Jasmine

Unfortunately I do not, the server I am using for testing is run by an ISP. Thats an interesting idea though, I may try setting up my own server for testing. – Elixir

I am facing same issue. Not able to send email. I have used same code as above. Please suggest the solution. – Hairline

Answer 1

It seems to have been an issue with the SMTP server I was using. I setup Papercut as a local smtp server and I can see it receive the messages

Elixir

Hi, could you explain further. I have set up same logger configuration for three servers, and only one is not working. How does papercut helps – Hawkes

Papercuts is just a local smtp server. Using that, I could see the logger was correctly firing the mail requests at the correct time. Knowing that it wasnt the logger not working correctly, I could move on to debugging why my real smtp server was not working. In this case it was not accepting requests from my IP. – Elixir

Thank you, got the problem fixed. Logger was fine but gmail was preventing a single server due its security – Hawkes

Gmail security reference link - support.google.com/accounts/answer/6010255 @Hawkes – Youngs

Answer 2

I also faced this issue and found the solution. To run the above code, you have to make some changes in your configuration:

1. Add <STARTTLS>true</STARTTLS>
2. Add <asynchronousSending>false</asynchronousSending>

Hairline

wasn't expecting to need <asynchronousSending>false</asynchronousSending>. Thanks! – Phonon

Thank you so much. I know the issue because of "starttls" but don't have any idea how to define it. – Orthopedist

Answer 3

If you are using the gmail for sending the emails then following logback configurations worked for me.

<springProperty scope="context" name="smtpHost" source="spring.mail.host" />
    <springProperty scope="context" name="smtpPort" source="spring.mail.port" />
    <springProperty scope="context" name="username" source="spring.mail.username" />
    <springProperty scope="context" name="password" source="spring.mail.password" />

<appender name="EMAIL" class="ch.qos.logback.classic.net.SMTPAppender">
    <smtpHost>${smtpHost}</smtpHost>
    <smtpPort>${smtpPort}</smtpPort>
    <SSL>true</SSL>
    <username>${username}</username>
    <password>${password}</password>
    <to>${username}</to>
    <from>${username}</from>
    <subject>Error From ERP: %logger{20} - %m</subject>

    <layout class="ch.qos.logback.classic.html.HTMLLayout"/>
    <cyclicBufferTracker class="ch.qos.logback.core.spi.CyclicBufferTracker">
        <!-- only 5 log entries on email -->
        <bufferSize>5</bufferSize>
    </cyclicBufferTracker>
</appender>

While my configurations exists in application.yaml file which can be seen I am trying to fetch them from there. smtp port is set to 465 in my case.

Racoon