Skip to content

Commit fe7f775

Browse files
vonzshikvonzshik
authored
Fix logging parameters with batches (#6079)
Fixes #6078
1 parent 892774f commit fe7f775

File tree

4 files changed

+51
-16
lines changed

4 files changed

+51
-16
lines changed

‎src/Npgsql/LogMessages.cs‎

Lines changed: 2 additions & 2 deletions
Original file line numberDiff line numberDiff line change
@@ -180,7 +180,7 @@ static partial class LogMessages
180180
Level = LogLevel.Debug,
181181
Message = "Executing batch: {BatchCommands}",
182182
SkipEnabledCheck = true)]
183-
internal static partial void ExecutingBatchWithParameters(ILogger logger, (string CommandText, object[] Parameters)[] BatchCommands, int ConnectorId);
183+
internal static partial void ExecutingBatchWithParameters(ILogger logger, (string CommandText, IEnumerable<object> Parameters)[] BatchCommands, int ConnectorId);
184184

185185
[LoggerMessage(
186186
EventId = NpgsqlEventId.CommandExecutionCompleted,
@@ -209,7 +209,7 @@ static partial class LogMessages
209209
Message = "Batch execution completed (duration={DurationMs}ms): {BatchCommands}",
210210
SkipEnabledCheck = true)]
211211
internal static partial void BatchExecutionCompletedWithParameters(
212-
ILogger logger, (string CommandText, object[] Parameters)[] BatchCommands, long DurationMs, int ConnectorId);
212+
ILogger logger, (string CommandText, IEnumerable<object> Parameters)[] BatchCommands, long DurationMs, int ConnectorId);
213213

214214
[LoggerMessage(
215215
EventId = NpgsqlEventId.CancellingCommand,

‎src/Npgsql/NpgsqlCommand.cs‎

Lines changed: 3 additions & 2 deletions
Original file line numberDiff line numberDiff line change
@@ -1823,6 +1823,7 @@ internal void LogExecutingCompleted(NpgsqlConnector connector, bool executing)
18231823
{
18241824
var logParameters = connector.LoggingConfiguration.IsParameterLoggingEnabled || connector.Settings.LogParameters;
18251825
var logger = connector.LoggingConfiguration.CommandLogger;
1826+
Debug.Assert(executing ? logger.IsEnabled(LogLevel.Debug) : logger.IsEnabled(LogLevel.Information));
18261827

18271828
if (InternalBatchCommands.Count == 1)
18281829
{
@@ -1860,9 +1861,9 @@ internal void LogExecutingCompleted(NpgsqlConnector connector, bool executing)
18601861
{
18611862
if (logParameters)
18621863
{
1863-
var commands = new (string, object[])[InternalBatchCommands.Count];
1864+
var commands = new (string, IEnumerable<object>)[InternalBatchCommands.Count];
18641865
for (var i = 0; i < InternalBatchCommands.Count; i++)
1865-
commands[i] = (InternalBatchCommands[i].FinalCommandText!, GetParametersForLogging(InternalBatchCommands[i]));
1866+
commands[i] = (InternalBatchCommands[i].FinalCommandText!, new LoggingEnumerable<object>(GetParametersForLogging(InternalBatchCommands[i])));
18661867

18671868
if (executing)
18681869
LogMessages.ExecutingBatchWithParameters(logger, commands, connector.Id);

‎src/Npgsql/Util/LoggingEnumerable.cs‎

Lines changed: 36 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -0,0 +1,36 @@
1+
using System.Collections;
2+
using System.Collections.Generic;
3+
using System.Text;
4+
5+
namespace Npgsql.Util;
6+
7+
// For logging batches we have to use a wrapper for parameters, otherwise they're logged as object[]. See https://github.com/npgsql/npgsql/issues/6078.
8+
sealed class LoggingEnumerable<T>(IEnumerable<T> wrappedEnumerable) : IEnumerable<T>
9+
{
10+
public IEnumerator<T> GetEnumerator() => wrappedEnumerable.GetEnumerator();
11+
12+
IEnumerator IEnumerable.GetEnumerator() => ((IEnumerable)wrappedEnumerable).GetEnumerator();
13+
14+
public override string ToString()
15+
{
16+
var sb = new StringBuilder();
17+
18+
sb.Append('[');
19+
20+
var appended = false;
21+
22+
foreach (var o in wrappedEnumerable)
23+
{
24+
if (appended)
25+
sb.Append(", ");
26+
else
27+
appended = true;
28+
29+
sb.Append(o);
30+
}
31+
32+
sb.Append(']');
33+
34+
return sb.ToString();
35+
}
36+
}

‎test/Npgsql.Tests/LoggingTests.cs‎

Lines changed: 10 additions & 12 deletions
Original file line numberDiff line numberDiff line change
@@ -143,8 +143,8 @@ public async Task Command_ExecuteScalar_multiple_statement_without_parameters()
143143
}
144144

145145
var executingCommandEvent = listLoggerProvider.Log.Single(l => l.Id == NpgsqlEventId.CommandExecutionCompleted);
146-
Assert.That(executingCommandEvent.Message, Does.Contain("Batch execution completed").And.Contains("[(SELECT 1, System.Object[]), (SELECT 2, System.Object[])]"));
147-
var batchCommands = (IList<(string CommandText, object[] Parameters)>)AssertLoggingStateContains(executingCommandEvent, "BatchCommands");
146+
Assert.That(executingCommandEvent.Message, Does.Contain("Batch execution completed").And.Contains("[(SELECT 1, []), (SELECT 2, [])]"));
147+
var batchCommands = (IList<(string CommandText, IEnumerable<object> Parameters)>)AssertLoggingStateContains(executingCommandEvent, "BatchCommands");
148148
Assert.That(batchCommands.Count, Is.EqualTo(2));
149149
Assert.That(batchCommands[0].CommandText, Is.EqualTo("SELECT 1"));
150150
Assert.That(batchCommands[0].Parameters, Is.Empty);
@@ -171,13 +171,13 @@ public async Task Command_ExecuteScalar_multiple_statement_with_parameters()
171171
}
172172

173173
var executingCommandEvent = listLoggerProvider.Log.Single(l => l.Id == NpgsqlEventId.CommandExecutionCompleted);
174-
Assert.That(executingCommandEvent.Message, Does.Contain("Batch execution completed").And.Contains("[(SELECT $1, System.Object[]), (SELECT $1, System.Object[])]"));
175-
var batchCommands = (IList<(string CommandText, object[] Parameters)>)AssertLoggingStateContains(executingCommandEvent, "BatchCommands");
174+
Assert.That(executingCommandEvent.Message, Does.Contain("Batch execution completed").And.Contains("[(SELECT $1, [8]), (SELECT $1, [9])]"));
175+
var batchCommands = (IList<(string CommandText, IEnumerable<object> Parameters)>)AssertLoggingStateContains(executingCommandEvent, "BatchCommands");
176176
Assert.That(batchCommands.Count, Is.EqualTo(2));
177177
Assert.That(batchCommands[0].CommandText, Is.EqualTo("SELECT $1"));
178-
Assert.That(batchCommands[0].Parameters[0], Is.EqualTo(8));
178+
Assert.That(batchCommands[0].Parameters.First(), Is.EqualTo(8));
179179
Assert.That(batchCommands[1].CommandText, Is.EqualTo("SELECT $1"));
180-
Assert.That(batchCommands[1].Parameters[0], Is.EqualTo(9));
180+
Assert.That(batchCommands[1].Parameters.First(), Is.EqualTo(9));
181181
AssertLoggingStateDoesNotContain(executingCommandEvent, "Parameters");
182182

183183
if (!IsMultiplexing)
@@ -256,21 +256,19 @@ public async Task Batch_ExecuteScalar_multiple_statements_with_parameters()
256256

257257
var executingCommandEvent = listLoggerProvider.Log.Single(l => l.Id == NpgsqlEventId.CommandExecutionCompleted);
258258

259-
// Note: the message formatter of Microsoft.Extensions.Logging doesn't seem to handle arrays inside tuples, so we get the
260-
// following ugliness (https://github.com/dotnet/runtime/issues/63165). Serilog handles this fine.
261-
Assert.That(executingCommandEvent.Message, Does.Contain("Batch execution completed").And.Contains("[(SELECT $1, System.Object[]), (SELECT $1, 9, System.Object[])]"));
259+
Assert.That(executingCommandEvent.Message, Does.Contain("Batch execution completed").And.Contains("[(SELECT $1, [8]), (SELECT $1, 9, [9])]"));
262260
AssertLoggingStateDoesNotContain(executingCommandEvent, "CommandText");
263261
AssertLoggingStateDoesNotContain(executingCommandEvent, "Parameters");
264262

265263
if (!IsMultiplexing)
266264
AssertLoggingStateContains(executingCommandEvent, "ConnectorId", conn.ProcessID);
267265

268-
var batchCommands = (IList<(string CommandText, object[] Parameters)>)AssertLoggingStateContains(executingCommandEvent, "BatchCommands");
266+
var batchCommands = (IList<(string CommandText, IEnumerable<object> Parameters)>)AssertLoggingStateContains(executingCommandEvent, "BatchCommands");
269267
Assert.That(batchCommands.Count, Is.EqualTo(2));
270268
Assert.That(batchCommands[0].CommandText, Is.EqualTo("SELECT $1"));
271-
Assert.That(batchCommands[0].Parameters[0], Is.EqualTo(8));
269+
Assert.That(batchCommands[0].Parameters.First(), Is.EqualTo(8));
272270
Assert.That(batchCommands[1].CommandText, Is.EqualTo("SELECT $1, 9"));
273-
Assert.That(batchCommands[1].Parameters[0], Is.EqualTo(9));
271+
Assert.That(batchCommands[1].Parameters.First(), Is.EqualTo(9));
274272
}
275273

276274
[Test]

0 commit comments

Comments
 (0)