Logging...?

[stoepf]

Auch von mir nochmal Danke für die ausführliche Erklärung.
Ich hatte es nämlich anderst verstanden.

Viele Grüße
Stefan

[wvhn]

Msinn
danke für die super Erklärung. Ich hab es jetzt nochmal ohne Handler probiert und jetzt klappt es. Jetzt wird auch der Logger als untergeordneter Logger erkannt, was vorher anders war.
grafik.png
Entweder war meine logging.yaml zu alt, oder ich hatte einen Fehler in den Einrückungen.

Gruß
Wolfram

[Msinn]

mein Eindruck war, dass man im Gegensatz zu den Plugin-Loggern bei den Modul-Loggern im zweiten Teil doch einen eigenen Handler braucht.

Warum sollte da so sein? Beim Logging handelt es sich um eine Python Stanard Funktionalität (und Python interessiert sich nicht dafür, war ein Modul und was ein Plugin ist )

Zur Erklärung:

1. Die Handler haben auch einen Loglevel. Der steuert, welche Meldnugen durch den Handler ausgegeben werden:

• shng_warnings_file hat den Level NOTICE. Es werden also nur NOTICE, WARNING, ERROR und CRITICAL Meldungen durch den Handler ausgegeben.
• shng_details_file hat den Level DEBUG. Es werden also alle Meldungen durch den Handler ausgegebe.

2. Bei den Loggern gibt es eine Vererbung:

• Wenn ein Parameter nicht angegeben wird, wird er vom übergeordneten Logger übernommen
• Listen Parameter werden mit dem entsprechenden Parameter vom übergeordneten Logger gemergt

  modules:
        # Default logger for SmartHomeNG modules
        handlers: [shng_details_file]
        level: WARNING

    modules.websocket:
        handlers: [shng_details_file]
        level: INFO

führt also dazu, dass in der Handler Liste für modules.websocket zwei mal der Handler shng_details_file steht, daher die doppelte Ausgabe. Da der Handler shng_warnings_file den Level NOTICE hat, erfolgt die Ausgabe der INFO Meldungen nicht in durch diesen Logger.

Wenn (wie in diesem Beispiel) die Liste der Handler gleich ist, sollte man sie im untergeordneten Logger weglassen. Dann sind auch die doppelten Logeintäge weg.

[wvhn]

Moin,

mein Eindruck war, dass man im Gegensatz zu den Plugin-Loggern bei den Modul-Loggern im zweiten Teil doch einen eigenen Handler braucht. Jetzt habe ich nochmal die aktuellste logging.default.yaml der v1.9.3 genommen und die Einstellungen übertragen. Zusätzlich habe ich den neuen Logger angelegt, dieses Mal mit Handler:

    modules:
        # Default logger for SmartHomeNG modules
        handlers: [shng_details_file]
        level: WARNING

    modules.websocket:
        handlers: [shng_details_file]
        level: INFO
​

Jetzt erhalte ich die Meldungen des Websocket-Moduls in der Datei "smarthome-details.log" wieder doppelt (siehe oben):

2023-01-17  09:44:09 WARNING  modules.websocket   smartVISU_protocol_v4 error: Client myiPad.x.y (192.168.2.106:53313), smartVISU v3.3.a, Safari 16 - no close frame received or sent
2023-01-17  09:44:09 WARNING  modules.websocket   smartVISU_protocol_v4 error: Client myiPad.x.y (192.168.2.106:53313), smartVISU v3.3.a, Safari 16 - no close frame received or sent
2023-01-17  09:44:09 INFO     modules.websocket   smartVISU_protocol_v4: Client 192.168.2.106:53313 stopped
2023-01-17  09:44:09 INFO     modules.websocket   smartVISU_protocol_v4: Client 192.168.2.106:53313 stopped
2023-01-17  09:44:09 INFO     modules.websocket   USER removed: 192.168.2.106:53313 - local port: 2424
2023-01-17  09:44:09 INFO     modules.websocket   USER removed: 192.168.2.106:53313 - local port: 2424​

In die Datei "smarthome-warnings.log" wird die WARNING jedoch nur einmal geschrieben. Lasse ich den Logger "modules.websocket" weg und stelle den Logger "modules" auf INFO, erhalte ich die INFO-Meldungen vom Websocket-Modul nur einmal - aber eben alle Meldungen der anderen Module auch.

Gruß
Wolfram

[stoepf]

Was ich eigentlich sagen wollte, ist das folgenden Konfigruation dazu führt, das jede WARNING (und ERROR) doppelt im Log erscheint.
Zumindest hatte ich das Verhalten so letztens beobachtet und hatte deshalb wohl oben nicht genau genug gelesen.

    plugins:
        handlers: [shng_details_file]
        level: WARNING​​
    plugins.pluginname:
        handlers: [shng_details_file]
        level: INFO​

Im zweiten Teil braucht man kein "handlers" mehr angeben. Kann das aber natürlich machen, wenn man einen Anderen (andere Datei) benutzen möchte.
Danke fürs klarstellen.

[Msinn]

stoepf

Bei den Plugins darf man keinen handler mehr angeben

wie kommst Du darauf? Du kannst je Plugin eine eigene Logger Konfiguration anlegen.

[Msinn]

wvhn Setz doch nur den Logger für das Websocket Modul uaf INFO und nicht den Sammellogger für alle Module.

Falls nicht vorhanden, füge einen Logger modules.websocket ein.

[stoepf]

[*]Lege ich einen weiteren logger "modules.websocket" mit dem level: INFO an und setze den level für "modules" auf WARNING, dann bekomme ich alle Infos vom Websocket-Modul doppelt - vor allem aber schon in der Initialisierungsphase sehr viel mehr Infos.

Bei den Plugins darf man keinen handler mehr angeben (https://github.com/smarthomeNG/smart...l.default#L175)
Hätte jetzt vermutet, dass das bei den Modulen vielleicht ähnlich ist.

Gruß Stefan

[wvhn]

Ich hänge mich hier mal an:
beim Testen des Websocketmoduls möchte ich von diesem möglichst viele Meldungen bekommen. Also habe ich den loglevel für "modules" auf "INFO" gesetzt.

   modules:
        # Default logger for SmartHomeNG modules
        handlers: [shng_details_file]
        level: INFO​

Dadurch wird aber auch der Logger vom Admin-Modul ziemlich gesprächig. Um das zu unterbinden habe ich verschiedenes versucht.

• Lege ich einen weiteren logger "modules.websocket" mit dem level: INFO an und setze den level für "modules" auf WARNING, dann bekomme ich alle Infos vom Websocket-Modul doppelt - vor allem aber schon in der Initialisierungsphase sehr viel mehr Infos.
• Lege ich stattdessen einen weiteren Logger "modules.admin" mit dem Level "WARNING" (gleiches Vorgehen wie im Beispiel "plugins.cli"), fängt das http-Modul an zu quatschen und das Websocket-Modul liefert auch erhöhten Output. Allerdings ist "admin" leise. In der Liste der Logger taucht modules.admin als eigener Logger mit Handler "shng_details_file" auf,
  grafik.png
  während ein auf gleiche Weise angelegter Logger für plugins.database auf den plugins-Logger referenziert.grafik.png
• Lege ich einen Filter mit "module: admin" an, dann ist das Ergebnis ungefähr wie im zweiten Fall. (Man kann nicht zusätzlich auf "level" filtern, oder? Die Liste der "Advanced Logger" zeigt dann nichts mehr an. Ich habe das als Fehler im Filter interpretiert).

Was muss/kann ich anders machen, um nur das Logging des Websocketmoduls auf "INFO" zu setzen?

Danke und Gruß
Wolfram

[Msinn]

Im v1.7.2 Master ist die Zeile zumindest nicht auskommentiert.

[Morg]

In der Version, die ich hier habe (müsste nachsehen, ich glaube, der letzte Release) war es auskommentiert.

[Msinn]

Ich habe gerade gesehen, dass da bereits

        cherrypy.config.update({'log.screen': False})

stand. Das hatte also nicht gereicht?

[Msinn]

Da sehe ich erstmal keine negativen Nebenwirkungen. Das kann ich ja für das kommende Release ins http Modul einbauen.

[Morg]

Die beiden access-Zeilen kommen aus cherrypy, und zwar über die App, die das webservices-Plugin dort anmeldet. Sie kommen auch über den access-Logger - dann aber im korrekten Format, und die lassen sich auch steuern.

Die Zeilen, die direkt mit der IP anfangen, sind der "Inhalts"anteil der Access-Logmeldungen und werden von cherrypy (mal wieder) direkt in die Konsole geschrieben.

Ich habe das mit einer etwas brutalen Methode in http-Modul abwürgen können, aber das ist ja eigentlich nicht Sinn der Sache - auf der anderen Seite sollte so ein Modul wie cherrypy eigentlich nicht von sich aus auf die Konsole schreiben, aber das ist ein anderes Thema.

Vielleicht lässt sich das ja in webservices konfigurieren, ansonsten wäre es ggf. doch nochmal ein Thema für module.http....

Hinter cherrypy.config.update(global_conf) habe ich eingefügt:

    cherrypy.config.update(
        {
            'log.screen': False,
            'log.access_file': '',
            'log.error_file': ''
        }
    )

Damit wird nicht mehr "selbstständig" geloggt, sondern nur noch über die Vererbung an shng. Dort lässt es sich dann konfigurieren.

[Msinn]

Ich bin immer noch der Meingung dir beiden Zeilen kommen aus cherrypy und können wie ich oben schrieb durch den logger cherrypy.access gesteuert werden.