Either "ERR: read timeout during receive..." or "ERR: SYN received during receive..."

[jvanoosterhout]

Hey,

I am getting more exited about the work done on ebus control, though also a litle lost (again). Probably it is just some silly setting, though there are so many 🙈. I really hope someone can point me in the right direction. Please let me know when more information is needed or how I can contribute improving the tool and its descriptions.

Issue
While using default settings as seen in e.g. https://github.com/christiaanderidder/brink-renovent-hru or https://github.com/dstrigl/ebusd-config-brink-renovent-excellent-300, I am not able to read/receive any useful data, besides the master and slave including successfully loading a config file to the slave and the SW version (the later just in the last phase of prepairing this question). It is very cool to see that the slave is down/unidentified just after starting the daemon, and then it find one and connects it to the config file.

After playing some with the latency (0, 10, 20, 30, 40, 50, 60, 20.000 and even 200.000 as some sugest) I noticed a transition in ERR messages. Lower values (<20) tend to present "ERR: read timeout during receive command ACK, switching to skip" while higher values (>20) tend to present "ERR: SYN received during receive command ACK, switching to ready". I do not know how to solve this issue given that other have succeded with the "default" settings on similar devices.

Hardware:

• eBUS Adapter Shield v5 connected via USB
• Raspbery pi 4 (1gb ram)
• Brink Renovent Excellent 400 plus (working ebus: I have a working Brink Air Control unit, a zone valve and 2 co2 sensors, though all is disconnected to isolate potential issues and get the ebus adapter working)

Software:

• Pi operating System: fresh installed and updated Debian GNU/Linux 12 (bookworm arm64)
• ebusd: lates build in Docker with configurations as shown below.
• ebus firmware: 2024-10-08

Notable remaks, but potentially unrelated

• The slave is listed in “ebusctl info” as scan.c7 where c7 is its address, but I did not name it scan, nor do I see any other post mentioning this type of naming. I do not understand what this means. The other configuration files map normally to the names given in the csv.
• Although I specified an EBUSD_CONFIGPATH, the scan insist that the configuration file are located in a subfolder named after the manufacturer, encon in this case. Only then it can usefully match/load the config. I have not seen these instructions elsewhere.
• After adding the config file “scan.csv” from ebusd-brink-hru/ebusd-scan/scan.csv at main · pvyleta/ebusd-brink-hru to the encon directory, the ebusd finds one entry:
  Excellent400 SoftwareVersion = S1.08.05 0004
  Notably, this is the correct SW, though the data is assigned to an entry of the c7.csv config and not the scan.csv. The entries of the scan.csv remain:

scan id = no data stored
scan Software Version = no data stored

Neither does the SW version end up in the mysterious “scan.c7” device (first point in this list)
scan.7c = ENCON; ;-;-
I do not understand what this means.

docker-compose.yaml

services:
  ebusd:
    # For all configuration options, see: https://github.com/john30/ebusd/blob/master/contrib/docker/docker-compose.example.yaml
    container_name: ebusd
    image: john30/ebusd:v24.1
    restart: unless-stopped
    # privileged: true
    ports:
      - 8888:8888
    volumes:
      # Make sure to configure the correct local path for your docker mount here
      - ./:/home/jeroenvanoosterhout/Workspace/Domotica/MV/
    devices:
      # when using an USB device, make sure to hand it in to the container like this:
      - /dev/ttyACM0:/dev/ttyACM0
    environment:
      # Make sure to set the correct IP for your eBUSd Adapter Shield here
      EBUSD_DEVICE: "ens:/dev/ttyACM0"
      # Load custom eBUS message config from docker volume
      EBUSD_CONFIGPATH: "/home/jeroenvanoosterhout/Workspace/Domotica/MV/mvconfig"
      # Extra transfer latency in ms
      EBUSD_LATENCY: 15
      # Pick CSV config files matching initial scan (ADDR="none" or empty for no initial scan message, "full" for full
      # scan, or a single hex address to scan, default is broadcast ident message).
      EBUSD_SCANCONFIG: "full"
      # Poll for data every SEC seconds (0=disable)
      EBUSD_POLLINTERVAL: 10
      # Expect a slave to answer within MSEC ms
      EBUSD_RECEIVETIMEOUT: 10
      # Only write log below or equal to LEVEL: error|notice|info|debug
      EBUSD_LOGLEVEL: "debug"
      # Log messages or all received/sent bytes on the bus
      EBUSD_LOGRAWDATA: "byte"

7c.Excellent400.csv
brink-renovent-hru/ebusd/config/7c.Excellent400.csv at main · christiaanderidder/brink-renovent-hru
ebusd-brink-hru/ebusd-scan/scan.csv at main · pvyleta/ebusd-brink-hru

ebusd log

jeroenvanoosterhout@raspberrypi:~/Workspace/Domotica/MV $ docker compose up
[+] Running 1/1
 ✔ Container ebusd  Recreated                                                                         0.3s 
Attaching to ebusd
ebusd  | 2024-10-27 13:24:43.538 [device notice] transport opened
ebusd  | 2024-10-27 13:24:43.539 [main info] registering data handlers
ebusd  | 2024-10-27 13:24:43.539 [main info] registered data handlers
ebusd  | 2024-10-27 13:24:43.540 [main notice] ebusd 24.1.24.1 started with broadcast scan on device: /dev/ttyACM0, serial high speed, enhanced
ebusd  | 2024-10-27 13:24:43.540 [main info] loading configuration files from /home/jeroenvanoosterhout/Workspace/Domotica/MV/mvconfig/
ebusd  | 2024-10-27 13:24:43.540 [main debug] reading directory /home/jeroenvanoosterhout/Workspace/Domotica/MV/mvconfig/
ebusd  | 2024-10-27 13:24:43.540 [main debug] file type of /home/jeroenvanoosterhout/Workspace/Domotica/MV/mvconfig/encon is dir
ebusd  | 2024-10-27 13:24:43.540 [main info] read config files, got 0 messages
ebusd  | 2024-10-27 13:24:43.541 [bus notice] bus started with own address 31/36
ebusd  | 2024-10-27 13:24:43.541 [device notice] reset, supports info
ebusd  | 2024-10-27 13:24:43.541 [device notice] extra info: firmware 1.1[4a08].1[4a08], jumpers 0x03
ebusd  | 2024-10-27 13:24:43.545 [bus debug] ERR: SYN received during no signal, switching to ready
ebusd  | 2024-10-27 13:24:43.545 [bus notice] signal acquired
ebusd  | 2024-10-27 13:24:45.802 [bus notice] new master 77, master count 2
ebusd  | 2024-10-27 13:24:45.837 [bus debug] ERR: read timeout during receive command ACK, switching to skip
ebusd  | 2024-10-27 13:24:45.849 [bus notice] <778040a004007d007d1c
ebusd  | 2024-10-27 13:24:50.865 [bus debug] ERR: read timeout during receive command ACK, switching to skip
ebusd  | 2024-10-27 13:24:50.878 [bus notice] <778140a004007d007dca
ebusd  | 2024-10-27 13:24:53.542 [main debug] performing regular tasks
ebusd  | 2024-10-27 13:24:53.542 [main notice] starting initial broadcast scan
ebusd  | 2024-10-27 13:24:53.542 [bus info] send message: 31fe07fe00
ebusd  | 2024-10-27 13:24:53.567 [bus debug] start request 31
ebusd  | 2024-10-27 13:24:53.567 [bus debug] arbitration start with 31
ebusd  | 2024-10-27 13:24:53.617 [bus debug] arbitration won
ebusd  | 2024-10-27 13:24:53.617 [bus debug] arbitration delay 14 micros
ebusd  | 2024-10-27 13:24:53.617 [bus info] arbitration delay 14 - 14 micros
ebusd  | 2024-10-27 13:24:53.617 [bus debug] switching from ready to send command
ebusd  | 2024-10-27 13:24:53.622 [bus debug] send/receive symbol latency 4 ms
ebusd  | 2024-10-27 13:24:53.622 [bus info] send/receive symbol latency 4 - 4 ms
ebusd  | 2024-10-27 13:24:53.626 [bus debug] send/receive symbol latency 4 ms
ebusd  | 2024-10-27 13:24:53.634 [bus debug] send/receive symbol latency 7 ms
ebusd  | 2024-10-27 13:24:53.634 [bus info] send/receive symbol latency 4 - 7 ms
ebusd  | 2024-10-27 13:24:53.638 [bus debug] send/receive symbol latency 4 ms
ebusd  | 2024-10-27 13:24:53.638 [bus debug] switching from send command to send command CRC
ebusd  | 2024-10-27 13:24:53.643 [bus debug] send/receive symbol latency 4 ms
ebusd  | 2024-10-27 13:24:53.643 [update info] sent BC cmd: 31fe07fe00
ebusd  | 2024-10-27 13:24:53.643 [update notice] sent unknown BC cmd: 31fe07fe00
ebusd  | 2024-10-27 13:24:53.643 [bus debug] notify request: done
ebusd  | 2024-10-27 13:24:53.643 [bus debug] read res: 
ebusd  | 2024-10-27 13:24:53.643 [bus debug] switching from send command CRC to send SYN
ebusd  | 2024-10-27 13:24:53.643 [bus notice] >31fe07fe0035
ebusd  | 2024-10-27 13:24:53.648 [bus debug] send/receive symbol latency 4 ms
ebusd  | 2024-10-27 13:24:53.648 [bus debug] switching from send SYN to ready
ebusd  | 2024-10-27 13:24:55.843 [bus debug] ERR: read timeout during receive command ACK, switching to skip
ebusd  | 2024-10-27 13:24:55.855 [bus notice] <778240a004007d007d2b
ebusd  | 2024-10-27 13:25:00.887 [bus debug] ERR: read timeout during receive command ACK, switching to skip
ebusd  | 2024-10-27 13:25:00.899 [bus notice] <778340a004007d007dfd
ebusd  | 2024-10-27 13:25:03.644 [main debug] performing regular tasks
ebusd  | 2024-10-27 13:25:03.644 [bus info] scan 7c cmd: 317c070400
ebusd  | 2024-10-27 13:25:03.689 [bus debug] start request 31
ebusd  | 2024-10-27 13:25:03.689 [bus debug] arbitration start with 31
ebusd  | 2024-10-27 13:25:03.739 [bus debug] arbitration won
ebusd  | 2024-10-27 13:25:03.739 [bus debug] arbitration delay 16 micros
ebusd  | 2024-10-27 13:25:03.739 [bus info] arbitration delay 14 - 16 micros
ebusd  | 2024-10-27 13:25:03.739 [bus debug] switching from ready to send command
ebusd  | 2024-10-27 13:25:03.746 [bus debug] send/receive symbol latency 7 ms
ebusd  | 2024-10-27 13:25:03.751 [bus debug] send/receive symbol latency 4 ms
ebusd  | 2024-10-27 13:25:03.756 [bus debug] send/receive symbol latency 4 ms
ebusd  | 2024-10-27 13:25:03.760 [bus debug] send/receive symbol latency 4 ms
ebusd  | 2024-10-27 13:25:03.760 [bus debug] switching from send command to send command CRC
ebusd  | 2024-10-27 13:25:03.765 [bus debug] send/receive symbol latency 4 ms
ebusd  | 2024-10-27 13:25:03.765 [bus debug] switching from send command CRC to receive command ACK
ebusd  | 2024-10-27 13:25:03.769 [bus debug] switching from receive command ACK to receive response
ebusd  | 2024-10-27 13:25:03.815 [bus debug] switching from receive response to receive response CRC
ebusd  | 2024-10-27 13:25:03.819 [bus debug] switching from receive response CRC to send response ACK
ebusd  | 2024-10-27 13:25:03.823 [bus debug] send/receive symbol latency 4 ms
ebusd  | 2024-10-27 13:25:03.823 [update info] sent MS cmd: 317c070400 / 0a400811002203ffffffff
ebusd  | 2024-10-27 13:25:03.824 [bus notice] scan 7c: ;ENCON;  ;-;-
ebusd  | 2024-10-27 13:25:03.824 [update notice] store 7c ident: done
ebusd  | 2024-10-27 13:25:03.824 [update notice] sent scan-read scan.7c  QQ=31: ENCON;  ;-;-
ebusd  | 2024-10-27 13:25:03.824 [bus debug] notify request: done
ebusd  | 2024-10-27 13:25:03.824 [bus notice] scan 7c: ;ENCON;  ;-;-
ebusd  | 2024-10-27 13:25:03.824 [bus debug] switching from send response ACK to send SYN
ebusd  | 2024-10-27 13:25:03.824 [bus notice] >317c07040022<000a400811002203ffffffff66>00
ebusd  | 2024-10-27 13:25:03.824 [main debug] reading directory /home/jeroenvanoosterhout/Workspace/Domotica/MV/mvconfig/encon/
ebusd  | 2024-10-27 13:25:03.826 [main debug] file type of /home/jeroenvanoosterhout/Workspace/Domotica/MV/mvconfig/encon/scan.csv is file
ebusd  | 2024-10-27 13:25:03.826 [main debug] file type of /home/jeroenvanoosterhout/Workspace/Domotica/MV/mvconfig/encon/7c.Excellent400.csv is file
ebusd  | 2024-10-27 13:25:03.826 [main debug] found 1 matching scan config files from encon with prefix 7c: done
ebusd  | 2024-10-27 13:25:03.826 [main debug] reading directory /home/jeroenvanoosterhout/Workspace/Domotica/MV/mvconfig/encon/
ebusd  | 2024-10-27 13:25:03.827 [main debug] file type of /home/jeroenvanoosterhout/Workspace/Domotica/MV/mvconfig/encon/scan.csv is file
ebusd  | 2024-10-27 13:25:03.827 [main debug] file type of /home/jeroenvanoosterhout/Workspace/Domotica/MV/mvconfig/encon/7c.Excellent400.csv is file
ebusd  | 2024-10-27 13:25:03.829 [bus debug] send/receive symbol latency 4 ms
ebusd  | 2024-10-27 13:25:03.829 [bus debug] switching from send SYN to ready
ebusd  | 2024-10-27 13:25:03.830 [main notice] read common config file encon/scan.csv
ebusd  | 2024-10-27 13:25:03.849 [main notice] read scan config file encon/7c.Excellent400.csv for ID "", SW65535, HW65535
ebusd  | 2024-10-27 13:25:03.849 [main notice] found messages: 137 (0 conditional on 0 conditions, 0 poll, 0 update)
ebusd  | 2024-10-27 13:25:03.849 [bus info] scan 7c cmd: 317c40220100
ebusd  | 2024-10-27 13:25:03.875 [bus debug] start request 31
ebusd  | 2024-10-27 13:25:03.875 [bus debug] arbitration start with 31
ebusd  | 2024-10-27 13:25:03.929 [bus debug] arbitration won
ebusd  | 2024-10-27 13:25:03.929 [bus debug] arbitration delay 9 micros
ebusd  | 2024-10-27 13:25:03.929 [bus info] arbitration delay 9 - 16 micros
ebusd  | 2024-10-27 13:25:03.929 [bus debug] switching from ready to send command
ebusd  | 2024-10-27 13:25:03.935 [bus debug] send/receive symbol latency 6 ms
ebusd  | 2024-10-27 13:25:03.940 [bus debug] send/receive symbol latency 3 ms
ebusd  | 2024-10-27 13:25:03.940 [bus info] send/receive symbol latency 3 - 7 ms
ebusd  | 2024-10-27 13:25:03.944 [bus debug] send/receive symbol latency 2 ms
ebusd  | 2024-10-27 13:25:03.944 [bus info] send/receive symbol latency 2 - 7 ms
ebusd  | 2024-10-27 13:25:03.951 [bus debug] send/receive symbol latency 7 ms
ebusd  | 2024-10-27 13:25:03.956 [bus debug] send/receive symbol latency 4 ms
ebusd  | 2024-10-27 13:25:03.957 [bus debug] switching from send command to send command CRC
ebusd  | 2024-10-27 13:25:03.962 [bus debug] send/receive symbol latency 4 ms
ebusd  | 2024-10-27 13:25:03.962 [bus debug] switching from send command CRC to receive command ACK
ebusd  | 2024-10-27 13:25:03.968 [bus debug] switching from receive command ACK to receive response
ebusd  | 2024-10-27 13:25:04.024 [bus debug] switching from receive response to receive response CRC
ebusd  | 2024-10-27 13:25:04.029 [bus debug] switching from receive response CRC to send response ACK
ebusd  | 2024-10-27 13:25:04.033 [bus debug] send/receive symbol latency 4 ms
ebusd  | 2024-10-27 13:25:04.033 [update info] sent MS cmd: 317c40220100 / 0d53312e30382e30352030303034
ebusd  | 2024-10-27 13:25:04.033 [update notice] sent read Excellent400 SoftwareVersion QQ=31: S1.08.05 0004
ebusd  | 2024-10-27 13:25:04.033 [bus debug] notify request: done
ebusd  | 2024-10-27 13:25:04.033 [bus notice] scan 7c: ;49;14384;12334
ebusd  | 2024-10-27 13:25:04.033 [bus debug] switching from send response ACK to send SYN
ebusd  | 2024-10-27 13:25:04.033 [main info] scan config 7c message received
ebusd  | 2024-10-27 13:25:04.033 [bus notice] >317c402201000f<000d53312e30382e30352030303034a1>00
ebusd  | 2024-10-27 13:25:04.038 [bus debug] send/receive symbol latency 4 ms
ebusd  | 2024-10-27 13:25:04.038 [bus debug] switching from send SYN to ready
ebusd  | 2024-10-27 13:25:05.960 [bus debug] ERR: read timeout during receive command ACK, switching to skip
ebusd  | 2024-10-27 13:25:05.973 [bus notice] <778540a004007d007da4
ebusd  | 2024-10-27 13:25:06.033 [main debug] performing regular tasks
ebusd  | 2024-10-27 13:25:10.985 [bus debug] ERR: read timeout during receive command ACK, switching to skip
ebusd  | 2024-10-27 13:25:10.997 [bus notice] <778640a004007d007d45
ebusd  | 2024-10-27 13:25:16.013 [bus debug] ERR: read timeout during receive command ACK, switching to skip
ebusd  | 2024-10-27 13:25:16.024 [bus notice] <778740a004007d007d93
ebusd  | 2024-10-27 13:25:16.034 [main debug] performing regular tasks
ebusd  | 2024-10-27 13:25:21.010 [bus debug] ERR: read timeout during receive command ACK, switching to skip

ebusctl info verbose

jeroenvanoosterhout@raspberrypi:~ $ docker exec -it ebusd /bin/bash
root@d1621ca6df7f:/# ebusctl info verbose
version: ebusd 24.1.24.1
device: /dev/ttyACM0, serial high speed, enhanced, firmware 1.1[4a08].1[4a08], temperature 40 °C, supply voltage unknown, bus voltage 13.9 V - 24.0 V
signal: acquired
symbol rate: 64
max symbol rate: 64
min arbitration micros: 8
max arbitration micros: 33
min symbol latency: 3
max symbol latency: 5
scan: running
reconnects: 0
masters: 2
messages: 137
conditional: 0
poll: 0
update: 0
config path: /home/jeroenvanoosterhout/Workspace/Domotica/MV/mvconfig/
address 31: master #8, ebusd
address 36: slave #8, ebusd
address 77: master #19
address 7c: slave #19, scanned "MF=ENCON;ID=  ;SW=-;HW=-", loaded "encon/7c.Excellent400.csv"

ebusctl find

jeroenvanoosterhout@raspberrypi:~ $ docker exec -it ebusd /bin/bash
root@d1621ca6df7f:/# ebusctl find
Excellent400 ActualExhaustfanSpeed = no data stored
...
skiped for convinience
...
Excellent400 SelectionInput2 = no data stored
Excellent400 SoftwareVersion = S1.08.05 0004 
Excellent400 SupplyFanModeSwInput1 = no data stored
...
skiped for convinience
...
Excellent400 TotalFlow = no data stored
scan id = no data stored
scan SoftwareVersion = no data stored
scan.7c  = ENCON;  ;-;-