diff --git a/scripts/run_cli_tests.sh b/scripts/run_cli_tests.sh index 56a27ca..3d2db5d 100755 --- a/scripts/run_cli_tests.sh +++ b/scripts/run_cli_tests.sh @@ -74,5 +74,6 @@ if [[ "$action" == "run" ]]; then scripts/test_mysql_epoch_refresh.sh scripts/test_mysql_persistent_pool.sh scripts/test_log_timeliness.sh + scripts/test_raw_http_request_log.sh scripts/test_socket_activation.sh fi diff --git a/scripts/test_raw_http_request_log.sh b/scripts/test_raw_http_request_log.sh new file mode 100755 index 0000000..64d9372 --- /dev/null +++ b/scripts/test_raw_http_request_log.sh @@ -0,0 +1,59 @@ +#!/usr/bin/env bash +set -euo pipefail +cd "$(dirname "$0")/.." + +http_port="${UCE_RAW_HTTP_TEST_PORT:-}" +if [[ -z "$http_port" && -r /etc/uce/settings.cfg ]]; then + http_port=$(awk -F= '/^[[:space:]]*HTTP_PORT[[:space:]]*=/ {gsub(/^[[:space:]]+|[[:space:]]+$/, "", $2); print $2; exit}' /etc/uce/settings.cfg) +fi +http_port="${http_port:-8080}" +request_path="${UCE_RAW_HTTP_TEST_PATH:-/info/index.uce}" +marker="raw-http-log-$$-$(date +%s%N)" +separator="?" +if [[ "$request_path" == *\?* ]]; then + separator="&" +fi +started_at=$(date '+%Y-%m-%d %H:%M:%S') + +response=$(curl -fsS --max-time 15 "http://127.0.0.1:${http_port}${request_path}${separator}__uce_log_probe=${marker}") +if [[ -z "$response" ]]; then + echo "raw HTTP probe returned an empty response" >&2 + exit 1 +fi + +request_logs="" +for _ in $(seq 1 30); do + request_logs=$(journalctl -u uce --since "$started_at" --no-pager | grep '(r)' | grep "$marker" || true) + if [[ $(printf '%s\n' "$request_logs" | grep -c '(r)' || true) -ge 2 ]]; then + break + fi + sleep 0.1 +done + +if [[ $(printf '%s\n' "$request_logs" | grep -c '(r)' || true) -ne 2 ]]; then + echo "expected exactly two raw HTTP request-stage records" >&2 + printf '%s\n' "$request_logs" >&2 + exit 1 +fi +if [[ $(printf '%s\n' "$request_logs" | grep -c 'transport:http' || true) -ne 1 || + $(printf '%s\n' "$request_logs" | grep -c 'transport:fastcgi' || true) -ne 1 ]]; then + echo "raw HTTP request-stage records did not identify HTTP and FastCGI transports" >&2 + printf '%s\n' "$request_logs" >&2 + exit 1 +fi + +mapfile -t durations < <(printf '%s\n' "$request_logs" | sed -n 's/.*[[:space:]]\([0-9][0-9.]*\)s[[:space:]]*fps:.*/\1/p') +if [[ ${#durations[@]} -ne 2 ]]; then + echo "could not parse both raw HTTP request-stage durations" >&2 + printf '%s\n' "$request_logs" >&2 + exit 1 +fi +for duration in "${durations[@]}"; do + awk -v duration="$duration" 'BEGIN { exit !(duration > 0 && duration < 60) }' || { + echo "raw HTTP request-stage duration is outside (0, 60) seconds: ${duration}s" >&2 + printf '%s\n' "$request_logs" >&2 + exit 1 + } +done + +echo "raw HTTP request log passed" diff --git a/src/fastcgi/src/fcgicc.cc b/src/fastcgi/src/fcgicc.cc index 045fcec..fa89688 100644 --- a/src/fastcgi/src/fcgicc.cc +++ b/src/fastcgi/src/fcgicc.cc @@ -858,6 +858,8 @@ FastCGIServer::process_http_request(FastCGIRequest& request, String& data) } else { + if(request.stats.time_start == 0) + request.stats.time_start = time_precise(); on_complete(request); assemble_output_buffer( @@ -1332,10 +1334,13 @@ FastCGIServer::assemble_output_buffer(FastCGIRequest& request, Connection* conne request.stats.time_end = time_precise(); if(request.flags.log_request) { + const char* transport = !connection ? "fastcgi" : + connection->type == 'H' ? "http" : + connection->type == 'C' ? "cli" : "unknown"; auto elapsed_us = [&](f64 from, f64 to) -> f64 { return(from > 0 && to >= from ? (to - from) * 1000000.0 : 0.0); }; - printf("(r) pid:%i\t%s\t%0.6fs\tfps:%0.0f\tout:%0.1fkB\tmem:%0.0f/%0.0fkB\twasm-ready:%0.3fms\twasm:%0.3fms\tworkspace:%0.3fms\tinvoke:%0.3fms\tcollect:%0.3fms\tpost:%0.3fms\n", + printf("(r) pid:%i\t%s\t%0.6fs\tfps:%0.0f\tout:%0.1fkB\tmem:%0.0f/%0.0fkB\twasm-ready:%0.3fms\twasm:%0.3fms\tworkspace:%0.3fms\tinvoke:%0.3fms\tcollect:%0.3fms\tpost:%0.3fms\ttransport:%s\n", my_pid, request.params["REQUEST_URI"].c_str(), request.stats.time_end - request.stats.time_start, @@ -1348,7 +1353,8 @@ FastCGIServer::assemble_output_buffer(FastCGIRequest& request, Connection* conne (f64)request.stats.wasm_workspace_complete_us / 1000.0, (f64)request.stats.wasm_entry_invoke_us / 1000.0, (f64)request.stats.wasm_output_collect_us / 1000.0, - elapsed_us(request.stats.wasm_backend_finished, request.stats.time_end) / 1000.0 + elapsed_us(request.stats.wasm_backend_finished, request.stats.time_end) / 1000.0, + transport ); }