BUG #17070: Sometimes copy from ingnores transaction
The following bug has been logged on the website:
Bug reference: 17070
Logged by: Дмитрий Секретов
Email address: d.sekretov@gmail.com
PostgreSQL version: 12.1
Operating system: Windows Server 2016
Description:
Driver: Npgsql 4.0.9 (.net 4.7.1)
We use following construction in our code:
1. Start transaction
2. COPY FROM STDIN BINARY (table name depends on context)
3. Insert into "some_table"("some_value")
4. Commit transaction
It works fine. When something goes wrong then transaction rollbacks.
But we found the issue. We do copy operation (step 2). When copy commands
ended the driver sends “copy done” command to postgresql backed and starts
waiting for “command complete” message and error occurs during waiting.
2021-04-29 02:40:01,593 ERROR Exception while reading from stream --->
System.IO.IOException: Unable to read data from the transport connection: A
connection attempt failed because the connected party did not properly
respond after a period of time, or established connection failed because
connected host has failed to respond.
In a 160 seconds postgresql reported in logs
2021-04-29 02:42:41 database LOG: duration: 202590.129 ms statement: COPY
"principal_reference" (id,"some_payload") FROM STDIN BINARY;
2021-04-29 02:42:41 database LOG: could not receive data from client: An
established connection was aborted by the software in your host machine.
In our application code we retry operation, if something goes wrong. And
when we start retrying we've got an exception
2021-04-29 02:42:41 database ERROR: duplicate key value violates unique
constraint "PK_principal_reference_id"
We didn't commit transaction. But copy done successfully and there is no row
inserted at step 3.
Is there a workaround? Like a copy into temp table and then insert from temp
table?
On Wed, Jun 23, 2021 at 07:02:18AM +0000, PG Bug reporting form wrote:
The following bug has been logged on the website:
Bug reference: 17070
Logged by: Дмитрий Секретов
Email address: d.sekretov@gmail.com
PostgreSQL version: 12.1
Operating system: Windows Server 2016
Description:Driver: Npgsql 4.0.9 (.net 4.7.1)
We use following construction in our code:
1. Start transaction
2. COPY FROM STDIN BINARY (table name depends on context)
3. Insert into "some_table"("some_value")
4. Commit transactionIt works fine. When something goes wrong then transaction rollbacks.
But we found the issue. We do copy operation (step 2). When copy commands
ended the driver sends “copy done” command to postgresql backed and starts
waiting for “command complete” message and error occurs during waiting.2021-04-29 02:40:01,593 ERROR Exception while reading from stream --->
System.IO.IOException: Unable to read data from the transport connection: A
connection attempt failed because the connected party did not properly
respond after a period of time, or established connection failed because
connected host has failed to respond.In a 160 seconds postgresql reported in logs
2021-04-29 02:42:41 database LOG: duration: 202590.129 ms statement: COPY
"principal_reference" (id,"some_payload") FROM STDIN BINARY;
2021-04-29 02:42:41 database LOG: could not receive data from client: An
established connection was aborted by the software in your host machine.In our application code we retry operation, if something goes wrong. And
when we start retrying we've got an exception
2021-04-29 02:42:41 database ERROR: duplicate key value violates unique
constraint "PK_principal_reference_id"We didn't commit transaction. But copy done successfully and there is no row
inserted at step 3.
Most likely, (1) never happened, so your application was actually running (2)
as an implied transaction that did commit. One way to confirm this is to set
log_statement=all and look for the BEGIN (or START TRANSACTION) command in the
logs. What sequence of commands does the server log show from the session
that experiences the problem?
Is there a workaround? Like a copy into temp table and then insert from temp
table?
There probably would be a workaround, but if COPY results are visible after a
transaction rollback, that would be a bug.
It happens very rarely and it happens in production (2-3 times a year), i
can't log all. I look into code and we always start transaction. We have
tests - rollback works fine. But it happened.
вс, 22 авг. 2021 г. в 21:38, Noah Misch <noah@leadboat.com>:
Show quoted text
On Wed, Jun 23, 2021 at 07:02:18AM +0000, PG Bug reporting form wrote:
The following bug has been logged on the website:
Bug reference: 17070
Logged by: Дмитрий Секретов
Email address: d.sekretov@gmail.com
PostgreSQL version: 12.1
Operating system: Windows Server 2016
Description:Driver: Npgsql 4.0.9 (.net 4.7.1)
We use following construction in our code:
1. Start transaction
2. COPY FROM STDIN BINARY (table name depends on context)
3. Insert into "some_table"("some_value")
4. Commit transactionIt works fine. When something goes wrong then transaction rollbacks.
But we found the issue. We do copy operation (step 2). When copy commands
ended the driver sends “copy done” command to postgresql backed andstarts
waiting for “command complete” message and error occurs during waiting.
2021-04-29 02:40:01,593 ERROR Exception while reading from stream --->
System.IO.IOException: Unable to read data from the transportconnection: A
connection attempt failed because the connected party did not properly
respond after a period of time, or established connection failed because
connected host has failed to respond.In a 160 seconds postgresql reported in logs
2021-04-29 02:42:41 database LOG: duration: 202590.129 ms statement:
COPY
"principal_reference" (id,"some_payload") FROM STDIN BINARY;
2021-04-29 02:42:41 database LOG: could not receive data from client: An
established connection was aborted by the software in your host machine.In our application code we retry operation, if something goes wrong. And
when we start retrying we've got an exception
2021-04-29 02:42:41 database ERROR: duplicate key value violates unique
constraint "PK_principal_reference_id"We didn't commit transaction. But copy done successfully and there is no
row
inserted at step 3.
Most likely, (1) never happened, so your application was actually running
(2)
as an implied transaction that did commit. One way to confirm this is to
set
log_statement=all and look for the BEGIN (or START TRANSACTION) command in
the
logs. What sequence of commands does the server log show from the session
that experiences the problem?Is there a workaround? Like a copy into temp table and then insert from
temp
table?
There probably would be a workaround, but if COPY results are visible
after a
transaction rollback, that would be a bug.
On Fri, Sep 17, 2021 at 02:13:43PM +0300, Дмитрий Секретов wrote:
It happens very rarely and it happens in production (2-3 times a year), i
can't log all. I look into code and we always start transaction. We have
tests - rollback works fine. But it happened.
A missing BEGIN is something like one hundred times as likely as a PostgreSQL
bug here. I understand you can't set log_statement=all in production. If you
do a non-production test with log_statement=all, you may be able to locate the
missing BEGIN.