eventAppeared being called with the same event to 2 threads

EventStoreDB
1

I am debugging an issue right now and would like to make the devs aware of it because I am reasonably certain it may be a bug.

Using the latest version of the event store and C# client I am seeing multiple of the same event appear in my event dispatcher on separate threads.

Using logging right now inside my eventAppeared lamba to print out the event id, number, and stream and I have found this happening:

2016-01-13 04:35:16,985 [63] INFO DurableSubscriber [(null)] - Processing event number 0 id df53d681-c0b7-4899-b293-1576b4f26c4d from stream default.90277d8b-c2bc-416d-bfe2-621a0d2ba1c0

2016-01-13 04:35:17,020 [22] INFO DurableSubscriber [(null)] - Processing event number 0 id df53d681-c0b7-4899-b293-1576b4f26c4d from stream default.90277d8b-c2bc-416d-bfe2-621a0d2ba1c0

63 and 22 are the 2 thread ids mentioned.

I can reproduce it everytime in my app after a few minutes of running, I am guessing it appears most often when my machine is under load but I can’t confirm that yet.

I’ll post more information as I search through the eventstore code base to figure out how this might be happening

2

Need to mention I am pretty sure its related to my subscriber getting disconnected from the store repeatedly. After upgrading to 3.4 it seems to be happening a lot more - and these event collisions always happen around the same time as the app reconnects. So I am guessing there is some internal state issue at play here inside the subscription.

I am trying to solve this 2 ways:

Figuring out a way to not block at all in eventAppeared (best option but not great if getting more events than I can handle)

Lengthening the connection timeout via a setting?

3

You mentioned that you didn’t experience this issue before?
Which version of the client and server were you using before?

4

"Need to mention I am pretty sure its related to my subscriber getting
disconnected from the store repeatedly. After upgrading to 3.4 it
seems to be happening a lot more - and these event collisions always
happen around the same time as the app reconnects. So I am guessing
there is some internal state issue at play here inside the
subscription."

How are you measuring this? What is in the client logs?

5

are you explicitly resubscribing the subscription on a reconnect?

If you restart the Eventstore N times does each event appear N times?

6

Sorry for the absence I needed to rest after being up all night.

Pieter: I am not sure and I doubt its related to the version of event store. Since upgrading to the latest I’ve also changed features in my app around that could also be causing the tcp stream to timeout if the app is under load. Which I believe is what is happening as when I lose the event store connection the web api also becomes unresponsive. I am thinking that I should put the event dispatcher and store connection code ona different thread than app main.

Greg: I put a custom logger on the event store client api and log messages inside eventAppeared, liveProcessingStarted, and subscriptionDropped. The couple lines I copied above are from inside eventAppeared

sadprof: I am using .KeepReconnecting() on the client api connection so it automatically reconnects yes. I am using the SubscribeToAllFrom api to get events as they appear in the event store. Not sure what you mean about restarting the store, the store stays up its my connection to it that drops when my app is under load.

I am working on getting a log file from the store and client that can show this, but since it only happens when the app is under load and the eventstore connection is wobbling its difficult to reproduce 100% of the time. Will post when I have it

7

Ok sorry for the wall of text but here is some extra log information. I highlighted logs from the EventStore logger in bold

The exceptions at the bottom are caused by the processing of an event twice due to this issue.

Still not sure why my app keeps disconnecting from the store (??) and still not sure what the disconnects have to do with multiprocessing the event but I’ll still be investigating

2016-01-13 19:55:34,389 [8] INFO Aggregates.DurableSubscriber [(null)] - Processing event number 1130 id b61f3d0e-0e3d-4acb-8341-2b51b13e80b0 from stream default.b60744cd-5e9e-4633-befb-e60b7dfc7c72

2016-01-13 19:55:34,965 [8] INFO Aggregates.DurableSubscriber [(null)] - Processing event number 1131 id a6168854-3de0-4369-a7b1-bcf4bac955c1 from stream default.b60744cd-5e9e-4633-befb-e60b7dfc7c72

2016-01-13 19:55:34,998 [8] INFO Aggregates.DurableSubscriber [(null)] - Processing event number 1132 id 27a05f14-2eb3-470a-a6f9-475e3e8dbe4d from stream default.b60744cd-5e9e-4633-befb-e60b7dfc7c72

2016-01-13 19:55:35,006 [8] INFO Aggregates.DurableSubscriber [(null)] - Processing event number 1133 id 3ac7b723-a573-4466-883e-c5eb5be1c2bb from stream default.b60744cd-5e9e-4633-befb-e60b7dfc7c72

2016-01-13 19:55:35,006 [8] INFO Aggregates.DurableSubscriber [(null)] - Processing event number 1134 id 73c41efa-3416-488b-8fee-a9d187c423a3 from stream default.b60744cd-5e9e-4633-befb-e60b7dfc7c72

2016-01-13 19:55:35,007 [8] INFO Aggregates.DurableSubscriber [(null)] - Processing event number 1135 id d1c54da1-ef35-4023-a10f-766a598bfe93 from stream default.b60744cd-5e9e-4633-befb-e60b7dfc7c72

2016-01-13 19:55:35,601 [8] INFO Aggregates.DurableSubscriber [(null)] - Processing event number 1136 id 64af540a-931d-495c-9bef-ca21e3f1a147 from stream default.b60744cd-5e9e-4633-befb-e60b7dfc7c72

2016-01-13 19:55:35,691 [8] INFO Aggregates.DurableSubscriber [(null)] - Processing event number 1137 id 2d824218-4cf7-4aa4-be12-5b2c891205e5 from stream default.b60744cd-5e9e-4633-befb-e60b7dfc7c72

2016-01-13 19:55:35,962 [8] INFO Aggregates.DurableSubscriber [(null)] - Processing event number 1138 id 5dbc8f40-6bbd-4e41-93ce-427d973d1ae0 from stream default.b60744cd-5e9e-4633-befb-e60b7dfc7c72

2016-01-13 19:55:35,962 [8] INFO Aggregates.DurableSubscriber [(null)] - Processing event number 1139 id f10b1c03-cf94-410a-af19-d51bc6aba897 from stream default.b60744cd-5e9e-4633-befb-e60b7dfc7c72

2016-01-13 19:55:36,144 [8] INFO Aggregates.DurableSubscriber [(null)] - Processing event number 1140 id e4b15b03-bc62-43bd-82e6-460b7542f6db from stream default.b60744cd-5e9e-4633-befb-e60b7dfc7c72

2016-01-13 19:55:37,671 [101] INFO EventStore [(null)] - ClientAPI TcpConnection closed [01:55:37.671: N127.0.0.1:3111, L127.0.0.1:4687, {22c79498-ba33-4314-b09d-e1f3f4eb4f5c}]:

Received bytes: 520632, Sent bytes: 2864

Send calls: 127, callbacks: 127

Receive calls: 430, callbacks: 430

Close reason: [Success] Socket closed

2016-01-13 19:55:37,672 [101] INFO EventStore [(null)] - TcpPackageConnection: connection [127.0.0.1:3111, L127.0.0.1:4687, {22c79498-ba33-4314-b09d-e1f3f4eb4f5c}] was closed cleanly.

2016-01-13 19:55:38,149 [8] INFO Aggregates.DurableSubscriber [(null)] - Processing event number 1141 id ee77c280-95f7-45a0-8a60-c64ca7ff581c from stream default.b60744cd-5e9e-4633-befb-e60b7dfc7c72

2016-01-13 19:55:38,202 [8] INFO Aggregates.DurableSubscriber [(null)] - Processing event number 1142 id 0e50d2b5-d7ce-4f6a-a4fb-fd0867d76e83 from stream default.b60744cd-5e9e-4633-befb-e60b7dfc7c72

2016-01-13 19:55:38,215 [8] INFO Aggregates.DurableSubscriber [(null)] - Processing event number 1143 id eb3f5649-bb44-4bfa-8f48-a2e0edc56121 from stream default.b60744cd-5e9e-4633-befb-e60b7dfc7c72

2016-01-13 19:55:38,215 [8] INFO Aggregates.DurableSubscriber [(null)] - Processing event number 1144 id 5d81bedc-44f2-4c91-8793-2c4053389b73 from stream default.b60744cd-5e9e-4633-befb-e60b7dfc7c72

2016-01-13 19:55:38,215 [8] INFO Aggregates.DurableSubscriber [(null)] - Processing event number 1145 id b356d763-ed6e-4485-8c6a-fe9385d1dbca from stream default.b60744cd-5e9e-4633-befb-e60b7dfc7c72

2016-01-13 19:55:38,222 [8] INFO Aggregates.DurableSubscriber [(null)] - Processing event number 1146 id 70f1fad2-f8e3-4c3d-aa5e-1564f74fc91a from stream default.b60744cd-5e9e-4633-befb-e60b7dfc7c72

2016-01-13 19:55:38,245 [8] INFO Aggregates.DurableSubscriber [(null)] - Processing event number 1147 id 5adb42dc-c0ef-4204-92a7-d01cf6308204 from stream default.b60744cd-5e9e-4633-befb-e60b7dfc7c72

2016-01-13 19:55:38,286 [8] INFO Aggregates.DurableSubscriber [(null)] - Processing event number 1148 id 1185017c-94e7-416e-98e4-d36cc8cabf57 from stream default.b60744cd-5e9e-4633-befb-e60b7dfc7c72

2016-01-13 19:55:38,365 [8] INFO Aggregates.DurableSubscriber [(null)] - Processing event number 1149 id 02dfa823-7d54-4802-a1c4-995dedfa7768 from stream default.b60744cd-5e9e-4633-befb-e60b7dfc7c72

2016-01-13 19:55:38,380 [8] INFO Aggregates.DurableSubscriber [(null)] - Processing event number 1150 id 7fcaeb2b-e4c7-4935-8ac4-8d9b872480e3 from stream default.b60744cd-5e9e-4633-befb-e60b7dfc7c72

2016-01-13 19:55:38,381 [102] INFO EventStore [(null)] - TcpPackageConnection: connected to [127.0.0.1:3111, L127.0.0.1:4715, {bb1deab0-e077-44d3-9a22-44297979e97b}].

2016-01-13 19:55:38,539 [8] INFO Aggregates.DurableSubscriber [(null)] - Processing event number 1151 id c4f5895a-12f6-4e52-ab4a-63d0e326e864 from stream default.b60744cd-5e9e-4633-befb-e60b7dfc7c72

2016-01-13 19:55:38,576 [8] INFO Aggregates.DurableSubscriber [(null)] - Processing event number 1152 id cc193fad-c4b7-463a-8c46-f2a8e4754d29 from stream default.b60744cd-5e9e-4633-befb-e60b7dfc7c72

2016-01-13 19:55:38,605 [8] INFO Aggregates.DurableSubscriber [(null)] - Processing event number 1153 id 35f9f62f-a544-4053-be97-935c630d6158 from stream default.b60744cd-5e9e-4633-befb-e60b7dfc7c72

2016-01-13 19:55:38,608 [8] INFO Aggregates.DurableSubscriber [(null)] - Processing event number 1154 id e0ad58ec-81d5-4b95-9b6b-ec1eff48edcd from stream default.b60744cd-5e9e-4633-befb-e60b7dfc7c72

2016-01-13 19:55:45,043 [8] INFO Aggregates.DurableSubscriber [(null)] - Processing event number 1171 id ef8c4764-05b0-4be5-9294-32c91ed02715 from stream default.b60744cd-5e9e-4633-befb-e60b7dfc7c72

2016-01-13 19:55:45,094 [102] INFO Aggregates.DurableSubscriber [(null)] - Processing event number 1173 id c882543e-1dbb-4bbd-a10c-bbb59817416d from stream default.b60744cd-5e9e-4633-befb-e60b7dfc7c72

2016-01-13 19:55:45,319 [8] INFO Aggregates.DurableSubscriber [(null)] - Processing event number 1172 id ae661882-0767-4c7d-829d-8de24d410e18 from stream default.b60744cd-5e9e-4633-befb-e60b7dfc7c72

2016-01-13 19:55:45,426 [102] INFO Aggregates.DurableSubscriber [(null)] - Processing event number 1174 id ca95cf4b-4d99-4304-9022-ed958d8d4e46 from stream default.b60744cd-5e9e-4633-befb-e60b7dfc7c72

2016-01-13 19:55:45,702 [8] INFO Aggregates.DurableSubscriber [(null)] - Processing event number 1173 id c882543e-1dbb-4bbd-a10c-bbb59817416d from stream default.b60744cd-5e9e-4633-befb-e60b7dfc7c72

2016-01-13 19:55:45,748 [102] INFO Aggregates.DurableSubscriber [(null)] - Processing event number 1175 id 7b3841bb-a55c-4ca4-80e9-790cacca1c6b from stream default.b60744cd-5e9e-4633-befb-e60b7dfc7c72

2016-01-13 19:55:45,988 [102] INFO Aggregates.DurableSubscriber [(null)] - Processing event number 1176 id 480924d3-219a-4f3b-ba41-c821b7d7b5df from stream default.b60744cd-5e9e-4633-befb-e60b7dfc7c72

2016-01-13 19:55:46,008 [8] INFO Aggregates.DurableSubscriber [(null)] - Processing event number 1174 id ca95cf4b-4d99-4304-9022-ed958d8d4e46 from stream default.b60744cd-5e9e-4633-befb-e60b7dfc7c72

2016-01-13 19:55:46,384 [102] INFO Aggregates.DurableSubscriber [(null)] - Processing event number 1177 id 7ec4c232-729f-4833-a04f-41bd893d04ba from stream default.b60744cd-5e9e-4633-befb-e60b7dfc7c72

2016-01-13 19:55:46,511 [8] INFO Aggregates.DurableSubscriber [(null)] - Processing event number 1175 id 7b3841bb-a55c-4ca4-80e9-790cacca1c6b from stream default.b60744cd-5e9e-4633-befb-e60b7dfc7c72

2016-01-13 19:55:46,648 [8] INFO Aggregates.DurableSubscriber [(null)] - Processing event number 1176 id 480924d3-219a-4f3b-ba41-c821b7d7b5df from stream default.b60744cd-5e9e-4633-befb-e60b7dfc7c72

2016-01-13 19:55:46,709 [102] INFO Aggregates.DurableSubscriber [(null)] - Processing event number 1178 id cc85004f-f369-4ec4-a787-c6d361e9c3fc from stream default.b60744cd-5e9e-4633-befb-e60b7dfc7c72

2016-01-13 19:55:47,138 [102] INFO Aggregates.DurableSubscriber [(null)] - Processing event number 1179 id 23f34d42-a92c-44ea-9710-acbebaeba847 from stream default.b60744cd-5e9e-4633-befb-e60b7dfc7c72

2016-01-13 19:55:47,138 [8] INFO Aggregates.DurableSubscriber [(null)] - Processing event number 1177 id 7ec4c232-729f-4833-a04f-41bd893d04ba from stream default.b60744cd-5e9e-4633-befb-e60b7dfc7c72

2016-01-13 19:55:47,415 [102] INFO Aggregates.DurableSubscriber [(null)] - Processing event number 1180 id 62877110-cbfc-4af8-ac95-3fb65476d1fe from stream default.b60744cd-5e9e-4633-befb-e60b7dfc7c72

2016-01-13 19:55:47,415 [85] ERROR Aggregates.Internal.NServiceBusDispatcher [(null)] - Error processing event Pulse.Domain.Network.Stash.Events.Tock__impl. Exception: System.Data.SqlClient.SqlException (0x80131904): Violation of PRIMARY KEY constraint ‘PK__Stash.Ti__3214EC07BA47D12E’. Cannot insert duplicate key in object ‘dbo.Stash.Tick’. The duplicate key value is (8541ef91-0930-422f-a7ca-15ef8c7cc55c).

2016-01-13 19:55:47,653 [8] INFO Aggregates.DurableSubscriber [(null)] - Processing event number 1178 id cc85004f-f369-4ec4-a787-c6d361e9c3fc from stream default.b60744cd-5e9e-4633-befb-e60b7dfc7c72

2016-01-13 19:55:47,727 [67] ERROR Aggregates.Internal.NServiceBusDispatcher [(null)] - Error processing event Pulse.Domain.Network.Stash.Events.Tock__impl. Exception: System.Data.SqlClient.SqlException (0x80131904): Violation of PRIMARY KEY constraint ‘PK__Stash.Ti__3214EC07BA47D12E’. Cannot insert duplicate key in object ‘dbo.Stash.Tick’. The duplicate key value is (41ef0294-9cf8-4173-a33c-b7fdfd9cef38).

2016-01-13 19:55:47,806 [102] INFO Aggregates.DurableSubscriber [(null)] - Processing event number 1181 id baa08d53-d9bb-4cfc-b975-31a410a91982 from stream default.b60744cd-5e9e-4633-befb-e60b7dfc7c72

2016-01-13 19:55:47,987 [85] ERROR Aggregates.Internal.NServiceBusDispatcher [(null)] - Error processing event Pulse.Domain.Network.Stash.Events.Tock__impl. Exception: System.Data.SqlClient.SqlException (0x80131904): Violation of PRIMARY KEY constraint ‘PK__Stash.Ti__3214EC07BA47D12E’. Cannot insert duplicate key in object ‘dbo.Stash.Tick’. The duplicate key value is (8541ef91-0930-422f-a7ca-15ef8c7cc55c).

2016-01-13 19:55:48,020 [80] ERROR Aggregates.Internal.NServiceBusDispatcher [(null)] - Error processing event Pulse.Domain.Network.Stash.Events.Tock__impl. Exception: System.Data.SqlClient.SqlException (0x80131904): Violation of PRIMARY KEY constraint ‘PK__Stash.Ti__3214EC07BA47D12E’. Cannot insert duplicate key in object ‘dbo.Stash.Tick’. The duplicate key value is (b84ff709-7d4d-4546-be19-d4fc2a80426b).

2016-01-13 19:55:48,021 [8] INFO Aggregates.DurableSubscriber [(null)] - Processing event number 1179 id 23f34d42-a92c-44ea-9710-acbebaeba847 from stream default.b60744cd-5e9e-4633-befb-e60b7dfc7c72

2016-01-13 19:55:48,022 [102] INFO Aggregates.DurableSubscriber [(null)] - Processing event number 1182 id febcf8b8-085a-438a-a6c9-724be04cc729 from stream default.b60744cd-5e9e-4633-befb-e60b7dfc7c72

2016-01-13 19:55:48,184 [67] ERROR Aggregates.Internal.NServiceBusDispatcher [(null)] - Error processing event Pulse.Domain.Network.Stash.Events.Tock__impl. Exception: System.Data.SqlClient.SqlException (0x80131904): Violation of PRIMARY KEY constraint ‘PK__Stash.Ti__3214EC07BA47D12E’. Cannot insert duplicate key in object ‘dbo.Stash.Tick’. The duplicate key value is (41ef0294-9cf8-4173-a33c-b7fdfd9cef38).

8

Ok! I finally managed to reproduce this with verbose event store logging on - I can’t attach the full log because its too big but check out this snippet. Event Id c0a211c7-94fd-4b3b-8465-aeeb5ca5d090 (highlighted) is processed twice, first time its processed the store gets disconnected immediately after, when it reconnects it skips a bunch of events but ends up re-processing this event.

If you’d like to see the full log I can send it via email

2016-01-14 00:24:00,803 [349] INFO Aggregates.DurableSubscriber [(null)] - Processing event number 2661 id c0a211c7-94fd-4b3b-8465-aeeb5ca5d090 from stream default.198329a7-c55f-4f95-98c9-4b9bb8e26cf0

2016-01-14 00:24:01,120 [102] INFO EventStore [(null)] - EventStoreConnection ‘ES-eab81e2a-1c32-4477-be2c-d3989217c24b’: enqueueing message EventStore.ClientAPI.Internal.HandleTcpPackageMessage…

2016-01-14 00:24:01,132 [59] INFO EventStore [(null)] - EventStoreConnection ‘ES-eab81e2a-1c32-4477-be2c-d3989217c24b’: HandleTcpPackage connId d181abc3-9737-4849-828b-e904d2a3d13e, package HeartbeatResponseCommand, d07e6c42-d09b-40ca-90e0-e6c156cf762c…

2016-01-14 00:24:01,937 [102] INFO EventStore [(null)] - EventStoreConnection ‘ES-eab81e2a-1c32-4477-be2c-d3989217c24b’: enqueueing message EventStore.ClientAPI.Internal.HandleTcpPackageMessage…

2016-01-14 00:24:01,989 [102] INFO EventStore [(null)] - EventStoreConnection ‘ES-eab81e2a-1c32-4477-be2c-d3989217c24b’: enqueueing message EventStore.ClientAPI.Internal.HandleTcpPackageMessage…

2016-01-14 00:24:02,183 [102] INFO EventStore [(null)] - EventStoreConnection ‘ES-eab81e2a-1c32-4477-be2c-d3989217c24b’: enqueueing message EventStore.ClientAPI.Internal.HandleTcpPackageMessage…

2016-01-14 00:24:03,219 [7] INFO EventStore [(null)] - EventStoreConnection ‘ES-eab81e2a-1c32-4477-be2c-d3989217c24b’: enqueueing message EventStore.ClientAPI.Internal.HandleTcpPackageMessage…

2016-01-14 00:24:03,219 [102] INFO EventStore [(null)] - ClientAPI TcpConnection closed [06:24:03.219: N127.0.0.1:3111, L127.0.0.1:13593, {d181abc3-9737-4849-828b-e904d2a3d13e}]:

Received bytes: 227510, Sent bytes: 1331

Send calls: 55, callbacks: 55

Receive calls: 160, callbacks: 160

Close reason: [Success] Socket closed

2016-01-14 00:24:03,263 [102] INFO EventStore [(null)] - TcpPackageConnection: connection [127.0.0.1:3111, L127.0.0.1:13593, {d181abc3-9737-4849-828b-e904d2a3d13e}] was closed cleanly.

2016-01-14 00:24:03,263 [102] INFO EventStore [(null)] - EventStoreConnection ‘ES-eab81e2a-1c32-4477-be2c-d3989217c24b’: enqueueing message EventStore.ClientAPI.Internal.TcpConnectionClosedMessage…

2016-01-14 00:24:03,259 [85] INFO EventStore [(null)] - EventStoreConnection ‘ES-eab81e2a-1c32-4477-be2c-d3989217c24b’: HandleTcpPackage connId d181abc3-9737-4849-828b-e904d2a3d13e, package StreamEventAppeared, 8d05b32a-2694-41a2-846c-ac3766c167b9…

2016-01-14 00:24:03,309 [85] INFO EventStore [(null)] - Subscription {8d05b32a-2694-41a2-846c-ac3766c167b9} to : event appeared (default.cf82c938-61ae-4d4f-8ebf-60ded92a9b9b, 1119, Pulse.Domain.Network.Stash.Events.Tock, Domain.Network.Messages, Version=0.1.0.0, Culture=neutral, PublicKeyToken=null @ 14141711/14141711).

2016-01-14 00:24:03,309 [85] INFO EventStore [(null)] - EventStoreConnection ‘ES-eab81e2a-1c32-4477-be2c-d3989217c24b’: HandleTcpPackage SUBSCRIPTION DECISION DoNothing (StreamEventAppeared), Subscription VolatileSubscriptionOperation (8d05b32a-2694-41a2-846c-ac3766c167b9): EventStore.ClientAPI.ClientOperations.VolatileSubscriptionOperation, is subscribed: True, retry count: 0, created: 06:23:21.078, last updated: 06:23:21.078.

2016-01-14 00:24:03,310 [85] INFO EventStore [(null)] - EventStoreConnection ‘ES-eab81e2a-1c32-4477-be2c-d3989217c24b’: HandleTcpPackage connId d181abc3-9737-4849-828b-e904d2a3d13e, package HeartbeatRequestCommand, 1e9f895a-42b6-4939-800c-daca4a0a90aa…

2016-01-14 00:24:03,310 [85] INFO EventStore [(null)] - EventStoreConnection ‘ES-eab81e2a-1c32-4477-be2c-d3989217c24b’: HandleTcpPackage connId d181abc3-9737-4849-828b-e904d2a3d13e, package StreamEventAppeared, 8d05b32a-2694-41a2-846c-ac3766c167b9…

2016-01-14 00:24:03,310 [85] INFO EventStore [(null)] - Subscription {8d05b32a-2694-41a2-846c-ac3766c167b9} to : event appeared (default.7812b014-d3df-4741-b0fd-6586c76cc01e, 1119, Pulse.Domain.Network.Stash.Events.Tock, Domain.Network.Messages, Version=0.1.0.0, Culture=neutral, PublicKeyToken=null @ 14142993/14142993).

2016-01-14 00:24:03,310 [85] INFO EventStore [(null)] - EventStoreConnection ‘ES-eab81e2a-1c32-4477-be2c-d3989217c24b’: HandleTcpPackage SUBSCRIPTION DECISION DoNothing (StreamEventAppeared), Subscription VolatileSubscriptionOperation (8d05b32a-2694-41a2-846c-ac3766c167b9): EventStore.ClientAPI.ClientOperations.VolatileSubscriptionOperation, is subscribed: True, retry count: 0, created: 06:23:21.078, last updated: 06:23:21.078.

2016-01-14 00:24:03,310 [85] INFO EventStore [(null)] - EventStoreConnection ‘ES-eab81e2a-1c32-4477-be2c-d3989217c24b’: HandleTcpPackage connId d181abc3-9737-4849-828b-e904d2a3d13e, package StreamEventAppeared, 8d05b32a-2694-41a2-846c-ac3766c167b9…

2016-01-14 00:24:03,310 [85] INFO EventStore [(null)] - Subscription {8d05b32a-2694-41a2-846c-ac3766c167b9} to : event appeared (default.29028c50-8b3a-4e5f-b8ee-814a25f8c8f8, 1119, Pulse.Domain.Network.Stash.Events.Tock, Domain.Network.Messages, Version=0.1.0.0, Culture=neutral, PublicKeyToken=null @ 14144277/14144277).

2016-01-14 00:24:03,311 [85] INFO EventStore [(null)] - EventStoreConnection ‘ES-eab81e2a-1c32-4477-be2c-d3989217c24b’: HandleTcpPackage SUBSCRIPTION DECISION DoNothing (StreamEventAppeared), Subscription VolatileSubscriptionOperation (8d05b32a-2694-41a2-846c-ac3766c167b9): EventStore.ClientAPI.ClientOperations.VolatileSubscriptionOperation, is subscribed: True, retry count: 0, created: 06:23:21.078, last updated: 06:23:21.078.

2016-01-14 00:24:03,311 [85] INFO EventStore [(null)] - EventStoreConnection ‘ES-eab81e2a-1c32-4477-be2c-d3989217c24b’: TCP connection to [127.0.0.1:3111, L127.0.0.1:13593, {d181abc3-9737-4849-828b-e904d2a3d13e}] closed…

2016-01-14 00:24:03,311 [85] INFO EventStore [(null)] - Subscription {8d05b32a-2694-41a2-846c-ac3766c167b9} to : closing subscription, reason: ConnectionClosed, exception: EventStore.ClientAPI.Exceptions.ConnectionClosedException: Connection was closed…

2016-01-14 00:24:03,311 [85] INFO EventStore [(null)] - Catch-up Subscription to : event appeared (default.cf82c938-61ae-4d4f-8ebf-60ded92a9b9b, 1119, Pulse.Domain.Network.Stash.Events.Tock, Domain.Network.Messages, Version=0.1.0.0, Culture=neutral, PublicKeyToken=null @ 14141711/14141711).

2016-01-14 00:24:03,311 [85] INFO EventStore [(null)] - Catch-up Subscription to : event appeared (default.7812b014-d3df-4741-b0fd-6586c76cc01e, 1119, Pulse.Domain.Network.Stash.Events.Tock, Domain.Network.Messages, Version=0.1.0.0, Culture=neutral, PublicKeyToken=null @ 14142993/14142993).

2016-01-14 00:24:03,311 [85] INFO EventStore [(null)] - Catch-up Subscription to : event appeared (default.29028c50-8b3a-4e5f-b8ee-814a25f8c8f8, 1119, Pulse.Domain.Network.Stash.Events.Tock, Domain.Network.Messages, Version=0.1.0.0, Culture=neutral, PublicKeyToken=null @ 14144277/14144277).

2016-01-14 00:24:04,979 [62] INFO EventStore [(null)] - EventStoreConnection ‘ES-eab81e2a-1c32-4477-be2c-d3989217c24b’: TimerTick checking reconnection…

2016-01-14 00:24:04,979 [62] INFO EventStore [(null)] - EventStoreConnection ‘ES-eab81e2a-1c32-4477-be2c-d3989217c24b’: DiscoverEndPoint.

2016-01-14 00:24:04,979 [62] INFO EventStore [(null)] - EventStoreConnection ‘ES-eab81e2a-1c32-4477-be2c-d3989217c24b’: enqueueing message EventStore.ClientAPI.Internal.EstablishTcpConnectionMessage…

2016-01-14 00:24:05,159 [62] INFO EventStore [(null)] - EventStoreConnection ‘ES-eab81e2a-1c32-4477-be2c-d3989217c24b’: EstablishTcpConnection to [127.0.0.1:3111].

2016-01-14 00:24:05,160 [62] INFO EventStore [(null)] - TcpPackageConnection: connected to [127.0.0.1:3111, L127.0.0.1:13612, {0ff5f906-3932-4f69-ba7e-a12b8736b498}].

2016-01-14 00:24:05,161 [62] INFO EventStore [(null)] - EventStoreConnection ‘ES-eab81e2a-1c32-4477-be2c-d3989217c24b’: enqueueing message EventStore.ClientAPI.Internal.TcpConnectionEstablishedMessage…

2016-01-14 00:24:05,162 [62] INFO EventStore [(null)] - EventStoreConnection ‘ES-eab81e2a-1c32-4477-be2c-d3989217c24b’: TCP connection to [127.0.0.1:3111, L127.0.0.1:13612, {0ff5f906-3932-4f69-ba7e-a12b8736b498}] established…

2016-01-14 00:24:05,163 [102] INFO EventStore [(null)] - EventStoreConnection ‘ES-eab81e2a-1c32-4477-be2c-d3989217c24b’: enqueueing message EventStore.ClientAPI.Internal.HandleTcpPackageMessage…

2016-01-14 00:24:05,168 [44] INFO EventStore [(null)] - EventStoreConnection ‘ES-eab81e2a-1c32-4477-be2c-d3989217c24b’: HandleTcpPackage connId 0ff5f906-3932-4f69-ba7e-a12b8736b498, package Authenticated, 1ec73652-1c1a-43f2-be68-9445b23f701d…

2016-01-14 00:24:05,169 [44] INFO EventStore [(null)] - <log4net.Error>Exception during StringFormat: Index (zero based) must be greater than or equal to zero and less than the size of the argument list. Catch-up Subscription to {0}: recovering after reconnection.{}</log4net.Error>

2016-01-14 00:24:05,646 [44] INFO EventStore [(null)] - <log4net.Error>Exception during StringFormat: Index (zero based) must be greater than or equal to zero and less than the size of the argument list. Catch-up Subscription to {0}: unhooking from connection.Connected.{}</log4net.Error>

2016-01-14 00:24:05,903 [44] INFO EventStore [(null)] - Catch-up Subscription to : running…

2016-01-14 00:24:05,905 [44] INFO EventStore [(null)] - Catch-up Subscription to : pulling events…

2016-01-14 00:24:05,905 [44] INFO EventStore [(null)] - EventStoreConnection ‘ES-eab81e2a-1c32-4477-be2c-d3989217c24b’: enqueueing message EventStore.ClientAPI.Internal.StartOperationMessage…

2016-01-14 00:24:05,908 [57] INFO EventStore [(null)] - EventStoreConnection ‘ES-eab81e2a-1c32-4477-be2c-d3989217c24b’: StartOperation schedule ReadAllEventsForwardOperation, Position: 13984756/13984756, MaxCount: 500, ResolveLinkTos: False, RequireMaster: True, 10, 00:00:07…

2016-01-14 00:24:05,909 [57] INFO EventStore [(null)] - EventStoreConnection ‘ES-eab81e2a-1c32-4477-be2c-d3989217c24b’: ScheduleOperation package ReadAllEventsForward, 20723b39-1bc7-4e45-973a-8c43c1e44f89, Operation ReadAllEventsForwardOperation (20723b39-1bc7-4e45-973a-8c43c1e44f89): Position: 13984756/13984756, MaxCount: 500, ResolveLinkTos: False, RequireMaster: True, retry count: 0, created: 06:24:05.909, last updated: 06:24:05.909…

2016-01-14 00:24:06,014 [39] INFO EventStore [(null)] - EventStoreConnection ‘ES-eab81e2a-1c32-4477-be2c-d3989217c24b’: enqueueing message EventStore.ClientAPI.Internal.HandleTcpPackageMessage…

2016-01-14 00:24:06,026 [57] INFO EventStore [(null)] - EventStoreConnection ‘ES-eab81e2a-1c32-4477-be2c-d3989217c24b’: HandleTcpPackage connId 0ff5f906-3932-4f69-ba7e-a12b8736b498, package ReadAllEventsForwardCompleted, 20723b39-1bc7-4e45-973a-8c43c1e44f89…

2016-01-14 00:24:06,027 [44] INFO EventStore [(null)] - Catch-up Subscription to : skipping event (default.cf82c938-61ae-4d4f-8ebf-60ded92a9b9b, 1111, Pulse.Domain.Network.Stash.Events.Tock, Domain.Network.Messages, Version=0.1.0.0, Culture=neutral, PublicKeyToken=null @ 13984896/13984896).

2016-01-14 00:24:06,027 [44] INFO EventStore [(null)] - Catch-up Subscription to : skipping event (default.7812b014-d3df-4741-b0fd-6586c76cc01e, 1111, Pulse.Domain.Network.Stash.Events.Tock, Domain.Network.Messages, Version=0.1.0.0, Culture=neutral, PublicKeyToken=null @ 13986179/13986179).

2016-01-14 00:24:06,028 [44] INFO EventStore [(null)] - Catch-up Subscription to : skipping event (default.4e890d87-5ece-4dbb-9708-9ad5237dd5d0, 1118, Pulse.Domain.Network.Stash.Events.Tock, Domain.Network.Messages, Version=0.1.0.0, Culture=neutral, PublicKeyToken=null @ 13987464/13987464).

2016-01-14 00:24:06,028 [44] INFO EventStore [(null)] - Catch-up Subscription to : skipping event (default.4e890d87-5ece-4dbb-9708-9ad5237dd5d0, 1119, Pulse.Domain.Network.Stash.Events.Tock, Domain.Network.Messages, Version=0.1.0.0, Culture=neutral, PublicKeyToken=null @ 13988760/13988760).

2016-01-14 00:24:06,028 [44] INFO EventStore [(null)] - Catch-up Subscription to : skipping event (default.29028c50-8b3a-4e5f-b8ee-814a25f8c8f8, 1111, Pulse.Domain.Network.Stash.Events.Tock, Domain.Network.Messages, Version=0.1.0.0, Culture=neutral, PublicKeyToken=null @ 13990058/13990058).

2016-01-14 00:24:06,028 [44] INFO EventStore [(null)] - Catch-up Subscription to : skipping event (default.198329a7-c55f-4f95-98c9-4b9bb8e26cf0, 2613, Pulse.Domain.Network.Stash.Events.Tock, Domain.Network.Messages, Version=0.1.0.0, Culture=neutral, PublicKeyToken=null @ 13991650/13991650).

2016-01-14 00:24:06,028 [44] INFO EventStore [(null)] - Catch-up Subscription to : skipping event (default.198329a7-c55f-4f95-98c9-4b9bb8e26cf0, 2614, Pulse.Domain.Network.Stash.Events.Tock, Domain.Network.Messages, Version=0.1.0.0, Culture=neutral, PublicKeyToken=null @ 13992958/13992958).

2016-01-14 00:24:06,028 [44] INFO EventStore [(null)] - Catch-up Subscription to : skipping event (default.198329a7-c55f-4f95-98c9-4b9bb8e26cf0, 2615, Pulse.Domain.Network.Stash.Events.Tock, Domain.Network.Messages, Version=0.1.0.0, Culture=neutral, PublicKeyToken=null @ 13994268/13994268).

2016-01-14 00:24:06,029 [44] INFO EventStore [(null)] - Catch-up Subscription to : skipping event (default.198329a7-c55f-4f95-98c9-4b9bb8e26cf0.snapshots, 523, Pulse.Domain.Network.Stash.Memento, Domain.Network.Aggregates, Version=0.1.0.0, Culture=neutral, PublicKeyToken=null @ 13995438/13995438).

2016-01-14 00:24:06,029 [44] INFO EventStore [(null)] - Catch-up Subscription to : skipping event (default.198329a7-c55f-4f95-98c9-4b9bb8e26cf0, 2616, Pulse.Domain.Network.Stash.Events.Tock, Domain.Network.Messages, Version=0.1.0.0, Culture=neutral, PublicKeyToken=null @ 13996393/13996393).

2016-01-14 00:24:06,029 [44] INFO EventStore [(null)] - Catch-up Subscription to : skipping event (default.198329a7-c55f-4f95-98c9-4b9bb8e26cf0, 2617, Pulse.Domain.Network.Stash.Events.Tock, Domain.Network.Messages, Version=0.1.0.0, Culture=neutral, PublicKeyToken=null @ 13997702/13997702).

2016-01-14 00:24:06,029 [44] INFO EventStore [(null)] - Catch-up Subscription to : skipping event (default.198329a7-c55f-4f95-98c9-4b9bb8e26cf0, 2618, Pulse.Domain.Network.Stash.Events.Tock, Domain.Network.Messages, Version=0.1.0.0, Culture=neutral, PublicKeyToken=null @ 13999013/13999013).

2016-01-14 00:24:06,029 [44] INFO EventStore [(null)] - Catch-up Subscription to : skipping event (default.198329a7-c55f-4f95-98c9-4b9bb8e26cf0, 2619, Pulse.Domain.Network.Stash.Events.Tock, Domain.Network.Messages, Version=0.1.0.0, Culture=neutral, PublicKeyToken=null @ 14000324/14000324).

2016-01-14 00:24:06,029 [44] INFO EventStore [(null)] - Catch-up Subscription to : skipping event (default.198329a7-c55f-4f95-98c9-4b9bb8e26cf0, 2620, Pulse.Domain.Network.Stash.Events.Tock, Domain.Network.Messages, Version=0.1.0.0, Culture=neutral, PublicKeyToken=null @ 14001635/14001635).

2016-01-14 00:24:06,029 [44] INFO EventStore [(null)] - Catch-up Subscription to : skipping event (default.198329a7-c55f-4f95-98c9-4b9bb8e26cf0.snapshots, 524, Pulse.Domain.Network.Stash.Memento, Domain.Network.Aggregates, Version=0.1.0.0, Culture=neutral, PublicKeyToken=null @ 14002806/14002806).

2016-01-14 00:24:06,029 [44] INFO EventStore [(null)] - Catch-up Subscription to : skipping event (default.198329a7-c55f-4f95-98c9-4b9bb8e26cf0, 2621, Pulse.Domain.Network.Stash.Events.Tock, Domain.Network.Messages, Version=0.1.0.0, Culture=neutral, PublicKeyToken=null @ 14003761/14003761).

2016-01-14 00:24:06,030 [44] INFO EventStore [(null)] - Catch-up Subscription to : skipping event (default.198329a7-c55f-4f95-98c9-4b9bb8e26cf0, 2622, Pulse.Domain.Network.Stash.Events.Tock, Domain.Network.Messages, Version=0.1.0.0, Culture=neutral, PublicKeyToken=null @ 14005071/14005071).

2016-01-14 00:24:06,030 [44] INFO EventStore [(null)] - Catch-up Subscription to : skipping event (default.198329a7-c55f-4f95-98c9-4b9bb8e26cf0, 2623, Pulse.Domain.Network.Stash.Events.Tock, Domain.Network.Messages, Version=0.1.0.0, Culture=neutral, PublicKeyToken=null @ 14006381/14006381).

2016-01-14 00:24:06,030 [44] INFO EventStore [(null)] - Catch-up Subscription to : skipping event (default.198329a7-c55f-4f95-98c9-4b9bb8e26cf0, 2624, Pulse.Domain.Network.Stash.Events.Tock, Domain.Network.Messages, Version=0.1.0.0, Culture=neutral, PublicKeyToken=null @ 14007692/14007692).

2016-01-14 00:24:06,030 [44] INFO EventStore [(null)] - Catch-up Subscription to : skipping event (default.198329a7-c55f-4f95-98c9-4b9bb8e26cf0, 2625, Pulse.Domain.Network.Stash.Events.Tock, Domain.Network.Messages, Version=0.1.0.0, Culture=neutral, PublicKeyToken=null @ 14009001/14009001).

2016-01-14 00:24:06,030 [44] INFO EventStore [(null)] - Catch-up Subscription to : skipping event (default.198329a7-c55f-4f95-98c9-4b9bb8e26cf0.snapshots, 525, Pulse.Domain.Network.Stash.Memento, Domain.Network.Aggregates, Version=0.1.0.0, Culture=neutral, PublicKeyToken=null @ 14010171/14010171).

2016-01-14 00:24:06,030 [44] INFO EventStore [(null)] - Catch-up Subscription to : skipping event (default.198329a7-c55f-4f95-98c9-4b9bb8e26cf0, 2626, Pulse.Domain.Network.Stash.Events.Tock, Domain.Network.Messages, Version=0.1.0.0, Culture=neutral, PublicKeyToken=null @ 14011126/14011126).

2016-01-14 00:24:06,030 [44] INFO EventStore [(null)] - Catch-up Subscription to : skipping event (default.198329a7-c55f-4f95-98c9-4b9bb8e26cf0, 2627, Pulse.Domain.Network.Stash.Events.Tock, Domain.Network.Messages, Version=0.1.0.0, Culture=neutral, PublicKeyToken=null @ 14012436/14012436).

2016-01-14 00:24:06,031 [44] INFO EventStore [(null)] - Catch-up Subscription to : skipping event (default.198329a7-c55f-4f95-98c9-4b9bb8e26cf0, 2628, Pulse.Domain.Network.Stash.Events.Tock, Domain.Network.Messages, Version=0.1.0.0, Culture=neutral, PublicKeyToken=null @ 14013752/14013752).

2016-01-14 00:24:06,031 [44] INFO EventStore [(null)] - Catch-up Subscription to : skipping event (default.cf82c938-61ae-4d4f-8ebf-60ded92a9b9b, 1112, Pulse.Domain.Network.Stash.Events.Tock, Domain.Network.Messages, Version=0.1.0.0, Culture=neutral, PublicKeyToken=null @ 14015067/14015067).

2016-01-14 00:24:06,031 [44] INFO EventStore [(null)] - Catch-up Subscription to : skipping event (default.7812b014-d3df-4741-b0fd-6586c76cc01e, 1112, Pulse.Domain.Network.Stash.Events.Tock, Domain.Network.Messages, Version=0.1.0.0, Culture=neutral, PublicKeyToken=null @ 14016350/14016350).

2016-01-14 00:24:06,031 [44] INFO EventStore [(null)] - Catch-up Subscription to : skipping event (default.29028c50-8b3a-4e5f-b8ee-814a25f8c8f8, 1112, Pulse.Domain.Network.Stash.Events.Tock, Domain.Network.Messages, Version=0.1.0.0, Culture=neutral, PublicKeyToken=null @ 14017635/14017635).

2016-01-14 00:24:06,031 [44] INFO EventStore [(null)] - Catch-up Subscription to : skipping event (default.198329a7-c55f-4f95-98c9-4b9bb8e26cf0, 2629, Pulse.Domain.Network.Stash.Events.Tock, Domain.Network.Messages, Version=0.1.0.0, Culture=neutral, PublicKeyToken=null @ 14019229/14019229).

2016-01-14 00:24:06,031 [44] INFO EventStore [(null)] - Catch-up Subscription to : skipping event (default.198329a7-c55f-4f95-98c9-4b9bb8e26cf0, 2630, Pulse.Domain.Network.Stash.Events.Tock, Domain.Network.Messages, Version=0.1.0.0, Culture=neutral, PublicKeyToken=null @ 14020538/14020538).

2016-01-14 00:24:06,031 [44] INFO EventStore [(null)] - Catch-up Subscription to : skipping event (default.198329a7-c55f-4f95-98c9-4b9bb8e26cf0.snapshots, 526, Pulse.Domain.Network.Stash.Memento, Domain.Network.Aggregates, Version=0.1.0.0, Culture=neutral, PublicKeyToken=null @ 14021708/14021708).

2016-01-14 00:24:06,032 [44] INFO EventStore [(null)] - Catch-up Subscription to : skipping event (default.198329a7-c55f-4f95-98c9-4b9bb8e26cf0, 2631, Pulse.Domain.Network.Stash.Events.Tock, Domain.Network.Messages, Version=0.1.0.0, Culture=neutral, PublicKeyToken=null @ 14022663/14022663).

2016-01-14 00:24:06,032 [44] INFO EventStore [(null)] - Catch-up Subscription to : skipping event (default.198329a7-c55f-4f95-98c9-4b9bb8e26cf0, 2632, Pulse.Domain.Network.Stash.Events.Tock, Domain.Network.Messages, Version=0.1.0.0, Culture=neutral, PublicKeyToken=null @ 14023974/14023974).

2016-01-14 00:24:06,032 [44] INFO EventStore [(null)] - Catch-up Subscription to : skipping event (default.198329a7-c55f-4f95-98c9-4b9bb8e26cf0, 2633, Pulse.Domain.Network.Stash.Events.Tock, Domain.Network.Messages, Version=0.1.0.0, Culture=neutral, PublicKeyToken=null @ 14025285/14025285).

2016-01-14 00:24:06,032 [44] INFO EventStore [(null)] - Catch-up Subscription to : skipping event (default.198329a7-c55f-4f95-98c9-4b9bb8e26cf0, 2634, Pulse.Domain.Network.Stash.Events.Tock, Domain.Network.Messages, Version=0.1.0.0, Culture=neutral, PublicKeyToken=null @ 14026596/14026596).

2016-01-14 00:24:06,032 [44] INFO EventStore [(null)] - Catch-up Subscription to : skipping event (default.198329a7-c55f-4f95-98c9-4b9bb8e26cf0, 2635, Pulse.Domain.Network.Stash.Events.Tock, Domain.Network.Messages, Version=0.1.0.0, Culture=neutral, PublicKeyToken=null @ 14027906/14027906).

2016-01-14 00:24:06,032 [44] INFO EventStore [(null)] - Catch-up Subscription to : skipping event (default.198329a7-c55f-4f95-98c9-4b9bb8e26cf0.snapshots, 527, Pulse.Domain.Network.Stash.Memento, Domain.Network.Aggregates, Version=0.1.0.0, Culture=neutral, PublicKeyToken=null @ 14029076/14029076).

2016-01-14 00:24:06,033 [44] INFO EventStore [(null)] - Catch-up Subscription to : skipping event (default.198329a7-c55f-4f95-98c9-4b9bb8e26cf0, 2636, Pulse.Domain.Network.Stash.Events.Tock, Domain.Network.Messages, Version=0.1.0.0, Culture=neutral, PublicKeyToken=null @ 14030031/14030031).

2016-01-14 00:24:06,033 [44] INFO EventStore [(null)] - Catch-up Subscription to : skipping event (default.198329a7-c55f-4f95-98c9-4b9bb8e26cf0, 2637, Pulse.Domain.Network.Stash.Events.Tock, Domain.Network.Messages, Version=0.1.0.0, Culture=neutral, PublicKeyToken=null @ 14031341/14031341).

2016-01-14 00:24:06,033 [44] INFO EventStore [(null)] - Catch-up Subscription to : skipping event (default.198329a7-c55f-4f95-98c9-4b9bb8e26cf0, 2638, Pulse.Domain.Network.Stash.Events.Tock, Domain.Network.Messages, Version=0.1.0.0, Culture=neutral, PublicKeyToken=null @ 14032650/14032650).

2016-01-14 00:24:06,034 [44] INFO EventStore [(null)] - Catch-up Subscription to : skipping event (default.198329a7-c55f-4f95-98c9-4b9bb8e26cf0, 2639, Pulse.Domain.Network.Stash.Events.Tock, Domain.Network.Messages, Version=0.1.0.0, Culture=neutral, PublicKeyToken=null @ 14033960/14033960).

2016-01-14 00:24:06,034 [44] INFO EventStore [(null)] - Catch-up Subscription to : skipping event (default.198329a7-c55f-4f95-98c9-4b9bb8e26cf0, 2640, Pulse.Domain.Network.Stash.Events.Tock, Domain.Network.Messages, Version=0.1.0.0, Culture=neutral, PublicKeyToken=null @ 14035270/14035270).

2016-01-14 00:24:06,034 [44] INFO EventStore [(null)] - Catch-up Subscription to : skipping event (default.198329a7-c55f-4f95-98c9-4b9bb8e26cf0.snapshots, 528, Pulse.Domain.Network.Stash.Memento, Domain.Network.Aggregates, Version=0.1.0.0, Culture=neutral, PublicKeyToken=null @ 14036439/14036439).

2016-01-14 00:24:06,035 [44] INFO EventStore [(null)] - Catch-up Subscription to : skipping event (default.198329a7-c55f-4f95-98c9-4b9bb8e26cf0, 2641, Pulse.Domain.Network.Stash.Events.Tock, Domain.Network.Messages, Version=0.1.0.0, Culture=neutral, PublicKeyToken=null @ 14037394/14037394).

2016-01-14 00:24:06,035 [44] INFO EventStore [(null)] - Catch-up Subscription to : skipping event (default.198329a7-c55f-4f95-98c9-4b9bb8e26cf0, 2642, Pulse.Domain.Network.Stash.Events.Tock, Domain.Network.Messages, Version=0.1.0.0, Culture=neutral, PublicKeyToken=null @ 14038704/14038704).

2016-01-14 00:24:06,036 [44] INFO EventStore [(null)] - Catch-up Subscription to : skipping event (default.198329a7-c55f-4f95-98c9-4b9bb8e26cf0, 2643, Pulse.Domain.Network.Stash.Events.Tock, Domain.Network.Messages, Version=0.1.0.0, Culture=neutral, PublicKeyToken=null @ 14040014/14040014).

2016-01-14 00:24:06,036 [44] INFO EventStore [(null)] - Catch-up Subscription to : skipping event (default.198329a7-c55f-4f95-98c9-4b9bb8e26cf0, 2644, Pulse.Domain.Network.Stash.Events.Tock, Domain.Network.Messages, Version=0.1.0.0, Culture=neutral, PublicKeyToken=null @ 14041322/14041322).

2016-01-14 00:24:06,036 [44] INFO EventStore [(null)] - Catch-up Subscription to : skipping event (default.198329a7-c55f-4f95-98c9-4b9bb8e26cf0, 2645, Pulse.Domain.Network.Stash.Events.Tock, Domain.Network.Messages, Version=0.1.0.0, Culture=neutral, PublicKeyToken=null @ 14042631/14042631).

2016-01-14 00:24:06,036 [44] INFO EventStore [(null)] - Catch-up Subscription to : skipping event (default.198329a7-c55f-4f95-98c9-4b9bb8e26cf0.snapshots, 529, Pulse.Domain.Network.Stash.Memento, Domain.Network.Aggregates, Version=0.1.0.0, Culture=neutral, PublicKeyToken=null @ 14043800/14043800).

2016-01-14 00:24:06,036 [44] INFO EventStore [(null)] - Catch-up Subscription to : skipping event (default.198329a7-c55f-4f95-98c9-4b9bb8e26cf0, 2646, Pulse.Domain.Network.Stash.Events.Tock, Domain.Network.Messages, Version=0.1.0.0, Culture=neutral, PublicKeyToken=null @ 14044755/14044755).

2016-01-14 00:24:06,037 [44] INFO EventStore [(null)] - Catch-up Subscription to : skipping event (default.198329a7-c55f-4f95-98c9-4b9bb8e26cf0, 2647, Pulse.Domain.Network.Stash.Events.Tock, Domain.Network.Messages, Version=0.1.0.0, Culture=neutral, PublicKeyToken=null @ 14046064/14046064).

2016-01-14 00:24:06,037 [44] INFO EventStore [(null)] - Catch-up Subscription to : skipping event (default.198329a7-c55f-4f95-98c9-4b9bb8e26cf0, 2648, Pulse.Domain.Network.Stash.Events.Tock, Domain.Network.Messages, Version=0.1.0.0, Culture=neutral, PublicKeyToken=null @ 14047374/14047374).

2016-01-14 00:24:06,037 [44] INFO EventStore [(null)] - Catch-up Subscription to : skipping event (default.198329a7-c55f-4f95-98c9-4b9bb8e26cf0, 2649, Pulse.Domain.Network.Stash.Events.Tock, Domain.Network.Messages, Version=0.1.0.0, Culture=neutral, PublicKeyToken=null @ 14048685/14048685).

2016-01-14 00:24:06,044 [44] INFO EventStore [(null)] - Catch-up Subscription to : skipping event (default.198329a7-c55f-4f95-98c9-4b9bb8e26cf0, 2650, Pulse.Domain.Network.Stash.Events.Tock, Domain.Network.Messages, Version=0.1.0.0, Culture=neutral, PublicKeyToken=null @ 14049994/14049994).

2016-01-14 00:24:06,044 [44] INFO EventStore [(null)] - Catch-up Subscription to : skipping event (default.198329a7-c55f-4f95-98c9-4b9bb8e26cf0.snapshots, 530, Pulse.Domain.Network.Stash.Memento, Domain.Network.Aggregates, Version=0.1.0.0, Culture=neutral, PublicKeyToken=null @ 14051164/14051164).

2016-01-14 00:24:06,044 [44] INFO EventStore [(null)] - Catch-up Subscription to : skipping event (default.198329a7-c55f-4f95-98c9-4b9bb8e26cf0, 2651, Pulse.Domain.Network.Stash.Events.Tock, Domain.Network.Messages, Version=0.1.0.0, Culture=neutral, PublicKeyToken=null @ 14052119/14052119).

2016-01-14 00:24:06,045 [44] INFO EventStore [(null)] - Catch-up Subscription to : skipping event (default.198329a7-c55f-4f95-98c9-4b9bb8e26cf0, 2652, Pulse.Domain.Network.Stash.Events.Tock, Domain.Network.Messages, Version=0.1.0.0, Culture=neutral, PublicKeyToken=null @ 14053429/14053429).

2016-01-14 00:24:06,045 [44] INFO EventStore [(null)] - Catch-up Subscription to : skipping event (default.cf82c938-61ae-4d4f-8ebf-60ded92a9b9b, 1113, Pulse.Domain.Network.Stash.Events.Tock, Domain.Network.Messages, Version=0.1.0.0, Culture=neutral, PublicKeyToken=null @ 14054737/14054737).

2016-01-14 00:24:06,045 [44] INFO EventStore [(null)] - Catch-up Subscription to : skipping event (default.7812b014-d3df-4741-b0fd-6586c76cc01e, 1113, Pulse.Domain.Network.Stash.Events.Tock, Domain.Network.Messages, Version=0.1.0.0, Culture=neutral, PublicKeyToken=null @ 14056020/14056020).

2016-01-14 00:24:06,045 [44] INFO EventStore [(null)] - Catch-up Subscription to : skipping event (default.29028c50-8b3a-4e5f-b8ee-814a25f8c8f8, 1113, Pulse.Domain.Network.Stash.Events.Tock, Domain.Network.Messages, Version=0.1.0.0, Culture=neutral, PublicKeyToken=null @ 14057305/14057305).

2016-01-14 00:24:06,045 [44] INFO EventStore [(null)] - Catch-up Subscription to : skipping event (default.198329a7-c55f-4f95-98c9-4b9bb8e26cf0, 2653, Pulse.Domain.Network.Stash.Events.Tock, Domain.Network.Messages, Version=0.1.0.0, Culture=neutral, PublicKeyToken=null @ 14058903/14058903).

2016-01-14 00:24:06,045 [44] INFO EventStore [(null)] - Catch-up Subscription to : skipping event (default.198329a7-c55f-4f95-98c9-4b9bb8e26cf0, 2654, Pulse.Domain.Network.Stash.Events.Tock, Domain.Network.Messages, Version=0.1.0.0, Culture=neutral, PublicKeyToken=null @ 14060219/14060219).

2016-01-14 00:24:06,045 [44] INFO EventStore [(null)] - Catch-up Subscription to : skipping event (default.198329a7-c55f-4f95-98c9-4b9bb8e26cf0, 2655, Pulse.Domain.Network.Stash.Events.Tock, Domain.Network.Messages, Version=0.1.0.0, Culture=neutral, PublicKeyToken=null @ 14061535/14061535).

2016-01-14 00:24:06,045 [44] INFO EventStore [(null)] - Catch-up Subscription to : skipping event (default.198329a7-c55f-4f95-98c9-4b9bb8e26cf0.snapshots, 531, Pulse.Domain.Network.Stash.Memento, Domain.Network.Aggregates, Version=0.1.0.0, Culture=neutral, PublicKeyToken=null @ 14062704/14062704).

2016-01-14 00:24:06,045 [44] INFO EventStore [(null)] - Catch-up Subscription to : skipping event (default.198329a7-c55f-4f95-98c9-4b9bb8e26cf0, 2656, Pulse.Domain.Network.Stash.Events.Tock, Domain.Network.Messages, Version=0.1.0.0, Culture=neutral, PublicKeyToken=null @ 14063659/14063659).

2016-01-14 00:24:06,046 [44] INFO EventStore [(null)] - Catch-up Subscription to : skipping event (default.cf82c938-61ae-4d4f-8ebf-60ded92a9b9b, 1114, Pulse.Domain.Network.Stash.Events.Tock, Domain.Network.Messages, Version=0.1.0.0, Culture=neutral, PublicKeyToken=null @ 14064970/14064970).

2016-01-14 00:24:06,046 [44] INFO EventStore [(null)] - Catch-up Subscription to : skipping event (default.7812b014-d3df-4741-b0fd-6586c76cc01e, 1114, Pulse.Domain.Network.Stash.Events.Tock, Domain.Network.Messages, Version=0.1.0.0, Culture=neutral, PublicKeyToken=null @ 14066253/14066253).

2016-01-14 00:24:06,046 [44] INFO EventStore [(null)] - Catch-up Subscription to : skipping event (default.4e890d87-5ece-4dbb-9708-9ad5237dd5d0, 1120, Pulse.Domain.Network.Stash.Events.Tock, Domain.Network.Messages, Version=0.1.0.0, Culture=neutral, PublicKeyToken=null @ 14067538/14067538).

2016-01-14 00:24:06,046 [44] INFO EventStore [(null)] - Catch-up Subscription to : skipping event (default.4e890d87-5ece-4dbb-9708-9ad5237dd5d0.snapshots, 224, Pulse.Domain.Network.Stash.Memento, Domain.Network.Aggregates, Version=0.1.0.0, Culture=neutral, PublicKeyToken=null @ 14068694/14068694).

2016-01-14 00:24:06,046 [44] INFO EventStore [(null)] - Catch-up Subscription to : skipping event (default.29028c50-8b3a-4e5f-b8ee-814a25f8c8f8, 1114, Pulse.Domain.Network.Stash.Events.Tock, Domain.Network.Messages, Version=0.1.0.0, Culture=neutral, PublicKeyToken=null @ 14069649/14069649).

2016-01-14 00:24:06,046 [44] INFO EventStore [(null)] - Catch-up Subscription to : skipping event (default.198329a7-c55f-4f95-98c9-4b9bb8e26cf0, 2657, Pulse.Domain.Network.Stash.Events.Tock, Domain.Network.Messages, Version=0.1.0.0, Culture=neutral, PublicKeyToken=null @ 14071245/14071245).

2016-01-14 00:24:06,046 [44] INFO EventStore [(null)] - Catch-up Subscription to : skipping event (default.198329a7-c55f-4f95-98c9-4b9bb8e26cf0, 2658, Pulse.Domain.Network.Stash.Events.Tock, Domain.Network.Messages, Version=0.1.0.0, Culture=neutral, PublicKeyToken=null @ 14072554/14072554).

2016-01-14 00:24:06,046 [44] INFO EventStore [(null)] - Catch-up Subscription to : skipping event (default.cf82c938-61ae-4d4f-8ebf-60ded92a9b9b, 1115, Pulse.Domain.Network.Stash.Events.Tock, Domain.Network.Messages, Version=0.1.0.0, Culture=neutral, PublicKeyToken=null @ 14073865/14073865).

2016-01-14 00:24:06,047 [44] INFO EventStore [(null)] - Catch-up Subscription to : skipping event (default.cf82c938-61ae-4d4f-8ebf-60ded92a9b9b.snapshots, 223, Pulse.Domain.Network.Stash.Memento, Domain.Network.Aggregates, Version=0.1.0.0, Culture=neutral, PublicKeyToken=null @ 14075008/14075008).

2016-01-14 00:24:06,047 [44] INFO EventStore [(null)] - Catch-up Subscription to : skipping event (default.7812b014-d3df-4741-b0fd-6586c76cc01e, 1115, Pulse.Domain.Network.Stash.Events.Tock, Domain.Network.Messages, Version=0.1.0.0, Culture=neutral, PublicKeyToken=null @ 14075963/14075963).

2016-01-14 00:24:06,047 [44] INFO EventStore [(null)] - Catch-up Subscription to : skipping event (default.7812b014-d3df-4741-b0fd-6586c76cc01e.snapshots, 223, Pulse.Domain.Network.Stash.Memento, Domain.Network.Aggregates, Version=0.1.0.0, Culture=neutral, PublicKeyToken=null @ 14077108/14077108).

2016-01-14 00:24:06,047 [44] INFO EventStore [(null)] - Catch-up Subscription to : skipping event (default.4e890d87-5ece-4dbb-9708-9ad5237dd5d0, 1121, Pulse.Domain.Network.Stash.Events.Tock, Domain.Network.Messages, Version=0.1.0.0, Culture=neutral, PublicKeyToken=null @ 14078063/14078063).

2016-01-14 00:24:06,047 [44] INFO EventStore [(null)] - Catch-up Subscription to : skipping event (default.4e890d87-5ece-4dbb-9708-9ad5237dd5d0, 1122, Pulse.Domain.Network.Stash.Events.Tock, Domain.Network.Messages, Version=0.1.0.0, Culture=neutral, PublicKeyToken=null @ 14079360/14079360).

2016-01-14 00:24:06,047 [44] INFO EventStore [(null)] - Catch-up Subscription to : skipping event (default.29028c50-8b3a-4e5f-b8ee-814a25f8c8f8, 1115, Pulse.Domain.Network.Stash.Events.Tock, Domain.Network.Messages, Version=0.1.0.0, Culture=neutral, PublicKeyToken=null @ 14080656/14080656).

2016-01-14 00:24:06,047 [44] INFO EventStore [(null)] - Catch-up Subscription to : skipping event (default.29028c50-8b3a-4e5f-b8ee-814a25f8c8f8.snapshots, 223, Pulse.Domain.Network.Stash.Memento, Domain.Network.Aggregates, Version=0.1.0.0, Culture=neutral, PublicKeyToken=null @ 14082111/14082111).

2016-01-14 00:24:06,048 [44] INFO EventStore [(null)] - Catch-up Subscription to : skipping event (default.198329a7-c55f-4f95-98c9-4b9bb8e26cf0, 2659, Pulse.Domain.Network.Stash.Events.Tock, Domain.Network.Messages, Version=0.1.0.0, Culture=neutral, PublicKeyToken=null @ 14083065/14083065).

2016-01-14 00:24:06,048 [44] INFO EventStore [(null)] - Catch-up Subscription to : skipping event (default.198329a7-c55f-4f95-98c9-4b9bb8e26cf0, 2660, Pulse.Domain.Network.Stash.Events.Tock, Domain.Network.Messages, Version=0.1.0.0, Culture=neutral, PublicKeyToken=null @ 14084373/14084373).

2016-01-14 00:24:06,048 [44] INFO EventStore [(null)] - Catch-up Subscription to : skipping event (default.198329a7-c55f-4f95-98c9-4b9bb8e26cf0.snapshots, 532, Pulse.Domain.Network.Stash.Memento, Domain.Network.Aggregates, Version=0.1.0.0, Culture=neutral, PublicKeyToken=null @ 14085545/14085545).

2016-01-14 00:24:06,048 [44] INFO Aggregates.DurableSubscriber [(null)] - Processing event number 2661 id c0a211c7-94fd-4b3b-8465-aeeb5ca5d090 from stream default.198329a7-c55f-4f95-98c9-4b9bb8e26cf0

2016-01-14 00:24:06,027 [57] INFO EventStore [(null)] - EventStoreConnection ‘ES-eab81e2a-1c32-4477-be2c-d3989217c24b’: HandleTcpPackage OPERATION DECISION EndOperation (Success), Operation ReadAllEventsForwardOperation (20723b39-1bc7-4e45-973a-8c43c1e44f89): Position: 13984756/13984756, MaxCount: 500, ResolveLinkTos: False, RequireMaster: True, retry count: 0, created: 06:24:05.909, last updated: 06:24:05.909.

2016-01-14 00:24:06,124 [57] INFO EventStore [(null)] - EventStoreConnection ‘ES-eab81e2a-1c32-4477-be2c-d3989217c24b’: RemoveOperation SUCCEEDED for Operation ReadAllEventsForwardOperation (20723b39-1bc7-4e45-973a-8c43c1e44f89): Position: 13984756/13984756, MaxCount: 500, ResolveLinkTos: False, RequireMaster: True, retry count: 0, created: 06:24:05.909, last updated: 06:24:05.909.

2016-01-14 00:24:06,188 [349] INFO EventStore [(null)] - Catch-up Subscription to : processed event (default.198329a7-c55f-4f95-98c9-4b9bb8e26cf0, 2661, Pulse.Domain.Network.Stash.Events.Tock, Domain.Network.Messages, Version=0.1.0.0, Culture=neutral, PublicKeyToken=null @ 14086500/14086500).

2016-01-14 00:24:06,190 [349] INFO Aggregates.DurableSubscriber [(null)] - Processing event number 2662 id c0bbfaa9-b586-460e-a875-121e20622ce0 from stream default.198329a7-c55f-4f95-98c9-4b9bb8e26cf0

9

I think I figured out the problem, seems there is a race condition when apps quickly disconnect and reconnect to the store.

When the client reconnects RunSubscription is called immediately but its possible that ProcessLiveQueue is still running. Which causes ReadEventsTill to incorrectly identify the _lastProcessedPosition and process an event twice (once before the disconnect and once after a reconnect)

This also explains why the event is being double processed on 2 different threads.

To prevent this from happening you’ll just need to write some lock to prevent ProcessLiveQueue and the RunSubscription job from running at the same time.

All I did was add:

while (_isProcessing == 1)

Thread.Sleep(5);

On line 184 and the issue went away - but I only added to prove the point not being very familiar with the locking mechanisms you guys are using I am sure there is a better solution.

Now why the event store keeps disconnecting my client is another problem but at least the double event issue is solved.

Please let me know if this makes sense / can be fixed in the future because its affecting my app greatly. When an event is double processed all processing stops for a good ~3 seconds while it retries handling the event. I can use a custom build of event store for now but it doesn’t work when deployed.

10

I just submitted a pull request here https://github.com/EventStore/EventStore/pull/791 to fix the reconnect race condition.

Also found out that the reconnections were because my app was strangling the ThreadPool - so thats fixed too. I am using the TPL in various places to speed up foreach loops and events which are declared as parallel safe and it turns out having Environment.ProcessorCount threads running at 100% prevents something in the store from making a stable connection causing the connection to terminate. To fix this I am going to designate my event handing threads as a lower priority so that the event store threads will have priority over my less important logic threads.

11

"Also found out that the reconnections were because my app was
strangling the ThreadPool - so thats fixed too. I am using the TPL in
various places to speed up foreach loops and events which are declared
as parallel safe and it turns out having Environment.ProcessorCount
threads running at 100% prevents something in the store from making a
stable connection causing the connection to terminate. To fix this I
am going to designate my event handing threads as a lower priority so
that the event store threads will have priority over my less important
logic threads."

Yes the connection uses the threadpool if its saturated you will get
heartbeat timeouts. We have considered using explicit threads but this
also has a big trade off in terms of overhead.