Raspiblitz reboot endet im Desaster

Danke für den Tipp. Gemacht. Habe gesehen, dass bei mir eine Stunde zurück ist (also noch Winterzeit). Kann das einen Einfluss haben?

Mein RaspiBlitz ist ja noch v1.7.2, auch wenn ich bitcoind und LND und andere Apps aktuell halte. Gründe dafür spielen jetzt hier keine Rolle.

Ich finde auch bei mir im /var/log Verzeichnis einige Dinge etwas merkwürdig und werde dem, allerdings nur langsam, auf die Spur zu kommen versuchen.

total 4.8G
drwxr-xr-x  2 root       root            4.0K Jul  1  2022 apt
-rw-r-----  1 root       adm             784M Apr 15 12:46 auth.log
drwxr-xr-x  2 root       root            4.0K Apr 15 00:00 cups
-rw-r-----  1 root       adm                0 Mar  7 00:00 daemon.log
-rw-r-----  1 root       adm             2.0G Apr 15 12:46 daemon.log.1
-rw-r-----  1 root       adm                0 Mar  5 00:00 debug
-rw-r-----  1 root       adm             3.4K Apr 15 11:35 debug.1
drwxr-xr-x  3 root       root            4.0K Jan 28  2022 hp
drwxr-sr-x+ 3 root       systemd-journal 4.0K Jan 28  2022 journal
-rw-r-----  1 root       adm              14M Apr 15 12:46 kern.log
drwx--x--x  2 root       root            4.0K Jan 28  2022 lightdm
-rw-r-----  1 root       adm                0 Mar  5 00:00 messages
-rw-r-----  1 root       adm              14M Apr 15 12:46 messages.1
drwxr-s---  2 mysql      adm             4.0K Feb 26  2022 mysql
drwxr-xr-x  2 root       adm             4.0K Apr 15 00:00 nginx
drwxrwxr-t  2 root       postgres        4.0K Mar  5 00:00 postgresql
drwx------  2 root       root            4.0K Jan 28  2022 private
drwxr-s---  2 redis      adm             4.0K Mar  5 00:00 redis
drwxr-xr-x  4 root       root            4.0K Feb  8  2022 runit
-rw-r-----  1 root       adm                0 Mar  5 00:00 syslog
-rw-r-----  1 root       adm             2.0G Apr 15 12:46 syslog.1
drwxr-xr-x  2 root       root            4.0K Feb  2  2021 sysstat
drwxr-s---  2 debian-tor adm             4.0K Feb  8  2022 tor
-rw-r-----  1 root       adm                0 Mar  5 00:00 ufw.log
-rw-r-----  1 root       adm              14M Apr 15 12:46 ufw.log.1
-rw-r-----  1 root       adm                0 Mar  5 00:00 user.log
-rw-r-----  1 root       adm              36K Apr 15 11:35 user.log.1

Die größten Klöpse sind die daemon.log.1 und die syslog.1 mit jeweils so ca. 2GB. Merkwürdig finde ich vorallem, daß nicht in die daemon.log und syslog die aktuellsten Logeinträge reinlaufen, sondern in die eigentlich durch logrotate für „delaycompress“ angelegten Kopien der eigentlichen Logdateien daemon.log.1 und syslog.1. Ich vermute den Fehler hier in den Konfigurationsdateien vom logrotate, da wird eine Rotationseinstellungsoption auch bei mir verkehrt sein!
Meine microSD-Karte ist allerdings 128GB groß, läuft aber trotzdem nicht voll, auch wenn ich meinen RaspiBlitz diesbezüglich über Wochen und Monate nicht anfassen oder bereinigen muss.

Denn auf einem „korrekt“ konfigurierten System sähe das z.B. für syslog so aus:

-rw-r-----   1 syslog    adm       4872820 Apr 15 12:32 syslog
-rw-r-----   1 syslog    adm       1482124 Apr  9 00:00 syslog.1
-rw-r-----   1 syslog    adm        199766 Apr  2 00:00 syslog.2.gz
-rw-r-----   1 syslog    adm        131847 Mär 26 00:00 syslog.3.gz
-rw-r-----   1 syslog    adm        114468 Mär 19 00:00 syslog.4.gz

Hier ist es, wie es sein sollte: aktuelles in syslog; wenn nach einer Woche rotiert wird kopiert logrotate die laufende Logdatei zu syslog.1 (zunächst noch unkomprimiert); bei der nächsten Rotation wird aus syslog.1syslog.2.gz usw.

Auf dem RaspiBlitz ist dagegen syslog immer leer, 0 Byte groß, was möglicherweise logrotate irritiert, während syslog.1 munter vollgeschrieben wird. Da stimmt auch bei mir etwas nicht.

Kürzen kannst du Logdateien (auch aktive) mit folgendem Befehl (gibt mehrere Möglichkeiten, mit dem von mir angegebenen hat man bessere Optionen und Kontrolle, wieviel man ggf. behalten möchte):
sudo truncate -c -s <size> logdateiname
Ich hab auf meinem RaspiBlitz folgendes gemacht: sudo truncate -c -s 1G daemon.log.1 und der hat die dann sofort gekürzt und weiteres Logging läuft normal in diese Datei weiter (dafür sollte auch die Option -c sein, die truncate anweist, keine neuen Dateien zu erstellen, sondern die Kürzung in-place zu machen, dieselbe Datei zu kürzen.
Ergebnis ist dann

-rw-r-----  1 root       adm             1.1G Apr 15 13:17 daemon.log.1

Das Problem bei dir und mir wird wohl sein, daß logrotate nicht so richtig seinen Job machen kann. Ich hab’ weniger LND-Kanäle wie du und mein lokaler mempool.space ist auch DEGUG geschwätzig. Das bräuchte ich auch nicht und werde mir mal bei Gelegenheit ansehen, wie und wo man das abstellen kann. Sehr wahrscheinlich in einer Konfigurationsdatei vom mempool.space.

Protokollierung unter Linux ist eine Wissenschaft für sich und bei einem PI sicherlich noch etwas schlimmer. Man könnte mal ein logrotate manuell auslösen.

sudo logrotate --force /etc/logrotate.d/rsyslog

Ob es bei einem PI funkt. keine Ahnung.

danke. Habe es so gemacht und alle Log-Dateien sogar auf 10M reduziert. Dennoch ist dev/root noch ziemlich voll. Muss wohl auch noch an etwas anderem liegen.

Any ideas?

Ich glaube nicht, daß der Electrum Server das Problem ist. Der labert zwar auch, aber lange nicht so viel wie mempool.space. mempool.space braucht auch den electrs.
Mit über 24+ Kanälen wird dein LND ziemlich viel zu loggen haben, dann auch getriggert durch LNDg bzw. der loggt ja auch lustig vor sich hin (ist auch nicht verkehrt).

Wir müssen das Problem lösen, daß die Log-Rotation nicht richtig arbeitet. Bei logrotate hätte man auch die Möglichkeit eine Maximalgröße der Logdatei als Rotationstrigger zu definieren bzw. sogar Zeit und Größe gemeinsam, je nachdem, was zuerst auslöst.
Dazu muss aber das Logging und die Log-Rotation richtig arbeiten und nicht das aktuelle loggen in die *.1 laufen.

17G finde ich jetzt nicht viel, wie sieht es bei dir @Cricktor aus?

Was ergibt folgender Befehl bei dir? sudo du -x -d 1 -h /

admin@192.168.178.119:/var/log  sudo du -x -d 1 -h /
120K	/tmp
7.5M	/etc
3.9G	/usr
16K	/lost+found
8.0K	/mnt
87M	/root
12K	/opt
5.0G	/var
5.1G	/home
4.0K	/srv
4.0K	/media
15G	/

Sieht ja in etwas wie bei @Saia21 aus 15G zu 17G

Hier könnte mal mit

sudo journalctl -u logrotate

schauen, ob logrotate Fehler wirft.

Ja, finde ich auch, ich hab’ nur mehr Spielraum auf /dev/root, dafür muss ich mal auf meiner SSD etwas aufräumen…

admin@192.168.178.119:/var/log  df
Filesystem     1K-blocks      Used Available Use% Mounted on
/dev/root      122756868  14732652 103001092  13% /
devtmpfs         3990876         0   3990876   0% /dev
tmpfs            4025532        16   4025516   1% /dev/shm
tmpfs            1610216       772   1609444   1% /run
tmpfs               5120         0      5120   0% /run/lock
tmpfs              32768         4     32764   1% /var/cache/raspiblitz
/dev/mmcblk0p1    258095     30823    227272  12% /boot
/dev/sda1      960379920 746252800 165272696  82% /mnt/hdd
tmpfs             805104        20    805084   1% /run/user/1000
tmpfs             805104        20    805084   1% /run/user/1001

Bei mir nicht…

admin@192.168.178.119:~  sudo journalctl -u logrotate
-- Journal begins at Sat 2023-04-15 01:34:05 CEST, ends at Sat 2023-04-15 13:53:52 CEST. --
-- No entries --
admin@192.168.178.119:~  

Aber das hilft hier auch nicht wirklich weiter, wenn das journal erst heute Nacht angefangen hat.

Das sieht merkwürdig aus, bei mir reicht es viel weiter zurück:

-- Boot 70fc4fa0a1f1428aa006c212a45a121f --
Apr 09 07:56:46 ComputerName systemd[1]: Starting Rotate log files...
Apr 09 07:56:47 ComputerName systemd[1]: logrotate.service: Deactivated successfully.
Apr 09 07:56:47 ComputerName systemd[1]: Finished Rotate log files.
-- Boot 6e2d1284b3754eeea54ce1838b0eaa2a --
Apr 10 08:05:04 ComputerName systemd[1]: Starting Rotate log files...
Apr 10 08:05:05 ComputerName systemd[1]: logrotate.service: Deactivated successfully.
Apr 10 08:05:05 ComputerName systemd[1]: Finished Rotate log files.
-- Boot 53aa6836daa647148bd6384f8b5c2944 --
Apr 11 07:56:22 ComputerName systemd[1]: Starting Rotate log files...
Apr 11 07:56:23 ComputerName systemd[1]: logrotate.service: Deactivated successfully.
Apr 11 07:56:23 ComputerName systemd[1]: Finished Rotate log files.
-- Boot 5cbc3a5bd47b4845aa2eecadf0d383af --
Apr 12 07:52:53 ComputerName systemd[1]: Starting Rotate log files...
Apr 12 07:52:54 ComputerName systemd[1]: logrotate.service: Deactivated successfully.
Apr 12 07:52:54 ComputerName systemd[1]: Finished Rotate log files.
-- Boot 17542222bb064c079c8bd330b19dfed8 --
Apr 13 06:38:52 ComputerName systemd[1]: Starting Rotate log files...
Apr 13 06:38:53 ComputerName systemd[1]: logrotate.service: Deactivated successfully.
Apr 13 06:38:53 ComputerName systemd[1]: Finished Rotate log files.
-- Boot 38a7216b854945ae9fe0538c38caff5b --
Apr 14 06:39:52 ComputerName systemd[1]: Starting Rotate log files...
Apr 14 06:39:53 ComputerName systemd[1]: logrotate.service: Deactivated successfully.
Apr 14 06:39:53 ComputerName systemd[1]: Finished Rotate log files.
-- Boot 4f31e03fab574f8089cf2c5de87496ab --
Apr 15 08:49:06 ComputerName systemd[1]: Starting Rotate log files...
Apr 15 08:49:07 ComputerName systemd[1]: logrotate.service: Deactivated successfully.
Apr 15 08:49:07 ComputerName systemd[1]: Finished Rotate log files.

Das logrotate-Journal auf meinem Ubuntu-Desktop reicht bis zum Juni 2022 zurück. Bräuchte ich zwar nicht, aber frisst ja kaum Brot.

Ich sehe auch Unterschiede in der /etc/logrotate.d/rsyslog zw. RaspiBlitz und meinem Ubuntu Desktop. Muss mich aber auch erstmal durch ein paar man-Pages wühlen. Auch was beim postrotate-Script aufgerufen wird, ist unterschiedlich, aber das kann auch am Unterschied von RasbianOS und Ubuntu LTS 22.04 liegen.

Desktop und Server sieht bei mir gleich aus: 22.04 LTS

/var/log/syslog
/var/log/mail.info
/var/log/mail.warn
/var/log/mail.err
/var/log/mail.log
/var/log/daemon.log
/var/log/kern.log
/var/log/auth.log
/var/log/user.log
/var/log/lpr.log
/var/log/cron.log
/var/log/debug
/var/log/messages
{
	rotate 4
	weekly
	missingok
	notifempty
	compress
	delaycompress
	sharedscripts
	postrotate
		/usr/lib/rsyslog/rsyslog-rotate
	endscript
}

Erwartungsgemäß bei mir genauso für den Ubuntu Desktop 22.04 LTS, den ich diesbzgl. auch nicht angepasst habe.

Bei meinem RaspiBlitz steht folgendes in der /etc/logrotate.d/rsyslog:

/var/log/syslog
{
        rotate 7
        daily
        missingok
        notifempty
        delaycompress
  compress
  postrotate
    invoke-rc.d rsyslog rotate > /dev/null
  endscript
}

/var/log/mail.info
/var/log/mail.warn
/var/log/mail.err
/var/log/mail.log
/var/log/daemon.log
{
  rotate 4
  size=100M
  missingok
  notifempty
  compress
  delaycompress
  sharedscripts
  postrotate
    invoke-rc.d rsyslog rotate > /dev/null
  enscript
}


/var/log/kern.log
/var/log/auth.log
{
        rotate 4
        size=100M
        missingok
        notifempty
        compress
        delaycompress
        sharedscripts
        postrotate
                invoke-rc.d rsyslog rotate > /dev/null
        endscript
}

/var/log/user.log
/var/log/lpr.log
/var/log/cron.log
/var/log/debug
/var/log/messages
{
        rotate 4
        weekly
        missingok
        notifempty
        compress
        delaycompress
        sharedscripts
        postrotate
                invoke-rc.d rsyslog rotate > /dev/null
        endscript
}

Die Problem-Option ist auf jeden Fall schon mal notifempty, die bei einer leeren Ausgangsdatei dazu führt, daß logrotate garnix macht.

Jetzt muss ich nur rausfinden, warum bei mir und @Saia21 z.B. in syslog.1 geschnattert wird, anstatt in syslog, wie es eigentlich sein sollte. Denn dann würde logrotate seinen Job machen können. Weird!!

1 „Gefällt mir“

So siehts bei mir aus:

Cricktor und ich sitzen im selben Boot. :slight_smile:

/home ist bei dir fast doppelt so viel wie auf meinem RaspiBlitz. Aber erstmal nicht alarmierend, außer es wächst auch stetig. Dann müsste man nachsehen, warum bzw. was da wächst.

Bei mir:

admin@192.168.178.119:~  sudo du -x -d 1 -h /home
56K	/home/lit
35M	/home/pi
107M	/home/root
455M	/home/bos
655M	/home/bitcoin
412M	/home/admin
143M	/home/btcrpcexplorer
19M	/home/fulcrum
1.3G	/home/thunderhub
1.3G	/home/mempool
899M	/home/rtl
5.1G	/home
admin@192.168.178.119:~  

Ich bin noch bei der Analyse, warum unser logrotate nicht richtig arbeitet. Lösung ist in Sicht, sehr wahrscheinlich.

Es bleibt spannend. Danke euch.

Auf meinem RaspiBlitz habe ich folgende globalen Optionen in der /etc/logrotate.conf, die dann noch durch die individuellen Dateien in /etc/logrotate.d/* ergänzt bzw. präzisiert werden:

# see "man logrotate" for details
# global options do not affect preceding include directives
# rotate log files daily
daily

# keep 14 copies worth of backlogs
rotate 14

# create new (empty) log files after rotating old ones
create

# use date as a suffix of the rotated file
#dateext

# uncomment this if you want your log files compressed
compress

# packages drop log rotation information into this directory
include /etc/logrotate.d

# system-specific logs may also be configured here.

Ich werde bei mir dort create durch copytruncate ersetzen und logrotate und den rsyslog dann neustarten. Mal sehen, ob’s das war. Beim RaspiBlitz scheint der rsyslog die erste Rotation nicht richtig zu verdauen und loggt dann im umbenannten .1-Dateilog weiter, anstatt über das postrotate-Script die nach Rotation neu erstellte Logdatei zu verwenden. Irgendwas ist da Murks…

P.S.
Sieht erstmal auf den ersten Blick OK aus mit create → copytruncate in der /etc/logrotate.conf, muss aber eine Log-Rotation abwarten, die unter normalen System-Umständen gemacht wird.