X-Git-Url: https://git.distorted.org.uk/u/mdw/putty/blobdiff_plain/4512d432b3e9cd880789982bc6fa7fcc57e97fa3..HEAD:/logging.c

diff --git a/logging.c b/logging.c
index b8091bfd..fc89db73 100644
--- a/logging.c
+++ b/logging.c
@@ -1,3 +1,7 @@
+/*
+ * Session logging.
+ */
+
 #include <stdio.h>
 #include <stdlib.h>
 #include <ctype.h>
@@ -10,12 +14,180 @@
 /* log session to file stuff ... */
 struct LogContext {
     FILE *lgfp;
-    char currlogfilename[FILENAME_MAX];
+    enum { L_CLOSED, L_OPENING, L_OPEN, L_ERROR } state;
+    bufchain queue;
+    Filename *currlogfilename;
     void *frontend;
-    Config cfg;
+    Conf *conf;
+    int logtype;		       /* cached out of conf */
 };
 
-static void xlatlognam(char *d, char *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
+ * to the log file. It takes care of opening the log file if it
+ * isn't open, buffering data if it's in the process of being
+ * opened asynchronously, etc.
+ */
+static void logwrite(struct LogContext *ctx, void *data, int len)
+{
+    /*
+     * 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 == L_CLOSED)
+	logfopen(ctx);
+
+    if (ctx->state == L_OPENING) {
+	bufchain_add(&ctx->queue, data, len);
+    } else if (ctx->state == L_OPEN) {
+	assert(ctx->lgfp);
+	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 */
+}
+
+/*
+ * Convenience wrapper on logwrite() which printf-formats the
+ * string.
+ */
+static void logprintf(struct LogContext *ctx, const char *fmt, ...)
+{
+    va_list ap;
+    char *data;
+
+    va_start(ap, fmt);
+    data = dupvprintf(fmt, ap);
+    va_end(ap);
+
+    logwrite(ctx, data, strlen(data));
+    sfree(data);
+}
+
+/*
+ * Flush any open log file.
+ */
+void logflush(void *handle) {
+    struct LogContext *ctx = (struct LogContext *)handle;
+    if (ctx->logtype > 0)
+	if (ctx->state == L_OPEN)
+	    fflush(ctx->lgfp);
+}
+
+static void logfopen_callback(void *handle, int mode)
+{
+    struct LogContext *ctx = (struct LogContext *)handle;
+    char buf[256], *event;
+    struct tm tm;
+    const char *fmode;
+
+    if (mode == 0) {
+	ctx->state = L_ERROR;	       /* disable logging */
+    } else {
+	fmode = (mode == 1 ? "ab" : "wb");
+	ctx->lgfp = f_open(ctx->currlogfilename, fmode, FALSE);
+	if (ctx->lgfp)
+	    ctx->state = L_OPEN;
+	else
+	    ctx->state = L_ERROR;
+    }
+
+    if (ctx->state == L_OPEN) {
+	/* Write header line into log file. */
+	tm = ltime();
+	strftime(buf, 24, "%Y.%m.%d %H:%M:%S", &tm);
+	logprintf(ctx, "=~=~=~=~=~=~=~=~=~=~=~= PuTTY log %s"
+		  " =~=~=~=~=~=~=~=~=~=~=~=\r\n", buf);
+    }
+
+    event = dupprintf("%s session log (%s mode) to file: %s",
+		      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));
+    logevent(ctx->frontend, event);
+    sfree(event);
+
+    /*
+     * Having either succeeded or failed in opening the log file,
+     * we should write any queued data out.
+     */
+    assert(ctx->state != L_OPENING);   /* make _sure_ it won't be requeued */
+    while (bufchain_size(&ctx->queue)) {
+	void *data;
+	int len;
+	bufchain_prefix(&ctx->queue, &data, &len);
+	logwrite(ctx, data, len);
+	bufchain_consume(&ctx->queue, len);
+    }
+}
+
+/*
+ * Open the log file. Takes care of detecting an already-existing
+ * file and asking the user whether they want to append, overwrite
+ * or cancel logging.
+ */
+void logfopen(void *handle)
+{
+    struct LogContext *ctx = (struct LogContext *)handle;
+    struct tm tm;
+    int mode;
+
+    /* Prevent repeat calls */
+    if (ctx->state != L_CLOSED)
+	return;
+
+    if (!ctx->logtype)
+	return;
+
+    tm = ltime();
+
+    /* substitute special codes in file name */
+    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", FALSE);  /* file already present? */
+    if (ctx->lgfp) {
+	int logxfovr = conf_get_int(ctx->conf, CONF_logxfovr);
+	fclose(ctx->lgfp);
+	if (logxfovr != LGXF_ASK) {
+	    mode = ((logxfovr == LGXF_OVR) ? 2 : 1);
+	} else
+	    mode = askappend(ctx->frontend, ctx->currlogfilename,
+			     logfopen_callback, ctx);
+    } else
+	mode = 2;		       /* create == overwrite */
+
+    if (mode < 0)
+	ctx->state = L_OPENING;
+    else
+	logfopen_callback(ctx, mode);  /* open the file */
+}
+
+void logfclose(void *handle)
+{
+    struct LogContext *ctx = (struct LogContext *)handle;
+    if (ctx->lgfp) {
+	fclose(ctx->lgfp);
+	ctx->lgfp = NULL;
+    }
+    ctx->state = L_CLOSED;
+}
 
 /*
  * Log session traffic.
@@ -23,14 +195,9 @@ static void xlatlognam(char *d, char *s, char *hostname, struct tm *tm);
 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) {
-	    /* deferred open file from pgm start? */
-	    if (!ctx->lgfp)
-		logfopen(ctx);
-	    if (ctx->lgfp)
-		fputc(c, ctx->lgfp);
-	}
+    if (ctx->logtype > 0) {
+	if (ctx->logtype == logmode)
+	    logwrite(ctx, &c, 1);
     }
 }
 
@@ -43,140 +210,174 @@ void logtraffic(void *handle, unsigned char c, int logmode)
  * platforms. Platforms which don't have a meaningful stderr can
  * just avoid defining FLAG_STDERR.
  */
-void log_eventlog(void *handle, char *event)
+void log_eventlog(void *handle, const char *event)
 {
     struct LogContext *ctx = (struct LogContext *)handle;
     if ((flags & FLAG_STDERR) && (flags & FLAG_VERBOSE)) {
 	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->lgfp)
-	logfopen(ctx);
-    if (ctx->lgfp)
-	fprintf(ctx->lgfp, "Event Log: %s\r\n", event);
+    if (ctx->logtype != LGTYP_PACKETS &&
+	ctx->logtype != LGTYP_SSHRAW)
+	return;
+    logprintf(ctx, "Event Log: %s\r\n", event);
+    logflush(ctx);
 }
 
 /*
  * Log an SSH packet.
+ * If n_blanks != 0, blank or omit some parts.
+ * Set of blanking areas must be in increasing order.
  */
 void log_packet(void *handle, int direction, int type,
-		char *texttype, void *data, int len)
+		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;
-    int i, j;
     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;
-    if (!ctx->lgfp)
-	logfopen(ctx);
-    if (ctx->lgfp) {
-	fprintf(ctx->lgfp, "%s packet type %d / 0x%02x (%s)\r\n",
-		direction == PKT_INCOMING ? "Incoming" : "Outgoing",
-		type, type, texttype);
-	for (i = 0; i < len; i += 16) {
-	    sprintf(dumpdata, "  %08x%*s\r\n", i, 1+3*16+2+16, "");
-	    for (j = 0; j < 16 && i+j < len; j++) {
-		int c = ((unsigned char *)data)[i+j];
-		sprintf(smalldata, "%02x", c);
-		dumpdata[10+2+3*j] = smalldata[0];
-		dumpdata[10+2+3*j+1] = smalldata[1];
-		dumpdata[10+1+3*16+2+j] = (isprint(c) ? c : '.');
-	    }
-	    strcpy(dumpdata + 10+1+3*16+2+j, "\r\n");
-	    fputs(dumpdata, ctx->lgfp);
+
+    /* Packet header. */
+    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);
 	}
-	fflush(ctx->lgfp);
+    } 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);
     }
-}
 
-/* open log file append/overwrite mode */
-void logfopen(void *handle)
-{
-    struct LogContext *ctx = (struct LogContext *)handle;
-    char buf[256];
-    time_t t;
-    struct tm tm;
-    char writemod[4];
+    /*
+     * Output a hex/ASCII dump of the packet body, blanking/omitting
+     * parts as specified.
+     */
+    while (p < len) {
+	int blktype;
 
-    /* Prevent repeat calls */
-    if (ctx->lgfp)
-	return;
+	/* Move to a current entry in the blanking array. */
+	while ((b < n_blanks) &&
+	       (p >= blanks[b].offset + blanks[b].len))
+	    b++;
+	/* Work out what type of blanking to apply to
+	 * this byte. */
+	blktype = PKTLOG_EMIT; /* default */
+	if ((b < n_blanks) &&
+	    (p >= blanks[b].offset) &&
+	    (p < blanks[b].offset + blanks[b].len))
+	    blktype = blanks[b].type;
 
-    if (!ctx->cfg.logtype)
-	return;
-    sprintf(writemod, "wb");	       /* default to rewrite */
+	/* If we're about to stop omitting, it's time to say how
+	 * much we omitted. */
+	if ((blktype != PKTLOG_OMIT) && omitted) {
+	    logprintf(ctx, "  (%d byte%s omitted)\r\n",
+		      omitted, (omitted==1?"":"s"));
+	    omitted = 0;
+	}
 
-    time(&t);
-    tm = *localtime(&t);
+	/* (Re-)initialise dumpdata as necessary
+	 * (start of row, or if we've just stopped omitting) */
+	if (!output_pos && !omitted)
+	    sprintf(dumpdata, "  %08x%*s\r\n", p-(p%16), 1+3*16+2+16, "");
 
-    /* substitute special codes in file name */
-    xlatlognam(ctx->currlogfilename, ctx->cfg.logfilename,ctx->cfg.host, &tm);
+	/* Deal with the current byte. */
+	if (blktype == PKTLOG_OMIT) {
+	    omitted++;
+	} else {
+	    int c;
+	    if (blktype == PKTLOG_BLANK) {
+		c = 'X';
+		sprintf(smalldata, "XX");
+	    } else {  /* PKTLOG_EMIT */
+		c = ((unsigned char *)data)[p];
+		sprintf(smalldata, "%02x", c);
+	    }
+	    dumpdata[10+2+3*(p%16)] = smalldata[0];
+	    dumpdata[10+2+3*(p%16)+1] = smalldata[1];
+	    dumpdata[10+1+3*16+2+(p%16)] = (isprint(c) ? c : '.');
+	    output_pos = (p%16) + 1;
+	}
 
-    ctx->lgfp = fopen(ctx->currlogfilename, "r");  /* file already present? */
-    if (ctx->lgfp) {
-	int i;
-	fclose(ctx->lgfp);
-	if (ctx->cfg.logxfovr != LGXF_ASK) {
-	    i = ((ctx->cfg.logxfovr == LGXF_OVR) ? 2 : 1);
-	} else
-	    i = askappend(ctx->frontend, ctx->currlogfilename);
-	if (i == 1)
-	    writemod[0] = 'a';	       /* set append mode */
-	else if (i == 0) {	       /* cancelled */
-	    ctx->lgfp = NULL;
-	    ctx->cfg.logtype = 0;	       /* disable logging */
-	    return;
+	p++;
+
+	/* Flush row if necessary */
+	if (((p % 16) == 0) || (p == len) || omitted) {
+	    if (output_pos) {
+		strcpy(dumpdata + 10+1+3*16+2+output_pos, "\r\n");
+		logwrite(ctx, dumpdata, strlen(dumpdata));
+		output_pos = 0;
+	    }
 	}
-    }
 
-    ctx->lgfp = fopen(ctx->currlogfilename, writemod);
-    if (ctx->lgfp) {			       /* enter into event log */
-	/* --- write header line into log file */
-	fputs("=~=~=~=~=~=~=~=~=~=~=~= PuTTY log ", ctx->lgfp);
-	strftime(buf, 24, "%Y.%m.%d %H:%M:%S", &tm);
-	fputs(buf, ctx->lgfp);
-	fputs(" =~=~=~=~=~=~=~=~=~=~=~=\r\n", ctx->lgfp);
-
-	sprintf(buf, "%s session log (%s mode) to file: ",
-		(writemod[0] == 'a') ? "Appending" : "Writing new",
-		(ctx->cfg.logtype == LGTYP_ASCII ? "ASCII" :
-		 ctx->cfg.logtype == LGTYP_DEBUG ? "raw" :
-		 ctx->cfg.logtype == LGTYP_PACKETS ? "SSH packets" : "<ukwn>"));
-	/* Make sure we do not exceed the output buffer size */
-	strncat(buf, ctx->currlogfilename, 128);
-	buf[strlen(buf)] = '\0';
-	logevent(ctx->frontend, buf);
     }
-}
 
-void logfclose(void *handle)
-{
-    struct LogContext *ctx = (struct LogContext *)handle;
-    if (ctx->lgfp) {
-	fclose(ctx->lgfp);
-	ctx->lgfp = NULL;
-    }
+    /* Tidy up */
+    if (omitted)
+	logprintf(ctx, "  (%d byte%s omitted)\r\n",
+		  omitted, (omitted==1?"":"s"));
+    logflush(ctx);
 }
 
-void *log_init(void *frontend, Config *cfg)
+void *log_init(void *frontend, Conf *conf)
 {
-    struct LogContext *ctx = smalloc(sizeof(struct LogContext));
+    struct LogContext *ctx = snew(struct LogContext);
     ctx->lgfp = NULL;
+    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;
 }
 
-void log_reconfig(void *handle, Config *cfg)
+void log_free(void *handle)
+{
+    struct LogContext *ctx = (struct LogContext *)handle;
+
+    logfclose(ctx);
+    bufchain_clear(&ctx->queue);
+    if (ctx->currlogfilename)
+        filename_free(ctx->currlogfilename);
+    sfree(ctx);
+}
+
+void log_reconfig(void *handle, Conf *conf)
 {
     struct LogContext *ctx = (struct LogContext *)handle;
     int reset_logging;
 
-    if (strcmp(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;
@@ -184,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);
@@ -194,12 +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":<hostname>   "&&":&
+ * "&Y":YYYY   "&m":MM   "&d":DD   "&T":hhmmss   "&h":<hostname>   "&&":&
  */
-static void xlatlognam(char *d, char *s, char *hostname, struct tm *tm) {
+static Filename *xlatlognam(Filename *src, char *hostname, struct tm *tm)
+{
     char buf[10], *bufp;
     int size;
-    int len = FILENAME_MAX-1;
+    char *buffer;
+    int buflen, bufsize;
+    const char *s;
+    Filename *ret;
+
+    bufsize = FILENAME_MAX;
+    buffer = snewn(bufsize, char);
+    buflen = 0;
+    s = filename_to_str(src);
 
     while (*s) {
 	/* Let (bufp, len) be the string to append. */
@@ -208,7 +421,7 @@ static void xlatlognam(char *d, char *s, char *hostname, struct tm *tm) {
 	    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;
@@ -235,11 +448,16 @@ static void xlatlognam(char *d, char *s, char *hostname, struct tm *tm) {
 	    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';
+
+    ret = filename_from_str(buffer);
+    sfree(buffer);
+    return ret;
 }