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