From e769a9b1ca8076e4aeceb573c86140a950f9cf8f Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?S=C3=B6nke=20Ludwig?= Date: Thu, 23 Mar 2017 17:45:31 +0100 Subject: [PATCH] Avoid lazy evaluation of log arguments while the loggers are locked. Fixes rejectedsoftware/vibe.d#1717. The deadlock happened because a function that waits for a worker task to finish was passed to the log functions. Evaluated lazily, it got called while the logger's mutex was locked, meaning that any log call from within that thread would cause a deadlock. This change also has another, possibly important, implication - arguments are evaluated only once instead of possibly multiple times if multiple loggers are registered. This could very well make a lot of existing (wrong) code more robust (e.g. logInfo("%s", i++)). --- source/vibe/core/log.d | 48 ++++++++++++++++++++++++------------------ 1 file changed, 28 insertions(+), 20 deletions(-) diff --git a/source/vibe/core/log.d b/source/vibe/core/log.d index 2bfebcc..505bd42 100644 --- a/source/vibe/core/log.d +++ b/source/vibe/core/log.d @@ -115,37 +115,28 @@ nothrow { args = Any input values needed for formatting */ void log(LogLevel level, /*string mod = __MODULE__, string func = __FUNCTION__,*/ string file = __FILE__, int line = __LINE__, S, T...)(S fmt, lazy T args) - nothrow if (isSomeString!S) + nothrow if (isSomeString!S && level != LogLevel.none) { - static assert(level != LogLevel.none); - try { - foreach (l; getLoggers()) - if (l.minLevel <= level) { // WARNING: TYPE SYSTEM HOLE: accessing field of shared class! - auto ll = l.lock(); - auto rng = LogOutputRange(ll, file, line, level); - /*() @trusted {*/ rng.formattedWrite(fmt, args); //} (); // formattedWrite is not @safe at least up to 2.068.0 - rng.finalize(); - } - } catch(Exception e) debug assert(false, e.msg); + doLog(level, null, null, file, line, fmt, args); } /// ditto -void logTrace(/*string mod = __MODULE__, string func = __FUNCTION__,*/ string file = __FILE__, int line = __LINE__, S, T...)(S fmt, lazy T args) nothrow { log!(LogLevel.trace/*, mod, func*/, file, line)(fmt, args); } +void logTrace(/*string mod = __MODULE__, string func = __FUNCTION__,*/ string file = __FILE__, int line = __LINE__, S, T...)(S fmt, lazy T args) nothrow { doLog(LogLevel.trace, null, null/*, mod, func*/, file, line, fmt, args); } /// ditto -void logDebugV(/*string mod = __MODULE__, string func = __FUNCTION__,*/ string file = __FILE__, int line = __LINE__, S, T...)(S fmt, lazy T args) nothrow { log!(LogLevel.debugV/*, mod, func*/, file, line)(fmt, args); } +void logDebugV(/*string mod = __MODULE__, string func = __FUNCTION__,*/ string file = __FILE__, int line = __LINE__, S, T...)(S fmt, lazy T args) nothrow { doLog(LogLevel.debugV, null, null/*, mod, func*/, file, line, fmt, args); } /// ditto -void logDebug(/*string mod = __MODULE__, string func = __FUNCTION__,*/ string file = __FILE__, int line = __LINE__, S, T...)(S fmt, lazy T args) nothrow { log!(LogLevel.debug_/*, mod, func*/, file, line)(fmt, args); } +void logDebug(/*string mod = __MODULE__, string func = __FUNCTION__,*/ string file = __FILE__, int line = __LINE__, S, T...)(S fmt, lazy T args) nothrow { doLog(LogLevel.debug_, null, null/*, mod, func*/, file, line, fmt, args); } /// ditto -void logDiagnostic(/*string mod = __MODULE__, string func = __FUNCTION__,*/ string file = __FILE__, int line = __LINE__, S, T...)(S fmt, lazy T args) nothrow { log!(LogLevel.diagnostic/*, mod, func*/, file, line)(fmt, args); } +void logDiagnostic(/*string mod = __MODULE__, string func = __FUNCTION__,*/ string file = __FILE__, int line = __LINE__, S, T...)(S fmt, lazy T args) nothrow { doLog(LogLevel.diagnostic, null, null/*, mod, func*/, file, line, fmt, args); } /// ditto -void logInfo(/*string mod = __MODULE__, string func = __FUNCTION__,*/ string file = __FILE__, int line = __LINE__, S, T...)(S fmt, lazy T args) nothrow { log!(LogLevel.info/*, mod, func*/, file, line)(fmt, args); } +void logInfo(/*string mod = __MODULE__, string func = __FUNCTION__,*/ string file = __FILE__, int line = __LINE__, S, T...)(S fmt, lazy T args) nothrow { doLog(LogLevel.info, null, null/*, mod, func*/, file, line, fmt, args); } /// ditto -void logWarn(/*string mod = __MODULE__, string func = __FUNCTION__,*/ string file = __FILE__, int line = __LINE__, S, T...)(S fmt, lazy T args) nothrow { log!(LogLevel.warn/*, mod, func*/, file, line)(fmt, args); } +void logWarn(/*string mod = __MODULE__, string func = __FUNCTION__,*/ string file = __FILE__, int line = __LINE__, S, T...)(S fmt, lazy T args) nothrow { doLog(LogLevel.warn, null, null/*, mod, func*/, file, line, fmt, args); } /// ditto -void logError(/*string mod = __MODULE__, string func = __FUNCTION__,*/ string file = __FILE__, int line = __LINE__, S, T...)(S fmt, lazy T args) nothrow { log!(LogLevel.error/*, mod, func*/, file, line)(fmt, args); } +void logError(/*string mod = __MODULE__, string func = __FUNCTION__,*/ string file = __FILE__, int line = __LINE__, S, T...)(S fmt, lazy T args) nothrow { doLog(LogLevel.error, null, null/*, mod, func*/, file, line, fmt, args); } /// ditto -void logCritical(/*string mod = __MODULE__, string func = __FUNCTION__,*/ string file = __FILE__, int line = __LINE__, S, T...)(S fmt, lazy T args) nothrow { log!(LogLevel.critical/*, mod, func*/, file, line)(fmt, args); } +void logCritical(/*string mod = __MODULE__, string func = __FUNCTION__,*/ string file = __FILE__, int line = __LINE__, S, T...)(S fmt, lazy T args) nothrow { doLog(LogLevel.critical, null, null/*, mod, func*/, file, line, fmt, args); } /// ditto -void logFatal(string file = __FILE__, int line = __LINE__, S, T...)(S fmt, lazy T args) nothrow { log!(LogLevel.fatal, file, line)(fmt, args); } +void logFatal(string file = __FILE__, int line = __LINE__, S, T...)(S fmt, lazy T args) nothrow { doLog(LogLevel.fatal, null, null, file, line, fmt, args); } /// @safe unittest { @@ -794,9 +785,26 @@ package void initializeLogModule() setLogLevel(cast(LogLevel)(LogLevel.diagnostic - i)); break; } + + if (verbose[3]) setLogFormat(FileLogger.Format.threadTime, FileLogger.Format.threadTime); } } +private nothrow void doLog(S, T...)(LogLevel level, string mod, string func, string file, int line, S fmt, lazy T args) +{ + try { + auto args_copy = args; + + foreach (l; getLoggers()) + if (l.minLevel <= level) { // WARNING: TYPE SYSTEM HOLE: accessing field of shared class! + auto ll = l.lock(); + auto rng = LogOutputRange(ll, file, line, level); + /*() @trusted {*/ rng.formattedWrite(fmt, args_copy); //} (); // formattedWrite is not @safe at least up to 2.068.0 + rng.finalize(); + } + } catch(Exception e) debug assert(false, e.msg); +} + private struct LogOutputRange { LogLine info; ScopedLock!Logger* logger;