help debugging Glorp errors

from time to time I get into troubles with INSERTs that contain NULL for not nil fields and have no idea why, because on the application side, you cannot save forms in which these particular objects are edited if the contents of the instvars #isNil.

Since I seem to be unable to reproduce my problems in a development image, I have to make the best out of log output.

And there is one interesting thing showing up in the walk backs when this happens:

 a DatabaseRow(UMSATZ)

    Field(UMSATZ.id)->1885

    Field(UMSATZ.version)->1

    Field(UMSATZ.istsoll)->1

    Field(UMSATZ.istmwst)->0

    Field(UMSATZ.betrag)->0.0

    Field(UMSATZ.konto_id)->an Object

    Field(UMSATZ.buchsatz_id)->1022

You may realize that the line Field(UMSATZ.konto_id)->an Object looks strange here. I wonder if anyone has an idea how to find out what exactly that is. 

My first idea was it could be a Proxy that cannot find the object it is looking for. But looking at Proxy>>#printOn: it seems the output should rather look like this: '{nil}' or like '{Konto}'.

An important info in this context sure is that the field is a foreign key referencing the primary key of a newly to be inserted object.

It is worth mentioning that this operation works in this very same image a few hundred or thousand times a day without any troubles, but in some cases it fails and I have the feeling this strange output is the key to understanding what is going on.

Any hint is highly appreciated.

Thanks,

Joachim

thanks a lot for your explanations. So far I understand something has gone wrong with the write order of the objects. And I understand that "an Object" tells me Glorp has no idea what to write.

Since this error only happens on the production server and I have not been able to reproduce it (yet) in a dev environment, I can not answer most of the questions you suggest here, some of which I've asked myself as well. So for example, the Konto that an Umsatz object references exists and comes from the database, and it was read in the same session. So it is a mystery for me how Glorp could not be able to find its id. But as I said, the same piece of code runs hundreds of times without any problems, and we just had one user that encountered this effect. So together with your explanations, this gives me a bit of confidence that it is safe to put this error into the unexplainable phenomena department, which exists in every project and fills up over the years. The only hope we have now is that next time this happens we see another piece of the mosaic, and we can be relatively sure the system is not broken big time.

Joachim


Am Dienstag, 15. April 2014 16:41:19 UTC+2 schrieb alan.knight:

The field with an "an Object" in it indicates that it hasn't been initialized. Because null is a valid value, we need a marker object to show that a field has no value (or in the case of an update, it might also mean that it hasn't changed.)

So what happens internally is that a relationship mapping provides a constraint that two (or more) fields have the same value. Inside the row object a field might point directly to a value, or it might point to a wrapper on a value. There's a "unification" step in which it ensures that that's true by making the fields point to the same wrapper.

When you have a konto_id that has no value, it might mean that the unification with the other row didn't happen. Or it might mean that the other object's row has no ID field in it. Which might mean a bug, but also might mean a problem with the write order. That depends on what database you're using and what sequence mechanism. If it's possible we usually use a pre-allocating sequence mechanism, so the row gets a value before it's written. On SQL Server it gets a value afterwards. But either way the Konto would need to be written before the Umsatz. So an odd ordering issue might fit with something that happens rarely. So might a race condition. Possibly so could either the Umsatz or the Konto having come from a different unit of work, or not being in a unit of work.

So interesting questions for debugging would be 

  - does the Umstaz actually have a Konto object?

  - does the Konto have an id.

  - in the row object for each, is the wrapper object for umsatz.konto_id and <a href="http://konto.id" target="_blank" onmousedown="this.href='http://www.google.com/url?q\75http%3A%2F%2Fkonto.id\46sa\75D\46sntz\0751\46usg\75AFQjCNFnR9qIkdIhcivoL-CrIW0-8CRo0g';return true;" onclick="this.href='http://www.google.com/url?q\75http%3A%2F%2Fkonto.id\46sa\75D\46sntz\0751\46usg\75AFQjCNFnR9qIkdIhcivoL-CrIW0-8CRo0g';return true;">konto.id the identical object.

  - has the Konto already been written when it's trying to write the Umsatz?

I hope that's helpful,

   Alan

On Tue Apr 15 2014 at 7:00:05 AM, jtuchel <<a href="javascript:" target="_blank" gdf-obfuscated-mailto="JdVn_D-weNsJ" onmousedown="this.href='javascript:';return true;" onclick="this.href='javascript:';return true;">jtu...@...> wrote:

Hi,

from time to time I get into troubles with INSERTs that contain NULL for not nil fields and have no idea why, because on the application side, you cannot save forms in which these particular objects are edited if the contents of the instvars #isNil.

Since I seem to be unable to reproduce my problems in a development image, I have to make the best out of log output.

And there is one interesting thing showing up in the walk backs when this happens:

 a DatabaseRow(UMSATZ)

    Field(UMSATZ.id)->1885

    Field(UMSATZ.version)->1

    Field(UMSATZ.istsoll)->1

    Field(UMSATZ.istmwst)->0

    Field(UMSATZ.betrag)->0.0

    Field(UMSATZ.konto_id)->an Object

    Field(UMSATZ.buchsatz_id)->1022

You may realize that the line Field(UMSATZ.konto_id)->an Object looks strange here. I wonder if anyone has an idea how to find out what exactly that is. 

My first idea was it could be a Proxy that cannot find the object it is looking for. But looking at Proxy>>#printOn: it seems the output should rather look like this: '{nil}' or like '{Konto}'.

An important info in this context sure is that the field is a foreign key referencing the primary key of a newly to be inserted object.

It is worth mentioning that this operation works in this very same image a few hundred or thousand times a day without any troubles, but in some cases it fails and I have the feeling this strange output is the key to understanding what is going on.

Any hint is highly appreciated.

Thanks,

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 <a href="javascript:" target="_blank" gdf-obfuscated-mailto="JdVn_D-weNsJ" onmousedown="this.href='javascript:';return true;" onclick="this.href='javascript:';return true;">glorp-group...@googlegroups.com.
To post to this group, send email to <a href="javascript:" target="_blank" gdf-obfuscated-mailto="JdVn_D-weNsJ" onmousedown="this.href='javascript:';return true;" onclick="this.href='javascript:';return true;">glorp...@....
Visit this group at <a href="http://groups.google.com/group/glorp-group" target="_blank" onmousedown="this.href='http://groups.google.com/group/glorp-group';return true;" onclick="this.href='http://groups.google.com/group/glorp-group';return true;">http://groups.google.com/group/glorp-group.
For more options, visit <a href="https://groups.google.com/d/optout" target="_blank" onmousedown="this.href='https://groups.google.com/d/optout';return true;" onclick="this.href='https://groups.google.com/d/optout';return true;">https://groups.google.com/d/optout.

believe it or not: your race condition tip was correct.

I accidentally found the cause of the problem. It turns out it has nothing to do with Glorp. 

Some Web Browsers do submit forms twice if you press Enter twice real fast. This leads to interesting effects on the server side, because Glorp tries to insert objects that don't exist. I didn't debug this deep enough to fully understand the details, but my first tests show that if I suppress re-submits for a second (by using jQuery), the problem cannot be reproduced.

Don't ask how I found out. It's one of the more expensive bugs in our system. 

If you are interested in more details: When hardcore errors with double Glorp INSERTs turn out to be ancient web problems

Joachim

  

Am Dienstag, 15. April 2014 16:41:19 UTC+2 schrieb alan.knight:

The field with an "an Object" in it indicates that it hasn't been initialized. Because null is a valid value, we need a marker object to show that a field has no value (or in the case of an update, it might also mean that it hasn't changed.)

So what happens internally is that a relationship mapping provides a constraint that two (or more) fields have the same value. Inside the row object a field might point directly to a value, or it might point to a wrapper on a value. There's a "unification" step in which it ensures that that's true by making the fields point to the same wrapper.

When you have a konto_id that has no value, it might mean that the unification with the other row didn't happen. Or it might mean that the other object's row has no ID field in it. Which might mean a bug, but also might mean a problem with the write order. That depends on what database you're using and what sequence mechanism. If it's possible we usually use a pre-allocating sequence mechanism, so the row gets a value before it's written. On SQL Server it gets a value afterwards. But either way the Konto would need to be written before the Umsatz. So an odd ordering issue might fit with something that happens rarely. So might a race condition. Possibly so could either the Umsatz or the Konto having come from a different unit of work, or not being in a unit of work.

So interesting questions for debugging would be 

  - does the Umstaz actually have a Konto object?

  - does the Konto have an id.

  - in the row object for each, is the wrapper object for umsatz.konto_id and <a href="http://konto.id" target="_blank" onmousedown="this.href='http://www.google.com/url?q\75http%3A%2F%2Fkonto.id\46sa\75D\46sntz\0751\46usg\75AFQjCNFnR9qIkdIhcivoL-CrIW0-8CRo0g';return true;" onclick="this.href='http://www.google.com/url?q\75http%3A%2F%2Fkonto.id\46sa\75D\46sntz\0751\46usg\75AFQjCNFnR9qIkdIhcivoL-CrIW0-8CRo0g';return true;">konto.id the identical object.

  - has the Konto already been written when it's trying to write the Umsatz?

I hope that's helpful,

   Alan

On Tue Apr 15 2014 at 7:00:05 AM, jtuchel <<a href="javascript:" target="_blank" gdf-obfuscated-mailto="JdVn_D-weNsJ" onmousedown="this.href='javascript:';return true;" onclick="this.href='javascript:';return true;">jtu...@...> wrote:

Hi,

from time to time I get into troubles with INSERTs that contain NULL for not nil fields and have no idea why, because on the application side, you cannot save forms in which these particular objects are edited if the contents of the instvars #isNil.

Since I seem to be unable to reproduce my problems in a development image, I have to make the best out of log output.

And there is one interesting thing showing up in the walk backs when this happens:

 a DatabaseRow(UMSATZ)

    Field(UMSATZ.id)->1885

    Field(UMSATZ.version)->1

    Field(UMSATZ.istsoll)->1

    Field(UMSATZ.istmwst)->0

    Field(UMSATZ.betrag)->0.0

    Field(UMSATZ.konto_id)->an Object

    Field(UMSATZ.buchsatz_id)->1022

You may realize that the line Field(UMSATZ.konto_id)->an Object looks strange here. I wonder if anyone has an idea how to find out what exactly that is. 

My first idea was it could be a Proxy that cannot find the object it is looking for. But looking at Proxy>>#printOn: it seems the output should rather look like this: '{nil}' or like '{Konto}'.

An important info in this context sure is that the field is a foreign key referencing the primary key of a newly to be inserted object.

It is worth mentioning that this operation works in this very same image a few hundred or thousand times a day without any troubles, but in some cases it fails and I have the feeling this strange output is the key to understanding what is going on.

Any hint is highly appreciated.

Thanks,

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 <a href="javascript:" target="_blank" gdf-obfuscated-mailto="JdVn_D-weNsJ" onmousedown="this.href='javascript:';return true;" onclick="this.href='javascript:';return true;">glorp-group...@googlegroups.com.
To post to this group, send email to <a href="javascript:" target="_blank" gdf-obfuscated-mailto="JdVn_D-weNsJ" onmousedown="this.href='javascript:';return true;" onclick="this.href='javascript:';return true;">glorp...@....
Visit this group at <a href="http://groups.google.com/group/glorp-group" target="_blank" onmousedown="this.href='http://groups.google.com/group/glorp-group';return true;" onclick="this.href='http://groups.google.com/group/glorp-group';return true;">http://groups.google.com/group/glorp-group.
For more options, visit <a href="https://groups.google.com/d/optout" target="_blank" onmousedown="this.href='https://groups.google.com/d/optout';return true;" onclick="this.href='https://groups.google.com/d/optout';return true;">https://groups.google.com/d/optout.