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