Scene too fast for gateway?
-
@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.
-
@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:
-
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.
-
@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.
-
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....
-
@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);
-
@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: 1Your 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.
-
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: 1but 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: 0only 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\nwithout 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\nDuring 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\nas I hint - I hope I'm wrong
- Pit
-
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?
-
@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.
-
@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?
-
@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.
-
@BulldogLowell I have some 10mF. Would this be enough or do you suggest somthing bigger...
-
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.
-
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.
-
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#L38And in the Vera serial configuration.
-
@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.
-
@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.
-
@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?
-
Powered hub alone did not make any improvements.
I'll try bigger capacitor next.
-
10 mF also no change. I'll try someting bigger when i can
-
@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
-
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?
-
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.
-
@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?
-
You can do a soft link to from the mount to your logfile.
-
@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 deniedand it didn't work
-
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.
-
@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
-
@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>
-
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.
-
@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.
-
Well, If I call the function directly at the begining it gets executed, but neither timer nor delay work.
-
@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
-
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?
-
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).
-
@hek
Here's the linkhttps://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
-
@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.
-
@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.
-
@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
-
@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.luaYesterday 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:
