ceph/src/seastar/src/util/log.cc

   1 /*
   2  * This file is open source software, licensed to you under the terms
   3  * of the Apache License, Version 2.0 (the "License").  See the NOTICE file
   4  * distributed with this work for additional information regarding copyright
   5  * ownership.  You may not use this file except in compliance with the License.
   6  *
   7  * You may obtain a copy of the License at
   8  *
   9  *   http://www.apache.org/licenses/LICENSE-2.0
  10  *
  11  * Unless required by applicable law or agreed to in writing,
  12  * software distributed under the License is distributed on an
  13  * "AS IS" BASIS, WITHOUT WARRANTIES OR CONDITIONS OF ANY
  14  * KIND, either express or implied.  See the License for the
  15  * specific language governing permissions and limitations
  16  * under the License.
  17  */
  18 /*
  19  * Copyright (C) 2015 Cloudius Systems, Ltd.
  20  */
  21
  22 #include <fmt/core.h>
  23 #if FMT_VERSION >= 60000
  24 #include <fmt/chrono.h>
  25 #elif FMT_VERSION >= 50000
  26 #include <fmt/time.h>
  27 #endif
  28
  29 #include <seastar/util/log.hh>
  30 #include <seastar/core/smp.hh>
  31 #include <seastar/util/log-cli.hh>
  32
  33 #include <seastar/core/array_map.hh>
  34 #include <seastar/core/reactor.hh>
  35 #include <seastar/core/future.hh>
  36 #include <seastar/core/print.hh>
  37
  38 #include <boost/any.hpp>
  39 #include <boost/lexical_cast.hpp>
  40 #include <boost/range/adaptor/map.hpp>
  41 #include <cxxabi.h>
  42 #include <syslog.h>
  43
  44 #include <iostream>
  45 #include <map>
  46 #include <regex>
  47 #include <string>
  48 #include <system_error>
  49 #include <chrono>
  50
  51 #include "core/program_options.hh"
  52
  53 using namespace std::chrono_literals;
  54
  55 namespace seastar {
  56
  57 namespace internal {
  58
  59 void log_buf::free_buffer() noexcept {
  60     if (_own_buf) {
  61         delete[] _begin;
  62     }
  63 }
  64
  65 void log_buf::realloc_buffer() {
  66     const auto old_size = size();
  67     const auto new_size = old_size * 2;
  68
  69     auto new_buf = new char[new_size];
  70     std::memcpy(new_buf, _begin, old_size);
  71     free_buffer();
  72
  73     _begin = new_buf;
  74     _current = _begin + old_size;
  75     _end = _begin + new_size;
  76     _own_buf = true;
  77 }
  78
  79 log_buf::log_buf()
  80     : _begin(new char[512])
  81     , _end(_begin + 512)
  82     , _current(_begin)
  83     , _own_buf(true)
  84 {
  85 }
  86
  87 log_buf::log_buf(char* external_buf, size_t size) noexcept
  88     : _begin(external_buf)
  89     , _end(_begin + size)
  90     , _current(_begin)
  91     , _own_buf(false)
  92 {
  93 }
  94
  95 log_buf::~log_buf() {
  96     free_buffer();
  97 }
  98
  99 } // namespace internal
 100
 101 thread_local uint64_t logging_failures = 0;
 102
 103 void validate(boost::any& v,
 104               const std::vector<std::string>& values,
 105               logger_timestamp_style* target_type, int) {
 106     using namespace boost::program_options;
 107     validators::check_first_occurrence(v);
 108     auto s = validators::get_single_string(values);
 109     if (s == "none") {
 110         v = logger_timestamp_style::none;
 111         return;
 112     } else if (s == "boot") {
 113         v = logger_timestamp_style::boot;
 114         return;
 115     } else if (s == "real") {
 116         v = logger_timestamp_style::real;
 117         return;
 118     }
 119     throw validation_error(validation_error::invalid_option_value);
 120 }
 121
 122 std::ostream& operator<<(std::ostream& os, logger_timestamp_style lts) {
 123     switch (lts) {
 124     case logger_timestamp_style::none: return os << "none";
 125     case logger_timestamp_style::boot: return os << "boot";
 126     case logger_timestamp_style::real: return os << "real";
 127     default: abort();
 128     }
 129     return os;
 130 }
 131
 132 void validate(boost::any& v,
 133               const std::vector<std::string>& values,
 134               logger_ostream_type* target_type, int) {
 135     using namespace boost::program_options;
 136     validators::check_first_occurrence(v);
 137     auto s = validators::get_single_string(values);
 138     if (s == "none") {
 139         v = logger_ostream_type::none;
 140         return;
 141     } else if (s == "stdout") {
 142         v = logger_ostream_type::stdout;
 143         return;
 144     } else if (s == "stderr") {
 145         v = logger_ostream_type::stderr;
 146         return;
 147     }
 148     throw validation_error(validation_error::invalid_option_value);
 149 }
 150
 151 std::ostream& operator<<(std::ostream& os, logger_ostream_type lot) {
 152     switch (lot) {
 153     case logger_ostream_type::none: return os << "none";
 154     case logger_ostream_type::stdout: return os << "stdout";
 155     case logger_ostream_type::stderr: return os << "stderr";
 156     default: abort();
 157     }
 158     return os;
 159 }
 160
 161 static internal::log_buf::inserter_iterator print_no_timestamp(internal::log_buf::inserter_iterator it) {
 162     return it;
 163 }
 164
 165 static internal::log_buf::inserter_iterator print_boot_timestamp(internal::log_buf::inserter_iterator it) {
 166     auto n = std::chrono::steady_clock::now().time_since_epoch() / 1us;
 167     return fmt::format_to(it, "{:10d}.{:06d}", n / 1000000, n % 1000000);
 168 }
 169
 170 static internal::log_buf::inserter_iterator print_real_timestamp(internal::log_buf::inserter_iterator it) {
 171     struct a_second {
 172         time_t t;
 173         std::string s;
 174     };
 175     static thread_local a_second this_second;
 176     using clock = std::chrono::system_clock;
 177     auto n = clock::now();
 178     auto t = clock::to_time_t(n);
 179     if (this_second.t != t) {
 180         this_second.s = fmt::format("{:%Y-%m-%d %T}", fmt::localtime(t));
 181         this_second.t = t;
 182     }
 183     auto ms = (n - clock::from_time_t(t)) / 1ms;
 184     return fmt::format_to(it, "{},{:03d}", this_second.s, ms);
 185 }
 186
 187 static internal::log_buf::inserter_iterator (*print_timestamp)(internal::log_buf::inserter_iterator) = print_no_timestamp;
 188
 189 const std::map<log_level, sstring> log_level_names = {
 190         { log_level::trace, "trace" },
 191         { log_level::debug, "debug" },
 192         { log_level::info, "info" },
 193         { log_level::warn, "warn" },
 194         { log_level::error, "error" },
 195 };
 196
 197 std::ostream& operator<<(std::ostream& out, log_level level) {
 198     return out << log_level_names.at(level);
 199 }
 200
 201 std::istream& operator>>(std::istream& in, log_level& level) {
 202     sstring s;
 203     in >> s;
 204     if (!in) {
 205         return in;
 206     }
 207     for (auto&& x : log_level_names) {
 208         if (s == x.second) {
 209             level = x.first;
 210             return in;
 211         }
 212     }
 213     in.setstate(std::ios::failbit);
 214     return in;
 215 }
 216
 217 std::ostream* logger::_out = &std::cerr;
 218 std::atomic<bool> logger::_ostream = { true };
 219 std::atomic<bool> logger::_syslog = { false };
 220
 221 logger::logger(sstring name) : _name(std::move(name)) {
 222     global_logger_registry().register_logger(this);
 223 }
 224
 225 logger::logger(logger&& x) : _name(std::move(x._name)), _level(x._level.load(std::memory_order_relaxed)) {
 226     global_logger_registry().moved(&x, this);
 227 }
 228
 229 logger::~logger() {
 230     global_logger_registry().unregister_logger(this);
 231 }
 232
 233 static thread_local std::array<char, 8192> static_log_buf;
 234
 235 bool logger::rate_limit::check() {
 236     const auto now = clock::now();
 237     if (now < _next) {
 238         ++_dropped_messages;
 239         return false;
 240     }
 241     _next = now + _interval;
 242     return true;
 243 }
 244
 245 logger::rate_limit::rate_limit(std::chrono::milliseconds interval)
 246     : _interval(interval), _next(clock::now())
 247 { }
 248
 249 void
 250 logger::do_log(log_level level, log_writer& writer) {
 251     bool is_ostream_enabled = _ostream.load(std::memory_order_relaxed);
 252     bool is_syslog_enabled = _syslog.load(std::memory_order_relaxed);
 253     if(!is_ostream_enabled && !is_syslog_enabled) {
 254       return;
 255     }
 256     static array_map<sstring, 20> level_map = {
 257             { int(log_level::debug), "DEBUG" },
 258             { int(log_level::info),  "INFO "  },
 259             { int(log_level::trace), "TRACE" },
 260             { int(log_level::warn),  "WARN "  },
 261             { int(log_level::error), "ERROR" },
 262     };
 263     auto print_once = [&] (internal::log_buf::inserter_iterator it) {
 264       if (local_engine) {
 265           it = fmt::format_to(it, " [shard {}]", this_shard_id());
 266       }
 267       it = fmt::format_to(it, " {} - ", _name);
 268       return writer(it);
 269     };
 270
 271     // Mainly this protects us from re-entrance via malloc()'s
 272     // oversized allocation warnings and failed allocation errors
 273     silencer be_silent(*this);
 274
 275     if (is_ostream_enabled) {
 276         internal::log_buf buf(static_log_buf.data(), static_log_buf.size());
 277         auto it = buf.back_insert_begin();
 278         it = fmt::format_to(it, "{} ", level_map[int(level)]);
 279         it = print_timestamp(it);
 280         it = print_once(it);
 281         *it++ = '\n';
 282         *_out << buf.view();
 283         _out->flush();
 284     }
 285     if (is_syslog_enabled) {
 286         internal::log_buf buf(static_log_buf.data(), static_log_buf.size());
 287         auto it = buf.back_insert_begin();
 288         it = print_once(it);
 289         *it = '\0';
 290         static array_map<int, 20> level_map = {
 291                 { int(log_level::debug), LOG_DEBUG },
 292                 { int(log_level::info), LOG_INFO },
 293                 { int(log_level::trace), LOG_DEBUG },  // no LOG_TRACE
 294                 { int(log_level::warn), LOG_WARNING },
 295                 { int(log_level::error), LOG_ERR },
 296         };
 297         // NOTE: syslog() can block, which will stall the reactor thread.
 298         //       this should be rare (will have to fill the pipe buffer
 299         //       before syslogd can clear it) but can happen.  If it does,
 300         //       we'll have to implement some internal buffering (which
 301         //       still means the problem can happen, just less frequently).
 302         // syslog() interprets % characters, so send msg as a parameter
 303         syslog(level_map[int(level)], "%s", buf.data());
 304     }
 305 }
 306
 307 void logger::failed_to_log(std::exception_ptr ex, format_info fmt) noexcept
 308 {
 309     try {
 310         lambda_log_writer writer([ex = std::move(ex), fmt = std::move(fmt)] (internal::log_buf::inserter_iterator it) {
 311             it = fmt::format_to(it, "{}:{} @{}: failed to log message", fmt.loc.file_name(), fmt.loc.line(), fmt.loc.function_name());
 312             if (!fmt.format.empty()) {
 313                 it = fmt::format_to(it, ": fmt='{}'", fmt.format);
 314             }
 315             return fmt::format_to(it, ": {}", ex);
 316         });
 317         do_log(log_level::error, writer);
 318     } catch (...) {
 319         ++logging_failures;
 320     }
 321 }
 322
 323 void
 324 logger::set_ostream(std::ostream& out) noexcept {
 325     _out = &out;
 326 }
 327
 328 void
 329 logger::set_ostream_enabled(bool enabled) noexcept {
 330     _ostream.store(enabled, std::memory_order_relaxed);
 331 }
 332
 333 void
 334 logger::set_stdout_enabled(bool enabled) noexcept {
 335     _ostream.store(enabled, std::memory_order_relaxed);
 336 }
 337
 338 void
 339 logger::set_syslog_enabled(bool enabled) noexcept {
 340     _syslog.store(enabled, std::memory_order_relaxed);
 341 }
 342
 343 bool logger::is_shard_zero() noexcept {
 344     return this_shard_id() == 0;
 345 }
 346
 347 void
 348 logger_registry::set_all_loggers_level(log_level level) {
 349     std::lock_guard<std::mutex> g(_mutex);
 350     for (auto&& l : _loggers | boost::adaptors::map_values) {
 351         l->set_level(level);
 352     }
 353 }
 354
 355 log_level
 356 logger_registry::get_logger_level(sstring name) const {
 357     std::lock_guard<std::mutex> g(_mutex);
 358     return _loggers.at(name)->level();
 359 }
 360
 361 void
 362 logger_registry::set_logger_level(sstring name, log_level level) {
 363     std::lock_guard<std::mutex> g(_mutex);
 364     _loggers.at(name)->set_level(level);
 365 }
 366
 367 std::vector<sstring>
 368 logger_registry::get_all_logger_names() {
 369     std::lock_guard<std::mutex> g(_mutex);
 370     auto ret = _loggers | boost::adaptors::map_keys;
 371     return std::vector<sstring>(ret.begin(), ret.end());
 372 }
 373
 374 void
 375 logger_registry::register_logger(logger* l) {
 376     std::lock_guard<std::mutex> g(_mutex);
 377     if (_loggers.find(l->name()) != _loggers.end()) {
 378         throw std::runtime_error(format("Logger '{}' registered twice", l->name()));
 379     }
 380     _loggers[l->name()] = l;
 381 }
 382
 383 void
 384 logger_registry::unregister_logger(logger* l) {
 385     std::lock_guard<std::mutex> g(_mutex);
 386     _loggers.erase(l->name());
 387 }
 388
 389 void
 390 logger_registry::moved(logger* from, logger* to) {
 391     std::lock_guard<std::mutex> g(_mutex);
 392     _loggers[from->name()] = to;
 393 }
 394
 395 void apply_logging_settings(const logging_settings& s) {
 396     global_logger_registry().set_all_loggers_level(s.default_level);
 397
 398     for (const auto& pair : s.logger_levels) {
 399         try {
 400             global_logger_registry().set_logger_level(pair.first, pair.second);
 401         } catch (const std::out_of_range&) {
 402             throw std::runtime_error(
 403                         seastar::format("Unknown logger '{}'. Use --help-loggers to list available loggers.",
 404                                         pair.first));
 405         }
 406     }
 407
 408     logger_ostream_type logger_ostream = s.stdout_enabled ? s.logger_ostream : logger_ostream_type::none;
 409     switch (logger_ostream) {
 410     case logger_ostream_type::none:
 411         logger::set_ostream_enabled(false);
 412         break;
 413     case logger_ostream_type::stdout:
 414         logger::set_ostream(std::cout);
 415         logger::set_ostream_enabled(true);
 416         break;
 417     case logger_ostream_type::stderr:
 418         logger::set_ostream(std::cerr);
 419         logger::set_ostream_enabled(true);
 420         break;
 421     }
 422     logger::set_syslog_enabled(s.syslog_enabled);
 423
 424     switch (s.stdout_timestamp_style) {
 425     case logger_timestamp_style::none:
 426         print_timestamp = print_no_timestamp;
 427         break;
 428     case logger_timestamp_style::boot:
 429         print_timestamp = print_boot_timestamp;
 430         break;
 431     case logger_timestamp_style::real:
 432         print_timestamp = print_real_timestamp;
 433         break;
 434     default:
 435         break;
 436     }
 437 }
 438
 439 sstring pretty_type_name(const std::type_info& ti) {
 440     int status;
 441     std::unique_ptr<char[], void (*)(void*)> result(
 442             abi::__cxa_demangle(ti.name(), 0, 0, &status), std::free);
 443     return result.get() ? result.get() : ti.name();
 444 }
 445
 446 logger_registry& global_logger_registry() {
 447     static logger_registry g_registry;
 448     return g_registry;
 449 }
 450
 451 sstring level_name(log_level level) {
 452     return  log_level_names.at(level);
 453 }
 454
 455 namespace log_cli {
 456
 457 namespace bpo = boost::program_options;
 458
 459 log_level parse_log_level(const sstring& s) {
 460     try {
 461         return boost::lexical_cast<log_level>(s.c_str());
 462     } catch (const boost::bad_lexical_cast&) {
 463         throw std::runtime_error(format("Unknown log level '{}'", s));
 464     }
 465 }
 466
 467 void parse_map_associations(const std::string& v, std::function<void(std::string, std::string)> consume_key_value) {
 468     static const std::regex colon(":");
 469
 470     std::sregex_token_iterator s(v.begin(), v.end(), colon, -1);
 471     const std::sregex_token_iterator e;
 472     while (s != e) {
 473         const sstring p = std::string(*s++);
 474
 475         const auto i = p.find('=');
 476         if (i == sstring::npos) {
 477             throw bpo::invalid_option_value(p);
 478         }
 479
 480         auto k = p.substr(0, i);
 481         auto v = p.substr(i + 1, p.size());
 482         consume_key_value(std::move(k), std::move(v));
 483     };
 484 }
 485
 486 bpo::options_description get_options_description() {
 487     program_options::options_description_building_visitor descriptor;
 488     options(nullptr).describe(descriptor);
 489     return std::move(descriptor).get_options_description();
 490 }
 491
 492 options::options(program_options::option_group* parent_group)
 493     : program_options::option_group(parent_group, "Logging options")
 494     , default_log_level(*this, "default-log-level",
 495              log_level::info,
 496              "Default log level for log messages. Valid values are trace, debug, info, warn, error."
 497              )
 498     , logger_log_level(*this, "logger-log-level",
 499              {{}},
 500              "Map of logger name to log level. The format is \"NAME0=LEVEL0[:NAME1=LEVEL1:...]\". "
 501              "Valid logger names can be queried with --help-loggers. "
 502              "Valid values for levels are trace, debug, info, warn, error. "
 503              "This option can be specified multiple times."
 504             )
 505     , logger_stdout_timestamps(*this, "logger-stdout-timestamps", logger_timestamp_style::real,
 506                     "Select timestamp style for stdout logs: none|boot|real")
 507     , log_to_stdout(*this, "log-to-stdout", true, "Send log output to output stream, as selected by --logger-ostream-type")
 508     , logger_ostream_type(*this, "logger-ostream-type", logger_ostream_type::stderr,
 509             "Send log output to: none|stdout|stderr")
 510     , log_to_syslog(*this, "log-to-syslog", false, "Send log output to syslog.")
 511 {
 512 }
 513
 514 void print_available_loggers(std::ostream& os) {
 515     auto names = global_logger_registry().get_all_logger_names();
 516     // For quick searching by humans.
 517     std::sort(names.begin(), names.end());
 518
 519     os << "Available loggers:\n";
 520
 521     for (auto&& name : names) {
 522         os << "    " << name << '\n';
 523     }
 524 }
 525
 526 logging_settings extract_settings(const boost::program_options::variables_map& vars) {
 527     options opts(nullptr);
 528     program_options::variables_map_extracting_visitor visitor(vars);
 529     opts.mutate(visitor);
 530     return extract_settings(opts);
 531 }
 532
 533 logging_settings extract_settings(const options& opts) {
 534     return logging_settings{
 535         opts.logger_log_level.get_value(),
 536         opts.default_log_level.get_value(),
 537         opts.log_to_stdout.get_value(),
 538         opts.log_to_syslog.get_value(),
 539         opts.logger_stdout_timestamps.get_value(),
 540         opts.logger_ostream_type.get_value(),
 541     };
 542 }
 543
 544 }
 545
 546 }
 547 namespace boost {
 548 template<>
 549 seastar::log_level lexical_cast(const std::string& source) {
 550     std::istringstream in(source);
 551     seastar::log_level level;
 552     if (!(in >> level)) {
 553         throw boost::bad_lexical_cast();
 554     }
 555     return level;
 556 }
 557
 558 }
 559
 560 namespace std {
 561 std::ostream& operator<<(std::ostream& out, const std::exception_ptr& eptr) {
 562     if (!eptr) {
 563         out << "<no exception>";
 564         return out;
 565     }
 566     try {
 567         std::rethrow_exception(eptr);
 568     } catch(...) {
 569         auto tp = abi::__cxa_current_exception_type();
 570         if (tp) {
 571             out << seastar::pretty_type_name(*tp);
 572         } else {
 573             // This case shouldn't happen...
 574             out << "<unknown exception>";
 575         }
 576         // Print more information on some familiar exception types
 577         try {
 578             throw;
 579         } catch (const seastar::nested_exception& ne) {
 580             out << fmt::format(": {} (while cleaning up after {})", ne.inner, ne.outer);
 581         } catch (const std::system_error& e) {
 582             out << " (error " << e.code() << ", " << e.what() << ")";
 583         } catch (const std::exception& e) {
 584             out << " (" << e.what() << ")";
 585         } catch (...) {
 586             // no extra info
 587         }
 588
 589         try {
 590             throw;
 591         } catch (const std::nested_exception& ne) {
 592             out << ": " << ne.nested_ptr();
 593         } catch (...) {
 594             // do nothing
 595         }
 596     }
 597     return out;
 598 }
 599
 600 std::ostream& operator<<(std::ostream& out, const std::exception& e) {
 601     return out << seastar::pretty_type_name(typeid(e)) << " (" << e.what() << ")";
 602 }
 603
 604 std::ostream& operator<<(std::ostream& out, const std::system_error& e) {
 605     return out << seastar::pretty_type_name(typeid(e)) << " (error " << e.code() << ", " << e.what() << ")";
 606 }
 607
 608 }