logging.c

   1 /*
   2  * Session logging.
   3  */
   4
   5 #include <stdio.h>
   6 #include <stdlib.h>
   7 #include <ctype.h>
   8
   9 #include <time.h>
  10 #include <assert.h>
  11
  12 #include "putty.h"
  13
  14 /* log session to file stuff ... */
  15 struct LogContext {
  16     FILE *lgfp;
  17     enum { L_CLOSED, L_OPENING, L_OPEN, L_ERROR } state;
  18     bufchain queue;
  19     Filename *currlogfilename;
  20     void *frontend;
  21     Conf *conf;
  22     int logtype;                       /* cached out of conf */
  23 };
  24
  25 static Filename *xlatlognam(Filename *s, char *hostname, int port,
  26                             struct tm *tm);
  27
  28 /*
  29  * Internal wrapper function which must be called for _all_ output
  30  * to the log file. It takes care of opening the log file if it
  31  * isn't open, buffering data if it's in the process of being
  32  * opened asynchronously, etc.
  33  */
  34 static void logwrite(struct LogContext *ctx, void *data, int len)
  35 {
  36     /*
  37      * In state L_CLOSED, we call logfopen, which will set the state
  38      * to one of L_OPENING, L_OPEN or L_ERROR. Hence we process all of
  39      * those three _after_ processing L_CLOSED.
  40      */
  41     if (ctx->state == L_CLOSED)
  42         logfopen(ctx);
  43
  44     if (ctx->state == L_OPENING) {
  45         bufchain_add(&ctx->queue, data, len);
  46     } else if (ctx->state == L_OPEN) {
  47         assert(ctx->lgfp);
  48         if (fwrite(data, 1, len, ctx->lgfp) < (size_t)len) {
  49             logfclose(ctx);
  50             ctx->state = L_ERROR;
  51             /* Log state is L_ERROR so this won't cause a loop */
  52             logevent(ctx->frontend,
  53                      "Disabled writing session log due to error while writing");
  54         }
  55     }                                  /* else L_ERROR, so ignore the write */
  56 }
  57
  58 /*
  59  * Convenience wrapper on logwrite() which printf-formats the
  60  * string.
  61  */
  62 static void logprintf(struct LogContext *ctx, const char *fmt, ...)
  63 {
  64     va_list ap;
  65     char *data;
  66
  67     va_start(ap, fmt);
  68     data = dupvprintf(fmt, ap);
  69     va_end(ap);
  70
  71     logwrite(ctx, data, strlen(data));
  72     sfree(data);
  73 }
  74
  75 /*
  76  * Flush any open log file.
  77  */
  78 void logflush(void *handle) {
  79     struct LogContext *ctx = (struct LogContext *)handle;
  80     if (ctx->logtype > 0)
  81         if (ctx->state == L_OPEN)
  82             fflush(ctx->lgfp);
  83 }
  84
  85 static void logfopen_callback(void *handle, int mode)
  86 {
  87     struct LogContext *ctx = (struct LogContext *)handle;
  88     char buf[256], *event;
  89     struct tm tm;
  90     const char *fmode;
  91     int shout = FALSE;
  92
  93     if (mode == 0) {
  94         ctx->state = L_ERROR;          /* disable logging */
  95     } else {
  96         fmode = (mode == 1 ? "ab" : "wb");
  97         ctx->lgfp = f_open(ctx->currlogfilename, fmode, FALSE);
  98         if (ctx->lgfp) {
  99             ctx->state = L_OPEN;
 100         } else {
 101             ctx->state = L_ERROR;
 102             shout = TRUE;
 103         }
 104     }
 105
 106     if (ctx->state == L_OPEN) {
 107         /* Write header line into log file. */
 108         tm = ltime();
 109         strftime(buf, 24, "%Y.%m.%d %H:%M:%S", &tm);
 110         logprintf(ctx, "=~=~=~=~=~=~=~=~=~=~=~= PuTTY log %s"
 111                   " =~=~=~=~=~=~=~=~=~=~=~=\r\n", buf);
 112     }
 113
 114     event = dupprintf("%s session log (%s mode) to file: %s",
 115                       ctx->state == L_ERROR ?
 116                       (mode == 0 ? "Disabled writing" : "Error writing") :
 117                       (mode == 1 ? "Appending" : "Writing new"),
 118                       (ctx->logtype == LGTYP_ASCII ? "ASCII" :
 119                        ctx->logtype == LGTYP_DEBUG ? "raw" :
 120                        ctx->logtype == LGTYP_PACKETS ? "SSH packets" :
 121                        ctx->logtype == LGTYP_SSHRAW ? "SSH raw data" :
 122                        "unknown"),
 123                       filename_to_str(ctx->currlogfilename));
 124     logevent(ctx->frontend, event);
 125     if (shout) {
 126         /*
 127          * If we failed to open the log file due to filesystem error
 128          * (as opposed to user action such as clicking Cancel in the
 129          * askappend box), we should log it more prominently. We do
 130          * this by sending it to the same place that stderr output
 131          * from the main session goes (so, either a console tool's
 132          * actual stderr, or a terminal window).
 133          *
 134          * Of course this is one case in which that policy won't cause
 135          * it to turn up embarrassingly in a log file of real server
 136          * output, because the whole point is that we haven't managed
 137          * to open any such log file :-)
 138          */
 139         from_backend(ctx->frontend, 1, event, strlen(event));
 140         from_backend(ctx->frontend, 1, "\r\n", 2);
 141     }
 142     sfree(event);
 143
 144     /*
 145      * Having either succeeded or failed in opening the log file,
 146      * we should write any queued data out.
 147      */
 148     assert(ctx->state != L_OPENING);   /* make _sure_ it won't be requeued */
 149     while (bufchain_size(&ctx->queue)) {
 150         void *data;
 151         int len;
 152         bufchain_prefix(&ctx->queue, &data, &len);
 153         logwrite(ctx, data, len);
 154         bufchain_consume(&ctx->queue, len);
 155     }
 156 }
 157
 158 /*
 159  * Open the log file. Takes care of detecting an already-existing
 160  * file and asking the user whether they want to append, overwrite
 161  * or cancel logging.
 162  */
 163 void logfopen(void *handle)
 164 {
 165     struct LogContext *ctx = (struct LogContext *)handle;
 166     struct tm tm;
 167     FILE *fp;
 168     int mode;
 169
 170     /* Prevent repeat calls */
 171     if (ctx->state != L_CLOSED)
 172         return;
 173
 174     if (!ctx->logtype)
 175         return;
 176
 177     tm = ltime();
 178
 179     /* substitute special codes in file name */
 180     if (ctx->currlogfilename)
 181         filename_free(ctx->currlogfilename);
 182     ctx->currlogfilename =
 183         xlatlognam(conf_get_filename(ctx->conf, CONF_logfilename),
 184                    conf_get_str(ctx->conf, CONF_host),
 185                    conf_get_int(ctx->conf, CONF_port), &tm);
 186
 187     fp = f_open(ctx->currlogfilename, "r", FALSE);  /* file already present? */
 188     if (fp) {
 189         int logxfovr = conf_get_int(ctx->conf, CONF_logxfovr);
 190         fclose(fp);
 191         if (logxfovr != LGXF_ASK) {
 192             mode = ((logxfovr == LGXF_OVR) ? 2 : 1);
 193         } else
 194             mode = askappend(ctx->frontend, ctx->currlogfilename,
 195                              logfopen_callback, ctx);
 196     } else
 197         mode = 2;                      /* create == overwrite */
 198
 199     if (mode < 0)
 200         ctx->state = L_OPENING;
 201     else
 202         logfopen_callback(ctx, mode);  /* open the file */
 203 }
 204
 205 void logfclose(void *handle)
 206 {
 207     struct LogContext *ctx = (struct LogContext *)handle;
 208     if (ctx->lgfp) {
 209         fclose(ctx->lgfp);
 210         ctx->lgfp = NULL;
 211     }
 212     ctx->state = L_CLOSED;
 213 }
 214
 215 /*
 216  * Log session traffic.
 217  */
 218 void logtraffic(void *handle, unsigned char c, int logmode)
 219 {
 220     struct LogContext *ctx = (struct LogContext *)handle;
 221     if (ctx->logtype > 0) {
 222         if (ctx->logtype == logmode)
 223             logwrite(ctx, &c, 1);
 224     }
 225 }
 226
 227 /*
 228  * Log an Event Log entry. Used in SSH packet logging mode; this is
 229  * also as convenient a place as any to put the output of Event Log
 230  * entries to stderr when a command-line tool is in verbose mode.
 231  * (In particular, this is a better place to put it than in the
 232  * front ends, because it only has to be done once for all
 233  * platforms. Platforms which don't have a meaningful stderr can
 234  * just avoid defining FLAG_STDERR.
 235  */
 236 void log_eventlog(void *handle, const char *event)
 237 {
 238     struct LogContext *ctx = (struct LogContext *)handle;
 239     if ((flags & FLAG_STDERR) && (flags & FLAG_VERBOSE)) {
 240         fprintf(stderr, "%s\n", event);
 241         fflush(stderr);
 242     }
 243     /* If we don't have a context yet (eg winnet.c init) then skip entirely */
 244     if (!ctx)
 245         return;
 246     if (ctx->logtype != LGTYP_PACKETS &&
 247         ctx->logtype != LGTYP_SSHRAW)
 248         return;
 249     logprintf(ctx, "Event Log: %s\r\n", event);
 250     logflush(ctx);
 251 }
 252
 253 /*
 254  * Log an SSH packet.
 255  * If n_blanks != 0, blank or omit some parts.
 256  * Set of blanking areas must be in increasing order.
 257  */
 258 void log_packet(void *handle, int direction, int type,
 259                 const char *texttype, const void *data, int len,
 260                 int n_blanks, const struct logblank_t *blanks,
 261                 const unsigned long *seq,
 262                 unsigned downstream_id, const char *additional_log_text)
 263 {
 264     struct LogContext *ctx = (struct LogContext *)handle;
 265     char dumpdata[80], smalldata[5];
 266     int p = 0, b = 0, omitted = 0;
 267     int output_pos = 0; /* NZ if pending output in dumpdata */
 268
 269     if (!(ctx->logtype == LGTYP_SSHRAW ||
 270           (ctx->logtype == LGTYP_PACKETS && texttype)))
 271         return;
 272
 273     /* Packet header. */
 274     if (texttype) {
 275         logprintf(ctx, "%s packet ",
 276                   direction == PKT_INCOMING ? "Incoming" : "Outgoing");
 277
 278         if (seq)
 279             logprintf(ctx, "#0x%lx, ", *seq);
 280
 281         logprintf(ctx, "type %d / 0x%02x (%s)", type, type, texttype);
 282
 283         if (downstream_id) {
 284             logprintf(ctx, " on behalf of downstream #%u", downstream_id);
 285             if (additional_log_text)
 286                 logprintf(ctx, " (%s)", additional_log_text);
 287         }
 288
 289         logprintf(ctx, "\r\n");
 290     } else {
 291         /*
 292          * Raw data is logged with a timestamp, so that it's possible
 293          * to determine whether a mysterious delay occurred at the
 294          * client or server end. (Timestamping the raw data avoids
 295          * cluttering the normal case of only logging decrypted SSH
 296          * messages, and also adds conceptual rigour in the case where
 297          * an SSH message arrives in several pieces.)
 298          */
 299         char buf[256];
 300         struct tm tm;
 301         tm = ltime();
 302         strftime(buf, 24, "%Y-%m-%d %H:%M:%S", &tm);
 303         logprintf(ctx, "%s raw data at %s\r\n",
 304                   direction == PKT_INCOMING ? "Incoming" : "Outgoing",
 305                   buf);
 306     }
 307
 308     /*
 309      * Output a hex/ASCII dump of the packet body, blanking/omitting
 310      * parts as specified.
 311      */
 312     while (p < len) {
 313         int blktype;
 314
 315         /* Move to a current entry in the blanking array. */
 316         while ((b < n_blanks) &&
 317                (p >= blanks[b].offset + blanks[b].len))
 318             b++;
 319         /* Work out what type of blanking to apply to
 320          * this byte. */
 321         blktype = PKTLOG_EMIT; /* default */
 322         if ((b < n_blanks) &&
 323             (p >= blanks[b].offset) &&
 324             (p < blanks[b].offset + blanks[b].len))
 325             blktype = blanks[b].type;
 326
 327         /* If we're about to stop omitting, it's time to say how
 328          * much we omitted. */
 329         if ((blktype != PKTLOG_OMIT) && omitted) {
 330             logprintf(ctx, "  (%d byte%s omitted)\r\n",
 331                       omitted, (omitted==1?"":"s"));
 332             omitted = 0;
 333         }
 334
 335         /* (Re-)initialise dumpdata as necessary
 336          * (start of row, or if we've just stopped omitting) */
 337         if (!output_pos && !omitted)
 338             sprintf(dumpdata, "  %08x%*s\r\n", p-(p%16), 1+3*16+2+16, "");
 339
 340         /* Deal with the current byte. */
 341         if (blktype == PKTLOG_OMIT) {
 342             omitted++;
 343         } else {
 344             int c;
 345             if (blktype == PKTLOG_BLANK) {
 346                 c = 'X';
 347                 sprintf(smalldata, "XX");
 348             } else {  /* PKTLOG_EMIT */
 349                 c = ((unsigned char *)data)[p];
 350                 sprintf(smalldata, "%02x", c);
 351             }
 352             dumpdata[10+2+3*(p%16)] = smalldata[0];
 353             dumpdata[10+2+3*(p%16)+1] = smalldata[1];
 354             dumpdata[10+1+3*16+2+(p%16)] = (isprint(c) ? c : '.');
 355             output_pos = (p%16) + 1;
 356         }
 357
 358         p++;
 359
 360         /* Flush row if necessary */
 361         if (((p % 16) == 0) || (p == len) || omitted) {
 362             if (output_pos) {
 363                 strcpy(dumpdata + 10+1+3*16+2+output_pos, "\r\n");
 364                 logwrite(ctx, dumpdata, strlen(dumpdata));
 365                 output_pos = 0;
 366             }
 367         }
 368
 369     }
 370
 371     /* Tidy up */
 372     if (omitted)
 373         logprintf(ctx, "  (%d byte%s omitted)\r\n",
 374                   omitted, (omitted==1?"":"s"));
 375     logflush(ctx);
 376 }
 377
 378 void *log_init(void *frontend, Conf *conf)
 379 {
 380     struct LogContext *ctx = snew(struct LogContext);
 381     ctx->lgfp = NULL;
 382     ctx->state = L_CLOSED;
 383     ctx->frontend = frontend;
 384     ctx->conf = conf_copy(conf);
 385     ctx->logtype = conf_get_int(ctx->conf, CONF_logtype);
 386     ctx->currlogfilename = NULL;
 387     bufchain_init(&ctx->queue);
 388     return ctx;
 389 }
 390
 391 void log_free(void *handle)
 392 {
 393     struct LogContext *ctx = (struct LogContext *)handle;
 394
 395     logfclose(ctx);
 396     bufchain_clear(&ctx->queue);
 397     if (ctx->currlogfilename)
 398         filename_free(ctx->currlogfilename);
 399     conf_free(ctx->conf);
 400     sfree(ctx);
 401 }
 402
 403 void log_reconfig(void *handle, Conf *conf)
 404 {
 405     struct LogContext *ctx = (struct LogContext *)handle;
 406     int reset_logging;
 407
 408     if (!filename_equal(conf_get_filename(ctx->conf, CONF_logfilename),
 409                         conf_get_filename(conf, CONF_logfilename)) ||
 410         conf_get_int(ctx->conf, CONF_logtype) !=
 411         conf_get_int(conf, CONF_logtype))
 412         reset_logging = TRUE;
 413     else
 414         reset_logging = FALSE;
 415
 416     if (reset_logging)
 417         logfclose(ctx);
 418
 419     conf_free(ctx->conf);
 420     ctx->conf = conf_copy(conf);
 421
 422     ctx->logtype = conf_get_int(ctx->conf, CONF_logtype);
 423
 424     if (reset_logging)
 425         logfopen(ctx);
 426 }
 427
 428 /*
 429  * translate format codes into time/date strings
 430  * and insert them into log file name
 431  *
 432  * "&Y":YYYY   "&m":MM   "&d":DD   "&T":hhmmss   "&h":<hostname>   "&&":&
 433  */
 434 static Filename *xlatlognam(Filename *src, char *hostname, int port,
 435                             struct tm *tm)
 436 {
 437     char buf[32], *bufp;
 438     int size;
 439     char *buffer;
 440     int buflen, bufsize;
 441     const char *s;
 442     Filename *ret;
 443
 444     bufsize = FILENAME_MAX;
 445     buffer = snewn(bufsize, char);
 446     buflen = 0;
 447     s = filename_to_str(src);
 448
 449     while (*s) {
 450         int sanitise = FALSE;
 451         /* Let (bufp, len) be the string to append. */
 452         bufp = buf;                    /* don't usually override this */
 453         if (*s == '&') {
 454             char c;
 455             s++;
 456             size = 0;
 457             if (*s) switch (c = *s++, tolower((unsigned char)c)) {
 458               case 'y':
 459                 size = strftime(buf, sizeof(buf), "%Y", tm);
 460                 break;
 461               case 'm':
 462                 size = strftime(buf, sizeof(buf), "%m", tm);
 463                 break;
 464               case 'd':
 465                 size = strftime(buf, sizeof(buf), "%d", tm);
 466                 break;
 467               case 't':
 468                 size = strftime(buf, sizeof(buf), "%H%M%S", tm);
 469                 break;
 470               case 'h':
 471                 bufp = hostname;
 472                 size = strlen(bufp);
 473                 break;
 474               case 'p':
 475                 size = sprintf(buf, "%d", port);
 476                 break;
 477               default:
 478                 buf[0] = '&';
 479                 size = 1;
 480                 if (c != '&')
 481                     buf[size++] = c;
 482             }
 483             /* Never allow path separators - or any other illegal
 484              * filename character - to come out of any of these
 485              * auto-format directives. E.g. 'hostname' can contain
 486              * colons, if it's an IPv6 address, and colons aren't
 487              * legal in filenames on Windows. */
 488             sanitise = TRUE;
 489         } else {
 490             buf[0] = *s++;
 491             size = 1;
 492         }
 493         if (bufsize <= buflen + size) {
 494             bufsize = (buflen + size) * 5 / 4 + 512;
 495             buffer = sresize(buffer, bufsize, char);
 496         }
 497         while (size-- > 0) {
 498             char c = *bufp++;
 499             if (sanitise)
 500                 c = filename_char_sanitise(c);
 501             buffer[buflen++] = c;
 502         }
 503     }
 504     buffer[buflen] = '\0';
 505
 506     ret = filename_from_str(buffer);
 507     sfree(buffer);
 508     return ret;
 509 }