Atomikos Forum

I'm using Atomikos Transactions Essentials 3.7.0 in tests with web apps running in Tomcat 6.0.29 on Windows Server Standard (2007).  The web apps use log4j and the Tomcat lib directory contains slf4j-log4j12.jar.  Initially, I thought I could turn Atomikos logging on by simply adding a jta.properties file.  So, I provided one that looks like this:

com.atomikos.icatch.service=com.atomikos.icatch.standalone.UserTransactionServiceFactory
com.atomikos.icatch.console_log_level=DEBUG
com.atomikos.icatch.output_dir=c:/

I pass it into the JVM at server startup.  I then see the following log entry at server statup:

INFO  | jvm 1    | 2011/09/16 18:24:22 | Using init file: /c:/jta.properties

And I see JMS logging entries like the following in C:\tm.out, but no database logging:

11-09-16 16:33:07,784 [org.springframework.jms.listener.DefaultMessageListenerContainer#2-1] getCompositeTransaction()  returning instance with id 10.21.13.35.tm0185800027
11-09-16 16:33:07,785 [org.springframework.jms.listener.DefaultMessageListenerContainer#2-1] getCompositeTransaction()  returning instance with id 10.21.13.35.tm0185800027
11-09-16 16:33:07,785 [org.springframework.jms.listener.DefaultMessageListenerContainer#2-1] getCompositeTransaction()  returning instance with id 10.21.13.35.tm0185800027
11-09-16 16:33:07,785 [org.springframework.jms.listener.DefaultMessageListenerContainer#2-1] getCompositeTransaction()  returning instance with id 10.21.13.35.tm0185800027
11-09-16 16:33:07,785 [org.springframework.jms.listener.DefaultMessageListenerContainer#2-1] getCompositeTransaction()  returning instance with id 10.21.13.35.tm0185800027
11-09-16 16:33:07,785 [org.springframework.jms.listener.DefaultMessageListenerContainer#2-1] getCompositeTransaction()  returning instance with id 10.21.13.35.tm0185800027
11-09-16 16:33:07,785 [org.springframework.jms.listener.DefaultMessageListenerContainer#2-1] commit() done (by application) of transaction 10.21.13.35.tm0185800027
11-09-16 16:33:07,785 [org.springframework.jms.listener.DefaultMessageListenerContainer#2-1] Coordinator 10.21.13.35.tm0185800027 entering state: COMMITTING
11-09-16 16:33:07,791 [org.springframework.jms.listener.DefaultMessageListenerContainer#2-1] Coordinator 10.21.13.35.tm0185800027 entering state: TERMINATED
11-09-16 16:33:07,791 [org.springframework.jms.listener.DefaultMessageListenerContainer#2-1] Coordinator 10.21.13.35.tm0185800027 : stopping timer...
11-09-16 16:33:07,792 [org.springframework.jms.listener.DefaultMessageListenerContainer#2-1] Coordinator 10.21.13.35.tm0185800027 : disposing statehandler TERMINATED...
11-09-16 16:33:07,792 [org.springframework.jms.listener.DefaultMessageListenerContainer#2-1] Coordinator 10.21.13.35.tm0185800027 : disposed.

I also see log entries like these:

1-09-16 15:56:13,804 [WrapperSimpleAppMain] Coordinator 10.21.13.35.tm0040400026 entering state: HEUR_HAZARD
11-09-16 15:56:13,804 [WrapperSimpleAppMain] Local heuristic termination of coordinator 10.21.13.35.tm0040400026 with state COMMITTING
11-09-16 15:56:13,804 [WrapperSimpleAppMain] Done read of logfile
11-09-16 15:56:13,804 [WrapperSimpleAppMain] Logfile closed: C:\home\tcserver\springsource-tc-server-developer\SASServer1\bin\winx86_64\.\tmlog2028.log
11-09-16 15:56:13,804 [WrapperSimpleAppMain] USING core version: 3.7.0
11-09-16 15:56:13,804 [WrapperSimpleAppMain] USING com.atomikos.icatch.console_file_name = tm.out
11-09-16 15:56:13,804 [WrapperSimpleAppMain] USING com.atomikos.icatch.console_file_count = 1
11-09-16 15:56:13,804 [WrapperSimpleAppMain] USING com.atomikos.icatch.automatic_resource_registration = true
11-09-16 15:56:13,804 [WrapperSimpleAppMain] USING com.atomikos.icatch.client_demarcation = false
11-09-16 15:56:13,804 [WrapperSimpleAppMain] USING com.atomikos.icatch.threaded_2pc = false
11-09-16 15:56:13,804 [WrapperSimpleAppMain] USING com.atomikos.icatch.serial_jta_transactions = true
11-09-16 15:56:13,804 [WrapperSimpleAppMain] USING com.atomikos.icatch.log_base_dir = .\
11-09-16 15:56:13,804 [WrapperSimpleAppMain] USING com.atomikos.icatch.console_log_level = DEBUG
11-09-16 15:56:13,804 [WrapperSimpleAppMain] USING com.atomikos.icatch.max_actives = 50
11-09-16 15:56:13,804 [WrapperSimpleAppMain] USING com.atomikos.icatch.checkpoint_interval = 500
11-09-16 15:56:13,804 [WrapperSimpleAppMain] USING com.atomikos.icatch.enable_logging = true
11-09-16 15:56:13,804 [WrapperSimpleAppMain] USING com.atomikos.icatch.output_dir = c:/
11-09-16 15:56:13,804 [WrapperSimpleAppMain] USING com.atomikos.icatch.log_base_name = tmlog
11-09-16 15:56:13,804 [WrapperSimpleAppMain] USING com.atomikos.icatch.console_file_limit = -1
11-09-16 15:56:13,804 [WrapperSimpleAppMain] USING com.atomikos.icatch.max_timeout = 300000
11-09-16 15:56:13,804 [WrapperSimpleAppMain] USING com.atomikos.icatch.tm_unique_name = 10.21.13.35.tm
11-09-16 15:56:13,804 [WrapperSimpleAppMain] USING java.naming.factory.initial = com.sun.jndi.rmi.registry.RegistryContextFactory
11-09-16 15:56:13,804 [WrapperSimpleAppMain] USING java.naming.provider.url = rmi://localhost:1099
11-09-16 15:56:13,804 [WrapperSimpleAppMain] USING com.atomikos.icatch.service = com.atomikos.icatch.standalone.UserTransactionServiceFactory
11-09-16 15:56:13,804 [WrapperSimpleAppMain] USING com.atomikos.icatch.force_shutdown_on_vm_exit = false
11-09-16 15:56:13,804 [WrapperSimpleAppMain] USING com.atomikos.icatch.default_jta_timeout = 10000
11-09-16 15:57:18,914 [WrapperSimpleAppMain] getCompositeTransaction() returning NULL!
11-09-16 15:57:18,915 [WrapperSimpleAppMain] getCompositeTransaction() returning NULL!
11-09-16 15:57:18,915 [WrapperSimpleAppMain] getCompositeTransaction() returning NULL!
11-09-16 15:57:18,915 [WrapperSimpleAppMain] Coordinator 10.21.13.35.tm0000100027 entering state: ACTIVE
11-09-16 15:57:18,921 [WrapperSimpleAppMain] TaskManager: initializing...
11-09-16 15:57:18,921 [WrapperSimpleAppMain] THREADS: using JDK thread pooling...
11-09-16 15:57:18,924 [WrapperSimpleAppMain] THREADS: using executor class com.atomikos.icatch.imp.thread.Java15ExecutorFactory$Executor
11-09-16 15:57:18,925 [WrapperSimpleAppMain] (1.5) executing task: com.atomikos.timing.PooledAlarmTimer@154575ea
11-09-16 15:57:18,926 [WrapperSimpleAppMain] ThreadFactory: creating new thread: Atomikos:0

Thinking that I may be encountering a logging problem due to the web apps doing their own log4j logging, I added the following log4j.xml file to the server's classpath:

<?xml version="1.0" encoding="UTF-8"?>
<!DOCTYPE log4j:configuration SYSTEM "log4j.dtd">

<log4j:configuration xmlns:log4j="http://jakarta.apache.org/log4j/" debug="true">

  <appender name="FILE" class="org.apache.log4j.FileAppender">
      <param name="File" value="${catalina.base}/logs/log4j.log"/>
      <param name="Threshold" value="TRACE"/>

      <layout class="org.apache.log4j.PatternLayout">
        <!-- The default pattern: Date Priority [Category] (Thread) Message\n -->
        <param name="ConversionPattern" value="%d %-5p [%c] (%t) %m%n"/>
      </layout>
  </appender>

  <!-- ============================== -->
  <!-- Append messages to the console -->
  <!-- ============================== -->

  <appender name="CONSOLE" class="org.apache.log4j.ConsoleAppender">
      <param name="Target" value="System.out"/>
      <param name="Threshold" value="DEBUG"/>

      <layout class="org.apache.log4j.PatternLayout">
        <!-- The default pattern: Date Priority [Category] Message\n -->
        <param name="ConversionPattern" value="%d{ABSOLUTE} %-5p [%c{1}] %m%n"/>
      </layout>
  </appender>


  <!-- ================ -->
  <!-- Limit categories -->
  <!-- ================ -->

  <category name="com.atomikos">
    <priority value="TRACE"/>
  </category>

  <!-- ======================= -->
  <!-- Setup the Root category -->
  <!-- ======================= -->

  <root>
      <priority value="TRACE"/>
      <!-- appender-ref ref="CONSOLE"/ -->
      <appender-ref ref="FILE"/>
  </root>

</log4j:configuration>

When I run my web app tests with this I see the same kinds of log entries as above, but formatted differently and output to the log4j.log file.

Am I doing something wrong that is causing me not to get all of the log output I should?  My test results clearly indicate that data is being output to the database, yet I see no transaction logging that shows that.  Am I using the wrong Atomikos logger (or category) name for example? 

Should I use something other than com.atomikos? 

Should my jta.properties file specify something other than com.atomikos.icatch.standalone.UserTransactionServiceFactory?  My context.xml file specifies:

  <Resource name="UserTransaction" auth="Container"
          type="javax.transaction.UserTransaction"
              factory="com.atomikos.icatch.jta.UserTransactionFactory" />

Does this conflict in some way with the UserTransactionServiceFactory?

If what I've described seems reasonable, I guess I should start looking into the possibility that the database records are somehow being written without transaction processing taking place.

Thanks.

At first sight this seems to hint that your resources are not in XA mode.

I think I am experiencing the same problem (same version of everything).  I have the same set up and am not seeing any Atomikos logging messages in my application log file.  I do see *some* in the tm.out file.

From experience, I recall that the Atomikos logger is just "atomikos" not "com.atomikos".  For example, when I run Atomikos outside Tomcat (or Jetty), I see the Atomikos log entries in my Maven surefire build log using the following appender:

    <logger name="atomikos" additivity="false">
        <level value="WARN" />
        <appender-ref ref="TESTLOGFILE" />
    </logger>

However, when I run Atomikos inside my webapp within Tomcat or Jetty I see no messages in the application log.  I have following the instructions for "Per WAR file" configuration.  I do not have the slf4j-nop.jar on my classpath.

Is the problem that logging is mis-configured or that Atomikos isn't creating any transactions?  I ask because I am a hibernate lazy init exception that I believe is caused by the lack of a transaction.

In my case it turned out that there was some problem with Atomikos being configured by the servlet container.  I was using JNDI to hand the user transaction to the app from Jetty/Tomcat and something wasn't working.

So I pulled the configuration into my app and everything works fine now.  It's not ideal, but at least I left the data source configuration externalized.

Thanks for the update!