Re: Reproduced: Re: FN cannot start
Oh, interesting! Is this a symptom of a malformed client.dat.crypt? If you restore the file, does it fail in the same way again? - Steve Sent from ProtonMail Mobile On Thu, Jun 13, 2019 at 10:36 AM, Krzysztof wrote: > 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 >> : freenet.node.FSParseException: Unable to load address tracker table, >> assuming an unclean shutdown: Last ID was but stored >> freenet.node.FSParseException: Unable to load address tracker table, >> assuming an unclean shutdown: Last ID was but stored >> at freenet.io.AddressTracker.(AddressTracker.java:115) >> at freenet.io.AddressTracker.create(AddressTracker.java:84) >> at freenet.io.comm.UdpSocketHandler.(UdpSocketHandler.java:161) >> at freenet.node.NodeCrypto.(NodeCrypto.java:121) >> at freenet.node.Node.(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=0x7f68005f7000 nid=0x27ae in Object.wait() [0x7f681dc9e000] >> java.lang.Thread.State: TIMED_WAITING (on object monitor) >> at java.lang.Object.wait(Native Method) >> - waiting on <0x9d22ff80> (a freenet.support.PooledExecutor$MyThread) >> at freenet.support.PooledExecutor$MyThread.innerRun(PooledExecutor.java:218) >> - locked <0x9d22ff80> (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=0x7f680009d000 nid=0x27a1 in >> Object.wait() [0x7f681e19f000] >> java.lang.Thread.State: WAITING (on object monitor) >> at java.lang.Object.wait(Native Method) >> - waiting on <0x9cfdf0b0> (a java.util.TaskQueue) >> at java.lang.Object.wait(Object.java:502) >> at java.util.TimerThread.mainLoop(Timer.java:526) >> - locked <0x9cfdf0b0> (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=0x7f6800844800 >> nid=0x2788 waiting on condition [0x7f681e4a] >> java.lang.Thread.State: WAITING (parking) >> at sun.misc.Unsafe.park(Native Method) >> - parking to wait for <0x9cfdf740> (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=0x7f6800843000 nid=0x2787 runnable [0x7f681e5a1000] >> 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.n
Re: Reproduced: Re: FN cannot start
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 : freenet.node.FSParseException: Unable to load address tracker table, assuming an unclean shutdown: Last ID was but stored freenet.node.FSParseException: Unable to load address tracker table, assuming an unclean shutdown: Last ID was but stored at freenet.io.AddressTracker.(AddressTracker.java:115) at freenet.io.AddressTracker.create(AddressTracker.java:84) at freenet.io.comm.UdpSocketHandler.(UdpSocketHandler.java:161) at freenet.node.NodeCrypto.(NodeCrypto.java:121) at freenet.node.Node.(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=0x7f68005f7000 nid=0x27ae in Object.wait() [0x7f681dc9e000] java.lang.Thread.State: TIMED_WAITING (on object monitor) at java.lang.Object.wait(Native Method) - waiting on <0x9d22ff80> (a freenet.support.PooledExecutor$MyThread) at freenet.support.PooledExecutor$MyThread.innerRun(PooledExecutor.java:218) - locked <0x9d22ff80> (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=0x7f680009d000 nid=0x27a1 in Object.wait() [0x7f681e19f000] java.lang.Thread.State: WAITING (on object monitor) at java.lang.Object.wait(Native Method) - waiting on <0x9cfdf0b0> (a java.util.TaskQueue) at java.lang.Object.wait(Object.java:502) at java.util.TimerThread.mainLoop(Timer.java:526) - locked <0x9cfdf0b0> (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=0x7f6800844800 nid=0x2788 waiting on condition [0x7f681e4a] java.lang.Thread.State: WAITING (parking) at sun.misc.Unsafe.park(Native Method) - parking to wait for <0x9cfdf740> (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=0x7f6800843000 nid=0x2787 runnable [0x7f681e5a1000] 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$MyT
Reproduced: Re: FN cannot start
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 : freenet.node.FSParseException: Unable to load address tracker table, assuming an unclean shutdown: Last ID was but stored freenet.node.FSParseException: Unable to load address tracker table, assuming an unclean shutdown: Last ID was but stored at freenet.io.AddressTracker.(AddressTracker.java:115) at freenet.io.AddressTracker.create(AddressTracker.java:84) at freenet.io.comm.UdpSocketHandler.(UdpSocketHandler.java:161) at freenet.node.NodeCrypto.(NodeCrypto.java:121) at freenet.node.Node.(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=0x7f68005f7000 nid=0x27ae in Object.wait() [0x7f681dc9e000] java.lang.Thread.State: TIMED_WAITING (on object monitor) at java.lang.Object.wait(Native Method) - waiting on <0x9d22ff80> (a freenet.support.PooledExecutor$MyThread) at freenet.support.PooledExecutor$MyThread.innerRun(PooledExecutor.java:218) - locked <0x9d22ff80> (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=0x7f680009d000 nid=0x27a1 in Object.wait() [0x7f681e19f000] java.lang.Thread.State: WAITING (on object monitor) at java.lang.Object.wait(Native Method) - waiting on <0x9cfdf0b0> (a java.util.TaskQueue) at java.lang.Object.wait(Object.java:502) at java.util.TimerThread.mainLoop(Timer.java:526) - locked <0x9cfdf0b0> (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=0x7f6800844800 nid=0x2788 waiting on condition [0x7f681e4a] java.lang.Thread.State: WAITING (parking) at sun.misc.Unsafe.park(Native Method) - parking to wait for <0x9cfdf740> (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=0x7f6800843000 nid=0x2787 runnable [0x7f681e5a1000] 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=0x7f6800172800 nid=0x277f waiting on
Re: FN cannot start
Krzysztof writes: > No. It didn't help. There is A part of wrapper.log below if you could > look at it. > > STATUS | wrapper | 2019/06/12 22:47:54 | --> Wrapper Started as Daemon > STATUS | wrapper | 2019/06/12 22:47:54 | Java Service Wrapper > Community Edition 64-bit 3.5.20 > STATUS | wrapper | 2019/06/12 22:47:54 | Copyright (C) 1999-2013 > Tanuki Software, Ltd. All Rights Reserved. > STATUS | wrapper | 2019/06/12 22:47:54 | http://wrapper.tanukisoftware.com > STATUS | wrapper | 2019/06/12 22:47:54 | > STATUS | wrapper | 2019/06/12 22:47:55 | Launching a JVM... > INFO | jvm 1| 2019/06/12 22:48:00 | setpriority() succeeded! > INFO | jvm 1| 2019/06/12 22:48:02 | BouncyCastle: BC version 1.59 > INFO | jvm 1| 2019/06/12 22:48:02 | SunPKCS11-NSS: null > INFO | jvm 1| 2019/06/12 22:48:02 | SUN: SUN version 1.8 > INFO | jvm 1| 2019/06/12 22:48:02 | SunJCE: SunJCE version 1.8 > INFO | jvm 1| 2019/06/12 22:48:02 | WrapperManager: Initializing... > INFO | jvm 1| 2019/06/12 22:48:03 | freenet.jar built with > freenet-ext.jar Build #29 rv29 running with ext build 29 rv29 > INFO | jvm 1| 2019/06/12 22:48:03 | Creating config from freenet.ini > INFO | jvm 1| 2019/06/12 22:48:03 | Creating logger... > INFO | jvm 1| 2019/06/12 22:48:03 | Set interval to 10 and > multiplier to 1 > INFO | jvm 1| 2019/06/12 22:48:03 | Starting executor... > INFO | jvm 1| 2019/06/12 22:48:03 | Finding old log files. New > log file is /home/.../Freenet/logs/freenet-1484-2019-06-12-22.log.gz > INFO | jvm 1| 2019/06/12 22:48:03 | Using the NativeThread > implementation (base nice level is 10) > INFO | jvm 1| 2019/06/12 22:48:04 | Old log file exists for this > time period: /home/.../Freenet/logs/freenet-1484-2019-06-12-22.log.gz > INFO | jvm 1| 2019/06/12 22:48:04 | Renaming to: > /home/.../Freenet/logs/freenet-1484-2019-06-12-22-2.log.gz > INFO | jvm 1| 2019/06/12 22:48:04 | Created log files > INFO | jvm 1| 2019/06/12 22:48:04 | Initializing Node using > Freenet Build #1484 rbuild01484 and freenet-ext Build #29 rv29 with > Oracle Corporation JVM version 1.8.0_212 running on amd64 Linux > 4.9.0-9-amd64 > INFO | jvm 1| 2019/06/12 22:48:04 | Set fproxy max length to > 2306867 and max length with progress to 57671680 = 57671680 > INFO | jvm 1| 2019/06/12 22:48:04 | Starting FProxy on > 127.0.0.1,0:0:0:0:0:0:0:1: > INFO | jvm 1| 2019/06/12 22:48:04 | SHA1: using SUN version 1.8 > INFO | jvm 1| 2019/06/12 22:48:04 | MD5: using SUN version 1.8 > INFO | jvm 1| 2019/06/12 22:48:04 | SHA-256: using SUN version 1.8 > INFO | jvm 1| 2019/06/12 22:48:04 | SHA-384: using SUN version 1.8 > INFO | jvm 1| 2019/06/12 22:48:04 | SHA-512: using SUN version 1.8 > INFO | jvm 1| 2019/06/12 22:48:01 | AES/CTR/NOPADDING (SunJCE > version 1.8): 700373ns > INFO | jvm 1| 2019/06/12 22:48:01 | AES/CTR/NOPADDING (BC > version 1.59): 2018025ns > INFO | jvm 1| 2019/06/12 22:48:01 | Using JCA cipher provider: > SunJCE version 1.8 > INFO | jvm 1| 2019/06/12 22:48:01 | Not enough entropy available. > INFO | jvm 1| 2019/06/12 22:48:01 | Trying to gather entropy > (randomness) by reading the disk... > INFO | jvm 1| 2019/06/12 22:48:01 | You should consider > installing a better random number generator e.g. haveged. > INFO | jvm 1| 2019/06/12 22:48:01 | Trying to read master keys file... > INFO | jvm 1| 2019/06/12 22:48:01 | Read old master keys file > INFO | jvm 1| 2019/06/12 22:48:02 | FNP port created on 0.0.0.0:23499 > INFO | jvm 1| 2019/06/12 22:48:02 | Testnet mode DISABLED. You > may have some level of anonymity. :) > INFO | jvm 1| 2019/06/12 22:48:02 | Note that this version of > Freenet is still a very early alpha, and may well have numerous bugs > and design flaws. > INFO | jvm 1| 2019/06/12 22:48:02 | In particular: YOU ARE WIDE > OPEN TO YOUR IMMEDIATE PEERS! They can eavesdrop on your requests with > relatively little difficulty at present (correlation attacks etc). > INFO | jvm 1| 2019/06/12 22:48:02 | Creating PeerManager > INFO | jvm 1| 2019/06/12 22:48:02 | Memory is 455MB > INFO | jvm 1| 2019/06/12 22:48:02 | Setting standard 500 thread > limit. This should be enough for most nodes but more memory is usually > a good thing. > INFO | jvm 1| 2019/06/12 22:48:03 | Deleted 0 of 0 temporary > files (0 non-temp files in temp directory) in 0s I don’t see here why it stops. At this point the wrapper has successfully started Freenet and passed control over to Freenet itself. Do you see something suspicious in logs/freenet-latest.log? Best wishes, Arne > STATUS | wrapper | 2019/06/12 22:50:46 | Anchor file > deleted. Shutting down. > INFO | jvm 1| 2019/06/12 22:50:46 | Shutting down... > INFO | jvm 1| 2019/06/12 22:50:46 | Stopping database > jobs...Stopping FEC decode threads... > INFO | jvm 1
