Logging Thread Names with Log4j

In some applications that start multiple threads to handle some concurrent processing, tracking the activity for a particular thread can be tricky. Take the following log file snippet where a group of JMS messages are sent off all around the same time:

2011-11-15 10:08:25,460 INFO  [JmsMessageSender:?] Sending message to queue: UPDATE.REQ.QUEUE
2011-11-15 10:08:25,460 INFO  [JMSMessageReceiver:47] Using JMS Selector JMSCorrelationID='d6d3278b-7f7d-47f5-9d1f-a67e4100d800'
2011-11-15 10:08:25,461 INFO  [JmsMessageSender:?] Sending message to queue: UPDATE.REQ.QUEUE
2011-11-15 10:08:25,489 INFO  [JMSMessageSender:60] Using replyToQueue UPDATE.RESP.QUEUE
2011-11-15 10:08:25,486 INFO  [JMSMessageReceiver:47] Using JMS Selector JMSCorrelationID='10287b5f-c061-4bba-8d9d-f92dbf6fb239'
2011-11-15 10:08:25,489 INFO  [JMSMessageSender:60] Using replyToQueue UPDATE.RESP.QUEUE
2011-11-15 10:08:25,505 INFO  [JMSMessageReceiver:47] Using JMS Selector JMSCorrelationID='b7892699-8f26-4260-ae36-62fa8b09c9c3'
2011-11-15 10:08:25,517 INFO  [JmsMessageSender:?] Received message from queue UPDATE.RESP.QUEUE
2011-11-15 10:08:25,564 INFO  [JmsMessageSender:?] Received message from queue UPDATE.RESP.QUEUE

With the case above, where many messages are sent and the responses will be eventually dealt with for further processing (which will also be logged), we could filter the log
Message on the thread to help track where something may have gone wrong.

The logging patterns for log4j allow for logging the name of the thread with %t. Here is the pattern used to output the messages above:

log4j.appender.outFile.layout.ConversionPattern=%d{ISO8601} %-5p [%c{1}:%L] %m%n

We can add the %t next to the class (%c):

log4j.appender.outFile.layout.ConversionPattern=%d{ISO8601} %-5p [%t:%c{1}:%L] %m%n

The next run produces similar logging statements with the thread name. As this is a Spring Batch application, the threads are named after the class handling their creation, SimpleAsyncTaskExecutor, with a number appened on as in: SimpleAsyncTaskExecutor-5

2011-11-15 10:57:51,643 INFO  [SimpleAsyncTaskExecutor-5:JMSMessageSender:47] Sending to destination queue UPDATE.REQ.QUEUE
2011-11-15 10:57:51,659 INFO  [SimpleAsyncTaskExecutor-5:JMSMessageSender:60] Using replyToQueue UPDATE.RESP.QUEUE
2011-11-15 10:57:51,665 INFO  [SimpleAsyncTaskExecutor-4:JmsMessageSender:?] Sending message to queue: UPDATE.REQ.QUEUE
2011-11-15 10:57:51,665 INFO  [SimpleAsyncTaskExecutor-4:JMSMessageSender:47] Sending to destination queue UPDATE.REQ.QUEUE
2011-11-15 10:57:51,666 INFO  [SimpleAsyncTaskExecutor-5:JMSMessageReceiver:47] Using JMS Selector JMSCorrelationID='846cc984-84fd-47a5-bfd3-c293da829927'
2011-11-15 10:57:51,687 INFO  [SimpleAsyncTaskExecutor-4:JMSMessageSender:60] Using replyToQueue UPDATE.RESP.QUEUE
2011-11-15 10:57:51,695 INFO  [SimpleAsyncTaskExecutor-4:JMSMessageReceiver:47] Using JMS Selector JMSCorrelationID='d44087e2-bd19-474a-a8d1-71ac0fc618a7'
2011-11-15 10:57:51,827 INFO  [SimpleAsyncTaskExecutor-5:JmsMessageSender:?] Received message from queue UPDATE.RESP.QUEUE
2011-11-15 10:57:51,831 INFO  [SimpleAsyncTaskExecutor-4:JmsMessageSender:?] Received message from queue UPDATE.RESP.QUEUE

Here we can now map request and responses to particular threads if we were to encounter a error (that's logged of course) later in processing.

I'm sure something similar can be done with the newer logging frameworks as well.

Groovy: A Look at Mixins

Groovy's XML support is often cited as one of the bigger attractions of the language. I often find myself writing classes that parse XML messages of the form:

    class MyXmlParser {
        def parse(String response) {
            def parsedXml = parsed(response)
            doSomethingWith(parsedXml)
        }

        def parsed(String response) {
            new XmlSlurper().parseText(response)
        }
        
        // ...
    }

One of the things that bothers me about the above pattern is the duplication in the parsed method that might spread throughout a group of classes. Using an inheritance scheme here might jump out as a possible solution at first, but that doesn't sit so well with me, as although the classes that use the duplicated method all parse XML, they all may not serve a similar substitutable purpose (one may send parsed results to a database, while another transforms the XML into an object, for example).

A newer feature of Groovy that I've been meaning to look into is the Mixin Transformation. Here, I could mixin the parsed method to all my classes that need to parse some XML. I started with the example linked to the left, but ran into a couple problems doing joint-compilation with Maven. Before we take a look at that, I'll demonstrate the mixin approach I used for this case.

The first step to adding mixins is to ensure the class you want to have make use of the mixin implement a common interface:

    package prystasj.groovy.xml

    interface XmlParser {
        def parse(String xml)
    }

    class MyXmlParser implements XmlParser {
        def parse(String response) {
            def parsedXml = parsed(response)
            doSomethingWith(parsedXml)
        }
        // ...
    }

The next step was to define the mixin class using the @Category annotation:

    package prystasj.groovy.xml

    @Category(XmlParser)
    class XmlParsing {
        def parsed(String response) {
            new XmlSlurper().parseText(response)
        }
    }

Finally, we can apply the @Mixin annotation and remove the parsed method for our parser:

    package prystasj.groovy.xml

    @Mixin(XmlParsing)
    class MyXmlParser implements XmlParser {
        def parse(String response) {
            def parsedXml = parsed(response)
            doSomethingWith(parsedXml)
        }
        // ... method parsed(String response) removed ...
    }

The MyXmlParser class now has the parsed method mixed in and no longer needs to define it. Is this a worthwile use of a mixin however, i.e. is the overhead worth having the duplication removed? In a more concrete situation, we might have many more duplicated methods between a group of classes that we would could add to the mixin, improving its worth.

Now back to the compilation problems I referred to earlier. When I went to compile, the GMaven plugin created the stubs required for joint compilation, and the Maven Compiler Plugin stumbled:

    [ERROR] /home/prystasj/.../target/generated-sources/groovy-stubs/main/prystasj/groovy/xml/MyXmlParser.java:[..] cannot find symbol
    [ERROR] symbol: variable XmlParsing

Everything in the stub looked legitimate, so I was rather stumped. I remembered running into a similar problem before, so I went ahead and tried fully qualifying the references inside the annotations:

    package prystasj.groovy.xml

    @Category(prystasj.groovy.xml.XmlParser)
    class XmlParsing {
        def parsed(String response) {
            new XmlSlurper().parseText(response)
        }
    }

    @Mixin(prystasj.groovy.xml.XmlParsing)
    class MyXmlParser implements XmlParser {
        def parse(String response) {
            def parsedXml = parsed(response)
            doSomethingWith(parsedXml)
        }
        // ... method parsed(String response) removed ...
    }

This resolved the issue and the project compile happily. If I'm not missing something, maybe this might be something worthwile to bring up with the GMaven developers? Thoughts? Thanks for reading.

Spring Batch: Deadlock Inserting Job Instances

I have been working on my first Spring Batch project and so far I'm a big fan. I think I'm pretty far along and the only real issue I've had is random occurrences of deadlock when the app tries to create instances of the same job simultaneously in the job database (in table BATCH_JOB_INSTANCE):

  2011-11-13 12:48:18,808 ERROR [AbstractStep:212] Encountered an error executing the step
  org.springframework.dao.DeadlockLoserDataAccessException: PreparedStatementCallback;
  SQL [INSERT into BATCH_JOB_INSTANCE(JOB_INSTANCE_ID, JOB_NAME, JOB_KEY, VERSION) values (?, ?, ?, ?)]; 
  Deadlock found when trying to get lock; try restarting transaction; 
  nested exception is com.mysql.jdbc.exceptions.jdbc4.MySQLTransactionRollbackException:
  Deadlock found when trying to get lock; try restarting transaction
        at org.springframework.jdbc.support.SQLErrorCodeSQLExceptionTranslator.doTranslate(SQLErrorCodeSQLExceptionTranslator.java:265)
        at org.springframework.jdbc.support.AbstractFallbackSQLExceptionTranslator.translate(AbstractFallbackSQLExceptionTranslator.java:72)
        at org.springframework.jdbc.core.JdbcTemplate.execute(JdbcTemplate.java:602)

I'm using MySQL as the database backing the batch app. The Job Repository, I'm using seemed pretty stock and I never had given it much thought:

     <bean id="jobRepository"
           class="org.springframework.batch.core.repository.support.JobRepositoryFactoryBean"
           p:dataSource-ref="dataSource" 
           p:transactionManager-ref="transactionManager" 
           p:lobHandler-ref="lobHandler"/>

One of the properties on the repository that can be set is isolationLevelForCache. I found that setting this value to ISOLATION_READ_UNCOMMITTED helped my deadlock issue.

     <bean id="jobRepository"
           class="org.springframework.batch.core.repository.support.JobRepositoryFactoryBean"
           p:dataSource-ref="dataSource" 
           p:transactionManager-ref="transactionManager" 
           p:isolationLevelForCache="ISOLATION_READ_UNCOMMITTED"
           p:lobHandler-ref="lobHandler"/>

Whether or not this is the solution to use come production time is yet to be seen. For now, I surmise this works because the app is starting enough jobs at the same time, that the framework is ready to proceed with one before the insert to the database table is formally committed.

Maven Tomcat Plugin: Selecting an XML Parser

The Tomcat Maven Plugin is a great tool for quickly working through the cycle of making and verifying changes in a webapp. One such app I was working with included an XML parser from Oracle:

  oracle:oracle_xmlparserv2:jar:10.2.0.3:compile

The inclusion of the parser created a problem as it did not take kindly to a document parsed during startup, causing an error:

  $ mvn tomcat:run 
  ...
  Caused by: oracle.xml.parser.schema.XSDException: Duplicated definition for: 'identifiedType'
          at oracle.xml.parser.schema.XSDBuilder.buildSchema(XSDBuilder.java:731)
          at oracle.xml.parser.schema.XSDBuilder.build(XSDBuilder.java:435)
          at oracle.xml.parser.schema.XSDValidator.processSchemaLocation(XSDValidator.java:879)
          at oracle.xml.parser.schema.XSDValidator.startElement(XSDValidator.java:496)
          at oracle.xml.parser.v2.NonValidatingParser.parseElement(NonValidatingParser.java:1224)
          at oracle.xml.parser.v2.NonValidatingParser.parseRootElement(NonValidatingParser.java:311)
          at oracle.xml.parser.v2.NonValidatingParser.parseDocument(NonValidatingParser.java:278)
         ... 52 more

A colleague of mine at work pointed at that you can select another parser through system properties, so I wanted to share his solution here:

  $ mvn tomcat:run \
    -DXMLPARSER=XERCES \
    -DXSLENGINE=XERCES \
    -Djavax.xml.parsers.DocumentBuilderFactory=org.apache.xerces.jaxp.DocumentBuilderFactoryImpl \
    -Djavax.xml.transform.TransformerFactory=org.apache.xalan.processor.TransformerFactoryImpl \
    -Djavax.xml.parsers.SAXParserFactory=org.apache.xerces.jaxp.SAXParserFactoryImpl

The above selects a JAXP parser from Apache, requiring Xerces and Xalan:

  xerces:xercesImpl:${xercesImpl.version}
  xalan:xalan:${xalan.version}

To avoid having to script the above command or have to remember it, you can add the settings to the plugin definition:

    <plugin>
        <groupId>org.codehaus.mojo</groupId>
        <artifactId>tomcat-maven-plugin</artifactId>
        <version>1.0</version>
        <configuration>
            <port>${tomcatPort}</port>
            <path>/${project.artifactId}-${project.version}</path>
            <systemProperties>
                <env>${env}</env>
                <tomcatPort>${tomcatPort}</tomcatPort>
                <XMLPARSER>XERCES</XMLPARSER>
                <XSLENGINE>XERCES</XSLENGINE>
                <javax.xml.parsers.DocumentBuilderFactory>org.apache.xerces.jaxp.DocumentBuilderFactoryImpl</javax.xml.parsers.DocumentBuilderFactory>
                <javax.xml.transform.TransformerFactory>org.apache.xalan.processor.TransformerFactoryImpl</javax.xml.transform.TransformerFactory>
                <javax.xml.parsers.SAXParserFactory>org.apache.xerces.jaxp.SAXParserFactoryImpl</javax.xml.parsers.SAXParserFactory>
            </systemProperties>
        </configuration>
        <dependencies>
            <dependency>
                <groupId>xerces</groupId>
                <artifactId>xercesImpl</artifactId>
                <version>${xercesImpl.version}</version>
            </dependency>
            <dependency>
                <groupId>xalan</groupId>
                <artifactId>xalan</artifactId>
                <version>${xalan.version}</version>
            </dependency>
        </dependencies>
    </plugin>

Hope this helps anyone else who may run into a similar situation.

Prompted for GNOME Keyring Password During a Subversion Commit

Out of the blue when trying a Subversion commit, I was presented with a prompt for the password to the GNOME Keyring:

  $ svn ci -m"adding module"
  Password for '(null)' GNOME keyring:
  svn: Commit failed (details follow):
  svn: MKACTIVITY of '/svn/projectr/!svn/act/c5d9f7fb-76ee-4900-9a0b-b55928d418f0': authorization failed:
  Could not authenticate to server: rejected Basic challenge (http://svn.myorginazation.org)

In my case, the password for my login took care of the problem. While I do not understand the reasons for the prompt, the same may work for someone else, as by default the login password is what is being asked for.

If anyone understands why the prompt may have occurred (I haven't done much research yet), please leave a comment. Thanks!