search

evcc-io / evcc

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

Easee hängt minutenlang mit "panic in logger" #4290

Closed TTXaser2 closed 2 years ago

TTXaser2 commented 2 years ago

Describe the bug

Hallo,

erst mal vielen Dank für EVCC!! Bin seit drei Wochen EVCC-Nutzer, wirklich sehr happy damit und finde die Lösung extra genial, weshalb ich sie auch gerne als Sponsor supporte.

Zu meinem System: Raspberry Pi 3b+ mit Debian-Desktop-System auf welchem EVCC, XRDP und ClamAV läuft, sonst nichts, per LAN im Netzwerk. EV: VW ID3 Wallbox Easee Home SMA HomeManager 2.0 Wechselrichter SMA Sunny Tripower 8000 und SunnyBoy 5000TLS, Batterie-Laderegler SMA SunnyIsland 3.0M

EVCC läuft in der Regel (die zwei Ausnahmen sind unten erläutert) problemlos, lädt - je nach eingestelltem Modus - perfekt nur Überschuss ins Auto. Auch im SMA Sunny Portal taucht der EVCC-Ladepunkt wie er soll mit Verbrauchswerten als nicht-steuerbarer Verbraucher auf. Die auf der EVCC-Webseite dargestellten Werte sind alle plausibel und entsprechen den Daten bspw. in der SMA Energy App.

Zum Problem: Die EVCC-Webseite ist ab und an über mehrere Minuten nicht erreichbar, heute ist mir das bereits zwei mal aufgefallen. Gleichzeitig komme ich auch nicht über RDP auf das System drauf, hab ich schon eine RDP-Session offen ist die gesamte UI eingefroren. Tut man nichts und wartet mehrere Minuten, kommt das System auch wieder zurück und läuft ganz normal weiter. Ich hab jetzt heute mal alles mitgeloggt und habe entdeckt, dass kurz nachdem der PI aus dem Freeze zurückkommt im EVCC-Log eine Logger-Panic-Meldung in Verbindung mit der Wallbox auftaucht. Meine Vermutung(!) ist dass EVCC irgendwo festhängt und das gesamte System deshalb freezed.
Siehe hierzu im beigefügten Logfile beispielhaft die Einträge ab Timestamp 09:51:40 -> Da freezed das System, nächster Timestamp ist erst wieder 09:58:17, da ist das System wieder komplett erreichbar (Web&RDP):

[lp-1  ] DEBUG 2022/09/02 09:51:40 charge power: 0W
[lp-1  ] DEBUG 2022/09/02 09:51:40 charge currents: [0.009 0.008 0.009]A
[lp-1  ] DEBUG 2022/09/02 09:51:40 charger status: B
[lp-1  ] DEBUG 2022/09/02 09:51:40 next soc poll remaining time: 19m48s
[sma   ] ERROR 2022/09/02 09:58:17 energy meter does not respond
[lp-1  ] DEBUG 2022/09/02 09:58:18 pv charge current: 2.29A = 0A + 2.29A (-527W @ 1p)
[server] ERROR 2022/09/02 09:58:18 write tcp 192.168.0.171:7070->192.168.0.153:61118: write: broken pipe
[lp-1  ] DEBUG 2022/09/02 09:58:19 climater active: false, target temp: 21.5°C, outside temp: 21.5°C
[lp-1  ] DEBUG 2022/09/02 09:58:19 climater active: false, target temp: 21.5°C, outside temp: 21.5°C
[lp-1  ] DEBUG 2022/09/02 09:58:19 charge power: 0W
[lp-1  ] DEBUG 2022/09/02 09:58:20 charge currents: [0.009 0.008 0.009]A
[lp-1  ] DEBUG 2022/09/02 09:58:20 charger status: B
[lp-1  ] DEBUG 2022/09/02 09:58:20 next soc poll remaining time: 13m9s
[lp-1  ] DEBUG 2022/09/02 09:58:20 pv charge current: 2.25A = 0A + 2.25A (-518W @ 1p)
[lp-1  ] DEBUG 2022/09/02 09:58:20 climater active: false, target temp: 21.5°C, outside temp: 21.5°C
[lp-1  ] DEBUG 2022/09/02 09:58:20 climater active: false, target temp: 21.5°C, outside temp: 21.5°C
recovering from panic in logger: expected string, got []interface {} from [ts 2022-09-02T07:58:24.050162127Z class Client connection jUObeOndRM7CWMG5x2KtCg hub charger.Easee ts 2022-09-02T07:58:24.050165252Z level info event message send message signalr.hubMessage{Type:6} error *signalr.webSocketConnection: failed to write msg: failed to write frame: WebSocket closed: received close frame: status = StatusNormalClosure and reason = ""]
recovering from panic in logger: expected string, got []interface {} from [ts 2022-09-02T07:58:24.068668732Z level info connect breaking loop. hubConnection canceled: context canceled]
[lp-1  ] DEBUG 2022/09/02 09:58:29 charge power: 0W
[lp-1  ] DEBUG 2022/09/02 09:58:29 charge currents: [0.009 0.008 0.009]A
[lp-1  ] DEBUG 2022/09/02 09:58:29 charger status: B
[lp-1  ] DEBUG 2022/09/02 09:58:29 next soc poll remaining time: 12m59s

ein weiterer Freeze ist im beigefügten Logfile zwischen Timestamp 2022/09/02 10:59:30 und 2022/09/02 11:10:53 zu finden, wieder kurz drauf mit nem Logger-Panic. Im File selber sind noch viel mehr dieser Einträge vorhanden, immer ein paar Einträge vorher mit eklatanten Zeitlücken im Logging wo einfach nichts passiert.

Vielleicht hängt das ja auch mit meinem zweiten Problem zusammen, dass bspw. bei gesetztem ID3-Ladeziel 85% der Vehicle-SoC auf der Webseite ab 84% nicht mehr aktualisiert wird und EVCC dann einfach hemmungslos PV-Überschuss weiterlädt. Im ongoing Logging vom Service zeigt er mir permanent die 84% an; Selbst wenn ich mit "sudo evcc -l debug vehicle" ein update fahre und den realen Ladezustand (bspw. 87%) angezeigt kriege (d.h. EVCC kann den aktuellen SoC des ID3 erfolgreich abfragen) aktualisiert er den SoC-Wert auf der Webseite nicht und lädt einfach fröhlich weiter. Ein Restart des EVCC-Service beendet den Zauber, er erkennt den richtigen SoC, zeigt ihn auf der Webseite richtig an und hört mit Laden auf. Hier hab ich aber momentan keine Logfiles parat die das untermauern. Aber evtl. hat das Verhalten ja was mit obigem Fehler zu tun?

Steps to reproduce

EVCC auf Raspberry Pi starten Elektroauto einstecken Log beobachten.

Configuration details

# open evcc at http://evcc.local:7070
network:
  schema: http
  host: evcc.local # .local suffix announces the hostname on MDNS
  port: 7070

log: info
levels:
  site: info
  lp-1: debug
  sma: debug  
  VWID3: info
  cache: error

interval: 10s # control cycle interval

sponsortoken: XXXXXXXXXX # your token from cloud.evcc.io

meters:
- name: my_grid
  type: template
  template: sma-home-manager
  usage: grid
  host: 192.168.0.157 # IP-Adresse oder Hostname 
- name: my_pv
  type: template
  template: sma-inverter
  usage: pv
  host: 192.168.0.158 # IP-Adresse oder Hostname
  password: XXXXXXXXXX # Passwort für Benutzergruppe Benutzer # Optional #

- name: my_pv2
  type: template
  template: sma-inverter
  usage: pv
  host: 192.168.0.159 # IP-Adresse oder Hostname
#  password: XXXXXXXXXX # Passwort für Benutzergruppe Benutzer # Optional #

#- name: SunnyBoy
#  type: sma
#  serial: 2XXXXX07
#- name: shm2
#  type: sma
#  uri: 192.168.0.157
  #serial: 301XXXX05
#- name: SunnyTriPower
#  type: sma
#  serial: 301XXXXX7
#  password: XXXXXXXXXX

- name: SunnyIsland
  type: sma
  uri: 192.168.0.76

chargers:
  - name: Eddys_Easee
    type: template
    template: easee
    user: inf@email.com # Benutzerkonto (bspw. E-Mail Adresse, User Id, etc.)
    password: XXXXXXXXXX # Passwort des Benutzerkontos (bei führenden Nullen bitte in einfache Hochkommata setzen)
    charger: EHDXXXXJ 

loadpoints:
  - title: Garage # display name for UI
    charger: Eddys_Easee # Wallbox Referenz
    vehicle: ev5 # Referenz auf Standardfahrzeug
    mode: pv # charge mode (off, now, minpv, pv)
    resetOnDisconnect: false
    phases: 0

vehicles:
- type: template
  template: id 
  title: VWID3  
  user: info@eduardfuchs.com  
  password: XXXXXXXXXX  
  vin: WVWZZZXXXXXXXXXX885  
  capacity: 58  
  name: ev5
  targetSoC: 85

tariffs:
  currency: EUR # (default EUR)
  grid:
    # static grid price
    type: fixed
    price: 0.277 # [currency]/kWh

  feedin:
    # rate for feeding excess (pv) energy to the grid
    type: fixed
    price: 0.1231 # [currency]/kWh

site:
  title: Zuhause
  meters:
    grid: my_grid
    pvs:
    - my_pv
    - my_pv2
    batteries:
    - SunnyIsland
  residualPower: 100
  bufferSoC: 90  #oberhalb 90% SoC wird Batterie bei ungenügendem Überschuss zum EV-Laden mitverwendet
  prioritySoC: 75 #unterhalb 75% SoC wird Batterie vor EV mit Überschuss geladen

hems:
  type: sma
  AllowControl: false

# Message config using evcc go-text-template rendering, evcc variables and sprig-functions
messaging:
  services:
  - type: telegram
    token: 5647XXXXXXXXXXx8zlWl8  # bot id : jede laufende Instanz von evcc benötigt eine eigene bot id
    chats:
    - 50XXXXX00

  events:
    start: # charge start event
      title: Charge of {{.vehicleTitle}} started
      msg: |
        Wallbox {{.title}} startet Laden des {{.vehicleTitle}} im Modus {{ toString .mode | upper }} mit {{.activePhases}} Phase(n) und {{round (divf .chargePower 1000) 2 }} kW Leistung.
        Aktueller Ladestand {{.vehicleSoC}}%, Zielladestand {{.targetSoC}}%. 
        -----------------------------------
        Aktueller System-Status {{printf `(%02d-%02d-%d %02d:%02d:%02d)` now.Day now.Month now.Year now.Hour now.Minute now.Second}}
        Netz-Leistung (-=Einsp.): {{round (divf .gridPower 1000) 3 }} kW
        Solar-Leistung: {{round (divf .pvPower 1000) 3 }} kW
        Hausverbrauch (ohne WB): {{round (divf .homePower 1000) 3 }} kW
        {{if .batteryConfigured}}Batteriespeicher: {{round (divf .batteryPower 1000) 3 }} kW ({{.batterySoC }}%){{end}}
    stop: # charge stop event
      title: Charge of {{.vehicleTitle}} finished
      msg: |
        Wallbox {{.title}} beendet Laden des {{.vehicleTitle}} mit {{round (divf .chargedEnergy 1000) 2 }} kWh und Ladestand {{.vehicleSoC}}% nach {{.chargeDuration}}.
        -----------------------------------
        Aktueller System-Status {{printf `(%02d-%02d-%d %02d:%02d:%02d)` now.Day now.Month now.Year now.Hour now.Minute now.Second}}
        Netz-Leistung (-=Einsp.): {{round (divf .gridPower 1000) 3 }} kW
        Solar-Leistung: {{round (divf .pvPower 1000) 3 }} kW
        Hausverbrauch (ohne WB): {{round (divf .homePower 1000) 3 }} kW
        {{if .batteryConfigured}}Batteriespeicher: {{round (divf .batteryPower 1000) 3 }} kW ({{.batterySoC }}%){{end}}
    connect: # vehicle connect event
      title: "{{.vehicleTitle}} connected on wallbox {{.title}}"
      msg: |
        {{.vehicleTitle}} mit Ladestand {{.vehicleSoC}}% verbunden mit Wallbox {{.title}} bei aktuell {{round (divf .pvPower 1000) 2 }} kW PV-Leistung.
        -----------------------------------
        Aktueller System-Status {{printf `(%02d-%02d-%d %02d:%02d:%02d)` now.Day now.Month now.Year now.Hour now.Minute now.Second}}
        Netz-Leistung (-=Einsp.): {{round (divf .gridPower 1000) 3 }} kW
        Solar-Leistung: {{round (divf .pvPower 1000) 3 }} kW
        Hausverbrauch (ohne WB): {{round (divf .homePower 1000) 3 }} kW
        {{if .batteryConfigured}}Batteriespeicher: {{round (divf .batteryPower 1000) 3 }} kW ({{.batterySoC }}%){{end}}
    disconnect: # vehicle connected event
      title: "{{.vehicleTitle}} disconnected of wallbox {{.title}}"
      msg: |
        {{.vehicleTitle}} ausgesteckt aus Wallbox {{.title}} nach {{.connectedDuration}} mit Ladestand {{.vehicleSoC}}% und vorauss. Reichweite {{.vehicleRange}}km.
        -----------------------------------
        Aktueller System-Status {{printf `(%02d-%02d-%d %02d:%02d:%02d)` now.Day now.Month now.Year now.Hour now.Minute now.Second}}
        Netz-Leistung (-=Einsp.): {{round (divf .gridPower 1000) 3 }} kW
        Solar-Leistung: {{round (divf .pvPower 1000) 3 }} kW
        Hausverbrauch (ohne WB): {{round (divf .homePower 1000) 3 }} kW
        {{if .batteryConfigured}}Batteriespeicher: {{round (divf .batteryPower 1000) 3 }} kW ({{.batterySoC }}%){{end}}

Log details

evcc.log

What type of operating system are you running?

Linux

Version

evcc version 0.100

andig commented 2 years ago

Kannst Du das auf Knopfdruck reproduzieren? Falls ja wär es super, wenn ich mir das im Debugger anschauen könnte. Der Hänger dürfte aber eher daher kommen, dass die Verbindung zur Easee Cloud weg ist. Du kannst mal in nightly prüfen, ob die Fehlermeldung noch kommt.

TTXaser2 commented 2 years ago

Danke für die schnelle Reaktion! Nein, auf Knopfdruck kann ich das leider nicht reproduzieren, wüsste zumindest stand heute nicht wie. Wenn ich aber was zur Lösung/Klarstellung beitragen kann, gern her damit :-) Sofern ich das in meiner knappen Freizeit hinkriege :-/

Ich hab jetzt vorhin mal die Nightly installiert (dauert bei mir, bin Linux/Raspi-Beginner, sorry). Werde das System jetzt mal nen guten Tag durchlaufen lassen und schauen ob's wieder Hänger gibt.