Log4j SMTPAppender and deadlocks - Adding Timeout support

On the post: Sending Email alerts with Log4j we saw how we can easily send mails whenever our system has an exception. But we have to remember that using Apache Log4j SMTPAppender, can be very risky if not used cautiously. In general, the Log4j SMTPAppender has 2 main problems:

1. The part that send the mail, is synchronous. In fact, it is synchronous between all Log4j appenders. It means that when you log an error and a mail is being sent, all log commands are locked. This is quite risky. Especially when your system has many errors (for whatever reason). This may cause your whole system to get stuck. This issue can be easily handled by using: AsyncAppender. I may write about AsyncAppender in more detail in the future.
2. The code responsible for sending the mail, which is written by Apache developers, doesn't has a Timeout. That mean, a mail being sent can be stuck forever and simply cause your entire system to go into a deadlock.
   In this post, we will improve the Apache SMTPAppender to include a Timeout property. The Timout property will make sure, that if a mail is being sent using SMTP connection for too long, it will be dropped. We may loose a report about an exception, but we will make sure our system won't be stuck indefinitely.

We will create a new class name: SMTPAppenderTimeout, that extends SMTPAppender. This new class will override the SMTPAppender method: createSession.
The new createSession method will make sure to add the following 2 properties to the mail session: 

• mail.smtp.connectiontimeout
• mail.smtp.timeout

These 2 properties instruct the Java mail framework to set a timeout on the SMTP connection.
Let's have a look on the SMTPAppenderTimeout class:

package com.bashan.blog; 
import org.apache.log4j.net.SMTPAppender; 
import javax.mail.Authenticator; 
import javax.mail.PasswordAuthentication; 
import javax.mail.Session; 
import java.util.Properties; 
/** 
* @author Bashan 
*/ 
public class SMTPAppenderTimeout extends SMTPAppender { 
  private int timeout; 
  public int getTimeout() { 
    return timeout; 
  } 
  public void setTimeout(int timeout) { 
    this.timeout = timeout; 
  } 
  @Override 
  protected Session createSession() { 
    Properties props; 
    try { 
      props = new Properties(System.getProperties()); 
    } catch (SecurityException ex) { 
      props = new Properties(); 
    } 
    if (timeout > 0) { 
      String timeoutStr = Integer.toString(timeout); 
      props.setProperty("mail.smtp.connectiontimeout", timeoutStr); 
      props.setProperty("mail.smtp.timeout", timeoutStr); 
    } 
    if (getSMTPHost() != null) { 
      props.put("mail.smtp.host", getSMTPHost()); 
    } 
    Authenticator auth = null; 
    if (getSMTPPassword() != null && getSMTPUsername() != null) { 
      props.put("mail.smtp.auth", "true"); 
      auth = new Authenticator() { 
        protected PasswordAuthentication getPasswordAuthentication() { 
          return new PasswordAuthentication(getSMTPUsername(), getSMTPPassword()); 
        } 
      }; 
    } 
    Session session = Session.getInstance(props, auth); 
    if (getSMTPDebug()) { 
      session.setDebug(getSMTPDebug()); 
    } 
    return session; 
  } 
} 

You can also download the SMTPAppenderTimeout.



Let's see an example of a log4j.xml file which use SMTPAppenderTimeout to allow timeout of 5 seconds (5000ms):       

<?xml version="1.0" encoding="UTF-8" ?>
<!DOCTYPE log4j:configuration SYSTEM "log4j.dtd">
<log4j:configuration xmlns:log4j="http://jakarta.apache.org/log4j/">
	
	<appender name="RollFile" class="org.apache.log4j.RollingFileAppender">
		<param name="File" value="C:\\testlog.txt" />
		<param name="MaxFileSize" value="10MB" />
		<param name="MaxBackupIndex" value="1" />
		<layout class="org.apache.log4j.PatternLayout">
			<param name="ConversionPattern" value="%d{HH:mm:ss} %-5p [%c{1}]: %m%n" />
		</layout>
	</appender>
	<appender name="Email" class="com.bashan.blog.SMTPAppenderTimeout">
		<param name="BufferSize" value="10" />
		<param name="SMTPHost" value="smtpout.secureserver.net" />
		<param name="SMTPUsername" value="test_user" />
		<param name="SMTPPassword" value="test_password" />
		<param name="Timeout" value="5000" />
		<param name="From" value="someone@mail.com" />
		<param name="To" value="bashan@mail.com" />
		<param name="Subject" value="System Error Notification" />
		<layout class="org.apache.log4j.PatternLayout">
			<param name="ConversionPattern" value="%d [%t] %-5p %c %x - %m%n" />
		</layout>
	</appender>
	
	<root>
		<priority value="info" />
		<appender-ref ref="RollFile" />
		<appender-ref ref="Email" />
	</root>
</log4j:configuration>

You can also download the log4j.xml.

Adding TLS support to Log4j SMTP Appender

SMTPAppender that comes with log4j is a pretty useful Appender, allowing easily to start getting email alerts for errors in your application. But, this class is missing one important property (well, maybe more than one...): TLS support. Most modern mail servers use TLS for sending mails. TLS (Transport Layer Security) is a secure way for transfering information between two machines. For example, if you are using Google Apps (or even if you have a regular Gmail account) and you would like to use your account (user name and password of course) to send mail using SMTPAppender you won't be able to do it. That is because, Google allows sending mails only using TLS.

In this post: "Sending Email alerts with Log4j – Controlled Alerts" I showed how log4j SMTPAppender class can be extended to allow email alerts to be more controlled. In this post: "Sending SMS alerts with Log4j using ipipi.com", I showed how log4j SMTPAppender can be extended to send SMS error messages using ipipi.com service.
Both posts use this class: BaseFilteredSMTPAppender as a basic class for adding more neat capabilities to SMTPAppender.

I will show you how this class (BaseFilteredSMTPAppender) can be easily changed, to add the SMTPAppender TLS capabilities.
Unfortunatly, SMTPAppender class was not designed so well. It does not allow any control over the properties used for the creation of javax.mail.Session instance. In order to add TLS support to mail sending, we simply have to add to the javax.mail.Session class the following property:

props.put("mail.smtp.starttls.enable","true");

Where props is a simple Property instance containing mail properties.
And then we get the session instance, for example, by doing:

Session session = Session.getInstance(props);

But, as was said before, we have no access to the Properties instance, and therefore cannot add the TLS property.

Luckily, SMTPAppender does contain a protected method, for getting the Session instance: createSession. We can override this method and create a Session instance that contains TLS support. I copied the code of this method exactly as it was on the original SMTPAppender, and simply added the TLS property (note that TLS support is added only if user actually use the TLS property in the appender definition). This is how the class BaseFilteredSMTPAppender looks after adding the TLS support:

import org.apache.log4j.net.SMTPAppender;
import javax.mail.Authenticator;
import javax.mail.PasswordAuthentication;
import javax.mail.Session;
import java.util.*;
public abstract class BaseFilteredSMTPAppender extends SMTPAppender {
  private int timeFrame;
  private int maxEMails;
  protected long timeFrameMillis;
  protected Boolean isTLS;
  protected List<Date> exceptionDates = new ArrayList<Date>();
  public int getTimeFrame() {
    return timeFrame;
  }
  public void setTimeFrame(int timeFrame) {
    this.timeFrame = timeFrame;
  }
  public int getMaxEMails() {
    return maxEMails;
  }
  public void setMaxEMails(int maxEMails) {
    this.maxEMails = maxEMails;
  }
  public void setTLS(boolean isTLS) {
    this.isTLS = isTLS;
  }
  @Override
  public void activateOptions() {
    super.activateOptions();
    timeFrameMillis = timeFrame * 60 * 1000;
  }
  @Override
  protected Session createSession() {
    Properties props = null;
    try {
        props = new Properties (System.getProperties());
    } catch(SecurityException ex) {
        props = new Properties();
    }
    if (getSMTPHost() != null) {
      props.put("mail.smtp.host", getSMTPHost());
    }
    Authenticator auth = null;
    if(getSMTPUsername() != null && getSMTPPassword() != null) {
      props.put("mail.smtp.auth", "true");
      auth = new Authenticator() {
        protected PasswordAuthentication getPasswordAuthentication() {
          return new PasswordAuthentication(getSMTPUsername(), getSMTPPassword());
        }
      };
    }
    if (isTLS != null && isTLS)
    {
      props.put("mail.smtp.starttls.enable","true");
    }
    Session session = Session.getInstance(props, auth);
    if (getSMTPDebug()) {
        session.setDebug(getSMTPDebug());
    }
    return session;
  }
  protected void cleanTimedoutExceptions() {
    Date current = new Date();
    // Remove timedout exceptions
    Iterator<Date> itr = exceptionDates.iterator();
    while (itr.hasNext()) {
      Date exceptionDate = itr.next();
      if (current.getTime() - exceptionDate.getTime() > timeFrameMillis) {
        itr.remove();
      } else {
        break;
      }
    }
  }
  protected void addException() {
    exceptionDates.add(new Date());
  }
  protected boolean isSendMailAllowed() {
    return exceptionDates.size() < maxEMails;
  }
}

In order to use the Appender, only one additional parameter has to be added to the parameters already used and shown in the previous 2 blogs dealing with log4j SMTPAppender: TLS.

In order to make things a little interesting I will show you log4j configuration example using XML file instead of properties file:

<?xml version="1.0" encoding="UTF-8"?>
<!DOCTYPE log4j:configuration SYSTEM "log4j.dtd">
<log4j:configuration xmlns:log4j="http://jakarta.apache.org/log4j/" debug="false">  
   <appender name="console" class="org.apache.log4j.ConsoleAppender">
      <param name="Target" value="System.out"/>
      <layout class="org.apache.log4j.PatternLayout">
         <param name="ConversionPattern" value="%d{HH:mm:ss,SSS} %-5p [%c{1}] %m%n"/>
      </layout>
   </appender>
    <appender name="email" class="com.bashan.log4j.appender.FilteredSMTPAppender">
        <param name="BufferSize" value="10"/>
        <param name="SMTPHost" value="smtp.gmail.com"/>
        <param name="SMTPUsername" value="username@gmail.com"/>
        <param name="SMTPPassword" value="password"/>
        <param name="TLS" value="true"/>
        <param name="TimeFrame" value="10"/>
        <param name="MaxEMails" value="2"/>
        <param name="From" value="username@gmail.com"/>
        <param name="To" value="anotherUsername@gmail.com"/>
        <param name="Subject" value="Server Error"/>
        <layout class="org.apache.log4j.PatternLayout">
          <param name="ConversionPattern" value="%d{HH:mm:ss,SSS} %-5p [%c{1}] %m%n"/>
        </layout>
    </appender>  
    <root>
      <priority value="warn"/>
      <appender-ref ref="console"/>
      <appender-ref ref="email"/>
   </root>
</log4j:configuration>

This file can be dropped on your root src directory and log4j will know to find and load it automatically.

Note that TLS property is not mandatory. If you don't need TLS support, you can simply not add it to the appender properties.

Sending SMS alerts with Log4j using ipipi.com

In the post “Sending Email alerts with Log4j” and in the post “Sending Email alerts with Log4j – Controlled Alerts” I wrote about a simple way of sending email alerts using the ready log4j appender SMTPAppender. But, there are times in which an organization wants to send system alerts directly to a cell phone, in order to be notified about a problem as soon as possible.

ipipi.com is SMS service allowing sending SMS messages to almost every cell phone in the world. There is a support for sending SMS messages over SMTP protocol. Extending log4j SMTP appender to send SMS alert messages is easy task.

There is only one thing important to notice: Sending error message as SMS has to be much shorter than sending email. SMS messages can have very few characters. For this reason log4j SMTP appender has to be altered in order to send only the error string written to the log and the first line from the exception stack trace. This is done in the following class: FilteredShortSMTPAppender. Note that this class extends BaseFilteredSMTPAppender from the post “Sending Email alerts with Log4j – Controlled Alerts”:

import org.apache.log4j.spi.LoggingEvent;
import org.apache.log4j.helpers.LogLog;
import java.util.Date;
import javax.mail.Multipart;
import javax.mail.Transport;
import javax.mail.internet.MimeMultipart;
import javax.mail.internet.MimeBodyPart;

public class FilteredShortSMTPAppender extends BaseFilteredSMTPAppender {
  @Override
  public void activateOptions()
  {
    super.activateOptions();
    setBufferSize(1);
  }

  @Override
  protected void sendBuffer() {
    cleanTimedoutExceptions();
    if (isSendMailAllowed()) {
      try {
        MimeBodyPart part = new MimeBodyPart();
        StringBuffer sbuf = new StringBuffer();
        String t = layout.getHeader();
        if (t != null) {
          sbuf.append(t);
        }
        LoggingEvent event = cb.get();
        sbuf.append(layout.format(event));
        if (layout.ignoresThrowable()) {
          String[] s = event.getThrowableStrRep();
          if (s != null && s.length > 0) {
            sbuf.append(s[0]);
        }
        t = layout.getFooter();
          }
        if (t != null) {
          sbuf.append(t);
        }
        part.setContent(sbuf.toString(), layout.getContentType());
        Multipart mp = new MimeMultipart();
        mp.addBodyPart(part);
        msg.setContent(mp);
        msg.setSentDate(new Date());
        Transport.send(msg);
        addException();
      }
      catch (Exception e) {
        LogLog.error("Error occured while sending e-mail notification.", e);
      }
    }
  }
}

The class FilteredShortSMTPAppender allows to send email alerts in a short version. It can be used exactly the same as FilteredSMTPAppender, besides the parameter: BufferSize is no longer needed, since we do not send log history with the mail message.

After we have the class FilteredShortSMTPAppender we can easily extend it to send SMS email alerts over SMTP using the ipipi.com service:

import org.apache.log4j.helpers.LogLog;
import java.io.IOException;
import java.util.Properties;

public final class IPIPISmsOverSmtpAppender extends FilteredShortSMTPAppender {
  private static final String KEY_HOST = "host";
  private static final String TO_SERVER = "to.server";
  private String toServer;

  @Override
  public void activateOptions() {
    Properties properties = new Properties();
    try {
      properties.load(IPIPISmsOverSmtpAppender.class.getResourceAsStream("ipipi.properties"));
      setSMTPHost(properties.getProperty(KEY_HOST));
      setFrom(getSMTPUsername() + "@" + getSMTPHost());
      toServer = properties.getProperty(TO_SERVER);
      setTo(parseAddress(getTo()));  
    }
    catch (IOException ioe) {
      LogLog.error("Failed loading IPIPI service properties", ioe);
    }
    super.activateOptions();
  }

  private String parseAddress(String addressStr) {
    String[] addresses = addressStr.split(",");
    StringBuffer sb = new StringBuffer();
    for (String address : addresses) {
      sb.append(address).append("@").append(toServer).append(",");
    }
    return sb.substring(0, sb.length() - 1);
  }
}

Note that the information regarding the ipipi.com service is on external file named ipipi.properties. This file should be located on the same package as the IPIPISmsOverSmtpAppender class:

host=ipipi.com
to.server=sms.ipipi.com

This class extends the capabilities of the class FilteredShortSMTPAppender to allow adding cell phone numbers instead of email addresses. In your appender configuration file you can simply insert cell phone numbers and this code will know to convert the cell phone numbers to email addresses used for ipipi.com convention. The service allows sending SMS message to almost any cell phone on the planet by using the cell phone owner as the email address prefix. for example, you can simply send SMS message to a cell phone by emailing to: 972541234567@ipipi.com. Of course, that the service costs money, and in order to send SMS messages you must first register to the service and buy a package of SMS messages. Your registered username and password is used as login details for ipipi.com SMTP server.

This is an example of the IPIPISmsOverSmtpAppender log4j configuration:

log4j.rootLogger=INFO, a, sms
log4j.appender.a=org.apache.log4j.ConsoleAppender
log4j.appender.a.layout=org.apache.log4j.PatternLayout
log4j.appender.a.layout.ConversionPattern=%d{HH:mm:ss} %-5p [%c{1}]: %m%n
log4j.appender.sms=com.bashan.log4j.IPIPISmsOverSmtpAppender
log4j.appender.sms.SMTPUsername=bashan
log4j.appender.sms.SMTPPassword=bashan
log4j.appender.sms.TimeFrame=10
log4j.appender.sms.MaxEMails=30
log4j.appender.sms.To=972541234567,972542345678
log4j.appender.sms.layout=org.apache.log4j.PatternLayout
log4j.appender.sms.layout.ConversionPattern=%d [%t] %-5p %c %x - %m%n

Note for few things:

• Phone numbers must contain country prefix.
  
• TimeFrame and MaxEMails parameters from the class: FilteredSMTPAppender exist on this appender as well.
  
• BufferSize parameter is no longer used.

Sending Email alerts with Log4j – Controlled Alerts

In one of my recent posts I wrote about sending email alerts using log4j. The SMTPAppender supplied with log4j is nice, but it a lacks of a basic important feature, when it comes to sending mail alerts: mails sent are not controlled. On every exception logged by log4j a mail message is sent. This is not always a good thing, since there are times servers may encounter massive amount of exceptions in a short period of time. When such a thing happens we don’t always care about all the exceptions, usually because when big amount of exceptions happen on a short period of time, there is a high probability they are all of the same type and happen from the same cause.

For example, the server may be trying to send some information over the network to a remote machine. If the server fails, it tries to send the information again after one second. Suppose the network is going down for 30 minutes. This will cause the server to send big amount of email alerts. When actually it is necessary to receive only one email alert notifying about the problem.

For this reason, I wrote an email alerts appender that extends the capabilities of the SMTPAppender supplied by log4j, to add basic level of controllability over the mail alerts send by log4j. The appender simply gives adds 2 new parameters:

• TimeFrame: Time frame in minutes.
• MaxEmails: Maximum allowed email alerts.

Both parameters restricts the maximum allowed email alerts that can be send in a given time frame.

For example, you can define that the maximum amount of emails in 30 minutes is 10. In a case of a severe server problem that generates big amount of email alerts, the appender simply stops sending mails after 10 messages were already sent. After 30 minutes, the server will allow mails again. This is not an ideal solution, but it is simple and neat, and it answers most of the needs from a basic alerts mechanism.

The appender is constructed from 2 classes:

• BaseFilteredSMTPAppender: which is an abstract class that defines the basic behavior of the controlled smtp appender.
• FilteredSMTPAppender: which extend BaseFilteredSMTPAppender to create the actual controlled filtering of email alerts.

This is the code of the BaseFilteredSMTPAppender:

import org.apache.log4j.net.SMTPAppender;
import java.util.Date;
import java.util.List;
import java.util.ArrayList;
import java.util.Iterator;
public abstract class BaseFilteredSMTPAppender extends SMTPAppender {
  private int timeFrame;
  private int maxEMails;
  protected long timeFrameMillis;
  protected List<Date> exceptionDates = new ArrayList<Date>();
  public int getTimeFrame() {
    return timeFrame;
  }
  public void setTimeFrame(int timeFrame) {
    this.timeFrame = timeFrame;
  }
  public int getMaxEMails() {
    return maxEMails;
  }
  public void setMaxEMails(int maxEMails) {
    this.maxEMails = maxEMails;
  }
  @Override
  public void activateOptions()
  {
    super.activateOptions();
    timeFrameMillis = timeFrame * 60 * 1000;
  }
  protected void cleanTimedoutExceptions()
  {
    Date current = new Date();
    // Remove timedout exceptions
    Iterator<Date> itr = exceptionDates.iterator();
    while (itr.hasNext())
    {
      Date exceptionDate = itr.next();
      if (current.getTime() - exceptionDate.getTime() > timeFrameMillis)
      {
        itr.remove();
      }
      else
      {
        break;
      }
    }
  }
  protected void addException()
  {
    exceptionDates.add(new Date());
  }
  protected boolean isSendMailAllowed()
  {
    return exceptionDates.size() < maxEMails;
  }
}

And the code of the FilteredSMTPAppender which is much simpler and contains only the actual filtering:

import org.apache.log4j.net.SMTPAppender;
public class FilteredSMTPAppender extends BaseFilteredSMTPAppender {
  @Override
  protected void sendBuffer()
  {
    cleanTimedoutExceptions();
    if (isSendMailAllowed())
    {
      super.sendBuffer();
      addException();
    }
  }
}

And log4j configuration is very similar to the one already posted on the previous blog dealing with email alerts, besides adding the 2 new parameters: TimeFrame, MaxEmails. Here is an example if how it looks:

log4j.rootLogger=INFO, a, email
log4j.appender.a=org.apache.log4j.ConsoleAppender
log4j.appender.a.layout=org.apache.log4j.PatternLayout
log4j.appender.a.layout.ConversionPattern=%d{HH:mm:ss} %-5p [%c{1}]: %m%n

log4j.appender.email=com.bashan.log4j.FilteredSMTPAppender
log4j.appender.email.BufferSize=10
log4j.appender.email.SMTPHost=mysmtp.mailserver.net
log4j.appender.email.SMTPUsername=myusername@mycompany.com
log4j.appender.email.SMTPPassword=mypassword
log4j.appender.email.TimeFrame=30
log4j.appender.email.MaxEMails=10
log4j.appender.email.From=admin@mycompany.com
log4j.appender.email.To=me@mycompany.com
log4j.appender.email.Subject=My Module Error
log4j.appender.email.layout=org.apache.log4j.PatternLayout
log4j.appender.email.layout.ConversionPattern=%d [%t] %-5p %c %x - %m%n

That’s it. Now you can get email alerts, without your mail box being blocked… ;-)