Crash following upgrade to 3.12

stevebates7 years ago

Hi,

I've just upgraded to 3.12 but server is failing to start, logs reporting the following:


WARNING|wrapper|Service traccar|17-07-08 10:29:46|YAJSW: yajsw-stable-12.09
WARNING|wrapper|Service traccar|17-07-08 10:29:46|OS   : Linux/4.9.15-x86_64-linode81/amd64
WARNING|wrapper|Service traccar|17-07-08 10:29:46|JVM  : Oracle Corporation/1.8.0_121//usr/lib/jvm/java-8-openjdk-amd64/jre/64
INFO|wrapper|Service traccar|17-07-08 10:29:47|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/h2-1.4.196.jar:/opt/traccar/lib/mysql-connector-java-5.1.42.jar:/opt/traccar/lib/postgresql-42.1.1.jre7.jar:/opt/traccar/lib/mssql-jdbc-6.2.0.jre7.jar:/opt/traccar/lib/HikariCP-java7-2.4.12.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.22.v20170606.jar:/opt/traccar/lib/javax.servlet-api-3.1.0.jar:/opt/traccar/lib/jetty-http-9.2.22.v20170606.jar:/opt/traccar/lib/jetty-io-9.2.22.v20170606.jar:/opt/traccar/lib/jetty-servlet-9.2.22.v20170606.jar:/opt/traccar/lib/jetty-security-9.2.22.v20170606.jar:/opt/traccar/lib/jetty-webapp-9.2.22.v20170606.jar:/opt/traccar/lib/jetty-xml-9.2.22.v20170606.jar:/opt/traccar/lib/jetty-jndi-9.2.22.v20170606.jar:/opt/traccar/lib/jetty-util-9.2.22.v20170606.jar:/opt/traccar/lib/websocket-server-9.2.22.v20170606.jar:/opt/traccar/lib/websocket-common-9.2.22.v20170606.jar:/opt/traccar/lib/websocket-api-9.2.22.v20170606.jar:/opt/traccar/lib/websocket-client-9.2.22.v20170606.jar:/opt/traccar/lib/websocket-servlet-9.2.22.v20170606.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.3.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.0.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.12.jar:/opt/traccar/lib/poi-3.14.jar:/opt/traccar/lib/poi-ooxml-3.14.jar:/opt/traccar/lib/poi-ooxml-schemas-3.14.jar:/opt/traccar/lib/xmlbeans-2.6.0.jar:/opt/traccar/lib/stax-api-1.0.1.jar:/opt/traccar/lib/curvesapi-1.03.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/ical4j-2.0.0.jar:/opt/traccar/lib/commons-collections4-4.0.jar:/opt/traccar/lib/groovy-all-2.3.2.jar:/opt/traccar/lib/bndlib-2.3.0.jar:/opt/traccar/lib/org.osgi.core-4.3.1.jar:/opt/traccar/lib/commons-lang3-3.3.2.jar:/opt/traccar/lib/commons-codec-1.9.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=-850512486623367409" "-Dwrapper.teeName=-850512486623367409$1499506186940" "-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|17-07-08 10:29:47|posix_spawn pid 15400
INFO|wrapper|Service traccar|17-07-08 10:29:47|started process 15400
INFO|wrapper|Service traccar|17-07-08 10:29:47|started process with pid 15400
INFO|15400/0|Service traccar|17-07-08 10:29:49|[INFO] StandardFileSystemManager - Using "/tmp/vfs_cache" as temporary files store.
INFO|15400/0|Service traccar|17-07-08 10:29:50|[main] INFO com.zaxxer.hikari.HikariDataSource - HikariPool-1 - Starting...
INFO|15400/0|Service traccar|17-07-08 10:29:50|[main] INFO com.zaxxer.hikari.HikariDataSource - HikariPool-1 - Start completed.
INFO|15400/0|Service traccar|17-07-08 10:29:51|INFO 7/8/17 10:29 AM: liquibase: Clearing database change log checksums
INFO|15400/0|Service traccar|17-07-08 10:29:51|INFO 7/8/17 10:29 AM: liquibase: Successfully acquired change log lock
INFO|15400/0|Service traccar|17-07-08 10:29:52|INFO 7/8/17 10:29 AM: liquibase: Successfully released change log lock
INFO|15400/0|Service traccar|17-07-08 10:29:52|INFO 7/8/17 10:29 AM: liquibase: Successfully acquired change log lock
INFO|15400/0|Service traccar|17-07-08 10:29:54|INFO 7/8/17 10:29 AM: liquibase: Reading from traccar.DATABASECHANGELOG
INFO|15400/0|Service traccar|17-07-08 10:29:55|INFO 7/8/17 10:29 AM: liquibase: Reading from traccar.DATABASECHANGELOG
INFO|15400/0|Service traccar|17-07-08 10:29:55|SEVERE 7/8/17 10:29 AM: liquibase: ./schema/changelog-master.xml: changelog-3.12::changelog-3.12::author: Change Set changelog-3.12::changelog-3.12::author failed.  Error: Duplicate column name 'mailsent' [Failed SQL: ALTER TABLE traccar.statistics ADD mailsent INT DEFAULT 0 NOT NULL, ADD smssent INT DEFAULT 0 NOT NULL, ADD geocoderrequests INT DEFAULT 0 NOT NULL, ADD geolocationrequests INT DEFAULT 0 NOT NULL]
INFO|15400/0|Service traccar|17-07-08 10:29:55|INFO 7/8/17 10:29 AM: liquibase: changelog-3.12::changelog-3.12::author: Successfully released change log lock
INFO|15400/0|Service traccar|17-07-08 10:29:55|java.lang.reflect.InvocationTargetException
INFO|15400/0|Service traccar|17-07-08 10:29:55|	at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
INFO|15400/0|Service traccar|17-07-08 10:29:55|	at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62)
INFO|15400/0|Service traccar|17-07-08 10:29:55|	at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
INFO|15400/0|Service traccar|17-07-08 10:29:55|	at java.lang.reflect.Method.invoke(Method.java:498)
INFO|15400/0|Service traccar|17-07-08 10:29:55|	at org.rzo.yajsw.app.WrapperJVMMain.executeMain(WrapperJVMMain.java:60)
INFO|15400/0|Service traccar|17-07-08 10:29:55|	at org.rzo.yajsw.app.WrapperJVMMain.main(WrapperJVMMain.java:43)
INFO|15400/0|Service traccar|17-07-08 10:29:55|Caused by: liquibase.exception.MigrationFailedException: Migration failed for change set changelog-3.12::changelog-3.12::author:
INFO|15400/0|Service traccar|17-07-08 10:29:55|     Reason: liquibase.exception.DatabaseException: Duplicate column name 'mailsent' [Failed SQL: ALTER TABLE traccar.statistics ADD mailsent INT DEFAULT 0 NOT NULL, ADD smssent INT DEFAULT 0 NOT NULL, ADD geocoderrequests INT DEFAULT 0 NOT NULL, ADD geolocationrequests INT DEFAULT 0 NOT NULL]
INFO|15400/0|Service traccar|17-07-08 10:29:55|	at liquibase.changelog.ChangeSet.execute(ChangeSet.java:619)
INFO|15400/0|Service traccar|17-07-08 10:29:55|	at liquibase.changelog.visitor.UpdateVisitor.visit(UpdateVisitor.java:51)
INFO|15400/0|Service traccar|17-07-08 10:29:55|	at liquibase.changelog.ChangeLogIterator.run(ChangeLogIterator.java:79)
INFO|15400/0|Service traccar|17-07-08 10:29:55|	at liquibase.Liquibase.update(Liquibase.java:214)
INFO|15400/0|Service traccar|17-07-08 10:29:55|	at liquibase.Liquibase.update(Liquibase.java:192)
INFO|15400/0|Service traccar|17-07-08 10:29:55|	at liquibase.Liquibase.update(Liquibase.java:188)
INFO|15400/0|Service traccar|17-07-08 10:29:55|	at org.traccar.database.DataManager.initDatabaseSchema(DataManager.java:150)
INFO|15400/0|Service traccar|17-07-08 10:29:55|	at org.traccar.database.DataManager.<init>(DataManager.java:76)
INFO|15400/0|Service traccar|17-07-08 10:29:55|	at org.traccar.Context.init(Context.java:221)
INFO|15400/0|Service traccar|17-07-08 10:29:55|	at org.traccar.Main.main(Main.java:35)
INFO|15400/0|Service traccar|17-07-08 10:29:55|	... 6 more
INFO|15400/0|Service traccar|17-07-08 10:29:55|Caused by: liquibase.exception.DatabaseException: Duplicate column name 'mailsent' [Failed SQL: ALTER TABLE traccar.statistics ADD mailsent INT DEFAULT 0 NOT NULL, ADD smssent INT DEFAULT 0 NOT NULL, ADD geocoderrequests INT DEFAULT 0 NOT NULL, ADD geolocationrequests INT DEFAULT 0 NOT NULL]
INFO|15400/0|Service traccar|17-07-08 10:29:55|	at liquibase.executor.jvm.JdbcExecutor$ExecuteStatementCallback.doInStatement(JdbcExecutor.java:309)
INFO|15400/0|Service traccar|17-07-08 10:29:55|	at liquibase.executor.jvm.JdbcExecutor.execute(JdbcExecutor.java:55)
INFO|15400/0|Service traccar|17-07-08 10:29:55|	at liquibase.executor.jvm.JdbcExecutor.execute(JdbcExecutor.java:113)
INFO|15400/0|Service traccar|17-07-08 10:29:55|	at liquibase.database.AbstractJdbcDatabase.execute(AbstractJdbcDatabase.java:1277)
INFO|15400/0|Service traccar|17-07-08 10:29:55|	at liquibase.database.AbstractJdbcDatabase.executeStatements(AbstractJdbcDatabase.java:1259)
INFO|15400/0|Service traccar|17-07-08 10:29:55|	at liquibase.changelog.ChangeSet.execute(ChangeSet.java:582)
INFO|15400/0|Service traccar|17-07-08 10:29:55|	... 15 more
INFO|15400/0|Service traccar|17-07-08 10:29:55|Caused by: com.mysql.jdbc.exceptions.jdbc4.MySQLSyntaxErrorException: Duplicate column name 'mailsent'
INFO|15400/0|Service traccar|17-07-08 10:29:55|	at sun.reflect.NativeConstructorAccessorImpl.newInstance0(Native Method)
INFO|15400/0|Service traccar|17-07-08 10:29:55|	at sun.reflect.NativeConstructorAccessorImpl.newInstance(NativeConstructorAccessorImpl.java:62)
INFO|15400/0|Service traccar|17-07-08 10:29:55|	at sun.reflect.DelegatingConstructorAccessorImpl.newInstance(DelegatingConstructorAccessorImpl.java:45)
INFO|15400/0|Service traccar|17-07-08 10:29:55|	at java.lang.reflect.Constructor.newInstance(Constructor.java:423)
INFO|15400/0|Service traccar|17-07-08 10:29:55|	at com.mysql.jdbc.Util.handleNewInstance(Util.java:425)
INFO|15400/0|Service traccar|17-07-08 10:29:55|	at com.mysql.jdbc.Util.getInstance(Util.java:408)
INFO|15400/0|Service traccar|17-07-08 10:29:55|	at com.mysql.jdbc.SQLError.createSQLException(SQLError.java:943)
INFO|15400/0|Service traccar|17-07-08 10:29:55|	at com.mysql.jdbc.MysqlIO.checkErrorPacket(MysqlIO.java:3973)
INFO|15400/0|Service traccar|17-07-08 10:29:55|	at com.mysql.jdbc.MysqlIO.checkErrorPacket(MysqlIO.java:3909)
INFO|15400/0|Service traccar|17-07-08 10:29:55|	at com.mysql.jdbc.MysqlIO.sendCommand(MysqlIO.java:2527)
INFO|15400/0|Service traccar|17-07-08 10:29:55|	at com.mysql.jdbc.MysqlIO.sqlQueryDirect(MysqlIO.java:2680)
INFO|15400/0|Service traccar|17-07-08 10:29:55|	at com.mysql.jdbc.ConnectionImpl.execSQL(ConnectionImpl.java:2486)
INFO|15400/0|Service traccar|17-07-08 10:29:55|	at com.mysql.jdbc.ConnectionImpl.execSQL(ConnectionImpl.java:2444)
INFO|15400/0|Service traccar|17-07-08 10:29:55|	at com.mysql.jdbc.StatementImpl.executeInternal(StatementImpl.java:845)
INFO|15400/0|Service traccar|17-07-08 10:29:55|	at com.mysql.jdbc.StatementImpl.execute(StatementImpl.java:745)
INFO|15400/0|Service traccar|17-07-08 10:29:55|	at liquibase.executor.jvm.JdbcExecutor$ExecuteStatementCallback.doInStatement(JdbcExecutor.java:307)
INFO|15400/0|Service traccar|17-07-08 10:29:55|	... 20 more
INFO|wrapper|Service traccar|17-07-08 10:29:55|waitpid 15400 59136
INFO|wrapper|Service traccar|17-07-08 10:29:55|exit code posix process: 59136 application: 0

It appears there is an SQL error?

Regards,

Steve.

Anton Tananaev7 years ago

The problem is that you didn't wait till it finish migration the first time you started, so your database now is in invalid state. You need to restore original state before upgrade and do it again. Make sure you wait till Traccar starts. Don't stop the process in the middle of database migration.

stevebates7 years ago

Sorry but i didnt terminate it?

The installation wiped my traccar.xml file so it booted up, i shut it down as usual and replaced the XML file with my usual one then started it and nothing.

If migration is that important, what safeguards are in place to tell me migration is occurring?

Anton Tananaev7 years ago

Log messages are pretty self-explanatory. There are messages about database locks.

Are you upgrading from the last official release?

stevebates7 years ago

Think you've missed my point but it doesnt matter now i've just reset the database.

I was trying to point out that on installation traccar.xml which was pointing at MySQL was overwirtten which i dont fully understand as theres traccar_default.xml but during installation this then re-points the database to the default one. I then stopped the server as the installer starts it automatically pointing it at the wrong place, thinking i dont use this database, it cant be important. Replaced traccar.xml and started it again pointing at MySQL but it didnt start.

Like i say though, server now running.

Anton Tananaev7 years ago

There is an official upgrade guide:

https://www.traccar.org/upgrading-traccar/