Eventstore: NetCore client final cherrypick edition

[bartelink]

@jageall I have extracted this from a polluting comment thread in #1716 - I have removed my comment, can you remove your response and put it here please (I know it should be in NetCore). When you paste here I'll respond. The TL;DR is that mine has a concurrency fix, but the more important one was done by Hayley IIRC (will dig it up). Also if you are doing a final cherrypick, I'd like to have KeepDiscovering pulled in too. Apologies for not doing the due diligence of pointing this out over there - but I really didnt want to encourage persisting with two code bases.

I am not sure that saying the client connects half-successfully is really even vaguely accurate as it has 1000s of hours of use. I have observed problems with reconnection and some settings not working as expected

Repeating, but I feel its important to state that there are two significant concurrency fixes in 4.1.1 - I've destruction tested it with various combinations of killing and restarting servers, sockets etc, after various outages and have not seen it fail. (Also we put plenty load inc all sorts of DDOS attack effects through it on a regular basis problem free). The current NetCore client fails at the very first hurdle on my most basic load test rig for, to me, obvious reasons (concurrency bugs), which manifest as a disconnection with a complete failure to automatically reconnect. (The same basic problems exist in 3.9.x). We also have some prod NetCore stuff failing load tests for the same [for me entirely obvious] reason. It is for these reasons (aside from wanting feature parity and less messy builds) that I was eager to have #1680 expedited.

As long as the eye is on the goal of having a netstandard build of the ClientAPI in EventStore/EventStore/master being on NuGet (at least as an alpha) real soon, this overall plan is obviously in everyone's interest (feel free to ping me the minute one is available and I'll run it on my rig - I really hope that will before I get that rig open sourced, which will be this year). (I don't want to oversell the rig - it just runs hundreds of client threads against a single EventStoreConnection connecting with gossip [to a local instance for most of my testing])

[bartelink]

@jageall Preview - will re-post at tail after you re-post your response here
Wishlist/need list in order of age sequence I think they need to be applied in:

1. Depending on messiness, PreferSlaveNode is nice to have in order to be able to trust semantics to be equivalent https://github.com/EventStore/EventStore/pull/1557 and https://github.com/EventStore/EventStore/pull/1559
2. Most critical concurrency fix IME is @hayley-jean's ConcurrentDictionary https://github.com/EventStore/EventStore/pull/1561
3. I think I build on https://github.com/EventStore/EventStore/pull/1567 so best to take
4. Would be nice to have KeepDiscovering API, and it's small: https://github.com/EventStore/EventStore/pull/1578
5. My feature includes a concurrency bugfix (and is critical to be able to deal with backlogs under load without swamping servers): https://github.com/EventStore/EventStore/pull/1582
6. Fix bug so discovery does not throw on localhost: https://github.com/EventStore/EventStore/pull/1600
   Finally can I ask that it be called something other than 4.1.1 - while I think this is pretty much full bug and feature compat with it, we don't know that for a fact and I'd hate to have people making bad assumptions

[bartelink]

Final suggestion though: https://github.com/EventStore/EventStore/pull/1680 pretty much achieves all of this - and could actually be legitimately labelled 4.1.1. I reckon using that is actually the best way to get a reliable NetCore client into the field.

I can appreciate that you/ES might not wish to stand over it and/or invest the time to put something like that through a full test/release cycle - but you could label it -alpha1 in terms of NuGet version tagging

Either way, I'll test an alpha/RC if/when it arrives a) with my load test rig b) by re-running a (currently failing) prod load test against a prod cluster (assuming that works it'll be in prod pretty quick - I simply don't trust the code as it is given the ample evidence and logical reasons not to)

[jageall]

For ease i will revert the pr that causes the codebases to diverge and do a
full 4.1.1 compatibility release candidate . I will then publish an rc.
Once you have verified it passes your tests i will do a 4.1.1 release (some
people need a non rc version to put into prod). I will then ask all the
current prs to be redone against the main client or move them myself.

I do hear all that you are saying, but would rather a final release with
full parity before switching over.

Re your test rig. I have been discussing the need for more rigorous load
testing of all the client features against a cluster that has failovers
occuring as part of the release process. I am pretty sure this will happen,
but i dont have timescales for achieving it.

If you are unable to open source your rig, i am sure your input would be
valued when we do that work.

Again thanks for your help and apologies again about the misunderstanding
on my part.

On Sun, 2 Sep 2018, 08:40 Ruben Bartelink, [e-mail] wrote:

@jageall https://github.com/jageall Preview - will re-post at tail
after you re-post your response here
Wishlist/need list in order of age sequence I think they need to be
applied in:

1. Depending on messiness, PreferSlaveNode is nice to have in order to
   be able to trust semantics to be equivalent #1557
   https://github.com/EventStore/EventStore/pull/1557 and #1559
   https://github.com/EventStore/EventStore/pull/1559
2. Most critical concurrency fix IME is @hayley-jean
   https://github.com/hayley-jean's ConcurrentDictionary #1561
   https://github.com/EventStore/EventStore/pull/1561
3. I think I build on #1567
   https://github.com/EventStore/EventStore/pull/1567 so best to take
4. Would be nice to have KeepDiscovering API, and it's small: #1578
   https://github.com/EventStore/EventStore/pull/1578
5. My feature includes a concurrency bugfix (and is critical to be
   able to deal with backlogs under load without swamping servers): #1582
   https://github.com/EventStore/EventStore/pull/1582
6. Fix bug so discovery does not throw on localhost: #1600
   https://github.com/EventStore/EventStore/pull/1600
   Finally can I ask that it be called something other than 4.1.1 - while
   I think this is pretty much full bug and feature compat with it, we don't
   know that for a fact and I'd hate to have people making bad assumptions

—
You are receiving this because you were mentioned.
Reply to this email directly, view it on GitHub
https://github.com/EventStore/EventStore/issues/1719#issuecomment-417911432,
or mute the thread
https://github.com/notifications/unsubscribe-auth/AEYR6UsJvhQukkBgcWaFlcXpi05qjL5Jks5uW4twgaJpZM4WWgAV
.

[jageall]

1561 is a serverside fix? Is that the correct one or did you mean a other?

On Sun, 2 Sep 2018, 08:40 Ruben Bartelink, [e-mail] wrote:

@jageall https://github.com/jageall Preview - will re-post at tail
after you re-post your response here
Wishlist/need list in order of age sequence I think they need to be
applied in:

1. Depending on messiness, PreferSlaveNode is nice to have in order to
   be able to trust semantics to be equivalent #1557
   https://github.com/EventStore/EventStore/pull/1557 and #1559
   https://github.com/EventStore/EventStore/pull/1559
2. Most critical concurrency fix IME is @hayley-jean
   https://github.com/hayley-jean's ConcurrentDictionary #1561
   https://github.com/EventStore/EventStore/pull/1561
3. I think I build on #1567
   https://github.com/EventStore/EventStore/pull/1567 so best to take
4. Would be nice to have KeepDiscovering API, and it's small: #1578
   https://github.com/EventStore/EventStore/pull/1578
5. My feature includes a concurrency bugfix (and is critical to be
   able to deal with backlogs under load without swamping servers): #1582
   https://github.com/EventStore/EventStore/pull/1582
6. Fix bug so discovery does not throw on localhost: #1600
   https://github.com/EventStore/EventStore/pull/1600
   Finally can I ask that it be called something other than 4.1.1 - while
   I think this is pretty much full bug and feature compat with it, we don't
   know that for a fact and I'd hate to have people making bad assumptions

—
You are receiving this because you were mentioned.
Reply to this email directly, view it on GitHub
https://github.com/EventStore/EventStore/issues/1719#issuecomment-417911432,
or mute the thread
https://github.com/notifications/unsubscribe-auth/AEYR6UsJvhQukkBgcWaFlcXpi05qjL5Jks5uW4twgaJpZM4WWgAV
.

[bartelink]

Don't have time to peep right now, but I remember it being that kinda shape (i.e., you could well be corect that something else shot the bear) - I also recall doing a history of stuff touching ClientApi and something like that being in the mix. What I am certain of is that the 4.0.1 Nuget and the NetCore one failed in the same way and there were not a lot of commits - ~April.

The test rig we/I have is at its core a perf+load test (i.e. the idea for https://github.com/EventStore/EventStore/issues/1652 arises for its perf when threads get into conflict on the same stream); it just happens to be a good soak/resilience test for the client as a side-effect, but there is good scope to extend it. Failure injections are not part of it though - i.e. I was closing sockets with tcpview and killing servers with Ctrl C.

I'll see if I can establish a timeline as to when it can hit the open; there's a full set of client wrappers etc. which all need to generate NuGets and have good build pipelines before I release them. One other important blocker was that I was hoping to avoid the extra build work to make it target NetCore.ClientAPI and normal Client API conditionally, which is what https://github.com/EventStore/EventStore/pull/1680 was supposed to alleviate ;)

[jageall]

Ok, I have published an rc with all the changes moved across to the core client. Hopefully it will fix the problems with the core client.

Just to be clear, the core client was a personal project to get the client working on core, which is why it was a bit behind (read very busy with paying work) However, as i am now working on getting the unified client/core build fairly heavily, if there are changes required that you find in your load testing, i will try and update the client asap.

[bartelink]

This is awesome James - will be in touch, hopefully over the weekend. The fact you did this in the first instance is and was much appreciated from everyone's perspective.

[bartelink]

EDIT: Need to triple check before assuming the worst - I had the correct DLL but it was not being used. Digging deeper...
Leaving this here as it represents the before state:-

---

Still seeing what I believe to be the same behavior (and an exception that suggests one of the commits re IPv6 localhost handling is not included UPDATE: but ILSpy shows the commit per your repo 🤔 ). Have done zero digging - perhaps I should start from trying a binary from #1680 - but we can to/fro if you DM me.

[17:25:02 INF] Running for 00:10:00, targeting localhost with heartbeat: 00:00:01.5000000, max concurrent requests: 5000
Test freq 4000 hits/s; Operation timeout: 00:00:03 and 1 retries; max errors: 3000
Reporting intervals: ["00:10:00", "00:00:10", "00:01:00", "00:05:00"], report file: \bin\Release\netcoreapp2.0\log.txt
[17:25:03 INF] Discovering: found best choice [127.0.0.1:1113,n/a] (Master).
[17:25:03 INF] Discovering: found best choice [127.0.0.1:1113,n/a] (Master).
[17:25:03 INF] Discovering attempt 1/2147483647 successful: best candidate is [127.0.0.1:1113, n/a].
[17:25:03 INF] Discovering attempt 1/2147483647 successful: best candidate is [127.0.0.1:1113, n/a].
[17:25:03 INF] Initializing session pool count=8000
[17:25:03 INF] Session pool ready
[17:25:03 INF] Load test started
[17:25:14 INF] Aggregate:
Bucket   : span=10s timestamp=2018-09-08T17:25:13
Tests    : total=4323 success=3262 OperationTimedOutException=1061
Latency  : max=9.74s p99=9.076s p95=8.468s p50=4.386s min=1.759s avg=4.758s stddev=2.289s
[17:25:18 INF] ClientAPI TcpConnection closed [16:25:18.508: N127.0.0.1:1113, L127.0.0.1:57702, {edf6e266-0f34-4879-b71b-23a1ba6f7ac0}]:
[17:25:18 INF] Received bytes: 522950, Sent bytes: 2632735
[17:25:18 INF] Send calls: 13075, callbacks: 13075
[17:25:18 INF] Receive calls: 184, callbacks: 184
[17:25:18 INF] Close reason: [Success] Socket closed
[17:25:23 INF] Discovering attempt 1/2147483647 failed: no candidate found.
[17:25:23 INF] Aggregate:
Bucket   : span=10s timestamp=2018-09-08T17:25:23
Tests    : total=5415 success=5415
Latency  : max=16.76s p99=13.24s p95=12.37s p50=11.97s min=8.5s avg=11.64s stddev=0.903s
[17:25:24 INF] Discovering attempt 2/2147483647 failed with error: System.UriFormatException: Invalid URI: The hostname could not be parsed.
   at System.Uri.CreateThis(String uri, Boolean dontEscape, UriKind uriKind)
   at System.Uri..ctor(String uriString)
   at EventStore.ClientAPI.Transport.Http.HttpAsyncClient.Receive(String method, String url, UserCredentials userCredentials, Action`1 onSuccess, Action`1 onException, String hostHeader)
   at EventStore.ClientAPI.Transport.Http.HttpAsyncClient.Get(String url, UserCredentials userCredentials, Action`1 onSuccess, Action`1 onException, String hostHeader)
   at EventStore.ClientAPI.Internal.ClusterDnsEndPointDiscoverer.TryGetGossipFrom(GossipSeed endPoint)
   at EventStore.ClientAPI.Internal.ClusterDnsEndPointDiscoverer.<DiscoverEndPoint>d__11.MoveNext()
--- End of stack trace from previous location where exception was thrown ---
   at System.Runtime.ExceptionServices.ExceptionDispatchInfo.Throw()
   at System.Runtime.CompilerServices.TaskAwaiter.HandleNonSuccessAndDebuggerNotification(Task task)
   at EventStore.ClientAPI.Internal.ClusterDnsEndPointDiscoverer.<DiscoverAsync>d__10.MoveNext().
[17:25:25 INF] Discovering: found best choice [127.0.0.1:1113,n/a] (Master).
[17:25:25 INF] Discovering attempt 3/2147483647 successful: best candidate is [127.0.0.1:1113, n/a].
[17:25:31 INF] ClientAPI TcpConnection closed [16:25:31.632: N127.0.0.1:1113, L127.0.0.1:57701, {cbbd9d6d-4aa0-4ccd-a780-829bd2996cec}]:
[17:25:34 INF] Received bytes: 26257303, Sent bytes: 6978183
[17:25:34 INF] Send calls: 83076, callbacks: 83076
[17:25:34 INF] Receive calls: 10675, callbacks: 10675
[17:25:34 INF] Close reason: [Success] Socket closed
[17:25:33 INF] Aggregate:
Bucket   : span=10s timestamp=2018-09-08T17:25:32
Tests    : total=1 success=1
Latency  : max=23.26s p99=23.26s p95=23.26s p50=23.26s min=23.26s avg=23.26s stddev=NaNs
[17:25:39 INF] ClientAPI TcpConnection closed [16:25:39.885: N127.0.0.1:1113, L127.0.0.1:57705, {7920d016-448e-41bc-b492-b945c4b53544}]:
[17:25:39 INF] Received bytes: 1654254, Sent bytes: 3693060
[17:25:39 INF] Send calls: 19759, callbacks: 19759
[17:25:39 INF] Receive calls: 934, callbacks: 934
[17:25:39 INF] Close reason: [Success] Socket closed

Server log:

[10244,01,16:24:46.015]
ES VERSION:               4.1.0.0 (oss-v4.1.0/daddeca886f43e40489efd7d9f45cb6ddd4aed8a, Tue, 23 Jan 2018 14:12:35 +0200)
[10244,01,16:24:46.015] OS:                       Windows (Microsoft Windows NT 6.2.9200.0)
[10244,01,16:24:46.015] RUNTIME:                  .NET 4.0.30319.42000 (64-bit)
[10244,01,16:24:46.015] GC:                       3 GENERATIONS
[10244,01,16:24:46.015] LOGS:                     C:\ProgramData\chocolatey\lib\eventstore-oss\tools\logs
[10244,01,16:24:46.034] MODIFIED OPTIONS:

        GOSSIP ON SINGLE NODE:    true (Command Line)
        DISCOVER VIA DNS:         0 (Command Line)
        EXT HTTP PORT:            30778 (Command Line)

DEFAULT OPTIONS:

        HELP:                     False (<DEFAULT>)
        VERSION:                  False (<DEFAULT>)
        LOG:                      C:\ProgramData\chocolatey\lib\eventstore-oss\tools\logs (<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>)
        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>)
        CONNECTION PENDING SEND BYTES THRESHOLD: 10485760 (<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>)
        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>)
        DB:                       C:\ProgramData\chocolatey\lib\eventstore-oss\tools\data (<DEFAULT>)
        INDEX:                    <empty> (<DEFAULT>)
        MEM DB:                   False (<DEFAULT>)
        SKIP DB VERIFY:           False (<DEFAULT>)
        WRITE THROUGH:            False (<DEFAULT>)
        UNBUFFERED:               False (<DEFAULT>)
        CHUNK INITIAL READER COUNT: 5 (<DEFAULT>)
        RUN PROJECTIONS:          None (<DEFAULT>)
        PROJECTION THREADS:       3 (<DEFAULT>)
        WORKER THREADS:           5 (<DEFAULT>)
        PROJECTIONS QUERY EXPIRY: 0 (<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>)
        SKIP INDEX VERIFY:        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>)
        SKIP INDEX SCAN ON READS: False (<DEFAULT>)

[10244,01,16:24:46.034] DNS discovery is disabled, but no gossip seed endpoints have been specified. Since the cluster size is set to 1, this may be intentional. Gossip seeds can be specified using the `GossipSeed` option.
[10244,01,16:24:46.034] Quorum size set to 1
[10244,01,16:24:46.060] Cannot find plugins path: C:\ProgramData\chocolatey\lib\eventstore-oss\tools\plugins
[10244,01,16:24:46.192] INSTANCE ID:              8d435572-4966-460e-bdf4-332ec1d8b564
[10244,01,16:24:46.192] DATABASE:                 C:\ProgramData\chocolatey\lib\eventstore-oss\tools\data
[10244,01,16:24:46.192] WRITER CHECKPOINT:        80237230 (0x4C852AE)
[10244,01,16:24:46.192] CHASER CHECKPOINT:        80237230 (0x4C852AE)
[10244,01,16:24:46.192] EPOCH CHECKPOINT:         41644077 (0x27B702D)
[10244,01,16:24:46.192] TRUNCATE CHECKPOINT:      -1 (0xFFFFFFFFFFFFFFFF)
[10244,01,16:24:46.349] MessageHierarchy initialization took 00:00:00.1172776.
[10244,01,16:24:46.624] Opened ongoing C:\ProgramData\chocolatey\lib\eventstore-oss\tools\data\chunk-000000.000000 as version 3
[10244,01,16:24:46.682] CACHED TFChunk #0-0 (chunk-000000.000000) in 00:00:00.0524087.
[10244,01,16:24:47.005] Starting MiniWeb for /web/es/js/projections ==> C:\ProgramData\chocolatey\lib\eventstore-oss\tools\projections
[10244,01,16:24:47.005] Starting MiniWeb for /web/es/js/projections/v8/Prelude ==> C:\ProgramData\chocolatey\lib\eventstore-oss\tools\Prelude
[10244,01,16:24:47.015] Starting MiniWeb for /web ==> C:\ProgramData\chocolatey\lib\eventstore-oss\tools\clusternode-web
[10244,01,16:24:47.015] Binding MiniWeb to /web/{*remaining_path}
[10244,12,16:24:47.039] ========== [127.0.0.1:2112] SYSTEM INIT...
[10244,12,16:24:47.057] Starting Normal TCP listening on TCP endpoint: 127.0.0.1:1113.
[10244,13,16:24:47.066] TableIndex initialization...
[10244,13,16:24:47.078] ReadIndex building...
[10244,12,16:24:47.078] Starting HTTP server on [http://127.0.0.1:30778/,http://localhost:30778/]...
[10244,12,16:24:47.078] HTTP server is up and listening on [http://127.0.0.1:30778/,http://localhost:30778/]
[10244,12,16:24:47.109] SLOW QUEUE MSG [MainQueue]: SystemInit - 70ms. Q: 0/5.
[10244,12,16:24:47.109] ========== [127.0.0.1:2112] Service 'StorageReader' initialized.
[10244,12,16:24:47.109] ========== [127.0.0.1:2112] Service 'StorageWriter' initialized.
[10244,12,16:24:47.125] CLUSTER HAS CHANGED
[10244,12,16:24:47.125] Old:
[10244,12,16:24:47.125] VND {8d435572-4966-460e-bdf4-332ec1d8b564} <LIVE> [Unknown, 127.0.0.1:1112, 127.0.0.1:0, 127.0.0.1:1113, 127.0.0.1:0, 127.0.0.1:2112, 127.0.0.1:30778] -1/80237230/80237230/E3@41644077:{9c39b6de-62d1-41b4-9fc2-fc665f24
1279} | 2018-09-08 16:24:47.091
[10244,12,16:24:47.125] New:
[10244,12,16:24:47.125] VND {8d435572-4966-460e-bdf4-332ec1d8b564} <LIVE> [Unknown, 127.0.0.1:1112, 127.0.0.1:0, 127.0.0.1:1113, 127.0.0.1:0, 127.0.0.1:2112, 127.0.0.1:30778] -1/80237230/80237230/E3@41644077:{9c39b6de-62d1-41b4-9fc2-fc665f24
1279} | 2018-09-08 16:24:47.091
[10244,12,16:24:47.125] --------------------------------------------------------------------------------
[10244,13,16:24:47.641] ReadIndex Rebuilding: processed 100000 records (32.2%).
[10244,13,16:24:48.080] ReadIndex rebuilding done: total processed 193285 records, time elapsed: 00:00:01.0019980.
[10244,12,16:24:48.100] ========== [127.0.0.1:2112] Service 'StorageChaser' initialized.
[10244,12,16:24:48.100] ========== [127.0.0.1:2112] SYSTEM START...
[10244,12,16:24:48.100] ========== [127.0.0.1:2112] IS UNKNOWN...
[10244,30,16:24:48.126] Subscriptions received state change to Unknown stopping listening.
[10244,12,16:24:48.141] ELECTIONS: STARTING ELECTIONS.
[10244,12,16:24:48.141] ELECTIONS: (V=0) SHIFT TO LEADER ELECTION.
[10244,12,16:24:48.141] ELECTIONS: (V=0) VIEWCHANGE FROM [127.0.0.1:2112, {8d435572-4966-460e-bdf4-332ec1d8b564}].
[10244,12,16:24:48.141] ELECTIONS: (V=0) MAJORITY OF VIEWCHANGE.
[10244,12,16:24:48.141] ELECTIONS: (V=0) SHIFT TO PREPARE PHASE.
[10244,12,16:24:48.141] ELECTIONS: (V=0) PREPARE_OK FROM [127.0.0.1:2112,{8d435572-4966-460e-bdf4-332ec1d8b564}](L=80221530,W=80237230,C=80237230,E3@41644077:{9c39b6de-62d1-41b4-9fc2-fc665f241279}).
[10244,12,16:24:48.141] ELECTIONS: (V=0) SHIFT TO REG_LEADER.
[10244,12,16:24:48.157] ELECTIONS: (V=0) SENDING PROPOSAL CANDIDATE: [127.0.0.1:2112,{8d435572-4966-460e-bdf4-332ec1d8b564}](L=80221530,W=80237230,C=80237230,E3@41644077:{9c39b6de-62d1-41b4-9fc2-fc665f241279}), ME: [127.0.0.1:2112,{8d435572-
4966-460e-bdf4-332ec1d8b564}](L=80221530,W=80237230,C=80237230,E3@41644077:{9c39b6de-62d1-41b4-9fc2-fc665f241279}).
[10244,12,16:24:48.157] ELECTIONS: (V=0) ACCEPT FROM [127.0.0.1:2112,{8d435572-4966-460e-bdf4-332ec1d8b564}] M=[127.0.0.1:2112,{8d435572-4966-460e-bdf4-332ec1d8b564}]).
[10244,12,16:24:48.157] ELECTIONS: (V=0) DONE. ELECTED MASTER = [127.0.0.1:2112,{8d435572-4966-460e-bdf4-332ec1d8b564}](L=80221530,W=80237230,C=80237230,E3@41644077:{9c39b6de-62d1-41b4-9fc2-fc665f241279}). ME=[127.0.0.1:2112,{8d435572-4966-4
60e-bdf4-332ec1d8b564}](L=80221530,W=80237230,C=80237230,E3@41644077:{9c39b6de-62d1-41b4-9fc2-fc665f241279}).
[10244,12,16:24:48.157] ========== [127.0.0.1:2112] PRE-MASTER STATE, WAITING FOR CHASER TO CATCH UP...
[10244,28,16:24:48.157] Subscriptions received state change to PreMaster stopping listening.
[10244,12,16:24:48.157] ========== [127.0.0.1:2112] IS MASTER... SPARTA!
[10244,25,16:24:48.157] Subscriptions Became Master so now handling subscriptions
[10244,10,16:24:48.253] === Writing E4@80237230:{52f0a722-ae77-4ec8-bfd7-fc9d5e05f725} (previous epoch at 41644077).
[10244,10,16:24:48.253] === Update Last Epoch E4@80237230:{52f0a722-ae77-4ec8-bfd7-fc9d5e05f725} (previous epoch at 41644077).
[10244,32,16:24:48.275] PROJECTIONS: Starting Projections Core Coordinator. (Node State : Master)
[10244,12,16:24:48.275] ========== [127.0.0.1:2112] Sub System 'Projections' initialized.
[10244,32,16:24:48.292] PROJECTIONS: Starting Projections Manager. (Node State : Master)
[10244,32,16:24:48.292] PROJECTIONS: SubComponent Started: EventReaderCoreService
[10244,07,16:24:48.297] SLOW QUEUE MSG [MonitoringQueue]: SystemInit - 1246ms. Q: 0/3.
[10244,32,16:24:48.327] PROJECTIONS: Resetting Worker Writer
[10244,07,16:24:48.342] Created stats stream '$stats-127.0.0.1:30778', code = WrongExpectedVersion
[10244,25,16:25:02.741] Segments count: 1, buffers count: 20, should be when full: 20
[10244,12,16:25:02.769] CLUSTER HAS CHANGED (gossip received from [])
[10244,12,16:25:02.769] Old:
[10244,12,16:25:02.769] VND {8d435572-4966-460e-bdf4-332ec1d8b564} <LIVE> [Master, 127.0.0.1:1112, 127.0.0.1:0, 127.0.0.1:1113, 127.0.0.1:0, 127.0.0.1:2112, 127.0.0.1:30778] 80221530/80237230/80237230/E3@41644077:{9c39b6de-62d1-41b4-9fc2-fc6
65f241279} | 2018-09-08 16:24:48.167
[10244,12,16:25:02.769] New:
[10244,12,16:25:02.769] VND {8d435572-4966-460e-bdf4-332ec1d8b564} <LIVE> [Master, 127.0.0.1:1112, 127.0.0.1:0, 127.0.0.1:1113, 127.0.0.1:0, 127.0.0.1:2112, 127.0.0.1:30778] 80237460/80237590/80237590/E4@80237230:{52f0a722-ae77-4ec8-bfd7-fc9
d5e05f725} | 2018-09-08 16:25:02.745
[10244,12,16:25:02.769] --------------------------------------------------------------------------------
[10244,04,16:25:03.335] Segments count: 1, buffers count: 512, should be when full: 512
[10244,04,16:25:03.359] External TCP connection accepted: [Normal, 127.0.0.1:57701, L127.0.0.1:1113, {933b44d0-d817-416d-b976-af70b2943f9a}].
[10244,34,16:25:03.359] External TCP connection accepted: [Normal, 127.0.0.1:57702, L127.0.0.1:1113, {c4bfe179-7798-42ba-9631-796d64d1f2e2}].
[10244,04,16:25:03.663] Connection 'external-normal' ({c4bfe179-7798-42ba-9631-796d64d1f2e2}) identified by client. Client connection name: 'I=262cfc32-b874-43db-bb4b-ad7f6d33c8dc', Client versi
on: V2.
[10244,34,16:25:03.663] Connection 'external-normal' ({933b44d0-d817-416d-b976-af70b2943f9a}) identified by client. Client connection name: 'I=262cfc32-b874-43db-bb4b-ad7f6d33c8dc', Client
version: V2.
[10244,11,16:25:18.456] Closing connection 'external-normal:I=262cfc32-b874-43db-bb4b-ad7f6d33c8dc' [127.0.0.1:57702, L127.0.0.1:1113, {c4bfe179-7798-42ba-9631-796d64d1f2e2}] cleanly. Reason: HE
ARTBEAT TIMEOUT at msgNum 7726
[10244,11,16:25:18.472] ES TcpConnection closed [16:25:18.458: N127.0.0.1:57702, L127.0.0.1:1113, {c4bfe179-7798-42ba-9631-796d64d1f2e2}]:Received bytes: 2632735, Sent bytes: 522950
[10244,11,16:25:18.472] ES TcpConnection closed [16:25:18.473: N127.0.0.1:57702, L127.0.0.1:1113, {c4bfe179-7798-42ba-9631-796d64d1f2e2}]:Send calls: 3121, callbacks: 3121
[10244,11,16:25:18.472] ES TcpConnection closed [16:25:18.473: N127.0.0.1:57702, L127.0.0.1:1113, {c4bfe179-7798-42ba-9631-796d64d1f2e2}]:Receive calls: 7951, callbacks: 7950
[10244,11,16:25:18.472] ES TcpConnection closed [16:25:18.473: N127.0.0.1:57702, L127.0.0.1:1113, {c4bfe179-7798-42ba-9631-796d64d1f2e2}]:Close reason: [Success] HEARTBEAT TIMEOUT at msgNum 7726
[10244,11,16:25:18.472] Connection 'external-normal:I=262cfc32-b874-43db-bb4b-ad7f6d33c8dc' [127.0.0.1:57702, {c4bfe179-7798-42ba-9631-796d64d1f2e2}] closed: Success.
[10244,27,16:25:18.472] Lost connection from 127.0.0.1:57702
[10244,38,16:25:25.794] External TCP connection accepted: [Normal, 127.0.0.1:57705, L127.0.0.1:1113, {4294403c-9247-4f5a-ad76-8cfddd727da3}].
[10244,35,16:25:25.794] Connection 'external-normal' ({4294403c-9247-4f5a-ad76-8cfddd727da3}) identified by client. Client connection name: ';I=262cfc32-b874-43db-bb4b-ad7f6d33c8dc', Client versi
on: V2.
[10244,11,16:25:31.521] Closing connection 'external-normal:I=262cfc32-b874-43db-bb4b-ad7f6d33c8dc' [127.0.0.1:57701, L127.0.0.1:1113, {933b44d0-d817-416d-b976-af70b2943f9a}] cleanly. Reaso
n: HEARTBEAT TIMEOUT at msgNum 55228
[10244,11,16:25:31.521] ES TcpConnection closed [16:25:31.521: N127.0.0.1:57701, L127.0.0.1:1113, {933b44d0-d817-416d-b976-af70b2943f9a}]:Received bytes: 6978183, Sent bytes: 26257303
[10244,11,16:25:31.521] ES TcpConnection closed [16:25:31.521: N127.0.0.1:57701, L127.0.0.1:1113, {933b44d0-d817-416d-b976-af70b2943f9a}]:Send calls: 17003, callbacks: 17003
[10244,11,16:25:31.521] ES TcpConnection closed [16:25:31.521: N127.0.0.1:57701, L127.0.0.1:1113, {933b44d0-d817-416d-b976-af70b2943f9a}]:Receive calls: 56134, callbacks: 56133
[10244,11,16:25:31.521] ES TcpConnection closed [16:25:31.521: N127.0.0.1:57701, L127.0.0.1:1113, {933b44d0-d817-416d-b976-af70b2943f9a}]:Close reason: [Success] HEARTBEAT TIMEOUT at msgNum 55228
[10244,11,16:25:31.521] Connection 'external-normal:I=262cfc32-b874-43db-bb4b-ad7f6d33c8dc' [127.0.0.1:57701, {933b44d0-d817-416d-b976-af70b2943f9a}] closed: Success.
[10244,21,16:25:31.521] Lost connection from 127.0.0.1:57701
[10244,11,16:25:39.861] Closing connection 'external-normal:I=262cfc32-b874-43db-bb4b-ad7f6d33c8dc' [127.0.0.1:57705, L127.0.0.1:1113, {4294403c-9247-4f5a-ad76-8cfddd727da3}] cleanly. Reason: HE
ARTBEAT TIMEOUT at msgNum 13939
[10244,11,16:25:39.861] ES TcpConnection closed [16:25:39.861: N127.0.0.1:57705, L127.0.0.1:1113, {4294403c-9247-4f5a-ad76-8cfddd727da3}]:Received bytes: 3693060, Sent bytes: 1654254
[10244,11,16:25:39.861] ES TcpConnection closed [16:25:39.861: N127.0.0.1:57705, L127.0.0.1:1113, {4294403c-9247-4f5a-ad76-8cfddd727da3}]:Send calls: 6419, callbacks: 6419
[10244,11,16:25:39.861] ES TcpConnection closed [16:25:39.861: N127.0.0.1:57705, L127.0.0.1:1113, {4294403c-9247-4f5a-ad76-8cfddd727da3}]:Receive calls: 14467, callbacks: 14466
[10244,11,16:25:39.861] ES TcpConnection closed [16:25:39.861: N127.0.0.1:57705, L127.0.0.1:1113, {4294403c-9247-4f5a-ad76-8cfddd727da3}]:Close reason: [Success] HEARTBEAT TIMEOUT at msgNum 13939
[10244,11,16:25:39.861] Connection 'external-normal:I=262cfc32-b874-43db-bb4b-ad7f6d33c8dc' [127.0.0.1:57705, {4294403c-9247-4f5a-ad76-8cfddd727da3}] closed: Success.
[10244,24,16:25:39.861] Lost connection from 127.0.0.1:57705

re-running had similar effects (no initial flurry of timeouts as warm, but same behavior wrt connection being lost etc)

[bartelink]

WAIT... - I think I'm getting an incorrect DLL version actually being included in the build :doh:

[jageall]

I had some problems with publishing the package so it might be my fault,
but i thought i published it ok. I cant see what i missed re ipv6 but will
test it when i get back. Sadly almost none of the changes had tests to
verify they were working. Something i would like to get fixed.

On Sat, 8 Sep 2018, 20:31 Ruben Bartelink, [e-mail] wrote:

WAIT... - I think I'm getting an incorrect DLL version actually being
included in the build :doh:

—
You are receiving this because you were mentioned.
Reply to this email directly, view it on GitHub
https://github.com/EventStore/EventStore/issues/1719#issuecomment-419659778,
or mute the thread
https://github.com/notifications/unsubscribe-auth/AEYR6UUH6-WYE-8Ln35a2sAco65agiXPks5uY_72gaJpZM4WWgAV
.

[bartelink]

Hm, will remove the log above and replace with a better one later on. It's no longer hanging, but it is getting into a bad state which it does not in normal FW where it's losing connection. This might be down to perf differences and related necessary timeout adjustments... So, it's back to watch this space, sorry!

[jageall]

No problem. Thank you very much for.your work on this

On Sat, 8 Sep 2018, 20:47 Ruben Bartelink, [e-mail] wrote:

Hm, will remove the log above and replace with a better one later on. It's
no longer hanging, but it is getting into a bad state which it does not in
normal FW where it's losing connection. This might be down to perf
differences and related necessary timeout adjustments... So, it's back to
watch this space, sorry!

—
You are receiving this because you were mentioned.
Reply to this email directly, view it on GitHub
https://github.com/EventStore/EventStore/issues/1719#issuecomment-419660760,
or mute the thread
https://github.com/notifications/unsubscribe-auth/AEYR6SlT_6Njv7JQANo0LVhIOGdqshYcks5uZAK8gaJpZM4WWgAV
.

[bartelink]

OK, more preliminary results:- it's not hanging, and the APIs and bugfixes are in. I need to spend some time later to dig deeper into the perf and will report back (I have never been in a position to do a comparison as my record run was about 5s on the old version of the NetCore client). So 🤞 but looking good atm.

[jageall]

Watching this space :)

On Sat, 8 Sep 2018, 21:03 Ruben Bartelink, [e-mail] wrote:

OK, more preliminary results:- it's not hanging, and the APIs and bugfixes
are in. I need to spend some time later to dig deeper into the perf and
will report back (I have never been in a position to do a comparison as my
record run was about 5s on the old version of the NetCore client). So 🤞
but looking good atm.

—
You are receiving this because you were mentioned.
Reply to this email directly, view it on GitHub
https://github.com/EventStore/EventStore/issues/1719#issuecomment-419661722,
or mute the thread
https://github.com/notifications/unsubscribe-auth/AEYR6Z6oEpkG4ZznIPPiXWqOB1e81xf0ks5uZAZYgaJpZM4WWgAV
.

[bartelink]

... Seeing a StackOverflowException on long runs [but long runs actually being possible is a step up]. Will report if/when I get to take a deeper look

[jageall]

Send me the stack trace if you can. I was suspicious of some of the
changes. It also might be a difference in the jit between core and full
framework

On Sat, 8 Sep 2018, 21:45 Ruben Bartelink, [e-mail] wrote:

... Seeing a StackOverflowException on long runs [but long runs actually
being possible is a step up]. Will report if/when I get to take a deeper
look

—
You are receiving this because you were mentioned.
Reply to this email directly, view it on GitHub
https://github.com/EventStore/EventStore/issues/1719#issuecomment-419664707,
or mute the thread
https://github.com/notifications/unsubscribe-auth/AEYR6TtRgxTH-w0D3QkiVjcPUVEVdPWKks5uZBBQgaJpZM4WWgAV
.

[bartelink]

Have not been able to repro this situation on 5.x in recent times despite trying so am closing this as can't repro. That does not mean it's absolutely definitely gone (I've had VMWare Fusion foisted on me which has destroyed disk perf), but I've definitely tried and don't think the issue is adding value in its open state.