Issues with AK Bond installation

[CJMH]

I am not having any trouble using the web interface. It is very responsive. The time between clicking on an action icon and it taking effect is nearly instantaneous. HS Touch and HS Mobile running on a Pixel 3 are no faster for me.

I think you are still having problems with processing a com errors. I restarted HS3 and the polling follows the Config Page (every ten seconds as I have it now). However once a communication error occurs in AK Bond, the polling gets erratic. Restarting AK bond does not correct the problem either. I have to restart HS3 which for me means rebooting the ZEE S2.

Hope that gives you a clue .....

[alexbk66]

I think you are still having problems with processing a com errors. I restarted HS3 and the polling follows the Config Page (every ten seconds as I have it now). However once a communication error occurs in AK Bond, the polling gets erratic. Restarting AK bond does not correct the problem either. I have to restart HS3 which for me means rebooting the ZEE S2.

Hope that gives you a clue .....

Thank you for detailed feedback.

Interesting information. Please verify that the comms errors do cause the polling issue, if that's the case - it can be a clue.

And I still research this Mono issue too.

[alexbk66]

And also, try disabling Z-Wave plugin temporary

[CJMH]

I tried disabling the Z-Wave plugin and it did nothing to stop the erratic AK Bond polling behavior once it starts.

I have restarted HS3 several times now and the polling works according to the AK Bond Config Page after the restart until a com error occurs and then the polling gets erratic. The time it takes for an error to occur seems fairly random, but the erratic polling start as soon as the error occurs.

I checked the disk usage and there is still 1.7G of space left so I don't think that is the problem.

Out of 945 Mbytes of memory there is 301 Mbyte used leaving 644 Mbyte free. Also does not seem to be a problem.

I have attached a usage report with both Z-Wave and AK Bond running

top - 10:31:40 up 2 min, 0 users, load average: 0.57, 0.33, 0.13
Tasks: 126 total, 1 running, 125 sleeping, 0 stopped, 0 zombie
%Cpu(s): 10.7 us, 1.7 sy, 0.0 ni, 84.6 id, 2.9 wa, 0.0 hi, 0.1 si, 0.0 st
KiB Mem: 945512 total, 301488 used, 644024 free, 20964 buffers
KiB Swap: 102396 total, 0 used, 102396 free. 125472 cached Mem

I restarted HS3 again and it has been running the whole time I have been collecting this information and writing the email. As of yet there has not been a com error and the log shows updating every 10 seconds. However, it has only been running for a little over 10 minutes.

[CJMH]

More info ... When the polling is working correctly changing a device state on the Android Bond App does show up as a change on the HS3 AK Bond on the 10 second pool interval. When the polling is erratic the same scenario shows up erratically on the AK Bond device but usually no longer than a couple seconds. It certain is not taking up to ten seconds to show the change.

Here is my procedure for testing this:

Make a change on the Bond App and wait for the change to appear in HS3 AK Bond device. A soon as I see the change, make another change on the Bond app. When the polling is working correctly the HS3 AK Bond deivec does not show the change for 10 seconds. If I wait 6 seconds after I see the change on the HS3 AK Bond device before making another change on the Bond App, the new change only takes 4 seconds to show up on the AK Bond device. This is consistent with 10 second polling.

When the polling is erratic, making a change on the Bond app cause the HS3 AK Bond device to instantly to a couple seconds change. This is consistent with what I see in the log in regards to the erratic polling.

AK Bond still has not reported a com error and it has been running for 30 minutes and the polling is still every ten seconds. But I have not been changing any devices from the HS3 side.

[CJMH]

More info. I have been running the AK Bond plugin after a system restart for over two hours with no com errors and polling every 10 seconds, but no changes to any AK Bond devices. Then I started toggling the fan light using the AK Bond device at first in the HS3 web interface, then in the HS Mobile app on my phone. Not sure which I was using at the time of the resulting error (see below). It seems you poll the Bond after each command/action sent to the Bond (or the Bond responds automatically) and if this happens when the polling interval timer attempts to poll the bond, an error occurs. It is also possible this is just a coincidence. I will try to duplicate it.

 [TABLE="cellspacing: 0"]
[TR]
[TD="align: left"][COLOR=#000000]Feb-05 12:46:55 PM[/COLOR][/TD]
 			[TD="align: left"] [/TD]
 			[TD="colspan: 3, align: left"][COLOR=#000000]Device Control[/COLOR][/TD]
 			[TD="colspan: 8, align: left"][COLOR=#000000]Device: Bond Sue's Room Sue's Fan.Light to ToggleLight (-8) by/from: CAPI Control Handler[/COLOR][/TD]
 		[/TR]
[/TABLE]
[TABLE="cellspacing: 0"]
[TR]
[TD="align: left"][COLOR=#000000]Feb-05 12:46:49 PM[/COLOR][/TD]
 			[TD="align: left"] [/TD]
 			[TD="colspan: 3, align: left"][COLOR=#000000]AK Bond[/COLOR][/TD]
 			[TD="colspan: 8, align: left"][COLOR=#000000][480]: {"light":1,"power":0,"speed":1,"direction":1,"_":"f44253c 1"}[/COLOR][/TD]
 		[/TR]
[/TABLE]
[TABLE="cellspacing: 0"]
[TR]
[TD="align: left"][COLOR=#000000]Feb-05 12:46:49 PM[/COLOR][/TD]
 			[TD="align: left"] [/TD]
 			[TD="colspan: 3, align: left"][COLOR=#000000]AK Bond[/COLOR][/TD]
 			[TD="colspan: 8, align: left"][COLOR=#000000][480]: Execute cmd: /v2/devices/2cc7d17f/state[/COLOR][/TD]
 		[/TR]
[/TABLE]
[TABLE="cellspacing: 0"]
[TR]
[TD="align: left"][COLOR=#000000]Feb-05 12:46:49 PM[/COLOR][/TD]
 			[TD="align: left"] [/TD]
 			[TD="colspan: 3, align: left"][COLOR=#000000]AK Bond[/COLOR][/TD]
 			[TD="colspan: 8, align: left"][COLOR=#000000][480]: No response '/v2/devices/2cc7d17f/actions/ToggleLight'[/COLOR][/TD]
 		[/TR]
[/TABLE]
[TABLE="cellspacing: 0"]
[TR]
[TD="align: left"][COLOR=#000000]Feb-05 12:46:49 PM[/COLOR][/TD]
 			[TD="align: left"] [/TD]
 			[TD="colspan: 3, align: left"][COLOR=#000000]AK Bond[/COLOR][/TD]
 			[TD="colspan: 8, align: left"][COLOR=#000000][480]: Execute cmd: /v2/devices/2cc7d17f/actions/ToggleLight[/COLOR][/TD]
 		[/TR]
[/TABLE]
[TABLE="cellspacing: 0"]
[TR]
[TD="align: left"][COLOR=#000000]Feb-05 12:46:49 PM[/COLOR][/TD]
 			[TD="align: left"] [/TD]
 			[TD="colspan: 3, align: left"][COLOR=#000000]Device Control[/COLOR][/TD]
 			[TD="colspan: 8, align: left"][COLOR=#000000]Device: Bond Sue's Room Sue's Fan.Light to ToggleLight (-8) by/from: CAPI Control Handler[/COLOR][/TD]
 		[/TR]
[/TABLE]
[TABLE="cellspacing: 0"]
[TR]
[TD="align: left"][COLOR=#000000]Feb-05 12:46:47 PM[/COLOR][/TD]
 			[TD="align: left"] [/TD]
 			[TD="colspan: 3, align: left"][COLOR=#000000]AK Bond[/COLOR][/TD]
 			[TD="colspan: 8, align: left"][COLOR=#000000][480]: {"light":0,"power":0,"speed":1,"direction":1,"_":"5bacc1d 5"}[/COLOR][/TD]
 		[/TR]
[/TABLE]
[TABLE="cellspacing: 0"]
[TR]
[TD="align: left"][COLOR=#000000]Feb-05 12:46:47 PM[/COLOR][/TD]
 			[TD="align: left"] [/TD]
 			[TD="colspan: 3, align: left"][COLOR=#000000]AK Bond[/COLOR][/TD]
 			[TD="colspan: 8, align: left"][COLOR=#000000][480]: Execute cmd: /v2/devices/2cc7d17f/state[/COLOR][/TD]
 		[/TR]
[/TABLE]
[TABLE="cellspacing: 0"]
[TR]
[TD="align: left"][COLOR=#000000]Feb-05 12:46:47 PM[/COLOR][/TD]
 			[TD="align: left"] [/TD]
 			[TD="colspan: 3, align: left"][COLOR=#000000]AK Bond[/COLOR][/TD]
 			[TD="colspan: 8, align: left"][COLOR=#000000][480]: {"light":0,"power":0,"speed":1,"_":"07ac5af3"}[/COLOR][/TD]
 		[/TR]
[/TABLE]
[TABLE="cellspacing: 0"]
[TR]
[TD="align: left"][COLOR=#000000]Feb-05 12:46:47 PM[/COLOR][/TD]
 			[TD="align: left"] [/TD]
 			[TD="colspan: 3, align: left"][COLOR=#000000]AK Bond[/COLOR][/TD]
 			[TD="colspan: 8, align: left"][COLOR=#000000][480]: Execute cmd: /v2/devices/68479fa2/state[/COLOR][/TD]
 		[/TR]
[/TABLE]
[TABLE="cellspacing: 0"]
[TR]
[TD="align: left"][COLOR=#FF0000]Feb-05 12:46:47 PM[/COLOR][/TD]
 			[TD="align: left"] [/TD]
 			[TD="colspan: 3, align: left"][COLOR=#FF0000]AK Bond ERROR[/COLOR][/TD]
 			[TD="colspan: 8, align: left"][COLOR=#FF0000][480]: [Bond Bridge] ZZCC69147 (192.168.0.135): Execute '/v2/devices/2cc7d17f/state': Status: 'Error' (ReceiveFailure). Error: 'Error getting response stream (ReadDoneAsync2): ReceiveFailure'.[/COLOR][/TD]
 		[/TR]
[/TABLE]
[TABLE="cellspacing: 0"]
[TR]
[TD="align: left"][COLOR=#000000]Feb-05 12:46:47 PM[/COLOR][/TD]
 			[TD="align: left"] [/TD]
 			[TD="colspan: 3, align: left"][COLOR=#000000]AK Bond[/COLOR][/TD]
 			[TD="colspan: 8, align: left"][COLOR=#000000][480]: No response '/v2/devices/2cc7d17f/state'[/COLOR][/TD]
 		[/TR]
[/TABLE]
[TABLE="cellspacing: 0"]
[TR]
[TD="align: left"][COLOR=#000000]Feb-05 12:46:47 PM[/COLOR][/TD]
 			[TD="align: left"] [/TD]
 			[TD="colspan: 3, align: left"][COLOR=#000000]AK Bond[/COLOR][/TD]
 			[TD="colspan: 8, align: left"][COLOR=#000000][480]: Execute cmd: /v2/devices/2cc7d17f/state[/COLOR][/TD]
 		[/TR]
[/TABLE]
[TABLE="cellspacing: 0"]
[TR]
[TD="align: left"][COLOR=#000000]Feb-05 12:46:47 PM[/COLOR][/TD]
 			[TD="align: left"] [/TD]
 			[TD="colspan: 3, align: left"][COLOR=#000000]AK Bond[/COLOR][/TD]
 			[TD="colspan: 8, align: left"][COLOR=#000000][480]: No response '/v2/devices/2cc7d17f/actions/ToggleLight'[/COLOR][/TD]
 		[/TR]
[/TABLE]
[TABLE="cellspacing: 0"]
[TR]
[TD="align: left"][COLOR=#000000]Feb-05 12:46:47 PM[/COLOR][/TD]
 			[TD="align: left"] [/TD]
 			[TD="colspan: 3, align: left"][COLOR=#000000]AK Bond[/COLOR][/TD]
 			[TD="colspan: 8, align: left"][COLOR=#000000][480]: Execute cmd: /v2/devices/2cc7d17f/actions/ToggleLight[/COLOR][/TD]
 		[/TR]
[/TABLE]
[TABLE="cellspacing: 0"]
[TR]
[TD="align: left"][COLOR=#000000]Feb-05 12:46:47 PM[/COLOR][/TD]
 			[TD="align: left"] [/TD]
 			[TD="colspan: 3, align: left"][COLOR=#000000]Device Control[/COLOR][/TD]
 			[TD="colspan: 8, align: left"][COLOR=#000000]Device: Bond Sue's Room Sue's Fan.Light to ToggleLight (-8) by/from: CAPI Control Handler[/COLOR][/TD]
 		[/TR]
[/TABLE]
[TABLE="cellspacing: 0"]
[TR]
[TD="align: left"][COLOR=#000000]Feb-05 12:46:45 PM[/COLOR][/TD]
 			[TD="align: left"] [/TD]
 			[TD="colspan: 3, align: left"][COLOR=#000000]AK Bond[/COLOR][/TD]
 			[TD="colspan: 8, align: left"][COLOR=#000000][480]: {"light":1,"power":0,"speed":1,"direction":1,"_":"b843968 6"}[/COLOR][/TD]
 		[/TR]
[/TABLE]

[CJMH]

I have now duplicated the issue. If I am careful to make an AK Bond device change in between polling requests everything works perfectly with no com errors. If I time it just right so the device change is processed just before the polling interval takes place a com error occurs. To make sure this was not just a coincidence I have successfully changed the device state about 30 times, with no errors, making sure that I do it well between interval polls.

Hope this helps figure it out.

[CJMH]

I've been looking through the logs when an com error occurs. I assume when you send a /v2/devices/68479fa2/state command you then attempt to read a status packet back from the Bond with a timeout condition set. Is a timeout what is causing the com error? If so, what control do you have over the timeout? I suspect you may be correct about the PI being slow, but not that polling every ten seconds or even every two seconds is a burden, but if when sending the /v2/devices/68479fa2/state command there is a lot of other activity going on, the timeout may expire before the processor has a chance to read the return packet if the timeout is too short. From what I can see in the log, the error occurs within a second (minimum granularity of the time stamp) of issuing /v2/devices/68479fa2/state command, so the timeout may be way too short for PI processor. I have noticed that when HS3 is busy processing events from a trigger the com errors occur in AK Bond. This would lend credence to a timeout being too short.

If my assumption is correct and the timeout is the issue, can you increase the timeout to a couple seconds and let me give that a try?

Thanks!

[alexbk66]

It seems you poll the Bond after each command/action sent to the Bond (or the Bond responds automatically) and if this happens when the polling interval timer attempts to poll the bond, an error occurs. It is also possible this is just a coincidence.

Yeah, there was a synchronisation issue you describe, but I thought I fixed it. I'll check.

And you are right, after each change from the plugin - I have to poll for state to verify that the change was applied correctly. Unfortunately Bond app doesn't return any confirmation.

Since I also have the timer polling - this status request above may be unnecessary, just after you click any button in HS - you will wait longer for confirmation from the Bond.

May be after manual polling I should reset the timer, so it fires after specified polling interval.

[alexbk66]

I've been looking through the logs when an com error occurs. I assume when you send a /v2/devices/68479fa2/state command you then attempt to read a status packet back from the Bond with a timeout condition set. Is a timeout what is causing the com error? If so, what control do you have over the timeout? I suspect you may be correct about the PI being slow, but not that polling every ten seconds or even every two seconds is a burden, but if when sending the /v2/devices/68479fa2/state command there is a lot of other activity going on, the timeout may expire before the processor has a chance to read the return packet if the timeout is too short. From what I can see in the log, the error occurs within a second (minimum granularity of the time stamp) of issuing /v2/devices/68479fa2/state command, so the timeout may be way too short for PI processor. I have noticed that when HS3 is busy processing events from a trigger the com errors occur in AK Bond. This would lend credence to a timeout being too short.

If my assumption is correct and the timeout is the issue, can you increase the timeout to a couple seconds and let me give that a try?

Thanks!

The syncronisation issue you describe was happening because when you control a device manually from HS - it creates a socket connection with the Bond app, and according to the Bond documentation it blocks until the action is physically executed - which may be a while. If the timer kicks in during this time - it creates a new socket connection which probably kills the old one. I added sync lock on the socket, but it's hard to test. I will add more syncronisation, probably the best is to kill the timer during communication, and then restart the timer.

[CJMH]

Here is another clue. If the log is ON and update interval 10 seconds I rarely see com errors. The only time I have seen a com error under this condition is when a command is sent to the Bond at nearly the same time as the periodic update occurs. However, if I disable AK Bond the logging I start seeing errors more frequently even when nothing else is going on. I would not have guess that.

[alexbk66]

Here is another clue. If the log is ON and update interval 10 seconds I rarely see com errors. The only time I have seen a com error under this condition is when a command is sent to the Bond at nearly the same time as the periodic update occurs. However, if I disable AK Bond the logging I start seeing errors more frequently even when nothing else is going on. I would not have guess that.

Hmm, that breaks the previous theory

[CJMH]

I am up for anything you want to try. Don't know what to say about turning logging off, but perhaps with the logging off it effects the timing of things that exacerbates whatever the problem/conflict is. critical sections (sync locking) can be tricky sometimes to think through all the possible side effects if things are at all complicated. But without it in the right places behavior like with turning off the log can cause the very problem I am seeing. In other words the delay caused by the logging eliminates the synchronization conflict that needs the sync lock. Just guessing here as I don;t have a complete understanding of the process.

I just want to say again I appreciate your efforts on this plugin. I am sold on HomeSeer and want to see it succeed with as many mainstream technologies as it can.

[alexbk66]

I think I found the problem - I wasn't deleting the timer after it fired, so you were getting multiple timer callbacks at random intervals. New timer was created every time you execute an action from HS.

Please try ver 3.0.0.21 (currently in BETA section). Hopefully it fixes all your issues. Not sure why it didn't manifest itself on Windows.

[CJMH]

Things are a little better, but I am still seeing both occasional com errors (if the log is off) and random polling after an error occurs. However, if I leave the log on, I have yest to see an error. And I have punished the system with rapid AK Bond devices changes.

I'm guessing the logging creates enough of a delay after the socket send that things work correctly. If I knew more about the process I might be able to help troubleshoot better. Are you using Sokcet.Send/Receive for the communication to the bond?