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 26026922 for webobjects-dev@wocommunity.org; Tue, 15 Jun 2021 17:42:37 +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 0871818009C6; Tue, 15 Jun 2021 17:42:17 +0200 (CEST) Received: from [172.19.31.211] (unknown [46.167.220.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 C5A113000085; Tue, 15 Jun 2021 17:42:16 +0200 (CEST) Content-Type: multipart/alternative; boundary="Apple-Mail=_8A8ED321-AE0C-4A7A-B332-D346A59C479E" Mime-Version: 1.0 (Mac OS X Mail 13.4 \(3608.120.23.2.6\)) Date: Tue, 15 Jun 2021 17:42:16 +0200 Subject: old/invalid :1 relationship value, how the H. possible?!? Message-Id: <72BDD861-3584-4BF8-8990-A2E7732819B8@ocs.cz> To: OCsite X-Mailer: Apple Mail (2.3608.120.23.2.6) --Apple-Mail=_8A8ED321-AE0C-4A7A-B332-D346A59C479E Content-Transfer-Encoding: quoted-printable Content-Type: text/plain; charset=utf-8 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!=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: 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 --Apple-Mail=_8A8ED321-AE0C-4A7A-B332-D346A59C479E Content-Transfer-Encoding: quoted-printable Content-Type: text/html; charset=utf-8
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






= --Apple-Mail=_8A8ED321-AE0C-4A7A-B332-D346A59C479E--