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/valgrind.h"
  10
  11 #include "include/ceph_assert.h"
  12 #include "include/compat.h"
  13 #include "include/on_exit.h"
  14
  15 #include "Entry.h"
  16 #include "LogClock.h"
  17 #include "SubsystemMap.h"
  18
  19 #include <errno.h>
  20 #include <fcntl.h>
  21 #include <syslog.h>
  22
  23 #include <iostream>
  24 #include <set>
  25
  26 #define MAX_LOG_BUF 65536
  27
  28 namespace ceph {
  29 namespace logging {
  30
  31 static OnExitManager exit_callbacks;
  32
  33 static void log_on_exit(void *p)
  34 {
  35   Log *l = *(Log **)p;
  36   if (l)
  37     l->flush();
  38   delete (Log **)p;// Delete allocated pointer (not Log object, the pointer only!)
  39 }
  40
  41 Log::Log(const SubsystemMap *s)
  42   : m_indirect_this(nullptr),
  43     m_subs(s),
  44     m_recent(DEFAULT_MAX_RECENT)
  45 {
  46   m_log_buf.reserve(MAX_LOG_BUF);
  47 }
  48
  49 Log::~Log()
  50 {
  51   if (m_indirect_this) {
  52     *m_indirect_this = nullptr;
  53   }
  54
  55   ceph_assert(!is_started());
  56   if (m_fd >= 0)
  57     VOID_TEMP_FAILURE_RETRY(::close(m_fd));
  58 }
  59
  60
  61 ///
  62 void Log::set_coarse_timestamps(bool coarse) {
  63   std::scoped_lock lock(m_flush_mutex);
  64   if (coarse)
  65     clock.coarsen();
  66   else
  67     clock.refine();
  68 }
  69
  70 void Log::set_flush_on_exit()
  71 {
  72   std::scoped_lock lock(m_flush_mutex);
  73   // Make sure we flush on shutdown.  We do this by deliberately
  74   // leaking an indirect pointer to ourselves (on_exit() can't
  75   // unregister a callback).  This is not racy only becuase we
  76   // assume that exit() won't race with ~Log().
  77   if (m_indirect_this == NULL) {
  78     m_indirect_this = new (Log*)(this);
  79     exit_callbacks.add_callback(log_on_exit, m_indirect_this);
  80   }
  81 }
  82
  83 void Log::set_max_new(std::size_t n)
  84 {
  85   std::scoped_lock lock(m_queue_mutex);
  86   m_max_new = n;
  87 }
  88
  89 void Log::set_max_recent(std::size_t n)
  90 {
  91   std::scoped_lock lock(m_flush_mutex);
  92   m_max_recent = n;
  93 }
  94
  95 void Log::set_log_file(std::string_view fn)
  96 {
  97   std::scoped_lock lock(m_flush_mutex);
  98   m_log_file = fn;
  99 }
 100
 101 void Log::set_log_stderr_prefix(std::string_view p)
 102 {
 103   std::scoped_lock lock(m_flush_mutex);
 104   m_log_stderr_prefix = p;
 105 }
 106
 107 void Log::reopen_log_file()
 108 {
 109   std::scoped_lock lock(m_flush_mutex);
 110   if (!is_started()) {
 111     return;
 112   }
 113   m_flush_mutex_holder = pthread_self();
 114   if (m_fd >= 0)
 115     VOID_TEMP_FAILURE_RETRY(::close(m_fd));
 116   if (m_log_file.length()) {
 117     m_fd = ::open(m_log_file.c_str(), O_CREAT|O_WRONLY|O_APPEND|O_CLOEXEC, 0644);
 118     if (m_fd >= 0 && (m_uid || m_gid)) {
 119       if (::fchown(m_fd, m_uid, m_gid) < 0) {
 120         int e = errno;
 121         std::cerr << "failed to chown " << m_log_file << ": " << cpp_strerror(e)
 122              << std::endl;
 123       }
 124     }
 125   } else {
 126     m_fd = -1;
 127   }
 128   m_flush_mutex_holder = 0;
 129 }
 130
 131 void Log::chown_log_file(uid_t uid, gid_t gid)
 132 {
 133   std::scoped_lock lock(m_flush_mutex);
 134   if (m_fd >= 0) {
 135     int r = ::fchown(m_fd, uid, gid);
 136     if (r < 0) {
 137       r = -errno;
 138       std::cerr << "failed to chown " << m_log_file << ": " << cpp_strerror(r)
 139            << std::endl;
 140     }
 141   }
 142 }
 143
 144 void Log::set_syslog_level(int log, int crash)
 145 {
 146   std::scoped_lock lock(m_flush_mutex);
 147   m_syslog_log = log;
 148   m_syslog_crash = crash;
 149 }
 150
 151 void Log::set_stderr_level(int log, int crash)
 152 {
 153   std::scoped_lock lock(m_flush_mutex);
 154   m_stderr_log = log;
 155   m_stderr_crash = crash;
 156 }
 157
 158 void Log::set_graylog_level(int log, int crash)
 159 {
 160   std::scoped_lock lock(m_flush_mutex);
 161   m_graylog_log = log;
 162   m_graylog_crash = crash;
 163 }
 164
 165 void Log::start_graylog()
 166 {
 167   std::scoped_lock lock(m_flush_mutex);
 168   if (! m_graylog.get())
 169     m_graylog = std::make_shared<Graylog>(m_subs, "dlog");
 170 }
 171
 172
 173 void Log::stop_graylog()
 174 {
 175   std::scoped_lock lock(m_flush_mutex);
 176   m_graylog.reset();
 177 }
 178
 179 void Log::submit_entry(Entry&& e)
 180 {
 181   std::unique_lock lock(m_queue_mutex);
 182   m_queue_mutex_holder = pthread_self();
 183
 184   if (unlikely(m_inject_segv))
 185     *(volatile int *)(0) = 0xdead;
 186
 187   // wait for flush to catch up
 188   while (is_started() &&
 189          m_new.size() > m_max_new) {
 190     if (m_stop) break; // force addition
 191     m_cond_loggers.wait(lock);
 192   }
 193
 194   m_new.emplace_back(std::move(e));
 195   m_cond_flusher.notify_all();
 196   m_queue_mutex_holder = 0;
 197 }
 198
 199 void Log::flush()
 200 {
 201   std::scoped_lock lock1(m_flush_mutex);
 202   m_flush_mutex_holder = pthread_self();
 203
 204   {
 205     std::scoped_lock lock2(m_queue_mutex);
 206     m_queue_mutex_holder = pthread_self();
 207     assert(m_flush.empty());
 208     m_flush.swap(m_new);
 209     m_cond_loggers.notify_all();
 210     m_queue_mutex_holder = 0;
 211   }
 212
 213   _flush(m_flush, false);
 214   m_flush_mutex_holder = 0;
 215 }
 216
 217 void Log::_log_safe_write(std::string_view sv)
 218 {
 219   if (m_fd < 0)
 220     return;
 221   int r = safe_write(m_fd, sv.data(), sv.size());
 222   if (r != m_fd_last_error) {
 223     if (r < 0)
 224       std::cerr << "problem writing to " << m_log_file
 225            << ": " << cpp_strerror(r)
 226            << std::endl;
 227     m_fd_last_error = r;
 228   }
 229 }
 230
 231 void Log::_flush_logbuf()
 232 {
 233   if (m_log_buf.size()) {
 234     _log_safe_write(std::string_view(m_log_buf.data(), m_log_buf.size()));
 235     m_log_buf.resize(0);
 236   }
 237 }
 238
 239 void Log::_flush(EntryVector& t, bool crash)
 240 {
 241   long len = 0;
 242   if (t.empty()) {
 243     assert(m_log_buf.empty());
 244     return;
 245   }
 246   if (crash) {
 247     len = t.size();
 248   }
 249   for (auto& e : t) {
 250     auto prio = e.m_prio;
 251     auto stamp = e.m_stamp;
 252     auto sub = e.m_subsys;
 253     auto thread = e.m_thread;
 254     auto str = e.strv();
 255
 256     bool should_log = crash || m_subs->get_log_level(sub) >= prio;
 257     bool do_fd = m_fd >= 0 && should_log;
 258     bool do_syslog = m_syslog_crash >= prio && should_log;
 259     bool do_stderr = m_stderr_crash >= prio && should_log;
 260     bool do_graylog2 = m_graylog_crash >= prio && should_log;
 261
 262     if (do_fd || do_syslog || do_stderr) {
 263       const std::size_t cur = m_log_buf.size();
 264       std::size_t used = 0;
 265       const std::size_t allocated = e.size() + 80;
 266       m_log_buf.resize(cur + allocated);
 267
 268       char* const start = m_log_buf.data();
 269       char* pos = start + cur;
 270
 271       if (crash) {
 272         used += (std::size_t)snprintf(pos + used, allocated - used, "%6ld> ", -(--len));
 273       }
 274       used += (std::size_t)append_time(stamp, pos + used, allocated - used);
 275       used += (std::size_t)snprintf(pos + used, allocated - used, " %lx %2d ", (unsigned long)thread, prio);
 276       memcpy(pos + used, str.data(), str.size());
 277       used += str.size();
 278       pos[used] = '\0';
 279       ceph_assert((used + 1 /* '\n' */) < allocated);
 280
 281       if (do_syslog) {
 282         syslog(LOG_USER|LOG_INFO, "%s", pos);
 283       }
 284
 285       if (do_stderr) {
 286         std::cerr << m_log_stderr_prefix << std::string_view(pos, used) << std::endl;
 287       }
 288
 289       /* now add newline */
 290       pos[used++] = '\n';
 291
 292       if (do_fd) {
 293         m_log_buf.resize(cur + used);
 294       } else {
 295         m_log_buf.resize(0);
 296       }
 297
 298       if (m_log_buf.size() > MAX_LOG_BUF) {
 299         _flush_logbuf();
 300       }
 301     }
 302
 303     if (do_graylog2 && m_graylog) {
 304       m_graylog->log_entry(e);
 305     }
 306
 307     m_recent.push_back(std::move(e));
 308   }
 309   t.clear();
 310
 311   _flush_logbuf();
 312 }
 313
 314 void Log::_log_message(const char *s, bool crash)
 315 {
 316   if (m_fd >= 0) {
 317     size_t len = strlen(s);
 318     std::string b;
 319     b.reserve(len + 1);
 320     b.append(s, len);
 321     b += '\n';
 322     int r = safe_write(m_fd, b.c_str(), b.size());
 323     if (r < 0)
 324       std::cerr << "problem writing to " << m_log_file << ": " << cpp_strerror(r) << std::endl;
 325   }
 326   if ((crash ? m_syslog_crash : m_syslog_log) >= 0) {
 327     syslog(LOG_USER|LOG_INFO, "%s", s);
 328   }
 329
 330   if ((crash ? m_stderr_crash : m_stderr_log) >= 0) {
 331     std::cerr << s << std::endl;
 332   }
 333 }
 334
 335 void Log::dump_recent()
 336 {
 337   std::scoped_lock lock1(m_flush_mutex);
 338   m_flush_mutex_holder = pthread_self();
 339
 340   {
 341     std::scoped_lock lock2(m_queue_mutex);
 342     m_queue_mutex_holder = pthread_self();
 343     assert(m_flush.empty());
 344     m_flush.swap(m_new);
 345     m_queue_mutex_holder = 0;
 346   }
 347
 348   _flush(m_flush, false);
 349
 350   _log_message("--- begin dump of recent events ---", true);
 351   std::set<pthread_t> recent_pthread_ids;
 352   {
 353     EntryVector t;
 354     t.insert(t.end(), std::make_move_iterator(m_recent.begin()), std::make_move_iterator(m_recent.end()));
 355     m_recent.clear();
 356     for (const auto& e : t) {
 357       recent_pthread_ids.emplace(e.m_thread);
 358     }
 359     _flush(t, true);
 360   }
 361
 362   char buf[4096];
 363   _log_message("--- logging levels ---", true);
 364   for (const auto& p : m_subs->m_subsys) {
 365     snprintf(buf, sizeof(buf), "  %2d/%2d %s", p.log_level, p.gather_level, p.name);
 366     _log_message(buf, true);
 367   }
 368   sprintf(buf, "  %2d/%2d (syslog threshold)", m_syslog_log, m_syslog_crash);
 369   _log_message(buf, true);
 370   sprintf(buf, "  %2d/%2d (stderr threshold)", m_stderr_log, m_stderr_crash);
 371   _log_message(buf, true);
 372
 373   _log_message("--- pthread ID / name mapping for recent threads ---", true);
 374   for (const auto pthread_id : recent_pthread_ids)
 375   {
 376     char pthread_name[16] = {0}; //limited by 16B include terminating null byte.
 377     ceph_pthread_getname(pthread_id, pthread_name, sizeof(pthread_name));
 378     snprintf(buf, sizeof(buf), "  %lx / %s", pthread_id, pthread_name);
 379     _log_message(buf, true);
 380   }
 381
 382   sprintf(buf, "  max_recent %9zu", m_max_recent);
 383   _log_message(buf, true);
 384   sprintf(buf, "  max_new    %9zu", m_max_new);
 385   _log_message(buf, true);
 386   sprintf(buf, "  log_file %s", m_log_file.c_str());
 387   _log_message(buf, true);
 388
 389   _log_message("--- end dump of recent events ---", true);
 390
 391   assert(m_log_buf.empty());
 392
 393   m_flush_mutex_holder = 0;
 394 }
 395
 396 void Log::start()
 397 {
 398   ceph_assert(!is_started());
 399   {
 400     std::scoped_lock lock(m_queue_mutex);
 401     m_stop = false;
 402   }
 403   create("log");
 404 }
 405
 406 void Log::stop()
 407 {
 408   if (is_started()) {
 409     {
 410       std::scoped_lock lock(m_queue_mutex);
 411       m_stop = true;
 412       m_cond_flusher.notify_one();
 413       m_cond_loggers.notify_all();
 414     }
 415     join();
 416   }
 417 }
 418
 419 void *Log::entry()
 420 {
 421   reopen_log_file();
 422   {
 423     std::unique_lock lock(m_queue_mutex);
 424     m_queue_mutex_holder = pthread_self();
 425     while (!m_stop) {
 426       if (!m_new.empty()) {
 427         m_queue_mutex_holder = 0;
 428         lock.unlock();
 429         flush();
 430         lock.lock();
 431         m_queue_mutex_holder = pthread_self();
 432         continue;
 433       }
 434
 435       m_cond_flusher.wait(lock);
 436     }
 437     m_queue_mutex_holder = 0;
 438   }
 439   flush();
 440   return NULL;
 441 }
 442
 443 bool Log::is_inside_log_lock()
 444 {
 445   return
 446     pthread_self() == m_queue_mutex_holder ||
 447     pthread_self() == m_flush_mutex_holder;
 448 }
 449
 450 void Log::inject_segv()
 451 {
 452   m_inject_segv = true;
 453 }
 454
 455 void Log::reset_segv()
 456 {
 457   m_inject_segv = false;
 458 }
 459
 460 } // ceph::logging::
 461 } // ceph::