X-Git-Url: https://git.distorted.org.uk/u/mdw/putty/blobdiff_plain/a5a6f839780c4cb39f3001602162576d98e9fcca..919baedb34e9f6e351d70820529398181d8d0ea6:/logging.c

diff --git a/logging.c b/logging.c
index f1c42cde..a54b167f 100644
--- a/logging.c
+++ b/logging.c
@@ -10,6 +10,8 @@
 /* log session to file stuff ... */
 struct LogContext {
     FILE *lgfp;
+    enum { CLOSED, OPENING, OPEN, ERROR } state;
+    bufchain queue;
     Filename currlogfilename;
     void *frontend;
     Config cfg;
@@ -18,20 +20,44 @@ struct LogContext {
 static void xlatlognam(Filename *d, Filename s, char *hostname, struct tm *tm);
 
 /*
- * Log session traffic.
+ * 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.
  */
-void logtraffic(void *handle, unsigned char c, int logmode)
+static void logwrite(struct LogContext *ctx, void *data, int len)
 {
-    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);
-	}
-    }
+    /*
+     * 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.
+     */
+    if (ctx->state == CLOSED)
+	logfopen(ctx);
+
+    if (ctx->state == OPENING) {
+	bufchain_add(&ctx->queue, data, len);
+    } else if (ctx->state == OPEN) {
+	assert(ctx->lgfp);
+	fwrite(data, 1, len, ctx->lgfp);
+    }				       /* else 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);
 }
 
 /*
@@ -40,10 +66,123 @@ void logtraffic(void *handle, unsigned char c, int logmode)
 void logflush(void *handle) {
     struct LogContext *ctx = (struct LogContext *)handle;
     if (ctx->cfg.logtype > 0)
-	if (ctx->lgfp)
+	if (ctx->state == 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 = ERROR;	       /* disable logging */
+    } else {
+	fmode = (mode == 1 ? "a" : "w");
+	ctx->lgfp = f_open(ctx->currlogfilename, fmode);
+	if (ctx->lgfp)
+	    ctx->state = OPEN;
+	else
+	    ctx->state = ERROR;
+    }
+
+    if (ctx->state == 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",
+		      (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" :
+		       "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 != 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 != CLOSED)
+	return;
+
+    if (!ctx->cfg.logtype)
+	return;
+
+    tm = ltime();
+
+    /* substitute special codes in file name */
+    xlatlognam(&ctx->currlogfilename, ctx->cfg.logfilename,ctx->cfg.host, &tm);
+
+    ctx->lgfp = f_open(ctx->currlogfilename, "r");  /* file already present? */
+    if (ctx->lgfp) {
+	fclose(ctx->lgfp);
+	if (ctx->cfg.logxfovr != LGXF_ASK) {
+	    mode = ((ctx->cfg.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 = 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 = CLOSED;
+}
+
+/*
+ * Log session traffic.
+ */
+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)
+	    logwrite(ctx, &c, 1);
+    }
+}
+
 /*
  * Log an Event Log entry. Used in SSH packet logging mode; this is
  * also as convenient a place as any to put the output of Event Log
@@ -62,10 +201,7 @@ void log_eventlog(void *handle, const char *event)
     }
     if (ctx->cfg.logtype != LGTYP_PACKETS)
 	return;
-    if (!ctx->lgfp)
-	logfopen(ctx);
-    if (ctx->lgfp)
-	fprintf(ctx->lgfp, "Event Log: %s\r\n", event);
+    logprintf(ctx, "Event Log: %s\r\n", event);
 }
 
 /*
@@ -79,164 +215,95 @@ void log_packet(void *handle, int direction, int type,
 {
     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)
 	return;
-    if (!ctx->lgfp)
-	logfopen(ctx);
-    if (ctx->lgfp) {
-	int p = 0, b = 0, omitted = 0;
-	int output_pos = 0; /* NZ if pending output in dumpdata */
-
-	/* Packet header. */
-	fprintf(ctx->lgfp, "%s packet type %d / 0x%02x (%s)\r\n",
-		direction == PKT_INCOMING ? "Incoming" : "Outgoing",
-		type, type, texttype);
-
-	/*
-	 * Output a hex/ASCII dump of the packet body, blanking/omitting
-	 * parts as specified.
-	 */
-	while (p < len) {
-	    int blktype;
-
-	    /* 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 we're about to stop omitting, it's time to say how
-	     * much we omitted. */
-	    if ((blktype != PKTLOG_OMIT) && omitted) {
-		fprintf(ctx->lgfp, "  (%d byte%s omitted)\r\n",
-			omitted, (omitted==1?"":"s"));
-		omitted = 0;
-	    }
 
-	    /* (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, "");
-
-	    /* 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;
-	    }
+    /* Packet header. */
+    logprintf(ctx, "%s packet type %d / 0x%02x (%s)\r\n",
+	      direction == PKT_INCOMING ? "Incoming" : "Outgoing",
+	      type, type, texttype);
+
+    /*
+     * Output a hex/ASCII dump of the packet body, blanking/omitting
+     * parts as specified.
+     */
+    while (p < len) {
+	int blktype;
+
+	/* 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 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;
+	}
 
-	    p++;
+	/* (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, "");
 
-	    /* 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");
-		    fputs(dumpdata, ctx->lgfp);
-		    output_pos = 0;
-		}
+	/* 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;
 	}
 
-	/* Tidy up */
-	if (omitted)
-	    fprintf(ctx->lgfp, "  (%d byte%s omitted)\r\n",
-		    omitted, (omitted==1?"":"s"));
-	fflush(ctx->lgfp);
-    }
-}
-
-/* open log file append/overwrite mode */
-void logfopen(void *handle)
-{
-    struct LogContext *ctx = (struct LogContext *)handle;
-    char buf[256];
-    struct tm tm;
-    char writemod[4];
-
-    /* Prevent repeat calls */
-    if (ctx->lgfp)
-	return;
-
-    if (!ctx->cfg.logtype)
-	return;
-    sprintf(writemod, "wb");	       /* default to rewrite */
+	p++;
 
-    tm = ltime();
-
-    /* substitute special codes in file name */
-    xlatlognam(&ctx->currlogfilename, ctx->cfg.logfilename,ctx->cfg.host, &tm);
-
-    ctx->lgfp = f_open(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;
+	/* 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 = f_open(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, filename_to_str(&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)
 {
     struct LogContext *ctx = snew(struct LogContext);
     ctx->lgfp = NULL;
+    ctx->state = CLOSED;
     ctx->frontend = frontend;
     ctx->cfg = *cfg;		       /* STRUCTURE COPY */
+    bufchain_init(&ctx->queue);
     return ctx;
 }
 
@@ -245,6 +312,7 @@ void log_free(void *handle)
     struct LogContext *ctx = (struct LogContext *)handle;
 
     logfclose(ctx);
+    bufchain_clear(&ctx->queue);
     sfree(ctx);
 }