1 /*
2  * The Doomsday Engine Project -- libcore
3  *
4  * Copyright © 2004-2017 Jaakko Keränen <jaakko.keranen@iki.fi>
5  *
6  * @par License
7  * LGPL: http://www.gnu.org/licenses/lgpl.html
8  *
9  * <small>This program is free software; you can redistribute it and/or modify
10  * it under the terms of the GNU Lesser General Public License as published by
11  * the Free Software Foundation; either version 3 of the License, or (at your
12  * option) any later version. This program is distributed in the hope that it
13  * will be useful, but WITHOUT ANY WARRANTY; without even the implied warranty
14  * of MERCHANTABILITY or FITNESS FOR A PARTICULAR PURPOSE. See the GNU Lesser
15  * General Public License for more details. You should have received a copy of
16  * the GNU Lesser General Public License along with this program; if not, see:
17  * http://www.gnu.org/licenses</small>
18  */
19 
20 #include "de/Log"
21 #include "de/Time"
22 #include "de/Date"
23 #include "de/LogBuffer"
24 #include "de/Guard"
25 #include "de/Reader"
26 #include "de/Writer"
27 #include "de/FIFO"
28 #include "../src/core/logtextstyle.h"
29 
30 #include <QMap>
31 #include <QTextStream>
32 #include <QThread>
33 #include <QThreadStorage>
34 #include <QStringList>
35 #include <array>
36 
37 namespace de {
38 
39 char const *TEXT_STYLE_NORMAL        = DENG2_ESC("0"); // normal
40 char const *TEXT_STYLE_MESSAGE       = DENG2_ESC("0"); // normal
41 char const *TEXT_STYLE_MAJOR_MESSAGE = DENG2_ESC("1"); // major
42 char const *TEXT_STYLE_MINOR_MESSAGE = DENG2_ESC("2"); // minor
43 char const *TEXT_STYLE_SECTION       = DENG2_ESC("3"); // meta
44 char const *TEXT_STYLE_MAJOR_SECTION = DENG2_ESC("4"); // major meta
45 char const *TEXT_STYLE_MINOR_SECTION = DENG2_ESC("5"); // minor meta
46 char const *TEXT_STYLE_LOG_TIME      = DENG2_ESC("6"); // aux meta
47 char const *TEXT_MARK_INDENT         = DENG2_ESC(">");
48 
49 char const *MAIN_SECTION = "";
50 
51 /// If the section is longer than this, it will be alone on one line while
52 /// the rest of the entry continues after a break.
53 static int const LINE_BREAKING_SECTION_LENGTH = 30;
54 
55 namespace internal {
56 
57 #if 0
58 /**
59  * @internal
60  * The logs table is lockable so that multiple threads can access their logs at
61  * the same time.
62  */
63 class Logs : public Lockable, public QHash<QThread *, Log *>
64 {
65 public:
66     Logs() {}
67     ~Logs() {
68         DENG2_GUARD_PTR(this);
69         // The logs are owned by the logs table.
70         for (Log *log : *this) delete log;
71     }
72 };
73 #endif
74 
75 } // namespace internal
76 
77 /// The logs table contains the log of each thread that uses logging.
78 //static std::unique_ptr<internal::Logs> logsPtr;
79 
80 /// Unused entry arguments are stored here in the pool.
81 static FIFO<LogEntry::Arg> argPool;
82 
Arg()83 LogEntry::Arg::Arg() : _type(IntegerArgument)
84 {
85     _data.intValue = 0;
86 }
87 
~Arg()88 LogEntry::Arg::~Arg()
89 {
90     clear();
91 }
92 
clear()93 void LogEntry::Arg::clear()
94 {
95     if (_type == StringArgument)
96     {
97         delete _data.stringValue;
98         _data.stringValue = 0;
99         _type = IntegerArgument;
100     }
101 }
102 
setValue(dint i)103 void LogEntry::Arg::setValue(dint i)
104 {
105     clear();
106     _type = IntegerArgument;
107     _data.intValue = i;
108 }
109 
setValue(duint i)110 void LogEntry::Arg::setValue(duint i)
111 {
112     clear();
113     _type = IntegerArgument;
114     _data.intValue = i;
115 }
116 
setValue(long int i)117 void LogEntry::Arg::setValue(long int i)
118 {
119     clear();
120     _type = IntegerArgument;
121     _data.intValue = i;
122 }
123 
setValue(long unsigned int i)124 void LogEntry::Arg::setValue(long unsigned int i)
125 {
126     clear();
127     _type = IntegerArgument;
128     _data.intValue = i;
129 }
130 
setValue(duint64 i)131 void LogEntry::Arg::setValue(duint64 i)
132 {
133     clear();
134     _type = IntegerArgument;
135     _data.intValue = dint64(i);
136 }
137 
setValue(dint64 i)138 void LogEntry::Arg::setValue(dint64 i)
139 {
140     clear();
141     _type = IntegerArgument;
142     _data.intValue = i;
143 }
144 
setValue(ddouble d)145 void LogEntry::Arg::setValue(ddouble d)
146 {
147     clear();
148     _type = FloatingPointArgument;
149     _data.floatValue = d;
150 }
151 
setValue(void const * p)152 void LogEntry::Arg::setValue(void const *p)
153 {
154     clear();
155     _type = IntegerArgument;
156     _data.intValue = dint64(p);
157 }
158 
setValue(char const * s)159 void LogEntry::Arg::setValue(char const *s)
160 {
161     clear();
162     _type = StringArgument;
163     _data.stringValue = new String(s);
164 }
165 
setValue(String const & s)166 void LogEntry::Arg::setValue(String const &s)
167 {
168     clear();
169     _type = StringArgument;
170     // Ensure a deep copy of the string is taken.
171     _data.stringValue = new String(s.data(), s.size());
172 }
173 
setValue(std::array<char,4> const & typecode)174 void LogEntry::Arg::setValue(std::array<char, 4> const &typecode)
175 {
176     setValue(QString::fromLatin1(typecode.data(), 4));
177 }
178 
setValue(LogEntry::Arg::Base const & arg)179 void LogEntry::Arg::setValue(LogEntry::Arg::Base const &arg)
180 {
181     switch (arg.logEntryArgType())
182     {
183     case IntegerArgument:
184         setValue(arg.asInt64());
185         break;
186 
187     case FloatingPointArgument:
188         setValue(arg.asDouble());
189         break;
190 
191     case StringArgument:
192         setValue(arg.asText()); // deep copy
193         break;
194     }
195 }
196 
operator =(Arg const & other)197 LogEntry::Arg &LogEntry::Arg::operator = (Arg const &other)
198 {
199     clear();
200     if (other._type == StringArgument)
201     {
202         setValue(*other._data.stringValue); // deep copy
203     }
204     else
205     {
206         _type = other._type;
207         _data = other._data;
208     }
209     return *this;
210 }
211 
asNumber() const212 ddouble LogEntry::Arg::asNumber() const
213 {
214     if (_type == IntegerArgument)
215     {
216         return ddouble(_data.intValue);
217     }
218     else if (_type == FloatingPointArgument)
219     {
220         return _data.floatValue;
221     }
222     throw TypeError("Log::Arg::asNumber", "String argument cannot be used as a number");
223 }
224 
asText() const225 String LogEntry::Arg::asText() const
226 {
227     if (_type == StringArgument)
228     {
229         return *_data.stringValue;
230     }
231     else if (_type == IntegerArgument)
232     {
233         return String::number(_data.intValue);
234     }
235     else if (_type == FloatingPointArgument)
236     {
237         return String::number(_data.floatValue);
238     }
239     throw TypeError("Log::Arg::asText", "Number argument cannot be used a string");
240 }
241 
operator >>(Writer & to) const242 void LogEntry::Arg::operator >> (Writer &to) const
243 {
244     to << dbyte(_type);
245 
246     switch (_type)
247     {
248     case IntegerArgument:
249         to << _data.intValue;
250         break;
251 
252     case FloatingPointArgument:
253         to << _data.floatValue;
254         break;
255 
256     case StringArgument:
257         to << *_data.stringValue;
258         break;
259     }
260 }
261 
operator <<(Reader & from)262 void LogEntry::Arg::operator << (Reader &from)
263 {
264     if (_type == StringArgument) delete _data.stringValue;
265 
266     from.readAs<dbyte>(_type);
267 
268     switch (_type)
269     {
270     case IntegerArgument:
271         from >> _data.intValue;
272         break;
273 
274     case FloatingPointArgument:
275         from >> _data.floatValue;
276         break;
277 
278     case StringArgument:
279         _data.stringValue = new String;
280         from >> *_data.stringValue;
281         break;
282     }
283 }
284 
newFromPool()285 LogEntry::Arg *LogEntry::Arg::newFromPool()
286 {
287     Arg *arg = argPool.take();
288     if (arg) return arg;
289     // Need a new one.
290     return new LogEntry::Arg;
291 }
292 
returnToPool(Arg * arg)293 void LogEntry::Arg::returnToPool(Arg *arg)
294 {
295     arg->clear();
296     argPool.put(arg);
297 }
298 
LogEntry()299 LogEntry::LogEntry() : _metadata(0), _sectionDepth(0), _disabled(true)
300 {}
301 
LogEntry(duint32 metadata,String const & section,int sectionDepth,String const & format,Args args)302 LogEntry::LogEntry(duint32 metadata, String const &section, int sectionDepth, String const &format, Args args)
303     : _metadata(metadata)
304     , _section(section)
305     , _sectionDepth(sectionDepth)
306     , _format(format)
307     , _disabled(false)
308     , _args(args)
309 {
310     if (!LogBuffer::get().isEnabled(metadata))
311     {
312         _disabled = true;
313     }
314 }
315 
LogEntry(LogEntry const & other,Flags extraFlags)316 LogEntry::LogEntry(LogEntry const &other, Flags extraFlags)
317     : Lockable()
318     , ISerializable()
319     , _when(other._when)
320     , _metadata(other._metadata)
321     , _section(other._section)
322     , _sectionDepth(other._sectionDepth)
323     , _format(other._format)
324     , _defaultFlags(other._defaultFlags | extraFlags)
325     , _disabled(other._disabled)
326 {
327     DENG2_FOR_EACH_CONST(Args, i, other._args)
328     {
329         Arg *a = Arg::newFromPool();
330         *a = **i;
331         _args.append(a);
332     }
333 }
334 
~LogEntry()335 LogEntry::~LogEntry()
336 {
337     DENG2_GUARD(this);
338 
339     // Put the arguments back to the shared pool.
340     for (Args::iterator i = _args.begin(); i != _args.end(); ++i)
341     {
342         Arg::returnToPool(*i);
343     }
344 }
345 
flags() const346 LogEntry::Flags LogEntry::flags() const
347 {
348     return _defaultFlags;
349 }
350 
asText(Flags const & formattingFlags,int shortenSection) const351 String LogEntry::asText(Flags const &formattingFlags, int shortenSection) const
352 {
353     DENG2_GUARD(this);
354 
355     /// @todo This functionality belongs in an entry formatter class.
356 
357     Flags flags = formattingFlags;
358     QString result;
359     QTextStream output(&result);
360 
361     if (_defaultFlags & Simple)
362     {
363         flags |= Simple;
364     }
365 
366     // In simple mode, skip the metadata.
367     if (!flags.testFlag(Simple))
368     {
369         // Begin with the timestamp.
370         if (flags.testFlag(Styled)) output << TEXT_STYLE_LOG_TIME;
371 
372         output << _when.asText(Date::SecondsSinceStart) << " ";
373 
374         if (!flags.testFlag(OmitDomain))
375         {
376             QChar dc = (_metadata & Resource? 'R' :
377                         _metadata & Map?      'M' :
378                         _metadata & Script?   'S' :
379                         _metadata & GL?       'G' :
380                         _metadata & Audio?    'A' :
381                         _metadata & Input?    'I' :
382                         _metadata & Network?  'N' : ' ');
383             if (_metadata & Dev)
384             {
385                 if (dc != ' ')
386                     dc = dc.toLower();
387                 else
388                     dc = '-'; // Generic developer message
389             }
390 
391             if (!flags.testFlag(Styled))
392             {
393                 output << dc;
394             }
395             else
396             {
397                 output << _E(s)_E(F)_E(m) << dc << _E(.) << " ";
398             }
399         }
400 
401         if (!flags.testFlag(OmitLevel))
402         {
403             if (!flags.testFlag(Styled))
404             {
405                 char const *levelNames[] = {
406                     "", // not used
407                     "(vv)",
408                     "(v)",
409                     "",
410                     "(i)",
411                     "(WRN)",
412                     "(ERR)",
413                     "(!!!)"
414                 };
415                 output << qSetPadChar(' ') << qSetFieldWidth(5)
416                        << levelNames[level()] << qSetFieldWidth(0) << " ";
417             }
418             else
419             {
420                 char const *levelNames[] = {
421                     "", // not used
422                     "XVerbose",
423                     "Verbose",
424                     "",
425                     "Note!",
426                     "Warning",
427                     "ERROR",
428                     "FATAL!"
429                 };
430                 output << "\t"
431                     << (level() >= LogEntry::Warning? TEXT_STYLE_MAJOR_SECTION :
432                         level() <= LogEntry::Verbose? TEXT_STYLE_MINOR_SECTION :
433                                                       TEXT_STYLE_SECTION)
434                     << levelNames[level()] << "\t";
435             }
436         }
437     }
438 
439     // Section name.
440     if (!flags.testFlag(OmitSection) && !_section.empty())
441     {
442         if (flags.testFlag(Styled))
443         {
444             output << TEXT_MARK_INDENT
445                    << (level() >= LogEntry::Warning? TEXT_STYLE_MAJOR_SECTION :
446                        level() <= LogEntry::Verbose? TEXT_STYLE_MINOR_SECTION :
447                                                      TEXT_STYLE_SECTION);
448         }
449 
450         // Process the section: shortening and possible abbreviation.
451         QString sect;
452         if (flags.testFlag(AbbreviateSection))
453         {
454             /*
455              * We'll split the section into parts, and then abbreviate some of
456              * the parts, trying not to lose too much information.
457              * @a shortenSection controls how much of the section can be
458              * abbreviated (num of chars from beginning).
459              */
460             QStringList parts = _section.split(" > ");
461             int len = 0;
462             while (!parts.isEmpty())
463             {
464                 if (!sect.isEmpty())
465                 {
466                     len += 3;
467                     sect += " > ";
468                 }
469 
470                 if (len + parts.first().size() >= shortenSection) break;
471 
472                 len += parts.first().size();
473                 if (sect.isEmpty())
474                 {
475                     // Never abbreviate the first part.
476                     sect += parts.first();
477                 }
478                 else
479                 {
480                     sect += "..";
481                 }
482                 parts.removeFirst();
483             }
484             // Append the remainer as-is.
485             sect += _section.mid(len);
486         }
487         else
488         {
489             if (shortenSection < _section.size())
490             {
491                 sect = _section.right(_section.size() - shortenSection);
492             }
493         }
494 
495         if (flags.testFlag(SectionSameAsBefore))
496         {
497             int visibleSectLen = (!sect.isEmpty() && shortenSection? sect.size() : 0);
498             int fillLen = de::max(shortenSection, _section.size()) - visibleSectLen;
499             if (fillLen > LINE_BREAKING_SECTION_LENGTH) fillLen = 2;
500             output << String(fillLen, QChar(' '));
501             if (visibleSectLen)
502             {
503                 output << "[" << sect << "] ";
504             }
505             else
506             {
507                 output << "   ";
508             }
509         }
510         else
511         {
512             // If the section is very long, it's clearer to break the line here.
513             char const *separator = (sect.size() > LINE_BREAKING_SECTION_LENGTH? "\n    " : " ");
514             output << "[" << sect << "]" << separator;
515         }
516     }
517 
518     if (flags.testFlag(Styled))
519     {
520         output << TEXT_MARK_INDENT
521                << (level() >= LogEntry::Warning? TEXT_STYLE_MAJOR_MESSAGE :
522                    level() <= LogEntry::Verbose? TEXT_STYLE_MINOR_MESSAGE :
523                                                  TEXT_STYLE_MESSAGE);
524     }
525 
526     // Message text with the arguments formatted.
527     if (_args.empty())
528     {
529         output << _format; // Verbatim.
530     }
531     else
532     {
533         String::PatternArgs patArgs;
534         DENG2_FOR_EACH_CONST(Args, i, _args) patArgs << *i;
535         output << _format % patArgs;
536     }
537 
538     return result;
539 }
540 
operator >>(Writer & to) const541 void LogEntry::operator >> (Writer &to) const
542 {
543     to << _when
544        << _section
545        << _format
546        << duint32(_metadata)
547        << dbyte(_sectionDepth)
548        << duint32(_defaultFlags);
549 
550     to.writeObjects(_args);
551 }
552 
operator <<(Reader & from)553 void LogEntry::operator << (Reader &from)
554 {
555     foreach (Arg *a, _args) delete a;
556     _args.clear();
557 
558     from >> _when
559          >> _section
560          >> _format;
561 
562     if (from.version() >= DENG2_PROTOCOL_1_14_0_LogEntry_metadata)
563     {
564         // This version adds context information to the entry.
565         from.readAs<duint32>(_metadata);
566     }
567     else
568     {
569         dbyte oldLevel;
570         from >> oldLevel;
571         _metadata = oldLevel; // lacks audience information
572     }
573 
574     from.readAs<dbyte>(_sectionDepth)
575         .readAs<duint32>(_defaultFlags)
576         .readObjects<Arg>(_args);
577 }
578 
operator <<(QTextStream & stream,LogEntry::Arg const & arg)579 QTextStream &operator << (QTextStream &stream, LogEntry::Arg const &arg)
580 {
581     switch (arg.type())
582     {
583     case LogEntry::Arg::IntegerArgument:
584         stream << arg.intValue();
585         break;
586 
587     case LogEntry::Arg::FloatingPointArgument:
588         stream << arg.floatValue();
589         break;
590 
591     case LogEntry::Arg::StringArgument:
592         stream << arg.stringValue();
593         break;
594     }
595     return stream;
596 }
597 
Section(char const * name)598 Log::Section::Section(char const *name) : _log(threadLog()), _name(name)
599 {
600     _log.beginSection(_name);
601 }
602 
~Section()603 Log::Section::~Section()
604 {
605     _log.endSection(_name);
606 }
607 
DENG2_PIMPL_NOREF(Log)608 DENG2_PIMPL_NOREF(Log)
609 {
610     typedef QVector<char const *> SectionStack;
611     SectionStack sectionStack;
612     LogEntry *throwawayEntry;
613     duint32 currentEntryMedata; ///< Applies to the current entry being staged in the thread.
614     int interactive = 0;
615 
616     Impl()
617         : throwawayEntry(new LogEntry) ///< A disabled LogEntry, so doesn't accept arguments.
618         , currentEntryMedata(0)
619     {
620         sectionStack.push_back(MAIN_SECTION);
621     }
622 
623     ~Impl()
624     {
625         delete throwawayEntry;
626     }
627 };
628 
Log()629 Log::Log() : d(new Impl)
630 {}
631 
~Log()632 Log::~Log() // virtual
633 {}
634 
setCurrentEntryMetadata(duint32 metadata)635 void Log::setCurrentEntryMetadata(duint32 metadata)
636 {
637     d->currentEntryMedata = metadata;
638 }
639 
currentEntryMetadata() const640 duint32 Log::currentEntryMetadata() const
641 {
642     return d->currentEntryMedata;
643 }
644 
isStaging() const645 bool Log::isStaging() const
646 {
647     return d->currentEntryMedata != 0;
648 }
649 
beginSection(char const * name)650 void Log::beginSection(char const *name)
651 {
652     d->sectionStack.push_back(name);
653 }
654 
endSection(char const * DENG2_DEBUG_ONLY (name))655 void Log::endSection(char const *DENG2_DEBUG_ONLY(name))
656 {
657     DENG2_ASSERT(d->sectionStack.back() == name);
658     d->sectionStack.pop_back();
659 }
660 
beginInteractive()661 void Log::beginInteractive()
662 {
663     d->interactive++;
664 }
665 
endInteractive()666 void Log::endInteractive()
667 {
668     d->interactive--;
669     DENG2_ASSERT(d->interactive >= 0);
670 }
671 
isInteractive() const672 bool Log::isInteractive() const
673 {
674     return d->interactive > 0;
675 }
676 
enter(String const & format,LogEntry::Args arguments)677 LogEntry &Log::enter(String const &format, LogEntry::Args arguments)
678 {
679     return enter(LogEntry::Message, format, arguments);
680 }
681 
enter(duint32 metadata,String const & format,LogEntry::Args arguments)682 LogEntry &Log::enter(duint32 metadata, String const &format, LogEntry::Args arguments)
683 {
684     // Staging done.
685     d->currentEntryMedata = 0;
686 
687     if (isInteractive())
688     {
689         // Ensure the Interactive flag is set.
690         metadata |= LogEntry::Interactive;
691     }
692 
693     if (!LogBuffer::get().isEnabled(metadata))
694     {
695         DENG2_ASSERT(arguments.isEmpty());
696 
697         // If the level is disabled, no messages are entered into it.
698         return *d->throwawayEntry;
699     }
700 
701     // Collect the sections.
702     String context;
703     String latest;
704     int depth = 0;
705     foreach (char const *i, d->sectionStack)
706     {
707         if (i == latest)
708         {
709             // Don't repeat if it has the exact same name (due to recursive calls).
710             continue;
711         }
712         if (context.size())
713         {
714             context += " > ";
715         }
716         latest = i;
717         context += i;
718         ++depth;
719     }
720 
721     // Make a new entry.
722     LogEntry *entry = new LogEntry(metadata, context, depth, format, arguments);
723 
724     // Add it to the application's buffer. The buffer gets ownership.
725     LogBuffer::get().add(entry);
726 
727     return *entry;
728 }
729 
730 /*static internal::Logs &theLogs()
731 {
732     if (logsPtr.get()) return *logsPtr;
733     static Lockable lock;
734     DENG2_GUARD(lock);
735     if (!logsPtr.get()) logsPtr.reset(new internal::Logs);
736     return *logsPtr;
737 }*/
738 
739 static QThreadStorage<Log> theLogs;
740 
threadLog()741 Log &Log::threadLog()
742 {
743     // Each thread has its own log.
744     //QThread *thread = QThread::currentThread();
745 
746     return theLogs.localData();
747 
748     /*if (!theLogs.hasLocalData())
749     {
750         theLogs.setLocalData(<#de::Log t#>)
751     internal::Logs &logs = theLogs();
752     DENG2_GUARD(logs);
753 
754     auto found = logs.constFind(thread);
755     if (found == logs.constEnd())
756     {
757         // Create a new log.
758         Log *theLog = new Log;
759         logs.insert(thread, theLog);
760         return *theLog;
761     }
762     else
763     {
764         return *found.value();
765     }*/
766 }
767 
disposeThreadLog()768 void Log::disposeThreadLog()
769 {
770     /*internal::Logs &logs = theLogs();
771     DENG2_GUARD(logs);
772 
773     QThread *thread = QThread::currentThread();
774     auto found = logs.find(thread);
775     if (found != logs.end())
776     {
777         delete found.value();
778         logs.erase(found);
779     }*/
780 }
781 
LogEntryStager(duint32 metadata,String const & format)782 LogEntryStager::LogEntryStager(duint32 metadata, String const &format)
783     : _metadata(metadata)
784 {
785     if (!LogBuffer::appBufferExists())
786     {
787         _disabled = true;
788     }
789     else
790     {
791         auto &log = LOG();
792 
793         // Automatically set the Generic domain.
794         if (!(_metadata & LogEntry::DomainMask))
795         {
796             _metadata |= LogEntry::Generic;
797         }
798 
799         // Flag interactive messages.
800         if (log.isInteractive())
801         {
802             _metadata |= LogEntry::Interactive;
803         }
804 
805         _disabled = !LogBuffer::get().isEnabled(_metadata);
806 
807         if (!_disabled)
808         {
809             _format = format;
810 
811             log.setCurrentEntryMetadata(_metadata);
812         }
813     }
814 }
815 
~LogEntryStager()816 LogEntryStager::~LogEntryStager()
817 {
818     if (!_disabled)
819     {
820         // Ownership of the args is transferred to the LogEntry.
821         LOG().enter(_metadata, _format, _args);
822     }
823 }
824 
825 } // namespace de
826