evcc-io / evcc

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

Twingo: wake-up vehicle HTTP 500 #10970

Closed kwitt21 closed 9 months ago

kwitt21 commented 9 months ago

Describe the bug

Beim Einstellen einer Ladeplanung oder Klick auf "Schnell" zum Sofortladen ist es schon häufiger vorgekommen, dass unser Twingo einfach nicht starten wollte. Die GUI sagt dann "Warte auf Fahrzeug" während im Log folgernder Eintrag zu sehen ist.

[lp-1 ] DEBUG 2023/11/30 13:22:29 wake-up vehicle [lp-1 ] ERROR 2023/11/30 13:22:30 wake-up vehicle: unexpected status: 500 (Internal Server Error)

Ich kann oder besser muss dann via Wallbox oder Fahrzeug App die Ladung starten.

Meine Beobachtungen:

Steps to reproduce

1.Fahrzeug anstecken 2.Fahrzeug über längere Zeit (mehrere Stunden) angesteckt lassen, optional zusätzlich 1-phasig PV Überschuss laden 3.Fahrzeug Ladung mit "Schnell" oder berechneter Ladeplanung mit maximaler Ladeleistung (3-phasig) starten

Configuration details

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

log: debug
levels:
  cache: error

# unique installation id
plant: XXX

interval: 30s # control cycle interval

sponsortoken: XXX

# sponsors can set telemetry: true to enable anonymous data aggregation
# see https://github.com/evcc-io/evcc/discussions/4554
telemetry: false

meters:
- type: template
  template: e3dc 
  usage: grid  
  host: XXX
  port: 502  
  name: grid1
- type: template
  template: e3dc 
  usage: pv  
  host: XXX 
  port: 502  
  name: pv2
- type: template
  template: e3dc 
  usage: battery  
  host: XXX  
  port: 502  
  name: battery3

chargers:
- type: template
  template: go-e-v3 
  host: XXX
  name: wallbox5

vehicles:
- name: twingo
  type: template
  template: renault 
  title: Twingo  
  capacity: 22  
  user: XXX
  password: XXX
  vin: XXX 
  mode: pv
  mincurrent: 8
  maxcurrent: 16
  targetSoc: 80
  #priority: 5

loadpoints:
- title: go-e Charger
  charger: wallbox5
  #vehicle: twingo
  mode: pv
  phases: 0
  mincurrent: 6
  maxcurrent: 16
  resetOnDisconnect: true

site:
  title: Daheim
  meters:
    grid: grid1
    pv:
    - pv2
    battery:
    - battery3
  residualPower: 200 # additional household usage margin

# tariffs are the fixed or variable tariffs
tariffs:
  currency: EUR # three letter ISO-4217 currency code (default EUR)
  grid:
    # either static grid price (or price zones)
    type: fixed
    price: 0.307 # EUR/kWh

  feedin:
    # rate for feeding excess (pv) energy to the grid
    type: fixed
    price: 0.071 # EUR/kWh

mqtt:
  broker: homeassistant.local:1883
  topic: evcc # root topic for publishing, set empty to disable
  user: evcc
  password: XXX

Log details

Start von EVCC

Using config file: /config/evcc.yaml
starting evcc: 'EVCC_DATABASE_DSN=/data/evcc.db evcc --config /config/evcc.yaml'
[main  ] INFO 2023/12/01 13:33:30 evcc 0.122.1
[main  ] INFO 2023/12/01 13:33:30 using config file: /config/evcc.yaml
[main  ] INFO 2023/12/01 13:33:30 starting ui and api at :7070
[db    ] INFO 2023/12/01 13:33:30 using sqlite database: /data/evcc.db
[mqtt  ] INFO 2023/12/01 13:33:30 connecting evcc-1982719531 at tcp://homeassistant.local:1883
[mqtt  ] DEBUG 2023/12/01 13:33:30 tcp://homeassistant.local:1883 connected
[lp-1  ] DEBUG 2023/12/01 13:33:32 charge total import: 678.274kWh
[site  ] INFO 2023/12/01 13:33:32 site config:
[site  ] INFO 2023/12/01 13:33:32   meters:      grid ✓ pv ✓ battery ✓
[site  ] INFO 2023/12/01 13:33:32     grid:      power ✓ energy ✗ currents ✗
[site  ] INFO 2023/12/01 13:33:32     pv 1:      power ✓ energy ✗ currents ✗
[site  ] INFO 2023/12/01 13:33:32     battery 1: power ✓ energy ✗ currents ✗ soc ✓ capacity ✗
[site  ] INFO 2023/12/01 13:33:32   vehicles:
[site  ] INFO 2023/12/01 13:33:32     vehicle 1: range ✓ finish ✓ status ✓ climate ✓ wakeup ✓
[lp-1  ] INFO 2023/12/01 13:33:32 loadpoint 1:
[lp-1  ] INFO 2023/12/01 13:33:32   mode:        pv
[lp-1  ] INFO 2023/12/01 13:33:32   charger:     power ✓ energy ✓ currents ✓ phases ✓ wakeup ✗
[lp-1  ] INFO 2023/12/01 13:33:32   meters:      charge ✓
[lp-1  ] INFO 2023/12/01 13:33:32     charge:    power ✓ energy ✓ currents ✓
[lp-1  ] DEBUG 2023/12/01 13:33:32 phase timer inactive
[lp-1  ] DEBUG 2023/12/01 13:33:32 pv timer inactive
[lp-1  ] DEBUG 2023/12/01 13:33:32 guard timer inactive
[site  ] DEBUG 2023/12/01 13:33:32 ----
[lp-1  ] DEBUG 2023/12/01 13:33:32 charge power: 0W
[site  ] DEBUG 2023/12/01 13:33:32 pv power: 468W
[site  ] DEBUG 2023/12/01 13:33:32 battery soc: 32%
[site  ] DEBUG 2023/12/01 13:33:32 battery power: -123W
[site  ] DEBUG 2023/12/01 13:33:32 grid power: -26W
[site  ] DEBUG 2023/12/01 13:33:32 battery has priority at soc 32% (< 65%)
[site  ] DEBUG 2023/12/01 13:33:32 site power: 174W
[lp-1  ] DEBUG 2023/12/01 13:33:32 charge currents: [0 0 0]A
[lp-1  ] DEBUG 2023/12/01 13:33:32 charge total import: 678.274kWh
[lp-1  ] DEBUG 2023/12/01 13:33:32 charger status: A
[lp-1  ] INFO 2023/12/01 13:33:32 car disconnected
[lp-1  ] DEBUG 2023/12/01 13:33:32 set charge mode: pv
[lp-1  ] DEBUG 2023/12/01 13:33:32 set min current: 6
[lp-1  ] DEBUG 2023/12/01 13:33:32 set max current: 16
[lp-1  ] DEBUG 2023/12/01 13:33:32 set priority: 0

Sofortladen via Klick auf "Schnell"

[site  ] DEBUG 2023/11/30 13:21:49 ----
[lp-1  ] DEBUG 2023/11/30 13:21:49 charge power: 0W
[site  ] DEBUG 2023/11/30 13:21:49 pv power: 41W
[site  ] DEBUG 2023/11/30 13:21:49 battery soc: 23%
[site  ] DEBUG 2023/11/30 13:21:49 battery power: -9W
[site  ] DEBUG 2023/11/30 13:21:49 grid power: 321W
[site  ] DEBUG 2023/11/30 13:21:49 battery has priority at soc 23% (< 65%)
[site  ] DEBUG 2023/11/30 13:21:49 site power: 521W
[lp-1  ] DEBUG 2023/11/30 13:21:49 charge currents: [0 0 0]A
[lp-1  ] DEBUG 2023/11/30 13:21:49 charge total import: 672.043kWh
[lp-1  ] DEBUG 2023/11/30 13:21:49 charger status: B
[lp-1  ] DEBUG 2023/11/30 13:21:49 pv charge current: 0A = 0A + -2.27A (521W @ 1p)
[lp-1  ] DEBUG 2023/11/30 13:21:52 set charge mode: now
[site  ] DEBUG 2023/11/30 13:21:52 ----
[lp-1  ] DEBUG 2023/11/30 13:21:52 charge power: 0W
[site  ] DEBUG 2023/11/30 13:21:52 pv power: 40W
[site  ] DEBUG 2023/11/30 13:21:52 battery soc: 23%
[site  ] DEBUG 2023/11/30 13:21:52 battery power: 6W
[site  ] DEBUG 2023/11/30 13:21:52 grid power: 327W
[site  ] DEBUG 2023/11/30 13:21:52 site power: 533W
[lp-1  ] DEBUG 2023/11/30 13:21:52 charge currents: [0 0 0]A
[lp-1  ] DEBUG 2023/11/30 13:21:52 charge total import: 672.043kWh
[lp-1  ] DEBUG 2023/11/30 13:21:52 charger status: B
[lp-1  ] DEBUG 2023/11/30 13:21:52 !! scalePhasesIfAvailable: 3p -> 3p
[lp-1  ] DEBUG 2023/11/30 13:21:52 !! scalePhases: GetPhases 1p <> 3p wanted
[lp-1  ] DEBUG 2023/11/30 13:21:52 switched phases: 3p
[lp-1  ] DEBUG 2023/11/30 13:21:52 charger: guard elapse
[lp-1  ] DEBUG 2023/11/30 13:21:52 guard timer inactive
[lp-1  ] DEBUG 2023/11/30 13:21:52 charger enable
[lp-1  ] DEBUG 2023/11/30 13:21:52 wake-up timer: start
[site  ] DEBUG 2023/11/30 13:21:59 ----
[lp-1  ] DEBUG 2023/11/30 13:21:59 charge power: 0W
[site  ] DEBUG 2023/11/30 13:21:59 pv power: 41W
[site  ] DEBUG 2023/11/30 13:21:59 battery soc: 23%
[site  ] DEBUG 2023/11/30 13:21:59 battery power: 12W
[site  ] DEBUG 2023/11/30 13:21:59 grid power: 320W
[site  ] DEBUG 2023/11/30 13:21:59 site power: 532W
[lp-1  ] DEBUG 2023/11/30 13:21:59 charge currents: [0 0 0]A
[lp-1  ] DEBUG 2023/11/30 13:21:59 charge total import: 672.043kWh
[lp-1  ] DEBUG 2023/11/30 13:21:59 charger status: B
[lp-1  ] DEBUG 2023/11/30 13:21:59 !! scalePhasesIfAvailable: 3p -> 3p
[lp-1  ] DEBUG 2023/11/30 13:21:59 !! scalePhases: GetPhases 3p <> 3p wanted
[site  ] DEBUG 2023/11/30 13:22:09 ----
[lp-1  ] DEBUG 2023/11/30 13:22:09 charge power: 0W
[site  ] DEBUG 2023/11/30 13:22:09 pv power: 41W
[site  ] DEBUG 2023/11/30 13:22:09 battery soc: 23%
[site  ] DEBUG 2023/11/30 13:22:09 battery power: 6W
[site  ] DEBUG 2023/11/30 13:22:09 grid power: 330W
[site  ] DEBUG 2023/11/30 13:22:09 site power: 536W
[lp-1  ] DEBUG 2023/11/30 13:22:09 charge currents: [0 0 0]A
[lp-1  ] DEBUG 2023/11/30 13:22:09 charge total import: 672.043kWh
[lp-1  ] DEBUG 2023/11/30 13:22:09 charger status: B
[lp-1  ] DEBUG 2023/11/30 13:22:09 !! scalePhasesIfAvailable: 3p -> 3p
[lp-1  ] DEBUG 2023/11/30 13:22:09 !! scalePhases: GetPhases 3p <> 3p wanted
[site  ] DEBUG 2023/11/30 13:22:19 ----
[lp-1  ] DEBUG 2023/11/30 13:22:19 charge power: 0W
[site  ] DEBUG 2023/11/30 13:22:19 pv power: 41W
[site  ] DEBUG 2023/11/30 13:22:19 battery soc: 23%
[site  ] DEBUG 2023/11/30 13:22:19 battery power: 12W
[site  ] DEBUG 2023/11/30 13:22:19 grid power: 321W
[site  ] DEBUG 2023/11/30 13:22:19 site power: 533W
[lp-1  ] DEBUG 2023/11/30 13:22:19 charge currents: [0 0 0]A
[lp-1  ] DEBUG 2023/11/30 13:22:19 charge total import: 672.043kWh
[lp-1  ] DEBUG 2023/11/30 13:22:19 charger status: B
[lp-1  ] DEBUG 2023/11/30 13:22:19 !! scalePhasesIfAvailable: 3p -> 3p
[lp-1  ] DEBUG 2023/11/30 13:22:19 !! scalePhases: GetPhases 3p <> 3p wanted
[site  ] DEBUG 2023/11/30 13:22:29 ----
[lp-1  ] DEBUG 2023/11/30 13:22:29 charge power: 0W
[site  ] DEBUG 2023/11/30 13:22:29 pv power: 44W
[site  ] DEBUG 2023/11/30 13:22:29 battery soc: 23%
[site  ] DEBUG 2023/11/30 13:22:29 battery power: 6W
[site  ] DEBUG 2023/11/30 13:22:29 grid power: 322W
[site  ] DEBUG 2023/11/30 13:22:29 site power: 528W
[lp-1  ] DEBUG 2023/11/30 13:22:29 charge currents: [0 0 0]A
[lp-1  ] DEBUG 2023/11/30 13:22:29 charge total import: 672.043kWh
[lp-1  ] DEBUG 2023/11/30 13:22:29 charger status: B
[lp-1  ] DEBUG 2023/11/30 13:22:29 !! scalePhasesIfAvailable: 3p -> 3p
[lp-1  ] DEBUG 2023/11/30 13:22:29 !! scalePhases: GetPhases 3p <> 3p wanted
[lp-1  ] DEBUG 2023/11/30 13:22:29 wake-up vehicle
[lp-1  ] ERROR 2023/11/30 13:22:30 wake-up vehicle: unexpected status: 500 (Internal Server Error)
[site  ] DEBUG 2023/11/30 13:22:39 ----
[lp-1  ] DEBUG 2023/11/30 13:22:39 charge power: 0W
[site  ] DEBUG 2023/11/30 13:22:39 pv power: 41W
[site  ] DEBUG 2023/11/30 13:22:39 battery soc: 23%
[site  ] DEBUG 2023/11/30 13:22:39 battery power: 18W
[site  ] DEBUG 2023/11/30 13:22:39 grid power: 317W
[site  ] DEBUG 2023/11/30 13:22:39 site power: 535W
[lp-1  ] DEBUG 2023/11/30 13:22:39 charge currents: [0 0 0]A
[lp-1  ] DEBUG 2023/11/30 13:22:39 charge total import: 672.043kWh
[lp-1  ] DEBUG 2023/11/30 13:22:39 charger status: B
[lp-1  ] DEBUG 2023/11/30 13:22:39 !! scalePhasesIfAvailable: 3p -> 3p
[lp-1  ] DEBUG 2023/11/30 13:22:39 !! scalePhases: GetPhases 3p <> 3p wanted

Via Renault App Laden gestartet

[lp-1  ] DEBUG 2023/11/30 13:24:59 charge power: 0W
[site  ] DEBUG 2023/11/30 13:24:59 pv power: 41W
[site  ] DEBUG 2023/11/30 13:24:59 battery soc: 23%
[site  ] DEBUG 2023/11/30 13:24:59 battery power: -3W
[site  ] DEBUG 2023/11/30 13:25:00 grid power: 319W
[site  ] DEBUG 2023/11/30 13:25:00 battery has priority at soc 23% (< 65%)
[site  ] DEBUG 2023/11/30 13:25:00 site power: 519W
[lp-1  ] DEBUG 2023/11/30 13:25:00 charge currents: [0 0 0]A
[lp-1  ] DEBUG 2023/11/30 13:25:00 charge total import: 672.043kWh
[lp-1  ] DEBUG 2023/11/30 13:25:00 charger status: B
[lp-1  ] DEBUG 2023/11/30 13:25:00 !! scalePhasesIfAvailable: 3p -> 3p
[lp-1  ] DEBUG 2023/11/30 13:25:00 !! scalePhases: GetPhases 3p <> 3p wanted
[site  ] DEBUG 2023/11/30 13:25:09 ----
[lp-1  ] DEBUG 2023/11/30 13:25:09 charge power: 9550W
[site  ] DEBUG 2023/11/30 13:25:09 pv power: 41W
[site  ] DEBUG 2023/11/30 13:25:09 battery soc: 23%
[site  ] DEBUG 2023/11/30 13:25:09 battery power: 12W
[site  ] DEBUG 2023/11/30 13:25:09 grid power: 10361W
[site  ] DEBUG 2023/11/30 13:25:09 site power: 10573W
[lp-1  ] DEBUG 2023/11/30 13:25:09 charge currents: [15.1 15.3 15.3]A
[lp-1  ] DEBUG 2023/11/30 13:25:09 charge total import: 672.050kWh
[lp-1  ] DEBUG 2023/11/30 13:25:09 charger status: C
[lp-1  ] INFO 2023/11/30 13:25:09 start charging ->
[lp-1  ] DEBUG 2023/11/30 13:25:09 wake-up timer: stop
[lp-1  ] DEBUG 2023/11/30 13:25:10 soc estimated: 39.03% (vehicle: 39.00%)
[lp-1  ] DEBUG 2023/11/30 13:25:10 vehicle soc: 39%
[lp-1  ] DEBUG 2023/11/30 13:25:10 vehicle range: 57km
[lp-1  ] DEBUG 2023/11/30 13:25:10 !! scalePhasesIfAvailable: 3p -> 3p
[lp-1  ] DEBUG 2023/11/30 13:25:10 !! scalePhases: GetPhases 3p <> 3p wanted
[site  ] DEBUG 2023/11/30 13:25:19 ----
[lp-1  ] DEBUG 2023/11/30 13:25:19 charge power: 9561W
[site  ] DEBUG 2023/11/30 13:25:19 pv power: 44W
[site  ] DEBUG 2023/11/30 13:25:19 battery soc: 23%
[site  ] DEBUG 2023/11/30 13:25:19 battery power: 6W
[site  ] DEBUG 2023/11/30 13:25:19 grid power: 10360W
[site  ] DEBUG 2023/11/30 13:25:19 site power: 10566W
[lp-1  ] DEBUG 2023/11/30 13:25:19 charge currents: [15.1 15.3 15.3]A
[lp-1  ] DEBUG 2023/11/30 13:25:19 detected active phases: 3p
[lp-1  ] DEBUG 2023/11/30 13:25:19 charge total import: 672.077kWh
[lp-1  ] DEBUG 2023/11/30 13:25:19 charger status: C
[lp-1  ] DEBUG 2023/11/30 13:25:19 soc estimated: 39.14% (vehicle: 39.00%)
[lp-1  ] DEBUG 2023/11/30 13:25:19 vehicle soc: 39%
[lp-1  ] DEBUG 2023/11/30 13:25:19 vehicle range: 57km
[lp-1  ] DEBUG 2023/11/30 13:25:19 !! scalePhasesIfAvailable: 3p -> 3p
[lp-1  ] DEBUG 2023/11/30 13:25:19 !! scalePhases: GetPhases 3p <> 3p wanted

What type of operating system are you running?

HomeAssistant Add-on

Version

0.122.1

andig commented 9 months ago

[lp-1 ] ERROR 2023/11/30 13:22:30 wake-up vehicle: unexpected status: 500 (Internal Server Error)

Es braucht ein trace log des Renault und Zugangsdaten für info@evcc.io. Mit Go-E hat das nichts zu tun.

kwitt21 commented 9 months ago

[lp-1 ] ERROR 2023/11/30 13:22:30 wake-up vehicle: unexpected status: 500 (Internal Server Error)

Es braucht ein trace log des Renault und Zugangsdaten für info@evcc.io. Mit Go-E hat das nichts zu tun.

Heisst, ich müsste den Log Level in EVCC auf "TRACE" stellen und das Problem reproduzieren?

Das ist leider quasi nicht möglich, da bei mir EVCC als Home Assistant Add On läuft und ich nur Zugriff auf die letzten (etwa 100?) Zeilen im "Protokoll" Fester habe. Ich habe dazu auch schon einen Eintrag im "evcc-io/hassio-addon" Bereich bei Euch gemacht.

andig commented 9 months ago

…einfach ohne HA erzeugen…

andig commented 9 months ago

@kwitt21 Dein Log ist in der Tat interessant:

2023/12/12 18:26:03 POST https://api-wired-prod-1-euw1.wrd-aws.com/commerce/v1/accounts/***/kamereon/kcm/v1/vehicles/***/charge/pause-resume?country=DE
2023/12/12 18:26:04 {"data":{"attributes":{"action":"resume"},"type":"ChargePauseResume"}}
--
{"type":"FUNCTIONAL","messages":[{"code":"err.func.wired.unauthorized","message":"The access is unauthorized"}],"errors":[{"errorCode":"err.func.wired.unauthorized","errorMessage":"The access is unauthorized"}],"error_reference":"FUNCTIONAL"}

Der POST Request scheint mangels gültigem Login fehlzuschlagen. Das ist, ok, Login wird dann nachgeholt.

2023/12/12 18:26:04 GET https://api-wired-prod-1-euw1.wrd-aws.com/commerce/v1/accounts/***/kamereon/kcm/v1/vehicles/***/charge/pause-resume?country=DE
2023/12/12 18:26:04 {"type":"TECHNICAL","messages":[{"code":"err.tech.500","message":"{\"errors\":[{\"status\":\"Internal Server Error\",\"code\":\"500001\",\"title\":\"Unexpected Error\",\"detail\":\"An error occurred on the server: Message - Error calling car-adapter - message: 502 Bad Gateway\",\"meta\":{\"spanId\":\"7aa6101fef932481\",\"traceId\":\"51265a2976a94ace7aa6101fef932481\",\"parentSpanId\":\"null\",\"component\":\"aic-se-chargemanager-prod\"}}]}"}],"errors":[{"errorCode":"err.tech.500","errorMessage":"{\"errors\":[{\"status\":\"Internal Server Error\",\"code\":\"500001\",\"title\":\"Unexpected Error\",\"detail\":\"An error occurred on the server: Message - Error calling car-adapter - message: 502 Bad Gateway\",\"meta\":{\"spanId\":\"7aa6101fef932481\",\"traceId\":\"51265a2976a94ace7aa6101fef932481\",\"parentSpanId\":\"null\",\"component\":\"aic-se-chargemanager-prod\"}}]}"}],"error_reference":"TECHNICAL"}

Dieser Request jetzt ist aber ein GET Request, der dann auch failed. Warum hier überhaupt ein GET ausgeführt wird ist unklar.