Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Trace does not show events about cancelling operation, rollback and detach when connection uses local protocol and is terminated forcely without waiting for it will finish its work [CORE4915] #5207

Closed
firebird-automations opened this issue Aug 27, 2015 · 4 comments

Comments

@firebird-automations
Copy link
Collaborator

Submitted by: @pavel-zotov

Run trace with config:

enabled = true
log_sweep = true
log_errors = true
time_threshold = 0
log_connections = true
log_transactions = true

log_statement_prepare = true
log_statement_start = true
log_statement_free = true
log_statement_finish = true

print_perf = true
max_sql_length = 8192
max_log_size = 5000000

Create SQL script:

recreate table test(id int primary key);
commit;
insert into test values(1);
set echo on;
set term ^;
execute block as
begin
in autonomous transaction
do insert into test values(1);
end
^
set term ;^

When this script will be issued in ISQL, it will hangs during value = 'DeadlockTimeout' parameter from firebird.conf.

CASE-1.
~~~~~~
ISQL connection uses remote protocol and its work is interrupted by using psKill.exe utility from SysInternals.
Trace log:

2015-08-27T17:56:24.0470 (1384:01B419F8) FAILED EXECUTE_STATEMENT_FINISH
e30 (ATT_80, SYSDBA:NONE, NONE, TCPv4:127.0.0.1)
C:\MIX\Firebird\fb30\isql.exe:3128
(TRA_107, CONCURRENCY | WAIT | READ_WRITE)

Statement 135:
-------------------------------------------------------------------------------
execute block as
begin
in autonomous transaction
do insert into test values(1);
end

0 records fetched
8045 ms, 1 write(s), 21 fetch(es), 6 mark(s)

Table Natural Index Update Insert Delete Backout Purge Expunge
***************************************************************************************************************
TEST 1 1 1

2015-08-27T17:56:24.0470 (1384:01B419F8) ERROR AT JStatement::execute
e30 (ATT_80, SYSDBA:NONE, NONE, TCPv4:127.0.0.1)
C:\MIX\Firebird\fb30\isql.exe:3128
335544794 : operation was cancelled

2015-08-27T17:56:24.0470 (1384:01B419F8) ROLLBACK_TRANSACTION
e30 (ATT_80, SYSDBA:NONE, NONE, TCPv4:127.0.0.1)
C:\MIX\Firebird\fb30\isql.exe:3128
(TRA_107, CONCURRENCY | WAIT | READ_WRITE)
0 ms, 5 write(s), 16 fetch(es), 6 mark(s)

Table Natural Index Update Insert Delete Backout Purge Expunge
***************************************************************************************************************
TEST 1

2015-08-27T17:56:24.0470 (1384:01B419F8) DETACH_DATABASE
e30 (ATT_80, SYSDBA:NONE, NONE, TCPv4:127.0.0.1)
C:\MIX\Firebird\fb30\isql.exe:3128

2015-08-27T17:56:24.0470 (1384:01B419F8) TRACE_FINI
SESSION_1

(i.e. all fine, one may see that statement was cancelled, transaction was rolled back and connection was closed).

CASE-2.
~~~~~~
ISQL connection uses local ("embedded" ? I still can`t recognize difference of these terms...) protocol and its work is terminates by pressing Ctrl-C (btw, Ctrl-Break doesn`t work in many cases when use ISQL 3.0!).

Trace log:

2015-08-27T18:05:36.4530 (3532:012819F8) FAILED EXECUTE_STATEMENT_FINISH
e30 (ATT_94, SYSDBA:NONE, NONE, <internal>)
(TRA_126, CONCURRENCY | WAIT | READ_WRITE)

Statement 141:
-------------------------------------------------------------------------------
execute block as
begin
in autonomous transaction
do insert into test values(1);
end

0 records fetched
7554 ms, 1 write(s), 21 fetch(es), 6 mark(s)

Table Natural Index Update Insert Delete Backout Purge Expunge
***************************************************************************************************************
TEST 1 1 1

2015-08-27T18:05:36.4530 (3532:012819F8) ERROR AT JStatement::execute
e30 (ATT_94, SYSDBA:NONE, NONE, <internal>)
335544794 : operation was cancelled

2015-08-27T18:05:36.4530 (3532:012819F8) ROLLBACK_TRANSACTION
e30 (ATT_94, SYSDBA:NONE, NONE, <internal>)
(TRA_126, CONCURRENCY | WAIT | READ_WRITE)
0 ms, 5 write(s), 16 fetch(es), 6 mark(s)

Table Natural Index Update Insert Delete Backout Purge Expunge
***************************************************************************************************************
TEST 1

2015-08-27T18:05:36.4530 (3532:012819F8) FREE_STATEMENT
e30 (ATT_94, SYSDBA:NONE, NONE, <internal>)

Statement 141:
-------------------------------------------------------------------------------
execute block as
begin
in autonomous transaction
do insert into test values(1);
end

2015-08-27T18:05:36.4530 (3532:012819F8) DETACH_DATABASE
e30 (ATT_94, SYSDBA:NONE, NONE, <internal>)

2015-08-27T18:05:36.4530 (3532:012819F8) TRACE_FINI
SESSION_2

(i.e. also all OK, but I have to note that in at least on 2.5.1 (or 2.5.2) pressing Ctrl-C produced COMMIT rather than rollback -- CORE3664).

CASE-3.
~~~~~~
ISQL connection uses local protocol and its work is interrupted by using psKill.exe utility from SysInternals.
Trace log:

2015-08-27T18:16:18.1250 (2180:012819F8) EXECUTE_STATEMENT_START
e30 (ATT_98, SYSDBA:NONE, NONE, <internal>)
(TRA_131, CONCURRENCY | WAIT | READ_WRITE)

Statement 141:
-------------------------------------------------------------------------------
execute block as
begin
in autonomous transaction
do insert into test values(1);
end

2015-08-27T18:16:18.1250 (2180:012819F8) START_TRANSACTION
e30 (ATT_98, SYSDBA:NONE, NONE, <internal>)
(TRA_133, CONCURRENCY | WAIT | READ_WRITE)

2015-08-27T18:16:18.1410 (2180:01284B48) TRACE_INIT
SESSION_1

2015-08-27T18:16:18.1410 (2180:01284B48) START_TRANSACTION
C:\MIX\firebird\QA\fbt-repo\tmp\E30.FDB (ATT_97, Garbage Collector, NONE, <internal>)
(TRA_132, READ_COMMITTED | REC_VERSION | WAIT | READ_ONLY)

And that's all. NO more messages about killed session.

@firebird-automations
Copy link
Collaborator Author

Commented by: @dyemanov

ISQL + embedded connect = single process. How do you expect the forcibly killed process to write anything to the log? There's no cancel, no rollback, no detach - process just dies immediately.

@firebird-automations
Copy link
Collaborator Author

Commented by: @hvlad

Dmitry explained it very well

@firebird-automations
Copy link
Collaborator Author

Modified by: @hvlad

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

resolution: Won't Fix [ 2 ]

@firebird-automations
Copy link
Collaborator Author

Modified by: @pcisar

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

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Projects
None yet
Development

No branches or pull requests

1 participant