Live-only subscription produces heartbeat timeout

[srogovtsev]

I am trying to write a simple proof-of-concept with Event Store. The code follows:

var settings = ConnectionSettings.Create()
    .UseConsoleLogger()
    .KeepReconnecting()
    .KeepRetrying()
    .WithConnectionTimeoutOf(TimeSpan.FromSeconds(10))
    .SetReconnectionDelayTo(TimeSpan.FromMilliseconds(0))
    .FailOnNoServerResponse()
    .Build();

using (var c = EventStoreConnection.Create(settings, new IPEndPoint(IPAddress.Loopback, 1113)))
{
    await c.ConnectAsync().ConfigureAwait(false);

    //c.SubscribeToStreamFrom("$ce-httpSession", null, true, (ss, er) =>
    //{
    //Console.WriteLine("{0} {1}", er.Event.EventType, er.Event.EventId);
    //}, s => {Console.Write("live");});

    await c.SubscribeToStreamAsync("$ce-httpSession", true, (ss, er) =>
    {
        Console.WriteLine("{0} {1}", er.Event.EventType, er.Event.EventId);
    }).ConfigureAwait(false);

    var cts = new CancellationTokenSource();
    Task.Factory.StartNew(() => EventProducer(c), cts.Token);
    Console.WriteLine("Press Enter to stop.");
    Console.ReadLine();
    cts.Cancel();
}

(The code inside EventProducer just produces some random events that I want to work on.)

When there's no subscription, everything works.
When I use catch-up subscription (code commented), everything works, even after the subscription switches from catch-up to live mode.

When I try using live-only subscription (uncommented), EventStoreConnection closes abruptly.

Here's client log:

[03,07:48:29.505,DEBUG] TcpPackageConnection: connected to [127.0.0.1:1113, L127.0.0.1:63046, {cfe5e213-404c-4256-a492-2b87b0cb893d}].
Press Enter to stop.
Processing session cc4d0856-e1ce-e311-be8b-50e5493f01a4
[08,07:48:34.507,INFO] ClientAPI TcpConnection closed [07:48:34.507: N127.0.0.1:1113, L127.0.0.1:63046, {cfe5e213-404c-4256-a492-2b87b0cb893d}]:
Received bytes: 74, Sent bytes: 63
Send calls: 2, callbacks: 2
Receive calls: 4, callbacks: 4
Close reason: [Success] Socket closed

[08,07:48:34.509,DEBUG] TcpPackageConnection: connection [127.0.0.1:1113, L127.0.0.1:63046, {cfe5e213-404c-4256-a492-2b87b0cb893d}] was closed cleanly.

If I try debugging I see that connection closes during first attempt to publish an event to store (inside EventProducer), event never gets published, the control just never leaves AppendToStreamAsync). The code for that is simplistic:

Console.WriteLine("Processing session " + session.Id);
await eventStoreConnection
    .AppendToStreamAsync(GetStreamId(session), ExpectedVersion.Any, new EventData(session.Id, "httpSessionStart", false, null, null))
    .ConfigureAwait(false);

Here's corresponding server part of log:

[17804,25,07:48:29.500] External TCP connection accepted: [Normal, 127.0.0.1:63046, L127.0.0.1:1113, {de078bd1-7326-417c-a98e-7056db66ce9c}].
[17804,11,07:48:34.503] Closing connection 'external-normal' [127.0.0.1:63046, L127.0.0.1:1113, {de078bd1-7326-417c-a98e-7056db66ce9c}] cleanly. Reason: HEARTBEAT TIMEOUT at msgNum 2
[17804,11,07:48:34.503] ES TcpConnection closed [07:48:34.503: N127.0.0.1:63046, L127.0.0.1:1113, {de078bd1-7326-417c-a98e-7056db66ce9c}]:
Received bytes: 63, Sent bytes: 74
Send calls: 3, callbacks: 3
Receive calls: 3, callbacks: 2
Close reason: [Success] HEARTBEAT TIMEOUT at msgNum 2

[17804,11,07:48:34.503] Connection 'external-normal' [127.0.0.1:63046, {de078bd1-7326-417c-a98e-7056db66ce9c}] closed: Success.

I am using latest stable build (3.0.3).

[gregoryyoung]

This is a heartbeat timeout.

Are you by chance hitting a breakpoint in your debugger? This causes it.
Iirc as you haven't set timeouts the default is 500ms

On Saturday, March 21, 2015, Serg Rogovtsev notifications@github.com
wrote:

I am trying to write a simple proof-of-concept with Event Store. The code
follows:

var settings = ConnectionSettings.Create()
.UseConsoleLogger()
.KeepReconnecting()
.KeepRetrying()
.WithConnectionTimeoutOf(TimeSpan.FromSeconds(10))
.SetReconnectionDelayTo(TimeSpan.FromMilliseconds(0))
.FailOnNoServerResponse()
.Build();

using (var c = EventStoreConnection.Create(settings, new IPEndPoint(IPAddress.Loopback, 1113)))
{
await c.ConnectAsync().ConfigureAwait(false);

//c.SubscribeToStreamFrom("$ce-httpSession", null, true, (ss, er) =>
//{
//Console.WriteLine("{0} {1}", er.Event.EventType, er.Event.EventId);
//}, s => {Console.Write("live");});

await c.SubscribeToStreamAsync("$ce-httpSession", true, (ss, er) =>
{
    Console.WriteLine("{0} {1}", er.Event.EventType, er.Event.EventId);
}).ConfigureAwait(false);

var cts = new CancellationTokenSource();
Task.Factory.StartNew(() => EventProducer(c), cts.Token);
Console.WriteLine("Press Enter to stop.");
Console.ReadLine();
cts.Cancel();

}

(The code inside EventProducer just produces some random events that I
want to work on.)

When there's no subscription, everything works.
When I use catch-up subscription (code commented), everything works, even
after the subscription switches from catch-up to live mode.

When I try using live-only subscription (uncommented),
EventStoreConnection closes abruptly.

Here's client log:

[03,07:48:29.505,DEBUG] TcpPackageConnection: connected to [127.0.0.1:1113, L127.0.0.1:63046, {cfe5e213-404c-4256-a492-2b87b0cb893d}].
Press Enter to stop.
Processing session cc4d0856-e1ce-e311-be8b-50e5493f01a4
[08,07:48:34.507,INFO] ClientAPI TcpConnection closed [07:48:34.507: N127.0.0.1:1113, L127.0.0.1:63046, {cfe5e213-404c-4256-a492-2b87b0cb893d}]:
Received bytes: 74, Sent bytes: 63
Send calls: 2, callbacks: 2
Receive calls: 4, callbacks: 4
Close reason: [Success] Socket closed

[08,07:48:34.509,DEBUG] TcpPackageConnection: connection [127.0.0.1:1113,
L127.0.0.1:63046, {cfe5e213-404c-4256-a492-2b87b0cb893d}] was closed
cleanly.

If I try debugging I see that connection closes during first attempt to
publish an event to store (inside EventProducer), event never gets
published, the control just never leaves AppendToStreamAsync). The code
for that is simplistic:

Console.WriteLine("Processing session " + session.Id);
await eventStoreConnection
.AppendToStreamAsync(GetStreamId(session), ExpectedVersion.Any, new EventData(session.Id, "httpSessionStart", false, null, null))
.ConfigureAwait(false);

Here's corresponding server part of log:

[17804,25,07:48:29.500] External TCP connection accepted: [Normal, 127.0.0.1:63046, L127.0.0.1:1113, {de078bd1-7326-417c-a98e-7056db66ce9c}].
[17804,11,07:48:34.503] Closing connection 'external-normal' [127.0.0.1:63046, L127.0.0.1:1113, {de078bd1-7326-417c-a98e-7056db66ce9c}] cleanly. Reason: HEARTBEAT TIMEOUT at msgNum 2
[17804,11,07:48:34.503] ES TcpConnection closed [07:48:34.503: N127.0.0.1:63046, L127.0.0.1:1113, {de078bd1-7326-417c-a98e-7056db66ce9c}]:
Received bytes: 63, Sent bytes: 74
Send calls: 3, callbacks: 3
Receive calls: 3, callbacks: 2
Close reason: [Success] HEARTBEAT TIMEOUT at msgNum 2

[17804,11,07:48:34.503] Connection 'external-normal' [127.0.0.1:63046, {de078bd1-7326-417c-a98e-7056db66ce9c}] closed: Success.

—
Reply to this email directly or view it on GitHub
#425.

Studying for the Turing test

[srogovtsev]

Where do I have to increase them - on server side, or on client side? I
tried increasing (on both, in fact) to 15000, nothing changed. But I am
ready to give it a try.

And why doesn't catch-up subscription produce them?

On Sat, Mar 21, 2015 at 1:09 PM, Greg Young notifications@github.com
wrote:

This is a heartbeat timeout.

Are you by chance hitting a breakpoint in your debugger? This causes it.
Iirc as you haven't set timeouts the default is 500ms

On Saturday, March 21, 2015, Serg Rogovtsev notifications@github.com
wrote:

I am trying to write a simple proof-of-concept with Event Store. The code
follows:

var settings = ConnectionSettings.Create()
.UseConsoleLogger()
.KeepReconnecting()
.KeepRetrying()
.WithConnectionTimeoutOf(TimeSpan.FromSeconds(10))
.SetReconnectionDelayTo(TimeSpan.FromMilliseconds(0))
.FailOnNoServerResponse()
.Build();

using (var c = EventStoreConnection.Create(settings, new
IPEndPoint(IPAddress.Loopback, 1113)))
{
await c.ConnectAsync().ConfigureAwait(false);

//c.SubscribeToStreamFrom("$ce-httpSession", null, true, (ss, er) =>
//{
//Console.WriteLine("{0} {1}", er.Event.EventType, er.Event.EventId);
//}, s => {Console.Write("live");});

await c.SubscribeToStreamAsync("$ce-httpSession", true, (ss, er) =>
{
Console.WriteLine("{0} {1}", er.Event.EventType, er.Event.EventId);
}).ConfigureAwait(false);

var cts = new CancellationTokenSource();
Task.Factory.StartNew(() => EventProducer(c), cts.Token);
Console.WriteLine("Press Enter to stop.");
Console.ReadLine();
cts.Cancel();
}

(The code inside EventProducer just produces some random events that I
want to work on.)

When there's no subscription, everything works.
When I use catch-up subscription (code commented), everything works, even
after the subscription switches from catch-up to live mode.

When I try using live-only subscription (uncommented),
EventStoreConnection closes abruptly.

Here's client log:

[03,07:48:29.505,DEBUG] TcpPackageConnection: connected to [
127.0.0.1:1113, L127.0.0.1:63046, {cfe5e213-404c-4256-a492-2b87b0cb893d}].
Press Enter to stop.
Processing session cc4d0856-e1ce-e311-be8b-50e5493f01a4
[08,07:48:34.507,INFO] ClientAPI TcpConnection closed [07:48:34.507:
N127.0.0.1:1113, L127.0.0.1:63046, {cfe5e213-404c-4256-a492-2b87b0cb893d}]:
Received bytes: 74, Sent bytes: 63
Send calls: 2, callbacks: 2
Receive calls: 4, callbacks: 4
Close reason: [Success] Socket closed

[08,07:48:34.509,DEBUG] TcpPackageConnection: connection [127.0.0.1:1113
,
L127.0.0.1:63046, {cfe5e213-404c-4256-a492-2b87b0cb893d}] was closed
cleanly.

If I try debugging I see that connection closes during first attempt to
publish an event to store (inside EventProducer), event never gets
published, the control just never leaves AppendToStreamAsync). The code
for that is simplistic:

Console.WriteLine("Processing session " + session.Id);
await eventStoreConnection
.AppendToStreamAsync(GetStreamId(session), ExpectedVersion.Any, new
EventData(session.Id, "httpSessionStart", false, null, null))
.ConfigureAwait(false);

Here's corresponding server part of log:

[17804,25,07:48:29.500] External TCP connection accepted: [Normal,
127.0.0.1:63046, L127.0.0.1:1113, {de078bd1-7326-417c-a98e-7056db66ce9c}].
[17804,11,07:48:34.503] Closing connection 'external-normal' [
127.0.0.1:63046, L127.0.0.1:1113, {de078bd1-7326-417c-a98e-7056db66ce9c}]
cleanly. Reason: HEARTBEAT TIMEOUT at msgNum 2
[17804,11,07:48:34.503] ES TcpConnection closed [07:48:34.503:
N127.0.0.1:63046, L127.0.0.1:1113, {de078bd1-7326-417c-a98e-7056db66ce9c}]:
Received bytes: 63, Sent bytes: 74
Send calls: 3, callbacks: 3
Receive calls: 3, callbacks: 2
Close reason: [Success] HEARTBEAT TIMEOUT at msgNum 2

[17804,11,07:48:34.503] Connection 'external-normal' [127.0.0.1:63046,
{de078bd1-7326-417c-a98e-7056db66ce9c}] closed: Success.

—
Reply to this email directly or view it on GitHub
#425.

Studying for the Turing test

—
Reply to this email directly or view it on GitHub
#425 (comment)
.

[gregoryyoung]

They are produced on the connection not by a subscription. Are you hitting
a breakpoint?

Basically a heartbeat timeout is if you have not sent me a message in x
then a message is sent ping to which you should respond pong. If you don't
you are assumed to be dead.

On Saturday, March 21, 2015, Serg Rogovtsev notifications@github.com
wrote:

Where do I have to increase them - on server side, or on client side? I
tried increasing (on both, in fact) to 15000, nothing changed. But I am
ready to give it a try.

And why doesn't catch-up subscription produce them?

On Sat, Mar 21, 2015 at 1:09 PM, Greg Young <notifications@github.com
javascript:_e(%7B%7D,'cvml','notifications@github.com');>
wrote:

This is a heartbeat timeout.

Are you by chance hitting a breakpoint in your debugger? This causes it.
Iirc as you haven't set timeouts the default is 500ms

On Saturday, March 21, 2015, Serg Rogovtsev <notifications@github.com
javascript:_e(%7B%7D,'cvml','notifications@github.com');>
wrote:

I am trying to write a simple proof-of-concept with Event Store. The
code
follows:

var settings = ConnectionSettings.Create()
.UseConsoleLogger()
.KeepReconnecting()
.KeepRetrying()
.WithConnectionTimeoutOf(TimeSpan.FromSeconds(10))
.SetReconnectionDelayTo(TimeSpan.FromMilliseconds(0))
.FailOnNoServerResponse()
.Build();

using (var c = EventStoreConnection.Create(settings, new
IPEndPoint(IPAddress.Loopback, 1113)))
{
await c.ConnectAsync().ConfigureAwait(false);

//c.SubscribeToStreamFrom("$ce-httpSession", null, true, (ss, er) =>
//{
//Console.WriteLine("{0} {1}", er.Event.EventType, er.Event.EventId);
//}, s => {Console.Write("live");});

await c.SubscribeToStreamAsync("$ce-httpSession", true, (ss, er) =>
{
Console.WriteLine("{0} {1}", er.Event.EventType, er.Event.EventId);
}).ConfigureAwait(false);

var cts = new CancellationTokenSource();
Task.Factory.StartNew(() => EventProducer(c), cts.Token);
Console.WriteLine("Press Enter to stop.");
Console.ReadLine();
cts.Cancel();
}

(The code inside EventProducer just produces some random events that I
want to work on.)

When there's no subscription, everything works.
When I use catch-up subscription (code commented), everything works,
even
after the subscription switches from catch-up to live mode.

When I try using live-only subscription (uncommented),
EventStoreConnection closes abruptly.

Here's client log:

[03,07:48:29.505,DEBUG] TcpPackageConnection: connected to [
127.0.0.1:1113, L127.0.0.1:63046,
{cfe5e213-404c-4256-a492-2b87b0cb893d}].
Press Enter to stop.
Processing session cc4d0856-e1ce-e311-be8b-50e5493f01a4
[08,07:48:34.507,INFO] ClientAPI TcpConnection closed [07:48:34.507:
N127.0.0.1:1113, L127.0.0.1:63046,
{cfe5e213-404c-4256-a492-2b87b0cb893d}]:
Received bytes: 74, Sent bytes: 63
Send calls: 2, callbacks: 2
Receive calls: 4, callbacks: 4
Close reason: [Success] Socket closed

[08,07:48:34.509,DEBUG] TcpPackageConnection: connection [
127.0.0.1:1113
,
L127.0.0.1:63046, {cfe5e213-404c-4256-a492-2b87b0cb893d}] was closed
cleanly.

If I try debugging I see that connection closes during first attempt to
publish an event to store (inside EventProducer), event never gets
published, the control just never leaves AppendToStreamAsync). The code
for that is simplistic:

Console.WriteLine("Processing session " + session.Id);
await eventStoreConnection
.AppendToStreamAsync(GetStreamId(session), ExpectedVersion.Any, new
EventData(session.Id, "httpSessionStart", false, null, null))
.ConfigureAwait(false);

Here's corresponding server part of log:

[17804,25,07:48:29.500] External TCP connection accepted: [Normal,
127.0.0.1:63046, L127.0.0.1:1113,
{de078bd1-7326-417c-a98e-7056db66ce9c}].
[17804,11,07:48:34.503] Closing connection 'external-normal' [
127.0.0.1:63046, L127.0.0.1:1113,
{de078bd1-7326-417c-a98e-7056db66ce9c}]
cleanly. Reason: HEARTBEAT TIMEOUT at msgNum 2
[17804,11,07:48:34.503] ES TcpConnection closed [07:48:34.503:
N127.0.0.1:63046, L127.0.0.1:1113,
{de078bd1-7326-417c-a98e-7056db66ce9c}]:
Received bytes: 63, Sent bytes: 74
Send calls: 3, callbacks: 3
Receive calls: 3, callbacks: 2
Close reason: [Success] HEARTBEAT TIMEOUT at msgNum 2

[17804,11,07:48:34.503] Connection 'external-normal' [127.0.0.1:63046,
{de078bd1-7326-417c-a98e-7056db66ce9c}] closed: Success.

—
Reply to this email directly or view it on GitHub
#425.

Studying for the Turing test

—
Reply to this email directly or view it on GitHub
<
https://github.com/EventStore/EventStore/issues/425#issuecomment-84296930>
.

—
Reply to this email directly or view it on GitHub
#425 (comment)
.

Studying for the Turing test

[gregoryyoung]

There are two places to set btw command line on server ext heartbeat
timeout and interval and there is an option in the connection configuration
in client.

On Saturday, March 21, 2015, Serg Rogovtsev notifications@github.com
wrote:

Where do I have to increase them - on server side, or on client side? I
tried increasing (on both, in fact) to 15000, nothing changed. But I am
ready to give it a try.

And why doesn't catch-up subscription produce them?

On Sat, Mar 21, 2015 at 1:09 PM, Greg Young <notifications@github.com
javascript:_e(%7B%7D,'cvml','notifications@github.com');>
wrote:

This is a heartbeat timeout.

Are you by chance hitting a breakpoint in your debugger? This causes it.
Iirc as you haven't set timeouts the default is 500ms

On Saturday, March 21, 2015, Serg Rogovtsev <notifications@github.com
javascript:_e(%7B%7D,'cvml','notifications@github.com');>
wrote:

I am trying to write a simple proof-of-concept with Event Store. The
code
follows:

var settings = ConnectionSettings.Create()
.UseConsoleLogger()
.KeepReconnecting()
.KeepRetrying()
.WithConnectionTimeoutOf(TimeSpan.FromSeconds(10))
.SetReconnectionDelayTo(TimeSpan.FromMilliseconds(0))
.FailOnNoServerResponse()
.Build();

using (var c = EventStoreConnection.Create(settings, new
IPEndPoint(IPAddress.Loopback, 1113)))
{
await c.ConnectAsync().ConfigureAwait(false);

//c.SubscribeToStreamFrom("$ce-httpSession", null, true, (ss, er) =>
//{
//Console.WriteLine("{0} {1}", er.Event.EventType, er.Event.EventId);
//}, s => {Console.Write("live");});

await c.SubscribeToStreamAsync("$ce-httpSession", true, (ss, er) =>
{
Console.WriteLine("{0} {1}", er.Event.EventType, er.Event.EventId);
}).ConfigureAwait(false);

var cts = new CancellationTokenSource();
Task.Factory.StartNew(() => EventProducer(c), cts.Token);
Console.WriteLine("Press Enter to stop.");
Console.ReadLine();
cts.Cancel();
}

(The code inside EventProducer just produces some random events that I
want to work on.)

When there's no subscription, everything works.
When I use catch-up subscription (code commented), everything works,
even
after the subscription switches from catch-up to live mode.

When I try using live-only subscription (uncommented),
EventStoreConnection closes abruptly.

Here's client log:

[03,07:48:29.505,DEBUG] TcpPackageConnection: connected to [
127.0.0.1:1113, L127.0.0.1:63046,
{cfe5e213-404c-4256-a492-2b87b0cb893d}].
Press Enter to stop.
Processing session cc4d0856-e1ce-e311-be8b-50e5493f01a4
[08,07:48:34.507,INFO] ClientAPI TcpConnection closed [07:48:34.507:
N127.0.0.1:1113, L127.0.0.1:63046,
{cfe5e213-404c-4256-a492-2b87b0cb893d}]:
Received bytes: 74, Sent bytes: 63
Send calls: 2, callbacks: 2
Receive calls: 4, callbacks: 4
Close reason: [Success] Socket closed

[08,07:48:34.509,DEBUG] TcpPackageConnection: connection [
127.0.0.1:1113
,
L127.0.0.1:63046, {cfe5e213-404c-4256-a492-2b87b0cb893d}] was closed
cleanly.

If I try debugging I see that connection closes during first attempt to
publish an event to store (inside EventProducer), event never gets
published, the control just never leaves AppendToStreamAsync). The code
for that is simplistic:

Console.WriteLine("Processing session " + session.Id);
await eventStoreConnection
.AppendToStreamAsync(GetStreamId(session), ExpectedVersion.Any, new
EventData(session.Id, "httpSessionStart", false, null, null))
.ConfigureAwait(false);

Here's corresponding server part of log:

[17804,25,07:48:29.500] External TCP connection accepted: [Normal,
127.0.0.1:63046, L127.0.0.1:1113,
{de078bd1-7326-417c-a98e-7056db66ce9c}].
[17804,11,07:48:34.503] Closing connection 'external-normal' [
127.0.0.1:63046, L127.0.0.1:1113,
{de078bd1-7326-417c-a98e-7056db66ce9c}]
cleanly. Reason: HEARTBEAT TIMEOUT at msgNum 2
[17804,11,07:48:34.503] ES TcpConnection closed [07:48:34.503:
N127.0.0.1:63046, L127.0.0.1:1113,
{de078bd1-7326-417c-a98e-7056db66ce9c}]:
Received bytes: 63, Sent bytes: 74
Send calls: 3, callbacks: 3
Receive calls: 3, callbacks: 2
Close reason: [Success] HEARTBEAT TIMEOUT at msgNum 2

[17804,11,07:48:34.503] Connection 'external-normal' [127.0.0.1:63046,
{de078bd1-7326-417c-a98e-7056db66ce9c}] closed: Success.

—
Reply to this email directly or view it on GitHub
#425.

Studying for the Turing test

—
Reply to this email directly or view it on GitHub
<
https://github.com/EventStore/EventStore/issues/425#issuecomment-84296930>
.

—
Reply to this email directly or view it on GitHub
#425 (comment)
.

Studying for the Turing test

[srogovtsev]

No, there's no breakpoint, I ran the code with no debugger attached.

Let me rephrase the question: why do I get heartbeat timeouts with live subscriptions, and do not get them with catch-up subscriptions?

-- СР

-----Original Message-----
From: "Greg Young" notifications@github.com
Sent: ‎21.‎03.‎2015 14:24
To: "EventStore/EventStore" EventStore@noreply.github.com
Cc: "Serg Rogovtsev" lair@hawke.ru
Subject: Re: [EventStore] Live-only subscription produces heartbeat timeout(#425)

They are produced on the connection not by a subscription. Are you hitting
a breakpoint?

Basically a heartbeat timeout is if you have not sent me a message in x
then a message is sent ping to which you should respond pong. If you don't
you are assumed to be dead.

On Saturday, March 21, 2015, Serg Rogovtsev notifications@github.com
wrote:

Where do I have to increase them - on server side, or on client side? I
tried increasing (on both, in fact) to 15000, nothing changed. But I am
ready to give it a try.

And why doesn't catch-up subscription produce them?

On Sat, Mar 21, 2015 at 1:09 PM, Greg Young <notifications@github.com
javascript:_e(%7B%7D,'cvml','notifications@github.com');>
wrote:

This is a heartbeat timeout.

Are you by chance hitting a breakpoint in your debugger? This causes it.
Iirc as you haven't set timeouts the default is 500ms

On Saturday, March 21, 2015, Serg Rogovtsev <notifications@github.com
javascript:_e(%7B%7D,'cvml','notifications@github.com');>
wrote:

I am trying to write a simple proof-of-concept with Event Store. The
code
follows:

var settings = ConnectionSettings.Create()
.UseConsoleLogger()
.KeepReconnecting()
.KeepRetrying()
.WithConnectionTimeoutOf(TimeSpan.FromSeconds(10))
.SetReconnectionDelayTo(TimeSpan.FromMilliseconds(0))
.FailOnNoServerResponse()
.Build();

using (var c = EventStoreConnection.Create(settings, new
IPEndPoint(IPAddress.Loopback, 1113)))
{
await c.ConnectAsync().ConfigureAwait(false);

//c.SubscribeToStreamFrom("$ce-httpSession", null, true, (ss, er) =>
//{
//Console.WriteLine("{0} {1}", er.Event.EventType, er.Event.EventId);
//}, s => {Console.Write("live");});

await c.SubscribeToStreamAsync("$ce-httpSession", true, (ss, er) =>
{
Console.WriteLine("{0} {1}", er.Event.EventType, er.Event.EventId);
}).ConfigureAwait(false);

var cts = new CancellationTokenSource();
Task.Factory.StartNew(() => EventProducer(c), cts.Token);
Console.WriteLine("Press Enter to stop.");
Console.ReadLine();
cts.Cancel();
}

(The code inside EventProducer just produces some random events that I
want to work on.)

When there's no subscription, everything works.
When I use catch-up subscription (code commented), everything works,
even
after the subscription switches from catch-up to live mode.

When I try using live-only subscription (uncommented),
EventStoreConnection closes abruptly.

Here's client log:

[03,07:48:29.505,DEBUG] TcpPackageConnection: connected to [
127.0.0.1:1113, L127.0.0.1:63046,
{cfe5e213-404c-4256-a492-2b87b0cb893d}].
Press Enter to stop.
Processing session cc4d0856-e1ce-e311-be8b-50e5493f01a4
[08,07:48:34.507,INFO] ClientAPI TcpConnection closed [07:48:34.507:
N127.0.0.1:1113, L127.0.0.1:63046,
{cfe5e213-404c-4256-a492-2b87b0cb893d}]:
Received bytes: 74, Sent bytes: 63
Send calls: 2, callbacks: 2
Receive calls: 4, callbacks: 4
Close reason: [Success] Socket closed

[08,07:48:34.509,DEBUG] TcpPackageConnection: connection [
127.0.0.1:1113
,
L127.0.0.1:63046, {cfe5e213-404c-4256-a492-2b87b0cb893d}] was closed
cleanly.

If I try debugging I see that connection closes during first attempt to
publish an event to store (inside EventProducer), event never gets
published, the control just never leaves AppendToStreamAsync). The code
for that is simplistic:

Console.WriteLine("Processing session " + session.Id);
await eventStoreConnection
.AppendToStreamAsync(GetStreamId(session), ExpectedVersion.Any, new
EventData(session.Id, "httpSessionStart", false, null, null))
.ConfigureAwait(false);

Here's corresponding server part of log:

[17804,25,07:48:29.500] External TCP connection accepted: [Normal,
127.0.0.1:63046, L127.0.0.1:1113,
{de078bd1-7326-417c-a98e-7056db66ce9c}].
[17804,11,07:48:34.503] Closing connection 'external-normal' [
127.0.0.1:63046, L127.0.0.1:1113,
{de078bd1-7326-417c-a98e-7056db66ce9c}]
cleanly. Reason: HEARTBEAT TIMEOUT at msgNum 2
[17804,11,07:48:34.503] ES TcpConnection closed [07:48:34.503:
N127.0.0.1:63046, L127.0.0.1:1113,
{de078bd1-7326-417c-a98e-7056db66ce9c}]:
Received bytes: 63, Sent bytes: 74
Send calls: 3, callbacks: 3
Receive calls: 3, callbacks: 2
Close reason: [Success] HEARTBEAT TIMEOUT at msgNum 2

[17804,11,07:48:34.503] Connection 'external-normal' [127.0.0.1:63046,
{de078bd1-7326-417c-a98e-7056db66ce9c}] closed: Success.

—
Reply to this email directly or view it on GitHub
#425.

Studying for the Turing test

—
Reply to this email directly or view it on GitHub
<
https://github.com/EventStore/EventStore/issues/425#issuecomment-84296930>
.

—
Reply to this email directly or view it on GitHub
#425 (comment)
.

Studying for the Turing test

—
Reply to this email directly or view it on GitHub.

[jen20]

I think this is actually an issue with messages not being pumped because of async and await. Can you try removing your async stuff and blocking on the subscription coming back to see if this is the case - change:

await c.SubscribeToStreamAsync("$ce-httpSession", true, (ss, er) =>
    {
        Console.WriteLine("{0} {1}", er.Event.EventType, er.Event.EventId);
    }).ConfigureAwait(false);

to

c.SubscribeToStreamAsync("$ce-httpSession", true, (ss, er) => { ... }).Wait();

[gregoryyoung]

"Let me rephrase the question: why do I get heartbeat timeouts with live
subscriptions, and do not get them with catch-up subscriptions?"

It could also be the JIT compiler blocking. There are 1000 reasons why code
could pause. It could be you had 100% CPU usage and its thread didn't get
scheduled.

Or it could be as James pointed out your calling code.

All it is is at a connection level something caused the connection to not
be able to respond within the timeout. The connection if configured will
just automatically reconnect. The timeouts are configurable. The intervals
are configurable. You can even turn them off.

On Sat, Mar 21, 2015 at 1:56 PM, Serg Rogovtsev notifications@github.com
wrote:

No, there's no breakpoint, I ran the code with no debugger attached.

Let me rephrase the question: why do I get heartbeat timeouts with live
subscriptions, and do not get them with catch-up subscriptions?

-- СР

-----Original Message-----
From: "Greg Young" notifications@github.com
Sent: ‎21.‎03.‎2015 14:24
To: "EventStore/EventStore" EventStore@noreply.github.com
Cc: "Serg Rogovtsev" lair@hawke.ru
Subject: Re: [EventStore] Live-only subscription produces heartbeat
timeout(#425)

They are produced on the connection not by a subscription. Are you hitting
a breakpoint?

Basically a heartbeat timeout is if you have not sent me a message in x
then a message is sent ping to which you should respond pong. If you don't
you are assumed to be dead.

On Saturday, March 21, 2015, Serg Rogovtsev notifications@github.com
wrote:

Where do I have to increase them - on server side, or on client side? I
tried increasing (on both, in fact) to 15000, nothing changed. But I am
ready to give it a try.

And why doesn't catch-up subscription produce them?

On Sat, Mar 21, 2015 at 1:09 PM, Greg Young <notifications@github.com
javascript:_e(%7B%7D,'cvml','notifications@github.com');>
wrote:

This is a heartbeat timeout.

Are you by chance hitting a breakpoint in your debugger? This causes
it.
Iirc as you haven't set timeouts the default is 500ms

On Saturday, March 21, 2015, Serg Rogovtsev <notifications@github.com
javascript:_e(%7B%7D,'cvml','notifications@github.com');>

wrote:

I am trying to write a simple proof-of-concept with Event Store. The
code
follows:

var settings = ConnectionSettings.Create()
.UseConsoleLogger()
.KeepReconnecting()
.KeepRetrying()
.WithConnectionTimeoutOf(TimeSpan.FromSeconds(10))
.SetReconnectionDelayTo(TimeSpan.FromMilliseconds(0))
.FailOnNoServerResponse()
.Build();

using (var c = EventStoreConnection.Create(settings, new
IPEndPoint(IPAddress.Loopback, 1113)))
{
await c.ConnectAsync().ConfigureAwait(false);

//c.SubscribeToStreamFrom("$ce-httpSession", null, true, (ss, er) =>
//{
//Console.WriteLine("{0} {1}", er.Event.EventType, er.Event.EventId);
//}, s => {Console.Write("live");});

await c.SubscribeToStreamAsync("$ce-httpSession", true, (ss, er) =>
{
Console.WriteLine("{0} {1}", er.Event.EventType, er.Event.EventId);
}).ConfigureAwait(false);

var cts = new CancellationTokenSource();
Task.Factory.StartNew(() => EventProducer(c), cts.Token);
Console.WriteLine("Press Enter to stop.");
Console.ReadLine();
cts.Cancel();
}

(The code inside EventProducer just produces some random events that
I
want to work on.)

When there's no subscription, everything works.
When I use catch-up subscription (code commented), everything works,
even
after the subscription switches from catch-up to live mode.

When I try using live-only subscription (uncommented),
EventStoreConnection closes abruptly.

Here's client log:

[03,07:48:29.505,DEBUG] TcpPackageConnection: connected to [
127.0.0.1:1113, L127.0.0.1:63046,
{cfe5e213-404c-4256-a492-2b87b0cb893d}].
Press Enter to stop.
Processing session cc4d0856-e1ce-e311-be8b-50e5493f01a4
[08,07:48:34.507,INFO] ClientAPI TcpConnection closed [07:48:34.507:
N127.0.0.1:1113, L127.0.0.1:63046,
{cfe5e213-404c-4256-a492-2b87b0cb893d}]:
Received bytes: 74, Sent bytes: 63
Send calls: 2, callbacks: 2
Receive calls: 4, callbacks: 4
Close reason: [Success] Socket closed

[08,07:48:34.509,DEBUG] TcpPackageConnection: connection [
127.0.0.1:1113
,
L127.0.0.1:63046, {cfe5e213-404c-4256-a492-2b87b0cb893d}] was closed
cleanly.

If I try debugging I see that connection closes during first attempt
to
publish an event to store (inside EventProducer), event never gets
published, the control just never leaves AppendToStreamAsync). The
code
for that is simplistic:

Console.WriteLine("Processing session " + session.Id);
await eventStoreConnection
.AppendToStreamAsync(GetStreamId(session), ExpectedVersion.Any, new
EventData(session.Id, "httpSessionStart", false, null, null))
.ConfigureAwait(false);

Here's corresponding server part of log:

[17804,25,07:48:29.500] External TCP connection accepted: [Normal,
127.0.0.1:63046, L127.0.0.1:1113,
{de078bd1-7326-417c-a98e-7056db66ce9c}].
[17804,11,07:48:34.503] Closing connection 'external-normal' [
127.0.0.1:63046, L127.0.0.1:1113,
{de078bd1-7326-417c-a98e-7056db66ce9c}]
cleanly. Reason: HEARTBEAT TIMEOUT at msgNum 2
[17804,11,07:48:34.503] ES TcpConnection closed [07:48:34.503:
N127.0.0.1:63046, L127.0.0.1:1113,
{de078bd1-7326-417c-a98e-7056db66ce9c}]:
Received bytes: 63, Sent bytes: 74
Send calls: 3, callbacks: 3
Receive calls: 3, callbacks: 2
Close reason: [Success] HEARTBEAT TIMEOUT at msgNum 2

[17804,11,07:48:34.503] Connection 'external-normal' [
127.0.0.1:63046,
{de078bd1-7326-417c-a98e-7056db66ce9c}] closed: Success.

—
Reply to this email directly or view it on GitHub
#425.

Studying for the Turing test

—
Reply to this email directly or view it on GitHub
<

https://github.com/EventStore/EventStore/issues/425#issuecomment-84296930>

.

—
Reply to this email directly or view it on GitHub
<
https://github.com/EventStore/EventStore/issues/425#issuecomment-84310279>
.

Studying for the Turing test

—
Reply to this email directly or view it on GitHub.

—
Reply to this email directly or view it on GitHub
#425 (comment)
.

Studying for the Turing test

[srogovtsev]

@jen20 you were right! If I change await subscription to .Wait(), it works nicely.

But why is that? The only difference between first and second version is that (a) Wait blocks the thread until the subscription is complete while await yields the thread to another computation (which I don't have, so it just waits) and (b) there is some exception unwrapping (which does not happen here because there's no exception).

But that also explains why catch-up subscription works: it is synchronous.

[jen20]

Sadly that's not the only difference - async and await are quite subtle - if you look through the generated state machine with a decompiler you'll likely spot the problem. I actually did a whole conference talk about this precise issue last year :-)

The issue is that you do have another computation - a blocking Console.ReadLine() call on the thread which is required to pump messages.

[srogovtsev]

Ahem. Console.ReadLine() is after await. I thought that control can't reach any code after await until task is completed. In fact, I though that's the whole point of await - I could do var sub = await conn.SubscribeAsync(); and get there a result of subscription, same as var sub = conn.SubscribeAsync().Result.

I understand that there are differences in implementation, but I still hope, for my sanity, that ReadLine has nothing to do with that.

[jen20]

That's not how it works in this case - you need to be pumping messages for anything to work. If you replace it with conn.SubscribeAsync().Result all will be well.

[srogovtsev]

Both .Wait() and .Result block the thread they're on. Which thread is pumping messages then?

[srogovtsev]

@jen20 you're right again, just moving Console.ReadLine out of the method did the trick.

static void Main(string[] args)
{
    var cts = new CancellationTokenSource();
    #pragma warning disable 4014
    MainImpl(cts);
    #pragma warning restore 4014
    Console.WriteLine("Press Enter to stop.");
    Console.ReadLine();
    cts.Cancel();
}

private static async Task MainImpl(CancellationTokenSource cts)
{
    //...
    await c.ConnectAsync().ConfigureAwait(false);
    //...
    await c.SubscribeToStreamAsync(...).ConfigureAwait(false);
    //...
    await Task.Factory.StartNew(() => EventProducer(dc, c), cts.Token).ConfigureAwait(false);
}

I wish I understood that.

[gregoryyoung]

I am closing this as it appears to just be async/await