Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Ocpp: autostart without remotestop #14804

Closed
andig opened this issue Jul 9, 2024 · 55 comments · Fixed by #14824 or #15371
Closed

Ocpp: autostart without remotestop #14804

andig opened this issue Jul 9, 2024 · 55 comments · Fixed by #14824 or #15371
Assignees
Labels
bug Something isn't working devices Specific device support

Comments

@andig
Copy link
Member

andig commented Jul 9, 2024

Is there any way of having some middle ground between the default behaviour (transaction per charging session) and the autoStart behaviour in #14733 ? My EVSE (ZJ Beny) will not auto start, and if an RFID card is used to start the transaction it will then ignore OCPP altogether and charge at full rate. It does need to keep a single transaction, as if one is stopped it will not allow a new one to start until the car is physically disconnected.

Originally posted by @ross-w in #12861 (comment)

@andig
Copy link
Member Author

andig commented Jul 9, 2024

I just have to cry when I read about the plethora of ocpp quirks. What we could do:

  • add nostop
  • localstart implies nostop and is equivalent to not using remotestart or remotestop
  • nostop standalone is equivalant to using remotestart, but not remotestop

@andig andig added the devices Specific device support label Jul 9, 2024
@andig andig changed the title Ocpp: localstart without localstop Ocpp: autostart without remotestop Jul 9, 2024
@andig
Copy link
Member Author

andig commented Jul 10, 2024

@ross-w could you give #14824 a try? Totally untested.

@ross-w
Copy link
Contributor

ross-w commented Jul 11, 2024

@andig thanks heaps for this.

Am I missing something here? I am building from the branch feat/ocpp-nostop, however if I specify my charger like this:

chargers:
  - name: zjbeny
    type: template
    template: ocpp
    stationid: zjb
    getconfiguration: false
    timeout: 2m
    nostop: true

I get the following error on startup:

[main  ] FATAL 2024/07/11 20:13:51 cannot create charger 'zjbeny': cannot create charger type 'template': invalid key: nostop

Build is

[main  ] INFO 2024/07/11 20:14:35 evcc 0.128.2 (7e99a843)

@ross-w
Copy link
Contributor

ross-w commented Jul 11, 2024

Ah, I worked it out. I needed to add

  - name: nostop
    advanced: true
    type: bool

to templates/definition/charger/ocpp.yaml

Unfortunately with the above configuration it will still stop the transaction when charging is set to off:

[ocpp  ] TRACE 2024/07/11 20:39:24 recv zjb: [2,"ynb2s8y895n3fyi9s6ibpdy8","StatusNotification",{"connectorId":1,"errorCode":"NoError","status":"Finishing","timestamp":"2024-07-11T10:39:23Z"}]
[ocpp  ] TRACE 2024/07/11 20:39:24 sent zjb: [3,"ynb2s8y895n3fyi9s6ibpdy8",{}]
[ocpp  ] TRACE 2024/07/11 20:39:25 recv zjb: [2,"bue28hyt0lkni5k4uaeiv108","StopTransaction",{"idTag":"evcc","meterStop":519258,"timestamp":"2024-07-11T10:39:24Z","transactionId":1,"reason":"Remote"}]
[ocpp  ] TRACE 2024/07/11 20:39:25 sent zjb: [3,"bue28hyt0lkni5k4uaeiv108",{"idTagInfo":{"status":"Accepted"}}]

@andig
Copy link
Member Author

andig commented Jul 11, 2024

it will still stop the transaction

Who is "it"? What happens before?

@ross-w

This comment was marked as resolved.

@andig
Copy link
Member Author

andig commented Jul 11, 2024

And what's your config? Make sure to test latest commit (or use type: ocpp). #14804 (comment) is not sufficient.

@ross-w
Copy link
Contributor

ross-w commented Jul 11, 2024

Ah, you've added a new commit. I've just rebuilt with b2c8ecd.

Unfortunately, same results. Config:

chargers:
  - name: zjbeny
    type: template
    template: ocpp
    stationid: zjb
    getconfiguration: false
    timeout: 2m
    nostop: true

@ross-w
Copy link
Contributor

ross-w commented Jul 11, 2024

1000 apologies @andig !! It does work!

I had neglected to kill the old running binary before running the latest test

@ross-w
Copy link
Contributor

ross-w commented Jul 11, 2024

I can confirm that with b2c8ecd I am able to stop and start charging again. There is however a bit of a glitch.

Using the following sequence:

  • Evcc set to "solar" (it's night now so there is no solar)
  • Plug in car
  • Set to Min+Solar (car will start charging)
  • Set to "off" (car stops charging, charger does not beep indicating end of transaction, good!)
  • Set to Min+Solar

The display will remain on "Ready. Waiting for vehicle…". If I instead repeat the sequence but change the last step to "Fast", it will once again charge.

I can repeat this without unplugging the car and happily switch between "Fast" and "off" successfully. But not Min+Solar

@ross-w
Copy link
Contributor

ross-w commented Jul 11, 2024

And to clarify, if I switch to Min+Solar /after/ switching to Fast, it will work as well. Just going from Off to Min+Solar triggers the issue.

@ross-w

This comment was marked as resolved.

@andig
Copy link
Member Author

andig commented Jul 11, 2024

The mental load to interleave different logs is too much for me :(. Can we please look at a single log?

@andig andig added the enhancement New feature or request label Jul 11, 2024
@andig
Copy link
Member Author

andig commented Jul 11, 2024

@ross-w could your give #14824 a try? Fixed a bug that I could reproduce.

@ross-w
Copy link
Contributor

ross-w commented Jul 12, 2024

@andig sorry for the delay. The latest version does not start charging. When I switch to min+solar I get this repeatedly in the log:

[lp-1 ] ERROR 2024/07/12 22:31:31 max charge current 6A: no transaction running 

@andig
Copy link
Member Author

andig commented Jul 12, 2024

Do you have a log? Your charger should start the transaction and hence have one?

@ross-w

This comment was marked as resolved.

@andig
Copy link
Member Author

andig commented Jul 13, 2024

I've updated PR once more. Also: I need the trace log for OCPP.

@ross-w

This comment was marked as resolved.

@andig
Copy link
Member Author

andig commented Jul 13, 2024

Pls once more- our internal testing is happy now :)

@ross-w
Copy link
Contributor

ross-w commented Jul 13, 2024

Thanks @andig ! This one is nearly working again. It has the same behaviour as before, but I've now realised it's not to do with minpv but rather whatever it was last set to. I can reproduce the issue with fast as well. It seems to be that if I set the charger to whatever the current was before I set it to off, it gets stuck on "Ready, waiting for vehicle". If I set something else, it works.

Eg: Off->Minpv->Off->Minpv fails, Off->Minpv->Off->Fast works. Off->Fast->Off->Fast fails, Off->Fast->Off->Minpv works.

Trace log:

[main  ] INFO 2024/07/13 21:04:43 evcc 0.128.2 (0ff9f38b)
[main  ] INFO 2024/07/13 21:04:43 using config file: /Users/ross/Projects/evcc/evcc.yaml
[main  ] INFO 2024/07/13 21:04:44 listening at :7070
[zjb-1 ] DEBUG 2024/07/13 21:04:44 waiting for chargepoint: 5m0s
[ocpp  ] DEBUG 2024/07/13 21:04:49 charge point connected: zjb
[ocpp  ] TRACE 2024/07/13 21:04:49 recv zjb: [2,"o30df15h518x0f8wej8yww1i","StatusNotification",{"connectorId":0,"errorCode":"NoError","status":"Available","timestamp":"2024-07-13T11:04:48Z"}]
[ocpp  ] TRACE 2024/07/13 21:04:50 recv zjb: [2,"e1ten2lo4u827xb9l8iows5h","StatusNotification",{"connectorId":1,"errorCode":"NoError","status":"Preparing","timestamp":"2024-07-13T11:04:48Z"}]
[ocpp  ] TRACE 2024/07/13 21:04:50 send zjb: [3,"e1ten2lo4u827xb9l8iows5h",{}]
[lp-1  ] WARN 2024/07/13 21:04:50 deprecated: maxcurrent setting is ignored, please remove
[lp-1  ] WARN 2024/07/13 21:04:50 deprecated: phases setting is ignored, please remove
[lp-1  ] INFO 2024/07/13 21:04:52 loadpoint 1:
[lp-1  ] INFO 2024/07/13 21:04:52   mode:        pv
[lp-1  ] INFO 2024/07/13 21:04:52   charger:     power ✗ energy ✗ currents ✗ phases ✗ wakeup ✗
[lp-1  ] INFO 2024/07/13 21:04:52   meters:      charge ✗
[main  ] TRACE 2024/07/13 21:04:52 GET https://api.github.com/repos/evcc-io/evcc/releases/latest
[lp-1  ] DEBUG 2024/07/13 21:04:52 !! active phases: 1p = min(0p measured 0p vehicle 1p physical 0p charger)
[lp-1  ] DEBUG 2024/07/13 21:04:52 phase timer inactive
[lp-1  ] DEBUG 2024/07/13 21:04:52 pv timer inactive
[lp-1  ] INFO 2024/07/13 21:04:52 vehicle updated: unknown -> Ioniq 5
[lp-1  ] DEBUG 2024/07/13 21:04:52 set charge mode: pv
[lp-1  ] DEBUG 2024/07/13 21:04:52 !! active phases: 1p = min(0p measured 0p vehicle 1p physical 0p charger)
[lp-1  ] DEBUG 2024/07/13 21:04:52 charge power: 0W
[lp-1  ] DEBUG 2024/07/13 21:04:53 !! active phases: 1p = min(0p measured 0p vehicle 1p physical 0p charger)
[lp-1  ] DEBUG 2024/07/13 21:04:53 charger status: B
[lp-1  ] INFO 2024/07/13 21:04:53 car connected
[lp-1  ] DEBUG 2024/07/13 21:04:53 pv timer elapse
[lp-1  ] DEBUG 2024/07/13 21:04:53 pv timer inactive
[lp-1  ] DEBUG 2024/07/13 21:04:53 !! active phases: 1p = min(0p measured 0p vehicle 1p physical 0p charger)
[lp-1  ] DEBUG 2024/07/13 21:04:54 vehicle soc: 60%
[lp-1  ] DEBUG 2024/07/13 21:04:54 !! active phases: 1p = min(0p measured 0p vehicle 1p physical 0p charger)
[lp-1  ] DEBUG 2024/07/13 21:04:54 pv charge current: 0A = 0A + -6.09A (1400W @ 1p)
[lp-1  ] DEBUG 2024/07/13 21:04:54 pv enable timer reset
[lp-1  ] DEBUG 2024/07/13 21:04:54 pv timer inactive
[lp-1  ] DEBUG 2024/07/13 21:04:54 !! active phases: 1p = min(0p measured 0p vehicle 1p physical 0p charger)
[lp-1  ] DEBUG 2024/07/13 21:04:54 charge power: 0W
[lp-1  ] DEBUG 2024/07/13 21:04:54 !! active phases: 1p = min(0p measured 0p vehicle 1p physical 0p charger)
[lp-1  ] DEBUG 2024/07/13 21:04:54 charger status: B
[lp-1  ] DEBUG 2024/07/13 21:04:54 !! active phases: 1p = min(0p measured 0p vehicle 1p physical 0p charger)
[lp-1  ] DEBUG 2024/07/13 21:04:54 pv charge current: 0A = 0A + -6.09A (1400W @ 1p)
[lp-1  ] DEBUG 2024/07/13 21:04:54 !! active phases: 1p = min(0p measured 0p vehicle 1p physical 0p charger)
[lp-1  ] DEBUG 2024/07/13 21:05:02 charge power: 0W
[lp-1  ] DEBUG 2024/07/13 21:05:02 !! active phases: 1p = min(0p measured 0p vehicle 1p physical 0p charger)
[lp-1  ] DEBUG 2024/07/13 21:05:02 charger status: B
[lp-1  ] DEBUG 2024/07/13 21:05:02 !! active phases: 1p = min(0p measured 0p vehicle 1p physical 0p charger)
[lp-1  ] DEBUG 2024/07/13 21:05:02 pv charge current: 0A = 0A + -6.09A (1400W @ 1p)
[lp-1  ] DEBUG 2024/07/13 21:05:02 !! active phases: 1p = min(0p measured 0p vehicle 1p physical 0p charger)
[lp-1  ] DEBUG 2024/07/13 21:05:06 set charge mode: minpv
[lp-1  ] DEBUG 2024/07/13 21:05:06 charge power: 0W
[lp-1  ] DEBUG 2024/07/13 21:05:06 !! active phases: 1p = min(0p measured 0p vehicle 1p physical 0p charger)
[lp-1  ] DEBUG 2024/07/13 21:05:06 charger status: B
[lp-1  ] DEBUG 2024/07/13 21:05:06 !! active phases: 1p = min(0p measured 0p vehicle 1p physical 0p charger)
[lp-1  ] DEBUG 2024/07/13 21:05:06 pv charge current: min 6A > 0A (1351W @ 1p, battery: false)
[lp-1  ] DEBUG 2024/07/13 21:05:06 !! active phases: 1p = min(0p measured 0p vehicle 1p physical 0p charger)
[lp-1  ] DEBUG 2024/07/13 21:05:06 max charge current: 6A
[lp-1  ] DEBUG 2024/07/13 21:05:06 !! active phases: 1p = min(0p measured 0p vehicle 1p physical 0p charger)
[ocpp  ] TRACE 2024/07/13 21:05:06 send zjb: [2,"3172667729","RemoteStartTransaction",{"connectorId":1,"idTag":"evcc","chargingProfile":{"chargingProfileId":1,"stackLevel":0,"chargingProfilePurpose":"TxProfile","chargingProfileKind":"Relative","chargingSchedule":{"chargingRateUnit":"A","chargingSchedulePeriod":[{"startPeriod":0,"limit":6}]}}}]
[ocpp  ] TRACE 2024/07/13 21:05:06 recv zjb: [3,"3172667729",{"status":"Accepted"}]
[lp-1  ] DEBUG 2024/07/13 21:05:06 charger enable
[lp-1  ] DEBUG 2024/07/13 21:05:06 !! active phases: 1p = min(0p measured 0p vehicle 1p physical 0p charger)
[lp-1  ] DEBUG 2024/07/13 21:05:06 wake-up timer: start
[ocpp  ] TRACE 2024/07/13 21:05:08 recv zjb: [2,"zfm1bukdpu774cisba8mqvzj","StartTransaction",{"connectorId":1,"idTag":"evcc","meterStart":547698,"timestamp":"2024-07-13T11:05:07Z"}]
[ocpp  ] TRACE 2024/07/13 21:05:08 send zjb: [3,"zfm1bukdpu774cisba8mqvzj",{"idTagInfo":{"status":"Accepted"},"transactionId":1}]
[ocpp  ] TRACE 2024/07/13 21:05:08 recv zjb: [2,"fv0qg09b0ehmhwum1wmoq1yt","MeterValues",{"connectorId":1,"transactionId":1,"meterValue":[{"timestamp":"2024-07-13T11:05:08Z","sampledValue":[{"value":"547698","context":"Sample.Periodic","measurand":"Energy.Active.Import.Register","format":"Raw","unit":"Wh"},{"value":"0","measurand":"Power.Active.Import","format":"Raw","unit":"W"},{"value":"0","phase":"L1-N","measurand":"Current.Import","format":"Raw","unit":"A"},{"value":"6","measurand":"Current.Offered","format":"Raw","unit":"A"},{"value":"232","phase":"L1-N","measurand":"Voltage","format":"Raw","unit":"V"}]}]}]
[ocpp  ] TRACE 2024/07/13 21:05:08 send zjb: [3,"fv0qg09b0ehmhwum1wmoq1yt",{}]
[ocpp  ] TRACE 2024/07/13 21:05:09 recv zjb: [2,"fin8jc72i20yls7qmwpaztr2","StatusNotification",{"connectorId":1,"errorCode":"NoError","status":"Charging","timestamp":"2024-07-13T11:05:09Z"}]
[ocpp  ] TRACE 2024/07/13 21:05:09 send zjb: [3,"fin8jc72i20yls7qmwpaztr2",{}]
[lp-1  ] DEBUG 2024/07/13 21:05:12 charge power: 0W
[lp-1  ] DEBUG 2024/07/13 21:05:12 !! active phases: 1p = min(0p measured 0p vehicle 1p physical 0p charger)
[lp-1  ] DEBUG 2024/07/13 21:05:12 charger status: C
[lp-1  ] INFO 2024/07/13 21:05:12 start charging ->
[lp-1  ] DEBUG 2024/07/13 21:05:12 wake-up timer: stop
[lp-1  ] DEBUG 2024/07/13 21:05:12 !! active phases: 1p = min(0p measured 0p vehicle 1p physical 0p charger)
[lp-1  ] DEBUG 2024/07/13 21:05:12 charger vehicle id: evcc
[lp-1  ] DEBUG 2024/07/13 21:05:12 vehicle soc: 60%
[lp-1  ] DEBUG 2024/07/13 21:05:12 !! active phases: 1p = min(0p measured 0p vehicle 1p physical 0p charger)
[lp-1  ] DEBUG 2024/07/13 21:05:12 pv charge current: min 6A > 0.126A (1351W @ 1p, battery: false)
[lp-1  ] DEBUG 2024/07/13 21:05:12 !! active phases: 1p = min(0p measured 0p vehicle 1p physical 0p charger)
[lp-1  ] DEBUG 2024/07/13 21:05:22 charge power: 1380W
[lp-1  ] DEBUG 2024/07/13 21:05:22 !! active phases: 1p = min(0p measured 0p vehicle 1p physical 0p charger)
[lp-1  ] DEBUG 2024/07/13 21:05:22 !! session: chargeRater.chargedEnergy=0.0 - chargedAtStartup=0.0
[lp-1  ] DEBUG 2024/07/13 21:05:22 charger status: C
[lp-1  ] DEBUG 2024/07/13 21:05:22 vehicle soc: 60%
[lp-1  ] DEBUG 2024/07/13 21:05:22 !! active phases: 1p = min(0p measured 0p vehicle 1p physical 0p charger)
[lp-1  ] DEBUG 2024/07/13 21:05:22 pv charge current: min 6A > 0A (1401W @ 1p, battery: false)
[lp-1  ] DEBUG 2024/07/13 21:05:22 !! active phases: 1p = min(0p measured 0p vehicle 1p physical 0p charger)
[ocpp  ] TRACE 2024/07/13 21:05:31 recv zjb: [2,"7dbz1fe03613el6fklm55r9d","MeterValues",{"connectorId":1,"transactionId":1,"meterValue":[{"timestamp":"2024-07-13T11:05:30Z","sampledValue":[{"value":"547702","context":"Sample.Periodic","measurand":"Energy.Active.Import.Register","format":"Raw","unit":"Wh"},{"value":"1182","measurand":"Power.Active.Import","format":"Raw","unit":"W"},{"value":"5","phase":"L1-N","measurand":"Current.Import","format":"Raw","unit":"A"},{"value":"6","measurand":"Current.Offered","format":"Raw","unit":"A"},{"value":"230","phase":"L1-N","measurand":"Voltage","format":"Raw","unit":"V"}]}]}]
[ocpp  ] TRACE 2024/07/13 21:05:31 send zjb: [3,"7dbz1fe03613el6fklm55r9d",{}]
[lp-1  ] DEBUG 2024/07/13 21:05:32 charge power: 1380W
[lp-1  ] DEBUG 2024/07/13 21:05:32 !! active phases: 1p = min(0p measured 0p vehicle 1p physical 0p charger)
[lp-1  ] DEBUG 2024/07/13 21:05:32 !! session: chargeRater.chargedEnergy=0.0 - chargedAtStartup=0.0
[lp-1  ] DEBUG 2024/07/13 21:05:32 charger status: C
[lp-1  ] DEBUG 2024/07/13 21:05:32 vehicle soc: 60%
[lp-1  ] DEBUG 2024/07/13 21:05:32 !! active phases: 1p = min(0p measured 0p vehicle 1p physical 0p charger)
[lp-1  ] DEBUG 2024/07/13 21:05:32 pv charge current: min 6A > 0A (2598W @ 1p, battery: false)
[lp-1  ] DEBUG 2024/07/13 21:05:32 !! active phases: 1p = min(0p measured 0p vehicle 1p physical 0p charger)
[lp-1  ] DEBUG 2024/07/13 21:05:37 set charge mode: off
[lp-1  ] DEBUG 2024/07/13 21:05:37 charge power: 1380W
[lp-1  ] DEBUG 2024/07/13 21:05:37 !! active phases: 1p = min(0p measured 0p vehicle 1p physical 0p charger)
[lp-1  ] DEBUG 2024/07/13 21:05:37 !! session: chargeRater.chargedEnergy=0.0 - chargedAtStartup=0.0
[lp-1  ] DEBUG 2024/07/13 21:05:37 charger status: C
[lp-1  ] DEBUG 2024/07/13 21:05:37 vehicle soc: 60%
[lp-1  ] DEBUG 2024/07/13 21:05:37 !! active phases: 1p = min(0p measured 0p vehicle 1p physical 0p charger)
[ocpp  ] TRACE 2024/07/13 21:05:37 send zjb: [2,"232648269","SetChargingProfile",{"connectorId":1,"csChargingProfiles":{"chargingProfileId":1,"transactionId":1,"stackLevel":0,"chargingProfilePurpose":"TxProfile","chargingProfileKind":"Relative","chargingSchedule":{"chargingRateUnit":"A","chargingSchedulePeriod":[{"startPeriod":0,"limit":0}]}}}]
[ocpp  ] TRACE 2024/07/13 21:05:37 recv zjb: [3,"232648269",{"status":"Accepted"}]
[lp-1  ] DEBUG 2024/07/13 21:05:37 charger disable
[lp-1  ] DEBUG 2024/07/13 21:05:37 !! active phases: 1p = min(0p measured 0p vehicle 1p physical 0p charger)
[lp-1  ] DEBUG 2024/07/13 21:05:37 wake-up timer: stop
[ocpp  ] TRACE 2024/07/13 21:05:39 recv zjb: [2,"2wkj9mlfp714wawtemas1v5f","StatusNotification",{"connectorId":1,"errorCode":"NoError","status":"SuspendedEVSE","timestamp":"2024-07-13T11:05:38Z"}]
[ocpp  ] TRACE 2024/07/13 21:05:39 send zjb: [3,"2wkj9mlfp714wawtemas1v5f",{}]
[lp-1  ] DEBUG 2024/07/13 21:05:42 charge power: 0W
[lp-1  ] DEBUG 2024/07/13 21:05:42 !! active phases: 1p = min(0p measured 0p vehicle 1p physical 0p charger)
[lp-1  ] DEBUG 2024/07/13 21:05:42 !! session: chargeRater.chargedEnergy=0.0 - chargedAtStartup=0.0
[lp-1  ] DEBUG 2024/07/13 21:05:42 charger status: B
[lp-1  ] INFO 2024/07/13 21:05:42 stop charging <-
[lp-1  ] DEBUG 2024/07/13 21:05:42 !! session: chargedEnergy=0.0 > chargedEnergy=0.0
[lp-1  ] DEBUG 2024/07/13 21:05:42 !! session: start=0.000 stop=0.000 chargedEnergy=0.010
[lp-1  ] DEBUG 2024/07/13 21:05:42 !! active phases: 1p = min(0p measured 0p vehicle 1p physical 0p charger)
[lp-1  ] DEBUG 2024/07/13 21:05:42 vehicle soc: 60%
[lp-1  ] DEBUG 2024/07/13 21:05:42 !! active phases: 1p = min(0p measured 0p vehicle 1p physical 0p charger)
[lp-1  ] DEBUG 2024/07/13 21:05:49 set charge mode: minpv
[lp-1  ] DEBUG 2024/07/13 21:05:49 charge power: 0W
[lp-1  ] DEBUG 2024/07/13 21:05:49 !! active phases: 1p = min(0p measured 0p vehicle 1p physical 0p charger)
[lp-1  ] DEBUG 2024/07/13 21:05:49 !! session: chargeRater.chargedEnergy=0.0 - chargedAtStartup=0.0
[lp-1  ] DEBUG 2024/07/13 21:05:49 charger status: B
[lp-1  ] DEBUG 2024/07/13 21:05:49 !! active phases: 1p = min(0p measured 0p vehicle 1p physical 0p charger)
[lp-1  ] DEBUG 2024/07/13 21:05:49 pv charge current: min 6A > 0A (1348W @ 1p, battery: false)
[lp-1  ] DEBUG 2024/07/13 21:05:49 !! active phases: 1p = min(0p measured 0p vehicle 1p physical 0p charger)
[lp-1  ] DEBUG 2024/07/13 21:05:49 charger enable
[lp-1  ] DEBUG 2024/07/13 21:05:49 !! active phases: 1p = min(0p measured 0p vehicle 1p physical 0p charger)
[lp-1  ] DEBUG 2024/07/13 21:05:49 wake-up timer: start
[ocpp  ] TRACE 2024/07/13 21:05:50 recv zjb: [2,"gyfu6op1bdguzoz3bkc9zbzc","MeterValues",{"connectorId":1,"transactionId":1,"meterValue":[{"timestamp":"2024-07-13T11:05:50Z","sampledValue":[{"value":"547704","context":"Sample.Periodic","measurand":"Energy.Active.Import.Register","format":"Raw","unit":"Wh"},{"value":"0","measurand":"Power.Active.Import","format":"Raw","unit":"W"},{"value":"0","phase":"L1-N","measurand":"Current.Import","format":"Raw","unit":"A"},{"value":"6","measurand":"Current.Offered","format":"Raw","unit":"A"},{"value":"231","phase":"L1-N","measurand":"Voltage","format":"Raw","unit":"V"}]}]}]
[ocpp  ] TRACE 2024/07/13 21:05:50 send zjb: [3,"gyfu6op1bdguzoz3bkc9zbzc",{}]
[lp-1  ] DEBUG 2024/07/13 21:05:52 charge power: 0W
[lp-1  ] DEBUG 2024/07/13 21:05:52 !! active phases: 1p = min(0p measured 0p vehicle 1p physical 0p charger)
[lp-1  ] DEBUG 2024/07/13 21:05:52 !! session: chargeRater.chargedEnergy=0.0 - chargedAtStartup=0.0
[lp-1  ] DEBUG 2024/07/13 21:05:52 charger status: B
[lp-1  ] DEBUG 2024/07/13 21:05:52 !! active phases: 1p = min(0p measured 0p vehicle 1p physical 0p charger)
[lp-1  ] DEBUG 2024/07/13 21:05:52 pv charge current: min 6A > 0A (1348W @ 1p, battery: false)
[lp-1  ] DEBUG 2024/07/13 21:05:52 !! active phases: 1p = min(0p measured 0p vehicle 1p physical 0p charger)
[lp-1  ] DEBUG 2024/07/13 21:06:02 charge power: 0W
[lp-1  ] DEBUG 2024/07/13 21:06:02 !! active phases: 1p = min(0p measured 0p vehicle 1p physical 0p charger)
[lp-1  ] DEBUG 2024/07/13 21:06:02 !! session: chargeRater.chargedEnergy=0.0 - chargedAtStartup=0.0
[lp-1  ] DEBUG 2024/07/13 21:06:02 charger status: B
[lp-1  ] DEBUG 2024/07/13 21:06:02 !! active phases: 1p = min(0p measured 0p vehicle 1p physical 0p charger)
[lp-1  ] DEBUG 2024/07/13 21:06:02 pv charge current: min 6A > 0A (1358W @ 1p, battery: false)
[lp-1  ] DEBUG 2024/07/13 21:06:02 !! active phases: 1p = min(0p measured 0p vehicle 1p physical 0p charger)
[lp-1  ] DEBUG 2024/07/13 21:06:12 charge power: 0W
[lp-1  ] DEBUG 2024/07/13 21:06:12 !! active phases: 1p = min(0p measured 0p vehicle 1p physical 0p charger)
[lp-1  ] DEBUG 2024/07/13 21:06:12 !! session: chargeRater.chargedEnergy=0.0 - chargedAtStartup=0.0
[lp-1  ] DEBUG 2024/07/13 21:06:12 charger status: B
[lp-1  ] DEBUG 2024/07/13 21:06:12 !! active phases: 1p = min(0p measured 0p vehicle 1p physical 0p charger)
[lp-1  ] DEBUG 2024/07/13 21:06:12 pv charge current: min 6A > 0A (1364W @ 1p, battery: false)
[lp-1  ] DEBUG 2024/07/13 21:06:12 !! active phases: 1p = min(0p measured 0p vehicle 1p physical 0p charger)
[ocpp  ] TRACE 2024/07/13 21:06:20 recv zjb: [2,"bdx327pim42wm428etaljp2l","MeterValues",{"connectorId":1,"transactionId":1,"meterValue":[{"timestamp":"2024-07-13T11:06:20Z","sampledValue":[{"value":"547704","context":"Sample.Periodic","measurand":"Energy.Active.Import.Register","format":"Raw","unit":"Wh"},{"value":"0","measurand":"Power.Active.Import","format":"Raw","unit":"W"},{"value":"0","phase":"L1-N","measurand":"Current.Import","format":"Raw","unit":"A"},{"value":"6","measurand":"Current.Offered","format":"Raw","unit":"A"},{"value":"232","phase":"L1-N","measurand":"Voltage","format":"Raw","unit":"V"}]}]}]
[ocpp  ] TRACE 2024/07/13 21:06:20 send zjb: [3,"bdx327pim42wm428etaljp2l",{}]
[lp-1  ] DEBUG 2024/07/13 21:06:22 charge power: 0W
[lp-1  ] DEBUG 2024/07/13 21:06:22 !! active phases: 1p = min(0p measured 0p vehicle 1p physical 0p charger)
[lp-1  ] DEBUG 2024/07/13 21:06:22 !! session: chargeRater.chargedEnergy=0.0 - chargedAtStartup=0.0
[lp-1  ] DEBUG 2024/07/13 21:06:22 charger status: B
[lp-1  ] DEBUG 2024/07/13 21:06:22 !! active phases: 1p = min(0p measured 0p vehicle 1p physical 0p charger)
[lp-1  ] DEBUG 2024/07/13 21:06:22 pv charge current: min 6A > 0A (1381W @ 1p, battery: false)
[lp-1  ] DEBUG 2024/07/13 21:06:22 !! active phases: 1p = min(0p measured 0p vehicle 1p physical 0p charger)
[lp-1  ] DEBUG 2024/07/13 21:06:32 charge power: 0W
[lp-1  ] DEBUG 2024/07/13 21:06:32 !! active phases: 1p = min(0p measured 0p vehicle 1p physical 0p charger)
[lp-1  ] DEBUG 2024/07/13 21:06:32 !! session: chargeRater.chargedEnergy=0.0 - chargedAtStartup=0.0
[lp-1  ] DEBUG 2024/07/13 21:06:32 charger status: B
[lp-1  ] DEBUG 2024/07/13 21:06:32 !! active phases: 1p = min(0p measured 0p vehicle 1p physical 0p charger)
[lp-1  ] DEBUG 2024/07/13 21:06:32 pv charge current: min 6A > 0A (1360W @ 1p, battery: false)
[lp-1  ] DEBUG 2024/07/13 21:06:32 !! active phases: 1p = min(0p measured 0p vehicle 1p physical 0p charger)
[lp-1  ] DEBUG 2024/07/13 21:06:40 set charge mode: now
[lp-1  ] DEBUG 2024/07/13 21:06:40 charge power: 0W
[lp-1  ] DEBUG 2024/07/13 21:06:40 !! active phases: 1p = min(0p measured 0p vehicle 1p physical 0p charger)
[lp-1  ] DEBUG 2024/07/13 21:06:40 !! session: chargeRater.chargedEnergy=0.0 - chargedAtStartup=0.0
[lp-1  ] DEBUG 2024/07/13 21:06:40 charger status: B
[lp-1  ] DEBUG 2024/07/13 21:06:40 !! active phases: 1p = min(0p measured 0p vehicle 1p physical 0p charger)
[ocpp  ] TRACE 2024/07/13 21:06:40 send zjb: [2,"3138687333","SetChargingProfile",{"connectorId":1,"csChargingProfiles":{"chargingProfileId":1,"transactionId":1,"stackLevel":0,"chargingProfilePurpose":"TxProfile","chargingProfileKind":"Relative","chargingSchedule":{"chargingRateUnit":"A","chargingSchedulePeriod":[{"startPeriod":0,"limit":31.3}]}}}]
[ocpp  ] TRACE 2024/07/13 21:06:40 recv zjb: [3,"3138687333",{"status":"Accepted"}]
[lp-1  ] DEBUG 2024/07/13 21:06:40 max charge current: 31.3A
[lp-1  ] DEBUG 2024/07/13 21:06:40 !! active phases: 1p = min(0p measured 0p vehicle 1p physical 0p charger)
[ocpp  ] TRACE 2024/07/13 21:06:42 recv zjb: [2,"3zvm8hchc4iysrqv6qxsr2x3","StatusNotification",{"connectorId":1,"errorCode":"NoError","status":"SuspendedEV","timestamp":"2024-07-13T11:06:41Z"}]
[ocpp  ] TRACE 2024/07/13 21:06:42 send zjb: [3,"3zvm8hchc4iysrqv6qxsr2x3",{}]
[lp-1  ] DEBUG 2024/07/13 21:06:42 charge power: 0W
[lp-1  ] DEBUG 2024/07/13 21:06:42 !! active phases: 1p = min(0p measured 0p vehicle 1p physical 0p charger)
[lp-1  ] DEBUG 2024/07/13 21:06:42 !! session: chargeRater.chargedEnergy=0.0 - chargedAtStartup=0.0
[lp-1  ] DEBUG 2024/07/13 21:06:42 charger status: B
[lp-1  ] DEBUG 2024/07/13 21:06:42 !! active phases: 1p = min(0p measured 0p vehicle 1p physical 0p charger)
[ocpp  ] TRACE 2024/07/13 21:06:46 recv zjb: [2,"g5l20teyxjy8r33x8ak907cq","StatusNotification",{"connectorId":1,"errorCode":"NoError","status":"Charging","timestamp":"2024-07-13T11:06:45Z"}]
[ocpp  ] TRACE 2024/07/13 21:06:46 send zjb: [3,"g5l20teyxjy8r33x8ak907cq",{}]
[ocpp  ] TRACE 2024/07/13 21:06:50 recv zjb: [2,"zjvfoh3hek0r5jeyoymg2ek1","MeterValues",{"connectorId":1,"transactionId":1,"meterValue":[{"timestamp":"2024-07-13T11:06:50Z","sampledValue":[{"value":"547704","context":"Sample.Periodic","measurand":"Energy.Active.Import.Register","format":"Raw","unit":"Wh"},{"value":"0","measurand":"Power.Active.Import","format":"Raw","unit":"W"},{"value":"0","phase":"L1-N","measurand":"Current.Import","format":"Raw","unit":"A"},{"value":"31","measurand":"Current.Offered","format":"Raw","unit":"A"},{"value":"232","phase":"L1-N","measurand":"Voltage","format":"Raw","unit":"V"}]}]}]
[ocpp  ] TRACE 2024/07/13 21:06:50 send zjb: [3,"zjvfoh3hek0r5jeyoymg2ek1",{}]
[lp-1  ] DEBUG 2024/07/13 21:06:52 charge power: 0W
[lp-1  ] DEBUG 2024/07/13 21:06:52 !! active phases: 1p = min(0p measured 0p vehicle 1p physical 0p charger)
[lp-1  ] DEBUG 2024/07/13 21:06:52 !! session: chargeRater.chargedEnergy=0.0 - chargedAtStartup=0.0
[lp-1  ] DEBUG 2024/07/13 21:06:52 charger status: C
[lp-1  ] INFO 2024/07/13 21:06:52 start charging ->
[lp-1  ] DEBUG 2024/07/13 21:06:52 wake-up timer: stop
[lp-1  ] DEBUG 2024/07/13 21:06:52 !! active phases: 1p = min(0p measured 0p vehicle 1p physical 0p charger)
[lp-1  ] DEBUG 2024/07/13 21:06:52 vehicle soc: 60%
[lp-1  ] DEBUG 2024/07/13 21:06:52 !! active phases: 1p = min(0p measured 0p vehicle 1p physical 0p charger)
[ocpp  ] TRACE 2024/07/13 21:06:53 recv zjb: [2,"x33lgro6blfinxl4labfjy2x","MeterValues",{"connectorId":1,"transactionId":1,"meterValue":[{"timestamp":"2024-07-13T11:06:52Z","sampledValue":[{"value":"547708","context":"Sample.Periodic","measurand":"Energy.Active.Import.Register","format":"Raw","unit":"Wh"},{"value":"6544","measurand":"Power.Active.Import","format":"Raw","unit":"W"},{"value":"30","phase":"L1-N","measurand":"Current.Import","format":"Raw","unit":"A"},{"value":"31","measurand":"Current.Offered","format":"Raw","unit":"A"},{"value":"221","phase":"L1-N","measurand":"Voltage","format":"Raw","unit":"V"}]}]}]
[ocpp  ] TRACE 2024/07/13 21:06:53 send zjb: [3,"x33lgro6blfinxl4labfjy2x",{}]
[lp-1  ] DEBUG 2024/07/13 21:07:02 charge power: 7200W
[lp-1  ] DEBUG 2024/07/13 21:07:02 !! active phases: 1p = min(0p measured 0p vehicle 1p physical 0p charger)
[lp-1  ] DEBUG 2024/07/13 21:07:02 !! session: chargeRater.chargedEnergy=0.0 - chargedAtStartup=0.0
[lp-1  ] DEBUG 2024/07/13 21:07:02 charger status: C
[lp-1  ] DEBUG 2024/07/13 21:07:02 vehicle soc: 60%
[lp-1  ] DEBUG 2024/07/13 21:07:02 !! active phases: 1p = min(0p measured 0p vehicle 1p physical 0p charger)
[lp-1  ] DEBUG 2024/07/13 21:07:09 set charge mode: off
[lp-1  ] DEBUG 2024/07/13 21:07:09 charge power: 7200W
[lp-1  ] DEBUG 2024/07/13 21:07:09 !! active phases: 1p = min(0p measured 0p vehicle 1p physical 0p charger)
[lp-1  ] DEBUG 2024/07/13 21:07:09 !! session: chargeRater.chargedEnergy=0.0 - chargedAtStartup=0.0
[lp-1  ] DEBUG 2024/07/13 21:07:09 charger status: C
[lp-1  ] DEBUG 2024/07/13 21:07:09 vehicle soc: 60%
[lp-1  ] DEBUG 2024/07/13 21:07:09 !! active phases: 1p = min(0p measured 0p vehicle 1p physical 0p charger)
[ocpp  ] TRACE 2024/07/13 21:07:09 send zjb: [2,"3368408260","SetChargingProfile",{"connectorId":1,"csChargingProfiles":{"chargingProfileId":1,"transactionId":1,"stackLevel":0,"chargingProfilePurpose":"TxProfile","chargingProfileKind":"Relative","chargingSchedule":{"chargingRateUnit":"A","chargingSchedulePeriod":[{"startPeriod":0,"limit":0}]}}}]
[ocpp  ] TRACE 2024/07/13 21:07:10 recv zjb: [3,"3368408260",{"status":"Accepted"}]
[lp-1  ] DEBUG 2024/07/13 21:07:10 charger disable
[lp-1  ] DEBUG 2024/07/13 21:07:10 !! active phases: 1p = min(0p measured 0p vehicle 1p physical 0p charger)
[lp-1  ] DEBUG 2024/07/13 21:07:10 wake-up timer: stop
[ocpp  ] TRACE 2024/07/13 21:07:11 recv zjb: [2,"vh9z548r8b8kjrd1kvwph0mt","StatusNotification",{"connectorId":1,"errorCode":"NoError","status":"SuspendedEVSE","timestamp":"2024-07-13T11:07:11Z"}]
[ocpp  ] TRACE 2024/07/13 21:07:11 send zjb: [3,"vh9z548r8b8kjrd1kvwph0mt",{}]
[lp-1  ] DEBUG 2024/07/13 21:07:12 charge power: 0W
[lp-1  ] DEBUG 2024/07/13 21:07:12 !! active phases: 1p = min(0p measured 0p vehicle 1p physical 0p charger)
[lp-1  ] DEBUG 2024/07/13 21:07:12 !! session: chargeRater.chargedEnergy=0.0 - chargedAtStartup=0.0
[lp-1  ] DEBUG 2024/07/13 21:07:12 charger status: B
[lp-1  ] INFO 2024/07/13 21:07:12 stop charging <-
[lp-1  ] DEBUG 2024/07/13 21:07:12 !! session: chargedEnergy=0.0 > chargedEnergy=0.0
[lp-1  ] DEBUG 2024/07/13 21:07:12 !! session: start=0.000 stop=0.000 chargedEnergy=0.044
[lp-1  ] DEBUG 2024/07/13 21:07:12 !! active phases: 1p = min(0p measured 0p vehicle 1p physical 0p charger)
[lp-1  ] DEBUG 2024/07/13 21:07:12 vehicle soc: 60%
[lp-1  ] DEBUG 2024/07/13 21:07:12 !! active phases: 1p = min(0p measured 0p vehicle 1p physical 0p charger)
[ocpp  ] TRACE 2024/07/13 21:07:13 recv zjb: [2,"0a738asgx02z842c0ikbh0uf","MeterValues",{"connectorId":1,"transactionId":1,"meterValue":[{"timestamp":"2024-07-13T11:07:12Z","sampledValue":[{"value":"547741","context":"Sample.Periodic","measurand":"Energy.Active.Import.Register","format":"Raw","unit":"Wh"},{"value":"2494","measurand":"Power.Active.Import","format":"Raw","unit":"W"},{"value":"8","phase":"L1-N","measurand":"Current.Import","format":"Raw","unit":"A"},{"value":"6","measurand":"Current.Offered","format":"Raw","unit":"A"},{"value":"225","phase":"L1-N","measurand":"Voltage","format":"Raw","unit":"V"}]}]}]
[ocpp  ] TRACE 2024/07/13 21:07:13 send zjb: [3,"0a738asgx02z842c0ikbh0uf",{}]
[lp-1  ] DEBUG 2024/07/13 21:07:22 charge power: 0W
[lp-1  ] DEBUG 2024/07/13 21:07:22 !! active phases: 1p = min(0p measured 0p vehicle 1p physical 0p charger)
[lp-1  ] DEBUG 2024/07/13 21:07:22 !! session: chargeRater.chargedEnergy=0.0 - chargedAtStartup=0.0
[lp-1  ] DEBUG 2024/07/13 21:07:22 charger status: B
[lp-1  ] DEBUG 2024/07/13 21:07:22 !! active phases: 1p = min(0p measured 0p vehicle 1p physical 0p charger)
[ocpp  ] TRACE 2024/07/13 21:07:23 recv zjb: [2,"o3wsfxgk6l5qjzsccdskkjp9","MeterValues",{"connectorId":1,"transactionId":1,"meterValue":[{"timestamp":"2024-07-13T11:07:22Z","sampledValue":[{"value":"547741","context":"Sample.Periodic","measurand":"Energy.Active.Import.Register","format":"Raw","unit":"Wh"},{"value":"0","measurand":"Power.Active.Import","format":"Raw","unit":"W"},{"value":"0","phase":"L1-N","measurand":"Current.Import","format":"Raw","unit":"A"},{"value":"6","measurand":"Current.Offered","format":"Raw","unit":"A"},{"value":"230","phase":"L1-N","measurand":"Voltage","format":"Raw","unit":"V"}]}]}]
[ocpp  ] TRACE 2024/07/13 21:07:23 send zjb: [3,"o3wsfxgk6l5qjzsccdskkjp9",{}]
[lp-1  ] DEBUG 2024/07/13 21:07:32 charge power: 0W
[lp-1  ] DEBUG 2024/07/13 21:07:32 !! active phases: 1p = min(0p measured 0p vehicle 1p physical 0p charger)
[lp-1  ] DEBUG 2024/07/13 21:07:32 !! session: chargeRater.chargedEnergy=0.0 - chargedAtStartup=0.0
[lp-1  ] DEBUG 2024/07/13 21:07:32 charger status: B
[lp-1  ] DEBUG 2024/07/13 21:07:32 !! active phases: 1p = min(0p measured 0p vehicle 1p physical 0p charger)
[lp-1  ] DEBUG 2024/07/13 21:07:34 set charge mode: minpv
[lp-1  ] DEBUG 2024/07/13 21:07:34 charge power: 0W
[lp-1  ] DEBUG 2024/07/13 21:07:34 !! active phases: 1p = min(0p measured 0p vehicle 1p physical 0p charger)
[lp-1  ] DEBUG 2024/07/13 21:07:34 !! session: chargeRater.chargedEnergy=0.0 - chargedAtStartup=0.0
[lp-1  ] DEBUG 2024/07/13 21:07:34 charger status: B
[lp-1  ] DEBUG 2024/07/13 21:07:34 !! active phases: 1p = min(0p measured 0p vehicle 1p physical 0p charger)
[lp-1  ] DEBUG 2024/07/13 21:07:34 pv charge current: min 6A > 0A (2655W @ 1p, battery: false)
[lp-1  ] DEBUG 2024/07/13 21:07:34 !! active phases: 1p = min(0p measured 0p vehicle 1p physical 0p charger)
[ocpp  ] TRACE 2024/07/13 21:07:34 send zjb: [2,"1458599572","SetChargingProfile",{"connectorId":1,"csChargingProfiles":{"chargingProfileId":1,"transactionId":1,"stackLevel":0,"chargingProfilePurpose":"TxProfile","chargingProfileKind":"Relative","chargingSchedule":{"chargingRateUnit":"A","chargingSchedulePeriod":[{"startPeriod":0,"limit":6}]}}}]
[ocpp  ] TRACE 2024/07/13 21:07:34 recv zjb: [3,"1458599572",{"status":"Accepted"}]
[lp-1  ] DEBUG 2024/07/13 21:07:34 max charge current: 6A
[lp-1  ] DEBUG 2024/07/13 21:07:34 !! active phases: 1p = min(0p measured 0p vehicle 1p physical 0p charger)
[lp-1  ] DEBUG 2024/07/13 21:07:34 charger enable
[lp-1  ] DEBUG 2024/07/13 21:07:34 !! active phases: 1p = min(0p measured 0p vehicle 1p physical 0p charger)
[lp-1  ] DEBUG 2024/07/13 21:07:34 wake-up timer: start
[ocpp  ] TRACE 2024/07/13 21:07:35 recv zjb: [2,"mu8oavrikzl0dmret84g9f3t","StatusNotification",{"connectorId":1,"errorCode":"NoError","status":"SuspendedEV","timestamp":"2024-07-13T11:07:35Z"}]
[ocpp  ] TRACE 2024/07/13 21:07:35 send zjb: [3,"mu8oavrikzl0dmret84g9f3t",{}]
[ocpp  ] TRACE 2024/07/13 21:07:36 recv zjb: [2,"zxa5fc6ht6jvgpldc5z9c8oi","StatusNotification",{"connectorId":1,"errorCode":"NoError","status":"Charging","timestamp":"2024-07-13T11:07:36Z"}]
[ocpp  ] TRACE 2024/07/13 21:07:36 send zjb: [3,"zxa5fc6ht6jvgpldc5z9c8oi",{}]
[lp-1  ] DEBUG 2024/07/13 21:07:42 charge power: 0W
[lp-1  ] DEBUG 2024/07/13 21:07:42 !! active phases: 1p = min(0p measured 0p vehicle 1p physical 0p charger)
[lp-1  ] DEBUG 2024/07/13 21:07:42 !! session: chargeRater.chargedEnergy=0.0 - chargedAtStartup=0.0
[lp-1  ] DEBUG 2024/07/13 21:07:42 charger status: C
[lp-1  ] INFO 2024/07/13 21:07:42 start charging ->
[lp-1  ] DEBUG 2024/07/13 21:07:42 wake-up timer: stop
[lp-1  ] DEBUG 2024/07/13 21:07:42 !! active phases: 1p = min(0p measured 0p vehicle 1p physical 0p charger)
[lp-1  ] DEBUG 2024/07/13 21:07:42 vehicle soc: 60%
[lp-1  ] DEBUG 2024/07/13 21:07:42 !! active phases: 1p = min(0p measured 0p vehicle 1p physical 0p charger)
[lp-1  ] DEBUG 2024/07/13 21:07:42 pv charge current: min 6A > 0A (2655W @ 1p, battery: false)
[lp-1  ] DEBUG 2024/07/13 21:07:42 !! active phases: 1p = min(0p measured 0p vehicle 1p physical 0p charger)
[lp-1  ] DEBUG 2024/07/13 21:07:52 charge power: 1380W
[lp-1  ] DEBUG 2024/07/13 21:07:52 !! active phases: 1p = min(0p measured 0p vehicle 1p physical 0p charger)
[lp-1  ] DEBUG 2024/07/13 21:07:52 !! session: chargeRater.chargedEnergy=0.0 - chargedAtStartup=0.0
[lp-1  ] DEBUG 2024/07/13 21:07:52 charger status: C
[lp-1  ] DEBUG 2024/07/13 21:07:52 vehicle soc: 60%
[lp-1  ] DEBUG 2024/07/13 21:07:52 !! active phases: 1p = min(0p measured 0p vehicle 1p physical 0p charger)
[lp-1  ] DEBUG 2024/07/13 21:07:52 pv charge current: min 6A > 0A (2763W @ 1p, battery: false)
[lp-1  ] DEBUG 2024/07/13 21:07:52 !! active phases: 1p = min(0p measured 0p vehicle 1p physical 0p charger)
[ocpp  ] TRACE 2024/07/13 21:07:53 recv zjb: [2,"znffgyrlmjxepv7kjwx4hpmy","MeterValues",{"connectorId":1,"transactionId":1,"meterValue":[{"timestamp":"2024-07-13T11:07:52Z","sampledValue":[{"value":"547745","context":"Sample.Periodic","measurand":"Energy.Active.Import.Register","format":"Raw","unit":"Wh"},{"value":"1166","measurand":"Power.Active.Import","format":"Raw","unit":"W"},{"value":"5","phase":"L1-N","measurand":"Current.Import","format":"Raw","unit":"A"},{"value":"6","measurand":"Current.Offered","format":"Raw","unit":"A"},{"value":"228","phase":"L1-N","measurand":"Voltage","format":"Raw","unit":"V"}]}]}]
[ocpp  ] TRACE 2024/07/13 21:07:53 send zjb: [3,"znffgyrlmjxepv7kjwx4hpmy",{}]
[lp-1  ] DEBUG 2024/07/13 21:07:54 set charge mode: off
[lp-1  ] DEBUG 2024/07/13 21:07:54 charge power: 1380W
[lp-1  ] DEBUG 2024/07/13 21:07:54 !! active phases: 1p = min(0p measured 0p vehicle 1p physical 0p charger)
[lp-1  ] DEBUG 2024/07/13 21:07:54 !! session: chargeRater.chargedEnergy=0.0 - chargedAtStartup=0.0
[lp-1  ] DEBUG 2024/07/13 21:07:54 charger status: C
[lp-1  ] DEBUG 2024/07/13 21:07:54 vehicle soc: 60%
[lp-1  ] DEBUG 2024/07/13 21:07:54 !! active phases: 1p = min(0p measured 0p vehicle 1p physical 0p charger)
[ocpp  ] TRACE 2024/07/13 21:07:54 send zjb: [2,"2110165543","SetChargingProfile",{"connectorId":1,"csChargingProfiles":{"chargingProfileId":1,"transactionId":1,"stackLevel":0,"chargingProfilePurpose":"TxProfile","chargingProfileKind":"Relative","chargingSchedule":{"chargingRateUnit":"A","chargingSchedulePeriod":[{"startPeriod":0,"limit":0}]}}}]
[ocpp  ] TRACE 2024/07/13 21:07:55 recv zjb: [3,"2110165543",{"status":"Accepted"}]
[lp-1  ] DEBUG 2024/07/13 21:07:55 charger disable
[lp-1  ] DEBUG 2024/07/13 21:07:55 !! active phases: 1p = min(0p measured 0p vehicle 1p physical 0p charger)
[lp-1  ] DEBUG 2024/07/13 21:07:55 wake-up timer: stop
[ocpp  ] TRACE 2024/07/13 21:07:56 recv zjb: [2,"gqqu144o2mh3ap5bmfy4govz","StatusNotification",{"connectorId":1,"errorCode":"NoError","status":"SuspendedEVSE","timestamp":"2024-07-13T11:07:55Z"}]
[ocpp  ] TRACE 2024/07/13 21:07:56 send zjb: [3,"gqqu144o2mh3ap5bmfy4govz",{}]
[lp-1  ] DEBUG 2024/07/13 21:08:02 charge power: 0W
[lp-1  ] DEBUG 2024/07/13 21:08:02 !! active phases: 1p = min(0p measured 0p vehicle 1p physical 0p charger)
[lp-1  ] DEBUG 2024/07/13 21:08:02 !! session: chargeRater.chargedEnergy=0.0 - chargedAtStartup=0.0
[lp-1  ] DEBUG 2024/07/13 21:08:02 charger status: B
[lp-1  ] INFO 2024/07/13 21:08:02 stop charging <-
[lp-1  ] DEBUG 2024/07/13 21:08:02 !! session: chargedEnergy=0.0 > chargedEnergy=0.0
[lp-1  ] DEBUG 2024/07/13 21:08:02 !! session: start=0.000 stop=0.000 chargedEnergy=0.048
[lp-1  ] DEBUG 2024/07/13 21:08:02 !! active phases: 1p = min(0p measured 0p vehicle 1p physical 0p charger)
[lp-1  ] DEBUG 2024/07/13 21:08:02 vehicle soc: 60%
[lp-1  ] DEBUG 2024/07/13 21:08:02 !! active phases: 1p = min(0p measured 0p vehicle 1p physical 0p charger)

@andig
Copy link
Member Author

andig commented Jul 13, 2024

Eg: Off->Minpv->Off->Minpv fails, Off->Minpv->Off->Fast works. Off->Fast->Off->Fast fails, Off->Fast->Off->Minpv works.

@premultiply could you take a look at the test board?

@premultiply
Copy link
Member

From the log above it looks like in the cases where it does not start again no SetChargingProfile command is sent for unknown reason.

@andig
Copy link
Member Author

andig commented Jul 13, 2024

Indeed. Seems something is short-circuited but I don't see what:

[lp-1  ] DEBUG 2024/07/13 21:05:06 set charge mode: minpv
[lp-1  ] DEBUG 2024/07/13 21:05:06 charger status: B
[lp-1  ] DEBUG 2024/07/13 21:05:06 pv charge current: min 6A > 0A (1351W @ 1p, battery: false)
[lp-1  ] DEBUG 2024/07/13 21:05:06 max charge current: 6A
[ocpp  ] TRACE 2024/07/13 21:05:06 send zjb: [2,"3172667729","RemoteStartTransaction",{"connectorId":1,"idTag":"evcc","chargingProfile":{"chargingProfileId":1,"stackLevel":0,"chargingProfilePurpose":"TxProfile","chargingProfileKind":"Relative","chargingSchedule":{"chargingRateUnit":"A","chargingSchedulePeriod":[{"startPeriod":0,"limit":6}]}}}]
[ocpp  ] TRACE 2024/07/13 21:05:06 recv zjb: [3,"3172667729",{"status":"Accepted"}]
[lp-1  ] DEBUG 2024/07/13 21:05:06 charger enable
[lp-1  ] DEBUG 2024/07/13 21:05:06 wake-up timer: start
[ocpp  ] TRACE 2024/07/13 21:05:08 recv zjb: [2,"zfm1bukdpu774cisba8mqvzj","StartTransaction",{"connectorId":1,"idTag":"evcc","meterStart":547698,"timestamp":"2024-07-13T11:05:07Z"}]
[ocpp  ] TRACE 2024/07/13 21:05:08 send zjb: [3,"zfm1bukdpu774cisba8mqvzj",{"idTagInfo":{"status":"Accepted"},"transactionId":1}]
[ocpp  ] TRACE 2024/07/13 21:05:08 recv zjb: [2,"fv0qg09b0ehmhwum1wmoq1yt","MeterValues",{"connectorId":1,"transactionId":1,"meterValue":[{"timestamp":"2024-07-13T11:05:08Z","sampledValue":[{"value":"547698","context":"Sample.Periodic","measurand":"Energy.Active.Import.Register","format":"Raw","unit":"Wh"},{"value":"0","measurand":"Power.Active.Import","format":"Raw","unit":"W"},{"value":"0","phase":"L1-N","measurand":"Current.Import","format":"Raw","unit":"A"},{"value":"6","measurand":"Current.Offered","format":"Raw","unit":"A"},{"value":"232","phase":"L1-N","measurand":"Voltage","format":"Raw","unit":"V"}]}]}]
[ocpp  ] TRACE 2024/07/13 21:05:08 send zjb: [3,"fv0qg09b0ehmhwum1wmoq1yt",{}]
[ocpp  ] TRACE 2024/07/13 21:05:09 recv zjb: [2,"fin8jc72i20yls7qmwpaztr2","StatusNotification",{"connectorId":1,"errorCode":"NoError","status":"Charging","timestamp":"2024-07-13T11:05:09Z"}]
[ocpp  ] TRACE 2024/07/13 21:05:09 send zjb: [3,"fin8jc72i20yls7qmwpaztr2",{}]
[lp-1  ] DEBUG 2024/07/13 21:05:12 charger status: C
[lp-1  ] INFO 2024/07/13 21:05:12 start charging ->
[lp-1  ] DEBUG 2024/07/13 21:05:12 wake-up timer: stop
[lp-1  ] DEBUG 2024/07/13 21:05:12 charger vehicle id: evcc
[lp-1  ] DEBUG 2024/07/13 21:05:12 pv charge current: min 6A > 0.126A (1351W @ 1p, battery: false)
[lp-1  ] DEBUG 2024/07/13 21:05:22 charger status: C
[lp-1  ] DEBUG 2024/07/13 21:05:22 pv charge current: min 6A > 0A (1401W @ 1p, battery: false)
[ocpp  ] TRACE 2024/07/13 21:05:31 recv zjb: [2,"7dbz1fe03613el6fklm55r9d","MeterValues",{"connectorId":1,"transactionId":1,"meterValue":[{"timestamp":"2024-07-13T11:05:30Z","sampledValue":[{"value":"547702","context":"Sample.Periodic","measurand":"Energy.Active.Import.Register","format":"Raw","unit":"Wh"},{"value":"1182","measurand":"Power.Active.Import","format":"Raw","unit":"W"},{"value":"5","phase":"L1-N","measurand":"Current.Import","format":"Raw","unit":"A"},{"value":"6","measurand":"Current.Offered","format":"Raw","unit":"A"},{"value":"230","phase":"L1-N","measurand":"Voltage","format":"Raw","unit":"V"}]}]}]
[ocpp  ] TRACE 2024/07/13 21:05:31 send zjb: [3,"7dbz1fe03613el6fklm55r9d",{}]
[lp-1  ] DEBUG 2024/07/13 21:05:32 charger status: C
[lp-1  ] DEBUG 2024/07/13 21:05:32 pv charge current: min 6A > 0A (2598W @ 1p, battery: false)
[lp-1  ] DEBUG 2024/07/13 21:05:37 set charge mode: off
[lp-1  ] DEBUG 2024/07/13 21:05:37 charger status: C
[ocpp  ] TRACE 2024/07/13 21:05:37 send zjb: [2,"232648269","SetChargingProfile",{"connectorId":1,"csChargingProfiles":{"chargingProfileId":1,"transactionId":1,"stackLevel":0,"chargingProfilePurpose":"TxProfile","chargingProfileKind":"Relative","chargingSchedule":{"chargingRateUnit":"A","chargingSchedulePeriod":[{"startPeriod":0,"limit":0}]}}}]
[ocpp  ] TRACE 2024/07/13 21:05:37 recv zjb: [3,"232648269",{"status":"Accepted"}]
[lp-1  ] DEBUG 2024/07/13 21:05:37 charger disable
[lp-1  ] DEBUG 2024/07/13 21:05:37 wake-up timer: stop
[ocpp  ] TRACE 2024/07/13 21:05:39 recv zjb: [2,"2wkj9mlfp714wawtemas1v5f","StatusNotification",{"connectorId":1,"errorCode":"NoError","status":"SuspendedEVSE","timestamp":"2024-07-13T11:05:38Z"}]
[ocpp  ] TRACE 2024/07/13 21:05:39 send zjb: [3,"2wkj9mlfp714wawtemas1v5f",{}]
[lp-1  ] DEBUG 2024/07/13 21:05:42 charger status: B
[lp-1  ] INFO 2024/07/13 21:05:42 stop charging <-
[lp-1  ] DEBUG 2024/07/13 21:05:49 set charge mode: minpv
[lp-1  ] DEBUG 2024/07/13 21:05:49 charger status: B
[lp-1  ] DEBUG 2024/07/13 21:05:49 pv charge current: min 6A > 0A (1348W @ 1p, battery: false)
[lp-1  ] DEBUG 2024/07/13 21:05:49 charger enable
[lp-1  ] DEBUG 2024/07/13 21:05:49 wake-up timer: start
[ocpp  ] TRACE 2024/07/13 21:05:50 recv zjb: [2,"gyfu6op1bdguzoz3bkc9zbzc","MeterValues",{"connectorId":1,"transactionId":1,"meterValue":[{"timestamp":"2024-07-13T11:05:50Z","sampledValue":[{"value":"547704","context":"Sample.Periodic","measurand":"Energy.Active.Import.Register","format":"Raw","unit":"Wh"},{"value":"0","measurand":"Power.Active.Import","format":"Raw","unit":"W"},{"value":"0","phase":"L1-N","measurand":"Current.Import","format":"Raw","unit":"A"},{"value":"6","measurand":"Current.Offered","format":"Raw","unit":"A"},{"value":"231","phase":"L1-N","measurand":"Voltage","format":"Raw","unit":"V"}]}]}]
[ocpp  ] TRACE 2024/07/13 21:05:50 send zjb: [3,"gyfu6op1bdguzoz3bkc9zbzc",{}]

@andig
Copy link
Member Author

andig commented Jul 13, 2024

Ahhh: found and fixed: 68edb17. Please retry. Also the enable branch needs to switch methods once we have a transaction.

@andig
Copy link
Member Author

andig commented Jul 28, 2024

@ross-w would be great if you could test, only cosmetic changes to be done.

@andig
Copy link
Member Author

andig commented Aug 6, 2024

@ross-w currently nightly would be great to get another test- thank you!

@ross-w
Copy link
Contributor

ross-w commented Aug 6, 2024

@andig thanks for that. Testing with latest nightly, I needed to change my config to add remoteStart and remove noStop, but it does now work. It does have a long delay (about a minute) between selecting to charge and the charge starting (unlike the current released version using noStop), but it does work. Stopping is immediate.

Trace logs for ocpp below, with charge mode logs included.

[ocpp  ] DEBUG 2024/08/06 12:41:34 charge point connected: zjb
[ocpp  ] TRACE 2024/08/06 12:41:34 recv zjb: [2,"cxmrujzmlrcaszwx4en1ulz8","StatusNotification",{"connectorId":0,"errorCode":"NoError","status":"Available","timestamp":"2024-08-06T10:41:33Z"}]
[ocpp  ] TRACE 2024/08/06 12:41:34 recv zjb: [2,"4a7iiw2h6ayrfoq2nsu148mb","StatusNotification",{"connectorId":1,"errorCode":"NoError","status":"Preparing","timestamp":"2024-08-06T10:41:33Z"}]
[ocpp  ] TRACE 2024/08/06 12:41:34 send zjb: [3,"4a7iiw2h6ayrfoq2nsu148mb",{}]
[ocpp  ] TRACE 2024/08/06 12:41:35 send zjb: [2,"753714930","GetConfiguration",{}]
[ocpp  ] TRACE 2024/08/06 12:41:35 recv zjb: [3,"753714930",{"configurationKey":[{"key":"AllowOfflineTxForUnknownId","readonly":false,"value":"true"},{"key":"AuthorizationCacheEnabled","readonly":false,"value":"true"},{"key":"AuthorizeRemoteTxRequests","readonly":false,"value":"false"},{"key":"ClockAlignedDataInterval","readonly":false,"value":"0"},{"key":"ConnectionTimeOut","readonly":false,"value":"120"},{"key":"GetConfigurationMaxKeys","readonly":true,"value":"10"},{"key":"HeartbeatInterval","readonly":false,"value":"60"},{"key":"LocalAuthorizeOffline","readonly":false,"value":"true"},{"key":"LocalPreAuthorize","readonly":false,"value":"true"},{"key":"MeterValueSampleInterval","readonly":false,"value":"10"},{"key":"MinimumStatusDuration","readonly":false,"value":"1"},{"key":"NumberOfConnectors","readonly":true,"value":"1"},{"key":"ResetRetries","readonly":false,"value":"1"},{"key":"StopTransactionOnEVSideDisconnect","readonly":false,"value":"true"},{"key":"StopTransactionOnInvalidId","readonly":false,"value":"true"},{"key":"TransactionMessageAttempts","readonly":false,"value":"3"},{"key":"TransactionMessageRetryInterval","readonly":false,"value":"5"},{"key":"UnlockConnectorOnEVSideDisconnect","readonly":false,"value":"true"},{"key":"WebSocketPingInterval","readonly":false,"value":"30"},{"key":"LocalAuthListEnabled","readonly":false,"value":"true"},{"key":"LocalAuthListMaxLength","readonly":true,"value":"200"},{"key":"SendLocalListMaxLength","readonly":true,"value":"10"},{"key":"ReserveConnectorZeroSupported","readonly":true,"value":"true"},{"key":"ChargeProfileMaxStackLevel","readonly":true,"value":"10"},{"key":"ChargingScheduleAllowedChargingRateUnit","readonly":true,"value":"Current,Power"},{"key":"ChargingScheduleMaxPeriods","readonly":true,"value":"10"},{"key":"ConnectorSwitch3to1PhaseSupported","readonly":true,"value":"false"},{"key":"MaxChargingProfilesInstalled","readonly":true,"value":"20"}]}]
[ocpp  ] TRACE 2024/08/06 12:41:35 send zjb: [2,"2332058160","ChangeConfiguration",{"key":"MeterValuesSampledData","value":"Energy.Active.Import.Register"}]
[ocpp  ] TRACE 2024/08/06 12:41:35 recv zjb: [3,"2332058160",{"status":"Accepted"}]
[ocpp  ] TRACE 2024/08/06 12:41:35 send zjb: [2,"1383255008","ChangeConfiguration",{"key":"MeterValuesSampledData","value":"Power.Active.Import"}]
[ocpp  ] TRACE 2024/08/06 12:41:36 recv zjb: [3,"1383255008",{"status":"Accepted"}]
[ocpp  ] TRACE 2024/08/06 12:41:36 send zjb: [2,"4102566411","ChangeConfiguration",{"key":"MeterValuesSampledData","value":"SoC"}]
[ocpp  ] TRACE 2024/08/06 12:41:36 recv zjb: [3,"4102566411",{"status":"Accepted"}]
[ocpp  ] TRACE 2024/08/06 12:41:36 send zjb: [2,"208787011","ChangeConfiguration",{"key":"MeterValuesSampledData","value":"Current.Offered"}]
[ocpp  ] TRACE 2024/08/06 12:41:37 recv zjb: [3,"208787011",{"status":"Accepted"}]
[ocpp  ] TRACE 2024/08/06 12:41:37 send zjb: [2,"2131284993","ChangeConfiguration",{"key":"MeterValuesSampledData","value":"Power.Offered"}]
[ocpp  ] TRACE 2024/08/06 12:41:37 recv zjb: [3,"2131284993",{"status":"Accepted"}]
[ocpp  ] TRACE 2024/08/06 12:41:37 send zjb: [2,"908884930","ChangeConfiguration",{"key":"MeterValuesSampledData","value":"Current.Import"}]
[ocpp  ] TRACE 2024/08/06 12:41:37 recv zjb: [3,"908884930",{"status":"Accepted"}]
[ocpp  ] TRACE 2024/08/06 12:41:37 send zjb: [2,"4135063379","ChangeConfiguration",{"key":"MeterValuesSampledData","value":"Voltage"}]
[ocpp  ] TRACE 2024/08/06 12:41:37 recv zjb: [3,"4135063379",{"status":"Accepted"}]
[ocpp  ] TRACE 2024/08/06 12:41:37 send zjb: [2,"1108548328","ChangeConfiguration",{"key":"MeterValuesSampledData","value":"Energy.Active.Import.Register"}]
[ocpp  ] TRACE 2024/08/06 12:41:37 recv zjb: [3,"1108548328",{"status":"Accepted"}]
[ocpp  ] TRACE 2024/08/06 12:41:37 send zjb: [2,"3679269059","ChangeConfiguration",{"key":"MeterValueSampleInterval","value":"10"}]
[ocpp  ] TRACE 2024/08/06 12:41:37 recv zjb: [3,"3679269059",{"status":"Accepted"}]
[ocpp  ] TRACE 2024/08/06 12:41:37 send zjb: [2,"3925561591","ChangeConfiguration",{"key":"WebSocketPingInterval","value":"30"}]
[ocpp  ] TRACE 2024/08/06 12:41:37 recv zjb: [3,"3925561591",{"status":"Accepted"}]
[lp-1  ] WARN 2024/08/06 12:41:37 deprecated: maxcurrent setting is ignored, please remove
[lp-1  ] WARN 2024/08/06 12:41:37 deprecated: phases setting is ignored, please remove
[lp-1  ] INFO 2024/08/06 12:41:40 loadpoint 1:
[lp-1  ] INFO 2024/08/06 12:41:40   mode:        pv
[lp-1  ] INFO 2024/08/06 12:41:40   charger:     power ✗ energy ✓ currents ✗ phases ✗ wakeup ✗
[lp-1  ] INFO 2024/08/06 12:41:40   meters:      charge ✗
[lp-1  ] DEBUG 2024/08/06 12:41:40 !! active phases: 1p = min(0p measured 0p vehicle 1p physical 0p charger)
[lp-1  ] DEBUG 2024/08/06 12:41:40 phase timer inactive
[lp-1  ] DEBUG 2024/08/06 12:41:40 pv timer inactive
[lp-1  ] INFO 2024/08/06 12:41:40 vehicle updated: unknown -> Ioniq 5
[lp-1  ] DEBUG 2024/08/06 12:41:40 set charge mode: pv
[lp-1  ] DEBUG 2024/08/06 12:41:40 !! active phases: 1p = min(0p measured 0p vehicle 1p physical 0p charger)
[ocpp  ] TRACE 2024/08/06 12:41:40 send zjb: [2,"3761197280","GetCompositeSchedule",{"connectorId":1,"duration":60}]
[ocpp  ] TRACE 2024/08/06 12:41:40 recv zjb: [3,"3761197280",{"status":"Accepted","connectorId":1,"scheduleStart":"2024-08-06T10:41:39Z","chargingSchedule":{"duration":60,"chargingRateUnit":"A","chargingSchedulePeriod":[{"startPeriod":0,"limit":6.0}]}}]
[lp-1  ] DEBUG 2024/08/06 12:41:40 !! active phases: 1p = min(0p measured 0p vehicle 1p physical 0p charger)
[ocpp  ] TRACE 2024/08/06 12:41:40 send zjb: [2,"1717491598","SetChargingProfile",{"connectorId":1,"csChargingProfiles":{"chargingProfileId":20,"stackLevel":10,"chargingProfilePurpose":"TxDefaultProfile","chargingProfileKind":"Absolute","chargingSchedule":{"startSchedule":"2024-08-06T10:41:40Z","chargingRateUnit":"A","chargingSchedulePeriod":[{"startPeriod":0,"limit":6}]}}}]
[ocpp  ] TRACE 2024/08/06 12:41:40 recv zjb: [3,"1717491598",{"status":"Accepted"}]
[lp-1  ] DEBUG 2024/08/06 12:41:40 max charge current: 6A
[lp-1  ] DEBUG 2024/08/06 12:41:40 !! active phases: 1p = min(0p measured 0p vehicle 1p physical 0p charger)
[lp-1  ] DEBUG 2024/08/06 12:41:40 charge power: 0W
[lp-1  ] DEBUG 2024/08/06 12:41:40 !! active phases: 1p = min(0p measured 0p vehicle 1p physical 0p charger)
[ocpp  ] TRACE 2024/08/06 12:41:40 send zjb: [2,"1370399521","RemoteStartTransaction",{"connectorId":1,"idTag":"evcc"}]
[ocpp  ] TRACE 2024/08/06 12:41:41 recv zjb: [3,"1370399521",{"status":"Accepted"}]
[lp-1  ] DEBUG 2024/08/06 12:41:41 charger status: B
[lp-1  ] INFO 2024/08/06 12:41:41 car connected
[lp-1  ] DEBUG 2024/08/06 12:41:41 pv timer elapse
[lp-1  ] DEBUG 2024/08/06 12:41:41 pv timer inactive
[lp-1  ] DEBUG 2024/08/06 12:41:41 !! active phases: 1p = min(0p measured 0p vehicle 1p physical 0p charger)
[ocpp  ] TRACE 2024/08/06 12:41:42 recv zjb: [2,"4rkkq2hu5xn9pjcaszj3gy7a","StartTransaction",{"connectorId":1,"idTag":"evcc","meterStart":714061,"timestamp":"2024-08-06T10:41:41Z"}]
[ocpp  ] TRACE 2024/08/06 12:41:42 send zjb: [3,"4rkkq2hu5xn9pjcaszj3gy7a",{"idTagInfo":{"status":"Accepted"},"transactionId":1}]
[lp-1  ] DEBUG 2024/08/06 12:41:42 vehicle soc: 53%
[ocpp  ] TRACE 2024/08/06 12:41:42 send zjb: [2,"1180456531","GetCompositeSchedule",{"connectorId":1,"duration":60}]
[ocpp  ] TRACE 2024/08/06 12:41:42 recv zjb: [3,"1180456531",{"status":"Accepted","connectorId":1,"scheduleStart":"2024-08-06T10:41:41Z","chargingSchedule":{"duration":60,"chargingRateUnit":"A","chargingSchedulePeriod":[{"startPeriod":0,"limit":6.0}]}}]
[lp-1  ] DEBUG 2024/08/06 12:41:42 !! active phases: 1p = min(0p measured 0p vehicle 1p physical 0p charger)
[lp-1  ] DEBUG 2024/08/06 12:41:42 pv charge current: 0A = 0A + -2.23A (514W @ 1p)
[lp-1  ] DEBUG 2024/08/06 12:41:42 projected site power 514W >= 0W disable threshold
[lp-1  ] DEBUG 2024/08/06 12:41:42 pv disable in 0s
[lp-1  ] DEBUG 2024/08/06 12:41:42 pv disable timer elapsed
[lp-1  ] DEBUG 2024/08/06 12:41:42 !! active phases: 1p = min(0p measured 0p vehicle 1p physical 0p charger)
[ocpp  ] TRACE 2024/08/06 12:41:42 send zjb: [2,"2923753524","SetChargingProfile",{"connectorId":1,"csChargingProfiles":{"chargingProfileId":20,"stackLevel":10,"chargingProfilePurpose":"TxDefaultProfile","chargingProfileKind":"Absolute","chargingSchedule":{"startSchedule":"2024-08-06T10:41:42Z","chargingRateUnit":"A","chargingSchedulePeriod":[{"startPeriod":0,"limit":0}]}}}]
[ocpp  ] TRACE 2024/08/06 12:41:43 recv zjb: [3,"2923753524",{"status":"Accepted"}]
[lp-1  ] DEBUG 2024/08/06 12:41:43 charger disable
[lp-1  ] DEBUG 2024/08/06 12:41:43 !! active phases: 1p = min(0p measured 0p vehicle 1p physical 0p charger)
[lp-1  ] DEBUG 2024/08/06 12:41:43 wake-up timer: stop
[lp-1  ] DEBUG 2024/08/06 12:41:43 charge power: 0W
[lp-1  ] DEBUG 2024/08/06 12:41:43 !! active phases: 1p = min(0p measured 0p vehicle 1p physical 0p charger)
[lp-1  ] DEBUG 2024/08/06 12:41:43 charger status: B
[lp-1  ] DEBUG 2024/08/06 12:41:43 charger vehicle id: evcc
[ocpp  ] TRACE 2024/08/06 12:41:43 send zjb: [2,"3105277940","GetCompositeSchedule",{"connectorId":1,"duration":60}]
[ocpp  ] TRACE 2024/08/06 12:41:43 recv zjb: [2,"15yycjrtnnswp0hahmvz775x","MeterValues",{"connectorId":1,"transactionId":1,"meterValue":[{"timestamp":"2024-08-06T10:41:42Z","sampledValue":[{"value":"714061","context":"Sample.Periodic","measurand":"Energy.Active.Import.Register","format":"Raw","unit":"Wh"},{"value":"0","measurand":"Power.Active.Import","format":"Raw","unit":"W"}]}]}]
[ocpp  ] TRACE 2024/08/06 12:41:43 send zjb: [3,"15yycjrtnnswp0hahmvz775x",{}]
[ocpp  ] TRACE 2024/08/06 12:41:43 recv zjb: [3,"3105277940",{"status":"Accepted","connectorId":1,"scheduleStart":"2024-08-06T10:41:42Z","chargingSchedule":{"duration":60,"chargingRateUnit":"A","chargingSchedulePeriod":[]}}]
[ocpp  ] ERROR 2024/08/06 12:41:43 ocpp message (3105277940): PropertyConstraintViolation - Field CallResult.Payload.ChargingSchedule.ChargingSchedulePeriod must be minimum 1, but was 0 for feature GetCompositeSchedule ([3,"3105277940",{"status":"Accepted","connectorId":1,"scheduleStart":"2024-08-06T10:41:42Z","chargingSchedule":{"duration":60,"chargingRateUnit":"A","chargingSchedulePeriod":[]}}])
[ocpp  ] TRACE 2024/08/06 12:41:44 recv zjb: [2,"15yycjrtnnswp0hahmvz775x","MeterValues",{"connectorId":1,"transactionId":1,"meterValue":[{"timestamp":"2024-08-06T10:41:42Z","sampledValue":[{"value":"714061","context":"Sample.Periodic","measurand":"Energy.Active.Import.Register","format":"Raw","unit":"Wh"},{"value":"0","measurand":"Power.Active.Import","format":"Raw","unit":"W"}]}]}]
[ocpp  ] TRACE 2024/08/06 12:41:44 send zjb: [3,"15yycjrtnnswp0hahmvz775x",{}]
[ocpp  ] TRACE 2024/08/06 12:41:44 recv zjb: [2,"yqztb8v1cbmbj3xejobx0muk","StatusNotification",{"connectorId":1,"errorCode":"NoError","status":"Charging","timestamp":"2024-08-06T10:41:43Z"}]
[ocpp  ] TRACE 2024/08/06 12:41:44 send zjb: [3,"yqztb8v1cbmbj3xejobx0muk",{}]
[ocpp  ] TRACE 2024/08/06 12:41:48 recv zjb: [2,"nqtkvf6p6tgh37k0805chsc1","StatusNotification",{"connectorId":1,"errorCode":"NoError","status":"SuspendedEVSE","timestamp":"2024-08-06T10:41:47Z"}]
[ocpp  ] TRACE 2024/08/06 12:41:48 send zjb: [3,"nqtkvf6p6tgh37k0805chsc1",{}]
[ocpp  ] TRACE 2024/08/06 12:41:53 recv zjb: [2,"sc229jdsl1p4meg150t5utdx","MeterValues",{"connectorId":1,"transactionId":1,"meterValue":[{"timestamp":"2024-08-06T10:41:52Z","sampledValue":[{"value":"714061","context":"Sample.Periodic","measurand":"Energy.Active.Import.Register","format":"Raw","unit":"Wh"},{"value":"0","measurand":"Power.Active.Import","format":"Raw","unit":"W"}]}]}]
[ocpp  ] TRACE 2024/08/06 12:41:53 send zjb: [3,"sc229jdsl1p4meg150t5utdx",{}]
[lp-1  ] DEBUG 2024/08/06 12:41:58 set charge mode: minpv
[lp-1  ] DEBUG 2024/08/06 12:41:58 pv timer reset
[lp-1  ] DEBUG 2024/08/06 12:41:58 pv timer inactive
[ocpp  ] TRACE 2024/08/06 12:42:03 recv zjb: [2,"gj1kaaqirzoau2938mvom1c6","MeterValues",{"connectorId":1,"transactionId":1,"meterValue":[{"timestamp":"2024-08-06T10:42:02Z","sampledValue":[{"value":"714061","context":"Sample.Periodic","measurand":"Energy.Active.Import.Register","format":"Raw","unit":"Wh"},{"value":"0","measurand":"Power.Active.Import","format":"Raw","unit":"W"}]}]}]
[ocpp  ] TRACE 2024/08/06 12:42:03 send zjb: [3,"gj1kaaqirzoau2938mvom1c6",{}]
[ocpp  ] TRACE 2024/08/06 12:42:13 recv zjb: [2,"dx5e1y3a8bbx26b3kj3o0fhq","MeterValues",{"connectorId":1,"transactionId":1,"meterValue":[{"timestamp":"2024-08-06T10:42:12Z","sampledValue":[{"value":"714061","context":"Sample.Periodic","measurand":"Energy.Active.Import.Register","format":"Raw","unit":"Wh"},{"value":"0","measurand":"Power.Active.Import","format":"Raw","unit":"W"}]}]}]
[ocpp  ] TRACE 2024/08/06 12:42:13 send zjb: [3,"dx5e1y3a8bbx26b3kj3o0fhq",{}]
[ocpp  ] TRACE 2024/08/06 12:42:23 recv zjb: [2,"cbh3y8wy7kw2mhpf53li9qdb","MeterValues",{"connectorId":1,"transactionId":1,"meterValue":[{"timestamp":"2024-08-06T10:42:22Z","sampledValue":[{"value":"714061","context":"Sample.Periodic","measurand":"Energy.Active.Import.Register","format":"Raw","unit":"Wh"},{"value":"0","measurand":"Power.Active.Import","format":"Raw","unit":"W"}]}]}]
[ocpp  ] TRACE 2024/08/06 12:42:23 send zjb: [3,"cbh3y8wy7kw2mhpf53li9qdb",{}]
[ocpp  ] TRACE 2024/08/06 12:42:33 recv zjb: [2,"t4ueoto16apuy41525uds2gl","MeterValues",{"connectorId":1,"transactionId":1,"meterValue":[{"timestamp":"2024-08-06T10:42:32Z","sampledValue":[{"value":"714061","context":"Sample.Periodic","measurand":"Energy.Active.Import.Register","format":"Raw","unit":"Wh"},{"value":"0","measurand":"Power.Active.Import","format":"Raw","unit":"W"}]}]}]
[ocpp  ] TRACE 2024/08/06 12:42:33 send zjb: [3,"t4ueoto16apuy41525uds2gl",{}]
[ocpp  ] TRACE 2024/08/06 12:42:43 recv zjb: [2,"6s0tdzlht5jbxnyj1l1eph08","MeterValues",{"connectorId":1,"transactionId":1,"meterValue":[{"timestamp":"2024-08-06T10:42:42Z","sampledValue":[{"value":"714061","context":"Sample.Periodic","measurand":"Energy.Active.Import.Register","format":"Raw","unit":"Wh"},{"value":"0","measurand":"Power.Active.Import","format":"Raw","unit":"W"}]}]}]
[ocpp  ] TRACE 2024/08/06 12:42:43 send zjb: [3,"6s0tdzlht5jbxnyj1l1eph08",{}]
[lp-1  ] DEBUG 2024/08/06 12:42:43 !! active phases: 1p = min(0p measured 0p vehicle 1p physical 0p charger)
[lp-1  ] DEBUG 2024/08/06 12:42:43 pv charge current: min 6A > 0A (554W @ 1p, battery: false)
[lp-1  ] DEBUG 2024/08/06 12:42:43 !! active phases: 1p = min(0p measured 0p vehicle 1p physical 0p charger)
[ocpp  ] TRACE 2024/08/06 12:42:43 send zjb: [2,"1008212269","SetChargingProfile",{"connectorId":1,"csChargingProfiles":{"chargingProfileId":20,"stackLevel":10,"chargingProfilePurpose":"TxDefaultProfile","chargingProfileKind":"Absolute","chargingSchedule":{"startSchedule":"2024-08-06T10:42:43Z","chargingRateUnit":"A","chargingSchedulePeriod":[{"startPeriod":0,"limit":6}]}}}]
[ocpp  ] TRACE 2024/08/06 12:42:43 recv zjb: [3,"1008212269",{"status":"Accepted"}]
[lp-1  ] DEBUG 2024/08/06 12:42:43 max charge current: 6A
[lp-1  ] DEBUG 2024/08/06 12:42:43 !! active phases: 1p = min(0p measured 0p vehicle 1p physical 0p charger)
[ocpp  ] TRACE 2024/08/06 12:42:43 send zjb: [2,"1129750641","SetChargingProfile",{"connectorId":1,"csChargingProfiles":{"chargingProfileId":20,"stackLevel":10,"chargingProfilePurpose":"TxDefaultProfile","chargingProfileKind":"Absolute","chargingSchedule":{"startSchedule":"2024-08-06T10:42:43Z","chargingRateUnit":"A","chargingSchedulePeriod":[{"startPeriod":0,"limit":6}]}}}]
[ocpp  ] TRACE 2024/08/06 12:42:44 recv zjb: [3,"1129750641",{"status":"Accepted"}]
[lp-1  ] DEBUG 2024/08/06 12:42:44 charger enable
[lp-1  ] DEBUG 2024/08/06 12:42:44 !! active phases: 1p = min(0p measured 0p vehicle 1p physical 0p charger)
[lp-1  ] DEBUG 2024/08/06 12:42:44 wake-up timer: start
[lp-1  ] DEBUG 2024/08/06 12:42:44 charge power: 0W
[lp-1  ] DEBUG 2024/08/06 12:42:44 !! active phases: 1p = min(0p measured 0p vehicle 1p physical 0p charger)
[lp-1  ] DEBUG 2024/08/06 12:42:44 charger status: B
[lp-1  ] DEBUG 2024/08/06 12:42:44 !! active phases: 1p = min(0p measured 0p vehicle 1p physical 0p charger)
[lp-1  ] DEBUG 2024/08/06 12:42:44 pv charge current: min 6A > 0A (518W @ 1p, battery: false)
[lp-1  ] DEBUG 2024/08/06 12:42:44 !! active phases: 1p = min(0p measured 0p vehicle 1p physical 0p charger)
[lp-1  ] DEBUG 2024/08/06 12:42:44 charge power: 0W
[ocpp  ] TRACE 2024/08/06 12:42:45 recv zjb: [2,"kp89edlef9gmwceiv28ksofe","StatusNotification",{"connectorId":1,"errorCode":"NoError","status":"SuspendedEV","timestamp":"2024-08-06T10:42:44Z"}]
[ocpp  ] TRACE 2024/08/06 12:42:45 send zjb: [3,"kp89edlef9gmwceiv28ksofe",{}]
[ocpp  ] TRACE 2024/08/06 12:42:46 recv zjb: [2,"fgargq0afah0oa15zt08u446","StatusNotification",{"connectorId":1,"errorCode":"NoError","status":"Charging","timestamp":"2024-08-06T10:42:45Z"}]
[ocpp  ] TRACE 2024/08/06 12:42:46 send zjb: [3,"fgargq0afah0oa15zt08u446",{}]
[lp-1  ] DEBUG 2024/08/06 12:42:50 charge power: 0W
[lp-1  ] DEBUG 2024/08/06 12:42:52 !! active phases: 1p = min(0p measured 0p vehicle 1p physical 0p charger)
[lp-1  ] DEBUG 2024/08/06 12:42:52 charger status: C
[lp-1  ] INFO 2024/08/06 12:42:52 start charging ->
[lp-1  ] DEBUG 2024/08/06 12:42:52 wake-up timer: stop
[lp-1  ] DEBUG 2024/08/06 12:42:52 !! active phases: 1p = min(0p measured 0p vehicle 1p physical 0p charger)
[lp-1  ] DEBUG 2024/08/06 12:42:52 vehicle soc: 53%
[lp-1  ] DEBUG 2024/08/06 12:42:52 !! active phases: 1p = min(0p measured 0p vehicle 1p physical 0p charger)
[lp-1  ] DEBUG 2024/08/06 12:42:52 pv charge current: min 6A > 3.75A (518W @ 1p, battery: false)
[lp-1  ] DEBUG 2024/08/06 12:42:52 !! active phases: 1p = min(0p measured 0p vehicle 1p physical 0p charger)
[ocpp  ] TRACE 2024/08/06 12:42:53 recv zjb: [2,"naxblg2137gpq13rm80i4c9a","MeterValues",{"connectorId":1,"transactionId":1,"meterValue":[{"timestamp":"2024-08-06T10:42:52Z","sampledValue":[{"value":"714062","context":"Sample.Periodic","measurand":"Energy.Active.Import.Register","format":"Raw","unit":"Wh"},{"value":"1198","measurand":"Power.Active.Import","format":"Raw","unit":"W"}]}]}]
[ocpp  ] TRACE 2024/08/06 12:42:53 send zjb: [3,"naxblg2137gpq13rm80i4c9a",{}]
[lp-1  ] DEBUG 2024/08/06 12:43:00 set charge mode: pv
[lp-1  ] DEBUG 2024/08/06 12:43:00 charge power: 1380W
[lp-1  ] DEBUG 2024/08/06 12:43:00 !! active phases: 1p = min(0p measured 0p vehicle 1p physical 0p charger)
[lp-1  ] DEBUG 2024/08/06 12:43:00 !! session: chargeRater.chargedEnergy=0.0 - chargedAtStartup=0.0
[lp-1  ] DEBUG 2024/08/06 12:43:00 charger status: C
[lp-1  ] DEBUG 2024/08/06 12:43:00 vehicle soc: 53%
[lp-1  ] DEBUG 2024/08/06 12:43:00 !! active phases: 1p = min(0p measured 0p vehicle 1p physical 0p charger)
[lp-1  ] DEBUG 2024/08/06 12:43:00 pv charge current: 3.9A = 6A + -2.1A (484W @ 1p)
[lp-1  ] DEBUG 2024/08/06 12:43:00 projected site power 484W >= 0W disable threshold
[lp-1  ] DEBUG 2024/08/06 12:43:00 pv disable timer start: 3m0s
[lp-1  ] DEBUG 2024/08/06 12:43:00 pv disable in 3m0s
[lp-1  ] DEBUG 2024/08/06 12:43:00 !! active phases: 1p = min(0p measured 0p vehicle 1p physical 0p charger)
[lp-1  ] DEBUG 2024/08/06 12:43:00 charge power: 1380W
[ocpp  ] TRACE 2024/08/06 12:43:03 recv zjb: [2,"nxglahwd8u7oqelp90ekz6t0","MeterValues",{"connectorId":1,"transactionId":1,"meterValue":[{"timestamp":"2024-08-06T10:43:02Z","sampledValue":[{"value":"714065","context":"Sample.Periodic","measurand":"Energy.Active.Import.Register","format":"Raw","unit":"Wh"},{"value":"1170","measurand":"Power.Active.Import","format":"Raw","unit":"W"}]}]}]
[ocpp  ] TRACE 2024/08/06 12:43:03 send zjb: [3,"nxglahwd8u7oqelp90ekz6t0",{}]
[lp-1  ] DEBUG 2024/08/06 12:43:10 set charge mode: off
[lp-1  ] DEBUG 2024/08/06 12:43:10 pv timer reset
[lp-1  ] DEBUG 2024/08/06 12:43:10 pv timer inactive
[lp-1  ] DEBUG 2024/08/06 12:43:10 charge power: 1380W
[lp-1  ] DEBUG 2024/08/06 12:43:10 !! active phases: 1p = min(0p measured 0p vehicle 1p physical 0p charger)
[lp-1  ] DEBUG 2024/08/06 12:43:10 !! session: chargeRater.chargedEnergy=0.0 - chargedAtStartup=0.0
[lp-1  ] DEBUG 2024/08/06 12:43:10 charger status: C
[lp-1  ] DEBUG 2024/08/06 12:43:10 vehicle soc: 53%
[lp-1  ] DEBUG 2024/08/06 12:43:10 !! active phases: 1p = min(0p measured 0p vehicle 1p physical 0p charger)
[ocpp  ] TRACE 2024/08/06 12:43:10 send zjb: [2,"1344022536","SetChargingProfile",{"connectorId":1,"csChargingProfiles":{"chargingProfileId":20,"stackLevel":10,"chargingProfilePurpose":"TxDefaultProfile","chargingProfileKind":"Absolute","chargingSchedule":{"startSchedule":"2024-08-06T10:43:10Z","chargingRateUnit":"A","chargingSchedulePeriod":[{"startPeriod":0,"limit":0}]}}}]
[ocpp  ] TRACE 2024/08/06 12:43:10 recv zjb: [3,"1344022536",{"status":"Accepted"}]
[lp-1  ] DEBUG 2024/08/06 12:43:10 charger disable
[lp-1  ] DEBUG 2024/08/06 12:43:10 !! active phases: 1p = min(0p measured 0p vehicle 1p physical 0p charger)
[lp-1  ] DEBUG 2024/08/06 12:43:10 wake-up timer: stop
[lp-1  ] DEBUG 2024/08/06 12:43:10 charge power: 0W
[lp-1  ] DEBUG 2024/08/06 12:43:10 !! active phases: 1p = min(0p measured 0p vehicle 1p physical 0p charger)
[lp-1  ] DEBUG 2024/08/06 12:43:10 !! session: chargeRater.chargedEnergy=0.0 - chargedAtStartup=0.0
[lp-1  ] DEBUG 2024/08/06 12:43:10 charger status: C
[lp-1  ] DEBUG 2024/08/06 12:43:11 vehicle soc: 53%
[lp-1  ] DEBUG 2024/08/06 12:43:11 !! active phases: 1p = min(0p measured 0p vehicle 1p physical 0p charger)
[ocpp  ] TRACE 2024/08/06 12:43:12 recv zjb: [2,"4u83wvmgobmsk8nzgixxb0oj","StatusNotification",{"connectorId":1,"errorCode":"NoError","status":"SuspendedEVSE","timestamp":"2024-08-06T10:43:11Z"}]
[ocpp  ] TRACE 2024/08/06 12:43:12 send zjb: [3,"4u83wvmgobmsk8nzgixxb0oj",{}]
[ocpp  ] TRACE 2024/08/06 12:43:13 recv zjb: [2,"nfu3hauavpaqsiqxjb6542ww","MeterValues",{"connectorId":1,"transactionId":1,"meterValue":[{"timestamp":"2024-08-06T10:43:12Z","sampledValue":[{"value":"714068","context":"Sample.Periodic","measurand":"Energy.Active.Import.Register","format":"Raw","unit":"Wh"},{"value":"1166","measurand":"Power.Active.Import","format":"Raw","unit":"W"}]}]}]
[ocpp  ] TRACE 2024/08/06 12:43:13 send zjb: [3,"nfu3hauavpaqsiqxjb6542ww",{}]
[lp-1  ] DEBUG 2024/08/06 12:43:14 set charge mode: pv
[lp-1  ] DEBUG 2024/08/06 12:43:14 charge power: 0W
[lp-1  ] DEBUG 2024/08/06 12:43:14 !! active phases: 1p = min(0p measured 0p vehicle 1p physical 0p charger)
[lp-1  ] DEBUG 2024/08/06 12:43:14 !! session: chargeRater.chargedEnergy=0.0 - chargedAtStartup=0.0
[lp-1  ] DEBUG 2024/08/06 12:43:14 charger status: B
[lp-1  ] INFO 2024/08/06 12:43:14 stop charging <-
[lp-1  ] DEBUG 2024/08/06 12:43:14 !! session: chargedEnergy=0.0 > chargedEnergy=0.0
[lp-1  ] DEBUG 2024/08/06 12:43:14 !! session: start=0.000 stop=0.000 chargedEnergy=0.007
[lp-1  ] DEBUG 2024/08/06 12:43:14 !! active phases: 1p = min(0p measured 0p vehicle 1p physical 0p charger)
[lp-1  ] DEBUG 2024/08/06 12:43:14 vehicle soc: 53%
[lp-1  ] DEBUG 2024/08/06 12:43:14 !! active phases: 1p = min(0p measured 0p vehicle 1p physical 0p charger)
[lp-1  ] DEBUG 2024/08/06 12:43:14 pv charge current: 0A = 0A + -7.44A (1712W @ 1p)
[lp-1  ] DEBUG 2024/08/06 12:43:14 !! active phases: 1p = min(0p measured 0p vehicle 1p physical 0p charger)
[lp-1  ] DEBUG 2024/08/06 12:43:20 charge power: 0W
[ocpp  ] TRACE 2024/08/06 12:43:23 recv zjb: [2,"zq7ffzzoz0fxlbhrzoz83pvo","MeterValues",{"connectorId":1,"transactionId":1,"meterValue":[{"timestamp":"2024-08-06T10:43:22Z","sampledValue":[{"value":"714068","context":"Sample.Periodic","measurand":"Energy.Active.Import.Register","format":"Raw","unit":"Wh"},{"value":"0","measurand":"Power.Active.Import","format":"Raw","unit":"W"}]}]}]
[ocpp  ] TRACE 2024/08/06 12:43:23 send zjb: [3,"zq7ffzzoz0fxlbhrzoz83pvo",{}]
[lp-1  ] DEBUG 2024/08/06 12:43:30 charge power: 0W
[lp-1  ] DEBUG 2024/08/06 12:43:32 !! active phases: 1p = min(0p measured 0p vehicle 1p physical 0p charger)
[lp-1  ] DEBUG 2024/08/06 12:43:32 !! session: chargeRater.chargedEnergy=0.0 - chargedAtStartup=0.0
[lp-1  ] DEBUG 2024/08/06 12:43:32 charger status: B
[lp-1  ] DEBUG 2024/08/06 12:43:32 !! active phases: 1p = min(0p measured 0p vehicle 1p physical 0p charger)
[lp-1  ] DEBUG 2024/08/06 12:43:32 pv charge current: 0A = 0A + -2.1A (483W @ 1p)
[lp-1  ] DEBUG 2024/08/06 12:43:32 !! active phases: 1p = min(0p measured 0p vehicle 1p physical 0p charger)
[ocpp  ] TRACE 2024/08/06 12:43:33 recv zjb: [2,"i0uwlb388kbwlcnpoeoub8je","MeterValues",{"connectorId":1,"transactionId":1,"meterValue":[{"timestamp":"2024-08-06T10:43:32Z","sampledValue":[{"value":"714068","context":"Sample.Periodic","measurand":"Energy.Active.Import.Register","format":"Raw","unit":"Wh"},{"value":"0","measurand":"Power.Active.Import","format":"Raw","unit":"W"}]}]}]
[ocpp  ] TRACE 2024/08/06 12:43:33 send zjb: [3,"i0uwlb388kbwlcnpoeoub8je",{}]

@andig
Copy link
Member Author

andig commented Aug 6, 2024

t does have a long delay (about a minute) between selecting to charge and the charge starting (unlike the current released version using noStop)

Is that visible in the logs? /cc @premultiply

@ross-w
Copy link
Contributor

ross-w commented Aug 6, 2024

@andig you can see in the log above I selected minpv at 12:41:58, then it sent the SetChargingProfile request at 12:42:43

@andig
Copy link
Member Author

andig commented Aug 6, 2024

Hard to say- there's so little logging for the loadpoint?

@ross-w
Copy link
Contributor

ross-w commented Aug 6, 2024

@andig updated with more detail. I'm trying not to spam you will the full trace log which includes a lot of irrelevant stuff like MQTT, tariff, DB etc

@andig
Copy link
Member Author

andig commented Aug 6, 2024

Doesn't charge because there's simply not enough power:

[lp-1  ] DEBUG 2024/08/06 12:41:42 pv charge current: 0A = 0A + -2.23A (514W @ 1p)

@ross-w
Copy link
Contributor

ross-w commented Aug 6, 2024

@andig sorry for the alarm. I've tried it again and it seems fine. So in short, latest nightly works! There must have been something strange about my MQTT feed right as I booted evcc (it should not be anywhere near its limit at this time of night)

@ross-w
Copy link
Contributor

ross-w commented Aug 9, 2024

Latest nightly appears to have an issue and is perpetually stuck on waiting for local authentication. I'll do some more testing tonight and grab some logs
`

@ross-w
Copy link
Contributor

ross-w commented Aug 9, 2024

@andig here's the behaviour on the latest nightly

[zjb-1 ] DEBUG 2024/08/09 12:52:12 waiting for chargepoint: 5m0s
[ocpp  ] DEBUG 2024/08/09 12:52:32 charge point connected: zjb
[ocpp  ] TRACE 2024/08/09 12:52:32 recv zjb: [2,"g97zdjqothtwp5bdkjntn2hf","StatusNotification",{"connectorId":0,"errorCode":"NoError","status":"Available","timestamp":"2024-08-09T10:52:33Z"}]
[ocpp  ] TRACE 2024/08/09 12:52:32 send zjb: [3,"g97zdjqothtwp5bdkjntn2hf",{}]
[ocpp  ] TRACE 2024/08/09 12:52:33 recv zjb: [2,"h79w3lkk1wtzmim8u978trbr","StatusNotification",{"connectorId":1,"errorCode":"NoError","status":"Preparing","timestamp":"2024-08-09T10:52:33Z"}]
[ocpp  ] TRACE 2024/08/09 12:52:33 send zjb: [3,"h79w3lkk1wtzmim8u978trbr",{}]
[ocpp  ] TRACE 2024/08/09 12:52:33 send zjb: [2,"2942027420","GetConfiguration",{}]
[ocpp  ] TRACE 2024/08/09 12:52:33 recv zjb: [3,"2942027420",{"configurationKey":[{"key":"AllowOfflineTxForUnknownId","readonly":false,"value":"true"},{"key":"AuthorizationCacheEnabled","readonly":false,"value":"true"},{"key":"AuthorizeRemoteTxRequests","readonly":false,"value":"false"},{"key":"ClockAlignedDataInterval","readonly":false,"value":"0"},{"key":"ConnectionTimeOut","readonly":false,"value":"120"},{"key":"GetConfigurationMaxKeys","readonly":true,"value":"10"},{"key":"HeartbeatInterval","readonly":false,"value":"60"},{"key":"LocalAuthorizeOffline","readonly":false,"value":"true"},{"key":"LocalPreAuthorize","readonly":false,"value":"true"},{"key":"MeterValueSampleInterval","readonly":false,"value":"10"},{"key":"MinimumStatusDuration","readonly":false,"value":"1"},{"key":"NumberOfConnectors","readonly":true,"value":"1"},{"key":"ResetRetries","readonly":false,"value":"1"},{"key":"StopTransactionOnEVSideDisconnect","readonly":false,"value":"true"},{"key":"StopTransactionOnInvalidId","readonly":false,"value":"true"},{"key":"TransactionMessageAttempts","readonly":false,"value":"3"},{"key":"TransactionMessageRetryInterval","readonly":false,"value":"5"},{"key":"UnlockConnectorOnEVSideDisconnect","readonly":false,"value":"true"},{"key":"WebSocketPingInterval","readonly":false,"value":"30"},{"key":"LocalAuthListEnabled","readonly":false,"value":"true"},{"key":"LocalAuthListMaxLength","readonly":true,"value":"200"},{"key":"SendLocalListMaxLength","readonly":true,"value":"10"},{"key":"ReserveConnectorZeroSupported","readonly":true,"value":"true"},{"key":"ChargeProfileMaxStackLevel","readonly":true,"value":"10"},{"key":"ChargingScheduleAllowedChargingRateUnit","readonly":true,"value":"Current,Power"},{"key":"ChargingScheduleMaxPeriods","readonly":true,"value":"10"},{"key":"ConnectorSwitch3to1PhaseSupported","readonly":true,"value":"false"},{"key":"MaxChargingProfilesInstalled","readonly":true,"value":"20"}]}]
[ocpp  ] TRACE 2024/08/09 12:52:33 send zjb: [2,"549291329","ChangeConfiguration",{"key":"MeterValuesSampledData","value":"Energy.Active.Import.Register"}]
[ocpp  ] TRACE 2024/08/09 12:52:33 recv zjb: [3,"549291329",{"status":"Accepted"}]
[ocpp  ] TRACE 2024/08/09 12:52:33 send zjb: [2,"3786760549","ChangeConfiguration",{"key":"MeterValuesSampledData","value":"Power.Active.Import"}]
[ocpp  ] TRACE 2024/08/09 12:52:33 recv zjb: [3,"3786760549",{"status":"Accepted"}]
[ocpp  ] TRACE 2024/08/09 12:52:33 send zjb: [2,"2661204682","ChangeConfiguration",{"key":"MeterValuesSampledData","value":"SoC"}]
[ocpp  ] TRACE 2024/08/09 12:52:34 recv zjb: [3,"2661204682",{"status":"Accepted"}]
[ocpp  ] TRACE 2024/08/09 12:52:34 send zjb: [2,"3773003073","ChangeConfiguration",{"key":"MeterValuesSampledData","value":"Current.Offered"}]
[ocpp  ] TRACE 2024/08/09 12:52:34 recv zjb: [3,"3773003073",{"status":"Accepted"}]
[ocpp  ] TRACE 2024/08/09 12:52:34 send zjb: [2,"1301889724","ChangeConfiguration",{"key":"MeterValuesSampledData","value":"Power.Offered"}]
[ocpp  ] TRACE 2024/08/09 12:52:34 recv zjb: [3,"1301889724",{"status":"Accepted"}]
[ocpp  ] TRACE 2024/08/09 12:52:34 send zjb: [2,"1370134030","ChangeConfiguration",{"key":"MeterValuesSampledData","value":"Current.Import"}]
[ocpp  ] TRACE 2024/08/09 12:52:34 recv zjb: [3,"1370134030",{"status":"Accepted"}]
[ocpp  ] TRACE 2024/08/09 12:52:34 send zjb: [2,"4264633097","ChangeConfiguration",{"key":"MeterValuesSampledData","value":"Voltage"}]
[ocpp  ] TRACE 2024/08/09 12:52:34 recv zjb: [3,"4264633097",{"status":"Accepted"}]
[ocpp  ] TRACE 2024/08/09 12:52:34 send zjb: [2,"3331998625","ChangeConfiguration",{"key":"MeterValuesSampledData","value":"Energy.Active.Import.Register"}]
[ocpp  ] TRACE 2024/08/09 12:52:34 recv zjb: [3,"3331998625",{"status":"Accepted"}]
[ocpp  ] TRACE 2024/08/09 12:52:34 send zjb: [2,"1021215764","ChangeConfiguration",{"key":"MeterValueSampleInterval","value":"10"}]
[ocpp  ] TRACE 2024/08/09 12:52:34 recv zjb: [3,"1021215764",{"status":"Accepted"}]
[ocpp  ] TRACE 2024/08/09 12:52:34 send zjb: [2,"3840926526","ChangeConfiguration",{"key":"WebSocketPingInterval","value":"30"}]
[ocpp  ] TRACE 2024/08/09 12:52:34 recv zjb: [3,"3840926526",{"status":"Accepted"}]
[lp-1  ] WARN 2024/08/09 12:52:34 deprecated: maxcurrent setting is ignored, please remove
[lp-1  ] WARN 2024/08/09 12:52:34 deprecated: phases setting is ignored, please remove
[lp-1  ] INFO 2024/08/09 12:52:37 loadpoint 1:
[lp-1  ] INFO 2024/08/09 12:52:37   mode:        pv
[lp-1  ] INFO 2024/08/09 12:52:37   charger:     power ✗ energy ✓ currents ✗ phases ✗ wakeup ✗
[lp-1  ] INFO 2024/08/09 12:52:37   meters:      charge ✗
[lp-1  ] DEBUG 2024/08/09 12:52:37 phase timer inactive
[lp-1  ] DEBUG 2024/08/09 12:52:37 pv timer inactive
[lp-1  ] INFO 2024/08/09 12:52:37 vehicle updated: unknown -> Ioniq 5
[lp-1  ] DEBUG 2024/08/09 12:52:37 set charge mode: pv
[ocpp  ] TRACE 2024/08/09 12:52:37 send zjb: [2,"2586819892","GetCompositeSchedule",{"connectorId":1,"duration":60}]
[ocpp  ] TRACE 2024/08/09 12:52:37 recv zjb: [3,"2586819892",{"status":"Accepted","connectorId":1,"scheduleStart":"2024-08-09T10:52:38Z","chargingSchedule":{"duration":60,"chargingRateUnit":"A","chargingSchedulePeriod":[]}}]
[ocpp  ] ERROR 2024/08/09 12:52:37 ocpp message (2586819892): PropertyConstraintViolation - Field CallResult.Payload.ChargingSchedule.ChargingSchedulePeriod must be minimum 1, but was 0 for feature GetCompositeSchedule ([3,"2586819892",{"status":"Accepted","connectorId":1,"scheduleStart":"2024-08-09T10:52:38Z","chargingSchedule":{"duration":60,"chargingRateUnit":"A","chargingSchedulePeriod":[]}}])
[ocpp  ] TRACE 2024/08/09 12:52:37 recv zjb: [2,"wflmortjj7hpa5y8k27ssyey","StopTransaction",{"idTag":"230400221","meterStop":727803,"timestamp":"2024-08-09T10:52:13Z","transactionId":1,"reason":"EVDisconnected"}]
[ocpp  ] TRACE 2024/08/09 12:52:37 send zjb: [3,"wflmortjj7hpa5y8k27ssyey",{"idTagInfo":{"status":"Accepted"}}]
[lp-1  ] DEBUG 2024/08/09 12:53:37 charge power: 0W
[zjb-1 ] WARN 2024/08/09 12:53:37 waiting for local authentication
[lp-1  ] DEBUG 2024/08/09 12:53:37 charger status: B
[lp-1  ] INFO 2024/08/09 12:53:37 car connected
[lp-1  ] DEBUG 2024/08/09 12:53:37 pv timer elapse
[lp-1  ] DEBUG 2024/08/09 12:53:37 pv timer inactive
[ocpp  ] TRACE 2024/08/09 12:53:38 recv zjb: [2,"wqz4l29ejnjmm0p04hdaitxo","Heartbeat",{}]
[ocpp  ] TRACE 2024/08/09 12:53:38 send zjb: [3,"wqz4l29ejnjmm0p04hdaitxo",{"currentTime":"2024-08-09T10:53:38Z"}]
[lp-1  ] DEBUG 2024/08/09 12:53:38 vehicle soc: 68%
[ocpp  ] TRACE 2024/08/09 12:53:38 send zjb: [2,"3464655160","GetCompositeSchedule",{"connectorId":1,"duration":60}]
[ocpp  ] TRACE 2024/08/09 12:53:38 recv zjb: [3,"3464655160",{"status":"Accepted","connectorId":1,"scheduleStart":"2024-08-09T10:53:38Z","chargingSchedule":{"duration":60,"chargingRateUnit":"A","chargingSchedulePeriod":[]}}]
[ocpp  ] ERROR 2024/08/09 12:53:38 ocpp message (3464655160): PropertyConstraintViolation - Field CallResult.Payload.ChargingSchedule.ChargingSchedulePeriod must be minimum 1, but was 0 for feature GetCompositeSchedule ([3,"3464655160",{"status":"Accepted","connectorId":1,"scheduleStart":"2024-08-09T10:53:38Z","chargingSchedule":{"duration":60,"chargingRateUnit":"A","chargingSchedulePeriod":[]}}])
[lp-1  ] DEBUG 2024/08/09 12:53:43 set charge mode: minpv
[lp-1  ] DEBUG 2024/08/09 12:53:43 pv timer reset
[lp-1  ] DEBUG 2024/08/09 12:53:43 pv timer inactive
[lp-1  ] DEBUG 2024/08/09 12:54:38 pv charge current: min 6A > 0A (439W @ 1p, battery: false)
[ocpp  ] TRACE 2024/08/09 12:54:38 send zjb: [2,"25632121","SetChargingProfile",{"connectorId":1,"csChargingProfiles":{"chargingProfileId":20,"stackLevel":10,"chargingProfilePurpose":"TxDefaultProfile","chargingProfileKind":"Absolute","chargingSchedule":{"startSchedule":"2024-08-09T10:54:38Z","chargingRateUnit":"A","chargingSchedulePeriod":[{"startPeriod":0,"limit":6}]}}}]
[ocpp  ] TRACE 2024/08/09 12:54:38 recv zjb: [3,"25632121",{"status":"Accepted"}]
[lp-1  ] DEBUG 2024/08/09 12:54:38 max charge current: 6A
[ocpp  ] TRACE 2024/08/09 12:54:38 send zjb: [2,"1563673556","SetChargingProfile",{"connectorId":1,"csChargingProfiles":{"chargingProfileId":20,"stackLevel":10,"chargingProfilePurpose":"TxDefaultProfile","chargingProfileKind":"Absolute","chargingSchedule":{"startSchedule":"2024-08-09T10:54:38Z","chargingRateUnit":"A","chargingSchedulePeriod":[{"startPeriod":0,"limit":6}]}}}]
[ocpp  ] TRACE 2024/08/09 12:54:38 recv zjb: [3,"1563673556",{"status":"Accepted"}]
[lp-1  ] DEBUG 2024/08/09 12:54:38 charger enable
[lp-1  ] DEBUG 2024/08/09 12:54:38 wake-up timer: start
[lp-1  ] DEBUG 2024/08/09 12:54:38 charge power: 0W
[lp-1  ] DEBUG 2024/08/09 12:54:39 charge power: 0W
[zjb-1 ] WARN 2024/08/09 12:54:39 waiting for local authentication
[lp-1  ] DEBUG 2024/08/09 12:54:39 charger status: B
[ocpp  ] TRACE 2024/08/09 12:54:39 send zjb: [2,"64155384","GetCompositeSchedule",{"connectorId":1,"duration":60}]
[ocpp  ] TRACE 2024/08/09 12:54:39 recv zjb: [3,"64155384",{"status":"Accepted","connectorId":1,"scheduleStart":"2024-08-09T10:54:39Z","chargingSchedule":{"duration":60,"chargingRateUnit":"A","chargingSchedulePeriod":[{"startPeriod":0,"limit":6.0}]}}]
[lp-1  ] DEBUG 2024/08/09 12:54:39 pv charge current: min 6A > 0A (447W @ 1p, battery: false)
[lp-1  ] DEBUG 2024/08/09 12:54:47 charge power: 0W
[zjb-1 ] WARN 2024/08/09 12:54:47 waiting for local authentication
[lp-1  ] DEBUG 2024/08/09 12:54:47 charger status: B
[ocpp  ] TRACE 2024/08/09 12:54:47 send zjb: [2,"3365033808","GetCompositeSchedule",{"connectorId":1,"duration":60}]
[ocpp  ] TRACE 2024/08/09 12:54:47 recv zjb: [3,"3365033808",{"status":"Accepted","connectorId":1,"scheduleStart":"2024-08-09T10:54:47Z","chargingSchedule":{"duration":60,"chargingRateUnit":"A","chargingSchedulePeriod":[{"startPeriod":0,"limit":6.0}]}}]
[lp-1  ] DEBUG 2024/08/09 12:54:47 pv charge current: min 6A > 0A (446W @ 1p, battery: false)
[lp-1  ] DEBUG 2024/08/09 12:54:57 charge power: 0W
[lp-1  ] DEBUG 2024/08/09 12:55:07 charge power: 0W
[zjb-1 ] WARN 2024/08/09 12:55:07 waiting for local authentication
[lp-1  ] DEBUG 2024/08/09 12:55:07 charger status: B
[ocpp  ] TRACE 2024/08/09 12:55:07 send zjb: [2,"174691472","GetCompositeSchedule",{"connectorId":1,"duration":60}]
[ocpp  ] TRACE 2024/08/09 12:55:07 recv zjb: [3,"174691472",{"status":"Accepted","connectorId":1,"scheduleStart":"2024-08-09T10:55:07Z","chargingSchedule":{"duration":60,"chargingRateUnit":"A","chargingSchedulePeriod":[{"startPeriod":0,"limit":6.0}]}}]
[lp-1  ] DEBUG 2024/08/09 12:55:07 pv charge current: min 6A > 0A (455W @ 1p, battery: false)
[lp-1  ] DEBUG 2024/08/09 12:55:17 charge power: 0W
[lp-1  ] DEBUG 2024/08/09 12:55:27 charge power: 0W
[zjb-1 ] WARN 2024/08/09 12:55:27 waiting for local authentication
[lp-1  ] DEBUG 2024/08/09 12:55:27 charger status: B
[ocpp  ] TRACE 2024/08/09 12:55:27 send zjb: [2,"1449539915","GetCompositeSchedule",{"connectorId":1,"duration":60}]
[ocpp  ] TRACE 2024/08/09 12:55:27 recv zjb: [3,"1449539915",{"status":"Accepted","connectorId":1,"scheduleStart":"2024-08-09T10:55:27Z","chargingSchedule":{"duration":60,"chargingRateUnit":"A","chargingSchedulePeriod":[{"startPeriod":0,"limit":6.0}]}}]
[lp-1  ] DEBUG 2024/08/09 12:55:27 pv charge current: min 6A > 0A (444W @ 1p, battery: false)
[lp-1  ] DEBUG 2024/08/09 12:55:37 charge power: 0W
[lp-1  ] DEBUG 2024/08/09 12:55:47 charge power: 0W
[zjb-1 ] WARN 2024/08/09 12:55:47 waiting for local authentication
[lp-1  ] DEBUG 2024/08/09 12:55:47 charger status: B
[ocpp  ] TRACE 2024/08/09 12:55:47 send zjb: [2,"90321759","GetCompositeSchedule",{"connectorId":1,"duration":60}]
[ocpp  ] TRACE 2024/08/09 12:55:47 recv zjb: [3,"90321759",{"status":"Accepted","connectorId":1,"scheduleStart":"2024-08-09T10:55:47Z","chargingSchedule":{"duration":60,"chargingRateUnit":"A","chargingSchedulePeriod":[{"startPeriod":0,"limit":6.0}]}}]
[lp-1  ] DEBUG 2024/08/09 12:55:47 pv charge current: min 6A > 0A (441W @ 1p, battery: false)

@premultiply
Copy link
Member

There is no way to walk into the conditional path where this message is generated if remotestart: true is set.

	if c.conn.NeedsAuthentication() {
		if c.remoteStart {
			// lock the cable by starting remote transaction after vehicle connected
			if err := c.initTransaction(); err != nil {
				c.log.WARN.Printf("failed to start remote transaction: %v", err)
			}
		} else {
			// TODO: bring this status to UI
			c.log.WARN.Printf("waiting for local authentication")
		}
	}

@ross-w
Copy link
Contributor

ross-w commented Aug 11, 2024

I'm at a loss as to how this is occurring. Looking at the code I don't see how this is possible either. Config for charger is:

  - name: zjbeny
    type: template
    template: ocpp
    stationid: zjb
    timeout: 2m
    remotestart: true

And yet I'm still seeing "waiting for local authentication". Nightly a2e36a2

@andig
Copy link
Member Author

andig commented Aug 11, 2024

While strictly not the same issue lets reopen here to not lose

@andig andig reopened this Aug 11, 2024
@andig andig added bug Something isn't working and removed enhancement New feature or request devices Specific device support labels Aug 11, 2024
@andig andig added the devices Specific device support label Aug 11, 2024
@andig
Copy link
Member Author

andig commented Aug 12, 2024

@ross-w could you retry current nightly? There was a bad bug in #15351 that may have caused this and even worse, it only happened by chance.

@ross-w
Copy link
Contributor

ross-w commented Aug 13, 2024

@andig Unfortunately the behaviour is the same with nightly 9bf8dc7. Just in case I tried remotestart and remoteStart but same results with both

@andig
Copy link
Member Author

andig commented Aug 13, 2024

There is no way to walk into the conditional path where this message is generated if remotestart: true is set.

Habs gefunden. Das geht wenn das Setting nie ankommt.

@premultiply in der ocpp.tpl sehe ich kein remotestart mehr. Fehler beim Umbau?

@premultiply
Copy link
Member

Sieht ganz so aus, dass das beim auseinander ziehen verschütt' gegangen ist.

@pdonovan

This comment was marked as off-topic.

@andig

This comment was marked as off-topic.

@ross-w
Copy link
Contributor

ross-w commented Aug 16, 2024

@andig did something change? latest nightly 3798d4e is working again, no more "waiting for local authentication" :) no changes on my end. I'm still seeing weird delays on the first charge after plugging in, but I will try to troubleshoot that

@andig
Copy link
Member Author

andig commented Aug 16, 2024

There is 40b6d1b. Not sure if that makes sense?

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
bug Something isn't working devices Specific device support
Projects
None yet
Development

Successfully merging a pull request may close this issue.

4 participants