ceph/src/log/Log.cc

   1 // -*- mode:C++; tab-width:8; c-basic-offset:2; indent-tabs-mode:t -*-
   2 // vim: ts=8 sw=2 smarttab
   3
   4 #include "Log.h"
   5
   6 #include "common/errno.h"
   7 #include "common/safe_io.h"
   8 #include "common/Graylog.h"
   9 #include "common/Journald.h"
  10 #include "common/valgrind.h"
  11
  12 #include "include/ceph_assert.h"
  13 #include "include/compat.h"
  14 #include "include/on_exit.h"
  15 #include "include/uuid.h"
  16
  17 #include "Entry.h"
  18 #include "LogClock.h"
  19 #include "SubsystemMap.h"
  20
  21 #include <boost/container/vector.hpp>
  22
  23 #include <errno.h>
  24 #include <fcntl.h>
  25 #include <limits.h>
  26 #include <syslog.h>
  27
  28 #include <algorithm>
  29 #include <iostream>
  30 #include <set>
  31
  32 #include <fmt/format.h>
  33 #include <fmt/ostream.h>
  34
  35 #define MAX_LOG_BUF 65536
  36
  37 namespace ceph {
  38 namespace logging {
  39
  40 static OnExitManager exit_callbacks;
  41
  42 static void log_on_exit(void *p)
  43 {
  44   Log *l = *(Log **)p;
  45   if (l)
  46     l->flush();
  47   delete (Log **)p;// Delete allocated pointer (not Log object, the pointer only!)
  48 }
  49
  50 Log::Log(const SubsystemMap *s)
  51   : m_indirect_this(nullptr),
  52     m_subs(s),
  53     m_recent(DEFAULT_MAX_RECENT)
  54 {
  55   m_log_buf.reserve(MAX_LOG_BUF);
  56   _configure_stderr();
  57 }
  58
  59 Log::~Log()
  60 {
  61   if (m_indirect_this) {
  62     *m_indirect_this = nullptr;
  63   }
  64
  65   ceph_assert(!is_started());
  66   if (m_fd >= 0) {
  67     VOID_TEMP_FAILURE_RETRY(::close(m_fd));
  68     m_fd = -1;
  69   }
  70 }
  71
  72 void Log::_configure_stderr()
  73 {
  74 #ifndef _WIN32
  75   struct stat info;
  76   if (int rc = fstat(m_fd_stderr, &info); rc == -1) {
  77     std::cerr << "failed to stat stderr: " << cpp_strerror(errno) << std::endl;
  78     return;
  79   }
  80
  81   if (S_ISFIFO(info.st_mode)) {
  82     /* Set O_NONBLOCK on FIFO stderr file. We want to ensure atomic debug log
  83      * writes so they do not get partially read by e.g. buggy container
  84      * runtimes. See also IEEE Std 1003.1-2017 and Log::_log_stderr below.
  85      *
  86      * This isn't required on Windows.
  87      */
  88     int flags = fcntl(m_fd_stderr, F_GETFL);
  89     if (flags == -1) {
  90       std::cerr << "failed to get fcntl flags for stderr: " << cpp_strerror(errno) << std::endl;
  91       return;
  92     }
  93     if (!(flags & O_NONBLOCK)) {
  94       flags |= O_NONBLOCK;
  95       flags = fcntl(m_fd_stderr, F_SETFL, flags);
  96       if (flags == -1) {
  97         std::cerr << "failed to set fcntl flags for stderr: " << cpp_strerror(errno) << std::endl;
  98         return;
  99       }
 100     }
 101     do_stderr_poll = true;
 102   }
 103 #endif // !_WIN32
 104 }
 105
 106
 107 ///
 108 void Log::set_coarse_timestamps(bool coarse) {
 109   std::scoped_lock lock(m_flush_mutex);
 110   if (coarse)
 111     Entry::clock().coarsen();
 112   else
 113     Entry::clock().refine();
 114 }
 115
 116 void Log::set_flush_on_exit()
 117 {
 118   std::scoped_lock lock(m_flush_mutex);
 119   // Make sure we flush on shutdown.  We do this by deliberately
 120   // leaking an indirect pointer to ourselves (on_exit() can't
 121   // unregister a callback).  This is not racy only becuase we
 122   // assume that exit() won't race with ~Log().
 123   if (m_indirect_this == NULL) {
 124     m_indirect_this = new (Log*)(this);
 125     exit_callbacks.add_callback(log_on_exit, m_indirect_this);
 126   }
 127 }
 128
 129 void Log::set_max_new(std::size_t n)
 130 {
 131   std::scoped_lock lock(m_queue_mutex);
 132   m_max_new = n;
 133 }
 134
 135 void Log::set_max_recent(std::size_t n)
 136 {
 137   std::scoped_lock lock(m_flush_mutex);
 138   m_recent.set_capacity(n);
 139 }
 140
 141 void Log::set_log_file(std::string_view fn)
 142 {
 143   std::scoped_lock lock(m_flush_mutex);
 144   m_log_file = fn;
 145 }
 146
 147 void Log::set_log_stderr_prefix(std::string_view p)
 148 {
 149   std::scoped_lock lock(m_flush_mutex);
 150   m_log_stderr_prefix = p;
 151 }
 152
 153 void Log::reopen_log_file()
 154 {
 155   std::scoped_lock lock(m_flush_mutex);
 156   if (!is_started()) {
 157     return;
 158   }
 159   m_flush_mutex_holder = pthread_self();
 160   if (m_fd >= 0) {
 161     VOID_TEMP_FAILURE_RETRY(::close(m_fd));
 162     m_fd = -1;
 163   }
 164   if (m_log_file.length()) {
 165     m_fd = ::open(m_log_file.c_str(), O_CREAT|O_WRONLY|O_APPEND|O_CLOEXEC, 0644);
 166     if (m_fd >= 0 && (m_uid || m_gid)) {
 167       if (::fchown(m_fd, m_uid, m_gid) < 0) {
 168         int e = errno;
 169         std::cerr << "failed to chown " << m_log_file << ": " << cpp_strerror(e)
 170              << std::endl;
 171       }
 172     }
 173   }
 174   m_flush_mutex_holder = 0;
 175 }
 176
 177 void Log::chown_log_file(uid_t uid, gid_t gid)
 178 {
 179   std::scoped_lock lock(m_flush_mutex);
 180   if (m_fd >= 0) {
 181     int r = ::fchown(m_fd, uid, gid);
 182     if (r < 0) {
 183       r = -errno;
 184       std::cerr << "failed to chown " << m_log_file << ": " << cpp_strerror(r)
 185            << std::endl;
 186     }
 187   }
 188 }
 189
 190 void Log::set_syslog_level(int log, int crash)
 191 {
 192   std::scoped_lock lock(m_flush_mutex);
 193   m_syslog_log = log;
 194   m_syslog_crash = crash;
 195 }
 196
 197 void Log::set_stderr_level(int log, int crash)
 198 {
 199   std::scoped_lock lock(m_flush_mutex);
 200   m_stderr_log = log;
 201   m_stderr_crash = crash;
 202 }
 203
 204 void Log::set_graylog_level(int log, int crash)
 205 {
 206   std::scoped_lock lock(m_flush_mutex);
 207   m_graylog_log = log;
 208   m_graylog_crash = crash;
 209 }
 210
 211 void Log::start_graylog(const std::string& host,
 212                         const uuid_d& fsid)
 213 {
 214   std::scoped_lock lock(m_flush_mutex);
 215   if (! m_graylog.get()) {
 216     m_graylog = std::make_shared<Graylog>(m_subs, "dlog");
 217     m_graylog->set_hostname(host);
 218     m_graylog->set_fsid(fsid);
 219   }
 220 }
 221
 222
 223 void Log::stop_graylog()
 224 {
 225   std::scoped_lock lock(m_flush_mutex);
 226   m_graylog.reset();
 227 }
 228
 229 void Log::set_journald_level(int log, int crash)
 230 {
 231   std::scoped_lock lock(m_flush_mutex);
 232   m_journald_log = log;
 233   m_journald_crash = crash;
 234 }
 235
 236 void Log::start_journald_logger()
 237 {
 238   std::scoped_lock lock(m_flush_mutex);
 239   if (!m_journald) {
 240     m_journald = std::make_unique<JournaldLogger>(m_subs);
 241   }
 242 }
 243
 244 void Log::stop_journald_logger()
 245 {
 246   std::scoped_lock lock(m_flush_mutex);
 247   m_journald.reset();
 248 }
 249
 250 void Log::submit_entry(Entry&& e)
 251 {
 252   std::unique_lock lock(m_queue_mutex);
 253   m_queue_mutex_holder = pthread_self();
 254
 255   if (unlikely(m_inject_segv))
 256     *(volatile int *)(0) = 0xdead;
 257
 258   // wait for flush to catch up
 259   while (is_started() &&
 260          m_new.size() > m_max_new) {
 261     if (m_stop) break; // force addition
 262     m_cond_loggers.wait(lock);
 263   }
 264
 265   m_new.emplace_back(std::move(e));
 266   m_cond_flusher.notify_all();
 267   m_queue_mutex_holder = 0;
 268 }
 269
 270 void Log::flush()
 271 {
 272   std::scoped_lock lock1(m_flush_mutex);
 273   m_flush_mutex_holder = pthread_self();
 274
 275   {
 276     std::scoped_lock lock2(m_queue_mutex);
 277     m_queue_mutex_holder = pthread_self();
 278     assert(m_flush.empty());
 279     m_flush.swap(m_new);
 280     m_cond_loggers.notify_all();
 281     m_queue_mutex_holder = 0;
 282   }
 283
 284   _flush(m_flush, false);
 285   m_flush_mutex_holder = 0;
 286 }
 287
 288 void Log::_log_safe_write(std::string_view sv)
 289 {
 290   if (m_fd < 0)
 291     return;
 292   int r = safe_write(m_fd, sv.data(), sv.size());
 293   if (r != m_fd_last_error) {
 294     if (r < 0)
 295       std::cerr << "problem writing to " << m_log_file
 296            << ": " << cpp_strerror(r)
 297            << std::endl;
 298     m_fd_last_error = r;
 299   }
 300 }
 301
 302 void Log::set_stderr_fd(int fd)
 303 {
 304   m_fd_stderr = fd;
 305   _configure_stderr();
 306 }
 307
 308 void Log::_log_stderr(std::string_view strv)
 309 {
 310   if (do_stderr_poll) {
 311     auto& prefix = m_log_stderr_prefix;
 312     size_t const len = prefix.size() + strv.size();
 313     boost::container::small_vector<char, PIPE_BUF> buf;
 314     buf.resize(len+1, '\0');
 315     memcpy(buf.data(), prefix.c_str(), prefix.size());
 316     memcpy(buf.data()+prefix.size(), strv.data(), strv.size());
 317
 318     char const* const start = buf.data();
 319     char const* current = start;
 320     while ((size_t)(current-start) < len) {
 321       auto chunk = std::min<ssize_t>(PIPE_BUF, len-(ssize_t)(current-start));
 322       while (1) {
 323         ssize_t rc = write(m_fd_stderr, current, chunk);
 324         if (rc == chunk) {
 325           current += chunk;
 326           break;
 327         } else if (rc > 0) {
 328           /* According to IEEE Std 1003.1-2017, this cannot happen:
 329            *
 330            * Write requests to a pipe or FIFO shall be handled in the same way as a regular file with the following exceptions:
 331            * ...
 332            *   If the O_NONBLOCK flag is set ...
 333            *   ...
 334            *     A write request for {PIPE_BUF} or fewer bytes shall have the
 335            *     following effect: if there is sufficient space available in
 336            *     the pipe, write() shall transfer all the data and return the
 337            *     number of bytes requested. Otherwise, write() shall transfer
 338            *     no data and return -1 with errno set to [EAGAIN].
 339            *
 340            * In any case, handle misbehavior gracefully by incrementing current.
 341            */
 342           current += rc;
 343           break;
 344         } else if (rc == -1) {
 345           if (errno == EAGAIN) {
 346             struct pollfd pfd[1];
 347             pfd[0].fd = m_fd_stderr;
 348             pfd[0].events = POLLOUT;
 349             poll(pfd, 1, -1);
 350             /* ignore errors / success, just retry the write */
 351           } else if (errno == EINTR) {
 352             continue;
 353           } else {
 354             /* some other kind of error, no point logging if stderr writes fail */
 355             return;
 356           }
 357         }
 358       }
 359     }
 360   } else {
 361     fmt::print(std::cerr, "{}{}", m_log_stderr_prefix, strv);
 362   }
 363 }
 364
 365 void Log::_flush_logbuf()
 366 {
 367   if (m_log_buf.size()) {
 368     _log_safe_write(std::string_view(m_log_buf.data(), m_log_buf.size()));
 369     m_log_buf.resize(0);
 370   }
 371 }
 372
 373 void Log::_flush(EntryVector& t, bool crash)
 374 {
 375   long len = 0;
 376   if (t.empty()) {
 377     assert(m_log_buf.empty());
 378     return;
 379   }
 380   if (crash) {
 381     len = t.size();
 382   }
 383   for (auto& e : t) {
 384     auto prio = e.m_prio;
 385     auto stamp = e.m_stamp;
 386     auto sub = e.m_subsys;
 387     auto thread = e.m_thread;
 388     auto str = e.strv();
 389
 390     bool should_log = crash || m_subs->get_log_level(sub) >= prio;
 391     bool do_fd = m_fd >= 0 && should_log;
 392     bool do_syslog = m_syslog_crash >= prio && should_log;
 393     bool do_stderr = m_stderr_crash >= prio && should_log;
 394     bool do_graylog2 = m_graylog_crash >= prio && should_log;
 395     bool do_journald = m_journald_crash >= prio && should_log;
 396
 397     if (do_fd || do_syslog || do_stderr) {
 398       const std::size_t cur = m_log_buf.size();
 399       std::size_t used = 0;
 400       const std::size_t allocated = e.size() + 80;
 401       m_log_buf.resize(cur + allocated);
 402
 403       char* const start = m_log_buf.data();
 404       char* pos = start + cur;
 405
 406       if (crash) {
 407         used += (std::size_t)snprintf(pos + used, allocated - used, "%6ld> ", -(--len));
 408       }
 409       used += (std::size_t)append_time(stamp, pos + used, allocated - used);
 410       used += (std::size_t)snprintf(pos + used, allocated - used, " %lx %2d ", (unsigned long)thread, prio);
 411       memcpy(pos + used, str.data(), str.size());
 412       used += str.size();
 413       pos[used] = '\0';
 414       ceph_assert((used + 1 /* '\n' */) < allocated);
 415
 416       if (do_syslog) {
 417         syslog(LOG_USER|LOG_INFO, "%s", pos);
 418       }
 419
 420       /* now add newline */
 421       pos[used++] = '\n';
 422
 423       if (do_stderr) {
 424         _log_stderr(std::string_view(pos, used));
 425       }
 426
 427       if (do_fd) {
 428         m_log_buf.resize(cur + used);
 429       } else {
 430         m_log_buf.resize(0);
 431       }
 432
 433       if (m_log_buf.size() > MAX_LOG_BUF) {
 434         _flush_logbuf();
 435       }
 436     }
 437
 438     if (do_graylog2 && m_graylog) {
 439       m_graylog->log_entry(e);
 440     }
 441
 442     if (do_journald && m_journald) {
 443       m_journald->log_entry(e);
 444     }
 445
 446     m_recent.push_back(std::move(e));
 447   }
 448   t.clear();
 449
 450   _flush_logbuf();
 451 }
 452
 453 void Log::_log_message(std::string_view s, bool crash)
 454 {
 455   if (m_fd >= 0) {
 456     std::string b = fmt::format("{}\n", s);
 457     int r = safe_write(m_fd, b.data(), b.size());
 458     if (r < 0)
 459       std::cerr << "problem writing to " << m_log_file << ": " << cpp_strerror(r) << std::endl;
 460   }
 461   if ((crash ? m_syslog_crash : m_syslog_log) >= 0) {
 462     syslog(LOG_USER|LOG_INFO, "%.*s", static_cast<int>(s.size()), s.data());
 463   }
 464
 465   if ((crash ? m_stderr_crash : m_stderr_log) >= 0) {
 466     std::cerr << s << std::endl;
 467   }
 468 }
 469
 470 template<typename T>
 471 static uint64_t tid_to_int(T tid)
 472 {
 473   if constexpr (std::is_pointer_v<T>) {
 474     return reinterpret_cast<std::uintptr_t>(tid);
 475   } else {
 476     return tid;
 477   }
 478 }
 479
 480 void Log::dump_recent()
 481 {
 482   std::scoped_lock lock1(m_flush_mutex);
 483   m_flush_mutex_holder = pthread_self();
 484
 485   {
 486     std::scoped_lock lock2(m_queue_mutex);
 487     m_queue_mutex_holder = pthread_self();
 488     assert(m_flush.empty());
 489     m_flush.swap(m_new);
 490     m_queue_mutex_holder = 0;
 491   }
 492
 493   _flush(m_flush, false);
 494
 495   _log_message("--- begin dump of recent events ---", true);
 496   std::set<pthread_t> recent_pthread_ids;
 497   {
 498     EntryVector t;
 499     t.insert(t.end(), std::make_move_iterator(m_recent.begin()), std::make_move_iterator(m_recent.end()));
 500     m_recent.clear();
 501     for (const auto& e : t) {
 502       recent_pthread_ids.emplace(e.m_thread);
 503     }
 504     _flush(t, true);
 505   }
 506
 507   _log_message("--- logging levels ---", true);
 508   for (const auto& p : m_subs->m_subsys) {
 509     _log_message(fmt::format("  {:2d}/{:2d} {}",
 510                              p.log_level, p.gather_level, p.name), true);
 511   }
 512   _log_message(fmt::format("  {:2d}/{:2d} (syslog threshold)",
 513                            m_syslog_log, m_syslog_crash), true);
 514   _log_message(fmt::format("  {:2d}/{:2d} (stderr threshold)",
 515                            m_stderr_log, m_stderr_crash), true);
 516
 517   _log_message("--- pthread ID / name mapping for recent threads ---", true);
 518   for (const auto pthread_id : recent_pthread_ids)
 519   {
 520     char pthread_name[16] = {0}; //limited by 16B include terminating null byte.
 521     ceph_pthread_getname(pthread_id, pthread_name, sizeof(pthread_name));
 522     // we want the ID to be printed in the same format as we use for a log entry.
 523     // The reason is easier grepping.
 524     _log_message(fmt::format("  {:x} / {}",
 525                              tid_to_int(pthread_id), pthread_name), true);
 526   }
 527
 528   _log_message(fmt::format("  max_recent {:9}", m_recent.capacity()), true);
 529   _log_message(fmt::format("  max_new    {:9}", m_max_new), true);
 530   _log_message(fmt::format("  log_file {}", m_log_file), true);
 531
 532   _log_message("--- end dump of recent events ---", true);
 533
 534   assert(m_log_buf.empty());
 535
 536   m_flush_mutex_holder = 0;
 537 }
 538
 539 void Log::start()
 540 {
 541   ceph_assert(!is_started());
 542   {
 543     std::scoped_lock lock(m_queue_mutex);
 544     m_stop = false;
 545   }
 546   create("log");
 547 }
 548
 549 void Log::stop()
 550 {
 551   if (is_started()) {
 552     {
 553       std::scoped_lock lock(m_queue_mutex);
 554       m_stop = true;
 555       m_cond_flusher.notify_one();
 556       m_cond_loggers.notify_all();
 557     }
 558     join();
 559   }
 560 }
 561
 562 void *Log::entry()
 563 {
 564   reopen_log_file();
 565   {
 566     std::unique_lock lock(m_queue_mutex);
 567     m_queue_mutex_holder = pthread_self();
 568     while (!m_stop) {
 569       if (!m_new.empty()) {
 570         m_queue_mutex_holder = 0;
 571         lock.unlock();
 572         flush();
 573         lock.lock();
 574         m_queue_mutex_holder = pthread_self();
 575         continue;
 576       }
 577
 578       m_cond_flusher.wait(lock);
 579     }
 580     m_queue_mutex_holder = 0;
 581   }
 582   flush();
 583   return NULL;
 584 }
 585
 586 bool Log::is_inside_log_lock()
 587 {
 588   return
 589     pthread_self() == m_queue_mutex_holder ||
 590     pthread_self() == m_flush_mutex_holder;
 591 }
 592
 593 void Log::inject_segv()
 594 {
 595   m_inject_segv = true;
 596 }
 597
 598 void Log::reset_segv()
 599 {
 600   m_inject_segv = false;
 601 }
 602
 603 } // ceph::logging::
 604 } // ceph::