feature: log transaction/connection ID to track SQL executions for a request

Question

feature: log transaction/connection ID to track SQL executions for a request

sio4 opened this issue 2 years ago · 0 comments

Description

Currently, SQL logs are enabled for development mode only but they have no identifier that can be used to identify requests or transactions. The current logs are similar to:

DEBU[2022-11-12T11:08:04+09:00] --- BEGIN Transaction ---
DEBU[2022-11-12T11:08:04+09:00] SELECT name_othernames.created_at, name_othernames.description, name_othernames.id, name_othernames.tile, name_othernames.updated_at FROM name_othernames AS name_othernames LIMIT 1
DEBU[2022-11-12T11:08:04+09:00] SELECT name_othernames.created_at, name_othernames.description, name_othernames.id, name_othernames.tile, name_othernames.updated_at FROM name_othernames AS name_othernames LIMIT 20 OFFSET 0
DEBU[2022-11-12T11:08:04+09:00] SELECT COUNT(*) AS row_count FROM (SELECT name_othernames.created_at, name_othernames.description, name_othernames.id, name_othernames.tile, name_othernames.updated_at FROM name_othernames AS name_othernames) a
DEBU[2022-11-12T11:08:04+09:00] --- END Transaction ---
INFO[2022-11-12T11:08:04+09:00] /name_othernames/ db="348.715µs" duration=4.619541ms human_size="2.3 kB" method=GET params="{}" path=/name_othernames/ render=1.804822ms request_id=c50e320d4a7fad1a8956-d275eaef7393e2fcdff1 size=2263 status=200

DEBU[2022-11-12T11:08:11+09:00] --- BEGIN Transaction ---
DEBU[2022-11-12T11:08:11+09:00] SELECT name_othernames.created_at, name_othernames.description, name_othernames.id, name_othernames.tile, name_othernames.updated_at FROM name_othernames AS name_othernames WHERE name_othernames.id = ? LIMIT 1 $1=e60c7e01-1534-4b9b-8489-0a11e8a7560a
DEBU[2022-11-12T11:08:11+09:00] --- END Transaction ---
INFO[2022-11-12T11:08:11+09:00] /name_othernames/e60c7e01-1534-4b9b-8489-0a11e8a7560a/ db=0s duration=3.292847ms human_size="1.5 kB" method=GET params="{\"name_othername_id\":[\"e60c7e01-1534-4b9b-8489-0a11e8a7560a\"]}" path=/name_othernames/e60c7e01-1534-4b9b-8489-0a11e8a7560a/ render=1.362451ms request_id=05f1abd9f540fa835ed2-15f9ab1f8c301738fa42 size=1468 status=200

This is fine since we do not log SQL logs in production, and developers send only one request at a time usually. However, it could be better if we have an identifier in the log explicitly to track if things are properly working with a transaction.

Especially in the situation like:

By adding the connection/transaction ID, we can get the following logs and can find there is something we do not intend:

[POP] 2022/11/12 11:17:26 sql - BEGIN Transaction --- (conn=tx-2425235574379030578, tx=2425235574379030578)
[POP] 2022/11/12 11:17:26 sql - SELECT name_othernames.created_at, name_othernames.description, name_othernames.id, name_othernames.tile, name_othernames.updated_at FROM name_othernames AS name_othernames LIMIT 1 (conn=tx-2425235574379030578, tx=2425235574379030578)
[POP] 2022/11/12 11:17:26 sql - SELECT name_othernames.created_at, name_othernames.description, name_othernames.id, name_othernames.tile, name_othernames.updated_at FROM name_othernames AS name_othernames LIMIT 20 OFFSET 0 (conn=tx-2425235574379030578-bilMcF, tx=2425235574379030578)
[POP] 2022/11/12 11:17:26 sql - SELECT COUNT(*) AS row_count FROM (SELECT name_othernames.created_at, name_othernames.description, name_othernames.id, name_othernames.tile, name_othernames.updated_at FROM name_othernames AS name_othernames) a (conn=tx-2425235574379030578-bilMcF, tx=2425235574379030578)
[POP] 2022/11/12 11:17:26 sql - END Transaction --- (conn=tx-2425235574379030578, tx=2425235574379030578)
INFO[2022-11-12T11:17:26+09:00] /name_othernames/ conn=tx-2425235574379030578 db="550.694µs" duration=5.279465ms human_size="2.3 kB" method=GET params="{}" path=/name_othernames/ render=1.928161ms request_id=5407f2b72e3d543dea2a-8f6010c24ac9fa0cf6e8 size=2263 status=200 tx=2425235574379030578

For the above logs, they all have the same transaction ID (tx) and the same set of connection IDs with copied tags (conn). These logs were generated when we use tx. However, when we use models.DB, it made a different pattern of logs:

[POP] 2022/11/12 11:17:31 sql - BEGIN Transaction --- (conn=tx-7253232795803335351, tx=7253232795803335351)
[POP] 2022/11/12 11:17:31 sql - SELECT name_othernames.created_at, name_othernames.description, name_othernames.id, name_othernames.tile, name_othernames.updated_at FROM name_othernames AS name_othernames WHERE name_othernames.id = ? LIMIT 1 | ["e60c7e01-1534-4b9b-8489-0a11e8a7560a"] (conn=conn-1367989891836989282, tx=0)
[POP] 2022/11/12 11:17:31 sql - END Transaction --- (conn=tx-7253232795803335351, tx=7253232795803335351)
INFO[2022-11-12T11:17:31+09:00] /name_othernames/e60c7e01-1534-4b9b-8489-0a11e8a7560a/ conn=tx-7253232795803335351 db=0s duration=2.883651ms human_size="1.5 kB" method=GET params="{\"name_othername_id\":[\"e60c7e01-1534-4b9b-8489-0a11e8a7560a\"]}" path=/name_othernames/e60c7e01-1534-4b9b-8489-0a11e8a7560a/ render=1.363569ms request_id=d32a47a69a60e75fe1d1-79f6421fe05714e49857 size=1468 status=200 tx=7253232795803335351

The conn for the transaction was tx-72532... but the conn for the actual SQL execution was conn-13679... which means there are two connections for the same simple request.

For now, I would like to add a transaction/connection ID to the log so we can easily find this kind of situation.

Additional Information

No response