Skip to content

Improve logging of SQL parameter types and values NH-3920 #527

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.

Sign up for GitHub

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

Merged
merged 4 commits into from
Nov 14, 2016
Merged

Improve logging of SQL parameter types and values NH-3920 #527

Show file tree
Hide file tree
Changes from all commits
Commits
Show all changes
4 commits
Select commit Hold shift + click to select a range
fb75d7d
SqlStatementLogger: Minor cleanup to formatting and spelling.
oskarb Nov 14, 2016
38719fb
SqlStatementLogger: Don't cause NRE if the parameter doesn't implemen…
oskarb Nov 14, 2016
2b23a85
SqlStatementLogger: Also print parameter scale and precision. NH-3920.
oskarb Nov 14, 2016
625ccba
SqlStatementLogger: Print full details of DateTime parameter values. …
oskarb Nov 14, 2016
File filter

Filter by extension

Filter by extension
Conversations
Failed to load comments.
Loading
Jump to
Jump to file
Failed to load files.
Loading
Diff view
Diff view
4 changes: 3 additions & 1 deletion src/NHibernate.Test/NHSpecificTest/Futures/FutureQueryFixture.cs
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -138,7 +138,9 @@ public void CanExecuteMultipleQueryWithSameParameterName()
Assert.AreEqual(1, events.Length);
var wholeLog = logSpy.GetWholeLog();
string paramPrefix = ((DriverBase) Sfi.ConnectionProvider.Driver).NamedPrefix;
Assert.That(wholeLog.Contains(paramPrefix + "p0 = 1 [Type: Int32 (0)], " + paramPrefix + "p1 = 2 [Type: Int32 (0)]"), Is.True);
Assert.That(
wholeLog,
Is.StringContaining(paramPrefix + "p0 = 1 [Type: Int32 (0:0:0)], " + paramPrefix + "p1 = 2 [Type: Int32 (0:0:0)]"));
}
}
}
Expand Down
6 changes: 4 additions & 2 deletions src/NHibernate.Test/NHSpecificTest/Futures/LinqFutureFixture.cs
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -353,9 +353,11 @@ public void CanExecuteMultipleQueriesOnSameExpression()
Assert.AreEqual(1, events.Length);
var wholeLog = logSpy.GetWholeLog();
string paramPrefix = ((DriverBase)Sfi.ConnectionProvider.Driver).NamedPrefix;
Assert.That(wholeLog.Contains(paramPrefix + "p0 = 1 [Type: Int32 (0)], " + paramPrefix + "p1 = 2 [Type: Int32 (0)]"), Is.True);
Assert.That(
wholeLog,
Is.StringContaining(paramPrefix + "p0 = 1 [Type: Int32 (0:0:0)], " + paramPrefix + "p1 = 2 [Type: Int32 (0:0:0)]"));
}
}
}
}
}
}
4 changes: 2 additions & 2 deletions src/NHibernate.Test/SqlTest/Identity/MsSQL/MSSQLIdentityInsertWithStoredProcsTest.cs
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -14,12 +14,12 @@ protected override bool AppliesTo(Dialect.Dialect dialect)

protected override string GetExpectedInsertOrgLogStatement(string orgName)
{
return string.Format("exec nh_organization_native_id_insert @p0;@p0 = '{0}' [Type: String (4000)]", orgName);
return string.Format("exec nh_organization_native_id_insert @p0;@p0 = '{0}' [Type: String (4000:0:0)]", orgName);
}

protected override IList Mappings
{
get { return new[] { "SqlTest.Identity.MsSQL.MSSQLIdentityInsertWithStoredProcs.hbm.xml" }; }
}
}
}
}
96 changes: 59 additions & 37 deletions src/NHibernate/AdoNet/Util/SqlStatementLogger.cs
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -8,10 +8,12 @@ namespace NHibernate.AdoNet.Util
/// <summary> Centralize logging handling for SQL statements. </summary>
public class SqlStatementLogger
{
private static readonly IInternalLogger log = LoggerProvider.LoggerFor("NHibernate.SQL");
private static readonly IInternalLogger Logger = LoggerProvider.LoggerFor("NHibernate.SQL");

/// <summary> Constructs a new SqlStatementLogger instance.</summary>
public SqlStatementLogger() : this(false, false) { }
public SqlStatementLogger() : this(false, false)
{
}

/// <summary> Constructs a new SqlStatementLogger instance. </summary>
/// <param name="logToStdout">Should we log to STDOUT in addition to our internal logger. </param>
Expand All @@ -28,7 +30,7 @@ public SqlStatementLogger(bool logToStdout, bool formatSql)

public bool IsDebugEnabled
{
get { return log.IsDebugEnabled; }
get { return Logger.IsDebugEnabled; }
}

/// <summary> Log a IDbCommand. </summary>
Expand All @@ -37,7 +39,7 @@ public bool IsDebugEnabled
/// <param name="style">The requested formatting style. </param>
public virtual void LogCommand(string message, IDbCommand command, FormatStyle style)
{
if (!log.IsDebugEnabled && !LogToStdout || string.IsNullOrEmpty(command.CommandText))
if (!Logger.IsDebugEnabled && !LogToStdout || string.IsNullOrEmpty(command.CommandText))
{
return;
}
Expand All @@ -53,7 +55,7 @@ public virtual void LogCommand(string message, IDbCommand command, FormatStyle s
{
logMessage = message + statement;
}
log.Debug(logMessage);
Logger.Debug(logMessage);
if (LogToStdout)
{
Console.Out.WriteLine("NHibernate: " + statement);
Expand All @@ -78,7 +80,7 @@ public string GetCommandLineWithParameters(IDbCommand command)
}
else
{
var output = new StringBuilder(command.CommandText.Length + (command.Parameters.Count * 20));
var output = new StringBuilder(command.CommandText.Length + (command.Parameters.Count*20));
output.Append(command.CommandText.TrimEnd(' ', ';', '\n'));
output.Append(";");

Expand All @@ -92,54 +94,74 @@ public string GetCommandLineWithParameters(IDbCommand command)
output.Append(", ");
}
appendComma = true;
p = (IDataParameter)command.Parameters[i];
output.Append(string.Format("{0} = {1} [Type: {2}]", p.ParameterName, GetParameterLogableValue(p), GetParameterLogableType(p)));
p = (IDataParameter) command.Parameters[i];
output.Append(
string.Format("{0} = {1} [Type: {2}]", p.ParameterName, GetParameterLoggableValue(p), GetParameterLoggableType(p)));
}
outputText = output.ToString();
}
return outputText;
}

private static string GetParameterLogableType(IDataParameter dataParameter)
{
var p = dataParameter as IDbDataParameter;
if (p != null)
return p.DbType + " (" + p.Size + ")";
return p.DbType.ToString();
private static string GetParameterLoggableType(IDataParameter dataParameter)
{
var p = dataParameter as IDbDataParameter;
if (p != null)
return p.DbType + " (" + p.Size + ":" + p.Scale + ":" + p.Precision + ")";
return dataParameter.DbType.ToString();
}


}
public string GetParameterLoggableValue(IDataParameter parameter)
{
const int maxLoggableStringLength = 1000;

public string GetParameterLogableValue(IDataParameter parameter)
if (parameter.Value == null || DBNull.Value.Equals(parameter.Value))
{
const int maxLogableStringLength = 1000;
if (parameter.Value == null || DBNull.Value.Equals(parameter.Value))
{
return "NULL";
}
if (IsStringType(parameter.DbType))
{
return string.Concat("'", TruncateWithEllipsis(parameter.Value.ToString(), maxLogableStringLength), "'");
}
var buffer = parameter.Value as byte[];
if (buffer != null)
{
return GetBufferAsHexString(buffer);
}
return parameter.Value.ToString();
return "NULL";
}

if (IsStringType(parameter.DbType))
{
return string.Concat("'", TruncateWithEllipsis(parameter.Value.ToString(), maxLoggableStringLength), "'");
}

if (parameter.Value is DateTime)
return ((DateTime) parameter.Value).ToString("O");

if (parameter.Value is DateTimeOffset)
return ((DateTimeOffset) parameter.Value).ToString("O");

var buffer = parameter.Value as byte[];
if (buffer != null)
{
return GetBufferAsHexString(buffer);
}

return parameter.Value.ToString();

}


[Obsolete("Use GetParameterLoggableValue(parameter) instead.")]
public string GetParameterLogableValue(IDataParameter parameter)
{
return GetParameterLoggableValue(parameter);
}


private static string GetBufferAsHexString(byte[] buffer)
{
const int maxBytes = 128;
int bufferLength = buffer.Length;

var sb = new StringBuilder(maxBytes * 2 + 8);
var sb = new StringBuilder(maxBytes*2 + 8);
sb.Append("0x");
for (int i = 0; i < bufferLength && i < maxBytes; i++)
{
sb.Append(buffer[i].ToString("X2"));
}
if(bufferLength > maxBytes)
if (bufferLength > maxBytes)
{
sb.Append("...");
}
Expand All @@ -149,7 +171,7 @@ private static string GetBufferAsHexString(byte[] buffer)
private static bool IsStringType(DbType dbType)
{
return DbType.String.Equals(dbType) || DbType.AnsiString.Equals(dbType)
|| DbType.AnsiStringFixedLength.Equals(dbType) || DbType.StringFixedLength.Equals(dbType);
|| DbType.AnsiStringFixedLength.Equals(dbType) || DbType.StringFixedLength.Equals(dbType);
}

public FormatStyle DetermineActualStyle(FormatStyle style)
Expand All @@ -159,8 +181,8 @@ public FormatStyle DetermineActualStyle(FormatStyle style)

public void LogBatchCommand(string batchCommand)
{
log.Debug(batchCommand);
if(LogToStdout)
Logger.Debug(batchCommand);
if (LogToStdout)
{
Console.Out.WriteLine("NHibernate: " + batchCommand);
}
Expand All @@ -176,4 +198,4 @@ private string TruncateWithEllipsis(string source, int length)
return source;
}
}
}
}