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: "OCsite" Received: from smtp-beta-2.zoner.com ([217.198.120.71] verified) by post.selbstdenker.com (CommuniGate Pro SMTP 6.3.3) with ESMTPS id 26030605 for webobjects-dev@wocommunity.org; Wed, 16 Jun 2021 06:35:21 +0200 Received-SPF: none receiver=post.selbstdenker.com; client-ip=217.198.120.71; 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-2.zoner.com (Postfix) with ESMTPS id 0F82218002D4 for ; Wed, 16 Jun 2021 06:35:01 +0200 (CEST) Received: from smtpclient.apple (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 9EC403000076 for ; Wed, 16 Jun 2021 06:35:00 +0200 (CEST) Content-Type: multipart/alternative; boundary="Apple-Mail=_76AA1025-8B73-40B7-B4DA-9B53C674B45B" Mime-Version: 1.0 (Mac OS X Mail 14.0 \(3654.100.0.2.22\)) Subject: Re: [WO-DEV] old/invalid :1 relationship value, how the H. possible?!? Date: Wed, 16 Jun 2021 06:35:00 +0200 References: To: WebObjects & WOnder Development In-Reply-To: Message-Id: X-Mailer: Apple Mail (2.3654.100.0.2.22) --Apple-Mail=_76AA1025-8B73-40B7-B4DA-9B53C674B45B Content-Transfer-Encoding: quoted-printable Content-Type: text/plain; charset=utf-8 Matthew, no luck this way: one instance only, and one OSC = (ERXObjectStoreCoordinatorPool.maxCoordinators=3D1). Thanks, OC > On 16. 6. 2021, at 2:57, Matthew Ness = wrote: >=20 >=20 > On Wed, Jun 16, 2021, at 1:42 AM, OCsite wrote: >> Hi there, >>=20 >> today we have bumped into a weird behaviour which I can't grok. We = got an old/invalid value for a :1 relationship to an important object = (important enough we even added its FK to the modelled locked attributes = aside of the PK; not that it helped any, but thanks to that, we see the = current snapshot values in the database operations). >>=20 >> 1. user A stored new object into the relationship; since we log all = database operations, we can see for his EC how this happened: >>=20 >> 11:00:12.995 UPDATE on 'DBAuction' ((uid =3D 1005602) and = (lastValidPriceOfferID =3D 1061694)) -> {lastValidPriceOfferID:1061695} >>=20 >> The saveChanges operation did not fail and the appropriate R/R loop = did end without a glitch, no exception, no problem at all, at = 11:00:13.036. >>=20 >> 2. user B changed the object; again, we can see for his EC >>=20 >> 11:00:25.220 UPDATE on 'DBAuction' ((uid =3D 1005602) and = (lastValidPriceOfferID =3D 1061695)) -> {lastValidPriceOfferID:1061698} >>=20 >> The saveChanges operation again finished successfully and the = appropriate R/R loop did end all right at 11:00:25.424. >>=20 >> 3. in a new R/R loop which started at 11:00:40.947, user A read the = value (the very standard way through = storedValueForKey('lastValidPriceOffer') =E2=80=94 which is the one we = observe all the time, modelled as a simple :1 relationship with FK = lastValidPriceOfferID) =E2=80=94, and got the stale object PK:1061695!=20= >>=20 >> How is it possible that the step 2 did not update values in user A's = EC? Incidentally, to make extra sure we do not get stale values even if = R/R threads happen to overlap, the code uses in the step 3 looks like = this: >>=20 >> synchronized (alock) { // lock for the DBAuction 1005602 object = (conceptually on PK to lock out all users regardless their ECs) >> try { >> auction.editingContext().unlock() // so as to process = recent changes from other ECs (thanks, Chuck!) >> auction.editingContext().lock() // of course we have to = keep it locked >> DBPriceOffer wins=3Dauction.lastValidPriceOffer() // = simply calls storedValueForKey('lastValidPriceOffer') >> println "... last valid $wins" >>=20 >> and this very log shows we have got the old price offer, the one with = PK:1061695. >>=20 >> I could understand this if user A changed the object to 1061695 and = did not save it (in which case the EC sync would not touch the change; = but then it would be all right, if the change was not saved), but he = very definitely did save the 1061695 successfully in step 1, and never = changed it later (until he got it again =E2=80=94 the old/invalid value! = =E2=80=94 in step 3). >>=20 >> Can anyone see a scenario which would lead to him seeing still = 1061695 in step 3, regardless that >> - he did save it successfully at 11:00:12 and never changed it later; >> - another user did change it to 1061698 and successfully did save at = 11:00:25; >> - aside of the extra lock/unlock shown above, there is no manual EC = locking, ECs are auto-locked at R/Rs; >> - and besides, even if the extra lock/unlock was not used, the R/R = threads here did not overlap, so the change should be synced all right, = and the user should get 1061698 in the step 3? >>=20 >> What do I overlook? >>=20 >> Thanks and all the best, >> OC >>=20 >=20 > Hi, >=20 > How many instances of the application aretypically running? >=20 > Regards, >=20 > --=20 > Matt > https://logicsquad.net > https://www.linkedin.com/company/logic-squad/ = >=20 >=20 --Apple-Mail=_76AA1025-8B73-40B7-B4DA-9B53C674B45B Content-Transfer-Encoding: quoted-printable Content-Type: text/html; charset=utf-8 Matthew,

no= luck this way: one instance only, and one OSC (ERXObjectStoreCoordinatorPool.maxCoordinators=3D1).

Thanks,
OC

On 16. 6. 2021, at 2:57, Matthew Ness <webobjects-dev@wocommunity.org> wrote:


On Wed, = Jun 16, 2021, at 1:42 AM, OCsite wrote:
Hi there,

today we have = bumped into a weird behaviour which I can't grok. We got an old/invalid = value for a :1 relationship to an important object (important enough we = even added its FK to the modelled locked attributes aside of the PK; not = that it helped any, but thanks to that, we see the current snapshot = values in the database operations).

1. user A stored = new object into the relationship; since we log all database operations, = we can see for his EC how this happened:

11:00:12.995 UPDATE on 'DBAuction' ((uid = =3D 1005602) and (lastValidPriceOfferID =3D 1061694)) -> = {lastValidPriceOfferID:1061695}

The saveChanges operation did not = fail and the appropriate R/R loop did end without a glitch, no = exception, no problem at all, at 11:00:13.036.

2. user B changed the object; again, we can see for his = EC

11:00:25.220 = UPDATE on 'DBAuction' ((uid =3D 1005602) and = (lastValidPriceOfferID =3D 1061695)) -> = {lastValidPriceOfferID:1061698}

The saveChanges = operation again finished successfully and the appropriate R/R loop did = end all right at 11:00:25.424.

3. in a new R/R = loop which started at 11:00:40.947, user A read the value (the very = standard way through storedValueForKey('lastValidPriceOffer') =E2=80=94 = which is the one we observe all the time, modelled as a simple :1 = relationship with FK lastValidPriceOfferID) =E2=80=94= , and got the stale object PK:1061695! 

How is it possible that the step 2 did not update values = in user A's EC? Incidentally, to make extra sure we do not get stale = values even if R/R threads happen to overlap, the code uses in the step = 3 looks like this:

    synchronized (alock) = { // lock for the = DBAuction 1005602 object (conceptually on PK to lock out all users = regardless their ECs)
  =       try {
        =     auction.editingContext().unlock() // so as to process recent changes from other ECs (thanks, = Chuck!)
        =     auction.editingContext().lock()   // of course we have to keep it = locked
    =         DBPriceOffer = wins=3Dauction.lastValidPriceOffer() // simply = calls storedValueForKey('lastValidPriceOffer')
            println = "... last valid $wins"

and this very log = shows we have got the old price offer, the one with PK:1061695.

I could understand this if user A changed the object to = 1061695 and did not save it (in which case the = EC sync would not touch the change; but then it would be all right, if = the change was not saved), but he very definitely did save = the 1061695 successfully in step 1, and never changed it later = (until he got it again =E2=80=94 the old/invalid value! =E2=80=94 in = step 3).

Can anyone see a scenario which would lead to him seeing = still 1061695 in step 3, regardless that
- he did save it successfully at 11:00:12 and never = changed it later;
- another user = did change it to 1061698 and successfully did save = at 11:00:25;
- aside of the = extra lock/unlock shown above, there is no manual EC locking, ECs are = auto-locked at R/Rs;
- and = besides, even if the extra lock/unlock was not used, the R/R = threads here did not overlap, so the change should be synced all right, and the user should get 1061698 in the step 3?

What do I overlook?

Thanks and all the = best,
OC


Hi,

How = many instances of the application aretypically running?

Regards,

-- 
Matt
https://logicsquad.net
https://www.linkedin.com/company/logic-squad/



= --Apple-Mail=_76AA1025-8B73-40B7-B4DA-9B53C674B45B--