Re: [BUGS] BUG #1061: message type 0x49 arrived from server while

#1

--Multipart_Thu__22_Jan_2004_20_05_09_-0700_=.zVMFUDkjHJwc81
Content-Type: text/plain; charset=US-ASCII
Content-Disposition: inline
Content-Transfer-Encoding: 7bit

When grilled further on (Thu, 22 Jan 2004 14:27:19 -0500),
Tom Lane <tgl (AT) sss (DOT) pgh.pa.us> confessed:

Quote:

"PostgreSQL Bugs List" <pgsql-bugs (AT) postgresql (DOT) org> writes:
Description: message type 0x49 arrived from server while idle

Hm. This would seem to have something to do with issuing empty queries
(message type 0x49 = 'I' is EmptyQueryResponse). I couldn't duplicate the
problem in some simple tests, however. Unless you can come up with more
information, there's not a lot I can do ...

What more information would you be looking for? I'm thinking that maybe the
query that was executed (or not executed)? I looked at the log and there was no
info other than "unexpected EOF on client connection", which I get regularly
from my multi-process program. I'll turn on logging of all queries to see if
any happen to be empty. I don't believe I'm executing empty queries, and the
problem is not reproducible by running the same program multiple times. It just
shows up every now and then.

I was not getting this error while running 7.4Beta4, but that was running on
Solaris 2.8 and compiled with GCC 3.1. The same 7.3.3 PGSQL would of been used
in this instance.

Quote:

The PGSQL version on Solaris is 7.3.3, but that shouldn't matter?

No, that's *extremely* relevant, because it means the wire protocol is
going to be 2.0 not 3.0. I couldn't get anything funny to happen by
issuing empty queries with a 7.3 libpq and a 7.4 server, though.

I'll look into doing an install of the client side only (7.4.1) that I can
access when running my scripts, and re-install DBD::Pg against that version.
Probably won't happen 'till next week at the earliest though.

Cheers,
Rob

--
19:48:21 up 25 days, 9:35, 4 users, load average: 2.49, 2.43, 2.18

--Multipart_Thu__22_Jan_2004_20_05_09_-0700_=.zVMFUDkjHJwc81
Content-Type: application/pgp-signature

-----BEGIN PGP SIGNATURE-----
Version: GnuPG v1.2.2 (GNU/Linux)

iEYEARECAAYFAkAQj2sACgkQLQ/DKuwDYzmi9QCeIxaohsJUwJkAPF00Wyy4Pp+n
5lYAn3SvNE7NuFHv9l3c56ZH25QRpkEN
=reIF
-----END PGP SIGNATURE-----

--Multipart_Thu__22_Jan_2004_20_05_09_-0700_=.zVMFUDkjHJwc81--

#2

--Multipart_Thu__22_Jan_2004_20_48_19_-0700_=.3u2dB(+D(x/7MH
Content-Type: text/plain; charset=US-ASCII
Content-Disposition: inline
Content-Transfer-Encoding: 7bit

When grilled further on (Thu, 22 Jan 2004 22:19:44 -0500),
Tom Lane <tgl (AT) sss (DOT) pgh.pa.us> confessed:

Quote:

Robert Creager <Robert_Creager (AT) LogicalChaos (DOT) org> writes:
What more information would you be looking for?

Well, in the words of the old saw, if we knew what we were looking for
it wouldn't be research ...

That's fine. The 'tone' of your e-mail led me to believe I wasn't providing
something obvious, which I could believe.

Quote:

I'm sure we could solve it quickly if we could get a reproducible test
case, but it sounds like you are nowhere near being able to provide
that. I would suggest looking for context information: what else is
happening at the same time this happens?

Multiple 'simultaneous' connections (through forking) is a possibility. I
believe it was 4 child processes when this occurred the last time, but I'm not
100% sure.

Quote:

Another thing that would probably give enough information to solve it
is a trace of the connection from a TCP packet sniffer, for at least
a few packets leading up to the error message. Not sure if it's
practical to try to get one, but if you could it'd be great.

Not a problem. Thankfully I have full control on this box, not the Solaris side
though. And the box is dedicated to this database, so there shouldnb't be a ton
of extra traffic either. Just the normal mis-configured network client
broadcast jabber ;-) I should be able to figure out tcpdump enough to filter
out all traffic except that between the two servers.

Cheers,
Rob

--
20:40:25 up 25 days, 10:27, 4 users, load average: 2.02, 2.02, 2.00

--Multipart_Thu__22_Jan_2004_20_48_19_-0700_=.3u2dB(+D(x/7MH
Content-Type: application/pgp-signature

-----BEGIN PGP SIGNATURE-----
Version: GnuPG v1.2.2 (GNU/Linux)

iEYEARECAAYFAkAQmYQACgkQLQ/DKuwDYzn+TQCdFrta0CwiB37werPLAV0FQjBD
pFkAn2RBrkiZZwtyFkShrTfyOGsTMa6R
=Nvf+
-----END PGP SIGNATURE-----

--Multipart_Thu__22_Jan_2004_20_48_19_-0700_=.3u2dB(+D(x/7MH--

#3

--Multipart_Sat__24_Jan_2004_14_25_39_-0700_=.escfvFQ?bH=InS
Content-Type: text/plain; charset=US-ASCII
Content-Disposition: inline
Content-Transfer-Encoding: 7bit

When grilled further on (Sat, 24 Jan 2004 15:54:07 -0500),
Tom Lane <tgl (AT) sss (DOT) pgh.pa.us> confessed:

Quote:

A custom Perl 5.6.1, DBI 1.30, DBD::Pg 1.22 script on Solaris 5.8.
Using pgsql client version 7.3.3. I'm thinking it may be related to
my forking? My program has a db connection, which is then overwritten
in all child processes, first thing upon forking:

Judging by that trace, there are multiple processes trying to use the
same database connection. Better take a closer look at what you are
doing.

I suspect that "overwriting" the connection is not good enough, and that
you have to somehow actively close the DBI object inherited from the
parent. The fact that the excess operations all seem to be empty
queries is suspicious. I wonder whether those are coming from logic
internal to DBI or DBD::Pg, that might still have access to the
connection even though your Perl code doesn't anymore.

I have more of a clue now. I'm calling "DBI->connect_cached" when I fork, even
though I only use that particular db connection in the parent. connect_cached
sends a ping to verify the connection is alive, which is probably what the empty
queries are. The logs confirm that the pid associated with that connection
[721] and [1050] don't actually execute any requests. The new server is much
faster than the old one, so it is probably processing the packets faster, thus
occasionally getting into this problem when the fork timing is just wrong and
the dual packets are received before the first can be processed.

I can remove that second connection (which was used to vacuum) now that I have
pg_autovacuum running on the new server. I suspect this will clear up the empty
queries and the message coming back because of the overlapping empty queries.

Presuming this is the problem, I never would of found this without your help.
Thanks for taking the time. I'll not forget to be more careful of using
"connect_cached" next time around.

Quote:

Hmm ... AFAIR, libpq doesn't provide any clean way to close the socket
and discard the PGconn without actually sending a Terminate message to
the backend, which is what you'd want to happen in the child process.
This seems like a shortcoming in its API.

Cheers,
Rob

--
14:08:58 up 27 days, 3:55, 4 users, load average: 2.05, 2.05, 2.05

--Multipart_Sat__24_Jan_2004_14_25_39_-0700_=.escfvFQ?bH=InS
Content-Type: application/pgp-signature

-----BEGIN PGP SIGNATURE-----
Version: GnuPG v1.2.2 (GNU/Linux)

iEYEARECAAYFAkAS4tMACgkQLQ/DKuwDYzmmHACgloMbtzYof7OyY79E/1OVs7Hl
L40AnjdzfETkM2nmUTnLkbbnraPHq8GZ
=h5YE
-----END PGP SIGNATURE-----

--Multipart_Sat__24_Jan_2004_14_25_39_-0700_=.escfvFQ?bH=InS--

Thread Tools
Show Printable Version Email this Page
Display Modes
Linear Mode Switch to Hybrid Mode Switch to Threaded Mode

Re: [BUGS] BUG #1061: message type 0x49 arrived from server while

mailing.database.pgsql-bugs mailing.database.pgsql-bugs

Re: [BUGS] BUG #1061: message type 0x49 arrived from server while - 01-22-2004 , 09:07 PM

Re: [BUGS] BUG #1061: message type 0x49 arrived from server while - 01-22-2004 , 09:50 PM

Re: [BUGS] BUG #1061: message type 0x49 arrived from server while - 01-26-2004 , 10:17 AM