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