debian-packages/vibe-core
1
0
Fork 0
Code Issues Pull requests Projects Releases Wiki Activity

Avoid lazy evaluation of log arguments while the loggers are locked. Fixes rejectedsoftware/vibe.d#1717.

Browse source 
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++)).
This commit is contained in:
Sönke Ludwig 2017-03-23 17:45:31 +01:00
parent bcf1dfe799
commit e769a9b1ca
1 changed files with 28 additions and 20 deletions
Show stats Download patch file Download diff file Expand all files Collapse all files

48
source/vibe/core/log.d
View file

@ -115,37 +115,28 @@ nothrow {
args = Any input values needed for formatting 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) 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); doLog(level, null, null, file, line, fmt, args);
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);
} }
/// ditto /// 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 /// 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 /// 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 /// 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 /// 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 /// 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 /// 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 /// 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 /// 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 { @safe unittest {
@ -794,9 +785,26 @@ package void initializeLogModule()
setLogLevel(cast(LogLevel)(LogLevel.diagnostic - i)); setLogLevel(cast(LogLevel)(LogLevel.diagnostic - i));
break; 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 { private struct LogOutputRange {
LogLine info; LogLine info;
ScopedLock!Logger* logger; ScopedLock!Logger* logger;