public override void OnActionExecuting(HttpActionContext actionContext)
{
this._diagnosticsTracingService.Trace(TraceLevel.Warn, $"--------------------------------------------------");
this._diagnosticsTracingService.Trace(TraceLevel.Warn, $"Request Start....");
SessionOperation sessionOperationLog = _sessionOperationLogService.Current;
sessionOperationLog.BeginDateTimeUtc = DateTime.UtcNow;
sessionOperationLog.ClientIp = actionContext.Request.RemoteIPChain();
//sessionOperationLog.SessionFK = this._principalService.CurrentSessionIdentifier;
sessionOperationLog.Url = actionContext.Request.RequestUri.OriginalString;
sessionOperationLog.ControllerName = actionContext.ActionDescriptor.ControllerDescriptor.ControllerName;
sessionOperationLog.ActionName = actionContext.ActionDescriptor.ActionName;
sessionOperationLog.ActionArguments = "{}"; //todo: FIX this up
//actionContext.Request.Content.
/*
* sessionOperationLog.ActionArguments = JsonConvert.SerializeObject(actionContext.ActionArguments,
* Formatting.Indented, new JsonSerializerSettings {ReferenceLoopHandling = ReferenceLoopHandling.Ignore});
*/// When using ODataQueryOptions this throws an outofmemoryException
sessionOperationLog.ResponseCode = "-1";
//No need to start tracking, and it is allready automatically committed when gotten.
base.OnActionExecuting(actionContext);
}
public override void OnActionExecuted(HttpActionExecutedContext actionExecutedContext)
{
base.OnActionExecuted(actionExecutedContext);
SessionOperation sessionOperation = _sessionOperationLogService.Current;
sessionOperation.EndDateTimeUtc = DateTime.UtcNow;
sessionOperation.Duration =
sessionOperation.EndDateTimeUtc.Subtract(sessionOperation.BeginDateTimeUtc);
if (actionExecutedContext.Response != null)
{
sessionOperation.ResponseCode = ((int)actionExecutedContext.Response.StatusCode).ToString();
}
else
{
sessionOperation.ResponseCode = "-1";
}
if (sessionOperation.Duration.TotalMilliseconds > 2000)
{
this._diagnosticsTracingService.Trace(TraceLevel.Warn, $"Operation took too long: {sessionOperation.Duration}");
}
_sessionManagmentService.SaveSessionOperationAsync(sessionOperation, _principalService);
}
public override void OnActionExecuting(ActionExecutingContext filterContext)
{
// Filters are shared across requests, so save variables within the Request context to pass between methods:
SessionOperation sessionOperation = _sessionOperationLogService.Current;
//sessionOperation.SessionFK = this._principalService.CurrentSessionIdentifier;
sessionOperation.BeginDateTimeUtc = DateTime.UtcNow;
sessionOperation.ClientIp = filterContext.RequestContext.HttpContext.Request.RemoteIPChain();
sessionOperation.Url = filterContext.RequestContext.HttpContext.Request.RawUrl;
sessionOperation.ControllerName =
filterContext.ActionDescriptor.ControllerDescriptor
.ControllerName; //filterContext.RouteData.Values["controller"] as string;
sessionOperation.ActionName =
filterContext.ActionDescriptor.ActionName; //filterContext.RouteData.Values["action"] as string;
sessionOperation.ResponseCode = "-1";
try
{
sessionOperation.ActionArguments = JsonConvert.SerializeObject(filterContext.ActionParameters,
Formatting.Indented,
new JsonSerializerSettings {
ReferenceLoopHandling = ReferenceLoopHandling.Ignore
});
}
catch
{
sessionOperation.ActionArguments = "ERROR";
}
//PS: No need to AddOnCommit the entity, as it's already been done by the original Current property...
base.OnActionExecuting(filterContext);
}
public override void OnResultExecuted(ResultExecutedContext filterContext)
{
base.OnResultExecuted(filterContext);
SessionOperation sessionOperation = _sessionOperationLogService.Current;
//Record the HTTP response code (should be 200 everytime, right?)
sessionOperation.ResponseCode = filterContext.HttpContext.Response.StatusCode.ToString();
//Record end, and duration:
sessionOperation.EndDateTimeUtc = DateTimeOffset.UtcNow;
sessionOperation.Duration =
sessionOperation.EndDateTimeUtc.Subtract(sessionOperation.BeginDateTimeUtc);
_sessionManagmentService.SaveSessionOperationAsync(sessionOperation, _principalService);
//if (sessionOperation.Duration.TotalMilliseconds > 2000)
//{
// this._diagnosticsTracingService.Trace(TraceLevel.Warn, $"Operation took too long: {sessionOperation.Duration}");
//}
//var msg = "Invoked:";
//Log(msg);
}
private void HackSessionLog(ResultExecutedContext filterContext)
{
SessionOperation sessionOperation = this._sessionOperationLogService.Current;
sessionOperation.EndDateTimeUtc = DateTimeOffset.UtcNow;
sessionOperation.Duration =
sessionOperation.EndDateTimeUtc.Subtract(sessionOperation.BeginDateTimeUtc);
sessionOperation.ResponseCode = filterContext.HttpContext.Response.StatusCode.ToString();
}
private void SaveTheSession(SessionOperation sessionOperation, PrincipalUserSession principalService)
{
if (!principalService.IsAuthenticated)
{
_repositoryService.AddOnCommit(AppCoreDbContextNames.Core, sessionOperation);
_repositoryService.SaveChanges(AppCoreDbContextNames.Core);
return;
}
AddSession(sessionOperation, principalService);
}
public void SaveSessionOperationAsync(SessionOperation sessionOperation, IPrincipalService principalService)
{
var principal = new PrincipalUserSession
{
UniqueSessionIdentifier = principalService.UniqueSessionIdentifier,
CurrentPrincipalIdentifierGuid = principalService.CurrentPrincipalIdentifierGuid,
IsAuthenticated = principalService.IsAuthenticated
};
HostingEnvironment.QueueBackgroundWorkItem(x => { SaveTheSession(sessionOperation, principal); });
}
private void AddSession(SessionOperation sessionOperation, PrincipalUserSession principalService)
{
var session = _sessionService.Get(principalService.UniqueSessionIdentifier);
if (session == null)
{
if (!principalService.CurrentPrincipalIdentifierGuid.HasValue)
{
return;
}
try
{
_semaphoreSlim.Wait();
session = _sessionService.Get(principalService.UniqueSessionIdentifier);
if (session == null)
{
var principal = _principalManagmentService.Get(principalService.CurrentPrincipalIdentifierGuid.Value);
session = _sessionService.Create(principal, principalService.UniqueSessionIdentifier);
session.Operations.Add(sessionOperation);
_repositoryService.SaveChanges(AppCoreDbContextNames.Core);
return;
}
}
finally
{
_semaphoreSlim.Release();
}
}
sessionOperation.SessionFK = session.Id;
_repositoryService.AddOnCommit(AppCoreDbContextNames.Core, sessionOperation);
_repositoryService.SaveChanges(AppCoreDbContextNames.Core);
//return session;
}
/// <summary>
/// Process operations and manage session
/// </summary>
/// <returns></returns>
private async Task RunAsync()
{
// Create a static keep alive operation object for the the session
var keepAlive = (0, new KeepAlive(_keepAlive));
// We cache the last operation and priority if operation should be
// retried next loop
SessionOperation operation = null;
var priority = 0;
var reconnect = false;
var recreate = false;
var retryCount = 0;
var everSuccessful = _persistent;
// Save identity and certificate to update session if there are changes.
var identity = _endpoint.User.ToStackModel();
try {
while (!_cts.Token.IsCancellationRequested)
{
Exception ex = null;
if (_session == null)
{
// Try create session
recreate = false;
reconnect = false;
try {
_logger.Debug("{session}: Creating new session to {url} via {endpoint}...",
_sessionId, _endpoint.Url, _endpointUrl);
_session = await CreateSessionAsync(identity);
_logger.Debug("{session}: Session to {url} via {endpoint} created.",
_sessionId, _endpoint.Url, _endpointUrl);
}
catch (Exception e) {
_logger.Information(
"{session}: {message} creating session to {url} via {endpoint} - retry.",
_sessionId, e.Message, _endpoint.Url, _endpointUrl);
_logger.Debug(e, "{session}: Error connecting - retry.",
_sessionId);
ex = e;
}
}
if (recreate)
{
// Try recreate session from current one
try {
_logger.Debug("{session}: Recreating session to {url} via {endpoint}...",
_sessionId, _endpoint.Url, _endpointUrl);
var session = await Task.Run(() => Session.Recreate(_session), _cts.Token);
_logger.Debug("{session}: Session recreated to {url} via {endpoint}.",
_sessionId, _endpoint.Url, _endpointUrl);
_session.Close();
_session = session;
recreate = false;
}
catch (Exception e) {
ex = e;
_logger.Information("{session}: {message} while recreating session " +
"to {url} via {endpoint} - create new one.",
_sessionId, e.Message, _endpoint.Url, _endpointUrl);
_logger.Debug(e, "{session}: Error connecting - create new session.",
_sessionId);
_session?.Close();
_session = null;
}
}
if (reconnect)
{
// Try reconnect the session
try {
_logger.Debug("{session}: Reconnecting session to {url} via {endpoint}...",
_sessionId, _endpoint.Url, _endpointUrl);
#pragma warning disable RECS0002 // Convert anonymous method to method group
await Task.Run(() => _session.Reconnect(), _cts.Token);
#pragma warning restore RECS0002 // Convert anonymous method to method group
_logger.Debug("{session}: Session reconnected to {url} via {endpoint}.",
_sessionId, _endpoint.Url, _endpointUrl);
reconnect = false;
}
catch (Exception e) {
ex = e;
recreate = true;
reconnect = false;
if (e is ServiceResultException sre)
{
if (sre.StatusCode == StatusCodes.BadTcpEndpointUrlInvalid ||
sre.StatusCode == StatusCodes.BadTcpInternalError ||
sre.StatusCode == StatusCodes.BadCommunicationError ||
sre.StatusCode == StatusCodes.BadNotConnected)
{
if (retryCount < kMaxReconnectAttempts && Pending > 0)
{
_logger.Information("{session}: {message} while reconnecting session" +
" to {url} via {endpoint} - retry...",
_sessionId, sre.Message, _endpoint.Url, _endpointUrl);
recreate = false;
reconnect = true; // Try again
}
}
}
_logger.Debug(e,
"{session}: Error reconnecting to {url} via {endpoint} - recreating session...",
_sessionId, _endpoint.Url, _endpointUrl);
}
}
// Failed to connect
if (recreate || reconnect || _session == null)
{
await NotifyConnectivityStateChangeAsync(ToConnectivityState(ex));
if (ex is ServiceResultException sre)
{
ex = sre.ToTypedException();
}
// Compress operations queue
var operations = new List <(int, SessionOperation)>();
while (_queue.TryDequeue(out var op))
{
if (op.Item2 == null)
{
break;
}
operations.Add(op);
}
foreach (var op in operations)
{
if (ex != null && !op.Item2.ShouldRetry(ex))
{
op.Item2.Fail(ex);
}
else if (!op.Item2.IsCompleted())
{
// Re-add the still valid ones...
_queue.Enqueue(op);
}
}
++retryCount;
if (!_persistent && retryCount > kMaxEmptyReconnectAttempts && Pending == 0)
{
_logger.Warning(
"{session}: Give up on empty non-persistent session to {url} via {endpoint}...",
_sessionId, _endpoint.Url, _endpointUrl);
break;
}
// Try again to connect with an exponential delay
var delay = Retry.GetExponentialDelay(retryCount,
kMaxReconnectDelayWhenPendingOperations / 2, kMaxRetries);
if (delay > kMaxReconnectDelayWhenPendingOperations)
{
//
// If pending operations, do not delay longer than 5 seconds
// otherwise wait for 2 hours or until new operation is queued.
//
delay = Pending != 0 ? kMaxReconnectDelayWhenPendingOperations :
kMaxReconnectDelayWhenNoPendingOperations;
}
_logger.Information("{session}: Try to connect to {url} via {endpoint} in {delay} ms...",
_sessionId, _endpoint.Url, _endpointUrl, delay);
// Wait for either the retry delay to pass or until new operation is added
await WaitForNewlyEnqueuedOperationAsync(delay);
continue;
}
// We have a session that should work for us, get next operation and
// complete it.
retryCount = 0;
recreate = false;
reconnect = false;
if (operation == null)
{
if (!_queue.TryDequeue(out var next))
{
// Wait for enqueue or keep alive timeout
var timeout = await WaitForNewlyEnqueuedOperationAsync(
(int)_keepAlive.TotalMilliseconds);
// Check cancellation
if (_cts.Token.IsCancellationRequested)
{
continue;
}
if (timeout || !_queue.TryDequeue(out next))
{
next = keepAlive;
}
}
(priority, operation) = next;
}
if (operation.IsCompleted())
{
operation = null; // Already completed because timeout or cancellation, get next
continue;
}
if (operation is KeepAlive)
{
_logger.Verbose("{session}: Sending keep alive message...", _sessionId);
}
try {
// Check if the desired user identity is the same as the current one
if (!Utils.IsEqual((operation.Identity ?? identity).GetIdentityToken(),
_session.Identity.GetIdentityToken()))
{
// Try Elevate or de-elevate session
try {
_logger.Verbose("{session}: Updating session user identity...", _sessionId);
await Task.Run(() => _session.UpdateSession(operation.Identity,
_session.PreferredLocales));
_logger.Debug("{session}: Updated session user identity.", _sessionId);
}
catch (ServiceResultException sre) {
if (StatusCodeEx.IsSecurityError(sre.StatusCode))
{
_logger.Debug(sre, "{session}: Failed updating session identity",
_sessionId);
await NotifyConnectivityStateChangeAsync(ToConnectivityState(sre));
operation.Fail(sre.ToTypedException());
operation = null;
continue;
}
throw;
}
}
await Task.Run(() => operation.Complete(_session), _cts.Token);
_lastActivity = DateTime.UtcNow;
await NotifyConnectivityStateChangeAsync(EndpointConnectivityState.Ready);
everSuccessful = true;
_logger.Verbose("{session}: Session operation completed.", _sessionId);
operation = null;
}
catch (Exception e) {
// Process exception - first convert sre into non opc exception
var oex = e;
if (e is ServiceResultException sre)
{
e = sre.ToTypedException();
}
// See which ones we can retry, and which ones we cannot
switch (e)
{
case TimeoutException te:
case ServerBusyException sb:
_logger.Debug(e, "{session}: Server timeout error.", _sessionId);
if (everSuccessful && operation.ShouldRetry(e))
{
_logger.Information("{session}: Timeout error talking to " +
"{url} via {endpoint} - {error} - try again later...",
_sessionId, _endpoint.Url, _endpointUrl, e.Message);
_queue.Enqueue(priority, operation);
operation = null;
}
else
{
reconnect = operation is KeepAlive;
if (!reconnect)
{
_logger.Error("{session}: Timeout error talking to " +
"{url} via {endpoint}- {error} - fail user operation.",
_sessionId, _endpoint.Url, _endpointUrl, e.Message);
}
operation.Fail(e);
operation = null;
}
break;
case ConnectionException cn:
case ProtocolException pe:
case CommunicationException ce:
_logger.Debug(e, "{session}: Server communication error.", _sessionId);
if (everSuccessful && operation.ShouldRetry(e))
{
_logger.Information("{session}: Communication error talking to " +
"{url} via {endpoint} - {error} - Reconnect and try again...",
_sessionId, _endpoint.Url, _endpointUrl, e.Message);
// Reconnect session
reconnect = true;
}
else
{
reconnect = operation is KeepAlive;
if (!reconnect)
{
_logger.Error("{session}: Communication error talking to " +
"{url} via {endpoint} - {error} - fail user operation.",
_sessionId, _endpoint.Url, _endpointUrl, e.Message);
}
operation.Fail(e);
operation = null;
}
break;
default:
// App error - fail and continue
_logger.Debug(e, "{session}: Application error occurred talking to " +
"{url} via {endpoint} - fail operation.",
_sessionId, _endpoint.Url, _endpointUrl, e.Message);
reconnect = operation is KeepAlive;
operation.Fail(e);
operation = null;
break;
}
if (reconnect || !everSuccessful)
{
await NotifyConnectivityStateChangeAsync(ToConnectivityState(oex, false));
}
if (!everSuccessful)
{
break; // Give up here - might have just been used to test endpoint
}
}
} // end while
}
catch (OperationCanceledException) {
// Expected on cancellation
}
catch (Exception ex) {
_logger.Error(ex, "{session}: Session operation processor exited with exception",
_sessionId);
}
finally {
if (operation != null)
{
_queue.Enqueue(priority, operation);
}
_lastActivity = DateTime.MinValue;
_logger.Verbose("{session}: Closing session...", _sessionId);
_session?.Close();
_session = null;
_logger.Debug("{session}: Session closed.", _sessionId);
}
_logger.Verbose("{session}: Processor stopped.", _sessionId);
}
