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