Ocelot response timing
So far so good. I managed to get the update in last night before my 11pm busy X10 time. I send 3 x10 commands at 11pm and they all came into HB no problem and the buffer stayed in sync.
Same for x10 sunrise event.... HB captured the entire event and the extra bytes didn't get stuck in the buffer.
Tim
Same for x10 sunrise event.... HB captured the entire event and the extra bytes didn't get stuck in the buffer.
Tim
Re: Ocelot response timing
Hi Scott,
Sorry to dig this one up again...
But my last note of being stable didn't pan out, and actually I've been living with the issue for about a year since I just did not have time to trouble-shoot it.
Something is disrupting the Ocelot comm protocol and it looks like the send (and possibly receive) buffer is getting really out-of-whack. Before we start down the path of looking at the logs in too much detail and trying to figure out what is going on...
- Seeing how the Ocelot is a dying (possibly dead) technology... And not knowing how many of your users still require it to be supported... It is worth spending a bit of time trouble-shooting this?
- I will be moving off my Ocelot for lighting at some point in the near future and going with probably Insteon or z-wave.
- I will be moving all my Ocelot code over to Housebot.
- My inputs are all full on the Ocelot and will move to one-wire/hobby board or phidgets for I/O, temp, an other advanced sensing.
- I'll probably keep the Ocelot for IR.
What I'm saying is, I don't know how long I'll be committed to the Ocelot (but it'll be at least 6-12 months), so I don't want to waste your time trouble-shooting it if I am going to ditch the device. Maybe we can take a quick look if you think it's worth it.
Let me know.
Thanks
Tim
PS: Yep... I have upgraded to the latest and greatest.
Sorry to dig this one up again...
But my last note of being stable didn't pan out, and actually I've been living with the issue for about a year since I just did not have time to trouble-shoot it.
Something is disrupting the Ocelot comm protocol and it looks like the send (and possibly receive) buffer is getting really out-of-whack. Before we start down the path of looking at the logs in too much detail and trying to figure out what is going on...
- Seeing how the Ocelot is a dying (possibly dead) technology... And not knowing how many of your users still require it to be supported... It is worth spending a bit of time trouble-shooting this?
- I will be moving off my Ocelot for lighting at some point in the near future and going with probably Insteon or z-wave.
- I will be moving all my Ocelot code over to Housebot.
- My inputs are all full on the Ocelot and will move to one-wire/hobby board or phidgets for I/O, temp, an other advanced sensing.
- I'll probably keep the Ocelot for IR.
What I'm saying is, I don't know how long I'll be committed to the Ocelot (but it'll be at least 6-12 months), so I don't want to waste your time trouble-shooting it if I am going to ditch the device. Maybe we can take a quick look if you think it's worth it.
Let me know.
Thanks
Tim
PS: Yep... I have upgraded to the latest and greatest.
Re: Ocelot response timing
I just couldn't resist...
It turns out that I never turned off logging from last year...
My guess is that it is a timing thing again. Looking at the thread, we weren't waiting long enough for the full x-10 command, so when it did come in, it pushed all the bytes off by one.
It could be the same thing but with the I/O notification code ff. What I am seeing in the log is an 0xff, which triggers HB to do the write to grab the new data. But at the beginning of the new data returned from the Ocelot, I see another 0xff 0xff 0x2a ...... Where 0x2a usually starts the Ocelot data, ans should not be the 3rd byte in.
What I am going to guess is that I have 3 changes happening at a very close time/simultaneously on my IO, which causes the Ocelot to spew out 3 0xff notifications. This would make sense with what I have wired into my IO. In that they will sometimes, but not always, change very close/same time as each other. Once that triple 0xff comes in, it's all downhill from there.
I'm not sure the work-around, but maybe ignore subsequant 0xff notifications? And/or after seeing an 0xff, read 1 byte chunks until you see 0x2a to indicate the start of the new status?
Just guessing at this happening, but it makes sense in my feeble brain.
Thanks
Tim
"3/31/2009","3:41:10 pm","Ocelot","Debug","Read [1] bytes [ff]"
"3/31/2009","3:41:10 pm","Ocelot","Debug","Received remote IO status changed indicator"
"3/31/2009","3:41:10 pm","Ocelot","Debug","--> Read Pending... WriteData. 8 bytes"
"3/31/2009","3:41:10 pm","Ocelot","Debug","Writing [8] bytes [2a 00 00 8d b5 00 25 e9]"
"3/31/2009","3:41:11 pm","Ocelot","Debug","Read [264] bytes [ff ff 2a 00 00 8d b5 00 00 00 fd 01 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00]"
"3/31/2009","3:41:11 pm","Ocelot","Debug","Read [1] bytes [ee]"
"3/31/2009","3:41:11 pm","Ocelot","Debug","Realtime Data = [ff 2a 00 00 8d b5 00 00 00 fd 01 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 ee]"
"3/31/2009","3:41:11 pm","Ocelot","Error","Invalid CRC in realtime data"
"3/31/2009","3:48:11 pm","Ocelot","Debug","--> Read Pending... WriteData. 8 bytes"
"3/31/2009","3:48:11 pm","Ocelot","Debug","Writing [8] bytes [c8 33 02 02 01 00 00 00]"
"3/31/2009","3:48:11 pm","Ocelot","Debug","Read [3] bytes [93 06 00]"
"3/31/2009","3:48:11 pm","Ocelot","Error","Error: Return from Ocelot when setting relay state. Return = [93 06 00]"
"3/31/2009","3:48:11 pm","Ocelot","Debug","Read [1] bytes [ff]"
"3/31/2009","3:48:11 pm","Ocelot","Debug","Received remote IO status changed indicator"
"3/31/2009","3:48:11 pm","Ocelot","Debug","--> Read Pending... WriteData. 8 bytes"
"3/31/2009","3:48:11 pm","Ocelot","Debug","Writing [8] bytes [2a 00 00 8d b5 00 25 e9]"
"3/31/2009","3:48:12 pm","Ocelot","Debug","Read [264] bytes [06 2a 00 00 8d b5 00 00 00 f5 05 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00]"
"3/31/2009","3:48:12 pm","Ocelot","Error","Invalid response header from realtime data request"
"3/31/2009","3:51:10 pm","Ocelot","Debug","Read [1] bytes [ff]"
"3/31/2009","3:51:10 pm","Ocelot","Debug","Received remote IO status changed indicator"
"3/31/2009","3:51:10 pm","Ocelot","Debug","--> Read Pending... WriteData. 8 bytes"
"3/31/2009","3:51:10 pm","Ocelot","Debug","Writing [8] bytes [2a 00 00 8d b5 00 25 e9]"
"3/31/2009","3:51:11 pm","Ocelot","Debug","Read [264] bytes [44 2a 00 00 8d b5 00 00 00 b5 05 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00]"
"3/31/2009","3:51:11 pm","Ocelot","Error","Invalid response header from realtime data request"
It turns out that I never turned off logging from last year...
My guess is that it is a timing thing again. Looking at the thread, we weren't waiting long enough for the full x-10 command, so when it did come in, it pushed all the bytes off by one.
It could be the same thing but with the I/O notification code ff. What I am seeing in the log is an 0xff, which triggers HB to do the write to grab the new data. But at the beginning of the new data returned from the Ocelot, I see another 0xff 0xff 0x2a ...... Where 0x2a usually starts the Ocelot data, ans should not be the 3rd byte in.
What I am going to guess is that I have 3 changes happening at a very close time/simultaneously on my IO, which causes the Ocelot to spew out 3 0xff notifications. This would make sense with what I have wired into my IO. In that they will sometimes, but not always, change very close/same time as each other. Once that triple 0xff comes in, it's all downhill from there.
I'm not sure the work-around, but maybe ignore subsequant 0xff notifications? And/or after seeing an 0xff, read 1 byte chunks until you see 0x2a to indicate the start of the new status?
Just guessing at this happening, but it makes sense in my feeble brain.
Thanks
Tim
"3/31/2009","3:41:10 pm","Ocelot","Debug","Read [1] bytes [ff]"
"3/31/2009","3:41:10 pm","Ocelot","Debug","Received remote IO status changed indicator"
"3/31/2009","3:41:10 pm","Ocelot","Debug","--> Read Pending... WriteData. 8 bytes"
"3/31/2009","3:41:10 pm","Ocelot","Debug","Writing [8] bytes [2a 00 00 8d b5 00 25 e9]"
"3/31/2009","3:41:11 pm","Ocelot","Debug","Read [264] bytes [ff ff 2a 00 00 8d b5 00 00 00 fd 01 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00]"
"3/31/2009","3:41:11 pm","Ocelot","Debug","Read [1] bytes [ee]"
"3/31/2009","3:41:11 pm","Ocelot","Debug","Realtime Data = [ff 2a 00 00 8d b5 00 00 00 fd 01 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 ee]"
"3/31/2009","3:41:11 pm","Ocelot","Error","Invalid CRC in realtime data"
"3/31/2009","3:48:11 pm","Ocelot","Debug","--> Read Pending... WriteData. 8 bytes"
"3/31/2009","3:48:11 pm","Ocelot","Debug","Writing [8] bytes [c8 33 02 02 01 00 00 00]"
"3/31/2009","3:48:11 pm","Ocelot","Debug","Read [3] bytes [93 06 00]"
"3/31/2009","3:48:11 pm","Ocelot","Error","Error: Return from Ocelot when setting relay state. Return = [93 06 00]"
"3/31/2009","3:48:11 pm","Ocelot","Debug","Read [1] bytes [ff]"
"3/31/2009","3:48:11 pm","Ocelot","Debug","Received remote IO status changed indicator"
"3/31/2009","3:48:11 pm","Ocelot","Debug","--> Read Pending... WriteData. 8 bytes"
"3/31/2009","3:48:11 pm","Ocelot","Debug","Writing [8] bytes [2a 00 00 8d b5 00 25 e9]"
"3/31/2009","3:48:12 pm","Ocelot","Debug","Read [264] bytes [06 2a 00 00 8d b5 00 00 00 f5 05 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00]"
"3/31/2009","3:48:12 pm","Ocelot","Error","Invalid response header from realtime data request"
"3/31/2009","3:51:10 pm","Ocelot","Debug","Read [1] bytes [ff]"
"3/31/2009","3:51:10 pm","Ocelot","Debug","Received remote IO status changed indicator"
"3/31/2009","3:51:10 pm","Ocelot","Debug","--> Read Pending... WriteData. 8 bytes"
"3/31/2009","3:51:10 pm","Ocelot","Debug","Writing [8] bytes [2a 00 00 8d b5 00 25 e9]"
"3/31/2009","3:51:11 pm","Ocelot","Debug","Read [264] bytes [44 2a 00 00 8d b5 00 00 00 b5 05 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00]"
"3/31/2009","3:51:11 pm","Ocelot","Error","Invalid response header from realtime data request"
Re: Ocelot response timing
Tim,
I think your analysis is correct. The code would actually try and handle the case where there are 2 0xff's received, but three.... not so much.
I made a quick change so that it should handle up to 10 0xff's received consecutively. More than 10, and I'm thinking there's probably something else going on.
I've not tested this at all, so let me know if it works any better.
Download the new plugin here. Unzip it and copy the DLL into your \HouseBot\Plugins\Interfaces directory (backup the old dll first).
I think your analysis is correct. The code would actually try and handle the case where there are 2 0xff's received, but three.... not so much.
I made a quick change so that it should handle up to 10 0xff's received consecutively. More than 10, and I'm thinking there's probably something else going on.
I've not tested this at all, so let me know if it works any better.
Download the new plugin here. Unzip it and copy the DLL into your \HouseBot\Plugins\Interfaces directory (backup the old dll first).
Scott