src/journal/journald-kmsg.c

	journald-kmsg.c revision 07630cea1f3a845c09309f197ac7c4f11edd3b62
b5da077ddf01546c4a85688624d6957766d6c00cMichal Schmidt/*-*- Mode: C; c-basic-offset: 8; indent-tabs-mode: nil -*-*/
b5da077ddf01546c4a85688624d6957766d6c00cMichal Schmidt
b5da077ddf01546c4a85688624d6957766d6c00cMichal Schmidt/***
d710d36375bacbf9cfb8903107bedf2c0aada84eMichal Schmidt  This file is part of systemd.
b5da077ddf01546c4a85688624d6957766d6c00cMichal Schmidt
fff87a35d9e26c0d4ea41273a963c0eb20e18da4Zbigniew Jędrzejewski-Szmek  Copyright 2011 Lennart Poettering
b5da077ddf01546c4a85688624d6957766d6c00cMichal Schmidt
b5da077ddf01546c4a85688624d6957766d6c00cMichal Schmidt  systemd is free software; you can redistribute it and/or modify it
b5da077ddf01546c4a85688624d6957766d6c00cMichal Schmidt  under the terms of the GNU Lesser General Public License as published by
b5da077ddf01546c4a85688624d6957766d6c00cMichal Schmidt  the Free Software Foundation; either version 2.1 of the License, or
889a90422dd47284dffa32b9234a6e58991b000cRonny Chevalier  (at your option) any later version.
b5da077ddf01546c4a85688624d6957766d6c00cMichal Schmidt
b5da077ddf01546c4a85688624d6957766d6c00cMichal Schmidt  systemd is distributed in the hope that it will be useful, but
b5da077ddf01546c4a85688624d6957766d6c00cMichal Schmidt  WITHOUT ANY WARRANTY; without even the implied warranty of
b5da077ddf01546c4a85688624d6957766d6c00cMichal Schmidt  MERCHANTABILITY or FITNESS FOR A PARTICULAR PURPOSE. See the GNU
41a5ef639b248aa3d10609d9af5d0043b909d93cHarald Hoyer  Lesser General Public License for more details.
b5da077ddf01546c4a85688624d6957766d6c00cMichal Schmidt
b5da077ddf01546c4a85688624d6957766d6c00cMichal Schmidt  You should have received a copy of the GNU Lesser General Public License
41a5ef639b248aa3d10609d9af5d0043b909d93cHarald Hoyer  along with systemd; If not, see <http://www.gnu.org/licenses/>.
b5da077ddf01546c4a85688624d6957766d6c00cMichal Schmidt***/
b5da077ddf01546c4a85688624d6957766d6c00cMichal Schmidt
b5da077ddf01546c4a85688624d6957766d6c00cMichal Schmidt#include <fcntl.h>
b5da077ddf01546c4a85688624d6957766d6c00cMichal Schmidt#include <sys/epoll.h>
b5da077ddf01546c4a85688624d6957766d6c00cMichal Schmidt#include <sys/mman.h>
b5da077ddf01546c4a85688624d6957766d6c00cMichal Schmidt#include <sys/socket.h>
b5da077ddf01546c4a85688624d6957766d6c00cMichal Schmidt#include <unistd.h>
889a90422dd47284dffa32b9234a6e58991b000cRonny Chevalier
889a90422dd47284dffa32b9234a6e58991b000cRonny Chevalier#include "libudev.h"
b5da077ddf01546c4a85688624d6957766d6c00cMichal Schmidt#include "sd-messages.h"
b5da077ddf01546c4a85688624d6957766d6c00cMichal Schmidt
b5da077ddf01546c4a85688624d6957766d6c00cMichal Schmidt#include "escape.h"
b5da077ddf01546c4a85688624d6957766d6c00cMichal Schmidt#include "formats-util.h"
889a90422dd47284dffa32b9234a6e58991b000cRonny Chevalier#include "journald-server.h"
889a90422dd47284dffa32b9234a6e58991b000cRonny Chevalier#include "journald-syslog.h"
b5da077ddf01546c4a85688624d6957766d6c00cMichal Schmidt#include "process-util.h"
b5da077ddf01546c4a85688624d6957766d6c00cMichal Schmidt#include "string-util.h"
b5da077ddf01546c4a85688624d6957766d6c00cMichal Schmidt#include "journald-kmsg.h"
b5da077ddf01546c4a85688624d6957766d6c00cMichal Schmidt
b5da077ddf01546c4a85688624d6957766d6c00cMichal Schmidtvoid server_forward_kmsg(
b5da077ddf01546c4a85688624d6957766d6c00cMichal Schmidt        Server *s,
b5da077ddf01546c4a85688624d6957766d6c00cMichal Schmidt        int priority,
889a90422dd47284dffa32b9234a6e58991b000cRonny Chevalier        const char *identifier,
b5da077ddf01546c4a85688624d6957766d6c00cMichal Schmidt        const char *message,
b5da077ddf01546c4a85688624d6957766d6c00cMichal Schmidt        const struct ucred *ucred) {
b5da077ddf01546c4a85688624d6957766d6c00cMichal Schmidt
b5da077ddf01546c4a85688624d6957766d6c00cMichal Schmidt        struct iovec iovec[5];
b5da077ddf01546c4a85688624d6957766d6c00cMichal Schmidt        char header_priority[DECIMAL_STR_MAX(priority) + 3],
b5da077ddf01546c4a85688624d6957766d6c00cMichal Schmidt             header_pid[sizeof("[]: ")-1 + DECIMAL_STR_MAX(pid_t) + 1];
b5da077ddf01546c4a85688624d6957766d6c00cMichal Schmidt        int n = 0;
b5da077ddf01546c4a85688624d6957766d6c00cMichal Schmidt        char *ident_buf = NULL;
889a90422dd47284dffa32b9234a6e58991b000cRonny Chevalier
b5da077ddf01546c4a85688624d6957766d6c00cMichal Schmidt        assert(s);
b5da077ddf01546c4a85688624d6957766d6c00cMichal Schmidt        assert(priority >= 0);
b5da077ddf01546c4a85688624d6957766d6c00cMichal Schmidt        assert(priority <= 999);
b5da077ddf01546c4a85688624d6957766d6c00cMichal Schmidt        assert(message);
b5da077ddf01546c4a85688624d6957766d6c00cMichal Schmidt
b5da077ddf01546c4a85688624d6957766d6c00cMichal Schmidt        if (_unlikely_(LOG_PRI(priority) > s->max_level_kmsg))
b5da077ddf01546c4a85688624d6957766d6c00cMichal Schmidt                return;
b5da077ddf01546c4a85688624d6957766d6c00cMichal Schmidt
b5da077ddf01546c4a85688624d6957766d6c00cMichal Schmidt        if (_unlikely_(s->dev_kmsg_fd < 0))
b5da077ddf01546c4a85688624d6957766d6c00cMichal Schmidt                return;
b5da077ddf01546c4a85688624d6957766d6c00cMichal Schmidt
b5da077ddf01546c4a85688624d6957766d6c00cMichal Schmidt        /* Never allow messages with kernel facility to be written to
b5da077ddf01546c4a85688624d6957766d6c00cMichal Schmidt         * kmsg, regardless where the data comes from. */
d710d36375bacbf9cfb8903107bedf2c0aada84eMichal Schmidt        priority = syslog_fixup_facility(priority);
d710d36375bacbf9cfb8903107bedf2c0aada84eMichal Schmidt
b5da077ddf01546c4a85688624d6957766d6c00cMichal Schmidt        /* First: priority field */
b5da077ddf01546c4a85688624d6957766d6c00cMichal Schmidt        xsprintf(header_priority, "<%i>", priority);
889a90422dd47284dffa32b9234a6e58991b000cRonny Chevalier        IOVEC_SET_STRING(iovec[n++], header_priority);
b5da077ddf01546c4a85688624d6957766d6c00cMichal Schmidt
889a90422dd47284dffa32b9234a6e58991b000cRonny Chevalier        /* Second: identifier and PID */
b5da077ddf01546c4a85688624d6957766d6c00cMichal Schmidt        if (ucred) {
b5da077ddf01546c4a85688624d6957766d6c00cMichal Schmidt                if (!identifier) {
b5da077ddf01546c4a85688624d6957766d6c00cMichal Schmidt                        get_process_comm(ucred->pid, &ident_buf);
b5da077ddf01546c4a85688624d6957766d6c00cMichal Schmidt                        identifier = ident_buf;
b5da077ddf01546c4a85688624d6957766d6c00cMichal Schmidt                }
b5da077ddf01546c4a85688624d6957766d6c00cMichal Schmidt
b5da077ddf01546c4a85688624d6957766d6c00cMichal Schmidt                xsprintf(header_pid, "["PID_FMT"]: ", ucred->pid);
b5da077ddf01546c4a85688624d6957766d6c00cMichal Schmidt
b5da077ddf01546c4a85688624d6957766d6c00cMichal Schmidt                if (identifier)
b5da077ddf01546c4a85688624d6957766d6c00cMichal Schmidt                        IOVEC_SET_STRING(iovec[n++], identifier);
b5da077ddf01546c4a85688624d6957766d6c00cMichal Schmidt
b5da077ddf01546c4a85688624d6957766d6c00cMichal Schmidt                IOVEC_SET_STRING(iovec[n++], header_pid);
        } else if (identifier) {
                IOVEC_SET_STRING(iovec[n++], identifier);
                IOVEC_SET_STRING(iovec[n++], ": ");
        }

        /* Fourth: message */
        IOVEC_SET_STRING(iovec[n++], message);
        IOVEC_SET_STRING(iovec[n++], "\n");

        if (writev(s->dev_kmsg_fd, iovec, n) < 0)
                log_debug_errno(errno, "Failed to write to /dev/kmsg for logging: %m");

        free(ident_buf);
}

static bool is_us(const char *pid) {
        pid_t t;

        assert(pid);

        if (parse_pid(pid, &t) < 0)
                return false;

        return t == getpid();
}

static void dev_kmsg_record(Server *s, const char *p, size_t l) {
        struct iovec iovec[N_IOVEC_META_FIELDS + 7 + N_IOVEC_KERNEL_FIELDS + 2 + N_IOVEC_UDEV_FIELDS];
        char *message = NULL, *syslog_priority = NULL, *syslog_pid = NULL, *syslog_facility = NULL, *syslog_identifier = NULL, *source_time = NULL;
        int priority, r;
        unsigned n = 0, z = 0, j;
        unsigned long long usec;
        char *identifier = NULL, *pid = NULL, *e, *f, *k;
        uint64_t serial;
        size_t pl;
        char *kernel_device = NULL;

        assert(s);
        assert(p);

        if (l <= 0)
                return;

        e = memchr(p, ',', l);
        if (!e)
                return;
        *e = 0;

        r = safe_atoi(p, &priority);
        if (r < 0 || priority < 0 || priority > 999)
                return;

        if (s->forward_to_kmsg && (priority & LOG_FACMASK) != LOG_KERN)
                return;

        l -= (e - p) + 1;
        p = e + 1;
        e = memchr(p, ',', l);
        if (!e)
                return;
        *e = 0;

        r = safe_atou64(p, &serial);
        if (r < 0)
                return;

        if (s->kernel_seqnum) {
                /* We already read this one? */
                if (serial < *s->kernel_seqnum)
                        return;

                /* Did we lose any? */
                if (serial > *s->kernel_seqnum)
                        server_driver_message(s, SD_MESSAGE_JOURNAL_MISSED, "Missed %"PRIu64" kernel messages",
                                              serial - *s->kernel_seqnum);

                /* Make sure we never read this one again. Note that
                 * we always store the next message serial we expect
                 * here, simply because this makes handling the first
                 * message with serial 0 easy. */
                *s->kernel_seqnum = serial + 1;
        }

        l -= (e - p) + 1;
        p = e + 1;
        f = memchr(p, ';', l);
        if (!f)
                return;
        /* Kernel 3.6 has the flags field, kernel 3.5 lacks that */
        e = memchr(p, ',', l);
        if (!e || f < e)
                e = f;
        *e = 0;

        r = safe_atollu(p, &usec);
        if (r < 0)
                return;

        l -= (f - p) + 1;
        p = f + 1;
        e = memchr(p, '\n', l);
        if (!e)
                return;
        *e = 0;

        pl = e - p;
        l -= (e - p) + 1;
        k = e + 1;

        for (j = 0; l > 0 && j < N_IOVEC_KERNEL_FIELDS; j++) {
                char *m;
                /* Metadata fields attached */

                if (*k != ' ')
                        break;

                k ++, l --;

                e = memchr(k, '\n', l);
                if (!e)
                        return;

                *e = 0;

                if (cunescape_length_with_prefix(k, e - k, "_KERNEL_", UNESCAPE_RELAX, &m) < 0)
                        break;

                if (startswith(m, "_KERNEL_DEVICE="))
                        kernel_device = m + 15;

                IOVEC_SET_STRING(iovec[n++], m);
                z++;

                l -= (e - k) + 1;
                k = e + 1;
        }

        if (kernel_device) {
                struct udev_device *ud;

                ud = udev_device_new_from_device_id(s->udev, kernel_device);
                if (ud) {
                        const char *g;
                        struct udev_list_entry *ll;
                        char *b;

                        g = udev_device_get_devnode(ud);
                        if (g) {
                                b = strappend("_UDEV_DEVNODE=", g);
                                if (b) {
                                        IOVEC_SET_STRING(iovec[n++], b);
                                        z++;
                                }
                        }

                        g = udev_device_get_sysname(ud);
                        if (g) {
                                b = strappend("_UDEV_SYSNAME=", g);
                                if (b) {
                                        IOVEC_SET_STRING(iovec[n++], b);
                                        z++;
                                }
                        }

                        j = 0;
                        ll = udev_device_get_devlinks_list_entry(ud);
                        udev_list_entry_foreach(ll, ll) {

                                if (j > N_IOVEC_UDEV_FIELDS)
                                        break;

                                g = udev_list_entry_get_name(ll);
                                if (g) {
                                        b = strappend("_UDEV_DEVLINK=", g);
                                        if (b) {
                                                IOVEC_SET_STRING(iovec[n++], b);
                                                z++;
                                        }
                                }

                                j++;
                        }

                        udev_device_unref(ud);
                }
        }

        if (asprintf(&source_time, "_SOURCE_MONOTONIC_TIMESTAMP=%llu", usec) >= 0)
                IOVEC_SET_STRING(iovec[n++], source_time);

        IOVEC_SET_STRING(iovec[n++], "_TRANSPORT=kernel");

        if (asprintf(&syslog_priority, "PRIORITY=%i", priority & LOG_PRIMASK) >= 0)
                IOVEC_SET_STRING(iovec[n++], syslog_priority);

        if (asprintf(&syslog_facility, "SYSLOG_FACILITY=%i", LOG_FAC(priority)) >= 0)
                IOVEC_SET_STRING(iovec[n++], syslog_facility);

        if ((priority & LOG_FACMASK) == LOG_KERN)
                IOVEC_SET_STRING(iovec[n++], "SYSLOG_IDENTIFIER=kernel");
        else {
                pl -= syslog_parse_identifier((const char**) &p, &identifier, &pid);

                /* Avoid any messages we generated ourselves via
                 * log_info() and friends. */
                if (pid && is_us(pid))
                        goto finish;

                if (identifier) {
                        syslog_identifier = strappend("SYSLOG_IDENTIFIER=", identifier);
                        if (syslog_identifier)
                                IOVEC_SET_STRING(iovec[n++], syslog_identifier);
                }

                if (pid) {
                        syslog_pid = strappend("SYSLOG_PID=", pid);
                        if (syslog_pid)
                                IOVEC_SET_STRING(iovec[n++], syslog_pid);
                }
        }

        if (cunescape_length_with_prefix(p, pl, "MESSAGE=", UNESCAPE_RELAX, &message) >= 0)
                IOVEC_SET_STRING(iovec[n++], message);

        server_dispatch_message(s, iovec, n, ELEMENTSOF(iovec), NULL, NULL, NULL, 0, NULL, priority, 0);

finish:
        for (j = 0; j < z; j++)
                free(iovec[j].iov_base);

        free(message);
        free(syslog_priority);
        free(syslog_identifier);
        free(syslog_pid);
        free(syslog_facility);
        free(source_time);
        free(identifier);
        free(pid);
}

static int server_read_dev_kmsg(Server *s) {
        char buffer[8192+1]; /* the kernel-side limit per record is 8K currently */
        ssize_t l;

        assert(s);
        assert(s->dev_kmsg_fd >= 0);

        l = read(s->dev_kmsg_fd, buffer, sizeof(buffer) - 1);
        if (l == 0)
                return 0;
        if (l < 0) {
                /* Old kernels who don't allow reading from /dev/kmsg
                 * return EINVAL when we try. So handle this cleanly,
                 * but don' try to ever read from it again. */
                if (errno == EINVAL) {
                        s->dev_kmsg_event_source = sd_event_source_unref(s->dev_kmsg_event_source);
                        return 0;
                }

                if (errno == EAGAIN || errno == EINTR || errno == EPIPE)
                        return 0;

                log_error_errno(errno, "Failed to read from kernel: %m");
                return -errno;
        }

        dev_kmsg_record(s, buffer, l);
        return 1;
}

int server_flush_dev_kmsg(Server *s) {
        int r;

        assert(s);

        if (s->dev_kmsg_fd < 0)
                return 0;

        if (!s->dev_kmsg_readable)
                return 0;

        log_debug("Flushing /dev/kmsg...");

        for (;;) {
                r = server_read_dev_kmsg(s);
                if (r < 0)
                        return r;

                if (r == 0)
                        break;
        }

        return 0;
}

static int dispatch_dev_kmsg(sd_event_source *es, int fd, uint32_t revents, void *userdata) {
        Server *s = userdata;

        assert(es);
        assert(fd == s->dev_kmsg_fd);
        assert(s);

        if (revents & EPOLLERR)
                log_warning("/dev/kmsg buffer overrun, some messages lost.");

        if (!(revents & EPOLLIN))
                log_error("Got invalid event from epoll for /dev/kmsg: %"PRIx32, revents);

        return server_read_dev_kmsg(s);
}

int server_open_dev_kmsg(Server *s) {
        int r;

        assert(s);

        s->dev_kmsg_fd = open("/dev/kmsg", O_RDWR|O_CLOEXEC|O_NONBLOCK|O_NOCTTY);
        if (s->dev_kmsg_fd < 0) {
                log_full(errno == ENOENT ? LOG_DEBUG : LOG_WARNING,
                         "Failed to open /dev/kmsg, ignoring: %m");
                return 0;
        }

        r = sd_event_add_io(s->event, &s->dev_kmsg_event_source, s->dev_kmsg_fd, EPOLLIN, dispatch_dev_kmsg, s);
        if (r < 0) {

                /* This will fail with EPERM on older kernels where
                 * /dev/kmsg is not readable. */
                if (r == -EPERM) {
                        r = 0;
                        goto fail;
                }

                log_error_errno(r, "Failed to add /dev/kmsg fd to event loop: %m");
                goto fail;
        }

        r = sd_event_source_set_priority(s->dev_kmsg_event_source, SD_EVENT_PRIORITY_IMPORTANT+10);
        if (r < 0) {
                log_error_errno(r, "Failed to adjust priority of kmsg event source: %m");
                goto fail;
        }

        s->dev_kmsg_readable = true;

        return 0;

fail:
        s->dev_kmsg_event_source = sd_event_source_unref(s->dev_kmsg_event_source);
        s->dev_kmsg_fd = safe_close(s->dev_kmsg_fd);

        return r;
}

int server_open_kernel_seqnum(Server *s) {
        _cleanup_close_ int fd;
        uint64_t *p;

        assert(s);

        /* We store the seqnum we last read in an mmaped file. That
         * way we can just use it like a variable, but it is
         * persistent and automatically flushed at reboot. */

        fd = open("/run/systemd/journal/kernel-seqnum", O_RDWR|O_CREAT|O_CLOEXEC|O_NOCTTY|O_NOFOLLOW, 0644);
        if (fd < 0) {
                log_error_errno(errno, "Failed to open /run/systemd/journal/kernel-seqnum, ignoring: %m");
                return 0;
        }

        if (posix_fallocate(fd, 0, sizeof(uint64_t)) < 0) {
                log_error_errno(errno, "Failed to allocate sequential number file, ignoring: %m");
                return 0;
        }

        p = mmap(NULL, sizeof(uint64_t), PROT_READ|PROT_WRITE, MAP_SHARED, fd, 0);
        if (p == MAP_FAILED) {
                log_error_errno(errno, "Failed to map sequential number file, ignoring: %m");
                return 0;
        }

        s->kernel_seqnum = p;

        return 0;
}