Permission denied when restarting the neo4j kubernetes pod

I have a deployment of neo4j which runs together with Azure (Azure-Files) and it works great - find below the yaml used to create the service and deployment.
I next fill my graph with nodes Question, Author, Translation and the TimeTree from GraphAware is attached (this all happens via neomodel in Django). The data is successfully mounted and I see the data stored in Azure, great! In the neo4j browser (port 7474 or 7473) I can view all nodes and play around with them, no problem.

However, the moment I shut down the pod, for example using:

kubectl scale deployment mygraph-deployment replicas=0 # stop the pod
kubectl scale deployment mygraph-deployment replicas=1 # start the pod

Something strange happens. If I now go to the browser and click on Question I see a limit of 25 Question nodes, great! However, if I click on Translation I get an error regarding permissions, see below.

As a note:

  1. I have experimented with both setting the environmental variables for authorisation, e.g.
Authentication
    - name: NEO4J_AUTH
      value: neo4j/mypass
  1. I have also tried removing the store_lock file in /data/databases/graph.db, but that made no impact either.
  2. When adding different nodes, the same behaviour is visible. Some can be viewed in the browser, whereas other cannot. For no clear reason.
  3. The files auth, auth.ini and roles are successfully created and mounted within the /data/dbms folder.

Any help is very welcome, thanks!

debug.log

2019-09-10 15:59:31.243+0000 ERROR [o.n.b.v.r.ErrorReporter] Client triggered an unexpected error [UnknownError]: java.io.IOException: Permission denied, reference 0f51f4b8-097a-491a-9648-8ee6eec75c86.
2019-09-10 15:59:31.243+0000 ERROR [o.n.b.v.r.ErrorReporter] Client triggered an unexpected error [UnknownError]: java.io.IOException: Permission denied, reference 0f51f4b8-097a-491a-9648-8ee6eec75c86. java.io.IOException: Permission denied
org.neo4j.kernel.impl.store.UnderlyingStorageException: java.io.IOException: Permission denied
	at org.neo4j.kernel.impl.store.StoreRecordCursor.next(StoreRecordCursor.java:87)
	at org.neo4j.kernel.impl.store.StoreRecordCursor.next(StoreRecordCursor.java:50)
	at org.neo4j.kernel.impl.api.store.StorePropertyPayloadCursor.readFromStore(StorePropertyPayloadCursor.java:291)
	at org.neo4j.kernel.impl.api.store.StorePropertyPayloadCursor.stringValue(StorePropertyPayloadCursor.java:210)
	at org.neo4j.kernel.impl.api.store.StorePropertyPayloadCursor.value(StorePropertyPayloadCursor.java:253)
	at org.neo4j.kernel.impl.api.store.StorePropertyCursor.value(StorePropertyCursor.java:106)
	at org.neo4j.kernel.impl.core.NodeProxy.getAllProperties(NodeProxy.java:423)
	at org.neo4j.kernel.impl.util.NodeProxyWrappingNodeValue.properties(NodeProxyWrappingNodeValue.java:111)
	at org.neo4j.kernel.impl.util.NodeProxyWrappingNodeValue.writeTo(NodeProxyWrappingNodeValue.java:59)
	at org.neo4j.bolt.v1.messaging.Neo4jPack$Packer.pack(Neo4jPack.java:86)
	at org.neo4j.bolt.v1.messaging.BoltResponseMessageWriter.onRecord(BoltResponseMessageWriter.java:75)
	at org.neo4j.bolt.v1.messaging.BoltMessageRouter$ResultHandler$1.visit(BoltMessageRouter.java:153)
	at org.neo4j.bolt.v1.runtime.CypherAdapterStream.lambda$accept$0(CypherAdapterStream.java:78)
	at org.neo4j.cypher.internal.compiler.v3_3.generated.GeneratedExecutionPlan626997086318577Execution.accept(Unknown Source)
	at org.neo4j.cypher.internal.compatibility.v3_3.runtime.compiled.CompiledExecutionResult.accept(CompiledExecutionResult.scala:53)
	at org.neo4j.cypher.internal.compatibility.ClosingExecutionResult$$anonfun$accept$2.apply$mcV$sp(ClosingExecutionResult.scala:175)
	at org.neo4j.cypher.internal.compatibility.ClosingExecutionResult$$anonfun$accept$2.apply(ClosingExecutionResult.scala:174)
	at org.neo4j.cypher.internal.compatibility.ClosingExecutionResult$$anonfun$accept$2.apply(ClosingExecutionResult.scala:174)
	at org.neo4j.cypher.internal.compatibility.v3_3.exceptionHandler$runSafely$.apply(exceptionHandler.scala:90)
	at org.neo4j.cypher.internal.compatibility.ClosingExecutionResult.accept(ClosingExecutionResult.scala:174)
	at org.neo4j.bolt.v1.runtime.CypherAdapterStream.accept(CypherAdapterStream.java:76)
	at org.neo4j.bolt.v1.messaging.BoltMessageRouter$ResultHandler.onRecords(BoltMessageRouter.java:146)
	at org.neo4j.bolt.v1.runtime.BoltStateMachine$State$3.lambda$pullAll$0(BoltStateMachine.java:462)
	at org.neo4j.bolt.v1.runtime.TransactionStateMachine$State$1.streamResult(TransactionStateMachine.java:271)
	at org.neo4j.bolt.v1.runtime.TransactionStateMachine.streamResult(TransactionStateMachine.java:105)
	at org.neo4j.bolt.v1.runtime.BoltStateMachine$State$3.pullAll(BoltStateMachine.java:461)
	at org.neo4j.bolt.v1.runtime.BoltStateMachine.pullAll(BoltStateMachine.java:236)
	at org.neo4j.bolt.v1.messaging.BoltMessageRouter.lambda$onPullAll$6(BoltMessageRouter.java:114)
	at org.neo4j.bolt.v1.runtime.concurrent.RunnableBoltWorker.execute(RunnableBoltWorker.java:152)
	at org.neo4j.bolt.v1.runtime.concurrent.RunnableBoltWorker.executeBatch(RunnableBoltWorker.java:145)
	at org.neo4j.bolt.v1.runtime.concurrent.RunnableBoltWorker.run(RunnableBoltWorker.java:110)
	at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:511)
	at java.util.concurrent.FutureTask.run(FutureTask.java:266)
	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)
	at org.neo4j.helpers.NamedThreadFactory$2.run(NamedThreadFactory.java:109)
Caused by: java.io.IOException: Permission denied
	at sun.nio.ch.FileDispatcherImpl.pread0(Native Method)
	at sun.nio.ch.FileDispatcherImpl.pread(FileDispatcherImpl.java:52)
	at sun.nio.ch.IOUtil.readIntoNativeBuffer(IOUtil.java:220)
	at sun.nio.ch.IOUtil.read(IOUtil.java:192)
	at sun.nio.ch.FileChannelImpl.readInternal(FileChannelImpl.java:735)
	at sun.nio.ch.FileChannelImpl.read(FileChannelImpl.java:721)
	at org.neo4j.io.fs.StoreFileChannel.read(StoreFileChannel.java:105)
	at org.neo4j.io.pagecache.impl.SingleFilePageSwapper.swapIn(SingleFilePageSwapper.java:237)
	at org.neo4j.io.pagecache.impl.SingleFilePageSwapper.read(SingleFilePageSwapper.java:292)
	at org.neo4j.io.pagecache.impl.muninn.PageList.fault(PageList.java:446)
	at org.neo4j.io.pagecache.impl.muninn.MuninnPageCursor.pageFault(MuninnPageCursor.java:372)
	at org.neo4j.io.pagecache.impl.muninn.MuninnPageCursor.uncommonPin(MuninnPageCursor.java:321)
	at org.neo4j.io.pagecache.impl.muninn.MuninnPageCursor.pin(MuninnPageCursor.java:295)
	at org.neo4j.io.pagecache.impl.muninn.MuninnReadPageCursor.next(MuninnReadPageCursor.java:61)
	at org.neo4j.io.pagecache.impl.muninn.MuninnPageCursor.next(MuninnPageCursor.java:127)
	at org.neo4j.kernel.impl.store.CommonAbstractStore.readIntoRecord(CommonAbstractStore.java:1069)
	at org.neo4j.kernel.impl.store.StoreRecordCursor.next(StoreRecordCursor.java:82)
	... 36 more

security.log

2019-09-10 15:59:21.913+0000 ERROR []: failed to log in: invalid principal or credentials
2019-09-10 15:59:22.337+0000 INFO  [neo4j]: logged in
2019-09-10 15:59:23.729+0000 INFO  [neo4j]: logged in
2019-09-10 15:59:23.846+0000 INFO  [neo4j]: logged in
2019-09-10 15:59:23.892+0000 INFO  [neo4j]: logged in
2019-09-10 15:59:23.997+0000 INFO  [neo4j]: logged in
2019-09-10 15:59:25.510+0000 INFO  [neo4j]: logged in
2019-09-10 15:59:27.669+0000 INFO  [neo4j]: logged in
2019-09-10 15:59:28.685+0000 INFO  [neo4j]: logged in
2019-09-10 15:59:28.723+0000 INFO  [neo4j]: logged in
2019-09-10 15:59:29.334+0000 INFO  [neo4j]: logged in
2019-09-10 15:59:31.026+0000 INFO  [neo4j]: logged in
2019-09-10 15:59:43.480+0000 INFO  [neo4j]: logged in
2019-09-10 15:59:43.527+0000 INFO  [neo4j]: logged in
2019-09-10 15:59:44.041+0000 INFO  [neo4j]: logged in
2019-09-10 16:00:03.784+0000 INFO  [neo4j]: logged in
2019-09-10 16:00:03.822+0000 INFO  [neo4j]: logged in
2019-09-10 16:00:04.410+0000 INFO  [neo4j]: logged in

Graph yaml

apiVersion: v1
kind: Service
metadata:
  name: myservice
spec:
  selector:
    app: mygraph
  ports:
    - name: bolt
      protocol: TCP
      port: 7687
      targetPort: 7687
      nodePort: 30076
    - name: http
      protocol: TCP
      port: 7474
      targetPort: 7474
      nodePort: 30074
    - name: https
      protocol: TCP
      port: 7473
      targetPort: 7473
      nodePort: 30073
  type: LoadBalancer
  loadBalancerIP: 40.118.172.46
---
apiVersion: apps/v1
kind: Deployment
metadata:
  name: mygraph-deployment
  labels:
    app: mygraph
spec:
  replicas: 1
  selector:
    matchLabels:
      app: mygraph
  template:
    metadata:
      labels:
        app: mygraph
    spec:
      containers:
      - name: mygraph
        image: mycontainer.azurecr.io/mygraph:dev
        securityContext:
          privileged: true
        ports:
        - containerPort: 7687
        - containerPort: 7474
        - containerPort: 7473
        env:
          - name: NEO4J_dbms_jvm_additional
            value: "-Xms512m -Xmx6g"
        # When adding the below lines the deployment failes. Without it, it works great!
        volumeMounts:
        - name: neo4jdata
          mountPath: /var/lib/neo4j/data/
      volumes:
        - name: neo4jdata
          persistentVolumeClaim:
            claimName: azurefile

This sure looks like a variant of exactly the same problem you had before:

The giveaway here is:

org.neo4j.kernel.impl.store.UnderlyingStorageException: java.io.IOException: Permission denied

Again, I'm not sure how Azure storage works, but that's where to look. This suggests that when you scaled to zero and then scaled back to 1, something about the file permissions changed. I don't really know what would have happened, because it probably has to do with either the way you set up the kubernetes pod, or the way Azure storage works. But at a minimum -- that error is ultra clear. The Neo4j process inside of the docker container doesn't have permissions to write data to necessary files.

Something changed in the scaling operation.

Hi David, thank you for responding. I am contacting Azure again on this one. Hopefully they can help me any further. Whenever the answer becomes clear (or when it doesn't) I'll come back here.

Hi @david_allen,

I have been trying to isolate the issue, and I think I reached a point where you may be of help. First of all, as with my previous question, I am using neo4j 3.3.9.

I have been running in development mode, meaning, I disabled all plugins and use the following yaml:

apiVersion: apps/v1
kind: StatefulSet
metadata:
  name: mygraph
  labels:
    app: mygraph
spec:
  serviceName: mygraph
  replicas: 1
  selector:
    matchLabels:
      app: mygraph
  template:
    metadata:
      labels:
        app: mygraph
    spec:
      containers:
      - name: mygraph
        image: mycontainer.azurecr.io/mygraph
        command: ["/bin/bash", "-c", "sleep 30000"] 
        securityContext:
          runAsUser: 0 
        ports:
        - containerPort: 7687
        - containerPort: 7474
        - containerPort: 7473
        volumeMounts:
        - name: neo4jmount
          mountPath: /data
          subPath: data
        - mountPath: /logs
          name: neo4jmount
          subPath: logs
        env:
          - name: AUTH_ENABLED
            value: "true"
          - name: NEO4J_SECRETS_PASSWORD
            value: "mypass"
          # Java
          - name: NEO4J_dbms_memory_heap_initial__size
            value: 512m
          - name: NEO4J_dbms_memory_heap_max__size
            value: 6G
          - name: NEO4J_dbms_jvm_additional
            value: "-Xms512m -Xmx6g"

When the pod is running I enter the pod's bash

kubectl exec -it mygraph-0 /bin/bash

There I start Neo4j

/docker-entrypoint.sh "neo4j"

Now I add some nodes, which are successfully created in neo4j.

Then I do a hard kill by running

kill -9 [neo4j-pid]

Now I start Neo4j again using the entrypoint as above, and everything again works well. No issues. I can work around in the browser just fine.
Now I repeat this whole process but instead of the hard kill I trigger a Neo4j shutdown by doing

kill [neo4j-pid]

Neo4j again starts up, but now if I want to view a particular node in the browser I get the permission denied error, as the previous time:

2019-09-12 11:25:15.440+0000 ERROR Client triggered an unexpected error [UnknownError]: java.io.IOException: Permission denied, reference d0a1f12d-27a0-4c4d-ab7f-e747b21cd876.
Now, as you can see, I have not done anything particular with the Azure Storage. It seems to be some behaviour triggered by neo4j.

It thus seems that something in the shutdown of neo4j is particularly different sets different rights on folders and/or files. Could that indeed be the case? Or do you notice anything else that might help me solve this issue?

Thank you!

As additional information:

  1. the pod/container is not closed during the above test
  2. the right that are given to the /data directory within Azure are created out of the StorageClass below.
  3. if we remove the rows on uid and gid, and therefore setting permission for everyone to read, write and execute, it still gives the same results.
  4. When we get into the bash of the container as either root or neo4j user, we can add, modify and delete files in the graph.db folder.
  5. Together with Azure Support I have run through all possible verifications to check on permission issues, and they believe it to be an application issue.
kind: StorageClass
apiVersion: storage.k8s.io/v1
metadata:
  name: azurefile-neo4j
provisioner: kubernetes.io/azure-file
reclaimPolicy: Retain
allowVolumeExpansion: true
mountOptions:
  - dir_mode=0777
  - file_mode=0777
  - uid=100 # provide access to neo4j
  - gid=101
parameters:
  skuName: Standard_LRS

I am really not sure here. I'm not trying to say that this isn't a Neo4j bug, but I can't think of anything in our software that could cause the symptom you're talking about. You can inspect the docker-entrypoint.sh script if you like, what it does with the files on disk before Neo4j even starts can be found there.

A thing that I do not understand about your configuration, which I would urge you to understand here before proceeding, is the connection between the StorageClass (which you showed the definition) and the Volume. In our Neo4j helm charts, typically we use PersistentVolumeClaims, and not regular volumes. The Persistent bit is important, because typically you'd otherwise be creating a new volume every time you restarted the docker container.

I'm not saying that's the error here, it's just my speculation. I can't be sure of this because I'm not familiar with Azure kubernetes, or with how Azure file storage provides for volumes on Azure kubernetes.

Hi @david_allen,

Regarding the StorageClass and PersistentVolumeClaim: I have a StorageClass and a PersistentVolumeClaim. Based on that claim, which refers to the StorageClass a PersistentVolume is dynamically created, with the retain property. Therefore when reinitiating Neo4j the database doesn't start empty but continues in the state it left after shutdown (or force stop). Find below my PersistentVolumeClaim yaml.

In the next reply I'll share a log of the first scenario - the one that results in an error - of the two scenarios I described above. Let me restate:

  1. In the first scenario I startup Neo4j on a container within the bash using /docker-entrypoint.sh "neo4j". Then I add some data to Neo4j and I shut down Neo4j. Then continuing on the same container, I restart Neo4j. Then when I try to view some node in the browser I get the permission denied error. See the log below that starts as of the shutdown of Neo4j.
  2. In the second scenario I startup Neo4j on a (new - so unrelated to scenario 1) container, again via de bash using /docker-entrypoint.sh "neo4j". Then I add the exact same data as in scenario 1, via the exact same process. Now I do a forced kill kill -9 [neo4j-pid], so no need shutdown, which can be seen in the log. Now I start Neo4j again via the same entrypoint and try to view the same node as in scenario 1, and no errors!

Do the logs below provide you with any information that might be helpful to solve this issue?

I am further investigating also with the Azure team, but they are clueless after we opened up all rights for all users.

PS. I cant share more of the log due to restrictions on the amount of characters.

The peristent volume claim

apiVersion: v1
kind: PersistentVolumeClaim
metadata:
  name: pvc-neo4j
spec:
  accessModes:
    - ReadWriteOnce
  storageClassName: azurefile-neo4j
  resources:
    requests:
      storage: 10Gi

StorageClass*

kind: StorageClass
apiVersion: storage.k8s.io/v1
metadata:
  name: azurefile-neo4j
provisioner: kubernetes.io/azure-file
reclaimPolicy: Retain
allowVolumeExpansion: true
mountOptions:
  - dir_mode=0777
  - file_mode=0777
  - uid=100 # same errors when removeing the lines on uid and gid
  - gid=101

Log of the scenario where Neo4j is startup and shutdown which results in an error
If we do the same with a force kill, there are no issues.

2019-09-13 12:16:28.847+0000 INFO [o.n.k.i.f.GraphDatabaseFacadeFactory] Shutdown started
2019-09-13 12:16:28.847+0000 INFO [o.n.k.i.f.GraphDatabaseFacadeFactory] Database is now unavailable
2019-09-13 12:16:28.850+0000 INFO [o.n.k.i.t.l.c.CheckPointerImpl] Check Pointing triggered by database shutdown [16]:  Starting check pointing...
2019-09-13 12:16:28.850+0000 INFO [o.n.k.i.t.l.c.CheckPointerImpl] Check Pointing triggered by database shutdown [16]:  Starting store flush...
2019-09-13 12:16:28.883+0000 INFO [o.n.k.i.s.c.CountsTracker] About to rotate counts store at transaction 16 to [/var/lib/neo4j/data/databases/graph.db/neostore.counts.db.b], from [/var/lib/neo4j/data/databases/graph.db/neostore.counts.db.a].
2019-09-13 12:16:28.950+0000 INFO [o.n.k.i.s.c.CountsTracker] Successfully rotated counts store at transaction 16 to [/var/lib/neo4j/data/databases/graph.db/neostore.counts.db.b], from [/var/lib/neo4j/data/databases/graph.db/neostore.counts.db.a].
2019-09-13 12:16:29.112+0000 INFO [o.n.k.i.t.l.c.CheckPointerImpl] Check Pointing triggered by database shutdown [16]:  Store flush completed
2019-09-13 12:16:29.112+0000 INFO [o.n.k.i.t.l.c.CheckPointerImpl] Check Pointing triggered by database shutdown [16]:  Starting appending check point entry into the tx log...
2019-09-13 12:16:29.139+0000 INFO [o.n.k.i.t.l.c.CheckPointerImpl] Check Pointing triggered by database shutdown [16]:  Appending check point entry into the tx log completed
2019-09-13 12:16:29.139+0000 INFO [o.n.k.i.t.l.c.CheckPointerImpl] Check Pointing triggered by database shutdown [16]:  Check pointing completed
2019-09-13 12:16:29.139+0000 INFO [o.n.k.i.t.l.p.LogPruningImpl] Log Rotation [0]:  Starting log pruning.
2019-09-13 12:16:29.140+0000 INFO [o.n.k.i.t.l.p.LogPruningImpl] Log Rotation [0]:  Log pruning complete.
2019-09-13 12:16:30.696+0000 INFO [o.n.k.i.DiagnosticsManager] --- STOPPING diagnostics START ---
2019-09-13 12:16:30.697+0000 INFO [o.n.k.i.DiagnosticsManager] --- STOPPING diagnostics END ---
2019-09-13 12:16:39.118+0000 INFO [o.n.k.i.f.CommunityEditionModule] No locking implementation specified, defaulting to 'community'
2019-09-13 12:16:39.360+0000 INFO [o.n.k.AvailabilityGuard] Requirement makes database unavailable: Database available
2019-09-13 12:16:39.395+0000 INFO [o.n.k.i.DiagnosticsManager] --- INITIALIZED diagnostics START ---
2019-09-13 12:16:39.396+0000 INFO [o.n.k.i.DiagnosticsManager] Neo4j Kernel properties:
2019-09-13 12:16:39.396+0000 INFO [o.n.k.i.DiagnosticsManager] cypher.lenient_create_relationship=true
2019-09-13 12:16:39.396+0000 INFO [o.n.k.i.DiagnosticsManager] dbms.connector.http.enabled=true
2019-09-13 12:16:39.396+0000 INFO [o.n.k.i.DiagnosticsManager] causal_clustering.discovery_listen_address=0.0.0.0:5000
2019-09-13 12:16:39.396+0000 INFO [o.n.k.i.DiagnosticsManager] dbms.security.auth_enabled=true
2019-09-13 12:16:39.396+0000 INFO [o.n.k.i.DiagnosticsManager] dbms.connector.http.listen_address=0.0.0.0:7474
2019-09-13 12:16:39.396+0000 INFO [o.n.k.i.DiagnosticsManager] unsupported.dbms.directories.neo4j_home=/var/lib/neo4j
2019-09-13 12:16:39.397+0000 INFO [o.n.k.i.DiagnosticsManager] causal_clustering.raft_advertised_address=vilansgraph-0:7000
2019-09-13 12:16:39.397+0000 INFO [o.n.k.i.DiagnosticsManager] dbms.directories.import=import
2019-09-13 12:16:39.397+0000 INFO [o.n.k.i.DiagnosticsManager] dbms.memory.heap.initial_size=512m
2019-09-13 12:16:39.397+0000 INFO [o.n.k.i.DiagnosticsManager] causal_clustering.raft_listen_address=0.0.0.0:7000
2019-09-13 12:16:39.397+0000 INFO [o.n.k.i.DiagnosticsManager] ACCEPT.LICENSE.AGREEMENT=yes
2019-09-13 12:16:39.397+0000 INFO [o.n.k.i.DiagnosticsManager] ha.host.coordination=vilansgraph-0:5001
2019-09-13 12:16:39.397+0000 INFO [o.n.k.i.DiagnosticsManager] dbms.connector.https.enabled=true
2019-09-13 12:16:39.397+0000 INFO [o.n.k.i.DiagnosticsManager] dbms.jvm.additional=-Xms512m -Xmx6g
2019-09-13 12:16:39.397+0000 INFO [o.n.k.i.DiagnosticsManager] dbms.tx_log.rotation.retention_policy=100M size
2019-09-13 12:16:39.397+0000 INFO [o.n.k.i.DiagnosticsManager] dbms.memory.heap.max_size=6G
2019-09-13 12:16:39.398+0000 INFO [o.n.k.i.DiagnosticsManager] dbms.connectors.default_listen_address=0.0.0.0
2019-09-13 12:16:39.398+0000 INFO [o.n.k.i.DiagnosticsManager] EDITION=community
2019-09-13 12:16:39.398+0000 INFO [o.n.k.i.DiagnosticsManager] dbms.security.procedures.unrestricted=apoc.*,graphql.*,algo.*,ga.timetree.*
2019-09-13 12:16:39.398+0000 INFO [o.n.k.i.DiagnosticsManager] dbms.windows_service_name=neo4j
2019-09-13 12:16:39.398+0000 INFO [o.n.k.i.DiagnosticsManager] dbms.connector.https.listen_address=0.0.0.0:7473
2019-09-13 12:16:39.398+0000 INFO [o.n.k.i.DiagnosticsManager] dbms.connector.bolt.listen_address=0.0.0.0:7687
2019-09-13 12:16:39.398+0000 INFO [o.n.k.i.DiagnosticsManager] causal_clustering.transaction_advertised_address=vilansgraph-0:6000
2019-09-13 12:16:39.398+0000 INFO [o.n.k.i.DiagnosticsManager] causal_clustering.discovery_advertised_address=vilansgraph-0:5000
2019-09-13 12:16:39.398+0000 INFO [o.n.k.i.DiagnosticsManager] dbms.memory.pagecache.size=512M
2019-09-13 12:16:39.398+0000 INFO [o.n.k.i.DiagnosticsManager] ha.host.data=vilansgraph-0:6001
2019-09-13 12:16:39.399+0000 INFO [o.n.k.i.DiagnosticsManager] unsupported.dbms.edition=community
2019-09-13 12:16:39.399+0000 INFO [o.n.k.i.DiagnosticsManager] dbms.directories.logs=/logs
2019-09-13 12:16:39.399+0000 INFO [o.n.k.i.DiagnosticsManager] dbms.connector.bolt.enabled=true
2019-09-13 12:16:39.399+0000 INFO [o.n.k.i.DiagnosticsManager] causal_clustering.transaction_listen_address=0.0.0.0:6000
2019-09-13 12:16:39.399+0000 INFO [o.n.k.i.DiagnosticsManager] wrapper.java.additional=-Dneo4j.ext.udc.source=docker
2019-09-13 12:16:39.399+0000 INFO [o.n.k.i.DiagnosticsManager] dbms.security.procedures.whitelist=apoc.*,graphql.*,algo.*,ga.timetree.*
2019-09-13 12:16:39.399+0000 INFO [o.n.k.i.DiagnosticsManager] Diagnostics providers:
2019-09-13 12:16:39.399+0000 INFO [o.n.k.i.DiagnosticsManager] org.neo4j.kernel.configuration.Config
2019-09-13 12:16:39.400+0000 INFO [o.n.k.i.DiagnosticsManager] org.neo4j.kernel.info.DiagnosticsManager
2019-09-13 12:16:39.400+0000 INFO [o.n.k.i.DiagnosticsManager] SYSTEM_MEMORY
2019-09-13 12:16:39.400+0000 INFO [o.n.k.i.DiagnosticsManager] JAVA_MEMORY
2019-09-13 12:16:39.401+0000 INFO [o.n.k.i.DiagnosticsManager] OPERATING_SYSTEM
2019-09-13 12:16:39.401+0000 INFO [o.n.k.i.DiagnosticsManager] JAVA_VIRTUAL_MACHINE
2019-09-13 12:16:39.401+0000 INFO [o.n.k.i.DiagnosticsManager] CLASSPATH
2019-09-13 12:16:39.402+0000 INFO [o.n.k.i.DiagnosticsManager] LIBRARY_PATH
2019-09-13 12:16:39.402+0000 INFO [o.n.k.i.DiagnosticsManager] SYSTEM_PROPERTIES
2019-09-13 12:16:39.402+0000 INFO [o.n.k.i.DiagnosticsManager] LINUX_SCHEDULERS
2019-09-13 12:16:39.402+0000 INFO [o.n.k.i.DiagnosticsManager] NETWORK
2019-09-13 12:16:39.402+0000 INFO [o.n.k.i.DiagnosticsManager] System memory information:
2019-09-13 12:16:39.409+0000 INFO [o.n.k.i.DiagnosticsManager] Total Physical memory: 6.78 GB
2019-09-13 12:16:39.410+0000 INFO [o.n.k.i.DiagnosticsManager] Free Physical memory: 4.11 GB
2019-09-13 12:16:39.412+0000 INFO [o.n.k.i.DiagnosticsManager] Committed virtual memory: 7.37 GB
2019-09-13 12:16:39.412+0000 INFO [o.n.k.i.DiagnosticsManager] Total swap space: 0.00 B
2019-09-13 12:16:39.412+0000 INFO [o.n.k.i.DiagnosticsManager] Free swap space: 0.00 B
2019-09-13 12:16:39.413+0000 INFO [o.n.k.i.DiagnosticsManager] JVM memory information:
2019-09-13 12:16:39.413+0000 INFO [o.n.k.i.DiagnosticsManager] Free  memory: 402.03 MB
2019-09-13 12:16:39.413+0000 INFO [o.n.k.i.DiagnosticsManager] Total memory: 494.94 MB
2019-09-13 12:16:39.413+0000 INFO [o.n.k.i.DiagnosticsManager] Max   memory: 5.80 GB
2019-09-13 12:16:39.415+0000 INFO [o.n.k.i.DiagnosticsManager] Garbage Collector: Copy: [Eden Space, Survivor Space]
2019-09-13 12:16:39.415+0000 INFO [o.n.k.i.DiagnosticsManager] Garbage Collector: MarkSweepCompact: [Eden Space, Survivor Space, Tenured Gen]
2019-09-13 12:16:39.415+0000 INFO [o.n.k.i.DiagnosticsManager] Memory Pool: Code Cache (Non-heap memory): committed=5.00 MB, used=4.92 MB, max=240.00 MB, threshold=0.00 B
2019-09-13 12:16:39.416+0000 INFO [o.n.k.i.DiagnosticsManager] Memory Pool: Metaspace (Non-heap memory): committed=15.25 MB, used=14.27 MB, max=-1.00 B, threshold=0.00 B
2019-09-13 12:16:39.416+0000 INFO [o.n.k.i.DiagnosticsManager] Memory Pool: Compressed Class Space (Non-heap memory): committed=2.00 MB, used=1.74 MB, max=1.00 GB, threshold=0.00 B
2019-09-13 12:16:39.416+0000 INFO [o.n.k.i.DiagnosticsManager] Memory Pool: Eden Space (Heap memory): committed=136.50 MB, used=92.91 MB, max=1.60 GB, threshold=?
2019-09-13 12:16:39.416+0000 INFO [o.n.k.i.DiagnosticsManager] Memory Pool: Survivor Space (Heap memory): committed=17.06 MB, used=0.00 B, max=204.75 MB, threshold=?
2019-09-13 12:16:39.416+0000 INFO [o.n.k.i.DiagnosticsManager] Memory Pool: Tenured Gen (Heap memory): committed=341.38 MB, used=0.00 B, max=4.00 GB, threshold=0.00 B
2019-09-13 12:16:39.416+0000 INFO [o.n.k.i.DiagnosticsManager] Operating system information:
2019-09-13 12:16:39.417+0000 INFO [o.n.k.i.DiagnosticsManager] Operating System: Linux; version: 4.15.0-1052-azure; arch: amd64; cpus: 1
2019-09-13 12:16:39.417+0000 INFO [o.n.k.i.DiagnosticsManager] Max number of file descriptors: 1048576
2019-09-13 12:16:39.417+0000 INFO [o.n.k.i.DiagnosticsManager] Number of open file descriptors: 103
2019-09-13 12:16:39.419+0000 INFO [o.n.k.i.DiagnosticsManager] Process id: 425@vilansgraph-0.vilansgraph.default.svc.cluster.local
2019-09-13 12:16:39.419+0000 INFO [o.n.k.i.DiagnosticsManager] Byte order: LITTLE_ENDIAN
2019-09-13 12:16:39.428+0000 INFO [o.n.k.i.DiagnosticsManager] Local timezone: GMT
2019-09-13 12:16:39.428+0000 INFO [o.n.k.i.DiagnosticsManager] JVM information:
2019-09-13 12:16:39.429+0000 INFO [o.n.k.i.DiagnosticsManager] VM Name: OpenJDK 64-Bit Server VM
2019-09-13 12:16:39.429+0000 INFO [o.n.k.i.DiagnosticsManager] VM Vendor: IcedTea
2019-09-13 12:16:39.429+0000 INFO [o.n.k.i.DiagnosticsManager] VM Version: 25.212-b04
2019-09-13 12:16:39.429+0000 INFO [o.n.k.i.DiagnosticsManager] JIT compiler: HotSpot 64-Bit Tiered Compilers
2019-09-13 12:16:39.430+0000 INFO [o.n.k.i.DiagnosticsManager] VM Arguments: [-Xms512m, -Xmx6G, -Xms512m, -Xmx6g, -Dfile.encoding=UTF-8]

[java classpath..]

2019-09-13 12:16:40.194+0000 INFO [o.n.k.i.s.f.RecordFormatSelector] Selected RecordFormat:StandardV3_2[v0.A.8] record format from store /var/lib/neo4j/data/databases/graph.db
2019-09-13 12:16:40.341+0000 INFO [o.n.k.i.s.f.RecordFormatSelector] Selected RecordFormat:StandardV3_2[v0.A.8] record format from store /var/lib/neo4j/data/databases/graph.db
2019-09-13 12:16:40.341+0000 INFO [o.n.k.i.s.f.RecordFormatSelector] Format not configured. Selected format from the store: RecordFormat:StandardV3_2[v0.A.8]
2019-09-13 12:16:42.530+0000 INFO [o.n.k.i.a.i.IndexingService] IndexingService.init: indexes not specifically mentioned above are null
2019-09-13 12:16:42.789+0000 INFO [o.n.k.NeoStoreDataSource] No commits found after last check point (which is at LogPosition{logVersion=0, byteOffset=2071193})
2019-09-13 12:16:42.810+0000 INFO [o.n.k.i.a.i.IndexingService] IndexingService.start: indexes not specifically mentioned above are null
2019-09-13 12:16:42.825+0000 INFO [o.n.k.i.DatabaseHealth] Database health set to OK
2019-09-13 12:16:43.427+0000 INFO [o.n.k.AvailabilityGuard] Fulfilling of requirement makes database available: Database available
2019-09-13 12:16:43.427+0000 INFO [o.n.k.i.f.GraphDatabaseFacadeFactory] Database is now ready
2019-09-13 12:16:43.429+0000 INFO [o.n.k.i.DiagnosticsManager] --- STARTED diagnostics for KernelDiagnostics:Versions START ---
2019-09-13 12:16:43.431+0000 INFO [o.n.k.i.DiagnosticsManager] Graph Database: community single StoreId{creationTime=1568376789822, randomId=-8172356107186671854, storeVersion=15813456178476550, upgradeTime=1568376789822, upgradeId=1}
2019-09-13 12:16:43.431+0000 INFO [o.n.k.i.DiagnosticsManager] Kernel version: 3.3.9,b0aa20af1715cad17b833fe09b0078693fd680e1
2019-09-13 12:16:43.431+0000 INFO [o.n.k.i.DiagnosticsManager] --- STARTED diagnostics for KernelDiagnostics:Versions END ---
2019-09-13 12:16:43.434+0000 INFO [o.n.k.i.DiagnosticsManager] --- STARTED diagnostics for NEO_STORE_VERSIONS START ---
2019-09-13 12:16:43.434+0000 INFO [o.n.k.i.DiagnosticsManager] Store versions:
2019-09-13 12:16:43.434+0000 INFO [o.n.k.i.DiagnosticsManager] Store versions:
2019-09-13 12:16:43.434+0000 INFO [o.n.k.i.DiagnosticsManager]   ArrayPropertyStore v0.A.8
2019-09-13 12:16:43.434+0000 INFO [o.n.k.i.DiagnosticsManager]   NodeStore v0.A.8
2019-09-13 12:16:43.434+0000 INFO [o.n.k.i.DiagnosticsManager]   StringPropertyStore v0.A.8
2019-09-13 12:16:43.434+0000 INFO [o.n.k.i.DiagnosticsManager]   PropertyIndexStore v0.A.8
2019-09-13 12:16:43.435+0000 INFO [o.n.k.i.DiagnosticsManager]   StringPropertyStore v0.A.8
2019-09-13 12:16:43.435+0000 INFO [o.n.k.i.DiagnosticsManager]   ArrayPropertyStore v0.A.8
2019-09-13 12:16:43.435+0000 INFO [o.n.k.i.DiagnosticsManager]   PropertyStore v0.A.8
2019-09-13 12:16:43.435+0000 INFO [o.n.k.i.DiagnosticsManager]   RelationshipStore v0.A.8
2019-09-13 12:16:43.435+0000 INFO [o.n.k.i.DiagnosticsManager]   StringPropertyStore v0.A.8
2019-09-13 12:16:43.436+0000 INFO [o.n.k.i.DiagnosticsManager]   RelationshipTypeStore v0.A.8
2019-09-13 12:16:43.436+0000 INFO [o.n.k.i.DiagnosticsManager]   StringPropertyStore v0.A.8
2019-09-13 12:16:43.436+0000 INFO [o.n.k.i.DiagnosticsManager]   LabelTokenStore v0.A.8
2019-09-13 12:16:43.436+0000 INFO [o.n.k.i.DiagnosticsManager]   SchemaStore v0.A.8
2019-09-13 12:16:43.436+0000 INFO [o.n.k.i.DiagnosticsManager]   RelationshipGroupStore v0.A.8
2019-09-13 12:16:43.436+0000 INFO [o.n.k.i.DiagnosticsManager]   NeoStore v0.A.8
2019-09-13 12:16:43.437+0000 INFO [o.n.k.i.DiagnosticsManager] --- STARTED diagnostics for NEO_STORE_VERSIONS END ---
2019-09-13 12:16:43.437+0000 INFO [o.n.k.i.DiagnosticsManager] --- STARTED diagnostics for NEO_STORE_ID_USAGE START ---
2019-09-13 12:16:43.437+0000 INFO [o.n.k.i.DiagnosticsManager] Id usage:
2019-09-13 12:16:43.441+0000 INFO [o.n.k.i.DiagnosticsManager] Id usage:
2019-09-13 12:16:43.441+0000 INFO [o.n.k.i.DiagnosticsManager]   ArrayPropertyStore: used=1 high=0
2019-09-13 12:16:43.441+0000 INFO [o.n.k.i.DiagnosticsManager]   NodeStore: used=5470 high=5499
2019-09-13 12:16:43.441+0000 INFO [o.n.k.i.DiagnosticsManager]   StringPropertyStore: used=10 high=9
2019-09-13 12:16:43.441+0000 INFO [o.n.k.i.DiagnosticsManager]   PropertyIndexStore: used=9 high=8
2019-09-13 12:16:43.441+0000 INFO [o.n.k.i.DiagnosticsManager]   StringPropertyStore: used=3687 high=3720
2019-09-13 12:16:43.442+0000 INFO [o.n.k.i.DiagnosticsManager]   ArrayPropertyStore: used=1 high=0
2019-09-13 12:16:43.442+0000 INFO [o.n.k.i.DiagnosticsManager]   PropertyStore: used=13703 high=13719
2019-09-13 12:16:43.442+0000 INFO [o.n.k.i.DiagnosticsManager]   RelationshipStore: used=0 high=-1
2019-09-13 12:16:43.442+0000 INFO [o.n.k.i.DiagnosticsManager]   StringPropertyStore: used=1 high=0
2019-09-13 12:16:43.442+0000 INFO [o.n.k.i.DiagnosticsManager]   RelationshipTypeStore: used=0 high=-1
2019-09-13 12:16:43.442+0000 INFO [o.n.k.i.DiagnosticsManager]   StringPropertyStore: used=4 high=3
2019-09-13 12:16:43.442+0000 INFO [o.n.k.i.DiagnosticsManager]   LabelTokenStore: used=3 high=2
2019-09-13 12:16:43.442+0000 INFO [o.n.k.i.DiagnosticsManager]   SchemaStore: used=1 high=0
2019-09-13 12:16:43.442+0000 INFO [o.n.k.i.DiagnosticsManager]   RelationshipGroupStore: used=1 high=0
2019-09-13 12:16:43.442+0000 INFO [o.n.k.i.DiagnosticsManager]   NeoStore: used=15 high=14
2019-09-13 12:16:43.443+0000 INFO [o.n.k.i.DiagnosticsManager] --- STARTED diagnostics for NEO_STORE_ID_USAGE END ---
2019-09-13 12:16:43.443+0000 INFO [o.n.k.i.DiagnosticsManager] --- STARTED diagnostics for NEO_STORE_RECORDS START ---
2019-09-13 12:16:43.443+0000 INFO [o.n.k.i.DiagnosticsManager] Neostore records:
2019-09-13 12:16:43.443+0000 INFO [o.n.k.i.DiagnosticsManager] TIME (Creation time): 1568376789822
2019-09-13 12:16:43.443+0000 INFO [o.n.k.i.DiagnosticsManager] RANDOM_NUMBER (Random number for store id): -8172356107186671854
2019-09-13 12:16:43.443+0000 INFO [o.n.k.i.DiagnosticsManager] LOG_VERSION (Current log version): 0
2019-09-13 12:16:43.443+0000 INFO [o.n.k.i.DiagnosticsManager] LAST_TRANSACTION_ID (Last committed transaction): 16
2019-09-13 12:16:43.444+0000 INFO [o.n.k.i.DiagnosticsManager] STORE_VERSION (Store format version): 15813456178476550
2019-09-13 12:16:43.444+0000 INFO [o.n.k.i.DiagnosticsManager] FIRST_GRAPH_PROPERTY (First property record containing graph properties): -1
2019-09-13 12:16:43.444+0000 INFO [o.n.k.i.DiagnosticsManager] LAST_CONSTRAINT_TRANSACTION (Last committed transaction containing constraint changes): 0
2019-09-13 12:16:43.444+0000 INFO [o.n.k.i.DiagnosticsManager] UPGRADE_TRANSACTION_ID (Transaction id most recent upgrade was performed at): 1
2019-09-13 12:16:43.444+0000 INFO [o.n.k.i.DiagnosticsManager] UPGRADE_TIME (Time of last upgrade): 1568376789822
2019-09-13 12:16:43.444+0000 INFO [o.n.k.i.DiagnosticsManager] LAST_TRANSACTION_CHECKSUM (Checksum of last committed transaction): -162194476345
2019-09-13 12:16:43.444+0000 INFO [o.n.k.i.DiagnosticsManager] UPGRADE_TRANSACTION_CHECKSUM (Checksum of transaction id the most recent upgrade was performed at): 0
2019-09-13 12:16:43.444+0000 INFO [o.n.k.i.DiagnosticsManager] LAST_CLOSED_TRANSACTION_LOG_VERSION (Log version where the last transaction commit entry has been written into): 0
2019-09-13 12:16:43.444+0000 INFO [o.n.k.i.DiagnosticsManager] LAST_CLOSED_TRANSACTION_LOG_BYTE_OFFSET (Byte offset in the log file where the last transaction commit entry has been written into): 2071193
2019-09-13 12:16:43.444+0000 INFO [o.n.k.i.DiagnosticsManager] LAST_TRANSACTION_COMMIT_TIMESTAMP (Commit time timestamp for last committed transaction): 1568376960959
2019-09-13 12:16:43.444+0000 INFO [o.n.k.i.DiagnosticsManager] UPGRADE_TRANSACTION_COMMIT_TIMESTAMP (Commit timestamp of transaction the most recent upgrade was performed at): 0
2019-09-13 12:16:43.444+0000 INFO [o.n.k.i.DiagnosticsManager] --- STARTED diagnostics for NEO_STORE_RECORDS END ---
2019-09-13 12:16:43.445+0000 INFO [o.n.k.i.DiagnosticsManager] --- STARTED diagnostics for TRANSACTION_RANGE START ---
2019-09-13 12:16:43.445+0000 INFO [o.n.k.i.DiagnosticsManager] Transaction log:
2019-09-13 12:16:43.464+0000 INFO [o.n.k.i.DiagnosticsManager] Oldest transaction 2 found in log with version 0
2019-09-13 12:16:43.464+0000 INFO [o.n.k.i.DiagnosticsManager] --- STARTED diagnostics for TRANSACTION_RANGE END ---
2019-09-13 12:16:43.478+0000 INFO [o.n.k.i.DiagnosticsManager] --- STARTED diagnostics for KernelDiagnostics:StoreFiles START ---
2019-09-13 12:16:43.502+0000 INFO [o.n.k.i.DiagnosticsManager] Disk space on partition (Total / Free / Free %): 10737418240 / 10734010368 / 99
2019-09-13 12:16:43.502+0000 INFO [o.n.k.i.DiagnosticsManager] Storage files: (filename : modification date - size)
2019-09-13 12:16:43.517+0000 INFO [o.n.k.i.DiagnosticsManager]   index:
2019-09-13 12:16:43.532+0000 INFO [o.n.k.i.DiagnosticsManager]   - Total: 2019-09-13T12:13:10+0000 - 0.00 B
2019-09-13 12:16:43.535+0000 INFO [o.n.k.i.DiagnosticsManager]   neostore: 2019-09-13T12:16:28+0000 - 8.00 kB
2019-09-13 12:16:43.536+0000 INFO [o.n.k.i.DiagnosticsManager]   neostore.counts.db.a: 2019-09-13T12:13:10+0000 - 96.00 B
2019-09-13 12:16:43.536+0000 INFO [o.n.k.i.DiagnosticsManager]   neostore.counts.db.b: 2019-09-13T12:16:28+0000 - 224.00 B
2019-09-13 12:16:43.536+0000 INFO [o.n.k.i.DiagnosticsManager]   neostore.id: 2019-09-13T12:16:42+0000 - 9.00 B
2019-09-13 12:16:43.537+0000 INFO [o.n.k.i.DiagnosticsManager]   neostore.labelscanstore.db: 2019-09-13T12:16:29+0000 - 48.00 kB
2019-09-13 12:16:43.537+0000 INFO [o.n.k.i.DiagnosticsManager]   neostore.labeltokenstore.db: 2019-09-13T12:16:28+0000 - 8.00 kB
2019-09-13 12:16:43.538+0000 INFO [o.n.k.i.DiagnosticsManager]   neostore.labeltokenstore.db.id: 2019-09-13T12:16:41+0000 - 9.00 B
2019-09-13 12:16:43.539+0000 INFO [o.n.k.i.DiagnosticsManager]   neostore.labeltokenstore.db.names: 2019-09-13T12:16:28+0000 - 8.00 kB
2019-09-13 12:16:43.540+0000 INFO [o.n.k.i.DiagnosticsManager]   neostore.labeltokenstore.db.names.id: 2019-09-13T12:16:41+0000 - 9.00 B
2019-09-13 12:16:43.540+0000 INFO [o.n.k.i.DiagnosticsManager]   neostore.nodestore.db: 2019-09-13T12:16:29+0000 - 87.98 kB
2019-09-13 12:16:43.542+0000 INFO [o.n.k.i.DiagnosticsManager]   neostore.nodestore.db.id: 2019-09-13T12:16:40+0000 - 249.00 B
2019-09-13 12:16:43.542+0000 INFO [o.n.k.i.DiagnosticsManager]   neostore.nodestore.db.labels: 2019-09-13T12:13:07+0000 - 8.00 kB
2019-09-13 12:16:43.543+0000 INFO [o.n.k.i.DiagnosticsManager]   neostore.nodestore.db.labels.id: 2019-09-13T12:16:40+0000 - 9.00 B
2019-09-13 12:16:43.544+0000 INFO [o.n.k.i.DiagnosticsManager]   neostore.propertystore.db: 2019-09-13T12:16:29+0000 - 549.78 kB
2019-09-13 12:16:43.544+0000 INFO [o.n.k.i.DiagnosticsManager]   neostore.propertystore.db.arrays: 2019-09-13T12:13:08+0000 - 8.00 kB
2019-09-13 12:16:43.545+0000 INFO [o.n.k.i.DiagnosticsManager]   neostore.propertystore.db.arrays.id: 2019-09-13T12:16:41+0000 - 9.00 B
2019-09-13 12:16:43.545+0000 INFO [o.n.k.i.DiagnosticsManager]   neostore.propertystore.db.id: 2019-09-13T12:16:41+0000 - 145.00 B
2019-09-13 12:16:43.545+0000 INFO [o.n.k.i.DiagnosticsManager]   neostore.propertystore.db.index: 2019-09-13T12:16:29+0000 - 8.00 kB
2019-09-13 12:16:43.545+0000 INFO [o.n.k.i.DiagnosticsManager]   neostore.propertystore.db.index.id: 2019-09-13T12:16:40+0000 - 9.00 B
2019-09-13 12:16:43.546+0000 INFO [o.n.k.i.DiagnosticsManager]   neostore.propertystore.db.index.keys: 2019-09-13T12:16:29+0000 - 8.00 kB
2019-09-13 12:16:43.546+0000 INFO [o.n.k.i.DiagnosticsManager]   neostore.propertystore.db.index.keys.id: 2019-09-13T12:16:40+0000 - 9.00 B
2019-09-13 12:16:43.547+0000 INFO [o.n.k.i.DiagnosticsManager]   neostore.propertystore.db.strings: 2019-09-13T12:16:29+0000 - 464.00 kB
2019-09-13 12:16:43.548+0000 INFO [o.n.k.i.DiagnosticsManager]   neostore.propertystore.db.strings.id: 2019-09-13T12:16:40+0000 - 281.00 B
2019-09-13 12:16:43.556+0000 INFO [o.n.k.i.DiagnosticsManager]   neostore.relationshipgroupstore.db: 2019-09-13T12:13:09+0000 - 8.00 kB
2019-09-13 12:16:43.557+0000 INFO [o.n.k.i.DiagnosticsManager]   neostore.relationshipgroupstore.db.id: 2019-09-13T12:16:41+0000 - 9.00 B
2019-09-13 12:16:43.558+0000 INFO [o.n.k.i.DiagnosticsManager]   neostore.relationshipstore.db: 2019-09-13T12:13:08+0000 - 0.00 B
2019-09-13 12:16:43.561+0000 INFO [o.n.k.i.DiagnosticsManager]   neostore.relationshipstore.db.id: 2019-09-13T12:16:41+0000 - 9.00 B
2019-09-13 12:16:43.561+0000 INFO [o.n.k.i.DiagnosticsManager]   neostore.relationshiptypestore.db: 2019-09-13T12:13:08+0000 - 0.00 B
2019-09-13 12:16:43.561+0000 INFO [o.n.k.i.DiagnosticsManager]   neostore.relationshiptypestore.db.id: 2019-09-13T12:16:41+0000 - 9.00 B
2019-09-13 12:16:43.561+0000 INFO [o.n.k.i.DiagnosticsManager]   neostore.relationshiptypestore.db.names: 2019-09-13T12:13:08+0000 - 8.00 kB
2019-09-13 12:16:43.562+0000 INFO [o.n.k.i.DiagnosticsManager]   neostore.relationshiptypestore.db.names.id: 2019-09-13T12:16:41+0000 - 9.00 B
2019-09-13 12:16:43.564+0000 INFO [o.n.k.i.DiagnosticsManager]   neostore.schemastore.db: 2019-09-13T12:13:09+0000 - 8.00 kB
2019-09-13 12:16:43.564+0000 INFO [o.n.k.i.DiagnosticsManager]   neostore.schemastore.db.id: 2019-09-13T12:16:41+0000 - 9.00 B
2019-09-13 12:16:43.564+0000 INFO [o.n.k.i.DiagnosticsManager]   neostore.transaction.db.0: 2019-09-13T12:16:29+0000 - 1.98 MB
2019-09-13 12:16:43.570+0000 INFO [o.n.k.i.DiagnosticsManager]   store_lock: 2019-09-13T12:13:07+0000 - 0.00 B
2019-09-13 12:16:43.570+0000 INFO [o.n.k.i.DiagnosticsManager] Storage summary: 
2019-09-13 12:16:43.570+0000 INFO [o.n.k.i.DiagnosticsManager]   Total size of store: 3.18 MB
2019-09-13 12:16:43.570+0000 INFO [o.n.k.i.DiagnosticsManager]   Total size of mapped files: 1.20 MB
2019-09-13 12:16:43.570+0000 INFO [o.n.k.i.DiagnosticsManager] --- STARTED diagnostics for KernelDiagnostics:StoreFiles END ---
2019-09-13 12:16:46.135+0000 INFO [o.n.k.i.DiagnosticsManager] --- SERVER STARTED START ---
2019-09-13 12:16:47.367+0000 INFO [o.n.k.i.DiagnosticsManager] --- SERVER STARTED END ---
2019-09-13 12:17:03.260+0000 ERROR [o.n.b.v.r.ErrorReporter] Client triggered an unexpected error [UnknownError]: java.io.IOException: Permission denied, reference 21aa4419-2f39-4eb4-868d-33ab22fd0b38.
2019-09-13 12:17:03.260+0000 ERROR [o.n.b.v.r.ErrorReporter] Client triggered an unexpected error [UnknownError]: java.io.IOException: Permission denied, reference 21aa4419-2f39-4eb4-868d-33ab22fd0b38. java.io.IOException: Permission denied
org.neo4j.kernel.impl.store.UnderlyingStorageException: java.io.IOException: Permission denied
	at org.neo4j.kernel.impl.store.StoreRecordCursor.next(StoreRecordCursor.java:87)
	at org.neo4j.kernel.impl.store.StoreRecordCursor.next(StoreRecordCursor.java:50)
	at org.neo4j.kernel.impl.api.store.StorePropertyCursor.next(StorePropertyCursor.java:76)
	at org.neo4j.kernel.impl.core.NodeProxy.getAllProperties(NodeProxy.java:419)
	at org.neo4j.kernel.impl.util.NodeProxyWrappingNodeValue.properties(NodeProxyWrappingNodeValue.java:111)
	at org.neo4j.kernel.impl.util.NodeProxyWrappingNodeValue.writeTo(NodeProxyWrappingNodeValue.java:59)
	at org.neo4j.bolt.v1.messaging.Neo4jPack$Packer.pack(Neo4jPack.java:86)
	at org.neo4j.bolt.v1.messaging.BoltResponseMessageWriter.onRecord(BoltResponseMessageWriter.java:75)
	at org.neo4j.bolt.v1.messaging.BoltMessageRouter$ResultHandler$1.visit(BoltMessageRouter.java:153)
	at org.neo4j.bolt.v1.runtime.CypherAdapterStream.lambda$accept$0(CypherAdapterStream.java:78)
	at org.neo4j.cypher.internal.compatibility.v3_3.runtime.helpers.RuntimeJavaValueConverter$feedIteratorToVisitable.accept(RuntimeJavaValueConverter.scala:55)
	at org.neo4j.cypher.internal.compatibility.v3_3.runtime.PipeExecutionResult.accept(PipeExecutionResult.scala:112)
	at org.neo4j.cypher.internal.compatibility.ClosingExecutionResult$$anonfun$accept$2.apply$mcV$sp(ClosingExecutionResult.scala:175)
	at org.neo4j.cypher.internal.compatibility.ClosingExecutionResult$$anonfun$accept$2.apply(ClosingExecutionResult.scala:174)
	at org.neo4j.cypher.internal.compatibility.ClosingExecutionResult$$anonfun$accept$2.apply(ClosingExecutionResult.scala:174)
	at org.neo4j.cypher.internal.compatibility.v3_3.exceptionHandler$runSafely$.apply(exceptionHandler.scala:90)
	at org.neo4j.cypher.internal.compatibility.ClosingExecutionResult.accept(ClosingExecutionResult.scala:174)
	at org.neo4j.bolt.v1.runtime.CypherAdapterStream.accept(CypherAdapterStream.java:76)
	at org.neo4j.bolt.v1.messaging.BoltMessageRouter$ResultHandler.onRecords(BoltMessageRouter.java:146)
	at org.neo4j.bolt.v1.runtime.BoltStateMachine$State$3.lambda$pullAll$0(BoltStateMachine.java:462)
	at org.neo4j.bolt.v1.runtime.TransactionStateMachine$State$1.streamResult(TransactionStateMachine.java:271)
	at org.neo4j.bolt.v1.runtime.TransactionStateMachine.streamResult(TransactionStateMachine.java:105)
	at org.neo4j.bolt.v1.runtime.BoltStateMachine$State$3.pullAll(BoltStateMachine.java:461)
	at org.neo4j.bolt.v1.runtime.BoltStateMachine.pullAll(BoltStateMachine.java:236)
	at org.neo4j.bolt.v1.messaging.BoltMessageRouter.lambda$onPullAll$6(BoltMessageRouter.java:114)
	at org.neo4j.bolt.v1.runtime.concurrent.RunnableBoltWorker.execute(RunnableBoltWorker.java:152)
	at org.neo4j.bolt.v1.runtime.concurrent.RunnableBoltWorker.executeBatch(RunnableBoltWorker.java:145)
	at org.neo4j.bolt.v1.runtime.concurrent.RunnableBoltWorker.run(RunnableBoltWorker.java:110)
	at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:511)
	at java.util.concurrent.FutureTask.run(FutureTask.java:266)
	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)
	at org.neo4j.helpers.NamedThreadFactory$2.run(NamedThreadFactory.java:109)
Caused by: java.io.IOException: Permission denied
	at sun.nio.ch.FileDispatcherImpl.pread0(Native Method)
	at sun.nio.ch.FileDispatcherImpl.pread(FileDispatcherImpl.java:52)
	at sun.nio.ch.IOUtil.readIntoNativeBuffer(IOUtil.java:220)
	at sun.nio.ch.IOUtil.read(IOUtil.java:192)
	at sun.nio.ch.FileChannelImpl.readInternal(FileChannelImpl.java:735)
	at sun.nio.ch.FileChannelImpl.read(FileChannelImpl.java:721)
	at org.neo4j.io.fs.StoreFileChannel.read(StoreFileChannel.java:105)
	at org.neo4j.io.pagecache.impl.SingleFilePageSwapper.swapIn(SingleFilePageSwapper.java:237)
	at org.neo4j.io.pagecache.impl.SingleFilePageSwapper.read(SingleFilePageSwapper.java:292)
	at org.neo4j.io.pagecache.impl.muninn.PageList.fault(PageList.java:446)
	at org.neo4j.io.pagecache.impl.muninn.MuninnPageCursor.pageFault(MuninnPageCursor.java:372)
	at org.neo4j.io.pagecache.impl.muninn.MuninnPageCursor.uncommonPin(MuninnPageCursor.java:321)
	at org.neo4j.io.pagecache.impl.muninn.MuninnPageCursor.pin(MuninnPageCursor.java:295)
	at org.neo4j.io.pagecache.impl.muninn.MuninnReadPageCursor.next(MuninnReadPageCursor.java:61)
	at org.neo4j.io.pagecache.impl.muninn.MuninnPageCursor.next(MuninnPageCursor.java:127)
	at org.neo4j.kernel.impl.store.CommonAbstractStore.readIntoRecord(CommonAbstractStore.java:1069)
	at org.neo4j.kernel.impl.store.StoreRecordCursor.next(StoreRecordCursor.java:82)
	... 33 more

Taking from your graph YML:

        volumeMounts:
        - name: neo4jmount
          mountPath: /data
          subPath: data

Looking at your PVC -- I still cannot see that you're using the actual PVC. You're instead using some other volume called neo4jmount that hasn't been defined (or may be defined somewhere else)

Your PVC is named pvc-neo4j, and it has the storage class, and that all looks fine. But this basic point about tracking down access on /data to a PVC still hasn't been established. What am I missing here?

Recapping:

  1. I know of no reason why the docker container would do this
  2. The error looks fairly clear and straightforward: the underlying DBMS is failing to read a file off of disk
  3. I am speculating (but do not know for sure) that permissions changed in the meantime
  4. We don't yet know why that would be.

To further diagnose, I recommend:

  1. Prove all the way down that the appropriate PVC is being used
  2. Optionally, build your own neo4j container, and modify docker-entrypoint.sh to explicitly change permissions on the files in /data, or otherwise just list the permissions (executing something like find . -type file -exec ls -l {} \; in the container, in order to list each permission for each file on every startup of the container. If you do this, you will spot if the permissions on files change, but it won't answer why they're changing.

Hi @david_allen,

After a full week of research in Azure we found the resolution to the issue. It was, as it always is, a very simple setting. In the storage class you need to include two additional mount-options: mfsymlinks and nobrl. These are not (yet) documented and it was therefore almost impossible to find any information on these options.

  • Mfsymlinks: Enable support for Minshall+French symlinks(see here). This option is ignored when specified together with the 'sfu' option. Minshall+French symlinks are used even if the server supports the CIFS Unix Extensions.
  • Nobrl: Do not send byte range lock requests to the server. This is necessary for certain applications that break with cifs style mandatory byte range locks (and most cifs servers do not yet support requesting advisory byte range locks).

The resulting storage class therefore looks like this:

kind: StorageClass
apiVersion: storage.k8s.io/v1
metadata:
  name: azurefile-neo4j
provisioner: kubernetes.io/azure-file
reclaimPolicy: Retain
allowVolumeExpansion: true
mountOptions:
  - dir_mode=0755
  - file_mode=0755
  - uid=100
  - gid=101
  - mfsymlinks
  - nobrl
parameters:
  skuName: Standard_LRS

Anyone working with Azure Files and Neo4j will eventually run into this issue and therefore I believe it's worthile to know about this for many other users.

Regards,
Nathan

1 Like

Thanks for posting this -- very helpful for future people dealing with AzureFS. Very sorry that it took this much to get there, but I'm also glad to hear that it was resolved.

I am facing a similar issue with GKE using the suggestions in the storage class. Do you have any suggestions