commit 15ab15881a9216d75ee66cf825f298a8445fd8f0 Author: Chris Ball chris@printf.net Date: Sun Feb 12 19:26:22 2012 -0500

bug5079: Scrub IPs before displaying them in logs.

Scrubbing is turned on by default and can be disabled with "--no-safe-logging".

The scrubbing implemented here goes farther than Tor, in that it scrubs the client addresses too; this avoids putting live obfsproxy bridge addresses in the log. As a side effect, protocol traffic between obfsproxy and Tor is no longer logged -- it can also contain addresses. --- src/main.c | 7 +++- src/managed.c | 10 ++++-- src/network.c | 100 +++++++++++++++++++++++++++++++------------------------- src/util.c | 9 +++++ src/util.h | 4 ++ 5 files changed, 81 insertions(+), 49 deletions(-)

diff --git a/src/main.c b/src/main.c index 7ebdd51..31878f9 100644 --- a/src/main.c +++ b/src/main.c @@ -35,6 +35,8 @@ static struct event *sig_term;

/* Pluggable transport proxy mode. ('External' or 'Managed') */ static int is_external_proxy=1; +/* Whether to scrub connection addresses -- on by default */ +int safe_logging=1;

/** Prints the obfsproxy usage instructions then exits. @@ -52,7 +54,8 @@ usage(void) fprintf(stderr, "\n* obfsproxy_args:\n" "--log-file=<file> ~ set logfile\n" "--log-min-severity=warn|info|debug ~ set minimum logging severity\n" - "--no-log ~ disable logging\n"); + "--no-log ~ disable logging\n" + "--no-safe-logging ~ disable safe (scrubbed address) logging\n");

exit(1); } @@ -164,6 +167,8 @@ handle_obfsproxy_args(const char *const *argv) }

logsev_set=1; + } else if (!strncmp(argv[i], "--no-safe-logging", 18)) { + safe_logging=0; } else if (!strncmp(argv[i], "--managed", 10)) { is_external_proxy=0; } else { diff --git a/src/managed.c b/src/managed.c index 01814f8..2c3f967 100644 --- a/src/managed.c +++ b/src/managed.c @@ -153,9 +153,13 @@ print_protocol_line(const char *format, ...) vprintf(format, ap); fflush(stdout);

- /* log the protocol message */ - log_debug("We sent:"); - log_debug_raw(format, ap2); + /* log the protocol message -- unless safe_logging is on, in which case + * we censor it because the METHOD line contains the bridge address. + */ + if (!safe_logging) { + log_debug("We sent:"); + log_debug_raw(format, ap2); + }

va_end(ap); va_end(ap2); diff --git a/src/network.c b/src/network.c index e61e82d..5e3e788 100644 --- a/src/network.c +++ b/src/network.c @@ -236,7 +236,7 @@ open_listeners(struct event_base *base, config_t *cfg)

if (!lsn->listener) { log_warn("Failed to open listening socket on %s: %s", - lsn->address, + safe_str_client(lsn->address), evutil_socket_error_to_string(EVUTIL_SOCKET_ERROR())); listener_free(lsn); return 0; @@ -299,7 +299,7 @@ listener_cb(struct evconnlistener *evcl, evutil_socket_t fd,

if (!conn || !buf) { log_warn("%s: failed to set up new connection from %s.", - lsn->address, peername); + safe_str_client(lsn->address), safe_str_client(peername)); if (buf) bufferevent_free(buf); else @@ -313,8 +313,10 @@ listener_cb(struct evconnlistener *evcl, evutil_socket_t fd, if (!connections) connections = smartlist_create(); smartlist_add(connections, conn); - log_debug("%s: new connection from %s (%d total)", lsn->address, peername, - smartlist_len(connections)); + log_debug("%s: new connection from %s (%d total)", + safe_str_client(lsn->address), + safe_str_client(peername), + smartlist_len(connections));

conn->peername = peername; conn->buffer = buf; @@ -336,7 +338,7 @@ simple_client_listener_cb(conn_t *conn) { obfs_assert(conn); obfs_assert(conn->mode == LSN_SIMPLE_CLIENT); - log_debug("%s: simple client connection", conn->peername); + log_debug("%s: simple client connection", safe_str_client(conn->peername));

bufferevent_setcb(conn->buffer, upstream_read_cb, NULL, error_cb, conn);

@@ -345,7 +347,7 @@ simple_client_listener_cb(conn_t *conn) return; }

- log_debug("%s: setup complete", conn->peername); + log_debug("%s: setup complete", safe_str_client(conn->peername)); }

/** @@ -357,7 +359,7 @@ socks_client_listener_cb(conn_t *conn) { obfs_assert(conn); obfs_assert(conn->mode == LSN_SOCKS_CLIENT); - log_debug("%s: socks client connection", conn->peername); + log_debug("%s: socks client connection", safe_str_client(conn->peername));

circuit_create_socks(conn);

@@ -367,7 +369,7 @@ socks_client_listener_cb(conn_t *conn) /* Do not create a circuit at this time; the socks handler will do it after it learns the remote peer address. */

- log_debug("%s: setup complete", conn->peername); + log_debug("%s: setup complete", safe_str_client(conn->peername)); }

/** @@ -379,7 +381,7 @@ simple_server_listener_cb(conn_t *conn) { obfs_assert(conn); obfs_assert(conn->mode == LSN_SIMPLE_SERVER); - log_debug("%s: server connection", conn->peername); + log_debug("%s: server connection", safe_str_client(conn->peername));

bufferevent_setcb(conn->buffer, downstream_read_cb, NULL, error_cb, conn);

@@ -388,7 +390,7 @@ simple_server_listener_cb(conn_t *conn) return; }

- log_debug("%s: setup complete", conn->peername); + log_debug("%s: setup complete", safe_str_client(conn->peername)); }

/** @@ -403,7 +405,7 @@ conn_free(conn_t *conn) if (connections) { smartlist_remove(connections, conn); log_debug("Closing connection with %s; %d remaining", - conn->peername ? conn->peername : "'unknown'", + safe_str_client(conn->peername) ? safe_str_client(conn->peername) : "'unknown'", smartlist_len(connections)); } if (conn->peername) @@ -430,7 +432,7 @@ static void conn_free_on_flush(struct bufferevent *bev, void *arg) { conn_t *conn = arg; - log_debug("%s for %s", __func__, conn->peername); + log_debug("%s for %s", __func__, safe_str_client(conn->peername));

if (evbuffer_get_length(bufferevent_get_output(bev)) == 0) conn_free(conn); @@ -506,20 +508,20 @@ open_outbound(conn_t *conn, bufferevent_data_cb readcb) conn_t *newconn;

if (!addr) { - log_warn("%s: no target addresses available", conn->peername); + log_warn("%s: no target addresses available", safe_str_client(conn->peername)); return NULL; }

buf = bufferevent_socket_new(base, -1, BEV_OPT_CLOSE_ON_FREE); if (!buf) { - log_warn("%s: unable to create outbound socket buffer", conn->peername); + log_warn("%s: unable to create outbound socket buffer", safe_str_client(conn->peername)); return NULL; }

newconn = proto_conn_create(conn->cfg); if (!newconn) { log_warn("%s: failed to allocate state for outbound connection", - conn->peername); + safe_str_client(conn->peername)); bufferevent_free(buf); return NULL; } @@ -532,7 +534,7 @@ open_outbound(conn_t *conn, bufferevent_data_cb readcb) if (bufferevent_socket_connect(buf, addr->ai_addr, addr->ai_addrlen) >= 0) goto success; log_info("%s: connection to %s failed: %s", - conn->peername, peername, + safe_str_client(conn->peername), safe_str_client(peername), evutil_socket_error_to_string(EVUTIL_SOCKET_ERROR())); free(peername); addr = addr->ai_next; @@ -546,7 +548,7 @@ open_outbound(conn_t *conn, bufferevent_data_cb readcb)

success: log_info("%s (%s): Successful outbound connection to '%s'.", - conn->peername, conn->cfg->vtable->name, peername); + safe_str_client(conn->peername), conn->cfg->vtable->name, safe_str_client(peername)); bufferevent_enable(buf, EV_READ|EV_WRITE); newconn->peername = peername; obfs_assert(connections); @@ -567,13 +569,13 @@ open_outbound_hostname(conn_t *conn, int af, const char *addr, uint16_t port)

buf = bufferevent_socket_new(base, -1, BEV_OPT_CLOSE_ON_FREE); if (!buf) { - log_warn("%s: unable to create outbound socket buffer", conn->peername); + log_warn("%s: unable to create outbound socket buffer", safe_str_client(conn->peername)); return NULL; } newconn = proto_conn_create(conn->cfg); if (!newconn) { log_warn("%s: failed to allocate state for outbound connection", - conn->peername); + safe_str_client(conn->peername)); bufferevent_free(buf); return NULL; } @@ -604,7 +606,7 @@ open_outbound_hostname(conn_t *conn, int af, const char *addr, uint16_t port) if (bufferevent_socket_connect_hostname(buf, get_evdns_base(), af, addr, port) < 0) { log_warn("%s: outbound connection to %s:%u failed: %s", - conn->peername, addr, port, + safe_str_client(conn->peername), addr, port, evutil_socket_error_to_string(EVUTIL_SOCKET_ERROR())); conn_free(newconn); return NULL; @@ -626,7 +628,8 @@ socks_read_cb(struct bufferevent *bev, void *arg) socks_state_t *socks; enum socks_ret socks_ret;

- log_debug("%s: %s", conn->peername, __func__); + log_debug("%s: %s", safe_str_client(conn->peername), __func__); + obfs_assert(conn->circuit); obfs_assert(conn->circuit->socks_state); socks = conn->circuit->socks_state; @@ -642,8 +645,9 @@ socks_read_cb(struct bufferevent *bev, void *arg) const char *addr=NULL; r = socks_state_get_address(socks, &af, &addr, &port); obfs_assert(r==0); + log_info("%s: socks: trying to connect to %s:%u", - conn->peername, addr, port); + safe_str_client(conn->peername), safe_str_client(addr), port); if (circuit_add_down(conn->circuit, open_outbound_hostname(conn, af, addr, port))) { /* XXXX send socks reply */ @@ -686,7 +690,7 @@ upstream_read_cb(struct bufferevent *bev, void *arg) { conn_t *up = arg; conn_t *down; - log_debug("%s: %s, %lu bytes available", up->peername, __func__, + log_debug("%s: %s, %lu bytes available", safe_str_client(up->peername), __func__, (unsigned long)evbuffer_get_length(bufferevent_get_input(bev)));

obfs_assert(up->buffer == bev); @@ -699,10 +703,12 @@ upstream_read_cb(struct bufferevent *bev, void *arg) if (proto_send(up, bufferevent_get_input(up->buffer), bufferevent_get_output(down->buffer))) { - log_debug("%s: error during transmit.", up->peername); + log_debug("%s: error during transmit.", + safe_str_client(up->peername)); conn_free(up); } else { - log_debug("%s: transmitted %lu bytes", down->peername, + log_debug("%s: transmitted %lu bytes", + safe_str_client(down->peername), (unsigned long) evbuffer_get_length(bufferevent_get_output(down->buffer))); } @@ -720,7 +726,8 @@ downstream_read_cb(struct bufferevent *bev, void *arg) conn_t *up; enum recv_ret r;

- log_debug("%s: %s, %lu bytes available", down->peername, __func__, + log_debug("%s: %s, %lu bytes available", + safe_str_client(down->peername), __func__, (unsigned long)evbuffer_get_length(bufferevent_get_input(bev)));

obfs_assert(down->buffer == bev); @@ -736,23 +743,23 @@ downstream_read_cb(struct bufferevent *bev, void *arg) bufferevent_get_output(up->buffer));

if (r == RECV_BAD) { - log_debug("%s: error during receive.", down->peername); + log_debug("%s: error during receive.", safe_str_client(down->peername)); conn_free(down); } else { - log_debug("%s: forwarded %lu bytes", down->peername, + log_debug("%s: forwarded %lu bytes", safe_str_client(down->peername), (unsigned long) evbuffer_get_length(bufferevent_get_output(up->buffer))); if (r == RECV_SEND_PENDING) { - log_debug("%s: reply of %lu bytes", down->peername, + log_debug("%s: reply of %lu bytes", safe_str_client(down->peername), (unsigned long) evbuffer_get_length(bufferevent_get_input(up->buffer))); if (proto_send(up, bufferevent_get_input(up->buffer), bufferevent_get_output(down->buffer)) < 0) { - log_debug("%s: error during reply.", down->peername); + log_debug("%s: error during reply.", safe_str_client(down->peername)); conn_free(down); } else { - log_debug("%s: transmitted %lu bytes", down->peername, + log_debug("%s: transmitted %lu bytes", safe_str_client(down->peername), (unsigned long) evbuffer_get_length(bufferevent_get_output(down->buffer))); } @@ -772,7 +779,7 @@ error_or_eof(conn_t *conn) struct bufferevent *bev_err = conn->buffer; struct bufferevent *bev_flush;

- log_debug("%s for %s", __func__, conn->peername); + log_debug("%s for %s", __func__, safe_str_client(conn->peername)); if (!circ || !circ->upstream || !circ->downstream || !circ->is_open || circ->is_flushing) { conn_free(conn); @@ -809,7 +816,7 @@ error_cb(struct bufferevent *bev, short what, void *arg) { conn_t *conn = arg; int errcode = EVUTIL_SOCKET_ERROR(); - log_debug("%s for %s: what=0x%04x errno=%d", __func__, conn->peername, + log_debug("%s for %s: what=0x%04x errno=%d", __func__, safe_str_client(conn->peername), what, errcode);

/* It should be impossible to get here with BEV_EVENT_CONNECTED. */ @@ -817,12 +824,12 @@ error_cb(struct bufferevent *bev, short what, void *arg)

if (what & BEV_EVENT_ERROR) { log_warn("Error talking to %s: %s", - conn->peername, + safe_str_client(conn->peername), evutil_socket_error_to_string(errcode)); } else if (what & BEV_EVENT_EOF) { - log_info("EOF from %s", conn->peername); + log_info("EOF from %s", safe_str_client(conn->peername)); } else if (what & BEV_EVENT_TIMEOUT) { - log_info("Timeout talking to %s", conn->peername); + log_info("Timeout talking to %s", safe_str_client(conn->peername)); } error_or_eof(conn); } @@ -836,7 +843,7 @@ flush_error_cb(struct bufferevent *bev, short what, void *arg) { conn_t *conn = arg; int errcode = EVUTIL_SOCKET_ERROR(); - log_debug("%s for %s: what=0x%04x errno=%d", __func__, conn->peername, + log_debug("%s for %s: what=0x%04x errno=%d", __func__, safe_str_client(conn->peername), what, errcode);

/* It should be impossible to get here with BEV_EVENT_CONNECTED. */ @@ -846,7 +853,7 @@ flush_error_cb(struct bufferevent *bev, short what, void *arg) obfs_assert(conn->circuit->is_flushing);

log_warn("Error during flush of connection with %s: %s", - conn->peername, + safe_str_client(conn->peername), evutil_socket_error_to_string(errcode)); conn_free(conn); return; @@ -862,7 +869,7 @@ static void pending_conn_cb(struct bufferevent *bev, short what, void *arg) { conn_t *conn = arg; - log_debug("%s: %s", conn->peername, __func__); + log_debug("%s: %s", safe_str_client(conn->peername), __func__);

/* Upon successful connection, enable traffic on both sides of the connection, and replace this callback with the regular error_cb */ @@ -873,12 +880,12 @@ pending_conn_cb(struct bufferevent *bev, short what, void *arg)

circ->is_open = 1;

- log_debug("%s: Successful connection", conn->peername); + log_debug("%s: Successful connection", safe_str_client(conn->peername));

/* Queue handshake, if any. */ if (proto_handshake(circ->downstream, bufferevent_get_output(circ->downstream->buffer))<0) { - log_debug("%s: Error during handshake", conn->peername); + log_debug("%s: Error during handshake", safe_str_client(conn->peername)); conn_free(conn); return; } @@ -910,7 +917,7 @@ pending_socks_cb(struct bufferevent *bev, short what, void *arg) conn_t *up; socks_state_t *socks;

- log_debug("%s: %s", down->peername, __func__); + log_debug("%s: %s", safe_str_client(down->peername), __func__);

obfs_assert(circ); obfs_assert(circ->upstream); @@ -958,10 +965,12 @@ pending_socks_cb(struct bufferevent *bev, short what, void *arg) connected to. */

char *peername = printable_address(sa, slen); + if (down->peername) { log_debug("We connected to our SOCKS destination! " "Replacing peername '%s' with '%s'", - down->peername, peername); + safe_str_client(down->peername), + safe_str_client(peername)); free(down->peername); } down->peername = peername; @@ -980,7 +989,8 @@ pending_socks_cb(struct bufferevent *bev, short what, void *arg) circ->socks_state = NULL; circ->is_open = 1; log_debug("%s: Successful outbound connection to %s", - up->peername, down->peername); + safe_str_client(up->peername), + safe_str_client(down->peername));

bufferevent_setcb(up->buffer, upstream_read_cb, NULL, error_cb, up); bufferevent_setcb(down->buffer, downstream_read_cb, NULL, error_cb, down); @@ -989,7 +999,7 @@ pending_socks_cb(struct bufferevent *bev, short what, void *arg)

/* Queue handshake, if any. */ if (proto_handshake(down, bufferevent_get_output(down->buffer))) { - log_debug("%s: Error during handshake", down->peername); + log_debug("%s: Error during handshake", safe_str_client(down->peername)); conn_free(down); return; } diff --git a/src/util.c b/src/util.c index f2089df..7ab3567 100644 --- a/src/util.c +++ b/src/util.c @@ -215,6 +215,15 @@ resolve_address_port(const char *address, int nodns, int passive, return ai; }

+const char * +safe_str_client(const char *address) +{ + if (safe_logging) + return "[scrubbed]"; + else + return address; +} + char * printable_address(struct sockaddr *addr, socklen_t addrlen) { diff --git a/src/util.h b/src/util.h index 3396abf..5b758cf 100644 --- a/src/util.h +++ b/src/util.h @@ -153,6 +153,10 @@ int obfs_snprintf(char *str, size_t size, "yyyy-mm-dd hh:mm:ss" (without quotes). */ #define ISO_TIME_LEN 19

+/** Safely log an address, scrubbing if necessary. */ +extern int safe_logging; /* defined in main.c */ +const char * safe_str_client(const char *address); + /** Set the log method, and open the logfile 'filename' if appropriate. */ int log_set_method(int method, const char *filename);