1 /** 2 Central logging facility for dalicious. 3 4 Copyright: © 2019 Arne Ludwig <arne.ludwig@posteo.de> 5 License: Subject to the terms of the MIT license, as written in the 6 included LICENSE file. 7 Authors: Arne Ludwig <arne.ludwig@posteo.de> 8 */ 9 module dalicious.log; 10 11 import std.array; 12 import std.datetime; 13 import std.format; 14 import std.process; 15 import std.range; 16 import std.stdio; 17 import core.thread; 18 19 private 20 { 21 __gshared LogLevel minLevel = LogLevel.info; 22 } 23 24 /// Sets the minimum log level to be printed. 25 void setLogLevel(LogLevel level) nothrow 26 { 27 synchronized 28 minLevel = level; 29 } 30 31 LogLevel getLogLevel() 32 { 33 return minLevel; 34 } 35 36 bool shouldLog(LogLevel level) 37 { 38 return level >= minLevel; 39 } 40 41 /** 42 Logs a message in JSON format. 43 Params: 44 args = pairs of `name` (`string`) and `value` 45 */ 46 void logJsonDebug(T...)(lazy T args) nothrow 47 { 48 logJson(LogLevel.debug_, args); 49 } 50 /// ditto 51 void logJsonDiagnostic(T...)(lazy T args) nothrow 52 { 53 logJson(LogLevel.diagnostic, args); 54 } 55 /// ditto 56 void logJsonInfo(T...)(lazy T args) nothrow 57 { 58 logJson(LogLevel.info, args); 59 } 60 /// ditto 61 void logJsonWarn(T...)(lazy T args) nothrow 62 { 63 logJson(LogLevel.warn, args); 64 } 65 /// ditto 66 void logJsonError(T...)(lazy T args) nothrow 67 { 68 logJson(LogLevel.error, args); 69 } 70 71 /// ditto 72 void logJson(T...)(LogLevel level, lazy T args) nothrow 73 { 74 import dalicious.range : Chunks, chunks; 75 import std.datetime.systime : Clock; 76 import std.traits : isSomeString; 77 import vibe.data.json : Json, serializeToJson; 78 79 enum threadKey = "thread"; 80 enum timestampKey = "timestamp"; 81 82 if (level < minLevel) 83 return; 84 85 try 86 { 87 Json json = Json.emptyObject; 88 89 static foreach (KeyValuePair; Chunks!(2, T)) 90 { 91 static assert(isSomeString!(KeyValuePair.chunks[0]), "missing name"); 92 } 93 94 json[timestampKey] = Clock.currStdTime; 95 json[threadKey] = thisThreadID; 96 97 foreach (keyValuePair; args.chunks!2) 98 json[keyValuePair[0]] = serializeToJson(keyValuePair[1]); 99 100 return log(level, json.to!string); 101 } 102 catch (Exception e) 103 { 104 // this is bad but what can we do.. 105 debug assert(false, e.msg); 106 } 107 } 108 109 /// 110 unittest 111 { 112 import std.stdio : File, stderr; 113 import vibe.data.json : Json, parseJsonString; 114 115 auto origStderr = stderr; 116 stderr = File.tmpfile(); 117 scope (exit) 118 { 119 stderr.close(); 120 stderr = origStderr; 121 } 122 123 logJsonError("error", "mysterious observation", "secret", 42); 124 125 stderr.rewind(); 126 auto observed = parseJsonString(stderr.readln); 127 128 assert(observed["thread"].type == Json.Type.int_); 129 assert(observed["timestamp"].type == Json.Type.int_); 130 assert(observed["error"] == "mysterious observation"); 131 assert(observed["secret"] == 42); 132 } 133 134 /** 135 Logs a message. 136 Params: 137 level = The log level for the logged message 138 fmt = See http://dlang.org/phobos/std_format.html#format-string 139 */ 140 void logDebug(T...)(string fmt, lazy T args) nothrow 141 { 142 log(LogLevel.debug_, fmt, args); 143 } 144 /// ditto 145 void logDiagnostic(T...)(string fmt, lazy T args) nothrow 146 { 147 log(LogLevel.diagnostic, fmt, args); 148 } 149 /// ditto 150 void logInfo(T...)(string fmt, lazy T args) nothrow 151 { 152 log(LogLevel.info, fmt, args); 153 } 154 /// ditto 155 void logWarn(T...)(string fmt, lazy T args) nothrow 156 { 157 log(LogLevel.warn, fmt, args); 158 } 159 /// ditto 160 void logError(T...)(string fmt, lazy T args) nothrow 161 { 162 log(LogLevel.error, fmt, args); 163 } 164 165 /// ditto 166 void log(T...)(LogLevel level, string fmt, lazy T args) nothrow 167 { 168 if (level < minLevel) 169 return; 170 171 try 172 { 173 auto txt = appender!string(); 174 txt.reserve(256); 175 static if (args.length > 0) 176 { 177 formattedWrite(txt, fmt, args); 178 } 179 else 180 { 181 txt ~= fmt; 182 } 183 184 if (level >= minLevel) 185 { 186 File output = stderr; 187 188 synchronized if (output.isOpen) 189 { 190 output.writeln(txt.data); 191 output.flush(); 192 } 193 } 194 } 195 catch (Exception e) 196 { 197 // this is bad but what can we do.. 198 debug assert(false, e.msg); 199 } 200 } 201 202 /// Specifies the log level for a particular log message. 203 enum LogLevel 204 { 205 debug_, 206 diagnostic, 207 info, 208 warn, 209 error, 210 fatal, 211 none 212 } 213 214 struct ExecutionTracer(LogLevel logLevel = LogLevel.diagnostic) 215 { 216 import std.datetime.stopwatch : StopWatch; 217 import std.typecons : Yes; 218 219 string functionName; 220 StopWatch timer; 221 222 this(int dummy, string fnName = __FUNCTION__) nothrow @safe 223 { 224 this.functionName = fnName; 225 226 () @trusted { logJson( 227 logLevel, 228 `state`, `enter`, 229 `function`, this.functionName, 230 ); }(); 231 232 this.timer = StopWatch(Yes.autoStart); 233 } 234 235 ~this() nothrow @safe 236 { 237 timer.stop(); 238 239 () @trusted { logJson( 240 logLevel, 241 `state`, `exit`, 242 `function`, functionName, 243 `timeElapsedSecs`, timer.peek().total!`hnsecs` * 100e-9, 244 ); }(); 245 } 246 } 247 248 string traceExecution(LogLevel logLevel = LogLevel.diagnostic)() 249 { 250 import std.conv : to; 251 import std..string : replace; 252 import std.traits : moduleName; 253 254 return q"{ 255 static import $thisModule; 256 257 scope __executionTracer = $thisModule.ExecutionTracer!($logLevel)(0); 258 }" 259 .replace("$thisModule", moduleName!LogLevel) 260 .replace("$logLevel", "LogLevel." ~ logLevel.to!string); 261 } 262 263 264 unittest 265 { 266 import std.regex : ctRegex, matchFirst; 267 import std.stdio : File, stderr; 268 import vibe.data.json : Json, parseJsonString; 269 270 auto origStderr = stderr; 271 stderr = File.tmpfile(); 272 scope (exit) 273 { 274 stderr.close(); 275 stderr = origStderr; 276 } 277 278 void doSomething() 279 { 280 mixin(traceExecution!(LogLevel.error)); 281 282 import core.thread : Thread; 283 import core.time : dur; 284 285 Thread.getThis.sleep(dur!"hnsecs"(50)); 286 } 287 288 doSomething(); 289 stderr.rewind(); 290 291 enum functionFQN = ctRegex!`dalicious\.log\.__unittest_L[0-9]+_C[0-9]+\.doSomething`; 292 auto observed1 = parseJsonString(stderr.readln); 293 auto observed2 = parseJsonString(stderr.readln); 294 295 assert(observed1["thread"].type == Json.Type.int_); 296 assert(observed1["timestamp"].type == Json.Type.int_); 297 assert(observed1["state"] == "enter"); 298 assert(matchFirst(observed1["function"].to!string, functionFQN)); 299 300 assert(observed2["thread"].type == Json.Type.int_); 301 assert(observed2["timestamp"].type == Json.Type.int_); 302 assert(observed2["state"] == "exit"); 303 assert(matchFirst(observed2["function"].to!string, functionFQN)); 304 } 305 306 /// Create a new todo. A todo list will be generated on end of compilation. 307 debug enum todo(string task, string file = __FILE__, size_t line = __LINE__) = 308 "[TODO] " ~ task ~ " at " ~ file ~ ":" ~ line.stringof;