Nagle nie wiadomo dlaczego i skąd dostaję informację, że niektóre usługi na serwerze odmawiają współpracy z użytkownikami. Po nitce do kłębka okazuje się, że winowajcą jest demon PostgreSQL (patrz poniżej).
# systemctl status postgresql
● postgresql.service - PostgreSQL database server
Loaded: loaded (/usr/lib/systemd/system/postgresql.service; enabled; vendor preset: disabled)
Active: failed (Result: exit-code) since czw 2018-08-16 19:13:20 CEST; 13s ago
Process: 2301 ExecStart=/usr/bin/pg_ctl start -D ${PGDATA} -s -o -p ${PGPORT} -w -t 300 (code=exited, status=1/FAILURE)
Process: 2294 ExecStartPre=/usr/bin/postgresql-check-db-dir ${PGDATA} (code=exited, status=0/SUCCESS)
sie 16 19:13:19 mx.bit.sos.pl systemd[1]: Starting PostgreSQL database server...
sie 16 19:13:19 mx.bit.sos.pl pg_ctl[2301]: postgres: nie udało się znaleźć systemu bazy danych sie 16 19:13:19 mx.bit.sos.pl pg_ctl[2301]: Powinien był znajdować się w folderze "/var/lib/pgsql/data",
sie 16 19:13:19 mx.bit.sos.pl pg_ctl[2301]: ale nie udało się otworzyć pliku "/var/lib/pgsql/data/global/pg_control": Brak dostępu sie 16 19:13:20 mx.bit.sos.pl pg_ctl[2301]: pg_ctl: Nie udało się uruchomić serwera sie 16 19:13:20 mx.bit.sos.pl systemd[1]: postgresql.service: control process exited, code=exited status=1 sie 16 19:13:20 mx.bit.sos.pl systemd[1]: Failed to start PostgreSQL database server.
sie 16 19:13:20 mx.bit.sos.pl systemd[1]: Unit postgresql.service entered failed state.
sie 16 19:13:20 mx.bit.sos.pl systemd[1]: postgresql.service failed.
W pliku /var/lib/messages znajdujemy więcej szczegółów na temat problemu:
Aug 16 18:55:59 mx pg_ctl: postgres: nie udało się znaleźć systemu bazy danych
Aug 16 18:55:59 mx kernel: type=1400 audit(1534438559.787:236): avc: denied { read } for pid=1956 comm="postgres" name="pg_control" dev="sda3" ino=66396 scontext=system_u:system_r:postgresql_t:s0 tcontext=system_u:object_r:unlabeled_t:s0 tclass=file
Aug 16 18:55:59 mx kernel: type=1300 audit(1534438559.787:236): arch=c000003e syscall=2 success=no exit=-13 a0=7ffe69f54900 a1=0 a2=1b6 a3=24 items=0 ppid=1954 pid=1956 auid=4294967295 uid=26 gid=26 euid=26 suid=26 fsuid=26 egid=26 sgid=26 fsgid=26 tty=(none) ses=4294967295 comm="postgres" exe="/usr/bin/postgres" subj=system_u:system_r:postgresql_t:s0 key=(null)
Aug 16 18:56:00 mx kernel: type=1130 audit(1534438560.719:237): pid=1 uid=0 auid=4294967295 ses=4294967295 subj=system_u:system_r:init_t:s0 msg='unit=postgresql comm="systemd" exe="/usr/lib/systemd/systemd" hostname=? addr=? terminal=? res=failed'
Aug 16 18:56:00 mx systemd: postgresql.service: control process exited, code=exited status=1 Aug 16 18:56:00 mx systemd: Unit postgresql.service entered failed state.
Aug 16 18:56:00 mx systemd: postgresql.service failed.
Wskazują one, że to kontrola dostępu SELINUX zablokowała nie tylko działanie, ale też i uruchomienie się serwera baz danych PostgrSQL. Logicznym jest więc, że po więcej szczegółów uderzamy do logów SELINUX-a (/var/log/audit/audit.log).
# grep postgre /var/log/audit/audit.log
type=SERVICE_START msg=audit(1534430125.204:84430): pid=1 uid=0 auid=4294967295 ses=4294967295 subj=system_u:system_r:init_t:s0 msg='unit=postgresql comm="systemd" exe="/usr/lib/systemd/systemd" hostname=? addr=? terminal=? res=success'
type=SERVICE_STOP msg=audit(1534430125.204:84431): pid=1 uid=0 auid=4294967295 ses=4294967295 subj=system_u:system_r:init_t:s0 msg='unit=postgresql comm="systemd" exe="/usr/lib/systemd/systemd" hostname=? addr=? terminal=? res=success'
I tu przeżyłem ogólne zdziwienie. SELINUX jak widać twierdzi, że wszystko jest OK. Po głębszym zastanowieniu stwierdziłem, że albo PostgreSQL źle współpracuje z zasadami zabezpieczeń, albo system zabezpieczeń zgłupiał i zabrania dostępu dla serwera baz danych do jego plików (zapomniałem wspomnieć na samy początku, że oczywiście sprawdziłem fizycznie z poziomu root-a istnienie plików, ich wielkość, daty itd). Wykonanie komendy:
# restorecon -R -v /var/lib
restorecon reset /var/lib/pgsql/data/pg_xlog/000000010000000000000001 context system_u:object_r:unlabeled_t:s0->system_u:object_r:postgresql_db_t:s0
restorecon reset /var/lib/pgsql/data/global/pg_control context system_u:object_r:unlabeled_t:s0->system_u:object_r:postgresql_db_t:s0
restorecon reset /var/lib/pgsql/data/pg_clog/0000 context system_u:object_r:unlabeled_t:s0->system_u:object_r:postgresql_db_t:s0 restorecon reset /var/lib/pgsql/data/pg_multixact/offsets/0000 context system_u:object_r:unlabeled_t:s0->system_u:object_r:postgresql_db_t:s0
potwierdziło tezę, że to SELINUX zablokował Postgresa.
# systemctl status postgresql
● postgresql.service - PostgreSQL database server
Loaded: loaded (/usr/lib/systemd/system/postgresql.service; enabled; vendor preset: disabled)
Active: active (running) since czw 2018-08-16 19:20:03 CEST; 39s ago
Process: 1392 ExecStart=/usr/bin/pg_ctl start -D ${PGDATA} -s -o -p ${PGPORT} -w -t 300 (code=exited, status=0/SUCCESS)
Process: 1379 ExecStartPre=/usr/bin/postgresql-check-db-dir ${PGDATA} (code=exited, status=0/SUCCESS)
Main PID: 1439 (postgres)
CGroup: /system.slice/postgresql.service
├─1439 /usr/bin/postgres -D /var/lib/pgsql/data -p 11111
├─1476 postgres: logger process
├─1480 postgres: checkpointer process
├─1481 postgres: writer process
├─1482 postgres: wal writer process
├─1483 postgres: autovacuum launcher process
├─1484 postgres: stats collector process
├─1723 postgres: mail courier 127.0.0.1(51390) idle
└─1841 postgres: mail courier 127.0.0.1(51406) idle
sie 16 19:20:01 mx.bit.sos.pl systemd[1]: Starting PostgreSQL database server...
Niby sukces. ale dlaczego ni stąd, ni zowąd zaczęło się to od:
# grep postgre /var/log/messages
Aug 16 16:36:07 mx kernel: type=1400 audit(1534430167.959:175): avc: denied { read } for pid=1436 comm="postgres" name="pg_control" dev="sda3" ino=66396 scontext=system_u:system_r:postgresql_t:s0 tcontext=system_u:object_r:unlabeled_t:s0 tclass=file
Aug 16 16:36:07 mx kernel: type=1300 audit(1534430167.959:175): arch=c000003e syscall=2 success=no exit=-13 a0=7ffdef1c5950 a1=0 a2=1b6 a3=24 items=0 ppid=1386 pid=1436 auid=4294967295 uid=26 gid=26 euid=26 suid=26 fsuid=26 egid=26 sgid=26 fsgid=26 tty=(none) ses=4294967295 comm="postgres" exe="/usr/bin/postgres" subj=system_u:system_r:postgresql_t:s0 key=(null)
Aug 16 16:36:07 mx pg_ctl: postgres: nie udało się znaleźć systemu bazy danych Aug 16 16:36:08 mx systemd: postgresql.service: control process exited, code=exited status=1 Aug 16 16:36:08 mx kernel: type=1130 audit(1534430168.658:178): pid=1 uid=0 auid=4294967295 ses=4294967295 subj=system_u:system_r:init_t:s0 msg='unit=postgresql comm="systemd" exe="/usr/lib/systemd/systemd" hostname=? addr=? terminal=? res=failed'
Aug 16 16:36:08 mx systemd: Unit postgresql.service entered failed state.
Aug 16 16:36:08 mx systemd: postgresql.service failed.
# grep 16:3 /var/log/secure
Aug 16 16:35:17 mx login: pam_securetty(login:auth): access denied: tty 'tty1' is not secure !
Aug 16 16:35:17 mx login: pam_faillock(login:auth): User unknown
Aug 16 16:35:19 mx login: pam_unix(login:auth): check pass; user unknown Aug 16 16:35:19 mx login: pam_unix(login:auth): authentication failure; logname=LOGIN uid=0 euid=0 tty=tty1 ruser= rhost=
Aug 16 16:35:21 mx login: FAILED LOGIN 1 FROM tty1 FOR (unknown), User not known to the underlying authentication module
Aug 16 16:35:58 mx polkitd[959]: Loading rules from directory /etc/polkit-1/rules.d Aug 16 16:35:58 mx polkitd[959]: Loading rules from directory /usr/share/polkit-1/rules.d
Aug 16 16:35:58 mx polkitd[959]: Finished loading, compiling and executing 2 rules Aug 16 16:35:58 mx polkitd[959]: Acquired the name org.freedesktop.PolicyKit1 on the system bus
pozostaje kwestią otwartą i w efekcie nie daje radości uzmysławiając mi po raz kolejny mą małość w stosunku do potęgi wiedzy, jaką udało się skumulowanej w systemie LINUX zaledwie jednemu pokoleniu ludzi olśnionych wizjią wolnego oprogramowania.