commit 7950342e23c4739ed2c21f43b38493230520d625 Author: Zack Weinberg <zackw@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);