Re: 2 new contributions to pgdg

Dear Christoph,

Regarding the first test failure, it is very interesting.  I am still seeing the test result differently than you (as well as another co-worker) on both 11.0 and 11.1.  I see this same result on all of my local 9.5-10 installs as well.

The test is trying to launch a background worker on an invalid database OID.  I found that the behavior of that changed on my own machine when I moved from debian wheezy to ubuntu xenial, when I also upgraded point release versions.  In your environment, it looks like you are seeing the behavior that I used to see.  Here was that post (which received no replies): https://www.postgresql.org/message-id/CAMa1XUi0g7KRbzcxPwNvBfGU2vh9A9jwHZ4EWTmaJzLrOhHA2Q@mail.gmail.com

I changed that test because it used to do what you are showing - it would show an actual pid.  But this is what happens in my environment:

ERROR:  could not start background process

HINT:  More details may be available in the server log.

Do you have any idea how this could happen?  I'm a bit at a loss.

I may ping hackers again to see if anyone has ideas.

Thanks,
Jeremy

On Fri, Nov 9, 2018 at 3:57 PM Christoph Berg <myon@debian.org> wrote:

Re: Jeremy Finzel 2018-11-09 <CAMa1XUhLN8Ur-Fgded0NLiopRrqnwn_vA5Sd-SUqbixTQrr7qg@mail.gmail.com>
> Dear Christoph,
>
> I have 2 new packages I would like to contribute to pgdg:

Cool :)

> pglogical_ticker: https://github.com/enova/pglogical_ticker (Time-based
> replication delay for pglogical)

The package looks mostly fine, but it fails the regression tests:

Ver Cluster Port Status Owner    Data directory                            Log file
11  regress 5433 online postgres /tmp/pg_virtualenv.pURpIq/data/11/regress /tmp/pg_virtualenv.pURpIq/log/postgresql-11-regress.log

/usr/lib/postgresql/11/lib/pgxs/src/makefiles/../../src/test/regress/pg_regress --inputdir=./ --bindir='/usr/lib/postgresql/11/bin'    --dbname=contrib_regression 01_create_ext 02_setup 03_deploy 04_add_to_rep 05_tick 06_worker 07_handlers 08_reentrance 09_1_2_tests 99_cleanup
(using postmaster on localhost, port 5433)
============== dropping database "contrib_regression" ==============
NOTICE:  database "contrib_regression" does not exist, skipping
DROP DATABASE
============== creating database "contrib_regression" ==============
CREATE DATABASE
ALTER DATABASE
============== running regression test queries        ==============
test 01_create_ext                ... ok
test 02_setup                     ... ok
test 03_deploy                    ... ok
test 04_add_to_rep                ... ok
test 05_tick                      ... ok
test 06_worker                    ... ok
test 07_handlers                  ... FAILED
test 08_reentrance                ... ok
test 09_1_2_tests                 ... FAILED
test 99_cleanup                   ... ok

=======================
 2 of 10 tests failed.
=======================

The differences that caused some tests to fail can be viewed in the
file "/tmp/autopkgtest.qWZgMz/tree/regression.diffs".  A copy of the test summary that you see
above is saved in the file "/tmp/autopkgtest.qWZgMz/tree/regression.out".

make: *** [/usr/lib/postgresql/11/lib/pgxs/src/makefiles/pgxs.mk:396: installcheck] Error 1
*** /tmp/pg_virtualenv.pURpIq/log/postgresql-11-regress.log (last 100 lines) ***
2018-11-09 22:44:53.961 CET [17933] LOG:  listening on IPv6 address "::1", port 5433
2018-11-09 22:44:53.961 CET [17933] LOG:  listening on IPv4 address "127.0.0.1", port 5433
2018-11-09 22:44:53.961 CET [17933] LOG:  listening on Unix socket "/var/run/postgresql/.s.PGSQL.5433"
2018-11-09 22:44:53.968 CET [17934] LOG:  database system was shut down at 2018-11-09 22:44:53 CET
2018-11-09 22:44:53.971 CET [17933] LOG:  database system is ready to accept connections
2018-11-09 22:44:53.971 CET [17940] LOG:  starting pglogical supervisor
2018-11-09 22:44:53.976 CET [17942] [unknown]@postgres LOG:  manager worker [17942] at slot 0 generation 1 detaching cleanly
2018-11-09 22:44:53.982 CET [17943] [unknown]@template1 LOG:  manager worker [17943] at slot 0 generation 2 detaching cleanly
2018-11-09 22:44:54.552 CET [17945] [unknown]@[unknown] LOG:  incomplete startup packet
2018-11-09 22:44:56.563 CET [17989] [unknown]@postgres LOG:  manager worker [17989] at slot 0 generation 3 detaching cleanly
2018-11-09 22:44:56.567 CET [17990] [unknown]@contrib_regression LOG:  starting pglogical database manager for database contrib_regression
2018-11-09 22:44:56.699 CET [18007] LOG:  pglogical_ticker worker initialized
2018-11-09 22:44:57.569 CET [18009] [unknown]@template1 LOG:  manager worker [18009] at slot 1 generation 1 detaching cleanly
2018-11-09 22:45:09.725 CET [18007] ERROR:  canceling statement due to user request
2018-11-09 22:45:09.727 CET [17933] LOG:  background worker "pglogical_ticker" (PID 18007) exited with exit code 1
2018-11-09 22:45:09.732 CET [18017] LOG:  pglogical_ticker worker initialized
2018-11-09 22:45:11.734 CET [18017] ERROR:  canceling statement due to user request
2018-11-09 22:45:11.736 CET [17933] LOG:  background worker "pglogical_ticker" (PID 18017) exited with exit code 1
2018-11-09 22:45:11.760 CET [18022] FATAL:  database 9999999 does not exist
2018-11-09 22:45:11.761 CET [17933] LOG:  background worker "pglogical_ticker" (PID 18022) exited with exit code 1
2018-11-09 22:45:11.764 CET [18023] LOG:  pglogical_ticker worker initialized
2018-11-09 22:45:11.767 CET [18024] LOG:  pglogical_ticker worker initialized
2018-11-09 22:45:12.769 CET [18024] ERROR:  canceling statement due to user request
2018-11-09 22:45:12.769 CET [18023] ERROR:  canceling statement due to user request
2018-11-09 22:45:12.771 CET [17933] LOG:  background worker "pglogical_ticker" (PID 18023) exited with exit code 1
2018-11-09 22:45:12.771 CET [17933] LOG:  background worker "pglogical_ticker" (PID 18024) exited with exit code 1
2018-11-09 22:45:13.853 CET [18035] postgres@contrib_regression ERROR:  cannot drop table pglogical_ticker.test1 because extension pglogical_ticker requires it
2018-11-09 22:45:13.853 CET [18035] postgres@contrib_regression HINT:  You can drop extension pglogical_ticker instead.
2018-11-09 22:45:13.853 CET [18035] postgres@contrib_regression STATEMENT:  DROP TABLE pglogical_ticker.test1;
2018-11-09 22:45:13.893 CET [17990] [unknown]@contrib_regression LOG:  manager worker [17990] at slot 0 generation 4 detaching cleanly
Dropping cluster 11/regress ...
**** regression.diffs ****
*** /tmp/autopkgtest.qWZgMz/tree/expected/07_handlers.out       2018-11-09 22:42:25.902459886 +0100
--- /tmp/autopkgtest.qWZgMz/tree/results/07_handlers.out        2018-11-09 22:45:13.771207281 +0100
***************
*** 2,16 ****
  --The _launch function is not supposed to be used directly
  --This tests that stupid things don't do something really bad
  SELECT pglogical_ticker._launch(9999999::OID) AS pid;
! ERROR:  could not start background process
! HINT:  More details may be available in the server log.
  --Verify that it exits cleanly if the SQL within the worker errors out
  --In this case, renaming the function will do it
  ALTER FUNCTION pglogical_ticker.tick() RENAME TO tick_oops;
  SELECT pglogical_ticker.launch();
! ERROR:  could not start background process
! HINT:  More details may be available in the server log.
! CONTEXT:  SQL function "launch" statement 1
  ALTER FUNCTION pglogical_ticker.tick_oops() RENAME TO tick;
  --Verify we can't start multiple workers - the second attempt should return NULL
  --We know this is imperfect but so long as pglogical_ticker.launch is not executed
--- 2,21 ----
  --The _launch function is not supposed to be used directly
  --This tests that stupid things don't do something really bad
  SELECT pglogical_ticker._launch(9999999::OID) AS pid;
!   pid
! -------
!  18022
! (1 row)
!
  --Verify that it exits cleanly if the SQL within the worker errors out
  --In this case, renaming the function will do it
  ALTER FUNCTION pglogical_ticker.tick() RENAME TO tick_oops;
  SELECT pglogical_ticker.launch();
!  launch
! --------
!   18023
! (1 row)
!
  ALTER FUNCTION pglogical_ticker.tick_oops() RENAME TO tick;
  --Verify we can't start multiple workers - the second attempt should return NULL
  --We know this is imperfect but so long as pglogical_ticker.launch is not executed
***************
*** 43,49 ****
   pg_cancel_backend
  -------------------
   t
! (1 row)

  SELECT pg_sleep(1);
   pg_sleep
--- 48,55 ----
   pg_cancel_backend
  -------------------
   t
!  t
! (2 rows)

  SELECT pg_sleep(1);
   pg_sleep

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

*** /tmp/autopkgtest.qWZgMz/tree/expected/09_1_2_tests.out      2018-11-09 22:42:25.902459886 +0100
--- /tmp/autopkgtest.qWZgMz/tree/results/09_1_2_tests.out       2018-11-09 22:45:13.851207793 +0100
***************
*** 98,105 ****
  ORDER BY set_name, set_reloid::TEXT;
   set_name |              set_reloid
  ----------+--------------------------------------
-  test1    | pglogical_ticker.ddl_sql
   test1    | pglogical_ticker."default"
   test1    | pglogical_ticker.default_insert_only
   test1    | pglogical_ticker.test1
   test1    | pglogical_ticker.test10
--- 98,105 ----
  ORDER BY set_name, set_reloid::TEXT;
   set_name |              set_reloid
  ----------+--------------------------------------
   test1    | pglogical_ticker."default"
+  test1    | pglogical_ticker.ddl_sql
   test1    | pglogical_ticker.default_insert_only
   test1    | pglogical_ticker.test1
   test1    | pglogical_ticker.test10

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

autopkgtest [22:45:14]: test installcheck: -----------------------]
autopkgtest [22:45:14]: test installcheck:  - - - - - - - - - - results - - - - - - - - - -
installcheck         FAIL non-zero exit status 1


One minor thing: remove debian/files from git, it's a temporary file
during build.

> pg_fact_loader: https://github.com/enova/pg_fact_loader (Build fact tables
> asynchronously with Postgres)

(Will try that later.)

> pg_fact_loader does not explicitly depend on pglogical_ticker (it can be
> used with or without), however, some of the test suite does depend on it.
> I'm not sure exactly how that needs to be configured but wanted to point it
> out.

You can add test dependencies in debian/tests/control:

Depends: @, postgresql-server-dev-all
Tests: installcheck
Restrictions: allow-stderr

For dependencies depending on the PG version, use
debian/tests/control.in:

Depends: @, postgresql-server-dev-all, postgresql-PGVERSION-pglogical-ticker
Tests: installcheck
Restrictions: allow-stderr

> Please let us know if there's anything else you need, and I appreciate your
> help with these!

There are no releases on Github yet, so the debian/watch files can't
find the tarballs.

Christoph