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