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 "replace.h"
  21 #include "system/filesys.h"
  22 #include "system/network.h"
  23 #include "system/syslog.h"
  24 #include "system/time.h"
  25
  26 #include <talloc.h>
  27 #include <tevent.h>
  28
  29 #include "lib/util/dlinklist.h"
  30 #include "lib/util/debug.h"
  31 #include "lib/util/blocking.h"
  32 #include "lib/util/time.h"
  33
  34 #include "ctdb_private.h"
  35 #include "ctdb_client.h"
  36
  37 #include "common/system.h"
  38 #include "common/common.h"
  39 #include "common/logging.h"
  40
  41 const char *debug_extra = "";
  42
  43 struct ctdb_log_backend {
  44         struct ctdb_log_backend *prev, *next;
  45         const char *prefix;
  46         ctdb_log_setup_fn_t setup;
  47 };
  48
  49 struct ctdb_log_state {
  50         const char *prefix;
  51         int fd, pfd;
  52         char buf[1024];
  53         uint16_t buf_used;
  54         void (*logfn)(const char *, uint16_t, void *);
  55         void *logfn_private;
  56         struct ctdb_log_backend *backends;
  57 };
  58
  59 /* Used by ctdb_set_child_logging() */
  60 static struct ctdb_log_state *log_state;
  61
  62 void ctdb_log_register_backend(const char *prefix, ctdb_log_setup_fn_t setup)
  63 {
  64         struct ctdb_log_backend *b;
  65
  66         b = talloc_zero(log_state, struct ctdb_log_backend);
  67         if (b == NULL) {
  68                 printf("Failed to register backend \"%s\" - no memory\n",
  69                        prefix);
  70                 return;
  71         }
  72
  73         b->prefix = prefix;
  74         b->setup = setup;
  75
  76         DLIST_ADD_END(log_state->backends, b);
  77 }
  78
  79
  80 /* Initialise logging */
  81 bool ctdb_logging_init(TALLOC_CTX *mem_ctx, const char *logging)
  82 {
  83         struct ctdb_log_backend *b;
  84         int ret;
  85
  86         log_state = talloc_zero(mem_ctx, struct ctdb_log_state);
  87         if (log_state == NULL) {
  88                 printf("talloc_zero failed\n");
  89                 abort();
  90         }
  91
  92         ctdb_log_init_file();
  93         ctdb_log_init_syslog();
  94
  95         for (b = log_state->backends; b != NULL; b = b->next) {
  96                 size_t l = strlen(b->prefix);
  97                 /* Exact match with prefix or prefix followed by ':' */
  98                 if (strncmp(b->prefix, logging, l) == 0 &&
  99                     (logging[l] == '\0' || logging[l] == ':')) {
 100                         ret = b->setup(mem_ctx, logging, "ctdbd");
 101                         if (ret == 0) {
 102                                 return true;
 103                         }
 104                         printf("Log init for \"%s\" failed with \"%s\"\n",
 105                                logging, strerror(ret));
 106                         return false;
 107                 }
 108         }
 109
 110         printf("Unable to find log backend for \"%s\"\n", logging);
 111         return false;
 112 }
 113
 114 /* Note that do_debug always uses the global log state. */
 115 static void write_to_log(struct ctdb_log_state *log,
 116                          const char *buf, unsigned int len)
 117 {
 118         if (script_log_level <= DEBUGLEVEL) {
 119                 if (log != NULL && log->prefix != NULL) {
 120                         dbgtext("%s: %*.*s\n", log->prefix, len, len, buf);
 121                 } else {
 122                         dbgtext("%*.*s\n", len, len, buf);
 123                 }
 124                 /* log it in the eventsystem as well */
 125                 if (log && log->logfn) {
 126                         log->logfn(log->buf, len, log->logfn_private);
 127                 }
 128         }
 129 }
 130
 131 /*
 132   called when log data comes in from a child process
 133  */
 134 static void ctdb_child_log_handler(struct tevent_context *ev,
 135                                    struct tevent_fd *fde,
 136                                    uint16_t flags, void *private)
 137 {
 138         struct ctdb_log_state *log = talloc_get_type(private, struct ctdb_log_state);
 139         char *p;
 140         int n;
 141
 142         if (!(flags & TEVENT_FD_READ)) {
 143                 return;
 144         }
 145
 146         n = sys_read(log->pfd, &log->buf[log->buf_used],
 147                  sizeof(log->buf) - log->buf_used);
 148         if (n > 0) {
 149                 log->buf_used += n;
 150         } else if (n == 0) {
 151                 if (log != log_state) {
 152                         talloc_free(log);
 153                 }
 154                 return;
 155         }
 156
 157         while (log->buf_used > 0 &&
 158                (p = memchr(log->buf, '\n', log->buf_used)) != NULL) {
 159                 int n1 = (p - log->buf)+1;
 160                 int n2 = n1 - 1;
 161                 /* swallow \r from child processes */
 162                 if (n2 > 0 && log->buf[n2-1] == '\r') {
 163                         n2--;
 164                 }
 165                 write_to_log(log, log->buf, n2);
 166                 memmove(log->buf, p+1, sizeof(log->buf) - n1);
 167                 log->buf_used -= n1;
 168         }
 169
 170         /* the buffer could have completely filled - unfortunately we have
 171            no choice but to dump it out straight away */
 172         if (log->buf_used == sizeof(log->buf)) {
 173                 write_to_log(log, log->buf, log->buf_used);
 174                 log->buf_used = 0;
 175         }
 176 }
 177
 178 static int log_context_destructor(struct ctdb_log_state *log)
 179 {
 180         /* Flush buffer in case it wasn't \n-terminated. */
 181         if (log->buf_used > 0) {
 182                 write_to_log(log, log->buf, log->buf_used);
 183         }
 184         return 0;
 185 }
 186
 187 /*
 188  * vfork + exec, redirecting child output to logging and specified callback.
 189  */
 190 struct ctdb_log_state *ctdb_vfork_with_logging(TALLOC_CTX *mem_ctx,
 191                                                struct ctdb_context *ctdb,
 192                                                const char *log_prefix,
 193                                                const char *helper,
 194                                                int helper_argc,
 195                                                const char **helper_argv,
 196                                                void (*logfn)(const char *, uint16_t, void *),
 197                                                void *logfn_private, pid_t *pid)
 198 {
 199         int p[2];
 200         struct ctdb_log_state *log;
 201         struct tevent_fd *fde;
 202         char **argv;
 203         int i;
 204         struct timeval before;
 205         double delta_t;
 206
 207         log = talloc_zero(mem_ctx, struct ctdb_log_state);
 208         CTDB_NO_MEMORY_NULL(ctdb, log);
 209
 210         log->prefix = log_prefix;
 211         log->logfn = logfn;
 212         log->logfn_private = logfn_private;
 213
 214         if (pipe(p) != 0) {
 215                 DEBUG(DEBUG_ERR, (__location__ " Failed to setup pipe for child logging\n"));
 216                 goto free_log;
 217         }
 218
 219         argv = talloc_array(mem_ctx, char *, helper_argc + 2);
 220         if (argv == NULL) {
 221                 DEBUG(DEBUG_ERR, (__location__ "Failed to allocate memory for helper\n"));
 222                 goto free_log;
 223         }
 224         argv[0] = discard_const(helper);
 225         argv[1] = talloc_asprintf(argv, "%d", p[1]);
 226         if (argv[1] == NULL) {
 227                 DEBUG(DEBUG_ERR, (__location__ "Failed to allocate memory for helper\n"));
 228                 talloc_free(argv);
 229                 goto free_log;
 230         }
 231
 232         for (i=0; i<helper_argc; i++) {
 233                 argv[i+2] = discard_const(helper_argv[i]);
 234         }
 235
 236         before = timeval_current();
 237
 238         *pid = vfork();
 239         if (*pid == 0) {
 240                 execv(helper, argv);
 241                 _exit(1);
 242         }
 243         close(p[1]);
 244
 245         if (*pid < 0) {
 246                 DEBUG(DEBUG_ERR, (__location__ "vfork failed for helper process\n"));
 247                 close(p[0]);
 248                 goto free_log;
 249         }
 250
 251         delta_t = timeval_elapsed(&before);
 252         if (delta_t > 3.0) {
 253                 DEBUG(DEBUG_WARNING, ("vfork() took %lf seconds\n", delta_t));
 254         }
 255
 256         ctdb_track_child(ctdb, *pid);
 257
 258         log->pfd = p[0];
 259         set_close_on_exec(log->pfd);
 260         talloc_set_destructor(log, log_context_destructor);
 261         fde = tevent_add_fd(ctdb->ev, log, log->pfd, TEVENT_FD_READ,
 262                             ctdb_child_log_handler, log);
 263         tevent_fd_set_auto_close(fde);
 264
 265         return log;
 266
 267 free_log:
 268         talloc_free(log);
 269         return NULL;
 270 }
 271
 272
 273 /*
 274   setup for logging of child process stdout
 275 */
 276 int ctdb_set_child_logging(struct ctdb_context *ctdb)
 277 {
 278         int p[2];
 279         int old_stdout, old_stderr;
 280         struct tevent_fd *fde;
 281
 282         if (log_state->fd == STDOUT_FILENO) {
 283                 /* not needed for stdout logging */
 284                 return 0;
 285         }
 286
 287         /* setup a pipe to catch IO from subprocesses */
 288         if (pipe(p) != 0) {
 289                 DEBUG(DEBUG_ERR,(__location__ " Failed to setup for child logging pipe\n"));
 290                 return -1;
 291         }
 292
 293         /* We'll fail if stderr/stdout not already open; it's simpler. */
 294         old_stdout = dup(STDOUT_FILENO);
 295         if (old_stdout < 0) {
 296                 DEBUG(DEBUG_ERR, ("Failed to dup stdout for child logging\n"));
 297                 return -1;
 298         }
 299         old_stderr = dup(STDERR_FILENO);
 300         if (old_stderr < 0) {
 301                 DEBUG(DEBUG_ERR, ("Failed to dup stderr for child logging\n"));
 302                 close(old_stdout);
 303                 return -1;
 304         }
 305         if (dup2(p[1], STDOUT_FILENO) < 0 || dup2(p[1], STDERR_FILENO) < 0) {
 306                 int saved_errno = errno;
 307                 dup2(old_stdout, STDOUT_FILENO);
 308                 dup2(old_stderr, STDERR_FILENO);
 309                 close(old_stdout);
 310                 close(old_stderr);
 311                 close(p[0]);
 312                 close(p[1]);
 313                 errno = saved_errno;
 314
 315                 printf(__location__ " dup2 failed: %s\n",
 316                         strerror(errno));
 317                 return -1;
 318         }
 319         close(p[1]);
 320         close(old_stdout);
 321         close(old_stderr);
 322
 323         fde = tevent_add_fd(ctdb->ev, log_state, p[0], TEVENT_FD_READ,
 324                             ctdb_child_log_handler, log_state);
 325         tevent_fd_set_auto_close(fde);
 326
 327         log_state->pfd = p[0];
 328
 329         DEBUG(DEBUG_DEBUG, (__location__ " Created PIPE FD:%d for logging\n", p[0]));
 330
 331         return 0;
 332 }
 333
 334
 335 /*
 336  * set up a log handler to catch logging from TEVENT
 337  */
 338 static void ctdb_tevent_logging(void *private_data,
 339                                 enum tevent_debug_level level,
 340                                 const char *fmt,
 341                                 va_list ap) PRINTF_ATTRIBUTE(3, 0);
 342 static void ctdb_tevent_logging(void *private_data,
 343                                 enum tevent_debug_level level,
 344                                 const char *fmt,
 345                                 va_list ap)
 346 {
 347         enum debug_level lvl = DEBUG_CRIT;
 348
 349         switch (level) {
 350         case TEVENT_DEBUG_FATAL:
 351                 lvl = DEBUG_CRIT;
 352                 break;
 353         case TEVENT_DEBUG_ERROR:
 354                 lvl = DEBUG_ERR;
 355                 break;
 356         case TEVENT_DEBUG_WARNING:
 357                 lvl = DEBUG_WARNING;
 358                 break;
 359         case TEVENT_DEBUG_TRACE:
 360                 lvl = DEBUG_DEBUG;
 361                 break;
 362         }
 363
 364         if (lvl <= DEBUGLEVEL) {
 365                 dbgtext_va(fmt, ap);
 366         }
 367 }
 368
 369 int ctdb_init_tevent_logging(struct ctdb_context *ctdb)
 370 {
 371         int ret;
 372
 373         ret = tevent_set_debug(ctdb->ev,
 374                         ctdb_tevent_logging,
 375                         ctdb);
 376         return ret;
 377 }