source: filezilla/trunk/fuentes/src/putty/logging.c @ 3185

Last change on this file since 3185 was 3185, checked in by jrpelegrina, 2 years ago

Update new version: 3.15.02

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