I am testing an application with a heartbeat of 1 minute. It connects to an app running 5.9 on Azure Linux App Service. The client application is running on a Windows server. I am using memory SSE. The client app will heartbeat great for weeks, until it can’t anymore and the only fix is restarting the Azure app service. Restarting the client application has no effect.
Here is an example of logs from the client app:
{"SourceContext":"ServiceStack.ServerEventsClient","MachineName":"WIN-RL5PO5CPCDU"}2020-07-08 23:56:02.061 -05:00 [DBG] Start()
{"SourceContext":"ServiceStack.ServerEventsClient","MachineName":"WIN-RL5PO5CPCDU"}2020-07-08 23:56:03.232 -05:00 [DBG] [SSE-CLIENT] LastPulseAt: 04:56:03.2319745
{"SourceContext":"ServiceStack.ServerEventsClient","MachineName":"WIN-RL5PO5CPCDU"}2020-07-08 23:56:03.232 -05:00 [INF] OnReconnect "2020-07-08T23:56:03.2322307-05:00"
{"MachineName":"WIN-RL5PO5CPCDU"}2020-07-08 23:56:03.232 -05:00 [DBG] [SSE-CLIENT] OnConnectReceived: 1 on #One_Handsome_Man_ / bxtgz3LGq79vBvgXpaJm on (agents)
{"SourceContext":"ServiceStack.ServerEventsClient","MachineName":"WIN-RL5PO5CPCDU"}2020-07-08 23:56:03.232 -05:00 [DBG] OnConnect "2020-07-08T23:56:03.2325894-05:00"
{"MachineName":"WIN-RL5PO5CPCDU"}2020-07-08 23:57:03.252 -05:00 [DBG] [SSE-CLIENT] Prep for Heartbeat...
{"SourceContext":"ServiceStack.ServerEventsClient","MachineName":"WIN-RL5PO5CPCDU"}2020-07-08 23:57:03.252 -05:00 [DBG] [SSE-CLIENT] Sending Heartbeat...
{"SourceContext":"ServiceStack.ServerEventsClient","MachineName":"WIN-RL5PO5CPCDU"}2020-07-08 23:57:03.560 -05:00 [DBG] Connection ended on One_Handsome_Man_
{"SourceContext":"ServiceStack.ServerEventsClient","MachineName":"WIN-RL5PO5CPCDU"}2020-07-08 23:57:03.560 -05:00 [DBG] Stop()
{"SourceContext":"ServiceStack.ServerEventsClient","MachineName":"WIN-RL5PO5CPCDU"}2020-07-08 23:57:03.560 -05:00 [DBG] [SSE-CLIENT] Unregistering...
{"SourceContext":"ServiceStack.ServerEventsClient","MachineName":"WIN-RL5PO5CPCDU"}2020-07-08 23:57:03.560 -05:00 [DBG] [SSE-CLIENT] Heartbeat error. Heartbeat is cancelled.
{"SourceContext":"ServiceStack.ServerEventsClient","MachineName":"WIN-RL5PO5CPCDU"}2020-07-08 23:57:03.768 -05:00 [DBG] Start()
{"SourceContext":"ServiceStack.ServerEventsClient","MachineName":"WIN-RL5PO5CPCDU"}2020-07-08 23:57:04.981 -05:00 [DBG] [SSE-CLIENT] LastPulseAt: 04:57:04.9815796
{"SourceContext":"ServiceStack.ServerEventsClient","MachineName":"WIN-RL5PO5CPCDU"}2020-07-08 23:57:04.981 -05:00 [INF] OnReconnect "2020-07-08T23:57:04.9818469-05:00"
{"MachineName":"WIN-RL5PO5CPCDU"}2020-07-08 23:57:04.982 -05:00 [DBG] [SSE-CLIENT] OnConnectReceived: 1 on #One_Handsome_Man_ / W2KQxU3JGktRDok0zas3 on (agents)
{"SourceContext":"ServiceStack.ServerEventsClient","MachineName":"WIN-RL5PO5CPCDU"}2020-07-08 23:57:04.982 -05:00 [DBG] OnConnect "2020-07-08T23:57:04.9822271-05:00"
{"MachineName":"WIN-RL5PO5CPCDU"}2020-07-08 23:58:04.982 -05:00 [DBG] [SSE-CLIENT] Prep for Heartbeat...
{"SourceContext":"ServiceStack.ServerEventsClient","MachineName":"WIN-RL5PO5CPCDU"}2020-07-08 23:58:04.982 -05:00 [DBG] [SSE-CLIENT] Sending Heartbeat...
{"SourceContext":"ServiceStack.ServerEventsClient","MachineName":"WIN-RL5PO5CPCDU"}2020-07-08 23:58:05.231 -05:00 [DBG] Connection ended on One_Handsome_Man_
{"SourceContext":"ServiceStack.ServerEventsClient","MachineName":"WIN-RL5PO5CPCDU"}2020-07-08 23:58:05.262 -05:00 [DBG] Stop()
{"SourceContext":"ServiceStack.ServerEventsClient","MachineName":"WIN-RL5PO5CPCDU"}2020-07-08 23:58:05.262 -05:00 [DBG] [SSE-CLIENT] Unregistering...
{"SourceContext":"ServiceStack.ServerEventsClient","MachineName":"WIN-RL5PO5CPCDU"}2020-07-08 23:58:05.231 -05:00 [DBG] [SSE-CLIENT] Error from Heartbeat: The remote server returned an error: (404) Subscription 'W2KQxU3JGktRDok0zas3' does not exist.
{"SourceContext":"ServiceStack.ServerEventsClient","MachineName":"WIN-RL5PO5CPCDU"}2020-07-08 23:58:05.262 -05:00 [ERR] [SSE-CLIENT] OnExceptionReceived: The remote server returned an error: (404) Subscription 'W2KQxU3JGktRDok0zas3' does not exist. on #One_Handsome_Man_
System.Net.WebException: The remote server returned an error: (404) Subscription 'W2KQxU3JGktRDok0zas3' does not exist.
at System.Net.HttpWebRequest.EndGetResponse(IAsyncResult asyncResult)
at System.Net.WebRequest.<>c.<GetResponseAsync>b__68_2(IAsyncResult iar)
at System.Threading.Tasks.TaskFactory`1.FromAsyncCoreLogic(IAsyncResult iar, Func`2 endFunction, Action`1 endAction, Task`1 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, Action`1 requestFilter, Action`1 responseFilter)
{"SourceContext":"ServiceStack.ServerEventsClient","MachineName":"WIN-RL5PO5CPCDU","ExceptionDetail":{"HResult":-2146233079,"Message":"The remote server returned an error: (404) Subscription 'W2KQxU3JGktRDok0zas3' does not exist.","Source":"System.Net.Requests","StackTrace":" at System.Net.HttpWebRequest.EndGetResponse(IAsyncResult asyncResult)\r\n at System.Net.WebRequest.<>c.<GetResponseAsync>b__68_2(IAsyncResult iar)\r\n at System.Threading.Tasks.TaskFactory`1.FromAsyncCoreLogic(IAsyncResult iar, Func`2 endFunction, Action`1 endAction, Task`1 promise, Boolean requiresSynchronization)\r\n--- End of stack trace from previous location where exception was thrown ---\r\n at ServiceStack.HttpUtils.SendStringToUrlAsync(String url, String method, String requestBody, String contentType, String accept, Action`1 requestFilter, Action`1 responseFilter)","Status":"ProtocolError","Response":{"IsMutuallyAuthenticated":false,"ContentLength":0,"ContentType":"","ContentEncoding":null,"Cookies":[{"Comment":"","CommentUri":null,"HttpOnly":true,"Discard":false,"Domain":"elbalert.azurewebsites.net","Expired":false,"Expires":"0001-01-01T00:00:00.0000000","Name":"ss-id","Path":"/","Port":"","Secure":true,"TimeStamp":"2020-06-15T10:32:38.5939843-05:00","Value":"ouBdVQo6sfdfmT0uGJhn","Version":0},{"Comment":"","CommentUri":null,"HttpOnly":true,"Discard":false,"Domain":"elbalert.azurewebsites.net","Expired":false,"Expires":"2040-06-15T10:32:37.0000000-05:00","Name":"ss-pid","Path":"/","Port":"","Secure":true,"TimeStamp":"2020-06-15T10:32:38.6223174-05:00","Value":"7j9K6xNM23ZT4GIjnqu3","Version":0},{"Comment":"","CommentUri":null,"HttpOnly":true,"Discard":false,"Domain":"elbalert.azurewebsites.net","Expired":false,"Expires":"2040-07-08T23:57:04.0000000-05:00","Name":"X-UAId","Path":"/","Port":"","Secure":false,"TimeStamp":"2020-07-08T23:57:04.9810571-05:00","Value":"2","Version":0}],"LastModified":"2020-07-08T23:58:05.2638408-05:00","Server":"Kestrel","ProtocolVersion":{"Major":1,"Minor":1,"Build":-1,"Revision":-1,"MajorRevision":-1,"MinorRevision":-1},"Headers":["Vary","Server","X-Powered-By","Date","Content-Length"],"Method":"GET","ResponseUri":"https://elbalert.azurewebsites.net/event-heartbeat?id=W2KQxU3JGktRDok0zas3","StatusCode":"NotFound","StatusDescription":"Subscription 'W2KQxU3JGktRDok0zas3' does not exist","CharacterSet":null,"SupportsHeaders":true,"IsFromCache":false},"Type":"System.Net.WebException"}}2020-07-08 23:58:05.265 -05:00 [ERR] OnException "2020-07-08T23:58:05.2653469-05:00"
Is there anyway to get visibility to all active subscriptions?
Here is my ServerEvents cs file:
public class ConfigureServerEvents:IConfigureAppHost, IConfigureServices, IAfterInitAppHost
{
IConfiguration Configuration { get; }
public ConfigureServerEvents(IConfiguration configuration) => Configuration = configuration;
private Container _container;
public void Configure(IAppHost appHost)
{
_container = appHost.GetContainer();
appHost.Plugins.Add(new ServerEventsFeature(){
LimitToAuthenticatedUsers = true
,HeartbeatInterval = TimeSpan.FromSeconds(60)
,IdleTimeout = TimeSpan.FromSeconds(300)
,NotifyChannelOfSubscriptions = false
//,HouseKeepingInterval = TimeSpan.FromSeconds(1)
,OnSubscribeAsync = OnSubscribeAsync
,OnUnsubscribeAsync = OnUnsubscribeAsync
,OnPublishAsync = OnPublishAsync
,OnError = OnError
,OnHeartbeatInit = OnHeartbeatInit
, OnCreated = OnCreated
, OnInit = OnInit
});
}
private void OnInit(IRequest req)
{
Log.ForContext<ConfigureServerEvents>().Debug("Sub has been init {request}", req);
}
private void OnError(IEventSubscription iEventSubscription, Exception exception)
{
Log.ForContext<ConfigureServerEvents>().Error(exception, "OnException {0}", iEventSubscription);
}
private void OnCreated(IEventSubscription subscription, IRequest req)
{
//No reason to send these values to agents/clients, no public info to share between clients
subscription.Meta.Clear();
//No reason to send the profileUrl every connection
subscription.ConnectArgs.Remove("profileUrl");
Log.ForContext<ConfigureServerEvents>().Debug("Sub has been created {@subscription}", subscription);
}
private void OnHeartbeatInit(IRequest iRequest)
{
//I wrap the whole thing because if this fails, it interrupts the SSE process
try
{
var db = _container.Resolve<IDbConnectionFactory>();
using var connection = db.OpenDbConnection();
var subscriptionId = iRequest.QueryString["id"];
var serverEvents = _container.Resolve<IServerEvents>();
var subscriptionInfo = serverEvents.GetSubscriptionInfo(subscriptionId);
if (subscriptionInfo == null)
{
Log.ForContext<ConfigureServerEvents>().Error($"Sub id not found: {subscriptionId}", subscriptionId);
return;
}
var foundConnectionLog = connection.Single<ConnectionLog>(new
{SubscriptionUserId = subscriptionInfo.UserId
, ConnectionEventType = ConnectionEventType.HeartBeat
, subscriptionInfo.SubscriptionId
, subscriptionInfo.SessionId
});
if (foundConnectionLog != null)
{
foundConnectionLog.Count += 1;
foundConnectionLog.DateModified = DateTime.UtcNow;
connection.Update(foundConnectionLog);
}
else
{
connection.Insert(new ConnectionLog()
{
DateCreated = DateTime.UtcNow
, IpAddress = iRequest.RemoteIp
, SubscriptionUserId = subscriptionInfo.UserId
, SubscriptionId = subscriptionId
, SessionId = subscriptionInfo.SessionId
, ConnectionEventType = ConnectionEventType.HeartBeat
});
}
}
catch (Exception ex)
{
Log.ForContext<ConfigureServerEvents>().Error(ex, "Code Red. We have a problem with OnHeartbeatInit");
}
}
private Task OnPublishAsync(IEventSubscription iEventSubscription, IResponse iResponse, string arg3)
{
try
{
var db = _container.Resolve<IDbConnectionFactory>();
using var connection = db.OpenDbConnection();
connection.Insert(new PublishLog()
{
DateCreated = DateTime.UtcNow
, IpAddress = iEventSubscription.UserAddress
, UserAuthId = iEventSubscription.UserId
, SubscriptionId = iEventSubscription.SubscriptionId
, SessionId = iEventSubscription.SessionId
});
}
catch (Exception ex)
{
Log.ForContext<ConfigureServerEvents>().Error(ex, "Code Red. We have a problem in OnPublish");
}
return Task.CompletedTask;
}
private Task OnSubscribeAsync (IEventSubscription subscription)
{
Log.ForContext<ConfigureServerEvents>().Debug("Sub has subscribed {@subscription}", subscription);
try
{
var db = _container.Resolve<IDbConnectionFactory>();
using var connection = db.OpenDbConnection();
connection.Insert(new ConnectionLog()
{
DateCreated = DateTime.UtcNow
, IpAddress = subscription.UserAddress
, SubscriptionUserId = subscription.UserId
, SubscriptionId = subscription.SubscriptionId
, SessionId = subscription.SessionId
, ConnectionEventType = ConnectionEventType.Subscribe
});
}
catch (Exception ex)
{
Log.ForContext<ConfigureServerEvents>().Error(ex, "Code Red. We have a problem in OnSubscribe");
}
return Task.CompletedTask;
}
private Task OnUnsubscribeAsync(IEventSubscription subscription)
{
try
{
Log.ForContext<ConfigureServerEvents>().Debug("Sub has unsubscribed {subscription}", subscription);
var db = _container.Resolve<IDbConnectionFactory>();
using var connection = db.OpenDbConnection();
connection.Insert(new ConnectionLog()
{
DateCreated = DateTime.UtcNow
, IpAddress = subscription.UserAddress
, SubscriptionUserId = subscription.UserId
, SubscriptionId = subscription.SubscriptionId
, SessionId = subscription.SessionId
, ConnectionEventType = ConnectionEventType.Unsubscribe
});
}
catch (Exception ex)
{
Log.ForContext<ConfigureServerEvents>().Error(ex, "Code Red. We have a problem in OnUnsubscribe");
}
return Task.CompletedTask;
}
public void Configure(IServiceCollection services)
{
//Start Redis Server event
services.AddSingleton<IServerEvents>(c =>
new RedisServerEvents(c.Resolve<IRedisClientsManager>()));
}
public void AfterInit(IAppHost appHost)
{
appHost.Resolve<IServerEvents>().Start();
}
}