search

john30 / ebusd

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

Adapter v3 cannot recognize vaillant heater #507

Closed nklebedev closed 2 years ago

nklebedev commented 2 years ago

I'm trying to connect adapter v3 with Vaillant heater (the only device on eBUS) with no success. I'm using official adapter with wemos D1 mini and pretty sure that the hardware (jumpers, wires) is set correctly.

The content of the debug log (with raw data) is always like this:

2022-01-23 18:30:13.734 [main notice] ebusd 21.3.v21.3-130-g13221e2 started with auto scan on enhanced device 10.64.100.12:9999
2022-01-23 18:30:13.734 [main info] loading configuration files from http://cfg.ebusd.eu/
...
2022-01-23 18:30:15.172 [bus notice] device status: resetting
2022-01-23 18:30:15.173 [bus notice] bus started with own address 31/36
2022-01-23 18:30:15.173 [main info] registering data handlers
2022-01-23 18:30:15.173 [main info] registered data handlers
2022-01-23 18:30:15.354 [bus notice] <aa
2022-01-23 18:30:15.354 [bus debug] ERR: SYN received during no signal, switching to ready
2022-01-23 18:30:15.354 [bus notice] signal acquired
2022-01-23 18:30:15.354 [bus notice] <aa
2022-01-23 18:30:15.374 [bus notice] <aa
...
2022-01-23 18:30:16.163 [bus notice] <aa
2022-01-23 18:30:16.180 [bus notice] device status: reset, supports info
2022-01-23 18:30:16.180 [bus notice] <aa
...
2022-01-23 18:30:40.266 [bus notice] <aa
2022-01-23 18:30:40.304 [bus notice] <aa
2022-01-23 18:30:40.321 [bus notice] <00
2022-01-23 18:30:40.321 [bus notice] <08
2022-01-23 18:30:40.335 [bus notice] <b5
2022-01-23 18:30:40.335 [bus notice] <09
2022-01-23 18:30:40.335 [bus notice] <02
2022-01-23 18:30:40.374 [bus notice] <28
2022-01-23 18:30:40.374 [bus notice] <02
2022-01-23 18:30:40.374 [bus notice] <8e
2022-01-23 18:30:40.375 [bus notice] new master 00, master count 2
2022-01-23 18:30:40.661 [bus debug] ERR: read timeout during receive command ACK, switching to skip
2022-01-23 18:30:40.946 [bus notice] <aa
...
2022-01-23 18:30:41.062 [bus notice] <aa
2022-01-23 18:30:41.063 [bus notice] <00
2022-01-23 18:30:41.069 [bus notice] <08
2022-01-23 18:30:41.080 [bus notice] <b5
2022-01-23 18:30:41.080 [bus notice] <09
2022-01-23 18:30:41.080 [bus notice] <02
2022-01-23 18:30:41.135 [bus notice] <28
2022-01-23 18:30:41.135 [bus notice] <02
2022-01-23 18:30:41.135 [bus notice] <8e
2022-01-23 18:30:41.413 [bus debug] ERR: read timeout during receive command ACK, switching to skip
2022-01-23 18:30:41.664 [bus notice] <aa
2022-01-23 18:30:41.664 [bus notice] <aa
...
2022-01-23 18:30:45.156 [bus notice] <aa
2022-01-23 18:30:45.198 [main debug] performing regular tasks
2022-01-23 18:30:45.198 [bus info] scan 05 cmd: 3105070400
2022-01-23 18:30:45.198 [bus notice] <aa
2022-01-23 18:30:45.198 [bus debug] start request 31
2022-01-23 18:30:45.198 [bus debug] arbitration start with 31
2022-01-23 18:30:45.241 [bus notice] <aa
2022-01-23 18:30:45.273 [bus notice] <aa
2022-01-23 18:30:45.282 [bus notice] >31
2022-01-23 18:30:45.282 [bus notice] <31
2022-01-23 18:30:45.282 [bus debug] arbitration won
2022-01-23 18:30:45.282 [bus debug] arbitration delay 4 micros
2022-01-23 18:30:45.282 [bus info] arbitration delay 4 - 4 micros
2022-01-23 18:30:45.282 [bus debug] switching from ready to send command
2022-01-23 18:30:45.282 [bus notice] >05
2022-01-23 18:30:45.335 [bus notice] <aa
2022-01-23 18:30:45.335 [bus debug] notify request: ERR: SYN received
2022-01-23 18:30:45.335 [bus debug] ERR: SYN received during send command, switching to ready
2022-01-23 18:30:45.335 [main error] scan config 05: ERR: SYN received
2022-01-23 18:30:45.354 [bus notice] <05
2022-01-23 18:30:45.400 [bus notice] <aa
2022-01-23 18:30:45.400 [bus debug] ERR: SYN received during receive command, switching to ready
2022-01-23 18:30:45.436 [bus notice] <aa
2022-01-23 18:30:45.473 [bus notice] <aa
2022-01-23 18:30:45.533 [bus notice] <aa
2022-01-23 18:30:45.574 [bus notice] <aa

It shows scan attempts that always end with "ERR: SYN received".

john30 commented 2 years ago

is the behaviour the same when using usb instead of wifi?

nklebedev commented 2 years ago

I've made an experiment with USB today and result is actually quite different! Heater was successfully detected as Vaillant;BAI00;0108;7503.

all wifi attempts to scan 08 look like:

...
2022-01-27 19:30:44.259 [bus info] scan 08 cmd: 3108070400
2022-01-27 19:30:44.294 [bus notice] <aa
2022-01-27 19:30:44.294 [bus debug] start request 31
2022-01-27 19:30:44.294 [bus debug] arbitration start with 31
2022-01-27 19:30:44.336 [bus notice] <aa
2022-01-27 19:30:44.383 [bus notice] <aa
2022-01-27 19:30:44.390 [bus notice] >31
2022-01-27 19:30:44.390 [bus notice] <31
2022-01-27 19:30:44.390 [bus debug] arbitration won
2022-01-27 19:30:44.390 [bus debug] arbitration delay 6 micros
2022-01-27 19:30:44.390 [bus debug] switching from ready to send command
2022-01-27 19:30:44.390 [bus notice] >08
2022-01-27 19:30:44.434 [bus notice] <aa
2022-01-27 19:30:44.434 [bus debug] notify request: ERR: SYN received
2022-01-27 19:30:44.434 [bus debug] ERR: SYN received during send command, switching to ready
2022-01-27 19:30:44.434 [bus notice] <08
2022-01-27 19:30:44.434 [main error] scan config 08: ERR: SYN received
2022-01-27 19:30:44.474 [bus notice] <aa
2022-01-27 19:30:44.474 [bus debug] ERR: SYN received during receive command, switching to ready
2022-01-27 19:30:44.516 [bus notice] <aa
2022-01-27 19:30:44.554 [bus notice] <aa
2022-01-27 19:30:44.614 [bus notice] <aa
...

and USB:

...
2022-01-27 08:45:22.424 [bus info] scan 08 cmd: 3108070400
2022-01-27 08:45:22.447 [bus notice] <aa
2022-01-27 08:45:22.449 [bus debug] start request 31
2022-01-27 08:45:22.449 [bus debug] arbitration start with 31
2022-01-27 08:45:22.490 [bus notice] <aa
2022-01-27 08:45:22.498 [bus notice] >31
2022-01-27 08:45:22.498 [bus notice] <31
2022-01-27 08:45:22.498 [bus debug] arbitration won
2022-01-27 08:45:22.498 [bus debug] arbitration delay 3691 micros
2022-01-27 08:45:22.498 [bus info] arbitration delay 3691 - 4435 micros
2022-01-27 08:45:22.498 [bus debug] switching from ready to send command
2022-01-27 08:45:22.506 [bus notice] >08
2022-01-27 08:45:22.521 [bus notice] <08
2022-01-27 08:45:22.521 [bus debug] send/receive symbol latency 15 ms
2022-01-27 08:45:22.531 [bus notice] >07
2022-01-27 08:45:22.546 [bus notice] <07
2022-01-27 08:45:22.546 [bus debug] send/receive symbol latency 15 ms
2022-01-27 08:45:22.555 [bus notice] >04
2022-01-27 08:45:22.570 [bus notice] <04
2022-01-27 08:45:22.570 [bus debug] send/receive symbol latency 15 ms
2022-01-27 08:45:22.578 [bus notice] >00
2022-01-27 08:45:22.593 [bus notice] <00
2022-01-27 08:45:22.593 [bus debug] send/receive symbol latency 15 ms
2022-01-27 08:45:22.594 [bus debug] switching from send command to send command CRC
2022-01-27 08:45:22.601 [bus notice] >d1
2022-01-27 08:45:22.618 [bus notice] <d1
2022-01-27 08:45:22.618 [bus debug] send/receive symbol latency 16 ms
2022-01-27 08:45:22.618 [bus debug] switching from send command CRC to receive command ACK
2022-01-27 08:45:22.626 [bus notice] <00
2022-01-27 08:45:22.626 [bus debug] switching from receive command ACK to receive response
2022-01-27 08:45:22.631 [bus notice] <0a
2022-01-27 08:45:22.637 [bus notice] <b5
2022-01-27 08:45:22.642 [bus notice] <42
2022-01-27 08:45:22.646 [bus notice] <41
2022-01-27 08:45:22.651 [bus notice] <49
2022-01-27 08:45:22.655 [bus notice] <30
2022-01-27 08:45:22.659 [bus notice] <30
2022-01-27 08:45:22.663 [bus notice] <01
2022-01-27 08:45:22.667 [bus notice] <08
2022-01-27 08:45:22.671 [bus notice] <75
2022-01-27 08:45:22.679 [bus notice] <03
2022-01-27 08:45:22.679 [bus debug] switching from receive response to receive response CRC
2022-01-27 08:45:22.688 [bus notice] <ae
2022-01-27 08:45:22.688 [bus debug] switching from receive response CRC to send response ACK
2022-01-27 08:45:22.696 [bus notice] >00
2022-01-27 08:45:22.711 [bus notice] <00
2022-01-27 08:45:22.711 [bus debug] send/receive symbol latency 14 ms
2022-01-27 08:45:22.711 [bus info] send/receive symbol latency 14 - 16 ms
2022-01-27 08:45:22.711 [update info] sent MS cmd: 3108070400 / 0ab5424149303001087503
...

It is noteworthy that USB attempts have an arbitration delay of several thousand microseconds, unlike wifi, where delays are several microseconds.

john30 commented 2 years ago

please post ebusd-esp configuration and cmdline with which ebusd is started in both variants

nklebedev commented 2 years ago

hi, John, thank you for the response!

adapter configuration:

Max packet size: 256
Device ID: 30b0 (PIC16F15356)
Blocksize erase: 32
Blocksize write: 32
User ID 1: ff
User ID 2: ff
User ID 3: ff
User ID 4: ff
User ID:
0000: ff 3f ff 14 ff 3f ff 3f
Rev ID, Device ID:
0005: 02 20 b0 30
Device revision: 0.2
Configuration words:
0007: ec 3f ff 3f bf 3f f6 3c ff 3f
MUI:
0100: 22 01 94 31 01 51 43 10
0108: 40
EUI:
010a: ff 3f ff 3f ff 3f ff 3f ff 3f ff 3f ff 3f ff 3f
TSHR2: 585
FVRA2X: 2048
FVRC2X: 2050
Flash:
Bootloader version: 1 [0a6c]
Firmware version: 1 [554f]
MAC address: ae:b0:53:43:10:40
IP address: DHCP
Arbitration delay: 200 us

command line wifi: ebusd --scanconfig -d enh:10.64.100.12:9999 --lograwdata=bytes --loglevel=debug command line USB: ebusd --scanconfig -d enh:/dev/ttyUSB0 --lograwdata=bytes --loglevel=debug

nklebedev commented 2 years ago

image

image

image

nklebedev commented 2 years ago

I did some more experiments this weekend and the problem seems to became clearer.

Actually I have the following scheme:

image

ebusd and adapter are located on the same network but separated by a VPN tunnel. There is a ping delay around 100-150 milliseconds between them.

If I place ebusd and adapter on the same physical network, the extra SYN is gone and everything works much better:

2022-01-27 19:30:44.390 [bus notice] >31
2022-01-27 19:30:44.390 [bus notice] <31
2022-01-27 19:30:44.390 [bus debug] arbitration won
2022-01-27 19:30:44.390 [bus debug] arbitration delay 6 micros
2022-01-27 19:30:44.390 [bus debug] switching from ready to send command
2022-01-27 19:30:44.390 [bus notice] >08
2022-01-27 19:30:44.434 [bus notice] <aa     <---------------------------- this out of order SYN is gone
2022-01-27 19:30:44.434 [bus debug] notify request: ERR: SYN received
john30 commented 2 years ago

you can't run ebus traffic with 100ms latency as this violates the protocol. think about placing a raspberry or something else running ebusd in the net where the ebus is