Hi,
I've spent the whole day hunting down a sporadic problem in one of my
apps without getting any closer. The problem occurs a few times a day
in production and I was able to somehow reproduce it locally a few
times also, but without seeing a pattern that causes the problem.
The problem seems to be restricted to one single page and one single
entity. The entity represents an order, the page allows to create
orders. First, an order is created, then a customer is assigned, then
order positions are added. During that process, the order and related
EOs are saved several times.
This is all working reliably. The only thing which sometimes doesn't
work is the last step: Changing the state (Integer) from one to
another and setting a timestamp.
Attached is some stripped down logging output from three orders
created this way, where the middle one shows the problem. Some code
fragments are also in there.
It looks like somehow (and I'd really like to find out why), an order
EO is modified, but not registered in the list of updated objects in
its EC. "changesFromCommittedSnapshot" is empty when the problem
happens.
No inheritance, no background threads, concurrent request handling is
off, single instance, I was the only user and I didn't leave the page
for the whole day. Locking done via ERXEC auto-locking.
Probably not relevant: Page is in permanent cache and uses a lot of
Ajax, JGroupsSynchronizer is configured but there was no other instance.
And yes, I'm pretty certain that I don't violate the EOF commandments.
Any ideas how that could happen?
Thanks for any help,
Timo (currently a bit frustrated)
(FastOrderPage.java:261) INFO xxx.pages.backend.FastOrderPage - Approving
order 11324. Current state is 0
(Order.java:666) INFO xxx.om.Order - updating state from 0 to 1
(FastOrderPage.java:264) INFO xxx.pages.backend.FastOrderPage - EC of order
is er.extensions.eof.er...@559e58. Parent is
com.webobjects.eocontrol.eoobjectstorecoordina...@88fb82
(ERXExtensions.java:470) INFO er.transaction.adaptor.EOAdaptorDebugEnabled -
Adaptor debug on
(ERXNSLogLog4jBridge.java:46) DEBUG NSLog - === Begin Internal Transaction
(ERXNSLogLog4jBridge.java:46) DEBUG NSLog - evaluateExpression:
<com.webobjects.jdbcadaptor._FrontBasePlugIn$FrontbaseExpression: "SELECT
t0."campaign", t0."comment", t0."customerAddress1", t0."customerAddress2",
t0."customerCity", t0."customerContactName", t0."customerCountry",
t0."customerID", t0."customerName1", t0."customerName2", t0."customerNumber",
cast(t0."customerNumber" as char(16)), t0."customerZip", t0."deliverUntilDate",
t0."deliveryAddress1", t0."deliveryAddress2", t0."deliveryCity",
t0."deliveryCountry", t0."deliveryName1", t0."deliveryName2", t0."deliveryZip",
t0."guid", t0."id", t0."importedOrderNumber", t0."orderDate", t0."orderNumber",
t0."orderNumberStr", t0."priority", t0."publicComment", t0."reference",
t0."shipmentRequiresPalette", t0."state", t0."userID" FROM "T_Order" t0 WHERE
t0."orderNumber" = 11324">
(ERXNSLogLog4jBridge.java:46) DEBUG NSLog - 1 row(s) processed
(ERXNSLogLog4jBridge.java:46) DEBUG NSLog - === Commit Internal Transaction
(ERXNSLogLog4jBridge.java:46) DEBUG NSLog - === Begin Internal Transaction
(ERXNSLogLog4jBridge.java:46) DEBUG NSLog - evaluateExpression:
<com.webobjects.jdbcadaptor._FrontBasePlugIn$FrontbaseExpression: "UPDATE
"T_Order" SET "state" = 1, "orderDate" = TIMESTAMP '2009-05-29 11:22:45.900'
WHERE ("id" = 1011065 AND "state" = 0)">
(ERXNSLogLog4jBridge.java:46) DEBUG NSLog - === Commit Internal Transaction
(ERXExtensions.java:472) INFO er.transaction.adaptor.EOAdaptorDebugEnabled -
Adaptor debug off
(FastOrderPage.java:276) INFO xxx.pages.backend.FastOrderPage - Approved
order 11324. New state is 1
(FastOrderPage.java:280) INFO xxx.pages.backend.FastOrderPage - Refetched
order 11324 by orderNumber. State is 1
(FastOrderPage.java:285) INFO xxx.pages.backend.FastOrderPage - Refetched
order 11324 by globalID. State is 1
(FastOrderPage.java:261) INFO xxx.pages.backend.FastOrderPage - Approving
order 11325. Current state is 0
(Order.java:666) INFO xxx.om.Order - updating state from 0 to 1
(FastOrderPage.java:264) INFO xxx.pages.backend.FastOrderPage - EC of order
is er.extensions.eof.er...@559e58. Parent is
com.webobjects.eocontrol.eoobjectstorecoordina...@88fb82
(ERXExtensions.java:470) INFO er.transaction.adaptor.EOAdaptorDebugEnabled -
Adaptor debug on
(ERXExtensions.java:472) INFO er.transaction.adaptor.EOAdaptorDebugEnabled -
Adaptor debug off
(FastOrderPage.java:276) INFO xxx.pages.backend.FastOrderPage - Approved
order 11325. New state is 1
(FastOrderPage.java:280) INFO xxx.pages.backend.FastOrderPage - Refetched
order 11325 by orderNumber. State is 0
(FastOrderPage.java:285) INFO xxx.pages.backend.FastOrderPage - Refetched
order 11325 by globalID. State is 0
(FastOrderPage.java:261) INFO xxx.pages.backend.FastOrderPage - Approving
order 11326. Current state is 0
(Order.java:666) INFO xxx.om.Order - updating state from 0 to 1
(FastOrderPage.java:264) INFO xxx.pages.backend.FastOrderPage - EC of order
is er.extensions.eof.er...@559e58. Parent is
com.webobjects.eocontrol.eoobjectstorecoordina...@88fb82
(ERXExtensions.java:470) INFO er.transaction.adaptor.EOAdaptorDebugEnabled -
Adaptor debug on
(ERXNSLogLog4jBridge.java:46) DEBUG NSLog - === Begin Internal Transaction
(ERXNSLogLog4jBridge.java:46) DEBUG NSLog - evaluateExpression:
<com.webobjects.jdbcadaptor._FrontBasePlugIn$FrontbaseExpression: "SELECT
t0."campaign", t0."comment", t0."customerAddress1", t0."customerAddress2",
t0."customerCity", t0."customerContactName", t0."customerCountry",
t0."customerID", t0."customerName1", t0."customerName2", t0."customerNumber",
cast(t0."customerNumber" as char(16)), t0."customerZip", t0."deliverUntilDate",
t0."deliveryAddress1", t0."deliveryAddress2", t0."deliveryCity",
t0."deliveryCountry", t0."deliveryName1", t0."deliveryName2", t0."deliveryZip",
t0."guid", t0."id", t0."importedOrderNumber", t0."orderDate", t0."orderNumber",
t0."orderNumberStr", t0."priority", t0."publicComment", t0."reference",
t0."shipmentRequiresPalette", t0."state", t0."userID" FROM "T_Order" t0 WHERE
t0."orderNumber" = 11326">
(ERXNSLogLog4jBridge.java:46) DEBUG NSLog - 1 row(s) processed
(ERXNSLogLog4jBridge.java:46) DEBUG NSLog - === Commit Internal Transaction
(ERXNSLogLog4jBridge.java:46) DEBUG NSLog - === Begin Internal Transaction
(ERXNSLogLog4jBridge.java:46) DEBUG NSLog - evaluateExpression:
<com.webobjects.jdbcadaptor._FrontBasePlugIn$FrontbaseExpression: "UPDATE
"T_Order" SET "state" = 1, "orderDate" = TIMESTAMP '2009-05-29 11:35:07.953'
WHERE ("id" = 1011067 AND "state" = 0)">
(ERXNSLogLog4jBridge.java:46) DEBUG NSLog - === Commit Internal Transaction
(ERXExtensions.java:472) INFO er.transaction.adaptor.EOAdaptorDebugEnabled -
Adaptor debug off
(FastOrderPage.java:276) INFO xxx.pages.backend.FastOrderPage - Approved
order 11326. New state is 1
(FastOrderPage.java:280) INFO xxx.pages.backend.FastOrderPage - Refetched
order 11326 by orderNumber. State is 1
(FastOrderPage.java:285) INFO xxx.pages.backend.FastOrderPage - Refetched
order 11326 by globalID. State is 1
FastOrderPage:
==============
private void _approveOrder() {
log.info("Approving order " + order().orderNumber() + ". Current state
is " + order().state());
order().approve();
EOEditingContext editingContext = order().editingContext();
log.info("EC of order is " + editingContext + ". Parent is " +
editingContext.parentObjectStore());
boolean flag = ERXExtensions.adaptorLogging();
try {
ERXExtensions.setAdaptorLogging(true);
editingContext.saveChanges();
} catch (RuntimeException e) {
// maybe swallowed somewhere?
log.warn(e, e);
throw e;
} finally {
ERXExtensions.setAdaptorLogging(flag);
}
log.info("Approved order " + order().orderNumber() + ". New state is "
+ order().state());
EOEditingContext tempEC = ERXEC.newEditingContext();
Order tmp = Order.clazz.fetchRequiredOrder(tempEC,
Order.ORDER_NUMBER.is(order.orderNumber()));
log.info("Refetched order " + tmp.orderNumber() + " by orderNumber.
State is " + tmp.state());
tempEC = ERXEC.newEditingContext();
EOGlobalID globalID = editingContext.globalIDForObject(order());
tmp = (Order) tempEC.faultForGlobalID(globalID, tempEC);
log.info("Refetched order " + tmp.orderNumber() + " by globalID. State
is " + tmp.state());
}
Order:
======
public void approve() {
if (STATE_NEW.equals(state()) || STATE_IMPORTED_OPEN.equals(state())) {
setState(STATE_APPROVED);
setOrderDate(new NSTimestamp());
} else {
log.warn("Cannot approve order: State is " + state(), new
RuntimeException("DEBUG"));
}
}
@Override
public void setState(Integer value) {
if (state() != null)
log.info("updating state from " + state() + " to " + value);
super.setState(value);
}
@Override
public void validateForSave() throws ValidationException {
super.validateForSave();
ERXEOControlUtilities.validateUniquenessOf(this, Key.ORDER_NUMBER);
}
_Order:
=======
public void setState(Integer value) {
takeStoredValueForKey(value, "state");
}
public Integer orderNumber() {
return (Integer) storedValueForKey("orderNumber");
}
public Integer state() {
return (Integer) storedValueForKey("state");
}
_______________________________________________
Do not post admin requests to the list. They will be ignored.
Webobjects-dev mailing list ([email protected])
Help/Unsubscribe/Update your Subscription:
http://lists.apple.com/mailman/options/webobjects-dev/archive%40mail-archive.com
This email sent to [email protected]
