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: OC <email@hidden>
- Date: Thu, 11 Dec 2014 14:37:28 +0100
Got it again today.
Since it did never happen before and now it happened twice in about a week, I guess it must _somehow_ be linked to my last changes -- the management of optimistic locking exceptions, reported by the database.
The weird thing is, they were never used, i.e., the database did not report any exception for me to manage, before the problem occurred: just like before, it is the very first exception in the log, from the moment the instance was launched nothing amiss happened before the "Unlocking thread is not locking thread" mess.
The previous R/R loops are different. On the other hand, it was again caused by/reported in a background thread which imports CSV, exactly like before -- so it seems highly probable the culprit would be _somewhere somehow_ in the concurrent access of the background thread and the main one...
On 10. 12. 2014, at 0:28, OC <email@hidden> wrote:
> Chuck,
>
> thanks again for a quick answer!
>
> On 9. 12. 2014, at 11:55, Chuck Hill <email@hidden> wrote:
>
>> 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.
>
> The latter is nigh impossible: I log out free memory each R/R loop, and it kept at 97-odd per cent all the time.
>
> The former in principle might happen, but definitely nothing at all was reported in the log.
>
> Actually the instance run for just about 20 hours and did a little enough work; the load was very light at the time. The “ FATAL Unlocking thread” exception is the very first thing amiss; before it, nothing as much as suspicious (of course, any number of grave problems might have occurred unlogged).
>
>> How modern is your Wonder version? It could be a bug in Wonder.
>
> To be frank, I don't really know whether there's an overall Wonder version somewhere, something like “WebObjects 5.4” -- all I found were versions of concrete frameworks. My ERExtensions is "6.1.2-SNAPSHOT".
>
> Far as I can recall, last time I've upgraded Wonder was the spring, or perhaps summer? Not sure. Perhaps it's time to upgrade again :)
>
>> 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.
>
> I see, thanks! I'll fix that.
>
> All the best,
> OC
>
>> ________________________________________
>> 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
_______________________________________________
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