logger.c

   1 /*-*- Mode: C; c-basic-offset: 8 -*-*/
   2
   3 #include <sys/socket.h>
   4 #include <sys/types.h>
   5 #include <assert.h>
   6 #include <time.h>
   7 #include <string.h>
   8 #include <stdio.h>
   9 #include <errno.h>
  10 #include <unistd.h>
  11 #include <sys/poll.h>
  12 #include <sys/epoll.h>
  13 #include <sys/un.h>
  14 #include <fcntl.h>
  15
  16 #include "util.h"
  17 #include "log.h"
  18 #include "list.h"
  19
  20 #define STREAM_BUFFER 2048
  21 #define STREAMS_MAX 256
  22 #define SERVER_FD_START 3
  23 #define SERVER_FD_MAX 16
  24 #define TIMEOUT ((int) (10*MSEC_PER_SEC))
  25
  26 typedef struct Stream Stream;
  27
  28 typedef struct Server {
  29         int syslog_fd;
  30         int kmsg_fd;
  31         int epoll_fd;
  32
  33         unsigned n_server_fd;
  34
  35         LIST_HEAD(Stream, streams);
  36         unsigned n_streams;
  37 } Server;
  38
  39 typedef enum StreamState {
  40         STREAM_LOG_TARGET,
  41         STREAM_PRIORITY,
  42         STREAM_PROCESS,
  43         STREAM_RUNNING
  44 } StreamState;
  45
  46 typedef enum LogTarget {
  47         LOG_TARGET_SYSLOG,
  48         LOG_TARGET_KMSG
  49 } LogTarget;
  50
  51 struct Stream {
  52         Server *server;
  53
  54         StreamState state;
  55
  56         int fd;
  57
  58         LogTarget target;
  59         int priority;
  60         char *process;
  61         pid_t pid;
  62         uid_t uid;
  63
  64         char buffer[STREAM_BUFFER];
  65         size_t length;
  66
  67         LIST_FIELDS(Stream, stream);
  68 };
  69
  70 #define IOVEC_SET_STRING(iovec, s)              \
  71         do {                                    \
  72                 (iovec).iov_base = s;           \
  73                 (iovec).iov_len = strlen(s);    \
  74         } while(false);
  75
  76 static int stream_log(Stream *s, char *p, usec_t timestamp) {
  77
  78         char header_priority[16], header_time[64], header_pid[16];
  79         struct msghdr msghdr;
  80         struct iovec iovec[5];
  81
  82         assert(s);
  83         assert(p);
  84
  85         if (*p == 0)
  86                 return 0;
  87
  88         /*
  89          * The format glibc uses to talk to the syslog daemon is:
  90          *
  91          *     <priority>time process[pid]: msg
  92          *
  93          * The format the kernel uses is:
  94          *
  95          *     <priority>msg\n
  96          *
  97          *  We extend the latter to include the process name and pid.
  98          */
  99
 100         snprintf(header_priority, sizeof(header_priority), "<%i>",
 101                  s->target == LOG_TARGET_SYSLOG ? s->priority : LOG_PRI(s->priority));
 102         char_array_0(header_priority);
 103
 104         if (s->target == LOG_TARGET_SYSLOG) {
 105                 time_t t;
 106                 struct tm *tm;
 107
 108                 t = (time_t) (timestamp / USEC_PER_SEC);
 109                 if (!(tm = localtime(&t)))
 110                         return -EINVAL;
 111
 112                 if (strftime(header_time, sizeof(header_time), "%h %e %T ", tm) <= 0)
 113                         return -EINVAL;
 114         }
 115
 116         snprintf(header_pid, sizeof(header_pid), "[%llu]: ", (unsigned long long) s->pid);
 117         char_array_0(header_pid);
 118
 119         zero(iovec);
 120         IOVEC_SET_STRING(iovec[0], header_priority);
 121
 122         if (s->target == LOG_TARGET_SYSLOG) {
 123                 IOVEC_SET_STRING(iovec[1], header_time);
 124                 IOVEC_SET_STRING(iovec[2], s->process);
 125                 IOVEC_SET_STRING(iovec[3], header_pid);
 126                 IOVEC_SET_STRING(iovec[4], p);
 127
 128                 zero(msghdr);
 129                 msghdr.msg_iov = iovec;
 130                 msghdr.msg_iovlen = ELEMENTSOF(iovec);
 131
 132                 if (sendmsg(s->server->syslog_fd, &msghdr, MSG_NOSIGNAL) < 0)
 133                         return -errno;
 134
 135         } else if (s->target == LOG_TARGET_KMSG) {
 136                 IOVEC_SET_STRING(iovec[1], s->process);
 137                 IOVEC_SET_STRING(iovec[2], header_pid);
 138                 IOVEC_SET_STRING(iovec[3], p);
 139                 IOVEC_SET_STRING(iovec[4], "\n");
 140
 141                 if (writev(s->server->kmsg_fd, iovec, ELEMENTSOF(iovec)) < 0)
 142                         return -errno;
 143         } else
 144                 assert_not_reached("Unknown log target");
 145
 146         return 0;
 147 }
 148
 149 static int stream_line(Stream *s, char *p, usec_t timestamp) {
 150         int r;
 151
 152         assert(s);
 153         assert(p);
 154
 155         p = strstrip(p);
 156
 157         switch (s->state) {
 158
 159         case STREAM_LOG_TARGET:
 160                 if (streq(p, "syslog"))
 161                         s->target = LOG_TARGET_SYSLOG;
 162                 else if (streq(p, "kmsg")) {
 163
 164                         if (s->server->kmsg_fd >= 0 && s->uid == 0)
 165                                 s->target = LOG_TARGET_KMSG;
 166                         else {
 167                                 log_warning("/dev/kmsg logging not available.");
 168                                 return -EPERM;
 169                         }
 170                 } else {
 171                         log_warning("Failed to parse log target line.");
 172                         return -EBADMSG;
 173                 }
 174                 s->state = STREAM_PRIORITY;
 175                 return 0;
 176
 177         case STREAM_PRIORITY:
 178                 if ((r = safe_atoi(p, &s->priority)) < 0) {
 179                         log_warning("Failed to parse log priority line: %s", strerror(errno));
 180                         return r;
 181                 }
 182
 183                 if (s->priority < 0) {
 184                         log_warning("Log priority negative: %s", strerror(errno));
 185                         return -ERANGE;
 186                 }
 187
 188                 s->state = STREAM_PROCESS;
 189                 return 0;
 190
 191         case STREAM_PROCESS:
 192                 if (!(s->process = strdup(p)))
 193                         return -ENOMEM;
 194
 195                 s->state = STREAM_RUNNING;
 196                 return 0;
 197
 198         case STREAM_RUNNING:
 199                 return stream_log(s, p, timestamp);
 200         }
 201
 202         assert_not_reached("Unknown stream state");
 203 }
 204
 205 static int stream_scan(Stream *s, usec_t timestamp) {
 206         char *p;
 207         size_t remaining;
 208         int r = 0;
 209
 210         assert(s);
 211
 212         p = s->buffer;
 213         remaining = s->length;
 214         for (;;) {
 215                 char *newline;
 216
 217                 if (!(newline = memchr(p, '\n', remaining)))
 218                         break;
 219
 220                 *newline = 0;
 221
 222                 if ((r = stream_line(s, p, timestamp)) >= 0) {
 223                         remaining -= newline-p+1;
 224                         p = newline+1;
 225                 }
 226         }
 227
 228         if (p > s->buffer) {
 229                 memmove(s->buffer, p, remaining);
 230                 s->length = remaining;
 231         }
 232
 233         return r;
 234 }
 235
 236 static int stream_process(Stream *s, usec_t timestamp) {
 237         ssize_t l;
 238         int r;
 239         assert(s);
 240
 241         if ((l = read(s->fd, s->buffer+s->length, STREAM_BUFFER-s->length)) < 0) {
 242
 243                 if (errno == EAGAIN)
 244                         return 0;
 245
 246                 log_warning("Failed to read from stream: %s", strerror(errno));
 247                 return -1;
 248         }
 249
 250
 251         if (l == 0)
 252                 return 0;
 253
 254         s->length += l;
 255         r = stream_scan(s, timestamp);
 256
 257         if (r < 0)
 258                 return r;
 259
 260         return 1;
 261 }
 262
 263 static void stream_free(Stream *s) {
 264         assert(s);
 265
 266         if (s->server) {
 267                 assert(s->server->n_streams > 0);
 268                 s->server->n_streams--;
 269                 LIST_REMOVE(Stream, stream, s->server->streams, s);
 270
 271         }
 272
 273         if (s->fd >= 0) {
 274                 if (s->server)
 275                         epoll_ctl(s->server->epoll_fd, EPOLL_CTL_DEL, s->fd, NULL);
 276
 277                 assert_se(close_nointr(s->fd) == 0);
 278         }
 279
 280         free(s->process);
 281         free(s);
 282 }
 283
 284 static int stream_new(Server *s, int server_fd) {
 285         Stream *stream;
 286         int fd;
 287         struct ucred ucred;
 288         socklen_t len = sizeof(ucred);
 289         struct epoll_event ev;
 290         int r;
 291
 292         assert(s);
 293
 294         if ((fd = accept4(server_fd, NULL, NULL, SOCK_NONBLOCK|SOCK_CLOEXEC)) < 0)
 295                 return -errno;
 296
 297         if (s->n_streams >= STREAMS_MAX) {
 298                 log_warning("Too many connections, refusing connection.");
 299                 assert_se(close_nointr(fd) == 0);
 300                 return 0;
 301         }
 302
 303         if (!(stream = new0(Stream, 1))) {
 304                 assert_se(close_nointr(fd) == 0);
 305                 return -ENOMEM;
 306         }
 307
 308         stream->fd = fd;
 309
 310         if (getsockopt(stream->fd, SOL_SOCKET, SO_PEERCRED, &ucred, &len) < 0) {
 311                 r = -errno;
 312                 goto fail;
 313         }
 314
 315         if (shutdown(fd, SHUT_WR) < 0) {
 316                 r = -errno;
 317                 goto fail;
 318         }
 319
 320         zero(ev);
 321         ev.data.ptr = stream;
 322         ev.events = EPOLLIN;
 323         if (epoll_ctl(s->epoll_fd, EPOLL_CTL_ADD, fd, &ev) < 0) {
 324                 r = -errno;
 325                 goto fail;
 326         }
 327
 328         stream->pid = ucred.pid;
 329         stream->uid = ucred.uid;
 330
 331         stream->server = s;
 332         LIST_PREPEND(Stream, stream, s->streams, stream);
 333         s->n_streams ++;
 334
 335         return 0;
 336
 337 fail:
 338         stream_free(stream);
 339         return r;
 340 }
 341
 342 static int verify_environment(unsigned *n_sockets) {
 343         unsigned long long pid;
 344         const char *e;
 345         int r;
 346         unsigned ns;
 347
 348         assert_se(n_sockets);
 349
 350         if (!(e = getenv("LISTEN_PID"))) {
 351                 log_error("Missing $LISTEN_PID environment variable.");
 352                 return -ENOENT;
 353         }
 354
 355         if ((r = safe_atollu(e, &pid)) < 0) {
 356                 log_error("Failed to parse $LISTEN_PID: %s", strerror(-r));
 357                 return r;
 358         }
 359
 360         if (pid != (unsigned long long) getpid()) {
 361                 log_error("Socket nor for me.");
 362                 return -ENOENT;
 363         }
 364
 365         if (!(e = getenv("LISTEN_FDS"))) {
 366                 log_error("Missing $LISTEN_FDS environment variable.");
 367                 return -ENOENT;
 368         }
 369
 370         if ((r = safe_atou(e, &ns)) < 0) {
 371                 log_error("Failed to parse $LISTEN_FDS: %s", strerror(-r));
 372                 return -E2BIG;
 373         }
 374
 375         if (ns <= 0 || ns > SERVER_FD_MAX) {
 376                 log_error("Wrong number of file descriptors passed: %s", e);
 377                 return -E2BIG;
 378         }
 379
 380         *n_sockets = ns;
 381
 382         return 0;
 383 }
 384
 385 static void server_done(Server *s) {
 386         unsigned i;
 387         assert(s);
 388
 389         while (s->streams)
 390                 stream_free(s->streams);
 391
 392         for (i = 0; i < s->n_server_fd; i++)
 393                 assert_se(close_nointr(SERVER_FD_START+i) == 0);
 394
 395         if (s->syslog_fd >= 0)
 396                 assert_se(close_nointr(s->syslog_fd) == 0);
 397
 398         if (s->epoll_fd >= 0)
 399                 assert_se(close_nointr(s->epoll_fd) == 0);
 400
 401         if (s->kmsg_fd >= 0)
 402                 assert_se(close_nointr(s->kmsg_fd) == 0);
 403 }
 404
 405 static int server_init(Server *s, unsigned n_sockets) {
 406         int r;
 407         unsigned i;
 408         union {
 409                 struct sockaddr sa;
 410                 struct sockaddr_un un;
 411         } sa;
 412
 413         assert(s);
 414         assert(n_sockets > 0);
 415
 416         zero(*s);
 417
 418         s->n_server_fd = n_sockets;
 419         s->syslog_fd = -1;
 420         s->kmsg_fd = -1;
 421
 422         if ((s->epoll_fd = epoll_create1(EPOLL_CLOEXEC)) < 0) {
 423                 r = -errno;
 424                 log_error("Failed to create epoll object: %s", strerror(errno));
 425                 goto fail;
 426         }
 427
 428         for (i = 0; i < n_sockets; i++) {
 429                 struct epoll_event ev;
 430
 431                 zero(ev);
 432                 ev.events = EPOLLIN;
 433                 ev.data.ptr = UINT_TO_PTR(SERVER_FD_START+i);
 434                 if (epoll_ctl(s->epoll_fd, EPOLL_CTL_ADD, SERVER_FD_START+i, &ev) < 0) {
 435                         r = -errno;
 436                         log_error("Failed to add server fd to epoll object: %s", strerror(errno));
 437                         goto fail;
 438                 }
 439         }
 440
 441         if ((s->syslog_fd = socket(AF_UNIX, SOCK_DGRAM|SOCK_CLOEXEC, 0)) < 0) {
 442                 r = -errno;
 443                 log_error("Failed to create log fd: %s", strerror(errno));
 444                 goto fail;
 445         }
 446
 447         zero(sa);
 448         sa.un.sun_family = AF_UNIX;
 449         strncpy(sa.un.sun_path, "/dev/log", sizeof(sa.un.sun_path));
 450
 451         if (connect(s->syslog_fd, &sa.sa, sizeof(sa)) < 0) {
 452                 r = -errno;
 453                 log_error("Failed to connect log socket to /dev/log: %s", strerror(errno));
 454                 goto fail;
 455         }
 456
 457         /* /dev/kmsg logging is strictly optional */
 458         if ((s->kmsg_fd = open("/dev/kmsg", O_WRONLY|O_NOCTTY|O_CLOEXEC)) < 0)
 459                 log_debug("Failed to open /dev/kmsg for logging, disabling kernel log buffer support: %s", strerror(errno));
 460
 461         return 0;
 462
 463 fail:
 464         server_done(s);
 465         return r;
 466 }
 467
 468 static int process_event(Server *s, struct epoll_event *ev) {
 469         int r;
 470
 471         assert(s);
 472
 473         /* Yes, this is a bit ugly, we assume that that valid pointers
 474          * are > SERVER_FD_START+SERVER_FD_MAX. Which is certainly
 475          * true on Linux (and probably most other OSes, too, since the
 476          * first 4k usually are part of a seperate null pointer
 477          * dereference page. */
 478
 479         if (PTR_TO_UINT(ev->data.ptr) >= SERVER_FD_START &&
 480             PTR_TO_UINT(ev->data.ptr) < SERVER_FD_START+s->n_server_fd) {
 481
 482                 if (ev->events != EPOLLIN) {
 483                         log_info("Got invalid event from epoll. (1)");
 484                         return -EIO;
 485                 }
 486
 487                 if ((r = stream_new(s, PTR_TO_UINT(ev->data.ptr))) < 0) {
 488                         log_info("Failed to accept new connection: %s", strerror(-r));
 489                         return r;
 490                 }
 491
 492         } else {
 493                 usec_t timestamp;
 494                 Stream *stream = ev->data.ptr;
 495
 496                 timestamp = now(CLOCK_REALTIME);
 497
 498                 if (!(ev->events & EPOLLIN)) {
 499                         log_info("Got invalid event from epoll. (3)");
 500                         stream_free(stream);
 501                         return 0;
 502                 }
 503
 504                 if ((r = stream_process(stream, timestamp)) <= 0) {
 505
 506                         if (r < 0)
 507                                 log_info("Got error on stream: %s", strerror(-r));
 508
 509                         stream_free(stream);
 510                         return 0;
 511                 }
 512         }
 513
 514         return 0;
 515 }
 516
 517 int main(int argc, char *argv[]) {
 518         Server server;
 519         int r = 3;
 520         unsigned n;
 521
 522         log_info("systemd-logger running as pid %llu", (unsigned long long) getpid());
 523
 524         if (verify_environment(&n) < 0)
 525                 return 1;
 526
 527         if (server_init(&server, n) < 0)
 528                 return 2;
 529
 530         for (;;) {
 531                 struct epoll_event event;
 532                 int n;
 533
 534                 if ((n = epoll_wait(server.epoll_fd,
 535                                     &event, 1,
 536                                     server.n_streams <= 0 ? TIMEOUT : -1)) < 0) {
 537
 538                         if (errno == EINTR)
 539                                 continue;
 540
 541                         log_error("epoll_wait() failed: %s", strerror(errno));
 542                         goto fail;
 543                 }
 544
 545                 if (n <= 0)
 546                         break;
 547
 548                 if ((r = process_event(&server, &event)) < 0)
 549                         goto fail;
 550         }
 551         r = 0;
 552
 553 fail:
 554         server_done(&server);
 555
 556         log_info("systemd-logger stopped as pid %llu", (unsigned long long) getpid());
 557
 558         return r;
 559 }