Incoming telegram bot msgs not processed

jalm · September 18, 2020, 10:55am

Hi everybody,

I’ve been using Telegram binding succesfully for some months already. I can send commands from my smartphone and receive notifications from Openhab 2.5.8 by using a Telegram bot, which I configured in PaperUI.

However, since last update my messages to the bot are processed only for a while. Then, apparently after 15-30 minutes of restarting openhab service my messages are queued undefinitely and not processed any longer. I can see in my smartphone that my messages are delivered (double tick), but OH2 is simply not handling them. In fact, the corresponding lastMessageText channel of my Telegram bot is not updated (checked both in PaperUI and from Visual Studio Code). Of course my rules depending on that channel update are not triggered.

I read that after an OH2 update it is advisable to clean the cache, which I did by running:

openhab-cli clean-cache

and possibly restart OH2 a couple of times. I’ve tried that several times but to no avail.

I have found two ways of overcoming the problem.

Restarting openhab service: the message queue works normally (but again only for 15-30 minutes) and my pending messages are lost…
Disabling and re-enabling Telegram thing in openhab: all pending messages are processed immediately and rules are triggered correctly for 15-30 minutes.

Maybe someone has a clue of the underlying issue?

Wolfgang_S · September 18, 2020, 11:04am

Please post your rule and bot configuration.
Any entry in the openhab.log or events.log logfile ?

jalm · September 18, 2020, 11:30am

Telegram bot is configured in PaperUI (no files) as follows:

Two Chat Ids have been defined in the “Chat Ids” field.

My rule (ChatIdJavi has been abreviated):


val telegramActions = getActions("telegram","telegram:telegramBot:Tbot")
val Long ChatIdJavi = 14877...L

rule "Receive telegram DTenue"
when
    Item telegram_telegramBot_Tbot_lastMessageText received update "DTenue"
then
	knx_device_cc714aee_Despacho1.sendCommand(15)
	telegramActions.sendTelegram(ChatIdJavi, "DTenue")
	logInfo("telegram", "Escena DTenue - Javi")
end

openhab.log has no errors or warnings.

events.log is not being particularly useful either. All I can see when disabling (12:22:02) and re-enabling the bot thing is that my pending messages are all processed immediately (only DTenue message triggers a rule):

2020-09-18 12:22:02.201 [hingStatusInfoChangedEvent] - 'telegram:telegramBot:Tbot' changed from ONLINE to UNINITIALIZED
2020-09-18 12:22:02.250 [hingStatusInfoChangedEvent] - 'telegram:telegramBot:Tbot' changed from UNINITIALIZED to UNINITIALIZED (DISABLED)
2020-09-18 12:22:02.995 [hingStatusInfoChangedEvent] - 'telegram:telegramBot:Tbot' changed from UNINITIALIZED (DISABLED) to INITIALIZING
2020-09-18 12:22:03.106 [hingStatusInfoChangedEvent] - 'telegram:telegramBot:Tbot' changed from INITIALIZING to UNKNOWN
2020-09-18 12:22:03.483 [hingStatusInfoChangedEvent] - 'telegram:telegramBot:Tbot' changed from UNKNOWN to ONLINE
2020-09-18 12:22:03.550 [vent.ItemStateChangedEvent] - telegram_telegramBot_Tbot_lastMessageDate changed from 2020-09-18T10:03:49.000+0000 to 2020-09-18T10:14:45.000+0000
2020-09-18 12:22:03.562 [vent.ItemStateChangedEvent] - telegram_telegramBot_Tbot_lastMessageDate changed from 2020-09-18T10:14:45.000+0000 to 2020-09-18T10:16:34.000+0000
2020-09-18 12:22:03.565 [vent.ItemStateChangedEvent] - telegram_telegramBot_Tbot_lastMessageText changed from A to B
2020-09-18 12:22:03.566 [vent.ItemStateChangedEvent] - telegram_telegramBot_Tbot_lastMessageDate changed from 2020-09-18T10:16:34.000+0000 to 2020-09-18T10:17:06.000+0000
2020-09-18 12:22:03.568 [vent.ItemStateChangedEvent] - telegram_telegramBot_Tbot_lastMessageText changed from B to A
2020-09-18 12:22:03.569 [vent.ItemStateChangedEvent] - telegram_telegramBot_Tbot_lastMessageDate changed from 2020-09-18T10:17:06.000+0000 to 2020-09-18T10:17:10.000+0000
2020-09-18 12:22:03.570 [vent.ItemStateChangedEvent] - telegram_telegramBot_Tbot_lastMessageText changed from A to H
2020-09-18 12:22:03.572 [vent.ItemStateChangedEvent] - telegram_telegramBot_Tbot_lastMessageDate changed from 2020-09-18T10:17:10.000+0000 to 2020-09-18T10:17:30.000+0000
2020-09-18 12:22:03.574 [vent.ItemStateChangedEvent] - telegram_telegramBot_Tbot_lastMessageText changed from H to DTenue
2020-09-18 12:22:03.575 [vent.ItemStateChangedEvent] - telegram_telegramBot_Tbot_lastMessageDate changed from 2020-09-18T10:17:30.000+0000 to 2020-09-18T10:18:29.000+0000
2020-09-18 12:22:03.577 [vent.ItemStateChangedEvent] - telegram_telegramBot_Tbot_lastMessageDate changed from 2020-09-18T10:18:29.000+0000 to 2020-09-18T10:21:06.000+0000
2020-09-18 12:22:05.361 [ome.event.ItemCommandEvent] - Item 'knx_device_cc714aee_Despacho1' received command 15
2020-09-18 12:22:05.376 [ome.event.ItemCommandEvent] - Item 'knx_device_cc714aee_Despacho1' received command 15
2020-09-18 12:22:05.388 [nt.ItemStatePredictedEvent] - knx_device_cc714aee_Despacho1 predicted to become 15
2020-09-18 12:22:05.395 [nt.ItemStatePredictedEvent] - knx_device_cc714aee_Despacho1 predicted to become 15
2020-09-18 12:22:05.403 [vent.ItemStateChangedEvent] - knx_device_cc714aee_Despacho1 changed from 0 to 15

However, I cannot find any error or warning entry corresponding to the moment when the queue is stopped.

Thanks, Wolfgang, for answering so quickly! If you need any more informations, I’d be glad to provide them.

mstormi · September 18, 2020, 12:32pm

With this info it is mostly guessing.
Get proper debug output first to find out if anything arrives on telegram and if the rule is triggered.
To find out, set proper Karaf log levels:

log:set debug org.openhab.binding.telegram
log:set debug org.eclipse.smarthome.model.script.telegram

jalm · September 18, 2020, 3:39pm

Thanks for pointing out log levels in Karaf. I have changed them as suggested but no much further information was thrown out, so I changed the log levels to TRACE:

openhab> log:get
Logger                                             │ Level
───────────────────────────────────────────────────┼──────
ROOT                                               │ WARN
javax.jmdns                                        │ ERROR
javax.mail                                         │ ERROR
org.apache.karaf.jaas.modules.audit                │ INFO
org.apache.karaf.kar.internal.KarServiceImpl       │ ERROR
org.apache.karaf.shell.ssh.SshUtils                │ ERROR
org.apache.karaf.shell.support                     │ OFF
org.apache.sshd                                    │ WARN
org.eclipse.lsp4j                                  │ OFF
org.eclipse.smarthome                              │ INFO
org.eclipse.smarthome.model.script.telegram        │ TRACE
org.jupnp                                          │ ERROR
org.openhab                                        │ INFO
org.openhab.binding.telegram                       │ TRACE
org.openhab.ui.paper                               │ WARN
org.openhab.ui.paper.internal                      │ INFO
org.ops4j.pax.url.mvn.internal.AetherBasedResolver │ ERROR
org.ops4j.pax.web.pax-web-runtime                  │ OFF
smarthome.event                                    │ INFO
smarthome.event.InboxUpdatedEvent                  │ ERROR
smarthome.event.ItemAddedEvent                     │ ERROR
smarthome.event.ItemRemovedEvent                   │ ERROR
smarthome.event.ItemStateEvent                     │ ERROR
smarthome.event.ThingAddedEvent                    │ ERROR
smarthome.event.ThingRemovedEvent                  │ ERROR
smarthome.event.ThingStatusInfoEvent               │ ERROR

This is the result of log:tail when sending DTenue from my smartphone shortly after OH2 restart (26 minutes after restart to be exact):

17:04:07.425 [INFO ] [smarthome.event.ItemStateChangedEvent] - telegram_telegramBot_Tbot_lastMessageDate changed from 2020-09-18T14:59:07.000+0000 to 2020-09-18T15:04:07.000+0000
17:04:07.429 [INFO ] [smarthome.event.ItemCommandEvent     ] - Item 'knx_device_cc714aee_Despacho1' received command 15
17:04:07.446 [INFO ] [arthome.event.ItemStatePredictedEvent] - knx_device_cc714aee_Despacho1 predicted to become 15
17:04:07.458 [INFO ] [smarthome.event.ItemStateChangedEvent] - knx_device_cc714aee_Despacho1 changed from 0 to 15
17:04:07.511 [INFO ] [lipse.smarthome.model.script.telegram] - Escena DTenue - Javi

The scene is correctly set up.
However, 2 minutes later I send DTenue again, but his time the scene is not set up and no messages whatsoever are logged, not even in the 9 minutes period I waited for.
If I then disable and re-enable TBot thing from PaperUI, following messages are logged:

17:15:04.967 [INFO ] [ome.event.ThingStatusInfoChangedEvent] - 'telegram:telegramBot:Tbot' changed from ONLINE to UNINITIALIZED
17:15:04.988 [DEBUG] [ing.telegram.internal.TelegramHandler] - Trying to dispose Telegram client
17:15:04.991 [DEBUG] [ing.telegram.internal.TelegramHandler] - Telegram client closed
17:15:05.008 [INFO ] [ome.event.ThingStatusInfoChangedEvent] - 'telegram:telegramBot:Tbot' changed from UNINITIALIZED to UNINITIALIZED (DISABLED)
17:15:05.523 [INFO ] [ome.event.ThingStatusInfoChangedEvent] - 'telegram:telegramBot:Tbot' changed from UNINITIALIZED (DISABLED) to INITIALIZING
17:15:05.551 [INFO ] [ome.event.ThingStatusInfoChangedEvent] - 'telegram:telegramBot:Tbot' changed from INITIALIZING to UNKNOWN
17:15:05.978 [INFO ] [ome.event.ThingStatusInfoChangedEvent] - 'telegram:telegramBot:Tbot' changed from UNKNOWN to ONLINE
17:15:05.992 [INFO ] [smarthome.event.ItemStateChangedEvent] - telegram_telegramBot_Tbot_lastMessageDate changed from 2020-09-18T15:04:07.000+0000 to 2020-09-18T15:06:57.000+0000
17:15:05.995 [INFO ] [smarthome.event.ItemCommandEvent     ] - Item 'knx_device_cc714aee_Despacho1' received command 15
17:15:06.018 [INFO ] [arthome.event.ItemStatePredictedEvent] - knx_device_cc714aee_Despacho1 predicted to become 15
17:15:06.027 [INFO ] [smarthome.event.ItemStateChangedEvent] - knx_device_cc714aee_Despacho1 changed from 0 to 15
17:15:06.340 [INFO ] [lipse.smarthome.model.script.telegram] - Escena DTenue - Javi

As you can see, in the log entry from 17:15:05.992 the lastMessageDate is set to 17:06:57, i.e. the time when I sent the second DTenue which was ignored by OH2. The scene is now correctly set up.

Additional info: OH2 2.5.8 is running on a Raspberry Pi 4 under Debian 10.4.

jalm · September 24, 2020, 10:45pm

I’ve found a workaround. I post it here for reference, as this might help other folks having the same issue in the future.

I have introduced a cron rule which runs every 10 minutes to disable and then re-enable my telegram bot thing using the REST API (see also [SOLVED] Enabling and disabling Things from for example Basic UI)

rule "Desbloquear Tbot"
when
    Time cron "0 */10 * ? * *"                  /* Cada 10 minutos */
then
    sendHttpPutRequest("http://localhost:8080/rest/things/telegram:telegramBot:Tbot/enable", "application/json", 'false', 5000)
	Thread::sleep(500)  
    sendHttpPutRequest("http://localhost:8080/rest/things/telegram:telegramBot:Tbot/enable", "application/json", 'true', 5000)
end

StefanH · September 25, 2020, 1:01pm

Hi all,

I can confirm that disabling and re-enabling the bot helps. Same situation here, it worked like a charm, out of a sudden no updates anymore in openHAB. After disabling/enabling I see in the logs that the telegram items have been updated.

PS: I’m on 2.5.9

Stefan

Kulwinderjit_Singh · March 8, 2021, 2:29am

I am facing exactly same issue. Is there any actual fix instead of workaround?

jalm · March 8, 2021, 9:58am

I have not checked whether the issue has meanwhile been solved. Are you running OH 2.5 or 3.0?

Kulwinderjit_Singh · March 8, 2021, 12:12pm

i am using latest 3.0.1 openhabian on rpi

Bee0001 · June 28, 2021, 2:54pm

I have the same issue in openHAB 3.1.0

At the moment I have solved it by modifying the rule so that it works in openHAB 3:

rule "Restart Telegram Binding"
when
    Time cron "0 */10 * ? * *"
then
    val headers = newHashMap("Authorization" -> "Bearer <your-api-token>", "WWW-Authenticate"-> "Basic")
    sendHttpPutRequest("http://localhost:8080/rest/things/telegram:telegramBot:XXXXXX/enable", "application/json", 'false', headers, 5000)
    Thread::sleep(500)  
    sendHttpPutRequest("http://localhost:8080/rest/things/telegram:telegramBot:XXXXXX/enable", "application/json", 'true', headers, 5000)
end

@jalm are you in openhab 3? have you found a different solution?

jalm · June 30, 2021, 11:36am

No, I’m still using OpenHab 2.5.12.

mstormi · June 30, 2021, 11:47am

I noticed at times that my chatbot needs to reauthorize. Just enter any message in the chat with your OH.

L777 · June 23, 2022, 5:27am

Hello, I have the same issue with OH 3.2. Is there a bug fixing going on for this problem? In any case thank you for the work around.

Wolfgang_S · June 23, 2022, 6:24am

also after 15 - 30 minutes ?

In this post a user remarked that in his case it seems to be related to ISP disconnects.

L777 · June 28, 2022, 7:07am

In my case it seems more random, I need to do some other tests. For the makority of the time the message arrives to the item very quick, sometime it tooks 1 or 2 hours, sometime it never comes to the item. When it does not arrive at all, if I stop and start the thing everything start to work normally again.