Timeout is not applied to the running query when transaction is involved.

[JuanLuisNL]

If I run this from a computer:

execute(‘BEGIN’)
String cSQL = ‘SELECT * FROM customers WHERE id = 1635 FOR UPDATE’
execute(cSQL, queryMode: QueryMode.extended, timeout: const Duration(seconds: 5))
.....

and from another order I execute the same code to check the lock, although I have a timeout of 5 seconds, the error takes about 1 minute.
SERVER: statement_timeout = 0
What could be happening?

[isoos]

@JuanLuisNL: Thanks for reporting this! Is there any chance that you can provide a minimal working example, using the dockerized test setup like this: https://github.com/isoos/postgresql-dart/blob/master/test/decode_test.dart#L328-L343 ?

[JuanLuisNL]

Sorry for my ignorance, I don't understand what you mean).
I have this function (I have removed the unimportant parts), first I execute it from a computer, when I execute this same code from another computer (to prevent the modification of the row), the program waits 1 minute instead of 5 seconds. If I commit in the first computer, automatically in the second one the process continues. I don't know if I'm making myself clear

Future lockRow(String cTabla, int id) async {
try {
String cSQL = "SELECT * FROM $cTabla WHERE id = $id FOR UPDATE";
await execute("BEGIN");
await _oCn.execute(cSQL, queryMode: QueryMode.extended, timeout: timeOut);
return true;
} catch (e, stack) {
Utils.printError(e, stack);
return false;
}
}

[JuanLuisNL]

Can I provide more information to solve the problem?

[isoos]

@JuanLuisNL: I was mostly offline for the past two weeks, slowly getting back to these issues.

The most helpful thing would be a minimal test in our test suite that fails (as a PR or a comment here), along the lines of:

  withPostgresServer('sql null', (server) {
    test('decode output', () async {
      final c1 = await server.newConnection();
      final c2 = await server.newConnection();

      // ... demonstrates the issue
    });
  });

The test suite will create a local postgres instance inside a docker image, and we can run it repeatedly in CI after fixing the underlying issue.

[JuanLuisNL]

Sorry, I'm not familiar with that kind of testing and I don't really know what to do (

What I do to test is from "pgadmin" run this :
BEGIN ;
SELECT * FROM emp0001.customers WHERE id = 1635 FOR UPDATE;

Then from my code I run:
await execute("BEGIN");
String cSQL = "SELECT * FROM emp0001.customers WHERE id = 1635 FOR UPDATE";
Result result = await execute(cSQL, timeOut: const Duration(seconds: 5));

The program stops for about 1 minute, not 5 seconds..
But if from "pgadmin" I do COMMIT the program continues immediately.

I'm sorry I can't do more to explain myself ...

[isoos]

@JuanLuisNL: Yeah, that's a helpful description. I may need some time to look into it, but now I understand it better.

[JuanLuisNL]

Thank you very much

[isoos]

@JuanLuisNL: I was able to create a small reproduction of the issue as a regular test: #362

Unfortunately I don't see a quick fix for it, as it will require the cancellation of the currently running query with the coordination of a client-side timer. If somebody wants to dig into it, I imagine it something like:

• When timeout is set, a Timer starts at the scheduling of the query.
• When a query completes, the Timer is cancelled.
• When the Timer runs, it marks the current query as timed out, and issues a back-channel cancellation as described in https://www.postgresql.org/docs/current/protocol-flow.html#PROTOCOL-FLOW-CANCELING-REQUESTS
• Only after that yields back control with a TimeoutException.

[isoos]

We should also consider to use the statement_timeout variable on each session (or per-query + reset if needed).

[JuanLuisNL]

Thank you very much István

I did the ‘statement_timeout’ (per-query + reset if needed) and it works perfectly. As before I check if there is a lock set, that command will be executed very few times, so it's not a problem to do it that way.

I appreciate your help

[isoos]

As before I check if there is a lock set

Could you please elaborate if this is a DB lock or something in your app?

I am starting to think that statement_timeout would be the correct way to address this. E.g. on each connection start we set it to whatever the resolved value is, and we keep track of the latest value we have set it to. Whenever we send in a new statement, the client may check the currently resolved timeout parameter and if it differs, we send a new value. /cc @simolus3 - is there any similar feature in the sqlite client package?

[simolus3]

There isn't, as sqlite3 doesn't have an obvious way to set timeouts (it's possible because you can inject a callback that it invokes once in a while, but nothing official like with postgres).

and we keep track of the latest value we have set it to. Whenever we send in a new statement, the client may check the currently resolved timeout parameter and if it differs, we send a new value

I think this is a reasonable approach 👍 We might want to suggest setting a statement timeout on the connection primarily, only altering it for rare queries that really need different values. Otherwise we'd end up sending a lot of variable changes as the effective timeout for every query jumps around.
(or maybe there should just be a Future<void> setQueryTimeout(Duration) method instead of an explicit option for statements?)

[isoos]

We might want to suggest setting a statement timeout on the connection primarily, only altering it for rare queries that really need different values.

We already have SessionSettings.queryTimeout (which should be migrated to / renamed to statementTimeout long term?) with a default of 5 minutes. Users using the defaults would just have it set at connection time, and whenever you override it for a query or session, it would be updated. Certainly not for every query, unless you do set a different value for the queries.

[isoos]

@JuanLuisNL: Please give me more details on how you made the transaction + the session_timeout work. I have a pending work in #363 that is not really working yet, but I may be overlooking something.

[isoos]

I was able to get that specific test working, but I'd consider that solution a hack (and other timeout tests are failing). I will need to look into this a bit more to figure out a better way handle it.

[JuanLuisNL]

In short I do this and it works for me:

• I check if there is a lock in the row (isLockRow):
  
• I set ‘statement_timeout’ to 2 seconds
• I start the transaction
• I run the query and if there is a timeout error I do a rollback.
• Finally I reset statement_timeout

CODE:

if (await isLockRow(cTabla, idLock)) return false;
await execute("set statement_timeout to 2000");
await execute("BEGIN");
await execute("SELECT * FROM $tbl WHERE id = $id FOR UPDATE");
if (timeoutError) await execute("ROLLBACK");
await execute("set statement_timeout to 0");
.....

I have omitted the lines that are not important, for internal use of the app.

[isoos]

@JuanLuisNL: after a couple of PRs #380 is now passing on the test use case you've described. I've released 3.4.0-dev.2, could you please help me to verify that timeouts are working for you as expected?

[JuanLuisNL]

Hello
I have upgraded to version ‘postgres: ^3.4.0-dev.2’.

• I set the lock from ‘pgadmin’.
• I try to set the lock from Flutter with:
  await execute("SELECT ... FOR UPDATE’, queryMode: QueryMode.extended, timeout: const Duration(seconds: 2));
• The application waits for a long time, it fails with and without transaction, the problem is ‘FOR UPDATE’.
• If I do it with ‘set statement_timeout’ it waits 2 seconds.

---

• If I set the lock in pgadmin, then start the transaction in flutter without writing ‘FOR UPDATE’ the program waits 2 seconds only.

[isoos]

Hm, are you doing something conceptually different that the test case here?
https://github.com/isoos/postgresql-dart/blob/master/test/timeout_test.dart#L113-L133

[JuanLuisNL]

I do exactly the same:
(I show the parameters of the connection in case it influences in something)
With the first connection the waiting time is 0 seconds.
With the second connection the programme waits.

  Connection oCn;
  oCn = await Connection.open(Endpoint(host: '192.168.0.7', database: 'GV00001', username: 'postgres', password: 'xx', port: 25060), settings: const ConnectionSettings(sslMode: SslMode.disable));
  await oCn.execute('BEGIN');
  await oCn.execute('SELECT * FROM $cTabla WHERE id = 1635 FOR UPDATE', timeout: const Duration(seconds: 2));

  Connection oCn1;
  oCn1 = await Connection.open(Endpoint(host: '192.168.0.7', database: 'GV00001', username: 'postgres', password: 'xx', port: 25060), settings: const ConnectionSettings(sslMode: SslMode.disable));
  await oCn1.execute('BEGIN');
  await oCn1.execute('SELECT * FROM $cTabla WHERE id = 1635 FOR UPDATE', timeout: const Duration(seconds: 2));

[isoos]

Yeah, that's the same, barring the ssl mode, but if I change the test it is still working.

Are you running it from a console app? Is there any zone-handler that catches and swallows unhandled exceptions?

[JuanLuisNL]

I run it in flutter desktop for windows and yes, I have ‘runZonedGuarded’, I have also tried try catch.

[isoos]

The current implementation may have an exception emitted from the timeout timer, which is not (yet) exposed through the execute, it is rather an uncatched at zone-level. Have you tried to print the onError in the zone and nothing there?

[JuanLuisNL]

yes, the programme stops, there is no error

[JuanLuisNL]

it just stands there.

[isoos]

@JuanLuisNL: Could you please try to set my debug branch as your dependency and give it a try? https://github.com/isoos/postgresql-dart/tree/debug

I have added a few extra checks and prints to see what's happening.

As described here: https://dart.dev/tools/pub/dependencies#git-packages

[JuanLuisNL]

I don't see any print on the console. After this function, it stops in the dispose.

[isoos]

Thanks for the patience and the debugging! However, this is still not there yet:

I do have this statement in the Timer:

print('Cancel request triggered.');

I would like to see that somewhere, and also a corresponding completed printout. If this is absent, it is very likely that the uncaught exception from the timer is also swallowed by some top-level catch-all zone.

As an alternative, could you please try to just run it from a local dart app, something along the line of the test, just within a simple main method?

[JuanLuisNL]

From main.dart

[isoos]

Not sure what we are looking at here: did it reach the first print? How about the second? or any exception?

[JuanLuisNL]

Now, yes, clean up the project. Maybe I ran the previous version before.
Thank you very much, it works
Error:
57014: cancelando la sentencia debido a una petición del usuario mientras se bloqueaba la tupla (20,20) de la relación «clientes»

[isoos]

I'm glad it is working!

57014: cancelando la sentencia debido a una petición del usuario

Ouch, so this localized message will screw up exception transformations like this:
https://github.com/isoos/postgresql-dart/blob/master/lib/src/exceptions.dart#L198

[JuanLuisNL]

Very kind, thank you again!

[JuanLuisNL]

I can now report that someone else is modifying a record from another computer with an appropriate message.