Scene too fast for gateway?

[ferpando]

@olaeke
If you are able to turn 4 devices at the same time that is more than I can do at the moment. Maybe power is one of the issues as @Zeph suggested, but not the only one.

[ferpando]

@hek
I'll try lowering the rate after upgrading the powersupply. Maybe this will also help a bit more.
About the buffer, would an ethernet gateway behave better in this matter?
Maybe all this could resolve itself changing gateway type?

[ferpando]

Powered hub alone did not make any improvements.
I'll try bigger capacitor next.

[ferpando]

10 mF also no change. I'll try someting bigger when i can

[ferpando]

@hek
I recompiled the gateway with 9600 bauds but the vera plugin won't start if not 115200.

Any way to change this without messing everything up?
I reuploaded L_Arduino.lua changing the setting but vera does not use the new file. I can see both in the list.
I'll try to delete both via ssh and reupload to see what happens

[ferpando]

After deleting the files and reuploading the 9600 version, nothing changed, so this is not the problem.

From the lua file, I see there is a function that sends the data to the nodes.
How does it work? Is it invoked by vera when you push some button?

Would it be too complex to make the function store command on an array for instance and send a command to a node from that array queue and not sending another until acknowledge is recevied?

[hek]

@ferpando

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.

[ferpando]

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

[hek]

The closest to "main" is this:
https://github.com/mysensors/Vera/blob/master/L_Arduino.lua#L543

Debugging 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.

[ferpando]

@hek
I'll take a look at this. Thank you.
I already have my NAS mounted for datamine storage. How can I send the vera logs to the nas?

[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.