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 §ion, 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