Record Modification in Transaction Leads to Loading Issues and Errors

Question

Record Modification in Transaction Leads to Loading Issues and Errors

mikhalov opened this issue 4 months ago · 18 comments

OrientDB Version: 3.2.31

Java Version: corretto-20.0.2.1

OS: Windows 11

Problem:

When a record is modified and saved within a transaction, and in a subsequent query, filtering is performed on that record by a field, for example:

SELECT expand(out('SomeEdge')[status = 'ACTIVE']) FROM :p_entity

In the code ODocument.getProperty(field), the ODocument is in the NOT_LOADED status. Therefore, we fall into com.orientechnologies.orient.core.tx.OTransactionOptimistic#reloadRecord(com.orientechnologies.orient.core.id.ORID, com.orientechnologies.orient.core.record.ORecord, java.lang.String, boolean, boolean) where, on the comparison passedRecord != null && txRecord != passedRecord, we have txRecord loaded from the transaction and lazy loaded passedRecord. Consequently, we receive a warning in the database console:
Found record in transaction with the same RID #4190:930 but different instance. Probably the record has been loaded from another transaction and reused on the current one: reload it from current transaction before to update or delete it [OTransactionOptimisticServer]
Additionally, sometimes this warning correlates with an error in our application:
com.orientechnologies.orient.core.exception.ORecordNotFoundException: The record with id '#4190:930' was not found

Additional Context:

The record that generates the warning is retrieved from the edge out('SomeEdge').

Steps to Reproduce:

Modify and save a record within a transaction.
Perform a query on this record with a filter on a field within the same transaction.
Observe the status of the ODocument and the subsequent operations leading to the warning and potential error.

Expected Behavior:

The record should be properly loaded without causing warnings or errors in the transaction.

Actual Behavior:

Warnings and errors are generated due to the record being in NOT_LOADED status and issues with transaction handling.

Here is the stack trace at the point where we get the warning

reloadRecord:329, OTransactionOptimistic (com.orientechnologies.orient.core.tx)
reload:782, ODatabaseDocumentAbstract (com.orientechnologies.orient.core.db.document)
reload:80, ODatabaseDocumentAbstract (com.orientechnologies.orient.core.db.document)
reload:272, ORecordAbstract (com.orientechnologies.orient.core.record)
reload:261, ORecordAbstract (com.orientechnologies.orient.core.record)
reload:1249, ODocument (com.orientechnologies.orient.core.record.impl)
reload:120, ODocument (com.orientechnologies.orient.core.record.impl)
checkForLoading:485, ORecordAbstract (com.orientechnologies.orient.core.record)
getProperty:407, ODocument (com.orientechnologies.orient.core.record.impl)
execute:90, OSuffixIdentifier (com.orientechnologies.orient.core.sql.parser)
execute:63, OBaseIdentifier (com.orientechnologies.orient.core.sql.parser)
execute:107, OBaseExpression (com.orientechnologies.orient.core.sql.parser)
execute:60, OExpression (com.orientechnologies.orient.core.sql.parser)
evaluate:37, OBinaryCondition (com.orientechnologies.orient.core.sql.parser)
evaluate:32, ONotBlock (com.orientechnologies.orient.core.sql.parser)
evaluate:33, OAndBlock (com.orientechnologies.orient.core.sql.parser)
evaluate:35, OOrBlock (com.orientechnologies.orient.core.sql.parser)
evaluate:60, OOrBlock (com.orientechnologies.orient.core.sql.parser)
filterByCondition:172, OModifier (com.orientechnologies.orient.core.sql.parser)
execute:137, OModifier (com.orientechnologies.orient.core.sql.parser)
execute:133, OBaseExpression (com.orientechnologies.orient.core.sql.parser)
execute:102, OExpression (com.orientechnologies.orient.core.sql.parser)
execute:177, OProjectionItem (com.orientechnologies.orient.core.sql.parser)
calculateSingle:167, OProjection (com.orientechnologies.orient.core.sql.parser)
calculateProjections:41, ProjectionCalculationStep (com.orientechnologies.orient.core.sql.executor)
mapResult:33, ProjectionCalculationStep (com.orientechnologies.orient.core.sql.executor)
lambda$syncPull$0:27, ProjectionCalculationStep (com.orientechnologies.orient.core.sql.executor)
map:-1, ProjectionCalculationStep$$Lambda/0x000001d1c32ad048 (com.orientechnologies.orient.core.sql.executor)
next:28, OResultSetMapper (com.orientechnologies.orient.core.sql.executor.resultset)
fetchNext:114, ExpandStep (com.orientechnologies.orient.core.sql.executor)
access$100:18, ExpandStep (com.orientechnologies.orient.core.sql.executor)
hasNext:40, ExpandStep$1 (com.orientechnologies.orient.core.sql.executor)
hasNext:24, OLimitedResultSet (com.orientechnologies.orient.core.sql.executor.resultset)
fetchNext:37, OLocalResultSet (com.orientechnologies.orient.core.sql.parser)
<init>:27, OLocalResultSet (com.orientechnologies.orient.core.sql.parser)
execute:377, OSelectStatement (com.orientechnologies.orient.core.sql.parser)
execute:85, OStatement (com.orientechnologies.orient.core.sql.parser)
query:614, ODatabaseDocumentEmbedded (com.orientechnologies.orient.core.db.document)
executeQuery:1326, OConnectionBinaryExecutor (com.orientechnologies.orient.server)
execute:143, OQueryRequest (com.orientechnologies.orient.client.remote.message)
sessionRequest:354, ONetworkProtocolBinary (com.orientechnologies.orient.server.network.protocol.binary)
execute:238, ONetworkProtocolBinary (com.orientechnologies.orient.server.network.protocol.binary)
run:68, OSoftThread (com.orientechnologies.common.thread)

Answer 1 · 2024-07-08T12:53:44.000Z

Hi,

How are you obtaining the instance of the record that you are modifying ?

The warning means that there are two instances of ODocument that have two different state for the record in the current context, this often happen if the instance of the ODocument is created by hand assigning the id, and than saved.

So do you have an example of the logic of load + modify + save of the record?

Regards

Answer 2 · 2024-07-08T13:40:36.000Z

The record already exists at the moment of the transaction. I retrieve it from another vertex (in code) through an edge, modify its status, and then in another query within the same transaction, I retrieve a field of this record using a query like this:

SELECT expand(out('SomeEdge')[status = 'ACTIVE'].someField) FROM :p_entity

At this moment, during the filtering execution, I receive a warning in the database.

Also this record is present in db local cache

Answer 3 · 2024-07-12T09:29:04.000Z

I tried replacing the dependencies with the current snapshot, but it didn't help; the warning is still logged, and through the debugger, we don't even reach the class com.orientechnologies.orient.core.sql.method.misc.OSQLMethodField which was modified.

I also found another query without which we don't get the warning. It also goes through the edge to the records that trigger the warning but only reads it and doesn't change its state.

Answer 4 · 2024-07-12T10:10:56.000Z

Moreover, this happens only if the query is in the form SELECT expand(out('SomeEdge')[status = 'ACTIVE']) FROM :p_entity. However, if rewrite the query to SELECT FROM Record WHERE in('SomeEdge').@rid = :p_entity AND status= 'ACTIVE', the warning does not occur.

It's enough to change just any of the two queries that go to records through edges to a direct query with filtering, and the warning does not occur.

Answer 5 · 2024-07-12T11:25:57.000Z

@mikhalov may I ask you to try this branch https://github.com/andrii0lomakin/orientdb . There was substantial work done to avoid such problem there.

Answer 6 · 2024-07-12T13:27:45.000Z

@andrii0lomakin
I do a clean install(which fails in the end with the error java.lang.NoSuchMethodError: 'void sun.misc.Unsafe.ensureClassInitialized(java.lang.Class)' but the dependencies in the .m2 folder are created) and replace the version of dependencies in my project's pom.xml with this snapshot. Is this not enough?

Answer 7 · 2024-07-12T13:39:02.000Z

If this is enough, then nothing has changed; the warning is still logged, and additionally, the bootstrap of our application is broken and it crashes (I checked via a test bypassing the bootstrap).

Answer 8 · 2024-07-12T13:43:42.000Z

@mikhalov Do you use JDK 22 ? We did not fix the GraalVM dependency for this case. I will fix it and let you know at Monday then.

Answer 9 · 2024-07-12T13:53:10.000Z

@andrii0lomakin
The 22 version was used by default. I changed it to 17, and now the build completes, but it doesn't solve the problem.

Answer 10 · 2024-07-12T13:59:15.000Z

I will work on this @mikhalov thank you for all your efforts. I will notify you when I fix it.

Answer 11 · 2024-07-12T14:13:25.000Z

@mikhalov do you use remote or embedded deployment?

Answer 12 · 2024-07-12T14:17:55.000Z

@andrii0lomakin I use remote deployment, as I run the database through .\orientdb-community-3.2.31\bin\server.bat.

Answer 13 · 2024-07-12T16:22:17.000Z

Hi,

I see from what you are reporting there is a good chance that there is an issue in the expand( logic, @andrii0lomakin if you want to check also that you are welcome, otherwise let me know I can put some effort in that check.

Bye

Answer 14 · 2024-09-14T16:57:40.000Z

@andrii0lomakin @tglman

I investigated this issue further and found new facts: the problem is not with `expand()`, but with filtering through `[]`

This issue doesn't reproduce with just filtering in this way; a specific sequence of actions must occur. However, investigating this further has led me to a dead end. I can only say that in this sequence, both the queries and the code navigate through the same vertices via edges (we use VertexFrame wrappers and in the code, we call company.getCompanyFeature()).

It's also important to note that in this sequence, we modify the vertex field status value in the code(feature.setStatus(ACTIVE)), which is used for filtering in the final query and logs a warning in the console.

Below, I will provide variations of the final query (the one that produces the warning in the logs).

Both of these queries produce a warning in the logs:

SELECT expand(out('CompanyFeature')[status = 'ACTIVE'])
FROM :p_company

SELECT expand($feature)
FROM :p_company
let
$feature = out('CompanyFeature')[status = 'ACTIVE']

But if I rewrite it to WHERE filtering, the issue doesn't occur:

SELECT FROM (
SELECT expand(out('CompanyFeature'))
FROM :p_company
)
WHERE status = 'ACTIVE'

SELECT 
FROM Feature 
WHERE in('CompanyFeature') = :p_company AND status = 'ACTIVE'

Answer 15 · 2024-09-16T16:01:39.000Z

Hi,

thanks to this detailed check, this may be because that specific filtering may duplicate a document for some reason, I will check it and update.

Answer 16 · 2024-09-17T06:09:23.000Z

@mikhalov, do you have a database instance to reproduce this case? If so I would greatly appreciate if you send it to me, I will check it on upcoming branch when I fix such inconsistencies.

Answer 17 · 2024-09-17T09:28:22.000Z

@andrii0lomakin
I tried to reproduce this in unit tests to share with you, but I couldn't. I managed to reproduce it on an empty database, but by running our main tests, creating all the vertices and edges, and executing a certain sequence of method calls from our codebase.