[tor-commits] [obfsproxy/master] More logging! And shuffle calls to proto_handshake around. obfs2 still doesn't work.
nickm at torproject.org
nickm at torproject.org
Fri Sep 9 17:08:58 UTC 2011
commit 7950342e23c4739ed2c21f43b38493230520d625
Author: Zack Weinberg <zackw at panix.com>
Date: Thu Jul 28 15:42:33 2011 -0700
More logging! And shuffle calls to proto_handshake around. obfs2 still doesn't work.
---
src/network.c | 81 ++++++++++++++++++++++++++++---------------------
src/protocols/obfs2.c | 47 +++++++++++++++++-----------
2 files changed, 75 insertions(+), 53 deletions(-)
diff --git a/src/network.c b/src/network.c
index 7831a4e..10e45fd 100644
--- a/src/network.c
+++ b/src/network.c
@@ -250,11 +250,6 @@ simple_client_listener_cb(struct evconnlistener *evcl,
bufferevent_setcb(conn->downstream,
downstream_read_cb, NULL, pending_conn_cb, conn);
- /* Queue handshake, if any, before connecting. */
- if (proto_handshake(conn->proto,
- bufferevent_get_output(conn->downstream))<0)
- goto err;
-
/* Launch the connect attempt. */
if (bufferevent_socket_connect(conn->downstream,
lsn->proto_params->target_addr->ai_addr,
@@ -384,11 +379,6 @@ simple_server_listener_cb(struct evconnlistener *evcl,
bufferevent_setcb(conn->upstream,
upstream_read_cb, NULL, pending_conn_cb, conn);
- /* Queue handshake, if any, before connecting. */
- if (proto_handshake(conn->proto,
- bufferevent_get_output(conn->upstream))<0)
- goto err;
-
/* Launch the connect attempt. */
if (bufferevent_socket_connect(conn->upstream,
lsn->proto_params->target_addr->ai_addr,
@@ -501,14 +491,6 @@ socks_read_cb(struct bufferevent *bev, void *arg)
bufferevent_setcb(conn->downstream,
downstream_read_cb, NULL, pending_socks_cb, conn);
- /* Queue handshake, if any, before connecting. */
- if (proto_handshake(conn->proto,
- bufferevent_get_output(conn->downstream))<0) {
- /* XXXX send socks reply */
- close_conn(conn);
- return;
- }
-
r = bufferevent_socket_connect_hostname(conn->downstream,
get_evdns_base(),
af, addr, port);
@@ -555,13 +537,16 @@ static void
upstream_read_cb(struct bufferevent *bev, void *arg)
{
conn_t *conn = arg;
- log_debug("%s for %s", __func__, conn->peername);
+ log_debug("%s: %s, %lu bytes available", conn->peername, __func__,
+ evbuffer_get_length(bufferevent_get_input(bev)));
obfs_assert(bev == conn->upstream);
if (proto_send(conn->proto,
bufferevent_get_input(conn->upstream),
- bufferevent_get_output(conn->downstream)) < 0)
+ bufferevent_get_output(conn->downstream)) < 0) {
+ log_debug("%s: Error during transmit.", conn->peername);
close_conn(conn);
+ }
}
/**
@@ -574,19 +559,27 @@ downstream_read_cb(struct bufferevent *bev, void *arg)
{
conn_t *conn = arg;
enum recv_ret r;
- log_debug("%s for %s", __func__, conn->peername);
+ log_debug("%s: %s, %lu bytes available", conn->peername, __func__,
+ evbuffer_get_length(bufferevent_get_input(bev)));
obfs_assert(bev == conn->downstream);
r = proto_recv(conn->proto,
bufferevent_get_input(conn->downstream),
bufferevent_get_output(conn->upstream));
- if (r == RECV_BAD)
+ if (r == RECV_BAD) {
+ log_debug("%s: Error during receive.", conn->peername);
close_conn(conn);
- else if (r == RECV_SEND_PENDING)
- proto_send(conn->proto,
- bufferevent_get_input(conn->upstream),
- bufferevent_get_output(conn->downstream));
+ } else if (r == RECV_SEND_PENDING) {
+ log_debug("%s: Reply of %ld bytes", conn->peername,
+ evbuffer_get_length(bufferevent_get_input(conn->upstream)));
+ if (proto_send(conn->proto,
+ bufferevent_get_input(conn->upstream),
+ bufferevent_get_output(conn->downstream)) < 0) {
+ log_debug("%s: Error during reply.", conn->peername);
+ close_conn(conn);
+ }
+ }
}
/**
@@ -615,10 +608,11 @@ error_or_eof(conn_t *conn, struct bufferevent *bev_err)
bufferevent_disable(bev_err, EV_READ|EV_WRITE);
bufferevent_setcb(bev_err, NULL, NULL, flush_error_cb, conn);
- bufferevent_disable(bev_flush, EV_READ);
- bufferevent_setcb(bev_flush, NULL,
+ /* XXX Dirty access to bufferevent guts. There appears to be no
+ official API to retrieve the callback functions and/or change
+ just one callback while leaving the others intact. */
+ bufferevent_setcb(bev_flush, bev_flush->readcb,
close_conn_on_flush, flush_error_cb, conn);
- bufferevent_enable(bev_flush, EV_WRITE);
}
/**
@@ -697,7 +691,7 @@ pending_conn_cb(struct bufferevent *bev, short what, void *arg)
{
conn_t *conn = arg;
struct bufferevent *other;
- log_debug("%s for %s", __func__, conn->peername);
+ log_debug("%s: %s", conn->peername, __func__);
if (bev == conn->upstream) other = conn->downstream;
else if (bev == conn->downstream) other = conn->upstream;
@@ -709,9 +703,16 @@ pending_conn_cb(struct bufferevent *bev, short what, void *arg)
obfs_assert(!conn->flushing);
conn->is_open = 1;
- log_debug("Successful %s connection for %s",
- bev == conn->upstream ? "upstream" : "downstream",
- conn->peername);
+ log_debug("%s: Successful %s connection", conn->peername,
+ bev == conn->upstream ? "upstream" : "downstream");
+
+ /* Queue handshake, if any. */
+ if (proto_handshake(conn->proto,
+ bufferevent_get_output(conn->downstream))<0) {
+ log_debug("%s: Error during handshake", conn->peername);
+ close_conn(conn);
+ return;
+ }
/* XXX Dirty access to bufferevent guts. There appears to be no
official API to retrieve the callback functions and/or change
@@ -734,7 +735,7 @@ static void
pending_socks_cb(struct bufferevent *bev, short what, void *arg)
{
conn_t *conn = arg;
- log_debug("%s for %s", __func__, conn->peername);
+ log_debug("%s: %s", conn->peername, __func__);
obfs_assert(bev == conn->downstream);
obfs_assert(conn->socks_state);
@@ -779,13 +780,23 @@ pending_socks_cb(struct bufferevent *bev, short what, void *arg)
socks_state_free(conn->socks_state);
conn->socks_state = NULL;
conn->is_open = 1;
- log_debug("Connection successful");
+ log_debug("%s: Successful %s connection", conn->peername,
+ bev == conn->upstream ? "upstream" : "downstream");
bufferevent_setcb(conn->upstream,
upstream_read_cb, NULL, error_cb, conn);
bufferevent_setcb(conn->downstream,
downstream_read_cb, NULL, error_cb, conn);
bufferevent_enable(conn->upstream, EV_READ|EV_WRITE);
+
+ /* Queue handshake, if any. */
+ if (proto_handshake(conn->proto,
+ bufferevent_get_output(conn->downstream))<0) {
+ log_debug("%s: Error during handshake", conn->peername);
+ close_conn(conn);
+ return;
+ }
+
if (evbuffer_get_length(bufferevent_get_input(conn->upstream)) != 0)
upstream_read_cb(conn->upstream, conn);
return;
diff --git a/src/protocols/obfs2.c b/src/protocols/obfs2.c
index 6a6a975..7d57e20 100644
--- a/src/protocols/obfs2.c
+++ b/src/protocols/obfs2.c
@@ -348,6 +348,11 @@ obfs2_handshake(protocol_t *s, struct evbuffer *buf)
/* Put it on the buffer */
evbuffer_add(buf, msg, OBFUSCATE_SEED_LENGTH+8+plength);
+
+ log_debug("obfs2_handshake: %s queued %ld bytes",
+ state->we_are_initiator ? "initiator" : "responder",
+ evbuffer_get_length(buf));
+
return 0;
}
@@ -366,7 +371,7 @@ obfs2_crypt_and_transmit(crypt_t *crypto,
return 0;
stream_crypt(crypto, data, n);
evbuffer_add(dest, data, n);
- log_debug("%s(): Processed %d bytes.", __func__, n);
+ log_debug("%s: Processed %d bytes.", __func__, n);
}
}
@@ -384,16 +389,25 @@ obfs2_send(protocol_t *s,
if (state->send_crypto) {
/* First of all, send any data that we've been waiting to send. */
if (state->pending_data_to_send) {
- obfs2_crypt_and_transmit(state->send_crypto, state->pending_data_to_send,
+ log_debug("%s: transmitting %ld bytes previously queued.", __func__,
+ evbuffer_get_length(state->pending_data_to_send));
+ obfs2_crypt_and_transmit(state->send_crypto,
+ state->pending_data_to_send,
dest);
evbuffer_free(state->pending_data_to_send);
state->pending_data_to_send = NULL;
}
/* Our crypto is set up; just relay the bytes */
+ if (evbuffer_get_length(source)) {
+ log_debug("%s: transmitting %ld bytes.", __func__,
+ evbuffer_get_length(source));
+ }
return obfs2_crypt_and_transmit(state->send_crypto, source, dest);
} else {
/* Our crypto isn't set up yet, we'll have to queue the data */
if (evbuffer_get_length(source)) {
+ log_debug("%s: handshake incomplete, queueing %ld bytes.", __func__,
+ evbuffer_get_length(source));
if (! state->pending_data_to_send) {
if ((state->pending_data_to_send = evbuffer_new()) == NULL)
return -1;
@@ -453,7 +467,6 @@ obfs2_recv(protocol_t *s, struct evbuffer *source,
struct evbuffer *dest)
{
obfs2_protocol_t *state = downcast_protocol(s);
- enum recv_ret r=0;
if (state->state == ST_WAIT_FOR_KEY) {
/* We're waiting for the first OBFUSCATE_SEED_LENGTH+8 bytes to show up
@@ -461,9 +474,12 @@ obfs2_recv(protocol_t *s, struct evbuffer *source,
uchar buf[OBFUSCATE_SEED_LENGTH+8], *other_seed;
uint32_t magic, plength;
if (evbuffer_get_length(source) < OBFUSCATE_SEED_LENGTH+8) {
+ log_debug("%s: waiting for key, %ld/%d bytes so far",
+ __func__, evbuffer_get_length(source), OBFUSCATE_SEED_LENGTH+8);
/* data not here yet */
return RECV_INCOMPLETE;
}
+
evbuffer_remove(source, buf, OBFUSCATE_SEED_LENGTH+8);
if (state->we_are_initiator)
@@ -494,16 +510,10 @@ obfs2_recv(protocol_t *s, struct evbuffer *source,
/* Fall through here: if there is padding data waiting on the buffer, pull
it off immediately. */
- log_debug("%s(): Received key, expecting %d bytes of padding",
+ log_debug("%s: received key, expecting %d bytes of padding",
__func__, plength);
}
- /* If we have pending data to send, we set the return code
- appropriately so that we call proto_send() right after we get out of
- here! */
- if (state->pending_data_to_send)
- r = RECV_SEND_PENDING;
-
/* If we're still looking for padding, start pulling off bytes and
discarding them. */
while (state->padding_left_to_read) {
@@ -511,25 +521,26 @@ obfs2_recv(protocol_t *s, struct evbuffer *source,
size_t sourcelen = evbuffer_get_length(source);
if (!sourcelen)
return RECV_INCOMPLETE;
- if ((size_t) n > evbuffer_get_length(source))
- n = evbuffer_get_length(source);
+ if ((size_t) n > sourcelen)
+ n = sourcelen;
evbuffer_drain(source, n);
state->padding_left_to_read -= n;
- log_debug("%s(): Received %d bytes of padding; %d left to read",
+ log_debug("%s: consumed %d bytes padding, %d still to come",
__func__, n, state->padding_left_to_read);
}
/* Okay; now we're definitely open. Process whatever data we have. */
state->state = ST_OPEN;
- log_debug("%s(): Processing %d bytes data onto destination buffer",
- __func__, (int) evbuffer_get_length(source));
+ log_debug("%s: Processing %ld bytes application data",
+ __func__, evbuffer_get_length(source));
obfs2_crypt_and_transmit(state->recv_crypto, source, dest);
- if (r != RECV_SEND_PENDING)
- r = RECV_GOOD;
+ /* If we have pending data to send, transmit it now. */
+ if (state->pending_data_to_send)
+ return RECV_SEND_PENDING;
- return r;
+ return RECV_GOOD;
}
DEFINE_PROTOCOL_VTABLE(obfs2);
More information about the tor-commits
mailing list