Logs füllen SD-Karte voll

[schloessl]

Hallo heckmannju,

hier meine logging.yaml

file:
class: logging.handlers.TimedRotatingFileHandler
formatter: simple
filters: [loggerfilter]
when: midnight
# maxBytes: 104857600
# 100 MB
backupCount: 7
encoding: utf8
filename: ./var/log/smarthome.log
busmonitor_file:
class: logging.handlers.TimedRotatingFileHandler
formatter: busmonitor_format
when: midnight
backupCount: 7
encoding: utf8
filename: ./var/log/knx_busmonitor.log

Der Fehler schlägt nur in großen Abständen zu, bei mir ca. jede 2-3 Wochen. Kann es ein Netztstolperer des Netzanbieters sein?

[heckmannju]

Hi,
zu deinem Probelm warum die logs voll werden kann ich nix sagen. Dein Problem das maxBytes bei dir nicht geht ist das du den logging.handlers.TimedRotatingFileHandler nimmst der kann das nicht du must den
logging.handlers.RotatingFileHandler nehmen der kann das

file:    
    #logging.handlers.RotatingFileHandler(filename, mode='a', maxBytes=0, backupCount=0, encoding=None, delay=False)
    #class: logging.handlers.TimedRotatingFileHandler    
    class: logging.handlers.RotatingFileHandler    
    formatter: simple    
    filters: [loggerfilter]    
    maxBytes: 10480    
    #when: midnight    
    backupCount: 7    
    encoding: utf8    
    filename: ./var/log/smarthome.log

VG Jürgen

[schloessl]

Hallo Jürgen,
danke für Deinen Hinweis.
Ich habe die logging.yaml einmal mit dem logging.handlers.RotatingFileHandler versorgt.
Schauen wir einmal was herauskommt.

Den
logging.handlers.TimedRotatingFileHandler hatte ich von bmx #23 weiter oben übernommen. Wahrscheinlich lebt er in einer anderen Systemumwelt

VG Wolfgang

[ic14m001]

Hab jetzt auch mal den RICHTIGEN ( class: logging.handlers.RotatingFileHandler) Handler in der logging.yaml eingstellt - mal schauen, was passiert, wenn der Fehler wieder auftritt; Grundsätzlich sollte es zwar so sein, dass die Logs den Speicher nicht mehr vollschreiben können, jedoch erwarte ich eine "Fehlerschleife", sprich dass smarthomeng immer weiter den Fehler in die Logs schreibt und die Systemleistung in die Knie geht - ich lass mich mal überraschen ....

Wenn ich die Beiträge durchschaue, dürfte es doch mehrere User mit der gleichen Problematik geben - nur keine Lösung ;-)

[mumpf]

Hi,

Du hast vollkommen recht! Die Änderung der Logging-Einstellungen bekämpft nur das Symptom, nicht die Ursache. Mit dem netten Nebeneffekt, dass - falls man nicht merkt, dass das Problem aktuell existiert - die SD-Karte potentiell "kaputtgeschrieben" wird, da ja dauernd Daten geschrieben und gelöscht werden.

Eine Lösung kann es nur geben, wenn man die Ursache findet. Wenn man also herausfindet, um was für einen Dateideskriptor es sich handelt. Das können aber nur die Leute machen, bei denen das Problem auftritt. Wenn man die Ursache für das Problem weiß, können die shNG.py-Entwickler auch eine Lösung entwickeln.

Gruß, Waldemar

[heckmannju]

Hi,

welche plugins hat ihr den alle im einsatz auf den Rechnern wo das auftritt?

VG
Jürgen

[Lonie]

Bei mir laufen die folgenden Plugins wobei der knxd aktuell am dauerneustart ist da der IP Router nicht erreicht werden kann (Testaufbau).

BackendServer:
knx:
visu:
smartvisu:
cli:
uzsu:
database:
ical:
telegram:
Sonos:
smarttv:

[ic14m001]

Also ich habe 2 Stück RPi's 3 Model B mit dem Standardimage von Onkelandy (auf Letztstand 1.4.2) im Einsatz; einer hat OneWire mit DummySensoren aktiviert, der andere läuft noch ohne Anpassungen im Leerlauf ..... Einzig hab ich auf beiden die Bluetooth-Schnittstelle deaktiviert, da es hier lauf Forumseinträgen zu Verzögerungen kommen soll, wenn knxd zum Einsatz kommt ...

Unbenannt.jpg
Grüße
David

[heckmannju]

Hi,
wie man das final löst habe ich keine idee. Allerdings könnte man um die sache erst mal zu entschärfen einen Sleep von 2-3sekunden einbauen wenn man auf die Fehlermeldung stösst damit das Log nicht so viel schreibt und die SD Karten nicht kaputt gehen.
VG
Jürgen

[mumpf]

Naja, ich würde Debug-Ausgaben einbauen:

Vor dem self._epoll.modify(fileno, self._ro) in Zeile 106 die fileno ausgeben und beim register_connection in Zeile 72 würde ich fileno und obj ausgeben.
Dann kann man hoffentlich rausfinden, welcher filedescriptor fehlt.

Gruß, Waldemar

[schloessl]

Kurze Zwischenmeldung.

der in #32 aufgezeigte Weg die Log-Datei zu begrenzen hat heute die Wirksamkeit bewiese. Es wurden LOG7 bis LOG1 beschrieben, dann wieder bei LOG1 degonnen.
Erfolg: die Karte läuft nichr mehr zu.

Trotzdem ist der Raspi nahezu tot. Gut zu sehen an den Zeiten der Log-Files.

log1.jpg

Ich würde gerne die Debug-Ausgaben laut mumpf einbauen, wer gibt mir eine Hilfe dazu?

[ic14m001]

Hallo miteinander!

Gleiches Problem wie bei schloessl : SD-Karte läuft zwar nicht mehr voll, jedoch ist das System extrem träge! Es stellt sich die Frage, ob das System dann im Produktivbetrieb funktioniert, wenn einige 1Wire-Sensoren auf den KNX-Bus ihre Werte liefern sollen ....

Ich frage mich, was ich "falsch" mache und dieses Problem nur bei wenigen Usern auftritt ........

Update: Hab jetzt mal mittels "crontab" eingestellt, dass täglich um 01 Uhr das Service "smarthome" neu gestartet wird; ist zwar nicht die Problemlösung, aber evtl. passiert der Fehler immer erst nach längerer Systemlaufzeit .......

[bmx]

Du kannst mal eine Sicherheitskopie von lib/connection.py anfertigen und dann im Original mal folgendes einkopieren und testen:

Bei Zeile 72:

    def register_connection(self, fileno, obj):
        self._connections[fileno] = obj
        self._epoll.register(fileno, self._ro)
        logger.debug("Connection registered for fileno={} and object='{}'".format(fileno,str(obj)))

sowie etwas weiter unten:

    def poll(self):
        time.sleep(0.0000000001)  # give epoll.modify a chance
        if not self._connections:
            time.sleep(1)
            return
        for fileno in self._connections:
            if fileno not in self._servers:
                try:
                    if self._connections[fileno].outbuffer:
                        self._epoll.modify(fileno, self._rw)
                    else:
                        self._epoll.modify(fileno, self._ro)
                except OSError as e:
                    logger.debug("OSError '{}' occurred using fileno {}".format(e, fileno))
                    # self._connections[fileno].close()

        for fileno, event in self._epoll.poll(timeout=1):
           .... etc. ....

Bitte Einrückungen beachten! Wie schon oben geschrieben habe ich den Master nicht im Einsatz und kann das derzeit nicht testen ohne einen entsprechenden Zeitaufwand. Aber vielleicht kommen wir der Sache so näher.

Wenn wir wissen, das das Problem verursacht, könnte man den ungültigen Desriptor aus der Liste entfernen. Ob das close funktioniert, weiß ich nicht, daher habe ich es mal auskommentiert mit #.
Du könntest das aber ggf. mal aktivieren, wenn der Fehler wieder aufgetreten ist und Ergebnisse vorliegen. Da Problem ist, das wir mit obigem Code den Fehler zwar abfangen aber dennoch einen Logeintrag generieren und damit weiter müllen. Aber wir wollen ja die Ursache wissen um das Übel an der Wurzel zu packen.

[ic14m001]

Guten Morgen!

Danke für die Info/Erläuterungen bmx; Hab jetzt mal die von Dir vorgeschlagenen Anpassungen auf einen der beiden RPIs durchgeführt -

# self._connections[fileno].close()

habe ich auskommentiert gelassen; den zweiten lass ich mal wie er ist und versuchs mal mit dem täglichen Neustart des Services in der Nacht ...

Beste Grüße
David

[ic14m001]

Update: Just nachdem ich die Änderungen in der lib/connection.py gemacht habe, hat das System wieder zu loggen begonnen. Unterschied zu bisher: Nur ein Eintrag im Log:

2018-02-26  07:39:42 INFO     CP Server Thread-22 172.16.10.13 - - [26/Feb/2018:07:39:42] "GET /backend/pypi.json HTTP/1.1" 200 20789 "http://172.16.11.26:8383/backend/system.html" "Mozilla/5.0 (Windows NT 10.0; WOW64; rv:56.0) Gecko/20100101 Firefox/56.0"
2018-02-26  07:43:26 ERROR    Main         Connection polling failed: dictionary changed size during iteration
Traceback (most recent call last):
  File "/usr/local/smarthome/bin/smarthome.py", line 493, in start
    self.connections.poll()
  File "/usr/local/smarthome/lib/connection.py", line 102, in poll
    for fileno in self._connections:
RuntimeError: dictionary changed size during iteration

System läuft nachwievor ganz normal - die Fehlermeldung im Log ist anders als jene, die immer kam, wenn das System zugemüllt wurde. Versteht jemand, was da das System "sagt" ?
LG