X-Git-Url: https://git.distorted.org.uk/u/mdw/putty/blobdiff_plain/919baedb34e9f6e351d70820529398181d8d0ea6..HEAD:/logging.c diff --git a/logging.c b/logging.c index a54b167f..fc89db73 100644 --- a/logging.c +++ b/logging.c @@ -1,3 +1,7 @@ +/* + * Session logging. + */ + #include #include #include @@ -10,14 +14,15 @@ /* log session to file stuff ... */ struct LogContext { FILE *lgfp; - enum { CLOSED, OPENING, OPEN, ERROR } state; + enum { L_CLOSED, L_OPENING, L_OPEN, L_ERROR } state; bufchain queue; - Filename currlogfilename; + Filename *currlogfilename; void *frontend; - Config cfg; + Conf *conf; + int logtype; /* cached out of conf */ }; -static void xlatlognam(Filename *d, Filename s, char *hostname, struct tm *tm); +static Filename *xlatlognam(Filename *s, char *hostname, struct tm *tm); /* * Internal wrapper function which must be called for _all_ output @@ -28,19 +33,25 @@ static void xlatlognam(Filename *d, Filename s, char *hostname, struct tm *tm); static void logwrite(struct LogContext *ctx, void *data, int len) { /* - * In state CLOSED, we call logfopen, which will set the state - * to one of OPENING, OPEN or ERROR. Hence we process all of - * those three _after_ processing CLOSED. + * In state L_CLOSED, we call logfopen, which will set the state + * to one of L_OPENING, L_OPEN or L_ERROR. Hence we process all of + * those three _after_ processing L_CLOSED. */ - if (ctx->state == CLOSED) + if (ctx->state == L_CLOSED) logfopen(ctx); - if (ctx->state == OPENING) { + if (ctx->state == L_OPENING) { bufchain_add(&ctx->queue, data, len); - } else if (ctx->state == OPEN) { + } else if (ctx->state == L_OPEN) { assert(ctx->lgfp); - fwrite(data, 1, len, ctx->lgfp); - } /* else ERROR, so ignore the write */ + if (fwrite(data, 1, len, ctx->lgfp) < (size_t)len) { + logfclose(ctx); + ctx->state = L_ERROR; + /* Log state is L_ERROR so this won't cause a loop */ + logevent(ctx->frontend, + "Disabled writing session log due to error while writing"); + } + } /* else L_ERROR, so ignore the write */ } /* @@ -65,8 +76,8 @@ static void logprintf(struct LogContext *ctx, const char *fmt, ...) */ void logflush(void *handle) { struct LogContext *ctx = (struct LogContext *)handle; - if (ctx->cfg.logtype > 0) - if (ctx->state == OPEN) + if (ctx->logtype > 0) + if (ctx->state == L_OPEN) fflush(ctx->lgfp); } @@ -78,17 +89,17 @@ static void logfopen_callback(void *handle, int mode) const char *fmode; if (mode == 0) { - ctx->state = ERROR; /* disable logging */ + ctx->state = L_ERROR; /* disable logging */ } else { - fmode = (mode == 1 ? "a" : "w"); - ctx->lgfp = f_open(ctx->currlogfilename, fmode); + fmode = (mode == 1 ? "ab" : "wb"); + ctx->lgfp = f_open(ctx->currlogfilename, fmode, FALSE); if (ctx->lgfp) - ctx->state = OPEN; + ctx->state = L_OPEN; else - ctx->state = ERROR; + ctx->state = L_ERROR; } - if (ctx->state == OPEN) { + if (ctx->state == L_OPEN) { /* Write header line into log file. */ tm = ltime(); strftime(buf, 24, "%Y.%m.%d %H:%M:%S", &tm); @@ -97,13 +108,15 @@ static void logfopen_callback(void *handle, int mode) } event = dupprintf("%s session log (%s mode) to file: %s", - (mode == 0 ? "Disabled writing" : - mode == 1 ? "Appending" : "Writing new"), - (ctx->cfg.logtype == LGTYP_ASCII ? "ASCII" : - ctx->cfg.logtype == LGTYP_DEBUG ? "raw" : - ctx->cfg.logtype == LGTYP_PACKETS ? "SSH packets" : + ctx->state == L_ERROR ? + (mode == 0 ? "Disabled writing" : "Error writing") : + (mode == 1 ? "Appending" : "Writing new"), + (ctx->logtype == LGTYP_ASCII ? "ASCII" : + ctx->logtype == LGTYP_DEBUG ? "raw" : + ctx->logtype == LGTYP_PACKETS ? "SSH packets" : + ctx->logtype == LGTYP_SSHRAW ? "SSH raw data" : "unknown"), - filename_to_str(&ctx->currlogfilename)); + filename_to_str(ctx->currlogfilename)); logevent(ctx->frontend, event); sfree(event); @@ -111,7 +124,7 @@ static void logfopen_callback(void *handle, int mode) * Having either succeeded or failed in opening the log file, * we should write any queued data out. */ - assert(ctx->state != OPENING); /* make _sure_ it won't be requeued */ + assert(ctx->state != L_OPENING); /* make _sure_ it won't be requeued */ while (bufchain_size(&ctx->queue)) { void *data; int len; @@ -133,22 +146,27 @@ void logfopen(void *handle) int mode; /* Prevent repeat calls */ - if (ctx->state != CLOSED) + if (ctx->state != L_CLOSED) return; - if (!ctx->cfg.logtype) + if (!ctx->logtype) return; tm = ltime(); /* substitute special codes in file name */ - xlatlognam(&ctx->currlogfilename, ctx->cfg.logfilename,ctx->cfg.host, &tm); + if (ctx->currlogfilename) + filename_free(ctx->currlogfilename); + ctx->currlogfilename = + xlatlognam(conf_get_filename(ctx->conf, CONF_logfilename), + conf_get_str(ctx->conf, CONF_host), &tm); - ctx->lgfp = f_open(ctx->currlogfilename, "r"); /* file already present? */ + ctx->lgfp = f_open(ctx->currlogfilename, "r", FALSE); /* file already present? */ if (ctx->lgfp) { + int logxfovr = conf_get_int(ctx->conf, CONF_logxfovr); fclose(ctx->lgfp); - if (ctx->cfg.logxfovr != LGXF_ASK) { - mode = ((ctx->cfg.logxfovr == LGXF_OVR) ? 2 : 1); + if (logxfovr != LGXF_ASK) { + mode = ((logxfovr == LGXF_OVR) ? 2 : 1); } else mode = askappend(ctx->frontend, ctx->currlogfilename, logfopen_callback, ctx); @@ -156,7 +174,7 @@ void logfopen(void *handle) mode = 2; /* create == overwrite */ if (mode < 0) - ctx->state = OPENING; + ctx->state = L_OPENING; else logfopen_callback(ctx, mode); /* open the file */ } @@ -168,7 +186,7 @@ void logfclose(void *handle) fclose(ctx->lgfp); ctx->lgfp = NULL; } - ctx->state = CLOSED; + ctx->state = L_CLOSED; } /* @@ -177,8 +195,8 @@ void logfclose(void *handle) void logtraffic(void *handle, unsigned char c, int logmode) { struct LogContext *ctx = (struct LogContext *)handle; - if (ctx->cfg.logtype > 0) { - if (ctx->cfg.logtype == logmode) + if (ctx->logtype > 0) { + if (ctx->logtype == logmode) logwrite(ctx, &c, 1); } } @@ -199,9 +217,14 @@ void log_eventlog(void *handle, const char *event) fprintf(stderr, "%s\n", event); fflush(stderr); } - if (ctx->cfg.logtype != LGTYP_PACKETS) + /* If we don't have a context yet (eg winnet.c init) then skip entirely */ + if (!ctx) + return; + if (ctx->logtype != LGTYP_PACKETS && + ctx->logtype != LGTYP_SSHRAW) return; logprintf(ctx, "Event Log: %s\r\n", event); + logflush(ctx); } /* @@ -210,21 +233,47 @@ void log_eventlog(void *handle, const char *event) * Set of blanking areas must be in increasing order. */ void log_packet(void *handle, int direction, int type, - char *texttype, void *data, int len, - int n_blanks, const struct logblank_t *blanks) + char *texttype, const void *data, int len, + int n_blanks, const struct logblank_t *blanks, + const unsigned long *seq) { struct LogContext *ctx = (struct LogContext *)handle; char dumpdata[80], smalldata[5]; int p = 0, b = 0, omitted = 0; int output_pos = 0; /* NZ if pending output in dumpdata */ - if (ctx->cfg.logtype != LGTYP_PACKETS) + if (!(ctx->logtype == LGTYP_SSHRAW || + (ctx->logtype == LGTYP_PACKETS && texttype))) return; /* Packet header. */ - logprintf(ctx, "%s packet type %d / 0x%02x (%s)\r\n", - direction == PKT_INCOMING ? "Incoming" : "Outgoing", - type, type, texttype); + if (texttype) { + if (seq) { + logprintf(ctx, "%s packet #0x%lx, type %d / 0x%02x (%s)\r\n", + direction == PKT_INCOMING ? "Incoming" : "Outgoing", + *seq, type, type, texttype); + } else { + logprintf(ctx, "%s packet type %d / 0x%02x (%s)\r\n", + direction == PKT_INCOMING ? "Incoming" : "Outgoing", + type, type, texttype); + } + } else { + /* + * Raw data is logged with a timestamp, so that it's possible + * to determine whether a mysterious delay occurred at the + * client or server end. (Timestamping the raw data avoids + * cluttering the normal case of only logging decrypted SSH + * messages, and also adds conceptual rigour in the case where + * an SSH message arrives in several pieces.) + */ + char buf[256]; + struct tm tm; + tm = ltime(); + strftime(buf, 24, "%Y-%m-%d %H:%M:%S", &tm); + logprintf(ctx, "%s raw data at %s\r\n", + direction == PKT_INCOMING ? "Incoming" : "Outgoing", + buf); + } /* * Output a hex/ASCII dump of the packet body, blanking/omitting @@ -296,13 +345,15 @@ void log_packet(void *handle, int direction, int type, logflush(ctx); } -void *log_init(void *frontend, Config *cfg) +void *log_init(void *frontend, Conf *conf) { struct LogContext *ctx = snew(struct LogContext); ctx->lgfp = NULL; - ctx->state = CLOSED; + ctx->state = L_CLOSED; ctx->frontend = frontend; - ctx->cfg = *cfg; /* STRUCTURE COPY */ + ctx->conf = conf_copy(conf); + ctx->logtype = conf_get_int(ctx->conf, CONF_logtype); + ctx->currlogfilename = NULL; bufchain_init(&ctx->queue); return ctx; } @@ -313,16 +364,20 @@ void log_free(void *handle) logfclose(ctx); bufchain_clear(&ctx->queue); + if (ctx->currlogfilename) + filename_free(ctx->currlogfilename); sfree(ctx); } -void log_reconfig(void *handle, Config *cfg) +void log_reconfig(void *handle, Conf *conf) { struct LogContext *ctx = (struct LogContext *)handle; int reset_logging; - if (!filename_equal(ctx->cfg.logfilename, cfg->logfilename) || - ctx->cfg.logtype != cfg->logtype) + if (!filename_equal(conf_get_filename(ctx->conf, CONF_logfilename), + conf_get_filename(conf, CONF_logfilename)) || + conf_get_int(ctx->conf, CONF_logtype) != + conf_get_int(conf, CONF_logtype)) reset_logging = TRUE; else reset_logging = FALSE; @@ -330,7 +385,10 @@ void log_reconfig(void *handle, Config *cfg) if (reset_logging) logfclose(ctx); - ctx->cfg = *cfg; /* STRUCTURE COPY */ + conf_free(ctx->conf); + ctx->conf = conf_copy(conf); + + ctx->logtype = conf_get_int(ctx->conf, CONF_logtype); if (reset_logging) logfopen(ctx); @@ -340,19 +398,21 @@ void log_reconfig(void *handle, Config *cfg) * translate format codes into time/date strings * and insert them into log file name * - * "&Y":YYYY "&m":MM "&d":DD "&T":hhmm "&h": "&&":& + * "&Y":YYYY "&m":MM "&d":DD "&T":hhmmss "&h": "&&":& */ -static void xlatlognam(Filename *dest, Filename src, - char *hostname, struct tm *tm) { +static Filename *xlatlognam(Filename *src, char *hostname, struct tm *tm) +{ char buf[10], *bufp; int size; - char buffer[FILENAME_MAX]; - int len = sizeof(buffer)-1; - char *d; + char *buffer; + int buflen, bufsize; const char *s; + Filename *ret; - d = buffer; - s = filename_to_str(&src); + bufsize = FILENAME_MAX; + buffer = snewn(bufsize, char); + buflen = 0; + s = filename_to_str(src); while (*s) { /* Let (bufp, len) be the string to append. */ @@ -361,7 +421,7 @@ static void xlatlognam(Filename *dest, Filename src, char c; s++; size = 0; - if (*s) switch (c = *s++, tolower(c)) { + if (*s) switch (c = *s++, tolower((unsigned char)c)) { case 'y': size = strftime(buf, sizeof(buf), "%Y", tm); break; @@ -388,13 +448,16 @@ static void xlatlognam(Filename *dest, Filename src, buf[0] = *s++; size = 1; } - if (size > len) - size = len; - memcpy(d, bufp, size); - d += size; - len -= size; + if (bufsize <= buflen + size) { + bufsize = (buflen + size) * 5 / 4 + 512; + buffer = sresize(buffer, bufsize, char); + } + memcpy(buffer + buflen, bufp, size); + buflen += size; } - *d = '\0'; + buffer[buflen] = '\0'; - *dest = filename_from_str(buffer); + ret = filename_from_str(buffer); + sfree(buffer); + return ret; }