Tasmota icon indicating copy to clipboard operation
Tasmota copied to clipboard
verified publisher icon arendst

Telegram sending error on 14.0.0.1 (and master 14.0.0 also)

Open nikvostro opened this issue 1 year ago • 7 comments

PROBLEM DESCRIPTION

Telegram returns error when sending message on 14.0.0.1 (and master 14.0.0 also). Sending via Telegram API using webquery works for master 14.0.0 build (which I've initially compiled and updated one of my tasmotas) but don't work for dev.

REQUESTED INFORMATION

  • [x] Read the Contributing Guide and Policy and the Code of Conduct
  • [x] Searched the problem in issues
  • [x] Searched the problem in discussions
  • [x] Searched the problem in the docs
  • [x] Searched the problem in the chat
  • [x] Device used (e.g., Sonoff Basic): Lolin D32 PRO
  • [x] Tasmota binary firmware version number used: 14.0.0 development branch on 21.05.2024 ~~- [ ] Pre-compiled~~
    • [x] Self-compiled
  • [x] Flashing tools used: VSC
  • [x] Provide the output of command: Backlog Template; Module; GPIO 255:
20:20:03.624 RSL: RESULT = {"NAME":"ESP32-DevKit","GPIO":[1,1,1,1,1,1,1,1,1,1,1,1,1,1,1,1,0,1,1,1,0,1,1,1,0,0,0,0,1,1,1,1,1,0,0,1],"FLAG":0,"BASE":1}
20:20:03.851 RSL: RESULT = {"Module":{"1":"ESP32-DevKit"}}
20:20:04.059 RSL: RESULT = {"GPIO0":{"0":"None"},"GPIO1":{"0":"None"},"GPIO2":{"0":"None"},"GPIO3":{"0":"None"},"GPIO4":{"0":"None"},"GPIO5":{"0":"None"},"GPIO6":{"0":"None"},"GPIO7":{"0":"None"},"GPIO8":{"0":"None"},"GPIO9":{"0":"None"},"GPIO10":{"0":"None"},"GPIO11":{"0":"None"},"GPIO12":{"0":"None"},"GPIO13":{"0":"None"},"GPIO14":{"0":"None"},"GPIO15":{"0":"None"},"GPIO16":{"0":"None"},"GPIO17":{"0":"None"},"GPIO18":{"0":"None"},"GPIO19":{"0":"None"},"GPIO20":{"0":"None"},"GPIO21":{"0":"None"},"GPIO22":{"0":"None"},"GPIO23":{"0":"None"},"GPIO24":{"0":"None"},"GPIO25":{"0":"None"},"GPIO26":{"0":"None"},"GPIO27":{"0":"None"},"GPIO32":{"0":"None"},"GPIO33":{"0":"None"},"GPIO34":{"0":"None"},"GPIO35":{"0":"None"},"GPIO36":{"0":"None"},"GPIO37":{"0":"None"},"GPIO38":{"0":"None"},"GPIO39":{"0":"None"}}

~~- [ ] If using rules, provide the output of this command: Backlog Rule1; Rule2; Rule3:~~

  • [x] Provide the output of this command: Status 0:
20:20:28.289 RSL: STATUS = {"Status":{"Module":1,"DeviceName":"Tasmota","FriendlyName":["Tasmota"],"Topic":"tasmota_C6CAB8","ButtonTopic":"0","Power":"0","PowerLock":"0","PowerOnState":0,"LedState":1,"LedMask":"FFFF","SaveData":1,"SaveState":0,"SwitchTopic":"0","SwitchMode":[0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0],"ButtonRetain":0,"SwitchRetain":0,"SensorRetain":0,"PowerRetain":0,"InfoRetain":0,"StateRetain":0,"StatusRetain":0}}
20:20:28.322 RSL: STATUS1 = {"StatusPRM":{"Baudrate":115200,"SerialConfig":"8N1","GroupTopic":"tasmotas","OtaUrl":"http://ota.tasmota.com/tasmota32/release/tasmota32.bin","RestartReason":"Software reset CPU","Uptime":"0T00:01:58","StartupUTC":"2024-05-21T17:18:30","Sleep":50,"CfgHolder":4617,"BootCount":1,"BCResetTime":"2024-05-21T20:18:35","SaveCount":6}}
20:20:28.355 RSL: STATUS2 = {"StatusFWR":{"Version":"14.0.0.1(tasmota32)","BuildDateTime":"2024-05-21T20:16:28","Core":"3_0_0","SDK":"5.1.3.240430","CpuFrequency":160,"Hardware":"ESP32-D0WD-V3 v3.1","CR":"401/699"}}
20:20:28.377 RSL: STATUS3 = {"StatusLOG":{"SerialLog":2,"WebLog":2,"MqttLog":0,"SysLog":0,"LogHost":"","LogPort":514,"SSId":["domuk",""],"TelePeriod":0,"Resolution":"558180C0","SetOption":["00008000","1405C80005000600003C5A0A192800000000","00800080","00006000","00004001","00000000"]}}
20:20:28.413 RSL: STATUS4 = {"StatusMEM":{"ProgramSize":1366,"Free":1513,"Heap":158,"StackLowMark":3,"PsrMax":4096,"PsrFree":4085,"ProgramFlashSize":16384,"FlashSize":16384,"FlashChipId":"1840C8","FlashFrequency":40,"FlashMode":"DIO","Features":["0809","978A159F","0009A001","B7F7BFCF","05DA9BC4","60360C47","4808C0D2","20200000","D4BC4825","810A80B1","00000014"],"Drivers":"1,!2,!3,!4,!5,!8,9,10,11,!12,!14,!16,!17,!24,29,!34,38,40,50,!59,!60,62,!63,!66,!67,!68,!73,82,!86,!87,!88,!121","Sensors":"1,2,3,5,6,7,8,9,10,11,12,13,14,15,17,18,19,20,21,22,26,31,34,37,39,40,42,43,45,51,52,55,56,58,59,64,66,67,74,85,92,95,98,103,105,109,127","I2CDriver":"7,8,9,10,11,12,13,14,15,17,18,20,24,29,31,36,41,42,44,46,48,58,62,65,69,76,77,82"}}
20:20:28.478 RSL: STATUS5 = {"StatusNET":{"Hostname":"tasmota-C6CAB8-2744","IPAddress":"192.168.11.179","Gateway":"192.168.11.1","Subnetmask":"255.255.255.0","DNSServer1":"192.168.11.1","DNSServer2":"0.0.0.0","Mac":"08:D1:ww:xx:yy:zz","IP6Global":"","IP6Local":"fe80::ad1:f9ff:fec6:cab8%st1","Ethernet":{"Hostname":"","IPAddress":"0.0.0.0","Gateway":"0.0.0.0","Subnetmask":"0.0.0.0","DNSServer1":"192.168.11.1","DNSServer2":"0.0.0.0","Mac":"00:00:00:00:00:00","IP6Global":"","IP6Local":""},"Webserver":2,"HTTP_API":1,"WifiConfig":4,"WifiPower":16.0}}
20:20:28.522 RSL: STATUS7 = {"StatusTIM":{"UTC":"2024-05-21T17:20:28Z","Local":"2024-05-21T20:20:28","StartDST":"2024-03-31T02:00:00","EndDST":"2024-10-27T03:00:00","Timezone":"+03:00","Sunrise":"04:06","Sunset":"20:44"}}
20:20:28.546 RSL: STATUS10 = {"StatusSNS":{"Time":"2024-05-21T20:20:28"}}
20:20:28.551 RSL: STATUS11 = {"StatusSTS":{"Time":"2024-05-21T20:20:28","Uptime":"0T00:01:58","UptimeSec":118,"Heap":158,"SleepMode":"Dynamic","Sleep":50,"LoadAvg":19,"MqttCount":0,"Wifi":{"AP":1,"SSId":"[mywifinet]","BSSId":"7C:10:ww:xx:yy:zz","Channel":11,"Mode":"HT20","RSSI":78,"Signal":-61,"LinkCount":1,"Downtime":"0T00:00:04"}}}```
  • [x] Set weblog to 4 and then, when you experience your issue, provide the output of the Console log:
20:23:40.590 CMD: tmstate 2
20:23:40.592 SRC: WebConsole from 192.168.11.80
20:23:40.594 CMD: Grp 0, Cmd 'TMSTATE', Idx 1, Len 1, Pld 2, Data '2'
20:23:40.597 RSL: RESULT = {"TmState":{"Send":"ON","Receive":"OFF","Echo":"OFF"}}
20:23:42.439 CMD: tmstate 3
20:23:42.440 SRC: WebConsole from 192.168.11.80
20:23:42.442 CMD: Grp 0, Cmd 'TMSTATE', Idx 1, Len 1, Pld 3, Data '3'
20:23:42.444 RSL: RESULT = {"TmState":{"Send":"ON","Receive":"ON","Echo":"OFF"}}
20:24:40.636 CMD: tmtoken [mybottokenhere]
20:24:40.637 SRC: WebConsole from 192.168.11.80
20:24:40.638 CMD: Grp 0, Cmd 'TMTOKEN', Idx 1, Len 45, Pld 984067856, Data '[mybottokenhere]'
20:24:40.641 CFG: CR 446/699, Busy 0
20:24:40.643 RSL: RESULT = {"TmToken":"[mybottokenhere]"}
20:25:32.619 CMD: tmchatid [myprivatechatID]
20:25:32.621 SRC: WebConsole from 192.168.11.80
20:25:32.622 CMD: Grp 0, Cmd 'TMCHATID', Idx 1, Len 9, Pld [myprivatechatID], Data '[myprivatechatID]'
20:25:32.625 CFG: CR 455/699, Busy 0
20:25:32.626 RSL: RESULT = {"TmChatId":"[myprivatechatID]"}
20:26:33.594 CMD: so132
20:26:33.596 SRC: WebConsole from 192.168.11.80
20:26:33.598 CMD: Grp 0, Cmd 'SO', Idx 132, Len 0, Pld -99, Data ''
20:26:33.599 RSL: RESULT = {"SetOption132":"OFF"}
20:26:36.546 CMD: so132 1
20:26:36.548 SRC: WebConsole from 192.168.11.80
20:26:36.549 CMD: Grp 0, Cmd 'SO', Idx 132, Len 1, Pld 1, Data '1'
20:26:36.551 RSL: RESULT = {"SetOption132":"ON"}
[Tasmota has restarted here]
...
20:26:43.518 TGM: getUpdates
20:26:43.524 WIF: DNS resolved 'api.telegram.org' (149.154.167.220) in 6 ms
20:26:43.670 TGM: Response ''
20:26:46.531 QPC: Reset
20:26:48.522 APP: Boot Count 2
20:26:49.335 CFG: Saved, Count 13, Bytes 4096
20:26:56.519 TGM: getUpdates
20:26:56.521 WIF: DNS resolved 'api.telegram.org' (149.154.167.220) in 0 ms
20:26:56.655 TGM: Response ''

20:28:07.829 CMD: tmsend "test"
20:28:07.830 SRC: WebConsole from 192.168.11.80
20:28:07.831 CMD: Grp 0, Cmd 'TMSEND', Idx 1, Len 6, Pld -99, Data '"test"'
20:28:07.833 TGM: sendMessage
20:28:07.834 WIF: DNS resolved 'api.telegram.org' (149.154.167.220) in 0 ms
20:28:07.968 RSL: RESULT = {"TmSend":"Failed"}

TO REPRODUCE

  1. Build tasmtota32 standard env using dev 21.05.2024 with -DUSE_TELEGRAM
  2. Set telegram parameters: token, chatid, state
  3. SO132 1 (Force TLS fingerprint validation instead of CA)
  4. Try to send message via tmsend command

EXPECTED BEHAVIOUR

Telegram sends message

SCREENSHOTS

n/a

ADDITIONAL CONTEXT

Telegram was working fine with every release lower than v14 with on many Tasmota devices.

Manual sending via webquery worked for the master branch 14.0.0.1 but don't work for dev 14.0.0.1:

20:50:04.548 CMD: webquery https://api.telegram.org/bot[mybottokenhere]/sendMessage?text=test&chat_id=[myprivatechatID]
20:50:04.551 SRC: WebConsole from 192.168.11.80
20:50:04.553 CMD: Grp 0, Cmd 'WEBQUERY', Idx 1, Len 113, Pld -99, Data 'https://api.telegram.org/bot[mybottokenhere]/sendMessage?text=test&chat_id=[myprivatechatID]'
20:50:04.665 RSL: RESULT = {"WebQuery":"Done"}

After "Done" nothing comes to the telegram chat. At the same time this query works on another tasmotas and PC. (Please, remember to close the issue when the problem has been addressed)

nikvostro avatar May 21 '24 17:05 nikvostro

I can confirm, just build 13.4.0 and work correctly, on 14.x it's not working anymore

inode- avatar May 23 '24 07:05 inode-

I'm not familiar with the time it normally makes, but it seems the two log lines are very close to each other:

20:28:07.833 TGM: sendMessage
20:28:07.834 WIF: DNS resolved 'api.telegram.org' (149.154.167.220) in 0 ms
20:28:07.968 RSL: RESULT = {"TmSend":"Failed"}

It's maybe linked to https://github.com/arendst/Tasmota/pull/21442

The timeout value changed from seconds to milliseconds in the Core3 API. This could explain why the "Failed" messages happens only 134ms after the actual command (which is shorter than a full TLS handshake)

s-hadinger avatar May 23 '24 18:05 s-hadinger

It consistently replies:

23:08:44.996 TGM: getUpdates
connect(api.telegram.org,443)
connect(149.154.167.220,443)
_connectSSL: start connection
_wait_for_handshake: failed
Couldn't connect. Error = 1
23:08:45.101 TGM: Response ''

even with a timeout of 10000 ms (being default in code)

arendst avatar May 23 '24 21:05 arendst

I'm still surprised how quickly it returns the error, 105 ms including the logging

s-hadinger avatar May 23 '24 21:05 s-hadinger

From what I see above it doesn't connect at all as _wait_for_handshake: failed returns immediatly.

and no heap usage either:

23:27:31.958 TGM: getUpdates
connect(api.telegram.org,443)
connect(149.154.167.220,443)
> Heap Before calling _connectSSL = 3712
> Heap _connectSSL.start = 3712
> Heap Thunk allocated = 3712
_connectSSL: start connection
> Heap _connectSSL before DecoderContext allocation = 3712
> Heap _connectSSL after DecoderContext allocation = 3712
> Heap _connectSSL before PrivKey allocation = 3712
_wait_for_handshake: failed
Couldn't connect. Error = 1
> Heap _connectSSL.end = 3712
> Heap _connectSSL after release of Priv Key = 3712
23:27:32.103 TGM: Response ''

arendst avatar May 23 '24 21:05 arendst

Unrelated issue:

GoDaddy Daddy Secure Certificate Authority - G2, RSA 2048 bits SHA 256, valid until 20220523

It seems that the GoDaddy Authority is long expired. Although I understand you don't use it and use fingerprint instead

s-hadinger avatar May 23 '24 21:05 s-hadinger

Yep. That was the reason we had to use SO132 1 for fingerprint.

arendst avatar May 23 '24 21:05 arendst

I'm still looking into the Telegram issue. As a test I started to reuse an ESP8266 but it fails there too. So for now we can rule out core3.

How about the fingerprint? Where can I see if the fingerprint is still valid?

arendst avatar May 27 '24 14:05 arendst

Invalid fingerprint would generate a TLS error. It's not the case here. You can also reset the fingerprint with all zeroes to accept any value

s-hadinger avatar May 27 '24 14:05 s-hadinger

Adding some more debug info doesn't ring my bells:

17:50:08.675-014 CMD: tmsend hello
17:50:08.677-014 SRC: Serial
17:50:08.680-014 CMD: Grp 0, Cmd 'TMSEND', Idx 1, Len 5, Pld -99, Data 'hello'
17:50:08.683-014 TGM: Connect start 'bot1179906608:AAE-3UfPJt3u8d-gbGXslnFO96o3DahG6EM/sendMessage?chat_id=139920293&text=hello'
connect(api.telegram.org,443)
connect(149.154.167.220,443)
_connectSSL: start connection
_run_until: BR_SSL_CLOSED
_wait_for_handshake: failed
Couldn't connect. Error = 1
17:50:08.812-014 TGM: Connect failed
17:50:08.814-014 TGM: Response 
17:50:08.818-011 MQT: stat/wemos4/RESULT = {"TmSend":"Failed"}

I'm lost for now.

arendst avatar May 27 '24 15:05 arendst

Ah, it is a TLS connection error after all. Let me first update the CA.

s-hadinger avatar May 27 '24 16:05 s-hadinger

I updated the CA from Telegram, but now I get error 49: BR_ERR_X509_UNSUPPORTED - certificate contains unsupported features that cannot be ignored.

This would be a lot of work to allow unsupported features, hence I'm in favor of removing CA verification in Telegram (which wasn't working anyways).

The Fingerprint seems to have changed, it is now: 4E 7F F5 6D 1E 29 40 58 AB 84 DE 63 69 7B CD DF 44 2E D2 F6

s-hadinger avatar May 27 '24 20:05 s-hadinger

With latest change in CA and SO132 1 (and fingerprint set 0's):

22:10:45.362-017 TGM: Connect start 'bot1179906608:AAE-3UfPJt3u8d-gbGXslnFO96o3DahG6EM/getUpdates?offset=0'
connect(api.telegram.org,443)
connect(149.154.167.220,443)
_connectSSL: start connection
_run_until: BR_SSL_CLOSED
_wait_for_handshake: failed
Couldn't connect. Error = 1
22:10:45.487-015 TGM: Connect failed

with SO132 0:

22:11:03.340-017 TGM: Connect start 'bot1179906608:AAE-3UfPJt3u8d-gbGXslnFO96o3DahG6EM/getUpdates?offset=0'
connect(api.telegram.org,443)
connect(149.154.167.220,443)
_connectSSL: start connection
_run_until: BR_SSL_CLOSED
_wait_for_handshake: failed
Couldn't connect. Error = 49
22:11:03.993-015 TGM: Connect failed

arendst avatar May 27 '24 20:05 arendst

Yep! Succes. The changed fingerprint workx.

arendst avatar May 27 '24 20:05 arendst