1 module glued.logging;
2 
3 import std.conv: to, text;
4 import std.traits: EnumMembers;
5 import std.algorithm: maxElement, min, startsWith;
6 
7 import optional;
8 import properd;
9 
10 //todo this module could really use splitting down to package
11 
12 enum ___Module___;
13 
14 enum Level {
15     ANY,
16     DEVELOPMENT,
17     TRACE,
18     DEBUG,
19     INFO,
20     WARN,
21     ERROR,
22     NONE
23 }
24 
25 Level toLevel(string s){
26     foreach (v; EnumMembers!Level){
27         if (v.to!string == s){
28             return v;
29         }
30     }
31     throw new Exception("No level named "~s);
32 }
33 
34 immutable maxLevelNameLength = (cast(Level[]) [ EnumMembers!Level ]).maxElement!"to!string(a).length".to!string.length;
35 
36 string cutDown(string s, size_t len){
37     return s[0..min(len, s.length)];
38 }
39 
40 string enforceLength(string s, int maxLength){
41     if (s.length > 40){
42         s = s.normalize;
43     }
44     if (s.length > 40){
45         s = s.shorten;
46     }
47     if (s.length > 40){
48         s = s.shortenLastSegmentTemplating;
49     }
50     if (s.length > 40){
51         s = s.collapse(40);
52     }
53     if (s.length > 40){
54         s = "..."~s[$-37..$];
55     }
56     return s;
57 }
58 
59 string format(LogEvent e){
60     import std..string;
61     string lvl = to!string(e.level).center(maxLevelNameLength, ' ');
62     string path = e.loggerLocation.path;
63     //if log happens in same aggregate place as logger was declared, use event path
64     //if not, that means that logger was passed around to another piece of code
65     //  in such case we should still show path of logger, since its the logger
66     //  that is communicating to the reader of log
67     if (e.eventLocation.path.startsWith(path))
68         path = e.eventLocation.path;
69     path = path.enforceLength(40);
70     //todo enforce filename length in similar fashion; probably wrap these functions into struct that takes separator as field
71     string filename = e.eventLocation.filename;
72     string tid;
73     return (filename~":"~to!string(e.eventLocation.line)).leftJustify(55)~" @ "~
74     ( e.timestamp.empty ? 
75         "N/A (compile-time)".center(25, ' ') : 
76         e.timestamp.front().to!string.cutDown(25).leftJustify(25, ' ')
77      ) ~ " ( " ~
78      ( e.tid.empty ?
79         "N/A".center(12, ' ') :
80         e.tid.front().to!string["Tid(".length..$-")".length].center(12, ' ')
81      ) ~
82      " ) [ " ~ lvl ~ " ] " ~ 
83      path.leftJustify(40, ' ')~" | "~
84      to!string(e.message);
85 }
86 
87 struct StaticSink {
88     import std.array;
89     import std.conv;
90     
91     private static string getBuildLogConfig(string filename)(){
92         static if (__traits(compiles, import(filename)) && !import(filename).empty){
93             return import(filename);
94         } else {
95             version(silent_build) {}
96             else
97             {
98                 pragma(msg, "Build log configuration ("~filename~") is missing or is empty!");
99             }
100             return "";
101         }
102     }
103     
104     //todo this can be useful for runtime logging as well
105     //fixme there is similar class-based structure in utils (treepath) - it would be useful here if it would be a struct
106     private struct PackageLogEntry {
107         string fullModuleName;
108         PackageLogEntry[string] subModules;
109         Optional!Level explicitDefinition = no!Level;
110         
111         void put(string modName, Level lvl){
112             put(modName.split("."), lvl);
113         }
114         
115         void put(string[] modName, Level lvl){
116             if (modName.empty){
117                 explicitDefinition = lvl;
118             } else {
119                 if (!(modName[0] in subModules)){
120                     string subName = (this.fullModuleName.empty ? "" : this.fullModuleName~".")~modName[0];
121                     subModules[modName[0]] = PackageLogEntry(subName);
122                 }
123                 subModules[modName[0]].put(modName[1..$], lvl);
124             }
125         }
126         
127         Optional!Level get(string modName){
128             return get(modName.split("."));
129         }
130     
131         Optional!Level get(string[] modName){
132             if (modName.empty){
133                 return explicitDefinition;
134             }
135             auto deeperResult = modName[0] in subModules ? subModules[modName[0]].get(modName[1..$]) : no!Level;
136             if (deeperResult.empty){
137                 return explicitDefinition;
138             }
139             return deeperResult;
140         }
141     }
142     
143     private static PackageLogEntry getBuildLogProperd(){
144         PackageLogEntry[string] x;
145         PackageLogEntry root = PackageLogEntry("", x, no!Level);
146         void load(string filename)()
147         {
148             auto props = parseProperties(getBuildLogConfig!(filename)());
149         
150             foreach (k; props.keys()){
151                 auto name = k;
152                 if (name.startsWith("log.level")) {
153                     name = name["log.level".length..$];
154                     if (name.startsWith("."))
155                         name = name[1..$];
156                     root.put(name, props[k].toLevel);
157                 }
158             }
159         }
160         //todo test this finally...
161         load!"buildLog.conf"();
162         version(unittest)
163         {
164             load!"buildLog.test.conf"();
165         }
166         
167         if (root.explicitDefinition.empty)
168         {
169             version (silent_build)
170             {
171                 root.explicitDefinition = Level.NONE.some;
172             }
173             else 
174             {
175                 root.explicitDefinition = Level.INFO.some;
176             }
177         }
178         return root;
179     }
180 
181     private static string formatLogEvent(LogEvent e){
182         //todo add format specified in build log config
183         return format(e);
184     }
185     
186     static bool shouldShow(LogEvent e){
187         //todo would checking eventLocation make more sense? maybe per-type filtering as well?
188         //we can safely call front() without worrying about empty optional, because root always have a default
189         return getBuildLogProperd().get(e.loggerLocation.moduleName).front() <= e.level;
190     }
191 
192     static void consume(LogEvent e)(){
193         static if (shouldShow(e)){
194             pragma(msg, formatLogEvent(e));
195         }
196     }
197 }
198 
199 interface LogSink {
200     void consume(LogEvent e);
201 }
202 
203 
204 class DeferredLogSink: LogSink {
205     private LogEvent[] _deferred;
206     private LogSink _delegate = null;
207     
208     void consume(LogEvent e){
209         if (_delegate is null){
210             _deferred ~= e;
211         } else {
212             _delegate.consume(e);
213         }
214     }
215     
216     @property
217     bool resolved(){
218         return _delegate !is null;
219     }
220     
221     void resolve(LogSink sink){
222         if (_delegate is null){
223             _delegate = sink;
224             flushDeferred();
225         } else {
226             assert(false); //todo exception
227         }
228     }
229     
230     private void flushDeferred(){
231         foreach (e; _deferred)
232             _delegate.consume(e);
233         _deferred = [];
234     }
235 }
236 
237 ///Trivial sink, useful mostly for debugging, development and testing
238 class StdoutSink: LogSink {
239     import std.stdio;
240         
241     override void consume(LogEvent e){
242         //todo if dev.emit is used, be angry? I mean, that method shouldn't be used in the final commit
243         //todo this is a quickfix for log filtering; use this to implement bundles, then use bundles to load runtime config in... well, runtime
244         if (StaticSink.shouldShow(e)){
245             stdout.writeln(format(e));
246             stdout.flush();
247         }
248     }
249 }
250 
251 ///No-op sink, usually used as a default param value
252 class VoidSink: LogSink {
253     override void consume(LogEvent e){}
254 }
255 
256 /**
257  * if p="a.b!(c.d).e", then segments = ["a", "b!(c", "d)", "e"]
258  * this foo turns that back to ["a", "b!(c.d)", "e"]
259  */
260 string[] mergeBrokenSegments(string[] segs) {
261     bool isBalanced(string s){
262         import std.algorithm: canFind, sum;
263         char[char] closingToOpen;
264         closingToOpen[')'] = '(';
265         closingToOpen[']'] = '[';
266         int[char] counts;
267         foreach (c; s){
268             if (closingToOpen.values.canFind(c)){
269                 counts[c] += 1;
270             } else if (c in closingToOpen){
271                 counts[closingToOpen[c]] -= 1;
272             }
273         }
274         return counts.values.sum == 0;
275     }
276     string[] result;
277     int i;
278     while (i < segs.length){
279         string current = segs[i];
280         while (!isBalanced(current)){
281             i += 1;
282             if (i < segs.length){
283                 current ~= "."~segs[i];
284             } else {
285                 if (!isBalanced(current)){
286                     throw new Exception("Segments: "~to!string(segs)~" cannot be merged; the whole path doesn't seem to be balanced!");
287                 }
288             }
289         }
290         i += 1;
291         result ~= current;
292     }
293     return result;
294 }
295 
296 
297 /**
298  * turn ["a", "b!(x)", "b"] (path "a.b!(x).b") into  ["a, "b!(x)"] ("a.b!(x)")
299  * Assumes that input was already fixed with mergeBrokenSegments
300  */
301 string[] normalizeSegments(string[] segs){
302     import std.algorithm: startsWith;
303     string[] result;
304     int i; 
305     while (i < segs.length-1){
306         result ~= segs[i];
307         if (segs[i].startsWith(segs[i+1]~"!")){
308             i += 2;
309         } else {
310             i += 1;
311         }
312     }
313     //todo there is probably some smarter condition to be used here
314     if (result[$-1] != segs[$-1] && !result[$-1].startsWith(segs[$-1]))
315         result ~= segs[$-1];
316     return result;
317 }
318 
319 string normalize(string p){
320     import std..string;
321     string[] segments= p.split(".");
322        
323     string[] merged = mergeBrokenSegments(segments);
324     
325     string[] normalized = normalizeSegments(merged);
326     return normalized.join(".");
327 }
328 
329 //todo params fromRight/fromLeft and maxLength
330 string[] shortenSegments(string[] segs){
331     import std..string;
332     import std.algorithm;
333     string shortenSegment(string seg){
334         string result = seg[0..1];
335         if (seg.canFind("!")){
336             result ~= "!(";
337             string toAdd = seg.split("!")[1];
338             while (toAdd.startsWith("!") || toAdd.startsWith("("))
339                 toAdd = toAdd[1..$];
340             bool closeBrace = false;
341             if (toAdd.startsWith("[")){
342                 closeBrace = true;
343                 result ~= "[";
344                 toAdd = toAdd[1..$];
345                 while (toAdd.startsWith("!") || toAdd.startsWith("("))
346                     toAdd = toAdd[1..$];
347             }
348             result ~= toAdd[0];
349             if (closeBrace)
350                 result ~= "...]";
351             result ~= ")";
352         }
353         return result;
354     }
355     string[] result;
356     foreach (s; segs[0..$-1]){
357         result ~= shortenSegment(s);
358     }
359     result ~= segs[$-1];
360     return result;
361 }
362 
363 string shorten(string p){
364     import std..string;
365     string[] segments= p.split(".");
366        
367     string[] merged = mergeBrokenSegments(segments);
368     
369     string[] shortened = shortenSegments(merged);
370     return shortened.join(".");
371 }
372 
373 string shortenLastSegmentTemplating(string p){
374     import std..string;
375     import std.algorithm;
376     string[] segments= p.split(".");
377        
378     string[] merged = mergeBrokenSegments(segments);
379     string foo(string seg){
380         string result = seg.split("!")[0];
381         if (seg.canFind("!")){
382             result ~= "!(";
383             string toAdd = seg.split("!")[1];
384             while (toAdd.startsWith("!") || toAdd.startsWith("("))
385                 toAdd = toAdd[1..$];
386             bool closeBrace = false;
387             if (toAdd.startsWith("[")){
388                 closeBrace = true;
389                 result ~= "[";
390                 toAdd = toAdd[1..$];
391                 while (toAdd.startsWith("!") || toAdd.startsWith("("))
392                     toAdd = toAdd[1..$];
393             }
394             result ~= toAdd[0];
395             if (closeBrace)
396                 result ~= "...]";
397             result ~= ")";
398         }
399         return result;
400     }
401     string[] shortened = segments[0..$-1] ~ foo(segments[$-1]);
402     return shortened.join(".");
403 }
404 
405 
406 string collapse(string p, int maxLength){
407     if (p.length <= maxLength){
408         return p;
409     }
410     import std..string;
411     import std.stdio;
412     string[] segments= p.split(".");
413        
414     string[] merged = mergeBrokenSegments(segments);
415     string[] pre;
416     string[] post;
417     immutable filler = "(...)";
418     string result(){
419         return (pre ~ (merged.empty ? [] : [filler]) ~ post).join(".");
420     }
421     bool fromRight = true;
422     while (!merged.empty){
423         if (fromRight){
424             post = [ merged[$-1] ]~post;
425             merged = merged[0..$-1];
426             if (result().length > maxLength){
427                 merged ~= post[0];
428                 post = post[1..$];
429                 break;
430             }
431             fromRight = false;
432         } else {
433             pre ~= merged[0];
434             merged = merged[1..$];
435             if (result().length > maxLength){
436                 merged = pre[$-1] ~ merged;
437                 pre = pre[0..$-1];
438                 break;
439             }
440             fromRight = true;
441         }
442     }
443     //if this couldn't produce a valid result, or the result was just (...), then 
444     //just return original version and let the caller worry about it, we cannot 
445     //collapse it any better
446     if (result().length > maxLength || (pre.empty && post.empty))
447         return p;
448     return result();
449 }
450 
451 
452 struct CodeLocation {
453     string filename;
454     int line;
455     string moduleName;
456     string aggregateName;
457     string functionName;
458     string prettyFunctionName;
459 
460     @property
461     string path(){
462         if (functionName.length)
463             return functionName;
464         if (aggregateName.length)
465             return aggregateName;
466         if (moduleName.length)
467             return moduleName;
468         assert(false);
469     }
470 }
471 
472 struct LogEvent {
473     import optional: Optional;
474     import std.datetime: SysTime;
475     import std.concurrency: Tid;
476 
477     Level level;
478     CodeLocation loggerLocation;
479     CodeLocation eventLocation;
480     string message;
481     
482     Optional!SysTime timestamp;
483     Optional!Tid tid;
484 }
485 
486 mixin template CreateLogger(string f=__FILE__, int l=__LINE__, string m=__MODULE__, string foo=__FUNCTION__,  string prettyFoo=__PRETTY_FUNCTION__){
487     static if (__traits(compiles, typeof(this))){
488         alias Here = typeof(this);
489     } else {
490         alias Here = ___Module___;
491     }
492     
493     struct Logger {
494         import std.traits: fullyQualifiedName;
495         import std.meta: staticMap;
496         import std.conv: to;
497         import std..string: join;
498         import std.algorithm: startsWith;
499         import std.array: split;
500         import std.datetime: Clock, SysTime;
501         import std.concurrency: thisTid, Tid;
502         import optional: Optional, no, some;
503         
504         LogSink logSink;
505         
506         this(LogSink logSink){
507             this.logSink = logSink;
508         }
509         
510         this(string f=__FILE__, int l=__LINE__, string m=__MODULE__, string foo=__FUNCTION__, string prettyFoo=__PRETTY_FUNCTION__)(){
511             Warn!(f, l, m, foo, prettyFoo).Emit!("Creating logger with default sink! You're probably misconfigured!");
512             this(new StdoutSink);
513         }
514         
515         @property
516         static CodeLocation location(){
517             static if (is(Here == ___Module___)){
518                 return CodeLocation(f, l, m, "", foo, prettyFoo);
519             } else {
520                 return CodeLocation(f, l, m, fullyQualifiedName!Here, foo, prettyFoo);
521             }
522         }
523         
524         static LogEvent event(Level level, string message, CodeLocation eventLocation, bool figureOutEventAggregate=true){
525             if (figureOutEventAggregate) { //todo you removed config, it was there; what to do with this?
526                 
527                 if (location.moduleName == eventLocation.moduleName && 
528                     location.aggregateName.length > 0 && eventLocation.functionName.length > 0 && 
529                     eventLocation.functionName.startsWith(location.aggregateName)){
530                         eventLocation.aggregateName = eventLocation.functionName.split(".")[0..$-1].join(".");
531                 }
532             }
533             if (__ctfe){
534                 return LogEvent(level, location, eventLocation, message, no!SysTime, no!Tid);
535             } else {
536                 return LogEvent(level, location, eventLocation, message, Clock.currTime().some, thisTid.some);
537             }
538         }
539         
540         struct LogClosure(string f=__FILE__, int l=__LINE__, string m=__MODULE__, string foo=__FUNCTION__,  string prettyFoo=__PRETTY_FUNCTION__) {
541             void Emit(Level level, T...)(){
542                 //todo figureOutEventAggregate was here
543                 StaticSink.consume!(event(level, txt!T, CodeLocation(f, l, m, "", foo, prettyFoo)))();
544             }
545         }
546         
547         static auto Log(string f=__FILE__, int l=__LINE__, string m=__MODULE__, string foo=__FUNCTION__,  string prettyFoo=__PRETTY_FUNCTION__)(){
548             return LogClosure!(f, l, m, foo, prettyFoo)();
549         }
550         
551         //todo private
552         mixin template StaticLevelMixin(string method, string member){
553             mixin("struct "~method~"Closure(string f=__FILE__, int l=__LINE__, string m=__MODULE__, string foo=__FUNCTION__,  string prettyFoo=__PRETTY_FUNCTION__) {
554                 void Emit(T...)(){
555                     Log!(f, l, m, foo, prettyFoo).Emit!(Level."~member~", T);
556                 }
557             }");
558             mixin("@property static auto "~method~"(string f=__FILE__, int l=__LINE__, string m=__MODULE__, string foo=__FUNCTION__,  string prettyFoo=__PRETTY_FUNCTION__)(){
559             return "~method~"Closure!(f, l, m, foo, prettyFoo)();
560         }");
561         }
562        
563         
564         struct logClosure(string f=__FILE__, int l=__LINE__, string m=__MODULE__, string foo=__FUNCTION__,  string prettyFoo=__PRETTY_FUNCTION__) {
565             LogSink logSink;
566         
567             void emit(T...)(Level level, T t){
568                 import std.conv;
569                 //fixme figureOutEventAggregate was here
570                 auto e = event(level, text!(T)(t), CodeLocation(f, l, m, "", foo, prettyFoo));
571                 logSink.consume(e);
572             }
573         }
574         
575         @property
576         auto log(string f=__FILE__, int l=__LINE__, string m=__MODULE__, string foo=__FUNCTION__,  string prettyFoo=__PRETTY_FUNCTION__)(){
577             return logClosure!(f, l, m, foo, prettyFoo)(logSink);
578         }
579         
580         //todo private
581         mixin template RuntimeLevelMixin(string method, string member){
582             mixin("struct "~method~"Closure(string f=__FILE__, int l=__LINE__, string m=__MODULE__, string foo=__FUNCTION__,  string prettyFoo=__PRETTY_FUNCTION__) {
583                 Logger logger;
584             
585                 void emit(T...)(T t){
586                     logger.log!(f, l, m, foo, prettyFoo)().emit(Level."~member~", t);
587                 }
588             }");
589             mixin("@property 
590         auto "~method~"(string f=__FILE__, int l=__LINE__, string m=__MODULE__, string foo=__FUNCTION__,  string prettyFoo=__PRETTY_FUNCTION__)(){
591             return "~method~"Closure!(f, l, m, foo, prettyFoo)(this);
592         }");
593         }
594         
595         mixin template LevelMixin(string staticMethod, string runtimeMethod, string member){
596             mixin StaticLevelMixin!(staticMethod, member);
597             mixin RuntimeLevelMixin!(runtimeMethod, member);
598         }
599         
600         
601         private struct Triple { string s, r, m; }
602         
603         static foreach (t; [
604                 Triple("Error", "error", "ERROR"),
605                 Triple("Warn", "warn", "WARN"),
606                 Triple("Info", "info", "INFO"),
607                 Triple("Debug", "debug_", "DEBUG"),
608                 Triple("Trace", "trace", "TRACE"),
609                 Triple("Dev", "dev", "DEVELOPMENT")
610             ]){
611             mixin LevelMixin!(t.s, t.r, t.m);
612         }
613     
614         static string txt(T...)(){
615             string asString(X...)(){
616                 static if (is(X)){
617                     return fullyQualifiedName!X;
618                 } else static if (is(typeof(X))){
619                     return to!string(X);
620                 } else {
621                     static assert(false); //no support yet
622                 }
623             }
624             string fold(int i, string acc)(){
625                 static if (i<T.length){
626                     return fold!(i+1, acc~asString!(T[i]))();
627                 } else {
628                     return acc;
629                 }
630             }
631             return fold!(0, "")();
632         }
633         
634         static string numberLines(string s, int l){
635             import std..string: splitLines, leftJustify;
636             import std.conv: to;
637             
638             string[] lines = s.splitLines();
639             string result; 
640             foreach (i, line; lines){
641                 result ~= to!string(l+i).leftJustify(4, ' ')~" |"~line~"\n"; //padding
642             }
643             return result;
644         }
645         
646         static string indentLines(string s, string onLeft="\t"){
647             import std..string: splitLines, leftJustify;
648             import std.conv: to;
649             
650             string[] lines = s.splitLines();
651             string result; 
652             foreach (i, line; lines){
653                 result ~= onLeft~line~"\n";
654             }
655             return result;
656         }
657         
658         struct LoggedClosure(string f=__FILE__, int l=__LINE__, string m=__MODULE__, string foo=__FUNCTION__,  string prettyFoo=__PRETTY_FUNCTION__) {
659             //todo prefix/suffix should be customizable when obtaining this closure
660             string value(string s)(){
661                 Debug!(f, l, m, foo, prettyFoo).Emit!("mixing in:\n"~indentLines(numberLines(s, l))~"--- END OF MIXIN ---")();
662                 return s;
663             }
664         }
665         
666         @property
667         static auto logged(string f=__FILE__, int l=__LINE__, string m=__MODULE__, string foo=__FUNCTION__,  string prettyFoo=__PRETTY_FUNCTION__)(){
668             return LoggedClosure!(f, l, m, foo, prettyFoo)();
669         }
670     }
671 }
672