NE:ONE returns 500 error for 4% of POST requests when handling many POST requests sequentially, related to database connection
Summary
The NE:ONE to database connection using RDF4J fails seemingly randomly when handling many POST-requests sequentially
Description
The NE:ONE to database connection using RDF4J fails seemingly randomly when handling many POST-requests sequentially. The server returns "500" errors. When reproducing with the same dataset, different LOs are affected. Re-trying usually creates the LOs successfully, sometimes requiring a few tries. Roughly 4% of transactions fail (sample 4076 requests, 2 runs). Connected Database is GraphDB. LOs feature pre-definded URIs.
The NE:ONE server logs the following whenever a transaction fails:
2024-03-04 10:56:14 2024-03-04 09:56:14,394 WARN [org.ope.neo.rep.RepositoryTransaction] (executor-thread-128) Exception during transaction, rolling back transaction: org.eclipse.rdf4j.query.QueryInterruptedException 2024-03-04 10:56:14 at org.eclipse.rdf4j.http.client.SPARQLProtocolSession.execute(SPARQLProtocolSession.java:1077) 2024-03-04 10:56:14 at org.eclipse.rdf4j.http.client.SPARQLProtocolSession.executeOK(SPARQLProtocolSession.java:1029) 2024-03-04 10:56:14 at org.eclipse.rdf4j.http.client.SPARQLProtocolSession.sendGraphQueryViaHttp(SPARQLProtocolSession.java:945) 2024-03-04 10:56:14 at org.eclipse.rdf4j.http.client.SPARQLProtocolSession.getRDFBackground(SPARQLProtocolSession.java:812) 2024-03-04 10:56:14 at org.eclipse.rdf4j.http.client.SPARQLProtocolSession.sendGraphQuery(SPARQLProtocolSession.java:430) 2024-03-04 10:56:14 at org.eclipse.rdf4j.repository.http.HTTPGraphQuery.evaluate(HTTPGraphQuery.java:52) 2024-03-04 10:56:14 at org.openlogisticsfoundation.neone.repository.AclAuthorizationRepository.findAclAuthorizations(AclAuthorizationRepository.java:77) 2024-03-04 10:56:14 at org.openlogisticsfoundation.neone.repository.AclAuthorizationRepository.getAclAuthorization(AclAuthorizationRepository.java:51) 2024-03-04 10:56:14 at org.openlogisticsfoundation.neone.repository.AclAuthorizationRepository.grantAccess(AclAuthorizationRepository.java:104) 2024-03-04 10:56:14 at org.openlogisticsfoundation.neone.repository.AclAuthorizationRepository.grantDefaultAccess(AclAuthorizationRepository.java:189) 2024-03-04 10:56:14 at org.openlogisticsfoundation.neone.repository.AclAuthorizationRepository_ClientProxy.grantDefaultAccess(Unknown Source) 2024-03-04 10:56:14 at org.openlogisticsfoundation.neone.service.LogisticsObjectService.lambda$createLogisticsObject$1(LogisticsObjectService.java:193) 2024-03-04 10:56:14 at org.openlogisticsfoundation.neone.repository.RepositoryTransaction.lambda$transactionallyDo$1(RepositoryTransaction.java:47) 2024-03-04 10:56:14 at org.openlogisticsfoundation.neone.repository.RepositoryTransaction.transactionallyGet(RepositoryTransaction.java:64) 2024-03-04 10:56:14 at org.openlogisticsfoundation.neone.repository.RepositoryTransaction.transactionallyDo(RepositoryTransaction.java:46) 2024-03-04 10:56:14 at org.openlogisticsfoundation.neone.repository.RepositoryTransaction_ClientProxy.transactionallyDo(Unknown Source) 2024-03-04 10:56:14 at org.openlogisticsfoundation.neone.service.LogisticsObjectService.createLogisticsObject(LogisticsObjectService.java:163) 2024-03-04 10:56:14 at org.openlogisticsfoundation.neone.service.LogisticsObjectService.createLogisticsObjects(LogisticsObjectService.java:157) 2024-03-04 10:56:14 at org.openlogisticsfoundation.neone.service.LogisticsObjectService_ClientProxy.createLogisticsObjects(Unknown Source) 2024-03-04 10:56:14 at org.openlogisticsfoundation.neone.controller.LogisticsObjectController.createLogisticsObject(LogisticsObjectController.java:103) 2024-03-04 10:56:14 at org.openlogisticsfoundation.neone.controller.LogisticsObjectController$quarkusrestinvoker$createLogisticsObject_8b4f711f969bba1d2b2cfda7d61515c5f8e42232.invoke(Unknown Source) 2024-03-04 10:56:14 at org.jboss.resteasy.reactive.server.handlers.InvocationHandler.handle(InvocationHandler.java:29) 2024-03-04 10:56:14 at io.quarkus.resteasy.reactive.server.runtime.QuarkusResteasyReactiveRequestContext.invokeHandler(QuarkusResteasyReactiveRequestContext.java:141) 2024-03-04 10:56:14 at org.jboss.resteasy.reactive.common.core.AbstractResteasyReactiveContext.run(AbstractResteasyReactiveContext.java:147) 2024-03-04 10:56:14 at io.quarkus.vertx.core.runtime.VertxCoreRecorder$14.runWith(VertxCoreRecorder.java:582) 2024-03-04 10:56:14 at org.jboss.threads.EnhancedQueueExecutor$Task.run(EnhancedQueueExecutor.java:2513) 2024-03-04 10:56:14 at org.jboss.threads.EnhancedQueueExecutor$ThreadBody.run(EnhancedQueueExecutor.java:1538) 2024-03-04 10:56:14 at org.jboss.threads.DelegatingRunnable.run(DelegatingRunnable.java:29) 2024-03-04 10:56:14 at org.jboss.threads.ThreadLocalResettingRunnable.run(ThreadLocalResettingRunnable.java:29) 2024-03-04 10:56:14 at io.netty.util.concurrent.FastThreadLocalRunnable.run(FastThreadLocalRunnable.java:30) 2024-03-04 10:56:14 at java.base/java.lang.Thread.run(Thread.java:840) 2024-03-04 10:56:14 2024-03-04 10:56:14 2024-03-04 09:56:14,400 ERROR [org.ope.neo.exc.UncaughtExceptionMapper] (executor-thread-128) Uncaught exception for path [http://localhost:8080/logistics-objects]: org.eclipse.rdf4j.query.QueryInterruptedException 2024-03-04 10:56:14 at org.eclipse.rdf4j.http.client.SPARQLProtocolSession.execute(SPARQLProtocolSession.java:1077) 2024-03-04 10:56:14 at org.eclipse.rdf4j.http.client.SPARQLProtocolSession.executeOK(SPARQLProtocolSession.java:1029) 2024-03-04 10:56:14 at org.eclipse.rdf4j.http.client.SPARQLProtocolSession.sendGraphQueryViaHttp(SPARQLProtocolSession.java:945) 2024-03-04 10:56:14 at org.eclipse.rdf4j.http.client.SPARQLProtocolSession.getRDFBackground(SPARQLProtocolSession.java:812) 2024-03-04 10:56:14 at org.eclipse.rdf4j.http.client.SPARQLProtocolSession.sendGraphQuery(SPARQLProtocolSession.java:430) 2024-03-04 10:56:14 at org.eclipse.rdf4j.repository.http.HTTPGraphQuery.evaluate(HTTPGraphQuery.java:52) 2024-03-04 10:56:14 at org.openlogisticsfoundation.neone.repository.AclAuthorizationRepository.findAclAuthorizations(AclAuthorizationRepository.java:77) 2024-03-04 10:56:14 at org.openlogisticsfoundation.neone.repository.AclAuthorizationRepository.getAclAuthorization(AclAuthorizationRepository.java:51) 2024-03-04 10:56:14 at org.openlogisticsfoundation.neone.repository.AclAuthorizationRepository.grantAccess(AclAuthorizationRepository.java:104) 2024-03-04 10:56:14 at org.openlogisticsfoundation.neone.repository.AclAuthorizationRepository.grantDefaultAccess(AclAuthorizationRepository.java:189) 2024-03-04 10:56:14 at org.openlogisticsfoundation.neone.repository.AclAuthorizationRepository_ClientProxy.grantDefaultAccess(Unknown Source) 2024-03-04 10:56:14 at org.openlogisticsfoundation.neone.service.LogisticsObjectService.lambda$createLogisticsObject$1(LogisticsObjectService.java:193) 2024-03-04 10:56:14 at org.openlogisticsfoundation.neone.repository.RepositoryTransaction.lambda$transactionallyDo$1(RepositoryTransaction.java:47) 2024-03-04 10:56:14 at org.openlogisticsfoundation.neone.repository.RepositoryTransaction.transactionallyGet(RepositoryTransaction.java:64) 2024-03-04 10:56:14 at org.openlogisticsfoundation.neone.repository.RepositoryTransaction.transactionallyDo(RepositoryTransaction.java:46) 2024-03-04 10:56:14 at org.openlogisticsfoundation.neone.repository.RepositoryTransaction_ClientProxy.transactionallyDo(Unknown Source) 2024-03-04 10:56:14 at org.openlogisticsfoundation.neone.service.LogisticsObjectService.createLogisticsObject(LogisticsObjectService.java:163) 2024-03-04 10:56:14 at org.openlogisticsfoundation.neone.service.LogisticsObjectService.createLogisticsObjects(LogisticsObjectService.java:157) 2024-03-04 10:56:14 at org.openlogisticsfoundation.neone.service.LogisticsObjectService_ClientProxy.createLogisticsObjects(Unknown Source) 2024-03-04 10:56:14 at org.openlogisticsfoundation.neone.controller.LogisticsObjectController.createLogisticsObject(LogisticsObjectController.java:103) 2024-03-04 10:56:14 at org.openlogisticsfoundation.neone.controller.LogisticsObjectController$quarkusrestinvoker$createLogisticsObject_8b4f711f969bba1d2b2cfda7d61515c5f8e42232.invoke(Unknown Source) 2024-03-04 10:56:14 at org.jboss.resteasy.reactive.server.handlers.InvocationHandler.handle(InvocationHandler.java:29) 2024-03-04 10:56:14 at io.quarkus.resteasy.reactive.server.runtime.QuarkusResteasyReactiveRequestContext.invokeHandler(QuarkusResteasyReactiveRequestContext.java:141) 2024-03-04 10:56:14 at org.jboss.resteasy.reactive.common.core.AbstractResteasyReactiveContext.run(AbstractResteasyReactiveContext.java:147) 2024-03-04 10:56:14 at io.quarkus.vertx.core.runtime.VertxCoreRecorder$14.runWith(VertxCoreRecorder.java:582) 2024-03-04 10:56:14 at org.jboss.threads.EnhancedQueueExecutor$Task.run(EnhancedQueueExecutor.java:2513) 2024-03-04 10:56:14 at org.jboss.threads.EnhancedQueueExecutor$ThreadBody.run(EnhancedQueueExecutor.java:1538) 2024-03-04 10:56:14 at org.jboss.threads.DelegatingRunnable.run(DelegatingRunnable.java:29) 2024-03-04 10:56:14 at org.jboss.threads.ThreadLocalResettingRunnable.run(ThreadLocalResettingRunnable.java:29) 2024-03-04 10:56:14 at io.netty.util.concurrent.FastThreadLocalRunnable.run(FastThreadLocalRunnable.java:30) 2024-03-04 10:56:14 at java.base/java.lang.Thread.run(Thread.java:840)
Steps to Reproduce (for bugs)
- Start a clean NE:ONE server using the docker compose scripts provided at https://github.com/ddoeppner/one-record-server-first-steps
- Use the script and test data provided at https://github.com/NiclasScheiber/sparqling-one-record/tree/main/testdata
- Monitor the log of the script for 500 errors
Expected Behavior
201 created for every POST request
Actual Behavior
500 internal server error for 4% of POST requests
Screenshots (if applicable)
Sample POST request bodies of failed transactions:
[ { "@id": "http://localhost:8080/logistics-objects/transportMovementTruck_370_Express_Export_202330_083000_1078753092", "@type": [ "https://onerecord.iata.org/ns/cargo#TransportMovement" ], "https://onerecord.iata.org/ns/cargo#arrivalLocation": [ { "@id": "http://localhost:8080/logistics-objects/Ground_Handling_Warehouse_FRA" } ], "https://onerecord.iata.org/ns/cargo#executionStatus": [ { "@id": "https://onerecord.iata.org/ns/cargo#COMPLETED" } ], "https://onerecord.iata.org/ns/cargo#loadingActions": [ { "@id": "http://localhost:8080/logistics-objects/unload113-71007766onTruck_370_Express_Export_202330_083000_1078753092" }, { "@id": "http://localhost:8080/logistics-objects/unload84860000771onTruck_370_Express_Export_202330_083000_1078753092" }, { "@id": "http://localhost:8080/logistics-objects/unload113-41007447onTruck_370_Express_Export_202330_083000_1078753092" } ], "https://onerecord.iata.org/ns/cargo#modeCode": [ { "@id": "https://onerecord.iata.org/ns/coreCodeLists#ModeCode_ROAD_TRANSPORT" } ], "https://onerecord.iata.org/ns/cargo#modeQualifier": [ { "@id": "https://onerecord.iata.org/ns/cargo#PRE_CARRIAGE" } ], "https://onerecord.iata.org/ns/cargo#movementTimes": [ { "@id": "_:N2078c133fd11494db41b23b7a904dd69" } ], "https://onerecord.iata.org/ns/cargo#servedServices": [ { "@id": "http://localhost:8080/logistics-objects/Transport_Service_" }, { "@id": "http://localhost:8080/logistics-objects/Transport_Service_84860000771" } ], "https://onerecord.iata.org/ns/cargo#transportIdentifier": [ { "@value": "Truck_370_Express_Export_202330_083000_1078753092" } ] }, { "@id": "_:N2078c133fd11494db41b23b7a904dd69", "@type": [ "https://onerecord.iata.org/ns/cargo#MovementTime" ], "https://onerecord.iata.org/ns/cargo#direction": [ { "@id": "https://onerecord.iata.org/ns/cargo#INBOUND" } ], "https://onerecord.iata.org/ns/cargo#movementMilestone": [ { "@id": "https://onerecord.iata.org/ns/coreCodeLists#MovementIndicator_AG" } ], "https://onerecord.iata.org/ns/cargo#movementTimeType": [ { "@id": "https://onerecord.iata.org/ns/cargo#ACTUAL" } ], "https://onerecord.iata.org/ns/cargo#movementTimestamp": [ { "@type": "http://www.w3.org/2001/XMLSchema#dateTime", "@value": "2023-11-24T08:30:00+00:00" } ] } ]
'[ { "@id": "http://localhost:8080/logistics-objects/Piece1245278980", "@type": [ "https://onerecord.iata.org/ns/cargo#PieceDg" ], "https://onerecord.iata.org/ns/cargo#contentProducts": [ { "@id": "http://localhost:8080/logistics-objects/Product_10240000652_851580" } ], "https://onerecord.iata.org/ns/cargo#dgDeclaration": [ { "@id": "http://localhost:8080/logistics-objects/Piece1245278980_DGD" } ], "https://onerecord.iata.org/ns/cargo#goodsDescription": [ { "@value": "LASER BEAMS" } ], "https://onerecord.iata.org/ns/cargo#grossWeight": [ { "@id": ":Ne143c7dfffc0472f84d24a45ee7e6381" } ], "https://onerecord.iata.org/ns/cargo#involvedInActions": [ { "@id": "http://localhost:8080/logistics-objects/unload10240000652onTruck_706_1_Export" }, { "@id": "http://localhost:8080/logistics-objects/compose113-340065251463680099" }, { "@id": "http://localhost:8080/logistics-objects/decompose113-340065251463680099" } ], "https://onerecord.iata.org/ns/cargo#loadType": [ { "@id": "https://onerecord.iata.org/ns/cargo#PALLET" } ], "https://onerecord.iata.org/ns/cargo#ofShipment": [ { "@id": "http://localhost:8080/logistics-objects/shipment10240000652" } ], "https://onerecord.iata.org/ns/cargo#specialHandlingCodes": [ { "@id": "https://onerecord.iata.org/ns/coreCodeLists#SpecialHandlingCode_EAP" }, { "@id": "https://onerecord.iata.org/ns/coreCodeLists#SpecialHandlingCode_ECC" }, { "@id": "https://onerecord.iata.org/ns/coreCodeLists#SecurityStatus_SPX" } ] }, { "@id": ":Ne143c7dfffc0472f84d24a45ee7e6381", "@type": [ "https://onerecord.iata.org/ns/cargo#Value" ], "https://onerecord.iata.org/ns/cargo#numericalValue": [ { "@value": 1002.0 } ], "https://onerecord.iata.org/ns/cargo#unit": [ { "@id": "https://onerecord.iata.org/ns/coreCodeLists#MeasurementUnitCode_KGM" } ] } ]'
Additional Information (optional)
Not tested with different database endpoint yet