Repository navigation
[v3] there is already a transaction in progress and there is no transaction in progress #274
Description
Currently I don't have a minimally reproducible example but I may be able to provide one in a few days if needed (please just tell me then).
I strongly suspect the following code is at fault:
export const sql = postgres(process.env["DATABASE_URL"], {
host: process.env["DATABASE_HOST"],
debug: (conn, query, params) => {
console.log(conn, query, params);
},
});
export async function retryableBegin(
options: string,
cb: (
tsql: TransactionSql<Record<string, never>>
) =>
| postgres.RowList<postgres.Row[]>
| Promise<postgres.RowList<postgres.Row[]>>
): Promise<postgres.RowList<postgres.Row[]>> {
for (;;) {
try {
return await sql.begin(options, cb);
} catch (error) {
if (error instanceof postgres.PostgresError && error.code === "40001") {
console.log("SERIALIZATION FAILURE - RETRYING");
} else {
throw error;
}
}
}
}
await retryableBegin("READ WRITE", async (sql) => {
return await sql`UPDATE sessions SET updated_at = CURRENT_TIMESTAMP FROM users WHERE users.id = sessions.user_id AND session_id = ${session_id_} AND CURRENT_TIMESTAMP < updated_at + interval '24 hours' RETURNING users.id, users.type, users.username, users.group, users.age`;
})If this is executed in parallel it seems that some transactions are not managed properly. I don't understand yet whether my code is at fault or not.
Also I think the error handling part is never reached because I misconfigured my local development postgresql instance (didn't enable that level of transaction isolation) so maybe it's just the amount of concurrent requests.
Using apache bench I found out this happens at
11 concurrent requests with very low probability and the further you go away from 10 (which I think is the default number of concurrent connections in the postgresql pool) the more likely they get.
ab -n 10000 -c 11 -T 'text/json' -m GET -k -H 'x-csrf-protection: projektwahl' -H 'Cookie: strict_id=f0774391c90792730a0f374bd0609d9b3e0c7c48c9227eefcdc10104f961b16a; lax_id=f0774391c90792730a0f374bd0609d9b3e0c7c48c9227eefcdc10104f961b16a; username=admin' https://localhost:8443/api/v1/users
created just really few (1-2) of these notices.
Activity
porsager commentedon Mar 13, 2022
Would be great with a reproducible example for this one if you can create one. Thanks.
mohe2015 commentedon Mar 13, 2022
@porsager
I can reproduce with
You may need to adjust the count (and the database connection url of course). This almost always prints the following:
several times and sometimes it even hangs at the end.
mohe2015 commentedon Mar 13, 2022
For me it
worksbreaks more or less reliably with 12.mohe2015 commentedon Mar 14, 2022
This could (depending on root cause) be (considered) a security issue but now it's too late anyways.
mohe2015 commentedon Mar 14, 2022
If you need help finding the bug (if you can even reproduce) feel free to ask me. I don't know the code but maybe I can still help.
porsager commentedon Mar 15, 2022
Hi @mohe2015 .. Thanks a lot!!! I've been too busy to check into this until now, but your repro is good, I'll look closer now.
Fix wrong connection reserved state if initial begin query - fixes #274
porsager commentedon Mar 15, 2022
@mohe2015 Thanks a lot for finding and helping on this. That was an important fix, and great to get in before release!
I found the issue to be a race condition when a transaction was the first query on a newly opened connection.
Would you mind testing 3a8efe7 (current rewrite branch)?
Thank you
mohe2015 commentedon Mar 15, 2022
Can confirm. Thank you very much.