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

[Hager Witty Park / 1.0.0.0 / 9.0.1.0] Stop charging look not working #55

Closed
TenGbps opened this issue Apr 29, 2024 · 7 comments
Closed

Comments

@TenGbps
Copy link

TenGbps commented Apr 29, 2024

Capture d’écran 2024-04-29 à 15 12 25
Can you help me understand why I never get an end of charge?

Logs on my Hager Witty Park :
[2024-04-29 05:26:18] Connector 3: Cable connection
[2024-04-29 05:26:18] Connector 3: OCPP Status Preparing
[2024-04-29 05:26:18] Connector 3: Cable 32 A
[2024-04-29 05:26:23] Connector 3: Vehicle connection
[2024-04-29 05:27:03] RFID tag: XXXXXXX1
[2024-04-29 05:27:03] Authorize (tag = XXXXXXX1, status = Accepted, expiry date = 2024-04-29T05:32:03Z)
[2024-04-29 05:27:04] Connector 3: Suspended EVSE
[2024-04-29 05:27:04] Connector 3: OCPP Status Suspended EVSE
[2024-04-29 05:27:05] Connector 3: Suspended EV
[2024-04-29 05:27:05] Connector 3: OCPP Status Suspended EV
[2024-04-29 05:27:11] Connector 3: Charging
[2024-04-29 05:27:11] Connector 3: OCPP Status Charging
[2024-04-29 05:27:14] Connector 3: OCPP Status Charging
[2024-04-29 09:09:16] Connector 3: Suspended EV
[2024-04-29 09:09:16] Connector 3: OCPP Status Suspended EV
[2024-04-29 10:31:46] Connector 3: Vehicle disconnection
[2024-04-29 10:31:46] Connector 3: OCPP Status Finishing
[2024-04-29 10:31:53] Connector 3: Cable disconnection
[2024-04-29 10:31:53] Connector 3: OCPP Status Available

@dallmann-consulting
Copy link
Owner

Hi,
it seems like this is the same behavior like issue #47 .
The charger most probably doesn't send a "StopTransaction" message. The usual process is:

1.) The charger sends an "Authorize" massage when an RFID-tag is presented.
2.) The server responds with accepted.
3.) When a car is connected, the charger sends a StartTransaction message.
4.) The server stores the transaction (ID + meter value) and accepts the transaction for the specific connector.
5.) The charger periodically sends meter value and can also send status messages (like suspended etc.)
6.) The charger sends a StopTransaction message when the transaction is finally stopped. This message contains the stop meter value and can also contain signed data about the transaction.
7.) The charger send a status like no EV connected.

Your log above also doesn't show anything about a "StartTransaction" or StopTransaction message. The start message must have been sent. Otherwise no transaction would be running. But as the transactions are not stopped, the chargers probably doesn't send the expected stop message.
Can you check the dump folder (where all massages are stored) if you find a StopTransaction method?

@TenGbps
Copy link
Author

TenGbps commented May 7, 2024

Searching in all dump StartTransaction
Capture d’écran 2024-05-07 à 17 01 04

Searching in all dump StopTransaction
Capture d’écran 2024-05-07 à 17 26 18

@dallmann-consulting
Copy link
Owner

OK. The charger sends a StopTransaction but this message lacks the required transaction id. It is always "-1".

From OCPP specification:

transactionId integer 1..1 Required. This contains the transaction-id as received by the
StartTransaction.conf.

With OCPP 1.6 the servers answers the StartTransaction-Message with a generated transaction id (integer). The charger needs to send this back with the StopTransaction message. Your charger doesn't do this and then the server can't stop the transaction. The servers answer to these stop-messages is probably an error. You should see errors in the log files.

OCPP 2.0 changes the id handling, that the charger generates a UID as a transaction id and sends this with the start-message. Does your charger support OCPP 2.0? Maybe that works!?

@TenGbps
Copy link
Author

TenGbps commented May 15, 2024

ì have open a case to hager i waiting reply

Full dump in-out of transaction :
2024-05-15_16-29-15-5620_ocpp16-in.txt:[2, "819767f0-12c7-11ef-8012-0c8629738129", "StatusNotification", {"connectorId":4,"errorCode":"NoError","status":"Preparing","timestamp":"2024-05-15T14:29:15Z"}] 2024-05-15_16-29-16-2064_ocpp16-out.txt:[3,"819767f0-12c7-11ef-8012-0c8629738129",{}] 2024-05-15_16-29-16-3552_ocpp16-in.txt:[2, "821ceba0-12c7-11ef-8012-0c8629738129", "StatusNotification", {"connectorId":3,"errorCode":"NoError","status":"Preparing","timestamp":"2024-05-15T14:29:15Z"}] 2024-05-15_16-29-16-3657_ocpp16-out.txt:[3,"821ceba0-12c7-11ef-8012-0c8629738129",{}] 2024-05-15_16-29-17-1209_ocpp16-in.txt:[2, "828f5c80-12c7-11ef-8012-0c8629738129", "Authorize", {"idTag":"ABCD1234"}] 2024-05-15_16-29-17-1532_ocpp16-out.txt:[3,"828f5c80-12c7-11ef-8012-0c8629738129",{"idTagInfo":{"expiryDate":"2024-05-15T14:34:17.1253835+00:00","parentIdTag":"charger","status":"Accepted"}}] 2024-05-15_16-29-17-4183_ocpp16-in.txt:[2, "82b58220-12c7-11ef-8012-0c8629738129", "StatusNotification", {"connectorId":4,"errorCode":"NoError","status":"SuspendedEVSE","timestamp":"2024-05-15T14:29:17Z"}] 2024-05-15_16-29-17-4292_ocpp16-out.txt:[3,"82b58220-12c7-11ef-8012-0c8629738129",{}] 2024-05-15_16-29-18-3871_ocpp16-in.txt:[2, "834e18a0-12c7-11ef-8012-0c8629738129", "StatusNotification", {"connectorId":4,"errorCode":"NoError","status":"Charging","timestamp":"2024-05-15T14:29:18Z"}] 2024-05-15_16-29-18-3959_ocpp16-out.txt:[3,"834e18a0-12c7-11ef-8012-0c8629738129",{}] 2024-05-15_16-29-20-5423_ocpp16-in.txt:[2, "84925870-12c7-11ef-8012-0c8629738129", "StartTransaction", {"connectorId":4,"idTag":"ABCD1234","meterStart":51880,"timestamp":"2024-05-15T14:25:12Z"}] 2024-05-15_16-29-20-6023_ocpp16-out.txt:[3,"84925870-12c7-11ef-8012-0c8629738129",{"idTagInfo":{"expiryDate":"2199-12-31T00:00:00+01:00","parentIdTag":"charger","status":"ConcurrentTx"},"transactionId":0}] 2024-05-15_16-29-22-4483_ocpp16-in.txt:[2, "85c38570-12c7-11ef-8012-0c8629738129", "StatusNotification", {"connectorId":4,"errorCode":"NoError","status":"Finishing","timestamp":"2024-05-15T14:29:22Z"}] 2024-05-15_16-29-22-4573_ocpp16-out.txt:[3,"85c38570-12c7-11ef-8012-0c8629738129",{}] 2024-05-15_16-29-24-0016_ocpp16-in.txt:[2, "86a86730-12c7-11ef-8012-0c8629738129", "StatusNotification", {"connectorId":3,"errorCode":"NoError","status":"Available","timestamp":"2024-05-15T14:29:23Z"}] 2024-05-15_16-29-24-0105_ocpp16-out.txt:[3,"86a86730-12c7-11ef-8012-0c8629738129",{}] 2024-05-15_16-29-24-1574_ocpp16-in.txt:[2, "86bb7a00-12c7-11ef-8012-0c8629738129", "StatusNotification", {"connectorId":4,"errorCode":"NoError","status":"Available","timestamp":"2024-05-15T14:29:23Z"}] 2024-05-15_16-29-24-1674_ocpp16-out.txt:[3,"86bb7a00-12c7-11ef-8012-0c8629738129",{}] 2024-05-15_16-29-29-2199_ocpp16-in.txt:[2, "89c97d50-12c7-11ef-8012-0c8629738129", "StatusNotification", {"connectorId":4,"errorCode":"NoError","status":"Preparing","timestamp":"2024-05-15T14:29:29Z"}] 2024-05-15_16-29-29-2288_ocpp16-out.txt:[3,"89c97d50-12c7-11ef-8012-0c8629738129",{}] 2024-05-15_16-29-29-3803_ocpp16-in.txt:[2, "89dc9020-12c7-11ef-8012-0c8629738129", "StatusNotification", {"connectorId":3,"errorCode":"NoError","status":"Preparing","timestamp":"2024-05-15T14:29:29Z"}] 2024-05-15_16-29-29-3888_ocpp16-out.txt:[3,"89dc9020-12c7-11ef-8012-0c8629738129",{}] 2024-05-15_16-29-31-2338_ocpp16-in.txt:[2, "8afaaa50-12c7-11ef-8012-0c8629738129", "Authorize", {"idTag":"ABCD1234"}] 2024-05-15_16-29-31-2362_ocpp16-out.txt:[3,"8afaaa50-12c7-11ef-8012-0c8629738129",{"idTagInfo":{"expiryDate":"2024-05-15T14:34:31.2351101+00:00","parentIdTag":"charger","status":"Accepted"}}] 2024-05-15_16-29-31-5014_ocpp16-in.txt:[2, "8b20cff0-12c7-11ef-8012-0c8629738129", "StatusNotification", {"connectorId":4,"errorCode":"NoError","status":"SuspendedEVSE","timestamp":"2024-05-15T14:29:31Z"}] 2024-05-15_16-29-31-5120_ocpp16-out.txt:[3,"8b20cff0-12c7-11ef-8012-0c8629738129",{}] 2024-05-15_16-29-32-4609_ocpp16-in.txt:[2, "8bb96670-12c7-11ef-8012-0c8629738129", "StatusNotification", {"connectorId":4,"errorCode":"NoError","status":"Charging","timestamp":"2024-05-15T14:29:32Z"}] 2024-05-15_16-29-32-4700_ocpp16-out.txt:[3,"8bb96670-12c7-11ef-8012-0c8629738129",{}] 2024-05-15_16-29-38-8170_ocpp16-in.txt:[2, "8f8625e0-12c7-11ef-8012-0c8629738129", "StatusNotification", {"connectorId":4,"errorCode":"NoError","status":"Finishing","info":"EV side disconnected","timestamp":"2024-05-15T14:29:38Z"}] 2024-05-15_16-29-38-8260_ocpp16-out.txt:[3,"8f8625e0-12c7-11ef-8012-0c8629738129",{}] 2024-05-15_16-29-38-9750_ocpp16-in.txt:[2, "8f9938b0-12c7-11ef-8012-0c8629738129", "StatusNotification", {"connectorId":4,"errorCode":"NoError","status":"Available","timestamp":"2024-05-15T14:29:38Z"}] 2024-05-15_16-29-38-9833_ocpp16-out.txt:[3,"8f9938b0-12c7-11ef-8012-0c8629738129",{}] 2024-05-15_16-29-39-1339_ocpp16-in.txt:[2, "8fac4b80-12c7-11ef-8012-0c8629738129", "StatusNotification", {"connectorId":3,"errorCode":"NoError","status":"Available","timestamp":"2024-05-15T14:29:38Z"}] 2024-05-15_16-29-39-1423_ocpp16-out.txt:[3,"8fac4b80-12c7-11ef-8012-0c8629738129",{}] 2024-05-15_16-29-41-5002_ocpp16-in.txt:[2, "9116b0f0-12c7-11ef-8012-0c8629738129", "StartTransaction", {"connectorId":4,"idTag":"ABCD1234","meterStart":51880,"timestamp":"2024-05-15T14:25:12Z"}] 2024-05-15_16-29-41-5125_ocpp16-out.txt:[3,"9116b0f0-12c7-11ef-8012-0c8629738129",{"idTagInfo":{"expiryDate":"2199-12-31T00:00:00+01:00","parentIdTag":"charger","status":"ConcurrentTx"},"transactionId":0}] 2024-05-15_16-29-42-4577_ocpp16-in.txt:[2, "91af4770-12c7-11ef-8012-0c8629738129", "Heartbeat", {}] 2024-05-15_16-29-42-4596_ocpp16-out.txt:[3,"91af4770-12c7-11ef-8012-0c8629738129",{"currentTime":"2024-05-15T14:29:42.4587962+00:00"}] 2024-05-15_16-29-42-6153_ocpp16-in.txt:[2, "91af4771-12c7-11ef-8013-0c8629738129", "MeterValues", {"connectorId":4,"meterValue":[{"timestamp":"2024-05-15T14:25:12Z","sampledValue":[{"value":"51880","context":"Transaction.Begin","format":"Raw","measurand":"Energy.Active.Import.Register","location":"Outlet","unit":"Wh"}]}],"transactionId":-1}] 2024-05-15_16-29-42-6462_ocpp16-out.txt:[3,"91af4771-12c7-11ef-8013-0c8629738129",{}] 2024-05-15_16-29-43-4904_ocpp16-in.txt:[2, "9247ddf0-12c7-11ef-8013-0c8629738129", "MeterValues", {"connectorId":4,"meterValue":[{"timestamp":"2024-05-15T14:25:17Z","sampledValue":[{"value":"51880","context":"Transaction.End","format":"Raw","measurand":"Energy.Active.Import.Register","location":"Outlet","unit":"Wh"}]}],"transactionId":-1}] 2024-05-15_16-29-43-5011_ocpp16-out.txt:[3,"9247ddf0-12c7-11ef-8013-0c8629738129",{}] 2024-05-15_16-29-44-5523_ocpp16-in.txt:[2, "92e07470-12c7-11ef-8013-0c8629738129", "StopTransaction", {"meterStop":51880,"timestamp":"2024-05-15T14:25:17Z","transactionId":-1,"idTag":"ABCD1234","reason":"Local"}] 2024-05-15_16-29-44-5654_ocpp16-out.txt:[4,"92e07470-12c7-11ef-8013-0c8629738129","PropertyConstraintViolation","",{}]

I have also a wireshark capture.

@dallmann-consulting
Copy link
Owner

The charger requests to authorize the RFID token and the server says "accepted".

2024-05-15_16-29-31-2338_ocpp16-in.txt:[2, "8afaaa50-12c7-11ef-8012-0c8629738129", "Authorize", {"idTag":"ABCD1234"}]
2024-05-15_16-29-31-2362_ocpp16-out.txt:[3,"8afaaa50-12c7-11ef-8012-0c8629738129",{"idTagInfo":{"expiryDate":"2024-05-15T14:34:31.2351101+00:00","parentIdTag":"charger","status":"Accepted"}}]

Then the charger sends a StartTransaction message:

2024-05-15_16-29-41-5002_ocpp16-in.txt:[2, "9116b0f0-12c7-11ef-8012-0c8629738129", "StartTransaction", {"connectorId":4,"idTag":"ABCD1234","meterStart":51880,"timestamp":"2024-05-15T14:25:12Z"}]

The server responds with status "ConcurrentTx" because there is another transaction running with same RFID token:

2024-05-15_16-29-41-5125_ocpp16-out.txt:[3,"9116b0f0-12c7-11ef-8012-0c8629738129",{"idTagInfo":{"expiryDate":"2199-12-31T00:00:00+01:00","parentIdTag":"charger","status":"ConcurrentTx"},"transactionId":0}]

The OCPP spec says about "ConcurrentTx":
ConcurrentTx Identifier is already involved in another transaction and multiple transactions are not allowed.

So the server does not send a transaction ID (=0) and the charger should not start charging.
But then the charger surpringly sends a StopTransaction message (with the transaction ID "-1":

2024-05-15_16-29-44-5523_ocpp16-in.txt:[2, "92e07470-12c7-11ef-8013-0c8629738129", "StopTransaction", {"meterStop":51880,"timestamp":"2024-05-15T14:25:17Z","transactionId":-1,"idTag":"ABCD1234","reason":"Local"}]

And the server answers with an error because of the unknown transaction ID.

2024-05-15_16-29-44-5654_ocpp16-out.txt:[4,"92e07470-12c7-11ef-8013-0c8629738129","PropertyConstraintViolation","",{}]

Try to change the configuration in the OCPP server to allow concurrent transactions for the same RFID token:
"DenyConcurrentTx": false

@TenGbps
Copy link
Author

TenGbps commented Aug 13, 2024

I reproduce the issue, and it turns out that our terminal does not accept expiry dates beyond 12/31/2105. If the terminal receives a StartTransaction response with an expiry date later than this, it will not consider the response and, therefore, will not recognize the TransactionID. It will then resend the StartTransaction request, to which your server responds with ConcurrentTx, which is correct since you have already provided a transaction number for this badge ID (see logs below).

Text: [2, "29ad5210-1c0a-11ef-8005-0c862973805e", "StartTransaction", {"connectorId":3,"idTag":"1234567800","meterStart":22579,"timestamp":"2024-05-27T09:19:04Z"}]
Text: [3,"29ad5210-1c0a-11ef-8005-0c862973805e",{"idTagInfo":{"expiryDate":"2199-12-31T00:00:00+01:00","parentIdTag":"charger","status":"Accepted"},"transactionId":10}]
Text: [2, "29e68a80-1c0a-11ef-8005-0c862973805e", "StatusNotification", {"connectorId":3,"errorCode":"NoError","status":"SuspendedEVSE","timestamp":"2024-05-27T09:19:05Z"}]
Text: [2, "2ab85970-1c0a-11ef-8005-0c862973805e", "StatusNotification", {"connectorId":3,"errorCode":"NoError","status":"SuspendedEV","timestamp":"2024-05-27T09:19:06Z"}]
Text: [2, "2b9d3b30-1c0a-11ef-8005-0c862973805e", "StatusNotification", {"connectorId":3,"errorCode":"NoError","status":"Charging","timestamp":"2024-05-27T09:19:07Z"}]
Text: [2, "2d40d910-1c0a-11ef-8005-0c862973805e", "StartTransaction", {"connectorId":3,"idTag":"1234567800","meterStart":22579,"timestamp":"2024-05-27T09:19:04Z"}]
Text: [3,"2d40d910-1c0a-11ef-8005-0c862973805e",{"idTagInfo":{"expiryDate":"2199-12-31T00:00:00+01:00","parentIdTag":"charger","status":"ConcurrentTx"},"transactionId":0}]
Text: [2, "da1b5610-1c0a-11ef-8005-0c862973805e", "StopTransaction", {"meterStop":22744,"timestamp":"2024-05-27T09:23:58Z","transactionId":-1,"reason":"EVDisconnected"}]

 

@dallmann-consulting
Copy link
Owner

What a surprising issue... good analysis!
I've changed the fixed max. date to a dynamic current date plus 1 year.

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
None yet
Projects
None yet
Development

No branches or pull requests

2 participants