Occasional AccessDeniedErrors after applying ACL metadata to a soft-deleted stream

jonasholtkamp commented 5 years ago

Lately I've observed a strange asynchronous behavior of setStreamMetadataRaw. Let me explain my test setup first, then I'll go on and explain the problem.

Test setup

create an ES user with exhaustive group privileges ([ 'test-r', 'test-w', 'test-d', 'test-mr', 'test-mw' ])
connect to the ES with this user
set ACLs on an arbitrary stream (test-1) that match the group privileges above (this gives our user all privileges on this stream)
append an arbitrary event to test-1
soft-delete test-1
try to read from test-1
this (as expected) fails with an AccessDeniedError because the ACLs have been deleted as well
set the exact same ACLs like above again on test-1
try to read from test-1
expectation: reading succeeds for test-1, it's however empty

Problem

in some cases (<10%) the last reading step fails with this error:

(node:30306) UnhandledPromiseRejectionWarning: AccessDeniedError: Read access denied for stream 'test-1'.
at ReadStreamEventsBackwardOperation.module.exports.ReadStreamEventsBackwardOperation._inspectResponse (/Users/[redacted]/node_modules/node-eventstore-client/lib/dist.js:5409:17)
at ReadStreamEventsBackwardOperation.module.exports.OperationBase.inspectPackage (/Users/[redacted]/node_modules/node-eventstore-client/lib/dist.js:549:19)
at EventStoreConnectionLogicHandler.module.exports.EventStoreConnectionLogicHandler._handleTcpPackage (/Users/[redacted]/node_modules/node-eventstore-client/lib/dist.js:3548:38)
at /Users/[redacted]/node_modules/node-eventstore-client/lib/dist.js:3098:10
at Immediate._handlers.(anonymous function) (/Users/[redacted]/node_modules/node-eventstore-client/lib/dist.js:3748:7)
at processImmediate (timers.js:639:17)

if I after this check the ACLs of test-1 (or try to read again) that works perfectly fine

It seems to me that there is some form of asynchronous problem with which setStreamMetadataRaw resolves before the metadata are actually set.

nicdex commented 5 years ago

Can you provide some code that reproduce this?

Thanks

jonasholtkamp commented 5 years ago

Yep, you'll find it here: https://gist.github.com/jonasholtkamp/055de46f83eac8a11f66388d23e63207. The occasionally unexpectedly failing (last) reading step I mentioned is in line 113.

nicdex commented 5 years ago

After running the script you provided I get a different behavior. After soft-deleting the stream, the following read returns a status of streamNotFound. I don't get an AccessDeniedError.

I'll need the version of node-eventstore-client you are using (do npm ls to get specific version), EventStore, node.js and also your OS info.

Thanks

jonasholtkamp commented 5 years ago

Try running it repeatedly, please. As I said this behavior only occurs occasionally.

node-eventstore-client: 0.2.6
Eventstore: 4.1.1 (running in Docker 18.09.1)
Node.js: 11.9.0
OS: macOS 10.14.3

nicdex commented 5 years ago

As far as I understand your issue is with the second read after setting the ACL on the soft-deleted stream.I'm telling you I'm not having the same behavior for the FIRST read after the soft delete. So in your example I'm not getting into the catch(e) where e.name === 'AccessDeniedError'.

nicdex commented 5 years ago

I updated your example https://gist.github.com/nicdex/42457c19294965bdddc80679083f32f5

I added a 1000 loop and I get no error, for each loop I get

Working with stream test- Read: success Read: streamNotFound Read: success

nicdex commented 5 years ago

I can't reproduce the issue. I've tried different setup/settings and I always get the same results. Maybe it could be related to EventStore being under load and somehow the ACL settings are delayed, but it's doubtful. I'll try to add some tests around the setStreamMetadataRaw call, right now there is none, maybe I'll be lucky and will be able to reproduce your issue.

For now, can I ask you why you are soft-deleting and re-using streams? What's your use case?

jonasholtkamp commented 5 years ago

Thanks for taking the extra effort in investigating the issue. Sad to hear that you aren't able to reproduce this issue.

As to the need of soft-deleting and re-using streams: It is only by soft-deleting (instead of hard-deleting) streams that one is able to re-use streams. Trying to re-use hard-deleted streams results in an error. We use this construct to have easy and cheap duplicate checking in place. The ID part of a stream name (<name>-<id>) is an UUID5 that is based on some data that should not be duplicated. However it may be deleted and is therefore free to be used again.

jonasholtkamp commented 5 years ago

Hey @nicdex, might be that I forgot an important detail: We're using the following default ACLs for our Eventstore:

  '$userStreamAcl': {
      '$r': '$admins',
      '$w': '$admins',
      '$d': '$admins',
      '$mr': '$all',
      '$mw': '$all'
    },
    '$systemStreamAcl': {
      '$r': '$admins',
      '$w': '$admins',
      '$d': '$admins',
      '$mr': '$admins',
      '$mw': '$admins'
    }

With that the user is not by default allowed to write to/read from any stream.

Here is an updated example of my test script that sets the default ACL. With that you should be able to reproduce the behavior I experience. However it may be a general Eventstore issue rather than an issue with node-eventstore-client: https://gist.github.com/jonasholtkamp/a1909ecedad5f16ec4dbbe9f0c8007da.

Thanks for your support!

nicdex commented 5 years ago

So I was able to reproduce the issue with the verbose logging on. I can definitively see at the low level of the client that the setAcls operation is completed before the read operation is started. I'm 99% certain that the problem is on the server side. Please open a ticket with EventStore itself https://github.com/EventStore/EventStore/issues

jonasholtkamp commented 5 years ago

I have done as you asked, thanks for your support @nicdex.

nicdex / node-eventstore-client

Occasional AccessDeniedErrors after applying ACL metadata to a soft-deleted stream #65

Test setup

Problem