The Battle for Wesnoth  1.19.5+dev
log.cpp
Go to the documentation of this file.
1 /*
2  Copyright (C) 2004 - 2024
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 #include "filesystem.hpp"
25 #include "mt_rng.hpp"
26 #include "utils/general.hpp"
27 
28 #include <boost/algorithm/string.hpp>
29 
30 #include <map>
31 #include <ctime>
32 #include <mutex>
33 #include <iostream>
34 #include <iomanip>
35 
36 #ifdef _WIN32
37 #include <io.h>
38 #endif
39 
40 static lg::log_domain log_setup("logsetup");
41 #define ERR_LS LOG_STREAM(err, log_setup)
42 #define WRN_LS LOG_STREAM(warn, log_setup)
43 #define LOG_LS LOG_STREAM(info, log_setup)
44 #define DBG_LS LOG_STREAM(debug, log_setup)
45 
46 namespace {
47 
48 class null_streambuf : public std::streambuf
49 {
50  virtual int overflow(int c) { return std::char_traits< char >::not_eof(c); }
51 public:
52  null_streambuf() {}
53 };
54 
55 } // end anonymous namespace
56 
57 static std::ostream null_ostream(new null_streambuf);
58 static int indent = 0;
59 static bool timestamp = true;
60 static bool precise_timestamp = false;
61 static std::mutex log_mutex;
62 
63 static bool log_sanitization = true;
64 
65 /** whether the current logs directory is writable */
66 static utils::optional<bool> is_log_dir_writable_ = utils::nullopt;
67 /** alternative stream to write data to */
68 static std::ostream *output_stream_ = nullptr;
69 
70 /**
71  * @return std::cerr if the redirect_output_setter isn't being used, output_stream_ if it is
72  */
73 static std::ostream& output()
74 {
75  if(output_stream_) {
76  return *output_stream_;
77  }
78  return std::cerr;
79 }
80 
81 /** path to the current log file; does not include the extension */
82 static std::string output_file_path_ = "";
83 /** path to the current logs directory; may change after being initially set if a custom userdata directory is given on the command line */
84 static std::string logs_dir_ = "";
85 
86 namespace lg {
87 
88 std::ostringstream& operator<<(std::ostringstream& oss, const lg::severity severity)
89 {
90  oss << static_cast<int>(severity);
91  return oss;
92 }
93 
94 bool is_not_log_file(const std::string& fn)
95 {
96  return !(boost::algorithm::istarts_with(fn, lg::log_file_prefix) &&
97  boost::algorithm::iends_with(fn, lg::log_file_suffix));
98 }
99 
100 void rotate_logs(const std::string& log_dir)
101 {
102  // if logging to file is disabled, don't rotate the logs
103  if(output_file_path_.empty()) {
104  return;
105  }
106 
107  std::vector<std::string> files;
108  filesystem::get_files_in_dir(log_dir, &files);
109 
111 
112  if(files.size() <= lg::max_logs) {
113  return;
114  }
115 
116  // Sorting the file list and deleting all but the last max_logs items
117  // should hopefully be faster than stat'ing every single file for its
118  // time attributes (which aren't very reliable to begin with).
119 
120  std::sort(files.begin(), files.end());
121 
122  for(std::size_t j = 0; j < files.size() - lg::max_logs; ++j) {
123  const std::string path = log_dir + '/' + files[j];
124  LOG_LS << "rotate_logs(): delete " << path;
126  ERR_LS << "rotate_logs(): failed to delete " << path << "!";
127  }
128  }
129 }
130 
131 std::string unique_log_filename()
132 {
133  std::ostringstream o;
134  const std::time_t cur = std::time(nullptr);
135  randomness::mt_rng rng;
136 
138  << std::put_time(std::localtime(&cur), "%Y%m%d-%H%M%S-")
139  << rng.get_next_random();
140 
141  return o.str();
142 }
143 
145 {
146  std::string dummy_log = filesystem::get_logs_dir()+"/dummy.log";
147 
148  // log directory doesn't exist and can't be created
150  is_log_dir_writable_ = false;
151  return;
152  }
153 
154  // can't create and write new log files
155  try {
156  filesystem::write_file(dummy_log, " ");
157  } catch(const filesystem::io_exception&) {
158  is_log_dir_writable_ = false;
159  return;
160  }
161 
162  // confirm that file exists and was written to
163  if(filesystem::file_size(dummy_log) != 1) {
164  is_log_dir_writable_ = false;
165  }
166 
167  // can't delete files - prevents log rotation
168  if(filesystem::file_exists(dummy_log) && !filesystem::delete_file(dummy_log)) {
169  is_log_dir_writable_ = false;
170  return;
171  }
172 
173  is_log_dir_writable_ = true;
174 }
175 
177 {
178  if(logs_dir_ == filesystem::get_logs_dir() || logs_dir_ == "") {
179  return;
180  }
181 
183 
184  if(is_log_dir_writable_.value_or(false)) {
185 #ifdef _WIN32
186  std::string old_path = output_file_path_;
188 
189  // flush and close existing log files, since Windows doesn't allow moving open files
190  std::fflush(stderr);
191  std::cerr.flush();
192  if(!std::freopen("NUL", "a", stderr)) {
193  std::cerr << "Failed to close stderr log file: '" << old_path << "'";
194  // stderr is where basically all output goes through, so if that fails then don't attempt anything else
195  // moving just the stdout log would be pointless
196  return;
197  }
198  std::fflush(stdout);
199  std::cout.flush();
200  if(!std::freopen("NUL", "a", stdout)) {
201  std::cerr << "Failed to close stdout log file: '" << old_path << "'";
202  }
203 
204  // move the .log and .out.log files
205  // stdout and stderr are set to NUL currently so nowhere to send info on failure
206  if(rename((old_path+lg::log_file_suffix).c_str(), (output_file_path_+lg::log_file_suffix).c_str()) == -1) {
207  return;
208  }
209  rename((old_path+lg::out_log_file_suffix).c_str(), (output_file_path_+lg::out_log_file_suffix).c_str());
210 
211  // reopen to log files at new location
212  // stdout and stderr are still NUL if freopen fails, so again nowhere to send info on failure
213  std::fflush(stderr);
214  std::cerr.flush();
215  std::freopen((output_file_path_+lg::log_file_suffix).c_str(), "a", stderr);
216 
217  std::fflush(stdout);
218  std::cout.flush();
219  std::freopen((output_file_path_+lg::out_log_file_suffix).c_str(), "a", stdout);
220 #else
221  std::string old_path = get_log_file_path();
223 
224  // non-Windows can just move the file
225  if(rename(old_path.c_str(), get_log_file_path().c_str()) == -1) {
226  std::cerr << "Failed to rename log file from '" << old_path << "' to '" << output_file_path_ << "'";
227  }
228 #endif
229  }
230 }
231 
233 {
235  // if the log directory is not writable, then don't try to do anything.
236  // if the log directory is writable, then setup logging and rotate the logs.
237  // if the optional isn't set, then logging to file has been disabled, so don't try to do anything
238  if(is_log_dir_writable_.value_or(false)) {
239  // get the log file stream and assign cerr+cout to it
242 
243  // IMPORTANT: apparently redirecting stderr/stdout will also redirect std::cerr/std::cout, but the reverse is not true
244  // redirecting std::cerr/std::cout will *not* redirect stderr/stdout
245 
246  // redirect stderr to file
247  std::fflush(stderr);
248  std::cerr.flush();
249  if(!std::freopen((output_file_path_+lg::log_file_suffix).c_str(), "w", stderr)) {
250  std::cerr << "Failed to redirect stderr to a file!";
251  }
252 
253  // redirect stdout to file
254  // separate handling for Windows since dup2() just... doesn't work for GUI apps there apparently
255  // redirect to a separate file on Windows as well, since otherwise two streams independently writing to the same file can cause weirdness
256 #ifdef _WIN32
257  std::fflush(stdout);
258  std::cout.flush();
259  if(!std::freopen((output_file_path_+lg::out_log_file_suffix).c_str(), "w", stdout)) {
260  std::cerr << "Failed to redirect stdout to a file!";
261  }
262 #else
263  if(dup2(STDERR_FILENO, STDOUT_FILENO) == -1) {
264  std::cerr << "Failed to redirect stdout to a file!";
265  }
266 #endif
267 
268  // make stdout unbuffered - otherwise some output might be lost
269  // in practice shouldn't make much difference either way, given how little output goes through stdout/std::cout
270  if(setvbuf(stdout, NULL, _IONBF, 2) == -1) {
271  std::cerr << "Failed to set stdout to be unbuffered";
272  }
273 
275  }
276 }
277 
278 utils::optional<bool> log_dir_writable()
279 {
280  return is_log_dir_writable_;
281 }
282 
283 std::string get_log_file_path()
284 {
286 }
287 
289  : old_stream_(output_stream_)
290 {
291  output_stream_ = &stream;
292 }
293 
295 {
297 }
298 
299 typedef std::map<std::string, severity> domain_map;
302 void timestamps(bool t) { timestamp = t; }
303 void precise_timestamps(bool pt) { precise_timestamp = pt; }
304 
306 {
307  static logger lg("error", severity::LG_ERROR);
308  return lg;
309 }
310 
312 {
313  static logger lg("warning", severity::LG_WARN);
314  return lg;
315 }
316 
318 {
319  static logger lg("info", severity::LG_INFO);
320  return lg;
321 }
322 
324 {
325  static logger lg("debug", severity::LG_DEBUG);
326  return lg;
327 }
328 
329 static log_domain dom("general");
330 
332 {
333  return dom;
334 }
335 
337  : domain_(nullptr)
338 {
339  // Indirection to prevent initialization depending on link order.
340  if (!domains) domains = new domain_map;
341  domain_ = &*domains->insert(logd(name, severity)).first;
342  domain_->second = severity;
343 }
344 
345 bool set_log_domain_severity(const std::string& name, severity severity)
346 {
347  std::string::size_type s = name.size();
348  if (name == "all") {
349  for(logd &l : *domains) {
350  l.second = severity;
351  }
352  } else if (s > 2 && name.compare(s - 2, 2, "/*") == 0) {
353  for(logd &l : *domains) {
354  if (l.first.compare(0, s - 1, name, 0, s - 1) == 0)
355  l.second = severity;
356  }
357  } else {
358  domain_map::iterator it = domains->find(name);
359  if (it == domains->end())
360  return false;
361  it->second = severity;
362  }
363  return true;
364 }
365 bool set_log_domain_severity(const std::string& name, const logger &lg) {
366  return set_log_domain_severity(name, lg.get_severity());
367 }
368 
369 bool get_log_domain_severity(const std::string& name, severity &severity)
370 {
371  domain_map::iterator it = domains->find(name);
372  if (it == domains->end())
373  return false;
374  severity = it->second;
375  return true;
376 }
377 
378 std::string list_log_domains(const std::string& filter)
379 {
380  std::ostringstream res;
381  for(logd &l : *domains) {
382  if(l.first.find(filter) != std::string::npos)
383  res << l.first << "\n";
384  }
385  return res.str();
386 }
387 
390 }
391 
393  set_strict_severity(lg.get_severity());
394 }
395 
396 static bool strict_threw_ = false;
397 
398 bool broke_strict() {
399  return strict_threw_;
400 }
401 
402 std::string get_timestamp(const std::time_t& t, const std::string& format) {
403  std::ostringstream ss;
404 
405  ss << std::put_time(std::localtime(&t), format.c_str());
406 
407  return ss.str();
408 }
409 std::string get_timespan(const std::time_t& t) {
410  std::ostringstream sout;
411  // There doesn't seem to be any library function for this
412  const std::time_t minutes = t / 60;
413  const std::time_t days = minutes / 60 / 24;
414  if(t <= 0) {
415  sout << "expired";
416  } else if(minutes == 0) {
417  sout << t << " seconds";
418  } else if(days == 0) {
419  sout << minutes / 60 << " hours, " << minutes % 60 << " minutes";
420  } else {
421  sout << days << " days, " << (minutes / 60) % 24 << " hours, " << minutes % 60 << " minutes";
422  }
423  return sout.str();
424 }
425 
426 static void print_precise_timestamp(std::ostream& out) noexcept
427 {
428  try {
429  auto now = std::chrono::system_clock::now();
430  auto seconds = std::chrono::time_point_cast<std::chrono::seconds>(now);
431  auto fractional = std::chrono::duration_cast<std::chrono::microseconds>(now - seconds);
432  std::time_t tm = std::chrono::system_clock::to_time_t(seconds);
433  char c = out.fill('0');
434  out << std::put_time(std::localtime(&tm), "%Y%m%d %H:%M:%S") << "." << std::setw(6) << fractional.count() << ' ';
435  out.fill(c);
436  } catch(...) {}
437 }
438 
439 void set_log_sanitize(bool sanitize) {
440  log_sanitization = sanitize;
441 }
442 
443 std::string sanitize_log(const std::string& logstr)
444 {
445  if(!log_sanitization) {
446  return logstr;
447  }
448 
449  std::string str = logstr;
450 
451 #ifdef _WIN32
452  const char* user_name = getenv("USERNAME");
453 #else
454  const char* user_name = getenv("USER");
455 #endif
456 
457  if(user_name != nullptr) {
458  boost::replace_all(str, std::string("/") + user_name + "/", "/USER/");
459  boost::replace_all(str, std::string("\\") + user_name + "\\", "\\USER\\");
460  }
461 
462  return str;
463 }
464 
466  const log_domain& domain,
467  bool show_names,
468  bool do_indent,
469  bool show_timestamps,
470  bool break_strict,
471  bool auto_newline) const
472 {
473  if (severity_ > domain.domain_->second) {
474  return null_ostream;
475  } else {
476  log_in_progress stream = output();
477  if(do_indent) {
478  stream.set_indent(indent);
479  }
480  if (timestamp && show_timestamps) {
481  stream.enable_timestamp();
482  }
483  if (show_names) {
484  stream.set_prefix(formatter() << name_ << ' ' << domain.domain_->first << ": ");
485  }
486  if (!strict_threw_ && severity_ <= strict_level_ && break_strict) {
487  stream | formatter() << "Error (strict mode, strict_level = " << strict_level_ << "): wesnoth reported on channel " << name_ << " " << domain.domain_->first << std::endl;
488  strict_threw_ = true;
489  }
490  stream.set_auto_newline(auto_newline);
491  return stream;
492  }
493 }
494 
495 log_in_progress::log_in_progress(std::ostream& stream)
496  : stream_(stream)
497 {}
498 
500 {
501  std::scoped_lock lock(log_mutex);
502  for(int i = 0; i < indent; ++i)
503  stream_ << " ";
504  if(timestamp_) {
505  if(precise_timestamp) {
507  } else {
508  stream_ << get_timestamp(std::time(nullptr));
509  }
510  }
511  stream_ << prefix_ << sanitize_log(message.str());
512  if(auto_newline_) {
513  stream_ << std::endl;
514  }
515 }
516 
518  indent_ = level;
519 }
520 
522  timestamp_ = true;
523 }
524 
525 void log_in_progress::set_prefix(const std::string& prefix) {
526  prefix_ = prefix;
527 }
528 
529 void log_in_progress::set_auto_newline(bool auto_newline) {
530  auto_newline_ = auto_newline;
531 }
532 
533 void scope_logger::do_log_entry(const std::string& str) noexcept
534 {
535  str_ = str;
536  start_ = std::chrono::steady_clock::now();
537  debug()(domain_, false, true) | formatter() << "{ BEGIN: " << str_;
538  ++indent;
539 }
540 
542 {
543  --indent;
544  auto output = debug()(domain_, false, true);
545  output.set_indent(indent);
546  if(timestamp) output.enable_timestamp();
547  auto now = std::chrono::steady_clock::now();
548  auto elapsed = std::chrono::duration_cast<std::chrono::microseconds>(now - start_);
549  output | formatter() << "} END: " << str_ << " (took " << elapsed.count() << "us)"; // FIXME c++20 stream: operator
550 }
551 
552 std::stringstream& log_to_chat()
553 {
554  static std::stringstream lg;
555  return lg;
556 }
557 
558 } // end namespace lg
double t
Definition: astarsearch.cpp:63
std::ostringstream wrapper.
Definition: formatter.hpp:40
logd * domain_
Definition: log.hpp:126
log_domain(char const *name, severity severity=severity::LG_WARN)
Definition: log.cpp:336
void operator|(formatter &&message)
Definition: log.cpp:499
std::string prefix_
Definition: log.hpp:196
std::ostream & stream_
Definition: log.hpp:193
void set_auto_newline(bool enabled)
Definition: log.cpp:529
void set_prefix(const std::string &prefix)
Definition: log.cpp:525
void enable_timestamp()
Definition: log.cpp:521
bool auto_newline_
Definition: log.hpp:197
void set_indent(int level)
Definition: log.cpp:517
log_in_progress(std::ostream &stream)
Definition: log.cpp:495
char const * name_
Definition: log.hpp:208
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:465
severity severity_
Definition: log.hpp:209
std::ostream * old_stream_
The previously set redirection.
Definition: log.hpp:118
redirect_output_setter(std::ostream &stream)
Constructor.
Definition: log.cpp:288
const log_domain & domain_
Definition: log.hpp:244
void do_log_entry(const std::string &str) noexcept
Definition: log.cpp:533
std::string str_
Definition: log.hpp:245
std::chrono::steady_clock::time_point start_
Definition: log.hpp:243
void do_log_exit() noexcept
Definition: log.cpp:541
uint32_t get_next_random()
Get a new random number.
Definition: mt_rng.cpp:63
Declarations for File-IO.
std::size_t i
Definition: function.cpp:1023
#define ERR_LS
Definition: log.cpp:41
static bool precise_timestamp
Definition: log.cpp:60
static std::string logs_dir_
path to the current logs directory; may change after being initially set if a custom userdata directo...
Definition: log.cpp:84
static utils::optional< bool > is_log_dir_writable_
whether the current logs directory is writable
Definition: log.cpp:66
#define LOG_LS
Definition: log.cpp:43
static std::string output_file_path_
path to the current log file; does not include the extension
Definition: log.cpp:82
static std::ostream null_ostream(new null_streambuf)
static std::mutex log_mutex
Definition: log.cpp:61
static int indent
Definition: log.cpp:58
static std::ostream & output()
Definition: log.cpp:73
static bool log_sanitization
Definition: log.cpp:63
static std::ostream * output_stream_
alternative stream to write data to
Definition: log.cpp:68
static lg::log_domain log_setup("logsetup")
static bool timestamp
Definition: log.cpp:59
Standard logging facilities (interface).
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:444
bool delete_file(const std::string &filename)
static bool file_exists(const bfs::path &fpath)
Definition: filesystem.cpp:325
int file_size(const std::string &fname)
Returns the size of a file, or -1 if the file doesn't exist.
void write_file(const std::string &fname, const std::string &data, std::ios_base::openmode mode)
Throws io_exception if an error occurs.
std::string get_logs_dir()
Definition: filesystem.cpp:832
bool make_directory(const std::string &dirname)
std::string path
Definition: filesystem.cpp:90
Definition: pump.hpp:41
bool get_log_domain_severity(const std::string &name, severity &severity)
Definition: log.cpp:369
logger & err()
Definition: log.cpp:305
severity
Definition: log.hpp:83
std::string list_log_domains(const std::string &filter)
Definition: log.cpp:378
log_domain & general()
Definition: log.cpp:331
bool broke_strict()
Definition: log.cpp:398
std::string get_timespan(const std::time_t &t)
Definition: log.cpp:409
logger & debug()
Definition: log.cpp:323
const std::string out_log_file_suffix
Definition: log.hpp:71
void rotate_logs(const std::string &log_dir)
Check how many log files exist and delete the oldest when there's too many.
Definition: log.cpp:100
std::string unique_log_filename()
Generate a unique file name using the current timestamp and a randomly generated number.
Definition: log.cpp:131
void set_log_to_file()
Do the initial redirection to a log file if the logs directory is writable.
Definition: log.cpp:232
static log_domain dom("general")
void set_log_sanitize(bool sanitize)
toggle log sanitization
Definition: log.cpp:439
utils::optional< bool > log_dir_writable()
Returns the result set by check_log_dir_writable().
Definition: log.cpp:278
void move_log_file()
Move the log file to another directory.
Definition: log.cpp:176
logger & warn()
Definition: log.cpp:311
void timestamps(bool t)
Definition: log.cpp:302
std::string sanitize_log(const std::string &logstr)
Definition: log.cpp:443
static severity strict_level_
Definition: log.cpp:301
const unsigned max_logs
Definition: log.hpp:76
void check_log_dir_writable()
Checks that a dummy file can be written to and deleted from the logs directory.
Definition: log.cpp:144
std::stringstream & log_to_chat()
Use this to show WML errors in the ingame chat.
Definition: log.cpp:552
const std::string log_file_prefix
Definition: log.hpp:68
std::map< std::string, severity > domain_map
Definition: log.cpp:299
static domain_map * domains
Definition: log.cpp:300
std::pair< const std::string, severity > logd
Definition: log.hpp:121
static bool strict_threw_
Definition: log.cpp:396
std::string get_timestamp(const std::time_t &t, const std::string &format)
Definition: log.cpp:402
bool is_not_log_file(const std::string &fn)
Use the defined prefix and suffix to determine if a filename is a log file.
Definition: log.cpp:94
void precise_timestamps(bool pt)
Definition: log.cpp:303
logger & info()
Definition: log.cpp:317
bool set_log_domain_severity(const std::string &name, severity severity)
Definition: log.cpp:345
void set_strict_severity(severity severity)
Definition: log.cpp:388
std::string get_log_file_path()
Definition: log.cpp:283
static void print_precise_timestamp(std::ostream &out) noexcept
Definition: log.cpp:426
const std::string log_file_suffix
Definition: log.hpp:69
std::ostringstream & operator<<(std::ostringstream &oss, const lg::severity severity)
Definition: log.cpp:88
void erase_if(Container &container, const Predicate &predicate)
Convenience wrapper for using std::remove_if on a container.
Definition: general.hpp:100
std::string::const_iterator iterator
Definition: tokenizer.hpp:25
An exception object used when an IO error occurs.
Definition: filesystem.hpp:67
mock_char c
static map_location::direction s