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