9

I am running the transaction queries in code like this (simplified):

try {
    runQuery("begin");
    runQuery("some query ...");
    runQuery("some other query ...");
    runQuery("some more query ...");
    runQuery("some extra query ...");
    runQuery("commit");
} catch (e){
    runQuery("rollback");
}

Here is the list of statements from the postgres log file.
Notice that first begin / commit works fine and the second commit gives the error mentioned in the subject:

2015-02-18 20:19:17 UTC [6459-7] vdsr@sails LOG:  statement: begin
2015-02-18 20:19:17 UTC [6459-8] vdsr@sails LOG:  execute <unnamed>: INSERT INTO "groups" ("name", "parentGroupRef", "isCompany", "companyRef", "createdAt", "updatedAt") values ($1, $2, $3, $4, $5, $6) RETURNING *
2015-02-18 20:19:17 UTC [6459-9] vdsr@sails DETAIL:  parameters: $1 = 'testclient', $2 = '5', $3 = 't', $4 = '1', $5 = '2015-02-18 20:19:17+00', $6 = '2015-02-18 20:19:17+00'
2015-02-18 20:19:17 UTC [6459-10] vdsr@sails LOG:  execute <unnamed>: INSERT INTO "users" ("firstName", "lastName", "email", "companyRef", "isMainUser", "password", "middleName", "createdAt", "updatedAt") values ($1, $2, $3, $4, $5, $6, $7, $8, $9) RETURNING *
2015-02-18 20:19:17 UTC [6459-11] vdsr@sails DETAIL:  parameters: $1 = 'aa', $2 = 'bb', $3 = 'aa@bb.com', $4 = '18', $5 = 't', $6 = '06a8ec164adcc7db4edfb6ca20c07b20', $7 = '', $8 = '2015-02-18 20:19:17+00', $9 = '2015-02-18 20:19:17+00'
2015-02-18 20:19:17 UTC [6459-12] vdsr@sails LOG:  execute <unnamed>: INSERT INTO "roles" ("name", "companyRef", "createdAt", "updatedAt") values ($1, $2, $3, $4) RETURNING *
2015-02-18 20:19:17 UTC [6459-13] vdsr@sails DETAIL:  parameters: $1 = 'Master', $2 = '18', $3 = '2015-02-18 20:19:17+00', $4 = '2015-02-18 20:19:17+00'
2015-02-18 20:19:17 UTC [6459-14] vdsr@sails LOG:  execute <unnamed>: INSERT INTO "userroles" ("roleRef", "userRef", "createdAt", "updatedAt") values ($1, $2, $3, $4) RETURNING *
2015-02-18 20:19:17 UTC [6459-15] vdsr@sails DETAIL:  parameters: $1 = '11', $2 = '13', $3 = '2015-02-18 20:19:17+00', $4 = '2015-02-18 20:19:17+00'
2015-02-18 20:19:17 UTC [6459-16] vdsr@sails LOG:  execute <unnamed>: INSERT INTO "rolepermissions" ("roleRef", "permissionRef", "createdAt", "updatedAt") values ($1, $2, $3, $4) RETURNING *
2015-02-18 20:19:17 UTC [6459-17] vdsr@sails DETAIL:  parameters: $1 = '11', $2 = '24', $3 = '2015-02-18 20:19:17+00', $4 = '2015-02-18 20:19:17+00'
2015-02-18 20:19:17 UTC [6459-18] vdsr@sails LOG:  execute <unnamed>: INSERT INTO "rolepermissions" ("roleRef", "permissionRef", "createdAt", "updatedAt") values ($1, $2, $3, $4) RETURNING *
2015-02-18 20:19:17 UTC [6459-19] vdsr@sails DETAIL:  parameters: $1 = '11', $2 = '22', $3 = '2015-02-18 20:19:17+00', $4 = '2015-02-18 20:19:17+00'
2015-02-18 20:19:17 UTC [6459-20] vdsr@sails LOG:  execute <unnamed>: SELECT "groups"."name", "groups"."notes", "groups"."parentGroupRef", "groups"."isCompany", "groups"."hierPos", "groups"."companyRef", "groups"."id", "groups"."createdAt", "groups"."updatedAt" FROM "groups" AS "groups"  WHERE "groups"."companyRef" = $1 
2015-02-18 20:19:17 UTC [6459-21] vdsr@sails DETAIL:  parameters: $1 = '1'
2015-02-18 20:19:17 UTC [6461-1] vdsr@sails LOG:  statement:  update groups set "hierPos" = case id when 2 then '1' when 3 then '2' when 4 then '3' when 5 then '4' when 6 then '4.1' when 10 then '4.1.1' when 18 then '4.2' when 13 then '5' when 17 then '6' else "hierPos" end  where id in (2,3,4,5,6,10,18,13,17) 
2015-02-18 20:19:17 UTC [6459-22] vdsr@sails LOG:  statement: commit
2015-02-18 20:26:08 UTC [6477-1] vdsr@sails LOG:  execute <unnamed>: SELECT "users"."firstName", "users"."middleName", "users"."lastName", "users"."email", "users"."password", "users"."resetKey", "users"."resetKeyGeneratedAt", "users"."isMainUser", "users"."companyRef", "users"."id", "users"."createdAt", "users"."updatedAt" FROM "users" AS "users"  WHERE "users"."id" = $1  LIMIT 1
2015-02-18 20:26:08 UTC [6477-2] vdsr@sails DETAIL:  parameters: $1 = '8'
2015-02-18 20:26:08 UTC [6477-3] vdsr@sails LOG:  execute <unnamed>: select p.name from permissions p  inner join rolepermissions rp on rp."permissionRef" = p.id   inner join roles r on r.id = rp."roleRef"  inner join userroles ur on ur."roleRef" = r.id  where ur."userRef" = $1
2015-02-18 20:26:08 UTC [6477-4] vdsr@sails DETAIL:  parameters: $1 = '8'
2015-02-18 20:26:08 UTC [6477-5] vdsr@sails LOG:  statement: begin
2015-02-18 20:26:08 UTC [6477-6] vdsr@sails LOG:  execute <unnamed>: INSERT INTO "groups" ("name", "isCompany", "parentGroupRef", "companyRef", "createdAt", "updatedAt") values ($1, $2, $3, $4, $5, $6) RETURNING *
2015-02-18 20:26:08 UTC [6477-7] vdsr@sails DETAIL:  parameters: $1 = 'ddffdfd', $2 = 't', $3 = '1', $4 = '1', $5 = '2015-02-18 20:26:08+00', $6 = '2015-02-18 20:26:08+00'
2015-02-18 20:26:08 UTC [6477-8] vdsr@sails LOG:  execute <unnamed>: INSERT INTO "users" ("firstName", "lastName", "email", "companyRef", "isMainUser", "password", "middleName", "createdAt", "updatedAt") values ($1, $2, $3, $4, $5, $6, $7, $8, $9) RETURNING *
2015-02-18 20:26:08 UTC [6477-9] vdsr@sails DETAIL:  parameters: $1 = 'fdfd', $2 = 'fdfd', $3 = 'fdf@df.com', $4 = '19', $5 = 't', $6 = '7b9e87b1795e4d96bf9fbb898fa669fe', $7 = '', $8 = '2015-02-18 20:26:08+00', $9 = '2015-02-18 20:26:08+00'
2015-02-18 20:26:08 UTC [6477-10] vdsr@sails LOG:  execute <unnamed>: INSERT INTO "roles" ("name", "companyRef", "createdAt", "updatedAt") values ($1, $2, $3, $4) RETURNING *
2015-02-18 20:26:08 UTC [6477-11] vdsr@sails DETAIL:  parameters: $1 = 'Master', $2 = '19', $3 = '2015-02-18 20:26:08+00', $4 = '2015-02-18 20:26:08+00'
2015-02-18 20:26:08 UTC [6477-12] vdsr@sails LOG:  execute <unnamed>: INSERT INTO "userroles" ("roleRef", "userRef", "createdAt", "updatedAt") values ($1, $2, $3, $4) RETURNING *
2015-02-18 20:26:08 UTC [6477-13] vdsr@sails DETAIL:  parameters: $1 = '12', $2 = '14', $3 = '2015-02-18 20:26:08+00', $4 = '2015-02-18 20:26:08+00'
2015-02-18 20:26:08 UTC [6477-14] vdsr@sails LOG:  execute <unnamed>: INSERT INTO "rolepermissions" ("roleRef", "permissionRef", "createdAt", "updatedAt") values ($1, $2, $3, $4) RETURNING *
2015-02-18 20:26:08 UTC [6477-15] vdsr@sails DETAIL:  parameters: $1 = '12', $2 = '24', $3 = '2015-02-18 20:26:08+00', $4 = '2015-02-18 20:26:08+00'
2015-02-18 20:26:08 UTC [6477-16] vdsr@sails LOG:  execute <unnamed>: INSERT INTO "rolepermissions" ("roleRef", "permissionRef", "createdAt", "updatedAt") values ($1, $2, $3, $4) RETURNING *
2015-02-18 20:26:08 UTC [6477-17] vdsr@sails DETAIL:  parameters: $1 = '12', $2 = '22', $3 = '2015-02-18 20:26:08+00', $4 = '2015-02-18 20:26:08+00'
2015-02-18 20:26:08 UTC [6477-18] vdsr@sails LOG:  execute <unnamed>: INSERT INTO "rolepermissions" ("roleRef", "permissionRef", "createdAt", "updatedAt") values ($1, $2, $3, $4) RETURNING *
2015-02-18 20:26:08 UTC [6477-19] vdsr@sails DETAIL:  parameters: $1 = '12', $2 = '23', $3 = '2015-02-18 20:26:08+00', $4 = '2015-02-18 20:26:08+00'
2015-02-18 20:26:08 UTC [6477-20] vdsr@sails LOG:  execute <unnamed>: SELECT "groups"."name", "groups"."notes", "groups"."parentGroupRef", "groups"."isCompany", "groups"."hierPos", "groups"."companyRef", "groups"."id", "groups"."createdAt", "groups"."updatedAt" FROM "groups" AS "groups"  WHERE "groups"."companyRef" = $1 
2015-02-18 20:26:08 UTC [6477-21] vdsr@sails DETAIL:  parameters: $1 = '1'
2015-02-18 20:26:08 UTC [6478-1] vdsr@sails LOG:  statement:  update groups set "hierPos" = case id when 2 then '1' when 3 then '2' when 4 then '3' when 5 then '4' when 6 then '4.1' when 10 then '4.1.1' when 18 then '4.2' when 13 then '5' when 17 then '6' when 19 then '7' else "hierPos" end  where id in (2,3,4,5,6,10,18,13,17,19) 
2015-02-18 20:26:08 UTC [6479-1] vdsr@sails LOG:  statement: commit
2015-02-18 20:26:08 UTC [6479-2] vdsr@sails WARNING:  there is no transaction in progress
Erwin Brandstetter
  • 605,456
  • 145
  • 1,078
  • 1,228
Nihat
  • 3,055
  • 3
  • 18
  • 28
  • Thats why: http://www.postgresql.org/docs/9.1/static/sql-start-transaction.html – Jorge Campos Feb 18 '15 at 21:01
  • Nothing over there explains it. I have already read the 9.3 manuals regarding transaction. Also, begin is equal to start transaction in Postgres, if that is what you are getting into. – Nihat Feb 18 '15 at 21:04
  • This part: `In the standard, it is not necessary to issue START TRANSACTION to start a transaction block: any SQL command implicitly begins a block. PostgreSQL's behavior can be seen as implicitly issuing a COMMIT after each command that does not follow START TRANSACTION (or BEGIN), and it is therefore often called "autocommit". Other relational database systems might offer an autocommit feature as a convenience.` – Jorge Campos Feb 18 '15 at 21:05
  • so, you don't need your commit command. Once the operation is finished it will be commited unless you have set the connection to autocommit false – Jorge Campos Feb 18 '15 at 21:06
  • I don't need commit command? I don't understand. I am running a transaction (list of statements that I want to be executed altogether or not executed at all) so I must have a begin and commit. – Nihat Feb 18 '15 at 21:09
  • Maybe you're hitting the "Execute pgScript" intead of "Execute Query" in pgAdminIII query editor? – Christian Feb 18 '15 at 21:10
  • I am not running it via pgAdmin, These queries are run by node based app and these are the logs generated by the postgres. – Nihat Feb 18 '15 at 21:12
  • @JorgeCampos I don't want each query to be independently committed right afterwards. So, that is why, I must issue begin command explicitly to tell postgres that it should not commit until it sees a commit command so that group of statements between begin and commit can be committed / rolled back together. If any of those queries between begin and commit failed, my code in the node app would issue a rollback. – Nihat Feb 18 '15 at 21:19
  • You said that this commads are running in a node based app which means that this app should control the transactions not your pgplsql code. Maybe it is issuing the warning because you are running the commit command and the app transaction is trying to commit therefore the warning. – Jorge Campos Feb 18 '15 at 23:10

2 Answers2

13

This seems to be a misunderstanding. Consider my bold emphasis:

[6459-7] vdsr@sails LOG: statement: begin
[6459-8] vdsr@sails LOG: execute : INSERT INTO "groups" ("name", "parentGroupRef", "isCompany", "companyRef", "createdAt", "updatedAt") values ($1, $2, $3, $4, $5, $6) RETURNING *
...
[6459-22] vdsr@sails LOG: statement: commit
...
[6477-5] vdsr@sails LOG: statement: begin
[6477-6] vdsr@sails LOG: execute : INSERT INTO "groups" ("name", "isCompany", "parentGroupRef", "companyRef", "createdAt", "updatedAt") values ($1, $2, $3, $4, $5, $6) RETURNING *
...
[6479-1] vdsr@sails LOG: statement: commit
[6479-2] vdsr@sails WARNING: there is no transaction in progress

The WARNING obviously belongs to a different concurrent transaction, which did not start an explicit transaction. The commit is misplaced there, since it's operating in autocommit mode.

If you keep reading your log, you will probably find an entry for the commit further down:

[6477-??] vdsr@sails LOG: statement: commit

Debug

If you find neither that nor a rollback entry nor an error, I would check for problems in your app leaving uncommitted zombi transactions, which would be a bad thing.

Start the investigation by checking the system view pg_stat_activity while connected to your database:

SELECT *
FROM   pg_stat_activity
WHERE  datname = current_database()  -- only current database
AND    pid <> pg_backend_pid()       -- except your current session
AND    state LIKE 'idle%';

The state value idle is not necessarily suspicious - just a session that's waiting for input.
But idle in transaction and idle in transaction (aborted) are.

More in the manual here or these related answers:

Erwin Brandstetter
  • 605,456
  • 145
  • 1,078
  • 1,228
  • Hi. I am not sure if there was any differeny concurrent transaction. I am on a my local development computer and am pretty sure there was no other transactions happening. In fact, I just pasted all the logs from the time the postgres started in here in full with session ids this time ( https://bpaste.net/show/06bb02e11cba ). You will see that there is only one start transaction and one commit and there is no other commit further down (the log file is pasted in its entirety). You will see that warning again after the commit at the end of the log – Nihat Feb 19 '15 at 13:56
  • @Nihat: There is a *single* warning in your log, the one I quoted. Anyway, turns out it *was* a different transaction, just not concurrent. The behaviour of your client needs to be fixed of course. I would also check whether that leaves the uncommitted transactions in limbo. I added pointers how to debug. – Erwin Brandstetter Feb 19 '15 at 22:45
1

This is caused by the sails-postgresql node module I am using. It is causing a new session to be created in the middle of my transaction queries and so the commit query was being issued by a different session. That was causing the warning.

Nihat
  • 3,055
  • 3
  • 18
  • 28