Log errors v0.1.0b5

[tteck]

Everything appears to be working

Logger: homeassistant
Source: /usr/src/homeassistant/homeassistant/runner.py:98
First occurred: 3:28:26 PM (13 occurrences)
Last logged: 3:29:02 PM

Error doing job: Exception in callback MqttConnHelper.on_socket_open.<locals>.call_bk() at /usr/local/lib/python3.9/site-packages/pyduke_energy/realtime.py:299
Traceback (most recent call last):
  File "/usr/local/lib/python3.9/asyncio/events.py", line 80, in _run
    self._context.run(self._callback, *self._args)
  File "/usr/local/lib/python3.9/site-packages/pyduke_energy/realtime.py", line 302, in call_bk
    client.loop_read()
  File "/usr/local/lib/python3.9/site-packages/paho/mqtt/client.py", line 1572, in loop_read
    rc = self._packet_read()
  File "/usr/local/lib/python3.9/site-packages/paho/mqtt/client.py", line 2310, in _packet_read
    rc = self._packet_handle()
  File "/usr/local/lib/python3.9/site-packages/paho/mqtt/client.py", line 2936, in _packet_handle
    return self._handle_publish()
  File "/usr/local/lib/python3.9/site-packages/paho/mqtt/client.py", line 3216, in _handle_publish
    self._handle_on_message(message)
  File "/usr/local/lib/python3.9/site-packages/paho/mqtt/client.py", line 3444, in _handle_on_message
    self.on_message(self, self._userdata, message)
  File "/usr/local/lib/python3.9/site-packages/pyduke_energy/realtime.py", line 168, in _on_msg
    self.rx_msg.set_result((msg.payload.decode("utf8")))
asyncio.exceptions.InvalidStateError: invalid state

Logger: pyduke_energy.realtime
Source: /usr/local/lib/python3.9/site-packages/paho/mqtt/client.py:2404
First occurred: 3:28:26 PM (13 occurrences)
Last logged: 3:29:02 PM

Caught exception in on_message: invalid state

HA version 2021.11.0
Home Assistant Container
python version 3.9.7

[tteck]

Noticed that the HA Integration had 2 devices !?
deleted and reinstalled the HA Integration, now only 1 device
having 2 devices may have been the cause of the errors?
time will tell

[mjmeli]

I've seen some of these same logs. I'll try to look into what is causing them.

As for the 2 devices, the device in HA used to be tied 1:1 to the day's usage sensor entity. Now that I've added the real-time sensor entity, I had to change the device to be 1:many. That switch was creating 2 devices by default. I put migration code in place that was supposed to consolidate the 2 devices into 1, I guess for some reason it didn't work in your case.

[tteck]

Bump paho-mqtt to 1.6.1 (@emontnemery - #59339)
2021.11.2 may have fixed it

EDIT: It hasn't been fixed

[mjmeli]

Got some debug logs today of this happening

2021-11-17 09:34:17 DEBUG (MainThread) [pyduke_energy.realtime] Socket readable, calling loop_read()
2021-11-17 09:34:17 DEBUG (MainThread) [pyduke_energy.realtime] Received PUBLISH (d0, q0, r0, m0), 'DESH/P210400903/out/sm/1/live', ...  (128 bytes)
2021-11-17 09:34:17 DEBUG (MainThread) [custom_components.duke_energy_gateway] Ignoring real-time update as still in throttling interval
2021-11-17 09:34:26 DEBUG (MainThread) [pyduke_energy.realtime] Socket readable, calling loop_read()
2021-11-17 09:34:26 DEBUG (MainThread) [pyduke_energy.realtime] Received PUBLISH (d0, q0, r0, m0), 'DESH/P210400903/out/sm/1/live', ...  (128 bytes)
2021-11-17 09:34:27 DEBUG (MainThread) [pyduke_energy.realtime] Sending PINGREQ
2021-11-17 09:34:27 DEBUG (MainThread) [pyduke_energy.realtime] Watching socket for writability.
2021-11-17 09:34:27 DEBUG (MainThread) [pyduke_energy.realtime] Socket readable, calling loop_read()
2021-11-17 09:34:27 DEBUG (MainThread) [pyduke_energy.realtime] Received PUBLISH (d0, q0, r0, m0), 'DESH/P210400903/out/sm/1/live', ...  (128 bytes)
2021-11-17 09:34:27 ERROR (MainThread) [pyduke_energy.realtime] Caught exception in on_message: invalid state
2021-11-17 09:34:27 ERROR (MainThread) [homeassistant] Error doing job: Exception in callback MqttConnHelper.on_socket_open.<locals>.call_bk() at /usr/local/lib/python3.9/site-packages/pyduke_energy/realtime.py:299
Traceback (most recent call last):
  File "/usr/local/lib/python3.9/asyncio/events.py", line 80, in _run
    self._context.run(self._callback, *self._args)
  File "/usr/local/lib/python3.9/site-packages/pyduke_energy/realtime.py", line 302, in call_bk
    client.loop_read()
  File "/usr/local/lib/python3.9/site-packages/paho/mqtt/client.py", line 1556, in loop_read
    rc = self._packet_read()
  File "/usr/local/lib/python3.9/site-packages/paho/mqtt/client.py", line 2439, in _packet_read
    rc = self._packet_handle()
  File "/usr/local/lib/python3.9/site-packages/paho/mqtt/client.py", line 3033, in _packet_handle
    return self._handle_publish()
  File "/usr/local/lib/python3.9/site-packages/paho/mqtt/client.py", line 3327, in _handle_publish
    self._handle_on_message(message)
  File "/usr/local/lib/python3.9/site-packages/paho/mqtt/client.py", line 3570, in _handle_on_message
    on_message(self, self._userdata, message)
  File "/usr/local/lib/python3.9/site-packages/pyduke_energy/realtime.py", line 168, in _on_msg
    self.rx_msg.set_result((msg.payload.decode("utf8")))
asyncio.exceptions.InvalidStateError: invalid state
2021-11-17 09:34:28 DEBUG (MainThread) [custom_components.duke_energy_gateway] New measurement received: 855.000000
2021-11-17 09:34:28 DEBUG (MainThread) [pyduke_energy.realtime] Socket readable, calling loop_read()

Another one

2021-11-17 09:46:26 DEBUG (MainThread) [pyduke_energy.realtime] Socket readable, calling loop_read()
2021-11-17 09:46:26 DEBUG (MainThread) [pyduke_energy.realtime] Received PUBLISH (d0, q0, r0, m0), 'DESH/P210400903/out/sm/1/live', ...  (128 bytes)
2021-11-17 09:46:26 DEBUG (MainThread) [custom_components.duke_energy_gateway] New measurement received: 853.000000
2021-11-17 09:46:27 DEBUG (MainThread) [pyduke_energy.client] Requesting usage between 2021-11-17T05:00 UTC and 2021-11-18T05:00 UTC
2021-11-17 09:46:34 DEBUG (MainThread) [custom_components.duke_energy_gateway] Finished fetching homeassistant data in 7.585 seconds (success: True)
2021-11-17 09:46:34 DEBUG (MainThread) [pyduke_energy.realtime] Socket readable, calling loop_read()
2021-11-17 09:46:34 DEBUG (MainThread) [pyduke_energy.realtime] Received PUBLISH (d0, q0, r0, m0), 'DESH/P210400903/out/sm/1/live', ...  (128 bytes)
2021-11-17 09:46:34 DEBUG (MainThread) [custom_components.duke_energy_gateway] Ignoring real-time update as still in throttling interval
2021-11-17 09:46:35 DEBUG (MainThread) [pyduke_energy.realtime] Socket readable, calling loop_read()
2021-11-17 09:46:35 DEBUG (MainThread) [pyduke_energy.realtime] Received PUBLISH (d0, q0, r0, m0), 'DESH/P210400903/out/sm/1/live', ...  (128 bytes)
2021-11-17 09:46:35 ERROR (MainThread) [pyduke_energy.realtime] Caught exception in on_message: invalid state
2021-11-17 09:46:35 ERROR (MainThread) [homeassistant] Error doing job: Exception in callback MqttConnHelper.on_socket_open.<locals>.call_bk() at /usr/local/lib/python3.9/site-packages/pyduke_energy/realtime.py:299
Traceback (most recent call last):
  File "/usr/local/lib/python3.9/asyncio/events.py", line 80, in _run
    self._context.run(self._callback, *self._args)
  File "/usr/local/lib/python3.9/site-packages/pyduke_energy/realtime.py", line 302, in call_bk
    client.loop_read()
  File "/usr/local/lib/python3.9/site-packages/paho/mqtt/client.py", line 1556, in loop_read
    rc = self._packet_read()
  File "/usr/local/lib/python3.9/site-packages/paho/mqtt/client.py", line 2439, in _packet_read
    rc = self._packet_handle()
  File "/usr/local/lib/python3.9/site-packages/paho/mqtt/client.py", line 3033, in _packet_handle
    return self._handle_publish()
  File "/usr/local/lib/python3.9/site-packages/paho/mqtt/client.py", line 3327, in _handle_publish
    self._handle_on_message(message)
  File "/usr/local/lib/python3.9/site-packages/paho/mqtt/client.py", line 3570, in _handle_on_message
    on_message(self, self._userdata, message)
  File "/usr/local/lib/python3.9/site-packages/pyduke_energy/realtime.py", line 168, in _on_msg
    self.rx_msg.set_result((msg.payload.decode("utf8")))
asyncio.exceptions.InvalidStateError: invalid state

There more but they similar to this. Seems to happen in bursts over 15-30 minutes.

One thing that stands out to me is that these timestamps are very close together. It might be possible we are receiving events too fast for the processing to handle at times.

[mjmeli]

FWIW - this won't cause anything to break, just that one of the readings will be skipped

[mjmeli]

I believe I've fixed this via mjmeli/pyduke-energy#6 and the corresponding version bump in v0.1.0b6. I'll watch my logs for a few days before closing this though.