Possible transaction bug with isolation level serialisable?

Hi,

Two concurrent transaction first check if a certain value is listed in a table and if not try to insert it. As the value inserted hasto be unique and both try to enter the same one, one transaction fails reporting that the value is already part of the table. As both are executed within a transaction with isolation level SERIALIZABLE I would have expected that one of them would return with a serialization failure, which my program would have been ready to handle and re-execute the transaction.

The reason I think something is fishy is, because I find the behaviour is somehow similar to a nonrepeatable read which should not occur with this transaction level. The

SELECT "userRef" FROM "VerifyQueue" WHERE lower("email")=lower($1)

reports, that the value is NOT in the table, thus the program then tries to insert it, and at that point the value is shown as being in the table.

So is this a bug, or did I misunderstand something?

This is with version 9.3.4 of PostgreSQL.

$ psql --version; postgres --version; uname -a
psql (PostgreSQL) 9.3.4
postgres (PostgreSQL) 9.3.4
Darwin Claudios-MacBook-Pro.local 13.1.0 Darwin Kernel Version 13.1.0: Wed Apr 2 23:52:02 PDT 2014; root:xnu-2422.92.1~2/RELEASE_X86_64 x86_64

Here all the lines from the log file concerning the two transactions.

2014-04-23 23:58:48 CEST [63576]: [1-1] user=[unknown],db=[unknown] LOG: connection received: host=127.0.0.1 port=62251
2014-04-23 23:58:48 CEST [63584]: [1-1] user=[unknown],db=[unknown] LOG: connection received: host=127.0.0.1 port=62259
2014-04-23 23:58:48 CEST [63584]: [2-1] user=reslist,db=reslist LOG: connection authorized: user=reslist database=reslist
2014-04-23 23:58:48 CEST [63584]: [3-1] user=reslist,db=reslist LOG: duration: 0.210 ms parse <unnamed>: SET extra_float_digits = 3
2014-04-23 23:58:48 CEST [63584]: [4-1] user=reslist,db=reslist LOG: duration: 0.021 ms bind <unnamed>: SET extra_float_digits = 3
2014-04-23 23:58:48 CEST [63584]: [5-1] user=reslist,db=reslist LOG: duration: 0.012 ms execute <unnamed>: SET extra_float_digits = 3
2014-04-23 23:58:48 CEST [63576]: [2-1] user=reslist,db=reslist LOG: connection authorized: user=reslist database=reslist
2014-04-23 23:58:48 CEST [63584]: [6-1] user=reslist,db=reslist LOG: duration: 0.051 ms parse <unnamed>: SET SESSION CHARACTERISTICS AS TRANSACTION ISOLATION LEVEL SERIALIZABLE
2014-04-23 23:58:48 CEST [63584]: [7-1] user=reslist,db=reslist LOG: duration: 0.007 ms bind <unnamed>: SET SESSION CHARACTERISTICS AS TRANSACTION ISOLATION LEVEL SERIALIZABLE
2014-04-23 23:58:48 CEST [63584]: [8-1] user=reslist,db=reslist LOG: duration: 0.009 ms execute <unnamed>: SET SESSION CHARACTERISTICS AS TRANSACTION ISOLATION LEVEL SERIALIZABLE
2014-04-23 23:58:48 CEST [63584]: [9-1] user=reslist,db=reslist LOG: duration: 0.025 ms parse <unnamed>: BEGIN
2014-04-23 23:58:48 CEST [63584]: [10-1] user=reslist,db=reslist LOG: duration: 0.005 ms bind <unnamed>: BEGIN
2014-04-23 23:58:48 CEST [63584]: [11-1] user=reslist,db=reslist LOG: duration: 0.006 ms execute <unnamed>: BEGIN
2014-04-23 23:58:48 CEST [63584]: [12-1] user=reslist,db=reslist LOG: duration: 1.370 ms parse <unnamed>: SELECT "id" FROM "User" WHERE "nick"=$1 AND "deleted" IS NULL
2014-04-23 23:58:48 CEST [63576]: [3-1] user=reslist,db=reslist LOG: duration: 0.224 ms parse <unnamed>: SET extra_float_digits = 3
2014-04-23 23:58:48 CEST [63576]: [4-1] user=reslist,db=reslist LOG: duration: 0.024 ms bind <unnamed>: SET extra_float_digits = 3
2014-04-23 23:58:48 CEST [63576]: [5-1] user=reslist,db=reslist LOG: duration: 0.015 ms execute <unnamed>: SET extra_float_digits = 3
2014-04-23 23:58:48 CEST [63576]: [6-1] user=reslist,db=reslist LOG: duration: 0.037 ms parse <unnamed>: SET SESSION CHARACTERISTICS AS TRANSACTION ISOLATION LEVEL SERIALIZABLE
2014-04-23 23:58:48 CEST [63576]: [7-1] user=reslist,db=reslist LOG: duration: 0.006 ms bind <unnamed>: SET SESSION CHARACTERISTICS AS TRANSACTION ISOLATION LEVEL SERIALIZABLE
2014-04-23 23:58:48 CEST [63576]: [8-1] user=reslist,db=reslist LOG: duration: 0.009 ms execute <unnamed>: SET SESSION CHARACTERISTICS AS TRANSACTION ISOLATION LEVEL SERIALIZABLE
2014-04-23 23:58:48 CEST [63584]: [13-1] user=reslist,db=reslist LOG: duration: 0.684 ms bind <unnamed>: SELECT "id" FROM "User" WHERE "nick"=$1 AND "deleted" IS NULL
2014-04-23 23:58:48 CEST [63584]: [14-1] user=reslist,db=reslist DETAIL: parameters: $1 = 'silberbatzen'
2014-04-23 23:58:48 CEST [63584]: [15-1] user=reslist,db=reslist LOG: duration: 0.024 ms execute <unnamed>: SELECT "id" FROM "User" WHERE "nick"=$1 AND "deleted" IS NULL
2014-04-23 23:58:48 CEST [63584]: [16-1] user=reslist,db=reslist DETAIL: parameters: $1 = 'silberbatzen'
2014-04-23 23:58:48 CEST [63576]: [9-1] user=reslist,db=reslist LOG: duration: 0.026 ms parse <unnamed>: BEGIN
2014-04-23 23:58:48 CEST [63576]: [10-1] user=reslist,db=reslist LOG: duration: 0.005 ms bind <unnamed>: BEGIN
2014-04-23 23:58:48 CEST [63576]: [11-1] user=reslist,db=reslist LOG: duration: 0.007 ms execute <unnamed>: BEGIN
2014-04-23 23:58:48 CEST [63584]: [17-1] user=reslist,db=reslist LOG: duration: 0.227 ms parse <unnamed>: SELECT "userRef" FROM "VerifyQueue" WHERE lower("email")=lower($1)
2014-04-23 23:58:48 CEST [63584]: [18-1] user=reslist,db=reslist LOG: duration: 0.265 ms bind <unnamed>: SELECT "userRef" FROM "VerifyQueue" WHERE lower("email")=lower($1)
2014-04-23 23:58:48 CEST [63584]: [19-1] user=reslist,db=reslist DETAIL: parameters: $1 = 'silberbatzen(at)gmail(dot)com'
2014-04-23 23:58:48 CEST [63584]: [20-1] user=reslist,db=reslist LOG: duration: 0.014 ms execute <unnamed>: SELECT "userRef" FROM "VerifyQueue" WHERE lower("email")=lower($1)
2014-04-23 23:58:48 CEST [63584]: [21-1] user=reslist,db=reslist DETAIL: parameters: $1 = 'silberbatzen(at)gmail(dot)com'
2014-04-23 23:58:48 CEST [63584]: [22-1] user=reslist,db=reslist LOG: duration: 0.258 ms parse <unnamed>: SELECT "User"."id","User"."nick","User"."address","User"."givenname","User"."surname","User"."email","User"."newmailNotification","User"."realnameVisible","User"."language","User"."last_login","User"."creationTime","User"."deleted","Host"."name","Service"."name","User"."password","User"."salt" FROM "User" INNER JOIN "Host" ON "User"."hostRef"="Host"."id" INNER JOIN "Service" ON "Host"."serviceRef"="Service"."id" WHERE lower("email")=lower($1)
2014-04-23 23:58:48 CEST [63576]: [12-1] user=reslist,db=reslist LOG: duration: 1.241 ms parse <unnamed>: SELECT "id" FROM "User" WHERE "nick"=$1 AND "deleted" IS NULL
2014-04-23 23:58:48 CEST [63584]: [23-1] user=reslist,db=reslist LOG: duration: 0.434 ms bind <unnamed>: SELECT "User"."id","User"."nick","User"."address","User"."givenname","User"."surname","User"."email","User"."newmailNotification","User"."realnameVisible","User"."language","User"."last_login","User"."creationTime","User"."deleted","Host"."name","Service"."name","User"."password","User"."salt" FROM "User" INNER JOIN "Host" ON "User"."hostRef"="Host"."id" INNER JOIN "Service" ON "Host"."serviceRef"="Service"."id" WHERE lower("email")=lower($1)
2014-04-23 23:58:48 CEST [63584]: [24-1] user=reslist,db=reslist DETAIL: parameters: $1 = 'silberbatzen(at)gmail(dot)com'
2014-04-23 23:58:48 CEST [63584]: [25-1] user=reslist,db=reslist LOG: duration: 0.015 ms execute <unnamed>: SELECT "User"."id","User"."nick","User"."address","User"."givenname","User"."surname","User"."email","User"."newmailNotification","User"."realnameVisible","User"."language","User"."last_login","User"."creationTime","User"."deleted","Host"."name","Service"."name","User"."password","User"."salt" FROM "User" INNER JOIN "Host" ON "User"."hostRef"="Host"."id" INNER JOIN "Service" ON "Host"."serviceRef"="Service"."id" WHERE lower("email")=lower($1)
2014-04-23 23:58:48 CEST [63584]: [26-1] user=reslist,db=reslist DETAIL: parameters: $1 = 'silberbatzen(at)gmail(dot)com'
2014-04-23 23:58:48 CEST [63584]: [27-1] user=reslist,db=reslist LOG: duration: 0.046 ms parse <unnamed>: SELECT "id" FROM "Host" WHERE "name"=$1
2014-04-23 23:58:48 CEST [63584]: [28-1] user=reslist,db=reslist LOG: duration: 0.082 ms bind <unnamed>: SELECT "id" FROM "Host" WHERE "name"=$1
2014-04-23 23:58:48 CEST [63584]: [29-1] user=reslist,db=reslist DETAIL: parameters: $1 = 'localhost'
2014-04-23 23:58:48 CEST [63584]: [30-1] user=reslist,db=reslist LOG: duration: 0.026 ms execute <unnamed>: SELECT "id" FROM "Host" WHERE "name"=$1
2014-04-23 23:58:48 CEST [63584]: [31-1] user=reslist,db=reslist DETAIL: parameters: $1 = 'localhost'
2014-04-23 23:58:48 CEST [63576]: [13-1] user=reslist,db=reslist LOG: duration: 0.639 ms bind <unnamed>: SELECT "id" FROM "User" WHERE "nick"=$1 AND "deleted" IS NULL
2014-04-23 23:58:48 CEST [63576]: [14-1] user=reslist,db=reslist DETAIL: parameters: $1 = 'silberbatzen'
2014-04-23 23:58:48 CEST [63576]: [15-1] user=reslist,db=reslist LOG: duration: 0.022 ms execute <unnamed>: SELECT "id" FROM "User" WHERE "nick"=$1 AND "deleted" IS NULL
2014-04-23 23:58:48 CEST [63576]: [16-1] user=reslist,db=reslist DETAIL: parameters: $1 = 'silberbatzen'
2014-04-23 23:58:48 CEST [63576]: [17-1] user=reslist,db=reslist LOG: duration: 0.208 ms parse <unnamed>: SELECT "userRef" FROM "VerifyQueue" WHERE lower("email")=lower($1)
2014-04-23 23:58:48 CEST [63576]: [18-1] user=reslist,db=reslist LOG: duration: 0.247 ms bind <unnamed>: SELECT "userRef" FROM "VerifyQueue" WHERE lower("email")=lower($1)
2014-04-23 23:58:48 CEST [63576]: [19-1] user=reslist,db=reslist DETAIL: parameters: $1 = 'silberbatzen(at)gmail(dot)com'
2014-04-23 23:58:48 CEST [63576]: [20-1] user=reslist,db=reslist LOG: duration: 0.014 ms execute <unnamed>: SELECT "userRef" FROM "VerifyQueue" WHERE lower("email")=lower($1)
2014-04-23 23:58:48 CEST [63576]: [21-1] user=reslist,db=reslist DETAIL: parameters: $1 = 'silberbatzen(at)gmail(dot)com'
2014-04-23 23:58:48 CEST [63576]: [22-1] user=reslist,db=reslist LOG: duration: 0.345 ms parse <unnamed>: SELECT "User"."id","User"."nick","User"."address","User"."givenname","User"."surname","User"."email","User"."newmailNotification","User"."realnameVisible","User"."language","User"."last_login","User"."creationTime","User"."deleted","Host"."name","Service"."name","User"."password","User"."salt" FROM "User" INNER JOIN "Host" ON "User"."hostRef"="Host"."id" INNER JOIN "Service" ON "Host"."serviceRef"="Service"."id" WHERE lower("email")=lower($1)
2014-04-23 23:58:48 CEST [63576]: [23-1] user=reslist,db=reslist LOG: duration: 0.581 ms bind <unnamed>: SELECT "User"."id","User"."nick","User"."address","User"."givenname","User"."surname","User"."email","User"."newmailNotification","User"."realnameVisible","User"."language","User"."last_login","User"."creationTime","User"."deleted","Host"."name","Service"."name","User"."password","User"."salt" FROM "User" INNER JOIN "Host" ON "User"."hostRef"="Host"."id" INNER JOIN "Service" ON "Host"."serviceRef"="Service"."id" WHERE lower("email")=lower($1)
2014-04-23 23:58:48 CEST [63576]: [24-1] user=reslist,db=reslist DETAIL: parameters: $1 = 'silberbatzen(at)gmail(dot)com'
2014-04-23 23:58:48 CEST [63576]: [25-1] user=reslist,db=reslist LOG: duration: 0.019 ms execute <unnamed>: SELECT "User"."id","User"."nick","User"."address","User"."givenname","User"."surname","User"."email","User"."newmailNotification","User"."realnameVisible","User"."language","User"."last_login","User"."creationTime","User"."deleted","Host"."name","Service"."name","User"."password","User"."salt" FROM "User" INNER JOIN "Host" ON "User"."hostRef"="Host"."id" INNER JOIN "Service" ON "Host"."serviceRef"="Service"."id" WHERE lower("email")=lower($1)
2014-04-23 23:58:48 CEST [63576]: [26-1] user=reslist,db=reslist DETAIL: parameters: $1 = 'silberbatzen(at)gmail(dot)com'
2014-04-23 23:58:48 CEST [63576]: [27-1] user=reslist,db=reslist LOG: duration: 0.046 ms parse <unnamed>: SELECT "id" FROM "Host" WHERE "name"=$1
2014-04-23 23:58:48 CEST [63576]: [28-1] user=reslist,db=reslist LOG: duration: 0.075 ms bind <unnamed>: SELECT "id" FROM "Host" WHERE "name"=$1
2014-04-23 23:58:48 CEST [63576]: [29-1] user=reslist,db=reslist DETAIL: parameters: $1 = 'localhost'
2014-04-23 23:58:48 CEST [63576]: [30-1] user=reslist,db=reslist LOG: duration: 0.021 ms execute <unnamed>: SELECT "id" FROM "Host" WHERE "name"=$1
2014-04-23 23:58:48 CEST [63576]: [31-1] user=reslist,db=reslist DETAIL: parameters: $1 = 'localhost'
2014-04-23 23:58:48 CEST [63584]: [32-1] user=reslist,db=reslist LOG: duration: 0.226 ms parse <unnamed>: INSERT INTO "User"("nick","password","salt","address","givenname","surname","email","newmailNotification","realnameVisible","pictureVisible","language","hostRef","creationTime","agb") VALUES ($1,$2,$3,$4,$5,$6,NULL,$7,$8,$9,$10,$11,$12,$13)
2014-04-23 23:58:48 CEST [63584]: [33-1] user=reslist,db=reslist LOG: duration: 0.136 ms bind <unnamed>: INSERT INTO "User"("nick","password","salt","address","givenname","surname","email","newmailNotification","realnameVisible","pictureVisible","language","hostRef","creationTime","agb") VALUES ($1,$2,$3,$4,$5,$6,NULL,$7,$8,$9,$10,$11,$12,$13)
2014-04-23 23:58:48 CEST [63584]: [34-1] user=reslist,db=reslist DETAIL: parameters: $1 = 'silberbatzen', $2 = 'HBfkwJDphdr+YDB2Yp7bwC8oci7JSWkOhtn2JFGRcTo=', $3 = 'ogrUEWQCi/k=', $4 = 'Technical', $5 = 'Testuser', $6 = 'Silver', $7 = 'f', $8 = 'f', $9 = 'f', $10 = 'de', $11 = '4', $12 = '1398290328', $13 = '8ZEwvtmABppOjChHuxnGo34EJLgejz/cF4OT+y7W6F8='
2014-04-23 23:58:48 CEST [63576]: [32-1] user=reslist,db=reslist LOG: duration: 0.164 ms parse <unnamed>: INSERT INTO "User"("nick","password","salt","address","givenname","surname","email","newmailNotification","realnameVisible","pictureVisible","language","hostRef","creationTime","agb") VALUES ($1,$2,$3,$4,$5,$6,NULL,$7,$8,$9,$10,$11,$12,$13)
2014-04-23 23:58:48 CEST [63576]: [33-1] user=reslist,db=reslist LOG: duration: 0.152 ms bind <unnamed>: INSERT INTO "User"("nick","password","salt","address","givenname","surname","email","newmailNotification","realnameVisible","pictureVisible","language","hostRef","creationTime","agb") VALUES ($1,$2,$3,$4,$5,$6,NULL,$7,$8,$9,$10,$11,$12,$13)
2014-04-23 23:58:48 CEST [63576]: [34-1] user=reslist,db=reslist DETAIL: parameters: $1 = 'silberbatzen', $2 = 'PqhzQDLRd8cNKef2idIhyoNE3/cOPgGomB93PoWhhHM=', $3 = 'rsJG2GZudz8=', $4 = 'Technical', $5 = 'Testuser', $6 = 'Silver', $7 = 'f', $8 = 'f', $9 = 'f', $10 = 'de', $11 = '4', $12 = '1398290328', $13 = '8ZEwvtmABppOjChHuxnGo34EJLgejz/cF4OT+y7W6F8='
2014-04-23 23:58:48 CEST [63584]: [35-1] user=reslist,db=reslist LOG: duration: 4.444 ms execute <unnamed>: INSERT INTO "User"("nick","password","salt","address","givenname","surname","email","newmailNotification","realnameVisible","pictureVisible","language","hostRef","creationTime","agb") VALUES ($1,$2,$3,$4,$5,$6,NULL,$7,$8,$9,$10,$11,$12,$13)
2014-04-23 23:58:48 CEST [63584]: [36-1] user=reslist,db=reslist DETAIL: parameters: $1 = 'silberbatzen', $2 = 'HBfkwJDphdr+YDB2Yp7bwC8oci7JSWkOhtn2JFGRcTo=', $3 = 'ogrUEWQCi/k=', $4 = 'Technical', $5 = 'Testuser', $6 = 'Silver', $7 = 'f', $8 = 'f', $9 = 'f', $10 = 'de', $11 = '4', $12 = '1398290328', $13 = '8ZEwvtmABppOjChHuxnGo34EJLgejz/cF4OT+y7W6F8='
2014-04-23 23:58:48 CEST [63584]: [37-1] user=reslist,db=reslist LOG: duration: 0.096 ms parse <unnamed>: SELECT currval('"userSeq"')
2014-04-23 23:58:48 CEST [63584]: [38-1] user=reslist,db=reslist LOG: duration: 0.027 ms bind <unnamed>: SELECT currval('"userSeq"')
2014-04-23 23:58:48 CEST [63584]: [39-1] user=reslist,db=reslist LOG: duration: 0.096 ms execute <unnamed>: SELECT currval('"userSeq"')
2014-04-23 23:58:48 CEST [63576]: [35-1] user=reslist,db=reslist LOG: duration: 4.431 ms execute <unnamed>: INSERT INTO "User"("nick","password","salt","address","givenname","surname","email","newmailNotification","realnameVisible","pictureVisible","language","hostRef","creationTime","agb") VALUES ($1,$2,$3,$4,$5,$6,NULL,$7,$8,$9,$10,$11,$12,$13)
2014-04-23 23:58:48 CEST [63576]: [36-1] user=reslist,db=reslist DETAIL: parameters: $1 = 'silberbatzen', $2 = 'PqhzQDLRd8cNKef2idIhyoNE3/cOPgGomB93PoWhhHM=', $3 = 'rsJG2GZudz8=', $4 = 'Technical', $5 = 'Testuser', $6 = 'Silver', $7 = 'f', $8 = 'f', $9 = 'f', $10 = 'de', $11 = '4', $12 = '1398290328', $13 = '8ZEwvtmABppOjChHuxnGo34EJLgejz/cF4OT+y7W6F8='
2014-04-23 23:58:48 CEST [63576]: [37-1] user=reslist,db=reslist LOG: duration: 0.080 ms parse <unnamed>: SELECT currval('"userSeq"')
2014-04-23 23:58:48 CEST [63576]: [38-1] user=reslist,db=reslist LOG: duration: 0.032 ms bind <unnamed>: SELECT currval('"userSeq"')
2014-04-23 23:58:48 CEST [63576]: [39-1] user=reslist,db=reslist LOG: duration: 0.043 ms execute <unnamed>: SELECT currval('"userSeq"')
2014-04-23 23:58:48 CEST [63584]: [40-1] user=reslist,db=reslist LOG: duration: 0.112 ms parse <unnamed>: SELECT "groupRef" FROM "InviteQueue" WHERE "token"=$1
2014-04-23 23:58:48 CEST [63576]: [40-1] user=reslist,db=reslist LOG: duration: 0.126 ms parse <unnamed>: SELECT "groupRef" FROM "InviteQueue" WHERE "token"=$1
2014-04-23 23:58:48 CEST [63584]: [41-1] user=reslist,db=reslist LOG: duration: 0.159 ms bind <unnamed>: SELECT "groupRef" FROM "InviteQueue" WHERE "token"=$1
2014-04-23 23:58:48 CEST [63584]: [42-1] user=reslist,db=reslist DETAIL: parameters: $1 = NULL
2014-04-23 23:58:48 CEST [63584]: [43-1] user=reslist,db=reslist LOG: duration: 0.003 ms execute <unnamed>: SELECT "groupRef" FROM "InviteQueue" WHERE "token"=$1
2014-04-23 23:58:48 CEST [63584]: [44-1] user=reslist,db=reslist DETAIL: parameters: $1 = NULL
2014-04-23 23:58:48 CEST [63576]: [41-1] user=reslist,db=reslist LOG: duration: 0.166 ms bind <unnamed>: SELECT "groupRef" FROM "InviteQueue" WHERE "token"=$1
2014-04-23 23:58:48 CEST [63576]: [42-1] user=reslist,db=reslist DETAIL: parameters: $1 = NULL
2014-04-23 23:58:48 CEST [63576]: [43-1] user=reslist,db=reslist LOG: duration: 0.004 ms execute <unnamed>: SELECT "groupRef" FROM "InviteQueue" WHERE "token"=$1
2014-04-23 23:58:48 CEST [63576]: [44-1] user=reslist,db=reslist DETAIL: parameters: $1 = NULL
2014-04-23 23:58:48 CEST [63584]: [45-1] user=reslist,db=reslist LOG: duration: 0.041 ms parse <unnamed>: INSERT INTO "VerifyQueue"("email","token","userRef","groupRef","creationTime") VALUES ($1,$2,$3,$4,$5)
2014-04-23 23:58:48 CEST [63584]: [46-1] user=reslist,db=reslist LOG: duration: 0.041 ms bind <unnamed>: INSERT INTO "VerifyQueue"("email","token","userRef","groupRef","creationTime") VALUES ($1,$2,$3,$4,$5)
2014-04-23 23:58:48 CEST [63584]: [47-1] user=reslist,db=reslist DETAIL: parameters: $1 = 'silberbatzen(at)gmail(dot)com', $2 = 'fg8t3iG30eTfQyVPb79yhw.html', $3 = '1', $4 = NULL, $5 = '1398290328'
2014-04-23 23:58:48 CEST [63576]: [45-1] user=reslist,db=reslist LOG: duration: 0.054 ms parse <unnamed>: INSERT INTO "VerifyQueue"("email","token","userRef","groupRef","creationTime") VALUES ($1,$2,$3,$4,$5)
2014-04-23 23:58:48 CEST [63576]: [46-1] user=reslist,db=reslist LOG: duration: 0.100 ms bind <unnamed>: INSERT INTO "VerifyQueue"("email","token","userRef","groupRef","creationTime") VALUES ($1,$2,$3,$4,$5)
2014-04-23 23:58:48 CEST [63576]: [47-1] user=reslist,db=reslist DETAIL: parameters: $1 = 'silberbatzen(at)gmail(dot)com', $2 = 'aF6n8wyzaQ0pBipusp3wg.html', $3 = '2', $4 = NULL, $5 = '1398290328'
2014-04-23 23:58:48 CEST [63584]: [48-1] user=reslist,db=reslist LOG: duration: 2.576 ms execute <unnamed>: INSERT INTO "VerifyQueue"("email","token","userRef","groupRef","creationTime") VALUES ($1,$2,$3,$4,$5)
2014-04-23 23:58:48 CEST [63584]: [49-1] user=reslist,db=reslist DETAIL: parameters: $1 = 'silberbatzen(at)gmail(dot)com', $2 = 'fg8t3iG30eTfQyVPb79yhw.html', $3 = '1', $4 = NULL, $5 = '1398290328'
2014-04-23 23:58:48 CEST [63584]: [50-1] user=reslist,db=reslist LOG: duration: 0.051 ms parse <unnamed>: SELECT "Service"."name" FROM "Service" INNER JOIN "Host" ON "Host"."serviceRef"="Service"."id" WHERE "Host"."id"=$1
2014-04-23 23:58:48 CEST [63584]: [51-1] user=reslist,db=reslist LOG: duration: 0.117 ms bind <unnamed>: SELECT "Service"."name" FROM "Service" INNER JOIN "Host" ON "Host"."serviceRef"="Service"."id" WHERE "Host"."id"=$1
2014-04-23 23:58:48 CEST [63584]: [52-1] user=reslist,db=reslist DETAIL: parameters: $1 = '4'
2014-04-23 23:58:48 CEST [63584]: [53-1] user=reslist,db=reslist LOG: duration: 0.049 ms execute <unnamed>: SELECT "Service"."name" FROM "Service" INNER JOIN "Host" ON "Host"."serviceRef"="Service"."id" WHERE "Host"."id"=$1
2014-04-23 23:58:48 CEST [63584]: [54-1] user=reslist,db=reslist DETAIL: parameters: $1 = '4'
2014-04-23 23:58:48 CEST [63584]: [55-1] user=reslist,db=reslist LOG: duration: 0.021 ms parse S_1: COMMIT
2014-04-23 23:58:48 CEST [63584]: [56-1] user=reslist,db=reslist LOG: duration: 0.013 ms bind S_1: COMMIT
2014-04-23 23:58:48 CEST [63584]: [57-1] user=reslist,db=reslist LOG: duration: 0.226 ms execute S_1: COMMIT
2014-04-23 23:58:48 CEST [63576]: [48-1] user=reslist,db=reslist ERROR: duplicate key value violates unique constraint "QueueLowerEmailIdx"
2014-04-23 23:58:48 CEST [63576]: [49-1] user=reslist,db=reslist DETAIL: Key (lower(email::text))=(silberbatzen(at)gmail(dot)com) already exists.
2014-04-23 23:58:48 CEST [63576]: [50-1] user=reslist,db=reslist STATEMENT: INSERT INTO "VerifyQueue"("email","token","userRef","groupRef","creationTime") VALUES ($1,$2,$3,$4,$5)
2014-04-23 23:58:48 CEST [63584]: [58-1] user=reslist,db=reslist LOG: disconnection: session time: 0:00:00.023 user=reslist database=reslist host=127.0.0.1 port=62259
2014-04-23 23:58:48 CEST [63576]: [51-1] user=reslist,db=reslist LOG: duration: 0.036 ms parse S_1: ROLLBACK
2014-04-23 23:58:48 CEST [63576]: [52-1] user=reslist,db=reslist LOG: duration: 0.010 ms bind S_1: ROLLBACK
2014-04-23 23:58:48 CEST [63576]: [53-1] user=reslist,db=reslist LOG: duration: 0.011 ms execute S_1: ROLLBACK
2014-04-23 23:58:48 CEST [63576]: [54-1] user=reslist,db=reslist LOG: disconnection: session time: 0:00:00.044 user=reslist database=reslist host=127.0.0.1 port=62251

claudio
--
Claudio Nieder . mailto:claudio(dot)nieder(at)inodes(dot)ch . http://inodes.ch/
iNodes AG . Loogartenstrasse 14 . CH-8048 Zürich . +41 43 960 0066