freeswan/pluto/log.c

   1 /* error logging functions
   2  * Copyright (C) 1997 Angelos D. Keromytis.
   3  * Copyright (C) 1998-2001  D. Hugh Redelmeier.
   4  *
   5  * This program is free software; you can redistribute it and/or modify it
   6  * under the terms of the GNU General Public License as published by the
   7  * Free Software Foundation; either version 2 of the License, or (at your
   8  * option) any later version.  See <http://www.fsf.org/copyleft/gpl.txt>.
   9  *
  10  * This program is distributed in the hope that it will be useful, but
  11  * WITHOUT ANY WARRANTY; without even the implied warranty of MERCHANTABILITY
  12  * or FITNESS FOR A PARTICULAR PURPOSE.  See the GNU General Public License
  13  * for more details.
  14  *
  15  * RCSID $Id: log.c,v 1.46 2002/03/15 22:30:16 dhr Exp $
  16  */
  17
  18 #include <stdio.h>
  19 #include <stdlib.h>
  20 #include <ctype.h>
  21 #include <stdarg.h>
  22 #include <syslog.h>
  23 #include <errno.h>
  24 #include <string.h>
  25 #include <unistd.h>
  26 #include <signal.h>     /* used only if MSG_NOSIGNAL not defined */
  27
  28 #include <freeswan.h>
  29
  30 #include "constants.h"
  31 #include "defs.h"
  32 #include "log.h"
  33 #include "state.h"
  34 #include "id.h"
  35 #include "x509.h"
  36 #include "connections.h"        /* needs id.h */
  37 #include "whack.h"      /* needs connections.h */
  38
  39 bool
  40     log_to_stderr = TRUE,       /* should log go to stderr? */
  41     log_to_syslog = TRUE;       /* should log go to syslog? */
  42
  43 /* Context for logging.
  44  *
  45  * Global variables: must be carefully adjusted at transaction boundaries!
  46  * If the context provides a whack file descriptor, messages
  47  * should be copied to it -- see whack_log()
  48  */
  49 int whack_log_fd = NULL_FD;     /* only set during whack_handle() */
  50 struct state *cur_state = NULL; /* current state, for diagnostics */
  51 struct connection *cur_connection = NULL;       /* current connection, for diagnostics */
  52 const ip_address *cur_from = NULL;      /* source of current current message */
  53 u_int16_t cur_from_port;        /* host order */
  54
  55 void
  56 init_log(void)
  57 {
  58     if (log_to_stderr)
  59         setbuf(stderr, NULL);
  60     if (log_to_syslog)
  61         openlog("Pluto", LOG_CONS | LOG_NDELAY | LOG_PID, LOG_AUTHPRIV);
  62 }
  63
  64 void
  65 close_log(void)
  66 {
  67     if (log_to_syslog)
  68         closelog();
  69 }
  70
  71 /* Sanitize character string in situ: turns dangerous characters into \OOO.
  72  * With a bit of work, we could use simpler reps for \\, \r, etc.,
  73  * but this is only to protect against something that shouldn't be used.
  74  * Truncate resulting string to what fits in buffer.
  75  */
  76 static size_t
  77 sanitize(char *buf, size_t size)
  78 {
  79 #   define UGLY_WIDTH   4       /* width for ugly character: \OOO */
  80     size_t len;
  81     size_t added = 0;
  82     char *p;
  83
  84     passert(size >= UGLY_WIDTH);        /* need room to swing cat */
  85
  86     /* find right side of string to be sanitized and count
  87      * number of columns to be added.  Stop on end of string
  88      * or lack of room for more result.
  89      */
  90     for (p = buf; *p != '\0' && &p[added] < &buf[size - UGLY_WIDTH]; )
  91     {
  92         unsigned char c = *p++;
  93
  94         if (c == '\\' || !isprint(c))
  95             added += UGLY_WIDTH - 1;
  96     }
  97
  98     /* at this point, p points after last original character to be
  99      * included.  added is how many characters are added to sanitize.
 100      * so p[added] will point after last sanitized character.
 101      */
 102
 103     p[added] = '\0';
 104     len = &p[added] - buf;
 105
 106     /* scan backwards, copying characters to their new home
 107      * and inserting the expansions for ugly characters.
 108      * It is finished when no more shifting is required.
 109      * This is a predecrement loop.
 110      */
 111     while (added != 0)
 112     {
 113         char fmtd[UGLY_WIDTH + 1];
 114         unsigned char c;
 115
 116         while ((c = *--p) != '\\' && isprint(c))
 117             p[added] = c;
 118         added -= UGLY_WIDTH - 1;
 119         snprintf(fmtd, sizeof(fmtd), "\\%03o", c);
 120         memcpy(p + added, fmtd, UGLY_WIDTH);
 121     }
 122     return len;
 123 #   undef UGLY_WIDTH
 124 }
 125
 126 /* format a string for the log, with suitable prefixes.
 127  * A format starting with ~ indicates that this is a reprocessing
 128  * of the message, so prefixing and quoting is suppressed.
 129  */
 130 static void
 131 fmt_log(char *buf, size_t buf_len, const char *fmt, va_list ap)
 132 {
 133     bool reproc = *fmt == '~';
 134     size_t ps;
 135     struct connection *c = cur_state != NULL ? cur_state->st_connection
 136         : cur_connection;
 137
 138     buf[0] = '\0';
 139     if (reproc)
 140         fmt++;  /* ~ at start of format suppresses this prefix */
 141     else if (c != NULL)
 142     {
 143         /* start with name of connection */
 144         char *const be = buf + buf_len;
 145         char *bp = buf;
 146
 147         snprintf(bp, be - bp, "\"%s\"", c->name);
 148         bp += strlen(bp);
 149
 150         /* if it fits, put in any connection instance information */
 151         if (be - bp > CONN_INST_BUF)
 152         {
 153             fmt_conn_instance(c, bp);
 154             bp += strlen(bp);
 155         }
 156
 157         if (cur_state != NULL)
 158         {
 159             /* state number */
 160             snprintf(bp, be - bp, " #%lu", cur_state->st_serialno);
 161             bp += strlen(bp);
 162         }
 163         snprintf(bp, be - bp, ": ");
 164     }
 165     else if (cur_from != NULL)
 166     {
 167         /* peer's IP address */
 168         /* Note: must not use ip_str() because our caller might! */
 169         char ab[ADDRTOT_BUF];
 170
 171         (void) addrtot(cur_from, 0, ab, sizeof(ab));
 172         snprintf(buf, buf_len, "packet from %s:%u: "
 173             , ab, (unsigned)cur_from_port);
 174     }
 175
 176     ps = strlen(buf);
 177     vsnprintf(buf + ps, buf_len - ps, fmt, ap);
 178     if (!reproc)
 179         (void)sanitize(buf, buf_len);
 180 }
 181
 182 void
 183 log(const char *message, ...)
 184 {
 185     va_list args;
 186     char m[1024];       /* longer messages will be truncated */
 187
 188     va_start(args, message);
 189     fmt_log(m, sizeof(m), message, args);
 190     va_end(args);
 191
 192     if (log_to_stderr)
 193         fprintf(stderr, "%s\n", m);
 194     if (log_to_syslog)
 195         syslog(LOG_WARNING, "%s", m);
 196
 197     whack_log(RC_LOG, "~%s", m);
 198 }
 199
 200 void
 201 loglog(int mess_no, const char *message, ...)
 202 {
 203     va_list args;
 204     char m[1024];       /* longer messages will be truncated */
 205
 206     va_start(args, message);
 207     fmt_log(m, sizeof(m), message, args);
 208     va_end(args);
 209
 210     if (log_to_stderr)
 211         fprintf(stderr, "%s\n", m);
 212     if (log_to_syslog)
 213         syslog(LOG_WARNING, "%s", m);
 214
 215     whack_log(mess_no, "~%s", m);
 216 }
 217
 218 void
 219 log_errno_routine(int e, const char *message, ...)
 220 {
 221     va_list args;
 222     char m[1024];       /* longer messages will be truncated */
 223
 224     va_start(args, message);
 225     fmt_log(m, sizeof(m), message, args);
 226     va_end(args);
 227
 228     if (log_to_stderr)
 229         fprintf(stderr, "ERROR: %s. Errno %d: %s\n", m, e, strerror(e));
 230     if (log_to_syslog)
 231         syslog(LOG_ERR, "ERROR: %s. Errno %d: %s", m, e, strerror(e));
 232
 233     whack_log(RC_LOG_SERIOUS
 234         , "~ERROR: %s. Errno %d: %s", m, e, strerror(e));
 235 }
 236
 237 void
 238 exit_log(const char *message, ...)
 239 {
 240     va_list args;
 241     char m[1024];       /* longer messages will be truncated */
 242
 243     va_start(args, message);
 244     fmt_log(m, sizeof(m), message, args);
 245     va_end(args);
 246
 247     if (log_to_stderr)
 248         fprintf(stderr, "FATAL ERROR: %s\n", m);
 249     if (log_to_syslog)
 250         syslog(LOG_ERR, "FATAL ERROR: %s", m);
 251
 252     whack_log(RC_LOG_SERIOUS, "~FATAL ERROR: %s", m);
 253
 254     exit_pluto(1);
 255 }
 256
 257 void
 258 exit_log_errno_routine(int e, const char *message, ...)
 259 {
 260     va_list args;
 261     char m[1024];       /* longer messages will be truncated */
 262
 263     va_start(args, message);
 264     fmt_log(m, sizeof(m), message, args);
 265     va_end(args);
 266
 267     if (log_to_stderr)
 268         fprintf(stderr, "FATAL ERROR: %s. Errno %d: %s\n", m, e, strerror(e));
 269     if (log_to_syslog)
 270         syslog(LOG_ERR, "FATAL ERROR: %s. Errno %d: %s", m, e, strerror(e));
 271
 272     whack_log(RC_LOG_SERIOUS
 273         , "~FATAL ERROR: %s. Errno %d: %s", m, e, strerror(e));
 274
 275     exit_pluto(1);
 276 }
 277
 278 /* emit message to whack.
 279  * form is "ddd statename text" where
 280  * - ddd is a decimal status code (RC_*) as described in whack.h
 281  * - text is a human-readable annotation
 282  */
 283 void
 284 whack_log(int mess_no, const char *message, ...)
 285 {
 286     int wfd = whack_log_fd != NULL_FD ? whack_log_fd
 287         : cur_state != NULL ? cur_state->st_whack_sock
 288         : NULL_FD;
 289
 290     if (wfd != NULL_FD)
 291     {
 292         va_list args;
 293         char m[1024];   /* longer messages will be truncated */
 294         int prelen = snprintf(m, sizeof(m), "%03d ", mess_no);
 295         size_t len;
 296
 297         passert(prelen >= 0);
 298
 299         va_start(args, message);
 300         fmt_log(m+prelen, sizeof(m)-prelen, message, args);
 301         va_end(args);
 302
 303         len = strlen(m);
 304         m[len] = '\n';  /* don't need NUL, do need NL */
 305
 306         /* write to whack socket, but suppress possible SIGPIPE */
 307 #ifdef MSG_NOSIGNAL     /* depends on version of glibc??? */
 308         (void) send(wfd, m, len + 1, MSG_NOSIGNAL);
 309 #else /* !MSG_NOSIGNAL */
 310         {
 311             int r;
 312             struct sigaction act
 313                 , oldact;
 314
 315             act.sa_handler = SIG_IGN;
 316             sigemptyset(&act.sa_mask);
 317             act.sa_flags = 0;   /* no nothing */
 318             r = sigaction(SIGPIPE, &act, &oldact);
 319             passert(r == 0);
 320
 321             (void) write(wfd, m, len + 1);
 322
 323             r = sigaction(SIGPIPE, &oldact, NULL);
 324             passert(r == 0);
 325         }
 326 #endif /* !MSG_NOSIGNAL */
 327     }
 328 }
 329
 330 /* Build up a diagnostic in a static buffer.
 331  * Although this would be a generally useful function, it is very
 332  * hard to come up with a discipline that prevents different uses
 333  * from interfering.  It is intended that by limiting it to building
 334  * diagnostics, we will avoid this problem.
 335  * Juggling is performed to allow an argument to be a previous
 336  * result: the new string may safely depend on the old one.  This
 337  * restriction is not checked in any way: violators will produce
 338  * confusing results (without crashing!).
 339  */
 340 char diag_space[sizeof(diag_space)];
 341
 342 err_t
 343 builddiag(const char *fmt, ...)
 344 {
 345     static char diag_space[1024];       /* longer messages will be truncated */
 346     char t[sizeof(diag_space)]; /* build result here first */
 347     va_list args;
 348
 349     va_start(args, fmt);
 350     t[0] = '\0';        /* in case nothing terminates string */
 351     vsnprintf(t, sizeof(t), fmt, args);
 352     va_end(args);
 353     strcpy(diag_space, t);
 354     return diag_space;
 355 }
 356
 357 /* Debugging message support */
 358
 359 #ifdef DEBUG
 360
 361 void
 362 passert_fail(const char *pred_str, const char *file_str, unsigned long line_no)
 363 {
 364     /* we will get a possibly unplanned prefix.  Hope it works */
 365     loglog(RC_LOG_SERIOUS, "ASSERTION FAILED at %s:%lu: %s", file_str, line_no, pred_str);
 366     abort();    /* exiting correctly doesn't always work */
 367 }
 368
 369 unsigned int
 370     base_debugging = DBG_NONE,  /* default to reporting nothing */
 371     cur_debugging =  DBG_NONE;
 372
 373 void
 374 extra_debugging(const struct connection *c)
 375 {
 376     if (c->extra_debugging != 0)
 377     {
 378         log("enabling for connection: %s"
 379             , bitnamesof(debug_bit_names, c->extra_debugging & ~cur_debugging));
 380         cur_debugging |= c->extra_debugging;
 381     }
 382 }
 383
 384 /* log a debugging message (prefixed by "| ") */
 385
 386 void
 387 DBG_log(const char *message, ...)
 388 {
 389     va_list args;
 390     char m[1024];       /* longer messages will be truncated */
 391
 392     va_start(args, message);
 393     vsnprintf(m, sizeof(m), message, args);
 394     va_end(args);
 395
 396     (void)sanitize(m, sizeof(m));
 397
 398     if (log_to_stderr)
 399         fprintf(stderr, "| %s\n", m);
 400     if (log_to_syslog)
 401         syslog(LOG_DEBUG, "| %s", m);
 402 }
 403
 404 /* dump raw bytes in hex to stderr (for lack of any better destination) */
 405
 406 void
 407 DBG_dump(const char *label, const void *p, size_t len)
 408 {
 409 #   define DUMP_LABEL_WIDTH 20  /* arbitrary modest boundary */
 410 #   define DUMP_WIDTH   (4 * (1 + 4 * 3) + 1)
 411     char buf[DUMP_LABEL_WIDTH + DUMP_WIDTH];
 412     char *bp;
 413     const unsigned char *cp = p;
 414
 415     bp = buf;
 416
 417     if (label != NULL && label[0] != '\0')
 418     {
 419         /* Handle the label.  Care must be taken to avoid buffer overrun. */
 420         size_t llen = strlen(label);
 421
 422         if (llen + 1 > sizeof(buf))
 423         {
 424             DBG_log("%s", label);
 425         }
 426         else
 427         {
 428             strcpy(buf, label);
 429             if (buf[llen-1] == '\n')
 430             {
 431                 buf[llen-1] = '\0';     /* get rid of newline */
 432                 DBG_log("%s", buf);
 433             }
 434             else if (llen < DUMP_LABEL_WIDTH)
 435             {
 436                 bp = buf + llen;
 437             }
 438             else
 439             {
 440                 DBG_log("%s", buf);
 441             }
 442         }
 443     }
 444
 445     do {
 446         int i, j;
 447
 448         for (i = 0; len!=0 && i!=4; i++) {
 449             *bp++ = ' ';
 450             for (j = 0; len!=0 && j!=4; len--, j++)
 451             {
 452                 static const char hexdig[] = "0123456789abcdef";
 453
 454                 *bp++ = ' ';
 455                 *bp++ = hexdig[(*cp >> 4) & 0xF];
 456                 *bp++ = hexdig[*cp & 0xF];
 457                 cp++;
 458             }
 459         }
 460         *bp = '\0';
 461         DBG_log("%s", buf);
 462         bp = buf;
 463     } while (len != 0);
 464 #   undef DUMP_LABEL_WIDTH
 465 #   undef DUMP_WIDTH
 466 }
 467
 468 #endif /* DEBUG */
 469
 470
 471 /* ip_str: a simple to use variant of addrtot.
 472  * It stores its result in a static buffer.
 473  * This means that newer calls overwrite the storage of older calls.
 474  * Note: this is not used in any of the logging functions, so their
 475  * callers may use it.
 476  */
 477 const char *
 478 ip_str(const ip_address *src)
 479 {
 480     static char buf[ADDRTOT_BUF];
 481
 482     addrtot(src, 0, buf, sizeof(buf));
 483     return buf;
 484 }