On 24 Mar 2021, at 16:21, ocs@ocs.cz <webobjects-dev@wocommunity.org> wrote:

Hi there,

some followup to the problem quoted below. Eventually, I've found the order of jars on classpath does not seem to be the culprit; the problem seem to be caused by...

On 21. 3. 2021, at 5:01 AM, OCsite <webobjects-dev@wocommunity.org> wrote:

occasionally (not too often), we are running a background import task, which uses its own EO stack: at launch, it creates a new EOObjectStoreCoordinator (and for it it creates an ERXEC and uses it to import data). When done and saved, the coordinator is disposed and released.

... this. It looks like the dispose might happen at the same moment the ERXObjectStoreCoordinatorSynchronizer$ProcessChangesQueue.run is performed in another thread, and this did cause the exceptions.

Now I am caching and reusing the coordinator, like this:

===

private static EOObjectStoreCoordinator importOSC

void importTaskImpl() {

  if (!importOSC) importOSC=new EOObjectStoreCoordinator()

  ERXEC ec=ERXEC.newEditingContext(importOSC)

  ... ... import code ... ...

  ec.saveChanges()

}

===

Is this the proper approach? From the moment we started using the code above, the NPE never occurred; on the other hand, we got once (and only once so far, all attempts to repeat it failed) a very strange exception — the OSCSynchronizer could not fetch an object:

===

16:16:21.939 ERROR er.extensions.eof.ERXDatabaseContextDelegate$ObjectNotAvailableException: No cz.ocs.model.DBDFPrototype found with globalID: <DBDFPrototype: [uid: '1000028'] >       //log:er.extensions.eof.ERXObjectStoreCoordinatorSynchronizer [ERXOSCProcessChanges]

ObjectNotAvailableException: No cz.ocs.model.DBDFPrototype found with globalID: <DBDFPrototype: [uid: '1000028'] >

  at er.extensions.eof.ERXDatabaseContextDelegate.databaseContextFailedToFetchObject(ERXDatabaseContextDelegate.java:346)

     ... skipped 5 stack elements

  at com.webobjects.foundation._NSDelegate._perform(_NSDelegate.java:223)

  at com.webobjects.foundation._NSDelegate.perform(_NSDelegate.java:167)

     ... skipped 1 stack elements

  at com.webobjects.eoaccess.EOAccessFaultHandler.completeInitializationOfObject(EOAccessFaultHandler.java:89)

  at com.webobjects.eocontrol.EOCustomObject.willRead(EOCustomObject.java:1172)

  at com.webobjects.eocontrol.EOCustomObject.willChange(EOCustomObject.java:332)

  at com.webobjects.eocontrol._EOMutableKnownKeyDictionary$Initializer$_GenericRecordBinding.setValueInObject(_EOMutableKnownKeyDictionary.java:579)

  at com.webobjects.eocontrol.EOCustomObject.takeStoredValueForKey(EOCustomObject.java:1663)

  at er.extensions.eof.ERXGenericRecord.takeStoredValueForKey(ERXGenericRecord.java:1261)

  at com.webobjects.eocontrol.EOEditingContext._mergeValueForKey(EOEditingContext.java:663)

  at com.webobjects.eocontrol.EOEditingContext._mergeObjectWithChanges(EOEditingContext.java:3457)

  at com.webobjects.eocontrol.EOEditingContext._processObjectStoreChanges(EOEditingContext.java:3546)

  at er.extensions.eof.ERXEC._processObjectStoreChanges(ERXEC.java:1569)

     ... skipped 5 stack elements

  at com.webobjects.eocontrol.EOEditingContext._sendOrEnqueueNotification(EOEditingContext.java:4715)

  at com.webobjects.eocontrol.EOEditingContext._objectsChangedInStore(EOEditingContext.java:3562)

  at er.extensions.eof.ERXEC._objectsChangedInStore(ERXEC.java:1509)

     ... skipped 7 stack elements

  at com.webobjects.eocontrol.EOObjectStoreCoordinator._objectsChangedInSubStore(EOObjectStoreCoordinator.java:693)

     ... skipped 7 stack elements

  at er.extensions.eof.ERXObjectStoreCoordinatorSynchronizer$ProcessChangesQueue$UpdateSnapshotProcessor.processSnapshots(ERXObjectStoreCoordinatorSynchronizer.java:295)

  at er.extensions.eof.ERXObjectStoreCoordinatorSynchronizer$ProcessChangesQueue._process(ERXObjectStoreCoordinatorSynchronizer.java:522)

  at er.extensions.eof.ERXObjectStoreCoordinatorSynchronizer$ProcessChangesQueue.process(ERXObjectStoreCoordinatorSynchronizer.java:540)

  at er.extensions.eof.ERXObjectStoreCoordinatorSynchronizer$ProcessChangesQueue.run(ERXObjectStoreCoordinatorSynchronizer.java:617)

  ... skipped 1 stack elements

===

The <DBDFPrototype:1000028> object existed all the time, was created years ago, still exists.

Probably as a consequence, again the [TERMINATE] problem detailed below happened — it sort of looks like any exception in OSCSynchronizer causes it eventually.

I wonder if somebody has any idea what might have caused the ObjectNotAvailableException exception?

Thanks and all the best,

OC

Original problem:

The rationale is that the imported data might be big and we don't want to limit normal workers processing to wait until the import saves its results into the database.

For a long long time it worked reliably and without a glitch.

Lately, it often (though by far not each time!) happens that

(i) a save in the background task reports the following exception:

===

04:38:38.600 ERROR java.lang.NullPointerException       //log:er.extensions.eof.ERXObjectStoreCoordinatorSynchronizer [ERXOSCProcessChanges]

NullPointerException

  at com.webobjects.eoaccess.EOModelGroup.modelGroupForObjectStoreCoordinator(EOModelGroup.java:795)

  at er.extensions.eof.ERXEOAccessUtilities.databaseContextForEntityNamed(ERXEOAccessUtilities.java:1086)

  at er.extensions.eof.ERXObjectStoreCoordinatorSynchronizer$ProcessChangesQueue._process(ERXObjectStoreCoordinatorSynchronizer.java:509)

  at er.extensions.eof.ERXObjectStoreCoordinatorSynchronizer$ProcessChangesQueue.process(ERXObjectStoreCoordinatorSynchronizer.java:540)

  at er.extensions.eof.ERXObjectStoreCoordinatorSynchronizer$ProcessChangesQueue.run(ERXObjectStoreCoordinatorSynchronizer.java:617)

  ... skipped 1 stack elements

===

(ii) after that, usually no more exceptions are reported, but the ERXObjectStoreCoordinatorSynchronizer does not seem to work properly anymore, and it often happens that the changes done in the background task are not visible in the main OSC for awhile.

From the user's perspective it usually means that the import is finished, but the imported data is not visible for a long long time (does not seem to be just a fetchTimestampLag, for newly logged-in users with their new sessions and new ECs still don't see the imported data for awhile. Frankly, I can't see what the H. might be the culprit :/ )

[TERMINATE] (iii) another problem which seems to be also caused (perhaps indirectly) by the above exception is that the application cannot be normally quit from JavaMonitor, reporting upon an attempt

===

04:33:43.441 ERROR Exception caught: null

... ...

IllegalStateException: Attempted to stop the ProcessChangesQueue when it wasn't already running

  at er.extensions.eof.ERXObjectStoreCoordinatorSynchronizer$ProcessChangesQueue.stop(ERXObjectStoreCoordinatorSynchronizer.java:637)

  at er.extensions.eof.ERXObjectStoreCoordinatorSynchronizer.stopRemoteSynchronizer(ERXObjectStoreCoordinatorSynchronizer.java:132)

     ... skipped 8 stack elements

  at er.extensions.appserver.ERXApplication.terminate(ERXApplication.java:2861)

... ...

===

Any idea what might be the culprit and how to fix it?

Thanks and all the best,

OC