auto_explain log_verbose causes regression failure

I am getting a repeatable failure on the HEAD regression tests when
auto_explain's log_verbose is set. If auto_explain.log_verbose is turned
off the failure disappears. Data below.

cheers

andrew

config settings:

custom_variable_classes = 'auto_explain'
auto_explain.log_min_duration = 0
auto_explain.log_format = 'xml'
auto_explain.log_analyze = on
auto_explain.log_verbose = on
shared_preload_libraries = 'auto_explain'

regression diffs:

***
/home/andrew/pgl/pgsql.hetry/src/test/regress/expected/transactions.out
2009-08-09 19:29:31.000000000 -0400
---
/home/andrew/pgl/pgsql.hetry/src/test/regress/results/transactions.out
2009-08-19 19:48:20.000000000 -0400
***************
*** 496,504 ****
(1 row)

rollback to x;
-- should fail
fetch from foo;
! ERROR: cursor "foo" does not exist
commit;
begin;
create table abc (a int);
--- 496,506 ----
(1 row)

rollback to x;
+ WARNING: AbortSubTransaction while in ABORT state
+ ERROR: cache lookup failed for attribute 1 of relation 28000
-- should fail
fetch from foo;
! ERROR: current transaction is aborted, commands ignored until end of
transaction block
commit;
begin;
create table abc (a int);
***************
*** 527,532 ****
--- 529,536 ----
(1 row)

abort;
+ WARNING: AbortTransaction while in ABORT state
+ ERROR: cache lookup failed for attribute 1 of relation 28003
-- tests for the "tid" type
SELECT '(3, 3)'::tid = '(3, 4)'::tid;
?column?

======================================================================

*** /home/andrew/pgl/pgsql.hetry/src/test/regress/expected/arrays.out
2009-08-09 19:29:31.000000000 -0400
--- /home/andrew/pgl/pgsql.hetry/src/test/regress/results/arrays.out
2009-08-19 19:48:21.000000000 -0400
***************
*** 15,22 ****
--- 15,25 ----
--
INSERT INTO arrtest (a[1:5], b[1:1][1:2][1:2], c, d, f, g)
VALUES ('{1,2,3,4,5}', '{{{0,0},{1,2}}}', '{}', '{}', '{}', '{}');
+ ERROR: unexpected refassgnexpr
UPDATE arrtest SET e[0] = '1.1';
+ ERROR: unexpected refassgnexpr
UPDATE arrtest SET e[1] = '2.2';
+ ERROR: unexpected refassgnexpr
INSERT INTO arrtest (f)
VALUES ('{"too long"}');
ERROR: value too long for type character(5)
***************
*** 24,38 ****
VALUES ('{11,12,23}', '{{3,4},{4,5}}', '{"foobar"}',
'{{"elt1", "elt2"}}', '{"3.4", "6.7"}',
'{"abc","abcde"}', '{"abc","abcde"}');
INSERT INTO arrtest (a, b[1:2], c, d[1:2])
VALUES ('{}', '{3,4}', '{foo,bar}', '{bar,foo}');
SELECT * FROM arrtest;
a | b | c | d |
e | f | g
!
-------------+-----------------+-----------+---------------+-----------------+-----------------+-------------
! {1,2,3,4,5} | {{{0,0},{1,2}}} | {} | {} |
[0:1]={1.1,2.2} | {} | {}
! {11,12,23} | {{3,4},{4,5}} | {foobar} | {{elt1,elt2}} |
{3.4,6.7} | {"abc ",abcde} | {abc,abcde}
! {} | {3,4} | {foo,bar} | {bar,foo}
| | |
! (3 rows)

SELECT arrtest.a[1],
arrtest.b[1][1][1],
--- 27,40 ----
VALUES ('{11,12,23}', '{{3,4},{4,5}}', '{"foobar"}',
'{{"elt1", "elt2"}}', '{"3.4", "6.7"}',
'{"abc","abcde"}', '{"abc","abcde"}');
+ ERROR: unexpected refassgnexpr
INSERT INTO arrtest (a, b[1:2], c, d[1:2])
VALUES ('{}', '{3,4}', '{foo,bar}', '{bar,foo}');
+ ERROR: unexpected refassgnexpr
SELECT * FROM arrtest;
a | b | c | d | e | f | g
! ---+---+---+---+---+---+---
! (0 rows)

SELECT arrtest.a[1],
arrtest.b[1][1][1],
***************
*** 41,60 ****
arrtest.e[0]
FROM arrtest;
a | b | c | d | e
! ----+---+--------+------+-----
! 1 | 0 | | | 1.1
! 11 | | foobar | elt1 |
! | | foo | |
! (3 rows)

SELECT a[1], b[1][1][1], c[1], d[1][1], e[0]
FROM arrtest;
a | b | c | d | e
! ----+---+--------+------+-----
! 1 | 0 | | | 1.1
! 11 | | foobar | elt1 |
! | | foo | |
! (3 rows)

SELECT a[1:3],
b[1:1][1:2][1:2],
--- 43,56 ----
arrtest.e[0]
FROM arrtest;
a | b | c | d | e
! ---+---+---+---+---
! (0 rows)

SELECT a[1], b[1][1][1], c[1], d[1][1], e[0]
FROM arrtest;
a | b | c | d | e
! ---+---+---+---+---
! (0 rows)

SELECT a[1:3],
b[1:1][1:2][1:2],
***************
*** 62,90 ****
d[1:1][1:2]
FROM arrtest;
a | b | c | d
! ------------+-----------------+-----------+---------------
! {1,2,3} | {{{0,0},{1,2}}} | {} | {}
! {11,12,23} | {} | {foobar} | {{elt1,elt2}}
! {} | {} | {foo,bar} | {}
! (3 rows)

SELECT array_ndims(a) AS a,array_ndims(b) AS b,array_ndims(c) AS c
FROM arrtest;
a | b | c
---+---+---
! 1 | 3 |
! 1 | 2 | 1
! | 1 | 1
! (3 rows)

SELECT array_dims(a) AS a,array_dims(b) AS b,array_dims(c) AS c
FROM arrtest;
a | b | c
! -------+-----------------+-------
! [1:5] | [1:1][1:2][1:2] |
! [1:3] | [1:2][1:2] | [1:1]
! | [1:2] | [1:2]
! (3 rows)

-- returns nothing
SELECT *
--- 58,77 ----
d[1:1][1:2]
FROM arrtest;
a | b | c | d
! ---+---+---+---
! (0 rows)

SELECT array_ndims(a) AS a,array_ndims(b) AS b,array_ndims(c) AS c
FROM arrtest;
a | b | c
---+---+---
! (0 rows)

SELECT array_dims(a) AS a,array_dims(b) AS b,array_dims(c) AS c
FROM arrtest;
a | b | c
! ---+---+---
! (0 rows)

-- returns nothing
SELECT *
***************
*** 98,117 ****
UPDATE arrtest
SET a[1:2] = '{16,25}'
WHERE NOT a = '{}'::_int2;
UPDATE arrtest
SET b[1:1][1:1][1:2] = '{113, 117}',
b[1:1][1:2][2:2] = '{142, 147}'
WHERE array_dims(b) = '[1:1][1:2][1:2]';
UPDATE arrtest
SET c[2:2] = '{"new_word"}'
WHERE array_dims(c) is not null;
SELECT a,b,c FROM arrtest;
a | b | c
! ---------------+-----------------------+-------------------
! {16,25,3,4,5} | {{{113,142},{1,147}}} | {}
! {} | {3,4} | {foo,new_word}
! {16,25,23} | {{3,4},{4,5}} | {foobar,new_word}
! (3 rows)

SELECT a[1:3],
b[1:1][1:2][1:2],
--- 85,104 ----
UPDATE arrtest
SET a[1:2] = '{16,25}'
WHERE NOT a = '{}'::_int2;
+ ERROR: unexpected refassgnexpr
UPDATE arrtest
SET b[1:1][1:1][1:2] = '{113, 117}',
b[1:1][1:2][2:2] = '{142, 147}'
WHERE array_dims(b) = '[1:1][1:2][1:2]';
+ ERROR: unexpected refassgnexpr
UPDATE arrtest
SET c[2:2] = '{"new_word"}'
WHERE array_dims(c) is not null;
+ ERROR: unexpected refassgnexpr
SELECT a,b,c FROM arrtest;
a | b | c
! ---+---+---
! (0 rows)

SELECT a[1:3],
b[1:1][1:2][1:2],
***************
*** 119,156 ****
d[1:1][2:2]
FROM arrtest;
a | b | c | d
! ------------+-----------------------+-------------------+----------
! {16,25,3} | {{{113,142},{1,147}}} | {} | {}
! {} | {} | {foo,new_word} | {}
! {16,25,23} | {} | {foobar,new_word} | {{elt2}}
! (3 rows)

INSERT INTO arrtest(a) VALUES('{1,null,3}');
SELECT a FROM arrtest;
a
! ---------------
! {16,25,3,4,5}
! {}
! {16,25,23}
{1,NULL,3}
! (4 rows)

UPDATE arrtest SET a[4] = NULL WHERE a[2] IS NULL;
SELECT a FROM arrtest WHERE a[2] IS NULL;
a
! -----------------
! [4:4]={NULL}
! {1,NULL,3,NULL}
! (2 rows)

DELETE FROM arrtest WHERE a[2] IS NULL AND b IS NULL;
SELECT a,b,c FROM arrtest;
a | b | c
! ---------------+-----------------------+-------------------
! {16,25,3,4,5} | {{{113,142},{1,147}}} | {}
! {16,25,23} | {{3,4},{4,5}} | {foobar,new_word}
! [4:4]={NULL} | {3,4} | {foo,new_word}
! (3 rows)

--
-- test array extension
--- 106,134 ----
d[1:1][2:2]
FROM arrtest;
a | b | c | d
! ---+---+---+---
! (0 rows)

INSERT INTO arrtest(a) VALUES('{1,null,3}');
SELECT a FROM arrtest;
a
! ------------
{1,NULL,3}
! (1 row)

UPDATE arrtest SET a[4] = NULL WHERE a[2] IS NULL;
+ ERROR: unexpected refassgnexpr
SELECT a FROM arrtest WHERE a[2] IS NULL;
a
! ------------
! {1,NULL,3}
! (1 row)

DELETE FROM arrtest WHERE a[2] IS NULL AND b IS NULL;
SELECT a,b,c FROM arrtest;
a | b | c
! ---+---+---
! (0 rows)

--
-- test array extension
***************
*** 164,250 ****
(1 row)

update arrtest1 set i[2] = 22, t[2] = 'twenty-two';
select * from arrtest1;
i | t
! ---------------+----------------------------
! {1,22,NULL,4} | {one,twenty-two,NULL,four}
(1 row)

update arrtest1 set i[5] = 5, t[5] = 'five';
select * from arrtest1;
i | t
! -----------------+---------------------------------
! {1,22,NULL,4,5} | {one,twenty-two,NULL,four,five}
(1 row)

update arrtest1 set i[8] = 8, t[8] = 'eight';
select * from arrtest1;
i |
t
!
-----------------------------+-------------------------------------------------
! {1,22,NULL,4,5,NULL,NULL,8} |
{one,twenty-two,NULL,four,five,NULL,NULL,eight}
(1 row)

update arrtest1 set i[0] = 0, t[0] = 'zero';
select * from arrtest1;
i |
t
!
-------------------------------------+------------------------------------------------------------
! [0:8]={0,1,22,NULL,4,5,NULL,NULL,8} |
[0:8]={zero,one,twenty-two,NULL,four,five,NULL,NULL,eight}
(1 row)

update arrtest1 set i[-3] = -3, t[-3] = 'minus-three';
select * from arrtest1;
i
|
t
!
---------------------------------------------------+-----------------------------------------------------------------------------------
! [-3:8]={-3,NULL,NULL,0,1,22,NULL,4,5,NULL,NULL,8} |
[-3:8]={minus-three,NULL,NULL,zero,one,twenty-two,NULL,four,five,NULL,NULL,eight}
(1 row)

update arrtest1 set i[0:2] = array[10,11,12], t[0:2] =
array['ten','eleven','twelve'];
select * from arrtest1;
i
|
t
!
-----------------------------------------------------+---------------------------------------------------------------------------------
! [-3:8]={-3,NULL,NULL,10,11,12,NULL,4,5,NULL,NULL,8} |
[-3:8]={minus-three,NULL,NULL,ten,eleven,twelve,NULL,four,five,NULL,NULL,eight}
(1 row)

update arrtest1 set i[8:10] = array[18,null,20], t[8:10] =
array['p18',null,'p20'];
select * from arrtest1;
i
|
t
!
---------------------------------------------------------------+-----------------------------------------------------------------------------------------
! [-3:10]={-3,NULL,NULL,10,11,12,NULL,4,5,NULL,NULL,18,NULL,20} |
[-3:10]={minus-three,NULL,NULL,ten,eleven,twelve,NULL,four,five,NULL,NULL,p18,NULL,p20}
(1 row)

update arrtest1 set i[11:12] = array[null,22], t[11:12] =
array[null,'p22'];
select * from arrtest1;
i
|
t
!
-----------------------------------------------------------------------+--------------------------------------------------------------------------------------------------
! [-3:12]={-3,NULL,NULL,10,11,12,NULL,4,5,NULL,NULL,18,NULL,20,NULL,22}
|
[-3:12]={minus-three,NULL,NULL,ten,eleven,twelve,NULL,four,five,NULL,NULL,p18,NULL,p20,NULL,p22}
(1 row)

update arrtest1 set i[15:16] = array[null,26], t[15:16] =
array[null,'p26'];
select * from arrtest1;

i
|
t
!
-----------------------------------------------------------------------------------------+---------------------------------------------------------------------------------------------------------------------
!
[-3:16]={-3,NULL,NULL,10,11,12,NULL,4,5,NULL,NULL,18,NULL,20,NULL,22,NULL,NULL,NULL,26}
|
[-3:16]={minus-three,NULL,NULL,ten,eleven,twelve,NULL,four,five,NULL,NULL,p18,NULL,p20,NULL,p22,NULL,NULL,NULL,p26}
(1 row)

update arrtest1 set i[-5:-3] = array[-15,-14,-13], t[-5:-3] =
array['m15','m14','m13'];
select * from arrtest1;

i
|
t
!
--------------------------------------------------------------------------------------------------+---------------------------------------------------------------------------------------------------------------------
!
[-5:16]={-15,-14,-13,NULL,NULL,10,11,12,NULL,4,5,NULL,NULL,18,NULL,20,NULL,22,NULL,NULL,NULL,26}
|
[-5:16]={m15,m14,m13,NULL,NULL,ten,eleven,twelve,NULL,four,five,NULL,NULL,p18,NULL,p20,NULL,p22,NULL,NULL,NULL,p26}
(1 row)

update arrtest1 set i[-7:-6] = array[-17,null], t[-7:-6] =
array['m17',null];
select * from arrtest1;

i
|
t
!
-----------------------------------------------------------------------------------------------------------+------------------------------------------------------------------------------------------------------------------------------
!
[-7:16]={-17,NULL,-15,-14,-13,NULL,NULL,10,11,12,NULL,4,5,NULL,NULL,18,NULL,20,NULL,22,NULL,NULL,NULL,26}
|
[-7:16]={m17,NULL,m15,m14,m13,NULL,NULL,ten,eleven,twelve,NULL,four,five,NULL,NULL,p18,NULL,p20,NULL,p22,NULL,NULL,NULL,p26}
(1 row)

update arrtest1 set i[-12:-10] = array[-22,null,-20], t[-12:-10] =
array['m22',null,'m20'];
select * from arrtest1;

i
|
t
!
-----------------------------------------------------------------------------------------------------------------------------------+------------------------------------------------------------------------------------------------------------------------------------------------------
!
[-12:16]={-22,NULL,-20,NULL,NULL,-17,NULL,-15,-14,-13,NULL,NULL,10,11,12,NULL,4,5,NULL,NULL,18,NULL,20,NULL,22,NULL,NULL,NULL,26}
|
[-12:16]={m22,NULL,m20,NULL,NULL,m17,NULL,m15,m14,m13,NULL,NULL,ten,eleven,twelve,NULL,four,five,NULL,NULL,p18,NULL,p20,NULL,p22,NULL,NULL,NULL,p26}
(1 row)

delete from arrtest1;
--- 142,240 ----
(1 row)

update arrtest1 set i[2] = 22, t[2] = 'twenty-two';
+ ERROR: unexpected refassgnexpr
select * from arrtest1;
i | t
! --------------+---------------------
! {1,2,NULL,4} | {one,two,NULL,four}
(1 row)

update arrtest1 set i[5] = 5, t[5] = 'five';
+ ERROR: unexpected refassgnexpr
select * from arrtest1;
i | t
! --------------+---------------------
! {1,2,NULL,4} | {one,two,NULL,four}
(1 row)

update arrtest1 set i[8] = 8, t[8] = 'eight';
+ ERROR: unexpected refassgnexpr
select * from arrtest1;
i | t
! --------------+---------------------
! {1,2,NULL,4} | {one,two,NULL,four}
(1 row)

update arrtest1 set i[0] = 0, t[0] = 'zero';
+ ERROR: unexpected refassgnexpr
select * from arrtest1;
i | t
! --------------+---------------------
! {1,2,NULL,4} | {one,two,NULL,four}
(1 row)

update arrtest1 set i[-3] = -3, t[-3] = 'minus-three';
+ ERROR: unexpected refassgnexpr
select * from arrtest1;
i | t
! --------------+---------------------
! {1,2,NULL,4} | {one,two,NULL,four}
(1 row)

update arrtest1 set i[0:2] = array[10,11,12], t[0:2] =
array['ten','eleven','twelve'];
+ ERROR: unexpected refassgnexpr
select * from arrtest1;
i | t
! --------------+---------------------
! {1,2,NULL,4} | {one,two,NULL,four}
(1 row)

update arrtest1 set i[8:10] = array[18,null,20], t[8:10] =
array['p18',null,'p20'];
+ ERROR: unexpected refassgnexpr
select * from arrtest1;
i | t
! --------------+---------------------
! {1,2,NULL,4} | {one,two,NULL,four}
(1 row)

update arrtest1 set i[11:12] = array[null,22], t[11:12] =
array[null,'p22'];
+ ERROR: unexpected refassgnexpr
select * from arrtest1;
i | t
! --------------+---------------------
! {1,2,NULL,4} | {one,two,NULL,four}
(1 row)

update arrtest1 set i[15:16] = array[null,26], t[15:16] =
array[null,'p26'];
+ ERROR: unexpected refassgnexpr
select * from arrtest1;
i | t
! --------------+---------------------
! {1,2,NULL,4} | {one,two,NULL,four}
(1 row)

update arrtest1 set i[-5:-3] = array[-15,-14,-13], t[-5:-3] =
array['m15','m14','m13'];
+ ERROR: unexpected refassgnexpr
select * from arrtest1;
i | t
! --------------+---------------------
! {1,2,NULL,4} | {one,two,NULL,four}
(1 row)

update arrtest1 set i[-7:-6] = array[-17,null], t[-7:-6] =
array['m17',null];
+ ERROR: unexpected refassgnexpr
select * from arrtest1;
i | t
! --------------+---------------------
! {1,2,NULL,4} | {one,two,NULL,four}
(1 row)

update arrtest1 set i[-12:-10] = array[-22,null,-20], t[-12:-10] =
array['m22',null,'m20'];
+ ERROR: unexpected refassgnexpr
select * from arrtest1;
i | t
! --------------+---------------------
! {1,2,NULL,4} | {one,two,NULL,four}
(1 row)

delete from arrtest1;
***************
*** 256,265 ****
(1 row)

update arrtest1 set i[0:5] = array[0,1,2,null,4,5], t[0:5] =
array['z','p1','p2',null,'p4','p5'];
select * from arrtest1;
i | t
! ------------------------+----------------------------
! [0:5]={0,1,2,NULL,4,5} | [0:5]={z,p1,p2,NULL,p4,p5}
(1 row)

--
--- 246,256 ----
(1 row)

update arrtest1 set i[0:5] = array[0,1,2,null,4,5], t[0:5] =
array['z','p1','p2',null,'p4','p5'];
+ ERROR: unexpected refassgnexpr
select * from arrtest1;
i | t
! --------------+---------------------
! {1,2,NULL,4} | {one,two,NULL,four}
(1 row)

--
***************
*** 369,377 ****
-- operators
SELECT a FROM arrtest WHERE b = ARRAY[[[113,142],[1,147]]];
a
! ---------------
! {16,25,3,4,5}
! (1 row)

SELECT NOT ARRAY[1.1,1.2,1.3] = ARRAY[1.1,1.2,1.3] AS "FALSE";
FALSE
--- 360,367 ----
-- operators
SELECT a FROM arrtest WHERE b = ARRAY[[[113,142],[1,147]]];
a
! ---
! (0 rows)

SELECT NOT ARRAY[1.1,1.2,1.3] = ARRAY[1.1,1.2,1.3] AS "FALSE";
FALSE

======================================================================

*** /home/andrew/pgl/pgsql.hetry/src/test/regress/expected/rowtypes.out
2008-10-14 20:27:28.000000000 -0400
--- /home/andrew/pgl/pgsql.hetry/src/test/regress/results/rowtypes.out
2009-08-19 19:48:41.000000000 -0400
***************
*** 98,117 ****

-- test insertion/updating of subfields
update people set fn.suffix = 'Jr';
select * from people;
fn | bd
! ---------------+------------
! (Joe,Blow,Jr) | 01-10-1984
(1 row)

insert into quadtable (f1, q.c1.r, q.c2.i) values(44,55,66);
select * from quadtable;
f1 | q
----+---------------------------
1 | ("(3.3,4.4)","(5.5,6.6)")
2 | ("(,4.4)","(5.5,6.6)")
! 44 | ("(55,)","(,66)")
! (3 rows)

-- The object here is to ensure that toasted references inside
-- composite values don't cause problems. The large f1 value will
--- 98,118 ----

-- test insertion/updating of subfields
update people set fn.suffix = 'Jr';
+ ERROR: unexpected FieldStore
select * from people;
fn | bd
! -------------+------------
! (Joe,Blow,) | 01-10-1984
(1 row)

insert into quadtable (f1, q.c1.r, q.c2.i) values(44,55,66);
+ ERROR: unexpected FieldStore
select * from quadtable;
f1 | q
----+---------------------------
1 | ("(3.3,4.4)","(5.5,6.6)")
2 | ("(,4.4)","(5.5,6.6)")
! (2 rows)

-- The object here is to ensure that toasted references inside
-- composite values don't cause problems. The large f1 value will

======================================================================