src/journal/journald-kmsg.c

   1 /*-*- Mode: C; c-basic-offset: 8; indent-tabs-mode: nil -*-*/
   2
   3 /***
   4   This file is part of systemd.
   5
   6   Copyright 2011 Lennart Poettering
   7
   8   systemd is free software; you can redistribute it and/or modify it
   9   under the terms of the GNU Lesser General Public License as published by
  10   the Free Software Foundation; either version 2.1 of the License, or
  11   (at your option) any later version.
  12
  13   systemd is distributed in the hope that it will be useful, but
  14   WITHOUT ANY WARRANTY; without even the implied warranty of
  15   MERCHANTABILITY or FITNESS FOR A PARTICULAR PURPOSE. See the GNU
  16   Lesser General Public License for more details.
  17
  18   You should have received a copy of the GNU Lesser General Public License
  19   along with systemd; If not, see <http://www.gnu.org/licenses/>.
  20 ***/
  21
  22 #include <fcntl.h>
  23 #include <sys/epoll.h>
  24 #include <sys/mman.h>
  25 #include <sys/socket.h>
  26 #include <unistd.h>
  27
  28 #include "libudev.h"
  29 #include "sd-messages.h"
  30
  31 #include "escape.h"
  32 #include "fd-util.h"
  33 #include "formats-util.h"
  34 #include "journald-kmsg.h"
  35 #include "journald-server.h"
  36 #include "journald-syslog.h"
  37 #include "process-util.h"
  38 #include "string-util.h"
  39
  40 void server_forward_kmsg(
  41         Server *s,
  42         int priority,
  43         const char *identifier,
  44         const char *message,
  45         const struct ucred *ucred) {
  46
  47         struct iovec iovec[5];
  48         char header_priority[DECIMAL_STR_MAX(priority) + 3],
  49              header_pid[sizeof("[]: ")-1 + DECIMAL_STR_MAX(pid_t) + 1];
  50         int n = 0;
  51         char *ident_buf = NULL;
  52
  53         assert(s);
  54         assert(priority >= 0);
  55         assert(priority <= 999);
  56         assert(message);
  57
  58         if (_unlikely_(LOG_PRI(priority) > s->max_level_kmsg))
  59                 return;
  60
  61         if (_unlikely_(s->dev_kmsg_fd < 0))
  62                 return;
  63
  64         /* Never allow messages with kernel facility to be written to
  65          * kmsg, regardless where the data comes from. */
  66         priority = syslog_fixup_facility(priority);
  67
  68         /* First: priority field */
  69         xsprintf(header_priority, "<%i>", priority);
  70         IOVEC_SET_STRING(iovec[n++], header_priority);
  71
  72         /* Second: identifier and PID */
  73         if (ucred) {
  74                 if (!identifier) {
  75                         get_process_comm(ucred->pid, &ident_buf);
  76                         identifier = ident_buf;
  77                 }
  78
  79                 xsprintf(header_pid, "["PID_FMT"]: ", ucred->pid);
  80
  81                 if (identifier)
  82                         IOVEC_SET_STRING(iovec[n++], identifier);
  83
  84                 IOVEC_SET_STRING(iovec[n++], header_pid);
  85         } else if (identifier) {
  86                 IOVEC_SET_STRING(iovec[n++], identifier);
  87                 IOVEC_SET_STRING(iovec[n++], ": ");
  88         }
  89
  90         /* Fourth: message */
  91         IOVEC_SET_STRING(iovec[n++], message);
  92         IOVEC_SET_STRING(iovec[n++], "\n");
  93
  94         if (writev(s->dev_kmsg_fd, iovec, n) < 0)
  95                 log_debug_errno(errno, "Failed to write to /dev/kmsg for logging: %m");
  96
  97         free(ident_buf);
  98 }
  99
 100 static bool is_us(const char *pid) {
 101         pid_t t;
 102
 103         assert(pid);
 104
 105         if (parse_pid(pid, &t) < 0)
 106                 return false;
 107
 108         return t == getpid();
 109 }
 110
 111 static void dev_kmsg_record(Server *s, const char *p, size_t l) {
 112         struct iovec iovec[N_IOVEC_META_FIELDS + 7 + N_IOVEC_KERNEL_FIELDS + 2 + N_IOVEC_UDEV_FIELDS];
 113         char *message = NULL, *syslog_priority = NULL, *syslog_pid = NULL, *syslog_facility = NULL, *syslog_identifier = NULL, *source_time = NULL;
 114         int priority, r;
 115         unsigned n = 0, z = 0, j;
 116         unsigned long long usec;
 117         char *identifier = NULL, *pid = NULL, *e, *f, *k;
 118         uint64_t serial;
 119         size_t pl;
 120         char *kernel_device = NULL;
 121
 122         assert(s);
 123         assert(p);
 124
 125         if (l <= 0)
 126                 return;
 127
 128         e = memchr(p, ',', l);
 129         if (!e)
 130                 return;
 131         *e = 0;
 132
 133         r = safe_atoi(p, &priority);
 134         if (r < 0 || priority < 0 || priority > 999)
 135                 return;
 136
 137         if (s->forward_to_kmsg && (priority & LOG_FACMASK) != LOG_KERN)
 138                 return;
 139
 140         l -= (e - p) + 1;
 141         p = e + 1;
 142         e = memchr(p, ',', l);
 143         if (!e)
 144                 return;
 145         *e = 0;
 146
 147         r = safe_atou64(p, &serial);
 148         if (r < 0)
 149                 return;
 150
 151         if (s->kernel_seqnum) {
 152                 /* We already read this one? */
 153                 if (serial < *s->kernel_seqnum)
 154                         return;
 155
 156                 /* Did we lose any? */
 157                 if (serial > *s->kernel_seqnum)
 158                         server_driver_message(s, SD_MESSAGE_JOURNAL_MISSED, "Missed %"PRIu64" kernel messages",
 159                                               serial - *s->kernel_seqnum);
 160
 161                 /* Make sure we never read this one again. Note that
 162                  * we always store the next message serial we expect
 163                  * here, simply because this makes handling the first
 164                  * message with serial 0 easy. */
 165                 *s->kernel_seqnum = serial + 1;
 166         }
 167
 168         l -= (e - p) + 1;
 169         p = e + 1;
 170         f = memchr(p, ';', l);
 171         if (!f)
 172                 return;
 173         /* Kernel 3.6 has the flags field, kernel 3.5 lacks that */
 174         e = memchr(p, ',', l);
 175         if (!e || f < e)
 176                 e = f;
 177         *e = 0;
 178
 179         r = safe_atollu(p, &usec);
 180         if (r < 0)
 181                 return;
 182
 183         l -= (f - p) + 1;
 184         p = f + 1;
 185         e = memchr(p, '\n', l);
 186         if (!e)
 187                 return;
 188         *e = 0;
 189
 190         pl = e - p;
 191         l -= (e - p) + 1;
 192         k = e + 1;
 193
 194         for (j = 0; l > 0 && j < N_IOVEC_KERNEL_FIELDS; j++) {
 195                 char *m;
 196                 /* Metadata fields attached */
 197
 198                 if (*k != ' ')
 199                         break;
 200
 201                 k ++, l --;
 202
 203                 e = memchr(k, '\n', l);
 204                 if (!e)
 205                         return;
 206
 207                 *e = 0;
 208
 209                 if (cunescape_length_with_prefix(k, e - k, "_KERNEL_", UNESCAPE_RELAX, &m) < 0)
 210                         break;
 211
 212                 if (startswith(m, "_KERNEL_DEVICE="))
 213                         kernel_device = m + 15;
 214
 215                 IOVEC_SET_STRING(iovec[n++], m);
 216                 z++;
 217
 218                 l -= (e - k) + 1;
 219                 k = e + 1;
 220         }
 221
 222         if (kernel_device) {
 223                 struct udev_device *ud;
 224
 225                 ud = udev_device_new_from_device_id(s->udev, kernel_device);
 226                 if (ud) {
 227                         const char *g;
 228                         struct udev_list_entry *ll;
 229                         char *b;
 230
 231                         g = udev_device_get_devnode(ud);
 232                         if (g) {
 233                                 b = strappend("_UDEV_DEVNODE=", g);
 234                                 if (b) {
 235                                         IOVEC_SET_STRING(iovec[n++], b);
 236                                         z++;
 237                                 }
 238                         }
 239
 240                         g = udev_device_get_sysname(ud);
 241                         if (g) {
 242                                 b = strappend("_UDEV_SYSNAME=", g);
 243                                 if (b) {
 244                                         IOVEC_SET_STRING(iovec[n++], b);
 245                                         z++;
 246                                 }
 247                         }
 248
 249                         j = 0;
 250                         ll = udev_device_get_devlinks_list_entry(ud);
 251                         udev_list_entry_foreach(ll, ll) {
 252
 253                                 if (j > N_IOVEC_UDEV_FIELDS)
 254                                         break;
 255
 256                                 g = udev_list_entry_get_name(ll);
 257                                 if (g) {
 258                                         b = strappend("_UDEV_DEVLINK=", g);
 259                                         if (b) {
 260                                                 IOVEC_SET_STRING(iovec[n++], b);
 261                                                 z++;
 262                                         }
 263                                 }
 264
 265                                 j++;
 266                         }
 267
 268                         udev_device_unref(ud);
 269                 }
 270         }
 271
 272         if (asprintf(&source_time, "_SOURCE_MONOTONIC_TIMESTAMP=%llu", usec) >= 0)
 273                 IOVEC_SET_STRING(iovec[n++], source_time);
 274
 275         IOVEC_SET_STRING(iovec[n++], "_TRANSPORT=kernel");
 276
 277         if (asprintf(&syslog_priority, "PRIORITY=%i", priority & LOG_PRIMASK) >= 0)
 278                 IOVEC_SET_STRING(iovec[n++], syslog_priority);
 279
 280         if (asprintf(&syslog_facility, "SYSLOG_FACILITY=%i", LOG_FAC(priority)) >= 0)
 281                 IOVEC_SET_STRING(iovec[n++], syslog_facility);
 282
 283         if ((priority & LOG_FACMASK) == LOG_KERN)
 284                 IOVEC_SET_STRING(iovec[n++], "SYSLOG_IDENTIFIER=kernel");
 285         else {
 286                 pl -= syslog_parse_identifier((const char**) &p, &identifier, &pid);
 287
 288                 /* Avoid any messages we generated ourselves via
 289                  * log_info() and friends. */
 290                 if (pid && is_us(pid))
 291                         goto finish;
 292
 293                 if (identifier) {
 294                         syslog_identifier = strappend("SYSLOG_IDENTIFIER=", identifier);
 295                         if (syslog_identifier)
 296                                 IOVEC_SET_STRING(iovec[n++], syslog_identifier);
 297                 }
 298
 299                 if (pid) {
 300                         syslog_pid = strappend("SYSLOG_PID=", pid);
 301                         if (syslog_pid)
 302                                 IOVEC_SET_STRING(iovec[n++], syslog_pid);
 303                 }
 304         }
 305
 306         if (cunescape_length_with_prefix(p, pl, "MESSAGE=", UNESCAPE_RELAX, &message) >= 0)
 307                 IOVEC_SET_STRING(iovec[n++], message);
 308
 309         server_dispatch_message(s, iovec, n, ELEMENTSOF(iovec), NULL, NULL, NULL, 0, NULL, priority, 0);
 310
 311 finish:
 312         for (j = 0; j < z; j++)
 313                 free(iovec[j].iov_base);
 314
 315         free(message);
 316         free(syslog_priority);
 317         free(syslog_identifier);
 318         free(syslog_pid);
 319         free(syslog_facility);
 320         free(source_time);
 321         free(identifier);
 322         free(pid);
 323 }
 324
 325 static int server_read_dev_kmsg(Server *s) {
 326         char buffer[8192+1]; /* the kernel-side limit per record is 8K currently */
 327         ssize_t l;
 328
 329         assert(s);
 330         assert(s->dev_kmsg_fd >= 0);
 331
 332         l = read(s->dev_kmsg_fd, buffer, sizeof(buffer) - 1);
 333         if (l == 0)
 334                 return 0;
 335         if (l < 0) {
 336                 /* Old kernels who don't allow reading from /dev/kmsg
 337                  * return EINVAL when we try. So handle this cleanly,
 338                  * but don' try to ever read from it again. */
 339                 if (errno == EINVAL) {
 340                         s->dev_kmsg_event_source = sd_event_source_unref(s->dev_kmsg_event_source);
 341                         return 0;
 342                 }
 343
 344                 if (errno == EAGAIN || errno == EINTR || errno == EPIPE)
 345                         return 0;
 346
 347                 log_error_errno(errno, "Failed to read from kernel: %m");
 348                 return -errno;
 349         }
 350
 351         dev_kmsg_record(s, buffer, l);
 352         return 1;
 353 }
 354
 355 int server_flush_dev_kmsg(Server *s) {
 356         int r;
 357
 358         assert(s);
 359
 360         if (s->dev_kmsg_fd < 0)
 361                 return 0;
 362
 363         if (!s->dev_kmsg_readable)
 364                 return 0;
 365
 366         log_debug("Flushing /dev/kmsg...");
 367
 368         for (;;) {
 369                 r = server_read_dev_kmsg(s);
 370                 if (r < 0)
 371                         return r;
 372
 373                 if (r == 0)
 374                         break;
 375         }
 376
 377         return 0;
 378 }
 379
 380 static int dispatch_dev_kmsg(sd_event_source *es, int fd, uint32_t revents, void *userdata) {
 381         Server *s = userdata;
 382
 383         assert(es);
 384         assert(fd == s->dev_kmsg_fd);
 385         assert(s);
 386
 387         if (revents & EPOLLERR)
 388                 log_warning("/dev/kmsg buffer overrun, some messages lost.");
 389
 390         if (!(revents & EPOLLIN))
 391                 log_error("Got invalid event from epoll for /dev/kmsg: %"PRIx32, revents);
 392
 393         return server_read_dev_kmsg(s);
 394 }
 395
 396 int server_open_dev_kmsg(Server *s) {
 397         int r;
 398
 399         assert(s);
 400
 401         s->dev_kmsg_fd = open("/dev/kmsg", O_RDWR|O_CLOEXEC|O_NONBLOCK|O_NOCTTY);
 402         if (s->dev_kmsg_fd < 0) {
 403                 log_full(errno == ENOENT ? LOG_DEBUG : LOG_WARNING,
 404                          "Failed to open /dev/kmsg, ignoring: %m");
 405                 return 0;
 406         }
 407
 408         r = sd_event_add_io(s->event, &s->dev_kmsg_event_source, s->dev_kmsg_fd, EPOLLIN, dispatch_dev_kmsg, s);
 409         if (r < 0) {
 410
 411                 /* This will fail with EPERM on older kernels where
 412                  * /dev/kmsg is not readable. */
 413                 if (r == -EPERM) {
 414                         r = 0;
 415                         goto fail;
 416                 }
 417
 418                 log_error_errno(r, "Failed to add /dev/kmsg fd to event loop: %m");
 419                 goto fail;
 420         }
 421
 422         r = sd_event_source_set_priority(s->dev_kmsg_event_source, SD_EVENT_PRIORITY_IMPORTANT+10);
 423         if (r < 0) {
 424                 log_error_errno(r, "Failed to adjust priority of kmsg event source: %m");
 425                 goto fail;
 426         }
 427
 428         s->dev_kmsg_readable = true;
 429
 430         return 0;
 431
 432 fail:
 433         s->dev_kmsg_event_source = sd_event_source_unref(s->dev_kmsg_event_source);
 434         s->dev_kmsg_fd = safe_close(s->dev_kmsg_fd);
 435
 436         return r;
 437 }
 438
 439 int server_open_kernel_seqnum(Server *s) {
 440         _cleanup_close_ int fd;
 441         uint64_t *p;
 442
 443         assert(s);
 444
 445         /* We store the seqnum we last read in an mmaped file. That
 446          * way we can just use it like a variable, but it is
 447          * persistent and automatically flushed at reboot. */
 448
 449         fd = open("/run/systemd/journal/kernel-seqnum", O_RDWR|O_CREAT|O_CLOEXEC|O_NOCTTY|O_NOFOLLOW, 0644);
 450         if (fd < 0) {
 451                 log_error_errno(errno, "Failed to open /run/systemd/journal/kernel-seqnum, ignoring: %m");
 452                 return 0;
 453         }
 454
 455         if (posix_fallocate(fd, 0, sizeof(uint64_t)) < 0) {
 456                 log_error_errno(errno, "Failed to allocate sequential number file, ignoring: %m");
 457                 return 0;
 458         }
 459
 460         p = mmap(NULL, sizeof(uint64_t), PROT_READ|PROT_WRITE, MAP_SHARED, fd, 0);
 461         if (p == MAP_FAILED) {
 462                 log_error_errno(errno, "Failed to map sequential number file, ignoring: %m");
 463                 return 0;
 464         }
 465
 466         s->kernel_seqnum = p;
 467
 468         return 0;
 469 }