Timed out waiting for client to be identified

EventStoreDB
1

Hi! I need some help getting the .NET client to connect to a server locally. (I’m sure it’s me, but I’ve been researching and I’m not sure how it’s me.)

The primary symptom is the client closing with a message of “Timed out waiting for client to be identified”.

Searching for that phrase on this group led me to this post:

https://groups.google.com/forum/#!searchin/event-store/"timed$20out$20waiting$20for$20client"|sort:date/event-store/_3wcW1ihHKY/EYfqN8kAAgAJ

It seems to indicate that the client and server were on different versions of the 4.0 release. It is also the only result for this phrase on google besides the code that contains the string.

Where I am stuck is that I’m using the .NET client v4.0.3 and the server v4.0.0.4. I’m not sure what next steps to take to debug further.

The other piece of data is that, before the client gives the message “Timed out waiting for client to be identified”, it also shows a BadRequest command from HandleTcpPackage for an UNMAPPED PACKAGE (see screenshot).

Any help is greatly appreciated. I’ve used EventStore before and am looking forward to getting this running again.

  • Bryan

eventstore-badrequest.png

2

Hi Brian,

Do you see any error messages in the server logs?

3

Thanks Hayley-Jean for your response.

I am using the default server configuration. Here is the initial connection and two reconnect attempts:

…startup…
[INFO TcpService ] External TCP connection accepted: [Normal, 127.0.0.1:14529, L127.0.0.1:1113, {e5ccba88-4568-4008-a0d0-68822117c7f7}].
[INFO TcpConnection ] ES TcpConnection closed [04:49:02.761: N127.0.0.1:14529, L127.0.0.1:1113, {e5ccba88-4568-4008-a0d0-68822117c7f7}]:Received bytes: 190, Sent bytes: 182
[INFO TcpConnection ] ES TcpConnection closed [04:49:02.782: N127.0.0.1:14529, L127.0.0.1:1113, {e5ccba88-4568-4008-a0d0-68822117c7f7}]:Send calls: 6, callbacks: 6
[INFO TcpConnection ] ES TcpConnection closed [04:49:02.782: N127.0.0.1:14529, L127.0.0.1:1113, {e5ccba88-4568-4008-a0d0-68822117c7f7}]:Receive calls: 7, callbacks: 7
[INFO TcpConnection ] ES TcpConnection closed [04:49:02.782: N127.0.0.1:14529, L127.0.0.1:1113, {e5ccba88-4568-4008-a0d0-68822117c7f7}]:Close reason: [Success] Socket closed
[INFO TcpConnectionManager] Connection ‘external-normal’ [127.0.0.1:14529, {e5ccba88-4568-4008-a0d0-68822117c7f7}] closed: Success.
[DEBUG PersistentSubscripti] Lost connection from 127.0.0.1:14529
[INFO TcpService ] External TCP connection accepted: [Normal, 127.0.0.1:14533, L127.0.0.1:1113, {5d136318-9d6d-44d6-bf13-c1c4d5714ac4}].
[INFO TcpConnection ] ES TcpConnection closed [04:49:10.069: N127.0.0.1:14533, L127.0.0.1:1113, {5d136318-9d6d-44d6-bf13-c1c4d5714ac4}]:Received bytes: 190, Sent bytes: 182
[INFO TcpConnection ] ES TcpConnection closed [04:49:10.069: N127.0.0.1:14533, L127.0.0.1:1113, {5d136318-9d6d-44d6-bf13-c1c4d5714ac4}]:Send calls: 6, callbacks: 6
[INFO TcpConnection ] ES TcpConnection closed [04:49:10.069: N127.0.0.1:14533, L127.0.0.1:1113, {5d136318-9d6d-44d6-bf13-c1c4d5714ac4}]:Receive calls: 7, callbacks: 7
[INFO TcpConnection ] ES TcpConnection closed [04:49:10.069: N127.0.0.1:14533, L127.0.0.1:1113, {5d136318-9d6d-44d6-bf13-c1c4d5714ac4}]:Close reason: [Success] Socket closed
[INFO TcpConnectionManager] Connection ‘external-normal’ [127.0.0.1:14533, {5d136318-9d6d-44d6-bf13-c1c4d5714ac4}] closed: Success.
[DEBUG PersistentSubscripti] Lost connection from 127.0.0.1:14533
[INFO TcpService ] External TCP connection accepted: [Normal, 127.0.0.1:14534, L127.0.0.1:1113, {50f97429-f779-4ffb-ae2e-a40fae5b0372}].
[INFO TcpConnection ] ES TcpConnection closed [04:49:17.368: N127.0.0.1:14534, L127.0.0.1:1113, {50f97429-f779-4ffb-ae2e-a40fae5b0372}]:Received bytes: 190, Sent bytes: 182
[INFO TcpConnection ] ES TcpConnection closed [04:49:17.368: N127.0.0.1:14534, L127.0.0.1:1113, {50f97429-f779-4ffb-ae2e-a40fae5b0372}]:Send calls: 6, callbacks: 6
[INFO TcpConnection ] ES TcpConnection closed [04:49:17.368: N127.0.0.1:14534, L127.0.0.1:1113, {50f97429-f779-4ffb-ae2e-a40fae5b0372}]:Receive calls: 7, callbacks: 7
[INFO TcpConnection ] ES TcpConnection closed [04:49:17.369: N127.0.0.1:14534, L127.0.0.1:1113, {50f97429-f779-4ffb-ae2e-a40fae5b0372}]:Close reason: [Success] Socket closed
[INFO TcpConnectionManager] Connection ‘external-normal’ [127.0.0.1:14534, {50f97429-f779-4ffb-ae2e-a40fae5b0372}] closed: Success.
[DEBUG PersistentSubscripti] Lost connection from 127.0.0.1:14534

4

Long shot, but are you running ES in docker? I had this exact same error for a while and spent some time troubleshooting it, but couldn’t get to the bottom of it. worked when running the same version outside of docker. redownloaded the image for a totally different reason and it started working. which was entirely bizarre. I never managed to reproduce it again after that.

5

What do the client logs say? Add a verbisoe logger

6

@James I am not running in docker, no, but thanks for the response.

@Greg the original post had a screenshot of some verbose output. I will capture a full log when I am back at my machine.

7

Below are the full logs for client and server.

The client is using the default settings, and the URI has the default credentials.

Thanks again for looking it over.

– CLIENT LOG –

11:08:51.481 PM Debug | EventStoreConnection ‘“ES-899f6605-9795-4c62-a5d6-c5c8a3b8e95d”’: “enqueueing message EventStore.ClientAPI.Internal.StartConnectionMessage.”.
11:08:51.483 PM Debug | EventStoreConnection ‘“ES-899f6605-9795-4c62-a5d6-c5c8a3b8e95d”’: “StartConnection”.
11:08:51.484 PM Debug | EventStoreConnection ‘“ES-899f6605-9795-4c62-a5d6-c5c8a3b8e95d”’: “DiscoverEndPoint”.
11:08:51.486 PM Debug | EventStoreConnection ‘“ES-899f6605-9795-4c62-a5d6-c5c8a3b8e95d”’: “enqueueing message EventStore.ClientAPI.Internal.EstablishTcpConnectionMessage.”.
11:08:51.487 PM Debug | EventStoreConnection ‘“ES-899f6605-9795-4c62-a5d6-c5c8a3b8e95d”’: “EstablishTcpConnection to [127.0.0.1:1113]”.
11:08:51.497 PM Debug | TcpPackageConnection: connected to [“127.0.0.1:1113”, L"127.0.0.1:51493", {5688b986-6a74-4c35-84bf-7bb4ab1802fb}].
11:08:51.500 PM Debug | EventStoreConnection ‘“ES-899f6605-9795-4c62-a5d6-c5c8a3b8e95d”’: “enqueueing message EventStore.ClientAPI.Internal.TcpConnectionEstablishedMessage.”.
11:08:51.503 PM Debug | EventStoreConnection ‘“ES-899f6605-9795-4c62-a5d6-c5c8a3b8e95d”’: “TCP connection to [127.0.0.1:1113, L127.0.0.1:51493, {5688b986-6a74-4c35-84bf-7bb4ab1802fb}] established.”.
11:08:51.561 PM Debug | EventStoreConnection ‘“ES-899f6605-9795-4c62-a5d6-c5c8a3b8e95d”’: “enqueueing message EventStore.ClientAPI.Internal.HandleTcpPackageMessage.”.
11:08:51.564 PM Debug | EventStoreConnection ‘“ES-899f6605-9795-4c62-a5d6-c5c8a3b8e95d”’: “HandleTcpPackage connId 5688b986-6a74-4c35-84bf-7bb4ab1802fb, package Authenticated, 49c6093b-66a5-4d07-bbb7-a71787195069.”.
11:08:51.607 PM Debug | EventStoreConnection ‘“ES-899f6605-9795-4c62-a5d6-c5c8a3b8e95d”’: “enqueueing message EventStore.ClientAPI.Internal.HandleTcpPackageMessage.”.
11:08:51.608 PM Debug | EventStoreConnection ‘“ES-899f6605-9795-4c62-a5d6-c5c8a3b8e95d”’: “HandleTcpPackage connId 5688b986-6a74-4c35-84bf-7bb4ab1802fb, package BadRequest, 5eb55305-6b62-4643-b510-908f4e1ac8e9.”.
11:08:51.608 PM Debug | EventStoreConnection ‘“ES-899f6605-9795-4c62-a5d6-c5c8a3b8e95d”’: “HandleTcpPackage UNMAPPED PACKAGE with CorrelationId {5eb55305-6b62-4643-b510-908f4e1ac8e9}, Command: BadRequest”.
11:08:53.234 PM Debug | EventStoreConnection ‘“ES-899f6605-9795-4c62-a5d6-c5c8a3b8e95d”’: “enqueueing message EventStore.ClientAPI.Internal.HandleTcpPackageMessage.”.
11:08:53.238 PM Debug | EventStoreConnection ‘“ES-899f6605-9795-4c62-a5d6-c5c8a3b8e95d”’: “HandleTcpPackage connId 5688b986-6a74-4c35-84bf-7bb4ab1802fb, package HeartbeatResponseCommand, c1b4bd00-8152-4bb5-b889-86f295761928.”.
11:08:55.520 PM Debug | EventStoreConnection ‘“ES-899f6605-9795-4c62-a5d6-c5c8a3b8e95d”’: “enqueueing message EventStore.ClientAPI.Internal.HandleTcpPackageMessage.”.
11:08:55.527 PM Debug | EventStoreConnection ‘“ES-899f6605-9795-4c62-a5d6-c5c8a3b8e95d”’: “HandleTcpPackage connId 5688b986-6a74-4c35-84bf-7bb4ab1802fb, package HeartbeatRequestCommand, d2903b60-ffca-4eab-a254-87f5f806f551.”.
11:08:56.480 PM Debug | EventStoreConnection ‘“ES-899f6605-9795-4c62-a5d6-c5c8a3b8e95d”’: “enqueueing message EventStore.ClientAPI.Internal.HandleTcpPackageMessage.”.
11:08:56.489 PM Debug | EventStoreConnection ‘“ES-899f6605-9795-4c62-a5d6-c5c8a3b8e95d”’: “HandleTcpPackage connId 5688b986-6a74-4c35-84bf-7bb4ab1802fb, package HeartbeatResponseCommand, 12955c61-db2e-4ca3-8cb1-f88fcac1d3e0.”.
11:08:58.521 PM Debug | EventStoreConnection ‘“ES-899f6605-9795-4c62-a5d6-c5c8a3b8e95d”’: “enqueueing message EventStore.ClientAPI.Internal.HandleTcpPackageMessage.”.
11:08:58.526 PM Debug | EventStoreConnection ‘“ES-899f6605-9795-4c62-a5d6-c5c8a3b8e95d”’: “HandleTcpPackage connId 5688b986-6a74-4c35-84bf-7bb4ab1802fb, package HeartbeatRequestCommand, efd97f2c-f1f6-412b-89ff-fd07fb715377.”.
11:08:58.701 PM Debug | EventStoreConnection ‘“ES-899f6605-9795-4c62-a5d6-c5c8a3b8e95d”’: “Timed out waiting for client to be identified”.
11:08:58.709 PM Debug | EventStoreConnection ‘“ES-899f6605-9795-4c62-a5d6-c5c8a3b8e95d”’: “CloseTcpConnection”.
11:08:58.717 PM Information | ClientAPI “TcpConnection” closed [04:08:58.716: N"127.0.0.1:1113", L"127.0.0.1:51493", {5688b986-6a74-4c35-84bf-7bb4ab1802fb}]:
11:08:58.728 PM Information | Received bytes: 182, Sent bytes: 190
11:08:58.733 PM Information | Send calls: 6, callbacks: 6
11:08:58.736 PM Information | Receive calls: 7, callbacks: 6
11:08:58.739 PM Information | Close reason: [Success] “Timed out waiting for client to be identified”
11:08:58.744 PM Debug | TcpPackageConnection: connection [“127.0.0.1:1113”, L"127.0.0.1:51493", {5688b986-6a74-4c35-84bf-7bb4ab1802fb}] was closed “cleanly.”
11:08:58.750 PM Debug | EventStoreConnection ‘“ES-899f6605-9795-4c62-a5d6-c5c8a3b8e95d”’: “enqueueing message EventStore.ClientAPI.Internal.TcpConnectionClosedMessage.”.
11:08:58.757 PM Debug | EventStoreConnection ‘“ES-899f6605-9795-4c62-a5d6-c5c8a3b8e95d”’: “TCP connection to [127.0.0.1:1113, L127.0.0.1:51493, {5688b986-6a74-4c35-84bf-7bb4ab1802fb}] closed.”.
11:08:58.763 PM Debug | EventStoreConnection ‘“ES-899f6605-9795-4c62-a5d6-c5c8a3b8e95d”’: “IGNORED (_state: Connecting, _conn.ID: {00000000-0000-0000-0000-000000000000}, conn.ID: {5688b986-6a74-4c35-84bf-7bb4ab1802fb}): TCP connection to [127.0.0.1:1113, L127.0.0.1:51493] closed.”.
11:08:58.911 PM Debug | EventStoreConnection ‘“ES-899f6605-9795-4c62-a5d6-c5c8a3b8e95d”’: “TimerTick checking reconnection…”.
11:08:58.927 PM Debug | EventStoreConnection ‘“ES-899f6605-9795-4c62-a5d6-c5c8a3b8e95d”’: “DiscoverEndPoint”.
11:08:58.933 PM Debug | EventStoreConnection ‘“ES-899f6605-9795-4c62-a5d6-c5c8a3b8e95d”’: “enqueueing message EventStore.ClientAPI.Internal.EstablishTcpConnectionMessage.”.
11:08:58.939 PM Debug | EventStoreConnection ‘“ES-899f6605-9795-4c62-a5d6-c5c8a3b8e95d”’: “EstablishTcpConnection to [127.0.0.1:1113]”.
11:08:58.944 PM Debug | TcpPackageConnection: connected to [“127.0.0.1:1113”, L"127.0.0.1:51496", {5dfd721b-db63-4133-8a79-8b3137ff6c8d}].
11:08:58.947 PM Debug | EventStoreConnection ‘“ES-899f6605-9795-4c62-a5d6-c5c8a3b8e95d”’: “enqueueing message EventStore.ClientAPI.Internal.TcpConnectionEstablishedMessage.”.
11:08:58.950 PM Debug | EventStoreConnection ‘“ES-899f6605-9795-4c62-a5d6-c5c8a3b8e95d”’: “TCP connection to [127.0.0.1:1113, L127.0.0.1:51496, {5dfd721b-db63-4133-8a79-8b3137ff6c8d}] established.”.
11:08:58.953 PM Debug | EventStoreConnection ‘“ES-899f6605-9795-4c62-a5d6-c5c8a3b8e95d”’: “enqueueing message EventStore.ClientAPI.Internal.HandleTcpPackageMessage.”.
11:08:58.955 PM Debug | EventStoreConnection ‘“ES-899f6605-9795-4c62-a5d6-c5c8a3b8e95d”’: “HandleTcpPackage connId 5dfd721b-db63-4133-8a79-8b3137ff6c8d, package Authenticated, 5ce1b7b6-2975-4fdf-bf21-989a0be942ae.”.
11:08:58.958 PM Debug | EventStoreConnection ‘“ES-899f6605-9795-4c62-a5d6-c5c8a3b8e95d”’: “enqueueing message EventStore.ClientAPI.Internal.HandleTcpPackageMessage.”.
11:08:58.960 PM Debug | EventStoreConnection ‘“ES-899f6605-9795-4c62-a5d6-c5c8a3b8e95d”’: “HandleTcpPackage connId 5dfd721b-db63-4133-8a79-8b3137ff6c8d, package BadRequest, b498308e-4519-48c7-b486-d23be3d8d45f.”.
11:08:58.963 PM Debug | EventStoreConnection ‘“ES-899f6605-9795-4c62-a5d6-c5c8a3b8e95d”’: “HandleTcpPackage UNMAPPED PACKAGE with CorrelationId {b498308e-4519-48c7-b486-d23be3d8d45f}, Command: BadRequest”.
11:09:00.527 PM Debug | EventStoreConnection ‘“ES-899f6605-9795-4c62-a5d6-c5c8a3b8e95d”’: “enqueueing message EventStore.ClientAPI.Internal.HandleTcpPackageMessage.”.
11:09:00.535 PM Debug | EventStoreConnection ‘“ES-899f6605-9795-4c62-a5d6-c5c8a3b8e95d”’: “HandleTcpPackage connId 5dfd721b-db63-4133-8a79-8b3137ff6c8d, package HeartbeatResponseCommand, a8ca3da6-73fe-41ed-a815-227e871517e2.”.
11:09:02.944 PM Debug | EventStoreConnection ‘“ES-899f6605-9795-4c62-a5d6-c5c8a3b8e95d”’: “enqueueing message EventStore.ClientAPI.Internal.HandleTcpPackageMessage.”.
11:09:02.951 PM Debug | EventStoreConnection ‘“ES-899f6605-9795-4c62-a5d6-c5c8a3b8e95d”’: “HandleTcpPackage connId 5dfd721b-db63-4133-8a79-8b3137ff6c8d, package HeartbeatRequestCommand, 8b7de631-4e94-4b4e-92dd-dd7537445cb7.”.
11:09:03.772 PM Debug | EventStoreConnection ‘“ES-899f6605-9795-4c62-a5d6-c5c8a3b8e95d”’: “enqueueing message EventStore.ClientAPI.Internal.HandleTcpPackageMessage.”.
11:09:03.780 PM Debug | EventStoreConnection ‘“ES-899f6605-9795-4c62-a5d6-c5c8a3b8e95d”’: “HandleTcpPackage connId 5dfd721b-db63-4133-8a79-8b3137ff6c8d, package HeartbeatResponseCommand, 07b53ec3-42c6-4212-bd22-954f1dc98b9b.”.
11:09:05.945 PM Debug | EventStoreConnection ‘“ES-899f6605-9795-4c62-a5d6-c5c8a3b8e95d”’: “enqueueing message EventStore.ClientAPI.Internal.HandleTcpPackageMessage.”.
11:09:05.951 PM Debug | EventStoreConnection ‘“ES-899f6605-9795-4c62-a5d6-c5c8a3b8e95d”’: “HandleTcpPackage connId 5dfd721b-db63-4133-8a79-8b3137ff6c8d, package HeartbeatRequestCommand, d83d4ea1-e449-45ee-b8c3-2f8553a90908.”.
11:09:06.006 PM Debug | EventStoreConnection ‘“ES-899f6605-9795-4c62-a5d6-c5c8a3b8e95d”’: “Timed out waiting for client to be identified”.
11:09:06.013 PM Debug | EventStoreConnection ‘“ES-899f6605-9795-4c62-a5d6-c5c8a3b8e95d”’: “CloseTcpConnection”.
11:09:06.019 PM Information | ClientAPI “TcpConnection” closed [04:09:06.019: N"127.0.0.1:1113", L"127.0.0.1:51496", {5dfd721b-db63-4133-8a79-8b3137ff6c8d}]:
11:09:06.026 PM Information | Received bytes: 182, Sent bytes: 190
11:09:06.029 PM Information | Send calls: 6, callbacks: 6
11:09:06.031 PM Information | Receive calls: 7, callbacks: 6
11:09:06.034 PM Information | Close reason: [Success] “Timed out waiting for client to be identified”
11:09:06.037 PM Debug | TcpPackageConnection: connection [“127.0.0.1:1113”, L"127.0.0.1:51496", {5dfd721b-db63-4133-8a79-8b3137ff6c8d}] was closed “cleanly.”
11:09:06.043 PM Debug | EventStoreConnection ‘“ES-899f6605-9795-4c62-a5d6-c5c8a3b8e95d”’: “enqueueing message EventStore.ClientAPI.Internal.TcpConnectionClosedMessage.”.
11:09:06.048 PM Debug | EventStoreConnection ‘“ES-899f6605-9795-4c62-a5d6-c5c8a3b8e95d”’: “TCP connection to [127.0.0.1:1113, L127.0.0.1:51496, {5dfd721b-db63-4133-8a79-8b3137ff6c8d}] closed.”.
11:09:06.052 PM Debug | EventStoreConnection ‘“ES-899f6605-9795-4c62-a5d6-c5c8a3b8e95d”’: “IGNORED (_state: Connecting, _conn.ID: {00000000-0000-0000-0000-000000000000}, conn.ID: {5dfd721b-db63-4133-8a79-8b3137ff6c8d}): TCP connection to [127.0.0.1:1113, L127.0.0.1:51496] closed.”.
11:09:06.216 PM Debug | EventStoreConnection ‘“ES-899f6605-9795-4c62-a5d6-c5c8a3b8e95d”’: “TimerTick checking reconnection…”.
11:09:06.226 PM Debug | EventStoreConnection ‘“ES-899f6605-9795-4c62-a5d6-c5c8a3b8e95d”’: “DiscoverEndPoint”.
11:09:06.231 PM Debug | EventStoreConnection ‘“ES-899f6605-9795-4c62-a5d6-c5c8a3b8e95d”’: “enqueueing message EventStore.ClientAPI.Internal.EstablishTcpConnectionMessage.”.
11:09:06.236 PM Debug | EventStoreConnection ‘“ES-899f6605-9795-4c62-a5d6-c5c8a3b8e95d”’: “EstablishTcpConnection to [127.0.0.1:1113]”.
11:09:06.241 PM Debug | TcpPackageConnection: connected to [“127.0.0.1:1113”, L"127.0.0.1:51501", {5c838cbd-ece4-4aa0-a4d5-2a57557ed40e}].
11:09:06.247 PM Debug | EventStoreConnection ‘“ES-899f6605-9795-4c62-a5d6-c5c8a3b8e95d”’: “enqueueing message EventStore.ClientAPI.Internal.TcpConnectionEstablishedMessage.”.
11:09:06.252 PM Debug | EventStoreConnection ‘“ES-899f6605-9795-4c62-a5d6-c5c8a3b8e95d”’: “TCP connection to [127.0.0.1:1113, L127.0.0.1:51501, {5c838cbd-ece4-4aa0-a4d5-2a57557ed40e}] established.”.
11:09:06.257 PM Debug | EventStoreConnection ‘“ES-899f6605-9795-4c62-a5d6-c5c8a3b8e95d”’: “enqueueing message EventStore.ClientAPI.Internal.HandleTcpPackageMessage.”.
11:09:06.261 PM Debug | EventStoreConnection ‘“ES-899f6605-9795-4c62-a5d6-c5c8a3b8e95d”’: “HandleTcpPackage connId 5c838cbd-ece4-4aa0-a4d5-2a57557ed40e, package Authenticated, 9786d346-6494-4969-bf4f-b6c0f958b22e.”.
11:09:06.266 PM Debug | EventStoreConnection ‘“ES-899f6605-9795-4c62-a5d6-c5c8a3b8e95d”’: “enqueueing message EventStore.ClientAPI.Internal.HandleTcpPackageMessage.”.
11:09:06.271 PM Debug | EventStoreConnection ‘“ES-899f6605-9795-4c62-a5d6-c5c8a3b8e95d”’: “HandleTcpPackage connId 5c838cbd-ece4-4aa0-a4d5-2a57557ed40e, package BadRequest, dd464b3b-9761-461a-b677-4e3922908cdb.”.
11:09:06.276 PM Debug | EventStoreConnection ‘“ES-899f6605-9795-4c62-a5d6-c5c8a3b8e95d”’: “HandleTcpPackage UNMAPPED PACKAGE with CorrelationId {dd464b3b-9761-461a-b677-4e3922908cdb}, Command: BadRequest”.
11:09:07.832 PM Debug | EventStoreConnection ‘“ES-899f6605-9795-4c62-a5d6-c5c8a3b8e95d”’: “enqueueing message EventStore.ClientAPI.Internal.HandleTcpPackageMessage.”.
11:09:07.834 PM Debug | EventStoreConnection ‘“ES-899f6605-9795-4c62-a5d6-c5c8a3b8e95d”’: “HandleTcpPackage connId 5c838cbd-ece4-4aa0-a4d5-2a57557ed40e, package HeartbeatResponseCommand, 1ae50c38-8719-4e40-aa26-9a1be1d4577e.”.
11:09:10.241 PM Debug | EventStoreConnection ‘“ES-899f6605-9795-4c62-a5d6-c5c8a3b8e95d”’: “enqueueing message EventStore.ClientAPI.Internal.HandleTcpPackageMessage.”.
11:09:10.249 PM Debug | EventStoreConnection ‘“ES-899f6605-9795-4c62-a5d6-c5c8a3b8e95d”’: “HandleTcpPackage connId 5c838cbd-ece4-4aa0-a4d5-2a57557ed40e, package HeartbeatRequestCommand, 91050185-cfbd-4714-9e71-88ff4f131d61.”.
11:09:11.078 PM Debug | EventStoreConnection ‘“ES-899f6605-9795-4c62-a5d6-c5c8a3b8e95d”’: “enqueueing message EventStore.ClientAPI.Internal.HandleTcpPackageMessage.”.
11:09:11.086 PM Debug | EventStoreConnection ‘“ES-899f6605-9795-4c62-a5d6-c5c8a3b8e95d”’: “HandleTcpPackage connId 5c838cbd-ece4-4aa0-a4d5-2a57557ed40e, package HeartbeatResponseCommand, 6ab4c950-988e-4c9f-970b-4f45b7c14aee.”.
11:09:13.241 PM Debug | EventStoreConnection ‘“ES-899f6605-9795-4c62-a5d6-c5c8a3b8e95d”’: “enqueueing message EventStore.ClientAPI.Internal.HandleTcpPackageMessage.”.
11:09:13.249 PM Debug | EventStoreConnection ‘“ES-899f6605-9795-4c62-a5d6-c5c8a3b8e95d”’: “HandleTcpPackage connId 5c838cbd-ece4-4aa0-a4d5-2a57557ed40e, package HeartbeatRequestCommand, 8a1e0eb9-48e4-4e1b-a696-6b846c55e3dc.”.
11:09:13.311 PM Debug | EventStoreConnection ‘“ES-899f6605-9795-4c62-a5d6-c5c8a3b8e95d”’: “Timed out waiting for client to be identified”.
11:09:13.319 PM Debug | EventStoreConnection ‘“ES-899f6605-9795-4c62-a5d6-c5c8a3b8e95d”’: “CloseTcpConnection”.
11:09:13.324 PM Information | ClientAPI “TcpConnection” closed [04:09:13.324: N"127.0.0.1:1113", L"127.0.0.1:51501", {5c838cbd-ece4-4aa0-a4d5-2a57557ed40e}]:
11:09:13.335 PM Information | Received bytes: 182, Sent bytes: 190
11:09:13.339 PM Information | Send calls: 6, callbacks: 6
11:09:13.342 PM Information | Receive calls: 7, callbacks: 6
11:09:13.346 PM Information | Close reason: [Success] “Timed out waiting for client to be identified”
11:09:13.349 PM Debug | TcpPackageConnection: connection [“127.0.0.1:1113”, L"127.0.0.1:51501", {5c838cbd-ece4-4aa0-a4d5-2a57557ed40e}] was closed “cleanly.”
11:09:13.358 PM Debug | EventStoreConnection ‘“ES-899f6605-9795-4c62-a5d6-c5c8a3b8e95d”’: “enqueueing message EventStore.ClientAPI.Internal.TcpConnectionClosedMessage.”.
11:09:13.365 PM Debug | EventStoreConnection ‘“ES-899f6605-9795-4c62-a5d6-c5c8a3b8e95d”’: “TCP connection to [127.0.0.1:1113, L127.0.0.1:51501, {5c838cbd-ece4-4aa0-a4d5-2a57557ed40e}] closed.”.
11:09:13.373 PM Debug | EventStoreConnection ‘“ES-899f6605-9795-4c62-a5d6-c5c8a3b8e95d”’: “IGNORED (_state: Connecting, _conn.ID: {00000000-0000-0000-0000-000000000000}, conn.ID: {5c838cbd-ece4-4aa0-a4d5-2a57557ed40e}): TCP connection to [127.0.0.1:1113, L127.0.0.1:51501] closed.”.
11:09:13.508 PM Debug | EventStoreConnection ‘“ES-899f6605-9795-4c62-a5d6-c5c8a3b8e95d”’: “TimerTick checking reconnection…”.
11:09:13.518 PM Debug | EventStoreConnection ‘“ES-899f6605-9795-4c62-a5d6-c5c8a3b8e95d”’: “DiscoverEndPoint”.
11:09:13.524 PM Debug | EventStoreConnection ‘“ES-899f6605-9795-4c62-a5d6-c5c8a3b8e95d”’: “enqueueing message EventStore.ClientAPI.Internal.EstablishTcpConnectionMessage.”.
11:09:13.532 PM Debug | EventStoreConnection ‘“ES-899f6605-9795-4c62-a5d6-c5c8a3b8e95d”’: “EstablishTcpConnection to [127.0.0.1:1113]”.
11:09:13.539 PM Debug | TcpPackageConnection: connected to [“127.0.0.1:1113”, L"127.0.0.1:51502", {d9eef1f8-15c9-46be-a2ee-bc8cdfbd3873}].
11:09:13.547 PM Debug | EventStoreConnection ‘“ES-899f6605-9795-4c62-a5d6-c5c8a3b8e95d”’: “enqueueing message EventStore.ClientAPI.Internal.TcpConnectionEstablishedMessage.”.
11:09:13.554 PM Debug | EventStoreConnection ‘“ES-899f6605-9795-4c62-a5d6-c5c8a3b8e95d”’: “TCP connection to [127.0.0.1:1113, L127.0.0.1:51502, {d9eef1f8-15c9-46be-a2ee-bc8cdfbd3873}] established.”.
11:09:13.561 PM Debug | EventStoreConnection ‘“ES-899f6605-9795-4c62-a5d6-c5c8a3b8e95d”’: “enqueueing message EventStore.ClientAPI.Internal.HandleTcpPackageMessage.”.
11:09:13.568 PM Debug | EventStoreConnection ‘“ES-899f6605-9795-4c62-a5d6-c5c8a3b8e95d”’: “HandleTcpPackage connId d9eef1f8-15c9-46be-a2ee-bc8cdfbd3873, package Authenticated, f6b0ce8d-e14f-4c09-a0b2-78d820fb001c.”.
11:09:13.576 PM Debug | EventStoreConnection ‘“ES-899f6605-9795-4c62-a5d6-c5c8a3b8e95d”’: “enqueueing message EventStore.ClientAPI.Internal.HandleTcpPackageMessage.”.
11:09:13.582 PM Debug | EventStoreConnection ‘“ES-899f6605-9795-4c62-a5d6-c5c8a3b8e95d”’: “HandleTcpPackage connId d9eef1f8-15c9-46be-a2ee-bc8cdfbd3873, package BadRequest, 981d0dbf-e800-4704-a714-4fa8bc7abf3e.”.
11:09:13.587 PM Debug | EventStoreConnection ‘“ES-899f6605-9795-4c62-a5d6-c5c8a3b8e95d”’: “HandleTcpPackage UNMAPPED PACKAGE with CorrelationId {981d0dbf-e800-4704-a714-4fa8bc7abf3e}, Command: BadRequest”.
11:09:15.138 PM Debug | EventStoreConnection ‘“ES-899f6605-9795-4c62-a5d6-c5c8a3b8e95d”’: “enqueueing message EventStore.ClientAPI.Internal.HandleTcpPackageMessage.”.
11:09:15.145 PM Debug | EventStoreConnection ‘“ES-899f6605-9795-4c62-a5d6-c5c8a3b8e95d”’: “HandleTcpPackage connId d9eef1f8-15c9-46be-a2ee-bc8cdfbd3873, package HeartbeatResponseCommand, b2b4de68-3a87-465f-acd5-0b57261114e5.”.
11:09:17.541 PM Debug | EventStoreConnection ‘“ES-899f6605-9795-4c62-a5d6-c5c8a3b8e95d”’: “enqueueing message EventStore.ClientAPI.Internal.HandleTcpPackageMessage.”.
11:09:17.548 PM Debug | EventStoreConnection ‘“ES-899f6605-9795-4c62-a5d6-c5c8a3b8e95d”’: “HandleTcpPackage connId d9eef1f8-15c9-46be-a2ee-bc8cdfbd3873, package HeartbeatRequestCommand, ae189ffd-e59d-4e5d-b2f9-399a3f98d11d.”.
11:09:18.383 PM Debug | EventStoreConnection ‘“ES-899f6605-9795-4c62-a5d6-c5c8a3b8e95d”’: “enqueueing message EventStore.ClientAPI.Internal.HandleTcpPackageMessage.”.
11:09:18.391 PM Debug | EventStoreConnection ‘“ES-899f6605-9795-4c62-a5d6-c5c8a3b8e95d”’: “HandleTcpPackage connId d9eef1f8-15c9-46be-a2ee-bc8cdfbd3873, package HeartbeatResponseCommand, 67b7296c-85a8-46c3-87c7-38d71ba0fdeb.”.
11:09:20.541 PM Debug | EventStoreConnection ‘“ES-899f6605-9795-4c62-a5d6-c5c8a3b8e95d”’: “enqueueing message EventStore.ClientAPI.Internal.HandleTcpPackageMessage.”.
11:09:20.549 PM Debug | EventStoreConnection ‘“ES-899f6605-9795-4c62-a5d6-c5c8a3b8e95d”’: “HandleTcpPackage connId d9eef1f8-15c9-46be-a2ee-bc8cdfbd3873, package HeartbeatRequestCommand, 3bfdfed0-d258-4b34-973b-b1cbc40f2f0f.”.
11:09:20.604 PM Debug | EventStoreConnection ‘“ES-899f6605-9795-4c62-a5d6-c5c8a3b8e95d”’: “Timed out waiting for client to be identified”.
11:09:20.611 PM Debug | EventStoreConnection ‘“ES-899f6605-9795-4c62-a5d6-c5c8a3b8e95d”’: “CloseTcpConnection”.
11:09:20.617 PM Information | ClientAPI “TcpConnection” closed [04:09:20.617: N"127.0.0.1:1113", L"127.0.0.1:51502", {d9eef1f8-15c9-46be-a2ee-bc8cdfbd3873}]:
11:09:20.628 PM Information | Received bytes: 182, Sent bytes: 190
11:09:20.632 PM Information | Send calls: 6, callbacks: 6
11:09:20.637 PM Information | Receive calls: 7, callbacks: 6
11:09:20.642 PM Information | Close reason: [Success] “Timed out waiting for client to be identified”
11:09:20.648 PM Debug | TcpPackageConnection: connection [“127.0.0.1:1113”, L"127.0.0.1:51502", {d9eef1f8-15c9-46be-a2ee-bc8cdfbd3873}] was closed “cleanly.”
11:09:20.657 PM Debug | EventStoreConnection ‘“ES-899f6605-9795-4c62-a5d6-c5c8a3b8e95d”’: “enqueueing message EventStore.ClientAPI.Internal.TcpConnectionClosedMessage.”.
11:09:20.665 PM Debug | EventStoreConnection ‘“ES-899f6605-9795-4c62-a5d6-c5c8a3b8e95d”’: “TCP connection to [127.0.0.1:1113, L127.0.0.1:51502, {d9eef1f8-15c9-46be-a2ee-bc8cdfbd3873}] closed.”.
11:09:20.671 PM Debug | EventStoreConnection ‘“ES-899f6605-9795-4c62-a5d6-c5c8a3b8e95d”’: “IGNORED (_state: Connecting, _conn.ID: {00000000-0000-0000-0000-000000000000}, conn.ID: {d9eef1f8-15c9-46be-a2ee-bc8cdfbd3873}): TCP connection to [127.0.0.1:1113, L127.0.0.1:51502] closed.”.
11:09:20.814 PM Debug | EventStoreConnection ‘“ES-899f6605-9795-4c62-a5d6-c5c8a3b8e95d”’: “TimerTick checking reconnection…”.
11:09:20.821 PM Debug | EventStoreConnection ‘“ES-899f6605-9795-4c62-a5d6-c5c8a3b8e95d”’: “CloseConnection, reason Reconnection limit reached., exception .”.
11:09:20.832 PM Debug | EventStoreConnection ‘“ES-899f6605-9795-4c62-a5d6-c5c8a3b8e95d”’: “CloseTcpConnection IGNORED because _connection == null”.
11:09:20.841 PM Information | EventStoreConnection ‘“ES-899f6605-9795-4c62-a5d6-c5c8a3b8e95d”’: “Closed. Reason: Reconnection limit reached…”.
11:11:25.574 PM Debug | EventStoreConnection ‘“ES-899f6605-9795-4c62-a5d6-c5c8a3b8e95d”’: “enqueueing message EventStore.ClientAPI.Internal.CloseConnectionMessage.”.
11:11:25.578 PM Debug | EventStoreConnection ‘“ES-899f6605-9795-4c62-a5d6-c5c8a3b8e95d”’: “CloseConnection IGNORED because is ESConnection is CLOSED, reason Connection close requested by client., exception .”.

– SERVER LOG –

[PID:10128:001 2017.12.26 04:08:35.377 INFO ProgramBase1 ] ES VERSION: 4.0.0.4 (oss-v4.0.0-rc1-2-g7336a8ad5/7336a8ad580686e8f4d124c9073362e132e8279f, Mon, 20 Feb 2017 16:23:58 +0000) [PID:10128:001 2017.12.26 04:08:35.387 INFO ProgramBase1 ] OS: Windows (Microsoft Windows NT 6.1.7601 Service Pack 1)
[PID:10128:001 2017.12.26 04:08:35.387 INFO ProgramBase1 ] RUNTIME: .NET 4.0.30319.42000 (64-bit) [PID:10128:001 2017.12.26 04:08:35.387 INFO ProgramBase1 ] GC: 3 GENERATIONS
[PID:10128:001 2017.12.26 04:08:35.387 INFO ProgramBase1 ] LOGS: <snip> [PID:10128:001 2017.12.26 04:08:35.387 INFO ProgramBase1 ] MODIFIED OPTIONS:

DB:                       ./_data/db (Command Line)
LOG:                      ./_data/logs (Command Line)

DEFAULT OPTIONS:

HELP:                     False (<DEFAULT>)
VERSION:                  False (<DEFAULT>)
CONFIG:                   <empty> (<DEFAULT>)
DEFINES:                  <empty> (<DEFAULT>)
WHAT IF:                  False (<DEFAULT>)
START STANDARD PROJECTIONS: False (<DEFAULT>)
DISABLE HTTP CACHING:     False (<DEFAULT>)
MONO MIN THREADPOOL SIZE: 10 (<DEFAULT>)
INT IP:                   127.0.0.1 (<DEFAULT>)
EXT IP:                   127.0.0.1 (<DEFAULT>)
INT HTTP PORT:            2112 (<DEFAULT>)
EXT HTTP PORT:            2113 (<DEFAULT>)
INT TCP PORT:             1112 (<DEFAULT>)
INT SECURE TCP PORT:      0 (<DEFAULT>)
EXT TCP PORT:             1113 (<DEFAULT>)
EXT SECURE TCP PORT ADVERTISE AS: 0 (<DEFAULT>)
EXT SECURE TCP PORT:      0 (<DEFAULT>)
EXT IP ADVERTISE AS:      <empty> (<DEFAULT>)
EXT TCP PORT ADVERTISE AS: 0 (<DEFAULT>)
EXT HTTP PORT ADVERTISE AS: 0 (<DEFAULT>)
INT IP ADVERTISE AS:      <empty> (<DEFAULT>)
INT SECURE TCP PORT ADVERTISE AS: 0 (<DEFAULT>)
INT TCP PORT ADVERTISE AS: 0 (<DEFAULT>)
INT HTTP PORT ADVERTISE AS: 0 (<DEFAULT>)
INT TCP HEARTBEAT TIMEOUT: 700 (<DEFAULT>)
EXT TCP HEARTBEAT TIMEOUT: 1000 (<DEFAULT>)
INT TCP HEARTBEAT INTERVAL: 700 (<DEFAULT>)
EXT TCP HEARTBEAT INTERVAL: 2000 (<DEFAULT>)
GOSSIP ON SINGLE NODE:    False (<DEFAULT>)
FORCE:                    False (<DEFAULT>)
CLUSTER SIZE:             1 (<DEFAULT>)
NODE PRIORITY:            0 (<DEFAULT>)
MIN FLUSH DELAY MS:       2 (<DEFAULT>)
COMMIT COUNT:             -1 (<DEFAULT>)
PREPARE COUNT:            -1 (<DEFAULT>)
ADMIN ON EXT:             True (<DEFAULT>)
STATS ON EXT:             True (<DEFAULT>)
GOSSIP ON EXT:            True (<DEFAULT>)
DISABLE SCAVENGE MERGING: False (<DEFAULT>)
SCAVENGE HISTORY MAX AGE: 30 (<DEFAULT>)
DISCOVER VIA DNS:         True (<DEFAULT>)
CLUSTER DNS:              fake.dns (<DEFAULT>)
CLUSTER GOSSIP PORT:      30777 (<DEFAULT>)
GOSSIP SEED:              <empty> (<DEFAULT>)
STATS PERIOD SEC:         30 (<DEFAULT>)
CACHED CHUNKS:            -1 (<DEFAULT>)
READER THREADS COUNT:     4 (<DEFAULT>)
CHUNKS CACHE SIZE:        536871424 (<DEFAULT>)
MAX MEM TABLE SIZE:       1000000 (<DEFAULT>)
HASH COLLISION READ LIMIT: 100 (<DEFAULT>)
INDEX:                    <empty> (<DEFAULT>)
MEM DB:                   False (<DEFAULT>)
SKIP DB VERIFY:           False (<DEFAULT>)
WRITE THROUGH:            False (<DEFAULT>)
UNBUFFERED:               False (<DEFAULT>)
RUN PROJECTIONS:          None (<DEFAULT>)
PROJECTION THREADS:       3 (<DEFAULT>)
WORKER THREADS:           5 (<DEFAULT>)
INT HTTP PREFIXES:        <empty> (<DEFAULT>)
EXT HTTP PREFIXES:        <empty> (<DEFAULT>)
ENABLE TRUSTED AUTH:      False (<DEFAULT>)
ADD INTERFACE PREFIXES:   True (<DEFAULT>)
CERTIFICATE STORE LOCATION: <empty> (<DEFAULT>)
CERTIFICATE STORE NAME:   <empty> (<DEFAULT>)
CERTIFICATE SUBJECT NAME: <empty> (<DEFAULT>)
CERTIFICATE THUMBPRINT:   <empty> (<DEFAULT>)
CERTIFICATE FILE:         <empty> (<DEFAULT>)
CERTIFICATE PASSWORD:     <empty> (<DEFAULT>)
USE INTERNAL SSL:         False (<DEFAULT>)
DISABLE INSECURE TCP:     False (<DEFAULT>)
SSL TARGET HOST:          n/a (<DEFAULT>)
SSL VALIDATE SERVER:      True (<DEFAULT>)
AUTHENTICATION TYPE:      internal (<DEFAULT>)
AUTHENTICATION CONFIG:    <empty> (<DEFAULT>)
PREPARE TIMEOUT MS:       2000 (<DEFAULT>)
COMMIT TIMEOUT MS:        2000 (<DEFAULT>)
UNSAFE DISABLE FLUSH TO DISK: False (<DEFAULT>)
BETTER ORDERING:          False (<DEFAULT>)
UNSAFE IGNORE HARD DELETE: False (<DEFAULT>)
INDEX CACHE DEPTH:        16 (<DEFAULT>)
GOSSIP INTERVAL MS:       1000 (<DEFAULT>)
GOSSIP ALLOWED DIFFERENCE MS: 60000 (<DEFAULT>)
GOSSIP TIMEOUT MS:        500 (<DEFAULT>)
ENABLE HISTOGRAMS:        False (<DEFAULT>)
LOG HTTP REQUESTS:        False (<DEFAULT>)
ALWAYS KEEP SCAVENGED:    False (<DEFAULT>)

[PID:10128:001 2017.12.26 04:08:35.399 INFO ProgramBase1 ] Quorum size set to 1 [PID:10128:001 2017.12.26 04:08:35.399 INFO ProgramBase1 ] Cannot find plugins path: C:\ProgramData\chocolatey\lib\eventstore-oss\tools\plugins
[PID:10128:001 2017.12.26 04:08:35.498 INFO VNodeBuilder ] INSTANCE ID: 79404485-0a2b-4a99-a632-c35346b90188
[PID:10128:001 2017.12.26 04:08:35.498 INFO VNodeBuilder ] DATABASE: ./_data/db
[PID:10128:001 2017.12.26 04:08:35.498 INFO VNodeBuilder ] WRITER CHECKPOINT: 104698714 (0x63D935A)
[PID:10128:001 2017.12.26 04:08:35.498 INFO VNodeBuilder ] CHASER CHECKPOINT: 104698714 (0x63D935A)
[PID:10128:001 2017.12.26 04:08:35.498 INFO VNodeBuilder ] EPOCH CHECKPOINT: 104668603 (0x63D1DBB)
[PID:10128:001 2017.12.26 04:08:35.498 INFO VNodeBuilder ] TRUNCATE CHECKPOINT: -1 (0xFFFFFFFFFFFFFFFF)
[PID:10128:001 2017.12.26 04:08:35.577 TRACE MessageHierarchy ] MessageHierarchy initialization took 00:00:00.0462461.
[PID:10128:001 2017.12.26 04:08:35.904 TRACE TFChunk ] Opened ongoing ./_data/db\chunk-000000.000000 as version 3
[PID:10128:001 2017.12.26 04:08:35.959 TRACE TFChunk ] CACHED TFChunk #0-0 (chunk-000000.000000) in 00:00:00.0496372.
[PID:10128:001 2017.12.26 04:08:36.184 INFO MiniWeb ] Starting MiniWeb for /web/es/js/projections ==> C:\ProgramData\chocolatey\lib\eventstore-oss\tools\projections
[PID:10128:001 2017.12.26 04:08:36.184 INFO MiniWeb ] Starting MiniWeb for /web/es/js/projections/v8/Prelude ==> C:\ProgramData\chocolatey\lib\eventstore-oss\tools\Prelude
[PID:10128:001 2017.12.26 04:08:36.191 INFO MiniWeb ] Starting MiniWeb for /web ==> C:\ProgramData\chocolatey\lib\eventstore-oss\tools\clusternode-web
[PID:10128:001 2017.12.26 04:08:36.191 TRACE MiniWeb ] Binding MiniWeb to /web/{*remaining_path}
[PID:10128:016 2017.12.26 04:08:36.191 INFO ClusterVNodeControll] ========== [127.0.0.1:2112] SYSTEM INIT…
[PID:10128:016 2017.12.26 04:08:36.217 INFO TcpServerListener ] Starting Normal TCP listening on TCP endpoint: 127.0.0.1:1113.
[PID:10128:017 2017.12.26 04:08:36.229 INFO IndexCommitter ] TableIndex initialization…
[PID:10128:017 2017.12.26 04:08:36.229 INFO IndexCommitter ] ReadIndex building…
[PID:10128:016 2017.12.26 04:08:36.238 INFO HttpAsyncServer ] Starting HTTP server on [http://127.0.0.1:2113/,http://localhost:2113/].…
[PID:10128:016 2017.12.26 04:08:36.238 INFO HttpAsyncServer ] HTTP server is up and listening on [http://127.0.0.1:2113/,http://localhost:2113/]
[PID:10128:016 2017.12.26 04:08:36.251 TRACE QueuedHandlerMresWit] SLOW QUEUE MSG [MainQueue]: SystemInit - 48ms. Q: 0/4.
[PID:10128:016 2017.12.26 04:08:36.251 INFO ClusterVNodeControll] ========== [127.0.0.1:2112] Service ‘StorageReader’ initialized.
[PID:10128:016 2017.12.26 04:08:36.251 INFO ClusterVNodeControll] ========== [127.0.0.1:2112] Service ‘StorageWriter’ initialized.
[PID:10128:017 2017.12.26 04:08:36.301 DEBUG IndexCommitter ] ReadIndex rebuilding done: total processed 7065 records, time elapsed: 00:00:00.0720072.
[PID:10128:016 2017.12.26 04:08:36.319 INFO ClusterVNodeControll] ========== [127.0.0.1:2112] Service ‘StorageChaser’ initialized.
[PID:10128:016 2017.12.26 04:08:36.319 INFO ClusterVNodeControll] ========== [127.0.0.1:2112] SYSTEM START…
[PID:10128:016 2017.12.26 04:08:36.319 INFO ClusterVNodeControll] ========== [127.0.0.1:2112] IS UNKNOWN…
[PID:10128:008 2017.12.26 04:08:36.334 DEBUG PersistentSubscripti] Subscriptions received state change to Unknown stopping listening.
[PID:10128:016 2017.12.26 04:08:36.334 DEBUG ElectionsService ] ELECTIONS: STARTING ELECTIONS.
[PID:10128:016 2017.12.26 04:08:36.334 DEBUG ElectionsService ] ELECTIONS: (V=0) SHIFT TO LEADER ELECTION.
[PID:10128:016 2017.12.26 04:08:36.334 DEBUG ElectionsService ] ELECTIONS: (V=0) VIEWCHANGE FROM [127.0.0.1:2112, {79404485-0a2b-4a99-a632-c35346b90188}].
[PID:10128:016 2017.12.26 04:08:36.334 DEBUG ElectionsService ] ELECTIONS: (V=0) MAJORITY OF VIEWCHANGE.
[PID:10128:016 2017.12.26 04:08:36.334 DEBUG ElectionsService ] ELECTIONS: (V=0) SHIFT TO PREPARE PHASE.
[PID:10128:016 2017.12.26 04:08:36.345 DEBUG ElectionsService ] ELECTIONS: (V=0) PREPARE_OK FROM [127.0.0.1:2112,{79404485-0a2b-4a99-a632-c35346b90188}](L=104683859,W=104698714,C=104698714,E13@104668603:{aeaa8c08-3d72-412d-b1a8-ccee946cb5fa}).
[PID:10128:016 2017.12.26 04:08:36.345 DEBUG ElectionsService ] ELECTIONS: (V=0) SHIFT TO REG_LEADER.
[PID:10128:016 2017.12.26 04:08:36.345 DEBUG ElectionsService ] ELECTIONS: (V=0) SENDING PROPOSAL CANDIDATE: [127.0.0.1:2112,{79404485-0a2b-4a99-a632-c35346b90188}](L=104683859,W=104698714,C=104698714,E13@104668603:{aeaa8c08-3d72-412d-b1a8-ccee946cb5fa}), ME: [127.0.0.1:2112,{79404485-0a2b-4a99-a632-c35346b90188}](L=104683859,W=104698714,C=104698714,E13@104668603:{aeaa8c08-3d72-412d-b1a8-ccee946cb5fa}).
[PID:10128:016 2017.12.26 04:08:36.345 DEBUG ElectionsService ] ELECTIONS: (V=0) ACCEPT FROM [127.0.0.1:2112,{79404485-0a2b-4a99-a632-c35346b90188}] M=[127.0.0.1:2112,{79404485-0a2b-4a99-a632-c35346b90188}]).
[PID:10128:016 2017.12.26 04:08:36.345 INFO ElectionsService ] ELECTIONS: (V=0) DONE. ELECTED MASTER = [127.0.0.1:2112,{79404485-0a2b-4a99-a632-c35346b90188}](L=104683859,W=104698714,C=104698714,E13@104668603:{aeaa8c08-3d72-412d-b1a8-ccee946cb5fa}). ME=[127.0.0.1:2112,{79404485-0a2b-4a99-a632-c35346b90188}](L=104683859,W=104698714,C=104698714,E13@104668603:{aeaa8c08-3d72-412d-b1a8-ccee946cb5fa}).
[PID:10128:016 2017.12.26 04:08:36.345 INFO ClusterVNodeControll] ========== [127.0.0.1:2112] PRE-MASTER STATE, WAITING FOR CHASER TO CATCH UP…
[PID:10128:009 2017.12.26 04:08:36.345 DEBUG PersistentSubscripti] Subscriptions received state change to PreMaster stopping listening.
[PID:10128:016 2017.12.26 04:08:36.345 INFO ClusterVNodeControll] ========== [127.0.0.1:2112] IS MASTER… SPARTA!
[PID:10128:011 2017.12.26 04:08:36.345 DEBUG PersistentSubscripti] Subscriptions Became Master so now handling subscriptions
[PID:10128:014 2017.12.26 04:08:36.399 DEBUG EpochManager ] === Writing E14@104698714:{9512c67d-b1f3-4574-9fbb-5fb1965a28b6} (previous epoch at 104668603).
[PID:10128:014 2017.12.26 04:08:36.399 DEBUG EpochManager ] === Update Last Epoch E14@104698714:{9512c67d-b1f3-4574-9fbb-5fb1965a28b6} (previous epoch at 104668603).
[PID:10128:019 2017.12.26 04:08:36.409 DEBUG ProjectionCoreCoordi] PROJECTIONS: Starting Projections Core Coordinator. (Node State : Master)
[PID:10128:016 2017.12.26 04:08:36.409 INFO ClusterVNodeControll] ========== [127.0.0.1:2112] Sub System ‘Projections’ initialized.
[PID:10128:019 2017.12.26 04:08:36.409 DEBUG ProjectionManager ] PROJECTIONS: Starting Projections Manager. (Node State : Master)
[PID:10128:019 2017.12.26 04:08:36.426 DEBUG MultiStreamMessageWr] PROJECTIONS: Resetting Worker Writer
[PID:10128:007 2017.12.26 04:08:37.754 TRACE MonitoringService ] Could not create performance counter: category=’.NET CLR Exceptions’, counter=’# of Exceps Thrown / sec’, instance=‘EventStore.ClusterNode’. Error: Category does not exist.
[PID:10128:007 2017.12.26 04:08:37.754 TRACE MonitoringService ] Could not create performance counter: category=’.NET CLR LocksAndThreads’, counter=‘Contention Rate / sec’, instance=‘EventStore.ClusterNode’. Error: Category does not exist.
[PID:10128:007 2017.12.26 04:08:37.754 TRACE MonitoringService ] Could not create performance counter: category=’.NET CLR Memory’, counter=’# Gen 0 Collections’, instance=‘EventStore.ClusterNode’. Error: Category does not exist.
[PID:10128:007 2017.12.26 04:08:37.754 TRACE MonitoringService ] Could not create performance counter: category=’.NET CLR Memory’, counter=’# Gen 1 Collections’, instance=‘EventStore.ClusterNode’. Error: Category does not exist.
[PID:10128:007 2017.12.26 04:08:37.754 TRACE MonitoringService ] Could not create performance counter: category=’.NET CLR Memory’, counter=’# Gen 2 Collections’, instance=‘EventStore.ClusterNode’. Error: Category does not exist.
[PID:10128:007 2017.12.26 04:08:37.754 TRACE MonitoringService ] Could not create performance counter: category=’.NET CLR Memory’, counter=‘Gen 0 heap size’, instance=‘EventStore.ClusterNode’. Error: Category does not exist.
[PID:10128:007 2017.12.26 04:08:37.754 TRACE MonitoringService ] Could not create performance counter: category=’.NET CLR Memory’, counter=‘Gen 1 heap size’, instance=‘EventStore.ClusterNode’. Error: Category does not exist.
[PID:10128:007 2017.12.26 04:08:37.754 TRACE MonitoringService ] Could not create performance counter: category=’.NET CLR Memory’, counter=‘Gen 2 heap size’, instance=‘EventStore.ClusterNode’. Error: Category does not exist.
[PID:10128:007 2017.12.26 04:08:37.754 TRACE MonitoringService ] Could not create performance counter: category=’.NET CLR Memory’, counter=‘Large Object Heap size’, instance=‘EventStore.ClusterNode’. Error: Category does not exist.
[PID:10128:007 2017.12.26 04:08:37.754 TRACE MonitoringService ] Could not create performance counter: category=’.NET CLR Memory’, counter=‘Allocated Bytes/sec’, instance=‘EventStore.ClusterNode’. Error: Category does not exist.
[PID:10128:007 2017.12.26 04:08:37.754 TRACE MonitoringService ] Could not create performance counter: category=’.NET CLR Memory’, counter=’% Time in GC’, instance=‘EventStore.ClusterNode’. Error: Category does not exist.
[PID:10128:007 2017.12.26 04:08:37.754 TRACE MonitoringService ] Could not create performance counter: category=’.NET CLR Memory’, counter=’# Bytes in all Heaps’, instance=‘EventStore.ClusterNode’. Error: Category does not exist.
[PID:10128:007 2017.12.26 04:08:37.771 TRACE QueuedHandlerThreadP] SLOW QUEUE MSG [MonitoringQueue]: SystemInit - 1555ms. Q: 0/5.
[PID:10128:007 2017.12.26 04:08:37.771 TRACE MonitoringService ] Created stats stream ‘$stats-127.0.0.1:2113’, code = WrongExpectedVersion
[PID:10128:004 2017.12.26 04:08:51.514 INFO TcpService ] External TCP connection accepted: [Normal, 127.0.0.1:51493, L127.0.0.1:1113, {b331a66a-7ebb-433a-b09c-26250aec08e0}].
[PID:10128:023 2017.12.26 04:08:58.774 INFO TcpConnection ] ES TcpConnection closed [04:08:58.748: N127.0.0.1:51493, L127.0.0.1:1113, {b331a66a-7ebb-433a-b09c-26250aec08e0}]:Received bytes: 190, Sent bytes: 182
[PID:10128:023 2017.12.26 04:08:58.774 INFO TcpConnection ] ES TcpConnection closed [04:08:58.774: N127.0.0.1:51493, L127.0.0.1:1113, {b331a66a-7ebb-433a-b09c-26250aec08e0}]:Send calls: 6, callbacks: 6
[PID:10128:023 2017.12.26 04:08:58.774 INFO TcpConnection ] ES TcpConnection closed [04:08:58.774: N127.0.0.1:51493, L127.0.0.1:1113, {b331a66a-7ebb-433a-b09c-26250aec08e0}]:Receive calls: 7, callbacks: 7
[PID:10128:023 2017.12.26 04:08:58.774 INFO TcpConnection ] ES TcpConnection closed [04:08:58.774: N127.0.0.1:51493, L127.0.0.1:1113, {b331a66a-7ebb-433a-b09c-26250aec08e0}]:Close reason: [Success] Socket closed
[PID:10128:023 2017.12.26 04:08:58.794 INFO TcpConnectionManager] Connection ‘external-normal’ [127.0.0.1:51493, {b331a66a-7ebb-433a-b09c-26250aec08e0}] closed: Success.
[PID:10128:021 2017.12.26 04:08:58.794 DEBUG PersistentSubscripti] Lost connection from 127.0.0.1:51493
[PID:10128:004 2017.12.26 04:08:58.944 INFO TcpService ] External TCP connection accepted: [Normal, 127.0.0.1:51496, L127.0.0.1:1113, {13fe7471-6514-4037-b9e0-e98f773fb45d}].
[PID:10128:023 2017.12.26 04:09:06.037 INFO TcpConnection ] ES TcpConnection closed [04:09:06.037: N127.0.0.1:51496, L127.0.0.1:1113, {13fe7471-6514-4037-b9e0-e98f773fb45d}]:Received bytes: 190, Sent bytes: 182
[PID:10128:023 2017.12.26 04:09:06.037 INFO TcpConnection ] ES TcpConnection closed [04:09:06.038: N127.0.0.1:51496, L127.0.0.1:1113, {13fe7471-6514-4037-b9e0-e98f773fb45d}]:Send calls: 6, callbacks: 6
[PID:10128:023 2017.12.26 04:09:06.037 INFO TcpConnection ] ES TcpConnection closed [04:09:06.038: N127.0.0.1:51496, L127.0.0.1:1113, {13fe7471-6514-4037-b9e0-e98f773fb45d}]:Receive calls: 7, callbacks: 7
[PID:10128:023 2017.12.26 04:09:06.037 INFO TcpConnection ] ES TcpConnection closed [04:09:06.038: N127.0.0.1:51496, L127.0.0.1:1113, {13fe7471-6514-4037-b9e0-e98f773fb45d}]:Close reason: [Success] Socket closed
[PID:10128:023 2017.12.26 04:09:06.037 INFO TcpConnectionManager] Connection ‘external-normal’ [127.0.0.1:51496, {13fe7471-6514-4037-b9e0-e98f773fb45d}] closed: Success.
[PID:10128:007 2017.12.26 04:09:06.037 DEBUG PersistentSubscripti] Lost connection from 127.0.0.1:51496
[PID:10128:004 2017.12.26 04:09:06.241 INFO TcpService ] External TCP connection accepted: [Normal, 127.0.0.1:51501, L127.0.0.1:1113, {a316dc2f-9711-4661-8ae8-f5a816b93c55}].
[PID:10128:023 2017.12.26 04:09:13.349 INFO TcpConnection ] ES TcpConnection closed [04:09:13.349: N127.0.0.1:51501, L127.0.0.1:1113, {a316dc2f-9711-4661-8ae8-f5a816b93c55}]:Received bytes: 190, Sent bytes: 182
[PID:10128:023 2017.12.26 04:09:13.349 INFO TcpConnection ] ES TcpConnection closed [04:09:13.349: N127.0.0.1:51501, L127.0.0.1:1113, {a316dc2f-9711-4661-8ae8-f5a816b93c55}]:Send calls: 6, callbacks: 6
[PID:10128:023 2017.12.26 04:09:13.349 INFO TcpConnection ] ES TcpConnection closed [04:09:13.350: N127.0.0.1:51501, L127.0.0.1:1113, {a316dc2f-9711-4661-8ae8-f5a816b93c55}]:Receive calls: 7, callbacks: 7
[PID:10128:023 2017.12.26 04:09:13.349 INFO TcpConnection ] ES TcpConnection closed [04:09:13.350: N127.0.0.1:51501, L127.0.0.1:1113, {a316dc2f-9711-4661-8ae8-f5a816b93c55}]:Close reason: [Success] Socket closed
[PID:10128:023 2017.12.26 04:09:13.349 INFO TcpConnectionManager] Connection ‘external-normal’ [127.0.0.1:51501, {a316dc2f-9711-4661-8ae8-f5a816b93c55}] closed: Success.
[PID:10128:006 2017.12.26 04:09:13.349 DEBUG PersistentSubscripti] Lost connection from 127.0.0.1:51501
[PID:10128:004 2017.12.26 04:09:13.539 INFO TcpService ] External TCP connection accepted: [Normal, 127.0.0.1:51502, L127.0.0.1:1113, {420d32da-87f3-4fa7-a230-8999aa8b3b55}].
[PID:10128:004 2017.12.26 04:09:20.648 INFO TcpConnection ] ES TcpConnection closed [04:09:20.648: N127.0.0.1:51502, L127.0.0.1:1113, {420d32da-87f3-4fa7-a230-8999aa8b3b55}]:Received bytes: 190, Sent bytes: 182
[PID:10128:004 2017.12.26 04:09:20.648 INFO TcpConnection ] ES TcpConnection closed [04:09:20.648: N127.0.0.1:51502, L127.0.0.1:1113, {420d32da-87f3-4fa7-a230-8999aa8b3b55}]:Send calls: 6, callbacks: 6
[PID:10128:004 2017.12.26 04:09:20.648 INFO TcpConnection ] ES TcpConnection closed [04:09:20.648: N127.0.0.1:51502, L127.0.0.1:1113, {420d32da-87f3-4fa7-a230-8999aa8b3b55}]:Receive calls: 7, callbacks: 7
[PID:10128:004 2017.12.26 04:09:20.648 INFO TcpConnection ] ES TcpConnection closed [04:09:20.648: N127.0.0.1:51502, L127.0.0.1:1113, {420d32da-87f3-4fa7-a230-8999aa8b3b55}]:Close reason: [Success] Socket closed
[PID:10128:004 2017.12.26 04:09:20.648 INFO TcpConnectionManager] Connection ‘external-normal’ [127.0.0.1:51502, {420d32da-87f3-4fa7-a230-8999aa8b3b55}] closed: Success.
[PID:10128:022 2017.12.26 04:09:20.648 DEBUG PersistentSubscripti] Lost connection from 127.0.0.1:51502

8

Attached is a minimal repro of the issue that produces the logs above.

The server is Event Store 4.0.3 Hotfix 1 for Windows: https://eventstore.org/downloads/EventStore-OSS-Win-v4.0.3-hotfix1.zip

EventStoreTest.zip (3.75 KB)

9

Hi Brian,

I’ve tried your client and it works fine on my machine with server 4.0.3-hotfix1 / client 4.0.3

It appears you’re using an older version of EventStore which is not compatible with the client.

The unmapped TCP message that your server is not understanding (throwing BadRequest) is the “ClientIdentified” message which was introduced in this commit:

https://github.com/EventStore/EventStore/commit/2a2c4c2c16598d7aa892913a91772a068fc27c8b

I’ve tried to build a version of EventStore just before that commit and receive the same error:

git checkout 2a2c4c2c16598d7aa892913a91772a068fc27c8b^

./build.sh

mono ./bin/clusternode/EventStore.ClusterNode.exe --db …/db --log …/logs --run-projections=All

Could it be possible there’s another older instance of Eventstore running?

Thanks,

Shaan

10

Just to confirm, I’ve also done a build with tag oss-v4.0.3-hotfix1 and this one works fine with your client and doesn’t receive “BadRequest” message.
So there’s probably an older version of the server running.

Thanks,

Shaan

11

It was indeed me!

@Shaan thanks for your verification, it made me start from scratch on my process.

Part of that was a batch file to start the .exe, which had an incorrect folder name in the path.

Windows, trying to be helpful but failing, appeared to start some v4.0.0.4 .exe it had cached somewhere.

This was perplexing because I was deleting the download folder, then redownloading, and getting the same result.

Again, thanks everyone who helped me clear that hurdle!

12

Hello Brian,

Great to hear it’s working!

Regards,

Shaan