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