Thank you for your donation!


Cloudsmith graciously provides open-source package management and distribution for our project.


Problem: /var/log/auth.log flooded
#1
Hi!
Today i've find out that /var/log/auth.log is flooded with he following message:
.
.
Jul  7 19:51:47 moode sudo:     root : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/usr/sbin/alsactl store
Jul  7 19:51:47 moode sudo: pam_unix(sudo:session): session opened for user root by (uid=0)
Jul  7 19:51:47 moode sudo: pam_unix(sudo:session): session closed for user root
Jul  7 19:51:50 moode sudo:     root : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/usr/sbin/alsactl store
Jul  7 19:51:50 moode sudo: pam_unix(sudo:session): session opened for user root by (uid=0)
Jul  7 19:51:50 moode sudo: pam_unix(sudo:session): session closed for user root
Jul  7 19:51:53 moode sudo:     root : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/usr/sbin/alsactl store
Jul  7 19:51:53 moode sudo: pam_unix(sudo:session): session opened for user root by (uid=0)
Jul  7 19:51:53 moode sudo: pam_unix(sudo:session): session closed for user root
Jul  7 19:51:56 moode sudo:     root : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/usr/sbin/alsactl store
Jul  7 19:51:56 moode sudo: pam_unix(sudo:session): session opened for user root by (uid=0)
Jul  7 19:51:56 moode sudo: pam_unix(sudo:session): session closed for user root
Jul  7 19:51:59 moode sudo:     root : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/usr/sbin/alsactl store
Jul  7 19:51:59 moode sudo: pam_unix(sudo:session): session opened for user root by (uid=0)
Jul  7 19:51:59 moode sudo: pam_unix(sudo:session): session closed for user root
.
.
As you can see, this repeats every few seconds. It's a fresh install of moode on a RP3. The same message was flooding the latest 6.4 versions too, actually that's why i upgraded to the last one, but i have the same result.
I'm using an external USB DAC
The installation is just running from just 5-6 hours, but /var/log/auth.log is already 600k in size.
Thanks!
Reply
#2
Interesting. It doesn't appear to cause any problems with audio or system performance but I see entries in auth.log for one of my pi's that has Bluetooth enabled.

Maybe someone that knows what this log is for can help out.

Code:
Jul  7 21:10:12 rp2 sudo: pam_unix(sudo:session): session opened for user root by (uid=0)
Jul  7 21:10:13 rp2 sudo: pam_unix(sudo:session): session closed for user root
Jul  7 21:10:16 rp2 sudo:     root : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/usr/bin/pgrep -l bluealsa-aplay
Jul  7 21:10:16 rp2 sudo: pam_unix(sudo:session): session opened for user root by (uid=0)
Jul  7 21:10:16 rp2 sudo: pam_unix(sudo:session): session closed for user root
Jul  7 21:10:19 rp2 sudo:     root : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/usr/bin/pgrep -l bluealsa-aplay
Jul  7 21:10:19 rp2 sudo: pam_unix(sudo:session): session opened for user root by (uid=0)
Jul  7 21:10:19 rp2 sudo: pam_unix(sudo:session): session closed for user root
pi@rp2:~ $ ls -lh /var/log/auth.log
-rw-r----- 1 root adm 435K Jul  7 21:10 /var/log/auth.log
pi@rp2:~ $
Enjoy the Music!
moodeaudio.org | Mastodon Feed | GitHub
Reply
#3
I've never paid any attention to the auth.log. Until this thread I'd certainly not noticed it growing unbounded. Looking now, I see lots of messages like those from the OP relating to alsactl.

Clearly, the PAM subsystem is dutifully logging sudo sessions and actions, of which moOde has a lot. The question is, how to tweak the PAM configuration files to stop this. I never did any security-related sysadm work IRL and don't really grok the PAM subsystem.

Google returned some useful hits when I tried searching on variations of "sudo pam auth log", especially several specifically discussing "sudo" actions flooding the log. I haven't tried any of the nostrums yet.

Regards,
Kent
Reply
#4
In practice, moOde's maintenance task truncates most of the logs every 3 hours. I'm not sure thats really necessary since AFAIK Linux logs are "circular" and only accumulate some number of entries before starting to delete old entries.

If you think about it, if Linux logs accumulated indefinitely then a lot of systems would end up in the deep end of the pool where the Alligators live.
Enjoy the Music!
moodeaudio.org | Mastodon Feed | GitHub
Reply
#5
These are child processes being spawned by a daemon, likely alsa, that is regularly storing alsa's current state to /var/lib/alsa/asound.state.
Nothing to worry about, the alsa state includes audio devices, driver settings, output levels etc.

The logrotate daemon takes care of log growth, you can see that auth.log is one of the system logs rotated by logrotated in the config file /etc/logrotate.d/rsyslog
Reply
#6
(07-08-2020, 12:38 PM)vinnn Wrote: These are child processes being spawned by a daemon, likely alsa, that is regularly storing alsa's current state to /var/lib/alsa/asound.state.
Nothing to worry about, the alsa state includes audio devices, driver settings, output levels etc.

The logrotate daemon takes care of log growth, you can see that auth.log is one of the system logs rotated by logrotated in the config file /etc/logrotate.d/rsyslog

Well, the question is why would alsa do that? I looked on my laptop (running Fedora 32) and I use the soundcard a lot - listening to music, going on live meetings for the job and so on - and I don't see anything alsa related in auth or secure logs.
Reply
#7
moOde's worker daemon executes the code block below every 3 seconds.

Code:
    if ($_SESSION['cardnum'] == '1') { // TEST: experimental usb audio hot-plug mgt
        sysCmd('alsactl store');
    }
Enjoy the Music!
moodeaudio.org | Mastodon Feed | GitHub
Reply
#8
Checked my logs on two RPis and have nothing alsa related in my /var/log/auth.log.

Question for @Nessor: what happens when you unplug your USB DAC? Do you still get those log lines?
Reply
#9
(07-08-2020, 01:57 PM)radu- Wrote:
(07-08-2020, 12:38 PM)vinnn Wrote: These are child processes being spawned by a daemon, likely alsa, that is regularly storing alsa's current state to /var/lib/alsa/asound.state.
Nothing to worry about, the alsa state includes audio devices, driver settings, output levels etc.

The logrotate daemon takes care of log growth, you can see that auth.log is one of the system logs rotated by logrotated in the config file /etc/logrotate.d/rsyslog

Well, the question is why would alsa do that? I looked on my laptop (running Fedora 32) and I use the soundcard a lot - listening to music, going on live meetings for the job and so on - and I don't see anything alsa related in auth or secure logs.

As Tim has shown, it's Moode's code that is regularly executing "alsactl store".

I'll add that on Fedora you wouldn't normally have applications outputting directly to ALSA so ALSA's config and state is less of a consideration (but you can still tweak ALSA with alsamixer).
On a desktop distro like Fedora you'll have PulseAudio that takes the audio output from all your applications and resamples them into one audio stream that is sent to ALSA, this way multiple applications can make noise simultaneously but usually at the detriment of any "bit-perfect"-ness, like how audio stacks work on other operating systems such as Windows, Android and MacOS but PulseAudio is a bit more flexible than those.
Reply
#10
So in summary:
  • moOde is behaving normally in invoking 'sudo alsactrl'
  • the Linux PAM subsystem is behaving normally in logging this event and other events requesting elevated permissions to auth.log
  • auto log-rotation is used to keep the auth.log file (and other log files) from growing forever
  • if it's really annoying on purist grounds, then one can "poke a stick in the eye" of the PAM logging config to prevent it from logging this normal event
Reply


Forum Jump: