[Date Prev][Date Next] [Thread Prev][Thread Next] [Date Index] [Thread Index]

systemd & postgresql - flooding system log

Hi,
I'm running Debian server hosting Request Tracker with Postgresql as
database back-end. There is also gnupg-agent & dirmngr installed
(because of SMIME/GPG mail support). Systemd logs about starting user
sessions and Postgresql for some reason starts user sessions internally
frequently. This is the result of upgrade from Jessie to Stretch on
syslog size:

  rt2:/etc/systemd# ll /var/log/syslog-2017* |tail
  -rw-r----- 1 root adm     8058 Jun 28 06:25 /var/log/syslog-20170628.gz
  -rw-r----- 1 root adm     7967 Jun 29 06:25 /var/log/syslog-20170629.gz
  -rw-r----- 1 root adm  2537880 Jun 30 06:25 /var/log/syslog-20170630.gz
  -rw-r----- 1 root adm  3111373 Jul  1 06:26 /var/log/syslog-20170701.gz
  -rw-r----- 1 root adm  3265502 Jul  2 06:26 /var/log/syslog-20170702.gz
  -rw-r----- 1 root adm  3264072 Jul  3 06:26 /var/log/syslog-20170703.gz
  -rw-r----- 1 root adm  3241260 Jul  4 06:26 /var/log/syslog-20170704.gz
  -rw-r----- 1 root adm  3255989 Jul  5 06:26 /var/log/syslog-20170705.gz
  -rw-r----- 1 root adm  3256939 Jul  6 06:26 /var/log/syslog-20170706.gz
  -rw-r----- 1 root adm 63687210 Jul  7 06:26 /var/log/syslog-20170707

I did upgrade on Jun 30...

The system log was full of 

  Jul  6 06:26:33 rt2 liblogging-stdlog:  [origin software="rsyslogd" swVersion="8.24.0" x-pid="406" x-info
  ="http://www.rsyslog.com";] rsyslogd was HUPed
  Jul  6 06:26:36 rt2 systemd[1]: Created slice User Slice of postgres.
  Jul  6 06:26:36 rt2 systemd[1]: Starting User Manager for UID 109...
  Jul  6 06:26:36 rt2 systemd[1]: Started Session c146966 of user postgres.
  Jul  6 06:26:36 rt2 systemd[1860]: Listening on GnuPG cryptographic agent and passphrase cache (restricte
  d).
  Jul  6 06:26:36 rt2 systemd[1860]: Listening on GnuPG cryptographic agent (access for web browsers).
  Jul  6 06:26:36 rt2 systemd[1860]: Listening on GnuPG cryptographic agent (ssh-agent emulation).
  Jul  6 06:26:36 rt2 systemd[1860]: Listening on GnuPG network certificate management daemon.
  Jul  6 06:26:36 rt2 systemd[1860]: Reached target Paths.
  Jul  6 06:26:36 rt2 systemd[1860]: Reached target Timers.
  Jul  6 06:26:36 rt2 systemd[1860]: Listening on GnuPG cryptographic agent and passphrase cache.
  Jul  6 06:26:36 rt2 systemd[1860]: Reached target Sockets.
  Jul  6 06:26:36 rt2 systemd[1860]: Reached target Basic System.
  Jul  6 06:26:36 rt2 systemd[1860]: Reached target Default.
  Jul  6 06:26:36 rt2 systemd[1860]: Startup finished in 11ms.
  Jul  6 06:26:36 rt2 systemd[1]: Started User Manager for UID 109.
  Jul  6 06:26:36 rt2 systemd[1]: Stopping User Manager for UID 109...
  Jul  6 06:26:36 rt2 systemd[1860]: Stopped target Default.
  Jul  6 06:26:36 rt2 systemd[1860]: Stopped target Basic System.
  Jul  6 06:26:36 rt2 systemd[1860]: Stopped target Sockets.
  Jul  6 06:26:36 rt2 systemd[1860]: Closed GnuPG network certificate management daemon.
  Jul  6 06:26:36 rt2 systemd[1860]: Closed GnuPG cryptographic agent and passphrase cache.
  Jul  6 06:26:36 rt2 systemd[1860]: Closed GnuPG cryptographic agent (access for web browsers).
  Jul  6 06:26:36 rt2 systemd[1860]: Closed GnuPG cryptographic agent and passphrase cache (restricted).
  Jul  6 06:26:36 rt2 systemd[1860]: Closed GnuPG cryptographic agent (ssh-agent emulation).
  Jul  6 06:26:36 rt2 systemd[1860]: Reached target Shutdown.
  Jul  6 06:26:36 rt2 systemd[1860]: Starting Exit the Session...
  Jul  6 06:26:36 rt2 systemd[1860]: Stopped target Paths.
  Jul  6 06:26:36 rt2 systemd[1860]: Stopped target Timers.
  ...

19 user sessions per minute :-/.
I found a bug report
https://bugs.debian.org/cgi-bin/bugreport.cgi?bug=850982

But after disabling gnupg-agent & dirmngs sockets using:

  systemctl --global mask --now dirmngr.socket
  systemctl --global mask --now gpg-agent.service gpg-agent.socket gpg-agent-ssh.socket gpg-agent-extra.socket gpg-agent-browser.socket

I got this

  Jul  7 12:16:36 rt2 systemd[21005]: gpg-agent-ssh.socket: Cannot add dependency job, ignoring: Unit gpg-agent-ssh.socket is masked.
  Jul  7 12:16:36 rt2 systemd[21005]: gpg-agent.socket: Cannot add dependency job, ignoring: Unit gpg-agent.socket is masked.
  Jul  7 12:16:36 rt2 systemd[21005]: gpg-agent-extra.socket: Cannot add dependency job, ignoring: Unit gpg-agent-extra.socket is masked.
  Jul  7 12:16:36 rt2 systemd[21005]: gpg-agent-browser.socket: Cannot add dependency job, ignoring: Unit gpg-agent-browser.socket is masked.
  Jul  7 12:16:36 rt2 systemd[21005]: dirmngr.socket: Cannot add dependency job, ignoring: Unit dirmngr.socket is masked.

instead of info about opening/closing sockets :-/

Finally I tried

  loginctl enable-linger postgres

Now the only thing rest:

  Jul  7 15:42:35 rt2 systemd[1]: Started Session c4504 of user postgres.
  Jul  7 15:42:35 rt2 systemd[1]: Started Session c4505 of user postgres.
  Jul  7 15:42:35 rt2 systemd[1]: Started Session c4506 of user postgres.
  Jul  7 15:42:35 rt2 systemd[1]: Started Session c4507 of user postgres.
  Jul  7 15:42:35 rt2 systemd[1]: Started Session c4508 of user postgres.
  Jul  7 15:42:36 rt2 systemd[1]: Started Session c4509 of user postgres.

Every minute 19 lines of this.

I have Postgresql installed on several machines and every logs to two remote
syslog servers. Why store and transfer over net this cruft.

How I should get rid of this session management the right way? (Besides
switching to SysV init)

https://access.redhat.com/solutions/1564823
    - this seems to me a bit a hack

Switch systemd LogLevel to notice?
(https://www.centos.org/forums/viewtopic.php?t=48785)
    - maybe I will miss something in the future?

Isn't this a problem of Postgresql the user session opened so
frequently?

Regards
-- 
Zito
Reply to: