search

evcc-io / evcc

Sonne tanken ☀️🚘
https://evcc.io
MIT License
3.56k stars 659 forks source link

Version 1.120.0 produziert bei phoenix-ev-eth controllern i/o timeout #9981

Closed ExecuteGK closed 1 year ago

ExecuteGK commented 1 year ago

Describe the bug

Nach dem Wechsel von Version 1.119.5 nach 1.1120.0 produziert eine Wallbox mit dem phoenix-ev-eth controller und der firmware 1.27 folgende Fehler:

vcc[1008602]: [lp-1 ] ERROR 2023/09/20 18:12:11 charger: read tcp 192.168.1.101:34486->192.168.7.8:502: i/o timeout

Steps to reproduce

  1. Installiere version 1.119.5
  2. Verifiziere das die Config ohne Fehler läuft
  3. Installiere 1.120.0
  4. Fehler im Logfile werden produziert. ...

Configuration details

chargers:
- type: template
  template: phoenix-ev-eth
  host: 192.168.7.8
  port: 502
  name: wallbox5

Log details

[main  ] INFO 2023/09/20 18:25:53 evcc 0.120.0
[main  ] INFO 2023/09/20 18:25:53 using config file: /etc/evcc.yaml
[main  ] INFO 2023/09/20 18:25:53 starting ui and api at :7070
[db    ] INFO 2023/09/20 18:25:53 using sqlite database: /root/.evcc/evcc.db
[mqtt  ] INFO 2023/09/20 18:25:53 connecting evcc-1972285256 at tcp://localhost:1883
[mqtt  ] DEBUG 2023/09/20 18:25:53 tcp://localhost:1883 connected
[site  ] WARN 2023/09/20 18:26:27 deprecated: use 'pv' instead of 'pvs'
[site  ] WARN 2023/09/20 18:26:27 deprecated: use 'battery' instead of 'batteries'
[site  ] WARN 2023/09/20 18:26:27 battery configured but residualPower is missing (add residualPower: 100 to site)
[site  ] INFO 2023/09/20 18:26:27 site config:
[site  ] INFO 2023/09/20 18:26:27   meters:      grid ✓ pv ✓ battery ✓
[site  ] INFO 2023/09/20 18:26:27     grid:      power ✓ energy ✗ currents ✗
[site  ] INFO 2023/09/20 18:26:27     pv 1:      power ✓ energy ✗ currents ✗
[site  ] INFO 2023/09/20 18:26:27     battery 1: power ✓ energy ✗ currents ✗ soc ✓ capacity ✗
[site  ] INFO 2023/09/20 18:26:27   vehicles:
[site  ] INFO 2023/09/20 18:26:27     vehicle 1: range ✓ finish ✓ status ✓ climate ✓ wakeup ✓
[lp-1  ] INFO 2023/09/20 18:26:27 loadpoint 1:
[lp-1  ] INFO 2023/09/20 18:26:27   mode:        pv
[lp-1  ] INFO 2023/09/20 18:26:27   charger:     power ✗ energy ✗ currents ✗ phases ✗ wakeup ✗
[lp-1  ] INFO 2023/09/20 18:26:27   meters:      charge ✗
[lp-2  ] INFO 2023/09/20 18:26:27 loadpoint 2:
[lp-2  ] INFO 2023/09/20 18:26:27   mode:        pv
[lp-2  ] INFO 2023/09/20 18:26:27   charger:     power ✓ energy ✓ currents ✓ phases ✗ wakeup ✗
[lp-2  ] INFO 2023/09/20 18:26:27   meters:      charge ✓
[lp-2  ] INFO 2023/09/20 18:26:27     charge:    power ✓ energy ✓ currents ✓
[lp-1  ] DEBUG 2023/09/20 18:26:27 phase timer inactive
[lp-1  ] DEBUG 2023/09/20 18:26:27 pv timer inactive
[lp-1  ] DEBUG 2023/09/20 18:26:27 guard timer inactive
[lp-1  ] ERROR 2023/09/20 18:26:37 charger: read tcp 192.168.1.101:60868->192.168.7.8:502: i/o timeout
[lp-2  ] DEBUG 2023/09/20 18:26:37 phase timer inactive
[lp-2  ] DEBUG 2023/09/20 18:26:37 pv timer inactive
[lp-2  ] DEBUG 2023/09/20 18:26:37 guard timer inactive
[site  ] WARN 2023/09/20 18:26:37 interval <30s can lead to unexpected behavior, see https://docs.evcc.io/docs/reference/configuration/interval
[site  ] DEBUG 2023/09/20 18:26:37 ----
[lp-1  ] DEBUG 2023/09/20 18:26:37 charge power: 0W
[lp-2  ] DEBUG 2023/09/20 18:26:37 charge power: 0W
[site  ] DEBUG 2023/09/20 18:26:37 pv power: 1118W
[site  ] DEBUG 2023/09/20 18:26:37 battery soc: 92%
[site  ] DEBUG 2023/09/20 18:26:37 battery power: -438W
[site  ] DEBUG 2023/09/20 18:26:37 grid power: 11W
[site  ] DEBUG 2023/09/20 18:26:37 site power: -427W
[lp-1  ] ERROR 2023/09/20 18:26:47 charger: read tcp 192.168.1.101:56568->192.168.7.8:502: i/o timeout
[site  ] DEBUG 2023/09/20 18:26:47 ----

What type of operating system are you running?

Linux

Version

evcc version 0.120.0

andig commented 1 year ago

Hilft es, timeout zu setzen? Die Verbindung selbst klappt ja anscheinend?

premultiply commented 1 year ago

Bitte mal evcc charger --log trace --diagnose laufen lassen damit man überhaupt mal sieht was hier genau in ein Timeout läuft.

ExecuteGK commented 1 year ago

Hier der Output. Ich hab die DB Sektion und die andere Wallbox mal raus geschnitten....

--------
[main  ] INFO 2023/09/21 08:20:16 evcc 0.120.0
[main  ] INFO 2023/09/21 08:20:16 using config file: /etc/evcc.yaml
[ev-eth] TRACE 2023/09/21 08:20:16 modbus: send 00 01 00 00 00 06 01 04 00 6c 00 02
[ev-eth] TRACE 2023/09/21 08:20:26 modbus: send 00 02 00 00 00 06 01 01 01 a3 00 01
[ev-eth] TRACE 2023/09/21 08:20:36 modbus: send 00 03 00 00 00 06 01 03 02 10 00 01
Diagnostic dump:
wallbox5
--------
[ev-eth] TRACE 2023/09/21 08:20:47 modbus: send 00 04 00 00 00 06 01 04 00 64 00 01
[ev-eth] TRACE 2023/09/21 08:20:57 modbus: send 00 05 00 00 00 06 01 01 01 90 00 01
Charge status: read tcp 192.168.1.101:51136->192.168.7.8:502: i/o timeout
Enabled:       read tcp 192.168.1.101:57470->192.168.7.8:502: i/o timeout

Diagnostic dump:
[ev-eth] TRACE 2023/09/21 08:21:07 modbus: send 00 06 00 00 00 06 01 04 00 69 00 02

Grüße

Sebastian

ExecuteGK commented 1 year ago

Mit der 1.119.5 sieht das so aus:

wallbox5
--------
[ev-eth] TRACE 2023/09/21 08:26:49 modbus: send 00 01 00 00 00 06 ff 04 00 78 00 02
[ev-eth] TRACE 2023/09/21 08:26:49 modbus: recv 00 01 00 00 00 07 ff 04 04 00 00 00 00
[ev-eth] TRACE 2023/09/21 08:26:49 modbus: send 00 02 00 00 00 06 ff 03 03 88 00 02
[ev-eth] TRACE 2023/09/21 08:26:49 modbus: recv 00 02 00 00 00 07 ff 03 04 86 9f 00 2c
[ev-eth] TRACE 2023/09/21 08:26:49 modbus: send 00 03 00 00 00 06 ff 04 00 72 00 02
[ev-eth] TRACE 2023/09/21 08:26:49 modbus: recv 00 03 00 00 00 07 ff 04 04 00 00 00 00
[ev-eth] TRACE 2023/09/21 08:26:49 modbus: send 00 04 00 00 00 06 ff 04 00 74 00 02
[ev-eth] TRACE 2023/09/21 08:26:49 modbus: recv 00 04 00 00 00 07 ff 04 04 00 00 00 00
[ev-eth] TRACE 2023/09/21 08:26:49 modbus: send 00 05 00 00 00 06 ff 04 00 76 00 02
[ev-eth] TRACE 2023/09/21 08:26:49 modbus: recv 00 05 00 00 00 07 ff 04 04 00 00 00 00
[ev-eth] TRACE 2023/09/21 08:26:49 modbus: send 00 06 00 00 00 06 ff 04 00 64 00 01
[ev-eth] TRACE 2023/09/21 08:26:49 modbus: recv 00 06 00 00 00 05 ff 04 02 00 41
[ev-eth] TRACE 2023/09/21 08:26:49 modbus: send 00 07 00 00 00 06 ff 01 01 90 00 01
[ev-eth] TRACE 2023/09/21 08:26:49 modbus: recv 00 07 00 00 00 04 ff 01 01 00
[ev-eth] TRACE 2023/09/21 08:26:49 modbus: send 00 08 00 00 00 06 ff 04 00 66 00 02
[ev-eth] TRACE 2023/09/21 08:26:49 modbus: recv 00 08 00 00 00 07 ff 04 04 00 00 00 00
Power:          0W
Energy:         2918.0kWh
Current L1..L3: 0A 0A 0A
Charge status:  A
Enabled:        false
Duration:       0s
premultiply commented 1 year ago

Problem erkannt: Trag mal bitte in deiner Konfig bei diesem charger id: 255 ein. Das fehlt dort und wird wohl mit dem internen Default-Wert 1 übergeben.

ExecuteGK commented 1 year ago

Yup, läuft.

wallbox5
--------
[ev-eth] TRACE 2023/09/21 09:16:29 modbus: send 00 04 00 00 00 06 ff 04 00 78 00 02
[ev-eth] TRACE 2023/09/21 09:16:29 modbus: recv 00 04 00 00 00 07 ff 04 04 00 00 00 00
[ev-eth] TRACE 2023/09/21 09:16:29 modbus: send 00 05 00 00 00 06 ff 03 03 88 00 02
[ev-eth] TRACE 2023/09/21 09:16:29 modbus: recv 00 05 00 00 00 07 ff 03 04 86 a0 00 2c
[ev-eth] TRACE 2023/09/21 09:16:29 modbus: send 00 06 00 00 00 06 ff 04 00 72 00 06
[ev-eth] TRACE 2023/09/21 09:16:29 modbus: recv 00 06 00 00 00 0f ff 04 0c 00 00 00 00 00 00 00 00 00 00 00 00
[ev-eth] TRACE 2023/09/21 09:16:29 modbus: send 00 07 00 00 00 06 ff 04 00 6c 00 06
[ev-eth] TRACE 2023/09/21 09:16:29 modbus: recv 00 07 00 00 00 0f ff 04 0c 00 e2 00 00 00 e4 00 00 00 e1 00 00
[ev-eth] TRACE 2023/09/21 09:16:29 modbus: send 00 08 00 00 00 06 ff 04 00 64 00 01
[ev-eth] TRACE 2023/09/21 09:16:29 modbus: recv 00 08 00 00 00 05 ff 04 02 00 41
[ev-eth] TRACE 2023/09/21 09:16:29 modbus: send 00 09 00 00 00 06 ff 01 01 90 00 01
[ev-eth] TRACE 2023/09/21 09:16:29 modbus: recv 00 09 00 00 00 04 ff 01 01 00
Power:          0W
Energy:         2918.0kWh
Current L1..L3: 0A 0A 0A
Voltage L1..L3: 226V 1.49e+07V 228V
Charge status:  A
Enabled:        false

Ist was für die Releasenotes ;)

Sebastian

andig commented 1 year ago

@premultiply Fehler im Template? Wenns vorher ging sollte es das ja weiterhin tun?

premultiply commented 1 year ago

Die ID war vorher fix verdübelt und nicht im Template drin. Wenn man neu mit configure arbeitet passt es auch.

Hilfreich wäre wenn wir bei Modbus TCP immer als internen Default 255 nehmen könnten. Da wird irgendwo derzeit dann immer 1 genommen. Das ist für Modbus TCP aber zu 80% falsch. Ausnahmen bestätigen die Regel.

andig commented 1 year ago

Dann ist das dennoch ein breaking change. Genau die wollen wir mit den Templates egtl. verhindern! Wir können nicht einfach einen Default weg fallen lassen den es vorher gab.

ExecuteGK commented 1 year ago

Yup, läuft.

wallbox5
--------
[ev-eth] TRACE 2023/09/21 09:16:29 modbus: send 00 04 00 00 00 06 ff 04 00 78 00 02
[ev-eth] TRACE 2023/09/21 09:16:29 modbus: recv 00 04 00 00 00 07 ff 04 04 00 00 00 00
[ev-eth] TRACE 2023/09/21 09:16:29 modbus: send 00 05 00 00 00 06 ff 03 03 88 00 02
[ev-eth] TRACE 2023/09/21 09:16:29 modbus: recv 00 05 00 00 00 07 ff 03 04 86 a0 00 2c
[ev-eth] TRACE 2023/09/21 09:16:29 modbus: send 00 06 00 00 00 06 ff 04 00 72 00 06
[ev-eth] TRACE 2023/09/21 09:16:29 modbus: recv 00 06 00 00 00 0f ff 04 0c 00 00 00 00 00 00 00 00 00 00 00 00
[ev-eth] TRACE 2023/09/21 09:16:29 modbus: send 00 07 00 00 00 06 ff 04 00 6c 00 06
[ev-eth] TRACE 2023/09/21 09:16:29 modbus: recv 00 07 00 00 00 0f ff 04 0c 00 e2 00 00 00 e4 00 00 00 e1 00 00
[ev-eth] TRACE 2023/09/21 09:16:29 modbus: send 00 08 00 00 00 06 ff 04 00 64 00 01
[ev-eth] TRACE 2023/09/21 09:16:29 modbus: recv 00 08 00 00 00 05 ff 04 02 00 41
[ev-eth] TRACE 2023/09/21 09:16:29 modbus: send 00 09 00 00 00 06 ff 01 01 90 00 01
[ev-eth] TRACE 2023/09/21 09:16:29 modbus: recv 00 09 00 00 00 04 ff 01 01 00
Power:          0W
Energy:         2918.0kWh
Current L1..L3: 0A 0A 0A
Voltage L1..L3: 226V 1.49e+07V 228V
Charge status:  A
Enabled:        false

Voltage L2 wird übrigens auch recht sportlich dargestellt. Ich weiss allerdings nicht ob das früher anders war. Im MQTT kommt das dann auch so an.

premultiply commented 1 year ago 
[ev-eth] TRACE 2023/09/21 09:16:29 modbus: recv 00 07 00 00 00 0f ff 04 0c 00 e2 00 00 00 e4 00 00 00 e1 00 00
Voltage L1..L3: 226V 1.49e+07V 228V

Das hab ich auch mal hier und da schon gesehen, habe aber keine Erklärung wo das herkommt. @andig Hast du eine Idee?

andig commented 1 year ago

Falsches Register? Da stimmt ja der Wert einfach nicht.

premultiply commented 1 year ago

Wie man an der Modbus-Antwort sieht sind die zurückgegebenen Integer eindeutig. Alle diese Werte werden in einem Rutsch gelesen und identisch verarbeitet. Die Darstellung entgleist dennoch. Auch die Reihenfolge ist etwas seltsam. 🧐

andig commented 1 year ago

Alle diese Werte werden in einem Rutsch gelesen und identisch verarbeitet.

Identisch falsch:

var res [3]float64
for i := 0; i < 3; i++ {
    res[i] = float64(encoding.Int32LswFirst(b[2*i:]))
}

Soweit ich sehe, sind die Werte 32 bit. Der Code greift 16 bit ab. @premultiply

premultiply commented 1 year ago

Aua 🤦🏻‍♂️

premultiply commented 1 year ago

Fixed in https://github.com/evcc-io/evcc/commit/b69abc6b278fefd5890f88e643b917a51b215390