Closed rabbit83ka closed 1 month ago
Missing full config
Added full config
Es gibt also zwei Heidelberg am Bus, keine weiteren Geräte. Kannst Du raus finden, ab welchem Nightly das passiert? Alternativ: könntest Du info@evcc.io Remotezugang (zum Raspi?) geben damit wir ein git bisect
durchführen können?
I experienced the same bug with Heidelberg. I am using a NUC installation HA with evcc as adon
"me too" does not give us more insights. https://github.com/evcc-io/evcc/issues/16866#issuecomment-2439552582 would.
When upgrading from 0.130.13 to 0.131.0 or 1,
That's the diff: https://github.com/evcc-io/evcc/compare/0.130.13...0.131.0. We've twice upgraded the modbus library here after intense local testing.
@premultiply in https://github.com/evcc-io/modbus/commit/c89f591d8ae8855156602bc3d150484ca31916c7 we're setting the deadline after receiving the first character. For debugging, we could output the sofar- received characters to see where that goes wrong?
Ich teste heute Abend mal die Nightlies durch. Sind zwei Geräte, habe auch schon eins aus der Config genommen, Fehler trat trotzdem auf.
Könnte ich Dir mal ein Binary mit mehr Logging bauen? Für welche Plattform? Meld Dich bitte mal bei info@evcc.io.
Gerne, Mail ist raus.
Log des bereitgestellten Binary:
sudo ./evcc charger -l trace
[main ] INFO 2024/10/26 18:00:46 evcc 0.131.1 (959921856)
[main ] INFO 2024/10/26 18:00:46 using config file: /etc/evcc.yaml
[db ] INFO 2024/10/26 18:00:46 using sqlite database: /var/lib/evcc/evcc.db
[db ] TRACE 2024/10/26 18:00:46 SELECT count(*) FROM sqlite_master WHERE type='table' AND name="settings" -1 <nil>
[db ] TRACE 2024/10/26 18:00:46 SELECT sql FROM sqlite_master WHERE type IN ("table","index") AND tbl_name = "settings" AND sql IS NOT NULL order by type = "table" desc 1 <nil>
[db ] TRACE 2024/10/26 18:00:46 SELECT * FROM `settings` LIMIT 1 -1 <nil>
[db ] TRACE 2024/10/26 18:00:46 SELECT * FROM `settings` 52 <nil>
[db ] TRACE 2024/10/26 18:00:47 SELECT count(*) FROM sqlite_master WHERE type='table' AND name="devices" -1 <nil>
[db ] TRACE 2024/10/26 18:00:47 SELECT count(*) FROM sqlite_master WHERE type='table' AND name="device_details" -1 <nil>
[db ] TRACE 2024/10/26 18:00:47 SELECT count(*) FROM sqlite_master WHERE type='table' AND name="configs" -1 <nil>
[db ] TRACE 2024/10/26 18:00:47 SELECT sql FROM sqlite_master WHERE type IN ("table","index") AND tbl_name = "configs" AND sql IS NOT NULL order by type = "table" desc 1 <nil>
[db ] TRACE 2024/10/26 18:00:47 SELECT * FROM `configs` LIMIT 1 -1 <nil>
[db ] TRACE 2024/10/26 18:00:47 SELECT count(*) FROM sqlite_master WHERE type='table' AND name="config_details" -1 <nil>
[db ] TRACE 2024/10/26 18:00:47 SELECT count(*) FROM sqlite_master WHERE type='table' AND name="config_details" -1 <nil>
[db ] TRACE 2024/10/26 18:00:47 SELECT * FROM `configs` WHERE `configs`.`class` = 1 0 <nil>
[tasmota] TRACE 2024/10/26 18:00:47 GET http://192.168.0.154/cm?cmnd=Status+0&password=&user=
[heidel] TRACE 2024/10/26 18:00:47 modbus: send 02 10 01 02 00 01 02 00 04 a2 41
[heidel] TRACE 2024/10/26 18:00:47 modbus: recv expected bytes: 8 taking 11.44ms
[heidel] TRACE 2024/10/26 18:00:47 modbus: recv
[tasmota] TRACE 2024/10/26 18:00:47 {"Status":{"Module":0,"DeviceName":"Lader_Roller","FriendlyName":["Tasmota"],"Topic":"tasmota_17CF1B","ButtonTopic":"0","Power":0,"PowerOnState":3,"LedState":1,"LedMask":"FFFF","SaveData":1,"SaveState":1,"SwitchTopic":"0","SwitchMode":[0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0],"ButtonRetain":0,"SwitchRetain":0,"SensorRetain":0,"PowerRetain":0,"InfoRetain":0,"StateRetain":0,"StatusRetain":0},"StatusPRM":{"Baudrate":115200,"SerialConfig":"8N1","GroupTopic":"tasmotas","OtaUrl":"http://ota.tasmota.com/tasmota/release/tasmota.bin.gz","RestartReason":"Power On","Uptime":"28T22:47:04","StartupUTC":"2024-09-27T17:13:43","Sleep":50,"CfgHolder":4617,"BootCount":19,"BCResetTime":"2024-07-30T17:49:39","SaveCount":297,"SaveAddress":"FB000"},"StatusFWR":{"Version":"13.0.0(tasmota)","BuildDateTime":"2023-06-26T10:42:07","Boot":31,"Core":"2_7_4_9","SDK":"2.2.2-dev(38a443e)","CpuFrequency":80,"Hardware":"ESP8266EX","CR":"388/699"},"StatusLOG":{"SerialLog":2,"WebLog":2,"MqttLog":0,"SysLog":0,"LogHost":"","LogPort":514,"SSId":["maedel_garten","maedel"],"TelePeriod":300,"Resolution":"558180C0","SetOption":["00008009","2805C80001000600003C5A0A192800000000","00000080","00006000","00004000","00000000"]},"StatusMEM":{"ProgramSize":634,"Free":368,"Heap":23,"ProgramFlashSize":1024,"FlashSize":1024,"FlashChipId":"1460C4","FlashFrequency":40,"FlashMode":"DOUT","Features":["00000809","8F9AC787","04368001","000000CF","010013C0","C000F981","00004004","00001000","54000020","00000080"],"Drivers":"1,2,3,4,5,6,7,8,9,10,12,16,18,19,20,21,22,24,26,27,29,30,35,37,45,62,68","Sensors":"1,2,3,4,5,6","I2CDriver":"7"},"StatusNET":{"Hostname":"tasmota-17CF1B-3867","IPAddress":"192.168.0.154","Gateway":"192.168.0.1","Subnetmask":"255.255.255.0","DNSServer1":"192.168.0.10","DNSServer2":"0.0.0.0","Mac":"48:55:19:17:CF:1B","Webserver":2,"HTTP_API":1,"WifiConfig":4,"WifiPower":17.0},"StatusMQT":{"MqttHost":"","MqttPort":1883,"MqttClientMask":"DVES_%06X","MqttClient":"DVES_17CF1B","MqttUser":"DVES_USER","MqttCount":0,"MAX_PACKET_SIZE":1200,"KEEPALIVE":30,"SOCKET_TIMEOUT":4},"StatusTIM":{"UTC":"2024-10-26T16:00:47","Local":"2024-10-26T17:00:47","StartDST":"2024-03-31T02:00:00","EndDST":"2024-10-27T03:00:00","Timezone":"+01:00","Sunrise":"07:28","Sunset":"17:39"},"StatusPTH":{"PowerDelta":[0,0,0],"PowerLow":0,"PowerHigh":0,"VoltageLow":0,"VoltageHigh":0,"CurrentLow":0,"CurrentHigh":0},"StatusSNS":{"Time":"2024-10-26T17:00:47","ENERGY":{"TotalStartTime":"2024-07-30T17:53:54","Total":37.659,"Yesterday":0.000,"Today":0.000,"Power":0,"ApparentPower":0,"ReactivePower":0,"Factor":0.00,"Voltage":0,"Current":0.000}},"StatusSTS":{"Time":"2024-10-26T17:00:47","Uptime":"28T22:47:04","UptimeSec":2501224,"Heap":23,"SleepMode":"Dynamic","Sleep":50,"LoadAvg":19,"MqttCount":0,"POWER":"OFF","Wifi":{"AP":1,"SSId":"maedel_garten","BSSId":"86:8B:09:99:E6:B7","Channel":11,"Mode":"11n","RSSI":86,"Signal":-57,"LinkCount":13,"Downtime":"0T00:01:10"}}}
[heidel] TRACE 2024/10/26 18:00:47 modbus: send 01 10 01 02 00 01 02 00 04 b6 b1
[heidel] TRACE 2024/10/26 18:00:47 modbus: recv expected bytes: 8 taking 11.44ms
[heidel] TRACE 2024/10/26 18:00:47 modbus: recv 01 10 01 02 00 01 a1 f5
[heidel] TRACE 2024/10/26 18:00:48 modbus: send 01 03 01 01 00 01 d4 36
[heidel] TRACE 2024/10/26 18:00:48 modbus: recv expected bytes: 7 taking 10.01ms
[heidel] TRACE 2024/10/26 18:00:48 modbus: recv
[main ] FATAL 2024/10/26 18:00:48 cannot create charger 'wallbox2': cannot create charger type 'template': cannot create charger type 'heidelberg': failed to read from serial port within deadline: 11.44ms, state: 16, since start: 21.166653ms, since first byte received: 16.372044ms, received: 02 10 01 02 00 01
ich habs mal lesbar formatiert, muss ich mir erst anschauen. Hier der spannende Teil:
recv expected bytes: 7 taking 10.01ms
failed to read... within deadline: 11.44ms, state: 16, since start: 21.166653ms, since first byte received: 16.372044ms, received: 02 10 01 02 00 01
Es fehlt also die Zeit fürs letzte Byte. Jetzt müssen wir nur heraus finden, warum das so ist!
/cc @premultiply
@JanDragon hättest Du nochmal das Log von der funktionierenden Version (bitte nur ein Charger)? Dann können wir nochmal schauen wir die Antwort aussehen muss und ob die Erwartung von 7 Antwortbytes überhaupt richtig ist. Ich glaube so langsam gar nichts mehr...
@JanDragon hättest Du nochmal das Log von der funktionierenden Version (bitte nur ein Charger)? Dann können wir nochmal schauen wir die Antwort aussehen muss und ob die Erwartung von 7 Antwortbytes überhaupt richtig ist. Ich glaube so langsam gar nichts mehr...
Moin, evtl. falsche Person? Kann leider nicht mit einer Heidelberg Wallbox dienen da ich nur Go-E Boxen bei mir installiert habe. Tut mir leid.
@JanDragon , er meinte mich. @andig , hier das log der 0.130.13:
wallbox2
--------
[heidel] TRACE 2024/10/26 18:42:39 modbus: send 02 04 00 0e 00 01 50 3a
[heidel] TRACE 2024/10/26 18:42:39 modbus: recv 02 04 02 00 00 fd 30
[heidel] TRACE 2024/10/26 18:42:39 modbus: send 02 04 00 11 00 02 21 fd
[heidel] TRACE 2024/10/26 18:42:39 modbus: recv 02 04 04 00 31 dd e9 01 95
[heidel] TRACE 2024/10/26 18:42:39 modbus: send 02 04 00 06 00 03 50 39
[heidel] TRACE 2024/10/26 18:42:39 modbus: recv 02 04 06 00 00 00 00 00 00 74 63
[heidel] TRACE 2024/10/26 18:42:39 modbus: send 02 04 00 0a 00 03 90 3a
[heidel] TRACE 2024/10/26 18:42:39 modbus: recv 02 04 06 00 ed 00 ee 00 ee 38 0d
[heidel] TRACE 2024/10/26 18:42:39 modbus: send 02 04 00 05 00 01 21 f8
[heidel] TRACE 2024/10/26 18:42:39 modbus: recv 02 04 02 00 02 7c f1
[heidel] TRACE 2024/10/26 18:42:39 modbus: send 02 03 01 05 00 01 95 c4
[heidel] TRACE 2024/10/26 18:42:39 modbus: recv 02 03 02 00 00 fc 44
Power: 0W
Energy: 3268.1kWh
Current L1..L3: 0A 0A 0A
Voltage L1..L3: 237V 238V 238V
Charge status: A
Enabled: false
wallbox
-------
[heidel] TRACE 2024/10/26 18:42:39 modbus: send 01 04 00 0e 00 01 50 09
[heidel] TRACE 2024/10/26 18:42:39 modbus: recv 01 04 02 00 00 b9 30
[heidel] TRACE 2024/10/26 18:42:39 modbus: send 01 04 00 11 00 02 21 ce
[heidel] TRACE 2024/10/26 18:42:39 modbus: recv 01 04 04 00 52 81 67 7b ef
[heidel] TRACE 2024/10/26 18:42:40 modbus: send 01 04 00 06 00 03 50 0a
[heidel] TRACE 2024/10/26 18:42:40 modbus: recv 01 04 06 00 00 00 00 00 00 60 93
[heidel] TRACE 2024/10/26 18:42:40 modbus: send 01 04 00 0a 00 03 90 09
[heidel] TRACE 2024/10/26 18:42:40 modbus: recv 01 04 06 00 ed 00 ee 00 ee 2c fd
[heidel] TRACE 2024/10/26 18:42:40 modbus: send 01 04 00 05 00 01 21 cb
[heidel] TRACE 2024/10/26 18:42:40 modbus: recv 01 04 02 00 02 38 f1
[heidel] TRACE 2024/10/26 18:42:40 modbus: send 01 03 01 05 00 01 95 f7
[heidel] TRACE 2024/10/26 18:42:40 modbus: recv 01 03 02 00 00 b8 44
Power: 0W
Energy: 5407.1kWh
Current L1..L3: 0A 0A 0A
Voltage L1..L3: 237V 238V 238V
Charge status: A
Enabled: false
Irgendwie sind die Abfragen anders. Mir fehlt die
modbus: send 01 03 01 01 00 01 d4 36
aber seis drum. 7 Antwortbytes scheinen zu stimmen. Bleibt die Frage, warum die Zeit dafür nicht reicht.
Hab die neue binary nochmal getestet, sieht ähnlich aus. Müsste das zweite Byte nicht 04 statt 10 sein? ModBus_register_table.pdf
[heidel] TRACE 2024/10/26 19:27:53 modbus: send 01 10 01 02 00 01 02 00 04 b6 b1
[heidel] TRACE 2024/10/26 19:27:53 modbus: recv expecting bytes: 8 taking 11.448ms
[heidel] TRACE 2024/10/26 19:27:53 modbus: recv 01 10 01 02 00 01 a1 f5
[heidel] TRACE 2024/10/26 19:27:53 modbus: send 01 03 01 01 00 01 d4 36
[heidel] TRACE 2024/10/26 19:27:53 modbus: recv expecting bytes: 7 taking 10.017ms
[heidel] TRACE 2024/10/26 19:27:53 modbus: recv
[heidel] TRACE 2024/10/26 19:27:53 modbus: send 02 10 01 02 00 01 02 00 04 a2 41
[heidel] TRACE 2024/10/26 19:27:53 modbus: recv expecting bytes: 8 taking 11.448ms
[heidel] TRACE 2024/10/26 19:27:53 modbus: recv 02 10 01 02 00 01 a1 c6
[heidel] TRACE 2024/10/26 19:27:53 modbus: send 02 03 01 01 00 01 d4 05
[heidel] TRACE 2024/10/26 19:27:53 modbus: recv expecting bytes: 7 taking 10.017ms
[heidel] TRACE 2024/10/26 19:27:53 modbus: recv 02 03 02 3a 98 ef 4e
[main ] FATAL 2024/10/26 19:27:53 cannot create charger 'wallbox': cannot create charger type 'template': cannot create charger type 'heidelberg': failsafe timeout: failed to read within deadline: state: 10017000, delay: 4, since start: 18.26625ms, since first byte received: 16.389855ms, received: 01 03 (2)
since first byte received: 16.389855ms
Heisst bei 7 Bytes von denen das letzte noch fehlt und das erste schon empfangen wurde bevor die Zählung beginnt ja 3,2ms je Zeichen (5 empfangen). Es dürften sein 1,43ms wenn ich den Standard richtig lese (https://modbus.org/docs/Modbus_over_serial_line_V1_02.pdf). Irgendwas ist also faul.
Entweder ist unsere serielle Implementierung jetzt falsch oder die Heidelberg hält sich nicht dran.
Waiting for @premultiply
Schrottzeichen-Binary:
[heidel] TRACE 2024/10/26 20:12:18 modbus: send 01 10 01 02 00 01 02 00 04 b6 b1
[heidel] TRACE 2024/10/26 20:12:18 modbus: recv expecting bytes: 8 taking 11.448ms
[heidel] TRACE 2024/10/26 20:12:18 modbus: recv
[heidel] TRACE 2024/10/26 20:12:19 modbus: send 02 10 01 02 00 01 02 00 04 a2 41
[heidel] TRACE 2024/10/26 20:12:19 modbus: recv expecting bytes: 8 taking 11.448ms
[heidel] TRACE 2024/10/26 20:12:19 modbus: recv 02 10 01 02 00 01 a1 c6
[heidel] TRACE 2024/10/26 20:12:19 modbus: send 02 03 01 01 00 01 d4 05
[heidel] TRACE 2024/10/26 20:12:19 modbus: recv expecting bytes: 7 taking 10.017ms
[heidel] TRACE 2024/10/26 20:12:19 modbus: recv
[main ] FATAL 2024/10/26 20:12:19 cannot create charger 'wallbox': cannot create charger type 'template': cannot create charger type 'heidelberg': failed to read within deadline: state: 8, delay: 11.448ms, since start: 20.312335ms, since first byte received: 16.374701ms, received: 01 10 01 02 00 (5)
Auch mit der Version von heute Vormittag noch ein timeout:
[heidel] TRACE 2024/10/27 11:34:57 modbus: recv expecting bytes: 8 taking 11.448ms
[heidel] TRACE 2024/10/27 11:34:57 modbus: recv 01 10 01 02 00 01 a1 f5
[heidel] TRACE 2024/10/27 11:34:57 modbus: send 01 03 01 01 00 01 d4 36
[heidel] TRACE 2024/10/27 11:34:57 modbus: recv expecting bytes: 7 taking 10.017ms
[heidel] TRACE 2024/10/27 11:34:57 modbus: recv 01 03 02 3a 98 ab 4e
[heidel] TRACE 2024/10/27 11:34:57 modbus: send 02 10 01 02 00 01 02 00 04 a2 41
[heidel] TRACE 2024/10/27 11:34:58 modbus: recv expecting bytes: 8 taking 11.448ms
[heidel] TRACE 2024/10/27 11:34:58 modbus: recv 02 10 01 02 00 01 a1 c6
[heidel] TRACE 2024/10/27 11:34:58 modbus: send 02 03 01 01 00 01 d4 05
[heidel] TRACE 2024/10/27 11:34:58 modbus: recv expecting bytes: 7 taking 10.017ms
[heidel] TRACE 2024/10/27 11:34:58 modbus: recv
[main ] FATAL 2024/10/27 11:34:58 cannot create charger 'wallbox2': cannot create charger type 'template': cannot create charger type 'heidelberg': failsafe timeout: failed to read within deadline: state: 8, delay: 10.017ms, since start: 13.837838ms, since first byte received: 13.823411ms, received: 02 03 02 3a (4)
Das neueste Binary evcc 0.131.1 (ce0872d0f)
sieht gut aus:
wallbox
-------
[heidel] TRACE 2024/10/27 13:03:28 modbus: send 01 04 00 0e 00 01 50 09
[heidel] TRACE 2024/10/27 13:03:29 modbus: recv 01 04 02 00 00 b9 30
[heidel] TRACE 2024/10/27 13:03:29 modbus: send 01 04 00 11 00 02 21 ce
[heidel] TRACE 2024/10/27 13:03:29 modbus: recv 01 04 04 00 52 81 67 7b ef
[heidel] TRACE 2024/10/27 13:03:29 modbus: send 01 04 00 06 00 03 50 0a
[heidel] TRACE 2024/10/27 13:03:29 modbus: recv 01 04 06 00 00 00 00 00 00 60 93
[heidel] TRACE 2024/10/27 13:03:29 modbus: send 01 04 00 0a 00 03 90 09
[heidel] TRACE 2024/10/27 13:03:29 modbus: recv 01 04 06 00 f1 00 f2 00 f0 bc f1
[heidel] TRACE 2024/10/27 13:03:29 modbus: send 01 04 00 05 00 01 21 cb
[heidel] TRACE 2024/10/27 13:03:29 modbus: recv 01 04 02 00 02 38 f1
[heidel] TRACE 2024/10/27 13:03:29 modbus: send 01 03 01 05 00 01 95 f7
[heidel] TRACE 2024/10/27 13:03:29 modbus: recv 01 03 02 00 00 b8 44
Power: 0W
Energy: 5407.1kWh
Current L1..L3: 0A 0A 0A
Voltage L1..L3: 241V 242V 240V
Charge status: A
Enabled: false
wallbox2
--------
[heidel] TRACE 2024/10/27 13:03:29 modbus: send 02 04 00 0e 00 01 50 3a
[heidel] TRACE 2024/10/27 13:03:29 modbus: recv 02 04 02 00 00 fd 30
[heidel] TRACE 2024/10/27 13:03:29 modbus: send 02 04 00 11 00 02 21 fd
[heidel] TRACE 2024/10/27 13:03:29 modbus: recv 02 04 04 00 31 dd e9 01 95
[heidel] TRACE 2024/10/27 13:03:30 modbus: send 02 04 00 06 00 03 50 39
[heidel] TRACE 2024/10/27 13:03:30 modbus: recv 02 04 06 00 00 00 00 00 00 74 63
[heidel] TRACE 2024/10/27 13:03:30 modbus: send 02 04 00 0a 00 03 90 3a
[heidel] TRACE 2024/10/27 13:03:30 modbus: recv 02 04 06 00 f1 00 f3 00 f0 f9 c1
[heidel] TRACE 2024/10/27 13:03:30 modbus: send 02 04 00 05 00 01 21 f8
[heidel] TRACE 2024/10/27 13:03:30 modbus: recv 02 04 02 00 02 7c f1
[heidel] TRACE 2024/10/27 13:03:30 modbus: send 02 03 01 05 00 01 95 c4
[heidel] TRACE 2024/10/27 13:03:30 modbus: recv 02 03 02 00 00 fc 44
Power: 0W
Energy: 3268.1kWh
Current L1..L3: 0A 0A 0A
Voltage L1..L3: 241V 243V 240V
Charge status: A
Enabled: false
Danke. Jetzt müssen wir intern nochmal schauen ob es auch die anderen Tests besteht aufgrund derer wir die Änderungen überhaupt gemacht hatten.
@premultiply siehe https://github.com/evcc-io/modbus/pull/13 zur Diskussion.
Works in 0.131.2. Thanks!
Describe the bug
When upgrading from 0.130.13 to 0.131.0 or 1, my Heidelberg chargers stop working. Nothing else changed, downgrading fixes the issue. Uncommenting one charger in the config doesn't help
Steps to reproduce
Update 0.130.13 to 0.131.x with Heidelberg Charger
Configuration details
Log details
What type of operating system are you running?
Linux
Nightly build
Version
0.131.1