Email per transaction

Triggering an email containing the isolated logs of selected transactions

Let Dave and Carol be software QA engineers working at a company called Fooware.com. As you might have guessed, Fooware.com sells foos. Yes, foos... Let Buscrit be a business critical backend system running at Fooware.com. Buscrit is called by a number of applications to make business-critical transactions of various types.

We would like to allow Carol to access the logging data generated by Buscrit as conveniently as possible. We could assume that Carol has access to the log files directly on the server where Buscrit runs. However, let us assume that accessing the log files is somehow impractical because one or ore more of the following conditions holds true:

Buscrit runs on multiple hosts and it is difficult to identify the host where a particular transaction was executed
Carol does not (or does not wish to) have access to the hosts where Buscrit runs
Buscrit is tested by multiple testers, e.g. Dave and Carol and others, simultaneously so that it is hard to identify and track an individual transaction in the log files

Given the above circumstances, let us create a logback configuration so that Carol receives an email message at the end of every transaction. We will iteratively refine this configuration so that Carol will receive an email containing the logs of each transaction in isolation and only for the transactions she explicitly selects.

Triggering an email message at the end of each transaction

We will be using SMTPAppender to generate emails containing logging data. Please refer to the appropriate section of the manual to familiarize yourself with SMTPAppender and its properties.

The logback-demo project contains a Struts action called PrimeAction. It can factorize integers. Here is the pertinent structure of PrimeAction's code:

package ch.qos.logback.demo.prime;

import org.apache.struts.action.Action;
...
import javax.servlet.http.HttpServletRequest;
import javax.servlet.http.HttpServletResponse;

public class PrimeAction extends Action {

  Logger logger = LoggerFactory.getLogger(PrimeAction.class);
  static Marker SMTP_TRIGGER = MarkerFactory.getMarker("SMTP_TRIGGER");

  public ActionForward execute(ActionMapping actionMapping,
                               ActionForm actionForm, HttpServletRequest request,
                               HttpServletResponse response) throws Exception {

    PrimeForm form = (PrimeForm) actionForm;

    Long number = form.getNumber();
    try {
      NumberCruncher nc = new NumberCruncherImpl();
      Long start = System.currentTimeMillis();
      Long[] result = nc.factor(number);
      Long duration = System.currentTimeMillis() - start;
      logger.info("Results computed in {} ms", duration);

      ...
    } finally {
      logger.info(SMTP_TRIGGER, "Prime computation ended");
    }
  }
}

In a real world application, a transaction would involve systems external to the application, e.g. a database or a messaging queue. For the sake of this example, let us consider each factorization request as a transaction. At the end of each factorization request, i.e. each transaction, the logger of the PrimeAction instance is invoked with the SMTP_TRIGGER marker and the message "Prime computation ended". We can capitalize on this logging request to clearly identify the end of every transaction in order to trigger an outgoing email message.

Here is a configuration file which uses JaninoEventEvaluator to trigger an outgoing email for logging event marked with SMTP_TRIGGER.

<configuration scan="true" scanPeriod="3 seconds">

  <!-- always a good idea to have an OnConsoleStatusListener -->
  <statusListener class="ch.qos.logback.core.status.OnConsoleStatusListener" />

  <appender name="SMTP" class="ch.qos.logback.classic.net.SMTPAppender">
    <smtpHost>NAME_OF_SMTP_HOST</smtpHost>
    <to>...</to>                                         
    <from>...</from>
    <subject>Prime - %mdc{number} by %mdc{userid} </subject>
    <layout class="ch.qos.logback.classic.html.HTMLLayout">
      <pattern>%date%level%logger{24}%msg</pattern>
    </layout>
    
    <evaluator class="ch.qos.logback.classic.boolex.JaninoEventEvaluator">
      <expression>
        marker != null  && marker.contains("SMTP_TRIGGER")
      </expression>
    </evaluator>
  </appender>

  <root level="DEBUG">
    <appender-ref ref="SMTP" /> 
  </root>

</configuration>

Transaction isolation

While the previous configuration file will trigger an outgoing email message whenever an event is marked with "SMTP_TRIGGER", the contents of the message will contain events generated by different transactions. With a little effort, we can actually separate events belonging to different transactions so that the outgoing email triggered at the end of the transaction contains logs from that transaction and only that transaction.

To isolate a given transaction, there must first be a way to distinguish it from other transactions. Typically this would be accomplished by putting the unique identifier of the transaction into the MDC.

String transactionId = ...; // extract id from transaction 
MDC.put("txId", transactionId);

In the UserServletFilter class, this is done by retrieving the id of the session and putting it into the MDC under the key "txId".

public class UserServletFilter implements Filter {

   public void doFilter(ServletRequest request, ServletResponse response,
                       FilterChain chain) throws IOException, ServletException {

    HttpServletRequest req = (HttpServletRequest) request;
    HttpSession session = req.getSession();
    MDC.put("txId", session.getId());
    ...
    try {
      // invoke subsequent filters
      chain.doFilter(request, response);
    } finally {
      // always clear the MDC at the end of the request
      MDC.clear();
    }
  }
}

By setting an appropriate discriminator in SMTPAppender, you can scatter incoming events into different buffers according to the value returned by the discriminator. Given that each request session is placed under the MDC key "txId", we can use an MDC-based discriminator to isolate the logs generated by each transaction.

<configuration scan="true" scanPeriod="3 seconds">

  <statusListener class="ch.qos.logback.core.status.OnConsoleStatusListener" />

  <appender name="SMTP" class="ch.qos.logback.classic.net.SMTPAppender">
    <smtpHost>NAME_OF_SMTP_HOST</smtpHost>
    <to>...</to>                                         
    <from>...</from>

    <smtpHost>NAME_OF_SMTP_HOST</smtpHost>
    <to>name@some.smtp.host</to>
    <from>testing@...</from>
    <subject>Prime - %mdc{number} by %mdc{userid} </subject>
    <layout class="ch.qos.logback.classic.html.HTMLLayout">
       <pattern>%date%level%logger{24}%msg</pattern>
    </layout>

    <evaluator class="ch.qos.logback.classic.boolex.JaninoEventEvaluator">
      <expression>
        marker != null && marker.contains("SMTP_TRIGGER") 
      </expression>
    </evaluator>

    <discriminator class="ch.qos.logback.classic.sift.MDCBasedDiscriminator">
      <key>txId</key>
      <defaultValue>default</defaultValue>
    </discriminator>
  </appender>  

  <root level="DEBUG">
    <appender-ref ref="SMTP" /> 
  </root>
</configuration>

After starting the logback-demo web-application with the above configuration file (with smtpHost and to options adapted for my environment) on localhost and then visiting the Prime number page to factorize the number 123, I received the following email:

Note that the above email contains the logs generated by the factorization of the number 123, without log pollution from any other "transaction".

Selective triggering & recipient addressing with transaction isolation

In a real world scenario, receiving isolated transactions is not enough. You would need to trigger outgoing emails only for certain users, typically QA engineers such as Dave and Carol. Moreover, you would want the emails generated by transaction made by Carol to Carol's mailbox and those generated by Dave to Dave's mailbox.

Selective triggering and addressing are two distinct problems. Depending on the exact circumstances, there are many ways of tackling these two issues. However, for the sake of simplicity, let us assume that the SMTP server at Fooware.com accepts address tags. Such an SMTP server treats an incoming message sent to username+xyz@fooware.com as if it were addressed to username@fooware.com, effectively stripping the +xyz part.

Let us further assume that we can somehow extract the email address of the user from the contents of her transaction, via a database lookup or perhaps some other means. The extracted email addressed is placed into the MDC under the key "txEmail".

Upon a logging event marked as SMTP_TRIGGER, the following configuration file will trigger an email message addressed to the value of "%mdc{txEmail}" but only if it contains the string "+log".

<configuration scan="true" scanPeriod="3 seconds">

  <statusListener class="ch.qos.logback.core.status.OnConsoleStatusListener" />

  <appender name="SMTP" class="ch.qos.logback.classic.net.SMTPAppender">
    <SMTPHost>NAME_OF_SMTP_HOST</SMTPHost>
    <to>%mdc{txEmail}</to>
    <from></from>
    <subject>Prime - %mdc{number}</subject>

    <layout class="ch.qos.logback.classic.html.HTMLLayout">
       <pattern>%date%level%logger{24}%msg</pattern>
    </layout>

    <discriminator class="ch.qos.logback.classic.sift.MDCBasedDiscriminator">
      <key>txId</key>
      <defaultValue>default</defaultValue>
    </discriminator>

    <evaluator class="ch.qos.logback.classic.boolex.JaninoEventEvaluator">
      <expression>
        (mdc != null &amp;&amp; mdc.get("txEmail") != null &amp;&amp; 
            ((String) mdc.get("txEmail")).contains("+log") )
        &amp;&amp;
        (marker != null  && marker.contains("SMTP_TRIGGER") )
      </expression>
    </evaluator>
  </appender>

  <root level="DEBUG">
    <appender-ref ref="SMTP" /> 
  </root>
</configuration>

If your particular SMTP server does not handle address tags, you can still use them within the evaluator but remove them in the recipient address with the help of the %replace conversion word. Here is the relevant configuration snippet:

<appender name="SMTP" class="ch.qos.logback.classic.net.SMTPAppender">
  <to>%replace(%mdc{txEmail}){'\+log', ''}</to>
  ...
</appender>

This replaces any occurrence of the string "+log" within the string returned by %mdc{txEmail} with the empty string, effectively erasing +log from the recipient address.

Buffer management in very busy systems

The solution described so far provides an amazingly flexible solution to the initial problem. Indeed, any QA-engineer at Fooware.com, say Carol, can have the logs generated by requests she makes to Buscrit sent to her automatically by email. All she has to do is to suffix the user part in her email address with "+log" when she registers with Buscrit.

By default SMTPAppender will cap the number of buffers it maintains to the value of the maxNumberOfBuffers option (64 by default) and automatically discards buffers untouched for at least 30 minutes. While this approach will work nicely in a test environment with few transactions, in a very busy production system, these buffer management mechanisms will cause Carol to receive truncated log buffers.

To deal with this problem, we instruct SMTPAppender to discard the appropriate buffer at the end of each transaction. This is done by logging an event marked as "FINALIZE_SESSION". Here is a modified version of PrimeAction which marks the end of a transaction with "FINALIZE_SESSION".

package ch.qos.logback.demo.prime;

import static ch.qos.logback.classic.ClassicConstants.FINALIZE_SESSION_MARKER;

public class PrimeAction extends Action {

  Logger logger = LoggerFactory.getLogger(PrimeAction.class);
  static Marker SMTP_TRIGGER = MarkerFactory.getMarker("SMTP_TRIGGER");
  static {
     // markers can hold references to other markers
     SMTP_TRIGGER.add(FINALIZE_SESSION_MARKER);
  }

  public ActionForward execute(ActionMapping actionMapping, ... ) throws Exception {

    Long number = form.getNumber();
    try {
      ...
    } finally {
      logger.info(SMTP_TRIGGER, "Prime computation ended");
      MDC.put("txId", null); // clear txId asap to avoid accidental rebirth
    }
  }
}

Not that at the end of each transaction the appropriate buffer is discarded, we can increase the value of maxNumberOfBuffers as shown in the next configuration file..

<configuration scan="true" scanPeriod="3 seconds">

  <statusListener class="ch.qos.logback.core.status.OnConsoleStatusListener" />

  <appender name="SMTP" class="ch.qos.logback.classic.net.SMTPAppender">
    <SMTPHost>NAME_OF_SMTP_HOST</SMTPHost>
    <to>%mdc{txEmail}</to>
    <from></from>
    <subject>Prime - %mdc{number}</subject>

    <layout class="ch.qos.logback.classic.html.HTMLLayout">
       <pattern>%date%level%logger{24}%msg</pattern>
    </layout>

    <discriminator class="ch.qos.logback.classic.sift.MDCBasedDiscriminator">
      <key>txId</key>
      <defaultValue>default</defaultValue>
    </discriminator>

    <cyclicBufferTracker class="ch.qos.logback.core.spi.CyclicBufferTracker">
      <maxNumberOfBuffers>512</maxNumberOfBuffers>
    </cyclicBufferTracker>

    <evaluator class="ch.qos.logback.classic.boolex.JaninoEventEvaluator">
      <expression>
        (mdc != null &amp;&amp; mdc.get("txEmail") != null &amp;&amp;
            ((String) mdc.get("txEmail")).contains("+log") )
        &amp;&amp;
        (marker != null  && marker.contains("SMTP_TRIGGER") )
      </expression>
    </evaluator>

  <root level="DEBUG">
    <appender-ref ref="SMTP" /> 
  </root>
</configuration>

With these latest changes, we can selectively send isolated logs for selected transactions to the concerned recipient, even in very busy production systems without excessive memory consumption.