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