evcc icon indicating copy to clipboard operation
evcc copied to clipboard

Published 20 hours ago • verified publisher icon evcc-io

EN+: "Preparing" timeout before RemoteStartTransaction could be sent on long intervals

Open jeffborg opened this issue 6 months ago • 6 comments

Describe the bug

evcc is now unworkable when your ocpp evse decides to jump to finishing status upon plugging in

Prior to 0.130.0 evcc was quite happy to break ocpp spec and jump from Finishing back to SuspendedEVSE state (IE tell the evse to start charging!)

This happens even if the mode is set to min + solar or it's off (no solar) - I spent almost 1/2 hour trying to evcc into a working state this morning!

Only way to get going now seems to be to restart both the evse & evcc & unplug replug car! & make sure evcc is in min+solar or fast mode before plugging the car in! And not do this too quickly either otherwise evcc crashed see

[ocpp  ] TRACE 2024/08/28 08:23:02 send SN10052307203612: [2,"1810363461","ChangeConfiguration",{"key":"WebSocketPingInterval","value":"30"}]
[ocpp  ] TRACE 2024/08/28 08:23:02 recv SN10052307203612: [3,"1810363461",{"status":"NotSupported"}]
panic: send on closed channel

goroutine 52 [running]:
github.com/evcc-io/evcc/charger.(*OCPP).configure.func1(0x0?, {0x0, 0x0})
	github.com/evcc-io/evcc/charger/ocpp.go:375 +0xc0
github.com/lorenzodonini/ocpp-go/ocpp1%2e6.(*centralSystem).ChangeConfiguration.func1({0x344b480?, 0x40014a63b0?}, {0x0?, 0x0?})
	github.com/lorenzodonini/[email protected]/ocpp1.6/central_system.go:78 +0x54
created by github.com/lorenzodonini/ocpp-go/ocpp1%2e6.(*centralSystem).handleIncomingConfirmation in goroutine 87
	github.com/lorenzodonini/[email protected]/ocpp1.6/central_system.go:545 +0xc8

Note this evse can't be set to free vend mode as this disables ocpp!

I have tried other combos to try and get going

  • unplug replug car with evcc enabled for charging - no go ends in finishing state
  • unplug car, turn off evse, turn on evse, plug car in no go ends in finishing state
  • restart evcc in enabled mode - doesn't even boot up timeout for ocpp configure

relying upon vendors to fix issues is really a non starter, my only real option is evcc isn't fixed is to implement ocpp in node red and just connect this to evcc.

Steps to reproduce

  1. unplug car
  2. plug car back in
  3. evcc still wants to unplug and plug car back in
  4. jump to 1 evcc still wants to unplug and replug car in!

Configuration details

chargers:
  - name: solax
    type: template
    template: ocpp
    timeout: 2m
    # added for 0.130.0
    remotestart: true
    # commented out 19/8 for 0.130.0 update from 0.129.0
    # getconfiguration: false
    # metervalues: Energy.Active.Import.Register,Power.Active.Import,Current.Import
    # bootnotification: false
    # meterinterval: 10s

Log details

[ocpp  ] DEBUG 2024/08/28 08:07:55 charge point connected: SN10052307203612
[ocpp  ] TRACE 2024/08/28 08:07:57 send SN10052307203612: [2,"56388924","TriggerMessage",{"requestedMessage":"MeterValues","connectorId":1}]
[ocpp  ] TRACE 2024/08/28 08:07:57 recv SN10052307203612: [3,"56388924",{"status":"Accepted"}]
[site  ] DEBUG 2024/08/28 08:07:58 ----
[lp-1  ] DEBUG 2024/08/28 08:07:58 charge power: 0W
[lp-1  ] DEBUG 2024/08/28 08:07:58 charge currents: [0 0 0]A
[circuit-main] DEBUG 2024/08/28 08:07:58 power: 558.75W
[circuit-main] DEBUG 2024/08/28 08:07:58 current: 0A
[site  ] DEBUG 2024/08/28 08:07:58 pv power: 807W
[site  ] DEBUG 2024/08/28 08:07:58 grid meter: 559W
[site  ] DEBUG 2024/08/28 08:07:58 site power: 559W
[lp-1  ] DEBUG 2024/08/28 08:07:58 vehicle odometer: 81195km
[lp-1  ] DEBUG 2024/08/28 08:07:58 charge voltages: [244 0 0]V
[lp-1  ] DEBUG 2024/08/28 08:07:58 detected connected phases: 1p
[lp-1  ] DEBUG 2024/08/28 08:07:58 charge total import: 0.000kWh
[lp-1  ] DEBUG 2024/08/28 08:07:58 charger status: A
[ocpp  ] TRACE 2024/08/28 08:07:58 send SN10052307203612: [2,"4288998214","SetChargingProfile",{"connectorId":1,"csChargingProfiles":{"chargingProfileId":3,"stackLevel":5,"chargingProfilePurpose":"TxDefaultProfile","chargingProfileKind":"Absolute","chargingSchedule":{"startSchedule":"2024-08-27T22:07:58Z","chargingRateUnit":"A","chargingSchedulePeriod":[{"startPeriod":0,"limit":0}]}}}]
[ocpp  ] TRACE 2024/08/28 08:07:59 recv SN10052307203612: [3,"4288998214",{"status":"Accepted"}]
[lp-1  ] DEBUG 2024/08/28 08:07:59 charger disable
[ocpp  ] TRACE 2024/08/28 08:07:59 send SN10052307203612: [2,"3105039279","TriggerMessage",{"requestedMessage":"MeterValues","connectorId":1}]
[lp-1  ] DEBUG 2024/08/28 08:07:59 wake-up timer: stop
[ocpp  ] TRACE 2024/08/28 08:08:00 recv SN10052307203612: [3,"3105039279",{"status":"Accepted"}]
[ocpp  ] TRACE 2024/08/28 08:08:01 send SN10052307203612: [2,"1765718411","TriggerMessage",{"requestedMessage":"MeterValues","connectorId":1}]
[ocpp  ] TRACE 2024/08/28 08:08:01 recv SN10052307203612: [3,"1765718411",{"status":"Accepted"}]
[ocpp  ] TRACE 2024/08/28 08:08:03 send SN10052307203612: [2,"3251360294","TriggerMessage",{"requestedMessage":"MeterValues","connectorId":1}]
[ocpp  ] TRACE 2024/08/28 08:08:04 recv SN10052307203612: [2,"4","BootNotification",{"chargePointModel":"23","chargePointSerialNumber":"SN10052307203612","chargePointVendor":"EN+","firmwareVersion":"1.3.53"}]
[ocpp  ] TRACE 2024/08/28 08:08:04 recv SN10052307203612: [3,"3251360294",{"status":"Accepted"}]
[ocpp  ] TRACE 2024/08/28 08:08:04 send SN10052307203612: [3,"4",{"currentTime":"2024-08-27T22:08:04Z","interval":60,"status":"Accepted"}]
[ocpp  ] TRACE 2024/08/28 08:08:05 send SN10052307203612: [2,"2984233680","TriggerMessage",{"requestedMessage":"MeterValues","connectorId":1}]
[ocpp  ] TRACE 2024/08/28 08:08:05 recv SN10052307203612: [2,"6","DataTransfer",{"vendorId":"EN+","messageId":"gatewayInfo","data":"{\"SN\":\"SN10052307203612\",\"fwVer\":\"V43.0.552\",\"gateCode\":107,\"measureType\":1,\"disconnectReason\":0,\"maxCurr\":320,\"phase\":1,\"sdCardStatus\":0}"}]
[ocpp  ] TRACE 2024/08/28 08:08:05 recv SN10052307203612: [2,"offline-5","MeterValues",{"connectorId":1,"meterValue":[{"timestamp":"1970-01-01T00:00:32Z","sampledValue":[{"measurand":"Current.Offered","unit":"A","value":"32.0","context":"Trigger"},{"measurand":"Current.Import","unit":"A","phase":"L1","value":"0.0"},{"measurand":"Voltage","unit":"V","phase":"L1","value":"0.0","context":"Trigger"},{"measurand":"Energy.Active.Import.Register","unit":"Wh","value":"0.0","context":"Trigger"},{"measurand":"Power.Active.Import","unit":"W","value":"0.0","context":"Trigger"}]}]}]
[ocpp  ] TRACE 2024/08/28 08:08:05 send SN10052307203612: [3,"6",{"status":"Accepted"}]
[ocpp  ] TRACE 2024/08/28 08:08:05 send SN10052307203612: [3,"offline-5",{}]
[ocpp  ] TRACE 2024/08/28 08:08:05 recv SN10052307203612: [2,"7","StatusNotification",{"connectorId":0,"status":"Available","errorCode":"NoError","timestamp":"2024-08-27T22:08:01Z","vendorId":"EN+","info":"{\"reason\":\"None\",\"cpv\":0,\"rv\":0}"}]
[ocpp  ] TRACE 2024/08/28 08:08:05 send SN10052307203612: [3,"7",{}]
[ocpp  ] TRACE 2024/08/28 08:08:06 recv SN10052307203612: [3,"2984233680",{"status":"Accepted"}]
[ocpp  ] TRACE 2024/08/28 08:08:06 recv SN10052307203612: [2,"8","MeterValues",{"connectorId":1,"meterValue":[{"timestamp":"2024-08-27T22:08:04Z","sampledValue":[{"measurand":"Current.Offered","unit":"A","value":"32.0","context":"Trigger"},{"measurand":"Current.Import","unit":"A","phase":"L1","value":"0.0"},{"measurand":"Voltage","unit":"V","phase":"L1","value":"245.3","context":"Trigger"},{"measurand":"Energy.Active.Import.Register","unit":"Wh","value":"0.0","context":"Trigger"},{"measurand":"Power.Active.Import","unit":"W","value":"0.0","context":"Trigger"}]}]}]
[ocpp  ] TRACE 2024/08/28 08:08:06 send SN10052307203612: [3,"8",{}]
[ocpp  ] TRACE 2024/08/28 08:08:06 recv SN10052307203612: [2,"9","StatusNotification",{"connectorId":1,"status":"Available","errorCode":"NoError","timestamp":"2024-08-27T22:08:01Z","vendorId":"EN+","info":"{\"reason\":\"None\",\"cpv\":0,\"rv\":0}"}]
[ocpp  ] TRACE 2024/08/28 08:08:06 recv SN10052307203612: [2,"10","Heartbeat",{}]
[ocpp  ] TRACE 2024/08/28 08:08:06 send SN10052307203612: [3,"10",{"currentTime":"2024-08-27T22:08:06Z"}]
[ocpp  ] TRACE 2024/08/28 08:08:06 send SN10052307203612: [3,"9",{}]
[ocpp  ] TRACE 2024/08/28 08:08:15 send SN10052307203612: [2,"1441389827","TriggerMessage",{"requestedMessage":"MeterValues","connectorId":1}]
[ocpp  ] TRACE 2024/08/28 08:08:15 recv SN10052307203612: [3,"1441389827",{"status":"Accepted"}]
[ocpp  ] TRACE 2024/08/28 08:08:15 recv SN10052307203612: [2,"11","MeterValues",{"connectorId":1,"meterValue":[{"timestamp":"2024-08-27T22:08:14Z","sampledValue":[{"measurand":"Current.Offered","unit":"A","value":"32.0","context":"Trigger"},{"measurand":"Current.Import","unit":"A","phase":"L1","value":"0.0"},{"measurand":"Voltage","unit":"V","phase":"L1","value":"245.3","context":"Trigger"},{"measurand":"Energy.Active.Import.Register","unit":"Wh","value":"0.0","context":"Trigger"},{"measurand":"Power.Active.Import","unit":"W","value":"0.0","context":"Trigger"}]}]}]
[ocpp  ] TRACE 2024/08/28 08:08:15 send SN10052307203612: [3,"11",{}]
[ocpp  ] TRACE 2024/08/28 08:08:25 send SN10052307203612: [2,"4084174118","TriggerMessage",{"requestedMessage":"MeterValues","connectorId":1}]
[ocpp  ] TRACE 2024/08/28 08:08:25 recv SN10052307203612: [3,"4084174118",{"status":"Accepted"}]
[ocpp  ] TRACE 2024/08/28 08:08:26 recv SN10052307203612: [2,"12","MeterValues",{"connectorId":1,"meterValue":[{"timestamp":"2024-08-27T22:08:24Z","sampledValue":[{"measurand":"Current.Offered","unit":"A","value":"32.0","context":"Trigger"},{"measurand":"Current.Import","unit":"A","phase":"L1","value":"0.0"},{"measurand":"Voltage","unit":"V","phase":"L1","value":"245.3","context":"Trigger"},{"measurand":"Energy.Active.Import.Register","unit":"Wh","value":"0.0","context":"Trigger"},{"measurand":"Power.Active.Import","unit":"W","value":"0.0","context":"Trigger"}]}]}]
[ocpp  ] TRACE 2024/08/28 08:08:26 send SN10052307203612: [3,"12",{}]
[site  ] DEBUG 2024/08/28 08:08:28 ----
[lp-1  ] DEBUG 2024/08/28 08:08:28 charge power: 0W
[lp-1  ] DEBUG 2024/08/28 08:08:28 charge currents: [0 0 0]A
[circuit-main] DEBUG 2024/08/28 08:08:28 power: 559.51W
[circuit-main] DEBUG 2024/08/28 08:08:28 current: 0A
[site  ] DEBUG 2024/08/28 08:08:28 pv power: 835W
[site  ] DEBUG 2024/08/28 08:08:28 grid meter: 560W
[site  ] DEBUG 2024/08/28 08:08:28 site power: 560W
[lp-1  ] DEBUG 2024/08/28 08:08:28 charge voltages: [245 0 0]V
[lp-1  ] DEBUG 2024/08/28 08:08:28 detected connected phases: 1p
[lp-1  ] DEBUG 2024/08/28 08:08:28 charge total import: 0.000kWh
[lp-1  ] DEBUG 2024/08/28 08:08:28 charger status: A
[ocpp  ] TRACE 2024/08/28 08:08:35 send SN10052307203612: [2,"2212275582","TriggerMessage",{"requestedMessage":"MeterValues","connectorId":1}]
[ocpp  ] TRACE 2024/08/28 08:08:35 recv SN10052307203612: [2,"13","DataTransfer",{"vendorId":"EN+","messageId":"cpChargingParameterRpt","data":"{\"duty\":0,\"cpVolt\":931,\"transactionId\":0,\"totalPowerFactor\":256,\"aPhasesPowerFactor\":0,\"bPhasesPowerFactor\":6,\"cPhasesPowerFactor\":0,\"ccVolt\":256,\"offset0\":2012,\"offset1\":2017,\"leakcurr\":0,\"AMBTemp\":247,\"lockStatus\":1,\"ctCurrent\":9}"}]
[ocpp  ] TRACE 2024/08/28 08:08:35 send SN10052307203612: [3,"13",{"status":"Accepted"}]
[ocpp  ] TRACE 2024/08/28 08:08:36 recv SN10052307203612: [3,"2212275582",{"status":"Accepted"}]
[ocpp  ] TRACE 2024/08/28 08:08:36 recv SN10052307203612: [2,"14","MeterValues",{"connectorId":1,"meterValue":[{"timestamp":"2024-08-27T22:08:34Z","sampledValue":[{"measurand":"Current.Offered","unit":"A","value":"32.0","context":"Trigger"},{"measurand":"Current.Import","unit":"A","phase":"L1","value":"0.0"},{"measurand":"Voltage","unit":"V","phase":"L1","value":"245.3","context":"Trigger"},{"measurand":"Energy.Active.Import.Register","unit":"Wh","value":"0.0","context":"Trigger"},{"measurand":"Power.Active.Import","unit":"W","value":"0.0","context":"Trigger"}]}]}]
[ocpp  ] TRACE 2024/08/28 08:08:36 send SN10052307203612: [3,"14",{}]
[ocpp  ] TRACE 2024/08/28 08:08:36 recv SN10052307203612: [2,"15","StatusNotification",{"connectorId":1,"status":"Preparing","errorCode":"NoError","timestamp":"2024-08-27T22:08:33Z","vendorId":"EN+","info":"{\"reason\":\"plugInGun\",\"cpv\":0,\"rv\":0}"}]
[ocpp  ] TRACE 2024/08/28 08:08:36 send SN10052307203612: [3,"15",{}]
[ocpp  ] TRACE 2024/08/28 08:08:45 send SN10052307203612: [2,"3545938426","TriggerMessage",{"requestedMessage":"MeterValues","connectorId":1}]
[ocpp  ] TRACE 2024/08/28 08:08:45 recv SN10052307203612: [3,"3545938426",{"status":"Accepted"}]
[ocpp  ] TRACE 2024/08/28 08:08:46 recv SN10052307203612: [2,"16","MeterValues",{"connectorId":1,"meterValue":[{"timestamp":"2024-08-27T22:08:44Z","sampledValue":[{"measurand":"Current.Offered","unit":"A","value":"32.0","context":"Trigger"},{"measurand":"Current.Import","unit":"A","phase":"L1","value":"0.0"},{"measurand":"Voltage","unit":"V","phase":"L1","value":"245.3","context":"Trigger"},{"measurand":"Energy.Active.Import.Register","unit":"Wh","value":"0.0","context":"Trigger"},{"measurand":"Power.Active.Import","unit":"W","value":"0.0","context":"Trigger"}]}]}]
[ocpp  ] TRACE 2024/08/28 08:08:46 send SN10052307203612: [3,"16",{}]
[ocpp  ] TRACE 2024/08/28 08:08:55 send SN10052307203612: [2,"1627595517","TriggerMessage",{"requestedMessage":"MeterValues","connectorId":1}]
[ocpp  ] TRACE 2024/08/28 08:08:55 recv SN10052307203612: [3,"1627595517",{"status":"Accepted"}]
[ocpp  ] TRACE 2024/08/28 08:08:56 recv SN10052307203612: [2,"17","MeterValues",{"connectorId":1,"meterValue":[{"timestamp":"2024-08-27T22:08:54Z","sampledValue":[{"measurand":"Current.Offered","unit":"A","value":"32.0","context":"Trigger"},{"measurand":"Current.Import","unit":"A","phase":"L1","value":"0.0"},{"measurand":"Voltage","unit":"V","phase":"L1","value":"245.3","context":"Trigger"},{"measurand":"Energy.Active.Import.Register","unit":"Wh","value":"0.0","context":"Trigger"},{"measurand":"Power.Active.Import","unit":"W","value":"0.0","context":"Trigger"}]}]}]
[ocpp  ] TRACE 2024/08/28 08:08:56 send SN10052307203612: [3,"17",{}]
[site  ] DEBUG 2024/08/28 08:08:58 ----
[lp-1  ] DEBUG 2024/08/28 08:08:58 charge power: 0W
[lp-1  ] DEBUG 2024/08/28 08:08:58 charge currents: [0 0 0]A
[circuit-main] DEBUG 2024/08/28 08:08:58 power: 496.48W
[circuit-main] DEBUG 2024/08/28 08:08:58 current: 0A
[site  ] DEBUG 2024/08/28 08:08:58 pv power: 841W
[site  ] DEBUG 2024/08/28 08:08:58 grid meter: 496W
[site  ] DEBUG 2024/08/28 08:08:58 site power: 496W
[lp-1  ] DEBUG 2024/08/28 08:08:58 charge voltages: [245 0 0]V
[lp-1  ] DEBUG 2024/08/28 08:08:58 detected connected phases: 1p
[lp-1  ] DEBUG 2024/08/28 08:08:58 charge total import: 0.000kWh
[lp-1  ] DEBUG 2024/08/28 08:08:58 charger status: B
[lp-1  ] DEBUG 2024/08/28 08:08:58 charge start energy: 0.000kWh
[lp-1  ] INFO 2024/08/28 08:08:58 car connected
[lp-1  ] DEBUG 2024/08/28 08:08:58 pv timer elapse
[lp-1  ] DEBUG 2024/08/28 08:08:58 pv timer inactive
[lp-1  ] DEBUG 2024/08/28 08:08:58 charge total import: 0.000kWh
[lp-1  ] DEBUG 2024/08/28 08:08:58 charger vehicle id: evcc
[lp-1  ] DEBUG 2024/08/28 08:08:58 vehicle status: A
[lp-1  ] DEBUG 2024/08/28 08:08:58 vehicle soc: 83%
[lp-1  ] DEBUG 2024/08/28 08:08:58 vehicle range: 335km
[lp-1  ] DEBUG 2024/08/28 08:08:58 pv charge current: 0A = 0A + -2.16A (496W @ 1p)
[lp-1  ] DEBUG 2024/08/28 08:08:58 pv enable timer reset
[lp-1  ] DEBUG 2024/08/28 08:08:58 pv timer inactive
[ocpp  ] TRACE 2024/08/28 08:09:04 recv SN10052307203612: [2,"18","Heartbeat",{}]
[ocpp  ] TRACE 2024/08/28 08:09:04 send SN10052307203612: [3,"18",{"currentTime":"2024-08-27T22:09:04Z"}]
[ocpp  ] TRACE 2024/08/28 08:09:05 send SN10052307203612: [2,"3269614396","TriggerMessage",{"requestedMessage":"MeterValues","connectorId":1}]
[ocpp  ] TRACE 2024/08/28 08:09:05 recv SN10052307203612: [3,"3269614396",{"status":"Accepted"}]
[ocpp  ] TRACE 2024/08/28 08:09:05 recv SN10052307203612: [2,"19","MeterValues",{"connectorId":1,"meterValue":[{"timestamp":"2024-08-27T22:09:04Z","sampledValue":[{"measurand":"Current.Offered","unit":"A","value":"32.0","context":"Trigger"},{"measurand":"Current.Import","unit":"A","phase":"L1","value":"0.0"},{"measurand":"Voltage","unit":"V","phase":"L1","value":"245.3","context":"Trigger"},{"measurand":"Energy.Active.Import.Register","unit":"Wh","value":"0.0","context":"Trigger"},{"measurand":"Power.Active.Import","unit":"W","value":"0.0","context":"Trigger"}]}]}]
[ocpp  ] TRACE 2024/08/28 08:09:05 send SN10052307203612: [3,"19",{}]
[ocpp  ] TRACE 2024/08/28 08:09:06 recv SN10052307203612: [2,"20","StatusNotification",{"connectorId":1,"status":"Finishing","errorCode":"NoError","timestamp":"2024-08-27T22:09:03Z","vendorId":"EN+","info":"{\"reason\":\"plugInGun\",\"cpv\":0,\"rv\":0}"}]
[ocpp  ] TRACE 2024/08/28 08:09:06 send SN10052307203612: [3,"20",{}]

What type of operating system are you running?

Linux

Version

0.130.6

jeffborg avatar Aug 27 '24 22:08 jeffborg