Project Malmo  0.37.0
Logger.h
1 // --------------------------------------------------------------------------------------------------
2 // Copyright (c) 2016 Microsoft Corporation
3 //
4 // Permission is hereby granted, free of charge, to any person obtaining a copy of this software and
5 // associated documentation files (the "Software"), to deal in the Software without restriction,
6 // including without limitation the rights to use, copy, modify, merge, publish, distribute,
7 // sublicense, and/or sell copies of the Software, and to permit persons to whom the Software is
8 // furnished to do so, subject to the following conditions:
9 //
10 // The above copyright notice and this permission notice shall be included in all copies or
11 // substantial portions of the Software.
12 //
13 // THE SOFTWARE IS PROVIDED "AS IS", WITHOUT WARRANTY OF ANY KIND, EXPRESS OR IMPLIED, INCLUDING BUT
14 // NOT LIMITED TO THE WARRANTIES OF MERCHANTABILITY, FITNESS FOR A PARTICULAR PURPOSE AND
15 // NONINFRINGEMENT. IN NO EVENT SHALL THE AUTHORS OR COPYRIGHT HOLDERS BE LIABLE FOR ANY CLAIM,
16 // DAMAGES OR OTHER LIABILITY, WHETHER IN AN ACTION OF CONTRACT, TORT OR OTHERWISE, ARISING FROM,
17 // OUT OF OR IN CONNECTION WITH THE SOFTWARE OR THE USE OR OTHER DEALINGS IN THE SOFTWARE.
18 // --------------------------------------------------------------------------------------------------
19 
20 #ifndef _MALMO_LOGGER_H_
21 #define _MALMO_LOGGER_H_
22 
23 // Ideally we'd use boost::log rather than reinventing the wheel here, but due to our requirements to be able
24 // to use boost statically, boost::log is not an option:
25 // "If your application consists of more than one module (e.g. an exe and one or several dll's) that use Boost.Log,
26 // the library must be built as a shared object. If you have a single executable or a single module that works
27 // with Boost.Log, you may build the library as a static library."
28 // (from http://www.boost.org/doc/libs/1_64_0/libs/log/doc/html/log/installation/config.html )
29 
30 // The logger can act straight away (when Logger::print is called), but for performance reasons it is better to
31 // buffer the log messages and dump them en masse periodically, preferably in a background thread.
32 // Unfortuantely there are some hairy object lifetime difficulties involved in keeping our *own* thread, since the
33 // logger is a static singleton, which will be destroyed after main() has exited, which, with VS2013 at least,
34 // will cause a deadlock our thread hasn't already joined() -
35 // see https://connect.microsoft.com/VisualStudio/feedback/details/747145 for example.
36 // See comments below in log_spooler() for details.
37 
38 
39 // This logger partly owes its genesis to this Dr Dobbs article:
40 // http://www.drdobbs.com/parallel/more-memory-for-dos-exec/parallel/a-lightweight-logger-for-c/240147505
41 // and the associated github project by Filip Janiszewski - https://github.com/fjanisze/logger
42 // Note however that the code in github will not work on Windows (under VS2013 at least) for several reasons -
43 // firstly for the thread lifetime issue above, secondly because of the way VS treats std::move of string literals -
44 // see http://stackoverflow.com/questions/34160614/stdmove-of-string-literal-which-compiler-is-correct for an example.
45 // Thirdly VS2013 doesn't support the use of the ATOMIC_FLAG_INIT initialisation macro (eg see
46 // https://connect.microsoft.com/VisualStudio/feedback/details/800243/visual-studio-2013-rc-std-atomic-flag-regression etc.)
47 
48 // Boost:
49 #include <boost/date_time/posix_time/posix_time_types.hpp>
50 #include <boost/date_time/posix_time/posix_time_io.hpp>
51 
52 // STL:
53 #include <string>
54 #include <mutex>
55 #include <thread>
56 #include <atomic>
57 #include <vector>
58 #include <sstream>
59 #include <iostream>
60 #include <fstream>
61 #include <algorithm>
62 
63 namespace malmo
64 {
65  // To use logging in your source file, #define LOG_COMPONENT at the top -
66  // eg for logging video events, #define LOG_COMPONENT Logger::LOG_VIDEO
67  // #undef at the bottom of the file to avoid macro redefinition compiler warnings.
68  // Use "#define LOG_COMPONENT Logger::LOG_ALL_COMPONENTS" to ensure your file's log
69  // messages always get logged, regardless of the components selected for logging.
70  // The log messages generated by this file are all to do with object life times:
71  #define LOG_COMPONENT Logger::LOG_OBJECTLIFETIME
72 
73  #define LOGERROR(...) Logger::getLogger().print<Logger::LOG_ERRORS, LOG_COMPONENT>(__VA_ARGS__)
74  #define LOGWARNING(...) Logger::getLogger().print<Logger::LOG_WARNINGS, LOG_COMPONENT>(__VA_ARGS__)
75  #define LOGINFO(...) Logger::getLogger().print<Logger::LOG_INFO, LOG_COMPONENT>(__VA_ARGS__)
76  #define LOGFINE(...) Logger::getLogger().print<Logger::LOG_FINE, LOG_COMPONENT>(__VA_ARGS__)
77  #define LOGTRACE(...) Logger::getLogger().print<Logger::LOG_TRACE, LOG_COMPONENT>(__VA_ARGS__)
78  #define LOGSIMPLE(level, message) Logger::getLogger().print<Logger:: level , LOG_COMPONENT >(std::string(message))
79  #define LOGSECTION(level, message) LogSection<Logger:: level , LOG_COMPONENT> log_section(message);
80  #define LT(x) std::string(x)
81  #define MALMO_LOGGABLE_OBJECT(name) LoggerLifetimeTracker log_tracker{ #name };
82 
83  class Logger
84  {
85  public:
88  LOG_OFF
89  , LOG_ERRORS
90  , LOG_WARNINGS
91  , LOG_INFO
92  , LOG_FINE
93  , LOG_TRACE
94  , LOG_ALL
95  };
96 
99  LOG_TCP = 1
100  , LOG_RECORDING = 2
101  , LOG_VIDEO = 4
102  , LOG_AGENTHOST = 8
103  , LOG_OBJECTLIFETIME = 16
104  , LOG_ALL_COMPONENTS = 31
105  };
106 
107  Logger() : line_number(0), indentation(0)
108  {
109  this->has_backend = false;
110  this->is_spooling.clear();
111  this->logger_backend = new std::thread{ Logger::log_spooler, this };
112  }
113  ~Logger()
114  {
115  // Switch off logging now, to avoid complications:
116  this->severity_level = LOG_OFF;
117  // Let our spooling thread know that we want it to stop:
118  this->is_spooling.clear();
119  // Wait for it to finish (we can't use join() due to
120  // the exit lock issue.)
121  // In some scenarios, ExitProcess has already been called by this point,
122  // and our thread will have been terminated - so we don't want to wait
123  // indefinitely.
124  // It would be nicer to use std::this_thread::sleep_for(...), but it's not safe
125  // to call from within dllmain.
126  auto start = std::chrono::system_clock::now();
127  while (this->has_backend && (std::chrono::system_clock::now() - start).count() < 2.0);
128  // Clear whatever is left in our buffer.
129  // DON'T acquire the write_guard lock at this point - by this point
130  // there should be no danger of anyone else accessing our buffer,
131  // and if we got here because the process is exiting, it might not be
132  // safe to use the mutex.
133  clear_backlog();
134  // Detach the thread:
135  this->logger_backend->detach();
136  // And close our file, if we have one:
137  if (this->writer.is_open())
138  this->writer.close();
139  }
140  Logger(const malmo::Logger &) = delete;
141 
142  static Logger& getLogger()
143  {
144  static Logger the_logger;
145  return the_logger;
146  }
147 
148  template<LoggingSeverityLevel level, LoggingComponent component, typename...Args>
149  void print(Args&&...args);
150  void setSeverityLevel(LoggingSeverityLevel level) { severity_level = level; }
151  void setFilename(const std::string& file)
152  {
153  std::lock_guard< std::timed_mutex > lock(this->write_guard);
154  if (this->writer.is_open())
155  this->writer.close();
156  this->writer.open(file, std::ofstream::out | std::ofstream::app);
157  }
158  void setComponent(LoggingComponent component, bool enable_logging)
159  {
160  if (enable_logging)
161  this->logging_components |= component;
162  else
163  this->logging_components &= ~component;
164  }
165 
169  static void setLogging(const std::string& filename, LoggingSeverityLevel severity_level)
170  {
171  Logger::getLogger().setFilename(filename);
172  Logger::getLogger().setSeverityLevel(severity_level);
173  }
175  static void setLoggingComponent(LoggingComponent component, bool enable_logging)
176  {
177  Logger::getLogger().setComponent(component, enable_logging);
178  }
185  static void appendToLog(LoggingSeverityLevel severity_level, const std::string& message)
186  {
187 
188  switch (severity_level)
189  {
190  case LOG_OFF:
191  Logger::getLogger().print<LOG_OFF, LOG_ALL_COMPONENTS>(message); break;
192  case LOG_ERRORS:
193  Logger::getLogger().print<LOG_ERRORS, LOG_ALL_COMPONENTS>(message); break;
194  case LOG_WARNINGS:
195  Logger::getLogger().print<LOG_WARNINGS, LOG_ALL_COMPONENTS>(message); break;
196  case LOG_INFO:
197  Logger::getLogger().print<LOG_INFO, LOG_ALL_COMPONENTS>(message); break;
198  case LOG_FINE:
199  Logger::getLogger().print<LOG_FINE, LOG_ALL_COMPONENTS>(message); break;
200  case LOG_TRACE:
201  Logger::getLogger().print<LOG_TRACE, LOG_ALL_COMPONENTS>(message); break;
202  case LOG_ALL:
203  Logger::getLogger().print<LOG_ALL, LOG_ALL_COMPONENTS>(message); break;
204  }
205  }
206 
207  protected:
208  template<LoggingSeverityLevel level, Logger::LoggingComponent component> friend class LogSection;
209  friend class LoggerLifetimeTracker;
210 
211  void indent()
212  {
213  std::lock_guard< std::timed_mutex > lock(write_guard);
214  indentation++;
215  }
216  void unindent()
217  {
218  std::lock_guard< std::timed_mutex > lock(write_guard);
219  indentation--;
220  }
221 
222  static void log_spooler(Logger* logger)
223  {
224  logger->has_backend = true;
225  logger->is_spooling.test_and_set();
226  std::unique_lock<std::timed_mutex> writing_lock{ logger->write_guard, std::defer_lock };
227  // Loop until the logger clears the is_spooling flag - this happens when the logger is destructed.
228  do
229  {
230  std::this_thread::sleep_for(std::chrono::milliseconds{ 100 });
231  if (logger->log_buffer.size())
232  {
233  writing_lock.lock();
234  logger->clear_backlog();
235  writing_lock.unlock();
236  }
237  } while (logger->is_spooling.test_and_set());
238  // The logger will be waiting for us to finish spooling - let it know it can continue:
239  logger->has_backend = false;
240  // ON WINDOWS, VS2013:
241  // If we let this function end now, we will get a nasty race condition with the CRT.
242  // When the thread finishes running its main method (this function), it will enter
243  // _Cnd_do_broadcast_at_thread_exit(), and attempt to signal the news of the thread's demise
244  // to anyone waiting for it. Doing this involves creating an "at_thread_exit_mutex", and adding
245  // a destruction method for it ("destroy_at_thread_exit_mutex") to the DLL's atexit/_onexit list.
246  // (This is a list of functions which will get called when the DLL is signalled to exit by ExitProcess.)
247 
248  // BUT:
249 
250  // Because logger is a static singleton, its destruction takes place AFTER main() exits, at
251  // which point the CRT has imposed an EXIT LOCK. All exit code needs to own the exit lock before it can
252  // execute. At the point when ~Logger() is called, the main thread owns this exit lock, and it won't
253  // relinquish it until right before it calls ExitProcess, after going through its own atexit/_onexit list.
254  // The worker thread needs to aquire this lock before it can create the at_thread_exit_mutex, so it
255  // is forced to wait while everything else is destructed and cleaned before it can carry on.
256 
257  // The end result is that the worker thread has just enough time to create and lock the mutex before
258  // the main thread calls ExitProcess, which calls the DLL cleanup code, which deletes the mutex,
259  // resulting in an abort() with a "mutex destroyed while busy" error.
260 
261  // To get around this, we simply go to sleep for a bit, to give the main thread a chance to exit
262  // before we even have a chance to leave this function.
263  std::this_thread::sleep_for(std::chrono::milliseconds(100000));
264  // It'll all be over before we even wake up.
265  }
266 
267  void clear_backlog()
268  {
269  for (auto& item : this->log_buffer)
270  {
271  performWrite(item);
272  }
273  this->log_buffer.clear();
274  }
275 
276  void performWrite(const std::string& logline)
277  {
278  std::string str(logline);
279  str.erase(std::remove(str.begin(), str.end(), '\n'), str.end());
280  if (this->writer.is_open())
281  this->writer << str << std::endl;
282  else
283  std::cout << str << std::endl;
284  }
285 
286  private:
287  friend void log_spooler(Logger* logger);
288 
289  template<typename First, typename... Others> void print_impl(std::stringstream&& message_stream, First&& param1, Others&&... params)
290  {
291  message_stream << param1;
292  print_impl(std::forward<std::stringstream>(message_stream), std::move(params)...);
293  }
294 
295  void print_impl(std::stringstream&& message_stream)
296  {
297  std::lock_guard< std::timed_mutex > lock(this->write_guard);
298  this->log_buffer.push_back(message_stream.str());
299  }
300 
301  LoggingSeverityLevel severity_level{ LOG_OFF };
302  unsigned int logging_components{ LOG_ALL_COMPONENTS };
303  int line_number;
304  int indentation;
305  std::timed_mutex write_guard;
306  std::vector<std::string> log_buffer;
307  std::thread spooler;
308  std::atomic_bool has_backend;
309  std::atomic_flag is_spooling;
310  bool terminated;
311  std::ofstream writer;
312  std::thread *logger_backend;
313  };
314 
315  template<Logger::LoggingSeverityLevel level, Logger::LoggingComponent component, typename...Args>void Logger::print(Args&&...args)
316  {
317  if (level > this->severity_level)
318  return;
319  if (!(this->logging_components & component))
320  return;
321  std::stringstream message_stream;
322  auto now = boost::posix_time::microsec_clock::universal_time();
323  message_stream << now << " P "; // 'P' for 'Platform' - useful if combining logs with Mod-side.
324  switch (level)
325  {
326  case LoggingSeverityLevel::LOG_ALL:
327  case LoggingSeverityLevel::LOG_ERRORS:
328  message_stream << "ERROR ";
329  break;
330  case LoggingSeverityLevel::LOG_WARNINGS:
331  message_stream << "WARNING ";
332  break;
333  case LoggingSeverityLevel::LOG_INFO:
334  message_stream << "INFO ";
335  break;
336  case LoggingSeverityLevel::LOG_FINE:
337  message_stream << "FINE ";
338  break;
339  case LoggingSeverityLevel::LOG_TRACE:
340  case LoggingSeverityLevel::LOG_OFF:
341  message_stream << "TRACE ";
342  break;
343  }
344  for (int i = 0; i < this->indentation; i++)
345  message_stream << " ";
346 
347  print_impl(std::forward<std::stringstream>(message_stream), std::move(args)...);
348  this->line_number++;
349  }
350 
351  template<Logger::LoggingSeverityLevel level, Logger::LoggingComponent component>
353  {
354  public:
355  LogSection(const std::string& title)
356  {
357  Logger::getLogger().print<level, component>(title);
358  Logger::getLogger().print<level, component>(std::string("{"));
359  Logger::getLogger().indent();
360  }
361  ~LogSection()
362  {
363  Logger::getLogger().unindent();
364  Logger::getLogger().print<level, component>(std::string("}"));
365  }
366  };
367 
369  {
370  public:
371  LoggerLifetimeTracker(const std::string& _name) : name(_name)
372  {
373  addref();
374  }
375  LoggerLifetimeTracker(const LoggerLifetimeTracker& rhs) : name(rhs.name)
376  {
377  addref();
378  }
380  {
381  int prev_val = object_count.fetch_add(-1);
382  LOGFINE(LT("Destructing "), this->name, LT(" (object count now "), prev_val - 1, LT(")"));
383  }
384 
385  private:
386  void addref()
387  {
388  int prev_val = object_count.fetch_add(1);
389  LOGFINE(LT("Constructing "), this->name, LT(" (object count now "), prev_val + 1, LT(")"));
390  }
391  static std::atomic<int> object_count;
392  std::string name;
393  };
394 }
395 
396 #undef LOG_COMPONENT
397 #endif //_MALMO_LOGGER_H_
Definition: Logger.h:353
Definition: Logger.h:84
static void setLogging(const std::string &filename, LoggingSeverityLevel severity_level)
Sets logging options for debugging.
Definition: Logger.h:169
LoggingComponent
Specifies the components that will output logging information.
Definition: Logger.h:98
LoggingSeverityLevel
Specifies the detail that will be logged, if logging is enabled.
Definition: Logger.h:87
static void appendToLog(LoggingSeverityLevel severity_level, const std::string &message)
Add a single line to the log.
Definition: Logger.h:185
static void setLoggingComponent(LoggingComponent component, bool enable_logging)
Switches on/off logging for a particular component. All components are enabled by default....
Definition: Logger.h:175
Definition: Logger.h:369