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).

diff --git a/be_misc.c b/be_misc.c
index cf8f65c4ed05b21a8c4cce2328532f03c65635df..739f1602876cbef0be57c7af47eebf1b3e79c1fb 100644 (file)
--- 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 2ffa8f38bb228cddba6b0fff4c9e65d98402d0a8..bebbd22407824cbc1c3fdbf9f07c911b0cb63ae9 100644 (file)
--- 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 c66cda2e827b9455cd3e54f0205943cc49bc2385..0460522e421f6f370ae9c710bb11dd2214681b20 100644 (file)
--- 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 f52d5211572f3ad1e98d6194dd6793e777f9b11e..6c00181589b6f5693facb622b583ab2ab61f1162 100644 (file)
--- 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 0e8ac6994dc5baa45e21fff76d84451a480f1a32..85a3c3ffc3b6e37b252ba0c7f1d92cd41d33fa7d 100644 (file)
--- 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 2547fd71c5a3863b8114ab8ca4777a0a86e33d5e..f992a4f0cbfd98f46a7dd95f760f6da07c3c1b27 100644 (file)
--- 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 4430a8cbc9f265dbc53ae000a48af1a9155658e2..19ad589c670baca0495577268da9940988e0aa7a 100644 (file)
--- 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);
 }