subscribetoAllAsync fails with BadRequest

[fabiocarneiro]

When using the example for subscribetoAllAsync with EventStore 20.10.0 it fails with BadRequest.

Logs:

[2021-02-01 12:48:53] event-store-client.DEBUG: EventStoreNodeConnection 'a5c079994e9d994c8ce18da36a0fdce1': enqueuing message HandleTcpPackageMessage
[2021-02-01 12:48:53] event-store-client.DEBUG: EventStoreNodeConnection 'a5c079994e9d994c8ce18da36a0fdce1': HandleTcpPackage connId ddfa25ed32816d40a4b3015f015e9b09, package ClientIdentified, b9e0d3250c7a574ba2aa9bf7ca9079ba
connected
[2021-02-01 12:48:53] event-store-client.DEBUG: EventStoreNodeConnection 'a5c079994e9d994c8ce18da36a0fdce1': StartSubscription SUBSCRIBING Subscription VolatileSubscription (4d8b6031d5898f4bbcdd9f4e18957a36): StreamId: , ResolveLinkTos: yes, is subscribed: no, retry count: 0, created: 2021-02-01T12:48:53.258600+00:00, last updated: 2021-02-01T12:48:53.325841+00:00
[2021-02-01 12:48:53] event-store-client.DEBUG: EventStoreNodeConnection 'a5c079994e9d994c8ce18da36a0fdce1': enqueuing message HandleTcpPackageMessage
[2021-02-01 12:48:53] event-store-client.DEBUG: EventStoreNodeConnection 'a5c079994e9d994c8ce18da36a0fdce1': HandleTcpPackage connId ddfa25ed32816d40a4b3015f015e9b09, package BadRequest, 4d8b6031d5898f4bbcdd9f4e18957a36
[2021-02-01 12:48:53] event-store-client.DEBUG: Subscription 4d8b6031d5898f4bbcdd9f4e18957a36 to <all>: closing subscription, reason: ServerError, exception: Server error...
[2021-02-01 12:48:53] event-store-client.DEBUG: EventStoreNodeConnection 'a5c079994e9d994c8ce18da36a0fdce1': HandleTcpPackage 4d8b6031d5898f4bbcdd9f4e18957a36 SUBSCRIPTION DECISION EndOperation (BadRequest), 
[2021-02-01 12:48:53] event-store-client.DEBUG: EventStoreNodeConnection 'a5c079994e9d994c8ce18da36a0fdce1': RemoveSubscription Subscription VolatileSubscription (4d8b6031d5898f4bbcdd9f4e18957a36): StreamId: , ResolveLinkTos: yes, is subscribed: no, retry count: 0, created: 2021-02-01T12:48:53.258600+00:00, last updated: 2021-02-01T12:48:53.325841+00:00, result yes

[prolic]

I will look into this. I am currently sick, so it may take a couple of days.

[tomtimmerman]

Any news on this issue. I'am running into exactly the same problem with EventStore 21.10. It looks like the problem only occurs when the end of the all stream is reached.

{"message":"Catch-up Subscription  to <all>: skipping event ($projections-projector-condition-fact, 1, $ProjectionUpdated @ C:473581341/P:473581341)","context":{},"level":100,"level_name":"DEBUG","channel":"test","datetime":"2022-07-26T07:46:49.053059+00:00","extra":{}}
{"message":"EventStoreNodeConnection 'c2998afc9e8d2e44874dcb8a3c646c57': enqueuing message StartOperationMessage","context":{},"level":100,"level_name":"DEBUG","channel":"test","datetime":"2022-07-26T07:46:49.053656+00:00","extra":{}}
{"message":"EventStoreNodeConnection 'c2998afc9e8d2e44874dcb8a3c646c57': StartOperation schedule ReadAllEventsForward, Position: C:473582662/P:0, MaxCount: 100, ResolveLinkTos: no, RequireMaster: no, 10, 7000","context":{},"level":100,"level_name":"DEBUG","channel":"test","datetime":"2022-07-26T07:46:49.053856+00:00","extra":{}}
{"message":"EventStoreNodeConnection 'c2998afc9e8d2e44874dcb8a3c646c57': ExecuteOperation package ReadAllEventsForward, 050de963dddf9c4a8a076ceb27edea59, Operation ReadAllEventsForward (050de963dddf9c4a8a076ceb27edea59): Position: C:473582662/P:0, MaxCount: 100, ResolveLinkTos: no, RequireMaster: no, retry count: 0, created: 2022-07-26T07:46:49.054005+00:00, last updated: 2022-07-26T07:46:49.054138+00:00","context":{},"level":100,"level_name":"DEBUG","channel":"test","datetime":"2022-07-26T07:46:49.055390+00:00","extra":{}}
{"message":"EventStoreNodeConnection 'c2998afc9e8d2e44874dcb8a3c646c57': HandleTcpPackage OPERATION DECISION EndOperation (Success), Operation ReadAllEventsForward (67eb9c6a2249b046b269ddb48a949ebb): Position: C:473581341/P:473581341, MaxCount: 100, ResolveLinkTos: no, RequireMaster: no, retry count: 0, created: 2022-07-26T07:46:48.105593+00:00, last updated: 2022-07-26T07:46:48.963090+00:00","context":{},"level":100,"level_name":"DEBUG","channel":"test","datetime":"2022-07-26T07:46:49.064897+00:00","extra":{}}
{"message":"EventStoreNodeConnection 'c2998afc9e8d2e44874dcb8a3c646c57': RemoveOperation SUCCEEDED for Operation ReadAllEventsForward (67eb9c6a2249b046b269ddb48a949ebb): Position: C:473581341/P:473581341, MaxCount: 100, ResolveLinkTos: no, RequireMaster: no, retry count: 0, created: 2022-07-26T07:46:48.105593+00:00, last updated: 2022-07-26T07:46:48.963090+00:00","context":{},"level":100,"level_name":"DEBUG","channel":"test","datetime":"2022-07-26T07:46:49.065108+00:00","extra":{}}
{"message":"EventStoreNodeConnection 'c2998afc9e8d2e44874dcb8a3c646c57': enqueuing message HandleTcpPackageMessage","context":{},"level":100,"level_name":"DEBUG","channel":"test","datetime":"2022-07-26T07:46:49.094261+00:00","extra":{}}
{"message":"EventStoreNodeConnection 'c2998afc9e8d2e44874dcb8a3c646c57': HandleTcpPackage connId c52b892ae7c8804c80bb243cf45c0889, package ReadAllEventsForwardCompleted, 050de963dddf9c4a8a076ceb27edea59","context":{},"level":100,"level_name":"DEBUG","channel":"test","datetime":"2022-07-26T07:46:49.094505+00:00","extra":{}}
{"message":"Catch-up Subscription  to <all>: finished reading events, nextReadPosition = C:473582662/P:0","context":{},"level":100,"level_name":"DEBUG","channel":"test","datetime":"2022-07-26T07:46:49.095615+00:00","extra":{}}
{"message":"Catch-up Subscription  to <all>: subscribing...","context":{},"level":100,"level_name":"DEBUG","channel":"test","datetime":"2022-07-26T07:46:49.095893+00:00","extra":{}}
{"message":"EventStoreNodeConnection 'c2998afc9e8d2e44874dcb8a3c646c57': enqueuing message StartSubscriptionMessage","context":{},"level":100,"level_name":"DEBUG","channel":"test","datetime":"2022-07-26T07:46:49.101414+00:00","extra":{}}
{"message":"EventStoreNodeConnection 'c2998afc9e8d2e44874dcb8a3c646c57': StartSubscription fire VolatileSubscription, StreamId: , ResolveLinkTos: no, MaxRetries: 10, Timeout: 7000","context":{},"level":100,"level_name":"DEBUG","channel":"test","datetime":"2022-07-26T07:46:49.117024+00:00","extra":{}}
{"message":"EventStoreNodeConnection 'c2998afc9e8d2e44874dcb8a3c646c57': StartSubscription SUBSCRIBING Subscription VolatileSubscription (0e8159e815a0a64da3ba90e0fd955de0): StreamId: , ResolveLinkTos: no, is subscribed: no, retry count: 0, created: 2022-07-26T07:46:49.127428+00:00, last updated: 2022-07-26T07:46:49.127656+00:00","context":{},"level":100,"level_name":"DEBUG","channel":"test","datetime":"2022-07-26T07:46:49.133801+00:00","extra":{}}
{"message":"EventStoreNodeConnection 'c2998afc9e8d2e44874dcb8a3c646c57': HandleTcpPackage OPERATION DECISION EndOperation (Success), Operation ReadAllEventsForward (050de963dddf9c4a8a076ceb27edea59): Position: C:473582662/P:0, MaxCount: 100, ResolveLinkTos: no, RequireMaster: no, retry count: 0, created: 2022-07-26T07:46:49.054005+00:00, last updated: 2022-07-26T07:46:49.054138+00:00","context":{},"level":100,"level_name":"DEBUG","channel":"test","datetime":"2022-07-26T07:46:49.134221+00:00","extra":{}}
{"message":"EventStoreNodeConnection 'c2998afc9e8d2e44874dcb8a3c646c57': RemoveOperation SUCCEEDED for Operation ReadAllEventsForward (050de963dddf9c4a8a076ceb27edea59): Position: C:473582662/P:0, MaxCount: 100, ResolveLinkTos: no, RequireMaster: no, retry count: 0, created: 2022-07-26T07:46:49.054005+00:00, last updated: 2022-07-26T07:46:49.054138+00:00","context":{},"level":100,"level_name":"DEBUG","channel":"test","datetime":"2022-07-26T07:46:49.134420+00:00","extra":{}}
{"message":"EventStoreNodeConnection 'c2998afc9e8d2e44874dcb8a3c646c57': enqueuing message HandleTcpPackageMessage","context":{},"level":100,"level_name":"DEBUG","channel":"test","datetime":"2022-07-26T07:46:49.161528+00:00","extra":{}}
{"message":"EventStoreNodeConnection 'c2998afc9e8d2e44874dcb8a3c646c57': HandleTcpPackage connId c52b892ae7c8804c80bb243cf45c0889, package BadRequest, 0e8159e815a0a64da3ba90e0fd955de0","context":{},"level":100,"level_name":"DEBUG","channel":"test","datetime":"2022-07-26T07:46:49.162172+00:00","extra":{}}
{"message":"Subscription 0e8159e815a0a64da3ba90e0fd955de0 to <all>: closing subscription, reason: ServerError, exception: Server error...","context":{},"level":100,"level_name":"DEBUG","channel":"test","datetime":"2022-07-26T07:46:49.205194+00:00","extra":{}}
{"message":"Catch-up Subscription  to <all>: dropped subscription, reason: CatchUpError Server error","context":{},"level":100,"level_name":"DEBUG","channel":"test","datetime":"2022-07-26T07:46:49.205866+00:00","extra":{}}
{"message":"Dropped","context":{},"level":200,"level_name":"INFO","channel":"test","datetime":"2022-07-26T07:46:49.206084+00:00","extra":{}}
{"message":"EventStoreNodeConnection 'c2998afc9e8d2e44874dcb8a3c646c57': HandleTcpPackage 0e8159e815a0a64da3ba90e0fd955de0 SUBSCRIPTION DECISION EndOperation (BadRequest), ","context":{},"level":100,"level_name":"DEBUG","channel":"test","datetime":"2022-07-26T07:46:49.206946+00:00","extra":{}}
{"message":"EventStoreNodeConnection 'c2998afc9e8d2e44874dcb8a3c646c57': RemoveSubscription Subscription VolatileSubscription (0e8159e815a0a64da3ba90e0fd955de0): StreamId: , ResolveLinkTos: no, is subscribed: no, retry count: 0, created: 2022-07-26T07:46:49.127428+00:00, last updated: 2022-07-26T07:46:49.127656+00:00, result yes","context":{},"level":100,"level_name":"DEBUG","channel":"test","datetime":"2022-07-26T07:46:49.207395+00:00","extra":{}}

It looks like an authentication issue. I get the following response from the server:

Error while processing package. Error: System.ArgumentNullException: Value cannot be null. (Parameter 'value')
   at EventStore.Plugins.Authorization.Operations.Streams.Parameters.StreamId(String streamId)
   at EventStore.Core.Services.AuthorizationGateway.Authorize(SubscribeToStream msg, IPublisher destination) in /home/runner/work/TrainStation/TrainStation/build/oss-eventstore/src/EventStore.Core/Services/AuthorizationGateway.cs:line 248
   at EventStore.Core.Services.Transport.Tcp.TcpConnectionManager.ProcessPackage(TcpPackage package) in /home/runner/work/TrainStation/TrainStation/build/oss-eventstore/src/EventStore.Core/Services/Transport/Tcp/TcpConnectionManager.cs:line 322
   at EventStore.Core.Services.Transport.Tcp.TcpConnectionManager.OnPackageReceived(TcpPackage package) in /home/runner/work/TrainStation/TrainStation/build/oss-eventstore/src/EventStore.Core/Services/Transport/Tcp/TcpConnectionManager.cs:line 250

[prolic]

@fabiocarneiro @tomtimmerman can you confirm this error with the latest master branch? If so, would you be able to setup a test case that fails? I'll try to look into it and to resolve the issue.