Integration Modbus - Error with Core Version > 2024.3.3

Wolfgang-03 commented 3 months ago

The problem

I am using a USB2Serial (RS485) adapter to get data from an energy meter, what has worked well for months.

After Updating from 2024.3.3 to 2024.4.3, I get the following error:

Logger: homeassistant.components.modbus.modbus
Source: components/modbus/modbus.py:318
integration: Modbus (documentation, issues)
First occurred: 15:16:56 (2 occurrences)
Last logged: 15:18:57

Pymodbus: EM_Heizung: Error: device: 0 address: 1024 -> Modbus Error: [Input/Output] ERROR: No response received after 3 retries
Pymodbus: EM_Heizung: Error: device: 0 address: 1056 -> Modbus Error: [Input/Output] ERROR: No response received after 3 retries

If I go back to version 2024.3.3 everything works fine. I have tried several version between, up to 2024.6.2, the problem still remains the same. Only line number chages from 318 (2024.4.3) to 331 (2024.6.2)

Source: components/modbus/modbus.py:318 Source: components/modbus/modbus.py:331

Here is my hardware-configuration:

ttyUSB0 /dev/serial/by-id/usb-1a86_USB_Serial-if00-port0
Subsystem: tty
Device path: /dev/ttyUSB0
ID: /dev/serial/by-id/usb-1a86_USB_Serial-if00-port0

DEVLINKS: >-
/dev/serial/by-id/usb-1a86_USB_Serial-if00-port0
/dev/serial/by-path/pci-0000:00:06.1-usb-0:2:1.0-port0
/dev/serial/by-path/pci-0000:00:06.1-usbv1-0:2:1.0-port0
DEVNAME: /dev/ttyUSB0
DEVPATH: /devices/pci0000:00/0000:00:06.1/usb3/3-2/3-2:1.0/ttyUSB0/tty/ttyUSB0
ID_BUS: usb
ID_MODEL: USB_Serial
ID_MODEL_ENC: USB\x20Serial
ID_MODEL_ID: ‘7523’
ID_PATH: pci-0000:00:06.1-usb-0:2:1.0
ID_PATH_TAG: pci-0000_00_06_1-usb-0_2_1_0
ID_PATH_WITH_USB_REVISION: pci-0000:00:06.1-usbv1-0:2:1.0
ID_REVISION: ‘0264’
ID_SERIAL: 1a86_USB_Serial
ID_TYPE: generic
ID_USB_DRIVER: ch341
ID_USB_INTERFACES: ‘:ff0102:’
ID_USB_INTERFACE_NUM: ‘00’
ID_USB_MODEL: USB_Serial
ID_USB_MODEL_ENC: USB\x20Serial
ID_USB_MODEL_ID: ‘7523’
ID_USB_REVISION: ‘0264’
ID_USB_SERIAL: 1a86_USB_Serial
ID_USB_TYPE: generic
ID_USB_VENDOR: 1a86
ID_USB_VENDOR_ENC: 1a86
ID_USB_VENDOR_ID: 1a86
ID_VENDOR: 1a86
ID_VENDOR_ENC: 1a86
ID_VENDOR_ID: 1a86
MAJOR: ‘188’
MINOR: ‘0’
SUBSYSTEM: tty
TAGS: ‘:systemd:’
USEC_INITIALIZED: ‘9600961691’

What version of Home Assistant Core has the issue?

core-2024.4.1 .. core-2024.6.2

What was the last working version of Home Assistant Core?

core-2024.3.3

What type of installation are you running?

Home Assistant OS

Integration causing the issue

Modbus

Link to integration documentation on our website

https://www.home-assistant.io/integrations/modbus/

Diagnostics information

No response

Example YAML snippet

modbus:
  - name: EM_Heizung
    type: serial
    port: /dev/ttyUSB1
    baudrate: 115200
    bytesize: 8
    method: rtu
    parity: N
    stopbits: 1
    delay: 0
    message_wait_milliseconds: 60
    timeout: 50
    sensors:
      - name: EM L1 Voltage
        unique_id: em_l1_voltage
        unit_of_measurement: V
        address: 0x0400
        data_type: uint32
        scale: 0.001
        precision: 3
        state_class: measurement
        scan_interval: 30

      # here are many more sensors

      - name: EM Total Power
        unique_id: em_total_power
        unit_of_measurement: W
        address: 0x0420
        data_type: uint32
        scan_interval: 10

Anything in the logs that might be useful for us?

Logger: homeassistant.components.modbus.modbus
Source: components/modbus/modbus.py:331
integration: Modbus (documentation, issues)
First occurred: 14:37:54 (2 occurrences)
Last logged: 14:57:55

    Pymodbus: EM_Heizung: Error: device: 0 address: 1024 -> Modbus Error: [Input/Output] ERROR: No response received after 3 retries
    Pymodbus: EM_Heizung: Error: device: 0 address: 1054 -> Modbus Error: [Input/Output] ERROR: No response received after 3 retries

Additional information

home-assistant[bot] commented 3 months ago

Hey there @janiversen, mind taking a look at this issue as it has been labeled with an integration (modbus) you are listed as a code owner for? Thanks!

Code owner commands

Code owners of `modbus` can trigger bot actions by commenting: - `@home-assistant close` Closes the issue. - `@home-assistant rename Awesome new title` Renames the issue. - `@home-assistant reopen` Reopen the issue. - `@home-assistant unassign modbus` Removes the current integration label and assignees on the issue, add the integration domain after the command. - `@home-assistant add-label needs-more-information` Add a label (needs-more-information, problem in dependency, problem in custom component) to the issue. - `@home-assistant remove-label needs-more-information` Remove a label (needs-more-information, problem in dependency, problem in custom component) on the issue.

_{^{(message by CodeOwnersMention)}}

modbus documentation modbus source _{^{(message by IssueLinks)}}

janiversen commented 3 months ago

That is your device, not responding.

Please add a debug log as pr modbus integration documentation.

Wolfgang-03 commented 3 months ago

I went back to 2024.6.2. After a restart, the log looks like this:

2024-06-12 20:52:17.384 WARNING (SyncWorker_0) [homeassistant.loader] We found a custom integration landroid_cloud which has not been tested by Home Assistant. This component might cause stability problems, be sure to disable it if you experience issues with Home Assistant
2024-06-12 20:52:17.384 WARNING (SyncWorker_0) [homeassistant.loader] We found a custom integration robovac which has not been tested by Home Assistant. This component might cause stability problems, be sure to disable it if you experience issues with Home Assistant
2024-06-12 20:52:17.385 WARNING (SyncWorker_0) [homeassistant.loader] We found a custom integration icloud3 which has not been tested by Home Assistant. This component might cause stability problems, be sure to disable it if you experience issues with Home Assistant
2024-06-12 20:52:17.385 WARNING (SyncWorker_0) [homeassistant.loader] We found a custom integration hacs which has not been tested by Home Assistant. This component might cause stability problems, be sure to disable it if you experience issues with Home Assistant
2024-06-12 20:52:21.317 ERROR (MainThread) [homeassistant.components.notify] Failed to initialize notification service file
2024-06-12 20:52:21.317 ERROR (MainThread) [homeassistant.components.notify] Failed to initialize notification service file
2024-06-12 20:52:21.317 ERROR (MainThread) [homeassistant.components.notify] Failed to initialize notification service file
2024-06-12 20:52:22.690 WARNING (MainThread) [homeassistant.helpers.frame] Detected that custom integration 'hacs' accesses hass.components.frontend. This is deprecated and will stop working in Home Assistant 2024.9, it should be updated to import functions used from frontend directly at custom_components/hacs/frontend.py, line 68: hass.components.frontend.async_register_built_in_panel(, please create a bug report at https://github.com/hacs/integration/issues
2024-06-12 20:55:41.406 ERROR (MainThread) [homeassistant.components.modbus.modbus] Pymodbus: EM_Heizung: Error: device: 0 address: 1024 -> Modbus Error: [Input/Output] ERROR: No response received after 3 retries
2024-06-12 20:57:32.981 WARNING (MainThread) [homeassistant.bootstrap] Setup timed out for bootstrap waiting on {<Task pending name='call_later 0.1' coro=<ModbusRegisterSensor.async_update() running at /usr/src/homeassistant/homeassistant/components/modbus/sensor.py:113> wait_for=<Future pending cb=[Task.task_wakeup()]> cb=[set.remove()]>, <Task pending name='call_later 0.1' coro=<ModbusRegisterSensor.async_update() running at /usr/src/homeassistant/homeassistant/components/modbus/sensor.py:113> wait_for=<Future pending cb=[Task.task_wakeup()]> cb=[set.remove()]>, <Task pending name='call_later 0.1' coro=<ModbusRegisterSensor.async_update() running at /usr/src/homeassistant/homeassistant/components/modbus/sensor.py:113> wait_for=<Future pending cb=[Task.task_wakeup()]> cb=[set.remove()]>, <Task pending name='call_later 0.1' coro=<ModbusRegisterSensor.async_update() running at /usr/src/homeassistant/homeassistant/components/modbus/sensor.py:113> wait_for=<Future pending cb=[Task.task_wakeup()]> cb=[set.remove()]>, <Task pending name='call_later 0.1' coro=<ModbusRegisterSensor.async_update() running at /usr/src/homeassistant/homeassistant/components/modbus/sensor.py:113> wait_for=<Future pending cb=[Task.task_wakeup()]> cb=[set.remove()]>, <Task pending name='call_later 0.1' coro=<ModbusRegisterSensor.async_update() running at /usr/src/homeassistant/homeassistant/components/modbus/sensor.py:113> wait_for=<Future pending cb=[Task.task_wakeup()]> cb=[set.remove()]>, <Task pending name='call_later 0.1' coro=<ModbusRegisterSensor.async_update() running at /usr/src/homeassistant/homeassistant/components/modbus/sensor.py:113> wait_for=<Future pending cb=[Task.task_wakeup()]> cb=[set.remove()]>, <Task pending name='call_later 0.1' coro=<ModbusRegisterSensor.async_update() running at /usr/src/homeassistant/homeassistant/components/modbus/sensor.py:113> wait_for=<Future pending cb=[Task.task_wakeup()]> cb=[set.remove()]>, <Task pending name='call_later 0.1' coro=<ModbusRegisterSensor.async_update() running at /usr/src/homeassistant/homeassistant/components/modbus/sensor.py:113> wait_for=<Future pending cb=[Task.task_wakeup()]> cb=[set.remove()]>, <Task pending name='call_later 0.1' coro=<ModbusRegisterSensor.async_update() running at /usr/src/homeassistant/homeassistant/components/modbus/sensor.py:113> wait_for=<Future pending cb=[Task.task_wakeup()]> cb=[set.remove()]>, <Task pending name='call_later 0.1' coro=<ModbusRegisterSensor.async_update() running at /usr/src/homeassistant/homeassistant/components/modbus/sensor.py:113> wait_for=<Future pending cb=[Task.task_wakeup()]> cb=[set.remove()]>, <Task pending name='call_later 0.1' coro=<ModbusRegisterSensor.async_update() running at /usr/src/homeassistant/homeassistant/components/modbus/sensor.py:113> wait_for=<Future pending cb=[Task.task_wakeup()]> cb=[set.remove()]>, <Task pending name='call_later 0.1' coro=<ModbusRegisterSensor.async_update() running at /usr/src/homeassistant/homeassistant/components/modbus/sensor.py:113> wait_for=<Future pending cb=[Task.task_wakeup()]> cb=[set.remove()]>, <Task pending name='call_later 0.1' coro=<ModbusRegisterSensor.async_update() running at /usr/src/homeassistant/homeassistant/components/modbus/sensor.py:113> wait_for=<Future pending cb=[Task.task_wakeup()]> cb=[set.remove()]>, <Task pending name='call_later 0.1' coro=<ModbusRegisterSensor.async_update() running at /usr/src/homeassistant/homeassistant/components/modbus/sensor.py:113> wait_for=<Future pending cb=[Task.task_wakeup()]> cb=[set.remove()]>} - moving forward
2024-06-12 20:57:33.074 WARNING (MainThread) [homeassistant.helpers.frame] Detected that custom integration 'hacs' accesses hass.helpers.event. This is deprecated and will stop working in Home Assistant 2024.11, it should be updated to import functions used from event directly at custom_components/hacs/base.py, line 630: self.hass.helpers.event.async_track_time_interval(, please create a bug report at https://github.com/hacs/integration/issues
2024-06-12 20:57:48.067 WARNING (MainThread) [homeassistant.core] Something is blocking Home Assistant from wrapping up the start up phase. We're going to continue anyway. Please report the following info at https://github.com/home-assistant/core/issues: ssdp, tts, modbus, file, backup, landroid_cloud.select, cloud, persistent_notification, mobile_app.binary_sensor, openweathermap, fritz.sensor, landroid_cloud, reolink.number, group.notify, cover, ffmpeg, ping, mqtt.update, group, landroid_cloud.binary_sensor, websocket_api, update, shelly, robovac, filesize.sensor, notify, light, fritz.switch, schedule, template, bmw_connected_drive.button, system_health, utility_meter, timer, device_automation, utility_meter.sensor, worxlandroid.sensor, ping.device_tracker, braviatv.remote, assist_pipeline, sun, template.sensor, input_select, shelly.button, bmw_connected_drive.lock, forecast_solar.sensor, cloud.tts, application_credentials, reolink.siren, mqtt, usb, mqtt.text, shelly.light, search, filesize, map, landroid_cloud.lawn_mower, reolink.select, landroid_cloud.button, met.weather, http, dlna_dmr, script, recorder, google_translate.tts, analytics, shelly.valve, landroid_cloud.number, shelly.update, input_number, hacs, my, device_tracker, input_button, mqtt.scene, ping.binary_sensor, icloud3, conversation, lawn_mower, mqtt.switch, smtp.notify, sun.sensor, reolink.sensor, wake_word, hassio, event, network, media_player, mqtt.climate, shelly.climate, hassio.binary_sensor, ipp, bmw_connected_drive.number, select, mobile_app.notify, androidtv_remote.remote, siren, reolink.switch, icloud3.sensor, energy.sensor, scene, mobile_app, climate, homeassistant, auth, homeassistant_alerts, dlna_dms, input_datetime, button, androidtv_remote.media_player, braviatv.media_player, hassio.sensor, cast, file.notify, vacuum, hacs.sensor, repairs, met, automation, reolink.light, trace, lock, camera, bmw_connected_drive.device_tracker, image, snmp.sensor, valve, reolink.binary_sensor, logbook, integration.sensor, androidtv_remote, velux.light, mqtt.binary_sensor, braviatv.button, fritz.device_tracker, bmw_connected_drive.select, bmw_connected_drive.notify, reolink.button, mqtt.select, system_log, bmw_connected_drive, modbus.sensor, reolink, mqtt.lock, bmw_connected_drive.binary_sensor, zeroconf, shelly.event, landroid_cloud.sensor, counter, fritz, input_boolean, weather, velux.cover, fritz.update, zone, hassio.update, bmw_connected_drive.switch, braviatv, mqtt.button, onboarding, config, python_script, webhook, stream, default_config, file_upload, reolink.update, stt, tag, radio_browser, cast.media_player, diagnostics, dlna_dmr.media_player, reolink.camera, robovac.vacuum, mqtt.number, shelly.switch, intent, template.binary_sensor, shelly.cover, dhcp, bmw_connected_drive.sensor, number, homeassistant.scene, sensor, fritz.binary_sensor, frontend, image_upload, velux.scene, api, hardware, fritz.button, binary_sensor, mobile_app.device_tracker, history, logger, icloud3.device_tracker, shelly.sensor, blueprint, mobile_app.sensor, mqtt.sensor, switch, ping.sensor, robovac.sensor, bluetooth, shelly.binary_sensor, forecast_solar, text, landroid_cloud.switch, fritz.image, ipp.sensor, lovelace, input_text, velux, media_source, person, energy, remote The system is waiting for tasks: {<Task pending name='call_later 0.1' coro=<ModbusRegisterSensor.async_update() running at /usr/src/homeassistant/homeassistant/components/modbus/sensor.py:113> wait_for=<Future pending cb=[Task.task_wakeup()]> cb=[set.remove()]>, <Task pending name='call_later 0.1' coro=<ModbusRegisterSensor.async_update() running at /usr/src/homeassistant/homeassistant/components/modbus/sensor.py:113> wait_for=<Future pending cb=[Task.task_wakeup()]> cb=[set.remove()]>, <Task pending name='call_later 0.1' coro=<ModbusRegisterSensor.async_update() running at /usr/src/homeassistant/homeassistant/components/modbus/sensor.py:113> wait_for=<Future pending cb=[Task.task_wakeup()]> cb=[set.remove()]>, <Task pending name='call_later 0.1' coro=<ModbusRegisterSensor.async_update() running at /usr/src/homeassistant/homeassistant/components/modbus/sensor.py:113> wait_for=<Future pending cb=[Task.task_wakeup()]> cb=[set.remove()]>, <Task pending name='call_later 0.1' coro=<ModbusRegisterSensor.async_update() running at /usr/src/homeassistant/homeassistant/components/modbus/sensor.py:113> wait_for=<Future pending cb=[Task.task_wakeup()]> cb=[set.remove()]>, <Task pending name='call_later 0.1' coro=<ModbusRegisterSensor.async_update() running at /usr/src/homeassistant/homeassistant/components/modbus/sensor.py:113> wait_for=<Future pending cb=[Task.task_wakeup()]> cb=[set.remove()]>, <Task pending name='call_later 0.1' coro=<ModbusRegisterSensor.async_update() running at /usr/src/homeassistant/homeassistant/components/modbus/sensor.py:113> wait_for=<Future pending cb=[Task.task_wakeup()]> cb=[set.remove()]>, <Task pending name='call_later 0.1' coro=<ModbusRegisterSensor.async_update() running at /usr/src/homeassistant/homeassistant/components/modbus/sensor.py:113> wait_for=<Future pending cb=[Task.task_wakeup()]> cb=[set.remove()]>, <Task pending name='call_later 0.1' coro=<ModbusRegisterSensor.async_update() running at /usr/src/homeassistant/homeassistant/components/modbus/sensor.py:113> wait_for=<Future pending cb=[Task.task_wakeup()]> cb=[set.remove()]>, <Task pending name='call_later 0.1' coro=<ModbusRegisterSensor.async_update() running at /usr/src/homeassistant/homeassistant/components/modbus/sensor.py:113> wait_for=<Future pending cb=[Task.task_wakeup()]> cb=[set.remove()]>, <Task pending name='call_later 0.1' coro=<ModbusRegisterSensor.async_update() running at /usr/src/homeassistant/homeassistant/components/modbus/sensor.py:113> wait_for=<Future pending cb=[Task.task_wakeup()]> cb=[set.remove()]>, <Task pending name='call_later 0.1' coro=<ModbusRegisterSensor.async_update() running at /usr/src/homeassistant/homeassistant/components/modbus/sensor.py:113> wait_for=<Future pending cb=[Task.task_wakeup()]> cb=[set.remove()]>, <Task pending name='call_later 0.1' coro=<ModbusRegisterSensor.async_update() running at /usr/src/homeassistant/homeassistant/components/modbus/sensor.py:113> wait_for=<Future pending cb=[Task.task_wakeup()]> cb=[set.remove()]>, <Task pending name='call_later 0.1' coro=<ModbusRegisterSensor.async_update() running at /usr/src/homeassistant/homeassistant/components/modbus/sensor.py:113> wait_for=<Future pending cb=[Task.task_wakeup()]> cb=[set.remove()]>, <Task pending name='call_later 0.1' coro=<ModbusRegisterSensor.async_update() running at /usr/src/homeassistant/homeassistant/components/modbus/sensor.py:113> wait_for=<Future pending cb=[Task.task_wakeup()]> cb=[set.remove()]>}
2024-06-12 21:15:42.276 ERROR (MainThread) [homeassistant.components.modbus.modbus] Pymodbus: EM_Heizung: Error: device: 0 address: 1054 -> Modbus Error: [Input/Output] ERROR: No response received after 3 retries
2024-06-12 21:15:42.400 ERROR (MainThread) [homeassistant.components.template.template_entity] TemplateError('ValueError: Template error: float got invalid input 'unavailable' when rendering template '{% if float(states('sensor.em_total_power')) - float(states('sensor.shellyplus1pm_bwwp_switch_0_power')) < 0 %}
  {{ [float(states('sensor.em_total_power')), float(32.222)] | min }}
{% else %}
  {{ float(states('sensor.em_total_power')) - float(states('sensor.shellyplus1pm_bwwp_switch_0_power')) }}
{% endif %}' but no default was specified') while processing template 'Template<template=({% if float(states('sensor.em_total_power')) - float(states('sensor.shellyplus1pm_bwwp_switch_0_power')) < 0 %}
  {{ [float(states('sensor.em_total_power')), float(32.222)] | min }}
{% else %}
  {{ float(states('sensor.em_total_power')) - float(states('sensor.shellyplus1pm_bwwp_switch_0_power')) }}
{% endif %}) renders=6>' for attribute '_attr_native_value' in entity 'sensor.heizung_total_power'
2024-06-12 21:15:42.401 ERROR (MainThread) [homeassistant.components.template.template_entity] TemplateError('ValueError: Template error: float got invalid input 'unavailable' when rendering template '{{ float(states('sensor.em_total_power')) - float(states('sensor.heizung_total_power')) }}' but no default was specified') while processing template 'Template<template=({{ float(states('sensor.em_total_power')) - float(states('sensor.heizung_total_power')) }}) renders=6>' for attribute '_attr_native_value' in entity 'sensor.warmwasser_total_power'

How can it be my device that is not responding when it works perfectly with 2024.3.3?

janiversen commented 3 months ago

Because the software is different (see release notes), and the demanded python version is different.

I need to see a debug log, to determine if there is a bug in the modbus integration

Wolfgang-03 commented 3 months ago

home-assistant-debug.log

janiversen commented 3 months ago

As I suspected:

2024-06-12 21:52:06.833 DEBUG (MainThread) [pymodbus.logging] Connection lost comm due to Server not responding

your device stops responding or something in between stops the traffic.

But the communication gets back to normal, so what is the real problem?

janiversen commented 3 months ago

And you have an error in your template:

{% endif %}) renders=2> Traceback (most recent call last): File "/usr/src/homeassistant/homeassistant/helpers/template.py", line 2229, in forgiving_float return float(value) ^^^^^^^^^^^^ ValueError: could not convert string to float: 'unknown'

Wolfgang-03 commented 3 months ago

And you have an error in your template:

{% endif %}) renders=2> Traceback (most recent call last): File "/usr/src/homeassistant/homeassistant/helpers/template.py", line 2229, in forgiving_float return float(value) ^^^^^^^^^^^^ ValueError: could not convert string to float: 'unknown'

The problem is, that the entity did not recive a valid value from modbus integration and so the value of the entity is set to "unknown". And "unknown" could not be converted to a float. I can of course rewrite the template and intercept the dropouts, but the dropouts are so large and so long that this is an unsatisfactory solution. And until version 2024.3.3, it always worked properly, with out dropouts.

grafik

your device stops responding or something in between stops the traffic.

I can't believe that there is a technical problem and the device stops responding. Why should the device do this, just because the querying software has been changed? There is also nothing in between, just one cable and and one electricity meter, no other devices on the same bus.

janiversen commented 3 months ago

No it actually worked wrong, because the dropouts was not reported, now all drop outs are reported (and due to the speed more are detected).

you might not believe it, but the modbus integration do not receive any data even after 3 retries, and I have not seen any logs that indicate a problem within the integration.

And there are a lot of things in between...the python interpreter, pyserial, hass, core which all have changed too, and of course your usb adapter which python might use differently.

Wolfgang-03 commented 3 months ago

But it doesn't stop at dropouts. In the end, I no longer get any data at all with 2024.6.2.

grafik

I don't know what the problem is, but if I go back to 2024.3.3, I get data again. So I went back to 2024.3.3 and then created a debug log, maybe that will help narrow down the problem?

home-assistant-debug_2024_3_3.log

There is always only 15-20 ms between "WAITING FOR REPLY" and "PROCESSING REPLY".

And all entities are available.

grafik

For 2024.6.2, all are set to "unavailable".

Wolfgang-03 commented 3 months ago

I replaced the USB2Serial (RS485) adapter to a complete new one. This one registers himself on /dev/ttyACM0.

grafik

Unfortunately with the same result. Runs under 2024.3.3, does not run under 2024.6.2

No unexpected dropout with 2024.3.3 grafik

After startup with 2024.6.2 I receive some data from modbus. grafik

Severall minutes later, more and more entities change to unavailable. grafik

I would assume that it has something to do with these two entries in the log:

2024-06-13 14:14:21.282 WARNING (MainThread) [homeassistant.bootstrap] Setup timed out for bootstrap waiting on {<Task pending name='call_later 0.1' coro=<ModbusRegisterSensor.async_update() running at /usr/src/homeassistant/homeassistant/components/modbus/sensor.py:113> wait_for=<Future pending cb=[Task.task_wakeup()]> cb=[set.remove()]>, <Task pending name='call_later 0.1' coro=<ModbusRegisterSensor.async_update() running at /usr/src/homeassistant/homeassistant/components/modbus/sensor.py:113> wait_for=<Future pending cb=[Task.task_wakeup()]> cb=[set.remove()]>, <Task pending name='call_later 0.1' coro=<ModbusRegisterSensor.async_update() running at /usr/src/homeassistant/homeassistant/components/modbus/sensor.py:113> wait_for=<Future pending cb=[Task.task_wakeup()]> cb=[set.remove()]>, <Task pending name='call_later 0.1' coro=<ModbusRegisterSensor.async_update() running at /usr/src/homeassistant/homeassistant/components/modbus/sensor.py:113> wait_for=<Future pending cb=[Task.task_wakeup()]> cb=[set.remove()]>, <Task pending name='call_later 0.1' coro=<ModbusRegisterSensor.async_update() running at /usr/src/homeassistant/homeassistant/components/modbus/sensor.py:113> wait_for=<Future pending cb=[Task.task_wakeup()]> cb=[set.remove()]>, <Task pending name='call_later 0.1' coro=<ModbusRegisterSensor.async_update() running at /usr/src/homeassistant/homeassistant/components/modbus/sensor.py:113> wait_for=<Future pending cb=[Task.task_wakeup()]> cb=[set.remove()]>, <Task pending name='call_later 0.1' coro=<ModbusRegisterSensor.async_update() running at /usr/src/homeassistant/homeassistant/components/modbus/sensor.py:113> wait_for=<Future pending cb=[Task.task_wakeup()]> cb=[set.remove()]>, <Task pending name='call_later 0.1' coro=<ModbusRegisterSensor.async_update() running at /usr/src/homeassistant/homeassistant/components/modbus/sensor.py:113> wait_for=<Future pending cb=[Task.task_wakeup()]> cb=[set.remove()]>, <Task pending name='call_later 0.1' coro=<ModbusRegisterSensor.async_update() running at /usr/src/homeassistant/homeassistant/components/modbus/sensor.py:113> wait_for=<Future pending cb=[Task.task_wakeup()]> cb=[set.remove()]>, <Task pending name='call_later 0.1' coro=<ModbusRegisterSensor.async_update() running at /usr/src/homeassistant/homeassistant/components/modbus/sensor.py:113> wait_for=<Future pending cb=[Task.task_wakeup()]> cb=[set.remove()]>, <Task pending name='call_later 0.1' coro=<ModbusRegisterSensor.async_update() running at /usr/src/homeassistant/homeassistant/components/modbus/sensor.py:113> wait_for=<Future pending cb=[Task.task_wakeup()]> cb=[set.remove()]>, <Task pending name='call_later 0.1' coro=<ModbusRegisterSensor.async_update() running at /usr/src/homeassistant/homeassistant/components/modbus/sensor.py:113> wait_for=<Future pending cb=[Task.task_wakeup()]> cb=[set.remove()]>, <Task pending name='call_later 0.1' coro=<ModbusRegisterSensor.async_update() running at /usr/src/homeassistant/homeassistant/components/modbus/sensor.py:113> wait_for=<Future pending cb=[Task.task_wakeup()]> cb=[set.remove()]>, <Task pending name='call_later 0.1' coro=<ModbusRegisterSensor.async_update() running at /usr/src/homeassistant/homeassistant/components/modbus/sensor.py:113> wait_for=<Future pending cb=[Task.task_wakeup()]> cb=[set.remove()]>, <Task pending name='call_later 0.1' coro=<ModbusRegisterSensor.async_update() running at /usr/src/homeassistant/homeassistant/components/modbus/sensor.py:113> wait_for=<Future pending cb=[Task.task_wakeup()]> cb=[set.remove()]>} - moving forward

The system is waiting for tasks: {<Task pending name='call_later 0.1' coro=<ModbusRegisterSensor.async_update() running at /usr/src/homeassistant/homeassistant/components/modbus/sensor.py:113>

2024-06-13 14:14:36.362 WARNING (MainThread) [homeassistant.core] Something is blocking Home Assistant from wrapping up the start up phase. We're going to continue anyway. Please report the following info at https://github.com/home-assistant/core/issues: hassio.sensor, tts, timer, device_tracker, map, fritz, trace, reolink.select, ipp.sensor, stt, number, dlna_dms, mqtt.update, select, search, mqtt.switch, network, landroid_cloud.button, lovelace, group.notify, androidtv_remote.media_player, forecast_solar.sensor, default_config, reolink.button, hassio.binary_sensor, mobile_app.sensor, braviatv.button, shelly.climate, utility_meter.sensor, integration.sensor, reolink.siren, reolink.switch, system_health, braviatv.media_player, group, input_boolean, mqtt, dlna_dmr.media_player, shelly.event, onboarding, shelly.light, logbook, input_select, filesize.sensor, icloud3.device_tracker, reolink.camera, lawn_mower, shelly.cover, application_credentials, google_translate.tts, image_upload, homeassistant_alerts, lock, modbus, ping, api, cloud, shelly.valve, landroid_cloud.lawn_mower, mqtt.scene, mqtt.climate, fritz.binary_sensor, websocket_api, http, switch, sun, my, radio_browser, shelly.switch, automation, hassio, hassio.update, script, event, input_text, bmw_connected_drive.lock, counter, sun.sensor, utility_meter, reolink, bluetooth, bmw_connected_drive.switch, openweathermap.sensor, landroid_cloud.binary_sensor, input_number, reolink.number, landroid_cloud.select, shelly.sensor, config, text, binary_sensor, zone, mqtt.text, shelly.update, landroid_cloud.switch, reolink.binary_sensor, logger, history, mqtt.sensor, assist_pipeline, velux, vacuum, frontend, worxlandroid.sensor, bmw_connected_drive.number, persistent_notification, hardware, fritz.device_tracker, fritz.image, hacs, auth, button, modbus.sensor, shelly.button, zeroconf, device_automation, light, webhook, backup, met, icloud3, androidtv_remote.remote, ffmpeg, update, bmw_connected_drive.button, filesize, mqtt.binary_sensor, reolink.update, velux.scene, mqtt.number, mobile_app.notify, landroid_cloud.sensor, image, mobile_app, openweathermap, velux.light, icloud3.sensor, fritz.button, energy.sensor, cast.media_player, bmw_connected_drive.binary_sensor, siren, dlna_dmr, landroid_cloud, cloud.tts, mobile_app.binary_sensor, robovac.sensor, fritz.sensor, camera, person, wake_word, input_button, forecast_solar, robovac, landroid_cloud.number, mobile_app.device_tracker, reolink.sensor, cast, template.sensor, fritz.update, diagnostics, weather, template.binary_sensor, homeassistant.scene, mqtt.lock, mqtt.select, file_upload, shelly, snmp.sensor, ping.binary_sensor, remote, ping.sensor, bmw_connected_drive.select, homeassistant, template, velux.cover, climate, stream, dhcp, sensor, intent, valve, braviatv.remote, bmw_connected_drive.sensor, reolink.light, file.notify, met.weather, bmw_connected_drive.device_tracker, media_player, mqtt.button, repairs, androidtv_remote, notify, blueprint, ipp, fritz.switch, usb, python_script, analytics, system_log, conversation, bmw_connected_drive, ping.device_tracker, media_source, shelly.binary_sensor, smtp.notify, ssdp, braviatv, schedule, openweathermap.weather, robovac.vacuum, input_datetime, scene, tag, cover, energy, file, hacs.sensor, recorder, bmw_connected_drive.notify The system is waiting for tasks: {<Task pending name='call_later 0.1' coro=<ModbusRegisterSensor.async_update() running at /usr/src/homeassistant/homeassistant/components/modbus/sensor.py:113> wait_for=<Future pending cb=[Task.task_wakeup()]> cb=[set.remove()]>, <Task pending name='call_later 0.1' coro=<ModbusRegisterSensor.async_update() running at /usr/src/homeassistant/homeassistant/components/modbus/sensor.py:113> wait_for=<Future pending cb=[Task.task_wakeup()]> cb=[set.remove()]>, <Task pending name='call_later 0.1' coro=<ModbusRegisterSensor.async_update() running at /usr/src/homeassistant/homeassistant/components/modbus/sensor.py:113> wait_for=<Future pending cb=[Task.task_wakeup()]> cb=[set.remove()]>, <Task pending name='call_later 0.1' coro=<ModbusRegisterSensor.async_update() running at /usr/src/homeassistant/homeassistant/components/modbus/sensor.py:113> wait_for=<Future pending cb=[Task.task_wakeup()]> cb=[set.remove()]>, <Task pending name='call_later 0.1' coro=<ModbusRegisterSensor.async_update() running at /usr/src/homeassistant/homeassistant/components/modbus/sensor.py:113> wait_for=<Future pending cb=[Task.task_wakeup()]> cb=[set.remove()]>, <Task pending name='call_later 0.1' coro=<ModbusRegisterSensor.async_update() running at /usr/src/homeassistant/homeassistant/components/modbus/sensor.py:113> wait_for=<Future pending cb=[Task.task_wakeup()]> cb=[set.remove()]>, <Task pending name='call_later 0.1' coro=<ModbusRegisterSensor.async_update() running at /usr/src/homeassistant/homeassistant/components/modbus/sensor.py:113> wait_for=<Future pending cb=[Task.task_wakeup()]> cb=[set.remove()]>, <Task pending name='call_later 0.1' coro=<ModbusRegisterSensor.async_update() running at /usr/src/homeassistant/homeassistant/components/modbus/sensor.py:113> wait_for=<Future pending cb=[Task.task_wakeup()]> cb=[set.remove()]>, <Task pending name='call_later 0.1' coro=<ModbusRegisterSensor.async_update() running at /usr/src/homeassistant/homeassistant/components/modbus/sensor.py:113> wait_for=<Future pending cb=[Task.task_wakeup()]> cb=[set.remove()]>, <Task pending name='call_later 0.1' coro=<ModbusRegisterSensor.async_update() running at /usr/src/homeassistant/homeassistant/components/modbus/sensor.py:113> wait_for=<Future pending cb=[Task.task_wakeup()]> cb=[set.remove()]>, <Task pending name='call_later 0.1' coro=<ModbusRegisterSensor.async_update() running at /usr/src/homeassistant/homeassistant/components/modbus/sensor.py:113> wait_for=<Future pending cb=[Task.task_wakeup()]> cb=[set.remove()]>, <Task pending name='call_later 0.1' coro=<ModbusRegisterSensor.async_update() running at /usr/src/homeassistant/homeassistant/components/modbus/sensor.py:113> wait_for=<Future pending cb=[Task.task_wakeup()]> cb=[set.remove()]>, <Task pending name='call_later 0.1' coro=<ModbusRegisterSensor.async_update() running at /usr/src/homeassistant/homeassistant/components/modbus/sensor.py:113> wait_for=<Future pending cb=[Task.task_wakeup()]> cb=[set.remove()]>, <Task pending name='call_later 0.1' coro=<ModbusRegisterSensor.async_update() running at /usr/src/homeassistant/homeassistant/components/modbus/sensor.py:113> wait_for=<Future pending cb=[Task.task_wakeup()]> cb=[set.remove()]>, <Task pending name='call_later 0.1' coro=<ModbusRegisterSensor.async_update() running at /usr/src/homeassistant/homeassistant/components/modbus/sensor.py:113> wait_for=<Future pending cb=[Task.task_wakeup()]> cb=[set.remove()]>}

I have made new debug-logs for you, first one is on 2024.3.3, second on 2024.6.2 home-assistant_debug_2024_3_3_newUSB.log home-assistant-debug_2024_6_2_newUSB.log

Please take a look at line 2253, 2255, 4345, 4347, 6474, 6476 in the second one.

Thanks!

janiversen commented 3 months ago

What I can see is that in line 2262, 4364 .... the modbus integration start delivering data again.

Wolfgang-03 commented 3 months ago

I have noticed that a modbus/tcp integration is also active in my productive configuration, which runs smoothly, also under 2024.6.2. However, this modbus/tcp integration also writes data to the debug log file and makes things confusing.

To avoid mixing up things and to be sure that there went nothing wrong with my productive system, I have set up a new Raspi4 with a newly installed HA-OS, on which nothing else is running except the modus/serial integration.

This is what the yaml entry looks like, 1 sensor/entity, nothing else:

modbus:
  - name: EM_Heizung
    type: serial
    port: /dev/ttyACM0
    baudrate: 115200
    bytesize: 8
    method: rtu
    parity: N
    stopbits: 1
    delay: 0
    message_wait_milliseconds: 60
    timeout: 50
    sensors:
      - name: EM Total Power
        unique_id: em_total_power
        unit_of_measurement: W
        address: 0x0420
        data_type: uint32
        scan_interval: 10

When I use Core 2024.3.3 here, it runs for several hours without any problems and I don't get any dropouts. I can also see request every 10 seconds as requested.

Debug_2024_3_3.log

After upgrading to Core 2024.6.2 at 20:45 (see logs), I only receive 2 values at 21:08:01 and 21:11:21.

grafik

Debug_2024_6_2.log

But I can't see in the log file where the problem lies.

2024-06-14 21:08:01.019 DEBUG (MainThread) [pymodbus.logging] Adding transaction 7
2024-06-14 21:08:01.019 DEBUG (MainThread) [pymodbus.logging] Resetting frame - Current Frame in buffer - 
2024-06-14 21:08:01.019 DEBUG (MainThread) [pymodbus.logging] send: 0x0 0x3 0x4 0x20 0x0 0x2 0xc5 0x20
2024-06-14 21:08:01.032 DEBUG (MainThread) [pymodbus.logging] recv: 0x7 0x3 0x4 0x0 0x0 0x0 0x17 0xdc 0x3d old_data:  addr=None
2024-06-14 21:08:01.033 DEBUG (MainThread) [pymodbus.logging] Processing: 0x7 0x3 0x4 0x0 0x0 0x0 0x17 0xdc 0x3d
2024-06-14 21:08:01.033 DEBUG (MainThread) [pymodbus.logging] Getting Frame - 0x3 0x4 0x0 0x0 0x0 0x17
2024-06-14 21:08:01.033 DEBUG (MainThread) [pymodbus.logging] Factory Response[ReadHoldingRegistersResponse': 3]
2024-06-14 21:08:01.033 DEBUG (MainThread) [pymodbus.logging] Frame advanced, resetting header!!
2024-06-14 21:08:01.033 DEBUG (MainThread) [pymodbus.logging] Getting transaction 7
   --> Missing "Unrequested message: ReadHoldingRegistersResponse (2)"
2024-06-14 21:08:01.096 DEBUG (MainThread) [pymodbus.logging] Adding transaction 8
2024-06-14 21:08:01.096 DEBUG (MainThread) [pymodbus.logging] Resetting frame - Current Frame in buffer - 
2024-06-14 21:08:01.096 DEBUG (MainThread) [pymodbus.logging] send: 0x0 0x3 0x4 0x20 0x0 0x2 0xc5 0x20
2024-06-14 21:08:01.111 DEBUG (MainThread) [pymodbus.logging] recv: 0x7 0x3 0x4 0x0 0x0 0x0 0x17 0xdc 0x3d old_data:  addr=None
2024-06-14 21:08:01.112 DEBUG (MainThread) [pymodbus.logging] Processing: 0x7 0x3 0x4 0x0 0x0 0x0 0x17 0xdc 0x3d
2024-06-14 21:08:01.112 DEBUG (MainThread) [pymodbus.logging] Getting Frame - 0x3 0x4 0x0 0x0 0x0 0x17
2024-06-14 21:08:01.112 DEBUG (MainThread) [pymodbus.logging] Factory Response[ReadHoldingRegistersResponse': 3]
2024-06-14 21:08:01.113 DEBUG (MainThread) [pymodbus.logging] Frame advanced, resetting header!!
2024-06-14 21:08:01.113 DEBUG (MainThread) [pymodbus.logging] Getting transaction 7
2024-06-14 21:08:01.113 DEBUG (MainThread) [pymodbus.logging] Unrequested message: ReadHoldingRegistersResponse (2)
2024-06-14 21:08:51.099 DEBUG (MainThread) [pymodbus.logging] Adding transaction 8

2024-06-14 21:11:21.104 DEBUG (MainThread) [pymodbus.logging] Connection lost comm due to Server not responding
2024-06-14 21:11:21.111 DEBUG (MainThread) [pymodbus.logging] callback_disconnected called: Server not responding
2024-06-14 21:11:21.111 ERROR (MainThread) [homeassistant.components.modbus.modbus] Pymodbus: EM_Heizung: Error: device: 0 address: 1056 -> Modbus Error: [Input/Output] ERROR: No response received after 3 retries
2024-06-14 21:11:21.112 DEBUG (MainThread) [pymodbus.logging] Wait comm 100.0 ms before reconnecting.
2024-06-14 21:11:21.173 DEBUG (MainThread) [homeassistant.components.modbus.modbus] Pymodbus: EM_Heizung: Error: device: 0 address: 1056 -> Modbus Error: [Connection] Not connected[AsyncModbusSerialClient /dev/ttyACM0:0]
2024-06-14 21:11:21.213 DEBUG (MainThread) [pymodbus.logging] Connecting to /dev/ttyACM0.
2024-06-14 21:11:21.213 DEBUG (MainThread) [pymodbus.logging] Connecting comm
2024-06-14 21:11:21.218 DEBUG (MainThread) [pymodbus.logging] Connected to comm
2024-06-14 21:11:21.218 DEBUG (MainThread) [pymodbus.logging] Resetting frame - Current Frame in buffer - 
2024-06-14 21:11:21.235 DEBUG (MainThread) [pymodbus.logging] Adding transaction 9
2024-06-14 21:11:21.235 DEBUG (MainThread) [pymodbus.logging] Resetting frame - Current Frame in buffer - 
2024-06-14 21:11:21.236 DEBUG (MainThread) [pymodbus.logging] send: 0x0 0x3 0x4 0x20 0x0 0x2 0xc5 0x20
2024-06-14 21:11:21.250 DEBUG (MainThread) [pymodbus.logging] recv: 0x7 0x3 0x4 0x0 0x0 0x0 0x17 0xdc 0x3d old_data:  addr=None
2024-06-14 21:11:21.250 DEBUG (MainThread) [pymodbus.logging] Processing: 0x7 0x3 0x4 0x0 0x0 0x0 0x17 0xdc 0x3d
2024-06-14 21:11:21.250 DEBUG (MainThread) [pymodbus.logging] Getting Frame - 0x3 0x4 0x0 0x0 0x0 0x17
2024-06-14 21:11:21.250 DEBUG (MainThread) [pymodbus.logging] Factory Response[ReadHoldingRegistersResponse': 3]
2024-06-14 21:11:21.251 DEBUG (MainThread) [pymodbus.logging] Frame advanced, resetting header!!
2024-06-14 21:11:21.251 DEBUG (MainThread) [pymodbus.logging] Getting transaction 7
2024-06-14 21:11:21.251 DEBUG (MainThread) [pymodbus.logging] Unrequested message: ReadHoldingRegistersResponse (2)
  --> Still in here "Unrequested message: ReadHoldingRegistersResponse (2)"
2024-06-14 21:12:11.239 DEBUG (MainThread) [pymodbus.logging] Adding transaction 9

Furthermore in the log file are only request every 50 seconds, not as requested every 10 seconds!?

I would assume that the main problem is that a response comes from the device (energy meter), but it is interpreted as an "Unrequested message", for whatever reason.

Can you please take another look at this? I cannot believe that it is due to the hardware or other components in my case, as I have really changed absolutely nothing (between 2024.3.3 and 2024.6.2) and the error also occurs with a completely new system. The only thing I can think of is that the energy meter is not supplying data 100% correctly, which obviously didn't matter until version 2024.3.3. But I am sure that the energy meter is still delivering data. I have also tested this in the meantime with a completely different system (Windows) and there I was also able to read all the data form the energy meter and did not get any errors.

janiversen commented 3 months ago

The "Unrequested message: ReadHoldingRegistersResponse (2)" is a bug, that have just been solved in the underlying library, this will cause responses to be dropped.

Once there is a new version of pymodbus, the modbus integration will be updated.

Feel free to try the dev version of pymodbus.

Wolfgang-03 commented 3 months ago

I can do that, but I am not familiar with how to test a development version of an integration.

Can you give me a quick hint on how to do this. Thank you very much!

janiversen commented 3 months ago

That depends a lot on your installation, there are no general hints. But Ha have documentation how to test/develop

amos41 commented 3 months ago

I have the same problem with ORNO counters Last version with those working until 2024.3.3

janiversen commented 3 months ago

Mam ten sam problem z licznikami ORNO

Ostatnia wersja z jaką działają to 2024.3.3

This is an english forum.

Wolfgang-03 commented 3 months ago

Once there is a new version of pymodbus, the modbus integration will be updated.

Which version of HA does the new version of pymodbus come with?

janiversen commented 3 months ago

Who knows, I at least do not know... release notes will tell.

amos41 commented 3 months ago

I solved the problem by changing the device address from slave 0 to slave 1 in the device configuration

janiversen commented 3 months ago

Slave 0 is broadcast and should never be used in production.

home-assistant / core