Telegram instant messaging TelegramBot - Empfangen und Senden per FHEM

[gloob]

Ich kann die Probleme auch bestätigen.

Werde folgendes mal testen:

Habe aktuell pollingTimeout auf 0 gesetzt und seitdem hängt sich FHEM nicht mehr auf

[macmattes]

nur kurz ne meldung, hier das gleiche Problem.

Fhem hängt für eien  zeit x und aus die SSl read meldung kommt im log.

hab mir mit neme Polling timeout von 1 s geholfen, fhem hängt damit zumindets nicht so lange fest, aber telegram geht , trotz fehler meldung

[mbrak]

Hab gestern gegen 23:30 Uhr ein Update gemacht. Telegram geht einwandfrei ohne Hänger. Das System läuft stabil ohne logeinträge.

Gruß Michael

[viegener]

@macmattes, gloob, neumann, haus-automatisierung.com, tschu, Papaloewe, etc:
Da das Problem bei mir (und wohl auch anderen) mit der neusten Version nicht auftritt, brauche ich Eure Hilfe

1) Ich vermute ihr habt nach dem update ein restart von FHEM gemacht?
2) Könnt Ihr mir ein paar Infos zu Plattform/Betriebssystem und perl-version geben?
3) Gibt es andere Auffälligkeiten / Fehlermeldungen im Log?
4) Könnt ihr mal (bei pollingTimeout > 0) ein

Code Auswählen Erweitern

set <euertbot> reset durchführen und dann schauen ob das Hängen weiterhin auftritt
5) Wenn das nicht hilft: Könnt Ihr mal kurzzeitig global das System auf verbose 5 setzen und mir einen Logausschnitt zur Verfügung stellen?

Momentan ist mir der Effekt bei der geringen Anzahl von Änderungen noch ein Rätsel, deshalb die etwas breite Abfrage...

[neumann]

Also ich hatte schon eine Weile nicht mehr geupdatet und das Problem ist auf einmal gestern aufgetreten, dann habe ich geupdatet, hat allerdings nichts geholfen (natürlich mit Neustart).
Ich bin auf einem RasPi 3 Perl v5.20.2
Auffälligkeiten im Log gibt es nicht, bei dem Ausschnitt, den ich gepostet hatte war global verboose auf 5, bei jedem Hänger sah der Log gleich aus.
Das mit dem Reset werde ich versuchen.

[viegener]

Also ich hatte schon eine Weile nicht mehr geupdatet und das Problem ist auf einmal gestern aufgetreten, dann habe ich geupdatet, hat allerdings nichts geholfen (natürlich mit Neustart).
Ich bin auf einem RasPi 3 Perl v5.20.2
Auffälligkeiten im Log gibt es nicht, bei dem Ausschnitt, den ich gepostet hatte war global verboose auf 5, bei jedem Hänger sah der Log gleich aus.
Das mit dem Reset werde ich versuchen.

Danke für die schnelle Reaktion: Frage: Das Problem ist also aufgetreten BEVOR Du das update gemacht hast?

[neumann]

ja, da bin ich mir ziemlich sicher

[awel]

Raspberry Pi 1B
Perl Version 5.14.2
sonst keine Auffälligkeiten im Log

gestern gab es auch ein Update der HttpUtils - könnte da ein Zusammenhang bestehen?

[viegener]

@awel: Das habe ich mir auch angeschaut, ich kann aber nicht erkennen wie das zusammenhängen könnte, denn es geht nur um digest authentication? Das sollte eigentlich beitelegram nicht passieren, da die authentifizierung über den URL erfolgt.

@awel: Könntest Du mal das Attribut utf8special auf 1 setzen (oder wenn bereits gesetzt auf 0)?

@neumann: Das ist verwirrend, denn dann ist ja am telegrambot-Modul keine Änderung passiert, während bei den anderen nach dem update das Problem aufgetaucht ist.

Bitte beschreibt welches Problem ihr habt, ob es hängt  und was im log steht --> "SSL wants a read first:" ist etwas anderes als das "write to https://api.telegram.org:443 timed out"

[macmattes]

mac mini osx 10.9 und Perl 5.24 über macports installiert
habe die hänger gestern bemerkt und dann auf verdacht ein update gemacht, bin so erst auf die SSL fehler gestossen
habs mit der letzten Modulversion versucht, ist auch der Fehler
Reset half nur kurz

anbei 3 log ausschnitte, der dritte ist nach Telegram gefiltert, und ended beim hängen

wenn ich im netzt nach 'SSL wants a read first' suche bin ich auf was gestossen
http://www.perlmonks.org/?node_id=1188364


2017.08.16 17:45:57 4: <hidden>: HTTP response code 200
2017.08.16 17:45:57 4: HttpUtils <hidden>: Got data, length: 23
2017.08.16 17:45:57 5: HttpUtils response header:
HTTP/1.1 200 OK
Server: nginx/1.10.0
Date: Wed, 16 Aug 2017 15:45:24 GMT
Content-Type: application/json
Content-Length: 23
Connection: close
Access-Control-Allow-Origin: *
Access-Control-Allow-Methods: GET, POST, OPTIONS
Access-Control-Expose-Headers: Content-Length,Content-Type,Date,Server,Connection
Strict-Transport-Security: max-age=31536000; includeSubdomains
2017.08.16 17:45:57 5: TelegramBot_Callback fhem_bot: called from Polling
2017.08.16 17:45:57 5: TelegramBot_Callback fhem_bot: data returned :{"ok":true,"result":[]}:
2017.08.16 17:45:57 5: TelegramBot_Deepencode fhem_bot: found an ARRAY
2017.08.16 17:45:57 5: TelegramBot_Deepencode fhem_bot: encoded a String from :1: to :1:
2017.08.16 17:45:57 5: TelegramBot_Deepencode fhem_bot: found a HASH
2017.08.16 17:45:57 5: TelegramBot_Callback fhem_bot: after encoding
2017.08.16 17:45:57 5: TelegramBot_Callback fhem_bot: polling returned result? 0
2017.08.16 17:45:57 5: UpdatePoll fhem_bot: number of results 0
2017.08.16 17:45:57 5: TelegramBot_UpdatePoll fhem_bot: called
2017.08.16 17:45:57 5: TelegramBot_readToken: Read Telegram API token from file
2017.08.16 17:45:57 4: TelegramBot_UpdatePoll fhem_bot: initiate polling with nonblockingGet with 120s
2017.08.16 17:45:57 4: HttpUtils url=<hidden>
2017.08.16 17:45:57 4: TelegramBot_Callback fhem_bot: resulted in SUCCESS from Polling



2017.08.16 18:05:15 4: <hidden>: HTTP response code 200
2017.08.16 18:05:15 4: HttpUtils <hidden>: Got data, length: 23
2017.08.16 18:05:15 5: HttpUtils response header:
HTTP/1.1 200 OK
Server: nginx/1.10.0
Date: Wed, 16 Aug 2017 16:04:41 GMT
Content-Type: application/json
Content-Length: 23
Connection: close
Access-Control-Allow-Origin: *
Access-Control-Allow-Methods: GET, POST, OPTIONS
Access-Control-Expose-Headers: Content-Length,Content-Type,Date,Server,Connection
Strict-Transport-Security: max-age=31536000; includeSubdomains
2017.08.16 18:05:15 5: TelegramBot_Callback fhem_bot: called from Polling
2017.08.16 18:05:15 5: TelegramBot_Callback fhem_bot: data returned :{"ok":true,"result":[]}:
2017.08.16 18:05:15 5: TelegramBot_Deepencode fhem_bot: encoded a String from :1: to :1:
2017.08.16 18:05:15 5: TelegramBot_Deepencode fhem_bot: found an ARRAY
2017.08.16 18:05:15 5: TelegramBot_Deepencode fhem_bot: found a HASH
2017.08.16 18:05:15 5: TelegramBot_Callback fhem_bot: after encoding
2017.08.16 18:05:15 5: TelegramBot_Callback fhem_bot: polling returned result? 0
2017.08.16 18:05:15 5: UpdatePoll fhem_bot: number of results 0
2017.08.16 18:05:15 5: TelegramBot_UpdatePoll fhem_bot: called
2017.08.16 18:05:15 5: TelegramBot_readToken: Read Telegram API token from file
2017.08.16 18:05:15 4: TelegramBot_UpdatePoll fhem_bot: initiate polling with nonblockingGet with 120s
2017.08.16 18:05:15 4: HttpUtils url=<hidden>
2017.08.16 18:05:15 4: TelegramBot_Callback fhem_bot: resulted in SUCCESS from Polling




mini:~ root# /opt/local/bin/perl /usr/share/fhem/fhem.pl /etc/fhem.cfg | grep Telegram
2017.08.16 18:10:19 5: Cmd: >define fhem_bot TelegramBot<
2017.08.16 18:10:19 5: Loading /usr/share/fhem/FHEM/50_TelegramBot.pm
2017.08.16 18:10:19 3: TelegramBot_Define fhem_bot: called
2017.08.16 18:10:19 5: TelegramBot_readToken: Read Telegram API token from file
2017.08.16 18:10:19 4: TelegramBot_Setup fhem_bot: called
2017.08.16 18:10:19 5: TelegramBot_readToken: Read Telegram API token from file
2017.08.16 18:10:19 5: TelegramBot_readToken: Read Telegram API token from file
2017.08.16 18:10:19 5: TelegramBot_DoUrlCommand fhem_bot: called
2017.08.16 18:10:20 2: TelegramBot_DoUrlCommand fhem_bot: FAILED http access returned error :https://api.telegram.org/xxxxxxxxxx/getMe: Can't connect(2) to https://api.telegram.org:443:  SSL wants a read first:
2017.08.16 18:10:20 5: TelegramBot_DoUrlCommand fhem_bot: called
agent: TelegramBot/1.0
User-Agent: TelegramBot/1.0
2017.08.16 18:10:20 4: TelegramBot_DoUrlCommand OK with result
2017.08.16 18:10:20 4: TelegramBot_ResetPolling fhem_bot: called
2017.08.16 18:10:20 4: TelegramBot_ResetPolling fhem_bot: finished
2017.08.16 18:10:20 4: TelegramBot_Setup fhem_bot: ended
2017.08.16 18:10:20 5: TelegramBot_Attr fhem_bot: called
2017.08.16 18:10:20 5: TelegramBot_Attr fhem_bot: set  on DbLogExclude to .*
2017.08.16 18:10:20 5: TelegramBot_Attr fhem_bot: called
2017.08.16 18:10:20 5: TelegramBot_Attr fhem_bot: set  on cmdFavorites to Favs
2017.08.16 18:10:20 5: TelegramBot_Attr fhem_bot: called
2017.08.16 18:10:20 5: TelegramBot_Attr fhem_bot: set  on cmdKeyword to Doit
2017.08.16 18:10:20 5: TelegramBot_Attr fhem_bot: called
2017.08.16 18:10:20 5: TelegramBot_Attr fhem_bot: set  on cmdRestrictedPeer to xxxxxxxxx
2017.08.16 18:10:20 5: TelegramBot_Attr fhem_bot: called
2017.08.16 18:10:20 5: TelegramBot_Attr fhem_bot: set  on defaultPeer to xxxxxxxx
2017.08.16 18:10:20 5: TelegramBot_Attr fhem_bot: called
2017.08.16 18:10:20 5: TelegramBot_Attr fhem_bot: set  on favorites to /ok=set Dev_Alarm_Cancel Cancel; /scharf=set Dev_Alarm_Arm Arm; /unscharf=set Dev_Alarm_Disarm Disarm
2017.08.16 18:10:20 4: TelegramBot_SplitFavoriteDef cmd :/ok=set Dev_Alarm_Cancel Cancel:
2017.08.16 18:10:20 4: TelegramBot_SplitFavoriteDef cmd : /scharf=set Dev_Alarm_Arm Arm:
2017.08.16 18:10:20 4: TelegramBot_SplitFavoriteDef cmd : /unscharf=set Dev_Alarm_Disarm Disarm:
2017.08.16 18:10:20 5: TelegramBot_Attr fhem_bot: called
2017.08.16 18:10:20 5: TelegramBot_Attr fhem_bot: set  on group to IO_Gateway
2017.08.16 18:10:20 5: TelegramBot_Attr fhem_bot: called
2017.08.16 18:10:20 5: TelegramBot_Attr fhem_bot: set  on pollingTimeout to 120
2017.08.16 18:10:20 4: TelegramBot_ResetPolling fhem_bot: called
2017.08.16 18:10:20 4: TelegramBot_ResetPolling fhem_bot: finished
2017.08.16 18:10:20 5: TelegramBot_Attr fhem_bot: called
2017.08.16 18:10:20 5: TelegramBot_Attr fhem_bot: set  on room to Unsorted
2017.08.16 18:10:20 5: TelegramBot_Attr fhem_bot: called
2017.08.16 18:10:20 5: TelegramBot_Attr fhem_bot: set  on verbose to 5
2017.08.16 18:10:20 4: TelegramBot_State Contacts hash has now :2:
2017.08.16 18:10:23 4: TelegramBot_Set fhem_bot: called
2017.08.16 18:10:23 4: TelegramBot_Set fhem_bot: Processing TelegramBot_Set( ? )
2017.08.16 18:10:23 4: TelegramBot_Set fhem_bot: called
2017.08.16 18:10:23 4: TelegramBot_Set fhem_bot: Processing TelegramBot_Set( ? )
2017.08.16 18:10:23 4: TelegramBot_Set fhem_bot: called
2017.08.16 18:10:23 4: TelegramBot_Set fhem_bot: Processing TelegramBot_Set( ? )
2017.08.16 18:10:23 5: TelegramBot_Get fhem_bot: called
2017.08.16 18:10:23 5: TelegramBot_Get fhem_bot: Processing TelegramBot_Get( ? )
2017.08.16 18:10:23 4: TelegramBot_Set fhem_bot: called
2017.08.16 18:10:23 4: TelegramBot_Set fhem_bot: Processing TelegramBot_Set( ? )
2017.08.16 18:10:50 4: TelegramBot_RestartPolling fhem_bot: called
2017.08.16 18:10:50 5: TelegramBot_UpdatePoll fhem_bot: called
2017.08.16 18:10:50 5: TelegramBot_readToken: Read Telegram API token from file
2017.08.16 18:10:50 4: TelegramBot_UpdatePoll fhem_bot: initiate polling with nonblockingGet with 120s
2017.08.16 18:10:50 4: TelegramBot_RestartPolling fhem_bot: finished
agent: TelegramBot/1.0
User-Agent: TelegramBot/1.0
2017.08.16 18:11:28 4: TelegramBot_Set fhem_bot: called
2017.08.16 18:11:28 4: TelegramBot_Set fhem_bot: Processing TelegramBot_Set( ? )
2017.08.16 18:11:28 4: TelegramBot_Set fhem_bot: called
2017.08.16 18:11:28 4: TelegramBot_Set fhem_bot: Processing TelegramBot_Set( ? )
2017.08.16 18:11:28 5: TelegramBot_Get fhem_bot: called
2017.08.16 18:11:28 5: TelegramBot_Get fhem_bot: Processing TelegramBot_Get( ? )
2017.08.16 18:11:40 5: TelegramBot_Callback fhem_bot: called from Polling
2017.08.16 18:11:40 5: TelegramBot_Callback fhem_bot: data returned :{"ok":true,"result":[]}:
2017.08.16 18:11:40 5: TelegramBot_Deepencode fhem_bot: found an ARRAY
2017.08.16 18:11:40 5: TelegramBot_Deepencode fhem_bot: encoded a String from :1: to :1:
2017.08.16 18:11:40 5: TelegramBot_Deepencode fhem_bot: found a HASH
2017.08.16 18:11:40 5: TelegramBot_Callback fhem_bot: after encoding
2017.08.16 18:11:40 5: TelegramBot_Callback fhem_bot: polling returned result? 0
2017.08.16 18:11:40 5: TelegramBot_UpdatePoll fhem_bot: called
2017.08.16 18:11:40 5: TelegramBot_readToken: Read Telegram API token from file
2017.08.16 18:11:40 4: TelegramBot_UpdatePoll fhem_bot: initiate polling with nonblockingGet with 120s
2017.08.16 18:11:40 4: TelegramBot_Callback fhem_bot: resulted in SUCCESS from Polling

[viegener]

@macmattes: OK, also hängt es also auch bei Dir nicht direkt mit dem letzten Update zusammen.
Auch der "SSL wants a read first" ist unkritisch, der tritt nach dem Neustart wohl auf, aber die folgenden Logs zeigen, dass Polling grundsätzlich funktioniert (kein timeout on write o.ä.). Nach meiner Recherche vor einiger Zeit ist hier ein SSL-Fehler beteiligt, der aber auch laut Deinem Log nur einmalig auftritt.

Das Log ist aber interessant, was den Hänger angeht. Zum Zeitpunkt des Hängers läuft eigentlich kein Code des TelegramBot-Moduls

Code Auswählen Erweitern

2017.08.16 17:45:57 4: HttpUtils url=<hidden>
2017.08.16 17:45:57 4: TelegramBot_Callback fhem_bot: resulted in SUCCESS from Polling

Danach wird die Kontrolle zurück an FHEM übergeben und der http-request läuft im Hintergrund weiter (im HTTPUtils-Modul). Sichtbar ist, dass der Request erfolgreich zurückkommt von Telegram:

Code Auswählen Erweitern

2017.08.16 18:05:15 4: <hidden>: HTTP response code 200
...

und dann normal weiterverarbeitet wird und dann geht es von vorne los.

Leider gibt das alles keine Erklärung, warum der Server hängt und was er in der Zeit macht und warum das jetzt auftritt...

[Tueftler1983]

Hier das selbe Problem wenn ich pollingTimeout auf 0 setze läuft fhem ganz normal.
Habe noch nen Auszug aus dem Log ab dem Moment wo fhem hängt +- 1min



2017.08.16 22:19:16 5: HttpUtils response header:
HTTP/1.1 200 OK
Server: nginx/1.10.0
Date: Wed, 16 Aug 2017 20:19:16 GMT
Content-Type: application/json
Content-Length: 23
Connection: close
Access-Control-Allow-Origin: *
Access-Control-Allow-Methods: GET, POST, OPTIONS
Access-Control-Expose-Headers: Content-Length,Content-Type,Date,Server,Connection
Strict-Transport-Security: max-age=31536000; includeSubdomains
2017.08.16 22:19:16 5: TelegramBot_Callback FHEMBOT: called from Polling
2017.08.16 22:19:16 5: TelegramBot_Callback FHEMBOT: data returned :{"ok":true,"result":[]}:
2017.08.16 22:19:16 5: TelegramBot_Deepencode FHEMBOT: found an ARRAY
2017.08.16 22:19:16 5: TelegramBot_Deepencode FHEMBOT: encoded a String from :true: to :true:
2017.08.16 22:19:16 5: TelegramBot_Deepencode FHEMBOT: found a HASH
2017.08.16 22:19:16 5: TelegramBot_Callback FHEMBOT: after encoding
2017.08.16 22:19:16 5: TelegramBot_Callback FHEMBOT: polling returned result? 0
2017.08.16 22:19:16 5: UpdatePoll FHEMBOT: number of results 0
2017.08.16 22:19:16 5: TelegramBot_UpdatePoll FHEMBOT: called
2017.08.16 22:19:16 5: TelegramBot_readToken: Read Telegram API token from file
2017.08.16 22:19:16 4: TelegramBot_UpdatePoll FHEMBOT: initiate polling with nonblockingGet with 120s
2017.08.16 22:19:16 4: HttpUtils url=<hidden>
2017.08.16 22:19:16 4: TelegramBot_Callback FHEMBOT: resulted in SUCCESS from Polling

[Avatar]

Hallo Zusammen
Ich habe genau das gleiche Problem, dass FHEM dann einfach blockiert ist.
Dies hat meines erachtens nichts mit der neuen Version zu tun, sonder aufgefallen ist es mir am 15.8. und das im laufe des Tages um ca. 14Uhr hat es angefangen.

Grüsse

[Frank_Huber]

kann es eventuell auch mit NICHT gesetztem DNS im global zusammenhängen?
Die Idee kam vorhin in der Facebook Gruppe auf.

Und Ich habe keine Probleme mut Telegram, habe aber den DNS gesetzt.

[mbrak]

Möglich! Habe aufgrund des Wettermoduls auch den DNS in global gesetzt. Auch keine Probleme mit Telegram!