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         int 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 && 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         int 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 struct file_log_state {
 115         const char *app_name;
 116         int fd;
 117         char buffer[1024];
 118 };
 119
 120 static void file_log(void *private_data, int level, const char *msg)
 121 {
 122         struct file_log_state *state = talloc_get_type_abort(
 123                 private_data, struct file_log_state);
 124         struct timeval tv;
 125         struct timeval_buf tvbuf;
 126         int ret;
 127
 128         if (state->fd == STDERR_FILENO) {
 129                 ret = snprintf(state->buffer, sizeof(state->buffer),
 130                                "%s[%u]: %s\n",
 131                                state->app_name, (unsigned)getpid(), msg);
 132         } else {
 133                 GetTimeOfDay(&tv);
 134                 timeval_str_buf(&tv, false, true, &tvbuf);
 135
 136                 ret = snprintf(state->buffer, sizeof(state->buffer),
 137                                "%s %s[%u]: %s\n", tvbuf.buf,
 138                                state->app_name, (unsigned)getpid(), msg);
 139         }
 140         if (ret < 0) {
 141                 return;
 142         }
 143
 144         state->buffer[sizeof(state->buffer)-1] = '\0';
 145
 146         sys_write_v(state->fd, state->buffer, strlen(state->buffer));
 147 }
 148
 149 static int file_log_state_destructor(struct file_log_state *state)
 150 {
 151         if (state->fd != -1 && state->fd != STDERR_FILENO) {
 152                 close(state->fd);
 153                 state->fd = -1;
 154         }
 155         return 0;
 156 }
 157
 158 static bool file_log_validate(const char *option)
 159 {
 160         char *t, *dir;
 161         struct stat st;
 162         int ret;
 163
 164         if (option == NULL || strcmp(option, "-") == 0) {
 165                 return true;
 166         }
 167
 168         t = strdup(option);
 169         if (t == NULL) {
 170                 return false;
 171         }
 172
 173         dir = dirname(t);
 174
 175         ret = stat(dir, &st);
 176         free(t);
 177         if (ret != 0) {
 178                 return false;
 179         }
 180
 181         if (! S_ISDIR(st.st_mode)) {
 182                 return false;
 183         }
 184
 185         return true;
 186 }
 187
 188 static int file_log_setup(TALLOC_CTX *mem_ctx, const char *option,
 189                           const char *app_name)
 190 {
 191         struct file_log_state *state;
 192
 193         state = talloc_zero(mem_ctx, struct file_log_state);
 194         if (state == NULL) {
 195                 return ENOMEM;
 196         }
 197
 198         state->app_name = app_name;
 199
 200         if (option == NULL || strcmp(option, "-") == 0) {
 201                 int ret;
 202
 203                 state->fd = STDERR_FILENO;
 204                 ret = dup2(STDERR_FILENO, STDOUT_FILENO);
 205                 if (ret == -1) {
 206                         int save_errno = errno;
 207                         talloc_free(state);
 208                         return save_errno;
 209                 }
 210
 211         } else {
 212                 state->fd = open(option, O_WRONLY|O_APPEND|O_CREAT, 0644);
 213                 if (state->fd == -1) {
 214                         int save_errno = errno;
 215                         talloc_free(state);
 216                         return save_errno;
 217                 }
 218
 219                 if (! set_close_on_exec(state->fd)) {
 220                         int save_errno = errno;
 221                         talloc_free(state);
 222                         return save_errno;
 223                 }
 224         }
 225
 226         talloc_set_destructor(state, file_log_state_destructor);
 227         debug_set_callback(state, file_log);
 228
 229         return 0;
 230 }
 231
 232 /*
 233  * syslog logging backend
 234  */
 235
 236 /* Copied from lib/util/debug.c */
 237 static int debug_level_to_priority(int level)
 238 {
 239         /*
 240          * map debug levels to syslog() priorities
 241          */
 242         static const int priority_map[] = {
 243                 LOG_ERR,     /* 0 */
 244                 LOG_WARNING, /* 1 */
 245                 LOG_NOTICE,  /* 2 */
 246                 LOG_NOTICE,  /* 3 */
 247                 LOG_NOTICE,  /* 4 */
 248                 LOG_NOTICE,  /* 5 */
 249                 LOG_INFO,    /* 6 */
 250                 LOG_INFO,    /* 7 */
 251                 LOG_INFO,    /* 8 */
 252                 LOG_INFO,    /* 9 */
 253         };
 254         int priority;
 255
 256         if( level >= ARRAY_SIZE(priority_map) || level < 0)
 257                 priority = LOG_DEBUG;
 258         else
 259                 priority = priority_map[level];
 260
 261         return priority;
 262 }
 263
 264 struct syslog_log_state {
 265         int fd;
 266         const char *app_name;
 267         const char *hostname;
 268         int (*format)(int dbglevel, struct syslog_log_state *state,
 269                       const char *str, char *buf, int bsize);
 270         /* RFC3164 says: The total length of the packet MUST be 1024
 271            bytes or less. */
 272         char buffer[1024];
 273         unsigned int dropped_count;
 274 };
 275
 276 /* Format messages as per RFC3164
 277  *
 278  * It appears that some syslog daemon implementations do not allow a
 279  * hostname when messages are sent via a Unix domain socket, so omit
 280  * it.  Similarly, syslogd on FreeBSD does not understand the hostname
 281  * part of the header, even when logging via UDP.  Note that most
 282  * implementations will log messages against "localhost" when logging
 283  * via UDP.  A timestamp could be sent but rsyslogd on Linux limits
 284  * the timestamp logged to the precision that was received on
 285  * /dev/log.  It seems sane to send degenerate RFC3164 messages
 286  * without a header at all, so that the daemon will generate high
 287  * resolution timestamps if configured.
 288  */
 289 static int format_rfc3164(int dbglevel, struct syslog_log_state *state,
 290                           const char *str, char *buf, int bsize)
 291 {
 292         int pri;
 293         int len;
 294
 295         pri = LOG_DAEMON | debug_level_to_priority(dbglevel);
 296         len = snprintf(buf, bsize, "<%d>%s[%u]: %s",
 297                        pri, state->app_name, getpid(), str);
 298         buf[bsize-1] = '\0';
 299         len = MIN(len, bsize - 1);
 300
 301         return len;
 302 }
 303
 304 /* Format messages as per RFC5424
 305  *
 306  * <165>1 2003-08-24T05:14:15.000003-07:00 192.0.2.1
 307  *         myproc 8710 - - %% It's time to make the do-nuts.
 308  */
 309 static int format_rfc5424(int dbglevel, struct syslog_log_state *state,
 310                           const char *str, char *buf, int bsize)
 311 {
 312         int pri;
 313         struct timeval tv;
 314         struct timeval_buf tvbuf;
 315         int len, s;
 316
 317         /* Header */
 318         pri = LOG_DAEMON | debug_level_to_priority(dbglevel);
 319         GetTimeOfDay(&tv);
 320         len = snprintf(buf, bsize,
 321                        "<%d>1 %s %s %s %u - - ",
 322                        pri, timeval_str_buf(&tv, true, true, &tvbuf),
 323                        state->hostname, state->app_name, getpid());
 324         /* A truncated header is not useful... */
 325         if (len >= bsize) {
 326                 return -1;
 327         }
 328
 329         /* Message */
 330         s = snprintf(&buf[len], bsize - len, "%s", str);
 331         buf[bsize-1] = '\0';
 332         len = MIN(len + s, bsize - 1);
 333
 334         return len;
 335 }
 336
 337 static void syslog_log(void *private_data, int level, const char *msg)
 338 {
 339         syslog(debug_level_to_priority(level), "%s", msg);
 340 }
 341
 342 static int syslog_log_sock_maybe(struct syslog_log_state *state,
 343                                  int level, const char *msg)
 344 {
 345         int n;
 346         ssize_t ret;
 347
 348         n = state->format(level, state, msg, state->buffer,
 349                           sizeof(state->buffer));
 350         if (n == -1) {
 351                 return E2BIG;
 352         }
 353
 354         do {
 355                 ret = write(state->fd, state->buffer, n);
 356         } while (ret == -1 && errno == EINTR);
 357
 358         if (ret == -1) {
 359                 return errno;
 360         }
 361
 362         return 0;
 363
 364 }
 365 static void syslog_log_sock(void *private_data, int level, const char *msg)
 366 {
 367         struct syslog_log_state *state = talloc_get_type_abort(
 368                 private_data, struct syslog_log_state);
 369         int ret;
 370
 371         if (state->dropped_count > 0) {
 372                 char t[64] = { 0 };
 373                 snprintf(t, sizeof(t),
 374                          "[Dropped %u log messages]\n",
 375                          state->dropped_count);
 376                 t[sizeof(t)-1] = '\0';
 377                 ret = syslog_log_sock_maybe(state, level, t);
 378                 if (ret == EAGAIN || ret == EWOULDBLOCK) {
 379                         state->dropped_count++;
 380                         /*
 381                          * If above failed then actually drop the
 382                          * message that would be logged below, since
 383                          * it would have been dropped anyway and it is
 384                          * also likely to fail.  Falling through and
 385                          * attempting to log the message also means
 386                          * that the dropped message count will be
 387                          * logged out of order.
 388                          */
 389                         return;
 390                 }
 391                 if (ret != 0) {
 392                         /* Silent failure on any other error */
 393                         return;
 394                 }
 395                 state->dropped_count = 0;
 396         }
 397
 398         ret = syslog_log_sock_maybe(state, level, msg);
 399         if (ret == EAGAIN || ret == EWOULDBLOCK) {
 400                 state->dropped_count++;
 401         }
 402 }
 403
 404 static int syslog_log_setup_syslog(TALLOC_CTX *mem_ctx, const char *app_name)
 405 {
 406         openlog(app_name, LOG_PID, LOG_DAEMON);
 407
 408         debug_set_callback(NULL, syslog_log);
 409
 410         return 0;
 411 }
 412
 413 static int syslog_log_state_destructor(struct syslog_log_state *state)
 414 {
 415         if (state->fd != -1) {
 416                 close(state->fd);
 417                 state->fd = -1;
 418         }
 419         return 0;
 420 }
 421
 422 static int syslog_log_setup_common(TALLOC_CTX *mem_ctx, const char *app_name,
 423                                    struct syslog_log_state **result)
 424 {
 425         struct syslog_log_state *state;
 426
 427         state = talloc_zero(mem_ctx, struct syslog_log_state);
 428         if (state == NULL) {
 429                 return ENOMEM;
 430         }
 431
 432         state->fd = -1;
 433         state->app_name = app_name;
 434         talloc_set_destructor(state, syslog_log_state_destructor);
 435
 436         *result = state;
 437         return 0;
 438 }
 439
 440 #ifdef _PATH_LOG
 441 static int syslog_log_setup_nonblocking(TALLOC_CTX *mem_ctx,
 442                                         const char *app_name)
 443 {
 444         struct syslog_log_state *state = NULL;
 445         struct sockaddr_un dest;
 446         int ret;
 447
 448         ret = syslog_log_setup_common(mem_ctx, app_name, &state);
 449         if (ret != 0) {
 450                 return ret;
 451         }
 452
 453         state->fd = socket(AF_UNIX, SOCK_DGRAM, 0);
 454         if (state->fd == -1) {
 455                 int save_errno = errno;
 456                 talloc_free(state);
 457                 return save_errno;
 458         }
 459
 460         dest.sun_family = AF_UNIX;
 461         strncpy(dest.sun_path, _PATH_LOG, sizeof(dest.sun_path)-1);
 462         ret = connect(state->fd,
 463                       (struct sockaddr *)&dest, sizeof(dest));
 464         if (ret == -1) {
 465                 int save_errno = errno;
 466                 talloc_free(state);
 467                 return save_errno;
 468         }
 469
 470         ret = set_blocking(state->fd, false);
 471         if (ret != 0) {
 472                 int save_errno = errno;
 473                 talloc_free(state);
 474                 return save_errno;
 475         }
 476
 477         if (! set_close_on_exec(state->fd)) {
 478                 int save_errno = errno;
 479                 talloc_free(state);
 480                 return save_errno;
 481         }
 482
 483         state->hostname = NULL; /* Make this explicit */
 484         state->format = format_rfc3164;
 485
 486         debug_set_callback(state, syslog_log_sock);
 487
 488         return 0;
 489 }
 490 #endif /* _PATH_LOG */
 491
 492 static int syslog_log_setup_udp(TALLOC_CTX *mem_ctx, const char *app_name,
 493                                 bool rfc5424)
 494 {
 495         struct syslog_log_state *state = NULL;
 496         struct sockaddr_in dest;
 497         int ret;
 498
 499         ret = syslog_log_setup_common(mem_ctx, app_name, &state);
 500         if (ret != 0) {
 501                 return ret;
 502         }
 503
 504         state->fd = socket(AF_INET, SOCK_DGRAM, IPPROTO_UDP);
 505         if (state->fd == -1) {
 506                 int save_errno = errno;
 507                 talloc_free(state);
 508                 return save_errno;
 509         }
 510
 511         dest.sin_family = AF_INET;
 512         dest.sin_port   = htons(514);
 513         dest.sin_addr.s_addr = htonl(INADDR_LOOPBACK);
 514         ret = connect(state->fd,
 515                       (struct sockaddr *)&dest, sizeof(dest));
 516         if (ret == -1) {
 517                 int save_errno = errno;
 518                 talloc_free(state);
 519                 return save_errno;
 520         }
 521
 522         if (! set_close_on_exec(state->fd)) {
 523                 int save_errno = errno;
 524                 talloc_free(state);
 525                 return save_errno;
 526         }
 527
 528         state->hostname = get_myname(state);
 529         if (state->hostname == NULL) {
 530                 /* Use a fallback instead of failing initialisation */
 531                 state->hostname = "localhost";
 532         }
 533         if (rfc5424) {
 534                 state->format = format_rfc5424;
 535         } else {
 536                 state->format = format_rfc3164;
 537         }
 538
 539         debug_set_callback(state, syslog_log_sock);
 540
 541         return 0;
 542 }
 543
 544 static bool syslog_log_validate(const char *option)
 545 {
 546         if (option == NULL) {
 547                 return true;
 548 #ifdef _PATH_LOG
 549         } else if (strcmp(option, "nonblocking") == 0) {
 550                 return true;
 551 #endif
 552         } else if (strcmp(option, "udp") == 0) {
 553                 return true;
 554         } else if (strcmp(option, "udp-rfc5424") == 0) {
 555                 return true;
 556         }
 557
 558         return false;
 559 }
 560
 561 static int syslog_log_setup(TALLOC_CTX *mem_ctx, const char *option,
 562                             const char *app_name)
 563 {
 564         if (option == NULL) {
 565                 return syslog_log_setup_syslog(mem_ctx, app_name);
 566 #ifdef _PATH_LOG
 567         } else if (strcmp(option, "nonblocking") == 0) {
 568                 return syslog_log_setup_nonblocking(mem_ctx, app_name);
 569 #endif
 570         } else if (strcmp(option, "udp") == 0) {
 571                 return syslog_log_setup_udp(mem_ctx, app_name, false);
 572         } else if (strcmp(option, "udp-rfc5424") == 0) {
 573                 return syslog_log_setup_udp(mem_ctx, app_name, true);
 574         }
 575
 576         return EINVAL;
 577 }
 578
 579 struct log_backend {
 580         const char *name;
 581         bool (*validate)(const char *option);
 582         int (*setup)(TALLOC_CTX *mem_ctx,
 583                      const char *option,
 584                      const char *app_name);
 585 };
 586
 587 static struct log_backend log_backend[] = {
 588         {
 589                 .name = "file",
 590                 .validate = file_log_validate,
 591                 .setup = file_log_setup,
 592         },
 593         {
 594                 .name = "syslog",
 595                 .validate = syslog_log_validate,
 596                 .setup = syslog_log_setup,
 597         },
 598 };
 599
 600 static int log_backend_parse(TALLOC_CTX *mem_ctx,
 601                              const char *logging,
 602                              struct log_backend **backend,
 603                              char **backend_option)
 604 {
 605         struct log_backend *b = NULL;
 606         char *t, *name, *option;
 607         int i;
 608
 609         t = talloc_strdup(mem_ctx, logging);
 610         if (t == NULL) {
 611                 return ENOMEM;
 612         }
 613
 614         name = strtok(t, ":");
 615         if (name == NULL) {
 616                 talloc_free(t);
 617                 return EINVAL;
 618         }
 619         option = strtok(NULL, ":");
 620
 621         for (i=0; i<ARRAY_SIZE(log_backend); i++) {
 622                 if (strcmp(log_backend[i].name, name) == 0) {
 623                         b = &log_backend[i];
 624                 }
 625         }
 626
 627         if (b == NULL) {
 628                 talloc_free(t);
 629                 return ENOENT;
 630         }
 631
 632         *backend = b;
 633         if (option != NULL) {
 634                 *backend_option = talloc_strdup(mem_ctx, option);
 635                 if (*backend_option == NULL) {
 636                         talloc_free(t);
 637                         return ENOMEM;
 638                 }
 639         } else {
 640                 *backend_option = NULL;
 641         }
 642
 643         talloc_free(t);
 644         return 0;
 645 }
 646
 647 bool logging_validate(const char *logging)
 648 {
 649         TALLOC_CTX *tmp_ctx;
 650         struct log_backend *backend;
 651         char *option;
 652         int ret;
 653         bool status;
 654
 655         tmp_ctx = talloc_new(NULL);
 656         if (tmp_ctx == NULL) {
 657                 return false;
 658         }
 659
 660         ret = log_backend_parse(tmp_ctx, logging, &backend, &option);
 661         if (ret != 0) {
 662                 talloc_free(tmp_ctx);
 663                 return false;
 664         }
 665
 666         status = backend->validate(option);
 667         talloc_free(tmp_ctx);
 668         return status;
 669 }
 670
 671 /* Initialise logging */
 672 int logging_init(TALLOC_CTX *mem_ctx, const char *logging,
 673                  const char *debug_level, const char *app_name)
 674 {
 675         struct log_backend *backend = NULL;
 676         char *option = NULL;
 677         int level;
 678         int ret;
 679
 680         setup_logging(app_name, DEBUG_STDERR);
 681
 682         if (debug_level == NULL) {
 683                 debug_level = getenv("CTDB_DEBUGLEVEL");
 684         }
 685         if (! debug_level_parse(debug_level, &level)) {
 686                 return EINVAL;
 687         }
 688         debuglevel_set(level);
 689
 690         if (logging == NULL) {
 691                 logging = getenv("CTDB_LOGGING");
 692         }
 693         if (logging == NULL || logging[0] == '\0') {
 694                 return EINVAL;
 695         }
 696
 697         ret = log_backend_parse(mem_ctx, logging, &backend, &option);
 698         if (ret != 0) {
 699                 if (ret == ENOENT) {
 700                         fprintf(stderr, "Invalid logging option \'%s\'\n",
 701                                 logging);
 702                 }
 703                 talloc_free(option);
 704                 return ret;
 705         }
 706
 707         ret = backend->setup(mem_ctx, option, app_name);
 708         talloc_free(option);
 709         return ret;
 710 }