Logging...?

[Morg]

Moin,

dass ich mit der neuen Logging-Konfiguration nicht warm werde, ist eine Sache - aber sie macht es mir auch nicht einfach.

Ich möchte:
"Standard"-Log WARN+ in Datei smarthome-warn.log
alles DEBUG+ in Datei smarthome.log
NUR plugin.kodi debug auf smarthome-kodi.log und Konsole -> insbesondere keine DEBUG-Ausgaben vom http-Modul!
um die Module "einzufangen", habe ich die ausschließlich auf smarthome-http.log geleitet - dachte ich.

meine logging.yaml:

%YAML 1.1
# vim: set encoding=utf-8 tabstop=4 softtabstop=4 shiftwidth=4 expandtab
---
version: 1
disable_existing_loggers: true
formatters:
    simple:
        format: '%(asctime)s %(levelname)-8s %(threadName)-12s %(message)s'
        datefmt: '%Y-%m-%d    %H:%M:%S'
    detail:
        format: '%(asctime)s %(levelname)-8s %(module)-12s %(threadName)-12s %(message)s -- %(filename)s:%(funcName)s:%(lineno)d'
        datefmt: '%Y-%m-%d %H:%M:%S'

handlers:
    console:
        class: logging.StreamHandler
        formatter: simple
        stream: ext://sys.stdout
    file_kodi:
        class: logging.handlers.TimedRotatingFileHandler
        level: DEBUG
        formatter: simple
        when: midnight
        backupCount: 7
        filename: ./smarthome-kodi.log
    file:
        class: logging.handlers.TimedRotatingFileHandler
        level: WARN
        formatter: detail
        when: midnight
        backupCount: 7
        filename: ./smarthome-warn.log
    file_debug:
        class: logging.handlers.TimedRotatingFileHandler
        level: DEBUG
        formatter: detail
        when: midnight
        backupCount: 7
        filename: ./smarthome.log
    file_http:
        class: logging.handlers.TimedRotatingFileHandler
        level: DEBUG
        formatter: detail
        when: midnight
        backupCount: 7
        filename: ./var/log/http.log

loggers:
    plugins.kodi:
        handlers: [console, file_kodi]
    modules.admin:
        handlers: [file_http]
        level: WARN
    modules.http:
        handlers: [file_http]
        level: WARN

root:
    level: DEBUG
    handlers: [file]

Ergebnis: Konsole voll mit DEBUG vom http-Modul. Kann man das nicht abstellen?

[Msinn]

Wenn Du den root Logger auf Debug setzt, bekommst Du alle denug Ausgaben ins Log. Das geht nicht anders (Python Standard). Deshalb sollte der root Lgger immer auf WARNING stehen.

Hast Du Dir in der Doku https://www.smarthomeng.de/user/konf...n/logging.html und den Unterpunkt Best Practices durchgelesen? Die Doku versucht die Komplexität des Python Logging Systems etwas zugänglicher zu machen.

Fang mal an Dein Logging von der Default Config aus anzupassen (etc/logging.yaml.default)

[Morg]

Das generelle Logging funktioniert ja, im Wesentlichen auch so, wie ich es haben wollte. Ich habe jetzt nochmal das Logging auf Basis der Default-Config neu aufgesetzt. (NB: das Loggin im Produktivsystem ist ja okay. Zum Testen mit ständigem Neustart von shng ist das aber unpraktisch, darum ist meine Config deutlich vom Default weg)

Auch der root-Logger war nicht das Problem, den habe ich ja nur in eine Datei loggen lassen, da sollte ja DEBUG rein, das passte auch.

Das Problem ist cherrypy, das immer auf Konsole loggt und sich nicht an die logging-Vorgaben hält, soweit man sie konfigurieren kann (oder ich weiß nicht, wie).Ich habe das jetzt manuell abgewürgt, indem ich im http-Modul
```
cherrypy.config.update({'log.screen': False})
```
eingefügt habe. Jetzt kann ich den Rest der Logs auch ausreichend steuern.

Ist die "screen"-Ausgabe von cherrypy ausdrücklich gewünscht? Sonst könnte man das ggf. dauerhaft unterdrücken und das Loggin über die plugin-Section der logging.yaml besser steuern...

Die Ideen aus den Best Practices werde ich für den Rest noch umsetzen, da stehen noch ein paar gute Sachen drin.

[Msinn]

Wenn Du die Logger entsprechend konfiguriert hast, kannst Du in der Admin GUI zur Laufzeit den Loglevel der jeweiligen Logger unter Logs/Liste der Logger einstellen (aber nur wenn der Logger schon existiert).

[Morg]

Den Loglevel im Betrieb zu ändern hilft mir aber nicht wirklich... wozu sollte ich das brauchen?

Neustarten muss ich, weil ich am Code was geändert habe, das geht m.W. noch nicht "live"

Und an den cherrypy-Logger komme ich im Admin-GUI nicht dran, jedenfalls wüsste ich nicht, wie. Insbesondere, weil der Screen-Logger anscheinend auch nicht groß konfiguriert werden kann..

[Msinn]

Den Loglevel im Betrieb zu ändern hilft mir aber nicht wirklich... wozu sollte ich das brauchen?

Wenn Du im Betrieb ein merkwürdiges Verhalten hast, kannst Du den Loglevel hochdrehen und damit Logeinträge bekommen, die Du vielleicht nach einem Neustart nicht hättest.

An die CherryPy Logger (access und error) kommst Du ran, wenn Du sie in logging.yaml definiert hast. Das Screen Logging könnte man zwar auch darüber einstellen, aber das braucht wirklich keiner. Ich habe (Deinem Vorschlag folgend) das im http Modul abgestellt.

[Morg]

Okay, danke dir!

[Morg]

Mannomann, irgendwie komme ich mit dem Logging nicht klar.. mal wieder.

Ich möchte
- verschiedene WARNING-Level in das smarthome-warning schreiben
- das aktuell in Entwicklung befindliche priv_viessmann DEBUG in ./shng.log und auf die Konsole schreiben
- sonst NICHTS auf der Konsole haben.

Ich starte shng.py mit

python3 bin/smarthome.py -f

und erhalte

[12/Dec/2020:18:07:53] ENGINE Bus STARTING
[12/Dec/2020:18:07:53] ENGINE Serving on http://192.168.2.231:8383
[12/Dec/2020:18:07:54] ENGINE Serving on http://192.168.2.231:8384
[12/Dec/2020:18:07:54] ENGINE Bus STARTED
192.168.2.231 - - [12/Dec/2020:18:07:55] "GET /ws/items/d.stat.knx.last_data HTTP/1.1" 404 3872 "" "Python-urllib/3.7"
192.168.2.231 - - [12/Dec/2020:18:07:55] "GET /ws/items/d.stat.knx.activity HTTP/1.1" 404 3871 "" "Python-urllib/3.7"

Meine Konfiguration:

# etc/logging.yaml

version: 1
disable_existing_loggers: True
formatters:
    shng_simple:
        format: '%(asctime)s %(levelname)-8s %(name)-19s %(message)s'
        datefmt: '%Y-%m-%d  %H:%M:%S'

    shng_detail:
        format: '%(asctime)s %(levelname)-8s %(module)-17s %(threadName)-12s %(message)s  --  (%(filename)s:%(funcName)s:%(lineno)d)'
        datefmt: '%Y-%m-%d %H:%M:%S %Z'

    shng_special:
        format: '%(asctime)s %(levelname)-3s %(name)-16s %(funcName)-16s %(message)s'
        datefmt: '%H:%M:%S'

handlers:
    console:
        class: logging.StreamHandler
        formatter: shng_special
        stream: ext://sys.stdout

    shng_warnings_file:
        class: logging.handlers.TimedRotatingFileHandler
        formatter: shng_simple
        level: WARNING
        when: midnight
        backupCount: 7
        filename: ./var/log/smarthome-warnings.log
        encoding: utf8

    shng_details_file:
        class: logging.handlers.TimedRotatingFileHandler
        formatter: shng_detail
        level: DEBUG
        when: midnight
        backupCount: 7
        filename: ./var/log/smarthome-details.log
        encoding: utf8

    shng_special_file:
        class: logging.handlers.TimedRotatingFileHandler
        formatter: shng_special
        level: DEBUG
        when: midnight
        backupCount: 7
        filename: ./shng.log
        encoding: utf8

loggers:
    __main__:
        level: WARNING
        handlers: [shng_warnings_file]

#
# add "special" logger here, e.g. isolated plugin
#
#    plugins.kodi:
#        level: DEBUG
#        handlers: [shng_special_file, console]
plugins.priv_viessmann:
    level: DEBUG
    handlers: [shng_special_file, console]

cherrypy.access:
    level: ERROR
    handlers: [shng_warnings_file]

cherrypy.error:
    level: ERROR
    handlers: [shng_warnings_file]

root:
    level: WARNING
    handlers: [shng_warnings_file]

Was mache ich falsch? Woher kommen die Meldungen?

Und wieso bekomme ich keine Plugin-Ausgabe? Ich habe sowohl plugins.priv_viessmann als auch plugins.viessmann probiert, ohne Unterschied...

[Msinn]

Wie heisst denn der Logger in Deinem Plugin? Hast Du selber einen initialisiert oder nutzt Du den Logger den die SmartPlugin Klasse initialisiert?

Zur Sicherheit kannst Du in der Admin GUI auch unter Logs/Liste der Logger nachsehen.
Dort siehst Du welche Logger initialisiert sind, welchen Minimal Level sie loggen, welchen Handler sie nutzen und in welche Datei sie schreiben.

[Msinn]

Ich habe eben noch gesehen, dass Deine logging.yaml falsch ist.

Deine Logger müssen in den Abschnitt loggers: und nicht auf die oberste Ebene. Auf die oberste Ebene gehört nur der root-Logger. Also einrücken:

loggers:
    __main__:
        level: WARNING
        handlers: [shng_warnings_file]

    #
    # add "special" logger here, e.g. isolated plugin
    #
    #    plugins.kodi:
    #        level: DEBUG
    #        handlers: [shng_special_file, console]

    plugins.priv_viessmann:
        level: DEBUG
        handlers: [shng_special_file, console]

    cherrypy.access:
        level: ERROR
        handlers: [shng_warnings_file]

    cherrypy.error:
        level: ERROR
        handlers: [shng_warnings_file]

root:
    level: WARNING
    handlers: [shng_warnings_file]

[Morg]

Der kommt aus der smartplugin-Klasse:

...
    # initialize logger if necessary
    if '.'.join(VERSION.split('.', 2)[:2]) <= '1.5':
        self.logger = logging.getLogger(__name__)
...

Soweit ich das verstanden habe, initialisiert die SmartPlugin-Klasse den ja selbst, also wird der Code oben nur in der älteren shng-Version ausgeführt...

Weißt du, was die Ausgaben im vorherigen Beitrag sind bzw. wer die verursacht und wie man die abstellen kann? Die scheinen ja auch nicht dem Loggingformat zu entsprechen. Ich habe auch mit "Bus" und "STARTING" keine Dateien in ./modules/ finden können, um dem auf den Grund zu gehen.

Die ersten vier Zeilen sind ja irgendwo aus CherryPy, daher die Portnummern, richtig?
Die weiteren Ausgaben sind Reaktionen auf Abfragen an das network-Plugin. Gibt es da noch ein Logging, das nicht abgefangen wird?

[Morg]

[Einrückungen] Arg... okay, danke, das probiere ich erstmal

edit: okay, der priv_viessmann geht jetzt wieder. War ein blöder Fehler, das hätte ich auch merken können.

Die anderen Logdaten kommen allerdings immer noch.

[Msinn]

Weißt du, was die Ausgaben im vorherigen Beitrag sind bzw. wer die verursacht und wie man die abstellen kann?

Die cherrypy Einträge kommen durch einen Logger den cherrypy selber erzeugt Die kann man nicht abstellen, sondern nur kanalisieren (so gut es geht).
Einen Teil kannst Du loswerden, wenn Du einen Logger cherrypy.access anlegst und die Einträge in die Walachei schickst.

Ganz los kann man die nur werden, wenn man einen Logfilter programmiert und im Abschnitt filters: in die logging.yaml einbindet. (Dazu müsstest Du die Python Doku bemühen.)

[Msinn]

In den Logfiles kannst Du cherrypy recht gut wegfiltern. Das funktioniert aber nicht für das console logging, weshalb ich console logging überhaupt nicht mehr nutze (einfach zu schlecht konfigurierbar). Ich mache einfach das entsprechende Logfile in einem Editor auf, der bei Aktualisierungen der Datei die Änderungen automatisch nachlädt.

[Morg]

Im normalen Betrieb ist das auch völlig ok. Aber wenn ich am Plugin baue, muss ich ständig shng anhalten und neu starten, wenn irgendwo ein Syntaxfehler ist oder etwas nicht so geht, wie es soll. Da müsste ich dann entweder den Editor nicht nur neu laden lassen, sondern live mitscrollen lassen - dann braucht das neben Editor für den Code und dem Terminal noch ein Fenster und ich müsste auch immer hin und her wechseln, statt nur im Terminal zu scrollen.

Für den Dauerbetrieb passt das Logging ja.

Die ersten vier Zeilen ("ENGINE...") schreibt cherrypy anscheinend so auf die Konsole, ich habs zum Testen jetzt deaktiviert, das Modul. Woher der Rest kommt, weiß ich nicht. Das Network-Plugin hat keine (für mich) erkennbaren Log-Anweisungen, die so "komisch" (ohne Log-Format) schreiben. Da werde ich bei Gelegenheit nochmal weiter reinschauen, das zwickt mich jetzt, dass ich das nicht finde...