Plugin won't initialize at startup

[w.vuyk]

That indeed makes sense I guess

[bsobel]

The only HSevent the plugin handles is indeed a CONFIG_Change, Which in the plugin is evaluated to see if the changed device is of the plugin. Sounds to me that HS is offering all devices as a change during startup?
Wim

Forgot to comment on this. I need to verify with Rich, what I *think* is occurring is that HS keeps a queue of changes and replays them to use as a kind of change log (without the intermediary changes) if your plugin has not been running to catch you up. Again, I need to verify that, but I have seen some startups where I get lots of changes and others where I get none or only a few...

[bsobel]

In that case the logline of hs is not really describing the issue when it is not only "Events". It should just mention the "plugin queue overloaded" or similar?

11:56:18:2096:[Warning]->Dropping event callbacks due to full queue (Type: CONFIG_CHANGE) (2000 entries), system may be too busy, plugins and HSTouch may not receive all device updates

The first GetDeviceEnumerator in the plugin is outside the INITIO, INITIO does basic initialisation of the database and then exits with starting a timerroutine for the plugin. This routine discovers it is a maiden start and gets bridges and other devices.

FYI, put everything I currently know into one thread: https://forums.homeseer.com/forum/de...lugins-for-hs3

[w.vuyk]

In that case the logline of hs is not really describing the issue when it is not only "Events". It should just mention the "plugin queue overloaded" or similar?

11:56:18:2096:[Warning]->Dropping event callbacks due to full queue (Type: CONFIG_CHANGE) (2000 entries), system may be too busy, plugins and HSTouch may not receive all device updates

The first GetDeviceEnumerator in the plugin is outside the INITIO, INITIO does basic initialisation of the database and then exits with starting a timerroutine for the plugin. This routine discovers it is a maiden start and gets bridges and other devices.

[bsobel]

The only HSevent the plugin handles is indeed a CONFIG_Change, Which in the plugin is evaluated to see if the changed device is of the plugin. Sounds to me that HS is offering all devices as a change during startup? If it is a device owned by the plugin, it is handled in a seperate thread.
If the plugin indeed handles the device change, a logline is created on level debug.
I think the question is here why HS offers all devices (2000 of 3000?) to a plugin that won't do anything with it. I am a bit doubting if HS would offer those queued events all to the plugin, I think it just don't know where to deliver them if my plugin is the only one?
Wim

An interesting development in this. As I have gone deeper down the rabbit hole, I have come to realize that the HomeSeer server side has a single thread per plugin processing RPC calls. What this means is that say in your InitIO you launch a background thread. That background thread calls GetDeviceEnumerator() (which can take well over a minute on my system), and then you get an HSEvent. If you make a call in that event, say GetDeviceString(), that call is sent to the server and sits in the queue which is not being drained as the thread is executing the GetDeviceEnumerator() call still. So in effect, regardless of the number of threads in your plugin, all calls to HS go into a single serial queue. This helps explain why some of the event issues are occurring, you may be making what should be a light weight call but in actuality it could hang for seconds to minutes. I am changing the code (Rich was nice enough to send me the com code, so I have been doing some open heart surgery to figure some of these issues out) to use a thread pool so calls will get dispatched and not held up as today. Will be interesting to retest all this with that in place.

[w.vuyk]

An update, we are still fighting the root cause but are very close. We now know exactly where the timeout is occurring in the SCS code which results in the NULL internally that gets propagated as the NPE. However, it may not be a timeout as much as a deadlock Rich and I are testing this now, I thought InitIO in conjunction with GetDeviceEnumerator caused it but it may actually be HSEvent taking a lock as InitIO doesn't seem to have any shared locks around that explains it. That all said, not stopping until this is dead!

Had two requests for you; I see that when JowiHue starts even if its the only plugin running on the system some events are dropped. This usually means that HSEvent has done some long running thing, as 2000 events can happen very very quickly at startup a delay of just a few seconds can cause this. Can you look at your HSEvent logic and see if there are things you can defer to a queue instead of processing in line?

Startup:
Connected, waiting to be initialized...
11:56:08:1651:[Starting Plug-In]->Initializing plugin JowiHue ...
11:56:09:3469:[JowiHue]->Starting plugin JowiHue 2.0.4.6 on Linux
11:56:10:2997:[JowiHue]->InitIO:Plugin basic initialisation done
11:56:10:3318:[Starting Plug-In]->Plugin JowiHue started successfully in 2166 milliseconds
11:56:10:3656:[Starting Plug-In]->JowiHue loaded in 3405 milliseconds
11:56:10:3757:[Plug-In]->Finished initializing plug-in JowiHue
11:56:18:2096:[Warning]->Dropping event callbacks due to full queue (Type: CONFIG_CHANGE) (2000 entries), system may be too busy, plugins and HSTouch may not receive all device updates
Slow call: Process: HSPI_JowiHue Thread: 10:Thread Pool Worker Message: ScsRemoteInvokeMessage: IHSApplication.GetDeviceEnumerator(...) Timeout: 60000
Slow call: Process: HSPI_JowiHue Thread: 3: Message: ScsRemoteInvokeMessage: IHSApplication.GetDeviceByRef(...) Timeout: 60000
Slow call: Process: HSConsole Thread: 17: Message: ScsRemoteInvokeMessage: IAllRemoteAPI.HSEvent(...) Timeout: 480000
Slow call: Process: HSConsole Thread: 11:Thread Pool Worker Message: ScsRemoteInvokeMessage: IAllRemoteAPI.InterfaceStatus(...) Timeout: 480000
Slow call: Process: HSConsole Thread: 32:Thread Pool Worker Message: ScsRemoteInvokeMessage: IAllRemoteAPI.InterfaceStatus(...) Timeout: 480000
Slow call: Process: HSConsole Thread: 89:Check Interfaces Message: ScsRemoteInvokeMessage: IAllRemoteAPI.get_Name(...) Timeout: 480000
11:57:00:2431:[Event]->Event Trigger "Delayed Actions System Startup Notification (Delayed Event) - 1"
11:57:00:2705:[Event]->Event Trigger "Maintenance System Startup Notification"

Bill,

The only HSevent the plugin handles is indeed a CONFIG_Change, Which in the plugin is evaluated to see if the changed device is of the plugin. Sounds to me that HS is offering all devices as a change during startup? If it is a device owned by the plugin, it is handled in a seperate thread.
If the plugin indeed handles the device change, a logline is created on level debug.
I think the question is here why HS offers all devices (2000 of 3000?) to a plugin that won't do anything with it. I am a bit doubting if HS would offer those queued events all to the plugin, I think it just don't know where to deliver them if my plugin is the only one?

In the plugin I do limit the requested callback with

callback.RegisterEventCB(Enums.HSEvent.CONFIG_CHANGE, IFACE_NAME, "")

So would really only expect the plugins devices to be offered, and even then, nothing changed yet, so why offer it?

Guess this might need some viewing?

Will be back on the shutdown issue later

Wim

[bsobel]

Bill,

That indeed clarifies the issue, also for my understanding. Thanks for diving this deep to get to the roots!

Wim

An update, we are still fighting the root cause but are very close. We now know exactly where the timeout is occurring in the SCS code which results in the NULL internally that gets propagated as the NPE. However, it may not be a timeout as much as a deadlock Rich and I are testing this now, I thought InitIO in conjunction with GetDeviceEnumerator caused it but it may actually be HSEvent taking a lock as InitIO doesn't seem to have any shared locks around that explains it. That all said, not stopping until this is dead!

Had two requests for you; I see that when JowiHue starts even if its the only plugin running on the system some events are dropped. This usually means that HSEvent has done some long running thing, as 2000 events can happen very very quickly at startup a delay of just a few seconds can cause this. Can you look at your HSEvent logic and see if there are things you can defer to a queue instead of processing in line?

Startup:
Connected, waiting to be initialized...
11:56:08:1651:[Starting Plug-In]->Initializing plugin JowiHue ...
11:56:09:3469:[JowiHue]->Starting plugin JowiHue 2.0.4.6 on Linux
11:56:10:2997:[JowiHue]->InitIO:Plugin basic initialisation done
11:56:10:3318:[Starting Plug-In]->Plugin JowiHue started successfully in 2166 milliseconds
11:56:10:3656:[Starting Plug-In]->JowiHue loaded in 3405 milliseconds
11:56:10:3757:[Plug-In]->Finished initializing plug-in JowiHue
11:56:18:2096:[Warning]->Dropping event callbacks due to full queue (Type: CONFIG_CHANGE) (2000 entries), system may be too busy, plugins and HSTouch may not receive all device updates
Slow call: Process: HSPI_JowiHue Thread: 10:Thread Pool Worker Message: ScsRemoteInvokeMessage: IHSApplication.GetDeviceEnumerator(...) Timeout: 60000
Slow call: Process: HSPI_JowiHue Thread: 3: Message: ScsRemoteInvokeMessage: IHSApplication.GetDeviceByRef(...) Timeout: 60000
Slow call: Process: HSConsole Thread: 17: Message: ScsRemoteInvokeMessage: IAllRemoteAPI.HSEvent(...) Timeout: 480000
Slow call: Process: HSConsole Thread: 11:Thread Pool Worker Message: ScsRemoteInvokeMessage: IAllRemoteAPI.InterfaceStatus(...) Timeout: 480000
Slow call: Process: HSConsole Thread: 32:Thread Pool Worker Message: ScsRemoteInvokeMessage: IAllRemoteAPI.InterfaceStatus(...) Timeout: 480000
Slow call: Process: HSConsole Thread: 89:Check Interfaces Message: ScsRemoteInvokeMessage: IAllRemoteAPI.get_Name(...) Timeout: 480000
11:57:00:2431:[Event]->Event Trigger "Delayed Actions System Startup Notification (Delayed Event) - 1"
11:57:00:2705:[Event]->Event Trigger "Maintenance System Startup Notification"

Second issue is more maintenance, but you seem like the same type of coder I am so wanted you to know. Looks like when you receive the shutdown call you may still have a thread in a loop doing work that is not checking if the plugin is active. Now with additional exception logging in the communication framework this is what i see at shutdown (notice ShutdownIO is called, but thread 10 is calling GetDeviceByRef quite a bit post that). Since the server is disconnected the calls fail fairly quickly, but figured you might want to know in case you have a shared shutdown flag or cancellation token you could be checking in that thread.

Slow call: Process: HSPI_JowiHue Thread: 3: Message: ScsRemoteInvokeMessage: IHSApplication.GetDeviceByRef(...) Timeout: 60000
Slow call: Process: HSPI_JowiHue Thread: 10:Thread Pool Worker Message: ScsRemoteInvokeMessage: IHSApplication.GetDeviceEnumerator(...) Timeout: 60000
Slow call: Process: HSConsole Thread: 17: Message: ScsRemoteInvokeMessage: IAllRemoteAPI.HSEvent(...) Timeout: 480000
Slow call: Process: HSConsole Thread: 9:Thread Pool Worker Message: ScsRemoteInvokeMessage: IAllRemoteAPI.InterfaceStatus(...) Timeout: 480000
Slow call: Process: HSConsole Thread: 89:Check Interfaces Message: ScsRemoteInvokeMessage: IAllRemoteAPI.get_Name(...) Timeout: 480000
11:58:09:1449:[JowiHue]->Error: (ShutdownIO)::Error ending JowiHue Plug-In
Shutting down plugin
**** Exception Process: HSPI_JowiHue Thread: 10:Thread Pool Worker Message: ScsRemoteInvokeMessage: IHSApplication.GetDeviceByRef(...) Timeout: 60000 Exception: System.Exception: Client is not connected to the server communication state: Disconnected
at HSCF.Communication.Scs.Client.ScsClientBase.SendMessage (HSCF.Communication.Scs.Communication.Messages.IScsMessage message) [0x0001d] in <90ce3ee650ce43fd8757f2f759091405>:0
at HSCF.Communication.ScsServices.Communication.RequestReplyMes senger`1[T].SendMessageAndWaitForResponse (HSCF.Communication.Scs.Communication.Messages.IScsMessage message, System.Int32 timeoutMilliseconds) [0x000c0] in <90ce3ee650ce43fd8757f2f759091405>:0
at HSCF.Communication.ScsServices.Communication.RequestReplyMes senger`1[T].SendMessageAndWaitForResponse (HSCF.Communication.Scs.Communication.Messages.IScsMessage message) [0x00007] in <90ce3ee650ce43fd8757f2f759091405>:0
ScsServiceClient:Client_Disconnected Process: HSPI_JowiHue Thread: 7: Sender: HSCF.Communication.Scs.Client.Tcp.ScsTcpClient Args: System.EventArgs
Error SendInvokeResponse: Client is not connected to the server communication state: Disconnected
ScsServiceClient:Client_Disconnected Process: HSPI_JowiHue Thread: 5: Sender: HSCF.Communication.Scs.Client.Tcp.ScsTcpClient Args: System.EventArgs
Disconnected from server - client
**** Exception Process: HSPI_JowiHue Thread: 10:Thread Pool Worker Message: ScsRemoteInvokeMessage: IHSApplication.GetDeviceByRef(...) Timeout: 60000 Exception: System.Exception: Client is not connected to the server communication state: Disconnected
at HSCF.Communication.Scs.Client.ScsClientBase.SendMessage (HSCF.Communication.Scs.Communication.Messages.IScsMessage message) [0x0001d] in <90ce3ee650ce43fd8757f2f759091405>:0
at HSCF.Communication.ScsServices.Communication.RequestReplyMes senger`1[T].SendMessageAndWaitForResponse (HSCF.Communication.Scs.Communication.Messages.IScsMessage message, System.Int32 timeoutMilliseconds) [0x000c0] in <90ce3ee650ce43fd8757f2f759091405>:0
at HSCF.Communication.ScsServices.Communication.RequestReplyMes senger`1[T].SendMessageAndWaitForResponse (HSCF.Communication.Scs.Communication.Messages.IScsMessage message) [0x00007] in <90ce3ee650ce43fd8757f2f759091405>:0
**** Exception Process: HSPI_JowiHue Thread: 10:Thread Pool Worker Message: ScsRemoteInvokeMessage: IHSApplication.GetDeviceByRef(...) Timeout: 60000 Exception: System.Exception: Client is not connected to the server communication state: Disconnected
at HSCF.Communication.Scs.Client.ScsClientBase.SendMessage (HSCF.Communication.Scs.Communication.Messages.IScsMessage message) [0x0001d] in <90ce3ee650ce43fd8757f2f759091405>:0
at HSCF.Communication.ScsServices.Communication.RequestReplyMes senger`1[T].SendMessageAndWaitForResponse (HSCF.Communication.Scs.Communication.Messages.IScsMessage message, System.Int32 timeoutMilliseconds) [0x000c0] in <90ce3ee650ce43fd8757f2f759091405>:0
at HSCF.Communication.ScsServices.Communication.RequestReplyMes senger`1[T].SendMessageAndWaitForResponse (HSCF.Communication.Scs.Communication.Messages.IScsMessage message) [0x00007] in <90ce3ee650ce43fd8757f2f759091405>:0
**** Exception Process: HSPI_JowiHue Thread: 10:Thread Pool Worker Message: ScsRemoteInvokeMessage: IHSApplication.GetDeviceByRef(...) Timeout: 60000 Exception: System.Exception: Client is not connected to the server communication state: Disconnected
at HSCF.Communication.Scs.Client.ScsClientBase.SendMessage (HSCF.Communication.Scs.Communication.Messages.IScsMessage message) [0x0001d] in <90ce3ee650ce43fd8757f2f759091405>:0
at HSCF.Communication.ScsServices.Communication.RequestReplyMes senger`1[T].SendMessageAndWaitForResponse (HSCF.Communication.Scs.Communication.Messages.IScsMessage message, System.Int32 timeoutMilliseconds) [0x000c0] in <90ce3ee650ce43fd8757f2f759091405>:0
at HSCF.Communication.ScsServices.Communication.RequestReplyMes senger`1[T].SendMessageAndWaitForResponse (HSCF.Communication.Scs.Communication.Messages.IScsMessage message) [0x00007] in <90ce3ee650ce43fd8757f2f759091405>:0
**** Exception Process: HSPI_JowiHue Thread: 10:Thread Pool Worker Message: ScsRemoteInvokeMessage: IHSApplication.GetDeviceByRef(...) Timeout: 60000 Exception: System.Exception: Client is not connected to the server communication state: Disconnected
at HSCF.Communication.Scs.Client.ScsClientBase.SendMessage (HSCF.Communication.Scs.Communication.Messages.IScsMessage message) [0x0001d] in <90ce3ee650ce43fd8757f2f759091405>:0
at HSCF.Communication.ScsServices.Communication.RequestReplyMes senger`1[T].SendMessageAndWaitForResponse (HSCF.Communication.Scs.Communication.Messages.IScsMessage message, System.Int32 timeoutMilliseconds) [0x000c0] in <90ce3ee650ce43fd8757f2f759091405>:0
at HSCF.Communication.ScsServices.Communication.RequestReplyMes senger`1[T].SendMessageAndWaitForResponse (HSCF.Communication.Scs.Communication.Messages.IScsMessage message) [0x00007] in <90ce3ee650ce43fd8757f2f759091405>:0
**** Exception Process: HSPI_JowiHue Thread: 10:Thread Pool Worker Message: ScsRemoteInvokeMessage: IHSApplication.GetDeviceByRef(...) Timeout: 60000 Exception: System.Exception: Client is not connected to the server communication state: Disconnected
at HSCF.Communication.Scs.Client.ScsClientBase.SendMessage (HSCF.Communication.Scs.Communication.Messages.IScsMessage message) [0x0001d] in <90ce3ee650ce43fd8757f2f759091405>:0
at HSCF.Communication.ScsServices.Communication.RequestReplyMes senger`1[T].SendMessageAndWaitForResponse (HSCF.Communication.Scs.Communication.Messages.IScsMessage message, System.Int32 timeoutMilliseconds) [0x000c0] in <90ce3ee650ce43fd8757f2f759091405>:0
at HSCF.Communication.ScsServices.Communication.RequestReplyMes senger`1[T].SendMessageAndWaitForResponse (HSCF.Communication.Scs.Communication.Messages.IScsMessage message) [0x00007] in <90ce3ee650ce43fd8757f2f759091405>:0
**** Exception Process: HSPI_JowiHue Thread: 10:Thread Pool Worker Message: ScsRemoteInvokeMessage: IHSApplication.GetDeviceByRef(...) Timeout: 60000 Exception: System.Exception: Client is not connected to the server communication state: Disconnected
at HSCF.Communication.Scs.Client.ScsClientBase.SendMessage (HSCF.Communication.Scs.Communication.Messages.IScsMessage message) [0x0001d] in <90ce3ee650ce43fd8757f2f759091405>:0
at HSCF.Communication.ScsServices.Communication.RequestReplyMes senger`1[T].SendMessageAndWaitForResponse (HSCF.Communication.Scs.Communication.Messages.IScsMessage message, System.Int32 timeoutMilliseconds) [0x000c0] in <90ce3ee650ce43fd8757f2f759091405>:0
at HSCF.Communication.ScsServices.Communication.RequestReplyMes senger`1[T].SendMessageAndWaitForResponse (HSCF.Communication.Scs.Communication.Messages.IScsMessage message) [0x00007] in <90ce3ee650ce43fd8757f2f759091405>:0
**** Exception Process: HSPI_JowiHue Thread: 10:Thread Pool Worker Message: ScsRemoteInvokeMessage: IHSApplication.GetDeviceByRef(...) Timeout: 60000 Exception: System.Exception: Client is not connected to the server communication state: Disconnected
at HSCF.Communication.Scs.Client.ScsClientBase.SendMessage (HSCF.Communication.Scs.Communication.Messages.IScsMessage message) [0x0001d] in <90ce3ee650ce43fd8757f2f759091405>:0
at HSCF.Communication.ScsServices.Communication.RequestReplyMes senger`1[T].SendMessageAndWaitForResponse (HSCF.Communication.Scs.Communication.Messages.IScsMessage message, System.Int32 timeoutMilliseconds) [0x000c0] in <90ce3ee650ce43fd8757f2f759091405>:0
at HSCF.Communication.ScsServices.Communication.RequestReplyMes senger`1[T].SendMessageAndWaitForResponse (HSCF.Communication.Scs.Communication.Messages.IScsMessage message) [0x00007] in <90ce3ee650ce43fd8757f2f759091405>:0
**** Exception Process: HSPI_JowiHue Thread: 10:Thread Pool Worker Message: ScsRemoteInvokeMessage: IHSApplication.GetDeviceByRef(...) Timeout: 60000 Exception: System.Exception: Client is not connected to the server communication state: Disconnected
at HSCF.Communication.Scs.Client.ScsClientBase.SendMessage (HSCF.Communication.Scs.Communication.Messages.IScsMessage message) [0x0001d] in <90ce3ee650ce43fd8757f2f759091405>:0
at HSCF.Communication.ScsServices.Communication.RequestReplyMes senger`1[T].SendMessageAndWaitForResponse (HSCF.Communication.Scs.Communication.Messages.IScsMessage message, System.Int32 timeoutMilliseconds) [0x000c0] in <90ce3ee650ce43fd8757f2f759091405>:0
at HSCF.Communication.ScsServices.Communication.RequestReplyMes senger`1[T].SendMessageAndWaitForResponse (HSCF.Communication.Scs.Communication.Messages.IScsMessage message) [0x00007] in <90ce3ee650ce43fd8757f2f759091405>:0
**** Exception Process: HSPI_JowiHue Thread: 10:Thread Pool Worker Message: ScsRemoteInvokeMessage: IHSApplication.GetDeviceByRef(...) Timeout: 60000 Exception: System.Exception: Client is not connected to the server communication state: Disconnected
at HSCF.Communication.Scs.Client.ScsClientBase.SendMessage (HSCF.Communication.Scs.Communication.Messages.IScsMessage message) [0x0001d] in <90ce3ee650ce43fd8757f2f759091405>:0
at HSCF.Communication.ScsServices.Communication.RequestReplyMes senger`1[T].SendMessageAndWaitForResponse (HSCF.Communication.Scs.Communication.Messages.IScsMessage message, System.Int32 timeoutMilliseconds) [0x000c0] in <90ce3ee650ce43fd8757f2f759091405>:0
at HSCF.Communication.ScsServices.Communication.RequestReplyMes senger`1[T].SendMessageAndWaitForResponse (HSCF.Communication.Scs.Communication.Messages.IScsMessage message) [0x00007] in <90ce3ee650ce43fd8757f2f759091405>:0
**** Exception Process: HSPI_JowiHue Thread: 10:Thread Pool Worker Message: ScsRemoteInvokeMessage: IHSApplication.GetDeviceByRef(...) Timeout: 60000 Exception: System.Exception: Client is not connected to the server communication state: Disconnected
at HSCF.Communication.Scs.Client.ScsClientBase.SendMessage (HSCF.Communication.Scs.Communication.Messages.IScsMessage message) [0x0001d] in <90ce3ee650ce43fd8757f2f759091405>:0
at HSCF.Communication.ScsServices.Communication.RequestReplyMes senger`1[T].SendMessageAndWaitForResponse (HSCF.Communication.Scs.Communication.Messages.IScsMessage message, System.Int32 timeoutMilliseconds) [0x000c0] in <90ce3ee650ce43fd8757f2f759091405>:0
at HSCF.Communication.ScsServices.Communication.RequestReplyMes senger`1[T].SendMessageAndWaitForResponse (HSCF.Communication.Scs.Communication.Messages.IScsMessage message) [0x00007] in <90ce3ee650ce43fd8757f2f759091405>:0
**** Exception Process: HSPI_JowiHue Thread: 10:Thread Pool Worker Message: ScsRemoteInvokeMessage: IHSApplication.GetDeviceByRef(...) Timeout: 60000 Exception: System.Exception: Client is not connected to the server communication state: Disconnected
at HSCF.Communication.Scs.Client.ScsClientBase.SendMessage (HSCF.Communication.Scs.Communication.Messages.IScsMessage message) [0x0001d] in <90ce3ee650ce43fd8757f2f759091405>:0
at HSCF.Communication.ScsServices.Communication.RequestReplyMes senger`1[T].SendMessageAndWaitForResponse (HSCF.Communication.Scs.Communication.Messages.IScsMessage message, System.Int32 timeoutMilliseconds) [0x000c0] in <90ce3ee650ce43fd8757f2f759091405>:0
at HSCF.Communication.ScsServices.Communication.RequestReplyMes senger`1[T].SendMessageAndWaitForResponse (HSCF.Communication.Scs.Communication.Messages.IScsMessage message) [0x00007] in <90ce3ee650ce43fd8757f2f759091405>:0
**** Exception Process: HSPI_JowiHue Thread: 10:Thread Pool Worker Message: ScsRemoteInvokeMessage: IHSApplication.GetDeviceByRef(...) Timeout: 60000 Exception: System.Exception: Client is not connected to the server communication state: Disconnected
at HSCF.Communication.Scs.Client.ScsClientBase.SendMessage (HSCF.Communication.Scs.Communication.Messages.IScsMessage message) [0x0001d] in <90ce3ee650ce43fd8757f2f759091405>:0
at HSCF.Communication.ScsServices.Communication.RequestReplyMes senger`1[T].SendMessageAndWaitForResponse (HSCF.Communication.Scs.Communication.Messages.IScsMessage message, System.Int32 timeoutMilliseconds) [0x000c0] in <90ce3ee650ce43fd8757f2f759091405>:0
at HSCF.Communication.ScsServices.Communication.RequestReplyMes senger`1[T].SendMessageAndWaitForResponse (HSCF.Communication.Scs.Communication.Messages.IScsMessage message) [0x00007] in <90ce3ee650ce43fd8757f2f759091405>:0

(Repeats for awhile but the forum has a post length limit so reducing the list)

[bsobel]

I am having a similar issue with the latest BETA 2.0.4.8.

Sep-04 23:09:23 Info Plugin JowiHue has connected. IP:127.0.0.1:52615
Sep-04 23:09:23 Warning I/O interface JowiHue is down, executable is not running, restarting ...
Sep-04 23:09:06 Info Plugin JowiHue with instance: has disconnected
Sep-04 23:09:06 JowiHue Initialisation bridgedevices did not complete correctly, exiting plugin
Sep-04 23:09:06 JowiHue Error: (FindBridgesSelf)::Object reference not set to an instance of an object
Sep-04 23:08:54 JowiHue Importing SensorModels
Sep-04 23:08:54 JowiHue Importing SensorTypes
Sep-04 23:08:54 JowiHue Importing lampTypes
Sep-04 23:08:53 Plug-In Finished initializing plug-in JowiHue
Sep-04 23:08:53 Starting Plug-In JowiHue loaded in 500 milliseconds
Sep-04 23:08:53 Starting Plug-In Plugin JowiHue started successfully in 238 milliseconds
Sep-04 23:08:53 JowiHue InitIO:Plugin basic initialisation done
Sep-04 23:08:53 JowiHue Starting plugin JowiHue 2.0.4.8 on Linux

I also sometimes see a: "/usr/local/HomeSeer/html/JowiHue_Configuration" not found error.

I am on centos 7.1 x64. Mono v6

Sounds like you are running into what I've been fighting. This is most likely not a JowiHue issue, its a HS core issue. I am literally in the code debugging it now working with Rich on a fix.

I am having a similar issue with the latest BETA 2.0.4.8.

Sep-04 23:09:23         Info    Plugin JowiHue has connected. IP:127.0.0.1:52615
Sep-04 23:09:23         Warning    I/O interface JowiHue is down, executable is not running, restarting ...
Sep-04 23:09:06         Info    Plugin JowiHue with instance: has disconnected
Sep-04 23:09:06         JowiHue    Initialisation bridgedevices did not complete correctly, exiting plugin
Sep-04 23:09:06         JowiHue    Error: (FindBridgesSelf)::Object reference not set to an instance of an object
Sep-04 23:08:54         JowiHue    Importing SensorModels
Sep-04 23:08:54         JowiHue    Importing SensorTypes
Sep-04 23:08:54         JowiHue    Importing lampTypes
Sep-04 23:08:53         Plug-In    Finished initializing plug-in JowiHue
Sep-04 23:08:53         Starting Plug-In    JowiHue loaded in 500 milliseconds
Sep-04 23:08:53         Starting Plug-In    Plugin JowiHue started successfully in 238 milliseconds
Sep-04 23:08:53         JowiHue    InitIO:Plugin basic initialisation done
Sep-04 23:08:53         JowiHue    Starting plugin JowiHue 2.0.4.8 on Linux

I also sometimes see a: "/usr/local/HomeSeer/html/JowiHue_Configuration" not found error.

I am on centos 7.1 x64. Mono v6

[w.vuyk]

Bill,

That indeed clarifies the issue, also for my understanding. Thanks for diving this deep to get to the roots!

Wim

[bsobel]

A further update, Rich was kind enough to get me the code I needed to debug. Internally there is a single threaded queue of requests from plugins for the server to process, it appears this queue stalls during InitIO and at least GetDeviceEnumerator() I suspect they share a lock object. If the total time spent waiting in the queue is 60 seconds or longer, the plugins abort the request and you get the NPE we are seeing.

My system has 3300 devices and 28 plugins, so just basic math means each plugin needs to complete startup in 2.14 seconds or less or the error will occur. WeatherXML as an example sometimes takes 250 seconds to start, guaranteeing this issue will effect your startup. I proposed some changes to Rich to deal with it which should solve it for the release he puts it in and later, but we will have to code defensively and retry if we want to support older versions.

Thank you again for your willingness to make those changes, and I am very very happy to finally have root cause on this darn thing; this one took awhile...

[bsobel]

Just wanted to update you on what I've found, in further debugging:

HomeSeer has a thread called "Check Interfaces" which is responsible, among other things, for calling the InitIO routine of each plugin in series at startup. The call is a RPC, so the thread itself is held up while the remote call occurs. During this time calls from other plugins to HS fail with a null pointer exception in remoting, they start working again when that thread is not blocked. I suspect (but have not verified) this same thread is the one that calls HSEvent as well and likely has the same problem them (albeit HSEvent is usually a faster call than InitIO), so we have this condition where the load sequence and timing of plugins makes the issue appear 'random' but finally know when the issue is occurring. This feels 'fixable' (potentially with a secondary thread to do the actual calls while this thread continues to do whatever else it does that enables the remoting calls to not fail), but a backwards compatibility issue will remain until everyone gets updated to a fixed version .

[bsobel]

Bill,

Beta is available now... be sure to install 2.0.4.7 as for some reason some users do see two beta's of the JowiHue plugin

Thanks, will grab it tomorrow. Continuing to debug the issue so trying to not change my config at all.

Minor issue; as an FYI I notice that at every HS shutdown I see:

Unhandled Exception:
System.NullReferenceException: Object reference not set to an instance of an object
at HSPI_JowiHue.BaseCache.StopTimers () [0x0000f] in <2ad28a1e03c442209dd24cf9deef1f6f>:0
at HSPI_JowiHue.BaseCache.Dispose (System.Boolean disposing) [0x00015] in <2ad28a1e03c442209dd24cf9deef1f6f>:0
at HSPI_JowiHue.BaseCache.Finalize () [0x00001] in <2ad28a1e03c442209dd24cf9deef1f6f>:0
[ERROR] FATAL UNHANDLED EXCEPTION: System.NullReferenceException: Object reference not set to an instance of an object
at HSPI_JowiHue.BaseCache.StopTimers () [0x0000f] in <2ad28a1e03c442209dd24cf9deef1f6f>:0
at HSPI_JowiHue.BaseCache.Dispose (System.Boolean disposing) [0x00015] in <2ad28a1e03c442209dd24cf9deef1f6f>:0
at HSPI_JowiHue.BaseCache.Finalize () [0x00001] in <2ad28a1e03c442209dd24cf9deef1f6f>:0


Guessing no really side effects, but wanted you to know just in case the exception is stopping some additional shutdown activity you rely on...

[w.vuyk]

Bill,

Beta is available now... be sure to install 2.0.4.7 as for some reason some users do see two beta's of the JowiHue plugin

[bsobel]

Ok, had finished the check on the enumarator as you said earlier, but will also put the repeat in the HS init part, which adds the webages.

Wim

Great. Been talking with Rich, there definitely is some long running process on the main STA thread at startup, we are discussing some options to fix and I'll be testing it here to see if we can get things stable for all.