webobjects-dev@wocommunity.org Mailing List Archive

Samuel,

On 16. 6. 2021, at 19:40, Samuel Pelletier <webobjects-dev@wocommunity.org> wrote:
Very strange but seems like the error when trying to trigger a fault on a temporary GID.

I might be wrong, but I don't really think so. Correct me please if I am wrong, but I believe temp GIDs are used for newly created EOs (nothing like that there). When fetching though, I understand a key GID is assigned, no temp GID needed at all.

It looks like

- either the database does not provide PK in the SELECT result set, which would be extremely weird;

- or the JDBC/EOF somehow mangles the result set and loses the PK, which would be even couriouser...

I suspect that the error has nothing to do with the previous fetch.

It seems to me that the error is caused by some kind of concurrent fetches through different OSCs. At the very least

- whenever it happened so far, logs of both fetches (the R/R one and the background one) intertwined, like at [1] below;

- if I switch the background threads altogether, so far, the problem never occurred;

- nor it happened when I switched to single OSC (which sort of makes sense: single OSC effectively serialises fetches and the concurrency disappears).

Do you move GID of non committed objects between EditingContext ?

Nope, at the moment there are no non-commited data at all. From the moment the app was launched, nothing chnaged; only fetches happened.

You may also check your connection settings, I use READ COMMITTED, this provides the best compromise for me.

I believe we do, too — read-committed plus optimistic locking.

Thanks and all the best,

Le 13 juin 2021 à 13:52, OCsite <webobjects-dev@wocommunity.org> a écrit :

Just a quick followup: I have rewritten the original code

foo=eolist.representedObject.records().isEmpty?...:...

to this ugly contraption (logging removed for clarity):

for (int n=1;n<=1000;n++) {
try {
foo=eolist.representedObject.records().isEmpty?...:...
break
} catch (exc) {
println "#$n DIDTHROW: $exc.localizedMessage"
Thread.sleep(10)
}
}

which sort-of cured the problem: when it happens, the fault gets re-fired, and sooner or later (so far at worst at the 4th attempt) it succeeds and reads the records properly.

Still I would like to know what's the culprit and how to really cure it; this is an ugly work-around at best, and besides, the same problem might happen elswhere.

Thanks and all the best,
OC

On 11. 6. 2021, at 17:08, OCsite <webobjects-dev@wocommunity.org> wrote:

P.P.S. It actually does look like the weird cancelled fetch was somehow affected by the background task; upon further investigation of the case

On 11. 6. 2021, at 15:20, OCsite <webobjects-dev@wocommunity.org> wrote:
===
15:05:48.528 DEBUG === Begin Internal Transaction //log:NSLog [WorkerThread5]
15:05:48.528 DEBUG evaluateExpression: <com.webobjects.jdbcadaptor.FrontbasePlugIn$FrontbaseExpression: "SELECT ... t0."C_UID", ... FROM "T_RECORD" t0 WHERE t0."C_IMPORT_ID" = 1003547" withBindings: > //log:NSLog [WorkerThread5]
15:05:49.937 DEBUG fetch canceled //log:NSLog [WorkerThread5]
15:05:49.937 DEBUG 164 row(s) processed //log:NSLog [WorkerThread5]
15:05:49.941 DEBUG === Commit Internal Transaction //log:NSLog [WorkerThread5]
15:05:49.941 INFO Database Exception occured: java.lang.IllegalArgumentException: Cannot determine primary key for entity DBRecord from row: {... uid = <com.webobjects.foundation.NSKeyValueCoding$Null>; ... } //log:er.transaction.adaptor.Exceptions [WorkerThread5]
===

[1] I've found that concurrently a background fetch did run, and essentially at the same time — just couple of hundreds of second later — was cancelled, too:

===
15:05:47.355 DEBUG === Begin Internal Transaction //log:NSLog [MainPageSlaveRowsCountThread_Cizí nákupy EB]
15:05:47.355 DEBUG evaluateExpression: <com.webobjects.jdbcadaptor.FrontbasePlugIn$FrontbaseExpression: "SELECT count(*) FROM "T_RECORD" t0, "T_IMPORT" T1, "T_IMPORT" T3, "T_RECORD" T2 WHERE (t0."C_OWNER__ID" is NULL AND T3."C_DATA_BLOCK_ID" = 1000387) AND t0."C_IMPORT_ID" = T1."C_UID" AND T2."C_IMPORT_ID" = T3."C_UID" AND T1."C_OWNER_RECORD_ID" = T2."C_UID"" withBindings: > //log:NSLog [MainPageSlaveRowsCountThread_Cizí nákupy EB]
15:05:49.973 DEBUG fetch canceled //log:NSLog [MainPageSlaveRowsCountThread_Cizí nákupy EB]
15:05:49.975 DEBUG 1 row(s) processed //log:NSLog [MainPageSlaveRowsCountThread_Cizí nákupy EB]
15:05:49.983 DEBUG === Commit Internal Transaction //log:NSLog [MainPageSlaveRowsCountThread_Cizí nákupy EB]
===

Note it runs over a different OSC, but still — might this be the culprit? Would EOF somehow cancel a fetch if two of them happen in the same moment, albeit both of them happen in different ECs over a different OSC?

I do not lock here, for there is absolutely no danger more threads would use the same EC concurrently (though more different background threads could use concurrently ECs over same OSC). I thought it is all right in this case. Is it not? Should I try to lock those ECs or even the OSC?

Thanks,
OC

Any idea what might go wrong and how to fix it? Thanks!
OC

On 11. 6. 2021, at 13:37, OCsite <webobjects-dev@wocommunity.org> wrote:

Hi there,

just bumped into another weird EOF case. A pretty plain fetch caused a “Cannot determine primary key for entity” exception. The row contains a number of columns whose values makes sense, some null, some non-null, with one exception — the primary key, modelled as an attribute uid, is indeed a null, thus the exception makes a perfect sense.

How can this happen?

===
IllegalArgumentException: Cannot determine primary key for entity DBRecord from row: {... uid = <com.webobjects.foundation.NSKeyValueCoding$Null>; ... }
at com.webobjects.eoaccess.EODatabaseChannel._fetchObject(EODatabaseChannel.java:348)
... skipped 2 stack elements
at com.webobjects.eocontrol.EOObjectStoreCoordinator.objectsWithFetchSpecification(EOObjectStoreCoordinator.java:488)
at com.webobjects.eocontrol.EOEditingContext.objectsWithFetchSpecification(EOEditingContext.java:4069)
at er.extensions.eof.ERXEC.objectsWithFetchSpecification(ERXEC.java:1215)
... skipped 1 stack elements
at com.webobjects.eocontrol.EOObjectStoreCoordinator.objectsForSourceGlobalID(EOObjectStoreCoordinator.java:634)
at com.webobjects.eocontrol.EOEditingContext.objectsForSourceGlobalID(EOEditingContext.java:3923)
at er.extensions.eof.ERXEC.objectsForSourceGlobalID(ERXEC.java:1178)
... skipped 1 stack elements
at com.webobjects.eoaccess.EOAccessArrayFaultHandler.completeInitializationOfObject(EOAccessArrayFaultHandler.java:77)
at com.webobjects.eocontrol._EOCheapCopyMutableArray.willRead(_EOCheapCopyMutableArray.java:45)
at com.webobjects.eocontrol._EOCheapCopyMutableArray.count(_EOCheapCopyMutableArray.java:103)
at com.webobjects.foundation.NSArray.isEmpty(NSArray.java:1888)
...
===

Just in case it happens to be important (I believe it is not), the problem happens at row

... =eolist.representedObject.records().isEmpty()?...:...

where records just returns storedValueForKey('records'), self-evidently a fault, which fires to fetch the rows.

Searching the Web, all I've found is this (linked from here), which does not really help :) Truth is, some background threads do run at the moment; they are comparatively plain though and I can't see why they should cause the problem for the R/R thread. All they do is to

1. get their own OSC from the pool, making sure they never get the same OSC normal sessions have
2. create a new ERXEC in this OSC
3. get a local instance of an object in the EC

=== this is the code of the background thread; a number of those runs:
  def store
for (def pool=ERXObjectStoreCoordinatorPool._pool();;) {
store=pool.nextObjectStore
if (store!=_sessionosc) break // there's one OSC for all sessions, stored in _sessionosc
}
  return eo.localInstanceIn(ERXEC.newEditingContext(store)).numberOfMasterRowsWithoutOwner()
===

and the method simply fetches:

===
  int numberOfMasterRowsWithoutOwner {
  def mymasterrow=EOQualifier.qualifierWithQualifierFormat("importObject.dataBlock = %@ AND recordOwner = NULL",[this] as NSA)
return ERXEOControlUtilities.objectCountWithQualifier(this.editingContext, 'DBRecord', mymasterrow)
  }
===

Most time it works properly. Occasionally — rather rarely — the problem above happens. Can you see what am I doing wrong?

Thanks a lot,
OC