Log fills the 25G of /dev/root killing the sound play (was: No more sound (any zone any input) except for /announce)

mpo · August 23, 2022, 5:30pm

could use some help to debug / revive my amplipi

since this morning (no idea about plausible cause) no of my zones are producing any volume

browser-UI allows me to control volume (and looks like all is ok)
but no sound actually plays
and the display on the device shows all volume-bars on zero (or 100% ??)
however - using the /announce endpoint with media==mp3-url I am still assured that sound can be played (all zones through source 3)

things I’ve tried (to no avail)

changing all sorts of zones and input combinations
double checked zones min-max vol settings (never changed them so still -80, 0 defaults)
note: one zone is disabled all others are just operational
checking up on the zones section in the status json I curl-GET from /api ==> vol_f shows actual values (changing as I modify through the UI)
reset through the UI (cogwheel > config and reset > reset)
reboot through ssh pi@amplipi (using displayed password)
using ssh to check if network access and dns are operational (ping 1.1.1.1; nc -zv google.com 80; host www.google.com) they all are

so am a bit at loss here

any tips / suggestions?

log files I can check
command sequences I could try?
anything?

more context:

upgraded to 0.1.8 without issues roughly one week ago
been using the device normally since
up until this morning ¯_(ツ)_/¯
I do have an own service that hooks my doorbell to an announce (which is still working)

mpo · August 23, 2022, 8:22pm

during another ssh session I see that /dev/root is 100% full I assume this is the root of all my troubles?

pi@amplipi:~/.ssh $ df -h
Filesystem      Size  Used Avail Use% Mounted on
/dev/root        29G   29G     0 100% /
devtmpfs        430M     0  430M   0% /dev
tmpfs           462M   12K  462M   1% /dev/shm
tmpfs           462M  6.3M  456M   2% /run
tmpfs           5.0M  4.0K  5.0M   1% /run/lock
tmpfs           462M     0  462M   0% /sys/fs/cgroup
/dev/mmcblk0p1  253M   49M  204M  20% /boot
tmpfs            93M     0   93M   0% /run/user/1000

digging deeper with du -sh I see 25G is consumed by /var/log → roughly split into 3x 8G for deamon.log daemon.log.1 and syslog

removed daemon.log.1 → sound restored!

think we need a more aggresive logrotate + less elaborate logging → every 2 seconds a line for the /api poll is triggered by open running clients and added to the log

Aug 23 16:20:11 amplipi authbind[808]: INFO:     10.0.100.181:35554 - "GET /api HTTP/1.1" 200 OK
Aug 23 16:20:13 amplipi authbind[808]: INFO:     10.0.100.181:35554 - "GET /api HTTP/1.1" 200 OK
Aug 23 16:20:15 amplipi authbind[808]: INFO:     10.0.100.181:35554 - "GET /api HTTP/1.1" 200 OK
Aug 23 16:20:17 amplipi authbind[808]: INFO:     10.0.100.181:35554 - "GET /api HTTP/1.1" 200 OK
Aug 23 16:20:19 amplipi authbind[808]: INFO:     10.0.100.181:35554 - "GET /api HTTP/1.1" 200 OK

at this speed another 8G will fill up fast …

any suggestions?

linknum23 · August 24, 2022, 1:34pm

Sorry about that! This looks like a journalctl configuration issue. By default newer AmpliPis should no longer log to disk. We need to add a check for this in the install script to fix older installs.

mpo · August 24, 2022, 2:03pm

any quick fix I can apply locally?
I noticed ssh also gives me sudo so I could be vi-tweeking configs all around

linknum23 · August 24, 2022, 2:42pm

Yup:

Edit /etc/systemd/journald.conf with the contents below:

Storage=volatile                                                                                                              
RuntimeMaxUse=64M

This will force journalctl to only use 64MB of ram for logs and not use any disk ever.

We need to reload journalctl’s config:
sudo systemctl restart systemd-journald.service

Noe lets clear out the systemd logs:

Check how much space you are using:
journalctl --disk-usage
Clear out the logs
sudo journalctl --rotate
sudo journalctl --vacuum-time=1s
Check how much space you are using now, it should be almost none:
journalctl --disk-usage

sumnerboy · August 24, 2022, 9:18pm

I have just applied these steps to my problematic AmpliPi to see if it helps.

mpo · August 25, 2022, 7:38am

applied and commands executed → another 8G freed up, looks good!

there still is one 8G /var/log/daemon.log on disk but I suspect logrotate will eventually clean that out over the coming weeks…

thx again for the swift support

linknum23 · August 25, 2022, 1:59pm

How much space were the logs using originally?

linknum23 · August 25, 2022, 2:01pm

Hmm I don’t know why that wasn’t deleted.

linknum23 · August 25, 2022, 4:46pm

Digging in to what is writing to all of these log files a little deeper it looks like reconfiguring journalctl for volatile operation reduced the writing to /var/log/daemon.log but did not eliminate it. Additionally /var/log/syslog was being written by an entirely seperate logging utility called rsyslog.

Since there is no need to double log everything, we can disable the service with:

sudo systemctl stop rsyslog.service
sudo systemctl disable rsyslog.service

However this will not delete any of the previous logs. I attempted to use logrotate to clean up some of the bigger log files but this seems more complicated than it is worth.

For simplicity you might as well just delete the daemon and sys logs:

sudo rm /var/log/daemon* /var/log/syslog*

Note: this was edited to clarify some earlier confusion between daemon.log and syslog files

mpo · August 25, 2022, 8:22pm

thx for the extra folluw up
all commands applied and back to 24G of available space

looking healthy
(and enjoying the sound)

sumnerboy · August 25, 2022, 10:07pm

I just noticed /var/log/user.log is very large and filling up very quickly with;

Aug 26 10:06:32 amplipi authbind[806]: Device or resource busy.
Aug 26 10:06:32 amplipi authbind[806]: [0254ae50] main audio output error: module not functional
Aug 26 10:06:32 amplipi authbind[806]: [7050e258] main decoder error: failed to create audio output
Aug 26 10:06:32 amplipi authbind[806]: [0254ae50] alsa audio output error: cannot open ALSA device "ch0": Device or resource busy
Aug 26 10:06:32 amplipi authbind[806]: [0254ae50] main audio output error: Audio output failed
Aug 26 10:06:32 amplipi authbind[806]: [0254ae50] main audio output error: The audio device "ch0" could not be used:
Aug 26 10:06:32 amplipi authbind[806]: Device or resource busy.
Aug 26 10:06:32 amplipi authbind[806]: [0254ae50] main audio output error: module not functional
Aug 26 10:06:32 amplipi authbind[806]: [7050e258] main decoder error: failed to create audio output
Aug 26 10:06:32 amplipi authbind[806]: [0254ae50] alsa audio output error: cannot open ALSA device "ch0": Device or resource busy
Aug 26 10:06:32 amplipi authbind[806]: [0254ae50] main audio output error: Audio output failed
Aug 26 10:06:32 amplipi authbind[806]: [0254ae50] main audio output error: The audio device "ch0" could not be used:
Aug 26 10:06:32 amplipi authbind[806]: Device or resource busy.
Aug 26 10:06:32 amplipi authbind[806]: [0254ae50] main audio output error: module not functional
Aug 26 10:06:32 amplipi authbind[806]: [7050e258] main decoder error: failed to create audio output
Aug 26 10:06:32 amplipi authbind[806]: [0254ae50] alsa audio output error: cannot open ALSA device "ch0": Device or resource busy
Aug 26 10:06:32 amplipi authbind[806]: [0254ae50] main audio output error: Audio output failed
Aug 26 10:06:32 amplipi authbind[806]: [0254ae50] main audio output error: The audio device "ch0" could not be used:
Aug 26 10:06:32 amplipi authbind[806]: Device or resource busy.
Aug 26 10:06:32 amplipi authbind[806]: [0254ae50] main audio output error: module not functional
Aug 26 10:06:32 amplipi authbind[806]: [7050e258] main decoder error: failed to create audio output
Aug 26 10:06:32 amplipi authbind[806]: [0254ae50] alsa audio output error: cannot open ALSA device "ch0": Device or resource busy
Aug 26 10:06:32 amplipi authbind[806]: [0254ae50] main audio output error: Audio output failed
Aug 26 10:06:32 amplipi authbind[806]: [0254ae50] main audio output error: The audio device "ch0" could not be used:
Aug 26 10:06:32 amplipi authbind[806]: Device or resource busy.
Aug 26 10:06:32 amplipi authbind[806]: [0254ae50] main audio output error: module not functional
Aug 26 10:06:32 amplipi authbind[806]: [7050e258] main decoder error: failed to create audio output

sumnerboy · August 25, 2022, 10:09pm

The same messages are appearing in /var/log/messages and /var/log/syslog which are equally big, and growing

linknum23 · August 26, 2022, 2:18pm

I’ve been testing a script that we are planning on adding to the next update. As far as I can tell it stops most of the logging to disk @sumnerboy, happen to want to try it out?

  # stop and disable the secondary logging utility rsyslog
  sudo systemctl stop rsyslog.service
  sudo systemctl disable rsyslog.service
  # reconfigure journald to only log to RAM
  echo -e "[Journal]\nStorage=volatile\nRuntimeMaxUse=64M\n" | sudo tee /etc/systemd/journald.conf
  sudo systemctl restart systemd-journald.service
  # delete some old logs
  sudo journalctl --rotate
  sudo journalctl --vacuum-time=10m
  sudo rm /var/log/daemon* /var/log/syslog*

Here’s the draft PR its from: Only log to RAM by linknum23 · Pull Request #369 · micro-nova/AmpliPi · GitHub

Edit

I tested it on your 1 spotify and 3 internet radio stations config and didnt see any new logs in messages, user.log, syslog, or daemon.log.

I verified this with:

tail /var/log/user.log /var/log/messages /var/log/syslog /var/log/daemon.log

linknum23 · August 26, 2022, 3:33pm

I got more clarity on this from a post @Lohrer found: Why Journald?

It looks like journald by default forwards messages to rsyslog which was writing the logs to disk even after we told journald not to log to disk. This is why we needed to disabled rsyslog after configuring journald for RAM only logging.

sumnerboy · August 26, 2022, 11:53pm

Ran all these commands, but I am still seeing continuous logging to /var/log/user.log and /var/log/messages (see log I posted above about Audio output failed).

A reboot appears to have stopped the continuous logging, so I have cleared out user.log and messages and rebooted again.

I wonder if whatever is causing those audio output failed log events is the root cause of my issues?

sumnerboy · August 26, 2022, 11:59pm

The only issue with this is my remote logging will no longer work without rsyslog. Hopefully it doesn’t get in a state again where I can’t SSH in.

Ideally we would disable syslogging to disk but still allow rsyslog to run so you can log to remote logging servers.

linknum23 · August 29, 2022, 2:55pm

We can look into a configuration that makes server logging possible. What does your rsyslog configuration look like?

sumnerboy · August 29, 2022, 9:10pm

I am using Ansible to provision the following entry on all my local servers, so they all log everything back to my self-hosted Graylog server;

# Ansible managed
*.* @192.168.10.20:1514;RSYSLOG_SyslogProtocol23Format

This is provisioned in /etc/rsyslog.d/90-graylog.conf by Ansible.

linknum23 · August 31, 2022, 7:08pm

Alright so let’s test this out

Here’s what I think a logfile-less /etc/rsyslog.conf looks like:

# /etc/rsyslog.conf configuration file for rsyslog
#
# For more information install rsyslog-doc and see
# /usr/share/doc/rsyslog-doc/html/configuration/index.html


#################
#### MODULES ####
#################

module(load="imuxsock") # provides support for local system logging
module(load="imklog")   # provides kernel logging support
#module(load="immark")  # provides --MARK-- message capability

# provides UDP syslog reception
#module(load="imudp")
#input(type="imudp" port="514")

# provides TCP syslog reception
#module(load="imtcp")
#input(type="imtcp" port="514")


###########################
#### GLOBAL DIRECTIVES ####
###########################

#
# Use traditional timestamp format.
# To enable high precision timestamps, comment out the following line.
#
$ActionFileDefaultTemplate RSYSLOG_TraditionalFileFormat

#
# Set the default permissions for all log files.
#
$FileOwner root
$FileGroup adm
$FileCreateMode 0640
$DirCreateMode 0755
$Umask 0022

#
# Where to place spool and state files
#
$WorkDirectory /var/spool/rsyslog

#
# Include all config files in /etc/rsyslog.d/
#
$IncludeConfig /etc/rsyslog.d/*.conf


###############
#### RULES ####
###############

# Do almost nothing! We probably don't need any of the old rules :)

# Emergencies are sent to everybody logged in.
#
*.emerg                         :omusrmsg:*

After updating that file, restart rsyslog with the commands below. Does your logging setup work again?

 sudo systemctl enable rsyslog.service
 sudo systemctl start rsyslog.service

NOTE: we may need to add the flag ForwardToSyslog=yes to /etc/systemd/journald.conf and restart journald (sudo systemctl restart systemd-journald.service) but I think this is enabled by default

Topic		Replies	Views
Announce endpoint zone specific Troubleshooting	21	171	July 11, 2024
No sound whatsoever, until physical reboot Troubleshooting	2	192	May 3, 2023
Zone Specific Announce Misbehaving Troubleshooting	25	70	November 17, 2024
Web gui volume control strange behavior Troubleshooting	15	244	December 24, 2023
API Announce is not audible Troubleshooting	5	229	June 15, 2022

Log fills the 25G of /dev/root killing the sound play (was: No more sound (any zone any input) except for /announce)

Edit

Related topics