Connection unstable - Githubissues

M10tech commented 2 months ago

Maybe the word unstable is not correct.

However, I witness that the plugin works for a limited amount of calls, then breaks down (or whatever) and after the following error starts reporting new json results. This stalled state takes about 18 minutes. Error: Quatt: Async Read Exception (192.168.178.2:8080): 110, Connection timed out

I noticed the use of oustandingPings and quote another script found online that uses the same variable including the typo! It is written by Gizmocuz, father(?) of the Domoticz project.

Is there something that you know to solve based on this? PS. maybe this does not happen in debug=all mode. It happens to me in debug=none mode.

deleted as not relevant

M10tech commented 2 months ago

Some more feedback:

The issue occurs also with full debug on.

This is a repeating pattern until the error and the beginning of new success

2024-07-09 22:21:22.046 Quatt: Pushing 'onHeartbeatCallback' on to queue
2024-07-09 22:21:22.096 Quatt: Processing 'onHeartbeatCallback' message
2024-07-09 22:21:22.096 Quatt: Acquiring GIL for 'onHeartbeatCallback'
2024-07-09 22:21:22.096 Quatt: Calling message handler 'onHeartbeat' on 'module' type object.
2024-07-09 22:21:22.097 Quatt: Pushing 'WriteDirective' on to queue
2024-07-09 22:21:22.097 Quatt: Acquiring GIL for 'onHeartbeatCallback'
2024-07-09 22:21:22.097 Quatt: Processing 'WriteDirective' message
2024-07-09 22:21:22.097 Quatt: Acquiring GIL for 'WriteDirective'
2024-07-09 22:21:22.097 Quatt: Sending 63 bytes of data
2024-07-09 22:21:22.097 Quatt: 47 45 54 20 2f 62 65 74 61 2f 66 65 65 64 2f 64 61 74 61 2e GET./beta/feed/data.
2024-07-09 22:21:22.097 Quatt: 6a 73 6f 6e 20 48 54 54 50 2f 31 2e 31 0d 0a 55 73 65 72 2d json.HTTP/1.1..User-
2024-07-09 22:21:22.097 Quatt: 41 67 65 6e 74 3a 20 44 6f 6d 6f 74 69 63 7a 2f 31 2e 30 0d Agent:.Domoticz/1.0.
2024-07-09 22:21:22.097 Quatt: 0a 0d 0a .. .. .. .. .. .. .. .. .. .. .. .. .. .. .. .. .. ...
2024-07-09 22:21:22.097 Quatt: Acquiring GIL for 'WriteDirective'
2024-07-09 22:21:52.029 Quatt: Pushing 'onHeartbeatCallback' on to queue
2024-07-09 22:21:52.079 Quatt: Processing 'onHeartbeatCallback' message
2024-07-09 22:21:52.080 Quatt: Acquiring GIL for 'onHeartbeatCallback'
2024-07-09 22:21:52.080 Quatt: Calling message handler 'onHeartbeat' on 'module' type object.
2024-07-09 22:21:52.080 Quatt: Acquiring GIL for 'onHeartbeatCallback'
2024-07-09 22:22:22.011 Quatt: Pushing 'onHeartbeatCallback' on to queue
2024-07-09 22:22:22.061 Quatt: Processing 'onHeartbeatCallback' message
2024-07-09 22:22:22.062 Quatt: Acquiring GIL for 'onHeartbeatCallback'
2024-07-09 22:22:22.062 Quatt: Calling message handler 'onHeartbeat' on 'module' type object.
2024-07-09 22:22:22.062 Quatt: Acquiring GIL for 'onHeartbeatCallback'
2024-07-09 22:22:52.037 Quatt: Pushing 'onHeartbeatCallback' on to queue
2024-07-09 22:22:52.087 Quatt: Processing 'onHeartbeatCallback' message
2024-07-09 22:22:52.087 Quatt: Acquiring GIL for 'onHeartbeatCallback'
2024-07-09 22:22:52.087 Quatt: Calling message handler 'onHeartbeat' on 'module' type object.
2024-07-09 22:22:52.087 Quatt: Acquiring GIL for 'onHeartbeatCallback'
2024-07-09 22:23:22.020 Quatt: Pushing 'onHeartbeatCallback' on to queue
2024-07-09 22:23:22.070 Quatt: Processing 'onHeartbeatCallback' message
2024-07-09 22:23:22.070 Quatt: Acquiring GIL for 'onHeartbeatCallback'
2024-07-09 22:23:22.071 Quatt: Calling message handler 'onHeartbeat' on 'module' type object.
2024-07-09 22:23:22.071 Quatt: Acquiring GIL for 'onHeartbeatCallback'
2024-07-09 22:23:52.055 Quatt: Pushing 'onHeartbeatCallback' on to queue
2024-07-09 22:23:52.105 Quatt: Processing 'onHeartbeatCallback' message
2024-07-09 22:23:52.105 Quatt: Acquiring GIL for 'onHeartbeatCallback'
2024-07-09 22:23:52.105 Quatt: Calling message handler 'onHeartbeat' on 'module' type object.
2024-07-09 22:23:52.105 Quatt: Pushing 'WriteDirective' on to queue
2024-07-09 22:23:52.105 Quatt: Acquiring GIL for 'onHeartbeatCallback'
2024-07-09 22:23:52.105 Quatt: Processing 'WriteDirective' message
2024-07-09 22:23:52.105 Quatt: Acquiring GIL for 'WriteDirective'
2024-07-09 22:23:52.106 Quatt: Sending 63 bytes of data
2024-07-09 22:23:52.106 Quatt: 47 45 54 20 2f 62 65 74 61 2f 66 65 65 64 2f 64 61 74 61 2e GET./beta/feed/data.
2024-07-09 22:23:52.106 Quatt: 6a 73 6f 6e 20 48 54 54 50 2f 31 2e 31 0d 0a 55 73 65 72 2d json.HTTP/1.1..User-
2024-07-09 22:23:52.106 Quatt: 41 67 65 6e 74 3a 20 44 6f 6d 6f 74 69 63 7a 2f 31 2e 30 0d Agent:.Domoticz/1.0.
2024-07-09 22:23:52.106 Quatt: 0a 0d 0a .. .. .. .. .. .. .. .. .. .. .. .. .. .. .. .. .. ...
2024-07-09 22:23:52.106 Quatt: Acquiring GIL for 'WriteDirective'
2024-07-09 22:24:22.038 Quatt: Pushing 'onHeartbeatCallback' on to queue
2024-07-09 22:24:22.088 Quatt: Processing 'onHeartbeatCallback' message
2024-07-09 22:24:22.088 Quatt: Acquiring GIL for 'onHeartbeatCallback'
2024-07-09 22:24:22.088 Quatt: Calling message handler 'onHeartbeat' on 'module' type object.
2024-07-09 22:24:22.088 Quatt: Acquiring GIL for 'onHeartbeatCallback'
2024-07-09 22:24:52.018 Quatt: Pushing 'onHeartbeatCallback' on to queue
2024-07-09 22:24:52.068 Quatt: Processing 'onHeartbeatCallback' message
2024-07-09 22:24:52.068 Quatt: Acquiring GIL for 'onHeartbeatCallback'
2024-07-09 22:24:52.068 Quatt: Calling message handler 'onHeartbeat' on 'module' type object.
2024-07-09 22:24:52.068 Quatt: Acquiring GIL for 'onHeartbeatCallback'
2024-07-09 22:25:06.672 Quatt: Acquiring GIL for 'CPluginTransportTCP::handleRead'
2024-07-09 22:25:06.672 Quatt: Pushing 'DisconnectedEvent' on to queue
2024-07-09 22:25:06.710 Quatt: Processing 'DisconnectedEvent' message
2024-07-09 22:25:06.710 Quatt: Acquiring GIL for 'DisconnectedEvent'
2024-07-09 22:25:06.710 Quatt: Disconnect event received for '192.168.178.170:8080'.
2024-07-09 22:25:06.710 Quatt: Pushing 'onDisconnectCallback' on to queue
2024-07-09 22:25:06.710 Quatt: Acquiring GIL for 'DisconnectedEvent'
2024-07-09 22:25:06.710 Quatt: Processing 'onDisconnectCallback' message
2024-07-09 22:25:06.710 Quatt: Acquiring GIL for 'onDisconnectCallback'
2024-07-09 22:25:06.711 Quatt: Calling message handler 'onDisconnect' on 'module' type object.
2024-07-09 22:25:06.711 Quatt: onDisconnect called for connection to: 192.168.178.170:8080
2024-07-09 22:25:06.711 Quatt: Acquiring GIL for 'onDisconnectCallback'
2024-07-09 22:25:06.672 Error: Quatt: Async Read Exception (192.168.178.170:8080): 110, Connection timed out
2024-07-09 22:25:22.057 Quatt: Acquiring GIL for 'ConnectDirective'
2024-07-09 22:25:22.058 Quatt: Acquiring GIL for 'CPluginTransportTCP::handleAsyncResolve'
2024-07-09 22:25:22.069 Quatt: Acquiring GIL for 'CPluginTransportTCP::handleAsyncResolve'
2024-07-09 22:25:22.069 Quatt: Pushing 'onConnectCallback' on to queue
2024-07-09 22:25:22.108 Quatt: Processing 'onConnectCallback' message
2024-07-09 22:25:22.108 Quatt: Acquiring GIL for 'onConnectCallback'
2024-07-09 22:25:22.108 Quatt: Calling message handler 'onConnect' on 'module' type object.
2024-07-09 22:25:22.108 Quatt: onConnect called: 0 | 192.168.178.170:8080
2024-07-09 22:25:22.108 Quatt: Connected successfully to: 192.168.178.170:8080
2024-07-09 22:25:22.108 Quatt: Pushing 'WriteDirective' on to queue
2024-07-09 22:25:22.108 Quatt: Acquiring GIL for 'onConnectCallback'
2024-07-09 22:25:22.108 Quatt: Processing 'WriteDirective' message
2024-07-09 22:25:22.108 Quatt: Acquiring GIL for 'WriteDirective'
2024-07-09 22:25:22.109 Quatt: Sending 63 bytes of data
2024-07-09 22:25:22.109 Quatt: 47 45 54 20 2f 62 65 74 61 2f 66 65 65 64 2f 64 61 74 61 2e GET./beta/feed/data.
2024-07-09 22:25:22.109 Quatt: 6a 73 6f 6e 20 48 54 54 50 2f 31 2e 31 0d 0a 55 73 65 72 2d json.HTTP/1.1..User-
2024-07-09 22:25:22.109 Quatt: 41 67 65 6e 74 3a 20 44 6f 6d 6f 74 69 63 7a 2f 31 2e 30 0d Agent:.Domoticz/1.0.
2024-07-09 22:25:22.109 Quatt: 0a 0d 0a .. .. .. .. .. .. .. .. .. .. .. .. .. .. .. .. .. ...
2024-07-09 22:25:22.109 Quatt: Acquiring GIL for 'WriteDirective'
2024-07-09 22:25:22.116 Quatt: Acquiring GIL for 'CPluginTransportTCP::handleRead'
2024-07-09 22:25:22.116 Quatt: Pushing 'ReadEvent' on to queue
2024-07-09 22:25:22.122 Quatt: Acquiring GIL for 'CPluginTransportTCP::handleRead'
2024-07-09 22:25:22.122 Quatt: Pushing 'ReadEvent' on to queue
2024-07-09 22:25:22.159 Quatt: Processing 'ReadEvent' message
2024-07-09 22:25:22.160 Quatt: Acquiring GIL for 'ReadEvent'
2024-07-09 22:25:22.160 Quatt: Received 102 bytes of data
2024-07-09 22:25:22.160 Quatt: 48 54 54 50 2f 31 2e 31 20 32 30 30 20 4f 4b 0d 0a 43 6f 6e HTTP/1.1.200.OK..Con
2024-07-09 22:25:22.160 Quatt: 74 65 6e 74 2d 4c 65 6e 67 74 68 3a 20 38 33 37 0d 0a 43 6f tent-Length:.837..Co
2024-07-09 22:25:22.160 Quatt: 6e 74 65 6e 74 2d 54 79 70 65 3a 20 61 70 70 6c 69 63 61 74 ntent-Type:.applicat
2024-07-09 22:25:22.160 Quatt: 69 6f 6e 2f 6a 73 6f 6e 0d 0a 4b 65 65 70 2d 41 6c 69 76 65 ion/json..Keep-Alive
2024-07-09 22:25:22.160 Quatt: 3a 20 74 69 6d 65 6f 75 74 3d 35 2c 20 6d 61 78 3d 35 0d 0a :.timeout=5,.max=5..
2024-07-09 22:25:22.160 Quatt: 0d 0a .. .. .. .. .. .. .. .. .. .. .. .. .. .. .. .. .. .. ..
2024-07-09 22:25:22.160 Quatt: Acquiring GIL for 'ReadEvent'
2024-07-09 22:25:22.160 Quatt: Processing 'ReadEvent' message
2024-07-09 22:25:22.160 Quatt: Acquiring GIL for 'ReadEvent'
2024-07-09 22:25:22.161 Quatt: Received 837 bytes of data
2024-07-09 22:25:22.161 Quatt: 7b 22 62 6f 69 6c 65 72 22 3a 7b 22 6f 54 74 62 54 75 72 6e {"boiler":{"oTtbTurn
...

M10tech commented 2 months ago

Never mind the suggestions about this oustandingPings

I've created a connection handling that is a lot more robust.

While it has not been build on your 0.4 but on 0.3 release, these are the diffs

Half of them are related to functional updates, like the status and rounding The other half make sure that the connection will work in 99% of the time, as opposed to the 50% now. The oustandingPings have been removed as not relevant.

diff -wc plugin.py.03 plugin.py
*** plugin.py.03    2024-04-10 21:19:32.982277983 +0200
--- plugin.py   2024-07-10 21:11:55.251088722 +0200
***************
*** 28,34 ****
  class QuattPlugin:
      httpConn = None
      sendAfterConnect = {'Verb': 'GET', 'URL': '/beta/feed/data.json'}
-     oustandingPings = 0

      def __init__(self):
          self.update_interval = 3
--- 28,33 ----
***************
*** 91,109 ****
          Domoticz.Debug("Quatt Plugin stopped")

      def onHeartbeat(self):
!         try:
!             if (self.httpConn.Connected()):
!                 if (self.oustandingPings > 3):
!                     self.httpConn.Send(self.sendAfterConnect)
!                     self.oustandingPings = 0
                  else:
!                     self.oustandingPings = self.oustandingPings + 1
              else:
!                 self.oustandingPings = 0
                  self.httpConn.Connect()
-             return True
-         except:
-             Domoticz.Log("Unhandled exception in onHeartbeat, forcing disconnect.")

      def onMessage(self, Connection, Data):
          Domoticz.Debug("onMessage called with data: " + str(Data))
--- 91,108 ----
          Domoticz.Debug("Quatt Plugin stopped")

      def onHeartbeat(self):
!         if (self.httpConn.Connecting()):
!             Domoticz.Error("onHeartBeat connecting")
          else:
!             if (self.httpConn.Connected()):
!                 Domoticz.Error("onHeartBeat connected")
!                 self.httpConn.Disconnect()
!                 self.httpConn=None
!                 sleep(1)
!                 self.httpConn = Domoticz.Connection(Name="Quatt", Transport="TCP/IP", Protocol="HTTP", Address=Parameters["Address"], Port=Parameters["Port"])
              else:
!                 Domoticz.Log("onHeartBeat unconnected")
              self.httpConn.Connect()

      def onMessage(self, Connection, Data):
          Domoticz.Debug("onMessage called with data: " + str(Data))
***************
*** 134,140 ****
              98: 'Anti-Freeze protection - water circulation',
              99: 'Fault - circulation pump on',
          }.get(QuattCM, 'Unknown')
!         Domoticz.Log("Quatt Status: " + Quatt_Status)
          COP = round(data["hp1"]["power"] / data["hp1"]["powerInput"], 2)

          try:
--- 131,137 ----
              98: 'Anti-Freeze protection - water circulation',
              99: 'Fault - circulation pump on',
          }.get(QuattCM, 'Unknown')
!         Domoticz.Status(Quatt_Status)
          COP = round(data["hp1"]["power"] / data["hp1"]["powerInput"], 2)

          try:
***************
*** 142,148 ****
          except Exception as e:
              Domoticz.Error("Error updating device 1: {}".format(str(e)))            
          try:
!             Devices[2].Update(nValue=1, sValue=str(data["thermostat"]["otFtRoomTemperature"]), TimedOut=0)
          except Exception as e:
              Domoticz.Error("Error updating device 1: {}".format(str(e)))
          try:
--- 139,145 ----
          except Exception as e:
              Domoticz.Error("Error updating device 1: {}".format(str(e)))            
          try:
!             Devices[2].Update(nValue=1, sValue=str(round(data["thermostat"]["otFtRoomTemperature"],2)), TimedOut=0)
          except Exception as e:
              Domoticz.Error("Error updating device 1: {}".format(str(e)))
          try:
***************
*** 166,172 ****
          except Exception as e:
              Domoticz.Error("Error updating device 1: {}".format(str(e)))
          try:
!             Devices[8].Update(nValue=1, sValue=str(data["flowMeter"]["flowRate"]), TimedOut=0)
          except Exception as e:
              Domoticz.Error("Error updating device 1: {}".format(str(e)))
          try:
--- 163,169 ----
          except Exception as e:
              Domoticz.Error("Error updating device 1: {}".format(str(e)))
          try:
!             Devices[8].Update(nValue=1, sValue=str(round(data["flowMeter"]["waterSupplyTemperature"],2)), TimedOut=0)
          except Exception as e:
              Domoticz.Error("Error updating device 1: {}".format(str(e)))
          try:
***************

and focussing on the onHeartbeat

    def onHeartbeat(self):
        if (self.httpConn.Connecting()):
            Domoticz.Error("onHeartBeat connecting")
        else:
            if (self.httpConn.Connected()):
                Domoticz.Error("onHeartBeat connected")
                self.httpConn.Disconnect()
                self.httpConn=None
                self.httpConn = Domoticz.Connection(Name="Quatt", Transport="TCP/IP", Protocol="HTTP", Address=Parameters["Address"], Port=Parameters["Port"])
            else:
                Domoticz.Log("onHeartBeat unconnected")
            self.httpConn.Connect()

galadril commented 2 months ago

Great research! If you have time to create a PR on v0.04, ill test it and merge it, to make you contributor ;)

M10tech commented 2 months ago

done PR is waiting for you ;-)

M10tech commented 2 months ago

added a few extra improvements to the same PR

galadril commented 2 months ago

Thanks for your contribution

galadril / Domoticz-Quatt-Plugin

Connection unstable #3