DevCat and Links with 5 Thermostats

[RMan54]

HS3 Pro 3.0.0.208 (Windows) on HomeTroller S6 Pro (Windows 7 Embedded), 32-bit, 4 GB
Hardware: Insteon Hub | Insteon 2441TH (5) | Z-Net
Plugins: Insteon | Insteon Thermostat (trial) | HSTouch Server| Kinect | Z-Wave | Restart
Kinect & Speaker Client on WinBooks TW700 and TW100 (both Windows 8.1)
HSTouch App/Client on iPhone (iOS) and WFTT07 (Android)

[RMan54]

It appears that the initialization process of the Insteon Thermostat plugin gets stuck when I restart HS3, and hence, the DevCat data are not set. It doesn't happen all the time and sometimes only a few of the 5 thermostats have missing DevCat data. I am starting to think that it's a timing issue of several intense plugins being initialized at the same time. I have to do some more testing but if I not initialize my 2 Kinect microphones, both on remote Windows 8 tablets, the Insteon Thermostat initialization process completes with all thermostats having DevCat data. I simply don't run the remote Kinect plugin exe's, but just the speaker client both remote tablets, and then restart HS3.
If it is really a timing issue, that could explain why the stuck initialization of the thermostat plugin isn't happening all the time. The remote initialization of the Kinects and the 5 thermostats (as opposed to only 1 or 2) may be a bit much for the HS3 startup process. And I am wondering whether it's possible to do a staggered startup of the plugins. For example, let the Thermostat plugin complete before another plugin can start. Any suggestions? its driving me crazy. Thanks.
Rene

[nfrobertson]

Hello Rene,

First, thank you for your very complete explanation of your current situation. It's very helpful to understand the entire picture.

As you may have seen in other threads, DEVCAT (device category) is a problem for the plugin when it is missing. The plugin uses this information to know how to send the correct commands to different Insteon thermostat types. At plugin startup, there is a poll issued to the configured thermostats to obtain their DEVCAT. The reply from this poll is a broadcast. It's clear that sometimes this broadcast is lost. Whether it's lost due to communications issues, or as you have pointed out, a heavy HS3 startup workload is unclear but the fact remains if it's missing then it's a problem.

Recently I attempted to address this with a timer thread that would repoll thermostats that were still missing DEVCAT 2 minutes after initial plungin startup. My guess is that is working for some with only one or a few thermostats but in your case with 5 and a heavy HS3 startup, perhaps this needs more thought. I have some ideas on a better more permanent fix for DEVCAT that should help you. In the mean time, polling any thermostats that are missing DEVCAT should resolve the issue temporarily (until HS3 reboot). I don't recommend starting over as you have a working system that we just need to fine tune for stability.

I do want to revisit your initial experience though. You mentioned as you added thermostats, you would have to use the update links at least once to get them correctly reporting to HS3? That indicates there was some level of communications issues right from the start. The thermostats are RF only devices. You mention you have 2 access points. Do you also have other dual-band Insteon devices / switches etc. in the house? If not you will probably want to add at least one near each of your 2441TH thermostats to ensure quality communications from them. The quality of the insteon network is the biggest unknown in all of this so anything that can be done to improve it should help.

Nathan

[RMan54]

I did some more testing and the root cause for the issue is certainly correct (as explained in previous post). Letting the startup cycle of the Insteon Thermostat plugin complete before manually starting up the remote Kinect plugin exe's works fine. I just need to automate that process.

The Thermostat plugin startup takes about 3 minutes to complete (5 thermostats), as you can see:
Nov-03 9:21:53 PM Insteon Thermostat Starting Up... Insteon Thermostat plug-in version = 3.0.3.4
...
Nov-03 9:24:57 PM Insteon Thermostat Post-startup timer to check for thermostat DEVCAT. All thermostats have DEVCAT. Timer exiting.

[nfrobertson]

I agree, that's one solution to work around the issue you're having. I think there are a couple more adjustments I can make that will also improve your situation without having to go through startup gyrations. In either case, if we both pursue fixes your system should be the better for it.

Nathan

[nfrobertson]

I should have also mentioned, that last log message is the 2-minute timer to check on DEVCAT after the plugin has started up. Sounds like it takes a minute for the actual plugin startup and then a couple more for that timer to double-check the DEVCAT. That was the fix in version 3.0.3.3 but the 2 minute timer is a hardcoded value right now. I have some ideas on improving that.

[nfrobertson]

When you were testing, did you get messages like below every 2 minutes until all your thermostats obtained their DEVCAT ? I just went back and looked at the post-startup timer implementation and it continues to check all configured thermostats every 2 minutes indefinitely until they all report back DEVCAT. In the example below I shortened the timer to 20 seconds in my test box and tweaked the test so it fails the DEVCAT confirmation check to confirm how the timer behaves.

11/4/2015 7:08:32 AM ~ Insteon Thermostat ~ ERRORS ~ Post-startup timer to check for thermostat DEVCAT: sh2441th still missing DEVCAT after 1 run(s). Requesting protocol again.
11/4/2015 7:08:32 AM ~ Insteon Thermostat ~ ERRORS ~ Post-startup timer to check for thermostat DEVCAT: t1700 still missing DEVCAT after 1 run(s). Requesting protocol again.
11/4/2015 7:08:32 AM ~ Insteon Thermostat ~ ERRORS ~ Post-startup timer to check for thermostat DEVCAT: zth2441 still missing DEVCAT after 1 run(s). Requesting protocol again.

11/4/2015 7:08:52 AM ~ Insteon Thermostat ~ ERRORS ~ Post-startup timer to check for thermostat DEVCAT: sh2441th still missing DEVCAT after 2 run(s). Requesting protocol again.
11/4/2015 7:08:52 AM ~ Insteon Thermostat ~ ERRORS ~ Post-startup timer to check for thermostat DEVCAT: t1700 still missing DEVCAT after 2 run(s). Requesting protocol again.
11/4/2015 7:08:52 AM ~ Insteon Thermostat ~ ERRORS ~ Post-startup timer to check for thermostat DEVCAT: zth2441 still missing DEVCAT after 2 run(s). Requesting protocol again.

11/4/2015 7:09:12 AM ~ Insteon Thermostat ~ ERRORS ~ Post-startup timer to check for thermostat DEVCAT: sh2441th still missing DEVCAT after 3 run(s). Requesting protocol again.
11/4/2015 7:09:12 AM ~ Insteon Thermostat ~ ERRORS ~ Post-startup timer to check for thermostat DEVCAT: t1700 still missing DEVCAT after 3 run(s). Requesting protocol again.
11/4/2015 7:09:12 AM ~ Insteon Thermostat ~ ERRORS ~ Post-startup timer to check for thermostat DEVCAT: zth2441 still missing DEVCAT after 3 run(s). Requesting protocol again.

This is the timer that ultimately produces the line you reported when it's finally successful and stops running:

Nov-03 9:24:57 PM Insteon Thermostat Post-startup timer to check for thermostat DEVCAT. All thermostats have DEVCAT. Timer exiting.

Nathan

[RMan54]

Hi Nathan,

I appreciate your responses and your efforts to make this better. I like the plugin and the simplicity of the programs.

First, I like to address your comments about potential communications issues. I have 53 internal Insteon devices, most of which are dual-band SwithLinc and LampLinc dimmers. And I am using the Insteon Hub 2242-222. No problems with communications. When I had a smaller system, I had some issues that were solved with the 2 access points (still in use) and putting a filter on the power plug of my garage refrigerator. But of course, you have a valid point about having to update the links means that there may be communication issues. Since the remote Kinects gave me problems during initialization of the plugin after an HS3 restart, I really should test registering a thermostat without the remote Kinects trying to connect. It's on my list to do.

Then, to answer your question, I don't see the post-startup missing DevCat errors. What I see with the remote Kinects active during HS3 restart is repeated messages of "Insteon Thermostat ~ DEBUG ~ Initializing...". And the same in the HS3 plugin manager (image attached). None of the thermostats have set DevCat data (image attached).

I also have attached the InsteonThermostatDebug log. There are two HS3 sessions in there. One starting at 1:32pm with a successful init of the 5 thermostats (valid DevCat data), and an unregistering of the 5 thermostats when I shut down HS3. The 2nd HS3 session started at 1:35pm but didn't initialize successfully (showing the Debug Initialization repeatedly). In both sessions, I had the remote Kinect plugin's active (and the Speaker clients as well). The remote Kinect plugins are trying to reconnect to HS3 every 60 seconds. Maybe you can figure out what the differences are between both sessions. Both sessions (HS3 stop and restart) in the same situation but the 1st was ok and the 2nd not ok. Thank so much!





InsteonThermostatDebug.txt

[nfrobertson]

That log is very interesting. It appears that the plugin is stuck in/after a call to register the "Family Room" thermostat and never recovers from that "Initializing..." state. I'll need to research this more.

[RMan54]

Nathan, this is interesting indeed. I went back and looked for that session at the HS3 log because that log has other entries than just the Thermostat Plugin entries. The last Thermostat entry before the "Debug ~ Initializing" stuck looping was at 1:36:32 PM (unregister Family Room thermostat). I looked at the HS3 log from then on (see attached partial log). Just what I expected... The Kinect stuff started initializing and is rather busy in the log. Supporting evidence that this is a timing/startup resource issue?
I will go back now and check the log from the successful HS3 session, and see where the Kinect stuff initializes there.
Thanks
Rene

[RMan54]

Nathan: Here is my analysis of the successful session. There are 2 back-to-back entries in the Thermostat log, as follows:
11/4/2015 1:32:27 PM ~ Insteon Thermostat ~ DEBUG ~ SQLite DB version = 3.7.17
11/4/2015 1:32:32 PM ~ Insteon Thermostat ~ DEBUG ~ HS3 still starting...
And all the Kinect init stuff happens in between. The partial HS3 log is attached. After that, the Thermostat plugin reports several "DEBUG ~ Initializing..." messages but the process goes on and completes just fine. I suspect that if the Kinect stuff initializes outside of the Thermostat plugin loop of unregistering/registering, etc., that all is fine. Only when the remote Kinects initialize within that loop, the loops gets stuck with no DevCats getting set.

When the remote Kinects get disconnected (because of an HS3 restart in this case), they try to reconnect every 60 seconds (that number can be changed). Depending on that timing and the timing of the HS3 restarts, the initialization processes are pretty much different every time with regards to timing after an HS3 restart.

Assuming that this analysis is correct, the question is how to untangle both init processes by design. Can you program this loop without allowing anyone else in?
Thanks again for looking at that.
Rene

[nfrobertson]

This is good analysis. Unfortunately I'm at a bit of a loss currently. My Insteon Thermostat plugin loops over the list of thermostats from the INI file at startup calling unregister then register with Mark's Insteon plugin. Of course HS3 is a multi-process, multi-threaded system so other things are going on as well. Somehow while I'm attempting to register with Mark's plugin things seem to simply stop and my plugin never finishes. From a previous log you provided I could see that even though my plugin was stuck in "Initializing..." you started to get back humidity updates on the InsteonRcv() method so I know the plugin itself is still working. I'm wondering if there was some caught but discarded exception somewhere leaving my plugin in a not fully Init state?

Let me think on this a while and get back with you.

[RMan54]

Not sure if it makes a difference but I am running Mark's plugin version 3.0.5.20. I was planning to upgrade today to the latest beta.

[nfrobertson]

I would stick with 3.0.5.20 right now. Adding the latest beta only invites more variables. I should have a test build for you later today with some additional error handling/logging during my Init routies. We'll use the updater_override process so you can load that separate from the regular updater stream.

Nathan

[nfrobertson]

Rene,

I just posted 3.0.3.6 but it's not part of the regular updater stream yet. You can install to your HS3 directory an updater_override.txt which you can get at the link below. This will allow you to use the Manage page to download 3.0.3.6. Be sure to remove or rename the updater_override.txt afterwards so it doesn't block other updates for you.

http://www.kazteel.com/HomeSeer3/dev...r_override.txt

I put additional try/except checks around the unregister / register thermostats section to hopefully help with the unknown Init... sticking we are getting. Please give this a try and see if anything improves or simply stays the same.

Nathan