Re: buildfarm logging versus embedded nulls

Andrew Dunstan <andrew@dunslane.net> writes:
> Tom Lane wrote:
>> I was looking at this recent nonrepeatable buildfarm failure:
>> http://buildfarm.postgresql.org/cgi-bin/show_log.pl?nm=polecat&dt=2010-03-11%2021:45:10

> Well, the good news is that we actually have the data on the server, in 
> a temp file that will be cleaned up, but hasn't been yet. I have placed 
> a copy at <http://buildfarm.postgresql.org/polecat-check.log.gz>.

Thanks for that.  I found the relevant part of the postmaster log:

[4b99671f.ddb4:36] LOG:  statement: DELETE FROM vactst WHERE i != 0;
[4b99671f.ddb4:37] LOG:  statement: VACUUM (FULL) vactst;
[4b99671f.ddb4:38] WARNING:  pgstat wait timeout
[4b99671f.ddb4:39] LOG:  statement: DELETE FROM vactst;
[4b99671f.ddb4:40] LOG:  statement: SELECT * FROM vactst;
[4b99671f.ddb4:41] LOG:  statement: VACUUM (FULL, FREEZE) vactst;
[4b99671f.ddb4:42] WARNING:  pgstat wait timeout
[4b99671f.ddb4:43] LOG:  statement: VACUUM (ANALYZE, FULL) vactst;
[4b99671f.ddb4:44] WARNING:  pgstat wait timeout
[4b99671f.ddb4:45] LOG:  statement: CREATE TABLE vaccluster (i INT PRIMARY KEY);
[4b99671f.ddb4:46] LOG:  statement: ALTER TABLE vaccluster CLUSTER ON vaccluster_pkey;
[4b99671f.ddb4:47] LOG:  statement: INSERT INTO vaccluster SELECT * FROM vactst;
[4b99671f.ddb4:48] LOG:  statement: CLUSTER vaccluster;
[4b99671f.ddb4:49] LOG:  statement: VACUUM FULL pg_am;
[4b99671f.ddb4:50] WARNING:  pgstat wait timeout
[4b99671f.ddb4:51] LOG:  statement: VACUUM FULL pg_class;
[4b99671f.ddb4:52] WARNING:  pgstat wait timeout
[4b99671f.ddb4:53] LOG:  statement: VACUUM FULL pg_database;
[4b99671f.ddb4:54] WARNING:  pgstat wait timeout
[4b99671f.ddb4:55] LOG:  statement: VACUUM FULL vaccluster;
[4b996707.dcc0:2] WARNING:  pgstat wait timeout
[4b99671f.ddb4:56] WARNING:  pgstat wait timeout
[4b99671f.ddb4:57] LOG:  statement: VACUUM FULL vactst;
[4b996707.dcc0:3] WARNING:  pgstat wait timeout
[4b996747.ddcc:1] WARNING:  pgstat wait timeout
[4b99671f.ddba:4] LOG:  statement: INSERT INTO DEFAULT_TBL VALUES (1, 'thomas', 57.0613);

Most of the "pgstat wait timeout" gripes are coming from the backend
running the "vacuum" regression test, but there are two that came from
process dcc0, which is shown by other log entries to be the autovacuum
launcher.  So now I'm wondering if there could be some issue that occurs
when the autovac launcher and a backend both want stats concurrently.
I have not got further than that in my uncaffeinated state --- anybody
have any ideas?

> Now, the log_text field in our build_status_log table is text, so it's 
> on insertion to the database that it gets truncated. I'm thinking that I 
> should just escape nulls with a regex ( 's/\x00/\\0/g' or similar) 
> before inserting the data.

Works for me.
        regards, tom lane