How do you recover from a Heartbeat Exception

VAST · September 2, 2019, 9:02am

Hi,

I am using ServiceStack 5.5.1 with .NET Core 2.2 and would like to know how you can recover from a Server Event Heartbeat Exception.

In the log I get the following on a C# console client:

2019-08-28 22:25:58,470 [72] DEBUG ServiceStack.ServerEventsClient [(null)] - [SSE-CLIENT] Heartbeat sent to: https://server01.myserver.com/event-heartbeat?id=5GD4KIbbwCIRrVA1k3wU
2019-08-28 22:26:08,478 [72] DEBUG ServiceStack.ServerEventsClient [(null)] - [SSE-CLIENT] Prep for Heartbeat…
2019-08-28 22:26:08,478 [72] DEBUG ServiceStack.ServerEventsClient [(null)] - [SSE-CLIENT] Sending Heartbeat…
2019-08-28 22:26:08,664 [6] DEBUG ServiceStack.ServerEventsClient [(null)] - [SSE-CLIENT] LastPulseAt: 21:26:08.6646476
2019-08-28 22:26:08,664 [6] DEBUG ServiceStack.ServerEventsClient [(null)] - [SSE-CLIENT] OnHeartbeatReceived: (ServerEventHeartbeat) #10270 on #SERVER01_DGXzea49) (agent)
2019-08-28 22:26:08,664 [6] DEBUG ServiceStack.ServerEventsClient [(null)] - [SSE-CLIENT] Heartbeat sent to: https://server01.myserver.com/event-heartbeat?id=5GD4KIbbwCIRrVA1k3wU
2019-08-28 22:26:18,666 [6] DEBUG ServiceStack.ServerEventsClient [(null)] - [SSE-CLIENT] Prep for Heartbeat…
2019-08-28 22:26:18,666 [6] DEBUG ServiceStack.ServerEventsClient [(null)] - [SSE-CLIENT] Sending Heartbeat…
2019-08-28 22:26:18,786 [72] DEBUG ServiceStack.ServerEventsClient [(null)] - [SSE-CLIENT] LastPulseAt: 21:26:18.7861605
2019-08-28 22:26:18,786 [72] DEBUG ServiceStack.ServerEventsClient [(null)] - [SSE-CLIENT] OnHeartbeatReceived: (ServerEventHeartbeat) #10271 on #SERVER01_DGXzea49) (agent)
2019-08-28 22:26:18,786 [18] DEBUG ServiceStack.ServerEventsClient [(null)] - [SSE-CLIENT] Heartbeat sent to: https://server01.myserver.com/event-heartbeat?id=5GD4KIbbwCIRrVA1k3wU
2019-08-28 22:26:28,791 [18] DEBUG ServiceStack.ServerEventsClient [(null)] - [SSE-CLIENT] Prep for Heartbeat…
2019-08-28 22:26:28,792 [18] DEBUG ServiceStack.ServerEventsClient [(null)] - [SSE-CLIENT] Sending Heartbeat…
2019-08-28 22:26:31,532 [18] DEBUG ServiceStack.ServerEventsClient [(null)] - [SSE-CLIENT] Error from Heartbeat: The remote server returned an error: (404) Subscription ‘5GD4KIbbwCIRrVA1k3wU’ does not exist.
2019-08-28 22:26:31,532 [18] ERROR ServiceStack.ServerEventsClient [(null)] - [SSE-CLIENT] OnExceptionReceived: The remote server returned an error: (404) Subscription ‘5GD4KIbbwCIRrVA1k3wU’ does not exist. on #SERVER01_DGXzea49)
System.Net.WebException: The remote server returned an error: (404) Subscription ‘5GD4KIbbwCIRrVA1k3wU’ does not exist.
at System.Net.HttpWebRequest.EndGetResponse(IAsyncResult asyncResult)
at System.Net.WebRequest.<>c.b__68_2(IAsyncResult iar)
at System.Threading.Tasks.TaskFactory1.FromAsyncCoreLogic(IAsyncResult iar, Func2 endFunction, Action1 endAction, Task1 promise, Boolean requiresSynchronization)
— End of stack trace from previous location where exception was thrown —
at ServiceStack.HttpUtils.SendStringToUrlAsync(String url, String method, String requestBody, String contentType, String accept, Action1 requestFilter, Action1 responseFilter) in C:\BuildAgent\work\912418dcce86a188\src\ServiceStack.Text\HttpUtils.cs:line 600
2019-08-28 22:26:31,533 [18] DEBUG ServiceStack.ServerEventsClient [(null)] - Stop()
2019-08-28 22:26:31,533 [18] DEBUG ServiceStack.ServerEventsClient [(null)] - [SSE-CLIENT] Unregistering…
2019-08-28 22:26:31,860 [18] DEBUG ServiceStack.ServerEventsClient [(null)] - Start()
2019-08-28 22:26:31,968 [18] ERROR ServiceStack.ServerEventsClient [(null)] - [SSE-CLIENT] OnExceptionReceived: The remote server returned an error: (401) Unauthorized. on #(not connected)
System.Net.WebException: The remote server returned an error: (401) Unauthorized.
at ServiceStack.PclExport.GetResponse(WebRequest webRequest) in C:\BuildAgent\work\912418dcce86a188\src\ServiceStack.Text\PclExport.cs:line 180
at ServiceStack.ServerEventsClient.Start() in C:\BuildAgent\work\3481147c480f4a2f\src\ServiceStack.Client\ServerEventsClient.cs:line 222
at ServiceStack.ServerEventsClient.b__104_1(Task t) in C:\BuildAgent\work\3481147c480f4a2f\src\ServiceStack.Client\ServerEventsClient.cs:line 485
2019-08-28 22:26:32,641 [18] DEBUG ServiceStack.ServerEventsClient [(null)] - Stop()
2019-08-28 22:26:32,641 [51] DEBUG ServiceStack.ServerEventsClient [(null)] - Sleeping for 22ms after 2 continuous errors
2019-08-28 22:26:32,666 [51] DEBUG ServiceStack.ServerEventsClient [(null)] - Start()
2019-08-28 22:26:32,777 [51] DEBUG ServiceStack.ServerEventsClient [(null)] - [SSE-CLIENT] LastPulseAt: 21:26:32.7777449

After this happens the client doesn’t reconnect. Is there an event I can subscribe to so I can reconnect as it doesn’t seem to reconnect automatically.

Thanks in advance.

mythz · September 2, 2019, 2:58pm

This StackTrace suggests the Subscription it’s trying to send heartbeats to no longer exists and when it tried to reconnect it it received a (401) Unauthorized response suggesting the client is no longer authenticated. So you would need to re-authenticate the client before attempting to re-establish a new Server Events connection.

VAST · September 2, 2019, 3:50pm

Hi, yes I did wonder if that was happening. I just wondered how I should catch this error? Is there an event I can handle to attempt to reconnect on a heartbeat failure?

I am already handling ServerEventsClient.OnException which attempts to authenticate again which generally catches this sort of thing but for some reason the OnException isn’t triggering for the heartbeat failure.

Thanks again.

mythz · September 2, 2019, 4:01pm

Heartbeat Exceptions are being sent through the same OnExceptionReceived() error handler which is triggering the restart I can see in the StackTrace, the restart is failing because of the 401 Unauthorized response which is also benig routed through the same OnExceptionReceived() handler.

VAST · September 9, 2019, 8:48am

Hi, ok I tweaked my code so it looks like this:

client.OnException = (ex) =>
{
    logger.Error("Connection error", ex);

        try
        {
            logger.Info("Attempting to authenticate again...");

            client.Authenticate(new Authenticate
            {
                provider = "credentials",
                UserName = username,
                Password = password,
                RememberMe = true
            });

            logger.Info("Authenticated");
        }
        catch (Exception exx)
        {
            logger.Error("Failed to authenticate", exx);
        }
};

I left the application running, it then eventually received:

ERROR ServiceStack.ServerEventsClient [(null)] - [SSE-CLIENT] OnExceptionReceived: The remote server returned an error: (404) Subscription 'qgjfe8IE8kNbUhROKXJ1' does not exist. on #SEVERNAME_JATzgn45!

After that my authentication code in the exception event above triggered, then my log shows:

2019-09-09 02:01:02,519 [53] INFO  DataService.ClientService [(null)] - Attempting to authenticate again...
2019-09-09 02:01:02,720 [53] INFO  DataService.ClientService [(null)] - Authenticated
2019-09-09 02:01:02,720 [53] DEBUG ServiceStack.ServerEventsClient [(null)] - Stop()
2019-09-09 02:01:02,720 [53] DEBUG ServiceStack.ServerEventsClient [(null)] - [SSE-CLIENT] Unregistering...
2019-09-09 02:01:02,954 [53] DEBUG ServiceStack.ServerEventsClient [(null)] - Start()
2019-09-09 02:01:03,136 [53] DEBUG ServiceStack.ServerEventsClient [(null)] - [SSE-CLIENT] LastPulseAt: 01:01:03.1369860

After the above my client.SubscriptionId is empty.

Should I be adding client.Authenticate to the client.OnReconnect event as this event gets triggered after the last entry in the log?

Thanks again.

mythz · September 9, 2019, 4:14pm

That looks right, it stops and starts a new SSE connection as the authenticated user?

Though I’d personally prefer to start with a clean new Server Events Connection.

taglius · September 12, 2019, 2:27pm

Note: I am getting these same 404 subscription errors now - we believe this might be a problem introduced by Chrome 76. (co-workers with Chrome 75 are not getting the errors).