Service starts ok manually but it won't at bootup

eric5658 years ago

I think this is a mysql related error, but i don't know how to solve it, below some more details....

Centos 6.8 - 64 bits

traccar 3.6 

java -version 
openjdk version 1.8.0_101"
OpenJDK Runtime Environment (build 1.8.0_101-b13)
OpenJDK 64-Bit Server VM (build 25.101-b13, mixed mode)

traccar, as a service is

traccar port : 8092

Shorewall rules port 8092 open

iptables off

wrapper.log.... 

[WrapperSimpleAppMain] INFO com.zaxxer.hikari.HikariDataSource - HikariPool-1 - Started.

INFO   | jvm 1    | 2016/08/04 01:40:03 | 
INFO 8/4/16 1:40 AM: liquibase: Clearing database change log checksums

INFO   | jvm 1    | 2016/08/04 01:40:04 | 
INFO 8/4/16 1:40 AM: liquibase: Successfully acquired change log lock

INFO   | jvm 1    | 2016/08/04 01:40:04 | 
INFO 8/4/16 1:40 AM: liquibase: Successfully released change log lock

INFO   | jvm 1    | 2016/08/04 01:40:04 | 
INFO 8/4/16 1:40 AM: liquibase: Successfully acquired change log lock

INFO   | jvm 1    | 2016/08/04 01:40:05 | INFO 8/4/16 1:40 AM: liquibase: Reading from rastreo_01.DATABASECHANGELOG

INFO   | jvm 1    | 2016/08/04 01:40:05 | INFO 8/4/16 1:40 AM: liquibase: Reading from rastreo_01.DATABASECHANGELOG

INFO   | jvm 1    | 2016/08/04 01:40:05 | INFO 8/4/16 1:40 AM: liquibase: Successfully released change log lock

INFO   | jvm 1    | 2016/08/04 01:40:05 | [WrapperSimpleAppMain] 
INFO org.eclipse.jetty.util.log - Logging initialized @2500ms

INFO   | jvm 1    | 2016/08/04 01:40:05 | [WrapperSimpleAppMain] 
INFO org.eclipse.jetty.server.Server - jetty-9.2.17.v20160517

INFO   | jvm 1    | 2016/08/04 01:40:06 | [WrapperSimpleAppMain] 
INFO org.eclipse.jetty.server.handler.ContextHandler - Started o.e.j.s.ServletContextHandler@739602d6{/api,null,AVAILABLE}

INFO   | jvm 1    | 2016/08/04 01:40:06 | [WrapperSimpleAppMain] 
INFO org.eclipse.jetty.server.ServerConnector - Started ServerConnector@461d1cf8{HTTP/1.1}{0.0.0.0:8092}

INFO   | jvm 1    | 2016/08/04 01:40:06 | [WrapperSimpleAppMain] 
INFO org.eclipse.jetty.server.Server - Started @3555ms

STATUS | wrapper  | 2016/08/04 08:27:06 | TERM trapped.  Shutting down.

INFO   | jvm 1    | 2016/08/04 08:27:07 | [Thread-10] 
INFO org.eclipse.jetty.server.ServerConnector - Stopped ServerConnector@461d1cf8{HTTP/1.1}{0.0.0.0:8092}

INFO   | jvm 1    | 2016/08/04 08:27:07 | [Thread-10] 
INFO org.eclipse.jetty.server.handler.ContextHandler - Stopped o.e.j.s.ServletContextHandler@739602d6{/api,null,UNAVAILABLE}

STATUS | wrapper  | 2016/08/04 08:27:07 | <-- Wrapper Stopped

STATUS | wrapper  | 2016/08/04 08:27:14 | --> Wrapper Started as Daemon
STATUS | wrapper  | 2016/08/04 08:27:14 | Java Service Wrapper Community Edition 64-bit 3.5.28

STATUS | wrapper  | 2016/08/04 08:27:14 |   Copyright (C) 1999-2016 Tanuki Software, Ltd. All Rights Reserved.

STATUS | wrapper  | 2016/08/04 08:27:14 |     http://wrapper.tanukisoftware.com

STATUS | wrapper  | 2016/08/04 08:27:14 | 

STATUS | wrapper  | 2016/08/04 08:27:14 | Launching a JVM...
INFO   | jvm 1    | 2016/08/04 08:27:14 | WrapperManager: Initializing...

INFO   | jvm 1    | 2016/08/04 08:27:15 | [WrapperSimpleAppMain] INFO com.zaxxer.hikari.HikariDataSource - HikariPool-1 - Started.

INFO   | jvm 1    | 2016/08/04 08:27:19 | [WrapperSimpleAppMain] INFO com.zaxxer.hikari.pool.HikariPool - HikariPool-1 - Close initiated...

INFO   | jvm 1    | 2016/08/04 08:27:19 | [WrapperSimpleAppMain] INFO com.zaxxer.hikari.pool.HikariPool - HikariPool-1 - Closed.

[WrapperSimpleAppMain] INFO com.zaxxer.hikari.HikariDataSource - HikariPool-1 - Started.
INFO   | jvm 1    | 2016/08/04 01:40:03 | INFO 8/4/16 1:40 AM: liquibase: Clearing database change log checksums
INFO   | jvm 1    | 2016/08/04 01:40:04 | INFO 8/4/16 1:40 AM: liquibase: Successfully acquired change log lock
INFO   | jvm 1    | 2016/08/04 01:40:04 | INFO 8/4/16 1:40 AM: liquibase: Successfully released change log lock
INFO   | jvm 1    | 2016/08/04 01:40:04 | INFO 8/4/16 1:40 AM: liquibase: Successfully acquired change log lock
INFO   | jvm 1    | 2016/08/04 01:40:05 | INFO 8/4/16 1:40 AM: liquibase: Reading from rastreo_01.DATABASECHANGELOG
INFO   | jvm 1    | 2016/08/04 01:40:05 | INFO 8/4/16 1:40 AM: liquibase: Reading from rastreo_01.DATABASECHANGELOG
INFO   | jvm 1    | 2016/08/04 01:40:05 | INFO 8/4/16 1:40 AM: liquibase: Successfully released change log lock
INFO   | jvm 1    | 2016/08/04 01:40:05 | [WrapperSimpleAppMain] INFO org.eclipse.jetty.util.log - Logging initialized @2500ms
INFO   | jvm 1    | 2016/08/04 01:40:05 | [WrapperSimpleAppMain] INFO org.eclipse.jetty.server.Server - jetty-9.2.17.v20160517
INFO   | jvm 1    | 2016/08/04 01:40:06 | [WrapperSimpleAppMain] INFO org.eclipse.jetty.server.handler.ContextHandler - Started o.e.j.s.ServletContextHandler@739602d6{/api,null,AVAILABLE}
INFO   | jvm 1    | 2016/08/04 01:40:06 | [WrapperSimpleAppMain] INFO org.eclipse.jetty.server.ServerConnector - Started ServerConnector@461d1cf8{HTTP/1.1}{0.0.0.0:8092}
INFO   | jvm 1    | 2016/08/04 01:40:06 | [WrapperSimpleAppMain] INFO org.eclipse.jetty.server.Server - Started @3555ms
STATUS | wrapper  | 2016/08/04 08:27:06 | TERM trapped.  Shutting down.
INFO   | jvm 1    | 2016/08/04 08:27:07 | [Thread-10] INFO org.eclipse.jetty.server.ServerConnector - Stopped ServerConnector@461d1cf8{HTTP/1.1}{0.0.0.0:8092}
INFO   | jvm 1    | 2016/08/04 08:27:07 | [Thread-10] INFO org.eclipse.jetty.server.handler.ContextHandler - Stopped o.e.j.s.ServletContextHandler@739602d6{/api,null,UNAVAILABLE}
STATUS | wrapper  | 2016/08/04 08:27:07 | <-- Wrapper Stopped
STATUS | wrapper  | 2016/08/04 08:27:14 | --> Wrapper Started as Daemon
STATUS | wrapper  | 2016/08/04 08:27:14 | Java Service Wrapper Community Edition 64-bit 3.5.28
STATUS | wrapper  | 2016/08/04 08:27:14 |   Copyright (C) 1999-2016 Tanuki Software, Ltd. All Rights Reserved.
STATUS | wrapper  | 2016/08/04 08:27:14 |     http://wrapper.tanukisoftware.com
STATUS | wrapper  | 2016/08/04 08:27:14 | 
STATUS | wrapper  | 2016/08/04 08:27:14 | Launching a JVM...
INFO   | jvm 1    | 2016/08/04 08:27:14 | WrapperManager: Initializing...
INFO   | jvm 1    | 2016/08/04 08:27:15 | [WrapperSimpleAppMain] INFO com.zaxxer.hikari.HikariDataSource - HikariPool-1 - Started.
INFO   | jvm 1    | 2016/08/04 08:27:19 | [WrapperSimpleAppMain] INFO com.zaxxer.hikari.pool.HikariPool - HikariPool-1 - Close initiated...
INFO   | jvm 1    | 2016/08/04 08:27:19 | [WrapperSimpleAppMain] INFO com.zaxxer.hikari.pool.HikariPool - HikariPool-1 - Closed.
INFO   | jvm 1    | 2016/08/04 08:27:19 | WrapperSimpleApp: 
INFO   | jvm 1    | 2016/08/04 08:27:19 | WrapperSimpleApp Error: Encountered an error running main:
INFO   | jvm 1    | 2016/08/04 08:27:19 | WrapperSimpleApp Error: com.zaxxer.hikari.pool.HikariPool$PoolInitializationException: Failed to initialize pool: Could not create connection to database server. Attempted reconnect 3 times. Giving up.
INFO   | jvm 1    | 2016/08/04 08:27:19 | WrapperSimpleApp Error: 	at com.zaxxer.hikari.pool.HikariPool.checkFailFast(HikariPool.java:516)
INFO   | jvm 1    | 2016/08/04 08:27:19 | WrapperSimpleApp Error: 	at com.zaxxer.hikari.pool.HikariPool.<init>(HikariPool.java:118)
INFO   | jvm 1    | 2016/08/04 08:27:19 | WrapperSimpleApp Error: 	at com.zaxxer.hikari.HikariDataSource.<init>(HikariDataSource.java:71)
INFO   | jvm 1    | 2016/08/04 08:27:19 | WrapperSimpleApp Error: 	at org.traccar.database.DataManager.initDatabase(DataManager.java:134)
INFO   | jvm 1    | 2016/08/04 08:27:19 | WrapperSimpleApp Error: 	at org.traccar.database.DataManager.<init>(DataManager.java:87)
INFO   | jvm 1    | 2016/08/04 08:27:19 | WrapperSimpleApp Error: 	at org.traccar.Context.init(Context.java:136)
INFO   | jvm 1    | 2016/08/04 08:27:19 | WrapperSimpleApp Error: 	at org.traccar.Main.main(Main.java:30)
INFO   | jvm 1    | 2016/08/04 08:27:19 | WrapperSimpleApp Error: 	at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
INFO   | jvm 1    | 2016/08/04 08:27:19 | WrapperSimpleApp Error: 	at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62)
INFO   | jvm 1    | 2016/08/04 08:27:19 | WrapperSimpleApp Error: 	at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
INFO   | jvm 1    | 2016/08/04 08:27:19 | WrapperSimpleApp Error: 	at java.lang.reflect.Method.invoke(Method.java:498)
INFO   | jvm 1    | 2016/08/04 08:27:19 | WrapperSimpleApp Error: 	at org.tanukisoftware.wrapper.WrapperSimpleApp.run(WrapperSimpleApp.java:325)
INFO   | jvm 1    | 2016/08/04 08:27:19 | WrapperSimpleApp Error: 	at java.lang.Thread.run(Thread.java:745)
INFO   | jvm 1    | 2016/08/04 08:27:19 | WrapperSimpleApp Error: Caused by: com.mysql.jdbc.exceptions.jdbc4.MySQLNonTransientConnectionException: Could not create connection to database server. Attempted reconnect 3 times. Giving up.
INFO   | jvm 1    | 2016/08/04 08:27:19 | WrapperSimpleApp Error: 	at sun.reflect.NativeConstructorAccessorImpl.newInstance0(Native Method)
INFO   | jvm 1    | 2016/08/04 08:27:19 | WrapperSimpleApp Error: 	at sun.reflect.NativeConstructorAccessorImpl.newInstance(NativeConstructorAccessorImpl.java:62)
INFO   | jvm 1    | 2016/08/04 08:27:19 | WrapperSimpleApp Error: 	at sun.reflect.DelegatingConstructorAccessorImpl.newInstance(DelegatingConstructorAccessorImpl.java:45)
INFO   | jvm 1    | 2016/08/04 08:27:19 | WrapperSimpleApp Error: 	at java.lang.reflect.Constructor.newInstance(Constructor.java:423)
INFO   | jvm 1    | 2016/08/04 08:27:19 | WrapperSimpleApp Error: 	at com.mysql.jdbc.Util.handleNewInstance(Util.java:404)
INFO   | jvm 1    | 2016/08/04 08:27:19 | WrapperSimpleApp Error: 	at com.mysql.jdbc.Util.getInstance(Util.java:387)
INFO   | jvm 1    | 2016/08/04 08:27:19 | WrapperSimpleApp Error: 	at com.mysql.jdbc.SQLError.createSQLException(SQLError.java:917)
INFO   | jvm 1    | 2016/08/04 08:27:19 | WrapperSimpleApp Error: 	at com.mysql.jdbc.SQLError.createSQLException(SQLError.java:896)
INFO   | jvm 1    | 2016/08/04 08:27:19 | WrapperSimpleApp Error: 	at com.mysql.jdbc.SQLError.createSQLException(SQLError.java:885)
INFO   | jvm 1    | 2016/08/04 08:27:19 | WrapperSimpleApp Error: 	at com.mysql.jdbc.SQLError.createSQLException(SQLError.java:860)
INFO   | jvm 1    | 2016/08/04 08:27:19 | WrapperSimpleApp Error: 	at com.mysql.jdbc.ConnectionImpl.connectWithRetries(ConnectionImpl.java:2163)
INFO   | jvm 1    | 2016/08/04 08:27:19 | WrapperSimpleApp Error: 	at com.mysql.jdbc.ConnectionImpl.createNewIO(ConnectionImpl.java:2088)
INFO   | jvm 1    | 2016/08/04 08:27:19 | WrapperSimpleApp Error: 	at com.mysql.jdbc.ConnectionImpl.<init>(ConnectionImpl.java:806)
INFO   | jvm 1    | 2016/08/04 08:27:19 | WrapperSimpleApp Error: 	at com.mysql.jdbc.JDBC4Connection.<init>(JDBC4Connection.java:47)
INFO   | jvm 1    | 2016/08/04 08:27:19 | WrapperSimpleApp Error: 	at sun.reflect.NativeConstructorAccessorImpl.newInstance0(Native Method)
INFO   | jvm 1    | 2016/08/04 08:27:19 | WrapperSimpleApp Error: 	at sun.reflect.NativeConstructorAccessorImpl.newInstance(NativeConstructorAccessorImpl.java:62)
INFO   | jvm 1    | 2016/08/04 08:27:19 | WrapperSimpleApp Error: 	at sun.reflect.DelegatingConstructorAccessorImpl.newInstance(DelegatingConstructorAccessorImpl.java:45)
INFO   | jvm 1    | 2016/08/04 08:27:19 | WrapperSimpleApp Error: 	at java.lang.reflect.Constructor.newInstance(Constructor.java:423)
INFO   | jvm 1    | 2016/08/04 08:27:19 | WrapperSimpleApp Error: 	at com.mysql.jdbc.Util.handleNewInstance(Util.java:404)
INFO   | jvm 1    | 2016/08/04 08:27:19 | WrapperSimpleApp Error: 	at com.mysql.jdbc.ConnectionImpl.getInstance(ConnectionImpl.java:410)
INFO   | jvm 1    | 2016/08/04 08:27:19 | WrapperSimpleApp Error: 	at com.mysql.jdbc.NonRegisteringDriver.connect(NonRegisteringDriver.java:328)
INFO   | jvm 1    | 2016/08/04 08:27:19 | WrapperSimpleApp Error: 	at com.zaxxer.hikari.util.DriverDataSource.getConnection(DriverDataSource.java:95)
INFO   | jvm 1    | 2016/08/04 08:27:19 | WrapperSimpleApp Error: 	at com.zaxxer.hikari.util.DriverDataSource.getConnection(DriverDataSource.java:101)
INFO   | jvm 1    | 2016/08/04 08:27:19 | WrapperSimpleApp Error: 	at com.zaxxer.hikari.pool.PoolBase.newConnection(PoolBase.java:316)
INFO   | jvm 1    | 2016/08/04 08:27:19 | WrapperSimpleApp Error: 	at com.zaxxer.hikari.pool.HikariPool.checkFailFast(HikariPool.java:506)
INFO   | jvm 1    | 2016/08/04 08:27:19 | WrapperSimpleApp Error: 	... 12 more
INFO   | jvm 1    | 2016/08/04 08:27:19 | WrapperSimpleApp Error: Caused by: com.mysql.jdbc.exceptions.jdbc4.CommunicationsException: Communications link failure
INFO   | jvm 1    | 2016/08/04 08:27:19 | WrapperSimpleApp Error: 
INFO   | jvm 1    | 2016/08/04 08:27:19 | WrapperSimpleApp Error: The last packet sent successfully to the server was 0 milliseconds ago. The driver has not received any packets from the server.
INFO   | jvm 1    | 2016/08/04 08:27:19 | WrapperSimpleApp Error: 	at sun.reflect.NativeConstructorAccessorImpl.newInstance0(Native Method)
INFO   | jvm 1    | 2016/08/04 08:27:19 | WrapperSimpleApp Error: 	at sun.reflect.NativeConstructorAccessorImpl.newInstance(NativeConstructorAccessorImpl.java:62)
INFO   | jvm 1    | 2016/08/04 08:27:19 | WrapperSimpleApp Error: 	at sun.reflect.DelegatingConstructorAccessorImpl.newInstance(DelegatingConstructorAccessorImpl.java:45)
INFO   | jvm 1    | 2016/08/04 08:27:19 | WrapperSimpleApp Error: 	at java.lang.reflect.Constructor.newInstance(Constructor.java:423)
INFO   | jvm 1    | 2016/08/04 08:27:19 | WrapperSimpleApp Error: 	at com.mysql.jdbc.Util.handleNewInstance(Util.java:404)
INFO   | jvm 1    | 2016/08/04 08:27:19 | WrapperSimpleApp Error: 	at com.mysql.jdbc.SQLError.createCommunicationsException(SQLError.java:988)
INFO   | jvm 1    | 2016/08/04 08:27:19 | WrapperSimpleApp Error: 	at com.mysql.jdbc.MysqlIO.<init>(MysqlIO.java:341)
INFO   | jvm 1    | 2016/08/04 08:27:19 | WrapperSimpleApp Error: 	at com.mysql.jdbc.ConnectionImpl.coreConnect(ConnectionImpl.java:2251)
INFO   | jvm 1    | 2016/08/04 08:27:19 | WrapperSimpleApp Error: 	at com.mysql.jdbc.ConnectionImpl.connectWithRetries(ConnectionImpl.java:2104)
INFO   | jvm 1    | 2016/08/04 08:27:19 | WrapperSimpleApp Error: 	... 26 more
INFO   | jvm 1    | 2016/08/04 08:27:19 | WrapperSimpleApp Error: Caused by: java.net.ConnectException: Conexión rehusada
INFO   | jvm 1    | 2016/08/04 08:27:19 | WrapperSimpleApp Error: 	at java.net.PlainSocketImpl.socketConnect(Native Method)
INFO   | jvm 1    | 2016/08/04 08:27:19 | WrapperSimpleApp Error: 	at java.net.AbstractPlainSocketImpl.doConnect(AbstractPlainSocketImpl.java:350)
INFO   | jvm 1    | 2016/08/04 08:27:19 | WrapperSimpleApp Error: 	at java.net.AbstractPlainSocketImpl.connectToAddress(AbstractPlainSocketImpl.java:206)
INFO   | jvm 1    | 2016/08/04 08:27:19 | WrapperSimpleApp Error: 	at java.net.AbstractPlainSocketImpl.connect(AbstractPlainSocketImpl.java:188)
INFO   | jvm 1    | 2016/08/04 08:27:19 | WrapperSimpleApp Error: 	at java.net.SocksSocketImpl.connect(SocksSocketImpl.java:392)
INFO   | jvm 1    | 2016/08/04 08:27:19 | WrapperSimpleApp Error: 	at java.net.Socket.connect(Socket.java:589)
INFO   | jvm 1    | 2016/08/04 08:27:19 | WrapperSimpleApp Error: 	at com.mysql.jdbc.StandardSocketFactory.connect(StandardSocketFactory.java:211)
INFO   | jvm 1    | 2016/08/04 08:27:19 | WrapperSimpleApp Error: 	at com.mysql.jdbc.MysqlIO.<init>(MysqlIO.java:300)
INFO   | jvm 1    | 2016/08/04 08:27:19 | WrapperSimpleApp Error: 	... 28 more
STATUS | wrapper  | 2016/08/04 08:27:21 | <-- Wrapper Stopped
Anton Tananaev8 years ago

As you can see the error is "Could not create connection to database server". It means that database connection details are incorrect.

eric5658 years ago

This is the db config at traccar.xml

    <entry key='database.driver'>com.mysql.jdbc.Driver</entry>
    <entry key='database.url'>jdbc:mysql://localhost:3306/rastreo_01?allowMultiQueries=true&autoReconnect=true&useUnicode=yes&characterEncoding=UTF-8&sessionVariables=sql_mode=ANSI_QUOTES</entry>
    <entry key='database.user'>root</entry>
    <entry key='database.password'>ROOT</entry>

if I "service traccar start" It works Ok, With the same config, just when the system boots up it doesn't start :(

Anton Tananaev8 years ago

OK, then I guess the problem is that MySQL starts after Traccar. You need to change startup priority somehow.

eric5658 years ago

Now I know that traccar starts "before" mysql, I tried to change priority order without success (editing BEGIN INIT INFO), Is there a custom way to start traccar "after" mysqld ?

Anton Tananaev8 years ago

Are you using Linux? You just need to change init scripts priority.