[postgis-tickets] [PostGIS] #4144: If during writing tables that contains PostGIS geometry fields AUTOVACUUM is launched, it crashes and force PostgreSQL to restart.

PostGIS trac at osgeo.org
Thu Aug 9 00:27:34 PDT 2018 

#4144: If during writing tables that contains PostGIS geometry fields AUTOVACUUM
is launched, it crashes and force PostgreSQL to restart.
---------------------+--------------------------
 Reporter:  zancos   |      Owner:  pramsey
     Type:  defect   |     Status:  new
 Priority:  medium   |  Milestone:  PostGIS GDAL
Component:  postgis  |    Version:  2.4.x
 Keywords:           |
---------------------+--------------------------
 If during writing tables that contains PostGIS geometry fields AUTOVACUUM
 is launched, it crashes and force PostgreSQL to restart.
 If over the same table I execute VACUUM manually, it works fine with no
 issues.

 Although it always happens when I try to insert data in the database that
 I am developing, I have also managed to reproduce it by inserting data in
 the following table:


 {{{
 CREATE TABLE "bug_schema"."bug_table" (
   "#tbl" int8 NOT NULL DEFAULT
 nextval('bug_schema."bug_table_#tbl_seq"'::regclass),
   "guid" uuid NOT NULL DEFAULT NULL,
   "text" varchar(255) COLLATE "pg_catalog"."default" NOT NULL DEFAULT
 NULL,
   "metadata" json NOT NULL DEFAULT NULL,
   "bounding_box" "bug_schema"."geometry" NOT NULL DEFAULT NULL,
   "flag" bool NOT NULL DEFAULT NULL,
   "pose" float8[] NOT NULL DEFAULT NULL
 )
 ;
 }}}

 Tested versions:

  * PostgreSQL 9.6.9 on x86_64-pc-linux-gnu (Debian 9.6.9-2.pgdg90+1),
 compiled by gcc (Debian 6.3.0-18+deb9u1) 6.3.0 20170516, 64-bit
  POSTGIS="2.4.4 r16526" PGSQL="96" GEOS="3.5.1-CAPI-1.9.1 r4246"
 SFCGAL="1.3.0" PROJ="Rel. 4.9.3, 15 August 2016" GDAL="GDAL 2.1.2,
 released 2016/10/24" LIBXML="2.9.4" LIBJSON="0.12.1" LIBPROTOBUF="1.2.1"
 RASTER

  * On both, Windows Server 2012 R2 and CentOS Linux release 7.5.1804

  * Also tested with the last PostgreSQL 10.4 and PostGIS 2.4 via docker
 (only over linux)



 Log record one, using our table structure (sorry, I cannot provide you the
 whole database design):


 {{{
 [unknown] 2018-08-08 15:20:07.228 UTC 00000 451LOG:  statement: EXECUTE
 qpsqlpstmt_be8 ('{55a7f8e7-781b-4b50-bb82-d2ed524be4a0}', '{fcce536f-
 c28f-4208-956b-de8c5d58070f}')
 [unknown] 2018-08-08 15:20:07.228 UTC 00000 451DETAIL:  prepare: PREPARE
 qpsqlpstmt_be8 AS INSERT INTO "wdb"."jt_resource_link" ("FK_resource",
 "FK_link") VALUES ($1, $2)
 [unknown] 2018-08-08 15:20:07.230 UTC 00000 451LOG:  statement: DEALLOCATE
 qpsqlpstmt_be8
 [unknown] 2018-08-08 15:20:07.231 UTC 00000 451LOG:  statement: PREPARE
 qpsqlpstmt_be9 AS INSERT INTO "wdb".resource (guid, "FK_resource_type",
 metadata, "FK_entity_owner", deleted) VALUES ($1, (SELECT
 "wdb"."resource_type"."guid" FROM "wdb"."resource_type" WHERE
 "resource_type"."resource_type" = $2), $3, $4, $5)
 [unknown] 2018-08-08 15:20:07.232 UTC 00000 451LOG:  statement: EXECUTE
 qpsqlpstmt_be9 ('{51cabefc-86b0-42c5-8679-542f0fcafa7f}', 'Point Cloud',
 NULL, '{c746c96e-ff10-4eb4-aaeb-0c935f809558}', FALSE)
 [unknown] 2018-08-08 15:20:07.232 UTC 00000 451DETAIL:  prepare: PREPARE
 qpsqlpstmt_be9 AS INSERT INTO "wdb".resource (guid, "FK_resource_type",
 metadata, "FK_entity_owner", deleted) VALUES ($1, (SELECT
 "wdb"."resource_type"."guid" FROM "wdb"."resource_type" WHERE
 "resource_type"."resource_type" = $2), $3, $4, $5)
 [unknown] 2018-08-08 15:20:07.233 UTC 00000 451LOG:  statement: DEALLOCATE
 qpsqlpstmt_be9
 [unknown] 2018-08-08 15:20:07.234 UTC 00000 451LOG:  statement: PREPARE
 qpsqlpstmt_bea AS SELECT "wdb"."server".*,
 "wdb"."server_type"."server_type" FROM "wdb".server INNER JOIN
 "wdb"."server_type" ON "wdb"."server"."FK_server_type" =
 "wdb"."server_type"."guid" WHERE "wdb"."server"."name" = $1 AND
 "wdb"."server"."deleted" = FALSE
 [unknown] 2018-08-08 15:20:07.235 UTC 00000 451LOG:  statement: EXECUTE
 qpsqlpstmt_bea ('CRASH')
 [unknown] 2018-08-08 15:20:07.235 UTC 00000 451DETAIL:  prepare: PREPARE
 qpsqlpstmt_bea AS SELECT "wdb"."server".*,
 "wdb"."server_type"."server_type" FROM "wdb".server INNER JOIN
 "wdb"."server_type" ON "wdb"."server"."FK_server_type" =
 "wdb"."server_type"."guid" WHERE "wdb"."server"."name" = $1 AND
 "wdb"."server"."deleted" = FALSE
 [unknown] 2018-08-08 15:20:07.236 UTC 00000 451LOG:  statement: DEALLOCATE
 qpsqlpstmt_bea
 [unknown] 2018-08-08 15:20:07.237 UTC 00000 451LOG:  statement: PREPARE
 qpsqlpstmt_beb AS SELECT * FROM "wdb".link_view WHERE "path" = $1
 [unknown] 2018-08-08 15:20:07.238 UTC 00000 451LOG:  statement: EXECUTE
 qpsqlpstmt_beb ('\Scan\{c746c96e-ff10-4eb4-aaeb-
 0c935f809558}\20180612_Ed52_Outdoor_Z.C_Scan8.ply')
 [unknown] 2018-08-08 15:20:07.238 UTC 00000 451DETAIL:  prepare: PREPARE
 qpsqlpstmt_beb AS SELECT * FROM "wdb".link_view WHERE "path" = $1
 [unknown] 2018-08-08 15:20:07.239 UTC 00000 451LOG:  statement: DEALLOCATE
 qpsqlpstmt_beb
 [unknown] 2018-08-08 15:20:07.240 UTC 00000 451LOG:  statement: PREPARE
 qpsqlpstmt_bec AS SELECT "wdb"."resource".*,
 "wdb"."resource_type"."resource_type" FROM "wdb"."resource" INNER JOIN
 "wdb"."resource_type" ON "wdb"."resource"."FK_resource_type" =
 "wdb"."resource_type"."guid" INNER JOIN "wdb"."jt_resource_link" ON
 "wdb"."jt_resource_link"."FK_resource" = "wdb"."resource"."guid" WHERE
 "wdb"."jt_resource_link"."FK_link" = $1 AND "wdb"."resource"."deleted" =
 FALSE
 [unknown] 2018-08-08 15:20:07.241 UTC 00000 451LOG:  statement: EXECUTE
 qpsqlpstmt_bec (NULL)
 [unknown] 2018-08-08 15:20:07.241 UTC 00000 451DETAIL:  prepare: PREPARE
 qpsqlpstmt_bec AS SELECT "wdb"."resource".*,
 "wdb"."resource_type"."resource_type" FROM "wdb"."resource" INNER JOIN
 "wdb"."resource_type" ON "wdb"."resource"."FK_resource_type" =
 "wdb"."resource_type"."guid" INNER JOIN "wdb"."jt_resource_link" ON
 "wdb"."jt_resource_link"."FK_resource" = "wdb"."resource"."guid" WHERE
 "wdb"."jt_resource_link"."FK_link" = $1 AND "wdb"."resource"."deleted" =
 FALSE
 [unknown] 2018-08-08 15:20:07.243 UTC 00000 451LOG:  statement: DEALLOCATE
 qpsqlpstmt_bec
 [unknown] 2018-08-08 15:20:07.244 UTC 00000 451LOG:  statement: PREPARE
 qpsqlpstmt_bed AS SELECT "wdb"."server".*,
 "wdb"."server_type"."server_type" FROM "wdb".server INNER JOIN
 "wdb"."server_type" ON "wdb"."server"."FK_server_type" =
 "wdb"."server_type"."guid" INNER JOIN "wdb"."jt_link_server" ON
 "wdb"."jt_link_server"."FK_server" = "wdb"."server"."guid" WHERE
 "wdb"."jt_link_server"."FK_link" = $1 AND "wdb"."server"."deleted" = FALSE
 [unknown] 2018-08-08 15:20:07.244 UTC 00000 451LOG:  statement: EXECUTE
 qpsqlpstmt_bed (NULL)
 [unknown] 2018-08-08 15:20:07.244 UTC 00000 451DETAIL:  prepare: PREPARE
 qpsqlpstmt_bed AS SELECT "wdb"."server".*,
 "wdb"."server_type"."server_type" FROM "wdb".server INNER JOIN
 "wdb"."server_type" ON "wdb"."server"."FK_server_type" =
 "wdb"."server_type"."guid" INNER JOIN "wdb"."jt_link_server" ON
 "wdb"."jt_link_server"."FK_server" = "wdb"."server"."guid" WHERE
 "wdb"."jt_link_server"."FK_link" = $1 AND "wdb"."server"."deleted" = FALSE
 [unknown] 2018-08-08 15:20:07.246 UTC 00000 451LOG:  statement: DEALLOCATE
 qpsqlpstmt_bed
 [unknown] 2018-08-08 15:20:07.247 UTC 00000 451LOG:  statement: PREPARE
 qpsqlpstmt_bee AS INSERT INTO "wdb"."link" ("guid", "FK_link_type",
 "path", "deleted") VALUES ($1, (SELECT "wdb"."link_type"."guid" FROM
 "wdb"."link_type" WHERE "link_type"."link_type" = $2), $3, $4)
 [unknown] 2018-08-08 15:20:07.248 UTC 00000 451LOG:  statement: EXECUTE
 qpsqlpstmt_bee ('{d816c240-95a0-40b8-b1cc-80626505e225}', 'Point Cloud Ply
 link', '\Scan\{c746c96e-ff10-4eb4-aaeb-
 0c935f809558}\20180612_Ed52_Outdoor_Z.C_Scan8.ply', FALSE)
 [unknown] 2018-08-08 15:20:07.248 UTC 00000 451DETAIL:  prepare: PREPARE
 qpsqlpstmt_bee AS INSERT INTO "wdb"."link" ("guid", "FK_link_type",
 "path", "deleted") VALUES ($1, (SELECT "wdb"."link_type"."guid" FROM
 "wdb"."link_type" WHERE "link_type"."link_type" = $2), $3, $4)
 [unknown] 2018-08-08 15:20:07.249 UTC 00000 451LOG:  statement: DEALLOCATE
 qpsqlpstmt_bee
 [unknown] 2018-08-08 15:20:07.250 UTC 00000 451LOG:  statement: PREPARE
 qpsqlpstmt_bef AS INSERT INTO "wdb"."jt_link_server" ("FK_link",
 "FK_server") VALUES ($1, $2)
 [unknown] 2018-08-08 15:20:07.251 UTC 00000 451LOG:  statement: EXECUTE
 qpsqlpstmt_bef ('{d816c240-95a0-40b8-b1cc-80626505e225}',
 '{c8f68af8-52e2-4e12-bcee-e810c5d1a5a5}')
 [unknown] 2018-08-08 15:20:07.251 UTC 00000 451DETAIL:  prepare: PREPARE
 qpsqlpstmt_bef AS INSERT INTO "wdb"."jt_link_server" ("FK_link",
 "FK_server") VALUES ($1, $2)
 [unknown] 2018-08-08 15:20:07.253 UTC 00000 451LOG:  statement: DEALLOCATE
 qpsqlpstmt_bef
  2018-08-08 15:20:08.801 UTC 00000 1LOG:  server process (PID 471) was
 terminated by signal 11: Segmentation fault
  2018-08-08 15:20:08.801 UTC 00000 1DETAIL:  Failed process was running:
 autovacuum: ANALYZE wdb.scan
  2018-08-08 15:20:08.801 UTC 00000 1LOG:  terminating any other active
 server processes
 [unknown] 2018-08-08 15:20:08.801 UTC 57P02 451WARNING:  terminating
 connection because of crash of another server process
 [unknown] 2018-08-08 15:20:08.801 UTC 57P02 451DETAIL:  The postmaster has
 commanded this server process to roll back the current transaction and
 exit, because another server process exited abnormally and possibly
 corrupted shared memory.
 [unknown] 2018-08-08 15:20:08.801 UTC 57P02 451HINT:  In a moment you
 should be able to reconnect to the database and repeat your command.
 [unknown] 2018-08-08 15:20:08.801 UTC 57P02 447WARNING:  terminating
 connection because of crash of another server process
 [unknown] 2018-08-08 15:20:08.801 UTC 57P02 447DETAIL:  The postmaster has
 commanded this server process to roll back the current transaction and
 exit, because another server process exited abnormally and possibly
 corrupted shared memory.
 [unknown] 2018-08-08 15:20:08.801 UTC 57P02 447HINT:  In a moment you
 should be able to reconnect to the database and repeat your command.
 App 2018-08-08 15:20:08.802 UTC 57P02 126WARNING:  terminating connection
 because of crash of another server process
 App 2018-08-08 15:20:08.802 UTC 57P02 126DETAIL:  The postmaster has
 commanded this server process to roll back the current transaction and
 exit, because another server process exited abnormally and possibly
 corrupted shared memory.
 App 2018-08-08 15:20:08.802 UTC 57P02 126HINT:  In a moment you should be
 able to reconnect to the database and repeat your command.
 App 2018-08-08 15:20:08.803 UTC 57P02 31WARNING:  terminating connection
 because of crash of another server process
 App 2018-08-08 15:20:08.803 UTC 57P02 31DETAIL:  The postmaster has
 commanded this server process to roll back the current transaction and
 exit, because another server process exited abnormally and possibly
 corrupted shared memory.
 App 2018-08-08 15:20:08.803 UTC 57P02 31HINT:  In a moment you should be
 able to reconnect to the database and repeat your command.
 App 2018-08-08 15:20:08.804 UTC 57P02 84WARNING:  terminating connection
 because of crash of another server process
 App 2018-08-08 15:20:08.804 UTC 57P02 84DETAIL:  The postmaster has
 commanded this server process to roll back the current transaction and
 exit, because another server process exited abnormally and possibly
 corrupted shared memory.
 App 2018-08-08 15:20:08.804 UTC 57P02 84HINT:  In a moment you should be
 able to reconnect to the database and repeat your command.
 App 2018-08-08 15:20:08.805 UTC 57P02 28WARNING:  terminating connection
 because of crash of another server process
 App 2018-08-08 15:20:08.805 UTC 57P02 28DETAIL:  The postmaster has
 commanded this server process to roll back the current transaction and
 exit, because another server process exited abnormally and possibly
 corrupted shared memory.
 App 2018-08-08 15:20:08.805 UTC 57P02 28HINT:  In a moment you should be
 able to reconnect to the database and repeat your command.
  2018-08-08 15:20:08.807 UTC 57P02 25WARNING:  terminating connection
 because of crash of another server process
  2018-08-08 15:20:08.807 UTC 57P02 25DETAIL:  The postmaster has commanded
 this server process to roll back the current transaction and exit, because
 another server process exited abnormally and possibly corrupted shared
 memory.
  2018-08-08 15:20:08.807 UTC 57P02 25HINT:  In a moment you should be able
 to reconnect to the database and repeat your command.
  2018-08-08 15:20:08.812 UTC 00000 1LOG:  all server processes terminated;
 reinitializing
  2018-08-08 15:20:08.889 UTC 00000 472LOG:  database system was
 interrupted; last known up at 2018-08-08 14:48:13 UTC
  2018-08-08 15:20:10.214 UTC 00000 472LOG:  database system was not
 properly shut down; automatic recovery in progress
  2018-08-08 15:20:10.232 UTC 00000 472LOG:  redo starts at 0/D47FA430
  2018-08-08 15:20:10.249 UTC 00000 472LOG:  invalid record length at
 0/D484D4C0: wanted 24, got 0
  2018-08-08 15:20:10.249 UTC 00000 472LOG:  redo done at 0/D484D498
  2018-08-08 15:20:10.249 UTC 00000 472LOG:  last completed transaction was
 at log time 2018-08-08 15:20:08.508645+00
  2018-08-08 15:20:10.274 UTC 00000 472LOG:  MultiXact member wraparound
 protections are now enabled
  2018-08-08 15:20:10.277 UTC 00000 476LOG:  autovacuum launcher started
  2018-08-08 15:20:10.277 UTC 00000 1LOG:  database system is ready to
 accept connections
 }}}


 Log record two (also attached the whole file)


 {{{
 LOG:  statement: PREPARE qpsqlpstmt_1 AS INSERT INTO
 "bug_database"."bug_schema"."bug_table" (guid, text, metadata,
 bounding_box, flag, pose) VALUES ($1, $2, $3, $4, $5, $6)
 LOG:  statement: EXECUTE qpsqlpstmt_1
 ('{00000000-0000-0000-0000-000000000000}', 'text', '{ }',
 'GEOMETRYCOLLECTION(POINT(0.0 0.0 0.0),POINT(0.0 0.0 0.0))', FALSE, '{0,
 0, 0, 0, 0, 0}')
 DETAIL:  prepare: PREPARE qpsqlpstmt_1 AS INSERT INTO
 "bug_database"."bug_schema"."bug_table" (guid, text, metadata,
 bounding_box, flag, pose) VALUES ($1, $2, $3, $4, $5, $6)
 LOG:  statement: DEALLOCATE qpsqlpstmt_1
 LOG:  statement: PREPARE qpsqlpstmt_1 AS INSERT INTO
 "bug_database"."bug_schema"."bug_table" (guid, text, metadata,
 bounding_box, flag, pose) VALUES ($1, $2, $3, $4, $5, $6)
 LOG:  statement: EXECUTE qpsqlpstmt_1
 ('{00000000-0000-0000-0000-000000000000}', 'text', '{ }',
 'GEOMETRYCOLLECTION(POINT(0.0 0.0 0.0),POINT(0.0 0.0 0.0))', FALSE, '{0,
 0, 0, 0, 0, 0}')
 DETAIL:  prepare: PREPARE qpsqlpstmt_1 AS INSERT INTO
 "bug_database"."bug_schema"."bug_table" (guid, text, metadata,
 bounding_box, flag, pose) VALUES ($1, $2, $3, $4, $5, $6)
 LOG:  statement: DEALLOCATE qpsqlpstmt_1
 LOG:  statement: PREPARE qpsqlpstmt_1 AS INSERT INTO
 "bug_database"."bug_schema"."bug_table" (guid, text, metadata,
 bounding_box, flag, pose) VALUES ($1, $2, $3, $4, $5, $6)
 LOG:  statement: EXECUTE qpsqlpstmt_1
 ('{00000000-0000-0000-0000-000000000000}', 'text', '{ }',
 'GEOMETRYCOLLECTION(POINT(0.0 0.0 0.0),POINT(0.0 0.0 0.0))', FALSE, '{0,
 0, 0, 0, 0, 0}')
 DETAIL:  prepare: PREPARE qpsqlpstmt_1 AS INSERT INTO
 "bug_database"."bug_schema"."bug_table" (guid, text, metadata,
 bounding_box, flag, pose) VALUES ($1, $2, $3, $4, $5, $6)
 LOG:  statement: DEALLOCATE qpsqlpstmt_1
 LOG:  statement: PREPARE qpsqlpstmt_1 AS INSERT INTO
 "bug_database"."bug_schema"."bug_table" (guid, text, metadata,
 bounding_box, flag, pose) VALUES ($1, $2, $3, $4, $5, $6)
 LOG:  statement: EXECUTE qpsqlpstmt_1
 ('{00000000-0000-0000-0000-000000000000}', 'text', '{ }',
 'GEOMETRYCOLLECTION(POINT(0.0 0.0 0.0),POINT(0.0 0.0 0.0))', FALSE, '{0,
 0, 0, 0, 0, 0}')
 DETAIL:  prepare: PREPARE qpsqlpstmt_1 AS INSERT INTO
 "bug_database"."bug_schema"."bug_table" (guid, text, metadata,
 bounding_box, flag, pose) VALUES ($1, $2, $3, $4, $5, $6)
 LOG:  statement: DEALLOCATE qpsqlpstmt_1
 LOG:  statement: PREPARE qpsqlpstmt_1 AS INSERT INTO
 "bug_database"."bug_schema"."bug_table" (guid, text, metadata,
 bounding_box, flag, pose) VALUES ($1, $2, $3, $4, $5, $6)
 LOG:  statement: EXECUTE qpsqlpstmt_1
 ('{00000000-0000-0000-0000-000000000000}', 'text', '{ }',
 'GEOMETRYCOLLECTION(POINT(0.0 0.0 0.0),POINT(0.0 0.0 0.0))', FALSE, '{0,
 0, 0, 0, 0, 0}')
 DETAIL:  prepare: PREPARE qpsqlpstmt_1 AS INSERT INTO
 "bug_database"."bug_schema"."bug_table" (guid, text, metadata,
 bounding_box, flag, pose) VALUES ($1, $2, $3, $4, $5, $6)
 LOG:  statement: DEALLOCATE qpsqlpstmt_1
 LOG:  server process (PID 28) was terminated by signal 11: Segmentation
 fault
 DETAIL:  Failed process was running: autovacuum: ANALYZE
 bug_schema.bug_table
 LOG:  terminating any other active server processes
 WARNING:  terminating connection because of crash of another server
 process
 DETAIL:  The postmaster has commanded this server process to roll back the
 current transaction and exit, because another server process exited
 abnormally and possibly corrupted shared memory.
 HINT:  In a moment you should be able to reconnect to the database and
 repeat your command.
 WARNING:  terminating connection because of crash of another server
 process
 DETAIL:  The postmaster has commanded this server process to roll back the
 current transaction and exit, because another server process exited
 abnormally and possibly corrupted shared memory.
 HINT:  In a moment you should be able to reconnect to the database and
 repeat your command.
 LOG:  all server processes terminated; reinitializing
 LOG:  database system was interrupted; last known up at 2018-08-07
 14:18:12 UTC
 LOG:  database system was not properly shut down; automatic recovery in
 progress
 LOG:  redo starts at 0/CE894A60
 LOG:  invalid record length at 0/CE8B5540: wanted 24, got 0
 LOG:  redo done at 0/CE8B5518
 LOG:  last completed transaction was at log time 2018-08-07
 14:19:35.060534+00
 LOG:  MultiXact member wraparound protections are now enabled
 LOG:  database system is ready to accept connections
 LOG:  autovacuum launcher started
 }}}



 I used for testing the following Dockerfile to build the testing platform:


 {{{
 FROM postgres:9.6

 ##Installation
 RUN apt-get -y update && apt-get -y install postgresql-9.6-postgis-2.4
 postgresql-9.6-postgis-2.4-scripts --no-install-recommends

 ## cleaning
 RUN apt-get purge -y --auto-remove && apt-get -y autoclean && rm -fr
 /var/lib/apt/lists/*
 }}}


 Maybe could also be related with this reported bug:
 https://trac.osgeo.org/postgis/ticket/3550#no1

 Disabling autovacuum, I have no issues inserting the same records in the
 same database structure.
 I'm not a PostgreSQL / Database expert, so please, let me know how could I
 provide you better information if needed.

-- 
Ticket URL: <https://trac.osgeo.org/postgis/ticket/4144>
PostGIS <http://trac.osgeo.org/postgis/>
The PostGIS Trac is used for bug, enhancement & task tracking, a user and developer wiki, and a view into the subversion code repository of PostGIS project.

More information about the postgis-tickets mailing list