Re: Unable to create new store: freenet.node.NodeInitException: Operation not supported (3)

CyberLeo <[email protected]> Wed, 25 Sep 2019 23:34:00 -0500
Newsgroups gmane.network.freenet.support
Message-ID <[email protected]>
On 9/25/19 9:36 PM, Steve Dougherty wrote:
> Hm, I’m not loving the exception logging there; the stack trace of the 
> source of the problem does not appear to be included. The useful part of 
> that trace seems like
> 
> https://github.com/freenet/fred/blob/build01484/src/freenet/node/Node.java#L862
> https://github.com/freenet/fred/blob/build01484/src/freenet/node/Node.java#L2900
> 
> I’d expect wrapper.log (or stderr depending on how you’ve started the 
> node) to contain more information after the string "Could not open store: "
> 
> Can you find such a log line?

Ah yes. It was in the wrapper.log, not in the freenet log where I was 
looking.

And now that you've pointed that out, the problem was obvious: NFS 
locking wasn't running!

After starting statd and lockd, switching the datastore type from ram to 
salt-hash worked perfectly.

Thanks for your help!

The log:

----8<----
INFO   | jvm 1    | 2019/08/18 20:36:40 | Setting datastore size to 
524056200KiB
INFO   | jvm 1    | 2019/08/18 20:36:40 | Initializing CHK Datastore 
(7668822 keys)
INFO   | jvm 1    | 2019/08/18 20:36:40 | Could not open store: 
java.io.IOException: Operation not supported
INFO   | jvm 1    | 2019/08/18 20:36:40 | java.io.IOException: Operation 
not supported
INFO   | jvm 1    | 2019/08/18 20:36:40 |       at 
sun.nio.ch.FileDispatcherImpl.lock0(Native Method)
INFO   | jvm 1    | 2019/08/18 20:36:40 |       at 
sun.nio.ch.FileDispatcherImpl.lock(FileDispatcherImpl.java:94)
INFO   | jvm 1    | 2019/08/18 20:36:40 |       at 
sun.nio.ch.FileChannelImpl.lock(FileChannelImpl.java:1072)
INFO   | jvm 1    | 2019/08/18 20:36:40 |       at 
java.nio.channels.FileChannel.lock(FileChannel.java:1053)
INFO   | jvm 1    | 2019/08/18 20:36:40 |       at 
freenet.store.saltedhash.SaltedHashFreenetStore.openStoreFiles(SaltedHashFreenetStore.java:838)
INFO   | jvm 1    | 2019/08/18 20:36:40 |       at 
freenet.store.saltedhash.SaltedHashFreenetStore.<init>(SaltedHashFreenetStore.java:192)
INFO   | jvm 1    | 2019/08/18 20:36:40 |       at 
freenet.store.saltedhash.SaltedHashFreenetStore.construct(SaltedHashFreenetStore.java:149)
INFO   | jvm 1    | 2019/08/18 20:36:40 |       at 
freenet.node.Node.makeStore(Node.java:2980)
INFO   | jvm 1    | 2019/08/18 20:36:40 |       at 
freenet.node.Node.makeStore(Node.java:2973)
INFO   | jvm 1    | 2019/08/18 20:36:40 |       at 
freenet.node.Node.initSaltHashFS(Node.java:2803)
INFO   | jvm 1    | 2019/08/18 20:36:40 |       at 
freenet.node.Node.makeStore(Node.java:862)
INFO   | jvm 1    | 2019/08/18 20:36:40 |       at 
freenet.node.Node$StoreTypeCallback.set(Node.java:336)
INFO   | jvm 1    | 2019/08/18 20:36:40 |       at 
freenet.node.Node$StoreTypeCallback.set(Node.java:309)
INFO   | jvm 1    | 2019/08/18 20:36:40 |       at 
freenet.config.Option.set(Option.java:73)
INFO   | jvm 1    | 2019/08/18 20:36:40 |       at 
freenet.config.Option.setValue(Option.java:62)
INFO   | jvm 1    | 2019/08/18 20:36:40 |       at 
freenet.config.SubConfig.set(SubConfig.java:318)
INFO   | jvm 1    | 2019/08/18 20:36:40 |       at 
freenet.clients.http.wizardsteps.DATASTORE_SIZE._setDatastoreSize(DATASTORE_SIZE.java:122)
INFO   | jvm 1    | 2019/08/18 20:36:40 |       at 
freenet.clients.http.wizardsteps.DATASTORE_SIZE.postStep(DATASTORE_SIZE.java:93)
INFO   | jvm 1    | 2019/08/18 20:36:40 |       at 
freenet.clients.http.FirstTimeWizardToadlet.handleMethodPOST(FirstTimeWizardToadlet.java:262)
INFO   | jvm 1    | 2019/08/18 20:36:40 |       at 
sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
INFO   | jvm 1    | 2019/08/18 20:36:40 |       at 
sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62)
INFO   | jvm 1    | 2019/08/18 20:36:40 |       at 
sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
INFO   | jvm 1    | 2019/08/18 20:36:40 |       at 
java.lang.reflect.Method.invoke(Method.java:498)
INFO   | jvm 1    | 2019/08/18 20:36:40 |       at 
freenet.clients.http.ToadletContextImpl.callToadletMethod(ToadletContextImpl.java:747)
INFO   | jvm 1    | 2019/08/18 20:36:40 |       at 
freenet.clients.http.ToadletContextImpl.handle(ToadletContextImpl.java:660)
INFO   | jvm 1    | 2019/08/18 20:36:40 |       at 
freenet.clients.http.SimpleToadletServer$SocketHandler.run(SimpleToadletServer.java:1036)
INFO   | jvm 1    | 2019/08/18 20:36:40 |       at 
freenet.support.PooledExecutor$MyThread.innerRun(PooledExecutor.java:249)
INFO   | jvm 1    | 2019/08/18 20:36:40 |       at 
freenet.support.PooledExecutor$MyThread.realRun(PooledExecutor.java:189)
INFO   | jvm 1    | 2019/08/18 20:36:40 |       at 
freenet.support.io.NativeThread.run(NativeThread.java:156)
----8<----


> On Wed, Sep 25, 2019 at 8:07 PM, CyberLeo <[email protected] 
> <mailto:[email protected]>> wrote:
>> You know, I just realized I sent this from the wrong address and it
>> never made it to the list.
>>
>> On 8/19/19 2:10 AM, CyberLeo wrote:
>> > During test-setup of a new node from Github release build01484, I get
>> > the following exception, both during the new startup wizard and whenever
>> > I instruct the node to change the datastore type from ram to salt-hash.
>> > The store type remains as ram.
>> >
>> > The node is a VM running FreeBSD 11.3-RELEASE amd64, NFS-mounted home
>> > directory from the host, and the host filesystem is backed by a
>> > dedicated ZFS dataset with plenty of space.
>> >
>> > Any ideas on how to start troubleshooting the source of this error?
>> >
>> > Thanks!
>> >
>> > ----8<----
>> > Aug 18, 2019 20:36:40:281 (freenet.node.Node, HTTP socket
>> > handler@1389158290(3), ERROR): Unable to create new store
>> > freenet.node.NodeInitException: Operation not supported (3)
>> >     at freenet.node.Node.initSaltHashFS(Node.java:2900)
>> >     at freenet.node.Node.makeStore(Node.java:862)
>> >     at freenet.node.Node$StoreTypeCallback.set(Node.java:336)
>> >     at freenet.node.Node$StoreTypeCallback.set(Node.java:309)
>> >     at freenet.config.Option.set(Option.java:73)
>> >     at freenet.config.Option.setValue(Option.java:62)
>> >     at freenet.config.SubConfig.set(SubConfig.java:318)
>> >     at
>> > 
>> freenet.clients.http.wizardsteps.DATASTORE_SIZE._setDatastoreSize(DATASTORE_SIZE.java:122)
>> >
>> >     at
>> > 
>> freenet.clients.http.wizardsteps.DATASTORE_SIZE.postStep(DATASTORE_SIZE.java:93)
>> >
>> >     at
>> > 
>> freenet.clients.http.FirstTimeWizardToadlet.handleMethodPOST(FirstTimeWizardToadlet.java:262)
>> >
>> >     at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
>> >     at
>> > 
>> sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62)
>> >
>> >     at
>> > 
>> sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
>> >
>> >     at java.lang.reflect.Method.invoke(Method.java:498)
>> >     at
>> > 
>> freenet.clients.http.ToadletContextImpl.callToadletMethod(ToadletContextImpl.java:747)
>> >
>> >     at
>> > 
>> freenet.clients.http.ToadletContextImpl.handle(ToadletContextImpl.java:660)
>> >     at
>> > 
>> freenet.clients.http.SimpleToadletServer$SocketHandler.run(SimpleToadletServer.java:1036)
>> >
>> >     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)
>> > Aug 18, 2019 20:36:40:305
>> > (freenet.clients.http.wizardsteps.DATASTORE_SIZE, HTTP socket
>> > handler@1389158290(3), ERROR): Should not happen, please
>> > report!freenet.config.InvalidConfigValueException: Unable to create new
>> > store: freenet.node.NodeInitException: Operation not supported (3)
>> > freenet.config.InvalidConfigValueException: Unable to create new store:
>> > freenet.node.NodeInitException: Operation not supported (3)
>> >     at freenet.node.Node.makeStore(Node.java:868)
>> >     at freenet.node.Node$StoreTypeCallback.set(Node.java:336)
>> >     at freenet.node.Node$StoreTypeCallback.set(Node.java:309)
>> >     at freenet.config.Option.set(Option.java:73)
>> >     at freenet.config.Option.setValue(Option.java:62)
>> >     at freenet.config.SubConfig.set(SubConfig.java:318)
>> >     at
>> > 
>> freenet.clients.http.wizardsteps.DATASTORE_SIZE._setDatastoreSize(DATASTORE_SIZE.java:122)
>> >
>> >     at
>> > 
>> freenet.clients.http.wizardsteps.DATASTORE_SIZE.postStep(DATASTORE_SIZE.java:93)
>> >
>> >     at
>> > 
>> freenet.clients.http.FirstTimeWizardToadlet.handleMethodPOST(FirstTimeWizardToadlet.java:262)
>> >
>> >     at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
>> >     at
>> > 
>> sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62)
>> >
>> >     at
>> > 
>> sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
>> >
>> >     at java.lang.reflect.Method.invoke(Method.java:498)
>> >     at
>> > 
>> freenet.clients.http.ToadletContextImpl.callToadletMethod(ToadletContextImpl.java:747)
>> >
>> >     at
>> > 
>> freenet.clients.http.ToadletContextImpl.handle(ToadletContextImpl.java:660)
>> >     at
>> > 
>> freenet.clients.http.SimpleToadletServer$SocketHandler.run(SimpleToadletServer.java:1036)
>> >
>> >     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)
>> > ----8<----
>> >

-- 
Fuzzy love,
-CyberLeo

<[email protected]>
Technical Administrator

CyberLeo.Net Webhosting
http://www.CyberLeo.Net

Element9 Communications
http://www.Element9.net


Furry Peace! - http://www.fur.com/peace/