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