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 26033427 for webobjects-dev@wocommunity.org; Wed, 16 Jun 2021 21:53:03 +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 42A4818002D0 for ; Wed, 16 Jun 2021 21:52:43 +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 DE3583000068 for ; Wed, 16 Jun 2021 21:52:42 +0200 (CEST) Content-Type: multipart/alternative; boundary="Apple-Mail=_CA3FC70F-8966-4355-BFB6-213641AEEF8D" 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 21:52:42 +0200 References: To: WebObjects & WOnder Development In-Reply-To: Message-Id: <8F53D2BD-E9BE-445C-AD61-799FA2B38298@ocs.cz> X-Mailer: Apple Mail (2.3654.100.0.2.22) --Apple-Mail=_CA3FC70F-8966-4355-BFB6-213641AEEF8D Content-Transfer-Encoding: quoted-printable Content-Type: text/plain; charset=utf-8 Samuel, > On 16. 6. 2021, at 19:57, Samuel Pelletier = wrote: > I never looked an the snapshot merging code. You should check it. Is it accessible somewhere? I thought this is Apple code, unlike Wonder, = alas, non-public. > I suspect that if your object contains uncommitted changes, this may = prevent updating... Far as my understanding of the documentation goes, it should not. Such = an object should - get uncommitted changes stored first - then be refaulted to get the new data from the low-level snapshot - and then get the stored uncommitted changes back. It sort of works this way indeed, far as I can say. Besides, far as I can say, there were no uncommitted changes anyway. The = object should not be in the updateObjects list at all; after the save of = [2], it was (far as I can say) never changed anyhow. > You seem to rely on EOF change propagation for time sensitive data = propagation. Indeed. It is quicker than a refault from snapshot, not speaking of a = possible DB roundtrip. And so far, I believed it is completely reliable. Either it is not, or I must be overlooking something pretty darn = important :/ > I would suggest to use a more in memory solution and use EOF to store = the data if your need is a high throughput change where everyone need to = see the latest data. Actually, I am at this moment considering to use a cache of the = =E2=80=9Cproper=E2=80=9D value which would be checked against the = current EO value; if the differ, I'll refault the EO (which still should = get its data from the snapshot without a DB roundtrip, far as I = understand). I wonder whether to write my own cache, or whether to use the snapshot = for that. Thanks and all the best, OC >> Le 16 juin 2021 =C3=A0 09:01, OCsite > a =C3=A9crit : >>=20 >> Some followup: I have analysed the R/R loops in details and found = that >>=20 >> - the user B saved changes at 11:00:25.220 >> - at this moment, there was a user A's R/R loop (which never touched = the relevant data), running from 11:00:24.570 to 11:00:25.548 >> - the next user A's R/R loop started at 11:00:38.113, read the = relevant data, did not see the changes of 11:00:25.220 >>=20 >> In other words, >> - at 11:00:25.220, user A's EC was locked; it should not merge the = changes immediately... >> - ... but, at 11:00:25.548 the user A's EC was unlocked: at this = moment the 11:00:25.220 changes should be merged into the EC... >> - ... which self-evidently did not happen, for in the next R/R loop = started at 11:00:38.113 the 11:00:25.220 changes were still not visible. >>=20 >> How could that happen? What could prevent the merge at the EC = unlock/RR loop end? >>=20 >> Thanks for any advice, >> OC >>=20 >>> On 16 Jun 2021, at 6:35, OCsite > wrote: >>>=20 >>> Matthew, >>>=20 >>> no luck this way: one instance only, and one OSC = (ERXObjectStoreCoordinatorPool.maxCoordinators=3D1). >>>=20 >>> Thanks, >>> OC >>>=20 >>>> 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 >>>>> [2] 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 --Apple-Mail=_CA3FC70F-8966-4355-BFB6-213641AEEF8D Content-Transfer-Encoding: quoted-printable Content-Type: text/html; charset=utf-8 Samuel,

On 16. 6. 2021, at 19:57, = Samuel Pelletier <webobjects-dev@wocommunity.org> wrote:
I never looked an the snapshot merging code. You should check = it.

Is it = accessible somewhere? I thought this is Apple code, unlike Wonder, alas, = non-public.

I suspect that if your = object contains uncommitted changes, this may prevent = updating...

Far = as my understanding of the documentation goes, it should not. Such an = object should
- get uncommitted changes stored = first
- then be refaulted to get the new data from the = low-level snapshot
- and then get the stored uncommitted = changes back.

It sort of works this = way indeed, far as I can say.

Besides,= far as I can say, there were no uncommitted changes anyway. The object = should not be in the updateObjects list at all; after the save of [2], = it was (far as I can say) never changed anyhow.

You seem to rely on EOF change propagation = for time sensitive data propagation.

Indeed. It is quicker than a refault from = snapshot, not speaking of a possible DB roundtrip. And so far, I = believed it is completely reliable.

Either it is not, or I must be overlooking = something pretty darn important :/

I would suggest to use a more in memory solution and use EOF = to store the data if your need is a high throughput change where = everyone need to see the latest data.

Actually, I am at this moment considering to use a = cache of the =E2=80=9Cproper=E2=80=9D value which would be checked = against the current EO value; if the differ, I'll refault the EO (which = still should get its data from the snapshot without a DB roundtrip, far = as I understand).

I wonder whether = to write my own cache, or whether to use the snapshot for = that.

Thanks and all the = best,
OC


Le 16 juin 2021 =C3=A0 09:01, OCsite <webobjects-dev@wocommunity.org> a =C3=A9crit = :

Some followup: I have = analysed the R/R loops in details and found that

- the user B saved changes at = 11:00:25.220
- at this moment, there was a user A's = R/R loop (which never touched the relevant data), running = from 11:00:24.570 to 11:00:25.548
- the = next user A's R/R loop started at 11:00:38.113, read the = relevant data, did not see the changes = of 11:00:25.220

In other words,
- at 11:00:25.220, user = A's EC was locked; it should not merge the changes = immediately...
- ... but, at 11:00:25.548 the user = A's EC was unlocked: at this moment the 11:00:25.220 changes should be = merged into the EC...
- ... which self-evidently = did not happen, for in the next R/R loop started at 11:00:38.113 = the 11:00:25.220 changes were still not visible.

How could that happen? What could = prevent the merge at the EC unlock/RR loop end?

Thanks for any advice,
OC

On 16 = Jun 2021, at 6:35, OCsite <webobjects-dev@wocommunity.org> wrote:

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}

<= /div>
<= /blockquote>
[2] 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=_CA3FC70F-8966-4355-BFB6-213641AEEF8D--