search

evcc-io / evcc

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

Charging does not stop with openWB in PV Mode #9948

Closed MarkusGH closed 11 months ago

MarkusGH commented 12 months ago

Describe the bug

When charging stops in PV mode due to PV timer expired, charging disable command is sent to openWB, but due to delayed response charging resumes immediately.

Steps to reproduce

  1. Use openWB
  2. Use PV mode
  3. EV is charging, PV power drops below threshold
  4. Charging stops, then resumes immediately

Configuration details

network:
  # schema is the HTTP schema
  # setting to `https` does not enable https, it only changes the way URLs are generated
  schema: http
  # host is the hostname or IP address
  # if the host name contains a `.local` suffix, the name will be announced on MDNS
  # docker: MDNS announcements don't work. host must be set to the docker host's name.
  host: localhost
  # port is the listening port for UI and api
  # evcc will listen on all available interfaces
  port: 7070

interval: 3s # control cycle interval

log: info
levels:
  porsche: trace
  lp-1: debug
  lp-2: debug
  openwb: trace

mqtt:
  broker: mqtt.xxx.de:1883
  topic: evcc

tariffs:
  currency: EUR # (default EUR)
  grid:
    type: fixed
    price: 0.1570 # [currency]/kWh
  feedin:
    type: fixed
    price: 0.0816 # [currency]/kWh

meters:
- name: grid1
  type: movingaverage
  decay: 1 # 0.5
  meter:
    type: custom
    power:
      source: mqtt
      topic: mbmd/solaredge1-1-1/Power
      scale: -1  # Die Leistung wird in Watt erwartet. Falls z.b. kW geliefert wird, kann dies hier mit dem Wert 1000 angepasst werden
      timeout: 30s  # Akzeptiere keine Daten die älter als dieser Wert ist
    energy:
      source: mqtt
      topic: mbmd/solaredge1-1-1/Import
      timeout: 30s  # Akzeptiere keine Daten die älter als dieser Wert ist
    currents:
      - source: mqtt
        topic: mbmd/solaredge1-1-1/Current/L1
        timeout: 30s  # Akzeptiere keine Daten die älter als dieser Wert ist
      - source: mqtt
        topic: mbmd/solaredge1-1-1/Current/L2
        timeout: 30s  # Akzeptiere keine Daten die älter als dieser Wert ist
      - source: mqtt
        topic: mbmd/solaredge1-1-1/Current/L3
        timeout: 30s  # Akzeptiere keine Daten die älter als dieser Wert ist
- name: pv1
  type: custom
  power:
    source: mqtt
    topic: mbmd/solaredge1-1/Power
    timeout: 30s  # Akzeptiere keine Daten die älter als dieser Wert ist
  energy:
    source: mqtt
    topic: mbmd/solaredge1-1/Export
    timeout: 30s  # Akzeptiere keine Daten die älter als dieser Wert ist
  currents:
    - source: mqtt
      topic: mbmd/solaredge1-1/Current/L1
      timeout: 30s  # Akzeptiere keine Daten die älter als dieser Wert ist
    - source: mqtt
      topic: mbmd/solaredge1-1/Current/L2
      timeout: 30s  # Akzeptiere keine Daten die älter als dieser Wert ist
    - source: mqtt
      topic: mbmd/solaredge1-1/Current/L3
      timeout: 30s  # Akzeptiere keine Daten die älter als dieser Wert ist

chargers:
- name: openwb1
  type: openwb
  phases1p3p: true
  broker: openwb.xxx.de # openWB IP
  id: 1                      # loadpoint ID
- name: openwb2
  type: openwb
  phases1p3p: true
  broker: openwb.xxx.de # openWB IP
  id: 2                      # loadpoint ID

vehicles:
- name: ev1
  type: template
  template: porsche
  title: Das Batmobil  # Wird in der Benutzeroberfläche angezeigt
  user: xxx  # Benutzername um auf das Gerät zuzugreifen
  password: xxx  # Passwort des Benutzerkontos
  vin: xxx # Erforderlich, wenn mehrere Fahrzeuge des Herstellers vorhanden sind
  capacity: 17.9  # Akku-Kapazität in kWh
  phases: 2
  maxCurrent: 16
  cache: 20m

loadpoints:
- title: Carport
  charger: openwb2
  resetOnDisconnect: true
  mode: pv
  soc:
    poll:
      mode: charging
      interval: 60m
    estimate: true
  phases: 0
  mincurrent: 6
  maxcurrent: 32
  enable:
    threshold: -600
    delay: 1m
  disable:
    threshold: 800
    delay: 3m
  guardduration: 5m
- title: Straße
  charger: openwb1
  resetOnDisconnect: true
  mode: pv
  soc:
    poll:
      mode: charging
      interval: 60m
    estimate: true
  phases: 0
  mincurrent: 6
  maxcurrent: 32
  enable:
    threshold: -1380
    delay: 1m
  disable:
    threshold: 0
    delay: 3m

site:
  title: XXX
  meters:
    grid: grid1
    pvs:
    - pv1
  residualPower: 0
#  maxCurrent: 63

Log details

Sep 18 12:10:59 homebridge evcc[1771769]: [lp-1  ] DEBUG 2023/09/18 12:10:59 charge power: 1354W
Sep 18 12:10:59 homebridge evcc[1771769]: [site  ] DEBUG 2023/09/18 12:10:59 pv power: 3842W
Sep 18 12:10:59 homebridge evcc[1771769]: [site  ] DEBUG 2023/09/18 12:10:59 grid power: 627W
Sep 18 12:10:59 homebridge evcc[1771769]: [site  ] DEBUG 2023/09/18 12:10:59 grid powers: [-670 1052 -1009]W
Sep 18 12:10:59 homebridge evcc[1771769]: [site  ] DEBUG 2023/09/18 12:10:59 grid currents: [-3.6 4.6 -4.7]A
Sep 18 12:10:59 homebridge evcc[1771769]: [site  ] DEBUG 2023/09/18 12:10:59 site power: 627W
Sep 18 12:10:59 homebridge evcc[1771769]: [lp-1  ] DEBUG 2023/09/18 12:10:59 charge currents: [5.9 0 0]A
Sep 18 12:10:59 homebridge evcc[1771769]: [lp-1  ] DEBUG 2023/09/18 12:10:59 detected active phases: 1p
Sep 18 12:10:59 homebridge evcc[1771769]: [lp-1  ] DEBUG 2023/09/18 12:10:59 charge total import: 3072.348kWh
Sep 18 12:10:59 homebridge evcc[1771769]: [lp-1  ] DEBUG 2023/09/18 12:10:59 charger status: C
Sep 18 12:10:59 homebridge evcc[1771769]: [lp-1  ] DEBUG 2023/09/18 12:10:59 soc estimated: 3.50% (vehicle: 1.00%)
Sep 18 12:10:59 homebridge evcc[1771769]: [lp-1  ] DEBUG 2023/09/18 12:10:59 vehicle soc: 4%
Sep 18 12:10:59 homebridge evcc[1771769]: [lp-1  ] DEBUG 2023/09/18 12:10:59 vehicle range: 0km
Sep 18 12:10:59 homebridge evcc[1771769]: [lp-1  ] DEBUG 2023/09/18 12:10:59 pv charge current: 3.27A = 6A + -2.73A (627W @ 1p)
Sep 18 12:10:59 homebridge evcc[1771769]: [lp-1  ] DEBUG 2023/09/18 12:10:59 site power 627W >= 0W disable threshold
Sep 18 12:10:59 homebridge evcc[1771769]: [lp-1  ] DEBUG 2023/09/18 12:10:59 pv disable in 0s
Sep 18 12:10:59 homebridge evcc[1771769]: [lp-1  ] DEBUG 2023/09/18 12:10:59 pv disable timer elapsed
Sep 18 12:10:59 homebridge evcc[1771769]: [lp-1  ] ERROR 2023/09/18 12:10:59 climater: emobility - unknown climate state: UNKNOWN
Sep 18 12:10:59 homebridge evcc[1771769]: [lp-1  ] DEBUG 2023/09/18 12:10:59 charger: guard elapse
Sep 18 12:10:59 homebridge evcc[1771769]: [lp-1  ] DEBUG 2023/09/18 12:10:59 guard timer inactive
Sep 18 12:10:59 homebridge evcc[1771769]: [openwb] TRACE 2023/09/18 12:10:59 send openWB/set/isss/Lp2Current: '0'
Sep 18 12:10:59 homebridge evcc[1771769]: [lp-1  ] DEBUG 2023/09/18 12:10:59 charger disable
Sep 18 12:10:59 homebridge evcc[1771769]: [lp-1  ] DEBUG 2023/09/18 12:10:59 wake-up timer: stop
Sep 18 12:11:02 homebridge evcc[1771769]: [openwb] TRACE 2023/09/18 12:11:02 recv openWB/system/Timestamp: '1695031862'
Sep 18 12:11:02 homebridge evcc[1771769]: [openwb] TRACE 2023/09/18 12:11:02 recv openWB/lp/2/kWhCounter: '3072.35'
Sep 18 12:11:02 homebridge evcc[1771769]: [site  ] DEBUG 2023/09/18 12:11:02 ----
Sep 18 12:11:02 homebridge evcc[1771769]: [lp-1  ] DEBUG 2023/09/18 12:11:02 charge power: 1354W
Sep 18 12:11:02 homebridge evcc[1771769]: [site  ] DEBUG 2023/09/18 12:11:02 pv power: 3826W
Sep 18 12:11:02 homebridge evcc[1771769]: [site  ] DEBUG 2023/09/18 12:11:02 grid power: 674W
Sep 18 12:11:02 homebridge evcc[1771769]: [site  ] DEBUG 2023/09/18 12:11:02 grid powers: [-708 1046 -1012]W
Sep 18 12:11:02 homebridge evcc[1771769]: [site  ] DEBUG 2023/09/18 12:11:02 grid currents: [-3.7 4.6 -4.7]A
Sep 18 12:11:02 homebridge evcc[1771769]: [site  ] DEBUG 2023/09/18 12:11:02 site power: 674W
Sep 18 12:11:03 homebridge evcc[1771769]: [openwb] TRACE 2023/09/18 12:11:03 send openWB/set/isss/heartbeat: '1'
Sep 18 12:11:03 homebridge evcc[1771769]: [openwb] TRACE 2023/09/18 12:11:03 send openWB/set/isss/heartbeat: '1'
Sep 18 12:11:05 homebridge evcc[1771769]: [site  ] DEBUG 2023/09/18 12:11:05 ----
Sep 18 12:11:05 homebridge evcc[1771769]: [lp-1  ] DEBUG 2023/09/18 12:11:05 charge power: 1354W
Sep 18 12:11:05 homebridge evcc[1771769]: [site  ] DEBUG 2023/09/18 12:11:05 pv power: 3825W
Sep 18 12:11:05 homebridge evcc[1771769]: [site  ] DEBUG 2023/09/18 12:11:05 grid power: -683W
Sep 18 12:11:05 homebridge evcc[1771769]: [site  ] DEBUG 2023/09/18 12:11:05 grid powers: [646 1043 -1006]W
Sep 18 12:11:05 homebridge evcc[1771769]: [site  ] DEBUG 2023/09/18 12:11:05 grid currents: [3.7 4.6 -4.7]A
Sep 18 12:11:05 homebridge evcc[1771769]: [site  ] DEBUG 2023/09/18 12:11:05 site power: -683W
Sep 18 12:11:05 homebridge evcc[1771769]: [lp-1  ] DEBUG 2023/09/18 12:11:05 charge currents: [5.9 0 0]A
Sep 18 12:11:05 homebridge evcc[1771769]: [lp-1  ] DEBUG 2023/09/18 12:11:05 detected active phases: 1p
Sep 18 12:11:05 homebridge evcc[1771769]: [lp-1  ] DEBUG 2023/09/18 12:11:05 charge total import: 3072.350kWh
Sep 18 12:11:05 homebridge evcc[1771769]: [lp-1  ] DEBUG 2023/09/18 12:11:05 charger status: C
Sep 18 12:11:05 homebridge evcc[1771769]: [lp-1  ] DEBUG 2023/09/18 12:11:05 soc estimated: 3.51% (vehicle: 1.00%)
Sep 18 12:11:05 homebridge evcc[1771769]: [lp-1  ] DEBUG 2023/09/18 12:11:05 vehicle soc: 4%
Sep 18 12:11:05 homebridge evcc[1771769]: [lp-1  ] DEBUG 2023/09/18 12:11:05 vehicle range: 0km
Sep 18 12:11:05 homebridge evcc[1771769]: [lp-1  ] DEBUG 2023/09/18 12:11:05 charger: guard elapse
Sep 18 12:11:05 homebridge evcc[1771769]: [lp-1  ] DEBUG 2023/09/18 12:11:05 guard timer inactive
Sep 18 12:11:05 homebridge evcc[1771769]: [lp-1  ] DEBUG 2023/09/18 12:11:05 pv charge current: 8.97A = 6A + 2.97A (-683W @ 1p)
Sep 18 12:11:05 homebridge evcc[1771769]: [lp-1  ] DEBUG 2023/09/18 12:11:05 pv timer reset
Sep 18 12:11:05 homebridge evcc[1771769]: [lp-1  ] DEBUG 2023/09/18 12:11:05 pv timer inactive
Sep 18 12:11:05 homebridge evcc[1771769]: [openwb] TRACE 2023/09/18 12:11:05 send openWB/set/isss/Lp2Current: '8'
Sep 18 12:11:05 homebridge evcc[1771769]: [lp-1  ] DEBUG 2023/09/18 12:11:05 max charge current: 8A
Sep 18 12:11:06 homebridge evcc[1771769]: [openwb] TRACE 2023/09/18 12:11:06 recv openWB/lp/2/W: '0'
Sep 18 12:11:06 homebridge evcc[1771769]: [openwb] TRACE 2023/09/18 12:11:06 recv openWB/lp/2/boolChargeStat: '0'
Sep 18 12:11:06 homebridge evcc[1771769]: [openwb] TRACE 2023/09/18 12:11:06 recv openWB/lp/2/APhase1: '0.0'
Sep 18 12:11:06 homebridge evcc[1771769]: [openwb] TRACE 2023/09/18 12:11:06 recv openWB/lp/2/kWhCounter: '3072.351'
Sep 18 12:11:08 homebridge evcc[1771769]: [site  ] DEBUG 2023/09/18 12:11:08 ----
Sep 18 12:11:08 homebridge evcc[1771769]: [lp-1  ] DEBUG 2023/09/18 12:11:08 charge power: 0W
Sep 18 12:11:08 homebridge evcc[1771769]: [site  ] DEBUG 2023/09/18 12:11:08 pv power: 3816W
Sep 18 12:11:08 homebridge evcc[1771769]: [site  ] DEBUG 2023/09/18 12:11:08 grid power: -686W
Sep 18 12:11:08 homebridge evcc[1771769]: [site  ] DEBUG 2023/09/18 12:11:08 grid powers: [666 1040 -1020]W
Sep 18 12:11:08 homebridge evcc[1771769]: [site  ] DEBUG 2023/09/18 12:11:08 grid currents: [3.2 4.6 -5]A
Sep 18 12:11:08 homebridge evcc[1771769]: [site  ] DEBUG 2023/09/18 12:11:08 site power: -686W
Sep 18 12:11:10 homebridge evcc[1771769]: [openwb] TRACE 2023/09/18 12:11:10 recv openWB/lp/2/boolChargeStat: '1'
Sep 18 12:11:11 homebridge evcc[1771769]: [site  ] DEBUG 2023/09/18 12:11:11 ----
Sep 18 12:11:11 homebridge evcc[1771769]: [lp-1  ] DEBUG 2023/09/18 12:11:11 charge power: 0W
Sep 18 12:11:11 homebridge evcc[1771769]: [site  ] DEBUG 2023/09/18 12:11:11 pv power: 3805W
Sep 18 12:11:11 homebridge evcc[1771769]: [site  ] DEBUG 2023/09/18 12:11:11 grid power: -683W
Sep 18 12:11:11 homebridge evcc[1771769]: [site  ] DEBUG 2023/09/18 12:11:11 grid powers: [670 1038 -1025]W
Sep 18 12:11:11 homebridge evcc[1771769]: [site  ] DEBUG 2023/09/18 12:11:11 grid currents: [3.2 4.6 -5]A
Sep 18 12:11:11 homebridge evcc[1771769]: [site  ] DEBUG 2023/09/18 12:11:11 site power: -683W
Sep 18 12:11:11 homebridge evcc[1771769]: [lp-1  ] DEBUG 2023/09/18 12:11:11 charge currents: [0 0 0]A
Sep 18 12:11:11 homebridge evcc[1771769]: [lp-1  ] DEBUG 2023/09/18 12:11:11 charge total import: 3072.351kWh
Sep 18 12:11:11 homebridge evcc[1771769]: [lp-1  ] DEBUG 2023/09/18 12:11:11 charger status: C
Sep 18 12:11:11 homebridge evcc[1771769]: [lp-1  ] DEBUG 2023/09/18 12:11:11 soc estimated: 3.52% (vehicle: 1.00%)
Sep 18 12:11:11 homebridge evcc[1771769]: [lp-1  ] DEBUG 2023/09/18 12:11:11 vehicle soc: 4%
Sep 18 12:11:11 homebridge evcc[1771769]: [lp-1  ] DEBUG 2023/09/18 12:11:11 vehicle range: 0km
Sep 18 12:11:11 homebridge evcc[1771769]: [lp-1  ] DEBUG 2023/09/18 12:11:11 pv charge current: 4.97A = 2A + 2.97A (-683W @ 1p)
Sep 18 12:11:11 homebridge evcc[1771769]: [openwb] TRACE 2023/09/18 12:11:11 send openWB/set/isss/Lp2Current: '6'
Sep 18 12:11:11 homebridge evcc[1771769]: [lp-1  ] DEBUG 2023/09/18 12:11:11 max charge current: 6A
Sep 18 12:11:12 homebridge evcc[1771769]: [openwb] TRACE 2023/09/18 12:11:12 recv openWB/system/Timestamp: '1695031872'
Sep 18 12:11:13 homebridge evcc[1771769]: [openwb] TRACE 2023/09/18 12:11:13 send openWB/set/isss/heartbeat: '1'
Sep 18 12:11:13 homebridge evcc[1771769]: [openwb] TRACE 2023/09/18 12:11:13 send openWB/set/isss/heartbeat: '1'
Sep 18 12:11:14 homebridge evcc[1771769]: [site  ] DEBUG 2023/09/18 12:11:14 ----
Sep 18 12:11:14 homebridge evcc[1771769]: [lp-1  ] DEBUG 2023/09/18 12:11:14 charge power: 0W
Sep 18 12:11:14 homebridge evcc[1771769]: [site  ] DEBUG 2023/09/18 12:11:14 pv power: 3794W
Sep 18 12:11:14 homebridge evcc[1771769]: [site  ] DEBUG 2023/09/18 12:11:14 grid power: 1130W
Sep 18 12:11:14 homebridge evcc[1771769]: [site  ] DEBUG 2023/09/18 12:11:14 grid powers: [-1120 1038 -1049]W
Sep 18 12:11:14 homebridge evcc[1771769]: [site  ] DEBUG 2023/09/18 12:11:14 grid currents: [-3.5 4.5 -4.9]A
Sep 18 12:11:14 homebridge evcc[1771769]: [site  ] DEBUG 2023/09/18 12:11:14 site power: 1130W
Sep 18 12:11:17 homebridge evcc[1771769]: [openwb] TRACE 2023/09/18 12:11:17 recv openWB/lp/2/W: '1783'
Sep 18 12:11:17 homebridge evcc[1771769]: [openwb] TRACE 2023/09/18 12:11:17 recv openWB/lp/2/APhase1: '7.8'
Sep 18 12:11:17 homebridge evcc[1771769]: [openwb] TRACE 2023/09/18 12:11:17 recv openWB/lp/2/kWhCounter: '3072.352'
Sep 18 12:11:17 homebridge evcc[1771769]: [site  ] DEBUG 2023/09/18 12:11:17 ----
Sep 18 12:11:17 homebridge evcc[1771769]: [lp-1  ] DEBUG 2023/09/18 12:11:17 charge power: 1783W
Sep 18 12:11:17 homebridge evcc[1771769]: [site  ] DEBUG 2023/09/18 12:11:17 pv power: 3792W
Sep 18 12:11:17 homebridge evcc[1771769]: [site  ] DEBUG 2023/09/18 12:11:17 grid power: 1145W
Sep 18 12:11:17 homebridge evcc[1771769]: [site  ] DEBUG 2023/09/18 12:11:17 grid powers: [-1120 1031 -1056]W
Sep 18 12:11:17 homebridge evcc[1771769]: [site  ] DEBUG 2023/09/18 12:11:17 grid currents: [-3.5 4.5 -4.9]A

What type of operating system are you running?

Linux

Version

evcc version 0.119.5 (8abaea79)

VolkerK62 commented 12 months ago

but due to delayed response charging resumes immediately.

interval: 3s # control cycle interval

Hast du es mal mit einem größeren Intervall probiert? 3s ist schon sehr sportlich.

MarkusGH commented 12 months ago

Ich wusste dass das kommt ;-) Ich kann das testen, aber dennoch stellt sich die Frage, ob die an der Stelle kürzlich geänderte Logik "wasserdicht" ist oder angepasst werden sollte. Werde mit aktueller Version nachtesten, gerade eben war der Fehler weg. Eventuell hat ja https://github.com/evcc-io/evcc/pull/9932 das Problem behoben. Werde weiter beobachten.

MarkusGH commented 12 months ago

Nach näherer Prüfung der Quellcodes würde ich meinen, dass das die Folge einer Race Condition ist, bei der der vermeintliche oder echte Status des Chargers zurück auf den Loadpoint übernommen wird. Wenn der Charger z. B. trotz vorherigem Enable(false) das Laden noch nicht beendet hat meldet er "Charging" und "Enabled". Im Falle der openWB bleibt der "Enabled" State sogar auf Ebene des Chargers erhalten wenn das Laden schon beendet wurde. Vorgeschlagene Korrektur: https://github.com/evcc-io/evcc/pull/9959

andig commented 12 months ago

Hast du mal probiert, ob ein normal großes Intervall das Problem auch löst?

GrimmiMeloni commented 12 months ago

9932 hat das Problem das der Charger lädt obwohl er disabled ist, nur bei einer Restart Situation bei laufendem Charge behoben. Dabei ist es dann OK, den Charger nochmal zu aktivieren, weil es nichts verändert.

Markus hat hier ein anderes mögliches Szenario für den Zustand gefunden. Der Charger schafft es nicht bis zum nächsten Regelinterval physikalisch abzuschalten. Dann haben wir das gleiche Bild wie beim Restart: Charger lädt (Status() liefert C) und gleichzeitig ist er disabled. #9932 reaktiviert den Charger dann aber wieder.

Ich habe mir #9959 angeschaut. Der Change am Loadpoint sieht erstmal richtig aus. Der Loadpoint.enabled folgt dem Charger dann nur nach Ablauf der Grace Period. Ich denk das ist OK. Allerdings hatte ich jetzt keine Zeit das Zusammenspiel mit Loadpoint.setLimit() zu durchdenken. Testen war um diese Uhrzeit ebenfalls nicht drin. 😉

MarkusGH commented 11 months ago

Danke - freut mich dass ich mit meinen Überlegungen durchdringe. Ich habe gerade im Loadpoint noch eine Änderung gemacht, denn wenn am Charger Enabled und Charging auseinanderfallen gibt es dieselbe Race Condition. Sei so nett und schau Dir das auch mal an ob das so passen könnte.

MarkusGH commented 11 months ago

So sieht das dann übrigens in Grafana aus image

VolkerK62 commented 11 months ago

Netzbezug reagiert viel schneller, als der Carport

MarkusGH commented 11 months ago

Genau - deswegen der PR https://github.com/evcc-io/evcc/pull/10011