evcc-io / evcc

Solar Charging ☀️🚘
https://evcc.io
MIT License
3.67k stars 687 forks source link

Add checkpointing of savings statistics #9072

Closed droerich closed 1 year ago

droerich commented 1 year ago

Describe the bug

I cut the power of the device (Raspi) evcc is running. After restarting the device and thus evcc the values of database keys savings.gridCharged and savings.selfConsumptionCharged are smaller than before the shutdown. As far as I can tell, no loading sessions in the recent past are missing in the sessions database though.

Steps to reproduce

  1. Kill evcc (e.g. cut power)

I don't know if this always reproduces the described behavior.

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: debug
levels:
  cache: error

# unique installation id
plant: ***

interval: 10s # control cycle interval

meters:
- type: template
  template: sma-home-manager
  usage: grid
  host: 192.168.178.63
  name: grid1
- type: template
  template: sma-inverter
  usage: pv
  host: 192.168.178.61
  name: pv2

vehicles:
- type: template
  template: renault
  title: Megane
  user: ***
  password: ***
  vin: ***
  capacity: 60
  phases: 3
  icon: car
  cache: 15m
  minSoC: 20
  targetSoC: 80
  minCurrent: 6
  maxCurrent: 32
  name: ev3

sponsortoken: ***

chargers:
- type: template
  template: easee
  user: ***
  password: ***
  charger: EHZP2PDQ
  name: wallbox1

loadpoints:
- title: Stellplatz
  charger: wallbox1
  vehicle: ev3
  mode: off

site:
  title: Silcher20
  meters:
    grid: grid1
    pvs:
    - pv2

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

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

Log details

$ journalctl --unit evcc --since today
-- Journal begins at Sun 2023-07-09 11:02:57 CEST, ends at Sat 2023-07-22 22:41:17 CEST. --
Jul 22 17:16:37 evctl evcc[426]: [main  ] FATAL 2023/07/22 17:16:37 evcc was stopped. OS should restart the service. Or restart manually.
Jul 22 17:16:37 evctl systemd[1]: evcc.service: Main process exited, code=exited, status=1/FAILURE
Jul 22 17:16:37 evctl systemd[1]: evcc.service: Failed with result 'exit-code'.
Jul 22 17:16:37 evctl systemd[1]: evcc.service: Consumed 3.428s CPU time.
Jul 22 17:16:47 evctl systemd[1]: evcc.service: Scheduled restart job, restart counter is at 1.
Jul 22 17:16:47 evctl systemd[1]: Stopped evcc.
Jul 22 17:16:47 evctl systemd[1]: evcc.service: Consumed 3.428s CPU time.
Jul 22 17:16:47 evctl systemd[1]: Started evcc.
Jul 22 17:16:48 evctl evcc[796]: [main  ] INFO 2023/07/22 17:16:48 evcc 0.118.1
Jul 22 17:16:48 evctl evcc[796]: [main  ] INFO 2023/07/22 17:16:48 using config file: /etc/evcc.yaml
Jul 22 17:16:48 evctl evcc[796]: [main  ] INFO 2023/07/22 17:16:48 starting ui and api at :7070
Jul 22 17:16:49 evctl evcc[796]: [db    ] INFO 2023/07/22 17:16:49 using sqlite database: /var/lib/evcc/evcc.db
Jul 22 17:16:53 evctl evcc[796]: [easee ] DEBUG 2023/07/22 17:16:53 current mismatch, expected 6.0, got 7.0
Jul 22 17:16:55 evctl evcc[796]: [site  ] DEBUG 2023/07/22 17:16:55 static grid tariff
Jul 22 17:16:55 evctl evcc[796]: [site  ] WARN 2023/07/22 17:16:55 deprecated: use 'pv' instead of 'pvs'
Jul 22 17:16:55 evctl evcc[796]: [site  ] INFO 2023/07/22 17:16:55 site config:
Jul 22 17:16:55 evctl evcc[796]: [site  ] INFO 2023/07/22 17:16:55   meters:      grid ✓ pv ✓ battery ✗
Jul 22 17:16:55 evctl evcc[796]: [site  ] INFO 2023/07/22 17:16:55     grid:      power ✓ energy ✓ currents ✓
Jul 22 17:16:55 evctl evcc[796]: [site  ] INFO 2023/07/22 17:16:55     pv 1:      power ✓ energy ✓ currents ✓
Jul 22 17:16:55 evctl evcc[796]: [site  ] INFO 2023/07/22 17:16:55   vehicles:
Jul 22 17:16:55 evctl evcc[796]: [site  ] INFO 2023/07/22 17:16:55     vehicle 1: range ✓ finish ✓ status ✓ climate ✓ wakeup ✓
Jul 22 17:16:55 evctl evcc[796]: [lp-1  ] INFO 2023/07/22 17:16:55 loadpoint 1:
Jul 22 17:16:55 evctl evcc[796]: [lp-1  ] INFO 2023/07/22 17:16:55   mode:        off
Jul 22 17:16:55 evctl evcc[796]: [lp-1  ] INFO 2023/07/22 17:16:55   charger:     power ✓ energy ✓ currents ✓ phases ✓ wakeup ✗
Jul 22 17:16:55 evctl evcc[796]: [lp-1  ] INFO 2023/07/22 17:16:55   meters:      charge ✓
Jul 22 17:16:55 evctl evcc[796]: [lp-1  ] INFO 2023/07/22 17:16:55     charge:    power ✓ energy ✓ currents ✓
Jul 22 17:16:55 evctl evcc[796]: [site  ] DEBUG 2023/07/22 17:16:55 static grid tariff
Jul 22 17:16:55 evctl evcc[796]: [lp-1  ] DEBUG 2023/07/22 17:16:55 phase timer inactive
Jul 22 17:16:55 evctl evcc[796]: [lp-1  ] DEBUG 2023/07/22 17:16:55 pv timer inactive
Jul 22 17:16:55 evctl evcc[796]: [lp-1  ] DEBUG 2023/07/22 17:16:55 guard timer inactive
Jul 22 17:16:55 evctl evcc[796]: [lp-1  ] INFO 2023/07/22 17:16:55 vehicle updated: unknown -> Megane
Jul 22 17:16:55 evctl evcc[796]: [lp-1  ] DEBUG 2023/07/22 17:16:55 set min current: 6
Jul 22 17:16:55 evctl evcc[796]: [lp-1  ] DEBUG 2023/07/22 17:16:55 set min soc: 20
Jul 22 17:16:55 evctl evcc[796]: [lp-1  ] DEBUG 2023/07/22 17:16:55 set target soc: 80
Jul 22 17:16:55 evctl evcc[796]: [site  ] DEBUG 2023/07/22 17:16:55 ----
Jul 22 17:16:55 evctl evcc[796]: [lp-1  ] DEBUG 2023/07/22 17:16:55 charge power: 0W
Jul 22 17:16:55 evctl evcc[796]: [site  ] DEBUG 2023/07/22 17:16:55 static grid tariff
Jul 22 17:16:55 evctl evcc[796]: [site  ] DEBUG 2023/07/22 17:16:55 pv power: 948W
Jul 22 17:16:55 evctl evcc[796]: [site  ] DEBUG 2023/07/22 17:16:55 grid power: -14W
Jul 22 17:16:55 evctl evcc[796]: [site  ] DEBUG 2023/07/22 17:16:55 grid powers: [444 -189 -269]W
Jul 22 17:16:55 evctl evcc[796]: [site  ] DEBUG 2023/07/22 17:16:55 grid currents: [2.12 -0.878 -1.15]A
Jul 22 17:16:55 evctl evcc[796]: [site  ] DEBUG 2023/07/22 17:16:55 site power: -14W
Jul 22 17:16:55 evctl evcc[796]: [lp-1  ] DEBUG 2023/07/22 17:16:55 vehicle odometer: 8662km
Jul 22 17:16:55 evctl evcc[796]: [lp-1  ] DEBUG 2023/07/22 17:16:55 charge currents: [0 0 0]A
Jul 22 17:16:55 evctl evcc[796]: [lp-1  ] DEBUG 2023/07/22 17:16:55 charge total import: 1375.073kWh
Jul 22 17:16:55 evctl evcc[796]: [main  ] INFO 2023/07/22 17:16:55 new version available: 0.118.10
Jul 22 17:16:56 evctl evcc[796]: [lp-1  ] DEBUG 2023/07/22 17:16:56 charger status: A
Jul 22 17:16:56 evctl evcc[796]: [lp-1  ] INFO 2023/07/22 17:16:56 car disconnected
Jul 22 17:16:56 evctl evcc[796]: [lp-1  ] DEBUG 2023/07/22 17:16:56 set min current: 6
Jul 22 17:16:56 evctl evcc[796]: [lp-1  ] DEBUG 2023/07/22 17:16:56 set min soc: 20
Jul 22 17:16:56 evctl evcc[796]: [lp-1  ] DEBUG 2023/07/22 17:16:56 set target soc: 80
Jul 22 17:16:56 evctl evcc[796]: [site  ] DEBUG 2023/07/22 17:16:56 ----
Jul 22 17:16:56 evctl evcc[796]: [lp-1  ] DEBUG 2023/07/22 17:16:56 charge power: 0W
Jul 22 17:16:56 evctl evcc[796]: [site  ] DEBUG 2023/07/22 17:16:56 static grid tariff
Jul 22 17:16:56 evctl evcc[796]: [site  ] DEBUG 2023/07/22 17:16:56 pv power: 948W
Jul 22 17:16:57 evctl evcc[796]: [site  ] DEBUG 2023/07/22 17:16:57 grid power: 14W
Jul 22 17:16:57 evctl evcc[796]: [site  ] DEBUG 2023/07/22 17:16:57 grid powers: [469 -187 -268]W
Jul 22 17:16:57 evctl evcc[796]: [site  ] DEBUG 2023/07/22 17:16:57 grid currents: [2.22 -0.869 -1.14]A
Jul 22 17:16:57 evctl evcc[796]: [site  ] DEBUG 2023/07/22 17:16:57 site power: 14W
Jul 22 17:16:57 evctl evcc[796]: [lp-1  ] DEBUG 2023/07/22 17:16:57 charge currents: [0 0 0]A
Jul 22 17:16:57 evctl evcc[796]: [lp-1  ] DEBUG 2023/07/22 17:16:57 charge total import: 1375.073kWh
Jul 22 17:16:57 evctl evcc[796]: [lp-1  ] DEBUG 2023/07/22 17:16:57 charger status: A
Jul 22 17:17:05 evctl evcc[796]: [site  ] DEBUG 2023/07/22 17:17:05 ----
Jul 22 17:17:05 evctl evcc[796]: [lp-1  ] DEBUG 2023/07/22 17:17:05 charge power: 0W
Jul 22 17:17:05 evctl evcc[796]: [site  ] DEBUG 2023/07/22 17:17:05 static grid tariff
Jul 22 17:17:05 evctl evcc[796]: [site  ] DEBUG 2023/07/22 17:17:05 pv power: 950W
Jul 22 17:17:05 evctl evcc[796]: [site  ] DEBUG 2023/07/22 17:17:05 grid power: 27W
Jul 22 17:17:05 evctl evcc[796]: [site  ] DEBUG 2023/07/22 17:17:05 grid powers: [480 -187 -266]W
Jul 22 17:17:05 evctl evcc[796]: [site  ] DEBUG 2023/07/22 17:17:05 grid currents: [2.26 -0.872 -1.13]A
Jul 22 17:17:05 evctl evcc[796]: [site  ] DEBUG 2023/07/22 17:17:05 site power: 27W
Jul 22 17:17:05 evctl evcc[796]: [lp-1  ] DEBUG 2023/07/22 17:17:05 charge currents: [0 0 0]A
Jul 22 17:17:05 evctl evcc[796]: [lp-1  ] DEBUG 2023/07/22 17:17:05 charge total import: 1375.073kWh
Jul 22 17:17:05 evctl evcc[796]: [lp-1  ] DEBUG 2023/07/22 17:17:05 charger status: A
Jul 22 17:17:15 evctl evcc[796]: [site  ] DEBUG 2023/07/22 17:17:15 ----
Jul 22 17:17:15 evctl evcc[796]: [lp-1  ] DEBUG 2023/07/22 17:17:15 charge power: 0W
Jul 22 17:17:15 evctl evcc[796]: [site  ] DEBUG 2023/07/22 17:17:15 static grid tariff
Jul 22 17:17:15 evctl evcc[796]: [site  ] DEBUG 2023/07/22 17:17:15 pv power: 948W
Jul 22 17:17:15 evctl evcc[796]: [site  ] DEBUG 2023/07/22 17:17:15 grid power: 45W
Jul 22 17:17:15 evctl evcc[796]: [site  ] DEBUG 2023/07/22 17:17:15 grid powers: [497 -187 -266]W
Jul 22 17:17:15 evctl evcc[796]: [site  ] DEBUG 2023/07/22 17:17:15 grid currents: [2.33 -0.871 -1.14]A
Jul 22 17:17:15 evctl evcc[796]: [site  ] DEBUG 2023/07/22 17:17:15 site power: 45W
Jul 22 17:17:15 evctl evcc[796]: [lp-1  ] DEBUG 2023/07/22 17:17:15 charge currents: [0 0 0]A
Jul 22 17:17:15 evctl evcc[796]: [lp-1  ] DEBUG 2023/07/22 17:17:15 charge total import: 1375.073kWh
Jul 22 17:17:15 evctl evcc[796]: [lp-1  ] DEBUG 2023/07/22 17:17:15 charger status: A
Jul 22 17:17:25 evctl evcc[796]: [site  ] DEBUG 2023/07/22 17:17:25 ----
Jul 22 17:17:25 evctl evcc[796]: [lp-1  ] DEBUG 2023/07/22 17:17:25 charge power: 0W
Jul 22 17:17:25 evctl evcc[796]: [site  ] DEBUG 2023/07/22 17:17:25 static grid tariff
Jul 22 17:17:25 evctl evcc[796]: [site  ] DEBUG 2023/07/22 17:17:25 pv power: 938W
Jul 22 17:17:25 evctl evcc[796]: [site  ] DEBUG 2023/07/22 17:17:25 grid power: 20W
Jul 22 17:17:25 evctl evcc[796]: [site  ] DEBUG 2023/07/22 17:17:25 grid powers: [471 -185 -265]W
Jul 22 17:17:25 evctl evcc[796]: [site  ] DEBUG 2023/07/22 17:17:25 grid currents: [2.23 -0.867 -1.13]A
Jul 22 17:17:25 evctl evcc[796]: [site  ] DEBUG 2023/07/22 17:17:25 site power: 20W
Jul 22 17:17:25 evctl evcc[796]: [lp-1  ] DEBUG 2023/07/22 17:17:25 charge currents: [0 0 0]A
Jul 22 17:17:25 evctl evcc[796]: [lp-1  ] DEBUG 2023/07/22 17:17:25 charge total import: 1375.073kWh
Jul 22 17:17:25 evctl evcc[796]: [lp-1  ] DEBUG 2023/07/22 17:17:25 charger status: A

What type of operating system are you running?

Linux

Version

0.118.1

andig commented 1 year ago

Und worin besteht das Problem?

droerich commented 1 year ago

Das Problem besteht im Verlust der Daten über die insgesamt bezogene Energie aus dem Netzt und aus der PV-Anlage in der Größenordnung von mehreren Dutzend kW. Die in der Datenbank gespeicherten Werte von savings.gridCharged und savings.selfConsumptionCharged entsprechen einem Stand, der mutmaßlich mehrere Wochen alt ist (genau konnte ich es nicht herausfinden) und nicht den Werten, die zuletzt, also vor dem harten Abschalten, auf der UI angezeigt wurden. Ich hätte erwartet, dass diese Werte regelmäßig in die Datenbank persistiert werden. So verstehe ich im Übrigen auch den Code: Update(..) wird regelmäßig aufgerufen und aktualisiert sowohl die UI als auch die entsprechenden Daten in der Datenbank. Da das bei mir aber offensichtlich nicht so funktioniert hat, gehe ich von einem Bug aus.

andig commented 1 year ago

Dann brauchts ein trace log für db um das nachvollziehen zu können.

droerich commented 1 year ago

Kann man das Log-Level für einzelne Komponenten individuell einstellen?

andig commented 1 year ago

Ja, siehe levels

droerich commented 1 year ago

Ich konnte das Verhalten gerade mit 0.118.10 reproduzieren.

Vor hartem Abschalten auf Web-UI

Nach Neustart auf Web-UI

Leider noch keine Tracing-Logs für die DB, denn dazu hätte ich meine Konfig ändern und evcc neu starten müssen, was das Experiment verfälscht hätte durch das reguläre Beenden von evcc.

andig commented 1 year ago

Was ist denn "reguläres" Beenden im Vergleich? In jedem Fall brauchts mal logs von regulär und dem Fehlerfall zum Vergleich.

droerich commented 1 year ago

Mit regulärem Beenden meine ich ein systemctl stop evcc sprich ein SIGTERM an evcc.

Ich habe jetzt trace-Logs für DB aktiviert und werde das Experiment wiederholen, sobald ein neuer Ladevorgang hinzugekommen ist.

andig commented 1 year ago

Wir behandeln die eigentlich alle gleich:

// catch signals
go func() {
    signalC := make(chan os.Signal, 1)
    signal.Notify(signalC, os.Interrupt, syscall.SIGTERM)

    <-signalC                        // wait for signal
    once.Do(func() { close(stopC) }) // signal loop to end
}()

Beendest Du es vllt. per SIGKILL?

droerich commented 1 year ago

Der Fehler tritt auf, wenn ich das Gerät, auf dem evcc läuft, hart abschalte, indem ich die Stromversorgung trenne.

andig commented 1 year ago

In dem Fall... mache ich hier zu- denn darauf kann keine SW der Welt reagieren.

droerich commented 1 year ago

Das kann ich nicht nachvollziehen. Es geht hier ja nicht um Daten aus den letzten Sekunden vor dem Abschalten, sondern um Daten aus einem Zeitraum von mehreren Wochen. Daten aus solchen Zeiträumen kann man ja wohl persistieren ohne dass sie bei einem Stromausfall verlorgengehen. Klappt ja übrigens mit den Ladevorgängen in der sessions-Datenbank auch, die in meinem Fall erhalten blieben -- trotz Trennung der Stromversorgung.

andig commented 1 year ago

Klick. Jetzt hab ichs verstanden.

droerich commented 1 year ago

Ich habe den Fehler mit trace-Level-Log für DB reproduziert

Hier die Logs: evcc.log.gz

droerich commented 1 year ago

Heute habe ich evcc zum Vergleich nochmal regulär heruntergefahren (systemctl stop evcc)

Logs (Trace-Level für DB): evcc-230726.log.gz

andig commented 1 year ago

Und?

droerich commented 1 year ago

Und die letzten Logs, die ich gepostet habe, sind nutzlos, weil durch einen Fehler von mir die Datenbank für evcc nicht schreibbar war. Muss das Experiment wiederholen.

andig commented 1 year ago

Ich muss es auch nochmal wiederholen: hartes Abschalten ist kein Case, auf den wir optimieren wollen...

droerich commented 1 year ago

Zwischen Optimierung für einen Edge-Case und Berücksichtigung eines Edge-Cases gibt es ja auch eine gewissen Bandbreite. Plötzliches Abschalten/Stromausfälle sind eine Realität von Embedded Devices, die eine robuste Anwendung meiner Meinung nach berücksichtigen sollte.

Ich mache diese Auswertungen, weil ich euch dabei helfen will, die App zu verbessern. Wenn daran kein Interesse besteht, akzeptiere ich das natürlich. Dann behalte ich halt im Hinterkopf, dass man evcc immer sauber runterfahren muss, um solche Datenverluste zu vermeiden. Aber sagt es mir halt bitte, damit ich hier keine Arbeit für die Tonne mache.

naltatis commented 1 year ago

@droerich danke für die Analyse. Ich bin da total bei dir. Wir sollten alle zu persistierenden Daten in regelmäßigen Abständen (bspw. alle 30min) auch wirklich auf die Platte schreiben. Stromausfall und Stecker-Ziehen beim Raspberry sind in der Praxis nicht vermeidbar.

RTTTC commented 1 year ago

I have also lost some data, noticed that my total solar energy % went down after a power outage. It was slowly going up the last few months, as there is plenty of sun. (97% Solar for July, but was pretty bad during winter months.) Good catch and good effort @droerich ! 😎

PeterPablo commented 1 year ago

Let me describe a related use case / issue: Currently, ongoing charging sessions are not persisted (written to the database) as long as the sessions is has not ended. For the main use case of a car charging, this is typically not an issue as it only takes some hours. In contrary to that my use case has several load points instantiated to record the energy consumption of apartments (with their actual price due to PV being available). Recently, there was a house wide power outage due to a service technician. This led to instantaneous power loss of the Raspberry Pi and consequently evcc did not end the sessions properly and write the data. Thus, several days of power consumption of the apartments were not logged at all.

Possible solution: Also write the ongoing charging sessions with an interval (e.g. 30mins) to the database by updating the last session's entry.

There was recently a similar request, which did not yet get much attention: https://github.com/evcc-io/evcc/issues/8788 The root cause is the same.

ignazhabibi commented 1 year ago

Ich habe das gleiche Problem auch schon mehrfach erlebt. Schade wenn die Statistiken dann mehrere Wochen alt sind, weil man den Raspi mal vom Strom trennen musste.

Passiert übrigens auch wenn man einen Home Assistant Restore macht und da evcc Add-on verwendet. Dies aber nur am Rande.