Problems in Deploying OTP Application

[RudiThoeni]

Today i experience problems on the Deployment of the OTP Application...

By starting the otp container this error is given:

12:34:00.951 INFO (GraphService.java:176) Registering new router 'openmove'
otp_1         | 12:34:00.960 INFO (InputStreamGraphSource.java:177) Loading graph...
otp_1         | 12:34:01.318 ERROR (InputStreamGraphSource.java:181) Exception while loading graph 'openmove'.
otp_1         | com.esotericsoftware.kryo.KryoException: Buffer underflow.
otp_1         |         at com.esotericsoftware.kryo.io.Input.require(Input.java:199) ~[otp-unofficial.jar:1.1]
otp_1         |         at com.esotericsoftware.kryo.io.Input.readVarInt(Input.java:373) ~[otp-unofficial.jar:1.1]
otp_1         |         at com.esotericsoftware.kryo.util.DefaultClassResolver.readClass(DefaultClassResolver.java:127) ~[otp-unofficial.jar:1.1]
otp_1         |         at com.esotericsoftware.kryo.Kryo.readClass(Kryo.java:693) ~[otp-unofficial.jar:1.1]
otp_1         |         at com.esotericsoftware.kryo.Kryo.readClassAndObject(Kryo.java:804) ~[otp-unofficial.jar:1.1]
otp_1         |         at org.opentripplanner.routing.graph.Graph.load(Graph.java:767) ~[otp-unofficial.jar:1.1]
otp_1         |         at org.opentripplanner.routing.impl.InputStreamGraphSource.loadGraph(InputStreamGraphSource.java:179) [otp-unofficial.jar:1.1]
otp_1         |         at org.opentripplanner.routing.impl.InputStreamGraphSource.reload(InputStreamGraphSource.java:103) [otp-unofficial.jar:1.1]
otp_1         |         at org.opentripplanner.routing.services.GraphService.registerGraph(GraphService.java:183) [otp-unofficial.jar:1.1]
otp_1         |         at org.opentripplanner.routing.impl.GraphScanner.startup(GraphScanner.java:69) [otp-unofficial.jar:1.1]
otp_1         |         at org.opentripplanner.standalone.OTPMain.run(OTPMain.java:131) [otp-unofficial.jar:1.1]
otp_1         |         at org.opentripplanner.standalone.OTPMain.main(OTPMain.java:74) [otp-unofficial.jar:1.1]
otp_1         | 12:34:01.320 WARN (InputStreamGraphSource.java:114) Unable to load data for router 'openmove'.
otp_1         | 12:34:01.320 WARN (GraphService.java:185) Can't register router ID 'openmove', no graph.
otp_1         | 12:34:01.329 INFO (GrizzlyServer.java:72) Starting OTP Grizzly server on ports 8080 (HTTP) and 8081 (HTTPS) of interface 0.0.0.0
otp_1         | 12:34:01.329 INFO (GrizzlyServer.java:74) OTP server base path is /var/otp
otp_1         | 12:34:01.426 INFO (GrizzlyServer.java:51) Java reports that this machine has 2 available processors.
otp_1         | 12:34:01.427 INFO (GrizzlyServer.java:62) Maximum HTTP handler thread pool size will be 4 threads.
otp_1         | 2021-11-18T12:34:07.109+0000  WARNING  There is no way how to transform value "true" [java.lang.Boolean] to type [java.lang.String].
otp_1         | 12:34:07.238 INFO (GrizzlyServer.java:153) Grizzly server running.
otp_1         | 12:34:39.765 ERROR (GraphService.java:111) no graph registered with the routerId 'openmove'
otp_1         | 12:34:39.768 ERROR (ErrorUtils.java:53) Unhandled server exception
otp_1         | org.opentripplanner.routing.error.GraphNotFoundException: null
otp_1         |         at org.opentripplanner.routing.services.GraphService.getRouter(GraphService.java:112) ~[otp-unofficial.jar:1.1]
otp_1         |         at org.opentripplanner.standalone.OTPServer.getRouter(OTPServer.java:75) ~[otp-unofficial.jar:1.1]
otp_1         |         at org.opentripplanner.api.resource.BikeRental.getBikeRentalStations(BikeRental.java:41) ~[otp-unofficial.jar:1.1]
otp_1         |         at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method) ~[na:1.8.0_275]
otp_1         |         at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62) ~[na:1.8.0_275]
otp_1         |         at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) ~[na:1.8.0_275]
otp_1         |         at java.lang.reflect.Method.invoke(Method.java:498) ~[na:1.8.0_275]
otp_1         |         at org.glassfish.jersey.server.model.internal.ResourceMethodInvocationHandlerFactory$1.invoke(ResourceMethodInvocationHandlerFactory.java:81) ~[otp-unofficial.jar:1.1]

I tried many deploys without success....

So i also started the Graph Calculation. (https://github.com/noi-techpark/odh-mentor-otp/blob/master/infrastructure/Jenkinsfile-Test-Calculate.groovy), rebuilding the graph Normally it takes about 15 - 20 minutes, Today it took 1,5 hours and 2,5 hours Since the additional instance for graph calculation is shut down after completed i did not see the logs.....

In the otp containter in data/openmove the Graph.obj file is about 0 bytes

I will start the graph calculation and see if i can provide you some logs...... any suggestions?

[zabuTNT]

 (GraphService.java:176) Registering new router 'openmove'
otp_1         | 12:34:00.960 INFO (InputStreamGraphSource.java:177) Loading graph...
otp_1         | 12:34:01.318 ERROR (InputStreamGraphSource.java:181) Exception while loading graph 'openmove'.
otp_1         | com.esotericsoftware.kryo.KryoException: Buffer underflow.

This happens when there are few memory resources. OTP reads the graphs, discover the router (in this case openmove, the name for our graph) and put it in memory.

Buffer underflow means that the in-memory copy failed due lack of resources.

So, OTP skip the import for the "openmove" graph.... but then, we explicitly said that we want to use the graph openmove

https://github.com/noi-techpark/odh-mentor-otp/blob/master/infrastructure/docker/otp/docker-entrypoint.sh#L133

and this obviously fails:

2:34:39.765 ERROR (GraphService.java:111) no graph registered with the routerId 'openmove'
otp_1         | 12:34:39.768 ERROR (ErrorUtils.java:53) Unhandled server exception

How much memory you assigned for the instance?

[RudiThoeni]

@zabuTNT thx for your feedback, so the solution would be to increase ressources.... The test server is a docker environment with 16GB of memory in total at the moment only 35% are used...... I normally resolved this by increasing this JAVA_MX Variable https://github.com/noi-techpark/odh-mentor-otp/blob/development/infrastructure/Jenkinsfile-Test-Execute.groovy#L28

What i find strange is the graph calculation today takes so long...... (which is done on another instance with a lot more resources). I started it 20 minutes ago and it is still processing:

otp_1  | 13:09:36.144 INFO (DirectTransferGenerator.java:69) Linked 22000 stops
otp_1  | 13:10:34.307 INFO (DirectTransferGenerator.java:69) Linked 23000 stops
otp_1  | 13:11:51.420 INFO (DirectTransferGenerator.java:69) Linked 24000 stops
otp_1  | 13:13:54.126 INFO (DirectTransferGenerator.java:69) Linked 25000 stops

a few weeks ago it always took around 15 minutes.... so i found it very strange today......because there nothing was changed?

[zabuTNT]

Is the same GTFS? Maybe STA added routes and stops. We didn't change the build. Maybe a CPU limit?

For the graph with 0 size, maybe a copy error? The container was killed before the copy ended? The graph is build on root path so for instance: /data/Graph.obj , and when "otp-build" success we move the Graph inside openmove path, so /data/openmove/Graph.obj.

https://github.com/noi-techpark/odh-mentor-otp/blob/development/infrastructure/docker/otp/docker-entrypoint.sh#L120

[RudiThoeni]

@rcavaliere STA added routes and stops recently? ok i will check for the 0byte graph.obj file.....

the calculation is still in progress ;)

otp_1  | 13:38:59.835 INFO (DirectTransferGenerator.java:69) Linked 44000 stops
otp_1  | 13:42:08.058 INFO (DirectTransferGenerator.java:69) Linked 45000 stops
otp_1  | 13:51:52.327 INFO (DirectTransferGenerator.java:69) Linked 46000 stops

[RudiThoeni]

ok the graph calculation was out of memory (after more than 2 hours i finally got this error ;))

 Exception in thread "main" java.lang.OutOfMemoryError: Java heap space
otp_1  |        at org.locationtech.jts.geom.Coordinates.create(Coordinates.java:41)
otp_1  |        at org.locationtech.jts.geom.CoordinateSequence.createCoordinate(CoordinateSequence.java:128)
otp_1  |        at org.locationtech.jts.geom.impl.CoordinateArraySequence.copy(CoordinateArraySequence.java:307)
otp_1  |        at org.locationtech.jts.geom.impl.CoordinateArraySequence.copy(CoordinateArraySequence.java:36)
otp_1  |        at org.locationtech.jts.geom.LineString.reverse(LineString.java:185)
otp_1  |        at org.opentripplanner.common.geometry.CompactLineString.uncompactLineString(CompactLineString.java:160)
otp_1  |        at org.opentripplanner.routing.edgetype.StreetEdge.getGeometry(StreetEdge.java:1175)
otp_1  |        at org.opentripplanner.graph_builder.module.NearbyStopFinder.stopAtDistanceForState(NearbyStopFinder.java:219)
otp_1  |        at org.opentripplanner.graph_builder.module.NearbyStopFinder.findNearbyStopsViaStreets(NearbyStopFinder.java:148)
otp_1  |        at org.opentripplanner.graph_builder.module.NearbyStopFinder.findNearbyStops(NearbyStopFinder.java:126)
otp_1  |        at org.opentripplanner.graph_builder.module.NearbyStopFinder.findNearbyStopsConsideringPatterns(NearbyStopFinder.java:87)
otp_1  |        at org.opentripplanner.graph_builder.module.DirectTransferGenerator.buildGraph(DirectTransferGenerator.java:86)
otp_1  |        at org.opentripplanner.graph_builder.GraphBuilder.run(GraphBuilder.java:141)
otp_1  |        at org.opentripplanner.standalone.OTPMain.run(OTPMain.java:104)
otp_1  |        at org.opentripplanner.standalone.OTPMain.main(OTPMain.java:74)
otp_1  | Create new backup... Graph.obj.21-11-18.tgz

so now i set the jJAVA_MX variable to the max of the server memory, and after 15 minutes all was done,

also the application works again,

@zabuTNT thank you for your support!

[rcavaliere]

Just for info, the GTFS didn't change