ctdb/server/ctdb_logging.c

   1 /*
   2    ctdb logging code
   3
   4    Copyright (C) Andrew Tridgell  2008
   5
   6    This program is free software; you can redistribute it and/or modify
   7    it under the terms of the GNU General Public License as published by
   8    the Free Software Foundation; either version 3 of the License, or
   9    (at your option) any later version.
  10
  11    This program is distributed in the hope that it will be useful,
  12    but WITHOUT ANY WARRANTY; without even the implied warranty of
  13    MERCHANTABILITY or FITNESS FOR A PARTICULAR PURPOSE.  See the
  14    GNU General Public License for more details.
  15
  16    You should have received a copy of the GNU General Public License
  17    along with this program; if not, see <http://www.gnu.org/licenses/>.
  18 */
  19
  20 #include "includes.h"
  21 #include "../include/ctdb_client.h"
  22 #include "../include/ctdb_private.h"
  23 #include "system/syslog.h"
  24 #include "system/time.h"
  25 #include "system/filesys.h"
  26
  27 struct syslog_message {
  28         uint32_t level;
  29         uint32_t len;
  30         char message[1];
  31 };
  32
  33
  34 struct ctdb_syslog_state {
  35         int syslog_fd;
  36         int fd[2];
  37 };
  38
  39 static int syslogd_is_started = 0;
  40
  41 /* called when child is finished
  42  * this is for the syslog daemon, we can not use DEBUG here
  43  */
  44 static void ctdb_syslog_handler(struct event_context *ev, struct fd_event *fde,
  45                                       uint16_t flags, void *p)
  46 {
  47         struct ctdb_syslog_state *state = talloc_get_type(p, struct ctdb_syslog_state);
  48
  49         int count;
  50         char str[65536];
  51         struct syslog_message *msg;
  52
  53         if (state == NULL) {
  54                 return;
  55         }
  56
  57         count = recv(state->syslog_fd, str, sizeof(str), 0);
  58         if (count < sizeof(struct syslog_message)) {
  59                 return;
  60         }
  61         msg = (struct syslog_message *)str;
  62         if (msg->len >= (sizeof(str) - offsetof(struct syslog_message, message))) {
  63                 msg->len = (sizeof(str)-1) - offsetof(struct syslog_message, message);
  64         }
  65         msg->message[msg->len] = '\0';
  66
  67         syslog(msg->level, "%s", msg->message);
  68 }
  69
  70
  71 /* called when the pipe from the main daemon has closed
  72  * this is for the syslog daemon, we can not use DEBUG here
  73  */
  74 static void ctdb_syslog_terminate_handler(struct event_context *ev, struct fd_event *fde,
  75                                       uint16_t flags, void *p)
  76 {
  77         syslog(LOG_ERR, "Shutting down SYSLOG daemon with pid:%d", (int)getpid());
  78         _exit(0);
  79 }
  80
  81
  82
  83 /*
  84  * this is for the syslog daemon, we can not use DEBUG here
  85  */
  86 int start_syslog_daemon(struct ctdb_context *ctdb)
  87 {
  88         struct sockaddr_in syslog_sin;
  89         struct ctdb_syslog_state *state;
  90         struct tevent_fd *fde;
  91         int startup_fd[2];
  92         int ret = -1;
  93
  94         state = talloc(ctdb, struct ctdb_syslog_state);
  95         CTDB_NO_MEMORY(ctdb, state);
  96
  97         if (pipe(state->fd) != 0) {
  98                 printf("Failed to create syslog pipe\n");
  99                 talloc_free(state);
 100                 return -1;
 101         }
 102
 103         if (pipe(startup_fd) != 0) {
 104                 printf("Failed to create syslog startup pipe\n");
 105                 close(state->fd[0]);
 106                 close(state->fd[1]);
 107                 talloc_free(state);
 108                 return -1;
 109         }
 110
 111         ctdb->syslogd_pid = ctdb_fork(ctdb);
 112         if (ctdb->syslogd_pid == (pid_t)-1) {
 113                 printf("Failed to create syslog child process\n");
 114                 close(state->fd[0]);
 115                 close(state->fd[1]);
 116                 close(startup_fd[0]);
 117                 close(startup_fd[1]);
 118                 talloc_free(state);
 119                 return -1;
 120         }
 121
 122         if (ctdb->syslogd_pid != 0) {
 123                 ssize_t n;
 124                 int dummy;
 125
 126                 DEBUG(DEBUG_ERR,("Starting SYSLOG child process with pid:%d\n", (int)ctdb->syslogd_pid));
 127
 128                 close(state->fd[1]);
 129                 set_close_on_exec(state->fd[0]);
 130
 131                 close(startup_fd[1]);
 132                 n = read(startup_fd[0], &dummy, sizeof(dummy));
 133                 close(startup_fd[0]);
 134                 if (n < sizeof(dummy)) {
 135                         return -1;
 136                 }
 137
 138                 syslogd_is_started = 1;
 139                 return 0;
 140         }
 141
 142         debug_extra = talloc_asprintf(NULL, "syslogd:");
 143         talloc_free(ctdb->ev);
 144         ctdb->ev = event_context_init(NULL);
 145
 146         syslog(LOG_ERR, "Starting SYSLOG daemon with pid:%d", (int)getpid());
 147         ctdb_set_process_name("ctdb_syslogd");
 148
 149         close(state->fd[0]);
 150         close(startup_fd[0]);
 151         set_close_on_exec(state->fd[1]);
 152         set_close_on_exec(startup_fd[1]);
 153         fde = event_add_fd(ctdb->ev, state, state->fd[1], EVENT_FD_READ,
 154                      ctdb_syslog_terminate_handler, state);
 155         tevent_fd_set_auto_close(fde);
 156
 157         state->syslog_fd = socket(AF_INET, SOCK_DGRAM, IPPROTO_UDP);
 158         if (state->syslog_fd == -1) {
 159                 printf("Failed to create syslog socket\n");
 160                 close(startup_fd[1]);
 161                 return ret;
 162         }
 163
 164         set_close_on_exec(state->syslog_fd);
 165
 166         syslog_sin.sin_family = AF_INET;
 167         syslog_sin.sin_port   = htons(CTDB_PORT);
 168         syslog_sin.sin_addr.s_addr = htonl(INADDR_LOOPBACK);
 169
 170         if (bind(state->syslog_fd, (struct sockaddr *)&syslog_sin,
 171                  sizeof(syslog_sin)) == -1)
 172         {
 173                 printf("syslog daemon failed to bind to socket. errno:%d(%s)\n", errno, strerror(errno));
 174                 close(startup_fd[1]);
 175                 _exit(10);
 176         }
 177
 178
 179         fde = event_add_fd(ctdb->ev, state, state->syslog_fd, EVENT_FD_READ,
 180                      ctdb_syslog_handler, state);
 181         tevent_fd_set_auto_close(fde);
 182
 183         /* Tell parent that we're up */
 184         ret = 0;
 185         write(startup_fd[1], &ret, sizeof(ret));
 186         close(startup_fd[1]);
 187
 188         event_loop_wait(ctdb->ev);
 189
 190         /* this should not happen */
 191         _exit(10);
 192 }
 193
 194 struct ctdb_log_state {
 195         struct ctdb_context *ctdb;
 196         const char *prefix;
 197         int fd, pfd;
 198         char buf[1024];
 199         uint16_t buf_used;
 200         bool use_syslog;
 201         void (*logfn)(const char *, uint16_t, void *);
 202         void *logfn_private;
 203 };
 204
 205 /* we need this global to keep the DEBUG() syntax */
 206 static struct ctdb_log_state *log_state;
 207
 208 /*
 209   syslog logging function
 210  */
 211 static void ctdb_syslog_log(const char *format, va_list ap)
 212 {
 213         struct syslog_message *msg;
 214         int level = LOG_DEBUG;
 215         char *s = NULL;
 216         int len, ret;
 217         int syslog_fd;
 218         struct sockaddr_in syslog_sin;
 219
 220         ret = vasprintf(&s, format, ap);
 221         if (ret == -1) {
 222                 return;
 223         }
 224
 225         switch (this_log_level) {
 226         case DEBUG_EMERG:
 227                 level = LOG_EMERG;
 228                 break;
 229         case DEBUG_ALERT:
 230                 level = LOG_ALERT;
 231                 break;
 232         case DEBUG_CRIT:
 233                 level = LOG_CRIT;
 234                 break;
 235         case DEBUG_ERR:
 236                 level = LOG_ERR;
 237                 break;
 238         case DEBUG_WARNING:
 239                 level = LOG_WARNING;
 240                 break;
 241         case DEBUG_NOTICE:
 242                 level = LOG_NOTICE;
 243                 break;
 244         case DEBUG_INFO:
 245                 level = LOG_INFO;
 246                 break;
 247         default:
 248                 level = LOG_DEBUG;
 249                 break;
 250         }
 251
 252         len = offsetof(struct syslog_message, message) + strlen(debug_extra) + strlen(s) + 1;
 253         msg = malloc(len);
 254         if (msg == NULL) {
 255                 free(s);
 256                 return;
 257         }
 258         msg->level = level;
 259         msg->len   = strlen(debug_extra) + strlen(s);
 260         strcpy(msg->message, debug_extra);
 261         strcat(msg->message, s);
 262
 263         if (syslogd_is_started == 0) {
 264                 syslog(msg->level, "%s", msg->message);
 265         } else {
 266                 syslog_fd = socket(AF_INET, SOCK_DGRAM, IPPROTO_UDP);
 267                 if (syslog_fd == -1) {
 268                         printf("Failed to create syslog socket\n");
 269                         free(s);
 270                         free(msg);
 271                         return;
 272                 }
 273
 274                 syslog_sin.sin_family = AF_INET;
 275                 syslog_sin.sin_port   = htons(CTDB_PORT);
 276                 syslog_sin.sin_addr.s_addr = htonl(INADDR_LOOPBACK);
 277
 278                 ret = sendto(syslog_fd, msg, len, 0,
 279                              (struct sockaddr *)&syslog_sin,
 280                              sizeof(syslog_sin));
 281                 /* no point in checking here since we cant log an error */
 282
 283                 close(syslog_fd);
 284         }
 285
 286         free(s);
 287         free(msg);
 288 }
 289
 290
 291 /*
 292   log file logging function
 293  */
 294 static void ctdb_logfile_log(const char *format, va_list ap)
 295 {
 296         struct timeval t;
 297         char *s = NULL;
 298         struct tm *tm;
 299         char tbuf[100];
 300         char *s2 = NULL;
 301         int ret;
 302
 303         ret = vasprintf(&s, format, ap);
 304         if (ret == -1) {
 305                 const char *errstr = "vasprintf failed\n";
 306
 307                 write(log_state->fd, errstr, strlen(errstr));
 308                 return;
 309         }
 310
 311         t = timeval_current();
 312         tm = localtime(&t.tv_sec);
 313
 314         strftime(tbuf,sizeof(tbuf)-1,"%Y/%m/%d %H:%M:%S", tm);
 315
 316         ret = asprintf(&s2, "%s.%06u [%s%5u]: %s",
 317                        tbuf, (unsigned)t.tv_usec,
 318                        debug_extra, (unsigned)getpid(), s);
 319         free(s);
 320         if (ret == -1) {
 321                 const char *errstr = "asprintf failed\n";
 322                 write(log_state->fd, errstr, strlen(errstr));
 323                 return;
 324         }
 325         if (s2) {
 326                 write(log_state->fd, s2, strlen(s2));
 327                 free(s2);
 328         }
 329 }
 330
 331 static void ctdb_logfile_log_add(const char *format, va_list ap)
 332 {
 333         char *s = NULL;
 334         int ret;
 335
 336         ret = vasprintf(&s, format, ap);
 337         if (ret == -1) {
 338                 const char *errstr = "vasprintf failed\n";
 339
 340                 write(log_state->fd, errstr, strlen(errstr));
 341                 return;
 342         }
 343
 344         if (s) {
 345                 write(log_state->fd, s, strlen(s));
 346                 free(s);
 347         }
 348 }
 349
 350
 351
 352 /*
 353   choose the logfile location
 354 */
 355 int ctdb_set_logfile(struct ctdb_context *ctdb, const char *logfile, bool use_syslog)
 356 {
 357         int ret;
 358
 359         ctdb->log = talloc_zero(ctdb, struct ctdb_log_state);
 360         if (ctdb->log == NULL) {
 361                 printf("talloc_zero failed\n");
 362                 abort();
 363         }
 364
 365         ctdb->log->ctdb = ctdb;
 366         log_state = ctdb->log;
 367
 368         if (use_syslog) {
 369                 do_debug_v = ctdb_syslog_log;
 370                 do_debug_add_v = ctdb_syslog_log;
 371                 ctdb->log->use_syslog = true;
 372         } else if (logfile == NULL || strcmp(logfile, "-") == 0) {
 373                 do_debug_v = ctdb_logfile_log;
 374                 do_debug_add_v = ctdb_logfile_log_add;
 375                 ctdb->log->fd = 1;
 376                 /* also catch stderr of subcommands to stdout */
 377                 ret = dup2(1, 2);
 378                 if (ret == -1) {
 379                         printf("dup2 failed: %s\n", strerror(errno));
 380                         abort();
 381                 }
 382         } else {
 383                 do_debug_v = ctdb_logfile_log;
 384                 do_debug_add_v = ctdb_logfile_log_add;
 385
 386                 ctdb->log->fd = open(logfile, O_WRONLY|O_APPEND|O_CREAT, 0666);
 387                 if (ctdb->log->fd == -1) {
 388                         printf("Failed to open logfile %s\n", logfile);
 389                         abort();
 390                 }
 391         }
 392
 393         return 0;
 394 }
 395
 396 /* Note that do_debug always uses the global log state. */
 397 static void write_to_log(struct ctdb_log_state *log,
 398                          const char *buf, unsigned int len)
 399 {
 400         if (script_log_level <= LogLevel) {
 401                 if (log != NULL && log->prefix != NULL) {
 402                         do_debug("%s: %*.*s\n", log->prefix, len, len, buf);
 403                 } else {
 404                         do_debug("%*.*s\n", len, len, buf);
 405                 }
 406                 /* log it in the eventsystem as well */
 407                 if (log && log->logfn) {
 408                         log->logfn(log->buf, len, log->logfn_private);
 409                 }
 410         }
 411 }
 412
 413 /*
 414   called when log data comes in from a child process
 415  */
 416 static void ctdb_log_handler(struct event_context *ev, struct fd_event *fde,
 417                              uint16_t flags, void *private)
 418 {
 419         struct ctdb_log_state *log = talloc_get_type(private, struct ctdb_log_state);
 420         char *p;
 421         int n;
 422
 423         if (!(flags & EVENT_FD_READ)) {
 424                 return;
 425         }
 426
 427         n = read(log->pfd, &log->buf[log->buf_used],
 428                  sizeof(log->buf) - log->buf_used);
 429         if (n > 0) {
 430                 log->buf_used += n;
 431         } else if (n == 0) {
 432                 if (log != log_state) {
 433                         talloc_free(log);
 434                 }
 435                 return;
 436         }
 437
 438         this_log_level = script_log_level;
 439
 440         while (log->buf_used > 0 &&
 441                (p = memchr(log->buf, '\n', log->buf_used)) != NULL) {
 442                 int n1 = (p - log->buf)+1;
 443                 int n2 = n1 - 1;
 444                 /* swallow \r from child processes */
 445                 if (n2 > 0 && log->buf[n2-1] == '\r') {
 446                         n2--;
 447                 }
 448                 write_to_log(log, log->buf, n2);
 449                 memmove(log->buf, p+1, sizeof(log->buf) - n1);
 450                 log->buf_used -= n1;
 451         }
 452
 453         /* the buffer could have completely filled - unfortunately we have
 454            no choice but to dump it out straight away */
 455         if (log->buf_used == sizeof(log->buf)) {
 456                 write_to_log(log, log->buf, log->buf_used);
 457                 log->buf_used = 0;
 458         }
 459 }
 460
 461 static int log_context_destructor(struct ctdb_log_state *log)
 462 {
 463         /* Flush buffer in case it wasn't \n-terminated. */
 464         if (log->buf_used > 0) {
 465                 this_log_level = script_log_level;
 466                 write_to_log(log, log->buf, log->buf_used);
 467         }
 468         return 0;
 469 }
 470
 471 /*
 472  * vfork + exec, redirecting child output to logging and specified callback.
 473  */
 474 struct ctdb_log_state *ctdb_vfork_with_logging(TALLOC_CTX *mem_ctx,
 475                                                struct ctdb_context *ctdb,
 476                                                const char *log_prefix,
 477                                                const char *helper,
 478                                                int helper_argc,
 479                                                const char **helper_argv,
 480                                                void (*logfn)(const char *, uint16_t, void *),
 481                                                void *logfn_private, pid_t *pid)
 482 {
 483         int p[2];
 484         struct ctdb_log_state *log;
 485         struct tevent_fd *fde;
 486         char **argv;
 487         int i;
 488
 489         log = talloc_zero(mem_ctx, struct ctdb_log_state);
 490         CTDB_NO_MEMORY_NULL(ctdb, log);
 491
 492         log->ctdb = ctdb;
 493         log->prefix = log_prefix;
 494         log->logfn = logfn;
 495         log->logfn_private = logfn_private;
 496
 497         if (pipe(p) != 0) {
 498                 DEBUG(DEBUG_ERR, (__location__ " Failed to setup pipe for child logging\n"));
 499                 goto free_log;
 500         }
 501
 502         argv = talloc_array(mem_ctx, char *, helper_argc + 2);
 503         if (argv == NULL) {
 504                 DEBUG(DEBUG_ERR, (__location__ "Failed to allocate memory for helper\n"));
 505                 goto free_log;
 506         }
 507         argv[0] = discard_const(helper);
 508         argv[1] = talloc_asprintf(argv, "%d", p[1]);
 509         if (argv[1] == NULL) {
 510                 DEBUG(DEBUG_ERR, (__location__ "Failed to allocate memory for helper\n"));
 511                 talloc_free(argv);
 512                 goto free_log;
 513         }
 514
 515         for (i=0; i<helper_argc; i++) {
 516                 argv[i+2] = discard_const(helper_argv[i]);
 517         }
 518
 519         *pid = vfork();
 520         if (*pid == 0) {
 521                 execv(helper, argv);
 522                 _exit(1);
 523         }
 524         close(p[1]);
 525
 526         if (*pid < 0) {
 527                 DEBUG(DEBUG_ERR, (__location__ "vfork failed for helper process\n"));
 528                 close(p[0]);
 529                 goto free_log;
 530         }
 531
 532         ctdb_track_child(ctdb, *pid);
 533
 534         log->pfd = p[0];
 535         set_close_on_exec(log->pfd);
 536         talloc_set_destructor(log, log_context_destructor);
 537         fde = tevent_add_fd(ctdb->ev, log, log->pfd, EVENT_FD_READ,
 538                             ctdb_log_handler, log);
 539         tevent_fd_set_auto_close(fde);
 540
 541         return log;
 542
 543 free_log:
 544         talloc_free(log);
 545         return NULL;
 546 }
 547
 548
 549 /*
 550   setup for logging of child process stdout
 551 */
 552 int ctdb_set_child_logging(struct ctdb_context *ctdb)
 553 {
 554         int p[2];
 555         int old_stdout, old_stderr;
 556         struct tevent_fd *fde;
 557
 558         if (ctdb->log->fd == STDOUT_FILENO) {
 559                 /* not needed for stdout logging */
 560                 return 0;
 561         }
 562
 563         /* setup a pipe to catch IO from subprocesses */
 564         if (pipe(p) != 0) {
 565                 DEBUG(DEBUG_ERR,(__location__ " Failed to setup for child logging pipe\n"));
 566                 return -1;
 567         }
 568
 569         /* We'll fail if stderr/stdout not already open; it's simpler. */
 570         old_stdout = dup(STDOUT_FILENO);
 571         old_stderr = dup(STDERR_FILENO);
 572         if (old_stdout < 0 || old_stderr < 0) {
 573                 DEBUG(DEBUG_ERR, ("Failed to dup stdout/stderr for child logging\n"));
 574                 return -1;
 575         }
 576         if (dup2(p[1], STDOUT_FILENO) < 0 || dup2(p[1], STDERR_FILENO) < 0) {
 577                 int saved_errno = errno;
 578                 dup2(old_stdout, STDOUT_FILENO);
 579                 dup2(old_stderr, STDERR_FILENO);
 580                 close(old_stdout);
 581                 close(old_stderr);
 582                 close(p[0]);
 583                 close(p[1]);
 584                 errno = saved_errno;
 585
 586                 printf(__location__ " dup2 failed: %s\n",
 587                         strerror(errno));
 588                 return -1;
 589         }
 590         close(p[1]);
 591         close(old_stdout);
 592         close(old_stderr);
 593
 594         fde = event_add_fd(ctdb->ev, ctdb->log, p[0],
 595                            EVENT_FD_READ, ctdb_log_handler, ctdb->log);
 596         tevent_fd_set_auto_close(fde);
 597
 598         ctdb->log->pfd = p[0];
 599
 600         DEBUG(DEBUG_DEBUG, (__location__ " Created PIPE FD:%d for logging\n", p[0]));
 601
 602         return 0;
 603 }
 604
 605
 606 /*
 607  * set up a log handler to catch logging from TEVENT
 608  */
 609 static void ctdb_tevent_logging(void *private_data,
 610                                 enum tevent_debug_level level,
 611                                 const char *fmt,
 612                                 va_list ap)
 613 {
 614         enum debug_level lvl = DEBUG_CRIT;
 615
 616         switch (level) {
 617         case TEVENT_DEBUG_FATAL:
 618                 lvl = DEBUG_CRIT;
 619                 break;
 620         case TEVENT_DEBUG_ERROR:
 621                 lvl = DEBUG_ERR;
 622                 break;
 623         case TEVENT_DEBUG_WARNING:
 624                 lvl = DEBUG_WARNING;
 625                 break;
 626         case TEVENT_DEBUG_TRACE:
 627                 lvl = DEBUG_DEBUG;
 628                 break;
 629         }
 630
 631         if (lvl <= LogLevel) {
 632                 this_log_level = lvl;
 633                 do_debug_v(fmt, ap);
 634         }
 635 }
 636
 637 int ctdb_init_tevent_logging(struct ctdb_context *ctdb)
 638 {
 639         int ret;
 640
 641         ret = tevent_set_debug(ctdb->ev,
 642                         ctdb_tevent_logging,
 643                         ctdb);
 644         return ret;
 645 }
 646
 647 void ctdb_collect_log(struct ctdb_context *ctdb, struct ctdb_get_log_addr *log_addr)
 648 {
 649         TDB_DATA data;
 650
 651         data = ctdb_log_ringbuffer_collect_log(ctdb, log_addr->level);
 652
 653         DEBUG(DEBUG_ERR,("Send log to %d:%d\n", (int)log_addr->pnn, (int)log_addr->srvid));
 654         ctdb_client_send_message(ctdb, log_addr->pnn, log_addr->srvid, data);
 655
 656         if (data.dptr) {
 657                 talloc_free(data.dptr);
 658         }
 659 }
 660
 661 int32_t ctdb_control_get_log(struct ctdb_context *ctdb, TDB_DATA addr)
 662 {
 663         struct ctdb_get_log_addr *log_addr = (struct ctdb_get_log_addr *)addr.dptr;
 664         pid_t child;
 665
 666         /* spawn a child process to marshall the huge log blob and send it back
 667            to the ctdb tool using a MESSAGE
 668         */
 669         child = ctdb_fork_no_free_ringbuffer(ctdb);
 670         if (child == (pid_t)-1) {
 671                 DEBUG(DEBUG_ERR,("Failed to fork a log collector child\n"));
 672                 return -1;
 673         }
 674
 675         if (child == 0) {
 676                 ctdb_set_process_name("ctdb_log_collector");
 677                 if (switch_from_server_to_client(ctdb, "log-collector") != 0) {
 678                         DEBUG(DEBUG_CRIT, (__location__ "ERROR: failed to switch log collector child into client mode.\n"));
 679                         _exit(1);
 680                 }
 681                 /* do logging here */
 682                 ctdb_collect_log(ctdb, log_addr);
 683                 _exit(0);
 684         }
 685
 686         return 0;
 687 }