src/lxc/log.c

   1 /*
   2  * lxc: linux Container library
   3  *
   4  * (C) Copyright IBM Corp. 2007, 2008
   5  *
   6  * Authors:
   7  * Cedric Le Goater <legoater@free.fr>
   8  *
   9  * This library is free software; you can redistribute it and/or
  10  * modify it under the terms of the GNU Lesser General Public
  11  * License as published by the Free Software Foundation; either
  12  * version 2.1 of the License, or (at your option) any later version.
  13  *
  14  * This library is distributed in the hope that it will be useful,
  15  * but WITHOUT ANY WARRANTY; without even the implied warranty of
  16  * MERCHANTABILITY or FITNESS FOR A PARTICULAR PURPOSE.  See the GNU
  17  * Lesser General Public License for more details.
  18  *
  19  * You should have received a copy of the GNU Lesser General Public
  20  * License along with this library; if not, write to the Free Software
  21  * Foundation, Inc., 51 Franklin Street, Fifth Floor, Boston, MA 02110-1301 USA
  22  */
  23
  24 #define _GNU_SOURCE
  25 #define __STDC_FORMAT_MACROS /* Required for PRIu64 to work. */
  26 #include <stdint.h>
  27 #include <stdio.h>
  28 #include <errno.h>
  29 #include <inttypes.h>
  30 #include <limits.h>
  31 #include <unistd.h>
  32 #include <sys/types.h>
  33 #include <sys/stat.h>
  34 #include <string.h>
  35 #include <pthread.h>
  36 #include <time.h>
  37
  38 #include <syslog.h>
  39 #include <stdio.h>
  40
  41 #include <fcntl.h>
  42 #include <stdlib.h>
  43
  44 #include "log.h"
  45 #include "caps.h"
  46 #include "utils.h"
  47
  48 /* We're logging in seconds and nanoseconds. Assuming that the underlying
  49  * datatype is currently at maximum a 64bit integer, we have a date string that
  50  * is of maximum length (2^64 - 1) * 2 = (21 + 21) = 42.
  51  */
  52 #define LXC_LOG_TIME_SIZE ((LXC_NUMSTRLEN64)*2)
  53
  54 int lxc_log_fd = -1;
  55 static int syslog_enable = 0;
  56 int lxc_quiet_specified;
  57 int lxc_log_use_global_fd;
  58 static int lxc_loglevel_specified;
  59
  60 static char log_prefix[LXC_LOG_PREFIX_SIZE] = "lxc";
  61 static char *log_fname = NULL;
  62 static char *log_vmname = NULL;
  63
  64 lxc_log_define(lxc_log, lxc);
  65
  66 static int lxc_log_priority_to_syslog(int priority)
  67 {
  68         switch (priority) {
  69         case LXC_LOG_PRIORITY_FATAL:
  70                 return LOG_EMERG;
  71         case LXC_LOG_PRIORITY_ALERT:
  72                 return LOG_ALERT;
  73         case LXC_LOG_PRIORITY_CRIT:
  74                 return LOG_CRIT;
  75         case LXC_LOG_PRIORITY_ERROR:
  76                 return LOG_ERR;
  77         case LXC_LOG_PRIORITY_WARN:
  78                 return LOG_WARNING;
  79         case LXC_LOG_PRIORITY_NOTICE:
  80         case LXC_LOG_PRIORITY_NOTSET:
  81                 return LOG_NOTICE;
  82         case LXC_LOG_PRIORITY_INFO:
  83                 return LOG_INFO;
  84         case LXC_LOG_PRIORITY_TRACE:
  85         case LXC_LOG_PRIORITY_DEBUG:
  86                 return LOG_DEBUG;
  87         }
  88
  89         /* Not reached */
  90         return LOG_NOTICE;
  91 }
  92
  93 /*---------------------------------------------------------------------------*/
  94 static int log_append_syslog(const struct lxc_log_appender *appender,
  95                              struct lxc_log_event *event)
  96 {
  97         char *msg;
  98         int rc, len;
  99         va_list args;
 100
 101         if (!syslog_enable)
 102                 return 0;
 103
 104         va_copy(args, *event->vap);
 105         len = vsnprintf(NULL, 0, event->fmt, args) + 1;
 106         va_end(args);
 107         msg = malloc(len * sizeof(char));
 108         if (msg == NULL)
 109                 return 0;
 110         rc = vsnprintf(msg, len, event->fmt, *event->vap);
 111         if (rc == -1 || rc >= len) {
 112                 free(msg);
 113                 return 0;
 114         }
 115
 116         syslog(lxc_log_priority_to_syslog(event->priority),
 117                 "%s%s %s - %s:%s:%d - %s" ,
 118                 log_vmname ? log_vmname : "",
 119                 log_vmname ? ":" : "",
 120                 event->category,
 121                 event->locinfo->file, event->locinfo->func,
 122                 event->locinfo->line,
 123                 msg);
 124         free(msg);
 125         return 0;
 126 }
 127
 128 /*---------------------------------------------------------------------------*/
 129 static int log_append_stderr(const struct lxc_log_appender *appender,
 130                              struct lxc_log_event *event)
 131 {
 132         if (event->priority < LXC_LOG_PRIORITY_ERROR)
 133                 return 0;
 134
 135         fprintf(stderr, "%s: %s%s", log_prefix, log_vmname ? log_vmname : "", log_vmname ? ": " : "");
 136         fprintf(stderr, "%s: %s: %d ", event->locinfo->file, event->locinfo->func, event->locinfo->line);
 137         vfprintf(stderr, event->fmt, *event->vap);
 138         fprintf(stderr, "\n");
 139         return 0;
 140 }
 141
 142 /*---------------------------------------------------------------------------*/
 143 int lxc_unix_epoch_to_utc(char *buf, size_t bufsize, const struct timespec *time)
 144 {
 145         int64_t epoch_to_days, z, era, doe, yoe, year, doy, mp, day, month,
 146             d_in_s, hours, h_in_s, minutes, seconds;
 147         char nanosec[LXC_NUMSTRLEN64];
 148         int ret;
 149
 150         /* See https://howardhinnant.github.io/date_algorithms.html for an
 151          * explanation of the algorithm used here.
 152          */
 153
 154         /* Convert Epoch in seconds to number of days. */
 155         epoch_to_days = time->tv_sec / 86400;
 156
 157         /* Shift the Epoch from 1970-01-01 to 0000-03-01. */
 158         z = epoch_to_days + 719468;
 159
 160         /* compute the era from the serial date by simply dividing by the number
 161          * of days in an era (146097).
 162          */
 163         era = (z >= 0 ? z : z - 146096) / 146097;
 164
 165         /* The day-of-era (doe) can then be found by subtracting the era number
 166          * times the number of days per era, from the serial date.
 167          */
 168         doe = (z - era * 146097);
 169
 170         /* From the day-of-era (doe), the year-of-era (yoe, range [0, 399]) can
 171          * be computed.
 172          */
 173         yoe = (doe - doe / 1460 + doe / 36524 - doe / 146096) / 365;
 174
 175         /* Given year-of-era, and era, one can now compute the year. */
 176         year = (yoe) + era * 400;
 177
 178         /* Also the day-of-year, again with the year beginning on Mar. 1, can be
 179          * computed from the day-of-era and year-of-era.
 180          */
 181         doy = doe - (365 * yoe + yoe / 4 - yoe / 100);
 182
 183         /* Given day-of-year, find the month number. */
 184         mp = (5 * doy + 2) / 153;
 185
 186         /* From day-of-year and month-of-year we can now easily compute
 187          * day-of-month.
 188          */
 189         day = doy - (153 * mp + 2) / 5 + 1;
 190
 191         /* Transform the month number from the [0, 11] / [Mar, Feb] system to
 192          * the civil system: [1, 12] to find the correct month.
 193          */
 194         month = mp + (mp < 10 ? 3 : -9);
 195
 196         /* Transform days in the epoch to seconds. */
 197         d_in_s = epoch_to_days * 86400;
 198
 199         /* To find the current hour simply substract the Epoch_to_days from the
 200          * total Epoch and divide by the number of seconds in an hour.
 201          */
 202         hours = (time->tv_sec - d_in_s) / 3600;
 203
 204         /* Transform hours to seconds. */
 205         h_in_s = hours * 3600;
 206
 207         /* Calculate minutes by substracting the seconds for all days in the
 208          * epoch and for all hours in the epoch and divide by the number of
 209          * minutes in an hour.
 210          */
 211         minutes = (time->tv_sec - d_in_s - h_in_s) / 60;
 212
 213         /* Calculate the seconds by substracting the seconds for all days in the
 214          * epoch, hours in the epoch and minutes in the epoch.
 215          */
 216         seconds = (time->tv_sec - d_in_s - h_in_s - (minutes * 60));
 217
 218         /* Make string from nanoseconds. */
 219         ret = snprintf(nanosec, LXC_NUMSTRLEN64, "%ld", time->tv_nsec);
 220         if (ret < 0 || ret >= LXC_NUMSTRLEN64)
 221                 return -1;
 222
 223         /* Create final timestamp for the log and shorten nanoseconds to 3
 224          * digit precision.
 225          */
 226         ret = snprintf(buf, bufsize,
 227                        "%" PRId64 "%02" PRId64 "%02" PRId64 "%02" PRId64
 228                        "%02" PRId64 "%02" PRId64 ".%.3s",
 229                        year, month, day, hours, minutes, seconds, nanosec);
 230         if (ret < 0 || (size_t)ret >= bufsize)
 231                 return -1;
 232
 233         return 0;
 234 }
 235
 236 /* This function needs to make extra sure that it is thread-safe. We had some
 237  * problems with that before. This especially involves time-conversion
 238  * functions. I don't want to find any localtime() or gmtime() functions or
 239  * relatives in here. Not even localtime_r() or gmtime_r() or relatives. They
 240  * all fiddle with global variables and locking in various libcs. They cause
 241  * deadlocks when liblxc is used multi-threaded and no matter how smart you
 242  * think you are, you __will__ cause trouble using them.
 243  * (As a short example how this can cause trouble: LXD uses forkstart to fork
 244  * off a new process that runs the container. At the same time the go runtime
 245  * LXD relies on does its own multi-threading thing which we can't controll. The
 246  * fork()ing + threading then seems to mess with the locking states in these
 247  * time functions causing deadlocks.)
 248  * The current solution is to be good old unix people and use the Epoch as our
 249  * reference point and simply use the seconds and nanoseconds that have past
 250  * since then. This relies on clock_gettime() which is explicitly marked MT-Safe
 251  * with no restrictions! This way, anyone who is really strongly invested in
 252  * getting the actual time the log entry was created, can just convert it for
 253  * themselves. Our logging is mostly done for debugging purposes so don't try
 254  * to make it pretty. Pretty might cost you thread-safety.
 255  */
 256 static int log_append_logfile(const struct lxc_log_appender *appender,
 257                               struct lxc_log_event *event)
 258 {
 259         char buffer[LXC_LOG_BUFFER_SIZE];
 260         char date_time[LXC_LOG_TIME_SIZE];
 261         int n;
 262         int fd_to_use = -1;
 263
 264 #ifndef NO_LXC_CONF
 265         if (!lxc_log_use_global_fd && current_config)
 266                 fd_to_use = current_config->logfd;
 267 #endif
 268
 269         if (fd_to_use == -1)
 270                 fd_to_use = lxc_log_fd;
 271
 272         if (fd_to_use == -1)
 273                 return 0;
 274
 275         if (lxc_unix_epoch_to_utc(date_time, LXC_LOG_TIME_SIZE, &event->timestamp) < 0)
 276                 return 0;
 277
 278         n = snprintf(buffer, sizeof(buffer),
 279                         "%15s%s%s %s %-8s %s - %s:%s:%d - ",
 280                         log_prefix,
 281                         log_vmname ? " " : "",
 282                         log_vmname ? log_vmname : "",
 283                         date_time,
 284                         lxc_log_priority_to_string(event->priority),
 285                         event->category,
 286                         event->locinfo->file, event->locinfo->func,
 287                         event->locinfo->line);
 288
 289         if (n < 0)
 290                 return n;
 291
 292         if ((size_t)n < (sizeof(buffer) - 1))
 293                 n += vsnprintf(buffer + n, sizeof(buffer) - n, event->fmt, *event->vap);
 294         else
 295                 n = sizeof(buffer) - 1;
 296
 297         buffer[n] = '\n';
 298
 299         return write(fd_to_use, buffer, n + 1);
 300 }
 301
 302 static struct lxc_log_appender log_appender_syslog = {
 303         .name           = "syslog",
 304         .append         = log_append_syslog,
 305         .next           = NULL,
 306 };
 307
 308 static struct lxc_log_appender log_appender_stderr = {
 309         .name           = "stderr",
 310         .append         = log_append_stderr,
 311         .next           = NULL,
 312 };
 313
 314 static struct lxc_log_appender log_appender_logfile = {
 315         .name           = "logfile",
 316         .append         = log_append_logfile,
 317         .next           = NULL,
 318 };
 319
 320 static struct lxc_log_category log_root = {
 321         .name           = "root",
 322         .priority       = LXC_LOG_PRIORITY_ERROR,
 323         .appender       = NULL,
 324         .parent         = NULL,
 325 };
 326
 327 struct lxc_log_category lxc_log_category_lxc = {
 328         .name           = "lxc",
 329         .priority       = LXC_LOG_PRIORITY_ERROR,
 330         .appender       = &log_appender_logfile,
 331         .parent         = &log_root
 332 };
 333
 334 /*---------------------------------------------------------------------------*/
 335 static int build_dir(const char *name)
 336 {
 337         char *n = strdup(name);  // because we'll be modifying it
 338         char *p, *e;
 339         int ret;
 340
 341         if (!n) {
 342                 ERROR("Out of memory while creating directory '%s'.", name);
 343                 return -1;
 344         }
 345
 346         e = &n[strlen(n)];
 347         for (p = n+1; p < e; p++) {
 348                 if (*p != '/')
 349                         continue;
 350                 *p = '\0';
 351                 if (access(n, F_OK)) {
 352                         ret = lxc_unpriv(mkdir(n, 0755));
 353                         if (ret && errno != EEXIST) {
 354                                 SYSERROR("failed to create directory '%s'.", n);
 355                                 free(n);
 356                                 return -1;
 357                         }
 358                 }
 359                 *p = '/';
 360         }
 361         free(n);
 362         return 0;
 363 }
 364
 365 /*---------------------------------------------------------------------------*/
 366 static int log_open(const char *name)
 367 {
 368         int fd;
 369         int newfd;
 370
 371         fd = lxc_unpriv(open(name, O_CREAT | O_WRONLY |
 372                              O_APPEND | O_CLOEXEC, 0666));
 373         if (fd == -1) {
 374                 ERROR("failed to open log file \"%s\" : %s", name,
 375                       strerror(errno));
 376                 return -1;
 377         }
 378
 379         if (fd > 2)
 380                 return fd;
 381
 382         newfd = fcntl(fd, F_DUPFD_CLOEXEC, 3);
 383         if (newfd == -1)
 384                 ERROR("failed to dup log fd %d : %s", fd, strerror(errno));
 385
 386         close(fd);
 387         return newfd;
 388 }
 389
 390 /*
 391  * Build the path to the log file
 392  * @name     : the name of the container
 393  * @lxcpath  : the lxcpath to use as a basename or NULL to use LOGPATH
 394  * Returns malloced path on success, or NULL on failure
 395  */
 396 static char *build_log_path(const char *name, const char *lxcpath)
 397 {
 398         char *p;
 399         int len, ret, use_dir;
 400
 401         if (!name)
 402                 return NULL;
 403
 404 #if USE_CONFIGPATH_LOGS
 405         use_dir = 1;
 406 #else
 407         use_dir = 0;
 408 #endif
 409
 410         /*
 411          * If USE_CONFIGPATH_LOGS is true or lxcpath is given, the resulting
 412          * path will be:
 413          * '$logpath' + '/' + '$name' + '/' + '$name' + '.log' + '\0'
 414          *
 415          * If USE_CONFIGPATH_LOGS is false the resulting path will be:
 416          * '$logpath' + '/' + '$name' + '.log' + '\0'
 417          */
 418         len = strlen(name) + 6; /* 6 == '/' + '.log' + '\0' */
 419         if (lxcpath)
 420                 use_dir = 1;
 421         else
 422                 lxcpath = LOGPATH;
 423
 424         if (use_dir)
 425                 len += strlen(lxcpath) + 1 + strlen(name) + 1;  /* add "/$container_name/" */
 426         else
 427                 len += strlen(lxcpath) + 1;
 428         p = malloc(len);
 429         if (!p)
 430                 return p;
 431
 432         if (use_dir)
 433                 ret = snprintf(p, len, "%s/%s/%s.log", lxcpath, name, name);
 434         else
 435                 ret = snprintf(p, len, "%s/%s.log", lxcpath, name);
 436
 437         if (ret < 0 || ret >= len) {
 438                 free(p);
 439                 return NULL;
 440         }
 441         return p;
 442 }
 443
 444 extern void lxc_log_close(void)
 445 {
 446         closelog();
 447         free(log_vmname);
 448         log_vmname = NULL;
 449         if (lxc_log_fd == -1)
 450                 return;
 451         close(lxc_log_fd);
 452         lxc_log_fd = -1;
 453         free(log_fname);
 454         log_fname = NULL;
 455 }
 456
 457 /*
 458  * This can be called:
 459  *   1. when a program calls lxc_log_init with no logfile parameter (in which
 460  *      case the default is used).  In this case lxc.logfile can override this.
 461  *   2. when a program calls lxc_log_init with a logfile parameter.  In this
 462  *      case we don't want lxc.logfile to override this.
 463  *   3. When a lxc.logfile entry is found in config file.
 464  */
 465 static int __lxc_log_set_file(const char *fname, int create_dirs)
 466 {
 467         if (lxc_log_fd != -1) {
 468                 // we are overriding the default.
 469                 lxc_log_close();
 470         }
 471
 472         if (!fname)
 473                 return -1;
 474
 475         if (strlen(fname) == 0) {
 476                 log_fname = NULL;
 477                 return 0;
 478         }
 479
 480 #if USE_CONFIGPATH_LOGS
 481         // we don't build_dir for the default if the default is
 482         // i.e. /var/lib/lxc/$container/$container.log
 483         if (create_dirs)
 484 #endif
 485         if (build_dir(fname)) {
 486                 ERROR("failed to create dir for log file \"%s\" : %s", fname,
 487                       strerror(errno));
 488                 return -1;
 489         }
 490
 491         lxc_log_fd = log_open(fname);
 492         if (lxc_log_fd == -1)
 493                 return -1;
 494
 495         log_fname = strdup(fname);
 496         return 0;
 497 }
 498
 499 static int _lxc_log_set_file(const char *name, const char *lxcpath, int create_dirs)
 500 {
 501         char *logfile;
 502         int ret;
 503
 504         logfile = build_log_path(name, lxcpath);
 505         if (!logfile) {
 506                 ERROR("could not build log path");
 507                 return -1;
 508         }
 509         ret = __lxc_log_set_file(logfile, create_dirs);
 510         free(logfile);
 511         return ret;
 512 }
 513
 514 extern int lxc_log_syslog(int facility)
 515 {
 516         struct lxc_log_appender *appender;
 517
 518         openlog(log_prefix, LOG_PID, facility);
 519         if (!lxc_log_category_lxc.appender) {
 520                 lxc_log_category_lxc.appender = &log_appender_syslog;
 521                 return 0;
 522         }
 523         appender = lxc_log_category_lxc.appender;
 524         while (appender->next != NULL)
 525                 appender = appender->next;
 526         appender->next = &log_appender_syslog;
 527
 528         return 0;
 529 }
 530
 531 extern void lxc_log_enable_syslog(void)
 532 {
 533         syslog_enable = 1;
 534 }
 535
 536 /*
 537  * lxc_log_init:
 538  * Called from lxc front-end programs (like lxc-create, lxc-start) to
 539  * initalize the log defaults.
 540  */
 541 extern int lxc_log_init(const char *name, const char *file,
 542                         const char *priority, const char *prefix, int quiet,
 543                         const char *lxcpath)
 544 {
 545         int lxc_priority = LXC_LOG_PRIORITY_ERROR;
 546         int ret;
 547
 548         if (lxc_log_fd != -1) {
 549                 WARN("lxc_log_init called with log already initialized");
 550                 return 0;
 551         }
 552
 553         if (priority)
 554                 lxc_priority = lxc_log_priority_to_int(priority);
 555
 556         if (!lxc_loglevel_specified) {
 557                 lxc_log_category_lxc.priority = lxc_priority;
 558                 lxc_loglevel_specified = 1;
 559         }
 560
 561         if (!lxc_quiet_specified) {
 562                 if (!quiet)
 563                         lxc_log_category_lxc.appender->next = &log_appender_stderr;
 564         }
 565
 566         if (prefix)
 567                 lxc_log_set_prefix(prefix);
 568
 569         if (name)
 570                 log_vmname = strdup(name);
 571
 572         if (file) {
 573                 if (strcmp(file, "none") == 0)
 574                         return 0;
 575                 ret = __lxc_log_set_file(file, 1);
 576                 lxc_log_use_global_fd = 1;
 577         } else {
 578                 /* if no name was specified, there nothing to do */
 579                 if (!name)
 580                         return 0;
 581
 582                 ret = -1;
 583
 584                 if (!lxcpath)
 585                         lxcpath = LOGPATH;
 586
 587                 /* try LOGPATH if lxcpath is the default for the privileged containers */
 588                 if (!geteuid() && strcmp(LXCPATH, lxcpath) == 0)
 589                         ret = _lxc_log_set_file(name, NULL, 0);
 590
 591                 /* try in lxcpath */
 592                 if (ret < 0)
 593                         ret = _lxc_log_set_file(name, lxcpath, 1);
 594
 595                 /* try LOGPATH in case its writable by the caller */
 596                 if (ret < 0)
 597                         ret = _lxc_log_set_file(name, NULL, 0);
 598         }
 599
 600         /*
 601          * If !file, that is, if the user did not request this logpath, then
 602          * ignore failures and continue logging to console
 603          */
 604         if (!file && ret != 0) {
 605                 INFO("Ignoring failure to open default logfile.");
 606                 ret = 0;
 607         }
 608
 609         return ret;
 610 }
 611
 612 /*
 613  * This is called when we read a lxc.loglevel entry in a lxc.conf file.  This
 614  * happens after processing command line arguments, which override the .conf
 615  * settings.  So only set the level if previously unset.
 616  */
 617 extern int lxc_log_set_level(int *dest, int level)
 618 {
 619         if (level < 0 || level >= LXC_LOG_PRIORITY_NOTSET) {
 620                 ERROR("invalid log priority %d", level);
 621                 return -1;
 622         }
 623         *dest = level;
 624         return 0;
 625 }
 626
 627 extern int lxc_log_get_level(void)
 628 {
 629         return lxc_log_category_lxc.priority;
 630 }
 631
 632 extern bool lxc_log_has_valid_level(void)
 633 {
 634         int log_level = lxc_log_get_level();
 635         if (log_level < 0 || log_level >= LXC_LOG_PRIORITY_NOTSET)
 636                 return false;
 637         return true;
 638 }
 639
 640 /*
 641  * This is called when we read a lxc.logfile entry in a lxc.conf file.  This
 642  * happens after processing command line arguments, which override the .conf
 643  * settings.  So only set the file if previously unset.
 644  */
 645 extern int lxc_log_set_file(int *fd, const char *fname)
 646 {
 647         if (*fd != -1) {
 648                 close(*fd);
 649                 *fd = -1;
 650         }
 651
 652         if (build_dir(fname)) {
 653                 ERROR("failed to create dir for log file \"%s\" : %s", fname,
 654                                 strerror(errno));
 655                 return -1;
 656         }
 657
 658         *fd = log_open(fname);
 659         if (*fd == -1)
 660                 return -errno;
 661         return 0;
 662 }
 663
 664 extern const char *lxc_log_get_file(void)
 665 {
 666         return log_fname;
 667 }
 668
 669 extern void lxc_log_set_prefix(const char *prefix)
 670 {
 671         strncpy(log_prefix, prefix, sizeof(log_prefix));
 672         log_prefix[sizeof(log_prefix) - 1] = 0;
 673 }
 674
 675 extern const char *lxc_log_get_prefix(void)
 676 {
 677         return log_prefix;
 678 }
 679
 680 extern void lxc_log_options_no_override()
 681 {
 682         lxc_quiet_specified = 1;
 683         lxc_loglevel_specified = 1;
 684 }