OmniSciDB  c07336695a
Logger.cpp
Go to the documentation of this file.
1 /*
2  * Copyright 2019 OmniSci, Inc.
3  *
4  * Licensed under the Apache License, Version 2.0 (the "License");
5  * you may not use this file except in compliance with the License.
6  * You may obtain a copy of the License at
7  *
8  * http://www.apache.org/licenses/LICENSE-2.0
9  *
10  * Unless required by applicable law or agreed to in writing, software
11  * distributed under the License is distributed on an "AS IS" BASIS,
12  * WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied.
13  * See the License for the specific language governing permissions and
14  * limitations under the License.
15  */
16 
17 #ifndef __CUDACC__
18 
19 #include "Logger.h"
20 #include "StringTransform.h"
21 
22 #include <boost/algorithm/string.hpp>
23 #include <boost/log/expressions.hpp>
24 #include <boost/log/sinks.hpp>
25 #include <boost/log/sources/global_logger_storage.hpp>
26 #include <boost/log/sources/logger.hpp>
27 #include <boost/log/sources/severity_feature.hpp>
28 #include <boost/log/support/date_time.hpp>
29 #include <boost/log/utility/setup.hpp>
30 #include <boost/phoenix.hpp>
31 
32 #include <atomic>
33 #include <cstdlib>
34 #include <iostream>
35 #include <mutex>
36 #include <regex>
37 
38 namespace logger {
39 
40 namespace attr = boost::log::attributes;
41 namespace expr = boost::log::expressions;
42 namespace keywords = boost::log::keywords;
43 namespace sinks = boost::log::sinks;
44 namespace sources = boost::log::sources;
45 namespace po = boost::program_options;
46 
47 BOOST_LOG_ATTRIBUTE_KEYWORD(process_id, "ProcessID", attr::current_process_id::value_type)
48 BOOST_LOG_ATTRIBUTE_KEYWORD(channel, "Channel", Channel)
49 BOOST_LOG_ATTRIBUTE_KEYWORD(severity, "Severity", Severity)
50 
51 BOOST_LOG_GLOBAL_LOGGER_DEFAULT(gChannelLogger, ChannelLogger)
52 BOOST_LOG_GLOBAL_LOGGER_DEFAULT(gSeverityLogger, SeverityLogger)
53 
54 LogOptions::LogOptions(char const* argv0) : options_("Logging") {
55  // Log file base_name matches name of program.
56  std::string const base_name = argv0 == nullptr
57  ? std::string("omnisci_server")
58  : boost::filesystem::path(argv0).filename().string();
59  file_name_pattern_ = base_name + file_name_pattern_;
60  symlink_ = base_name + symlink_;
61  std::string const channels = join(ChannelNames, " ");
62  // Filter out DEBUG[1-4] severities from --help options
63  std::string severities;
64  for (auto const& name : SeverityNames) {
65  if (!boost::algorithm::starts_with(name, "DEBUG")) {
66  (severities += (severities.empty() ? "" : " ")) += name;
67  }
68  }
69  options_.add_options()(
70  "log-directory",
71  po::value<boost::filesystem::path>(&log_dir_)->default_value(log_dir_),
72  "Logging directory. May be relative to data directory, or absolute.");
73  options_.add_options()(
74  "log-file-name",
75  po::value<std::string>(&file_name_pattern_)->default_value(file_name_pattern_),
76  "Log file name relative to log-directory.");
77  options_.add_options()("log-symlink",
78  po::value<std::string>(&symlink_)->default_value(symlink_),
79  "Symlink to active log.");
80  options_.add_options()("log-severity",
81  po::value<Severity>(&severity_)->default_value(severity_),
82  ("Log to file severity level: " + severities).c_str());
83  options_.add_options()(
84  "log-severity-clog",
85  po::value<Severity>(&severity_clog_)->default_value(severity_clog_),
86  ("Log to console severity level: " + severities).c_str());
87  options_.add_options()("log-channels",
88  po::value<Channels>(&channels_)->default_value(channels_),
89  ("Log channel debug info: " + channels).c_str());
90  options_.add_options()("log-auto-flush",
91  po::value<bool>(&auto_flush_)->default_value(auto_flush_),
92  "Flush logging buffer to file after each message.");
93  options_.add_options()("log-max-files",
94  po::value<size_t>(&max_files_)->default_value(max_files_),
95  "Maximum number of log files to keep.");
96  options_.add_options()(
97  "log-min-free-space",
98  po::value<size_t>(&min_free_space_)->default_value(20 << 20),
99  "Minimum number of bytes left on device before oldest log files are deleted.");
100  options_.add_options()("log-rotate-daily",
101  po::value<bool>(&rotate_daily_)->default_value(true),
102  "Start new log files at midnight.");
103  options_.add_options()("log-rotation-size",
104  po::value<size_t>(&rotation_size_)->default_value(10 << 20),
105  "Maximum file size in bytes before new log files are started.");
106 }
107 
108 boost::filesystem::path LogOptions::full_log_dir() const {
109  return log_dir_.has_root_directory() ? log_dir_ : base_path_ / log_dir_;
110 }
111 
112 po::options_description const& LogOptions::get_options() const {
113  return options_;
114 }
115 
116 // Typical usage calls either get_options() or parse_command_line() but not both.
117 void LogOptions::parse_command_line(int argc, char const* const* argv) {
118  po::variables_map vm;
119  po::store(
120  po::command_line_parser(argc, argv).options(options_).allow_unregistered().run(),
121  vm);
122  po::notify(vm); // Sets LogOptions member variables.
123 }
124 
125 // Must be called before init() to take effect.
126 void LogOptions::set_base_path(std::string const& base_path) {
127  base_path_ = base_path;
128 }
129 
130 template <typename TAG>
131 std::string replace_braces(std::string const& str, TAG const tag) {
132  constexpr std::regex::flag_type flags = std::regex::ECMAScript | std::regex::optimize;
133  static std::regex const regex(R"(\{SEVERITY\})", flags);
134  if /*constexpr*/ (std::is_same<TAG, Channel>::value) {
135  return std::regex_replace(str, regex, ChannelNames[tag]);
136  } else {
137  return std::regex_replace(str, regex, SeverityNames[tag]);
138  }
139 }
140 
141 // Print decimal value for process_id (14620) instead of hex (0x0000391c)
142 boost::log::attributes::current_process_id::value_type::native_type get_native_process_id(
143  boost::log::value_ref<boost::log::attributes::current_process_id::value_type,
144  tag::process_id> const& pid) {
145  return pid ? pid->native_id() : 0;
146 }
147 
148 template <typename SINK>
149 sinks::text_file_backend::open_handler_type create_or_replace_symlink(
150  boost::weak_ptr<SINK> weak_ptr,
151  std::string&& symlink) {
152  namespace fs = boost::filesystem;
153  return [weak_ptr,
154  symlink = std::move(symlink)](sinks::text_file_backend::stream_type& stream) {
155  if (boost::shared_ptr<SINK> sink = weak_ptr.lock()) {
157  fs::path const& file_name = sink->locked_backend()->get_current_file_name();
158  fs::path const symlink_path = file_name.parent_path() / symlink;
159  fs::remove(symlink_path, ec);
160  if (ec) {
161  stream << fs::path(__FILE__).filename().native() << ':' << __LINE__ << ' '
162  << ec.message() << std::endl;
163  }
164  fs::create_symlink(file_name.filename(), symlink_path, ec);
165  if (ec) {
166  stream << fs::path(__FILE__).filename().native() << ':' << __LINE__ << ' '
167  << ec.message() << std::endl;
168  }
169  }
170  };
171 }
172 
173 boost::log::formatting_ostream& operator<<(
174  boost::log::formatting_ostream& strm,
175  boost::log::to_log_manip<Channel, tag::channel> const& manip) {
176  return strm << ChannelSymbols[manip.get()];
177 }
178 
179 boost::log::formatting_ostream& operator<<(
180  boost::log::formatting_ostream& strm,
181  boost::log::to_log_manip<Severity, tag::severity> const& manip) {
182  return strm << SeveritySymbols[manip.get()];
183 }
184 
185 template <typename TAG, typename SINK>
186 void set_formatter(SINK& sink) {
187  if /*constexpr*/ (std::is_same<TAG, Channel>::value) {
188  sink->set_formatter(
189  expr::stream << expr::format_date_time<boost::posix_time::ptime>(
190  "TimeStamp", "%Y-%m-%dT%H:%M:%S.%f")
191  << ' ' << channel << ' '
192  << boost::phoenix::bind(&get_native_process_id, process_id.or_none())
193  << ' ' << expr::smessage);
194  } else {
195  sink->set_formatter(
196  expr::stream << expr::format_date_time<boost::posix_time::ptime>(
197  "TimeStamp", "%Y-%m-%dT%H:%M:%S.%f")
198  << ' ' << severity << ' '
199  << boost::phoenix::bind(&get_native_process_id, process_id.or_none())
200  << ' ' << expr::smessage);
201  }
202 }
203 
204 template <typename FILE_SINK, typename TAG>
205 boost::shared_ptr<FILE_SINK> make_sink(LogOptions const& log_opts,
206  boost::filesystem::path const& full_log_dir,
207  TAG const tag) {
208  auto sink = boost::make_shared<FILE_SINK>(
209  keywords::file_name =
210  full_log_dir / replace_braces(log_opts.file_name_pattern_, tag),
211  keywords::auto_flush = log_opts.auto_flush_,
212  keywords::rotation_size = log_opts.rotation_size_);
213  if /*constexpr*/ (std::is_same<TAG, Channel>::value) {
214  sink->set_filter(channel == static_cast<Channel>(tag));
215  set_formatter<Channel>(sink);
216  } else {
217  // INFO sink logs all other levels. Other sinks only log at their level or higher.
218  Severity const min_filter_level = static_cast<Severity>(tag) == Severity::INFO
219  ? log_opts.severity_
220  : static_cast<Severity>(tag);
221  sink->set_filter(min_filter_level <= severity);
222  set_formatter<Severity>(sink);
223  }
224  typename FILE_SINK::locked_backend_ptr backend = sink->locked_backend();
225  if (log_opts.rotate_daily_) {
226  backend->set_time_based_rotation(sinks::file::rotation_at_time_point(0, 0, 0));
227  }
228  backend->set_file_collector(
229  sinks::file::make_collector(keywords::target = full_log_dir,
230  keywords::max_files = log_opts.max_files_,
231  keywords::min_free_space = log_opts.min_free_space_));
232  backend->set_open_handler(create_or_replace_symlink(
233  boost::weak_ptr<FILE_SINK>(sink), replace_braces(log_opts.symlink_, tag)));
234  backend->scan_for_files();
235  return sink;
236 }
237 
238 // Pointer to function to optionally call on LOG(FATAL).
239 std::atomic<FatalFunc> g_fatal_func{nullptr};
240 std::once_flag g_fatal_func_flag;
241 
242 using ClogSync = sinks::synchronous_sink<sinks::text_ostream_backend>;
243 using FileSync = sinks::synchronous_sink<sinks::text_file_backend>;
244 
245 template <typename CONSOLE_SINK>
246 boost::shared_ptr<CONSOLE_SINK> make_sink(LogOptions const& log_opts) {
247  auto sink = boost::make_shared<CONSOLE_SINK>();
248  boost::shared_ptr<std::ostream> clog(&std::clog, boost::null_deleter());
249  sink->locked_backend()->add_stream(clog);
250  sink->set_filter(log_opts.severity_clog_ <= severity);
251  set_formatter<Severity>(sink);
252  return sink;
253 }
254 
255 // Locking/atomicity not needed for g_any_active_channels or g_min_active_severity
256 // as they are modifed by init() once.
259 
260 void init(LogOptions const& log_opts) {
261  boost::shared_ptr<boost::log::core> core = boost::log::core::get();
262  // boost::log::add_common_attributes(); // LineID TimeStamp ProcessID ThreadID
263  core->add_global_attribute("TimeStamp", attr::local_clock());
264  core->add_global_attribute("ProcessID", attr::current_process_id());
265  if (0 < log_opts.max_files_) {
266  boost::filesystem::path const full_log_dir = log_opts.full_log_dir();
267  bool const log_dir_was_created = boost::filesystem::create_directory(full_log_dir);
268  // Don't create separate log sinks for anything less than Severity::INFO.
269  Severity const min_sink_level = std::max(Severity::INFO, log_opts.severity_);
270  for (int i = min_sink_level; i < Severity::_NSEVERITIES; ++i) {
271  Severity const level = static_cast<Severity>(i);
272  core->add_sink(make_sink<FileSync>(log_opts, full_log_dir, level));
273  }
275  if (log_dir_was_created) {
276  LOG(INFO) << "Log directory(" << full_log_dir.native() << ") created.";
277  }
278  for (auto const channel : log_opts.channels_) {
279  core->add_sink(make_sink<FileSync>(log_opts, full_log_dir, channel));
280  }
281  g_any_active_channels = !log_opts.channels_.empty();
282  }
283  core->add_sink(make_sink<ClogSync>(log_opts));
285 }
286 
287 void set_once_fatal_func(FatalFunc fatal_func) {
288  if (g_fatal_func.exchange(fatal_func)) {
289  throw std::runtime_error(
290  "logger::set_once_fatal_func() should not be called more than once.");
291  }
292 }
293 
294 void shutdown() {
295  boost::log::core::get()->remove_all_sinks();
296 }
297 
298 // Used by boost::program_options when parsing enum Channel.
299 std::istream& operator>>(std::istream& in, Channels& channels) {
300  std::string line;
301  std::getline(in, line);
302  std::regex const rex(R"(\w+)");
303  using TokenItr = std::regex_token_iterator<std::string::iterator>;
304  TokenItr const end;
305  for (TokenItr tok(line.begin(), line.end(), rex); tok != end; ++tok) {
306  auto itr = std::find(ChannelNames.cbegin(), ChannelNames.cend(), *tok);
307  if (itr == ChannelNames.cend()) {
308  in.setstate(std::ios_base::failbit);
309  break;
310  } else {
311  channels.emplace(static_cast<Channel>(itr - ChannelNames.cbegin()));
312  }
313  }
314  return in;
315 }
316 
317 // Used by boost::program_options when stringifying Channels.
318 std::ostream& operator<<(std::ostream& out, Channels const& channels) {
319  int i = 0;
320  for (auto const channel : channels) {
321  out << (i++ ? " " : "") << ChannelNames.at(channel);
322  }
323  return out;
324 }
325 
326 // Used by boost::program_options when parsing enum Severity.
327 std::istream& operator>>(std::istream& in, Severity& sev) {
328  std::string token;
329  in >> token;
330  auto itr = std::find(SeverityNames.cbegin(), SeverityNames.cend(), token);
331  if (itr == SeverityNames.cend()) {
332  in.setstate(std::ios_base::failbit);
333  } else {
334  sev = static_cast<Severity>(itr - SeverityNames.cbegin());
335  }
336  return in;
337 }
338 
339 // Used by boost::program_options when stringifying enum Severity.
340 std::ostream& operator<<(std::ostream& out, Severity const& sev) {
341  return out << SeverityNames.at(sev);
342 }
343 
345  : is_channel_(true)
346  , enum_value_(channel)
347  , record_(std::make_unique<boost::log::record>(
348  gChannelLogger::get().open_record(boost::log::keywords::channel = channel))) {
349  if (*record_) {
350  stream_ = std::make_unique<boost::log::record_ostream>(*record_);
351  }
352 }
353 
355  : is_channel_(false)
356  , enum_value_(severity)
357  , record_(std::make_unique<boost::log::record>(gSeverityLogger::get().open_record(
358  boost::log::keywords::severity = severity))) {
359  if (*record_) {
360  stream_ = std::make_unique<boost::log::record_ostream>(*record_);
361  }
362 }
363 
365  if (stream_) {
366  if (is_channel_) {
367  gChannelLogger::get().push_record(boost::move(stream_->get_record()));
368  } else {
369  gSeverityLogger::get().push_record(boost::move(stream_->get_record()));
370  }
371  }
372  if (!is_channel_ && static_cast<Severity>(enum_value_) == Severity::FATAL) {
373  if (FatalFunc fatal_func = g_fatal_func.load()) {
374  // set_once_fatal_func() prevents race condition.
375  // Exceptions thrown by (*fatal_func)() are propagated here.
376  std::call_once(g_fatal_func_flag, *fatal_func);
377  }
378  abort();
379  }
380 }
381 
382 Logger::operator bool() const {
383  return static_cast<bool>(stream_);
384 }
385 
386 boost::log::record_ostream& Logger::stream(char const* file, int line) {
387  return *stream_ << boost::filesystem::path(file).filename().native() << ':' << line
388  << ' ';
389 }
390 
391 } // namespace logger
392 
393 #endif // #ifndef __CUDACC__
std::istream & operator>>(std::istream &in, Channels &channels)
Definition: Logger.cpp:299
int const enum_value_
Definition: Logger.h:153
size_t min_free_space_
Definition: Logger.h:118
std::string replace_braces(std::string const &str, TAG const tag)
Definition: Logger.cpp:131
std::set< Channel > Channels
Definition: Logger.h:100
boost::log::sources::channel_logger_mt< Channel > ChannelLogger
Definition: Logger.h:144
void set_formatter(SINK &sink)
Definition: Logger.cpp:186
std::unique_ptr< boost::log::record > record_
Definition: Logger.h:155
sinks::text_file_backend::open_handler_type create_or_replace_symlink(boost::weak_ptr< SINK > weak_ptr, std::string &&symlink)
Definition: Logger.cpp:149
std::once_flag g_fatal_func_flag
Definition: Logger.cpp:240
std::string base_path_
Definition: Logger.h:104
#define LOG(tag)
Definition: Logger.h:182
Channel
Definition: Logger.h:58
std::string join(T const &container, std::string const &delim)
boost::program_options::options_description const & get_options() const
Definition: Logger.cpp:112
void set_once_fatal_func(FatalFunc fatal_func)
Definition: Logger.cpp:287
sinks::synchronous_sink< sinks::text_ostream_backend > ClogSync
Definition: Logger.cpp:242
constexpr std::array< char, 8 > SeveritySymbols
Definition: Logger.h:91
Channels channels_
Definition: Logger.h:115
bool const is_channel_
Definition: Logger.h:152
constexpr std::array< char, 2 > ChannelSymbols
Definition: Logger.h:62
sinks::synchronous_sink< sinks::text_file_backend > FileSync
Definition: Logger.cpp:243
void init(LogOptions const &log_opts)
Definition: Logger.cpp:260
Severity g_min_active_severity
Definition: Logger.cpp:258
std::atomic< FatalFunc > g_fatal_func
Definition: Logger.cpp:239
const int8_t const int64_t const uint64_t const int32_t const int64_t int64_t uint32_t const int64_t int32_t * error_code
boost::shared_ptr< FILE_SINK > make_sink(LogOptions const &log_opts, boost::filesystem::path const &full_log_dir, TAG const tag)
Definition: Logger.cpp:205
bool rotate_daily_
Definition: Logger.h:119
std::string symlink_
Definition: Logger.h:112
std::unique_ptr< boost::log::record_ostream > stream_
Definition: Logger.h:156
Severity
Definition: Logger.h:70
boost::log::formatting_ostream & operator<<(boost::log::formatting_ostream &strm, boost::log::to_log_manip< Channel, tag::channel > const &manip)
Definition: Logger.cpp:173
void shutdown()
Definition: Logger.cpp:294
constexpr std::array< char const *, 8 > SeverityNames
Definition: Logger.h:82
boost::filesystem::path full_log_dir() const
Definition: Logger.cpp:108
Severity severity_
Definition: Logger.h:113
constexpr std::array< char const *, 2 > ChannelNames
Definition: Logger.h:60
bool g_any_active_channels
Definition: Logger.cpp:257
boost::program_options::options_description options_
Definition: Logger.h:105
boost::log::sources::severity_logger_mt< Severity > SeverityLogger
Definition: Logger.h:147
std::string file_name_pattern_
Definition: Logger.h:111
size_t rotation_size_
Definition: Logger.h:120
void set_base_path(std::string const &base_path)
Definition: Logger.cpp:126
boost::log::attributes::current_process_id::value_type::native_type get_native_process_id(boost::log::value_ref< boost::log::attributes::current_process_id::value_type, tag::process_id > const &pid)
Definition: Logger.cpp:142
size_t max_files_
Definition: Logger.h:117
Logger(Channel)
Definition: Logger.cpp:344
static bool run
const int8_t const int64_t const uint64_t const int32_t const int64_t int64_t ** out
void(*)() FatalFunc
Definition: Logger.h:141
Severity severity_clog_
Definition: Logger.h:114
boost::filesystem::path log_dir_
Definition: Logger.h:109
boost::log::record_ostream & stream(char const *file, int line)
Definition: Logger.cpp:386
void parse_command_line(int, char const *const *)
Definition: Logger.cpp:117