search

home-assistant / core

:house_with_garden: Open source home automation that puts local control and privacy first.
https://www.home-assistant.io
Apache License 2.0
71.8k stars 30.05k forks source link

Modbus with two devices freeze Home Assistant reboot #51364

Closed vdemidov closed 3 years ago

vdemidov commented 3 years ago

The problem

When add in Modbus integration more then one slave device reboot of Home Assistant (core-2021.6.0b5) take very long time. Older version of Home Assistant (core-2021.5.5) fully stop normal working. If slave only one device in config - all work perfect. Behavior depends only on config. Physically all devices connected every time.

What is version of Home Assistant Core has the issue?

core-2021.6.0b5

What was the last working version of Home Assistant Core?

No response

What type of installation are you running?

Home Assistant Supervised

Integration causing the issue

modbus

Link to integration documentation on our website

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

Example YAML snippet

modbus:
  type: serial
  delay: 1
  method: rtu
  port: /dev/serial/by-id/usb-1a86_USB2.0-Serial-if00-port0
  baudrate: 9600
  stopbits: 1
  bytesize: 8
  parity: N
  sensors:
    - name: energy_input_f1_voltage
      scan_interval: 5
      unit_of_measurement: V
      device_class: voltage
      slave: 1
      address: 0
      input_type: input
      scale: 0.1
      offset: 0
      precision: 1
    - name: energy_input_f2_voltage
      scan_interval: 5
      unit_of_measurement: V
      device_class: voltage
      slave: 2
      address: 0
      input_type: input
      scale: 0.1
      offset: 0
      precision: 1
    - name: energy_input_f3_voltage
      scan_interval: 5
      unit_of_measurement: V
      device_class: voltage
      slave: 3
      address: 0
      input_type: input
      scale: 0.1
      offset: 0
      precision: 1

Anything in the logs that might be useful for us?

Logs with problem:
2021-06-02 12:32:21 DEBUG (SyncWorker_13) [pymodbus.client.sync] New Transaction state 'SENDING'
[cont-finish.d] executing container finish scripts...
[cont-finish.d] done.
[s6-finish] waiting for services.
2021-06-02 12:32:30 DEBUG (SyncWorker_13) [pymodbus.client.sync] New Transaction state 'SENDING'
2021-06-02 12:32:30 DEBUG (SyncWorker_4) [pymodbus.client.sync] New Transaction state 'SENDING'
2021-06-02 12:32:36 ERROR (MainThread) [homeassistant.components.hassio.handler] Timeout on /homeassistant/restart request
2021-06-02 12:32:38 DEBUG (SyncWorker_4) [pymodbus.client.sync] New Transaction state 'SENDING'
2021-06-02 12:32:38 DEBUG (SyncWorker_1) [pymodbus.client.sync] New Transaction state 'SENDING'
2021-06-02 12:32:46 DEBUG (SyncWorker_1) [pymodbus.client.sync] New Transaction state 'SENDING'
2021-06-02 12:32:46 DEBUG (SyncWorker_8) [pymodbus.client.sync] New Transaction state 'SENDING'
2021-06-02 12:32:55 DEBUG (SyncWorker_8) [pymodbus.client.sync] New Transaction state 'SENDING'
2021-06-02 12:32:55 DEBUG (SyncWorker_1) [pymodbus.client.sync] New Transaction state 'SENDING'
2021-06-02 12:33:03 DEBUG (SyncWorker_1) [pymodbus.client.sync] New Transaction state 'SENDING'
2021-06-02 12:33:03 DEBUG (SyncWorker_0) [pymodbus.client.sync] New Transaction state 'SENDING'
2021-06-02 12:33:11 DEBUG (SyncWorker_0) [pymodbus.client.sync] New Transaction state 'SENDING'
2021-06-02 12:33:12 DEBUG (SyncWorker_8) [pymodbus.client.sync] New Transaction state 'SENDING'
2021-06-02 12:33:20 DEBUG (SyncWorker_8) [pymodbus.client.sync] New Transaction state 'SENDING'
2021-06-02 12:33:20 DEBUG (SyncWorker_3) [pymodbus.client.sync] New Transaction state 'SENDING'
2021-06-02 12:33:28 DEBUG (SyncWorker_3) [pymodbus.client.sync] New Transaction state 'SENDING'
2021-06-02 12:33:28 DEBUG (SyncWorker_9) [pymodbus.client.sync] New Transaction state 'SENDING'
2021-06-02 12:33:37 DEBUG (SyncWorker_9) [pymodbus.client.sync] New Transaction state 'SENDING'
2021-06-02 12:33:37 DEBUG (SyncWorker_2) [pymodbus.client.sync] New Transaction state 'SENDING'
2021-06-02 12:33:45 DEBUG (SyncWorker_2) [pymodbus.client.sync] New Transaction state 'SENDING'
2021-06-02 12:33:45 DEBUG (SyncWorker_13) [pymodbus.client.sync] New Transaction state 'SENDING'
2021-06-02 12:33:53 DEBUG (SyncWorker_13) [pymodbus.client.sync] New Transaction state 'SENDING'
2021-06-02 12:33:53 DEBUG (SyncWorker_7) [pymodbus.client.sync] New Transaction state 'SENDING'
2021-06-02 12:34:02 DEBUG (SyncWorker_7) [pymodbus.client.sync] New Transaction state 'SENDING'
2021-06-02 12:34:02 DEBUG (SyncWorker_0) [pymodbus.client.sync] New Transaction state 'SENDING'
2021-06-02 12:34:06 WARNING (MainThread) [homeassistant.core] Timed out waiting for shutdown stage 1 to complete, the shutdown will continue
2021-06-02 12:34:10 DEBUG (SyncWorker_0) [pymodbus.client.sync] New Transaction state 'SENDING'
2021-06-02 12:34:10 DEBUG (SyncWorker_12) [pymodbus.client.sync] New Transaction state 'SENDING'
2021-06-02 12:34:18 DEBUG (SyncWorker_12) [pymodbus.client.sync] New Transaction state 'SENDING'
2021-06-02 12:34:19 DEBUG (SyncWorker_5) [pymodbus.client.sync] New Transaction state 'SENDING'
2021-06-02 12:34:27 DEBUG (SyncWorker_5) [pymodbus.client.sync] New Transaction state 'SENDING'
2021-06-02 12:34:27 DEBUG (SyncWorker_6) [pymodbus.client.sync] New Transaction state 'SENDING'
2021-06-02 12:34:35 DEBUG (SyncWorker_6) [pymodbus.client.sync] New Transaction state 'SENDING'
2021-06-02 12:34:35 DEBUG (SyncWorker_12) [pymodbus.client.sync] New Transaction state 'SENDING'
2021-06-02 12:34:44 DEBUG (SyncWorker_12) [pymodbus.client.sync] New Transaction state 'SENDING'
2021-06-02 12:34:44 DEBUG (SyncWorker_3) [pymodbus.client.sync] New Transaction state 'SENDING'
2021-06-02 12:34:52 DEBUG (SyncWorker_3) [pymodbus.client.sync] New Transaction state 'SENDING'
2021-06-02 12:34:52 DEBUG (SyncWorker_0) [pymodbus.client.sync] New Transaction state 'SENDING'
2021-06-02 12:35:00 DEBUG (SyncWorker_0) [pymodbus.client.sync] New Transaction state 'SENDING'
2021-06-02 12:35:00 DEBUG (SyncWorker_12) [pymodbus.client.sync] New Transaction state 'SENDING'
2021-06-02 12:35:06 WARNING (MainThread) [homeassistant.core] Timed out waiting for shutdown stage 2 to complete, the shutdown will continue
2021-06-02 12:35:09 DEBUG (SyncWorker_12) [pymodbus.client.sync] New Transaction state 'SENDING'
2021-06-02 12:35:09 DEBUG (SyncWorker_3) [pymodbus.client.sync] New Transaction state 'SENDING'
2021-06-02 12:35:17 DEBUG (SyncWorker_3) [pymodbus.client.sync] New Transaction state 'SENDING'
2021-06-02 12:35:17 DEBUG (SyncWorker_12) [pymodbus.client.sync] New Transaction state 'SENDING'
2021-06-02 12:35:25 DEBUG (SyncWorker_12) [pymodbus.client.sync] New Transaction state 'SENDING'
2021-06-02 12:35:25 DEBUG (SyncWorker_1) [pymodbus.client.sync] New Transaction state 'SENDING'
2021-06-02 12:35:34 DEBUG (SyncWorker_1) [pymodbus.client.sync] New Transaction state 'SENDING'
2021-06-02 12:35:34 DEBUG (SyncWorker_10) [pymodbus.client.sync] New Transaction state 'SENDING'
2021-06-02 12:35:36 WARNING (MainThread) [homeassistant.core] Timed out waiting for shutdown stage 3 to complete, the shutdown will continue
2021-06-02 12:35:36 WARNING (MainThread) [homeassistant.util.executor] Thread[SyncWorker_10] is still running at shutdown: File "/usr/local/lib/python3.8/threading.py", line 890, in _bootstrap
    self._bootstrap_inner()
  File "/usr/local/lib/python3.8/threading.py", line 932, in _bootstrap_inner
    self.run()
  File "/usr/local/lib/python3.8/threading.py", line 870, in run
    self._target(*self._args, **self._kwargs)
  File "/usr/local/lib/python3.8/concurrent/futures/thread.py", line 80, in _worker
    work_item.run()
  File "/usr/local/lib/python3.8/concurrent/futures/thread.py", line 57, in run
    result = self.fn(*self.args, **self.kwargs)
  File "/usr/src/homeassistant/homeassistant/components/modbus/modbus.py", line 310, in _pymodbus_call
    result = self._call_type[use_call][ENTRY_FUNC](address, value, **kwargs)
  File "/usr/local/lib/python3.8/site-packages/pymodbus/client/common.py", line 125, in read_input_registers
    return self.execute(request)
  File "/usr/local/lib/python3.8/site-packages/pymodbus/client/sync.py", line 109, in execute
    return self.transaction.execute(request)
  File "/usr/local/lib/python3.8/site-packages/pymodbus/transaction.py", line 174, in execute
    response, last_exception = self._transact(
  File "/usr/local/lib/python3.8/site-packages/pymodbus/transaction.py", line 293, in _transact
    result = self._recv(response_length, full)
  File "/usr/local/lib/python3.8/site-packages/pymodbus/transaction.py", line 325, in _recv
    read_min = self.client.framer.recvPacket(min_size)
  File "/usr/local/lib/python3.8/site-packages/pymodbus/framer/rtu_framer.py", line 307, in recvPacket
    result = self.client.recv(size)
  File "/usr/local/lib/python3.8/site-packages/pymodbus/client/sync.py", line 89, in recv
    return self._recv(size)
  File "/usr/local/lib/python3.8/site-packages/pymodbus/client/sync.py", line 749, in _recv
    result = self.socket.read(size)
  File "/usr/local/lib/python3.8/site-packages/serial/serialposix.py", line 565, in read
    ready, _, _ = select.select([self.fd, self.pipe_abort_read_r], [], [], timeout.time_left())
2021-06-02 12:35:37 WARNING (MainThread) [homeassistant.util.executor] Thread[SyncWorker_10] is still running at shutdown: File "/usr/local/lib/python3.8/threading.py", line 890, in _bootstrap
    self._bootstrap_inner()
  File "/usr/local/lib/python3.8/threading.py", line 932, in _bootstrap_inner
    self.run()
  File "/usr/local/lib/python3.8/threading.py", line 870, in run
    self._target(*self._args, **self._kwargs)
  File "/usr/local/lib/python3.8/concurrent/futures/thread.py", line 80, in _worker
    work_item.run()
  File "/usr/local/lib/python3.8/concurrent/futures/thread.py", line 57, in run
    result = self.fn(*self.args, **self.kwargs)
  File "/usr/src/homeassistant/homeassistant/components/modbus/modbus.py", line 310, in _pymodbus_call
    result = self._call_type[use_call][ENTRY_FUNC](address, value, **kwargs)
  File "/usr/local/lib/python3.8/site-packages/pymodbus/client/common.py", line 125, in read_input_registers
    return self.execute(request)
  File "/usr/local/lib/python3.8/site-packages/pymodbus/client/sync.py", line 109, in execute
    return self.transaction.execute(request)
  File "/usr/local/lib/python3.8/site-packages/pymodbus/transaction.py", line 174, in execute
    response, last_exception = self._transact(
  File "/usr/local/lib/python3.8/site-packages/pymodbus/transaction.py", line 293, in _transact
    result = self._recv(response_length, full)
  File "/usr/local/lib/python3.8/site-packages/pymodbus/transaction.py", line 325, in _recv
    read_min = self.client.framer.recvPacket(min_size)
  File "/usr/local/lib/python3.8/site-packages/pymodbus/framer/rtu_framer.py", line 307, in recvPacket
    result = self.client.recv(size)
  File "/usr/local/lib/python3.8/site-packages/pymodbus/client/sync.py", line 89, in recv
    return self._recv(size)
  File "/usr/local/lib/python3.8/site-packages/pymodbus/client/sync.py", line 749, in _recv
    result = self.socket.read(size)
  File "/usr/local/lib/python3.8/site-packages/serial/serialposix.py", line 565, in read
    ready, _, _ = select.select([self.fd, self.pipe_abort_read_r], [], [], timeout.time_left())
/usr/local/lib/python3.8/asyncio/base_events.py:641: RuntimeWarning: coroutine 'Entity.async_update_ha_state' was never awaited
  self._ready.clear()
RuntimeWarning: Enable tracemalloc to get the object allocation traceback
s6-svscanctl: fatal: unable to control /var/run/s6/services: supervisor not listening
[s6-finish] sending all processes the TERM signal.
[s6-finish] sending all processes the KILL signal and exiting.
[s6-init] making user provided files available at /var/run/s6/etc...exited 0.
[s6-init] ensuring user provided files have correct perms...exited 0.
[fix-attrs.d] applying ownership & permissions fixes...
[fix-attrs.d] done.
[cont-init.d] executing container initialization scripts...
[cont-init.d] udev.sh: executing...
[cont-init.d] udev.sh: exited 0.
[cont-init.d] done.
[services.d] starting services
[services.d] done.

Log with only one device:
2021-06-02 12:47:42 DEBUG (SyncWorker_13) [pymodbus.client.sync] New Transaction state 'SENDING'
[cont-finish.d] executing container finish scripts...
[cont-finish.d] done.
[s6-finish] waiting for services.
2021-06-02 12:47:47 DEBUG (SyncWorker_0) [pymodbus.client.sync] New Transaction state 'SENDING'
2021-06-02 12:47:52 DEBUG (SyncWorker_1) [pymodbus.client.sync] New Transaction state 'SENDING'
2021-06-02 12:47:54 ERROR (MainThread) [homeassistant.components.hassio.handler] Client error on /homeassistant/restart request Server disconnected
s6-svscanctl: fatal: unable to control /var/run/s6/services: supervisor not listening
[s6-finish] sending all processes the TERM signal.
[s6-finish] sending all processes the KILL signal and exiting.
[s6-init] making user provided files available at /var/run/s6/etc...exited 0.
[s6-init] ensuring user provided files have correct perms...exited 0.
[fix-attrs.d] applying ownership & permissions fixes...
[fix-attrs.d] done.
[cont-init.d] executing container initialization scripts...
[cont-init.d] udev.sh: executing...
[cont-init.d] udev.sh: exited 0.
[cont-init.d] done.
[services.d] starting services
[services.d] done.

Additional information

System Health

version core-2021.6.0b5
installation_type Home Assistant Supervised
dev false
hassio true
docker true
virtualenv false
python_version 3.8.9
os_name Linux
os_version 4.19.0-16-amd64
arch x86_64
timezone Europe/Kiev
Home Assistant Community Store GitHub API | ok -- | -- Github API Calls Remaining | 5000 Installed Version | 1.12.4 Stage | running Available Repositories | 822 Installed Repositories | 5
Home Assistant Cloud logged_in | false -- | -- can_reach_cert_server | ok can_reach_cloud_auth | ok can_reach_cloud | ok
Home Assistant Supervisor host_os | Debian GNU/Linux 10 (buster) -- | -- update_channel | beta supervisor_version | supervisor-2021.05.4 docker_version | 20.10.6 disk_total | 216.1 GB disk_used | 85.7 GB healthy | true supported | true supervisor_api | ok version_api | ok installed_addons | Home Assistant Google Drive Backup (0.104.3), Check Home Assistant configuration (3.7.1), Log Viewer (0.11.0), File editor (5.3.1), Mosquitto broker (6.0.1), Grafana (6.3.5), NGINX Home Assistant SSL proxy (3.0.1), Terminal & SSH (9.1.3), Visual Studio Code (3.4.1), ESPHome (1.18.0), InfluxDB (4.1.1), MariaDB (2.3.0), Duck DNS (1.12.5), Zigbee2mqtt (1.18.3-1)
Lovelace dashboards | 1 -- | -- resources | 0 views | 8 mode | storage
janiversen commented 3 years ago

Please send the part of the log containing the pydmodbus connect. I would like to see if that is succesfull. Thanks in advance.

vdemidov commented 3 years ago

Sorry, but nothing like connect in log. Log after HA start: 2021-06-02 13:05:01 WARNING (SyncWorker_0) [homeassistant.loader] We found a custom integration xiaomi_gateway3 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 2021-06-02 13:05:01 WARNING (SyncWorker_1) [homeassistant.loader] We found a custom integration gismeteo 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 2021-06-02 13:05:01 WARNING (SyncWorker_1) [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 2021-06-02 13:05:01 WARNING (SyncWorker_1) [homeassistant.loader] We found a custom integration favicon 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 2021-06-02 13:05:09 INFO (MainThread) [homeassistant.components.device_tracker] Setting up device_tracker.luci 2021-06-02 13:05:10 INFO (MainThread) [homeassistant.components.device_tracker] Setting up device_tracker.mobile_app 2021-06-02 13:05:10 INFO (MainThread) [homeassistant.components.device_tracker] Not adding entity Viktor-N9 because it's disabled 2021-06-02 13:05:24 DEBUG (SyncWorker_1) [pymodbus.client.sync] New Transaction state 'SENDING' 2021-06-02 13:05:24 DEBUG (SyncWorker_5) [pymodbus.client.sync] New Transaction state 'SENDING' 2021-06-02 13:05:46 WARNING (MainThread) [homeassistant.helpers.template] Template variable warning: 'dict object' has no attribute 'click' when rendering '{{ value_json.click }}' 2021-06-02 13:05:53 DEBUG (SyncWorker_5) [pymodbus.client.sync] New Transaction state 'SENDING' 2021-06-02 13:05:53 DEBUG (SyncWorker_2) [pymodbus.client.sync] New Transaction state 'SENDING' 2021-06-02 13:06:21 DEBUG (SyncWorker_2) [pymodbus.client.sync] New Transaction state 'SENDING' 2021-06-02 13:06:21 DEBUG (SyncWorker_13) [pymodbus.client.sync] New Transaction state 'SENDING' 2021-06-02 13:06:50 DEBUG (SyncWorker_13) [pymodbus.client.sync] New Transaction state 'SENDING'

Logger settings:

logger:
  logs:
    homeassistant.components.modbus: debug
    pymodbus.client: debug
janiversen commented 3 years ago

Thanks and interesting, it seems pymodbus never manages to make a connection. This is something I have not seen before. You say it works if you change slave:2 and slave:3 to slave:1 ?

Could you please do that, and see if the log have a pymodbus connect message, thanks in advance.

Second test, with the configuration slave:1,2,3 (as you have it), add delay:30 to the modbus part. This gives a delay before pymodbus starts transmitting messages, and it could solve your problem.

Sorry for asking you to test, but that is the only way I can pinpoint the problem.

vdemidov commented 3 years ago

You say it works if you change slave:2 and slave:3 to slave:1 ?

Changed yaml:

modbus:
  type: serial
  delay: 30
  method: rtu
  port: /dev/serial/by-id/usb-1a86_USB2.0-Serial-if00-port0
  baudrate: 9600
  stopbits: 1
  bytesize: 8
  parity: N
  sensors:
    - name: energy_input_f1_voltage
      scan_interval: 5
      unit_of_measurement: V
      device_class: voltage
      slave: 1
      address: 0
      input_type: input
      scale: 0.1
      offset: 0
      precision: 1
    - name: energy_input_f2_voltage
      scan_interval: 5
      unit_of_measurement: V
      device_class: voltage
      slave: 1
      address: 0
      input_type: input
      scale: 0.1
      offset: 0
      precision: 1
    - name: energy_input_f3_voltage
      scan_interval: 5
      unit_of_measurement: V
      device_class: voltage
      slave: 1
      address: 0
      input_type: input
      scale: 0.1
      offset: 0
      precision: 1

Works perfect. No problem. But still any connect message from pymodbus Log:

2021-06-02 17:43:35 WARNING (SyncWorker_1) [homeassistant.loader] We found a custom integration xiaomi_gateway3 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
2021-06-02 17:43:35 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
2021-06-02 17:43:35 WARNING (SyncWorker_1) [homeassistant.loader] We found a custom integration gismeteo 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
2021-06-02 17:43:35 WARNING (SyncWorker_0) [homeassistant.loader] We found a custom integration favicon 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
2021-06-02 17:43:43 INFO (MainThread) [homeassistant.components.device_tracker] Setting up device_tracker.luci
2021-06-02 17:43:44 INFO (MainThread) [homeassistant.components.device_tracker] Setting up device_tracker.mobile_app
2021-06-02 17:43:44 INFO (MainThread) [homeassistant.components.device_tracker] Not adding entity Viktor-N9 because it's disabled
2021-06-02 17:44:13 DEBUG (SyncWorker_7) [pymodbus.client.sync] New Transaction state 'SENDING'
2021-06-02 17:44:13 DEBUG (SyncWorker_0) [pymodbus.client.sync] New Transaction state 'SENDING'
2021-06-02 17:44:13 DEBUG (SyncWorker_4) [pymodbus.client.sync] New Transaction state 'SENDING'

Second test, with the configuration slave:1,2,3 (as you have it), add delay:30 to the modbus part. This gives a delay before pymodbus starts transmitting messages, and it could solve your problem.

Problems exist. And restart takes more time. Log:

2021-06-02 17:51:01 WARNING (SyncWorker_0) [homeassistant.loader] We found a custom integration xiaomi_gateway3 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
2021-06-02 17:51:01 WARNING (SyncWorker_1) [homeassistant.loader] We found a custom integration gismeteo 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
2021-06-02 17:51:01 WARNING (SyncWorker_1) [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
2021-06-02 17:51:01 WARNING (SyncWorker_1) [homeassistant.loader] We found a custom integration favicon 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
2021-06-02 17:51:08 INFO (MainThread) [homeassistant.components.device_tracker] Setting up device_tracker.luci
2021-06-02 17:51:10 INFO (MainThread) [homeassistant.components.device_tracker] Setting up device_tracker.mobile_app
2021-06-02 17:51:10 INFO (MainThread) [homeassistant.components.device_tracker] Not adding entity Viktor-N9 because it's disabled
2021-06-02 17:51:40 DEBUG (SyncWorker_4) [pymodbus.client.sync] New Transaction state 'SENDING'
2021-06-02 17:51:40 DEBUG (SyncWorker_5) [pymodbus.client.sync] New Transaction state 'SENDING'
2021-06-02 17:51:48 DEBUG (SyncWorker_5) [pymodbus.client.sync] New Transaction state 'SENDING'
2021-06-02 17:51:48 DEBUG (SyncWorker_1) [pymodbus.client.sync] New Transaction state 'SENDING'
2021-06-02 17:51:51 WARNING (MainThread) [homeassistant.helpers.template] Template variable warning: 'dict object' has no attribute 'click' when rendering '{{ value_json.click }}'
2021-06-02 17:51:57 DEBUG (SyncWorker_1) [pymodbus.client.sync] New Transaction state 'SENDING'
2021-06-02 17:51:57 DEBUG (SyncWorker_5) [pymodbus.client.sync] New Transaction state 'SENDING'
2021-06-02 17:52:05 DEBUG (SyncWorker_5) [pymodbus.client.sync] New Transaction state 'SENDING'
2021-06-02 17:52:05 DEBUG (SyncWorker_6) [pymodbus.client.sync] New Transaction state 'SENDING'
2021-06-02 17:52:13 DEBUG (SyncWorker_6) [pymodbus.client.sync] New Transaction state 'SENDING'
2021-06-02 17:52:13 DEBUG (SyncWorker_11) [pymodbus.client.sync] New Transaction state 'SENDING'
[cont-finish.d] executing container finish scripts...
[cont-finish.d] done.
[s6-finish] waiting for services.
2021-06-02 17:52:22 DEBUG (SyncWorker_11) [pymodbus.client.sync] New Transaction state 'SENDING'
2021-06-02 17:52:22 DEBUG (SyncWorker_9) [pymodbus.client.sync] New Transaction state 'SENDING'
2021-06-02 17:52:30 DEBUG (SyncWorker_9) [pymodbus.client.sync] New Transaction state 'SENDING'
2021-06-02 17:52:30 DEBUG (SyncWorker_10) [pymodbus.client.sync] New Transaction state 'SENDING'
2021-06-02 17:52:31 ERROR (MainThread) [homeassistant.components.hassio.handler] Timeout on /homeassistant/restart request
2021-06-02 17:52:39 DEBUG (SyncWorker_10) [pymodbus.client.sync] New Transaction state 'SENDING'
2021-06-02 17:52:39 DEBUG (SyncWorker_12) [pymodbus.client.sync] New Transaction state 'SENDING'
2021-06-02 17:52:47 DEBUG (SyncWorker_12) [pymodbus.client.sync] New Transaction state 'SENDING'
2021-06-02 17:52:47 DEBUG (SyncWorker_5) [pymodbus.client.sync] New Transaction state 'SENDING'
2021-06-02 17:52:55 DEBUG (SyncWorker_5) [pymodbus.client.sync] New Transaction state 'SENDING'
2021-06-02 17:52:55 DEBUG (SyncWorker_2) [pymodbus.client.sync] New Transaction state 'SENDING'
2021-06-02 17:53:04 DEBUG (SyncWorker_2) [pymodbus.client.sync] New Transaction state 'SENDING'
2021-06-02 17:53:04 DEBUG (SyncWorker_1) [pymodbus.client.sync] New Transaction state 'SENDING'
2021-06-02 17:53:12 DEBUG (SyncWorker_1) [pymodbus.client.sync] New Transaction state 'SENDING'
2021-06-02 17:53:12 DEBUG (SyncWorker_6) [pymodbus.client.sync] New Transaction state 'SENDING'
2021-06-02 17:53:20 DEBUG (SyncWorker_6) [pymodbus.client.sync] New Transaction state 'SENDING'
2021-06-02 17:53:20 DEBUG (SyncWorker_3) [pymodbus.client.sync] New Transaction state 'SENDING'
2021-06-02 17:53:29 DEBUG (SyncWorker_3) [pymodbus.client.sync] New Transaction state 'SENDING'
2021-06-02 17:53:29 DEBUG (SyncWorker_9) [pymodbus.client.sync] New Transaction state 'SENDING'
2021-06-02 17:53:37 DEBUG (SyncWorker_9) [pymodbus.client.sync] New Transaction state 'SENDING'
2021-06-02 17:53:37 DEBUG (SyncWorker_10) [pymodbus.client.sync] New Transaction state 'SENDING'
2021-06-02 17:53:46 DEBUG (SyncWorker_10) [pymodbus.client.sync] New Transaction state 'SENDING'
2021-06-02 17:53:46 DEBUG (SyncWorker_7) [pymodbus.client.sync] New Transaction state 'SENDING'
2021-06-02 17:53:54 DEBUG (SyncWorker_7) [pymodbus.client.sync] New Transaction state 'SENDING'
2021-06-02 17:53:54 DEBUG (SyncWorker_10) [pymodbus.client.sync] New Transaction state 'SENDING'
2021-06-02 17:54:00 WARNING (MainThread) [homeassistant.core] Timed out waiting for shutdown stage 1 to complete, the shutdown will continue
2021-06-02 17:54:02 DEBUG (SyncWorker_10) [pymodbus.client.sync] New Transaction state 'SENDING'
2021-06-02 17:54:02 DEBUG (SyncWorker_4) [pymodbus.client.sync] New Transaction state 'SENDING'
2021-06-02 17:54:11 DEBUG (SyncWorker_4) [pymodbus.client.sync] New Transaction state 'SENDING'
2021-06-02 17:54:11 DEBUG (SyncWorker_5) [pymodbus.client.sync] New Transaction state 'SENDING'
2021-06-02 17:54:19 DEBUG (SyncWorker_5) [pymodbus.client.sync] New Transaction state 'SENDING'
2021-06-02 17:54:19 DEBUG (SyncWorker_8) [pymodbus.client.sync] New Transaction state 'SENDING'
2021-06-02 17:54:27 DEBUG (SyncWorker_8) [pymodbus.client.sync] New Transaction state 'SENDING'
2021-06-02 17:54:27 DEBUG (SyncWorker_9) [pymodbus.client.sync] New Transaction state 'SENDING'
2021-06-02 17:54:36 DEBUG (SyncWorker_9) [pymodbus.client.sync] New Transaction state 'SENDING'
2021-06-02 17:54:36 DEBUG (SyncWorker_8) [pymodbus.client.sync] New Transaction state 'SENDING'
2021-06-02 17:54:44 DEBUG (SyncWorker_8) [pymodbus.client.sync] New Transaction state 'SENDING'
2021-06-02 17:54:44 DEBUG (SyncWorker_4) [pymodbus.client.sync] New Transaction state 'SENDING'
2021-06-02 17:54:53 DEBUG (SyncWorker_4) [pymodbus.client.sync] New Transaction state 'SENDING'
2021-06-02 17:54:53 DEBUG (SyncWorker_7) [pymodbus.client.sync] New Transaction state 'SENDING'
2021-06-02 17:55:00 WARNING (MainThread) [homeassistant.core] Timed out waiting for shutdown stage 2 to complete, the shutdown will continue
2021-06-02 17:55:01 DEBUG (SyncWorker_7) [pymodbus.client.sync] New Transaction state 'SENDING'
2021-06-02 17:55:01 DEBUG (SyncWorker_1) [pymodbus.client.sync] New Transaction state 'SENDING'
2021-06-02 17:55:09 DEBUG (SyncWorker_1) [pymodbus.client.sync] New Transaction state 'SENDING'
2021-06-02 17:55:09 DEBUG (SyncWorker_3) [pymodbus.client.sync] New Transaction state 'SENDING'
2021-06-02 17:55:18 DEBUG (SyncWorker_3) [pymodbus.client.sync] New Transaction state 'SENDING'
2021-06-02 17:55:18 DEBUG (SyncWorker_9) [pymodbus.client.sync] New Transaction state 'SENDING'
2021-06-02 17:55:26 DEBUG (SyncWorker_9) [pymodbus.client.sync] New Transaction state 'SENDING'
2021-06-02 17:55:26 DEBUG (SyncWorker_10) [pymodbus.client.sync] New Transaction state 'SENDING'
2021-06-02 17:55:30 WARNING (MainThread) [homeassistant.core] Timed out waiting for shutdown stage 3 to complete, the shutdown will continue
2021-06-02 17:55:30 WARNING (MainThread) [homeassistant.util.executor] Thread[SyncWorker_10] is still running at shutdown: File "/usr/local/lib/python3.8/threading.py", line 890, in _bootstrap
    self._bootstrap_inner()
  File "/usr/local/lib/python3.8/threading.py", line 932, in _bootstrap_inner
    self.run()
  File "/usr/local/lib/python3.8/threading.py", line 870, in run
    self._target(*self._args, **self._kwargs)
  File "/usr/local/lib/python3.8/concurrent/futures/thread.py", line 80, in _worker
    work_item.run()
  File "/usr/local/lib/python3.8/concurrent/futures/thread.py", line 57, in run
    result = self.fn(*self.args, **self.kwargs)
  File "/usr/src/homeassistant/homeassistant/components/modbus/modbus.py", line 310, in _pymodbus_call
    result = self._call_type[use_call][ENTRY_FUNC](address, value, **kwargs)
  File "/usr/local/lib/python3.8/site-packages/pymodbus/client/common.py", line 125, in read_input_registers
    return self.execute(request)
  File "/usr/local/lib/python3.8/site-packages/pymodbus/client/sync.py", line 109, in execute
    return self.transaction.execute(request)
  File "/usr/local/lib/python3.8/site-packages/pymodbus/transaction.py", line 194, in execute
    response, last_exception = self._retry_transaction(retries, "empty", request, expected_response_length, full=full)
  File "/usr/local/lib/python3.8/site-packages/pymodbus/transaction.py", line 249, in _retry_transaction
    self.client.connect()
  File "/usr/local/lib/python3.8/site-packages/pymodbus/client/sync.py", line 652, in connect
    self.socket = serial.serial_for_url(self.port,
  File "/usr/local/lib/python3.8/site-packages/serial/__init__.py", line 90, in serial_for_url
    instance.open()
  File "/usr/local/lib/python3.8/site-packages/serial/serialposix.py", line 322, in open
    self.fd = os.open(self.portstr, os.O_RDWR | os.O_NOCTTY | os.O_NONBLOCK)
2021-06-02 17:55:31 WARNING (MainThread) [homeassistant.util.executor] Thread[SyncWorker_10] is still running at shutdown: File "/usr/local/lib/python3.8/threading.py", line 890, in _bootstrap
    self._bootstrap_inner()
  File "/usr/local/lib/python3.8/threading.py", line 932, in _bootstrap_inner
    self.run()
  File "/usr/local/lib/python3.8/threading.py", line 870, in run
    self._target(*self._args, **self._kwargs)
  File "/usr/local/lib/python3.8/concurrent/futures/thread.py", line 80, in _worker
    work_item.run()
  File "/usr/local/lib/python3.8/concurrent/futures/thread.py", line 57, in run
    result = self.fn(*self.args, **self.kwargs)
  File "/usr/src/homeassistant/homeassistant/components/modbus/modbus.py", line 310, in _pymodbus_call
    result = self._call_type[use_call][ENTRY_FUNC](address, value, **kwargs)
  File "/usr/local/lib/python3.8/site-packages/pymodbus/client/common.py", line 125, in read_input_registers
    return self.execute(request)
  File "/usr/local/lib/python3.8/site-packages/pymodbus/client/sync.py", line 109, in execute
    return self.transaction.execute(request)
  File "/usr/local/lib/python3.8/site-packages/pymodbus/transaction.py", line 194, in execute
    response, last_exception = self._retry_transaction(retries, "empty", request, expected_response_length, full=full)
  File "/usr/local/lib/python3.8/site-packages/pymodbus/transaction.py", line 255, in _retry_transaction
    return self._transact(packet, response_length, full=full)
  File "/usr/local/lib/python3.8/site-packages/pymodbus/transaction.py", line 273, in _transact
    size = self._send(packet)
  File "/usr/local/lib/python3.8/site-packages/pymodbus/transaction.py", line 308, in _send
    return self.client.framer.sendPacket(packet)
  File "/usr/local/lib/python3.8/site-packages/pymodbus/framer/rtu_framer.py", line 287, in sendPacket
    time.sleep(self.client.timeout)
/usr/local/lib/python3.8/asyncio/base_events.py:641: RuntimeWarning: coroutine 'Entity.async_update_ha_state' was never awaited
  self._ready.clear()
RuntimeWarning: Enable tracemalloc to get the object allocation traceback
s6-svscanctl: fatal: unable to control /var/run/s6/services: supervisor not listening
[s6-finish] sending all processes the TERM signal.
[s6-finish] sending all processes the KILL signal and exiting.
[s6-init] making user provided files available at /var/run/s6/etc...exited 0.
[s6-init] ensuring user provided files have correct perms...exited 0.
[fix-attrs.d] applying ownership & permissions fixes...
[fix-attrs.d] done.
[cont-init.d] executing container initialization scripts...
[cont-init.d] udev.sh: executing...
[cont-init.d] udev.sh: exited 0.
[cont-init.d] done.
[services.d] starting services
[services.d] done.
vdemidov commented 3 years ago

You say it works if you change slave:2 and slave:3 to slave:1 ?

Also it can be changed to slave:2 or slave:3 and works normally. Problem only when I have several different slave devices.

Thank you for help.

vdemidov commented 3 years ago

Actually this is minimal test config for reproduce. Actually working config has many sensors for every slave. There are 3 PZEM-016 devices with voltage, current, power, energy, frequency, power_factor for each. While it was alone all work perfect even with scan_interval: 1

janiversen commented 3 years ago

I assumed your production configuration was bigger, but it SUPER that you have scaled it down, that makes reading the log a joy !

To be honest right now, I do not have a clue with this happens to you, BUT I have enough information to setup my simulator and find the problem.

It seems you found another problem too, I can see a stack trace in all your logs, it seems to come when you shutdown HA, can you please confirm that ?

vdemidov commented 3 years ago

It seems you found another problem too, I can see a stack trace in all your logs, it seems to come when you shutdown HA, can you please confirm that ?

Sorry? I don't understand. Stack trace is different from time to time. I think it's only result of other problems.

janiversen commented 3 years ago

Yes it is different, but there are modules from pymodbus in all of them.

What I cannot see in the log, is that if it happens in the running system or just when you shut HA down ?

janiversen commented 3 years ago

Are you sure you get something back from your device, because I would have expected something like: 2021-05-31 17:12:06 DEBUG (SyncWorker_2) [pymodbus.client.sync] Connection to Modbus server established. Socket ('192.168.2.54', 33273) 2021-05-31 17:12:27 DEBUG (SyncWorker_3) [pymodbus.transaction] Current transaction state - IDLE 2021-05-31 17:12:27 DEBUG (SyncWorker_3) [pymodbus.transaction] Running transaction 1 2021-05-31 17:12:27 DEBUG (SyncWorker_3) [pymodbus.transaction] SEND: 0x0 0x1 0x0 0x0 0x0 0x6 0x0 0x3 0x90 0xf9 0x0 0x1 2021-05-31 17:12:27 DEBUG (SyncWorker_3) [pymodbus.client.sync] New Transaction state 'SENDING' 2021-05-31 17:12:27 DEBUG (SyncWorker_3) [pymodbus.transaction] Changing transaction state from 'SENDING' to 'WAITING FOR REPLY' 2021-05-31 17:12:27 DEBUG (SyncWorker_3) [pymodbus.transaction] Changing transaction state from 'WAITING FOR REPLY' to 'PROCESSING REPLY' 2021-05-31 17:12:27 DEBUG (SyncWorker_3) [pymodbus.transaction] RECV: 0x0 0x1 0x0 0x0 0x0 0x3 0x0 0x83 0x2 This is done with:

logger:
  logs:
    homeassistant.components.modbus: debug
    pymodbus.client: debug

So to me it seems (in all your logs) we never send to the device and therefore never receive from the device.

vdemidov commented 3 years ago

What I cannot see in the log, is that if it happens in the running system or just when you shut HA down ?

Only when HA shut down. In core-2021.5.5 it froze HA UI until reboot or disconnect RS485-USB from server. In beta version it works and update data of all devices but server have problem with shutdown and with start up if I set small scan_interval. But nothing in logs.

Are you sure you get something back from your device, because I would have expected something like:

I use serial connection, not TCP. logger settings same but any lines from modbus except lines like: 2021-06-02 19:16:22 DEBUG (SyncWorker_1) [pymodbus.client.sync] New Transaction state 'SENDING'

So to me it seems (in all your logs) we never send to the device and therefore never receive from the device.

No. Server receive data. And show it in ui. All works now. May be no so often as expected. I'm not sure.

vdemidov commented 3 years ago

I've checked update time. scan_interval: 15 but sensors updates every 2 minutes. It's strange.

janiversen commented 3 years ago

Look at the log, and see if that too only sends out every 2 minutes.

vdemidov commented 3 years ago

Look at the log, and see if that too only sends out every 2 minutes.

But, when slave:1 everywhere, it send 3 request every 5 seconds.

janiversen commented 3 years ago

That is what it should do. What I am looking is the slave:1-2-3, I question myself why 2 minutes, it is because pymodbus sends every 2 minutes (in which case pymodbus blocks) or does it still send rapidly, but you only see an update in the UI every 2 minutes.

vdemidov commented 3 years ago

I've read that in HA Modbus integration there is no delay between request to different slave device. This is not problem with Modbus over TCP but it's problem on serial connection. Is it true?

janiversen commented 3 years ago

I have not heard that, where did you read it ?

With tcp/ip it is like you have a direct serial line to each device (all are slave 0), but with serial you have 1 line and multiple devices (slave 1, slave 2, slave 3), that is bound to be slower, but we talk about max. 1/4 second when switching between devices.

Actually it is not slower when sending, but when receiving it adds a delay to check if the device wants to send more.

vdemidov commented 3 years ago

I have not heard that, where did you read it ?

At russian-language telegram channel. There was said that HA team know this problem but don't wont change this behavior.

Actually it is not slower when sending, but when receiving it adds a delay to check if the device wants to send more.

But in log we always see 2 request in the same second without any delay. For example:

2021-06-02 12:32:38 DEBUG (SyncWorker_4) [pymodbus.client.sync] New Transaction state 'SENDING'
2021-06-02 12:32:38 DEBUG (SyncWorker_1) [pymodbus.client.sync] New Transaction state 'SENDING'

An this looks like a problem.

janiversen commented 3 years ago

At russian-language telegram channel. There was said that HA team know this problem but don't wont change this behavior.

Well you can tell on that channel, that is not HA but the library we use: pymodbus.

And please do not forget this is the first issue I have seen regarding problems with slaves, so if nobody reported it, yes then we did nothing about it.

But in log we always see 2 request in the same second without any delay. For example:

2021-06-02 12:32:38 DEBUG (SyncWorker_4) [pymodbus.client.sync] New Transaction state 'SENDING'
2021-06-02 12:32:38 DEBUG (SyncWorker_1) [pymodbus.client.sync] New Transaction state 'SENDING'

An this looks like a problem. That is one send for each sensor. The request for each sensor depends on the scan_interval, so first all sensors are requested, then each sensor sleep scan_interval seconds.

vdemidov commented 3 years ago

Well you can tell on that channel, that is not HA but the library we use: pymodbus.

For users this is same. But I'm sorry. I've only asked about gossips that I've read.

And please do not forget this is the first issue I have seen regarding problems with slaves, so if nobody reported it, yes then we did nothing about it.

This is the reason why I've opened this issue and make all what I can for reproduce and investigation :)

That is one send for each sensor. The request for each sensor depends on the scan_interval, so first all sensors are requested, then each sensor sleep scan_interval seconds.

Are you sure? As I can see this is different workers. And they always run one by one in same second. No delay. But scan_interval:5 and delay:1. Should be pause at least 1 second.

janiversen commented 3 years ago

With scan_interval 5 and 1, you should see: second 0: sensor1, sensor2 second 1-4: sensor2 second 5: sensor1, sensor2

but in your case it is different because there are no connection and no bytes are sent or received.

What is the prblem with different workers? that is normal.

vdemidov commented 3 years ago

second 0: sensor1, sensor2

but this is problem. We ask two different slave without any delay. Should be second 0: sensor1 second 1: sensor2 second 2-4: pause second 5: sensor1 second 6: sensor2

but in your case it is different because there are no connection and no bytes are sent or received.

I think this is only logging problem, because data comes to server without messages about connection and receive

janiversen commented 3 years ago

no that is not how scan_interval works, it works independent on each sensor, so scan_interval: 1 means send a request every second for that sensor, the other with 5 is requested every 5 seconds.Sometimes both are requested in the same second and that is not a problem.

btw within the same second does not mean at the same time, you can send/receive about 400 messages pr second with 9.600bps.

janiversen commented 3 years ago

When you only see sending, without a number of hex bytes it is because the rs485 does not allow send (DTR and RTS high), when you receive something you will see hex bytes received and the transaction being ended.

janiversen commented 3 years ago

Anyhow I am about to setup a test bench with 2 sensors on different slaves, after that I can show you how your log should look like.

vdemidov commented 3 years ago

As I understand for testing I can put modified sources of modbus integration to custom_components in config?

vdemidov commented 3 years ago

Fix helps. Super. Thank you very match!!!

vdemidov commented 3 years ago

And now log looks like I expected:

2021-06-03 23:28:40 DEBUG (SyncWorker_1) [pymodbus.client.sync] New Transaction state 'SENDING'
2021-06-03 23:28:41 DEBUG (SyncWorker_0) [pymodbus.client.sync] New Transaction state 'SENDING'
2021-06-03 23:28:45 DEBUG (SyncWorker_4) [pymodbus.client.sync] New Transaction state 'SENDING'
2021-06-03 23:28:46 DEBUG (SyncWorker_3) [pymodbus.client.sync] New Transaction state 'SENDING'
2021-06-03 23:28:50 DEBUG (SyncWorker_1) [pymodbus.client.sync] New Transaction state 'SENDING'
2021-06-03 23:28:51 DEBUG (SyncWorker_4) [pymodbus.client.sync] New Transaction state 'SENDING'

Sending fire in different seconds :) line

And updates much more often. It can be seen on graph in right part.

vdemidov commented 3 years ago

I'm not sure about HA dev process. When does this fix can be found in release build? Should I wait or better use fixed version as custom_component in production server?

janiversen commented 3 years ago

This will not be released until 2021.7 because it contains a configuration change. So I suggest to use the fixed version until then.

vdemidov commented 3 years ago

I've thought about your fix. About:

Some USB serial RS485 adapter needs a short delay to switch between read and write.

And I think if this is true, problem should be reproduced with many sensors of one slave device. But it happened only with two devices. IMHO something wrong in slave devices, not in adapter.

And hardcoded 30ms it's good for my config and my devices. It will cause big performance trouble for high speed devices with many sensors. This delay should be configurable as timeout for modbus hub.