Re: Curious buildfarm failures (fwd)

On Tue, 15 Jan 2013, Andres Freund wrote:
> Any chance you could run make check again but with log_statement=all and
> log_min_messages=debug2? That might tell us a bit more, whether the
> dependency code doesn't work right or whether the checkpoint is doing
> strange things.

Here it is :


2013-01-15 23:06:18 MSK [50f5a8aa.1162:1] DEBUG:  SlruScanDirectory invoking callback on pg_notify/0000
2013-01-15 23:06:18 MSK [50f5a8aa.1162:2] DEBUG:  removing file "pg_notify/0000"
2013-01-15 23:06:18 MSK [50f5a8aa.1162:3] DEBUG:  max_safe_fds = 985, usable_fds = 1000, already_open = 5
2013-01-15 23:06:18 MSK [50f5a8aa.1167:1] LOG:  database system was shut down at 2013-01-15 23:06:18 MSK
2013-01-15 23:06:18 MSK [50f5a8aa.1167:2] DEBUG:  checkpoint record is at 0/17700E0
2013-01-15 23:06:18 MSK [50f5a8aa.1167:3] DEBUG:  redo record is at 0/17700E0; shutdown TRUE
2013-01-15 23:06:18 MSK [50f5a8aa.1167:4] DEBUG:  next transaction ID: 0/686; next OID: 12031
2013-01-15 23:06:18 MSK [50f5a8aa.1167:5] DEBUG:  next MultiXactId: 1; next MultiXactOffset: 0
2013-01-15 23:06:18 MSK [50f5a8aa.1167:6] DEBUG:  oldest unfrozen transaction ID: 676, in database 1
2013-01-15 23:06:18 MSK [50f5a8aa.1167:7] DEBUG:  transaction ID wrap limit is 2147484323, limited by database with OID
1
2013-01-15 23:06:18 MSK [50f5a8aa.1168:1] DEBUG:  checkpointer updated shared memory configuration values
2013-01-15 23:06:18 MSK [50f5a8aa.116b:1] LOG:  autovacuum launcher started
2013-01-15 23:06:18 MSK [50f5a8aa.1162:4] LOG:  database system is ready to accept connections
2013-01-15 23:06:19 MSK [50f5a8aa.1162:5] DEBUG:  forked new backend, pid=4463 socket=8
2013-01-15 23:06:19 MSK [50f5a8aa.1162:6] DEBUG:  server process (PID 4463) exited with exit code 0
2013-01-15 23:06:19 MSK [50f5a8aa.1162:7] DEBUG:  forked new backend, pid=4465 socket=8
2013-01-15 23:06:19 MSK [50f5a8ab.1171:1] LOG:  statement: CREATE DATABASE "regression" TEMPLATE=template0
2013-01-15 23:06:19 MSK [50f5a8aa.1168:2] LOG:  checkpoint starting: immediate force wait
2013-01-15 23:06:19 MSK [50f5a8aa.1168:3] DEBUG:  SlruScanDirectory invoking callback on pg_multixact/offsets/0000
2013-01-15 23:06:19 MSK [50f5a8aa.1168:4] DEBUG:  SlruScanDirectory invoking callback on pg_multixact/members/0000
2013-01-15 23:06:19 MSK [50f5a8aa.1168:5] DEBUG:  attempting to remove WAL segments older than log file
000000000000000000000000
2013-01-15 23:06:19 MSK [50f5a8aa.1168:6] DEBUG:  SlruScanDirectory invoking callback on pg_subtrans/0000
2013-01-15 23:06:19 MSK [50f5a8aa.1168:7] LOG:  checkpoint complete: wrote 3 buffers (0.0%); 0 transaction log file(s)
added,0 removed, 0 recycled; write=0.001 s, sync=0.000 s, total=0.001 s; sync files=0, longest=0.000 s, average=0.000
s
2013-01-15 23:06:19 MSK [50f5a8aa.1168:8] LOG:  checkpoint starting: immediate force wait
2013-01-15 23:06:19 MSK [50f5a8aa.1168:9] DEBUG:  attempting to remove WAL segments older than log file
000000000000000000000000
2013-01-15 23:06:19 MSK [50f5a8aa.1168:10] DEBUG:  SlruScanDirectory invoking callback on pg_subtrans/0000
2013-01-15 23:06:19 MSK [50f5a8aa.1168:11] LOG:  checkpoint complete: wrote 0 buffers (0.0%); 0 transaction log file(s)
added,0 removed, 0 recycled; write=0.001 s, sync=0.000 s, total=0.001 s; sync files=0, longest=0.000 s, average=0.000
s
2013-01-15 23:06:19 MSK [50f5a8aa.1162:8] DEBUG:  server process (PID 4465) exited with exit code 0
2013-01-15 23:06:19 MSK [50f5a8aa.1162:9] DEBUG:  forked new backend, pid=4467 socket=8
2013-01-15 23:06:19 MSK [50f5a8ab.1173:1] LOG:  statement: ALTER DATABASE "regression" SET lc_messages TO 'C';ALTER
DATABASE"regression" SET lc_monetary TO 'C';ALTER DATABASE "regression" SET lc_numeric TO 'C';ALTER DATABASE
"regression"SET lc_time TO 'C';ALTER DATABASE "regression" SET timezone_abbreviations TO 'Default';
 
2013-01-15 23:06:19 MSK [50f5a8aa.1162:10] DEBUG:  server process (PID 4467) exited with exit code 0
2013-01-15 23:06:19 MSK [50f5a8aa.1162:11] DEBUG:  forked new backend, pid=4469 socket=8
2013-01-15 23:06:19 MSK [50f5a8ab.1175:1] LOG:  statement: CREATE TABLESPACE testspace LOCATION
'/home/math/pg_git/src/test/regress/testtablespace';
2013-01-15 23:06:19 MSK [50f5a8ab.1175:2] LOG:  statement: ALTER TABLESPACE testspace SET (random_page_cost = 1.0);
2013-01-15 23:06:19 MSK [50f5a8ab.1175:3] LOG:  statement: ALTER TABLESPACE testspace SET (some_nonexistent_parameter =
true);
2013-01-15 23:06:19 MSK [50f5a8ab.1175:4] ERROR:  unrecognized parameter "some_nonexistent_parameter"
2013-01-15 23:06:19 MSK [50f5a8ab.1175:5] STATEMENT:  ALTER TABLESPACE testspace SET (some_nonexistent_parameter =
true);
2013-01-15 23:06:19 MSK [50f5a8ab.1175:6] LOG:  statement: ALTER TABLESPACE testspace RESET (random_page_cost = 2.0);
2013-01-15 23:06:19 MSK [50f5a8ab.1175:7] ERROR:  RESET must not include values for parameters
2013-01-15 23:06:19 MSK [50f5a8ab.1175:8] STATEMENT:  ALTER TABLESPACE testspace RESET (random_page_cost = 2.0);
2013-01-15 23:06:19 MSK [50f5a8ab.1175:9] LOG:  statement: ALTER TABLESPACE testspace RESET (random_page_cost,
seq_page_cost);
2013-01-15 23:06:19 MSK [50f5a8ab.1175:10] LOG:  statement: CREATE SCHEMA testschema;
2013-01-15 23:06:19 MSK [50f5a8ab.1175:11] LOG:  statement: CREATE TABLE testschema.foo (i int) TABLESPACE testspace;
2013-01-15 23:06:19 MSK [50f5a8ab.1175:12] LOG:  statement: SELECT relname, spcname FROM pg_catalog.pg_tablespace t,
pg_catalog.pg_classc            where c.reltablespace = t.oid AND c.relname = 'foo';
 
2013-01-15 23:06:19 MSK [50f5a8ab.1175:13] LOG:  statement: INSERT INTO testschema.foo VALUES(1);
2013-01-15 23:06:19 MSK [50f5a8ab.1175:14] LOG:  statement: INSERT INTO testschema.foo VALUES(2);
2013-01-15 23:06:19 MSK [50f5a8ab.1175:15] LOG:  statement: CREATE TABLE testschema.asselect TABLESPACE testspace AS
SELECT1;
 
2013-01-15 23:06:19 MSK [50f5a8ab.1175:16] LOG:  statement: SELECT relname, spcname FROM pg_catalog.pg_tablespace t,
pg_catalog.pg_classc            where c.reltablespace = t.oid AND c.relname = 'asselect';
 
2013-01-15 23:06:19 MSK [50f5a8ab.1175:17] LOG:  statement: PREPARE selectsource(int) AS SELECT $1;
2013-01-15 23:06:19 MSK [50f5a8ab.1175:18] LOG:  statement: CREATE TABLE testschema.asexecute TABLESPACE testspace
     AS EXECUTE selectsource(2);
 
2013-01-15 23:06:19 MSK [50f5a8ab.1175:19] LOG:  statement: SELECT relname, spcname FROM pg_catalog.pg_tablespace t,
pg_catalog.pg_classc            where c.reltablespace = t.oid AND c.relname = 'asexecute';
 
2013-01-15 23:06:19 MSK [50f5a8ab.1175:20] LOG:  statement: CREATE INDEX foo_idx on testschema.foo(i) TABLESPACE
testspace;
2013-01-15 23:06:19 MSK [50f5a8ab.1175:21] DEBUG:  building index "foo_idx" on table "foo"
2013-01-15 23:06:19 MSK [50f5a8ab.1175:22] LOG:  statement: SELECT relname, spcname FROM pg_catalog.pg_tablespace t,
pg_catalog.pg_classc            where c.reltablespace = t.oid AND c.relname = 'foo_idx';
 
2013-01-15 23:06:19 MSK [50f5a8ab.1175:23] LOG:  statement: CREATE TABLE testschema.atable AS VALUES (1), (2);
2013-01-15 23:06:19 MSK [50f5a8ab.1175:24] LOG:  statement: CREATE UNIQUE INDEX anindex ON testschema.atable(column1);
2013-01-15 23:06:19 MSK [50f5a8ab.1175:25] DEBUG:  building index "anindex" on table "atable"
2013-01-15 23:06:19 MSK [50f5a8ab.1175:26] LOG:  statement: ALTER TABLE testschema.atable SET TABLESPACE testspace;
2013-01-15 23:06:19 MSK [50f5a8ab.1175:27] LOG:  statement: ALTER INDEX testschema.anindex SET TABLESPACE testspace;
2013-01-15 23:06:19 MSK [50f5a8ab.1175:28] LOG:  statement: INSERT INTO testschema.atable VALUES(3);
2013-01-15 23:06:19 MSK [50f5a8ab.1175:29] LOG:  statement: INSERT INTO testschema.atable VALUES(1);
2013-01-15 23:06:19 MSK [50f5a8ab.1175:30] ERROR:  duplicate key value violates unique constraint "anindex"
2013-01-15 23:06:19 MSK [50f5a8ab.1175:31] DETAIL:  Key (column1)=(1) already exists.
2013-01-15 23:06:19 MSK [50f5a8ab.1175:32] STATEMENT:  INSERT INTO testschema.atable VALUES(1);
2013-01-15 23:06:19 MSK [50f5a8ab.1175:33] LOG:  statement: SELECT COUNT(*) FROM testschema.atable;
2013-01-15 23:06:19 MSK [50f5a8ab.1175:34] LOG:  statement: CREATE TABLESPACE badspace LOCATION '/no/such/location';
2013-01-15 23:06:19 MSK [50f5a8ab.1175:35] ERROR:  directory "/no/such/location" does not exist
2013-01-15 23:06:19 MSK [50f5a8ab.1175:36] STATEMENT:  CREATE TABLESPACE badspace LOCATION '/no/such/location';
2013-01-15 23:06:19 MSK [50f5a8ab.1175:37] LOG:  statement: CREATE TABLE bar (i int) TABLESPACE nosuchspace;
2013-01-15 23:06:19 MSK [50f5a8ab.1175:38] ERROR:  tablespace "nosuchspace" does not exist
2013-01-15 23:06:19 MSK [50f5a8ab.1175:39] STATEMENT:  CREATE TABLE bar (i int) TABLESPACE nosuchspace;
2013-01-15 23:06:19 MSK [50f5a8ab.1175:40] LOG:  statement: DROP TABLESPACE testspace;
2013-01-15 23:06:19 MSK [50f5a8aa.1168:12] LOG:  checkpoint starting: immediate force wait
2013-01-15 23:06:19 MSK [50f5a8aa.1168:13] DEBUG:  attempting to remove WAL segments older than log file
000000000000000000000000
2013-01-15 23:06:19 MSK [50f5a8aa.1168:14] DEBUG:  SlruScanDirectory invoking callback on pg_subtrans/0000
2013-01-15 23:06:19 MSK [50f5a8aa.1168:15] LOG:  checkpoint complete: wrote 37 buffers (0.2%); 0 transaction log
file(s)added, 0 removed, 0 recycled; write=0.000 s, sync=0.000 s, total=0.001 s; sync files=0, longest=0.000 s,
average=0.000s
 
2013-01-15 23:06:19 MSK [50f5a8ab.1175:41] ERROR:  tablespace "testspace" is not empty
2013-01-15 23:06:19 MSK [50f5a8ab.1175:42] STATEMENT:  DROP TABLESPACE testspace;
2013-01-15 23:06:19 MSK [50f5a8ab.1175:43] LOG:  statement: DROP SCHEMA testschema CASCADE;
2013-01-15 23:06:19 MSK [50f5a8ab.1175:44] DEBUG:  drop auto-cascades to index testschema.foo_idx
2013-01-15 23:06:19 MSK [50f5a8ab.1175:45] DEBUG:  drop auto-cascades to type testschema.foo
2013-01-15 23:06:19 MSK [50f5a8ab.1175:46] DEBUG:  drop auto-cascades to type testschema.foo[]
2013-01-15 23:06:19 MSK [50f5a8ab.1175:47] DEBUG:  drop auto-cascades to type testschema.asselect
2013-01-15 23:06:19 MSK [50f5a8ab.1175:48] DEBUG:  drop auto-cascades to type testschema.asselect[]
2013-01-15 23:06:19 MSK [50f5a8ab.1175:49] DEBUG:  drop auto-cascades to type testschema.asexecute
2013-01-15 23:06:19 MSK [50f5a8ab.1175:50] DEBUG:  drop auto-cascades to type testschema.asexecute[]
2013-01-15 23:06:19 MSK [50f5a8ab.1175:51] DEBUG:  drop auto-cascades to index testschema.anindex
2013-01-15 23:06:19 MSK [50f5a8ab.1175:52] DEBUG:  drop auto-cascades to type testschema.atable
2013-01-15 23:06:19 MSK [50f5a8ab.1175:53] DEBUG:  drop auto-cascades to type testschema.atable[]
2013-01-15 23:06:19 MSK [50f5a8ab.1175:54] NOTICE:  drop cascades to 4 other objects
2013-01-15 23:06:19 MSK [50f5a8ab.1175:55] DETAIL:  drop cascades to table testschema.foo        drop cascades to table
testschema.asselect       drop cascades to table testschema.asexecute        drop cascades to table testschema.atable
 
2013-01-15 23:06:19 MSK [50f5a8ab.1175:56] LOG:  statement: DROP TABLESPACE testspace;
2013-01-15 23:06:19 MSK [50f5a8aa.1168:16] LOG:  checkpoint starting: immediate force wait
2013-01-15 23:06:19 MSK [50f5a8aa.1168:17] DEBUG:  attempting to remove WAL segments older than log file
000000000000000000000000
2013-01-15 23:06:19 MSK [50f5a8aa.1168:18] DEBUG:  SlruScanDirectory invoking callback on pg_subtrans/0000
2013-01-15 23:06:19 MSK [50f5a8aa.1168:19] LOG:  checkpoint complete: wrote 9 buffers (0.1%); 0 transaction log file(s)
added,0 removed, 0 recycled; write=0.000 s, sync=0.000 s, total=0.000 s; sync files=0, longest=0.000 s, average=0.000
s
2013-01-15 23:06:19 MSK [50f5a8ab.1175:57] ERROR:  tablespace "testspace" is not empty
2013-01-15 23:06:19 MSK [50f5a8ab.1175:58] STATEMENT:  DROP TABLESPACE testspace;
2013-01-15 23:06:19 MSK [50f5a8aa.1162:12] DEBUG:  server process (PID 4469) exited with exit code 0


Cheers,    S
*****************************************************
Sergey E. Koposov, PhD, Research Associate
Institute of Astronomy, University of Cambridge
Madingley road, CB3 0HA, Cambridge, UK
Tel: +44-1223-337-551 Web: http://www.ast.cam.ac.uk/~koposov/