1 /// Logging module
2 ///
3 /// This module provides logging functionality.
4 /// Everything is thread-safe at the exception of global severity and mask
5 /// getters/setters. This is done so to avoid paying for synchronization of log
6 /// entries that will be filtered out.
7 module gfx.core.log;
8 
9 import core.sync.mutex : Mutex;
10 import std.datetime : SysTime;
11 
12 /// LogTag encapsulate a string tag and a bitmask.
13 /// It a also have helpers to log entries with the given tag and mask.
14 struct LogTag
15 {
16     string tag;
17     uint mask = 0xffff_ffff;
18 
19     /// add a log entry with this tag
20     void log (in Severity sev, scope lazy string msg) const
21     {
22         .log (sev, mask, tag, msg);
23     }
24 
25     /// add a formatted log entry with this tag
26     void logf (Args...)(in Severity sev, in string fmt, Args args) const
27     {
28         .logf (sev, mask, tag, fmt, args);
29     }
30 
31     /// add a trace log entry with this tag
32     void trace (scope lazy string msg) const
33     {
34         .log (Severity.trace, mask, tag, msg);
35     }
36 
37     /// add a formatted trace log entry with this tag
38     void tracef (Args...)(in string fmt, Args args) const
39     {
40         .logf (Severity.trace, mask, tag, fmt, args);
41     }
42 
43     /// add a debug log entry with this tag
44     void debug_ (scope lazy string msg) const
45     {
46         .log (Severity.debug_, mask, tag, msg);
47     }
48 
49     /// add a formatted debug log entry with this tag
50     void debugf (Args...)(in string fmt, Args args) const
51     {
52         .logf (Severity.debug_, mask, tag, fmt, args);
53     }
54 
55     /// add a info log entry with this tag
56     void info (scope lazy string msg) const
57     {
58         .log (Severity.info, mask, tag, msg);
59     }
60 
61     /// add a formatted info log entry with this tag
62     void infof (Args...)(in string fmt, Args args) const
63     {
64         .logf (Severity.info, mask, tag, fmt, args);
65     }
66 
67     /// add a warning log entry with this tag
68     void warning (scope lazy string msg) const
69     {
70         .log (Severity.warning, mask, tag, msg);
71     }
72 
73     /// add a formatted warning log entry with this tag
74     void warningf (Args...)(in string fmt, Args args) const
75     {
76         .logf (Severity.warning, mask, tag, fmt, args);
77     }
78 
79     /// add a error log entry with this tag
80     void error (scope lazy string msg) const
81     {
82         .log (Severity.error, mask, tag, msg);
83     }
84 
85     /// add a formatted error log entry with this tag
86     void errorf (Args...)(in string fmt, Args args) const
87     {
88         .logf (Severity.error, mask, tag, fmt, args);
89     }
90 }
91 
92 /// Log messages severity
93 enum Severity
94 {
95     ///
96     trace,
97     /// debug messages
98     debug_,
99     ///
100     info,
101     ///
102     warning,
103     ///
104     error,
105 }
106 
107 debug {
108     /// The default severity
109     enum defaultSeverity = Severity.debug_;
110 }
111 else {
112     /// The default severity
113     enum defaultSeverity = Severity.info;
114 }
115 
116 /// The default filter mask
117 enum uint defaultMask = 0xffff_ffff;
118 
119 /// add a log entry
120 void log (in Severity sev, in string tag, scope lazy string msg)
121 {
122     if (cast(int)sev >= cast(int)s_sev) {
123         s_mutex.lock();
124         scope(exit) s_mutex.unlock();
125 
126         s_logger.print(s_msgFmt.formatMsg(sev, tag, msg));
127     }
128 }
129 /// ditto
130 void log (in Severity sev, in uint mask, in string tag, scope lazy string msg)
131 {
132     if (cast(int)sev >= cast(int)s_sev && (mask & s_mask) != 0) {
133         s_mutex.lock();
134         scope(exit) s_mutex.unlock();
135 
136         s_logger.print(s_msgFmt.formatMsg(sev, tag, msg));
137     }
138 }
139 /// ditto
140 void logf (Args...) (in Severity sev, in string tag, in string fmt, Args args)
141 {
142     import std.format : format;
143 
144     if (cast(int)sev >= cast(int)s_sev) {
145         s_mutex.lock();
146         scope(exit) s_mutex.unlock();
147 
148         s_logger.print(s_msgFmt.formatMsg(sev, tag, format(fmt, args)));
149     }
150 }
151 /// ditto
152 void logf (Args...) (in Severity sev, in uint mask, in string tag, in string fmt, Args args)
153 {
154     import std.format : format;
155 
156     if (cast(int)sev >= cast(int)s_sev && (mask & s_mask) != 0) {
157         s_mutex.lock();
158         scope(exit) s_mutex.unlock();
159 
160         s_logger.print(s_msgFmt.formatMsg(sev, tag, format(fmt, args)));
161     }
162 }
163 
164 /// add a log entry with trace severity
165 void trace (in string tag, scope lazy string msg)
166 {
167     log (Severity.trace, tag, msg);
168 }
169 /// ditto
170 void trace (in uint mask, in string tag, scope lazy string msg)
171 {
172     log (Severity.trace, mask, tag, msg);
173 }
174 /// ditto
175 void tracef (Args...)(in string tag, in string fmt, Args args)
176 {
177     logf (Severity.trace, tag, fmt, args);
178 }
179 /// ditto
180 void tracef (Args...)(in uint mask, in string tag, in string fmt, Args args)
181 {
182     logf (Severity.trace, mask, tag, fmt, args);
183 }
184 
185 /// add a log entry with debug severity
186 void debug_ (in string tag, scope lazy string msg)
187 {
188     log (Severity.debug_, tag, msg);
189 }
190 /// ditto
191 void debug_ (in uint mask, in string tag, scope lazy string msg)
192 {
193     log (Severity.debug_, mask, tag, msg);
194 }
195 /// ditto
196 void debugf (Args...)(in string tag, in string fmt, Args args)
197 {
198     logf (Severity.debug_, tag, fmt, args);
199 }
200 /// ditto
201 void debugf (Args...)(in uint mask, in string tag, in string fmt, Args args)
202 {
203     logf (Severity.debug_, mask, tag, fmt, args);
204 }
205 
206 /// add a log entry with info severity
207 void info (in string tag, scope lazy string msg)
208 {
209     log (Severity.info, tag, msg);
210 }
211 /// ditto
212 void info (in uint mask, in string tag, scope lazy string msg)
213 {
214     log (Severity.info, mask, tag, msg);
215 }
216 /// ditto
217 void infof (Args...)(in string tag, in string fmt, Args args)
218 {
219     logf (Severity.info, tag, fmt, args);
220 }
221 /// ditto
222 void infof (Args...)(in uint mask, in string tag, in string fmt, Args args)
223 {
224     logf (Severity.info, mask, tag, fmt, args);
225 }
226 
227 /// add a log entry with warning severity
228 void warning (in string tag, scope lazy string msg)
229 {
230     log (Severity.warning, tag, msg);
231 }
232 /// ditto
233 void warning (in uint mask, in string tag, scope lazy string msg)
234 {
235     log (Severity.warning, mask, tag, msg);
236 }
237 /// ditto
238 void warningf (Args...)(in string tag, in string fmt, Args args)
239 {
240     logf (Severity.warning, tag, fmt, args);
241 }
242 /// ditto
243 void warningf (Args...)(in uint mask, in string tag, in string fmt, Args args)
244 {
245     logf (Severity.warning, mask, tag, fmt, args);
246 }
247 
248 /// add a log entry with error severity
249 void error (in string tag, scope lazy string msg)
250 {
251     log (Severity.error, tag, msg);
252 }
253 /// ditto
254 void error (in uint mask, in string tag, scope lazy string msg)
255 {
256     log (Severity.error, mask, tag, msg);
257 }
258 /// ditto
259 void errorf (Args...)(in string tag, in string fmt, Args args)
260 {
261     logf (Severity.error, tag, fmt, args);
262 }
263 /// ditto
264 void errorf (Args...)(in uint mask, in string tag, in string fmt, Args args)
265 {
266     logf (Severity.error, mask, tag, fmt, args);
267 }
268 
269 /// An abstract logger. All log operations are synchronized by a global mutex.
270 /// Implementations do not need to bother about thread safety.
271 interface Logger
272 {
273     /// print msg into the log
274     void print(in string msg);
275     /// release resource associated with the logger
276     void close();
277 }
278 
279 /// A logger that prints into a file
280 class FileLogger : Logger
281 {
282     import std.stdio : File;
283 
284     private File file;
285 
286     /// open file pointed to by name with mode
287     this (in string name, in string mode="a")
288     {
289         file = File(name, mode);
290     }
291 
292     override void print(in string msg)
293     {
294         file.writeln(msg);
295     }
296 
297     override void close()
298     {
299         file.close();
300     }
301 }
302 
303 /// A logger that prints to stdout
304 class StdOutLogger : Logger
305 {
306     override void print (in string msg)
307     {
308         import std.stdio : stdout;
309 
310         stdout.writeln(msg);
311     }
312 
313     override void close() {}
314 }
315 
316 /// A logger that prints to stderr
317 class StdErrLogger : Logger
318 {
319     override void print (in string msg)
320     {
321         import std.stdio : stderr;
322 
323         stderr.writeln(msg);
324     }
325 
326     override void close() {}
327 }
328 
329 /// The installed logger.
330 /// By default StdOutLogger.
331 /// Assigning null re-assign the default
332 @property Logger logger()
333 {
334     s_mutex.lock();
335     scope(exit) s_mutex.unlock();
336 
337     return s_logger;
338 }
339 /// ditto
340 @property void logger (Logger logger)
341 {
342     s_mutex.lock();
343     scope(exit) s_mutex.unlock();
344 
345     if (logger !is s_logger) {
346         s_logger.close();
347     }
348     s_logger = logger;
349     if (!s_logger) {
350         s_logger = new StdOutLogger;
351     }
352 }
353 
354 /// Minimum Severity for message filtering.
355 /// All messages with lower severity are filtered out.
356 /// By default Severity.info in release builds and Severity.debug_ in debug builds.
357 @property Severity severity()
358 {
359     return s_sev;
360 }
361 /// ditto
362 @property void severity (in Severity sev)
363 {
364     s_sev = sev;
365 }
366 
367 /// A mask for bypassing some messages.
368 /// By default 0xffffffff
369 @property uint mask()
370 {
371     return s_mask;
372 }
373 /// ditto
374 @property void mask(in uint mask)
375 {
376     s_mask = mask;
377 }
378 
379 /// the default format string for log messages
380 enum string defaultMsgFormat = "%d %p%s: %t %m";
381 
382 /// The format string for log messages
383 /// The entries are as follow:
384 ///  - %d: datetime (formatted according timeFormat)
385 ///  - %s: severity
386 ///  - %p: padding of severity
387 ///  - %t: tag
388 ///  - %m: msg
389 /// The default format string is defaultMsgFormat
390 @property string msgFormat()
391 {
392     s_mutex.lock();
393     scope(exit) s_mutex.unlock();
394 
395     return s_msgFmt.fmt;
396 }
397 /// ditto
398 @property void msgFormat(in string fmt)
399 {
400     import std.utf : validate;
401 
402     validate(fmt);
403 
404     s_mutex.lock();
405     scope(exit) s_mutex.unlock();
406 
407     s_msgFmt = MessageFmt(fmt);
408 }
409 
410 /// the default format string for date-time
411 enum string defaultTimeFormat = "HH:ii:ss.FFF";
412 
413 /// The format string for date-time in log message
414 /// The format of this string is the same as smjg.libs.util.datetime:
415 /// http://pr.stewartsplace.org.uk/d/sutil/doc/datetimeformat.html
416 @property string timeFormat()
417 {
418     s_mutex.lock();
419     scope(exit) s_mutex.unlock();
420 
421     return s_timeFmt;
422 }
423 /// ditto
424 @property void timeFormat(in string fmt)
425 {
426     import std.utf : validate;
427 
428     validate(fmt);
429 
430     s_mutex.lock();
431     scope(exit) s_mutex.unlock();
432 
433     s_timeFmt = fmt;
434 }
435 
436 private:
437 
438 __gshared {
439     Mutex s_mutex;
440     Logger s_logger;
441     Severity s_sev;
442     uint s_mask;
443     string s_timeFmt;
444     MessageFmt s_msgFmt;
445 }
446 
447 shared static this()
448 {
449     s_mutex = new Mutex();
450     s_logger = new StdOutLogger;
451     s_sev = defaultSeverity;
452     s_mask = defaultMask;
453     s_timeFmt = defaultTimeFormat;
454     s_msgFmt = MessageFmt(defaultMsgFormat);
455 }
456 
457 shared static ~this()
458 {
459     s_logger.close();
460 }
461 
462 struct MessageFmt
463 {
464     enum EntryType {
465         str, datetime, sev, pad, tag, msg,
466     }
467     struct Entry {
468         EntryType typ;
469         string str;
470     }
471 
472     this (string fmt)
473     {
474         this.fmt = fmt;
475 
476         string curStr;
477         bool percent;
478         foreach (char c; fmt) {
479             if (percent) {
480                 switch (c) {
481                 case 'd': entries ~= Entry(EntryType.datetime); break;
482                 case 's': entries ~= Entry(EntryType.sev); break;
483                 case 'p': entries ~= Entry(EntryType.pad); break;
484                 case 't': entries ~= Entry(EntryType.tag); break;
485                 case 'm': entries ~= Entry(EntryType.msg); break;
486                 default: throw new Exception("unknown log format entry: %"~c);
487                 }
488                 percent = false;
489             }
490             else if (c == '%') {
491                 if (curStr.length) {
492                     entries ~= Entry(EntryType.str, curStr);
493                     curStr = null;
494                 }
495                 percent = true;
496             }
497             else {
498                 curStr ~= c;
499             }
500         }
501         if (curStr.length) {
502             entries ~= Entry(EntryType.str, curStr);
503         }
504     }
505 
506     string fmt;
507     Entry[] entries;
508 
509     string formatMsg(in Severity sev, in string tag, in string msg)
510     {
511         import std.datetime : Clock;
512 
513         string res;
514         foreach (entry; entries) {
515             final switch (entry.typ) {
516             case EntryType.str:  res ~= entry.str;                      break;
517             case EntryType.datetime: res ~= formatTime(Clock.currTime); break;
518             case EntryType.sev: res ~= sevString(sev);                  break;
519             case EntryType.pad: res ~= sevPadString(sev);               break;
520             case EntryType.tag : res ~= tag;                            break;
521             case EntryType.msg : res ~= msg;                            break;
522             }
523         }
524         return res;
525     }
526 }
527 
528 string sevString(in Severity sev) pure
529 {
530     final switch (sev)
531     {
532     case Severity.trace: return "TRACE";
533     case Severity.debug_: return "DEBUG";
534     case Severity.info: return "INFO";
535     case Severity.warning: return "WARN";
536     case Severity.error: return "ERROR";
537     }
538 }
539 
540 string sevPadString(in Severity sev) pure
541 {
542     final switch (sev)
543     {
544     case Severity.trace: return null;
545     case Severity.debug_: return null;
546     case Severity.info: return " ";
547     case Severity.warning: return " ";
548     case Severity.error: return null;
549     }
550 }
551 
552 string formatTime(SysTime time)
553 {
554     import gfx.priv.datetimeformat : format;
555 
556     return format(time, s_timeFmt);
557 }