ports/175485: port databases/firebird25-server (classic) keeps attached to security2.fdb for each connection

[Haris Papadopoulos]

>Number:         175485
>Category:       ports
>Synopsis:       port databases/firebird25-server (classic) keeps attached to security2.fdb for each connection
>Confidential:   no
>Severity:       non-critical
>Priority:       low
>Responsible:    freebsd-ports-bugs
>State:          open
>Quarter:        
>Keywords:       
>Date-Required:
>Class:          sw-bug
>Submitter-Id:   current-users
>Arrival-Date:   Mon Jan 21 19:10:00 UTC 2013
>Closed-Date:
>Last-Modified:
>Originator:     Haris Papadopoulos
>Release:        9.0, 9.1
>Organization:
Softways S.A.
>Environment:
9.0-RELEASE FreeBSD 9.0-RELEASE #0: Tue Jan  3 07:46:30 UTC 2012     root at farrell.cse.buffalo.edu:/usr/obj/usr/src/sys/GENERIC  amd64

Also
9.1-PRERELEASE FreeBSD 9.1-PRERELEASE #0: Sun Sep 30 18:19:57 EEST 2012     root at serifos.softways.lan:/usr/obj/usr/src/sys/MYKERNEL  i386
>Description:
firebird-server-2.5.1_2 built successfully from ports.
FreeBSD 9.0-RELEASE #0: Tue Jan  3 07:46:30 UTC 2012 
root at farrell.cse.buffalo.edu:/usr/obj/usr/src/sys/GENERIC  amd64

First observation:
Trying to run Classic Server via inetd. When my Tomcat application 
server starts connections to multiple databases with 1 connection to 
each database(this is intented to be a web server) I notice that several 
fb_inet_server processes reach 100% CPU load and stay there until after 
some minutes they are automatically shut down and then I get infinite 
errors in firebird log like: semop failed errno = 22.

I suspected that this has to do with the limited number of semaphores 
provided by FreeBSD so I increased them in /boot/loader.conf and in 
/etc/sysctl.conf (I must say too much for testing). Here is the output 
of # sysctl -a | grep ipc

kern.ipc.maxsockbuf: 2097152
kern.ipc.sockbuf_waste_factor: 8
kern.ipc.somaxconn: 2048
kern.ipc.max_linkhdr: 16
kern.ipc.max_protohdr: 60
kern.ipc.max_hdr: 76
kern.ipc.max_datalen: 92
kern.ipc.nmbjumbo16: 3200
kern.ipc.nmbjumbo9: 6400
kern.ipc.nmbjumbop: 12800
kern.ipc.nmbclusters: 25600
kern.ipc.piperesizeallowed: 1
kern.ipc.piperesizefail: 0
kern.ipc.pipeallocfail: 0
kern.ipc.pipefragretry: 0
kern.ipc.pipekva: 65536
kern.ipc.maxpipekva: 133775360
kern.ipc.msgseg: 2048
kern.ipc.msgssz: 8
kern.ipc.msgtql: 1024
kern.ipc.msgmnb: 2048
kern.ipc.msgmni: 2048
kern.ipc.msgmax: 16384
kern.ipc.semaem: 32767
kern.ipc.semvmx: 65534
kern.ipc.semusz: 2048
kern.ipc.semume: 2048
kern.ipc.semopm: 2048
kern.ipc.semmsl: 2048
kern.ipc.semmnu: 2048
kern.ipc.semmns: 2048
kern.ipc.semmni: 2048
kern.ipc.shm_allow_removed: 1
kern.ipc.shm_use_phys: 0
kern.ipc.shmall: 1048566
kern.ipc.shmseg: 2048
kern.ipc.shmmni: 2048
kern.ipc.shmmin: 1
kern.ipc.shmmax: 4294926336
kern.ipc.maxsockets: 25600
kern.ipc.numopensockets: 32
kern.ipc.nsfbufsused: 0
kern.ipc.nsfbufspeak: 0
kern.ipc.nsfbufs: 0
security.jail.param.allow.sysvipc: 0
security.jail.sysvipc_allowed: 0

The problem remained.

Testing:
Then I enabled the audit-trace facility of Firebird and I created an 
empty database. When I connect to it via isql-fb:

isql-fb -USER SYSDBA -PASS masterkey firstdb.fdb

I get the following in my audit log:

2013-01-04T12:06:29.5840 (16180:0x8006f3590) TRACE_INIT SESSION_1 
Firebird Audit
2013-01-04T12:06:29.5840 (16180:0x8006f3590) ATTACH_DATABASE 
/var/db/firebird/security2.fdb (ATT_16, SYSDBA:NONE, NONE, )
2013-01-04T12:06:29.5870 (16180:0x8006f3590) COMPILE_BLR 
/var/db/firebird/security2.fdb (ATT_16, SYSDBA:NONE, NONE, )
----------------------------------------------------------
0 blr_version5,
1 blr_begin,
2 blr_message, 1, 4,0,
6 blr_long, 0,
8 blr_long, 0,
10 blr_short, 0,
12 blr_text, 66,0,
15 blr_message, 0, 1,0,
19 blr_cstring, 129,0,
22 blr_receive, 0,
24 blr_begin,
25 blr_for,
26 blr_rse, 1,
28 blr_relation, 9, 'R','D','B','$','U','S','E','R','S', 0,
40 blr_first,
41 blr_literal, blr_short, 0, 1,0...
7 ms
2013-01-04T12:06:29.5870 (16180:0x8006f3590) START_TRANSACTION 
/var/db/firebird/security2.fdb (ATT_16, SYSDBA:NONE, NONE, ) (TRA_35, 
CONCURRENCY | WAIT | READ_ONLY)
2013-01-04T12:06:29.5880 (16180:0x8006f3590) ROLLBACK_TRANSACTION 
/var/db/firebird/security2.fdb (ATT_16, SYSDBA:NONE, NONE, ) (TRA_35, 
CONCURRENCY | WAIT | READ_ONLY) 0 ms, 1 read(s), 1 write(s), 1 
fetch(es), 1 mark(s)
2013-01-04T12:06:29.6840 (16180:0x8006f1c40) TRACE_INIT SESSION_1 
Firebird Audit
2013-01-04T12:06:29.6840 (16180:0x8006f1c40) ATTACH_DATABASE 
/usr/local/firebird.data/firstdb.fdb (ATT_7, SYSDBA:NONE, NONE, )
2013-01-04T12:06:29.6850 (16180:0x8006f1c40) START_TRANSACTION 
/usr/local/firebird.data/firstdb.fdb (ATT_7, SYSDBA:NONE, NONE, ) 
(TRA_14, CONCURRENCY | WAIT | READ_WRITE)
2013-01-04T12:06:29.6860 (16180:0x8006f1c40) START_TRANSACTION 
/usr/local/firebird.data/firstdb.fdb (ATT_7, SYSDBA:NONE, NONE, ) 
(TRA_15, READ_COMMITTED | NO_REC_VERSION | WAIT | READ_WRITE)

The ROLLBACK_TRANSACTION line doesn't seem normal to me. Staying 
connected, I run fuser /var/db/firebird/security2.fdb and it shows that 
the process of isql-fb is still attached to the security database (no 
complaints in firebird.log).

If I run:
procstat -t 16180 # (16180 is the PID of fb_inet_server in my current test)
I get:

PID TID COMM TDNAME CPU PRI STATE WCHAN
16180 101202 isql-fb - 9 126 sleep ttyin
16180 104970 isql-fb - 1 120 sleep usem
16180 106138 isql-fb - 8 120 sleep usem
16180 106139 isql-fb - 1 120 sleep semwait
16180 106140 isql-fb - 1 124 sleep semwait

If I run:
procstat -k 16180
I get:

PID TID COMM TDNAME KSTACK
16180 101202 isql-fb - mi_switch sleepq_catch_signals sleepq_wait_sig 
_cv_wait_sig tty_wait ttydisc_read ttydev_read devfs_read_f dofileread 
kern_readv sys_read amd64_syscall Xfast_syscall
16180 104970 isql-fb - mi_switch sleepq_catch_signals sleepq_wait_sig 
_sleep do_sem_wait __umtx_op_sem_wait amd64_syscall Xfast_syscall
16180 106138 isql-fb - mi_switch sleepq_catch_signals 
sleepq_timedwait_sig _sleep do_sem_wait __umtx_op_sem_wait amd64_syscall 
Xfast_syscall
16180 106139 isql-fb - mi_switch sleepq_catch_signals sleepq_wait_sig 
_sleep sys_semop amd64_syscall Xfast_syscall
16180 106140 isql-fb - mi_switch sleepq_catch_signals sleepq_wait_sig 
_sleep sys_semop amd64_syscall Xfast_syscall

If I make another connection to the same or another database keeping 
this one, I see two attachments to security2.fdb. The isql-fb processes 
stay attached to security2.fdb as long as they stay connected to the 
database. Since this doesn't happen with Firebird 2.1 on another 
identical server I suspect that this might be a bug.

I also tested the same version (2.5.1) on my laptop:
FreeBSD 9.1-PRERELEASE FreeBSD 9.1 i386

I had the exact same behaviour.
>How-To-Repeat:
After an out-of-the-box installation(CLASSIC server):
1. isql-fb -USER SYSDBA -PASS masterkey
2. Create an empty database with CREATE DATABASE(firstdb.fdb)
3. Exit isql-fb
4. Enable audit-trace in firebird.conf
5. isql-fb -USER SYSDBA -PASS masterkey firstdb.fdb
6  Leave the connection open and inspect the audit trace log. There should be a ROLLBACK_TRANSACTION line for security2.fdb
7. Run fuser /var/db/firebird/security2.fdb. You should see that there is an active attachment to security2.fdb with the isql-fb pid. This won't go away until you actually close the connection to firstdb.fdb.
8. Leaving connections open, repeat steps 5 to 7 connecting to the same or other dbs. You should see as many attachments to security2.fdb as the number of open connections.
>Fix:


>Release-Note:
>Audit-Trail:
>Unformatted: