Scene too fast for gateway?

[hek]

You can do a soft link to from the mount to your logfile.

[ferpando]

@hek
I'm no linux expert, but I tried this:

ln -s /var/log/cmh/LuaUPnP.log /dataMine/log/vera.log
ln: /dataMine/log/vera.log: Permission denied

and it didn't work

[hek]

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.

[ferpando]

@hek
I think the problem might be that I'm trying to create the symLink as root and the cfis is using another user to connect to the nas

[ferpando]

@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
end

function 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]

...

end

And 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
end

It 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]

@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

[ferpando]

@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 think you have to re-initialize timer after each call. But it is weird that the first call never executes.

[ferpando]

@hek
yes, I call the timer again at the end of the function, but the first is inside the start function

[hek]

@ferpando

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.

[ferpando]

@hek
yes I saw it too, but in this case, the call should be recursive, so it should be better to use the timer version.
I'll try with delay and see if at least works.

[ferpando]

Well, If I call the function directly at the begining it gets executed, but neither timer nor delay work.

[ferpando]

@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

[ferpando]

@hek

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

[hek]

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?

[ferpando]

@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]

@ferpando

Hmm. do you have your fork on github so I can see the code?

But i like the idea of just queuing up messages. And something else picking up messages from this and send it (could be timer or some explicit call to get a instant pop/send).

[ferpando]

@hek
Here's the link

https://github.com/Fernando-Checa/Vera/blob/master/L_Arduino.lua

Now it has a delay of 5 seconds just for testing, but that should be reduced
Also changed some log calls just for clarity, but that will be discarded later on

[ferpando]

@hek
I have to say dispite this queue upgrade I'm still getting some messages lost. Not really lost, because they are ack'd but never executed by the remote node.

I started to investigate other posibilities, and since I'm using shift registers and optocouplers on some nodes (the problematic ones), maybe those components are just to slow to respond and if I change the register too fast, the optocupler does not have the time to really trigger anything.

Although I think this queue would be a good thing to add to the system, I might need to add something similar to the receiving part to slow down the procesing of messages, because shometimes might be neded.

I didn't try to use relays directly attached to the arduino without the optocouplers, so in that instance might no be really necesary. I read somewhere this particular shift register can be as fast as 500.000 changes per second.

Anyway, I'll think of something for the nodes and let you know.

[hek]

@ferpando said:

I have to say dispite this queue upgrade I'm still getting some messages lost. Not really lost, because they are ack'd but never executed by the remote node.

Ok, if the message reaches the node it must be something else then.

I do like the queue stuff.
But you should probably test it for a while and add the retry delay configuration and max retries easy accessible in the vera gui.