php.net |  support |  documentation |  report a bug |  advanced search |  search howto |  statistics |  random bug |  login
Bug #49985 pdo_pgsql prepare() re-use previous aborted transaction
Submitted: 2009-10-24 12:47 UTC Modified: 2009-10-26 02:02 UTC
From: ben dot pineau at gmail dot com Assigned:
Status: Closed Package: PDO related
PHP Version: 5.2.11 OS: Linux
Private report: No CVE-ID:
 [2009-10-24 12:47 UTC] ben dot pineau at gmail dot com
Description:
------------
When prepar()ing a statement in a separate function, pdo_pgsql behaves as if we hadn't rollbacked and started a new transaction.

But no such problem when either :
- we use another pdo driver (tested with sqlite)
- prepare() call is inlined in the same code block as beginTransaction (rather than in a distinct function)
- the function contains a straigth "query()" instead of prepare() + execute()

Reproduced with both php-5.2.6 and php-5.2.11, PostgreSQL 8.3.8.


Reproduce code:
---------------
/*
 * CREATE TABLE test (a SERIAL PRIMARY KEY);
 * INSERT INTO test VALUES (1);
 */

$cnx = new PDO('pgsql:dbname=testbase;host=localhost', 'postgres','');
$cnx->setAttribute(PDO::ATTR_ERRMODE, PDO::ERRMODE_EXCEPTION);

$sql = "INSERT INTO test (a) VALUES (1)";

function prepare_and_exec_query(&$pdo, $sql)
{
    $stmt = $pdo->prepare($sql);
    $stmt->execute();
}

for ($i = 0; $i < 3; $i++) {
    try {
        $cnx->beginTransaction();
        prepare_and_exec_query($cnx, $sql);
        $cnx->commit();
    } catch (Exception $e) {
        echo "Error: " . $e->getMessage() . "\n";
        if (true === $cnx->rollback()) echo "rollbacked ok\n";
    }
}


Expected result:
----------------
Error: SQLSTATE[23505]: Unique violation: 7 ERROR:  duplicate key value violates unique constraint "test_pkey"
rollbacked ok
Error: SQLSTATE[23505]: Unique violation: 7 ERROR:  duplicate key value violates unique constraint "test_pkey"
rollbacked ok
Error: SQLSTATE[23505]: Unique violation: 7 ERROR:  duplicate key value violates unique constraint "test_pkey"
rollbacked ok

Actual result:
--------------
Error: SQLSTATE[23505]: Unique violation: 7 ERROR:  duplicate key value violates unique constraint "test_pkey"
rollbacked ok
Error: SQLSTATE[25P02]: In failed sql transaction: 7 ERROR:  current transaction is aborted, commands ignored until end of transaction block
rollbacked ok
Error: SQLSTATE[25P02]: In failed sql transaction: 7 ERROR:  current transaction is aborted, commands ignored until end of transaction block
rollbacked ok

Patches

Add a Patch

Pull Requests

Add a Pull Request

History

AllCommentsChangesGit/SVN commitsRelated reports
 [2009-10-24 15:17 UTC] ben dot pineau at gmail dot com
Look at the PostgreSQL logs above (running the provided test case
with log_statement='all' and log_min_messages='INFO'), keeping
in mind that:
- PostgreSQL automatically abort transactions when something fails.
- PostgreSQL does maintains prepared statements outside transaction
  context. Prepared statements survive a rollback/abort, and last
  for the duration of the current database session.
- It seems that when executed in another function/context than 
  PDO::beginTransaction, PDO tries to DEALLOCATE right after the
  first transaction failure (vs. after the next BEGIN statement
  when in same context).

Therefore we have the following flow:

BEGIN;
  -- PDO successfully prepare the statement
  PREPARE prep_statement_1 AS ...;

  -- We execute a bogus statement that cause pg to automatically
  -- abort the current transaction. PDO raise a proper exception
  EXECUTE prep_statement_1;

  -- This fails because we're in aborted transaction;
  -- The prepared statement is thus left allocated.
  DEALLOCATE prep_statement_1;
ROLLBACK;

-- And then we loop with
BEGIN;
  -- This prep statement already exists (PDO failed to clean it)
  -- so this fails and pg automatically abort this new transaction.
  PREPARE prep_statement_1 AS ...;

  -- Given the above failure, PDO tries again to clean up the
  -- prepared stmt which will fail again.
  -- Hence PDO raising a "current transaction is aborted" exception.
  DEALLOCATE prep_statement_1;
ROLLBACK;


Surprisingly, when we call prepare() inline like this:
    try {
        $cnx->beginTransaction();
        $stmt = $cnx->prepare($sql);
        $stmt->execute();

instead of that :

    function qexec(&$pdo, $sql) {
        $stmt = $pdo->prepare($sql);
        $stmt->execute();
    }
    try {
        $cnx->beginTransaction();
        qexec($cnx, $sql);

we do get a different (and preferable) behaviour:
BEGIN -> PREPARE -> EXECUTE -> ROLLBACK
  -> BEGIN -> DEALLOCATE -> PREPARE -> EXECUTE -> ROLLBACK
  -> BEGIN -> DEALLOCATE -> PREPARE -> EXECUTE -> ROLLBACK -> ...

vs.
BEGIN -> PREPARE -> EXECUTE -> DEALLOCATE -> ROLLBACK
  -> BEGIN -> PREPARE (-> EXECUTE) -> DEALLOCATE -> ROLLBACK
  -> BEGIN -> PREPARE (-> EXECUTE) -> DEALLOCATE -> ROLLBACK -> ...


Granted, preparing the same exact statement in loop (rather than
once then using varying parameters) is dumb, but...

PostgreSQL logs from the provided test case:
Oct 24 15:29:15 dev postgres[26864]: [5-1] LOG:  statement: BEGIN
Oct 24 15:29:15 dev postgres[26864]: [6-1] LOG:  execute pdo_pgsql_stmt_01ef7698: INSERT INTO test (a) VALUES (1)
Oct 24 15:29:15 dev postgres[26864]: [7-1] ERROR:  duplicate key value violates unique constraint "test_pkey"
Oct 24 15:29:15 dev postgres[26864]: [7-2] STATEMENT:  INSERT INTO test (a) VALUES (1)
Oct 24 15:29:15 dev postgres[26864]: [8-1] LOG:  statement: DEALLOCATE pdo_pgsql_stmt_01ef7698
Oct 24 15:29:15 dev postgres[26864]: [9-1] ERROR:  current transaction is aborted, commands ignored until end of transaction block
Oct 24 15:29:15 dev postgres[26864]: [9-2] STATEMENT:  DEALLOCATE pdo_pgsql_stmt_01ef7698
Oct 24 15:29:15 dev postgres[26864]: [10-1] LOG:  statement: ROLLBACK
Oct 24 15:29:15 dev postgres[26864]: [11-1] LOG:  statement: BEGIN
Oct 24 15:29:15 dev postgres[26864]: [12-1] ERROR:  prepared statement "pdo_pgsql_stmt_01ef7698" already exists
Oct 24 15:29:15 dev postgres[26864]: [12-2] STATEMENT:  INSERT INTO test (a) VALUES (1)
Oct 24 15:29:15 dev postgres[26864]: [13-1] LOG:  statement: DEALLOCATE pdo_pgsql_stmt_01ef7698
Oct 24 15:29:15 dev postgres[26864]: [14-1] ERROR:  current transaction is aborted, commands ignored until end of transaction block
Oct 24 15:29:15 dev postgres[26864]: [14-2] STATEMENT:  DEALLOCATE pdo_pgsql_stmt_01ef7698
Oct 24 15:29:15 dev postgres[26864]: [15-1] ERROR:  current transaction is aborted, commands ignored until end of transaction block
Oct 24 15:29:15 dev postgres[26864]: [15-2] STATEMENT:  INSERT INTO test (a) VALUES (1)
Oct 24 15:29:15 dev postgres[26864]: [16-1] LOG:  statement: ROLLBACK
Oct 24 15:29:15 dev postgres[26864]: [17-1] LOG:  statement: BEGIN
Oct 24 15:29:15 dev postgres[26864]: [18-1] ERROR:  prepared statement "pdo_pgsql_stmt_01ef7698" already exists
Oct 24 15:29:15 dev postgres[26864]: [18-2] STATEMENT:  INSERT INTO test (a) VALUES (1)
Oct 24 15:29:15 dev postgres[26864]: [19-1] LOG:  statement: DEALLOCATE pdo_pgsql_stmt_01ef7698
Oct 24 15:29:15 dev postgres[26864]: [20-1] ERROR:  current transaction is aborted, commands ignored until end of transaction block
Oct 24 15:29:15 dev postgres[26864]: [20-2] STATEMENT:  DEALLOCATE pdo_pgsql_stmt_01ef7698
Oct 24 15:29:15 dev postgres[26864]: [21-1] ERROR:  current transaction is aborted, commands ignored until end of transaction block
Oct 24 15:29:15 dev postgres[26864]: [21-2] STATEMENT:  INSERT INTO test (a) VALUES (1)
Oct 24 15:29:15 dev postgres[26864]: [22-1] LOG:  statement: ROLLBACK
 [2009-10-25 14:22 UTC] ben dot pineau at gmail dot com
About the difference when running prepare+execute in a separate
function: we just get the same stmt pointer address in this case
(vs. a different pointer address when running everything in the 
same context). Thus stmt_name remains identical among successive
calls, stmt_name being just set as
spprintf(&S->stmt_name, 0, "pdo_pgsql_stmt_%08x", (unsigned int)stmt);
This explains why prepare() fails in the first case and succeed
in the other.

Anyway, here is a patch (against PHP_5_2 svn branch's head as of now) 
using savepoints around PQprepare attempts so we DEALLOCATE + retry 
without silently killing the current transaction, if/when the first 
prepare fails with code 42P05. 

Savepoints support started with pg 8.0 and I didn't ifdefed/autoconf
checked for this (will do if you ask); the patch will probably be
mangled by the bugrackers autowrapping (if so, please find a copy
at http://zouh.org/ben/various/pgsql_statement.c.diff ).

Index: pgsql_statement.c
===================================================================
--- pgsql_statement.c   (revision 289910)
+++ pgsql_statement.c   (working copy)
@@ -134,6 +134,14 @@
                /* using a prepared statement */

                if (!S->is_prepared) {
+                       /* don't break the whole current transaction when the first
+                        * prepare tentative fails (happens when the prepared statement
+                        * already exists). ignore those SAVEPOINT queries results because 
+                        * we don't care (may be outside transaction?).
+                        */
+                       char buf[100]; /* stmt_name == "pdo_pgsql_cursor_%08x" */
+                       snprintf(buf, sizeof(buf), "SAVEPOINT %s", S->stmt_name);
+                       PQexec(H->server, buf);
 stmt_retry:
                        /* we deferred the prepare until now, because we didn't
                         * know anything about the parameter types; now we do */
@@ -153,12 +161,14 @@
                                        /* 42P05 means that the prepared statement already existed. this can happen if you use
                                         * a connection pooling software line pgpool which doesn't close the db-connection once
                                         * php disconnects. if php dies (no chance to run RSHUTDOWN) during execution it has no
-                                        * chance to DEALLOCATE the prepared statements it has created. so, if we hit a 42P05 we 
-                                        * deallocate it and retry ONCE (thies 2005.12.15)
+                                        * chance to DEALLOCATE the prepared statements it has created. Also happens if we tried
+                                        * to DEALLOCATE the same statement name in an aborted transaction. so, if we hit a 42P05
+                                        * we deallocate it and retry ONCE (thies 2005.12.15)
                                         */
                                        if (!strcmp(sqlstate, "42P05")) {
-                                               char buf[100]; /* stmt_name == "pdo_pgsql_cursor_%08x" */
                                                PGresult *res;
+                                               snprintf(buf, sizeof(buf), "ROLLBACK TO SAVEPOINT %s", S->stmt_name);
+                                               PQexec(H->server, buf);
                                                snprintf(buf, sizeof(buf), "DEALLOCATE %s", S->stmt_name);
                                                res = PQexec(H->server, buf);
                                                if (res) {
@@ -166,11 +176,15 @@
                                                }
                                                goto stmt_retry;
                                        } else {
+                                               snprintf(buf, sizeof(buf), "RELEASE SAVEPOINT %s", S->stmt_name);
+                                               PQexec(H->server, buf);
                                                pdo_pgsql_error_stmt(stmt, status, sqlstate);
                                                return 0;
                                        }
                                }
                        }
+                       snprintf(buf, sizeof(buf), "RELEASE SAVEPOINT %s", S->stmt_name);
+                       PQexec(H->server, buf);
                }
                S->result = PQexecPrepared(H->server, S->stmt_name,
                                stmt->bound_params ?
 [2009-10-26 02:02 UTC] svn@php.net
Automatic comment from SVN on behalf of iliaa
Revision: http://svn.php.net/viewvc/?view=revision&revision=289924
Log: - Fixed bug #49985 (pdo_pgsql prepare() re-use previous aborted transaction).
 [2009-10-26 02:02 UTC] iliaa@php.net
This bug has been fixed in SVN.

Snapshots of the sources are packaged every three hours; this change
will be in the next snapshot. You can grab the snapshot at
http://snaps.php.net/.
 
Thank you for the report, and for helping us make PHP better.


 [2009-11-04 19:16 UTC] svn@php.net
Automatic comment from SVN on behalf of mbeccati
Revision: http://svn.php.net/viewvc/?view=revision&revision=290212
Log: - Reverting previous fix for bug #49985
# Unmerged changes from revision 289924
 [2009-11-04 19:32 UTC] svn@php.net
Automatic comment from SVN on behalf of mbeccati
Revision: http://svn.php.net/viewvc/?view=revision&revision=290214
Log: - Properly fixed bug #49985 (pdo_pgsql prepare() re-use previous aborted transaction).
# Removed usage of the memory address when generating prepared statemend names
# as uniqueness can't be enforced. Used a statment counter instead.
 
PHP Copyright © 2001-2014 The PHP Group
All rights reserved.
Last updated: Sat Apr 19 09:02:28 2014 UTC