Skip to main content

myko_server/
ws_handler.rs

1//! WebSocket handler for the cell-based server.
2//!
3//! Handles WebSocket connections using ClientSession for subscription management.
4
5use std::{
6    collections::HashMap,
7    net::SocketAddr,
8    sync::{
9        Arc, Mutex, OnceLock,
10        atomic::{AtomicBool, AtomicU8, AtomicU64, Ordering},
11    },
12    thread,
13    time::{Duration, Instant},
14};
15
16use futures_util::{SinkExt, StreamExt};
17use hyphae::SelectExt;
18use myko::{
19    WS_MAX_FRAME_SIZE_BYTES, WS_MAX_MESSAGE_SIZE_BYTES,
20    client::MykoProtocol,
21    command::{CommandContext, CommandHandlerRegistration},
22    entities::client::{Client, ClientId},
23    relationship::{
24        iter_client_id_registrations, iter_fallback_to_id_registrations,
25        iter_server_owned_registrations,
26    },
27    report::AnyOutput,
28    request::RequestContext,
29    server::{
30        CellServerCtx, ClientSession, PendingQueryResponse, WsWriter,
31        client_registry::try_client_registry,
32    },
33    wire::{
34        CancelSubscription, CommandError, CommandResponse, EncodedCommandMessage, MEvent,
35        MEventType, MykoMessage, PingData, QueryWindowUpdate, ViewError, ViewWindowUpdate,
36    },
37};
38use tokio::{net::TcpStream, sync::mpsc, time::interval};
39use tokio_tungstenite::{
40    accept_async_with_config,
41    tungstenite::{Message, protocol::WebSocketConfig},
42};
43use uuid::Uuid;
44
45struct WsBenchmarkStats {
46    message_count: AtomicU64,
47    total_bytes: AtomicU64,
48}
49
50static WS_BENCHMARK_STATS: OnceLock<Arc<WsBenchmarkStats>> = OnceLock::new();
51static WS_BENCHMARK_LOGGER_STARTED: AtomicBool = AtomicBool::new(false);
52
53fn ws_benchmark_stats() -> Arc<WsBenchmarkStats> {
54    WS_BENCHMARK_STATS
55        .get_or_init(|| {
56            Arc::new(WsBenchmarkStats {
57                message_count: AtomicU64::new(0),
58                total_bytes: AtomicU64::new(0),
59            })
60        })
61        .clone()
62}
63
64fn ensure_ws_benchmark_logger() {
65    if WS_BENCHMARK_LOGGER_STARTED
66        .compare_exchange(false, true, Ordering::Relaxed, Ordering::Relaxed)
67        .is_err()
68    {
69        return;
70    }
71
72    let stats = ws_benchmark_stats();
73    thread::Builder::new()
74        .name("ws-benchmark-logger".into())
75        .spawn(move || {
76            loop {
77                thread::sleep(Duration::from_secs(1));
78
79                let count = stats.message_count.swap(0, Ordering::Relaxed);
80                let bytes = stats.total_bytes.swap(0, Ordering::Relaxed);
81
82                if count == 0 {
83                    continue;
84                }
85
86                tracing::info!(
87                    "WebSocket benchmark last_1s messages={} bytes={} avg_bytes={}",
88                    count,
89                    bytes,
90                    bytes / count
91                );
92            }
93        })
94        .expect("failed to spawn websocket benchmark logger thread");
95}
96
97fn normalize_incoming_event(event: &mut MEvent, client_id: &str, host_id: uuid::Uuid) {
98    if event.change_type != MEventType::SET {
99        return;
100    }
101
102    // Auto-populate #[myko_client_id] fields with the connection's client_id
103    for reg in iter_client_id_registrations() {
104        if reg.entity_type == event.item_type {
105            if let Some(obj) = event.item.as_object_mut() {
106                obj.insert(
107                    reg.field_name_json.to_string(),
108                    serde_json::Value::String(client_id.to_string()),
109                );
110            }
111            break;
112        }
113    }
114
115    // Auto-populate #[server_owned] fields with this server's ID
116    for reg in iter_server_owned_registrations() {
117        if reg.entity_type == event.item_type {
118            if let Some(obj) = event.item.as_object_mut() {
119                let field = reg.field_name_json;
120                let current = obj.get(field).and_then(|v| v.as_str()).unwrap_or("");
121                if current.is_empty() {
122                    obj.insert(
123                        field.to_string(),
124                        serde_json::Value::String(host_id.to_string()),
125                    );
126                }
127            }
128            break;
129        }
130    }
131
132    // Auto-populate #[fallback_to_id] fields with the entity's own id
133    // if the field is null or missing.
134    if let Some(obj) = event.item.as_object_mut()
135        && let Some(id) = obj.get("id").and_then(|v| v.as_str()).map(String::from)
136    {
137        for reg in iter_fallback_to_id_registrations() {
138            if reg.entity_type == event.item_type {
139                let field = reg.field_name_json;
140                if matches!(obj.get(field), None | Some(serde_json::Value::Null)) {
141                    obj.insert(field.to_string(), serde_json::Value::String(id.clone()));
142                }
143            }
144        }
145    }
146}
147
148/// Per-connection drop tracking to avoid log storms when clients fall behind.
149///
150/// When the outbound channel is full, we will drop messages (same as today),
151/// but we must not `warn!` for every drop or we can effectively DoS ourselves.
152struct DropLogger {
153    client_id: Arc<str>,
154    dropped: std::sync::atomic::AtomicU64,
155    last_log_ms: std::sync::atomic::AtomicU64,
156}
157
158impl DropLogger {
159    fn new(client_id: Arc<str>) -> Self {
160        Self {
161            client_id,
162            dropped: std::sync::atomic::AtomicU64::new(0),
163            last_log_ms: std::sync::atomic::AtomicU64::new(0),
164        }
165    }
166
167    fn on_drop(&self, kind: &'static str, err: &dyn std::fmt::Display) {
168        use std::sync::atomic::Ordering;
169
170        self.dropped.fetch_add(1, Ordering::Relaxed);
171
172        // Log at most once per second per connection.
173        let now_ms = std::time::SystemTime::now()
174            .duration_since(std::time::UNIX_EPOCH)
175            .unwrap_or_default()
176            .as_millis() as u64;
177        let last_ms = self.last_log_ms.load(Ordering::Relaxed);
178        if now_ms.saturating_sub(last_ms) < 1000 {
179            return;
180        }
181
182        if self
183            .last_log_ms
184            .compare_exchange(last_ms, now_ms, Ordering::Relaxed, Ordering::Relaxed)
185            .is_err()
186        {
187            return;
188        }
189
190        let n = self.dropped.swap(0, Ordering::Relaxed);
191        tracing::warn!(
192            "WebSocket send buffer full; dropped {} message(s) for client {} (latest: {}): {}",
193            n,
194            self.client_id,
195            kind,
196            err
197        );
198    }
199}
200
201struct CommandJob {
202    tx_id: Arc<str>,
203    command_id: String,
204    command: serde_json::Value,
205    received_at: Instant,
206}
207
208/// Result of an async subscription build (query or view cell_factory).
209enum SubscriptionReady {
210    Query {
211        tx_id: Arc<str>,
212        query_id: Arc<str>,
213        cellmap: hyphae::CellMap<Arc<str>, Arc<dyn myko::item::AnyItem>, hyphae::CellImmutable>,
214        window: Option<myko::wire::QueryWindow>,
215    },
216    View {
217        tx_id: Arc<str>,
218        view_id: Arc<str>,
219        cellmap: hyphae::CellMap<Arc<str>, Arc<dyn myko::item::AnyItem>, hyphae::CellImmutable>,
220        window: Option<myko::wire::QueryWindow>,
221    },
222}
223
224enum OutboundMessage {
225    Message(MykoMessage),
226    SerializedCommand {
227        tx: Arc<str>,
228        command_id: String,
229        payload: EncodedCommandMessage,
230    },
231}
232
233enum DeferredOutbound {
234    Report(Arc<str>, Arc<dyn AnyOutput>),
235    Query {
236        response: PendingQueryResponse,
237        is_view: bool,
238    },
239}
240
241/// WebSocket handler for a single client connection.
242pub struct WsHandler;
243
244impl WsHandler {
245    /// Handle a new WebSocket connection (performs the handshake).
246    pub async fn handle_connection(
247        stream: TcpStream,
248        addr: SocketAddr,
249        ctx: Arc<CellServerCtx>,
250    ) -> Result<(), Box<dyn std::error::Error + Send + Sync>> {
251        let mut ws_config = WebSocketConfig::default();
252        ws_config.max_message_size = Some(WS_MAX_MESSAGE_SIZE_BYTES);
253        ws_config.max_frame_size = Some(WS_MAX_FRAME_SIZE_BYTES);
254        let ws_stream = accept_async_with_config(stream, Some(ws_config)).await?;
255        Self::handle_upgraded(ws_stream, addr, ctx).await
256    }
257
258    /// Handle a WebSocket connection whose HTTP/1.1 handshake has already
259    /// completed and produced a [`tokio_tungstenite::WebSocketStream`].
260    ///
261    /// Used by the front-door router when it pre-parses the HTTP request
262    /// (to dispatch between `/myko` WS and `/myko/mcp` HTTP/WS) and then
263    /// completes the WS handshake itself.
264    #[allow(clippy::too_many_arguments)]
265    pub async fn handle_upgraded(
266        ws_stream: tokio_tungstenite::WebSocketStream<TcpStream>,
267        addr: SocketAddr,
268        ctx: Arc<CellServerCtx>,
269    ) -> Result<(), Box<dyn std::error::Error + Send + Sync>> {
270        let host_id = ctx.host_id;
271
272        let (mut write, mut read) = ws_stream.split();
273
274        // Create a bounded channel for sending messages to the client
275        // High limit (10k) since we have good memory availability
276        let (tx, mut rx) = mpsc::channel::<OutboundMessage>(10_000);
277        let (deferred_tx, mut deferred_rx) = mpsc::channel::<DeferredOutbound>(10_000);
278        let (priority_tx, mut priority_rx) = mpsc::channel::<MykoMessage>(1_000);
279        let (command_tx, mut command_rx) = mpsc::unbounded_channel::<CommandJob>();
280        let (subscribe_tx, mut subscribe_rx) = mpsc::unbounded_channel::<SubscriptionReady>();
281
282        // Outgoing format for this session: defaults to JSON, sticky-promotes
283        // to CBOR on the first received binary frame. Never demotes.
284        let outgoing_format = Arc::new(AtomicU8::new(MykoProtocol::JSON as u8));
285
286        // Create client session with channel-based writer
287        let client_id: Arc<str> = Uuid::new_v4().to_string().into();
288        let drop_logger = Arc::new(DropLogger::new(client_id.clone()));
289        let writer = ChannelWriter {
290            tx: tx.clone(),
291            deferred_tx: deferred_tx.clone(),
292            drop_logger: drop_logger.clone(),
293            outgoing_format: outgoing_format.clone(),
294        };
295
296        // Register writer in the global client registry (if initialized)
297        let writer_arc: Arc<dyn WsWriter> = Arc::new(ChannelWriter {
298            tx: tx.clone(),
299            deferred_tx: deferred_tx.clone(),
300            drop_logger: drop_logger.clone(),
301            outgoing_format: outgoing_format.clone(),
302        });
303        if let Some(registry) = try_client_registry() {
304            registry.register(client_id.clone(), writer_arc);
305        }
306
307        let mut session = ClientSession::new(client_id.clone(), writer);
308
309        let outgoing_format_writer = outgoing_format.clone();
310        let query_ids_by_tx: Arc<Mutex<HashMap<Arc<str>, Arc<str>>>> =
311            Arc::new(Mutex::new(HashMap::new()));
312        let view_ids_by_tx: Arc<Mutex<HashMap<Arc<str>, Arc<str>>>> =
313            Arc::new(Mutex::new(HashMap::new()));
314        let subscribe_started_by_tx: Arc<Mutex<HashMap<Arc<str>, Instant>>> =
315            Arc::new(Mutex::new(HashMap::new()));
316        let command_started_by_tx: Arc<Mutex<HashMap<Arc<str>, Instant>>> =
317            Arc::new(Mutex::new(HashMap::new()));
318        let outbound_commands_by_tx: Arc<Mutex<HashMap<String, (String, Instant)>>> =
319            Arc::new(Mutex::new(HashMap::new()));
320
321        let outbound_commands_by_tx_writer = outbound_commands_by_tx.clone();
322
323        // Publish Client entity
324        let client_entity = Client {
325            id: ClientId(client_id.clone()),
326            server_id: host_id.to_string().into(),
327            address: Some(Arc::from(addr.to_string())),
328            windback: None,
329        };
330        if let Err(e) = ctx.set(&client_entity) {
331            tracing::error!("Failed to persist client entity: {e}");
332        }
333
334        tracing::info!("Client connected: {} from {}", client_id, addr);
335
336        let write_ctx = ctx.clone();
337        let write_client_id = client_id.clone();
338        let write_addr = addr;
339        let command_ctx = ctx.clone();
340        let command_priority_tx = priority_tx.clone();
341        let command_drop_logger = drop_logger.clone();
342        let command_client_id = client_id.clone();
343
344        // Spawn task to forward messages from channel to WebSocket
345        let write_task = tokio::spawn(async move {
346            let _ctx = write_ctx;
347            let mut normal_open = true;
348            let mut priority_open = true;
349            let mut deferred_open = true;
350            while normal_open || priority_open || deferred_open {
351                let msg = tokio::select! {
352                    biased;
353                    maybe = priority_rx.recv(), if priority_open => {
354                        match maybe {
355                            Some(msg) => OutboundMessage::Message(msg),
356                            None => {
357                                priority_open = false;
358                                continue;
359                            }
360                        }
361                    }
362                    maybe = deferred_rx.recv(), if deferred_open => {
363                        match maybe {
364                            Some(DeferredOutbound::Report(tx, output)) => {
365                                OutboundMessage::Message(MykoMessage::ReportResponse(myko::wire::ReportResponse {
366                                    response: output.to_value(),
367                                    tx: tx.to_string(),
368                                }))
369                            }
370                            Some(DeferredOutbound::Query { response, is_view }) => {
371                                if is_view {
372                                    OutboundMessage::Message(MykoMessage::ViewResponse(response.into_wire()))
373                                } else {
374                                    OutboundMessage::Message(MykoMessage::QueryResponse(response.into_wire()))
375                                }
376                            }
377                            None => {
378                                deferred_open = false;
379                                continue;
380                            }
381                        }
382                    }
383                    maybe = rx.recv(), if normal_open => {
384                        match maybe {
385                            Some(msg) => msg,
386                            None => {
387                                normal_open = false;
388                                continue;
389                            }
390                        }
391                    }
392                };
393                // Per-message timing tap (outbound). Counts by kind into the
394                // global ws_timing instrumentation, and by kind+client+tag
395                // into an OTLP counter. Counterpart to the inbound tap in
396                // `handle_message`.
397                match &msg {
398                    OutboundMessage::SerializedCommand { command_id, .. } => {
399                        crate::ws_timing::record_outbound_for_client(
400                            "Command",
401                            &write_client_id,
402                            Some(command_id.as_str()),
403                        )
404                    }
405                    OutboundMessage::Message(m) => crate::ws_timing::record_outbound_for_client(
406                        crate::ws_timing::message_kind(m),
407                        &write_client_id,
408                        crate::ws_timing::message_tag(m),
409                    ),
410                };
411                let (kind, tx_id, seq, _upserts, _deletes, _total_count) = match &msg {
412                    OutboundMessage::SerializedCommand { tx, .. } => {
413                        ("command", Some(tx.clone()), None, None, None, None)
414                    }
415                    OutboundMessage::Message(msg) => match msg {
416                        MykoMessage::ViewResponse(r) => (
417                            "view_response",
418                            Some(r.tx.clone()),
419                            Some(r.sequence),
420                            Some(r.upserts.len()),
421                            Some(r.deletes.len()),
422                            r.total_count,
423                        ),
424                        MykoMessage::QueryResponse(r) => (
425                            "query_response",
426                            Some(r.tx.clone()),
427                            Some(r.sequence),
428                            Some(r.upserts.len()),
429                            Some(r.deletes.len()),
430                            r.total_count,
431                        ),
432                        MykoMessage::CommandResponse(r) => (
433                            "command_response",
434                            Some(Arc::<str>::from(r.tx.clone())),
435                            None,
436                            None,
437                            None,
438                            None,
439                        ),
440                        MykoMessage::CommandError(r) => (
441                            "command_error",
442                            Some(Arc::<str>::from(r.tx.clone())),
443                            None,
444                            None,
445                            None,
446                            None,
447                        ),
448                        _ => ("other", None, None, None, None, None),
449                    },
450                };
451
452                match &msg {
453                    OutboundMessage::SerializedCommand { tx, command_id, .. } => {
454                        if !tx.trim().is_empty()
455                            && let Ok(mut map) = outbound_commands_by_tx_writer.lock()
456                        {
457                            map.insert(tx.to_string(), (command_id.clone(), Instant::now()));
458                        }
459                    }
460                    OutboundMessage::Message(MykoMessage::Command(wrapped)) => {
461                        if let Some(tx_id) = wrapped.command.get("tx").and_then(|v| v.as_str())
462                            && !tx_id.trim().is_empty()
463                            && let Ok(mut map) = outbound_commands_by_tx_writer.lock()
464                        {
465                            map.insert(
466                                tx_id.to_string(),
467                                (wrapped.command_id.clone(), Instant::now()),
468                            );
469                        }
470                    }
471                    _ => {}
472                }
473
474                let ws_msg = match &msg {
475                    OutboundMessage::SerializedCommand {
476                        payload: EncodedCommandMessage::Json(json),
477                        ..
478                    } => Message::Text(json.clone().into()),
479                    OutboundMessage::SerializedCommand {
480                        payload: EncodedCommandMessage::Cbor(bytes),
481                        ..
482                    } => Message::Binary(bytes.clone().into()),
483                    OutboundMessage::Message(msg)
484                        if outgoing_format_writer.load(Ordering::SeqCst)
485                            == MykoProtocol::CBOR as u8 =>
486                    {
487                        let mut bytes = Vec::new();
488                        match ciborium::ser::into_writer(msg, &mut bytes) {
489                            Ok(()) => Message::Binary(bytes.into()),
490                            Err(e) => {
491                                tracing::error!("Failed to serialize message to CBOR: {}", e);
492                                continue;
493                            }
494                        }
495                    }
496                    OutboundMessage::Message(msg) => match serde_json::to_string(msg) {
497                        Ok(json) => Message::Text(json.into()),
498                        Err(e) => {
499                            tracing::error!("Failed to serialize message to JSON: {}", e);
500                            continue;
501                        }
502                    },
503                };
504                let payload_bytes = match &ws_msg {
505                    Message::Binary(b) => b.len(),
506                    Message::Text(t) => t.len(),
507                    _ => 0,
508                };
509
510                if let Err(err) = write.send(ws_msg).await {
511                    tracing::error!(
512                        "WebSocket write failed for client {} from {} kind={} tx={:?} seq={:?} payload_bytes={} binary={}: {}",
513                        write_client_id,
514                        write_addr,
515                        kind,
516                        tx_id,
517                        seq,
518                        payload_bytes,
519                        outgoing_format_writer.load(Ordering::SeqCst) == MykoProtocol::CBOR as u8,
520                        err
521                    );
522                    break;
523                }
524            }
525            // NOTE(ts): Unregister from client registry immediately so the node
526            // executor stops serializing commands into a dead channel.
527            if let Some(registry) = try_client_registry() {
528                registry.unregister(&write_client_id);
529                tracing::info!(
530                    "WebSocket writer unregistered client {} from {} (write task exiting)",
531                    write_client_id,
532                    write_addr,
533                );
534            }
535            tracing::warn!(
536                "WebSocket writer task exiting for client {} from {} normal_open={} priority_open={} deferred_open={}",
537                write_client_id,
538                write_addr,
539                normal_open,
540                priority_open,
541                deferred_open
542            );
543        });
544
545        // Execute commands on a dedicated worker so ping/cancel traffic is never
546        // blocked by long-running command handlers.
547        let command_started_cleanup = command_started_by_tx.clone();
548        let command_task = tokio::spawn(async move {
549            while let Some(job) = command_rx.recv().await {
550                let command_ctx = command_ctx.clone();
551                let command_priority_tx = command_priority_tx.clone();
552                let command_drop_logger = command_drop_logger.clone();
553                let command_client_id = command_client_id.clone();
554                let tx_id = job.tx_id.clone();
555                let started_map = command_started_cleanup.clone();
556                match tokio::task::spawn_blocking(move || {
557                    Self::execute_command_job(
558                        command_ctx,
559                        &command_priority_tx,
560                        command_drop_logger.as_ref(),
561                        command_client_id,
562                        job,
563                    );
564                })
565                .await
566                {
567                    Ok(()) => {}
568                    Err(e) => {
569                        tracing::error!("Command worker panicked: {}", e);
570                    }
571                }
572                // NOTE(ts): Clean up timing entry after command completes (success or panic).
573                if let Ok(mut map) = started_map.lock() {
574                    map.remove(&tx_id);
575                }
576            }
577        });
578
579        // Process incoming messages and completed subscription builds concurrently.
580        // NOTE(ts): View/query cell_factory calls are spawned on the blocking thread pool
581        // so they don't block command processing or other messages.
582        let mut outbound_ttl_interval = interval(Duration::from_secs(10));
583        outbound_ttl_interval.tick().await; // NOTE(ts): consume the immediate first tick
584        loop {
585            tokio::select! {
586                // Completed subscription builds — register with session
587                Some(ready) = subscribe_rx.recv() => {
588                    let tx_id = match &ready {
589                        SubscriptionReady::Query { tx_id, .. } => tx_id.clone(),
590                        SubscriptionReady::View { tx_id, .. } => tx_id.clone(),
591                    };
592                    if let Ok(mut map) = subscribe_started_by_tx.lock() {
593                        map.remove(&tx_id);
594                    }
595                    match ready {
596                        SubscriptionReady::Query { tx_id, query_id, cellmap, window } => {
597                            session.subscribe_query(tx_id, query_id, cellmap, window);
598                        }
599                        SubscriptionReady::View { tx_id, view_id, cellmap, window } => {
600                            session.subscribe_view_with_id(tx_id, view_id, cellmap, window);
601                        }
602                    }
603                }
604                // NOTE(ts): Sweep outbound command entries older than 10s.
605                // Responses normally arrive quickly; stale entries are from
606                // dropped connections or commands that will never get a response.
607                _ = outbound_ttl_interval.tick() => {
608                    if let Ok(mut map) = outbound_commands_by_tx.lock() {
609                        let before = map.len();
610                        map.retain(|_, (_, started)| started.elapsed() < Duration::from_secs(10));
611                        let removed = before - map.len();
612                        if removed > 0 {
613                            tracing::debug!(
614                                "Outbound command TTL sweep client={}: removed {} stale entries, {} remaining",
615                                session.client_id,
616                                removed,
617                                map.len()
618                            );
619                        }
620                    }
621                }
622                // Incoming WebSocket messages
623                msg = read.next() => {
624                    let Some(msg) = msg else { break };
625                    let ctx = ctx.clone();
626                    let msg = match msg {
627                        Ok(m) => m,
628                        Err(e) => {
629                            tracing::error!("WebSocket read error from {}: {}", client_id, e);
630                            break;
631                        }
632                    };
633
634                    match msg {
635                        Message::Binary(data) => {
636                            if outgoing_format.load(Ordering::SeqCst) != MykoProtocol::CBOR as u8 {
637                                tracing::debug!(
638                                    "Client {} promoted outgoing format to CBOR via demonstration",
639                                    client_id
640                                );
641                                outgoing_format.store(MykoProtocol::CBOR as u8, Ordering::SeqCst);
642                            }
643
644                            match ciborium::de::from_reader::<MykoMessage, _>(data.as_ref()) {
645                                Ok(myko_msg) => {
646                                    if let Err(e) = Self::handle_message(
647                                        &mut session,
648                                        ctx,
649                                        &priority_tx,
650                                        &drop_logger,
651                                        &query_ids_by_tx,
652                                        &view_ids_by_tx,
653                                        &subscribe_started_by_tx,
654                                        &command_started_by_tx,
655                                        &outbound_commands_by_tx,
656                                        &command_tx,
657                                        &subscribe_tx,
658                                        myko_msg,
659                                    ) {
660                                        tracing::error!("Error handling message: {}", e);
661                                    }
662                                    tokio::task::yield_now().await;
663                                }
664                                Err(e) => {
665                                    tracing::warn!("Failed to parse message from {}: {}", client_id, e);
666                                }
667                            }
668                        }
669                        Message::Text(text) => {
670                            match serde_json::from_str::<MykoMessage>(&text) {
671                                Ok(myko_msg) => {
672                                    if let Err(e) = Self::handle_message(
673                                        &mut session,
674                                        ctx,
675                                        &priority_tx,
676                                        &drop_logger,
677                                        &query_ids_by_tx,
678                                        &view_ids_by_tx,
679                                        &subscribe_started_by_tx,
680                                        &command_started_by_tx,
681                                        &outbound_commands_by_tx,
682                                        &command_tx,
683                                        &subscribe_tx,
684                                        myko_msg,
685                                    ) {
686                                        tracing::error!("Error handling message: {}", e);
687                                    }
688                                    tokio::task::yield_now().await;
689                                }
690                                Err(e) => {
691                                    tracing::warn!(
692                                        "Failed to parse JSON message from {}: {} | raw: {}",
693                                        client_id,
694                                        e,
695                                        if text.len() > 1000 {
696                                            &text[..1000]
697                                        } else {
698                                            &text
699                                        }
700                                    );
701                                }
702                            }
703                        }
704                        Message::Ping(data) => {
705                            tracing::trace!("Ping from {}", client_id);
706                            let _ = data;
707                        }
708                        Message::Pong(_) => {
709                            tracing::trace!("Pong from {}", client_id);
710                        }
711                        Message::Close(frame) => {
712                            tracing::warn!("Client {} sent close frame: {:?}", client_id, frame);
713                            break;
714                        }
715                        Message::Frame(_) => {}
716                    }
717                }
718            }
719        }
720
721        // Cleanup. Order matters:
722        // 1. Abort the write/command tasks first so their channel receivers
723        //    are dropped — `ChannelWriter` clones held by subscriber
724        //    callbacks then short-circuit via `tx_dead()` / `deferred_dead()`
725        //    instead of doing useless work and emitting log spam while we
726        //    tear down the session.
727        // 2. Unregister the client writer from the global registry so other
728        //    parts of the system stop dispatching commands here.
729        // 3. Move the session drop to a blocking thread. `drop(session)`
730        //    cancels each subscription guard, and hyphae's per-cell
731        //    unsubscribe is O(N) in the cell's subscriber list (Vec clone +
732        //    filter + ArcSwap store), so a session with thousands of
733        //    subscriptions can take significant CPU time. Doing it on the
734        //    async runtime would block other connections' tasks; the
735        //    blocking pool is the right place for this.
736        write_task.abort();
737        command_task.abort();
738        if let Some(registry) = try_client_registry() {
739            registry.unregister(&client_id);
740        }
741
742        let drop_client_id = client_id.clone();
743        tokio::task::spawn_blocking(move || {
744            drop(session); // Drops all subscription guards
745            tracing::trace!(
746                "Client session subscriptions torn down for {}",
747                drop_client_id
748            );
749        });
750
751        // Delete Client entity
752        if let Err(e) = ctx.del(&client_entity) {
753            tracing::error!("Failed to delete client entity: {e}");
754        }
755
756        tracing::info!("Client disconnected: {} from {}", client_id, addr);
757
758        Ok(())
759    }
760
761    /// Handle a parsed MykoMessage.
762    #[allow(clippy::too_many_arguments)]
763    fn handle_message<W: WsWriter>(
764        session: &mut ClientSession<W>,
765        ctx: Arc<CellServerCtx>,
766        priority_tx: &mpsc::Sender<MykoMessage>,
767        drop_logger: &Arc<DropLogger>,
768        query_ids_by_tx: &Arc<Mutex<HashMap<Arc<str>, Arc<str>>>>,
769        view_ids_by_tx: &Arc<Mutex<HashMap<Arc<str>, Arc<str>>>>,
770        subscribe_started_by_tx: &Arc<Mutex<HashMap<Arc<str>, Instant>>>,
771        command_started_by_tx: &Arc<Mutex<HashMap<Arc<str>, Instant>>>,
772        outbound_commands_by_tx: &Arc<Mutex<HashMap<String, (String, Instant)>>>,
773        command_tx: &mpsc::UnboundedSender<CommandJob>,
774        subscribe_tx: &mpsc::UnboundedSender<SubscriptionReady>,
775        msg: MykoMessage,
776    ) -> Result<(), Box<dyn std::error::Error + Send + Sync>> {
777        // Per-message timing tap. Counts inbound messages by kind into the
778        // global instrumentation (periodic summarizer logs the deltas) and
779        // by kind+client+tag (command/query/report/view id) into an OTLP
780        // counter.
781        crate::ws_timing::record_inbound_for_client(
782            crate::ws_timing::message_kind(&msg),
783            &session.client_id,
784            crate::ws_timing::message_tag(&msg),
785        );
786
787        let handler_registry = ctx.handler_registry.clone();
788
789        let registry = ctx.registry.clone();
790
791        let host_id = ctx.host_id;
792
793        match msg {
794            MykoMessage::Query(wrapped) => {
795                // Extract tx from the query JSON
796                let tx_id: Arc<str> = wrapped
797                    .query
798                    .get("tx")
799                    .and_then(|v| v.as_str())
800                    .unwrap_or("unknown")
801                    .into();
802                let query_id = &wrapped.query_id;
803                let entity_type = &wrapped.query_item_type;
804
805                // Defensive dedupe: some clients can replay the same subscribe request.
806                // A duplicate for the same tx would reset server-side sequence/window state.
807                if session.has_subscription(&tx_id) {
808                    tracing::debug!(
809                        "Ignoring duplicate query subscribe client={} tx={} query_id={} item_type={}",
810                        session.client_id,
811                        tx_id,
812                        query_id,
813                        entity_type
814                    );
815                    return Ok(());
816                }
817                if let Ok(mut map) = query_ids_by_tx.lock() {
818                    map.insert(tx_id.clone(), query_id.clone());
819                }
820                if let Ok(mut map) = subscribe_started_by_tx.lock() {
821                    map.entry(tx_id.clone()).or_insert_with(Instant::now);
822                }
823
824                tracing::trace!("Query {} for {} (tx: {})", query_id, entity_type, tx_id);
825                tracing::trace!(
826                    "Query subscribe request client={} tx={} query_id={} item_type={} window={} active_subscriptions_before={}",
827                    session.client_id,
828                    tx_id,
829                    query_id,
830                    entity_type,
831                    wrapped.window.is_some(),
832                    session.subscription_count()
833                );
834
835                let request_context = Arc::new(RequestContext::from_client(
836                    tx_id.clone(),
837                    session.client_id.clone(),
838                    host_id,
839                ));
840
841                if let Some(query_data) = handler_registry.get_query(query_id) {
842                    let parsed = (query_data.parse)(wrapped.query.clone());
843                    match parsed {
844                        Ok(any_query) => {
845                            // NOTE(ts): Spawn cell_factory on blocking pool so it doesn't
846                            // block command processing or other messages.
847                            let cell_factory = query_data.cell_factory;
848                            let registry = registry.clone();
849                            let request_context = request_context.clone();
850                            let ctx = ctx.clone();
851                            let window = wrapped.window.clone();
852                            let query_id = query_id.clone();
853                            let sub_tx = subscribe_tx.clone();
854                            tokio::task::spawn_blocking(move || {
855                                match cell_factory(any_query, registry, request_context, Some(ctx))
856                                {
857                                    Ok(filtered_cellmap) => {
858                                        let _ = sub_tx.send(SubscriptionReady::Query {
859                                            tx_id,
860                                            query_id,
861                                            cellmap: filtered_cellmap,
862                                            window,
863                                        });
864                                    }
865                                    Err(e) => {
866                                        tracing::error!(
867                                            "Failed to create query cell for {}: {}",
868                                            query_id,
869                                            e
870                                        );
871                                    }
872                                }
873                            });
874                        }
875                        Err(e) => {
876                            tracing::error!(
877                                "Failed to parse query {}: {} | payload: {}",
878                                query_id,
879                                e,
880                                serde_json::to_string(&wrapped.query).unwrap_or_default()
881                            );
882                        }
883                    }
884                } else {
885                    // Fall back to select all for unknown queries
886                    tracing::warn!(
887                        "No registered query handler for {}, falling back to select all",
888                        query_id
889                    );
890                    let store: myko::store::EntityStore =
891                        (*registry.get_or_create(entity_type)).clone();
892                    let cellmap = hyphae::MapQuery::materialize(store.select(|_| true));
893                    session.subscribe_query(
894                        tx_id,
895                        query_id.clone(),
896                        cellmap,
897                        wrapped.window.clone(),
898                    );
899                }
900            }
901
902            MykoMessage::View(wrapped) => {
903                let tx_id: Arc<str> = wrapped
904                    .view
905                    .get("tx")
906                    .and_then(|v| v.as_str())
907                    .unwrap_or("unknown")
908                    .into();
909                let view_id = &wrapped.view_id;
910                let item_type = &wrapped.view_item_type;
911
912                // Defensive dedupe: ignore repeated subscribe for an already-active tx.
913                if session.has_subscription(&tx_id) {
914                    tracing::debug!(
915                        "Ignoring duplicate view subscribe client={} tx={} view_id={} item_type={}",
916                        session.client_id,
917                        tx_id,
918                        view_id,
919                        item_type
920                    );
921                    return Ok(());
922                }
923                if let Ok(mut map) = view_ids_by_tx.lock() {
924                    map.insert(tx_id.clone(), view_id.clone());
925                }
926                if let Ok(mut map) = subscribe_started_by_tx.lock() {
927                    map.entry(tx_id.clone()).or_insert_with(Instant::now);
928                }
929
930                tracing::trace!("View {} for {} (tx: {})", view_id, item_type, tx_id);
931                tracing::trace!(
932                    "View subscribe request client={} tx={} view_id={} item_type={} window={:?}",
933                    session.client_id,
934                    tx_id,
935                    view_id,
936                    item_type,
937                    wrapped.window
938                );
939
940                let request_context = Arc::new(RequestContext::from_client(
941                    tx_id.clone(),
942                    session.client_id.clone(),
943                    host_id,
944                ));
945
946                if let Some(view_data) = handler_registry.get_view(view_id) {
947                    let parsed = (view_data.parse)(wrapped.view.clone());
948                    match parsed {
949                        Ok(any_view) => {
950                            tracing::trace!(
951                                "View parsed successfully client={} tx={} view_id={}",
952                                session.client_id,
953                                tx_id,
954                                view_id
955                            );
956                            // NOTE(ts): Spawn cell_factory on blocking pool so it doesn't
957                            // block command processing or other messages.
958                            let cell_factory = view_data.cell_factory;
959                            let registry = registry.clone();
960                            let ctx = ctx.clone();
961                            let window = wrapped.window.clone();
962                            let view_id_clone = view_id.clone();
963                            let sub_tx = subscribe_tx.clone();
964                            let priority_tx = priority_tx.clone();
965                            let drop_logger = drop_logger.clone();
966                            tokio::task::spawn_blocking(move || {
967                                match cell_factory(any_view, registry, request_context, ctx) {
968                                    Ok(filtered_cellmap) => {
969                                        tracing::trace!(
970                                            "View cell factory succeeded tx={} view_id={}",
971                                            tx_id,
972                                            view_id_clone
973                                        );
974                                        let _ = sub_tx.send(SubscriptionReady::View {
975                                            tx_id,
976                                            view_id: view_id_clone,
977                                            cellmap: filtered_cellmap,
978                                            window,
979                                        });
980                                    }
981                                    Err(e) => {
982                                        tracing::error!(
983                                            "Failed to create view cell for {}: {}",
984                                            view_id_clone,
985                                            e
986                                        );
987                                        if let Err(err) = priority_tx.try_send(
988                                            MykoMessage::ViewError(ViewError {
989                                                tx: tx_id.to_string(),
990                                                view_id: view_id_clone.to_string(),
991                                                message: e,
992                                            }),
993                                        ) {
994                                            drop_logger.on_drop("ViewError", &err);
995                                        }
996                                    }
997                                }
998                            });
999                        }
1000                        Err(e) => {
1001                            let message = format!("Failed to parse view {}: {}", view_id, e);
1002                            tracing::error!(
1003                                "{} | payload: {}",
1004                                message,
1005                                serde_json::to_string(&wrapped.view).unwrap_or_default()
1006                            );
1007                            if let Err(err) =
1008                                priority_tx.try_send(MykoMessage::ViewError(ViewError {
1009                                    tx: tx_id.to_string(),
1010                                    view_id: view_id.to_string(),
1011                                    message,
1012                                }))
1013                            {
1014                                drop_logger.on_drop("ViewError", &err);
1015                            }
1016                        }
1017                    }
1018                } else {
1019                    let message = format!("No registered handler for view: {}", view_id);
1020                    tracing::warn!("{}", message);
1021                    if let Err(err) = priority_tx.try_send(MykoMessage::ViewError(ViewError {
1022                        tx: tx_id.to_string(),
1023                        view_id: view_id.to_string(),
1024                        message,
1025                    })) {
1026                        drop_logger.on_drop("ViewError", &err);
1027                    }
1028                }
1029            }
1030
1031            MykoMessage::QueryCancel(CancelSubscription { tx: tx_id }) => {
1032                tracing::trace!(
1033                    "QueryCancel received: client={} tx={}",
1034                    session.client_id,
1035                    tx_id
1036                );
1037                let tx_id: Arc<str> = tx_id.into();
1038                if let Ok(mut map) = query_ids_by_tx.lock() {
1039                    map.remove(&tx_id);
1040                }
1041                if let Ok(mut map) = subscribe_started_by_tx.lock() {
1042                    map.remove(&tx_id);
1043                }
1044                session.cancel(&tx_id);
1045            }
1046
1047            MykoMessage::QueryWindow(QueryWindowUpdate { tx, window }) => {
1048                let tx_id: Arc<str> = tx.into();
1049                tracing::trace!(
1050                    "Query window request client={} tx={} has_window={} active_subscriptions={}",
1051                    session.client_id,
1052                    tx_id,
1053                    window.is_some(),
1054                    session.subscription_count()
1055                );
1056                session.update_query_window(&tx_id, window);
1057            }
1058            MykoMessage::ViewCancel(CancelSubscription { tx: tx_id }) => {
1059                tracing::trace!("View cancel: {}", tx_id);
1060                let tx_id: Arc<str> = tx_id.into();
1061                if let Ok(mut map) = view_ids_by_tx.lock() {
1062                    map.remove(&tx_id);
1063                }
1064                if let Ok(mut map) = subscribe_started_by_tx.lock() {
1065                    map.remove(&tx_id);
1066                }
1067                session.cancel(&tx_id);
1068            }
1069            MykoMessage::ViewWindow(ViewWindowUpdate { tx, window }) => {
1070                let tx_id: Arc<str> = tx.into();
1071                tracing::trace!("View window update: {}", tx_id);
1072                session.update_view_window(&tx_id, window);
1073            }
1074
1075            MykoMessage::Report(wrapped) => {
1076                // Extract tx from the report JSON
1077                let tx_id: Arc<str> = wrapped
1078                    .report
1079                    .get("tx")
1080                    .and_then(|v| v.as_str())
1081                    .unwrap_or("unknown")
1082                    .into();
1083                let report_id = &wrapped.report_id;
1084
1085                tracing::trace!(
1086                    "Report subscribe request client={} tx={} report_id={} active_subscriptions_before={}",
1087                    session.client_id,
1088                    tx_id,
1089                    report_id,
1090                    session.subscription_count()
1091                );
1092
1093                // Look up the report registration
1094                if let Some(report_data) = handler_registry.get_report(report_id) {
1095                    // Parse the report JSON to the concrete type
1096                    let parsed = (report_data.parse)(wrapped.report.clone());
1097                    match parsed {
1098                        Ok(any_report) => {
1099                            let request_context = Arc::new(RequestContext::from_client(
1100                                tx_id.clone(),
1101                                session.client_id.clone(),
1102                                host_id,
1103                            ));
1104
1105                            // Create the cell using the factory (with host_id for context)
1106                            match (report_data.cell_factory)(any_report, request_context, ctx) {
1107                                Ok(cell) => {
1108                                    session.subscribe_report(
1109                                        tx_id,
1110                                        report_id.as_str().into(),
1111                                        cell,
1112                                    );
1113                                }
1114                                Err(e) => {
1115                                    tracing::error!(
1116                                        "Failed to create report cell for {}: {}",
1117                                        report_id,
1118                                        e
1119                                    );
1120                                }
1121                            }
1122                        }
1123                        Err(e) => {
1124                            tracing::error!(
1125                                "Failed to parse report {}: {} | payload: {}",
1126                                report_id,
1127                                e,
1128                                serde_json::to_string(&wrapped.report).unwrap_or_default()
1129                            );
1130                        }
1131                    }
1132                } else {
1133                    tracing::warn!("No registered handler for report: {}", report_id);
1134                }
1135            }
1136
1137            MykoMessage::ReportCancel(CancelSubscription { tx: tx_id }) => {
1138                tracing::trace!(
1139                    "ReportCancel received: client={} tx={} active_subscriptions_before={}",
1140                    session.client_id,
1141                    tx_id,
1142                    session.subscription_count()
1143                );
1144                session.cancel(&tx_id.into());
1145            }
1146
1147            MykoMessage::Event(mut event) => {
1148                event.sanitize_null_bytes();
1149                normalize_incoming_event(&mut event, &session.client_id, host_id);
1150                if let Err(e) = ctx.apply_event(event) {
1151                    tracing::error!(
1152                        "Failed to apply event from client {}: {e}",
1153                        session.client_id
1154                    );
1155                }
1156            }
1157
1158            MykoMessage::EventBatch(mut events) => {
1159                let incoming = events.len();
1160                if incoming >= 64 {
1161                    tracing::trace!(
1162                        "Received event batch from client {} size={}",
1163                        session.client_id,
1164                        incoming
1165                    );
1166                }
1167                for event in &mut events {
1168                    event.sanitize_null_bytes();
1169                    normalize_incoming_event(event, &session.client_id, host_id);
1170                }
1171                match ctx.apply_event_batch(events) {
1172                    Ok(applied) => {
1173                        tracing::trace!(
1174                            "Applied event batch from client {} size={}",
1175                            session.client_id,
1176                            applied
1177                        );
1178                    }
1179                    Err(e) => {
1180                        tracing::error!(
1181                            "Failed to apply event batch from client {}: {}",
1182                            session.client_id,
1183                            e
1184                        );
1185                    }
1186                }
1187            }
1188
1189            MykoMessage::Command(wrapped) => {
1190                // Extract tx from the command JSON
1191                let tx_id: Arc<str> = wrapped
1192                    .command
1193                    .get("tx")
1194                    .and_then(|v| v.as_str())
1195                    .unwrap_or("unknown")
1196                    .into();
1197
1198                let command_id = &wrapped.command_id;
1199
1200                tracing::trace!("Command {} (tx: {})", command_id, tx_id,);
1201                let received_at = Instant::now();
1202                if let Ok(mut map) = command_started_by_tx.lock() {
1203                    map.insert(tx_id.clone(), received_at);
1204                }
1205                if let Err(e) = command_tx.send(CommandJob {
1206                    tx_id: tx_id.clone(),
1207                    command_id: wrapped.command_id.clone(),
1208                    command: wrapped.command.clone(),
1209                    received_at,
1210                }) {
1211                    tracing::error!(
1212                        "Failed to enqueue command {} for client {} tx={}: {}",
1213                        command_id,
1214                        session.client_id,
1215                        tx_id,
1216                        e
1217                    );
1218                    let error = MykoMessage::CommandError(CommandError {
1219                        tx: tx_id.to_string(),
1220                        command_id: command_id.to_string(),
1221                        message: "Command queue unavailable".to_string(),
1222                    });
1223                    if let Err(err) = priority_tx.try_send(error) {
1224                        drop_logger.on_drop("CommandError", &err);
1225                    }
1226                }
1227            }
1228
1229            MykoMessage::Ping(PingData { id, timestamp }) => {
1230                // Echo back the ping data
1231                let pong = MykoMessage::Ping(PingData { id, timestamp });
1232                if let Err(e) = priority_tx.try_send(pong) {
1233                    drop_logger.on_drop("Ping", &e);
1234                }
1235            }
1236
1237            // Response messages - these shouldn't come from clients.
1238            MykoMessage::QueryResponse(resp) => {
1239                tracing::warn!(
1240                    "Unexpected client message kind=query_response client={} tx={} seq={} upserts={} deletes={} active_subscriptions={}",
1241                    session.client_id,
1242                    resp.tx,
1243                    resp.sequence,
1244                    resp.upserts.len(),
1245                    resp.deletes.len(),
1246                    session.subscription_count()
1247                );
1248            }
1249            MykoMessage::QueryError(err) => {
1250                tracing::warn!(
1251                    "Unexpected client message kind=query_error client={} tx={} query_id={} message={} active_subscriptions={}",
1252                    session.client_id,
1253                    err.tx,
1254                    err.query_id,
1255                    err.message,
1256                    session.subscription_count()
1257                );
1258            }
1259            MykoMessage::ViewResponse(resp) => {
1260                tracing::warn!(
1261                    "Unexpected client message kind=view_response client={} tx={} seq={} upserts={} deletes={} active_subscriptions={}",
1262                    session.client_id,
1263                    resp.tx,
1264                    resp.sequence,
1265                    resp.upserts.len(),
1266                    resp.deletes.len(),
1267                    session.subscription_count()
1268                );
1269            }
1270            MykoMessage::ViewError(err) => {
1271                tracing::warn!(
1272                    "Unexpected client message kind=view_error client={} tx={} view_id={} message={} active_subscriptions={}",
1273                    session.client_id,
1274                    err.tx,
1275                    err.view_id,
1276                    err.message,
1277                    session.subscription_count()
1278                );
1279            }
1280            MykoMessage::ReportResponse(resp) => {
1281                tracing::warn!(
1282                    "Unexpected client message kind=report_response client={} tx={} active_subscriptions={}",
1283                    session.client_id,
1284                    resp.tx,
1285                    session.subscription_count()
1286                );
1287            }
1288            MykoMessage::ReportError(err) => {
1289                tracing::warn!(
1290                    "Unexpected client message kind=report_error client={} tx={} report_id={} message={} active_subscriptions={}",
1291                    session.client_id,
1292                    err.tx,
1293                    err.report_id,
1294                    err.message,
1295                    session.subscription_count()
1296                );
1297            }
1298            MykoMessage::CommandResponse(resp) => {
1299                if resp.tx.trim().is_empty() {
1300                    tracing::warn!(
1301                        "Malformed client message kind=command_response client={} tx=<empty> active_subscriptions={}",
1302                        session.client_id,
1303                        session.subscription_count()
1304                    );
1305                } else {
1306                    let correlated = outbound_commands_by_tx
1307                        .lock()
1308                        .ok()
1309                        .and_then(|mut map| map.remove(&resp.tx));
1310                    if let Some((command_id, started)) = correlated {
1311                        // Success-path per-command roundtrip detail: fires once
1312                        // per correlated command response (ExecTargetAction etc.),
1313                        // tens of thousands per second under load. Keep at trace;
1314                        // the unmatched/error paths below stay at warn.
1315                        tracing::trace!(
1316                            "Client command response matched outbound command client={} tx={} command_id={} roundtrip_ms={} active_subscriptions={}",
1317                            session.client_id,
1318                            resp.tx,
1319                            command_id,
1320                            started.elapsed().as_millis(),
1321                            session.subscription_count()
1322                        );
1323                    } else {
1324                        tracing::warn!(
1325                            "Client command response without outbound match client={} tx={} active_subscriptions={}",
1326                            session.client_id,
1327                            resp.tx,
1328                            session.subscription_count()
1329                        );
1330                    }
1331                }
1332            }
1333            MykoMessage::CommandError(err) => {
1334                if err.tx.trim().is_empty() {
1335                    tracing::warn!(
1336                        "Malformed client message kind=command_error client={} tx=<empty> command_id={} message={} active_subscriptions={}",
1337                        session.client_id,
1338                        err.command_id,
1339                        err.message,
1340                        session.subscription_count()
1341                    );
1342                } else {
1343                    let correlated = outbound_commands_by_tx
1344                        .lock()
1345                        .ok()
1346                        .and_then(|mut map| map.remove(&err.tx));
1347                    if let Some((command_id, started)) = correlated {
1348                        tracing::warn!(
1349                            "Client command error matched outbound command client={} tx={} command_id={} transport_command_id={} message={} roundtrip_ms={} active_subscriptions={}",
1350                            session.client_id,
1351                            err.tx,
1352                            err.command_id,
1353                            command_id,
1354                            err.message,
1355                            started.elapsed().as_millis(),
1356                            session.subscription_count()
1357                        );
1358                    } else {
1359                        tracing::warn!(
1360                            "Client command error without outbound match client={} tx={} command_id={} message={} active_subscriptions={}",
1361                            session.client_id,
1362                            err.tx,
1363                            err.command_id,
1364                            err.message,
1365                            session.subscription_count()
1366                        );
1367                    }
1368                }
1369            }
1370            MykoMessage::Benchmark(payload) => {
1371                let stats = ws_benchmark_stats();
1372                ensure_ws_benchmark_logger();
1373                stats.message_count.fetch_add(1, Ordering::Relaxed);
1374                // Estimate payload size from the JSON value
1375                let size = payload.to_string().len() as u64;
1376                stats.total_bytes.fetch_add(size, Ordering::Relaxed);
1377            }
1378        }
1379
1380        Ok(())
1381    }
1382
1383    fn execute_command_job(
1384        ctx: Arc<CellServerCtx>,
1385        priority_tx: &mpsc::Sender<MykoMessage>,
1386        drop_logger: &DropLogger,
1387        client_id: Arc<str>,
1388        job: CommandJob,
1389    ) {
1390        let host_id = ctx.host_id;
1391        let started = Instant::now();
1392        let queue_wait_ms = started.duration_since(job.received_at).as_millis();
1393        let command_id = job.command_id.clone();
1394
1395        let mut handler_found = false;
1396        for registration in inventory::iter::<CommandHandlerRegistration> {
1397            if registration.command_id == command_id {
1398                handler_found = true;
1399                let executor = (registration.factory)();
1400
1401                let req = Arc::new(RequestContext::from_client(
1402                    job.tx_id.clone(),
1403                    client_id.clone(),
1404                    host_id,
1405                ));
1406                let cmd_id: Arc<str> = Arc::from(command_id.clone());
1407                let cmd_ctx = CommandContext::new(cmd_id, req, ctx.clone());
1408                let execute_started = Instant::now();
1409
1410                match executor.execute_from_value(job.command.clone(), cmd_ctx) {
1411                    Ok(result) => {
1412                        let response = MykoMessage::CommandResponse(CommandResponse {
1413                            response: result,
1414                            tx: job.tx_id.to_string(),
1415                        });
1416                        if let Err(e) = priority_tx.try_send(response) {
1417                            drop_logger.on_drop("CommandResponse", &e);
1418                        }
1419                    }
1420                    Err(e) => {
1421                        let error = MykoMessage::CommandError(CommandError {
1422                            tx: job.tx_id.to_string(),
1423                            command_id: command_id.clone(),
1424                            message: e.message,
1425                        });
1426                        if let Err(err) = priority_tx.try_send(error) {
1427                            drop_logger.on_drop("CommandError", &err);
1428                        }
1429                    }
1430                }
1431                let execute_ms = execute_started.elapsed().as_millis();
1432                let total_ms = job.received_at.elapsed().as_millis();
1433                tracing::trace!(
1434                    target: "myko_server::ws_perf",
1435                    "command_exec client={} tx={} command_id={} queue_wait_ms={} execute_ms={} total_ms={}",
1436                    client_id,
1437                    job.tx_id,
1438                    command_id,
1439                    queue_wait_ms,
1440                    execute_ms,
1441                    total_ms
1442                );
1443                break;
1444            }
1445        }
1446
1447        if !handler_found {
1448            tracing::warn!("No registered handler for command: {}", command_id);
1449            let error = MykoMessage::CommandError(CommandError {
1450                tx: job.tx_id.to_string(),
1451                command_id: command_id.clone(),
1452                message: format!("Command handler not found: {}", command_id),
1453            });
1454            if let Err(e) = priority_tx.try_send(error) {
1455                drop_logger.on_drop("CommandError", &e);
1456            }
1457        }
1458
1459        if !handler_found {
1460            tracing::debug!(
1461                target: "myko_server::ws_perf",
1462                "command_exec client={} tx={} command_id={} queue_wait_ms={} execute_ms=0 total_ms={} handler_found=false",
1463                client_id,
1464                job.tx_id,
1465                command_id,
1466                queue_wait_ms,
1467                job.received_at.elapsed().as_millis()
1468            );
1469        }
1470    }
1471}
1472
1473/// Channel-based WebSocket writer.
1474///
1475/// Sends messages through an mpsc channel which are then
1476/// forwarded to the actual WebSocket.
1477struct ChannelWriter {
1478    tx: mpsc::Sender<OutboundMessage>,
1479    deferred_tx: mpsc::Sender<DeferredOutbound>,
1480    drop_logger: Arc<DropLogger>,
1481    outgoing_format: Arc<AtomicU8>,
1482}
1483
1484impl ChannelWriter {
1485    /// Cheap "is the writer task gone?" check used to short-circuit
1486    /// subscriber callbacks for a disconnected client. `Sender::is_closed`
1487    /// returns true once the matching receiver is dropped, which happens as
1488    /// soon as the write task exits. Avoiding the work here prevents the
1489    /// "buffer full / channel closed" log storm we used to see for 10+
1490    /// seconds after every disconnect while the session was still tearing
1491    /// down its subscription guards.
1492    #[inline]
1493    fn tx_dead(&self) -> bool {
1494        self.tx.is_closed()
1495    }
1496
1497    #[inline]
1498    fn deferred_dead(&self) -> bool {
1499        self.deferred_tx.is_closed()
1500    }
1501}
1502
1503impl WsWriter for ChannelWriter {
1504    fn send(&self, msg: MykoMessage) {
1505        // Fast path: writer is gone. Don't try to send and don't log; the
1506        // dead-channel state is expected after the client disconnects, and
1507        // a dropped subscription will follow shortly when the session
1508        // teardown finishes. Avoiding the log+counter prevents the
1509        // "buffer full / channel closed" warning storm we used to see for
1510        // 10+ seconds after every disconnect.
1511        if self.tx_dead() {
1512            return;
1513        }
1514        if let Err(e) = self.tx.try_send(OutboundMessage::Message(msg)) {
1515            // Closed errors here race with the writer task exiting between
1516            // the is_dead check and the try_send; suppress them too.
1517            if !matches!(e, mpsc::error::TrySendError::Closed(_)) {
1518                self.drop_logger.on_drop("message", &e);
1519            }
1520        }
1521    }
1522
1523    fn protocol(&self) -> MykoProtocol {
1524        MykoProtocol::from(self.outgoing_format.load(Ordering::SeqCst))
1525    }
1526
1527    fn send_serialized_command(
1528        &self,
1529        tx: Arc<str>,
1530        command_id: String,
1531        payload: EncodedCommandMessage,
1532    ) {
1533        if self.tx_dead() {
1534            return;
1535        }
1536        if let Err(e) = self.tx.try_send(OutboundMessage::SerializedCommand {
1537            tx,
1538            command_id,
1539            payload,
1540        }) && !matches!(e, mpsc::error::TrySendError::Closed(_))
1541        {
1542            self.drop_logger.on_drop("serialized_command", &e);
1543        }
1544    }
1545
1546    fn send_report_response(&self, tx: Arc<str>, output: Arc<dyn AnyOutput>) {
1547        if self.deferred_dead() {
1548            return;
1549        }
1550        if let Err(e) = self
1551            .deferred_tx
1552            .try_send(DeferredOutbound::Report(tx, output))
1553            && !matches!(e, mpsc::error::TrySendError::Closed(_))
1554        {
1555            self.drop_logger.on_drop("ReportResponseDeferred", &e);
1556        }
1557    }
1558
1559    fn send_query_response(&self, response: PendingQueryResponse, is_view: bool) {
1560        if self.deferred_dead() {
1561            return;
1562        }
1563        if let Err(e) = self
1564            .deferred_tx
1565            .try_send(DeferredOutbound::Query { response, is_view })
1566            && !matches!(e, mpsc::error::TrySendError::Closed(_))
1567        {
1568            self.drop_logger.on_drop("QueryResponseDeferred", &e);
1569        }
1570    }
1571}
1572
1573#[cfg(test)]
1574mod tests {
1575    use super::*;
1576
1577    #[test]
1578    fn test_channel_writer() {
1579        let (tx, mut rx) = mpsc::channel(10);
1580        let (deferred_tx, _deferred_rx) = mpsc::channel(10);
1581        let drop_logger = Arc::new(DropLogger::new("test-client".into()));
1582        let writer = ChannelWriter {
1583            tx,
1584            deferred_tx,
1585            drop_logger,
1586            outgoing_format: Arc::new(AtomicU8::new(MykoProtocol::JSON as u8)),
1587        };
1588
1589        let msg = MykoMessage::Ping(PingData {
1590            id: "test".to_string(),
1591            timestamp: 0,
1592        });
1593        writer.send(msg);
1594
1595        let received = rx.try_recv().unwrap();
1596        assert!(matches!(
1597            received,
1598            OutboundMessage::Message(MykoMessage::Ping(_))
1599        ));
1600    }
1601
1602    #[test]
1603    fn outgoing_format_starts_as_json_and_promotes_to_cbor() {
1604        use std::sync::atomic::{AtomicU8, Ordering};
1605
1606        let outgoing_format = AtomicU8::new(MykoProtocol::JSON as u8);
1607
1608        // Initially JSON.
1609        assert_eq!(
1610            MykoProtocol::from(outgoing_format.load(Ordering::SeqCst)),
1611            MykoProtocol::JSON,
1612        );
1613
1614        // Simulate receiving a binary frame: promote.
1615        outgoing_format.store(MykoProtocol::CBOR as u8, Ordering::SeqCst);
1616        assert_eq!(
1617            MykoProtocol::from(outgoing_format.load(Ordering::SeqCst)),
1618            MykoProtocol::CBOR,
1619        );
1620
1621        // Simulate receiving more text frames after promotion: no change.
1622        // (The handler in the read loop only writes on Binary, never on Text,
1623        // so this is a no-op assertion that the field's last-write-wins
1624        // semantics give us stickiness for free.)
1625        assert_eq!(
1626            MykoProtocol::from(outgoing_format.load(Ordering::SeqCst)),
1627            MykoProtocol::CBOR,
1628        );
1629    }
1630}