From 722fa95f9d9b43821df1e13f9d3be91c1c8a86ef Mon Sep 17 00:00:00 2001 From: Alexandr Kitaev Date: Sat, 15 Nov 2025 20:07:23 +0300 Subject: [PATCH 1/7] enhance tls_filter to manage rustls read operations more efficiently --- src/tls_filter.c | 168 ++++++++++++++++++++++++++++++++++++++++++----- 1 file changed, 150 insertions(+), 18 deletions(-) diff --git a/src/tls_filter.c b/src/tls_filter.c index 4b9f9a6..7d68abb 100644 --- a/src/tls_filter.c +++ b/src/tls_filter.c @@ -69,6 +69,19 @@ static apr_status_t read_tls_to_rustls( rustls_result rr = RUSTLS_RESULT_OK; int os_err; apr_status_t rv = APR_SUCCESS; + apr_bucket *b; + /* Check if rustls wants to read data. If not, return EAGAIN to let + * the event loop call us again when rustls is ready. */ + if (!rustls_connection_wants_read(fctx->cc->rustls_connection)) { + if (fctx->fin_block == APR_NONBLOCK_READ) { + rv = APR_EAGAIN; + goto cleanup; + } + /* In blocking mode, we should wait, but for now just return EAGAIN + * to avoid busy-waiting. The event loop will call us again. */ + rv = APR_EAGAIN; + goto cleanup; + } if (APR_BRIGADE_EMPTY(fctx->fin_tls_bb)) { ap_log_error(APLOG_MARK, APLOG_TRACE2, rv, fctx->cc->server, @@ -80,8 +93,14 @@ static apr_status_t read_tls_to_rustls( } } - while (!APR_BRIGADE_EMPTY(fctx->fin_tls_bb) && passed < (apr_off_t)len) { - apr_bucket *b = APR_BRIGADE_FIRST(fctx->fin_tls_bb); + while (!APR_BRIGADE_EMPTY(fctx->fin_tls_bb)) { + /* Check wants_read before each bucket to ensure rustls is ready + * to accept more data. This prevents overwhelming rustls with + * too much data at once. */ + if (!rustls_connection_wants_read(fctx->cc->rustls_connection)) { + break; + } + b = APR_BRIGADE_FIRST(fctx->fin_tls_bb); if (APR_BUCKET_IS_EOS(b)) { ap_log_error(APLOG_MARK, APLOG_TRACE2, rv, fctx->cc->server, @@ -123,19 +142,33 @@ static apr_status_t read_tls_to_rustls( b->start += (apr_off_t)rlen; b->length -= rlen; } - fctx->fin_bytes_in_rustls += (apr_off_t)d.len; + fctx->fin_bytes_in_rustls += (apr_off_t)rlen; + /* passed tracks how much data rustls actually accepted (rlen) */ passed += (apr_off_t)rlen; + + /* Process packets after each successful read_tls call, as per rustls + * documentation: "You should call process_new_packets() each time + * a call to this function succeeds in order to empty the incoming + * TLS data buffer." */ + if (rlen > 0) { + rr = rustls_connection_process_new_packets(fctx->cc->rustls_connection); + if (rr != RUSTLS_RESULT_OK) { + /* If processing fails, we've already passed some data to rustls. + * This is an error condition. Log the error for debugging. */ + const char *err_descr = ""; + apr_status_t err_rv = tls_core_error(fctx->c, rr, &err_descr); + ap_log_cerror(APLOG_MARK, APLOG_WARNING, err_rv, fctx->c, APLOGNO(10353) + "processing TLS data after passing %ld bytes: [%d] %s", + (long)passed, (int)rr, err_descr); + goto cleanup; + } + } } else if (d.len == 0) { apr_bucket_delete(b); } } - if (passed > 0) { - rr = rustls_connection_process_new_packets(fctx->cc->rustls_connection); - if (rr != RUSTLS_RESULT_OK) goto cleanup; - } - cleanup: if (rr != RUSTLS_RESULT_OK) { rv = APR_ECONNRESET; @@ -414,17 +447,21 @@ static apr_status_t filter_conn_input( } /* If we have nothing buffered, try getting more input. + * Event-driven approach: make one attempt per call and return APR_EAGAIN + * if no data is available (in non-blocking mode). Apache's event loop will + * call us again when data becomes available. This avoids busy-waiting loops. * a) ask rustls_connection for decrypted data, if it has any. * Note that only full records can be decrypted. We might have * written TLS data to the session, but that does not mean it * can give unencrypted data out again. * b) read TLS bytes from the network and feed them to the rustls session. - * c) go back to a) if b) added data. + * c) try a) again if b) added data. */ while (APR_BRIGADE_EMPTY(fctx->fin_plain_bb)) { apr_size_t rlen = 0; apr_bucket *b; + /* First attempt: try to read decrypted data from rustls */ if (fctx->fin_bytes_in_rustls > 0) { in_buf_len = APR_BUCKET_BUFF_SIZE; in_buf = ap_calloc(in_buf_len, sizeof(char)); @@ -440,18 +477,75 @@ static apr_status_t filter_conn_input( if (rlen > 0) { b = apr_bucket_heap_create(in_buf, rlen, free, fctx->c->bucket_alloc); APR_BRIGADE_INSERT_TAIL(fctx->fin_plain_bb, b); + in_buf = NULL; + break; /* Got data, exit loop */ } else { free(in_buf); + in_buf = NULL; } - in_buf = NULL; } - if (rlen == 0) { - /* that did not produce anything either. try getting more - * TLS data from the network into the rustls session. */ - fctx->fin_bytes_in_rustls = 0; - rv = read_tls_to_rustls(fctx, fctx->fin_max_in_rustls, block, 0); - if (APR_SUCCESS != rv) goto cleanup; /* this also leave on APR_EAGAIN */ + + /* Second attempt: if we still have nothing, try reading TLS data from network */ + if (rlen == 0 && APR_BRIGADE_EMPTY(fctx->fin_plain_bb)) { + apr_off_t fin_bytes_before = fctx->fin_bytes_in_rustls; + /* Limit the amount of data we read and pass to rustls at once to avoid + * overwhelming rustls. Read at most one TLS record at a time to ensure + * rustls can process it. This is especially important when fin_tls_bb + * already contains data from previous calls. */ + apr_size_t read_limit = TLS_PREF_PLAIN_CHUNK_SIZE; + if (fctx->fin_max_in_rustls < read_limit) { + read_limit = fctx->fin_max_in_rustls; + } + rv = read_tls_to_rustls(fctx, read_limit, block, 0); + if (APR_SUCCESS != rv) { + /* APR_EAGAIN means no data available now. + * Return and let event loop call us again when data arrives. */ + if (APR_STATUS_IS_EAGAIN(rv)) { + goto cleanup; + } + /* Other errors, propagate them */ + goto cleanup; + } + + /* After reading TLS data, always try reading from rustls. + * rustls_connection_process_new_packets may have processed old data. + * Only try if we actually read new TLS data (fin_bytes_in_rustls increased). */ + if (fctx->fin_bytes_in_rustls > fin_bytes_before && APR_BRIGADE_EMPTY(fctx->fin_plain_bb)) { + in_buf_len = APR_BUCKET_BUFF_SIZE; + in_buf = ap_calloc(in_buf_len, sizeof(char)); + rr = rustls_connection_read(fctx->cc->rustls_connection, + (unsigned char*)in_buf, in_buf_len, &rlen); + if (rr == RUSTLS_RESULT_PLAINTEXT_EMPTY) { + rr = RUSTLS_RESULT_OK; + rlen = 0; + } + if (rr != RUSTLS_RESULT_OK) goto cleanup; + if (rlen > 0) { + b = apr_bucket_heap_create(in_buf, rlen, free, fctx->c->bucket_alloc); + APR_BRIGADE_INSERT_TAIL(fctx->fin_plain_bb, b); + in_buf = NULL; + break; /* Got data, exit loop */ + } + else { + free(in_buf); + in_buf = NULL; + } + } + } + + /* If we still have nothing after one iteration: + * - In non-blocking mode, return EAGAIN to let event loop call us again. + * - In blocking mode, continue the loop - read_tls_to_rustls will block + * on the next iteration if needed. This handles cases where TLS records + * arrive in multiple network reads. */ + if (APR_BRIGADE_EMPTY(fctx->fin_plain_bb)) { + if (block == APR_NONBLOCK_READ) { + rv = APR_EAGAIN; + goto cleanup; + } + /* In blocking mode, continue the loop */ + continue; } } @@ -482,7 +576,9 @@ static apr_status_t filter_conn_input( rv = APR_ENOTIMPL; goto cleanup; } - fout_pass_all_to_net(fctx, 0); + /* Note: We don't flush outgoing data from input filter to avoid conflicts + * when rustls is processing incoming data. Outgoing data will be flushed + * from the output filter (tls_filter_conn_output) when it's ready. */ cleanup: if (NULL != in_buf) free(in_buf); @@ -641,6 +737,11 @@ static apr_status_t fout_pass_buf_to_rustls( goto cleanup; } } + /* Note: We don't call fout_pass_rustls_to_tls() here to avoid conflicts. + * TLS data will be prepared and sent through fout_pass_all_to_tls() -> + * fout_pass_rustls_to_tls() which is called from fout_pass_all_to_net() + * at appropriate times. This ensures a single point of TLS data preparation + * and avoids synchronization issues. */ cleanup: if (rr != RUSTLS_RESULT_OK) { const char *err_descr = ""; @@ -743,6 +844,7 @@ static apr_status_t fout_append_plain(tls_filter_ctx_t *fctx, apr_bucket *b) apr_status_t rv = APR_SUCCESS; const char *lbuf = NULL; int flush = 0; + int flush_nonblock = 0; if (b) { /* if our plain buffer is full, now is a good time to flush it. */ @@ -784,6 +886,25 @@ static apr_status_t fout_append_plain(tls_filter_ctx_t *fctx, apr_bucket *b) * buffer contains data. */ rv = fout_add_bucket_to_plain(fctx, b); if (APR_SUCCESS != rv) goto cleanup; + /* For full duplex websocket connections, we need to send small chunks + * promptly to avoid blocking read operations. However, we still want + * to batch small chunks when possible for security (larger TLS records). + * Strategy: + * - If buffer is nearly full (>= 75%), flush with flush bucket + * - Always flush small chunks without blocking flush bucket to ensure + * timely delivery for full duplex websocket connections. + * Using non-blocking flush avoids breaking TLS record synchronization + * while ensuring data is sent promptly. */ + if (fctx->fout_buf_plain_len >= fctx->fout_buf_plain_size * 3 / 4) { + /* Buffer is nearly full, flush with flush bucket */ + flush = 1; + } + else { + /* Always flush small chunks without blocking flush bucket to ensure + * timely delivery for full duplex websocket connections. + * This is critical to avoid hanging on the first small chunk. */ + flush_nonblock = 1; + } } else { /* we have a large chunk and our plain buffer is empty, write it @@ -828,6 +949,9 @@ static apr_status_t fout_append_plain(tls_filter_ctx_t *fctx, apr_bucket *b) if (APR_SUCCESS != rv && !APR_STATUS_IS_EOF(rv)) goto cleanup; rv = fout_pass_buf_to_rustls(fctx, lbuf, dlen); if (APR_SUCCESS != rv) goto cleanup; + /* For large chunks, send TLS data without blocking flush + * to avoid blocking read operations in full duplex mode. */ + flush_nonblock = 1; apr_bucket_delete(b); } else { @@ -835,13 +959,21 @@ static apr_status_t fout_append_plain(tls_filter_ctx_t *fctx, apr_bucket *b) if (APR_SUCCESS != rv) goto cleanup; rv = fout_pass_buf_to_rustls(fctx, data, dlen); if (APR_SUCCESS != rv) goto cleanup; + /* For large chunks, send TLS data without blocking flush + * to avoid blocking read operations in full duplex mode. */ + flush_nonblock = 1; apr_bucket_delete(b); } } } maybe_flush: - if (flush) { + if (flush_nonblock) { + /* Send without blocking flush bucket for full duplex websocket */ + rv = fout_pass_all_to_net(fctx, 0); + if (APR_SUCCESS != rv) goto cleanup; + } + else if (flush) { rv = fout_pass_all_to_net(fctx, 1); if (APR_SUCCESS != rv) goto cleanup; } From 7ff98e02524cddde9b5a0280a836463b2e5b3f57 Mon Sep 17 00:00:00 2001 From: Alexandr Kitaev Date: Sat, 15 Nov 2025 20:31:42 +0300 Subject: [PATCH 2/7] refactor tls_filter to improve rustls data processing logic --- src/tls_filter.c | 9 +++++---- 1 file changed, 5 insertions(+), 4 deletions(-) diff --git a/src/tls_filter.c b/src/tls_filter.c index 7d68abb..aef1495 100644 --- a/src/tls_filter.c +++ b/src/tls_filter.c @@ -488,7 +488,6 @@ static apr_status_t filter_conn_input( /* Second attempt: if we still have nothing, try reading TLS data from network */ if (rlen == 0 && APR_BRIGADE_EMPTY(fctx->fin_plain_bb)) { - apr_off_t fin_bytes_before = fctx->fin_bytes_in_rustls; /* Limit the amount of data we read and pass to rustls at once to avoid * overwhelming rustls. Read at most one TLS record at a time to ensure * rustls can process it. This is especially important when fin_tls_bb @@ -509,9 +508,11 @@ static apr_status_t filter_conn_input( } /* After reading TLS data, always try reading from rustls. - * rustls_connection_process_new_packets may have processed old data. - * Only try if we actually read new TLS data (fin_bytes_in_rustls increased). */ - if (fctx->fin_bytes_in_rustls > fin_bytes_before && APR_BRIGADE_EMPTY(fctx->fin_plain_bb)) { + * rustls_connection_process_new_packets may have processed data and + * made decrypted data available. We should always try to read it, + * even if fin_bytes_in_rustls didn't increase (e.g., if we processed + * data that was already buffered in rustls). */ + if (APR_BRIGADE_EMPTY(fctx->fin_plain_bb)) { in_buf_len = APR_BUCKET_BUFF_SIZE; in_buf = ap_calloc(in_buf_len, sizeof(char)); rr = rustls_connection_read(fctx->cc->rustls_connection, From 4dedeb556937eb545bc243e6ea9b28d43c477f9c Mon Sep 17 00:00:00 2001 From: Alexandr Kitaev Date: Sun, 16 Nov 2025 18:50:10 +0300 Subject: [PATCH 3/7] refactor read_tls_to_rustls to enhance blocking and non-blocking behavior --- src/tls_filter.c | 386 +++++++++++++++++++++++++++++++++++++---------- 1 file changed, 308 insertions(+), 78 deletions(-) diff --git a/src/tls_filter.c b/src/tls_filter.c index aef1495..b4cdf51 100644 --- a/src/tls_filter.c +++ b/src/tls_filter.c @@ -16,6 +16,7 @@ #include #include #include +#include #include #include @@ -63,6 +64,7 @@ static rustls_io_result tls_read_callback( static apr_status_t read_tls_to_rustls( tls_filter_ctx_t *fctx, apr_size_t len, apr_read_type_e block, int errors_expected) { + apr_read_type_e caller_block = block; /* preserve caller's blocking mode */ tls_data_t d; apr_size_t rlen; apr_off_t passed = 0; @@ -70,34 +72,72 @@ static apr_status_t read_tls_to_rustls( int os_err; apr_status_t rv = APR_SUCCESS; apr_bucket *b; - /* Check if rustls wants to read data. If not, return EAGAIN to let - * the event loop call us again when rustls is ready. */ + int force_read = 0; /* Flag to force reading even if wants_read is false */ + apr_read_type_e read_block; + /* Check if rustls wants to read data. If not, we may still need to read + * from the network in blocking mode if we have incomplete TLS records + * (indicated by fin_bytes_in_rustls > 0). */ if (!rustls_connection_wants_read(fctx->cc->rustls_connection)) { - if (fctx->fin_block == APR_NONBLOCK_READ) { + if (block == APR_NONBLOCK_READ) { rv = APR_EAGAIN; goto cleanup; } - /* In blocking mode, we should wait, but for now just return EAGAIN - * to avoid busy-waiting. The event loop will call us again. */ - rv = APR_EAGAIN; - goto cleanup; + /* In blocking mode, if we have data in rustls, it means rustls is + * processing incomplete TLS records and needs more network data to + * complete them. We should continue reading from the network even + * though wants_read is false. */ + if (fctx->fin_bytes_in_rustls > 0) { + /* Rustls has incomplete records, continue to read from network. + * Set force_read flag to ignore wants_read check in the loop. */ + force_read = 1; + } + else { + /* Rustls is not ready and we have no data buffered inside rustls. + * In non-blocking mode, indicate try again; in blocking mode, just + * proceed to read from the network (below) and block as needed. */ + if (block == APR_NONBLOCK_READ) { + rv = APR_EAGAIN; + goto cleanup; + } + /* For blocking mode: do not error here; let the code below perform + * a blocking ap_get_brigade() to fetch more TLS bytes. */ + } } if (APR_BRIGADE_EMPTY(fctx->fin_tls_bb)) { ap_log_error(APLOG_MARK, APLOG_TRACE2, rv, fctx->cc->server, "read_tls_to_rustls, get data from network, block=%d", block); + /* If force_read is set, we need to read from network in blocking mode + * even if wants_read is false, to complete incomplete TLS records. */ + read_block = block; + if (force_read && fctx->fin_block != APR_NONBLOCK_READ) { + read_block = APR_BLOCK_READ; + } rv = ap_get_brigade(fctx->fin_ctx->next, fctx->fin_tls_bb, - AP_MODE_READBYTES, block, (apr_off_t)len); + AP_MODE_READBYTES, read_block, (apr_off_t)len); if (APR_SUCCESS != rv) { - goto cleanup; + /* In blocking mode, do not propagate EAGAIN upward; allow caller loop to retry */ + if (read_block == APR_BLOCK_READ && APR_STATUS_IS_EAGAIN(rv)) { + rv = APR_SUCCESS; + } + else { + goto cleanup; + } } } while (!APR_BRIGADE_EMPTY(fctx->fin_tls_bb)) { + /* Do not feed too much in a single call: keep to ~one TLS record + * so that upper logic can interleave decrypt/flush for WS full-duplex. */ + if (passed >= (apr_off_t)TLS_REC_MAX_SIZE) { + break; + } /* Check wants_read before each bucket to ensure rustls is ready * to accept more data. This prevents overwhelming rustls with - * too much data at once. */ - if (!rustls_connection_wants_read(fctx->cc->rustls_connection)) { + * too much data at once. However, if force_read is set, we ignore + * this check because we need to read more data to complete incomplete + * TLS records. */ + if (!force_read && !rustls_connection_wants_read(fctx->cc->rustls_connection)) { break; } b = APR_BRIGADE_FIRST(fctx->fin_tls_bb); @@ -171,12 +211,24 @@ static apr_status_t read_tls_to_rustls( cleanup: if (rr != RUSTLS_RESULT_OK) { - rv = APR_ECONNRESET; - if (!errors_expected) { - const char *err_descr = ""; - rv = tls_core_error(fctx->c, rr, &err_descr); - ap_log_cerror(APLOG_MARK, APLOG_WARNING, rv, fctx->c, APLOGNO(10353) - "processing TLS data: [%d] %s", (int)rr, err_descr); + /* Treat a peer close_notify as a graceful EOF, not a reset. */ + if (rr == RUSTLS_RESULT_ALERT_CLOSE_NOTIFY) { + rv = APR_EOF; + } + else { + /* If we already processed some bytes, return a soft error instead of reset */ + if (passed > 0) { + rv = APR_EGENERAL; + } + else { + rv = APR_ECONNRESET; + } + if (!errors_expected) { + const char *err_descr = ""; + apr_status_t map_rv = tls_core_error(fctx->c, rr, &err_descr); + ap_log_cerror(APLOG_MARK, APLOG_WARNING, map_rv, fctx->c, APLOGNO(10353) + "processing TLS data: [%d] %s", (int)rr, err_descr); + } } } else if (APR_STATUS_IS_EOF(rv) && passed > 0) { @@ -190,6 +242,31 @@ static apr_status_t read_tls_to_rustls( ap_log_error(APLOG_MARK, APLOG_TRACE2, rv, fctx->cc->server, "read_tls_to_rustls, passed %ld bytes to rustls", (long)passed); } + /* Coerce EAGAIN only for blocking callers; propagate for non-blocking */ + if ((rv == APR_EAGAIN || APR_STATUS_IS_EAGAIN(rv) || rv == APR_FROM_OS_ERROR(EAGAIN))) { + if (caller_block == APR_BLOCK_READ) { + if (APLOGctrace4(fctx->c)) { + ap_log_cerror(APLOG_MARK, APLOG_TRACE4, rv, fctx->c, + "read_tls_to_rustls: coerce EAGAIN->SUCCESS (blocking)"); + } + rv = APR_SUCCESS; + } else { + if (APLOGctrace4(fctx->c)) { + ap_log_cerror(APLOG_MARK, APLOG_TRACE4, rv, fctx->c, + "read_tls_to_rustls: return EAGAIN (non-blocking, no progress)"); + } + rv = APR_EAGAIN; + } + } + /* Final unified trace for exit status and state */ + if (APLOGctrace1(fctx->c)) { + int wants_r = rustls_connection_wants_read(fctx->cc->rustls_connection); + int wants_w = rustls_connection_wants_write(fctx->cc->rustls_connection); + ap_log_cerror(APLOG_MARK, APLOG_TRACE1, rv, fctx->c, + "read_tls_to_rustls: return rv=%d rr=%d passed=%ld block=%d wants_read=%d wants_write=%d fin_bytes_in_rustls=%ld", + (int)rv, (int)rr, (long)passed, (int)block, wants_r, wants_w, + (long)fctx->fin_bytes_in_rustls); + } return rv; } @@ -200,7 +277,8 @@ static apr_status_t fout_pass_tls_to_net(tls_filter_ctx_t *fctx) if (!APR_BRIGADE_EMPTY(fctx->fout_tls_bb)) { rv = ap_pass_brigade(fctx->fout_ctx->next, fctx->fout_tls_bb); if (APR_SUCCESS == rv && fctx->c->aborted) { - rv = APR_ECONNRESET; + /* Graceful close instead of hard reset if peer closed while we flushed */ + rv = APR_EOF; } fctx->fout_bytes_in_tls_bb = 0; apr_brigade_cleanup(fctx->fout_tls_bb); @@ -211,6 +289,9 @@ static apr_status_t fout_pass_tls_to_net(tls_filter_ctx_t *fctx) static apr_status_t fout_pass_all_to_net( tls_filter_ctx_t *fctx, int flush); +/* Forward declaration to allow calls from input filter before definition */ +static apr_status_t fout_pass_rustls_to_tls(tls_filter_ctx_t *fctx); + static apr_status_t filter_abort( tls_filter_ctx_t *fctx) { @@ -247,7 +328,9 @@ static apr_status_t filter_recv_client_hello(tls_filter_ctx_t *fctx) rv = read_tls_to_rustls(fctx, fctx->fin_max_in_rustls, APR_BLOCK_READ, 1); if (APR_SUCCESS != rv) { if (fctx->cc->client_hello_seen) { - rv = APR_EAGAIN; /* we got what we needed */ + /* We got what we needed - client hello was seen. + * In blocking mode, we return SUCCESS since we achieved our goal. */ + rv = APR_SUCCESS; break; } /* Something went wrong before we saw the client hello. @@ -269,7 +352,7 @@ static apr_status_t filter_recv_client_hello(tls_filter_ctx_t *fctx) fctx->fin_tls_bb = fctx->fin_tls_buffer_bb; /* data we already fed to the pre_session */ fctx->fin_tls_buffer_bb = NULL; APR_BRIGADE_CONCAT(fctx->fin_tls_bb, bb_tmp); /* all tls data from the client so far, reloaded */ - apr_brigade_destroy(bb_tmp); + apr_brigade_cleanup(bb_tmp); rv = APR_SUCCESS; } @@ -447,22 +530,31 @@ static apr_status_t filter_conn_input( } /* If we have nothing buffered, try getting more input. - * Event-driven approach: make one attempt per call and return APR_EAGAIN - * if no data is available (in non-blocking mode). Apache's event loop will - * call us again when data becomes available. This avoids busy-waiting loops. - * a) ask rustls_connection for decrypted data, if it has any. - * Note that only full records can be decrypted. We might have - * written TLS data to the session, but that does not mean it - * can give unencrypted data out again. - * b) read TLS bytes from the network and feed them to the rustls session. - * c) try a) again if b) added data. + * Use a simple loop similar to filter_recv_client_hello: + * - In blocking mode: loop until we get plaintext data or encounter an error + * - In non-blocking mode: make one attempt and return EAGAIN if no data available + * + * a) try to read decrypted data from rustls (if we have data in rustls) + * b) if nothing, check if rustls wants to read and read TLS bytes from network + * c) after reading TLS, try reading plaintext from rustls again */ while (APR_BRIGADE_EMPTY(fctx->fin_plain_bb)) { apr_size_t rlen = 0; apr_bucket *b; + int tls_read_attempted = 0; - /* First attempt: try to read decrypted data from rustls */ - if (fctx->fin_bytes_in_rustls > 0) { + /* If rustls has pending writes, flush them to the network first. + * This avoids stalling when peer expects TLS records (websocket full-duplex). */ + if (rustls_connection_wants_write(fctx->cc->rustls_connection)) { + rv = fout_pass_rustls_to_tls(fctx); + if (APR_SUCCESS != rv) goto cleanup; + } + + /* First attempt: try to read decrypted data from rustls. + * In blocking mode, always try to read plaintext, even if fin_bytes_in_rustls == 0, + * because rustls may process data asynchronously after process_new_packets. + * In non-blocking mode, only try if we have data in rustls. */ + if (fctx->fin_bytes_in_rustls > 0 || block == APR_BLOCK_READ) { in_buf_len = APR_BUCKET_BUFF_SIZE; in_buf = ap_calloc(in_buf_len, sizeof(char)); rr = rustls_connection_read(fctx->cc->rustls_connection, @@ -486,66 +578,132 @@ static apr_status_t filter_conn_input( } } - /* Second attempt: if we still have nothing, try reading TLS data from network */ + /* Second attempt: read TLS data from network if rustls wants to read. + * In blocking mode, always try reading if we don't have plaintext, to avoid + * infinite loops. In blocking mode, we must read until we get plaintext or EOF. */ if (rlen == 0 && APR_BRIGADE_EMPTY(fctx->fin_plain_bb)) { - /* Limit the amount of data we read and pass to rustls at once to avoid - * overwhelming rustls. Read at most one TLS record at a time to ensure - * rustls can process it. This is especially important when fin_tls_bb - * already contains data from previous calls. */ - apr_size_t read_limit = TLS_PREF_PLAIN_CHUNK_SIZE; - if (fctx->fin_max_in_rustls < read_limit) { - read_limit = fctx->fin_max_in_rustls; + int should_read_tls = 0; + if (rustls_connection_wants_read(fctx->cc->rustls_connection)) { + should_read_tls = 1; } - rv = read_tls_to_rustls(fctx, read_limit, block, 0); - if (APR_SUCCESS != rv) { - /* APR_EAGAIN means no data available now. - * Return and let event loop call us again when data arrives. */ - if (APR_STATUS_IS_EAGAIN(rv)) { + else if (block == APR_BLOCK_READ) { + /* In blocking mode, always try reading if we don't have plaintext. + * This prevents infinite loops when rustls needs more data but + * wants_read is temporarily false. */ + should_read_tls = 1; + } + + if (should_read_tls) { + apr_size_t read_limit; + int force_read_flag; + apr_off_t bytes_in_rustls_before; + /* Avoid blocking brigade length checks; they may stall the input filter */ + + /* Limit the amount of data we read and pass to rustls at once to avoid + * overwhelming rustls. Read at most one TLS record at a time to ensure + * rustls can process it. */ + /* Prefer larger pulls in non-blocking to reduce idle gaps */ + if (block == APR_NONBLOCK_READ) { + read_limit = fctx->fin_max_in_rustls; + } + else { + read_limit = TLS_PREF_PLAIN_CHUNK_SIZE; + if (fctx->fin_max_in_rustls < read_limit) { + read_limit = fctx->fin_max_in_rustls; + } + } + /* Use force_read if wants_read is false but we're in blocking mode. + * This allows us to read from network even when rustls says it doesn't + * want more data, which is necessary to avoid infinite loops when + * plaintext hasn't appeared yet. */ + force_read_flag = (block == APR_BLOCK_READ && + !rustls_connection_wants_read(fctx->cc->rustls_connection) && + (!APR_BRIGADE_EMPTY(fctx->fin_tls_bb) || fctx->fin_bytes_in_rustls > 0)) ? 1 : 0; + /* Track how much data we had in rustls before reading */ + bytes_in_rustls_before = fctx->fin_bytes_in_rustls; + /* Do not call apr_brigade_length() here to avoid blocking */ + + rv = read_tls_to_rustls(fctx, read_limit, block, force_read_flag); + tls_read_attempted = 1; + if (APR_SUCCESS != rv) { + if (APR_STATUS_IS_EAGAIN(rv)) { + /* On EAGAIN: non-blocking returns up; blocking always retry loop */ + if (block == APR_NONBLOCK_READ) { + goto cleanup; + } + /* Blocking mode: keep trying (do not bubble EAGAIN upward) */ + continue; + } + /* Other errors, propagate them */ goto cleanup; } - /* Other errors, propagate them */ - goto cleanup; - } - /* After reading TLS data, always try reading from rustls. - * rustls_connection_process_new_packets may have processed data and - * made decrypted data available. We should always try to read it, - * even if fin_bytes_in_rustls didn't increase (e.g., if we processed - * data that was already buffered in rustls). */ - if (APR_BRIGADE_EMPTY(fctx->fin_plain_bb)) { - in_buf_len = APR_BUCKET_BUFF_SIZE; - in_buf = ap_calloc(in_buf_len, sizeof(char)); - rr = rustls_connection_read(fctx->cc->rustls_connection, - (unsigned char*)in_buf, in_buf_len, &rlen); - if (rr == RUSTLS_RESULT_PLAINTEXT_EMPTY) { - rr = RUSTLS_RESULT_OK; - rlen = 0; + /* After feeding TLS bytes, if rustls wants to write (e.g., ACKs), flush them. */ + if (rustls_connection_wants_write(fctx->cc->rustls_connection)) { + rv = fout_pass_rustls_to_tls(fctx); + if (APR_SUCCESS != rv) goto cleanup; } - if (rr != RUSTLS_RESULT_OK) goto cleanup; - if (rlen > 0) { - b = apr_bucket_heap_create(in_buf, rlen, free, fctx->c->bucket_alloc); - APR_BRIGADE_INSERT_TAIL(fctx->fin_plain_bb, b); - in_buf = NULL; - break; /* Got data, exit loop */ + + /* Check if we actually read any new data. If not, and we're in blocking mode, + * we might be stuck. Continue the loop to try reading plaintext again. */ + if (block == APR_BLOCK_READ && fctx->fin_bytes_in_rustls == bytes_in_rustls_before && + APR_BRIGADE_EMPTY(fctx->fin_tls_bb)) { + /* No progress and no buffered TLS data: loop again and let network provide more */ + continue; } - else { - free(in_buf); - in_buf = NULL; + + /* After reading TLS data, always try reading plaintext from rustls. + * rustls_connection_process_new_packets may have processed data and + * made decrypted data available. We should always try to read it, + * even if fin_bytes_in_rustls didn't increase (e.g., if we processed + * data that was already buffered in rustls). */ + if (APR_BRIGADE_EMPTY(fctx->fin_plain_bb)) { + in_buf_len = APR_BUCKET_BUFF_SIZE; + in_buf = ap_calloc(in_buf_len, sizeof(char)); + rr = rustls_connection_read(fctx->cc->rustls_connection, + (unsigned char*)in_buf, in_buf_len, &rlen); + if (rr == RUSTLS_RESULT_PLAINTEXT_EMPTY) { + rr = RUSTLS_RESULT_OK; + rlen = 0; + } + if (rr != RUSTLS_RESULT_OK) goto cleanup; + if (rlen > 0) { + b = apr_bucket_heap_create(in_buf, rlen, free, fctx->c->bucket_alloc); + APR_BRIGADE_INSERT_TAIL(fctx->fin_plain_bb, b); + in_buf = NULL; + break; /* Got data, exit loop */ + } + else { + free(in_buf); + in_buf = NULL; + } } } } /* If we still have nothing after one iteration: * - In non-blocking mode, return EAGAIN to let event loop call us again. - * - In blocking mode, continue the loop - read_tls_to_rustls will block - * on the next iteration if needed. This handles cases where TLS records - * arrive in multiple network reads. */ + * - In blocking mode, continue the loop (similar to filter_recv_client_hello). */ if (APR_BRIGADE_EMPTY(fctx->fin_plain_bb)) { if (block == APR_NONBLOCK_READ) { rv = APR_EAGAIN; goto cleanup; } - /* In blocking mode, continue the loop */ + /* In blocking mode, if we just read TLS data but didn't get plaintext, + * continue the loop to try reading plaintext again (rustls may need + * more data to complete records) or read more TLS data if needed. */ + if (tls_read_attempted) { + /* We read TLS data but didn't get plaintext. Continue the loop + * to try reading plaintext again (on next iteration, fin_bytes_in_rustls + * will be checked) or read more TLS data if wants_read is true. */ + continue; + } + /* In blocking mode, check if we have buffered TLS data to process */ + if (!APR_BRIGADE_EMPTY(fctx->fin_tls_bb)) { + continue; + } + /* In blocking mode, continue the loop - read_tls_to_rustls will block if needed. + * Similar to filter_recv_client_hello, we just loop until we get data. */ continue; } } @@ -595,9 +753,23 @@ static apr_status_t filter_conn_input( ap_log_cerror(APLOG_MARK, APLOG_DEBUG, rv, fctx->c, APLOGNO(10355) "tls_filter_conn_input: [%d] %s", (int)rr, err_descr); } - else if (APR_STATUS_IS_EAGAIN(rv)) { - ap_log_cerror(APLOG_MARK, APLOG_TRACE4, rv, fctx->c, - "tls_filter_conn_input: no data available"); + else if (APR_STATUS_IS_EAGAIN(rv) || rv == APR_FROM_OS_ERROR(EAGAIN) || rv == APR_EAGAIN) { + /* Coerce EAGAIN only for blocking callers; propagate for non-blocking */ + if (fctx->fin_block == APR_BLOCK_READ) { + if (APLOGctrace4(fctx->c)) { + ap_log_cerror(APLOG_MARK, APLOG_TRACE4, rv, fctx->c, + "tls_filter_conn_input: coerce EAGAIN->SUCCESS (blocking)"); + } + rv = APR_SUCCESS; + ap_log_cerror(APLOG_MARK, APLOG_TRACE4, rv, fctx->c, + "tls_filter_conn_input: no data available"); + } else { + if (APLOGctrace4(fctx->c)) { + ap_log_cerror(APLOG_MARK, APLOG_TRACE4, rv, fctx->c, + "tls_filter_conn_input: return EAGAIN (non-blocking, no data)"); + } + rv = APR_EAGAIN; + } } else if (APR_SUCCESS != rv) { ap_log_cerror(APLOG_MARK, APLOG_DEBUG, rv, fctx->c, APLOGNO(10356) @@ -613,6 +785,29 @@ static apr_status_t filter_conn_input( ap_filter_setaside_brigade(f, fctx->fin_plain_bb); } #endif + /* Final guard: coerce EAGAIN only for blocking callers */ + if (APR_STATUS_IS_EAGAIN(rv) || rv == APR_FROM_OS_ERROR(EAGAIN) || rv == APR_EAGAIN) { + if (fctx->fin_block == APR_BLOCK_READ) { + if (APLOGctrace4(fctx->c)) { + ap_log_cerror(APLOG_MARK, APLOG_TRACE4, rv, fctx->c, + "tls_filter_conn_input: final coerce EAGAIN->SUCCESS (blocking)"); + } + rv = APR_SUCCESS; + } else { + if (APLOGctrace4(fctx->c)) { + ap_log_cerror(APLOG_MARK, APLOG_TRACE4, rv, fctx->c, + "tls_filter_conn_input: final return EAGAIN (non-blocking)"); + } + rv = APR_EAGAIN; + } + } + if (APLOGctrace1(fctx->c)) { + int wants_r = fctx->cc->rustls_connection ? rustls_connection_wants_read(fctx->cc->rustls_connection) : 0; + int wants_w = fctx->cc->rustls_connection ? rustls_connection_wants_write(fctx->cc->rustls_connection) : 0; + ap_log_cerror(APLOG_MARK, APLOG_TRACE1, rv, fctx->c, + "tls_filter_conn_input: return rv=%d rr=%d mode=%d block=%d passed=%ld wants_read=%d wants_write=%d fin_bytes_in_rustls=%ld", + (int)rv, (int)rr, (int)mode, (int)block, (long)passed, wants_r, wants_w, (long)fctx->fin_bytes_in_rustls); + } return rv; } @@ -868,6 +1063,15 @@ static apr_status_t fout_append_plain(tls_filter_ctx_t *fctx, apr_bucket *b) } /* Now `b` is the bucket that we need to append and consume */ if (APR_BUCKET_IS_METADATA(b)) { + /* According to Apache filter documentation, metadata buckets (especially + * FLUSH) must be passed down the chain. FLUSH buckets force filters to + * write any data set aside. We need to ensure all buffered data is + * sent before passing the metadata bucket. */ + /* Flush any buffered plain data before processing metadata bucket */ + if (fctx->fout_buf_plain_len > 0) { + rv = fout_pass_all_to_tls(fctx); + if (APR_SUCCESS != rv) goto cleanup; + } /* outgoing buckets: * [PLAINDATA META PLAINDATA META META] * need to become: @@ -1008,6 +1212,13 @@ static apr_status_t filter_conn_output( tls_filter_ctx_t *fctx = f->ctx; apr_status_t rv = APR_SUCCESS; rustls_result rr = RUSTLS_RESULT_OK; + int eos_seen = 0; + + /* According to Apache filter documentation, output filters should not + * pass empty brigades down the chain. Return early if empty. */ + if (APR_BRIGADE_EMPTY(bb)) { + return APR_SUCCESS; + } if (f->c->aborted) { ap_log_cerror(APLOG_MARK, APLOG_TRACE4, 0, fctx->c, @@ -1034,10 +1245,29 @@ static apr_status_t filter_conn_output( } while (!APR_BRIGADE_EMPTY(bb)) { - rv = fout_append_plain(fctx, APR_BRIGADE_FIRST(bb)); + apr_bucket *b = APR_BRIGADE_FIRST(bb); + + /* According to Apache filter documentation, after seeing EOS, + * all subsequent buckets should be ignored. */ + if (eos_seen) { + apr_bucket_delete(b); + continue; + } + + /* Check for EOS bucket */ + if (APR_BUCKET_IS_EOS(b)) { + eos_seen = 1; + } + + rv = fout_append_plain(fctx, b); if (APR_SUCCESS != rv) goto cleanup; } + /* After consuming all plain buckets, push any pending TLS data to the network. + * Use non-blocking flush semantics to avoid stalling full-duplex streams. */ + rv = fout_pass_all_to_net(fctx, 0); + if (APR_SUCCESS != rv) goto cleanup; + if (APLOGctrace5(fctx->c)) { tls_util_bb_log(fctx->c, APLOG_TRACE5, "filter_conn_output, processed plain", bb); tls_util_bb_log(fctx->c, APLOG_TRACE5, "filter_conn_output, tls", fctx->fout_tls_bb); @@ -1137,7 +1367,7 @@ void tls_filter_conn_init(conn_rec *c) "tls_filter_conn_init on %s, triggering handshake", c->base_server->server_hostname); temp = apr_brigade_create(c->pool, c->bucket_alloc); ap_get_brigade(c->input_filters, temp, AP_MODE_INIT, APR_BLOCK_READ, 0); - apr_brigade_destroy(temp); + apr_brigade_cleanup(temp); } } From 3dd11983979939dd2d5f9f60d1dbd17635212032 Mon Sep 17 00:00:00 2001 From: Stefan Eissing Date: Mon, 17 Nov 2025 17:52:32 +0100 Subject: [PATCH 4/7] add websocket test cases (#11) * add websocket test cases * add websockets to python requirements --- test/modules/tls/env.py | 12 --- test/modules/tls/test_13_proxy.py | 2 + test/modules/tls/test_18_ws.py | 141 ++++++++++++++++++++++++++++++ test/modules/tls/ws_server.py | 104 ++++++++++++++++++++++ test/pyhttpd/env.py | 1 + test/requirements.txt | 1 + 6 files changed, 249 insertions(+), 12 deletions(-) create mode 100644 test/modules/tls/test_18_ws.py create mode 100755 test/modules/tls/ws_server.py diff --git a/test/modules/tls/env.py b/test/modules/tls/env.py index 30910f0..8399d52 100644 --- a/test/modules/tls/env.py +++ b/test/modules/tls/env.py @@ -107,18 +107,6 @@ def __init__(self, pytestconfig=None): ' AddHandler cgi-script .py', ' Options +ExecCGI', '', - f'', - ' ServerName localhost', - ' DocumentRoot "htdocs"', - '', - f'', - f' ServerName {self.domain_a}', - ' DocumentRoot "htdocs/a.mod-tls.test"', - '', - f'', - f' ServerName {self.domain_b}', - ' DocumentRoot "htdocs/b.mod-tls.test"', - '', ]) self.add_cert_specs([ CertificateSpec(domains=[self.domain_a]), diff --git a/test/modules/tls/test_13_proxy.py b/test/modules/tls/test_13_proxy.py index 42a1efb..6490c79 100644 --- a/test/modules/tls/test_13_proxy.py +++ b/test/modules/tls/test_13_proxy.py @@ -18,6 +18,8 @@ def _class_scope(self, env): ] }) # add vhosts a+b and a ssl proxy from a to b + conf.add_vhost('localhost', port=env.http_port) + conf.add_vhost(env.domain_b, port=env.http_port, doc_root=f"htdocs/{env.domain_b}") conf.add_tls_vhosts(domains=[env.domain_a, env.domain_b]) conf.install() assert env.apache_restart() == 0 diff --git a/test/modules/tls/test_18_ws.py b/test/modules/tls/test_18_ws.py new file mode 100644 index 0000000..5ef90e8 --- /dev/null +++ b/test/modules/tls/test_18_ws.py @@ -0,0 +1,141 @@ +import ssl +from datetime import datetime, timedelta +import inspect +import os +import shutil +import subprocess +import time + +import pytest +import websockets +from websockets.sync.client import connect + +from .conf import TlsTestConf + + +def mk_text_file(fpath: str, lines: int): + t110 = 11 * "0123456789" + with open(fpath, "w") as fd: + for i in range(lines): + fd.write("{0:015d}: ".format(i)) # total 128 bytes per line + fd.write(t110) + fd.write("\n") + + +class TestWebSockets: + + @pytest.fixture(autouse=True, scope='class') + def _class_scope(self, env): + # Apache config that CONNECT proxies a WebSocket server for paths starting + # with '/ws/' + # The WebSocket server is started in pytest fixture 'ws_server' below. + conf = TlsTestConf(env, extras={ + 'base': [ + 'Timeout 1', + ], + 'localhost': [ + f'ProxyPass /ws/ http://127.0.0.1:{env.ws_port}/ upgrade=websocket \\', + f'timeout=2 flushpackets=on', + ], + f'cgi.{env.http_tld}': [ + f' ProxyPass /ws/ http://127.0.0.1:{env.ws_port}/ \\', + f' upgrade=websocket timeout=2 flushpackets=on', + f' ReadBufferSize 65535' + ] + }) + conf.add_vhost('localhost', port=env.http_port) + conf.add_tls_vhosts(['localhost'], port=env.https_port) + conf.install() + mk_text_file(os.path.join(env.gen_dir, "1k.txt"), 8) + mk_text_file(os.path.join(env.gen_dir, "10k.txt"), 80) + mk_text_file(os.path.join(env.gen_dir, "100k.txt"), 800) + mk_text_file(os.path.join(env.gen_dir, "1m.txt"), 8000) + mk_text_file(os.path.join(env.gen_dir, "10m.txt"), 80000) + assert env.apache_restart() == 0 + + def ws_check_alive(self, env, timeout=5): + url = f'http://localhost:{env.ws_port}/' + end = datetime.now() + timedelta(seconds=timeout) + while datetime.now() < end: + r = env.curl_get(url, 5) + if r.exit_code == 0: + return True + time.sleep(.1) + return False + + def _mkpath(self, path): + if not os.path.exists(path): + return os.makedirs(path) + + def _rmrf(self, path): + if os.path.exists(path): + return shutil.rmtree(path) + + def ws_recv_text(self, ws): + msg = "" + while True: + try: + msg += ws.recv() + except websockets.exceptions.ConnectionClosedOK: + return msg + + def ws_recv_bytes(self, ws): + msg = b'' + while True: + try: + msg += ws.recv() + except websockets.exceptions.ConnectionClosedOK: + return msg + + @pytest.fixture(autouse=True, scope='class') + def ws_server(self, env): + # Run our python websockets server that has some special behaviour + # for the different path to CONNECT to. + run_dir = os.path.join(env.gen_dir, 'ws-server') + err_file = os.path.join(run_dir, 'stderr') + self._rmrf(run_dir) + self._mkpath(run_dir) + with open(err_file, 'w') as cerr: + cmd = os.path.join(os.path.dirname(inspect.getfile(TestWebSockets)), + 'ws_server.py') + args = ['python3', cmd, '--port', str(env.ws_port)] + p = subprocess.Popen(args=args, cwd=run_dir, stderr=cerr, + stdout=cerr) + if not self.ws_check_alive(env): + p.kill() + p.wait() + pytest.fail(f'ws_server did not start. stderr={open(err_file).readlines()}') + yield + p.terminate() + + def test_tls_18_01_direct(self, env): + with connect(f"ws://127.0.0.1:{env.ws_port}/echo") as ws: + message = "Hello world!" + ws.send(message) + response = self.ws_recv_text(ws) + assert response == message + + def test_tls_18_02_httpd_plain(self, env): + with connect(f"ws://localhost:{env.http_port}/ws/echo/") as ws: + message = "Hello world!" + ws.send(message) + response = self.ws_recv_text(ws) + assert response == message + + @pytest.mark.parametrize("fname", ["1k.txt", "10k.txt", "100k.txt", "1m.txt", "10m.txt"]) + def test_tls_18_03_file(self, env, fname): + expected = open(os.path.join(env.gen_dir, fname), 'rb').read() + with connect(f"ws://localhost:{env.http_port}/ws/file/{fname}") as ws: + response = self.ws_recv_bytes(ws) + assert response == expected + + @pytest.mark.parametrize("fname", ["1k.txt", "10k.txt", "100k.txt", "1m.txt", "10m.txt"]) + def test_tls_18_04_tls_file(self, env, fname): + expected = open(os.path.join(env.gen_dir, fname), 'rb').read() + ssl_ctx = ssl.SSLContext(protocol=ssl.PROTOCOL_TLS_CLIENT) + ssl_ctx.check_hostname = False + ssl_ctx.verify_mode = ssl.VerifyMode.CERT_NONE + with connect(f"wss://localhost:{env.https_port}/ws/file/{fname}", + ssl_context=ssl_ctx) as ws: + response = self.ws_recv_bytes(ws) + assert response == expected diff --git a/test/modules/tls/ws_server.py b/test/modules/tls/ws_server.py new file mode 100755 index 0000000..99fb9cf --- /dev/null +++ b/test/modules/tls/ws_server.py @@ -0,0 +1,104 @@ +#!/usr/bin/env python3 +import argparse +import asyncio +import logging +import os +import sys +import time + +import websockets.server as ws_server +from websockets.exceptions import ConnectionClosedError + +log = logging.getLogger(__name__) + +logging.basicConfig( + format="[%(asctime)s] %(message)s", + level=logging.DEBUG, +) + + +async def echo(websocket): + try: + async for message in websocket: + try: + log.info(f'got request {message}') + except Exception as e: + log.error(f'error {e} getting path from {message}') + await websocket.send(message) + except ConnectionClosedError: + pass + + +async def on_async_conn(conn): + rpath = str(conn.path) + pcomps = rpath[1:].split('/') + if len(pcomps) == 0: + pcomps = ['echo'] # default handler + log.info(f'connection for {pcomps}') + if pcomps[0] == 'echo': + log.info(f'/echo endpoint') + for message in await conn.recv(): + await conn.send(message) + elif pcomps[0] == 'text': + await conn.send('hello!') + elif pcomps[0] == 'file': + if len(pcomps) < 2: + conn.close(code=4999, reason='unknown file') + return + fpath = os.path.join('../', pcomps[1]) + if not os.path.exists(fpath): + conn.close(code=4999, reason='file not found') + return + bufsize = 0 + if len(pcomps) > 2: + bufsize = int(pcomps[2]) + if bufsize <= 0: + bufsize = 16*1024 + delay_ms = 0 + if len(pcomps) > 3: + delay_ms = int(pcomps[3]) + n = 1 + if len(pcomps) > 4: + n = int(pcomps[4]) + for _ in range(n): + with open(fpath, 'r+b') as fd: + while True: + buf = fd.read(bufsize) + if buf is None or len(buf) == 0: + break + await conn.send(buf) + if delay_ms > 0: + time.sleep(delay_ms/1000) + else: + log.info(f'unknown endpoint: {rpath}') + await conn.close(code=4999, reason='path unknown') + await conn.close(code=1000, reason='') + + +async def run_server(port): + log.info(f'starting server on port {port}') + async with ws_server.serve(ws_handler=on_async_conn, + host="localhost", port=port): + await asyncio.Future() + + +async def main(): + parser = argparse.ArgumentParser(prog='scorecard', + description="Run a websocket echo server.") + parser.add_argument("--port", type=int, + default=0, help="port to listen on") + args = parser.parse_args() + + if args.port == 0: + sys.stderr.write('need --port\n') + sys.exit(1) + + logging.basicConfig( + format="%(asctime)s %(message)s", + level=logging.DEBUG, + ) + await run_server(args.port) + + +if __name__ == "__main__": + asyncio.run(main()) diff --git a/test/pyhttpd/env.py b/test/pyhttpd/env.py index aacedb7..6f2b285 100644 --- a/test/pyhttpd/env.py +++ b/test/pyhttpd/env.py @@ -312,6 +312,7 @@ def __init__(self, pytestconfig=None): f"test2.{self._http_tld}", f"test3.{self._http_tld}", f"cgi.{self._http_tld}", + "localhost", ], key_type='rsa4096')] self._verify_certs = False diff --git a/test/requirements.txt b/test/requirements.txt index 92e69fe..f6cb4d2 100644 --- a/test/requirements.txt +++ b/test/requirements.txt @@ -19,3 +19,4 @@ filelock python-multipart psutil tqdm +websockets From 661d713207cd2bee435dbb3d8f7752052f55350b Mon Sep 17 00:00:00 2001 From: Alexandr Kitaev Date: Mon, 17 Nov 2025 22:58:47 +0300 Subject: [PATCH 5/7] remove debug logs --- src/tls_filter.c | 39 +-------------------------------------- 1 file changed, 1 insertion(+), 38 deletions(-) diff --git a/src/tls_filter.c b/src/tls_filter.c index b4cdf51..c3c8426 100644 --- a/src/tls_filter.c +++ b/src/tls_filter.c @@ -193,13 +193,7 @@ static apr_status_t read_tls_to_rustls( if (rlen > 0) { rr = rustls_connection_process_new_packets(fctx->cc->rustls_connection); if (rr != RUSTLS_RESULT_OK) { - /* If processing fails, we've already passed some data to rustls. - * This is an error condition. Log the error for debugging. */ - const char *err_descr = ""; - apr_status_t err_rv = tls_core_error(fctx->c, rr, &err_descr); - ap_log_cerror(APLOG_MARK, APLOG_WARNING, err_rv, fctx->c, APLOGNO(10353) - "processing TLS data after passing %ld bytes: [%d] %s", - (long)passed, (int)rr, err_descr); + /* If processing fails, we've already passed some data to rustls. */ goto cleanup; } } @@ -223,12 +217,6 @@ static apr_status_t read_tls_to_rustls( else { rv = APR_ECONNRESET; } - if (!errors_expected) { - const char *err_descr = ""; - apr_status_t map_rv = tls_core_error(fctx->c, rr, &err_descr); - ap_log_cerror(APLOG_MARK, APLOG_WARNING, map_rv, fctx->c, APLOGNO(10353) - "processing TLS data: [%d] %s", (int)rr, err_descr); - } } } else if (APR_STATUS_IS_EOF(rv) && passed > 0) { @@ -756,18 +744,8 @@ static apr_status_t filter_conn_input( else if (APR_STATUS_IS_EAGAIN(rv) || rv == APR_FROM_OS_ERROR(EAGAIN) || rv == APR_EAGAIN) { /* Coerce EAGAIN only for blocking callers; propagate for non-blocking */ if (fctx->fin_block == APR_BLOCK_READ) { - if (APLOGctrace4(fctx->c)) { - ap_log_cerror(APLOG_MARK, APLOG_TRACE4, rv, fctx->c, - "tls_filter_conn_input: coerce EAGAIN->SUCCESS (blocking)"); - } rv = APR_SUCCESS; - ap_log_cerror(APLOG_MARK, APLOG_TRACE4, rv, fctx->c, - "tls_filter_conn_input: no data available"); } else { - if (APLOGctrace4(fctx->c)) { - ap_log_cerror(APLOG_MARK, APLOG_TRACE4, rv, fctx->c, - "tls_filter_conn_input: return EAGAIN (non-blocking, no data)"); - } rv = APR_EAGAIN; } } @@ -788,26 +766,11 @@ static apr_status_t filter_conn_input( /* Final guard: coerce EAGAIN only for blocking callers */ if (APR_STATUS_IS_EAGAIN(rv) || rv == APR_FROM_OS_ERROR(EAGAIN) || rv == APR_EAGAIN) { if (fctx->fin_block == APR_BLOCK_READ) { - if (APLOGctrace4(fctx->c)) { - ap_log_cerror(APLOG_MARK, APLOG_TRACE4, rv, fctx->c, - "tls_filter_conn_input: final coerce EAGAIN->SUCCESS (blocking)"); - } rv = APR_SUCCESS; } else { - if (APLOGctrace4(fctx->c)) { - ap_log_cerror(APLOG_MARK, APLOG_TRACE4, rv, fctx->c, - "tls_filter_conn_input: final return EAGAIN (non-blocking)"); - } rv = APR_EAGAIN; } } - if (APLOGctrace1(fctx->c)) { - int wants_r = fctx->cc->rustls_connection ? rustls_connection_wants_read(fctx->cc->rustls_connection) : 0; - int wants_w = fctx->cc->rustls_connection ? rustls_connection_wants_write(fctx->cc->rustls_connection) : 0; - ap_log_cerror(APLOG_MARK, APLOG_TRACE1, rv, fctx->c, - "tls_filter_conn_input: return rv=%d rr=%d mode=%d block=%d passed=%ld wants_read=%d wants_write=%d fin_bytes_in_rustls=%ld", - (int)rv, (int)rr, (int)mode, (int)block, (long)passed, wants_r, wants_w, (long)fctx->fin_bytes_in_rustls); - } return rv; } From ca212245377773cd6b683cad0958f641f1a4cbfb Mon Sep 17 00:00:00 2001 From: Stefan Eissing Date: Tue, 18 Nov 2025 13:19:06 +0100 Subject: [PATCH 6/7] Tests with wss: backend (#12) * add wss test cases for accessing a wss: server via httpd * would like to extend that to https: but pyhtons websocket client is flaky in CI test_tls_18_04 reproduces the problem with handling pending plain data in rustls. Disabled here, awaiting a fix like in #9. --- test/modules/tls/env.py | 1 + test/modules/tls/test_09_timeout.py | 3 +- test/modules/tls/test_18_ws.py | 201 +++++++++++++++++++--------- test/modules/tls/ws_server.py | 17 ++- test/pyhttpd/config.ini.in | 1 + test/pyhttpd/env.py | 5 + 6 files changed, 158 insertions(+), 70 deletions(-) diff --git a/test/modules/tls/env.py b/test/modules/tls/env.py index 8399d52..a05f73f 100644 --- a/test/modules/tls/env.py +++ b/test/modules/tls/env.py @@ -112,6 +112,7 @@ def __init__(self, pytestconfig=None): CertificateSpec(domains=[self.domain_a]), CertificateSpec(domains=[self.domain_b], key_type='secp256r1', single_file=True), CertificateSpec(domains=[self.domain_b], key_type='rsa4096'), + CertificateSpec(domains=['localhost'], key_type='rsa4096'), CertificateSpec(name="clientsX", sub_specs=[ CertificateSpec(name="user1", client=True, single_file=True), CertificateSpec(name="user2", client=True, single_file=True), diff --git a/test/modules/tls/test_09_timeout.py b/test/modules/tls/test_09_timeout.py index 70cc894..6c49192 100644 --- a/test/modules/tls/test_09_timeout.py +++ b/test/modules/tls/test_09_timeout.py @@ -24,7 +24,8 @@ def _function_scope(self, env): def test_tls_09_timeout_handshake(self, env): # in domain_b root, the StdEnvVars is switch on s = socket.create_connection(('localhost', env.https_port)) - s.send(b'1234') + # something that looks like a ClientHello + s.send(bytes.fromhex('3c37121e')) s.settimeout(0.0) try: s.recv(1024) diff --git a/test/modules/tls/test_18_ws.py b/test/modules/tls/test_18_ws.py index 5ef90e8..16636e9 100644 --- a/test/modules/tls/test_18_ws.py +++ b/test/modules/tls/test_18_ws.py @@ -13,17 +13,81 @@ from .conf import TlsTestConf -def mk_text_file(fpath: str, lines: int): - t110 = 11 * "0123456789" - with open(fpath, "w") as fd: - for i in range(lines): - fd.write("{0:015d}: ".format(i)) # total 128 bytes per line - fd.write(t110) - fd.write("\n") +class WsServer: + + def __init__(self, name, env, port, creds=None): + self.name = name + self.env = env + self.process = None + self.cerr = None + self.port = port + self.creds = creds + self.run_dir = os.path.join(env.gen_dir, self.name) + self.err_file = os.path.join(self.run_dir, 'stderr') + self._rmrf(self.run_dir) + self._mkpath(self.run_dir) + + def start(self): + if not self.process: + self.cerr = open(self.err_file, 'w') + cmd = os.path.join(os.path.dirname(inspect.getfile(TestWebSockets)), + 'ws_server.py') + args = ['python3', cmd, '--port', str(self.port)] + if self.creds: + args.extend([ + '--cert', self.creds[0].cert_file, + '--key', self.creds[0].pkey_file, + ]) + self.process = subprocess.Popen(args=args, cwd=self.run_dir, + stderr=self.cerr, stdout=self.cerr) + if not self.check_alive(): + self.stop() + pytest.fail(f'ws_server did not start. stderr={open(self.err_file).readlines()}') + + def stop(self): + if self.process: + self.process.kill() + self.process.wait() + self.process = None + if self.cerr: + self.cerr.close() + self.cerr = None + + def check_alive(self, timeout=5): + if self.creds: + url = f'https://localhost:{self.port}/' + else: + url = f'http://localhost:{self.port}/' + end = datetime.now() + timedelta(seconds=timeout) + while datetime.now() < end: + r = self.env.curl_get(url, 5) + if r.exit_code == 0: + return True + time.sleep(.1) + return False + + def _mkpath(self, path): + if not os.path.exists(path): + return os.makedirs(path) + + def _rmrf(self, path): + if os.path.exists(path): + return shutil.rmtree(path) + class TestWebSockets: + @staticmethod + def mk_text_file(fpath: str, lines: int): + t110 = 11 * "0123456789" + with open(fpath, "w") as fd: + for i in range(lines): + fd.write("{0:015d}: ".format(i)) # total 128 bytes per line + fd.write(t110) + fd.write("\n") + + @pytest.fixture(autouse=True, scope='class') def _class_scope(self, env): # Apache config that CONNECT proxies a WebSocket server for paths starting @@ -32,44 +96,52 @@ def _class_scope(self, env): conf = TlsTestConf(env, extras={ 'base': [ 'Timeout 1', + f'', + ' TLSProxyEngine on', + f' TLSProxyCA {env.ca.cert_file}', + ' ProxyPreserveHost on', + '', ], 'localhost': [ f'ProxyPass /ws/ http://127.0.0.1:{env.ws_port}/ upgrade=websocket \\', f'timeout=2 flushpackets=on', + f'ProxyPass /wss/ https://localhost:{env.wss_port}/ upgrade=websocket \\', + f'timeout=2 flushpackets=on', ], - f'cgi.{env.http_tld}': [ - f' ProxyPass /ws/ http://127.0.0.1:{env.ws_port}/ \\', - f' upgrade=websocket timeout=2 flushpackets=on', - f' ReadBufferSize 65535' - ] }) conf.add_vhost('localhost', port=env.http_port) conf.add_tls_vhosts(['localhost'], port=env.https_port) conf.install() - mk_text_file(os.path.join(env.gen_dir, "1k.txt"), 8) - mk_text_file(os.path.join(env.gen_dir, "10k.txt"), 80) - mk_text_file(os.path.join(env.gen_dir, "100k.txt"), 800) - mk_text_file(os.path.join(env.gen_dir, "1m.txt"), 8000) - mk_text_file(os.path.join(env.gen_dir, "10m.txt"), 80000) + TestWebSockets.mk_text_file(os.path.join(env.gen_dir, "1k.txt"), 8) + TestWebSockets.mk_text_file(os.path.join(env.gen_dir, "10k.txt"), 80) + TestWebSockets.mk_text_file(os.path.join(env.gen_dir, "100k.txt"), 800) + TestWebSockets.mk_text_file(os.path.join(env.gen_dir, "1m.txt"), 8000) assert env.apache_restart() == 0 - def ws_check_alive(self, env, timeout=5): - url = f'http://localhost:{env.ws_port}/' - end = datetime.now() + timedelta(seconds=timeout) - while datetime.now() < end: - r = env.curl_get(url, 5) - if r.exit_code == 0: - return True - time.sleep(.1) - return False - - def _mkpath(self, path): - if not os.path.exists(path): - return os.makedirs(path) + @pytest.fixture(autouse=True, scope='class') + def ws_server(self, env): + # Run our python websockets server that has some special behaviour + # for the different path to CONNECT to. + ws_server = WsServer('ws-server', env, port=env.ws_port) + ws_server.start() + yield ws_server + ws_server.stop() - def _rmrf(self, path): - if os.path.exists(path): - return shutil.rmtree(path) + @pytest.fixture(autouse=True, scope='class') + def wss_server(self, env): + # Run our python websockets server that has some special behaviour + # for the different path to CONNECT to. + creds = env.get_credentials_for_name('localhost') + assert creds + ws_server = WsServer('wss-server', env, port=env.wss_port, creds=creds) + ws_server.start() + yield ws_server + ws_server.stop() + + def ssl_ctx(self, env): + ssl_ctx = ssl.SSLContext(protocol=ssl.PROTOCOL_TLS_CLIENT) + ssl_ctx.load_verify_locations(cafile=env.ca.cert_file) + return ssl_ctx def ws_recv_text(self, ws): msg = "" @@ -87,55 +159,54 @@ def ws_recv_bytes(self, ws): except websockets.exceptions.ConnectionClosedOK: return msg - @pytest.fixture(autouse=True, scope='class') - def ws_server(self, env): - # Run our python websockets server that has some special behaviour - # for the different path to CONNECT to. - run_dir = os.path.join(env.gen_dir, 'ws-server') - err_file = os.path.join(run_dir, 'stderr') - self._rmrf(run_dir) - self._mkpath(run_dir) - with open(err_file, 'w') as cerr: - cmd = os.path.join(os.path.dirname(inspect.getfile(TestWebSockets)), - 'ws_server.py') - args = ['python3', cmd, '--port', str(env.ws_port)] - p = subprocess.Popen(args=args, cwd=run_dir, stderr=cerr, - stdout=cerr) - if not self.ws_check_alive(env): - p.kill() - p.wait() - pytest.fail(f'ws_server did not start. stderr={open(err_file).readlines()}') - yield - p.terminate() - - def test_tls_18_01_direct(self, env): + # verify the our plain websocket server works + def test_tls_18_01_ws_direct(self, env, ws_server): with connect(f"ws://127.0.0.1:{env.ws_port}/echo") as ws: message = "Hello world!" ws.send(message) response = self.ws_recv_text(ws) assert response == message - def test_tls_18_02_httpd_plain(self, env): + # verify that our secure websocket server works + def test_tls_18_02_wss_direct(self, env, wss_server): + pytest.skip(reason='For unknown reasons, this is flaky in CI') + with connect(f"wss://localhost:{env.wss_port}/echo", + ssl_context=self.ssl_ctx(env)) as ws: + message = "Hello world!" + ws.send(message) + response = self.ws_recv_text(ws) + assert response == message + + # verify to send plain websocket message pingpong through apache + def test_tls_18_03_http_ws(self, env, ws_server): with connect(f"ws://localhost:{env.http_port}/ws/echo/") as ws: message = "Hello world!" ws.send(message) response = self.ws_recv_text(ws) assert response == message - @pytest.mark.parametrize("fname", ["1k.txt", "10k.txt", "100k.txt", "1m.txt", "10m.txt"]) - def test_tls_18_03_file(self, env, fname): + # verify to send secure websocket message pingpong through apache + def test_tls_18_04_http_wss(self, env, wss_server): + pytest.skip(reason='This fails, needing a fix like PR #9') + with connect(f"ws://localhost:{env.http_port}/wss/echo/") as ws: + message = "Hello world!" + ws.send(message) + response = self.ws_recv_text(ws) + assert response == message + + # verify that getting a large file works without any TLS involved + @pytest.mark.parametrize("fname", ["1m.txt"]) + def test_tls_18_05_http_ws_file(self, env, fname, ws_server): expected = open(os.path.join(env.gen_dir, fname), 'rb').read() with connect(f"ws://localhost:{env.http_port}/ws/file/{fname}") as ws: response = self.ws_recv_bytes(ws) assert response == expected - @pytest.mark.parametrize("fname", ["1k.txt", "10k.txt", "100k.txt", "1m.txt", "10m.txt"]) - def test_tls_18_04_tls_file(self, env, fname): + # verify getting secure websocket from the http: server + # this is "backend" mod_tls work + @pytest.mark.parametrize("fname", ["1k.txt", "10k.txt", "100k.txt", "1m.txt"]) + def test_tls_18_06_http_wss_file(self, env, fname, ws_server): expected = open(os.path.join(env.gen_dir, fname), 'rb').read() - ssl_ctx = ssl.SSLContext(protocol=ssl.PROTOCOL_TLS_CLIENT) - ssl_ctx.check_hostname = False - ssl_ctx.verify_mode = ssl.VerifyMode.CERT_NONE - with connect(f"wss://localhost:{env.https_port}/ws/file/{fname}", - ssl_context=ssl_ctx) as ws: + with connect(f"ws://localhost:{env.http_port}/wss/file/{fname}") as ws: response = self.ws_recv_bytes(ws) assert response == expected diff --git a/test/modules/tls/ws_server.py b/test/modules/tls/ws_server.py index 99fb9cf..8c2760c 100755 --- a/test/modules/tls/ws_server.py +++ b/test/modules/tls/ws_server.py @@ -3,6 +3,7 @@ import asyncio import logging import os +import ssl import sys import time @@ -75,10 +76,14 @@ async def on_async_conn(conn): await conn.close(code=1000, reason='') -async def run_server(port): - log.info(f'starting server on port {port}') +async def run_server(port, cert, pkey): + log.info(f'starting server on port {port}, cert {cert}, key {pkey}') + ssl_ctx = None + if cert and pkey: + ssl_ctx = ssl.SSLContext(protocol=ssl.PROTOCOL_TLS_SERVER) + ssl_ctx.load_cert_chain(certfile=cert, keyfile=pkey) async with ws_server.serve(ws_handler=on_async_conn, - host="localhost", port=port): + host="localhost", port=port, ssl=ssl_ctx): await asyncio.Future() @@ -87,6 +92,10 @@ async def main(): description="Run a websocket echo server.") parser.add_argument("--port", type=int, default=0, help="port to listen on") + parser.add_argument("--cert", type=str, + default=None, help="TLS certificate") + parser.add_argument("--key", type=str, + default=None, help="TLS private key") args = parser.parse_args() if args.port == 0: @@ -97,7 +106,7 @@ async def main(): format="%(asctime)s %(message)s", level=logging.DEBUG, ) - await run_server(args.port) + await run_server(args.port, args.cert, args.key) if __name__ == "__main__": diff --git a/test/pyhttpd/config.ini.in b/test/pyhttpd/config.ini.in index 85c0cfa..582ce45 100644 --- a/test/pyhttpd/config.ini.in +++ b/test/pyhttpd/config.ini.in @@ -29,6 +29,7 @@ https_port = 5001 proxy_port = 5003 http_port2 = 5004 ws_port = 5100 +wss_port = 5101 http_tld = tests.httpd.apache.org test_dir = @abs_srcdir@ test_src_dir = @abs_srcdir@ diff --git a/test/pyhttpd/env.py b/test/pyhttpd/env.py index 6f2b285..be20516 100644 --- a/test/pyhttpd/env.py +++ b/test/pyhttpd/env.py @@ -275,6 +275,7 @@ def __init__(self, pytestconfig=None): self._https_port = int(self.config.get('test', 'https_port')) self._proxy_port = int(self.config.get('test', 'proxy_port')) self._ws_port = int(self.config.get('test', 'ws_port')) + self._wss_port = int(self.config.get('test', 'wss_port')) self._http_tld = self.config.get('test', 'http_tld') self._test_dir = self.config.get('test', 'test_dir') self._clients_dir = os.path.join(os.path.dirname(self._test_dir), 'clients') @@ -404,6 +405,10 @@ def proxy_port(self) -> int: def ws_port(self) -> int: return self._ws_port + @property + def wss_port(self) -> int: + return self._wss_port + @property def http_tld(self) -> str: return self._http_tld From 55501db7848b3b4ddbf177d53dbaf219f829c85c Mon Sep 17 00:00:00 2001 From: Alexandr Kitaev Date: Tue, 18 Nov 2025 15:46:08 +0300 Subject: [PATCH 7/7] remove unused variables --- src/tls_filter.c | 16 ++++------------ 1 file changed, 4 insertions(+), 12 deletions(-) diff --git a/src/tls_filter.c b/src/tls_filter.c index c3c8426..ad433fd 100644 --- a/src/tls_filter.c +++ b/src/tls_filter.c @@ -62,7 +62,7 @@ static rustls_io_result tls_read_callback( * function to handle the added data before leaving. */ static apr_status_t read_tls_to_rustls( - tls_filter_ctx_t *fctx, apr_size_t len, apr_read_type_e block, int errors_expected) + tls_filter_ctx_t* fctx, apr_size_t len, apr_read_type_e block) { apr_read_type_e caller_block = block; /* preserve caller's blocking mode */ tls_data_t d; @@ -313,7 +313,7 @@ static apr_status_t filter_recv_client_hello(tls_filter_ctx_t *fctx) fctx->fin_tls_buffer_bb = apr_brigade_create(fctx->c->pool, fctx->c->bucket_alloc); do { if (rustls_connection_wants_read(fctx->cc->rustls_connection)) { - rv = read_tls_to_rustls(fctx, fctx->fin_max_in_rustls, APR_BLOCK_READ, 1); + rv = read_tls_to_rustls(fctx, fctx->fin_max_in_rustls, APR_BLOCK_READ); if (APR_SUCCESS != rv) { if (fctx->cc->client_hello_seen) { /* We got what we needed - client hello was seen. @@ -389,7 +389,7 @@ static apr_status_t filter_do_handshake( if (APR_SUCCESS != rv) goto cleanup; } else if (rustls_connection_wants_read(fctx->cc->rustls_connection)) { - rv = read_tls_to_rustls(fctx, fctx->fin_max_in_rustls, APR_BLOCK_READ, 0); + rv = read_tls_to_rustls(fctx, fctx->fin_max_in_rustls, APR_BLOCK_READ); if (APR_SUCCESS != rv) goto cleanup; } } @@ -583,7 +583,6 @@ static apr_status_t filter_conn_input( if (should_read_tls) { apr_size_t read_limit; - int force_read_flag; apr_off_t bytes_in_rustls_before; /* Avoid blocking brigade length checks; they may stall the input filter */ @@ -600,18 +599,11 @@ static apr_status_t filter_conn_input( read_limit = fctx->fin_max_in_rustls; } } - /* Use force_read if wants_read is false but we're in blocking mode. - * This allows us to read from network even when rustls says it doesn't - * want more data, which is necessary to avoid infinite loops when - * plaintext hasn't appeared yet. */ - force_read_flag = (block == APR_BLOCK_READ && - !rustls_connection_wants_read(fctx->cc->rustls_connection) && - (!APR_BRIGADE_EMPTY(fctx->fin_tls_bb) || fctx->fin_bytes_in_rustls > 0)) ? 1 : 0; /* Track how much data we had in rustls before reading */ bytes_in_rustls_before = fctx->fin_bytes_in_rustls; /* Do not call apr_brigade_length() here to avoid blocking */ - rv = read_tls_to_rustls(fctx, read_limit, block, force_read_flag); + rv = read_tls_to_rustls(fctx, read_limit, block); tls_read_attempted = 1; if (APR_SUCCESS != rv) { if (APR_STATUS_IS_EAGAIN(rv)) {