jdeath / rd200v2

RadonEye RD200 Version 2 Integration for Home Assistant
MIT License
66 stars 16 forks source link

Sensors update only once after HA restart and then never again #11

Open mck182 opened 1 year ago

mck182 commented 1 year ago

Serial: FR:RU2221...

I've setup the integration and let it run for about an hour but I've noticed the data never gets updated after the initial fetch upon HA startup.

I have enabled debugging:

logger:
  default: warning
  logs:
    custom_components.rd200_ble: debug

but there isn't much being logged, this is all I have:

2023-01-31 22:09:36.454 DEBUG (MainThread) [custom_components.rd200_ble] Finished fetching rd200_ble data in 18.621 seconds (success: True)
2023-01-31 22:09:36.462 DEBUG (MainThread) [custom_components.rd200_ble.sensor] got sensors: {'radon': 17.0, 'radon_1day_level': 0.0, 'radon_1month_level': 0.0, 'radon_peak': 21.0, 'radon_uptime': 19517, 'radon_uptime_string': '0d 05:25:17'}
2023-01-31 23:11:53.956 DEBUG (MainThread) [custom_components.rd200_ble] Finished fetching rd200_ble data in 3137.854 seconds (success: True)
2023-01-31 23:11:54 -----HA restart-----

After restart, the data is refreshed but then not again until after the next HA restart. I've confirmed this with multiple HA restarts and the value being updated after.

jdeath commented 1 year ago

That is strange. I used v2.3 with your latest PR (thanks), restated and working fine. I added and removed the integration, and it works as well. I tried with both ESPHome proxies and/or USB BT adapters.

The "got sensors" line in the debug logs is only shown on the first update. After that, the debugging only shows:

2023-02-01 06:37:57.724 DEBUG (MainThread) [custom_components.rd200_ble.rd200_ble.parser] New Radon Peak: 2.457
2023-02-01 06:37:58.279 DEBUG (MainThread) [custom_components.rd200_ble] Finished fetching rd200_ble data in 2.174 seconds (success: True)

I kept the peak output because there was an old issue with ESPHome proxies, but using > 2022.12.4 fixes it if use the esp-idf framework. But that only affects the peak radon value/firmware, not the normal radon value. Look in your logs for something like: "Can't find characteristic 00001525-0000-1000-8000-00805f9b34fb" That means your proxy is missing the reading, it happens sometimes. Try moving it closer.

I thought the code was stable if the peak was not found, but I might have messed something up. You can remove the device = await self._get_radon_peak(client, device) line in the parser.py

Make sure your ESPProxy is at the latest version and looks like this. If your framework is arduino, change it it esp-idf and update via USB not wireless.

esp32:
  board: esp32dev
  framework:
    type: esp-idf
mck182 commented 1 year ago

I should have specified - sorry - this is running on Pi directly, without the proxy. I have no other logs from custom_components.rd200_ble in the log, just what's in the OP (and some other below).

I have confirmed the readings can be read with running the radon_reader.py from the linked EtoTen/radonreader project every 10 minutes, and things worked as expected with that - connection is great and values update accordingly. But somehow this integration never updates the sensors in HA. It's as if the integration is stuck waiting for the next update.

I have also seen the integration get stuck in "Initializing" on startup, so there might be some hangups going on? This is the log for that:

2023-01-31 23:15:14.602 WARNING (MainThread) [homeassistant.bootstrap] Waiting on integrations to complete setup: rd200_ble
2023-01-31 23:16:14.687 WARNING (MainThread) [homeassistant.bootstrap] Waiting on integrations to complete setup: rd200_ble
2023-01-31 23:17:14.762 WARNING (MainThread) [homeassistant.bootstrap] Waiting on integrations to complete setup: rd200_ble
2023-01-31 23:18:14.851 WARNING (MainThread) [homeassistant.bootstrap] Waiting on integrations to complete setup: rd200_ble
2023-01-31 23:19:14.936 WARNING (MainThread) [homeassistant.bootstrap] Waiting on integrations to complete setup: rd200_ble
2023-01-31 23:20:15.020 WARNING (MainThread) [homeassistant.bootstrap] Waiting on integrations to complete setup: rd200_ble
2023-01-31 23:21:15.110 WARNING (MainThread) [homeassistant.bootstrap] Waiting on integrations to complete setup: rd200_ble
2023-01-31 23:29:10.355 DEBUG (MainThread) [custom_components.rd200_ble] Finished fetching rd200_ble data in 1022.644 seconds (success: True)

I'll try with removing the suggested line and report back.

mck182 commented 1 year ago

Ok so I've commented out both peak and uptime:

#device = await self._get_radon_peak(client, device)
#device = await self._get_radon_uptime(client, device)

and I see the values being fetched every 10 minutes:

2023-02-01 09:52:41.463 DEBUG (MainThread) [custom_components.rd200_ble] Finished fetching rd200_ble data in 2.921 seconds (success: True)
2023-02-01 09:52:41.469 DEBUG (MainThread) [custom_components.rd200_ble.sensor] got sensors: {'radon': 19.0, 'radon_1day_level': 0.0, 'radon_1month_level': 0.0}
2023-02-01 10:02:49.453 DEBUG (MainThread) [custom_components.rd200_ble] Finished fetching rd200_ble data in 8.276 seconds (success: True)
2023-02-01 10:13:02.451 DEBUG (MainThread) [custom_components.rd200_ble] Finished fetching rd200_ble data in 13.275 seconds (success: True)

I've uncommented the peak one back and left the uptime still commented out:

device = await self._get_radon_peak(client, device)
#device = await self._get_radon_uptime(client, device)

The updates never arrived past the first one after startup:

2023-02-01 10:15:43.464 DEBUG (MainThread) [custom_components.rd200_ble] Finished fetching rd200_ble data in 12.273 seconds (success: True)
2023-02-01 10:15:43.467 DEBUG (MainThread) [custom_components.rd200_ble.sensor] got sensors: {'radon': 14.0, 'radon_1day_level': 0.0, 'radon_1month_level': 0.0, 'radon_peak': 21.0}
2023-02-01 10:29:23 -----HA restart-----

So then I commented out peak and left uptime:

#device = await self._get_radon_peak(client, device)
device = await self._get_radon_uptime(client, device)

And again no updates happened:

2023-02-01 10:28:35.473 DEBUG (MainThread) [custom_components.rd200_ble] Finished fetching rd200_ble data in 16.788 seconds (success: True)
2023-02-01 10:28:35.483 DEBUG (MainThread) [custom_components.rd200_ble.sensor] got sensors: {'radon': 16.0, 'radon_1day_level': 0.0, 'radon_1month_level': 0.0, 'radon_uptime': 63850, 'radon_uptime_string': '0d 17:44:10'}
2023-02-01 10:43:45 -----HA restart-----

I have of course also checked in the entity property in HA when was the last update and it corresponds with the log.

so the tl;dr is - commenting out both _get_radon_peak and _get_radon_uptime makes the sensor work as expected, leaving either one uncommented results in no updates past the initial one.

This is HA 2023.1.7.

Let me know if I can help any further with debugging.

jdeath commented 1 year ago

Sounds like the Pi has the same issue the proxy has, though not sure why the uptime would not work. I don't think it is an issue with the integration.

Are you using the HAOS install on your PI? If so, I think you should make an issue on the homeassistant github. Reference this esphome issue: https://github.com/esphome/issues/issues/4041 and say you are seeing something similar on the Pi (whatever model you are using).

I'll let the BT guru know as well. He has an RD200, so may be able to help

jdeath commented 1 year ago

braco confirmed PI may be using an older BT stack that may not handle the peak sensor. I think you'll just need to hang tight. Keep checking everytime there is a HAOS update or get an ESP32 proxy if really want the peak sensor.

mck182 commented 1 year ago

It's a dockerized HA install on the Pi.

I do see the peak being updated on startup, so perhaps the BT stack can handle it?

I've done some more debugging and narrowed it down to line 211 in parser.py:

        await client.start_notify(
            RADON_CHARACTERISTIC_UUID_READ, self.notification_handler
        )

This is the line that hangs the entire thing. I also see this hanging during HA startup from time to time; sometimes the peak is read fine during HA startup, sometimes it just hangs (as mentioned above).

Bunch of logs with my added logging (around all the awaits):

-----HA startup----
2023-02-01 20:37:50.274 DEBUG (MainThread) [custom_components.rd200_ble.rd200_ble.parser] fetching peak
2023-02-01 20:37:50.274 DEBUG (MainThread) [custom_components.rd200_ble.rd200_ble.parser] _get_radon_peak
2023-02-01 20:37:50.275 DEBUG (MainThread) [custom_components.rd200_ble.rd200_ble.parser] _get_radon_peak before first await
2023-02-01 20:37:50.389 DEBUG (MainThread) [custom_components.rd200_ble.rd200_ble.parser] _get_radon_peak after start_notify
2023-02-01 20:37:51.545 DEBUG (MainThread) [custom_components.rd200_ble.rd200_ble.parser] notification handler
2023-02-01 20:37:51.553 DEBUG (MainThread) [custom_components.rd200_ble.rd200_ble.parser] _get_radon_peak Before asyncio.wait_for
2023-02-01 20:37:51.574 DEBUG (MainThread) [custom_components.rd200_ble.rd200_ble.parser] _get_radon_peak After asyncio.wait_for
2023-02-01 20:37:51.602 DEBUG (MainThread) [custom_components.rd200_ble.rd200_ble.parser] _get_radon_peak After client.stop_notify
2023-02-01 20:37:51.603 DEBUG (MainThread) [custom_components.rd200_ble.rd200_ble.parser] Parsing data
2023-02-01 20:37:51.603 DEBUG (MainThread) [custom_components.rd200_ble.rd200_ble.parser] _get_radon_peak returning

-----after refresh timeout-----

2023-02-01 20:39:04.980 DEBUG (MainThread) [custom_components.rd200_ble.rd200_ble.parser] fetching peak
2023-02-01 20:39:04.980 DEBUG (MainThread) [custom_components.rd200_ble.rd200_ble.parser] _get_radon_peak
2023-02-01 20:39:04.980 DEBUG (MainThread) [custom_components.rd200_ble.rd200_ble.parser] _get_radon_peak before first await

I guess I can live without the peak, since that's sort of handled by HA itself anyway, but I'll keep poking it a bit more.

mck182 commented 1 year ago

I have now again tested with the EtoTen/radonreader where I've modified the write value to be the peak - \x40 and it reads it perfectly fine every time on the Pi, which leads me to believe the BT stack on the Pi is probably fine 🤔

jdeath commented 1 year ago

BT is finicky and etonten script and homeassistant may use a different software backend. Perhaps "stack" is the wrong term. It has to do with something called MTU. Homeassistant (on the backend, not the integration) caches connections. Each BT adapter can only have a few connections at a time, so homeassistant shares them between all connected devices. Before the proxy code was fixed, it works once on the initial connect, but then something forced the MTU to the default when it reconnects. When the MTU is the default, it only allows 20 bytes of data, but the RD200 wants to return 68 for the peak notify. I bet homeasistant on the Pi is doing this too.

My guess is entonten script owns the BT connection and never drops/shares it, or forces the MTU somehow. But I am guessing. USB adapters on X86 work just fine, so must be unique to the PI.

Long and short, it is a homeassistant issue. Either it is homeassistant or the BT software they use. I would make an issue there and reference EPSHOME issue 4041. Hopefully they can figure it out.

mck182 commented 1 year ago

Ah, that makes a lot of sense. Okay, I'll disable the peak for now and will go dig on the HA side.

Thanks for the support!

hejllukas commented 1 year ago

@mck182 I'm just letting you know that I created this issue https://github.com/home-assistant/core/issues/90307. I think I have exactly the same issue you have but with a different bluetooth device (Airthings Wave Plus).

hejllukas commented 1 year ago

@mck182 In https://github.com/home-assistant/core/issues/90307 bdraco mentioned that the bluetooth adapter in RPI isn't much stable and recommended using USB Bluetooth Adapter (one of the following https://www.home-assistant.io/integrations/bluetooth/#known-working-high-performance-adapters). So I bought one of them, and it seems that it fixed my issue, which was similar to your issue.