SteVe doesn't reply with StopTransaction.Conf on unknown transaction id

lategoodbye commented 5 years ago

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.3.0
Operating system  : Linux
JDK               : 11
Database          : 0.9.9

Expected Behavior

In case an OCPP 1.6 client sends a StopTransaction.Req with an unknown transaction id:

[2,"d51884d53448aa9ec78738dbafb76c8b2159","StopTransaction",{"meterStop":140,"reason":"PowerLoss","timestamp":"2019-07-02T09:44:21.530Z","transactionId":0}]

SteVe should reply with a StopTransaction.Conf (according to OCPP 1.6 spec, chapter 4.10).

Actual Behavior

SteVe triggers SQLIntegrityConstraintViolationException

[ERROR] 2019-07-02 09:44:21,662 de.rwth.idsg.steve.ocpp.ws.ocpp16.Ocpp16WebSocketEndpoint$Ocpp16CallHandler - Exception occurred
org.jooq.exception.DataAccessException: SQL [insert into `stevedb`.`transaction_stop` (`transaction_pk`, `event_timestamp`, `event_actor`, `stop_timestamp`, `stop_value`, `stop_reason`) values (?, ?, ?, ?, ?, ?)]; Cannot add or update a child row: a foreign key constraint fails (`stevedb`.`transaction_stop`, CONSTRAINT `FK_transaction_stop_transaction_pk` FOREIGN KEY (`transaction_pk`) REFERENCES `transaction_start` (`transaction_pk`) ON DELETE CASCADE ON UPDATE NO AC)
    at org.jooq_3.11.11.MYSQL.debug(Unknown Source) ~[?:?]
    at org.jooq.impl.Tools.translate(Tools.java:2430) ~[jooq-3.11.11.jar:?]
    at org.jooq.impl.DefaultExecuteContext.sqlException(DefaultExecuteContext.java:832) ~[jooq-3.11.11.jar:?]
    at org.jooq.impl.AbstractQuery.execute(AbstractQuery.java:364) ~[jooq-3.11.11.jar:?]
    at org.jooq.impl.AbstractDelegatingQuery.execute(AbstractDelegatingQuery.java:127) ~[jooq-3.11.11.jar:?]
    at de.rwth.idsg.steve.repository.impl.OcppServerRepositoryImpl.updateTransaction(OcppServerRepositoryImpl.java:248) ~[steve.jar:?]
    at de.rwth.idsg.steve.service.CentralSystemService16_Service.stopTransaction(CentralSystemService16_Service.java:194) ~[steve.jar:?]
    at de.rwth.idsg.steve.ocpp.soap.CentralSystemService16_SoapServer.stopTransaction(CentralSystemService16_SoapServer.java:117) ~[steve.jar:?]
    at de.rwth.idsg.steve.ocpp.ws.ocpp16.Ocpp16WebSocketEndpoint$Ocpp16CallHandler.dispatch(Ocpp16WebSocketEndpoint.java:97) ~[steve.jar:?]
    at de.rwth.idsg.steve.ocpp.ws.pipeline.AbstractCallHandler.accept(AbstractCallHandler.java:46) ~[steve.jar:?]
    at de.rwth.idsg.steve.ocpp.ws.pipeline.IncomingPipeline.accept(IncomingPipeline.java:61) ~[steve.jar:?]
    at de.rwth.idsg.steve.ocpp.ws.AbstractWebSocketEndpoint.handleTextMessage(AbstractWebSocketEndpoint.java:108) ~[steve.jar:?]
    at de.rwth.idsg.steve.ocpp.ws.AbstractWebSocketEndpoint.onMessage(AbstractWebSocketEndpoint.java:80) ~[steve.jar:?]
    at de.rwth.idsg.steve.ocpp.ws.ConcurrentWebSocketHandler.handleMessage(ConcurrentWebSocketHandler.java:50) ~[steve.jar:?]
    at org.springframework.web.socket.adapter.jetty.JettyWebSocketHandlerAdapter.onWebSocketText(JettyWebSocketHandlerAdapter.java:83) ~[spring-websocket-5.1.6.RELEASE.jar:5.1.6.RELEASE]
    at jdk.internal.reflect.NativeMethodAccessorImpl.invoke0(Native Method) ~[?:?]
    at jdk.internal.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62) ~[?:?]
    at jdk.internal.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) ~[?:?]
    at java.lang.reflect.Method.invoke(Method.java:566) ~[?:?]
    at org.eclipse.jetty.websocket.common.events.annotated.CallableMethod.call(CallableMethod.java:71) ~[websocket-common-9.4.17.v20190418.jar:9.4.17.v20190418]
    at org.eclipse.jetty.websocket.common.events.annotated.OptionalSessionCallableMethod.call(OptionalSessionCallableMethod.java:72) ~[websocket-common-9.4.17.v20190418.jar:9.4.17.v20190418]
    at org.eclipse.jetty.websocket.common.events.JettyAnnotatedEventDriver.onTextMessage(JettyAnnotatedEventDriver.java:241) ~[websocket-common-9.4.17.v20190418.jar:9.4.17.v20190418]
    at org.eclipse.jetty.websocket.common.message.SimpleTextMessage.messageComplete(SimpleTextMessage.java:69) ~[websocket-common-9.4.17.v20190418.jar:9.4.17.v20190418]
    at org.eclipse.jetty.websocket.common.events.AbstractEventDriver.appendMessage(AbstractEventDriver.java:65) ~[websocket-common-9.4.17.v20190418.jar:9.4.17.v20190418]
    at org.eclipse.jetty.websocket.common.events.JettyAnnotatedEventDriver.onTextFrame(JettyAnnotatedEventDriver.java:233) ~[websocket-common-9.4.17.v20190418.jar:9.4.17.v20190418]
    at org.eclipse.jetty.websocket.common.events.AbstractEventDriver.incomingFrame(AbstractEventDriver.java:150) ~[websocket-common-9.4.17.v20190418.jar:9.4.17.v20190418]
    at org.eclipse.jetty.websocket.common.WebSocketSession.incomingFrame(WebSocketSession.java:319) ~[websocket-common-9.4.17.v20190418.jar:9.4.17.v20190418]
    at org.eclipse.jetty.websocket.common.extensions.ExtensionStack.incomingFrame(ExtensionStack.java:201) ~[websocket-common-9.4.17.v20190418.jar:9.4.17.v20190418]
    at org.eclipse.jetty.websocket.common.Parser.notifyFrame(Parser.java:226) ~[websocket-common-9.4.17.v20190418.jar:9.4.17.v20190418]
    at org.eclipse.jetty.websocket.common.Parser.parse(Parser.java:255) ~[websocket-common-9.4.17.v20190418.jar:9.4.17.v20190418]
    at org.eclipse.jetty.websocket.common.io.AbstractWebSocketConnection.readParse(AbstractWebSocketConnection.java:581) ~[websocket-common-9.4.17.v20190418.jar:9.4.17.v20190418]
    at org.eclipse.jetty.websocket.common.io.AbstractWebSocketConnection.onFillable(AbstractWebSocketConnection.java:434) ~[websocket-common-9.4.17.v20190418.jar:9.4.17.v20190418]
    at org.eclipse.jetty.io.AbstractConnection$ReadCallback.succeeded(AbstractConnection.java:305) ~[jetty-io-9.4.17.v20190418.jar:9.4.17.v20190418]
    at org.eclipse.jetty.io.FillInterest.fillable(FillInterest.java:103) ~[jetty-io-9.4.17.v20190418.jar:9.4.17.v20190418]
    at org.eclipse.jetty.io.ChannelEndPoint$2.run(ChannelEndPoint.java:117) ~[jetty-io-9.4.17.v20190418.jar:9.4.17.v20190418]
    at org.eclipse.jetty.util.thread.strategy.EatWhatYouKill.runTask(EatWhatYouKill.java:333) ~[jetty-util-9.4.17.v20190418.jar:9.4.17.v20190418]
    at org.eclipse.jetty.util.thread.strategy.EatWhatYouKill.doProduce(EatWhatYouKill.java:310) ~[jetty-util-9.4.17.v20190418.jar:9.4.17.v20190418]
    at org.eclipse.jetty.util.thread.strategy.EatWhatYouKill.tryProduce(EatWhatYouKill.java:168) ~[jetty-util-9.4.17.v20190418.jar:9.4.17.v20190418]
    at org.eclipse.jetty.util.thread.strategy.EatWhatYouKill.run(EatWhatYouKill.java:126) ~[jetty-util-9.4.17.v20190418.jar:9.4.17.v20190418]
    at org.eclipse.jetty.util.thread.ReservedThreadExecutor$ReservedThread.run(ReservedThreadExecutor.java:366) ~[jetty-util-9.4.17.v20190418.jar:9.4.17.v20190418]
    at org.eclipse.jetty.util.thread.QueuedThreadPool.runJob(QueuedThreadPool.java:786) ~[jetty-util-9.4.17.v20190418.jar:9.4.17.v20190418]
    at org.eclipse.jetty.util.thread.QueuedThreadPool$2.run(QueuedThreadPool.java:743) ~[jetty-util-9.4.17.v20190418.jar:9.4.17.v20190418]
    at java.lang.Thread.run(Thread.java:834) [?:?]
Caused by: java.sql.SQLIntegrityConstraintViolationException: Cannot add or update a child row: a foreign key constraint fails (`stevedb`.`transaction_stop`, CONSTRAINT `FK_transaction_stop_transaction_pk` FOREIGN KEY (`transaction_pk`) REFERENCES `transaction_start` (`transaction_pk`) ON DELETE CASCADE ON UPDATE NO AC)
    at com.mysql.cj.jdbc.exceptions.SQLError.createSQLException(SQLError.java:117) ~[mysql-connector-java-8.0.16.jar:8.0.16]
    at com.mysql.cj.jdbc.exceptions.SQLError.createSQLException(SQLError.java:97) ~[mysql-connector-java-8.0.16.jar:8.0.16]
    at com.mysql.cj.jdbc.exceptions.SQLExceptionsMapping.translateException(SQLExceptionsMapping.java:122) ~[mysql-connector-java-8.0.16.jar:8.0.16]
    at com.mysql.cj.jdbc.ServerPreparedStatement.serverExecute(ServerPreparedStatement.java:634) ~[mysql-connector-java-8.0.16.jar:8.0.16]
    at com.mysql.cj.jdbc.ServerPreparedStatement.executeInternal(ServerPreparedStatement.java:414) ~[mysql-connector-java-8.0.16.jar:8.0.16]
    at com.mysql.cj.jdbc.ClientPreparedStatement.execute(ClientPreparedStatement.java:372) ~[mysql-connector-java-8.0.16.jar:8.0.16]
    at com.zaxxer.hikari.pool.ProxyPreparedStatement.execute(ProxyPreparedStatement.java:44) ~[HikariCP-3.3.1.jar:?]
    at com.zaxxer.hikari.pool.HikariProxyPreparedStatement.execute(HikariProxyPreparedStatement.java) ~[HikariCP-3.3.1.jar:?]
    at org.jooq.tools.jdbc.DefaultPreparedStatement.execute(DefaultPreparedStatement.java:209) ~[jooq-3.11.11.jar:?]
    at org.jooq.impl.AbstractQuery.execute(AbstractQuery.java:432) ~[jooq-3.11.11.jar:?]
    at org.jooq.impl.AbstractDMLQuery.execute(AbstractDMLQuery.java:613) ~[jooq-3.11.11.jar:?]
    at org.jooq.impl.AbstractQuery.execute(AbstractQuery.java:350) ~[jooq-3.11.11.jar:?]
    ... 39 more

and replies with an InternalError : Internal services failed while processing of the payload which causes the OCPP client to repeat the StopTransaction.Req

Steps to Reproduce the Problem

Choose a unknown transaction id
Make the OCPP client to send a StopTransaction.Req with this unknown transaction id after BootNotification

Note: This isn't a regression also SteVe 3.2.0 was effected.

goekay commented 5 years ago

hmm. thanks for using the template and reporting this issue in a very detailed manner!

failing upon receiving unknown transcation id is a known problem. i just don't know what a good workaround should be. we sure can always respond with a stop transaction conf. but then we start to swallow exceptions/problems which might go unnoticed and cause bigger problems afterwards.

in addition to that, in order to prevent information loss i also considered another database table (something like transaction_stop_unknown, in which we just insert the sent values without constraint checks and references to other tables), but i don't know how good of a solution this is.

lategoodbye commented 5 years ago

Personally, i don't have a problem with the exception as long as the StopTransaction.Conf is send.

goekay commented 5 years ago

yeah but we also have to think about its side effects in the big picture.

start transaction is in the same situation as well: steve must always respond with a start transaction conf. this might be problematic, since the transcation id might not be generated. something like -1 as place holder? how to differentiate between multiple -1 transactions? we cannot use something like UUID since the field is an integer. then... we probably need a transaction_start_unknown table to insert invalid data as well. how should the user (of steve, the station manager if you will) match start and stop events of invalid (-1) transactions?

lategoodbye commented 5 years ago

Even worse, i didn't find a clear definition of transaction id except of integer. At least in OCPP 2.0 it is defined as signed 32 bit. But i didn't find a statement, what clarifies what is a valid transaction or not.

goekay commented 5 years ago

StopTransaction processing should be exception free now. we catch all exceptions and log them. a confirmation is always sent back. however, i still have to figure out solutions for 1) the StartTransaction and 2) what to do with the data to prevent information loss.

goekay commented 5 years ago

still have to figure out solutions for 1) the StartTransaction and 2) what to do with the data to prevent information loss.

here is my rough thinking regarding 1: after looking at the processing of StartTransaction, i realized that there is very little that might go wrong, because we work around problematic cases already. if the connectorId and idTag properties are new and unknown, we insert them already. theoretically, an exception (for whatever reason) might still occur, but i don't want to touch such a case right now.

regarding 2: as i illustrated, i plan to insert failed transaction_stop insertions into another table transaction_stop_unknown that is column-wise similar to transaction_stop minus the constraints and foreign key references. i don't want to make this table in web ui available. users should just look at the database table for further analysis.

i hope this roadmap is okay for everyone.

steve-community / steve