Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

java.lang.NullPointerException: null at org.transitclock.gtfs.DbConfig.getStopIdsForRoute - core startup failure #251

Closed
BodoMinea opened this issue Nov 29, 2021 · 7 comments

Comments

@BodoMinea
Copy link

Hi everyone,

I am trying to launch my second deployment of TheTransitClock. The first one I managed to get running last year and is still working properly. However, by following the same steps I am now running into some problems that I haven't been able to diagnose.

Expected functionality
After going through the „full” deployment process for system - installing Ubuntu Server with Java 1.8, MariaDB 10, Tomcat 8, building TheTransitClock from GitHub, creating the database, table structures, importing data, adding API keys and WebAgencies and configuring them to be in Tomcat's environment, running the RMI Registry, running the Core.jar-s, the expected outcome would be to see agency names when opening up the web interface, and from there being able to inspect maps and reports in order to assess the functionality of the system.

Describe the bug
The Web UI only shows agency IDs in the table, as if it wasn't able to get the agency names from the system. Maps and reports do not work because the API calls are failing with error 400. There nothing in any log to suggest anything is wrong - catalina.out and core.log have no stack traces.

Version:
Latest develop from github.

Screenshots, Logs, Diagnostics & Additional context
Screenshot 2021-11-29 at 14 36 27
Screenshot 2021-11-29 at 14 35 53

root@server:/# ps aux | grep rmireg
user 1244175  0.2  0.3 4463048 31484 pts/1   Sl   13:55   0:00 rmiregistry
root@server:/# netstat -tulpn | grep rmi
tcp        0      0 0.0.0.0:1099            0.0.0.0:*               LISTEN      1244175/rmiregistry
root@server:/# netstat -tulpn | grep java
tcp        0      0 127.0.0.1:8005          0.0.0.0:*               LISTEN      1224358/java        
tcp        0      0 0.0.0.0:8009            0.0.0.0:*               LISTEN      1224358/java        
tcp        0      0 0.0.0.0:38825           0.0.0.0:*               LISTEN      1222078/java        
tcp        0      0 0.0.0.0:8080            0.0.0.0:*               LISTEN      1224358/java        
tcp        0      0 0.0.0.0:2099            0.0.0.0:*               LISTEN      1222078/java        
tcp        0      0 0.0.0.0:46293           0.0.0.0:*               LISTEN      1222072/java        
tcp        0      0 0.0.0.0:40505           0.0.0.0:*               LISTEN      1222129/java        
tcp        0      0 0.0.0.0:34787           0.0.0.0:*               LISTEN      1222079/java

Looking in the console at one of the cores reveals something like this:

--- a lot of other INFOs ---
05:49:26,989 |-INFO in ch.qos.logback.classic.joran.action.ConfigurationAction - End of configuration.
05:49:26,990 |-INFO in ch.qos.logback.classic.joran.JoranConfigurator@7a5d012c - Registering current configuration as safe fallback point

Nov 29, 2021 5:49:27 AM com.mchange.v2.log.MLog <clinit>
INFO: MLog clients using java 1.4+ standard logging.
Nov 29, 2021 5:49:27 AM com.mchange.v2.c3p0.C3P0Registry banner
INFO: Initializing c3p0-0.9.2.1 [built 20-March-2013 10:47:27 +0000; debug? true; trace: 10]
Nov 29, 2021 5:49:27 AM com.mchange.v2.c3p0.impl.AbstractPoolBackedDataSource getPoolManager
INFO: Initializing c3p0 pool... com.mchange.v2.c3p0.PoolBackedDataSource@7ed70f83 [ connectionPoolDataSource -> com.mchange.v2.c3p0.WrapperConnectionPoolDataSource@ed2bf036 [ acquireIncrement -> 3, acquireRetryAttempts -> 30, acquireRetryDelay -> 1000, autoCommitOnClose -> false, automaticTestTable -> null, breakAfterAcquireFailure -> false, checkoutTimeout -> 0, connectionCustomizerClassName -> null, connectionTesterClassName -> com.mchange.v2.c3p0.impl.DefaultConnectionTester, debugUnreturnedConnectionStackTraces -> false, factoryClassLocation -> null, forceIgnoreUnresolvedTransactions -> false, identityToken -> _REDACTED_, idleConnectionTestPeriod -> 0, initialPoolSize -> 2, maxAdministrativeTaskTime -> 0, maxConnectionAge -> 0, maxIdleTime -> 300, maxIdleTimeExcessConnections -> 0, maxPoolSize -> 20, maxStatements -> 50, maxStatementsPerConnection -> 0, minPoolSize -> 2, nestedDataSource -> com.mchange.v2.c3p0.DriverManagerDataSource@de715990 [ description -> null, driverClass -> null, factoryClassLocation -> null, identityToken -> _REDACTED_, jdbcUrl -> jdbc:mysql://localhost/transitime, properties -> {user=******, password=******} ], preferredTestQuery -> null, propertyCycle -> 0, statementCacheNumDeferredCloseThreads -> 0, testConnectionOnCheckin -> false, testConnectionOnCheckout -> false, unreturnedConnectionTimeout -> 0, usesTraditionalReflectiveProxies -> false; userOverrides: {} ], dataSourceName -> null, factoryClassLocation -> null, identityToken -> _REDACTED_, numHelperThreads -> 3 ]
Nov 29, 2021 5:49:30 AM com.mchange.v2.c3p0.impl.AbstractPoolBackedDataSource getPoolManager
INFO: Initializing c3p0 pool... com.mchange.v2.c3p0.PoolBackedDataSource@c18d6bf5 [ connectionPoolDataSource -> com.mchange.v2.c3p0.WrapperConnectionPoolDataSource@2ca15a3c [ acquireIncrement -> 3, acquireRetryAttempts -> 30, acquireRetryDelay -> 1000, autoCommitOnClose -> false, automaticTestTable -> null, breakAfterAcquireFailure -> false, checkoutTimeout -> 0, connectionCustomizerClassName -> null, connectionTesterClassName -> com.mchange.v2.c3p0.impl.DefaultConnectionTester, debugUnreturnedConnectionStackTraces -> false, factoryClassLocation -> null, forceIgnoreUnresolvedTransactions -> false, identityToken -> _REDACTED_, idleConnectionTestPeriod -> 0, initialPoolSize -> 2, maxAdministrativeTaskTime -> 0, maxConnectionAge -> 0, maxIdleTime -> 300, maxIdleTimeExcessConnections -> 0, maxPoolSize -> 20, maxStatements -> 50, maxStatementsPerConnection -> 0, minPoolSize -> 2, nestedDataSource -> com.mchange.v2.c3p0.DriverManagerDataSource@35d9500 [ description -> null, driverClass -> null, factoryClassLocation -> null, identityToken -> _REDACTED_, jdbcUrl -> jdbc:mysql://localhost/transitime, properties -> {user=******, password=******} ], preferredTestQuery -> null, propertyCycle -> 0, statementCacheNumDeferredCloseThreads -> 0, testConnectionOnCheckin -> false, testConnectionOnCheckout -> false, unreturnedConnectionTimeout -> 0, usesTraditionalReflectiveProxies -> false; userOverrides: {} ], dataSourceName -> null, factoryClassLocation -> null, identityToken -> _REDACTED_, numHelperThreads -> 3

Looks pretty normal to me.
Looking into the logs of one of the running cores:
core.log

Getting GTFS-realtime AVL data from URL=_REDACTED_
Parsing GTFS-realtime file into a FeedMessage took 4 msec
Processing each individual AvlReport...
Successfully processed 11 AVL reports from GTFS-realtime feed in 0 msec
====================================================AvlProcessor processing AvlReport [vehicleId=_REDACTED_, time=11-29-2021 14:02:04.000 EET, location=[44.52204, 25.99597], speed=NaN, heading=NaN, source=GTFS-rt, assignmentId=_REDACTED_, assignmentType=ROUTE_ID, licensePlate=_REDACTED_]
====================================================AvlProcessor processing AvlReport [vehicleId=_REDACTED_, time=11-29-2021 14:02:04.000 EET, location=[44.47101, 25.96766], speed=NaN, heading=NaN, source=GTFS-rt, assignmentId=_REDACTED_, assignmentType=ROUTE_ID, licensePlate=_REDACTED_]
====================================================AvlProcessor processing AvlReport [vehicleId=_REDACTED_, time=11-29-2021 14:02:04.000 EET, location=[44.51312, 25.97680], speed=NaN, heading=NaN, source=GTFS-rt, assignmentId=_REDACTED_, assignmentType=ROUTE_ID, licensePlate=_REDACTED_]
====================================================AvlProcessor processing AvlReport [vehicleId=_REDACTED_, time=11-29-2021 14:02:04.000 EET, location=[44.51495, 25.97055], speed=NaN, heading=NaN, source=GTFS-rt, assignmentId=_REDACTED_, assignmentType=ROUTE_ID, licensePlate=_REDACTED_]
====================================================AvlProcessor processing AvlReport [vehicleId=_REDACTED_, time=11-29-2021 14:02:04.000 EET, location=[44.47254, 25.97165], speed=NaN, heading=NaN, source=GTFS-rt, assignmentId=_REDACTED_, assignmentType=ROUTE_ID, licensePlate=_REDACTED_]
====================================================AvlProcessor processing AvlReport [vehicleId=_REDACTED_, time=11-29-2021 14:02:04.000 EET, location=[44.43230, 26.00527], speed=NaN, heading=NaN, source=GTFS-rt, assignmentId=_REDACTED_, assignmentType=ROUTE_ID, licensePlate=_REDACTED_]
====================================================AvlProcessor processing AvlReport [vehicleId=_REDACTED_, time=11-29-2021 14:02:04.000 EET, location=[44.51395, 25.97242], speed=NaN, heading=NaN, source=GTFS-rt, assignmentId=_REDACTED_, assignmentType=ROUTE_ID, licensePlate=_REDACTED_]
====================================================AvlProcessor processing AvlReport [vehicleId=_REDACTED_, time=11-29-2021 14:02:04.000 EET, location=[44.51519, 25.97053], speed=NaN, heading=NaN, source=GTFS-rt, assignmentId=_REDACTED_, assignmentType=ROUTE_ID, licensePlate=_REDACTED_]
====================================================AvlProcessor processing AvlReport [vehicleId=_REDACTED_, time=11-29-2021 14:02:04.000 EET, location=[44.48041, 26.03439], speed=NaN, heading=NaN, source=GTFS-rt, assignmentId=_REDACTED_, assignmentType=ROUTE_ID, licensePlate=_REDACTED_]
====================================================AvlProcessor processing AvlReport [vehicleId=_REDACTED_, time=11-29-2021 14:02:04.000 EET, location=[44.47739, 26.04251], speed=NaN, heading=NaN, source=GTFS-rt, assignmentId=_REDACTED_, assignmentType=ROUTE_ID, licensePlate=_REDACTED_]
====================================================AvlProcessor processing AvlReport [vehicleId=_REDACTED_, time=11-29-2021 14:02:04.000 EET, location=[44.37875, 26.00462], speed=NaN, heading=NaN, source=GTFS-rt, assignmentId=_REDACTED_, assignmentType=ROUTE_ID, licensePlate=_REDACTED_]
Getting GTFS-realtime AVL data from URL=_REDACTED_
Parsing GTFS-realtime file into a FeedMessage took 4 msec
Processing each individual AvlReport...
Successfully processed 11 AVL reports from GTFS-realtime feed in 0 msec

avl.log

Thread=avlClient-1 AvlClient processing AVL data AvlReport [vehicleId=_REDACTED_, time=11-29-2021 14:04:20.000 EET, location=[44.43230, 26.00527], speed=NaN, heading=NaN, source=GTFS-rt, assignmentId=PV1_429, assignmentType=ROUTE_ID, licensePlate=_REDACTED_]
Thread=avlClient-1 AvlClient processing AVL data AvlReport [vehicleId=_REDACTED_, time=11-29-2021 14:04:20.000 EET, location=[44.51533, 25.97027], speed=NaN, heading=NaN, source=GTFS-rt, assignmentId=PV1_476, assignmentType=ROUTE_ID, licensePlate=_REDACTED_]
Thread=avlClient-1 AvlClient processing AVL data AvlReport [vehicleId=_REDACTED_, time=11-29-2021 14:04:20.000 EET, location=[44.50986, 25.97831], speed=NaN, heading=NaN, source=GTFS-rt, assignmentId=PV1_476, assignmentType=ROUTE_ID, licensePlate=_REDACTED_]
Thread=avlClient-1 AvlClient processing AVL data AvlReport [vehicleId=_REDACTED_, time=11-29-2021 14:04:20.000 EET, location=[44.47710, 26.04270], speed=NaN, heading=NaN, source=GTFS-rt, assignmentId=PV1_476, assignmentType=ROUTE_ID, licensePlate=_REDACTED_]
Thread=avlClient-1 AvlClient processing AVL data AvlReport [vehicleId=_REDACTED_, time=11-29-2021 14:04:20.000 EET, location=[44.48123, 26.03293], speed=NaN, heading=NaN, source=GTFS-rt, assignmentId=PV1_476, assignmentType=ROUTE_ID, licensePlate=_REDACTED_]
Thread=avlClient-1 AvlClient processing AVL data AvlReport [vehicleId=_REDACTED_, time=11-29-2021 14:04:20.000 EET, location=[44.38467, 26.00059], speed=NaN, heading=NaN, source=GTFS-rt, assignmentId=PV1_481, assignmentType=ROUTE_ID, licensePlate=_REDACTED_]

Anyway, it seems to be running normally and doing its job. I can also see assignments being made in autoAssigner.log.

Now to Tomcat. This is relevant output from catalina.out

29-Nov-2021 06:16:26.872 INFO [localhost-startStop-1] org.apache.catalina.startup.HostConfig.deployWAR Deployment of web application archive /usr/local/tomcat/webapps/api.war has finished in 11,31
7 ms
29-Nov-2021 06:16:26.874 INFO [localhost-startStop-1] org.apache.catalina.startup.HostConfig.deployWAR Deploying web application archive /usr/local/tomcat/webapps/web.war
29-Nov-2021 06:16:29.223 INFO [localhost-startStop-1] org.apache.jasper.servlet.TldScanner.scanJars At least one JAR was scanned for TLDs yet contained no TLDs. Enable debug logging for this logge
r for a complete list of JARs that were scanned but no TLDs were found in them. Skipping unneeded JARs during scanning can improve startup time and JSP compilation time.
Reading from web.xml file the context-param name transitime_config_file_location from the web.xml file to determine the name of the Java properties configuration file.
Processing configuration file /usr/local/transitclock/config/_REDACTED_.xml
29-Nov-2021 06:16:29.507 INFO [localhost-startStop-1] org.apache.catalina.startup.HostConfig.deployWAR Deployment of web application archive /usr/local/tomcat/webapps/web.war has finished in 2,633 ms
29-Nov-2021 06:16:29.877 INFO [main] org.apache.coyote.AbstractProtocol.start Starting ProtocolHandler ["http-nio-8080"]
29-Nov-2021 06:16:29.883 INFO [main] org.apache.coyote.AbstractProtocol.start Starting ProtocolHandler ["ajp-nio-8009"]
29-Nov-2021 06:16:29.893 INFO [main] org.apache.catalina.startup.Catalina.start Server startup in 14380 ms
29-Nov-2021 06:16:30.862 INFO [http-nio-8080-exec-1] com.mchange.v2.log.MLog.<clinit> MLog clients using java 1.4+ standard logging.
29-Nov-2021 06:16:30.919 INFO [http-nio-8080-exec-1] com.mchange.v2.c3p0.C3P0Registry.banner Initializing c3p0-0.9.2.1 [built 20-March-2013 10:47:27 +0000; debug? true; trace: 10]
29-Nov-2021 06:16:30.982 INFO [http-nio-8080-exec-1] com.mchange.v2.c3p0.impl.AbstractPoolBackedDataSource.getPoolManager Initializing c3p0 pool... com.mchange.v2.c3p0.PoolBackedDataSource@b5d175f8 [ connectionPoolDataSource -> com.mchange.v2.c3p0.WrapperConnectionPoolDataSource@8134f7a7 [ acquireIncrement -> 3, acquireRetryAttempts -> 30, acquireRetryDelay -> 1000, autoCommitOnClose -> false, automaticTestTable -> null, breakAfterAcquireFailure -> false, checkoutTimeout -> 0, connectionCustomizerClassName -> null, connectionTesterClassName -> com.mchange.v2.c3p0.impl.DefaultConnectionTester, debugUnreturnedConnectionStackTraces -> false, factoryClassLocation -> null, forceIgnoreUnresolvedTransactions -> false, identityToken -> _REDACTED_, idleConnectionTestPeriod -> 0, initialPoolSize -> 2, maxAdministrativeTaskTime -> 0, maxConnectionAge -> 0, maxIdleTime -> 300, maxIdleTimeExcessConnections -> 0, maxPoolSize -> 20, maxStatements -> 50, maxStatementsPerConnection -> 0, minPoolSize -> 2, nestedDataSource -> com.mchange.v2.c3p0.DriverManagerDataSource@afaaae36 [ description -> null, driverClass -> null, factoryClassLocation -> null, identityToken -> _REDACTED_, jdbcUrl -> jdbc:mysql://localhost/transitime, properties -> {user=******, password=******} ], preferredTestQuery -> null, propertyCycle -> 0, statementCacheNumDeferredCloseThreads -> 0, testConnectionOnCheckin -> false, testConnectionOnCheckout -> false, unreturnedConnectionTimeout -> 0, usesTraditionalReflectiveProxies -> false; userOverrides: {} ], dataSourceName -> null, factoryClassLocation -> null, identityToken -> _REDACTED_, numHelperThreads -> 3 ]
29-Nov-2021 13:56:36.176 INFO [http-nio-8080-exec-1] com.mchange.v2.log.MLog.<clinit> MLog clients using java 1.4+ standard logging.
29-Nov-2021 13:56:36.239 INFO [http-nio-8080-exec-1] com.mchange.v2.c3p0.C3P0Registry.banner Initializing c3p0-0.9.2.1 [built 20-March-2013 10:47:27 +0000; debug? true; trace: 10]
29-Nov-2021 13:56:36.240 WARNING [http-nio-8080-exec-1] com.mchange.v2.c3p0.management.ActiveManagementCoordinator.attemptManageC3P0Registry A C3P0Registry mbean is already registered. This probably means that an application using c3p0 was undeployed, but not all PooledDataSources were closed prior to undeployment. This may lead to resource leaks over time. Please take care to close all PooledDataSources.
29-Nov-2021 13:56:36.298 INFO [http-nio-8080-exec-1] com.mchange.v2.c3p0.impl.AbstractPoolBackedDataSource.getPoolManager Initializing c3p0 pool... com.mchange.v2.c3p0.PoolBackedDataSource@5153fa5f [ connectionPoolDataSource -> com.mchange.v2.c3p0.WrapperConnectionPoolDataSource@189b28b7 [ acquireIncrement -> 3, acquireRetryAttempts -> 30, acquireRetryDelay -> 1000, autoCommitOnClose -> false, automaticTestTable -> null, breakAfterAcquireFailure -> false, checkoutTimeout -> 0, connectionCustomizerClassName -> null, connectionTesterClassName -> com.mchange.v2.c3p0.impl.DefaultConnectionTester, debugUnreturnedConnectionStackTraces -> false, factoryClassLocation -> null, forceIgnoreUnresolvedTransactions -> false, identityToken -> _REDACTED_, idleConnectionTestPeriod -> 0, initialPoolSize -> 2, maxAdministrativeTaskTime -> 0, maxConnectionAge -> 0, maxIdleTime -> 300, maxIdleTimeExcessConnections -> 0, maxPoolSize -> 20, maxStatements -> 50, maxStatementsPerConnection -> 0, minPoolSize -> 2, nestedDataSource -> com.mchange.v2.c3p0.DriverManagerDataSource@6abf595 [ description -> null, driverClass -> null, factoryClassLocation -> null, identityToken -> _REDACTED_, jdbcUrl -> jdbc:mysql://localhost/transitime, properties -> {user=******, password=******} ], preferredTestQuery -> null, propertyCycle -> 0, statementCacheNumDeferredCloseThreads -> 0, testConnectionOnCheckin -> false, testConnectionOnCheckout -> false, unreturnedConnectionTimeout -> 0, usesTraditionalReflectiveProxies -> false; userOverrides: {} ], dataSourceName -> null, factoryClassLocation -> null, identityToken -> _REDACTED_, numHelperThreads -> 3 ]

So... everything seems to be up and running and properly configured. There are no stack traces or errors recorded anywhere, not even when the server spits out a 400 code - I can only find in the normal access log. Some other things I tried:

  • disabling UFW and clearing all iptables rules
  • different Tomcat and MySQL/MariaDB versions
  • clean install on a different server
  • looked into issue 503 error on web #131 which seemed similar, but I cannot seem to find a link between the two. I have no stack traces or wrongly enabled/configured modules.
  • Query-ing the RMI with the given JAR:
root@server:/# java -jar RmiQuery.jar -a 1 -c "resetVehicle"
java.lang.Exception: Cannot connect to Command server.
        at org.transitclock.applications.RmiQuery.resetVehicles(RmiQuery.java:482)
        at org.transitclock.applications.RmiQuery.main(RmiQuery.java:463)
  • Different API calls:
    GET http://127.0.0.1:8080/api/v1/key/KEY/agency/AGENCY/command/routes - INVALID API KEY, VALID AGENCY (invalid agency yields same result)
    Application key "a" is not valid.
    Response seems to come from the app, not from Tomcat itself.
    GET http://127.0.0.1:8080/api/v1/key/KEY/agency/AGENCY/command/routes - VALID API KEY, INVALID AGENCY
    HTTP 400 Bad Request
    Response seems to come from the app, again, since it's plain text, not from Tomcat itself.
    GET http://127.0.0.1:8080/api/v1/key/KEY/agency/AGENCY/command/routes - VALID API KEY, VALID AGENCY (should have an actual response...)
    <!DOCTYPE html><html><head><title>Apache Tomcat/8.0.43 - Error report</title><style type="text/css">H1 {font-family:Tahoma,Arial,sans-serif;color:white;background-color:#525D76;font-size:22px;} H2 {font-family:Tahoma,Arial,sans-serif;color:white;background-color:#525D76;font-size:16px;} H3 {font-family:Tahoma,Arial,sans-serif;color:white;background-color:#525D76;font-size:14px;} BODY {font-family:Tahoma,Arial,sans-serif;color:black;background-color:white;} B {font-family:Tahoma,Arial,sans-serif;color:white;background-color:#525D76;} P {font-family:Tahoma,Arial,sans-serif;background:white;color:black;font-size:12px;}A {color : black;}A.name {color : black;}.line {height: 1px; background-color: #525D76; border: none;}</style> </head><body><h1>HTTP Status 400 - Bad Request</h1><div class="line"></div><p><b>type</b> Status report</p><p><b>message</b> <u>Bad Request</u></p><p><b>description</b> <u>The request sent by the client was syntactically incorrect.</u></p><hr class="line"><h3>Apache Tomcat/8.0.43</h3></body></html>
    So this is a 400 error from Tomcat itself, hence the formatting. There is no detailed message or stack trace anywhere.
    GET http://127.0.0.1:8080/api/v1/key/KEY/agency/AGENCY/command/routesDetails?format=json - VALID API KEY, VALID AGENCY
    Index: 0, Size: 0
    Again a response from the app...
    GET http://127.0.0.1:8080/api/v1/key/KEY/agency/AGENCY/command/gtfs-rt/tripUpdates?format=binary (or format=human)
    <!DOCTYPE html><html><head><title>Apache Tomcat/8.0.43 - Error report</title><style type="text/css">H1 {font-family:Tahoma,Arial,sans-serif;color:white;background-color:#525D76;font-size:22px;} H2 {font-family:Tahoma,Arial,sans-serif;color:white;background-color:#525D76;font-size:16px;} H3 {font-family:Tahoma,Arial,sans-serif;color:white;background-color:#525D76;font-size:14px;} BODY {font-family:Tahoma,Arial,sans-serif;color:black;background-color:white;} B {font-family:Tahoma,Arial,sans-serif;color:white;background-color:#525D76;} P {font-family:Tahoma,Arial,sans-serif;background:white;color:black;font-size:12px;}A {color : black;}A.name {color : black;}.line {height: 1px; background-color: #525D76; border: none;}</style> </head><body><h1>HTTP Status 500 - Internal Server Error</h1><div class="line"></div><p><b>type</b> Status report</p><p><b>message</b> <u>Internal Server Error</u></p><p><b>description</b> <u>The server encountered an internal error that prevented it from fulfilling this request.</u></p><hr class="line"><h3>Apache Tomcat/8.0.43</h3></body></html>
    Again... this comes from Tomcat and there are no details in the logs.
    GET http://127.0.0.1:8080/api/v1/key/KEY/agency/AGENCY/command/serverStatus - the only one that actually seems to work, as you can also see in the screenshot above.
{
  "agencyId": "1",
  "serverMonitor": [
    {
      "type": "AVL feed",
      "value": "Last valid AVL report was 8 secs old while allowable age is 300 secs as specified by parameter transitclock.monitoring.allowableNoAvlSecs ."
    },
    {
      "type": "Predictability",
      "value": "No currently active blocks so predictability considered to be OK."
    },
    {
      "type": "Database Queue",
      "value": "Database queue fraction=0.00 while max allowed fraction=0.40, and items in queue=0."
    },
    {
      "type": "Active Blocks"
    }
  ]
}

Does anyone have ideas regarding to what might be causing this? My next course of action, over the following days is to extract the JARs, WARs and Java/Tomcat binaries from my other server and replace them onto this installation, to check if that solves it.

Thank you!

@BodoMinea
Copy link
Author

New findings:

RMI Queries to the cores are actually working, I didn't have a hibernate config in the working directory (for the cores and Tomcat it's configured in env vars/cmd line params).
Predictions for agencyId=1 [0.00000, 0.00000] are:

From the comparison of log files between the server that works and the one that doesn't I could only find the following difference.

catalina.out - server that works

01-Dec-2021 00:27:34.305 INFO [main] org.apache.coyote.AbstractProtocol.start Starting ProtocolHandler [ajp-nio-8009]
01-Dec-2021 00:27:34.309 INFO [main] org.apache.catalina.startup.Catalina.start Server startup in 29565 ms
01-Dec-2021 00:27:35.799 INFO [http-nio-8080-exec-7] com.mchange.v2.log.MLog.<clinit> MLog clients using java 1.4+ standard logging.
01-Dec-2021 00:27:35.986 INFO [http-nio-8080-exec-7] com.mchange.v2.c3p0.C3P0Registry.banner Initializing c3p0-0.9.2.1 [built 20-March-2013 10:47:27 +0000; debug? true; trace: 10]
01-Dec-2021 00:27:36.190 INFO [http-nio-8080-exec-7] com.mchange.v2.c3p0.impl.AbstractPoolBackedDataSource.getPoolManager Initializing c3p0 pool... com.mchange.v2.c3p0.PoolBackedDataSource@1be7f961 [ connectionPoolDataSource -> com.mchange.v2.c3p0.WrapperConnectionPoolDataSource@b5c22298 [ acquireIncrement -> 3, acquireRetryAttempts -> 30, acquireRetryDelay -> 1000, autoCommitOnClose -> false, automaticTestTable -> null, breakAfterAcquireFailure -> false, checkoutTimeout -> 0, connectionCustomizerClassName -> null, connectionTesterClassName -> com.mchange.v2.c3p0.impl.DefaultConnectionTester, debugUnreturnedConnectionStackTraces -> false, factoryClassLocation -> null, forceIgnoreUnresolvedTransactions -> false, identityToken -> _, idleConnectionTestPeriod -> 0, initialPoolSize -> 2, maxAdministrativeTaskTime -> 0, maxConnectionAge -> 0, maxIdleTime -> 300, maxIdleTimeExcessConnections -> 0, maxPoolSize -> 20, maxStatements -> 50, maxStatementsPerConnection -> 0, minPoolSize -> 2, nestedDataSource -> com.mchange.v2.c3p0.DriverManagerDataSource@f488e53d [ description -> null, driverClass -> null, factoryClassLocation -> null, identityToken -> _, jdbcUrl -> jdbc:mysql://localhost/_, properties -> {user=******, password=******} ], preferredTestQuery -> null, propertyCycle -> 0, statementCacheNumDeferredCloseThreads -> 0, testConnectionOnCheckin -> false, testConnectionOnCheckout -> false, unreturnedConnectionTimeout -> 0, usesTraditionalReflectiveProxies -> false; userOverrides: {} ], dataSourceName -> null, factoryClassLocation -> null, identityToken ->_, numHelperThreads -> 3 ]
01-Dec-2021 00:27:45.512 INFO [http-nio-8080-exec-2] com.mchange.v2.log.MLog.<clinit> MLog clients using java 1.4+ standard logging.
01-Dec-2021 00:27:45.694 INFO [http-nio-8080-exec-2] com.mchange.v2.c3p0.C3P0Registry.banner Initializing c3p0-0.9.2.1 [built 20-March-2013 10:47:27 +0000; debug? true; trace: 10]
01-Dec-2021 00:27:45.698 WARNING [http-nio-8080-exec-2] com.mchange.v2.c3p0.management.ActiveManagementCoordinator.attemptManageC3P0Registry A C3P0Registry mbean is already registered. This probably means that an application using c3p0 was undeployed, but not all PooledDataSources were closed prior to undeployment. This may lead to resource leaks over time. Please take care to close all PooledDataSources.
01-Dec-2021 00:27:45.889 INFO [http-nio-8080-exec-2] com.mchange.v2.c3p0.impl.AbstractPoolBackedDataSource.getPoolManager Initializing c3p0 pool... com.mchange.v2.c3p0.PoolBackedDataSource@278b2d37 [ connectionPoolDataSource -> com.mchange.v2.c3p0.WrapperConnectionPoolDataSource@f50e6dc7 [ acquireIncrement -> 3, acquireRetryAttempts -> 30, acquireRetryDelay -> 1000, autoCommitOnClose -> false, automaticTestTable -> null, breakAfterAcquireFailure -> false, checkoutTimeout -> 0, connectionCustomizerClassName -> null, connectionTesterClassName -> com.mchange.v2.c3p0.impl.DefaultConnectionTester, debugUnreturnedConnectionStackTraces -> false, factoryClassLocation -> null, forceIgnoreUnresolvedTransactions -> false, identityToken -> _, idleConnectionTestPeriod -> 0, initialPoolSize -> 2, maxAdministrativeTaskTime -> 0, maxConnectionAge -> 0, maxIdleTime -> 300, maxIdleTimeExcessConnections -> 0, maxPoolSize -> 20, maxStatements -> 50, maxStatementsPerConnection -> 0, minPoolSize -> 2, nestedDataSource -> com.mchange.v2.c3p0.DriverManagerDataSource@611057e7 [ description -> null, driverClass -> null, factoryClassLocation -> null, identityToken -> _, jdbcUrl -> jdbc:mysql://localhost/_, properties -> {user=******, password=******} ], preferredTestQuery -> null, propertyCycle -> 0, statementCacheNumDeferredCloseThreads -> 0, testConnectionOnCheckin -> false, testConnectionOnCheckout -> false, unreturnedConnectionTimeout -> 0, usesTraditionalReflectiveProxies -> false; userOverrides: {} ], dataSourceName -> null, factoryClassLocation -> null, identityToken -> _, numHelperThreads -> 3 ]

catalina.out - server that doesn't work

01-Dec-2021 01:02:47.652 INFO [main] org.apache.coyote.AbstractProtocol.start Starting ProtocolHandler ["http-nio-8080"]
01-Dec-2021 01:02:47.660 INFO [main] org.apache.catalina.startup.Catalina.start Server startup in 8180 ms
01-Dec-2021 01:03:00.530 INFO [http-nio-8080-exec-1] com.mchange.v2.log.MLog.<clinit> MLog clients using java 1.4+ standard logging.
01-Dec-2021 01:03:00.600 INFO [http-nio-8080-exec-1] com.mchange.v2.c3p0.C3P0Registry.banner Initializing c3p0-0.9.2.1 [built 20-March-2013 10:47:27 +0000; debug? true; trace: 10]
01-Dec-2021 01:03:00.674 INFO [http-nio-8080-exec-1] com.mchange.v2.c3p0.impl.AbstractPoolBackedDataSource.getPoolManager Initializing c3p0 pool... com.mchange.v2.c3p0.PoolBackedDataSource@874b7e73 [ connectionPoolDataSource -> com.mchange.v2.c3p0.WrapperConnectionPoolDataSource@61d6147c [ acquireIncrement -> 3, acquireRetryAttempts -> 30, acquireRetryDelay -> 1000, autoCommitOnClose -> false, automaticTestTable -> null, breakAfterAcquireFailure -> false, checkoutTimeout -> 0, connectionCustomizerClassName -> null, connectionTesterClassName -> com.mchange.v2.c3p0.impl.DefaultConnectionTester, debugUnreturnedConnectionStackTraces -> false, factoryClassLocation -> null, forceIgnoreUnresolvedTransactions -> false, identityToken -> _, idleConnectionTestPeriod -> 0, initialPoolSize -> 2, maxAdministrativeTaskTime -> 0, maxConnectionAge -> 0, maxIdleTime -> 300, maxIdleTimeExcessConnections -> 0, maxPoolSize -> 20, maxStatements -> 50, maxStatementsPerConnection -> 0, minPoolSize -> 2, nestedDataSource -> com.mchange.v2.c3p0.DriverManagerDataSource@b33caba6 [ description -> null, driverClass -> null, factoryClassLocation -> null, identityToken -> _, jdbcUrl -> jdbc:mysql://localhost/transitime, properties -> {user=******, password=******} ], preferredTestQuery -> null, propertyCycle -> 0, statementCacheNumDeferredCloseThreads -> 0, testConnectionOnCheckin -> false, testConnectionOnCheckout -> false, unreturnedConnectionTimeout -> 0, usesTraditionalReflectiveProxies -> false; userOverrides: {} ], dataSourceName -> null, factoryClassLocation -> null, identityToken -> _, numHelperThreads -> 3 ]

So it looks like one of the lines regarding database connection isn't appearing in the tomcat catalina.out log for the server that doesn't work... All the other apps output both lines after running them. (the servers are using the same Tomcat and Java version with the same WAR archives).

@BodoMinea
Copy link
Author

BodoMinea commented Nov 30, 2021

I seemingly finally found a stacktrace which seems to have also been encountered by another user on the other repo Transitime#29 ...

HCANN000001: Hibernate Commons Annotations {4.0.5.Final}
HHH000412: Hibernate Core {4.3.9.Final}
HHH000206: hibernate.properties not found
HHH000021: Bytecode provider name : javassist
Configuring Hibernate for dbName=transitime using config file=/usr/local/transitclock/config/hibernate.cfg.xml
HHH000042: Configuring from file: hibernate.cfg.xml
HHH000221: Reading mappings from resource: named_queries.hbm.xml
Getting GTFS-realtime AVL data from URL=_ ...
Parsing GTFS-realtime file into a FeedMessage took 10 msec
Processing each individual AvlReport...
Successfully processed 585 AVL reports from GTFS-realtime feed in 0 msec
HHH000041: Configured SessionFactory: null
For Hibernate factory project dbName=transitime using url=jdbc:mysql://localhost/transitime username=_, and configured password
HHH010002: C3P0 using driver: com.mysql.jdbc.Driver at URL: jdbc:mysql://localhost/transitime
HHH000046: Connection properties: {user=_, password=****}
HHH000006: Autocommit mode: false
HHH000400: Using dialect: org.hibernate.dialect.MySQLDialect
HHH000424: Disabling contextual LOB creation as createClob() method threw error : java.lang.reflect.InvocationTargetException
HHH000399: Using default transaction strategy (direct JDBC transactions)
HHH000397: Using ASTQueryTranslatorFactory
Couldn't set RMI timeout to 4 seconds.
java.net.SocketException: factory already defined
        at java.rmi.server.RMISocketFactory.setSocketFactory(RMISocketFactory.java:151) ~[na:1.8.0_292]
        at org.transitclock.ipc.rmi.ClientFactory.enableRmiTimeout(ClientFactory.java:191) [transitclockCore-2.0.0-SNAPSHOT.jar:na]
        at org.transitclock.ipc.rmi.ClientFactory.getInstance(ClientFactory.java:87) [transitclockCore-2.0.0-SNAPSHOT.jar:na]
        at org.transitclock.ipc.clients.ConfigInterfaceFactory.get(ConfigInterfaceFactory.java:52) [transitclockCore-2.0.0-SNAPSHOT.jar:na]
        at org.transitclock.api.utils.StandardParameters.getConfigInterface(StandardParameters.java:245) [classes/:na]
        at org.transitclock.api.rootResources.TransitimeApi.getRoutes(TransitimeApi.java:681) [classes/:na]
        at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method) ~[na:1.8.0_292]
        at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62) ~[na:1.8.0_292]
        at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) ~[na:1.8.0_292]
        at java.lang.reflect.Method.invoke(Method.java:498) ~[na:1.8.0_292]

And this causes a later

Reading WebAgencies data from database "transitime"...
Done reading WebAgencies from database. Took 6 msec. They are [WebAgency [agencyId=_, hostName=127.0.0.1, active=true, dbName=transitime, dbType=mysql, dbHost=0.0.0.0, dbUserName=_, dbEncryptedPassword=_], WebAgency [agencyId=1, hostName=127.0.0.1, active=true, dbName=transitime, dbType=mysql, dbHost=0.0.0.0, dbUserName=_, dbEncryptedPassword=_], WebAgency [agencyId=_, hostName=127.0.0.1, active=true, dbName=transitime, dbType=mysql, dbHost=0.0.0.0, dbUserName=_, dbEncryptedPassword=_], WebAgency [agencyId=_, hostName=127.0.0.1, active=true, dbName=transitime, dbType=mysql, dbHost=0.0.0.0, dbUserName=_, dbEncryptedPassword=_]]
Bad Request
java.lang.ArrayIndexOutOfBoundsException: -1
        at java.util.ArrayList.elementData(ArrayList.java:424) ~[na:1.8.0_292]
        at java.util.ArrayList.get(ArrayList.java:437) ~[na:1.8.0_292]
        at org.transitclock.api.rootResources.TransitimeApi.getRoutes(TransitimeApi.java:729) ~[classes/:na]
        at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method) ~[na:1.8.0_292]
        at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62) ~[na:1.8.0_292]
        at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) ~[na:1.8.0_292]

So for some reason it crashes here -

@BodoMinea
Copy link
Author

I also found that some API endpoints work, apparently the ones that do not directly use GTFS data...?

For example http://127.0.0.1:8080/api/v1/key/KEY/agency/AGENCY/command/vehicles works for all agencies.

@BodoMinea
Copy link
Author

I may have found something peculiar...

On the installation that doesn't work properly, I ran SELECT * FROM ActiveRevisions and got this:

mysql> SELECT * FROM ActiveRevisions;
+----+-----------+----------------+
| id | configRev | travelTimesRev |
+----+-----------+----------------+
|  1 |         -1 |              -1 |
+----+-----------+----------------+
1 row in set (0.00 sec)

If I look at the imported data, I can see the configRev being 0. Could this mean that the import script somehow silently failed although I Can see the data in the tables? (I looked at the server that is working and the activeRevision for that corresponds to the latest one, of course).

mysql> SELECT configRev,agencyId FROM transitime.Agencies;
+-----------+----------+
| configRev | agencyId |
+-----------+----------+
|         0 | 1        |
+-----------+----------+

I tried manually setting both of those values to 0 and the result is that the cores are not launching anymore, which seems very weird.

core.log

Reading configuration database for configRev=0...
creating new session factory with readOnly=false
Configuring Hibernate for dbName=transitime using config file=/usr/local/transitclock/config/hibernate.cfg.xml
HHH000042: Configuring from file: hibernate.cfg.xml
HHH000221: Reading mappings from resource: named_queries.hbm.xml
HHH000041: Configured SessionFactory: null
For Hibernate factory project dbName=transitime using url=jdbc:mysql://localhost/transitime username=_, and configured password
HHH010002: C3P0 using driver: com.mysql.jdbc.Driver at URL: jdbc:mysql://localhost/transitime
HHH000046: Connection properties: {user=_, password=****}
HHH000006: Autocommit mode: false
HHH000400: Using dialect: org.hibernate.dialect.MySQLDialect
HHH000424: Disabling contextual LOB creation as createClob() method threw error : java.lang.reflect.InvocationTargetException
HHH000399: Using default transaction strategy (direct JDBC transactions)
HHH000397: Using ASTQueryTranslatorFactory
caching blocks....
caching complete
null
java.lang.NullPointerException: null
        at org.transitclock.gtfs.DbConfig.getStopIdsForRoute(DbConfig.java:376) ~[Core.jar:na]
        at org.transitclock.gtfs.DbConfig.putRoutesIntoMapByStopId(DbConfig.java:397) ~[Core.jar:na]
        at org.transitclock.gtfs.DbConfig.actuallyReadData(DbConfig.java:716) ~[Core.jar:na]
        at org.transitclock.gtfs.DbConfig.read(DbConfig.java:195) ~[Core.jar:na]
        at org.transitclock.applications.Core.<init>(Core.java:170) ~[Core.jar:na]
        at org.transitclock.applications.Core.createCore(Core.java:223) ~[Core.jar:na]
        at org.transitclock.applications.Core.main(Core.java:557) ~[Core.jar:na]
INFO: Initializing c3p0-0.9.2.1 [built 20-March-2013 10:47:27 +0000; debug? true; trace: 10]
Dec 01, 2021 3:37:56 AM com.mchange.v2.c3p0.impl.AbstractPoolBackedDataSource getPoolManager
INFO: Initializing c3p0 pool... com.mchange.v2.c3p0.PoolBackedDataSource@15146fb [ connectionPoolDataSource -> com.mchange.v2.c3p0.WrapperConnectionPoolDataSource@af50e9be [ acquireIncrement -> 3, acquireRetryAttempts -> 30, acquireRetryDelay -> 1000, autoCommitOnClose -> false, automaticTestTable -> null, breakAfterAcquireFailure -> false, checkoutTimeout -> 0, connectionCustomizerClassName -> null, connectionTesterClassName -> com.mchange.v2.c3p0.impl.DefaultConnectionTester, debugUnreturnedConnectionStackTraces -> false, factoryClassLocation -> null, forceIgnoreUnresolvedTransactions -> false, identityToken -> _, idleConnectionTestPeriod -> 0, initialPoolSize -> 2, maxAdministrativeTaskTime -> 0, maxConnectionAge -> 0, maxIdleTime -> 300, maxIdleTimeExcessConnections -> 0, maxPoolSize -> 20, maxStatements -> 50, maxStatementsPerConnection -> 0, minPoolSize -> 2, nestedDataSource -> com.mchange.v2.c3p0.DriverManagerDataSource@a0965318 [ description -> null, driverClass -> null, factoryClassLocation -> null, identityToken -> _, jdbcUrl -> jdbc:mysql://localhost/transitime, properties -> {user=******, password=******} ], preferredTestQuery -> null, propertyCycle -> 0, statementCacheNumDeferredCloseThreads -> 0, testConnectionOnCheckin -> false, testConnectionOnCheckout -> false, unreturnedConnectionTimeout -> 0, usesTraditionalReflectiveProxies -> false; userOverrides: {} ], dataSourceName -> null, factoryClassLocation -> null, identityToken -> _, numHelperThreads -> 3 ]
Dec 01, 2021 3:37:57 AM com.mchange.v2.c3p0.impl.AbstractPoolBackedDataSource getPoolManager
INFO: Initializing c3p0 pool... com.mchange.v2.c3p0.PoolBackedDataSource@894d512b [ connectionPoolDataSource -> com.mchange.v2.c3p0.WrapperConnectionPoolDataSource@30a1b03a [ acquireIncrement -> 3, acquireRetryAttempts -> 30, acquireRetryDelay -> 1000, autoCommitOnClose -> false, automaticTestTable -> null, breakAfterAcquireFailure -> false, checkoutTimeout -> 0, connectionCustomizerClassName -> null, connectionTesterClassName -> com.mchange.v2.c3p0.impl.DefaultConnectionTester, debugUnreturnedConnectionStackTraces -> false, factoryClassLocation -> null, forceIgnoreUnresolvedTransactions -> false, identityToken -> _, idleConnectionTestPeriod -> 0, initialPoolSize -> 2, maxAdministrativeTaskTime -> 0, maxConnectionAge -> 0, maxIdleTime -> 300, maxIdleTimeExcessConnections -> 0, maxPoolSize -> 20, maxStatements -> 50, maxStatementsPerConnection -> 0, minPoolSize -> 2, nestedDataSource -> com.mchange.v2.c3p0.DriverManagerDataSource@52eb0a2a [ description -> null, driverClass -> null, factoryClassLocation -> null, identityToken -> z8kfsxalw33v9616x0a53|6b530eb9, jdbcUrl -> jdbc:mysql://localhost/transitime, properties -> {user=******, password=******} ], preferredTestQuery -> null, propertyCycle -> 0, statementCacheNumDeferredCloseThreads -> 0, testConnectionOnCheckin -> false, testConnectionOnCheckout -> false, unreturnedConnectionTimeout -> 0, usesTraditionalReflectiveProxies -> false; userOverrides: {} ], dataSourceName -> null, factoryClassLocation -> null, identityToken -> z8kfsxalw33v9616x0a53|64a1923a, numHelperThreads -> 3 ]
java.lang.NullPointerException
        at org.transitclock.gtfs.DbConfig.getStopIdsForRoute(DbConfig.java:376)
        at org.transitclock.gtfs.DbConfig.putRoutesIntoMapByStopId(DbConfig.java:397)
        at org.transitclock.gtfs.DbConfig.actuallyReadData(DbConfig.java:716)
        at org.transitclock.gtfs.DbConfig.read(DbConfig.java:195)
        at org.transitclock.applications.Core.<init>(Core.java:170)
        at org.transitclock.applications.Core.createCore(Core.java:223)
        at org.transitclock.applications.Core.main(Core.java:557)
Dec 01, 2021 3:38:03 AM com.mchange.v2.c3p0.impl.AbstractPoolBackedDataSource getPoolManager
INFO: Initializing c3p0 pool... com.mchange.v2.c3p0.PoolBackedDataSource@23b7a0fa [ connectionPoolDataSource -> com.mchange.v2.c3p0.WrapperConnectionPoolDataSource@bbfff5f [ acquireIncrement -> 3, acquireRetryAttempts -> 30, acquireRetryDelay -> 1000, autoCommitOnClose -> false, automaticTestTable -> null, breakAfterAcquireFailure -> false, checkoutTimeout -> 0, connectionCustomizerClassName -> null, connectionTesterClassName -> com.mchange.v2.c3p0.impl.DefaultConnectionTester, debugUnreturnedConnectionStackTraces -> false, factoryClassLocation -> null, forceIgnoreUnresolvedTransactions -> false, identityToken -> _, idleConnectionTestPeriod -> 0, initialPoolSize -> 2, maxAdministrativeTaskTime -> 0, maxConnectionAge -> 0, maxIdleTime -> 300, maxIdleTimeExcessConnections -> 0, maxPoolSize -> 20, maxStatements -> 50, maxStatementsPerConnection -> 0, minPoolSize -> 2, nestedDataSource -> com.mchange.v2.c3p0.DriverManagerDataSource@ac6e4a72 [ description -> null, driverClass -> null, factoryClassLocation -> null, identityToken ->_, jdbcUrl -> jdbc:mysql://localhost/transitime, properties -> {user=******, password=******} ], preferredTestQuery -> null, propertyCycle -> 0, statementCacheNumDeferredCloseThreads -> 0, testConnectionOnCheckin -> false, testConnectionOnCheckout -> false, unreturnedConnectionTimeout -> 0, usesTraditionalReflectiveProxies -> false; userOverrides: {} ], dataSourceName -> null, factoryClassLocation -> null, identityToken -> _, numHelperThreads -> 3 ]
Calling shutdown hook.

I am starting to think that maybe the data imports introduce some invalid data that makes the program crash... I'll try setting the import logs to a different location in order to have a separate log just with that... and maybe allocate more memory for the import since this is a big dataset.

@BodoMinea
Copy link
Author

Weird, looks like the GtfsFileProcessor.jar finishes successfully, but on an emptied database I still get the activeRevision set to -1 after the first import.

flushed with 64100 % 100
flushing with 64200 % 100
flushed with 64200 % 100
flushing with 64300 % 100
flushed with 64300 % 100
flushing with 64400 % 100
flushed with 64400 % 100
flushing with 64500 % 100
flushed with 64500 % 100
Saving agencies to database...
Saving calendars to database...
Saving calendar dates to database...
Saving fare rules to database...
Saving fare attributes to database...
Saving frequencies to database...
flushing with 64600 % 100
flushed with 64600 % 100
Saving transfers to database...
Finished writing GTFS data to database . Took 854031 msec.
Finished processing GTFS data from _ . Took 867883 msec.
creating new session factory with readOnly=false
Configuring Hibernate for dbName=transitime using config file=/usr/local/transitclock/config/hibernate.cfg.xml
HHH000042: Configuring from file: hibernate.cfg.xml
HHH000221: Reading mappings from resource: named_queries.hbm.xml
HHH000041: Configured SessionFactory: null
For Hibernate factory project dbName=transitime using url=jdbc:mysql://localhost/transitime username=_, and configured password
HHH010002: C3P0 using driver: com.mysql.jdbc.Driver at URL: jdbc:mysql://localhost/transitime
HHH000046: Connection properties: {user=_, password=****}
HHH000006: Autocommit mode: false
HHH000400: Using dialect: org.hibernate.dialect.MySQLDialect
HHH000424: Disabling contextual LOB creation as createClob() method threw error : java.lang.reflect.InvocationTargetException
HHH000399: Using default transaction strategy (direct JDBC transactions)
HHH000397: Using ASTQueryTranslatorFactory
Found 58454 TravelTimesForTrips for 0:0 with expected=1, orginal=0
All regexs that were configured made a difference. None need to be removed.

The NullPointer error that prevents the cores from starting persists. I tried selecting for NULL agencyIds and stopIds with no luck, all result sets are empty.

@BodoMinea BodoMinea changed the title Cores and RMI running, Web and API (error 400) not working Cores and RMI running, Web and API (error 400) not working - activeRevisions confusion or incomplete import? Dec 1, 2021
@BodoMinea BodoMinea changed the title Cores and RMI running, Web and API (error 400) not working - activeRevisions confusion or incomplete import? java.lang.NullPointerException: null at org.transitclock.gtfs.DbConfig.getStopIdsForRoute - core startup failure Dec 1, 2021
@BodoMinea
Copy link
Author

Looks like the final issue boils down to java.lang.NullPointerException: null at org.transitclock.gtfs.DbConfig.getStopIdsForRoute. Although my GTFS file is valid according to the transitfeed validator and the import reports no errors, warnings or stacktraces, for whatever reason a NULL pointer is breaking this line -

for (TripPattern tripPattern : tripPatternsForRoute) {

@BodoMinea
Copy link
Author

For now I solved my issue by adding in the following „bodge”:

private Collection<String> getStopIdsForRoute(String routeId) {
                Collection<String> stopIds = new ArrayList<String>(100);

                List<TripPattern> tripPatternsForRoute = tripPatternsByRouteMap.get(routeId);
                try { 
                   for (TripPattern tripPattern : tripPatternsForRoute) {
                        for (String stopId : tripPattern.getStopIds()) {
                                stopIds.add(stopId);
                        }
                     }
                  } catch (Exception e) {
                      System.out.println("Something went wrong.");
                  }
                return stopIds;
        }

„Something went wrong” appeared once during core startup but otherwise the app works fine. I tried enablign SQL logging and manually executing queries to find if something NULL is coming from the database but there were far too many queries. The obvious ones yielded zero null results.

Since something may have been wrong with my data or setup, I do not consider this a fix and will not push it to my branch or create a PR for it.

Thanks!

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
None yet
Projects
None yet
Development

No branches or pull requests

1 participant