Database migration chokes on huge value of a "calendar-details" item in table "post_custom_fields"

amotl · December 7, 2020, 11:54am

TLDR;

At post #4 ff., we have been able to confirm that this problem was related to Discourse Calendar and the database migration was nudged into success after deactivating this temporarily – thanks @falco.
At post #9 ff., we found that the value of a specific calendar-details item on a single post contained ~80MB worth of data.
After deleting the offending row as outlined in post #13, the database migration has been fully successful even after enabling Discourse Calendar again – thanks again, @falco.
The background on this is a database migration being applied since March 2020, see https://github.com/discourse/discourse-calendar/pull/23. Thanks, @nbianca, @eviltrout and @joffreyjaffeux.

Dear Discourse developers,

after some time we had not been able to take care about our Discourse instances on https://community.hiveeyes.org/ and https://community.panodata.org/, we went into the process of upgrading them yesterday night.

The upgrade on the Hiveeyes Community Forum went pretty smooth as always. PostgreSQL was upgraded from version 10 to version 12 and it was a pleasure to watch the upgrade process without further ado. Kudos to the whole team for the excellent work you are putting into Discourse!

However, when trying to upgrade the Panodata Community Forum, we are observing some problems now. On the second stage of running ./launcher rebuild community.panodata.org, the system is experiencing extremely high load and currently grinds the whole machine.

I’ve kind of identified where this starts and will share some parts of the logs here. Apparently, it looks like the database migration process is running into a loop of some kind when touching the post_custom_fields table. Let me know if you need more information about that.

Did I manage to get ourselves into serious trouble here? I am very much looking forward on anything which could help us getting out of this situation.

Thank you in advance and with kind regards,
Andreas.

I, [2020-12-07T11:33:28.554810 #1]  INFO -- : > cd /var/www/discourse && su discourse -c 'bundle exec rake db:migrate'
2020-12-07 11:33:34.200 UTC [3888] discourse@discourse LOG:  duration: 119.116 ms  parse <unnamed>: SELECT t.oid, t.typname
	FROM pg_type as t
	WHERE t.typname IN ('int2', 'int4', 'int8', 'oid', 'float4', 'float8', 'bool', 'timestamp', 'timestamptz')

2020-12-07 11:33:34.413 UTC [3888] discourse@discourse LOG:  duration: 213.398 ms  bind <unnamed>: SELECT t.oid, t.typname
	FROM pg_type as t
	WHERE t.typname IN ('int2', 'int4', 'int8', 'oid', 'float4', 'float8', 'bool', 'timestamp', 'timestamptz')

2020-12-07 11:33:34.662 UTC [3888] discourse@discourse LOG:  duration: 220.921 ms  parse <unnamed>: SELECT t.oid, t.typname, t.typelem, t.typdelim, t.typinput, r.rngsubtype, t.typtype, t.typbasetype
	FROM pg_type as t
	LEFT JOIN pg_range as r ON oid = rngtypid
	WHERE
	  t.typname IN ('int2', 'int4', 'int8', 'oid', 'float4', 'float8', 'text', 'varchar', 'char', 'name', 'bpchar', 'bool', 'bit', 'varbit', 'timestamptz', 'date', 'money', 'bytea', 'point', 'hstore', 'json', 'jsonb', 'cidr', 'inet', 'uuid', 'xml', 'tsvector', 'macaddr', 'citext', 'ltree', 'line', 'lseg', 'box', 'path', 'polygon', 'circle', 'interval', 'time', 'timestamp', 'numeric')
	  OR t.typtype IN ('r', 'e', 'd')
	  OR t.typinput = 'array_in(cstring,oid,integer)'::regprocedure
	  OR t.typelem != 0

2020-12-07 11:33:34.820 UTC [3888] discourse@discourse LOG:  duration: 157.985 ms  bind <unnamed>: SELECT t.oid, t.typname, t.typelem, t.typdelim, t.typinput, r.rngsubtype, t.typtype, t.typbasetype
	FROM pg_type as t
	LEFT JOIN pg_range as r ON oid = rngtypid
	WHERE
	  t.typname IN ('int2', 'int4', 'int8', 'oid', 'float4', 'float8', 'text', 'varchar', 'char', 'name', 'bpchar', 'bool', 'bit', 'varbit', 'timestamptz', 'date', 'money', 'bytea', 'point', 'hstore', 'json', 'jsonb', 'cidr', 'inet', 'uuid', 'xml', 'tsvector', 'macaddr', 'citext', 'ltree', 'line', 'lseg', 'box', 'path', 'polygon', 'circle', 'interval', 'time', 'timestamp', 'numeric')
	  OR t.typtype IN ('r', 'e', 'd')
	  OR t.typinput = 'array_in(cstring,oid,integer)'::regprocedure
	  OR t.typelem != 0

2020-12-07 11:33:35.197 UTC [3888] discourse@discourse LOG:  duration: 376.904 ms  execute <unnamed>: SELECT t.oid, t.typname, t.typelem, t.typdelim, t.typinput, r.rngsubtype, t.typtype, t.typbasetype
	FROM pg_type as t
	LEFT JOIN pg_range as r ON oid = rngtypid
	WHERE
	  t.typname IN ('int2', 'int4', 'int8', 'oid', 'float4', 'float8', 'text', 'varchar', 'char', 'name', 'bpchar', 'bool', 'bit', 'varbit', 'timestamptz', 'date', 'money', 'bytea', 'point', 'hstore', 'json', 'jsonb', 'cidr', 'inet', 'uuid', 'xml', 'tsvector', 'macaddr', 'citext', 'ltree', 'line', 'lseg', 'box', 'path', 'polygon', 'circle', 'interval', 'time', 'timestamp', 'numeric')
	  OR t.typtype IN ('r', 'e', 'd')
	  OR t.typinput = 'array_in(cstring,oid,integer)'::regprocedure
	  OR t.typelem != 0

2020-12-07 11:33:35.388 UTC [3888] discourse@discourse LOG:  duration: 165.044 ms  statement: SELECT name, data_type, value FROM site_settings
2020-12-07 11:33:37.170 UTC [3888] discourse@discourse LOG:  duration: 166.378 ms  statement: SELECT a.attname, format_type(a.atttypid, a.atttypmod),
	       pg_get_expr(d.adbin, d.adrelid), a.attnotnull, a.atttypid, a.atttypmod,
	       c.collname, col_description(a.attrelid, a.attnum) AS comment
	  FROM pg_attribute a
	  LEFT JOIN pg_attrdef d ON a.attrelid = d.adrelid AND a.attnum = d.adnum
	  LEFT JOIN pg_type t ON a.atttypid = t.oid
	  LEFT JOIN pg_collation c ON a.attcollation = c.oid AND a.attcollation <> t.typcollation
	 WHERE a.attrelid = '"users"'::regclass
	   AND a.attnum > 0 AND NOT a.attisdropped
	 ORDER BY a.attnum

2020-12-07 11:33:40.578 UTC [3888] discourse@discourse ERROR:  relation "user_api_key_scopes" does not exist at character 454
2020-12-07 11:33:40.578 UTC [3888] discourse@discourse STATEMENT:  SELECT a.attname, format_type(a.atttypid, a.atttypmod),
	       pg_get_expr(d.adbin, d.adrelid), a.attnotnull, a.atttypid, a.atttypmod,
	       c.collname, col_description(a.attrelid, a.attnum) AS comment
	  FROM pg_attribute a
	  LEFT JOIN pg_attrdef d ON a.attrelid = d.adrelid AND a.attnum = d.adnum
	  LEFT JOIN pg_type t ON a.atttypid = t.oid
	  LEFT JOIN pg_collation c ON a.attcollation = c.oid AND a.attcollation <> t.typcollation
	 WHERE a.attrelid = '"user_api_key_scopes"'::regclass
	   AND a.attnum > 0 AND NOT a.attisdropped
	 ORDER BY a.attnum

2020-12-07 11:33:41.954 UTC [3898] discourse@discourse LOG:  duration: 232.874 ms  statement: CREATE TABLE "calendar_events" ("id" bigserial primary key, "topic_id" integer NOT NULL, "post_id" integer, "post_number" integer, "user_id" integer, "username" character varying, "description" character varying, "start_date" timestamp NOT NULL, "end_date" timestamp, "recurrence" character varying, "region" character varying, "created_at" timestamp NOT NULL, "updated_at" timestamp NOT NULL)
2020-12-07 11:33:42.693 UTC [3898] discourse@discourse LOG:  duration: 349.048 ms  execute <unnamed>: SELECT "post_custom_fields"."name", "post_custom_fields"."value" FROM "post_custom_fields" WHERE "post_custom_fields"."post_id" = 20 ORDER BY id asc
2020-12-07 11:33:43.190 UTC [3898] discourse@discourse LOG:  duration: 289.433 ms  execute <unnamed>: SELECT "post_custom_fields"."name", "post_custom_fields"."value" FROM "post_custom_fields" WHERE "post_custom_fields"."post_id" = 20 ORDER BY id asc
2020-12-07 11:33:43.692 UTC [3898] discourse@discourse LOG:  duration: 293.116 ms  execute <unnamed>: SELECT "post_custom_fields"."name", "post_custom_fields"."value" FROM "post_custom_fields" WHERE "post_custom_fields"."post_id" = 20 ORDER BY id asc
2020-12-07 11:33:44.189 UTC [3898] discourse@discourse LOG:  duration: 288.891 ms  execute <unnamed>: SELECT "post_custom_fields"."name", "post_custom_fields"."value" FROM "post_custom_fields" WHERE "post_custom_fields"."post_id" = 20 ORDER BY id asc
2020-12-07 11:33:44.622 UTC [3898] discourse@discourse LOG:  duration: 290.721 ms  execute <unnamed>: SELECT "post_custom_fields"."name", "post_custom_fields"."value" FROM "post_custom_fields" WHERE "post_custom_fields"."post_id" = 20 ORDER BY id asc
2020-12-07 11:33:45.051 UTC [3898] discourse@discourse LOG:  duration: 291.924 ms  execute <unnamed>: SELECT "post_custom_fields"."name", "post_custom_fields"."value" FROM "post_custom_fields" WHERE "post_custom_fields"."post_id" = 20 ORDER BY id asc
2020-12-07 11:33:45.544 UTC [3898] discourse@discourse LOG:  duration: 289.327 ms  execute <unnamed>: SELECT "post_custom_fields"."name", "post_custom_fields"."value" FROM "post_custom_fields" WHERE "post_custom_fields"."post_id" = 20 ORDER BY id asc
2020-12-07 11:33:46.039 UTC [3898] discourse@discourse LOG:  duration: 291.734 ms  execute <unnamed>: SELECT "post_custom_fields"."name", "post_custom_fields"."value" FROM "post_custom_fields" WHERE "post_custom_fields"."post_id" = 20 ORDER BY id asc
2020-12-07 11:33:46.471 UTC [3898] discourse@discourse LOG:  duration: 290.173 ms  execute <unnamed>: SELECT "post_custom_fields"."name", "post_custom_fields"."value" FROM "post_custom_fields" WHERE "post_custom_fields"."post_id" = 20 ORDER BY id asc
2020-12-07 11:33:46.900 UTC [3898] discourse@discourse LOG:  duration: 288.805 ms  execute <unnamed>: SELECT "post_custom_fields"."name", "post_custom_fields"."value" FROM "post_custom_fields" WHERE "post_custom_fields"."post_id" = 20 ORDER BY id asc
2020-12-07 11:33:47.392 UTC [3898] discourse@discourse LOG:  duration: 288.812 ms  execute <unnamed>: SELECT "post_custom_fields"."name", "post_custom_fields"."value" FROM "post_custom_fields" WHERE "post_custom_fields"."post_id" = 20 ORDER BY id asc
2020-12-07 11:33:47.884 UTC [3898] discourse@discourse LOG:  duration: 286.272 ms  execute <unnamed>: SELECT "post_custom_fields"."name", "post_custom_fields"."value" FROM "post_custom_fields" WHERE "post_custom_fields"."post_id" = 20 ORDER BY id asc
2020-12-07 11:33:48.326 UTC [3898] discourse@discourse LOG:  duration: 302.706 ms  execute <unnamed>: SELECT "post_custom_fields"."name", "post_custom_fields"."value" FROM "post_custom_fields" WHERE "post_custom_fields"."post_id" = 20 ORDER BY id asc
2020-12-07 11:33:48.755 UTC [3898] discourse@discourse LOG:  duration: 288.766 ms  execute <unnamed>: SELECT "post_custom_fields"."name", "post_custom_fields"."value" FROM "post_custom_fields" WHERE "post_custom_fields"."post_id" = 20 ORDER BY id asc
2020-12-07 11:33:49.260 UTC [3898] discourse@discourse LOG:  duration: 299.901 ms  execute <unnamed>: SELECT "post_custom_fields"."name", "post_custom_fields"."value" FROM "post_custom_fields" WHERE "post_custom_fields"."post_id" = 20 ORDER BY id asc
2020-12-07 11:33:49.762 UTC [3898] discourse@discourse LOG:  duration: 293.430 ms  execute <unnamed>: SELECT "post_custom_fields"."name", "post_custom_fields"."value" FROM "post_custom_fields" WHERE "post_custom_fields"."post_id" = 20 ORDER BY id asc
2020-12-07 11:33:50.192 UTC [3898] discourse@discourse LOG:  duration: 291.202 ms  execute <unnamed>: SELECT "post_custom_fields"."name", "post_custom_fields"."value" FROM "post_custom_fields" WHERE "post_custom_fields"."post_id" = 20 ORDER BY id asc
2020-12-07 11:33:50.625 UTC [3898] discourse@discourse LOG:  duration: 293.805 ms  execute <unnamed>: SELECT "post_custom_fields"."name", "post_custom_fields"."value" FROM "post_custom_fields" WHERE "post_custom_fields"."post_id" = 20 ORDER BY id asc
2020-12-07 11:33:51.138 UTC [3898] discourse@discourse LOG:  duration: 301.952 ms  execute <unnamed>: SELECT "post_custom_fields"."name", "post_custom_fields"."value" FROM "post_custom_fields" WHERE "post_custom_fields"."post_id" = 20 ORDER BY id asc
2020-12-07 11:33:51.643 UTC [3898] discourse@discourse LOG:  duration: 291.137 ms  execute <unnamed>: SELECT "post_custom_fields"."name", "post_custom_fields"."value" FROM "post_custom_fields" WHERE "post_custom_fields"."post_id" = 20 ORDER BY id asc
2020-12-07 11:33:52.075 UTC [3898] discourse@discourse LOG:  duration: 292.726 ms  execute <unnamed>: SELECT "post_custom_fields"."name", "post_custom_fields"."value" FROM "post_custom_fields" WHERE "post_custom_fields"."post_id" = 20 ORDER BY id asc
2020-12-07 11:33:52.517 UTC [3898] discourse@discourse LOG:  duration: 301.480 ms  execute <unnamed>: SELECT "post_custom_fields"."name", "post_custom_fields"."value" FROM "post_custom_fields" WHERE "post_custom_fields"."post_id" = 20 ORDER BY id asc
2020-12-07 11:33:53.027 UTC [3898] discourse@discourse LOG:  duration: 295.174 ms  execute <unnamed>: SELECT "post_custom_fields"."name", "post_custom_fields"."value" FROM "post_custom_fields" WHERE "post_custom_fields"."post_id" = 20 ORDER BY id asc
2020-12-07 11:33:53.583 UTC [3898] discourse@discourse LOG:  duration: 292.007 ms  execute <unnamed>: SELECT "post_custom_fields"."name", "post_custom_fields"."value" FROM "post_custom_fields" WHERE "post_custom_fields"."post_id" = 20 ORDER BY id asc
2020-12-07 11:33:54.025 UTC [3898] discourse@discourse LOG:  duration: 298.499 ms  execute <unnamed>: SELECT "post_custom_fields"."name", "post_custom_fields"."value" FROM "post_custom_fields" WHERE "post_custom_fields"."post_id" = 20 ORDER BY id asc
2020-12-07 11:33:54.461 UTC [3898] discourse@discourse LOG:  duration: 294.801 ms  execute <unnamed>: SELECT "post_custom_fields"."name", "post_custom_fields"."value" FROM "post_custom_fields" WHERE "post_custom_fields"."post_id" = 20 ORDER BY id asc
2020-12-07 11:33:54.957 UTC [3898] discourse@discourse LOG:  duration: 289.026 ms  execute <unnamed>: SELECT "post_custom_fields"."name", "post_custom_fields"."value" FROM "post_custom_fields" WHERE "post_custom_fields"."post_id" = 20 ORDER BY id asc
2020-12-07 11:33:55.463 UTC [3898] discourse@discourse LOG:  duration: 301.325 ms  execute <unnamed>: SELECT "post_custom_fields"."name", "post_custom_fields"."value" FROM "post_custom_fields" WHERE "post_custom_fields"."post_id" = 20 ORDER BY id asc
2020-12-07 11:33:55.905 UTC [3898] discourse@discourse LOG:  duration: 296.361 ms  execute <unnamed>: SELECT "post_custom_fields"."name", "post_custom_fields"."value" FROM "post_custom_fields" WHERE "post_custom_fields"."post_id" = 20 ORDER BY id asc
2020-12-07 11:33:56.348 UTC [3898] discourse@discourse LOG:  duration: 302.991 ms  execute <unnamed>: SELECT "post_custom_fields"."name", "post_custom_fields"."value" FROM "post_custom_fields" WHERE "post_custom_fields"."post_id" = 20 ORDER BY id asc
2020-12-07 11:33:58.843 UTC [3898] discourse@discourse LOG:  duration: 2289.322 ms  execute <unnamed>: SELECT "post_custom_fields"."name", "post_custom_fields"."value" FROM "post_custom_fields" WHERE "post_custom_fields"."post_id" = 20 ORDER BY id asc
2020-12-07 11:33:59.376 UTC [3898] discourse@discourse LOG:  duration: 322.300 ms  execute <unnamed>: SELECT "post_custom_fields"."name", "post_custom_fields"."value" FROM "post_custom_fields" WHERE "post_custom_fields"."post_id" = 20 ORDER BY id asc
2020-12-07 11:34:00.445 UTC [3898] discourse@discourse LOG:  duration: 921.013 ms  execute <unnamed>: SELECT "post_custom_fields"."name", "post_custom_fields"."value" FROM "post_custom_fields" WHERE "post_custom_fields"."post_id" = 20 ORDER BY id asc
2020-12-07 11:34:00.749 UTC [3898] discourse@discourse LOG:  duration: 111.277 ms  bind <unnamed>: SELECT "calendar_events".* FROM "calendar_events" WHERE "calendar_events"."post_id" = 186
2020-12-07 11:34:02.055 UTC [3898] discourse@discourse LOG:  duration: 1302.319 ms  execute <unnamed>: SELECT "post_custom_fields"."name", "post_custom_fields"."value" FROM "post_custom_fields" WHERE "post_custom_fields"."post_id" = 20 ORDER BY id asc
2020-12-07 11:34:02.611 UTC [3898] discourse@discourse LOG:  duration: 299.807 ms  execute <unnamed>: SELECT "post_custom_fields"."name", "post_custom_fields"."value" FROM "post_custom_fields" WHERE "post_custom_fields"."post_id" = 20 ORDER BY id asc
2020-12-07 11:34:03.130 UTC [3898] discourse@discourse LOG:  duration: 310.089 ms  execute <unnamed>: SELECT "post_custom_fields"."name", "post_custom_fields"."value" FROM "post_custom_fields" WHERE "post_custom_fields"."post_id" = 20 ORDER BY id asc
2020-12-07 11:34:03.586 UTC [3898] discourse@discourse LOG:  duration: 310.537 ms  execute <unnamed>: SELECT "post_custom_fields"."name", "post_custom_fields"."value" FROM "post_custom_fields" WHERE "post_custom_fields"."post_id" = 20 ORDER BY id asc
2020-12-07 11:34:04.050 UTC [3898] discourse@discourse LOG:  duration: 316.072 ms  execute <unnamed>: SELECT "post_custom_fields"."name", "post_custom_fields"."value" FROM "post_custom_fields" WHERE "post_custom_fields"."post_id" = 20 ORDER BY id asc
2020-12-07 11:34:04.585 UTC [3898] discourse@discourse LOG:  duration: 315.813 ms  execute <unnamed>: SELECT "post_custom_fields"."name", "post_custom_fields"."value" FROM "post_custom_fields" WHERE "post_custom_fields"."post_id" = 20 ORDER BY id asc
2020-12-07 11:34:05.138 UTC [3898] discourse@discourse LOG:  duration: 332.339 ms  execute <unnamed>: SELECT "post_custom_fields"."name", "post_custom_fields"."value" FROM "post_custom_fields" WHERE "post_custom_fields"."post_id" = 20 ORDER BY id asc
2020-12-07 11:34:05.611 UTC [3898] discourse@discourse LOG:  duration: 320.420 ms  execute <unnamed>: SELECT "post_custom_fields"."name", "post_custom_fields"."value" FROM "post_custom_fields" WHERE "post_custom_fields"."post_id" = 20 ORDER BY id asc
2020-12-07 11:34:06.086 UTC [3898] discourse@discourse LOG:  duration: 313.841 ms  execute <unnamed>: SELECT "post_custom_fields"."name", "post_custom_fields"."value" FROM "post_custom_fields" WHERE "post_custom_fields"."post_id" = 20 ORDER BY id asc
2020-12-07 11:34:06.636 UTC [3898] discourse@discourse LOG:  duration: 330.514 ms  execute <unnamed>: SELECT "post_custom_fields"."name", "post_custom_fields"."value" FROM "post_custom_fields" WHERE "post_custom_fields"."post_id" = 20 ORDER BY id asc
2020-12-07 11:34:07.277 UTC [3898] discourse@discourse LOG:  duration: 423.374 ms  execute <unnamed>: SELECT "post_custom_fields"."name", "post_custom_fields"."value" FROM "post_custom_fields" WHERE "post_custom_fields"."post_id" = 20 ORDER BY id asc
2020-12-07 11:34:08.308 UTC [3898] discourse@discourse LOG:  duration: 881.346 ms  execute <unnamed>: SELECT "post_custom_fields"."name", "post_custom_fields"."value" FROM "post_custom_fields" WHERE "post_custom_fields"."post_id" = 20 ORDER BY id asc
2020-12-07 11:34:09.041 UTC [3898] discourse@discourse LOG:  duration: 581.518 ms  execute <unnamed>: SELECT "post_custom_fields"."name", "post_custom_fields"."value" FROM "post_custom_fields" WHERE "post_custom_fields"."post_id" = 20 ORDER BY id asc
2020-12-07 11:34:09.674 UTC [3898] discourse@discourse LOG:  duration: 413.955 ms  execute <unnamed>: SELECT "post_custom_fields"."name", "post_custom_fields"."value" FROM "post_custom_fields" WHERE "post_custom_fields"."post_id" = 20 ORDER BY id asc
2020-12-07 11:34:10.538 UTC [3898] discourse@discourse LOG:  duration: 642.608 ms  execute <unnamed>: SELECT "post_custom_fields"."name", "post_custom_fields"."value" FROM "post_custom_fields" WHERE "post_custom_fields"."post_id" = 20 ORDER BY id asc
2020-12-07 11:34:11.047 UTC [3898] discourse@discourse LOG:  duration: 358.794 ms  execute <unnamed>: SELECT "post_custom_fields"."name", "post_custom_fields"."value" FROM "post_custom_fields" WHERE "post_custom_fields"."post_id" = 20 ORDER BY id asc
2020-12-07 11:34:17.793 UTC [3898] discourse@discourse LOG:  duration: 6599.545 ms  execute <unnamed>: SELECT "post_custom_fields"."name", "post_custom_fields"."value" FROM "post_custom_fields" WHERE "post_custom_fields"."post_id" = 20 ORDER BY id asc
2020-12-07 11:34:33.146 UTC [3898] discourse@discourse LOG:  duration: 15127.645 ms  execute <unnamed>: SELECT "post_custom_fields"."name", "post_custom_fields"."value" FROM "post_custom_fields" WHERE "post_custom_fields"."post_id" = 20 ORDER BY id asc
2020-12-07 11:34:53.075 UTC [3898] discourse@discourse LOG:  duration: 316.940 ms  execute <unnamed>: SELECT "post_custom_fields"."name", "post_custom_fields"."value" FROM "post_custom_fields" WHERE "post_custom_fields"."post_id" = 20 ORDER BY id asc
2020-12-07 11:35:04.574 UTC [57] LOG:  using stale statistics instead of current ones because stats collector is not responding
2020-12-07 11:35:19.396 UTC [3898] discourse@discourse LOG:  duration: 26159.832 ms  execute <unnamed>: SELECT "post_custom_fields"."name", "post_custom_fields"."value" FROM "post_custom_fields" WHERE "post_custom_fields"."post_id" = 20 ORDER BY id asc
2020-12-07 11:35:19.893 UTC [3898] discourse@discourse LOG:  duration: 315.783 ms  execute <unnamed>: SELECT "post_custom_fields"."name", "post_custom_fields"."value" FROM "post_custom_fields" WHERE "post_custom_fields"."post_id" = 20 ORDER BY id asc
2020-12-07 11:35:20.438 UTC [3898] discourse@discourse LOG:  duration: 322.196 ms  execute <unnamed>: SELECT "post_custom_fields"."name", "post_custom_fields"."value" FROM "post_custom_fields" WHERE "post_custom_fields"."post_id" = 20 ORDER BY id asc
2020-12-07 11:35:21.081 UTC [3898] discourse@discourse LOG:  duration: 403.873 ms  execute <unnamed>: SELECT "post_custom_fields"."name", "post_custom_fields"."value" FROM "post_custom_fields" WHERE "post_custom_fields"."post_id" = 20 ORDER BY id asc
2020-12-07 11:35:34.236 UTC [3898] discourse@discourse LOG:  duration: 12995.895 ms  execute <unnamed>: SELECT "post_custom_fields"."name", "post_custom_fields"."value" FROM "post_custom_fields" WHERE "post_custom_fields"."post_id" = 20 ORDER BY id asc
2020-12-07 11:35:55.785 UTC [3898] discourse@discourse LOG:  duration: 20970.124 ms  execute <unnamed>: SELECT "post_custom_fields"."name", "post_custom_fields"."value" FROM "post_custom_fields" WHERE "post_custom_fields"."post_id" = 20 ORDER BY id asc
167:M 07 Dec 2020 11:36:31.074 * 10 changes in 300 seconds. Saving...
167:M 07 Dec 2020 11:36:31.267 * Background saving started by pid 3911
2020-12-07 11:36:40.770 UTC [3898] discourse@discourse LOG:  duration: 44203.350 ms  execute <unnamed>: SELECT "post_custom_fields"."name", "post_custom_fields"."value" FROM "post_custom_fields" WHERE "post_custom_fields"."post_id" = 20 ORDER BY id asc
3911:C 07 Dec 2020 11:36:52.503 * DB saved on disk
3911:C 07 Dec 2020 11:36:52.518 * RDB: 1 MB of memory used by copy-on-write
167:M 07 Dec 2020 11:36:52.618 * Background saving terminated with success
2020-12-07 11:37:00.570 UTC [3898] discourse@discourse LOG:  duration: 19089.557 ms  execute <unnamed>: SELECT "post_custom_fields"."name", "post_custom_fields"."value" FROM "post_custom_fields" WHERE "post_custom_fields"."post_id" = 20 ORDER BY id asc
2020-12-07 11:37:09.917 UTC [3898] discourse@discourse LOG:  duration: 9086.196 ms  execute <unnamed>: SELECT "post_custom_fields"."name", "post_custom_fields"."value" FROM "post_custom_fields" WHERE "post_custom_fields"."post_id" = 20 ORDER BY id asc
2020-12-07 11:37:50.176 UTC [3898] discourse@discourse LOG:  duration: 39768.704 ms  execute <unnamed>: SELECT "post_custom_fields"."name", "post_custom_fields"."value" FROM "post_custom_fields" WHERE "post_custom_fields"."post_id" = 20 ORDER BY id asc
2020-12-07 11:38:06.180 UTC [3898] discourse@discourse LOG:  duration: 15340.958 ms  execute <unnamed>: SELECT "post_custom_fields"."name", "post_custom_fields"."value" FROM "post_custom_fields" WHERE "post_custom_fields"."post_id" = 20 ORDER BY id asc
2020-12-07 11:38:16.549 UTC [3898] discourse@discourse LOG:  duration: 9526.000 ms  execute <unnamed>: SELECT "post_custom_fields"."name", "post_custom_fields"."value" FROM "post_custom_fields" WHERE "post_custom_fields"."post_id" = 20 ORDER BY id asc
2020-12-07 11:38:45.231 UTC [3898] discourse@discourse LOG:  duration: 28221.839 ms  execute <unnamed>: SELECT "post_custom_fields"."name", "post_custom_fields"."value" FROM "post_custom_fields" WHERE "post_custom_fields"."post_id" = 20 ORDER BY id asc
2020-12-07 11:39:26.818 UTC [3898] discourse@discourse LOG:  duration: 41289.489 ms  execute <unnamed>: SELECT "post_custom_fields"."name", "post_custom_fields"."value" FROM "post_custom_fields" WHERE "post_custom_fields"."post_id" = 20 ORDER BY id asc
2020-12-07 11:39:56.099 UTC [3898] discourse@discourse LOG:  duration: 28172.307 ms  execute <unnamed>: SELECT "post_custom_fields"."name", "post_custom_fields"."value" FROM "post_custom_fields" WHERE "post_custom_fields"."post_id" = 20 ORDER BY id asc
2020-12-07 11:39:58.117 UTC [3898] discourse@discourse LOG:  duration: 1384.587 ms  execute <unnamed>: SELECT "post_custom_fields"."name", "post_custom_fields"."value" FROM "post_custom_fields" WHERE "post_custom_fields"."post_id" = 20 ORDER BY id asc
2020-12-07 11:39:59.305 UTC [3898] discourse@discourse LOG:  duration: 758.125 ms  execute <unnamed>: SELECT "post_custom_fields"."name", "post_custom_fields"."value" FROM "post_custom_fields" WHERE "post_custom_fields"."post_id" = 20 ORDER BY id asc
2020-12-07 11:41:07.711 UTC [3898] discourse@discourse LOG:  duration: 67823.399 ms  execute <unnamed>: SELECT "post_custom_fields"."name", "post_custom_fields"."value" FROM "post_custom_fields" WHERE "post_custom_fields"."post_id" = 20 ORDER BY id asc
2020-12-07 11:41:24.048 UTC [3898] discourse@discourse LOG:  duration: 15546.933 ms  execute <unnamed>: SELECT "post_custom_fields"."name", "post_custom_fields"."value" FROM "post_custom_fields" WHERE "post_custom_fields"."post_id" = 20 ORDER BY id asc
2020-12-07 11:41:35.033 UTC [3898] discourse@discourse LOG:  duration: 10181.365 ms  execute <unnamed>: SELECT "post_custom_fields"."name", "post_custom_fields"."value" FROM "post_custom_fields" WHERE "post_custom_fields"."post_id" = 20 ORDER BY id asc
2020-12-07 11:42:04.037 UTC [3898] discourse@discourse LOG:  duration: 28545.266 ms  execute <unnamed>: SELECT "post_custom_fields"."name", "post_custom_fields"."value" FROM "post_custom_fields" WHERE "post_custom_fields"."post_id" = 20 ORDER BY id asc
2020-12-07 11:43:41.573 UTC [3898] discourse@discourse LOG:  duration: 92603.676 ms  execute <unnamed>: SELECT "post_custom_fields"."name", "post_custom_fields"."value" FROM "post_custom_fields" WHERE "post_custom_fields"."post_id" = 20 ORDER BY id asc
2020-12-07 11:43:50.101 UTC [3898] discourse@discourse LOG:  duration: 7813.096 ms  execute <unnamed>: SELECT "post_custom_fields"."name", "post_custom_fields"."value" FROM "post_custom_fields" WHERE "post_custom_fields"."post_id" = 20 ORDER BY id asc
2020-12-07 11:44:03.377 UTC [3898] discourse@discourse LOG:  duration: 12590.301 ms  execute <unnamed>: SELECT "post_custom_fields"."name", "post_custom_fields"."value" FROM "post_custom_fields" WHERE "post_custom_fields"."post_id" = 20 ORDER BY id asc
2020-12-07 11:44:37.995 UTC [3898] discourse@discourse LOG:  duration: 34268.080 ms  execute <unnamed>: SELECT "post_custom_fields"."name", "post_custom_fields"."value" FROM "post_custom_fields" WHERE "post_custom_fields"."post_id" = 20 ORDER BY id asc
2020-12-07 11:44:54.399 UTC [3898] discourse@discourse LOG:  duration: 15760.378 ms  execute <unnamed>: SELECT "post_custom_fields"."name", "post_custom_fields"."value" FROM "post_custom_fields" WHERE "post_custom_fields"."post_id" = 20 ORDER BY id asc
2020-12-07 11:45:56.976 UTC [3898] discourse@discourse LOG:  duration: 58722.471 ms  execute <unnamed>: SELECT "post_custom_fields"."name", "post_custom_fields"."value" FROM "post_custom_fields" WHERE "post_custom_fields"."post_id" = 20 ORDER BY id asc
2020-12-07 11:46:46.091 UTC [3898] discourse@discourse LOG:  duration: 48556.685 ms  execute <unnamed>: SELECT "post_custom_fields"."name", "post_custom_fields"."value" FROM "post_custom_fields" WHERE "post_custom_fields"."post_id" = 20 ORDER BY id asc
2020-12-07 11:47:09.536 UTC [3898] discourse@discourse LOG:  duration: 23130.829 ms  execute <unnamed>: SELECT "post_custom_fields"."name", "post_custom_fields"."value" FROM "post_custom_fields" WHERE "post_custom_fields"."post_id" = 20 ORDER BY id asc
2020-12-07 11:47:33.762 UTC [3898] discourse@discourse LOG:  duration: 23694.256 ms  execute <unnamed>: SELECT "post_custom_fields"."name", "post_custom_fields"."value" FROM "post_custom_fields" WHERE "post_custom_fields"."post_id" = 20 ORDER BY id asc
2020-12-07 11:48:09.190 UTC [3898] discourse@discourse LOG:  duration: 34922.442 ms  execute <unnamed>: SELECT "post_custom_fields"."name", "post_custom_fields"."value" FROM "post_custom_fields" WHERE "post_custom_fields"."post_id" = 20 ORDER BY id asc
2020-12-07 11:48:09.539 UTC [3898] discourse@discourse LOG:  duration: 127.286 ms  parse <unnamed>: SELECT "calendar_events".* FROM "calendar_events" WHERE "calendar_events"."post_id" = 478
2020-12-07 11:49:05.314 UTC [3898] discourse@discourse LOG:  duration: 55677.361 ms  execute <unnamed>: SELECT "post_custom_fields"."name", "post_custom_fields"."value" FROM "post_custom_fields" WHERE "post_custom_fields"."post_id" = 20 ORDER BY id asc
2020-12-07 11:49:07.150 UTC [3898] discourse@discourse LOG:  duration: 1647.675 ms  execute <unnamed>: SELECT "post_custom_fields"."name", "post_custom_fields"."value" FROM "post_custom_fields" WHERE "post_custom_fields"."post_id" = 20 ORDER BY id asc
2020-12-07 11:49:19.072 UTC [3898] discourse@discourse LOG:  duration: 11720.259 ms  execute <unnamed>: SELECT "post_custom_fields"."name", "post_custom_fields"."value" FROM "post_custom_fields" WHERE "post_custom_fields"."post_id" = 20 ORDER BY id asc
2020-12-07 11:49:31.135 UTC [3898] discourse@discourse LOG:  duration: 11582.021 ms  execute <unnamed>: SELECT "post_custom_fields"."name", "post_custom_fields"."value" FROM "post_custom_fields" WHERE "post_custom_fields"."post_id" = 20 ORDER BY id asc
2020-12-07 11:49:44.365 UTC [3898] discourse@discourse LOG:  duration: 12831.278 ms  execute <unnamed>: SELECT "post_custom_fields"."name", "post_custom_fields"."value" FROM "post_custom_fields" WHERE "post_custom_fields"."post_id" = 20 ORDER BY id asc
2020-12-07 11:51:41.565 UTC [3898] discourse@discourse LOG:  duration: 116599.870 ms  execute <unnamed>: SELECT "post_custom_fields"."name", "post_custom_fields"."value" FROM "post_custom_fields" WHERE "post_custom_fields"."post_id" = 20 ORDER BY id asc
2020-12-07 11:52:22.060 UTC [3898] discourse@discourse LOG:  duration: 39664.789 ms  execute <unnamed>: SELECT "post_custom_fields"."name", "post_custom_fields"."value" FROM "post_custom_fields" WHERE "post_custom_fields"."post_id" = 20 ORDER BY id asc
2020-12-07 11:52:56.540 UTC [3898] discourse@discourse LOG:  duration: 33136.236 ms  execute <unnamed>: SELECT "post_custom_fields"."name", "post_custom_fields"."value" FROM "post_custom_fields" WHERE "post_custom_fields"."post_id" = 20 ORDER BY id asc
2020-12-07 11:52:57.214 UTC [3898] discourse@discourse LOG:  duration: 139.491 ms  parse <unnamed>: SELECT "calendar_events".* FROM "calendar_events" WHERE "calendar_events"."post_id" = 487
2020-12-07 11:52:57.472 UTC [3898] discourse@discourse LOG:  duration: 258.338 ms  bind <unnamed>: SELECT "calendar_events".* FROM "calendar_events" WHERE "calendar_events"."post_id" = 487
2020-12-07 11:53:08.567 UTC [3898] discourse@discourse LOG:  duration: 10615.113 ms  execute <unnamed>: SELECT "post_custom_fields"."name", "post_custom_fields"."value" FROM "post_custom_fields" WHERE "post_custom_fields"."post_id" = 20 ORDER BY id asc
2020-12-07 11:53:13.908 UTC [3898] discourse@discourse LOG:  duration: 1035.837 ms  parse <unnamed>: SELECT "calendar_events".* FROM "calendar_events" WHERE "calendar_events"."post_id" = 488
2020-12-07 11:53:14.443 UTC [3898] discourse@discourse LOG:  duration: 475.898 ms  bind <unnamed>: SELECT "calendar_events".* FROM "calendar_events" WHERE "calendar_events"."post_id" = 488
2020-12-07 11:53:21.659 UTC [3898] discourse@discourse LOG:  could not send data to client: Broken pipe
2020-12-07 11:53:21.659 UTC [3898] discourse@discourse STATEMENT:  SELECT "post_custom_fields"."name", "post_custom_fields"."value" FROM "post_custom_fields" WHERE "post_custom_fields"."post_id" = 20 ORDER BY id asc
2020-12-07 11:53:21.734 UTC [3898] discourse@discourse FATAL:  connection to client lost
2020-12-07 11:53:21.734 UTC [3898] discourse@discourse STATEMENT:  SELECT "post_custom_fields"."name", "post_custom_fields"."value" FROM "post_custom_fields" WHERE "post_custom_fields"."post_id" = 20 ORDER BY id asc
Killed
I, [2020-12-07T11:53:30.522597 #1]  INFO -- :
I, [2020-12-07T11:53:35.390781 #1]  INFO -- : Terminating async processes
I, [2020-12-07T11:53:35.815966 #1]  INFO -- : Sending INT to HOME=/var/lib/postgresql USER=postgres exec chpst -u postgres:postgres:ssl-cert -U postgres:postgres:ssl-cert /usr/lib/postgresql/12/bin/postmaster -D /etc/postgresql/12/main pid: 50
2020-12-07 11:53:36.108 UTC [50] LOG:  received fast shutdown request
I, [2020-12-07T11:53:36.185340 #1]  INFO -- : Sending TERM to exec chpst -u redis -U redis /usr/bin/redis-server /etc/redis/redis.conf pid: 167
167:signal-handler (1607342016) Received SIGTERM scheduling shutdown...
167:M 07 Dec 2020 11:53:36.211 # User requested shutdown...
167:M 07 Dec 2020 11:53:36.211 * Saving the final RDB snapshot before exiting.
2020-12-07 11:53:36.626 UTC [50] LOG:  aborting any active transactions
2020-12-07 11:53:37.025 UTC [50] LOG:  background worker "logical replication launcher" (PID 59) exited with exit code 1
2020-12-07 11:53:37.616 UTC [54] LOG:  shutting down
167:M 07 Dec 2020 11:53:38.311 * DB saved on disk
167:M 07 Dec 2020 11:53:38.312 # Redis is now ready to exit, bye bye...
2020-12-07 11:53:40.331 UTC [50] LOG:  database system is shut down


FAILED
--------------------
Pups::ExecError: cd /var/www/discourse && su discourse -c 'bundle exec rake db:migrate' failed with return #<Process::Status: pid 3870 exit 137>
Location of failure: /pups/lib/pups/exec_command.rb:112:in `spawn'
exec failed with the params {"cd"=>"$home", "hook"=>"db_migrate", "cmd"=>["su discourse -c 'bundle exec rake db:migrate'"]}
a03fe2903df190bacab2f312cb2c8dca7707a9f5d9fcca0821ea5b7ce0e2d742
** FAILED TO BOOTSTRAP ** please scroll up and look for earlier error messages, there may be more than one.
./discourse-doctor may help diagnose the problem.

amotl · December 7, 2020, 12:26pm

Following Upgrade of postgres failed and PostgreSQL 12 update, we haven’t been able to identify anything particular which might help us here.

This installation isn’t particular large

root@pulp:/srv/www/organizations/panodata/community.panodata.org# du -sch .
661M	total

and trying to launch the application again in order

fails, as the Rails app can’t connect to PostgreSQL:

==> shared/standalone/log/rails/unicorn.stderr.log <==
I, [2020-12-07T12:20:58.960126 #459]  INFO -- : Refreshing Gem list
/var/www/discourse/vendor/bundle/ruby/2.6.0/gems/pg-1.1.4/lib/pg.rb:56:in `initialize': could not connect to server: No such file or directory (PG::ConnectionBad)
	Is the server running locally and accepting
	connections on Unix domain socket "/var/run/postgresql/.s.PGSQL.5432"?
	from /var/www/discourse/vendor/bundle/ruby/2.6.0/gems/pg-1.1.4/lib/pg.rb:56:in `new'
	from /var/www/discourse/vendor/bundle/ruby/2.6.0/gems/pg-1.1.4/lib/pg.rb:56:in `connect'

amotl · December 7, 2020, 12:32pm

tail -n100 -F shared/standalone/log/rails/production.log

reveals:

Creating scope :pending. Overwriting existing method DiscoursePostEvent::EventDate.pending.
Creating scope :open. Overwriting existing method Poll.open.
Migrating to AddSmtpAndImapToGroups (20181220115844)
Migrating to AddImapFieldsToIncomingEmails (20190111183409)
Migrating to AddSecureToUploads (20190716173854)
Migrating to RsvpMigration (20191016154136)
Migrating to AddLastSeenToCategoryUsers (20191107025041)
Migrating to AddIndexToLastSeenAtOnCategoryUsers (20191107025140)
Migrating to ChangeNotificationLevel (20191107032231)
Migrating to RemoveSuppressFromLatestFromCategory (20191107190330)
Migrating to AddTargetTagIdToTags (20191113193141)
Migrating to AddGraphToPolls (20191114160613)
Migrating to RenameSiteSettingAssignEmailer (20191119174425)
Migrating to AddTimezoneToUserOptions (20191120015344)
Migrating to AddUniqueIndexToDevelopers (20191128222140)
Migrating to DropUnusedGoogleInstagramAuthTables (20191129144706)
Migrating to AddFeaturedTopicIdToUserProfiles (20191202202212)
Migrating to CreateStandaloneBookmarksTable (20191205100434)
Migrating to AddGroupNameToPolls (20191206123012)
Migrating to EnsuresUniqueAcceptedAnswerPostId (20191209095548)
Migrating to AddIndexToInvites (20191211152404)
Migrating to AddHashedApiKey (20191211170000)
Migrating to PopulateTopicIdOnBookmarks (20191217035630)
Migrating to RemoveKeyFromApiKeys (20191219112000)
Migrating to AddDistinctBadgeCountToUserStats (20191220134101)
Migrating to AddAccessControlColumnsToUpload (20191230055237)
Migrating to AddFeaturedRankToUserBadges (20200107161405)
Migrating to UpdateUserProfilesIndexes (20200109130028)
Migrating to AddGroupToCustomEmojis (20200116092259)
Migrating to RenameReplyIdColumn (20200116140132)
Migrating to UpdatePostReplyIndexes (20200117141138)
Migrating to AddTriggerToSyncPostReplies (20200117172135)
Migrating to MakePostReplyIdColumnReadOnly (20200117174646)
Migrating to DropUnusedColumns (20200120131338)
Migrating to RemoveBounceScoreThresholdDeactivateSiteSetting (20200130115859)
Migrating to MarkBookmarksTopicIdNotNull (20200203061927)
Migrating to CreateCalendarEvents (20200226183018)

and (probably!) on the second attempt of invoking ./launcher rebuild community.panodata.org, it said:

Creating scope :pending. Overwriting existing method DiscoursePostEvent::EventDate.pending.
Creating scope :open. Overwriting existing method Poll.open.
Migrating to CreateCalendarEvents (20200226183018)

Falco · December 7, 2020, 12:34pm

I suggest removing the calendar plugin and trying again.

amotl · December 7, 2020, 12:35pm

On it, thanks! I’ve just deactivated both of these and rebuilding again.

#          - git clone https://github.com/discourse/discourse-calendar.git
#          - git clone https://github.com/angusmcleod/discourse-events.git

amotl · December 7, 2020, 1:09pm

Dear Rafael,

I can confirm the Discourse Calendar plugin indeed has been the culprit here, so I will adjust the title of this post accordingly. FWIW, I am also sharing our current plugin list. With these plugins installed (and discourse-calendar deactivated), the database migration task succeeded just fine and the forum is up and running again – https://community.panodata.org/.

  after_code:
    - exec:
        cd: $home/plugins
        cmd:
          - git clone https://github.com/discourse/docker_manager.git
          - git clone https://github.com/discourse/discourse-translator.git
          - git clone https://github.com/discourse/discourse-checklist.git
          - git clone https://github.com/discourse/discourse-assign.git
          - git clone https://github.com/discourse/discourse-solved.git
          - git clone https://github.com/discourse/discourse-math.git
          - git clone https://github.com/angusmcleod/discourse-tickets.git
          - git clone https://github.com/angusmcleod/discourse-knowledge-base.git
          - git clone https://github.com/angusmcleod/discourse-locations.git
          - git clone https://github.com/discourse/discourse-footnote.git
          - git clone https://github.com/discourse/discourse-graphviz.git
          - git clone https://github.com/angusmcleod/discourse-custom-wizard.git
          - git clone https://github.com/discourse/discourse-sitemap.git
          - git clone https://github.com/angusmcleod/discourse-events.git

#          - git clone https://github.com/discourse/discourse-calendar.git

Thank you so much, keep up the spirit and with kind regards,
Andreas.

P.S.: How should we proceed on filing a bug against discourse-calendar, if that might be appropriate?

Falco · December 7, 2020, 1:22pm

Now that you are migrated to PG12 proper, you can try re-adding the plugin to see if the migration will work.

amotl · December 7, 2020, 2:49pm

I already did so. However, the migration process is running into the same situation.

amotl:

2020-12-07 11:33:41.954 UTC [3898] discourse@discourse LOG:  duration: 232.874 ms  statement: CREATE TABLE "calendar_events" ("id" bigserial primary key, "topic_id" integer NOT NULL, "post_id" integer, "post_number" integer, "user_id" integer, "username" character varying, "description" character varying, "start_date" timestamp NOT NULL, "end_date" timestamp, "recurrence" character varying, "region" character varying, "created_at" timestamp NOT NULL, "updated_at" timestamp NOT NULL)
2020-12-07 11:33:42.693 UTC [3898] discourse@discourse LOG:  duration: 349.048 ms  execute <unnamed>: SELECT "post_custom_fields"."name", "post_custom_fields"."value" FROM "post_custom_fields" WHERE "post_custom_fields"."post_id" = 20 ORDER BY id asc

Do you believe it has something to do with specific data in our instance within both the calendar_events and the post_custom_fields table?

Apparently, the process seems to get stuck at post_id = 20. So, I went ahead trying this:

./launcher enter community.panodata.org
rails console
DB.query('SELECT "post_custom_fields"."name", "post_custom_fields"."value" FROM "post_custom_fields" WHERE "post_custom_fields"."post_id" = 20 ORDER BY id asc')

After that, the system starts getting completely unresponsive and the system load goes through the roof.

`top`

top - 15:28:06 up 158 days, 14:05,  5 users,  load average: 19.28, 12.96, 5.94
Tasks: 289 total,   1 running, 288 sleeping,   0 stopped,   0 zombie
%Cpu(s):  2.3 us,  6.1 sy,  0.3 ni,  1.2 id, 90.0 wa,  0.0 hi,  0.0 si,  0.0 st
MiB Mem :   7006.9 total,     40.1 free,   6177.4 used,    789.4 buff/cache
MiB Swap:   4096.0 total,   2048.4 free,   2047.6 used.    659.2 avail Mem

  PID USER      PR  NI    VIRT    RES    SHR S  %CPU  %MEM     TIME+ COMMAND
12470 xxx       25   5 9229456  89424   4604 S 117.4   1.2   0:35.66 ruby
   43 root      20   0       0      0      0 D   1.0   0.0  11:46.02 kswapd0
10035 xxx       20   0 7481716   4.2g   6020 D   1.0  61.3   0:12.60 bundle

`iotop`

Total DISK READ:      1373.05 K/s | Total DISK WRITE:        29.79 K/s
Current DISK READ:    1373.05 K/s | Current DISK WRITE:       3.17 M/s
  TID  PRIO  USER     DISK READ  DISK WRITE  SWAPIN     IO>    COMMAND
27667 be/4 root        0.00 B/s    0.00 B/s  0.00 % 99.99 % sshd -D
10035 be/4 xxx         0.00 B/s    0.00 B/s  0.00 % 99.99 % pry
 4863 be/4 xxx         0.00 B/s    0.00 B/s  0.00 % 99.99 % bash config/unicorn_launcher -E production -c config/unicorn.conf.rb
11145 be/4 xxx         0.00 B/s    0.00 B/s  0.00 % 99.99 % unicorn worker[0] -E production -c config/unicorn.conf.rb
11363 be/4 xxx         0.00 B/s    0.00 B/s  0.00 % 99.99 % sleep 1
11362 be/4 xxx         0.00 B/s    0.00 B/s  0.00 % 99.99 % sleep 1
   43 be/4 root        0.00 B/s    0.00 B/s  0.00 % 99.99 % [kswapd0]
  344 be/4 root       49.66 K/s    0.00 B/s  0.00 % 61.49 % [xfsaild/xvda4]
13189 be/4 xxx         0.00 B/s    9.93 K/s  0.00 % 56.78 % postgres: 12/main: walwriter
13357 be/5 xxx         0.00 B/s    0.00 B/s  0.00 % 20.45 % sidekiq 6.1.2 discourse [0 of 5 busy] [mini_scheduler*]
 5497 be/5 xxx         4.97 K/s    0.00 B/s  2.82 %  0.00 % sidekiq 6.0.5 discourse [0 of 5 busy] [heartbeat]

Only after leaving

[3] pry(main)>

the system slowly recovers and things are starting to get responsive again. It looks like there is some serious resource thrashing going on.

DB.query_single('SELECT count(*) FROM "post_custom_fields"')
=> [2002]

DB.query_single('SELECT count(*) FROM "post_custom_fields" WHERE post_id=20')
=> [2]

DB.query_single('SELECT name FROM "post_custom_fields" WHERE post_id=20')
=> ["calendar-details", "post_detected_lang"]

However, as soon as I select the value column, all things go south.

amotl · December 7, 2020, 2:49pm

Ha. Is this sane?

DB.query_single('SELECT name, length(value) FROM "post_custom_fields" WHERE post_id=20')
=> ["calendar-details", 83361791, "post_detected_lang", 2]

So, the value column of this specific calendar-details item contains ~80MB worth of data. I believe we are on to something here.

Apparently, this is the only item carrying such a large payload within its calendar-details value.

print(DB.query("SELECT post_id, length(value) FROM post_custom_fields WHERE name='calendar-details' ORDER BY post_id").map { |r| r.post_id.to_s + ": " + r.length.to_s }.join("\n"))
20: 83361791
84: 113
133: 113
177: 58
223: 2
263: 113
379: 112
385: 130
439: 112
456: 112
457: 58
495: 117
552: 2

amotl · December 7, 2020, 3:10pm

I am making progress on narrowing this down.

DB.query("SELECT topic_id, cooked FROM posts WHERE id=20")
=> [#<#<Class:0x0000560b91760168>:0x0000560b8b841880
  @cooked=
   "<p>If you are interested in the activities on the <a href=\"https://github.com/panodata\" rel=\"nofollow noopener\">Panodata GitHub</a> repositories, please track this thread.</p>\n<p>We are feeding push notifications from GitHub into Discourse by using the fine <a href=\"https://github.com/huw/github-to-discourse\" class=\"inline-onebox\" rel=\"nofollow noopener\">GitHub - huw/github-to-discourse: Forwards commit data from a GitHub webhook to a Discourse thread</a>.</p>",
  @topic_id=16>]

So, it looks like it is the very first post on the topic Logbook of code changes - The workbench - Panodata Community. As far as I can trust my own sanity, I never assigned this post anything related to a calendar entry.

Actually, it is a topic where automatic posts are made to, using https://github.com/huw/github-to-discourse. However, the first post (id=20) was created manually.

Falco · December 7, 2020, 3:42pm

Well, so that means it has nothing to do with the PG12 update, so not my fault

Yeah, as we said several times using either plugin store or post_custom_fields for stuff that is complex is not sustainable long term. That is why calendar is doing this migration to move to proper tables.

Unfortunately looks like it didn’t come early enough for you and a event got in a bad state. Delete the problematic row and stuff should work again.

amotl · December 7, 2020, 3:46pm

Definitively not! I’ve already amended the topic title in order to reflect the current outcome. Thanks a stack for your help and feedback on this.

I see. Thanks again for your insights.

All right, will do. So, I believe there is no reason to investigate further about the root cause as you already have been aware of it and improved the situation by amending the database schema accordingly through the migration you referenced here. Thank you!

amotl · December 7, 2020, 4:01pm

Hi again,

[70] pry(main)> DB.query("DELETE FROM post_custom_fields WHERE post_id=20 AND name='calendar-details'")
=> []

After deleting the offending row, we activated discourse-calendar again. Followed up by another rebuild, we can report the missing migrations have been applied successfully

20200226183018 CreateCalendarEvents: migrated (0.8584s)
20200409102640 CreatePostEventsTable: migrated (0.0381s)
20200409102643 RenameTablesToDiscoursePostEvent: migrated (0.1840s)
20201110225115 CreatePostEventDatesTable: migrated (0.0655s)
20201111005205 MoveDataToEventDates: migrated (0.0039s)

and everything is fine again.

Thank you very much for the excellent work you are doing here.

With kind regards,
Andreas.

Topic		Replies	Views
Upgrade failed with "duplicate key value violates unique constraint" error installation	18	2180	March 30, 2020
Discourse update doesn't wait for Postgress DB to shut down installation	5	789	January 28, 2022
Building bootstrap error installation	46	1410	December 20, 2022
Recurrent automatic SQL backup causes slowness support	15	684	February 18, 2019
Discourse bundle exec rake multisite:migrate failed bug	5	1300	March 12, 2021

Database migration chokes on huge value of a "calendar-details" item in table "post_custom_fields"

TLDR;

top

iotop

Related Topics

`top`

`iotop`