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