diff options
Diffstat (limited to 'src/base/lnav_log.cc')
| -rw-r--r-- | src/base/lnav_log.cc | 671 |
1 files changed, 671 insertions, 0 deletions
diff --git a/src/base/lnav_log.cc b/src/base/lnav_log.cc new file mode 100644 index 0000000..c1b08c4 --- /dev/null +++ b/src/base/lnav_log.cc @@ -0,0 +1,671 @@ +/** + * Copyright (c) 2014, Timothy Stack + * + * All rights reserved. + * + * Redistribution and use in source and binary forms, with or without + * modification, are permitted provided that the following conditions are met: + * + * * Redistributions of source code must retain the above copyright notice, this + * list of conditions and the following disclaimer. + * * Redistributions in binary form must reproduce the above copyright notice, + * this list of conditions and the following disclaimer in the documentation + * and/or other materials provided with the distribution. + * * Neither the name of Timothy Stack nor the names of its contributors + * may be used to endorse or promote products derived from this software + * without specific prior written permission. + * + * THIS SOFTWARE IS PROVIDED BY THE REGENTS AND CONTRIBUTORS ''AS IS'' AND ANY + * EXPRESS OR IMPLIED WARRANTIES, INCLUDING, BUT NOT LIMITED TO, THE IMPLIED + * WARRANTIES OF MERCHANTABILITY AND FITNESS FOR A PARTICULAR PURPOSE ARE + * DISCLAIMED. IN NO EVENT SHALL THE REGENTS OR CONTRIBUTORS BE LIABLE FOR ANY + * DIRECT, INDIRECT, INCIDENTAL, SPECIAL, EXEMPLARY, OR CONSEQUENTIAL DAMAGES + * (INCLUDING, BUT NOT LIMITED TO, PROCUREMENT OF SUBSTITUTE GOODS OR SERVICES; + * LOSS OF USE, DATA, OR PROFITS; OR BUSINESS INTERRUPTION) HOWEVER CAUSED AND + * ON ANY THEORY OF LIABILITY, WHETHER IN CONTRACT, STRICT LIABILITY, OR TORT + * (INCLUDING NEGLIGENCE OR OTHERWISE) ARISING IN ANY WAY OUT OF THE USE OF THIS + * SOFTWARE, EVEN IF ADVISED OF THE POSSIBILITY OF SUCH DAMAGE. + * + * @file lnav_log.cc + */ + +#include <assert.h> +#include <ctype.h> +#include <fcntl.h> +#include <signal.h> +#include <stdarg.h> +#include <stdio.h> +#include <stdlib.h> +#include <string.h> +#include <sys/resource.h> +#include <termios.h> +#include <time.h> +#include <unistd.h> + +#include "config.h" + +#ifdef HAVE_EXECINFO_H +# include <execinfo.h> +#endif +#if BACKWARD_HAS_DW == 1 +# include "backward-cpp/backward.hpp" +#endif + +#include <algorithm> +#include <mutex> +#include <thread> +#include <vector> + +#define PCRE2_CODE_UNIT_WIDTH 8 +#include <pcre2.h> +#include <sys/param.h> +#include <sys/time.h> +#include <sys/types.h> +#include <sys/utsname.h> +#include <sys/wait.h> + +#if defined HAVE_NCURSESW_CURSES_H +# include <ncursesw/curses.h> +# include <ncursesw/termcap.h> +#elif defined HAVE_NCURSESW_H +# include <ncursesw.h> +# include <termcap.h> +#elif defined HAVE_NCURSES_CURSES_H +# include <ncurses/curses.h> +# include <ncurses/termcap.h> +#elif defined HAVE_NCURSES_H +# include <ncurses.h> +# include <termcap.h> +#elif defined HAVE_CURSES_H +# include <curses.h> +# include <termcap.h> +#else +# error "SysV or X/Open-compatible Curses header file required" +#endif + +#include "auto_mem.hh" +#include "enum_util.hh" +#include "lnav_log.hh" +#include "opt_util.hh" + +static const size_t BUFFER_SIZE = 256 * 1024; +static const size_t MAX_LOG_LINE_SIZE = 2 * 1024; + +static const char* CRASH_MSG + = "\n" + "\n" + "==== GURU MEDITATION ====\n" + "Unfortunately, lnav has crashed, sorry for the inconvenience.\n" + "\n" + "You can help improve lnav by sending the following file " + "to " PACKAGE_BUGREPORT + " :\n" + " %s\n" + "=========================\n"; + +nonstd::optional<FILE*> lnav_log_file; +lnav_log_level_t lnav_log_level = lnav_log_level_t::DEBUG; +const char* lnav_log_crash_dir; +nonstd::optional<const struct termios*> lnav_log_orig_termios; +// NOTE: This mutex is leaked so that it is not destroyed during exit. +// Otherwise, any attempts to log will fail. +static std::mutex* +lnav_log_mutex() +{ + static auto* retval = new std::mutex(); + + return retval; +} + +static std::vector<log_state_dumper*>& +DUMPER_LIST() +{ + static auto* retval = new std::vector<log_state_dumper*>(); + + return *retval; +} +static std::vector<log_crash_recoverer*> CRASH_LIST; + +struct thid { + static uint32_t COUNTER; + + thid() noexcept : t_id(COUNTER++) {} + + uint32_t t_id; +}; + +uint32_t thid::COUNTER = 0; + +thread_local thid current_thid; +thread_local std::string thread_log_prefix; + +static struct { + size_t lr_length; + off_t lr_frag_start; + off_t lr_frag_end; + char lr_data[BUFFER_SIZE]; +} log_ring = {0, BUFFER_SIZE, 0, {}}; + +static const char* LEVEL_NAMES[] = { + "T", + "D", + "I", + "W", + "E", +}; + +static char* +log_alloc() +{ + off_t data_end = log_ring.lr_length + MAX_LOG_LINE_SIZE; + + if (data_end >= (off_t) BUFFER_SIZE) { + const char* new_start = &log_ring.lr_data[MAX_LOG_LINE_SIZE]; + + new_start = (const char*) memchr( + new_start, '\n', log_ring.lr_length - MAX_LOG_LINE_SIZE); + log_ring.lr_frag_start = new_start - log_ring.lr_data; + log_ring.lr_frag_end = log_ring.lr_length; + log_ring.lr_length = 0; + + assert(log_ring.lr_frag_start >= 0); + assert(log_ring.lr_frag_start <= (off_t) BUFFER_SIZE); + } else if (data_end >= log_ring.lr_frag_start) { + const char* new_start = &log_ring.lr_data[log_ring.lr_frag_start]; + + new_start = (const char*) memchr( + new_start, '\n', log_ring.lr_frag_end - log_ring.lr_frag_start); + assert(new_start != nullptr); + log_ring.lr_frag_start = new_start - log_ring.lr_data; + assert(log_ring.lr_frag_start >= 0); + assert(log_ring.lr_frag_start <= (off_t) BUFFER_SIZE); + } + + return &log_ring.lr_data[log_ring.lr_length]; +} + +void +log_argv(int argc, char* argv[]) +{ + const char* log_path = getenv("LNAV_LOG_PATH"); + + if (log_path != nullptr) { + lnav_log_file = make_optional_from_nullable(fopen(log_path, "a")); + } + + log_info("argv[%d] =", argc); + for (int lpc = 0; lpc < argc; lpc++) { + log_info(" [%d] = %s", lpc, argv[lpc]); + } +} + +void +log_set_thread_prefix(std::string prefix) +{ + // thread_log_prefix = std::move(prefix); +} + +void +log_host_info() +{ + char cwd[MAXPATHLEN]; + char jittarget[128]; + struct utsname un; + struct rusage ru; + uint32_t pcre_jit; + + uname(&un); + pcre2_config(PCRE2_CONFIG_JIT, &pcre_jit); + pcre2_config(PCRE2_CONFIG_JITTARGET, jittarget); + + log_info("uname:"); + log_info(" sysname=%s", un.sysname); + log_info(" nodename=%s", un.nodename); + log_info(" machine=%s", un.machine); + log_info(" release=%s", un.release); + log_info(" version=%s", un.version); + log_info("PCRE:"); + log_info(" jit=%d", pcre_jit); + log_info(" jittarget=%s", jittarget); + log_info("Environment:"); + log_info(" HOME=%s", getenv("HOME")); + log_info(" XDG_CONFIG_HOME=%s", getenv("XDG_CONFIG_HOME")); + log_info(" LANG=%s", getenv("LANG")); + log_info(" PATH=%s", getenv("PATH")); + log_info(" TERM=%s", getenv("TERM")); + log_info(" TZ=%s", getenv("TZ")); + log_info("Process:"); + log_info(" pid=%d", getpid()); + log_info(" ppid=%d", getppid()); + log_info(" pgrp=%d", getpgrp()); + log_info(" uid=%d", getuid()); + log_info(" gid=%d", getgid()); + log_info(" euid=%d", geteuid()); + log_info(" egid=%d", getegid()); + if (getcwd(cwd, sizeof(cwd)) == nullptr) { + log_info(" ERROR: getcwd failed"); + } else { + log_info(" cwd=%s", cwd); + } + log_info("Executable:"); + log_info(" version=%s", VCS_PACKAGE_STRING); + + getrusage(RUSAGE_SELF, &ru); + log_rusage(lnav_log_level_t::INFO, ru); +} + +void +log_rusage_raw(enum lnav_log_level_t level, + const char* src_file, + int line_number, + const struct rusage& ru) +{ + log_msg(level, src_file, line_number, "rusage:"); + log_msg(level, + src_file, + line_number, + " utime=%d.%06d", + ru.ru_utime.tv_sec, + ru.ru_utime.tv_usec); + log_msg(level, + src_file, + line_number, + " stime=%d.%06d", + ru.ru_stime.tv_sec, + ru.ru_stime.tv_usec); + log_msg(level, src_file, line_number, " maxrss=%ld", ru.ru_maxrss); + log_msg(level, src_file, line_number, " ixrss=%ld", ru.ru_ixrss); + log_msg(level, src_file, line_number, " idrss=%ld", ru.ru_idrss); + log_msg(level, src_file, line_number, " isrss=%ld", ru.ru_isrss); + log_msg(level, src_file, line_number, " minflt=%ld", ru.ru_minflt); + log_msg(level, src_file, line_number, " majflt=%ld", ru.ru_majflt); + log_msg(level, src_file, line_number, " nswap=%ld", ru.ru_nswap); + log_msg(level, src_file, line_number, " inblock=%ld", ru.ru_inblock); + log_msg(level, src_file, line_number, " oublock=%ld", ru.ru_oublock); + log_msg(level, src_file, line_number, " msgsnd=%ld", ru.ru_msgsnd); + log_msg(level, src_file, line_number, " msgrcv=%ld", ru.ru_msgrcv); + log_msg(level, src_file, line_number, " nsignals=%ld", ru.ru_nsignals); + log_msg(level, src_file, line_number, " nvcsw=%ld", ru.ru_nvcsw); + log_msg(level, src_file, line_number, " nivcsw=%ld", ru.ru_nivcsw); +} + +void +log_msg(lnav_log_level_t level, + const char* src_file, + int line_number, + const char* fmt, + ...) +{ + struct timeval curr_time; + struct tm localtm; + ssize_t prefix_size; + va_list args; + ssize_t rc; + + if (level < lnav_log_level) { + return; + } + + std::lock_guard<std::mutex> log_lock(*lnav_log_mutex()); + + { + // get the base name of the file. NB: can't use basename() since it + // can modify its argument + const char* last_slash = src_file; + + for (int lpc = 0; src_file[lpc]; lpc++) { + if (src_file[lpc] == '/' || src_file[lpc] == '\\') { + last_slash = &src_file[lpc + 1]; + } + } + + src_file = last_slash; + } + + va_start(args, fmt); + gettimeofday(&curr_time, nullptr); + localtime_r(&curr_time.tv_sec, &localtm); + auto line = log_alloc(); + prefix_size = snprintf(line, + MAX_LOG_LINE_SIZE, + "%4d-%02d-%02dT%02d:%02d:%02d.%03d %s t%u %s:%d ", + localtm.tm_year + 1900, + localtm.tm_mon + 1, + localtm.tm_mday, + localtm.tm_hour, + localtm.tm_min, + localtm.tm_sec, + (int) (curr_time.tv_usec / 1000), + LEVEL_NAMES[lnav::enums::to_underlying(level)], + current_thid.t_id, + src_file, + line_number); +#if 0 + if (!thread_log_prefix.empty()) { + prefix_size += snprintf( + &line[prefix_size], MAX_LOG_LINE_SIZE - prefix_size, + "%s ", + thread_log_prefix.c_str()); + } +#endif + rc = vsnprintf( + &line[prefix_size], MAX_LOG_LINE_SIZE - prefix_size, fmt, args); + if (rc >= (ssize_t) (MAX_LOG_LINE_SIZE - prefix_size)) { + rc = MAX_LOG_LINE_SIZE - prefix_size - 1; + } + line[prefix_size + rc] = '\n'; + log_ring.lr_length += prefix_size + rc + 1; + lnav_log_file | [&](auto file) { + fwrite(line, 1, prefix_size + rc + 1, file); + fflush(file); + }; + va_end(args); +} + +void +log_msg_extra(const char* fmt, ...) +{ + std::lock_guard<std::mutex> mg(*lnav_log_mutex()); + va_list args; + + va_start(args, fmt); + auto line = log_alloc(); + auto rc = vsnprintf(line, MAX_LOG_LINE_SIZE - 1, fmt, args); + log_ring.lr_length += rc; + lnav_log_file | [&](auto file) { + fwrite(line, 1, rc, file); + fflush(file); + }; + va_end(args); +} + +void +log_msg_extra_complete() +{ + std::lock_guard<std::mutex> mg(*lnav_log_mutex()); + auto line = log_alloc(); + line[0] = '\n'; + log_ring.lr_length += 1; + lnav_log_file | [&](auto file) { + fwrite(line, 1, 1, file); + fflush(file); + }; +} + +#pragma GCC diagnostic push +#pragma GCC diagnostic ignored "-Wunused-result" +static void +sigabrt(int sig, siginfo_t* info, void* ctx) +{ + char crash_path[1024], latest_crash_path[1024]; + int fd; +#ifdef HAVE_EXECINFO_H + int frame_count; + void* frames[128]; +#endif + struct tm localtm; + time_t curr_time; + + if (lnav_log_crash_dir == nullptr) { + printf("%*s", (int) log_ring.lr_length, log_ring.lr_data); + return; + } + + log_error("Received signal: %d", sig); + +#ifdef HAVE_EXECINFO_H + frame_count = backtrace(frames, 128); +#endif + curr_time = time(nullptr); + localtime_r(&curr_time, &localtm); + snprintf(crash_path, + sizeof(crash_path), + "%s/crash-%4d-%02d-%02d-%02d-%02d-%02d.%d.log", + lnav_log_crash_dir, + localtm.tm_year + 1900, + localtm.tm_mon + 1, + localtm.tm_mday, + localtm.tm_hour, + localtm.tm_min, + localtm.tm_sec, + getpid()); + snprintf(latest_crash_path, + sizeof(latest_crash_path), + "%s/latest-crash.log", + lnav_log_crash_dir); + if ((fd = open(crash_path, O_CREAT | O_TRUNC | O_RDWR, 0600)) != -1) { + if (log_ring.lr_frag_start < (off_t) BUFFER_SIZE) { + (void) write(fd, + &log_ring.lr_data[log_ring.lr_frag_start], + log_ring.lr_frag_end - log_ring.lr_frag_start); + } + (void) write(fd, log_ring.lr_data, log_ring.lr_length); +#ifdef HAVE_EXECINFO_H + backtrace_symbols_fd(frames, frame_count, fd); +#endif +#if BACKWARD_HAS_DW == 1 + { + ucontext_t* uctx = static_cast<ucontext_t*>(ctx); + void* error_addr = nullptr; + +# ifdef REG_RIP // x86_64 + error_addr + = reinterpret_cast<void*>(uctx->uc_mcontext.gregs[REG_RIP]); +# elif defined(REG_EIP) // x86_32 + error_addr + = reinterpret_cast<void*>(uctx->uc_mcontext.gregs[REG_EIP]); +# endif + + backward::StackTrace st; + + if (error_addr) { + st.load_from(error_addr, + 32, + reinterpret_cast<void*>(uctx), + info->si_addr); + } else { + st.load_here(32, reinterpret_cast<void*>(uctx), info->si_addr); + } + backward::TraceResolver tr; + + tr.load_stacktrace(st); + for (size_t lpc = 0; lpc < st.size(); lpc++) { + auto trace = tr.resolve(st[lpc]); + char buf[1024]; + + snprintf(buf, + sizeof(buf), + "Frame %lu:%s:%s (%s:%d)\n", + lpc, + trace.object_filename.c_str(), + trace.object_function.c_str(), + trace.source.filename.c_str(), + trace.source.line); + write(fd, buf, strlen(buf)); + } + } +#endif + log_ring.lr_length = 0; + log_ring.lr_frag_start = BUFFER_SIZE; + log_ring.lr_frag_end = 0; + + log_host_info(); + + for (auto lsd : DUMPER_LIST()) { + lsd->log_state(); + } + + if (log_ring.lr_frag_start < (off_t) BUFFER_SIZE) { + write(fd, + &log_ring.lr_data[log_ring.lr_frag_start], + log_ring.lr_frag_end - log_ring.lr_frag_start); + } + write(fd, log_ring.lr_data, log_ring.lr_length); + if (getenv("DUMP_CRASH") != nullptr) { + char buffer[1024]; + int rc; + + lseek(fd, 0, SEEK_SET); + while ((rc = read(fd, buffer, sizeof(buffer))) > 0) { + write(STDERR_FILENO, buffer, rc); + } + } + close(fd); + + remove(latest_crash_path); + symlink(crash_path, latest_crash_path); + } + + lnav_log_orig_termios | [](auto termios) { + for (auto lcr : CRASH_LIST) { + lcr->log_crash_recover(); + } + + tcsetattr(STDOUT_FILENO, TCSAFLUSH, termios); + dup2(STDOUT_FILENO, STDERR_FILENO); + }; + fprintf(stderr, CRASH_MSG, crash_path); + +#ifndef ATTACH_ON_SIGNAL + if (isatty(STDIN_FILENO)) { + char response; + + fprintf(stderr, "\nWould you like to attach a debugger? (y/N) "); + fflush(stderr); + + if (scanf("%c", &response) > 0 && tolower(response) == 'y') { + pid_t lnav_pid = getpid(); + pid_t child_pid; + + switch ((child_pid = fork())) { + case 0: { + char pid_str[32]; + + snprintf(pid_str, sizeof(pid_str), "--pid=%d", lnav_pid); + execlp("gdb", "gdb", pid_str, nullptr); + + snprintf(pid_str, sizeof(pid_str), "%d", lnav_pid); + execlp("lldb", "lldb", "--attach-pid", pid_str, nullptr); + + fprintf(stderr, "Could not attach gdb or lldb, exiting.\n"); + _exit(1); + break; + } + + case -1: { + break; + } + + default: { + int status; + + while (wait(&status) < 0) { + } + break; + } + } + } + } +#endif + + _exit(1); +} +#pragma GCC diagnostic pop + +void +log_install_handlers() +{ + const size_t stack_size = 8 * 1024 * 1024; + const int sigs[] = { + SIGABRT, + SIGSEGV, + SIGBUS, + SIGILL, + SIGFPE, + }; + static auto_mem<void> stack_content; + + stack_t ss; + + stack_content = malloc(stack_size); + ss.ss_sp = stack_content; + ss.ss_size = stack_size; + ss.ss_flags = 0; + sigaltstack(&ss, nullptr); + for (const auto sig : sigs) { + struct sigaction sa; + + memset(&sa, 0, sizeof(sa)); + sa.sa_flags = SA_SIGINFO | SA_ONSTACK | SA_NODEFER | SA_RESETHAND; + sigfillset(&sa.sa_mask); + sigdelset(&sa.sa_mask, sig); + sa.sa_sigaction = sigabrt; + + sigaction(sig, &sa, nullptr); + } +} + +void +log_abort() +{ + raise(SIGABRT); + _exit(1); +} + +void +log_pipe_err(int fd) +{ + std::thread reader([fd]() { + char buffer[1024]; + bool done = false; + + while (!done) { + int rc = read(fd, buffer, sizeof(buffer)); + + switch (rc) { + case -1: + case 0: + done = true; + break; + default: + while (buffer[rc - 1] == '\n' || buffer[rc - 1] == '\r') { + rc -= 1; + } + + log_error("%.*s", rc, buffer); + break; + } + } + + close(fd); + }); + + reader.detach(); +} + +log_state_dumper::log_state_dumper() +{ + DUMPER_LIST().push_back(this); +} + +log_state_dumper::~log_state_dumper() +{ + auto iter = std::find(DUMPER_LIST().begin(), DUMPER_LIST().end(), this); + if (iter != DUMPER_LIST().end()) { + DUMPER_LIST().erase(iter); + } +} + +log_crash_recoverer::log_crash_recoverer() +{ + CRASH_LIST.push_back(this); +} + +log_crash_recoverer::~log_crash_recoverer() +{ + auto iter = std::find(CRASH_LIST.begin(), CRASH_LIST.end(), this); + + if (iter != CRASH_LIST.end()) { + CRASH_LIST.erase(iter); + } +} |