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

Last change on this file since 130 was 130, checked in by jrpelegrina, 3 years ago

First release to xenial

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    int mode;
168
169    /* Prevent repeat calls */
170    if (ctx->state != L_CLOSED)
171        return;
172
173    if (!ctx->logtype)
174        return;
175
176    tm = ltime();
177
178    /* substitute special codes in file name */
179    if (ctx->currlogfilename)
180        filename_free(ctx->currlogfilename);
181    ctx->currlogfilename = 
182        xlatlognam(conf_get_filename(ctx->conf, CONF_logfilename),
183                   conf_get_str(ctx->conf, CONF_host),
184                   conf_get_int(ctx->conf, CONF_port), &tm);
185
186    ctx->lgfp = f_open(ctx->currlogfilename, "r", FALSE);  /* file already present? */
187    if (ctx->lgfp) {
188        int logxfovr = conf_get_int(ctx->conf, CONF_logxfovr);
189        fclose(ctx->lgfp);
190        if (logxfovr != LGXF_ASK) {
191            mode = ((logxfovr == LGXF_OVR) ? 2 : 1);
192        } else
193            mode = askappend(ctx->frontend, ctx->currlogfilename,
194                             logfopen_callback, ctx);
195    } else
196        mode = 2;                      /* create == overwrite */
197
198    if (mode < 0)
199        ctx->state = L_OPENING;
200    else
201        logfopen_callback(ctx, mode);  /* open the file */
202}
203
204void logfclose(void *handle)
205{
206    struct LogContext *ctx = (struct LogContext *)handle;
207    if (ctx->lgfp) {
208        fclose(ctx->lgfp);
209        ctx->lgfp = NULL;
210    }
211    ctx->state = L_CLOSED;
212}
213
214/*
215 * Log session traffic.
216 */
217void logtraffic(void *handle, unsigned char c, int logmode)
218{
219    struct LogContext *ctx = (struct LogContext *)handle;
220    if (ctx->logtype > 0) {
221        if (ctx->logtype == logmode)
222            logwrite(ctx, &c, 1);
223    }
224}
225
226/*
227 * Log an Event Log entry. Used in SSH packet logging mode; this is
228 * also as convenient a place as any to put the output of Event Log
229 * entries to stderr when a command-line tool is in verbose mode.
230 * (In particular, this is a better place to put it than in the
231 * front ends, because it only has to be done once for all
232 * platforms. Platforms which don't have a meaningful stderr can
233 * just avoid defining FLAG_STDERR.
234 */
235void log_eventlog(void *handle, const char *event)
236{
237    struct LogContext *ctx = (struct LogContext *)handle;
238    if ((flags & FLAG_STDERR) && (flags & FLAG_VERBOSE)) {
239        fzprintf(sftpVerbose, "%s", event);
240    }
241    /* If we don't have a context yet (eg winnet.c init) then skip entirely */
242    if (!ctx)
243        return;
244    if (ctx->logtype != LGTYP_PACKETS &&
245        ctx->logtype != LGTYP_SSHRAW)
246        return;
247    logprintf(ctx, "Event Log: %s\r\n", event);
248    logflush(ctx);
249}
250
251/*
252 * Log an SSH packet.
253 * If n_blanks != 0, blank or omit some parts.
254 * Set of blanking areas must be in increasing order.
255 */
256void log_packet(void *handle, int direction, int type,
257                const char *texttype, const void *data, int len,
258                int n_blanks, const struct logblank_t *blanks,
259                const unsigned long *seq,
260                unsigned downstream_id, const char *additional_log_text)
261{
262    struct LogContext *ctx = (struct LogContext *)handle;
263    char dumpdata[80], smalldata[5];
264    int p = 0, b = 0, omitted = 0;
265    int output_pos = 0; /* NZ if pending output in dumpdata */
266
267    if (!(ctx->logtype == LGTYP_SSHRAW ||
268          (ctx->logtype == LGTYP_PACKETS && texttype)))
269        return;
270
271    /* Packet header. */
272    if (texttype) {
273        logprintf(ctx, "%s packet ",
274                  direction == PKT_INCOMING ? "Incoming" : "Outgoing");
275
276        if (seq)
277            logprintf(ctx, "#0x%lx, ", *seq);
278
279        logprintf(ctx, "type %d / 0x%02x (%s)", type, type, texttype);
280
281        if (downstream_id) {
282            logprintf(ctx, " on behalf of downstream #%u", downstream_id);
283            if (additional_log_text)
284                logprintf(ctx, " (%s)", additional_log_text);
285        }
286
287        logprintf(ctx, "\r\n");
288    } else {
289        /*
290         * Raw data is logged with a timestamp, so that it's possible
291         * to determine whether a mysterious delay occurred at the
292         * client or server end. (Timestamping the raw data avoids
293         * cluttering the normal case of only logging decrypted SSH
294         * messages, and also adds conceptual rigour in the case where
295         * an SSH message arrives in several pieces.)
296         */
297        char buf[256];
298        struct tm tm;
299        tm = ltime();
300        strftime(buf, 24, "%Y-%m-%d %H:%M:%S", &tm);
301        logprintf(ctx, "%s raw data at %s\r\n",
302                  direction == PKT_INCOMING ? "Incoming" : "Outgoing",
303                  buf);
304    }
305
306    /*
307     * Output a hex/ASCII dump of the packet body, blanking/omitting
308     * parts as specified.
309     */
310    while (p < len) {
311        int blktype;
312
313        /* Move to a current entry in the blanking array. */
314        while ((b < n_blanks) &&
315               (p >= blanks[b].offset + blanks[b].len))
316            b++;
317        /* Work out what type of blanking to apply to
318         * this byte. */
319        blktype = PKTLOG_EMIT; /* default */
320        if ((b < n_blanks) &&
321            (p >= blanks[b].offset) &&
322            (p < blanks[b].offset + blanks[b].len))
323            blktype = blanks[b].type;
324
325        /* If we're about to stop omitting, it's time to say how
326         * much we omitted. */
327        if ((blktype != PKTLOG_OMIT) && omitted) {
328            logprintf(ctx, "  (%d byte%s omitted)\r\n",
329                      omitted, (omitted==1?"":"s"));
330            omitted = 0;
331        }
332
333        /* (Re-)initialise dumpdata as necessary
334         * (start of row, or if we've just stopped omitting) */
335        if (!output_pos && !omitted)
336            sprintf(dumpdata, "  %08x%*s\r\n", p-(p%16), 1+3*16+2+16, "");
337
338        /* Deal with the current byte. */
339        if (blktype == PKTLOG_OMIT) {
340            omitted++;
341        } else {
342            int c;
343            if (blktype == PKTLOG_BLANK) {
344                c = 'X';
345                sprintf(smalldata, "XX");
346            } else {  /* PKTLOG_EMIT */
347                c = ((unsigned char *)data)[p];
348                sprintf(smalldata, "%02x", c);
349            }
350            dumpdata[10+2+3*(p%16)] = smalldata[0];
351            dumpdata[10+2+3*(p%16)+1] = smalldata[1];
352            dumpdata[10+1+3*16+2+(p%16)] = (isprint(c) ? c : '.');
353            output_pos = (p%16) + 1;
354        }
355
356        p++;
357
358        /* Flush row if necessary */
359        if (((p % 16) == 0) || (p == len) || omitted) {
360            if (output_pos) {
361                strcpy(dumpdata + 10+1+3*16+2+output_pos, "\r\n");
362                logwrite(ctx, dumpdata, strlen(dumpdata));
363                output_pos = 0;
364            }
365        }
366
367    }
368
369    /* Tidy up */
370    if (omitted)
371        logprintf(ctx, "  (%d byte%s omitted)\r\n",
372                  omitted, (omitted==1?"":"s"));
373    logflush(ctx);
374}
375
376void *log_init(void *frontend, Conf *conf)
377{
378    struct LogContext *ctx = snew(struct LogContext);
379    ctx->lgfp = NULL;
380    ctx->state = L_CLOSED;
381    ctx->frontend = frontend;
382    ctx->conf = conf_copy(conf);
383    ctx->logtype = conf_get_int(ctx->conf, CONF_logtype);
384    ctx->currlogfilename = NULL;
385    bufchain_init(&ctx->queue);
386    return ctx;
387}
388
389void log_free(void *handle)
390{
391    struct LogContext *ctx = (struct LogContext *)handle;
392
393    logfclose(ctx);
394    bufchain_clear(&ctx->queue);
395    if (ctx->currlogfilename)
396        filename_free(ctx->currlogfilename);
397    conf_free(ctx->conf);
398    sfree(ctx);
399}
400
401void log_reconfig(void *handle, Conf *conf)
402{
403    struct LogContext *ctx = (struct LogContext *)handle;
404    int reset_logging;
405
406    if (!filename_equal(conf_get_filename(ctx->conf, CONF_logfilename),
407                        conf_get_filename(conf, CONF_logfilename)) ||
408        conf_get_int(ctx->conf, CONF_logtype) !=
409        conf_get_int(conf, CONF_logtype))
410        reset_logging = TRUE;
411    else
412        reset_logging = FALSE;
413
414    if (reset_logging)
415        logfclose(ctx);
416
417    conf_free(ctx->conf);
418    ctx->conf = conf_copy(conf);
419
420    ctx->logtype = conf_get_int(ctx->conf, CONF_logtype);
421
422    if (reset_logging)
423        logfopen(ctx);
424}
425
426/*
427 * translate format codes into time/date strings
428 * and insert them into log file name
429 *
430 * "&Y":YYYY   "&m":MM   "&d":DD   "&T":hhmmss   "&h":<hostname>   "&&":&
431 */
432static Filename *xlatlognam(Filename *src, char *hostname, int port,
433                            struct tm *tm)
434{
435    char buf[32], *bufp;
436    int size;
437    char *buffer;
438    int buflen, bufsize;
439    const char *s;
440    Filename *ret;
441
442    bufsize = FILENAME_MAX;
443    buffer = snewn(bufsize, char);
444    buflen = 0;
445    s = filename_to_str(src);
446
447    while (*s) {
448        int sanitise = FALSE;
449        /* Let (bufp, len) be the string to append. */
450        bufp = buf;                    /* don't usually override this */
451        if (*s == '&') {
452            char c;
453            s++;
454            size = 0;
455            if (*s) switch (c = *s++, tolower((unsigned char)c)) {
456              case 'y':
457                size = strftime(buf, sizeof(buf), "%Y", tm);
458                break;
459              case 'm':
460                size = strftime(buf, sizeof(buf), "%m", tm);
461                break;
462              case 'd':
463                size = strftime(buf, sizeof(buf), "%d", tm);
464                break;
465              case 't':
466                size = strftime(buf, sizeof(buf), "%H%M%S", tm);
467                break;
468              case 'h':
469                bufp = hostname;
470                size = strlen(bufp);
471                break;
472              case 'p':
473                size = sprintf(buf, "%d", port);
474                break;
475              default:
476                buf[0] = '&';
477                size = 1;
478                if (c != '&')
479                    buf[size++] = c;
480            }
481            /* Never allow path separators - or any other illegal
482             * filename character - to come out of any of these
483             * auto-format directives. E.g. 'hostname' can contain
484             * colons, if it's an IPv6 address, and colons aren't
485             * legal in filenames on Windows. */
486            sanitise = TRUE;
487        } else {
488            buf[0] = *s++;
489            size = 1;
490        }
491        if (bufsize <= buflen + size) {
492            bufsize = (buflen + size) * 5 / 4 + 512;
493            buffer = sresize(buffer, bufsize, char);
494        }
495        while (size-- > 0) {
496            char c = *bufp++;
497            if (sanitise)
498                c = filename_char_sanitise(c);
499            buffer[buflen++] = c;
500        }
501    }
502    buffer[buflen] = '\0';
503
504    ret = filename_from_str(buffer);
505    sfree(buffer);
506    return ret;
507}
Note: See TracBrowser for help on using the repository browser.