putty/LOGGING.C

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