Triggering an email containing the isoloated logs of selected transactions

Let Dave and Tata be software 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 back-end 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 Tata, a QA-engineer, to access the logging data generated by Buscrit as conveniently as possible. Tata could access the log files directly on the server where Buscrit runs. Let us assume that accessing the log files is impractical because one or ore more of the following conditions holds true:

  1. Buscrit runs on multiple hosts and it is difficult to identify the host where a particular transaction was executed
  2. Tata does not (or does not wish to) have access to the hosts where Byscrit runs
  3. Buscrit is tested by multiple testers simultanesouly so that it is hard to indetify and track an individual transaction in the log files

Given the above circumstances, let us create a logback configuration so that Tata receives an email message at the end of every transaction. We will iteratively refine this configuration so that Tata 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 ships with a Struts action, namely PrimeAction, which can factorize integers. Here is the pertinent structure of the 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);
  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 simplicity, let us consider each factorization request as a transaciton. 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". Thus, we can capitalize on this logging request to clarly identify the end of every transaction in order to trigger an outgoing 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>
    <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

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

  <!-- always a good idea to have an OnConsoleStatusListener -->

  <appender name="SMTP" class="ch.qos.logback.classic.net.SMTPAppender">
    <SMTPHost>NAME_OF_SMTP_HOST</SMTPHost>
    <To>com</To>
    <From></From>
    <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>uuid</key>
      <defaultValue>default</defaultValue>
    </discriminator>

    <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>uuid</key>
      <defaultValue>default</defaultValue>
    </discriminator>

  </appender>  

Selective triggering & Transaction isolation

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

  <!-- always a good idea to have an OnConsoleStatusListener -->

  <appender name="SMTP" class="ch.qos.logback.classic.net.SMTPAppender">
    <SMTPHost>NAME_OF_SMTP_HOST</SMTPHost>
    <To>com</To>
    <From></From>
    <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>uuid</key>
      <defaultValue>default</defaultValue>
    </discriminator>

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

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

  </appender>