Обсуждение: unexpected message type 0x58 during COPY from stdin

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.


Cheers,

Bricklen

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

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.