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;