Updating a device from multiple triggers doesn't work properly [Solved]

[Roeldebest]

Hi,

I'm facing an issue that I'm not sure how to explain properly, but I'll try to do my best.
We have a thermostat that allows us to get the current state via JSON. The current state of the thermostat is fetched every minute and updated in Domoticz. One example is that whenever the thermostat program changes on the thermostat itself, it will be reflected in a dummy device in Domoticz after a minute tops. This is all working fine.

Recently I have written a basic Telegram Bot that allows me to send messages to it, which will be handled by Domoticz. Domoticz makes the initial call to the Telegram API with long polling, limited to 50 seconds (which is the maximum value). Whenever a message is sent, the response will be received by Domoticz. Domoticz is then able to handle the message and starts a new request, so the process starts over again. This works with the domoticz.openURL feature, which triggers the script to run (again) when a response is received from the Telegram API, basically a never ending loop.

However, a strange thing is happening that I cannot figure out by debugging. Whenever the thermostat program state changes in real life, the change will be collected from the thermostat at the next every minute timer trigger. Right before I update the thermostat program dummy device, I write a log to confirm that the dummy device will be updated. I can see that the log is being written, but the device does not update to the new state. Now whenever the long polling request of the Telegram API reaches its timeout, the device is updated to the new state. This doesn't make any sense to me.

This behavior only shows up when I have my Telegram Bot script turned on. When I turn it off, fetching the current state from the thermostat and reflecting it in Domoticz is working perfect.

Is there anyone who is possible able to tell me why this is happening? The behavior I described above is currently leading to very unexpected results in Domoticz, with devices being in wrong states and not reflecting the real world.

[waaren]

Is there anyone who is possible able to tell me why this is happening?

Not based on your problem description but maybe if you share your code and tell us the device type / device types of the devices playing a part in this scenario.

[Roeldebest]

Thanks for your reply. I've tried keep the scripts at minimal as possible to show the crucial parts.
I have a dummy hardware device (Toon) and a virtual Light/Switch device (Temperatuurprogramma).

I have two scripts. This one is to fetch the information from the Toon thermostat and update the virtual Temperatuurprogramma switch:

Code: Select all

return {
	on = {
	    timer = {
	        'every minute'
        }
	},
	execute = function(domoticz)
	    local handle = assert(io.popen(string.format('curl http://%s/happ_thermstat?action=getThermostatInfo', "192.168.178.29")))
        local ThermostatInfo = handle:read('*all')
        handle:close()
        
        local json = assert(loadfile "/home/pi/domoticz/scripts/lua/JSON.lua")()  -- For Linux
        local jsonThermostatInfo = json:decode(ThermostatInfo)
        
        if jsonThermostatInfo == nil then
            return
        end
        
        local previousActiveState = domoticz.devices('Temperatuurprogramma').level
        local currentActiveState = tonumber(jsonThermostatInfo.activeState)
        
        local switchLevel = -1;
        
        if currentActiveState == -1 then
            switchLevel = 0 -- Off
        elseif currentActiveState == 0 then
            switchLevel = 10 -- Comfort
        elseif currentActiveState == 1 then
            switchLevel = 20 -- Thuis
        elseif currentActiveState == 2 then
            switchLevel = 30 -- Slapen
        elseif currentActiveState == 3 then
            switchLevel = 40 -- Weg
        end
        
        if switchLevel ~= previousActiveState then
            domoticz.log("Update active state to " .. switchLevel)
            if switchLevel == 0 then
                domoticz.devices('Temperatuurprogramma').switchOff().silent()
            else
                domoticz.devices('Temperatuurprogramma').switchSelector(switchLevel).silent()
            end
        end
	end
}

The following one is a bit more complicated, which runs the Telegram Bot:

Code: Select all

return {
	on = {
		httpResponses = {
			'telegramTrigger' -- must match with the callback passed to the openURL command
		},
	    timer = {
	        'every minute'
        }
	},
    data = {
        lastUpdateId = { initial = 0 },
        isLoading = { initial = false }
    },
	execute = function(domoticz, item)
		if (item.isTimer and domoticz.data.isLoading == false) then
		    domoticz.data.isLoading = true
		    
		    domoticz.log('Making initial call for Telegram Bot.')
		    
		    domoticz.log('Doing initial call for ' .. domoticz.data.lastUpdateId)
		    
		    -- 50 seconds is the max timeout
			domoticz.openURL({
				url = 'https://api.telegram.org/<removed>/getUpdates?timeout=50&offset=0',
				method = 'GET',
				callback = 'telegramTrigger',
			})
		end

		if (item.isHTTPResponse) then
		    domoticz.data.isLoading = false

			if (item.statusCode == 200) then
				if (item.isJSON) then
				    local data = domoticz.utils.fromJSON(item.data)
				    
				    local lastUpdateId = domoticz.data.lastUpdateId
				    local messages = 0
				    
				    for key, value in pairs(data.result) do
				        messages = messages + 1
				        domoticz.log('Checking message ' .. value.update_id)
				        
			            lastUpdateId = value.update_id + 1
			      
                        local message = 'Onbekend commando: ' .. value.message.text
                        
                        if string.sub(value.message.text, 1, 1) == '/' then
                            local command = string.sub(value.message.text, 2)
                            
                            domoticz.log('Handling command: ' .. command)
                            
                            if command == 'temperatuur' then
                                local temperature = domoticz.utils.round(tonumber(domoticz.devices('Temperatuur Binnen').temperature), 2)
                                message = 'Het is binnen ' .. temperature .. '° C.'
                            end
                        end
                        
                        domoticz.openURL({
                            url = 'https://api.telegram.org/<removed>/sendMessage?chat_id=' .. value.message.chat.id .. '&parse_mode=markdown&text=' .. domoticz.utils.urlEncode(message),
                            method = 'GET'
                        })
		            end
    			 
    			    --if messages == 0 then
    			    --    domoticz.log('There were no messages to be processed.')
			        --end
			        
			        local url = 'https://api.telegram.org/<removed>/getUpdates?timeout=50&offset=' .. lastUpdateId
			        --domoticz.log('Calling after response ' .. url)
				    
        			domoticz.openURL({
        				url = url,
        				method = 'GET',
        				callback = 'telegramTrigger',
        			})
        			
        			domoticz.data.lastUpdateId = lastUpdateId
		            domoticz.data.isLoading = true
				end
			else
				domoticz.log('There was a problem handling the request', domoticz.LOG_ERROR)
				domoticz.log(item, domoticz.LOG_ERROR)
			end

		end

	end
}

Alright, so the script runs every minute because of the timer trigger, which is neccesary for the initial call (I couldn't figure out another way to handle this), which then sets the isLoading script level persistent variable to true to prevent the timer trigger from making another request.
Then, the script waits for a response to come in. Whenever the response comes in (either because of the long polling timeout or because a message was sent), the script handles the messages and starts a new long polling request and waits for the next timeout or message.

Now when the Telegram Bot script is running (and therefor is in a long polling request), the Temperatuurprogramma device is not updated during the every minute refresh of the thermostat state. It seems like it is trying to update the device state, but the actual update of the device only happens after the long polling request of the Telegram Bot is finished.

[waaren]

I've tried keep the scripts at minimal as possible to show the crucial parts.
Now when the Telegram Bot script is running (and therefor is in a long polling request), the Temperatuurprogramma device is not updated during the every minute refresh of the thermostat state. It seems like it is trying to update the device state, but the actual update of the device only happens after the long polling request of the Telegram Bot is finished.

Without seeing loglines from these script it's a bit guesswork but what I see in in your Toon script is that it executes an OS curl command and waits until it is finished. So if for whatever reason the curl is blocked or Toon does not respond the complete Event system will be blocked (as it is single threaded.) If there is no specific reason to use the OS curl, I would change that to the async method openurl and add some loglines while doing that.
It then could look like below (untested)

Code: Select all

local scriptVar = 'toonResponse'

return 
{
    on = 
    {
        timer = 
        {
            'every minute',
        },

        httpResponses =
        {
            scriptVar,
        },
    },

    logging = 
    { 
        level = domoticz.LOG_DEBUG
    },

    execute = function(dz, item)
        _G.logMarker =  _G.moduleLabel

        local function getToon()
            local url = 'http://192.168.178.29/happ_thermstat?action=getThermostatInfo'
            dz.openURL(
            { 
                url = url,
                callback = scriptVar,
            })
        end

        if item.isTimer then getToon() 
        elseif item.ok then
            local jsonThermostatInfo

            if item.isJSON then 
                jsonThermostatInfo = item.json
            else 
                jsonThermostatInfo = dz.utils.fromJSON(item.data)
            end

            if jsonThermostatInfo == nil then
                return
            end

            local previousActiveState = dz.devices('Temperatuurprogramma').level
            local currentActiveState = tonumber(jsonThermostatInfo.activeState)

            local switchLevel

            if currentActiveState == -1 then
                switchLevel = 0 -- Off
            elseif currentActiveState == 0 then
                switchLevel = 10 -- Comfort
            elseif currentActiveState == 1 then
                switchLevel = 20 -- Thuis
            elseif currentActiveState == 2 then
                switchLevel = 30 -- Slapen
            elseif currentActiveState == 3 then
                switchLevel = 40 -- Weg
            else 
                dz.log("Funny currentActiveState: " .. tostring(currentActiveState),dz.LOG_DEBUG)
                switchLevel = -1
            end

            if switchLevel ~= previousActiveState then
                dz.log("Update active state to " .. switchLevel,dz.LOG_DEBUG)
                if switchLevel == 0 then
                    dz.devices('Temperatuurprogramma').switchOff().silent()
                else
                    dz.devices('Temperatuurprogramma').switchSelector(switchLevel).silent()
                end
            else 
                dz.log("State was already " .. switchLevel,dz.LOG_DEBUG)
            end        
        else
            dz.log("No good response from Toon ", dz.LOG_ERROR)
            dz.utils.dumpTable(item)
        end
    end
}

[Roeldebest]

Thanks. That specific script was based on a script I found a while ago on some website to fetch data from this specific device and was before I was aware of the domoticz.openURL method. I have rewritten it to use openURL, but unfortunately the two scripts together still cause the same issue.

I see some interesting things in the logs now. I have created a separate trigger to handle the JSON response on the thermostat update, called thermostatTrigger, which is called as a result of the every minute timer of the same script. In the logs I see this:

2019-12-22 17:35:00.545 Status: dzVents: Info: ------ Start internal script: Telegram Bot:, trigger: every minute
2019-12-22 17:35:00.547 Status: dzVents: Info: ------ Finished Telegram Bot
2019-12-22 17:35:00.547 Status: dzVents: Info: ------ Start internal script: Update from thermostat:, trigger: every minute
2019-12-22 17:35:00.547 Status: dzVents: Info: ------ Finished Update from thermostat
2019-12-22 17:35:22.829 Status: dzVents: Info: Handling httpResponse-events for: "telegramTrigger
2019-12-22 17:35:22.829 Status: dzVents: Info: ------ Start internal script: Telegram Bot: HTTPResponse: "telegramTrigger"
2019-12-22 17:35:22.836 Status: dzVents: Info: ------ Finished Telegram Bot
2019-12-22 17:36:00.400 Status: dzVents: Info: ------ Start internal script: Telegram Bot:, trigger: every minute
2019-12-22 17:36:00.401 Status: dzVents: Info: ------ Finished Telegram Bot
2019-12-22 17:36:00.401 Status: dzVents: Info: ------ Start internal script: Update from thermostat:, trigger: every minute
2019-12-22 17:36:00.401 Status: dzVents: Info: ------ Finished Update from thermostat
2019-12-22 17:36:16.515 Status: dzVents: Info: Handling httpResponse-events for: "telegramTrigger
2019-12-22 17:36:16.515 Status: dzVents: Info: ------ Start internal script: Telegram Bot: HTTPResponse: "telegramTrigger"
2019-12-22 17:36:16.521 Status: dzVents: Info: ------ Finished Telegram Bot
2019-12-22 17:36:16.608 Status: dzVents: Info: Handling httpResponse-events for: "thermostatTrigger
2019-12-22 17:36:16.609 Status: dzVents: Info: ------ Start internal script: Update from thermostat: HTTPResponse: "thermostatTrigger"
2019-12-22 17:36:16.640 Status: dzVents: Info: ------ Finished Update from thermostat

You can see the every minute trigger of the Telegram Bot runs (for the initial call) and you can also see the httpResponse trigger for the Telegram Bot. What I don't understand though is that the thermostat every minute also runs, but the httpResponse trigger for the thermostat update only runs whenever the Telegram Bot httpResponse is handled.

This issue seems to get weirder and weirder as I look at it, lol.

[waaren]

This issue seems to get weirder and weirder as I look at it, lol.

Maybe if you increase the loglevel in dzVents and domoticz you will see some extra information ?

[Roeldebest]

I've increased the logging level. I can see that the HTTP response is immediately handled for the thermostat update when the Telegram Bot script is disabled:

2019-12-23 21:05:00.337 Status: dzVents: Debug: Commands sent to Domoticz:
2019-12-23 21:05:00.337 Status: dzVents: Debug: - OpenURL = {["_trigger"]="thermostatTrigger", ["URL"]="http://192.168.178.29/happ_thermstat?ac ... mostatInfo", ["method"]="GET"}
2019-12-23 21:05:00.337 Status: dzVents: Debug: =====================================================
2019-12-23 21:05:00.553 Status: dzVents: Debug: Dumping domoticz data to /home/pi/domoticz/scripts/dzVents/domoticzData.lua
2019-12-23 21:05:00.567 Status: dzVents: Debug: dzVents version: 2.4.19
2019-12-23 21:05:00.567 Status: dzVents: Debug: Event triggers:
2019-12-23 21:05:00.567 Status: dzVents: Debug: - HTTPResponse: thermostatTrigger
2019-12-23 21:05:00.601 Status: dzVents: Info: Handling httpResponse-events for: "thermostatTrigger
2019-12-23 21:05:00.601 Status: dzVents: Info: ------ Start internal script: Update from thermostat: HTTPResponse: "thermostatTrigger"
2019-12-23 21:05:00.629 Status: dzVents: Debug: Processing device-adapter for Temperatuur Binnen: Temperature device adapter
2019-12-23 21:05:00.630 Status: dzVents: Debug: Processing device-adapter for Brander: Switch device adapter
2019-12-23 21:05:00.631 Status: dzVents: Debug: Processing device-adapter for Ingestelde temperatuur: Thermostat setpoint device adapter
2019-12-23 21:05:00.632 Status: dzVents: Debug: Processing device-adapter for Temperatuurprogramma: Switch device adapter
2019-12-23 21:05:00.632 Status: dzVents: Info: ------ Finished Update from thermostat

With the Telegram Bot enabled, the OpenURL command for the thermostat update is sent, together with the OpenURL command for the Telegram Bot, but the response is only received right after the timeout response for the Telegram Bot arrives.

2019-12-23 21:07:00.306 Status: dzVents: Debug: Dumping domoticz data to /home/pi/domoticz/scripts/dzVents/domoticzData.lua
2019-12-23 21:07:00.321 Status: dzVents: Debug: Event triggers:
2019-12-23 21:07:00.321 Status: dzVents: Debug: - Timer
2019-12-23 21:07:00.357 Status: dzVents: Info: ------ Start internal script: Telegram Bot:, trigger: every minute
2019-12-23 21:07:00.358 Status: dzVents: Info: Making initial call for Telegram Bot.
2019-12-23 21:07:00.358 Status: dzVents: Info: Doing initial call for 125734719
2019-12-23 21:07:00.358 Status: dzVents: Debug: OpenURL: url = https://api.telegram.org/<removed>>/get ... 0&offset=0
2019-12-23 21:07:00.358 Status: dzVents: Debug: OpenURL: method = GET
2019-12-23 21:07:00.358 Status: dzVents: Debug: OpenURL: post data = nil
2019-12-23 21:07:00.358 Status: dzVents: Debug: OpenURL: headers = nil
2019-12-23 21:07:00.359 Status: dzVents: Debug: OpenURL: callback = telegramTrigger
2019-12-23 21:07:00.360 Status: dzVents: Info: ------ Finished Telegram Bot
2019-12-23 21:07:00.360 Status: dzVents: Info: ------ Start internal script: Update from thermostat:, trigger: every minute
2019-12-23 21:07:00.360 Status: dzVents: Debug: OpenURL: url = http://192.168.178.29/happ_thermstat?ac ... mostatInfo
2019-12-23 21:07:00.360 Status: dzVents: Debug: OpenURL: method = GET
2019-12-23 21:07:00.360 Status: dzVents: Debug: OpenURL: post data = nil
2019-12-23 21:07:00.360 Status: dzVents: Debug: OpenURL: headers = nil
2019-12-23 21:07:00.360 Status: dzVents: Debug: OpenURL: callback = thermostatTrigger
2019-12-23 21:07:00.360 Status: dzVents: Info: ------ Finished Update from thermostat
2019-12-23 21:07:00.360 Status: dzVents: Debug: Commands sent to Domoticz:
2019-12-23 21:07:00.361 Status: dzVents: Debug: - OpenURL = {["URL"]="https://api.telegram.org/<removed>/getU ... 0&offset=0", ["_trigger"]="telegramTrigger", ["method"]="GET"}
2019-12-23 21:07:00.361 Status: dzVents: Debug: - OpenURL = {["URL"]="http://192.168.178.29/happ_thermstat?ac ... mostatInfo", ["_trigger"]="thermostatTrigger", ["method"]="GET"}
2019-12-23 21:07:00.361 Status: dzVents: Debug: =====================================================
2019-12-23 21:07:50.923 Status: dzVents: Debug: Event triggers:
2019-12-23 21:07:50.923 Status: dzVents: Debug: - HTTPResponse: telegramTrigger
2019-12-23 21:07:50.959 Status: dzVents: Info: Handling httpResponse-events for: "telegramTrigger
2019-12-23 21:07:50.959 Status: dzVents: Info: ------ Start internal script: Telegram Bot: HTTPResponse: "telegramTrigger"
2019-12-23 21:07:50.964 Status: dzVents: Debug: OpenURL: url = https://api.telegram.org/<removed>/getU ... =125734719
2019-12-23 21:07:50.964 Status: dzVents: Debug: OpenURL: method = GET
2019-12-23 21:07:50.964 Status: dzVents: Debug: OpenURL: post data = nil
2019-12-23 21:07:50.964 Status: dzVents: Debug: OpenURL: headers = nil
2019-12-23 21:07:50.965 Status: dzVents: Debug: OpenURL: callback = telegramTrigger
2019-12-23 21:07:50.965 Status: dzVents: Info: ------ Finished Telegram Bot
2019-12-23 21:07:50.966 Status: dzVents: Debug: Commands sent to Domoticz:
2019-12-23 21:07:50.966 Status: dzVents: Debug: - OpenURL = {["method"]="GET", ["URL"]="https://api.telegram.org/<removed>/getU ... =125734719", ["_trigger"]="telegramTrigger"}
2019-12-23 21:07:50.966 Status: dzVents: Debug: =====================================================
2019-12-23 21:07:51.014 Status: dzVents: Debug: Dumping domoticz data to /home/pi/domoticz/scripts/dzVents/domoticzData.lua
2019-12-23 21:07:51.029 Status: dzVents: Debug: dzVents version: 2.4.19
2019-12-23 21:07:51.029 Status: dzVents: Debug: Event triggers:
2019-12-23 21:07:51.029 Status: dzVents: Debug: - HTTPResponse: thermostatTrigger
2019-12-23 21:07:51.068 Status: dzVents: Info: Handling httpResponse-events for: "thermostatTrigger
2019-12-23 21:07:51.068 Status: dzVents: Info: ------ Start internal script: Update from thermostat: HTTPResponse: "thermostatTrigger"
2019-12-23 21:07:51.106 Status: dzVents: Debug: Processing device-adapter for Temperatuur Binnen: Temperature device adapter
2019-12-23 21:07:51.108 Status: dzVents: Debug: Processing device-adapter for Brander: Switch device adapter
2019-12-23 21:07:51.109 Status: dzVents: Debug: Processing device-adapter for Ingestelde temperatuur: Thermostat setpoint device adapter
2019-12-23 21:07:51.110 Status: dzVents: Debug: Processing device-adapter for Temperatuurprogramma: Switch device adapter
2019-12-23 21:07:51.110 Status: dzVents: Info: ------ Finished Update from thermostat
2019-12-23 21:08:00.337 Status: dzVents: Debug: Event triggers:
2019-12-23 21:08:00.337 Status: dzVents: Debug: - Timer
2019-12-23 21:08:00.375 Status: dzVents: Info: ------ Start internal script: Telegram Bot:, trigger: every minute
2019-12-23 21:08:00.376 Status: dzVents: Info: ------ Finished Telegram Bot
2019-12-23 21:08:00.377 Status: dzVents: Info: ------ Start internal script: Update from thermostat:, trigger: every minute
2019-12-23 21:08:00.377 Status: dzVents: Debug: OpenURL: url = http://192.168.178.29/happ_thermstat?ac ... mostatInfo
2019-12-23 21:08:00.377 Status: dzVents: Debug: OpenURL: method = GET
2019-12-23 21:08:00.377 Status: dzVents: Debug: OpenURL: post data = nil
2019-12-23 21:08:00.378 Status: dzVents: Debug: OpenURL: headers = nil
2019-12-23 21:08:00.378 Status: dzVents: Debug: OpenURL: callback = thermostatTrigger
2019-12-23 21:08:00.378 Status: dzVents: Info: ------ Finished Update from thermostat
2019-12-23 21:08:00.378 Status: dzVents: Debug: Commands sent to Domoticz:
2019-12-23 21:08:00.379 Status: dzVents: Debug: - OpenURL = {["URL"]="http://192.168.178.29/happ_thermstat?ac ... mostatInfo", ["_trigger"]="thermostatTrigger", ["method"]="GET"}

I'm tempted to think this is a bug in Domoticz. Am I missing something here or is something configured wrongly?

[waaren]

I've increased the logging level. I can see that the HTTP response is immediately handled for the thermostat update when the Telegram Bot script is disabled:
I'm tempted to think this is a bug in Domoticz. Am I missing something here or is something configured wrongly?

Could be. I never came across it yet but have not used a timeout in a url either.
Can you please explain in laymens terms what the purpose of this timeout is and if it should be interpreted by domoticz of by telegram ?

[Roeldebest]

So basically long polling (the timeout parameter) is a feature of the Telegram API. If you set if for instance to 50, the API will keep the request open for 50 seconds. In this case two things can happen:

• A message was sent to the Telegram Bot. The request will be handled and the API will return a response immediately
• No message is sent within 50 seconds. In this case the request will timeout. The API will return an empty response

Long polling basically exists to prevent users from starting a new request quicker, for example every second. Instead, you only have to make a request every 50 seconds.

It seems like Domoticz is having issues doing multiple calls with openURL, where the long request is blocking the other ones from being handled as soon as they receive their response.

I wanted to experiment with the behavior of Domoticz with multiple scripts, where one script calls an API endpoint that returns a response immediately and one when the response takes a while (50 seconds in this case) to respond, but I don't have the proper equipment available right now.

Edit: so eventually I was able to setup what I explained above with two Python webservers (one with a 5 second sleep on a request and the other one which replies immediately) and a Domoticz Docker container. It works as expected, so the scripts are not clashing. It was on a previous version of Domoticz though, but I don’t expect this difference in behavior to be introduced in a minor version upgrade. I’ll do more investigation to see if I can find the issue and possibly fix it.

[waaren]

It seems like Domoticz is having issues doing multiple calls with openURL, where the long request is blocking the other ones from being handled as soon as they receive their response.

Thx for the explanation. Could be that domoticz is single threaded in this area, just as it is in the event system.