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(at)debian(dot)org> wrote:

> Re: Jeremy Finzel 2018-11-09 <
> CAMa1XUhLN8Ur-Fgded0NLiopRrqnwn_vA5Sd-SUqbixTQrr7qg(at)mail(dot)gmail(dot)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](at)postgres LOG: manager
> worker [17942] at slot 0 generation 1 detaching cleanly
> 2018-11-09 22:44:53.982 CET [17943] [unknown](at)template1 LOG: manager
> worker [17943] at slot 0 generation 2 detaching cleanly
> 2018-11-09 22:44:54.552 CET [17945] [unknown](at)[unknown] LOG: incomplete
> startup packet
> 2018-11-09 22:44:56.563 CET [17989] [unknown](at)postgres LOG: manager
> worker [17989] at slot 0 generation 3 detaching cleanly
> 2018-11-09 22:44:56.567 CET [17990] [unknown](at)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](at)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(at)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(at)contrib_regression HINT:
> You can drop extension pglogical_ticker instead.
> 2018-11-09 22:45:13.853 CET [18035] postgres(at)contrib_regression
> STATEMENT: DROP TABLE pglogical_ticker.test1;
> 2018-11-09 22:45:13.893 CET [17990] [unknown](at)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
>