Scene too fast for gateway?
-
Perhaps you could do some research buffering the outgoing messages.
I think they all requires ack back from nodes today so this new feature could also try to resend non-acked messages after some timeout.
@hek
Nothing seems to work.
I will upgrade the capacitor for the radio but I don't have many expectations.As for the plugin, I would need to know more about how vera works.
Is there a main function in the plugin?
Also, how do you debug the code in vera? -
The closest to "main" is this:
https://github.com/mysensors/Vera/blob/master/L_Arduino.lua#L543Debugging isn't easy. I usually ssh:ed into the box and tailed the logfile. Was also able to mount the NAS from Vera so I didn't have to scp/file upload changes.
-
The closest to "main" is this:
https://github.com/mysensors/Vera/blob/master/L_Arduino.lua#L543Debugging isn't easy. I usually ssh:ed into the box and tailed the logfile. Was also able to mount the NAS from Vera so I didn't have to scp/file upload changes.
-
Might be a cifs problem when linking.
http://ubuntuforums.org/showthread.php?t=1600541
Maybe I did it the other way around. Can't recall now.
-
The closest to "main" is this:
https://github.com/mysensors/Vera/blob/master/L_Arduino.lua#L543Debugging isn't easy. I usually ssh:ed into the box and tailed the logfile. Was also able to mount the NAS from Vera so I didn't have to scp/file upload changes.
@hek
Here's a basic implementation of the sending queue I came up with.First I modified this functions:
function sendCommandWithMessageType(altid, messageType, ack, variableId, value) local cmd = altid..";".. msgType[messageType] .. ";" .. ack .. ";" .. variableId .. ";" .. value -- only add to list if of SET type if (messageType =="SET") then addToMyQueue(cmd) end if (luup.io.write(cmd) == false) then task("Cannot send command - communications error", TASK_ERROR) luup.set_failure(true) return false end return true endfunction processIncoming(s) local incomingData = s:split(";") if (#incomingData >=4) then -- check if msg is in the list to remove it checkMyQueue(s); local nodeId = incomingData[1] ... endAnd added this other functions:
-- adds cmd msg to the list before sending function addToMyQueue(myCmd) local isFound = inTable(MyMsgs, myCmd); -- if not already in the list, add it if (isFound == false) then table.insert( MyMsgs, myCmd ) end end -- check if msg is in the list to remove it function checkMyQueue(msg) log(MyPrefix .. ">T> queue : " .. printTable(MyMsgs) ) local isFound = inTable(MyMsgs, msg); -- if msg found, remove it because has been executed if (isFound ~= false) then log("msg found in pos: "..isFound..". Removing from list...") table.remove (MyMsgs , isFound) else log("msg not found in list") end log(MyPrefix .. ">T> queue updated: " .. printTable(MyMsgs) ) end function inTable(tbl, item) for key, value in pairs(tbl) do if value == item then return key end end return false endIt basically works but the problem with this is that processIncoming() is only processed when a new message arrives, so there is no way we could re-send lost messages when iddle.
We need a function that could be executed at regular intervals to check if there are any messages left in the queue to be re-send.
-
@hek
Here's a basic implementation of the sending queue I came up with.First I modified this functions:
function sendCommandWithMessageType(altid, messageType, ack, variableId, value) local cmd = altid..";".. msgType[messageType] .. ";" .. ack .. ";" .. variableId .. ";" .. value -- only add to list if of SET type if (messageType =="SET") then addToMyQueue(cmd) end if (luup.io.write(cmd) == false) then task("Cannot send command - communications error", TASK_ERROR) luup.set_failure(true) return false end return true endfunction processIncoming(s) local incomingData = s:split(";") if (#incomingData >=4) then -- check if msg is in the list to remove it checkMyQueue(s); local nodeId = incomingData[1] ... endAnd added this other functions:
-- adds cmd msg to the list before sending function addToMyQueue(myCmd) local isFound = inTable(MyMsgs, myCmd); -- if not already in the list, add it if (isFound == false) then table.insert( MyMsgs, myCmd ) end end -- check if msg is in the list to remove it function checkMyQueue(msg) log(MyPrefix .. ">T> queue : " .. printTable(MyMsgs) ) local isFound = inTable(MyMsgs, msg); -- if msg found, remove it because has been executed if (isFound ~= false) then log("msg found in pos: "..isFound..". Removing from list...") table.remove (MyMsgs , isFound) else log("msg not found in list") end log(MyPrefix .. ">T> queue updated: " .. printTable(MyMsgs) ) end function inTable(tbl, item) for key, value in pairs(tbl) do if value == item then return key end end return false endIt basically works but the problem with this is that processIncoming() is only processed when a new message arrives, so there is no way we could re-send lost messages when iddle.
We need a function that could be executed at regular intervals to check if there are any messages left in the queue to be re-send.
-
@ferpando said:
We need a function that could be executed at regular intervals to check if there are any messages left in the queue to be re-send.
http://wiki.micasaverde.com/index.php/Luup_Lua_extensions#function:_call_timer
@hek
I almost got it but for some reason the call_timer is not being excuted. Not even the first time.Looking at the logs, i can see that the 6 commands are sent really quickly within milliseconds, and as you can see at the end, only 3 of the messages get through, leaving 3 lost
08 03/20/15 14:26:46.549 Scene::RunScene running 81 test6on <0x2f250680> 08 03/20/15 14:26:46.550 JobHandler_LuaUPnP::HandleActionRequest device: 219 service: urn:upnp-org:serviceId:SwitchPower1 action: SetTarget <0x2f250680> 08 03/20/15 14:26:46.550 JobHandler_LuaUPnP::HandleActionRequest argument newTargetValue=1 <0x2f250680> 50 03/20/15 14:26:46.553 luup_log:130: ****<-*->**** Arduino: ****<-*->**** >F> switchPower <0x2b2c1000> 50 03/20/15 14:26:46.554 luup_log:130: ****<-*->**** Arduino: ****<-*->**** >F> sendCommand <0x2b2c1000> 50 03/20/15 14:26:46.554 luup_log:130: ****<-*->**** Arduino: *** **** **** **** *** *** Sending: 6;0;1;1;2;1 <0x2b2c1000> 04 03/20/15 14:26:46.556 <Job ID="42" Name="" Device="219" Created="2015-03-20 14:26:46" Started="2015-03-20 14:26:46" Completed="2015-03-20 14:26:46" Duration="0.4574000" Runtime="0.2382000" Status="Successful" LastNote=""/> <0x2b2c1000> 08 03/20/15 14:26:46.562 JobHandler_LuaUPnP::HandleActionRequest device: 221 service: urn:upnp-org:serviceId:SwitchPower1 action: SetTarget <0x2f250680> 08 03/20/15 14:26:46.562 JobHandler_LuaUPnP::HandleActionRequest argument newTargetValue=1 <0x2f250680> 08 03/20/15 14:26:46.595 JobHandler_LuaUPnP::HandleActionRequest device: 216 service: urn:upnp-org:serviceId:SwitchPower1 action: SetTarget <0x2f250680> 08 03/20/15 14:26:46.596 JobHandler_LuaUPnP::HandleActionRequest argument newTargetValue=1 <0x2f250680> 08 03/20/15 14:26:46.597 JobHandler_LuaUPnP::HandleActionRequest device: 215 service: urn:upnp-org:serviceId:SwitchPower1 action: SetTarget <0x2f250680> 08 03/20/15 14:26:46.598 JobHandler_LuaUPnP::HandleActionRequest argument newTargetValue=1 <0x2f250680> 08 03/20/15 14:26:46.599 JobHandler_LuaUPnP::HandleActionRequest device: 218 service: urn:upnp-org:serviceId:SwitchPower1 action: SetTarget <0x2f250680> 08 03/20/15 14:26:46.600 JobHandler_LuaUPnP::HandleActionRequest argument newTargetValue=1 <0x2f250680> 50 03/20/15 14:26:46.601 luup_log:130: ****<-*->**** Arduino: ****<-*->**** >F> switchPower <0x2b2c1000> 50 03/20/15 14:26:46.602 luup_log:130: ****<-*->**** Arduino: ****<-*->**** >F> sendCommand <0x2b2c1000> 50 03/20/15 14:26:46.602 luup_log:130: ****<-*->**** Arduino: *** **** **** **** *** *** Sending: 6;1;1;1;2;1 <0x2b2c1000> 04 03/20/15 14:26:46.604 <Job ID="43" Name="" Device="221" Created="2015-03-20 14:26:46" Started="2015-03-20 14:26:46" Completed="2015-03-20 14:26:46" Duration="0.40816000" Runtime="0.2283000" Status="Successful" LastNote=""/> <0x2b2c1000> 50 03/20/15 14:26:46.605 luup_log:130: ****<-*->**** Arduino: ****<-*->**** >F> switchPower <0x2b2c1000> 50 03/20/15 14:26:46.606 luup_log:130: ****<-*->**** Arduino: ****<-*->**** >F> sendCommand <0x2b2c1000> 50 03/20/15 14:26:46.606 luup_log:130: ****<-*->**** Arduino: *** **** **** **** *** *** Sending: 6;2;1;1;2;1 <0x2b2c1000> 04 03/20/15 14:26:46.608 <Job ID="44" Name="" Device="216" Created="2015-03-20 14:26:46" Started="2015-03-20 14:26:46" Completed="2015-03-20 14:26:46" Duration="0.11100000" Runtime="0.2205000" Status="Successful" LastNote=""/> <0x2b2c1000> 50 03/20/15 14:26:46.610 luup_log:130: ****<-*->**** Arduino: ****<-*->**** >F> switchPower <0x2b2c1000> 50 03/20/15 14:26:46.610 luup_log:130: ****<-*->**** Arduino: ****<-*->**** >F> sendCommand <0x2b2c1000> 50 03/20/15 14:26:46.610 luup_log:130: ****<-*->**** Arduino: *** **** **** **** *** *** Sending: 6;3;1;1;2;1 <0x2b2c1000> 08 03/20/15 14:26:46.614 JobHandler_LuaUPnP::HandleActionRequest device: 220 service: urn:upnp-org:serviceId:SwitchPower1 action: SetTarget <0x2f250680> 08 03/20/15 14:26:46.614 JobHandler_LuaUPnP::HandleActionRequest argument newTargetValue=1 <0x2f250680> 04 03/20/15 14:26:46.620 <Job ID="45" Name="" Device="215" Created="2015-03-20 14:26:46" Started="2015-03-20 14:26:46" Completed="2015-03-20 14:26:46" Duration="0.20340000" Runtime="0.9573000" Status="Successful" LastNote=""/> <0x2b2c1000> 50 03/20/15 14:26:46.624 luup_log:130: ****<-*->**** Arduino: ****<-*->**** >F> switchPower <0x2b2c1000> 50 03/20/15 14:26:46.624 luup_log:130: ****<-*->**** Arduino: ****<-*->**** >F> sendCommand <0x2b2c1000> 50 03/20/15 14:26:46.625 luup_log:130: ****<-*->**** Arduino: *** **** **** **** *** *** Sending: 6;4;1;1;2;1 <0x2b2c1000> 04 03/20/15 14:26:46.627 <Job ID="46" Name="" Device="218" Created="2015-03-20 14:26:46" Started="2015-03-20 14:26:46" Completed="2015-03-20 14:26:46" Duration="0.25886000" Runtime="0.5533000" Status="Successful" LastNote=""/> <0x2b2c1000> 50 03/20/15 14:26:46.628 luup_log:130: ****<-*->**** Arduino: ****<-*->**** >F> switchPower <0x2b2c1000> 50 03/20/15 14:26:46.629 luup_log:130: ****<-*->**** Arduino: ****<-*->**** >F> sendCommand <0x2b2c1000> 50 03/20/15 14:26:46.629 luup_log:130: ****<-*->**** Arduino: *** **** **** **** *** *** Sending: 6;5;1;1;2;1 <0x2b2c1000> 04 03/20/15 14:26:46.631 <Job ID="47" Name="" Device="220" Created="2015-03-20 14:26:46" Started="2015-03-20 14:26:46" Completed="2015-03-20 14:26:46" Duration="0.15803000" Runtime="0.2479000" Status="Successful" LastNote=""/> <0x2b2c1000> 50 03/20/15 14:26:46.672 luup_log:130: ****<-*->**** Arduino: ****<-*->**** >F> processIncoming msg: 6;0;1;1;2;1 <0x2e850680> 50 03/20/15 14:26:46.673 luup_log:130: ****<-*->**** Arduino: ****<-*->**** >T> queue : {6;0;1;1;2;1, 6;1;1;1;2;1, 6;2;1;1;2;1, 6;3;1;1;2;1, 6;4;1;1;2;1, 6;5;1;1;2;1, } <0x2e850680> 50 03/20/15 14:26:46.674 luup_log:130: ****<-*->**** Arduino: ****<-*->**** >T> queue retrais: {0, 0, 0, 0, 0, 0, } <0x2e850680> 50 03/20/15 14:26:46.674 luup_log:130: ****<-*->**** Arduino: msg found in pos: 1. Removing from list... <0x2e850680> 50 03/20/15 14:26:46.677 luup_log:130: ****<-*->**** Arduino: ****<-*->**** >T> queue updated: {6;1;1;1;2;1, 6;2;1;1;2;1, 6;3;1;1;2;1, 6;4;1;1;2;1, 6;5;1;1;2;1, } <0x2e850680> 50 03/20/15 14:26:46.677 luup_log:130: ****<-*->**** Arduino: ****<-*->**** >T> queue retrais: {0, 0, 0, 0, 0, } <0x2e850680> 50 03/20/15 14:26:46.678 luup_log:130: ****<-*->**** Arduino: ****<-->**** Set variable: 6;0;1;1;2;1 <0x2e850680> 50 03/20/15 14:26:46.678 luup_log:130: ****<-*->**** Arduino: ****<-*->**** >F> setVariable <0x2e850680> 50 03/20/15 14:26:46.679 luup_log:130: ****<-*->**** Arduino: Setting variable 'Status' to value '1' <0x2e850680> 50 03/20/15 14:26:46.679 luup_log:130: ****<-*->**** Arduino: ****<-*->**** >F> setVariableIfChanged <0x2e850680> 50 03/20/15 14:26:46.679 luup_log:130: ****<-*->**** Arduino: ****<-*->**** urn:upnp-org:serviceId:SwitchPower1,Status, 1, 219 <0x2e850680> 06 03/20/15 14:26:46.680 Device_Variable::m_szValue_set device: 219 service: urn:upnp-org:serviceId:SwitchPower1 variable: Status was: 0 now: 1 #hooks: 4 upnp: 0 v:0x9b41e8/NONE duplicate:0 <0x2e850680> 50 03/20/15 14:26:46.680 luup_log:130: ****<-*->**** Arduino: ****<-*->**** >F> setVariableIfChanged <0x2e850680> 50 03/20/15 14:26:46.684 luup_log:130: ****<-*->**** Arduino: ****<-*->**** urn:micasaverde-com:serviceId:HaDevice1,LastUpdate, 1426858006, 219 <0x2e850680> 06 03/20/15 14:26:46.685 Device_Variable::m_szValue_set device: 219 service: urn:micasaverde-com:serviceId:HaDevice1 variable: LastUpdate was: 1426688846 now: 1426858006 #hooks: 0 upnp: 0 v:(nil)/NONE duplicate:0 <0x2e850680> 50 03/20/15 14:26:46.685 luup_log:130: ****<-*->**** Arduino: ****<-*->**** >F> setVariableIfChanged <0x2e850680> 50 03/20/15 14:26:46.686 luup_log:130: ****<-*->**** Arduino: ****<-*->**** urn:micasaverde-com:serviceId:HaDevice1,LastUpdate, 1426858006, 217 <0x2e850680> 06 03/20/15 14:26:46.686 Device_Variable::m_szValue_set device: 217 service: urn:micasaverde-com:serviceId:HaDevice1 variable: LastUpdate was: 1426857982 now: 1426858006 #hooks: 0 upnp: 0 v:(nil)/NONE duplicate:0 <0x2e850680> 50 03/20/15 14:26:46.687 luup_log:130: ****<-*->**** Arduino: ****<-*->**** >F> setVariableIfChanged <0x2e850680> 50 03/20/15 14:26:46.688 luup_log:130: ****<-*->**** Arduino: ****<-*->**** urn:micasaverde-com:serviceId:HaDevice1,LastUpdateHR, 14:26, 217 <0x2e850680> 50 03/20/15 14:26:46.752 luup_log:130: ****<-*->**** Arduino: ****<-*->**** >F> processIncoming msg: 6;1;1;1;2;1 <0x2e850680> 50 03/20/15 14:26:46.753 luup_log:130: ****<-*->**** Arduino: ****<-*->**** >T> queue : {6;1;1;1;2;1, 6;2;1;1;2;1, 6;3;1;1;2;1, 6;4;1;1;2;1, 6;5;1;1;2;1, } <0x2e850680> 50 03/20/15 14:26:46.753 luup_log:130: ****<-*->**** Arduino: ****<-*->**** >T> queue retrais: {0, 0, 0, 0, 0, } <0x2e850680> 50 03/20/15 14:26:46.754 luup_log:130: ****<-*->**** Arduino: msg found in pos: 1. Removing from list... <0x2e850680> 50 03/20/15 14:26:46.754 luup_log:130: ****<-*->**** Arduino: ****<-*->**** >T> queue updated: {6;2;1;1;2;1, 6;3;1;1;2;1, 6;4;1;1;2;1, 6;5;1;1;2;1, } <0x2e850680> 50 03/20/15 14:26:46.755 luup_log:130: ****<-*->**** Arduino: ****<-*->**** >T> queue retrais: {0, 0, 0, 0, } <0x2e850680> 50 03/20/15 14:26:46.755 luup_log:130: ****<-*->**** Arduino: ****<-->**** Set variable: 6;1;1;1;2;1 <0x2e850680> 50 03/20/15 14:26:46.756 luup_log:130: ****<-*->**** Arduino: ****<-*->**** >F> setVariable <0x2e850680> 50 03/20/15 14:26:46.756 luup_log:130: ****<-*->**** Arduino: Setting variable 'Status' to value '1' <0x2e850680> 50 03/20/15 14:26:46.756 luup_log:130: ****<-*->**** Arduino: ****<-*->**** >F> setVariableIfChanged <0x2e850680> 50 03/20/15 14:26:46.757 luup_log:130: ****<-*->**** Arduino: ****<-*->**** urn:upnp-org:serviceId:SwitchPower1,Status, 1, 221 <0x2e850680> 06 03/20/15 14:26:46.757 Device_Variable::m_szValue_set device: 221 service: urn:upnp-org:serviceId:SwitchPower1 variable: Status was: 0 now: 1 #hooks: 4 upnp: 0 v:0x9b41e8/NONE duplicate:0 <0x2e850680> 50 03/20/15 14:26:46.759 luup_log:130: ****<-*->**** Arduino: ****<-*->**** >F> setVariableIfChanged <0x2e850680> 50 03/20/15 14:26:46.759 luup_log:130: ****<-*->**** Arduino: ****<-*->**** urn:micasaverde-com:serviceId:HaDevice1,LastUpdate, 1426858006, 221 <0x2e850680> 06 03/20/15 14:26:46.760 Device_Variable::m_szValue_set device: 221 service: urn:micasaverde-com:serviceId:HaDevice1 variable: LastUpdate was: 1426688847 now: 1426858006 #hooks: 0 upnp: 0 v:(nil)/NONE duplicate:0 <0x2e850680> 50 03/20/15 14:26:46.760 luup_log:130: ****<-*->**** Arduino: ****<-*->**** >F> setVariableIfChanged <0x2e850680> 50 03/20/15 14:26:46.761 luup_log:130: ****<-*->**** Arduino: ****<-*->**** urn:micasaverde-com:serviceId:HaDevice1,LastUpdate, 1426858006, 217 <0x2e850680> 06 03/20/15 14:26:46.761 Device_Variable::m_szValue_set device: 217 service: urn:micasaverde-com:serviceId:HaDevice1 variable: LastUpdate was: 1426858006 now: 1426858006 #hooks: 0 upnp: 0 v:(nil)/NONE duplicate:1 <0x2e850680> 50 03/20/15 14:26:46.762 luup_log:130: ****<-*->**** Arduino: ****<-*->**** >F> setVariableIfChanged <0x2e850680> 50 03/20/15 14:26:46.762 luup_log:130: ****<-*->**** Arduino: ****<-*->**** urn:micasaverde-com:serviceId:HaDevice1,LastUpdateHR, 14:26, 217 <0x2e850680> 50 03/20/15 14:26:46.862 luup_log:130: ****<-*->**** Arduino: ****<-*->**** >F> processIncoming msg: 6;2;1;1;2;1 <0x2e850680> 50 03/20/15 14:26:46.863 luup_log:130: ****<-*->**** Arduino: ****<-*->**** >T> queue : {6;2;1;1;2;1, 6;3;1;1;2;1, 6;4;1;1;2;1, 6;5;1;1;2;1, } <0x2e850680> 50 03/20/15 14:26:46.863 luup_log:130: ****<-*->**** Arduino: ****<-*->**** >T> queue retrais: {0, 0, 0, 0, } <0x2e850680> 50 03/20/15 14:26:46.864 luup_log:130: ****<-*->**** Arduino: msg found in pos: 1. Removing from list... <0x2e850680> 50 03/20/15 14:26:46.864 luup_log:130: ****<-*->**** Arduino: ****<-*->**** >T> queue updated: {6;3;1;1;2;1, 6;4;1;1;2;1, 6;5;1;1;2;1, } <0x2e850680> -
@hek
I almost got it but for some reason the call_timer is not being excuted. Not even the first time.Looking at the logs, i can see that the 6 commands are sent really quickly within milliseconds, and as you can see at the end, only 3 of the messages get through, leaving 3 lost
08 03/20/15 14:26:46.549 Scene::RunScene running 81 test6on <0x2f250680> 08 03/20/15 14:26:46.550 JobHandler_LuaUPnP::HandleActionRequest device: 219 service: urn:upnp-org:serviceId:SwitchPower1 action: SetTarget <0x2f250680> 08 03/20/15 14:26:46.550 JobHandler_LuaUPnP::HandleActionRequest argument newTargetValue=1 <0x2f250680> 50 03/20/15 14:26:46.553 luup_log:130: ****<-*->**** Arduino: ****<-*->**** >F> switchPower <0x2b2c1000> 50 03/20/15 14:26:46.554 luup_log:130: ****<-*->**** Arduino: ****<-*->**** >F> sendCommand <0x2b2c1000> 50 03/20/15 14:26:46.554 luup_log:130: ****<-*->**** Arduino: *** **** **** **** *** *** Sending: 6;0;1;1;2;1 <0x2b2c1000> 04 03/20/15 14:26:46.556 <Job ID="42" Name="" Device="219" Created="2015-03-20 14:26:46" Started="2015-03-20 14:26:46" Completed="2015-03-20 14:26:46" Duration="0.4574000" Runtime="0.2382000" Status="Successful" LastNote=""/> <0x2b2c1000> 08 03/20/15 14:26:46.562 JobHandler_LuaUPnP::HandleActionRequest device: 221 service: urn:upnp-org:serviceId:SwitchPower1 action: SetTarget <0x2f250680> 08 03/20/15 14:26:46.562 JobHandler_LuaUPnP::HandleActionRequest argument newTargetValue=1 <0x2f250680> 08 03/20/15 14:26:46.595 JobHandler_LuaUPnP::HandleActionRequest device: 216 service: urn:upnp-org:serviceId:SwitchPower1 action: SetTarget <0x2f250680> 08 03/20/15 14:26:46.596 JobHandler_LuaUPnP::HandleActionRequest argument newTargetValue=1 <0x2f250680> 08 03/20/15 14:26:46.597 JobHandler_LuaUPnP::HandleActionRequest device: 215 service: urn:upnp-org:serviceId:SwitchPower1 action: SetTarget <0x2f250680> 08 03/20/15 14:26:46.598 JobHandler_LuaUPnP::HandleActionRequest argument newTargetValue=1 <0x2f250680> 08 03/20/15 14:26:46.599 JobHandler_LuaUPnP::HandleActionRequest device: 218 service: urn:upnp-org:serviceId:SwitchPower1 action: SetTarget <0x2f250680> 08 03/20/15 14:26:46.600 JobHandler_LuaUPnP::HandleActionRequest argument newTargetValue=1 <0x2f250680> 50 03/20/15 14:26:46.601 luup_log:130: ****<-*->**** Arduino: ****<-*->**** >F> switchPower <0x2b2c1000> 50 03/20/15 14:26:46.602 luup_log:130: ****<-*->**** Arduino: ****<-*->**** >F> sendCommand <0x2b2c1000> 50 03/20/15 14:26:46.602 luup_log:130: ****<-*->**** Arduino: *** **** **** **** *** *** Sending: 6;1;1;1;2;1 <0x2b2c1000> 04 03/20/15 14:26:46.604 <Job ID="43" Name="" Device="221" Created="2015-03-20 14:26:46" Started="2015-03-20 14:26:46" Completed="2015-03-20 14:26:46" Duration="0.40816000" Runtime="0.2283000" Status="Successful" LastNote=""/> <0x2b2c1000> 50 03/20/15 14:26:46.605 luup_log:130: ****<-*->**** Arduino: ****<-*->**** >F> switchPower <0x2b2c1000> 50 03/20/15 14:26:46.606 luup_log:130: ****<-*->**** Arduino: ****<-*->**** >F> sendCommand <0x2b2c1000> 50 03/20/15 14:26:46.606 luup_log:130: ****<-*->**** Arduino: *** **** **** **** *** *** Sending: 6;2;1;1;2;1 <0x2b2c1000> 04 03/20/15 14:26:46.608 <Job ID="44" Name="" Device="216" Created="2015-03-20 14:26:46" Started="2015-03-20 14:26:46" Completed="2015-03-20 14:26:46" Duration="0.11100000" Runtime="0.2205000" Status="Successful" LastNote=""/> <0x2b2c1000> 50 03/20/15 14:26:46.610 luup_log:130: ****<-*->**** Arduino: ****<-*->**** >F> switchPower <0x2b2c1000> 50 03/20/15 14:26:46.610 luup_log:130: ****<-*->**** Arduino: ****<-*->**** >F> sendCommand <0x2b2c1000> 50 03/20/15 14:26:46.610 luup_log:130: ****<-*->**** Arduino: *** **** **** **** *** *** Sending: 6;3;1;1;2;1 <0x2b2c1000> 08 03/20/15 14:26:46.614 JobHandler_LuaUPnP::HandleActionRequest device: 220 service: urn:upnp-org:serviceId:SwitchPower1 action: SetTarget <0x2f250680> 08 03/20/15 14:26:46.614 JobHandler_LuaUPnP::HandleActionRequest argument newTargetValue=1 <0x2f250680> 04 03/20/15 14:26:46.620 <Job ID="45" Name="" Device="215" Created="2015-03-20 14:26:46" Started="2015-03-20 14:26:46" Completed="2015-03-20 14:26:46" Duration="0.20340000" Runtime="0.9573000" Status="Successful" LastNote=""/> <0x2b2c1000> 50 03/20/15 14:26:46.624 luup_log:130: ****<-*->**** Arduino: ****<-*->**** >F> switchPower <0x2b2c1000> 50 03/20/15 14:26:46.624 luup_log:130: ****<-*->**** Arduino: ****<-*->**** >F> sendCommand <0x2b2c1000> 50 03/20/15 14:26:46.625 luup_log:130: ****<-*->**** Arduino: *** **** **** **** *** *** Sending: 6;4;1;1;2;1 <0x2b2c1000> 04 03/20/15 14:26:46.627 <Job ID="46" Name="" Device="218" Created="2015-03-20 14:26:46" Started="2015-03-20 14:26:46" Completed="2015-03-20 14:26:46" Duration="0.25886000" Runtime="0.5533000" Status="Successful" LastNote=""/> <0x2b2c1000> 50 03/20/15 14:26:46.628 luup_log:130: ****<-*->**** Arduino: ****<-*->**** >F> switchPower <0x2b2c1000> 50 03/20/15 14:26:46.629 luup_log:130: ****<-*->**** Arduino: ****<-*->**** >F> sendCommand <0x2b2c1000> 50 03/20/15 14:26:46.629 luup_log:130: ****<-*->**** Arduino: *** **** **** **** *** *** Sending: 6;5;1;1;2;1 <0x2b2c1000> 04 03/20/15 14:26:46.631 <Job ID="47" Name="" Device="220" Created="2015-03-20 14:26:46" Started="2015-03-20 14:26:46" Completed="2015-03-20 14:26:46" Duration="0.15803000" Runtime="0.2479000" Status="Successful" LastNote=""/> <0x2b2c1000> 50 03/20/15 14:26:46.672 luup_log:130: ****<-*->**** Arduino: ****<-*->**** >F> processIncoming msg: 6;0;1;1;2;1 <0x2e850680> 50 03/20/15 14:26:46.673 luup_log:130: ****<-*->**** Arduino: ****<-*->**** >T> queue : {6;0;1;1;2;1, 6;1;1;1;2;1, 6;2;1;1;2;1, 6;3;1;1;2;1, 6;4;1;1;2;1, 6;5;1;1;2;1, } <0x2e850680> 50 03/20/15 14:26:46.674 luup_log:130: ****<-*->**** Arduino: ****<-*->**** >T> queue retrais: {0, 0, 0, 0, 0, 0, } <0x2e850680> 50 03/20/15 14:26:46.674 luup_log:130: ****<-*->**** Arduino: msg found in pos: 1. Removing from list... <0x2e850680> 50 03/20/15 14:26:46.677 luup_log:130: ****<-*->**** Arduino: ****<-*->**** >T> queue updated: {6;1;1;1;2;1, 6;2;1;1;2;1, 6;3;1;1;2;1, 6;4;1;1;2;1, 6;5;1;1;2;1, } <0x2e850680> 50 03/20/15 14:26:46.677 luup_log:130: ****<-*->**** Arduino: ****<-*->**** >T> queue retrais: {0, 0, 0, 0, 0, } <0x2e850680> 50 03/20/15 14:26:46.678 luup_log:130: ****<-*->**** Arduino: ****<-->**** Set variable: 6;0;1;1;2;1 <0x2e850680> 50 03/20/15 14:26:46.678 luup_log:130: ****<-*->**** Arduino: ****<-*->**** >F> setVariable <0x2e850680> 50 03/20/15 14:26:46.679 luup_log:130: ****<-*->**** Arduino: Setting variable 'Status' to value '1' <0x2e850680> 50 03/20/15 14:26:46.679 luup_log:130: ****<-*->**** Arduino: ****<-*->**** >F> setVariableIfChanged <0x2e850680> 50 03/20/15 14:26:46.679 luup_log:130: ****<-*->**** Arduino: ****<-*->**** urn:upnp-org:serviceId:SwitchPower1,Status, 1, 219 <0x2e850680> 06 03/20/15 14:26:46.680 Device_Variable::m_szValue_set device: 219 service: urn:upnp-org:serviceId:SwitchPower1 variable: Status was: 0 now: 1 #hooks: 4 upnp: 0 v:0x9b41e8/NONE duplicate:0 <0x2e850680> 50 03/20/15 14:26:46.680 luup_log:130: ****<-*->**** Arduino: ****<-*->**** >F> setVariableIfChanged <0x2e850680> 50 03/20/15 14:26:46.684 luup_log:130: ****<-*->**** Arduino: ****<-*->**** urn:micasaverde-com:serviceId:HaDevice1,LastUpdate, 1426858006, 219 <0x2e850680> 06 03/20/15 14:26:46.685 Device_Variable::m_szValue_set device: 219 service: urn:micasaverde-com:serviceId:HaDevice1 variable: LastUpdate was: 1426688846 now: 1426858006 #hooks: 0 upnp: 0 v:(nil)/NONE duplicate:0 <0x2e850680> 50 03/20/15 14:26:46.685 luup_log:130: ****<-*->**** Arduino: ****<-*->**** >F> setVariableIfChanged <0x2e850680> 50 03/20/15 14:26:46.686 luup_log:130: ****<-*->**** Arduino: ****<-*->**** urn:micasaverde-com:serviceId:HaDevice1,LastUpdate, 1426858006, 217 <0x2e850680> 06 03/20/15 14:26:46.686 Device_Variable::m_szValue_set device: 217 service: urn:micasaverde-com:serviceId:HaDevice1 variable: LastUpdate was: 1426857982 now: 1426858006 #hooks: 0 upnp: 0 v:(nil)/NONE duplicate:0 <0x2e850680> 50 03/20/15 14:26:46.687 luup_log:130: ****<-*->**** Arduino: ****<-*->**** >F> setVariableIfChanged <0x2e850680> 50 03/20/15 14:26:46.688 luup_log:130: ****<-*->**** Arduino: ****<-*->**** urn:micasaverde-com:serviceId:HaDevice1,LastUpdateHR, 14:26, 217 <0x2e850680> 50 03/20/15 14:26:46.752 luup_log:130: ****<-*->**** Arduino: ****<-*->**** >F> processIncoming msg: 6;1;1;1;2;1 <0x2e850680> 50 03/20/15 14:26:46.753 luup_log:130: ****<-*->**** Arduino: ****<-*->**** >T> queue : {6;1;1;1;2;1, 6;2;1;1;2;1, 6;3;1;1;2;1, 6;4;1;1;2;1, 6;5;1;1;2;1, } <0x2e850680> 50 03/20/15 14:26:46.753 luup_log:130: ****<-*->**** Arduino: ****<-*->**** >T> queue retrais: {0, 0, 0, 0, 0, } <0x2e850680> 50 03/20/15 14:26:46.754 luup_log:130: ****<-*->**** Arduino: msg found in pos: 1. Removing from list... <0x2e850680> 50 03/20/15 14:26:46.754 luup_log:130: ****<-*->**** Arduino: ****<-*->**** >T> queue updated: {6;2;1;1;2;1, 6;3;1;1;2;1, 6;4;1;1;2;1, 6;5;1;1;2;1, } <0x2e850680> 50 03/20/15 14:26:46.755 luup_log:130: ****<-*->**** Arduino: ****<-*->**** >T> queue retrais: {0, 0, 0, 0, } <0x2e850680> 50 03/20/15 14:26:46.755 luup_log:130: ****<-*->**** Arduino: ****<-->**** Set variable: 6;1;1;1;2;1 <0x2e850680> 50 03/20/15 14:26:46.756 luup_log:130: ****<-*->**** Arduino: ****<-*->**** >F> setVariable <0x2e850680> 50 03/20/15 14:26:46.756 luup_log:130: ****<-*->**** Arduino: Setting variable 'Status' to value '1' <0x2e850680> 50 03/20/15 14:26:46.756 luup_log:130: ****<-*->**** Arduino: ****<-*->**** >F> setVariableIfChanged <0x2e850680> 50 03/20/15 14:26:46.757 luup_log:130: ****<-*->**** Arduino: ****<-*->**** urn:upnp-org:serviceId:SwitchPower1,Status, 1, 221 <0x2e850680> 06 03/20/15 14:26:46.757 Device_Variable::m_szValue_set device: 221 service: urn:upnp-org:serviceId:SwitchPower1 variable: Status was: 0 now: 1 #hooks: 4 upnp: 0 v:0x9b41e8/NONE duplicate:0 <0x2e850680> 50 03/20/15 14:26:46.759 luup_log:130: ****<-*->**** Arduino: ****<-*->**** >F> setVariableIfChanged <0x2e850680> 50 03/20/15 14:26:46.759 luup_log:130: ****<-*->**** Arduino: ****<-*->**** urn:micasaverde-com:serviceId:HaDevice1,LastUpdate, 1426858006, 221 <0x2e850680> 06 03/20/15 14:26:46.760 Device_Variable::m_szValue_set device: 221 service: urn:micasaverde-com:serviceId:HaDevice1 variable: LastUpdate was: 1426688847 now: 1426858006 #hooks: 0 upnp: 0 v:(nil)/NONE duplicate:0 <0x2e850680> 50 03/20/15 14:26:46.760 luup_log:130: ****<-*->**** Arduino: ****<-*->**** >F> setVariableIfChanged <0x2e850680> 50 03/20/15 14:26:46.761 luup_log:130: ****<-*->**** Arduino: ****<-*->**** urn:micasaverde-com:serviceId:HaDevice1,LastUpdate, 1426858006, 217 <0x2e850680> 06 03/20/15 14:26:46.761 Device_Variable::m_szValue_set device: 217 service: urn:micasaverde-com:serviceId:HaDevice1 variable: LastUpdate was: 1426858006 now: 1426858006 #hooks: 0 upnp: 0 v:(nil)/NONE duplicate:1 <0x2e850680> 50 03/20/15 14:26:46.762 luup_log:130: ****<-*->**** Arduino: ****<-*->**** >F> setVariableIfChanged <0x2e850680> 50 03/20/15 14:26:46.762 luup_log:130: ****<-*->**** Arduino: ****<-*->**** urn:micasaverde-com:serviceId:HaDevice1,LastUpdateHR, 14:26, 217 <0x2e850680> 50 03/20/15 14:26:46.862 luup_log:130: ****<-*->**** Arduino: ****<-*->**** >F> processIncoming msg: 6;2;1;1;2;1 <0x2e850680> 50 03/20/15 14:26:46.863 luup_log:130: ****<-*->**** Arduino: ****<-*->**** >T> queue : {6;2;1;1;2;1, 6;3;1;1;2;1, 6;4;1;1;2;1, 6;5;1;1;2;1, } <0x2e850680> 50 03/20/15 14:26:46.863 luup_log:130: ****<-*->**** Arduino: ****<-*->**** >T> queue retrais: {0, 0, 0, 0, } <0x2e850680> 50 03/20/15 14:26:46.864 luup_log:130: ****<-*->**** Arduino: msg found in pos: 1. Removing from list... <0x2e850680> 50 03/20/15 14:26:46.864 luup_log:130: ****<-*->**** Arduino: ****<-*->**** >T> queue updated: {6;3;1;1;2;1, 6;4;1;1;2;1, 6;5;1;1;2;1, } <0x2e850680> -
I think you have to re-initialize timer after each call. But it is weird that the first call never executes.
-
@hek
yes, I call the timer again at the end of the function, but the first is inside the start function -
Found this thread: http://forum.micasaverde.com/index.php/topic,15304.msg116321.html#msg116321
We're using job in the MySensors plugin. You might wanna try call_delay instead.
-
Well, If I call the function directly at the begining it gets executed, but neither timer nor delay work.
-
Found this thread: http://forum.micasaverde.com/index.php/topic,15304.msg116321.html#msg116321
We're using job in the MySensors plugin. You might wanna try call_delay instead.
@hek
I got the timer working with this help:http://forum.micasaverde.com/index.php?topic=10258.0
I'll implement it and see what happens
-
Found this thread: http://forum.micasaverde.com/index.php/topic,15304.msg116321.html#msg116321
We're using job in the MySensors plugin. You might wanna try call_delay instead.
Well, I think it sort of works for now.. still too slow and a lot of polishing might be needed, but the concept I think is valid.
Here I turn on 2 devices on an unplugged node, so the commands are put into the queue and the timer is started. Because the node i sunplugged no response is received.
08 03/20/15 22:13:19.706 JobHandler_LuaUPnP::HandleActionRequest device: 219 service: urn:upnp-org:serviceId:SwitchPower1 action: SetTarget <0x2f7fc680> 08 03/20/15 22:13:19.707 JobHandler_LuaUPnP::HandleActionRequest argument DeviceNum=219 <0x2f7fc680> 08 03/20/15 22:13:19.707 JobHandler_LuaUPnP::HandleActionRequest argument serviceId=urn:upnp-org:serviceId:SwitchPower1 <0x2f7fc680> 08 03/20/15 22:13:19.707 JobHandler_LuaUPnP::HandleActionRequest argument action=SetTarget <0x2f7fc680> 08 03/20/15 22:13:19.707 JobHandler_LuaUPnP::HandleActionRequest argument newTargetValue=1 <0x2f7fc680> 08 03/20/15 22:13:19.708 JobHandler_LuaUPnP::HandleActionRequest argument rand=0.980960675558267 <0x2f7fc680> 50 03/20/15 22:13:19.710 luup_log:130: ****<-*->**** Arduino: ****<-*->**** >F> switchPower <0x2ac6e000> 50 03/20/15 22:13:19.710 luup_log:130: ****<-*->**** Arduino: ****<-*->**** >F> sendCommand <0x2ac6e000> 50 03/20/15 22:13:19.711 luup_log:130: ****<-*->**** Arduino: *** **** **** **** *** *** Sending: 6;0;1;1;2;1 <0x2ac6e000> 04 03/20/15 22:13:19.714 <Job ID="5" Name="" Device="219" Created="2015-03-20 22:13:19" Started="2015-03-20 22:13:19" Completed="2015-03-20 22:13:19 08 03/20/15 22:13:22.567 JobHandler_LuaUPnP::HandleActionRequest device: 221 service: urn:upnp-org:serviceId:SwitchPower1 action: SetTarget <0x2f5fc680> 08 03/20/15 22:13:22.567 JobHandler_LuaUPnP::HandleActionRequest argument DeviceNum=221 <0x2f5fc680> 08 03/20/15 22:13:22.568 JobHandler_LuaUPnP::HandleActionRequest argument serviceId=urn:upnp-org:serviceId:SwitchPower1 <0x2f5fc680> 08 03/20/15 22:13:22.568 JobHandler_LuaUPnP::HandleActionRequest argument action=SetTarget <0x2f5fc680> 08 03/20/15 22:13:22.568 JobHandler_LuaUPnP::HandleActionRequest argument newTargetValue=1 <0x2f5fc680> 08 03/20/15 22:13:22.568 JobHandler_LuaUPnP::HandleActionRequest argument rand=0.3527142092837271 <0x2f5fc680> 50 03/20/15 22:13:22.570 luup_log:130: ****<-*->**** Arduino: ****<-*->**** >F> switchPower <0x2ac6e000> 50 03/20/15 22:13:22.570 luup_log:130: ****<-*->**** Arduino: ****<-*->**** >F> sendCommand <0x2ac6e000> 50 03/20/15 22:13:22.571 luup_log:130: ****<-*->**** Arduino: *** **** **** **** *** *** Sending: 6;1;1;1;2;1 <0x2ac6e000> 04 03/20/15 22:13:22.573 <Job ID="6" Name="" Device="221" Created="2015-03-20 22:13:22" Started="2015-03-20 22:13:22" Completed="2015-03-20 22:13:22"then it starts to try to resend the messages. i did set a limit of retries and then the message is deleted for good.
50 03/20/15 22:13:24.101 luup_log:130: ****<-*->**** Arduino: -=OOOO-chk-OOOO=- queue length: 2 <0x2cba1680> 50 03/20/15 22:13:24.102 luup_log:130: ****<-*->**** Arduino: -=OOOO-chk-OOOO=- queue : {6;0;1;1;2;1, 6;1;1;1;2;1, } <0x2cba1680> 50 03/20/15 22:13:24.102 luup_log:130: ****<-*->**** Arduino: queue last elem: 6;1;1;1;2;1 retried: 0 <0x2cba1680> 50 03/20/15 22:13:24.102 luup_log:130: ****<-*->**** Arduino: ****<-*->**** -=OOOO-snd-OOOO=- resending: 6;1;1;1;2;1 <0x2cba1680> 50 03/20/15 22:13:24.104 luup_log:130: ****<-*->**** Arduino: -=OOOO-ooo-OOOO=- starting timer <0x2cba1680> ........ 50 03/20/15 22:13:49.102 luup_log:130: ****<-*->**** Arduino: -=OOOO-chk-OOOO=- queue length: 2 <0x2cba1680> 50 03/20/15 22:13:49.102 luup_log:130: ****<-*->**** Arduino: -=OOOO-chk-OOOO=- queue : {6;0;1;1;2;1, 6;1;1;1;2;1, } <0x2cba1680> 50 03/20/15 22:13:49.102 luup_log:130: ****<-*->**** Arduino: queue last elem: 6;1;1;1;2;1 retried: 5 <0x2cba1680> 50 03/20/15 22:13:49.103 luup_log:130: ****<-*->**** Arduino: ****<-*->**** -=OOOO-snd-OOOO=- resending: 6;1;1;1;2;1 <0x2cba1680> 50 03/20/15 22:13:49.105 luup_log:130: ****<-*->**** Arduino: -=OOOO-ooo-OOOO=- starting timer <0x2cba1680>then when I connect the node back online, the messages are delivered
50 03/20/15 22:13:54.179 luup_log:130: ****<-*->**** Arduino: ****<-*->**** >F> processIncoming msg: 6;1;1;1;2;1 <0x2e3fc680> 50 03/20/15 22:13:54.180 luup_log:130: ****<-*->**** Arduino: ****<-*->**** >T> queue : {6;0;1;1;2;1, 6;1;1;1;2;1, } <0x2e3fc680> 50 03/20/15 22:13:54.180 luup_log:130: ****<-*->**** Arduino: ****<-*->**** >T> queue retries: {0, 7, } <0x2e3fc680> 50 03/20/15 22:13:54.181 luup_log:130: ****<-*->**** Arduino: msg found in pos: 2. Removing from list... <0x2e3fc680> 50 03/20/15 22:13:54.182 luup_log:130: ****<-*->**** Arduino: ****<-->**** Set variable: 6;1;1;1;2;1 <0x2e3fc680> 50 03/20/15 22:13:54.182 luup_log:130: ****<-*->**** Arduino: ****<-*->**** >F> setVariable <0x2e3fc680> 50 03/20/15 22:13:54.182 luup_log:130: ****<-*->**** Arduino: Setting variable 'Status' to value '1' <0x2e3fc680> ........ 50 03/20/15 22:13:59.101 luup_log:130: ****<-*->**** Arduino: -=OOOO-chk-OOOO=- queue length: 1 <0x2cba1680> 50 03/20/15 22:13:59.101 luup_log:130: ****<-*->**** Arduino: -=OOOO-chk-OOOO=- queue : {6;0;1;1;2;1, } <0x2cba1680> 50 03/20/15 22:13:59.102 luup_log:130: ****<-*->**** Arduino: queue last elem: 6;0;1;1;2;1 retried: 0 <0x2cba1680> 50 03/20/15 22:13:59.102 luup_log:130: ****<-*->**** Arduino: ****<-*->**** -=OOOO-snd-OOOO=- resending: 6;0;1;1;2;1 <0x2cba1680> 50 03/20/15 22:13:59.104 luup_log:130: ****<-*->**** Arduino: -=OOOO-snd-OOOO=- set cheking off queue just emptied <0x2cba1680> 50 03/20/15 22:13:59.209 luup_log:130: ****<-*->**** Arduino: ****<-*->**** >F> processIncoming msg: 6;0;1;1;2;1 <0x2e3fc680> 50 03/20/15 22:13:59.210 luup_log:130: ****<-*->**** Arduino: ****<-*->**** >T> queue : {6;0;1;1;2;1, } <0x2e3fc680> 50 03/20/15 22:13:59.210 luup_log:130: ****<-*->**** Arduino: ****<-*->**** >T> queue retries: {1, } <0x2e3fc680> 50 03/20/15 22:13:59.211 luup_log:130: ****<-*->**** Arduino: msg found in pos: 1. Removing from list... <0x2e3fc680> 50 03/20/15 22:13:59.211 luup_log:130: ****<-*->**** Arduino: ****<-*->**** >T> queue updated: {} <0x2e3fc680> 50 03/20/15 22:13:59.212 luup_log:130: ****<-*->**** Arduino: ****<-->**** Set variable: 6;0;1;1;2;1 <0x2e3fc680> 50 03/20/15 22:13:59.212 luup_log:130: ****<-*->**** Arduino: ****<-*->**** >F> setVariable <0x2e3fc680> 50 03/20/15 22:13:59.212 luup_log:130: ****<-*->**** Arduino: Setting variable 'Status' to value '1' <0x2e3fc680>I don't really know if this would be a useful way to solve the problem, or maybe I should look somewhere else
-
Looks good, Might be more people finding this useful. Could you prepare a pull request?
Q: Should the queuing/#retries be options in the plugin settings?
@hek
I use 2 variables that might be user configurable. One is the number of retries and the other is the time between retries.
I suppose there will always be someone willing to change something.I've been thinking about the approach for a while and I'd like to have your input on this.
Now, as I coded, commands are sent by sendCommandWithMessageType() and then added to the queue. Then the timer starts and tries to re-send lost messages.
What I was thinking is if sendCommandWithMessageType() should send the messages directly to the queue function, and let that manage the sending and ack's.
It would be more organized don't you think?
-
@hek
I use 2 variables that might be user configurable. One is the number of retries and the other is the time between retries.
I suppose there will always be someone willing to change something.I've been thinking about the approach for a while and I'd like to have your input on this.
Now, as I coded, commands are sent by sendCommandWithMessageType() and then added to the queue. Then the timer starts and tries to re-send lost messages.
What I was thinking is if sendCommandWithMessageType() should send the messages directly to the queue function, and let that manage the sending and ack's.
It would be more organized don't you think?