Thread: Problems with DBI, DBD::Pg and Postgres 7.2.

Problems with DBI, DBD::Pg and Postgres 7.2.

From

Johan Mjönes

Date:

23 February 2002, 14:50:55

Hello,

we're writing a small piece of software in Perl, utilizing a Postgres 7.2
database via DBI and DBD::Pg.

Our problem is that we get this message while running our software:

DBD::Pg::db do failed: server closed the connection unexpectedly at
/usr/local/lib/perl5/5.6.1/Atomic/afv3/urls.pm line 542.

The line 542 is just a Do, and I won't type it out since this can choke of any
of the SELECTs or UPDATEs we're doing.

The query it chokes on is among others this one:

UPDATE urldata SET eflags=0,modified='2002-02-23 17:40:52
+0:00',localservertime=1014479227,bytesize=35518,pagecrc=0,counter=counter+1,req
uesttime='0.447651982307434',cache='web/www.hn.se/arkiv.php?avdelning_1=106&mont
h=2&submit=Visa&year=2002' WHERE id = 217

We've tried reducing it, but at that point in the script, it doesn't matter if
we run this query or anything as simple as a very small INSERT or a DELETE, it
all chokes.

We can reproduce this as many times as we want - it always crashes on the same
position, but no matter what the query!

I we run the query from pgAdmin or another perl script (using the same DBI and
DBD::Pg on the same computer), it works flawlessly.

This is the last lines of the log file (level 2 debugging).

--------------------------------------------------------------------------------
----------------------------------------------------------------------

DEBUG:  query: INSERT INTO urldata
(spider_id,session_id,language,source,url,urlcrc,parent,depth,flags,eflags,frame
,mainframe,delete
d,bytesize,pagecrc,contcrc,linkname,linkpos,links,created,modified,counter,lasts
een,requesttime,localservertime,title,summary,cache)

VALUES(22,23,'SV',NULL,'http://www.hn.se/arkiv.php?avdelning_1=127&month=2&submi
t=Visa&year=2002',2471205215,0,0,2,0,0,0,0,0,0,0,''
,0,NULL,'2002-02-23 17:44:21 +0:00','1970-01-01 01:00:00 +0:00',0,'2002-02-23
17:44:21 +0:00',0,0,'','','')
DEBUG:  ProcessQuery
DEBUG:  CommitTransactionCommand
DEBUG:  StartTransactionCommand
DEBUG:  query: SELECT id FROM urldata WHERE spider_id = 22 AND urlcrc =
2471205215
DEBUG:  ProcessQuery
DEBUG:  CommitTransactionCommand
DEBUG:  StartTransactionCommand
DEBUG:  query: SELECT
id,url,session_id,flags,eflags,frame,bytesize,created,modified,localservertime,p
agecrc,contcrc,linkpos,counter
,title,summary FROM urldata WHERE spider_id = 22 AND urlcrc = 3297898899
DEBUG:  ProcessQuery
DEBUG:  CommitTransactionCommand
DEBUG:  StartTransactionCommand
DEBUG:  query: INSERT INTO urldata
(spider_id,session_id,language,source,url,urlcrc,parent,depth,flags,eflags,frame
,mainframe,delete
d,bytesize,pagecrc,contcrc,linkname,linkpos,links,created,modified,counter,lasts
een,requesttime,localservertime,title,summary,cache)

VALUES(22,23,'SV',NULL,'http://www.hn.se/arkiv.php?avdelning_1=161&month=2&submi
t=Visa&year=2002',3297898899,0,0,2,0,0,0,0,0,0,0,''
,0,NULL,'2002-02-23 17:44:21 +0:00','1970-01-01 01:00:00 +0:00',0,'2002-02-23
17:44:21 +0:00',0,0,'','','')
DEBUG:  ProcessQuery
DEBUG:  CommitTransactionCommand
DEBUG:  StartTransactionCommand
DEBUG:  query: SELECT id FROM urldata WHERE spider_id = 22 AND urlcrc =
3297898899
DEBUG:  ProcessQuery
DEBUG:  CommitTransactionCommand
DEBUG:  StartTransactionCommand
DEBUG:  query: SELECT
id,url,session_id,flags,eflags,frame,bytesize,created,modified,localservertime,p
agecrc,contcrc,linkpos,counter
,title,summary FROM urldata WHERE spider_id = 22 AND urlcrc = 1001135336
DEBUG:  ProcessQuery
DEBUG:  CommitTransactionCommand
DEBUG:  StartTransactionCommand
DEBUG:  query: INSERT INTO urldata
(spider_id,session_id,language,source,url,urlcrc,parent,depth,flags,eflags,frame
,mainframe,delete
d,bytesize,pagecrc,contcrc,linkname,linkpos,links,created,modified,counter,lasts
een,requesttime,localservertime,title,summary,cache)

VALUES(22,23,'SV',NULL,'http://www.hn.se/arkiv.php?avdelning_1=170&month=2&submi
t=Visa&year=2002',1001135336,0,0,2,0,0,0,0,0,0,0,''
,0,NULL,'2002-02-23 17:44:21 +0:00','1970-01-01 01:00:00 +0:00',0,'2002-02-23
17:44:21 +0:00',0,0,'','','')
DEBUG:  ProcessQuery
DEBUG:  CommitTransactionCommand
DEBUG:  StartTransactionCommand
DEBUG:  query: SELECT id FROM urldata WHERE spider_id = 22 AND urlcrc =
1001135336
DEBUG:  ProcessQuery
DEBUG:  CommitTransactionCommand
DEBUG:  proc_exit(0)
DEBUG:  shmem_exit(0)
DEBUG:  exit(0)
DEBUG:  reaping dead processes
DEBUG:  child process (pid 24958) exited with exit code 0

--------------------------------------------------------------------------------
----------------------------------------------------------------------

As you can see, this log doesn't note the last UPDATE query that fails, it just
claims that we lost connection and the child process exited with exit code 0.

Before this query
8 INSERTS
1 SELECT (to get the ID on which to run the UPDATE)
is run.

Does anybody have a clue? At least we don't :(

Best Regards,

Johan Mjönes

_______________________________________
Johan Mjönes        johan.mjones@agent25.se
Programmerare        08 - 527 90 464
Agent25            070 - 528 38 55



_______________________________________
Johan Mjönes        johan.mjones@agent25.se
Programmerare        08 - 527 90 464
Agent25            070 - 528 38 55

Re: Problems with DBI, DBD::Pg and Postgres 7.2.

From

Tom Lane

Date:

23 February 2002, 17:19:59

=?iso-8859-1?Q?Johan_Mj=F6nes?= <johan.mjones@agent25.se> writes:
> We can reproduce this as many times as we want - it always crashes on
> the same position, but no matter what the query!

Odd.  The postmaster log fragment you show contains no indication that
there's anything wrong, AFAICS.  Even odder, there's no complaint about
an unexpected client disconnect, so it would seem that the client side
sent a deliberate disconnect (X) command.

One idea that comes to mind is that perhaps either the client or server
side is running under "ulimit" restrictions that kick in right here.
That doesn't seem to explain your symptoms, but some related idea might
be the right answer.

It might be possible to learn something by attaching to the backend
process with gdb and setting a breakpoint at proc_exit, so you could
see where it's being called from.  If it's not reacting to an "X"
command then we'd learn what is making it exit.

            regards, tom lane

Re: Problems with DBI, DBD::Pg and Postgres 7.2.

From

"Greg Sabino Mullane"

Date:

24 February 2002, 11:28:55

-----BEGIN PGP SIGNED MESSAGE-----
Hash: SHA1


> Our problem is that we get this message while running our software:

> DBD::Pg::db do failed: server closed the connection unexpectedly at
> /usr/local/lib/perl5/5.6.1/Atomic/afv3/urls.pm line 542.

Look at the code around it - it looks to me as if your script is hamstringing
itself by disconnecting from the database without letting itself know about
it. Take a careful look at the code around it. If you are using fork, then
that's your problem - when you fork, whichever dies first (the parent or the
child) will take the connection to the database down with it, via DBI's
cleanup subroutine, which implicitly does a $dbh->disconnect. The relative
will still have what it thinks is a live connection to the database, but
will get the error above when it realizes that there is nobody listening on
the other end anymore. In other words, something like this:

#!/usr/bin/perl

use DBI;
use strict;

## Proof of concept of "server closed" message caused by forking

my $dbh = DBI->connect("dbi:Pg:dbname=test;port=5432",
          'joesizpack', 'tanstaafl', { AutoCommit => 0, RaiseError => 1 } );

if (fork) {
  ## I am the parent
  sleep sleep(1);
  $dbh->do("SELECT VERSION()");
  exit;
}

## I am the child
exit; ## Disconnects from database, $dbh no longer active



When you run the above code, $dbh gets set as normal. After the fork,
while the parent sleeps, the child exits and in the process disconnects
from the database, telling the server that we are done. The parent is
using the same variable but there is nobody on the other end. To the
parent, it looks as if the server has dropped the connection. It has, but
only because its child asked it to. :)

If this is the problem (and obviously I suspect it is or I would not have
done so much typing!) workarounds include (1) opening up a new database
connection for every child (use a different variable than $dbh), (2) waiting
to open the database connection until after the forks (basically achieves the
same effect), or use the "InactiveDestroy" attribute when opening the
initial connection to the database (see perldoc DBI for details). The last
way is probably the best overall solution because it does more of what you
might "expect", but may not work on other databases (e.g. Oracle) if you ever
intend your code to run elsewhere.

HTH,
Greg Sabino Mullane  greg@turnstep.com
PGP Key: 0x14964AC8 200202240835

-----BEGIN PGP SIGNATURE-----
Comment: http://www.turnstep.com/pgp.html

iD8DBQE8eOxsvJuQZxSWSsgRAuFdAKDojhWpWpQmPJ6cX+hXLiI5RY+PJgCeKGD1
OetaWUVlsIb9UOI7bbA3EH0=
=VXOh
-----END PGP SIGNATURE-----