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