/*
* Session logging.
*/
#include <stdio.h>
#include <stdlib.h>
#include <ctype.h>
#include <time.h>
#include <assert.h>
#include "putty.h"
/* log session to file stuff ... */
struct LogContext {
FILE *lgfp;
enum { L_CLOSED, L_OPENING, L_OPEN, L_ERROR } state;
bufchain queue;
Filename *currlogfilename;
LogPolicy *lp;
Conf *conf;
int logtype; /* cached out of conf */
};
static Filename *xlatlognam(Filename *s, char *hostname, int port,
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(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;
lp_eventlog(ctx->lp, "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(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(LogContext *ctx)
{
if (ctx->logtype > 0)
if (ctx->state == L_OPEN)
fflush(ctx->lgfp);
}
static void logfopen_callback(void *vctx, int mode)
{
LogContext *ctx = (LogContext *)vctx;
char buf[256], *event;
struct tm tm;
const char *fmode;
bool shout = false;
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;
shout = true;
}
}
if (ctx->state == L_OPEN && conf_get_bool(ctx->conf, CONF_logheader)) {
/* 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));
lp_eventlog(ctx->lp, event);
if (shout) {
/*
* If we failed to open the log file due to filesystem error
* (as opposed to user action such as clicking Cancel in the
* askappend box), we should log it more prominently.
*/
lp_logging_error(ctx->lp, 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);
}
logflush(ctx);
}
/*
* 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(LogContext *ctx)
{
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),
conf_get_int(ctx->conf, CONF_port), &tm);
if (open_for_write_would_lose_data(ctx->currlogfilename)) {
int logxfovr = conf_get_int(ctx->conf, CONF_logxfovr);
if (logxfovr != LGXF_ASK) {
mode = ((logxfovr == LGXF_OVR) ? 2 : 1);
} else
mode = lp_askappend(ctx->lp, 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(LogContext *ctx)
{
if (ctx->lgfp) {
fclose(ctx->lgfp);
ctx->lgfp = NULL;
}
ctx->state = L_CLOSED;
}
/*
* Log session traffic.
*/
void logtraffic(LogContext *ctx, unsigned char c, int logmode)
{
if (ctx->logtype > 0) {
if (ctx->logtype == logmode)
logwrite(ctx, &c, 1);
}
}
static void logevent_internal(LogContext *ctx, const char *event)
{
if (ctx->logtype == LGTYP_PACKETS || ctx->logtype == LGTYP_SSHRAW) {
logprintf(ctx, "Event Log: %s\r\n", event);
logflush(ctx);
}
lp_eventlog(ctx->lp, event);
}
void logevent(LogContext *ctx, const char *event)
{
if (!ctx)
return;
/*
* Replace newlines in Event Log messages with spaces. (Sometimes
* the same message string is reused for the Event Log and a GUI
* dialog box; newlines are sometimes appropriate in the latter,
* but never in the former.)
*/
if (strchr(event, '\n') || strchr(event, '\r')) {
char *dup = dupstr(event);
char *p = dup, *q = dup;
while (*p) {
if (*p == '\r' || *p == '\n') {
do {
p++;
} while (*p == '\r' || *p == '\n');
*q++ = ' ';
} else {
*q++ = *p++;
}
}
*q = '\0';
logevent_internal(ctx, dup);
sfree(dup);
} else {
logevent_internal(ctx, event);
}
}
void logevent_and_free(LogContext *ctx, char *event)
{
logevent(ctx, event);
sfree(event);
}
void logeventvf(LogContext *ctx, const char *fmt, va_list ap)
{
logevent_and_free(ctx, dupvprintf(fmt, ap));
}
void logeventf(LogContext *ctx, const char *fmt, ...)
{
va_list ap;
va_start(ap, fmt);
logeventvf(ctx, fmt, ap);
va_end(ap);
}
/*
* 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(LogContext *ctx, int direction, int type,
const char *texttype, const void *data, int len,
int n_blanks, const struct logblank_t *blanks,
const unsigned long *seq,
unsigned downstream_id, const char *additional_log_text)
{
char dumpdata[80], smalldata[5];
int p = 0, b = 0, omitted = 0;
int output_pos = 0; /* NZ if pending output in dumpdata */
if (!(ctx->logtype == LGTYP_SSHRAW ||
(ctx->logtype == LGTYP_PACKETS && texttype)))
return;
/* Packet header. */
if (texttype) {
logprintf(ctx, "%s packet ",
direction == PKT_INCOMING ? "Incoming" : "Outgoing");
if (seq)
logprintf(ctx, "#0x%lx, ", *seq);
logprintf(ctx, "type %d / 0x%02x (%s)", type, type, texttype);
if (downstream_id) {
logprintf(ctx, " on behalf of downstream #%u", downstream_id);
if (additional_log_text)
logprintf(ctx, " (%s)", additional_log_text);
}
logprintf(ctx, "\r\n");
} 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
* 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;
}
/* (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)] = (c >= 0x20 && c < 0x7F ? c : '.');
output_pos = (p%16) + 1;
}
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;
}
}
}
/* Tidy up */
if (omitted)
logprintf(ctx, " (%d byte%s omitted)\r\n",
omitted, (omitted==1?"":"s"));
logflush(ctx);
}
LogContext *log_init(LogPolicy *lp, Conf *conf)
{
LogContext *ctx = snew(LogContext);
ctx->lgfp = NULL;
ctx->state = L_CLOSED;
ctx->lp = lp;
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_free(LogContext *ctx)
{
logfclose(ctx);
bufchain_clear(&ctx->queue);
if (ctx->currlogfilename)
filename_free(ctx->currlogfilename);
conf_free(ctx->conf);
sfree(ctx);
}
void log_reconfig(LogContext *ctx, Conf *conf)
{
bool reset_logging;
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;
if (reset_logging)
logfclose(ctx);
conf_free(ctx->conf);
ctx->conf = conf_copy(conf);
ctx->logtype = conf_get_int(ctx->conf, CONF_logtype);
if (reset_logging)
logfopen(ctx);
}
/*
* translate format codes into time/date strings
* and insert them into log file name
*
* "&Y":YYYY "&m":MM "&d":DD "&T":hhmmss "&h":<hostname> "&&":&
*/
static Filename *xlatlognam(Filename *src, char *hostname, int port,
struct tm *tm)
{
char buf[32], *bufp;
int size;
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) {
bool sanitise = false;
/* Let (bufp, len) be the string to append. */
bufp = buf; /* don't usually override this */
if (*s == '&') {
char c;
s++;
size = 0;
if (*s) switch (c = *s++, tolower((unsigned char)c)) {
case 'y':
size = strftime(buf, sizeof(buf), "%Y", tm);
break;
case 'm':
size = strftime(buf, sizeof(buf), "%m", tm);
break;
case 'd':
size = strftime(buf, sizeof(buf), "%d", tm);
break;
case 't':
size = strftime(buf, sizeof(buf), "%H%M%S", tm);
break;
case 'h':
bufp = hostname;
size = strlen(bufp);
break;
case 'p':
size = sprintf(buf, "%d", port);
break;
default:
buf[0] = '&';
size = 1;
if (c != '&')
buf[size++] = c;
}
/* Never allow path separators - or any other illegal
* filename character - to come out of any of these
* auto-format directives. E.g. 'hostname' can contain
* colons, if it's an IPv6 address, and colons aren't
* legal in filenames on Windows. */
sanitise = true;
} else {
buf[0] = *s++;
size = 1;
}
if (bufsize <= buflen + size) {
bufsize = (buflen + size) * 5 / 4 + 512;
buffer = sresize(buffer, bufsize, char);
}
while (size-- > 0) {
char c = *bufp++;
if (sanitise)
c = filename_char_sanitise(c);
buffer[buflen++] = c;
}
}
buffer[buflen] = '\0';
ret = filename_from_str(buffer);
sfree(buffer);
return ret;
}