Chapter 4. Messages and logging

Messages and logging are frustratingly complex to manage. Java provides a flexible and robust set of logging APIs. Production systems can leverage that infrastructure in sophisticated ways to control what is logged, where, and how. But configuring that infrastructure, even learning how to configure it, are substantial tasks. They’re far more than a casual user running a single application on a local machine is ever likely to need.

XML Calabash tries to offer the best of both worlds. It uses the SLF4J logging framework (version 2.0.16) with the “logback classic” back end. (Other backends can be used, SLF4J supports the full logging ecosystem.) All of the messages that XML Calabash produces are sent to the logger. If the debug is used, the logging messages are also printed on the console. For more control, see Section 4.1, “Configuring the logging back end”.

In front of that back end, XML Calabash has its own “message reporter” interface which it ties into the various message listener and error listener APIs provided by the APIs it uses. Casual users can set the “verbosity level” (via a configuration option or on the command line) to quickly filter the level of detail they’re interested in.

That leaves only the category of “progress messages” to resolve. Often, it’s most convenient to run a pipeline and get its results with no concern about what steps ran, or in what order. But for long running or complex pipelines, it may be reassuring, especially during development, to track the progress of steps in the pipeline.

XML Calabash provides three “visualizations” for progress: silent, plain, and detailed. (Custom visualizations are also possible.) The silent visualizer, as the name suggests, prints nothing. That’s the default.

The plain visualizer prints the names of steps as they are run. It elides some noise, specifically the majority of steps introduced when constructing the graph. The plain output for sample pipeline in the graphs chapter looks like this:

Running p:declare-step
Running . cx:document (../xml/default-input.xml)
Running . p:xinclude
Running . ex:ident
Running .. p:identity
Running . p:for-each
Running .. p:identity/id1
Running .. p:add-attribute/add
Running .. p:identity/id1
Running .. p:add-attribute/add
Running .. p:identity/id1
Running .. p:add-attribute/add
Running .. p:identity/id1
Running .. p:add-attribute/add
Running . p:wrap-sequence
Running . p:identity/id2

The detail visualizer tracks the progress of all steps, both the start and end of compound steps, and can track the documents produced by each step along the way. With both step and document reporting enabled, its output looks like this:

┌─ p:declare-step/declare-step
│  ├─ cx:head/declare-step_head
│  ├─ cx:document/document (../xml/default-input.xml)
│  │  ┄ cx:document/document.result ⟶ <doc ...>
│  ├─ p:xinclude/xinclude
│  │  ┄ p:xinclude/xinclude.result ⟶ <doc ...>
│  ├─ ex:ident/declare-step_2
│  │  ├─ cx:head/declare-step_2_head
│  │  │  ┄ cx:head/declare-step_2_head.source ⟶ <doc ...>
│  │  ├─ p:identity/identity
│  │  │  ┄ p:identity/identity.result ⟶ <doc ...>
│  │  │  ┄ cx:foot/declare-step_2_foot.result ⟶ <doc ...>
│  │  ├─ cx:foot/declare-step_2_foot
│  ├─ ex:ident/declare-step_2
│  ├─ cx:select/select_IC511
│  │  ┄ cx:select/select_IC511.result ⟶ <chap ...>
│  │  ┄ cx:select/select_IC511.result ⟶ <chap ...>
│  │  ┄ cx:select/select_IC511.result ⟶ <chap ...>
│  │  ┄ cx:select/select_IC511.result ⟶ <app ...>
│  ├─ p:for-each/for-each
│  │  ├─ cx:head/for-each_head
│  │  │  ┄ cx:head/for-each_head.current ⟶ <chap ...>
│  │  ├─ p:identity/id1
│  │  │  ┄ p:identity/id1.result ⟶ <chap ...>
│  │  ├─ p:add-attribute/add
│  │  │  ┄ p:add-attribute/add.result ⟶ <chap ...>
│  │  │  ┄ cx:foot/for-each_foot.!result ⟶ <chap ...>
│  │  ├─ cx:foot/for-each_foot
│  │  ├─ cx:head/for-each_head
│  │  │  ┄ cx:head/for-each_head.current ⟶ <chap ...>
│  │  ├─ p:identity/id1
│  │  │  ┄ p:identity/id1.result ⟶ <chap ...>
│  │  ├─ p:add-attribute/add
│  │  │  ┄ p:add-attribute/add.result ⟶ <chap ...>
│  │  │  ┄ cx:foot/for-each_foot.!result ⟶ <chap ...>
│  │  ├─ cx:foot/for-each_foot
│  │  ├─ cx:head/for-each_head
│  │  │  ┄ cx:head/for-each_head.current ⟶ <chap ...>
│  │  ├─ p:identity/id1
│  │  │  ┄ p:identity/id1.result ⟶ <chap ...>
│  │  ├─ p:add-attribute/add
│  │  │  ┄ p:add-attribute/add.result ⟶ <chap ...>
│  │  │  ┄ cx:foot/for-each_foot.!result ⟶ <chap ...>
│  │  ├─ cx:foot/for-each_foot
│  │  ├─ cx:head/for-each_head
│  │  │  ┄ cx:head/for-each_head.current ⟶ <app ...>
│  │  ├─ p:identity/id1
│  │  │  ┄ p:identity/id1.result ⟶ <app ...>
│  │  ├─ p:add-attribute/add
│  │  │  ┄ p:add-attribute/add.result ⟶ <app ...>
│  │  │  ┄ cx:foot/for-each_foot.!result ⟶ <app ...>
│  │  ├─ cx:foot/for-each_foot
│  ├─ p:for-each/for-each
│  ├─ p:wrap-sequence/wrap-sequence
│  │  ┄ p:wrap-sequence/wrap-sequence.result ⟶ <set ...>
│  ├─ p:identity/id2
│  │  ┄ p:identity/id2.result ⟶ <set ...>
│  │  ┄ cx:foot/declare-step_foot.result ⟶ <set ...>
│  ├─ cx:foot/declare-step_foot
└─ p:declare-step/declare-step

It’s worth noting that the IDs in this output, for example “select_IC511”, are the same IDs that the debugger uses to set breakpoints. If you configure a default visualizer in the configuration file, using the --debugger option will automatically disable it. (But you can force it to be on with the --visualizer option, if that’s what you’d prefer.)

Configuring the logging back end

XML Calabash uses the “logback classic” backend by default. The configuration file that ships with XML Calabash only sends messages to the console and it uses a “turboFilter” to dynamically control the log level.

If you want to quickly configure XML Calabash to save log messages to a file, simply point to a logback configuration that is configured accordingly. For example, the configuration in Figure 4.1, “Example logback Configuration”.

 1 |<configuration>
   | 
   |  <appender name="STDERR" class="ch.qos.logback.core.ConsoleAppender">
   |    <target>System.err</target>
 5 |    <filter class="ch.qos.logback.classic.filter.ThresholdFilter">
   |      <level>WARN</level>
   |    </filter>
   |    <encoder>
   |      <pattern>%-5level %msg%n</pattern>
10 |    </encoder>
   |  </appender>
   | 
   |  <appender name="FILE" class="ch.qos.logback.core.rolling.RollingFileAppender">
   |    <file>/tmp/xmlcalabash.log</file>
15 |    <rollingPolicy class="ch.qos.logback.core.rolling.TimeBasedRollingPolicy">
   |      <fileNamePattern>/tmp/xmlcalabash.%d{yyyy-MM-dd}.log</fileNamePattern>
   |      <maxHistory>5</maxHistory>
   |    </rollingPolicy>
   |    <encoder>
20 |      <pattern>%d{HH:mm:ss.SSS}  %-4relative [%thread] %-5level %logger{35} - %msg%n</pattern>
   |    </encoder>
   |  </appender>
   |  
   |  <root level="TRACE" additivity="false">
25 |    <appender-ref ref="STDERR"/>
   |    <appender-ref ref="FILE"/>
   |  </root>
   |</configuration>
Figure 4.1. Example logback Configuration

This configuration doesn’t offer dynamic control of the log level. It sends warning and error messages to the console and all messages to the log file (/tmp/xmlcalabash.log in this example).

One way to tell Java to use this logging configuration instead of the default is to specify it with a system property, for example, on the command line:

$ java -Dlogback.configurationFile=/path/logback.xml …

Where /path/logback.xml is the path to your configuration file and “…” is the rest of the Java arguments you want to use.