Headless client rpi3 frequent disconnect

[rubipopubi]

Hey,

danke danke danke erstmal für das Projekt. Darauf hab ich lange gewartet. Nun zu meinem Problem: Ich bin gerade dabei, ein headless client (rpi3b) mit respeaker 2mic hat einzurichten. Sepia läuft auf einem rpi4 im gleichen Lan und die Kommunikation mit Iobroker (auf dem gleichen Pi4) läuft vollkommen problemlos (was mich begeistert!). Leider macht der Client Probleme: Verbindung, Wakeword Erkennung, usw. klappen eigentlich bestens. Jedoch bricht die Verbindung zwischen Client und Server (?) regelmäßig ab. Sie wird zwar fast augenblicklich wieder hergestellt, allerdings horcht der Client dann nicht mehr nach dem Wakeword, was mich zur Weißglut treibt :D. Manueller Reload, Reboot etc. beheben das Problem bis zum nächsten Disconnect. Hier anbei der Client Connections log, der während ich diesen Beitrag schreibe angefallen ist:

CLEXI server says welcome. Info: {"version":"CLEXI Node.js server v0.8.2","xtensions":{"clexi-broadcaster":{"active":true},"clexi-http-events":{"active":true},"runtime-commands":{"active":true}}} CLEXI connected CLEXI connecting ... CLEXI reconnecting after unexpected close. Try: 1 CLEXI closed. Reason: 1006 CLEXI server says welcome. Info: {"version":"CLEXI Node.js server v0.8.2","xtensions":{"clexi-broadcaster":{"active":true},"clexi-http-events":{"active":true},"runtime-commands":{"active":true}}} CLEXI connected CLEXI connecting ... CLEXI reconnecting after unexpected close. Try: 1 CLEXI closed. Reason: 1006 CLEXI server says welcome. Info: {"version":"CLEXI Node.js server v0.8.2","xtensions":{"clexi-broadcaster":{"active":true},"clexi-http-events":{"active":true},"runtime-commands":{"active":true}}} CLEXI connected CLEXI connecting ... CLEXI reconnecting after unexpected close. Try: 1 CLEXI closed. Reason: 1006 CLEXI server says welcome. Info: {"version":"CLEXI Node.js server v0.8.2","xtensions":{"clexi-broadcaster":{"active":true},"clexi-http-events":{"active":true},"runtime-commands":{"active":true}}} CLEXI connected CLEXI connecting ... CLEXI reconnecting after unexpected close. Try: 1 CLEXI closed. Reason: 1006 CLEXI server says welcome. Info: {"version":"CLEXI Node.js server v0.8.2","xtensions":{"clexi-broadcaster":{"active":true},"clexi-http-events":{"active":true},"runtime-commands":{"active":true}}} CLEXI connected CLEXI connecting ... CLEXI reconnecting after unexpected close. Try: 1 CLEXI closed. Reason: 1006 CLEXI server says welcome. Info: {"version":"CLEXI Node.js server v0.8.2","xtensions":{"clexi-broadcaster":{"active":true},"clexi-http-events":{"active":true},"runtime-commands":{"active":true}}} CLEXI connected CLEXI connecting ... CLEXI reconnecting after unexpected close. Try: 1 CLEXI closed. Reason: 1006 CLEXI server says welcome. Info: {"version":"CLEXI Node.js server v0.8.2","xtensions":{"clexi-broadcaster":{"active":true},"clexi-http-events":{"active":true},"runtime-commands":{"active":true}}} CLEXI connected CLEXI connecting ... CLEXI reconnecting after unexpected close. Try: 1 CLEXI closed. Reason: 1006 Broadcaster event: {"broadcast":{"client":"r1_chrome_app_v0.22.0","deviceId":"r1","sepia-wake-word":{"state":"active"}}} Broadcaster event: {"broadcast":{"client":"r1_chrome_app_v0.22.0","deviceId":"r1","event":{"state":"active","user":"uid1007"}}}

Woran könnte es liegen? Habe ich etwas falsch eingerichtet? Verbindung über LAN oder WLAN machen keinen Unterschied, weder beim Client noch beim Server.

Viele Grüße und danke schon einmal!

[sepia-assistant]

Hi und willkommen :-)

Kannst du ungefähr sagen welcher Zeitraum zwischen den Disconnects liegt? Eher 45min oder eher 4h? Kommt der Disconnect auch wenn der Client zwischendurch benutzt wurde? Oder nur nach "Leerlauf"?

v2.5.1 wird einige neue Features haben, die Verbindung und Reloads zuverlässiger machen, mit v2.5.0 wäre allerdings normalerweise nur zu erwarten, dass nach 4h Inaktivität einmal die Verbindung zum SEPIA Chat Server neu aufgebaut wird.

Grüße, Florian

[rubipopubi]

Hey, danke für die schnelle Antwort. Sind eher 45 Sekunden zwischen den Reconnects, gefühlt noch weniger.

[sepia-assistant]

Oh :-/ Das klingt eher danach, dass die Verbindung abgelehnt wird. Kannst du mal die CLEXI ID prüfen ("id": "clexi-123" in den CLEXI settings und "clexiServerId": "clexi-123" in den Client settings)?

[rubipopubi]

Habe nochmal nachgeschaut. Das passt alles eigentlich zusammen. :( Hatte testweise mal den Standard (clexi-123) durch r1 in beidem ersetzt. Das hat aber keinen Unterschied gemacht. Die Verbindung funktioniert ja jedes Mal, wenn ich neu verbinde. Nur kommt dann (wie ich festgestellt habe, nicht immer bzw. manchmal erst nach einigen Minuten, dann aber alle xx Sekunden) der Verbindungsabbruch und nach dem Reconnect horcht der Rpi nicht mehr nach dem Wakeword. Hatte mich gefragt, ob der Server verantwortlich ist. Der läuft au dem RPi4 mit 2gb Ram (könnte ihn aber sofort gegen einen 4er mit 4GB Ram austauschen), die Auslastung scheint aber kein Problem zu sein. Kann es an Marytts liegen?

[sepia-assistant]

Die Verbindung funktioniert ja jedes Mal, wenn ich neu verbinde. Nur kommt dann (wie ich festgestellt habe, nicht immer bzw. manchmal erst nach einigen Minuten, dann aber alle xx Sekunden) der Verbindungsabbruch und nach dem Reconnect horcht der Rpi nicht mehr nach dem Wakeword.

Das klingt wirklich sehr ungewöhnlich :thinking: . Auffällig im Fehler-Log von oben ist, dass der Client nur einmal am Anfang als 'active' auftaucht ({"state":"active","user":"uid1007"}) und dann in der Disconnect Loop mit dem CLEXI Server landet. Wenn die Verbindung SEPIA Server <-> SEPIA Client das Problem wäre sollte das eigentlich keinen CLEXI Server disconnect erzeugen. Kannst du mal in folgenden Logs gucken nach Hinweisen:

• ~/clexi/log.out (SEPIA Client)
• ~/SEPIA/sepia-assist-server/log.out (SEPIA Server)
• ~/SEPIA/sepia-websocket-server-java/log.out (SEPIA Server)

Hatte mich gefragt, ob der Server verantwortlich ist. Der läuft au dem RPi4 mit 2gb Ram (könnte ihn aber sofort gegen einen 4er mit 4GB Ram austauschen), die Auslastung scheint aber kein Problem zu sein. Kann es an Marytts liegen?

MaryTTS frisst tatsächlich viel RAM, aber 2GB müssten reichen. Sonst läuft nichts anderes mehr auf dem RPi4?

[rubipopubi]

/clexi/log.out zeigt folgendes:

Server with ID 'clexi-123' running at: http://127.0.0.1:8080 Hostname: localhost - SSL: false CLEXI Xtensions loaded: 3

/SEPIA/sepia-assist-server/log.out zeigte während einiger reconnects folgendes:

2020-08-29 10:24:42 LOG - USER uid1007 used SERVICE chat - TS: 1598689482461 - LANGUAGE: de - CLIENT: pi3_chrome_app_v0.22.0 - API: v2.5.0 2020-08-29 10:25:13 LOG - USER uid1007 used SERVICE smartdevice - TS: 1598689513750 - LANGUAGE: de - CLIENT: pi3_chrome_app_v0.22.0 - API: v2.5.0 2020-08-29 10:25:29 LOG - USER uid1007 used SERVICE smartdevice - TS: 1598689529633 - LANGUAGE: de - CLIENT: pi3_chrome_app_v0.22.0 - API: v2.5.0 2020-08-29 10:27:37 LOG - USER uid1007 used SERVICE events_personal - TS: 1598689657942 - LANGUAGE: de - CLIENT: pi3_chrome_app_v0.22.0 - API: v2.5.0 2020-08-29 10:27:37 LOG - USER uid1007 used SERVICE timer - TS: 1598689657959 - LANGUAGE: de - CLIENT: pi3_chrome_app_v0.22.0 - API: v2.5.0 2020-08-29 10:27:37 LOG - USER uid1007 used SERVICE timer - TS: 1598689657978 - LANGUAGE: de - CLIENT: pi3_chrome_app_v0.22.0 - API: v2.5.0 2020-08-29 10:33:46 LOG - USER uid1007 used SERVICE chat - TS: 1598690026581 - LANGUAGE: de - CLIENT: pi3_chrome_app_v0.22.0 - API: v2.5.0 2020-08-29 10:33:54 LOG - DuckDNS-worker: IP has been updated! (73 time(s)) It took (ms): 1290, average (ms): 784 2020-08-29 10:48:51 LOG - RSS-feed-worker: 45 feeds have been updated! (3 time(s)) It took (ms): 24274, average (ms): 29472 2020-08-29 10:49:48 LOG - USER uid1007 used SERVICE chat - TS: 1598690988256 - LANGUAGE: de - CLIENT: pi3_chrome_app_v0.22.0 - API: v2.5.0

Vielleicht ist das hier was? /SEPIA/sepia-websocket-server-java/log.out:

2020-08-29 08:32:25 [qtp2722054-18] INFO SepiaAuthenticationHandler - Authenticated: uid1005, roles: ["user","assistant"], deviceId: serv1 2020-08-29 09:28:32 [qtp2722054-17] INFO SepiaAuthenticationHandler - Authenticated: uid1007, roles: ["smarthomeguest"], deviceId: pi3 2020-08-29 09:28:32 [qtp2722054-19] INFO ChatsElasticsearchDb - getAllChannelsWithMissedMassegesForUser - restored data for user ID 'uid1007' in 8ms. 2020-08-29 09:34:07 [qtp2722054-16] INFO SepiaAuthenticationHandler - Authenticated: uid1007, roles: ["smarthomeguest"], deviceId: pi3 2020-08-29 09:35:35 [qtp2722054-19] INFO SepiaAuthenticationHandler - Authenticated: uid1007, roles: ["smarthomeguest"], deviceId: pi3 2020-08-29 10:17:26 [qtp2722054-12] INFO SepiaAuthenticationHandler - Authenticated: uid1007, roles: ["smarthomeguest"], deviceId: pi3 2020-08-29 10:19:11 [qtp2722054-13] INFO SepiaAuthenticationHandler - Authenticated: uid1007, roles: ["smarthomeguest"], deviceId: pi3 2020-08-29 10:24:36 [qtp2722054-13] INFO SepiaAuthenticationHandler - Authenticated: uid1007, roles: ["smarthomeguest"], deviceId: pi3 2020-08-29 10:27:36 [qtp2722054-19] INFO SepiaAuthenticationHandler - Authenticated: uid1007, roles: ["smarthomeguest"], deviceId: pi3 2020-08-29 10:27:36 [qtp2722054-19] ERROR SepiaSocketHandler - SepiaSocketHandler reported: null

Rein zeitlich und ähnlich frequentiert finde ich aber nichts, was mit den reconnects korrespondiert.

[rubipopubi]

Kurze Rückmeldung: Das Problem existiert auf mehreren Clients, die ich getestet habe, findet mittlerweile aber seltener statt. Nach einer unbestimmten Zeit schaltet sich die Wakeworderkennung ab, ich muss sie dann manuell wieder reaktivieren - was zwar nicht dramatisch, aber ja nicht Sinn der Sache ist.

[fquirin]

Hab gerade noch mal auf die Logs geguckt. Man sieht zwar die Reconnects aber keinen Grund dafür :-/ Eine Sache ist auffällig sollte aber theoretisch kein Problem sein: Bei der Rollenzuweisung für uid1007 scheint die Rolle "User" gelöscht worden zu sein (das Interface dafür habe ich für 2.5.1 schon verbessert).

Kurze Rückmeldung: Das Problem existiert auf mehreren Clients, die ich getestet habe, findet mittlerweile aber seltener statt. Nach einer unbestimmten Zeit schaltet sich die Wakeworderkennung ab, ich muss sie dann manuell wieder reaktivieren - was zwar nicht dramatisch, aber ja nicht Sinn der Sache ist.

Manuell reaktivieren heißt den Client reload triggern? Im FHEM Forum wurde mal ein ähnliches Problem gemeldet. Ich werde kommende Tage mal einen neuen Langzeittest starten mit der aktuellsten Version. In der Zwischenzeit etwas, was eventuell Abhilfe schaffen könnte: https://github.com/SEPIA-Framework/sepia-docs/issues/63#issuecomment-682451385 (die Skripte, der Kommentar zum Audiosystem kann ignoriert werden)

[rubipopubi]

Manuell reaktivieren heißt den Client reload triggern? Im FHEM Forum wurde mal ein ähnliches Problem gemeldet. Ich werde kommende Tage mal einen neuen Langzeittest starten mit der aktuellsten Version. In der Zwischenzeit etwas, was eventuell Abhilfe schaffen könnte: #63 (comment) (die Skripte, der Kommentar zum Audiosystem kann ignoriert werden)

Genau, ich muss den reload triggern, dann startet die Wakeworderkennung wieder. Die Scripts habe ich auf einem Client bereits installiert, da ich das 4mic-array mit den USB Speakern zum laufen bringen wollte. Das hat aber bei mir keine Auswirkung auf das beschriebene Problem. Ich werde zwischenzeitlich mal testweise alles was sepiarelated ist über einen separaten Wlanrouter bzw. Netzwerk anbinden und schauen ob das was an den Reconnects ändert. Scheint mir zwar unwahrscheinlich, aber man weiß ja nie.

Edit: mir ist aufgefallen, dass es gehäuft (fast immer) auftritt, wenn ich einen zweiten Pi Client einschalte. Dann verliert der bereits aktive Pi Client seine Wakeworderkennung.

Wie könnte ich denn als suboptimale Zwischenlösung mit so wenig wie möglich Manipulation des Gesamtsystems sowas wie nen automatischen Reload trigger umsetzen?

[fquirin]

Edit: mir ist aufgefallen, dass es gehäuft (fast immer) auftritt, wenn ich einen zweiten Pi Client einschalte. Dann verliert der bereits aktive Pi Client seine Wakeworderkennung.

Sorry es hat etwas lange gedauert diesmal mit ner Antwort :-| aber: Das ist eine interessante Info. Laufen die Clients mit der selben Device-ID? Falls ja kann dann immer nur ein Client aktiv sein, die WW Erkennung sollte aber eigentlich trotzdem gehen. Ich habe die neuste Version des Client jetzt seit einem Tag wieder im Dauerbetrieb und bisher keine Probleme. Ich beobachte mal noch etwas weiter.

Wie könnte ich denn als suboptimale Zwischenlösung mit so wenig wie möglich Manipulation des Gesamtsystems sowas wie nen automatischen Reload trigger umsetzen?

Die Reload Funktion, die man über CLEXI senden kann lässt sich theoretisch automatisieren. Ich habe dafür schon mal angefangen einen Node.js Client zu schreiben, der komplett unabhängig laufen könnte z.B. mit Node-Red, da ist das CLEXI Interface allerdings noch nicht fertig. Die direkteste (aber nicht einfache) Möglichkeit zur Zeit wäre die CLEXI Javascript Library zu benutzen und sich was damit zu bauen.