Eventstore: Create persistent subscriptions, test case

Created on 13 Oct 2015  ·  10Comments  ·  Source: EventStore/EventStore

Hi, we have another test case for you, in the same test fixture as the previous one... This time it's for persistent subscriptions.

Note how the persistent subscription is created (and how the server lists all [35908,10,15:54:35.666] state write successful from the previously created groups, but the call to ConnectToPersistentSubscription never returns.

        [Test]
        public async Task SubscribeToRandomPersistentSubscription ()
        {
            Console.WriteLine ();
            Console.WriteLine ("Persistent Subscription Test");


            var connSettings =
                ConnectionSettings.Create()
                    .UseConsoleLogger ()
                    .EnableVerboseLogging()
                    .KeepReconnecting ()
                    .SetHeartbeatTimeout (TimeSpan.FromSeconds (8))
                    .Build ();
            var conn = EventStoreConnection.Create (connSettings, new Uri ("tcp://admin:[email protected]:1113"), "myConn");
            await conn.ConnectAsync ();
            var stream = GenName ();

            Console.WriteLine ("Writing event to {0}", stream);

            var tr = await conn.AppendToStreamAsync (stream, -1, new[] {
                new EventData (Guid.NewGuid (), "myType", true, GenData (), GenData())
            });

            Console.WriteLine ("Wrote event to {0}", stream);

            Assert.That (tr.LogPosition.CommitPosition, Is.GreaterThan (0),
                "Should have written in the log");

            var tcs = new TaskCompletionSource<int> ();
            var count = 0;

            var pss =
                PersistentSubscriptionSettings
                    .Create ()
                    .StartFromBeginning ()
                    .ResolveLinkTos ()
                    .CheckPointAfter (TimeSpan.FromSeconds(1))
                    .MinimumCheckPointCountOf (1)
                    .MaximumCheckPointCountOf (10)
                    .Build ();

            var group = GenName ();

            await conn.CreatePersistentSubscriptionAsync (stream, group, pss, new UserCredentials("admin", "changeit"));

            conn.ConnectToPersistentSubscription(
                stream,
                group,
                (sub, evt) => {
                    Console.WriteLine ("Got expected event, because this is a persistent subscription with a random group");
                    if (Interlocked.Increment (ref count) == 1)
                        tcs.SetResult (1);
                    else
                        Assert.That (tcs.TrySetResult (count), Is.False);
                },
                (sub, reason, ex) => Console.WriteLine ("Error: {0}", ex),
                new UserCredentials("admin", "changeit"),
                10,
                true);

            Console.WriteLine ("Awaiting persistent subscription's events");

            Assert.That (await tcs.Task, Is.EqualTo (1),
                "Should receive category subscription");
        }

Output:

➜  EventStoreTests  export MONO_THREADS_PER_CPU=120
➜  EventStoreTests  mono ../packages/NUnit.Runners.2.6.4/tools/nunit-console.exe bin/Debug/EventStoreTests.dll
WARNING: The runtime version supported by this application is unavailable.
Using default runtime: v4.0.30319
NUnit-Console version 2.6.4.14350
Copyright (C) 2002-2012 Charlie Poole.
Copyright (C) 2002-2004 James W. Newkirk, Michael C. Two, Alexei A. Vorontsov.
Copyright (C) 2000-2002 Philip Craig.
All Rights Reserved.

Runtime Environment -
   OS Version: Unix 14.5.0.0
  CLR Version: 4.0.30319.17020 ( Mono 4.0 ( 4.2.0 (Stable 4.2.0.179/a224653 Tue Oct  6 11:27:49 PDT 2015) ) )

ProcessModel: Default    DomainUsage: Single
Execution Runtime: mono-4.0
.
Persistent Subscription Test
[06,15:54:37.159,DEBUG] EventStoreConnection 'myConn': enqueueing message EventStore.ClientAPI.Internal.StartConnectionMessage..
[08,15:54:37.169,DEBUG] EventStoreConnection 'myConn': StartConnection.
[08,15:54:37.169,DEBUG] EventStoreConnection 'myConn': DiscoverEndPoint.
[09,15:54:37.172,DEBUG] EventStoreConnection 'myConn': enqueueing message EventStore.ClientAPI.Internal.EstablishTcpConnectionMessage..
[08,15:54:37.174,DEBUG] EventStoreConnection 'myConn': EstablishTcpConnection to [127.0.0.1:1113].
Writing event to tju1ygge
[10,15:54:37.209,DEBUG] TcpPackageConnection: connected to [127.0.0.1:1113, L127.0.0.1:56411, {28075de7-a474-4690-94bc-5b63ab9d0bd9}].
[10,15:54:37.209,DEBUG] EventStoreConnection 'myConn': enqueueing message EventStore.ClientAPI.Internal.TcpConnectionEstablishedMessage..
[10,15:54:37.210,DEBUG] EventStoreConnection 'myConn': TCP connection to [127.0.0.1:1113, L127.0.0.1:56411, {28075de7-a474-4690-94bc-5b63ab9d0bd9}] established..
[10,15:54:37.272,DEBUG] EventStoreConnection 'myConn': enqueueing message EventStore.ClientAPI.Internal.HandleTcpPackageMessage..
[08,15:54:37.279,DEBUG] EventStoreConnection 'myConn': HandleTcpPackage connId 28075de7-a474-4690-94bc-5b63ab9d0bd9, package Authenticated, 9ccdcbdd-7eae-43da-8512-3073616149a0..
[09,15:54:37.285,DEBUG] EventStoreConnection 'myConn': enqueueing message EventStore.ClientAPI.Internal.StartOperationMessage..
[08,15:54:37.287,DEBUG] EventStoreConnection 'myConn': StartOperation schedule AppendToStreamOperation, Stream: tju1ygge, ExpectedVersion: -1, 10, 00:00:07..
[08,15:54:37.331,DEBUG] EventStoreConnection 'myConn': ScheduleOperation package WriteEvents, c7a1fc04-8de6-4402-9fbe-9348a9db1158, Operation AppendToStreamOperation (c7a1fc04-8de6-4402-9fbe-9348a9db1158): Stream: tju1ygge, ExpectedVersion: -1, retry count: 0, created: 15:54:37.287, last updated: 15:54:37.288..
[10,15:54:37.379,DEBUG] EventStoreConnection 'myConn': enqueueing message EventStore.ClientAPI.Internal.HandleTcpPackageMessage..
[10,15:54:37.379,DEBUG] EventStoreConnection 'myConn': HandleTcpPackage connId 28075de7-a474-4690-94bc-5b63ab9d0bd9, package WriteEventsCompleted, c7a1fc04-8de6-4402-9fbe-9348a9db1158..
Wrote event to tju1ygge
[10,15:54:37.393,DEBUG] EventStoreConnection 'myConn': enqueueing message EventStore.ClientAPI.Internal.StartOperationMessage..
[10,15:54:37.393,DEBUG] EventStoreConnection 'myConn': HandleTcpPackage OPERATION DECISION EndOperation (Success), Operation AppendToStreamOperation (c7a1fc04-8de6-4402-9fbe-9348a9db1158): Stream: tju1ygge, ExpectedVersion: -1, retry count: 0, created: 15:54:37.287, last updated: 15:54:37.288.
[10,15:54:37.394,DEBUG] EventStoreConnection 'myConn': RemoveOperation SUCCEEDED for Operation AppendToStreamOperation (c7a1fc04-8de6-4402-9fbe-9348a9db1158): Stream: tju1ygge, ExpectedVersion: -1, retry count: 0, created: 15:54:37.287, last updated: 15:54:37.288.
[10,15:54:37.394,DEBUG] EventStoreConnection 'myConn': StartOperation schedule CreatePersistentSubscriptionOperation, Stream: tju1ygge, Group Name: b0tho0ly, 10, 00:00:07..
[10,15:54:37.397,DEBUG] EventStoreConnection 'myConn': ScheduleOperation package CreatePersistentSubscription, e3c4a69d-2736-475e-bc5a-84faf7d6cffa, Operation CreatePersistentSubscriptionOperation (e3c4a69d-2736-475e-bc5a-84faf7d6cffa): Stream: tju1ygge, Group Name: b0tho0ly, retry count: 0, created: 15:54:37.394, last updated: 15:54:37.394..
[09,15:54:37.407,DEBUG] EventStoreConnection 'myConn': enqueueing message EventStore.ClientAPI.Internal.HandleTcpPackageMessage..
[09,15:54:37.407,DEBUG] EventStoreConnection 'myConn': HandleTcpPackage connId 28075de7-a474-4690-94bc-5b63ab9d0bd9, package CreatePersistentSubscriptionCompleted, e3c4a69d-2736-475e-bc5a-84faf7d6cffa..
[09,15:54:37.411,DEBUG] EventStoreConnection 'myConn': enqueueing message EventStore.ClientAPI.Internal.StartPersistentSubscriptionMessage..
[10,15:54:41.228,DEBUG] EventStoreConnection 'myConn': enqueueing message EventStore.ClientAPI.Internal.HandleTcpPackageMessage..
[10,15:54:42.267,INFO] ClientAPI TcpConnection closed [15:54:42.267: N127.0.0.1:1113, L127.0.0.1:56411, {28075de7-a474-4690-94bc-5b63ab9d0bd9}]:
Received bytes: 108, Sent bytes: 340
Send calls: 3, callbacks: 3
Receive calls: 5, callbacks: 5
Close reason: [Success] Socket closed

[10,15:54:42.269,DEBUG] TcpPackageConnection: connection [127.0.0.1:1113, L127.0.0.1:56411, {28075de7-a474-4690-94bc-5b63ab9d0bd9}] was closed cleanly.
[10,15:54:42.269,DEBUG] EventStoreConnection 'myConn': enqueueing message EventStore.ClientAPI.Internal.TcpConnectionClosedMessage..
<<HANG>>

EventStore Server logs:

➜  EventStore-OSS-MacOSX-v3.3.0  ./run-node.sh --run-projections=all
[35908,01,15:54:33.900]
ES VERSION:               0.0.0.0 (release-v3.3.0/4923f4c0f427a85a275f362402e62645bca38c07, Wed, 7 Oct 2015 07:37:39 +0200)
OS:                       MacOS (Unix 14.5.0.0)
RUNTIME:                  3.12.1 (tarball) (64-bit)
GC:                       2 GENERATIONS
LOGS:                     /Users/h/Downloads/EventStore-OSS-MacOSX-v3.3.0/logs

MODIFIED OPTIONS:

    RUN PROJECTIONS:          all (Command Line)

DEFAULT OPTIONS:

    HELP:                     False (<DEFAULT>)
    VERSION:                  False (<DEFAULT>)
    LOG:                      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>)
    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>)
    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>)
    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>)
    CHUNKS CACHE SIZE:        536871424 (<DEFAULT>)
    MAX MEM TABLE SIZE:       1000000 (<DEFAULT>)
    DB:                       data (<DEFAULT>)
    MEM DB:                   False (<DEFAULT>)
    SKIP DB VERIFY:           False (<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>)
    SSL TARGET HOST:          n/a (<DEFAULT>)
    SSL VALIDATE SERVER:      True (<DEFAULT>)
    AUTHENTICATION TYPE:      internal (<DEFAULT>)
    PREPARE TIMEOUT MS:       2000 (<DEFAULT>)
    COMMIT TIMEOUT MS:        2000 (<DEFAULT>)
    UNSAFE DISABLE FLUSH TO DISK: 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>)

[35908,01,15:54:33.926] Quorum size set to 1
[35908,01,15:54:33.932] Cannot find plugins path: plugins
[35908,01,15:54:33.955] INSTANCE ID:              9c0282dc-7fa3-4e61-b4d3-db5be478f1fc
[35908,01,15:54:33.956] DATABASE:                 data
[35908,01,15:54:33.956] WRITER CHECKPOINT:        27152083 (0x19E4ED3)
[35908,01,15:54:33.957] CHASER CHECKPOINT:        27152083 (0x19E4ED3)
[35908,01,15:54:33.957] EPOCH CHECKPOINT:         27121344 (0x19DD6C0)
[35908,01,15:54:33.957] TRUNCATE CHECKPOINT:      -1 (0xFFFFFFFFFFFFFFFF)
[35908,01,15:54:34.085] MessageHierarchy initialization took 00:00:00.0944664.
[35908,01,15:54:34.288] CACHED TFChunk #0-0 (chunk-000000.000000) in 00:00:00.0180752.
[35908,01,15:54:34.452] Starting MiniWeb for /web/es/js/projections ==> projections
[35908,01,15:54:34.452] Starting MiniWeb for /web/es/js/projections/v8/Prelude ==> Prelude
[35908,01,15:54:34.453] Binding MiniWeb to /web/es/js/projections/{*remaining_path}
[35908,01,15:54:34.453] Binding MiniWeb to /web/es/js/projections/v8/Prelude/{*remaining_path}
[35908,01,15:54:34.464] Starting MiniWeb for /web ==> clusternode-web
[35908,01,15:54:34.464] Binding MiniWeb to /web/{*remaining_path}
[35908,10,15:54:34.480] ========== [127.0.0.1:2112] SYSTEM INIT...
[35908,10,15:54:34.498] Starting Normal TCP listening on TCP endpoint: 127.0.0.1:1113.
[35908,15,15:54:34.514] TableIndex initialization...
[35908,15,15:54:34.521] ReadIndex building...
[35908,10,15:54:34.539] Starting HTTP server on [http://127.0.0.1:2113/,http://localhost:2113/]...
[35908,10,15:54:34.543] HTTP server is up and listening on [http://127.0.0.1:2113/,http://localhost:2113/]
[35908,10,15:54:34.566] SLOW QUEUE MSG [MainQueue]: SystemInit - 78ms. Q: 0/503.
[35908,10,15:54:34.566] ========== [127.0.0.1:2112] Service 'StorageReader' initialized.
[35908,10,15:54:34.566] ========== [127.0.0.1:2112] Service 'StorageWriter' initialized.
[35908,15,15:54:34.568] ReadIndex rebuilding done: total processed 2422 records, time elapsed: 00:00:00.0474060.
[35908,10,15:54:34.573] ========== [127.0.0.1:2112] Service 'StorageChaser' initialized.
[35908,10,15:54:34.573] ========== [127.0.0.1:2112] SYSTEM START...
[35908,10,15:54:34.575] ========== [127.0.0.1:2112] IS UNKNOWN...
[35908,06,15:54:34.591] Subscriptions received state change to Unknown stopping listening.
[35908,10,15:54:34.610] ELECTIONS: STARTING ELECTIONS.
[35908,10,15:54:34.611] ELECTIONS: (V=0) SHIFT TO LEADER ELECTION.
[35908,10,15:54:34.611] ELECTIONS: (V=0) VIEWCHANGE FROM [127.0.0.1:2112, {9c0282dc-7fa3-4e61-b4d3-db5be478f1fc}].
[35908,10,15:54:34.612] ELECTIONS: (V=0) MAJORITY OF VIEWCHANGE.
[35908,10,15:54:34.612] ELECTIONS: (V=0) SHIFT TO PREPARE PHASE.
[35908,10,15:54:34.613] ELECTIONS: (V=0) PREPARE_OK FROM [127.0.0.1:2112,{9c0282dc-7fa3-4e61-b4d3-db5be478f1fc}](L=27151921,W=27152083,C=27152083,E9@27121344:{ff63cc9e-4cc8-4375-bc9f-40a1d0243c4d}).
[35908,10,15:54:34.613] ELECTIONS: (V=0) SHIFT TO REG_LEADER.
[35908,10,15:54:34.618] ELECTIONS: (V=0) SENDING PROPOSAL CANDIDATE: [127.0.0.1:2112,{9c0282dc-7fa3-4e61-b4d3-db5be478f1fc}](L=27151921,W=27152083,C=27152083,E9@27121344:{ff63cc9e-4cc8-4375-bc9f-40a1d0243c4d}), ME: [127.0.0.1:2112,{9c0282dc-7fa3-4e61-b4d3-db5be478f1fc}](L=27151921,W=27152083,C=27152083,E9@27121344:{ff63cc9e-4cc8-4375-bc9f-40a1d0243c4d}).
[35908,10,15:54:34.618] ELECTIONS: (V=0) ACCEPT FROM [127.0.0.1:2112,{9c0282dc-7fa3-4e61-b4d3-db5be478f1fc}] M=[127.0.0.1:2112,{9c0282dc-7fa3-4e61-b4d3-db5be478f1fc}]).
[35908,10,15:54:34.620] ELECTIONS: (V=0) DONE. ELECTED MASTER = [127.0.0.1:2112,{9c0282dc-7fa3-4e61-b4d3-db5be478f1fc}](L=27151921,W=27152083,C=27152083,E9@27121344:{ff63cc9e-4cc8-4375-bc9f-40a1d0243c4d}). ME=[127.0.0.1:2112,{9c0282dc-7fa3-4e61-b4d3-db5be478f1fc}](L=27151921,W=27152083,C=27152083,E9@27121344:{ff63cc9e-4cc8-4375-bc9f-40a1d0243c4d}).
[35908,10,15:54:34.622] ========== [127.0.0.1:2112] PRE-MASTER STATE, WAITING FOR CHASER TO CATCH UP...
[35908,10,15:54:34.627] ========== [127.0.0.1:2112] IS MASTER... SPARTA!
[35908,06,15:54:34.632] Subscriptions received state change to PreMaster stopping listening.
[35908,06,15:54:34.633] Subscriptions Became Master so now handling subscriptions
[35908,11,15:54:34.729] SLOW BUS MSG [manager input bus]: Starting - 50ms. Handler: ProjectionManagerResponseReader.
[35908,10,15:54:34.729] SLOW BUS MSG [MainBus]: ReadStreamEventsBackwardCompleted - 57ms. Handler: RequestResponseDispatcher`2.
[35908,11,15:54:34.729] SLOW QUEUE MSG [Projections Master]: Starting - 100ms. Q: 0/1.
[35908,10,15:54:34.729] SLOW QUEUE MSG [MainQueue]: ReadStreamEventsBackwardCompleted - 61ms. Q: 0/27.
[35908,08,15:54:34.752] === Writing E10@27152083:{9d4864fb-c46e-4104-a2e5-50d1bc4c571b} (previous epoch at 27121344).
[35908,08,15:54:34.754] === Update Last Epoch E10@27152083:{9d4864fb-c46e-4104-a2e5-50d1bc4c571b} (previous epoch at 27121344).
[35908,10,15:54:34.770] Subscription p8wm1ucv::271kqj51: read checksum 0
[35908,10,15:54:34.770] Subscription kagvzvbq::8kg4lxbb: read checksum 0
[35908,10,15:54:34.771] Subscription glo1ahst::j7fl0kss: read checksum 0
[35908,10,15:54:34.771] Subscription hz4rg7zg::higtwpjl: read checksum 0
[35908,10,15:54:34.771] Subscription wi69r4hz::huzeb9mn: read checksum 0
[35908,10,15:54:34.771] Subscription kvrrojcr::5grxde1g: read checksum 0
[35908,10,15:54:34.771] Subscription xiqqbk32::0ks1nb93: read checksum 0
[35908,10,15:54:34.772] Subscription kxkur37f::o5mu7y1b: read checksum 0
[35908,10,15:54:34.772] Subscription udbe28yw::c2a97d5o: read checksum 0
[35908,10,15:54:34.772] Subscription 8regpabd::ql6bid2x: read checksum 0
[35908,10,15:54:34.772] Subscription 36utbg8t::s7ddlhxf: read checksum 0
[35908,10,15:54:34.772] Subscription ujgvqnc1::xwqjpong: read checksum 0
[35908,10,15:54:34.772] Subscription 5ctnl2om::hgivnl3v: read checksum 0
[35908,10,15:54:34.773] Subscription 4s5wc08w::d01rxwe6: read checksum 0
[35908,10,15:54:34.773] Subscription l8hyc48p::mrutepus: read checksum 0
[35908,10,15:54:34.773] Subscription fhmsd1vi::lteuvvcf: read checksum 0
[35908,06,15:54:34.797] Created stats stream '$stats-127.0.0.1:2113', code = WrongExpectedVersion
[35908,06,15:54:35.660] publishing checkpoint 0
[35908,06,15:54:35.660] publishing checkpoint 0
[35908,06,15:54:35.660] publishing checkpoint 0
[35908,06,15:54:35.660] publishing checkpoint 0
[35908,06,15:54:35.661] publishing checkpoint 0
[35908,06,15:54:35.661] publishing checkpoint 0
[35908,06,15:54:35.661] publishing checkpoint 0
[35908,06,15:54:35.661] publishing checkpoint 0
[35908,06,15:54:35.661] publishing checkpoint 0
[35908,06,15:54:35.661] publishing checkpoint 0
[35908,06,15:54:35.662] publishing checkpoint 0
[35908,06,15:54:35.662] publishing checkpoint 0
[35908,06,15:54:35.662] publishing checkpoint 0
[35908,06,15:54:35.662] publishing checkpoint 0
[35908,06,15:54:35.662] publishing checkpoint 0
[35908,06,15:54:35.662] publishing checkpoint 0
[35908,10,15:54:35.664] state write successful
[35908,10,15:54:35.664] state write successful
[35908,10,15:54:35.665] state write successful
[35908,10,15:54:35.665] state write successful
[35908,10,15:54:35.665] state write successful
[35908,10,15:54:35.665] state write successful
[35908,10,15:54:35.666] state write successful
[35908,10,15:54:35.666] state write successful
[35908,10,15:54:35.666] state write successful
[35908,10,15:54:35.666] state write successful
[35908,10,15:54:35.666] state write successful
[35908,10,15:54:35.666] state write successful
[35908,10,15:54:35.666] state write successful
[35908,10,15:54:35.666] state write successful
[35908,10,15:54:35.667] state write successful
[35908,10,15:54:35.667] state write successful
Segments count: 1, buffers count: 512, should be when full: 512
[35908,06,15:54:37.224] External TCP connection accepted: [Normal, 127.0.0.1:56411, L127.0.0.1:1113, {e7585bfd-dd66-4977-b369-c1238c1e5356}].
[35908,06,15:54:37.401] create subscription tju1ygge::b0tho0ly
[35908,06,15:54:37.401] New persistent subscription b0tho0ly.
[35908,06,15:54:37.402] Saving Configuration.
[35908,10,15:54:37.404] Subscription tju1ygge::b0tho0ly: read no checksum.
[35908,10,15:54:37.404] strtfrom = 0
[35908,06,15:54:37.664] publishing checkpoint 0
[35908,10,15:54:37.664] state write successful
[35908,09,15:54:42.244] Closing connection 'external-normal' [127.0.0.1:56411, L127.0.0.1:1113, {e7585bfd-dd66-4977-b369-c1238c1e5356}] cleanly. Reason: HEARTBEAT TIMEOUT at msgNum 3
[35908,09,15:54:42.260] ES TcpConnection closed [15:54:42.246: N127.0.0.1:56411, L127.0.0.1:1113, {e7585bfd-dd66-4977-b369-c1238c1e5356}]:Received bytes: 340, Sent bytes: 108
[35908,09,15:54:42.260] ES TcpConnection closed [15:54:42.261: N127.0.0.1:56411, L127.0.0.1:1113, {e7585bfd-dd66-4977-b369-c1238c1e5356}]:Send calls: 4, callbacks: 4
[35908,09,15:54:42.260] ES TcpConnection closed [15:54:42.261: N127.0.0.1:56411, L127.0.0.1:1113, {e7585bfd-dd66-4977-b369-c1238c1e5356}]:Receive calls: 4, callbacks: 3
[35908,09,15:54:42.260] ES TcpConnection closed [15:54:42.261: N127.0.0.1:56411, L127.0.0.1:1113, {e7585bfd-dd66-4977-b369-c1238c1e5356}]:Close reason: [Success] HEARTBEAT TIMEOUT at msgNum 3
[35908,09,15:54:42.267] Connection 'external-normal' [127.0.0.1:56411, {e7585bfd-dd66-4977-b369-c1238c1e5356}] closed: Success.
[35908,06,15:54:42.268] Lost connection from 127.0.0.1:56411

packages.config:

<?xml version="1.0" encoding="utf-8"?>
<packages>
  <package id="EventStore.Client" version="3.3.1" targetFramework="net45" />
  <package id="Newtonsoft.Json" version="7.0.1" targetFramework="net45" />
  <package id="NUnit" version="2.6.4" targetFramework="net45" />
</packages>

What are we doing wrong :'(?

UPDATE:

Also tested mono 3.12.1:

* 68a18ac - mono: update 3.12.1 bottle. (7 months ago) <BrewTestBot>
* 53acd1a - mono 3.12.1 (7 months ago) <Dominyk Tiller>
kinquestion
Source
picture haf

All 10 comments

Connect to persistent subscription should return almost immediately (with a
persistent subscription object). It doesn't wait on a message back from the
server.

One other thing I noticed is you have a heartbeat timeout occurring for
some reason

[35908,09,15:54:42.244] Closing connection 'external-normal'
[127.0.0.1:56411, L127.0.0.1:1113,
{e7585bfd-dd66-4977-b369-c1238c1e5356}] cleanly. Reason: HEARTBEAT
TIMEOUT at msgNum 3

On Tue, Oct 13, 2015 at 4:59 PM, Henrik Feldt [email protected]
wrote:

Hi, we have another test case for you, in the same test fixture as the
previous one... This time it's for persistent subscriptions.

Note how the persistent subscription is created (and how the server lists
all [35908,10,15:54:35.666] state write successful from the previously
created groups, but the call to ConnectToPersistentSubscription never
returns.

    [Test]
    public async Task SubscribeToRandomPersistentSubscription ()
    {
        Console.WriteLine ();
        Console.WriteLine ("Persistent Subscription Test");


        var connSettings =
            ConnectionSettings.Create()
                .UseConsoleLogger ()
                .EnableVerboseLogging()
                .KeepReconnecting ()
                .SetHeartbeatTimeout (TimeSpan.FromSeconds (8))
                .Build ();
        var conn = EventStoreConnection.Create (connSettings, new Uri ("tcp://admin:[email protected]:1113"), "myConn");
        await conn.ConnectAsync ();
        var stream = GenName ();

        Console.WriteLine ("Writing event to {0}", stream);

        var tr = await conn.AppendToStreamAsync (stream, -1, new[] {
            new EventData (Guid.NewGuid (), "myType", true, GenData (), GenData())
        });

        Console.WriteLine ("Wrote event to {0}", stream);

        Assert.That (tr.LogPosition.CommitPosition, Is.GreaterThan (0),
            "Should have written in the log");

        var tcs = new TaskCompletionSource<int> ();
        var count = 0;

        var pss =
            PersistentSubscriptionSettings
                .Create ()
                .StartFromBeginning ()
                .ResolveLinkTos ()
                .CheckPointAfter (TimeSpan.FromSeconds(1))
                .MinimumCheckPointCountOf (1)
                .MaximumCheckPointCountOf (10)
                .Build ();

        var group = GenName ();

        await conn.CreatePersistentSubscriptionAsync (stream, group, pss, new UserCredentials("admin", "changeit"));

        conn.ConnectToPersistentSubscription(
            stream,
            group,
            (sub, evt) => {
                Console.WriteLine ("Got expected event, because this is a persistent subscription with a random group");
                if (Interlocked.Increment (ref count) == 1)
                    tcs.SetResult (1);
                else
                    Assert.That (tcs.TrySetResult (count), Is.False);
            },
            (sub, reason, ex) => Console.WriteLine ("Error: {0}", ex),
            new UserCredentials("admin", "changeit"),
            10,
            true);

        Console.WriteLine ("Awaiting persistent subscription's events");

        Assert.That (await tcs.Task, Is.EqualTo (1),
            "Should receive category subscription");
    }

Output:

➜ EventStoreTests export MONO_THREADS_PER_CPU=120
➜ EventStoreTests mono ../packages/NUnit.Runners.2.6.4/tools/nunit-console.exe bin/Debug/EventStoreTests.dll
WARNING: The runtime version supported by this application is unavailable.
Using default runtime: v4.0.30319
NUnit-Console version 2.6.4.14350
Copyright (C) 2002-2012 Charlie Poole.
Copyright (C) 2002-2004 James W. Newkirk, Michael C. Two, Alexei A. Vorontsov.
Copyright (C) 2000-2002 Philip Craig.
All Rights Reserved.

Runtime Environment -
OS Version: Unix 14.5.0.0
CLR Version: 4.0.30319.17020 ( Mono 4.0 ( 4.2.0 (Stable 4.2.0.179/a224653 Tue Oct 6 11:27:49 PDT 2015) ) )

ProcessModel: Default DomainUsage: Single
Execution Runtime: mono-4.0
.
Persistent Subscription Test
[06,15:54:37.159,DEBUG] EventStoreConnection 'myConn': enqueueing message EventStore.ClientAPI.Internal.StartConnectionMessage..
[08,15:54:37.169,DEBUG] EventStoreConnection 'myConn': StartConnection.
[08,15:54:37.169,DEBUG] EventStoreConnection 'myConn': DiscoverEndPoint.
[09,15:54:37.172,DEBUG] EventStoreConnection 'myConn': enqueueing message EventStore.ClientAPI.Internal.EstablishTcpConnectionMessage..
[08,15:54:37.174,DEBUG] EventStoreConnection 'myConn': EstablishTcpConnection to [127.0.0.1:1113].
Writing event to tju1ygge
[10,15:54:37.209,DEBUG] TcpPackageConnection: connected to [127.0.0.1:1113, L127.0.0.1:56411, {28075de7-a474-4690-94bc-5b63ab9d0bd9}].
[10,15:54:37.209,DEBUG] EventStoreConnection 'myConn': enqueueing message EventStore.ClientAPI.Internal.TcpConnectionEstablishedMessage..
[10,15:54:37.210,DEBUG] EventStoreConnection 'myConn': TCP connection to [127.0.0.1:1113, L127.0.0.1:56411, {28075de7-a474-4690-94bc-5b63ab9d0bd9}] established..
[10,15:54:37.272,DEBUG] EventStoreConnection 'myConn': enqueueing message EventStore.ClientAPI.Internal.HandleTcpPackageMessage..
[08,15:54:37.279,DEBUG] EventStoreConnection 'myConn': HandleTcpPackage connId 28075de7-a474-4690-94bc-5b63ab9d0bd9, package Authenticated, 9ccdcbdd-7eae-43da-8512-3073616149a0..
[09,15:54:37.285,DEBUG] EventStoreConnection 'myConn': enqueueing message EventStore.ClientAPI.Internal.StartOperationMessage..
[08,15:54:37.287,DEBUG] EventStoreConnection 'myConn': StartOperation schedule AppendToStreamOperation, Stream: tju1ygge, ExpectedVersion: -1, 10, 00:00:07..
[08,15:54:37.331,DEBUG] EventStoreConnection 'myConn': ScheduleOperation package WriteEvents, c7a1fc04-8de6-4402-9fbe-9348a9db1158, Operation AppendToStreamOperation (c7a1fc04-8de6-4402-9fbe-9348a9db1158): Stream: tju1ygge, ExpectedVersion: -1, retry count: 0, created: 15:54:37.287, last updated: 15:54:37.288..
[10,15:54:37.379,DEBUG] EventStoreConnection 'myConn': enqueueing message EventStore.ClientAPI.Internal.HandleTcpPackageMessage..
[10,15:54:37.379,DEBUG] EventStoreConnection 'myConn': HandleTcpPackage connId 28075de7-a474-4690-94bc-5b63ab9d0bd9, package WriteEventsCompleted, c7a1fc04-8de6-4402-9fbe-9348a9db1158..
Wrote event to tju1ygge
[10,15:54:37.393,DEBUG] EventStoreConnection 'myConn': enqueueing message EventStore.ClientAPI.Internal.StartOperationMessage..
[10,15:54:37.393,DEBUG] EventStoreConnection 'myConn': HandleTcpPackage OPERATION DECISION EndOperation (Success), Operation AppendToStreamOperation (c7a1fc04-8de6-4402-9fbe-9348a9db1158): Stream: tju1ygge, ExpectedVersion: -1, retry count: 0, created: 15:54:37.287, last updated: 15:54:37.288.
[10,15:54:37.394,DEBUG] EventStoreConnection 'myConn': RemoveOperation SUCCEEDED for Operation AppendToStreamOperation (c7a1fc04-8de6-4402-9fbe-9348a9db1158): Stream: tju1ygge, ExpectedVersion: -1, retry count: 0, created: 15:54:37.287, last updated: 15:54:37.288.
[10,15:54:37.394,DEBUG] EventStoreConnection 'myConn': StartOperation schedule CreatePersistentSubscriptionOperation, Stream: tju1ygge, Group Name: b0tho0ly, 10, 00:00:07..
[10,15:54:37.397,DEBUG] EventStoreConnection 'myConn': ScheduleOperation package CreatePersistentSubscription, e3c4a69d-2736-475e-bc5a-84faf7d6cffa, Operation CreatePersistentSubscriptionOperation (e3c4a69d-2736-475e-bc5a-84faf7d6cffa): Stream: tju1ygge, Group Name: b0tho0ly, retry count: 0, created: 15:54:37.394, last updated: 15:54:37.394..
[09,15:54:37.407,DEBUG] EventStoreConnection 'myConn': enqueueing message EventStore.ClientAPI.Internal.HandleTcpPackageMessage..
[09,15:54:37.407,DEBUG] EventStoreConnection 'myConn': HandleTcpPackage connId 28075de7-a474-4690-94bc-5b63ab9d0bd9, package CreatePersistentSubscriptionCompleted, e3c4a69d-2736-475e-bc5a-84faf7d6cffa..
[09,15:54:37.411,DEBUG] EventStoreConnection 'myConn': enqueueing message EventStore.ClientAPI.Internal.StartPersistentSubscriptionMessage..
[10,15:54:41.228,DEBUG] EventStoreConnection 'myConn': enqueueing message EventStore.ClientAPI.Internal.HandleTcpPackageMessage..
[10,15:54:42.267,INFO] ClientAPI TcpConnection closed [15:54:42.267: N127.0.0.1:1113, L127.0.0.1:56411, {28075de7-a474-4690-94bc-5b63ab9d0bd9}]:
Received bytes: 108, Sent bytes: 340
Send calls: 3, callbacks: 3
Receive calls: 5, callbacks: 5
Close reason: [Success] Socket closed

[10,15:54:42.269,DEBUG] TcpPackageConnection: connection [127.0.0.1:1113, L127.0.0.1:56411, {28075de7-a474-4690-94bc-5b63ab9d0bd9}] was closed cleanly.
[10,15:54:42.269,DEBUG] EventStoreConnection 'myConn': enqueueing message EventStore.ClientAPI.Internal.TcpConnectionClosedMessage..

EventStore Server logs:

➜ EventStore-OSS-MacOSX-v3.3.0 ./run-node.sh --run-projections=all
[35908,01,15:54:33.900]
ES VERSION: 0.0.0.0 (release-v3.3.0/4923f4c0f427a85a275f362402e62645bca38c07, Wed, 7 Oct 2015 07:37:39 +0200)
OS: MacOS (Unix 14.5.0.0)
RUNTIME: 3.12.1 (tarball) (64-bit)
GC: 2 GENERATIONS
LOGS: /Users/h/Downloads/EventStore-OSS-MacOSX-v3.3.0/logs

MODIFIED OPTIONS:

RUN PROJECTIONS:          all (Command Line)

DEFAULT OPTIONS:

HELP:                     False (<DEFAULT>)
VERSION:                  False (<DEFAULT>)
LOG:                      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>)
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>)
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>)
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>)
CHUNKS CACHE SIZE:        536871424 (<DEFAULT>)
MAX MEM TABLE SIZE:       1000000 (<DEFAULT>)
DB:                       data (<DEFAULT>)
MEM DB:                   False (<DEFAULT>)
SKIP DB VERIFY:           False (<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>)
SSL TARGET HOST:          n/a (<DEFAULT>)
SSL VALIDATE SERVER:      True (<DEFAULT>)
AUTHENTICATION TYPE:      internal (<DEFAULT>)
PREPARE TIMEOUT MS:       2000 (<DEFAULT>)
COMMIT TIMEOUT MS:        2000 (<DEFAULT>)
UNSAFE DISABLE FLUSH TO DISK: 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>)

[35908,01,15:54:33.926] Quorum size set to 1
[35908,01,15:54:33.932] Cannot find plugins path: plugins
[35908,01,15:54:33.955] INSTANCE ID: 9c0282dc-7fa3-4e61-b4d3-db5be478f1fc
[35908,01,15:54:33.956] DATABASE: data
[35908,01,15:54:33.956] WRITER CHECKPOINT: 27152083 (0x19E4ED3)
[35908,01,15:54:33.957] CHASER CHECKPOINT: 27152083 (0x19E4ED3)
[35908,01,15:54:33.957] EPOCH CHECKPOINT: 27121344 (0x19DD6C0)
[35908,01,15:54:33.957] TRUNCATE CHECKPOINT: -1 (0xFFFFFFFFFFFFFFFF)
[35908,01,15:54:34.085] MessageHierarchy initialization took 00:00:00.0944664.
[35908,01,15:54:34.288] CACHED TFChunk #0-0 (chunk-000000.000000) in 00:00:00.0180752.
[35908,01,15:54:34.452] Starting MiniWeb for /web/es/js/projections ==> projections
[35908,01,15:54:34.452] Starting MiniWeb for /web/es/js/projections/v8/Prelude ==> Prelude
[35908,01,15:54:34.453] Binding MiniWeb to /web/es/js/projections/{_remaining_path}
[35908,01,15:54:34.453] Binding MiniWeb to /web/es/js/projections/v8/Prelude/{_remaining_path}
[35908,01,15:54:34.464] Starting MiniWeb for /web ==> clusternode-web
[35908,01,15:54:34.464] Binding MiniWeb to /web/{*remaining_path}
[35908,10,15:54:34.480] ========== [127.0.0.1:2112] SYSTEM INIT...
[35908,10,15:54:34.498] Starting Normal TCP listening on TCP endpoint: 127.0.0.1:1113.
[35908,15,15:54:34.514] TableIndex initialization...
[35908,15,15:54:34.521] ReadIndex building...
[35908,10,15:54:34.539] Starting HTTP server on [http://127.0.0.1:2113/,http://localhost:2113/]...
[35908,10,15:54:34.543] HTTP server is up and listening on [http://127.0.0.1:2113/,http://localhost:2113/]
[35908,10,15:54:34.566] SLOW QUEUE MSG [MainQueue]: SystemInit - 78ms. Q: 0/503.
[35908,10,15:54:34.566] ========== [127.0.0.1:2112] Service 'StorageReader' initialized.
[35908,10,15:54:34.566] ========== [127.0.0.1:2112] Service 'StorageWriter' initialized.
[35908,15,15:54:34.568] ReadIndex rebuilding done: total processed 2422 records, time elapsed: 00:00:00.0474060.
[35908,10,15:54:34.573] ========== [127.0.0.1:2112] Service 'StorageChaser' initialized.
[35908,10,15:54:34.573] ========== [127.0.0.1:2112] SYSTEM START...
[35908,10,15:54:34.575] ========== [127.0.0.1:2112] IS UNKNOWN...
[35908,06,15:54:34.591] Subscriptions received state change to Unknown stopping listening.
[35908,10,15:54:34.610] ELECTIONS: STARTING ELECTIONS.
[35908,10,15:54:34.611] ELECTIONS: (V=0) SHIFT TO LEADER ELECTION.
[35908,10,15:54:34.611] ELECTIONS: (V=0) VIEWCHANGE FROM [127.0.0.1:2112, {9c0282dc-7fa3-4e61-b4d3-db5be478f1fc}].
[35908,10,15:54:34.612] ELECTIONS: (V=0) MAJORITY OF VIEWCHANGE.
[35908,10,15:54:34.612] ELECTIONS: (V=0) SHIFT TO PREPARE PHASE.
[35908,10,15:54:34.613] ELECTIONS: (V=0) PREPARE_OK FROM 127.0.0.1:2112,{9c0282dc-7fa3-4e61-b4d3-db5be478f1fc}.
[35908,10,15:54:34.613] ELECTIONS: (V=0) SHIFT TO REG_LEADER.
[35908,10,15:54:34.618] ELECTIONS: (V=0) SENDING PROPOSAL CANDIDATE: 127.0.0.1:2112,{9c0282dc-7fa3-4e61-b4d3-db5be478f1fc}, ME: 127.0.0.1:2112,{9c0282dc-7fa3-4e61-b4d3-db5be478f1fc}.
[35908,10,15:54:34.618] ELECTIONS: (V=0) ACCEPT FROM [127.0.0.1:2112,{9c0282dc-7fa3-4e61-b4d3-db5be478f1fc}] M=[127.0.0.1:2112,{9c0282dc-7fa3-4e61-b4d3-db5be478f1fc}]).
[35908,10,15:54:34.620] ELECTIONS: (V=0) DONE. ELECTED MASTER = 127.0.0.1:2112,{9c0282dc-7fa3-4e61-b4d3-db5be478f1fc}. ME=127.0.0.1:2112,{9c0282dc-7fa3-4e61-b4d3-db5be478f1fc}.
[35908,10,15:54:34.622] ========== [127.0.0.1:2112] PRE-MASTER STATE, WAITING FOR CHASER TO CATCH UP...
[35908,10,15:54:34.627] ========== [127.0.0.1:2112] IS MASTER... SPARTA!
[35908,06,15:54:34.632] Subscriptions received state change to PreMaster stopping listening.
[35908,06,15:54:34.633] Subscriptions Became Master so now handling subscriptions
[35908,11,15:54:34.729] SLOW BUS MSG [manager input bus]: Starting - 50ms. Handler: ProjectionManagerResponseReader.
[35908,10,15:54:34.729] SLOW BUS MSG [MainBus]: ReadStreamEventsBackwardCompleted - 57ms. Handler: RequestResponseDispatcher`2.
[35908,11,15:54:34.729] SLOW QUEUE MSG [Projections Master]: Starting - 100ms. Q: 0/1.
[35908,10,15:54:34.729] SLOW QUEUE MSG [MainQueue]: ReadStreamEventsBackwardCompleted - 61ms. Q: 0/27.
[35908,08,15:54:34.752] === Writing E10@27152083:{9d4864fb-c46e-4104-a2e5-50d1bc4c571b} (previous epoch at 27121344).
[35908,08,15:54:34.754] === Update Last Epoch E10@27152083:{9d4864fb-c46e-4104-a2e5-50d1bc4c571b} (previous epoch at 27121344).
[35908,10,15:54:34.770] Subscription p8wm1ucv::271kqj51: read checksum 0
[35908,10,15:54:34.770] Subscription kagvzvbq::8kg4lxbb: read checksum 0
[35908,10,15:54:34.771] Subscription glo1ahst::j7fl0kss: read checksum 0
[35908,10,15:54:34.771] Subscription hz4rg7zg::higtwpjl: read checksum 0
[35908,10,15:54:34.771] Subscription wi69r4hz::huzeb9mn: read checksum 0
[35908,10,15:54:34.771] Subscription kvrrojcr::5grxde1g: read checksum 0
[35908,10,15:54:34.771] Subscription xiqqbk32::0ks1nb93: read checksum 0
[35908,10,15:54:34.772] Subscription kxkur37f::o5mu7y1b: read checksum 0
[35908,10,15:54:34.772] Subscription udbe28yw::c2a97d5o: read checksum 0
[35908,10,15:54:34.772] Subscription 8regpabd::ql6bid2x: read checksum 0
[35908,10,15:54:34.772] Subscription 36utbg8t::s7ddlhxf: read checksum 0
[35908,10,15:54:34.772] Subscription ujgvqnc1::xwqjpong: read checksum 0
[35908,10,15:54:34.772] Subscription 5ctnl2om::hgivnl3v: read checksum 0
[35908,10,15:54:34.773] Subscription 4s5wc08w::d01rxwe6: read checksum 0
[35908,10,15:54:34.773] Subscription l8hyc48p::mrutepus: read checksum 0
[35908,10,15:54:34.773] Subscription fhmsd1vi::lteuvvcf: read checksum 0
[35908,06,15:54:34.797] Created stats stream '$stats-127.0.0.1:2113', code = WrongExpectedVersion
[35908,06,15:54:35.660] publishing checkpoint 0
[35908,06,15:54:35.660] publishing checkpoint 0
[35908,06,15:54:35.660] publishing checkpoint 0
[35908,06,15:54:35.660] publishing checkpoint 0
[35908,06,15:54:35.661] publishing checkpoint 0
[35908,06,15:54:35.661] publishing checkpoint 0
[35908,06,15:54:35.661] publishing checkpoint 0
[35908,06,15:54:35.661] publishing checkpoint 0
[35908,06,15:54:35.661] publishing checkpoint 0
[35908,06,15:54:35.661] publishing checkpoint 0
[35908,06,15:54:35.662] publishing checkpoint 0
[35908,06,15:54:35.662] publishing checkpoint 0
[35908,06,15:54:35.662] publishing checkpoint 0
[35908,06,15:54:35.662] publishing checkpoint 0
[35908,06,15:54:35.662] publishing checkpoint 0
[35908,06,15:54:35.662] publishing checkpoint 0
[35908,10,15:54:35.664] state write successful
[35908,10,15:54:35.664] state write successful
[35908,10,15:54:35.665] state write successful
[35908,10,15:54:35.665] state write successful
[35908,10,15:54:35.665] state write successful
[35908,10,15:54:35.665] state write successful
[35908,10,15:54:35.666] state write successful
[35908,10,15:54:35.666] state write successful
[35908,10,15:54:35.666] state write successful
[35908,10,15:54:35.666] state write successful
[35908,10,15:54:35.666] state write successful
[35908,10,15:54:35.666] state write successful
[35908,10,15:54:35.666] state write successful
[35908,10,15:54:35.666] state write successful
[35908,10,15:54:35.667] state write successful
[35908,10,15:54:35.667] state write successful
Segments count: 1, buffers count: 512, should be when full: 512
[35908,06,15:54:37.224] External TCP connection accepted: [Normal, 127.0.0.1:56411, L127.0.0.1:1113, {e7585bfd-dd66-4977-b369-c1238c1e5356}].
[35908,06,15:54:37.401] create subscription tju1ygge::b0tho0ly
[35908,06,15:54:37.401] New persistent subscription b0tho0ly.
[35908,06,15:54:37.402] Saving Configuration.
[35908,10,15:54:37.404] Subscription tju1ygge::b0tho0ly: read no checksum.
[35908,10,15:54:37.404] strtfrom = 0
[35908,06,15:54:37.664] publishing checkpoint 0
[35908,10,15:54:37.664] state write successful
[35908,09,15:54:42.244] Closing connection 'external-normal' [127.0.0.1:56411, L127.0.0.1:1113, {e7585bfd-dd66-4977-b369-c1238c1e5356}] cleanly. Reason: HEARTBEAT TIMEOUT at msgNum 3
[35908,09,15:54:42.260] ES TcpConnection closed [15:54:42.246: N127.0.0.1:56411, L127.0.0.1:1113, {e7585bfd-dd66-4977-b369-c1238c1e5356}]:Received bytes: 340, Sent bytes: 108
[35908,09,15:54:42.260] ES TcpConnection closed [15:54:42.261: N127.0.0.1:56411, L127.0.0.1:1113, {e7585bfd-dd66-4977-b369-c1238c1e5356}]:Send calls: 4, callbacks: 4
[35908,09,15:54:42.260] ES TcpConnection closed [15:54:42.261: N127.0.0.1:56411, L127.0.0.1:1113, {e7585bfd-dd66-4977-b369-c1238c1e5356}]:Receive calls: 4, callbacks: 3
[35908,09,15:54:42.260] ES TcpConnection closed [15:54:42.261: N127.0.0.1:56411, L127.0.0.1:1113, {e7585bfd-dd66-4977-b369-c1238c1e5356}]:Close reason: [Success] HEARTBEAT TIMEOUT at msgNum 3
[35908,09,15:54:42.267] Connection 'external-normal' [127.0.0.1:56411, {e7585bfd-dd66-4977-b369-c1238c1e5356}] closed: Success.
[35908,06,15:54:42.268] Lost connection from 127.0.0.1:56411

packages.config:






What are we doing wrong :'(?

—
Reply to this email directly or view it on GitHub
https://github.com/EventStore/EventStore/issues/726.

Studying for the Turing test

gregoryyoung picture gregoryyoung on 13 Oct 2015

@haf
I do believe that it's a similar issue to the one we spoke about in https://github.com/EventStore/EventStore/issues/712

Does changing async Task to async void make the test pass?

pgermishuys picture pgermishuys on 13 Oct 2015

Yes, it does, but this time, I'm not using anything that blocks. So we have this problem in our app code, too.

haf picture haf on 13 Oct 2015

So the question becomes how to use the library if calling it will block the caller. What execution context should I call from or what invariant need to be there that I don't know about? And that's assuming you want to force your users to know about execution context, of course...

haf picture haf on 14 Oct 2015

Ok, so I have given birth to a bastard son of a workaround.
Do you have any plans for when I can get rid of him?

lapponiandevil picture lapponiandevil on 21 Oct 2015
👍1

A new async method, ConnectToPersistentSubscriptionAsync, was introduced in version 3.6.0
Using this should resolve the blocking issues we see in the above test case

hayley-jean picture hayley-jean on 13 May 2016

@lapponiandevil @haf mind giving us a quick heads up whether the method @hayley-jean mentioned works for you. If not, let's start talking about how to best resolve the issue you are experiencing.

pgermishuys picture pgermishuys on 23 May 2016

If you've fixed your threading bug then it probably works. We're currently running the workaround, as it was a lot of time since this was current work in progress for us.

It should be said that 3.6.1 fixed a lot of persistent subscription problems we had been having.

Let's ask the opposite question though: did you ever test the repro we gave you and did that fix the issue?

haf picture haf on 23 May 2016

@haf we did test the fix with by replacing conn.ConnectToPersistentSubscription with await conn.ConnectToPersistentSubscriptionAsync.

pgermishuys picture pgermishuys on 23 May 2016

Then I think this is a solved issue 👍

haf picture haf on 23 May 2016
😄1
Was this page helpful?
0 / 5 - 0 ratings

Related issues

puco picture puco  ·  7Comments
hayley-jean picture hayley-jean  ·  9Comments
Narvalex picture Narvalex  ·  6Comments
m-jepson picture m-jepson  ·  11Comments
AbdoDabbas picture AbdoDabbas  ·  6Comments