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
  92     if (mode == 0) {
  93         ctx->state = L_ERROR;          /* disable logging */
  94     } else {
  95         fmode = (mode == 1 ? "ab" : "wb");
  96         ctx->lgfp = f_open(ctx->currlogfilename, fmode, FALSE);
  97         if (ctx->lgfp)
  98             ctx->state = L_OPEN;
  99         else
 100             ctx->state = L_ERROR;
 101     }
 102
 103     if (ctx->state == L_OPEN) {
 104         /* Write header line into log file. */
 105         tm = ltime();
 106         strftime(buf, 24, "%Y.%m.%d %H:%M:%S", &tm);
 107         logprintf(ctx, "=~=~=~=~=~=~=~=~=~=~=~= PuTTY log %s"
 108                   " =~=~=~=~=~=~=~=~=~=~=~=\r\n", buf);
 109     }
 110
 111     event = dupprintf("%s session log (%s mode) to file: %s",
 112                       ctx->state == L_ERROR ?
 113                       (mode == 0 ? "Disabled writing" : "Error writing") :
 114                       (mode == 1 ? "Appending" : "Writing new"),
 115                       (ctx->logtype == LGTYP_ASCII ? "ASCII" :
 116                        ctx->logtype == LGTYP_DEBUG ? "raw" :
 117                        ctx->logtype == LGTYP_PACKETS ? "SSH packets" :
 118                        ctx->logtype == LGTYP_SSHRAW ? "SSH raw data" :
 119                        "unknown"),
 120                       filename_to_str(ctx->currlogfilename));
 121     logevent(ctx->frontend, event);
 122     sfree(event);
 123
 124     /*
 125      * Having either succeeded or failed in opening the log file,
 126      * we should write any queued data out.
 127      */
 128     assert(ctx->state != L_OPENING);   /* make _sure_ it won't be requeued */
 129     while (bufchain_size(&ctx->queue)) {
 130         void *data;
 131         int len;
 132         bufchain_prefix(&ctx->queue, &data, &len);
 133         logwrite(ctx, data, len);
 134         bufchain_consume(&ctx->queue, len);
 135     }
 136 }
 137
 138 /*
 139  * Open the log file. Takes care of detecting an already-existing
 140  * file and asking the user whether they want to append, overwrite
 141  * or cancel logging.
 142  */
 143 void logfopen(void *handle)
 144 {
 145     struct LogContext *ctx = (struct LogContext *)handle;
 146     struct tm tm;
 147     int mode;
 148
 149     /* Prevent repeat calls */
 150     if (ctx->state != L_CLOSED)
 151         return;
 152
 153     if (!ctx->logtype)
 154         return;
 155
 156     tm = ltime();
 157
 158     /* substitute special codes in file name */
 159     if (ctx->currlogfilename)
 160         filename_free(ctx->currlogfilename);
 161     ctx->currlogfilename =
 162         xlatlognam(conf_get_filename(ctx->conf, CONF_logfilename),
 163                    conf_get_str(ctx->conf, CONF_host),
 164                    conf_get_int(ctx->conf, CONF_port), &tm);
 165
 166     ctx->lgfp = f_open(ctx->currlogfilename, "r", FALSE);  /* file already present? */
 167     if (ctx->lgfp) {
 168         int logxfovr = conf_get_int(ctx->conf, CONF_logxfovr);
 169         fclose(ctx->lgfp);
 170         if (logxfovr != LGXF_ASK) {
 171             mode = ((logxfovr == LGXF_OVR) ? 2 : 1);
 172         } else
 173             mode = askappend(ctx->frontend, ctx->currlogfilename,
 174                              logfopen_callback, ctx);
 175     } else
 176         mode = 2;                      /* create == overwrite */
 177
 178     if (mode < 0)
 179         ctx->state = L_OPENING;
 180     else
 181         logfopen_callback(ctx, mode);  /* open the file */
 182 }
 183
 184 void logfclose(void *handle)
 185 {
 186     struct LogContext *ctx = (struct LogContext *)handle;
 187     if (ctx->lgfp) {
 188         fclose(ctx->lgfp);
 189         ctx->lgfp = NULL;
 190     }
 191     ctx->state = L_CLOSED;
 192 }
 193
 194 /*
 195  * Log session traffic.
 196  */
 197 void logtraffic(void *handle, unsigned char c, int logmode)
 198 {
 199     struct LogContext *ctx = (struct LogContext *)handle;
 200     if (ctx->logtype > 0) {
 201         if (ctx->logtype == logmode)
 202             logwrite(ctx, &c, 1);
 203     }
 204 }
 205
 206 /*
 207  * Log an Event Log entry. Used in SSH packet logging mode; this is
 208  * also as convenient a place as any to put the output of Event Log
 209  * entries to stderr when a command-line tool is in verbose mode.
 210  * (In particular, this is a better place to put it than in the
 211  * front ends, because it only has to be done once for all
 212  * platforms. Platforms which don't have a meaningful stderr can
 213  * just avoid defining FLAG_STDERR.
 214  */
 215 void log_eventlog(void *handle, const char *event)
 216 {
 217     struct LogContext *ctx = (struct LogContext *)handle;
 218     if ((flags & FLAG_STDERR) && (flags & FLAG_VERBOSE)) {
 219         fprintf(stderr, "%s\n", event);
 220         fflush(stderr);
 221     }
 222     /* If we don't have a context yet (eg winnet.c init) then skip entirely */
 223     if (!ctx)
 224         return;
 225     if (ctx->logtype != LGTYP_PACKETS &&
 226         ctx->logtype != LGTYP_SSHRAW)
 227         return;
 228     logprintf(ctx, "Event Log: %s\r\n", event);
 229     logflush(ctx);
 230 }
 231
 232 /*
 233  * Log an SSH packet.
 234  * If n_blanks != 0, blank or omit some parts.
 235  * Set of blanking areas must be in increasing order.
 236  */
 237 void log_packet(void *handle, int direction, int type,
 238                 const char *texttype, const void *data, int len,
 239                 int n_blanks, const struct logblank_t *blanks,
 240                 const unsigned long *seq,
 241                 unsigned downstream_id, const char *additional_log_text)
 242 {
 243     struct LogContext *ctx = (struct LogContext *)handle;
 244     char dumpdata[80], smalldata[5];
 245     int p = 0, b = 0, omitted = 0;
 246     int output_pos = 0; /* NZ if pending output in dumpdata */
 247
 248     if (!(ctx->logtype == LGTYP_SSHRAW ||
 249           (ctx->logtype == LGTYP_PACKETS && texttype)))
 250         return;
 251
 252     /* Packet header. */
 253     if (texttype) {
 254         logprintf(ctx, "%s packet ",
 255                   direction == PKT_INCOMING ? "Incoming" : "Outgoing");
 256
 257         if (seq)
 258             logprintf(ctx, "#0x%lx, ", *seq);
 259
 260         logprintf(ctx, "type %d / 0x%02x (%s)", type, type, texttype);
 261
 262         if (downstream_id) {
 263             logprintf(ctx, " on behalf of downstream #%u", downstream_id);
 264             if (additional_log_text)
 265                 logprintf(ctx, " (%s)", additional_log_text);
 266         }
 267
 268         logprintf(ctx, "\r\n");
 269     } else {
 270         /*
 271          * Raw data is logged with a timestamp, so that it's possible
 272          * to determine whether a mysterious delay occurred at the
 273          * client or server end. (Timestamping the raw data avoids
 274          * cluttering the normal case of only logging decrypted SSH
 275          * messages, and also adds conceptual rigour in the case where
 276          * an SSH message arrives in several pieces.)
 277          */
 278         char buf[256];
 279         struct tm tm;
 280         tm = ltime();
 281         strftime(buf, 24, "%Y-%m-%d %H:%M:%S", &tm);
 282         logprintf(ctx, "%s raw data at %s\r\n",
 283                   direction == PKT_INCOMING ? "Incoming" : "Outgoing",
 284                   buf);
 285     }
 286
 287     /*
 288      * Output a hex/ASCII dump of the packet body, blanking/omitting
 289      * parts as specified.
 290      */
 291     while (p < len) {
 292         int blktype;
 293
 294         /* Move to a current entry in the blanking array. */
 295         while ((b < n_blanks) &&
 296                (p >= blanks[b].offset + blanks[b].len))
 297             b++;
 298         /* Work out what type of blanking to apply to
 299          * this byte. */
 300         blktype = PKTLOG_EMIT; /* default */
 301         if ((b < n_blanks) &&
 302             (p >= blanks[b].offset) &&
 303             (p < blanks[b].offset + blanks[b].len))
 304             blktype = blanks[b].type;
 305
 306         /* If we're about to stop omitting, it's time to say how
 307          * much we omitted. */
 308         if ((blktype != PKTLOG_OMIT) && omitted) {
 309             logprintf(ctx, "  (%d byte%s omitted)\r\n",
 310                       omitted, (omitted==1?"":"s"));
 311             omitted = 0;
 312         }
 313
 314         /* (Re-)initialise dumpdata as necessary
 315          * (start of row, or if we've just stopped omitting) */
 316         if (!output_pos && !omitted)
 317             sprintf(dumpdata, "  %08x%*s\r\n", p-(p%16), 1+3*16+2+16, "");
 318
 319         /* Deal with the current byte. */
 320         if (blktype == PKTLOG_OMIT) {
 321             omitted++;
 322         } else {
 323             int c;
 324             if (blktype == PKTLOG_BLANK) {
 325                 c = 'X';
 326                 sprintf(smalldata, "XX");
 327             } else {  /* PKTLOG_EMIT */
 328                 c = ((unsigned char *)data)[p];
 329                 sprintf(smalldata, "%02x", c);
 330             }
 331             dumpdata[10+2+3*(p%16)] = smalldata[0];
 332             dumpdata[10+2+3*(p%16)+1] = smalldata[1];
 333             dumpdata[10+1+3*16+2+(p%16)] = (isprint(c) ? c : '.');
 334             output_pos = (p%16) + 1;
 335         }
 336
 337         p++;
 338
 339         /* Flush row if necessary */
 340         if (((p % 16) == 0) || (p == len) || omitted) {
 341             if (output_pos) {
 342                 strcpy(dumpdata + 10+1+3*16+2+output_pos, "\r\n");
 343                 logwrite(ctx, dumpdata, strlen(dumpdata));
 344                 output_pos = 0;
 345             }
 346         }
 347
 348     }
 349
 350     /* Tidy up */
 351     if (omitted)
 352         logprintf(ctx, "  (%d byte%s omitted)\r\n",
 353                   omitted, (omitted==1?"":"s"));
 354     logflush(ctx);
 355 }
 356
 357 void *log_init(void *frontend, Conf *conf)
 358 {
 359     struct LogContext *ctx = snew(struct LogContext);
 360     ctx->lgfp = NULL;
 361     ctx->state = L_CLOSED;
 362     ctx->frontend = frontend;
 363     ctx->conf = conf_copy(conf);
 364     ctx->logtype = conf_get_int(ctx->conf, CONF_logtype);
 365     ctx->currlogfilename = NULL;
 366     bufchain_init(&ctx->queue);
 367     return ctx;
 368 }
 369
 370 void log_free(void *handle)
 371 {
 372     struct LogContext *ctx = (struct LogContext *)handle;
 373
 374     logfclose(ctx);
 375     bufchain_clear(&ctx->queue);
 376     if (ctx->currlogfilename)
 377         filename_free(ctx->currlogfilename);
 378     conf_free(ctx->conf);
 379     sfree(ctx);
 380 }
 381
 382 void log_reconfig(void *handle, Conf *conf)
 383 {
 384     struct LogContext *ctx = (struct LogContext *)handle;
 385     int reset_logging;
 386
 387     if (!filename_equal(conf_get_filename(ctx->conf, CONF_logfilename),
 388                         conf_get_filename(conf, CONF_logfilename)) ||
 389         conf_get_int(ctx->conf, CONF_logtype) !=
 390         conf_get_int(conf, CONF_logtype))
 391         reset_logging = TRUE;
 392     else
 393         reset_logging = FALSE;
 394
 395     if (reset_logging)
 396         logfclose(ctx);
 397
 398     conf_free(ctx->conf);
 399     ctx->conf = conf_copy(conf);
 400
 401     ctx->logtype = conf_get_int(ctx->conf, CONF_logtype);
 402
 403     if (reset_logging)
 404         logfopen(ctx);
 405 }
 406
 407 /*
 408  * translate format codes into time/date strings
 409  * and insert them into log file name
 410  *
 411  * "&Y":YYYY   "&m":MM   "&d":DD   "&T":hhmmss   "&h":<hostname>   "&&":&
 412  */
 413 static Filename *xlatlognam(Filename *src, char *hostname, int port,
 414                             struct tm *tm)
 415 {
 416     char buf[32], *bufp;
 417     int size;
 418     char *buffer;
 419     int buflen, bufsize;
 420     const char *s;
 421     Filename *ret;
 422
 423     bufsize = FILENAME_MAX;
 424     buffer = snewn(bufsize, char);
 425     buflen = 0;
 426     s = filename_to_str(src);
 427
 428     while (*s) {
 429         /* Let (bufp, len) be the string to append. */
 430         bufp = buf;                    /* don't usually override this */
 431         if (*s == '&') {
 432             char c;
 433             s++;
 434             size = 0;
 435             if (*s) switch (c = *s++, tolower((unsigned char)c)) {
 436               case 'y':
 437                 size = strftime(buf, sizeof(buf), "%Y", tm);
 438                 break;
 439               case 'm':
 440                 size = strftime(buf, sizeof(buf), "%m", tm);
 441                 break;
 442               case 'd':
 443                 size = strftime(buf, sizeof(buf), "%d", tm);
 444                 break;
 445               case 't':
 446                 size = strftime(buf, sizeof(buf), "%H%M%S", tm);
 447                 break;
 448               case 'h':
 449                 bufp = hostname;
 450                 size = strlen(bufp);
 451                 break;
 452               case 'p':
 453                 size = sprintf(buf, "%d", port);
 454                 break;
 455               default:
 456                 buf[0] = '&';
 457                 size = 1;
 458                 if (c != '&')
 459                     buf[size++] = c;
 460             }
 461         } else {
 462             buf[0] = *s++;
 463             size = 1;
 464         }
 465         if (bufsize <= buflen + size) {
 466             bufsize = (buflen + size) * 5 / 4 + 512;
 467             buffer = sresize(buffer, bufsize, char);
 468         }
 469         memcpy(buffer + buflen, bufp, size);
 470         buflen += size;
 471     }
 472     buffer[buflen] = '\0';
 473
 474     ret = filename_from_str(buffer);
 475     sfree(buffer);
 476     return ret;
 477 }