Ständige Neustarts von Alexa-FHem Connector

[ReneR1986]

Hallo zusammen,

FHEM läuft bei mir in einer Docker Umgebung.
Leider bekomme ich alle 5 Minuten folgenden Fehler.

3/28/2020, 1:10:18 PM] Server emitted error: {"code":"EADDRINUSE","errno":"EADDRINUSE","syscall":"listen","address":"127.0.0.1","port":39901}
[3/28/2020, 1:10:18 PM] Terminating - starting the listener not possible (another instance running?)

Ich kann jedoch bisher nicht erkennen, dass dieser Port schon verwendet wird.
netstat zeigt nur eine Port an und der wird von localhost genutzt. Sieht für micht erstmal richtig aus.

[Kusselin]

Hi, hab eben mal ins Log geschaut...habe auch stündlich die alexa start/stop meldungen..

Hier das alexa log

Code Auswählen Erweitern

2020-07-22 20:00:06 caching: dmy_Alexa_Familie_Woche-state: off
[2020-7-22 8:00:06 PM] [FHEM] dmy_Alexa_Geburtstag is switch
[2020-7-22 8:00:06 PM] [FHEM] dmy_Alexa_Geburtstag has
[2020-7-22 8:00:06 PM] [FHEM]   On [state;on,off]
[2020-7-22 8:00:06 PM] [FHEM] dmy_Alexa_Geburtstag will not send proactive events
[2020-7-22 8:00:06 PM] [FHEM] dmy_Alexa_Geburtstag uses ID: 5f077377-f33f-7d29-a515-70a5141994a750d0
  2020-07-22 20:00:06 caching: dmy_Alexa_Geburtstag-state: off
[2020-7-22 8:00:06 PM] BearerToken '...4E28A' read from alexa
[2020-7-22 8:00:06 PM] 39_alexa.pm is new version: true
[2020-7-22 8:00:06 PM] sshautoconf: completed successfully
[2020-7-22 8:00:06 PM] *** SSH: proxy configuration set up done
[2020-7-22 8:00:06 PM] Reading alexaFHEM.ProxyConnection set to starting;; starting SSH
[2020-7-22 8:00:06 PM] [FHEM]   executing: http://127.0.0.1:8083/fhem?cmd=%7B%24defs%7Balexa%7D-%3E%7B%22active%22%7D%20%3D%201%3B%3Bundef%7D%3Bsetreading%20alexa%20alexaFHEM.ProxyConnection%20starting%3B%3B%20starting%20SSH%3B%7B%24defs%7Balexa%7D-%3E%7B%22active%22%7D%20%3D%200%3B%3Bundef%7D&fwcsrf=csrf_351728676652254&XHR=1
[2020-7-22 8:00:06 PM] Starting SSH with -R 1234:127.0.0.1:35091 -oServerAliveInterval=90 -i /opt/fhem/.ssh/id_rsa -p 58824 fhem-va.fhem.de
[2020-7-22 8:00:07 PM] Reading alexaFHEM.ProxyConnection set to running;; SSH connected
[2020-7-22 8:00:07 PM] [FHEM]   executing: http://127.0.0.1:8083/fhem?cmd=%7B%24defs%7Balexa%7D-%3E%7B%22active%22%7D%20%3D%201%3B%3Bundef%7D%3Bsetreading%20alexa%20alexaFHEM.ProxyConnection%20running%3B%3B%20SSH%20connected%3B%7B%24defs%7Balexa%7D-%3E%7B%22active%22%7D%20%3D%200%3B%3Bundef%7D&fwcsrf=csrf_351728676652254&XHR=1
[2020-7-22 8:00:07 PM] *** SSH: proxy connection established
[2020-7-22 8:00:07 PM] SSH: Welcome at the reverse proxy!  This pseudoshell does not react to any input - do not get irritated. 


[nobodyisp]

Hallo zusammen,

gibt es zu dem Problem schon was neues? Ich bin schon am verzweifeln. Ich habe die gleiche Fehlermeldung minütlich und es wird immer der Tunnel als auch alexa-Fhem beendet. Ich finde die Ursache einfach nicht und auch keine funktionierende Lösung online.

Hier noch mal die Meldung :
[20.1.2021, 23:58:54] Server emitted error: {"code":"EADDRINUSE","errno":"EADDRINUSE","syscall":"listen","address":"127.0.0.1","port":40439}
[20.1.2021, 23:58:54] Terminating - starting the listener not possible (another instance running?)

[gvzdus]

2 Annahmen:

• 40439 ist ein zufällig gewürfelter Port - da gibt es jedes Mal eine andere Nummer, richtig?
  
• Alexa startet durchaus, und dann gibt es plötzlich Ärger?

Ich habe bei mir in der Historie am 5. Januar so einen Fall gefunden. Natürlich lief alexa-fhem schon lange auf diesem Port, weswegen die eigentlich Meldung sinnlos ist: Wenn alexa-fhem den Port sich initial reservieren konnte, kann ihm den nicht plötzlich jemand wegnehmen. Ich habe mal nach Bugs in NodeJS gesucht, aber ich komme nur auf Hits von Verzweifelten, die nicht wissen, dass ein Port nur von einem Prozess belegt werden kann . Bei mir passierte der Fehler in dem Kontext, dass ich gerade ein Gerät in FHEM gelöscht hatte, und alexa-fhem kurz Kommunikation mit dem FHEM-Server darüber führte. Selbst, wenn diese fehlgeschlagen wäre, hätte sich das nicht auf den Listener-Port auswirken dürfen. Seht Ihr einen Kontext? Mein Node ist 10.21.0 unter Buster / RPi 3B+

[nobodyisp]

Hallo,

also der lokale Port ist zufällig und es wird jede Minute ein neuer Port geöffnet. Ich hab das ganze mal analysiert und musste feststellen, dass Alexa-Fhem auf dem Port bereits lauscht und dann versucht ihn ein zweites mal zu öffnen. Dann kommt es natürlich zu der gezeigten Fehlermeldung und dam Abbruch von Alexa-Fhem als auch zu dem SSH-Tunnel.

Ich nutze NodeJS 10.19.0 auf einem leistungsstarken Proxmox-Server

[gvzdus]

Wie kommst Du zu der Überzeugung, dass alexa-fhem versucht, den Serverport ein zweites Mal zu öffnen? Welche Version von alexa-fhem setzt Du ein?

[nobodyisp]

ich benutze folgende Version :  alexa-fhem@0.5.57

Ich hab dem Prozess Alexa-Fhem mit strace mal auf die Finger geschaut und gesehen, dass er den Port öffnen will, obwohl er schon von dem gleichen Prozess geöffnet wurde. War garnicht so einfach bzw. musste schnell tippen....

wenn das hilft, kann ich mal den kompletten trace posten, ist aber größer ...

Ahja, noch zu der Frage welches Problem ich damit habe: Das Thema ist dass der SSH-Tunnel und Alexa-Fhem minütlich durchstartet werden und nur ca. 30 Sekunden von der Minute wirklich aktiv ist. Sprich die anderenen 30 Sekunden von der Minute sind die Devices von Alexa nicht erreichbar und es nervt, wenn man in der Hälfte aller Fälle erst 30 Sekunden warten muss, bis man den Befehl noch mal an die Alexa absetzen kann.

[gvzdus]

Ich habe jetzt auch mal aktualisiert auf 0.5.57.

Lass' uns doch erst mal eingrenzen, ob alexa-fhem zum zweiten Mal "listenen" will, oder NodeJS schräg ist. Dafür wäre eine Logzeile vor dem Listener sinnvoll.

Verzeichnis ist bei mir: /usr/local/lib/node_modules/alexa-fhem/lib

Hier in der Datei "server.js":

Zeile 179 ändern:
log.error ("Server (proxy) emitted error: " + JSON.stringify(res));

Zeile 189 einfügen (direkt vor "server.listen(..."):
log.info("Start listening for proxy server on ", this._config.sshproxy.port);

Und vielleicht auch noch:
Zeile 362 ändern:
log.error ("Server (normal) emitted error: " + JSON.stringify(res));

Zeile 369 einfügen (direkt vor "server.listen(..."):
log.info ("Start listening for normal server on ", this._config.alexa.port);

Dann in FHEM "set alexa restart"

Ergebnis - viele Zeilen mal weglassend - sollte dann ein:

Code Auswählen Erweitern

[21.1.2021, 20:32:59] Start listening for proxy server on  undefined
[21.1.2021, 20:32:59] Server listening on: http://127.0.0.1:46275 for proxy connections

sein. Und spannend wird es, ob noch einmal "Start listening" auftaucht.

[nobodyisp]

Also, ich hab die Änderungen übernommen, Alexa-Fhem gestoppt und folgenden Befehl abgesetzt :

Code Auswählen Erweitern


sudo -u fhem strace -o strace.log alexa-fhem -D -c /opt/fhem/alexa-fhem.cfg >debug.log 2>&1


Die beiden Logfiles sind angehangen. Hier das wichtigste: ja es kommen zwei "Start listening" innerhalb von knapp einer Minute. Hier die entsprechenden Zeilen:

Code Auswählen Erweitern


[21.1.2021, 23:17:15] Start listening for proxy server on  undefined
[21.1.2021, 23:17:15] Server listening on: http://127.0.0.1:42323 for proxy connections
[21.1.2021, 23:18:02] Start listening for proxy server on  42323
[21.1.2021, 23:18:02] Server  (proxy) emitted error: {"code":"EADDRINUSE","errno":"EADDRINUSE","syscall":"listen","address":"127.0.0.1","port":42323}


Was mach ich falsch?

[gvzdus]

Du machst mutmaßlich nichts falsch. Gibt es bei Dir irgendwas, was periodisch neue Geräte anlegt oder löscht oder am Alexa-Device minütlich etwas macht?

Ich habe einen Verdacht und versuche, ihn mit Andre / justme1968 zu klären.

[nobodyisp]

Hallo,

also in FHEM ist schon ordentlich was los und ja, es werden auch Geräte bzw. at-Devices angelegt, aber es werden keine Devices mit einem Attribute alexaName angelegt. Ich habe aber in letzter Zeit viele Geräte angefasst und verändert.

Das Alexa-Device wird nicht periodisch verändert. Ich hatte es nur inzwischen schon etliche male neu angelegt und auf default zurückgesetzt, um den Fehler einzugrenzen.

[justme1968]

weiter oben war schon ein oder zwei mal ein anderes fhem modul für die probleme verantwortlich.

kannst du bitte testhalber mal fhem auf ein absolutes minimum abspecken? am liebten nur alexa und test dummy zum schalten.

[nobodyisp]

Das ist schon eine Herausforderung, aber ich setzt mich mal ran. Meine fhem.conf ist eine halbes MB groß.

[justme1968]

vermutlich ist es das einfachste wenn du in einer zweiten installation bei 0 anfängst und dein haupt fhem in ruhe lässt.

[gvzdus]

Vielleicht einfacher: Hast Du massenhaft & minütlich Meldungen wie
DELETEATTR
im fhem-Logfile?