Fix raw HTTP request timing logs

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

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"

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
 		);
 	}