Обсуждение: 2 new contributions to pgdg
Dear Christoph,
I have 2 new packages I would like to contribute to pgdg:
pglogical_ticker: https://github.com/enova/pglogical_ticker (Time-based replication delay for pglogical)
pg_fact_loader: https://github.com/enova/pg_fact_loader (Build fact tables asynchronously with Postgres)
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.
Both of these build fine with pg_buildext/debuild. You will see the debian directory which should meet all requirements.
Please let us know if there's anything else you need, and I appreciate your help with these!
Thanks,
Jeremy
Jeremy
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_tick06_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 becauseextension 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 detachingcleanly 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
Dear Christoph,
Thanks,
Jeremy
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
Dear Christoph,
I have just pushed up commits to fix the regression tests. Please let me know if it passes, and I will cut releases.
Thank you!
Jeremy
On Fri, Nov 9, 2018 at 5:22 PM Jeremy Finzel <finzelj@gmail.com> wrote:
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.comI 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 processHINT: 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,
JeremyOn 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
Hello again -
I have just tagged releases:
v1.3.0 pglogical_ticker
v1.5.0 pg_fact_loader
Hoping everything checks out. Let me know if anything is amiss.
Thanks,
Jeremy
Jeremy
On Tue, Nov 13, 2018 at 3:55 PM Jeremy Finzel <finzelj@gmail.com> wrote:
Dear Christoph,I have just pushed up commits to fix the regression tests. Please let me know if it passes, and I will cut releases.Thank you!JeremyOn Fri, Nov 9, 2018 at 5:22 PM Jeremy Finzel <finzelj@gmail.com> wrote: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.comI 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 processHINT: 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,
JeremyOn 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
Dear Christoph,
Just checking in if you could let me know this week the status of either of the below packages.
Just checking in if you could let me know this week the status of either of the below packages.
Thank you!
Jeremy
On Wed, Nov 14, 2018 at 10:23 AM Jeremy Finzel <finzelj@gmail.com> wrote:
Hello again -I have just tagged releases:v1.3.0 pglogical_tickerv1.5.0 pg_fact_loaderHoping everything checks out. Let me know if anything is amiss.Thanks,
JeremyOn Tue, Nov 13, 2018 at 3:55 PM Jeremy Finzel <finzelj@gmail.com> wrote:Dear Christoph,I have just pushed up commits to fix the regression tests. Please let me know if it passes, and I will cut releases.Thank you!JeremyOn Fri, Nov 9, 2018 at 5:22 PM Jeremy Finzel <finzelj@gmail.com> wrote: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.comI 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 processHINT: 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,
JeremyOn 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
Hi Jeremy,
The past week was pretty stressful for me, so your packages simply dropped off the table. Will have a look tomorrow. Sorry for not being more responsive here.
Christoph
The past week was pretty stressful for me, so your packages simply dropped off the table. Will have a look tomorrow. Sorry for not being more responsive here.
Christoph
Dear Christoph,
You have been very responsive; I was just checking in. I really appreciate your time. If it helps, I don't really need the packages until Dec 3rd at my hopeful latest.
Thank you!
Jeremy
On Tue, Nov 20, 2018 at 10:44 AM Christoph Berg <cb@df7cb.de> wrote:
Hi Jeremy,
The past week was pretty stressful for me, so your packages simply dropped off the table. Will have a look tomorrow. Sorry for not being more responsive here.
Christoph
Re: Jeremy Finzel 2018-11-14 <CAMa1XUiwpTZxZpywXJk8ueCiNhgT+2ARMGwu_HcEaRTKG+6uVQ@mail.gmail.com> > Hello again - > > I have just tagged releases: > v1.3.0 pglogical_ticker So here's the promised update. pglogical_ticker is basically fine, but the regression tests seem flaky. Re-running fixed the problems, so I put the package live now. Two builds were failing (each with 6 PG versions, testing stops on the first problem): https://pgdgbuild.dus.dg-i.net/job/pglogical-ticker-binaries/1/architecture=i386,distribution=stretch/console 10:39:54 /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_tick06_worker 07_handlers 08_reentrance 09_1_2_tests 99_cleanup 10:39:54 (using postmaster on localhost, port 5432) 10:39:54 ============== dropping database "contrib_regression" ============== 10:39:54 NOTICE: database "contrib_regression" does not exist, skipping 10:39:54 DROP DATABASE 10:39:54 ============== creating database "contrib_regression" ============== 10:39:54 CREATE DATABASE 10:39:54 ALTER DATABASE 10:39:54 ============== running regression test queries ============== 10:39:54 test 01_create_ext ... ok 10:39:55 test 02_setup ... ok 10:39:55 test 03_deploy ... ok 10:39:55 test 04_add_to_rep ... ok 10:39:55 test 05_tick ... ok 10:40:10 test 06_worker ... ok 10:40:12 test 07_handlers ... FAILED 10:40:12 test 08_reentrance ... ok 10:40:12 test 09_1_2_tests ... ok 10:40:12 test 99_cleanup ... ok 10:40:12 10:40:12 ======================= 10:40:12 1 of 10 tests failed. 10:40:12 ======================= 10:40:12 10:40:12 The differences that caused some tests to fail can be viewed in the 10:40:12 file "/tmp/autopkgtest.SdZHJC/tree/regression.diffs". A copy of the test summary that you see 10:40:12 above is saved in the file "/tmp/autopkgtest.SdZHJC/tree/regression.out". 10:40:12 10:40:12 make: *** [installcheck] Error 1 10:40:12 /usr/lib/postgresql/11/lib/pgxs/src/makefiles/pgxs.mk:396: recipe for target 'installcheck' failed 10:40:12 *** /tmp/pg_virtualenv.I2s8KW/log/postgresql-11-regress.log (last 100 lines) *** 10:40:12 2018-11-21 09:39:52.574 UTC [6361] LOG: listening on IPv6 address "::1", port 5432 10:40:12 2018-11-21 09:39:52.574 UTC [6361] LOG: listening on IPv4 address "127.0.0.1", port 5432 10:40:12 2018-11-21 09:39:52.574 UTC [6361] LOG: listening on Unix socket "/var/run/postgresql/.s.PGSQL.5432" 10:40:12 2018-11-21 09:39:52.586 UTC [6362] LOG: database system was shut down at 2018-11-21 09:39:52 UTC 10:40:12 2018-11-21 09:39:52.590 UTC [6361] LOG: database system is ready to accept connections 10:40:12 2018-11-21 09:39:52.590 UTC [6368] LOG: starting pglogical supervisor 10:40:12 2018-11-21 09:39:52.596 UTC [6370] [unknown]@postgres LOG: manager worker [6370] at slot 0 generation 1 detachingcleanly 10:40:12 2018-11-21 09:39:52.603 UTC [6371] [unknown]@template1 LOG: manager worker [6371] at slot 0 generation 2 detachingcleanly 10:40:12 2018-11-21 09:39:53.164 UTC [6372] [unknown]@[unknown] LOG: incomplete startup packet 10:40:12 2018-11-21 09:39:54.998 UTC [6416] [unknown]@postgres LOG: manager worker [6416] at slot 0 generation 3 detachingcleanly 10:40:12 2018-11-21 09:39:55.002 UTC [6418] [unknown]@contrib_regression LOG: starting pglogical database manager for databasecontrib_regression 10:40:12 2018-11-21 09:39:55.152 UTC [6434] LOG: pglogical_ticker worker initialized 10:40:12 2018-11-21 09:39:56.004 UTC [6435] [unknown]@template1 LOG: manager worker [6435] at slot 1 generation 1 detachingcleanly 10:40:12 2018-11-21 09:40:08.163 UTC [6434] ERROR: canceling statement due to user request 10:40:12 2018-11-21 09:40:08.166 UTC [6361] LOG: background worker "pglogical_ticker" (PID 6434) exited with exit code 1 10:40:12 2018-11-21 09:40:08.177 UTC [6436] LOG: pglogical_ticker worker initialized 10:40:12 2018-11-21 09:40:10.179 UTC [6436] ERROR: canceling statement due to user request 10:40:12 2018-11-21 09:40:10.181 UTC [6361] LOG: background worker "pglogical_ticker" (PID 6436) exited with exit code 1 10:40:12 2018-11-21 09:40:10.222 UTC [6441] FATAL: database 9999999 does not exist 10:40:12 2018-11-21 09:40:10.223 UTC [6442] LOG: pglogical_ticker worker initialized 10:40:12 2018-11-21 09:40:10.224 UTC [6361] LOG: background worker "pglogical_ticker" (PID 6441) exited with exit code 1 10:40:12 2018-11-21 09:40:11.227 UTC [6442] ERROR: canceling statement due to user request 10:40:12 2018-11-21 09:40:11.229 UTC [6361] LOG: background worker "pglogical_ticker" (PID 6442) exited with exit code 1 10:40:12 2018-11-21 09:40:12.360 UTC [6453] postgres@contrib_regression ERROR: cannot drop table pglogical_ticker.test1because extension pglogical_ticker requires it 10:40:12 2018-11-21 09:40:12.360 UTC [6453] postgres@contrib_regression HINT: You can drop extension pglogical_ticker instead. 10:40:12 2018-11-21 09:40:12.360 UTC [6453] postgres@contrib_regression STATEMENT: DROP TABLE pglogical_ticker.test1; 10:40:12 2018-11-21 09:40:12.434 UTC [6418] [unknown]@contrib_regression LOG: manager worker [6418] at slot 0 generation4 detaching cleanly 10:40:12 Dropping cluster 11/regress ... 10:40:12 **** regression.diffs **** 10:40:12 *** /tmp/autopkgtest.SdZHJC/tree/expected/07_handlers.out 2018-11-13 18:43:54.000000000 +0000 10:40:12 --- /tmp/autopkgtest.SdZHJC/tree/results/07_handlers.out 2018-11-21 09:40:12.228123205 +0000 10:40:12 *************** 10:40:12 *** 26,32 **** 10:40:12 SELECT pglogical_ticker.launch() IS NULL AS pid; 10:40:12 pid 10:40:12 ----- 10:40:12 ! f 10:40:12 (1 row) 10:40:12 10:40:12 SELECT pg_sleep(1); 10:40:12 --- 26,32 ---- 10:40:12 SELECT pglogical_ticker.launch() IS NULL AS pid; 10:40:12 pid 10:40:12 ----- 10:40:12 ! t 10:40:12 (1 row) 10:40:12 10:40:12 SELECT pg_sleep(1); 10:40:12 https://pgdgbuild.dus.dg-i.net/job/pglogical-ticker-binaries/1/architecture=ppc64el,distribution=xenial/console 10:41:00 /usr/lib/postgresql/9.5/lib/pgxs/src/makefiles/../../src/test/regress/pg_regress --inputdir=./ --bindir='/usr/lib/postgresql/9.5/bin' --dbname=contrib_regression 01_create_ext 02_setup 03_deploy 04_add_to_rep 05_tick06_worker 07_handlers 08_reentrance 09_1_2_tests 99_cleanup 10:41:00 (using postmaster on localhost, port 5432) 10:41:00 ============== dropping database "contrib_regression" ============== 10:41:00 NOTICE: database "contrib_regression" does not exist, skipping 10:41:00 DROP DATABASE 10:41:00 ============== creating database "contrib_regression" ============== 10:41:01 CREATE DATABASE 10:41:01 ALTER DATABASE 10:41:01 ============== running regression test queries ============== 10:41:01 test 01_create_ext ... ok 10:41:01 test 02_setup ... ok 10:41:01 test 03_deploy ... ok 10:41:01 test 04_add_to_rep ... ok 10:41:01 test 05_tick ... ok 10:41:16 test 06_worker ... FAILED 10:41:18 test 07_handlers ... ok 10:41:18 test 08_reentrance ... ok 10:41:18 test 09_1_2_tests ... ok 10:41:18 test 99_cleanup ... ok 10:41:18 10:41:18 ======================= 10:41:18 1 of 10 tests failed. 10:41:18 ======================= 10:41:18 10:41:18 The differences that caused some tests to fail can be viewed in the 10:41:18 file "/tmp/adt-run.Ctjy5G/tree/regression.diffs". A copy of the test summary that you see 10:41:18 above is saved in the file "/tmp/adt-run.Ctjy5G/tree/regression.out". 10:41:18 10:41:18 /usr/lib/postgresql/9.5/lib/pgxs/src/makefiles/pgxs.mk:274: recipe for target 'installcheck' failed 10:41:18 make: *** [installcheck] Error 1 10:41:18 *** /tmp/pg_virtualenv.AKgntO/log/postgresql-9.5-regress.log (last 100 lines) *** 10:41:18 2018-11-21 09:40:58.638 UTC [5679] LOG: database system was shut down at 2018-11-21 09:40:58 UTC 10:41:18 2018-11-21 09:40:58.639 UTC [5679] LOG: MultiXact member wraparound protections are now enabled 10:41:18 2018-11-21 09:40:58.645 UTC [5683] LOG: autovacuum launcher started 10:41:18 2018-11-21 09:40:58.647 UTC [5678] LOG: database system is ready to accept connections 10:41:18 2018-11-21 09:40:58.648 UTC [5685] LOG: starting pglogical supervisor 10:41:18 2018-11-21 09:40:58.656 UTC [5686] [unknown]@template1 LOG: manager worker [5686] at slot 0 generation 1 detachingcleanly 10:41:18 2018-11-21 09:40:59.122 UTC [5687] [unknown]@[unknown] LOG: incomplete startup packet 10:41:18 2018-11-21 09:40:59.653 UTC [5691] [unknown]@postgres LOG: manager worker [5691] at slot 0 generation 2 detachingcleanly 10:41:18 2018-11-21 09:41:01.367 UTC [5732] [unknown]@template1 LOG: manager worker [5732] at slot 0 generation 3 detachingcleanly 10:41:18 2018-11-21 09:41:01.614 UTC [5749] LOG: pglogical_ticker worker initialized 10:41:18 2018-11-21 09:41:02.380 UTC [5750] [unknown]@postgres LOG: manager worker [5750] at slot 0 generation 4 detachingcleanly 10:41:18 2018-11-21 09:41:03.373 UTC [5751] [unknown]@contrib_regression LOG: starting pglogical database manager for databasecontrib_regression 10:41:18 2018-11-21 09:41:14.635 UTC [5749] ERROR: canceling statement due to user request 10:41:18 2018-11-21 09:41:14.638 UTC [5678] LOG: worker process: pglogical_ticker worker (PID 5749) exited with exit code1 10:41:18 2018-11-21 09:41:16.700 UTC [5758] FATAL: database 9999999 does not exist 10:41:18 2018-11-21 09:41:16.703 UTC [5678] LOG: worker process: pglogical_ticker worker (PID 5758) exited with exit code1 10:41:18 2018-11-21 09:41:16.705 UTC [5759] LOG: pglogical_ticker worker initialized 10:41:18 2018-11-21 09:41:16.706 UTC [5760] LOG: pglogical_ticker worker initialized 10:41:18 2018-11-21 09:41:17.709 UTC [5759] ERROR: canceling statement due to user request 10:41:18 2018-11-21 09:41:17.709 UTC [5760] ERROR: canceling statement due to user request 10:41:18 2018-11-21 09:41:17.712 UTC [5678] LOG: worker process: pglogical_ticker worker (PID 5759) exited with exit code1 10:41:18 2018-11-21 09:41:17.712 UTC [5678] LOG: worker process: pglogical_ticker worker (PID 5760) exited with exit code1 10:41:18 2018-11-21 09:41:18.841 UTC [5769] postgres@contrib_regression ERROR: cannot drop table pglogical_ticker.test1because extension pglogical_ticker requires it 10:41:18 2018-11-21 09:41:18.841 UTC [5769] postgres@contrib_regression HINT: You can drop extension pglogical_ticker instead. 10:41:18 2018-11-21 09:41:18.841 UTC [5769] postgres@contrib_regression STATEMENT: DROP TABLE pglogical_ticker.test1; 10:41:18 Dropping cluster 9.5/regress ... 10:41:20 **** regression.diffs **** 10:41:20 *** /tmp/adt-run.Ctjy5G/tree/expected/06_worker.out 2018-11-13 18:43:54.000000000 +0000 10:41:20 --- /tmp/adt-run.Ctjy5G/tree/results/06_worker.out 2018-11-21 09:41:16.641272199 +0000 10:41:20 *************** 10:41:20 *** 47,60 **** 10:41:20 SELECT COUNT(1) FROM worker_pid WHERE pid IS NOT NULL; 10:41:20 count 10:41:20 ------- 10:41:20 ! 1 10:41:20 (1 row) 10:41:20 10:41:20 SELECT pg_cancel_backend(pid) 10:41:20 FROM worker_pid; 10:41:20 pg_cancel_backend 10:41:20 ------------------- 10:41:20 ! t 10:41:20 (1 row) 10:41:20 10:41:20 --Test it does nothing with no tables 10:41:20 --- 47,60 ---- 10:41:20 SELECT COUNT(1) FROM worker_pid WHERE pid IS NOT NULL; 10:41:20 count 10:41:20 ------- 10:41:20 ! 0 10:41:20 (1 row) 10:41:20 10:41:20 SELECT pg_cancel_backend(pid) 10:41:20 FROM worker_pid; 10:41:20 pg_cancel_backend 10:41:20 ------------------- 10:41:20 ! 10:41:20 (1 row) 10:41:20 10:41:20 --Test it does nothing with no tables 10:41:20 > v1.5.0 pg_fact_loader 07_launch_worker.out fails: 7 | 0001234567 | 35 | | 0 | 8 | 0001234568 | 35 | | 0 | 9 | 0001234569 | 35 | | 0 | ! 10 | 0001234577 | 35 | | 0 | (10 rows) UPDATE fact_loader.fact_tables SET force_worker_priority = FALSE WHERE fact_table_relid = 'test_fact.customers_fact'::REGCLASS; --- 35,41 ---- 7 | 0001234567 | 35 | | 0 | 8 | 0001234568 | 35 | | 0 | 9 | 0001234569 | 35 | | 0 | ! 10 | 0001234560 | 35 | | 0 | (10 rows) UPDATE fact_loader.fact_tables SET force_worker_priority = FALSE WHERE fact_table_relid = 'test_fact.customers_fact'::REGCLASS; The regression tests need the extension version adjusted: --- /tmp/autopkgtest.7mlirf/tree/results/17_1_3_features.out 2018-11-21 10:37:51.174647317 +0100 CREATE EXTENSION pg_fact_loader VERSION '1.2'; + ERROR: extension "pg_fact_loader" has no installation script nor update path for version "1.2" --- /tmp/autopkgtest.7mlirf/tree/results/18_alter_update_features.out CREATE EXTENSION pg_fact_loader VERSION '1.2'; + ERROR: extension "pg_fact_loader" has no installation script nor update path for version "1.2" That's on 11, the 9.5 log is worse: https://pgdgbuild.dus.dg-i.net/job/pg-fact-loader-binaries/2/architecture=amd64,distribution=sid/console Not sure how much of that is cause by hstore missing, you'll need to add postgresql-contrib-PGVERSION to debian/tests/control.in. (For PG10, -contrib is included in the main server package.) Christoph
Dear Christoph,
Thank you for the review and I'm sorry for this nuisance. I have tagged a new release version 1.5.1 which should fix this issue.
I missed this bug due to my own old extension files still existing and not removed via make uninstall because they had already been removed from my Makefile. I am hoping this should cover all the errors you had not only with 11 but with 9.5+.
Thanks!
Jeremy
On Wed, Nov 21, 2018 at 5:31 AM Christoph Berg <myon@debian.org> wrote:
Re: Jeremy Finzel 2018-11-14 <CAMa1XUiwpTZxZpywXJk8ueCiNhgT+2ARMGwu_HcEaRTKG+6uVQ@mail.gmail.com>
> Hello again -
>
> I have just tagged releases:
> v1.3.0 pglogical_ticker
So here's the promised update.
pglogical_ticker is basically fine, but the regression tests seem
flaky. Re-running fixed the problems, so I put the package live now.
Two builds were failing (each with 6 PG versions, testing stops on the
first problem):
https://pgdgbuild.dus.dg-i.net/job/pglogical-ticker-binaries/1/architecture=i386,distribution=stretch/console
10:39:54 /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
10:39:54 (using postmaster on localhost, port 5432)
10:39:54 ============== dropping database "contrib_regression" ==============
10:39:54 NOTICE: database "contrib_regression" does not exist, skipping
10:39:54 DROP DATABASE
10:39:54 ============== creating database "contrib_regression" ==============
10:39:54 CREATE DATABASE
10:39:54 ALTER DATABASE
10:39:54 ============== running regression test queries ==============
10:39:54 test 01_create_ext ... ok
10:39:55 test 02_setup ... ok
10:39:55 test 03_deploy ... ok
10:39:55 test 04_add_to_rep ... ok
10:39:55 test 05_tick ... ok
10:40:10 test 06_worker ... ok
10:40:12 test 07_handlers ... FAILED
10:40:12 test 08_reentrance ... ok
10:40:12 test 09_1_2_tests ... ok
10:40:12 test 99_cleanup ... ok
10:40:12
10:40:12 =======================
10:40:12 1 of 10 tests failed.
10:40:12 =======================
10:40:12
10:40:12 The differences that caused some tests to fail can be viewed in the
10:40:12 file "/tmp/autopkgtest.SdZHJC/tree/regression.diffs". A copy of the test summary that you see
10:40:12 above is saved in the file "/tmp/autopkgtest.SdZHJC/tree/regression.out".
10:40:12
10:40:12 make: *** [installcheck] Error 1
10:40:12 /usr/lib/postgresql/11/lib/pgxs/src/makefiles/pgxs.mk:396: recipe for target 'installcheck' failed
10:40:12 *** /tmp/pg_virtualenv.I2s8KW/log/postgresql-11-regress.log (last 100 lines) ***
10:40:12 2018-11-21 09:39:52.574 UTC [6361] LOG: listening on IPv6 address "::1", port 5432
10:40:12 2018-11-21 09:39:52.574 UTC [6361] LOG: listening on IPv4 address "127.0.0.1", port 5432
10:40:12 2018-11-21 09:39:52.574 UTC [6361] LOG: listening on Unix socket "/var/run/postgresql/.s.PGSQL.5432"
10:40:12 2018-11-21 09:39:52.586 UTC [6362] LOG: database system was shut down at 2018-11-21 09:39:52 UTC
10:40:12 2018-11-21 09:39:52.590 UTC [6361] LOG: database system is ready to accept connections
10:40:12 2018-11-21 09:39:52.590 UTC [6368] LOG: starting pglogical supervisor
10:40:12 2018-11-21 09:39:52.596 UTC [6370] [unknown]@postgres LOG: manager worker [6370] at slot 0 generation 1 detaching cleanly
10:40:12 2018-11-21 09:39:52.603 UTC [6371] [unknown]@template1 LOG: manager worker [6371] at slot 0 generation 2 detaching cleanly
10:40:12 2018-11-21 09:39:53.164 UTC [6372] [unknown]@[unknown] LOG: incomplete startup packet
10:40:12 2018-11-21 09:39:54.998 UTC [6416] [unknown]@postgres LOG: manager worker [6416] at slot 0 generation 3 detaching cleanly
10:40:12 2018-11-21 09:39:55.002 UTC [6418] [unknown]@contrib_regression LOG: starting pglogical database manager for database contrib_regression
10:40:12 2018-11-21 09:39:55.152 UTC [6434] LOG: pglogical_ticker worker initialized
10:40:12 2018-11-21 09:39:56.004 UTC [6435] [unknown]@template1 LOG: manager worker [6435] at slot 1 generation 1 detaching cleanly
10:40:12 2018-11-21 09:40:08.163 UTC [6434] ERROR: canceling statement due to user request
10:40:12 2018-11-21 09:40:08.166 UTC [6361] LOG: background worker "pglogical_ticker" (PID 6434) exited with exit code 1
10:40:12 2018-11-21 09:40:08.177 UTC [6436] LOG: pglogical_ticker worker initialized
10:40:12 2018-11-21 09:40:10.179 UTC [6436] ERROR: canceling statement due to user request
10:40:12 2018-11-21 09:40:10.181 UTC [6361] LOG: background worker "pglogical_ticker" (PID 6436) exited with exit code 1
10:40:12 2018-11-21 09:40:10.222 UTC [6441] FATAL: database 9999999 does not exist
10:40:12 2018-11-21 09:40:10.223 UTC [6442] LOG: pglogical_ticker worker initialized
10:40:12 2018-11-21 09:40:10.224 UTC [6361] LOG: background worker "pglogical_ticker" (PID 6441) exited with exit code 1
10:40:12 2018-11-21 09:40:11.227 UTC [6442] ERROR: canceling statement due to user request
10:40:12 2018-11-21 09:40:11.229 UTC [6361] LOG: background worker "pglogical_ticker" (PID 6442) exited with exit code 1
10:40:12 2018-11-21 09:40:12.360 UTC [6453] postgres@contrib_regression ERROR: cannot drop table pglogical_ticker.test1 because extension pglogical_ticker requires it
10:40:12 2018-11-21 09:40:12.360 UTC [6453] postgres@contrib_regression HINT: You can drop extension pglogical_ticker instead.
10:40:12 2018-11-21 09:40:12.360 UTC [6453] postgres@contrib_regression STATEMENT: DROP TABLE pglogical_ticker.test1;
10:40:12 2018-11-21 09:40:12.434 UTC [6418] [unknown]@contrib_regression LOG: manager worker [6418] at slot 0 generation 4 detaching cleanly
10:40:12 Dropping cluster 11/regress ...
10:40:12 **** regression.diffs ****
10:40:12 *** /tmp/autopkgtest.SdZHJC/tree/expected/07_handlers.out 2018-11-13 18:43:54.000000000 +0000
10:40:12 --- /tmp/autopkgtest.SdZHJC/tree/results/07_handlers.out 2018-11-21 09:40:12.228123205 +0000
10:40:12 ***************
10:40:12 *** 26,32 ****
10:40:12 SELECT pglogical_ticker.launch() IS NULL AS pid;
10:40:12 pid
10:40:12 -----
10:40:12 ! f
10:40:12 (1 row)
10:40:12
10:40:12 SELECT pg_sleep(1);
10:40:12 --- 26,32 ----
10:40:12 SELECT pglogical_ticker.launch() IS NULL AS pid;
10:40:12 pid
10:40:12 -----
10:40:12 ! t
10:40:12 (1 row)
10:40:12
10:40:12 SELECT pg_sleep(1);
10:40:12
https://pgdgbuild.dus.dg-i.net/job/pglogical-ticker-binaries/1/architecture=ppc64el,distribution=xenial/console
10:41:00 /usr/lib/postgresql/9.5/lib/pgxs/src/makefiles/../../src/test/regress/pg_regress --inputdir=./ --bindir='/usr/lib/postgresql/9.5/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
10:41:00 (using postmaster on localhost, port 5432)
10:41:00 ============== dropping database "contrib_regression" ==============
10:41:00 NOTICE: database "contrib_regression" does not exist, skipping
10:41:00 DROP DATABASE
10:41:00 ============== creating database "contrib_regression" ==============
10:41:01 CREATE DATABASE
10:41:01 ALTER DATABASE
10:41:01 ============== running regression test queries ==============
10:41:01 test 01_create_ext ... ok
10:41:01 test 02_setup ... ok
10:41:01 test 03_deploy ... ok
10:41:01 test 04_add_to_rep ... ok
10:41:01 test 05_tick ... ok
10:41:16 test 06_worker ... FAILED
10:41:18 test 07_handlers ... ok
10:41:18 test 08_reentrance ... ok
10:41:18 test 09_1_2_tests ... ok
10:41:18 test 99_cleanup ... ok
10:41:18
10:41:18 =======================
10:41:18 1 of 10 tests failed.
10:41:18 =======================
10:41:18
10:41:18 The differences that caused some tests to fail can be viewed in the
10:41:18 file "/tmp/adt-run.Ctjy5G/tree/regression.diffs". A copy of the test summary that you see
10:41:18 above is saved in the file "/tmp/adt-run.Ctjy5G/tree/regression.out".
10:41:18
10:41:18 /usr/lib/postgresql/9.5/lib/pgxs/src/makefiles/pgxs.mk:274: recipe for target 'installcheck' failed
10:41:18 make: *** [installcheck] Error 1
10:41:18 *** /tmp/pg_virtualenv.AKgntO/log/postgresql-9.5-regress.log (last 100 lines) ***
10:41:18 2018-11-21 09:40:58.638 UTC [5679] LOG: database system was shut down at 2018-11-21 09:40:58 UTC
10:41:18 2018-11-21 09:40:58.639 UTC [5679] LOG: MultiXact member wraparound protections are now enabled
10:41:18 2018-11-21 09:40:58.645 UTC [5683] LOG: autovacuum launcher started
10:41:18 2018-11-21 09:40:58.647 UTC [5678] LOG: database system is ready to accept connections
10:41:18 2018-11-21 09:40:58.648 UTC [5685] LOG: starting pglogical supervisor
10:41:18 2018-11-21 09:40:58.656 UTC [5686] [unknown]@template1 LOG: manager worker [5686] at slot 0 generation 1 detaching cleanly
10:41:18 2018-11-21 09:40:59.122 UTC [5687] [unknown]@[unknown] LOG: incomplete startup packet
10:41:18 2018-11-21 09:40:59.653 UTC [5691] [unknown]@postgres LOG: manager worker [5691] at slot 0 generation 2 detaching cleanly
10:41:18 2018-11-21 09:41:01.367 UTC [5732] [unknown]@template1 LOG: manager worker [5732] at slot 0 generation 3 detaching cleanly
10:41:18 2018-11-21 09:41:01.614 UTC [5749] LOG: pglogical_ticker worker initialized
10:41:18 2018-11-21 09:41:02.380 UTC [5750] [unknown]@postgres LOG: manager worker [5750] at slot 0 generation 4 detaching cleanly
10:41:18 2018-11-21 09:41:03.373 UTC [5751] [unknown]@contrib_regression LOG: starting pglogical database manager for database contrib_regression
10:41:18 2018-11-21 09:41:14.635 UTC [5749] ERROR: canceling statement due to user request
10:41:18 2018-11-21 09:41:14.638 UTC [5678] LOG: worker process: pglogical_ticker worker (PID 5749) exited with exit code 1
10:41:18 2018-11-21 09:41:16.700 UTC [5758] FATAL: database 9999999 does not exist
10:41:18 2018-11-21 09:41:16.703 UTC [5678] LOG: worker process: pglogical_ticker worker (PID 5758) exited with exit code 1
10:41:18 2018-11-21 09:41:16.705 UTC [5759] LOG: pglogical_ticker worker initialized
10:41:18 2018-11-21 09:41:16.706 UTC [5760] LOG: pglogical_ticker worker initialized
10:41:18 2018-11-21 09:41:17.709 UTC [5759] ERROR: canceling statement due to user request
10:41:18 2018-11-21 09:41:17.709 UTC [5760] ERROR: canceling statement due to user request
10:41:18 2018-11-21 09:41:17.712 UTC [5678] LOG: worker process: pglogical_ticker worker (PID 5759) exited with exit code 1
10:41:18 2018-11-21 09:41:17.712 UTC [5678] LOG: worker process: pglogical_ticker worker (PID 5760) exited with exit code 1
10:41:18 2018-11-21 09:41:18.841 UTC [5769] postgres@contrib_regression ERROR: cannot drop table pglogical_ticker.test1 because extension pglogical_ticker requires it
10:41:18 2018-11-21 09:41:18.841 UTC [5769] postgres@contrib_regression HINT: You can drop extension pglogical_ticker instead.
10:41:18 2018-11-21 09:41:18.841 UTC [5769] postgres@contrib_regression STATEMENT: DROP TABLE pglogical_ticker.test1;
10:41:18 Dropping cluster 9.5/regress ...
10:41:20 **** regression.diffs ****
10:41:20 *** /tmp/adt-run.Ctjy5G/tree/expected/06_worker.out 2018-11-13 18:43:54.000000000 +0000
10:41:20 --- /tmp/adt-run.Ctjy5G/tree/results/06_worker.out 2018-11-21 09:41:16.641272199 +0000
10:41:20 ***************
10:41:20 *** 47,60 ****
10:41:20 SELECT COUNT(1) FROM worker_pid WHERE pid IS NOT NULL;
10:41:20 count
10:41:20 -------
10:41:20 ! 1
10:41:20 (1 row)
10:41:20
10:41:20 SELECT pg_cancel_backend(pid)
10:41:20 FROM worker_pid;
10:41:20 pg_cancel_backend
10:41:20 -------------------
10:41:20 ! t
10:41:20 (1 row)
10:41:20
10:41:20 --Test it does nothing with no tables
10:41:20 --- 47,60 ----
10:41:20 SELECT COUNT(1) FROM worker_pid WHERE pid IS NOT NULL;
10:41:20 count
10:41:20 -------
10:41:20 ! 0
10:41:20 (1 row)
10:41:20
10:41:20 SELECT pg_cancel_backend(pid)
10:41:20 FROM worker_pid;
10:41:20 pg_cancel_backend
10:41:20 -------------------
10:41:20 !
10:41:20 (1 row)
10:41:20
10:41:20 --Test it does nothing with no tables
10:41:20
> v1.5.0 pg_fact_loader
07_launch_worker.out fails:
7 | 0001234567 | 35 | | 0 |
8 | 0001234568 | 35 | | 0 |
9 | 0001234569 | 35 | | 0 |
! 10 | 0001234577 | 35 | | 0 |
(10 rows)
UPDATE fact_loader.fact_tables SET force_worker_priority = FALSE WHERE fact_table_relid = 'test_fact.customers_fact'::REGCLASS;
--- 35,41 ----
7 | 0001234567 | 35 | | 0 |
8 | 0001234568 | 35 | | 0 |
9 | 0001234569 | 35 | | 0 |
! 10 | 0001234560 | 35 | | 0 |
(10 rows)
UPDATE fact_loader.fact_tables SET force_worker_priority = FALSE WHERE fact_table_relid = 'test_fact.customers_fact'::REGCLASS;
The regression tests need the extension version adjusted:
--- /tmp/autopkgtest.7mlirf/tree/results/17_1_3_features.out 2018-11-21 10:37:51.174647317 +0100
CREATE EXTENSION pg_fact_loader VERSION '1.2';
+ ERROR: extension "pg_fact_loader" has no installation script nor update path for version "1.2"
--- /tmp/autopkgtest.7mlirf/tree/results/18_alter_update_features.out
CREATE EXTENSION pg_fact_loader VERSION '1.2';
+ ERROR: extension "pg_fact_loader" has no installation script nor update path for version "1.2"
That's on 11, the 9.5 log is worse: https://pgdgbuild.dus.dg-i.net/job/pg-fact-loader-binaries/2/architecture=amd64,distribution=sid/console
Not sure how much of that is cause by hstore missing, you'll need to
add postgresql-contrib-PGVERSION to debian/tests/control.in. (For
PG10, -contrib is included in the main server package.)
Christoph
Re: Jeremy Finzel 2018-11-27 <CAMa1XUgogtFxnYC5S+t6rO-zP2fNAjO23k8S8v__6Zgtj3Jivg@mail.gmail.com> > Dear Christoph, > > Thank you for the review and I'm sorry for this nuisance. I have tagged a > new release version 1.5.1 which should fix this issue. > > I missed this bug due to my own old extension files still existing and not > removed via make uninstall because they had already been removed from my > Makefile. I am hoping this should cover all the errors you had not only > with 11 but with 9.5+. Hi Jeremy, the build is still not passing the regression tests. The good news is that the diff is the same on 9.5 and 11: 15:13:28 Dropping cluster 9.5/regress ... 15:13:29 **** regression.diffs **** 15:13:29 --- /tmp/autopkgtest.RWVqQv/tree/expected/07_launch_worker.out 2018-11-27 15:26:32.000000000 +0000 15:13:29 +++ /tmp/autopkgtest.RWVqQv/tree/results/07_launch_worker.out 2018-11-28 14:13:05.269366205 +0000 15:13:29 @@ -35,7 +35,7 @@ 15:13:29 7 | 0001234567 | 35 | | 0 | 15:13:29 8 | 0001234568 | 35 | | 0 | 15:13:29 9 | 0001234569 | 35 | | 0 | 15:13:29 - 10 | 0001234577 | 35 | | 0 | 15:13:29 + 10 | 0001234560 | 35 | | 0 | 15:13:29 (10 rows) 15:13:29 15:13:29 UPDATE fact_loader.fact_tables SET force_worker_priority = FALSE WHERE fact_table_relid = 'test_fact.customers_fact'::REGCLASS; 15:13:29 Christoph
Re: To Jeremy Finzel 2018-11-28 <20181128144419.GB7747@msg.df7cb.de> > Re: Jeremy Finzel 2018-11-27 <CAMa1XUgogtFxnYC5S+t6rO-zP2fNAjO23k8S8v__6Zgtj3Jivg@mail.gmail.com> > the build is still not passing the regression tests. The good news is > that the diff is the same on 9.5 and 11: Full log: https://pgdgbuild.dus.dg-i.net/job/pg-fact-loader-binaries/5/architecture=amd64,distribution=sid/console > 15:13:28 Dropping cluster 9.5/regress ... > 15:13:29 **** regression.diffs **** > 15:13:29 --- /tmp/autopkgtest.RWVqQv/tree/expected/07_launch_worker.out 2018-11-27 15:26:32.000000000 +0000 > 15:13:29 +++ /tmp/autopkgtest.RWVqQv/tree/results/07_launch_worker.out 2018-11-28 14:13:05.269366205 +0000 > 15:13:29 @@ -35,7 +35,7 @@ > 15:13:29 7 | 0001234567 | 35 | | 0 | > 15:13:29 8 | 0001234568 | 35 | | 0 | > 15:13:29 9 | 0001234569 | 35 | | 0 | > 15:13:29 - 10 | 0001234577 | 35 | | 0 | > 15:13:29 + 10 | 0001234560 | 35 | | 0 | > 15:13:29 (10 rows) > 15:13:29 > 15:13:29 UPDATE fact_loader.fact_tables SET force_worker_priority = FALSE WHERE fact_table_relid = 'test_fact.customers_fact'::REGCLASS; > 15:13:29 Christoph
Dear Christoph,
Thank you for the full log. I can't reproduce this issue on several machines ... is it possible for you to run this with log_min_messages = DEBUG and log_min_duration_statement = 0 and provide output?
Thanks,
On Wed, Nov 28, 2018 at 8:44 AM Christoph Berg <myon@debian.org> wrote:
Re: To Jeremy Finzel 2018-11-28 <20181128144419.GB7747@msg.df7cb.de>
> Re: Jeremy Finzel 2018-11-27 <CAMa1XUgogtFxnYC5S+t6rO-zP2fNAjO23k8S8v__6Zgtj3Jivg@mail.gmail.com>
> the build is still not passing the regression tests. The good news is
> that the diff is the same on 9.5 and 11:
Full log:
https://pgdgbuild.dus.dg-i.net/job/pg-fact-loader-binaries/5/architecture=amd64,distribution=sid/console
> 15:13:28 Dropping cluster 9.5/regress ...
> 15:13:29 **** regression.diffs ****
> 15:13:29 --- /tmp/autopkgtest.RWVqQv/tree/expected/07_launch_worker.out 2018-11-27 15:26:32.000000000 +0000
> 15:13:29 +++ /tmp/autopkgtest.RWVqQv/tree/results/07_launch_worker.out 2018-11-28 14:13:05.269366205 +0000
> 15:13:29 @@ -35,7 +35,7 @@
> 15:13:29 7 | 0001234567 | 35 | | 0 |
> 15:13:29 8 | 0001234568 | 35 | | 0 |
> 15:13:29 9 | 0001234569 | 35 | | 0 |
> 15:13:29 - 10 | 0001234577 | 35 | | 0 |
> 15:13:29 + 10 | 0001234560 | 35 | | 0 |
> 15:13:29 (10 rows)
> 15:13:29
> 15:13:29 UPDATE fact_loader.fact_tables SET force_worker_priority = FALSE WHERE fact_table_relid = 'test_fact.customers_fact'::REGCLASS;
> 15:13:29
Christoph
Dear Christoph,
This was an actual bug only apparent when testing on different cluster timezone configurations. I have fixed it and drafted a new release 1.5.2. Thanks for all your help with this. I hope this one passes! It does on my own machine and the VM I spun up on which I was able to reproduce your test failure.
Thanks,
On Wed, Nov 28, 2018 at 10:08 AM Jeremy Finzel <finzelj@gmail.com> wrote:
Dear Christoph,Thank you for the full log. I can't reproduce this issue on several machines ... is it possible for you to run this with log_min_messages = DEBUG and log_min_duration_statement = 0 and provide output?Thanks,On Wed, Nov 28, 2018 at 8:44 AM Christoph Berg <myon@debian.org> wrote:Re: To Jeremy Finzel 2018-11-28 <20181128144419.GB7747@msg.df7cb.de>
> Re: Jeremy Finzel 2018-11-27 <CAMa1XUgogtFxnYC5S+t6rO-zP2fNAjO23k8S8v__6Zgtj3Jivg@mail.gmail.com>
> the build is still not passing the regression tests. The good news is
> that the diff is the same on 9.5 and 11:
Full log:
https://pgdgbuild.dus.dg-i.net/job/pg-fact-loader-binaries/5/architecture=amd64,distribution=sid/console
> 15:13:28 Dropping cluster 9.5/regress ...
> 15:13:29 **** regression.diffs ****
> 15:13:29 --- /tmp/autopkgtest.RWVqQv/tree/expected/07_launch_worker.out 2018-11-27 15:26:32.000000000 +0000
> 15:13:29 +++ /tmp/autopkgtest.RWVqQv/tree/results/07_launch_worker.out 2018-11-28 14:13:05.269366205 +0000
> 15:13:29 @@ -35,7 +35,7 @@
> 15:13:29 7 | 0001234567 | 35 | | 0 |
> 15:13:29 8 | 0001234568 | 35 | | 0 |
> 15:13:29 9 | 0001234569 | 35 | | 0 |
> 15:13:29 - 10 | 0001234577 | 35 | | 0 |
> 15:13:29 + 10 | 0001234560 | 35 | | 0 |
> 15:13:29 (10 rows)
> 15:13:29
> 15:13:29 UPDATE fact_loader.fact_tables SET force_worker_priority = FALSE WHERE fact_table_relid = 'test_fact.customers_fact'::REGCLASS;
> 15:13:29
Christoph
Re: Jeremy Finzel 2018-11-29 <CAMa1XUjrMxQKSEwgBySM7mdRY=fo+X=z=Tsntgw8ObkoB4ffwg@mail.gmail.com> > This was an actual bug only apparent when testing on different cluster > timezone configurations. I have fixed it and drafted a new release 1.5.2. > Thanks for all your help with this. I hope this one passes! It does on my > own machine and the VM I spun up on which I was able to reproduce your test > failure. Hi Jeremy, the package built fine now. I'll also do the Debian uploads now. It would be nice if you could have a look at the pglogical-ticker instabilities mentioned earlier. The tests seem to have a few race conditions that trigger occasionally. Thanks, Christoph
Re: To Jeremy Finzel 2018-11-30 <20181130102855.GA20278@msg.df7cb.de> > It would be nice if you could have a look at the pglogical-ticker > instabilities mentioned earlier. The tests seem to have a few race > conditions that trigger occasionally. Poking around a bit more, the pg-fact-loader tests are also unstable. The two failures I've seen are: 12:33:26 Dropping cluster 11/regress ... 12:33:26 **** regression.diffs **** 12:33:26 --- /tmp/adt-run.TMZdfu/build.UnY/pg-fact-loader-1.5.2/expected/16_1_2_features.out 2018-11-29 20:17:47.000000000+0000 12:33:26 +++ /tmp/adt-run.TMZdfu/build.UnY/pg-fact-loader-1.5.2/results/16_1_2_features.out 2018-11-30 11:33:15.707006177+0000 12:33:26 @@ -235,18 +235,15 @@ 12:33:26 \! psql contrib_regression -c ' SELECT fact_loader.worker() INTO try2;' 12:33:26 SELECT 1 12:33:26 SELECT pg_sleep(2); 12:33:26 -COMMIT 12:33:26 pg_sleep 12:33:26 ---------- 12:33:26 12:33:26 (1 row) 12:33:26 12:33:26 SELECT * FROM try1; 12:33:26 - worker 12:33:26 --------- 12:33:26 - t 12:33:26 -(1 row) 12:33:26 - 12:33:26 +ERROR: relation "try1" does not exist 12:33:26 +LINE 1: SELECT * FROM try1; 12:33:26 + ^ 12:33:26 SELECT * FROM try2; 12:33:26 worker 12:33:26 -------- 12:33:26 @@ -292,6 +289,7 @@ 12:33:26 $BODY$ 12:33:26 LANGUAGE plpgsql; 12:33:26 UPDATE fact_loader.fact_tables SET enabled = FALSE; 12:33:26 +COMMIT 12:33:26 BEGIN; --Keep the same transaction time to make these tests possible 12:33:26 INSERT INTO fact_loader.fact_tables (fact_table_relid, enabled, priority, use_daily_schedule, daily_scheduled_time,daily_scheduled_tz, daily_scheduled_proid) 12:33:26 VALUES ('test_fact.daily_customers_fact', TRUE, 10, TRUE, now() + interval '1 second', 'America/Chicago', 'test_fact.daily_customers_fact_merge'::REGPROC); 12:33:26 12:30:28 Dropping cluster 9.5/regress ... 12:30:29 **** regression.diffs **** 12:30:29 --- /tmp/adt-run.Z3qsII/build.i9p/pg-fact-loader-1.5.2/expected/16_1_2_features.out 2018-11-29 20:17:47.000000000+0000 12:30:29 +++ /tmp/adt-run.Z3qsII/build.i9p/pg-fact-loader-1.5.2/results/16_1_2_features.out 2018-11-30 11:30:20.065918575+0000 12:30:29 @@ -227,15 +227,16 @@ 12:30:29 \! psql contrib_regression -c 'BEGIN; SELECT fact_loader.worker() INTO try1; SELECT pg_sleep(2); COMMIT;' & 12:30:29 SELECT pg_sleep(1); 12:30:29 NOTICE: table "process_queue" does not exist, skipping 12:30:29 +COMMIT 12:30:29 pg_sleep 12:30:29 ---------- 12:30:29 12:30:29 (1 row) 12:30:29 12:30:29 \! psql contrib_regression -c ' SELECT fact_loader.worker() INTO try2;' 12:30:29 +NOTICE: table "process_queue" does not exist, skipping 12:30:29 SELECT 1 12:30:29 SELECT pg_sleep(2); 12:30:29 -COMMIT 12:30:29 pg_sleep 12:30:29 ---------- 12:30:29 12:30:29 @@ -250,7 +251,7 @@ 12:30:29 SELECT * FROM try2; 12:30:29 worker 12:30:29 -------- 12:30:29 - f 12:30:29 + t 12:30:29 (1 row) 12:30:29 12:30:29 --Daily schedule test - with range format suggestions included!!! 12:30:29 Maybe pg_sleep(2) isn't enough? Christoph
Thanks for the reminder. I will look at both of these sporadic failures next week. Thank you so much for your review and for getting these packages out!
On Fri, Nov 30, 2018 at 5:44 AM Christoph Berg <myon@debian.org> wrote:
Re: To Jeremy Finzel 2018-11-30 <20181130102855.GA20278@msg.df7cb.de>
> It would be nice if you could have a look at the pglogical-ticker
> instabilities mentioned earlier. The tests seem to have a few race
> conditions that trigger occasionally.
Poking around a bit more, the pg-fact-loader tests are also unstable.
The two failures I've seen are:
12:33:26 Dropping cluster 11/regress ...
12:33:26 **** regression.diffs ****
12:33:26 --- /tmp/adt-run.TMZdfu/build.UnY/pg-fact-loader-1.5.2/expected/16_1_2_features.out 2018-11-29 20:17:47.000000000 +0000
12:33:26 +++ /tmp/adt-run.TMZdfu/build.UnY/pg-fact-loader-1.5.2/results/16_1_2_features.out 2018-11-30 11:33:15.707006177 +0000
12:33:26 @@ -235,18 +235,15 @@
12:33:26 \! psql contrib_regression -c ' SELECT fact_loader.worker() INTO try2;'
12:33:26 SELECT 1
12:33:26 SELECT pg_sleep(2);
12:33:26 -COMMIT
12:33:26 pg_sleep
12:33:26 ----------
12:33:26
12:33:26 (1 row)
12:33:26
12:33:26 SELECT * FROM try1;
12:33:26 - worker
12:33:26 ---------
12:33:26 - t
12:33:26 -(1 row)
12:33:26 -
12:33:26 +ERROR: relation "try1" does not exist
12:33:26 +LINE 1: SELECT * FROM try1;
12:33:26 + ^
12:33:26 SELECT * FROM try2;
12:33:26 worker
12:33:26 --------
12:33:26 @@ -292,6 +289,7 @@
12:33:26 $BODY$
12:33:26 LANGUAGE plpgsql;
12:33:26 UPDATE fact_loader.fact_tables SET enabled = FALSE;
12:33:26 +COMMIT
12:33:26 BEGIN; --Keep the same transaction time to make these tests possible
12:33:26 INSERT INTO fact_loader.fact_tables (fact_table_relid, enabled, priority, use_daily_schedule, daily_scheduled_time, daily_scheduled_tz, daily_scheduled_proid)
12:33:26 VALUES ('test_fact.daily_customers_fact', TRUE, 10, TRUE, now() + interval '1 second', 'America/Chicago', 'test_fact.daily_customers_fact_merge'::REGPROC);
12:33:26
12:30:28 Dropping cluster 9.5/regress ...
12:30:29 **** regression.diffs ****
12:30:29 --- /tmp/adt-run.Z3qsII/build.i9p/pg-fact-loader-1.5.2/expected/16_1_2_features.out 2018-11-29 20:17:47.000000000 +0000
12:30:29 +++ /tmp/adt-run.Z3qsII/build.i9p/pg-fact-loader-1.5.2/results/16_1_2_features.out 2018-11-30 11:30:20.065918575 +0000
12:30:29 @@ -227,15 +227,16 @@
12:30:29 \! psql contrib_regression -c 'BEGIN; SELECT fact_loader.worker() INTO try1; SELECT pg_sleep(2); COMMIT;' &
12:30:29 SELECT pg_sleep(1);
12:30:29 NOTICE: table "process_queue" does not exist, skipping
12:30:29 +COMMIT
12:30:29 pg_sleep
12:30:29 ----------
12:30:29
12:30:29 (1 row)
12:30:29
12:30:29 \! psql contrib_regression -c ' SELECT fact_loader.worker() INTO try2;'
12:30:29 +NOTICE: table "process_queue" does not exist, skipping
12:30:29 SELECT 1
12:30:29 SELECT pg_sleep(2);
12:30:29 -COMMIT
12:30:29 pg_sleep
12:30:29 ----------
12:30:29
12:30:29 @@ -250,7 +251,7 @@
12:30:29 SELECT * FROM try2;
12:30:29 worker
12:30:29 --------
12:30:29 - f
12:30:29 + t
12:30:29 (1 row)
12:30:29
12:30:29 --Daily schedule test - with range format suggestions included!!!
12:30:29
Maybe pg_sleep(2) isn't enough?
Christoph