Possible bug in driver

[bubnenkoff]

Hello. I can't handle exception on next code
https://stackoverflow.com/questions/70692397/cant-catch-exception-getting-unhandled-exception

Can it be bug in driver?

[isoos]

It looks like the server closed the connection. Is it happening reliably? Is there a specific query that triggers it?

[bubnenkoff]

Yes it happens every time. And I can't even catch exception. Full code with the queries:
https://gist.github.com/bubnenkoff/7377f735671aacd624371a14151856f4

[isoos]

Can you strip out everything, and reduce the code to: opening the connection, sending the queries (fixed ones by hand)? Looking at a method without context, or what the queries are doesn't do much...

[bubnenkoff]

I am trying to do it already several days. The single queries work (at last on my PC) but on real project (on big DB) I am getting fail.

[isoos]

If you are running the same queries, that suggests a network connection issue could be happening with the real project.

[bubnenkoff]

But DB and dart app is on same server. And I am getting an error approximately at same time.

Why catch do not handle nothing?

[isoos]

Sorry, I can't help you with the current information: I don't know nothing about your environment, setup, vpn, network policies etc. You'll need to create a much simpler reproduction code, otherwise I'm not able to try and debug it locally.

[julemand101]

One thing I noticed when looking at the code was:

postgresql-dart/lib/src/query.dart

Line 42 in d2197c9

final _onComplete = Completer<QueryResult<T>?>.sync();

There are lot of potential nasty issues by using the sync-version of Completer: https://api.dart.dev/stable/2.15.1/dart-async/Completer/Completer.sync.html

My suspicion is that the error flow have not been fully tested and verified that the sync Completer behaves correctly when things are failing.

[bubnenkoff]

@isoos julemand101 was right! it's bug. I removed sync call and I begin to catch:

Exception during Insert in xml_files: PostgreSQLSeverity.error : Attempting to execute query, but connection is not open. 

(I am happy with it :) )

[isoos]

@julemand101: great finding, I'll fix that soon...

[isoos]

Unfortunately many tests failed when I move it to async completer, so I've reverted the change for now. I'll need to dig into why the test fails, but I'm not sure if I'll have the time for it in the coming days. If anybody feels up for it, I'm happy to review and accept PRs changing this, as long as tests keep passing..

[julemand101]

@isoos Yeah, I did not expect the solution would be the one I suggested since I can spot multiple places in the code base where the intention is how events are handled. I have not made any detailed analysis of it so I cannot say for sure if this is needed. But I did get this feeling that some of the code base is specifically designed for the use of sync Completer. E.g.:

postgresql-dart/lib/src/connection_fsm.dart

Lines 345 to 350 in a9ea00e

	} catch (e, st) {
	scheduleMicrotask(() {
	q.completeError(e, st);
	});
	return this;

I don't know the history of this project and if this is some important attempt to solve performance issues. But it kinda smell like an attempt to improve performance where it is not needed (we are going to have IO wait time anyway since we are talking to an external database, so I don't really see a major benefit of preventing the spawn of one event per query).

I don't know if I am going to spend any time trying to get a better understanding of this package and fix this issue (especially since I don't even use PostgressSQL). But I might end up doing it if my weekend end up being boring enough. 🦆

[bubnenkoff]

@isoos oh... PostgreSQL is really pain. Fix above (remove sync call) is break your pool code.
The idea of code is next. It trying to insert data if it's getting exception, it assume that some duplicates exists and remove them, and do new insert.

After fix above the follow code stopped to work with message that second insert failed:

  Future<dynamic> sqlInsert(Map body) async {
    var isDataWasInserted = dbEnums.insertFailed; // т.к. идет несколько попыток
    try {
      await pgPool.runTx((ctx) async {
        for (var s in jsonDecode(body['sql'])) {
          await ctx.query(s);
        }
        isDataWasInserted = dbEnums.success;

      }).timeout(Duration(seconds: 120));
    } on PostgreSQLException catch (e) {

      print('FIRST INSERT FAILED: ${e.message} ');
      pgPool.cancelTransaction();
      try {
        print('There is some duplicates. Removing them');
        await pgPool.runTx((ctx) async {
          for (var s in jsonDecode(body['sql-remove'])) {
            await ctx.query(s);
          }

          print('Duplicates removed');

        }).timeout(Duration(seconds: 90));

        // new attempt to insert
        try {
          print('Second Insert');
          await pgPool.runTx((ctx) async {
            for (var s in jsonDecode(body['sql'])) {
              await ctx.query(s);
            }
            // print("INSERT2 SUCCESS");
            isDataWasInserted = dbEnums.success;
          }).timeout(Duration(seconds: 90));
          print('Second Insert Success');
        } on TimeoutException catch (e) {
          print('second attempt timeout error: ${e.message}');
        } on PostgreSQLException catch (e) {
          
          // если снова не вставилось, то значит вообще жопа какая-то
          print('PostgreSQLException SECOND INSERT WAS FAILED ${e.message}');
          pgPool.cancelTransaction();
          print('failed insert: ');
            for (var s in jsonDecode(body['sql'])) {
              print('sql insert: $s');
            }

          writeLog('SECOND INSERT WAS FAILED ', e.message); // !!!!
        }
      } on TimeoutException catch (e) {
        print('removing dups timeout error: ${e.message}');
      } on PostgreSQLException catch (e) {
        print('Removing duplicates was FAILED: ${e.message}');
      }
    } on Exception catch (e) {
      print('Some unknown exception with base class: $e');
    } 
    
    return isDataWasInserted;
    
  }

[isoos]

@bubnenkoff:

pgPool.cancelTransaction();

You don't need to call that, if you are using PgPool.runTx.

@julemand101: yeah, there are low-level parts in the code that pre-date my involvement and I have no insight on what the intention was. However, in this case, it seems that making the completer async screws up the order of the state transitions, and we've got duplicate rows in the result set - it makes tests fail.

So before doing this fix with the Completer, we should probably understand how the state transitions are intended.

On the plus side, I think the code has the potential to work just fine with the sync Completer, and we should be able to access the underlying issues. However, I really need a better reproduction case (/cc @bubnenkoff). E.g. I've added a few tests in #24 using a local postgres through docker, and you could probably follow the same pattern to create a code that reproduces your issue. I'll take over from there...

[bubnenkoff]

@isoos the reproduction is hard. I even was not able to reproduce it on on my local machine, only on working server...