RA-7777: Implement logging of timing events in the trillian ctfe

[himaschal]

Changes made:

This PR implements comprehensive request tracing infrastructure for the Certificate Transparency Frontend (CTFE), enabling end-to-end tracking of HTTP requests through to backend Trillian gRPC calls with structured logging and correlation IDs. It is supported by the changes made in this PR digicert/trillian#1

• Added request tracing - with a focus on timing - to Trillian ctfe which allows for structured logging of a request at the http entry point.
• Added structured logging package with transaction and span ID tracking
• HTTP middleware for automatic request timing and context injection
• JSON logging format
• Added / updated tests
• The transaction_id, span_id allows for correlation tracing across services.
• The logging is handled by the logrus library - which is useful for structured output.

Testing:

Prerequisite: I was testing in the local k8s cluster so need to port forward to the pods.

1. Basic Service Health Check

Expectation: We should get results. This is a sanity check to make sure nothing has broken.

Request

/Users/himaschalpursan/work/2025/RA-7777 % curl -s http://localhost:6962/log/ct/v1/get-sth
{"tree_size":0,"timestamp":1753192080766,"sha256_root_hash":"47DEQpj8HBSa+/TImW+5JCeuQeRkm5NMpJWZG3hSuFU=","tree_head_signature":"BAMARjBEAiAk7ly627LVs+DkaI66j9YLP/enuosqemGx0agjrIhm7wIgJOp+P3LyiuJ9n83hkrdbIhprgZbJgl5Ot8kRKvbXqQE="}%

Logs

Trillian: 

{"elapsed":1,"event_id":"timing","level":"info","method":"/trillian.TrillianLog/GetLatestSignedLogRoot","msg":"gRPC call completed","span_id":"3155a8c5-d6eb-4892-95be-77a2badb9349","status":"OK","time":"2025-07-22T18:06:24.273Z","transaction_id":"ef627dd7-7205-488e-b0ee-96691fd5931f"}

CTFE:

{"elapsed":"4ms","event_id":"timing","level":"info","method":"GET","msg":"request completed","path":"/log/ct/v1/get-sth","span_id":"25cc8763-3b3a-4bb5-be7a-f9d09d16b76f","status":200,"time":"2025-07-22T18:06:24.274Z","transaction_id":"ef627dd7-7205-488e-b0ee-96691fd5931f"}

---

2. Request with Custom Transaction ID

Expectation:

• we should see the same specified transaction_id present in the CTFE and Trillian logs - each will have uniquely generate span-id's

Request

curl -s -X GET "http://localhost:6962/log/ct/v1/get-sth" -H "X-Transaction-ID:demo-test-2" -H "Content-Type: application/json" --max-time 10
{"tree_size":0,"timestamp":1753192080766,"sha256_root_hash":"47DEQpj8HBSa+/TImW+5JCeuQeRkm5NMpJWZG3hSuFU=","tree_head_signature":"BAMARjBEAiAk7ly627LVs+DkaI66j9YLP/enuosqemGx0agjrIhm7wIgJOp+P3LyiuJ9n83hkrdbIhprgZbJgl5Ot8kRKvbXqQE="}%

Logs

Trillian: 
{"elapsed":0,"event_id":"timing","level":"info","method":"/trillian.TrillianLog/GetLatestSignedLogRoot","msg":"gRPC call completed","span_id":"a2470478-823b-418c-a519-8f4608582840","status":"OK","time":"2025-07-22T18:07:36.591Z","transaction_id":"demo-test-2"}


CTFE: 
{"elapsed":"3ms","event_id":"timing","level":"info","method":"GET","msg":"request completed","path":"/log/ct/v1/get-sth","span_id":"cd1261d0-04e1-4d09-8493-997a3d804dd9","status":200,"time":"2025-07-22T18:07:36.592Z","transaction_id":"demo-test-2"}

---

Test 3: Multiple Requests for Timing Analysis

Expectation:

• we should see the same specified transaction_id present in the CTFE and Trillian logs - each will have uniquely generate span-id's

Requests

/Users/himaschalpursan/workspace/trillian [RA-7777]% curl -s -X GET "http://localhost:6962/log/ct/v1/get-sth" -H "X-Transaction-ID:demo-test-3-1" -H "Content-Type: application/json" --max-time 10

{"tree_size":0,"timestamp":1753192080766,"sha256_root_hash":"47DEQpj8HBSa+/TImW+5JCeuQeRkm5NMpJWZG3hSuFU=","tree_head_signature":"BAMARjBEAiAk7ly627LVs+DkaI66j9YLP/enuosqemGx0agjrIhm7wIgJOp+P3LyiuJ9n83hkrdbIhprgZbJgl5Ot8kRKvbXqQE="}%

/Users/himaschalpursan/workspace/trillian [RA-7777]%  curl -s -X GET "http://localhost:6962/log/ct/v1/get-sth" -H "X-Transaction-ID:demo-test-3-2" -H "Content-Type: application/json" --max-time 10

{"tree_size":0,"timestamp":1753192080766,"sha256_root_hash":"47DEQpj8HBSa+/TImW+5JCeuQeRkm5NMpJWZG3hSuFU=","tree_head_signature":"BAMARjBEAiAk7ly627LVs+DkaI66j9YLP/enuosqemGx0agjrIhm7wIgJOp+P3LyiuJ9n83hkrdbIhprgZbJgl5Ot8kRKvbXqQE="}%

/Users/himaschalpursan/workspace/trillian [RA-7777]% curl -s -X GET "http://localhost:6962/log/ct/v1/get-sth" -H "X-Transaction-ID:demo-test-3-3" -H "Content-Type: application/json" --max-time 10

{"tree_size":0,"timestamp":1753192080766,"sha256_root_hash":"47DEQpj8HBSa+/TImW+5JCeuQeRkm5NMpJWZG3hSuFU=","tree_head_signature":"BAMARjBEAiAk7ly627LVs+DkaI66j9YLP/enuosqemGx0agjrIhm7wIgJOp+P3LyiuJ9n83hkrdbIhprgZbJgl5Ot8kRKvbXqQE="}%

Logs

Trillian: 

{"elapsed":0,"event_id":"timing","level":"info","method":"/trillian.TrillianLog/GetLatestSignedLogRoot","msg":"gRPC call completed","span_id":"e96998b1-7b1e-43a2-98d8-353b08f61ee8","status":"OK","time":"2025-07-22T18:08:38.775Z","transaction_id":"demo-test-3-1"}

CTFE:

 {"elapsed":"2ms","event_id":"timing","level":"info","method":"GET","msg":"request completed","path":"/log/ct/v1/get-sth","span_id":"a826e766-bf12-431f-8a33-f07bfea46b58","status":200,"time":"2025-07-22T18:08:38.775Z","transaction_id":"demo-test-3-1"}

Handling connection for 6962

Trillian: 

{"elapsed":0,"event_id":"timing","level":"info","method":"/trillian.TrillianLog/GetLatestSignedLogRoot","msg":"gRPC call completed","span_id":"23a26af7-58bd-42f0-ab90-681bbaebf59e","status":"OK","time":"2025-07-22T18:08:49.018Z","transaction_id":"demo-test-3-2"}

CTFE: 

{"elapsed":"2ms","event_id":"timing","level":"info","method":"GET","msg":"request completed","path":"/log/ct/v1/get-sth","span_id":"a18c3a04-8818-4913-9073-e0e4bca64591","status":200,"time":"2025-07-22T18:08:49.019Z","transaction_id":"demo-test-3-2"}

Handling connection for 6962

CTFE: 

{"elapsed":"3ms","event_id":"timing","level":"info","method":"GET","msg":"request completed","path":"/log/ct/v1/get-sth","span_id":"200b6912-d3bb-43e8-b254-e1e394234fed","status":200,"time":"2025-07-22T18:08:55.723Z","transaction_id":"demo-test-3-3"}

Trillian: 

{"elapsed":1,"event_id":"timing","level":"info","method":"/trillian.TrillianLog/GetLatestSignedLogRoot","msg":"gRPC call completed","span_id":"41bec245-b2ba-4fd8-b13a-0b28ce1cf139","status":"OK","time":"2025-07-22T18:08:55.723Z","transaction_id":"demo-test-3-3"}

[himaschal]

Killing this PR as #2 supersedes these changes