[Featurewunsch] Filter für env.core.log

[hijacker7]

Hallo,

wäre es möglich, dass man in der etc/logging.yaml einen Filter für den env.core.log hinzufügen könnte? Bzw. auch für Sonstige eigene Logger z.B. vom memlog Plugin.

Mich stört, dass mir folgender Eintrag immer den env.core.log (den ich gerne mal schnell in der SmartVisu checke) "zu spamt".

2023-03-17 08:57:16 WARNING modules.websocket.sv smartVISU_protocol_v4 error: Client 192.168.178.13:42432, smartVISU v3.3.0, Firefox 111 - sent 1011 (unexpected error) keepalive ping timeout; no close frame received

oder z.B. von einem Smartphone:

2023-03-16 23:21:36 WARNING modules.websocket.sv smartVISU_protocol_v4 error: Client 192.168.178.13:39142, smartVISU v3.3.0, Chrome 111 - sent 1011 (unexpected error) keepalive ping timeout; no close frame received

Deshalb habe ich immer mal wieder selbst einen Filter direkt in die def initMemLog(self): in lib/log.py geschrieben. Aber eine Lösung ist das irgendwie nicht, vorallem wenn man beim updaten nicht immer alles zurücksetzen und neumachen will.

Vieleicht sollte aber auch nicht der Logger bearbeitet werden, sondern das handling des Websockets bei Verbindungsabbruch selbst. Die warning kommt hauptsächlich dann, wenn am Smartphone die Visu-Homescreen-App radikal geschlossen wird oder der VPN gekappt wird.

Lg Thomas

[Msinn]

Die Meldungen sollten nicht kommen. Die zeigen, dass bei Dir etwas nicht in Ordnung ist (und das solltest Du nicht weg filtern).

Mein Tipp wäre, die smartVISU auf die aktuelle Version 3.3.1 upzudaten.

[hijacker7]

An der SmartVisu Version liegts nicht die Meldung kommt auch auf 3.3.1 oder dem aktuellen Develop 3.3.b. Aber die kam bei mir auch schon in den älteren Versionen immer, hab der erhlichgesagt nie besondere Beachtung geschenkt.

[Msinn]

Ja, weil Meldungen bei einem Abbruch kamen, hat wvhn in der 3.3.1 ja Änderungen vorgenommen.

Allerdings kenne ich den Fehler 1011 überhaupt nicht, den Fixefox sendet. Das Problem sonst war, dass der Browser die Websocket Verbindung nicht sauber geschlossen hat. Diese Fehler (1005 und 1006) sind deshalb nur mit Level INFO im Log, weshalb man sie im Warnings-Log nicht sieht.

Kannst Du mal testen, ob Du mit einem anderen Browser die Fehler auch bekommst? Mich würde auch interessieren, ob die Meldung bei ws und bei wss Verbindungen kommt.

Außerdem interessiert mich die websockets Version, die Du einsetzt. Die Autoren haben in letzter Zeit mit den Errortexten gespielt, weshalb das Websocket Modul von SmartHomeNG die Meldungen z.T. nicht richtig erkannte.

[hijacker7]

Kannst Du mal testen, ob Du mit einem anderen Browser die Fehler auch bekommst?

Ja Chrome auf Andriod z.B.:

2023-03-17 12:00:45 WARNING modules.websocket.sv smartVISU_protocol_v4 error: Client 192.168.178.13:59202, smartVISU v3.3.1, Chrome 111 - sent 1011 (unexpected error) keepalive ping timeout; no close frame received

Ich habe auch noch ein anderes System da kam der gestern z.B. auch:

2023-03-15 23:20:55 WARNING modules.websocket.sv smartVISU_protocol_v4 error: Client 192.168.0.85:43500, smartVISU v3.3.1, Chrome 111 - sent 1011 (unexpected error) keepalive ping timeout; no close frame received

Egal ob Chrome oder Firefox es kommt immer Fehler 1011

Mich würde auch interessieren, ob die Meldung bei ws und bei wss Verbindungen kommt.

Kann ich nicht genau sagen aber hier die 1. Meldung kommt über einen ReverseProxy, die zweite kommt von einem System wo direkt wss eingesetzt wird.

websockets Version

Ich bin auf dem aktuellsten Stand dh. v1.9.4 Develop

[wvhn]

„Websockets“ ist das Python-Modul, dessen Version Du im Admin-Interface bei den Python-Packages auslesen kannst.

Gruß
Wolfram

[hijacker7]

Achsoo dieses meintet ihr. Das neuste sprich 10.4

[Msinn]

Ok, in v10.4 haben sie was an der ping implementation geändert. Da muss ich rein schauen.
Ich nutze noch websockets v10.1 und habe die Log Messages nicht.

Du könntest schauen, ob ein Downgrade des websockets Packages auf 10.1 bei Dir etwas ändert.

[hijacker7]

Hi,

ich bin gestern mit websockets von 10.4 auf 10.1 runter wie du empfohlen hast. Zunächst dachte ich das wars, aber heute Nacht kamen dann doch noch diese beiden Meldungen. Beide von einem Android mit Chrome über einem Reverse Proxy.

2023-03-17 22:18:59 WARNING modules.websocket.sv smartVISU_protocol_v4 error: Client 192.168.178.13:51146, smartVISU v3.3.b, Chrome 111 - sent 1011 (unexpected error) keepalive ping timeout; no close frame received
​2023-03-18 00:34:31 WARNING modules.websocket.sv smartVISU_protocol_v4 error: Client 192.168.178.13:34032, smartVISU v3.3.b, Chrome 111 - sent 1011 (unexpected error) keepalive ping timeout; no close frame received

[wvhn]

Ich hatte den Websocket schon seit längerer Zeit mit websockets v10.4 getestet. Da gab es keine Probleme. Das System ist ein Raspi unter Buster und Python 3.7.3 mit shNG v1.9.4. Ich nutze allerdings weder wss noch einen Reverse Proxy.

Die Version v1.9.4 von shNG hat zuverlässig die Warnungen reduziert, die bei Verbindungsabbrüchen auftraten (Schließen von Browser-Tabs, Standby-Modus bei Mobilgeräten ….). Das haben wir intensiv getestet und dabei sind wir dem Fehler 1011 nicht begegnet.

Tritt der Fehler 1011 bei Dir auch bei bestehender Verbindung, also aktiven Browser-Tabs auf? Du hast Dir ja in smartVISU eine konfigurierbare Reconnect-Zeit gewünscht, was natürlich sinnvoll ist, wenn die Verbindung dauernd abbricht. Dann ist aber IMHO in Deinen Systemeinstellungen etwas nicht in Ordnung, so dass der Keepalive nicht durchkommt.

Gruß
Wolfram

EDIT: hier gibt es vlt. ein paar Hinweise: https://websockets.readthedocs.io/en...aq/common.html

[hijacker7]

Tritt der Fehler 1011 bei Dir auch bei bestehender Verbindung, also aktiven Browser-Tabs auf? Du hast Dir ja in smartVISU eine konfigurierbare Reconnect-Zeit gewünscht, was natürlich sinnvoll ist, wenn die Verbindung dauernd abbricht. Dann ist aber IMHO in Deinen Systemeinstellungen etwas nicht in Ordnung, so dass der Keepalive nicht durchkommt.

Nein bei aktiven Verbindungen tritt er nicht auf, deshalb habe ich mir die Reconnect-Zeit nicht gewünscht. Diese dient nur um nach einem Mobil-Gerät-Standby schneller wieder verbunden zu sein.

Insgesamt tritt der Fehler auch deutlich seltener auf als die von den letzten Versionen, heute z.B. noch nie auser die Nachts. Leider ist er auch mit meinen Methoden nicht reproduzierbar/erzwingbar. Da ich dummerweise die Meldung nicht wirklich genau gelesen habe, habe ich diesen Fehler mit den alten 1005 oder 1006 Fehlern verwechselt.

Hier noch ein paar Details zum System:

• Ubuntu Server 20.04.6 LTS (KVM)
• Intel Nuc mit Intel Xeon E3-12xx v2 (Ivy Bridge, IBRS)
• Python 3.11.2 final
• SmartHomeNG Version:v1.9.4.1-97a1144b8.develop
• SmartHomeNG Plugins Version:v1.9.4-master (c4ec71ee)
• PyPi websockets 10.1
• Verbindung über eigenen Reverse Proxy (hauptsächlich wegen SSL)

[Msinn]

Der Fehler 1011 ist auch etwas anders gelagert, als die Fehler 1005 und 1006. Im Gegensatz zu den beiden anderen Fehlern ist 1011 ein Server Fehler (was aus dem Fehlertext des websocket Packages nicht wirklich hervorgeht)

Nach RFC 6455:

• 1005 CLOSED_NO_STATUS
  
  1005 is a reserved value and MUST NOT be set as a status code in a Close control frame by an endpoint. It is designated for use in applications expecting a status code to indicate that no status code was actually present.
• 1006 CLOSE_ABNORMAL
  
  1006 is a reserved value and MUST NOT be set as a status code in a Close control frame by an endpoint. It is designated for use in applications expecting a status code to indicate that the connection was closed abnormally, e.g., without sending or receiving a Close control frame.

• 1011 Server error
  
  1011 indicates that a server is terminating the connection because it encountered an unexpected condition that prevented it from fulfilling the request.

Die Fehler 1005 und 1006 sind eigentlich nur Kennzeichen, dass sich der Client (der Browser) vom Hof gemacht hat ohne Tschüss zu sagen.
Mit der Textmeldung aus dem websockets Package sieht das so aus, als würde der Server (SmartHomeNG) versuchen ein Keep-Alive-Ping zu senden und würde das nicht los.

Meine Vermutung ist, dass normalerweise der Server sein Ping los wird (beim Client Rechner), nur keiner antwortet (Fehler 1005 und 1006). Bei Dir (Fehler 1011) scheint der Server aber nach Abbruch der Verbindung das Ping nicht mehr los zu werden (beim Proxy Rechner).

[hijacker7]

Ich habe das noch weiter im Auge behalten. Ich kann mir durchaus vorstellen, dass es beim System mit dem ProxyServer so ist, dass dieser das Ping nicht los wird und deshalb einen Fehler zurück an den Socketserver gibt.

Aber ich habe auf meinem zweiten komplett unabhänigigen und eigenständigen System genau den selben Fehler:

2023-03-19  15:49:35 WARNING  modules.websocket.sv smartVISU_protocol_v4 error: Client 192.168.0.85:45796, smartVISU v3.3.b, Chrome 111 - sent 1011 (unexpected error) keepalive ping timeout; no close frame received
2023-03-19  15:50:04 WARNING  modules.websocket.sv smartVISU_protocol_v4 error: Client 192.168.0.85:43504, smartVISU v3.3.b, Chrome 111 - sent 1011 (unexpected error) keepalive ping timeout; no close frame received
2023-03-19  16:12:47 WARNING  modules.websocket.sv smartVISU_protocol_v4 error: Client 192.168.0.85:47926, smartVISU v3.3.b, Chrome 111 - sent 1011 (unexpected error) keepalive ping timeout; no close frame received

2023-03-20  23:33:41 WARNING  modules.websocket.sv smartVISU_protocol_v4 error: Client 192.168.0.85:40070, smartVISU v3.3.b, Chrome 111 - sent 1011 (unexpected error) keepalive ping timeout; no close frame received

2023-03-21  17:28:40 WARNING  modules.websocket.sv smartVISU_protocol_v4 error: Client 192.168.0.85:43656, smartVISU v3.3.b, Chrome 111 - sent 1011 (unexpected error) keepalive ping timeout; no close frame received

Man sieht hier auch die häufigkeit des Fehlers. Ausgegangen sind diese Fehler meiner Meinung nach alle von einem Android Chrome.

Das zweite System:

• Ubuntu Server 18.04.6 LTS (KVM)
• Intel Nuc mit Intel Xeon E3-12xx v2 (Ivy Bridge, IBRS)
• Python 3.11.2 final
• SmartHomeNG Version:v1.9.4.1-62e262471.develop
• SmartHomeNG Plugins Version:v1.9.4-master (c4ec71ee)
• smartVISU v3.3.b (develop)
• PyPi websockets 10.4
• Verbindung direkt, hauptsächlich über SSL und WSS

P.S. Vieleicht sollten wir den Thread umbenennen um noch ein paar zu finden die evtl. auch diesen Fehler haben.

[wvhn]

Ich konnte das jetzt reproduzierbar mit einem Android-Testgerät nachstellen. Das alte Huawei P8 hält die Websocket-Verbindung etwa 35 Minuten lang offen, auch wenn der Screen ausgeschaltet ist. Dann bricht die Verbindung ab:

2023-03-21  23:32:56 WARNING  modules.websocket.sv smartVISU_protocol_v4 error: Client HUAWEI-P8.fritz.box (192.168.2.121:42927), smartVISU v3.3.b, Chrome 68 - sent 1011 (unexpected error) keepalive ping timeout; no close frame received
​

Danach entfernt das Websocketmodul den Client und beendet sauber alle Abos von items. Die Warnung kann deshalb IMHO unterdrückt werden.

Gruß
Wolfram

[Msinn]

Ok, ich würde den Fehler 1011 aber nur unterdrücken (bzw. als INFO loggen) wenn er mit einem 'keepalive ping timeout' auftritt.