Skip to content

Commit 91086e5

Browse files
balazsmeszegetoroji
balazsmeszegeto
and
roji
authored
Improve parameter logging: show actual values of array-typed parameters, fixes #5342 (#5673)
inspired by: LogValuesFormatter from Microsoft.Extensions.Logging.Abstractions Co-authored-by: Shay Rojansky <roji@roji.org>
1 parent 441c115 commit 91086e5

4 files changed

Lines changed: 347 additions & 276 deletions

File tree

‎src/Npgsql/NpgsqlCommand.cs‎

Lines changed: 45 additions & 6 deletions
Original file line numberDiff line numberDiff line change
@@ -17,6 +17,7 @@
1717
using Microsoft.Extensions.Logging;
1818
using Npgsql.Internal;
1919
using Npgsql.Properties;
20+
using System.Collections;
2021

2122
namespace Npgsql;
2223

@@ -1812,15 +1813,15 @@ internal void LogExecutingCompleted(NpgsqlConnector connector, bool executing)
18121813
LogMessages.ExecutingCommandWithParameters(
18131814
logger,
18141815
singleCommand.FinalCommandText!,
1815-
ParametersDbNullAsString(singleCommand),
1816+
GetParametersForLogging(singleCommand),
18161817
connector.Id);
18171818
}
18181819
else
18191820
{
18201821
LogMessages.CommandExecutionCompletedWithParameters(
18211822
logger,
18221823
singleCommand.FinalCommandText!,
1823-
ParametersDbNullAsString(singleCommand),
1824+
GetParametersForLogging(singleCommand),
18241825
connector.QueryLogStopWatch.ElapsedMilliseconds,
18251826
connector.Id);
18261827
}
@@ -1839,7 +1840,7 @@ internal void LogExecutingCompleted(NpgsqlConnector connector, bool executing)
18391840
{
18401841
var commands = new (string, object[])[InternalBatchCommands.Count];
18411842
for (var i = 0; i < InternalBatchCommands.Count; i++)
1842-
commands[i] = (InternalBatchCommands[i].FinalCommandText!, ParametersDbNullAsString(InternalBatchCommands[i]));
1843+
commands[i] = (InternalBatchCommands[i].FinalCommandText!, GetParametersForLogging(InternalBatchCommands[i]));
18431844

18441845
if (executing)
18451846
LogMessages.ExecutingBatchWithParameters(logger, commands, connector.Id);
@@ -1858,15 +1859,53 @@ internal void LogExecutingCompleted(NpgsqlConnector connector, bool executing)
18581859
}
18591860
}
18601861

1861-
object[] ParametersDbNullAsString(NpgsqlBatchCommand c)
1862+
static object[] GetParametersForLogging(NpgsqlBatchCommand c)
18621863
{
18631864
var positionalParameters = c.CurrentParametersReadOnly;
18641865
var parameters = new object[positionalParameters.Count];
18651866
for (var i = 0; i < positionalParameters.Count; i++)
1866-
parameters[i] = positionalParameters[i].Value == DBNull.Value ? "NULL" : positionalParameters[i].Value!;
1867+
{
1868+
parameters[i] = GetParameterForLogging(positionalParameters[i].Value);
1869+
}
18671870
return parameters;
1871+
1872+
object GetParameterForLogging(object? value)
1873+
{
1874+
return value switch
1875+
{
1876+
DBNull or null => "NULL",
1877+
IEnumerable enumerable and not string => GetEnumerableForLogging(enumerable),
1878+
_ => value
1879+
};
1880+
1881+
string GetEnumerableForLogging(IEnumerable enumerable)
1882+
{
1883+
var vsb = new StringBuilder(256);
1884+
var count = 0;
1885+
vsb.Append('[');
1886+
foreach (var e in enumerable)
1887+
{
1888+
if (count > 9)
1889+
{
1890+
vsb.Append(", ...");
1891+
break;
1892+
}
1893+
1894+
if (count > 0)
1895+
{
1896+
vsb.Append(", ");
1897+
}
1898+
1899+
vsb.Append(GetParameterForLogging(e));
1900+
count++;
1901+
}
1902+
1903+
vsb.Append(']');
1904+
return vsb.ToString();
1905+
}
1906+
}
18681907
}
1869-
}
1908+
}
18701909

18711910
/// <summary>
18721911
/// Create a new command based on this one.

‎test/Npgsql.Tests/BatchTests.cs‎

Lines changed: 0 additions & 94 deletions
Original file line numberDiff line numberDiff line change
@@ -797,100 +797,6 @@ public async Task Batch_dispose_reuse()
797797

798798
#endregion Miscellaneous
799799

800-
#region Logging
801-
802-
[Test]
803-
public async Task Log_ExecuteScalar_single_statement_without_parameters()
804-
{
805-
await using var dataSource = CreateLoggingDataSource(out var listLoggerProvider);
806-
await using var conn = await dataSource.OpenConnectionAsync();
807-
await using var cmd = new NpgsqlBatch(conn)
808-
{
809-
BatchCommands = { new("SELECT 1") }
810-
};
811-
812-
using (listLoggerProvider.Record())
813-
{
814-
await cmd.ExecuteScalarAsync();
815-
}
816-
817-
var executingCommandEvent = listLoggerProvider.Log.Single(l => l.Id == NpgsqlEventId.CommandExecutionCompleted);
818-
819-
Assert.That(executingCommandEvent.Message, Does.Contain("Command execution completed").And.Contains("SELECT 1"));
820-
AssertLoggingStateContains(executingCommandEvent, "CommandText", "SELECT 1");
821-
AssertLoggingStateDoesNotContain(executingCommandEvent, "Parameters");
822-
823-
if (!IsMultiplexing)
824-
AssertLoggingStateContains(executingCommandEvent, "ConnectorId", conn.ProcessID);
825-
}
826-
827-
[Test]
828-
public async Task Log_ExecuteScalar_multiple_statements_with_parameters()
829-
{
830-
await using var dataSource = CreateLoggingDataSource(out var listLoggerProvider);
831-
await using var conn = await dataSource.OpenConnectionAsync();
832-
await using var batch = new NpgsqlBatch(conn)
833-
{
834-
BatchCommands =
835-
{
836-
new("SELECT $1") { Parameters = { new() { Value = 8 } } },
837-
new("SELECT $1, 9") { Parameters = { new() { Value = 9 } } }
838-
}
839-
};
840-
841-
using (listLoggerProvider.Record())
842-
{
843-
await batch.ExecuteScalarAsync();
844-
}
845-
846-
var executingCommandEvent = listLoggerProvider.Log.Single(l => l.Id == NpgsqlEventId.CommandExecutionCompleted);
847-
848-
// Note: the message formatter of Microsoft.Extensions.Logging doesn't seem to handle arrays inside tuples, so we get the
849-
// following ugliness (https://github.com/dotnet/runtime/issues/63165). Serilog handles this fine.
850-
Assert.That(executingCommandEvent.Message, Does.Contain("Batch execution completed").And.Contains("[(SELECT $1, System.Object[]), (SELECT $1, 9, System.Object[])]"));
851-
AssertLoggingStateDoesNotContain(executingCommandEvent, "CommandText");
852-
AssertLoggingStateDoesNotContain(executingCommandEvent, "Parameters");
853-
854-
if (!IsMultiplexing)
855-
AssertLoggingStateContains(executingCommandEvent, "ConnectorId", conn.ProcessID);
856-
857-
var batchCommands = (IList<(string CommandText, object[] Parameters)>)AssertLoggingStateContains(executingCommandEvent, "BatchCommands");
858-
Assert.That(batchCommands.Count, Is.EqualTo(2));
859-
Assert.That(batchCommands[0].CommandText, Is.EqualTo("SELECT $1"));
860-
Assert.That(batchCommands[0].Parameters[0], Is.EqualTo(8));
861-
Assert.That(batchCommands[1].CommandText, Is.EqualTo("SELECT $1, 9"));
862-
Assert.That(batchCommands[1].Parameters[0], Is.EqualTo(9));
863-
}
864-
865-
[Test]
866-
public async Task Log_ExecuteScalar_single_statement_with_parameter_logging_off()
867-
{
868-
await using var dataSource = CreateLoggingDataSource(out var listLoggerProvider, sensitiveDataLoggingEnabled: false);
869-
await using var conn = await dataSource.OpenConnectionAsync();
870-
await using var batch = new NpgsqlBatch(conn)
871-
{
872-
BatchCommands =
873-
{
874-
new("SELECT $1") { Parameters = { new() { Value = 8 } } },
875-
new("SELECT $1, 9") { Parameters = { new() { Value = 9 } } }
876-
}
877-
};
878-
879-
using (listLoggerProvider.Record())
880-
{
881-
await batch.ExecuteScalarAsync();
882-
}
883-
884-
var executingCommandEvent = listLoggerProvider.Log.Single(l => l.Id == NpgsqlEventId.CommandExecutionCompleted);
885-
Assert.That(executingCommandEvent.Message, Does.Contain("Batch execution completed").And.Contains("[SELECT $1, SELECT $1, 9]"));
886-
var batchCommands = (IList<string>)AssertLoggingStateContains(executingCommandEvent, "BatchCommands");
887-
Assert.That(batchCommands.Count, Is.EqualTo(2));
888-
Assert.That(batchCommands[0], Is.EqualTo("SELECT $1"));
889-
Assert.That(batchCommands[1], Is.EqualTo("SELECT $1, 9"));
890-
}
891-
892-
#endregion Logging
893-
894800
#region Initialization / setup / teardown
895801

896802
// ReSharper disable InconsistentNaming

‎test/Npgsql.Tests/CommandTests.cs‎

Lines changed: 0 additions & 176 deletions
Original file line numberDiff line numberDiff line change
@@ -5,7 +5,6 @@
55
using NUnit.Framework;
66
using System;
77
using System.Buffers.Binary;
8-
using System.Collections.Generic;
98
using System.Data;
109
using System.Linq;
1110
using System.Text;
@@ -1640,179 +1639,4 @@ await server
16401639

16411640
Assert.That(connection.PostgresParameters, Contains.Key("SomeKey").WithValue("SomeValue"));
16421641
}
1643-
1644-
#region Logging
1645-
1646-
[Test]
1647-
public async Task Log_ExecuteScalar_single_statement_without_parameters()
1648-
{
1649-
await using var dataSource = CreateLoggingDataSource(out var listLoggerProvider);
1650-
await using var conn = await dataSource.OpenConnectionAsync();
1651-
await using var cmd = new NpgsqlCommand("SELECT 1", conn);
1652-
1653-
using (listLoggerProvider.Record())
1654-
{
1655-
await cmd.ExecuteScalarAsync();
1656-
}
1657-
1658-
var executingCommandEvent = listLoggerProvider.Log.Single(l => l.Id == NpgsqlEventId.CommandExecutionCompleted);
1659-
Assert.That(executingCommandEvent.Message, Does.Contain("Command execution completed").And.Contains("SELECT 1"));
1660-
AssertLoggingStateContains(executingCommandEvent, "CommandText", "SELECT 1");
1661-
AssertLoggingStateDoesNotContain(executingCommandEvent, "Parameters");
1662-
1663-
if (!IsMultiplexing)
1664-
AssertLoggingStateContains(executingCommandEvent, "ConnectorId", conn.ProcessID);
1665-
}
1666-
1667-
[Test]
1668-
public async Task Log_ExecuteScalar_single_statement_with_positional_parameters()
1669-
{
1670-
await using var dataSource = CreateLoggingDataSource(out var listLoggerProvider);
1671-
await using var conn = await dataSource.OpenConnectionAsync();
1672-
await using var cmd = new NpgsqlCommand("SELECT $1, $2", conn);
1673-
cmd.Parameters.Add(new() { Value = 8 });
1674-
cmd.Parameters.Add(new() { NpgsqlDbType = NpgsqlDbType.Integer, Value = DBNull.Value });
1675-
1676-
using (listLoggerProvider.Record())
1677-
{
1678-
await cmd.ExecuteScalarAsync();
1679-
}
1680-
1681-
var executingCommandEvent = listLoggerProvider.Log.Single(l => l.Id == NpgsqlEventId.CommandExecutionCompleted);
1682-
Assert.That(executingCommandEvent.Message, Does.Contain("Command execution completed")
1683-
.And.Contains("SELECT $1, $2")
1684-
.And.Contains("Parameters: [8, NULL]"));
1685-
AssertLoggingStateContains(executingCommandEvent, "CommandText", "SELECT $1, $2");
1686-
AssertLoggingStateContains(executingCommandEvent, "Parameters", new object[] { 8, "NULL" });
1687-
1688-
if (!IsMultiplexing)
1689-
AssertLoggingStateContains(executingCommandEvent, "ConnectorId", conn.ProcessID);
1690-
}
1691-
1692-
[Test]
1693-
public async Task Log_ExecuteScalar_single_statement_with_named_parameters()
1694-
{
1695-
await using var dataSource = CreateLoggingDataSource(out var listLoggerProvider);
1696-
await using var conn = await dataSource.OpenConnectionAsync();
1697-
await using var cmd = new NpgsqlCommand("SELECT @p1, @p2", conn);
1698-
cmd.Parameters.Add(new() { ParameterName = "p1", Value = 8 });
1699-
cmd.Parameters.Add(new() { ParameterName = "p2", NpgsqlDbType = NpgsqlDbType.Integer, Value = DBNull.Value });
1700-
1701-
using (listLoggerProvider.Record())
1702-
{
1703-
await cmd.ExecuteScalarAsync();
1704-
}
1705-
1706-
var executingCommandEvent = listLoggerProvider.Log.Single(l => l.Id == NpgsqlEventId.CommandExecutionCompleted);
1707-
Assert.That(executingCommandEvent.Message, Does.Contain("Command execution completed")
1708-
.And.Contains("SELECT $1, $2")
1709-
.And.Contains("Parameters: [8, NULL]"));
1710-
AssertLoggingStateContains(executingCommandEvent, "CommandText", "SELECT $1, $2");
1711-
AssertLoggingStateContains(executingCommandEvent, "Parameters", new object[] { 8, "NULL" });
1712-
1713-
if (!IsMultiplexing)
1714-
AssertLoggingStateContains(executingCommandEvent, "ConnectorId", conn.ProcessID);
1715-
}
1716-
1717-
[Test]
1718-
public async Task Log_ExecuteScalar_single_statement_with_parameter_logging_off()
1719-
{
1720-
await using var dataSource = CreateLoggingDataSource(out var listLoggerProvider, sensitiveDataLoggingEnabled: false);
1721-
await using var conn = await dataSource.OpenConnectionAsync();
1722-
await using var cmd = new NpgsqlCommand("SELECT $1, $2", conn);
1723-
cmd.Parameters.Add(new() { Value = 8 });
1724-
cmd.Parameters.Add(new() { Value = 9 });
1725-
1726-
using (listLoggerProvider.Record())
1727-
{
1728-
await cmd.ExecuteScalarAsync();
1729-
}
1730-
1731-
var executingCommandEvent = listLoggerProvider.Log.Single(l => l.Id == NpgsqlEventId.CommandExecutionCompleted);
1732-
Assert.That(executingCommandEvent.Message, Does.Contain("Command execution completed").And.Contains($"SELECT $1, $2"));
1733-
AssertLoggingStateContains(executingCommandEvent, "CommandText", "SELECT $1, $2");
1734-
AssertLoggingStateDoesNotContain(executingCommandEvent, "Parameters");
1735-
}
1736-
1737-
[Test]
1738-
public async Task Log_ExecuteScalar_multiple_statement_without_parameters()
1739-
{
1740-
await using var dataSource = CreateLoggingDataSource(out var listLoggerProvider);
1741-
await using var conn = await dataSource.OpenConnectionAsync();
1742-
await using var cmd = new NpgsqlCommand("SELECT 1; SELECT 2", conn);
1743-
1744-
using (listLoggerProvider.Record())
1745-
{
1746-
await cmd.ExecuteScalarAsync();
1747-
}
1748-
1749-
var executingCommandEvent = listLoggerProvider.Log.Single(l => l.Id == NpgsqlEventId.CommandExecutionCompleted);
1750-
Assert.That(executingCommandEvent.Message, Does.Contain("Batch execution completed").And.Contains("[(SELECT 1, System.Object[]), (SELECT 2, System.Object[])]"));
1751-
var batchCommands = (IList<(string CommandText, object[] Parameters)>)AssertLoggingStateContains(executingCommandEvent, "BatchCommands");
1752-
Assert.That(batchCommands.Count, Is.EqualTo(2));
1753-
Assert.That(batchCommands[0].CommandText, Is.EqualTo("SELECT 1"));
1754-
Assert.That(batchCommands[0].Parameters, Is.Empty);
1755-
Assert.That(batchCommands[1].CommandText, Is.EqualTo("SELECT 2"));
1756-
Assert.That(batchCommands[1].Parameters, Is.Empty);
1757-
AssertLoggingStateDoesNotContain(executingCommandEvent, "Parameters");
1758-
1759-
if (!IsMultiplexing)
1760-
AssertLoggingStateContains(executingCommandEvent, "ConnectorId", conn.ProcessID);
1761-
}
1762-
1763-
[Test]
1764-
public async Task Log_ExecuteScalar_multiple_statement_with_parameters()
1765-
{
1766-
await using var dataSource = CreateLoggingDataSource(out var listLoggerProvider);
1767-
await using var conn = await dataSource.OpenConnectionAsync();
1768-
await using var cmd = new NpgsqlCommand("SELECT @p1; SELECT @p2", conn);
1769-
cmd.Parameters.Add(new() { ParameterName = "p1", Value = 8 });
1770-
cmd.Parameters.Add(new() { ParameterName = "p2", Value = 9 });
1771-
1772-
using (listLoggerProvider.Record())
1773-
{
1774-
await cmd.ExecuteScalarAsync();
1775-
}
1776-
1777-
var executingCommandEvent = listLoggerProvider.Log.Single(l => l.Id == NpgsqlEventId.CommandExecutionCompleted);
1778-
Assert.That(executingCommandEvent.Message, Does.Contain("Batch execution completed").And.Contains("[(SELECT $1, System.Object[]), (SELECT $1, System.Object[])]"));
1779-
var batchCommands = (IList<(string CommandText, object[] Parameters)>)AssertLoggingStateContains(executingCommandEvent, "BatchCommands");
1780-
Assert.That(batchCommands.Count, Is.EqualTo(2));
1781-
Assert.That(batchCommands[0].CommandText, Is.EqualTo("SELECT $1"));
1782-
Assert.That(batchCommands[0].Parameters[0], Is.EqualTo(8));
1783-
Assert.That(batchCommands[1].CommandText, Is.EqualTo("SELECT $1"));
1784-
Assert.That(batchCommands[1].Parameters[0], Is.EqualTo(9));
1785-
AssertLoggingStateDoesNotContain(executingCommandEvent, "Parameters");
1786-
1787-
if (!IsMultiplexing)
1788-
AssertLoggingStateContains(executingCommandEvent, "ConnectorId", conn.ProcessID);
1789-
}
1790-
1791-
[Test]
1792-
public async Task Log_ExecuteScalar_multiple_statement_with_parameter_logging_off()
1793-
{
1794-
await using var dataSource = CreateLoggingDataSource(out var listLoggerProvider, sensitiveDataLoggingEnabled: false);
1795-
await using var conn = await dataSource.OpenConnectionAsync();
1796-
await using var cmd = new NpgsqlCommand("SELECT @p1; SELECT @p2", conn);
1797-
cmd.Parameters.Add(new() { ParameterName = "p1", Value = 8 });
1798-
cmd.Parameters.Add(new() { ParameterName = "p2", Value = 9 });
1799-
1800-
using (listLoggerProvider.Record())
1801-
{
1802-
await cmd.ExecuteScalarAsync();
1803-
}
1804-
1805-
var executingCommandEvent = listLoggerProvider.Log.Single(l => l.Id == NpgsqlEventId.CommandExecutionCompleted);
1806-
Assert.That(executingCommandEvent.Message, Does.Contain("Batch execution completed").And.Contains("[SELECT $1, SELECT $1]"));
1807-
var batchCommands = (IList<string>)AssertLoggingStateContains(executingCommandEvent, "BatchCommands");
1808-
Assert.That(batchCommands.Count, Is.EqualTo(2));
1809-
Assert.That(batchCommands[0], Is.EqualTo("SELECT $1"));
1810-
Assert.That(batchCommands[1], Is.EqualTo("SELECT $1"));
1811-
AssertLoggingStateDoesNotContain(executingCommandEvent, "Parameters");
1812-
1813-
if (!IsMultiplexing)
1814-
AssertLoggingStateContains(executingCommandEvent, "ConnectorId", conn.ProcessID);
1815-
}
1816-
1817-
#endregion Logging
18181642
}

0 commit comments

Comments
 (0)