Re: Reproduced: Re: FN cannot start

Krzysztof <[email protected]> Thu, 13 Jun 2019 16:36:11 +0200
Newsgroups gmane.network.freenet.support
Message-ID <[email protected]>
No, I don't.

What I discovered so far, after deleting file 'client.dat.crypt', the 
node started normally. Of course, all downloads were gone.

Maybe there is a way to test or repair this file?

Pozdrawiam
Krzysztof Jasieński

On 6/13/19 12:29 PM, Arne Babenhauserheide wrote:
> My node now also stopped starting.
>
>
> Question to Krzysztof: Do you have a darknet connection?
>
>
> When run via ./run.sh console, this is the last line I see before
> startup fails:
>
>
> jvm 2    | Deleted 0 of 0 temporary files (0 non-temp files in temp directory) in 0s
>
>
> This is what I should see:
>
>
> jvm 1    | Resumed 4 requests ...
> jvm 1    | Initializing USK Manager
> jvm 1    | Loading cache of request statuses...
> jvm 1    | Initializing Node Updater
>
>
> Disabling all plugins does not make a difference.
> Starting without the wrapper does not make a difference either.
> Moving tmp away does not make a difference, either.
> Moving datastore to datastore.broken does not make a difference.
> Moving persistent-temp to persistent-temp.broken only lets it show one
>      more error:
>      jvm 1    | Unable to resume request
>      freenet.clients.fcp.ClientGet@45d042f9 after loading it.
>
> So it looks like there is some broken state which blocks startup.
>
>
> logs/freenet-latest.log says
>
> Jun 13, 2019 09:18:00:317 (freenet.io.AddressTracker, WrapperListener_start_runner, WARNING): Failed to load from disk for port XXXX: freenet.node.FSParseException: Unable to load address tracker table, assuming an unclean shutdown: Last ID was XXXX but stored XXXX
> freenet.node.FSParseException: Unable to load address tracker table, assuming an unclean shutdown: Last ID was XXXX but stored XXXX
> 	at freenet.io.AddressTracker.<init>(AddressTracker.java:115)
> 	at freenet.io.AddressTracker.create(AddressTracker.java:84)
> 	at freenet.io.comm.UdpSocketHandler.<init>(UdpSocketHandler.java:161)
> 	at freenet.node.NodeCrypto.<init>(NodeCrypto.java:121)
> 	at freenet.node.Node.<init>(Node.java:1489)
> 	at freenet.node.NodeStarter.start(NodeStarter.java:194)
> 	at org.tanukisoftware.wrapper.WrapperManager$11.run(WrapperManager.java:4048)
>
>
>
> I took an application snapshot with jvisualvm: Here’s the threaddump
>
>
> Full thread dump OpenJDK 64-Bit Server VM (25.191-b12 mixed mode):
>
> "Pooled thread awaiting work @1 for prio 5" #42 daemon prio=5 os_prio=0 tid=0x00007f68005f7000 nid=0x27ae in Object.wait() [0x00007f681dc9e000]
>     java.lang.Thread.State: TIMED_WAITING (on object monitor)
>          at java.lang.Object.wait(Native Method)
>          - waiting on <0x000000009d22ff80> (a freenet.support.PooledExecutor$MyThread)
>          at freenet.support.PooledExecutor$MyThread.innerRun(PooledExecutor.java:218)
>          - locked <0x000000009d22ff80> (a freenet.support.PooledExecutor$MyThread)
>          at freenet.support.PooledExecutor$MyThread.realRun(PooledExecutor.java:189)
>          at freenet.support.io.NativeThread.run(NativeThread.java:156)
>
>     Locked ownable synchronizers:
>          - None
>
> "Timer-0" #36 daemon prio=5 os_prio=0 tid=0x00007f680009d000 nid=0x27a1 in Object.wait() [0x00007f681e19f000]
>     java.lang.Thread.State: WAITING (on object monitor)
>          at java.lang.Object.wait(Native Method)
>          - waiting on <0x000000009cfdf0b0> (a java.util.TaskQueue)
>          at java.lang.Object.wait(Object.java:502)
>          at java.util.TimerThread.mainLoop(Timer.java:526)
>          - locked <0x000000009cfdf0b0> (a java.util.TaskQueue)
>          at java.util.TimerThread.run(Timer.java:505)
>
>     Locked ownable synchronizers:
>          - None
>
> "SimpleToadletServer" #29 daemon prio=5 os_prio=0 tid=0x00007f6800844800 nid=0x2788 waiting on condition [0x00007f681e4a0000]
>     java.lang.Thread.State: WAITING (parking)
>          at sun.misc.Unsafe.park(Native Method)
>          - parking to wait for  <0x000000009cfdf740> (a java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject)
>          at java.util.concurrent.locks.LockSupport.park(LockSupport.java:175)
>          at java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject.awaitUninterruptibly(AbstractQueuedSynchronizer.java:1976)
>          at freenet.io.NetworkInterface.accept(NetworkInterface.java:249)
>          at freenet.clients.http.SimpleToadletServer.run(SimpleToadletServer.java:999)
>          at java.lang.Thread.run(Thread.java:748)
>
>     Locked ownable synchronizers:
>          - None
>
> "Network Interface Acceptor for ServerSocket[addr=/127.15.9.6,localport=8988](0)" #28 daemon prio=5 os_prio=0 tid=0x00007f6800843000 nid=0x2787 runnable [0x00007f681e5a1000]
>     java.lang.Thread.State: RUNNABLE
>          at java.net.PlainSocketImpl.socketAccept(Native Method)
>          at java.net.AbstractPlainSocketImpl.accept(AbstractPlainSocketImpl.java:409)
>          at java.net.ServerSocket.implAccept(ServerSocket.java:545)
>          at java.net.ServerSocket.accept(ServerSocket.java:513)
>          at freenet.io.NetworkInterface$Acceptor.run(NetworkInterface.java:389)
>          at freenet.support.PooledExecutor$MyThread.innerRun(PooledExecutor.java:249)
>          at freenet.support.PooledExecutor$MyThread.realRun(PooledExecutor.java:189)
>          at freenet.support.io.NativeThread.run(NativeThread.java:156)
>
>     Locked ownable synchronizers:
>          - None
>
> "Plug" #27 prio=10 os_prio=0 tid=0x00007f6800172800 nid=0x277f waiting on condition [0x00007f681e8a2000]
>     java.lang.Thread.State: TIMED_WAITING (sleeping)
>          at java.lang.Thread.sleep(Native Method)
>          at freenet.node.NodeStarter$1.run(NodeStarter.java:169)
>          at java.lang.Thread.run(Thread.java:748)
>          at freenet.support.io.NativeThread.run(NativeThread.java:155)
>
>     Locked ownable synchronizers:
>          - None
>
> "Log File Writer Thread" #24 daemon prio=5 os_prio=0 tid=0x00007f6800172000 nid=0x277e in Object.wait() [0x00007f681e9a3000]
>     java.lang.Thread.State: TIMED_WAITING (on object monitor)
>          at java.lang.Object.wait(Native Method)
>          at freenet.support.FileLoggerHook$WriterThread.run(FileLoggerHook.java:342)
>          - locked <0x000000009d07db98> (a java.util.concurrent.ArrayBlockingQueue)
>
>     Locked ownable synchronizers:
>          - None
>
> "WrapperListener_start_runner" #23 prio=5 os_prio=0 tid=0x00007f67fc003800 nid=0x2772 runnable [0x00007f681eaa3000]
>     java.lang.Thread.State: RUNNABLE
>          at freenet.support.io.PooledFileRandomAccessBuffer.closeRAF(PooledFileRandomAccessBuffer.java:260)
>          - locked <0x000000009cecc768> (a freenet.support.io.PooledFileRandomAccessBuffer$FDTracker)
>          at freenet.support.io.PooledFileRandomAccessBuffer.lockOpen(PooledFileRandomAccessBuffer.java:233)
>          - locked <0x000000009cecc768> (a freenet.support.io.PooledFileRandomAccessBuffer$FDTracker)
>          at freenet.support.io.PooledFileRandomAccessBuffer.lockOpen(PooledFileRandomAccessBuffer.java:206)
>          at freenet.support.io.PooledFileRandomAccessBuffer.pread(PooledFileRandomAccessBuffer.java:160)
>          at freenet.support.io.PaddedRandomAccessBuffer.pread(PaddedRandomAccessBuffer.java:32)
>          at freenet.crypt.EncryptedRandomAccessBuffer.setup(EncryptedRandomAccessBuffer.java:102)
>          at freenet.crypt.EncryptedRandomAccessBuffer.onResume(EncryptedRandomAccessBuffer.java:358)
>          at freenet.client.async.SplitFileFetcher.onResume(SplitFileFetcher.java:423)
>          at freenet.client.async.ClientGetter.innerOnResume(ClientGetter.java:983)
>          at freenet.client.async.ClientRequester.onResume(ClientRequester.java:407)
>          at freenet.clients.fcp.ClientRequest.onResume(ClientRequest.java:509)
>          at freenet.client.async.ClientLayerPersister.innerSetFilesAndLoad(ClientLayerPersister.java:272)
>          at freenet.client.async.ClientLayerPersister.setFilesAndLoad(ClientLayerPersister.java:159)
>          - locked <0x000000009d073540> (a java.lang.Object)
>          at freenet.node.NodeClientCore.initStorage(NodeClientCore.java:964)
>          at freenet.node.NodeClientCore.<init>(NodeClientCore.java:633)
>          at freenet.node.Node.<init>(Node.java:1666)
>          at freenet.node.NodeStarter.start(NodeStarter.java:194)
>          at org.tanukisoftware.wrapper.WrapperManager$11.run(WrapperManager.java:4048)
>
>     Locked ownable synchronizers:
>          - None
>
> "DestroyJavaVM" #22 prio=5 os_prio=0 tid=0x00007f683800b000 nid=0x2721 waiting on condition [0x0000000000000000]
>     java.lang.Thread.State: RUNNABLE
>
>     Locked ownable synchronizers:
>          - None
>
> "RMI TCP Connection(idle)" #21 daemon prio=9 os_prio=0 tid=0x00007f67e8010000 nid=0x2771 waiting on condition [0x00007f681eba5000]
>     java.lang.Thread.State: TIMED_WAITING (parking)
>          at sun.misc.Unsafe.park(Native Method)
>          - parking to wait for  <0x000000009cfdcd68> (a java.util.concurrent.SynchronousQueue$TransferStack)
>          at java.util.concurrent.locks.LockSupport.parkNanos(LockSupport.java:215)
>          at java.util.concurrent.SynchronousQueue$TransferStack.awaitFulfill(SynchronousQueue.java:460)
>          at java.util.concurrent.SynchronousQueue$TransferStack.transfer(SynchronousQueue.java:362)
>          at java.util.concurrent.SynchronousQueue.poll(SynchronousQueue.java:941)
>          at java.util.concurrent.ThreadPoolExecutor.getTask(ThreadPoolExecutor.java:1073)
>          at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1134)
>          at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624)
>          at java.lang.Thread.run(Thread.java:748)
>
>     Locked ownable synchronizers:
>          - None
>
> "RMI TCP Connection(3)-127.0.0.1" #20 daemon prio=9 os_prio=0 tid=0x00007f67e800e800 nid=0x2770 runnable [0x00007f681eca5000]
>     java.lang.Thread.State: RUNNABLE
>          at java.net.SocketInputStream.socketRead0(Native Method)
>          at java.net.SocketInputStream.socketRead(SocketInputStream.java:116)
>          at java.net.SocketInputStream.read(SocketInputStream.java:171)
>          at java.net.SocketInputStream.read(SocketInputStream.java:141)
>          at java.io.BufferedInputStream.fill(BufferedInputStream.java:246)
>          at java.io.BufferedInputStream.read(BufferedInputStream.java:265)
>          - locked <0x000000009c4371f8> (a java.io.BufferedInputStream)
>          at java.io.FilterInputStream.read(FilterInputStream.java:83)
>          at sun.rmi.transport.tcp.TCPTransport.handleMessages(TCPTransport.java:555)
>          at sun.rmi.transport.tcp.TCPTransport$ConnectionHandler.run0(TCPTransport.java:834)
>          at sun.rmi.transport.tcp.TCPTransport$ConnectionHandler.lambda$run$0(TCPTransport.java:688)
>          at sun.rmi.transport.tcp.TCPTransport$ConnectionHandler$$Lambda$10/48444814.run(Unknown Source)
>          at java.security.AccessController.doPrivileged(Native Method)
>          at sun.rmi.transport.tcp.TCPTransport$ConnectionHandler.run(TCPTransport.java:687)
>          at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149)
>          at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624)
>          at java.lang.Thread.run(Thread.java:748)
>
>     Locked ownable synchronizers:
>          - <0x000000009cfdce78> (a java.util.concurrent.ThreadPoolExecutor$Worker)
>
> "Wrapper-Connection" #19 daemon prio=10 os_prio=0 tid=0x00007f6838450800 nid=0x276f runnable [0x00007f681eda7000]
>     java.lang.Thread.State: RUNNABLE
>          at java.io.FileInputStream.read0(Native Method)
>          at java.io.FileInputStream.read(FileInputStream.java:207)
>          at java.io.DataInputStream.readByte(DataInputStream.java:265)
>          at org.tanukisoftware.wrapper.WrapperManager.handleBackend(WrapperManager.java:5188)
>          at org.tanukisoftware.wrapper.WrapperManager.run(WrapperManager.java:5561)
>          at java.lang.Thread.run(Thread.java:748)
>
>     Locked ownable synchronizers:
>          - None
>
> "Wrapper-Startup-Runner" #18 prio=10 os_prio=0 tid=0x00007f6838432800 nid=0x276e sleeping[0x00007f681eea8000]
>     java.lang.Thread.State: TIMED_WAITING (sleeping)
>          at java.lang.Thread.sleep(Native Method)
>          at org.tanukisoftware.wrapper.WrapperManager$4.run(WrapperManager.java:1045)
>
>     Locked ownable synchronizers:
>          - None
>
> "Wrapper-Control-Event-Monitor" #17 daemon prio=5 os_prio=0 tid=0x00007f6838434800 nid=0x276d sleeping[0x00007f681efa9000]
>     java.lang.Thread.State: TIMED_WAITING (sleeping)
>          at java.lang.Thread.sleep(Native Method)
>          at org.tanukisoftware.wrapper.WrapperManager$3.run(WrapperManager.java:978)
>
>     Locked ownable synchronizers:
>          - None
>
> "RMI TCP Connection(2)-127.0.0.1" #15 daemon prio=9 os_prio=0 tid=0x00007f67e8005000 nid=0x2765 runnable [0x00007f681f2b3000]
>     java.lang.Thread.State: RUNNABLE
>          at java.net.SocketInputStream.socketRead0(Native Method)
>          at java.net.SocketInputStream.socketRead(SocketInputStream.java:116)
>          at java.net.SocketInputStream.read(SocketInputStream.java:171)
>          at java.net.SocketInputStream.read(SocketInputStream.java:141)
>          at java.io.BufferedInputStream.fill(BufferedInputStream.java:246)
>          at java.io.BufferedInputStream.read(BufferedInputStream.java:265)
>          - locked <0x000000009c4377f0> (a java.io.BufferedInputStream)
>          at java.io.FilterInputStream.read(FilterInputStream.java:83)
>          at sun.rmi.transport.tcp.TCPTransport.handleMessages(TCPTransport.java:555)
>          at sun.rmi.transport.tcp.TCPTransport$ConnectionHandler.run0(TCPTransport.java:834)
>          at sun.rmi.transport.tcp.TCPTransport$ConnectionHandler.lambda$run$0(TCPTransport.java:688)
>          at sun.rmi.transport.tcp.TCPTransport$ConnectionHandler$$Lambda$10/48444814.run(Unknown Source)
>          at java.security.AccessController.doPrivileged(Native Method)
>          at sun.rmi.transport.tcp.TCPTransport$ConnectionHandler.run(TCPTransport.java:687)
>          at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149)
>          at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624)
>          at java.lang.Thread.run(Thread.java:748)
>
>     Locked ownable synchronizers:
>          - <0x000000009cfdd410> (a java.util.concurrent.ThreadPoolExecutor$Worker)
>
> "JMX server connection timeout 14" #14 daemon prio=9 os_prio=0 tid=0x00007f67ec018800 nid=0x2761 in Object.wait() [0x00007f681f3b5000]
>     java.lang.Thread.State: TIMED_WAITING (on object monitor)
>          at java.lang.Object.wait(Native Method)
>          at com.sun.jmx.remote.internal.ServerCommunicatorAdmin$Timeout.run(ServerCommunicatorAdmin.java:168)
>          - locked <0x000000009cfde588> (a [I)
>          at java.lang.Thread.run(Thread.java:748)
>
>     Locked ownable synchronizers:
>          - None
>
> "RMI Scheduler(0)" #13 daemon prio=9 os_prio=0 tid=0x00007f67ec016000 nid=0x275f waiting on condition [0x00007f681f4b6000]
>     java.lang.Thread.State: TIMED_WAITING (parking)
>          at sun.misc.Unsafe.park(Native Method)
>          - parking to wait for  <0x000000009c0b1110> (a java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject)
>          at java.util.concurrent.locks.LockSupport.parkNanos(LockSupport.java:215)
>          at java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject.awaitNanos(AbstractQueuedSynchronizer.java:2078)
>          at java.util.concurrent.ScheduledThreadPoolExecutor$DelayedWorkQueue.take(ScheduledThreadPoolExecutor.java:1093)
>          at java.util.concurrent.ScheduledThreadPoolExecutor$DelayedWorkQueue.take(ScheduledThreadPoolExecutor.java:809)
>          at java.util.concurrent.ThreadPoolExecutor.getTask(ThreadPoolExecutor.java:1074)
>          at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1134)
>          at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624)
>          at java.lang.Thread.run(Thread.java:748)
>
>     Locked ownable synchronizers:
>          - None
>
> "RMI TCP Connection(idle)" #12 daemon prio=9 os_prio=0 tid=0x00007f67e8003800 nid=0x275d waiting on condition [0x00007f681f7b7000]
>     java.lang.Thread.State: TIMED_WAITING (parking)
>          at sun.misc.Unsafe.park(Native Method)
>          - parking to wait for  <0x000000009cfdcd68> (a java.util.concurrent.SynchronousQueue$TransferStack)
>          at java.util.concurrent.locks.LockSupport.parkNanos(LockSupport.java:215)
>          at java.util.concurrent.SynchronousQueue$TransferStack.awaitFulfill(SynchronousQueue.java:460)
>          at java.util.concurrent.SynchronousQueue$TransferStack.transfer(SynchronousQueue.java:362)
>          at java.util.concurrent.SynchronousQueue.poll(SynchronousQueue.java:941)
>          at java.util.concurrent.ThreadPoolExecutor.getTask(ThreadPoolExecutor.java:1073)
>          at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1134)
>          at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624)
>          at java.lang.Thread.run(Thread.java:748)
>
>     Locked ownable synchronizers:
>          - None
>
> "RMI TCP Accept-0" #11 daemon prio=9 os_prio=0 tid=0x00007f67f00c3800 nid=0x275b runnable [0x00007f68241b1000]
>     java.lang.Thread.State: RUNNABLE
>          at java.net.PlainSocketImpl.socketAccept(Native Method)
>          at java.net.AbstractPlainSocketImpl.accept(AbstractPlainSocketImpl.java:409)
>          at java.net.ServerSocket.implAccept(ServerSocket.java:545)
>          at java.net.ServerSocket.accept(ServerSocket.java:513)
>          at sun.management.jmxremote.LocalRMIServerSocketFactory$1.accept(LocalRMIServerSocketFactory.java:52)
>          at sun.rmi.transport.tcp.TCPTransport$AcceptLoop.executeAcceptLoop(TCPTransport.java:405)
>          at sun.rmi.transport.tcp.TCPTransport$AcceptLoop.run(TCPTransport.java:377)
>          at java.lang.Thread.run(Thread.java:748)
>
>     Locked ownable synchronizers:
>          - None
>
> "Attach Listener" #8 daemon prio=9 os_prio=0 tid=0x00007f680c001000 nid=0x2738 waiting on condition [0x0000000000000000]
>     java.lang.Thread.State: RUNNABLE
>
>     Locked ownable synchronizers:
>          - None
>
> "Service Thread" #7 daemon prio=9 os_prio=0 tid=0x00007f68380d6000 nid=0x272c runnable [0x0000000000000000]
>     java.lang.Thread.State: RUNNABLE
>
>     Locked ownable synchronizers:
>          - None
>
> "C1 CompilerThread1" #6 daemon prio=9 os_prio=0 tid=0x00007f68380cb800 nid=0x272b waiting on condition [0x0000000000000000]
>     java.lang.Thread.State: RUNNABLE
>
>     Locked ownable synchronizers:
>          - None
>
> "C2 CompilerThread0" #5 daemon prio=9 os_prio=0 tid=0x00007f68380c9000 nid=0x272a waiting on condition [0x0000000000000000]
>     java.lang.Thread.State: RUNNABLE
>
>     Locked ownable synchronizers:
>          - None
>
> "Signal Dispatcher" #4 daemon prio=9 os_prio=0 tid=0x00007f68380bc800 nid=0x2729 runnable [0x0000000000000000]
>     java.lang.Thread.State: RUNNABLE
>
>     Locked ownable synchronizers:
>          - None
>
> "Finalizer" #3 daemon prio=8 os_prio=0 tid=0x00007f6838090800 nid=0x2727 in Object.wait() [0x00007f6825124000]
>     java.lang.Thread.State: WAITING (on object monitor)
>          at java.lang.Object.wait(Native Method)
>          - waiting on <0x000000009c75e3a0> (a java.lang.ref.ReferenceQueue$Lock)
>          at java.lang.ref.ReferenceQueue.remove(ReferenceQueue.java:144)
>          - locked <0x000000009c75e3a0> (a java.lang.ref.ReferenceQueue$Lock)
>          at java.lang.ref.ReferenceQueue.remove(ReferenceQueue.java:165)
>          at java.lang.ref.Finalizer$FinalizerThread.run(Finalizer.java:216)
>
>     Locked ownable synchronizers:
>          - None
>
> "Reference Handler" #2 daemon prio=10 os_prio=0 tid=0x00007f683808c000 nid=0x2726 in Object.wait() [0x00007f6825225000]
>     java.lang.Thread.State: WAITING (on object monitor)
>          at java.lang.Object.wait(Native Method)
>          - waiting on <0x000000009c47e558> (a java.lang.ref.Reference$Lock)
>          at java.lang.Object.wait(Object.java:502)
>          at java.lang.ref.Reference.tryHandlePending(Reference.java:191)
>          - locked <0x000000009c47e558> (a java.lang.ref.Reference$Lock)
>          at java.lang.ref.Reference$ReferenceHandler.run(Reference.java:153)
>
>     Locked ownable synchronizers:
>          - None
>
> "VM Thread" os_prio=0 tid=0x00007f6838082000 nid=0x2725 runnable
>
> "GC task thread#0 (ParallelGC)" os_prio=0 tid=0x00007f6838020000 nid=0x2722 runnable
>
> "GC task thread#1 (ParallelGC)" os_prio=0 tid=0x00007f6838022000 nid=0x2723 runnable
>
> "VM Periodic Task Thread" os_prio=0 tid=0x00007f68380db000 nid=0x272d waiting on condition
>
> JNI global references: 289
>
>
>
> I cannot look deeper now, need to start with my real job.
>
>
> Best wishes,
> Arne
> --
> Unpolitisch sein
> heißt politisch sein
> ohne es zu merken