Highlighted
Micro Focus Expert
Micro Focus Expert
318 views

(SM) Support Tip: Troubleshooting “The record being updated has been modified since read"

This article explains, what this error message is about, and how to analyze it with trace parameters, respective with debugging statement to print relevant information in case tracing is not possible (i.e. in production environments).

 

An update means that an existing record is updated with new values. This means, the existing record has to be selected first, and a reference to the current record to be update needs to be stored with the file variable.

In order to guarantee data integrity, SM server also is required to make sure that this record between the select and the update has not been changed by the same or another session. So the error message describes that exactly this happened:

RTE I dbUpdate: The record being updated has been modified since read

RTE I dbUpdate: file:(<dbdict>) key:(<unique key query>)

RTE D (0x09F649C0)      DBACCESS - Update       against file <dbdict> in 0.015000 seconds [rc=51] (<unique key query>)

The return code [rc=51] refers to the JavaScript constant RC_MODIFIED, which you could use to handle this issue programmatically.

 

When you trace this error in debugdbquery:999 trace, you first search for the error message, and then search upwards for the first update against this dbdict before. As string for this search just copy the string “Update       against file <your dbdict>”. Then make sure the unique key query as printed in brackets at the end of the line is identical. If not, ignore this line and search again.

Then you look at the DBACCESS lines which include the file handle information: You will see a different file handle updated the record with the same unique key.

  4536(  6716) 03/30/2016 16:33:58  RTE D (0x09F5F610)      >DBACCESS - Update       against file atest in 0.000000 seconds [rc=0 ] (id="20")

  4536(  6716) 03/30/2016 16:33:58  RTE I dbUpdate: The record being updated has been modified since read

  4536(  6716) 03/30/2016 16:33:58  RTE I dbUpdate: file:(atest) key:(id=20)

  4536(  6716) 03/30/2016 16:33:58  RTE D (0x09F649C0)      DBACCESS - Update       against file atest in 0.016000 seconds [rc=51] (id="20")

Now have a look at the start of the line, if process id and thread id of both lines are the same or not:

If not, another session interfered with this update:

This typically means that a longer operation had been performant. In most cases, the time between select and update is not required to take a long time and this is a tuning opportunity.

If quick fix is required, you can add a rtecall(“refresh”) directly before the update statement to make sure the file variable refers to the most current version.

  $L.success.flg=rtecall("refresh", $L.errcode, $L.file)

For more information, please refer to the Programming Guide.

If the same session updated the record, there is a bug in the implementation:

                Take a look at word DBACCESS in both Update lines: If there are greater-than-signs (“>”) proceeding DBACCESS, this refers to the recursive depth of trigger processing: If the interfering update line is proceeded by more greater-than-signs then of the failing update, it is likely that the interfering update is called by a trigger routine.

Typically you should activate rtm:3 tracing in order to identify the location of the select of the file variable where the update runs into error and the update of the file variable interfering.

 

In case tracing is not possible, i.e. because the issue can only be reproduced in production environment, then you can use this procedure.

1.       Add a before update trigger to the dbdict of where the record update causes the error (use a trigger name starting with “z” to have this trigger being executed as last trigger before the actual update).

 

Trigger Name: zDebug Trigger

Table Name: <dbdict name>

Trigger Type: 3 – Before Update

Script:

lib.debugUtils.logData("*** Update to atest record - Info block start ***");

 

lib.debugUtils.logData("* oldrecord: "+ system.functions.str(oldrecord));

 

lib.debugUtils.logData("*    record: "+ system.functions.str(record));

 

var JSstack = "";

try { throw Error(); } catch (ex) { JSstack = ex.stack; }

lib.debugUtils.logData("*   JSStack: "+ JSstack);

 

lib.debugUtils.logData("* current user: "+system.functions.operator());

 

lib.debugUtils.logData("*** Update to atest record - Info block end ***");

 

2.       Reproduce the issue and analyse the log file.

 

Example trace:

 

  4536(  6716) 03/30/2016 17:41:03  RAD I *** Update to atest record - Info block start ***

  4536(  6716) 03/30/2016 17:41:03  RAD I * oldrecord: atest={["24", "Test 4", , 0]}

  4536(  6716) 03/30/2016 17:41:03  RAD I *    record: atest={["24", "Test 24 Update'", true, 1]}

  4536(  6716) 03/30/2016 17:41:03  RAD I *   JSStack: Error()@:0

<internal>()@<no name>:8

doUpdate()@:0

<internal>()@<no name>:8

doInsert()@:0

<internal>()@<no name>:8

@:0

 

  4536(  6716) 03/30/2016 17:41:03  RAD I * current user: falcon

  4536(  6716) 03/30/2016 17:41:03  RAD I *** Update to atest record - Info block end ***

  4536(  6716) 03/30/2016 17:41:03  RTE D Dump of Current data

  4536(  6716) 03/30/2016 17:41:03  RTE D 0x09C368A0: 7B5B2232 34222C20 22546573 74203234 [{["24", "Test 24]

  4536(  6716) 03/30/2016 17:41:03  RTE D 0x09C368B0: 20557064 61746527 222C2074 7275652C [ Update'", true,]

  4536(  6716) 03/30/2016 17:41:03  RTE D 0x09C368C0: 20315D7D                            [ 1]}            ]

  4536(  6716) 03/30/2016 17:41:03  RTE D Dump of Saved data

  4536(  6716) 03/30/2016 17:41:03  RTE D 0x063A8A70: 7B5B2232 34222C20 22546573 74203422 [{["24", "Test 4"]

  4536(  6716) 03/30/2016 17:41:03  RTE D 0x063A8A80: 2C202C20 305D7D                     [, , 0]}         ]

  4536(  6716) 03/30/2016 17:41:03  RTE I dbUpdate: The record being updated has been modified since read

  4536(  6716) 03/30/2016 17:41:03  RTE I dbUpdate: file:(atest) key:(id=24)

 

We can see the now here that the oldrecord (at time of selection) and the record (value to be updated) of the interfering update. The failed update has the same oldrecord – while it should have the value after the interfering update – this is cause of the error message.

The JS stack is providing hints to the location of the interfering update: It may show function names, or like here show us the call flow between SM RTE and JavaScript engine by the <internal>() functions. These <internal>() functions here can be interpreted as execution of a trigger during database operation (insert/update/delete). So reading the stack trace bottom up: A trigger was executed, during this a doInsert() function – this is again a database operation and a trigger was executed, while this a doUpdate() and another trigger which is actually our debug message trigger, that called the Error() function as is required to generate the stack trace.

 

Now here the flawed implementation:

The Trigger 1 is executed before a record to dbdict atest is updated. It first guards against recursive execution and inserts a record into dbdict btest, which causes trigger being executed after add, to select and update a record in atest with the same id as our initial record (the interfering update). Finally, when then the atest record after the before trigger execution is to be updated, the selected record has already been modified.

 

Trigger 1:

Trigger name: atest

Table name: atest

Trigger type: 3 - Before Update

Script:

if (!record["recurse"])

{

   var b = new SCFile("btest");

 

   b["id"] = record["id"];

   b["contents"] = record["contents"];

 

   b.doInsert();

}

 

Trigger 2:

Trigger name: btest

Table name: btest

Trigger type: 2 - After Add

Script:

var a = new SCFile("atest");

 

var rc = a.doSelect('id="'+record["id"]+'"');

 

a["contents"] = record["contents"] + "'";

a["recurse"] = true;

 

 

rc = a.doUpdate();
Labels (1)
The opinions expressed above are the personal opinions of the authors, not of Micro Focus. By using this site, you accept the Terms of Use and Rules of Participation. Certain versions of content ("Material") accessible here may contain branding from Hewlett-Packard Company (now HP Inc.) and Hewlett Packard Enterprise Company. As of September 1, 2017, the Material is now offered by Micro Focus, a separately owned and operated company. Any reference to the HP and Hewlett Packard Enterprise/HPE marks is historical in nature, and the HP and Hewlett Packard Enterprise/HPE marks are the property of their respective owners.