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
