Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Nested BeginScope doesn't replace existing keys #267

Open
RogueJay opened this issue Feb 7, 2025 · 1 comment
Open

Nested BeginScope doesn't replace existing keys #267

RogueJay opened this issue Feb 7, 2025 · 1 comment
Labels

Comments

@RogueJay
Copy link

RogueJay commented Feb 7, 2025

In version 8, if you nested a BeginScope using the same KeyValue pair, the inner scope would use the newest value.
In version 9, the inner scope value does not replace the existing value.

The following is an XUnit test that works in 8 and fails in 9

		[Fact]
		public void LoggingScope_ReplaceExecutionTagProperty_yWhenCalledTwicetest()
		{
			// Create a context for this specific test to isolate log messages
			using (Serilog.Sinks.TestCorrelator.TestCorrelator.CreateContext())
			using (var logger = new Serilog.LoggerConfiguration().WriteTo.Sink(new TestCorrelatorSink()).Enrich.FromLogContext().CreateLogger())
			{
				Log.Logger = logger;

				var services = new ServiceCollection();
				services.AddLogging(l => l.AddSerilog());

				using var serviceProvider = services.BuildServiceProvider();
				var msLogger = serviceProvider.GetRequiredService<ILogger<Program>>();

				using (msLogger.BeginScope(new Dictionary<string, object> { { ContextProperties.EXECUTION_TAGS, "[TAG1]" } }))
				{
					msLogger.LogInformation("Message1");
					using (msLogger.BeginScope(new Dictionary<string, object> { { ContextProperties.EXECUTION_TAGS, "[TAG2]" } }))
					{
						msLogger.LogInformation("Message2");
					}
				}

				var logEvent = GetLogEvent("Message1");
				Assert.NotNull(logEvent);
				ValidateProperty(logEvent, ContextProperties.EXECUTION_TAGS, "[TAG1]");

				logEvent = GetLogEvent("Message2");
				Assert.NotNull(logEvent);
				ValidateProperty(logEvent, ContextProperties.EXECUTION_TAGS, "[TAG2]");   <-- FAILS BECAUSE TAG1 IS STILL USED
			}
		}

		private static LogEvent? GetLogEvent(string message)
			=> TestCorrelator.GetLogEventsFromCurrentContext().FirstOrDefault(e => e.MessageTemplate.Text == message);

		private static void ValidateProperty(LogEvent logEvent, string name, string value)
		{
			Assert.Contains(name, logEvent.Properties.Keys);
			Assert.True(logEvent.Properties.TryGetValue(name, out LogEventPropertyValue? result));
			Assert.Equal(value, result.ToString().Replace("\"", ""));
		}

I don't know if this is related, but looking at the stack at the point Message2 is about to be logged, I see the following. For version 8.0, the Scopes variable is null

Image

@nblumhardt nblumhardt added the bug label Feb 8, 2025
@nblumhardt
Copy link
Member

Thanks for the report! Looks like a good find 👍

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
Projects
None yet
Development

No branches or pull requests

2 participants