[Bug 1864423] Re: Failed test 'default log is not used' with new procps 3.3.16-1

Mon Feb 24 08:25:30 UTC 2020

The failing tests are part of 020_create_sql_remove.t:

The checks are like:
  ok -z $default_log, "default log is not used";

And $default_log points to /var/log/postgresql/postgresql-12-main.log in
both cases.

Entering interactive mode on fail:
$ sudo ./testsuite -f 20 -V -s

Eventually the whole cluster is cleaned, so the config and dirs are missing.
Changing the tests to find more details ...

The test sets a link:
/etc/postgresql/12/main/log -> /var/lib/postgresql/12/main/mylog
And then the instance is correctly using that log:
$ pg_lsclusters -h
12 main 5432 online postgres /var/lib/postgresql/12/main /var/lib/postgresql/12/main/mylog

But the old log "still" exists in the bad case and that breaks it.

log: Config >> symlink >> default path
The check wants to see the "default path" to be not existing - or actually not used.

It tries to clean the log via:
  is ((exec_as 'root', "pg_ctlcluster $v main stop"), 0, 'stopping cluster');
  open L, ">$default_log"; close L; # empty default log file

The problem seems to be non synchronous stop or a log file clean issue -
the log still contains stuff after being cleaned.

ok 11 - correct output of pg_lsclusters -h
/usr/bin/ls: cannot access '/etc/postgresql/12/main/log': No such file or directory
-rw-r----- 1 postgres adm 559 Feb 24 09:23 /var/log/postgresql/postgresql-12-main.log
12 main 5432 online postgres /var/lib/postgresql/12/main /var/log/postgresql/postgresql-12-main.log
PRE STOP
2020-02-24 09:23:07.177 CET [16492] LOG:  starting PostgreSQL 12.1 (Ubuntu 12.1-2build1) on x86_64-pc-linux-gnu, compiled by gcc (Ubuntu 9.2.1-25ubuntu1) 9.2.1 20200123, 64-bit
2020-02-24 09:23:07.177 CET [16492] LOG:  listening on IPv4 address "127.0.0.1", port 5432
2020-02-24 09:23:07.177 CET [16492] LOG:  listening on Unix socket "/var/run/postgresql/.s.PGSQL.5432"
2020-02-24 09:23:07.188 CET [16493] LOG:  database system was shut down at 2020-02-24 09:23:06 CET
2020-02-24 09:23:07.192 CET [16492] LOG:  database system is ready to accept connections
-- END --
ok 12 - stopping cluster
PRE CLEAN
2020-02-24 09:23:07.177 CET [16492] LOG:  starting PostgreSQL 12.1 (Ubuntu 12.1-2build1) on x86_64-pc-linux-gnu, compiled by gcc (Ubuntu 9.2.1-25ubuntu1) 9.2.1 20200123, 64-bit
2020-02-24 09:23:07.177 CET [16492] LOG:  listening on IPv4 address "127.0.0.1", port 5432
2020-02-24 09:23:07.177 CET [16492] LOG:  listening on Unix socket "/var/run/postgresql/.s.PGSQL.5432"
2020-02-24 09:23:07.188 CET [16493] LOG:  database system was shut down at 2020-02-24 09:23:06 CET
2020-02-24 09:23:07.192 CET [16492] LOG:  database system is ready to accept connections
2020-02-24 09:23:09.669 CET [16492] LOG:  received fast shutdown request
2020-02-24 09:23:09.669 CET [16492] LOG:  aborting any active transactions
2020-02-24 09:23:09.671 CET [16492] LOG:  background worker "logical replication launcher" (PID 16499) exited with exit code 1
2020-02-24 09:23:09.673 CET [16494] LOG:  shutting down
2020-02-24 09:23:09.680 CET [16492] LOG:  database system is shut down
-- END --
POST CLEAN
2020-02-24 09:23:07.177 CET [16492] LOG:  starting PostgreSQL 12.1 (Ubuntu 12.1-2build1) on x86_64-pc-linux-gnu, compiled by gcc (Ubuntu 9.2.1-25ubuntu1) 9.2.1 20200123, 64-bit
2020-02-24 09:23:07.177 CET [16492] LOG:  listening on IPv4 address "127.0.0.1", port 5432
2020-02-24 09:23:07.177 CET [16492] LOG:  listening on Unix socket "/var/run/postgresql/.s.PGSQL.5432"
2020-02-24 09:23:07.188 CET [16493] LOG:  database system was shut down at 2020-02-24 09:23:06 CET
2020-02-24 09:23:07.192 CET [16492] LOG:  database system is ready to accept connections
2020-02-24 09:23:09.669 CET [16492] LOG:  received fast shutdown request
2020-02-24 09:23:09.669 CET [16492] LOG:  aborting any active transactions
2020-02-24 09:23:09.671 CET [16492] LOG:  background worker "logical replication launcher" (PID 16499) exited with exit code 1
2020-02-24 09:23:09.673 CET [16494] LOG:  shutting down
2020-02-24 09:23:09.680 CET [16492] LOG:  database system is shut down
-- END --
ok 13 - restarting cluster with nondefault log symlink
lrwxrwxrwx 1 root     root  33 Feb 24 09:23 /etc/postgresql/12/main/log -> /var/lib/postgresql/12/main/mylog
-rw-r----- 1 postgres adm  961 Feb 24 09:23 /var/log/postgresql/postgresql-12-main.log
12 main 5432 online postgres /var/lib/postgresql/12/main /var/lib/postgresql/12/main/mylog
ok 14 - log target is used as log file
not ok 15 - default log is not used
#   Failed test 'default log is not used'
#   at ./t/020_create_sql_remove.t line 104.

-- 
You received this bug notification because you are a member of Ubuntu
Foundations Bugs, which is subscribed to procps in Ubuntu.
https://bugs.launchpad.net/bugs/1864423

Title:
  Failed test 'default log is not used' with new procps 3.3.16-1

Status in postgresql-common package in Ubuntu:
  New
Status in procps package in Ubuntu:
  New

Bug description:
  Since the new procps upload
   procps | 2:3.3.16-1ubuntu1   | focal-proposed  | source, amd64, arm64, armhf, i386, ppc64el, s390x
  the tests of postgresql-common fail.

  The issues are:
  autopkgtest [15:43:10]: test run-testsuite:  - - - - - - - - - - results - - - - - - - - - -
  run-testsuite        FAIL non-zero exit status 2
  autopkgtest [15:43:10]: test run-testsuite:  - - - - - - - - - - stderr - - - - - - - - - -
  #   Failed test 'default log is not used'
  #   at ./t/020_create_sql_remove.t line 143.
  #   Failed test 'default log is not used'
  #   at ./t/020_create_sql_remove.t line 154.
  # Looks like you failed 2 tests of 144.

  It was retried a few times by different people now and reproduced so
  we can assume it is a real issues for now.

  I was running two VMs to compare:
  $ sudo ~/work/autopkgtest/autopkgtest/runner/autopkgtest --no-built-binaries --apt-upgrade --test-name=run-testsuite --apt-pocket=proposed=src:procps --shell postgresql-common_211.dsc -- qemu --qemu-options='-cpu host' --ram-size=2048 --cpus 2 ~/work/autopkgtest-focal-amd64.img
  (and the other one without --apt-pocket=proposed=src:procps)

  The issue reproduced locally in only the one with the new procps.

  In Debian the latest similar run is
  https://ci.debian.net/data/autopkgtest/testing/amd64/p/postgresql-common/4279031/log.gz
  https://ci.debian.net/data/packages/testing/amd64/p/postgresql-common/4279031.log
  But that is pre-3.3.16 and I wasn't able to find their result with the same combination.

  Lets mark this bug update-excuse and check if we can find anything in
  these VMs.

To manage notifications about this bug go to:
https://bugs.launchpad.net/ubuntu/+source/postgresql-common/+bug/1864423/+subscriptions