Skip to content
This repository has been archived by the owner on Jul 12, 2023. It is now read-only.

Realtime data stops polling, won't resume until HA is restarted #153

Closed
koliha opened this issue Dec 15, 2022 · 2 comments · Fixed by #159
Closed

Realtime data stops polling, won't resume until HA is restarted #153

koliha opened this issue Dec 15, 2022 · 2 comments · Fixed by #159

Comments

@koliha
Copy link

koliha commented Dec 15, 2022

At some point after HA has been running, realtime energy no longer updates. There are no issues for the daily/other metrics that are provided by the plugin. If I restart or update HA, realtime usage data resumes. The debug logs show that a timeout occurs, but it never seems to reconnect after. Debug logs are pasted below - functional at the start, then timeout, then the same messages repeated over and over (which have continued for the last 5 hours).

Is there some solution for this or some way I could make HA restart the plugin components on a regular basis to work around this?

2022-12-15 09:24:27.144 DEBUG (MainThread) [pyduke_energy.realtime] Socket readable, calling loop_read()
2022-12-15 09:24:27.145 DEBUG (MainThread) [pyduke_energy.realtime] Received PUBLISH (d0, q0, r0, m0), 'DESH/Pxxxxxxxxx/out/sm/1/live', ... (129 bytes)
2022-12-15 09:24:27.145 DEBUG (MainThread) [custom_components.duke_energy_gateway] Ignoring real-time update as still in throttling interval
2022-12-15 09:24:30.121 DEBUG (MainThread) [pyduke_energy.realtime] Socket readable, calling loop_read()
2022-12-15 09:24:30.122 DEBUG (MainThread) [pyduke_energy.realtime] Received PUBLISH (d0, q0, r0, m0), 'DESH/Pxxxxxxxxx/out/sm/1/live', ... (129 bytes)
2022-12-15 09:24:30.122 DEBUG (MainThread) [custom_components.duke_energy_gateway] Ignoring real-time update as still in throttling interval
2022-12-15 09:24:35.996 DEBUG (MainThread) [pyduke_energy.realtime] Sending PINGREQ
2022-12-15 09:24:35.996 DEBUG (MainThread) [pyduke_energy.realtime] Watching socket for writability.
2022-12-15 09:24:35.997 DEBUG (MainThread) [pyduke_energy.realtime] Socket is writable, calling loop_write
2022-12-15 09:24:35.998 DEBUG (MainThread) [pyduke_energy.realtime] Stop watching socket for writability.
2022-12-15 09:24:36.015 DEBUG (MainThread) [pyduke_energy.realtime] Socket readable, calling loop_read()
2022-12-15 09:24:36.016 DEBUG (MainThread) [pyduke_energy.realtime] Received PINGRESP
2022-12-15 09:24:50.834 DEBUG (MainThread) [pyduke_energy.client] Requesting usage between 2022-12-15T05:00 UTC and 2022-12-16T05:00 UTC
2022-12-15 09:24:50.963 DEBUG (MainThread) [custom_components.duke_energy_gateway] Finished fetching homeassistant data in 0.129 seconds (success: True)
2022-12-15 09:25:20.835 DEBUG (MainThread) [pyduke_energy.client] Requesting usage between 2022-12-15T05:00 UTC and 2022-12-16T05:00 UTC
2022-12-15 09:25:20.961 DEBUG (MainThread) [custom_components.duke_energy_gateway] Finished fetching homeassistant data in 0.126 seconds (success: True)
2022-12-15 09:25:26.076 DEBUG (MainThread) [pyduke_energy.realtime] Sending PINGREQ
2022-12-15 09:25:26.076 DEBUG (MainThread) [pyduke_energy.realtime] Watching socket for writability.
2022-12-15 09:25:26.077 DEBUG (MainThread) [pyduke_energy.realtime] Socket is writable, calling loop_write
2022-12-15 09:25:26.078 DEBUG (MainThread) [pyduke_energy.realtime] Stop watching socket for writability.
2022-12-15 09:25:26.095 DEBUG (MainThread) [pyduke_energy.realtime] Socket readable, calling loop_read()
2022-12-15 09:25:26.096 DEBUG (MainThread) [pyduke_energy.realtime] Received PINGRESP
2022-12-15 09:25:30.125 DEBUG (MainThread) [pyduke_energy.realtime] Message timeout, requesting fastpoll
2022-12-15 09:25:30.159 DEBUG (MainThread) [pyduke_energy.client] Smartmeter fastpoll requested
2022-12-15 09:25:50.836 DEBUG (MainThread) [pyduke_energy.client] Requesting usage between 2022-12-15T05:00 UTC and 2022-12-16T05:00 UTC
2022-12-15 09:25:51.019 DEBUG (MainThread) [custom_components.duke_energy_gateway] Finished fetching homeassistant data in 0.183 seconds (success: True)
2022-12-15 09:26:16.148 DEBUG (MainThread) [pyduke_energy.realtime] Sending PINGREQ
2022-12-15 09:26:16.148 DEBUG (MainThread) [pyduke_energy.realtime] Watching socket for writability.
2022-12-15 09:26:16.149 DEBUG (MainThread) [pyduke_energy.realtime] Socket is writable, calling loop_write
2022-12-15 09:26:16.149 DEBUG (MainThread) [pyduke_energy.realtime] Stop watching socket for writability.
2022-12-15 09:26:16.167 DEBUG (MainThread) [pyduke_energy.realtime] Socket readable, calling loop_read()
2022-12-15 09:26:16.167 DEBUG (MainThread) [pyduke_energy.realtime] Received PINGRESP
2022-12-15 09:26:20.837 DEBUG (MainThread) [pyduke_energy.client] Requesting usage between 2022-12-15T05:00 UTC and 2022-12-16T05:00 UTC
2022-12-15 09:26:20.970 DEBUG (MainThread) [custom_components.duke_energy_gateway] Finished fetching homeassistant data in 0.133 seconds (success: True)
2022-12-15 09:26:30.160 DEBUG (MainThread) [pyduke_energy.realtime] Message timeout, requesting fastpoll
2022-12-15 09:26:30.186 DEBUG (MainThread) [pyduke_energy.client] Smartmeter fastpoll requested
2022-12-15 09:26:50.840 DEBUG (MainThread) [pyduke_energy.client] Requesting usage between 2022-12-15T05:00 UTC and 2022-12-16T05:00 UTC
2022-12-15 09:26:50.977 DEBUG (MainThread) [custom_components.duke_energy_gateway] Finished fetching homeassistant data in 0.137 seconds (success: True)
2022-12-15 09:27:06.221 DEBUG (MainThread) [pyduke_energy.realtime] Sending PINGREQ
2022-12-15 09:27:06.221 DEBUG (MainThread) [pyduke_energy.realtime] Watching socket for writability.
2022-12-15 09:27:06.223 DEBUG (MainThread) [pyduke_energy.realtime] Socket is writable, calling loop_write
2022-12-15 09:27:06.224 DEBUG (MainThread) [pyduke_energy.realtime] Stop watching socket for writability.
2022-12-15 09:27:06.241 DEBUG (MainThread) [pyduke_energy.realtime] Socket readable, calling loop_read()
2022-12-15 09:27:06.242 DEBUG (MainThread) [pyduke_energy.realtime] Received PINGRESP
2022-12-15 09:27:20.840 DEBUG (MainThread) [pyduke_energy.client] Requesting usage between 2022-12-15T05:00 UTC and 2022-12-16T05:00 UTC
2022-12-15 09:27:21.071 DEBUG (MainThread) [custom_components.duke_energy_gateway] Finished fetching homeassistant data in 0.231 seconds (success: True)
2022-12-15 09:27:30.187 DEBUG (MainThread) [pyduke_energy.realtime] Message timeout, requesting fastpoll
2022-12-15 09:27:30.220 DEBUG (MainThread) [pyduke_energy.client] Smartmeter fastpoll requested
2022-12-15 09:27:50.842 DEBUG (MainThread) [pyduke_energy.client] Requesting usage between 2022-12-15T05:00 UTC and 2022-12-16T05:00 UTC
2022-12-15 09:27:50.974 DEBUG (MainThread) [custom_components.duke_energy_gateway] Finished fetching homeassistant data in 0.133 seconds (success: True)
2022-12-15 09:27:56.289 DEBUG (MainThread) [pyduke_energy.realtime] Sending PINGREQ
2022-12-15 09:27:56.289 DEBUG (MainThread) [pyduke_energy.realtime] Watching socket for writability.
2022-12-15 09:27:56.289 DEBUG (MainThread) [pyduke_energy.realtime] Socket is writable, calling loop_write
2022-12-15 09:27:56.290 DEBUG (MainThread) [pyduke_energy.realtime] Stop watching socket for writability.
2022-12-15 09:27:56.307 DEBUG (MainThread) [pyduke_energy.realtime] Socket readable, calling loop_read()
2022-12-15 09:27:56.308 DEBUG (MainThread) [pyduke_energy.realtime] Received PINGRESP
2022-12-15 09:28:20.843 DEBUG (MainThread) [pyduke_energy.client] Requesting usage between 2022-12-15T05:00 UTC and 2022-12-16T05:00 UTC
2022-12-15 09:28:20.975 DEBUG (MainThread) [custom_components.duke_energy_gateway] Finished fetching homeassistant data in 0.132 seconds (success: True)
2022-12-15 09:28:30.221 DEBUG (MainThread) [pyduke_energy.realtime] Multiple msg timeout, attempting reconnect
2022-12-15 09:28:30.221 DEBUG (MainThread) [pyduke_energy.realtime] Sending UNSUBSCRIBE (d0, m26) [b'DESH/Pxxxxxxxxx/out/sm/1/live']
2022-12-15 09:28:30.221 DEBUG (MainThread) [pyduke_energy.realtime] Watching socket for writability.
2022-12-15 09:28:30.224 DEBUG (MainThread) [pyduke_energy.realtime] Socket is writable, calling loop_write
2022-12-15 09:28:30.224 DEBUG (MainThread) [pyduke_energy.realtime] Stop watching socket for writability.
2022-12-15 09:28:30.242 DEBUG (MainThread) [pyduke_energy.realtime] Socket readable, calling loop_read()
2022-12-15 09:28:30.243 DEBUG (MainThread) [pyduke_energy.realtime] Received UNSUBACK (Mid: 26)
2022-12-15 09:28:30.243 DEBUG (MainThread) [pyduke_energy.realtime] MQTT unsubscribed msg_id: 26
2022-12-15 09:28:30.243 DEBUG (MainThread) [pyduke_energy.realtime] Sending DISCONNECT
2022-12-15 09:28:30.243 DEBUG (MainThread) [pyduke_energy.realtime] Watching socket for writability.
2022-12-15 09:28:30.245 DEBUG (MainThread) [pyduke_energy.realtime] Socket is writable, calling loop_write
2022-12-15 09:28:30.246 DEBUG (MainThread) [pyduke_energy.realtime] MQTT disconnected with result code: No error.
2022-12-15 09:28:30.246 DEBUG (MainThread) [pyduke_energy.realtime] Stop watching socket for writability.
2022-12-15 09:28:30.247 DEBUG (MainThread) [pyduke_energy.realtime] Socket closed
2022-12-15 09:28:30.248 DEBUG (MainThread) [pyduke_energy.realtime] Misc loop cancelled
2022-12-15 09:28:30.248 DEBUG (MainThread) [pyduke_energy.realtime] Misc loop finished
2022-12-15 09:28:30.345 DEBUG (SyncWorker_4) [pyduke_energy.realtime] Socket opened
2022-12-15 09:28:30.346 DEBUG (MainThread) [pyduke_energy.realtime] Misc loop started
2022-12-15 09:28:30.347 DEBUG (SyncWorker_4) [pyduke_energy.realtime] Sending CONNECT (u1, p1, wr0, wq0, wf0, c1, k50) client_id=b'mobileSub1-Pxxxxxxxxx-02832c93-7a1d-4848-ad4c-46b87b2948e8'
2022-12-15 09:28:30.347 DEBUG (SyncWorker_4) [pyduke_energy.realtime] Watching socket for writability.
2022-12-15 09:28:30.348 DEBUG (MainThread) [pyduke_energy.realtime] Socket is writable, calling loop_write
2022-12-15 09:28:30.349 DEBUG (MainThread) [pyduke_energy.realtime] Stop watching socket for writability.
2022-12-15 09:28:30.677 DEBUG (MainThread) [pyduke_energy.realtime] Socket readable, calling loop_read()
2022-12-15 09:28:30.678 DEBUG (MainThread) [pyduke_energy.realtime] Received CONNACK (0, 0)
2022-12-15 09:28:30.678 DEBUG (MainThread) [pyduke_energy.realtime] MQTT connected with result code: Connection Accepted.
2022-12-15 09:28:30.678 DEBUG (MainThread) [pyduke_energy.realtime] Sending SUBSCRIBE (d0, m27) [(b'DESH/Pxxxxxxxxx/out/sm/1/live', 0)]
2022-12-15 09:28:30.678 DEBUG (MainThread) [pyduke_energy.realtime] Watching socket for writability.
2022-12-15 09:28:30.680 DEBUG (MainThread) [pyduke_energy.realtime] Socket is writable, calling loop_write
2022-12-15 09:28:30.681 DEBUG (MainThread) [pyduke_energy.realtime] Stop watching socket for writability.
2022-12-15 09:28:30.699 DEBUG (MainThread) [pyduke_energy.realtime] Socket readable, calling loop_read()
2022-12-15 09:28:30.700 DEBUG (MainThread) [pyduke_energy.realtime] Received SUBACK
2022-12-15 09:28:30.700 DEBUG (MainThread) [pyduke_energy.realtime] MQTT subscribed msg_id: 27 qos: (0,)
2022-12-15 09:28:50.844 DEBUG (MainThread) [pyduke_energy.client] Requesting usage between 2022-12-15T05:00 UTC and 2022-12-16T05:00 UTC
2022-12-15 09:28:50.972 DEBUG (MainThread) [custom_components.duke_energy_gateway] Finished fetching homeassistant data in 0.129 seconds (success: True)
2022-12-15 09:29:20.412 DEBUG (MainThread) [pyduke_energy.realtime] Sending PINGREQ
2022-12-15 09:29:20.413 DEBUG (MainThread) [pyduke_energy.realtime] Watching socket for writability.
2022-12-15 09:29:20.413 DEBUG (MainThread) [pyduke_energy.realtime] Socket is writable, calling loop_write
2022-12-15 09:29:20.414 DEBUG (MainThread) [pyduke_energy.realtime] Stop watching socket for writability.
2022-12-15 09:29:20.431 DEBUG (MainThread) [pyduke_energy.realtime] Socket readable, calling loop_read()
2022-12-15 09:29:20.431 DEBUG (MainThread) [pyduke_energy.realtime] Received PINGRESP
2022-12-15 09:29:20.845 DEBUG (MainThread) [pyduke_energy.client] Requesting usage between 2022-12-15T05:00 UTC and 2022-12-16T05:00 UTC
2022-12-15 09:29:20.972 DEBUG (MainThread) [custom_components.duke_energy_gateway] Finished fetching homeassistant data in 0.127 seconds (success: True)
2022-12-15 09:29:30.684 DEBUG (MainThread) [pyduke_energy.realtime] Multiple msg timeout, attempting reconnect
2022-12-15 09:29:30.684 DEBUG (MainThread) [pyduke_energy.realtime] Sending UNSUBSCRIBE (d0, m28) [b'DESH/Pxxxxxxxxx/out/sm/1/live']
2022-12-15 09:29:30.684 DEBUG (MainThread) [pyduke_energy.realtime] Watching socket for writability.
2022-12-15 09:29:30.685 DEBUG (MainThread) [pyduke_energy.realtime] Socket is writable, calling loop_write
2022-12-15 09:29:30.685 DEBUG (MainThread) [pyduke_energy.realtime] Stop watching socket for writability.
2022-12-15 09:29:30.703 DEBUG (MainThread) [pyduke_energy.realtime] Socket readable, calling loop_read()
2022-12-15 09:29:30.704 DEBUG (MainThread) [pyduke_energy.realtime] Received UNSUBACK (Mid: 28)
2022-12-15 09:29:30.704 DEBUG (MainThread) [pyduke_energy.realtime] MQTT unsubscribed msg_id: 28
2022-12-15 09:29:30.704 DEBUG (MainThread) [pyduke_energy.realtime] Sending DISCONNECT
2022-12-15 09:29:30.704 DEBUG (MainThread) [pyduke_energy.realtime] Watching socket for writability.
2022-12-15 09:29:30.705 DEBUG (MainThread) [pyduke_energy.realtime] Socket is writable, calling loop_write
2022-12-15 09:29:30.706 DEBUG (MainThread) [pyduke_energy.realtime] MQTT disconnected with result code: No error.
2022-12-15 09:29:30.706 DEBUG (MainThread) [pyduke_energy.realtime] Stop watching socket for writability.
2022-12-15 09:29:30.708 DEBUG (MainThread) [pyduke_energy.realtime] Socket closed
2022-12-15 09:29:30.708 DEBUG (MainThread) [pyduke_energy.realtime] Misc loop cancelled
2022-12-15 09:29:30.709 DEBUG (MainThread) [pyduke_energy.realtime] Misc loop finished
2022-12-15 09:29:30.791 DEBUG (SyncWorker_1) [pyduke_energy.realtime] Socket opened
2022-12-15 09:29:30.792 DEBUG (MainThread) [pyduke_energy.realtime] Misc loop started
2022-12-15 09:29:30.793 DEBUG (SyncWorker_1) [pyduke_energy.realtime] Sending CONNECT (u1, p1, wr0, wq0, wf0, c1, k50) client_id=b'mobileSub1-Pxxxxxxxxx-02832c93-7a1d-4848-ad4c-46b87b2948e8'
2022-12-15 09:29:30.793 DEBUG (SyncWorker_1) [pyduke_energy.realtime] Watching socket for writability.
2022-12-15 09:29:30.800 DEBUG (MainThread) [pyduke_energy.realtime] Socket is writable, calling loop_write
2022-12-15 09:29:30.800 DEBUG (MainThread) [pyduke_energy.realtime] Stop watching socket for writability.
2022-12-15 09:29:31.138 DEBUG (MainThread) [pyduke_energy.realtime] Socket readable, calling loop_read()
2022-12-15 09:29:31.139 DEBUG (MainThread) [pyduke_energy.realtime] Received CONNACK (0, 0)
2022-12-15 09:29:31.139 DEBUG (MainThread) [pyduke_energy.realtime] MQTT connected with result code: Connection Accepted.
2022-12-15 09:29:31.139 DEBUG (MainThread) [pyduke_energy.realtime] Sending SUBSCRIBE (d0, m29) [(b'DESH/Pxxxxxxxxx/out/sm/1/live', 0)]
2022-12-15 09:29:31.139 DEBUG (MainThread) [pyduke_energy.realtime] Watching socket for writability.
2022-12-15 09:29:31.141 DEBUG (MainThread) [pyduke_energy.realtime] Socket is writable, calling loop_write
2022-12-15 09:29:31.142 DEBUG (MainThread) [pyduke_energy.realtime] Stop watching socket for writability.
2022-12-15 09:29:31.161 DEBUG (MainThread) [pyduke_energy.realtime] Socket readable, calling loop_read()
2022-12-15 09:29:31.162 DEBUG (MainThread) [pyduke_energy.realtime] Received SUBACK
2022-12-15 09:29:31.162 DEBUG (MainThread) [pyduke_energy.realtime] MQTT subscribed msg_id: 29 qos: (0,)
2022-12-15 09:29:50.847 DEBUG (MainThread) [pyduke_energy.client] Requesting usage between 2022-12-15T05:00 UTC and 2022-12-16T05:00 UTC
2022-12-15 09:29:50.998 DEBUG (MainThread) [custom_components.duke_energy_gateway] Finished fetching homeassistant data in 0.151 seconds (success: True)
2022-12-15 09:30:20.848 DEBUG (MainThread) [pyduke_energy.client] Requesting usage between 2022-12-15T05:00 UTC and 2022-12-16T05:00 UTC
2022-12-15 09:30:20.860 DEBUG (MainThread) [pyduke_energy.realtime] Sending PINGREQ
2022-12-15 09:30:20.860 DEBUG (MainThread) [pyduke_energy.realtime] Watching socket for writability.
2022-12-15 09:30:20.861 DEBUG (MainThread) [pyduke_energy.realtime] Socket is writable, calling loop_write
2022-12-15 09:30:20.861 DEBUG (MainThread) [pyduke_energy.realtime] Stop watching socket for writability.
2022-12-15 09:30:20.879 DEBUG (MainThread) [pyduke_energy.realtime] Socket readable, calling loop_read()
2022-12-15 09:30:20.880 DEBUG (MainThread) [pyduke_energy.realtime] Received PINGRESP
2022-12-15 09:30:20.984 DEBUG (MainThread) [custom_components.duke_energy_gateway] Finished fetching homeassistant data in 0.136 seconds (success: True)
2022-12-15 09:30:31.145 DEBUG (MainThread) [pyduke_energy.realtime] Multiple msg timeout, attempting reconnect
2022-12-15 09:30:31.145 DEBUG (MainThread) [pyduke_energy.realtime] Sending UNSUBSCRIBE (d0, m30) [b'DESH/Pxxxxxxxxx/out/sm/1/live']
2022-12-15 09:30:31.145 DEBUG (MainThread) [pyduke_energy.realtime] Watching socket for writability.
2022-12-15 09:30:31.146 DEBUG (MainThread) [pyduke_energy.realtime] Socket is writable, calling loop_write
2022-12-15 09:30:31.146 DEBUG (MainThread) [pyduke_energy.realtime] Stop watching socket for writability.
2022-12-15 09:30:31.165 DEBUG (MainThread) [pyduke_energy.realtime] Socket readable, calling loop_read()
2022-12-15 09:30:31.166 DEBUG (MainThread) [pyduke_energy.realtime] Received UNSUBACK (Mid: 30)
2022-12-15 09:30:31.166 DEBUG (MainThread) [pyduke_energy.realtime] MQTT unsubscribed msg_id: 30
2022-12-15 09:30:31.166 DEBUG (MainThread) [pyduke_energy.realtime] Sending DISCONNECT
2022-12-15 09:30:31.166 DEBUG (MainThread) [pyduke_energy.realtime] Watching socket for writability.
2022-12-15 09:30:31.167 DEBUG (MainThread) [pyduke_energy.realtime] Socket is writable, calling loop_write
2022-12-15 09:30:31.167 DEBUG (MainThread) [pyduke_energy.realtime] MQTT disconnected with result code: No error.
2022-12-15 09:30:31.169 DEBUG (MainThread) [pyduke_energy.realtime] Stop watching socket for writability.
2022-12-15 09:30:31.170 DEBUG (MainThread) [pyduke_energy.realtime] Socket closed
2022-12-15 09:30:31.171 DEBUG (MainThread) [pyduke_energy.realtime] Misc loop cancelled
2022-12-15 09:30:31.171 DEBUG (MainThread) [pyduke_energy.realtime] Misc loop finished
2022-12-15 09:30:31.254 DEBUG (SyncWorker_0) [pyduke_energy.realtime] Socket opened
2022-12-15 09:30:31.254 DEBUG (MainThread) [pyduke_energy.realtime] Misc loop started
2022-12-15 09:30:31.255 DEBUG (SyncWorker_0) [pyduke_energy.realtime] Sending CONNECT (u1, p1, wr0, wq0, wf0, c1, k50) client_id=b'mobileSub1-Pxxxxxxxxx-02832c93-7a1d-4848-ad4c-46b87b2948e8'
2022-12-15 09:30:31.255 DEBUG (SyncWorker_0) [pyduke_energy.realtime] Watching socket for writability.
2022-12-15 09:30:31.261 DEBUG (MainThread) [pyduke_energy.realtime] Socket is writable, calling loop_write
2022-12-15 09:30:31.261 DEBUG (MainThread) [pyduke_energy.realtime] Stop watching socket for writability.
2022-12-15 09:30:31.556 DEBUG (MainThread) [pyduke_energy.realtime] Socket readable, calling loop_read()
2022-12-15 09:30:31.557 DEBUG (MainThread) [pyduke_energy.realtime] Received CONNACK (0, 0)
2022-12-15 09:30:31.557 DEBUG (MainThread) [pyduke_energy.realtime] MQTT connected with result code: Connection Accepted.
2022-12-15 09:30:31.557 DEBUG (MainThread) [pyduke_energy.realtime] Sending SUBSCRIBE (d0, m31) [(b'DESH/Pxxxxxxxxx/out/sm/1/live', 0)]
2022-12-15 09:30:31.557 DEBUG (MainThread) [pyduke_energy.realtime] Watching socket for writability.
2022-12-15 09:30:31.559 DEBUG (MainThread) [pyduke_energy.realtime] Socket is writable, calling loop_write
2022-12-15 09:30:31.560 DEBUG (MainThread) [pyduke_energy.realtime] Stop watching socket for writability.
2022-12-15 09:30:31.578 DEBUG (MainThread) [pyduke_energy.realtime] Socket readable, calling loop_read()
2022-12-15 09:30:31.579 DEBUG (MainThread) [pyduke_energy.realtime] Received SUBACK
2022-12-15 09:30:31.579 DEBUG (MainThread) [pyduke_energy.realtime] MQTT subscribed msg_id: 31 qos: (0,)
2022-12-15 09:30:50.849 DEBUG (MainThread) [pyduke_energy.client] Requesting usage between 2022-12-15T05:00 UTC and 2022-12-16T05:00 UTC
2022-12-15 09:30:50.981 DEBUG (MainThread) [custom_components.duke_energy_gateway] Finished fetching homeassistant data in 0.132 seconds (success: True)
2022-12-15 09:31:20.850 DEBUG (MainThread) [pyduke_energy.client] Requesting usage between 2022-12-15T05:00 UTC and 2022-12-16T05:00 UTC
2022-12-15 09:31:21.007 DEBUG (MainThread) [custom_components.duke_energy_gateway] Finished fetching homeassistant data in 0.157 seconds (success: True)
2022-12-15 09:31:21.343 DEBUG (MainThread) [pyduke_energy.realtime] Sending PINGREQ
2022-12-15 09:31:21.343 DEBUG (MainThread) [pyduke_energy.realtime] Watching socket for writability.
2022-12-15 09:31:21.344 DEBUG (MainThread) [pyduke_energy.realtime] Socket is writable, calling loop_write
2022-12-15 09:31:21.345 DEBUG (MainThread) [pyduke_energy.realtime] Stop watching socket for writability.
2022-12-15 09:31:21.363 DEBUG (MainThread) [pyduke_energy.realtime] Socket readable, calling loop_read()
2022-12-15 09:31:21.364 DEBUG (MainThread) [pyduke_energy.realtime] Received PINGRESP
2022-12-15 09:31:31.562 DEBUG (MainThread) [pyduke_energy.realtime] Multiple msg timeout, attempting reconnect
2022-12-15 09:31:31.562 DEBUG (MainThread) [pyduke_energy.realtime] Sending UNSUBSCRIBE (d0, m32) [b'DESH/Pxxxxxxxxx/out/sm/1/live']
2022-12-15 09:31:31.562 DEBUG (MainThread) [pyduke_energy.realtime] Watching socket for writability.
2022-12-15 09:31:31.563 DEBUG (MainThread) [pyduke_energy.realtime] Socket is writable, calling loop_write
2022-12-15 09:31:31.564 DEBUG (MainThread) [pyduke_energy.realtime] Stop watching socket for writability.
2022-12-15 09:31:31.583 DEBUG (MainThread) [pyduke_energy.realtime] Socket readable, calling loop_read()
2022-12-15 09:31:31.584 DEBUG (MainThread) [pyduke_energy.realtime] Received UNSUBACK (Mid: 32)
2022-12-15 09:31:31.584 DEBUG (MainThread) [pyduke_energy.realtime] MQTT unsubscribed msg_id: 32
2022-12-15 09:31:31.584 DEBUG (MainThread) [pyduke_energy.realtime] Sending DISCONNECT
2022-12-15 09:31:31.584 DEBUG (MainThread) [pyduke_energy.realtime] Watching socket for writability.
2022-12-15 09:31:31.585 DEBUG (MainThread) [pyduke_energy.realtime] Socket is writable, calling loop_write
2022-12-15 09:31:31.586 DEBUG (MainThread) [pyduke_energy.realtime] MQTT disconnected with result code: No error.
2022-12-15 09:31:31.587 DEBUG (MainThread) [pyduke_energy.realtime] Stop watching socket for writability.
2022-12-15 09:31:31.588 DEBUG (MainThread) [pyduke_energy.realtime] Socket closed
2022-12-15 09:31:31.589 DEBUG (MainThread) [pyduke_energy.realtime] Misc loop cancelled
2022-12-15 09:31:31.589 DEBUG (MainThread) [pyduke_energy.realtime] Misc loop finished
2022-12-15 09:31:31.669 DEBUG (SyncWorker_11) [pyduke_energy.realtime] Socket opened
2022-12-15 09:31:31.670 DEBUG (MainThread) [pyduke_energy.realtime] Misc loop started
2022-12-15 09:31:31.670 DEBUG (SyncWorker_11) [pyduke_energy.realtime] Sending CONNECT (u1, p1, wr0, wq0, wf0, c1, k50) client_id=b'mobileSub1-Pxxxxxxxxx-02832c93-7a1d-4848-ad4c-46b87b2948e8'
2022-12-15 09:31:31.670 DEBUG (SyncWorker_11) [pyduke_energy.realtime] Watching socket for writability.
2022-12-15 09:31:31.676 DEBUG (MainThread) [pyduke_energy.realtime] Socket is writable, calling loop_write
2022-12-15 09:31:31.677 DEBUG (MainThread) [pyduke_energy.realtime] Stop watching socket for writability.
2022-12-15 09:31:31.964 DEBUG (MainThread) [pyduke_energy.realtime] Socket readable, calling loop_read()
2022-12-15 09:31:31.965 DEBUG (MainThread) [pyduke_energy.realtime] Received CONNACK (0, 0)
2022-12-15 09:31:31.965 DEBUG (MainThread) [pyduke_energy.realtime] MQTT connected with result code: Connection Accepted.
2022-12-15 09:31:31.965 DEBUG (MainThread) [pyduke_energy.realtime] Sending SUBSCRIBE (d0, m33) [(b'DESH/Pxxxxxxxxx/out/sm/1/live', 0)]
2022-12-15 09:31:31.965 DEBUG (MainThread) [pyduke_energy.realtime] Watching socket for writability.
2022-12-15 09:31:31.967 DEBUG (MainThread) [pyduke_energy.realtime] Socket is writable, calling loop_write
2022-12-15 09:31:31.968 DEBUG (MainThread) [pyduke_energy.realtime] Stop watching socket for writability.
2022-12-15 09:31:31.989 DEBUG (MainThread) [pyduke_energy.realtime] Socket readable, calling loop_read()
2022-12-15 09:31:31.990 DEBUG (MainThread) [pyduke_energy.realtime] Received SUBACK
2022-12-15 09:31:31.990 DEBUG (MainThread) [pyduke_energy.realtime] MQTT subscribed msg_id: 33 qos: (0,)
2022-12-15 09:31:50.851 DEBUG (MainThread) [pyduke_energy.client] Requesting usage between 2022-12-15T05:00 UTC and 2022-12-16T05:00 UTC
2022-12-15 09:31:50.977 DEBUG (MainThread) [custom_components.duke_energy_gateway] Finished fetching homeassistant data in 0.126 seconds (success: True)
2022-12-15 09:32:20.852 DEBUG (MainThread) [pyduke_energy.client] Requesting usage between 2022-12-15T05:00 UTC and 2022-12-16T05:00 UTC
2022-12-15 09:32:20.982 DEBUG (MainThread) [custom_components.duke_energy_gateway] Finished fetching homeassistant data in 0.130 seconds (success: True)
2022-12-15 09:32:21.734 DEBUG (MainThread) [pyduke_energy.realtime] Sending PINGREQ
2022-12-15 09:32:21.734 DEBUG (MainThread) [pyduke_energy.realtime] Watching socket for writability.
2022-12-15 09:32:21.735 DEBUG (MainThread) [pyduke_energy.realtime] Socket is writable, calling loop_write
2022-12-15 09:32:21.736 DEBUG (MainThread) [pyduke_energy.realtime] Stop watching socket for writability.
2022-12-15 09:32:21.753 DEBUG (MainThread) [pyduke_energy.realtime] Socket readable, calling loop_read()
2022-12-15 09:32:21.754 DEBUG (MainThread) [pyduke_energy.realtime] Received PINGRESP
2022-12-15 09:32:31.970 DEBUG (MainThread) [pyduke_energy.realtime] Multiple msg timeout, attempting reconnect
2022-12-15 09:32:31.970 DEBUG (MainThread) [pyduke_energy.realtime] Sending UNSUBSCRIBE (d0, m34) [b'DESH/Pxxxxxxxxx/out/sm/1/live']
2022-12-15 09:32:31.970 DEBUG (MainThread) [pyduke_energy.realtime] Watching socket for writability.
2022-12-15 09:32:31.973 DEBUG (MainThread) [pyduke_energy.realtime] Socket is writable, calling loop_write
2022-12-15 09:32:31.974 DEBUG (MainThread) [pyduke_energy.realtime] Stop watching socket for writability.
2022-12-15 09:32:31.992 DEBUG (MainThread) [pyduke_energy.realtime] Socket readable, calling loop_read()
2022-12-15 09:32:31.993 DEBUG (MainThread) [pyduke_energy.realtime] Received UNSUBACK (Mid: 34)
2022-12-15 09:32:31.993 DEBUG (MainThread) [pyduke_energy.realtime] MQTT unsubscribed msg_id: 34
2022-12-15 09:32:31.993 DEBUG (MainThread) [pyduke_energy.realtime] Sending DISCONNECT
2022-12-15 09:32:31.993 DEBUG (MainThread) [pyduke_energy.realtime] Watching socket for writability.
2022-12-15 09:32:31.995 DEBUG (MainThread) [pyduke_energy.realtime] Socket is writable, calling loop_write
2022-12-15 09:32:31.996 DEBUG (MainThread) [pyduke_energy.realtime] MQTT disconnected with result code: No error.
2022-12-15 09:32:31.996 DEBUG (MainThread) [pyduke_energy.realtime] Stop watching socket for writability.
2022-12-15 09:32:31.997 DEBUG (MainThread) [pyduke_energy.realtime] Socket closed
2022-12-15 09:32:31.998 DEBUG (MainThread) [pyduke_energy.realtime] Misc loop cancelled
2022-12-15 09:32:31.998 DEBUG (MainThread) [pyduke_energy.realtime] Misc loop finished
2022-12-15 09:32:32.155 DEBUG (SyncWorker_15) [pyduke_energy.realtime] Socket opened
2022-12-15 09:32:32.156 DEBUG (MainThread) [pyduke_energy.realtime] Misc loop started
2022-12-15 09:32:32.157 DEBUG (SyncWorker_15) [pyduke_energy.realtime] Sending CONNECT (u1, p1, wr0, wq0, wf0, c1, k50) client_id=b'mobileSub1-Pxxxxxxxxx-02832c93-7a1d-4848-ad4c-46b87b2948e8'
2022-12-15 09:32:32.157 DEBUG (SyncWorker_15) [pyduke_energy.realtime] Watching socket for writability.
2022-12-15 09:32:32.163 DEBUG (MainThread) [pyduke_energy.realtime] Socket is writable, calling loop_write
2022-12-15 09:32:32.164 DEBUG (MainThread) [pyduke_energy.realtime] Stop watching socket for writability.
2022-12-15 09:32:32.505 DEBUG (MainThread) [pyduke_energy.realtime] Socket readable, calling loop_read()
2022-12-15 09:32:32.506 DEBUG (MainThread) [pyduke_energy.realtime] Received CONNACK (0, 0)
2022-12-15 09:32:32.506 DEBUG (MainThread) [pyduke_energy.realtime] MQTT connected with result code: Connection Accepted.
2022-12-15 09:32:32.506 DEBUG (MainThread) [pyduke_energy.realtime] Sending SUBSCRIBE (d0, m35) [(b'DESH/Pxxxxxxxxx/out/sm/1/live', 0)]
2022-12-15 09:32:32.506 DEBUG (MainThread) [pyduke_energy.realtime] Watching socket for writability.
2022-12-15 09:32:32.508 DEBUG (MainThread) [pyduke_energy.realtime] Socket is writable, calling loop_write
2022-12-15 09:32:32.509 DEBUG (MainThread) [pyduke_energy.realtime] Stop watching socket for writability.
2022-12-15 09:32:32.527 DEBUG (MainThread) [pyduke_energy.realtime] Socket readable, calling loop_read()
2022-12-15 09:32:32.528 DEBUG (MainThread) [pyduke_energy.realtime] Received SUBACK
2022-12-15 09:32:32.528 DEBUG (MainThread) [pyduke_energy.realtime] MQTT subscribed msg_id: 35 qos: (0,)
2022-12-15 09:32:50.854 DEBUG (MainThread) [pyduke_energy.client] Requesting usage between 2022-12-15T05:00 UTC and 2022-12-16T05:00 UTC
2022-12-15 09:32:50.985 DEBUG (MainThread) [custom_components.duke_energy_gateway] Finished fetching homeassistant data in 0.131 seconds (success: True)
2022-12-15 09:33:20.857 DEBUG (MainThread) [pyduke_energy.client] Requesting usage between 2022-12-15T05:00 UTC and 2022-12-16T05:00 UTC
2022-12-15 09:33:20.997 DEBUG (MainThread) [custom_components.duke_energy_gateway] Finished fetching homeassistant data in 0.140 seconds (success: True)
2022-12-15 09:33:22.223 DEBUG (MainThread) [pyduke_energy.realtime] Sending PINGREQ
2022-12-15 09:33:22.223 DEBUG (MainThread) [pyduke_energy.realtime] Watching socket for writability.
2022-12-15 09:33:22.225 DEBUG (MainThread) [pyduke_energy.realtime] Socket is writable, calling loop_write
2022-12-15 09:33:22.225 DEBUG (MainThread) [pyduke_energy.realtime] Stop watching socket for writability.
2022-12-15 09:33:22.243 DEBUG (MainThread) [pyduke_energy.realtime] Socket readable, calling loop_read()
2022-12-15 09:33:22.244 DEBUG (MainThread) [pyduke_energy.realtime] Received PINGRESP
2022-12-15 09:33:32.511 DEBUG (MainThread) [pyduke_energy.realtime] Multiple msg timeout, attempting reconnect
2022-12-15 09:33:32.512 DEBUG (MainThread) [pyduke_energy.realtime] Sending UNSUBSCRIBE (d0, m36) [b'DESH/Pxxxxxxxxx/out/sm/1/live']
2022-12-15 09:33:32.512 DEBUG (MainThread) [pyduke_energy.realtime] Watching socket for writability.
2022-12-15 09:33:32.514 DEBUG (MainThread) [pyduke_energy.realtime] Socket is writable, calling loop_write
2022-12-15 09:33:32.515 DEBUG (MainThread) [pyduke_energy.realtime] Stop watching socket for writability.

@mjmeli
Copy link
Owner

mjmeli commented Jan 5, 2023

Hi, sorry for the delay in getting to this. While I have not seen this behavior, I think I have identified a code flow in the underlying client library that might lead to this. The MQTT event stream has to be "pulsed" by a separate REST API call every 15 minutes. I think what is happening is that under certain conditions where that MQTT stream times out, the separate API call is not being made. I will try to get make an adjustment for that this week and we can see if it helps.

@mjmeli
Copy link
Owner

mjmeli commented Jan 6, 2023

Newest version v0.1.3 of the integration has a potential fix. It will try to force kill the whole connection after a number of timeouts. Let me know if this doesn't solve the issue for you.

Sign up for free to subscribe to this conversation on GitHub. Already have an account? Sign in.
Labels
None yet
Projects
None yet
Development

Successfully merging a pull request may close this issue.

2 participants