logback on BusinessWorks

Using logback on BusinessWorks 5.x

Posted by

Evolve your logging using logback on BusinessWorks 5.x, prepare for 6.x

Following our recent post on advance logging for BusinessWorks 6.x, some customers have asked for a similar feature in BW 5.x, maybe with custom java code. After some research, we have a very interesting conclusion: it is possible to use logback on Businessworks 5.x, seamlessly, without changing a single piece of code. Here, we’re going to summarise how we did it. (If someone is wondering whether this approach is feasible for domain managed engines, have a look at the end of the post. Just a minor tweak required)

First, we knew from our past projects, that BusinessWorks can be configured to use log4j, with just using a starting flag (try bwengine -h, and you will easy find what flag is :D ). Then, our first idea was to set up slf4j, to bridge between log4j and any other logging framework. Some details on this:

- Use the latest slf4j version. The one shipped with BusinessWorks 5.x lacks some configuration classes needed for bridging the logging engine. Place slf4j-api-1.7.10.jar, log4j-over-slf4j-1.7.10.jar, logback-core-1.1.2.jar and logback-classic-1.1.2.jar into a directory, to be included into the classpath later

- Drop any slf4j-log4j12 in the classpath, to avoid a loop on logging classes. (log4j -> slf4j -> log4j -> ….)

- And last but not least, in order to avoid NoSuchMethod exception at engine start up, the slf4j version that we used (1.7.10) needed to implement the method getAppender from  org.apache.log4j.Category class. So we added it to the log4j-over-slf4j.jar.

Remember to use the -log4j flag when booting your engine, and to perform a first test using the logback out of the box configuration as per the logback.xml in the classpath. We will go back later on this, because the idea is to achieve a more flexible per-component logback configuration.

At this point, the bwengine should start up smoothly. Adding some Trace.* flags to the properties file, it’s possible to display more info for debugging. This is the result:

Using property file /home/developer/bw/bwengine.tra
Using work space directory /home/developer/bw/working/bw-dev
Configuring log4j system
Using XMLReader org.apache.xerces.jaxp.SAXParserImpl$JAXPSAXParser
18:37:12.986 INFO [main] tibco.bw.infoRole - [BW-Core] BWENGINE-300001 Process Engine version 5.10.0, build V48, 2012-6-3
18:37:13.003 INFO [main] tibco.bw.infoRole - [BW-Core] BWENGINE-300009 BW Plugins: version 5.10.0, build V48, 2012-6-3
18:37:13.008 INFO [main] tibco.bw.infoRole - [BW-Core] BWENGINE-300010 XML Support: TIBCOXML Version 5.51.500.003
18:37:13.009 INFO [main] tibco.bw.infoRole - [BW-Core] BWENGINE-300011 Java version: Java HotSpot(TM) 64-Bit Server VM 23.3-b01
18:37:13.010 INFO [main] tibco.bw.infoRole - [BW-Core] BWENGINE-300012 OS version: amd64 Linux 2.6.32-220.el6.x86_64
18:37:14.355 INFO [main] tibco.bw.infoRole - [BW-Core] BWENGINE-300013 Tibrv string encoding: ISO8859-1
18:37:14.403 DEBUG [main] tibco.bw.debugRole - [BW-Core] partitions to load = *
18:37:14.464 DEBUG [main] tibco.bw.debugRole - [BW-Core] loaded propList.process
18:37:14.471 DEBUG [main] tibco.bw.debugRole - [BW-Core] loaded Tester.process
18:37:14.476 DEBUG [main] tibco.bw.debugRole - [BW-Core] loaded SendAuditMessage.process
18:37:14.495 DEBUG [main] tibco.bw.debugRole - [BW-Core] creating 8 threads
18:37:14.496 DEBUG [main] tibco.bw.debugRole - [BW-Core] Using the new validator
18:37:14.623 DEBUG [main] tibco.bw.debugRole - [BW-Core] initialized process propList.process
18:37:14.969 DEBUG [main] tibco.bw.debugRole - [BW-Core] initialized process Tester.process
18:37:14.983 DEBUG [main] tibco.bw.debugRole - [BW-Core] initialized process SendAuditMessage.process
18:37:14.991 INFO [main] tibco.bw.infoRole - [BW-Core] BWENGINE-300002 Engine bw-dev started

Excellent news!

Now it’s as easy as using the log activity from BW to do logging on the logfile, in other words everything looks as before, but now the logging is bridged to logback. Main difference is that when the log activity does not refer any of the builtin roles  (error, warn, info, debug), it will try to fin a new custom logger called tibco.bw.<rolename>. This feature could be pretty useful, i.e: for auditing purposes and of course, to set the so valuable async appender.

Fantastic! Now BusinessWorks engine uses the full power of logback. The catalog of options is fully open now, i.e: it’s possible to implement some custom classes like BusinessWorks Job Discriminator to use the Sifting appender :

<appender name="SIFT" class="ch.qos.logback.classic.sift.SiftingAppender">
<discriminator class="net.superuser.logback.bw5.sift.JobBasedDiscriminator">
<defaultValue>engine</defaultValue>
</discriminator>
<sift>
<appender name="FILE-${jobId}" class="ch.qos.logback.core.FileAppender">
<file>/home/developer/bw/log/${jobId}.log</file>
<layout class="ch.qos.logback.classic.PatternLayout">
<pattern>%d{HH:mm:ss.SSS} %level [%thread] %logger - %msg%n</pattern>
</layout>
</appender>
</sift>
</appender>

And with that quick set up,  you can get a file per job, which is very useful to debug integration tests. Here’s the a sample of the different files generated by logback using the above configuration.

[developer@bw-dev log]$ ls
2100.log engine.log

And as  mentioned before, it does not require of any modification in the BusinessWorks project!

Oh! While writing this post one customer requested to also send auditing messages asynchronously (to not impact the business processes)  to a JMS queue. Let’s see how that can we sorted with a quick configuration change:

<appender name=”JMSAppender” class=”ch.qos.logback.classic.net.JMSQueueAppender”>

<InitialContextFactoryName>com.tibco.tibjms.naming.TibjmsInitialContextFactory</InitialContextFactoryName>
<ProviderURL>tcp://localhost:7222</ProviderURL>
<UserName>logback</UserName>
<Password>password</Password>
<QueueConnectionFactoryBindingName>QueueConnectionFactory</QueueConnectionFactoryBindingName>
<QueueBindingName>bw5.audit</QueueBindingName>
</appender>

Now the auditing messages are sent to the queue, but the format is not correct…the client wants XML payloads generated according to an specific schema. It’s then necessary to create a custom JMS Appender, so a couple of lines of code later:

 

logback on Businessworks: audit message

That did the trick!

Reached this point, we mentioned at the beginning that domain managed engines would need a little tweak. Just two properties are required to be added to the bwengine.xml, which will enable log4j and a more flexible configuration (remember adding them before creating the ear file):

One of those properties, is the tibco.env.APP_ARGS (which is already included in application.args)

<property>
<name>Application Arguments</name>
<option>tibco.env.APP_ARGS</option>
<default></default>
<description>Specifies the remaining arguments to pass into the application</description>
</property>

And the other one is java.extended.properties:

<property>
<name>JVM extra properties</name>
<option>java.extended.properties</option>
<default></default>
<description>Specifies extra properties for JVM like -Dprop=value</description>
</property>

Once the ear is built using the modified bwengine.xml, as mentioned above,  the new properties will required of the following configuration:

- APP_ARGS with the -log4j flag,

- extended properties with -Dlogback.configurationFile=<logback_config_url>

Note:If you are concerned for storing your connection password in plain text, it is fairly simple (we did it in 2 hours) to implement your custom JMS Queue appender based on this, using the TIBCO Security Obfuscation feature, and put the same obfuscated password as you do in your Global Variable file.

Enjoy!

SuperUserTeam

Leave a Reply

Your email address will not be published.