Opened 3 years ago

Last modified 3 years ago

#1725 testing defect

Router console appears to be inaccessible before the time is synched

Reported by: killyourtv Owned by:
Priority: minor Milestone: undecided
Component: router/general Version: 0.9.23
Keywords: Cc:
Parent Tickets:

Description

Found with 0.9.23 with the netdb deadlock fix backported

What I'm seeing is that occasionally the router console will not be accessible if there's a problem reaching the SNTP servers. In the case below the router console wasn't reachable a minute after I2P's start. This may be acceptable.

In cases of extreme network problems I2P's router console may be inaccessible for several minutes while it's trying to reach the time servers. Or, it /seems/ that it's having a problem reaching the time servers.

On my own box I've seen I2P appear to be hung for five minutes or so. The network was also messed up at the time (to put it lightly). Once the NTP communication error was logged jetty was loaded and the router console could be reached.

2015/12/09 03:49:42 | --> Wrapper Started as Daemon
2015/12/09 03:49:42 | Java Service Wrapper Community Edition 32-bit 3.5.22
2015/12/09 03:49:42 |   Copyright (C) 1999-2013 Tanuki Software, Ltd. All Rights Reserved.
2015/12/09 03:49:42 |     http://wrapper.tanukisoftware.com
2015/12/09 03:49:42 | 
2015/12/09 03:49:42 | Launching a JVM...
2015/12/09 03:49:43 | WrapperManager: Initializing...
2015/12/09 03:49:43 | Starting I2P 0.9.23-1-2~deb8u+1
2015/12/09 03:49:43 | INFO: Native CPUID library jcpuid-x86-linux loaded from file
2015/12/09 03:49:43 | INFO: Locally optimized native BigInteger library loaded from file
2015/12/09 03:50:42 | Dumping JVM state.
2015/12/09 03:50:43 | 2015-12-09 03:50:42
2015/12/09 03:50:43 | Full thread dump OpenJDK Client VM (24.91-b01 mixed mode, sharing):
2015/12/09 03:50:43 | 
2015/12/09 03:50:43 | "JobQueue 1/1" prio=10 tid=0xf2d22000 nid=0x22d8 waiting on condition [0xf2bbe000]
2015/12/09 03:50:43 |    java.lang.Thread.State: WAITING (parking)
2015/12/09 03:50:43 | 	at sun.misc.Unsafe.park(Native Method)
2015/12/09 03:50:43 | 	- parking to wait for  <0xc9707f20> (a java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject)
2015/12/09 03:50:43 | 	at java.util.concurrent.locks.LockSupport.park(LockSupport.java:186)
2015/12/09 03:50:43 | 	at java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject.await(AbstractQueuedSynchronizer.java:2043)
2015/12/09 03:50:43 | 	at java.util.concurrent.LinkedBlockingQueue.take(LinkedBlockingQueue.java:442)
2015/12/09 03:50:43 | 	at net.i2p.router.JobQueue.getNext(JobQueue.java:464)
2015/12/09 03:50:43 | 	at net.i2p.router.JobQueueRunner.run(JobQueueRunner.java:44)
2015/12/09 03:50:43 | 
2015/12/09 03:50:43 | "RouterWatchdog" daemon prio=10 tid=0xf2d1f800 nid=0x22d7 waiting on condition [0xf2c0e000]
2015/12/09 03:50:43 |    java.lang.Thread.State: TIMED_WAITING (sleeping)
2015/12/09 03:50:43 | 	at java.lang.Thread.sleep(Native Method)
2015/12/09 03:50:43 | 	at net.i2p.router.tasks.RouterWatchdog.run(RouterWatchdog.java:127)
2015/12/09 03:50:43 | 	at java.lang.Thread.run(Thread.java:745)
2015/12/09 03:50:43 | 	at net.i2p.util.I2PThread.run(I2PThread.java:100)
2015/12/09 03:50:43 | 
2015/12/09 03:50:43 | "Graceful ShutdownHook" daemon prio=10 tid=0xf2d1e000 nid=0x22d6 in Object.wait() [0xf2c5e000]
2015/12/09 03:50:43 |    java.lang.Thread.State: WAITING (on object monitor)
2015/12/09 03:50:43 | 	at java.lang.Object.wait(Native Method)
2015/12/09 03:50:43 | 	- waiting on <0xc6913838> (a net.i2p.util.I2PAppThread)
2015/12/09 03:50:43 | 	at java.lang.Object.wait(Object.java:503)
2015/12/09 03:50:43 | 	at net.i2p.router.tasks.GracefulShutdown.run(GracefulShutdown.java:53)
2015/12/09 03:50:43 | 	- locked <0xc6913838> (a net.i2p.util.I2PAppThread)
2015/12/09 03:50:43 | 	at java.lang.Thread.run(Thread.java:745)
2015/12/09 03:50:43 | 	at net.i2p.util.I2PThread.run(I2PThread.java:100)
2015/12/09 03:50:43 | 
2015/12/09 03:50:43 | "Tunnel GW pumper 4/4" daemon prio=10 tid=0xf2d0e000 nid=0x22d5 in Object.wait() [0xf2cae000]
2015/12/09 03:50:43 |    java.lang.Thread.State: WAITING (on object monitor)
2015/12/09 03:50:43 | 	at java.lang.Object.wait(Native Method)
2015/12/09 03:50:43 | 	- waiting on <0xc97847a0> (a java.util.LinkedHashSet)
2015/12/09 03:50:43 | 	at java.lang.Object.wait(Object.java:503)
2015/12/09 03:50:43 | 	at net.i2p.router.tunnel.TunnelGatewayPumper.run(TunnelGatewayPumper.java:91)
2015/12/09 03:50:43 | 	- locked <0xc97847a0> (a java.util.LinkedHashSet)
2015/12/09 03:50:43 | 	at java.lang.Thread.run(Thread.java:745)
2015/12/09 03:50:43 | 	at net.i2p.util.I2PThread.run(I2PThread.java:100)
2015/12/09 03:50:43 | 
2015/12/09 03:50:43 | "Tunnel GW pumper 3/4" daemon prio=10 tid=0xf2d0c400 nid=0x22d4 in Object.wait() [0xf2cfe000]
2015/12/09 03:50:43 |    java.lang.Thread.State: WAITING (on object monitor)
2015/12/09 03:50:43 | 	at java.lang.Object.wait(Native Method)
2015/12/09 03:50:43 | 	- waiting on <0xc97847a0> (a java.util.LinkedHashSet)
2015/12/09 03:50:43 | 	at java.lang.Object.wait(Object.java:503)
2015/12/09 03:50:43 | 	at net.i2p.router.tunnel.TunnelGatewayPumper.run(TunnelGatewayPumper.java:91)
2015/12/09 03:50:43 | 	- locked <0xc97847a0> (a java.util.LinkedHashSet)
2015/12/09 03:50:43 | 	at java.lang.Thread.run(Thread.java:745)
2015/12/09 03:50:43 | 	at net.i2p.util.I2PThread.run(I2PThread.java:100)
2015/12/09 03:50:43 | 
2015/12/09 03:50:43 | "Tunnel GW pumper 2/4" daemon prio=10 tid=0xf2d0ac00 nid=0x22d3 in Object.wait() [0xf2e85000]
2015/12/09 03:50:43 |    java.lang.Thread.State: WAITING (on object monitor)
2015/12/09 03:50:43 | 	at java.lang.Object.wait(Native Method)
2015/12/09 03:50:43 | 	- waiting on <0xc97847a0> (a java.util.LinkedHashSet)
2015/12/09 03:50:43 | 	at java.lang.Object.wait(Object.java:503)
2015/12/09 03:50:43 | 	at net.i2p.router.tunnel.TunnelGatewayPumper.run(TunnelGatewayPumper.java:91)
2015/12/09 03:50:43 | 	- locked <0xc97847a0> (a java.util.LinkedHashSet)
2015/12/09 03:50:43 | 	at java.lang.Thread.run(Thread.java:745)
2015/12/09 03:50:43 | 	at net.i2p.util.I2PThread.run(I2PThread.java:100)
2015/12/09 03:50:43 | 
2015/12/09 03:50:43 | "Tunnel GW pumper 1/4" daemon prio=10 tid=0xf2d05400 nid=0x22d2 in Object.wait() [0xf2ed5000]
2015/12/09 03:50:43 |    java.lang.Thread.State: WAITING (on object monitor)
2015/12/09 03:50:43 | 	at java.lang.Object.wait(Native Method)
2015/12/09 03:50:43 | 	- waiting on <0xc97847a0> (a java.util.LinkedHashSet)
2015/12/09 03:50:43 | 	at java.lang.Object.wait(Object.java:503)
2015/12/09 03:50:43 | 	at net.i2p.router.tunnel.TunnelGatewayPumper.run(TunnelGatewayPumper.java:91)
2015/12/09 03:50:43 | 	- locked <0xc97847a0> (a java.util.LinkedHashSet)
2015/12/09 03:50:43 | 	at java.lang.Thread.run(Thread.java:745)
2015/12/09 03:50:43 | 	at net.i2p.util.I2PThread.run(I2PThread.java:100)
2015/12/09 03:50:43 | 
2015/12/09 03:50:43 | "BWRefiller" daemon prio=10 tid=0xf42ed000 nid=0x22d1 waiting on condition [0xf2f25000]
2015/12/09 03:50:43 |    java.lang.Thread.State: TIMED_WAITING (sleeping)
2015/12/09 03:50:43 | 	at java.lang.Thread.sleep(Native Method)
2015/12/09 03:50:43 | 	at net.i2p.router.transport.FIFOBandwidthRefiller.run(FIFOBandwidthRefiller.java:117)
2015/12/09 03:50:43 | 	at java.lang.Thread.run(Thread.java:745)
2015/12/09 03:50:43 | 	at net.i2p.util.I2PThread.run(I2PThread.java:100)
2015/12/09 03:50:43 | 
2015/12/09 03:50:43 | "Job Queue Pumper" daemon prio=10 tid=0xf42bc000 nid=0x22d0 in Object.wait() [0xf2f75000]
2015/12/09 03:50:43 |    java.lang.Thread.State: TIMED_WAITING (on object monitor)
2015/12/09 03:50:43 | 	at java.lang.Object.wait(Native Method)
2015/12/09 03:50:43 | 	- waiting on <0xc96d2f20> (a java.lang.Object)
2015/12/09 03:50:43 | 	at net.i2p.router.JobQueue$QueuePumper.run(JobQueue.java:590)
2015/12/09 03:50:43 | 	- locked <0xc96d2f20> (a java.lang.Object)
2015/12/09 03:50:43 | 	at java.lang.Thread.run(Thread.java:745)
2015/12/09 03:50:43 | 	at net.i2p.util.I2PThread.run(I2PThread.java:100)
2015/12/09 03:50:43 | 
2015/12/09 03:50:43 | "YK Precalc" daemon prio=10 tid=0xf42b7800 nid=0x22cf waiting on condition [0xf2fc5000]
2015/12/09 03:50:43 |    java.lang.Thread.State: TIMED_WAITING (sleeping)
2015/12/09 03:50:43 | 	at java.lang.Thread.sleep(Native Method)
2015/12/09 03:50:43 | 	at net.i2p.crypto.YKGenerator$YKPrecalcRunner.run(YKGenerator.java:233)
2015/12/09 03:50:43 | 	at java.lang.Thread.run(Thread.java:745)
2015/12/09 03:50:43 | 	at net.i2p.util.I2PThread.run(I2PThread.java:100)
2015/12/09 03:50:43 | 
2015/12/09 03:50:43 | "PRNG" daemon prio=10 tid=0xf4243c00 nid=0x22ce waiting on condition [0xf343f000]
2015/12/09 03:50:43 |    java.lang.Thread.State: WAITING (parking)
2015/12/09 03:50:43 | 	at sun.misc.Unsafe.park(Native Method)
2015/12/09 03:50:43 | 	- parking to wait for  <0xc957d638> (a java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject)
2015/12/09 03:50:43 | 	at java.util.concurrent.locks.LockSupport.park(LockSupport.java:186)
2015/12/09 03:50:43 | 	at java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject.await(AbstractQueuedSynchronizer.java:2043)
2015/12/09 03:50:43 | 	at java.util.concurrent.LinkedBlockingQueue.take(LinkedBlockingQueue.java:442)
2015/12/09 03:50:43 | 	at gnu.crypto.prng.AsyncFortunaStandalone.run(AsyncFortunaStandalone.java:134)
2015/12/09 03:50:43 | 	at java.lang.Thread.run(Thread.java:745)
2015/12/09 03:50:43 | 	at net.i2p.util.I2PThread.run(I2PThread.java:100)
2015/12/09 03:50:43 | 
2015/12/09 03:50:43 | "SimpleTimer2 4/4" daemon prio=10 tid=0xf423c000 nid=0x22cc waiting on condition [0xf348f000]
2015/12/09 03:50:43 |    java.lang.Thread.State: WAITING (parking)
2015/12/09 03:50:43 | 	at sun.misc.Unsafe.park(Native Method)
2015/12/09 03:50:43 | 	- parking to wait for  <0xc9566060> (a java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject)
2015/12/09 03:50:43 | 	at java.util.concurrent.locks.LockSupport.park(LockSupport.java:186)
2015/12/09 03:50:43 | 	at java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject.await(AbstractQueuedSynchronizer.java:2043)
2015/12/09 03:50:43 | 	at java.util.concurrent.ScheduledThreadPoolExecutor$DelayedWorkQueue.take(ScheduledThreadPoolExecutor.java:1085)
2015/12/09 03:50:43 | 	at java.util.concurrent.ScheduledThreadPoolExecutor$DelayedWorkQueue.take(ScheduledThreadPoolExecutor.java:807)
2015/12/09 03:50:43 | 	at java.util.concurrent.ThreadPoolExecutor.getTask(ThreadPoolExecutor.java:1068)
2015/12/09 03:50:43 | 	at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1130)
2015/12/09 03:50:43 | 	at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:615)
2015/12/09 03:50:43 | 	at java.lang.Thread.run(Thread.java:745)
2015/12/09 03:50:43 | 
2015/12/09 03:50:43 | "SimpleTimer2 3/4" daemon prio=10 tid=0xf423a400 nid=0x22cb waiting on condition [0xf34df000]
2015/12/09 03:50:43 |    java.lang.Thread.State: TIMED_WAITING (parking)
2015/12/09 03:50:43 | 	at sun.misc.Unsafe.park(Native Method)
2015/12/09 03:50:43 | 	- parking to wait for  <0xc9566060> (a java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject)
2015/12/09 03:50:43 | 	at java.util.concurrent.locks.LockSupport.parkNanos(LockSupport.java:226)
2015/12/09 03:50:43 | 	at java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject.awaitNanos(AbstractQueuedSynchronizer.java:2082)
2015/12/09 03:50:43 | 	at java.util.concurrent.ScheduledThreadPoolExecutor$DelayedWorkQueue.take(ScheduledThreadPoolExecutor.java:1090)
2015/12/09 03:50:43 | 	at java.util.concurrent.ScheduledThreadPoolExecutor$DelayedWorkQueue.take(ScheduledThreadPoolExecutor.java:807)
2015/12/09 03:50:43 | 	at java.util.concurrent.ThreadPoolExecutor.getTask(ThreadPoolExecutor.java:1068)
2015/12/09 03:50:43 | 	at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1130)
2015/12/09 03:50:43 | 	at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:615)
2015/12/09 03:50:43 | 	at java.lang.Thread.run(Thread.java:745)
2015/12/09 03:50:43 | 
2015/12/09 03:50:43 | "SimpleTimer2 2/4" daemon prio=10 tid=0xf4238c00 nid=0x22ca waiting on condition [0xf352f000]
2015/12/09 03:50:43 |    java.lang.Thread.State: WAITING (parking)
2015/12/09 03:50:43 | 	at sun.misc.Unsafe.park(Native Method)
2015/12/09 03:50:43 | 	- parking to wait for  <0xc9566060> (a java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject)
2015/12/09 03:50:43 | 	at java.util.concurrent.locks.LockSupport.park(LockSupport.java:186)
2015/12/09 03:50:43 | 	at java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject.await(AbstractQueuedSynchronizer.java:2043)
2015/12/09 03:50:43 | 	at java.util.concurrent.ScheduledThreadPoolExecutor$DelayedWorkQueue.take(ScheduledThreadPoolExecutor.java:1085)
2015/12/09 03:50:43 | 	at java.util.concurrent.ScheduledThreadPoolExecutor$DelayedWorkQueue.take(ScheduledThreadPoolExecutor.java:807)
2015/12/09 03:50:43 | 	at java.util.concurrent.ThreadPoolExecutor.getTask(ThreadPoolExecutor.java:1068)
2015/12/09 03:50:43 | 	at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1130)
2015/12/09 03:50:43 | 	at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:615)
2015/12/09 03:50:43 | 	at java.lang.Thread.run(Thread.java:745)
2015/12/09 03:50:43 | 
2015/12/09 03:50:43 | "SimpleTimer2 1/4" daemon prio=10 tid=0xf4237400 nid=0x22c9 waiting on condition [0xf357f000]
2015/12/09 03:50:43 |    java.lang.Thread.State: WAITING (parking)
2015/12/09 03:50:43 | 	at sun.misc.Unsafe.park(Native Method)
2015/12/09 03:50:43 | 	- parking to wait for  <0xc9566060> (a java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject)
2015/12/09 03:50:43 | 	at java.util.concurrent.locks.LockSupport.park(LockSupport.java:186)
2015/12/09 03:50:43 | 	at java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject.await(AbstractQueuedSynchronizer.java:2043)
2015/12/09 03:50:43 | 	at java.util.concurrent.ScheduledThreadPoolExecutor$DelayedWorkQueue.take(ScheduledThreadPoolExecutor.java:1085)
2015/12/09 03:50:43 | 	at java.util.concurrent.ScheduledThreadPoolExecutor$DelayedWorkQueue.take(ScheduledThreadPoolExecutor.java:807)
2015/12/09 03:50:43 | 	at java.util.concurrent.ThreadPoolExecutor.getTask(ThreadPoolExecutor.java:1068)
2015/12/09 03:50:43 | 	at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1130)
2015/12/09 03:50:43 | 	at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:615)
2015/12/09 03:50:43 | 	at java.lang.Thread.run(Thread.java:745)
2015/12/09 03:50:43 | 
2015/12/09 03:50:43 | "LogWriter" daemon prio=10 tid=0xf4230c00 nid=0x22c8 in Object.wait() [0xf35cf000]
2015/12/09 03:50:43 |    java.lang.Thread.State: TIMED_WAITING (on object monitor)
2015/12/09 03:50:43 | 	at java.lang.Object.wait(Native Method)
2015/12/09 03:50:43 | 	- waiting on <0xc9566450> (a net.i2p.util.LogWriter)
2015/12/09 03:50:43 | 	at net.i2p.util.LogWriterBase.flushRecords(LogWriterBase.java:120)
2015/12/09 03:50:43 | 	- locked <0xc9566450> (a net.i2p.util.LogWriter)
2015/12/09 03:50:43 | 	at net.i2p.util.LogWriterBase.flushRecords(LogWriterBase.java:85)
2015/12/09 03:50:43 | 	at net.i2p.util.LogWriterBase.run(LogWriterBase.java:74)
2015/12/09 03:50:43 | 	at java.lang.Thread.run(Thread.java:745)
2015/12/09 03:50:43 | 	at net.i2p.util.I2PThread.run(I2PThread.java:100)
2015/12/09 03:50:43 | 
2015/12/09 03:50:43 | "Timestamper" daemon prio=10 tid=0xf4226400 nid=0x22c7 runnable [0xf361f000]
2015/12/09 03:50:43 |    java.lang.Thread.State: RUNNABLE
2015/12/09 03:50:43 | 	at java.net.Inet6AddressImpl.lookupAllHostAddr(Native Method)
2015/12/09 03:50:43 | 	at java.net.InetAddress$1.lookupAllHostAddr(InetAddress.java:922)
2015/12/09 03:50:43 | 	at java.net.InetAddress.getAddressesFromNameService(InetAddress.java:1316)
2015/12/09 03:50:43 | 	at java.net.InetAddress.getAllByName0(InetAddress.java:1269)
2015/12/09 03:50:43 | 	at java.net.InetAddress.getAllByName(InetAddress.java:1185)
2015/12/09 03:50:43 | 	at java.net.InetAddress.getAllByName(InetAddress.java:1119)
2015/12/09 03:50:43 | 	at java.net.InetAddress.getByName(InetAddress.java:1069)
2015/12/09 03:50:43 | 	at net.i2p.router.time.NtpClient.currentTimeAndStratum(NtpClient.java:125)
2015/12/09 03:50:43 | 	at net.i2p.router.time.NtpClient.currentTimeAndStratum(NtpClient.java:96)
2015/12/09 03:50:43 | 	at net.i2p.router.time.RouterTimestamper.queryTime(RouterTimestamper.java:275)
2015/12/09 03:50:43 | 	at net.i2p.router.time.RouterTimestamper.run(RouterTimestamper.java:182)
2015/12/09 03:50:43 | 	at java.lang.Thread.run(Thread.java:745)
2015/12/09 03:50:43 | 	at net.i2p.util.I2PThread.run(I2PThread.java:100)
2015/12/09 03:50:43 | 
2015/12/09 03:50:43 | "WrapperSimpleAppMain" prio=10 tid=0x08aff000 nid=0x22c3 in Object.wait() [0xf366f000]
2015/12/09 03:50:43 |    java.lang.Thread.State: WAITING (on object monitor)
2015/12/09 03:50:43 | 	at java.lang.Object.wait(Native Method)
2015/12/09 03:50:43 | 	- waiting on <0xc9566580> (a net.i2p.router.time.RouterTimestamper)
2015/12/09 03:50:43 | 	at java.lang.Object.wait(Object.java:503)
2015/12/09 03:50:43 | 	at net.i2p.router.time.RouterTimestamper.waitForInitialization(RouterTimestamper.java:144)
2015/12/09 03:50:43 | 	- locked <0xc9566580> (a net.i2p.router.time.RouterTimestamper)
2015/12/09 03:50:43 | 	at net.i2p.router.Router.runRouter(Router.java:603)
2015/12/09 03:50:43 | 	- locked <0xc934c1d0> (a net.i2p.router.Router)
2015/12/09 03:50:43 | 	at net.i2p.router.Router.main(Router.java:1531)
2015/12/09 03:50:43 | 	at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
2015/12/09 03:50:43 | 	at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:57)
2015/12/09 03:50:43 | 	at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
2015/12/09 03:50:43 | 	at java.lang.reflect.Method.invoke(Method.java:606)
2015/12/09 03:50:43 | 	at org.tanukisoftware.wrapper.WrapperSimpleApp.run(WrapperSimpleApp.java:290)
2015/12/09 03:50:43 | 	at java.lang.Thread.run(Thread.java:745)
2015/12/09 03:50:43 | 
2015/12/09 03:50:43 | "DestroyJavaVM" prio=10 tid=0xf6708800 nid=0x22a6 waiting on condition [0x00000000]
2015/12/09 03:50:43 |    java.lang.Thread.State: RUNNABLE
2015/12/09 03:50:43 | 
2015/12/09 03:50:43 | "Wrapper-Connection" daemon prio=10 tid=0xf3b28c00 nid=0x22b6 runnable [0xf370f000]
2015/12/09 03:50:43 |    java.lang.Thread.State: RUNNABLE
2015/12/09 03:50:43 | 	at java.net.SocketInputStream.socketRead0(Native Method)
2015/12/09 03:50:43 | 	at java.net.SocketInputStream.read(SocketInputStream.java:152)
2015/12/09 03:50:43 | 	at java.net.SocketInputStream.read(SocketInputStream.java:122)
2015/12/09 03:50:43 | 	at java.net.SocketInputStream.read(SocketInputStream.java:210)
2015/12/09 03:50:43 | 	at java.io.DataInputStream.readByte(DataInputStream.java:265)
2015/12/09 03:50:43 | 	at org.tanukisoftware.wrapper.WrapperManager.handleBackend(WrapperManager.java:5254)
2015/12/09 03:50:43 | 	at org.tanukisoftware.wrapper.WrapperManager.run(WrapperManager.java:5631)
2015/12/09 03:50:43 | 	at java.lang.Thread.run(Thread.java:745)
2015/12/09 03:50:43 | 
2015/12/09 03:50:43 | "Wrapper-Control-Event-Monitor" daemon prio=10 tid=0xf3b33400 nid=0x22b1 waiting on condition [0xf37af000]
2015/12/09 03:50:43 |    java.lang.Thread.State: TIMED_WAITING (sleeping)
2015/12/09 03:50:43 | 	at java.lang.Thread.sleep(Native Method)
2015/12/09 03:50:43 | 	at org.tanukisoftware.wrapper.WrapperManager$3.run(WrapperManager.java:1034)
2015/12/09 03:50:43 | 
2015/12/09 03:50:43 | "Service Thread" daemon prio=10 tid=0xf674f800 nid=0x22ac runnable [0x00000000]
2015/12/09 03:50:43 |    java.lang.Thread.State: RUNNABLE
2015/12/09 03:50:43 | 
2015/12/09 03:50:43 | "C1 CompilerThread0" daemon prio=10 tid=0xf674d800 nid=0x22ab waiting on condition [0x00000000]
2015/12/09 03:50:43 |    java.lang.Thread.State: RUNNABLE
2015/12/09 03:50:43 | 
2015/12/09 03:50:43 | "Signal Dispatcher" daemon prio=10 tid=0xf674c000 nid=0x22aa waiting on condition [0x00000000]
2015/12/09 03:50:43 |    java.lang.Thread.State: RUNNABLE
2015/12/09 03:50:43 | 
2015/12/09 03:50:43 | "Finalizer" daemon prio=10 tid=0xf6734400 nid=0x22a9 in Object.wait() [0xf41fe000]
2015/12/09 03:50:43 |    java.lang.Thread.State: WAITING (on object monitor)
2015/12/09 03:50:43 | 	at java.lang.Object.wait(Native Method)
2015/12/09 03:50:43 | 	- waiting on <0xc934c6e0> (a java.lang.ref.ReferenceQueue$Lock)
2015/12/09 03:50:43 | 	at java.lang.ref.ReferenceQueue.remove(ReferenceQueue.java:135)
2015/12/09 03:50:43 | 	- locked <0xc934c6e0> (a java.lang.ref.ReferenceQueue$Lock)
2015/12/09 03:50:43 | 	at java.lang.ref.ReferenceQueue.remove(ReferenceQueue.java:151)
2015/12/09 03:50:43 | 	at java.lang.ref.Finalizer$FinalizerThread.run(Finalizer.java:209)
2015/12/09 03:50:43 | 
2015/12/09 03:50:43 | "Reference Handler" daemon prio=10 tid=0xf6732c00 nid=0x22a8 in Object.wait() [0xf4376000]
2015/12/09 03:50:43 |    java.lang.Thread.State: WAITING (on object monitor)
2015/12/09 03:50:43 | 	at java.lang.Object.wait(Native Method)
2015/12/09 03:50:43 | 	- waiting on <0xc934c770> (a java.lang.ref.Reference$Lock)
2015/12/09 03:50:43 | 	at java.lang.Object.wait(Object.java:503)
2015/12/09 03:50:43 | 	at java.lang.ref.Reference$ReferenceHandler.run(Reference.java:133)
2015/12/09 03:50:43 | 	- locked <0xc934c770> (a java.lang.ref.Reference$Lock)
2015/12/09 03:50:43 | 
2015/12/09 03:50:43 | "VM Thread" prio=10 tid=0xf6731400 nid=0x22a7 runnable 
2015/12/09 03:50:43 | 
2015/12/09 03:50:43 | "VM Periodic Task Thread" prio=10 tid=0xf6752000 nid=0x22ad waiting on condition 
2015/12/09 03:50:43 | 
2015/12/09 03:50:43 | JNI global references: 213
2015/12/09 03:50:43 | 
2015/12/09 03:50:43 | Heap
2015/12/09 03:50:43 |  def new generation   total 4928K, used 1737K [0xc6800000, 0xc6d50000, 0xc92a0000)
2015/12/09 03:50:43 |   eden space 4416K,  38% used [0xc6800000, 0xc69a56c0, 0xc6c50000)
2015/12/09 03:50:43 |   from space 512K,  10% used [0xc6cd0000, 0xc6cdcdb0, 0xc6d50000)
2015/12/09 03:50:43 |   to   space 512K,   0% used [0xc6c50000, 0xc6c50000, 0xc6cd0000)
2015/12/09 03:50:43 |  tenured generation   total 10944K, used 5166K [0xc92a0000, 0xc9d50000, 0xce800000)
2015/12/09 03:50:43 |    the space 10944K,  47% used [0xc92a0000, 0xc97abb88, 0xc97abc00, 0xc9d50000)
2015/12/09 03:50:43 |  compacting perm gen  total 12288K, used 3579K [0xce800000, 0xcf400000, 0xd2800000)
2015/12/09 03:50:43 |    the space 12288K,  29% used [0xce800000, 0xceb7ef30, 0xceb7f000, 0xcf400000)
2015/12/09 03:50:43 |     ro space 10240K,  58% used [0xd2800000, 0xd2de3ed8, 0xd2de4000, 0xd3200000)
2015/12/09 03:50:43 |     rw space 12288K,  59% used [0xd3200000, 0xd391c548, 0xd391c600, 0xd3e00000)
2015/12/09 03:50:43 | 
2015/12/09 03:50:47 | TERM trapped.  Shutting down.
2015/12/09 03:51:03 | Warning: Unable to reach any of the NTP servers [0.us.pool.ntp.org, 1.us.pool.ntp.org, 2.us.pool.ntp.org, 0.north-america.pool.ntp.org, 1.north-america.pool.ntp.org, 2.north-america.pool.ntp.org, 0.pool.ntp.org, 1.pool.ntp.org, 2.pool.ntp.org] - network disconnected? Or set time.sntpServerList=myserver1.com,myserver2.com in advanced configuration.
2015/12/09 03:51:03 | INFO: Jetty 8.1.17.v20150415 logging to I2P logs using class org.eclipse.jetty.server.Server
2015/12/09 03:51:03 | 2015-12-09 03:51:03.807:INFO:oejs.Server:jetty-8.1.17.v20150415
2015/12/09 03:51:03 | CRIT  [r 1 shutdown] net.i2p.router.Router         : Shutting down the router...
2015/12/09 03:51:03 | CRIT  [r 1 shutdown] net.i2p.router.Router         : Starting final shutdown(3)
2015/12/09 03:51:03 | CRIT  [r 1 shutdown] net.i2p.router.Router         : Shutdown(3) complete
2015/12/09 03:51:04 | <-- Wrapper Stopped

Subtickets (add)

Change History (3)

comment:1 Changed 3 years ago by zzz

  • Component changed from unspecified to router/general

Waiting is by design. It shouldn't wait more than a minute, but it may not be foolproof. It is indeed waiting in your thread dump:

2015/12/09 03:50:43 | at net.i2p.router.time.RouterTimestamper?.waitForInitialization(RouterTimestamper?.java:144)

The code waits for 5 seconds for each of up to 9 time servers (3 country, 3 continent, 3 global)

5 minutes is definitely a bug somewhere. I can do an easy fix to set a max wait time. Maybe even a minute is too long... 30 sec better? The goal is to not do a time shift after everything gets going, but we can't wait forever.

comment:2 Changed 3 years ago by zzz

Confirmed, seeing long hangs on my box w/ NTP blocked. Adv. config time.disabled=true fixes. Investigating.

comment:3 Changed 3 years ago by zzz

  • Status changed from new to testing

The very long (permanent) hangs in my recent testing were a result of deadlocks, some caused by code not-yet-checked-in, and possibly some related to #1722 with more fixes coming.

As seen in the OP dump, it's stuck waiting for DNS resolution of the NTP pool hostnames. No idea what the system DNS lookup timeout could be, but that could significantly affect the total time. DNS time is not accounted for in the 5-second timeout described in comment 1. And I don't think there's any way to set the DNS timeout from Java.

Set a 45-second hard max total wait time as described at end of comment 1, in 0ec204c58fa9534f5d85c660d0cfcf2d229407bf 0.9.23-12

Note: See TracTickets for help on using tickets.