Skip to content

Commit 2f9d58c

Browse files
committed
feat: per-request log gating (logLevel opt-in) + POST-SSE notification ordering fix
2026-07-28 RequestMetaObject.logLevel: 'If absent, the server MUST NOT send any notifications/message notifications for this request.' - tools/call handler surfaces the request's declared logLevel to the session context; SessionContext::notify_log gates emission on it — no declaration means no notifications/message, and the declared level is the severity threshold (replaces the removed logging/setLevel session threshold, which remains the filter on the 2025 lane via cfg). - Fixes a pre-existing POST-SSE ordering race affecting BOTH lanes: the final response frame was sent before the progress-task shutdown handshake, and the shutdown branch dropped queued events — request-scoped notifications emitted (and awaited) just before tool completion could be silently lost or arrive after the final frame. The progress task now flushes queued events on shutdown, and the main task sends the final frame only after the flush handshake, so notifications precede the final response and the response terminates the stream. Tests: log_gating_2026.rs — 2 real-HTTP SSE cases (suppressed without logLevel; delivered with 'info'; info filtered below an 'error' threshold). Revert-and-fail: the opt-in delivery case fails against the pre-fix ordering (notification dropped at shutdown) — recorded. 2025 lane verified via the consolidated e2e_tests suite (30 passed, incl. streamable_http_e2e). CI: log_gating_2026 gate in ci.yml + ci-gates.sh.
1 parent ebd7f15 commit 2f9d58c

7 files changed

Lines changed: 237 additions & 13 deletions

File tree

.github/workflows/ci.yml

Lines changed: 2 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -53,6 +53,8 @@ jobs:
5353
run: cargo test -p turul-mcp-server --no-default-features --features http,sse,protocol-2026-07-28 --test mrtr_2026
5454
- name: 2026 Mcp-Param-* mirroring (x-mcp-header validation)
5555
run: cargo test -p turul-mcp-server --no-default-features --features http,sse,protocol-2026-07-28 --test mcp_param_2026
56+
- name: 2026 per-request log gating (logLevel opt-in)
57+
run: cargo test -p turul-mcp-server --no-default-features --features http,sse,protocol-2026-07-28 --test log_gating_2026
5658
- name: protocol-2026 compliance + upstream wire fixtures
5759
run: cargo test -p turul-mcp-protocol-2026-07-28 --features compliance
5860
- name: Bilingual client (not in default-members)

CHANGELOG.md

Lines changed: 1 addition & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -44,6 +44,7 @@ and this project adheres to [Semantic Versioning](https://semver.org/spec/v2.0.0
4444

4545
### Added (2026-06-10)
4646

47+
- **Per-request log gating (2026-07-28).** `notifications/message` is now opt-in per request: a `tools/call` whose `_meta` lacks `io.modelcontextprotocol/logLevel` gets NO message notifications (spec MUST), and the declared level is the severity threshold (replaces the removed `logging/setLevel` session threshold, which remains the filter on the 2025 lane). The tools/call handler surfaces the declared level to the session context; `notify_log` gates emission. **Also fixes a pre-existing POST-SSE ordering race**: the final response frame could beat (and the shutdown path silently DROP) request-scoped notifications already queued on the progress channel — the progress task now flushes queued events on shutdown and the final frame is sent only after the flush handshake, so notifications precede the final response on the wire. Tests: `log_gating_2026.rs` (real-HTTP SSE: suppressed without `logLevel`, delivered with `"info"`, filtered below an `"error"` threshold; the opt-in case failed against the pre-fix ordering — revert-and-fail evidence), wired into the default CI lane.
4748
- **SEP-2243 `Mcp-Param-*` custom-header mirroring (client emission + server validation).** Completes the deferred remainder of the request-metadata headers work. Protocol crate: pure SEP-2243 logic in `headers.rs` — `scan_x_mcp_headers()` (annotation discovery at any nesting depth with the full constraint set: non-empty, `tchar` syntax, case-insensitive uniqueness, string/integer/boolean only), `encode_param_value()` / `decode_param_value()` (string/integer/boolean conversion, JS safe-integer range, `=?base64?…?=` sentinel incl. the self-matching-sentinel re-encode rule; unit tests reproduce all five spec encoding examples). Server: the tools/call handler validates every annotated parameter's mirrored header against the body argument (sentinel-decoded; integers compared numerically) — value-without-header, header-without-value, or decoded mismatch → `-32001 HeaderMismatch` at HTTP 400 (the transport surfaces request headers to handlers via the rpc session metadata; the inline 2026 JSON path now maps `-32001` to 400 alongside `-32003`). Client: `tools/list` rejects tool definitions with invalid `x-mcp-header` values (excluded + warning, per spec) and captures per-tool bindings BEFORE the 2025-vocabulary remap (which cannot carry the annotation); `tools/call` mirrors annotated arguments into `Mcp-Param-{name}` headers via a new `Transport::send_request_with_extra_headers` (default delegates to `send_request` — non-HTTP transports MAY ignore the annotations). Tests: `mcp_param_2026.rs` (4 real-HTTP server cases; revert-and-fail recorded — both negative cases fail with validation disabled) and a closed-loop client e2e (the validating server rejects missing mirrors, so the green client call proves emission; covers plain ASCII and Base64-sentinel values). Not implemented (acceptable per spec): the client's optional schema-stale auto-retry (`tools/list` + retry on rejection is left to the application).
4849
- **Schema pin re-vendored (content sha256 `1bf94a60…`, fixture pin `1304c8fe`).** One substantive upstream change: `ElicitationCompleteNotificationParams` extracted into a named interface extending `NotificationParams` (surface 159 → 160). The Rust binding already modeled the optional `_meta`, so the previously recorded deviation resolved upstream. ADR-027 revision log + COMPLIANCE.md/schema README hash records updated.
4950
- **Docs/ADR reconciliation to implemented behavior**: ADR-029 §CI surface rewritten to the as-built lanes (the prescribed `cargo test --workspace` matrices never compiled — spec-pinned workspace members trip the ADR's own mutex; per-crate matrix is the operative shape); ADR-025 revision entry recording the shim's branch reality (still consumed by four non-frozen crates; manifest carries an unpublishable 0.4.0 from the version sweep; the framework-wide cut remains 0.4.0 release-prep work); `docs/plans/2026-07-28-schema-coverage-matrix.md` marked STALE/superseded (authoritative coverage = COMPLIANCE.md + the compliance harness); COMPLIANCE.md elicitation-union and extension-crate-name notes refreshed.

crates/turul-http-mcp-server/src/streamable_http.rs

Lines changed: 18 additions & 6 deletions
Original file line numberDiff line numberDiff line change
@@ -2232,6 +2232,16 @@ impl StreamableHttpHandler {
22322232
// Handle explicit shutdown signal from main task
22332233
_ = &mut shutdown_rx => {
22342234
debug!("🔍 Progress task: shutdown_rx branch fired! Received explicit shutdown signal for session: {}", session_id_clone);
2235+
// Flush events already queued: request-scoped
2236+
// notifications were emitted (and awaited)
2237+
// before the tool returned, so they must reach
2238+
// the wire ahead of the final response frame.
2239+
while let Ok(sse_event) = progress_rx.try_recv() {
2240+
let sse_chunk = sse_event.format();
2241+
if sender_clone.send(Ok(Bytes::from(sse_chunk))).is_err() {
2242+
break;
2243+
}
2244+
}
22352245
break;
22362246
}
22372247
}
@@ -2338,12 +2348,10 @@ impl StreamableHttpHandler {
23382348
let final_chunk =
23392349
format!("data: {}\n\n", serde_json::to_string(&final_json).unwrap());
23402350

2341-
if let Err(err) = sender.send(Ok(Bytes::from(final_chunk))) {
2342-
error!("Failed to send SSE final chunk: {}", err);
2343-
}
2344-
2345-
// CRITICAL: Send explicit shutdown signal to progress forwarding task (SSE only)
2346-
// This breaks it out of the progress_rx.recv().await loop immediately
2351+
// Shut down (and flush) the progress forwarding task BEFORE the
2352+
// final frame goes out: request-scoped notifications precede the
2353+
// final response on the wire, and the final response terminates
2354+
// the stream.
23472355
if let Some(shutdown_tx) = shutdown_tx {
23482356
debug!(
23492357
"🔍 Main task sending shutdown signal to progress task for request: {:?}",
@@ -2399,6 +2407,10 @@ impl StreamableHttpHandler {
23992407
request_id
24002408
);
24012409
}
2410+
2411+
if let Err(err) = sender.send(Ok(Bytes::from(final_chunk))) {
2412+
error!("Failed to send SSE final chunk: {}", err);
2413+
}
24022414
} else {
24032415
// For JSON-only clients, send as regular JSON-RPC response (no streaming frames)
24042416
let final_json = serde_json::to_string(&response).unwrap();

crates/turul-mcp-server/src/server.rs

Lines changed: 8 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -1898,6 +1898,14 @@ impl JsonRpcHandler for SessionAwareToolHandler {
18981898
serde_json::Value::String(state.clone()),
18991899
);
19001900
}
1901+
// Per-request log opt-in: notifications/message is emitted only
1902+
// for requests whose _meta declares a logLevel.
1903+
#[allow(deprecated)]
1904+
if let Some(ref level) = call_params.meta.log_level
1905+
&& let Ok(v) = serde_json::to_value(level)
1906+
{
1907+
session.extensions.insert("mcp:logLevel".to_string(), v);
1908+
}
19011909
}
19021910
ctx
19031911
};

crates/turul-mcp-server/src/session.rs

Lines changed: 31 additions & 7 deletions
Original file line numberDiff line numberDiff line change
@@ -437,7 +437,37 @@ impl SessionContext {
437437
// Use the provided LoggingLevel directly
438438
let message_level = level;
439439

440-
// Check if this message should be sent to this session based on its logging level
440+
// 2026-07-28: notifications/message is opt-in PER REQUEST — the server
441+
// MUST NOT emit it for a request whose _meta lacks
442+
// io.modelcontextprotocol/logLevel. The declared level is the threshold
443+
// (replaces the removed logging/setLevel session threshold).
444+
#[cfg(feature = "protocol-2026-07-28")]
445+
{
446+
let request_threshold = self.extensions.get("mcp:logLevel").and_then(|v| {
447+
serde_json::from_value::<turul_mcp_protocol::logging::LoggingLevel>(v.clone()).ok()
448+
});
449+
match request_threshold {
450+
None => {
451+
debug!(
452+
"🔕 notifications/message suppressed for session {}: the request declared no logLevel",
453+
self.session_id
454+
);
455+
return;
456+
}
457+
Some(threshold) => {
458+
if !message_level.should_log(threshold) {
459+
debug!(
460+
"🔕 Filtering {:?} message for session {} (request threshold {:?})",
461+
message_level, self.session_id, threshold
462+
);
463+
return;
464+
}
465+
}
466+
}
467+
}
468+
469+
// 2025-11-25: filter against the logging/setLevel session threshold.
470+
#[cfg(feature = "protocol-2025-11-25")]
441471
if !self.should_log(message_level).await {
442472
let threshold = self.get_logging_level().await;
443473
debug!(
@@ -447,12 +477,6 @@ impl SessionContext {
447477
return;
448478
}
449479

450-
let threshold = self.get_logging_level().await;
451-
debug!(
452-
"📢 Sending {:?} level message to session {} (threshold: {:?})",
453-
message_level, self.session_id, threshold
454-
);
455-
456480
// Create proper LoggingMessageNotification struct once
457481
use turul_mcp_protocol::notifications::LoggingMessageNotification;
458482
let mut notification = LoggingMessageNotification::new(message_level, data);
Lines changed: 175 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -0,0 +1,175 @@
1+
//! Wire-level acceptance for per-request log gating (2026-07-28).
2+
//!
3+
//! `RequestMetaObject.logLevel`: "If absent, the server MUST NOT send any
4+
//! `notifications/message` notifications for this request. The client opts in
5+
//! to log messages by explicitly setting a level. Replaces the former
6+
//! `logging/setLevel` RPC."
7+
//!
8+
//! Built only under the 2026 feature; compiles to nothing under 2025-11-25.
9+
#![cfg(feature = "protocol-2026-07-28")]
10+
11+
use std::time::Duration;
12+
13+
use futures::StreamExt;
14+
use turul_mcp_derive::McpTool;
15+
use turul_mcp_server::prelude::*;
16+
17+
/// Emits one info-level `notifications/message` mid-execution, then returns.
18+
#[derive(McpTool, Clone, Default)]
19+
#[tool(name = "chatty", description = "Logs while working", output = String)]
20+
struct ChattyTool {}
21+
22+
impl ChattyTool {
23+
async fn execute(&self, session: Option<SessionContext>) -> McpResult<String> {
24+
if let Some(session) = session {
25+
session
26+
.notify_log(
27+
turul_mcp_protocol::logging::LoggingLevel::Info,
28+
serde_json::json!("working..."),
29+
Some("chatty".to_string()),
30+
None,
31+
)
32+
.await;
33+
}
34+
Ok("done".to_string())
35+
}
36+
}
37+
38+
async fn start_server() -> String {
39+
let port = std::net::TcpListener::bind("127.0.0.1:0")
40+
.unwrap()
41+
.local_addr()
42+
.unwrap()
43+
.port();
44+
45+
let server = McpServer::builder()
46+
.name("loggate-2026-test")
47+
.version("0.4.0")
48+
.tool(ChattyTool::default())
49+
.bind_address(format!("127.0.0.1:{port}").parse().unwrap())
50+
.build()
51+
.expect("build 2026 server");
52+
53+
tokio::spawn(async move {
54+
server.run().await.ok();
55+
});
56+
57+
let url = format!("http://127.0.0.1:{port}/mcp");
58+
let client = reqwest::Client::new();
59+
for _ in 0..50 {
60+
if client.get(&url).send().await.is_ok() {
61+
break;
62+
}
63+
tokio::time::sleep(Duration::from_millis(20)).await;
64+
}
65+
url
66+
}
67+
68+
/// POST a `chatty` tools/call with SSE framing; return every `data:` JSON
69+
/// payload observed on the response stream.
70+
async fn call_chatty(url: &str, log_level: Option<&str>) -> Vec<serde_json::Value> {
71+
let mut meta = serde_json::json!({
72+
"io.modelcontextprotocol/protocolVersion": "2026-07-28",
73+
"io.modelcontextprotocol/clientInfo": { "name": "test-client", "version": "1.0.0" },
74+
"io.modelcontextprotocol/clientCapabilities": {}
75+
});
76+
if let (Some(m), Some(level)) = (meta.as_object_mut(), log_level) {
77+
m.insert(
78+
"io.modelcontextprotocol/logLevel".to_string(),
79+
serde_json::json!(level),
80+
);
81+
}
82+
83+
let client = reqwest::Client::new();
84+
let resp = client
85+
.post(url)
86+
// Both media types accepted → tools/call gets the SSE framing, which
87+
// is where request-scoped notifications ride.
88+
.header("Accept", "application/json, text/event-stream")
89+
.header("MCP-Protocol-Version", "2026-07-28")
90+
.header("Mcp-Method", "tools/call")
91+
.header("Mcp-Name", "chatty")
92+
.json(&serde_json::json!({
93+
"jsonrpc": "2.0", "id": 1, "method": "tools/call",
94+
"params": { "name": "chatty", "arguments": {}, "_meta": meta }
95+
}))
96+
.send()
97+
.await
98+
.expect("chatty POST");
99+
assert_eq!(resp.status(), 200);
100+
101+
let mut events = Vec::new();
102+
let mut buffer = String::new();
103+
let mut stream = resp.bytes_stream();
104+
let deadline = tokio::time::Instant::now() + Duration::from_secs(5);
105+
loop {
106+
let remaining = deadline.saturating_duration_since(tokio::time::Instant::now());
107+
if remaining.is_zero() {
108+
break;
109+
}
110+
match tokio::time::timeout(remaining, stream.next()).await {
111+
Ok(Some(Ok(chunk))) => buffer.push_str(&String::from_utf8_lossy(&chunk)),
112+
_ => break,
113+
}
114+
let mut done = false;
115+
while let Some(pos) = buffer.find("\n\n") {
116+
let event: String = buffer.drain(..pos + 2).collect();
117+
for line in event.lines() {
118+
if let Some(data) = line.strip_prefix("data: ")
119+
&& let Ok(json) = serde_json::from_str::<serde_json::Value>(data)
120+
{
121+
// The final JSON-RPC response ends the request stream.
122+
if json.get("result").is_some() || json.get("error").is_some() {
123+
done = true;
124+
}
125+
events.push(json);
126+
}
127+
}
128+
}
129+
if done {
130+
break;
131+
}
132+
}
133+
events
134+
}
135+
136+
#[tokio::test]
137+
async fn message_notifications_require_a_declared_log_level() {
138+
let url = start_server().await;
139+
140+
// Without logLevel in _meta: the server MUST NOT emit notifications/message.
141+
let events = call_chatty(&url, None).await;
142+
assert!(
143+
!events.is_empty(),
144+
"the final response must arrive on the stream"
145+
);
146+
assert!(
147+
!events
148+
.iter()
149+
.any(|e| e["method"] == "notifications/message"),
150+
"no logLevel declared → no notifications/message, got: {events:?}"
151+
);
152+
153+
// With logLevel "info": the info-level message must be delivered.
154+
let events = call_chatty(&url, Some("info")).await;
155+
assert!(
156+
events
157+
.iter()
158+
.any(|e| e["method"] == "notifications/message"),
159+
"declared logLevel must opt in to notifications/message, got: {events:?}"
160+
);
161+
}
162+
163+
#[tokio::test]
164+
async fn declared_level_is_the_severity_threshold() {
165+
let url = start_server().await;
166+
167+
// The tool logs at info; a request declaring only "error" must not get it.
168+
let events = call_chatty(&url, Some("error")).await;
169+
assert!(
170+
!events
171+
.iter()
172+
.any(|e| e["method"] == "notifications/message"),
173+
"info-level message must be filtered below an 'error' threshold: {events:?}"
174+
);
175+
}

scripts/ci-gates.sh

Lines changed: 2 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -33,6 +33,8 @@ gate_default() {
3333
cargo test -p turul-mcp-server --no-default-features --features http,sse,protocol-2026-07-28 --test mrtr_2026
3434
run "2026 Mcp-Param-* mirroring (x-mcp-header validation)" \
3535
cargo test -p turul-mcp-server --no-default-features --features http,sse,protocol-2026-07-28 --test mcp_param_2026
36+
run "2026 per-request log gating (logLevel opt-in)" \
37+
cargo test -p turul-mcp-server --no-default-features --features http,sse,protocol-2026-07-28 --test log_gating_2026
3638
run "protocol-2026 compliance + upstream wire fixtures" \
3739
cargo test -p turul-mcp-protocol-2026-07-28 --features compliance
3840
run "bilingual client (not in default-members)" cargo test -p turul-mcp-client

0 commit comments

Comments
 (0)