Connector 0/zero causes Exception

[andle]

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
• [ x] 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.6.0
Operating system  : Linux 5.4.0-1108-raspi #120-Ubuntu
JDK               : openjdk 17.0.10 2024-01-16
                        OpenJDK Runtime Environment (build 17.0.10+7-Ubuntu-120.04.1)
                        OpenJDK 64-Bit Server VM (build 17.0.10+7-Ubuntu-120.04.1, mixed mode, sharing)

Database          : mariadb  Ver 15.1 Distrib 10.3.39-MariaDB, for debian-linux-gnu (aarch64) using readline 5.2

Expected Behavior

Send a ChargePointMaxProfile with connector set to 0 with no errors.

Actual Behavior

Charge profile is Accepted, but Java errors occur due to connector being zero/"null".

Steps to Reproduce the Problem

1. Create a ChargePointMaxProfile (any valid Max profile seems to do)
2. Set Charging Profile > select charger and profile > Set connector ID to 0 (zero)
3. Click "Perform"
4. Observe steve.log to see exception/error

Additional context

From steve.log:
[INFO ] 2024-06-03 17:35:27,793 de.rwth.idsg.steve.ocpp.ws.WebSocketLogger (SteVe-Executor-0) - [chargeBoxId=ST19A7114B1EE, sessionId=196ac060-e7ce-4a59-d4d2-0c0f228b7970] Sending: [2,"1dd34e02-476a-429d-b1bf-0d
7e20397ec9","SetChargingProfile",{"connectorId":0,"csChargingProfiles":{"chargingProfileId":1,"stackLevel":1,"chargingProfilePurpose":"ChargePointMaxProfile","chargingProfileKind":"Absolute","chargingSchedule":{
"chargingRateUnit":"A","chargingSchedulePeriod":[{"startPeriod":0,"limit":8,"numberPhases":1}]}}}]
[INFO ] 2024-06-03 17:35:29,311 de.rwth.idsg.steve.ocpp.ws.WebSocketLogger (qtp385739920-319) - [chargeBoxId=ST19A7114B1EE, sessionId=196ac060-e7ce-4a59-d4d2-0c0f228b7970] Received: [3,"1dd34e02-476a-429d-b1bf-0
d7e20397ec9",{"status":"Accepted"}]
[ERROR] 2024-06-03 17:35:29,367 de.rwth.idsg.steve.ocpp.task.SetChargingProfileTask (qtp385739920-319) - Exception occurred in OcppCallback
org.jooq.exception.IntegrityConstraintViolationException: SQL [insert into stevedb.connector_charging_profile (connector_pk, charging_profile_pk) values ((select stevedb.connector.connector_pk from
stevedb.connector where (stevedb.connector.charge_box_id = ? and stevedb.connector.connector_id = ?)), ?)]; Column 'connector_pk' cannot be null
at org.jooq_3.19.7.MYSQL.debug(Unknown Source) ~[?:?]
at org.jooq.impl.Tools.translate(Tools.java:3570) ~[jooq-3.19.7.jar:?]
at org.jooq.impl.Tools.translate(Tools.java:3560) ~[jooq-3.19.7.jar:?]
at org.jooq.impl.DefaultExecuteContext.sqlException(DefaultExecuteContext.java:827) ~[jooq-3.19.7.jar:?]
at org.jooq.impl.AbstractQuery.execute(AbstractQuery.java:362) ~[jooq-3.19.7.jar:?]
at org.jooq.impl.AbstractDelegatingQuery.execute(AbstractDelegatingQuery.java:115) ~[jooq-3.19.7.jar:?]
at de.rwth.idsg.steve.repository.impl.ChargingProfileRepositoryImpl.setProfile(ChargingProfileRepositoryImpl.java:79) ~[steve.jar:?]
at de.rwth.idsg.steve.ocpp.task.SetChargingProfileTask$1.success(SetChargingProfileTask.java:65) ~[steve.jar:?]
at de.rwth.idsg.steve.ocpp.task.SetChargingProfileTask$1.success(SetChargingProfileTask.java:57) ~[steve.jar:?]
at de.rwth.idsg.steve.ocpp.CommunicationTask.success(CommunicationTask.java:130) ~[steve.jar:?]
at de.rwth.idsg.steve.ocpp.task.SetChargingProfileTask.lambda$getOcpp16Handler$1(SetChargingProfileTask.java:113) ~[steve.jar:?]
at de.rwth.idsg.steve.ocpp.ws.data.CommunicationContext.lambda$createResultHandler$0(CommunicationContext.java:67) ~[steve.jar:?]
at de.rwth.idsg.steve.ocpp.ws.pipeline.IncomingPipeline.accept(IncomingPipeline.java:67) ~[steve.jar:?]
at de.rwth.idsg.steve.ocpp.ws.AbstractWebSocketEndpoint.handleTextMessage(AbstractWebSocketEndpoint.java:117) ~[steve.jar:?]
at de.rwth.idsg.steve.ocpp.ws.AbstractWebSocketEndpoint.onMessage(AbstractWebSocketEndpoint.java:89) ~[steve.jar:?]
at de.rwth.idsg.steve.ocpp.ws.ConcurrentWebSocketHandler.handleMessage(ConcurrentWebSocketHandler.java:50) ~[steve.jar:?]
at org.springframework.web.socket.adapter.jetty.Jetty10WebSocketHandlerAdapter.onWebSocketText(Jetty10WebSocketHandlerAdapter.java:78) ~[spring-websocket-5.3.34.jar:5.3.34]
at org.eclipse.jetty.websocket.core.internal.messages.StringMessageSink.accept(StringMessageSink.java:53) ~[websocket-core-common-10.0.14.jar:10.0.14]
at org.eclipse.jetty.websocket.common.JettyWebSocketFrameHandler.acceptMessage(JettyWebSocketFrameHandler.java:334) ~[websocket-jetty-common-10.0.14.jar:10.0.14]
at org.eclipse.jetty.websocket.common.JettyWebSocketFrameHandler.onTextFrame(JettyWebSocketFrameHandler.java:422) ~[websocket-jetty-common-10.0.14.jar:10.0.14]
at org.eclipse.jetty.websocket.common.JettyWebSocketFrameHandler.onFrame(JettyWebSocketFrameHandler.java:240) ~[websocket-jetty-common-10.0.14.jar:10.0.14]
at org.eclipse.jetty.websocket.core.internal.WebSocketCoreSession$IncomingAdaptor.lambda$onFrame$1(WebSocketCoreSession.java:671) ~[websocket-core-common-10.0.14.jar:10.0.14]
at org.eclipse.jetty.server.handler.ContextHandler.handle(ContextHandler.java:1470) ~[jetty-server-10.0.14.jar:10.0.14]
at org.eclipse.jetty.server.handler.ContextHandler.handle(ContextHandler.java:1489) ~[jetty-server-10.0.14.jar:10.0.14]
at org.eclipse.jetty.websocket.core.server.internal.AbstractHandshaker$1.handle(AbstractHandshaker.java:212) ~[websocket-core-server-10.0.14.jar:10.0.14]
at org.eclipse.jetty.websocket.core.internal.WebSocketCoreSession$IncomingAdaptor.onFrame(WebSocketCoreSession.java:671) ~[websocket-core-common-10.0.14.jar:10.0.14]
at org.eclipse.jetty.websocket.core.AbstractExtension.nextIncomingFrame(AbstractExtension.java:145) ~[websocket-core-common-10.0.14.jar:10.0.14]
at org.eclipse.jetty.websocket.core.internal.PerMessageDeflateExtension.nextIncomingFrame(PerMessageDeflateExtension.java:236) ~[websocket-core-common-10.0.14.jar:10.0.14]
at org.eclipse.jetty.websocket.core.internal.DemandingFlusher.emitFrame(DemandingFlusher.java:145) ~[websocket-core-common-10.0.14.jar:10.0.14]
at org.eclipse.jetty.websocket.core.internal.PerMessageDeflateExtension$IncomingFlusher.inflate(PerMessageDeflateExtension.java:480) ~[websocket-core-common-10.0.14.jar:10.0.14]
at org.eclipse.jetty.websocket.core.internal.PerMessageDeflateExtension$IncomingFlusher.handle(PerMessageDeflateExtension.java:413) ~[websocket-core-common-10.0.14.jar:10.0.14]
at org.eclipse.jetty.websocket.core.internal.DemandingFlusher.process(DemandingFlusher.java:169) ~[websocket-core-common-10.0.14.jar:10.0.14]
at org.eclipse.jetty.util.IteratingCallback.processing(IteratingCallback.java:243) ~[jetty-util-10.0.14.jar:10.0.14]
at org.eclipse.jetty.util.IteratingCallback.succeeded(IteratingCallback.java:369) ~[jetty-util-10.0.14.jar:10.0.14]
at org.eclipse.jetty.websocket.core.internal.DemandingFlusher.onFrame(DemandingFlusher.java:104) ~[websocket-core-common-10.0.14.jar:10.0.14]
at org.eclipse.jetty.websocket.core.internal.PerMessageDeflateExtension.onFrame(PerMessageDeflateExtension.java:93) ~[websocket-core-common-10.0.14.jar:10.0.14]
at org.eclipse.jetty.websocket.core.internal.ExtensionStack.onFrame(ExtensionStack.java:120) ~[websocket-core-common-10.0.14.jar:10.0.14]
at org.eclipse.jetty.websocket.core.internal.WebSocketCoreSession.onFrame(WebSocketCoreSession.java:481) ~[websocket-core-common-10.0.14.jar:10.0.14]
at org.eclipse.jetty.websocket.core.internal.WebSocketConnection.onFrame(WebSocketConnection.java:262) ~[websocket-core-common-10.0.14.jar:10.0.14]
at org.eclipse.jetty.websocket.core.internal.WebSocketConnection.fillAndParse(WebSocketConnection.java:455) ~[websocket-core-common-10.0.14.jar:10.0.14]
at org.eclipse.jetty.websocket.core.internal.WebSocketConnection.onFillable(WebSocketConnection.java:340) ~[websocket-core-common-10.0.14.jar:10.0.14]
at org.eclipse.jetty.io.AbstractConnection$ReadCallback.succeeded(AbstractConnection.java:314) ~[jetty-io-10.0.14.jar:10.0.14]
at org.eclipse.jetty.io.FillInterest.fillable(FillInterest.java:100) ~[jetty-io-10.0.14.jar:10.0.14]
at org.eclipse.jetty.io.ssl.SslConnection$DecryptedEndPoint.onFillable(SslConnection.java:558) ~[jetty-io-10.0.14.jar:10.0.14]
at org.eclipse.jetty.io.ssl.SslConnection.onFillable(SslConnection.java:379) ~[jetty-io-10.0.14.jar:10.0.14]
at org.eclipse.jetty.io.ssl.SslConnection$2.succeeded(SslConnection.java:146) ~[jetty-io-10.0.14.jar:10.0.14]
at org.eclipse.jetty.io.FillInterest.fillable(FillInterest.java:100) ~[jetty-io-10.0.14.jar:10.0.14]
at org.eclipse.jetty.io.SelectableChannelEndPoint$1.run(SelectableChannelEndPoint.java:53) ~[jetty-io-10.0.14.jar:10.0.14]
at org.eclipse.jetty.util.thread.strategy.AdaptiveExecutionStrategy.runTask(AdaptiveExecutionStrategy.java:416) ~[jetty-util-10.0.14.jar:10.0.14]
at org.eclipse.jetty.util.thread.strategy.AdaptiveExecutionStrategy.consumeTask(AdaptiveExecutionStrategy.java:385) ~[jetty-util-10.0.14.jar:10.0.14]
at org.eclipse.jetty.util.thread.strategy.AdaptiveExecutionStrategy.tryProduce(AdaptiveExecutionStrategy.java:272) ~[jetty-util-10.0.14.jar:10.0.14]
at org.eclipse.jetty.util.thread.strategy.AdaptiveExecutionStrategy.lambda$new$0(AdaptiveExecutionStrategy.java:140) ~[jetty-util-10.0.14.jar:10.0.14]
at org.eclipse.jetty.util.thread.ReservedThreadExecutor$ReservedThread.run(ReservedThreadExecutor.java:411) ~[jetty-util-10.0.14.jar:10.0.14]
at org.eclipse.jetty.util.thread.QueuedThreadPool.runJob(QueuedThreadPool.java:936) ~[jetty-util-10.0.14.jar:10.0.14]
at org.eclipse.jetty.util.thread.QueuedThreadPool$Runner.run(QueuedThreadPool.java:1080) ~[jetty-util-10.0.14.jar:10.0.14]
at java.base/java.lang.Thread.run(Thread.java:840) [?:?]
Caused by: java.sql.SQLIntegrityConstraintViolationException: Column 'connector_pk' cannot be null
at com.mysql.cj.jdbc.exceptions.SQLError.createSQLException(SQLError.java:117) ~[mysql-connector-java-8.0.30.jar:8.0.30]
at com.mysql.cj.jdbc.exceptions.SQLExceptionsMapping.translateException(SQLExceptionsMapping.java:122) ~[mysql-connector-java-8.0.30.jar:8.0.30]
at com.mysql.cj.jdbc.ServerPreparedStatement.serverExecute(ServerPreparedStatement.java:555) ~[mysql-connector-java-8.0.30.jar:8.0.30]
at com.mysql.cj.jdbc.ServerPreparedStatement.executeInternal(ServerPreparedStatement.java:339) ~[mysql-connector-java-8.0.30.jar:8.0.30]
at com.mysql.cj.jdbc.ClientPreparedStatement.execute(ClientPreparedStatement.java:354) ~[mysql-connector-java-8.0.30.jar:8.0.30]
at com.zaxxer.hikari.pool.ProxyPreparedStatement.execute(ProxyPreparedStatement.java:44) ~[HikariCP-5.1.0.jar:?]
at com.zaxxer.hikari.pool.HikariProxyPreparedStatement.execute(HikariProxyPreparedStatement.java) ~[HikariCP-5.1.0.jar:?]
at org.jooq.tools.jdbc.DefaultPreparedStatement.execute(DefaultPreparedStatement.java:219) ~[jooq-3.19.7.jar:?]
at org.jooq.impl.AbstractQuery.execute(AbstractQuery.java:458) ~[jooq-3.19.7.jar:?]
at org.jooq.impl.AbstractDMLQuery.execute(AbstractDMLQuery.java:1068) ~[jooq-3.19.7.jar:?]
at org.jooq.impl.AbstractQuery.execute(AbstractQuery.java:348) ~[jooq-3.19.7.jar:?]
... 51 more

This is also seen in other OCPP calls when connector zero is used.

[goekay]

in various places of the flow (where the station is sending some connector-specific message to steve) we have an optional step "if you see this connector id for the first time, insert into db".

the fact that you see this exception means that your station did not communicate with steve beforehand. possible?

This is also seen in other OCPP calls when connector zero is used.

this should not be happening. can you elaborate these calls, and the use cases etc?

[andle]

@goekay

The station had performed BootNotification, StatusNotifications, StartTransactions, etc. Is this what you mean by communication beforehand?
Subsequent SetChargingProfile.req's result in the same behavior, exception is seen.

This is also seen in other OCPP calls when connector zero is used.<

As for the other calls, I may be mistaken. I thought I had seen it in other connectorId=0 situations, but I can't currently reproduce them.

[goekay]

can you pls post some logs, for ex from StartTransaction?

[goekay]

actually the events/logs where connector 0 is used.

[andle]

If you look at the first line of the log in Additional Context, you can see the SetChargingProfile.req where connectorId:0 is used.

[goekay]

i am aware of SetChargingProfile.req with connectorId:0. i did not mean that.

i meant: can you pls post logs from other operations you mentioned (BootNotification, StatusNotifications, StartTransactions, etc.) where connector 0 is used?

[andle]

Apologies, Earlier I meant to say I was unable to reproduce with the other calls. I messed up the quotation on the comment.

[andle]

@goekay What are next steps? Will this be merged?

[goekay]

there is some discourse happening. it will be merged after the resolution of raised concerns.