The message Unknown tag (4) in isc_svc_query() results appears when fbtracemgr is interrupted by Ctrl-C [CORE3769]

[firebird-automations]

Submitted by: @pavel-zotov

Under some conditions fbtracemgr can output the following message when interrupt by Ctrl-C:
Unknown tag (4) in isc_svc_query() results

In particular I got this message when pressed Ctrl-C after tracing IBE for select count(*) from some_table.
Details (in russian): http://www.sql.ru/forum/actualutils.aspx?action=gotomsg&tid=838190&msg=12132939

Commits: 2c27cf6 57293c3

[firebird-automations]

Modified by: @dyemanov

Version: 2.5.1 [ 10333 ]

Version: 2.5.0 [ 10221 ]

Component: SVCMGR [ 10141 ]

Component: TRACEMGR [ 10140 ]

[firebird-automations]

Modified by: @AlexPeshkoff

assignee: Alexander Peshkov [ alexpeshkoff ]

[firebird-automations]

Commented by: @AlexPeshkoff

It's not good idea to add links to national forums from interantional tracker. Please provide reproducible test case here, preferably using only native firebird tools.

[firebird-automations]

Commented by: @AlexPeshkoff

Pavel, will test case be provided or should I close as 'cannot reproduce'?

[firebird-automations]

Commented by: @pavel-zotov

Alex, just now I have encountered this problem again, on our production.
I can`t provide 100% test case at this time so you can close this ticket if needed.
But if I could reproduce I will put testcase here.

[firebird-automations]

Commented by: @dyemanov

Alex, is the test case really needed? As far as I see, our utilities don't check for isc_info_data_not_ready being returned from isc_svc_query(). The example of how it could be handled can be found in GBAK. What other info is needed?

[firebird-automations]

Commented by: @pavel-zotov

I got it!

create the following script named 'ibe.sql':
--- begin of script ---
set transaction read committed record_version no wait;
select RDB$RELATION_NAME from RDB$RELATIONS
where (RDB$RELATION_NAME = 'MON$ATTACHMENTS') and
(RDB$VIEW_BLR is NULL);

commit;
connect 192.168.0.60:/var/db/firebird/test/test.fdb user sysdba password 'qp26vtz1';
--- end of script ---

Then run isql utility in some folder (in my case: /var/db/firebird/test) and do these commands in it:
SQL> create database 'test.fdb'; commit;
SQL> quit;

Then connect from windows workstation to this database - let this session have name #⁠1:

session #⁠1
---------------
C:\MIX\firebird\fb25\bin>C:\MIX\firebird\fb25\bin\isql.exe 192.168.0.60:/var/db/firebird/test/test.fdb -n
Database: 192.168.0.60:/var/db/firebird/test/test.fdb
SQL> commit;

session #⁠2 (PUTTy console):
---------------
supertee -n trc.txt fbtracemgr -sta -c zaudit.conf -se service_mgr

session #⁠1
----------------

SQL> in ibe.sql;

RDB$RELATION_NAME

MON$ATTACHMENTS -- And this is "THE END". No further activity, all databases are hangs.

Trace console:

-------- start of trace console -----
Trace session ID 8 started
2012-03-27T19:35:33.8090 (5151:0x7fb3f1b6c648) TRACE_INIT
SESSION_8

2012-03-27T19:35:33.8100 (5151:0x7fb3f1b6c648) START_TRANSACTION
/u02/db/firebird/test/test.fdb (ATT_4, SYSDBA:NONE, NONE, TCPv4:192.168.43.96)
C:\MIX\firebird\fb25\bin\isql.exe:1764
(TRA_91, READ_COMMITTED | REC_VERSION | NOWAIT | READ_WRITE)

2012-03-27T19:35:33.8140 (5151:0x7fb3f1b6c648) EXECUTE_STATEMENT_START
/u02/db/firebird/test/test.fdb (ATT_4, SYSDBA:NONE, NONE, TCPv4:192.168.43.96)
C:\MIX\firebird\fb25\bin\isql.exe:1764
(TRA_91, READ_COMMITTED | REC_VERSION | NOWAIT | READ_WRITE)

Statement 35:
-------------------------------------------------------------------------------
select RDB$RELATION_NAME from RDB$RELATIONS
where (RDB$RELATION_NAME = 'MON$ATTACHMENTS') and
(RDB$VIEW_BLR is NULL)

2012-03-27T19:35:33.8140 (5151:0x7fb3f1b6c648) EXECUTE_STATEMENT_FINISH
-------- end of trace console -----

Trace config file ('zaudit.conf'):
----- start of trace config ----
bash-4.1$ cat /opt/firebird/zaudit.conf
<database (%[\\/](r`eplcfg|ttt%|zzz%|k`untsevomain|kmain2012%|test%).fdb)|(k`ntsevomain|kmain4trace)>
enabled true
log_filename /var/db/firebird/trace/zaudit.log
log_connections true
log_transactions true

log_statement_start true
log_statement_finish true

#⁠log_trigger_start true
#⁠log_trigger_finish true
#⁠log_procedure_start true
#⁠log_procedure_finish true
#⁠print_plan true
print_perf true
max_sql_length 16384
time_threshold 0
max_log_size 10
</database>
----- end of trace config ----

bash-4.1$ lsof /var/db/firebird/test/test.fdb
COMMAND PID USER FD TYPE DEVICE SIZE/OFF NODE NAME
fb_inet_s 5151 firebird 9u REG 8,145 827392 10485906 /u02/db/firebird/test/test.fdb

top -p 5151

top - 19:45:31 up 12 days, 17:13, 5 users, load average: 46.86, 37.16, 23.01
Tasks: 1 total, 0 running, 1 sleeping, 0 stopped, 0 zombie
Cpu(s): 12.3%us, 2.9%sy, 0.0%ni, 81.8%id, 2.8%wa, 0.0%hi, 0.2%si, 0.0%st
Mem: 37139904k total, 27606200k used, 9533704k free, 109928k buffers
Swap: 36863992k total, 41876k used, 36822116k free, 22891200k cached

PID USER PR NI VIRT RES SHR S %CPU %MEM TIME+ COMMAND
5151 firebird 20 0 236m 12m 7140 S 14.0 0.0 3:10.49 fb_inet_server

top -p $(pgrep fbtracemgr)

top - 19:47:04 up 12 days, 17:14, 5 users, load average: 47.15, 39.89, 25.36
Tasks: 1 total, 0 running, 1 sleeping, 0 stopped, 0 zombie
Cpu(s): 12.3%us, 3.0%sy, 0.0%ni, 81.8%id, 2.8%wa, 0.0%hi, 0.2%si, 0.0%st
Mem: 37139904k total, 27603292k used, 9536612k free, 109988k buffers
Swap: 36863992k total, 41876k used, 36822116k free, 22891200k cached

PID USER PR NI VIRT RES SHR S %CPU %MEM TIME+ COMMAND
5342 firebird 20 0 154m 8448 6280 S 8.0 0.0 2:00.40 fbtracemgr

session #⁠ 3 (just for illustration: try to create another one database):
----------------
bash-4.1$ isql
Use CONNECT or CREATE DATABASE to specify a database
SQL> create database 'test2.fdb'; commit;
--- hangs infinite time!
^Z
[1]+ Stopped isql

PS. All these processes (fb_inet, fbtracemgr) can be cancelled only via kill -9, rather than kill -15.

[firebird-automations]

Commented by: @AlexPeshkoff

Dmitry, adding code to process data_not_ready condition is very simple to do. But I want to know conditions under which it happens (looks like it may happen only during services manager shutdown). And the worst detail - it happens sometimes, i.e. looks like we have a kind of races here. Before hiding them at client side I want to understand how do they happen and can it be dangerous or not.

[firebird-automations]

Commented by: @AlexPeshkoff

Pavel, sorry - I've tried to reproduce your hang, but no luck. The only difefrence is that instead of remote windows workstation (do not have one) I've used one more linux tty. Do not think that client makes much difference here. Everything works fine for me.

PS. How is it related with initial problem?

[firebird-automations]

Commented by: @dyemanov

As a wild guess - could it be somehow related to CORE3770? I mean that Alex has it fixed now while Pavel has not, and this fact could affect the ability to reproduce the issue being discussed.

[firebird-automations]

Commented by: @AlexPeshkoff

No.
I've emulated old behavior, but anyway no hang.

[firebird-automations]

Commented by: @AlexPeshkoff

Pavel, may be you have some special firebird.conf settings?

[firebird-automations]

Commented by: @pavel-zotov

I've tried this on:
SQL> show version;
ISQL Version: LI-V2.5.2.26436 Firebird 2.5
Server version:
Firebird/linux AMD64 (access method), version "LI-V2.5.2.26436 Firebird 2.5"
on disk structure version 11.2

There were only few changes in firebird.conf, namely:

#⁠ set 05.03.2012 1630, after change mode to SC:
DefaultDbCachePages = 768

#⁠ to be increased after 12.03.2012 (check connects count and memo consumption before doing that!)
#⁠TempCacheLimit = 16777216 // not sure that it was really done

#⁠ 28-11-2011 1747
MaxUnflushedWrites = -1

#⁠ 28-11-2011 1747
MaxUnflushedWriteTime = -1

#⁠ enabled 05-oct-2010 19:03 due to errors in firebird.log
BugcheckAbort = 1

#⁠ 16.11.2010 15:15:
ConnectionTimeout = 90

#⁠ increased 12.03.2012:
LockMemSize = 4194304

#⁠LockHashSlots =3169
#⁠LockHashSlots = 10091
#⁠ 12.03.2012 1755
#⁠ increase hashslots due to big average hash length = 10 (min/avg/max = 2/10/22 - looked at fb_lock_print log header blobk)
LockHashSlots = 25013

[firebird-automations]

Commented by: @AlexPeshkoff

Have no testcase to check, but this fix should help

[firebird-automations]

Modified by: @AlexPeshkoff

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

resolution: Fixed [ 1 ]

Fix Version: 2.5.2 [ 10450 ]

Fix Version: 3.0 Alpha 1 [ 10331 ]

[firebird-automations]

Modified by: @pcisar

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

[firebird-automations]

Modified by: @pavel-zotov

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

QA Status: No test