From: Tomas Krizek Date: Wed, 28 Nov 2018 10:36:20 +0000 (+0100) Subject: pytests: rehandshake - search log X-Git-Tag: v3.2.0~18^2~8 X-Git-Url: http://git.ipfire.org/cgi-bin/gitweb.cgi?a=commitdiff_plain;h=3d446036b53861514efbad8f985b25d7b4565e70;p=thirdparty%2Fknot-resolver.git pytests: rehandshake - search log --- diff --git a/tests/pytests/kresd.py b/tests/pytests/kresd.py index 717383cec..7f4394348 100644 --- a/tests/pytests/kresd.py +++ b/tests/pytests/kresd.py @@ -188,6 +188,23 @@ class Kresd(ContextDecorator): def ip6_tls_socket(self): return self._tls_socket_with_retry(socket.AF_INET6) + def partial_log(self): + partial_log = '\n (... ommiting log start)\n' + with open(self.logfile_path) as log: # display partial log for debugging + past_startup_msgid = False + past_startup = False + for line in log: + if past_startup: + partial_log += line + else: # find real start of test log (after initial alive-pings) + if not past_startup_msgid: + if re.match(KRESD_LOG_STARTUP_MSGID, line) is not None: + past_startup_msgid = True + else: + if re.match(KRESD_LOG_IO_CLOSE, line) is not None: + past_startup = True + return partial_log + def is_port_free(port, ip=None, ip6=None): def check(family, type_, dest): @@ -230,18 +247,4 @@ def make_kresd( tls_port = make_port(ip, ip6) if tls_port is None else tls_port with Kresd(workdir, port, tls_port, ip, ip6, certname, forward=forward, hints=hints) as kresd: yield kresd - with open(kresd.logfile_path) as log: # display partial log for debugging - past_startup_msgid = False - past_startup = False - for line in log: - if past_startup: - line = line.rstrip('\n') - print(line) - else: # find real start of test log (after initial alive-pings) - if not past_startup_msgid: - if re.match(KRESD_LOG_STARTUP_MSGID, line) is not None: - past_startup_msgid = True - else: - if re.match(KRESD_LOG_IO_CLOSE, line) is not None: - past_startup = True - print('\n (... ommiting log start)') + print(kresd.partial_log()) diff --git a/tests/pytests/pylintrc b/tests/pytests/pylintrc index b1cc5580a..d9cf1a1d6 100644 --- a/tests/pytests/pylintrc +++ b/tests/pytests/pylintrc @@ -23,6 +23,7 @@ ignore-imports=no [DESIGN] max-parents=10 +max-locals=20 [TYPECHECK] ignored-modules=ssl diff --git a/tests/pytests/rehandshake/tls-proxy.c b/tests/pytests/rehandshake/tls-proxy.c index 5f731fd38..bf6cc0d4b 100644 --- a/tests/pytests/rehandshake/tls-proxy.c +++ b/tests/pytests/rehandshake/tls-proxy.c @@ -9,7 +9,7 @@ #include "array.h" #define TLS_MAX_SEND_RETRIES 100 - +#define CLIENT_ANSWER_CHUNK_SIZE 8 struct buf { char buf[16 * 1024]; size_t size; @@ -25,6 +25,7 @@ enum peer_state { enum handshake_state { TLS_HS_NOT_STARTED = 0, + TLS_HS_EXPECTED, TLS_HS_IN_PROGRESS, TLS_HS_DONE, TLS_HS_CLOSING, @@ -266,40 +267,42 @@ static void write_to_client_cb(uv_write_t *req, int status) return; } } - if (proxy->client_pending.len > 0) { - struct buf *buf = get_first_client_pending(proxy); - fprintf(stdout, "successfully wrote %zi bytes to client, pending len is %zd\n", - buf->size, proxy->client_pending.len); - remove_first_client_pending(proxy); - release_io_buffer(proxy, buf); - if (proxy->client_state == STATE_CONNECTED && - proxy->tls.handshake_state == TLS_HS_DONE) { - write_to_client_pending(proxy); - } + fprintf(stdout, "successfully wrote to client, pending len is %zd\n", + proxy->client_pending.len); + if (proxy->client_state == STATE_CONNECTED && + proxy->tls.handshake_state == TLS_HS_DONE) { + write_to_client_pending(proxy); } } static void write_to_upstream_cb(uv_write_t *req, int status) { struct tls_proxy_ctx *proxy = (struct tls_proxy_ctx *)req->handle->loop->data; - free(req); if (status) { + free(req); fprintf(stderr, "error writing to upstream: %s\n", uv_strerror(status)); clear_upstream_pending(proxy); proxy->upstream_state = STATE_CLOSING_IN_PROGRESS; uv_close((uv_handle_t*)&proxy->upstream, on_upstream_close); return; } - fprintf(stdout, "successfully wrote to upstream, pending len is %zd\n", proxy->upstream_pending.len); - if (proxy->upstream_pending.len > 0) { + if (req->data != NULL) { + assert(proxy->upstream_pending.len > 0); struct buf *buf = get_first_upstream_pending(proxy); + assert(req->data == (void *)buf->buf); + fprintf(stdout, "successfully wrote %zi bytes to upstream, pending len is %zd\n", + buf->size, proxy->upstream_pending.len); remove_first_upstream_pending(proxy); release_io_buffer(proxy, buf); - if (proxy->upstream_state == STATE_CONNECTED && - proxy->upstream_pending.len > 0) { - write_to_upstream_pending(proxy); - } + } else { + fprintf(stdout, "successfully wrote bytes to upstream, pending len is %zd\n", + proxy->upstream_pending.len); + } + if (proxy->upstream_state == STATE_CONNECTED && + proxy->upstream_pending.len > 0) { + write_to_upstream_pending(proxy); } + free(req); } static void on_client_connection(uv_stream_t *server, int status) @@ -476,6 +479,7 @@ static void push_to_upstream_pending(struct tls_proxy_ctx *proxy, const char *bu memcpy(b->buf, buf, b->size); array_push(proxy->upstream_pending, b); size -= b->size; + buf += b->size; } } @@ -484,9 +488,13 @@ static void push_to_client_pending(struct tls_proxy_ctx *proxy, const char *buf, while (size > 0) { struct buf *b = borrow_io_buffer(proxy); b->size = size <= sizeof(b->buf) ? size : sizeof(b->buf); + if (b->size > CLIENT_ANSWER_CHUNK_SIZE) { + b->size = CLIENT_ANSWER_CHUNK_SIZE; + } memcpy(b->buf, buf, b->size); array_push(proxy->client_pending, b); size -= b->size; + buf += b->size; } } @@ -496,6 +504,7 @@ static int write_to_upstream_pending(struct tls_proxy_ctx *proxy) /* TODO avoid allocation */ uv_write_t *req = (uv_write_t *) malloc(sizeof(uv_write_t)); uv_buf_t wrbuf = uv_buf_init(buf->buf, buf->size); + req->data = buf->buf; fprintf(stdout, "writing %zd bytes to upstream\n", buf->size); return uv_write(req, (uv_stream_t *)&proxy->upstream, &wrbuf, 1, write_to_upstream_cb); } @@ -535,6 +544,7 @@ ssize_t proxy_gnutls_push(gnutls_transport_ptr_t h, const void *buf, size_t len) { data, len } }; memcpy(data, buf, len); + req->data = data; int res = uv_write(req, (uv_stream_t *)&proxy->client, uv_buf, 1, write_to_client_cb); if (res == 0) { ret = len; @@ -594,9 +604,16 @@ static int write_to_client_pending(struct tls_proxy_ctx *proxy) } } while (len > 0); + remove_first_client_pending(proxy); + release_io_buffer(proxy, buf); + fprintf(stdout, "submitted %zd bytes to client\n", submitted); assert (gnutls_safe_renegotiation_status(tls_session) != 0); assert (gnutls_rehandshake(tls_session) == GNUTLS_E_SUCCESS); + /* Prevent write-to-client callback from sending next pending chunk. + * At the same time tls_process_from_client() must not call gnutls_handshake() + * as there can be application data in this direction. */ + proxy->tls.handshake_state = TLS_HS_EXPECTED; fprintf(stdout, "rehandshake started\n"); return submitted; } @@ -613,10 +630,11 @@ static int tls_process_from_upstream(struct tls_proxy_ctx *proxy, const uint8_t return submitted; } + bool list_was_empty = (proxy->client_pending.len == 0); push_to_client_pending(proxy, buf, len); submitted = len; if (proxy->tls.handshake_state == TLS_HS_DONE) { - if (proxy->client_pending.len == 1) { + if (list_was_empty && proxy->client_pending.len > 0) { int ret = write_to_client_pending(proxy); if (ret < 0) { submitted = -1; diff --git a/tests/pytests/test_rehandshake.py b/tests/pytests/test_rehandshake.py index d6faf4822..e4b164335 100644 --- a/tests/pytests/test_rehandshake.py +++ b/tests/pytests/test_rehandshake.py @@ -11,6 +11,7 @@ Make sure to run `make all` in `rehandshake/` to compile the proxy. """ import os +import re import subprocess import time @@ -65,5 +66,16 @@ def test_rehandshake(tmpdir): for hint in hints: resolve_hint(sock2, hint) time.sleep(1) + + # verify log + n_connecting_to = 0 + n_rehandshake = 0 + for line in kresd.partial_log().splitlines(): + if re.search(r"connecting to: .*", line) is not None: + n_connecting_to += 1 + elif re.search(r"TLS rehandshake .* has started", line) is not None: + n_rehandshake += 1 + assert n_connecting_to == 0 # shouldn't be present in partial log + assert n_rehandshake > 0 finally: proxy.terminate()