Scene too fast for gateway?


  • Hero Member

    Hi,
    I have one scene created in vera which sends the ON command to 2 relays in an actuator node at the same time.
    The problem is only the first command is received. The second relay does nothing.
    I have to make use of the 1s delays and send one, then send the other a second after for it to work.
    Is this a limitation of the arduinos?

    Thanks in advace


  • Admin

    @ferpando

    Hard to say where it fails. Could you perhaps follow the messages from vera/gateway/relay (and back for the ack-message) to see where it disappears?


  • Hero Member

    I will try to replicate and keep you posted


  • Hero Member

    @hek
    I've been trying some things and the problem is consistent.
    If I turn on/off 2 or more devices on a scene at the same time, not all work.
    The message to some devices is lost never reaching its destination.

    How does the plugin handle this? Does it have some kind of buffer?

    From the node point of view, if 2 messages arrive too fast, what happens?
    If the arduino is busy doing something, will it receive the next message when it finishes processing?

    I don't know how to solve this. Just the 2-3 second delay between messages is working, but it is a bit annoying and not very practical.


  • Contest Winner

    @ferpando said:

    I don't know how to solve this. Just the 2-3 second delay between messages is working, but it is a bit annoying and not very practical.

    When applying an action from vera to multiple devices, I use a short delay in the scene for each device to allow the transmissions time and the radio to repond. There is the power aspect, and the serial processing aspect to deal with.

    With vera's delay capability built in to the scene, I find it only mildly annoying, but not at all impractical:

    Screen Shot 2015-03-13 at 9.45.45 AM.png


  • Hero Member

    Yes, tha's exactly what I do, but is not the best solution.
    It would be best is the system (plugin) had some kind of buffer and the nodes didn't get the next message from the gateway until the arduino was free to process.
    Maybe checking for messages in the main loop?
    I don't really know how the system works right now, but messages are lost if sent too fast.


  • Contest Winner

    @ferpando said:

    but is not the best solution.

    yeah, I agree. I ran into this early on but never thought about it since. I actually use luup attached to a scene rather than using the pushbutton controls. I can then use luup.sleep( ) function to allow a little time back to the controller... and I see all the actions on a single page:

    luup.inet.wget("192.168.1.50//?alarmState=0&", 1)
    luup.sleep(500)
    luup.inet.wget("192.168.1.50//?airconSetpoint=74&", 1)
    luup.sleep(500)
    os.execute("curl -k https://api.spark.io/v1/devices/"..sparkDeviceID.."/httpRequest  -d access_token="..sparkAccessToken.."  -d params=command#garageState#text=NULL#value0=0#value1=0?" ,1)
    luup.sleep(500)
    os.execute("curl -k https://api.spark.io/v1/devices/"..sparkDeviceID.."/httpRequest  -d access_token="..sparkAccessToken.."  -d params=command#airconSetpoint#text=NULL#value0=72#value1=0?" ,1)
    

    if you want to try writing some code I'm happy to help you test, and I'm sure others would too.


  • Hero Member

    That would be ok for 2 or 3 devices, but if you need to turn on let's say 5, waiting all those seconds is no good. Epecially if they are lights.

    I have some Chacon DI·O 433Mhz plugs controlled by rfxcom and I can turn 10 of them off without problem. They just go one after the other but very quickly.

    That's why I guess the problem is in the plugin that sends messages too fast for the nodes.

    Any of the programmers have some clue about this?



  • @ferpando I have actually exact the same problem right now but I expect that the Vera Edge is the problem. I looks like some devices are present in the scene but they are still not present. I have created a scene with about 10 devices in and that looks ok in the scene but when I look on the "scene info" on each device then some of them doesn't says that i exist in that scene. I have also made a quick check on the serial debug and it looks like the Vera doesn't send command for all devices. Right now I'm recreatcing my scene to verify that all devices actually are included.

    I'll be back....


  • Contest Winner

    @ferpando said:

    I guess the problem is in the plugin that sends messages too fast for the nodes.

    the dalays don't need to be that long... just an example...

    one of the issues you may face could be power available to the radio when you transmit. Do you have a capacitor on the gateway radio power already? if so, look at the output from the Serial monitor when you transmit, you may be able to see what's happening there. What type of power supply are you using on the gateway?

    FYI your arduino has a 64byte serial buffer and the NRF24L01 a 32byte buffer. A software alternative may be to add a little delay in parseAndSend( ) in MyGateway.cpp or just before that function call in your SerialGateway.ino or EhternetGateway.ino files, just so that you allow a little time for the buffer on the radio to clear out and the cap to recharge before sending the next message.

    on the Ethernet:

      Serial.print(inputString);
      delay(35);  // <<<<<<<<<<<<<<<<<<<<<<<< here, you can start with an imperceptible number like 35ms
      gw.parseAndSend(inputString);
    

  • Hero Member

    @BulldogLowell
    I use the VERA's USB to power my serial gateway.
    Would an ethernet gateway behave better?
    I tried adding the delay but all I get is a lot of fails in the messages. Maybe the gateway is busy waiting and doesn't catch new messages?
    This is the log from the node:

    read: 0-0-6 s=0,c=1,t=2,pt=0,l=1:0
    send: 6-6-0-0 s=0,c=1,t=2,pt=0,l=1,st=fail:0
    --> Incoming change for relay:0, New status: OFF
    Time ms: 1
    ************************************************
    read: 0-0-6 s=0,c=1,t=2,pt=0,l=1:0
    send: 6-6-0-0 s=0,c=1,t=2,pt=0,l=1,st=ok:0
    --> Incoming change for relay:0, New status: OFF
    Time ms: 1
    ************************************************
    read: 0-0-6 s=0,c=1,t=2,pt=0,l=1:1
    send: 6-6-0-0 s=0,c=1,t=2,pt=0,l=1,st=ok:1
    --> Incoming change for relay:0, New status: ON
    Time ms: 1
    ************************************************
    read: 0-0-6 s=0,c=1,t=2,pt=0,l=1:1
    send: 6-6-0-0 s=0,c=1,t=2,pt=0,l=1,st=fail:1
    --> Incoming change for relay:0, New status: ON
    Time ms: 1
    ************************************************
    read: 0-0-6 s=0,c=1,t=2,pt=0,l=1:1
    send: 6-6-0-0 s=0,c=1,t=2,pt=0,l=1,st=fail:1
    --> Incoming change for relay:0, New status: ON
    Time ms: 1
    ************************************************
    read: 0-0-6 s=0,c=1,t=2,pt=0,l=1:1
    send: 6-6-0-0 s=0,c=1,t=2,pt=0,l=1,st=fail:1
    --> Incoming change for relay:0, New status: ON
    Time ms: 1
    

    Your other option adding delays in code and call devices also in code seams to work for now. Something like this:

    local myDelay=300;
    luup.call_action("urn:upnp-org:serviceId:SwitchPower1","SetTarget",{newTargetValue="1"},219)
    luup.sleep(myDelay)
    luup.call_action("urn:upnp-org:serviceId:SwitchPower1","SetTarget",{newTargetValue="1"},221)
    luup.sleep(myDelay)
    luup.call_action("urn:upnp-org:serviceId:SwitchPower1","SetTarget",{ newTargetValue="1"},216)
    

    I'm gonna explore more this option and get back to you.


  • Hero Member

    If I use the above code with the delays in lua, it seams to work:

    read: 0-2-6 s=0,c=1,t=2,pt=0,l=1:1
    send: 6-6-2-0 s=0,c=1,t=2,pt=0,l=1,st=ok:1
    --> Incoming change for relay:0, New status: ON
    Time ms: 1
    ************************************************
    read: 0-2-6 s=1,c=1,t=2,pt=0,l=1:1
    send: 6-6-2-0 s=1,c=1,t=2,pt=0,l=1,st=ok:1
    --> Incoming change for relay:1, New status: ON
    Time ms: 1
    ************************************************
    read: 0-2-6 s=2,c=1,t=2,pt=0,l=1:1
    send: 6-6-2-0 s=2,c=1,t=2,pt=0,l=1,st=ok:1
    --> Incoming change for relay:2, New status: ON
    Time ms: 1
    ************************************************
    read: 0-2-6 s=3,c=1,t=2,pt=0,l=1:1
    send: 6-6-2-0 s=3,c=1,t=2,pt=0,l=1,st=ok:1
    --> Incoming change for relay:3, New status: ON
    Time ms: 1
    ************************************************
    read: 0-2-6 s=4,c=1,t=2,pt=0,l=1:1
    send: 6-6-2-0 s=4,c=1,t=2,pt=0,l=1,st=ok:1
    --> Incoming change for relay:4, New status: ON
    Time ms: 1
    ************************************************
    read: 0-2-6 s=5,c=1,t=2,pt=0,l=1:1
    send: 6-6-2-0 s=5,c=1,t=2,pt=0,l=1,st=ok:1
    --> Incoming change for relay:5, New status: ON
    Time ms: 1
    

    but if I use the devices on the scenes, the result I get is this:

    read: 0-2-6 s=0,c=1,t=2,pt=0,l=1:1
    send: 6-6-2-0 s=0,c=1,t=2,pt=0,l=1,st=ok:1
    --> Incoming change for relay:0, New status: ON
    Time ms: 0
    ************************************************
    read: 0-2-6 s=1,c=1,t=2,pt=0,l=1:1
    send: 6-6-2-0 s=1,c=1,t=2,pt=0,l=1,st=ok:1
    --> Incoming change for relay:1, New status: ON
    Time ms: 0
    

    only 2 of the 6 are received.

    If I lower the delay too much I also start to miss some of them.



  • I don't have vera but my 5 cent:

    If two or more commands send at the same time they can be packed in the same tcp package.

    with delay (4 tcp packages)
    12;6;0;0;x;1\n
    12;6;0;0;x;2\n
    12;6;0;0;x;3\n
    12;6;0;0;x;4\n

    without delay: (2 tpc packages - the first with 3 commands)
    12;6;0;0;x;1\n12;6;0;0;x;2\n12;6;0;0;x;3\n
    12;6;0;0;x;4\n

    During my walk throug the sources of different MYS impementations I didn't see code to parse the second case correctly - so with commands following in shoort time behind, the receiver see only the first command in a package:

    12;6;0;0;x;1\n
    12;6;0;0;x;4\n

    as I hint - I hope I'm wrong 🙂

    • Pit

  • Hero Member

    All this was on a test board.
    Now I'm trying it in the real world and it doesn't work.

    I noticed nodes have radio power set to max and gateway to low by default.
    Why is this?
    Maybe increasing gateway radio power would help?


  • Admin

    @ferpando said:

    I noticed nodes have radio power set to max and gateway to low by default.
    Why is this?

    Basically a safety thing. Many used the amplified NRF module on their gateway without feeding it with enough power. This resulted in failed transmissions and more support. 😉


  • Hero Member

    @hek
    So it would be ok to increase radio power on the standard version without causing problems?

    I noticed if I put the antenna inside a plastic box starts to fail a lot. But the distance is not much, 4m at the most.

    Also increasing datarate could help with this problem? If data is sent faster, maybe works better?


  • Contest Winner

    @ferpando said:

    I use the VERA's USB to power my serial gateway.

    and you have a capacitors on the radios, yes? I'm not sure if there is really enough power from the vera to keep up with the radio, so beefing up the cap may help too.

    makes a huge difference... having lots of power available for the multiple bursts of the radio.


  • Hero Member

    @BulldogLowell I have some 10mF. Would this be enough or do you suggest somthing bigger...


  • Contest Winner

    @ferpando

    that would be a good start. @hek recommends starting at 4.7µF but I have seen folks here swear they need much bigger.

    It depends, as you may know, on the power supply as well. Some folks may even have moved the USB gateway off to a powered USB hub.


  • Hero Member

    Has it been determined that the messages are getting to the gateway's radio (transmitter)? If so, then caps on the nRF24L01's power supply may indeed help if power sag is the issue; if not, then we're looking in the wrong place and some of the other suggestions may be relevant.

    IF it's about power sag in the radio, that may require large caps. Sometimes small caps help the radio, if it's having problems with high frequency spikes and noise in the power supply. But if the problem occurs over hundreds of uSec (one packet affecting the following one) then it would be very low frequency and relatively long duration.

    However, a better power supply would be a better solution if so. A scope (even an arduino based software scope given the frequencies involved) might help determine if the supply is really the problem.

    AND of course, the first question is whether the controller firmware is even TRYING to send every packet, as this post began.



  • @Zeph I dont't think it has to do with the powersupply. I have the same problem and I power my Gateway with 2A supply and on the radio I have 47uF. I have a coulple of scenes that turn on/off lamps and in my case it looks like there is a limit around 4 devices, if the scene contains more than 4 devices whith no delay then it often miss some of them. But when I added 1 sec delay between every third device then it works fine.


  • Admin

    Could it be the serial buffer of the arduino (64 bytes) that fills up to quick with the baudrate?

    What happens if you lower baudrate to say 9600?

    Change here and re-compile gateway:
    https://github.com/mysensors/Arduino/blob/master/libraries/MySensors/MySensor.h#L38

    And in the Vera serial configuration.


  • Hero Member

    @Zeph
    As you can see in the log above, the gateway starts to send messages and only the first and second reach the corresponding node.
    Maybe it is a power issue. I'll try a powered hub and see what happens.


  • Hero Member

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


  • Hero Member

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


  • Hero Member

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


  • Hero Member

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


  • Hero Member

    @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


  • Hero Member

    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?


  • Admin

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


  • Hero Member

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


  • Admin

    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.


  • Hero Member

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


  • Admin

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


  • Hero Member

    @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


  • Admin

    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.


  • Hero Member

    @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


  • Hero Member

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


  • Admin

    @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


  • Hero Member

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

  • Admin

    I think you have to re-initialize timer after each call. But it is weird that the first call never executes.


  • Hero Member

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


  • Admin

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


  • Hero Member

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


  • Hero Member

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


  • Hero Member

    @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


  • Hero Member

    @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


  • Admin

    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?


  • Hero Member

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


  • Admin

    @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).


  • Hero Member

    @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


  • Hero Member

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


  • Admin

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


  • Hero Member

    @hek
    Messages now are correctly ack'd because of the queue. Before they were lost.
    But that is not all to it, because now the lost messages are re-sent, ack'd back but not executed by the node.

    I'll do some more testing and post back


  • Hero Member

    @hek
    I've been trying to get some buttons in the vera plugin but I've had not much luck.
    I addded some code to arduino.xml and arduino.json but nothing appears.
    I uploaded the files to the repo. Could you take a look when you have the time?

    S_Arduino.xml
    D_Arduino1.json
    L_Arduino.lua

    Yesterday I also made a new system for the nodes to have also a queue.
    Looks something like this:

    
    #include <MySensor.h>
    #include <SPI.h>
    #include <MyBuffer.h>
    
    .......
    
    long previousMillis = 0;       // will store last time buffer was processed
    long interval = 1000;           // interval at which to check buffer
    MyBuffer buffer;               // define a new buffer
    MySensor gw;
    
    ..........
    void setup() {  .... sensor setup code....  }
    
    void loop() 
    { 
      gw.process();
            
      unsigned long currentMillis = millis();
      if(currentMillis - previousMillis > interval) {
            previousMillis = currentMillis;  
            processBuffer();    
          }
    } 
    
    void incomingMessage(const MyMessage &message) {
        buffer.push(message.sensor,message.type);
    }
    
    //gets message from buffer if exists
    void processBuffer(){
    if(!buffer.isEmpty()){
          String msg=buffer.pop();
          
          int mIndex = msg.indexOf(';');
          int secondmIndex = msg.indexOf(';,', mIndex+1);
    
          String firstValue = msg.substring(0, mIndex);
          String secondValue = msg.substring(mIndex+1, secondmIndex);
          
          int sensor = firstValue.toInt();
          int type = secondValue.toInt();
       
          processMsg(sensor, type);
      }
    }
    
    //process message from queue
    void processMsg(int sensor, int type){
         //do some stuff
    }
    

    It's pretty basic but it works.
    The library files are here:

    MyBuffer.h
    MyBuffer.cpp


Log in to reply
 

Suggested Topics

  • 1
  • 1
  • 3
  • 2
  • 5

0
Online

11.2k
Users

11.1k
Topics

112.5k
Posts