Eventstore: v20.6.0, gRPC subscriptions: undefined behavior when `MaxLiveEventBufferCount` is exceeded

[andersstorhaug]

Describe the bug

With the gRPC client, when a live subscription's buffer becomes full, the subscription has somewhat undefined behavior.

There also does not seem to be a way to detect that the subscription needs to be re-started in user code.

To Reproduce

1. Start a subscription using EventStoreClient.SubscribeToStreamAsync
2. Append batches of more than 16 events to the subscribed stream

Expected behavior

Preferably, this is handled internally where the subscription falls-back to historical and the live event buffer is flushed.

Alternatively, but not ideally, the subscriptionDropped handler is called so that the subscription can be restarted in user code.

Actual behavior

From what I've seen, one of the following happens:

• The eventAppeared handler is not called again
• The subscription continues after a delay and with duplicate event

Also, the subscriptionDropped handler is not called in this case, although that may be as designed with the new gRPC implementation.

Config/Logs/Screenshots

EventStore server console output from a stalled subscription:

Live subscription 9891cf37-b7c0-4cb7-8a03-15f089e10aa5 to "test" buffer is full.
Live subscription 9891cf37-b7c0-4cb7-8a03-15f089e10aa5 to "test" disposed.
Live subscription 9891cf37-b7c0-4cb7-8a03-15f089e10aa5 to "test" dropped: Unsubscribed
Live subscription 9891cf37-b7c0-4cb7-8a03-15f089e10aa5 to "test" disposed.

EventStore details

• EventStore server version: v20.6.0
• Operating system: Windows 10 x64
• EventStore client version (if applicable): v20.6.0

Additional context

References to relevant code:

• Example of MaxBufferSizeExceeded in Enumerators.StreamSubscription.cs L393
• MaxLiveEventBufferCount which is currently a constant of 16

[andersstorhaug]

I'm wondering actually if this issue is related to #2545.

While TCP-based subscriptions provide a work-around, this is a new application that I'm developing and it seemed to make sense to start with gRPC on v20.6.0.

[andersstorhaug]

If I used an internal buffer for eventAppeared I could probably reduce the chances of overflow, but, still with a limit of 16 I don't see how to avoid this issue (eg. due to client GC pauses). Also I can't imagine that the intention of the public subscription API includes having the end-user always implement their own intermediate buffer.

For starters, any confirmation that I'm raising a legitimate issue? Should I just not worry about it and stick to the TCP API?

[andersstorhaug]

Is any of this information helpful? What this means for me currently:

• There is no practical way to implement subscriptions with the gRPC API that do not effectively "stall" out after any amount of normal throughput / event handling behavior
• I can not easily detect when a subscription with the gRPC API should be restarted

[vektah]

I think there are 3 issues here:

• 
  
  1. I think the delays you are seeing were fixed in https://github.com/EventStore/EventStore/pull/2566 which was recently shipped in oss-20.6.1.
  
  
• 
  
  1. Theres an off by one when switching from catchup to follow reading from streams (but not $all). I have reproduced the duplicate event issue on 20.6.1 over here - go test -run TestRepeatedEvents to run the test.
  
  
• 
  
  1. the total stall, which never recovers - We are seeing the same thing with our go client but I still haven't managed to get the stalls to happen under controlled circumstances.
  
  

[vektah]

Ok, I've managed to track down the total stall (iii), its similar to (ii) in that it happens when MaxLiveEventBufferCount is hit, but happens when the client is heavily loaded and is not draining the server buffer fast enough.

Heres a reproduceable test - go test -v -count 100 -run TestHang to run - again sorry its in go, but thats where I'm most familiar. On my local machine it takes a while to see the issue, the -count 100 is important to actually reproduce.

[thefringeninja]

@vektah @andersstorhaug

This should be fixed on master. Can you run your tests to verify the problem has been fixed for you?

[vektah]

I've rerun the tests against docker.pkg.github.com/eventstore/eventstore/eventstore:20.10.0-rc1-buster-slim and two of the issues are fixed (reading while creating and the off by one when the reader doesnt block).

The third issue that causes hangs when the consumer is the bottleneck is still present. https://github.com/vektah/eventstore-tests/blob/master/all_test.go should allow you to easily reproduce against a clean eventstore, run with go test -run TestHang -count 100.

[YoEight]

Tag me in

[thefringeninja]

@vektah,

I tried to make a minimal reproduction in csharp - https://github.com/thefringeninja/es-issue-2544 - and go - https://github.com/thefringeninja/es-issue-2544-go/blob/go-client/hang_with_client_test.go - using our official clients. I am unable to reproduce the bug (but I acknowledge that the reproduction could be wrong). Could you try switching to the official go client and see if that works for you?

[vektah]

To reproduce the problem you likely need to bump the delay higher than 800
microseconds. Its only reproducible if the client is the bottleneck.

On Sat, 14 Nov 2020, 00:19 João Bragança, [e-mail] wrote:

@vektah https://github.com/vektah,

I tried to make a minimal reproduction in csharp -
https://github.com/thefringeninja/es-issue-2544 - and go -
https://github.com/thefringeninja/es-issue-2544-go/blob/go-client/hang_with_client_test.go

• using our official clients. I am unable to reproduce the bug (but I
  acknowledge that the reproduction could be wrong). Could you try switching
  to the official go client and see if that works for you?

—
You are receiving this because you were mentioned.
Reply to this email directly, view it on GitHub
https://github.com/EventStore/EventStore/issues/2544#issuecomment-726760070,
or unsubscribe
https://github.com/notifications/unsubscribe-auth/AARE2LXLI5AH23NVAEVU5PDSPUW5LANCNFSM4N2UMVOA
.

[thefringeninja]

@vektah,

I've tried increasing the delay to 500ms and I am still unable to reproduce the issue. Did you get a chance to try the official Go client?

[vektah]

Have reproduced with your client - see https://github.com/thefringeninja/es-issue-2544-go/pull/1

[thefringeninja]

@vektah,

They key to the problem appears to be https://github.com/grpc/grpc-go/issues/2927#issuecomment-513973765

I've updated the repro with the official golang client. And the fix is here: https://github.com/thefringeninja/es-issue-2544-go/commit/681bed3f9c14aaf434745bce736de8d6c1f691ff#diff-2dc3afff5133d73d7c47e0113cfb88b6d15424f772069f4b13d5fed64a12c602R28.

I was also able to fix the problem in your client, please see https://github.com/thefringeninja/es-issue-2544-go/commit/db81ddcfb3dd9ef5960e8fd190e0462744aae815

[vektah]

Innnnteresting. Closing the entire grpc connection fixes the issue.

They key to the problem appears to be grpc/grpc-go#2927 (comment)

// CloseSend closes the send direction of the stream. It closes the stream
// when non-nil error is met. It is also not safe to call CloseSend
// concurrently with SendMsg.

// RecvMsg blocks until it receives a message into m or the stream is
// done. It returns io.EOF when the stream completes successfully. On
// any other error, the stream is aborted and the error contains the RPC
// status.
//
// It is safe to have a goroutine calling SendMsg and another goroutine
// calling RecvMsg on the same stream at the same time, but it is not
// safe to call RecvMsg on the same stream in different goroutines.

best I can tell this is racing between RecvMessage and CloseSend, which looks to be undefined at best :(.

So https://github.com/EventStore/EventStore-Client-Go/blob/342c059a40674f3447319871920e7775e304e7e8/subscription/subscription.go#L40 is not required then?

Sweet, looks like this is resolved then. Is it now no longer possible for a live subscription to pass back into catchup mode if it falls behind?

[thefringeninja]

@vektah a live subscription may go back into catch up mode. It's unlikely but possible.

As for our official client, I think _something_ is required to clean up the subscription, but it's not clear from the documentation what that is.