From 3d4d4004e83f19310d90e6341dbf363a47382ec2 Mon Sep 17 00:00:00 2001 From: Simon Tatham Date: Sun, 22 Nov 2015 12:15:52 +0000 Subject: [PATCH] Log the setup of proxied network connections. I've defined a new value for the 'int type' parameter passed to plug_log(), which proxy sockets will use to pass their backend information on how the setup of their proxied connections are going. I've implemented support for the new type code in all _nontrivial_ plug log functions (which, conveniently, are precisely the ones I just refactored into backend_socket_log); the ones which just throw all their log data away anyway will do that to the new code as well. We use the new type code to log the DNS lookup and connection setup for connecting to a networked proxy, and also to log the exact command string sent down Telnet proxy connections (so the user can easily debug mistakes in the configured format string) and the exact command executed when spawning a local proxy process. (The latter was already supported on Windows by a bodgy logging call taking advantage of Windows in particular having no front end pointer; I've converted that into a sensible use of the new plug_log facility, and done the same thing on Unix.) --- be_misc.c | 5 +++ network.h | 5 +++ proxy.c | 80 +++++++++++++++++++++++++++++++++++++++++++--- unix/uxproxy.c | 6 ++++ windows/winproxy.c | 4 +-- 5 files changed, 93 insertions(+), 7 deletions(-) diff --git a/be_misc.c b/be_misc.c index 2ca4fac1..cf8f65c4 100644 --- a/be_misc.c +++ b/be_misc.c @@ -23,6 +23,11 @@ void backend_socket_log(void *frontend, int type, SockAddr addr, int port, sk_getaddr(addr, addrbuf, lenof(addrbuf)); msg = dupprintf("Failed to connect to %s: %s", addrbuf, error_msg); break; + case 2: + /* Proxy-related log messages have their own identifying + * prefix already, put on by our caller. */ + msg = dupstr(error_msg); + break; default: msg = NULL; /* shouldn't happen, but placate optimiser */ break; diff --git a/network.h b/network.h index fbab21a4..2ffa8f38 100644 --- a/network.h +++ b/network.h @@ -58,6 +58,11 @@ struct plug_function_table { * fatal error - we may well have other candidate addresses * to fall back to. When it _is_ fatal, the closing() * function will be called. + * - type==2 means that error_msg contains a line of generic + * logging information about setting up the connection. This + * will typically be a wodge of standard-error output from a + * proxy command, so the receiver should probably prefix it to + * indicate this. */ int (*closing) (Plug p, const char *error_msg, int error_code, int calling_back); diff --git a/proxy.c b/proxy.c index 1f4d7d3d..5b77bc76 100644 --- a/proxy.c +++ b/proxy.c @@ -362,6 +362,15 @@ int proxy_for_destination (SockAddr addr, const char *hostname, return 1; } +static char *dns_log_msg(const char *host, int addressfamily, + const char *reason) +{ + return dupprintf("Looking up host \"%s\"%s for %s", host, + (addressfamily == ADDRTYPE_IPV4 ? " (IPv4)" : + addressfamily == ADDRTYPE_IPV6 ? " (IPv6)" : + ""), reason); +} + SockAddr name_lookup(const char *host, int port, char **canonicalname, Conf *conf, int addressfamily, void *frontend, const char *reason) @@ -382,10 +391,7 @@ SockAddr name_lookup(const char *host, int port, char **canonicalname, return sk_nonamelookup(host); } else { if (frontend) { - logmsg = dupprintf("Looking up host \"%s\"%s for %s", host, - (addressfamily == ADDRTYPE_IPV4 ? " (IPv4)" : - addressfamily == ADDRTYPE_IPV6 ? " (IPv6)" : - ""), reason); + logmsg = dns_log_msg(host, addressfamily, reason); logevent(frontend, logmsg); sfree(logmsg); } @@ -426,6 +432,7 @@ Socket new_connection(SockAddr addr, const char *hostname, Proxy_Plug pplug; SockAddr proxy_addr; char *proxy_canonical_name; + const char *proxy_type; Socket sret; int type; @@ -458,23 +465,45 @@ Socket new_connection(SockAddr addr, const char *hostname, type = conf_get_int(conf, CONF_proxy_type); if (type == PROXY_HTTP) { ret->negotiate = proxy_http_negotiate; + proxy_type = "HTTP"; } else if (type == PROXY_SOCKS4) { ret->negotiate = proxy_socks4_negotiate; + proxy_type = "SOCKS 4"; } else if (type == PROXY_SOCKS5) { ret->negotiate = proxy_socks5_negotiate; + proxy_type = "SOCKS 5"; } else if (type == PROXY_TELNET) { ret->negotiate = proxy_telnet_negotiate; + proxy_type = "Telnet"; } else { ret->error = "Proxy error: Unknown proxy method"; return (Socket) ret; } + { + char *logmsg = dupprintf("Will use %s proxy at %s:%d to connect" + " to %s:%d", proxy_type, + conf_get_str(conf, CONF_proxy_host), + conf_get_int(conf, CONF_proxy_port), + hostname, port); + plug_log(plug, 2, NULL, 0, logmsg, 0); + sfree(logmsg); + } + /* create the proxy plug to map calls from the actual * socket into our proxy socket layer */ pplug = snew(struct Plug_proxy_tag); pplug->fn = &plug_fn_table; pplug->proxy_socket = ret; + { + char *logmsg = dns_log_msg(conf_get_str(conf, CONF_proxy_host), + conf_get_int(conf, CONF_addressfamily), + "proxy"); + plug_log(plug, 2, NULL, 0, logmsg, 0); + sfree(logmsg); + } + /* look-up proxy */ proxy_addr = sk_namelookup(conf_get_str(conf, CONF_proxy_host), &proxy_canonical_name, @@ -487,6 +516,16 @@ Socket new_connection(SockAddr addr, const char *hostname, } sfree(proxy_canonical_name); + { + char addrbuf[256], *logmsg; + sk_getaddr(addr, addrbuf, lenof(addrbuf)); + logmsg = dupprintf("Connecting to %s proxy at %s port %d", + proxy_type, addrbuf, + conf_get_int(conf, CONF_proxy_port)); + plug_log(plug, 2, NULL, 0, logmsg, 0); + sfree(logmsg); + } + /* create the actual socket we will be using, * connected to our proxy server and port. */ @@ -1473,6 +1512,39 @@ int proxy_telnet_negotiate (Proxy_Socket p, int change) formatted_cmd = format_telnet_command(p->remote_addr, p->remote_port, p->conf); + { + /* + * Re-escape control chars in the command, for logging. + */ + char *reescaped = snewn(4*strlen(formatted_cmd) + 1, char); + const char *in; + char *out; + char *logmsg; + + for (in = formatted_cmd, out = reescaped; *in; in++) { + if (*in == '\n') { + *out++ = '\\'; *out++ = 'n'; + } else if (*in == '\r') { + *out++ = '\\'; *out++ = 'r'; + } else if (*in == '\t') { + *out++ = '\\'; *out++ = 't'; + } else if (*in == '\\') { + *out++ = '\\'; *out++ = '\\'; + } else if ((unsigned)(((unsigned char)*in) - 0x20) < + (0x7F-0x20)) { + *out++ = *in; + } else { + out += sprintf(out, "\\x%02X", (unsigned)*in & 0xFF); + } + } + *out = '\0'; + + logmsg = dupprintf("Sending Telnet proxy command: %s", reescaped); + plug_log(p->plug, 2, NULL, 0, logmsg, 0); + sfree(logmsg); + sfree(reescaped); + } + sk_write(p->sub_socket, formatted_cmd, strlen(formatted_cmd)); sfree(formatted_cmd); diff --git a/unix/uxproxy.c b/unix/uxproxy.c index be414878..c66cda2e 100644 --- a/unix/uxproxy.c +++ b/unix/uxproxy.c @@ -270,6 +270,12 @@ Socket platform_new_connection(SockAddr addr, const char *hostname, if (proxytype == PROXY_CMD) { cmd = format_telnet_command(addr, port, conf); + { + char *logmsg = dupprintf("Starting local proxy command: %s", cmd); + plug_log(plug, 2, NULL, 0, logmsg, 0); + sfree(logmsg); + } + /* * Create the pipes to the proxy command, and spawn the proxy * command process. diff --git a/windows/winproxy.c b/windows/winproxy.c index 94954600..4430a8cb 100644 --- a/windows/winproxy.c +++ b/windows/winproxy.c @@ -37,9 +37,7 @@ Socket platform_new_connection(SockAddr addr, const char *hostname, { char *msg = dupprintf("Starting local proxy command: %s", cmd); - /* We're allowed to pass NULL here, because we're part of the Windows - * front end so we know logevent doesn't expect any data. */ - logevent(NULL, msg); + plug_log(plug, 2, NULL, 0, msg, 0); sfree(msg); } -- 2.45.2