miflora plant sensors breaks after single error

[BramVe]

Home Assistant release (hass --version):
0.62.1

Python release (python3 --version):
Python 3.6.3

Component/platform:
miflora component
Bluetooth BCM43xx - version 1.1
Xiaomi version: v3.1.8

Description of problem:
The miflora component breaks after an error has occurred for one of the sensors, the speed at which this occurs depends on the amount of sensors.
Sensors are polled every 30 seconds (regardless of cache_value setting), polling is not sequenced but (pratically) simultaneously, possibly causing errors.
Whenever an error has occured all sensors stop working and report the WARNING message in the log:
Updating miflora sensor took longer than the scheduled update interval 0:00:30

Expected:
Expected behaviour is to be able to recover from a single failed poll. When there are limits in the amount of sensors that can be polled simultaneously, some mitigation is expected (e.g. queue).

Problem-relevant configuration.yaml entries and steps to reproduce:

sensor:
  - platform: miflora
    mac: C4:7C:8D:66:04:E9
    name: flower_1
    force_update: true
    median: 1
    timeout: 60
    cache_value: 300
    monitored_conditions:
      - moisture
      - light
      - temperature
      - conductivity
      - battery
  - platform: miflora
    mac: C4:7C:8D:66:05:1A
    name: flower_2
    force_update: true
    median: 1
    timeout: 60
    cache_value: 300
    monitored_conditions:
      - moisture
      - light
      - temperature
      - conductivity
      - battery
  - platform: miflora
    mac: C4:7C:8D:66:02:D5
    name: flower_4
    force_update: true
    median: 1
    timeout: 60
    cache_value: 300
    monitored_conditions:
      - moisture
      - light
      - temperature
      - conductivity
      - battery

1. Connect >2 sensors to miflora
2. Reboot RPi

Traceback (if applicable):
Traceback generated by activating the debug mode on sensors:

2018-02-03 14:52:44 ERROR (MainThread) [homeassistant.helpers.entity] Update for sensor.flower_2_battery fails
Traceback (most recent call last):
  File "/usr/lib/python3.6/site-packages/homeassistant/helpers/entity.py", line 201, in async_update_ha_state
    yield from self.async_device_update()
  File "/usr/lib/python3.6/site-packages/homeassistant/helpers/entity.py", line 308, in async_device_update
    yield from self.hass.async_add_job(self.update)
  File "/usr/lib/python3.6/asyncio/futures.py", line 332, in __iter__
    yield self  # This tells Task to wait for completion.
  File "/usr/lib/python3.6/asyncio/tasks.py", line 250, in _wakeup
    future.result()
  File "/usr/lib/python3.6/asyncio/futures.py", line 245, in result
    raise self._exception
  File "/usr/lib/python3.6/concurrent/futures/thread.py", line 56, in run
    result = self.fn(*self.args, **self.kwargs)
  File "/usr/lib/python3.6/site-packages/homeassistant/components/sensor/miflora.py", line 143, in update
    data = self.poller.parameter_value(self.parameter)
  File "/usr/lib/python3.6/site-packages/miflora/miflora_poller.py", line 121, in parameter_value
    return self.battery_level()
  File "/usr/lib/python3.6/site-packages/miflora/miflora_poller.py", line 91, in battery_level
    self.firmware_version()
  File "/usr/lib/python3.6/site-packages/miflora/miflora_poller.py", line 99, in firmware_version
    with self._bt_interface.connect(self._mac) as connection:
  File "/usr/lib/python3.6/site-packages/miflora/backends/__init__.py", line 40, in __enter__
    self._bt_interface.backend.connect(self.mac)
  File "/usr/lib/python3.6/site-packages/miflora/backends/bluepy.py", line 22, in connect
    self._peripheral = Peripheral(mac, iface=iface)
  File "/usr/lib/python3.6/site-packages/bluepy/btle.py", line 353, in __init__
    self._connect(deviceAddr, addrType, iface)
  File "/usr/lib/python3.6/site-packages/bluepy/btle.py", line 402, in _connect
    "Failed to connect to peripheral %s, addr type: %s" % (addr, addrType))
bluepy.btle.BTLEException: Failed to connect to peripheral C4:7C:8D:66:05:1A, addr type: public

Example of a regular log entry log:

2018-02-03 14:52:41 DEBUG (SyncWorker_3) [homeassistant.components.sensor.miflora] Polling data for flower_4 Conductivity
2018-02-03 14:52:41 DEBUG (SyncWorker_3) [homeassistant.components.sensor.miflora] flower_4 Conductivity = 317
2018-02-03 14:52:41 DEBUG (SyncWorker_3) [homeassistant.components.sensor.miflora] Data collected: [317]
2018-02-03 14:52:41 DEBUG (SyncWorker_3) [homeassistant.components.sensor.miflora] Median is: 317

After an error has occurred every 30 seconds the logbook shows:

2018-02-03 14:54:04 WARNING (MainThread) [homeassistant.components.sensor] Updating miflora sensor took longer than the scheduled update interval 0:00:30

Additional info:
I've read and tried to apply tips and solutions in the following threads:
home-assistant/supervisor#307
https://community.home-assistant.io/t/hass-io-xiaomi-sensor-show-nothing/34695
#10790

The following checks have been performed:

• Through debug SSH login hcitool lescan lists all 4 sensors I have
• Through debug SSH login bluetoothctl and then scan on shows all 4 sensors
• Any combination of having only 2 sensors in the configuration.yaml results in a stable working solution, but sensors are still polled every 30 seconds (which is quite an overkill for plant sensors).
• miflora sensors are disconnected from my phone app.

Any help is much appreciated!

[BramVe]

Found a pull request on miflora, it is however unclear to me if this PR resolves the issues above.
#12149

[BramVe]

Issue is not related to the amount of sensors, also with 2 sensors the polling is stopped after an error has occurred. The behaviour does occur earlier with more sensors.

[kennedyshead]

Bought a couple of these and awaiting for delivery, if no one else fixes this you have my word I will ;)

[ChristianKuehnel]

Fix is ready, waiting for an upstream release:
#12149

[BramVe]

Issue fixed after update. Thanks @ChristianKuehnel

[emwolf1]

Hi I believe this issue (or something with similar symptoms) may have returned. I'm on 0.69.1 and find daily log entries "updating miflora.. took longer than... update interval 0:00:30" and loss of sensor data. Anyone else with this issue? Any workarounds?

[andlo]

I do have same problem. It works after reboot for a cuppel of hours, and then stops updating :(

[ChristianKuehnel]

The slow updates usually come from a bad Bluetooth connection to the sensors, either the sensors are too far from the bluetooth device or there is just some random noise in the air disturbing the communication.

I can't really reproduce the issue. In my setup the miflora sensors are working fine. Can you provide more information?

How many plants?
Is any other component using the bluetooth device?
Are there any useful error messages in the log file?
If not: Can you switch on debug logging?

logger:
  default: info
  logs:
   miflora: debug
   btlewrap: debug

[emwolf1]

It's not that there are missing polls, they all work fine for hours, then stop working and will not poll until my daily reboot. I have 8 sensors at the moment. Most are within 2-3m. 2 are about 6-7m away. Will do the debug log next week when I'm back home.

[andlo]

I to have thos problem, and did turn ondebug. The log shows it is working fine for up to 7 hours, and then it stops updating - i am not the best at reading ths log, but it looks like it stops getting data - seems like the bluetooth just stops connecting to the devises.

2018-06-08 17:03:40 DEBUG (SyncWorker_9) [btlewrap.bluepy] Call to <function BluepyBackend.connect at 0x7295c300> failed, try 1 of 3
2018-06-08 17:03:40 DEBUG (SyncWorker_9) [btlewrap.bluepy] Call to <function BluepyBackend.connect at 0x7295c300> failed, try 2 of 3
2018-06-08 17:03:41 DEBUG (SyncWorker_9) [btlewrap.bluepy] Call to <function BluepyBackend.connect at 0x7295c300> failed, try 3 of 3
2018-06-08 17:03:41 INFO (SyncWorker_9) [homeassistant.components.sensor.miflora] Polling error
2018-06-08 17:03:41 INFO (MainThread) [homeassistant.core] Bus:Handling <Event state_changed[L]: entity_id=sensor.plant_9_light_intensity, old_state=<state sensor.plant_9_light_in$
2018-06-08 17:03:41 DEBUG (SyncWorker_1) [btlewrap.bluepy] Call to <function BluepyBackend.connect at 0x7295c300> failed, try 1 of 3
2018-06-08 17:03:41 ERROR (SyncWorker_6) [homeassistant.core] Error doing job: Task was destroyed but it is pending!
2018-06-08 17:03:41 DEBUG (SyncWorker_1) [btlewrap.bluepy] Call to <function BluepyBackend.connect at 0x7295c300> failed, try 2 of 3
2018-06-08 17:03:42 DEBUG (SyncWorker_1) [btlewrap.bluepy] Call to <function BluepyBackend.connect at 0x7295c300> failed, try 3 of 3
2018-06-08 17:03:42 INFO (SyncWorker_1) [homeassistant.components.sensor.miflora] Polling error
2018-06-08 17:03:42 INFO (MainThread) [homeassistant.core] Bus:Handling <Event state_changed[L]: entity_id=sensor.plant_10_battery, old_state=<state sensor.plant_10_battery=unknow$2018-06-08 17:03:42 DEBUG (SyncWorker_14) [miflora.miflora_poller] Using cache (0:15:03.024829 < 0:20:00)
2018-06-08 17:03:42 INFO (SyncWorker_14) [homeassistant.components.sensor.miflora] Polling error Could not read data from Mi Flora sensor c4:7c:8d:66:19:c6

[ChristianKuehnel]

Yes, it seems like we can't connect to the device anymore using the underlying bluepy library. It get us a bit closer to the root cause. I probably need to add more logging output to see why it failed to connect...

[andlo]

well - it has been working pritty well and stable for last few days

[pattyland]

Had Mi Flora running fine for weeks. Installed it yesterday at a friend, and it could'n get any values. Since I restart my hass today, my values are gone too. Log get's flooded with "Updating miflora sensor took longer than the scheduled update interval 0:00:30".

My debug shows the same output like @andlo

2018-06-24 14:09:59 DEBUG (SyncWorker_5) [btlewrap.bluepy] Call to <function BluepyBackend.connect at 0x72966810> failed, try 1 of 3
2018-06-24 14:10:21 WARNING (MainThread) [homeassistant.components.sensor] Updating miflora sensor took longer than the scheduled update interval 0:00:30
2018-06-24 14:10:40 DEBUG (SyncWorker_5) [btlewrap.bluepy] Call to <function BluepyBackend.connect at 0x72966810> failed, try 2 of 3
2018-06-24 14:10:52 WARNING (MainThread) [homeassistant.components.sensor] Updating miflora sensor took longer than the scheduled update interval 0:00:30