From 28c15bc425c5580ef683faceae5dbac555ee60cf Mon Sep 17 00:00:00 2001 From: ta264 Date: Thu, 20 Aug 2020 22:13:25 +0100 Subject: [PATCH] Log out SQL trace on error Fixes #4910 Co-Authored-By: ta264 --- .../Instrumentation/NzbDroneLogger.cs | 6 +- .../Datastore/Extensions/BuilderExtensions.cs | 11 ++-- .../Extensions/SqlMapperExtensions.cs | 64 ++++++++++++++----- 3 files changed, 57 insertions(+), 24 deletions(-) diff --git a/src/NzbDrone.Common/Instrumentation/NzbDroneLogger.cs b/src/NzbDrone.Common/Instrumentation/NzbDroneLogger.cs index 216e80463..1d6f70d09 100644 --- a/src/NzbDrone.Common/Instrumentation/NzbDroneLogger.cs +++ b/src/NzbDrone.Common/Instrumentation/NzbDroneLogger.cs @@ -12,7 +12,7 @@ namespace NzbDrone.Common.Instrumentation { public static class NzbDroneLogger { - private const string FILE_LOG_LAYOUT = @"${date:format=yyyy-M-d HH\:mm\:ss.f}|${level}|${logger}|${message}${onexception:inner=${newline}${newline}[v${assembly-version}] ${exception:format=ToString}${newline}}"; + private const string FILE_LOG_LAYOUT = @"${date:format=yyyy-M-d HH\:mm\:ss.f}|${level}|${logger}|${message}${onexception:inner=${newline}${newline}[v${assembly-version}] ${exception:format=ToString}${newline}${exception:format=Data}${newline}}"; private static bool _isConfigured; @@ -94,7 +94,7 @@ private static void RegisterDebugger() { DebuggerTarget target = new DebuggerTarget(); target.Name = "debuggerLogger"; - target.Layout = "[${level}] [${threadid}] ${logger}: ${message} ${onexception:inner=${newline}${newline}[v${assembly-version}] ${exception:format=ToString}${newline}}"; + target.Layout = "[${level}] [${threadid}] ${logger}: ${message} ${onexception:inner=${newline}${newline}[v${assembly-version}] ${exception:format=ToString}${newline}${exception:format=Data}${newline}}"; var loggingRule = new LoggingRule("*", LogLevel.Trace, target); LogManager.Configuration.AddTarget("debugger", target); @@ -108,7 +108,7 @@ private static void RegisterConsole() var coloredConsoleTarget = new ColoredConsoleTarget(); coloredConsoleTarget.Name = "consoleLogger"; - coloredConsoleTarget.Layout = "[${level}] ${logger}: ${message} ${onexception:inner=${newline}${newline}[v${assembly-version}] ${exception:format=ToString}${newline}}"; + coloredConsoleTarget.Layout = "[${level}] ${logger}: ${message} ${onexception:inner=${newline}${newline}[v${assembly-version}] ${exception:format=ToString}${newline}${exception:format=Data}${newline}}"; var loggingRule = new LoggingRule("*", level, coloredConsoleTarget); diff --git a/src/NzbDrone.Core/Datastore/Extensions/BuilderExtensions.cs b/src/NzbDrone.Core/Datastore/Extensions/BuilderExtensions.cs index cba52d2cb..97ce5d731 100644 --- a/src/NzbDrone.Core/Datastore/Extensions/BuilderExtensions.cs +++ b/src/NzbDrone.Core/Datastore/Extensions/BuilderExtensions.cs @@ -98,7 +98,7 @@ public static SqlBuilder.Template LogQuery(this SqlBuilder.Template template) { if (LogSql) { - LogQuery(template.RawSql, (DynamicParameters)template.Parameters); + Logger.Trace(GetSqlLogString(template.RawSql, template.Parameters)); } return template; @@ -108,12 +108,14 @@ public static void LogQuery(string sql, object parameters) { if (LogSql) { - LogQuery(sql, new DynamicParameters(parameters)); + Logger.Trace(GetSqlLogString(sql, parameters)); } } - private static void LogQuery(string sql, DynamicParameters parameters) + public static string GetSqlLogString(string sql, object paramsObject) { + var parameters = new DynamicParameters(paramsObject); + var sb = new StringBuilder(); sb.AppendLine(); sb.AppendLine("==== Begin Query Trace ===="); @@ -122,6 +124,7 @@ private static void LogQuery(string sql, DynamicParameters parameters) sb.AppendLine(sql); sb.AppendLine(); sb.AppendLine("PARAMETERS:"); + foreach (var p in parameters.ToDictionary()) { var val = (p.Value is string) ? string.Format("\"{0}\"", p.Value) : p.Value; @@ -132,7 +135,7 @@ private static void LogQuery(string sql, DynamicParameters parameters) sb.AppendLine("==== End Query Trace ===="); sb.AppendLine(); - Logger.Trace(sb.ToString()); + return sb.ToString(); } private static Dictionary ToDictionary(this DynamicParameters dynamicParams) diff --git a/src/NzbDrone.Core/Datastore/Extensions/SqlMapperExtensions.cs b/src/NzbDrone.Core/Datastore/Extensions/SqlMapperExtensions.cs index 801961c30..230dd721d 100644 --- a/src/NzbDrone.Core/Datastore/Extensions/SqlMapperExtensions.cs +++ b/src/NzbDrone.Core/Datastore/Extensions/SqlMapperExtensions.cs @@ -11,7 +11,17 @@ public static IEnumerable Query(this IDatabase db, string sql, object para { using (var conn = db.OpenConnection()) { - var items = SqlMapper.Query(conn, sql, param); + IEnumerable items; + try + { + items = SqlMapper.Query(conn, sql, param); + } + catch (Exception e) + { + e.Data.Add("SQL", SqlBuilderExtensions.GetSqlLogString(sql, param)); + throw; + } + if (TableMapping.Mapper.LazyLoadList.TryGetValue(typeof(T), out var lazyProperties)) { foreach (var item in items) @@ -33,13 +43,18 @@ TReturn MapWithLazy(TFirst first, TSecond second) return map(first, second); } - IEnumerable result = null; using (var conn = db.OpenConnection()) { - result = SqlMapper.Query(conn, sql, MapWithLazy, param, transaction, buffered, splitOn, commandTimeout, commandType); + try + { + return SqlMapper.Query(conn, sql, MapWithLazy, param, transaction, buffered, splitOn, commandTimeout, commandType); + } + catch (Exception e) + { + e.Data.Add("SQL", SqlBuilderExtensions.GetSqlLogString(sql, param)); + throw; + } } - - return result; } public static IEnumerable Query(this IDatabase db, string sql, Func map, object param = null, IDbTransaction transaction = null, bool buffered = true, string splitOn = "Id", int? commandTimeout = null, CommandType? commandType = null) @@ -52,13 +67,18 @@ TReturn MapWithLazy(TFirst first, TSecond second, TThird third) return map(first, second, third); } - IEnumerable result = null; using (var conn = db.OpenConnection()) { - result = SqlMapper.Query(conn, sql, MapWithLazy, param, transaction, buffered, splitOn, commandTimeout, commandType); + try + { + return SqlMapper.Query(conn, sql, MapWithLazy, param, transaction, buffered, splitOn, commandTimeout, commandType); + } + catch (Exception e) + { + e.Data.Add("SQL", SqlBuilderExtensions.GetSqlLogString(sql, param)); + throw; + } } - - return result; } public static IEnumerable Query(this IDatabase db, string sql, Func map, object param = null, IDbTransaction transaction = null, bool buffered = true, string splitOn = "Id", int? commandTimeout = null, CommandType? commandType = null) @@ -72,13 +92,18 @@ TReturn MapWithLazy(TFirst first, TSecond second, TThird third, TFourth fourth) return map(first, second, third, fourth); } - IEnumerable result = null; using (var conn = db.OpenConnection()) { - result = SqlMapper.Query(conn, sql, MapWithLazy, param, transaction, buffered, splitOn, commandTimeout, commandType); + try + { + return SqlMapper.Query(conn, sql, MapWithLazy, param, transaction, buffered, splitOn, commandTimeout, commandType); + } + catch (Exception e) + { + e.Data.Add("SQL", SqlBuilderExtensions.GetSqlLogString(sql, param)); + throw; + } } - - return result; } public static IEnumerable Query(this IDatabase db, string sql, Func map, object param = null, IDbTransaction transaction = null, bool buffered = true, string splitOn = "Id", int? commandTimeout = null, CommandType? commandType = null) @@ -93,13 +118,18 @@ TReturn MapWithLazy(TFirst first, TSecond second, TThird third, TFourth fourth, return map(first, second, third, fourth, fifth); } - IEnumerable result = null; using (var conn = db.OpenConnection()) { - result = SqlMapper.Query(conn, sql, MapWithLazy, param, transaction, buffered, splitOn, commandTimeout, commandType); + try + { + return SqlMapper.Query(conn, sql, MapWithLazy, param, transaction, buffered, splitOn, commandTimeout, commandType); + } + catch (Exception e) + { + e.Data.Add("SQL", SqlBuilderExtensions.GetSqlLogString(sql, param)); + throw; + } } - - return result; } public static IEnumerable Query(this IDatabase db, SqlBuilder builder)