Alfen Eve S-Line: OCPP Error FormationViolation for transactionId

[skullmonkey911]

Checklist

• [X] I checked other issues already, but found no answer/solution
• [X] I checked the documentation and wiki, but found no answer/solution
• [X] I am running the latest version and the issue still occurs
• [ ] I am sure that this issue is about SteVe (and not about the charging station software or something unrelated to SteVe)

Specifications

SteVe Version     : 3.4.8
Operating system  : ubuntu 20.04 LTS
JDK               : openjdk 11
Database          : mariaDB 10.3

Expected Behavior

no errors

Actual Behavior

I'm getting constantly errors for Transaction ID:

2022-01-17T18:46:47.718Z:COM:ocpp_rpc.c:663:-> [2,"72","MeterValues",{"connectorId":1,"transactionId":9223372036854775807,"m 2022-01-17T18:46:47.718Z:COM:ocpp_rpc.c:663:eterValue":[{"timestamp":"2022-01-17T11:58:29Z","sampledValue":[{"value":"0.505" 2022-01-17T18:46:47.718Z:COM:ocpp_rpc.c:663:,"context":"Transaction.Begin","unit":"kWh"}]}]}] 2022-01-17T18:46:47.753Z:COM:ocpp_rpc.c:1105:<- [4,"72","FormationViolation","The payload for action could not be deserialize 2022-01-17T18:46:47.753Z:COM:ocpp_rpc.c:1105:d",{"errorMsg":"Numeric value (9223372036854775807) out of range of int (-214748 2022-01-17T18:46:47.753Z:COM:ocpp_rpc.c:1105:3648 - 2147483647)\n at [Source: UNKN..."}] 2022-01-17T18:46:47.789Z:ERROR:ocpp_json.c:339:WAMP_ERROR on (FormationViolation) Desc: The payload for action could not be des 2022-01-17T18:46:47.789Z:ERROR:ocpp_json.c:339:erialized 2022-01-17T18:46:47.808Z:ERROR:ocpp_rpc.c:425:reply error REPLY ERROR

Looks like value is expected as int but is longer...

Steps to Reproduce the Problem

I'm using Alfen Eve S-line WB with firmware 5.4.0; error is always there with ocpp Steve Backend.

Additional context

Kind regards,

Stephan

[goekay]

hey @skullmonkey911 ,

the ocpp specifies the transaction id field as an integer (both soap and json variants). steve implements it accordingly.

i think that this big of a transaction id value should not happen during normal circumstances. it is indicative of some problem, or edge case, the station could not handle and therefore decided to use instead as fallback. this value is literally the max value a long can have.

i would suggest the investigate the root cause. this is only a symptom.

[skullmonkey911]

mhm, okay. Tested serveral things with no luck. But it looks like a bug in the alfen OCPP 1.6j implementation. Integer is the correct typ. I also checked the api spec.

I will open a jira ticket with Alfen.

[serras29]

Hi @skullmonkey911 ,

I have the same error with 4 Alfen Eve S-line WB. Because these boxes are new, I cannot say if it worked with older firmware versions. I tried an downgrade of the firmware to 5.3.1, but this doesnt fixed it. The authorization works fine, it is only the "MeterValues"-request. If you find an solution or get info from Alfen, please let me know. Thanks.

[skullmonkey911]

Hi Serras29,

opened a ticket and they told me, I have to contact the retailer. He needs to open a ticket. :/

Kind regards,

Stephan

[serras29]

Hi Stephan,

I have done the same today and got the same answer. Now the ticket is on hold. :( After that we already opened a ticket at our reseller (Voltus in Germany) and told him the ticketno of Alfen. Hopefully they see that this is not an exotic issue.

I checked the official specification of OCPP 1.6 and for SOAP it is clearly a 32 Bit integer, but for JSON I did not find a definition of the used datatypes. In the documentation it is only called Integer, but I cannot find if this integer is 16 Bit, 32 Bit, 64 Bit,... And JSON have no striked datatypes, there is only numeric. If I look at the OCPP implementation of a Python library by MobilityHouse, they use "string" for this field. So they have not trouble with the length. I am not sure, if this is clearly an error of Alfen or only a inaccurate definition of the OCPP.

Kind regards Sebastian

[goekay]

I checked the official specification of OCPP 1.6 and for SOAP it is clearly a 32 Bit integer, but for JSON I did not find a definition of the used datatypes. In the documentation it is only called Integer, but I cannot find if this integer is 16 Bit, 32 Bit, 64 Bit,... And JSON have no striked datatypes, there is only numeric.

regardless of this aspect, i want to emphasize another one: the value from the logs is the maximum value a signed 64-bit numeric value can take. in the world of java, integer is 32 bit, and long is 64 bit. even if this field had the data type long (instead of integer), your logs would have indicated a problem, because...

under normal circumstances, the usage of this transactionId value signals that we maxed out the value space of 64-bit numbers and hit the ceiling. in my view, the probability of this happening is really low.

because of this, my assumption is that the usage of this value indicates a problem: a) the charging station uses this special value as the absence of a transactionid (even though this field is nullable) b) there was a situation the station could not handle, and used this value as some default/fallback.

[goekay]

another thing that supports my assumption that the station has an issue:

in the world of steve (read: in ocpp versions steve implements) the central system controls and decides the value of transactionId. since steve uses an 32 bit integer for this field, the value provided by the station (in the logs) cannot come from steve. it is just not possible.

[goRaspy]

Is this problem happen with chargepoint setup with ocpp 1.5 or 1.6 ?

Alfen stopped support of 1.5j. i think these kind of charger is more reliable with 1.6.

Le sam. 22 janv. 2022, 16:18, Sevket Gökay @.***> a écrit :

another thing that supports my assumption that the station has an issue:

in the world of steve (read: in ocpp versions steve implements) the central system controls and decides the value of transactionId. since steve uses an 32 bit integer for this field, the value provided by the station (in the logs) cannot come from steve. it is just not possible.

— Reply to this email directly, view it on GitHub https://github.com/RWTH-i5-IDSG/steve/issues/740#issuecomment-1019290233, or unsubscribe https://github.com/notifications/unsubscribe-auth/ACM5BTCYLZLLOLOLLYQ3W2LUXLDC5ANCNFSM5MGRA45Q . You are receiving this because you are subscribed to this thread.Message ID: @.***>

[skullmonkey911]

Hi,

happens with 1.6 JSON.

I've just looked at the csv exported with ACE Service Installer (Transactions). Here also the Transaction IDs are looking funny.

First two tests after installation where made with 4.x firmware. After Update to 5.4.0 the value started to look strange. I think 95% a firmware bug. Or they want to "promote" their own OCPP Backoffice Software ;)

Generated, 24. Jan. 2022 13:40:14

txstart: id 0x0000000000000001, socket 1, 2014-01-01 01:13:13 0.012kWh 0xxxxxxxxxx080 3 Y mv: socket 1, 2014-01-01 01:13:13 0.012 Y mv: socket 1, 2014-01-01 01:13:14 0.012 Y mv: socket 1, 2014-01-01 01:28:14 0.162 Y mv: socket 1, 2014-01-01 01:43:14 0.162 Y mv: socket 1, 2014-01-01 01:58:14 0.162 Y mv: socket 1, 2014-01-01 02:13:14 0.162 Y mv: socket 1, 2014-01-01 02:28:14 0.162 Y mv: socket 1, 2014-01-01 02:43:14 0.162 Y mv: socket 1, 2014-01-01 02:58:14 0.162 Y mv: socket 1, 2014-01-01 03:13:14 0.162 Y mv: socket 1, 2014-01-01 03:24:14 0.162 Y txstop: id 0x0000000000000001, socket 1, 2014-01-01 03:24:14 0.162kWh 0xxxxxxxxxx080 Y txstart: id 0x0000000000000002, socket 1, 2022-01-16 11:32:41 0.162kWh 0xxxxxxxxxx080 3 Y mv: socket 1, 2022-01-16 11:32:41 0.162 Y mv: socket 1, 2022-01-16 11:32:42 0.162 Y mv: socket 1, 2022-01-16 11:44:46 0.505 Y txstop: id 0x0000000000000002, socket 1, 2022-01-16 11:44:46 0.505kWh 0xxxxxxxxxx080 Y dto: 32 txstart: id 0xffffffffffffffff, socket 1, 2022-01-17 11:58:28 0.505kWh 6 Y mv: socket 1, 2022-01-17 11:58:29 0.505 N mv: socket 1, 2022-01-17 11:58:30 0.505 N txstop: id 0xffffffffffffffff, socket 1, 2022-01-17 11:59:10 0.505kWh (null) N txstart: id 0xffffffffffffffff, socket 1, 2022-01-18 13:23:54 0.505kWh 0xxxxxxxxxx080 3 N mv: socket 1, 2022-01-18 13:23:54 0.505 N mv: socket 1, 2022-01-18 13:23:56 0.505 N mv: socket 1, 2022-01-18 13:38:54 0.948 N mv: socket 1, 2022-01-18 13:53:55 1.590 N mv: socket 1, 2022-01-18 14:08:54 1.590 N mv: socket 1, 2022-01-18 14:23:54 1.590 N mv: socket 1, 2022-01-18 14:38:54 1.590 N mv: socket 1, 2022-01-18 14:53:54 1.590 N mv: socket 1, 2022-01-18 15:00:32 1.590 N txstop: id 0xffffffffffffffff, socket 1, 2022-01-18 15:00:32 1.590kWh 0xxxxxxxxxx080 N

First two transactions with numbering 1,2 but then hex value also maxed out...

[skullmonkey911]

Two futher remarks:

1. I've changed the pre-configured Customer Ident. number to *_garage. Because I'll get a other WB next year outside.
2. I didn't try a reset to Factory Default after Firmware update, because I don't want to mess with the delivery default. But maybe it would help ? ...

[trimix3]

I have the same problem regarding the transactionId.

After a bit of debugging I found out that the charging station does not send the StartTransaction message if the charging process was previously triggered with RemoteStartTransaction.

Thus the charging station does not receive a transactionId, but starts the charging process regardless.

[serras29]

I made some further tests and looked to the log of the Charger. The MeterValues.req are send every minute after the boot process. And as far as I understand the definition, they should not contain a transactionId. But they have this "MAX_Int64"-Value. The Authorize.req are working fine, but the charger sends no StartTransaction.req, so it never gets a transactionId. It only sends StatusNotification.req.

We have 4 chargers of Alfen, currently the half are on 5.3.1 and the other half on 5.4.0. I have never tested the charger with the firmware 4.x and SteVe. They are new and one of the first steps was the upgrade to the current firmware. And I am not sure, if I break the charger, if I try to downgrade to 4.x, because Alfen implemented a new security password.

My ticket at Alfen was yesterday approved by our Reseller (Voltus), but no response from Alfen so far.

[trimix3]

@serras29 did you get a response from your reseller?

[serras29]

I have no response from Alfen so far. They ask only for the serial no.

But I have made some more tests today. After the downgrade to 5.3.1 the MeterValues.req stopped. But the StartTransaction.req was never send. Then I made a factoryreset with both the 5.3.1 boxes and the 5.4.0 ones. And the 5.3.1er Firmware works fine now. But I have only test one quick charging. The StartTransaction.req is send and SteVe answers with a transactionID. No errors so far. A factory reset on the 5.4.0 boxes did not change everything. So it looks like a bug in the 5.4.0 firmware.

[goRaspy]

Hello,

I am trying to reproduce the problem without success. If my understanding is fine, in your case the charger do not send a ocpp start transaction after a remote start command ?

Many thanks

Le mar. 1 févr. 2022, 22:04, serras29 @.***> a écrit :

I have no response from Alfen so far. They ask only for the serial no.

But I have made some more tests today. After the downgrade to 5.3.1 the MeterValues.req stopped. But the StartTransaction.req was never send. Then I made a factoryreset with both the 5.3.1 boxes and the 5.4.0 ones. And the 5.3.1er Firmware works fine now. But I have only test one quick charging. The StartTransaction.req is send and SteVe answers with a transactionID. No errors so far. A factory reset on the 5.4.0 boxes did not change everything. So it looks like a bug in the 5.4.0 firmware.

— Reply to this email directly, view it on GitHub https://github.com/RWTH-i5-IDSG/steve/issues/740#issuecomment-1027284888, or unsubscribe https://github.com/notifications/unsubscribe-auth/ACM5BTBBHJVUVZPH467SLX3UZBDEVANCNFSM5MGRA45Q . You are receiving this because you commented.Message ID: @.***>

[serras29]

With firmware 5.4.0 the charger do not send the StartTransaction at the plug in of the car, after authorization by RFID via OCPP.

[skullmonkey911]

Hi, does someone know if the problem still exists with current alfen firmware 5.6.0? Regards, Stephan

[alflexRH]

I just connected our dual socket Alfen charger, with firmware version 6.1.0, and the issue is still there:

[INFO ] 2023-05-01 05:58:25,444 de.rwth.idsg.steve.ocpp.ws.WebSocketLogger (qtp455888635-448) - [chargeBoxId=FlexPower01, sessionId=8db17cfc-f371-73bb-0439-ac1dfab25577] Received: [2,"6","MeterValues",{"connectorId":2,"transactionId":9223372036854775807,"meterValue":[{"timestamp":"2021-09-21T12:14:53Z","sampledValue":[{"value":"20.900","context":"Transaction.Begin","unit":"kWh"}]}]}]
[ERROR] 2023-05-01 05:58:25,444 de.rwth.idsg.steve.ocpp.ws.pipeline.Deserializer (qtp455888635-448) - Exception occurred

This is after a fresh reboot.

Edit: I did a "Reset to factory defaults", that did not solve the issue.

[lohralfen]

Anyone have a bit more logging, preferably a week's worth, with this issue occurring? I could take a look.

[alflexRH]

Anyone have a bit more logging, preferably a week's worth, with this issue occurring? I could take a look.

I got a days worth, including a restart of the steve container, and a restart of the Alfen unit. Can i email them somewhere? I dont want to post them publicly since they contain urls/server names.

Thanks in advance!

[lohralfen]

Anyone have a bit more logging, preferably a week's worth, with this issue occurring? I could take a look.

I got a days worth, including a restart of the steve container, and a restart of the Alfen unit. Can i email them somewhere? I dont want to post them publicly since they contain urls/server names.

Thanks in advance!

Hey, you can send an email with the diagnostics to [email protected] (temporary email from a forwarding service to avoid scrapers/junk mail). I will reply to you from my business email to confirm receipt.

[alflexRH]

Been working with @lohralfen, and at least for me we managed to resolve the issue.

For me, it was very old data causing the issue. But the "message attempts" setting, in the ACE Service Installer, under Connectivity->Advanced settings ON->Transaction Data was set to 0, the EVSE never gave up on trying to send the data. I changed it to 10, and in the next few hours it kept failing one record after another, until it gave on them one by one, and then got to the actual good records. Since them, i have not seen the problem again.

Not a very satisfying result, because we have been unable to find out where the weird data came from (since it was from years ago). But it works.

I was able to see in the logs provided by the ACE Service Installer that it was old logs that the EVSE was trying to send:

2023-06-13T04:37:41.652Z:COM:ocpp_rpc.c:681:-> [2,"10982","MeterValues",{"connectorId":2,"transactionId":9223372036854775807
2023-06-13T04:37:41.652Z:COM:ocpp_rpc.c:681:,"meterValue":[{"timestamp":"**2021-09-21T12:14:53Z**","sampledValue":[{"value":"20.
2023-06-13T04:37:41.652Z:COM:ocpp_rpc.c:681:900","context":"Transaction.Begin","unit":"kWh"}]}]}]
2023-06-13T04:37:41.691Z:COM:ocpp_rpc.c:1127:<- [4,"10982","FormationViolation","The payload for action could not be deserial
2023-06-13T04:37:41.691Z:COM:ocpp_rpc.c:1127:ized",{"errorMsg":"Numeric value (9223372036854775807) out of range of int (-214
2023-06-13T04:37:41.691Z:COM:ocpp_rpc.c:1127:7483648 - 2147483647)\n at [Source: UNKN..."}]
2023-06-13T04:37:41.726Z:ERROR:ocpp_json.c:462:WAMP_ERROR on (FormationViolation) Desc: The payload for action could not be des
2023-06-13T04:37:41.726Z:ERROR:ocpp_json.c:462:erialized
2023-06-13T04:37:41.746Z:ERROR:ocpp_rpc.c:438:reply error REPLY ERROR

I hope this helps others.