src/logger.c

   1 /*-*- Mode: C; c-basic-offset: 8; indent-tabs-mode: nil -*-*/
   2
   3 /***
   4   This file is part of systemd.
   5
   6   Copyright 2010 Lennart Poettering
   7
   8   systemd is free software; you can redistribute it and/or modify it
   9   under the terms of the GNU General Public License as published by
  10   the Free Software Foundation; either version 2 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   General Public License for more details.
  17
  18   You should have received a copy of the GNU General Public License
  19   along with systemd; If not, see <http://www.gnu.org/licenses/>.
  20 ***/
  21
  22 #include <sys/socket.h>
  23 #include <sys/types.h>
  24 #include <assert.h>
  25 #include <time.h>
  26 #include <string.h>
  27 #include <stdio.h>
  28 #include <errno.h>
  29 #include <unistd.h>
  30 #include <sys/poll.h>
  31 #include <sys/epoll.h>
  32 #include <sys/un.h>
  33 #include <fcntl.h>
  34
  35 #include "util.h"
  36 #include "log.h"
  37 #include "list.h"
  38 #include "sd-daemon.h"
  39 #include "tcpwrap.h"
  40
  41 #define STREAMS_MAX 4096
  42 #define SERVER_FD_MAX 16
  43 #define TIMEOUT ((int) (5*60*MSEC_PER_SEC))
  44
  45 typedef struct Stream Stream;
  46
  47 typedef struct Server {
  48         int syslog_fd;
  49         int kmsg_fd;
  50         int epoll_fd;
  51
  52         unsigned n_server_fd;
  53
  54         bool syslog_is_stream;
  55
  56         LIST_HEAD(Stream, streams);
  57         unsigned n_streams;
  58 } Server;
  59
  60 typedef enum StreamTarget {
  61         STREAM_SYSLOG,
  62         STREAM_KMSG
  63 } StreamTarget;
  64
  65 typedef enum StreamState {
  66         STREAM_TARGET,
  67         STREAM_PRIORITY,
  68         STREAM_PROCESS,
  69         STREAM_PREFIX,
  70         STREAM_RUNNING
  71 } StreamState;
  72
  73 struct Stream {
  74         Server *server;
  75
  76         StreamState state;
  77
  78         int fd;
  79
  80         StreamTarget target;
  81         int priority;
  82         char *process;
  83         pid_t pid;
  84         uid_t uid;
  85         gid_t gid;
  86
  87         bool prefix:1;
  88         bool tee_console:1;
  89
  90         char buffer[LINE_MAX];
  91         size_t length;
  92
  93         LIST_FIELDS(Stream, stream);
  94 };
  95
  96 static int stream_log(Stream *s, char *p, usec_t ts) {
  97
  98         char header_priority[16], header_time[64], header_pid[16];
  99         struct iovec iovec[5];
 100         int priority;
 101
 102         assert(s);
 103         assert(p);
 104
 105         priority = s->priority;
 106
 107         if (s->prefix)
 108                 parse_syslog_priority(&p, &priority);
 109
 110         if (*p == 0)
 111                 return 0;
 112
 113         /* Patch in LOG_USER facility if necessary */
 114         if ((priority & LOG_FACMASK) == 0)
 115                 priority = LOG_USER | LOG_PRI(priority);
 116
 117         /*
 118          * The format glibc uses to talk to the syslog daemon is:
 119          *
 120          *     <priority>time process[pid]: msg
 121          *
 122          * The format the kernel uses is:
 123          *
 124          *     <priority>msg\n
 125          *
 126          *  We extend the latter to include the process name and pid.
 127          */
 128
 129         snprintf(header_priority, sizeof(header_priority), "<%i>", priority);
 130         char_array_0(header_priority);
 131
 132         if (s->target == STREAM_SYSLOG) {
 133                 time_t t;
 134                 struct tm *tm;
 135
 136                 t = (time_t) (ts / USEC_PER_SEC);
 137                 if (!(tm = localtime(&t)))
 138                         return -EINVAL;
 139
 140                 if (strftime(header_time, sizeof(header_time), "%h %e %T ", tm) <= 0)
 141                         return -EINVAL;
 142         }
 143
 144         snprintf(header_pid, sizeof(header_pid), "[%lu]: ", (unsigned long) s->pid);
 145         char_array_0(header_pid);
 146
 147         zero(iovec);
 148         IOVEC_SET_STRING(iovec[0], header_priority);
 149
 150         if (s->target == STREAM_SYSLOG) {
 151                 struct msghdr msghdr;
 152                 union {
 153                         struct cmsghdr cmsghdr;
 154                         uint8_t buf[CMSG_SPACE(sizeof(struct ucred))];
 155                 } control;
 156                 struct ucred *ucred;
 157
 158                 zero(control);
 159                 control.cmsghdr.cmsg_level = SOL_SOCKET;
 160                 control.cmsghdr.cmsg_type = SCM_CREDENTIALS;
 161                 control.cmsghdr.cmsg_len = CMSG_LEN(sizeof(struct ucred));
 162
 163                 ucred = (struct ucred*) CMSG_DATA(&control.cmsghdr);
 164                 ucred->pid = s->pid;
 165                 ucred->uid = s->uid;
 166                 ucred->gid = s->gid;
 167
 168                 IOVEC_SET_STRING(iovec[1], header_time);
 169                 IOVEC_SET_STRING(iovec[2], s->process);
 170                 IOVEC_SET_STRING(iovec[3], header_pid);
 171                 IOVEC_SET_STRING(iovec[4], p);
 172
 173                 /* When using syslog via SOCK_STREAM separate the messages by NUL chars */
 174                 if (s->server->syslog_is_stream)
 175                         iovec[4].iov_len++;
 176
 177                 zero(msghdr);
 178                 msghdr.msg_iov = iovec;
 179                 msghdr.msg_iovlen = ELEMENTSOF(iovec);
 180                 msghdr.msg_control = &control;
 181                 msghdr.msg_controllen = control.cmsghdr.cmsg_len;
 182
 183                 for (;;) {
 184                         ssize_t n;
 185
 186                         if ((n = sendmsg(s->server->syslog_fd, &msghdr, MSG_NOSIGNAL)) < 0) {
 187
 188                                 if (errno == ESRCH) {
 189                                         pid_t our_pid;
 190
 191                                         /* Hmm, maybe the process this
 192                                          * line originates from is
 193                                          * dead? Then let's patch in
 194                                          * our own pid and retry,
 195                                          * since we have nothing
 196                                          * better */
 197
 198                                         our_pid = getpid();
 199
 200                                         if (ucred->pid != our_pid) {
 201                                                 ucred->pid = our_pid;
 202                                                 continue;
 203                                         }
 204                                 }
 205
 206                                 return -errno;
 207                         }
 208
 209                         if (!s->server->syslog_is_stream ||
 210                             (size_t) n >= IOVEC_TOTAL_SIZE(iovec, ELEMENTSOF(iovec)))
 211                                 break;
 212
 213                         IOVEC_INCREMENT(iovec, ELEMENTSOF(iovec), n);
 214                 }
 215
 216         } else if (s->target == STREAM_KMSG) {
 217                 IOVEC_SET_STRING(iovec[1], s->process);
 218                 IOVEC_SET_STRING(iovec[2], header_pid);
 219                 IOVEC_SET_STRING(iovec[3], p);
 220                 IOVEC_SET_STRING(iovec[4], (char*) "\n");
 221
 222                 if (writev(s->server->kmsg_fd, iovec, ELEMENTSOF(iovec)) < 0)
 223                         return -errno;
 224         } else
 225                 assert_not_reached("Unknown log target");
 226
 227         if (s->tee_console) {
 228                 int console;
 229
 230                 if ((console = open_terminal("/dev/console", O_WRONLY|O_NOCTTY|O_CLOEXEC)) >= 0) {
 231                         IOVEC_SET_STRING(iovec[0], s->process);
 232                         IOVEC_SET_STRING(iovec[1], header_pid);
 233                         IOVEC_SET_STRING(iovec[2], p);
 234                         IOVEC_SET_STRING(iovec[3], (char*) "\n");
 235
 236                         writev(console, iovec, 4);
 237                 }
 238
 239         }
 240
 241         return 0;
 242 }
 243
 244 static int stream_line(Stream *s, char *p, usec_t ts) {
 245         int r;
 246
 247         assert(s);
 248         assert(p);
 249
 250         p = strstrip(p);
 251
 252         switch (s->state) {
 253
 254         case STREAM_TARGET:
 255                 if (streq(p, "syslog") || streq(p, "syslog+console"))
 256                         s->target = STREAM_SYSLOG;
 257                 else if (streq(p, "kmsg") || streq(p, "kmsg+console")) {
 258
 259                         if (s->server->kmsg_fd >= 0 && s->uid == 0)
 260                                 s->target = STREAM_KMSG;
 261                         else {
 262                                 log_warning("/dev/kmsg logging not available.");
 263                                 return -EPERM;
 264                         }
 265                 } else {
 266                         log_warning("Failed to parse log target line.");
 267                         return -EBADMSG;
 268                 }
 269
 270                 if (endswith(p, "+console"))
 271                         s->tee_console = true;
 272
 273                 s->state = STREAM_PRIORITY;
 274                 return 0;
 275
 276         case STREAM_PRIORITY:
 277                 if ((r = safe_atoi(p, &s->priority)) < 0) {
 278                         log_warning("Failed to parse log priority line: %m");
 279                         return r;
 280                 }
 281
 282                 if (s->priority < 0) {
 283                         log_warning("Log priority negative: %m");
 284                         return -ERANGE;
 285                 }
 286
 287                 s->state = STREAM_PROCESS;
 288                 return 0;
 289
 290         case STREAM_PROCESS:
 291                 if (!(s->process = strdup(p)))
 292                         return -ENOMEM;
 293
 294                 s->state = STREAM_PREFIX;
 295                 return 0;
 296
 297         case STREAM_PREFIX:
 298
 299                 if ((r = parse_boolean(p)) < 0)
 300                         return r;
 301
 302                 s->prefix = r;
 303                 s->state = STREAM_RUNNING;
 304                 return 0;
 305
 306         case STREAM_RUNNING:
 307                 return stream_log(s, p, ts);
 308         }
 309
 310         assert_not_reached("Unknown stream state");
 311 }
 312
 313 static int stream_scan(Stream *s, usec_t ts) {
 314         char *p;
 315         size_t remaining;
 316         int r = 0;
 317
 318         assert(s);
 319
 320         p = s->buffer;
 321         remaining = s->length;
 322         for (;;) {
 323                 char *newline;
 324
 325                 if (!(newline = memchr(p, '\n', remaining)))
 326                         break;
 327
 328                 *newline = 0;
 329
 330                 if ((r = stream_line(s, p, ts)) >= 0) {
 331                         remaining -= newline-p+1;
 332                         p = newline+1;
 333                 }
 334         }
 335
 336         if (p > s->buffer) {
 337                 memmove(s->buffer, p, remaining);
 338                 s->length = remaining;
 339         }
 340
 341         return r;
 342 }
 343
 344 static int stream_process(Stream *s, usec_t ts) {
 345         ssize_t l;
 346         int r;
 347         assert(s);
 348
 349         if ((l = read(s->fd, s->buffer+s->length, LINE_MAX-s->length)) < 0) {
 350
 351                 if (errno == EAGAIN)
 352                         return 0;
 353
 354                 log_warning("Failed to read from stream: %m");
 355                 return -errno;
 356         }
 357
 358
 359         if (l == 0)
 360                 return 0;
 361
 362         s->length += l;
 363         r = stream_scan(s, ts);
 364
 365         if (r < 0)
 366                 return r;
 367
 368         return 1;
 369 }
 370
 371 static void stream_free(Stream *s) {
 372         assert(s);
 373
 374         if (s->server) {
 375                 assert(s->server->n_streams > 0);
 376                 s->server->n_streams--;
 377                 LIST_REMOVE(Stream, stream, s->server->streams, s);
 378
 379         }
 380
 381         if (s->fd >= 0) {
 382                 if (s->server)
 383                         epoll_ctl(s->server->epoll_fd, EPOLL_CTL_DEL, s->fd, NULL);
 384
 385                 close_nointr_nofail(s->fd);
 386         }
 387
 388         free(s->process);
 389         free(s);
 390 }
 391
 392 static int stream_new(Server *s, int server_fd) {
 393         Stream *stream;
 394         int fd;
 395         struct ucred ucred;
 396         socklen_t len = sizeof(ucred);
 397         struct epoll_event ev;
 398         int r;
 399
 400         assert(s);
 401
 402         if ((fd = accept4(server_fd, NULL, NULL, SOCK_NONBLOCK|SOCK_CLOEXEC)) < 0)
 403                 return -errno;
 404
 405         if (s->n_streams >= STREAMS_MAX) {
 406                 log_warning("Too many connections, refusing connection.");
 407                 close_nointr_nofail(fd);
 408                 return 0;
 409         }
 410
 411         if (!socket_tcpwrap(fd, "systemd-logger")) {
 412                 close_nointr_nofail(fd);
 413                 return 0;
 414         }
 415
 416         if (!(stream = new0(Stream, 1))) {
 417                 close_nointr_nofail(fd);
 418                 return -ENOMEM;
 419         }
 420
 421         stream->fd = fd;
 422
 423         if (getsockopt(stream->fd, SOL_SOCKET, SO_PEERCRED, &ucred, &len) < 0) {
 424                 r = -errno;
 425                 goto fail;
 426         }
 427
 428         if (shutdown(fd, SHUT_WR) < 0) {
 429                 r = -errno;
 430                 goto fail;
 431         }
 432
 433         zero(ev);
 434         ev.data.ptr = stream;
 435         ev.events = EPOLLIN;
 436         if (epoll_ctl(s->epoll_fd, EPOLL_CTL_ADD, fd, &ev) < 0) {
 437                 r = -errno;
 438                 goto fail;
 439         }
 440
 441         stream->pid = ucred.pid;
 442         stream->uid = ucred.uid;
 443         stream->gid = ucred.gid;
 444
 445         stream->server = s;
 446         LIST_PREPEND(Stream, stream, s->streams, stream);
 447         s->n_streams ++;
 448
 449         return 0;
 450
 451 fail:
 452         stream_free(stream);
 453         return r;
 454 }
 455
 456 static void server_done(Server *s) {
 457         unsigned i;
 458         assert(s);
 459
 460         while (s->streams)
 461                 stream_free(s->streams);
 462
 463         for (i = 0; i < s->n_server_fd; i++)
 464                 close_nointr_nofail(SD_LISTEN_FDS_START+i);
 465
 466         if (s->syslog_fd >= 0)
 467                 close_nointr_nofail(s->syslog_fd);
 468
 469         if (s->epoll_fd >= 0)
 470                 close_nointr_nofail(s->epoll_fd);
 471
 472         if (s->kmsg_fd >= 0)
 473                 close_nointr_nofail(s->kmsg_fd);
 474 }
 475
 476 static int server_init(Server *s, unsigned n_sockets) {
 477         int r;
 478         unsigned i;
 479         union {
 480                 struct sockaddr sa;
 481                 struct sockaddr_un un;
 482         } sa;
 483
 484         assert(s);
 485         assert(n_sockets > 0);
 486
 487         zero(*s);
 488
 489         s->n_server_fd = n_sockets;
 490         s->syslog_fd = -1;
 491         s->kmsg_fd = -1;
 492
 493         if ((s->epoll_fd = epoll_create1(EPOLL_CLOEXEC)) < 0) {
 494                 r = -errno;
 495                 log_error("Failed to create epoll object: %m");
 496                 goto fail;
 497         }
 498
 499         for (i = 0; i < n_sockets; i++) {
 500                 struct epoll_event ev;
 501                 int fd;
 502
 503                 fd = SD_LISTEN_FDS_START+i;
 504
 505                 if ((r = sd_is_socket(fd, AF_UNSPEC, SOCK_STREAM, 1)) < 0) {
 506                         log_error("Failed to determine file descriptor type: %s", strerror(-r));
 507                         goto fail;
 508                 }
 509
 510                 if (!r) {
 511                         log_error("Wrong file descriptor type.");
 512                         r = -EINVAL;
 513                         goto fail;
 514                 }
 515
 516                 /* We use ev.data.ptr instead of ev.data.fd here,
 517                  * since on 64bit archs fd is 32bit while a pointer is
 518                  * 64bit. To make sure we can easily distinguish fd
 519                  * values and pointer values we want to make sure to
 520                  * write the full field unconditionally. */
 521
 522                 zero(ev);
 523                 ev.events = EPOLLIN;
 524                 ev.data.ptr = INT_TO_PTR(fd);
 525                 if (epoll_ctl(s->epoll_fd, EPOLL_CTL_ADD, fd, &ev) < 0) {
 526                         r = -errno;
 527                         log_error("Failed to add server fd to epoll object: %m");
 528                         goto fail;
 529                 }
 530         }
 531
 532         zero(sa);
 533         sa.un.sun_family = AF_UNIX;
 534         strncpy(sa.un.sun_path, "/dev/log", sizeof(sa.un.sun_path));
 535
 536         if ((s->syslog_fd = socket(AF_UNIX, SOCK_DGRAM|SOCK_CLOEXEC, 0)) < 0) {
 537                 r = -errno;
 538                 log_error("Failed to create log fd: %m");
 539                 goto fail;
 540         }
 541
 542         if (connect(s->syslog_fd, &sa.sa, sizeof(sa)) < 0) {
 543                 close_nointr_nofail(s->syslog_fd);
 544
 545                 if ((s->syslog_fd = socket(AF_UNIX, SOCK_STREAM|SOCK_CLOEXEC, 0)) < 0) {
 546                         r = -errno;
 547                         log_error("Failed to create log fd: %m");
 548                         goto fail;
 549                 }
 550
 551                 if (connect(s->syslog_fd, &sa.sa, sizeof(sa)) < 0) {
 552                         r = -errno;
 553                         log_error("Failed to connect log socket to /dev/log: %m");
 554                         goto fail;
 555                 }
 556
 557                 s->syslog_is_stream = true;
 558         } else
 559                 s->syslog_is_stream = false;
 560
 561         /* /dev/kmsg logging is strictly optional */
 562         if ((s->kmsg_fd = open("/dev/kmsg", O_WRONLY|O_NOCTTY|O_CLOEXEC)) < 0)
 563                 log_warning("Failed to open /dev/kmsg for logging, disabling kernel log buffer support: %m");
 564
 565         return 0;
 566
 567 fail:
 568         server_done(s);
 569         return r;
 570 }
 571
 572 static int process_event(Server *s, struct epoll_event *ev) {
 573         int r;
 574
 575         assert(s);
 576
 577         /* Yes, this is a bit ugly, we assume that that valid pointers
 578          * are > SD_LISTEN_FDS_START+SERVER_FD_MAX. Which is certainly
 579          * true on Linux (and probably most other OSes, too, since the
 580          * first 4k usually are part of a separate null pointer
 581          * dereference page. */
 582
 583         if (PTR_TO_INT(ev->data.ptr) >= SD_LISTEN_FDS_START &&
 584             PTR_TO_INT(ev->data.ptr) < SD_LISTEN_FDS_START+(int)s->n_server_fd) {
 585
 586                 if (ev->events != EPOLLIN) {
 587                         log_info("Got invalid event from epoll. (1)");
 588                         return -EIO;
 589                 }
 590
 591                 if ((r = stream_new(s, PTR_TO_INT(ev->data.ptr))) < 0) {
 592                         log_info("Failed to accept new connection: %s", strerror(-r));
 593                         return r;
 594                 }
 595
 596         } else {
 597                 usec_t ts;
 598                 Stream *stream = ev->data.ptr;
 599
 600                 ts = now(CLOCK_REALTIME);
 601
 602                 if (!(ev->events & EPOLLIN)) {
 603                         log_info("Got invalid event from epoll. (2)");
 604                         stream_free(stream);
 605                         return 0;
 606                 }
 607
 608                 if ((r = stream_process(stream, ts)) <= 0) {
 609
 610                         if (r < 0)
 611                                 log_info("Got error on stream: %s", strerror(-r));
 612
 613                         stream_free(stream);
 614                         return 0;
 615                 }
 616         }
 617
 618         return 0;
 619 }
 620
 621 int main(int argc, char *argv[]) {
 622         Server server;
 623         int r = EXIT_FAILURE, n;
 624
 625         if (getppid() != 1) {
 626                 log_error("This program should be invoked by init only.");
 627                 return EXIT_FAILURE;
 628         }
 629
 630         if (argc > 1) {
 631                 log_error("This program does not take arguments.");
 632                 return EXIT_FAILURE;
 633         }
 634
 635         log_set_target(LOG_TARGET_SYSLOG_OR_KMSG);
 636         log_parse_environment();
 637         log_open();
 638
 639         if ((n = sd_listen_fds(true)) < 0) {
 640                 log_error("Failed to read listening file descriptors from environment: %s", strerror(-r));
 641                 return EXIT_FAILURE;
 642         }
 643
 644         if (n <= 0 || n > SERVER_FD_MAX) {
 645                 log_error("No or too many file descriptors passed.");
 646                 return EXIT_FAILURE;
 647         }
 648
 649         if (server_init(&server, (unsigned) n) < 0)
 650                 return EXIT_FAILURE;
 651
 652         log_debug("systemd-logger running as pid %lu", (unsigned long) getpid());
 653
 654         sd_notify(false,
 655                   "READY=1\n"
 656                   "STATUS=Processing requests...");
 657
 658         for (;;) {
 659                 struct epoll_event event;
 660                 int k;
 661
 662                 if ((k = epoll_wait(server.epoll_fd,
 663                                     &event, 1,
 664                                     server.n_streams <= 0 ? TIMEOUT : -1)) < 0) {
 665
 666                         if (errno == EINTR)
 667                                 continue;
 668
 669                         log_error("epoll_wait() failed: %m");
 670                         goto fail;
 671                 }
 672
 673                 if (k <= 0)
 674                         break;
 675
 676                 if (process_event(&server, &event) < 0)
 677                         goto fail;
 678         }
 679
 680         r = EXIT_SUCCESS;
 681
 682         log_debug("systemd-logger stopped as pid %lu", (unsigned long) getpid());
 683
 684 fail:
 685         sd_notify(false,
 686                   "STATUS=Shutting down...");
 687
 688         server_done(&server);
 689
 690         return r;
 691 }