]> asedeno.scripts.mit.edu Git - PuTTY.git/blob - logging.c
Add timestamps to the 'SSH raw data' logging mode.
[PuTTY.git] / 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 {
240     struct LogContext *ctx = (struct LogContext *)handle;
241     char dumpdata[80], smalldata[5];
242     int p = 0, b = 0, omitted = 0;
243     int output_pos = 0; /* NZ if pending output in dumpdata */
244
245     if (!(ctx->logtype == LGTYP_SSHRAW ||
246           (ctx->logtype == LGTYP_PACKETS && texttype)))
247         return;
248
249     /* Packet header. */
250     if (texttype) {
251         if (seq) {
252             logprintf(ctx, "%s packet #0x%lx, type %d / 0x%02x (%s)\r\n",
253                       direction == PKT_INCOMING ? "Incoming" : "Outgoing",
254                       *seq, type, type, texttype);
255         } else {
256             logprintf(ctx, "%s packet type %d / 0x%02x (%s)\r\n",
257                       direction == PKT_INCOMING ? "Incoming" : "Outgoing",
258                       type, type, texttype);
259         }
260     } else {
261         /*
262          * Raw data is logged with a timestamp, so that it's possible
263          * to determine whether a mysterious delay occurred at the
264          * client or server end. (Timestamping the raw data avoids
265          * cluttering the normal case of only logging decrypted SSH
266          * messages, and also adds conceptual rigour in the case where
267          * an SSH message arrives in several pieces.)
268          */
269         char buf[256];
270         struct tm tm;
271         tm = ltime();
272         strftime(buf, 24, "%Y-%m-%d %H:%M:%S", &tm);
273         logprintf(ctx, "%s raw data at %s\r\n",
274                   direction == PKT_INCOMING ? "Incoming" : "Outgoing",
275                   buf);
276     }
277
278     /*
279      * Output a hex/ASCII dump of the packet body, blanking/omitting
280      * parts as specified.
281      */
282     while (p < len) {
283         int blktype;
284
285         /* Move to a current entry in the blanking array. */
286         while ((b < n_blanks) &&
287                (p >= blanks[b].offset + blanks[b].len))
288             b++;
289         /* Work out what type of blanking to apply to
290          * this byte. */
291         blktype = PKTLOG_EMIT; /* default */
292         if ((b < n_blanks) &&
293             (p >= blanks[b].offset) &&
294             (p < blanks[b].offset + blanks[b].len))
295             blktype = blanks[b].type;
296
297         /* If we're about to stop omitting, it's time to say how
298          * much we omitted. */
299         if ((blktype != PKTLOG_OMIT) && omitted) {
300             logprintf(ctx, "  (%d byte%s omitted)\r\n",
301                       omitted, (omitted==1?"":"s"));
302             omitted = 0;
303         }
304
305         /* (Re-)initialise dumpdata as necessary
306          * (start of row, or if we've just stopped omitting) */
307         if (!output_pos && !omitted)
308             sprintf(dumpdata, "  %08x%*s\r\n", p-(p%16), 1+3*16+2+16, "");
309
310         /* Deal with the current byte. */
311         if (blktype == PKTLOG_OMIT) {
312             omitted++;
313         } else {
314             int c;
315             if (blktype == PKTLOG_BLANK) {
316                 c = 'X';
317                 sprintf(smalldata, "XX");
318             } else {  /* PKTLOG_EMIT */
319                 c = ((unsigned char *)data)[p];
320                 sprintf(smalldata, "%02x", c);
321             }
322             dumpdata[10+2+3*(p%16)] = smalldata[0];
323             dumpdata[10+2+3*(p%16)+1] = smalldata[1];
324             dumpdata[10+1+3*16+2+(p%16)] = (isprint(c) ? c : '.');
325             output_pos = (p%16) + 1;
326         }
327
328         p++;
329
330         /* Flush row if necessary */
331         if (((p % 16) == 0) || (p == len) || omitted) {
332             if (output_pos) {
333                 strcpy(dumpdata + 10+1+3*16+2+output_pos, "\r\n");
334                 logwrite(ctx, dumpdata, strlen(dumpdata));
335                 output_pos = 0;
336             }
337         }
338
339     }
340
341     /* Tidy up */
342     if (omitted)
343         logprintf(ctx, "  (%d byte%s omitted)\r\n",
344                   omitted, (omitted==1?"":"s"));
345     logflush(ctx);
346 }
347
348 void *log_init(void *frontend, Conf *conf)
349 {
350     struct LogContext *ctx = snew(struct LogContext);
351     ctx->lgfp = NULL;
352     ctx->state = L_CLOSED;
353     ctx->frontend = frontend;
354     ctx->conf = conf_copy(conf);
355     ctx->logtype = conf_get_int(ctx->conf, CONF_logtype);
356     ctx->currlogfilename = NULL;
357     bufchain_init(&ctx->queue);
358     return ctx;
359 }
360
361 void log_free(void *handle)
362 {
363     struct LogContext *ctx = (struct LogContext *)handle;
364
365     logfclose(ctx);
366     bufchain_clear(&ctx->queue);
367     if (ctx->currlogfilename)
368         filename_free(ctx->currlogfilename);
369     sfree(ctx);
370 }
371
372 void log_reconfig(void *handle, Conf *conf)
373 {
374     struct LogContext *ctx = (struct LogContext *)handle;
375     int reset_logging;
376
377     if (!filename_equal(conf_get_filename(ctx->conf, CONF_logfilename),
378                         conf_get_filename(conf, CONF_logfilename)) ||
379         conf_get_int(ctx->conf, CONF_logtype) !=
380         conf_get_int(conf, CONF_logtype))
381         reset_logging = TRUE;
382     else
383         reset_logging = FALSE;
384
385     if (reset_logging)
386         logfclose(ctx);
387
388     conf_free(ctx->conf);
389     ctx->conf = conf_copy(conf);
390
391     ctx->logtype = conf_get_int(ctx->conf, CONF_logtype);
392
393     if (reset_logging)
394         logfopen(ctx);
395 }
396
397 /*
398  * translate format codes into time/date strings
399  * and insert them into log file name
400  *
401  * "&Y":YYYY   "&m":MM   "&d":DD   "&T":hhmmss   "&h":<hostname>   "&&":&
402  */
403 static Filename *xlatlognam(Filename *src, char *hostname, struct tm *tm)
404 {
405     char buf[10], *bufp;
406     int size;
407     char *buffer;
408     int buflen, bufsize;
409     const char *s;
410     Filename *ret;
411
412     bufsize = FILENAME_MAX;
413     buffer = snewn(bufsize, char);
414     buflen = 0;
415     s = filename_to_str(src);
416
417     while (*s) {
418         /* Let (bufp, len) be the string to append. */
419         bufp = buf;                    /* don't usually override this */
420         if (*s == '&') {
421             char c;
422             s++;
423             size = 0;
424             if (*s) switch (c = *s++, tolower((unsigned char)c)) {
425               case 'y':
426                 size = strftime(buf, sizeof(buf), "%Y", tm);
427                 break;
428               case 'm':
429                 size = strftime(buf, sizeof(buf), "%m", tm);
430                 break;
431               case 'd':
432                 size = strftime(buf, sizeof(buf), "%d", tm);
433                 break;
434               case 't':
435                 size = strftime(buf, sizeof(buf), "%H%M%S", tm);
436                 break;
437               case 'h':
438                 bufp = hostname;
439                 size = strlen(bufp);
440                 break;
441               default:
442                 buf[0] = '&';
443                 size = 1;
444                 if (c != '&')
445                     buf[size++] = c;
446             }
447         } else {
448             buf[0] = *s++;
449             size = 1;
450         }
451         if (bufsize <= buflen + size) {
452             bufsize = (buflen + size) * 5 / 4 + 512;
453             buffer = sresize(buffer, bufsize, char);
454         }
455         memcpy(buffer + buflen, bufp, size);
456         buflen += size;
457     }
458     buffer[buflen] = '\0';
459
460     ret = filename_from_str(buffer);
461     sfree(buffer);
462     return ret;
463 }