scheduleAtFixedRate in custom SMTPAppender doesn't delay

Question

I am sending objects to a server (around 90 in sequence) when there is an Exception e.g. endpoint is down, Logback triggers a custom STMP appender, Which onlys sends 1 email with max. 10 logs and then there is a delay and the other logs get sent. Is it possible, that start()gets invoked too often?

Problem:
scheduler.scheduleAtFixedRate(this::sendEmail, 1, 1L, TimeUnit.HOURS);
Doesn't delay after executed once and directly executes another time so that many emails get sent in under an hour.

What do I have to change that the delay of the scheduler works?

After debugging I notices that Attaching appender named [EMAIL] to Logger[ROOT] occured two times could that be the problem, if yes how can I fix that?

Image of the flood (As you can see, two email sent in under one hour...)

Logback.xml config:

<configuration debug="true">

<!-- Logging per console and per email -->
<appender name="CONSOLE" class="ch.qos.logback.core.ConsoleAppender">
    <layout class="ch.qos.logback.classic.PatternLayout">
        <Pattern>
            <!-- sets the format of the output -->
            %d{HH:mm:ss.SSS} [%t] %-5level %logger{36} - %msg%n
        </Pattern>
    </layout>
</appender>

<appender name="EMAIL" class="com.konverto.phonebillasaj.appenders.ScheduledSMTPAppender">
    <subject>TESTING: %logger{20} - %m</subject>
    <layout class="ch.qos.logback.classic.html.HTMLLayout" />

    <smtpHost>smtp.xxx.net</smtpHost>
    <smtpPort>587</smtpPort>
    <STARTTLS>true</STARTTLS>
    <username>[email protected]</username>
    <password>myPass</password>
    <to>[email protected]</to>
    <from>[email protected]</from>
    <maxMessages>10</maxMessages>

    <!-- for testing , comment in production, default 256 -->
    <cyclicBufferTracker class="ch.qos.logback.core.spi.CyclicBufferTracker">
        <!-- Send just one log entry per email, ready for a lot of emails if you put one. -->
        <bufferSize>1</bufferSize>
    </cyclicBufferTracker>

    <!-- for testing , comment in production, default asynchronousSending = true -->
    <asynchronousSending>false</asynchronousSending>
</appender>


<logger name="com.konverto.phonebillasaj" level="error" additivity="false">
    <appender-ref ref="EMAIL"/>
    <appender-ref ref="CONSOLE" />
</logger>

<root level="error">
    <appender-ref ref="EMAIL" />
    <appender-ref ref="CONSOLE" />
</root>

Code of the appender:

public class ScheduledSMTPAppender extends SMTPAppender {

private final ThreadFactory tf = r -> {
    Thread t = new Thread(r, "ScheduledSMTPAppender Thread");
    t.setDaemon(true); //make daemon or it will prevent your program to exit
    return t;
};
private final ScheduledExecutorService scheduler = Executors.newScheduledThreadPool(1, tf);


private final List<ILoggingEvent> events = new ArrayList<>();

private int maxMessages = 10;

public ScheduledSMTPAppender() {
    super();
}

public ScheduledSMTPAppender(EventEvaluator<ILoggingEvent> eventEvaluator) {
    super(eventEvaluator);
}

@Override public void start() {
    super.start();
    scheduler.scheduleAtFixedRate(this::sendEmail, 1, 1L, TimeUnit.HOURS);
}

@Override protected void sendBuffer(CyclicBuffer<ILoggingEvent> cb, ILoggingEvent lastEventObject) {
    events.add(lastEventObject);

    if (events.size() > maxMessages)
    {
        sendEmail();
    }
}

//needs to be synchronized for thread safety
private synchronized void sendEmail() {
    try {
        if (events.isEmpty()){
            return;
        }
        ILoggingEvent lastEvent = events.get(events.size() - 1);
        events.remove(events.size() - 1);
        CyclicBuffer<ILoggingEvent> cb;

        if (events.isEmpty()) {
            cb = new CyclicBuffer<>(1);
        } else {
            cb = new CyclicBuffer<>(events.size());
            for (ILoggingEvent e : events){
                cb.add(e);
            }

        }
        super.sendBuffer(cb, lastEvent);
        events.clear();
    } catch (Exception e) {
        //Important to have a catch all here or the scheduled task will die
        addError("Error occurred while sending e-mail notification.", e);
    }
}

//this allows to make "maxMessages" a parameter of your appender
public int getMaxMessages() {
    return maxMessages;
}

public String getContentType() {
    return layout.getContentType();
}

public void setMaxMessages(int maxMessages) {
    this.maxMessages = maxMessages;

}

Answer 1

This seems to be the problem

@Override 
public void start() {
    super.start();
    scheduler.scheduleAtFixedRate(this::sendEmail, 1, 1L, TimeUnit.HOURS);
}

This scheduler will queue up the sendEmail task for every appender initialised. Can you log the instance of the object or some id along with each log line, and each time start is called? That should clarify the scenario.

Just to be clear - I tried the same code using the Sysout instead of the logger (and initialised in the main method) and it worked as expected. Here's the code

public class ScheduledSMTPAppender /*extends SMTPAppender*/ {

    private static final ThreadFactory tf = r -> {
        Thread t = new Thread(r, "ScheduledSMTPAppender Thread");
        t.setDaemon(true); //make daemon or it will prevent your program to exit
        return t;
    };
    private static final ScheduledExecutorService scheduler = Executors.newScheduledThreadPool(1, tf);


    private final List<String> events = new ArrayList<>();

    private int maxMessages = 10;

    public static void main(String args[]) {
        ScheduledSMTPAppender app = new ScheduledSMTPAppender();
        System.out.println("started");
        Thread t = new Thread(() -> {
            try {
                scheduler.awaitTermination(1, TimeUnit.HOURS);
            } catch (Exception e) {
            }
        });
        System.out.println("awaiting termination");
        t.start();
        System.out.println("thread initiated");
        new Thread(() -> {
            // Thread to add events to check logs
            for (int i =0;i<10;i++)
            {app.addEvent("asd");
            try {Thread.sleep(1000);
            } catch(Exception e) {};}
        }).start();
    }


    public ScheduledSMTPAppender() {
        super();
        System.out.println("starting");
        scheduler.scheduleAtFixedRate(this::sendEmail, 1, 1L, TimeUnit.SECONDS);
    }

    /*
    public ScheduledSMTPAppender(EventEvaluator<String> eventEvaluator) {
        super(eventEvaluator);
    }

    @Override
    public void start() {
        super.start();
        scheduler.scheduleAtFixedRate(this::sendEmail, 1, 1L, TimeUnit.HOURS);
    }*/

    //@Override
    protected void sendBuffer(List<String> cb, String lastEventObject) {
        //System.out.println("sending email");
        events.add(lastEventObject);

        if (events.size() > maxMessages) {
            sendEmail();
        }
        System.out.println(new Date() + "sent email" + lastEventObject);
    }

    //needs to be synchronized for thread safety
    private synchronized void sendEmail() {
        try {
            if (events.isEmpty()) {
                return;
            }
            String lastEvent = events.get(events.size() - 1);
            events.remove(events.size() - 1);
            List<String> cb;

            if (events.isEmpty()) {
                cb = new ArrayList<>(1);
            } else {
                cb = new ArrayList<>(events.size());
                for (String e : events) {
                    cb.add(e);
                }

            }
            sendBuffer(cb, lastEvent);
            events.clear();
        } catch (Exception e) {
            //Important to have a catch all here or the scheduled task will die
            //addError("Error occurred while sending e-mail notification.", e);
        }
    }

    //this allows to make "maxMessages" a parameter of your appender
    public int getMaxMessages() {
        return maxMessages;
    }

//    public String getContentType() {
//        return layout.getContentType();
//    }

    public void setMaxMessages(int maxMessages) {
        this.maxMessages = maxMessages;

    }

    public void addEvent(String s) {
        events.add(s);
    }
}