runConcurrentThread Exception Bug?

Struggling to isolate an exception in runConcurrentThread() which I think may be a bug. While logged slightly differently, all appear to be the same error and are all the result of the same event. To reproduce the event:

• Connect to the Indigo server with a remote client running on a MacBook.
• With the remote connection active, close the lid of the laptop and wait for the laptop to sleep.

If you disconnect from the server prior to closing the laptop, the error doesn't occur. I have many other plugins running that don't display the error, so there's clearly something these plugins have in common. It seems that it *might* have something to do with interactions with self.StopThread(), but there are differences in how each of these plugins reference it. Plugins that don't reference self.StopThread() in some manner don't appear to ever display this behavior.

Code: Select all

2020-02-24 22:53:04.006   Adapters Error   Error in plugin execution ServerReplacedElem:
StandardError: ServerCommunicationError -- timeout waiting for response
2020-02-24 22:53:04.006   HomeKit Bridge Error   Exception in homekit.deviceInitialize line 867: ServerCommunicationError -- timeout waiting for response
2020-02-24 22:53:04.006   Sonos Error   Error in plugin execution runConcurrentThread:
StandardError: ServerCommunicationError -- timeout waiting for response
2020-02-24 22:53:04.006   Sonos Error   plugin runConcurrentThread function returned or failed (will attempt again in 10 seconds)
2020-02-24 22:53:04.006   GhostXML Error   Error in plugin execution runConcurrentThread:
StandardError: ServerCommunicationError -- timeout waiting for response
2020-02-24 22:53:04.007   GhostXML Error   plugin runConcurrentThread function returned or failed (will attempt again in 10 seconds)
2020-02-24 22:53:04.031   OWServer Error   Error parsing sensor states: ServerCommunicationError -- timeout waiting for response
2020-02-24 22:53:04.032   OWServer Error   Trying again in 60 seconds.

Adapters:

Code: Select all

   def runConcurrentThread(self):
      try:

         while True:
            self.sleep(5)

      except self.StopThread:
         pass   # Optionally catch the StopThread exception and do any needed cleanup.


Homekit:

Code: Select all

   def runConcurrentThread(self):
      try:
         while True:
            self._callBack (BEFORE, [])
            
            # Removed any update checking as of 2.2.1 because the Indigo Plugin Store renders is obsolete
            #if "update" in dir(self.factory):
            #   self.factory.update.check (False, False)
               
            if "devices" in dir(self.factory):
               self.factory.devices.runConcurrentThread()
               
            if "http" in dir(self.factory):
               self.factory.http.runConcurrentThread()   
            
            self._callBack (AFTER, [])
            
            self.isFinishedLoading() # Passive if we are ready, calculation if we are not - lightweight
                        
            self.factory.plugin.sleep(1)
            
            
      except self.factory.plugin.StopThread:
         pass


Sonos:

Code: Select all

   def runConcurrentThread(self):

      self.plugin.debugLog(u"Running Concurrent Thread")

      if self.EventProcessor == "SoCo":
         x = Thread(target=self.SoCoReactor)
         x.setDaemon(True)
         x.start()

      updateTime = time.time()
      eventTime = time.time()
      subTestTime = time.time()
      relTime = time.time()

      while self.plugin.StopThread == False:

         if time.time() - updateTime >= 3600:
            updateTime = time.time()
            
         if time.time() - eventTime >= int(self.EventCheck):
            eventTime = time.time()
            self.checkEvents()

         if time.time() - subTestTime >= int(self.SubscriptionCheck):
            subTestTime = time.time()
            self.socoSubTest()

         if time.time() - relTime >= 1:
            relTime = time.time()
            self.updateRelTime()

         self.plugin.sleep(0.1)


GhostXML:

Code: Select all

            while not self.pluginIsShuttingDown:

                # Iterate devices to see if an update is required.
                for devId in self.managedDevices:
                    dev = self.managedDevices[devId].device

                    # 2019-12-22 DaveL17
                    # If device name has changed in Indigo, update the copy in managedDevices.
                    # TODO: consider moving this to its own method and adding anything else that might need updating.
                    if dev.name != indigo.devices[devId].name:
                        self.managedDevices[devId].device.name = indigo.devices[devId].name

                    # If a device has failed too many times, disable it and notify the user.
                    retries = int(dev.pluginProps.get('maxRetries', 10))
                    if self.managedDevices[devId].bad_calls >= retries:
                        self.process_bad_calls(dev, retries)

                    # If time_to_update returns True, add device to its queue.
                    else:
                        if self.time_to_update(dev):
                            self.managedDevices[devId].queue.put(dev)

                self.process_triggers()
                self.sleep(2)

        except self.StopThread:
            self.indigo_log_handler.setLevel(20)
            self.logger.info(u'Stopping main thread.')
            self.indigo_log_handler.setLevel(self.debugLevel)


OWServer:

Code: Select all

    def runConcurrentThread(self):

        self.debugLog(u"Starting main OWServer thread.")

        self.sleep(5)

        try:
            while True:
                self.spotDeadSensors()
                self.updateDeviceStates()
                sleep_time = int(self.pluginPrefs.get('configMenuPollInterval', 900))
                self.sleep(sleep_time-5)

        except self.StopThread:
            self.debugLog(u"Fatal error. Stopping OWServer thread.")


Edit: fixed typo.

Why do you even have runConcurrentThread() in your Adapters plugin? It's not doing anything.

Sorry, got no clue about the other issue.

Oh, wait. Check your capitalization. I have:

Code: Select all

        except self.stopThread:
            pass       


Hmmm. You might be on to something. The docs actually have both!

https://wiki.indigodomo.com/doku.php?id=indigo_7.4_documentation:plugin_guide

I'd suspect that it's 'self.stopThread' and I'll see if that solves the issue.

Thanks!

p.s. the Adapters plugin isn't mine; only the last two are.

[jay (support)]

Hmmm. It looks like our docs are somewhat inconsistent. From the PluginBase class:

Code: Select all

   class StopThread(Exception):
      def __init__(self, value=None):
         super(PluginBase.StopThread, self).__init__(value)


So, everyone should be catching the self.StopThread exception. self.stopThread, on the other hand, is a boolean that's set when self.stopConcurrentThread is called:

Code: Select all

   def stopConcurrentThread(self):
      self.stopThread = True
      os.write(self._stopThreadPipeOut, "*")


So, it will depend on what your usage pattern is really.

[jay (support)]

Actually, I think the docs are right. Check out the runConcurrentThread(self) and stopConcurrentThread(self) methods in the plugin.py docs.

As it says there, I don't believe many will need to override the stopConcurrentThread(self) method, and more importantly, it's unlikely anyone should be using the self.stopThread instance variable directly unless you really understand how it works.

Okay, I think I've got it. I'll continue to use:

Code: Select all

        except self.StopThread:
            # do stuff


So boiling it down to just the GhostXML plugin (as an example) it continues to throw an exception based on the OP.

Code: Select all

        except self.StopThread:
            self.indigo_log_handler.setLevel(20)
            self.logger.info(u'Stopping main thread.')
            self.indigo_log_handler.setLevel(self.debugLevel)


It doesn't have a stopConcurrentThread() method.

[jay (support)]

Oh, and back to the original question: this error:

Code: Select all

2020-02-24 22:53:04.006   Adapters Error   Error in plugin execution ServerReplacedElem:
StandardError: ServerCommunicationError -- timeout waiting for response


Generally means that some plugin is not responding to the server, but it doesn't mean that it's the plugin that appears to be throwing it. All it really indicates is that there's a plugin out there with a round-trip to the server that's not responding. It could be that there's a dialog open, or that it's in the middle of some network communication without an appropriately short timeout, etc.

To test it out, you can just disable all plugins except the GhostXML plugin and see if it still does it.

(In other words, there might be a bug here, but maybe not LOL)

Jay, what you say makes sense. But I still don't understand why the error would be caused by a suspended client connection. If it's a round trip between the plugin and the server, I'm not sure how the remote client factors in. My interest lies in whether there's a way for me to gracefully trap these errors in my plugins, or if it's caused by how Indigo reacts to the lost client connection.

[jay (support)]

Jay, what you say makes sense. But I still don't understand why the error would be caused by a suspended client connection. If it's a round trip between the plugin and the server, I'm not sure how the remote client factors in. My interest lies in whether there's a way for me to gracefully trap these errors in my plugins, or if it's caused by how Indigo reacts to the lost client connection.

You can't trap those as (I believe) they're coming from the Indigo Host process, not actually from your plugin.

Did you try my suggestion? I'm just curious if that makes any difference. There is some communication from IPH->Indigo Server->(Remote) Client that may be causing this problem, though I don't know what exactly. I listed the general case when we see those issues, but there may be some other edge case that we can't see yet. Removing the typical cause (plugin holding open a roundtrip) from the scenario might help identify if it really is something about the round trip or of the error message is a red herring.

Alas, I misunderstood this statement:

Generally means that some plugin is not responding to the server, but it doesn't mean that it's the plugin that appears to be throwing it.

So I was busily down a rabbit hole and had not yet tried your suggestion to disable all the other plugins. However, as another data point (which also might be another red herring), my rabbit hole experience may have yielded more insight. In the Ghost XML plugin, there is a global variable 'self.pluginIsShuttingDown'. It was referenced in three places:

Code: Select all

    def __init__(self, pluginId, pluginDisplayName, pluginVersion, pluginPrefs):
        super(Plugin, self).__init__(pluginId, pluginDisplayName, pluginVersion, pluginPrefs)

       ...
        self.pluginIsShuttingDown = False
        ...

    def runConcurrentThread(self):

        ...

        try:
            while not self.pluginIsShuttingDown:
        ...

    def shutdown(self):

        self.pluginIsShuttingDown = True



I removed all references to the global and changed runConcurrentThread() to 'while True'. No more error from GhostXML, but other plugins still threw an exception. Of course, this could be sheer luck. I'll go and do the plugin isolation thing now.

I cannot for the life of me figure out what the issue is here. I tried disabling and enabling plugins in all manner of combinations and could not find a common thread. As far as I can tell -- and this is by no means definitive -- the trigger is closing the lid on a remote client session while it's connected. I watched the log from Indigo Touch and right before the errors appeared, the Indigo Touch connection was knocked offline (it came back on its own once the server recovered from the error). It's not the same plugins logging tracebacks each time, but based on Jay's message, that doesn't necessarily mean anything. Sometimes I'll get a client disconnect message in the log when the remote client goes to sleep, and sometimes I won't. I never get the errors if I disconnect manually before closing the lid.

I'm fairly well stumped. I'm not even sure the subject line is appropriate anymore.

[matt (support)]

My hypothesis is that the remote Indigo client going to sleep is causing the Indigo Server to hang for a few seconds. This is long enough that an Indigo Touch request fails and plugin API requests start to timeout. When the plugin API timeout happens it throws an exception and depending on when that occurs the runConcurrentThread() might exit and have to be restarted.

In general the Indigo Server doesn't wait / block on any client communication calls (it just broadcasts information to the clients), whereas clients obviously do frequently block waiting for server methods to complete. Point being, I don't know why the remote Indigo Client going down is causing the Indigo Server to hang. I suspect it isn't because the Indigo Server is blocked waiting for a reply but rather a lower-level network hang caused by the sleeping remote Mac. The solution here is probably for the Indigo Client to catch the about-to-sleep macOS hook and more politely shutdown the TCP socket to the server before it goes to sleep. I'll add investigating this in more detail to the ToDo list.

Thanks Matt.