Need help understanding "Inconsistent Values in row"

Joachim Tuchel

15:31 (jetzt) 

an VA Smalltalk

I have a problem popping up in production much more often than I'd like. Unfortunately, I cannot reproduce it in any of our test environments. Users told me what they are doing, and I tried the same dozens and hundreds of times, but I don't understand what is going on.

When users commit a Transaction after some operation, they sometimes get an "Inconsistent values in field" error. Sometimes they also get a "Conflicting Values in Rows", which seems to be somewhat the same thing...?).

A few things are strange here. But let's first look at a part of the walkback:

DirectMapping>>#mapFromObject:toTarget:puttingRowsIn:

  receiver = a DirectMapping(id) arg1 = a Konto (1572965): 1791 Umsatzsteuer frühere Jahre

  arg2 = a Konto (1572965): 1791 Umsatzsteuer frühere Jahre

  arg3 = a RowMapForMementos

  temp1 = 1572965

  temp2 = 1572965

  temp3 = a DatabaseRow(KPELEMENT)

Field(KPELEMENT.id)->1572848

Field(KPELEMENT.version)->an Object Field(KPELEMENT.typ)->'KO' Field(KPELEMENT.bezeichnung)->an Object Field(KPELEMENT.kontonummer)->an Object Field(KPELEMENT.anfangssaldo)->an Object Field(KPELEMENT.abschlusssaldo)->an Object Field(KPELEMENT.euerKz)->an Object Field(KPELEMENT.cont_id)->an Object Field(KPELEMENT.rahmen_element_id)->an Object Field(KPELEMENT.wurzel_id)->an Object Field(KPELEMENT.metakonto_nr)->an Object Field(KPELEMENT.kto_orig_id)->an Object

So first thing here is: it seems most contents of the Row are "an Object" which definitely is rubbish.

But reading the code of this method and looking at the temps and args, I have at least some idea of what might be going wrong here. This is the method:

mapFromObject: anObject toTarget: target puttingRowsIn: aRowMap

    | dbValue value row |

    self canWrite ifFalse: [^self].
    value := self getValueFrom: anObject.
    value := self session realObjectFor: value ifNone: [^self].
    dbValue := self convertedDbValueOf: value.
    row := aRowMap findOrAddRowForTable: self field table withKey: target.
    row at: field put: dbValue

What I find interesting is that the row which is displayed here is not the one that the meapper was looking for. The row to be changed has the id 157296, but the row in the Walkback has the id  Field(KPELEMENT.id)->157284. So I guess the problem is that  #findOrAddRowForTable: self field table withKey: target. returns the wrong row...

There is no point in changing the contents of ID anyways, since it is the primary key of the row....

So what would a Glorp pro do to "debug" this deeper - especially given that we have no way to reproduce this problem (yet)?

Joachim

--
You received this message because you are subscribed to the Google Groups "glorp-group" group.
To unsubscribe from this group and stop receiving emails from it, send an email to [hidden email].
To view this discussion on the web visit https://groups.google.com/d/msgid/glorp-group/a47ef5c8-273f-43a1-a218-46a02ef97d73n%40googlegroups.com.

The "an Object" value in a row indicates that nothing has written a value there yet. Because nil is a valid value, we need a placeholder to indicate the absence of a value, so there's a unique (Object new) that goes there.

One debugging tool is the debugWrite attribute on a mapping. That normally does a halt, but could be modified for production to log instead. The tricky part with that is that when there's a conflict, what you often want to know is who wrote the previous value. However, in your case it seems easier, because this just seems wrong. Basically, it seems to me that this is likely to be identity/caching, a lookup problem, or a race condition. With normal logic it should never be overwriting a primary key field. Does this always happen on the id field? Of the same table?

I think what I would try is instrumenting that method. In particular, check if row has an id which is different than the target. I can't see how that would ever be valid, and see if there's additional information you could provide, e.g. print that rowmap's keys and values, or at least the keys that are the two in question and the values, if present. You could also try to put some validation logic into the logic that adds to the rowmap, where if it ever adds something but then the lookup produces a different result you could log that or cause an error.

The other thing that seems suspicious to me is if this might be inheritance-related. I notice the table name is KPELEMENT, which seems more general than an account. Maybe there's something to do with the inheritance mappings/lookup that's confusing it. If this problem is on different tables, are they always inherited?

On Thu, Oct 22, 2020 at 9:33 AM jtuchel <[hidden email]> wrote:

Joachim Tuchel

15:31 (jetzt) 

an VA Smalltalk

I have a problem popping up in production much more often than I'd like. Unfortunately, I cannot reproduce it in any of our test environments. Users told me what they are doing, and I tried the same dozens and hundreds of times, but I don't understand what is going on.

When users commit a Transaction after some operation, they sometimes get an "Inconsistent values in field" error. Sometimes they also get a "Conflicting Values in Rows", which seems to be somewhat the same thing...?).

A few things are strange here. But let's first look at a part of the walkback:

DirectMapping>>#mapFromObject:toTarget:puttingRowsIn:

  receiver = a DirectMapping(id) arg1 = a Konto (1572965): 1791 Umsatzsteuer frühere Jahre

  arg2 = a Konto (1572965): 1791 Umsatzsteuer frühere Jahre

  arg3 = a RowMapForMementos

  temp1 = 1572965

  temp2 = 1572965

  temp3 = a DatabaseRow(KPELEMENT)

Field(KPELEMENT.id)->1572848

Field(KPELEMENT.version)->an Object Field(KPELEMENT.typ)->'KO' Field(KPELEMENT.bezeichnung)->an Object Field(KPELEMENT.kontonummer)->an Object Field(KPELEMENT.anfangssaldo)->an Object Field(KPELEMENT.abschlusssaldo)->an Object Field(KPELEMENT.euerKz)->an Object Field(KPELEMENT.cont_id)->an Object Field(KPELEMENT.rahmen_element_id)->an Object Field(KPELEMENT.wurzel_id)->an Object Field(KPELEMENT.metakonto_nr)->an Object Field(KPELEMENT.kto_orig_id)->an Object

So first thing here is: it seems most contents of the Row are "an Object" which definitely is rubbish.

But reading the code of this method and looking at the temps and args, I have at least some idea of what might be going wrong here. This is the method:

mapFromObject: anObject toTarget: target puttingRowsIn: aRowMap

    | dbValue value row |

    self canWrite ifFalse: [^self].
    value := self getValueFrom: anObject.
    value := self session realObjectFor: value ifNone: [^self].
    dbValue := self convertedDbValueOf: value.
    row := aRowMap findOrAddRowForTable: self field table withKey: target.
    row at: field put: dbValue

What I find interesting is that the row which is displayed here is not the one that the meapper was looking for. The row to be changed has the id 157296, but the row in the Walkback has the id  Field(KPELEMENT.id)->157284. So I guess the problem is that  #findOrAddRowForTable: self field table withKey: target. returns the wrong row...

There is no point in changing the contents of ID anyways, since it is the primary key of the row....

So what would a Glorp pro do to "debug" this deeper - especially given that we have no way to reproduce this problem (yet)?

Joachim

--
You received this message because you are subscribed to the Google Groups "glorp-group" group.
To unsubscribe from this group and stop receiving emails from it, send an email to [hidden email].
To view this discussion on the web visit https://groups.google.com/d/msgid/glorp-group/a47ef5c8-273f-43a1-a218-46a02ef97d73n%40googlegroups.com.

HI Alan,

that was a fast response ;-)

So "an Object" either means nothing has been written yet or we hava a race condition.... I doubt the latter is the case here...

IIUC, you suggest overriding #stopIfDebuggingWrite to check whether the mapping is the one which I suspect is the problem (id of a Konto / Account's ID attribute) and make it log something. The question is: what could I log here.... I already know the RowMaps both are RowMaps for the correct table, but the object to be written has another ID than the RowMap that gets modified in #mapFromObject: anObject toTarget: target puttingRowsIn: aRowMap. Keeping the halt in order to get "full info" is not an option in a web server... ;-)

You name it: KPELEMENT or better: its mapped class is an abstract superclass of three classes that all reside in the KPELEMENT table (FilteredTypeResolver). Konto (Account) is one of them (KP stands for Kontenplan, the German word for Chart of Accounts). So you might be richt that this is a caching problem. I remember Esteban mentioned some caching problems in conjunction with inheritence here on this group...

As far as I can tell, this error (and the other one, Conflicting values in rows) always seems to occur when accounts in accounting entries are changed. It is always a commit in the very same dialog of our Application. So it is always related to the KPELEMENT table. The other classes in the KPELEMENT hierarchy cannot be assigned to bookings, they are solely account groups etc, which can hold accounts ("bill of materials" - components with subcomponents etc., but only the leaves of that tree can be assigned to bookings).

I am not yet sure what to do actually, but what is interesting is that both IDs (the one of the object and the one of the "Wrong" RowMap) are existing ones in the Database. What's funny, however, is that the RowMap contains only "an Object"'s apart from the ID. So I would guess these are not Row Maps representing a row that was actually read from the DB (there are some Not NULL attributes in the table, so there shoule be real data if that RowMap had been found in some Cache). But if some CacheManager produced a new RowMap for the ID of the object, why would it create one with a different ID than the one it was aksed for? ID is the only Primary Key Field in that table, so the lookup key for the CacheManager is only this value....

I have the feeling I should try to find out more about this inheritence / Cache thing. Do you have any suggestions how to proceed? This would be so much easier if the problem could be reproduced in a development image. A Breakpoint and two hours of my time would be enough to find out...

Joachim

 

alan.knight schrieb am Donnerstag, 22. Oktober 2020 um 16:16:25 UTC+2:

The "an Object" value in a row indicates that nothing has written a value there yet. Because nil is a valid value, we need a placeholder to indicate the absence of a value, so there's a unique (Object new) that goes there.

One debugging tool is the debugWrite attribute on a mapping. That normally does a halt, but could be modified for production to log instead. The tricky part with that is that when there's a conflict, what you often want to know is who wrote the previous value. However, in your case it seems easier, because this just seems wrong. Basically, it seems to me that this is likely to be identity/caching, a lookup problem, or a race condition. With normal logic it should never be overwriting a primary key field. Does this always happen on the id field? Of the same table?

I think what I would try is instrumenting that method. In particular, check if row has an id which is different than the target. I can't see how that would ever be valid, and see if there's additional information you could provide, e.g. print that rowmap's keys and values, or at least the keys that are the two in question and the values, if present. You could also try to put some validation logic into the logic that adds to the rowmap, where if it ever adds something but then the lookup produces a different result you could log that or cause an error.

The other thing that seems suspicious to me is if this might be inheritance-related. I notice the table name is KPELEMENT, which seems more general than an account. Maybe there's something to do with the inheritance mappings/lookup that's confusing it. If this problem is on different tables, are they always inherited?

On Thu, Oct 22, 2020 at 9:33 AM jtuchel <[hidden email]> wrote:

Joachim Tuchel

15:31 (jetzt) 

an VA Smalltalk

I have a problem popping up in production much more often than I'd like. Unfortunately, I cannot reproduce it in any of our test environments. Users told me what they are doing, and I tried the same dozens and hundreds of times, but I don't understand what is going on.

When users commit a Transaction after some operation, they sometimes get an "Inconsistent values in field" error. Sometimes they also get a "Conflicting Values in Rows", which seems to be somewhat the same thing...?).

A few things are strange here. But let's first look at a part of the walkback:

DirectMapping>>#mapFromObject:toTarget:puttingRowsIn:

  receiver = a DirectMapping(id) arg1 = a Konto (1572965): 1791 Umsatzsteuer frühere Jahre

  arg2 = a Konto (1572965): 1791 Umsatzsteuer frühere Jahre

  arg3 = a RowMapForMementos

  temp1 = 1572965

  temp2 = 1572965

  temp3 = a DatabaseRow(KPELEMENT)

Field(KPELEMENT.id)->1572848

Field(KPELEMENT.version)->an Object Field(KPELEMENT.typ)->'KO' Field(KPELEMENT.bezeichnung)->an Object Field(KPELEMENT.kontonummer)->an Object Field(KPELEMENT.anfangssaldo)->an Object Field(KPELEMENT.abschlusssaldo)->an Object Field(KPELEMENT.euerKz)->an Object Field(KPELEMENT.cont_id)->an Object Field(KPELEMENT.rahmen_element_id)->an Object Field(KPELEMENT.wurzel_id)->an Object Field(KPELEMENT.metakonto_nr)->an Object Field(KPELEMENT.kto_orig_id)->an Object

So first thing here is: it seems most contents of the Row are "an Object" which definitely is rubbish.

But reading the code of this method and looking at the temps and args, I have at least some idea of what might be going wrong here. This is the method:

mapFromObject: anObject toTarget: target puttingRowsIn: aRowMap

    | dbValue value row |

    self canWrite ifFalse: [^self].
    value := self getValueFrom: anObject.
    value := self session realObjectFor: value ifNone: [^self].
    dbValue := self convertedDbValueOf: value.
    row := aRowMap findOrAddRowForTable: self field table withKey: target.
    row at: field put: dbValue

What I find interesting is that the row which is displayed here is not the one that the meapper was looking for. The row to be changed has the id 157296, but the row in the Walkback has the id  Field(KPELEMENT.id)->157284. So I guess the problem is that  #findOrAddRowForTable: self field table withKey: target. returns the wrong row...

There is no point in changing the contents of ID anyways, since it is the primary key of the row....

So what would a Glorp pro do to "debug" this deeper - especially given that we have no way to reproduce this problem (yet)?

Joachim

--
You received this message because you are subscribed to the Google Groups "glorp-group" group.
To unsubscribe from this group and stop receiving emails from it, send an email to [hidden email].
To view this discussion on the web visit https://groups.google.com/d/msgid/glorp-group/a47ef5c8-273f-43a1-a218-46a02ef97d73n%40googlegroups.com.