FHEMWEB und Modul 74_Unifi "Connection lost, trying a reconnect every 5 seconds"

Begonnen von hoppel118, 29 Dezember 2018, 23:36:35

Vorheriges Thema - Nächstes Thema

hoppel118

Hallo Leute,

ich nutze seit mittlerweile fast 3 Jahren FHEM, bin super zufrieden und werde langsam süchtig. ;)

Ich nutze folgendes Netzwerk-Equipment von Ubiquiti Unifi


  • Unifi Controller im Docker Container v5.6.40LTS
  • 1x Unifi Security Gateway
  • 2x Unifi Switch US 8 150W
  • 3x Unifi UAP AC Pro

Ich behaupte, dass mein Server die Performance bringt, die FHEM benötigt, um vernünftig betrieben werden zu können, siehe Signatur. Bitte nicht falsch verstehen, ich bin eigentlich das Gegenteil von eingebildet. ;)

Problematik

Kürzlich habe ich nun also das Modul "74_Unifi" in Betrieb genommen. Allerdings erhalte ich immer zum Interval (bei mir 30 Sekunden) der Device-Definition im FHEM WebInterface die folgende Meldung:

"Connection lost, trying a reconnect every 5 seconds".

Ich habe meine Problematik dann im Unifi Thread beschrieben. Dirk (alias Wuehler, der Modul Entwickler) hat mit mir ein paar Sachen analysiert. Am Ende habe ich dann eher zufällig herausgefunden, dass die Meldung ausschließlich auftritt, wenn ich mich in dem room "Netzwerk" befinde, in dem auch die Unifi-Devices definiert sind. Gehe ich in irgendeinen anderen room, bspw. "Schlafzimmer", erscheint die Meldung nicht.

Ansonsten habe ich das Modul seit gestern Abend in Betrieb, die Readings werden aktualisiert. Es gab auch sonst keine Performance-Probleme mit anderem Equipment. Meine CPU dümpelt meistens im einstelligen Bereich vor sich hin. Auch das Unifi-Modul lastet meinen Server nicht aus.

Weitere Vorgehensweise

Dirk bat mich hier in diesem Forenbereich einen eigenen Thread für dieses Thema zu öffnen, da er davon ausgeht, dass die Problematik mit FHEMWEB zusammenhängt. Zitat:

ZitatIch habe als Vermutung, dass es daran liegt, dass das Unifi-Modul viele http-requests absetzt und daher FhemWeb keine Ressourcen für sein Polling hat.
Da auch das Modul freezemon Unifi als mögliche Quelle für freezes anzeigt wäre das ein weiterer Hinweis das Design des Unifi-Moduls zu überdenken.
Wäre schön, wenn wir das mit FhemWeb klären könnten.

Hier der entsprechende Unifi-Modul-Thread: https://forum.fhem.de/index.php/topic,40287.msg878200.html#msg878200


Was braucht ihr nun, um dem Thema auf die Schliche zu kommen?

Ich bin für alle Schandtaten bereit. ;)

Danke und Gruß Hoppel
Server: Openmediavault, XEON E3-1240L-v5, Supermicro X11SSH-CTF, 64GB ECC RAM, SSD, RAID-Z2
Homebridge | Alexa | Yowsup
Homematic | HomeConnect | MQTT | Philips Hue | Sonos | Unifi Network & Protect | vbus | Xiaomi

Wuehler

Moin,

Danke Hoppel, klinke mich hier ein, um am Ball zu bleiben und mitzubekommen, ob/was am Unifi-Modul ggf. geändert werden muss.

Laut Hoppel kommt die Meldung in FhemWeb immer dann, wenn das Unifi-Modul die Informationen aus dem Unifi-Controller ausliest. In diesem "Moment" werden 7 Non-Blocking-Http-Request abgesetzt.
Seltsam finde ich, dass es nur in diesem einen Raum auftritt. Das passt irgendwie nicht zu meiner Vermutung.

VG,
Dirk

hoppel118

Moinsen,

welche Logs soll ich bereitstellen, FHEMWEB und Unifi gleichzeitig oder einzeln auf verbose 5 oder sogar global verbose 5?

Gruß Hoppel
Server: Openmediavault, XEON E3-1240L-v5, Supermicro X11SSH-CTF, 64GB ECC RAM, SSD, RAID-Z2
Homebridge | Alexa | Yowsup
Homematic | HomeConnect | MQTT | Philips Hue | Sonos | Unifi Network & Protect | vbus | Xiaomi

hoppel118

Server: Openmediavault, XEON E3-1240L-v5, Supermicro X11SSH-CTF, 64GB ECC RAM, SSD, RAID-Z2
Homebridge | Alexa | Yowsup
Homematic | HomeConnect | MQTT | Philips Hue | Sonos | Unifi Network & Protect | vbus | Xiaomi

rudolfkoenig

Zitatwelche Logs soll ich bereitstellen
Fuer die letzten 5 Sekunden vor der Reconnect Meldung:
- Daten aus der JavaScript-Konsole des Browsers
- ein "attr global verbose 5" Mitschnitt von FHEM.
Sonst: Definition der FHEMWEB Instanz, und Name des Browsers.

hoppel118

Hallo,

danke erstmal für die Unterstützung!

Zitat von: rudolfkoenig am 30 Dezember 2018, 10:43:42
und Name des Browsers.

Das hat mich gerade auf eine Idee gebracht. Hauptsächlich betrachte ich mein FHEMWEB an meinem PC (Windows 10) über Chrome. Irgendwann war Firefox einfach nur noch langsam und ich habe mich von Firefox abgewendet. Internet Explorer und/oder Edge habe ich nie wirklich genutzt. Ansonsten bediene ich FHEM über eine Homebridge per App oder Sprache.

Ich habe nun alle möglichen anderen OS und Browser mit folgendem Ergebnis getestet:

1. PC


  • OS: Windows 10 64 Bit (up-to-date)
  • Java: Version 8 Update 191 (Build 1.8.0_191-b12)
  • Browser: Microsoft Edge 42.17134.1.0 --> Problem besteht
  • Browser: Firefox Quantum (64Bit) 64.0 --> LÄUFT!!!
  • Browser: Google Chrome 71.0.3578.98 (Offizieller Build) (64-Bit) --> Problem besteht

2. MacBook Pro


  • OS: macOS Mojave (up-to-date)
  • Browser: Safari 12.0.2 (14606.3.4) --> LÄUFT!!!
  • Browser: Firefox Quantum (64Bit) 64.0 --> LÄUFT!!!

3. iPhone 8


  • OS: iOS (up-to-date)
  • Browser: Safari up-to-date --> LÄUFT!!!
  • Browser: Firefox Quantum up-to-date --> LÄUFT!!!
  • Browser: Google Chrome up-to-date --> LÄUFT!!!

Sorry, ich bin leider vorher nicht auf die Idee gekommen, es einfach mal einem anderen Gerät/Browser zu testen.

Mit Firefox hätte ich nun also einen Browser für alle meine Rechner bzw. Smartphones, bei dem es dieses Problem nicht gibt. Anscheinend hat sich beim Firefox in letzter Zeit einiges geändert. Die Resonanz im Internet zum neuen Firefox ist gar nicht so schlecht. Gibt es für FHEM so etwas wie einen empfohlenen oder nicht empfohlenen Browser?


Dennoch möchte ich gern dabei unterstützen, das Problem auch für Chrome und evtl. Edge zu lösen bzw. zumindest herauszufinden, wo das Problem liegt. Hier also alle Informationen, die ich liefern kann:

Zitat von: rudolfkoenig am 30 Dezember 2018, 10:43:42
Fuer die letzten 5 Sekunden vor der Reconnect Meldung:
- Daten aus der JavaScript-Konsole des Browsers

Wie mache ich das?

Zitat von: rudolfkoenig am 30 Dezember 2018, 10:43:42
- ein "attr global verbose 5" Mitschnitt von FHEM.

Um 16:51:02 wurden die Readings im Unifi Modul aktualisiert. Hier das Logfile:

https://pastebin.com/dSLF1LS1

Zitat von: rudolfkoenig am 30 Dezember 2018, 10:43:42
Sonst: Definition der FHEMWEB Instanz

define WEB FHEMWEB 8083 global
attr WEB HTTPS 1
attr WEB csrfToken none
attr WEB defaultRoom Thermostate
attr WEB editConfig 1
attr WEB group Beleuchtung,Lampen,Lichter,Strom,Sensoren,Thermostate
attr WEB iconPath fhemSVG:openautomation:default
attr WEB roomIcons Save.config:message_attention Aussen:temp_outside Badezimmer:scene_shower Büro:it_pc Flur:scene_stairs Küche:scene_cooking Schlafzimmer:scene_making_love_clean Wohnzimmer:scene_livingroom Dachboden:it_server Lampen:li$
attr WEB sortRooms Aussen Badezimmer Büro Flur Küche Schlafzimmer Wohnzimmer Dachboden
attr WEB sslVersion TLSv12:!SSLv2
attr WEB stylesheetPrefix dark
#attr WEB verbose 5
define allowed_WEB allowed
attr allowed_WEB basicAuth SHA256:xxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxx
attr allowed_WEB validFor WEB


Wenn ihr mir nun sagt, vergiss das Problem und verwende Firefox, dann kann das für mich eine Lösung sein. Bin gerade am Überlegen mal wieder einen Browserschwenk zu machen. Ob, das auf meinen Apple Devices Sinn macht, weiß ich noch nicht.

Danke für eure Unterstützung und viele Grüße Hoppel
Server: Openmediavault, XEON E3-1240L-v5, Supermicro X11SSH-CTF, 64GB ECC RAM, SSD, RAID-Z2
Homebridge | Alexa | Yowsup
Homematic | HomeConnect | MQTT | Philips Hue | Sonos | Unifi Network & Protect | vbus | Xiaomi

Wuehler

ZitatZitat von: rudolfkoenig am Heute um 10:43:42
Fuer die letzten 5 Sekunden vor der Reconnect Meldung:
- Daten aus der JavaScript-Konsole des Browsers

Wie mache ich das?
Die Entwicklertools des Browsers öffnen und dort dann die console. In Chrome müsste Ctrl+Shift+J funktionieren.

hoppel118

OK, mit global verbose 3 sehe ich dort schon Fehler:

Zitat22:29:45.572 FW_queryValue:{ReadingsVal("UnifiController","blockClient","")}
fhemweb.js:492 22:29:45.576 FW_queryValue:{AttrVal("UnifiController","room","")}
fhemweb.js:492 22:29:45.668 Inform-channel opened (websocket) with filter UnifiController
fhemweb.js:492 22:29:45.702 Rcvd:
fhemweb.js:1183 WebSocket connection to 'wss://10.11.11.11:8083/fhem?XHR=1&inform=type=status;filter=UnifiController;since=1546205382;fmt=JSON&fw_id=399&timestamp=1546205385667' failed: Invalid frame header
FW_longpoll @ fhemweb.js:1183
fhemweb.js:492 22:30:04.412 ERRMSG:Connection lost, trying a reconnect every 5 seconds.<
fhemweb.js:492 22:30:09.314 ERRMSG:<
fhemweb.js:492 22:30:09.416 Inform-channel opened (websocket) with filter UnifiController
fhemweb.js:492 22:30:09.455 Rcvd: ["UnifiController","connected","<div id=\u0022UnifiController\u0022  title=\u0022connected\u0022 class=\u0022col2\u0022>connected</d...(137)
fhemweb.js:1183 WebSocket connection to 'wss://10.11.11.11:8083/fhem?XHR=1&inform=type=status;filter=UnifiController;since=1546205382.1769998;fmt=JSON&fw_id=399&timestamp=1546205409415' failed: Invalid frame header
FW_longpoll @ fhemweb.js:1183
fhemweb.js:492 22:30:34.701 ERRMSG:Connection lost, trying a reconnect every 5 seconds.<
fhemweb.js:492 22:30:39.603 ERRMSG:<
fhemweb.js:492 22:30:39.705 Inform-channel opened (websocket) with filter UnifiController
fhemweb.js:492 22:30:39.746 Rcvd: ["UnifiController","connected","<div id=\u0022UnifiController\u0022  title=\u0022connected\u0022 class=\u0022col2\u0022>connected</d...(137)
fhemweb.js:1183 WebSocket connection to 'wss://10.11.11.11:8083/fhem?XHR=1&inform=type=status;filter=UnifiController;since=1546205405.9299998;fmt=JSON&fw_id=399&timestamp=1546205439704' failed: Invalid frame header
FW_longpoll @ fhemweb.js:1183
fhemweb.js:492 22:31:04.988 ERRMSG:Connection lost, trying a reconnect every 5 seconds.<
fhemweb.js:492 22:31:09.890 ERRMSG:<
fhemweb.js:492 22:31:09.991 Inform-channel opened (websocket) with filter UnifiController
fhemweb.js:492 22:31:10.023 Rcvd: ["UnifiController","connected","<div id=\u0022UnifiController\u0022  title=\u0022connected\u0022 class=\u0022col2\u0022>connected</d...(137)

Ich mach das Ganze dann gleich nochmal mit einem global verbose 5.

Gruß
Server: Openmediavault, XEON E3-1240L-v5, Supermicro X11SSH-CTF, 64GB ECC RAM, SSD, RAID-Z2
Homebridge | Alexa | Yowsup
Homematic | HomeConnect | MQTT | Philips Hue | Sonos | Unifi Network & Protect | vbus | Xiaomi

rudolfkoenig

Ich tippe auf dem Virenscanner als Verursacher, die sind fuer sowas bekannt.

Zitatfhemweb.js:1183 WebSocket connection to '...' failed: Invalid frame header
Hier waeren die Websocket-frame-header Details insteressant, siehe https://kaazing.com/inspecting-websocket-traffic-with-chrome-developer-tools/
Kannst du bitte "attr WEB longpoll 1" auch testen? Verwendet die alte HTTP-longpoll Methode statt websocket.

ZitatGibt es für FHEM so etwas wie einen empfohlenen oder nicht empfohlenen Browser?
Ich versuche alle zu unterstuetzen, es sei denn Dinosaurier wie IE machen extra viel Arbeit.

Zitat- Daten aus der JavaScript-Konsole des Browsers
Linux/Windows: Shift-Ctrl-i, OSX: Alt-Cmd-i, IE/Edge:F12 (wenn ich mich recht erinnere)
Es gibt dafuer ueberall auch einen Menueeintrag, Sinngemaess: Entwicklertools, Javascript-Console.

hoppel118

Ob verbose 3 oder 5 ist egal, es sind dieselben Meldungen. Somit brauche ich auch das Log nicht nochmal neu machen.

Im Firefox sieht das Ganze viel besser aus. Hier gibt es diesen "Websocket connection Fehler" nicht:

Zitat22:43:32.167 FW_queryValue:{ReadingsVal("UnifiController","blockClient","")} fhemweb.js:492:5
22:43:32.174 FW_queryValue:{AttrVal("UnifiController","room","")} fhemweb.js:492:5
22:43:32.257 Inform-channel opened (HTTP) with filter UnifiController fhemweb.js:492:5
22:43:32.263 Rcvd: fhemweb.js:492:5
22:43:50.637 Rcvd: ["UnifiController","connected","<div id=\u0022UnifiController\u0022  title=\u0022connected\u0022 class=\u0022col2\u0022>connected</d...(137) fhemweb.js:492:5
22:43:50.642 Rcvd: ["UnifiController--UC_speed_ping","0","0"] fhemweb.js:492:5
...
...

Braucht ihr noch irgendwas?

Danke und Gruß Hoppel
Server: Openmediavault, XEON E3-1240L-v5, Supermicro X11SSH-CTF, 64GB ECC RAM, SSD, RAID-Z2
Homebridge | Alexa | Yowsup
Homematic | HomeConnect | MQTT | Philips Hue | Sonos | Unifi Network & Protect | vbus | Xiaomi

hoppel118

Zitat von: rudolfkoenig am 30 Dezember 2018, 22:43:40
Ich tippe auf dem Virenscanner als Verursacher, die sind fuer sowas bekannt.

Ich habe keine speziellen Virenscanner im Einsatz. Auf meinem Windows PC ist es der Default "Viren- und Bedrohungsschutz".

Zitat von: rudolfkoenig am 30 Dezember 2018, 22:43:40
Hier waeren die Websocket-frame-header Details insteressant, siehe https://kaazing.com/inspecting-websocket-traffic-with-chrome-developer-tools/

Damit muss ich mich beschäftigen. Das sieht erstmal komplex aus, wenn man keine Ahnung hat, was das ist. ;)

Zitat von: rudolfkoenig am 30 Dezember 2018, 22:43:40
Kannst du bitte "attr WEB longpoll 1" auch testen? Verwendet die alte HTTP-longpoll Methode statt websocket.

Jo, das funktioniert. Sobald ich das gesetzt habe, sehen die Meldungen im Chrome genauso ausführlich und fehlerfrei aus, wie im Firefox.

Zitat von: rudolfkoenig am 30 Dezember 2018, 22:43:40
Ich versuche alle zu unterstuetzen, es sei denn Dinosaurier wie IE machen extra viel Arbeit.

Linux/Windows: Shift-Ctrl-i, OSX: Alt-Cmd-i, IE/Edge:F12 (wenn ich mich recht erinnere)
Es gibt dafuer ueberall auch einen Menueeintrag, Sinngemaess: Entwicklertools, Javascript-Console.

Aha, gut zu wissen. Danke!

Wie gehen wir jetzt weiter vor? Soll ich das mit den "Websocket-frame-header Details" noch machen? Oder ist das "attr WEB longpoll 1" nun die Lösung?

Wenn euch das weiter bringt, mache ich das aber gerne noch.

Gruß Hoppel
Server: Openmediavault, XEON E3-1240L-v5, Supermicro X11SSH-CTF, 64GB ECC RAM, SSD, RAID-Z2
Homebridge | Alexa | Yowsup
Homematic | HomeConnect | MQTT | Philips Hue | Sonos | Unifi Network & Protect | vbus | Xiaomi

rudolfkoenig

ZitatWie gehen wir jetzt weiter vor? Soll ich das mit den "Websocket-frame-header Details" noch machen? Oder ist das "attr WEB longpoll 1" nun die Lösung?
Websocket debuggen wird auch fuer mich Arbeit sein, und bis dato hat sich keiner sonst beschwert. Allerdings koennten wir das fuer die Zukunft vermeiden.
Wie du willst, entscheide Du.

hoppel118

Zitat von: rudolfkoenig am 30 Dezember 2018, 22:43:40
Hier waeren die Websocket-frame-header Details insteressant, siehe https://kaazing.com/inspecting-websocket-traffic-with-chrome-developer-tools/

OK, war doch nicht so komplex. Ich habe das "attr WEB longpoll 1" für diesen Test nochmal deaktiviert.

Hier das Ergebnis im "Headers"-Tab:

ZitatGeneral
  Request URL: wss://10.11.11.11:8083/fhem?XHR=1&inform=type=status;filter=UnifiController;since=1546208354.684;fmt=JSON&fw_id=326&timestamp=1546208389334
  Request Method: GET
  Status Code: 101 Switching Protocols
Response Headers
  Connection: Upgrade
  Sec-WebSocket-Accept: PMX8zKY2++4+ml53+J5udG9Dumg=
  Upgrade: websocket
Request Headers
  Accept-Encoding: gzip, deflate, br
  Accept-Language: de-DE,de;q=0.9,en-US;q=0.8,en;q=0.7
  Authorization: Basic YWRtaW46TWlob2F1Zzgy
  Cache-Control: no-cache
  Connection: Upgrade
  Cookie: X-OPENMEDIAVAULT-LOGIN-%242y%2410%242loOZ2p.snzH94EJKc6PreQfM2cbhbay2Kf30n2uZaS1AcC3W48xW=The+beginning+of+knowledge+is+the+discovery+of+something+we+do+not+understand.; X-OPENMEDIAVAULT-LOCALE=de_DE; X-OPENMEDIAVAULT-LOGIN-%242y%2410%24zDasAVz5Vorsx9rEmEyMoOhUvnTpSaWaR8HSFxnwT5Jht7DODh3xm=Fear+is+the+mind-killer.; XSRF-TOKEN=eyJpdiI6ImMyVmVwK0R5ZUR1SWY2UXZaY3hVZGc9PSIsInZhbHVlIjoiV2FXcjJVSndvcytoOVBVNlh1aDhETGxCcVU0NWwwOCswdWpQZkFtbkU3OTh5S3E3ZVVOSlpwakRIU2NkeGNzeCIsIm1hYyI6IjZlN2JjNjU5NzUwMTc1MzJlMDdlM2ZiNTBhYWE3NTYzMWY2NmU4MzY4ZmZjYmE0MjVmMDc5YTI3MjM3N2Q3ODcifQ%3D%3D; heimdall_session=eyJpdiI6IndYOVwvTGRaenJBRWtSTTVSZUVNbEtnPT0iLCJ2YWx1ZSI6IkxrcnppK1dJdDdQWDE3dTFUXC9cL1pyZGV0c1VlNW9OenVGVysra3VYVkxFa2tyemxyNDRlV0l4NlpCdWhGVjlQdSIsIm1hYyI6IjQxYWQ5ZDA0ZGExYWI2ZDAxMjdkMGU0ZDY0Yzg3N2JhMzhmMDhjMmY3MTM3YTRhMzRiY2JjYzcwMmQzOWQwNDYifQ%3D%3D
  Host: 10.11.11.11:8083
  Origin: https://10.11.11.11:8083
  Pragma: no-cache
  Sec-WebSocket-Extensions: permessage-deflate; client_max_window_bits
  Sec-WebSocket-Key: ha7Lr0ngLY/Ipeg/E2tH5Q==
  Sec-WebSocket-Version: 13
  Upgrade: websocket
  User-Agent: Mozilla/5.0 (Windows NT 10.0; Win64; x64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/71.0.3578.98 Safari/537.36
Query Strin Parameters
  XHR: 1
  inform: type=status;filter=UnifiController;since=1546208354.684;fmt=JSON
  fw_id: 326
  timestamp: 1546208389334

Hier das Ergebnis im "Frames"-Tab:

Zitat["UnifiController","connected","<div id=\u0022UnifiController\u0022 title=\u0022connected\u0022 class=\u0022col2\u0022>connected</div>"]   138   23:19:49.368
(Opcode -1)   20   23:20:14.612


Ist das das, was ihr braucht? Was braucht ihr noch? :D

Gruß Hoppel
Server: Openmediavault, XEON E3-1240L-v5, Supermicro X11SSH-CTF, 64GB ECC RAM, SSD, RAID-Z2
Homebridge | Alexa | Yowsup
Homematic | HomeConnect | MQTT | Philips Hue | Sonos | Unifi Network & Protect | vbus | Xiaomi

hoppel118

Zitat von: rudolfkoenig am 30 Dezember 2018, 23:23:23
Websocket debuggen wird auch fuer mich Arbeit sein, und bis dato hat sich keiner sonst beschwert. Allerdings koennten wir das fuer die Zukunft vermeiden.
Wie du willst, entscheide Du.

OK, meinetwegen gern. Wenn man damit in der Zukunft Fehler bei anderen vermeiden kann, spart das auch bei euch Entwicklern etwas Zeit und ihr könnt euch um andere evtl. spannendere Themen kümmern. ;) Ich bin gerade in der Thematik drin, nicht ganz auf den Kopf gefallen und habe mittlerweile einiges an Erfahrung in FHEM gesammelt. Wahrscheinlich bin ich nicht der schlechteste Tester. ;) 

Dirk sprach eigentlich mal davon, das Unifi Modul ggf. zu aktualisieren. Siehst du hier keine Notwendigkeit mehr?

Gruß Hoppel
Server: Openmediavault, XEON E3-1240L-v5, Supermicro X11SSH-CTF, 64GB ECC RAM, SSD, RAID-Z2
Homebridge | Alexa | Yowsup
Homematic | HomeConnect | MQTT | Philips Hue | Sonos | Unifi Network & Protect | vbus | Xiaomi

rudolfkoenig

ZitatIst das das, was ihr braucht? Was braucht ihr noch?
Einen dicken roten Pfeil auf die Zeile, die laut Chrome falsch sein soll, mit Beschreibung, wie es richtig ist. :)

Kannst du mir bitte bei der funktionierenden Version aus der JavaScript-Konsole alle Daten, die nach dem Aufruf der Problemseite protokolliert werden, hier anhaengen?
Evtl. sind in den Daten Sonderzeichen, die FHEMWEB in der Websocket Version escapen sollte.