Test run_logging_test is failing

[phracek]

Container platform

Podman/Docker

Version

No response

OS version of the container image

RHEL 7

Bugzilla, Jira

No response

Description

During the our nightly build test there is failed test test_logging_test:

==============================================
Tests were run for image rhscl/postgresql-10-rhel7:1
==============================================
Test cases results:

 [PASSED] for 'postgresql-container_tests' run_container_creation_tests (00:00:21)
 [PASSED] for 'postgresql-container_tests' run_general_tests (00:00:46)
 [PASSED] for 'postgresql-container_tests' run_change_password_test (00:00:08)
 [PASSED] for 'postgresql-container_tests' run_replication_test (00:00:05)
 [PASSED] for 'postgresql-container_tests' run_doc_test (00:00:00)
 [PASSED] for 'postgresql-container_tests' run_s2i_test (00:00:11)
 [PASSED] for 'postgresql-container_tests' run_test_cfg_hook (00:00:05)
 [PASSED] for 'postgresql-container_tests' run_s2i_bake_data_test (00:00:11)
 [PASSED] for 'postgresql-container_tests' run_s2i_enable_ssl_test (00:00:06)
 [PASSED] for 'postgresql-container_tests' run_upgrade_test (00:01:12)
 [PASSED] for 'postgresql-container_tests' run_migration_test (00:01:13)
 [PASSED] for 'postgresql-container_tests' run_pgaudit_test (00:00:00)
 [FAILED] for 'postgresql-container_tests' run_logging_test (00:00:03)

Tests for rhscl/postgresql-10-rhel7:1 failed.
errexit on line 38, common/test.sh

The log from the test is here:

-----------------------------------------------
Running test run_logging_test (starting at 2023-08-30 22:45:47-04:00) ... 
-----------------------------------------------
e7a450c313ed874de296e4eab262b81527ffbf9a36629d43519ff1134e51c61c
Created container e7a450c313ed874de296e4eab262b81527ffbf9a36629d43519ff1134e51c61c
psql: FATAL:  role "nonexistent" does not exist
ERROR: the container log does not include expected error message
Test for image 'rhscl/postgresql-10-rhel7:1' FAILED (exit code: 1)
Tests finished with EXIT=0

==============================================
Resources info:
Memory:
              total        used        free      shared  buff/cache   available
Mem:           1.8G        545M        192M        248M        1.1G        860M
Swap:            0B          0B          0B
Storage:

[snipped]

==============================================
Image rhscl/postgresql-10-rhel7:1 information:
==============================================
Uncompressed size of the image: 317MB
Compressed size of the image: 110MB

==============================================
Cleaning of testing containers and images started.
It may take a few seconds.
==============================================
Examining image ID files in $APP_ID_FILE_DIR=/tmp/tmp.b0sEpzEL1O
Examining CID files in $CID_FILE_DIR=/tmp/tmp.upD2aK4wlD
Stopping and removing container d31b86ba50d76b6932097e136bd7ba467912ed9ae9bb8b19cdbfb415f0516527...
d31b86ba50d76b6932097e136bd7ba467912ed9ae9bb8b19cdbfb415f0516527
d31b86ba50d76b6932097e136bd7ba467912ed9ae9bb8b19cdbfb415f0516527
Stopping and removing container 91d526b789acfc55fb2372acf324016b2c54f0091b2db6601984acfad5c92f26...
91d526b789acfc55fb2372acf324016b2c54f0091b2db6601984acfad5c92f26
91d526b789acfc55fb2372acf324016b2c54f0091b2db6601984acfad5c92f26
Stopping and removing container c4e42fb36b43b1152314629f1bb12b42de7ac287f2312963f504a7381b2da906...
c4e42fb36b43b1152314629f1bb12b42de7ac287f2312963f504a7381b2da906
c4e42fb36b43b1152314629f1bb12b42de7ac287f2312963f504a7381b2da906
Stopping and removing container 9bc22f02e1816b3d6df0304949d3c854dfd8f3d7d51f8d53cf42df6fc4baca0a...
Dumping logs for 9bc22f02e1816b3d6df0304949d3c854dfd8f3d7d51f8d53cf42df6fc4baca0a
The files belonging to this database system will be owned by user "postgres".
This user must also own the server process.
The database cluster will be initialized with locale "en_US.utf8".
The default database encoding has accordingly been set to "UTF8".
The default text search configuration will be set to "english".
Data page checksums are disabled.
fixing permissions on existing directory /var/lib/pgsql/data/userdata ... ok
creating subdirectories ... ok
selecting default max_connections ... 100
selecting default shared_buffers ... 128MB
selecting default timezone ... UTC
selecting dynamic shared memory implementation ... posix
creating configuration files ... ok
running bootstrap script ... ok
performing post-bootstrap initialization ... ok
WARNING: enabling "trust" authentication for local connections
You can change this by editing pg_hba.conf or using the option -A, or
--auth-local and --auth-host, the next time you run initdb.
syncing data to disk ... ok
Success. You can now start the database server using:
    pg_ctl -D /var/lib/pgsql/data/userdata -l logfile start
waiting for server to start....2023-08-31 02:42:37.105 UTC [37] LOG:  listening on Unix socket "/var/run/postgresql/.s.PGSQL.5432"
2023-08-31 02:42:37.116 UTC [37] LOG:  listening on Unix socket "/tmp/.s.PGSQL.5432"
2023-08-31 02:42:37.137 UTC [37] LOG:  redirecting log output to logging collector process
2023-08-31 02:42:37.137 UTC [37] HINT:  Future log output will appear in directory "log".
 done
server started
/var/run/postgresql:5432 - accepting connections
=> sourcing /usr/share/container-scripts/postgresql/start/set_passwords.sh ...
ALTER ROLE
ALTER ROLE
waiting for server to shut down.... done
server stopped
Starting server...
2023-08-31 02:42:37.586 UTC [1] LOG:  listening on IPv4 address "0.0.0.0", port 5432
2023-08-31 02:42:37.586 UTC [1] LOG:  listening on IPv6 address "::", port 5432
2023-08-31 02:42:37.591 UTC [1] LOG:  listening on Unix socket "/var/run/postgresql/.s.PGSQL.5432"
2023-08-31 02:42:37.596 UTC [1] LOG:  listening on Unix socket "/tmp/.s.PGSQL.5432"
2023-08-31 02:42:37.601 UTC [1] LOG:  redirecting log output to logging collector process
2023-08-31 02:42:37.601 UTC [1] HINT:  Future log output will appear in directory "log".
9bc22f02e1816b3d6df0304949d3c854dfd8f3d7d51f8d53cf42df6fc4baca0a
Stopping and removing container e880f2cb2806f430e9c4168a50bf1e70eebed84b0cd9cf4ba8f471bb39dee808...

Reproducer

No response

[zmiklank]

From the logs and from the code of the test it seems, that the container is behaving like it should. Seems like false positive, but needs further analysis.

 # try loggin in as a user that does not exist to trigger an error log message
  echo 'psql -U nonexistent' | docker exec -i $(get_cid "$name") bash || :
...
  if docker logs $(get_cid "$name") 2>&1 | grep -q 'FATAL:  role "nonexistent" does not exist' ; then
    ...
  else
    echo "ERROR: the container log does not include expected error message"
    return 1
  fi

[phracek]

See error log from Fedora nightly build machine:

-----------------------------------------------
Running test run_logging_test (starting at 2024-08-06 09:36:18-04:00) ...
-----------------------------------------------
c44f9b40e25164f2bfd6584d50f3465992a07522e1cc8ef1015d9df52c91cdb1
Created container c44f9b40e25164f2bfd6584d50f3465992a07522e1cc8ef1015d9df52c91cdb1
Error: can only start exec sessions when their container is running: container state improper
Error: can only create exec sessions on running containers: container state improper
Error: can only create exec sessions on running containers: container state improper
Error: can only create exec sessions on running containers: container state improper
Error: can only create exec sessions on running containers: container state improper
Error: can only create exec sessions on running containers: container state improper
Error: can only create exec sessions on running containers: container state improper
Error: can only create exec sessions on running containers: container state improper
Error: can only create exec sessions on running containers: container state improper
Error: can only create exec sessions on running containers: container state improper
Error: can only create exec sessions on running containers: container state improper
Error: can only create exec sessions on running containers: container state improper
Error: can only create exec sessions on running containers: container state improper