X-CGP-ClamAV-Result: CLEAN X-VirusScanner: Niversoft's CGPClamav Helper v1.22.2a (ClamAV engine v0.102.2) X-Junk-Score: 0 [] X-KAS-Score: 0 [] From: "ocs@ocs.cz" Received: from smtp-beta-1.zoner.com ([217.198.120.68] verified) by post.selbstdenker.com (CommuniGate Pro SMTP 6.3.3) with ESMTPS id 25622268 for webobjects-dev@wocommunity.org; Wed, 24 Mar 2021 16:21:54 +0100 Received-SPF: none receiver=post.selbstdenker.com; client-ip=217.198.120.68; envelope-from=ocs@ocs.cz Received: from smtp.zoner.com (smtp.zoner.com [217.198.120.6]) (using TLSv1.2 with cipher ADH-AES256-GCM-SHA384 (256/256 bits)) (No client certificate requested) by smtp-beta-1.zoner.com (Postfix) with ESMTPS id EAF48180017F for ; Wed, 24 Mar 2021 16:21:32 +0100 (CET) Received: from imac.ocsluj (smtp2stechovice.cli-eurosignal.cz [77.240.99.254]) (using TLSv1.2 with cipher ECDHE-RSA-AES256-GCM-SHA384 (256/256 bits)) (No client certificate requested) (Authenticated sender: ocs@ocs.cz) by smtp.zoner.com (Postfix) with ESMTPSA id 7A5A430000C0 for ; Wed, 24 Mar 2021 16:21:32 +0100 (CET) Content-Type: multipart/alternative; boundary="Apple-Mail=_5EAEFDCB-1C86-4E94-BD44-45FE8C46B38E" Mime-Version: 1.0 (Mac OS X Mail 14.0 \(3654.60.0.2.21\)) Subject: Re: [WO-DEV] ERXObjectStoreCoordinatorSynchronizer woes Date: Wed, 24 Mar 2021 16:21:31 +0100 References: To: WebObjects & WOnder Development In-Reply-To: Message-Id: <51C26F30-3EE8-4F16-AB68-B231F3EB8AFA@ocs.cz> X-Mailer: Apple Mail (2.3654.60.0.2.21) --Apple-Mail=_5EAEFDCB-1C86-4E94-BD44-45FE8C46B38E Content-Transfer-Encoding: quoted-printable Content-Type: text/plain; charset=utf-8 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 = 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: =3D=3D=3D private static EOObjectStoreCoordinator importOSC void importTaskImpl() { if (!importOSC) importOSC=3Dnew EOObjectStoreCoordinator() ERXEC ec=3DERXEC.newEditingContext(importOSC) ... ... import code ... ... ec.saveChanges() } =3D=3D=3D Is this the proper approach? =46rom 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 = =E2=80=94 the OSCSynchronizer could not fetch an object: =3D=3D=3D 16:16:21.939 ERROR = er.extensions.eof.ERXDatabaseContextDelegate$ObjectNotAvailableException: = No cz.ocs.model.DBDFPrototype found with globalID: = //log:er.extensions.eof.ERXObjectStoreCoordinatorSynchronizer = [ERXOSCProcessChanges] ObjectNotAvailableException: No cz.ocs.model.DBDFPrototype found with = globalID: at = er.extensions.eof.ERXDatabaseContextDelegate.databaseContextFailedToFetchO= bject(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.completeInitializationOfObjec= t(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$_Generic= RecordBinding.setValueInObject(_EOMutableKnownKeyDictionary.java:579) at = com.webobjects.eocontrol.EOCustomObject.takeStoredValueForKey(EOCustomObje= ct.java:1663) at = er.extensions.eof.ERXGenericRecord.takeStoredValueForKey(ERXGenericRecord.= java:1261) at = com.webobjects.eocontrol.EOEditingContext._mergeValueForKey(EOEditingConte= xt.java:663) at = com.webobjects.eocontrol.EOEditingContext._mergeObjectWithChanges(EOEditin= gContext.java:3457) at = com.webobjects.eocontrol.EOEditingContext._processObjectStoreChanges(EOEdi= tingContext.java:3546) at er.extensions.eof.ERXEC._processObjectStoreChanges(ERXEC.java:1569) ... skipped 5 stack elements at = com.webobjects.eocontrol.EOEditingContext._sendOrEnqueueNotification(EOEdi= tingContext.java:4715) at = com.webobjects.eocontrol.EOEditingContext._objectsChangedInStore(EOEditing= Context.java:3562) at er.extensions.eof.ERXEC._objectsChangedInStore(ERXEC.java:1509) ... skipped 7 stack elements at = com.webobjects.eocontrol.EOObjectStoreCoordinator._objectsChangedInSubStor= e(EOObjectStoreCoordinator.java:693) ... skipped 7 stack elements at = er.extensions.eof.ERXObjectStoreCoordinatorSynchronizer$ProcessChangesQueu= e$UpdateSnapshotProcessor.processSnapshots(ERXObjectStoreCoordinatorSynchr= onizer.java:295) at = er.extensions.eof.ERXObjectStoreCoordinatorSynchronizer$ProcessChangesQueu= e._process(ERXObjectStoreCoordinatorSynchronizer.java:522) at = er.extensions.eof.ERXObjectStoreCoordinatorSynchronizer$ProcessChangesQueu= e.process(ERXObjectStoreCoordinatorSynchronizer.java:540) at = er.extensions.eof.ERXObjectStoreCoordinatorSynchronizer$ProcessChangesQueu= e.run(ERXObjectStoreCoordinatorSynchronizer.java:617) ... skipped 1 stack elements =3D=3D=3D The object existed all the time, was created = years ago, still exists. Probably as a consequence, again the [TERMINATE] problem detailed below = happened =E2=80=94 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. >=20 > For a long long time it worked reliably and without a glitch. >=20 > Lately, it often (though by far not each time!) happens that >=20 > (i) a save in the background task reports the following exception: >=20 > =3D=3D=3D > 04:38:38.600 ERROR java.lang.NullPointerException = //log:er.extensions.eof.ERXObjectStoreCoordinatorSynchronizer = [ERXOSCProcessChanges] > NullPointerException > at = com.webobjects.eoaccess.EOModelGroup.modelGroupForObjectStoreCoordinator(E= OModelGroup.java:795) > at = er.extensions.eof.ERXEOAccessUtilities.databaseContextForEntityNamed(ERXEO= AccessUtilities.java:1086) > at = er.extensions.eof.ERXObjectStoreCoordinatorSynchronizer$ProcessChangesQueu= e._process(ERXObjectStoreCoordinatorSynchronizer.java:509) > at = er.extensions.eof.ERXObjectStoreCoordinatorSynchronizer$ProcessChangesQueu= e.process(ERXObjectStoreCoordinatorSynchronizer.java:540) > at = er.extensions.eof.ERXObjectStoreCoordinatorSynchronizer$ProcessChangesQueu= e.run(ERXObjectStoreCoordinatorSynchronizer.java:617) > ... skipped 1 stack elements > =3D=3D=3D >=20 > (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. >=20 > =46rom 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 :/ ) >=20 > [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 >=20 > =3D=3D=3D > 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$ProcessChangesQueu= e.stop(ERXObjectStoreCoordinatorSynchronizer.java:637) > at = er.extensions.eof.ERXObjectStoreCoordinatorSynchronizer.stopRemoteSynchron= izer(ERXObjectStoreCoordinatorSynchronizer.java:132) > ... skipped 8 stack elements > at = er.extensions.appserver.ERXApplication.terminate(ERXApplication.java:2861)= > ... ... > =3D=3D=3D >=20 > Any idea what might be the culprit and how to fix it? >=20 > Thanks and all the best, > OC >=20 --Apple-Mail=_5EAEFDCB-1C86-4E94-BD44-45FE8C46B38E Content-Transfer-Encoding: quoted-printable Content-Type: text/html; charset=utf-8 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:

=3D=3D=3D
private static EOObjectStoreCoordinator = importOSC
void importTaskImpl() {
  if = (!importOSC) importOSC=3Dnew EOObjectStoreCoordinator()
  ERXEC = ec=3DERXEC.newEditingContext(importOSC)
  ... ... import code ... = ...
  = ec.saveChanges()
}
=3D=3D=3D

Is= this the proper approach? =46rom 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 =E2=80=94 the OSCSynchronizer could not = fetch an object:

=3D=3D=3D
<= div style=3D"margin: 0px; font-stretch: normal; line-height: normal; = font-family: Menlo;" class=3D"">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.databaseContextFailedToFetchO= bject(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.completeInitializationOfObjec= t(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$_Generic= RecordBinding.setValueInObject(_EOMutableKnownKeyDictionary.java:579)
  = at = com.webobjects.eocontrol.EOCustomObject.takeStoredValueForKey(EOCustomObje= ct.java:1663)
  = at = er.extensions.eof.ERXGenericRecord.takeStoredValueForKey(ERXGenericRecord.= java:1261)
  = at = com.webobjects.eocontrol.EOEditingContext._mergeValueForKey(EOEditingConte= xt.java:663)
  = at = com.webobjects.eocontrol.EOEditingContext._mergeObjectWithChanges(EOEditin= gContext.java:3457)
  = at = com.webobjects.eocontrol.EOEditingContext._processObjectStoreChanges(EOEdi= tingContext.java:3546)
  at = er.extensions.eof.ERXEC._processObjectStoreChanges(ERXEC.java:1569)=
     ... skipped 5 stack = elements
  = at = com.webobjects.eocontrol.EOEditingContext._sendOrEnqueueNotification(EOEdi= tingContext.java:4715)
  at = com.webobjects.eocontrol.EOEditingContext._objectsChangedInStore(EOEditing= Context.java:3562)
  = at = er.extensions.eof.ERXEC._objectsChangedInStore(ERXEC.java:1509)
     ... skipped 7 stack = elements
  = at = com.webobjects.eocontrol.EOObjectStoreCoordinator._objectsChangedInSubStor= e(EOObjectStoreCoordinator.java:693)
     ... skipped 7 stack = elements
  = at = er.extensions.eof.ERXObjectStoreCoordinatorSynchronizer$ProcessChangesQueu= e$UpdateSnapshotProcessor.processSnapshots(ERXObjectStoreCoordinatorSynchr= onizer.java:295)
  = at = er.extensions.eof.ERXObjectStoreCoordinatorSynchronizer$ProcessChangesQueu= e._process(ERXObjectStoreCoordinatorSynchronizer.java:522)
  at = er.extensions.eof.ERXObjectStoreCoordinatorSynchronizer$ProcessChangesQueu= e.process(ERXObjectStoreCoordinatorSynchronizer.java:540)
  at = er.extensions.eof.ERXObjectStoreCoordinatorSynchronizer$ProcessChangesQueu= e.run(ERXObjectStoreCoordinatorSynchronizer.java:617)
  ... skipped 1 stack = elements
=3D=3D=3D

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 =E2=80=94 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:

=3D=3D=3D
04:38:38.600 ERROR = java.lang.NullPointerException       = //log:er.extensions.eof.ERXObjectStoreCoordinatorSynchronizer = [ERXOSCProcessChanges]
NullPointerException
  = at = com.webobjects.eoaccess.EOModelGroup.modelGroupForObjectStoreCoordinator(E= OModelGroup.java:795)
  at = er.extensions.eof.ERXEOAccessUtilities.databaseContextForEntityNamed(ERXEO= AccessUtilities.java:1086)
  at = er.extensions.eof.ERXObjectStoreCoordinatorSynchronizer$ProcessChangesQueu= e._process(ERXObjectStoreCoordinatorSynchronizer.java:509)
  = at = er.extensions.eof.ERXObjectStoreCoordinatorSynchronizer$ProcessChangesQueu= e.process(ERXObjectStoreCoordinatorSynchronizer.java:540)
  = at = er.extensions.eof.ERXObjectStoreCoordinatorSynchronizer$ProcessChangesQueu= e.run(ERXObjectStoreCoordinatorSynchronizer.java:617)
  = ... skipped 1 stack elements
=3D=3D=3D

(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.

=46rom 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

=3D=3D=3D
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$ProcessChangesQueu= e.stop(ERXObjectStoreCoordinatorSynchronizer.java:637)
  = at = er.extensions.eof.ERXObjectStoreCoordinatorSynchronizer.stopRemoteSynchron= izer(ERXObjectStoreCoordinatorSynchronizer.java:132)
     ... skipped 8 stack = elements
  at = er.extensions.appserver.ERXApplication.terminate(ERXApplication.java:2861)=
... ...
=3D=3D=3D

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

Thanks and all the best,
OC


= --Apple-Mail=_5EAEFDCB-1C86-4E94-BD44-45FE8C46B38E--