Issue Details (XML | Word | Printable)

Key: CORE-3859
Type: Bug Bug
Status: Closed Closed
Resolution: Fixed
Priority: Major Major
Assignee: Alexander Peshkov
Reporter: Pete Cervasio
Votes: 0
Watchers: 6
Operations

If you were logged in you would be able to see more operations.
Firebird Core

Too many different dynamic events crash server

Created: 30/May/12 07:04 PM   Updated: 18/Jan/16 04:01 PM
Component/s: Engine
Affects Version/s: 2.1.3, 2.0.6, 2.1.4, 2.0.7, 2.1.5
Fix Version/s: 2.1.6

Environment: CentOS 5 (5.5 and 5.8)

QA Status: No test


 Description  « Hide
A recent change to how our software is using triggers to create dynamic events has been found to crash the firebird server.

Our software is watching for changes to a 'PLAYLIST' table which has entries containing station number and date and time values. Since the system doesn't care about changes that are not within the immediate time frame a dynamic set of events was created in the form of 'PLAYLIST_INSERTED_x_yyyy-mm-dd_hh' where 'x' is a station number, 'yyyy-mm-dd' is the contents of a date field, and 'hh' is the first two characters of the scheduled time field. At the start of each hour, the program registers interest in the current and next hours.

After approximately 616 event registrations and event occurrences, the Firebird server will crash. Changing the length of the event names to use a single character 'I' instead of 'PLAYLIST_INSERTED_' makes that number jump a bit higher, but the crash still happens.

Operating system : CentOS 5.8 (but also tested on 5.5)
Firebird server : Tested on versions 2.0.6, 2.0.7, 2.1.4 and 2.1.5 release candidate (from 22 May 2012)

Server log when the crash happens:

~>tail /opt/firebird/firebird.log

serv1-0000.sbcglobal.net (Client) Mon May 28 14:26:04 2012
        /opt/firebird/bin/fbguard: /opt/firebird/bin/fbserver terminated abnormally (-1)



serv1-0000.sbcglobal.net (Client) Mon May 28 14:26:04 2012
        /opt/firebird/bin/fbguard: guardian starting bin/fbserver


Sample database:

-- ------------------------------------------------------------
-- ISQL scriptlet:

create database '/tmp/event_fail.fdb';

-- A table with the bare minimum to show this problem:
create table playlist (
    station_number integer not null,
    scheduled_date date not null,
    scheduled_time varchar(12) not null
);

-- Two triggers to go with it:
set term ;!!

create trigger pe_playlist_deleted for playlist
       active after delete position 0 as
begin
    post_event 'PLAYLIST_DELETED_' || old.station_number || '_' ||
    old.scheduled_date || '_' || substring(old.scheduled_time from 1 for 2);
end !!

create trigger pe_playlist_inserted for playlist
       active after insert position 0 as
begin
    post_event 'PLAYLIST_INSERTED_' || new.station_number || '_' ||
    new.scheduled_date || '_' || substring(new.scheduled_time from 1 for 2);
end !!
-- Two stored procedure with same params as our regular ones
create procedure insert_log_entry (
    station_num integer,
    dt date,
    tm varchar(12),
    id varchar(250),
    cluster integer,
    mandatory varchar(1))
returns
    (curr integer)
as
begin
    insert into playlist values (:station_num, :dt, :tm);
    curr = 0;
end !!

-- Unused in perl script, my pascal calls on it, though
create procedure remove_log_entry (
    station_num integer,
    curr integer)
returns
    (next integer)
as
begin
    delete from playlist where station_number = :station_num;
    next = 0;
end !!

set term ;!!

commit;

You might want to add that to your aliases:

echo "event_fail = /tmp/event_fail.fdb" >> /opt/firebird/aliases.conf

And here is a perl script which will show the error. I'm sure real perl programmers will cringe at this.

#!/usr/bin/perl -w
#
# Note: This needs DBI::InterBase. It might work with DBI::Firebird
# but I haven't tried it.
#
# Usage: $0 dbserver:database

use strict;
use DBI;
use POSIX qw(strftime mktime);

my $dsn = shift; # $ARGV[0] - Specified as dbhost:dbname.

my $DB_USER = 'sysdba';
my $DB_PASS = 'masterkey';

my ($dbhost, $dbname) = split ':', $dsn;

my $db = "dbi:InterBase:db=$dbname;host=$dbhost;ib_dialect=3";

my $dbi = DBI->connect($db, $DB_USER, $DB_PASS, { PrintError => 0,
                                                  RaiseError => 0,
                                                  AutoCommit => 1 })
    or die "FATAL ERROR: DBI->connect to $dsn failed";

# Counter for events.
my $want_events = 0;

# -----------------------------------------------------
# Event callback function
# -----------------------------------------------------
sub handle_event {
    my $pe = shift;

    while (my ($k, $v) = each %$pe) {
        print "Got event $k\n";
    }
    $want_events--;
    1;
}

my $station = 1;
my $curr_date = mktime(0, 0, 0, 1, 0, 110); # 01 Jan 2010 @00:00
my $end_date = mktime(0, 0, 0, 1, 0, 111); # 01 Jan 2011 @00:00

my $sql;

my $ev1 = "";
my $ev2 = "";

while ($curr_date < $end_date) {

    my ($sec,$min,$hour,$mday,$mon,$year,$wday,$yday) = localtime($curr_date);

    my $dd = strftime ('%F', localtime($curr_date));
    my $hh = sprintf ('%.2d', $hour);
    my $tt = "${hh}:000:00.00";

    # Only using one here. Kylix test program (and real application)
    # use both of these, so this script registers for both.
    $ev1 = "PLAYLIST_INSERTED_${station}_${dd}_${hh}";
    $ev2 = "PLAYLIST_DELETED_${station}_${dd}_${hh}";

    my $evh = $dbi->func($ev1, $ev2, 'ib_init_event');

    # Set the callback
    $dbi->func($evh, \&handle_event, 'ib_register_callback');

    $want_events = 1;
    $sql = "execute procedure insert_log_entry (?, ?, ?, ?, ?, ?)";
    my $sth = $dbi->prepare($sql);

    my $res = $sth->execute($station, $dd, $tt, 'Event Test Entry', 0, 'N');

    print "Inserted $dd $hh\n";

    $sth->finish;

    while ($want_events > 0) {
        sleep 1;
    }

    $dbi->func($evh, 'ib_cancel_callback');

    # Bump to next hour and repeat
    $curr_date += 3600;

}

$dbi->disconnect;


When I run the above perl, I get this as output:


~ $perl event_test.pl "serv1-0000:event_fail"
Inserted 2010-01-01 00
Got event PLAYLIST_INSERTED_1_2010-01-01_00
Inserted 2010-01-01 01
Got event PLAYLIST_INSERTED_1_2010-01-01_01
............much elided.....
Inserted 2010-01-13 17
Got event PLAYLIST_INSERTED_1_2010-01-13_17
Inserted 2010-01-13 18
Got event PLAYLIST_INSERTED_1_2010-01-13_18
DBD::InterBase::db::ib_register_callback() -- ev is not a blessed SV reference at event_test.pl line 91.
Can't call method "execute" on an undefined value at event_test.pl line 97.
Broken pipe

and over on the server is another instance of terminating abnormally.

Things I've tried:

a). Making the event names shorter as in PI_{date}_{hour}

b). Table modification to store hour as an integer value and having the trigger use that instead of calling on substring.

Both of those changes were for naught.


 All   Comments   Change History   Subversion Commits      Sort Order: Ascending order - Click to sort in descending order
There are no subversion log entries for this issue yet.