Database NPE preventing server starting/restarting?

Roger Howell7 years ago

Hi,

I am getting the following errors within wrapper.log and I'm not sure why. This is causing the traccar service to never (re-)start correctly (Ubuntu 16.04 / Traccar 3.16).

It began shortly after attempting to export data via the web UI (it seemed to hang?) and re-appears if doing a fresh install followed by copying the data folder over, suggesting that perhaps the database got corrupted perhaps? This is somewhat corroborated by the stack trace, though I am not familiar enough with H2 files/databases to meaningfully debug/analyse them.

While I am mostly happy to just wipe and start over as there's nothing critical stored there this time (instead it's more of an annoyance/nuisance), it makes me nervous that this might happen again when more important data is in there so would like to try and understand what has happened/how to resolve it.

Assistance with this would be appreciated.

Many thanks

WARNING|wrapper|Service traccar|18-04-18 00:40:00|YAJSW: yajsw-stable-12.12
WARNING|wrapper|Service traccar|18-04-18 00:40:00|OS   : Linux/4.4.0-119-generic/amd64
WARNING|wrapper|Service traccar|18-04-18 00:40:00|JVM  : Oracle Corporation/1.8.0_162//usr/lib/jvm/java-8-openjdk-amd64/jre/64
INFO|wrapper|Service traccar|18-04-18 00:40:00|exec:java -classpath /opt/traccar/wrapperApp.jar:/opt/traccar/tracker-server.jar:/opt/traccar/lib/log4j-1.2.17.jar:/opt/traccar/lib/joda-time-2.9.9.jar:/opt/traccar/lib/commons-codec-1.11.jar:/opt/traccar/lib/h2-1.4.196.jar:/opt/traccar/lib/mysql-connector-java-5.1.45.jar:/opt/traccar/lib/postgresql-42.2.1.jre7.jar:/opt/traccar/lib/mssql-jdbc-6.4.0.jre7.jar:/opt/traccar/lib/HikariCP-java7-2.4.13.jar:/opt/traccar/lib/slf4j-api-1.7.21.jar:/opt/traccar/lib/netty-3.10.6.Final.jar:/opt/traccar/lib/async-http-client-1.9.40.jar:/opt/traccar/lib/slf4j-simple-1.7.25.jar:/opt/traccar/lib/javax.json-1.0.4.jar:/opt/traccar/lib/jetty-server-9.2.24.v20180105.jar:/opt/traccar/lib/javax.servlet-api-3.1.0.jar:/opt/traccar/lib/jetty-http-9.2.24.v20180105.jar:/opt/traccar/lib/jetty-io-9.2.24.v20180105.jar:/opt/traccar/lib/jetty-servlet-9.2.24.v20180105.jar:/opt/traccar/lib/jetty-security-9.2.24.v20180105.jar:/opt/traccar/lib/jetty-webapp-9.2.24.v20180105.jar:/opt/traccar/lib/jetty-xml-9.2.24.v20180105.jar:/opt/traccar/lib/jetty-jndi-9.2.24.v20180105.jar:/opt/traccar/lib/jetty-util-9.2.24.v20180105.jar:/opt/traccar/lib/jetty-proxy-9.2.24.v20180105.jar:/opt/traccar/lib/jetty-client-9.2.24.v20180105.jar:/opt/traccar/lib/websocket-server-9.2.24.v20180105.jar:/opt/traccar/lib/websocket-common-9.2.24.v20180105.jar:/opt/traccar/lib/websocket-api-9.2.24.v20180105.jar:/opt/traccar/lib/websocket-client-9.2.24.v20180105.jar:/opt/traccar/lib/websocket-servlet-9.2.24.v20180105.jar:/opt/traccar/lib/jersey-container-servlet-2.25.1.jar:/opt/traccar/lib/jersey-container-servlet-core-2.25.1.jar:/opt/traccar/lib/javax.inject-2.5.0-b32.jar:/opt/traccar/lib/jersey-common-2.25.1.jar:/opt/traccar/lib/javax.annotation-api-1.2.jar:/opt/traccar/lib/jersey-guava-2.25.1.jar:/opt/traccar/lib/hk2-api-2.5.0-b32.jar:/opt/traccar/lib/hk2-utils-2.5.0-b32.jar:/opt/traccar/lib/aopalliance-repackaged-2.5.0-b32.jar:/opt/traccar/lib/hk2-locator-2.5.0-b32.jar:/opt/traccar/lib/javassist-3.20.0-GA.jar:/opt/traccar/lib/osgi-resource-locator-1.0.1.jar:/opt/traccar/lib/jersey-server-2.25.1.jar:/opt/traccar/lib/jersey-client-2.25.1.jar:/opt/traccar/lib/jersey-media-jaxb-2.25.1.jar:/opt/traccar/lib/validation-api-1.1.0.Final.jar:/opt/traccar/lib/javax.ws.rs-api-2.0.1.jar:/opt/traccar/lib/jersey-media-json-jackson-2.25.1.jar:/opt/traccar/lib/jersey-entity-filtering-2.25.1.jar:/opt/traccar/lib/jackson-jaxrs-base-2.8.4.jar:/opt/traccar/lib/jackson-core-2.8.4.jar:/opt/traccar/lib/jackson-databind-2.8.4.jar:/opt/traccar/lib/jackson-jaxrs-json-provider-2.8.4.jar:/opt/traccar/lib/jackson-module-jaxb-annotations-2.8.4.jar:/opt/traccar/lib/jackson-annotations-2.8.4.jar:/opt/traccar/lib/liquibase-core-3.5.5.jar:/opt/traccar/lib/snakeyaml-1.17.jar:/opt/traccar/lib/mail-1.4.7.jar:/opt/traccar/lib/activation-1.1.jar:/opt/traccar/lib/jxls-2.4.4.jar:/opt/traccar/lib/commons-jexl-2.1.1.jar:/opt/traccar/lib/commons-beanutils-1.9.2.jar:/opt/traccar/lib/jcl-over-slf4j-1.7.12.jar:/opt/traccar/lib/logback-core-1.1.3.jar:/opt/traccar/lib/jxls-poi-1.0.14.jar:/opt/traccar/lib/poi-3.17.jar:/opt/traccar/lib/poi-ooxml-3.17.jar:/opt/traccar/lib/poi-ooxml-schemas-3.17.jar:/opt/traccar/lib/xmlbeans-2.6.0.jar:/opt/traccar/lib/stax-api-1.0.1.jar:/opt/traccar/lib/curvesapi-1.04.jar:/opt/traccar/lib/velocity-1.7.jar:/opt/traccar/lib/commons-collections-3.2.1.jar:/opt/traccar/lib/commons-lang-2.4.jar:/opt/traccar/lib/velocity-tools-2.0.jar:/opt/traccar/lib/commons-digester-1.8.jar:/opt/traccar/lib/commons-chain-1.1.jar:/opt/traccar/lib/commons-logging-1.1.jar:/opt/traccar/lib/servlet-api-2.3.jar:/opt/traccar/lib/commons-validator-1.3.1.jar:/opt/traccar/lib/dom4j-1.1.jar:/opt/traccar/lib/oro-2.0.8.jar:/opt/traccar/lib/sslext-1.2-0.jar:/opt/traccar/lib/struts-core-1.3.8.jar:/opt/traccar/lib/antlr-2.7.2.jar:/opt/traccar/lib/struts-taglib-1.3.8.jar:/opt/traccar/lib/struts-tiles-1.3.8.jar:/opt/traccar/lib/commons-collections4-4.1.jar:/opt/traccar/lib/ical4j-2.0.5.jar:/opt/traccar/lib/commons-lang3-3.6.jar:/opt/traccar/lib/threetenbp-1.3.6.jar:/opt/traccar/lib/ch-smpp-5.0.9.jar:/opt/traccar/lib/ch-commons-util-6.0.2.jar:/opt/traccar/lib/ch-commons-charset-3.0.2.jar -Dfile.encoding=UTF-8 -Xrs -Dwrapper.service=true -Dwrapper.console.visible=false -Dwrapper.port=15003 -Dwrapper.key=-3795545736788486045 -Dwrapper.teeName=-3795545736788486045$1524012000416 -Dwrapper.tmp.path=/opt/traccar/tmp -Djna_tmpdir=/opt/traccar/tmp -Dwrapper.config=/opt/traccar/conf/wrapper.conf -Dwrapper.visible=false -Dwrapper.pidfile=/run/wrapper.traccar.pid org.rzo.yajsw.app.WrapperJVMMain
INFO|wrapper|Service traccar|18-04-18 00:40:00|posix_spawn pid 3372
INFO|wrapper|Service traccar|18-04-18 00:40:00|started process 3372
INFO|wrapper|Service traccar|18-04-18 00:40:00|started process with pid 3372
INFO|3372/0|Service traccar|18-04-18 00:40:03|[INFO] StandardFileSystemManager - Using "/tmp/vfs_cache" as temporary files store.
INFO|3372/0|Service traccar|18-04-18 00:40:05|[main] INFO com.zaxxer.hikari.HikariDataSource - HikariPool-1 - Starting...
INFO|3372/0|Service traccar|18-04-18 00:40:07|[main] ERROR com.zaxxer.hikari.pool.HikariPool - HikariPool-1 - Exception during pool initialization.
INFO|3372/0|Service traccar|18-04-18 00:40:07|org.h2.jdbc.JdbcSQLException: General error: "java.lang.NullPointerException" [50000-196]
INFO|3372/0|Service traccar|18-04-18 00:40:07|  at org.h2.message.DbException.getJdbcSQLException(DbException.java:345)
INFO|3372/0|Service traccar|18-04-18 00:40:07|  at org.h2.message.DbException.get(DbException.java:168)
INFO|3372/0|Service traccar|18-04-18 00:40:07|  at org.h2.message.DbException.convert(DbException.java:295)
INFO|3372/0|Service traccar|18-04-18 00:40:07|  at org.h2.engine.Database.openDatabase(Database.java:307)
INFO|3372/0|Service traccar|18-04-18 00:40:07|  at org.h2.engine.Database.<init>(Database.java:270)
INFO|3372/0|Service traccar|18-04-18 00:40:07|  at org.h2.engine.Engine.openSession(Engine.java:64)
INFO|3372/0|Service traccar|18-04-18 00:40:07|  at org.h2.engine.Engine.openSession(Engine.java:176)
INFO|3372/0|Service traccar|18-04-18 00:40:07|  at org.h2.engine.Engine.createSessionAndValidate(Engine.java:154)
INFO|3372/0|Service traccar|18-04-18 00:40:07|  at org.h2.engine.Engine.createSession(Engine.java:137)
INFO|3372/0|Service traccar|18-04-18 00:40:07|  at org.h2.engine.Engine.createSession(Engine.java:27)
INFO|3372/0|Service traccar|18-04-18 00:40:07|  at org.h2.engine.SessionRemote.connectEmbeddedOrServer(SessionRemote.java:354)
INFO|3372/0|Service traccar|18-04-18 00:40:07|  at org.h2.jdbc.JdbcConnection.<init>(JdbcConnection.java:116)
INFO|3372/0|Service traccar|18-04-18 00:40:07|  at org.h2.jdbc.JdbcConnection.<init>(JdbcConnection.java:100)
INFO|3372/0|Service traccar|18-04-18 00:40:07|  at org.h2.Driver.connect(Driver.java:69)
INFO|3372/0|Service traccar|18-04-18 00:40:07|  at com.zaxxer.hikari.util.DriverDataSource.getConnection(DriverDataSource.java:112)
INFO|3372/0|Service traccar|18-04-18 00:40:07|  at com.zaxxer.hikari.util.DriverDataSource.getConnection(DriverDataSource.java:118)
INFO|3372/0|Service traccar|18-04-18 00:40:07|  at com.zaxxer.hikari.pool.PoolBase.newConnection(PoolBase.java:341)
INFO|3372/0|Service traccar|18-04-18 00:40:07|  at com.zaxxer.hikari.pool.PoolBase.newPoolEntry(PoolBase.java:193)
INFO|3372/0|Service traccar|18-04-18 00:40:07|  at com.zaxxer.hikari.pool.HikariPool.createPoolEntry(HikariPool.java:428)
INFO|3372/0|Service traccar|18-04-18 00:40:07|  at com.zaxxer.hikari.pool.HikariPool.checkFailFast(HikariPool.java:499)
INFO|3372/0|Service traccar|18-04-18 00:40:07|  at com.zaxxer.hikari.pool.HikariPool.<init>(HikariPool.java:112)
INFO|3372/0|Service traccar|18-04-18 00:40:07|  at com.zaxxer.hikari.HikariDataSource.<init>(HikariDataSource.java:72)
INFO|3372/0|Service traccar|18-04-18 00:40:07|  at org.traccar.database.DataManager.initDatabase(DataManager.java:133)
INFO|3372/0|Service traccar|18-04-18 00:40:07|  at org.traccar.database.DataManager.<init>(DataManager.java:86)
INFO|3372/0|Service traccar|18-04-18 00:40:07|  at org.traccar.Context.init(Context.java:333)
INFO|3372/0|Service traccar|18-04-18 00:40:07|  at org.traccar.Main.main(Main.java:35)
INFO|3372/0|Service traccar|18-04-18 00:40:07|  at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
INFO|3372/0|Service traccar|18-04-18 00:40:07|  at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62)
INFO|3372/0|Service traccar|18-04-18 00:40:07|  at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
INFO|3372/0|Service traccar|18-04-18 00:40:07|  at java.lang.reflect.Method.invoke(Method.java:498)
INFO|3372/0|Service traccar|18-04-18 00:40:07|  at org.rzo.yajsw.app.WrapperJVMMain.executeMain(WrapperJVMMain.java:60)
INFO|3372/0|Service traccar|18-04-18 00:40:07|  at org.rzo.yajsw.app.WrapperJVMMain.main(WrapperJVMMain.java:43)
INFO|3372/0|Service traccar|18-04-18 00:40:07|Caused by: java.lang.NullPointerException
INFO|3372/0|Service traccar|18-04-18 00:40:07|  at org.h2.mvstore.db.ValueDataType.compare(ValueDataType.java:104)
INFO|3372/0|Service traccar|18-04-18 00:40:07|  at org.h2.mvstore.MVMap.compare(MVMap.java:713)
INFO|3372/0|Service traccar|18-04-18 00:40:07|  at org.h2.mvstore.Page.binarySearch(Page.java:334)
INFO|3372/0|Service traccar|18-04-18 00:40:07|  at org.h2.mvstore.MVMap.binarySearch(MVMap.java:466)
INFO|3372/0|Service traccar|18-04-18 00:40:07|  at org.h2.mvstore.MVMap.get(MVMap.java:455)
INFO|3372/0|Service traccar|18-04-18 00:40:07|  at org.h2.mvstore.MVMap.remove(MVMap.java:543)
INFO|3372/0|Service traccar|18-04-18 00:40:07|  at org.h2.mvstore.db.TransactionStore.rollbackTo(TransactionStore.java:506)
INFO|3372/0|Service traccar|18-04-18 00:40:07|  at org.h2.mvstore.db.TransactionStore$Transaction.rollback(TransactionStore.java:803)
INFO|3372/0|Service traccar|18-04-18 00:40:07|  at org.h2.mvstore.db.MVTableEngine$Store.initTransactions(MVTableEngine.java:256)
INFO|3372/0|Service traccar|18-04-18 00:40:07|  at org.h2.engine.Database.open(Database.java:767)
INFO|3372/0|Service traccar|18-04-18 00:40:07|  at org.h2.engine.Database.openDatabase(Database.java:276)
INFO|3372/0|Service traccar|18-04-18 00:40:07|  ... 28 more
INFO|3372/0|Service traccar|18-04-18 00:40:07|java.lang.reflect.InvocationTargetException
INFO|3372/0|Service traccar|18-04-18 00:40:07|  at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
INFO|3372/0|Service traccar|18-04-18 00:40:07|  at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62)
INFO|3372/0|Service traccar|18-04-18 00:40:07|  at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
INFO|3372/0|Service traccar|18-04-18 00:40:07|  at java.lang.reflect.Method.invoke(Method.java:498)
INFO|3372/0|Service traccar|18-04-18 00:40:07|  at org.rzo.yajsw.app.WrapperJVMMain.executeMain(WrapperJVMMain.java:60)
INFO|3372/0|Service traccar|18-04-18 00:40:07|  at org.rzo.yajsw.app.WrapperJVMMain.main(WrapperJVMMain.java:43)
INFO|3372/0|Service traccar|18-04-18 00:40:07|Caused by: com.zaxxer.hikari.pool.HikariPool$PoolInitializationException: Failed to initialize pool: General error: "java.lang.NullPointerException" [50000-196]
INFO|3372/0|Service traccar|18-04-18 00:40:07|  at com.zaxxer.hikari.pool.HikariPool.throwPoolInitializationException(HikariPool.java:528)
INFO|3372/0|Service traccar|18-04-18 00:40:07|  at com.zaxxer.hikari.pool.HikariPool.checkFailFast(HikariPool.java:520)
INFO|3372/0|Service traccar|18-04-18 00:40:07|  at com.zaxxer.hikari.pool.HikariPool.<init>(HikariPool.java:112)
INFO|3372/0|Service traccar|18-04-18 00:40:07|  at com.zaxxer.hikari.HikariDataSource.<init>(HikariDataSource.java:72)
INFO|3372/0|Service traccar|18-04-18 00:40:07|  at org.traccar.database.DataManager.initDatabase(DataManager.java:133)
INFO|3372/0|Service traccar|18-04-18 00:40:07|  at org.traccar.database.DataManager.<init>(DataManager.java:86)
INFO|3372/0|Service traccar|18-04-18 00:40:08|  at org.traccar.Context.init(Context.java:333)
INFO|3372/0|Service traccar|18-04-18 00:40:08|  at org.traccar.Main.main(Main.java:35)
INFO|3372/0|Service traccar|18-04-18 00:40:08|  ... 6 more
INFO|3372/0|Service traccar|18-04-18 00:40:08|Caused by: org.h2.jdbc.JdbcSQLException: General error: "java.lang.NullPointerException" [50000-196]
INFO|3372/0|Service traccar|18-04-18 00:40:08|  at org.h2.message.DbException.getJdbcSQLException(DbException.java:345)
INFO|3372/0|Service traccar|18-04-18 00:40:08|  at org.h2.message.DbException.get(DbException.java:168)
INFO|3372/0|Service traccar|18-04-18 00:40:08|  at org.h2.message.DbException.convert(DbException.java:295)
INFO|3372/0|Service traccar|18-04-18 00:40:08|  at org.h2.engine.Database.openDatabase(Database.java:307)
INFO|3372/0|Service traccar|18-04-18 00:40:08|  at org.h2.engine.Database.<init>(Database.java:270)
INFO|3372/0|Service traccar|18-04-18 00:40:08|  at org.h2.engine.Engine.openSession(Engine.java:64)
INFO|3372/0|Service traccar|18-04-18 00:40:08|  at org.h2.engine.Engine.openSession(Engine.java:176)
INFO|3372/0|Service traccar|18-04-18 00:40:08|  at org.h2.engine.Engine.createSessionAndValidate(Engine.java:154)
INFO|3372/0|Service traccar|18-04-18 00:40:08|  at org.h2.engine.Engine.createSession(Engine.java:137)
INFO|3372/0|Service traccar|18-04-18 00:40:08|  at org.h2.engine.Engine.createSession(Engine.java:27)
INFO|3372/0|Service traccar|18-04-18 00:40:08|  at org.h2.engine.SessionRemote.connectEmbeddedOrServer(SessionRemote.java:354)
INFO|3372/0|Service traccar|18-04-18 00:40:08|  at org.h2.jdbc.JdbcConnection.<init>(JdbcConnection.java:116)
INFO|3372/0|Service traccar|18-04-18 00:40:08|  at org.h2.jdbc.JdbcConnection.<init>(JdbcConnection.java:100)
INFO|3372/0|Service traccar|18-04-18 00:40:08|  at org.h2.Driver.connect(Driver.java:69)
INFO|3372/0|Service traccar|18-04-18 00:40:08|  at com.zaxxer.hikari.util.DriverDataSource.getConnection(DriverDataSource.java:112)
INFO|3372/0|Service traccar|18-04-18 00:40:08|  at com.zaxxer.hikari.util.DriverDataSource.getConnection(DriverDataSource.java:118)
INFO|3372/0|Service traccar|18-04-18 00:40:08|  at com.zaxxer.hikari.pool.PoolBase.newConnection(PoolBase.java:341)
INFO|3372/0|Service traccar|18-04-18 00:40:08|  at com.zaxxer.hikari.pool.PoolBase.newPoolEntry(PoolBase.java:193)
INFO|3372/0|Service traccar|18-04-18 00:40:08|  at com.zaxxer.hikari.pool.HikariPool.createPoolEntry(HikariPool.java:428)
INFO|3372/0|Service traccar|18-04-18 00:40:08|  at com.zaxxer.hikari.pool.HikariPool.checkFailFast(HikariPool.java:499)
INFO|3372/0|Service traccar|18-04-18 00:40:08|  ... 12 more
INFO|3372/0|Service traccar|18-04-18 00:40:08|Caused by: java.lang.NullPointerException
INFO|3372/0|Service traccar|18-04-18 00:40:08|  at org.h2.mvstore.db.ValueDataType.compare(ValueDataType.java:104)
INFO|3372/0|Service traccar|18-04-18 00:40:08|  at org.h2.mvstore.MVMap.compare(MVMap.java:713)
INFO|3372/0|Service traccar|18-04-18 00:40:08|  at org.h2.mvstore.Page.binarySearch(Page.java:334)
INFO|3372/0|Service traccar|18-04-18 00:40:08|  at org.h2.mvstore.MVMap.binarySearch(MVMap.java:466)
INFO|3372/0|Service traccar|18-04-18 00:40:08|  at org.h2.mvstore.MVMap.get(MVMap.java:455)
INFO|3372/0|Service traccar|18-04-18 00:40:08|  at org.h2.mvstore.MVMap.remove(MVMap.java:543)
INFO|3372/0|Service traccar|18-04-18 00:40:08|  at org.h2.mvstore.db.TransactionStore.rollbackTo(TransactionStore.java:506)
INFO|3372/0|Service traccar|18-04-18 00:40:08|  at org.h2.mvstore.db.TransactionStore$Transaction.rollback(TransactionStore.java:803)
INFO|3372/0|Service traccar|18-04-18 00:40:08|  at org.h2.mvstore.db.MVTableEngine$Store.initTransactions(MVTableEngine.java:256)
INFO|3372/0|Service traccar|18-04-18 00:40:08|  at org.h2.engine.Database.open(Database.java:767)
INFO|3372/0|Service traccar|18-04-18 00:40:08|  at org.h2.engine.Database.openDatabase(Database.java:276)
INFO|3372/0|Service traccar|18-04-18 00:40:08|  ... 28 more
INFO|wrapper|Service traccar|18-04-18 00:40:08|waitpid 3372 59136
INFO|wrapper|Service traccar|18-04-18 00:40:08|exit code posix process: 59136 application(status/signal): 231/0
Anton Tananaev7 years ago

You should never use H2 database for production environment. Use MySQL or any other fully-featured database.