Crashing on PostgreSQL9.5 dev on topology

[robe]

Debbie crashed during her weekly regress of PostgreSQL 9.5 snapshot.

 regress/st_simplify .. failed (diff expected obtained: /var/lib/jenkins/workspace/postgis/regress_pgdev/tmp/2_2_pg9.5w64/test_26_diff)
-----------------------------------------------------------------------------
--- regress/st_simplify_expected	2014-04-26 22:51:51.000000000 -0700
+++ /var/lib/jenkins/workspace/postgis/regress_pgdev/tmp/2_2_pg9.5w64/test_26_out	2014-10-25 20:18:11.000000000 -0700
@@ -3,7 +3,7 @@
 N2
 S1|f|t
 S2|f|t
-L2
-HS1|f|t
-HS2|f|t
-f
+server closed the connection unexpectedly
+	This probably means the server terminated abnormally
+	before or while processing the request.
+connection to server was lost

-----------------------------------------------------------------------------
--- regress/topoelement_expected	2014-04-26 22:51:51.000000000 -0700
+++ /var/lib/jenkins/workspace/postgis/regress_pgdev/tmp/2_2_pg9.5w64/test_27_out	2014-10-25 20:18:11.000000000 -0700
@@ -1,6 +1 @@
-1|{101,1}
-2|{101,2}
-3|{101,3}
-4|{1,104}
-ERROR:  value for domain topoelement violates check constraint "lower_dimension"
-ERROR:  value for domain topoelement violates check constraint "type_range"
+psql: FATAL:  the database system is in recovery mode

-----------------------------------------------------------------------------
 regress/topoelementarray_agg .. failed (diff expected obtained: /var/lib/jenkins/workspace/postgis/regress_pgdev/tmp/2_2_pg9.5w64/test_28_diff)
-----------------------------------------------------------------------------
--- regress/topoelementarray_agg_expected	2014-04-26 22:51:51.000000000 -0700
+++ /var/lib/jenkins/workspace/postgis/regress_pgdev/tmp/2_2_pg9.5w64/test_28_out	2014-10-25 20:18:11.000000000 -0700
@@ -1,2 +1 @@
-1|{{1,3}}
-2|{{4,1},{5,2}}
+psql: FATAL:  the database system is in recovery mode

There are a bunch more others but I suspect that was because she was in recovery mode. I'm going to run again just to see if it was a fluke of nature.

[robe]

Okay 9.5 really hates topology. First shutdown jenkins. Cleared all the orphan postgres instances and ran against 9.4. 9.4 worked fine. Then I ran against 9.5. 9.5 crashed again always in topology and always at the st_simplify step.

version details:

PostgreSQL 9.5devel on x86_64-unknown-linux-gnu, compiled by gcc (Debian 4.4.5-8) 4.4.5, 64-bit
  Postgis 2.2.0dev - r13114 - 2014-10-26 05:40:07
  scripts 2.2.0dev r13114
  GEOS: 3.4.3dev-CAPI-1.8.3 r4020
  PROJ: Rel. 4.7.1, 23 September 2009

Fall output here: ​http://debbie.postgis.net:8080/job/PostGIS_Regress_PGDEV_Weekly/112/consoleFull .

I'll try to setup 9.5 on my local desktop and see if I run into the same issues.

[robe]

Finally got around setting up latest 9.5 snapshot on my windows 7 64-bit compiled with mingw64. Same issue as debbie in same spot crashes as soon as it get's to st_simplify.

debbie is testing with 3.4.3dev and I'm testing with 3.5.0dev so a problem in both versions if it is geos specific.

Stepping thru the st_simplify regress test line by line, what seems to trigger the crash is this part:

CREATE TABLE tt.bigareas(id serial, g geometry);
INSERT INTO _test_layers SELECT 2,
  AddTopoGeometryColumn('tt', 'tt', 'bigareas', 'tg', 'polygon', layer_id)
  FROM _test_layers WHERE id = 1;
SELECT 'L' || layer_id FROM _test_layers WHERE id = 2;
INSERT INTO tt.bigareas (tg) SELECT
  topology.CreateTopoGeom( 'tt', 3,
    (select layer_id from _test_layers where id = 2),
    TopoElementArray_agg(ARRAY[r.topogeo_id, r.layer_id]))
  FROM tt.relation r, _test_layers l1
  WHERE r.layer_id = l1.layer_id AND l1.id = 1
  GROUP BY r.topogeo_id;
UPDATE tt.bigareas SET g = tg;

[robe]

I isolated further to this line:

INSERT INTO _test_layers SELECT 2,
  AddTopoGeometryColumn('tt', 'tt', 'bigareas', 'tg', 'polygon', layer_id)
  FROM _test_layers WHERE id = 1;

Now why on earth would something that simple cause it to crash. I do have cassert and debug enabled.

[strk]

Did you try stepping into AddTopoGeometryColumn ?

[robe]

Yes by itself it didn't crash even running several times. Was wondering if maybe because we are changing pg_depends in that function and also using a temp table that those are some how colliding in some way.

[robe]

Okay I did a back trace of it and this is what it looks like

Program received signal SIGSEGV, Segmentation fault.
[Switching to Thread 5568.0x15c4]
0x000000000054fbc9 in AfterTriggerPendingOnRel (relid=17984) at trigger.c:4781
4781                    for_each_event_chunk(event, chunk, afterTriggers.query_stack[depth])
(gdb) bt
#0  0x000000000054fbc9 in AfterTriggerPendingOnRel (relid=17984) at trigger.c:4781
#1  0x000000000053e05c in CheckTableNotInUse (rel=0xe650dc0, stmt=0x8ab69a <__func__.77621+8091> "ALTER TABLE") at tablecmds.c:2652
#2  0x0000000000545315 in AlterTable (relid=relid@entry=17984, lockmode=lockmode@entry=8, stmt=0xe32b580) at tablecmds.c:2724
#3  0x00000000006701ec in ProcessUtilitySlow (parsetree=0x256e290, queryString=0x256e0e8 " r2\016", context=<optimized out>, params=0xe32ae20, completionTag=0x256e290 "", dest=<optimize
#4  0x000000000066ee43 in standard_ProcessUtility (parsetree=0xe32ae20, queryString=0xdab7ec8 "ALTER TABLE tt.bigareas ADD COLUMN tg topology.TopoGeometry;", context=<optimized out>, pa
#5  0x000000000058ba46 in _SPI_execute_plan (plan=plan@entry=0x256e360, paramLI=paramLI@entry=0x0, snapshot=snapshot@entry=0x0, crosscheck_snapshot=crosscheck_snapshot@entry=0x0, read_o
#6  0x000000000058c035 in SPI_execute (src=src@entry=0xdab7ec8 "ALTER TABLE tt.bigareas ADD COLUMN tg topology.TopoGeometry;", read_only=<optimized out>, tcount=tcount@entry=0) at spi.c
#7  0x000000006ab50cf7 in exec_stmt_dynexecute (stmt=0xd974418, estate=0x256e730) at pl_exec.c:3521
#8  exec_stmt (stmt=0xd974418, estate=0x256e730) at pl_exec.c:1473
#9  exec_stmts (estate=0x256e730, stmts=<optimized out>) at pl_exec.c:1368
#10 0x000000006ab52151 in exec_stmt_block (estate=0x0, estate@entry=0x256e730, block=0xd9e42d0) at pl_exec.c:1306
#11 0x000000006ab523cd in plpgsql_exec_function (func=0xd9ca430, func@entry=0xd9bc740, fcinfo=0xd9bc740, fcinfo@entry=0x256e988, simple_eval_estate=simple_eval_estate@entry=0x0) at pl_e
#12 0x000000006ab473bb in plpgsql_call_handler (fcinfo=0x256e988) at pl_handler.c:243
#13 0x0000000000567ddb in ExecMakeFunctionResultNoSets (fcache=0xd9bc6d0, econtext=0xd9bc4d0, isNull=0xd988371 "\177~\177\177\177\177\177\210o+\r", isDone=<optimized out>) at execQual.c
#14 0x000000000056dd80 in ExecTargetList (isDone=0x256eafc, itemIsDone=0xd9884e8, isnull=0xd988370 "", values=0xd988348, econtext=0xd9bc4d0, targetlist=0xd988488) at execQual.c:5265
#15 ExecProject (projInfo=projInfo@entry=0xd988390, isDone=isDone@entry=0x256eafc) at execQual.c:5480
#16 0x000000000056e1d0 in ExecScan (node=node@entry=0xd9bc3b8, accessMtd=accessMtd@entry=0x5815c0 <SeqNext>, recheckMtd=recheckMtd@entry=0x5815b0 <SeqRecheck>) at execScan.c:207
#17 0x0000000000581633 in ExecSeqScan (node=node@entry=0xd9bc3b8) at nodeSeqscan.c:116
#18 0x0000000000566d38 in ExecProcNode (node=node@entry=0xd9bc3b8) at execProcnode.c:400
#19 0x000000000057e68d in ExecModifyTable (node=node@entry=0xd9bc260) at nodeModifyTable.c:926
#20 0x0000000000566d78 in ExecProcNode (node=node@entry=0xd9bc260) at execProcnode.c:377
#21 0x0000000000563c8e in ExecutePlan (dest=0xda608a0, direction=<optimized out>, numberTuples=0, sendTuples=0 '\000', operation=CMD_INSERT, planstate=0xd9bc260, estate=0xd9bc078) at ex
#22 standard_ExecutorRun (queryDesc=0xe3e4e38, direction=<optimized out>, count=0) at execMain.c:308
#23 0x000000000066c67c in ProcessQuery (plan=<optimized out>, sourceText=0x18fb00 "INSERT INTO _test_layers SELECT 2,\n  AddTopoGeometryColumn('tt', 'tt', 'bigareas', 'tg', 'polygon', l
    params=0x0, dest=0xda608a0, completionTag=0x256f230 "") at pquery.c:185
#24 0x000000000066c908 in PortalRunMulti (portal=portal@entry=0xd876b48, isTopLevel=isTopLevel@entry=0 '\000', dest=0xda608a0, dest@entry=0x0, altdest=0xda608a0, altdest@entry=0x75aed7
#25 0x000000000066d53c in PortalRun (portal=0x256eeb0, portal@entry=0xd876b48, count=39252592, count@entry=2147483647, isTopLevel=isTopLevel@entry=0 '\000', dest=0x0, dest@entry=0xda608
    completionTag@entry=0x400000000c7 <Address 0x400000000c7 out of bounds>) at pquery.c:816
#26 0x000000000066af76 in exec_simple_query (query_string=0x7fefef23fc0 <msvcrt!__iob_func> "H\215\005\271ê\a") at postgres.c:1045
#27 PostgresMain (argc=<optimized out>, argv=argv@entry=0xc80d8, dbname=0x8000700060017 <Address 0x8000700060017 out of bounds>, username=<optimized out>) at postgres.c:4010
#28 0x000000000060e363 in BackendRun (port=0x256f420) at postmaster.c:4118
#29 SubPostmasterMain (argc=argc@entry=3, argv=argv@entry=0x137e00) at postmaster.c:4622
#30 0x000000000079aab0 in main (argc=3, argv=0x137e00) at main.c:197

[strk]

I suggest you report this upstream to PostgreSQL as it looks like a bug there.

[robe]

I think so too, but I need to come up with a test case that doesn't require PostGIS / postgis_topology installed. Anyway I've switched the milestone on this to PostGIS PostgreSQL

[robe]

Okay this test that doesn't involve postgis at all seems to crash also which points the finger at 9.5:

CREATE OR REPLACE FUNCTION crash_test(table_name varchar, column_name varchar)
  RETURNS bigint AS
$$
DECLARE
 var_result bigint;
BEGIN
       EXECUTE 'ALTER TABLE ' || quote_ident(table_name) || ' ADD COLUMN ' || quote_ident(column_name) || ' text;';
       var_result = (random()*100000)::bigint;
       RETURN var_result;
END
$$
  LANGUAGE plpgsql VOLATILE
  COST 100;

DROP TABLE IF EXISTS test_1;
CREATE TABLE test_1(id serial primary key);
DROP TABLE IF EXISTS test_crash;
CREATE TEMP TABLE test_crash AS 
SELECT 1 As id, crash_test('test_1', 'lyr1') As layer;

INSERT INTO test_crash(id, layer)
SELECT id + 1, crash_test('test_1', 'lyr' || (id + 1)::text)
FROM test_crash
WHERE id = 1;

[robe]

reported upstream. I'll close out once fixed upstream.

Thread is here: ​http://www.postgresql.org/message-id/3367.1415311625@sss.pgh.pa.us

[robe]

Problem seems to have been fixed upstream — last run by debbie was successful and I confirmed by doing my own test.