Summary
Activity
Forums
Tracker
Lists
Tasks
Docs
Surveys
News
SCM
Files

[#1011310] Command timeouts after the first are not handled

View Trackers | Bugs | Download .csv | Monitor

Date:
2013-02-21 14:32		 Priority:
3
State:
Open
Submitted by:
Evan Martin (realityexists) 		Assigned to:
Nobody (None)
Npgsql Version:
2.0.12beta		 Category:
None
Group:
None		 Resolution:
None
Summary:
Command timeouts after the first are not handled

Detailed description
2.0.12 final version

When a command inside a transaction times out the caller may roll back to a savepoint and try again. This works OK the first time. The second time it appears to work, but the rollback takes a long time. On the third attempt the command returns an empty result set. The attached console app reproduces the problem.

On investigation, it appears that Npgsql is not cancelling any command after the first, once NpgsqlConnector.CancelRequestCalled is true.

More detail:

Set up a transaction and create a savepoint:
2013-02-21 23:14:26 EST LOG: statement: BEGIN; SET TRANSACTION ISOLATION LEVEL READ COMMITTED;
2013-02-21 23:14:26 EST LOG: statement: SAVEPOINT ExecuteScalarWithRetry

Try running a command with a short timeout:
2013-02-21 23:14:26 EST LOG: statement: SELECT 'Attempt 1' FROM pg_sleep(((3)))

After the timeout expires Npgsql sends a "cancel request" to the server
2013-02-21 23:14:27 EST ERROR: canceling statement due to user request
2013-02-21 23:14:27 EST STATEMENT: SELECT 'Attempt 1' FROM pg_sleep(((3)))

The first timeout is processed correctly - the command is cancelled. The client then rolls back to the savepoint and tries the command again:
2013-02-21 23:14:27 EST LOG: statement: ROLLBACK TO SAVEPOINT ExecuteScalarWithRetry
2013-02-21 23:14:27 EST LOG: statement: SELECT 'Attempt 2' FROM pg_sleep(((3)))

The command again times out from the client's point of view, but Npgsql does not send another "cancel request", so it actually continues exucuting on the server. The client, blissfully unaware of this, sends a rollback command:
2013-02-21 23:14:30 EST LOG: statement: ROLLBACK TO SAVEPOINT ExecuteScalarWithRetry

That rollback command takes an unusually long time. When the server returns it actually returns the response for the previous command ("SELECT 'Attempt 2'"), but the client thinks it's for the rollback and ignores it.

The client then tries the command a third time:
2013-02-21 23:14:30 EST LOG: statement: SELECT 'Attempt 3' FROM pg_sleep(((3)))

The server immediately returns a response, but it's the response for the previous rollback command, which the client doesn't expect.

Followup

Message
Date: 2013-02-27 13:19
Sender: Evan Martin

Thanks. I cannot test it, because getting the source from CVS fails with this error:

cvs [login aborted]: end of file from server (consult above messages if any)

I'll just take your word for it that the patch is applied. :)
Date: 2013-02-27 13:07
Sender: Francisco Figueiredo jr.

Patch 1011311 applied.

Thank you very much, Evan Martin for your help and support to solve this problem.

Please, give it a try and let me know if it is ok.

Attached Files:

Attachments:
NpgsqlTest.zip

Changes:

Field Old Value Date By
File Added793: NpgsqlTest.zip2013-02-21 14:32realityexists
Powered By FusionForge