Error in HA log: "Command failed: open failed" occurs during network operations

[ond000]

Describe the bug
In HA logs I see strange error without details:

Logger: custom_components.unraid.unraid
Zdroj: custom_components/unraid/unraid.py:87
integrace: UNRAID (dokumentace, problémy)
První výskyt: 23:13:38 (26 výskyty)
Naposledy logováno: 23:24:41

Command failed: open failed

When I look into debug log, there are no more details in that error, but probably can help whole block debug logs for finding which command failed, please see debug log below.

That error appears during network operations... for sure I have three network interfaces, eth0 (normal 1 Gig at MB), eth1 and eth3 (two 10 Gigs at PCI-E card), those eth1 and eth3 are bonded together to bond1 (as aggregated link - 802.3ad).

After interface existence check in code is part commented as "Get traffic stats" (line 261 in file network_operations.py) there are two commands one for rx bytes and one for tx bytes, that for tx bytes looks different, so I tried commands in Unraid Console

root@OK-USSTR:~# cat /sys/class/net/eth0/statistics/rx_bytes /sys/class/net/eth0/statistics/tx_bytes
405928273798
545492351685
root@OK-USSTR:~# cat /sys/class/net/eth1/statistics/rx_bytes /sys/class/net/eth1/statistics/tx_bytes
135457907838
159654895112
root@OK-USSTR:~# cat /sys/class/net/eth3/statistics/rx_bytes /sys/class/net/eth3/statistics/tx_bytes
170724649096
11255665434
root@OK-USSTR:~# cat /sys/class/net/bond1/statistics/rx_bytes /sys/class/net/bond1/statistics/tx_bytes
306183579445
170936637188

But for all four interfaces I've got response.

Expected behavior

Screenshots

Debug Log

2025-01-07 23:18:09.046 DEBUG (MainThread) [custom_components.unraid.api.vm_operations] Checking VM service status
2025-01-07 23:18:09.048 DEBUG (MainThread) [custom_components.unraid.api.docker_operations] Fetching Docker container information
2025-01-07 23:18:09.050 DEBUG (MainThread) [custom_components.unraid.api.userscript_operations] Fetching user scripts
2025-01-07 23:18:09.122 DEBUG (MainThread) [custom_components.unraid.api.vm_operations] Libvirt validated through process and socket checks
2025-01-07 23:18:09.191 DEBUG (MainThread) [custom_components.unraid.api.docker_operations] Docker validated through process and socket checks
2025-01-07 23:18:09.712 DEBUG (MainThread) [custom_components.unraid.helpers] No disk information found in system stats
2025-01-07 23:18:09.733 DEBUG (MainThread) [custom_components.unraid.api.network_operations] Processing interface: eth0 (normalized: eth0)
2025-01-07 23:18:09.736 DEBUG (MainThread) [custom_components.unraid.api.network_operations] Processing interface: eth1 (normalized: eth1)
2025-01-07 23:18:09.739 DEBUG (MainThread) [custom_components.unraid.api.network_operations] Processing interface: eth3 (normalized: eth3)
2025-01-07 23:18:09.741 DEBUG (MainThread) [custom_components.unraid.api.network_operations] Processing interface: bond1 (normalized: bond1)
2025-01-07 23:18:09.771 DEBUG (MainThread) [custom_components.unraid.api.network_operations] Interface existence check: eth0 (exists=True)
2025-01-07 23:18:09.774 DEBUG (MainThread) [custom_components.unraid.api.network_operations] Interface existence check: eth1 (exists=True)
2025-01-07 23:18:09.778 DEBUG (MainThread) [custom_components.unraid.api.network_operations] Interface existence check: eth3 (exists=True)
2025-01-07 23:18:09.781 DEBUG (MainThread) [custom_components.unraid.api.network_operations] Interface existence check: bond1 (exists=True)
2025-01-07 23:18:09.869 ERROR (MainThread) [custom_components.unraid.unraid] Command failed: open failed
2025-01-07 23:18:09.870 ERROR (MainThread) [custom_components.unraid.unraid] Command failed: open failed
2025-01-07 23:18:09.913 DEBUG (MainThread) [custom_components.unraid.api.network_operations] First measurement - storing bytes=405791019678 at 2025-01-07T22:18:09.913255+00:00
2025-01-07 23:18:09.913 DEBUG (MainThread) [custom_components.unraid.api.network_operations] First measurement - storing bytes=544497349430 at 2025-01-07T22:18:09.913513+00:00
2025-01-07 23:18:09.913 DEBUG (MainThread) [custom_components.unraid.api.network_operations] Update too frequent (0.000s < 1.000s) - keeping previous rate: 0.00 bits/s
2025-01-07 23:18:09.913 DEBUG (MainThread) [custom_components.unraid.api.network_operations] Update too frequent (0.000s < 1.000s) - keeping previous rate: 0.00 bits/s
2025-01-07 23:18:09.913 DEBUG (MainThread) [custom_components.unraid.api.network_operations] Update too frequent (0.001s < 1.000s) - keeping previous rate: 0.00 bits/s
2025-01-07 23:18:09.913 DEBUG (MainThread) [custom_components.unraid.api.network_operations] Update too frequent (0.000s < 1.000s) - keeping previous rate: 0.00 bits/s
2025-01-07 23:18:09.914 DEBUG (MainThread) [custom_components.unraid.api.network_operations] Update too frequent (0.001s < 1.000s) - keeping previous rate: 0.00 bits/s
2025-01-07 23:18:09.914 DEBUG (MainThread) [custom_components.unraid.api.network_operations] Update too frequent (0.001s < 1.000s) - keeping previous rate: 0.00 bits/s
2025-01-07 23:18:09.997 DEBUG (MainThread) [custom_components.unraid.coordinator] Found parity check cron: # Generated parity check schedule: 0 0 * * 0 /usr/local/sbin/mdcmd check NOCORRECT &> /dev/null

Unraid (please complete the following information):

• Version 6.2.14

Home Assistant (please complete the following information):

• Version 2025.1.1

Home Assistant installation type (please complete the following information):

• Docker / Container
• Virtual Machine
• Raspberry Pi
• Baremetal

Additional context

[domalab]

I made some updates

• I split the single cat command into two separate commands
• Added error handling for each command
• Maintained the same interface normalization and validation
• Added proper logging for debugging

[ond000]

I just downloaded code from git and replace it at HA, but error is still here and debug log looks similar:

2025-01-11 22:37:16.019 DEBUG (MainThread) [custom_components.unraid.api.network_operations] Processing interface: eth0 (normalized: eth0)
2025-01-11 22:37:16.022 DEBUG (MainThread) [custom_components.unraid.api.network_operations] Processing interface: eth1 (normalized: eth1)
2025-01-11 22:37:16.031 DEBUG (MainThread) [custom_components.unraid.api.network_operations] Processing interface: eth3 (normalized: eth3)
2025-01-11 22:37:16.034 DEBUG (MainThread) [custom_components.unraid.api.network_operations] Processing interface: bond1 (normalized: bond1)
2025-01-11 22:37:16.435 DEBUG (MainThread) [custom_components.unraid.api.network_operations] Interface existence check: eth0 (exists=True)
2025-01-11 22:37:16.439 DEBUG (MainThread) [custom_components.unraid.api.network_operations] Interface existence check: eth1 (exists=True)
2025-01-11 22:37:16.443 DEBUG (MainThread) [custom_components.unraid.api.network_operations] Interface existence check: eth3 (exists=True)
2025-01-11 22:37:16.446 DEBUG (MainThread) [custom_components.unraid.api.network_operations] Interface existence check: bond1 (exists=True)
2025-01-11 22:37:16.746 ERROR (MainThread) [custom_components.unraid.unraid] Command failed: open failed
2025-01-11 22:37:16.747 ERROR (MainThread) [custom_components.unraid.unraid] Command failed: open failed
2025-01-11 22:37:16.785 DEBUG (MainThread) [custom_components.unraid.api.network_operations] Rate calculation - bytes: 448629691649 → 448647317212 (+17625563), time: 64.979s, raw_rate: 2170006.55 bits/s
2025-01-11 22:37:16.785 DEBUG (MainThread) [custom_components.unraid.api.network_operations] Updated EMA: 344077.64 → 1074449.20 bits/s (alpha=0.40)
2025-01-11 22:37:16.785 DEBUG (MainThread) [custom_components.unraid.api.network_operations] Rate calculation - bytes: 815744873519 → 815765035401 (+20161882), time: 64.979s, raw_rate: 2482283.20 bits/s
2025-01-11 22:37:16.785 DEBUG (MainThread) [custom_components.unraid.api.network_operations] Updated EMA: 3320107.41 → 2984977.73 bits/s (alpha=0.40)
2025-01-11 22:37:16.786 DEBUG (MainThread) [custom_components.unraid.api.network_operations] Update too frequent (0.001s < 1.000s) - keeping previous rate: 1074449.20 bits/s
2025-01-11 22:37:16.786 DEBUG (MainThread) [custom_components.unraid.api.network_operations] Update too frequent (0.000s < 1.000s) - keeping previous rate: 2984977.73 bits/s
2025-01-11 22:37:16.786 DEBUG (MainThread) [custom_components.unraid.api.network_operations] Update too frequent (0.001s < 1.000s) - keeping previous rate: 1074449.20 bits/s
2025-01-11 22:37:16.786 DEBUG (MainThread) [custom_components.unraid.api.network_operations] Update too frequent (0.001s < 1.000s) - keeping previous rate: 2984977.73 bits/s
2025-01-11 22:37:16.786 DEBUG (MainThread) [custom_components.unraid.api.network_operations] Update too frequent (0.001s < 1.000s) - keeping previous rate: 1074449.20 bits/s
2025-01-11 22:37:16.786 DEBUG (MainThread) [custom_components.unraid.api.network_operations] Update too frequent (0.001s < 1.000s) - keeping previous rate: 2984977.73 bits/s
2025-01-11 22:37:16.786 DEBUG (MainThread) [custom_components.unraid.coordinator] Significant RX speed change for eth0: 344077.64 -> 1074449.20
2025-01-11 22:37:16.786 DEBUG (MainThread) [custom_components.unraid.coordinator] Significant RX speed change for eth1: 344077.64 -> 1074449.20
2025-01-11 22:37:16.786 DEBUG (MainThread) [custom_components.unraid.coordinator] Significant RX speed change for eth3: 344077.64 -> 1074449.20
2025-01-11 22:37:16.787 DEBUG (MainThread) [custom_components.unraid.coordinator] Significant RX speed change for bond1: 344077.64 -> 1074449.20