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