Hello OpenEJB Developers!
I am using OpenEJB embedded in a wicket web application running on Jetty.
Now I wanted to trace JPA / JTA operations in my test environment and turned the "transaction" logging level to "debug".
Here are the relevant snippets from my configuration:
====== Turned on external logging configuration in test case setup =========
....
System.setProperty("openejb.logger.external", "true");
p.put(Context.INITIAL_CONTEXT_FACTORY, "org.apache.openejb.client.LocalInitialContextFactory");
....
====== Extract from my log4j.properties file ========
log4j.rootLogger = fatal,C
...
log4j.category.Transaction = debug
...
log4j.appender.C = org.apache.log4j.ConsoleAppender
log4j.appender.C.layout = org.apache.log4j.SimpleLayout
=======================================
This led to an endless loop in the method org.apache.openejb.util.Memoizer.compute(..)
on several debug messages emitted by the class org.apache.openejb.core.transaction.JtaTransactionPolicy.
Here is an example message copied from the source code:
JtaTransactionPolicy.beginTransaction(JtaTransactionPolicy.java:235)
txLogger.debug("TX {}: Started transaction {}", transactionType, transaction);
The message key (ok, this cannot be a key anyway) is not found in
\openejb-core-3.1.jar\org\apache\openejb\util\resources\Messages.properties
so "TX {}: Started transaction {}" is passed on to java.text.MessageFormat.
But MessageFormat.makeFormat(..) expects arguments numbers in the braces and throws an IllegalArgumentException.
I solved the problem for myself by replacing all occurences of "{}" in all debug messages in this file (see below) and
copied the resulting class to openejb-core-3.1.jar.
Maybe the reason for this bug is that I my JDK version is not compatible?
makeFormat(..) could have had a default behaviour replacing all {} with {<{} position>} in a JDK < 1.5....?
Anyway, replacing JtaTransactionPolicy with my variant would be helpful for my configuration.
============ Stack Trace =============
java.util.concurrent.ExecutionException: java.lang.IllegalArgumentException: can't parse argument number
at java.util.concurrent.FutureTask$Sync.innerGet(FutureTask.java:205)
at java.util.concurrent.FutureTask.get(FutureTask.java:80)
at org.apache.openejb.util.Memoizer.compute(Memoizer.java:53)
at org.apache.openejb.util.Logger.formatMessage(Logger.java:185)
at org.apache.openejb.util.Logger.debug(Logger.java:234)
at org.apache.openejb.core.transaction.JtaTransactionPolicy.beginTransaction(JtaTransactionPolicy.java:235)
at org.apache.openejb.core.transaction.TxRequired.<init>(TxRequired.java:54)
at org.apache.openejb.core.transaction.JtaTransactionPolicyFactory.createTransactionPolicy(JtaTransactionPolicyFactory.java:36)
at org.apache.openejb.core.transaction.EjbTransactionUtil.createTransactionPolicy(EjbTransactionUtil.java:55)
at org.apache.openejb.core.stateless.StatelessContainer._invoke(StatelessContainer.java:200)
at org.apache.openejb.core.stateless.StatelessContainer.invoke(StatelessContainer.java:169)
at org.apache.openejb.core.ivm.EjbObjectProxyHandler.businessMethod(EjbObjectProxyHandler.java:217)
at org.apache.openejb.core.ivm.EjbObjectProxyHandler._invoke(EjbObjectProxyHandler.java:77)
at org.apache.openejb.core.ivm.BaseEjbProxyHandler.invoke(BaseEjbProxyHandler.java:286)
at $Proxy28.getUserFor(Unknown Source)
at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:39)
at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:25)
at java.lang.reflect.Method.invoke(Method.java:585)
at org.apache.wicket.proxy.LazyInitProxyFactory$JdkHandler.invoke(LazyInitProxyFactory.java:416)
at org.apache.wicket.proxy.$Proxy27.getUserFor(Unknown Source)
at de.trho.login.CreateUserAccountPage$1.onValidate(CreateUserAccountPage.java:89)
...
Caused by: java.lang.IllegalArgumentException: can't parse argument number
at java.text.MessageFormat.makeFormat(MessageFormat.java:1330)
at java.text.MessageFormat.applyPattern(MessageFormat.java:450)
at java.text.MessageFormat.<init>(MessageFormat.java:350)
at org.apache.openejb.util.Logger$4.compute(Logger.java:108)
at org.apache.openejb.util.Logger$4.compute(Logger.java:107)
at org.apache.openejb.util.Memoizer$1.call(Memoizer.java:42)
at java.util.concurrent.FutureTask$Sync.innerRun(FutureTask.java:269)
at java.util.concurrent.FutureTask.run(FutureTask.java:123)
at org.apache.openejb.util.Memoizer.compute(Memoizer.java:49)
... 60 more
================ Modified JtaTransactionPolicy File =======================
/**
* Licensed to the Apache Software Foundation (ASF) under one or more
* contributor license agreements. See the NOTICE file distributed with
* this work for additional information regarding copyright ownership.
* The ASF licenses this file to You under the Apache License, Version 2.0
* (the "License"); you may not use this file except in compliance with
* the License. You may obtain a copy of the License at
*
*
http://www.apache.org/licenses/LICENSE-2.0
*
* Unless required by applicable law or agreed to in writing, software
* distributed under the License is distributed on an "AS IS" BASIS,
* WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied.
* See the License for the specific language governing permissions and
* limitations under the License.
*/package org.apache.openejb.core.transaction;
import java.rmi.RemoteException;
import java.util.Map;
import java.util.LinkedHashMap;
import java.util.List;
import java.util.LinkedList;
import java.util.ArrayList;
import javax.transaction.HeuristicMixedException;
import javax.transaction.HeuristicRollbackException;
import javax.transaction.InvalidTransactionException;
import javax.transaction.RollbackException;
import javax.transaction.Status;
import javax.transaction.Transaction;
import javax.transaction.TransactionManager;
import javax.transaction.TransactionSynchronizationRegistry;
import javax.transaction.Synchronization;
import javax.transaction.xa.XAResource;
import org.apache.openejb.ApplicationException;
import org.apache.openejb.SystemException;
import org.apache.openejb.loader.SystemInstance;
import org.apache.openejb.util.LogCategory;
import org.apache.openejb.util.Logger;
public abstract class JtaTransactionPolicy implements TransactionPolicy {
protected final static Logger logger = Logger.getInstance(LogCategory.OPENEJB, "org.apache.openejb.util.resources");
protected final static Logger txLogger = Logger.getInstance(LogCategory.TRANSACTION, "org.apache.openejb.util.resources");
protected final TransactionType transactionType;
protected final TransactionManager transactionManager;
private final TransactionSynchronizationRegistry synchronizationRegistry;
private Map<Object,Object> resources;
private final List<TransactionSynchronization> synchronizations = new LinkedList<TransactionSynchronization>();
private boolean rollbackOnly;
public JtaTransactionPolicy(TransactionType transactionType, TransactionManager transactionManager) {
this.transactionType = transactionType;
this.transactionManager = transactionManager;
synchronizationRegistry = SystemInstance.get().getComponent(TransactionSynchronizationRegistry.class);
}
public TransactionType getTransactionType() {
return transactionType;
}
protected abstract Transaction getCurrentTrasaction();
public boolean isTransactionActive() {
Transaction trasaction = getCurrentTrasaction();
if (trasaction == null) {
return false;
}
try {
int status = trasaction.getStatus();
return status == Status.STATUS_ACTIVE || status == Status.STATUS_MARKED_ROLLBACK;
} catch (javax.transaction.SystemException e) {
return false;
}
}
public boolean isRollbackOnly() {
Transaction trasaction = getCurrentTrasaction();
if (trasaction != null) {
try {
int status = trasaction.getStatus();
return status == Status.STATUS_MARKED_ROLLBACK;
} catch (javax.transaction.SystemException e) {
return false;
}
} else {
return rollbackOnly;
}
}
public void setRollbackOnly() {
Transaction trasaction = getCurrentTrasaction();
if (trasaction != null) {
setRollbackOnly(trasaction);
} else {
rollbackOnly = true;
}
}
public Object getResource(Object key) {
if (isTransactionActive()) {
return synchronizationRegistry.getResource(key);
}
if (resources == null) {
return null;
}
return resources.get(key);
}
public void putResource(Object key, Object value) {
if (isTransactionActive()) {
synchronizationRegistry.putResource(key, value);
}
if (resources == null) {
resources = new LinkedHashMap<Object,Object>();
}
resources.put(key, value);
}
public Object removeResource(Object key) {
if (isTransactionActive()) {
Object value = synchronizationRegistry.getResource(key);
synchronizationRegistry.putResource(key, null);
return value;
}
if (resources == null) {
return null;
}
return resources.remove(key);
}
public void registerSynchronization(final TransactionSynchronization synchronization) {
if (isTransactionActive()) {
synchronizationRegistry.registerInterposedSynchronization(new Synchronization() {
public void beforeCompletion() {
synchronization.beforeCompletion();
}
public void afterCompletion(int s) {
TransactionSynchronization.Status status;
if (s == Status.STATUS_COMMITTED) {
status = TransactionSynchronization.Status.COMMITTED;
} else if (s == Status.STATUS_ROLLEDBACK) {
status = TransactionSynchronization.Status.ROLLEDBACK;
} else {
status = TransactionSynchronization.Status.UNKNOWN;
}
synchronization.afterCompletion(status);
}
});
} else {
synchronizations.add(synchronization);
}
}
protected void fireNonTransactionalCompletion() {
for (TransactionSynchronization synchronization : new ArrayList<TransactionSynchronization>(synchronizations)) {
try {
synchronization.beforeCompletion();
} catch (Throwable e) {
logger.error("Exception thrown from beforeCompletion() of TransactionSynchronization " + synchronization);
}
}
TransactionSynchronization.Status status = isRollbackOnly() ? TransactionSynchronization.Status.ROLLEDBACK : TransactionSynchronization.Status.COMMITTED;
for (TransactionSynchronization synchronization : new ArrayList<TransactionSynchronization>(synchronizations)) {
try {
synchronization.afterCompletion(status);
} catch (Exception e) {
logger.error("Exception thrown from afterCompletion(" + status + ") of TransactionSynchronization " + synchronization);
}
}
}
public void enlistResource(XAResource xaResource) throws SystemException {
Transaction transaction = getCurrentTrasaction();
if (transaction != null) {
try {
if (transaction.enlistResource(xaResource)) {
return;
}
} catch (Exception e) {
throw new SystemException("Unable to enlist xa resource in the transaction", e);
}
}
throw new SystemException("Unable to enlist xa resource in the transaction");
}
public String toString() {
return transactionType.toString();
}
protected Transaction getTransaction() throws SystemException {
try {
return transactionManager.getTransaction();
} catch (javax.transaction.SystemException e) {
txLogger.error("The Transaction Manager has encountered an unexpected error condition while attempting to obtain current transaction: {0}", e.getMessage());
throw new SystemException(e);
}
}
protected void setRollbackOnly(Transaction tx) {
try {
if (tx != null && tx.getStatus() == Status.STATUS_ACTIVE) {
tx.setRollbackOnly();
txLogger.debug("TX {0}: setRollbackOnly() on transaction {1}", transactionType, tx);
}
} catch (Exception e) {
txLogger.error("Exception during setRollbackOnly()", e);
throw new IllegalStateException("No transaction active", e);
}
}
protected Transaction beginTransaction() throws SystemException {
Transaction transaction;
try {
transactionManager.begin();
transaction = transactionManager.getTransaction();
} catch (Exception e) {
txLogger.error("The Transaction Manager has encountered an unexpected error condition while attempting to begin a new transaction: {0}", e.getMessage());
throw new SystemException(e);
}
if (transaction == null) {
throw new SystemException("Failed to begin a new transaction");
}
txLogger.debug("TX {0}: Started transaction {1}", transactionType, transaction);
return transaction;
}
protected Transaction suspendTransaction() throws SystemException {
try {
Transaction tx = transactionManager.suspend();
txLogger.info("TX {0}: Suspended transaction {1}", transactionType, tx);
return tx;
} catch (javax.transaction.SystemException se) {
txLogger.error("Exception during suspend()", se);
throw new SystemException(se);
}
}
protected void resumeTransaction(Transaction tx) throws SystemException {
try {
if (tx == null) {
txLogger.debug("TX {0}: No transaction to resume", transactionType);
} else {
txLogger.debug("TX {0}: Resuming transaction {1}",transactionType, tx);
transactionManager.resume(tx);
}
} catch (InvalidTransactionException ite) {
txLogger.error("Could not resume the client's transaction, the transaction is no longer valid: {}", ite.getMessage());
throw new SystemException(ite);
} catch (IllegalStateException e) {
txLogger.error("Could not resume the client's transaction: {0}", e.getMessage());
throw new SystemException(e);
} catch (javax.transaction.SystemException e) {
txLogger.error("Could not resume the client's transaction: The transaction reported a system exception: {0}", e.getMessage());
throw new SystemException(e);
}
}
protected void completeTransaction(Transaction tx) throws SystemException, ApplicationException {
boolean shouldRollback;
try {
shouldRollback = tx.getStatus() != Status.STATUS_ACTIVE;
} catch (javax.transaction.SystemException e) {
txLogger.error("The Transaction Manager has encountered an unexpected error condition while attempting to obtain transaction status: {0}", e.getMessage());
throw new SystemException(e);
}
if (shouldRollback) {
rollbackTransaction(tx);
return;
}
try {
txLogger.debug("TX {0}: Committing transaction {1}", transactionType, tx);
if (tx.equals(transactionManager.getTransaction())) {
transactionManager.commit();
} else {
tx.commit();
}
} catch (RollbackException e) {
txLogger.debug("The transaction has been rolled back rather than commited: {0}", e.getMessage());
Throwable txe = new TransactionRolledbackException("Transaction was rolled back, presumably because setRollbackOnly was called during a synchronization").initCause(e);
throw new ApplicationException(txe);
} catch (HeuristicMixedException e) {
txLogger.debug("A heuristic decision was made, some relevant updates have been committed while others have been rolled back: {0}", e.getMessage());
throw new ApplicationException(new RemoteException("A heuristic decision was made, some relevant updates have been committed while others have been rolled back").initCause(e));
} catch (HeuristicRollbackException e) {
txLogger.debug("A heuristic decision was made while commiting the transaction, some relevant updates have been rolled back: {0}", e.getMessage());
throw new ApplicationException(new RemoteException("A heuristic decision was made while commiting the transaction, some relevant updates have been rolled back").initCause(e));
} catch (SecurityException e) {
txLogger.error("The current thread is not allowed to commit the transaction: {0}", e.getMessage());
throw new SystemException(e);
} catch (IllegalStateException e) {
txLogger.error("The current thread is not associated with a transaction: {0}", e.getMessage());
throw new SystemException(e);
} catch (javax.transaction.SystemException e) {
txLogger.error("The Transaction Manager has encountered an unexpected error condition while attempting to commit the transaction: {0}", e.getMessage());
throw new SystemException(e);
}
}
protected void rollbackTransaction(Transaction tx) throws SystemException {
try {
txLogger.debug("TX {0}: Rolling back transaction {1}", transactionType, tx);
if (tx.equals(transactionManager.getTransaction())) {
transactionManager.rollback();
} else {
tx.rollback();
}
} catch (IllegalStateException e) {
logger.error("The TransactionManager reported an exception while attempting to rollback the transaction: " + e.getMessage());
throw new SystemException(e);
} catch (javax.transaction.SystemException e) {
logger.error("The TransactionManager reported an exception while attempting to rollback the transaction: " + e.getMessage());
throw new SystemException(e);
}
}
}
Bug
Closed
Major
Turning on transaction logging results in the IllegalArgumentException: can't parse argument number
