From 297efff30350ddffbc77dd6da4269db87103789c Mon Sep 17 00:00:00 2001 From: Simon Tatham Date: Sun, 22 Nov 2015 11:50:37 +0000 Subject: [PATCH] In GUI PuTTY, log standard error from local proxy commands. On both Unix and Windows, we now redirect the local proxy command's standard error into a third pipe; data received from that pipe is broken up at newlines and logged in the Event Log. So if the proxy command emits any error messages in the course of failing to connect to something, you now have a fighting chance of finding out what went wrong. This feature is disabled in command-line tools like PSFTP and Plink, on the basis that in that situation it seems more likely that the user would expect standard-error output to go to the ordinary standard error in the ordinary way. Only GUI PuTTY catches it and logs it like this, because it either doesn't have a standard error at all (on Windows) or is likely to be pointing it at some completely unhelpful session log file (under X). --- be_misc.c | 51 ++++++++++++++++++++++++++ network.h | 2 + unix/uxproxy.c | 91 +++++++++++++++++++++++++++++++++++++++------- windows/winhsock.c | 27 ++++++++++++-- windows/winnpc.c | 6 +-- windows/winnps.c | 6 +-- windows/winproxy.c | 29 +++++++++++++-- 7 files changed, 186 insertions(+), 26 deletions(-) diff --git a/be_misc.c b/be_misc.c index cf8f65c4..739f1602 100644 --- a/be_misc.c +++ b/be_misc.c @@ -2,6 +2,7 @@ * be_misc.c: helper functions shared between main network backends. */ +#define DEFINE_PLUG_METHOD_MACROS #include "putty.h" #include "network.h" @@ -39,3 +40,53 @@ void backend_socket_log(void *frontend, int type, SockAddr addr, int port, } } +void log_proxy_stderr(Plug plug, bufchain *buf, const void *vdata, int len) +{ + const char *data = (const char *)vdata; + int pos = 0; + int msglen; + char *nlpos, *msg, *fullmsg; + + /* + * This helper function allows us to collect the data written to a + * local proxy command's standard error in whatever size chunks we + * happen to get from its pipe, and whenever we have a complete + * line, we pass it to plug_log. + * + * Prerequisites: a plug to log to, and a bufchain stored + * somewhere to collect the data in. + */ + + while (pos < len && (nlpos = memchr(data+pos, '\n', len-pos)) != NULL) { + /* + * Found a newline in the current input buffer. Append it to + * the bufchain (which may contain a partial line from last + * time). + */ + bufchain_add(buf, data + pos, nlpos - (data + pos)); + + /* + * Collect the resulting line of data and pass it to plug_log. + */ + msglen = bufchain_size(buf); + msg = snewn(msglen+1, char); + bufchain_fetch(buf, msg, msglen); + bufchain_consume(buf, msglen); + msg[msglen] = '\0'; + fullmsg = dupprintf("proxy: %s", msg); + plug_log(plug, 2, NULL, 0, fullmsg, 0); + sfree(fullmsg); + sfree(msg); + + /* + * Advance past the newline. + */ + pos += nlpos+1 - (data + pos); + } + + /* + * Now any remaining data is a partial line, which we save for + * next time. + */ + bufchain_add(buf, data + pos, len - pos); +} diff --git a/network.h b/network.h index 2ffa8f38..bebbd224 100644 --- a/network.h +++ b/network.h @@ -228,5 +228,7 @@ Socket new_error_socket(const char *errmsg, Plug plug); */ void backend_socket_log(void *frontend, int type, SockAddr addr, int port, const char *error_msg, int error_code); +typedef struct bufchain_tag bufchain; /* rest of declaration in misc.c */ +void log_proxy_stderr(Plug plug, bufchain *buf, const void *vdata, int len); #endif diff --git a/unix/uxproxy.c b/unix/uxproxy.c index c66cda2e..0460522e 100644 --- a/unix/uxproxy.c +++ b/unix/uxproxy.c @@ -21,7 +21,7 @@ struct Socket_localproxy_tag { const struct socket_function_table *fn; /* the above variable absolutely *must* be the first in this structure */ - int to_cmd, from_cmd; /* fds */ + int to_cmd, from_cmd, cmd_err; /* fds */ char *error; @@ -29,6 +29,7 @@ struct Socket_localproxy_tag { bufchain pending_output_data; bufchain pending_input_data; + bufchain pending_error_data; enum { EOF_NO, EOF_PENDING, EOF_SENT } outgoingeof; }; @@ -37,7 +38,9 @@ static int localproxy_select_result(int fd, int event); /* * Trees to look up the pipe fds in. */ -static tree234 *localproxy_by_fromfd, *localproxy_by_tofd; +static tree234 *localproxy_by_fromfd; +static tree234 *localproxy_by_tofd; +static tree234 *localproxy_by_errfd; static int localproxy_fromfd_cmp(void *av, void *bv) { Local_Proxy_Socket a = (Local_Proxy_Socket)av; @@ -78,6 +81,26 @@ static int localproxy_tofd_find(void *av, void *bv) return +1; return 0; } +static int localproxy_errfd_cmp(void *av, void *bv) +{ + Local_Proxy_Socket a = (Local_Proxy_Socket)av; + Local_Proxy_Socket b = (Local_Proxy_Socket)bv; + if (a->cmd_err < b->cmd_err) + return -1; + if (a->cmd_err > b->cmd_err) + return +1; + return 0; +} +static int localproxy_errfd_find(void *av, void *bv) +{ + int a = *(int *)av; + Local_Proxy_Socket b = (Local_Proxy_Socket)bv; + if (a < b->cmd_err) + return -1; + if (a > b->cmd_err) + return +1; + return 0; +} /* basic proxy socket functions */ @@ -104,8 +127,14 @@ static void sk_localproxy_close (Socket s) uxsel_del(ps->from_cmd); close(ps->from_cmd); + del234(localproxy_by_errfd, ps); + uxsel_del(ps->cmd_err); + close(ps->cmd_err); + bufchain_clear(&ps->pending_input_data); bufchain_clear(&ps->pending_output_data); + bufchain_clear(&ps->pending_error_data); + sfree(ps); } @@ -209,19 +238,26 @@ static int localproxy_select_result(int fd, int event) int ret; if (!(s = find234(localproxy_by_fromfd, &fd, localproxy_fromfd_find)) && + !(s = find234(localproxy_by_fromfd, &fd, localproxy_errfd_find)) && !(s = find234(localproxy_by_tofd, &fd, localproxy_tofd_find)) ) return 1; /* boggle */ if (event == 1) { - assert(fd == s->from_cmd); - ret = read(fd, buf, sizeof(buf)); - if (ret < 0) { - return plug_closing(s->plug, strerror(errno), errno, 0); - } else if (ret == 0) { - return plug_closing(s->plug, NULL, 0, 0); - } else { - return plug_receive(s->plug, 0, buf, ret); - } + if (fd == s->cmd_err) { + ret = read(fd, buf, sizeof(buf)); + if (ret > 0) + log_proxy_stderr(s->plug, &s->pending_error_data, buf, ret); + } else { + assert(fd == s->from_cmd); + ret = read(fd, buf, sizeof(buf)); + if (ret < 0) { + return plug_closing(s->plug, strerror(errno), errno, 0); + } else if (ret == 0) { + return plug_closing(s->plug, NULL, 0, 0); + } else { + return plug_receive(s->plug, 0, buf, ret); + } + } } else if (event == 2) { assert(fd == s->to_cmd); if (localproxy_try_send(s)) @@ -252,7 +288,7 @@ Socket platform_new_connection(SockAddr addr, const char *hostname, }; Local_Proxy_Socket ret; - int to_cmd_pipe[2], from_cmd_pipe[2], pid, proxytype; + int to_cmd_pipe[2], from_cmd_pipe[2], cmd_err_pipe[2], pid, proxytype; proxytype = conf_get_int(conf, CONF_proxy_type); if (proxytype != PROXY_CMD && proxytype != PROXY_FUZZ) @@ -266,10 +302,23 @@ Socket platform_new_connection(SockAddr addr, const char *hostname, bufchain_init(&ret->pending_input_data); bufchain_init(&ret->pending_output_data); + bufchain_init(&ret->pending_error_data); if (proxytype == PROXY_CMD) { cmd = format_telnet_command(addr, port, conf); + if (flags & FLAG_STDERR) { + /* If we have a sensible stderr, the proxy command can + * send its own standard error there, so we won't + * interfere. */ + cmd_err_pipe[0] = cmd_err_pipe[1] = -1; + } else { + /* If we don't have a sensible stderr, we should catch the + * proxy command's standard error to put in our event + * log. */ + cmd_err_pipe[0] = cmd_err_pipe[1] = 0; + } + { char *logmsg = dupprintf("Starting local proxy command: %s", cmd); plug_log(plug, 2, NULL, 0, logmsg, 0); @@ -281,13 +330,16 @@ Socket platform_new_connection(SockAddr addr, const char *hostname, * command process. */ if (pipe(to_cmd_pipe) < 0 || - pipe(from_cmd_pipe) < 0) { + pipe(from_cmd_pipe) < 0 || + (cmd_err_pipe[0] == 0 && pipe(cmd_err_pipe) < 0)) { ret->error = dupprintf("pipe: %s", strerror(errno)); sfree(cmd); return (Socket)ret; } cloexec(to_cmd_pipe[1]); cloexec(from_cmd_pipe[0]); + if (cmd_err_pipe[0] >= 0) + cloexec(cmd_err_pipe[0]); pid = fork(); @@ -302,6 +354,10 @@ Socket platform_new_connection(SockAddr addr, const char *hostname, dup2(from_cmd_pipe[1], 1); close(to_cmd_pipe[0]); close(from_cmd_pipe[1]); + if (cmd_err_pipe[0] >= 0) { + dup2(cmd_err_pipe[1], 2); + close(cmd_err_pipe[1]); + } noncloexec(0); noncloexec(1); execl("/bin/sh", "sh", "-c", cmd, (void *)NULL); @@ -312,9 +368,12 @@ Socket platform_new_connection(SockAddr addr, const char *hostname, close(to_cmd_pipe[0]); close(from_cmd_pipe[1]); + if (cmd_err_pipe[0] >= 0) + close(cmd_err_pipe[1]); ret->to_cmd = to_cmd_pipe[1]; ret->from_cmd = from_cmd_pipe[0]; + ret->cmd_err = cmd_err_pipe[0]; } else { cmd = format_telnet_command(addr, port, conf); ret->to_cmd = open("/dev/null", O_WRONLY); @@ -330,17 +389,23 @@ Socket platform_new_connection(SockAddr addr, const char *hostname, return (Socket)ret; } sfree(cmd); + ret->cmd_err = -1; } if (!localproxy_by_fromfd) localproxy_by_fromfd = newtree234(localproxy_fromfd_cmp); if (!localproxy_by_tofd) localproxy_by_tofd = newtree234(localproxy_tofd_cmp); + if (!localproxy_by_errfd) + localproxy_by_errfd = newtree234(localproxy_errfd_cmp); add234(localproxy_by_fromfd, ret); add234(localproxy_by_tofd, ret); + if (ret->cmd_err >= 0) + add234(localproxy_by_errfd, ret); uxsel_set(ret->from_cmd, 1, localproxy_select_result); + uxsel_set(ret->cmd_err, 1, localproxy_select_result); /* We are responsible for this and don't need it any more */ sk_addr_free(addr); diff --git a/windows/winhsock.c b/windows/winhsock.c index f52d5211..6c001815 100644 --- a/windows/winhsock.c +++ b/windows/winhsock.c @@ -18,8 +18,8 @@ struct Socket_handle_tag { const struct socket_function_table *fn; /* the above variable absolutely *must* be the first in this structure */ - HANDLE send_H, recv_H; - struct handle *send_h, *recv_h; + HANDLE send_H, recv_H, stderr_H; + struct handle *send_h, *recv_h, *stderr_h; /* * Freezing one of these sockets is a slightly fiddly business, @@ -39,6 +39,9 @@ struct Socket_handle_tag { /* We buffer data here if we receive it from winhandl while frozen. */ bufchain inputdata; + /* Data received from stderr_H, if we have one. */ + bufchain stderrdata; + char *error; Plug plug; @@ -75,6 +78,16 @@ static int handle_gotdata(struct handle *h, void *data, int len) } } +static int handle_stderr(struct handle *h, void *data, int len) +{ + Handle_Socket ps = (Handle_Socket) handle_get_privdata(h); + + if (len > 0) + log_proxy_stderr(ps->plug, &ps->stderrdata, data, len); + + return 0; +} + static void handle_sentdata(struct handle *h, int new_backlog) { Handle_Socket ps = (Handle_Socket) handle_get_privdata(h); @@ -101,6 +114,7 @@ static void sk_handle_close(Socket s) if (ps->recv_H != ps->send_H) CloseHandle(ps->recv_H); bufchain_clear(&ps->inputdata); + bufchain_clear(&ps->stderrdata); sfree(ps); } @@ -259,8 +273,8 @@ static char *sk_handle_peer_info(Socket s) return NULL; } -Socket make_handle_socket(HANDLE send_H, HANDLE recv_H, Plug plug, - int overlapped) +Socket make_handle_socket(HANDLE send_H, HANDLE recv_H, HANDLE stderr_H, + Plug plug, int overlapped) { static const struct socket_function_table socket_fn_table = { sk_handle_plug, @@ -283,11 +297,16 @@ Socket make_handle_socket(HANDLE send_H, HANDLE recv_H, Plug plug, ret->error = NULL; ret->frozen = UNFROZEN; bufchain_init(&ret->inputdata); + bufchain_init(&ret->stderrdata); ret->recv_H = recv_H; ret->recv_h = handle_input_new(ret->recv_H, handle_gotdata, ret, flags); ret->send_H = send_H; ret->send_h = handle_output_new(ret->send_H, handle_sentdata, ret, flags); + ret->stderr_H = stderr_H; + if (ret->stderr_H) + ret->stderr_h = handle_input_new(ret->stderr_H, handle_stderr, + ret, flags); return (Socket) ret; } diff --git a/windows/winnpc.c b/windows/winnpc.c index 0e8ac699..85a3c3ff 100644 --- a/windows/winnpc.c +++ b/windows/winnpc.c @@ -16,8 +16,8 @@ #include "winsecur.h" -Socket make_handle_socket(HANDLE send_H, HANDLE recv_H, Plug plug, - int overlapped); +Socket make_handle_socket(HANDLE send_H, HANDLE recv_H, HANDLE stderr_H, + Plug plug, int overlapped); Socket new_named_pipe_client(const char *pipename, Plug plug) { @@ -96,7 +96,7 @@ Socket new_named_pipe_client(const char *pipename, Plug plug) LocalFree(psd); sfree(usersid); - return make_handle_socket(pipehandle, pipehandle, plug, TRUE); + return make_handle_socket(pipehandle, pipehandle, NULL, plug, TRUE); } #endif /* !defined NO_SECURITY */ diff --git a/windows/winnps.c b/windows/winnps.c index 2547fd71..f992a4f0 100644 --- a/windows/winnps.c +++ b/windows/winnps.c @@ -16,8 +16,8 @@ #include "winsecur.h" -Socket make_handle_socket(HANDLE send_H, HANDLE recv_H, Plug plug, - int overlapped); +Socket make_handle_socket(HANDLE send_H, HANDLE recv_H, HANDLE stderr_H, + Plug plug, int overlapped); typedef struct Socket_named_pipe_server_tag *Named_Pipe_Server_Socket; struct Socket_named_pipe_server_tag { @@ -120,7 +120,7 @@ static Socket named_pipe_accept(accept_ctx_t ctx, Plug plug) { HANDLE conn = (HANDLE)ctx.p; - return make_handle_socket(conn, conn, plug, TRUE); + return make_handle_socket(conn, conn, NULL, plug, TRUE); } /* diff --git a/windows/winproxy.c b/windows/winproxy.c index 4430a8cb..19ad589c 100644 --- a/windows/winproxy.c +++ b/windows/winproxy.c @@ -22,7 +22,9 @@ Socket platform_new_connection(SockAddr addr, const char *hostname, Plug plug, Conf *conf) { char *cmd; - HANDLE us_to_cmd, us_from_cmd, cmd_to_us, cmd_from_us; + HANDLE us_to_cmd, cmd_from_us; + HANDLE us_from_cmd, cmd_to_us; + HANDLE us_from_cmd_err, cmd_err_to_us; SECURITY_ATTRIBUTES sa; STARTUPINFO si; PROCESS_INFORMATION pi; @@ -64,8 +66,25 @@ Socket platform_new_connection(SockAddr addr, const char *hostname, return ret; } + if (flags & FLAG_STDERR) { + /* If we have a sensible stderr, the proxy command can send + * its own standard error there, so we won't interfere. */ + us_from_cmd_err = cmd_err_to_us = NULL; + } else { + /* If we don't have a sensible stderr, we should catch the + * proxy command's standard error to put in our event log. */ + if (!CreatePipe(&us_from_cmd_err, &cmd_err_to_us, &sa, 0)) { + Socket ret = new_error_socket + ("Unable to create pipes for proxy command", plug); + sfree(cmd); + return ret; + } + } + SetHandleInformation(us_to_cmd, HANDLE_FLAG_INHERIT, 0); SetHandleInformation(us_from_cmd, HANDLE_FLAG_INHERIT, 0); + if (us_from_cmd_err != NULL) + SetHandleInformation(us_from_cmd_err, HANDLE_FLAG_INHERIT, 0); si.cb = sizeof(si); si.lpReserved = NULL; @@ -76,7 +95,7 @@ Socket platform_new_connection(SockAddr addr, const char *hostname, si.lpReserved2 = NULL; si.hStdInput = cmd_from_us; si.hStdOutput = cmd_to_us; - si.hStdError = NULL; + si.hStdError = cmd_err_to_us; CreateProcess(NULL, cmd, NULL, NULL, TRUE, CREATE_NO_WINDOW | NORMAL_PRIORITY_CLASS, NULL, NULL, &si, &pi); @@ -88,5 +107,9 @@ Socket platform_new_connection(SockAddr addr, const char *hostname, CloseHandle(cmd_from_us); CloseHandle(cmd_to_us); - return make_handle_socket(us_to_cmd, us_from_cmd, plug, FALSE); + if (cmd_err_to_us != NULL) + CloseHandle(cmd_err_to_us); + + return make_handle_socket(us_to_cmd, us_from_cmd, us_from_cmd_err, + plug, FALSE); } -- 2.45.2