Groups | Search | Server Info | Keyboard shortcuts | Login | Register [http] [https] [nntp] [nntps]

Groups > linux.debian.user > #183339 > unrolled thread

systemd & postgresql - flooding system log

Back to article view | Back to linux.debian.user

Contents

  systemd & postgresql - flooding system log Václav Ovsík <vaclav.ovsik@gmail.com> - 2017-07-07 16:30 +0200
    Re: systemd & postgresql - flooding system log Michael Biebl <biebl@debian.org> - 2017-07-07 23:00 +0200
      Re: systemd & postgresql - flooding system log Václav Ovsík <vaclav.ovsik@gmail.com> - 2017-07-08 09:40 +0200
        FYI: systemd session logging - no solution Václav Ovsík <vaclav.ovsik@gmail.com> - 2017-07-10 17:10 +0200
          Re: FYI: systemd session logging - no solution Joel Rees <joel.rees@gmail.com> - 2017-07-11 15:30 +0200
          Re: FYI: systemd session logging - no solution Reco <recoverym4n@gmail.com> - 2017-07-12 13:00 +0200
        Re: systemd & postgresql - flooding system log Don Armstrong <don@debian.org> - 2017-07-15 00:30 +0200
          Re: systemd & postgresql - flooding system log Michael Biebl <biebl@debian.org> - 2017-07-15 00:50 +0200
            Re: systemd & postgresql - flooding system log Václav Ovsík <vaclav.ovsik@gmail.com> - 2017-07-16 00:50 +0200
              Re: systemd & postgresql - flooding system log Václav Ovsík <vaclav.ovsik@gmail.com> - 2017-07-16 12:20 +0200
                Re: systemd & postgresql - flooding system log Václav Ovsík <vaclav.ovsik@gmail.com> - 2017-07-16 12:50 +0200
                  Re: systemd & postgresql - flooding system log Don Armstrong <don@debian.org> - 2017-07-16 18:50 +0200
                    Re: systemd & postgresql - flooding system log Erwan David <erwan@rail.eu.org> - 2017-07-16 19:10 +0200
                      Re: systemd & postgresql - flooding system log Don Armstrong <don@debian.org> - 2017-07-17 21:50 +0200
                  Re: systemd & postgresql - flooding system log - SOLUTION Václav Ovsík <vaclav.ovsik@gmail.com> - 2017-07-17 09:10 +0200

#183339 — 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

[toc] | [next] | [standalone]

#183360

[Multipart message — attachments visible in raw view] — view raw

Am 07.07.2017 um 16:03 schrieb Václav Ovsík:

>   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.


You create 19 PAM sessions for the postgres user per minute. What
exactly are you doing here?
-- 
Why is it that all of the instruments seeking intelligent life in the
universe are pointed away from Earth?

[toc] | [prev] | [next] | [standalone]

#183371

On Fri, Jul 07, 2017 at 10:34:20PM +0200, Michael Biebl wrote:
>...
> You create 19 PAM sessions for the postgres user per minute. What
> exactly are you doing here?

This morning refreshed my mind :)
I completely forget about monitoring of the host yesterday.
There was installed plugin for Postgres in CheckMK agent monitoring agent.
http://mathias-kettner.com/checkmk.html
http://git.mathias-kettner.de/git/?p=check_mk.git;a=blob;f=agents/plugins/mk_postgres;h=1de9b6de2d536b5d254888e6188fa3ec8b64c9bc;hb=HEAD
The plugin can be improved the switch to database user will be done only
one time per run probably.
Nevertheless, is there a possibility in systemd to hide user sessions of
this system user?
-- 
Zito

[toc] | [prev] | [next] | [standalone]

#183529 — FYI: systemd session logging - no solution

Lately I found this:
https://github.com/systemd/systemd/issues/1291
so no nice solution unfortunately :(.
-- 
Zito

[toc] | [prev] | [next] | [standalone]

#183560 — Re: FYI: systemd session logging - no solution

On Mon, Jul 10, 2017 at 11:52 PM, Václav Ovsík <vaclav.ovsik@gmail.com> wrote:
> Lately I found this:
> https://github.com/systemd/systemd/issues/1291
> so no nice solution unfortunately :(.
> --
> Zito
>

I want to show that to Poettering's manager.

-- 
Joel Rees

One of these days I'll get someone to pay me
to design a language that combines the best of Forth and C.
Then I'll be able to leap wide instruction sets with a single #ifdef,
run faster than a speeding infinite loop with a #define,
and stop all integer size bugs with my bare cast.
http://defining-computers.blogspot.com/2017/06/reinventing-computers.html

More of my delusions:
http://reiisi.blogspot.com/2017/05/do-not-pay-modern-danegeld-ransomware.html
http://reiisi.blogspot.jp/p/novels-i-am-writing.html

[toc] | [prev] | [next] | [standalone]

#183587 — Re: FYI: systemd session logging - no solution

	Hi.

On Mon, Jul 10, 2017 at 04:52:33PM +0200, Václav Ovsík wrote:
> Lately I found this:
> https://github.com/systemd/systemd/issues/1291
> so no nice solution unfortunately :(.

So you're saying that rsyslog filtering is not nice somehow.
Care to elaborate?

Reco

[toc] | [prev] | [next] | [standalone]

#183699

On Sat, 08 Jul 2017, Václav Ovsík wrote:

> On Fri, Jul 07, 2017 at 10:34:20PM +0200, Michael Biebl wrote:
> >...
> > You create 19 PAM sessions for the postgres user per minute. What
> > exactly are you doing here?
> 
> This morning refreshed my mind :)
> I completely forget about monitoring of the host yesterday.
> There was installed plugin for Postgres in CheckMK agent monitoring agent.
> http://mathias-kettner.com/checkmk.html
> http://git.mathias-kettner.de/git/?p=check_mk.git;a=blob;f=agents/plugins/mk_postgres;h=1de9b6de2d536b5d254888e6188fa3ec8b64c9bc;hb=HEAD
> The plugin can be improved the switch to database user will be done only
> one time per run probably.

This plugin is horribly designed, and runs su - $DBUSER -c [...] for its
functioning.

It should instead just su $DBUSER -c [...]; or better yet, not actually
su to the database user, and instead run as a user which only has the
ability to read the appropriate tables and cannot also write to.

If you fix that so that it doesn't start a login session, you'll fix
the excessive number of sessions created.


-- 
Don Armstrong                      https://www.donarmstrong.com

He no longer wished to be dead. At the same time, it cannot be said
that he was glad to be alive. But at least he did not resent it. He
was alive, and the stubbornness of this fact had little by little
begun to fascinate him -- as if he had managed to outlive himself, as
if he were somehow living a posthumous life.
 -- Paul Auster _City of Glass_

[toc] | [prev] | [next] | [standalone]

#183701

[Multipart message — attachments visible in raw view] — view raw

Am 15.07.2017 um 00:07 schrieb Don Armstrong:
> This plugin is horribly designed, and runs su - $DBUSER -c [...] for its
> functioning.

Indeed.

> It should instead just su $DBUSER -c [...]; or better yet, not actually
> su to the database user, and instead run as a user which only has the
> ability to read the appropriate tables and cannot also write to.

There is an alternative utility called runuser which is more suitable
for such cases.
It uses a different pam config and doesn't start a systemd logind session.

-- 
Why is it that all of the instruments seeking intelligent life in the
universe are pointed away from Earth?

[toc] | [prev] | [next] | [standalone]

#183733

On Fri, Jul 14, 2017 at 05:07:22PM -0500, Don Armstrong wrote:
>... 
> This plugin is horribly designed, and runs su - $DBUSER -c [...] for its
> functioning.
> 
> It should instead just su $DBUSER -c [...]; or better yet, not actually
> su to the database user, and instead run as a user which only has the
> ability to read the appropriate tables and cannot also write to.
> 
> If you fix that so that it doesn't start a login session, you'll fix
> the excessive number of sessions created.

Unfortunately removing `-' didn't helped. 


On Sat, Jul 15, 2017 at 12:30:41AM +0200, Michael Biebl wrote:
> Am 15.07.2017 um 00:07 schrieb Don Armstrong:
> > This plugin is horribly designed, and runs su - $DBUSER -c [...] for its
> > functioning.
> 
> Indeed.
> 
> > It should instead just su $DBUSER -c [...]; or better yet, not actually
> > su to the database user, and instead run as a user which only has the
> > ability to read the appropriate tables and cannot also write to.
> 
> There is an alternative utility called runuser which is more suitable
> for such cases.
> It uses a different pam config and doesn't start a systemd logind session.

Bingo! This helped runuser instead of su.

 su - $DBUSER -c [...] 
    to
 runuser -c [...] $DBUSER

Thanks
-- 
Zito

[toc] | [prev] | [next] | [standalone]

#183734

On Sun, Jul 16, 2017 at 12:32:22AM +0200, Václav Ovsík wrote:
> Bingo! This helped runuser instead of su.
> 
>  su - $DBUSER -c [...] 
>     to
>  runuser -c [...] $DBUSER

OMG, I don't looked into /var/log/auth.log :(

Jul 16 11:57:57 rt2 runuser: pam_unix(runuser:session): session closed for user postgres
Jul 16 11:57:57 rt2 runuser: pam_unix(runuser:session): session opened for user postgres by (uid=0)
Jul 16 11:57:57 rt2 runuser: pam_unix(runuser:session): session closed for user postgres
Jul 16 11:57:57 rt2 runuser: pam_unix(runuser:session): session opened for user postgres by (uid=0)
Jul 16 11:57:57 rt2 runuser: pam_unix(runuser:session): session closed for user postgres

...flooding moved into /var/log/auth.log.

No, I'm going back to LogLevel notice setting of systemd. :(
-- 
Zito

[toc] | [prev] | [next] | [standalone]

#183735

On Sun, Jul 16, 2017 at 12:01:56PM +0200, Václav Ovsík wrote:
> OMG, I don't looked into /var/log/auth.log :(
> 
> Jul 16 11:57:57 rt2 runuser: pam_unix(runuser:session): session closed for user postgres
> Jul 16 11:57:57 rt2 runuser: pam_unix(runuser:session): session opened for user postgres by (uid=0)
> Jul 16 11:57:57 rt2 runuser: pam_unix(runuser:session): session closed for user postgres
> Jul 16 11:57:57 rt2 runuser: pam_unix(runuser:session): session opened for user postgres by (uid=0)
> Jul 16 11:57:57 rt2 runuser: pam_unix(runuser:session): session closed for user postgres
> 
> ...flooding moved into /var/log/auth.log.
> 
> No, I'm going back to LogLevel notice setting of systemd. :(

With su is /var/log/auth.log flooded too, I didn't noticed
before :-/ (logcheck was filtering this). So the last chance is probably
the utility setpriv mentioned in the runuser manpage. Unfortunately the
utility is in the optional package with the same name and must by
installed additionally. I will try tomorrow and write about it.
-- 
Zito

[toc] | [prev] | [next] | [standalone]

#183749

On Sun, 16 Jul 2017, Václav Ovsík wrote:
> On Sun, Jul 16, 2017 at 12:01:56PM +0200, Václav Ovsík wrote:
> > OMG, I don't looked into /var/log/auth.log :(
> > 
> > Jul 16 11:57:57 rt2 runuser: pam_unix(runuser:session): session closed for user postgres
> > Jul 16 11:57:57 rt2 runuser: pam_unix(runuser:session): session opened for user postgres by (uid=0)
> > Jul 16 11:57:57 rt2 runuser: pam_unix(runuser:session): session closed for user postgres
> > Jul 16 11:57:57 rt2 runuser: pam_unix(runuser:session): session opened for user postgres by (uid=0)
> > Jul 16 11:57:57 rt2 runuser: pam_unix(runuser:session): session closed for user postgres
> >
> > No, I'm going back to LogLevel notice setting of systemd. :(

This is not systemd logging this, but pam_unix.so.

> With su is /var/log/auth.log flooded too, I didn't noticed before :-/
> (logcheck was filtering this).

If you don't care about this in your log, then you can either filter it,
or comment out pam_unix in /etc/pam.d/common-session-noninteractive.


-- 
Don Armstrong                      https://www.donarmstrong.com

Religion is religion, however you wrap it, and like Quell says, a
preoccupation with the next world clearly signals an inability to cope
credibly with this one.
 -- Richard K. Morgan "Broken Angels" p65

[toc] | [prev] | [next] | [standalone]

#183750

Le 07/16/17 à 18:32, Don Armstrong a écrit :
> On Sun, 16 Jul 2017, Václav Ovsík wrote:
>> On Sun, Jul 16, 2017 at 12:01:56PM +0200, Václav Ovsík wrote:
>>> OMG, I don't looked into /var/log/auth.log :(
>>>
>>> Jul 16 11:57:57 rt2 runuser: pam_unix(runuser:session): session closed for user postgres
>>> Jul 16 11:57:57 rt2 runuser: pam_unix(runuser:session): session opened for user postgres by (uid=0)
>>> Jul 16 11:57:57 rt2 runuser: pam_unix(runuser:session): session closed for user postgres
>>> Jul 16 11:57:57 rt2 runuser: pam_unix(runuser:session): session opened for user postgres by (uid=0)
>>> Jul 16 11:57:57 rt2 runuser: pam_unix(runuser:session): session closed for user postgres
>>>
>>> No, I'm going back to LogLevel notice setting of systemd. :(
> 
> This is not systemd logging this, but pam_unix.so.
> 
>> With su is /var/log/auth.log flooded too, I didn't noticed before :-/
>> (logcheck was filtering this).
> 
> If you don't care about this in your log, then you can either filter it,
> or comment out pam_unix in /etc/pam.d/common-session-noninteractive.
> 
> 
Commenting it will remove authentication methods ? Following that logic
you could also tell to just stop the machine...

[toc] | [prev] | [next] | [standalone]

#183784

On Sun, 16 Jul 2017, Erwan David wrote:
> Le 07/16/17 à 18:32, Don Armstrong a écrit :
> > If you don't care about this in your log, then you can either filter it,
> > or comment out pam_unix in /etc/pam.d/common-session-noninteractive.
>
> Commenting it will remove authentication methods ?

No. That's a session module, not an auth module. If you comment it out
from /etc/pam.d/common-auth, *then* bad things will happen.

Quoting from pam_unix(8):

  "The session component of this module logs when a user logins or leave the system."

You can read the source yourself, too:

http://sources.debian.net/src/pam/1.1.8-3.6/modules/pam_unix/pam_unix_sess.c/#L99

-- 
Don Armstrong                      https://www.donarmstrong.com

"A one-question geek test. If you get the joke, you're a geek: Seen on
a California license plate on a VW Beetle: 'FEATURE'..."
 -- Joshua D. Wachs - Natural Intelligence, Inc.

[toc] | [prev] | [next] | [standalone]

#183761 — Re: systemd & postgresql - flooding system log - SOLUTION

On Sun, Jul 16, 2017 at 12:32:22PM +0200, Václav Ovsík wrote:
>... 
> With su is /var/log/auth.log flooded too, I didn't noticed
> before :-/ (logcheck was filtering this). So the last chance is probably
> the utility setpriv mentioned in the runuser manpage. Unfortunately the
> utility is in the optional package with the same name and must by
> installed additionally. I will try tomorrow and write about it.

The setpriv is the final solution I hope.
Replacement su by setpriv using the command:
    sed -r 's/su - \$DBUSER -c/setpriv --euid $DBUSER bash -c/g;' 
in the mk_postgres [1] quiets all log messages from pam and systemd.

[1] http://git.mathias-kettner.de/git/?p=check_mk.git;a=blob;f=agents/plugins/mk_postgres;h=1de9b6de2d536b5d254888e6188fa3ec8b64c9bc;hb=HEAD

Cheers
-- 
Zito

[toc] | [prev] | [standalone]

Back to top | Article view | linux.debian.user

csiph-web