TheTransitClock / transitime

TheTransitClock real-time transit information system
GNU General Public License v3.0
79 stars 30 forks source link

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

Closed BodoMinea closed 2 years ago

BodoMinea commented 2 years ago

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:

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 commented 2 years ago

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 commented 2 years ago

I seemingly finally found a stacktrace which seems to have also been encountered by another user on the other repo https://github.com/Transitime/core/issues/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 - https://github.com/TheTransitClock/transitime/blob/05ca94eeb7121d84f1c7958e8ed6c25bce4caea7/transitclockApi/src/main/java/org/transitclock/api/rootResources/TransitimeApi.java#L729

BodoMinea commented 2 years ago

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 commented 2 years ago

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 commented 2 years ago

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 commented 2 years ago

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 - https://github.com/TheTransitClock/transitime/blob/05ca94eeb7121d84f1c7958e8ed6c25bce4caea7/transitclock/src/main/java/org/transitclock/gtfs/DbConfig.java#L376

BodoMinea commented 2 years ago

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!