But since you mentionned it, the test case method call that follows the updateShippedQuantities, i.e. orderCtrl.getOrderValue(order1.getId()), does require it's own transaction (because of one-to-many CMR field the Order entity bean has). That might explain why there is an ejbStore call made by the container at timestamp 20:49:18,004 and 20:52:48,547 (one for each respective test case run).
Any one suggestion on to get more debugging information, short of actually running the server under a debugger.
Thanks
Kris
You are not using pure SQL somewhere in this part? Cause if you do, this code run in another transaction than the CMP-code and thus don't see the changes of the CMP before that transaction is commited.
For me this resulted in the junit test failing, and I had to commit the usertransaction inside the junit test method for the SQL to see the changes.
BTW: Is it possible to let CMP-code and SQL-code these run in the same transaction (connection)?
--
MVH
Marius Kotsbak
Boost communications AS
On Sat, Jan 04, 2003 at 11:09:17PM -0800, Kris wrote:
Hi, any help with this one would be appreciated.
** Environment:
- Plain out-of-the-box jboss-3.0.4_tomcat-4.1.12
- Window NT, 4.0, patch-level 5
** Scenario:
- A stateless session bean method, i.e. updateShippedQuantities, loops on an entity bean method call, i.e. updateShippedQuantity, which updates one of the bean persistent attribute, i.e. OrderItem collection element.
- The session bean method needs to be run under a transaction.
- A Junit test case exercises the session method updateShippedQuantities, then verifies that the entity bean has been updated accordingly
- The unit test case fails if the session method is run under a transaction, but succeed otherwise (e.g. run with transaction type being Supports).
** Log4j data
- Two Junit test case runs, one with transaction (transaction=Required), one without (transaction=Supports).
- Log4j data were edited for readability, relevancy, comments
** Where I need help/understanding (please refer to inline the EJB method definitions, Junit test case, and log4j output)
- Why is there an SQL query at time 20:49:17,673 (the transaction based test case), and none was made at time 20:52:48,547 (test case with no transaction)? Both logs were generated following the orderCtrl.getOrderValue(order1.getId()); test case call. The only difference is the existence/non-existence of a transaction
- I'm assuming that even though the bean ejbStore method is being called (i.e. at time 20:49:04,224) this doesn't mean that the Transaction manager will actually write the bean to the DB. Right? From the Jboss documentation did I read that in an 'optimistic' transaction scenario, the transaction manager will established if the bean state has been modified between the transaction start/end, and write/don't-write the data. But then how is this 'bean-state-has-changed' being established? In my case, the bean persistent attribute being modified is a specific attribute (shippedQuantity) of OrderItem instances contained in a Collection that the bean manages. Is it possible that the transaction manager may not have detected that the bean state has changed, since the changes are 'buried' way down a collection element class attribute?
Thanks for any input/info you may have, I've been staring at this one for a couple days now, and I can only see 'stars' ;-)
Kris
++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++
++++++++++++++++++++++++++++++
OrderController session method
++++++++++++++++++++++++++++++
/**
* Sets the collection order item shipped quantity. The method is 'wrapped'
* inside a transaction, so that all the items in the <code>items</code>
* collection are updated successfully, or none is if an error occurs.
*
* @param orderId The order id to set
* @param items A collection of OrderItem instances, with an updated
* shipped quantity field
*
* @ejb.interface-method
* view-type="both"
*
* @ejb.transaction
* type="Supports" <== This one was modified to Required
*/
public void updateShippedQuantities(String orderId, Collection items){
logger.enter();
try{
OrderLocal order = orderLocalHome.findByPrimaryKey(orderId);
logger.info(">>>>>>> Running with Transaction.type=Supports <<<<<<<<<");
Iterator iter = items.iterator();
while(iter != null && iter.hasNext()){
OrderItem item = (OrderItem)iter.next();
order.updateShippedQuantity(item);
}
} finally{
logger.exit();
}
}
++++++++++++++++++++++++++++++
Order Entity bean method
++++++++++++++++++++++++++++++
/**
* Sets an order item shipped quantity. The method is 'wrapped' inside
* a transaction, so that all the items in the <code>items</code> collection
* are updated successfully, or not is if an error occurs.
*
* @param item An OrderItem instances, with an updated
* shipped quantity field
*
* @ejb.interface-method
* view-type="both"
*
* @ejb.transaction
* type="Supports"
*/
public void updateShippedQuantity(OrderItem item){
logger.enter();
try{
ArrayList items = (ArrayList)getItems();
int index = items.indexOf(item);
if(index >= 0){
OrderItem currentItem = (OrderItem)items.get(index);
currentItem.setShippedQuantity(item.getShippedQuantity());
logger.info("Set shipped quantity " +
currentItem.getShippedQuantity() +
", on item " + currentItem.getProductId());
} else{
logger.error("Order item not found " + item.getProductId());
throw new InvalidParameterException(
"Order item not found " + item.getProductId());
}
} finally{
logger.exit();
}
}
++++++++++++++++++++++++++++++
Junit test case
++++++++++++++++++++++++++++++
/**
* Test of updateShippedQuantities method, of
* class com.newmancon.tos.ejb.order.interfaces.OrderCtrl
*
* Simple succes path
*/
public void testUpdateShippedQuantities1() {
//
// ... intitialize the test case
//
// Test the OrderController controller session method of interest
orderCtrl.updateShippedQuantities(order1.getId(), orderItems1);
// Get the order value, and verify that the shipped quantities have been
// modify
OrderValue orderValue = orderCtrl.getOrderValue(order1.getId());
//
// Verify the item shipped quantities using the above orderValue.
//
}
+++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++
+
+ LOG4J output
+
+++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++
>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>
>>>>>>>>>>>>>>>> START OF JUNIT TEST CASE, RUN #1 <<<<<<<<<<<<<<<<<<<<<<
>>>>>>>>>>>>>>>> TEST RUNNING WITH A TRANSACTION <<<<<<<<<<<<<<<<<<<<<<
>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>
// Junit setup initialization
20:49:03,793 DEBUG [OrderEJB:830] {Order ejbStore}Enter
20:49:03,813 INFO [OrderEJB:831] {Order ejbStore}Storing Order 8caad38242b7acda00ef1df6be3b8e59
20:49:03,813 INFO [OrderEJB:835] {Order ejbStore}Item id 8caac3d242b7acda01f2a9daf112c5b5, shipped: 0.0
20:49:03,853 INFO [OrderEJB:835] {Order ejbStore}Item id 8caac6cb42b7acda01ee69d33ad1fd70, shipped: 0.0
20:49:03,863 DEBUG [OrderEJB:839] {Order ejbStore}Exit
20:49:03,974 DEBUG [OrderControllerEJB:427] {OrderController setSessionContext}Enter
20:49:03,984 DEBUG [OrderControllerEJB:429] {OrderController setSessionContext}Exit
20:49:04,024 DEBUG [OrderControllerEJB:120] {OrderController ejbCreate}Enter
20:49:04,024 INFO [OrderControllerEJB:128] {OrderController ejbCreate}Created com.newmancon.tos.ejb.order.ejb.OrderControllerSession@b98a06
20:49:04,054 DEBUG [OrderControllerEJB:130] {OrderController ejbCreate}Exit
// Test case method call: updateShippedQuantities
20:49:04,084 DEBUG [OrderControllerEJB:228] {OrderController updateShippedQuantities}Enter
20:49:04,104 DEBUG [findByPrimaryKey:117] {OrderController updateShippedQuantities Order}Executing SQL: SELECT pk_key FROM ORDER_TABLE WHERE pk_key=?
20:49:04,114 INFO [OrderControllerEJB:238] {}>>>>>>> Running with Transaction.type=Required <<<<<<<<<
20:49:04,144 DEBUG [OrderEJB:651] {Order updateShippedQuantity}Enter
20:49:04,154 INFO [OrderEJB:671] {Order updateShippedQuantity}Set shipped quantity 1.0, on item 8caac3d242b7acda01f2a9daf112c5b5
20:49:04,164 DEBUG [OrderEJB:683] {Order updateShippedQuantity}Exit
20:49:04,174 DEBUG [OrderEJB:651] {Order updateShippedQuantity}Enter
20:49:04,184 INFO [OrderEJB:671] {Order updateShippedQuantity}Set shipped quantity 2.0, on item 8caac6cb42b7acda01ee69d33ad1fd70
20:49:04,194 DEBUG [OrderEJB:683] {Order updateShippedQuantity}Exit
20:49:04,204 DEBUG [OrderControllerEJB:248] {}Exit
// End of updateShippedQuantities method call
// End of transaction, save changes
20:49:04,224 DEBUG [OrderEJB:830] {ejbStore}Enter
20:49:04,234 INFO [OrderEJB:831] {ejbStore}Storing Order 8caad38242b7acda00ef1df6be3b8e59
//***************************************************************************************
// OK, even if this ejbStore method is called, does it really mean the Transaction will actually write
// the data to the DB???? See the next ejbStore comment block down
//
20:49:04,244 INFO [OrderEJB:835] {ejbStore}Item id 8caac3d242b7acda01f2a9daf112c5b5, shipped: 1.0
20:49:04,254 INFO [OrderEJB:835] {ejbStore}Item id 8caac6cb42b7acda01ee69d33ad1fd70, shipped: 2.0
//***************************************************************************************
20:49:04,264 DEBUG [OrderEJB:839] {ejbStore}Exit
// Test case orderCtrl.getOrderValue(order1.getId()); method call
20:49:17,673 DEBUG [Order:117] {Order}Executing SQL: SELECT account, accountId, customer, customerId, items, provincialTaxRate, federalTaxRate, shippingInfo, orderState, creationDate FROM ORDER_TABLE WHERE (pk_key=?)
20:49:17,994 DEBUG [OrderEJB:830] {Order ejbStore}Enter
20:49:18,004 INFO [OrderEJB:831] {Order ejbStore}Storing Order 8caad38242b7acda00ef1df6be3b8e59
//***************************************************************************************
// Sure doesn't look like the last ejbStore did actually write the data to the DB (See: just last ejbStore log above).
// How come the shipped values are 0.0???
//
20:49:18,004 INFO [OrderEJB:835] {Order ejbStore}Item id 8caac3d242b7acda01f2a9daf112c5b5, shipped: 0.0
20:49:18,014 INFO [OrderEJB:835] {Order ejbStore}Item id 8caac6cb42b7acda01ee69d33ad1fd70, shipped: 0.0
//***************************************************************************************
20:49:18,024 DEBUG [OrderEJB:839] {Order ejbStore}Exit
20:49:18,064 DEBUG [OrderControllerEJB:385] {OrderController getOrderValue}Enter
20:49:18,074 DEBUG [findByPrimaryKey:117] {OrderController getOrderValue Order}Executing SQL: SELECT pk_key FROM ORDER_TABLE WHERE pk_key=?
20:49:18,094 DEBUG [Account:117] {Order Account}Executing SQL: SELECT type, description, creationDate FROM ACCOUNT WHERE (pk_key=?)
20:49:18,114 DEBUG [Customer:117] {Customer}Executing SQL: SELECT creationDate, contactinfo_id_fk FROM CUSTOMER WHERE (pk_key=?)
20:49:18,154 DEBUG [ContactInfo:117] {Customer ContactInfo}Executing SQL: SELECT familyName, givenName, telephone, email, creationDate, address_id_fk FROM CONTACTINFO WHERE (pk_key=?)
20:49:18,184 DEBUG [Customer:117] {}Executing SQL: SELECT account_id_fk FROM CUSTOMER_ACCOUNTS_ACCOUNT_CUSTOMERS WHERE (customer_id_fk=?)
20:49:18,224 DEBUG [ContactInfo:117] {ContactInfo}Executing SQL: SELECT familyName, givenName, telephone, email, creationDate, address_id_fk FROM CONTACTINFO WHERE (pk_key=?)
20:49:18,294 DEBUG [Address:117] {ContactInfo Address}Executing SQL: SELECT streetName, city, state, zip, country, creationDate FROM ADDRESS WHERE (pk_key=?)
20:49:18,314 DEBUG [OrderEJB:830] {ejbStore}Enter
20:49:18,324 INFO [OrderEJB:831] {ejbStore}Storing Order 8caad38242b7acda00ef1df6be3b8e59
20:49:18,334 INFO [OrderEJB:835] {ejbStore}Item id 8caac3d242b7acda01f2a9daf112c5b5, shipped: 0.0
20:49:18,344 INFO [OrderEJB:835] {ejbStore}Item id 8caac6cb42b7acda01ee69d33ad1fd70, shipped: 0.0
20:49:18,364 DEBUG [OrderEJB:839] {ejbStore}Exit
20:49:18,384 DEBUG [OrderControllerEJB:400] {}Exit
>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>
>>>>>>>>>>>>>>>> START OF JUNIT TEST CASE RUN #2 <<<<<<<<<<<<<<<<<<<<<<
>>>>>>>>>>>>>>>> TEST RUNNING WITHOUT TRANSACTION <<<<<<<<<<<<<<<<<<<<<<
>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>
// Junit setup initialization
20:52:03,812 INFO [OrderEJB:831] {ejbStore}Storing Order 8cae5da742b7acda01341183c7a62ea6
20:52:03,822 INFO [OrderEJB:835] {ejbStore}Item id 8cae4e1542b7acda006d06b09ded6477, shipped: 0.0
20:52:03,832 INFO [OrderEJB:835] {ejbStore}Item id 8cae50b442b7acda01346812e0b9cb88, shipped: 0.0
20:52:03,842 DEBUG [OrderEJB:839] {ejbStore}Exit
20:52:27,276 DEBUG [OrderEJB:830] {Order ejbStore}Enter
20:52:27,286 INFO [OrderEJB:831] {Order ejbStore}Storing Order 8cae5da742b7acda01341183c7a62ea6
20:52:27,316 INFO [OrderEJB:835] {Order ejbStore}Item id 8cae4e1542b7acda006d06b09ded6477, shipped: 0.0
20:52:27,326 INFO [OrderEJB:835] {Order ejbStore}Item id 8cae50b442b7acda01346812e0b9cb88, shipped: 0.0
20:52:27,336 DEBUG [OrderEJB:839] {Order ejbStore}Exit
20:52:27,396 DEBUG [OrderControllerEJB:427] {OrderController setSessionContext}Enter
20:52:27,406 DEBUG [OrderControllerEJB:429] {OrderController setSessionContext}Exit
20:52:27,426 DEBUG [OrderControllerEJB:120] {OrderController ejbCreate}Enter
20:52:27,436 INFO [OrderControllerEJB:128] {OrderController ejbCreate}Created com.newmancon.tos.ejb.order.ejb.OrderControllerSession@1756db3
20:52:27,446 DEBUG [OrderControllerEJB:130] {OrderController ejbCreate}Exit
// Test case updateShippedQuantities method call
// Begin of Transaction
20:52:27,466 DEBUG [OrderControllerEJB:228] {OrderController updateShippedQuantities}Enter
20:52:27,476 DEBUG [findByPrimaryKey:117] {OrderController updateShippedQuantities Order}Executing SQL: SELECT pk_key FROM ORDER_TABLE WHERE pk_key=?
20:52:27,496 INFO [OrderControllerEJB:238] {}>>>>>>> Running with Transaction.type=Supports <<<<<<<<<
20:52:27,526 DEBUG [OrderEJB:651] {Order updateShippedQuantity}Enter
20:52:27,536 INFO [OrderEJB:671] {Order updateShippedQuantity}Set shipped quantity 1.0, on item 8cae4e1542b7acda006d06b09ded6477
20:52:27,546 DEBUG [OrderEJB:683] {Order updateShippedQuantity}Exit
20:52:27,566 DEBUG [OrderEJB:830] {Order ejbStore}Enter
20:52:27,576 INFO [OrderEJB:831] {Order ejbStore}Storing Order 8cae5da742b7acda01341183c7a62ea6
20:52:27,596 INFO [OrderEJB:835] {Order ejbStore}Item id 8cae4e1542b7acda006d06b09ded6477, shipped: 1.0
20:52:27,606 INFO [OrderEJB:835] {Order ejbStore}Item id 8cae50b442b7acda01346812e0b9cb88, shipped: 0.0
20:52:27,636 DEBUG [OrderEJB:839] {Order ejbStore}Exit
20:52:27,646 DEBUG [OrderEJB:651] {Order updateShippedQuantity}Enter
20:52:27,656 INFO [OrderEJB:671] {Order updateShippedQuantity}Set shipped quantity 2.0, on item 8cae50b442b7acda01346812e0b9cb88
20:52:27,666 DEBUG [OrderEJB:683] {Order updateShippedQuantity}Exit
20:52:27,687 DEBUG [OrderEJB:830] {Order ejbStore}Enter
20:52:27,687 INFO [OrderEJB:831] {Order ejbStore}Storing Order 8cae5da742b7acda01341183c7a62ea6
20:52:27,717 INFO [OrderEJB:835] {Order ejbStore}Item id 8cae4e1542b7acda006d06b09ded6477, shipped: 1.0
20:52:27,727 INFO [OrderEJB:835] {Order ejbStore}Item id 8cae50b442b7acda01346812e0b9cb88, shipped: 2.0
20:52:27,737 DEBUG [OrderEJB:839] {Order ejbStore}Exit
20:52:27,747 DEBUG [OrderControllerEJB:248] {}Exit
// End of updateShippedQuantities method call
// Get orderCtrl.getOrderValue(order1.getId()); method call
//***************************************************************************************
// Why is it that there's not SQL select call here. See previous test case run log output at time 20:49:17,673.
// The only difference in code here, is that the former/previous was run under a transaction, and here the test case
// is run without a transaction.
//
//***************************************************************************************
20:52:48,547 DEBUG [OrderEJB:830] {Order ejbStore}Enter
20:52:48,547 INFO [OrderEJB:831] {Order ejbStore}Storing Order 8cae5da742b7acda01341183c7a62ea6
20:52:48,557 INFO [OrderEJB:835] {Order ejbStore}Item id 8cae4e1542b7acda006d06b09ded6477, shipped: 1.0
20:52:48,577 INFO [OrderEJB:835] {Order ejbStore}Item id 8cae50b442b7acda01346812e0b9cb88, shipped: 2.0
20:52:48,587 DEBUG [OrderEJB:839] {Order ejbStore}Exit
20:52:48,627 DEBUG [OrderControllerEJB:385] {OrderController getOrderValue}Enter
20:52:48,647 DEBUG [findByPrimaryKey:117] {OrderController getOrderValue Order}Executing SQL: SELECT pk_key FROM ORDER_TABLE WHERE pk_key=?
20:52:48,677 DEBUG [Account:117] {Order Account}Executing SQL: SELECT type, description, creationDate FROM ACCOUNT WHERE (pk_key=?)
20:52:48,717 DEBUG [Customer:117] {Customer}Executing SQL: SELECT creationDate, contactinfo_id_fk FROM CUSTOMER WHERE (pk_key=?)
20:52:48,747 DEBUG [ContactInfo:117] {Customer ContactInfo}Executing SQL: SELECT familyName, givenName, telephone, email, creationDate, address_id_fk FROM CONTACTINFO WHERE (pk_key=?)
20:52:48,787 DEBUG [Customer:117] {}Executing SQL: SELECT account_id_fk FROM CUSTOMER_ACCOUNTS_ACCOUNT_CUSTOMERS WHERE (customer_id_fk=?)
20:52:48,827 DEBUG [ContactInfo:117] {ContactInfo}Executing SQL: SELECT familyName, givenName, telephone, email, creationDate, address_id_fk FROM CONTACTINFO WHERE (pk_key=?)
20:52:48,847 DEBUG [Address:117] {ContactInfo Address}Executing SQL: SELECT streetName, city, state, zip, country, creationDate FROM ADDRESS WHERE (pk_key=?)
20:52:48,877 DEBUG [OrderEJB:830] {ejbStore}Enter
20:52:48,887 INFO [OrderEJB:831] {ejbStore}Storing Order 8cae5da742b7acda01341183c7a62ea6
20:52:48,897 INFO [OrderEJB:835] {ejbStore}Item id 8cae4e1542b7acda006d06b09ded6477, shipped: 1.0
20:52:48,917 INFO [OrderEJB:835] {ejbStore}Item id 8cae50b442b7acda01346812e0b9cb88, shipped: 2.0
20:52:48,927 DEBUG [OrderEJB:839] {ejbStore}Exit
20:52:48,967 DEBUG [OrderControllerEJB:400] {}Exit
