Opened 8 years ago

Closed 7 years ago

#564 closed defect (fixed)

bote/seedless shutdown issues (was: Addressbook should not try to write to a read-only $I2P)

Reported by: killyourtv Owned by: HungryHobo
Priority: major Milestone: 0.9.5
Component: apps/plugins Version: 0.8.11
Keywords: Cc:
Parent Tickets: Sensitive: no

Description

I2P version: 0.8.11-18deb1
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

SeedlessServer version: 00.00.15
SeedlessCore version: 00.00.3B
Neodatis ODB version: 2.1.beta14-209 21-02-2010-20-30-42)PatchLevel 9

After shutting down I2P I noticed the following in my logs

2011/12/10 11:28:17 | SeedlessServer Exited.
2011/12/10 11:28:17 | EepAnnouncer server context destroyed
2011/12/10 11:28:18 | CRIT  [SeedlsScpPrs] .naming.BlockfileNamingService: Failed to initialize database
2011/12/10 11:28:18 | java.io.FileNotFoundException: /usr/share/i2p/hostsdb.blockfile (Permission denied)
2011/12/10 11:28:18 |   at java.io.RandomAccessFile.open(Native Method)

/usr/share/i2p is, of course, a read-only location. On my boxes (without $I2P in a read-only location) the hostdb is kept in i2p.dir.config.

Subtickets

Change History (13)

comment:1 Changed 8 years ago by sponge

Component: apps/pluginsapps/addressbook
Owner: changed from sponge to zzz
Status: newassigned
Summary: Seedless should not try to write to a read-only $I2PAddressbook should not try to write to a read-only $I2P

Does not look like a Seedless error, that's the new addressbook stuff. :-)

comment:2 Changed 8 years ago by zzz

Odd that it's trying to create the blockfile db at shutdown time, and that it's in the SeedlsScpPrs? thread.

kytv, need the rest of the stack trace to see who did it, you apparently truncataed it at RandomAccessFile?.open()

comment:3 Changed 8 years ago by killyourtv

Sorry, this is what I've got (from when the shutdown was initiated until it's complete):

2011/12/10 11:28:06 | INFO: Stopped net.i2p.router.web.LocaleWebAppHandler@561557c0
2011/12/10 11:28:06 | 10.12.2011 11:28:06 org.mortbay.util.Container stop
2011/12/10 11:28:06 | INFO: Stopped WebApplicationContext[/,/]
2011/12/10 11:28:06 | 10.12.2011 11:28:06 org.mortbay.util.Container stop
2011/12/10 11:28:06 | INFO: Stopped org.mortbay.jetty.Server@426295eb
2011/12/10 11:28:06 | NeoDatis server stopping
2011/12/10 11:28:06 | NeoDatis ODB Server (port 65534) shutdown [uptime=73Hours]
2011/12/10 11:28:06 | 10.12.2011 11:28:06 org.mortbay.util.ThreadedServer$Acceptor run
2011/12/10 11:28:06 | INFO: Stopping Acceptor [SSL: ServerSocket[addr=/127.0.0.1,port=0,localport=7650]]
2011/12/10 11:28:06 | Seedlessdb:Error while getting objects for query ((service = torrent and dest = dk7ehb6vbhbt6t3wz64lso6ao2pf7kktufvvm7vejqmb6lbhicra.b32.i2p) and metadata = 850b8dee293e431a345c64b749e55e4931a31241
2011/12/10 11:28:06 | VUZPAAAeQW5vbnltb3VzcZBjcdM=
2011/12/10 11:28:06 | seed)
2011/12/10 11:28:06 | 10.12.2011 11:28:06 org.mortbay.http.SocketListener stop
2011/12/10 11:28:06 | INFO: Stopped SocketListener on 127.0.0.1:7650
2011/12/10 11:28:06 | 10.12.2011 11:28:06 org.mortbay.util.Container stop
2011/12/10 11:28:06 | INFO: Stopped org.mortbay.jetty.servlet.ServletHandler@6ea85b4
2011/12/10 11:28:06 | 10.12.2011 11:28:06 org.mortbay.util.Container stop
2011/12/10 11:28:06 | INFO: Stopped ServletHttpContext[/,/]
2011/12/10 11:28:06 | 10.12.2011 11:28:06 org.mortbay.util.Container stop
2011/12/10 11:28:06 | INFO: Stopped org.mortbay.jetty.Server@2b347d33
2011/12/10 11:28:06 | org.neodatis.odb.NeoDatisRuntimeException: 
2011/12/10 11:28:06 | Version=2.1.beta14 , Build=209, Date=21-02-2010-20-30-42, Thread=Thread-634046
2011/12/10 11:28:06 | Message:Error while reading data for oid ff2c6eb9-040d-4471-9824-30013bf4d8e9@65d88ae5-47fd-4832-adeb-c6070f729733
2011/12/10 11:28:06 | StackTrace:
2011/12/10 11:28:06 | 	at org.neodatis.odb.core.layers.layer4.plugin.jdbm.NeoDatisJdbmPlugin.read(NeoDatisJdbmPlugin.java:58)
2011/12/10 11:28:06 | 	at org.neodatis.odb.core.session.SessionEngineImpl.layer4ToLayer3(SessionEngineImpl.java:353)
2011/12/10 11:28:06 | 	at org.neodatis.odb.core.session.SessionEngineImpl.getFieldValuesFromOid(SessionEngineImpl.java:474)
2011/12/10 11:28:06 | 	at org.neodatis.odb.core.query.criteria.CriteriaQueryExecutor.matchObjectWithOid(CriteriaQueryExecutor.java:86)
2011/12/10 11:28:06 | 	at org.neodatis.odb.core.query.GenericQueryExecutor.executeFullScan(GenericQueryExecutor.java:290)
2011/12/10 11:28:06 | 	at org.neodatis.odb.core.query.GenericQueryExecutor.execute(GenericQueryExecutor.java:168)
2011/12/10 11:28:06 | 	at org.neodatis.odb.core.session.SessionEngineImpl.getMetaObjects(SessionEngineImpl.java:694)
2011/12/10 11:28:06 | 	at org.neodatis.odb.core.server.connection.ClientServerConnection.manageGetObjectsCommand(ClientServerConnection.java:898)
2011/12/10 11:28:06 | 	at org.neodatis.odb.core.server.connection.ClientServerConnection.manageMessage(ClientServerConnection.java:183)
2011/12/10 11:28:06 | 	at org.neodatis.odb.core.server.connection.RemoteClientServerConnection.run(RemoteClientServerConnection.java:91)
2011/12/10 11:28:06 | 	at java.lang.Thread.run(Thread.java:679)
2011/12/10 11:28:06 | Caused by: java.lang.IllegalStateException: RecordManager has been closed
2011/12/10 11:28:06 | 	at jdbm.recman.CacheRecordManager.checkIfClosed(CacheRecordManager.java:445)
2011/12/10 11:28:06 | 	at jdbm.recman.CacheRecordManager.fetch(CacheRecordManager.java:308)
2011/12/10 11:28:06 | 	at jdbm.btree.BTree._fetch(BTree.java:863)
2011/12/10 11:28:06 | 	at jdbm.btree.BTree.getRoot(BTree.java:645)
2011/12/10 11:28:06 | 	at jdbm.btree.BTree.find(BTree.java:435)
2011/12/10 11:28:06 | 	at org.neodatis.odb.core.layers.layer4.plugin.jdbm.PHashMapBTree.get(PHashMapBTree.java:133)
2011/12/10 11:28:06 | 	at org.neodatis.odb.core.layers.layer4.plugin.jdbm.NeoDatisJdbmPlugin.read(NeoDatisJdbmPlugin.java:45)
2011/12/10 11:28:06 | 	... 10 more
2011/12/10 11:28:06 | 
2011/12/10 11:28:06 | Seedlessdb:Server error while closing
2011/12/10 11:28:06 | org.neodatis.odb.NeoDatisRuntimeException: 
2011/12/10 11:28:06 | Version=2.1.beta14 , Build=209, Date=21-02-2010-20-30-42, Thread=Thread-634046
2011/12/10 11:28:06 | NeoDatisError:1004:ODB session has already been closed (session-id=127.0.0.1-1323516486257-0)
2011/12/10 11:28:06 | StackTrace:
2011/12/10 11:28:06 | 	at org.neodatis.odb.core.session.SessionEngineImpl.close(SessionEngineImpl.java:803)
2011/12/10 11:28:06 | 	at org.neodatis.odb.core.session.SessionImpl.close(SessionImpl.java:174)
2011/12/10 11:28:06 | 	at org.neodatis.odb.core.server.connection.ClientServerConnection.manageCloseCommand(ClientServerConnection.java:488)
2011/12/10 11:28:06 | 	at org.neodatis.odb.core.server.connection.ClientServerConnection.manageMessage(ClientServerConnection.java:195)
2011/12/10 11:28:06 | 	at org.neodatis.odb.core.server.connection.RemoteClientServerConnection.run(RemoteClientServerConnection.java:91)
2011/12/10 11:28:06 | 	at java.lang.Thread.run(Thread.java:679)
2011/12/10 11:28:06 | 
2011/12/10 11:28:06 | RemoteClientServerConnection : Client connection is dead : Thread Thread-634046: Error in connection thread baseId=Seedlessdb and cid=null for message of type 'No message' : Client has terminated the connection!
2011/12/10 11:28:06 | Exception in thread "Seedless.Scrape-http://vnmf4apo3mpxitki2nzqjx24cq4ykuiptpdmihgyecomcql5ttaa.b32.i2p/Seedless/seedless" org.neodatis.odb.NeoDatisRuntimeException: 
2011/12/10 11:28:06 | Version=2.1.beta14 , Build=209, Date=21-02-2010-20-30-42, Thread=Seedless.Scrape-http://vnmf4apo3mpxitki2nzqjx24cq4ykuiptpdmihgyecomcql5ttaa.b32.i2p/Seedless/seedless
2011/12/10 11:28:06 | NeoDatisError:280:Server side error Error while getting objects on server side : Seedlessdb:Error while getting objects for query ((service = torrent and dest = dk7ehb6vbhbt6t3wz64lso6ao2pf7kktufvvm7vejqmb6lbhicra.b32.i2p) and metadata = 850b8dee293e431a345c64b749e55e4931a31241
2011/12/10 11:28:06 | VUZPAAAeQW5vbnltb3VzcZBjcdM=
2011/12/10 11:28:06 | seed):
2011/12/10 11:28:06 | org.neodatis.odb.NeoDatisRuntimeException: 
2011/12/10 11:28:06 | Version=2.1.beta14 , Build=209, Date=21-02-2010-20-30-42, Thread=Thread-634046
2011/12/10 11:28:06 | Message:Error while reading data for oid ff2c6eb9-040d-4471-9824-30013bf4d8e9@65d88ae5-47fd-4832-adeb-c6070f729733
2011/12/10 11:28:06 | StackTrace:
2011/12/10 11:28:06 | 	at org.neodatis.odb.core.layers.layer4.plugin.jdbm.NeoDatisJdbmPlugin.read(NeoDatisJdbmPlugin.java:58)
2011/12/10 11:28:06 | 	at org.neodatis.odb.core.session.SessionEngineImpl.layer4ToLayer3(SessionEngineImpl.java:353)
2011/12/10 11:28:06 | 	at org.neodatis.odb.core.session.SessionEngineImpl.getFieldValuesFromOid(SessionEngineImpl.java:474)
2011/12/10 11:28:06 | 	at org.neodatis.odb.core.query.criteria.CriteriaQueryExecutor.matchObjectWithOid(CriteriaQueryExecutor.java:86)
2011/12/10 11:28:06 | 	at org.neodatis.odb.core.query.GenericQueryExecutor.executeFullScan(GenericQueryExecutor.java:290)
2011/12/10 11:28:06 | 	at org.neodatis.odb.core.query.GenericQueryExecutor.execute(GenericQueryExecutor.java:168)
2011/12/10 11:28:06 | 	at org.neodatis.odb.core.session.SessionEngineImpl.getMetaObjects(SessionEngineImpl.java:694)
2011/12/10 11:28:06 | 	at org.neodatis.odb.core.server.connection.ClientServerConnection.manageGetObjectsCommand(ClientServerConnection.java:898)
2011/12/10 11:28:06 | 	at org.neodatis.odb.core.server.connection.ClientServerConnection.manageMessage(ClientServerConnection.java:183)
2011/12/10 11:28:06 | 	at org.neodatis.odb.core.server.connection.RemoteClientServerConnection.run(RemoteClientServerConnection.java:91)
2011/12/10 11:28:06 | 	at java.lang.Thread.run(Thread.java:679)
2011/12/10 11:28:06 | Caused by: java.lang.IllegalStateException: RecordManager has been closed
2011/12/10 11:28:06 | 	at jdbm.recman.CacheRecordManager.checkIfClosed(CacheRecordManager.java:445)
2011/12/10 11:28:06 | 	at jdbm.recman.CacheRecordManager.fetch(CacheRecordManager.java:308)
2011/12/10 11:28:06 | 	at jdbm.btree.BTree._fetch(BTree.java:863)
2011/12/10 11:28:06 | 	at jdbm.btree.BTree.getRoot(BTree.java:645)
2011/12/10 11:28:06 | 	at jdbm.btree.BTree.find(BTree.java:435)
2011/12/10 11:28:06 | 	at org.neodatis.odb.core.layers.layer4.plugin.jdbm.PHashMapBTree.get(PHashMapBTree.java:133)
2011/12/10 11:28:06 | 	at org.neodatis.odb.core.layers.layer4.plugin.jdbm.NeoDatisJdbmPlugin.read(NeoDatisJdbmPlugin.java:45)
2011/12/10 11:28:06 | 	... 10 more
2011/12/10 11:28:06 | 
2011/12/10 11:28:06 | StackTrace:
2011/12/10 11:28:06 | 	at org.neodatis.odb.core.server.ClientSessionEngineImpl.execute(ClientSessionEngineImpl.java:347)
2011/12/10 11:28:06 | 	at org.neodatis.odb.core.query.criteria.CriteriaQueryImpl.objects(CriteriaQueryImpl.java:97)
2011/12/10 11:28:06 | 	at net.i2p.seedless.reuse.scrape.Scrape.run(Scrape.java:301)
2011/12/10 11:28:06 | 	at java.lang.Thread.run(Thread.java:679)
2011/12/10 11:28:06 | 10.12.2011 11:28:06 org.mortbay.http.SocketListener stop
2011/12/10 11:28:06 | INFO: Stopped SocketListener on 127.0.0.1:7650
2011/12/10 11:28:06 | Active thread: I2PControl
2011/12/10 11:28:07 | CRIT  [hutdown hook] net.i2p.router.Router         : Graceful shutdown progress - no more tunnels, safe to die
2011/12/10 11:28:08 | Cleaned orphaned ODB instance. Bug in net.i2p.seedless.reuse.scrape.Scrape.
2011/12/10 11:28:11 | Proxy not quite ready yet, will retry in 60 seconds.
2011/12/10 11:28:15 | CRIT  [hutdown hook] net.i2p.router.Router         : Shutdown(5) complete
2011/12/10 11:28:17 | SeedlessServer Exited.
2011/12/10 11:28:17 | Seedless server context destroyed
2011/12/10 11:28:17 | SeedlessServer Exited.
2011/12/10 11:28:17 | EepAnnouncer server context destroyed
2011/12/10 11:28:18 | CRIT  [SeedlsScpPrs] .naming.BlockfileNamingService: Failed to initialize database
2011/12/10 11:28:18 | java.io.FileNotFoundException: /usr/share/i2p/hostsdb.blockfile (Permission denied)
2011/12/10 11:28:18 | 	at java.io.RandomAccessFile.open(Native Method)
2011/12/10 11:28:18 | 	at java.io.RandomAccessFile.<init>(RandomAccessFile.java:233)
2011/12/10 11:28:18 | 	at net.metanotion.io.RAIFile.<init>(RAIFile.java:59)
2011/12/10 11:28:18 | 	at net.i2p.client.naming.BlockfileNamingService.<init>(BlockfileNamingService.java:177)
2011/12/10 11:28:18 | 	at sun.reflect.NativeConstructorAccessorImpl.newInstance0(Native Method)
2011/12/10 11:28:18 | 	at sun.reflect.NativeConstructorAccessorImpl.newInstance(NativeConstructorAccessorImpl.java:57)
2011/12/10 11:28:18 | 	at sun.reflect.DelegatingConstructorAccessorImpl.newInstance(DelegatingConstructorAccessorImpl.java:45)
2011/12/10 11:28:18 | 	at java.lang.reflect.Constructor.newInstance(Constructor.java:532)
2011/12/10 11:28:18 | 	at net.i2p.client.naming.NamingService.createInstance(NamingService.java:464)
2011/12/10 11:28:18 | 	at net.i2p.I2PAppContext.initializeNamingService(I2PAppContext.java:596)
2011/12/10 11:28:18 | 	at net.i2p.I2PAppContext.namingService(I2PAppContext.java:589)
2011/12/10 11:28:18 | 	at i2p.bote.service.seedless.SeedlessScrapePeers.lookup(SeedlessScrapePeers.java:130)
2011/12/10 11:28:18 | 	at i2p.bote.service.seedless.SeedlessScrapePeers.doSeedlessScrapePeers(SeedlessScrapePeers.java:117)
2011/12/10 11:28:18 | 	at i2p.bote.service.seedless.SeedlessScrapePeers.doStep(SeedlessScrapePeers.java:73)
2011/12/10 11:28:18 | 	at i2p.bote.service.I2PBoteThread.run(I2PBoteThread.java:77)
2011/12/10 11:28:20 | on_exit trigger matched.  Restarting the JVM.  (Exit code: 5)
2011/12/10 11:28:35 | Launching a JVM...
2011/12/10 11:28:35 | WrapperManager: Initializing...

comment:4 Changed 8 years ago by killyourtv

…and I see that SeedlessScrapePeers?.java is in bote.

comment:5 Changed 8 years ago by zzz

Component: apps/addressbookapps/plugins
Owner: changed from zzz to HungryHobo, sponge
Summary: Addressbook should not try to write to a read-only $I2Pbote/seedless shutdown issues (was: Addressbook should not try to write to a read-only $I2P)

This is all very interesting.

All the shutdown hooks are called between here:

2011/12/10 11:28:07 | CRIT  [hutdown hook] net.i2p.router.Router         : Graceful shutdown progress - no more tunnels, safe to die

and here:

2011/12/10 11:28:15 | CRIT  [hutdown hook] net.i2p.router.Router         : Shutdown(5) complete

after which everything darn well should be done.

All the shenanigans are going on AFTER that. When there shouldn't be any threads and there isn't any context since it was destroyed. So a new context is created with no pointer to the config dir, so it tries the base directory, which is read-only, and dies.

So the whole Blockfile addressbook thing was a red herring.

The real issue is that bote and/or seedless threads are starting up when the shutdown hooks are called. Look between the start and end of shutdown for clues.

May or may not be related to #544 and #566.

Hint: log net.i2p.router.Router=WARN to see the shutdown hooks get called. But the real issue is somewhere in bote.

Reassigning to HH and sponge.

comment:6 Changed 8 years ago by zzz

One note of caution to looking at the order of things in the wrapper log however -

The I2P log system is buffered, so output to wrapper log is delayed by up to several seconds. Stuff that writes directly to the wrapper log like seedless is unbuffered.

So my statements above about what happens when may be incorrect.

comment:7 Changed 8 years ago by sponge

Now with the full log, I can say that bote is attempting to do naming look ups for seedless b32 addresses, this causes the addressbook code to attempt the write, etc.

The NeoDatis? server is indeed shut down, that is why the errors are thrown.

It also appears that TWO seedless servers are running?
As stated in the Seedless documentation, you should not do that.
Support only exists for ONE Seedless server per router.

You can have as many eep announcers as you wish, and you can even have a Seedless server that isn't eep announcing.

So it looks like multiple problems all tangled up to me.

comment:8 in reply to:  7 Changed 8 years ago by killyourtv

Replying to sponge:

The NeoDatis? server is indeed shut down, that is why the errors are thrown.

It also appears that TWO seedless servers are running?
As stated in the Seedless documentation, you should not do that.
Support only exists for ONE Seedless server per router.

What in the world would be the possible benefit of running *two* seedless servers on the same router? If two were running running at the same time it would have to be because of a bug spawning a second copy (like the bug from a month or so ago that resulted in two tunnels being monitored when only one was set up).

There may be a problem with bote or seedless, but as I feel I've been saying like a broken record, "This was not caused by user error."

comment:9 Changed 8 years ago by zzz

Milestone: 0.8.120.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:10 Changed 8 years ago by zzz

Milestone: 0.8.130.9.3

See comments in #566 on partial fix implemented in 0.9-13 to work around the lack of a root cause fix in seedless.

comment:11 Changed 7 years ago by HungryHobo

So the SeedlsScpPrs? thread is still running when it shouldn't be. Do I understand this right? That would make it a bote issue.

comment:12 Changed 7 years ago by HungryHobo

Milestone: 0.9.30.9.5
Owner: changed from HungryHobo, sponge to HungryHobo
Priority: minormajor
Status: assignedaccepted

Bote definitely leaves threads behind. I'll investigate.

comment:13 Changed 7 years ago by HungryHobo

Resolution: fixed
Status: acceptedclosed
Note: See TracTickets for help on using tickets.