Dear Anton,
I have two same configuration VPS with Ubuntu.
Traccar version 3.5 and MySQL DB
1st Instance of Traccar and 2nd Instance of Traccar is exactly same. (Clone)
However 1st Instance if I shutdown traccar and start it again, it takes a lot of time, to startup. and in MySQL i can see the Query process SELECT * FROM positions WHERE id IN (SELECT positionId FROM devices); active for long time.
2nd Instance of traccar has no issues (There is no difference in version of any software on the OS or any aspect of the hardware/software) its a clone of the 1st Server.
I even upgraded both servers Traccar to 3.6 today, still the 1st Instance starts up with an 30 to 40 minutes delay. One such time, when the service was starting up and for long it did not, I rebooted the machine, here is the wrapper log from that moment.
Is there anything in the log that might help? Please advice.
INFO | jvm 1 | 2016/08/21 12:30:09 | INFO 8/21/16 12:30 PM: liquibase: Successfully released change log lock
INFO | jvm 1 | 2016/08/21 12:30:09 | [WrapperSimpleAppMain] INFO org.eclipse.jetty.util.log - Logging initialized @11284ms
INFO | jvm 1 | 2016/08/21 13:19:42 | [WrapperSimpleAppMain] WARN com.zaxxer.hikari.pool.ProxyConnection - HikariPool-1 - Connection com.mysql.jdbc.JDBC4Connection@516986e6 marked as broken because of SQLSTATE(08S01), ErrorCode(0)
INFO | jvm 1 | 2016/08/21 13:19:42 | com.mysql.jdbc.exceptions.jdbc4.CommunicationsException: Communications link failure
INFO | jvm 1 | 2016/08/21 13:19:42 |
INFO | jvm 1 | 2016/08/21 13:19:42 | The last packet successfully received from the server was 2 milliseconds ago. The last packet sent successfully to the server was 1 milliseconds ago.
INFO | jvm 1 | 2016/08/21 13:19:42 | at sun.reflect.NativeConstructorAccessorImpl.newInstance0(Native Method)
INFO | jvm 1 | 2016/08/21 13:19:42 | at sun.reflect.NativeConstructorAccessorImpl.newInstance(NativeConstructorAccessorImpl.java:57)
INFO | jvm 1 | 2016/08/21 13:19:42 | at sun.reflect.DelegatingConstructorAccessorImpl.newInstance(DelegatingConstructorAccessorImpl.java:45)
INFO | jvm 1 | 2016/08/21 13:19:42 | at java.lang.reflect.Constructor.newInstance(Constructor.java:526)
INFO | jvm 1 | 2016/08/21 13:19:42 | at com.mysql.jdbc.Util.handleNewInstance(Util.java:404)
INFO | jvm 1 | 2016/08/21 13:19:42 | at com.mysql.jdbc.SQLError.createCommunicationsException(SQLError.java:988)
INFO | jvm 1 | 2016/08/21 13:19:42 | at com.mysql.jdbc.MysqlIO.reuseAndReadPacket(MysqlIO.java:3552)
INFO | jvm 1 | 2016/08/21 13:19:42 | at com.mysql.jdbc.MysqlIO.reuseAndReadPacket(MysqlIO.java:3452)
INFO | jvm 1 | 2016/08/21 13:19:42 | at com.mysql.jdbc.MysqlIO.checkErrorPacket(MysqlIO.java:3893)
INFO | jvm 1 | 2016/08/21 13:19:42 | at com.mysql.jdbc.MysqlIO.sendCommand(MysqlIO.java:2526)
INFO | jvm 1 | 2016/08/21 13:19:42 | at com.mysql.jdbc.MysqlIO.sqlQueryDirect(MysqlIO.java:2673)
INFO | jvm 1 | 2016/08/21 13:19:42 | at com.mysql.jdbc.ConnectionImpl.execSQL(ConnectionImpl.java:2549)
INFO | jvm 1 | 2016/08/21 13:19:42 | at com.mysql.jdbc.PreparedStatement.executeInternal(PreparedStatement.java:1861)
INFO | jvm 1 | 2016/08/21 13:19:42 | at com.mysql.jdbc.PreparedStatement.executeQuery(PreparedStatement.java:1962)
INFO | jvm 1 | 2016/08/21 13:19:42 | at com.zaxxer.hikari.pool.ProxyPreparedStatement.executeQuery(ProxyPreparedStatement.java:52)
INFO | jvm 1 | 2016/08/21 13:19:42 | at com.zaxxer.hikari.pool.HikariProxyPreparedStatement.executeQuery(HikariProxyPreparedStatement.java)
INFO | jvm 1 | 2016/08/21 13:19:42 | at org.traccar.database.QueryBuilder.executeQuery(QueryBuilder.java:380)
INFO | jvm 1 | 2016/08/21 13:19:42 | at org.traccar.database.DataManager.getGeofences(DataManager.java:565)
INFO | jvm 1 | 2016/08/21 13:19:42 | at org.traccar.database.GeofenceManager.refresh(GeofenceManager.java:115)
INFO | jvm 1 | 2016/08/21 13:19:42 | at org.traccar.database.GeofenceManager.<init>(GeofenceManager.java:56)
INFO | jvm 1 | 2016/08/21 13:19:42 | at org.traccar.Context.init(Context.java:204)
INFO | jvm 1 | 2016/08/21 13:19:42 | at org.traccar.Main.main(Main.java:30)
INFO | jvm 1 | 2016/08/21 13:19:42 | at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
INFO | jvm 1 | 2016/08/21 13:19:42 | at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:57)
INFO | jvm 1 | 2016/08/21 13:19:42 | at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
INFO | jvm 1 | 2016/08/21 13:19:42 | at java.lang.reflect.Method.invoke(Method.java:606)
INFO | jvm 1 | 2016/08/21 13:19:42 | at org.tanukisoftware.wrapper.WrapperSimpleApp.run(WrapperSimpleApp.java:325)
INFO | jvm 1 | 2016/08/21 13:19:42 | at java.lang.Thread.run(Thread.java:745)
INFO | jvm 1 | 2016/08/21 13:19:42 | Caused by: java.io.EOFException: Can not read response from server. Expected to read 4 bytes, read 0 bytes before connection was unexpectedly lost.
INFO | jvm 1 | 2016/08/21 13:19:42 | at com.mysql.jdbc.MysqlIO.readFully(MysqlIO.java:3004)
INFO | jvm 1 | 2016/08/21 13:19:42 | at com.mysql.jdbc.MysqlIO.reuseAndReadPacket(MysqlIO.java:3462)
INFO | jvm 1 | 2016/08/21 13:19:42 | ... 21 more
INFO | jvm 1 | 2016/08/21 13:19:42 | [WrapperSimpleAppMain] WARN com.zaxxer.hikari.pool.ProxyConnection - HikariPool-1 - Connection com.mysql.jdbc.JDBC4Connection@6c1194fa marked as broken because of SQLSTATE(08S01), ErrorCode(0)
INFO | jvm 1 | 2016/08/21 13:19:42 | com.mysql.jdbc.exceptions.jdbc4.CommunicationsException: Communications link failure
INFO | jvm 1 | 2016/08/21 13:19:42 |
INFO | jvm 1 | 2016/08/21 13:19:42 | The last packet successfully received from the server was 1 milliseconds ago. The last packet sent successfully to the server was 0 milliseconds ago.
INFO | jvm 1 | 2016/08/21 13:19:42 | at sun.reflect.NativeConstructorAccessorImpl.newInstance0(Native Method)
INFO | jvm 1 | 2016/08/21 13:19:42 | at sun.reflect.NativeConstructorAccessorImpl.newInstance(NativeConstructorAccessorImpl.java:57)
INFO | jvm 1 | 2016/08/21 13:19:42 | at sun.reflect.DelegatingConstructorAccessorImpl.newInstance(DelegatingConstructorAccessorImpl.java:45)
INFO | jvm 1 | 2016/08/21 13:19:42 | at java.lang.reflect.Constructor.newInstance(Constructor.java:526)
INFO | jvm 1 | 2016/08/21 13:19:42 | at com.mysql.jdbc.Util.handleNewInstance(Util.java:404)
INFO | jvm 1 | 2016/08/21 13:19:42 | at com.mysql.jdbc.SQLError.createCommunicationsException(SQLError.java:988)
INFO | jvm 1 | 2016/08/21 13:19:42 | at com.mysql.jdbc.MysqlIO.reuseAndReadPacket(MysqlIO.java:3552)
INFO | jvm 1 | 2016/08/21 13:19:42 | at com.mysql.jdbc.MysqlIO.reuseAndReadPacket(MysqlIO.java:3452)
INFO | jvm 1 | 2016/08/21 13:19:42 | at com.mysql.jdbc.MysqlIO.checkErrorPacket(MysqlIO.java:3893)
INFO | jvm 1 | 2016/08/21 13:19:42 | at com.mysql.jdbc.MysqlIO.sendCommand(MysqlIO.java:2526)
INFO | jvm 1 | 2016/08/21 13:19:42 | at com.mysql.jdbc.MysqlIO.sqlQueryDirect(MysqlIO.java:2673)
INFO | jvm 1 | 2016/08/21 13:19:42 | at com.mysql.jdbc.ConnectionImpl.execSQL(ConnectionImpl.java:2549)
INFO | jvm 1 | 2016/08/21 13:19:42 | at com.mysql.jdbc.PreparedStatement.executeInternal(PreparedStatement.java:1861)
INFO | jvm 1 | 2016/08/21 13:19:42 | at com.mysql.jdbc.PreparedStatement.executeQuery(PreparedStatement.java:1962)
INFO | jvm 1 | 2016/08/21 13:19:42 | at com.zaxxer.hikari.pool.ProxyPreparedStatement.executeQuery(ProxyPreparedStatement.java:52)
INFO | jvm 1 | 2016/08/21 13:19:42 | at com.zaxxer.hikari.pool.HikariProxyPreparedStatement.executeQuery(HikariProxyPreparedStatement.java)
INFO | jvm 1 | 2016/08/21 13:19:42 | at org.traccar.database.QueryBuilder.executeQuery(QueryBuilder.java:380)
INFO | jvm 1 | 2016/08/21 13:19:42 | at org.traccar.database.DataManager.getNotifications(DataManager.java:651)
INFO | jvm 1 | 2016/08/21 13:19:42 | at org.traccar.database.NotificationManager.refresh(NotificationManager.java:102)
INFO | jvm 1 | 2016/08/21 13:19:42 | at org.traccar.database.NotificationManager.<init>(NotificationManager.java:46)
INFO | jvm 1 | 2016/08/21 13:19:42 | at org.traccar.Context.init(Context.java:208)
INFO | jvm 1 | 2016/08/21 13:19:42 | at org.traccar.Main.main(Main.java:30)
INFO | jvm 1 | 2016/08/21 13:19:42 | at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
INFO | jvm 1 | 2016/08/21 13:19:42 | at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:57)
INFO | jvm 1 | 2016/08/21 13:19:42 | at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
INFO | jvm 1 | 2016/08/21 13:19:42 | at java.lang.reflect.Method.invoke(Method.java:606)
INFO | jvm 1 | 2016/08/21 13:19:42 | at org.tanukisoftware.wrapper.WrapperSimpleApp.run(WrapperSimpleApp.java:325)
INFO | jvm 1 | 2016/08/21 13:19:42 | at java.lang.Thread.run(Thread.java:745)
INFO | jvm 1 | 2016/08/21 13:19:42 | Caused by: java.io.EOFException: Can not read response from server. Expected to read 4 bytes, read 0 bytes before connection was unexpectedly lost.
INFO | jvm 1 | 2016/08/21 13:19:42 | at com.mysql.jdbc.MysqlIO.readFully(MysqlIO.java:3004)
INFO | jvm 1 | 2016/08/21 13:19:42 | at com.mysql.jdbc.MysqlIO.reuseAndReadPacket(MysqlIO.java:3462)
INFO | jvm 1 | 2016/08/21 13:19:42 | ... 21 more
INFO | jvm 1 | 2016/08/21 13:19:42 | [WrapperSimpleAppMain] INFO org.eclipse.jetty.server.Server - jetty-9.2.17.v20160517
INFO | jvm 1 | 2016/08/21 13:19:43 | [New I/O worker #15] WARN com.zaxxer.hikari.pool.ProxyConnection - HikariPool-1 - Connection com.mysql.jdbc.JDBC4Connection@5e84b982 marked as broken because of SQLSTATE(08S01), ErrorCode(0)
INFO | jvm 1 | 2016/08/21 13:19:43 | com.mysql.jdbc.exceptions.jdbc4.CommunicationsException: Communications link failure
INFO | jvm 1 | 2016/08/21 13:19:43 |
INFO | jvm 1 | 2016/08/21 13:19:43 | The last packet successfully received from the server was 0 milliseconds ago. The last packet sent successfully to the server was 0 milliseconds ago.
INFO | jvm 1 | 2016/08/21 13:19:43 | at sun.reflect.NativeConstructorAccessorImpl.newInstance0(Native Method)
INFO | jvm 1 | 2016/08/21 13:19:43 | at sun.reflect.NativeConstructorAccessorImpl.newInstance(NativeConstructorAccessorImpl.java:57)
INFO | jvm 1 | 2016/08/21 13:19:43 | at sun.reflect.DelegatingConstructorAccessorImpl.newInstance(DelegatingConstructorAccessorImpl.java:45)
INFO | jvm 1 | 2016/08/21 13:19:43 | at java.lang.reflect.Constructor.newInstance(Constructor.java:526)
INFO | jvm 1 | 2016/08/21 13:19:43 | at com.mysql.jdbc.Util.handleNewInstance(Util.java:404)
INFO | jvm 1 | 2016/08/21 13:19:43 | at com.mysql.jdbc.SQLError.createCommunicationsException(SQLError.java:988)
INFO | jvm 1 | 2016/08/21 13:19:43 | at com.mysql.jdbc.MysqlIO.reuseAndReadPacket(MysqlIO.java:3552)
INFO | jvm 1 | 2016/08/21 13:19:43 | at com.mysql.jdbc.MysqlIO.reuseAndReadPacket(MysqlIO.java:3452)
INFO | jvm 1 | 2016/08/21 13:19:43 | at com.mysql.jdbc.MysqlIO.checkErrorPacket(MysqlIO.java:3893)
INFO | jvm 1 | 2016/08/21 13:19:43 | at com.mysql.jdbc.MysqlIO.sendCommand(MysqlIO.java:2526)
INFO | jvm 1 | 2016/08/21 13:19:43 | at com.mysql.jdbc.MysqlIO.sqlQueryDirect(MysqlIO.java:2673)
INFO | jvm 1 | 2016/08/21 13:19:43 | at com.mysql.jdbc.ConnectionImpl.execSQL(ConnectionImpl.java:2549)
INFO | jvm 1 | 2016/08/21 13:19:43 | at com.mysql.jdbc.PreparedStatement.executeInternal(PreparedStatement.java:1861)
INFO | jvm 1 | 2016/08/21 13:19:43 | at com.mysql.jdbc.PreparedStatement.executeQuery(PreparedStatement.java:1962)
INFO | jvm 1 | 2016/08/21 13:19:43 | at com.zaxxer.hikari.pool.ProxyPreparedStatement.executeQuery(ProxyPreparedStatement.java:52)
INFO | jvm 1 | 2016/08/21 13:19:43 | at com.zaxxer.hikari.pool.HikariProxyPreparedStatement.executeQuery(HikariProxyPreparedStatement.java)
INFO | jvm 1 | 2016/08/21 13:19:43 | at org.traccar.database.QueryBuilder.executeQuery(QueryBuilder.java:380)
INFO | jvm 1 | 2016/08/21 13:19:43 | at org.traccar.database.DataManager.getAllDevices(DataManager.java:352)
INFO | jvm 1 | 2016/08/21 13:19:43 | at org.traccar.database.DataManager.updateDeviceCache(DataManager.java:156)
INFO | jvm 1 | 2016/08/21 13:19:43 | at org.traccar.database.DataManager.getDeviceByUniqueId(DataManager.java:208)
INFO | jvm 1 | 2016/08/21 13:19:43 | at org.traccar.BaseProtocolDecoder.identify(BaseProtocolDecoder.java:47)
INFO | jvm 1 | 2016/08/21 13:19:43 | at org.traccar.BaseProtocolDecoder.identify(BaseProtocolDecoder.java:71)
INFO | jvm 1 | 2016/08/21 13:19:43 | at org.traccar.protocol.Gt02ProtocolDecoder.decode(Gt02ProtocolDecoder.java:55)
INFO | jvm 1 | 2016/08/21 13:19:43 | at org.traccar.ExtendedObjectDecoder.handleUpstream(ExtendedObjectDecoder.java:57)
INFO | jvm 1 | 2016/08/21 13:19:43 | at org.jboss.netty.channel.DefaultChannelPipeline.sendUpstream(DefaultChannelPipeline.java:564)
INFO | jvm 1 | 2016/08/21 13:19:43 | at org.jboss.netty.channel.DefaultChannelPipeline$DefaultChannelHandlerContext.sendUpstream(DefaultChannelPipeline.java:791)
INFO | jvm 1 | 2016/08/21 13:19:43 | at org.jboss.netty.channel.Channels.fireMessageReceived(Channels.java:296)
INFO | jvm 1 | 2016/08/21 13:19:43 | at org.jboss.netty.handler.codec.frame.FrameDecoder.unfoldAndFireMessageReceived(FrameDecoder.java:462)
INFO | jvm 1 | 2016/08/21 13:19:43 | at org.jboss.netty.handler.codec.frame.FrameDecoder.callDecode(FrameDecoder.java:443)
INFO | jvm 1 | 2016/08/21 13:19:43 | at org.jboss.netty.handler.codec.frame.FrameDecoder.messageReceived(FrameDecoder.java:303)
INFO | jvm 1 | 2016/08/21 13:19:43 | at org.jboss.netty.channel.SimpleChannelUpstreamHandler.handleUpstream(SimpleChannelUpstreamHandler.java:70)
INFO | jvm 1 | 2016/08/21 13:19:43 | at org.jboss.netty.channel.DefaultChannelPipeline.sendUpstream(DefaultChannelPipeline.java:564)
INFO | jvm 1 | 2016/08/21 13:19:43 | at org.jboss.netty.channel.DefaultChannelPipeline$DefaultChannelHandlerContext.sendUpstream(DefaultChannelPipeline.java:791)
INFO | jvm 1 | 2016/08/21 13:19:43 | at org.jboss.netty.handler.logging.LoggingHandler.handleUpstream(LoggingHandler.java:332)
INFO | jvm 1 | 2016/08/21 13:19:43 | at org.jboss.netty.channel.DefaultChannelPipeline.sendUpstream(DefaultChannelPipeline.java:564)
INFO | jvm 1 | 2016/08/21 13:19:43 | at org.jboss.netty.channel.DefaultChannelPipeline$DefaultChannelHandlerContext.sendUpstream(DefaultChannelPipeline.java:791)
INFO | jvm 1 | 2016/08/21 13:19:43 | at org.jboss.netty.channel.SimpleChannelHandler.messageReceived(SimpleChannelHandler.java:142)
INFO | jvm 1 | 2016/08/21 13:19:43 | at org.jboss.netty.channel.SimpleChannelHandler.handleUpstream(SimpleChannelHandler.java:88)
INFO | jvm 1 | 2016/08/21 13:19:43 | at org.jboss.netty.channel.DefaultChannelPipeline.sendUpstream(DefaultChannelPipeline.java:564)
INFO | jvm 1 | 2016/08/21 13:19:43 | at org.jboss.netty.channel.DefaultChannelPipeline.sendUpstream(DefaultChannelPipeline.java:559)
INFO | jvm 1 | 2016/08/21 13:19:43 | at org.jboss.netty.channel.Channels.fireMessageReceived(Channels.java:268)
INFO | jvm 1 | 2016/08/21 13:19:43 | at org.jboss.netty.channel.Channels.fireMessageReceived(Channels.java:255)
INFO | jvm 1 | 2016/08/21 13:19:43 | at org.jboss.netty.channel.socket.nio.NioWorker.read(NioWorker.java:88)
INFO | jvm 1 | 2016/08/21 13:19:43 | at org.jboss.netty.channel.socket.nio.AbstractNioWorker.process(AbstractNioWorker.java:108)
INFO | jvm 1 | 2016/08/21 13:19:43 | at org.jboss.netty.channel.socket.nio.AbstractNioSelector.run(AbstractNioSelector.java:337)
INFO | jvm 1 | 2016/08/21 13:19:43 | at org.jboss.netty.channel.socket.nio.AbstractNioWorker.run(AbstractNioWorker.java:89)
INFO | jvm 1 | 2016/08/21 13:19:43 | at org.jboss.netty.channel.socket.nio.NioWorker.run(NioWorker.java:178)
INFO | jvm 1 | 2016/08/21 13:19:43 | at org.jboss.netty.util.ThreadRenamingRunnable.run(ThreadRenamingRunnable.java:108)
INFO | jvm 1 | 2016/08/21 13:19:43 | at org.jboss.netty.util.internal.DeadLockProofWorker$1.run(DeadLockProofWorker.java:42)
INFO | jvm 1 | 2016/08/21 13:19:43 | at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1145)
INFO | jvm 1 | 2016/08/21 13:19:43 | at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:615)
INFO | jvm 1 | 2016/08/21 13:19:43 | at java.lang.Thread.run(Thread.java:745)
INFO | jvm 1 | 2016/08/21 13:19:43 | Caused by: java.io.EOFException: Can not read response from server. Expected to read 4 bytes, read 0 bytes before connection was unexpectedly lost.
INFO | jvm 1 | 2016/08/21 13:19:43 | at com.mysql.jdbc.MysqlIO.readFully(MysqlIO.java:3004)
INFO | jvm 1 | 2016/08/21 13:19:43 | at com.mysql.jdbc.MysqlIO.reuseAndReadPacket(MysqlIO.java:3462)
INFO | jvm 1 | 2016/08/21 13:19:43 | ... 45 more
INFO | jvm 1 | 2016/08/21 13:19:43 | [WrapperSimpleAppMain] INFO org.eclipse.jetty.server.handler.ContextHandler - Started o.e.j.s.ServletContextHandler@43b34c70{/api,null,AVAILABLE}
INFO | jvm 1 | 2016/08/21 13:19:43 | [WrapperSimpleAppMain] INFO org.eclipse.jetty.server.ServerConnector - Started ServerConnector@650c234c{HTTP/1.1}{0.0.0.0:8667}
INFO | jvm 1 | 2016/08/21 13:19:43 | [WrapperSimpleAppMain] INFO org.eclipse.jetty.server.Server - Started @2985615ms
INFO | jvm 1 | 2016/08/21 13:19:44 | [New I/O worker #11] WARN com.zaxxer.hikari.pool.ProxyConnection - HikariPool-1 - Connection com.mysql.jdbc.JDBC4Connection@2e777e05 marked as broken because of SQLSTATE(08S01), ErrorCode(0)
INFO | jvm 1 | 2016/08/21 13:19:44 | com.mysql.jdbc.exceptions.jdbc4.CommunicationsException: Communications link failure
INFO | jvm 1 | 2016/08/21 13:19:44 |
INFO | jvm 1 | 2016/08/21 13:19:44 | The last packet successfully received from the server was 1 milliseconds ago. The last packet sent successfully to the server was 1 milliseconds ago.
INFO | jvm 1 | 2016/08/21 13:19:44 | at sun.reflect.NativeConstructorAccessorImpl.newInstance0(Native Method)
INFO | jvm 1 | 2016/08/21 13:19:44 | at sun.reflect.NativeConstructorAccessorImpl.newInstance(NativeConstructorAccessorImpl.java:57)
INFO | jvm 1 | 2016/08/21 13:19:44 | at sun.reflect.DelegatingConstructorAccessorImpl.newInstance(DelegatingConstructorAccessorImpl.java:45)
INFO | jvm 1 | 2016/08/21 13:19:44 | at java.lang.reflect.Constructor.newInstance(Constructor.java:526)
INFO | jvm 1 | 2016/08/21 13:19:44 | at com.mysql.jdbc.Util.handleNewInstance(Util.java:404)
INFO | jvm 1 | 2016/08/21 13:19:44 | at com.mysql.jdbc.SQLError.createCommunicationsException(SQLError.java:988)
INFO | jvm 1 | 2016/08/21 13:19:44 | at com.mysql.jdbc.MysqlIO.reuseAndReadPacket(MysqlIO.java:3552)
INFO | jvm 1 | 2016/08/21 13:19:44 | at com.mysql.jdbc.MysqlIO.reuseAndReadPacket(MysqlIO.java:3452)
INFO | jvm 1 | 2016/08/21 13:19:44 | at com.mysql.jdbc.MysqlIO.checkErrorPacket(MysqlIO.java:3893)
INFO | jvm 1 | 2016/08/21 13:19:44 | at com.mysql.jdbc.MysqlIO.sendCommand(MysqlIO.java:2526)
INFO | jvm 1 | 2016/08/21 13:19:44 | at com.mysql.jdbc.MysqlIO.sqlQueryDirect(MysqlIO.java:2673)
INFO | jvm 1 | 2016/08/21 13:19:44 | at com.mysql.jdbc.ConnectionImpl.execSQL(ConnectionImpl.java:2549)
INFO | jvm 1 | 2016/08/21 13:19:44 | at com.mysql.jdbc.PreparedStatement.executeInternal(PreparedStatement.java:1861)
INFO | jvm 1 | 2016/08/21 13:19:44 | at com.mysql.jdbc.PreparedStatement.executeQuery(PreparedStatement.java:1962)
INFO | jvm 1 | 2016/08/21 13:19:44 | at com.zaxxer.hikari.pool.ProxyPreparedStatement.executeQuery(ProxyPreparedStatement.java:52)
INFO | jvm 1 | 2016/08/21 13:19:44 | at com.zaxxer.hikari.pool.HikariProxyPreparedStatement.executeQuery(HikariProxyPreparedStatement.java)
INFO | jvm 1 | 2016/08/21 13:19:44 | at org.traccar.database.QueryBuilder.executeQuery(QueryBuilder.java:380)
INFO | jvm 1 | 2016/08/21 13:19:44 | at org.traccar.database.DataManager.getAllDevices(DataManager.java:352)
INFO | jvm 1 | 2016/08/21 13:19:44 | at org.traccar.database.DataManager.updateDeviceCache(DataManager.java:156)
INFO | jvm 1 | 2016/08/21 13:19:44 | at org.traccar.database.DataManager.getDeviceByUniqueId(DataManager.java:208)
INFO | jvm 1 | 2016/08/21 13:19:44 | at org.traccar.BaseProtocolDecoder.identify(BaseProtocolDecoder.java:47)
INFO | jvm 1 | 2016/08/21 13:19:44 | at org.traccar.BaseProtocolDecoder.identify(BaseProtocolDecoder.java:71)
INFO | jvm 1 | 2016/08/21 13:19:44 | at org.traccar.protocol.Gt02ProtocolDecoder.decode(Gt02ProtocolDecoder.java:55)
INFO | jvm 1 | 2016/08/21 13:19:44 | at org.traccar.ExtendedObjectDecoder.handleUpstream(ExtendedObjectDecoder.java:57)
INFO | jvm 1 | 2016/08/21 13:19:44 | at org.jboss.netty.channel.DefaultChannelPipeline.sendUpstream(DefaultChannelPipeline.java:564)
INFO | jvm 1 | 2016/08/21 13:19:44 | at org.jboss.netty.channel.DefaultChannelPipeline$DefaultChannelHandlerContext.sendUpstream(DefaultChannelPipeline.java:791)
INFO | jvm 1 | 2016/08/21 13:19:44 | at org.jboss.netty.channel.Channels.fireMessageReceived(Channels.java:296)
INFO | jvm 1 | 2016/08/21 13:19:44 | at org.jboss.netty.handler.codec.frame.FrameDecoder.unfoldAndFireMessageReceived(FrameDecoder.java:462)
INFO | jvm 1 | 2016/08/21 13:19:44 | at org.jboss.netty.handler.codec.frame.FrameDecoder.callDecode(FrameDecoder.java:443)
INFO | jvm 1 | 2016/08/21 13:19:44 | at org.jboss.netty.handler.codec.frame.FrameDecoder.messageReceived(FrameDecoder.java:303)
INFO | jvm 1 | 2016/08/21 13:19:44 | at org.jboss.netty.channel.SimpleChannelUpstreamHandler.handleUpstream(SimpleChannelUpstreamHandler.java:70)
INFO | jvm 1 | 2016/08/21 13:19:44 | at org.jboss.netty.channel.DefaultChannelPipeline.sendUpstream(DefaultChannelPipeline.java:564)
INFO | jvm 1 | 2016/08/21 13:19:44 | at org.jboss.netty.channel.DefaultChannelPipeline$DefaultChannelHandlerContext.sendUpstream(DefaultChannelPipeline.java:791)
INFO | jvm 1 | 2016/08/21 13:19:44 | at org.jboss.netty.handler.logging.LoggingHandler.handleUpstream(LoggingHandler.java:332)
INFO | jvm 1 | 2016/08/21 13:19:44 | at org.jboss.netty.channel.DefaultChannelPipeline.sendUpstream(DefaultChannelPipeline.java:564)
INFO | jvm 1 | 2016/08/21 13:19:44 | at org.jboss.netty.channel.DefaultChannelPipeline$DefaultChannelHandlerContext.sendUpstream(DefaultChannelPipeline.java:791)
INFO | jvm 1 | 2016/08/21 13:19:44 | at org.jboss.netty.channel.SimpleChannelHandler.messageReceived(SimpleChannelHandler.java:142)
INFO | jvm 1 | 2016/08/21 13:19:44 | at org.jboss.netty.channel.SimpleChannelHandler.handleUpstream(SimpleChannelHandler.java:88)
INFO | jvm 1 | 2016/08/21 13:19:44 | at org.jboss.netty.channel.DefaultChannelPipeline.sendUpstream(DefaultChannelPipeline.java:564)
INFO | jvm 1 | 2016/08/21 13:19:44 | at org.jboss.netty.channel.DefaultChannelPipeline.sendUpstream(DefaultChannelPipeline.java:559)
INFO | jvm 1 | 2016/08/21 13:19:44 | at org.jboss.netty.channel.Channels.fireMessageReceived(Channels.java:268)
INFO | jvm 1 | 2016/08/21 13:19:44 | at org.jboss.netty.channel.Channels.fireMessageReceived(Channels.java:255)
INFO | jvm 1 | 2016/08/21 13:19:44 | at org.jboss.netty.channel.socket.nio.NioWorker.read(NioWorker.java:88)
INFO | jvm 1 | 2016/08/21 13:19:44 | at org.jboss.netty.channel.socket.nio.AbstractNioWorker.process(AbstractNioWorker.java:108)
INFO | jvm 1 | 2016/08/21 13:19:44 | at org.jboss.netty.channel.socket.nio.AbstractNioSelector.run(AbstractNioSelector.java:337)
INFO | jvm 1 | 2016/08/21 13:19:44 | at org.jboss.netty.channel.socket.nio.AbstractNioWorker.run(AbstractNioWorker.java:89)
INFO | jvm 1 | 2016/08/21 13:19:44 | at org.jboss.netty.channel.socket.nio.NioWorker.run(NioWorker.java:178)
INFO | jvm 1 | 2016/08/21 13:19:44 | at org.jboss.netty.util.ThreadRenamingRunnable.run(ThreadRenamingRunnable.java:108)
INFO | jvm 1 | 2016/08/21 13:19:44 | at org.jboss.netty.util.internal.DeadLockProofWorker$1.run(DeadLockProofWorker.java:42)
INFO | jvm 1 | 2016/08/21 13:19:44 | at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1145)
INFO | jvm 1 | 2016/08/21 13:19:44 | at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:615)
INFO | jvm 1 | 2016/08/21 13:19:44 | at java.lang.Thread.run(Thread.java:745)
INFO | jvm 1 | 2016/08/21 13:19:44 | Caused by: java.io.EOFException: Can not read response from server. Expected to read 4 bytes, read 0 bytes before connection was unexpectedly lost.
INFO | jvm 1 | 2016/08/21 13:19:44 | at com.mysql.jdbc.MysqlIO.readFully(MysqlIO.java:3004)
INFO | jvm 1 | 2016/08/21 13:19:44 | at com.mysql.jdbc.MysqlIO.reuseAndReadPacket(MysqlIO.java:3462)
INFO | jvm 1 | 2016/08/21 13:19:44 | ... 45 more
STATUS | wrapper | 2016/08/21 13:19:47 | TERM trapped. Shutting down.
INFO | jvm 1 | 2016/08/21 13:19:47 | [Thread-10] INFO org.eclipse.jetty.server.ServerConnector - Stopped ServerConnector@650c234c{HTTP/1.1}{0.0.0.0:8667}
INFO | jvm 1 | 2016/08/21 13:19:47 | [Thread-10] INFO org.eclipse.jetty.server.handler.ContextHandler - Stopped o.e.j.s.ServletContextHandler@43b34c70{/api,null,UNAVAILABLE}
ERROR | wrapper | 2016/08/21 13:20:06 | Shutdown failed: Timed out waiting for the JVM to terminate.
ERROR | wrapper | 2016/08/21 13:20:06 | JVM did not exit on request, termination requested.
STATUS | wrapper | 2016/08/21 13:20:06 | JVM received a signal SIGKILL (9).
STATUS | wrapper | 2016/08/21 13:20:06 | JVM process is gone.
STATUS | wrapper | 2016/08/21 13:20:06 | JVM exited after being requested to terminate.
STATUS | wrapper | 2016/08/21 13:20:06 | <-- Wrapper Stopped
STATUS | wrapper | 2016/08/21 13:20:10 | --> Wrapper Started as Daemon
STATUS | wrapper | 2016/08/21 13:20:10 | Java Service Wrapper Community Edition 64-bit 3.5.28
STATUS | wrapper | 2016/08/21 13:20:10 | Copyright (C) 1999-2016 Tanuki Software, Ltd. All Rights Reserved.
STATUS | wrapper | 2016/08/21 13:20:10 | http://wrapper.tanukisoftware.com
STATUS | wrapper | 2016/08/21 13:20:10 |
Does one of the instances use MySQL database remotely?
No Anton., Both Instances are running seperately on its own, no remote database nothing. its each on their own VPS Instance.
The clone thing I mentioned, as Instance 1 has problems (While Instance 2 does not have problem, although Instance 2 is a copy of instance1 itself).
There is no change in both setups actually.
Well, this error means that there was some problem with connection to MySQL. Possibly it timed out or there is just some MySQL or network configuration problem.
I am trying to figure it out, because the initial startup query of traccar just keeps showing active for 40 + minutes,. and all other settings are same configurations to,. I was thinking of trying few things.
I have checked, all other queries after the startup query performs and works well.
This is the status of wrapper and traccar log, when server is starting during that 30 minutes or so.
and MySQL is this way.
What if you manually run that query? I don't really understand why it takes so much time.
SELECT * FROM positions WHERE id IN ( SELECT positionId FROM devices );
The query above, I ran manually, and its over 15 minutes still loading :( not executed.
That would mean, Its something to do with the MySQL DB right?
How many devices do you have? I just tested it on the demo server and it works OK. Less than a minute.
Dear Anton,
I am attaching wrapper log, after the server traccar starts/completes.
Same setup with 4 times more devices loads faster, like I said in the post before this.
But just now I got complete wrapper log, Not sure if it wold help.
STATUS | wrapper | 2016/08/22 18:54:24 | --> Wrapper Started as Daemon
STATUS | wrapper | 2016/08/22 18:54:24 | Java Service Wrapper Community Edition 64-bit 3.5.28
STATUS | wrapper | 2016/08/22 18:54:24 | Copyright (C) 1999-2016 Tanuki Software, Ltd. All Rights Reserved.
STATUS | wrapper | 2016/08/22 18:54:24 | http://wrapper.tanukisoftware.com
STATUS | wrapper | 2016/08/22 18:54:24 |
STATUS | wrapper | 2016/08/22 18:54:25 | Launching a JVM...
INFO | jvm 1 | 2016/08/22 18:54:25 | WrapperManager: Initializing...
INFO | jvm 1 | 2016/08/22 18:54:25 | [WrapperSimpleAppMain] INFO com.zaxxer.hikari.HikariDataSource - HikariPool-1 - Started.
INFO | jvm 1 | 2016/08/22 18:54:26 | INFO 8/22/16 6:54 PM: liquibase: Clearing database change log checksums
INFO | jvm 1 | 2016/08/22 18:54:26 | INFO 8/22/16 6:54 PM: liquibase: Successfully acquired change log lock
INFO | jvm 1 | 2016/08/22 18:54:26 | INFO 8/22/16 6:54 PM: liquibase: Successfully released change log lock
INFO | jvm 1 | 2016/08/22 18:54:26 | INFO 8/22/16 6:54 PM: liquibase: Successfully acquired change log lock
INFO | jvm 1 | 2016/08/22 18:54:28 | INFO 8/22/16 6:54 PM: liquibase: Reading from gps.DATABASECHANGELOG
INFO | jvm 1 | 2016/08/22 18:54:28 | INFO 8/22/16 6:54 PM: liquibase: Reading from gps.DATABASECHANGELOG
INFO | jvm 1 | 2016/08/22 18:54:28 | INFO 8/22/16 6:54 PM: liquibase: Successfully released change log lock
INFO | jvm 1 | 2016/08/22 18:54:28 | [WrapperSimpleAppMain] INFO org.eclipse.jetty.util.log - Logging initialized @3549ms
INFO | jvm 1 | 2016/08/22 19:46:02 | [WrapperSimpleAppMain] INFO org.eclipse.jetty.server.Server - jetty-9.2.17.v20160517
INFO | jvm 1 | 2016/08/22 19:46:03 | [WrapperSimpleAppMain] INFO org.eclipse.jetty.server.handler.ContextHandler - Started o.e.j.s.ServletContextHandler@531da6d3{/api,null,AVAILABLE}
INFO | jvm 1 | 2016/08/22 19:46:03 | [WrapperSimpleAppMain] INFO org.eclipse.jetty.server.ServerConnector - Started ServerConnector@7739fd54{HTTP/1.1}{0.0.0.0:8667}
INFO | jvm 1 | 2016/08/22 19:46:03 | [WrapperSimpleAppMain] INFO org.eclipse.jetty.server.Server - Started @3098642ms
Try to check query execution plan.
Try to check query execution plan.
Dear Anton,
I checked as you suggested,. the execution plan,. all was same as (The normal working instance)
Then, I tried one thing the other day that is,
I set indexes for positionid in positions table.
After that the query has improved now. it takes less than 30 seconds to startup now.
So sorry, I meant, in devices table for positionid i set indexes
Dear Anton,
I have two same configuration VPS with Ubuntu.
Traccar version 3.5 and MySQL DB
1st Instance of Traccar and 2nd Instance of Traccar is exactly same. (Clone)
However 1st Instance if I shutdown traccar and start it again, it takes a lot of time, to startup. and in MySQL i can see the Query process
SELECT * FROM positions WHERE id IN (SELECT positionId FROM devices);active for long time.2nd Instance of traccar has no issues (There is no difference in version of any software on the OS or any aspect of the hardware/software) its a clone of the 1st Server.
I even upgraded both servers Traccar to 3.6 today, still the 1st Instance starts up with an 30 to 40 minutes delay. One such time, when the service was starting up and for long it did not, I rebooted the machine, here is the wrapper log from that moment.
Is there anything in the log that might help? Please advice.