The Battle for Wesnoth  1.17.10+dev
log.cpp
Go to the documentation of this file.
1 /*
2  Copyright (C) 2004 - 2022
3  by Guillaume Melquiond <guillaume.melquiond@gmail.com>
4  Copyright (C) 2003 by David White <dave@whitevine.net>
5  Part of the Battle for Wesnoth Project https://www.wesnoth.org/
6 
7  This program is free software; you can redistribute it and/or modify
8  it under the terms of the GNU General Public License as published by
9  the Free Software Foundation; either version 2 of the License, or
10  (at your option) any later version.
11  This program is distributed in the hope that it will be useful,
12  but WITHOUT ANY WARRANTY.
13 
14  See the COPYING file for more details.
15 */
16 
17 /**
18  * @file
19  * Standard logging facilities (implementation).
20  * See also the command line switches --logdomains and --log-@<level@>="domain".
21  */
22 
23 #include "log.hpp"
24 
25 #include "filesystem.hpp"
26 #include "mt_rng.hpp"
27 
28 #include <boost/algorithm/string.hpp>
29 
30 #include <map>
31 #include <sstream>
32 #include <ctime>
33 #include <mutex>
34 #include <iostream>
35 #include <iomanip>
36 
37 static lg::log_domain log_setup("logsetup");
38 #define ERR_LS LOG_STREAM(err, log_setup)
39 #define WRN_LS LOG_STREAM(warn, log_setup)
40 #define LOG_LS LOG_STREAM(info, log_setup)
41 #define DBG_LS LOG_STREAM(debug, log_setup)
42 
43 namespace {
44 
45 class null_streambuf : public std::streambuf
46 {
47  virtual int overflow(int c) { return std::char_traits< char >::not_eof(c); }
48 public:
49  null_streambuf() {}
50 };
51 
52 } // end anonymous namespace
53 
54 static std::ostream null_ostream(new null_streambuf);
55 static int indent = 0;
56 static bool timestamp = true;
57 static bool precise_timestamp = false;
58 static std::mutex log_mutex;
59 
60 static std::ostream *output_stream_ = nullptr;
61 
62 static std::ostream& output()
63 {
64  if(output_stream_) {
65  return *output_stream_;
66  }
67  return std::cerr;
68 }
69 
70 // custom deleter needed to reset cerr and cout
71 // otherwise wesnoth segfaults on closing (such as clicking the Quit button on the main menu)
72 // seems to be that there's a final flush done outside of wesnoth's code just before exiting
73 // but at that point the output_file_ has already been cleaned up
74 static std::unique_ptr<std::ostream, void(*)(std::ostream*)> output_file_(nullptr, [](std::ostream*){
75  std::cerr.rdbuf(nullptr);
76  std::cout.rdbuf(nullptr);
77 });
78 static std::string output_file_path_ = "";
79 
80 namespace lg {
81 
82 /** Helper function for rotate_logs. */
83 bool is_not_log_file(const std::string& fn)
84 {
85  return !(boost::algorithm::istarts_with(fn, lg::log_file_prefix) &&
86  boost::algorithm::iends_with(fn, lg::log_file_suffix));
87 }
88 
89 /**
90  * Deletes old log files from the log directory.
91  */
92 void rotate_logs(const std::string& log_dir)
93 {
94  std::vector<std::string> files;
95  filesystem::get_files_in_dir(log_dir, &files);
96 
97  files.erase(std::remove_if(files.begin(), files.end(), is_not_log_file), files.end());
98 
99  if(files.size() <= lg::max_logs) {
100  return;
101  }
102 
103  // Sorting the file list and deleting all but the last max_logs items
104  // should hopefully be faster than stat'ing every single file for its
105  // time attributes (which aren't very reliable to begin with).
106 
107  std::sort(files.begin(), files.end());
108 
109  for(std::size_t j = 0; j < files.size() - lg::max_logs; ++j) {
110  const std::string path = log_dir + '/' + files[j];
111  LOG_LS << "rotate_logs(): delete " << path;
112  if(!filesystem::delete_file(path)) {
113  ERR_LS << "rotate_logs(): failed to delete " << path << "!";
114  }
115  }
116 }
117 
118 /**
119  * Generates a unique log file name.
120  */
121 std::string unique_log_filename()
122 {
123  std::ostringstream o;
124  const std::time_t cur = std::time(nullptr);
125  randomness::mt_rng rng;
126 
128  << std::put_time(std::localtime(&cur), "%Y%m%d-%H%M%S-")
129  << rng.get_next_random()
131 
132  return o.str();
133 }
134 
136 {
137  // get the log file stream and assign cerr+cout to it
138  output_file_path_ = filesystem::get_logs_dir()+"/"+unique_log_filename();
139  output_file_.reset(filesystem::ostream_file(output_file_path_).release());
140  std::cerr.rdbuf(output_file_.get()->rdbuf());
141  std::cout.rdbuf(output_file_.get()->rdbuf());
142 }
143 
144 std::string& get_log_file_path()
145 {
146  return output_file_path_;
147 }
148 void set_log_file_path(const std::string& path)
149 {
150  output_file_path_ = path;
151 }
152 
153 redirect_output_setter::redirect_output_setter(std::ostream& stream)
154  : old_stream_(output_stream_)
155 {
156  output_stream_ = &stream;
157 }
158 
160 {
162 }
163 
164 typedef std::map<std::string, int> domain_map;
165 static domain_map *domains;
166 static int strict_level_ = -1;
167 void timestamps(bool t) { timestamp = t; }
168 void precise_timestamps(bool pt) { precise_timestamp = pt; }
169 
171 {
172  static logger lg("error", 0);
173  return lg;
174 }
175 
177 {
178  static logger lg("warning", 1);
179  return lg;
180 }
181 
183 {
184  static logger lg("info", 2);
185  return lg;
186 }
187 
189 {
190  static logger lg("debug", 3);
191  return lg;
192 }
193 
194 static log_domain dom("general");
195 
197 {
198  return dom;
199 }
200 
201 log_domain::log_domain(char const *name, int severity)
202  : domain_(nullptr)
203 {
204  // Indirection to prevent initialization depending on link order.
205  if (!domains) domains = new domain_map;
206  domain_ = &*domains->insert(logd(name, severity)).first;
207  domain_->second = severity;
208 }
209 
210 bool set_log_domain_severity(const std::string& name, int severity)
211 {
212  std::string::size_type s = name.size();
213  if (name == "all") {
214  for(logd &l : *domains) {
215  l.second = severity;
216  }
217  } else if (s > 2 && name.compare(s - 2, 2, "/*") == 0) {
218  for(logd &l : *domains) {
219  if (l.first.compare(0, s - 1, name, 0, s - 1) == 0)
220  l.second = severity;
221  }
222  } else {
223  domain_map::iterator it = domains->find(name);
224  if (it == domains->end())
225  return false;
226  it->second = severity;
227  }
228  return true;
229 }
230 bool set_log_domain_severity(const std::string& name, const logger &lg) {
231  return set_log_domain_severity(name, lg.get_severity());
232 }
233 
234 bool get_log_domain_severity(const std::string& name, int &severity)
235 {
236  domain_map::iterator it = domains->find(name);
237  if (it == domains->end())
238  return false;
239  severity = it->second;
240  return true;
241 }
242 
243 std::string list_logdomains(const std::string& filter)
244 {
245  std::ostringstream res;
246  for(logd &l : *domains) {
247  if(l.first.find(filter) != std::string::npos)
248  res << l.first << "\n";
249  }
250  return res.str();
251 }
252 
254  strict_level_ = severity;
255 }
256 
259 }
260 
261 static bool strict_threw_ = false;
262 
263 bool broke_strict() {
264  return strict_threw_;
265 }
266 
267 std::string get_timestamp(const std::time_t& t, const std::string& format) {
268  std::ostringstream ss;
269 
270  ss << std::put_time(std::localtime(&t), format.c_str());
271 
272  return ss.str();
273 }
274 std::string get_timespan(const std::time_t& t) {
275  std::ostringstream sout;
276  // There doesn't seem to be any library function for this
277  const std::time_t minutes = t / 60;
278  const std::time_t days = minutes / 60 / 24;
279  if(t <= 0) {
280  sout << "expired";
281  } else if(minutes == 0) {
282  sout << t << " seconds";
283  } else if(days == 0) {
284  sout << minutes / 60 << " hours, " << minutes % 60 << " minutes";
285  } else {
286  sout << days << " days, " << (minutes / 60) % 24 << " hours, " << minutes % 60 << " minutes";
287  }
288  return sout.str();
289 }
290 
291 static void print_precise_timestamp(std::ostream& out) noexcept
292 {
293  try {
294  int64_t micros = std::chrono::duration_cast<std::chrono::microseconds>(std::chrono::high_resolution_clock::now().time_since_epoch()).count();
295  std::time_t seconds = micros/1'000'000;
296  int fractional = micros-(seconds*1'000'000);
297  char c = out.fill('0');
298  out << std::put_time(std::localtime(&seconds), "%Y%m%d %H:%M:%S") << "." << std::setw(6) << fractional << ' ';
299  out.fill(c);
300  } catch(...) {}
301 }
302 
303 std::string sanitize_log(const std::string& logstr)
304 {
305  std::string str = logstr;
306 
307 #ifdef _WIN32
308  const char* user_name = getenv("USERNAME");
309 #else
310  const char* user_name = getenv("USER");
311 #endif
312 
313  if(user_name != nullptr) {
314  boost::replace_all(str, std::string("/") + user_name + "/", "/USER/");
315  boost::replace_all(str, std::string("\\") + user_name + "\\", "\\USER\\");
316  }
317 
318  return str;
319 }
320 
322  const log_domain& domain,
323  bool show_names,
324  bool do_indent,
325  bool show_timestamps,
326  bool break_strict,
327  bool auto_newline) const
328 {
329  if (severity_ > domain.domain_->second) {
330  return null_ostream;
331  } else {
332  log_in_progress stream = output();
333  if(do_indent) {
334  stream.set_indent(indent);
335  }
336  if (timestamp && show_timestamps) {
337  stream.enable_timestamp();
338  }
339  if (show_names) {
340  stream.set_prefix(formatter() << name_ << ' ' << domain.domain_->first << ": ");
341  }
342  if (!strict_threw_ && severity_ <= strict_level_ && break_strict) {
343  stream | formatter() << "Error (strict mode, strict_level = " << strict_level_ << "): wesnoth reported on channel " << name_ << " " << domain.domain_->first << std::endl;
344  strict_threw_ = true;
345  }
346  stream.set_auto_newline(auto_newline);
347  return stream;
348  }
349 }
350 
351 log_in_progress::log_in_progress(std::ostream& stream)
352  : stream_(stream)
353 {}
354 
356 {
357  std::scoped_lock lock(log_mutex);
358  for(int i = 0; i < indent; ++i)
359  stream_ << " ";
360  if(timestamp_) {
361  if(precise_timestamp) {
363  } else {
364  stream_ << get_timestamp(std::time(nullptr));
365  }
366  }
367  stream_ << prefix_ << sanitize_log(message.str());
368  if(auto_newline_) {
369  stream_ << std::endl;
370  }
371 }
372 
374  indent_ = level;
375 }
376 
378  timestamp_ = true;
379 }
380 
381 void log_in_progress::set_prefix(const std::string& prefix) {
382  prefix_ = prefix;
383 }
384 
385 void log_in_progress::set_auto_newline(bool auto_newline) {
386  auto_newline_ = auto_newline;
387 }
388 
389 void scope_logger::do_log_entry(const std::string& str) noexcept
390 {
391  str_ = str;
392  try {
393  ticks_ = std::chrono::duration_cast<std::chrono::microseconds>(std::chrono::high_resolution_clock::now().time_since_epoch()).count();
394  } catch(...) {}
395  debug()(domain_, false, true) | formatter() << "{ BEGIN: " << str_;
396  ++indent;
397 }
398 
400 {
401  long ticks = 0;
402  try {
403  ticks = std::chrono::duration_cast<std::chrono::microseconds>(std::chrono::high_resolution_clock::now().time_since_epoch()).count() - ticks_;
404  } catch(...) {}
405  --indent;
406  auto output = debug()(domain_, false, true);
407  output.set_indent(indent);
408  if(timestamp) output.enable_timestamp();
409  output | formatter() << "} END: " << str_ << " (took " << ticks << "us)";
410 }
411 
412 std::stringstream& log_to_chat()
413 {
414  static std::stringstream lg;
415  return lg;
416 }
417 
418 } // end namespace lg
static log_domain dom("general")
static int strict_level_
Definition: log.cpp:166
std::string get_timestamp(const std::time_t &t, const std::string &format)
Definition: log.cpp:267
static std::mutex log_mutex
Definition: log.cpp:58
static domain_map * domains
Definition: log.cpp:165
std::string get_timespan(const std::time_t &t)
Definition: log.cpp:274
bool delete_file(const std::string &filename)
void do_log_exit() noexcept
Definition: log.cpp:399
logger & info()
Definition: log.cpp:182
void timestamps(bool t)
Definition: log.cpp:167
static std::unique_ptr< std::ostream, void(*)(std::ostream *)> output_file_(nullptr, [](std::ostream *){ std::cerr.rdbuf(nullptr);std::cout.rdbuf(nullptr);})
Definition: log.cpp:74
uint32_t get_next_random()
Get a new random number.
Definition: mt_rng.cpp:63
std::string get_logs_dir()
Definition: filesystem.cpp:812
log_in_progress(std::ostream &stream)
Definition: log.cpp:351
static lg::log_domain log_setup("logsetup")
log_domain(char const *name, int severity=1)
Definition: log.cpp:201
const std::string log_file_suffix
Definition: log.hpp:67
filesystem::scoped_ostream ostream_file(const std::string &fname, std::ios_base::openmode mode, bool create_directory)
log_in_progress operator()(const log_domain &domain, bool show_names=true, bool do_indent=false, bool show_timestamps=true, bool break_strict=true, bool auto_newline=true) const
Definition: log.cpp:321
std::pair< const std::string, int > logd
Definition: log.hpp:110
bool is_not_log_file(const std::string &fn)
Helper function for rotate_logs.
Definition: log.cpp:83
bool broke_strict()
Definition: log.cpp:263
void set_auto_newline(bool enabled)
Definition: log.cpp:385
static std::ostream & output()
Definition: log.cpp:62
std::string & get_log_file_path()
Definition: log.cpp:144
bool get_log_domain_severity(const std::string &name, int &severity)
Definition: log.cpp:234
std::ostringstream wrapper.
Definition: formatter.hpp:39
#define ERR_LS
Definition: log.cpp:38
std::string sanitize_log(const std::string &logstr)
Definition: log.cpp:303
void get_files_in_dir(const std::string &dir, std::vector< std::string > *files, std::vector< std::string > *dirs, name_mode mode, filter_mode filter, reorder_mode reorder, file_tree_checksum *checksum)
Get a list of all files and/or directories in a given directory.
Definition: filesystem.cpp:350
#define LOG_LS
Definition: log.cpp:40
void rotate_logs(const std::string &log_dir)
Deletes old log files from the log directory.
Definition: log.cpp:92
static bool precise_timestamp
Definition: log.cpp:57
std::string path
Definition: game_config.cpp:39
logger & debug()
Definition: log.cpp:188
severity
Definition: log.hpp:73
static int indent
Definition: log.cpp:55
log_domain & general()
Definition: log.cpp:196
void do_log_entry(const std::string &str) noexcept
Definition: log.cpp:389
std::string unique_log_filename()
Generates a unique log file name.
Definition: log.cpp:121
std::map< std::string, int > domain_map
Definition: log.cpp:164
Definition: pump.hpp:40
std::ostream * old_stream_
The previously set redirection.
Definition: log.hpp:107
std::size_t i
Definition: function.cpp:967
logger & err()
Definition: log.cpp:170
static void print_precise_timestamp(std::ostream &out) noexcept
Definition: log.cpp:291
void set_strict_severity(int severity)
Definition: log.cpp:253
static map_location::DIRECTION s
const unsigned max_logs
Definition: log.hpp:71
static std::ostream * output_stream_
Definition: log.cpp:60
static std::string output_file_path_
Definition: log.cpp:78
Declarations for File-IO.
bool set_log_domain_severity(const std::string &name, int severity)
Definition: log.cpp:210
void operator|(formatter &&message)
Definition: log.cpp:355
static bool strict_threw_
Definition: log.cpp:261
logger & warn()
Definition: log.cpp:176
double t
Definition: astarsearch.cpp:65
void enable_timestamp()
Definition: log.cpp:377
static bool timestamp
Definition: log.cpp:56
std::string list_logdomains(const std::string &filter)
Definition: log.cpp:243
std::string prefix_
Definition: log.hpp:146
Standard logging facilities (interface).
static std::ostream null_ostream(new null_streambuf)
void set_prefix(const std::string &prefix)
Definition: log.cpp:381
void set_indent(int level)
Definition: log.cpp:373
bool auto_newline_
Definition: log.hpp:147
void set_log_to_file()
Definition: log.cpp:135
mock_char c
void set_log_file_path(const std::string &path)
Definition: log.cpp:148
int get_severity() const
Returns following values depending on the logger: error: 0 warn: 1 info: 2 debug: 3 See also the lg::...
Definition: log.hpp:178
std::ostream & stream_
Definition: log.hpp:143
std::string::const_iterator iterator
Definition: tokenizer.hpp:25
const std::string log_file_prefix
Definition: log.hpp:66
void precise_timestamps(bool pt)
Definition: log.cpp:168
logd * domain_
Definition: log.hpp:115
std::stringstream & log_to_chat()
Use this to show WML errors in the ingame chat.
Definition: log.cpp:412