Telegram instant messaging TelegramBot - Empfangen und Senden per FHEM

[viegener]

@Tueftler1983: Das kann Dir vermutlich noch niemand sagen, allerdings beseitigt die debug-Version das Problem definitiv nicht, sondern dient nur dazu das Problem einzugrenzen.

Was bisher klar zu sein scheint:
- Problem tritt beim Verbindungsaufbau (SSL handshake) mit telegram auf (und zwar wohl nur mit telegram und nur bei bestimmten Benutzern)
- Hat irgendwann diese Woche angefangen
- Tritt wohl bei Benutzern entweder gar nicht auf oder gehäuft (ständig)

Hypothese: Irgendeine Änderung der Telegram-Server bedingt dieses Problem, wobei das Fehlverhalten (sprich timeout bei perl) irgendwie auch nicht ganz sinnvoll erscheint

@all: Vielleicht könntet Ihr noch ein paar Infos zu Eurer Umgebung mittteilen (perl/Betriebssystem/Plattform), damit man das vielleicht eingrenzen kann?

[Tueftler1983]

Also von mir folgende Infos:

Raspberry PI3

1. Welche Linux-Distributions und -Release ist installiert?
2. Welche Kernel-Version ist installiert?
3. Welche Firmware-Version ist installiert?

root@FHEM_Server:~# cat /etc/os-release
PRETTY_NAME="Raspbian GNU/Linux 8 (jessie)"
NAME="Raspbian GNU/Linux"
VERSION_ID="8"
VERSION="8 (jessie)"
ID=raspbian
ID_LIKE=debian
HOME_URL="http://www.raspbian.org/"
SUPPORT_URL="http://www.raspbian.org/RaspbianForums"
BUG_REPORT_URL="http://www.raspbian.org/RaspbianBugs"
root@FHEM_Server:~#
root@FHEM_Server:~#
root@FHEM_Server:~#
root@FHEM_Server:~# uname -a
Linux FHEM_Server 4.4.38-v7+ #938 SMP Thu Dec 15 15:22:21 GMT 2016 armv7l GNU/Linux
root@FHEM_Server:~#
root@FHEM_Server:~#
root@FHEM_Server:~#
root@FHEM_Server:~# vcgencmd version
Dec  9 2016 15:11:26
Copyright (c) 2012 Broadcom
version 2e557d8dac70add28597c3b449cb52c34588d818 (clean) (release)
root@FHEM_Server:~#

Perl Version:

root@FHEM_Server:~# perl -v

This is perl 5, version 20, subversion 2 (v5.20.2) built for arm-linux-gnueabihf-thread-multi-64int
(with 92 registered patches, see perl -V for more detail)

root@FHEM_Server:~#

[essera]

Habe das selbe Problem:

Seit einigen Tagen Hänger für 5-10 sek.
Habe mir schon einen Wolf gesucht woran das liegt und schon diverse Hardwareteile incl. Cul Stick im Verdacht gehabt. Deshalb hatte ich auch die Update Orgie gestartet. Hier kurz das was ich gemacht habe und zu keiner positiven Veränderung geführt hat.
Habe den Raspi B Version 2 mit Busware CUL Stick V. 1.66, Jessie 8.0
perl 5, version 20, subversion 2 (v5.20.2)

Habe dann Fhem auf die aktuelle Version incl. der letzten Änderungen gebracht - keine Änderung
habe Raspberry komplett auf die aktuelle Version gebracht - keine Änderung
habe Firmware UPdate der Raspi Hardware gemacht - keine Änderung


habe keine SSL Version in FHEMWEB gesetzt
habe Pollintervall bei Telegram auf Standard 205 gelassen

Wenn ich was testen soll bitte Bescheid geben.

[viegener]

Ein Versuch wäre es mal wert mit der Debugversion und der Einstellung "attr global sslVersion SSLv3" zu testen, ob dann weiter timeouts auftreten. Allerdings ist mit der Einstellung keine Verbindung zu telegram möglich, es wäre nur interessant ob es wirklich an unterschiedlichen cipher Einstellungen liegt.

Aber bitte nut temporär SSLv3 ist keine sinnvolle Dauer-Einstellung

[Tueftler1983]

Bei mir ist doch TLSv12:!SSLv3 oder ist das ein unterschied zu dem was du meinst mit SSLv3

[essera]

OK ich habe die beiden Dateien getauscht und unter global
attr global sslVersion SSLv3  gesetzt.
Verbose ist auf 4


Nun erhalte ich folgende Fehlermeldung im LOG:
TelegramBot xxxxx PollingLastError: NonBlockingGet: returned : Can't connect(2) to https://api.telegram.org:443: SSL connect attempt failed because of handshake problems error:14094410:SSL routines:SSL3_READ_BYTES:sslv3 alert handshake failure

[cawe]

Ein paar Informationen, vielleicht hilft es ja, den Fehler einzugrenzen:

1. Ich habe beide Einstellungen zur sslVersion ausprobiert

Code Auswählen Erweitern

attr global sslVersion SSLv23:!SSLv3:!SSLv2
und

Code Auswählen Erweitern

attr global sslVersion TLSv12:!SSLv3:!SSLv2

In beiden Einstellungen treten die Blockaden auf.

2. Logs einer funktionierenden Sequenz und einer blockierten

Code Auswählen Erweitern

2017.08.18 21:28:31 1: HttpUtils - connect2 - in direct readfn
2017.08.18 21:28:31 1: <hidden>: HTTP response code 200
2017.08.18 21:28:31 1: HttpUtils <hidden>: Got data, length: 23
2017.08.18 21:28:31 2: HttpUtils response header:
HTTP/1.1 200 OK
Server: nginx/1.10.1
Date: Fri, 18 Aug 2017 19:29:17 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.18 21:28:31 5: TelegramBot_Callback Vh22Bot: called from Polling
2017.08.18 21:28:31 5: TelegramBot_Callback Vh22Bot: data returned :{"ok":true,"result":[]}:
2017.08.18 21:28:31 5: TelegramBot_Deepencode Vh22Bot: found an ARRAY
2017.08.18 21:28:31 5: TelegramBot_Deepencode Vh22Bot: encoded a String from :true: to :true:
2017.08.18 21:28:31 5: TelegramBot_Deepencode Vh22Bot: found a HASH
2017.08.18 21:28:31 5: TelegramBot_Callback Vh22Bot: after encoding
2017.08.18 21:28:31 5: TelegramBot_Callback Vh22Bot: polling returned result? 0
2017.08.18 21:28:31 5: UpdatePoll Vh22Bot: number of results 0
2017.08.18 21:28:31 5: TelegramBot_UpdatePoll Vh22Bot: called
2017.08.18 21:28:31 4: TelegramBot_UpdatePoll Vh22Bot: - Initiate non blocking polling - With callback set
2017.08.18 21:28:31 5: TelegramBot_readToken: Read Telegram API token from file
2017.08.18 21:28:31 4: TelegramBot_UpdatePoll Vh22Bot: initiate polling with nonblockingGet with 120s
2017.08.18 21:28:31 1: HttpUtils url=<hidden>
2017.08.18 21:28:31 1: HttpUtils_Connect keepalive: No  conn: No
2017.08.18 21:28:31 1: HttpUtils_Connect after jump to connect 2
2017.08.18 21:28:31 1: HttpUtils_Connect nonblocking
2017.08.18 21:28:31 1: HttpUtils_Connect has non blocking conn
2017.08.18 21:28:31 1: HttpUtils x - in sub got iaddr: ????
2017.08.18 21:28:31 1: HttpUtils x - connect:
2017.08.18 21:28:31 1: HttpUtils x - got a connection set write fn
2017.08.18 21:28:31 1: HttpUtils x - start timer
2017.08.18 21:28:31 1: HttpUtils x - sub done
2017.08.18 21:28:31 4: TelegramBot_UpdatePoll Vh22Bot: - Ende > next polling started
2017.08.18 21:28:31 4: TelegramBot_Callback Vh22Bot: resulted in SUCCESS from Polling
2017.08.18 21:28:31 4: TelegramBot_Callback Vh22Bot: - polling so no retry
2017.08.18 21:28:31 4: TelegramBot_Callback Vh22Bot: - Ende > Control back to FHEM
2017.08.18 21:28:31 1: HttpUtils x - in write fn
2017.08.18 21:28:31 1: HttpUtils x - do connect2 in writeFn
2017.08.18 21:28:31 1: HttpUtils - in connect 2   conn: Yes
2017.08.18 21:28:31 1: HttpUtils_Connect2 is https und  has connection but no ssladded
2017.08.18 21:28:31 1: HttpUtils_Connect2 is https SSL there
2017.08.18 21:28:31 1: HttpUtils_Connect2 connection is now blocking
2017.08.18 21:28:31 1: HttpUtils_Connect2 start_ssl
2017.08.18 21:28:31 1: HttpUtils_Connect2 start_ssl done  conn: Yes
2017.08.18 21:28:31 1: HttpUtils_Connect2 connection established so start prepare header/content
2017.08.18 21:28:31 2: HttpUtils request header:
GET /xxxxxxxxxxxxxxxxxxxxxxxx/getUpdates?offset=xxxxxxxxx&limit=5&timeout=120 HTTP/1.0
Host: api.telegram.org
agent: TelegramBot/1.0
User-Agent: TelegramBot/1.0
Accept: application/json
Accept-Charset: utf-8

2017.08.18 21:28:31 1: HttpUtils - connect2 - data transfer after SSL - nonblocking
2017.08.18 21:28:31 1: HttpUtils - connect2 - start timer
2017.08.18 21:28:31 1: HttpUtils - connect2 - nonblocking done
2017.08.18 21:28:31 1: HttpUtils - connect2 - in direct writefn


Code Auswählen Erweitern

2017.08.18 21:40:36 1: HttpUtils - connect2 - in direct readfn
2017.08.18 21:40:36 1: <hidden>: HTTP response code 200
2017.08.18 21:40:36 1: HttpUtils <hidden>: Got data, length: 23
2017.08.18 21:40:36 2: HttpUtils response header:
HTTP/1.1 200 OK
Server: nginx/1.10.0
Date: Fri, 18 Aug 2017 19:40:36 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.18 21:40:36 5: TelegramBot_Callback Vh22Bot: called from Polling
2017.08.18 21:40:36 5: TelegramBot_Callback Vh22Bot: data returned :{"ok":true,"result":[]}:
2017.08.18 21:40:36 5: TelegramBot_Deepencode Vh22Bot: encoded a String from :true: to :true:
2017.08.18 21:40:36 5: TelegramBot_Deepencode Vh22Bot: found an ARRAY
2017.08.18 21:40:36 5: TelegramBot_Deepencode Vh22Bot: found a HASH
2017.08.18 21:40:36 5: TelegramBot_Callback Vh22Bot: after encoding
2017.08.18 21:40:36 5: TelegramBot_Callback Vh22Bot: polling returned result? 0
2017.08.18 21:40:36 5: UpdatePoll Vh22Bot: number of results 0
2017.08.18 21:40:36 5: TelegramBot_UpdatePoll Vh22Bot: called
2017.08.18 21:40:36 4: TelegramBot_UpdatePoll Vh22Bot: - Initiate non blocking polling - With callback set
2017.08.18 21:40:36 5: TelegramBot_readToken: Read Telegram API token from file
2017.08.18 21:40:36 4: TelegramBot_UpdatePoll Vh22Bot: initiate polling with nonblockingGet with 120s
2017.08.18 21:40:36 1: HttpUtils url=<hidden>
2017.08.18 21:40:36 1: HttpUtils_Connect keepalive: No  conn: No
2017.08.18 21:40:36 1: HttpUtils_Connect after jump to connect 2
2017.08.18 21:40:36 1: HttpUtils_Connect nonblocking
2017.08.18 21:40:36 1: HttpUtils_Connect has non blocking conn
2017.08.18 21:40:36 1: HttpUtils x - in sub got iaddr: ????
2017.08.18 21:40:36 1: HttpUtils x - connect:
2017.08.18 21:40:36 1: HttpUtils x - got a connection set write fn
2017.08.18 21:40:36 1: HttpUtils x - start timer
2017.08.18 21:40:36 1: HttpUtils x - sub done
2017.08.18 21:40:36 4: TelegramBot_UpdatePoll Vh22Bot: - Ende > next polling started
2017.08.18 21:40:36 4: TelegramBot_Callback Vh22Bot: resulted in SUCCESS from Polling
2017.08.18 21:40:36 4: TelegramBot_Callback Vh22Bot: - polling so no retry
2017.08.18 21:40:36 4: TelegramBot_Callback Vh22Bot: - Ende > Control back to FHEM
2017.08.18 21:40:36 1: HttpUtils x - in write fn
2017.08.18 21:40:36 1: HttpUtils x - do connect2 in writeFn
2017.08.18 21:40:36 1: HttpUtils - in connect 2   conn: Yes
2017.08.18 21:40:36 1: HttpUtils_Connect2 is https und  has connection but no ssladded
2017.08.18 21:40:36 1: HttpUtils_Connect2 is https SSL there
2017.08.18 21:40:36 1: HttpUtils_Connect2 connection is now blocking
2017.08.18 21:40:36 1: HttpUtils_Connect2 start_ssl
2017.08.18 21:44:41 1: HttpUtils_Connect2 start_ssl done  conn: No
2017.08.18 21:44:41 5: TelegramBot_Callback Vh22Bot: called from Polling
2017.08.18 21:44:41 5: TelegramBot_Callback Vh22Bot: polling returned result? <undef>
2017.08.18 21:44:41 5: Starting notify loop for Vh22Bot, 1 event(s), first is PollingLastError: NonBlockingGet: returned <hidden>: Can't connect(2) to https://api.telegram.org:443:  SSL wants a read first
2017.08.18 21:44:41 4: TelegramBot_Set Vh22Bot: called
2017.08.18 21:44:41 4: TelegramBot_Set Vh22Bot: Processing TelegramBot_Set( ? )
2017.08.18 21:44:41 4: TelegramBot_Set Vh22Bot: called
2017.08.18 21:44:41 4: TelegramBot_Set Vh22Bot: Processing TelegramBot_Set( ? )
2017.08.18 21:44:41 5: End notify loop for Vh22Bot
2017.08.18 21:44:41 5: Starting notify loop for Vh22Bot, 1 event(s), first is PollingErrCount: 8
2017.08.18 21:44:41 4: TelegramBot_Set Vh22Bot: called
2017.08.18 21:44:41 4: TelegramBot_Set Vh22Bot: Processing TelegramBot_Set( ? )
2017.08.18 21:44:41 4: TelegramBot_Set Vh22Bot: called
2017.08.18 21:44:41 4: TelegramBot_Set Vh22Bot: Processing TelegramBot_Set( ? )
2017.08.18 21:44:41 5: End notify loop for Vh22Bot
2017.08.18 21:44:41 5: TelegramBot_UpdatePoll Vh22Bot: called
2017.08.18 21:44:41 4: TelegramBot_UpdatePoll Vh22Bot: - Initiate non blocking polling - With callback set
2017.08.18 21:44:41 5: TelegramBot_readToken: Read Telegram API token from file
2017.08.18 21:44:41 4: TelegramBot_UpdatePoll Vh22Bot: initiate polling with nonblockingGet with 120s
2017.08.18 21:44:41 1: HttpUtils url=<hidden>
2017.08.18 21:44:41 1: HttpUtils_Connect keepalive: No  conn: No
2017.08.18 21:44:41 1: HttpUtils_Connect after jump to connect 2
2017.08.18 21:44:41 1: HttpUtils_Connect nonblocking
2017.08.18 21:44:41 1: HttpUtils_Connect has non blocking conn
2017.08.18 21:44:41 1: HttpUtils x - in sub got iaddr: ????
2017.08.18 21:44:41 1: HttpUtils x - connect:
2017.08.18 21:44:41 1: HttpUtils x - got a connection set write fn
2017.08.18 21:44:41 1: HttpUtils x - start timer
2017.08.18 21:44:41 1: HttpUtils x - sub done
2017.08.18 21:44:41 4: TelegramBot_UpdatePoll Vh22Bot: - Ende > next polling started
2017.08.18 21:44:41 4: TelegramBot_Callback Vh22Bot: resulted in NonBlockingGet: returned <hidden>: Can't connect(2) to https://api.telegram.org:443:  SSL wants a read first from Polling
2017.08.18 21:44:41 4: TelegramBot_Callback Vh22Bot: - polling so no retry
2017.08.18 21:44:41 4: TelegramBot_Callback Vh22Bot: - Ende > Control back to FHEM
2017.08.18 21:44:41 1: Perfmon: possible freeze starting at 21:40:37, delay is 244.554


3. Ein paar Ergebnisse aus Wireshark Mitschnitten
- keine Korrelation zwischen Blockade und der IP des Telegram Servers erkennbar, hängt mit allen der 4 IPs mal
- eine Blockade im angehängten Bild zwischen 309s und 354s (pollingTimeout auf 20s eingestellt, daher nur 45s blockiert)

4. Raspbian per apt-get upgrade aktualisiert, keine Änderung

5. Perl IO::SOCKET::SSL ist 2.0020 (CPAN hat 2.0500) -> perl upgrade läuft noch...

[essera]

Ich habe das nun das pollingTimeout beim TelegramBot erst mal auf 0 gestellt.
Gut nun ist der Bot auf static gegangen - freezes haben aber aufgehört ,
Ich kann aber jede Nachricht per Fhem Oberfläche verschicken (ohne Fehler )- weils das polling fehlt kommt natürlich nichts mehr rein. Kann ich für den Moment aber verschmerzen.

Ich werde später mal meine Logs durcharbeiten um den genauen Zeitpunkt und evtl. die Umstände zu ermitteln ab dem der Fehler auftauchte.
Wenn ich noch was testen soll - Info reicht.

[viegener]

OK ich habe die beiden Dateien getauscht und unter global
attr global sslVersion SSLv3  gesetzt.
Verbose ist auf 4


Nun erhalte ich folgende Fehlermeldung im LOG:
TelegramBot xxxxx PollingLastError: NonBlockingGet: returned : Can't connect(2) to https://api.telegram.org:443: SSL connect attempt failed because of handshake problems error:14094410:SSL routines:SSL3_READ_BYTES:sslv3 alert handshake failure

Und danach keine Timeouts? Die Fehlermeldung ist genau das was ich erreichen wollte.

[viegener]

@cawe: Interessante infos, machen das Puzzle aber noch rätselhafter

Bei Dir geht der Aufruf manchmal durch und manchmal kommt es zu den Blockaden und ich vermute ohne eine Änderung am System? Korrekt?

Zu den ssl-Einstellungen - mir ging es darum auszuprobieren, ob mit einer unpassenden ssl-Einstellung (nur SSLv3) auch die Blockaden auftreten, oder ob es dann einfach nicht zu einem Verbindungsaufbau kommt.

Was für eine Plattform (Hw/Betriebssystem/perl) verwendest Du?

[viegener]

Habe mal die bisherigen Infos zu den Plattformen gesammelt

Ich sehe vorwiegend eine Reihe von Debian8/jessie-Plattformen (plus ein macOSX)
@awel: Welche Linuxversion läuft bei Dir?

Perlversionen sind sehr uneinheitlich

Interessant wäre herauszufinden, ob auch wheezy/Debian7 betroffen ist?
Ich betreibe mein System noch auf wheezy und bin nicht betroffen

Ich habe aber auch noch weitere Spekulationen
- Es könnte eine Wechselwirkung zwischen Modulen geben, da wohl die Blockade nicht bei jedem Aufruf auftritt
- Vielleicht gibt es einen Zusammenhang mit DSLLite/Firewall/...?
- oder mit IPV6

Als kurze Vorwarnung: Ich bin ab morgen geschäftlich unterwegs und damit wohl nicht in der Lage irgendetwas zu lösen

[UweH]

Ich habe auf diesen beiden Systemen mit einem aktuellen FHEM keine Probleme:

Code Auswählen Erweitern

PRETTY_NAME="Raspbian GNU/Linux 8 (jessie)"
NAME="Raspbian GNU/Linux"
VERSION_ID="8"
VERSION="8 (jessie)"
ID=raspbian
ID_LIKE=debian

SSLv3
TLSv1.2

Code Auswählen Erweitern

DISTRIB_ID=Ubuntu
DISTRIB_RELEASE=15.10
DISTRIB_CODENAME=wily
DISTRIB_DESCRIPTION="Ubuntu 15.10"
NAME="Ubuntu"
VERSION="15.10 (Wily Werewolf)"
ID=ubuntu
ID_LIKE=debian
PRETTY_NAME="Ubuntu 15.10"
VERSION_ID="15.10"

SSLv3
TLSv1.2

Brauchst Du noch mehr Daten?

gruß
Uwe

[mbrak]

hi

ich habe

Raspberry 2
Jessi
Linux FHEM 4.1.17-v7+ #838 SMP Tue Feb 9 13:15:09 GMT 2016 armv7l GNU/Linux
Perl 5.20.2
Fhem aktuell
Hängt über eine FB (IPV4) an einem DSL (50mbit) Anschluß (DT)


Ich habe keine Probleme mit Telegram!

Gruß Michael

[awel]

@viegener

Linux-Version auf raspberry: wheezy

Code Auswählen Erweitern

root@raspberrypi:~# cat /etc/os-release
PRETTY_NAME="Raspbian GNU/Linux 7 (wheezy)"
NAME="Raspbian GNU/Linux"
VERSION_ID="7"
VERSION="7 (wheezy)"
ID=raspbian
ID_LIKE=debian
ANSI_COLOR="1;31"
HOME_URL="http://www.raspbian.org/"
SUPPORT_URL="http://www.raspbian.org/RaspbianForums"
BUG_REPORT_URL="http://www.raspbian.org/RaspbianBugs"

An eine Wechselwirkung verschiedener Module nach Updates der Module habe ich auch schon gedacht; irgendwelche Parameter, Attribute, Einstellungen etc. würden nur schwer erklären, warum bei allen Betroffenen der Fehler fast zeitgleich auftrat - wir werden nicht zeitgleich Einstellungen o.ä. geändert haben. Ein grundsätzlicher Fehler auf einem der Telegram-Server scheidet auch aus - das hätten auch Benutzer ohne fhem bemerkt.

Hier eine Liste meiner Module aus fheminfo:

Code Auswählen Erweitern

ABFALL
CALVIEW
CUL
CUL_HM
Calendar
DOIF
FBAHAHTTP
FBDECT
FB_CALLLIST
FB_CALLMONITOR
FHEMWEB
FRITZBOX
FS20
FileLog
GDS
HMinfo
IT
RESIDENTS
ROOMMATE
SONOS
SONOSPLAYER
STV
SVG
TelegramBot
Twilight
UWZ
Weather
alarmclock
at
autocreate
cmdalias
dummy
eventTypes
holiday
netatmo
notify
readingsGroup
sequence
telnet
weblink

Vielen Dank für Deine Mühen!!!

[essera]

Kleine Ergänzung:
Ich hänge an einem DSL Lite Anschluss von Unitymedia - also kein "echtes" IPv4.

Anmerkung:
Evtl. sollten wir noch die Unterscheidung machen ob jemand Telegram oder den TelegramBot nutzt.
Ich nutze nur den TelegramBot!!