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