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
73.21k stars 30.58k forks source link

Modbus integration fails to turn on light occasionally #51900

Closed kauha closed 3 years ago

kauha commented 3 years ago

The problem

I'm using Moxa IoLogik E1211 via Modbus TCP (or actually 3 of them) to turn on relays for lights etc. After upgrading to 2021.6.3 I have started to struggle to turn them on or off. Sometimes everything runs smoothly and sometimes not.

I am guessing maybe the integration sometimes tries to open more than one connection per device and the other connection is dropped.

I have devices of the same series to use for the digital input only and they seem to run normally. Only writing seems to be a problem.

At the same time I switched to use light instead of switch but I think it isn't the underlying reason for getting this error.

Attached part of the config yaml and few seconds worth of the log.

What is version of Home Assistant Core has the issue?

core-2021.6.3

What was the last working version of Home Assistant Core?

core-2021.4.5 (I haven't tried 2021.5)

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/

Example YAML snippet

modbus:
  - name: output0
    type: tcp
    host: 192.168.1.225
    port: 502
    lights:
      - name: Seinävalot tienpuoli
        write_type: coil 
        scan_interval: 30
        address: 0
      - name: Seinävalot takapuoli
        write_type: coil 
        scan_interval: 30
        address: 1
      - name: Seinävalot julkisivu
        write_type: coil 
        scan_interval: 30
        address: 3
      - name: Ovivalot
        write_type: coil 
        scan_interval: 30
        address: 2
      - name: Kaidevalot
        write_type: coil 
        scan_interval: 30
        address: 4
      - name: Muurivalot
        write_type: coil 
        scan_interval: 30
        address: 5
      - name: Kivikkovalot
        write_type: coil 
        scan_interval: 30
        address: 6
      - name: Pollarit
        write_type: coil 
        scan_interval: 30
        address: 7
      - name: Työvalot
        write_type: coil 
        scan_interval: 30
        address: 8
## Below here is the on in the error
      - name: Postilaatikko
        write_type: coil 
        scan_interval: 30
        address: 9
      - name: Alaterassi
        write_type: coil 
        scan_interval: 30
        address: 10
      - name: Autokatos
        write_type: coil 
        scan_interval: 30
        address: 11
      - name: Pollarit alapiha
        write_type: coil 
        scan_interval: 30
        address: 15
      - name: Porttipistorasiat
        write_type: coil 
        scan_interval: 30
        address: 12
    switches:
# Portti
      - name: SähköporttiA
        write_type: coil 
        scan_interval: 10
        address: 13
      - name: SähköporttiB
        write_type: coil 
        scan_interval: 10
        address: 14

Anything in the logs that might be useful for us?

2021-06-15 19:02:09 DEBUG (SyncWorker_1) [pymodbus.transaction] Current transaction state - TRANSACTION_COMPLETE
2021-06-15 19:02:09 DEBUG (SyncWorker_1) [pymodbus.transaction] Running transaction 1663
2021-06-15 19:02:09 DEBUG (SyncWorker_1) [pymodbus.transaction] SEND: 0x6 0x7f 0x0 0x0 0x0 0x6 0x0 0x4 0x0 0x81 0x0 0x1
2021-06-15 19:02:09 DEBUG (SyncWorker_1) [pymodbus.client.sync] New Transaction state 'SENDING'
2021-06-15 19:02:09 DEBUG (SyncWorker_1) [pymodbus.transaction] Changing transaction state from 'SENDING' to 'WAITING FOR REPLY'
2021-06-15 19:02:09 DEBUG (SyncWorker_1) [pymodbus.transaction] Changing transaction state from 'WAITING FOR REPLY' to 'PROCESSING REPLY'
2021-06-15 19:02:09 DEBUG (SyncWorker_1) [pymodbus.transaction] RECV: 0x6 0x7f 0x0 0x0 0x0 0x5 0x0 0x4 0x2 0x0 0xec
2021-06-15 19:02:09 DEBUG (SyncWorker_1) [pymodbus.framer.socket_framer] Processing: 0x6 0x7f 0x0 0x0 0x0 0x5 0x0 0x4 0x2 0x0 0xec
2021-06-15 19:02:09 DEBUG (SyncWorker_1) [pymodbus.factory] Factory Response[ReadInputRegistersResponse: 4]
2021-06-15 19:02:09 DEBUG (SyncWorker_1) [pymodbus.transaction] Adding transaction 1663
2021-06-15 19:02:09 DEBUG (SyncWorker_1) [pymodbus.transaction] Getting transaction 1663
2021-06-15 19:02:09 DEBUG (SyncWorker_1) [pymodbus.transaction] Changing transaction state from 'PROCESSING REPLY' to 'TRANSACTION_COMPLETE'
2021-06-15 19:02:09 DEBUG (SyncWorker_6) [pymodbus.transaction] Current transaction state - TRANSACTION_COMPLETE
2021-06-15 19:02:09 DEBUG (SyncWorker_6) [pymodbus.transaction] Running transaction 1664
2021-06-15 19:02:09 DEBUG (SyncWorker_6) [pymodbus.transaction] SEND: 0x6 0x80 0x0 0x0 0x0 0x6 0x0 0x4 0x0 0x83 0x0 0x1
2021-06-15 19:02:09 DEBUG (SyncWorker_6) [pymodbus.client.sync] New Transaction state 'SENDING'
2021-06-15 19:02:09 DEBUG (SyncWorker_6) [pymodbus.transaction] Changing transaction state from 'SENDING' to 'WAITING FOR REPLY'
2021-06-15 19:02:09 DEBUG (SyncWorker_6) [pymodbus.transaction] Changing transaction state from 'WAITING FOR REPLY' to 'PROCESSING REPLY'
2021-06-15 19:02:09 DEBUG (SyncWorker_6) [pymodbus.transaction] RECV: 0x6 0x80 0x0 0x0 0x0 0x5 0x0 0x4 0x2 0x5 0x64
2021-06-15 19:02:09 DEBUG (SyncWorker_6) [pymodbus.framer.socket_framer] Processing: 0x6 0x80 0x0 0x0 0x0 0x5 0x0 0x4 0x2 0x5 0x64
2021-06-15 19:02:09 DEBUG (SyncWorker_6) [pymodbus.factory] Factory Response[ReadInputRegistersResponse: 4]
2021-06-15 19:02:09 DEBUG (SyncWorker_6) [pymodbus.transaction] Adding transaction 1664
2021-06-15 19:02:09 DEBUG (SyncWorker_6) [pymodbus.transaction] Getting transaction 1664
2021-06-15 19:02:09 DEBUG (SyncWorker_6) [pymodbus.transaction] Changing transaction state from 'PROCESSING REPLY' to 'TRANSACTION_COMPLETE'
2021-06-15 19:02:10 DEBUG (SyncWorker_0) [pymodbus.transaction] Current transaction state - TRANSACTION_COMPLETE
2021-06-15 19:02:10 DEBUG (SyncWorker_0) [pymodbus.transaction] Running transaction 7
2021-06-15 19:02:10 DEBUG (SyncWorker_0) [pymodbus.transaction] SEND: 0x1 0x3 0x0 0x1 0x0 0x1 0xd5 0xca
2021-06-15 19:02:10 DEBUG (SyncWorker_0) [pymodbus.framer.rtu_framer] Changing state to IDLE - Last Frame End - 1623772915.328986, Current Time stamp - 1623772930.310066
2021-06-15 19:02:10 DEBUG (SyncWorker_0) [pymodbus.client.sync] New Transaction state 'SENDING'
2021-06-15 19:02:10 DEBUG (SyncWorker_5) [pymodbus.transaction] Current transaction state - TRANSACTION_COMPLETE
2021-06-15 19:02:10 DEBUG (SyncWorker_5) [pymodbus.transaction] Running transaction 16
2021-06-15 19:02:10 DEBUG (SyncWorker_5) [pymodbus.transaction] SEND: 0x0 0x10 0x0 0x0 0x0 0x6 0x64 0x3 0xb 0xb8 0x0 0x1
2021-06-15 19:02:10 DEBUG (SyncWorker_5) [pymodbus.client.sync] New Transaction state 'SENDING'
2021-06-15 19:02:10 DEBUG (SyncWorker_5) [pymodbus.transaction] Changing transaction state from 'SENDING' to 'WAITING FOR REPLY'
2021-06-15 19:02:10 DEBUG (SyncWorker_0) [pymodbus.transaction] Changing transaction state from 'SENDING' to 'WAITING FOR REPLY'
2021-06-15 19:02:10 DEBUG (SyncWorker_8) [pymodbus.transaction] Current transaction state - TRANSACTION_COMPLETE
2021-06-15 19:02:10 DEBUG (SyncWorker_8) [pymodbus.transaction] Running transaction 943
2021-06-15 19:02:10 DEBUG (SyncWorker_8) [pymodbus.transaction] SEND: 0x3 0xaf 0x0 0x0 0x0 0x6 0x1 0x1 0x0 0xf 0x0 0x1
2021-06-15 19:02:10 DEBUG (SyncWorker_8) [pymodbus.client.sync] New Transaction state 'SENDING'
2021-06-15 19:02:10 DEBUG (SyncWorker_8) [pymodbus.transaction] Changing transaction state from 'SENDING' to 'WAITING FOR REPLY'
2021-06-15 19:02:10 DEBUG (SyncWorker_1) [pymodbus.transaction] Current transaction state - IDLE
2021-06-15 19:02:10 DEBUG (SyncWorker_1) [pymodbus.transaction] Running transaction 1
2021-06-15 19:02:10 DEBUG (SyncWorker_1) [pymodbus.transaction] SEND: 0x0 0x1 0x0 0x0 0x0 0x6 0x1 0x5 0x0 0x9 0xff 0x0
2021-06-15 19:02:10 DEBUG (SyncWorker_1) [pymodbus.client.sync] New Transaction state 'SENDING'
2021-06-15 19:02:10 DEBUG (SyncWorker_1) [pymodbus.transaction] Transaction failed. ([Errno 104] Connection reset by peer) 
2021-06-15 19:02:10 DEBUG (SyncWorker_1) [pymodbus.framer.socket_framer] Processing: 
2021-06-15 19:02:10 DEBUG (SyncWorker_1) [pymodbus.transaction] Getting transaction 1
2021-06-15 19:02:10 DEBUG (SyncWorker_1) [pymodbus.transaction] Changing transaction state from 'PROCESSING REPLY' to 'TRANSACTION_COMPLETE'
2021-06-15 19:02:10 ERROR (SyncWorker_1) [homeassistant.components.modbus.modbus] Pymodbus: Modbus Error: [Input/Output] [Errno 104] Connection reset by peer

Additional information

No response

probot-home-assistant[bot] commented 3 years ago

Hey there @adamchengtkc, @janiversen, @vzahradnik, mind taking a look at this issue as its been labeled with an integration (modbus) you are listed as a codeowner for? Thanks! (message by CodeOwnersMention)

janiversen commented 3 years ago

I cannot see any errors in the log ? Did you do a turn on/off and made sure it is in the log you mailed ?

kauha commented 3 years ago

I cannot see any errors in the log ? Did you do a turn on/off and made sure it is in the log you mailed ?

Sorry for unclear description. I did, the error is in the last 9 lines of the log. The beginning is running normally, I just attached it if it's useful for debugging.

janiversen commented 3 years ago

There are no indications of us opening a new connection, until your device closes the connection. After transaction 16 it seems your device have problems responding, this could be caused by a try to write to the device, but it is perfectly legal in the modbus protocol.

kauha commented 3 years ago

There are no indications of us opening a new connection, until your device closes the connection. After transaction 16 it seems your device have problems responding, this could be caused by a try to write to the device, but it is perfectly legal in the modbus protocol.

I will get back to this in few days, once I have the time to do a couple of tests. But the problem is still new, it has been working perfectly before, and the device does work well with a PLC.

pruwait commented 3 years ago

I have this problem too with my modbus rtu switches. No errors in log. But all system is working slowwwly sometimes. Normally reboot server is about 10 seconds and modbus light switches turn on/off whithout problems after I restore my backup core 2021.6.3. Hassio working 5-10 hours and now I can't toggle my swithes. If I want to reboot server it will be 200-300 seconds now! I can`t see slow boot integration in Settings > About System. My modbus switches working with old version hassio more then 1 year!

Intel Nuc 8i3 Debian GNU/Linux 10 (buster) Docker 20.10.7

Bitwarden (Vaultwarden) (0.11.0), Duck DNS (1.12.5), File editor (5.3.1), Home Assistant Google Drive Backup (0.104.3), Mosquitto broker (6.0.1), NGINX Home Assistant SSL proxy (3.0.1), RPC Shutdown (2.2), Samba share (9.5.1), Terminal & SSH (9.1.3), Zigbee2mqtt (1.19.1-1)

Please help me to diagnose the problem.

pruwait commented 3 years ago

In log:

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: search, person, amcrest, updater, binary_sensor.mqtt, sensor.mqtt, persistent_notification, dhcp, zone, light.tasmota, websocket_api, switch.wake_on_lan, modbus, input_number, analytics, logbook, frontend, sensor.hassio, config, ssdp, shell_command, stream, light.group, switch, camera, binary_sensor.tasmota, sun, template, group, scene, sensor.upnp, homeassistant, input_select, mqtt, wake_on_lan, binary_sensor.hassio, weather, timer, light.mqtt, sensor.amcrest, light.modbus, cloud, binary_sensor.updater, http, counter, sensor.modbus, upnp, zeroconf, device_automation, tts, binary_sensor.mobile_app, script, cover.tasmota, auth, system_health, xiaomi_miio, lovelace, sensor.mobile_app, automation, binary_sensor, history, climate.mqtt, tts.google_translate, image, ffmpeg, webhook, media_source, map, hassio, network, sensor.hacs, system_log, binary_sensor.command_line, trace, notify, input_text, onboarding, switch.tasmota, fan.tasmota, sensor, device_tracker, scene.homeassistant, device_tracker.mobile_app, recorder, light, fan, hacs, logger, input_datetime, my, met, switch.mqtt, cover, mobile_app, camera.amcrest, api, binary_sensor.amcrest, sensor.tasmota, sensor.template, input_boolean, fan.xiaomi_miio, yandex_smart_home, blueprint, climate, tasmota, tag, default_config, weather.met, notify.mobile_app

Setup timed out for bootstrap - moving forward

janiversen commented 3 years ago

@pruwait if you think it is a modbus problem, then please follow the guideline https://www.home-assistant.io/integrations/modbus/#opening-an-issue

pruwait commented 3 years ago

This config not working on 2021.06.xx after some hours; configuration.zip log.zip

This config is working succesfully on my downgraded core 2021.3.2: configuration3.zip

janiversen commented 3 years ago

If you Look at the last lines in the log, it seems your device stopped responding, earlier transactions seems ok. Maybe you need to use some of the new parameters like waiting in the verify.

pruwait commented 3 years ago

How can I do it? Pls give me example

janiversen commented 3 years ago

Read the doc.

pruwait commented 3 years ago

Modbus Light > Modbus Switch Add delay:1 Testing 12hours, waiting for 3 days uptime core 2021.6.6

  switches:
#  lights:
      - name: "Коридор LED"
        write_type: holding
        slave: 1
        address: 0
        command_on: 1
        command_off: 0
        verify:
          delay: 1
        scan_interval: 5
PeteRager commented 3 years ago

What is the modbus device you have? Firmware version?