ctdb/common/logging.c

   1 /*
   2    Logging utilities
   3
   4    Copyright (C) Andrew Tridgell  2008
   5    Copyright (C) Martin Schwenke  2014
   6    Copyright (C) Amitay Isaacs  2015
   7
   8    This program is free software; you can redistribute it and/or modify
   9    it under the terms of the GNU General Public License as published by
  10    the Free Software Foundation; either version 3 of the License, or
  11    (at your option) any later version.
  12
  13    This program is distributed in the hope that it will be useful,
  14    but WITHOUT ANY WARRANTY; without even the implied warranty of
  15    MERCHANTABILITY or FITNESS FOR A PARTICULAR PURPOSE.  See the
  16    GNU General Public License for more details.
  17
  18    You should have received a copy of the GNU General Public License
  19    along with this program; if not, see <http://www.gnu.org/licenses/>.
  20 */
  21
  22 #include "replace.h"
  23 #include "system/network.h"
  24 #include "system/locale.h"
  25 #include "system/time.h"
  26 #include "system/filesys.h"
  27 #include "system/syslog.h"
  28 #include "system/dir.h"
  29
  30 #include "lib/util/time_basic.h"
  31 #include "lib/util/sys_rw.h"
  32 #include "lib/util/debug.h"
  33 #include "lib/util/blocking.h"
  34 #include "lib/util/samba_util.h" /* get_myname() */
  35
  36 #include "common/logging.h"
  37
  38 struct {
  39         int log_level;
  40         const char *log_string;
  41 } log_string_map[] = {
  42         { DEBUG_ERR,     "ERROR" },
  43         { DEBUG_WARNING, "WARNING" },
  44         { 2,             "WARNING" },
  45         { DEBUG_NOTICE,  "NOTICE" },
  46         { 4,             "NOTICE" },
  47         { DEBUG_INFO,    "INFO" },
  48         { 6,             "INFO" },
  49         { 7,             "INFO" },
  50         { 8,             "INFO" },
  51         { 9,             "INFO" },
  52         { DEBUG_DEBUG,   "DEBUG" },
  53 };
  54
  55 bool debug_level_parse(const char *log_string, int *log_level)
  56 {
  57         size_t i;
  58
  59         if (log_string == NULL) {
  60                 return false;
  61         }
  62
  63         if (isdigit(log_string[0])) {
  64                 int level = atoi(log_string);
  65
  66                 if (level >= 0 && (size_t)level < ARRAY_SIZE(log_string_map)) {
  67                         *log_level = level;
  68                         return true;
  69                 }
  70                 return false;
  71         }
  72
  73         for (i=0; i<ARRAY_SIZE(log_string_map); i++) {
  74                 if (strncasecmp(log_string_map[i].log_string,
  75                                 log_string, strlen(log_string)) == 0) {
  76                         *log_level = log_string_map[i].log_level;
  77                         return true;
  78                 }
  79         }
  80
  81         return false;
  82 }
  83
  84 const char *debug_level_to_string(int log_level)
  85 {
  86         size_t i;
  87
  88         for (i=0; i < ARRAY_SIZE(log_string_map); i++) {
  89                 if (log_string_map[i].log_level == log_level) {
  90                         return log_string_map[i].log_string;
  91                 }
  92         }
  93         return "UNKNOWN";
  94 }
  95
  96 int debug_level_from_string(const char *log_string)
  97 {
  98         bool found;
  99         int log_level;
 100
 101         found = debug_level_parse(log_string, &log_level);
 102         if (found) {
 103                 return log_level;
 104         }
 105
 106         /* Default debug level */
 107         return DEBUG_ERR;
 108 }
 109
 110 /*
 111  * file logging backend
 112  */
 113
 114 static bool file_log_validate(const char *option)
 115 {
 116         char *t, *dir;
 117         struct stat st;
 118         int ret;
 119
 120         if (option == NULL || strcmp(option, "-") == 0) {
 121                 return true;
 122         }
 123
 124         t = strdup(option);
 125         if (t == NULL) {
 126                 return false;
 127         }
 128
 129         dir = dirname(t);
 130
 131         ret = stat(dir, &st);
 132         free(t);
 133         if (ret != 0) {
 134                 return false;
 135         }
 136
 137         if (! S_ISDIR(st.st_mode)) {
 138                 return false;
 139         }
 140
 141         return true;
 142 }
 143
 144 static int file_log_setup(TALLOC_CTX *mem_ctx,
 145                           const char *option,
 146                           const char *app_name)
 147 {
 148         struct debug_settings settings = {
 149                 .debug_syslog_format = DEBUG_SYSLOG_FORMAT_ALWAYS,
 150                 .debug_hires_timestamp = true,
 151                 .debug_no_stderr_redirect = true,
 152         };
 153         const char *t = NULL;
 154
 155         if (option == NULL || strcmp(option, "-") == 0) {
 156                 /*
 157                  * Logging to stderr is the default and has already
 158                  * been done in logging init
 159                  */
 160                 return 0;
 161         }
 162
 163         /*
 164          * Support logging of fake hostname in local daemons.  This
 165          * hostname is basename(getenv(CTDB_BASE)).
 166          */
 167         t = getenv("CTDB_TEST_MODE");
 168         if (t != NULL) {
 169                 t = getenv("CTDB_BASE");
 170                 if (t != NULL) {
 171                         const char *p = strrchr(t, '/');
 172                         if (p != NULL) {
 173                                 p++;
 174                                 if (p[0] == '\0') {
 175                                         p = "unknown";
 176                                 }
 177                         } else {
 178                                 p = t;
 179                         }
 180
 181                         debug_set_hostname(p);
 182                 }
 183         }
 184
 185         debug_set_settings(&settings, "file", 0, false);
 186         debug_set_logfile(option);
 187         setup_logging(app_name, DEBUG_FILE);
 188
 189         return 0;
 190 }
 191
 192 /*
 193  * syslog logging backend
 194  */
 195
 196 /* Copied from lib/util/debug.c */
 197 static int debug_level_to_priority(int level)
 198 {
 199         /*
 200          * map debug levels to syslog() priorities
 201          */
 202         static const int priority_map[] = {
 203                 LOG_ERR,     /* 0 */
 204                 LOG_WARNING, /* 1 */
 205                 LOG_NOTICE,  /* 2 */
 206                 LOG_NOTICE,  /* 3 */
 207                 LOG_NOTICE,  /* 4 */
 208                 LOG_NOTICE,  /* 5 */
 209                 LOG_INFO,    /* 6 */
 210                 LOG_INFO,    /* 7 */
 211                 LOG_INFO,    /* 8 */
 212                 LOG_INFO,    /* 9 */
 213         };
 214         int priority;
 215
 216         if ((size_t)level >= ARRAY_SIZE(priority_map) || level < 0) {
 217                 priority = LOG_DEBUG;
 218         } else {
 219                 priority = priority_map[level];
 220         }
 221         return priority;
 222 }
 223
 224 struct syslog_log_state {
 225         int fd;
 226         const char *app_name;
 227         const char *hostname;
 228         int (*format)(int dbglevel, struct syslog_log_state *state,
 229                       const char *str, char *buf, int bsize);
 230         /* RFC3164 says: The total length of the packet MUST be 1024
 231            bytes or less. */
 232         char buffer[1024];
 233         unsigned int dropped_count;
 234 };
 235
 236 /* Format messages as per RFC3164
 237  *
 238  * It appears that some syslog daemon implementations do not allow a
 239  * hostname when messages are sent via a Unix domain socket, so omit
 240  * it.  Similarly, syslogd on FreeBSD does not understand the hostname
 241  * part of the header, even when logging via UDP.  Note that most
 242  * implementations will log messages against "localhost" when logging
 243  * via UDP.  A timestamp could be sent but rsyslogd on Linux limits
 244  * the timestamp logged to the precision that was received on
 245  * /dev/log.  It seems sane to send degenerate RFC3164 messages
 246  * without a header at all, so that the daemon will generate high
 247  * resolution timestamps if configured.
 248  */
 249 static int format_rfc3164(int dbglevel, struct syslog_log_state *state,
 250                           const char *str, char *buf, int bsize)
 251 {
 252         int pri;
 253         int len;
 254
 255         pri = LOG_DAEMON | debug_level_to_priority(dbglevel);
 256         len = snprintf(buf, bsize, "<%d>%s[%u]: %s",
 257                        pri, state->app_name, getpid(), str);
 258         buf[bsize-1] = '\0';
 259         len = MIN(len, bsize - 1);
 260
 261         return len;
 262 }
 263
 264 /* Format messages as per RFC5424
 265  *
 266  * <165>1 2003-08-24T05:14:15.000003-07:00 192.0.2.1
 267  *         myproc 8710 - - %% It's time to make the do-nuts.
 268  */
 269 static int format_rfc5424(int dbglevel, struct syslog_log_state *state,
 270                           const char *str, char *buf, int bsize)
 271 {
 272         int pri;
 273         struct timeval tv;
 274         struct timeval_buf tvbuf;
 275         int len, s;
 276
 277         /* Header */
 278         pri = LOG_DAEMON | debug_level_to_priority(dbglevel);
 279         GetTimeOfDay(&tv);
 280         len = snprintf(buf, bsize,
 281                        "<%d>1 %s %s %s %u - - ",
 282                        pri, timeval_str_buf(&tv, true, true, &tvbuf),
 283                        state->hostname, state->app_name, getpid());
 284         /* A truncated header is not useful... */
 285         if (len >= bsize) {
 286                 return -1;
 287         }
 288
 289         /* Message */
 290         s = snprintf(&buf[len], bsize - len, "%s", str);
 291         buf[bsize-1] = '\0';
 292         len = MIN(len + s, bsize - 1);
 293
 294         return len;
 295 }
 296
 297 static void syslog_log(void *private_data, int level, const char *msg)
 298 {
 299         syslog(debug_level_to_priority(level), "%s", msg);
 300 }
 301
 302 static int syslog_log_sock_maybe(struct syslog_log_state *state,
 303                                  int level, const char *msg)
 304 {
 305         int n;
 306         ssize_t ret;
 307
 308         n = state->format(level, state, msg, state->buffer,
 309                           sizeof(state->buffer));
 310         if (n == -1) {
 311                 return E2BIG;
 312         }
 313
 314         do {
 315                 ret = write(state->fd, state->buffer, n);
 316         } while (ret == -1 && errno == EINTR);
 317
 318         if (ret == -1) {
 319                 return errno;
 320         }
 321
 322         return 0;
 323
 324 }
 325 static void syslog_log_sock(void *private_data, int level, const char *msg)
 326 {
 327         struct syslog_log_state *state = talloc_get_type_abort(
 328                 private_data, struct syslog_log_state);
 329         int ret;
 330
 331         if (state->dropped_count > 0) {
 332                 char t[64] = { 0 };
 333                 snprintf(t, sizeof(t),
 334                          "[Dropped %u log messages]\n",
 335                          state->dropped_count);
 336                 t[sizeof(t)-1] = '\0';
 337                 ret = syslog_log_sock_maybe(state, level, t);
 338                 if (ret == EAGAIN || ret == EWOULDBLOCK) {
 339                         state->dropped_count++;
 340                         /*
 341                          * If above failed then actually drop the
 342                          * message that would be logged below, since
 343                          * it would have been dropped anyway and it is
 344                          * also likely to fail.  Falling through and
 345                          * attempting to log the message also means
 346                          * that the dropped message count will be
 347                          * logged out of order.
 348                          */
 349                         return;
 350                 }
 351                 if (ret != 0) {
 352                         /* Silent failure on any other error */
 353                         return;
 354                 }
 355                 state->dropped_count = 0;
 356         }
 357
 358         ret = syslog_log_sock_maybe(state, level, msg);
 359         if (ret == EAGAIN || ret == EWOULDBLOCK) {
 360                 state->dropped_count++;
 361         }
 362 }
 363
 364 static int syslog_log_setup_syslog(TALLOC_CTX *mem_ctx, const char *app_name)
 365 {
 366         openlog(app_name, LOG_PID, LOG_DAEMON);
 367
 368         debug_set_callback(NULL, syslog_log);
 369
 370         return 0;
 371 }
 372
 373 static int syslog_log_state_destructor(struct syslog_log_state *state)
 374 {
 375         if (state->fd != -1) {
 376                 close(state->fd);
 377                 state->fd = -1;
 378         }
 379         return 0;
 380 }
 381
 382 static int syslog_log_setup_common(TALLOC_CTX *mem_ctx, const char *app_name,
 383                                    struct syslog_log_state **result)
 384 {
 385         struct syslog_log_state *state;
 386
 387         state = talloc_zero(mem_ctx, struct syslog_log_state);
 388         if (state == NULL) {
 389                 return ENOMEM;
 390         }
 391
 392         state->fd = -1;
 393         state->app_name = app_name;
 394         talloc_set_destructor(state, syslog_log_state_destructor);
 395
 396         *result = state;
 397         return 0;
 398 }
 399
 400 #ifdef _PATH_LOG
 401 static int syslog_log_setup_nonblocking(TALLOC_CTX *mem_ctx,
 402                                         const char *app_name)
 403 {
 404         struct syslog_log_state *state = NULL;
 405         struct sockaddr_un dest;
 406         int ret;
 407
 408         ret = syslog_log_setup_common(mem_ctx, app_name, &state);
 409         if (ret != 0) {
 410                 return ret;
 411         }
 412
 413         state->fd = socket(AF_UNIX, SOCK_DGRAM, 0);
 414         if (state->fd == -1) {
 415                 int save_errno = errno;
 416                 talloc_free(state);
 417                 return save_errno;
 418         }
 419
 420         dest.sun_family = AF_UNIX;
 421         strncpy(dest.sun_path, _PATH_LOG, sizeof(dest.sun_path)-1);
 422         ret = connect(state->fd,
 423                       (struct sockaddr *)&dest, sizeof(dest));
 424         if (ret == -1) {
 425                 int save_errno = errno;
 426                 talloc_free(state);
 427                 return save_errno;
 428         }
 429
 430         ret = set_blocking(state->fd, false);
 431         if (ret != 0) {
 432                 int save_errno = errno;
 433                 talloc_free(state);
 434                 return save_errno;
 435         }
 436
 437         if (! set_close_on_exec(state->fd)) {
 438                 int save_errno = errno;
 439                 talloc_free(state);
 440                 return save_errno;
 441         }
 442
 443         state->hostname = NULL; /* Make this explicit */
 444         state->format = format_rfc3164;
 445
 446         debug_set_callback(state, syslog_log_sock);
 447
 448         return 0;
 449 }
 450 #endif /* _PATH_LOG */
 451
 452 static int syslog_log_setup_udp(TALLOC_CTX *mem_ctx, const char *app_name,
 453                                 bool rfc5424)
 454 {
 455         struct syslog_log_state *state = NULL;
 456         struct sockaddr_in dest;
 457         int ret;
 458
 459         ret = syslog_log_setup_common(mem_ctx, app_name, &state);
 460         if (ret != 0) {
 461                 return ret;
 462         }
 463
 464         state->fd = socket(AF_INET, SOCK_DGRAM, IPPROTO_UDP);
 465         if (state->fd == -1) {
 466                 int save_errno = errno;
 467                 talloc_free(state);
 468                 return save_errno;
 469         }
 470
 471         dest.sin_family = AF_INET;
 472         dest.sin_port   = htons(514);
 473         dest.sin_addr.s_addr = htonl(INADDR_LOOPBACK);
 474         ret = connect(state->fd,
 475                       (struct sockaddr *)&dest, sizeof(dest));
 476         if (ret == -1) {
 477                 int save_errno = errno;
 478                 talloc_free(state);
 479                 return save_errno;
 480         }
 481
 482         if (! set_close_on_exec(state->fd)) {
 483                 int save_errno = errno;
 484                 talloc_free(state);
 485                 return save_errno;
 486         }
 487
 488         state->hostname = get_myname(state);
 489         if (state->hostname == NULL) {
 490                 /* Use a fallback instead of failing initialisation */
 491                 state->hostname = "localhost";
 492         }
 493         if (rfc5424) {
 494                 state->format = format_rfc5424;
 495         } else {
 496                 state->format = format_rfc3164;
 497         }
 498
 499         debug_set_callback(state, syslog_log_sock);
 500
 501         return 0;
 502 }
 503
 504 static bool syslog_log_validate(const char *option)
 505 {
 506         if (option == NULL) {
 507                 return true;
 508 #ifdef _PATH_LOG
 509         } else if (strcmp(option, "nonblocking") == 0) {
 510                 return true;
 511 #endif
 512         } else if (strcmp(option, "udp") == 0) {
 513                 return true;
 514         } else if (strcmp(option, "udp-rfc5424") == 0) {
 515                 return true;
 516         }
 517
 518         return false;
 519 }
 520
 521 static int syslog_log_setup(TALLOC_CTX *mem_ctx, const char *option,
 522                             const char *app_name)
 523 {
 524         if (option == NULL) {
 525                 return syslog_log_setup_syslog(mem_ctx, app_name);
 526 #ifdef _PATH_LOG
 527         } else if (strcmp(option, "nonblocking") == 0) {
 528                 return syslog_log_setup_nonblocking(mem_ctx, app_name);
 529 #endif
 530         } else if (strcmp(option, "udp") == 0) {
 531                 return syslog_log_setup_udp(mem_ctx, app_name, false);
 532         } else if (strcmp(option, "udp-rfc5424") == 0) {
 533                 return syslog_log_setup_udp(mem_ctx, app_name, true);
 534         }
 535
 536         return EINVAL;
 537 }
 538
 539 struct log_backend {
 540         const char *name;
 541         bool (*validate)(const char *option);
 542         int (*setup)(TALLOC_CTX *mem_ctx,
 543                      const char *option,
 544                      const char *app_name);
 545 };
 546
 547 static struct log_backend log_backend[] = {
 548         {
 549                 .name = "file",
 550                 .validate = file_log_validate,
 551                 .setup = file_log_setup,
 552         },
 553         {
 554                 .name = "syslog",
 555                 .validate = syslog_log_validate,
 556                 .setup = syslog_log_setup,
 557         },
 558 };
 559
 560 static int log_backend_parse(TALLOC_CTX *mem_ctx,
 561                              const char *logging,
 562                              struct log_backend **backend,
 563                              char **backend_option)
 564 {
 565         struct log_backend *b = NULL;
 566         char *t, *name, *option;
 567         size_t i;
 568
 569         t = talloc_strdup(mem_ctx, logging);
 570         if (t == NULL) {
 571                 return ENOMEM;
 572         }
 573
 574         name = strtok(t, ":");
 575         if (name == NULL) {
 576                 talloc_free(t);
 577                 return EINVAL;
 578         }
 579         option = strtok(NULL, ":");
 580
 581         for (i=0; i<ARRAY_SIZE(log_backend); i++) {
 582                 if (strcmp(log_backend[i].name, name) == 0) {
 583                         b = &log_backend[i];
 584                 }
 585         }
 586
 587         if (b == NULL) {
 588                 talloc_free(t);
 589                 return ENOENT;
 590         }
 591
 592         *backend = b;
 593         if (option != NULL) {
 594                 *backend_option = talloc_strdup(mem_ctx, option);
 595                 if (*backend_option == NULL) {
 596                         talloc_free(t);
 597                         return ENOMEM;
 598                 }
 599         } else {
 600                 *backend_option = NULL;
 601         }
 602
 603         talloc_free(t);
 604         return 0;
 605 }
 606
 607 bool logging_validate(const char *logging)
 608 {
 609         TALLOC_CTX *tmp_ctx;
 610         struct log_backend *backend;
 611         char *option;
 612         int ret;
 613         bool status;
 614
 615         tmp_ctx = talloc_new(NULL);
 616         if (tmp_ctx == NULL) {
 617                 return false;
 618         }
 619
 620         ret = log_backend_parse(tmp_ctx, logging, &backend, &option);
 621         if (ret != 0) {
 622                 talloc_free(tmp_ctx);
 623                 return false;
 624         }
 625
 626         status = backend->validate(option);
 627         talloc_free(tmp_ctx);
 628         return status;
 629 }
 630
 631 /* Initialise logging */
 632 int logging_init(TALLOC_CTX *mem_ctx, const char *logging,
 633                  const char *debug_level, const char *app_name)
 634 {
 635         struct log_backend *backend = NULL;
 636         char *option = NULL;
 637         int level;
 638         int ret;
 639
 640         setup_logging(app_name, DEBUG_DEFAULT_STDERR);
 641
 642         if (debug_level == NULL) {
 643                 debug_level = getenv("CTDB_DEBUGLEVEL");
 644         }
 645         if (! debug_level_parse(debug_level, &level)) {
 646                 return EINVAL;
 647         }
 648         debuglevel_set(level);
 649
 650         if (logging == NULL) {
 651                 logging = getenv("CTDB_LOGGING");
 652         }
 653         if (logging == NULL || logging[0] == '\0') {
 654                 return EINVAL;
 655         }
 656
 657         ret = log_backend_parse(mem_ctx, logging, &backend, &option);
 658         if (ret != 0) {
 659                 if (ret == ENOENT) {
 660                         fprintf(stderr, "Invalid logging option \'%s\'\n",
 661                                 logging);
 662                 }
 663                 talloc_free(option);
 664                 return ret;
 665         }
 666
 667         ret = backend->setup(mem_ctx, option, app_name);
 668         talloc_free(option);
 669         return ret;
 670 }
 671
 672 bool logging_reopen_logs(void)
 673 {
 674         bool status;
 675
 676         status = reopen_logs_internal();
 677
 678         return status;
 679 }
 680
 681 struct logging_reopen_logs_data {
 682         void (*hook)(void *private_data);
 683         void *private_data;
 684 };
 685
 686 static void logging_sig_hup_handler(struct tevent_context *ev,
 687                                     struct tevent_signal *se,
 688                                     int signum,
 689                                     int count,
 690                                     void *dont_care,
 691                                     void *private_data)
 692 {
 693         bool status;
 694
 695         if (private_data != NULL) {
 696                 struct logging_reopen_logs_data *data = talloc_get_type_abort(
 697                         private_data, struct logging_reopen_logs_data);
 698
 699                 if (data->hook != NULL) {
 700                         data->hook(data->private_data);
 701                 }
 702         }
 703
 704         status = logging_reopen_logs();
 705         if (!status) {
 706                 D_WARNING("Failed to reopen logs\n");
 707                 return;
 708         }
 709
 710         D_NOTICE("Reopened logs\n");
 711
 712 }
 713
 714 bool logging_setup_sighup_handler(struct tevent_context *ev,
 715                                   TALLOC_CTX *talloc_ctx,
 716                                   void (*hook)(void *private_data),
 717                                   void *private_data)
 718 {
 719         struct logging_reopen_logs_data *data = NULL;
 720         struct tevent_signal *se;
 721
 722         if (hook != NULL) {
 723                 data = talloc(talloc_ctx, struct logging_reopen_logs_data);
 724                 if (data == NULL) {
 725                         return false;
 726                 }
 727
 728                 data->hook = hook;
 729                 data->private_data = private_data;
 730         }
 731
 732
 733         se = tevent_add_signal(ev,
 734                                talloc_ctx,
 735                                SIGHUP,
 736                                0,
 737                                logging_sig_hup_handler,
 738                                data);
 739         if (se == NULL) {
 740                 talloc_free(data);
 741                 return false;
 742         }
 743
 744         return true;
 745 }