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