Provide ability to see in the trace log actions related to session management (e.g. ALTER SESSION RESET) [CORE6469]

[firebird-automations]

Submitted by: @pavel-zotov

Is related to CORE5832

Ticket has been created after discuss with Vlad.
Currently trace log does not contain info about requests related to session management. It will be nice to see such info there.

Example:
1) create config for trace:

database =
{
enabled = true
log_initfini = false

log\_errors = true
time\_threshold = 0

log\_connections = true
log\_transactions = true

log\_statement\_finish = true

}

- and run trace

2) run following .sql:

set bail on;
shell del c:\temp\tmp4test.fdb 2>nul;
create database 'localhost:c:\temp\tmp4test.fdb' user 'sysdba' password 'masterkey';

set list on;
set autoddl off;
commit;

select cast(1234.5678 as decfloat(16)) as before_ssn_reset from rdb$database;

alter session reset;

select cast(3456.7890 as decfloat(16)) as after_ssn_reset from rdb$database;

In the trace log we see:

2021-01-19T07:53:11.6930 (2360:00000000061C0640) START_TRANSACTION
C:\TEMP\TMP4TEST.FDB (ATT_3, SYSDBA:NONE, NONE, TCPv6:::1/61195)
C:\FB\40SS\isql.exe:7044
(TRA_7, CONCURRENCY | WAIT | READ_WRITE)

2021-01-19T07:53:11.6940 (2360:00000000061C0640) EXECUTE_STATEMENT_FINISH
C:\TEMP\TMP4TEST.FDB (ATT_3, SYSDBA:NONE, NONE, TCPv6:::1/61195)
C:\FB\40SS\isql.exe:7044
(TRA_7, CONCURRENCY | WAIT | READ_WRITE)

Statement 6:
-------------------------------------------------------------------------------
select cast(1234.5678 as decfloat(16)) as before_ssn_reset from rdb$database
1 records fetched
0 ms, 5 fetch(es)

2021-01-19T07:53:11.6940 (2360:00000000061C0640) ROLLBACK_TRANSACTION
C:\TEMP\TMP4TEST.FDB (ATT_3, SYSDBA:NONE, NONE, TCPv6:::1/61195)
C:\FB\40SS\isql.exe:7044
(TRA_7, CONCURRENCY | WAIT | READ_WRITE)
0 ms, 1 fetch(es), 1 mark(s)

2021-01-19T07:53:11.6950 (2360:00000000061C0640) START_TRANSACTION
C:\TEMP\TMP4TEST.FDB (ATT_3, SYSDBA:NONE, NONE, TCPv6:::1/61195)
C:\FB\40SS\isql.exe:7044
(TRA_8, CONCURRENCY | WAIT | READ_WRITE)

2021-01-19T07:53:11.6950 (2360:00000000061C0640) EXECUTE_STATEMENT_FINISH
C:\TEMP\TMP4TEST.FDB (ATT_3, SYSDBA:NONE, NONE, TCPv6:::1/61195)
C:\FB\40SS\isql.exe:7044
(TRA_8, CONCURRENCY | WAIT | READ_WRITE)

Statement 7:
-------------------------------------------------------------------------------
select cast(3456.7890 as decfloat(16)) as after_ssn_reset from rdb$database
1 records fetched
0 ms, 5 fetch(es)

2021-01-19T07:53:11.6950 (2360:00000000061C0640) COMMIT_TRANSACTION
C:\TEMP\TMP4TEST.FDB (ATT_3, SYSDBA:NONE, NONE, TCPv6:::1/61195)
C:\FB\40SS\isql.exe:7044
(TRA_8, CONCURRENCY | WAIT | READ_WRITE)
0 ms, 1 fetch(es), 1 mark(s)

2021-01-19T07:53:11.6960 (2360:00000000061C0640) DETACH_DATABASE
C:\TEMP\TMP4TEST.FDB (ATT_3, SYSDBA:NONE, NONE, TCPv6:::1/61195)
C:\FB\40SS\isql.exe:7044

One can guess that something happen about session only by watching for Tx numbers (TRA_7 rolled back and TRA_8 appeared - without explicit command to finish 1st of them).
It will be good to see explicitly mentioned session-level statement between ROLLBACK and START Tx statements.

Commits: 98b1321 a65f19f FirebirdSQL/fbt-repository@25c4036

[firebird-automations]

Modified by: @hvlad

assignee: Vlad Khorsun [ hvlad ]

[firebird-automations]

Modified by: Sean Leyne (seanleyne)

Link: This issue is related to CORE5832 [ CORE5832 ]

[firebird-automations]

Modified by: @hvlad

status: Open [ 1 ] => Resolved [ 5 ]

resolution: Fixed [ 1 ]

Fix Version: 4.0 RC 1 [ 10930 ]

[firebird-automations]

Commented by: @hvlad

Trace plugin writers should be ready to handle NULL transaction in ITracePlugin::trace_dsql_execute().
It was already a case for ITracePlugin::trace_dsql_prepare(), btw.

[firebird-automations]

Modified by: @pavel-zotov

status: Resolved [ 5 ] => Resolved [ 5 ]

QA Status: No test => Done successfully

[firebird-automations]

Modified by: @pavel-zotov

status: Resolved [ 5 ] => Closed [ 6 ]