Opened 7 years ago

Closed 4 years ago

#566 closed defect (fixed)

Asked for router restart. Result: console hung (seedless sleeping)

Reported by: killyourtv Owned by: sponge
Priority: minor Milestone:
Component: apps/plugins Version: 0.8.11
Keywords: Seedless hang Cc:
Parent Tickets:

Description

I2P version: 0.8.11-20
Java version: Sun Microsystems Inc. 1.6.0_24 (OpenJDK Runtime Environment 1.6.0_24-b24)
Wrapper version: 3.5.13
Server version: Jetty/5.1.15
Platform: Linux amd64 3.1.0-1-amd64
Processor: Athlon 64 FX (Sledgehammer S939, 130 nm) (athlon64)
Jbigi: Locally optimized native BigInteger library loaded from file
Encoding: UTF-8

When attempting to update to 0.8.11-20 (irrelevant, sure) I hit 'Restart' as usual. After it said "Restart imminent" I hit reload in the browser. "Page could not be displayed" or "connection refused" or the like showed. Of course this is normal while the router is restarting and before the console/jetty is started. A minute later I still couldn't load the router console.

So I checked wrapper.log and found


2011/12/12 11:46:03 | INFO: Stopping Acceptor ServerSocket[addr=/0:0:0:0:0:0:0:1,port=0,localport=7657]
2011/12/12 11:46:03 | 12.12.2011 11:46:03 org.mortbay.http.SocketListener stop
2011/12/12 11:46:03 | INFO: Stopped SocketListener on 0:0:0:0:0:0:0:1:7657
2011/12/12 11:46:03 | 12.12.2011 11:46:03 org.mortbay.util.ThreadedServer$Acceptor run
2011/12/12 11:46:03 | INFO: Stopping Acceptor ServerSocket[addr=/127.0.0.1,port=0,localport=7657]
2011/12/12 11:46:03 | 12.12.2011 11:46:03 org.mortbay.http.SocketListener stop
2011/12/12 11:46:03 | INFO: Stopped SocketListener on 127.0.0.1:7657
2011/12/12 11:46:03 | 12.12.2011 11:46:03 org.mortbay.util.Container stop
2011/12/12 11:46:03 | INFO: Stopped org.mortbay.jetty.servlet.WebApplicationHandler@fba0f36
2011/12/12 11:46:03 | 12.12.2011 11:46:03 org.mortbay.util.Container stop
2011/12/12 11:46:03 | INFO: Stopped WebApplicationContext[/i2psnark,/i2psnark]
2011/12/12 11:46:03 | 12.12.2011 11:46:03 org.mortbay.util.Container stop
2011/12/12 11:46:03 | INFO: Stopped org.mortbay.jetty.servlet.WebApplicationHandler@57922f46
2011/12/12 11:46:03 | 12.12.2011 11:46:03 org.mortbay.util.Container stop
2011/12/12 11:46:03 | INFO: Stopped WebApplicationContext[/addressbook,/addressbook]
2011/12/12 11:46:04 | SeedlessCache Exited.

Attached is the rest of wrapper.log, including neodatis "log spam" from before this issue (probably related) and the thread dump.

Subtickets

Attachments (1)

wrapper.log.snippet.gz (17.9 KB) - added by killyourtv 7 years ago.

Download all attachments as: .zip

Change History (18)

Changed 7 years ago by killyourtv

comment:1 Changed 7 years ago by zzz

  • Owner set to sponge
  • Status changed from new to assigned
  • Summary changed from Asked for router restart. Result: console hung to Asked for router restart. Result: console hung (seedless sleeping)

Seedless again. Same issue as #544? Assigning to sponge. As I think I said in that ticket, you should never sleep forever in a listener. Get in and get out.

2011/12/12 11:47:25 | "Graceful shutdown hook" daemon prio=10 tid=0x00007f0618139000 nid=0x344 sleeping[0x00007f061c620000]
2011/12/12 11:47:25 |    java.lang.Thread.State: TIMED_WAITING (sleeping)
2011/12/12 11:47:25 | 	at java.lang.Thread.sleep(Native Method)
2011/12/12 11:47:25 | 	at net.i2p.seedless.console.SeedlessSeedFinderContextListener.contextDestroyed(SeedlessSeedFinderContextListener.java:148)
2011/12/12 11:47:25 | 	at org.mortbay.jetty.servlet.WebApplicationContext.doStop(WebApplicationContext.java:558)
2011/12/12 11:47:25 | 	at org.mortbay.util.Container.stop(Container.java:163)
2011/12/12 11:47:25 | 	- locked <0x00000000f06754e8> (a org.mortbay.jetty.servlet.WebApplicationContext)
2011/12/12 11:47:25 | 	at org.mortbay.http.HttpContext.stop(HttpContext.java:1733)
2011/12/12 11:47:25 | 	at org.mortbay.http.HttpServer.doStop(HttpServer.java:751)
2011/12/12 11:47:25 | 	- locked <0x00000000f031ea50> (a org.mortbay.jetty.Server)
2011/12/12 11:47:25 | 	at org.mortbay.util.Container.stop(Container.java:163)
2011/12/12 11:47:25 | 	- locked <0x00000000f031ea50> (a org.mortbay.jetty.Server)
2011/12/12 11:47:25 | 	at net.i2p.router.web.RouterConsoleRunner$ServerShutdown.run(RouterConsoleRunner.java:509)
2011/12/12 11:47:25 | 	at net.i2p.router.Router.shutdown2(Router.java:1004)
2011/12/12 11:47:25 | 	at net.i2p.router.Router.shutdown(Router.java:979)
2011/12/12 11:47:25 | 	at net.i2p.router.tasks.GracefulShutdown.run(GracefulShutdown.java:41)
2011/12/12 11:47:25 | 	at java.lang.Thread.run(Thread.java:679)
2011/12/12 11:47:25 | 	at net.i2p.util.I2PThread.run(I2PThread.java:85)

comment:2 Changed 7 years ago by zzz

  • Milestone changed from 0.8.12 to 0.8.13

@sponge Please fix this before 0.8.13. Otherwise I will have to implement threading for the plugin shutdown hooks which I really don't want to spend the time doing just to work around your bug. Thanks.

comment:3 Changed 7 years ago by sponge

  • Milestone changed from 0.8.13 to 0.8.14
  • Status changed from assigned to accepted

killyourtv: pull from the darcs or mtn repo, build, test. There is extra debug info sent to the wrapper.log during shutdown in order for me to find the issue.

comment:4 follow-up: Changed 7 years ago by killyourtv

Latest mtn, revision 7a7221188af3966303ef5a52936a2e457c681169

  [exec] -pre-pre-compile:
     [exec]     [mkdir] Created dir: /home/kytv/seedless/SeedlessCore/build/classes
     [exec] 
     [exec] -pre-compile:
     [exec] 
     [exec] -compile-depend:
     [exec] 
     [exec] -do-compile:
     [exec]     [javac] Compiling 34 source files to /home/kytv/seedless/SeedlessCore/build/classes
     [exec]     [javac] Scraper.java:273: unreported exception net.i2p.seedless.classes.DBException; must be caught or declared to be thrown
     [exec]     [javac]                 db.close();
     [exec]     [javac]                         ^
     [exec]     [javac] Scraper.java:383: unreported exception net.i2p.seedless.classes.DBException; must be caught or declared to be thrown
     [exec]     [javac]                 db.close();
     [exec]     [javac]                         ^
     [exec]     [javac] Scraper.java:459: unreported exception net.i2p.seedless.classes.DBException; must be caught or declared to be thrown
     [exec]     [javac]                                     db.close();
     [exec]     [javac]                                             ^
     [exec]     [javac] Scraper.java:491: unreported exception net.i2p.seedless.classes.DBException; must be caught or declared to be thrown
     [exec]     [javac]                         db.close();
     [exec]     [javac]                                 ^
     [exec]     [javac] Note: SeedlessServerAnnouncer.java uses unchecked or unsafe operations.
     [exec]     [javac] Note: Recompile with -Xlint:unchecked for details.
     [exec]     [javac] 4 errors
     [exec] 
     [exec] BUILD FAILED
     [exec] /home/kytv/seedless/SeedlessCore/nbproject/build-impl.xml:341: The following error occurred while executing this line:
     [exec] /home/kytv/seedless/SeedlessCore/nbproject/build-impl.xml:158: Compile failed; see the compiler error output for details.
     [exec] 
     [exec] Total time: 4 seconds

BUILD FAILED
/home/kytv/seedless/build.xml:35: exec returned: 1

Total time: 22 seconds

comment:5 in reply to: ↑ 4 Changed 7 years ago by killyourtv

Replying to killyourtv:

Latest mtn, revision 7a7221188af3966303ef5a52936a2e457c681169

Same errors with the darcs checkout,

Tue Mar 13 22:07:00 UTC 2012  sponge@mail.i2p
  * Try to find CNFE issue and debug shutdown

comment:6 Changed 7 years ago by zzz

  • Milestone changed from 0.8.14 to 0.9.3

As we have no fix after 6 months, I've threaded the router shutdown hooks in 0.9-13.

While this will prevent the shutdown from hanging, it is only a partial fix, as the RouterConsoleRunner? shutdown hook calls the Jetty shutdown (which calls the webapp shutdowns inline) and the plugin shutdowns inline. Thus, when seedless shutdown hangs, any webapp or plugin after it in the shutdown sequence will not get shut down cleanly. Threading the individual plugin shutdowns won't help as this bug is, at least some of the time, happening in the Jetty shutdown.

The recommendation is still, don't infinite loop or infinite sleep in a shutdown hook. including a webapp stop() method. Leaving this ticket open until that is addressed.

comment:7 Changed 7 years ago by guest

  • Version changed from 0.8.11 to 0.9.1

the router now comes down, but won't restart.

System:
I2P version: 0.9.1-1
Java version: Sun Microsystems Inc. 1.6.0_24 (OpenJDK Runtime Environment 1.6.0_24-b24)
Wrapper version: 3.5.12
Server version: 6.1.26
Servlet version: Jasper JSP 2.1 Engine
Platform: Linux amd64 3.1.10-1.16-desktop
Processor: AMD Turion X2/Athlon X2/Sempron (Lion/Sable?, 65 nm) (athlon64)
Jbigi: Locally optimized native BigInteger? library loaded from file
Encoding: UTF-8
Charset: UTF-8

log entries: http://pastethis.i2p/show/1568/

comment:8 follow-up: Changed 7 years ago by guest

also, seedless server often fails starting up correctly, so that the "Please run a server" message on Seedless Console is shown.

comment:9 Changed 7 years ago by guest

same with I2P version 0.9.1-4: http://pastethis.i2p/show/1608/

comment:10 Changed 6 years ago by guest

with 0.9.1-23-rc: http://pastethis.i2p/show/1896/

2012/09/11 21:35:59 | CRIT [r 1 shutdown] net.i2p.router.Router : Shutdown(3) complete
2012/09/11 21:36:48 | Proxy not quite ready yet, will retry in 60 seconds.
2012/09/11 21:36:49 | Seedless.war ERROR: context could not stop threads.
2012/09/11 21:36:50 | Heap
2012/09/11 21:36:50 | PSYoungGen total 148864K, used 34708K [0x00000000f5560000, 0x0000000100000000, 0x0000000100000000)
2012/09/11 21:36:50 | eden space 124096K, 27% used [0x00000000f5560000,0x00000000f771d0e0,0x00000000fce90000)
2012/09/11 21:36:50 | from space 24768K, 0% used [0x00000000fce90000,0x00000000fceb8000,0x00000000fe6c0000)
2012/09/11 21:36:50 | to space 24896K, 0% used [0x00000000fe7b0000,0x00000000fe7b0000,0x0000000100000000)
2012/09/11 21:36:50 | PSOldGen total 131840K, used 117191K [0x00000000e0000000, 0x00000000e80c0000, 0x00000000f5560000)
2012/09/11 21:36:50 | object space 131840K, 88% used [0x00000000e0000000,0x00000000e7271f88,0x00000000e80c0000)
2012/09/11 21:36:50 | PSPermGen total 46208K, used 24115K [0x00000000d5a00000, 0x00000000d8720000, 0x00000000e0000000)
2012/09/11 21:36:50 | object space 46208K, 52% used [0x00000000d5a00000,0x00000000d718cde8,0x00000000d8720000)
2012/09/11 21:36:50 | <-- Wrapper Stopped

comment:11 Changed 6 years ago by guest

Bote NOT running, pure seedless plus server

comment:12 follow-up: Changed 6 years ago by guest

  • Milestone changed from 0.9.3 to 0.9.4
  • Version changed from 0.9.1 to 0.9.2

on 0.9.2-15

2012/10/17 19:45:17 | 85660,217: [GC [PSYoungGen: 272178K->5521K(270976K)] 638850K->374300K(770944K), 0,1004890 secs] [Times: user=0,08 sys=0,00, real=0,10 secs]
2012/10/17 19:46:42 | 85744,609: [GC [PSYoungGen: 270929K->3088K(298560K)] 639708K->373829K(798528K), 0,0702020 secs] [Times: user=0,06 sys=0,00, real=0,08 secs]
2012/10/17 19:47:49 | SeedlessSeedFinder? Trying to Exit.... if it does not exit within 60 seconds, please report on http://trac.i2p2.i2p/ticket/566
2012/10/17 19:47:50 | SeedlessSeedFinder? Now trying to kill child threads...
2012/10/17 19:47:50 | SeedlessCache? Exited.
2012/10/17 19:47:50 | SeedlessSeedFinder? Exited.
2012/10/17 19:47:50 | SeedlessSeedFinder? server context destroyed
2012/10/17 19:47:50 | NeoDatis? server stopping
2012/10/17 19:47:57 | NeoDatis? ODB Server (port 65534) shutdown [uptime=23Hours]
2012/10/17 19:48:04 | 85826,924: [GC [PSYoungGen: 261456K->3939K(255616K)] 632197K->375056K(755584K), 0,1054950 secs] [Times: user=0,07 sys=0,01, real=0,11 secs]
2012/10/17 19:48:11 | CRIT [hutdown hook] net.i2p.router.Router : Restarting after a brief delay
2012/10/17 19:48:11 | CRIT [hutdown hook] net.i2p.router.Router : Starting final shutdown(4)
2012/10/17 19:48:15 | 85838,043: [GC [PSYoungGen: 255587K->544K(283648K)] 626704K->373184K(783616K), 0,1192180 secs] [Times: user=0,07 sys=0,00, real=0,12 secs]
2012/10/17 19:48:21 | 85843,879: [GC [PSYoungGen: 245728K->192K(239168K)] 618368K->373176K(739136K), 0,0225090 secs] [Times: user=0,02 sys=0,01, real=0,02 secs]
2012/10/17 19:48:25 | 85847,596: [GC [PSYoungGen: 239168K->160K(270464K)] 612152K->373168K(770432K), 0,0410840 secs] [Times: user=0,04 sys=0,00, real=0,04 secs]
2012/10/17 19:48:28 | 85851,059: [GC [PSYoungGen: 233120K->160K(227392K)] 606128K->373184K(727360K), 0,0160530 secs] [Times: user=0,01 sys=0,00, real=0,02 secs]
2012/10/17 19:48:30 | Shutdown failed: Timed out waiting for signal from JVM.
2012/10/17 19:48:30 | 85852,840: [GC [PSYoungGen: 227360K->160K(256896K)] 600384K->373208K(756864K), 0,0112100 secs] [Times: user=0,01 sys=0,00, real=0,01 secs]
2012/10/17 19:48:30 | JVM did not exit on request, terminated
2012/10/17 19:48:30 | <-- Wrapper Stopped
user@XYZ:~$

so if Seedless does not stop withing 60s, one's supposed to report back here, yet the router doesn't even seem to give it these 60 s:
2012/10/17 19:47:49 | SeedlessSeedFinder? Trying to Exit.... if it does not exit within 60 seconds, please report on http://trac.i2p2.i2p/ticket/566
2012/10/17 19:48:30 | JVM did not exit on request, terminated
2012/10/17 19:48:30 | <-- Wrapper Stopped
but 19:47:49 +60s => 19:48:49

comment:13 in reply to: ↑ 12 Changed 6 years ago by sponge

Replying to guest:

on 0.9.2-15
2012/10/17 19:47:49 | SeedlessSeedFinder? Trying to Exit.... if it does not exit within 60 seconds, please report on http://trac.i2p2.i2p/ticket/566
2012/10/17 19:47:50 | SeedlessSeedFinder? Now trying to kill child threads...
2012/10/17 19:47:50 | SeedlessCache? Exited.
2012/10/17 19:47:50 | SeedlessSeedFinder? Exited.
2012/10/17 19:47:50 | SeedlessSeedFinder? server context destroyed

...

2012/10/17 19:48:30 | JVM did not exit on request, terminated
2012/10/17 19:48:30 | <-- Wrapper Stopped
but 19:47:49 +60s => 19:48:49

Seedless did fully exit. You need to increase the shutdown wait time. I have seen this exact same problem on slow machines and machines with a high system load.

comment:14 in reply to: ↑ 8 Changed 6 years ago by sponge

Replying to guest:

also, seedless server often fails starting up correctly, so that the "Please run a server" message on Seedless Console is shown.

Ignore the message, if it works after some time. I need to change how the detection works yet.

The latest versions as of this writing are verified to work now even under the worse conditions.

EepAnnouncer version: 00.01.05
SeedlessServer? version: 00.01.05
SeedlessConsole? version: 00.01.0C
SeedlessCore? version: 00.01.07
Neodatis ODB version: 2.1.beta14-209 (21-02-2010-20-30-42) PatchLevel? 17

Please let me know if it works better for you too, and bump up that shutdown delay so i can close this ticket.

comment:15 Changed 6 years ago by str4d

  • Keywords Seedless added
  • Milestone 0.9.4 deleted

comment:16 Changed 5 years ago by killyourtv

  • Version changed from 0.9.2 to 0.8.11

comment:17 Changed 4 years ago by str4d

  • Keywords hang added
  • Resolution set to fixed
  • Status changed from accepted to closed

No response, closing optimistically.

Note: See TracTickets for help on using tickets.