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     int mode;
 168
 169     /* Prevent repeat calls */
 170     if (ctx->state != L_CLOSED)
 171         return;
 172
 173     if (!ctx->logtype)
 174         return;
 175
 176     tm = ltime();
 177
 178     /* substitute special codes in file name */
 179     if (ctx->currlogfilename)
 180         filename_free(ctx->currlogfilename);
 181     ctx->currlogfilename =
 182         xlatlognam(conf_get_filename(ctx->conf, CONF_logfilename),
 183                    conf_get_str(ctx->conf, CONF_host),
 184                    conf_get_int(ctx->conf, CONF_port), &tm);
 185
 186     ctx->lgfp = f_open(ctx->currlogfilename, "r", FALSE);  /* file already present? */
 187     if (ctx->lgfp) {
 188         int logxfovr = conf_get_int(ctx->conf, CONF_logxfovr);
 189         fclose(ctx->lgfp);
 190         if (logxfovr != LGXF_ASK) {
 191             mode = ((logxfovr == LGXF_OVR) ? 2 : 1);
 192         } else
 193             mode = askappend(ctx->frontend, ctx->currlogfilename,
 194                              logfopen_callback, ctx);
 195     } else
 196         mode = 2;                      /* create == overwrite */
 197
 198     if (mode < 0)
 199         ctx->state = L_OPENING;
 200     else
 201         logfopen_callback(ctx, mode);  /* open the file */
 202 }
 203
 204 void logfclose(void *handle)
 205 {
 206     struct LogContext *ctx = (struct LogContext *)handle;
 207     if (ctx->lgfp) {
 208         fclose(ctx->lgfp);
 209         ctx->lgfp = NULL;
 210     }
 211     ctx->state = L_CLOSED;
 212 }
 213
 214 /*
 215  * Log session traffic.
 216  */
 217 void logtraffic(void *handle, unsigned char c, int logmode)
 218 {
 219     struct LogContext *ctx = (struct LogContext *)handle;
 220     if (ctx->logtype > 0) {
 221         if (ctx->logtype == logmode)
 222             logwrite(ctx, &c, 1);
 223     }
 224 }
 225
 226 /*
 227  * Log an Event Log entry. Used in SSH packet logging mode; this is
 228  * also as convenient a place as any to put the output of Event Log
 229  * entries to stderr when a command-line tool is in verbose mode.
 230  * (In particular, this is a better place to put it than in the
 231  * front ends, because it only has to be done once for all
 232  * platforms. Platforms which don't have a meaningful stderr can
 233  * just avoid defining FLAG_STDERR.
 234  */
 235 void log_eventlog(void *handle, const char *event)
 236 {
 237     struct LogContext *ctx = (struct LogContext *)handle;
 238     if ((flags & FLAG_STDERR) && (flags & FLAG_VERBOSE)) {
 239         fprintf(stderr, "%s\n", event);
 240         fflush(stderr);
 241     }
 242     /* If we don't have a context yet (eg winnet.c init) then skip entirely */
 243     if (!ctx)
 244         return;
 245     if (ctx->logtype != LGTYP_PACKETS &&
 246         ctx->logtype != LGTYP_SSHRAW)
 247         return;
 248     logprintf(ctx, "Event Log: %s\r\n", event);
 249     logflush(ctx);
 250 }
 251
 252 /*
 253  * Log an SSH packet.
 254  * If n_blanks != 0, blank or omit some parts.
 255  * Set of blanking areas must be in increasing order.
 256  */
 257 void log_packet(void *handle, int direction, int type,
 258                 const char *texttype, const void *data, int len,
 259                 int n_blanks, const struct logblank_t *blanks,
 260                 const unsigned long *seq,
 261                 unsigned downstream_id, const char *additional_log_text)
 262 {
 263     struct LogContext *ctx = (struct LogContext *)handle;
 264     char dumpdata[80], smalldata[5];
 265     int p = 0, b = 0, omitted = 0;
 266     int output_pos = 0; /* NZ if pending output in dumpdata */
 267
 268     if (!(ctx->logtype == LGTYP_SSHRAW ||
 269           (ctx->logtype == LGTYP_PACKETS && texttype)))
 270         return;
 271
 272     /* Packet header. */
 273     if (texttype) {
 274         logprintf(ctx, "%s packet ",
 275                   direction == PKT_INCOMING ? "Incoming" : "Outgoing");
 276
 277         if (seq)
 278             logprintf(ctx, "#0x%lx, ", *seq);
 279
 280         logprintf(ctx, "type %d / 0x%02x (%s)", type, type, texttype);
 281
 282         if (downstream_id) {
 283             logprintf(ctx, " on behalf of downstream #%u", downstream_id);
 284             if (additional_log_text)
 285                 logprintf(ctx, " (%s)", additional_log_text);
 286         }
 287
 288         logprintf(ctx, "\r\n");
 289     } else {
 290         /*
 291          * Raw data is logged with a timestamp, so that it's possible
 292          * to determine whether a mysterious delay occurred at the
 293          * client or server end. (Timestamping the raw data avoids
 294          * cluttering the normal case of only logging decrypted SSH
 295          * messages, and also adds conceptual rigour in the case where
 296          * an SSH message arrives in several pieces.)
 297          */
 298         char buf[256];
 299         struct tm tm;
 300         tm = ltime();
 301         strftime(buf, 24, "%Y-%m-%d %H:%M:%S", &tm);
 302         logprintf(ctx, "%s raw data at %s\r\n",
 303                   direction == PKT_INCOMING ? "Incoming" : "Outgoing",
 304                   buf);
 305     }
 306
 307     /*
 308      * Output a hex/ASCII dump of the packet body, blanking/omitting
 309      * parts as specified.
 310      */
 311     while (p < len) {
 312         int blktype;
 313
 314         /* Move to a current entry in the blanking array. */
 315         while ((b < n_blanks) &&
 316                (p >= blanks[b].offset + blanks[b].len))
 317             b++;
 318         /* Work out what type of blanking to apply to
 319          * this byte. */
 320         blktype = PKTLOG_EMIT; /* default */
 321         if ((b < n_blanks) &&
 322             (p >= blanks[b].offset) &&
 323             (p < blanks[b].offset + blanks[b].len))
 324             blktype = blanks[b].type;
 325
 326         /* If we're about to stop omitting, it's time to say how
 327          * much we omitted. */
 328         if ((blktype != PKTLOG_OMIT) && omitted) {
 329             logprintf(ctx, "  (%d byte%s omitted)\r\n",
 330                       omitted, (omitted==1?"":"s"));
 331             omitted = 0;
 332         }
 333
 334         /* (Re-)initialise dumpdata as necessary
 335          * (start of row, or if we've just stopped omitting) */
 336         if (!output_pos && !omitted)
 337             sprintf(dumpdata, "  %08x%*s\r\n", p-(p%16), 1+3*16+2+16, "");
 338
 339         /* Deal with the current byte. */
 340         if (blktype == PKTLOG_OMIT) {
 341             omitted++;
 342         } else {
 343             int c;
 344             if (blktype == PKTLOG_BLANK) {
 345                 c = 'X';
 346                 sprintf(smalldata, "XX");
 347             } else {  /* PKTLOG_EMIT */
 348                 c = ((unsigned char *)data)[p];
 349                 sprintf(smalldata, "%02x", c);
 350             }
 351             dumpdata[10+2+3*(p%16)] = smalldata[0];
 352             dumpdata[10+2+3*(p%16)+1] = smalldata[1];
 353             dumpdata[10+1+3*16+2+(p%16)] = (isprint(c) ? c : '.');
 354             output_pos = (p%16) + 1;
 355         }
 356
 357         p++;
 358
 359         /* Flush row if necessary */
 360         if (((p % 16) == 0) || (p == len) || omitted) {
 361             if (output_pos) {
 362                 strcpy(dumpdata + 10+1+3*16+2+output_pos, "\r\n");
 363                 logwrite(ctx, dumpdata, strlen(dumpdata));
 364                 output_pos = 0;
 365             }
 366         }
 367
 368     }
 369
 370     /* Tidy up */
 371     if (omitted)
 372         logprintf(ctx, "  (%d byte%s omitted)\r\n",
 373                   omitted, (omitted==1?"":"s"));
 374     logflush(ctx);
 375 }
 376
 377 void *log_init(void *frontend, Conf *conf)
 378 {
 379     struct LogContext *ctx = snew(struct LogContext);
 380     ctx->lgfp = NULL;
 381     ctx->state = L_CLOSED;
 382     ctx->frontend = frontend;
 383     ctx->conf = conf_copy(conf);
 384     ctx->logtype = conf_get_int(ctx->conf, CONF_logtype);
 385     ctx->currlogfilename = NULL;
 386     bufchain_init(&ctx->queue);
 387     return ctx;
 388 }
 389
 390 void log_free(void *handle)
 391 {
 392     struct LogContext *ctx = (struct LogContext *)handle;
 393
 394     logfclose(ctx);
 395     bufchain_clear(&ctx->queue);
 396     if (ctx->currlogfilename)
 397         filename_free(ctx->currlogfilename);
 398     conf_free(ctx->conf);
 399     sfree(ctx);
 400 }
 401
 402 void log_reconfig(void *handle, Conf *conf)
 403 {
 404     struct LogContext *ctx = (struct LogContext *)handle;
 405     int reset_logging;
 406
 407     if (!filename_equal(conf_get_filename(ctx->conf, CONF_logfilename),
 408                         conf_get_filename(conf, CONF_logfilename)) ||
 409         conf_get_int(ctx->conf, CONF_logtype) !=
 410         conf_get_int(conf, CONF_logtype))
 411         reset_logging = TRUE;
 412     else
 413         reset_logging = FALSE;
 414
 415     if (reset_logging)
 416         logfclose(ctx);
 417
 418     conf_free(ctx->conf);
 419     ctx->conf = conf_copy(conf);
 420
 421     ctx->logtype = conf_get_int(ctx->conf, CONF_logtype);
 422
 423     if (reset_logging)
 424         logfopen(ctx);
 425 }
 426
 427 /*
 428  * translate format codes into time/date strings
 429  * and insert them into log file name
 430  *
 431  * "&Y":YYYY   "&m":MM   "&d":DD   "&T":hhmmss   "&h":<hostname>   "&&":&
 432  */
 433 static Filename *xlatlognam(Filename *src, char *hostname, int port,
 434                             struct tm *tm)
 435 {
 436     char buf[32], *bufp;
 437     int size;
 438     char *buffer;
 439     int buflen, bufsize;
 440     const char *s;
 441     Filename *ret;
 442
 443     bufsize = FILENAME_MAX;
 444     buffer = snewn(bufsize, char);
 445     buflen = 0;
 446     s = filename_to_str(src);
 447
 448     while (*s) {
 449         int sanitise = FALSE;
 450         /* Let (bufp, len) be the string to append. */
 451         bufp = buf;                    /* don't usually override this */
 452         if (*s == '&') {
 453             char c;
 454             s++;
 455             size = 0;
 456             if (*s) switch (c = *s++, tolower((unsigned char)c)) {
 457               case 'y':
 458                 size = strftime(buf, sizeof(buf), "%Y", tm);
 459                 break;
 460               case 'm':
 461                 size = strftime(buf, sizeof(buf), "%m", tm);
 462                 break;
 463               case 'd':
 464                 size = strftime(buf, sizeof(buf), "%d", tm);
 465                 break;
 466               case 't':
 467                 size = strftime(buf, sizeof(buf), "%H%M%S", tm);
 468                 break;
 469               case 'h':
 470                 bufp = hostname;
 471                 size = strlen(bufp);
 472                 break;
 473               case 'p':
 474                 size = sprintf(buf, "%d", port);
 475                 break;
 476               default:
 477                 buf[0] = '&';
 478                 size = 1;
 479                 if (c != '&')
 480                     buf[size++] = c;
 481             }
 482             /* Never allow path separators - or any other illegal
 483              * filename character - to come out of any of these
 484              * auto-format directives. E.g. 'hostname' can contain
 485              * colons, if it's an IPv6 address, and colons aren't
 486              * legal in filenames on Windows. */
 487             sanitise = TRUE;
 488         } else {
 489             buf[0] = *s++;
 490             size = 1;
 491         }
 492         if (bufsize <= buflen + size) {
 493             bufsize = (buflen + size) * 5 / 4 + 512;
 494             buffer = sresize(buffer, bufsize, char);
 495         }
 496         while (size-- > 0) {
 497             char c = *bufp++;
 498             if (sanitise)
 499                 c = filename_char_sanitise(c);
 500             buffer[buflen++] = c;
 501         }
 502     }
 503     buffer[buflen] = '\0';
 504
 505     ret = filename_from_str(buffer);
 506     sfree(buffer);
 507     return ret;
 508 }