Bug 175485

Summary: port databases/firebird25-server (classic) keeps attached to security2.fdb for each connection
Product: Ports & Packages Reporter: Haris Papadopoulos <haris>
Component: Individual Port(s)Assignee: Jose Alonso Cardenas Marquez <acm>
Status: Closed FIXED    
Severity: Affects Only Me    
Priority: Normal    
Version: Latest   
Hardware: Any   
OS: Any   

Description Haris Papadopoulos 2013-01-21 19:10:00 UTC
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.
Comment 1 Edwin Groothuis freebsd_committer freebsd_triage 2013-01-21 19:10:10 UTC
Responsible Changed
From-To: freebsd-ports-bugs->acm

Over to maintainer (via the GNATS Auto Assign Tool)
Comment 2 Jose Alonso Cardenas Marquez freebsd_committer freebsd_triage 2013-03-24 04:44:48 UTC
State Changed
From-To: open->feedback

- firebird25-* ports have been updated. Pleas, could you test it again?
Comment 3 Haris Papadopoulos 2013-05-01 13:15:56 UTC
I 've managed to setup a new laptop:

9.1-STABLE FreeBSD 9.1-STABLE #0 r249094: amd64

and I built and installed the new version successfully from ports:
# isql-fb -z
ISQL Version: FB-V2.5.2.26540 Firebird 2.5

I setup fbtrace.conf so that I could give you a complete feedback. 
Unfortunately, icu(obviously) stopped me. From firebird.log:

Trace plugin libfbtrace.so returned error on call trace_create.
Error details: cannot initialize UNICODE collation to use in trace plugin

icu version: 50.1.2 built from ports.

I can only confirm that fuser command still shows attachments to 
security2.fdb by the same processes that hold the actual connections to 
the database. I created an empty testdb.fdb, and connected to it from:
1. SQuirrel SQL using Jaybird driver and Classic 
server(/usr/local/sbin/fb_inet_server)
2. isql-fb

# ps -axfw | grep fb_inet
41417 ??  Is     0:00,04 fb_inet_server

# ps -axfw | grep isql
55581  1  I+     0:00,05 isql-fb -USER SYSDBA -PASS masterkey

# fuser /var/db/firebird/security2.fdb
/var/db/firebird/security2.fdb: 55581w 41417w

The above attachments will stay there until the connections are closed.

Haris
Comment 4 Jose Alonso Cardenas Marquez freebsd_committer freebsd_triage 2013-10-01 00:58:21 UTC
State Changed
From-To: feedback->closed

- It has been fixed with my latest commit. Please, update your ports tree and  
tell me if you have the same firebird problems
Comment 5 Haris Papadopoulos 2013-10-02 15:12:30 UTC
I can confirm that icu issue has been fixed. However, the issue with the 
security2.fdb attachments still remains. I have the audit trace log 
now(only for security2.fdb):

2013-10-02T16:56:07.8500 (2361:0x8006fbc18) TRACE_INIT
         SESSION_1 Firebird Audit


2013-10-02T16:56:07.8500 (2361:0x8006fbc18) ATTACH_DATABASE
         /var/db/firebird/security2.fdb (ATT_320, SYSDBA:NONE, NONE, 
<internal>)

2013-10-02T16:56:07.8510 (2361:0x8006fbc18) COMPILE_BLR
         /var/db/firebird/security2.fdb (ATT_320, SYSDBA:NONE, NONE, 
<internal>)
-------------------------------------------------------------------------------
    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,
   46                blr_boolean,
   47                   blr_eql,
   48                      blr_field, 0, 13, 
'R','D','B','$','U','S','E','R','_','N','A','M','E',
   64                      blr_parameter, 0, 0,0,
   68                blr_end,
   69             blr_send, 1,
   71                blr_begin,
   72                   blr_assignment,
   73                      blr_field, 0, 7, 'R','D','B','$','G','I','D',
   83                      blr_parameter, 1, 0,0,
   87                   blr_assignment,
   88                      blr_field, 0, 7, 'R','D','B','$','U','I','D',
   98                      blr_parameter, 1, 1,0,
  102                   blr_assignment,
  103                      blr_literal, blr_short, 0, 1,0,
  108                      blr_parameter, 1, 2,0,
  112                   blr_assignment,
  113                      blr_field, 0, 10, 
'R','D','B','$','P','A','S','S','W','D',
  126                      blr_parameter, 1, 3,0,
  130                   blr_end,
  131          blr_send, 1,
  133             blr_assignment,
  134                blr_literal, blr_short, 0, 0,0,
  139                blr_parameter, 1, 2,0,
  143          blr_end,
  144    blr_end,
  145 blr_eoc

       0 ms
2013-10-02T16:56:07.8520 (2361:0x8006fbc18) START_TRANSACTION
         /var/db/firebird/security2.fdb (ATT_320, SYSDBA:NONE, NONE, 
<internal>)
                 (TRA_126, CONCURRENCY | WAIT | READ_ONLY)

2013-10-02T16:56:07.8540 (2361:0x8006fbc18) ROLLBACK_TRANSACTION
         /var/db/firebird/security2.fdb (ATT_320, SYSDBA:NONE, NONE, 
<internal>)
                 (TRA_126, CONCURRENCY | WAIT | READ_ONLY)
       0 ms, 1 read(s), 1 write(s), 1 fetch(es), 1 mark(s)

2013-10-02T17:03:51.6320 (2361:0x8006fbc18) DETACH_DATABASE
         /var/db/firebird/security2.fdb (ATT_320, SYSDBA:NONE, NONE, 
<internal>)

2013-10-02T17:03:51.6320 (2361:0x8006fbc18) TRACE_FINI
         SESSION_1 Firebird Audit

Note the time difference for the DETACH_DATABASE. It happens when the 
connection to the database is closed.

/Haris
Comment 6 Jose Alonso Cardenas Marquez freebsd_committer freebsd_triage 2013-10-02 22:52:15 UTC
2013/10/2 Haris Papadopoulos <haris@softways.gr>

> The following reply was made to PR ports/175485; it has been noted by
> GNATS.
>
> From: Haris Papadopoulos <haris@softways.gr>
> To: bug-followup@FreeBSD.org, haris@softways.gr
> Cc:
> Subject: Re: ports/175485: port databases/firebird25-server (classic) keeps
>  attached to security2.fdb for each connection
> Date: Wed, 02 Oct 2013 17:12:30 +0300
>
>  I can confirm that icu issue has been fixed. However, the issue with the
>  security2.fdb attachments still remains. I have the audit trace log
>  now(only for security2.fdb):
>
>  2013-10-02T16:56:07.8500 (2361:0x8006fbc18) TRACE_INIT
>           SESSION_1 Firebird Audit
>
>
>  2013-10-02T16:56:07.8500 (2361:0x8006fbc18) ATTACH_DATABASE
>           /var/db/firebird/security2.fdb (ATT_320, SYSDBA:NONE, NONE,
>  <internal>)
>
>  2013-10-02T16:56:07.8510 (2361:0x8006fbc18) COMPILE_BLR
>           /var/db/firebird/security2.fdb (ATT_320, SYSDBA:NONE, NONE,
>  <internal>)
>
>  -------------------------------------------------------------------------------
>      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,
>     46                blr_boolean,
>     47                   blr_eql,
>     48                      blr_field, 0, 13,
>  'R','D','B','$','U','S','E','R','_','N','A','M','E',
>     64                      blr_parameter, 0, 0,0,
>     68                blr_end,
>     69             blr_send, 1,
>     71                blr_begin,
>     72                   blr_assignment,
>     73                      blr_field, 0, 7, 'R','D','B','$','G','I','D',
>     83                      blr_parameter, 1, 0,0,
>     87                   blr_assignment,
>     88                      blr_field, 0, 7, 'R','D','B','$','U','I','D',
>     98                      blr_parameter, 1, 1,0,
>    102                   blr_assignment,
>    103                      blr_literal, blr_short, 0, 1,0,
>    108                      blr_parameter, 1, 2,0,
>    112                   blr_assignment,
>    113                      blr_field, 0, 10,
>  'R','D','B','$','P','A','S','S','W','D',
>    126                      blr_parameter, 1, 3,0,
>    130                   blr_end,
>    131          blr_send, 1,
>    133             blr_assignment,
>    134                blr_literal, blr_short, 0, 0,0,
>    139                blr_parameter, 1, 2,0,
>    143          blr_end,
>    144    blr_end,
>    145 blr_eoc
>
>         0 ms
>  2013-10-02T16:56:07.8520 (2361:0x8006fbc18) START_TRANSACTION
>           /var/db/firebird/security2.fdb (ATT_320, SYSDBA:NONE, NONE,
>  <internal>)
>                   (TRA_126, CONCURRENCY | WAIT | READ_ONLY)
>
>  2013-10-02T16:56:07.8540 (2361:0x8006fbc18) ROLLBACK_TRANSACTION
>           /var/db/firebird/security2.fdb (ATT_320, SYSDBA:NONE, NONE,
>  <internal>)
>                   (TRA_126, CONCURRENCY | WAIT | READ_ONLY)
>         0 ms, 1 read(s), 1 write(s), 1 fetch(es), 1 mark(s)
>
>  2013-10-02T17:03:51.6320 (2361:0x8006fbc18) DETACH_DATABASE
>           /var/db/firebird/security2.fdb (ATT_320, SYSDBA:NONE, NONE,
>  <internal>)
>
>  2013-10-02T17:03:51.6320 (2361:0x8006fbc18) TRACE_FINI
>           SESSION_1 Firebird Audit
>
>  Note the time difference for the DETACH_DATABASE. It happens when the
>  connection to the database is closed.
>
>  /Haris
>

Hi Haris

if you use firebird like classic server this'll create connections by each
session to security2 database.

isql-fb -USER SYSDBA -PASS masterkey
'localhost:/var/db/firebird/firstdb.fdb'

but if you use firebird like super classic, the connections are managed via
network layer (firebird_server="YES" into /etc/rc.conf). this'll create
just one connection to security2 database

isql-fb -USER SYSDBA -PASS masterkey
'localhost:/var/db/firebird/firstdb.fdb'

fuser - firebird classic server for 4 connections:

 [root@hellfire]# fuser /var/db/firebird/security2.fdb
/var/db/firebird/security2.fdb: 75893w 75885w 75884w 75871w

fuser - firebird super classic for 4 connections:

 [root@hellfire]# fuser /var/db/firebird/security2.fdb
/var/db/firebird/security2.fdb: 75845w

Maybe you could look at
http://www.firebirdsql.org/manual/qsg25-appx-architectures.html. If I'm not
mistaken multiple connections to security2 on classic server are normals.

Greetings
ACM
Comment 7 Haris Papadopoulos 2013-10-04 18:20:39 UTC
Hi,

I 'm sorry to say that this doesn't work for me. I have:

firebird_enable="YES"
firebird_server="YES"
in /etc/rc.conf

root@raindog:~ # pkg_info | grep firebird
firebird-client-2.5.2_2 Firebird-2 database client
firebird-server-2.5.2_2 Firebird-2 relational database (server)

root@raindog:~ # isql-fb -z
ISQL Version: FB-V2.5.2.26540 Firebird 2.5

root@raindog:~ # uname -a
FreeBSD raindog.softways.lan 9.1-STABLE FreeBSD 9.1-STABLE #1: Sat Aug 
31 10:26:40 EEST 2013 
root@raindog.softways.lan:/usr/obj/usr/src/sys/MYKERNEL  amd64

root@raindog:~ # ps -axfw | grep fb_smp
2290  0  I      0:00,15 /usr/local/sbin/fb_smp_server

and I still see as many connections to security2.fdb as the connections 
to the actual database.

I can also understand that for fb_inet_server multiple connections would 
be OK but how can one explain that Firebird 2.1.x fb_inet_server does 
not keep these connections open.

Anyway, I don't know what else to check and it surely bothers me that 
Classic Superserver works for you.

Thanks again,
Greetings
/Haris
Comment 8 Jose Alonso Cardenas Marquez freebsd_committer freebsd_triage 2013-10-04 18:58:48 UTC
2013/10/4 Haris Papadopoulos <haris@softways.gr>

> The following reply was made to PR ports/175485; it has been noted by
> GNATS.
>
> From: Haris Papadopoulos <haris@softways.gr>
> To: bug-followup@FreeBSD.org, haris@softways.gr
> Cc:
> Subject: Re: ports/175485: port databases/firebird25-server (classic) keeps
>  attached to security2.fdb for each connection
> Date: Fri, 04 Oct 2013 20:20:39 +0300
>
>  Hi,
>
>  I 'm sorry to say that this doesn't work for me. I have:
>
>  firebird_enable="YES"
>  firebird_server="YES"
>  in /etc/rc.conf
>
>  root@raindog:~ # pkg_info | grep firebird
>  firebird-client-2.5.2_2 Firebird-2 database client
>  firebird-server-2.5.2_2 Firebird-2 relational database (server)
>
>  root@raindog:~ # isql-fb -z
>  ISQL Version: FB-V2.5.2.26540 Firebird 2.5
>
>  root@raindog:~ # uname -a
>  FreeBSD raindog.softways.lan 9.1-STABLE FreeBSD 9.1-STABLE #1: Sat Aug
>  31 10:26:40 EEST 2013
>  root@raindog.softways.lan:/usr/obj/usr/src/sys/MYKERNEL  amd64
>
>  root@raindog:~ # ps -axfw | grep fb_smp
>  2290  0  I      0:00,15 /usr/local/sbin/fb_smp_server
>
>  and I still see as many connections to security2.fdb as the connections
>  to the actual database.
>
>  I can also understand that for fb_inet_server multiple connections would
>  be OK but how can one explain that Firebird 2.1.x fb_inet_server does
>  not keep these connections open.
>
>  Anyway, I don't know what else to check and it surely bothers me that
>  Classic Superserver works for you.
>
>  Thanks again,
>  Greetings
>  /Haris
>

Hi Haris

are you use localhost:/path/to/database on connection string?

 isql-fb -USER SYSDBA -PASS masterkey
'localhost:/var/db/firebird/firstdb.fdb'

if you only use /path/to/database, your firebird client will connect like
classic server to database defined by you. You must add
'localhost:/path/to/database' if you want to connect like Classic Super
Server (localhost is the trick).

btw, I added Super Server support to firebird25-server. If you update to
latest version, you must add the following to /etc/rc.conf (see message
post installation):

firebird_enable="YES"
firebird_mode="superclassic"

Just remember:

Classic Server
Use inetd -> fb_inet_server -> localhost:/path/to/database or
/path/to/database (mutiple connections to security2)

Super Classic Server
Use rc.d/firebird -> fb_smp_server -> localhost:/path/to/database (one
connection to security2)

Super Server
Use rc.d/firebird -> fbguard -> IP:/path/to/database (one connection to
security2)

Greetings
ACM
Comment 9 Haris Papadopoulos 2013-10-04 19:43:26 UTC
Hi,

Yes! You are totally right! This is the trick. I can confirm that it has 
been fixed. Thank you for your great efforts. Also, great news for 
SuperServer! I will update asap.

Greetings,
Haris