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