search

mjmeli / ha-duke-energy-gateway

Uses the Duke Energy Gateway to import real time energy usage into Home Assistant
MIT License
34 stars 4 forks source link

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

Closed koliha closed 1 year ago

koliha commented 1 year ago

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 commented 1 year ago

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 commented 1 year ago

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.