Home Assistant release (hass --version):
Since 0.64.0
Python release (python3 --version):
3.5.3
Component/platform:
Telegram
Description of problem:
I noticed today that my Telegram automation is not working well. To simplify things, I replaced all my Telegram automations with this one, from samples:
- alias: 'Telegram bot that repeats text'
hide_entity: true
trigger:
platform: event
event_type: telegram_text
action:
- service: telegram_bot.send_message
data_template:
title: '*Dumb automation*'
target: '{{ trigger.event.data.user_id }}'
message: 'You said: {{ trigger.event.data.text }}'
With this automation, when I say “Hello” to my bot, my bot will start sending me this message within an interval of 1 minute, forever:
*Dumb automation*
You said: Hello
HA logbook also shows the problem:
19:00 Telegram bot that repeats text has been triggered
18:59 Telegram bot that repeats text has been triggered
18:58 Telegram bot that repeats text has been triggered
Expected:
Automation should be triggered only once
Problem-relevant configuration.yaml entries and steps to reproduce:
telegram_bot:
- platform: webhooks
api_key: !secret telegram_api_key
url: https://iprefertokeepmyurlprivate.duckdns.org:443
parse_mode: html
allowed_chat_ids:
- !secret telegram_chat_id_home-group
same issue here
@ devs - this might be a webhooks thing, I'm using polling and mine isn't doing this, and is working as expected.
(see #12781)
edit: that was a mistake (config wasn't saved correctly over SFTP), it works with _polling_ indeed.
@mf-social I changed my config from webhooks to polling and still see the same issue.
On 0.65.0 I'm gettiing:
2018-03-03 06:10:14 ERROR (SyncWorker_18) [homeassistant.components.telegram_bot] Error sending message: Can't parse entities: can't find end of the entity starting at byte offset 2. Args: (339855604, 'my_title\nanother'), kwargs: {'parse_mode': 'Markdown', 'disable_notification': False, 'disable_web_page_preview': None, 'reply_to_message_id': None, 'reply_markup': None, 'timeout': None}
@robmarkcole - I think that's unrelated, try parse_mode: html
I think if you leave it in markdown it tries to apply tags, so if you have an underscore or something in the output it's looking for a second one to close it, resulting in the error.
I can confirm that it doesn't work with polling either.
Anyone was able to workaround this before any fix?
same situation with my installation. everything worked in 0.63.x, after updating to 0.64.3 suddenly telegram bot loops.
Same here. Running latest hassio 0.64.3 and python 3.6.3. Using polling is working fine. Adding the bot as a webhook with a simple event listener starts executing the automation continuously, even without firing the command. It looks like it keeps creating events. This is my setup:
telegram_bot:
# - platform: polling
- platform: webhooks
api_key: !secret telegram_bot_api_key
allowed_chat_ids:
- !secret telegram_bot_chat_id_robert
url: https://redacted.duckdns.org
notify:
- name: telegram
platform: telegram
chat_id: !secret telegram_bot_chat_id_robert
################################################
## Automation
################################################
automation:
- alias: telegram_ping
hide_entity: true
trigger:
- platform: event
event_type: telegram_command
event_data:
command: '/ping'
action:
- service: notify.telegram
data:
message: 'pong'
Additionally: I run hass.io behind the Bestlibre Nginx add-on.
Tried also with 0.65.0
Issue still there. Now I think the issue is related to the cleanup of http which appeared in 0.64
@balloob could you please advice if this could be related to http cleanup?
I just updated to 0.65.3 (from 0.63.3) and also facing the same problem.
When I started a chat with my bot, it keep on triggering the same automation. This is what I have in my config...
##########################################################
# Telegram Bot
##########################################################
telegram_bot:
- platform: webhooks
api_key: !secret telegram_api_key
allowed_chat_ids:
- !secret telegram_chat_id_user1
- !secret telegramgroup_chat_id
parse_mode: html
##########################################################
# Automation
##########################################################
automation:
- alias: 'Telebot Start'
initial_state: 'on'
trigger:
- platform: event
event_type: telegram_command
event_data:
command: '/jarvis'
- platform: event
event_type: telegram_command
event_data:
command: '/start'
- platform: event
event_type: telegram_text
event_data:
text: 'jarvis'
- platform: event
event_type: telegram_text
event_data:
text: 'Jarvis'
action:
- service: telegram_bot.send_message
data_template:
message: 'What do you want {{ trigger.event.data.from_first }}?'
title: ''
target: '{{ trigger.event.data.chat_id }}'
disable_notification: true
keyboard:
- "/alarm_clock, /timer"
- "/device_control, /device_status"
- "/send_message"
- "/tell_me, /show_me"
- "/control_security"
- "/lock_door, /unlock_door"
If I send jarvis to my bot, it will keep on replying "What do you want [my name]?". Only way to stop this is to turn off automation.telebot_start via the Services page under Developer Tools. However, it will happen again after I restart HA.
Same error. Bot remember first triggered event and fire it even I start another event
I have changed to polling and no more issue.
I have a problem on the Telegram polling. My Hassio is not exposed to the internet
There have been some commits to the telegram_bot component recently
https://github.com/home-assistant/home-assistant/commits/dev/homeassistant/components/telegram_bot
My guess is on the http cleanup
I have re-installed HA using the latest version (0.66.0) on brand new SD card and the issue with webhooks is still happening.
Any news on this? Thanks
I have been debugging this and my log file shows that Telegram is repeatedly calling my webhooks endpoint. I can see the incoming HTTP POST.
Maybe Telegram thinks the message has not been delivered and attempts to re-deliver it again?
I have the same issue. And I was trying to investigate it.
I have a hass instance behind an nginx reverse proxy (https)
These are my logs, hope they will be helpful. I couldn't intercept any errors from hass, which generates 400 error.
As you can see below, Hass answers to telegram with 400 error on POST request
PS: I found out that an issue occurs only when you request a bot command. If hass sends any messages to telegram everything goes fine.
The Intercepted request from Telegram
> 2018/04/21 19:33:28.961850 length=680 from=0 to=679
POST /api/telegram_webhooks HTTP/1.1\r
Host: hass.domain.com\r
X-Real-IP: 149.154.167.226\r
X-Forwarded-Server: hass.domain.com\r
X-Forwarded-For: 149.154.167.226\r
X-Forwarded-Proto: https\r
Connection: upgrade\r
Content-Length: 386\r
Content-Type: application/json\r
Accept-Encoding: gzip, deflate\r
\r
{"update_id":3453XXXXX,
"message":{"message_id":51XX,"from":{"id":672XXXXX,"is_bot":false,"first_name":"Alexander","last_name":"Savin","username":"alex_savin","language_code":"en-US"},"chat":{"id":67239746,"first_name":"Alexander","last_name":"Savin","username":"alex_savin","type":"private"},"date":1524353594,"text":"/doors","entities":[{"offset":0,"length":6,"type":"bot_command"}]}}< 2018/04/21 19:33:28.981924 length=172 from=0 to=171
HTTP/1.1 200 OK\r
Content-Type: application/json\r
Content-Length: 4\r
Content-Encoding: deflate\r
Date: Sat, 21 Apr 2018 23:33:28 GMT\r
Server: Python/3.5 aiohttp/3.1.1\r
\r
The Nginx Access log
149.154.167.226 - - [21/Apr/2018:19:33:28 -0400] "POST /api/telegram_webhooks HTTP/1.1" 200 4 "-" "-"
149.154.167.226 - - [21/Apr/2018:19:33:29 -0400] "HTTP/1.1 400 Bad Request" 400 173 "-" "-"
The Nginx Error log (Debug)
2018/04/21 19:33:28 [debug] 26601#26601: *737 post event 0000563D53561200
2018/04/21 19:33:28 [debug] 26601#26601: *737 delete posted event 0000563D53561200
2018/04/21 19:33:28 [debug] 26601#26601: *737 http wait request handler
2018/04/21 19:33:28 [debug] 26601#26601: *737 malloc: 0000563D539E0840:1024
2018/04/21 19:33:28 [debug] 26601#26601: *737 SSL_read: 172
2018/04/21 19:33:28 [debug] 26601#26601: *737 SSL_read: 386
2018/04/21 19:33:28 [debug] 26601#26601: *737 SSL_read: -1
2018/04/21 19:33:28 [debug] 26601#26601: *737 SSL_get_error: 2
2018/04/21 19:33:28 [debug] 26601#26601: *737 reusable connection: 0
2018/04/21 19:33:28 [debug] 26601#26601: *737 posix_memalign: 0000563D534C9570:4096 @16
2018/04/21 19:33:28 [debug] 26601#26601: *737 http process request line
2018/04/21 19:33:28 [debug] 26601#26601: *737 http request line: "POST /api/telegram_webhooks HTTP/1.1"
2018/04/21 19:33:28 [debug] 26601#26601: *737 http uri: "/api/telegram_webhooks"
2018/04/21 19:33:28 [debug] 26601#26601: *737 http args: ""
2018/04/21 19:33:28 [debug] 26601#26601: *737 http exten: ""
2018/04/21 19:33:28 [debug] 26601#26601: *737 posix_memalign: 0000563D535F9180:4096 @16
2018/04/21 19:33:28 [debug] 26601#26601: *737 http process request header line
2018/04/21 19:33:28 [debug] 26601#26601: *737 http header: "Host: hass.domain.com"
2018/04/21 19:33:28 [debug] 26601#26601: *737 http header: "Content-Type: application/json"
2018/04/21 19:33:28 [debug] 26601#26601: *737 http header: "Content-Length: 386"
2018/04/21 19:33:28 [debug] 26601#26601: *737 http header: "Connection: keep-alive"
2018/04/21 19:33:28 [debug] 26601#26601: *737 http header: "Accept-Encoding: gzip, deflate"
2018/04/21 19:33:28 [debug] 26601#26601: *737 http header done
2018/04/21 19:33:28 [debug] 26601#26601: *737 event timer del: 11: 1524353667077
2018/04/21 19:33:28 [debug] 26601#26601: *737 generic phase: 0
2018/04/21 19:33:28 [debug] 26601#26601: *737 rewrite phase: 1
2018/04/21 19:33:28 [debug] 26601#26601: *737 test location: "/"
2018/04/21 19:33:28 [debug] 26601#26601: *737 test location: ~ "^/(.well-known/acme-challenge/.*)$"
2018/04/21 19:33:28 [debug] 26601#26601: *737 using configuration "/"
2018/04/21 19:33:28 [debug] 26601#26601: *737 http cl:386 max:1048576
2018/04/21 19:33:28 [debug] 26601#26601: *737 rewrite phase: 3
2018/04/21 19:33:28 [debug] 26601#26601: *737 upload-progress: get_tracking_id
2018/04/21 19:33:28 [debug] 26601#26601: *737 upload-progress: get_tracking_id no header found
2018/04/21 19:33:28 [debug] 26601#26601: *737 upload-progress: get_tracking_id no id found
2018/04/21 19:33:28 [debug] 26601#26601: *737 trackuploads no id found in POST upload req
2018/04/21 19:33:28 [debug] 26601#26601: *737 rewrite phase: 4
2018/04/21 19:33:28 [debug] 26601#26601: *737 http script var
2018/04/21 19:33:28 [debug] 26601#26601: *737 http script regex: "(.*)"
2018/04/21 19:33:28 [notice] 26601#26601: *737 "(.*)" matches "", client: 149.154.167.226, server: hass.domain.com, request: "POST /api/telegram_webhooks HTTP/1.1", host: "hass.domain.com"
2018/04/21 19:33:28 [debug] 26601#26601: *737 http script if
2018/04/21 19:33:28 [debug] 26601#26601: *737 http script value: "1"
2018/04/21 19:33:28 [debug] 26601#26601: *737 http script set $cors
2018/04/21 19:33:28 [debug] 26601#26601: *737 http script var
2018/04/21 19:33:28 [debug] 26601#26601: *737 http script var: "POST"
2018/04/21 19:33:28 [debug] 26601#26601: *737 http script value: "OPTIONS"
2018/04/21 19:33:28 [debug] 26601#26601: *737 http script equal
2018/04/21 19:33:28 [debug] 26601#26601: *737 http script equal: no
2018/04/21 19:33:28 [debug] 26601#26601: *737 http script if
2018/04/21 19:33:28 [debug] 26601#26601: *737 http script if: false
2018/04/21 19:33:28 [debug] 26601#26601: *737 http script var
2018/04/21 19:33:28 [debug] 26601#26601: *737 http script var: "1"
2018/04/21 19:33:28 [debug] 26601#26601: *737 http script value: "1"
2018/04/21 19:33:28 [debug] 26601#26601: *737 http script equal
2018/04/21 19:33:28 [debug] 26601#26601: *737 http script if
2018/04/21 19:33:28 [debug] 26601#26601: *737 http script var
2018/04/21 19:33:28 [debug] 26601#26601: *737 http script var: "1"
2018/04/21 19:33:28 [debug] 26601#26601: *737 http script value: "1o"
2018/04/21 19:33:28 [debug] 26601#26601: *737 http script equal
2018/04/21 19:33:28 [debug] 26601#26601: *737 http script equal: no
2018/04/21 19:33:28 [debug] 26601#26601: *737 http script if
2018/04/21 19:33:28 [debug] 26601#26601: *737 http script if: false
2018/04/21 19:33:28 [debug] 26601#26601: *737 post rewrite phase: 5
2018/04/21 19:33:28 [debug] 26601#26601: *737 generic phase: 6
2018/04/21 19:33:28 [debug] 26601#26601: *737 generic phase: 7
2018/04/21 19:33:28 [debug] 26601#26601: *737 generic phase: 8
2018/04/21 19:33:28 [debug] 26601#26601: *737 access phase: 9
2018/04/21 19:33:28 [debug] 26601#26601: *737 access phase: 10
2018/04/21 19:33:28 [debug] 26601#26601: *737 access phase: 11
2018/04/21 19:33:28 [debug] 26601#26601: *737 access phase: 12
2018/04/21 19:33:28 [debug] 26601#26601: *737 post access phase: 13
2018/04/21 19:33:28 [debug] 26601#26601: *737 http client request body preread 386
2018/04/21 19:33:28 [debug] 26601#26601: *737 http request body content length filter
2018/04/21 19:33:28 [debug] 26601#26601: *737 http body new buf t:1 f:0 0000563D539E08EC, pos 0000563D539E08EC, size: 386 file: 0, size: 0
2018/04/21 19:33:28 [debug] 26601#26601: *737 http init upstream, client timer: 0
2018/04/21 19:33:28 [debug] 26601#26601: *737 epoll add event: fd:11 op:3 ev:80002005
2018/04/21 19:33:28 [debug] 26601#26601: *737 http script copy: "Host: "
2018/04/21 19:33:28 [debug] 26601#26601: *737 http script var: "hass.domain.com"
2018/04/21 19:33:28 [debug] 26601#26601: *737 http script copy: "
"
2018/04/21 19:33:28 [debug] 26601#26601: *737 http script copy: "X-Real-IP: "
2018/04/21 19:33:28 [debug] 26601#26601: *737 http script var: "149.154.167.226"
2018/04/21 19:33:28 [debug] 26601#26601: *737 http script copy: "
"
2018/04/21 19:33:28 [debug] 26601#26601: *737 http script copy: "X-Forwarded-Server: "
2018/04/21 19:33:28 [debug] 26601#26601: *737 http script var: "hass.domain.com"
2018/04/21 19:33:28 [debug] 26601#26601: *737 http script copy: "
"
2018/04/21 19:33:28 [debug] 26601#26601: *737 http script copy: "X-Forwarded-For: "
2018/04/21 19:33:28 [debug] 26601#26601: *737 http script var: "149.154.167.226"
2018/04/21 19:33:28 [debug] 26601#26601: *737 http script copy: "
"
2018/04/21 19:33:28 [debug] 26601#26601: *737 http script copy: "X-Forwarded-Proto: "
2018/04/21 19:33:28 [debug] 26601#26601: *737 http script var: "https"
2018/04/21 19:33:28 [debug] 26601#26601: *737 http script copy: "
"
2018/04/21 19:33:28 [debug] 26601#26601: *737 http script copy: ""
2018/04/21 19:33:28 [debug] 26601#26601: *737 http script copy: ""
2018/04/21 19:33:28 [debug] 26601#26601: *737 http script copy: "Connection: upgrade
"
2018/04/21 19:33:28 [debug] 26601#26601: *737 http script copy: "Content-Length: "
2018/04/21 19:33:28 [debug] 26601#26601: *737 http script var: "386"
2018/04/21 19:33:28 [debug] 26601#26601: *737 http script copy: "
"
2018/04/21 19:33:28 [debug] 26601#26601: *737 http script copy: ""
2018/04/21 19:33:28 [debug] 26601#26601: *737 http script copy: ""
2018/04/21 19:33:28 [debug] 26601#26601: *737 http proxy header: "Content-Type: application/json"
2018/04/21 19:33:28 [debug] 26601#26601: *737 http proxy header: "Accept-Encoding: gzip, deflate"
2018/04/21 19:33:28 [debug] 26601#26601: *737 http proxy header:
"POST /api/telegram_webhooks HTTP/1.1
Host: hass.domain.com
X-Real-IP: 149.154.167.226
X-Forwarded-Server: hass.domain.com
X-Forwarded-For: 149.154.167.226
X-Forwarded-Proto: https
Connection: upgrade
Content-Length: 386
Content-Type: application/json
Accept-Encoding: gzip, deflate
"
2018/04/21 19:33:28 [debug] 26601#26601: *737 http cleanup add: 0000563D535F9D50
2018/04/21 19:33:28 [debug] 26601#26601: *737 get rr peer, try: 1
2018/04/21 19:33:28 [debug] 26601#26601: *737 stream socket 12
2018/04/21 19:33:28 [debug] 26601#26601: *737 epoll add connection: fd:12 ev:80002005
2018/04/21 19:33:28 [debug] 26601#26601: *737 connect to 127.0.0.1:8123, fd:12 #738
2018/04/21 19:33:28 [debug] 26601#26601: *737 http upstream connect: -2
2018/04/21 19:33:28 [debug] 26601#26601: *737 posix_memalign: 0000563D5389FC00:128 @16
2018/04/21 19:33:28 [debug] 26601#26601: *737 event timer add: 12: 60000:1524353668960
2018/04/21 19:33:28 [debug] 26601#26601: *737 http finalize request: -4, "/api/telegram_webhooks?" a:1, c:2
2018/04/21 19:33:28 [debug] 26601#26601: *737 http request count:2 blk:0
2018/04/21 19:33:28 [debug] 26601#26601: *737 post event 0000563D535D3830
2018/04/21 19:33:28 [debug] 26601#26601: *737 post event 0000563D535D3890
2018/04/21 19:33:28 [debug] 26601#26601: *737 delete posted event 0000563D535D3830
2018/04/21 19:33:28 [debug] 26601#26601: *737 http run request: "/api/telegram_webhooks?"
2018/04/21 19:33:28 [debug] 26601#26601: *737 http upstream check client, write event:1, "/api/telegram_webhooks"
2018/04/21 19:33:28 [debug] 26601#26601: *737 http upstream recv(): -1 (11: Resource temporarily unavailable)
2018/04/21 19:33:28 [debug] 26601#26601: *737 delete posted event 0000563D535D3890
2018/04/21 19:33:28 [debug] 26601#26601: *737 http upstream request: "/api/telegram_webhooks?"
2018/04/21 19:33:28 [debug] 26601#26601: *737 http upstream send request handler
2018/04/21 19:33:28 [debug] 26601#26601: *737 http upstream send request
2018/04/21 19:33:28 [debug] 26601#26601: *737 http upstream send request body
2018/04/21 19:33:28 [debug] 26601#26601: *737 chain writer buf fl:0 s:294
2018/04/21 19:33:28 [debug] 26601#26601: *737 chain writer buf fl:1 s:386
2018/04/21 19:33:28 [debug] 26601#26601: *737 chain writer in: 0000563D535F9DA8
2018/04/21 19:33:28 [debug] 26601#26601: *737 writev: 680 of 680
2018/04/21 19:33:28 [debug] 26601#26601: *737 chain writer out: 0000000000000000
2018/04/21 19:33:28 [debug] 26601#26601: *737 event timer del: 12: 1524353668960
2018/04/21 19:33:28 [debug] 26601#26601: *737 event timer add: 12: 60000:1524353668960
2018/04/21 19:33:28 [debug] 26601#26601: *737 post event 0000563D53561260
2018/04/21 19:33:28 [debug] 26601#26601: *737 post event 0000563D535D3890
2018/04/21 19:33:28 [debug] 26601#26601: *737 delete posted event 0000563D53561260
2018/04/21 19:33:28 [debug] 26601#26601: *737 http upstream request: "/api/telegram_webhooks?"
2018/04/21 19:33:28 [debug] 26601#26601: *737 http upstream process header
2018/04/21 19:33:28 [debug] 26601#26601: *737 malloc: 0000563D539D5260:4096
2018/04/21 19:33:28 [debug] 26601#26601: *737 recv: fd:12 172 of 4096
2018/04/21 19:33:28 [debug] 26601#26601: *737 http proxy status 200 "200 OK"
2018/04/21 19:33:28 [debug] 26601#26601: *737 http proxy header: "Content-Type: application/json"
2018/04/21 19:33:28 [debug] 26601#26601: *737 http proxy header: "Content-Length: 4"
2018/04/21 19:33:28 [debug] 26601#26601: *737 http proxy header: "Content-Encoding: deflate"
2018/04/21 19:33:28 [debug] 26601#26601: *737 http proxy header: "Date: Sat, 21 Apr 2018 23:33:28 GMT"
2018/04/21 19:33:28 [debug] 26601#26601: *737 http proxy header: "Server: Python/3.5 aiohttp/3.1.1"
2018/04/21 19:33:28 [debug] 26601#26601: *737 http proxy header done
2018/04/21 19:33:28 [debug] 26601#26601: *737 uploadprogress error-tracker error: 0
2018/04/21 19:33:28 [debug] 26601#26601: *737 headers more header filter, uri "/api/telegram_webhooks"
2018/04/21 19:33:28 [debug] 26601#26601: *737 http script copy: ""
2018/04/21 19:33:28 [debug] 26601#26601: *737 xslt filter header
2018/04/21 19:33:28 [debug] 26601#26601: *737 posix_memalign: 0000563D535B56D0:4096 @16
2018/04/21 19:33:28 [debug] 26601#26601: *737 HTTP/1.1 200 OK
Server: nginx/1.10.3
Date: Sat, 21 Apr 2018 23:33:28 GMT
Content-Type: application/json
Content-Length: 4
Connection: keep-alive
Content-Encoding: deflate
Access-Control-Allow-Credentials: true
Strict-Transport-Security: max-age=31536000; includeSubDomains
2018/04/21 19:33:28 [debug] 26601#26601: *737 write new buf t:1 f:0 0000563D535B56F0, pos 0000563D535B56F0, size: 284 file: 0, size: 0
2018/04/21 19:33:28 [debug] 26601#26601: *737 http write filter: l:0 f:0 s:284
2018/04/21 19:33:28 [debug] 26601#26601: *737 http cacheable: 0
2018/04/21 19:33:28 [debug] 26601#26601: *737 http proxy filter init s:200 h:0 c:0 l:4
2018/04/21 19:33:28 [debug] 26601#26601: *737 http upstream process upstream
2018/04/21 19:33:28 [debug] 26601#26601: *737 pipe read upstream: 1
2018/04/21 19:33:28 [debug] 26601#26601: *737 pipe preread: 4
2018/04/21 19:33:28 [debug] 26601#26601: *737 readv: 1, last:3924
2018/04/21 19:33:28 [debug] 26601#26601: *737 readv() not ready (11: Resource temporarily unavailable)
2018/04/21 19:33:28 [debug] 26601#26601: *737 pipe recv chain: -2
2018/04/21 19:33:28 [debug] 26601#26601: *737 pipe buf free s:0 t:1 f:0 0000563D539D5260, pos 0000563D539D5308, size: 4 file: 0, size: 0
2018/04/21 19:33:28 [debug] 26601#26601: *737 pipe length: 4
2018/04/21 19:33:28 [debug] 26601#26601: *737 input buf #0
2018/04/21 19:33:28 [debug] 26601#26601: *737 pipe write downstream: 1
2018/04/21 19:33:28 [debug] 26601#26601: *737 pipe write downstream flush in
2018/04/21 19:33:28 [debug] 26601#26601: *737 http output filter "/api/telegram_webhooks?"
2018/04/21 19:33:28 [debug] 26601#26601: *737 http copy filter: "/api/telegram_webhooks?"
2018/04/21 19:33:28 [debug] 26601#26601: *737 image filter
2018/04/21 19:33:28 [debug] 26601#26601: *737 xslt filter body
2018/04/21 19:33:28 [debug] 26601#26601: *737 http postpone filter "/api/telegram_webhooks?" 0000563D535F9DB8
2018/04/21 19:33:28 [debug] 26601#26601: *737 write old buf t:1 f:0 0000563D535B56F0, pos 0000563D535B56F0, size: 284 file: 0, size: 0
2018/04/21 19:33:28 [debug] 26601#26601: *737 write new buf t:1 f:0 0000563D539D5260, pos 0000563D539D5308, size: 4 file: 0, size: 0
2018/04/21 19:33:28 [debug] 26601#26601: *737 http write filter: l:0 f:0 s:288
2018/04/21 19:33:28 [debug] 26601#26601: *737 http copy filter: 0 "/api/telegram_webhooks?"
2018/04/21 19:33:28 [debug] 26601#26601: *737 pipe write downstream done
2018/04/21 19:33:28 [debug] 26601#26601: *737 event timer: 12, old: 1524353668960, new: 1524353668983
2018/04/21 19:33:28 [debug] 26601#26601: *737 http upstream exit: 0000000000000000
2018/04/21 19:33:28 [debug] 26601#26601: *737 finalize http upstream request: 0
2018/04/21 19:33:28 [debug] 26601#26601: *737 finalize http proxy request
2018/04/21 19:33:28 [debug] 26601#26601: *737 free rr peer 1 0
2018/04/21 19:33:28 [debug] 26601#26601: *737 close http upstream connection: 12
2018/04/21 19:33:28 [debug] 26601#26601: *737 free: 0000563D5389FC00, unused: 48
2018/04/21 19:33:28 [debug] 26601#26601: *737 event timer del: 12: 1524353668960
2018/04/21 19:33:28 [debug] 26601#26601: *737 delete posted event 0000563D535D3890
2018/04/21 19:33:28 [debug] 26601#26601: *737 reusable connection: 0
2018/04/21 19:33:28 [debug] 26601#26601: *737 http upstream temp fd: -1
2018/04/21 19:33:28 [debug] 26601#26601: *737 http output filter "/api/telegram_webhooks?"
2018/04/21 19:33:28 [debug] 26601#26601: *737 http copy filter: "/api/telegram_webhooks?"
2018/04/21 19:33:28 [debug] 26601#26601: *737 image filter
2018/04/21 19:33:28 [debug] 26601#26601: *737 xslt filter body
2018/04/21 19:33:28 [debug] 26601#26601: *737 http postpone filter "/api/telegram_webhooks?" 00007FFC892E4220
2018/04/21 19:33:28 [debug] 26601#26601: *737 write old buf t:1 f:0 0000563D535B56F0, pos 0000563D535B56F0, size: 284 file: 0, size: 0
2018/04/21 19:33:28 [debug] 26601#26601: *737 write old buf t:1 f:0 0000563D539D5260, pos 0000563D539D5308, size: 4 file: 0, size: 0
2018/04/21 19:33:28 [debug] 26601#26601: *737 write new buf t:0 f:0 0000000000000000, pos 0000000000000000, size: 0 file: 0, size: 0
2018/04/21 19:33:28 [debug] 26601#26601: *737 http write filter: l:1 f:0 s:288
2018/04/21 19:33:28 [debug] 26601#26601: *737 http write filter limit 0
2018/04/21 19:33:28 [debug] 26601#26601: *737 posix_memalign: 0000563D535B6A10:512 @16
2018/04/21 19:33:28 [debug] 26601#26601: *737 malloc: 0000563D5376F650:16384
2018/04/21 19:33:28 [debug] 26601#26601: *737 SSL buf copy: 284
2018/04/21 19:33:28 [debug] 26601#26601: *737 SSL buf copy: 4
2018/04/21 19:33:28 [debug] 26601#26601: *737 SSL to write: 288
2018/04/21 19:33:28 [debug] 26601#26601: *737 SSL_write: 288
2018/04/21 19:33:28 [debug] 26601#26601: *737 http write filter 0000000000000000
2018/04/21 19:33:28 [debug] 26601#26601: *737 http copy filter: 0 "/api/telegram_webhooks?"
2018/04/21 19:33:28 [debug] 26601#26601: *737 http finalize request: 0, "/api/telegram_webhooks?" a:1, c:1
2018/04/21 19:33:28 [debug] 26601#26601: *737 set http keepalive handler
2018/04/21 19:33:28 [debug] 26601#26601: *737 http close request
2018/04/21 19:33:28 [debug] 26601#26601: *737 http log handler
2018/04/21 19:33:28 [debug] 26601#26601: *737 free: 0000563D539D5260
2018/04/21 19:33:28 [debug] 26601#26601: *737 free: 0000563D534C9570, unused: 0
2018/04/21 19:33:28 [debug] 26601#26601: *737 free: 0000563D535F9180, unused: 8
2018/04/21 19:33:28 [debug] 26601#26601: *737 free: 0000563D535B56D0, unused: 3270
2018/04/21 19:33:28 [debug] 26601#26601: *737 free: 0000563D539E0840
2018/04/21 19:33:28 [debug] 26601#26601: *737 hc free: 0000000000000000 0
2018/04/21 19:33:28 [debug] 26601#26601: *737 hc busy: 0000000000000000 0
2018/04/21 19:33:28 [debug] 26601#26601: *737 free: 0000563D5376F650
2018/04/21 19:33:28 [debug] 26601#26601: *737 tcp_nodelay
2018/04/21 19:33:28 [debug] 26601#26601: *737 reusable connection: 1
2018/04/21 19:33:28 [debug] 26601#26601: *737 event timer add: 11: 70000:1524353678983
2018/04/21 19:33:29 [debug] 26601#26601: *737 post event 0000563D53561200
2018/04/21 19:33:29 [debug] 26601#26601: *737 post event 0000563D535D3830
2018/04/21 19:33:29 [debug] 26601#26601: *737 delete posted event 0000563D53561200
2018/04/21 19:33:29 [debug] 26601#26601: *737 http keepalive handler
2018/04/21 19:33:29 [debug] 26601#26601: *737 malloc: 0000563D539E0840:1024
2018/04/21 19:33:29 [debug] 26601#26601: *737 SSL_read: 47
2018/04/21 19:33:29 [debug] 26601#26601: *737 SSL_read: -1
2018/04/21 19:33:29 [debug] 26601#26601: *737 SSL_get_error: 2
2018/04/21 19:33:29 [debug] 26601#26601: *737 reusable connection: 0
2018/04/21 19:33:29 [debug] 26601#26601: *737 posix_memalign: 0000563D534C9570:4096 @16
2018/04/21 19:33:29 [debug] 26601#26601: *737 event timer del: 11: 1524353678983
2018/04/21 19:33:29 [debug] 26601#26601: *737 http process request line
2018/04/21 19:33:29 [info] 26601#26601: *737 client sent invalid method while reading client request line, client: 149.154.167.226, server: hass.domain.com, request: "HTTP/1.1 400 Bad Request"
2018/04/21 19:33:29 [debug] 26601#26601: *737 http finalize request: 400, "?" a:1, c:1
2018/04/21 19:33:29 [debug] 26601#26601: *737 http special response: 400, "?"
2018/04/21 19:33:29 [debug] 26601#26601: *737 http set discard body
2018/04/21 19:33:29 [debug] 26601#26601: *737 uploadprogress error-tracker error: 400
2018/04/21 19:33:29 [debug] 26601#26601: *737 uploadprogress error-tracker not tracking in this location
2018/04/21 19:33:29 [debug] 26601#26601: *737 headers more header filter, uri ""
2018/04/21 19:33:29 [debug] 26601#26601: *737 xslt filter header
2018/04/21 19:33:29 [debug] 26601#26601: *737 HTTP/1.1 400 Bad Request
Server: nginx/1.10.3
Date: Sat, 21 Apr 2018 23:33:29 GMT
Content-Type: text/html
Content-Length: 173
Connection: close
2018/04/21 19:33:29 [debug] 26601#26601: *737 write new buf t:1 f:0 0000563D534CA338, pos 0000563D534CA338, size: 152 file: 0, size: 0
2018/04/21 19:33:29 [debug] 26601#26601: *737 http write filter: l:0 f:0 s:152
2018/04/21 19:33:29 [debug] 26601#26601: *737 http output filter "?"
2018/04/21 19:33:29 [debug] 26601#26601: *737 http copy filter: "?"
2018/04/21 19:33:29 [debug] 26601#26601: *737 image filter
2018/04/21 19:33:29 [debug] 26601#26601: *737 xslt filter body
2018/04/21 19:33:29 [debug] 26601#26601: *737 http postpone filter "?" 0000563D534CA510
2018/04/21 19:33:29 [debug] 26601#26601: *737 write old buf t:1 f:0 0000563D534CA338, pos 0000563D534CA338, size: 152 file: 0, size: 0
2018/04/21 19:33:29 [debug] 26601#26601: *737 write new buf t:0 f:0 0000000000000000, pos 0000563D52A38940, size: 120 file: 0, size: 0
2018/04/21 19:33:29 [debug] 26601#26601: *737 write new buf t:0 f:0 0000000000000000, pos 0000563D52A38E40, size: 53 file: 0, size: 0
2018/04/21 19:33:29 [debug] 26601#26601: *737 http write filter: l:1 f:0 s:325
2018/04/21 19:33:29 [debug] 26601#26601: *737 http write filter limit 0
2018/04/21 19:33:29 [debug] 26601#26601: *737 malloc: 0000563D5376F650:16384
2018/04/21 19:33:29 [debug] 26601#26601: *737 SSL buf copy: 152
2018/04/21 19:33:29 [debug] 26601#26601: *737 SSL buf copy: 120
2018/04/21 19:33:29 [debug] 26601#26601: *737 SSL buf copy: 53
2018/04/21 19:33:29 [debug] 26601#26601: *737 SSL to write: 325
2018/04/21 19:33:29 [debug] 26601#26601: *737 SSL_write: 325
2018/04/21 19:33:29 [debug] 26601#26601: *737 http write filter 0000000000000000
2018/04/21 19:33:29 [debug] 26601#26601: *737 http copy filter: 0 "?"
2018/04/21 19:33:29 [debug] 26601#26601: *737 http finalize request: 0, "?" a:1, c:1
2018/04/21 19:33:29 [debug] 26601#26601: *737 event timer add: 11: 5000:1524353614067
2018/04/21 19:33:29 [debug] 26601#26601: *737 delete posted event 0000563D535D3830
2018/04/21 19:33:29 [debug] 26601#26601: *737 http empty handler
2018/04/21 19:33:29 [debug] 26601#26601: *737 post event 0000563D535D3830
2018/04/21 19:33:29 [debug] 26601#26601: *737 delete posted event 0000563D535D3830
2018/04/21 19:33:29 [debug] 26601#26601: *737 http empty handler
2018/04/21 19:33:29 [debug] 26601#26601: *737 post event 0000563D53561200
2018/04/21 19:33:29 [debug] 26601#26601: *737 post event 0000563D535D3830
2018/04/21 19:33:29 [debug] 26601#26601: *737 delete posted event 0000563D53561200
2018/04/21 19:33:29 [debug] 26601#26601: *737 http lingering close handler
2018/04/21 19:33:29 [debug] 26601#26601: *737 SSL_read: 0
2018/04/21 19:33:29 [debug] 26601#26601: *737 SSL_get_error: 5
2018/04/21 19:33:29 [debug] 26601#26601: *737 peer shutdown SSL cleanly
2018/04/21 19:33:29 [debug] 26601#26601: *737 lingering read: 0
2018/04/21 19:33:29 [debug] 26601#26601: *737 http request count:1 blk:0
2018/04/21 19:33:29 [debug] 26601#26601: *737 http close request
2018/04/21 19:33:29 [debug] 26601#26601: *737 http log handler
2018/04/21 19:33:29 [debug] 26601#26601: *737 posix_memalign: 0000563D535F9180:4096 @16
2018/04/21 19:33:29 [debug] 26601#26601: *737 free: 0000563D534C9570, unused: 32
2018/04/21 19:33:29 [debug] 26601#26601: *737 free: 0000563D535F9180, unused: 3938
2018/04/21 19:33:29 [debug] 26601#26601: *737 close http connection: 11
2018/04/21 19:33:29 [debug] 26601#26601: *737 SSL_shutdown: 1
2018/04/21 19:33:29 [debug] 26601#26601: *737 event timer del: 11: 1524353614067
2018/04/21 19:33:29 [debug] 26601#26601: *737 delete posted event 0000563D535D3830
2018/04/21 19:33:29 [debug] 26601#26601: *737 reusable connection: 0
2018/04/21 19:33:29 [debug] 26601#26601: *737 free: 0000563D539E0840
2018/04/21 19:33:29 [debug] 26601#26601: *737 free: 0000563D5376F650
2018/04/21 19:33:29 [debug] 26601#26601: *737 free: 0000563D538236F0, unused: 8
2018/04/21 19:33:29 [debug] 26601#26601: *737 free: 0000563D535B6A10, unused: 400
2018/04/21 19:33:29 [debug] 26601#26601: *739 SSL_do_handshake: -1
2018/04/21 19:33:29 [debug] 26601#26601: *739 SSL_get_error: 2
2018/04/21 19:33:29 [debug] 26601#26601: *739 reusable connection: 0
2018/04/21 19:33:29 [debug] 26601#26601: *739 post event 0000563D53561200
2018/04/21 19:33:29 [debug] 26601#26601: *739 delete posted event 0000563D53561200
2018/04/21 19:33:29 [debug] 26601#26601: *739 SSL handshake handler: 0
2018/04/21 19:33:29 [debug] 26601#26601: *739 SSL_do_handshake: 1
2018/04/21 19:33:29 [debug] 26601#26601: *739 SSL: TLSv1.2, cipher: "ECDHE-RSA-AES128-GCM-SHA256 TLSv1.2 Kx=ECDH Au=RSA Enc=AESGCM(128) Mac=AEAD"
2018/04/21 19:33:29 [debug] 26601#26601: *739 reusable connection: 1
2018/04/21 19:33:29 [debug] 26601#26601: *739 http wait request handler
2018/04/21 19:33:29 [debug] 26601#26601: *739 malloc: 0000563D539BBF10:1024
2018/04/21 19:33:29 [debug] 26601#26601: *739 SSL_read: -1
2018/04/21 19:33:29 [debug] 26601#26601: *739 SSL_get_error: 2
2018/04/21 19:33:29 [debug] 26601#26601: *739 free: 0000563D539BBF10
Guys, a have got this issue with telegram too. I try to fix it using pushbullet notification instead of telegram. But it is still triggered(( i guess, maybe it is not telegram issue, but maybe component (i use xiaomi sensors). thanks
I am using Nginx to proxy HomeAssistant. Can you guys share your Nginx settings? Let's see if they may be involved.
I have added keepalive_timeout 0; to my proxy settings and it seems to avoid the 400 error, but still Telegram seems to keep retrying messages as if they were not delivered.
My nginx settings, for the record (before any attempt to fix tihs):
server {
listen 443;
server_name myost;
ssl_certificate /etc/letsencrypt/live/myhost/fullchain.pem;
ssl_certificate_key /etc/letsencrypt/live/myhost/privkey.pem;
ssl on;
ssl_session_cache builtin:1000 shared:SSL:10m;
ssl_protocols TLSv1 TLSv1.1 TLSv1.2;
ssl_ciphers HIGH:!aNULL:!eNULL:!EXPORT:!CAMELLIA:!DES:!MD5:!PSK:!RC4;
ssl_prefer_server_ciphers on;
access_log /var/log/nginx/myhost.access.log;
#large_client_header_buffers 4 16k;
#ignore_invalid_headers off;
#keepalive_timeout 0;
proxy_buffering off;
location / {
proxy_set_header Host $host;
proxy_set_header X-Real-IP $remote_addr;
proxy_set_header X-Forwarded-For $proxy_add_x_forwarded_for;
proxy_set_header X-Forwarded-Proto $scheme;
proxy_set_header Upgrade $http_upgrade;
proxy_set_header Connection $connection_upgrade;
# Fix the “It appears that your reverse proxy set up is broken" error.
proxy_pass http://localhost:8123;
proxy_read_timeout 90;
proxy_redirect http://localhost:8123 https://myhost;
}
}
Also, my biggest question is about this line:
2018/04/21 19:33:29 [info] 26601#26601: *737 client sent invalid method while reading client request line, client: 149.154.167.226, server: hass.domain.com, request: "HTTP/1.1 400 Bad Request"
I don't understand it. It seems to suggest that while Nginx wa still processing the request and before producing any output, the client (Telegram), sent another HTTP verb? where does the 400 Bad Request come from, Nginx or Telegram?
I have searched and this might be related to websockets, I tried diabling connection upgrades (for websockets) altogether but Telegram still hits nginx several times.
I have also tried downgrading to python-telegram-bot 9.0.0 and upgrading to 10.0.2 with no result.
@jjmontesl That is my Nginx config file
upstream hass-domain-com {
server 10.20.30.40:8123;
# socat -v TCP-LISTEN:8123,fork TCP:10.20.30.40:8123
# server 127.0.0.1:8123;
}
server {
listen 80;
listen [::]:80;
server_name hass.domain.com;
return 301 https://hass.domain.com$request_uri;
}
server {
listen 443 ssl http2;
listen [::]:443 ssl http2;
server_name hass.domain.com;
keepalive_timeout 70;
gzip on;
gzip_comp_level 9;
gzip_min_length 512;
gzip_buffers 8 64k;
gzip_types text/css application/json application/x-javascript text/xml application/xml application/xml+rss text/javascript application/javascript image/svg+xml;
gzip_proxied any;
include templates/certbot.conf;
location / {
add_header Strict-Transport-Security "max-age=31536000; includeSubDomains" always;
proxy_http_version 1.1;
proxy_redirect off;
proxy_set_header Host $host;
proxy_set_header X-Real-IP $remote_addr;
proxy_set_header X-Forwarded-Server $host;
proxy_set_header X-Forwarded-For $proxy_add_x_forwarded_for;
proxy_set_header X-Forwarded-Proto $scheme;
proxy_set_header Upgrade $http_upgrade;
proxy_set_header Connection "upgrade";
# Nginx doesn't support nested If statements, so we
# concatenate compound conditions on the $cors variable
# and process later
# If request comes from allowed subdomain
# (hass.domain.com) then we enable CORS
if ($http_origin ~* (https?://hass\.domain\.com(:[0-9]+)?$)) {
set $cors "1";
}
# OPTIONS indicates a CORS pre-flight request
if ($request_method = 'OPTIONS') {
set $cors "${cors}o";
}
# Append CORS headers to any request from
# allowed CORS domain, except OPTIONS
if ($cors = "1") {
more_set_headers 'Access-Control-Allow-Origin: $http_origin';
more_set_headers 'Access-Control-Allow-Credentials: true';
proxy_pass http://hass-domain-com;
}
# OPTIONS (pre-flight) request from allowed
# CORS domain. return response directly
if ($cors = "1o") {
more_set_headers 'Access-Control-Allow-Origin: $http_origin';
more_set_headers 'Access-Control-Allow-Methods: GET, POST, OPTIONS, PUT, DELETE';
more_set_headers 'Access-Control-Allow-Credentials: true';
more_set_headers 'Access-Control-Allow-Headers: Origin,Content-Type,Accept';
add_header Content-Length 0;
add_header Content-Type text/plain;
return 204;
}
# Requests from non-allowed CORS domains
proxy_pass http://hass-domain-com;
}
ssl_certificate /etc/letsencrypt/live/hass.domain.com/fullchain.pem;
ssl_certificate_key /etc/letsencrypt/live/hass.domain.com/privkey.pem;
ssl_trusted_certificate /etc/letsencrypt/live/hass.domain.com/fullchain.pem;
ssl_session_timeout 1d;
ssl_session_cache shared:SSL:50m;
ssl_dhparam /etc/nginx/ssl/dhparam.pem;
ssl_protocols TLSv1 TLSv1.1 TLSv1.2;
ssl_ciphers 'ECDHE-RSA-AES128-GCM-SHA256:ECDHE-ECDSA-AES128-GCM-SHA256:ECDHE-RSA-AES256-GCM-SHA384:ECDHE-ECDSA-AES256-GCM-SHA384:DHE-RSA-AES128-GCM-SHA256:DHE-DSS-AES128-GCM-SHA256:kEDH+AESGCM:ECDHE-RSA-AES128-SHA256:ECDHE-ECDSA-AES128-SHA256:ECDHE-RSA-AES128-SHA:ECDHE-ECDSA-AES128-SHA:ECDHE-RSA-AES256-SHA384:ECDHE-ECDSA-AES256-SHA384:ECDHE-RSA-AES256-SHA:ECDHE-ECDSA-AES256-SHA:DHE-RSA-AES128-SHA256:DHE-RSA-AES128-SHA:DHE-DSS-AES128-SHA256:DHE-RSA-AES256-SHA256:DHE-DSS-AES256-SHA:DHE-RSA-AES256-SHA:ECDHE-RSA-DES-CBC3-SHA:ECDHE-ECDSA-DES-CBC3-SHA:AES128-GCM-SHA256:AES256-GCM-SHA384:AES128-SHA256:AES256-SHA256:AES128-SHA:AES256-SHA:AES:CAMELLIA:DES-CBC3-SHA:!aNULL:!eNULL:!EXPORT:!DES:!RC4:!MD5:!PSK:!aECDH:!EDH-DSS-DES-CBC3-SHA:!EDH-RSA-DES-CBC3-SHA:!KRB5-DES-CBC3-SHA';
ssl_prefer_server_ciphers on;
add_header Strict-Transport-Security max-age=15768000;
add_header X-Frame-Options "DENY";
ssl_stapling on;
ssl_stapling_verify on;
resolver 8.8.8.8 8.8.4.4 valid=300s;
resolver_timeout 5s;
access_log /var/log/nginx/access.hass.domain.com.log;
error_log /var/log/nginx/errors.hass.domain.com.log debug;
}
0.68
The issue still exists
There hasn't been any activity on this issue recently. Due to the high number of incoming GitHub notifications, we have to clean some of the old issues, as many of them have already been resolved with the latest updates.
Please make sure to update to the latest Home Assistant version and check if that solves the issue. Let us know if that works for you by adding a comment :+1:
@balloobbot I checked it today on v0.74.2.
And I have to say that it was fixed!
I just updated to 0.74.2 but still face the same problem when I changed to webhooks
I have updated and still have the same problem.
im having this issue too on 0.79.3 using webhooks, any way to fix it?
can confirm what switching for polling works for 0.79.3
Can confirm too, as a notification i used pushbullet.
I'm using polling since this bug appeared and it's working fine. Webhooks is broken.
Using 0.79.3
I tried to setup webhooks and found Telegram endlessly calling my webhook with the same updates - the message included in the POST was the same each time; as if Telegram believed I had not been notified of that message yet so was retrying.
Comparing the behaviour of webhooks.py to other examples on the web the only obvious difference was this component returned an empty json structure (line 123):
return self.json({})
I've changed that on my local copy to
return None
as other examples seem to simply return an HTTP 200 code, with no content.
Having done this the webhook seems to be working properly.
If anyone is still listening and wants to give it a try, it would be interesting to know if it solves anyone elses issues...
Thanks @davisonja
I tested it with a custom component changing to "return None" and works great!
Using 0.79.3
I tried to setup webhooks and found Telegram endlessly calling my webhook with the same updates - the message included in the POST was the same each time; as if Telegram believed I had not been notified of that message yet so was retrying.
Comparing the behaviour of webhooks.py to other examples on the web the only obvious difference was this component returned an empty json structure (line 123):
return self.json({})
I've changed that on my local copy to
return None
as other examples seem to simply return an HTTP 200 code, with no content.Having done this the webhook seems to be working properly.
If anyone is still listening and wants to give it a try, it would be interesting to know if it solves anyone elses issues...
i just gave it a try... and it works!
Anyway, referring back to the documentation at https://www.home-assistant.io/components/telegram_bot.webhooks/
It says "Using Telegrams setWebhook method your bot’s webhook URL should be set to https://
Anyone has any idea where to set this?
Thanks @luca-angemi for the Pull Request...I hope it gets accepted soon.
Thanks to @davisonja to find the fix!
@master-kenobi you don't have to set anything, just the configuration.yaml.
I think they are just referring to the fact that the webhook will have that endpoint.
Most helpful comment
Same here. Running latest hassio 0.64.3 and python 3.6.3. Using polling is working fine. Adding the bot as a webhook with a simple event listener starts executing the automation continuously, even without firing the command. It looks like it keeps creating events. This is my setup:
Additionally: I run hass.io behind the Bestlibre Nginx add-on.