Skip to content

Commit f0b1a11

Browse files
dei79dei79
committed
Reworked the message handling to be scope aware in Azure Functions as well
1 parent 04bfb2b commit f0b1a11

File tree

15 files changed

+301
-301
lines changed

15 files changed

+301
-301
lines changed

‎.gitignore‎

Lines changed: 1 addition & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -2,3 +2,4 @@
22
bin
33
obj
44
dotNet/.idea/.idea.TaskLogging/.idea
5+
*.user

‎dotNet/CoreHelpers.Extensions.Logging.Tasks/CoreHelpers.Extensions.Logging.Tasks.csproj‎

Lines changed: 1 addition & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -11,5 +11,6 @@
1111
<ItemGroup>
1212
<PackageReference Include="Microsoft.Extensions.Logging" Version="7.0.0" />
1313
<PackageReference Include="Microsoft.Extensions.Logging.Abstractions" Version="7.0.0" />
14+
<PackageReference Include="Newtonsoft.Json" Version="13.0.3" />
1415
</ItemGroup>
1516
</Project>

‎dotNet/CoreHelpers.Extensions.Logging.Tasks/TaskLogger.cs‎

Lines changed: 120 additions & 76 deletions
Original file line numberDiff line numberDiff line change
@@ -1,108 +1,152 @@
1-
using System;
1+
using System;
22
using System.Collections.Generic;
3+
using System.Linq;
34
using CoreHelpers.TaskLogging;
45
using Microsoft.Extensions.Logging;
6+
using Newtonsoft.Json;
57

68
namespace CoreHelpers.Extensions.Logging.Tasks
79
{
810
internal class TaskLogger : ILogger
911
{
10-
private ITaskLoggerFactory _taskLoggerFactory;
12+
private readonly string _categoryName;
13+
private readonly IExternalScopeProvider _scopeProvider;
14+
private readonly ITaskLoggerFactory _taskLoggerFactory;
1115

12-
private ITaskLogger? _currentTaskLogger = null;
13-
private bool _lastLogWasAnError = false;
14-
15-
public TaskLogger(ITaskLoggerFactory taskLoggerFactory)
16+
public TaskLogger(string categoryName, IExternalScopeProvider scopeProvider, ITaskLoggerFactory taskLoggerFactory)
1617
{
18+
_categoryName = categoryName;
19+
_scopeProvider = scopeProvider;
1720
_taskLoggerFactory = taskLoggerFactory;
1821
}
19-
20-
// By default the task logging framework does not care about
21-
// unknown scopes
22-
public IDisposable? BeginScope<TState>(TState state) where TState : notnull
23-
{
24-
// check if we are interested
25-
var castedState = state as TaskLoggerState;
26-
if (castedState == null)
27-
return null;
28-
29-
// just in case a task logger is active flush
30-
if (_currentTaskLogger != null)
22+
23+
public void Log<TState>(LogLevel logLevel, EventId eventId, TState state, Exception? exception, Func<TState, Exception?, string> formatter)
24+
{
25+
// check if the log level is enabled
26+
if (!IsEnabled(logLevel))
27+
return;
28+
29+
// collect ITaskLoggerTypedScope from the scope provider
30+
var scopes = new List<object>();
31+
_scopeProvider.ForEachScope((scope, list) => list.Add(scope), scopes);
32+
33+
// filter for the task logger scope, if not in the list nothing todo
34+
var taskLoggerState = scopes.FirstOrDefault(scope => scope is TaskLoggerState typed) as TaskLoggerState;
35+
if (taskLoggerState == null)
36+
return;
37+
38+
// check if we need to announce the task as it was not announced before
39+
if (eventId is { Id: 0, Name: "TaskScopeInitPending" })
3140
{
32-
_currentTaskLogger.Dispose();
33-
_lastLogWasAnError = false;
34-
}
41+
if (taskLoggerState.IsTaskAnnounced && !string.IsNullOrEmpty(taskLoggerState.TaskId))
42+
return;
3543

36-
// check if we need to announce the task
37-
if (!castedState.IsTaskAnnounced)
38-
{
39-
if (String.IsNullOrEmpty(castedState.MetaData))
44+
if (String.IsNullOrEmpty(taskLoggerState.MetaData))
4045
{
41-
castedState.TaskId = _taskLoggerFactory
42-
.AnnounceTask(castedState.TaskType, castedState.TaskSource, castedState.TaskWorker).GetAwaiter()
46+
taskLoggerState.TaskId = _taskLoggerFactory
47+
.AnnounceTask(taskLoggerState.TaskType, taskLoggerState.TaskSource, taskLoggerState.TaskWorker).GetAwaiter()
4348
.GetResult();
4449
}
4550
else
4651
{
47-
castedState.TaskId = _taskLoggerFactory
48-
.AnnounceTask(castedState.TaskType, castedState.TaskSource, castedState.TaskWorker, castedState.MetaData).GetAwaiter()
52+
taskLoggerState.TaskId = _taskLoggerFactory
53+
.AnnounceTask(taskLoggerState.TaskType, taskLoggerState.TaskSource, taskLoggerState.TaskWorker, taskLoggerState.MetaData).GetAwaiter()
4954
.GetResult();
5055
}
5156

52-
castedState.IsTaskAnnounced = true;
57+
taskLoggerState.IsTaskAnnounced = true;
58+
59+
return;
5360
}
5461

55-
// set a new task logger
56-
_currentTaskLogger = _taskLoggerFactory.CreateTaskLogger(castedState.TaskId);
57-
58-
// ensure the task is running now
59-
_taskLoggerFactory.UpdateTaskStatus(castedState.TaskId, TaskStatus.Running, castedState.TaskWorker).GetAwaiter().GetResult();
60-
61-
// done
62-
return new TaskLoggerScope(castedState, this);
62+
// check if we need to set the task as running
63+
if (eventId is { Id: 0, Name: "TaskScopeStarted" })
64+
{
65+
_taskLoggerFactory.UpdateTaskStatus(taskLoggerState.TaskId, TaskStatus.Running).Wait();
66+
return;
67+
}
68+
69+
// in case of exception, we need to log it more in details
70+
if (exception != null)
71+
{
72+
// set the last log as error so that the task will be marked as failed
73+
taskLoggerState.LastLogWasAnError = true;
74+
75+
// render the exception
76+
LogException(logLevel, exception, formatter);
77+
return;
78+
}
79+
80+
// lock the messages to avoid concurrency issues
81+
lock (taskLoggerState.PendingMessages)
82+
{
83+
// check if we received the dispose message
84+
if (eventId is { Id: 0, Name: "TaskScopeDisposed" })
85+
{
86+
// at this point we need to flush if needed
87+
taskLoggerState.PendingMessages = new List<string>(_taskLoggerFactory.MergePendingMessagesIfNeeded(DateTimeOffset.Now, true, taskLoggerState.TaskId, taskLoggerState.PendingMessages.ToArray()).GetAwaiter().GetResult());
88+
89+
// ensure the task is finished now
90+
_taskLoggerFactory.UpdateTaskStatus(taskLoggerState.TaskId, taskLoggerState.LastLogWasAnError ? TaskStatus.Failed : TaskStatus.Succeed).GetAwaiter().GetResult();
91+
}
92+
// check if we need to flush the messages
93+
else if (eventId is { Id: 0, Name: "TaskScopeFlushRequired" })
94+
{
95+
// at this point we need to flush if needed
96+
taskLoggerState.PendingMessages = new List<string>(_taskLoggerFactory.MergePendingMessagesIfNeeded(DateTimeOffset.Now, true, taskLoggerState.TaskId, taskLoggerState.PendingMessages.ToArray()).GetAwaiter().GetResult());
97+
}
98+
else
99+
{
100+
// get the formated message
101+
var msg = formatter(state, exception);
102+
if (msg == null)
103+
return;
104+
105+
// at this point we need to add the message to the scope
106+
taskLoggerState.PendingMessages.Add(msg);
107+
108+
// at this point we need to flush if needed
109+
taskLoggerState.PendingMessages = new List<string>(_taskLoggerFactory.MergePendingMessagesIfNeeded(DateTimeOffset.Now, false, taskLoggerState.TaskId, taskLoggerState.PendingMessages.ToArray()).GetAwaiter().GetResult());
110+
}
111+
}
63112
}
64-
65-
// All levels are eanbled
66-
public bool IsEnabled(LogLevel logLevel) => true;
67-
68-
// allow to log
69-
public void Log<TState>(LogLevel logLevel, EventId eventId, TState state, Exception? exception, Func<TState, Exception?, string> formatter)
113+
114+
private void LogException<TState>(LogLevel logLevel, Exception exception, Func<TState, Exception?, string> formatter, bool innerException = false)
70115
{
71-
if (_currentTaskLogger == null)
72-
return;
73-
74-
// adjust the log level
75-
var taskLogLevel = TaskLogLevel.Information;
76-
if (logLevel == LogLevel.Error || logLevel == LogLevel.Critical)
77-
taskLogLevel = TaskLogLevel.Error;
78-
79-
// log
80-
_currentTaskLogger.Log(taskLogLevel, formatter(state, exception), exception);
81-
82-
// remember the exception
83-
if (logLevel == LogLevel.Error)
84-
_lastLogWasAnError = true;
116+
if (innerException)
117+
this.Log(logLevel, $"Inner Exception: {exception.Message}", null, formatter);
85118
else
86-
_lastLogWasAnError = false;
119+
{
120+
this.Log(logLevel, $"Error with exception: {exception.Message}", null, formatter);
121+
try
122+
{
123+
this.Log(logLevel, "Dumping Raw-JSON-Export of the exception", null, formatter);
124+
this.Log(logLevel, JsonConvert.SerializeObject(exception), null, formatter);
125+
}
126+
catch (Exception)
127+
{
128+
// The exception is catched without handling to prevent
129+
// crashed just because of invalid JSON message we try to log
130+
}
131+
}
87132

88-
}
133+
if (exception.StackTrace != null)
134+
{
135+
var splittedError = exception.StackTrace.Split('\n');
136+
foreach (var el in splittedError)
137+
this.Log(logLevel, el, null, formatter);
138+
}
89139

90-
// ensure we write all backe
91-
public void DisposeScope(TaskLoggerState state, TaskLoggerScope scope)
92-
{
93-
if (_currentTaskLogger != null)
94-
{
95-
// write all messages back
96-
_currentTaskLogger.Dispose();
97-
_currentTaskLogger = null;
140+
if (exception.InnerException != null)
141+
LogException(logLevel, exception.InnerException, formatter, true);
142+
}
98143

99-
// ensure the task is finished now
100-
_taskLoggerFactory.UpdateTaskStatus(state.TaskId, _lastLogWasAnError ? TaskStatus.Failed : TaskStatus.Succeed).GetAwaiter().GetResult();
144+
public bool IsEnabled(LogLevel logLevel)
145+
=> true;
101146

102-
// reset the exception
103-
_lastLogWasAnError = false;
104-
}
105-
}
147+
public IDisposable? BeginScope<TState>(TState state) where TState : notnull
148+
{
149+
return _scopeProvider.Push(state);
150+
}
106151
}
107-
}
108-
152+
}

‎dotNet/CoreHelpers.Extensions.Logging.Tasks/TaskLoggerExtension.cs‎

Lines changed: 13 additions & 11 deletions
Original file line numberDiff line numberDiff line change
@@ -1,5 +1,4 @@
11
using System;
2-
using System.Runtime.CompilerServices;
32
using CoreHelpers.TaskLogging;
43
using Microsoft.Extensions.Logging;
54
using Microsoft.Extensions.DependencyInjection;
@@ -14,25 +13,28 @@ public static ILoggingBuilder AddTaskLogger(this ILoggingBuilder builder)
1413
return builder;
1514
}
1615

17-
public static ITaskLoggerTypedScope? BeginTaskScope(this ILogger logger, string taskId)
18-
=> BeginTypedTaskScope(logger, new TaskLoggerState() { TaskId = taskId, IsTaskAnnounced = true });
16+
public static ITaskLoggerScope? BeginTaskScope(this ILogger logger, string taskId, TimeSpan? cacheTimeSpan = null)
17+
=> BeginTypedTaskScope(logger, new TaskLoggerState() { TaskId = taskId, IsTaskAnnounced = true, CacheTimeSpan = cacheTimeSpan ?? TimeSpan.FromSeconds(30) });
1918

20-
public static ITaskLoggerTypedScope? BeginTaskScope(this ILogger logger, string taskId, string taskWorker)
21-
=> BeginTypedTaskScope(logger, new TaskLoggerState() { TaskId = taskId, IsTaskAnnounced = true, TaskWorker = taskWorker });
19+
public static ITaskLoggerScope? BeginTaskScope(this ILogger logger, string taskId, string taskWorker, TimeSpan? cacheTimeSpan = null)
20+
=> BeginTypedTaskScope(logger, new TaskLoggerState() { TaskId = taskId, IsTaskAnnounced = true, TaskWorker = taskWorker, CacheTimeSpan = cacheTimeSpan ?? TimeSpan.FromSeconds(30) });
2221

23-
public static ITaskLoggerTypedScope? BeginNewTaskScope(this ILogger logger, string taskType, string taskSource, string taskWorker)
24-
=> BeginTypedTaskScope(logger, new TaskLoggerState() { TaskId = string.Empty, TaskType = taskType, TaskSource = taskSource, TaskWorker = taskWorker, IsTaskAnnounced = false });
22+
public static ITaskLoggerScope? BeginNewTaskScope(this ILogger logger, string taskType, string taskSource, string taskWorker, TimeSpan? cacheTimeSpan = null)
23+
=> BeginTypedTaskScope(logger, new TaskLoggerState() { TaskId = string.Empty, TaskType = taskType, TaskSource = taskSource, TaskWorker = taskWorker, IsTaskAnnounced = false, CacheTimeSpan = cacheTimeSpan ?? TimeSpan.FromSeconds(30) });
2524

26-
public static ITaskLoggerTypedScope? BeginNewTaskScope(this ILogger logger, string taskType, string taskSource, string taskWorker, string metaDataString)
27-
=> BeginTypedTaskScope(logger, new TaskLoggerState() { TaskId = string.Empty, TaskType = taskType, TaskSource = taskSource, TaskWorker = taskWorker, IsTaskAnnounced = false, MetaData = metaDataString });
25+
public static ITaskLoggerScope? BeginNewTaskScope(this ILogger logger, string taskType, string taskSource, string taskWorker, string metaDataString, TimeSpan? cacheTimeSpan = null)
26+
=> BeginTypedTaskScope(logger, new TaskLoggerState() { TaskId = string.Empty, TaskType = taskType, TaskSource = taskSource, TaskWorker = taskWorker, IsTaskAnnounced = false, MetaData = metaDataString, CacheTimeSpan = cacheTimeSpan ?? TimeSpan.FromSeconds(30) });
2827

29-
private static ITaskLoggerTypedScope? BeginTypedTaskScope(ILogger logger, TaskLoggerState taskLoggerState)
28+
public static ITaskLoggerScope? BeginNewTaskScopeWithExternalId(this ILogger logger, string taskId, string taskType, string taskSource, string taskWorker, string metaDataString, TimeSpan? cacheTimeSpan = null)
29+
=> BeginTypedTaskScope(logger, new TaskLoggerState() { TaskId = taskId, TaskType = taskType, TaskSource = taskSource, TaskWorker = taskWorker, IsTaskAnnounced = false, MetaData = metaDataString, CacheTimeSpan = cacheTimeSpan ?? TimeSpan.FromSeconds(30) });
30+
31+
private static ITaskLoggerScope? BeginTypedTaskScope(ILogger logger, TaskLoggerState taskLoggerState)
3032
{
3133
var innerDisposable = logger.BeginScope<TaskLoggerState>(taskLoggerState);
3234
if (innerDisposable == null)
3335
return null;
3436

35-
return new TaskLoggerTypedScope(taskLoggerState, innerDisposable);
37+
return new TaskLoggerScope(logger, taskLoggerState, innerDisposable);
3638
}
3739
}
3840
}

‎dotNet/CoreHelpers.Extensions.Logging.Tasks/TaskLoggerProvider.cs‎

Lines changed: 14 additions & 20 deletions
Original file line numberDiff line numberDiff line change
@@ -1,31 +1,25 @@
1-
using System;
1+
using System;
22
using CoreHelpers.TaskLogging;
33
using Microsoft.Extensions.Logging;
44

55
namespace CoreHelpers.Extensions.Logging.Tasks
66
{
7-
internal class TaskLoggerProvider : ILoggerProvider
8-
{
9-
private ITaskLoggerFactory _taskLoggerFactory;
10-
private ILogger? _activeLogger = null;
11-
7+
internal class TaskLoggerProvider : ILoggerProvider, ISupportExternalScope
8+
{
9+
private readonly ITaskLoggerFactory _taskLoggerFactory;
10+
private IExternalScopeProvider? _scopeProvider;
11+
1212
public TaskLoggerProvider(ITaskLoggerFactory taskLoggerFactory)
13-
{
13+
{
1414
_taskLoggerFactory = taskLoggerFactory;
15-
}
15+
}
16+
17+
public void Dispose() { }
1618

1719
public ILogger CreateLogger(string categoryName)
18-
{
19-
if (_activeLogger == null)
20-
_activeLogger = new TaskLogger(_taskLoggerFactory);
20+
=> new TaskLogger(categoryName, _scopeProvider ?? new LoggerExternalScopeProvider(), _taskLoggerFactory);
2121

22-
return _activeLogger;
23-
}
24-
25-
public void Dispose()
26-
{
27-
28-
}
22+
public void SetScopeProvider(IExternalScopeProvider scopeProvider)
23+
=> _scopeProvider = scopeProvider;
2924
}
30-
}
31-
25+
}

‎dotNet/CoreHelpers.Extensions.Logging.Tasks/TaskLoggerScope.cs‎

Lines changed: 35 additions & 14 deletions
Original file line numberDiff line numberDiff line change
@@ -1,21 +1,42 @@
1-
using System;
1+
using System;
2+
using System.Threading;
3+
using CoreHelpers.TaskLogging;
4+
using Microsoft.Extensions.Logging;
5+
26
namespace CoreHelpers.Extensions.Logging.Tasks
37
{
4-
internal class TaskLoggerScope : IDisposable
5-
{
6-
private TaskLogger _taskLogger;
7-
private TaskLoggerState _taskState;
8-
9-
public TaskLoggerScope(TaskLoggerState taskState, TaskLogger taskLogger)
10-
{
11-
_taskLogger = taskLogger;
12-
_taskState = taskState;
13-
}
8+
internal class TaskLoggerScope : ITaskLoggerScope
9+
{
10+
private readonly ILogger _logger;
11+
private readonly TaskLoggerState _taskLoggerState;
12+
private readonly IDisposable _innerDisposable;
13+
private readonly Timer _flushTimer;
1414

15+
public TaskLoggerScope(ILogger logger, TaskLoggerState taskLoggerState, IDisposable innerDisposable)
16+
{
17+
_logger = logger;
18+
_taskLoggerState = taskLoggerState;
19+
_innerDisposable = innerDisposable;
20+
21+
if (!taskLoggerState.IsTaskAnnounced)
22+
_logger.Log(LogLevel.None, new EventId(0, "TaskScopeInitPending"), string.Empty);
23+
24+
_logger.Log(LogLevel.None, new EventId(0, "TaskScopeStarted"),string.Empty);
25+
26+
_flushTimer = new Timer((state) => {
27+
_logger.Log(LogLevel.None, new EventId(0, "TaskScopeFlushRequired"), string.Empty);
28+
}, null, taskLoggerState.CacheTimeSpan, taskLoggerState.CacheTimeSpan);
29+
}
1530
public void Dispose()
1631
{
17-
_taskLogger.DisposeScope(_taskState, this);
32+
_flushTimer.Dispose();
33+
_logger.Log(LogLevel.None, new EventId(0, "TaskScopeDisposed"), string.Empty);
34+
_innerDisposable.Dispose();
1835
}
19-
}
20-
}
2136

37+
public string TaskId => _taskLoggerState.TaskId;
38+
public string TaskType => _taskLoggerState.TaskType;
39+
public string TaskSource => _taskLoggerState.TaskSource;
40+
public string TaskWorker => _taskLoggerState.TaskWorker;
41+
}
42+
}

0 commit comments

Comments
 (0)