Opened 7 years ago
Closed 6 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: |
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 7 years ago by sponge
- Component changed from apps/plugins to apps/addressbook
- Owner changed from sponge to zzz
- Status changed from new to assigned
- Summary changed from Seedless should not try to write to a read-only $I2P to Addressbook should not try to write to a read-only $I2P
comment:2 Changed 7 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 7 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 7 years ago by killyourtv
...and I see that SeedlessScrapePeers?.java is in bote.
comment:5 Changed 7 years ago by zzz
- Component changed from apps/addressbook to apps/plugins
- Owner changed from zzz to HungryHobo, sponge
- Summary changed from Addressbook should not try to write to a read-only $I2P to bote/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 7 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 follow-up: ↓ 8 Changed 7 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 7 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 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:10 Changed 7 years ago by zzz
- Milestone changed from 0.8.13 to 0.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 6 years ago by HungryHobo
- Milestone changed from 0.9.3 to 0.9.5
- Owner changed from HungryHobo, sponge to HungryHobo
- Priority changed from minor to major
- Status changed from assigned to accepted
Bote definitely leaves threads behind. I'll investigate.
comment:13 Changed 6 years ago by HungryHobo
- Resolution set to fixed
- Status changed from accepted to closed
Note: See
TracTickets for help on using
tickets.
Does not look like a Seedless error, that's the new addressbook stuff. :-)