Обсуждение: Trigger only firing once

Anyone have any clues as to my question yesterday re: why my trigger
only fires on the first insert per connection?  After posting yesterday,
I tried a few different things, but the only thing that works (and
obviously not the most efficient thing to do) is to disconnect and
reconnect after every insert.

This trigger is:

create trigger log_trigger
before insert on log
for each row
execute procedure update_host_table();

The trigger runs fine, the procedure it calls runs fine, but it only
executes the
trigger once per connection.

The odd thing is that I generated the trigger and the procedure from a
text file of sql which hasn't changed in weeks.  It worked perfectly in
postgresql 7.0, but now that I think about it, I can't confirm it ever
working correctly in 7.1 since I upgraded earlier in the week.

Thanks,
Fran

Fran Fabrizio <ffabrizio@Exchange.WebMD.net> writes:
> Anyone have any clues as to my question yesterday re: why my trigger
> only fires on the first insert per connection?

Kinda hard to believe.  Can you provide a self-contained example?

            regards, tom lane

> Kinda hard to believe.

I know it, but that's what I am seeing..... (to recap, my trigger only
fires on the first insert per connection.)

This will be kind of long, it's a spliced-together version of my psql
client session and the server log.  I drop and re-create the procedure
and trigger, then I'll connect and test, and disconnect and reconnect and
show you what's happening.  Comments with ***** stars around them
**** are my running commentary to make following this session easier.

***** First, I use the text file to drop and recreate the procedure and
trigger.  *****

postgres@rusty ~$ psql monitoring < log_trigger
DROP
DROP
CREATE
CREATE
postgres@rusty ~$

***** Server log shows dropping and creating (long procedure, sorry)
*****

2001-05-14 11:51:12 DEBUG:  StartTransactionCommand
2001-05-14 11:51:12 DEBUG:  query: /* trigger to update the host table
for incoming records
The trigger will update the update the date and timestamps
for the host, insert a newhost if one is not found */
drop function update_host_table();
2001-05-14 11:51:12 DEBUG:  ProcessUtility: /* trigger to update the host
table for incoming records
The trigger will update the update the date and timestamps
for the host, insert a newhost if one is not found */
drop function update_host_table();
2001-05-14 11:51:12 DEBUG:  CommitTransactionCommand
2001-05-14 11:51:12 DEBUG:  StartTransactionCommand
2001-05-14 11:51:12 DEBUG:  query: drop trigger log_trigger on log ;
2001-05-14 11:51:12 DEBUG:  ProcessUtility: drop trigger log_trigger on
log ;
2001-05-14 11:51:12 DEBUG:  CommitTransactionCommand
2001-05-14 11:51:12 DEBUG:  StartTransactionCommand
2001-05-14 11:51:12 DEBUG:  query: create function update_host_table()
returns opaque
as 'declare

site_rec        record;
host_rec        record;
status_rec      record;

begin

new.tstamp := now() ;
/* check to see if we have see this site before */

select  * into site_rec
from sites s
        where s.fqdn = new.fqdn ;

/* -- if we have not found the machine name we are going to
insert a new record into the sites table and set the init_contact to now
*/

if not found
then
        insert into sites
        values
(nextval(''sites_site_id_seq''),new.fqdn,new.site,new.region,''f'',new.tstamp)
;

        /* we also have to insert a new host if this is a new site */


        insert into hosts
        values
(nextval(''hosts_host_id_seq''),currval(''sites_site_id_seq''),new.hostname,new.tstamp)
;

        /* now update the incoming record with the new host_id and
site_id */
        new.site_id=currval(''sites_site_id_seq'');
        new.host_id=currval(''hosts_host_id_seq'');

else
        /* we have seen the site before, update the incoming records
site_id */

        new.site_id = site_rec.site_id ;

        /* if we have seen this site before we need to check and see if
        we have ever seen this machine before */

        select * into host_rec
        from hosts h
                where h.hostname = new.hostname and
                h.site_id = site_rec.site_id ;

        /* new host */
        if not found
        then
                insert into hosts
                values
(nextval(''hosts_host_id_seq''),site_rec.site_id,new.hostname,new.tstamp)
;
                new.host_id = currval(''hosts_host_id_seq'');
        else
                new.host_id = host_rec.host_id ;

                update hosts
                set last_contact = new.tstamp
                where hosts.host_id = new.host_id ;
        end if ;

/*      update sites
        set last_contact = new.tstamp
        where sites.fqdn = new.fqdn ; */
end if ;


/* now we are going to update the status table with the new record */

select * into status_rec
        from status s where
        s.site_id = new.site_id and
        s.host_id = new.host_id and
        s.product = new.product and
        s.class = new.class and
        s.subclass = new.subclass ;

/* new monitored process */

if not found
then
        insert into status
        values (new.site_id,
                new.host_id,
                new.product,
                new.class,
                new.subclass,
                new.status,
                new.msg,
                new.tstamp);
else
        update status
        set status = new.status,
        tstamp = new.tstamp
        where site_id = new.site_id and
                host_id = new.host_id and
                product = new.product and
                class = new.class and
                subclass = new.subclass ;
end if ;
return new;
end ;'
language 'plpgsql';
2001-05-14 11:51:12 DEBUG:  ProcessUtility: create function
update_host_table()
returns opaque
as 'declare

site_rec        record;
host_rec        record;
status_rec      record;

begin

new.tstamp := now() ;
/* check to see if we have see this site before */

select  * into site_rec
from sites s
        where s.fqdn = new.fqdn ;

/* -- if we have not found the machine name we are going to
insert a new record into the sites table and set the init_contact to now
*/

if not found
then
        insert into sites
        values
(nextval(''sites_site_id_seq''),new.fqdn,new.site,new.region,''f'',new.tstamp)
;

        /* we also have to insert a new host if this is a new site */

        insert into hosts
        values
(nextval(''hosts_host_id_seq''),currval(''sites_site_id_seq''),new.hostname,new.tstamp)
;

        /* now update the incoming record with the new host_id and
site_id */
        new.site_id=currval(''sites_site_id_seq'');
        new.host_id=currval(''hosts_host_id_seq'');

else
        /* we have seen the site before, update the incoming records
site_id */

        new.site_id = site_rec.site_id ;

        /* if we have seen this site before we need to check and see if
        we have ever seen this machine before */

        select * into host_rec
        from hosts h
                where h.hostname = new.hostname and
                h.site_id = site_rec.site_id ;

        /* new host */
        if not found
        then
                insert into hosts
                values
(nextval(''hosts_host_id_seq''),site_rec.site_id,new.hostname,new.tstamp)
;
                new.host_id = currval(''hosts_host_id_seq'');
        else
                new.host_id = host_rec.host_id ;

                update hosts
                set last_contact = new.tstamp
                where hosts.host_id = new.host_id ;
        end if ;

/*      update sites
        set last_contact = new.tstamp
        where sites.fqdn = new.fqdn ; */
end if ;


/* now we are going to update the status table with the new record */


select * into status_rec
        from status s where
        s.site_id = new.site_id and
        s.host_id = new.host_id and
        s.product = new.product and
        s.class = new.class and
        s.subclass = new.subclass ;

/* new monitored process */

if not found
then
        insert into status
        values (new.site_id,
                new.host_id,
                new.product,
                new.class,
                new.subclass,
                new.status,
                new.msg,
                new.tstamp);
else
        update status
        set status = new.status,
       tstamp = new.tstamp
        where site_id = new.site_id and
                host_id = new.host_id and
                product = new.product and
                class = new.class and
                subclass = new.subclass ;
end if ;
return new;
end ;'
language 'plpgsql';
2001-05-14 11:51:12 DEBUG:  CommitTransactionCommand

**** This is where the trigger is created  ******

2001-05-14 11:51:12 DEBUG:  StartTransactionCommand
2001-05-14 11:51:12 DEBUG:  query: create trigger log_trigger
before insert on log
for each row
execute procedure update_host_table();
2001-05-14 11:51:12 DEBUG:  ProcessUtility: create trigger log_trigger
before insert on log
for each row
execute procedure update_host_table();
2001-05-14 11:51:12 DEBUG:  CommitTransactionCommand
2001-05-14 11:51:12 DEBUG:  proc_exit(0)

****** Now I connect to the database ******

2001-05-14 11:55:01 DEBUG:  connection: host=[local] user=postgres
database=monitoring
2001-05-14 11:55:01 DEBUG:  InitPostgres
2001-05-14 11:55:01 DEBUG:  StartTransactionCommand
2001-05-14 11:55:01 DEBUG:  query: SELECT usesuper FROM pg_user WHERE
usename = 'postgres'
2001-05-14 11:55:01 DEBUG:  ProcessQuery
2001-05-14 11:55:01 DEBUG:  CommitTransactionCommand

***** and I do an insert into the 'log' table   *****

monitoring=# insert into log values
(0,0,lower(''),lower(''),lower(''),lower('hostname.changed.com'),upper('Med'),
upper('Apps'), upper('Medssld'), upper('INFO'), '1  medssld(s) running.',
'20010513 23:45:00');
INSERT 2291562 1
monitoring=#

****** and you see from the server log that the trigger fired

2001-05-14 12:00:17 DEBUG:  StartTransactionCommand
2001-05-14 12:00:17 DEBUG:  query: insert into log values
(0,0,lower(''),lower(''),lower(''),lower('hostname.changed.com'),upper('Med'),
upper('Apps'), upper('Medssld'), upper('INFO'), '1  medssld(s) running.',
'20010513 23:45:00');
2001-05-14 12:00:17 DEBUG:  ProcessQuery

***** the following is the trigger behavior *****

2001-05-14 12:00:17 DEBUG:  query: SELECT  now()
2001-05-14 12:00:17 DEBUG:  query: SELECT  * from sites s where s.fqdn =
$1
2001-05-14 12:00:17 DEBUG:  query: SELECT  not  $1
2001-05-14 12:00:17 DEBUG:  query: SELECT   $1
2001-05-14 12:00:17 DEBUG:  query: SELECT  * from hosts h where
h.hostname =  $1  and h.site_id =  $2
2001-05-14 12:00:17 DEBUG:  query: SELECT  not  $1
2001-05-14 12:00:17 DEBUG:  query: SELECT   $1
2001-05-14 12:00:17 DEBUG:  query: update hosts set last_contact =  $1
where hosts.host_id =  $2
2001-05-14 12:00:17 DEBUG:  query: SELECT  not  $1
2001-05-14 12:00:17 DEBUG:  query: SELECT   $1
2001-05-14 12:00:17 DEBUG:  query: update hosts set last_contact =  $1
where hosts.host_id =  $2
2001-05-14 12:00:17 DEBUG:  query: SELECT  * from status s where
s.site_id =  $1  and s.host_id =  $2  and s.product =  $3  and s.class =
$4  and s.subclass =  $5
2001-05-14 12:00:17 DEBUG:  query: SELECT  not  $1
2001-05-14 12:00:17 DEBUG:  query: update status set status =  $1 ,
tstamp =  $2  where site_id =  $3  and host_id =  $4  and product =  $5
and class =  $6  and subclass =  $7
2001-05-14 12:00:17 DEBUG:  CommitTransactionCommand

***** I then immediately insert again, changing the timestamp by 15
minutes for clarity of tracking the behavior *****

monitoring=# insert into log values
(0,0,lower(''),lower(''),lower(''),lower('hostname.changed.com'),upper('Med'),
upper('Apps'), upper('Medssld'), upper('INFO'), '1  medssld(s) running.',
'20010513 00:00:00');
INSERT 2292069 1
monitoring=#

******* Here is the server log this time around   *******

2001-05-14 12:02:54 DEBUG:  StartTransactionCommand
2001-05-14 12:02:54 DEBUG:  query: insert into log values
(0,0,lower(''),lower(''),lower(''),lower('hostname.changed.com'),upper('Med'),
upper('Apps'), upper('Medssld'), upper('INFO'), '1  medssld(s) running.',
'20010513 00:00:00');
2001-05-14 12:02:54 DEBUG:  ProcessQuery
2001-05-14 12:02:54 DEBUG:  CommitTransactionCommand

****** Note, NO TRIGGER firing!  So I disconnect and reconnect....  *****

2001-05-14 12:04:24 DEBUG:  proc_exit(0)
2001-05-14 12:04:24 DEBUG:  shmem_exit(0)
2001-05-14 12:04:24 DEBUG:  exit(0)
postmaster: reaping dead processes...
postmaster: CleanupProc: pid 1986 exited with status 0
postmaster: ServerLoop:         handling reading 5
postmaster: ServerLoop:         handling reading 5
postmaster: ServerLoop:         handling writing 5
postmaster: BackendStartup: pid 1989 user postgres db monitoring socket 5

postmaster child[1989]: starting with (postgres -d2 -v131072 -p
monitoring )
FindExec: searching PATH ...
ValidateBinary: can't stat "/sbin/postgres"
ValidateBinary: can't stat "/usr/sbin/postgres"
ValidateBinary: can't stat "/bin/postgres"
ValidateBinary: can't stat "/usr/bin/postgres"
ValidateBinary: can't stat "/usr/local/bin/postgres"
ValidateBinary: can't stat "/usr/bin/X11/postgres"
ValidateBinary: can't stat "/usr/local/bin/postgres"
FindExec: found "/usr/local/pgsql/bin//postgres" using PATH
2001-05-14 12:04:24 DEBUG:  connection: host=[local] user=postgres
database=monitoring
2001-05-14 12:04:24 DEBUG:  InitPostgres
2001-05-14 12:04:24 DEBUG:  StartTransactionCommand
2001-05-14 12:04:24 DEBUG:  query: SELECT usesuper FROM pg_user WHERE
usename = 'postgres'
2001-05-14 12:04:24 DEBUG:  ProcessQuery
2001-05-14 12:04:24 DEBUG:  CommitTransactionCommand

***** And I try insert #2 again.... ******

monitoring=# insert into log values
(0,0,lower(''),lower(''),lower(''),lower('hostname.changed.com'),upper('Med'),
upper('Apps'),
monitoring(# upper('Medssld'), upper('INFO'), '1  medssld(s) running.',
'20010513 00:00:00');
INSERT 2292070 1


2001-05-14 12:05:47 DEBUG:  StartTransactionCommand
2001-05-14 12:05:47 DEBUG:  query: insert into log values
(0,0,lower(''),lower(''),lower(''),lower('hostname.changed.com'),upper('Med'),
upper('Apps'),
upper('Medssld'), upper('INFO'), '1  medssld(s) running.', '20010513
00:00:00');
2001-05-14 12:05:47 DEBUG:  ProcessQuery
2001-05-14 12:05:47 DEBUG:  query: SELECT  now()
2001-05-14 12:05:47 DEBUG:  query: SELECT  * from sites s where s.fqdn =
$1
2001-05-14 12:05:47 DEBUG:  query: SELECT  not  $1
2001-05-14 12:05:47 DEBUG:  query: SELECT   $1
2001-05-14 12:05:47 DEBUG:  query: SELECT  * from hosts h where
h.hostname =  $1  and h.site_id =  $2
2001-05-14 12:05:47 DEBUG:  query: SELECT  not  $1
2001-05-14 12:05:47 DEBUG:  query: SELECT   $1
2001-05-14 12:05:47 DEBUG:  query: update hosts set last_contact =  $1
where hosts.host_id =  $2
2001-05-14 12:05:47 DEBUG:  query: SELECT  * from status s where
s.site_id =  $1  and s.host_id =  $2  and s.product =  $3  and s.class =
$4  and s.subclass =  $5
2001-05-14 12:05:47 DEBUG:  query: SELECT  not  $1
2001-05-14 12:05:47 DEBUG:  query: update status set status =  $1 ,
tstamp =  $2  where site_id =  $3  and host_id =  $4  and product =  $5
and class =  $6  and subclass =  $7
2001-05-14 12:05:48 DEBUG:  CommitTransactionCommand

***** And sure enough, the trigger fires.  *****

So, I'm not imagining things, at least.  What I can't figure out is why
this was working under 7.0 and not 7.1.   I'm using the same text file to
create the procedure and trigger.  Weird, eh?

-Fran

Fran Fabrizio <ffabrizio@Exchange.WebMD.net> writes:
>> Kinda hard to believe.

> I know it, but that's what I am seeing..... (to recap, my trigger only
> fires on the first insert per connection.)

> [snip]

> ******* Here is the server log this time around   *******

> 2001-05-14 12:02:54 DEBUG:  StartTransactionCommand
> 2001-05-14 12:02:54 DEBUG:  query: insert into log values
> (0,0,lower(''),lower(''),lower(''),lower('hostname.changed.com'),upper('Med'),
> upper('Apps'), upper('Medssld'), upper('INFO'), '1  medssld(s) running.',
> '20010513 00:00:00');
> 2001-05-14 12:02:54 DEBUG:  ProcessQuery
> 2001-05-14 12:02:54 DEBUG:  CommitTransactionCommand

> ****** Note, NO TRIGGER firing!  So I disconnect and reconnect....  *****

This does NOT show that no trigger fired.  What it shows is that no
queries within the trigger needed to be recompiled.  The log entries
you are looking at come from the parser when a query is compiled, not
from plpgsql execution.

Try adding some "raise NOTICE" or "raise DEBUG" messages to your trigger
procedure to see what's really happening.

(Yes, I know that plpgsql could do with some better tracing/debugging
facilities than it's got.  Any volunteers out there?)

            regards, tom lane

Tom Lane wrote:
> Fran Fabrizio <ffabrizio@Exchange.WebMD.net> writes:
> >> Kinda hard to believe.
>
> > I know it, but that's what I am seeing..... (to recap, my trigger only
> > fires on the first insert per connection.)
>
> > [snip]
>
> > ******* Here is the server log this time around   *******
>
> > 2001-05-14 12:02:54 DEBUG:  StartTransactionCommand
> > 2001-05-14 12:02:54 DEBUG:  query: insert into log values
> > (0,0,lower(''),lower(''),lower(''),lower('hostname.changed.com'),upper('Med'),
> > upper('Apps'), upper('Medssld'), upper('INFO'), '1  medssld(s) running.',
> > '20010513 00:00:00');
> > 2001-05-14 12:02:54 DEBUG:  ProcessQuery
> > 2001-05-14 12:02:54 DEBUG:  CommitTransactionCommand
>
> > ****** Note, NO TRIGGER firing!  So I disconnect and reconnect....  *****
>
> This does NOT show that no trigger fired.  What it shows is that no
> queries within the trigger needed to be recompiled.  The log entries
> you are looking at come from the parser when a query is compiled, not
> from plpgsql execution.
>
> Try adding some "raise NOTICE" or "raise DEBUG" messages to your trigger
> procedure to see what's really happening.
>
> (Yes, I know that plpgsql could do with some better tracing/debugging
> facilities than it's got.  Any volunteers out there?)

    Hands  off  please.  I  have some drastic changes to PL/pgSQL
    outstanding that'll implement  *real*  cursor  support.  I'll
    look at tracing while at it. Stay tuned...


Jan

--

#======================================================================#
# It's easier to get forgiveness for being wrong than for being right. #
# Let's break this rule - forgive me.                                  #
#================================================== JanWieck@Yahoo.com #



_________________________________________________________
Do You Yahoo!?
Get your free @yahoo.com address at http://mail.yahoo.com