search

john30 / ebusd

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

'unknown command' errors + 'nothing' from ebus process. ebusctl scan hangs. #422

Closed netweaver1970 closed 3 years ago

netweaver1970 commented 3 years ago

When I plug in the the power for the EBUSD V3, using the Wemos D1 mini shield AND connected to the ebus (with Bulex MIGO Wifi thermostat + Bulex ThemaCondens 30/35 heater also on the bus), The EBUSD V3 + Wemos D1 mini are 30cm aways from the router, 100% wifi strenght, -36 dBm. So that can't be the issue ...

Free heap is always >33000

When replugging with a running ebusd on the Raspi, I'm getting this log on screen:

2021-04-23 15:35:01.859 [bus notice] device invalid 2021-04-23 15:35:01.859 [main error] scan config 15: ERR: no signal 2021-04-23 15:35:06.919 [bus notice] device status: resetting 2021-04-23 15:35:06.919 [bus notice] re-opened 192.168.0.128:9999 2021-04-23 15:35:06.919 [bus error] device status: unexpected available enhanced byte 2 2021-04-23 15:35:06.938 [bus notice] signal acquired 2021-04-23 15:35:07.716 [bus notice] device status: reset 2021-04-23 15:35:07.983 [update notice] received unknown MS cmd: 1008b503020001 / 0affffffffffffffffffff 2021-04-23 15:35:08.263 [update notice] received unknown MS cmd: 1008b503020002 / 0affffffffffffffffffff 2021-04-23 15:35:08.496 [update notice] received unknown MS cmd: 1008b503020003 / 00 2021-04-23 15:35:08.735 [update notice] received unknown MS cmd: 1008b503020004 / 00 2021-04-23 15:35:09.004 [update notice] received unknown MS cmd: 1008b5110101 / 09312f0080ffff0000ff 2021-04-23 15:35:09.278 [update notice] received unknown MS cmd: 1008b510090000006effff05ff00 / 0101 2021-04-23 15:35:18.074 [update notice] received unknown MS cmd: 1008b503020001 / 0affffffffffffffffffff 2021-04-23 15:35:18.353 [update notice] received unknown MS cmd: 1008b503020002 / 0affffffffffffffffffff 2021-04-23 15:35:18.590 [update notice] received unknown MS cmd: 1008b503020003 / 00 2021-04-23 15:35:18.826 [update notice] received unknown MS cmd: 1008b503020004 / 00 2021-04-23 15:35:19.094 [update notice] received unknown MS cmd: 1008b5110101 / 09312f0080ffff0000ff 2021-04-23 15:35:19.369 [update notice] received unknown MS cmd: 1008b510090000006effff05ff00 / 0101 2021-04-23 15:35:28.175 [update notice] received unknown MS cmd: 1008b503020001 / 0affffffffffffffffffff 2021-04-23 15:35:28.452 [update notice] received unknown MS cmd: 1008b503020002 / 0affffffffffffffffffff 2021-04-23 15:35:28.689 [update notice] received unknown MS cmd: 1008b503020003 / 00 2021-04-23 15:35:28.929 [update notice] received unknown MS cmd: 1008b503020004 / 00 2021-04-23 15:35:29.199 [update notice] received unknown MS cmd: 1008b5110101 / 09312f0080ffff0000ff 2021-04-23 15:35:29.471 [update notice] received unknown MS cmd: 1008b510090000006effff05ff00 / 0101 2021-04-23 15:35:30.545 [update notice] received unknown MS cmd: 1008b5110102 / 050014964c6e

And then the 7 lines repeat, over and over again.

When stopping the EBUSD process, and restarting with debug logging, I'm not getting the update messages anymore? 2021-04-23 15:54:01.440 [main info] read config files 2021-04-23 15:54:01.469 [bus notice] bus started with own address 31/36 2021-04-23 15:54:01.470 [main info] registering data handlers 2021-04-23 15:54:01.470 [mqtt info] mosquitto version 1.5.7 (compiled with 1.5.7) 2021-04-23 15:54:01.478 [mqtt debug] connection requested 2021-04-23 15:54:01.478 [main info] registered data handlers 2021-04-23 15:54:02.055 [mqtt notice] connection established 2021-04-23 15:54:02.055 [mqtt debug] publish ebusd/global/version "ebusd 21.2.v21.2" 2021-04-23 15:54:02.056 [mqtt debug] publish ebusd/global/running true 2021-04-23 15:54:11.479 [main debug] performing regular tasks 2021-04-23 15:54:11.479 [mqtt debug] publish ebusd/global/scan "finished" 2021-04-23 15:54:17.580 [mqtt debug] publish ebusd/global/uptime 16 2021-04-23 15:54:21.479 [main debug] performing regular tasks 2021-04-23 15:54:31.480 [main debug] performing regular tasks 2021-04-23 15:54:33.785 [mqtt debug] publish ebusd/global/uptime 32 2021-04-23 15:54:41.480 [main debug] performing regular tasks 2021-04-23 15:54:49.803 [mqtt debug] publish ebusd/global/uptime 48 2021-04-23 15:54:51.481 [main debug] performing regular tasks 2021-04-23 15:55:01.481 [main debug] performing regular tasks 2021-04-23 15:55:05.821 [mqtt debug] publish ebusd/global/uptime 64 2021-04-23 15:55:11.481 [main debug] performing regular tasks 2021-04-23 15:55:21.482 [main debug] performing regular tasks 2021-04-23 15:55:21.840 [mqtt debug] publish ebusd/global/uptime 80 2021-04-23 15:55:31.482 [main debug] performing regular tasks 2021-04-23 15:55:37.859 [mqtt debug] publish ebusd/global/uptime 96 2021-04-23 15:55:41.483 [main debug] performing regular tasks 2021-04-23 15:55:51.483 [main debug] performing regular tasks 2021-04-23 15:55:53.877 [mqtt debug] publish ebusd/global/uptime 112 2021-04-23 15:56:01.484 [main debug] performing regular tasks 2021-04-23 15:56:09.896 [mqtt debug] publish ebusd/global/uptime 128 2021-04-23 15:56:11.484 [main debug] performing regular tasks 2021-04-23 15:56:11.564 [main notice] update check: OK 2021-04-23 15:56:11.564 [mqtt debug] publish ebusd/global/updatecheck "OK"

and 'ebuctl info' give me this: pi@IOTstack:~ $ ebusctl info version: ebusd 21.2.v21.2 update check: OK signal: no signal reconnects: 5 masters: 3 messages: 13 conditional: 0 poll: 0 update: 4 address 03: master #11 address 08: slave #11 address 10: master #2 address 31: master #8, ebusd address 36: slave #8, ebusd

This was my commandline : ebusd -f --scanconfig --mqttport=1883 --mqtthost=192.168.0.11 --mqttuser=????? -d enh:192.168.0.128:9999 --mqttpass=????? --mqttjson --mqtttopic=ebusd/%circuit/%name --latency=20000

when doing a 'ebusctl scan' it just hangs, no output.

The Wemos web config page still states ebusd connected: yes (inactive). eBUS signal: aquired

Any idea?

Thanks.

netweaver1970 commented 3 years ago

some extra info (maybe) with debug logging (and also more readable than the above ones...

2021-04-23 19:18:02.077 [main info] loading configuration files from http://ebusd.eu/config/ 2021-04-23 19:18:02.161 [main info] reading templates / 2021-04-23 19:18:02.284 [main info] read templates in / 2021-04-23 19:18:02.284 [main info] reading file memory.csv 2021-04-23 19:18:02.369 [main info] successfully read file memory.csv 2021-04-23 19:18:02.369 [main info] reading file broadcast.csv 2021-04-23 19:18:02.447 [main info] successfully read file broadcast.csv 2021-04-23 19:18:02.447 [main info] read config files 2021-04-23 19:18:02.537 [bus notice] bus started with own address 31/36 2021-04-23 19:18:02.538 [main info] registering data handlers 2021-04-23 19:18:02.538 [mqtt info] mosquitto version 1.5.7 (compiled with 1.5.7) 2021-04-23 19:18:02.546 [mqtt debug] connection requested 2021-04-23 19:18:02.546 [main info] registered data handlers 2021-04-23 19:18:02.568 [bus debug] ERR: SYN received during no signal, switching to ready 2021-04-23 19:18:02.568 [bus notice] signal acquired 2021-04-23 19:18:03.057 [mqtt notice] connection established 2021-04-23 19:18:03.057 [mqtt debug] publish ebusd/global/version "ebusd 21.2.v21.2" 2021-04-23 19:18:03.058 [mqtt debug] publish ebusd/global/running true 2021-04-23 19:18:04.691 [bus notice] new master 10, master count 2 2021-04-23 19:18:04.765 [bus notice] new master 03, master count 3 2021-04-23 19:18:04.766 [update info] received MS cmd: 1008b503020001 / 0affffffffffffffffffff 2021-04-23 19:18:04.766 [update notice] received unknown MS cmd: 1008b503020001 / 0affffffffffffffffffff 2021-04-23 19:18:05.035 [update info] received MS cmd: 1008b503020002 / 0affffffffffffffffffff 2021-04-23 19:18:05.035 [update notice] received unknown MS cmd: 1008b503020002 / 0affffffffffffffffffff 2021-04-23 19:18:05.272 [update info] received MS cmd: 1008b503020003 / 00 2021-04-23 19:18:05.272 [update notice] received unknown MS cmd: 1008b503020003 / 00 2021-04-23 19:18:05.507 [update info] received MS cmd: 1008b503020004 / 00 2021-04-23 19:18:05.508 [update notice] received unknown MS cmd: 1008b503020004 / 00 2021-04-23 19:18:05.781 [update info] received MS cmd: 1008b5110101 / 0957540080ffff0000ff 2021-04-23 19:18:05.781 [update notice] received unknown MS cmd: 1008b5110101 / 0957540080ffff0000ff 2021-04-23 19:18:06.911 [update info] received MS cmd: 1008b510090000006effff05ff00 / 0101 2021-04-23 19:18:06.911 [update notice] received unknown MS cmd: 1008b510090000006effff05ff00 / 0101 2021-04-23 19:18:12.547 [main debug] performing regular tasks 2021-04-23 19:18:12.548 [bus info] scan 08 cmd: 3108070400 2021-04-23 19:18:12.558 [bus debug] start request 31 2021-04-23 19:18:12.558 [bus debug] arbitration start with 31 2021-04-23 19:18:14.810 [update info] received MS cmd: 1008b503020001 / 0affffffffffffffffffff 2021-04-23 19:18:14.811 [update notice] received unknown MS cmd: 1008b503020001 / 0affffffffffffffffffff 2021-04-23 19:18:15.090 [update info] received MS cmd: 1008b503020002 / 0affffffffffffffffffff 2021-04-23 19:18:15.090 [update notice] received unknown MS cmd: 1008b503020002 / 0affffffffffffffffffff 2021-04-23 19:18:15.327 [update info] received MS cmd: 1008b503020003 / 00 2021-04-23 19:18:15.327 [update notice] received unknown MS cmd: 1008b503020003 / 00 2021-04-23 19:18:15.562 [update info] received MS cmd: 1008b503020004 / 00 2021-04-23 19:18:15.563 [update notice] received unknown MS cmd: 1008b503020004 / 00 2021-04-23 19:18:15.831 [update info] received MS cmd: 1008b5110101 / 0957540080ffff0000ff 2021-04-23 19:18:15.831 [update notice] received unknown MS cmd: 1008b5110101 / 0957540080ffff0000ff 2021-04-23 19:18:16.966 [update info] received MS cmd: 1008b510090000006effff05ff00 / 0101 2021-04-23 19:18:16.966 [update notice] received unknown MS cmd: 1008b510090000006effff05ff00 / 0101 2021-04-23 19:18:18.236 [mqtt debug] publish ebusd/global/uptime 16 2021-04-23 19:18:18.236 [mqtt debug] publish ebusd/global/signal true 2021-04-23 19:18:23.078 [update info] received MS cmd: 1008b5110102 / 050014964c6e 2021-04-23 19:18:23.078 [update notice] received unknown MS cmd: 1008b5110102 / 050014964c6e 2021-04-23 19:18:24.907 [update info] received MS cmd: 1008b503020001 / 0affffffffffffffffffff 2021-04-23 19:18:24.907 [update notice] received unknown MS cmd: 1008b503020001 / 0affffffffffffffffffff 2021-04-23 19:18:25.184 [update info] received MS cmd: 1008b503020002 / 0affffffffffffffffffff 2021-04-23 19:18:25.184 [update notice] received unknown MS cmd: 1008b503020002 / 0affffffffffffffffffff 2021-04-23 19:18:25.422 [update info] received MS cmd: 1008b503020003 / 00 2021-04-23 19:18:25.422 [update notice] received unknown MS cmd: 1008b503020003 / 00 2021-04-23 19:18:25.658 [update info] received MS cmd: 1008b503020004 / 00 2021-04-23 19:18:25.658 [update notice] received unknown MS cmd: 1008b503020004 / 00 2021-04-23 19:18:25.926 [update info] received MS cmd: 1008b5110101 / 0958520080ffff0000ff 2021-04-23 19:18:25.926 [update notice] received unknown MS cmd: 1008b5110101 / 0958520080ffff0000ff 2021-04-23 19:18:27.057 [update info] received MS cmd: 1008b510090000006effff05ff00 / 0101 2021-04-23 19:18:27.058 [update notice] received unknown MS cmd: 1008b510090000006effff05ff00 / 0101 2021-04-23 19:18:34.349 [mqtt debug] publish ebusd/global/uptime 32 2021-04-23 19:18:34.996 [update info] received MS cmd: 1008b503020001 / 0affffffffffffffffffff 2021-04-23 19:18:34.996 [update notice] received unknown MS cmd: 1008b503020001 / 0affffffffffffffffffff 2021-04-23 19:18:35.276 [update info] received MS cmd: 1008b503020002 / 0affffffffffffffffffff 2021-04-23 19:18:35.276 [update notice] received unknown MS cmd: 1008b503020002 / 0affffffffffffffffffff 2021-04-23 19:18:35.513 [update info] received MS cmd: 1008b503020003 / 00 2021-04-23 19:18:35.513 [update notice] received unknown MS cmd: 1008b503020003 / 00 2021-04-23 19:18:35.748 [update info] received MS cmd: 1008b503020004 / 00 2021-04-23 19:18:35.748 [update notice] received unknown MS cmd: 1008b503020004 / 00 2021-04-23 19:18:36.017 [update info] received MS cmd: 1008b5110101 / 0953510080ffff0000ff 2021-04-23 19:18:36.017 [update notice] received unknown MS cmd: 1008b5110101 / 0953510080ffff0000ff 2021-04-23 19:18:37.108 [update info] received MS cmd: 1008b510090000006effff05ff00 / 0101 2021-04-23 19:18:37.108 [update notice] received unknown MS cmd: 1008b510090000006effff05ff00 / 0101 2021-04-23 19:18:41.833 [bus debug] ERR: read timeout during receive command ACK, switching to skip 2021-04-23 19:18:43.920 [bus debug] ERR: read timeout during receive command ACK, switching to skip 2021-04-23 19:18:45.007 [update info] received MS cmd: 1008b503020001 / 0affffffffffffffffffff 2021-04-23 19:18:45.008 [update notice] received unknown MS cmd: 1008b503020001 / 0affffffffffffffffffff 2021-04-23 19:18:45.286 [update info] received MS cmd: 1008b503020002 / 0affffffffffffffffffff 2021-04-23 19:18:45.286 [update notice] received unknown MS cmd: 1008b503020002 / 0affffffffffffffffffff 2021-04-23 19:18:45.524 [update info] received MS cmd: 1008b503020003 / 00 2021-04-23 19:18:45.524 [update notice] received unknown MS cmd: 1008b503020003 / 00 2021-04-23 19:18:45.759 [update info] received MS cmd: 1008b503020004 / 00 2021-04-23 19:18:45.759 [update notice] received unknown MS cmd: 1008b503020004 / 00 2021-04-23 19:18:46.003 [bus debug] ERR: read timeout during receive command ACK, switching to skip

and so on and on ...

netweaver1970 commented 3 years ago

mmmm, I do see a kind of start of scan (version of ebusd is newer so the logging was slightly different compared to the previous issue) but alas no progress :

2021-04-26 15:46:05.751 [update notice] received unknown MS cmd: 1008b510090000526effff04ff00 / 0101 2021-04-26 15:46:08.570 [main debug] performing regular tasks 2021-04-26 15:46:08.571 [bus info] scan 08 cmd: 3108070400 2021-04-26 15:46:08.601 [bus debug] start request 31 2021-04-26 15:46:08.602 [bus debug] arbitration start with 31 2021-04-26 15:46:12.877 [update info] received MS cmd: 1008b503020001 / 0affffffffffffffffffff

so it seems 31 (the V3 adapter) is indeed trying to scan something. But no response received. And also no error messages received, and after about 5 minutes there are time-out messages seen. I'm starting to understand this a bit more.

Still stuck on trying to figure out where the issue might be.

netweaver1970 commented 3 years ago

fixed! At least 1 (if not all the way) step further.

That TX line made me think, so I traced the TX line from the Wemos pins to the PIC on the schematic. It seems my jumper J1 was at the wrong position. Changed it to RPI position and the scan started to work:

version: ebusd 21.2.v21.2-28-gc8a4ad5
update check: revision v21.2 available
signal: acquired
symbol rate: 64
max symbol rate: 110
min arbitration micros: 17
max arbitration micros: 116
min symbol latency: 8
max symbol latency: 31
reconnects: 1
masters: 3
messages: 13
conditional: 0
poll: 0
update: 4
address 03: master #11
address 08: slave #11, scanned "MF=Vaillant;ID=BAI00;SW=0602;HW=3302"
address 10: master #2
address 15: slave #2, scanned "MF=Vaillant;ID=SCC00;SW=2200;HW=3903"
address 31: master #8, ebusd
address 36: slave #8, ebusd

More activity going on now in the log, but still missing definitions:


2021-04-26 18:29:40.596 [bus notice] scan 15: ;Vaillant;SCC00;2200;3903
2021-04-26 18:29:40.596 [update notice] store 15 ident: done
2021-04-26 18:29:40.596 [update notice] sent scan-read scan.15  QQ=31: Vaillant;SCC00;2200;3903
2021-04-26 18:29:40.596 [bus notice] scan 15: ;Vaillant;SCC00;2200;3903
2021-04-26 18:29:40.776 [update notice] sent unknown MS cmd: 3115b5090124 / 09003231313532393030
2021-04-26 18:29:40.959 [update notice] sent scan-read scan.15 id QQ=31:
2021-04-26 18:29:41.144 [update notice] sent scan-read scan.15 id QQ=31:
2021-04-26 18:29:41.334 [update notice] sent scan-read scan.15 id QQ=31: 21;15;29;0020197230;0932;005203;N0
2021-04-26 18:29:41.334 [bus notice] scan 15: ;21;15;29;0020197230;0932;005203;N0
2021-04-26 18:29:41.455 [main error] unable to load scan config 15: no file from vaillant with prefix 15 matches ID "scc00", SW2200, HW3903
2021-04-26 18:29:41.455 [main error] scan config 15: ERR: element not found
2021-04-26 18:29:43.384 [update notice] received read bai currenterror QQ=10: -;-;-;-;-
2021-04-26 18:29:43.663 [update notice] received unknown MS cmd: 1008b503020002 / 0affffffffffffffffffff
2021-04-26 18:29:43.900 [update notice] received unknown MS cmd: 1008b503020003 / 00
2021-04-26 18:29:44.136 [update notice] received unknown MS cmd: 1008b503020004 / 00
2021-04-26 18:29:44.405 [update notice] received read bai Status01 QQ=10: 45.5;45.0;-;-;-;off
2021-04-26 18:29:45.562 [update notice] received update-write bai SetMode QQ=10: auto;0.0;55.0;-;1;0;1;0;0;0
2021-04-26 18:29:53.440 [update notice] received read bai currenterror QQ=10: -;-;-;-;-
2021-04-26 18:29:53.718 [update notice] received unknown MS cmd: 1008b503020002 / 0affffffffffffffffffff
2021-04-26 18:29:53.956 [update notice] received unknown MS cmd: 1008b503020003 / 00
2021-04-26 18:29:54.203 [update notice] received unknown MS cmd: 1008b503020004 / 00
2021-04-26 18:29:54.492 [update notice] received read bai Status01 QQ=10: `45.5;45.0;-;-;-;off```

Any idea what I might be missing? Could it be the Migo (rebranded Netatmo) internet thermostat? If so, than I don't care :)

I do seem to get lots of BAI (heater related) values in from the heater using MQTT, so now I only need to figure out which are which and how to set them :)
netweaver1970 commented 3 years ago

closing issue.