RE: FATAL Unlocking thread is not locking thread
RE: FATAL Unlocking thread is not locking thread
- Subject: RE: FATAL Unlocking thread is not locking thread
- From: Chuck Hill <email@hidden>
- Date: Tue, 09 Dec 2014 10:55:10 +0000
- Thread-topic: FATAL Unlocking thread is not locking thread
It sounds like some code in a previous request locked the OSC and threw without an unlock in a finally block. Or an OutOfMemory exception prevented the unlock. How modern is your Wonder version? It could be a bug in Wonder.
Unrelated, but for the sake of completeness, the calls to lock() should be before the try as if the unlock were to throw, you would not want the call to unlock() in the finally block.
Chuck
________________________________________
From: webobjects-dev-bounces+chill=email@hidden <webobjects-dev-bounces+chill=email@hidden> on behalf of OC <email@hidden>
Sent: December 8, 2014 2:20:42 PM
To: email@hidden
Subject: FATAL Unlocking thread is not locking thread
Hello there,
just today I've got (for the first time in my life, and especially for the first time with the app, whose related code -- far as I can say -- runs for months at least) this exception:
===
15:18:12.543 FATAL Unlocking thread is not locking thread: LOCKING Thread[WorkerThread4,5,main] vs UNLOCKING Thread[others.ImportCSVTask@6405587a,1,main] //log:er.extensions.eof.ERXObjectStoreCoordinator [others.ImportCSVTask@6405587a]
RuntimeException: UnlockingTrace
at er.extensions.eof.ERXObjectStoreCoordinator.unlock(ERXObjectStoreCoordinator.java:132)
at com.webobjects.eocontrol.EOEditingContext.unlockObjectStore(EOEditingContext.java:4684)
at er.extensions.eof.ERXEC.unlockObjectStore(ERXEC.java:808)
at com.webobjects.eocontrol.EOCustomObject.willReadRelationship(EOCustomObject.java:1281)
at er.extensions.eof.ERXGenericRecord.willReadRelationship(ERXGenericRecord.java:380)
at com.webobjects.eocontrol._EOMutableKnownKeyDictionary$Initializer$_LazyGenericRecordBinding.valueInObject(_EOMutableKnownKeyDictionary.java:614)
at com.webobjects.eocontrol.EOCustomObject.storedValueForKey(EOCustomObject.java:1634)
at com.webobjects.eocontrol.EOKeyValueCoding$storedValueForKey$0.call(null:Unknown)
at org.codehaus.groovy.runtime.callsite.CallSiteArray.defaultCall(CallSiteArray.java:45)
at com.webobjects.eocontrol.EOKeyValueCoding$storedValueForKey$0.call(null:Unknown)
...
at others.CSVImport$_csv_closure3.doCall(CSVImport.groovy:110)
===
Seems to be rather rare, for the only occurrence Google found was the ERXObjectStoreCoordinator source :)
Anyway, there's only one place I am locking the store, and the weird thing is, it does not seem it has been ever called? There are some logs in case of success and it's run in an exception harness and logs the exception, and neither of them was ever logged. (More to that below)
Thus it seems probable that the above happened without me explicitly locking the store. The code which did throw above locks its (private) EC -- but at the moment it threw, the EC has been unlocked long ago; the code looks like this:
===
static ERXLongResponseTask csvTask(DBDFPrototype formPrototype) {
ERXEC ec=ERXEC.newEditingContext() // peer EC to prevent deadlocks
logln "=== preparing CSV import in EC $ec ==="
try {
ec.lock()
formPrototype=formPrototype.localInstanceIn(ec)
} finally {
ec.unlock()
}
def task=new ImportCSVTask(formPrototype)
task.start() // inside the task (which never locks/unlocks anything) the exception happened
task
}
===
To be frank, I am not quite sure what to search for :/
Can anybody see a potential culprit, or at least, is there an advice what to seek for?
---------
Just for completeness' sake, the only one place where I do lock the store looks like this -- the idea is that the addPriceOffer (which computes a new offer based on values of objects in the the priceOffers relationship and then adds it to the receiver's EC) needs to be REALLY atomic through all instances -- it must be forbidden that one instance changes the priceOffers table (happens only through the addPriceOffer method) whilst another enumerates them and prepares to insert new price offer itself.
Anyway, there are the logs:
===
EOEditingContext ec=auction.editingContext()
EOObjectStore osc=ec.rootObjectStore()
ERXEC tempec=nil
try {
osc.lock()
tempec=ERXEC.newEditingContext()
tempec.fetchTimestamp=System.currentTimeMillis() // should re-fetch anything
def tempau=auction.localInstanceIn(tempec),tempusr=user.localInstanceIn(tempec)
tempec.lockObject(tempau)
tempau.priceOffers.each { tempec.lockObject(it) }
tempau.addPriceOffer(priceOffer,tempusr); // logs out "adding price offer"
tempec.saveChanges()
} catch (exc) {
tempec.revert()
PRINT_ERROR(exc,"Exception adding offer") // logs out the argument and exception both
} finally {
osc.unlock()
}
===
Neither "adding price offer" nor "Exception adding offer" occurs anywhere in the logs, so it seems this code would probably be irrelevant.
Thanks for any idea,
OC
_______________________________________________
Do not post admin requests to the list. They will be ignored.
Webobjects-dev mailing list (email@hidden)
Help/Unsubscribe/Update your Subscription:
This email sent to email@hidden
_______________________________________________
Do not post admin requests to the list. They will be ignored.
Webobjects-dev mailing list (email@hidden)
Help/Unsubscribe/Update your Subscription:
This email sent to email@hidden