Exceptions thrown after upgrading to 3.4.0 & 3.4.4

[pst9354]

Edit: Had to revert to 3.2.1 to get it working.

---

Long running SQL query generates exception.

For 3.4.0:
Unhandled exception:
Bad state: Message parser consumed more bytes than expected. type=68 expectedLength=711
#0 MessageFramer.addBytes (package:postgres/src/message_window.dart:82:11)

#1 _readMessages...handleChunk (package:postgres/src/v3/protocol.dart:73:9)

For 3.4.4:
Unhandled exception:
Severity.error Socket error: Bad state: Not enough bytes to read.
#0 new _PgResultStreamSubscription (package:postgres/src/v3/connection.dart:758:29)
#1 _BoundStatement.listen (package:postgres/src/v3/connection.dart:728:12)
#2 _PreparedStatement.run (package:postgres/src/v3/connection.dart:677:43)
#3 _PgSessionBase.execute (package:postgres/src/v3/connection.dart:172:31)

#4 InvoiceJob.doInvoice (package:invoice_service/invoicejob.dart:2179:28)

#5 InvoiceQueue.handleInQueue. (package:invoice_service/invoice_queue.dart:423:17)

#6 InvoiceQueue.handleInQueue (package:invoice_service/invoice_queue.dart:419:7)

[isoos]

@pst9354 It would be great if we could create a reproduction test for this, otherwise this is not much to work with. Could you please give more context about the query and your setup?

[pst9354]

@isoos I don't think I can easily reproduce it.
This is one of our customers live data with a lot of data/relations.

If I were to debug it, where should I start?

[isoos]

As a start, a few information I would need: server version, what is the long-running query, what is the schema it is running on? It is very likely that this is related to a type serialization, either by a cast, or a plugin or a custom type. Any of this could be present here?

[pst9354]

I'm cloning their database to another machine at the moment.
Hopefully I can open up that database and let you debug against it.

[isoos]

@pst9354 For many legal reasons I definitely won't do that. Please don't share any of your client data to anybody.

[pst9354]

I will of course anonymize the data, before sharing it.

[isoos]

@pst9354 Please don't. I wouldn't risk any legal trouble by touching such data without written and signed agreements. We need to find other ways of debugging this.

[pst9354]

Ok, I will still need the clone to debug, so that I can reproduce it.

[pst9354]

Well, sadly I can't reproduce the error outside the live environment :-(

[pst9354]

I have reverted all our services to version 3.2.1.
Hopefully I can find some time over christmas to debug the problem.

[isoos]

Please note that the difference between that and the new version is that the errors still happen, but you are not aware of them.

[pst9354]

Not in my case.

In 3.2.1 the query will finnish and the Result is valid.

In 3.4.4 the query will throw an exception and quit.

I just had another run in a live environment, the try / catch doesn't catch it:
Unhandled exception:
Bad state: Cannot add event after closing
#0 _MultiStreamController.addErrorSync (dart:async/stream_impl.dart:1131:24)
#1 _readMessages...handleChunk (package:postgres/src/v3/protocol.dart:77:20)

[pst9354]

The problem has been reported on two different servers, running:

1. PostgreSQL 13.8 (Debian 13.8-0+deb11u1) on x86_64-pc-linux-gnu, compiled by gcc (Debian 10.2.1-6) 10.2.1 20210110, 64-bit
2. PostgreSQL 13.9 (Debian 13.9-0+deb11u1) on x86_64-pc-linux-gnu, compiled by gcc (Debian 10.2.1-6) 10.2.1 20210110, 64-bit

After the reports, we reverted to 3.2.1

[isoos]

Any idea on what query was running?

[pst9354]

Example of query generating the error:

SELECT * FROM (
SELECT o.id,0 AS invoice_type,o.status,v.number AS vehicle_number,v.regno,e.number AS employee_number,t.number AS trip_number,vo.org_number,o.pickup_time AS pickup_time,o.destination_time,o.real_pickup_time,o.real_destination_time,o.passenger,
o.phone,o.info,c.name AS customer,c.id AS customer_id,c.number AS customer_number,o.price_vat,o.payment_type,o.pax,o.vehicle_type_id,o.invoice_info,o.distance,
o.reference,o.external_orderid,o.parent_id,o.shared_type AS shared_type,COALESCE(cc.number,'') AS cc_number,COALESCE(cc.reference,'') AS cc_reference,
ap.street||' '||ap.number||', '||ap.city AS pickup_adress,
ap.latitude AS pickup_latitude,ap.longitude AS pickup_longitude,
ad.street||' '||ad.number||', '||ad.city AS destination_adress,
ad.latitude AS destination_latitude,ad.longitude AS destination_longitude,
o.invoice_id,c.new_invoice_per_cc,
(SELECT array_to_string(ARRAY(SELECT street || ' ' || number FROM adress WHERE type like 'via%' AND order_id=o.id ORDER BY type),', ')) AS via,price_self,p.number AS passenger_number,
COALESCE(cc.name,'') AS cc_name,
td.number AS tariff_number,td.start,o.max_start,o.km_tariff,o.time_tariff,o.trip_type,ova.id AS kombi,o.km_in,o.km_out,td.start_max,
o.pickup_zone,o.destination_zone,o.drive_time,o.pricelist_id,c.pricelist_id AS customer_pricelist_id,c.customer_type_id AS customer_type_id,
(SELECT array_to_string(array_agg(va.id),',') FROM _vehicleattribute AS va,_ordervehicleattribute AS ova WHERE ova.order_id=o.id AND ova.vehicle_attribute_id=va.id) AS attributes,
o.deleted_time,c.late_cancelled,ct.late_cancelled AS ct_late_cancelled,td.amount_km AS tariff_amount_km,td.amount_hour AS tariff_amount_hour

  FROM _order AS o LEFT OUTER JOIN _customercc AS cc ON o.customercc_id=cc.id
  LEFT OUTER JOIN _employee AS e ON e.id=(SELECT id FROM _employee AS d WHERE d.id=o.driver_id ORDER BY d.id DESC LIMIT 1)
  LEFT OUTER JOIN _passenger AS p ON p.id=o.pass_id
  LEFT OUTER JOIN _trip AS t ON t.id=(SELECT id FROM _trip AS tt WHERE tt.booking_no=o.id ORDER BY tt.id DESC LIMIT 1)
  LEFT OUTER JOIN _tariffdata AS td ON td.id=o.tariffdata_id
  LEFT OUTER JOIN _customer AS c ON c.id=o.customer_id
  LEFT OUTER JOIN _customertype AS ct ON c.customer_type_id=ct.id
  LEFT OUTER JOIN _ordervehicleattribute AS ova ON ova.id=(SELECT id FROM _ordervehicleattribute WHERE order_id=o.id AND vehicle_attribute_id=1601 ORDER BY id DESC LIMIT 1)
  LEFT OUTER JOIN _adress AS ap ON ap.id=(SELECT id FROM _adress WHERE type='pickup' AND order_id=o.id ORDER BY id DESC LIMIT 1) 
  LEFT OUTER JOIN _adress AS ad ON ad.id=(SELECT id FROM _adress WHERE type='destination' AND order_id=o.id ORDER BY id DESC LIMIT 1),
  _vehicle AS v LEFT OUTER JOIN _vehicleowner AS vo ON (v.owner_id=vo.id)
  WHERE 
  o.vehicle_id=v.id AND (ap.order_id=o.id AND ap.type='pickup')
  AND o.id>0 AND NOT COALESCE(o.customer_id,null,0)=0 
  AND o.pickup_time<'2024-11-30 23:59:00.000Z' AND o.trip_type<100
  AND LPAD(c.number, 32, '0')>=LPAD('0', 32, '0') AND LPAD(c.number, 32, '0')<=LPAD('99999999', 32, '0')  AND (o.status IN (3) OR (o.status=5 AND o.invoice_id IS null)) AND NOT COALESCE(o.invoice_id,0)=-1 
   AND o.payment_type=7 
  AND pickup_time>'2024-11-01 00:00:00.000Z' AND pickup_time>'2024-11-30 23:59:00.000Z'::timestamp-interval '6 months' 
  
  UNION
  
  SELECT o.id,1 AS invoice_type,o.status,v.number AS vehicle_number,v.regno,e.number  AS employee_number,t.number AS trip_number,vo.org_number,o.pickup_time AS pickup_time,o.destination_time,o.real_pickup_time,o.real_destination_time,o.passenger, 
  o.phone,o.info,c.name AS customer,c.id AS customer_id,c.number AS customer_number,o.price_self,o.payment_type_self,o.pax,o.vehicle_type_id,o.invoice_info,o.distance,
  o.reference,o.external_orderid,o.parent_id,o.shared_type AS shared_type,'','',
  ap.street||' '||ap.number||', '||ap.city AS pickup_adress,
  ap.latitude AS pickup_latitude,ap.longitude AS pickup_longitude,
  ad.street||' '||ad.number||', '||ad.city AS destination_adress,
  ad.latitude AS destination_latitude,ad.longitude AS destination_longitude,
  o.invoice_selfpayment_id AS invoice_id,c.new_invoice_per_cc,
  (SELECT array_to_string(ARRAY(SELECT street || ' ' || number FROM _adress WHERE type like 'via_%' AND order_id=o.id ORDER BY type),', ')) AS via,price_self,p.number AS passenger_number, '',
  td.number AS tariff_number,td.start,o.max_start,o.km_tariff,o.time_tariff,o.trip_type,ova.id AS kombi,o.km_in,o.km_out,td.start_max,
  o.pickup_zone,o.destination_zone,o.drive_time,o.pricelist_id,c.pricelist_id AS customer_pricelist_id,c.customer_type_id AS customer_type_id,
  (SELECT array_to_string(array_agg(va.id),',') FROM _vehicleattribute AS va,_ordervehicleattribute AS ova WHERE ova.order_id=o.id AND ova.vehicle_attribute_id=va.id) AS attributes,
  o.deleted_time,c.late_cancelled,ct.late_cancelled AS ct_late_cancelled,td.amount_km AS tariff_amount_km,td.amount_hour AS tariff_amount_hour

  FROM _order AS o LEFT OUTER JOIN _customercc AS cc ON o.customercc_id=cc.id
  LEFT OUTER JOIN _employee AS e ON e.id=(SELECT id FROM _employee AS d WHERE d.id=o.driver_id ORDER BY d.id DESC LIMIT 1)
  LEFT OUTER JOIN _passenger AS p ON p.id=o.pass_id
  LEFT OUTER JOIN _trip AS t ON t.id=(SELECT id FROM _trip AS tt WHERE tt.booking_no=o.id ORDER BY tt.id DESC LIMIT 1)
  LEFT OUTER JOIN _tariffdata AS td ON td.id=o.tariffdata_id
 	LEFT OUTER JOIN _customer AS c ON c.id=o.customer_selfpayment_id
  LEFT OUTER JOIN _customertype AS ct ON c.customer_type_id=ct.id
  LEFT OUTER JOIN _ordervehicleattribute AS ova ON ova.id=(SELECT id FROM _ordervehicleattribute WHERE order_id=o.id AND vehicle_attribute_id=1601 ORDER BY id DESC LIMIT 1)
  LEFT OUTER JOIN _adress AS ap ON ap.id=(SELECT id FROM _adress WHERE type='pickup' AND order_id=o.id ORDER BY id DESC LIMIT 1) 
  LEFT OUTER JOIN _adress AS ad ON ad.id=(SELECT id FROM _adress WHERE type='destination' AND order_id=o.id ORDER BY id DESC LIMIT 1),
  _vehicle AS v LEFT OUTER JOIN _vehicleowner AS vo ON (v.owner_id=vo.id)
  WHERE 
  o.vehicle_id=v.id AND (ap.order_id=o.id AND ap.type='pickup')
  AND o.id>0 AND NOT COALESCE(o.customer_id,null,0)=0 
  AND o.pickup_time<'2024-11-30 23:59:00.000Z' AND o.trip_type<100
	AND NOT o.price_self=0
   AND o.payment_type_self=7 
  AND LPAD(c.number, 32, '0')>=LPAD('0', 32, '0') AND LPAD(c.number, 32, '0')<=LPAD('99999999', 32, '0')  AND (o.status IN (3) OR (o.status=5 AND o.invoice_selfpayment_id IS null)) AND NOT COALESCE(o.invoice_selfpayment_id,0)=-1 
  AND pickup_time>'2024-11-01 00:00:00.000Z' AND pickup_time>'2024-11-30 23:59:00.000Z'::timestamp-interval '6 months' 

) AS joined_order ORDER BY LPAD(customer_number, 32, '0'),LPAD(COALESCE(cc_number,''), 32, '0'),cc_number,pickup_time,shared_type DESC;

[isoos]

@pst9354: as #398 is slightly similar issue, and it turns out it is present only when the SSL mode is disabled: what kind of SSL mode are you using here?

[pst9354]

sslMode: SslMode.disable

Tried to reproduce the error in our production envirnoment, but I couldn't at the moment.
It's not always possible to trigger the error...

[pst9354]

Found a company/client instance that I could reproduce the error on.

Run 1: SslMode.disable
Unhandled exception:
Bad state: Cannot add event after closing
#0 _MultiStreamController.addErrorSync (dart:async/stream_impl.dart:1131:24)
#1 _readMessages...handleChunk (package:postgres/src/v3/protocol.dart:77:20)

Run 2: SslMode.require
No error

Run 3: SslMode.disable
Unhandled exception:
Bad state: Cannot add event after closing
#0 _MultiStreamController.addErrorSync (dart:async/stream_impl.dart:1131:24)
#1 _readMessages...handleChunk (package:postgres/src/v3/protocol.dart:77:20)

Run 4: SslMode.require
No error

So yes, on my 4 test-runs, the SslMode.disable breaks things.

[pst9354]

An observation when enabling SslMode.require is that queries seems to run at half speed :-(

[isoos]

Based on the error from the other issue and your report here, I'm fairly confident that #400 fixes the issue (the bug part anyway). As for the half speed, we should probably expand on that test in #400 and benchmark the library, I could imagine that there are trivial gains here and there. If you have a different benchmark than in the test, please submit it as a separate issue, I'll take a look into it possibly next week.

Closing the issue as the newly published 3.4.5 should handle it, please reopen if you still find it failing.

[pst9354]

Thank you @isoos.
Sadly I can't reproduce the error with 3.4.4 at the moment, to confirm that 3.4.5 fixes the problem.

[pst9354]

I was finally able to reproduce the error and can confirm that 3.4.5 solves the problem.