UPDATE in transaction is not applied sometimes

[Radiokot]

Hi guys, I have this weird issue with 1.0.0-BETA28, and I would greatly appreciate any help in debugging it.

Scenario:

• An expense logging screen of an Android app is opened via a desktop shortcut
• User selects account and enters the amount
• A writeTransaction is executed in viewModelScope which contains the following queries:
  • INSERT new row into the transfers table
  • SELECT current account balance from the accounts table (stored as TEXT and mapped into BigInteger)
  • UPDATE the accounts table, set corresponding account balance to current - transfer amount
• Once writeTransaction is completed successfully, the screen closes and so the app goes to background

The issue: sometimes the balance UPDATE is not applied, although the new row gets inserted into the transfers table within the same transaction.

On the other hand, if the same expense logging is done from the main app screen, so the app doesn't go to background on transaction success, the UPDATE is always applied, and the user immediately sees the updated value in the UI (via database.watch())

Here is the log for the case when UPDATE has not been applied:

log.txt

There's a big time difference between 21:43:11.616 and 21:43:27.738 because I actually managed to suspend the SupabaseConnector by a breakpoint to confirm that table.update was indeed called with entry.opData having "balance=-4314082". Nevertheless, the balance in Supabase remained the same, and so it did in the app.

[simolus3]

Thanks for the report! In the logs, I see a number of SELECT id, tx_id, data FROM ps_crud ORDER BY id ASC LIMIT 1 calls indicating that you might be calling getCrudBatch with a limit of 1. Is this intentional? It splits up the transaction you had locally into separate supabase uploads which breaks the atomicity of the transaction. I'm not sure yet how that causes the issue of the update being lost, but it's still something that stands out.

[Radiokot]

I do not control this limit, I connect my PowerSyncDatabase with SupabaseConnector, pretty standard 🤔

[simolus3]

Oh right, sorry 🤦 And that one actually uses the default limit, so I need to check where that LIMIT 1 is coming from.

[Radiokot]

Is it this one?

powersync-kotlin/core/src/commonMain/kotlin/com/powersync/db/PowerSyncDatabaseImpl.kt

Line 294 in 3eda581

transaction.getAll("SELECT id, tx_id, data FROM ps_crud ORDER BY id ASC LIMIT 1") {

[Radiokot]

Hi @simolus3, I have new findings to share:

1. If I swap transfers INSERT and accounts UPDATE, so the update is executed first, then the update result is always preserved, and the transfer gets inserted locally as well!
2. However, when it immediately tries to sync the changes to Supabase when the app is already in background, the transfers INSERT (POST) sometimes gets rejected because of RLS policy violation. Why? Because for this operation for some reason an anon role JWT is used, despite my PowerSyncDatabase gets connected with SupabaseConnector upon creation. When I then open the app later and the sync restarts, the INSERT eventually gets synced.

So, weird stuff.

Here you can see attempts to sync transfers INSERT with anon role JWT:

11:14:47.146 <no-tag>                        E  Data upload error - retrying last entry: CrudEntry<40/92 PUT transfers/24678427-d3a8-43a7-8035-875d4b42242c {destination_amount=10000000, destination_id=96878196-f8fe-37db-8dd1-ad5ccd762087, source_amount=10000000, source_id=0733cd73-712b-345c-8358-31c04674c73a, time=2025-04-15T21:00:02Z}>, io.github.jan.supabase.postgrest.exception.PostgrestRestException: new row violates row-level security policy for table "transfers"
                                                URL: https://brbuezvbtkbrofypowjz.supabase.co/rest/v1/transfers?columns=destination_amount%2Cdestination_id%2Csource_amount%2Csource_id%2Ctime%2Cid
                                                Headers: [Authorization=[Bearer eyJhbGciOiJIUzI1NiIsInR5cCI6IkpXVCJ9.eyJpc3MiOiJzdXBhYmFzZSIsInJlZiI6ImJyYnVlenZidGticm9meXBvd2p6Iiwicm9sZSI6ImFub24iLCJpYXQiOjE3MzkwMjAwNjcsImV4cCI6MjA1NDU5NjA2N30.lmQmzRNj1b-ZfAc1YlU7gGBgKS_e706ioTU0jxxyG9A], Prefer=[return=minimal,resolution=merge-duplicates], Content-Profile=[public], apikey=[eyJhbGciOiJIUzI1NiIsInR5cCI6IkpXVCJ9.eyJpc3MiOiJzdXBhYmFzZSIsInJlZiI6ImJyYnVlenZidGticm9meXBvd2p6Iiwicm9sZSI6ImFub24iLCJpYXQiOjE3MzkwMjAwNjcsImV4cCI6MjA1NDU5NjA2N30.lmQmzRNj1b-ZfAc1YlU7gGBgKS_e706ioTU0jxxyG9A], X-Client-Info=[supabase-kt/3.1.4], Accept=[application/json], Accept-Charset=[UTF-8]]
                                                Http Method: POST
11:14:47.146 <no-tag>                        E  PowerSyncException: new row violates row-level security policy for table "transfers"
                                                URL: https://brbuezvbtkbrofypowjz.supabase.co/rest/v1/transfers?columns=destination_amount%2Cdestination_id%2Csource_amount%2Csource_id%2Ctime%2Cid
                                                Headers: [Authorization=[Bearer eyJhbGciOiJIUzI1NiIsInR5cCI6IkpXVCJ9.eyJpc3MiOiJzdXBhYmFzZSIsInJlZiI6ImJyYnVlenZidGticm9meXBvd2p6Iiwicm9sZSI6ImFub24iLCJpYXQiOjE3MzkwMjAwNjcsImV4cCI6MjA1NDU5NjA2N30.lmQmzRNj1b-ZfAc1YlU7gGBgKS_e706ioTU0jxxyG9A], Prefer=[return=minimal,resolution=merge-duplicates], Content-Profile=[public], apikey=[eyJhbGciOiJIUzI1NiIsInR5cCI6IkpXVCJ9.eyJpc3MiOiJzdXBhYmFzZSIsInJlZiI6ImJyYnVlenZidGticm9meXBvd2p6Iiwicm9sZSI6ImFub24iLCJpYXQiOjE3MzkwMjAwNjcsImV4cCI6MjA1NDU5NjA2N30.lmQmzRNj1b-ZfAc1YlU7gGBgKS_e706ioTU0jxxyG9A], X-Client-Info=[supabase-kt/3.1.4], Accept=[application/json], Accept-Charset=[UTF-8]]
                                                Http Method: POST
11:14:47.147 <no-tag>                        E  Error uploading crud: new row violates row-level security policy for table "transfers"
                                                URL: https://brbuezvbtkbrofypowjz.supabase.co/rest/v1/transfers?columns=destination_amount%2Cdestination_id%2Csource_amount%2Csource_id%2Ctime%2Cid
                                                Headers: [Authorization=[Bearer eyJhbGciOiJIUzI1NiIsInR5cCI6IkpXVCJ9.eyJpc3MiOiJzdXBhYmFzZSIsInJlZiI6ImJyYnVlenZidGticm9meXBvd2p6Iiwicm9sZSI6ImFub24iLCJpYXQiOjE3MzkwMjAwNjcsImV4cCI6MjA1NDU5NjA2N30.lmQmzRNj1b-ZfAc1YlU7gGBgKS_e706ioTU0jxxyG9A], Prefer=[return=minimal,resolution=merge-duplicates], Content-Profile=[public], apikey=[eyJhbGciOiJIUzI1NiIsInR5cCI6IkpXVCJ9.eyJpc3MiOiJzdXBhYmFzZSIsInJlZiI6ImJyYnVlenZidGticm9meXBvd2p6Iiwicm9sZSI6ImFub24iLCJpYXQiOjE3MzkwMjAwNjcsImV4cCI6MjA1NDU5NjA2N30.lmQmzRNj1b-ZfAc1YlU7gGBgKS_e706ioTU0jxxyG9A], X-Client-Info=[supabase-kt/3.1.4], Accept=[application/json], Accept-Charset=[UTF-8]]
                                                Http Method: POST
11:15:23.523 <no-tag>                        E  Error in streamingSync: Software caused connection abort

But after I manually opened the app in a minute, the same INSERT is synced successfully:

11:15:47.990 Supabase-Core                   D  Starting POST request to endpoint /rest/v1/transfers
11:15:47.996 4MN:DefaultRequest              V  Applied DefaultRequest to https://brbuezvbtkbrofypowjz.supabase.co/rest/v1/transfers?columns=destination_amount%2Cdestination_id%2Csource_amount%2Csource_id%2Ctime%2Cid. New url: https://brbuezvbtkbrofypowjz.supabase.co/rest/v1/transfers?columns=destination_amount%2Cdestination_id%2Csource_amount%2Csource_id%2Ctime%2Cid
11:15:47.996 4MN:ContentNegotiation          V  Adding Accept=application/json header for https://brbuezvbtkbrofypowjz.supabase.co/rest/v1/transfers?columns=destination_amount%2Cdestination_id%2Csource_amount%2Csource_id%2Ctime%2Cid
11:15:48.000 4MN:ContentNegotiation          V  Converted request body using io.ktor.serialization.kotlinx.KotlinxSerializationConverter@72a1da7 for https://brbuezvbtkbrofypowjz.supabase.co/rest/v1/transfers?columns=destination_amount%2Cdestination_id%2Csource_amount%2Csource_id%2Ctime%2Cid
11:15:48.000 4MN:HttpPlainText               V  Adding Accept-Charset=UTF-8 to https://brbuezvbtkbrofypowjz.supabase.co/rest/v1/transfers?columns=destination_amount%2Cdestination_id%2Csource_amount%2Csource_id%2Ctime%2Cid
11:15:48.001 4MN:defaultTransformers         V  Transformed with default transformers request body for https://brbuezvbtkbrofypowjz.supabase.co/rest/v1/transfers?columns=destination_amount%2Cdestination_id%2Csource_amount%2Csource_id%2Ctime%2Cid from class io.ktor.http.content.TextContent
11:15:48.082 TrafficStats                    D  tagSocket(154) with statsTag=0xffffffff, statsUid=-1
11:15:48.310 4MN:HttpCallValidator           V  Validating response for request https://brbuezvbtkbrofypowjz.supabase.co/rest/v1/transfers?columns=destination_amount%2Cdestination_id%2Csource_amount%2Csource_id%2Ctime%2Cid
11:15:48.310 4MN:DefaultResponseValidation   V  Skipping default response validation for https://brbuezvbtkbrofypowjz.supabase.co/rest/v1/transfers?columns=destination_amount%2Cdestination_id%2Csource_amount%2Csource_id%2Ctime%2Cid
11:15:48.318 Supabase-Core                   D  POST request to endpoint /rest/v1/transfers successfully finished in 295ms

[Radiokot]

Hi @simolus3,

The operation reorder workaround unfortunately seems unreliable, as through the week of testing this flow I faced data loss anyway. I just got harder to reproduce.

Currently, I'm testing another workaround, which is to wait for the changes from the transaction to be emitted in watch() flows, and only then proceed with app finishing.

[Radiokot]

The more I stare at the LIMIT 1 query, the more wrong it looks to me.

So the method getNextCrudTransaction() of the database is supposed to return next CRUD transaction to sync with the backend. At the beginning, it selects one oldest CRUD entry, and if it has no associated transactionId, returns CrudTransaction containing one entry.

However, if the entry has transactionId, then instead the method seems to be meant to return CrudTransaction with all the entries within the same database transaction. For this, it re-selects CRUD entries, but now specifying the transactionId from the initially selected single entry as ps_crud.tx_id.

It used to execute this query:

getCrudEntryByTxId:
SELECT id, tx_id, data FROM ps_crud WHERE tx_id = ? ORDER BY id ASC;

But in #145 , the executed query was changed to this:

SELECT id, tx_id, data FROM ps_crud ORDER BY id ASC LIMIT 1

Problems I see here:

1. The transactionId of the initially selected CRUD entry is ignored
2. LIMIT 1 ignores the fact that multiple CRUD entries occur in a transaction

So effectively this query returns the same initially selected oldest CRUD entry, and the whole

if (txId == null) {
...
} else {
...
}

is useless.

Moreover, once the connector has synced this partial transaction with one entry, the database completes the checkpoint (sorry if I use wrong term here) ignoring the possibility that syncing the next CRUD entry of the same transaction may fail – then what?

[simolus3]

Thank you very much for the report and all your help identifying and fixing this issue!! We have released your PR in version 1.0.0-BETA31. Could you check whether that fixes the problem or if you still have issues with that version?

[Radiokot]

Sure, I'll update the library and test the scenario over the next few days, as the issue is floating.

[Radiokot]

Should I create a separate issue for using "anon" Supabase token when trying to sync the changes in background? With the update, it no longer causes [CrudTransaction::complete] Completing transaction with checkpoint until all the changes in the transaction are applied. So it's a big improvement.

[simolus3]

That's good to hear 👍 If it does re-occur please let us know.

Should I create a separate issue for using "anon" Supabase token when trying to sync the changes in background?

Yes, I don't think I remember seeing that issue when testing background sync. So I think having more details on that in a separate issue would be best for us.