Skip to content

Nested BeginScope doesn't replace existing keys #267

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

Closed
RogueJay opened this issue Feb 7, 2025 · 4 comments · Fixed by #269
Closed

Nested BeginScope doesn't replace existing keys #267

RogueJay opened this issue Feb 7, 2025 · 4 comments · Fixed by #269
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 👍

@nblumhardt
Copy link
Member

Thanks for spotting this; I've opened PR #269 to fix.

@nblumhardt
Copy link
Member

Hi! The latest 9.0.1 dev build has the fix, if you're able to check it out a confirmation would be appreciated. Cheers!

@RogueJay
Copy link
Author

Hi.

Just wanted to confirm that the latest preview does indeed fix the issue.

Thanks 🙂

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

Successfully merging a pull request may close this issue.

2 participants