Arquilian Transactions vs EJB/JPA Transactions
My arquilian test with @Transactional(COMMIT/ROLLBACK) causes Hibernate to not execute load and as a result entity does not get populated. However, when I disable test transaction @Transactional(TransactionMode.DISABLED) test succeeds as hibernate does execute load thereby populating the entity:
package myapp.ejb.api.test;
import static org.junit.Assert.assertNotNull;
import static org.junit.Assert.assertNull;
import static org.junit.Assert.assertTrue;
import javax.ejb.EJB;
import org.jboss.arquillian.junit.Arquillian;
import org.jboss.arquillian.transaction.api.annotation.TransactionMode;
import org.jboss.arquillian.transaction.api.annotation.Transactional;
import org.junit.Test;
import org.junit.runner.RunWith;
import org.slf4j.Logger;
import org.slf4j.LoggerFactory;
import myapp.ejb.api.persistence.entities.CreditCard;
import myapp.ejb.api.persistence.entities.Customer;
import myapp.ejb.api.persistence.enums.CreditCardEnum;
import myapp.ejb.api.stateless.dto.CreditCardDtoEjbRemote;
import myapp.ejb.api.stateless.dto.CustomerDtoEjbRemote;
/**
* @author Adam Zimowski (mrazjava)
*/
@RunWith(Arquillian.class)
public class CreditCardDtoRemoteTest extends ArquillianPersistenceTest {
private static final Logger log = LoggerFactory.getLogger(CreditCardDtoRemoteTest.class);
@EJB
private CustomerDtoEjbRemote customerDto;
@EJB
private CreditCardDtoEjbRemote creditCardDto;
class TestData {
long customerId;
long creditCardId;
}
@Test //@Ignore
@Transactional(TransactionMode.DISABLED)
public void testCreditCard() throws Exception {
TestData td = prepareTestData();
testCreate(td);
testGetPlain(td);
testGetWithCustomer(td);
testDelete(td);
}
private TestData prepareTestData() {
TestData ps = new TestData();
ps.customerId = prepareTestCustomer();
return ps;
}
private long prepareTestCustomer() {
Customer customer = new Customer();
customer.setFirstName("VOJO*");
customer.setLastName("UBIPARIP*");
Customer result = customerDto.create(customer);
assertNotNull(result);
Long customerId = result.getId();
assertNotNull(customerId);
assertTrue(customerId > 0);
log.trace("using tmp customer with id [" + customerId + "]");
return customerId;
}
private void testCreate(TestData td) {
CreditCard creditCard = new CreditCard();
creditCard.setCardNumber("1111222233334444");
creditCard.setCardNumberLastFour("4444");
creditCard.setCreditCardType(CreditCardEnum.AmericanExpress);
creditCard.setCustomer(new Customer(td.customerId));
creditCard.setCvvCode("987");
creditCard.setExpirationMonth(8);
creditCard.setExpirationYear(2020);
creditCard.setFirstName("Vojo");
creditCard.setMiddleInitial("K");
creditCard.setLastName("Ubiparip");
CreditCard result = creditCardDto.create(creditCard);
assertNotNull(result);
Long creditCardId = result.getId();
assertNotNull(creditCardId);
td.creditCardId = creditCardId;
log.trace("card id: [" + creditCardId + "]");
assertTrue(creditCardId > 0);
}
private void testGetPlain(TestData td) throws Exception {
log.trace("reading cc with id [" + td.creditCardId + "]");
CreditCard cc = creditCardDto.get(td.creditCardId);
assertNotNull(cc);
assertNotNull(cc.getId());
assertTrue(cc.getId() > 0);
Customer customer = cc.getCustomer();
assertNotNull(customer);
assertNotNull(customer.getId());
assertNull(customer.getFirstName());
log.debug(cc.toString());
}
private void testGetWithCustomer(TestData td) {
log.trace("reading cc with id [" + td.creditCardId + "]");
CreditCard ccArg = new CreditCard(td.creditCardId);
ccArg.setCustomer(new Customer());
CreditCard cc = creditCardDto.get(ccArg);
assertNotNull(cc);
assertNotNull(cc.getId());
assertTrue(cc.getId() > 0);
Customer customer = cc.getCustomer();
assertNotNull(customer);
assertNotNull(customer.getId());
assertNotNull(customer.getFirstName());
log.debug(cc.toString());
}
private void testDelete(TestData td) {
log.trace("deleting cc [" + td.creditCardId + "]");
creditCardDto.delete(td.creditCardId);
CreditCard deletedCC = creditCardDto.get(td.creditCardId);
assertNotNull(deletedCC);
assertNull(deletedCC.getId());
}
}
The base sets up the deployment and note: in this test I chose not to use @UsingDataSet @ShouldMatchDataSet @Cleanup and friends.
package myapp.ejb.api.persistence.entities;
import java.io.Serializable;
import javax.persistence.Access;
import javax.persistence.AccessType;
import javax.persistence.Column;
import javax.persistence.Entity;
import javax.persistence.Enumerated;
import javax.persistence.GeneratedValue;
import javax.persistence.GenerationType;
import javax.persistence.Id;
import javax.persistence.Index;
import javax.persistence.JoinColumn;
import javax.persistence.ManyToOne;
import javax.persistence.Table;
import javax.persistence.UniqueConstraint;
import myapp.ejb.api.persistence.HibernateCustomTypes;
import myapp.ejb.api.persistence.enums.CreditCardEnum;
/**
* @author Adam Zimowski (mrazjava)
*/
@Entity
@Table(indexes={@Index(columnList="cardNumber",name="IDX_2499461766045791635_CARDNO",unique=true)}, uniqueConstraints = @UniqueConstraint(columnNames = { "customerId", "cardNo" }))
@Access(AccessType.FIELD)
public class CreditCard implements Serializable {
private static final long serialVersionUID = 2499461766045791635L;
@Id
@GeneratedValue(strategy = GenerationType.IDENTITY)
@Column(nullable = false, updatable = false)
private Long id;
@Enumerated
@Column(name = "ccType", nullable = false, updatable = false)
private CreditCardEnum creditCardType;
@Column
private String firstName;
@Column
private String middleInitial;
@Column
private String lastName;
/**
* CC number without the dashes. Is automatically AES encrypted and decrypted by the underlying user type.
*/
@org.hibernate.annotations.Type(type = HibernateCustomTypes.AES_USER_TYPE)
@Column(name = "cardNo", nullable = false, updatable = false, length = 48)
private String cardNumber;
@Column(name = "lastFour", nullable = false, updatable = false)
private String cardNumberLastFour;
@Column(name = "cvv")
private String cvvCode;
@Column(name = "expMonth")
private int expirationMonth;
@Column(name = "expYear")
private int expirationYear;
@ManyToOne(optional = false)
@JoinColumn(name = "customerId", nullable = false, updatable = false)
private Customer customer;
public CreditCard() {
}
public CreditCard(Long id) {
this();
this.id = id;
}
/**
* Instantiates a clone by deep copy from the source.
*
* @param creditCard
*/
public CreditCard(CreditCard creditCard) {
this();
if(creditCard != null) {
id = creditCard.id;
creditCardType = creditCard.creditCardType;
firstName = creditCard.firstName;
middleInitial = creditCard.middleInitial;
lastName = creditCard.lastName;
cardNumber = creditCard.cardNumber;
cardNumberLastFour = creditCard.cardNumberLastFour;
cvvCode = creditCard.cvvCode;
expirationMonth = creditCard.expirationMonth;
expirationYear = creditCard.expirationYear;
if(creditCard.customer != null) customer = new Customer(creditCard.customer.getId());
}
}
public Long getId() {
return id;
}
public void setId(Long aId) {
id = aId;
}
public CreditCardEnum getCreditCardType() {
return creditCardType;
}
public void setCreditCardType(CreditCardEnum aCreditCardType) {
creditCardType = aCreditCardType;
}
public String getFirstName() {
return firstName;
}
public void setFirstName(String aFirstName) {
firstName = aFirstName;
}
public String getMiddleInitial() {
return middleInitial;
}
public void setMiddleInitial(String aMiddleInitial) {
middleInitial = aMiddleInitial;
}
public String getLastName() {
return lastName;
}
public void setLastName(String aLastName) {
lastName = aLastName;
}
public String getCardNumber() {
return cardNumber;
}
public void setCardNumber(String aCardNumber) {
cardNumber = aCardNumber;
}
public String getCardNumberLastFour() {
return cardNumberLastFour;
}
public void setCardNumberLastFour(String aCardNumberLastFour) {
cardNumberLastFour = aCardNumberLastFour;
}
public String getCvvCode() {
return cvvCode;
}
public void setCvvCode(String aCvvCode) {
cvvCode = aCvvCode;
}
public int getExpirationMonth() {
return expirationMonth;
}
public void setExpirationMonth(int aExpirationMonth) {
expirationMonth = aExpirationMonth;
}
public int getExpirationYear() {
return expirationYear;
}
public void setExpirationYear(int aExpirationYear) {
expirationYear = aExpirationYear;
}
public Customer getCustomer() {
return customer;
}
public void setCustomer(Customer aCustomer) {
customer = aCustomer;
}
@Override
public String toString() {
String customerStr = null;
if(customer != null) customerStr = "@id " + customer.getId();
return "==> " + CreditCard.class.getSimpleName() + ": \n" +
"\tid: [" + id + "]\n" +
"\ttype: [" + creditCardType + "]\n" +
"\tfirst name: [" + firstName + "]\n" +
"\tmiddle init: [" + middleInitial + "]\n" +
"\tlast name: [" + lastName + "]\n" +
"\tcard number: [" + cardNumber + "]\n" +
"\tlast four: [" + cardNumberLastFour + "]\n" +
"\tcvv: [" + cvvCode + "]\n" +
"\texp month: [" + expirationMonth + "]\n" +
"\texp year: [" + expirationYear + "]\n" +
"\tcustomer: [" + customerStr + "]";
}
}
And the tested ejb is here:
package myapp.ejb.impl.stateless.dto;
import javax.ejb.EJB;
import javax.ejb.LocalBean;
import javax.ejb.Stateless;
import org.slf4j.Logger;
import org.slf4j.LoggerFactory;
import myapp.ejb.api.persistence.entities.CreditCard;
import myapp.ejb.api.persistence.entities.Customer;
import myapp.ejb.api.stateless.dto.CreditCardDtoEjbRemote;
import myapp.ejb.impl.stateless.dao.CreditCardDaoEjbLocal;
@Stateless
@LocalBean
public class CreditCardDtoEjb implements CreditCardDtoEjbRemote {
private static final Logger log = LoggerFactory.getLogger(CreditCardDtoEjb.class);
@EJB
private CreditCardDaoEjbLocal creditCardDao;
@Override
public CreditCard create(CreditCard card) {
if(card == null) return null;
CreditCard resultCC = creditCardDao.create(card);
Customer resultCustomer = resultCC.getCustomer();
CreditCard returnedCC = new CreditCard(resultCC);
returnedCC.setCustomer(new Customer(resultCustomer));
return returnedCC;
}
@Override
public CreditCard get(Long cardId) {
CreditCard result = creditCardDao.read(cardId);
return new CreditCard(result);
}
@Override
public CreditCard get(CreditCard card) {
if(card == null) {
log.warn("null argument; returning null");
return null;
}
Long id = card.getId();
if(id == null) {
log.warn("null id passed; returning empty instance");
return new CreditCard();
}
CreditCard ccResult = creditCardDao.read(id);
CreditCard returnedCC = new CreditCard(ccResult);
if(card.getCustomer() != null) {
Customer returnedCustomer = new Customer(ccResult.getCustomer());
returnedCC.setCustomer(returnedCustomer);
}
return returnedCC;
}
@Override
public void delete(Long cardId) {
creditCardDao.delete(new CreditCard(cardId));
}
}
So what happens is that when I setup @Transactional(TransactionMode.ROLLBACK), which is my goal, I'm getting AssertionError on CreditCardDtoRemoteTest.java:127 because related Customer is not loaded. However, test passes (customer does get loaded) when I change the TransactionMode to DISABLED.
Here is the log for failed test:
09:08:54,934 [INFO] [org.jboss.ejb.client] (<clinit>:42) JBoss EJB Client version 1.0.2.Final 09:08:55,041 [INFO] [stdout] (write:71) Hibernate: 09:08:55,042 [INFO] [stdout] (write:71) /* insert myapp.ejb.api.persistence.entities.Customer 09:08:55,043 [INFO] [stdout] (write:71) */ insert 09:08:55,043 [INFO] [stdout] (write:71) into 09:08:55,045 [INFO] [stdout] (write:71) O_CUSTOMER 09:08:55,046 [INFO] [stdout] (write:71) (address_id, discount, dob, first_name, last_name, mobile_phone) 09:08:55,047 [INFO] [stdout] (write:71) values 09:08:55,049 [INFO] [stdout] (write:71) (?, ?, ?, ?, ?, ?) 09:08:55,094 [TRACE] [myapp.ejb.api.test.CreditCardDtoRemoteTest] (prepareTestCustomer:69) using tmp customer with id [37] 09:08:55,100 [INFO] [stdout] (write:71) Hibernate: 09:08:55,100 [INFO] [stdout] (write:71) /* insert myapp.ejb.api.persistence.entities.CreditCard 09:08:55,101 [INFO] [stdout] (write:71) */ insert 09:08:55,102 [INFO] [stdout] (write:71) into 09:08:55,102 [INFO] [stdout] (write:71) O_CREDIT_CARD 09:08:55,103 [INFO] [stdout] (write:71) (card_no, last_four, cc_type, customer_id, cvv, exp_month, exp_year, first_name, last_name, middle_initial) 09:08:55,104 [INFO] [stdout] (write:71) values 09:08:55,105 [INFO] [stdout] (write:71) (?, ?, ?, ?, ?, ?, ?, ?, ?, ?) 09:08:55,106 [DEBUG] [myapp.ejb.crypto.CipherGnuAdapter] (encrypt:174) in.length: 16, out.length: 16 09:08:55,108 [DEBUG] [myapp.ejb.crypto.CipherGnuAdapter] (encrypt:181) encrypted: +X3iuCdU8BFZyNuvMGTvGg== 09:08:55,109 [DEBUG] [myapp.ejb.impl.persistence.hibernate.usertype.AESCipherUserType] (nullSafeSet:96) raw [1111222233334444], aes->hex [2B583369754364553842465A794E75764D47547647673D3D] 09:08:55,112 [TRACE] [myapp.ejb.api.test.CreditCardDtoRemoteTest] (testCreate:91) card id: [2] 09:08:55,113 [TRACE] [myapp.ejb.api.test.CreditCardDtoRemoteTest] (testGetPlain:96) reading cc with id [2] 09:08:55,115 [DEBUG] [myapp.ejb.api.test.CreditCardDtoRemoteTest] (testGetPlain:105) ==> CreditCard: id: [2] type: [AmericanExpress] first name: [Vojo] middle init: [K] last name: [Ubiparip] card number: [1111222233334444] last four: [4444] cvv: [987] exp month: [8] exp year: [2020] customer: [@id 37] 09:08:55,116 [TRACE] [myapp.ejb.api.test.CreditCardDtoRemoteTest] (testGetWithCustomer:109) reading cc with id [2] 09:08:55,183 [SEVERE] [org.jboss.arquillian.protocol.jmx.JMXTestRunner] (runTestMethodInternal:147) Failed: myapp.ejb.api.test.CreditCardDtoRemoteTest.testCreditCard: java.lang.AssertionError at org.junit.Assert.fail(Assert.java:86) [arquillian-service:] at org.junit.Assert.assertTrue(Assert.java:41) [arquillian-service:] at org.junit.Assert.assertNotNull(Assert.java:712) [arquillian-service:] at org.junit.Assert.assertNotNull(Assert.java:722) [arquillian-service:] at myapp.ejb.api.test.CreditCardDtoRemoteTest.testGetWithCustomer(CreditCardDtoRemoteTest.java:119) [myapp-ejb-test.jar:] at myapp.ejb.api.test.CreditCardDtoRemoteTest.testCreditCard(CreditCardDtoRemoteTest.java:50) [myapp-ejb-test.jar:] at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method) [rt.jar:1.7.0_80] at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:57) [rt.jar:1.7.0_80] at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) [rt.jar:1.7.0_80] at java.lang.reflect.Method.invoke(Method.java:606) [rt.jar:1.7.0_80] at org.junit.runners.model.FrameworkMethod$1.runReflectiveCall(FrameworkMethod.java:50) [arquillian-service:] at org.junit.internal.runners.model.ReflectiveCallable.run(ReflectiveCallable.java:12) [arquillian-service:] at org.junit.runners.model.FrameworkMethod.invokeExplosively(FrameworkMethod.java:47) [arquillian-service:] at org.jboss.arquillian.junit.Arquillian$8$1.invoke(Arquillian.java:370) [arquillian-service:] at org.jboss.arquillian.container.test.impl.execution.LocalTestExecuter.execute(LocalTestExecuter.java:60) [arquillian-service:] at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method) [rt.jar:1.7.0_80] at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:57) [rt.jar:1.7.0_80] at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) [rt.jar:1.7.0_80] at java.lang.reflect.Method.invoke(Method.java:606) [rt.jar:1.7.0_80] at org.jboss.arquillian.core.impl.ObserverImpl.invoke(ObserverImpl.java:94) [arquillian-service:] at org.jboss.arquillian.core.impl.EventContextImpl.invokeObservers(EventContextImpl.java:99) [arquillian-service:] at org.jboss.arquillian.core.impl.EventContextImpl.proceed(EventContextImpl.java:81) [arquillian-service:] at org.jboss.arquillian.core.impl.ManagerImpl.fire(ManagerImpl.java:145) [arquillian-service:] at org.jboss.arquillian.core.impl.ManagerImpl.fire(ManagerImpl.java:116) [arquillian-service:] at org.jboss.arquillian.core.impl.EventImpl.fire(EventImpl.java:67) [arquillian-service:] at org.jboss.arquillian.container.test.impl.execution.ContainerTestExecuter.execute(ContainerTestExecuter.java:38) [arquillian-service:] at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method) [rt.jar:1.7.0_80] at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:57) [rt.jar:1.7.0_80] at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) [rt.jar:1.7.0_80] at java.lang.reflect.Method.invoke(Method.java:606) [rt.jar:1.7.0_80] at org.jboss.arquillian.core.impl.ObserverImpl.invoke(ObserverImpl.java:94) [arquillian-service:] at org.jboss.arquillian.core.impl.EventContextImpl.invokeObservers(EventContextImpl.java:99) [arquillian-service:] at org.jboss.arquillian.core.impl.EventContextImpl.proceed(EventContextImpl.java:81) [arquillian-service:] at org.jboss.arquillian.test.impl.TestContextHandler.createTestContext(TestContextHandler.java:130) [arquillian-service:] at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method) [rt.jar:1.7.0_80] at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:57) [rt.jar:1.7.0_80] at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) [rt.jar:1.7.0_80] at java.lang.reflect.Method.invoke(Method.java:606) [rt.jar:1.7.0_80] at org.jboss.arquillian.core.impl.ObserverImpl.invoke(ObserverImpl.java:94) [arquillian-service:] at org.jboss.arquillian.core.impl.EventContextImpl.proceed(EventContextImpl.java:88) [arquillian-service:] at org.jboss.arquillian.test.impl.TestContextHandler.createClassContext(TestContextHandler.java:92) [arquillian-service:] at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method) [rt.jar:1.7.0_80] at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:57) [rt.jar:1.7.0_80] at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) [rt.jar:1.7.0_80] at java.lang.reflect.Method.invoke(Method.java:606) [rt.jar:1.7.0_80] at org.jboss.arquillian.core.impl.ObserverImpl.invoke(ObserverImpl.java:94) [arquillian-service:] at org.jboss.arquillian.core.impl.EventContextImpl.proceed(EventContextImpl.java:88) [arquillian-service:] at org.jboss.arquillian.test.impl.TestContextHandler.createSuiteContext(TestContextHandler.java:73) [arquillian-service:] at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method) [rt.jar:1.7.0_80] at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:57) [rt.jar:1.7.0_80] at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) [rt.jar:1.7.0_80] at java.lang.reflect.Method.invoke(Method.java:606) [rt.jar:1.7.0_80] at org.jboss.arquillian.core.impl.ObserverImpl.invoke(ObserverImpl.java:94) [arquillian-service:] at org.jboss.arquillian.core.impl.EventContextImpl.proceed(EventContextImpl.java:88) [arquillian-service:] at org.jboss.arquillian.core.impl.ManagerImpl.fire(ManagerImpl.java:145) [arquillian-service:] at org.jboss.arquillian.test.impl.EventTestRunnerAdaptor.test(EventTestRunnerAdaptor.java:136) [arquillian-service:] at org.jboss.arquillian.junit.Arquillian$8.evaluate(Arquillian.java:363) [arquillian-service:] at org.jboss.arquillian.junit.Arquillian$4.evaluate(Arquillian.java:245) [arquillian-service:] at org.jboss.arquillian.junit.Arquillian.multiExecute(Arquillian.java:422) [arquillian-service:] at org.jboss.arquillian.junit.Arquillian.access$200(Arquillian.java:54) [arquillian-service:] at org.jboss.arquillian.junit.Arquillian$5.evaluate(Arquillian.java:259) [arquillian-service:] at org.jboss.arquillian.junit.Arquillian$7$1.invoke(Arquillian.java:315) [arquillian-service:] at org.jboss.arquillian.container.test.impl.execution.BeforeLifecycleEventExecuter.on(BeforeLifecycleEventExecuter.java:35) [arquillian-service:] at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method) [rt.jar:1.7.0_80] at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:57) [rt.jar:1.7.0_80] at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) [rt.jar:1.7.0_80] at java.lang.reflect.Method.invoke(Method.java:606) [rt.jar:1.7.0_80] at org.jboss.arquillian.core.impl.ObserverImpl.invoke(ObserverImpl.java:94) [arquillian-service:] at org.jboss.arquillian.core.impl.EventContextImpl.invokeObservers(EventContextImpl.java:99) [arquillian-service:] at org.jboss.arquillian.core.impl.EventContextImpl.proceed(EventContextImpl.java:81) [arquillian-service:] at org.jboss.arquillian.test.impl.TestContextHandler.createTestContext(TestContextHandler.java:130) [arquillian-service:] at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method) [rt.jar:1.7.0_80] at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:57) [rt.jar:1.7.0_80] at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) [rt.jar:1.7.0_80] at java.lang.reflect.Method.invoke(Method.java:606) [rt.jar:1.7.0_80] at org.jboss.arquillian.core.impl.ObserverImpl.invoke(ObserverImpl.java:94) [arquillian-service:] at org.jboss.arquillian.core.impl.EventContextImpl.proceed(EventContextImpl.java:88) [arquillian-service:] at org.jboss.arquillian.test.impl.TestContextHandler.createClassContext(TestContextHandler.java:92) [arquillian-service:] at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method) [rt.jar:1.7.0_80] at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:57) [rt.jar:1.7.0_80] at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) [rt.jar:1.7.0_80] at java.lang.reflect.Method.invoke(Method.java:606) [rt.jar:1.7.0_80] at org.jboss.arquillian.core.impl.ObserverImpl.invoke(ObserverImpl.java:94) [arquillian-service:] at org.jboss.arquillian.core.impl.EventContextImpl.proceed(EventContextImpl.java:88) [arquillian-service:] at org.jboss.arquillian.test.impl.TestContextHandler.createSuiteContext(TestContextHandler.java:73) [arquillian-service:] at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method) [rt.jar:1.7.0_80] at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:57) [rt.jar:1.7.0_80] at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) [rt.jar:1.7.0_80] at java.lang.reflect.Method.invoke(Method.java:606) [rt.jar:1.7.0_80] at org.jboss.arquillian.core.impl.ObserverImpl.invoke(ObserverImpl.java:94) [arquillian-service:] at org.jboss.arquillian.core.impl.EventContextImpl.proceed(EventContextImpl.java:88) [arquillian-service:] at org.jboss.arquillian.core.impl.ManagerImpl.fire(ManagerImpl.java:145) [arquillian-service:] at org.jboss.arquillian.core.impl.ManagerImpl.fire(ManagerImpl.java:116) [arquillian-service:] at org.jboss.arquillian.test.impl.EventTestRunnerAdaptor.fireCustomLifecycle(EventTestRunnerAdaptor.java:159) [arquillian-service:] at org.jboss.arquillian.junit.Arquillian$7.evaluate(Arquillian.java:311) [arquillian-service:] at org.junit.runners.ParentRunner.runLeaf(ParentRunner.java:325) [arquillian-service:] at org.junit.runners.BlockJUnit4ClassRunner.runChild(BlockJUnit4ClassRunner.java:78) [arquillian-service:] at org.junit.runners.BlockJUnit4ClassRunner.runChild(BlockJUnit4ClassRunner.java:57) [arquillian-service:] at org.junit.runners.ParentRunner$3.run(ParentRunner.java:290) [arquillian-service:] at org.junit.runners.ParentRunner$1.schedule(ParentRunner.java:71) [arquillian-service:] at org.junit.runners.ParentRunner.runChildren(ParentRunner.java:288) [arquillian-service:] at org.junit.runners.ParentRunner.access$000(ParentRunner.java:58) [arquillian-service:] at org.junit.runners.ParentRunner$2.evaluate(ParentRunner.java:268) [arquillian-service:] at org.jboss.arquillian.junit.Arquillian$2.evaluate(Arquillian.java:204) [arquillian-service:] at org.jboss.arquillian.junit.Arquillian.multiExecute(Arquillian.java:422) [arquillian-service:] at org.jboss.arquillian.junit.Arquillian.access$200(Arquillian.java:54) [arquillian-service:] at org.jboss.arquillian.junit.Arquillian$3.evaluate(Arquillian.java:218) [arquillian-service:] at org.junit.runners.ParentRunner.run(ParentRunner.java:363) [arquillian-service:] at org.jboss.arquillian.junit.Arquillian.run(Arquillian.java:166) [arquillian-service:] at org.junit.runner.JUnitCore.run(JUnitCore.java:137) [arquillian-service:] at org.junit.runner.JUnitCore.run(JUnitCore.java:115) [arquillian-service:] at org.jboss.arquillian.junit.container.JUnitTestRunner.execute(JUnitTestRunner.java:66) [arquillian-service:] at org.jboss.arquillian.protocol.jmx.JMXTestRunner.runTestMethodInternal(JMXTestRunner.java:135) [arquillian-service:] at org.jboss.arquillian.protocol.jmx.JMXTestRunner.runTestMethod(JMXTestRunner.java:114) [arquillian-service:] at org.jboss.as.arquillian.service.ArquillianService$ExtendedJMXTestRunner.runTestMethod(ArquillianService.java:226) [arquillian-service:] at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method) [rt.jar:1.7.0_80] at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:57) [rt.jar:1.7.0_80] at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) [rt.jar:1.7.0_80] at java.lang.reflect.Method.invoke(Method.java:606) [rt.jar:1.7.0_80] at sun.reflect.misc.Trampoline.invoke(MethodUtil.java:75) [rt.jar:1.7.0_80] at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method) [rt.jar:1.7.0_80] at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:57) [rt.jar:1.7.0_80] at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) [rt.jar:1.7.0_80] at java.lang.reflect.Method.invoke(Method.java:606) [rt.jar:1.7.0_80] at sun.reflect.misc.MethodUtil.invoke(MethodUtil.java:279) [rt.jar:1.7.0_80] at com.sun.jmx.mbeanserver.StandardMBeanIntrospector.invokeM2(StandardMBeanIntrospector.java:112) [rt.jar:1.7.0_80] at com.sun.jmx.mbeanserver.StandardMBeanIntrospector.invokeM2(StandardMBeanIntrospector.java:46) [rt.jar:1.7.0_80] at com.sun.jmx.mbeanserver.MBeanIntrospector.invokeM(MBeanIntrospector.java:237) [rt.jar:1.7.0_80] at com.sun.jmx.mbeanserver.PerInterface.invoke(PerInterface.java:138) [rt.jar:1.7.0_80] at com.sun.jmx.mbeanserver.MBeanSupport.invoke(MBeanSupport.java:252) [rt.jar:1.7.0_80] at com.sun.jmx.interceptor.DefaultMBeanServerInterceptor.invoke(DefaultMBeanServerInterceptor.java:819) [rt.jar:1.7.0_80] at com.sun.jmx.mbeanserver.JmxMBeanServer.invoke(JmxMBeanServer.java:801) [rt.jar:1.7.0_80] at org.jboss.as.jmx.PluggableMBeanServerImpl$TcclMBeanServer.invoke(PluggableMBeanServerImpl.java:489) at org.jboss.as.jmx.PluggableMBeanServerImpl.invoke(PluggableMBeanServerImpl.java:243) at org.jboss.remoting3.jmx.protocol.v1.ServerProxy$InvokeHandler.handle(ServerProxy.java:1034) at org.jboss.remoting3.jmx.protocol.v1.ServerProxy$MessageReciever$1.run(ServerProxy.java:215) at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1145) [rt.jar:1.7.0_80] at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:615) [rt.jar:1.7.0_80] at java.lang.Thread.run(Thread.java:745) [rt.jar:1.7.0_80] Apr 23, 2015 9:08:55 AM org.jboss.arquillian.protocol.jmx.JMXMethodExecutor invoke SEVERE: Failed: myapp.ejb.api.test.CreditCardDtoRemoteTest.testCreditCard java.lang.AssertionError at org.junit.Assert.fail(Assert.java:86) at org.junit.Assert.assertTrue(Assert.java:41) at org.junit.Assert.assertNotNull(Assert.java:712) at org.junit.Assert.assertNotNull(Assert.java:722) at myapp.ejb.api.test.CreditCardDtoRemoteTest.testGetWithCustomer(CreditCardDtoRemoteTest.java:119) at myapp.ejb.api.test.CreditCardDtoRemoteTest.testCreditCard(CreditCardDtoRemoteTest.java:50) at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method) at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:57) at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) at java.lang.reflect.Method.invoke(Method.java:606) at org.junit.runners.model.FrameworkMethod$1.runReflectiveCall(FrameworkMethod.java:50) at org.junit.internal.runners.model.ReflectiveCallable.run(ReflectiveCallable.java:12) at org.junit.runners.model.FrameworkMethod.invokeExplosively(FrameworkMethod.java:47) at org.jboss.arquillian.junit.Arquillian$8$1.invoke(Arquillian.java:370) at org.jboss.arquillian.container.test.impl.execution.LocalTestExecuter.execute(LocalTestExecuter.java:60) at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method) at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:57) at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) at java.lang.reflect.Method.invoke(Method.java:606) at org.jboss.arquillian.core.impl.ObserverImpl.invoke(ObserverImpl.java:94) at org.jboss.arquillian.core.impl.EventContextImpl.invokeObservers(EventContextImpl.java:99) at org.jboss.arquillian.core.impl.EventContextImpl.proceed(EventContextImpl.java:81) at org.jboss.arquillian.core.impl.ManagerImpl.fire(ManagerImpl.java:145) at org.jboss.arquillian.core.impl.ManagerImpl.fire(ManagerImpl.java:116) at org.jboss.arquillian.core.impl.EventImpl.fire(EventImpl.java:67) at org.jboss.arquillian.container.test.impl.execution.ContainerTestExecuter.execute(ContainerTestExecuter.java:38) at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method) at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:57) at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) at java.lang.reflect.Method.invoke(Method.java:606) at org.jboss.arquillian.core.impl.ObserverImpl.invoke(ObserverImpl.java:94) at org.jboss.arquillian.core.impl.EventContextImpl.invokeObservers(EventContextImpl.java:99) at org.jboss.arquillian.core.impl.EventContextImpl.proceed(EventContextImpl.java:81) at org.jboss.arquillian.test.impl.TestContextHandler.createTestContext(TestContextHandler.java:130) at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method) at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:57) at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) at java.lang.reflect.Method.invoke(Method.java:606) at org.jboss.arquillian.core.impl.ObserverImpl.invoke(ObserverImpl.java:94) at org.jboss.arquillian.core.impl.EventContextImpl.proceed(EventContextImpl.java:88) at org.jboss.arquillian.test.impl.TestContextHandler.createClassContext(TestContextHandler.java:92) at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method) at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:57) at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) at java.lang.reflect.Method.invoke(Method.java:606) at org.jboss.arquillian.core.impl.ObserverImpl.invoke(ObserverImpl.java:94) at org.jboss.arquillian.core.impl.EventContextImpl.proceed(EventContextImpl.java:88) at org.jboss.arquillian.test.impl.TestContextHandler.createSuiteContext(TestContextHandler.java:73) at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method) at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:57) at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) at java.lang.reflect.Method.invoke(Method.java:606) at org.jboss.arquillian.core.impl.ObserverImpl.invoke(ObserverImpl.java:94) at org.jboss.arquillian.core.impl.EventContextImpl.proceed(EventContextImpl.java:88) at org.jboss.arquillian.core.impl.ManagerImpl.fire(ManagerImpl.java:145) at org.jboss.arquillian.test.impl.EventTestRunnerAdaptor.test(EventTestRunnerAdaptor.java:136) at org.jboss.arquillian.junit.Arquillian$8.evaluate(Arquillian.java:363) at org.jboss.arquillian.junit.Arquillian$4.evaluate(Arquillian.java:245) at org.jboss.arquillian.junit.Arquillian.multiExecute(Arquillian.java:422) at org.jboss.arquillian.junit.Arquillian.access$200(Arquillian.java:54) at org.jboss.arquillian.junit.Arquillian$5.evaluate(Arquillian.java:259) at org.jboss.arquillian.junit.Arquillian$7$1.invoke(Arquillian.java:315) at org.jboss.arquillian.container.test.impl.execution.BeforeLifecycleEventExecuter.on(BeforeLifecycleEventExecuter.java:35) at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method) at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:57) at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) at java.lang.reflect.Method.invoke(Method.java:606) at org.jboss.arquillian.core.impl.ObserverImpl.invoke(ObserverImpl.java:94) at org.jboss.arquillian.core.impl.EventContextImpl.invokeObservers(EventContextImpl.java:99) at org.jboss.arquillian.core.impl.EventContextImpl.proceed(EventContextImpl.java:81) at org.jboss.arquillian.test.impl.TestContextHandler.createTestContext(TestContextHandler.java:130) at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method) at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:57) at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) at java.lang.reflect.Method.invoke(Method.java:606) at org.jboss.arquillian.core.impl.ObserverImpl.invoke(ObserverImpl.java:94) at org.jboss.arquillian.core.impl.EventContextImpl.proceed(EventContextImpl.java:88) at org.jboss.arquillian.test.impl.TestContextHandler.createClassContext(TestContextHandler.java:92) at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method) at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:57) at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) at java.lang.reflect.Method.invoke(Method.java:606) at org.jboss.arquillian.core.impl.ObserverImpl.invoke(ObserverImpl.java:94) at org.jboss.arquillian.core.impl.EventContextImpl.proceed(EventContextImpl.java:88) at org.jboss.arquillian.test.impl.TestContextHandler.createSuiteContext(TestContextHandler.java:73) at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method) at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:57) at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) at java.lang.reflect.Method.invoke(Method.java:606) at org.jboss.arquillian.core.impl.ObserverImpl.invoke(ObserverImpl.java:94) at org.jboss.arquillian.core.impl.EventContextImpl.proceed(EventContextImpl.java:88) at org.jboss.arquillian.core.impl.ManagerImpl.fire(ManagerImpl.java:145) at org.jboss.arquillian.core.impl.ManagerImpl.fire(ManagerImpl.java:116) at org.jboss.arquillian.test.impl.EventTestRunnerAdaptor.fireCustomLifecycle(EventTestRunnerAdaptor.java:159) at org.jboss.arquillian.junit.Arquillian$7.evaluate(Arquillian.java:311) at org.junit.runners.ParentRunner.runLeaf(ParentRunner.java:325) at org.junit.runners.BlockJUnit4ClassRunner.runChild(BlockJUnit4ClassRunner.java:78) at org.junit.runners.BlockJUnit4ClassRunner.runChild(BlockJUnit4ClassRunner.java:57) at org.junit.runners.ParentRunner$3.run(ParentRunner.java:290) at org.junit.runners.ParentRunner$1.schedule(ParentRunner.java:71) at org.junit.runners.ParentRunner.runChildren(ParentRunner.java:288) at org.junit.runners.ParentRunner.access$000(ParentRunner.java:58) at org.junit.runners.ParentRunner$2.evaluate(ParentRunner.java:268) at org.jboss.arquillian.junit.Arquillian$2.evaluate(Arquillian.java:204) at org.jboss.arquillian.junit.Arquillian.multiExecute(Arquillian.java:422) at org.jboss.arquillian.junit.Arquillian.access$200(Arquillian.java:54) at org.jboss.arquillian.junit.Arquillian$3.evaluate(Arquillian.java:218) at org.junit.runners.ParentRunner.run(ParentRunner.java:363) at org.jboss.arquillian.junit.Arquillian.run(Arquillian.java:166) at org.junit.runner.JUnitCore.run(JUnitCore.java:137) at org.junit.runner.JUnitCore.run(JUnitCore.java:115) at org.jboss.arquillian.junit.container.JUnitTestRunner.execute(JUnitTestRunner.java:66) at org.jboss.arquillian.protocol.jmx.JMXTestRunner.runTestMethodInternal(JMXTestRunner.java:135) at org.jboss.arquillian.protocol.jmx.JMXTestRunner.runTestMethod(JMXTestRunner.java:114) at org.jboss.as.arquillian.service.ArquillianService$ExtendedJMXTestRunner.runTestMethod(ArquillianService.java:226) at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method) at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:57) at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) at java.lang.reflect.Method.invoke(Method.java:606) at sun.reflect.misc.Trampoline.invoke(MethodUtil.java:75) at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method) at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:57) at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) at java.lang.reflect.Method.invoke(Method.java:606) at sun.reflect.misc.MethodUtil.invoke(MethodUtil.java:279) at com.sun.jmx.mbeanserver.StandardMBeanIntrospector.invokeM2(StandardMBeanIntrospector.java:112) at com.sun.jmx.mbeanserver.StandardMBeanIntrospector.invokeM2(StandardMBeanIntrospector.java:46) at com.sun.jmx.mbeanserver.MBeanIntrospector.invokeM(MBeanIntrospector.java:237) at com.sun.jmx.mbeanserver.PerInterface.invoke(PerInterface.java:138) at com.sun.jmx.mbeanserver.MBeanSupport.invoke(MBeanSupport.java:252) at com.sun.jmx.interceptor.DefaultMBeanServerInterceptor.invoke(DefaultMBeanServerInterceptor.java:819) at com.sun.jmx.mbeanserver.JmxMBeanServer.invoke(JmxMBeanServer.java:801) at org.jboss.as.jmx.PluggableMBeanServerImpl$TcclMBeanServer.invoke(PluggableMBeanServerImpl.java:489) at org.jboss.as.jmx.PluggableMBeanServerImpl.invoke(PluggableMBeanServerImpl.java:243) at org.jboss.remoting3.jmx.protocol.v1.ServerProxy$InvokeHandler.handle(ServerProxy.java:1034) at org.jboss.remoting3.jmx.protocol.v1.ServerProxy$MessageReciever$1.run(ServerProxy.java:215) at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1145) at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:615) at java.lang.Thread.run(Thread.java:745) 09:08:55,383 [INFO] [org.jboss.weld.deployer] (stop:89) JBAS016009: Stopping weld service for deployment myapp-test.ear 09:08:55,393 [INFO] [org.jboss.as.jpa] (stop:94) JBAS011403: Stopping Persistence Unit Service 'myapp-test.ear/myapp-ejb-test.jar#myapp' 09:08:55,424 [INFO] [org.jboss.as.server.deployment] (stop:92) JBAS015877: Stopped deployment myapp-ejb-test.jar in 76ms 09:08:55,435 [INFO] [org.jboss.as.server.deployment] (stop:92) JBAS015877: Stopped deployment myapp-test.ear in 89ms 09:08:55,450 [INFO] [org.jboss.as.repository] (removeContent:269) JBAS014901: Content removed from location /opt/jboss/jboss-as-7.1.0.Final-test/standalone/data/content/44/9930060aa2c6f64c4a4827d22868c4cebe900e/content 09:08:55,452 [INFO] [org.jboss.as.server] (execute:309) JBAS018558: Undeployed "myapp-test.ear" 2015-04-23 09:08:55,469 [INFO] org.jboss.as.arquillian.protocol.jmx.ArquillianServiceDeployer (undeploy:72) - Undeploy arquillian service: arquillian-service: 999 assets 09:08:55,479 [INFO] [org.jboss.as.server.deployment] (stop:92) JBAS015877: Stopped deployment arquillian-service in 4ms 09:08:55,491 [INFO] [org.jboss.as.repository] (removeContent:269) JBAS014901: Content removed from location /opt/jboss/jboss-as-7.1.0.Final-test/standalone/data/content/33/a21a01d6a5d4844d504c3d419ab58ac278440f/content 09:08:55,492 [INFO] [org.jboss.as.server] (execute:309) JBAS018558: Undeployed "arquillian-service"
Note lines 23 and 24 of the log, when reading entity Hibernate does not load it; rather it returns cached version. When test TransactionMode is DISABLED and test passes, the log shows Hibernate loading entity as expected:
09:18:17,357 [INFO] [org.jboss.ejb.client] (<clinit>:42) JBoss EJB Client version 1.0.2.Final 09:18:17,475 [INFO] [stdout] (write:71) Hibernate: 09:18:17,475 [INFO] [stdout] (write:71) /* insert myapp.ejb.api.persistence.entities.Customer 09:18:17,476 [INFO] [stdout] (write:71) */ insert 09:18:17,477 [INFO] [stdout] (write:71) into 09:18:17,477 [INFO] [stdout] (write:71) O_CUSTOMER 09:18:17,478 [INFO] [stdout] (write:71) (address_id, discount, dob, first_name, last_name, mobile_phone) 09:18:17,478 [INFO] [stdout] (write:71) values 09:18:17,479 [INFO] [stdout] (write:71) (?, ?, ?, ?, ?, ?) 09:18:17,624 [TRACE] [myapp.ejb.api.test.CreditCardDtoRemoteTest] (prepareTestCustomer:69) using tmp customer with id [38] 09:18:17,628 [INFO] [stdout] (write:71) Hibernate: 09:18:17,629 [INFO] [stdout] (write:71) /* insert myapp.ejb.api.persistence.entities.CreditCard 09:18:17,630 [INFO] [stdout] (write:71) */ insert 09:18:17,630 [INFO] [stdout] (write:71) into 09:18:17,631 [INFO] [stdout] (write:71) O_CREDIT_CARD 09:18:17,631 [INFO] [stdout] (write:71) (card_no, last_four, cc_type, customer_id, cvv, exp_month, exp_year, first_name, last_name, middle_initial) 09:18:17,632 [INFO] [stdout] (write:71) values 09:18:17,633 [INFO] [stdout] (write:71) (?, ?, ?, ?, ?, ?, ?, ?, ?, ?) 09:18:17,633 [DEBUG] [myapp.ejb.crypto.CipherGnuAdapter] (encrypt:174) in.length: 16, out.length: 16 09:18:17,635 [DEBUG] [myapp.ejb.crypto.CipherGnuAdapter] (encrypt:181) encrypted: +X3iuCdU8BFZyNuvMGTvGg== 09:18:17,636 [DEBUG] [myapp.ejb.impl.persistence.hibernate.usertype.AESCipherUserType] (nullSafeSet:96) raw [1111222233334444], aes->hex [2B583369754364553842465A794E75764D47547647673D3D] 09:18:17,699 [TRACE] [myapp.ejb.api.test.CreditCardDtoRemoteTest] (testCreate:91) card id: [3] 09:18:17,700 [TRACE] [myapp.ejb.api.test.CreditCardDtoRemoteTest] (testGetPlain:96) reading cc with id [3] 09:18:17,707 [INFO] [stdout] (write:71) Hibernate: 09:18:17,708 [INFO] [stdout] (write:71) /* load myapp.ejb.api.persistence.entities.CreditCard */ select 09:18:17,708 [INFO] [stdout] (write:71) creditcard0_.id as id1_1_, 09:18:17,709 [INFO] [stdout] (write:71) creditcard0_.card_no as card2_1_1_, 09:18:17,710 [INFO] [stdout] (write:71) creditcard0_.last_four as last3_1_1_, 09:18:17,711 [INFO] [stdout] (write:71) creditcard0_.cc_type as cc4_1_1_, 09:18:17,712 [INFO] [stdout] (write:71) creditcard0_.customer_id as customer11_1_1_, 09:18:17,713 [INFO] [stdout] (write:71) creditcard0_.cvv as cvv1_1_, 09:18:17,714 [INFO] [stdout] (write:71) creditcard0_.exp_month as exp6_1_1_, 09:18:17,715 [INFO] [stdout] (write:71) creditcard0_.exp_year as exp7_1_1_, 09:18:17,715 [INFO] [stdout] (write:71) creditcard0_.first_name as first8_1_1_, 09:18:17,716 [INFO] [stdout] (write:71) creditcard0_.last_name as last9_1_1_, 09:18:17,716 [INFO] [stdout] (write:71) creditcard0_.middle_initial as middle10_1_1_, 09:18:17,717 [INFO] [stdout] (write:71) customer1_.id as id2_0_, 09:18:17,717 [INFO] [stdout] (write:71) customer1_.address_id as address7_2_0_, 09:18:17,718 [INFO] [stdout] (write:71) customer1_.discount as discount2_0_, 09:18:17,719 [INFO] [stdout] (write:71) customer1_.dob as dob2_0_, 09:18:17,719 [INFO] [stdout] (write:71) customer1_.first_name as first4_2_0_, 09:18:17,720 [INFO] [stdout] (write:71) customer1_.last_name as last5_2_0_, 09:18:17,720 [INFO] [stdout] (write:71) customer1_.mobile_phone as mobile6_2_0_ 09:18:17,721 [INFO] [stdout] (write:71) from 09:18:17,721 [INFO] [stdout] (write:71) O_CREDIT_CARD creditcard0_ 09:18:17,722 [INFO] [stdout] (write:71) inner join 09:18:17,722 [INFO] [stdout] (write:71) O_CUSTOMER customer1_ 09:18:17,723 [INFO] [stdout] (write:71) on creditcard0_.customer_id=customer1_.id 09:18:17,724 [INFO] [stdout] (write:71) where 09:18:17,724 [INFO] [stdout] (write:71) creditcard0_.id=? 09:18:17,729 [DEBUG] [myapp.ejb.impl.persistence.hibernate.usertype.AESCipherUserType] (nullSafeGet:62) encrypted aes->hex [2B583369754364553842465A794E75764D47547647673D3D], raw/decrypted [1111222233334444] 09:18:17,736 [INFO] [stdout] (write:71) Hibernate: 09:18:17,737 [INFO] [stdout] (write:71) /* load myapp.ejb.api.persistence.entities.CustomerPreferences */ select 09:18:17,737 [INFO] [stdout] (write:71) customerpr0_.customer_id as customer1_4_0_ 09:18:17,738 [INFO] [stdout] (write:71) from 09:18:17,738 [INFO] [stdout] (write:71) O_CUSTOMER_PREFERENCES customerpr0_ 09:18:17,739 [INFO] [stdout] (write:71) where 09:18:17,740 [INFO] [stdout] (write:71) customerpr0_.customer_id=? 09:18:17,743 [DEBUG] [myapp.ejb.api.test.CreditCardDtoRemoteTest] (testGetPlain:105) ==> CreditCard: id: [3] type: [AmericanExpress] first name: [Vojo] middle init: [K] last name: [Ubiparip] card number: [1111222233334444] last four: [4444] cvv: [987] exp month: [8] exp year: [2020] customer: [@id 38] 09:18:17,744 [TRACE] [myapp.ejb.api.test.CreditCardDtoRemoteTest] (testGetWithCustomer:109) reading cc with id [3] 09:18:17,746 [INFO] [stdout] (write:71) Hibernate: 09:18:17,746 [INFO] [stdout] (write:71) /* load myapp.ejb.api.persistence.entities.CreditCard */ select 09:18:17,747 [INFO] [stdout] (write:71) creditcard0_.id as id1_1_, 09:18:17,748 [INFO] [stdout] (write:71) creditcard0_.card_no as card2_1_1_, 09:18:17,748 [INFO] [stdout] (write:71) creditcard0_.last_four as last3_1_1_, 09:18:17,749 [INFO] [stdout] (write:71) creditcard0_.cc_type as cc4_1_1_, 09:18:17,749 [INFO] [stdout] (write:71) creditcard0_.customer_id as customer11_1_1_, 09:18:17,750 [INFO] [stdout] (write:71) creditcard0_.cvv as cvv1_1_, 09:18:17,750 [INFO] [stdout] (write:71) creditcard0_.exp_month as exp6_1_1_, 09:18:17,751 [INFO] [stdout] (write:71) creditcard0_.exp_year as exp7_1_1_, 09:18:17,752 [INFO] [stdout] (write:71) creditcard0_.first_name as first8_1_1_, 09:18:17,752 [INFO] [stdout] (write:71) creditcard0_.last_name as last9_1_1_, 09:18:17,753 [INFO] [stdout] (write:71) creditcard0_.middle_initial as middle10_1_1_, 09:18:17,753 [INFO] [stdout] (write:71) customer1_.id as id2_0_, 09:18:17,754 [INFO] [stdout] (write:71) customer1_.address_id as address7_2_0_, 09:18:17,754 [INFO] [stdout] (write:71) customer1_.discount as discount2_0_, 09:18:17,755 [INFO] [stdout] (write:71) customer1_.dob as dob2_0_, 09:18:17,755 [INFO] [stdout] (write:71) customer1_.first_name as first4_2_0_, 09:18:17,756 [INFO] [stdout] (write:71) customer1_.last_name as last5_2_0_, 09:18:17,757 [INFO] [stdout] (write:71) customer1_.mobile_phone as mobile6_2_0_ 09:18:17,757 [INFO] [stdout] (write:71) from 09:18:17,758 [INFO] [stdout] (write:71) O_CREDIT_CARD creditcard0_ 09:18:17,758 [INFO] [stdout] (write:71) inner join 09:18:17,759 [INFO] [stdout] (write:71) O_CUSTOMER customer1_ 09:18:17,760 [INFO] [stdout] (write:71) on creditcard0_.customer_id=customer1_.id 09:18:17,760 [INFO] [stdout] (write:71) where 09:18:17,761 [INFO] [stdout] (write:71) creditcard0_.id=? 09:18:17,763 [DEBUG] [myapp.ejb.impl.persistence.hibernate.usertype.AESCipherUserType] (nullSafeGet:62) encrypted aes->hex [2B583369754364553842465A794E75764D47547647673D3D], raw/decrypted [1111222233334444] 09:18:17,764 [INFO] [stdout] (write:71) Hibernate: 09:18:17,765 [INFO] [stdout] (write:71) /* load myapp.ejb.api.persistence.entities.CustomerPreferences */ select 09:18:17,766 [INFO] [stdout] (write:71) customerpr0_.customer_id as customer1_4_0_ 09:18:17,766 [INFO] [stdout] (write:71) from 09:18:17,767 [INFO] [stdout] (write:71) O_CUSTOMER_PREFERENCES customerpr0_ 09:18:17,767 [INFO] [stdout] (write:71) where 09:18:17,768 [INFO] [stdout] (write:71) customerpr0_.customer_id=? 09:18:17,771 [INFO] [stdout] (write:71) Hibernate: 09:18:17,771 [INFO] [stdout] (write:71) /* load one-to-many myapp.ejb.api.persistence.entities.Customer.creditCards */ select 09:18:17,772 [INFO] [stdout] (write:71) creditcard0_.customer_id as customer11_2_1_, 09:18:17,772 [INFO] [stdout] (write:71) creditcard0_.id as id1_, 09:18:17,773 [INFO] [stdout] (write:71) creditcard0_.id as id1_0_, 09:18:17,773 [INFO] [stdout] (write:71) creditcard0_.card_no as card2_1_0_, 09:18:17,774 [INFO] [stdout] (write:71) creditcard0_.last_four as last3_1_0_, 09:18:17,775 [INFO] [stdout] (write:71) creditcard0_.cc_type as cc4_1_0_, 09:18:17,776 [INFO] [stdout] (write:71) creditcard0_.customer_id as customer11_1_0_, 09:18:17,777 [INFO] [stdout] (write:71) creditcard0_.cvv as cvv1_0_, 09:18:17,777 [INFO] [stdout] (write:71) creditcard0_.exp_month as exp6_1_0_, 09:18:17,778 [INFO] [stdout] (write:71) creditcard0_.exp_year as exp7_1_0_, 09:18:17,779 [INFO] [stdout] (write:71) creditcard0_.first_name as first8_1_0_, 09:18:17,780 [INFO] [stdout] (write:71) creditcard0_.last_name as last9_1_0_, 09:18:17,781 [INFO] [stdout] (write:71) creditcard0_.middle_initial as middle10_1_0_ 09:18:17,782 [INFO] [stdout] (write:71) from 09:18:17,783 [INFO] [stdout] (write:71) O_CREDIT_CARD creditcard0_ 09:18:17,784 [INFO] [stdout] (write:71) where 09:18:17,785 [INFO] [stdout] (write:71) creditcard0_.customer_id=? 09:18:17,795 [DEBUG] [myapp.ejb.api.test.CreditCardDtoRemoteTest] (testGetWithCustomer:120) ==> CreditCard: id: [3] type: [AmericanExpress] first name: [Vojo] middle init: [K] last name: [Ubiparip] card number: [1111222233334444] last four: [4444] cvv: [987] exp month: [8] exp year: [2020] customer: [@id 38] 09:18:17,797 [TRACE] [myapp.ejb.api.test.CreditCardDtoRemoteTest] (testDelete:124) deleting cc [3] 09:18:17,801 [INFO] [stdout] (write:71) Hibernate: 09:18:17,802 [INFO] [stdout] (write:71) /* load myapp.ejb.api.persistence.entities.CreditCard */ select 09:18:17,803 [INFO] [stdout] (write:71) creditcard0_.id as id1_0_, 09:18:17,804 [INFO] [stdout] (write:71) creditcard0_.card_no as card2_1_0_, 09:18:17,805 [INFO] [stdout] (write:71) creditcard0_.last_four as last3_1_0_, 09:18:17,806 [INFO] [stdout] (write:71) creditcard0_.cc_type as cc4_1_0_, 09:18:17,807 [INFO] [stdout] (write:71) creditcard0_.customer_id as customer11_1_0_, 09:18:17,807 [INFO] [stdout] (write:71) creditcard0_.cvv as cvv1_0_, 09:18:17,808 [INFO] [stdout] (write:71) creditcard0_.exp_month as exp6_1_0_, 09:18:17,809 [INFO] [stdout] (write:71) creditcard0_.exp_year as exp7_1_0_, 09:18:17,810 [INFO] [stdout] (write:71) creditcard0_.first_name as first8_1_0_, 09:18:17,811 [INFO] [stdout] (write:71) creditcard0_.last_name as last9_1_0_, 09:18:17,812 [INFO] [stdout] (write:71) creditcard0_.middle_initial as middle10_1_0_ 09:18:17,813 [INFO] [stdout] (write:71) from 09:18:17,814 [INFO] [stdout] (write:71) O_CREDIT_CARD creditcard0_ 09:18:17,815 [INFO] [stdout] (write:71) where 09:18:17,816 [INFO] [stdout] (write:71) creditcard0_.id=? 09:18:17,817 [DEBUG] [myapp.ejb.impl.persistence.hibernate.usertype.AESCipherUserType] (nullSafeGet:62) encrypted aes->hex [2B583369754364553842465A794E75764D47547647673D3D], raw/decrypted [1111222233334444] 09:18:17,820 [INFO] [stdout] (write:71) Hibernate: 09:18:17,821 [INFO] [stdout] (write:71) /* load myapp.ejb.api.persistence.entities.Customer */ select 09:18:17,821 [INFO] [stdout] (write:71) customer0_.id as id2_2_, 09:18:17,822 [INFO] [stdout] (write:71) customer0_.address_id as address7_2_2_, 09:18:17,822 [INFO] [stdout] (write:71) customer0_.discount as discount2_2_, 09:18:17,823 [INFO] [stdout] (write:71) customer0_.dob as dob2_2_, 09:18:17,824 [INFO] [stdout] (write:71) customer0_.first_name as first4_2_2_, 09:18:17,824 [INFO] [stdout] (write:71) customer0_.last_name as last5_2_2_, 09:18:17,825 [INFO] [stdout] (write:71) customer0_.mobile_phone as mobile6_2_2_, 09:18:17,826 [INFO] [stdout] (write:71) address1_.id as id0_0_, 09:18:17,826 [INFO] [stdout] (write:71) address1_.bill_to as bill2_0_0_, 09:18:17,827 [INFO] [stdout] (write:71) address1_.city as city0_0_, 09:18:17,827 [INFO] [stdout] (write:71) address1_.customer_id as customer16_0_0_, 09:18:17,828 [INFO] [stdout] (write:71) address1_.email as email0_0_, 09:18:17,829 [INFO] [stdout] (write:71) address1_.first_name as first5_0_0_, 09:18:17,830 [INFO] [stdout] (write:71) address1_.last_name as last6_0_0_, 09:18:17,830 [INFO] [stdout] (write:71) address1_.phone as phone0_0_, 09:18:17,831 [INFO] [stdout] (write:71) address1_.postal_code as postal8_0_0_, 09:18:17,832 [INFO] [stdout] (write:71) address1_.ship_to as ship9_0_0_, 09:18:17,833 [INFO] [stdout] (write:71) address1_.sold_to as sold10_0_0_, 09:18:17,834 [INFO] [stdout] (write:71) address1_.state as state0_0_, 09:18:17,835 [INFO] [stdout] (write:71) address1_.street1 as street12_0_0_, 09:18:17,835 [INFO] [stdout] (write:71) address1_.street2 as street13_0_0_, 09:18:17,836 [INFO] [stdout] (write:71) address1_.street3 as street14_0_0_, 09:18:17,836 [INFO] [stdout] (write:71) address1_.title as title0_0_, 09:18:17,837 [INFO] [stdout] (write:71) customerpr2_.customer_id as customer1_4_1_ 09:18:17,838 [INFO] [stdout] (write:71) from 09:18:17,838 [INFO] [stdout] (write:71) O_CUSTOMER customer0_ 09:18:17,839 [INFO] [stdout] (write:71) left outer join 09:18:17,839 [INFO] [stdout] (write:71) O_ADDRESS address1_ 09:18:17,840 [INFO] [stdout] (write:71) on customer0_.address_id=address1_.id 09:18:17,841 [INFO] [stdout] (write:71) left outer join 09:18:17,841 [INFO] [stdout] (write:71) O_CUSTOMER_PREFERENCES customerpr2_ 09:18:17,842 [INFO] [stdout] (write:71) on customer0_.id=customerpr2_.customer_id 09:18:17,842 [INFO] [stdout] (write:71) where 09:18:17,843 [INFO] [stdout] (write:71) customer0_.id=? 09:18:17,852 [INFO] [stdout] (write:71) Hibernate: 09:18:17,853 [INFO] [stdout] (write:71) /* delete myapp.ejb.api.persistence.entities.CreditCard */ delete 09:18:17,853 [INFO] [stdout] (write:71) from 09:18:17,854 [INFO] [stdout] (write:71) O_CREDIT_CARD 09:18:17,854 [INFO] [stdout] (write:71) where 09:18:17,855 [INFO] [stdout] (write:71) id=? 09:18:17,924 [INFO] [stdout] (write:71) Hibernate: 09:18:17,925 [INFO] [stdout] (write:71) /* load myapp.ejb.api.persistence.entities.CreditCard */ select 09:18:17,926 [INFO] [stdout] (write:71) creditcard0_.id as id1_1_, 09:18:17,927 [INFO] [stdout] (write:71) creditcard0_.card_no as card2_1_1_, 09:18:17,927 [INFO] [stdout] (write:71) creditcard0_.last_four as last3_1_1_, 09:18:17,928 [INFO] [stdout] (write:71) creditcard0_.cc_type as cc4_1_1_, 09:18:17,929 [INFO] [stdout] (write:71) creditcard0_.customer_id as customer11_1_1_, 09:18:17,929 [INFO] [stdout] (write:71) creditcard0_.cvv as cvv1_1_, 09:18:17,930 [INFO] [stdout] (write:71) creditcard0_.exp_month as exp6_1_1_, 09:18:17,930 [INFO] [stdout] (write:71) creditcard0_.exp_year as exp7_1_1_, 09:18:17,931 [INFO] [stdout] (write:71) creditcard0_.first_name as first8_1_1_, 09:18:17,932 [INFO] [stdout] (write:71) creditcard0_.last_name as last9_1_1_, 09:18:17,933 [INFO] [stdout] (write:71) creditcard0_.middle_initial as middle10_1_1_, 09:18:17,933 [INFO] [stdout] (write:71) customer1_.id as id2_0_, 09:18:17,934 [INFO] [stdout] (write:71) customer1_.address_id as address7_2_0_, 09:18:17,935 [INFO] [stdout] (write:71) customer1_.discount as discount2_0_, 09:18:17,936 [INFO] [stdout] (write:71) customer1_.dob as dob2_0_, 09:18:17,936 [INFO] [stdout] (write:71) customer1_.first_name as first4_2_0_, 09:18:17,937 [INFO] [stdout] (write:71) customer1_.last_name as last5_2_0_, 09:18:17,938 [INFO] [stdout] (write:71) customer1_.mobile_phone as mobile6_2_0_ 09:18:17,938 [INFO] [stdout] (write:71) from 09:18:17,939 [INFO] [stdout] (write:71) O_CREDIT_CARD creditcard0_ 09:18:17,940 [INFO] [stdout] (write:71) inner join 09:18:17,940 [INFO] [stdout] (write:71) O_CUSTOMER customer1_ 09:18:17,941 [INFO] [stdout] (write:71) on creditcard0_.customer_id=customer1_.id 09:18:17,941 [INFO] [stdout] (write:71) where 09:18:17,942 [INFO] [stdout] (write:71) creditcard0_.id=? 09:18:18,015 [INFO] [org.jboss.weld.deployer] (stop:89) JBAS016009: Stopping weld service for deployment myapp-test.ear 09:18:18,019 [INFO] [org.jboss.as.jpa] (stop:94) JBAS011403: Stopping Persistence Unit Service 'myapp-test.ear/myapp-ejb-test.jar#myapp' 09:18:18,049 [INFO] [org.jboss.as.server.deployment] (stop:92) JBAS015877: Stopped deployment myapp-ejb-test.jar in 58ms 09:18:18,080 [INFO] [org.jboss.as.server.deployment] (stop:92) JBAS015877: Stopped deployment myapp-test.ear in 89ms 09:18:18,094 [INFO] [org.jboss.as.repository] (removeContent:269) JBAS014901: Content removed from location /opt/jboss/jboss-as-7.1.0.Final-test/standalone/data/content/61/a0e0c5cae0fbe29061146fc9650def95b2b000/content 09:18:18,096 [INFO] [org.jboss.as.server] (execute:309) JBAS018558: Undeployed "myapp-test.ear" 2015-04-23 09:18:18,113 [INFO] org.jboss.as.arquillian.protocol.jmx.ArquillianServiceDeployer (undeploy:72) - Undeploy arquillian service: arquillian-service: 999 assets 09:18:18,123 [INFO] [org.jboss.as.server.deployment] (stop:92) JBAS015877: Stopped deployment arquillian-service in 5ms 09:18:18,135 [INFO] [org.jboss.as.repository] (removeContent:269) JBAS014901: Content removed from location /opt/jboss/jboss-as-7.1.0.Final-test/standalone/data/content/6f/be31c05a27d55565dccc0320c6940c8946c538/content 09:18:18,140 [INFO] [org.jboss.as.server] (execute:309) JBAS018558: Undeployed "arquillian-service"
In the above log line 23 reading cc does result in hibernate load with a customer join.
So my question is twofold. How does Arquillian transaction management relate to EJB transaction management. In my case I haven't declared any custom transactions so the container should wrap my EJB methods per transaction. However, if I did declare some custom stuff like REQUIRES_NEW or NEVER how would that play with Arquilian @Transactional?
And of course, what can be done to enable transaction rollback in my Arquillian test without affecting my EJB/Hibernate ?