john30 / ebusd

daemon for communication with eBUS heating systems
GNU General Public License v3.0
594 stars 136 forks source link

Default root /usr/bin/ebusd intance causing conflicts #1184

Closed kjoglum closed 9 months ago

kjoglum commented 9 months ago

Description

On a fresh install (after having had a fully functional ebusd setup over several years), running Debian 12 (Bookworm) on RPi4, ebusd v23.3.23.3, ESERA eBus coupler USB, a default root /usr/bin/ebusd instance is causing conflicts.

The default /usr/bin/ebusd instance is restarted automatically after kill.

sudo nano /etc/default/ebusd is defined as #EBUSD_OPTS="--scanconfig.

Also see #1178.

Similar issues of Arbitration lost are reported over the last couple of weeks: https://github.com/john30/ebusd/discussions

Actual behavior

1. Manual start of ebusd without killing default /usr/bin/ebusd instance

sudo ebusd -d /dev/ttyUSB0 --scanconfig --configpath=/etc/ebusd/config --enablehex --lograwdata --logareas=all --logfile=/var/log/ebusd.log --loglevel=debug -f --mqtthost=localhost --mqttport=1883 --accesslevel="*"

Log indicate invalid device, which would point in the direction of already having an active instance (i.e. the /usr/bin/ebusd instance):

2024-02-05 12:28:05.550 [bus error] device status: transport closed 2024-02-05 12:28:05.550 [bus error] device status: transport closed 2024-02-05 12:28:05.550 [bus error] device /dev/ttyUSB0 not available 2024-02-05 12:28:05.550 [main info] registering data handlers 2024-02-05 12:28:05.550 [mqtt info] mosquitto version 2.0.11 (compiled with 2.0.11) 2024-02-05 12:28:05.552 [mqtt debug] connection requested 2024-02-05 12:28:05.552 [main info] registered data handlers 2024-02-05 12:28:05.552 [main notice] ebusd 23.3.23.3 started with broadcast scan on device: /dev/ttyUSB0, serial 2024-02-05 12:28:05.552 [main info] loading configuration files from /etc/ebusd/config/ 2024-02-05 12:28:05.552 [main debug] reading directory /etc/ebusd/config/ 2024-02-05 12:28:05.554 [main debug] file type of /etc/ebusd/config/._broadcast.csv is file 2024-02-05 12:28:05.554 [main debug] file type of /etc/ebusd/config/._.DS_Store is file 2024-02-05 12:28:05.555 [main debug] file type of /etc/ebusd/config/._vaillant is file 2024-02-05 12:28:05.555 [main debug] file type of /etc/ebusd/config/memory.csv is file 2024-02-05 12:28:05.555 [main debug] file type of /etc/ebusd/config/._memory.csv is file 2024-02-05 12:28:05.555 [main debug] file type of /etc/ebusd/config/vaillant is dir 2024-02-05 12:28:05.555 [main debug] file type of /etc/ebusd/config/.DS_Store is file 2024-02-05 12:28:05.555 [main debug] file type of /etc/ebusd/config/broadcast.csv is file 2024-02-05 12:28:05.555 [main debug] file type of /etc/ebusd/config/.__templates.csv is file 2024-02-05 12:28:05.555 [main debug] file type of /etc/ebusd/config/_templates.csv is file 2024-02-05 12:28:05.556 [main info] reading templates / 2024-02-05 12:28:05.558 [main info] read templates in / 2024-02-05 12:28:05.558 [main info] reading file ._broadcast.csv 2024-02-05 12:28:05.559 [main error] error reading config files from /etc/ebusd/config/: ERR: end of input reached, last error: ._broadcast.csv:1: ERR: end of input reached, missing message type/name/pbsb 2024-02-05 12:28:05.560 [bus notice] bus started with own address 31/36 2024-02-05 12:28:05.560 [bus notice] device invalid

2024-02-05 12:28:10.562 [bus error] device status: transport closed 2024-02-05 12:28:10.562 [bus error] device status: transport closed 2024-02-05 12:28:10.562 [bus notice] re-opened /dev/ttyUSB0 2024-02-05 12:28:10.562 [bus notice] device invalid

2. Manual start of ebusd after killing default /usr/bin/ebusd instance

sudo ebusd -d /dev/ttyUSB0 --scanconfig --configpath=/etc/ebusd/config --enablehex --lograwdata --logareas=all --logfile=/var/log/ebusd.log --loglevel=debug -f --mqtthost=localhost --mqttport=1883 --accesslevel="*"

Initiation starts as expected, bus traffic recognised:

2024-02-05 11:30:24.566 [bus notice] device status: transport opened 2024-02-05 11:30:24.566 [main info] registering data handlers 2024-02-05 11:30:24.566 [mqtt info] mosquitto version 2.0.11 (compiled with 2.0.11) 2024-02-05 11:30:24.568 [mqtt debug] connection requested 2024-02-05 11:30:24.568 [main info] registered data handlers 2024-02-05 11:30:24.568 [main notice] ebusd 23.3.23.3 started with broadcast scan on device: /dev/ttyUSB0, serial 2024-02-05 11:30:24.568 [main info] loading configuration files from /etc/ebusd/config/ 2024-02-05 11:30:24.568 [main debug] reading directory /etc/ebusd/config/ 2024-02-05 11:30:24.570 [main debug] file type of /etc/ebusd/config/._broadcast.csv is file 2024-02-05 11:30:24.570 [main debug] file type of /etc/ebusd/config/._.DS_Store is file 2024-02-05 11:30:24.570 [main debug] file type of /etc/ebusd/config/._vaillant is file 2024-02-05 11:30:24.571 [main debug] file type of /etc/ebusd/config/memory.csv is file 2024-02-05 11:30:24.571 [main debug] file type of /etc/ebusd/config/._memory.csv is file 2024-02-05 11:30:24.571 [main debug] file type of /etc/ebusd/config/vaillant is dir 2024-02-05 11:30:24.571 [main debug] file type of /etc/ebusd/config/.DS_Store is file 2024-02-05 11:30:24.571 [main debug] file type of /etc/ebusd/config/broadcast.csv is file 2024-02-05 11:30:24.571 [main debug] file type of /etc/ebusd/config/.__templates.csv is file 2024-02-05 11:30:24.571 [main debug] file type of /etc/ebusd/config/_templates.csv is file 2024-02-05 11:30:24.571 [main info] reading templates / 2024-02-05 11:30:24.574 [main info] read templates in / 2024-02-05 11:30:24.574 [main info] reading file ._broadcast.csv 2024-02-05 11:30:24.575 [main error] error reading config files from /etc/ebusd/config/: ERR: end of input reached, last error: ._broadcast.csv:1: ERR: end of input reached, missing message type/name/pbsb 2024-02-05 11:30:24.576 [bus notice] bus started with own address 31/36 2024-02-05 11:30:24.577 [mqtt notice] connection established 2024-02-05 11:30:24.577 [mqtt debug] publish ebusd/global/version ebusd 23.3.23.3 2024-02-05 11:30:24.578 [mqtt debug] publish ebusd/global/running true 2024-02-05 11:30:24.578 [mqtt debug] publish ebusd/global/running true 2024-02-05 11:30:24.592 [bus debug] ERR: SYN received during no signal, switching to ready 2024-02-05 11:30:24.592 [bus notice] signal acquired 2024-02-05 11:30:26.143 [bus notice] new master 03, master count 2 2024-02-05 11:30:26.213 [update info] received MS cmd: 03e8b512060b2602150200 / 0b2502000001ffffffffff00 2024-02-05 11:30:26.213 [update notice] received unknown MS cmd: 03e8b512060b2602150200 / 0b2502000001ffffffffff00 2024-02-05 11:30:26.217 [bus notice] <03e8b512060b26021502004e000b2502000001ffffffffff00b400 2024-02-05 11:30:28.004 [bus notice] new master 10, master count 3 2024-02-05 11:30:28.063 [update info] received MS cmd: 1008b5110101 / 0955530080ffff0100ff 2024-02-05 11:30:28.063 [update notice] received unknown MS cmd: 1008b5110101 / 0955530080ffff0100ff 2024-02-05 11:30:28.068 [bus notice] <1008b511010189000955530080ffff0100ff2400 2024-02-05 11:30:28.329 [bus notice] new master 71, master count 4 2024-02-05 11:30:28.329 [update info] received MS cmd: 1076b5110101 / 09ffffe8ffffff000051 2024-02-05 11:30:28.329 [update notice] received unknown MS cmd: 1076b5110101 / 09ffffe8ffffff000051 2024-02-05 11:30:28.333 [bus notice] <1076b5110101160009ffffe8ffffff0000513800 2024-02-05 11:30:28.593 [update info] received MS cmd: 1076b512030f0101 / 070080008a02ff01 2024-02-05 11:30:28.593 [update notice] received unknown MS cmd: 1076b512030f0101 / 070080008a02ff01 2024-02-05 11:30:28.597 [bus notice] <1076b512030f01016700070080008a02ff010100 2024-02-05 11:30:28.859 [update info] received MS cmd: 1008b51009000055ffffff060000 / 0101 2024-02-05 11:30:28.859 [update notice] received unknown MS cmd: 1008b51009000055ffffff060000 / 0101 2024-02-05 11:30:28.864 [bus notice] <1008b51009000055ffffff060000bd0001019a00 2024-02-05 11:30:29.121 [update info] received MS cmd: 1076b51009000000ffffff050000 / 0101 2024-02-05 11:30:29.121 [update notice] received unknown MS cmd: 1076b51009000000ffffff050000 / 0101 2024-02-05 11:30:29.125 [bus notice] <1076b51009000000ffffff050000dd0001019a00 2024-02-05 11:30:29.501 [update info] received MS cmd: 7108b5110107 / 0514dd000109 2024-02-05 11:30:29.502 [update notice] received unknown MS cmd: 7108b5110107 / 0514dd000109 2024-02-05 11:30:29.506 [bus notice] <7108b5110107b4000514dd0001093800

However, after a short while (corresponding to when the default /usr/bin/ebusd root instance is automatically reconnected?), the system is starting to report Arbitration lost:

2024-02-05 12:52:51.654 [bus debug] start request 31 2024-02-05 12:52:51.654 [bus debug] arbitration start with 31 2024-02-05 12:52:51.701 [bus debug] arbitration lost 2024-02-05 12:52:51.701 [bus debug] ERR: arbitration lost during ready, retry 2024-02-05 12:52:51.741 [bus debug] ERR: read timeout during receive command, switching to skip 2024-02-05 12:52:51.741 [bus debug] start request 31 2024-02-05 12:52:51.741 [bus debug] arbitration start with 31 2024-02-05 12:52:51.745 [bus notice] >31<00fe 2024-02-05 12:52:51.751 [bus debug] arbitration won 2024-02-05 12:52:51.751 [bus debug] arbitration delay 88 micros 2024-02-05 12:52:51.751 [bus info] arbitration delay 88 - 88 micros 2024-02-05 12:52:51.751 [bus debug] switching from ready to send command 2024-02-05 12:52:51.757 [bus debug] send/receive symbol latency 5 ms 2024-02-05 12:52:51.757 [bus info] send/receive symbol latency 5 - 5 ms 2024-02-05 12:52:51.763 [bus debug] send/receive symbol latency 5 ms 2024-02-05 12:52:51.769 [bus debug] send/receive symbol latency 5 ms 2024-02-05 12:52:51.775 [bus debug] send/receive symbol latency 5 ms 2024-02-05 12:52:51.775 [bus debug] switching from send command to send command CRC 2024-02-05 12:52:51.781 [bus debug] send/receive symbol latency 5 ms 2024-02-05 12:52:51.781 [update info] sent BC cmd: 31fe07fe00 2024-02-05 12:52:51.781 [update notice] sent unknown BC cmd: 31fe07fe00 2024-02-05 12:52:51.781 [bus debug] notify request: done 2024-02-05 12:52:51.781 [bus debug] read res: 2024-02-05 12:52:51.781 [bus debug] switching from send command CRC to send SYN

EDIT In fact, after downgrading to version 23.2, a default root /usr/bin/ebusd instance is NOT created/reconnected, and thus the manual ebusd initiation also works as expected again (without making any other changes, i.e. same as before). So something seems changed/broken between version 23.2 and 23.3.

Expected behavior

A default root /usr/bin/ebusd should not be initiated/reconnected?

ebusd version

23.3

ebusd arguments

EBUSD_OPTS="--scanconfig

Operating system

Debian 12 (Bookworm) / Ubuntu 22-23 / Raspberry Pi OS 12 (including lite)

CPU architecture

x64

Dockerized

None

Hardware interface

Adapter v3 USB

Related integration

No response

Logs

See above

john30 commented 9 months ago

duplicate of #1178, so closing.

anyway, repeating https://github.com/john30/ebusd/issues/1178#issuecomment-1937702280 :

if ebusd is installed, it registers in the OS as daemon and as such you have to stop that if you want to run it explicitly in foreground.

kjoglum commented 9 months ago

But how/why is this feature introduced between version 23.2 and 23.3? Even if killing the root instance, it restarts automatically. And if one uses custom config files, one would not be able to use ebusd v23.3.

john30 commented 9 months ago

just disable the daemon with the appropriate command to the system if you want to. thats the way it is supposed to work (for every daemon not just ebusd)

john30 commented 9 months ago

killing the "root instance" as you call it (which is the one started from systemd or init.d) won't solve it as it will be restarted intentionally (as with any daemon set up to do so e.g. in the systemd config file https://github.com/john30/ebusd/blob/7456bd6a54248507f9a6ae4c2bbb3116b3963aa2/contrib/debian/systemd/ebusd.service#L8)