unexpected message type 0x58 during COPY from stdin

On 25 August 2010 16:25, bricklen <bricklen@gmail.com> wrote:

Hello,

I'm getting a strange error during reload of one of our databases. For the
past several weeks, we have been seeing the following error regularly, but
not necessarily with the same table. The pg_restore aborts after this error,
resulting in an incomplete reload. At first I thought it might be related to
our upgrade to 8.4.4 several weeks ago so we downgraded to 8.4.2, but the
error still occurs. Interestingly, if I run the restore command manually
(from the command line), it works fine -- only in cron does it fail.

uname -a
Linux ike.nbinternal.com 2.6.18-164.6.1.el5 #1 SMP Tue Nov 3 16:12:36 EST
2009 x86_64 x86_64 x86_64 GNU/Linux

version()
PostgreSQL 8.4.2 on x86_64-redhat-linux-gnu, compiled by GCC gcc (GCC) 4.1.2
20071124 (Red Hat 4.1.2-42), 64-bit

-- dump file is created with:
pg_dump --format=custom $DATABASE $EXCLUDE_TABLES >
~/backups/daily-backup.dump

-- restore command:

pg_restore -d nbaffnet -F c -j 4 -v -C --no-data-for-failed-tables
/var/lib/pgsql/daily-backup.dump

-- error:
2010-08-25 04:16:46 PDT [2401]: [1-1] (user=postgres) ERROR:  unexpected
message type 0x58 during COPY from stdin
2010-08-25 04:16:46 PDT [2401]: [2-1] (user=postgres) CONTEXT:  COPY
afffraud, line 1
2010-08-25 04:16:46 PDT [2401]: [3-1] (user=postgres) STATEMENT:  COPY
afffraud (id, idaff, maxkey, maxvalue) FROM stdin;
2010-08-25 04:16:46 PDT [2401]: [4-1] (user=postgres) LOG:  could not send
data to client: Broken pipe
2010-08-25 04:16:46 PDT [2401]: [5-1] (user=postgres) STATEMENT:  COPY
afffraud (id, idaff, maxkey, maxvalue) FROM stdin;
2010-08-25 04:16:46 PDT [2401]: [6-1] (user=postgres) LOG:  unexpected EOF
on client connection

Note: we have been doing these backups and restores for at least a year and
a half without any problems, and we can't think of anything that might have
changed.

Just seeking the obvious, but is the file you've shown being output
with pg_dump the same one you're using on pg_restore? The paths are
different, although if that's on 2 different machines, that would make
perfect sense.

--
Thom Brown
Registered Linux user: #516935

On Wed, Aug 25, 2010 at 8:35 AM, Thom Brown <thom@linux.com> wrote:

Just seeking the obvious, but is the file you've shown being output
with pg_dump the same one you're using on pg_restore? The paths are
different, although if that's on 2 different machines, that would make
perfect sense.

--
Thom Brown
Registered Linux user: #516935

Yes, two different servers, same file. SCP is used to transfer that file
between the servers.

bricklen <bricklen@gmail.com> writes:

I'm getting a strange error during reload of one of our databases.

This appears to indicate that the server's first idea that there was
trouble came when the client side disconnected partway through a COPY:

2010-08-25 04:16:46 PDT [2401]: [1-1] (user=postgres) ERROR: unexpected
message type 0x58 during COPY from stdin

(0x58 = 'X' = Terminate message, implying client called PQfinish)

So it would be useful to look at what pg_restore thinks happened.
I rather suspect your cron setup sends pg_restore's output to
/dev/null ... or at least you failed to show it.

regards, tom lane

On Wed, Aug 25, 2010 at 12:01 PM, Tom Lane <tgl@sss.pgh.pa.us> wrote:

bricklen <bricklen@gmail.com> writes:

I'm getting a strange error during reload of one of our databases.

This appears to indicate that the server's first idea that there was
trouble came when the client side disconnected partway through a COPY:

2010-08-25 04:16:46 PDT [2401]: [1-1] (user=postgres) ERROR:  unexpected
message type 0x58 during COPY from stdin

(0x58 = 'X' = Terminate message, implying client called PQfinish)

So it would be useful to look at what pg_restore thinks happened.
I rather suspect your cron setup sends pg_restore's output to
/dev/null ... or at least you failed to show it.

                       regards, tom lane

cron:

MAILTO=""

30 2 * * * /var/lib/pgsql/sync-db.sh 2>&1

I'll modify that to append to a log file and see what else turns up.

On Wed, Aug 25, 2010 at 12:20 PM, bricklen <bricklen@gmail.com> wrote:

On Wed, Aug 25, 2010 at 12:01 PM, Tom Lane <tgl@sss.pgh.pa.us> wrote:

bricklen <bricklen@gmail.com> writes:

I'm getting a strange error during reload of one of our databases.

This appears to indicate that the server's first idea that there was
trouble came when the client side disconnected partway through a COPY:

2010-08-25 04:16:46 PDT [2401]: [1-1] (user=postgres) ERROR:  unexpected
message type 0x58 during COPY from stdin

(0x58 = 'X' = Terminate message, implying client called PQfinish)

So it would be useful to look at what pg_restore thinks happened.
I rather suspect your cron setup sends pg_restore's output to
/dev/null ... or at least you failed to show it.

                       regards, tom lane

cron:

MAILTO=""

30 2 * * * /var/lib/pgsql/sync-db.sh 2>&1

I'll modify that to append to a log file and see what else turns up.

FWIW, the output to a logfile from the cron was minimal and didn't
show anything new. I'm going to try it again tomorrow starting a
couple hours later, to rule out some odd 4am-ish problem that affects
the cron jobs.