pytests: rehandshake - search log

diff --git a/tests/pytests/kresd.py b/tests/pytests/kresd.py
index 717383cecd228879c3b85723bc9cfc20103928d1..7f439434832c107893a18f80aa85432ff085b3f9 100644 (file)
--- 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 b1cc5580afe8e46c4f79a76327c25f82c0ab302a..d9cf1a1d68be91de1be05e201619e86eb02ad914 100644 (file)
--- 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 5f731fd38abfc0ec99c030772603f2f0b037fdcb..bf6cc0d4ba1c7ffd54030491391b3d0c06f7f2ca 100644 (file)
--- 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 d6faf482218d67ffe118e1af9e4013106cd6e5b5..e4b164335ff960e0906bdb1c38d82dae4e2eb968 100644 (file)
--- 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()