Skip to content

Commit 417343d

Browse files
authored
feat(logging): add ExtraKeys to logger (#1128)
1 parent 9055519 commit 417343d

6 files changed

Lines changed: 1025 additions & 124 deletions

File tree

docs/core/logging.md

Lines changed: 118 additions & 3 deletions
Original file line numberDiff line numberDiff line change
@@ -604,10 +604,125 @@ You can remove any additional key from entry using `Logger.RemoveKeys()`.
604604
}
605605
```
606606

607-
## Extra Keys
607+
### Temporary keys with ExtraKeys
608608

609-
Extra keys allow you to append additional keys to a log entry. Unlike `AppendKey`, extra keys will only apply to the
610-
current log entry.
609+
The `ExtraKeys` method allows temporary modification of the Logger's context without manual cleanup. It's useful for adding context keys to specific workflows while maintaining the logger's overall state.
610+
611+
Keys are automatically removed when the scope ends, eliminating the need to manually call `AppendKey` and `RemoveKeys`.
612+
613+
=== "Using Dictionary"
614+
615+
```c# hl_lines="12-16"
616+
/**
617+
* Handler for requests to Lambda function.
618+
*/
619+
public class Function
620+
{
621+
[Logging]
622+
public async Task<APIGatewayProxyResponse> FunctionHandler
623+
(APIGatewayProxyRequest apigProxyEvent, ILambdaContext context)
624+
{
625+
var orderId = apigProxyEvent.PathParameters["orderId"];
626+
627+
using (Logger.ExtraKeys(new Dictionary<string, object> { { "orderId", orderId } }))
628+
{
629+
Logger.LogInformation("Processing order");
630+
await ProcessOrderAsync(orderId);
631+
Logger.LogInformation("Order processed"); // orderId included
632+
}
633+
// orderId is automatically removed
634+
635+
Logger.LogInformation("Continuing without orderId");
636+
}
637+
}
638+
```
639+
640+
=== "Using Tuples"
641+
642+
```c# hl_lines="12-16"
643+
/**
644+
* Handler for requests to Lambda function.
645+
*/
646+
public class Function
647+
{
648+
[Logging]
649+
public async Task<APIGatewayProxyResponse> FunctionHandler
650+
(APIGatewayProxyRequest apigProxyEvent, ILambdaContext context)
651+
{
652+
var orderId = apigProxyEvent.PathParameters["orderId"];
653+
654+
using (Logger.ExtraKeys(("orderId", orderId), ("customerId", "customer-123")))
655+
{
656+
Logger.LogInformation("Processing order");
657+
await ProcessOrderAsync(orderId);
658+
Logger.LogInformation("Order processed"); // orderId and customerId included
659+
}
660+
// Both keys are automatically removed
661+
}
662+
}
663+
```
664+
665+
=== "Nested Scopes"
666+
667+
```c# hl_lines="10-19"
668+
/**
669+
* Handler for requests to Lambda function.
670+
*/
671+
public class Function
672+
{
673+
[Logging]
674+
public async Task<APIGatewayProxyResponse> FunctionHandler
675+
(APIGatewayProxyRequest apigProxyEvent, ILambdaContext context)
676+
{
677+
using (Logger.ExtraKeys(("requestId", context.AwsRequestId)))
678+
{
679+
Logger.LogInformation("Starting request"); // requestId included
680+
681+
using (Logger.ExtraKeys(("step", "validation")))
682+
{
683+
Logger.LogInformation("Validating"); // requestId AND step included
684+
}
685+
// step removed, requestId still present
686+
687+
Logger.LogInformation("Request complete"); // only requestId
688+
}
689+
}
690+
}
691+
```
692+
693+
=== "Example CloudWatch Logs excerpt"
694+
695+
```json hl_lines="14 15"
696+
{
697+
"level": "Information",
698+
"message": "Processing order",
699+
"timestamp": "2024-01-15T10:30:00.0000000Z",
700+
"service": "order-service",
701+
"cold_start": true,
702+
"function_name": "OrderProcessor",
703+
"function_memory_size": 256,
704+
"function_arn": "arn:aws:lambda:eu-west-1:123456789:function:OrderProcessor",
705+
"function_request_id": "abc-123-def",
706+
"function_version": "$LATEST",
707+
"xray_trace_id": "1-abc-123",
708+
"name": "AWS.Lambda.Powertools.Logging.Logger",
709+
"order_id": "order-456",
710+
"customer_id": "customer-123"
711+
}
712+
```
713+
714+
!!! tip "When to use ExtraKeys vs AppendKey"
715+
Use `ExtraKeys` when you need keys for a specific operation or code block. Use `AppendKey` when keys should persist for the entire Lambda invocation.
716+
717+
!!! warning "Key overwrite behavior"
718+
If a key already exists when entering an `ExtraKeys` scope, it will be overwritten and then **removed** when the scope ends. The original value is not restored. Use unique key names within `ExtraKeys` scopes to avoid unexpected behavior.
719+
720+
!!! info "Async safe"
721+
`ExtraKeys` is safe to use across `async/await` boundaries. Keys will correctly flow through asynchronous operations within the same execution context.
722+
723+
## Extra Keys (Single Log Entry)
724+
725+
Extra keys can also be added to a single log entry using message templates. Unlike `AppendKey` or `ExtraKeys()`, these keys will only apply to the current log entry.
611726

612727
Extra keys argument is available for all log levels' methods, as implemented in the standard logging library - e.g.
613728
Logger.Information, Logger.Warning.

libraries/src/AWS.Lambda.Powertools.Logging/Logger.Scope.cs

Lines changed: 147 additions & 20 deletions
Original file line numberDiff line numberDiff line change
@@ -11,24 +11,63 @@ namespace AWS.Lambda.Powertools.Logging;
1111
public static partial class Logger
1212
{
1313
/// <summary>
14-
/// Thread-safe dictionary for per-thread scope storage.
15-
/// Uses ManagedThreadId as key to ensure isolation when Lambda processes
16-
/// multiple concurrent requests (AWS_LAMBDA_MAX_CONCURRENCY > 1).
17-
/// Inner dictionary is ConcurrentDictionary for thread-safe operations.
14+
/// AsyncLocal storage for per-invocation scope.
15+
/// Uses AsyncLocal to ensure keys flow correctly across async/await boundaries.
16+
///
17+
/// In Lambda's multi-threaded mode, each invocation starts with a fresh execution
18+
/// context, providing natural isolation between concurrent invocations.
19+
/// Keys added via AppendKey flow across async/await within the same invocation.
1820
/// </summary>
19-
private static readonly ConcurrentDictionary<int, ConcurrentDictionary<string, object>> _threadScopes = new();
21+
private static readonly AsyncLocal<ConcurrentDictionary<string, object>> _asyncScope = new();
2022

2123
/// <summary>
22-
/// Gets the scope for the current thread.
23-
/// Creates a new dictionary if one doesn't exist for this thread.
24+
/// Gets the scope for the current async execution context.
25+
/// Creates a new dictionary if one doesn't exist for this context.
2426
/// </summary>
2527
/// <value>The scope.</value>
2628
private static ConcurrentDictionary<string, object> Scope
2729
{
2830
get
2931
{
30-
var threadId = Environment.CurrentManagedThreadId;
31-
return _threadScopes.GetOrAdd(threadId, _ => new ConcurrentDictionary<string, object>(StringComparer.Ordinal));
32+
var scope = _asyncScope.Value;
33+
if (scope == null)
34+
{
35+
scope = new ConcurrentDictionary<string, object>(StringComparer.Ordinal);
36+
_asyncScope.Value = scope;
37+
}
38+
return scope;
39+
}
40+
}
41+
42+
/// <summary>
43+
/// Creates a new isolated scope for the current execution context.
44+
/// Used internally to simulate Lambda invocation isolation in tests.
45+
/// </summary>
46+
/// <returns>An IDisposable that restores the previous scope when disposed.</returns>
47+
internal static IDisposable UseScope()
48+
{
49+
return new LoggerScopeContext();
50+
}
51+
52+
/// <summary>
53+
/// Manages a new isolated scope context.
54+
/// </summary>
55+
private sealed class LoggerScopeContext : IDisposable
56+
{
57+
private readonly ConcurrentDictionary<string, object> _previousScope;
58+
private bool _disposed;
59+
60+
public LoggerScopeContext()
61+
{
62+
_previousScope = _asyncScope.Value;
63+
_asyncScope.Value = new ConcurrentDictionary<string, object>(StringComparer.Ordinal);
64+
}
65+
66+
public void Dispose()
67+
{
68+
if (_disposed) return;
69+
_disposed = true;
70+
_asyncScope.Value = _previousScope;
3271
}
3372
}
3473

@@ -49,7 +88,8 @@ public static string CorrelationId
4988
}
5089

5190
/// <summary>
52-
/// Appending additional key to the log context.
91+
/// Appends a key-value pair to the log context.
92+
/// Keys persist across async/await boundaries within the same execution context.
5393
/// </summary>
5494
/// <param name="key">The key.</param>
5595
/// <param name="value">The value.</param>
@@ -66,7 +106,7 @@ public static void AppendKey(string key, object value)
66106
}
67107

68108
/// <summary>
69-
/// Appending additional key to the log context.
109+
/// Appends multiple keys to the log context.
70110
/// </summary>
71111
/// <param name="keys">The list of keys.</param>
72112
public static void AppendKeys(IEnumerable<KeyValuePair<string, object>> keys)
@@ -76,7 +116,7 @@ public static void AppendKeys(IEnumerable<KeyValuePair<string, object>> keys)
76116
}
77117

78118
/// <summary>
79-
/// Appending additional key to the log context.
119+
/// Appends multiple keys to the log context.
80120
/// </summary>
81121
/// <param name="keys">The list of keys.</param>
82122
public static void AppendKeys(IEnumerable<KeyValuePair<string, string>> keys)
@@ -86,7 +126,7 @@ public static void AppendKeys(IEnumerable<KeyValuePair<string, string>> keys)
86126
}
87127

88128
/// <summary>
89-
/// Remove additional keys from the log context.
129+
/// Removes keys from the log context.
90130
/// </summary>
91131
/// <param name="keys">The list of keys.</param>
92132
public static void RemoveKeys(params string[] keys)
@@ -97,7 +137,7 @@ public static void RemoveKeys(params string[] keys)
97137
}
98138

99139
/// <summary>
100-
/// Returns all additional keys added to the log context.
140+
/// Returns all keys added to the log context.
101141
/// Returns a snapshot to ensure thread-safety during enumeration.
102142
/// </summary>
103143
/// <returns>IEnumerable&lt;KeyValuePair&lt;System.String, System.Object&gt;&gt;.</returns>
@@ -108,15 +148,11 @@ public static IEnumerable<KeyValuePair<string, object>> GetAllKeys()
108148
}
109149

110150
/// <summary>
111-
/// Removes all additional keys from the log context for the current thread.
151+
/// Removes all keys from the log context for the current execution context.
112152
/// </summary>
113153
internal static void RemoveAllKeys()
114154
{
115-
var threadId = Environment.CurrentManagedThreadId;
116-
if (_threadScopes.TryGetValue(threadId, out var scope))
117-
{
118-
scope.Clear();
119-
}
155+
_asyncScope.Value?.Clear();
120156
}
121157

122158
/// <summary>
@@ -126,4 +162,95 @@ public static void RemoveKey(string key)
126162
{
127163
Scope.TryRemove(key, out _);
128164
}
165+
166+
/// <summary>
167+
/// Adds temporary keys to the log context that are automatically removed when disposed.
168+
/// Safe to use across async/await boundaries.
169+
/// </summary>
170+
/// <param name="keys">The keys to add temporarily.</param>
171+
/// <returns>An IDisposable that removes the keys when disposed.</returns>
172+
/// <remarks>
173+
/// <para>
174+
/// <b>Important:</b> If a key already exists in the context, it will be overwritten
175+
/// and then removed when the scope is disposed. The original value is NOT restored.
176+
/// </para>
177+
/// <para>
178+
/// For example, if "orderId" = "A" exists and you create a scope with "orderId" = "B",
179+
/// disposing the scope will remove "orderId" entirely, not restore it to "A".
180+
/// </para>
181+
/// </remarks>
182+
/// <example>
183+
/// <code>
184+
/// using (Logger.ExtraKeys(new Dictionary&lt;string, object&gt; { {"orderId", "123"} }))
185+
/// {
186+
/// await ProcessOrderAsync();
187+
/// Logger.LogInformation("Order processed"); // includes orderId
188+
/// }
189+
/// // orderId is automatically removed
190+
/// </code>
191+
/// </example>
192+
public static IDisposable ExtraKeys(IEnumerable<KeyValuePair<string, object>> keys)
193+
{
194+
if (keys == null) throw new ArgumentNullException(nameof(keys));
195+
return new LoggerExtraKeysScope(keys);
196+
}
197+
198+
/// <summary>
199+
/// Adds temporary keys to the log context that are automatically removed when disposed.
200+
/// Safe to use across async/await boundaries.
201+
/// </summary>
202+
/// <param name="keys">The keys to add temporarily as tuples.</param>
203+
/// <returns>An IDisposable that removes the keys when disposed.</returns>
204+
/// <remarks>
205+
/// <para>
206+
/// <b>Important:</b> If a key already exists in the context, it will be overwritten
207+
/// and then removed when the scope is disposed. The original value is NOT restored.
208+
/// </para>
209+
/// </remarks>
210+
/// <example>
211+
/// <code>
212+
/// using (Logger.ExtraKeys(("orderId", "123"), ("customerId", "456")))
213+
/// {
214+
/// Logger.LogInformation("Processing"); // includes orderId and customerId
215+
/// }
216+
/// </code>
217+
/// </example>
218+
public static IDisposable ExtraKeys(params (string Key, object Value)[] keys)
219+
{
220+
if (keys == null) throw new ArgumentNullException(nameof(keys));
221+
return new LoggerExtraKeysScope(keys.Select(k => new KeyValuePair<string, object>(k.Key, k.Value)));
222+
}
223+
224+
/// <summary>
225+
/// Scope that manages temporary logging keys.
226+
/// Keys are added on construction and removed on disposal.
227+
/// </summary>
228+
private sealed class LoggerExtraKeysScope : IDisposable
229+
{
230+
private readonly string[] _keysToRemove;
231+
private bool _disposed;
232+
233+
public LoggerExtraKeysScope(IEnumerable<KeyValuePair<string, object>> keys)
234+
{
235+
var keyList = new List<string>();
236+
237+
foreach (var (key, value) in keys)
238+
{
239+
if (string.IsNullOrWhiteSpace(key)) continue;
240+
241+
AppendKey(key, value);
242+
keyList.Add(key);
243+
}
244+
245+
_keysToRemove = keyList.ToArray();
246+
}
247+
248+
public void Dispose()
249+
{
250+
if (_disposed) return;
251+
_disposed = true;
252+
253+
RemoveKeys(_keysToRemove);
254+
}
255+
}
129256
}

0 commit comments

Comments
 (0)