search

EventStore / EventStore-Client-Dotnet

Dotnet Client SDK for the Event Store gRPC Client API written in C#
Other
144 stars 37 forks source link

AppendToStreamAsync fails with client 20.6.1 under netcoreapp3.1 #85

Closed hlubovac closed 3 years ago

hlubovac commented 3 years ago

Describe the bug AppendToStreamAsync example (https://github.com/EventStore/EventStore.Samples.Dotnet/blob/master/WritingEvents/Program.cs) does not work when hosted within a netcoreapp3.1 application with EventStore.Client 20.6.1 (no events written to target stream). Console logs say that connection gets established and then closed.

Same sample does work under netcoreapp3.1 and against the same EventStore service, however with net40 EventStore.Client.3.4.0 assembly used instead (100 events written to the target stream; visible via UI).

Perhaps I don't have required feature enabled at the EventStore service (please examind step 1 below first; thank you)?

To Reproduce Steps to reproduce the behavior:

  1. Launch EventStore service at Docker; I'm not sure which ES version tag "latest" really is 
    
docker volume create eventstore-data
docker volume create eventstore-logs
docker volume create eventstore-index

docker run \ --name "eventstore"\ --volume "eventstore-data:/var/lib/eventstore" \ --volume "eventstore-logs:/var/log/eventstore" \ --volume "eventstore-index:/var/lib/eventstore/index" \ --hostname "eventstore" \ --network "bridge" \ --publish "1113:1113" \ --publish "2113:2113" \ --env "EVENTSTORE_CLUSTER_SIZE=1" \ --env "EVENTSTORE_SKIP_DB_VERIFY=true" \ --env "EVENTSTORE_RUN_PROJECTIONS=All" \ --env "EVENTSTORE_START_STANDARD_PROJECTIONS=true" \ --env "EVENTSTORE_ENABLE_EXTERNAL_TCP=true" \ --env "EVENTSTORE_ENABLE_ATOM_PUB_OVER_HTTP=true" \ --env "EVENTSTORE_EXT_TCP_PORT=1113" \ --env "EVENTSTORE_EXT_HTTP_PORT=2113" \ --restart "unless-stopped" \ --detach \ "eventstore/eventstore:latest" --insecure

2. Use example https://github.com/EventStore/EventStore.Samples.Dotnet/blob/master/WritingEvents/Program.cs with EventStore.Client 20.6.1 under netcoreapp3.1.

**Expected behavior**
dotnet project file for working scenario (copy of sample project; AssemblyInfo.cs removed):
Exe netcoreapp3.1 ..\packages\EventStore.Client.3.4.0\lib\net40\EventStore.ClientAPI.dll 

**Actual behavior**
dotnet project file for non-working scenario (copy of sample project; AssemblyInfo.cs removed):
Exe netcoreapp3.1 
For comparison, the sample project won't work (same symptoms) when targeting .NET Framework 4.5.2 and using EventStore.Client 20.6.1 in compatible build. So, with these 2 declarations in their relevant locations (csproj; packages.config):
v4.5.2 

**Config/Logs/Screenshots**

[01,22:26:46.421,DEBUG] EventStoreConnection 'ES-7f5e3a5e-e70d-46bb-b018-250a88916e51': enqueueing message EventStore.ClientAPI.Internal.StartConnectionMessage.. [06,22:26:46.444,DEBUG] EventStoreConnection 'ES-7f5e3a5e-e70d-46bb-b018-250a88916e51': StartConnection. [06,22:26:46.445,DEBUG] EventStoreConnection 'ES-7f5e3a5e-e70d-46bb-b018-250a88916e51': DiscoverEndPoint. [06,22:26:46.447,DEBUG] EventStoreConnection 'ES-7f5e3a5e-e70d-46bb-b018-250a88916e51': enqueueing message EventStore.ClientAPI.Internal.EstablishTcpConnectionMessage.. [04,22:26:46.959,DEBUG] EventStoreConnection 'ES-7f5e3a5e-e70d-46bb-b018-250a88916e51': EstablishTcpConnection to [127.0.0.1:1113]. [01,22:27:12.347,DEBUG] EventStoreConnection 'ES-7f5e3a5e-e70d-46bb-b018-250a88916e51': enqueueing message EventStore.ClientAPI.Internal.StartOperationMessage.. [04,22:27:12.413,DEBUG] EventStoreConnection 'ES-7f5e3a5e-e70d-46bb-b018-250a88916e51': StartOperation enqueue AppendToStreamOperation, Stream: a_test_stream, ExpectedVersion: -2, 0, 00:00:07.. [04,22:27:12.413,DEBUG] EventStoreConnection 'ES-7f5e3a5e-e70d-46bb-b018-250a88916e51': EnqueueOperation WAITING for Operation AppendToStreamOperation (2c7401ba-0dd6-47d0-8b12-b2b541e3a46e): Stream: a_test_stream, ExpectedVersion: -2, retry count: 0, created: 22:27:12.413, last updated: 22:27:12.413.. [07,22:27:12.488,DEBUG] TcpPackageConnection: connected to [127.0.0.1:1113, L127.0.0.1:63479, {84415501-7e60-417e-adac-8d40a868da9f}]. [07,22:27:12.488,DEBUG] EventStoreConnection 'ES-7f5e3a5e-e70d-46bb-b018-250a88916e51': enqueueing message EventStore.ClientAPI.Internal.TcpConnectionEstablishedMessage.. [07,22:27:12.489,DEBUG] EventStoreConnection 'ES-7f5e3a5e-e70d-46bb-b018-250a88916e51': TCP connection to [127.0.0.1:1113, L127.0.0.1:63479, {84415501-7e60-417e-adac-8d40a868da9f}] established.. [07,22:27:12.490,DEBUG] IdentifyClient; Client Version: 1, ConnectionName: ES-7f5e3a5e-e70d-46bb-b018-250a88916e51, [08,22:27:14.927,INFO] EventStoreConnection 'ES-7f5e3a5e-e70d-46bb-b018-250a88916e51': closing TCP connection [127.0.0.1:1113, 127.0.0.1:63479, 84415501-7e60-417e-adac-8d40a868da9f] due to HEARTBEAT TIMEOUT at pkgNum 0. [08,22:27:14.927,DEBUG] EventStoreConnection 'ES-7f5e3a5e-e70d-46bb-b018-250a88916e51': CloseTcpConnection. [08,22:27:14.928,INFO] ClientAPI TcpConnectionSsl closed [22:27:14.928: S127.0.0.1:1113, L127.0.0.1:63479, {84415501-7e60-417e-adac-8d40a868da9f}]: [08,22:27:14.929,INFO] Received bytes: 0, Sent bytes: 0 [08,22:27:14.929,INFO] Send calls: 0, callbacks: 0 [08,22:27:14.929,INFO] Receive calls: 0, callbacks: 0 [08,22:27:14.930,INFO] Close reason: [Success] EventStoreConnection 'ES-7f5e3a5e-e70d-46bb-b018-250a88916e51': closing TCP connection [127.0.0.1:1113, 127.0.0.1:63479, 84415501-7e60-417e-adac-8d40a868da9f] due to HEARTBEAT TIMEOUT at pkgNum 0. [08,22:27:14.932,DEBUG] TcpPackageConnection: connection [127.0.0.1:1113, L127.0.0.1:63479, {84415501-7e60-417e-adac-8d40a868da9f}] was closed cleanly. [08,22:27:14.932,DEBUG] EventStoreConnection 'ES-7f5e3a5e-e70d-46bb-b018-250a88916e51': enqueueing message EventStore.ClientAPI.Internal.TcpConnectionClosedMessage.. [08,22:27:14.933,DEBUG] EventStoreConnection 'ES-7f5e3a5e-e70d-46bb-b018-250a88916e51': TCP connection to [127.0.0.1:1113, L127.0.0.1:63479, {84415501-7e60-417e-adac-8d40a868da9f}] closed.. [08,22:27:14.935,DEBUG] EventStoreConnection 'ES-7f5e3a5e-e70d-46bb-b018-250a88916e51': TCP connection to [127.0.0.1:1113, L127.0.0.1:63479, {84415501-7e60-417e-adac-8d40a868da9f}] closed.. [08,22:27:15.126,DEBUG] EventStoreConnection 'ES-7f5e3a5e-e70d-46bb-b018-250a88916e51': TimerTick checking reconnection.... [08,22:27:15.145,DEBUG] EventStoreConnection 'ES-7f5e3a5e-e70d-46bb-b018-250a88916e51': ExecuteOperation package WriteEvents, 2c7401ba-0dd6-47d0-8b12-b2b541e3a46e, Operation AppendToStreamOperation (2c7401ba-0dd6-47d0-8b12-b2b541e3a46e): Stream: a_test_stream, ExpectedVersion: -2, retry count: 0, created: 22:27:12.413, last updated: 22:27:15.131.. [08,22:27:15.148,DEBUG] EventStoreConnection 'ES-7f5e3a5e-e70d-46bb-b018-250a88916e51': DiscoverEndPoint. [08,22:27:15.148,DEBUG] EventStoreConnection 'ES-7f5e3a5e-e70d-46bb-b018-250a88916e51': enqueueing message EventStore.ClientAPI.Internal.EstablishTcpConnectionMessage.. [07,22:27:15.148,DEBUG] EventStoreConnection 'ES-7f5e3a5e-e70d-46bb-b018-250a88916e51': EstablishTcpConnection to [127.0.0.1:1113]. [04,22:27:15.150,DEBUG] TcpPackageConnection: connected to [127.0.0.1:1113, L127.0.0.1:63480, {16adab56-836c-4799-a6b6-1bd0f400ed52}]. [04,22:27:15.150,DEBUG] EventStoreConnection 'ES-7f5e3a5e-e70d-46bb-b018-250a88916e51': enqueueing message EventStore.ClientAPI.Internal.TcpConnectionEstablishedMessage.. [04,22:27:15.151,DEBUG] EventStoreConnection 'ES-7f5e3a5e-e70d-46bb-b018-250a88916e51': TCP connection to [127.0.0.1:1113, L127.0.0.1:63480, {16adab56-836c-4799-a6b6-1bd0f400ed52}] established.. [04,22:27:15.151,DEBUG] IdentifyClient; Client Version: 1, ConnectionName: ES-7f5e3a5e-e70d-46bb-b018-250a88916e51, [11,22:27:17.527,INFO] EventStoreConnection 'ES-7f5e3a5e-e70d-46bb-b018-250a88916e51': closing TCP connection [127.0.0.1:1113, 127.0.0.1:63480, 16adab56-836c-4799-a6b6-1bd0f400ed52] due to HEARTBEAT TIMEOUT at pkgNum 0. [11,22:27:17.527,DEBUG] EventStoreConnection 'ES-7f5e3a5e-e70d-46bb-b018-250a88916e51': CloseTcpConnection IGNORED because was closed. [11,22:27:17.730,INFO] EventStoreConnection 'ES-7f5e3a5e-e70d-46bb-b018-250a88916e51': closing TCP connection [127.0.0.1:1113, 127.0.0.1:63480, 16adab56-836c-4799-a6b6-1bd0f400ed52] due to HEARTBEAT TIMEOUT at pkgNum 0. [11,22:27:17.730,DEBUG] EventStoreConnection 'ES-7f5e3a5e-e70d-46bb-b018-250a88916e51': CloseTcpConnection IGNORED because was closed. [07,22:27:17.934,INFO] EventStoreConnection 'ES-7f5e3a5e-e70d-46bb-b018-250a88916e51': closing TCP connection [127.0.0.1:1113, 127.0.0.1:63480, 16adab56-836c-4799-a6b6-1bd0f400ed52] due to HEARTBEAT TIMEOUT at pkgNum 0. [07,22:27:17.934,DEBUG] EventStoreConnection 'ES-7f5e3a5e-e70d-46bb-b018-250a88916e51': CloseTcpConnection IGNORED because was closed. [07,22:27:18.139,INFO] EventStoreConnection 'ES-7f5e3a5e-e70d-46bb-b018-250a88916e51': closing TCP connection [127.0.0.1:1113, 127.0.0.1:63480, 16adab56-836c-4799-a6b6-1bd0f400ed52] due to HEARTBEAT TIMEOUT at pkgNum 0. [07,22:27:18.139,DEBUG] EventStoreConnection 'ES-7f5e3a5e-e70d-46bb-b018-250a88916e51': CloseTcpConnection IGNORED because was closed. [04,22:27:18.337,INFO] EventStoreConnection 'ES-7f5e3a5e-e70d-46bb-b018-250a88916e51': closing TCP connection [127.0.0.1:1113, 127.0.0.1:63480, 16adab56-836c-4799-a6b6-1bd0f400ed52] due to HEARTBEAT TIMEOUT at pkgNum 0. [04,22:27:18.338,DEBUG] EventStoreConnection 'ES-7f5e3a5e-e70d-46bb-b018-250a88916e51': CloseTcpConnection IGNORED because was closed. [11,22:27:18.527,INFO] EventStoreConnection 'ES-7f5e3a5e-e70d-46bb-b018-250a88916e51': closing TCP connection [127.0.0.1:1113, 127.0.0.1:63480, 16adab56-836c-4799-a6b6-1bd0f400ed52] due to HEARTBEAT TIMEOUT at pkgNum 0. [11,22:27:18.527,DEBUG] EventStoreConnection 'ES-7f5e3a5e-e70d-46bb-b018-250a88916e51': CloseTcpConnection IGNORED because was closed. [11,22:27:18.729,INFO] EventStoreConnection 'ES-7f5e3a5e-e70d-46bb-b018-250a88916e51': closing TCP connection [127.0.0.1:1113, 127.0.0.1:63480, 16adab56-836c-4799-a6b6-1bd0f400ed52] due to HEARTBEAT TIMEOUT at pkgNum 0. [11,22:27:18.729,DEBUG] EventStoreConnection 'ES-7f5e3a5e-e70d-46bb-b018-250a88916e51': CloseTcpConnection IGNORED because was closed. [04,22:27:18.935,INFO] EventStoreConnection 'ES-7f5e3a5e-e70d-46bb-b018-250a88916e51': closing TCP connection [127.0.0.1:1113, 127.0.0.1:63480, 16adab56-836c-4799-a6b6-1bd0f400ed52] due to HEARTBEAT TIMEOUT at pkgNum 0. [04,22:27:18.935,DEBUG] EventStoreConnection 'ES-7f5e3a5e-e70d-46bb-b018-250a88916e51': CloseTcpConnection IGNORED because was closed. [04,22:27:19.138,INFO] EventStoreConnection 'ES-7f5e3a5e-e70d-46bb-b018-250a88916e51': closing TCP connection [127.0.0.1:1113, 127.0.0.1:63480, 16adab56-836c-4799-a6b6-1bd0f400ed52] due to HEARTBEAT TIMEOUT at pkgNum 0. [04,22:27:19.138,DEBUG] EventStoreConnection 'ES-7f5e3a5e-e70d-46bb-b018-250a88916e51': CloseTcpConnection IGNORED because was closed. [08,22:27:19.342,INFO] EventStoreConnection 'ES-7f5e3a5e-e70d-46bb-b018-250a88916e51': closing TCP connection [127.0.0.1:1113, 127.0.0.1:63480, 16adab56-836c-4799-a6b6-1bd0f400ed52] due to HEARTBEAT TIMEOUT at pkgNum 0. [08,22:27:19.342,DEBUG] EventStoreConnection 'ES-7f5e3a5e-e70d-46bb-b018-250a88916e51': CloseTcpConnection IGNORED because was closed. [07,22:27:19.527,INFO] EventStoreConnection 'ES-7f5e3a5e-e70d-46bb-b018-250a88916e51': closing TCP connection [127.0.0.1:1113, 127.0.0.1:63480, 16adab56-836c-4799-a6b6-1bd0f400ed52] due to HEARTBEAT TIMEOUT at pkgNum 0. [07,22:27:19.527,DEBUG] EventStoreConnection 'ES-7f5e3a5e-e70d-46bb-b018-250a88916e51': CloseTcpConnection IGNORED because was closed. [08,22:27:19.733,INFO] EventStoreConnection 'ES-7f5e3a5e-e70d-46bb-b018-250a88916e51': closing TCP connection [127.0.0.1:1113, 127.0.0.1:63480, 16adab56-836c-4799-a6b6-1bd0f400ed52] due to HEARTBEAT TIMEOUT at pkgNum 0. [08,22:27:19.733,DEBUG] EventStoreConnection 'ES-7f5e3a5e-e70d-46bb-b018-250a88916e51': CloseTcpConnection IGNORED because was closed. [08,22:27:19.937,INFO] EventStoreConnection 'ES-7f5e3a5e-e70d-46bb-b018-250a88916e51': closing TCP connection [127.0.0.1:1113, 127.0.0.1:63480, 16adab56-836c-4799-a6b6-1bd0f400ed52] due to HEARTBEAT TIMEOUT at pkgNum 0. [08,22:27:19.937,DEBUG] EventStoreConnection 'ES-7f5e3a5e-e70d-46bb-b018-250a88916e51': CloseTcpConnection IGNORED because was closed. [08,22:27:20.136,INFO] EventStoreConnection 'ES-7f5e3a5e-e70d-46bb-b018-250a88916e51': closing TCP connection [127.0.0.1:1113, 127.0.0.1:63480, 16adab56-836c-4799-a6b6-1bd0f400ed52] due to HEARTBEAT TIMEOUT at pkgNum 0. [08,22:27:20.136,DEBUG] EventStoreConnection 'ES-7f5e3a5e-e70d-46bb-b018-250a88916e51': CloseTcpConnection IGNORED because was closed. [09,22:27:20.219,INFO] [S127.0.0.1:1113, L127.0.0.1:63480]: Exception on EndAuthenticateAsClient. EXCEPTION(S) OCCURRED: System.IO.IOException: Received an unexpected EOF or 0 bytes from the transport stream. at System.Net.FixedSizeReader.ReadPacketAsync(Stream transport, AsyncProtocolRequest request) at System.Net.Security.SslStream.ThrowIfExceptional() at System.Net.Security.SslStream.InternalEndProcessAuthentication(LazyAsyncResult lazyResult) at System.Net.Security.SslStream.EndProcessAuthentication(IAsyncResult result) at System.Net.Security.SslStream.EndAuthenticateAsClient(IAsyncResult asyncResult) at EventStore.ClientAPI.Transport.Tcp.TcpConnectionSsl.OnEndAuthenticateAsClient(IAsyncResult ar)

[09,22:27:20.220,INFO] ClientAPI TcpConnectionSsl closed [22:27:20.220: S127.0.0.1:1113, L127.0.0.1:63480, {16adab56-836c-4799-a6b6-1bd0f400ed52}]: [09,22:27:20.221,INFO] Received bytes: 0, Sent bytes: 0 [09,22:27:20.221,INFO] Send calls: 0, callbacks: 0 [09,22:27:20.221,INFO] Receive calls: 0, callbacks: 0 [09,22:27:20.224,INFO] Close reason: [SocketError] Received an unexpected EOF or 0 bytes from the transport stream. [09,22:27:20.226,DEBUG] TcpPackageConnection: connection [127.0.0.1:1113, L127.0.0.1:63480, {16adab56-836c-4799-a6b6-1bd0f400ed52}] was closed with error: SocketError. [09,22:27:20.226,DEBUG] EventStoreConnection 'ES-7f5e3a5e-e70d-46bb-b018-250a88916e51': enqueueing message EventStore.ClientAPI.Internal.TcpConnectionClosedMessage.. [11,22:27:20.226,DEBUG] EventStoreConnection 'ES-7f5e3a5e-e70d-46bb-b018-250a88916e51': TCP connection to [127.0.0.1:1113, L127.0.0.1:63480, {16adab56-836c-4799-a6b6-1bd0f400ed52}] closed.. [11,22:27:20.342,DEBUG] EventStoreConnection 'ES-7f5e3a5e-e70d-46bb-b018-250a88916e51': TimerTick checking reconnection.... [11,22:27:20.343,DEBUG] EventStoreConnection 'ES-7f5e3a5e-e70d-46bb-b018-250a88916e51': RemoveOperation SUCCEEDED for Operation AppendToStreamOperation (2c7401ba-0dd6-47d0-8b12-b2b541e3a46e): Stream: a_test_stream, ExpectedVersion: -2, retry count: 0, created: 22:27:12.413, last updated: 22:27:15.131. [11,22:27:20.347,DEBUG] EventStoreConnection 'ES-7f5e3a5e-e70d-46bb-b018-250a88916e51': ScheduleOperationRetry for Operation AppendToStreamOperation (2c7401ba-0dd6-47d0-8b12-b2b541e3a46e): Stream: a_test_stream, ExpectedVersion: -2, retry count: 0, created: 22:27:12.413, last updated: 22:27:15.131. [11,22:27:20.348,DEBUG] EventStoreConnection 'ES-7f5e3a5e-e70d-46bb-b018-250a88916e51': DiscoverEndPoint. [11,22:27:20.348,DEBUG] EventStoreConnection 'ES-7f5e3a5e-e70d-46bb-b018-250a88916e51': enqueueing message EventStore.ClientAPI.Internal.EstablishTcpConnectionMessage.. [11,22:27:20.349,DEBUG] EventStoreConnection 'ES-7f5e3a5e-e70d-46bb-b018-250a88916e51': EstablishTcpConnection to [127.0.0.1:1113]. [11,22:27:20.400,DEBUG] TcpPackageConnection: connected to [127.0.0.1:1113, L127.0.0.1:63482, {8b165f51-e9ba-435c-b323-97887de34d6e}]. [11,22:27:20.400,DEBUG] EventStoreConnection 'ES-7f5e3a5e-e70d-46bb-b018-250a88916e51': enqueueing message EventStore.ClientAPI.Internal.TcpConnectionEstablishedMessage.. [11,22:27:20.401,DEBUG] EventStoreConnection 'ES-7f5e3a5e-e70d-46bb-b018-250a88916e51': TCP connection to [127.0.0.1:1113, L127.0.0.1:63482, {8b165f51-e9ba-435c-b323-97887de34d6e}] established.. [11,22:27:20.403,DEBUG] IdentifyClient; Client Version: 1, ConnectionName: ES-7f5e3a5e-e70d-46bb-b018-250a88916e51,


**EventStore details**

"ES VERSION:" "20.6.1.0" ("tags/oss-v20.6.1"/"9ea108855", "Unknown"), [ 1, 1,06:53:08.930,INF] "RUNTIME:" ".NET 3.1.9" (64-bit), [ 1, 1,06:53:08.928,INF] "OS:" Linux ("Unix 4.15.0.123")

hlubovac commented 3 years ago

I forgot to mention that I tried few past versions of the client, within the same netcoreapp3.1 scenario, and they worked: 5.0.9, 3.4.0.

Version 20.6.0 did not work either.

My conclusion is that I either don't have some feature enabled at the ES service, or that the client-side usage must be slightly different for ES 20 (which I'm not seeing), or that there may be a defect within the client v20. I hope that helps. Thank you!

In the meantime, I'm using client 5.0.9 for my experiments.

thefringeninja commented 3 years ago

@hlubovac If you specify insecure for the server you must also do so for the client, e.g. ConnectionSettings.Create().DisableTls()

alexeyzimarev commented 3 years ago

You also need to remember the issue with calling insecure gRPC in .NET: https://docs.microsoft.com/en-us/aspnet/core/grpc/troubleshoot?view=aspnetcore-5.0#call-insecure-grpc-services-with-net-core-client

hlubovac commented 3 years ago

I don't understand how I "specified insecured" transport. I can"t see anything in server configuration above that could mean that (if it's the server mandating that), while the samples-repo that I linked to is now gone (so, we can't see whatever was there).

I don't have the project in front of me. I resolved the problem by using older client lib. My original problem report was that client 20.6.1 didn't work with the same server (v20-something, I'm pretty sure). At that time that sounded like a bug in the client.

thefringeninja commented 3 years ago

I don't understand how I "specified insecured" transport. I can"t see anything in server configuration above that could mean that (if it's the server mandating that),

You did, by passing the --insecure flag when starting the docker container.

hlubovac commented 3 years ago

And I looked for something like that right before I said that 😀

Thank you! I'll give this a try.