refactor(api,agent): migrate libs/api room ws and libs/agent client to tracing
- api/room/ws.rs, ws_universal.rs: replace slog macros with tracing - agent/client.rs: replace slog macros with tracing for AI retry logs
This commit is contained in:
parent
236aebe4ea
commit
c850adb4eb
@ -14,22 +14,19 @@ use async_openai::types::chat::{
|
|||||||
use std::time::Instant;
|
use std::time::Instant;
|
||||||
|
|
||||||
use crate::error::{AgentError, Result};
|
use crate::error::{AgentError, Result};
|
||||||
use slog::warn;
|
|
||||||
|
|
||||||
/// Configuration for the AI client.
|
/// Configuration for the AI client.
|
||||||
#[derive(Clone)]
|
#[derive(Clone)]
|
||||||
pub struct AiClientConfig {
|
pub struct AiClientConfig {
|
||||||
pub api_key: String,
|
pub api_key: String,
|
||||||
pub base_url: Option<String>,
|
pub base_url: Option<String>,
|
||||||
pub logger: slog::Logger,
|
|
||||||
}
|
}
|
||||||
|
|
||||||
impl AiClientConfig {
|
impl AiClientConfig {
|
||||||
pub fn new(api_key: String, logger: slog::Logger) -> Self {
|
pub fn new(api_key: String) -> Self {
|
||||||
Self {
|
Self {
|
||||||
api_key,
|
api_key,
|
||||||
base_url: None,
|
base_url: None,
|
||||||
logger,
|
|
||||||
}
|
}
|
||||||
}
|
}
|
||||||
|
|
||||||
@ -175,12 +172,13 @@ pub async fn call_with_retry(
|
|||||||
Err(err) => {
|
Err(err) => {
|
||||||
if state.should_retry() && is_retryable_error(&err) {
|
if state.should_retry() && is_retryable_error(&err) {
|
||||||
let duration = state.backoff_duration();
|
let duration = state.backoff_duration();
|
||||||
warn!(config.logger, "ai_call_retry";
|
tracing::warn!(
|
||||||
"attempt" => state.attempt + 1,
|
attempt = state.attempt + 1,
|
||||||
"max_retries" => state.max_retries,
|
max_retries = state.max_retries,
|
||||||
"backoff_ms" => duration.as_millis() as u64,
|
backoff_ms = duration.as_millis() as u64,
|
||||||
"model" => %model,
|
model = %model,
|
||||||
"error" => %err.to_string()
|
error = %err.to_string(),
|
||||||
|
"ai_call_retry"
|
||||||
);
|
);
|
||||||
tokio::time::sleep(duration).await;
|
tokio::time::sleep(duration).await;
|
||||||
state.next();
|
state.next();
|
||||||
@ -243,12 +241,13 @@ pub async fn call_with_params(
|
|||||||
Err(err) => {
|
Err(err) => {
|
||||||
if state.should_retry() && is_retryable_error(&err) {
|
if state.should_retry() && is_retryable_error(&err) {
|
||||||
let duration = state.backoff_duration();
|
let duration = state.backoff_duration();
|
||||||
warn!(config.logger, "ai_call_retry";
|
tracing::warn!(
|
||||||
"attempt" => state.attempt + 1,
|
attempt = state.attempt + 1,
|
||||||
"max_retries" => state.max_retries,
|
max_retries = state.max_retries,
|
||||||
"backoff_ms" => duration.as_millis() as u64,
|
backoff_ms = duration.as_millis() as u64,
|
||||||
"model" => %model,
|
model = %model,
|
||||||
"error" => %err.to_string()
|
error = %err.to_string(),
|
||||||
|
"ai_call_retry"
|
||||||
);
|
);
|
||||||
tokio::time::sleep(duration).await;
|
tokio::time::sleep(duration).await;
|
||||||
state.next();
|
state.next();
|
||||||
|
|||||||
@ -31,11 +31,11 @@ async fn authenticate_ws_request(
|
|||||||
}) {
|
}) {
|
||||||
match service.ws_token.validate_token(token).await {
|
match service.ws_token.validate_token(token).await {
|
||||||
Ok(uid) => {
|
Ok(uid) => {
|
||||||
slog::debug!(service.logs, "WS: token auth successful for uid={}", uid);
|
tracing::debug!(uid = %uid, "WS: token auth successful");
|
||||||
return Ok(uid);
|
return Ok(uid);
|
||||||
}
|
}
|
||||||
Err(_) => {
|
Err(_) => {
|
||||||
slog::warn!(service.logs, "WS: token auth failed");
|
tracing::warn!("WS: token auth failed");
|
||||||
service
|
service
|
||||||
.room
|
.room
|
||||||
.room_manager
|
.room_manager
|
||||||
@ -64,7 +64,6 @@ async fn authenticate_ws_request(
|
|||||||
}
|
}
|
||||||
|
|
||||||
async fn check_ws_rate_limit(
|
async fn check_ws_rate_limit(
|
||||||
log: &slog::Logger,
|
|
||||||
manager: &Arc<room::connection::RoomConnectionManager>,
|
manager: &Arc<room::connection::RoomConnectionManager>,
|
||||||
message_count: &mut u32,
|
message_count: &mut u32,
|
||||||
rate_window_start: &mut Instant,
|
rate_window_start: &mut Instant,
|
||||||
@ -75,7 +74,7 @@ async fn check_ws_rate_limit(
|
|||||||
}
|
}
|
||||||
*message_count += 1;
|
*message_count += 1;
|
||||||
if *message_count > MAX_MESSAGES_PER_SECOND {
|
if *message_count > MAX_MESSAGES_PER_SECOND {
|
||||||
slog::warn!(log, "WS rate limit exceeded");
|
tracing::warn!("WS rate limit exceeded");
|
||||||
manager.metrics.ws_rate_limit_hits.increment(1);
|
manager.metrics.ws_rate_limit_hits.increment(1);
|
||||||
true
|
true
|
||||||
} else {
|
} else {
|
||||||
@ -351,21 +350,19 @@ pub async fn ws_room(
|
|||||||
.get("origin")
|
.get("origin")
|
||||||
.and_then(|v| v.to_str().ok())
|
.and_then(|v| v.to_str().ok())
|
||||||
.unwrap_or("(none)");
|
.unwrap_or("(none)");
|
||||||
slog::debug!(
|
tracing::debug!(
|
||||||
service.logs,
|
user_id = %user_id,
|
||||||
"WS room connection attempt user_id={} room_id={} origin={}",
|
room_id = %room_id,
|
||||||
user_id,
|
origin = %origin_val,
|
||||||
room_id,
|
"WS room connection attempt"
|
||||||
origin_val
|
|
||||||
);
|
);
|
||||||
|
|
||||||
if !validate_origin(&req) {
|
if !validate_origin(&req) {
|
||||||
slog::warn!(
|
tracing::warn!(
|
||||||
service.logs,
|
user_id = %user_id,
|
||||||
"WS room: origin rejected user_id={} room_id={} origin={}",
|
room_id = %room_id,
|
||||||
user_id,
|
origin = %origin_val,
|
||||||
room_id,
|
"WS room: origin rejected"
|
||||||
origin_val
|
|
||||||
);
|
);
|
||||||
service
|
service
|
||||||
.room
|
.room
|
||||||
@ -380,12 +377,11 @@ pub async fn ws_room(
|
|||||||
}
|
}
|
||||||
|
|
||||||
if let Err(e) = service.room.check_room_access(room_id, user_id).await {
|
if let Err(e) = service.room.check_room_access(room_id, user_id).await {
|
||||||
slog::warn!(
|
tracing::warn!(
|
||||||
service.logs,
|
user_id = %user_id,
|
||||||
"WS room: access denied for user_id={} room_id={} error={}",
|
room_id = %room_id,
|
||||||
user_id,
|
error = ?e,
|
||||||
room_id,
|
"WS room: access denied"
|
||||||
e
|
|
||||||
);
|
);
|
||||||
return Err(crate::error::ApiError::from(e).into());
|
return Err(crate::error::ApiError::from(e).into());
|
||||||
}
|
}
|
||||||
@ -401,7 +397,7 @@ pub async fn ws_room(
|
|||||||
let mut receiver = match manager.subscribe(room_id, user_id).await {
|
let mut receiver = match manager.subscribe(room_id, user_id).await {
|
||||||
Ok(r) => r,
|
Ok(r) => r,
|
||||||
Err(e) => {
|
Err(e) => {
|
||||||
slog::error!(service.logs, "Failed to subscribe to room: {}", e);
|
tracing::error!(error = ?e, "Failed to subscribe to room");
|
||||||
return;
|
return;
|
||||||
}
|
}
|
||||||
};
|
};
|
||||||
@ -420,14 +416,14 @@ pub async fn ws_room(
|
|||||||
tokio::select! {
|
tokio::select! {
|
||||||
_ = heartbeat_interval.tick() => {
|
_ = heartbeat_interval.tick() => {
|
||||||
if last_heartbeat.elapsed() > HEARTBEAT_TIMEOUT {
|
if last_heartbeat.elapsed() > HEARTBEAT_TIMEOUT {
|
||||||
slog::warn!(service.logs, "WS room {} heartbeat timeout for user {}", room_id, user_id);
|
tracing::warn!(room_id = %room_id, user_id = %user_id, "WS room heartbeat timeout");
|
||||||
manager.metrics.ws_heartbeat_timeout_total.increment(1);
|
manager.metrics.ws_heartbeat_timeout_total.increment(1);
|
||||||
let _ = session.close(Some(actix_ws::CloseCode::Policy.into())).await;
|
let _ = session.close(Some(actix_ws::CloseCode::Policy.into())).await;
|
||||||
break;
|
break;
|
||||||
}
|
}
|
||||||
|
|
||||||
if last_activity.elapsed() > MAX_IDLE_TIMEOUT {
|
if last_activity.elapsed() > MAX_IDLE_TIMEOUT {
|
||||||
slog::info!(service.logs, "WS room {} idle timeout for user {}", room_id, user_id);
|
tracing::info!(room_id = %room_id, user_id = %user_id, "WS room idle timeout");
|
||||||
manager.metrics.ws_idle_timeout_total.increment(1);
|
manager.metrics.ws_idle_timeout_total.increment(1);
|
||||||
let _ = session.close(Some(actix_ws::CloseCode::Normal.into())).await;
|
let _ = session.close(Some(actix_ws::CloseCode::Normal.into())).await;
|
||||||
break;
|
break;
|
||||||
@ -439,7 +435,7 @@ pub async fn ws_room(
|
|||||||
manager.metrics.ws_heartbeat_sent_total.increment(1);
|
manager.metrics.ws_heartbeat_sent_total.increment(1);
|
||||||
}
|
}
|
||||||
_ = shutdown_rx.recv() => {
|
_ = shutdown_rx.recv() => {
|
||||||
slog::info!(service.logs, "WS room {} shutdown", room_id);
|
tracing::info!(room_id = %room_id, "WS room shutdown");
|
||||||
let _ = session.close(Some(actix_ws::CloseCode::Normal.into())).await;
|
let _ = session.close(Some(actix_ws::CloseCode::Normal.into())).await;
|
||||||
break;
|
break;
|
||||||
}
|
}
|
||||||
@ -457,13 +453,13 @@ pub async fn ws_room(
|
|||||||
#[allow(unused_assignments)]
|
#[allow(unused_assignments)]
|
||||||
Some(Ok(WsMessage::Text(text))) => {
|
Some(Ok(WsMessage::Text(text))) => {
|
||||||
if last_activity.elapsed() > MAX_IDLE_TIMEOUT {
|
if last_activity.elapsed() > MAX_IDLE_TIMEOUT {
|
||||||
slog::info!(service.logs, "WS room {} idle timeout for user {}", room_id, user_id);
|
tracing::info!(room_id = %room_id, user_id = %user_id, "WS room idle timeout");
|
||||||
manager.metrics.ws_idle_timeout_total.increment(1);
|
manager.metrics.ws_idle_timeout_total.increment(1);
|
||||||
let _ = session.close(Some(actix_ws::CloseCode::Normal.into())).await;
|
let _ = session.close(Some(actix_ws::CloseCode::Normal.into())).await;
|
||||||
break;
|
break;
|
||||||
}
|
}
|
||||||
last_activity = Instant::now();
|
last_activity = Instant::now();
|
||||||
if check_ws_rate_limit(&service.logs, &manager, &mut message_count, &mut rate_window_start).await {
|
if check_ws_rate_limit(&manager, &mut message_count, &mut rate_window_start).await {
|
||||||
let _ = session.text(serde_json::json!({
|
let _ = session.text(serde_json::json!({
|
||||||
"type": "error",
|
"type": "error",
|
||||||
"error": "rate_limit_exceeded",
|
"error": "rate_limit_exceeded",
|
||||||
@ -473,7 +469,7 @@ pub async fn ws_room(
|
|||||||
}
|
}
|
||||||
|
|
||||||
if text.len() > MAX_TEXT_MESSAGE_LEN {
|
if text.len() > MAX_TEXT_MESSAGE_LEN {
|
||||||
slog::warn!(service.logs, "WS room {} message too long from user {}: {} bytes", room_id, user_id, text.len());
|
tracing::warn!(room_id = %room_id, user_id = %user_id, bytes = text.len(), "WS room message too long");
|
||||||
let _ = session.text(serde_json::json!({
|
let _ = session.text(serde_json::json!({
|
||||||
"type": "error",
|
"type": "error",
|
||||||
"error": "message_too_long",
|
"error": "message_too_long",
|
||||||
@ -482,7 +478,7 @@ pub async fn ws_room(
|
|||||||
break;
|
break;
|
||||||
}
|
}
|
||||||
|
|
||||||
slog::warn!(service.logs, "WS room {} unexpected text message from user {} ({} bytes) — WS is push-only, use REST to send messages", room_id, user_id, text.len());
|
tracing::warn!(room_id = %room_id, user_id = %user_id, bytes = text.len(), "WS room unexpected text message — WS is push-only, use REST to send messages");
|
||||||
let _ = session.text(serde_json::json!({
|
let _ = session.text(serde_json::json!({
|
||||||
"type": "error",
|
"type": "error",
|
||||||
"error": "ws_push_only",
|
"error": "ws_push_only",
|
||||||
@ -491,10 +487,10 @@ pub async fn ws_room(
|
|||||||
break;
|
break;
|
||||||
}
|
}
|
||||||
Some(Ok(WsMessage::Binary(_))) => {
|
Some(Ok(WsMessage::Binary(_))) => {
|
||||||
if check_ws_rate_limit(&service.logs, &manager, &mut message_count, &mut rate_window_start).await {
|
if check_ws_rate_limit(&manager, &mut message_count, &mut rate_window_start).await {
|
||||||
break;
|
break;
|
||||||
}
|
}
|
||||||
slog::warn!(service.logs, "WS room {} unexpected binary from user {}", room_id, user_id);
|
tracing::warn!(room_id = %room_id, user_id = %user_id, "WS room unexpected binary");
|
||||||
break;
|
break;
|
||||||
}
|
}
|
||||||
Some(Ok(WsMessage::Close(reason))) => {
|
Some(Ok(WsMessage::Close(reason))) => {
|
||||||
@ -503,7 +499,7 @@ pub async fn ws_room(
|
|||||||
}
|
}
|
||||||
Some(Ok(_)) => {}
|
Some(Ok(_)) => {}
|
||||||
Some(Err(e)) => {
|
Some(Err(e)) => {
|
||||||
slog::warn!(service.logs, "WS room error: {}", e);
|
tracing::warn!(error = ?e, "WS room error");
|
||||||
break;
|
break;
|
||||||
}
|
}
|
||||||
None => break,
|
None => break,
|
||||||
@ -525,7 +521,7 @@ pub async fn ws_room(
|
|||||||
}
|
}
|
||||||
}
|
}
|
||||||
Err(e) => {
|
Err(e) => {
|
||||||
slog::error!(service.logs, "WS serialize error: {}", e);
|
tracing::error!(error = ?e, "WS serialize error");
|
||||||
break;
|
break;
|
||||||
}
|
}
|
||||||
}
|
}
|
||||||
@ -549,7 +545,7 @@ pub async fn ws_room(
|
|||||||
}
|
}
|
||||||
}
|
}
|
||||||
Err(e) => {
|
Err(e) => {
|
||||||
slog::error!(service.logs, "WS streaming serialize error: {}", e);
|
tracing::error!(error = ?e, "WS streaming serialize error");
|
||||||
}
|
}
|
||||||
}
|
}
|
||||||
}
|
}
|
||||||
@ -627,7 +623,7 @@ pub async fn ws_project(
|
|||||||
let mut receiver = match manager.subscribe_project(project_id, user_id).await {
|
let mut receiver = match manager.subscribe_project(project_id, user_id).await {
|
||||||
Ok(r) => r,
|
Ok(r) => r,
|
||||||
Err(e) => {
|
Err(e) => {
|
||||||
slog::error!(service.logs, "Failed to subscribe to project: {}", e);
|
tracing::error!(error = ?e, "Failed to subscribe to project");
|
||||||
return;
|
return;
|
||||||
}
|
}
|
||||||
};
|
};
|
||||||
@ -645,14 +641,14 @@ pub async fn ws_project(
|
|||||||
tokio::select! {
|
tokio::select! {
|
||||||
_ = heartbeat_interval.tick() => {
|
_ = heartbeat_interval.tick() => {
|
||||||
if last_heartbeat.elapsed() > HEARTBEAT_TIMEOUT {
|
if last_heartbeat.elapsed() > HEARTBEAT_TIMEOUT {
|
||||||
slog::warn!(service.logs, "WS project {} heartbeat timeout for user {}", project_id, user_id);
|
tracing::warn!(project_id = %project_id, user_id = %user_id, "WS project heartbeat timeout");
|
||||||
manager.metrics.ws_heartbeat_timeout_total.increment(1);
|
manager.metrics.ws_heartbeat_timeout_total.increment(1);
|
||||||
let _ = session.close(Some(actix_ws::CloseCode::Policy.into())).await;
|
let _ = session.close(Some(actix_ws::CloseCode::Policy.into())).await;
|
||||||
break;
|
break;
|
||||||
}
|
}
|
||||||
|
|
||||||
if last_activity.elapsed() > MAX_IDLE_TIMEOUT {
|
if last_activity.elapsed() > MAX_IDLE_TIMEOUT {
|
||||||
slog::info!(service.logs, "WS project {} idle timeout for user {}", project_id, user_id);
|
tracing::info!(project_id = %project_id, user_id = %user_id, "WS project idle timeout");
|
||||||
manager.metrics.ws_idle_timeout_total.increment(1);
|
manager.metrics.ws_idle_timeout_total.increment(1);
|
||||||
let _ = session.close(Some(actix_ws::CloseCode::Normal.into())).await;
|
let _ = session.close(Some(actix_ws::CloseCode::Normal.into())).await;
|
||||||
break;
|
break;
|
||||||
@ -664,7 +660,7 @@ pub async fn ws_project(
|
|||||||
manager.metrics.ws_heartbeat_sent_total.increment(1);
|
manager.metrics.ws_heartbeat_sent_total.increment(1);
|
||||||
}
|
}
|
||||||
_ = shutdown_rx.recv() => {
|
_ = shutdown_rx.recv() => {
|
||||||
slog::info!(service.logs, "WS project {} shutdown", project_id);
|
tracing::info!(project_id = %project_id, "WS project shutdown");
|
||||||
let _ = session.close(Some(actix_ws::CloseCode::Normal.into())).await;
|
let _ = session.close(Some(actix_ws::CloseCode::Normal.into())).await;
|
||||||
break;
|
break;
|
||||||
}
|
}
|
||||||
@ -682,13 +678,13 @@ pub async fn ws_project(
|
|||||||
#[allow(unused_assignments)]
|
#[allow(unused_assignments)]
|
||||||
Some(Ok(WsMessage::Text(text))) => {
|
Some(Ok(WsMessage::Text(text))) => {
|
||||||
if last_activity.elapsed() > MAX_IDLE_TIMEOUT {
|
if last_activity.elapsed() > MAX_IDLE_TIMEOUT {
|
||||||
slog::info!(service.logs, "WS project {} idle timeout for user {}", project_id, user_id);
|
tracing::info!(project_id = %project_id, user_id = %user_id, "WS project idle timeout");
|
||||||
manager.metrics.ws_idle_timeout_total.increment(1);
|
manager.metrics.ws_idle_timeout_total.increment(1);
|
||||||
let _ = session.close(Some(actix_ws::CloseCode::Normal.into())).await;
|
let _ = session.close(Some(actix_ws::CloseCode::Normal.into())).await;
|
||||||
break;
|
break;
|
||||||
}
|
}
|
||||||
last_activity = Instant::now();
|
last_activity = Instant::now();
|
||||||
slog::warn!(service.logs, "WS project {} unexpected text from user {} ({} bytes) — WS is push-only", project_id, user_id, text.len());
|
tracing::warn!(project_id = %project_id, user_id = %user_id, bytes = text.len(), "WS project unexpected text — WS is push-only");
|
||||||
let _ = session.text(serde_json::json!({
|
let _ = session.text(serde_json::json!({
|
||||||
"type": "error",
|
"type": "error",
|
||||||
"error": "ws_push_only",
|
"error": "ws_push_only",
|
||||||
@ -697,8 +693,8 @@ pub async fn ws_project(
|
|||||||
break;
|
break;
|
||||||
}
|
}
|
||||||
Some(Ok(WsMessage::Binary(_))) => {
|
Some(Ok(WsMessage::Binary(_))) => {
|
||||||
if check_ws_rate_limit(&service.logs, &manager, &mut message_count, &mut rate_window_start).await {
|
if check_ws_rate_limit(&manager, &mut message_count, &mut rate_window_start).await {
|
||||||
slog::warn!(service.logs, "WS project {} rate limit exceeded for user {}", project_id, user_id);
|
tracing::warn!(project_id = %project_id, user_id = %user_id, "WS project rate limit exceeded");
|
||||||
let _ = session.text(serde_json::json!({
|
let _ = session.text(serde_json::json!({
|
||||||
"type": "error",
|
"type": "error",
|
||||||
"error": "rate_limit_exceeded",
|
"error": "rate_limit_exceeded",
|
||||||
@ -706,7 +702,7 @@ pub async fn ws_project(
|
|||||||
}).to_string()).await;
|
}).to_string()).await;
|
||||||
break;
|
break;
|
||||||
}
|
}
|
||||||
slog::warn!(service.logs, "WS project {} unexpected binary from user {}", project_id, user_id);
|
tracing::warn!(project_id = %project_id, user_id = %user_id, "WS project unexpected binary");
|
||||||
break;
|
break;
|
||||||
}
|
}
|
||||||
Some(Ok(WsMessage::Close(reason))) => {
|
Some(Ok(WsMessage::Close(reason))) => {
|
||||||
@ -715,7 +711,7 @@ pub async fn ws_project(
|
|||||||
}
|
}
|
||||||
Some(Ok(_)) => {}
|
Some(Ok(_)) => {}
|
||||||
Some(Err(e)) => {
|
Some(Err(e)) => {
|
||||||
slog::warn!(service.logs, "WS project error: {}", e);
|
tracing::warn!(error = ?e, "WS project error");
|
||||||
break;
|
break;
|
||||||
}
|
}
|
||||||
None => break,
|
None => break,
|
||||||
@ -737,7 +733,7 @@ pub async fn ws_project(
|
|||||||
}
|
}
|
||||||
}
|
}
|
||||||
Err(e) => {
|
Err(e) => {
|
||||||
slog::error!(service.logs, "WS serialize error: {}", e);
|
tracing::error!(error = ?e, "WS serialize error");
|
||||||
break;
|
break;
|
||||||
}
|
}
|
||||||
}
|
}
|
||||||
|
|||||||
@ -62,10 +62,9 @@ pub async fn ws_universal(
|
|||||||
.and_then(|v| v.to_str().ok())
|
.and_then(|v| v.to_str().ok())
|
||||||
.unwrap_or("(none)");
|
.unwrap_or("(none)");
|
||||||
if !validate_origin(&req) {
|
if !validate_origin(&req) {
|
||||||
slog::warn!(
|
tracing::warn!(
|
||||||
service.logs,
|
origin = %origin_val,
|
||||||
"WS universal: origin rejected origin={}",
|
"WS universal: origin rejected"
|
||||||
origin_val
|
|
||||||
);
|
);
|
||||||
return Err(ApiError(service::error::AppError::BadRequest(
|
return Err(ApiError(service::error::AppError::BadRequest(
|
||||||
"Invalid origin".into(),
|
"Invalid origin".into(),
|
||||||
@ -83,28 +82,25 @@ pub async fn ws_universal(
|
|||||||
.find(|p| p.starts_with("token="))
|
.find(|p| p.starts_with("token="))
|
||||||
.and_then(|p| p.split('=').nth(1))
|
.and_then(|p| p.split('=').nth(1))
|
||||||
}) {
|
}) {
|
||||||
slog::info!(
|
tracing::info!(
|
||||||
service.logs,
|
token = %token,
|
||||||
"WS universal: validating token token={} origin={}",
|
origin = %origin_val,
|
||||||
token,
|
"WS universal: validating token"
|
||||||
origin_val
|
|
||||||
);
|
);
|
||||||
match service.ws_token.validate_token(token).await {
|
match service.ws_token.validate_token(token).await {
|
||||||
Ok(uid) => {
|
Ok(uid) => {
|
||||||
slog::info!(
|
tracing::info!(
|
||||||
service.logs,
|
uid = %uid,
|
||||||
"WS universal: token auth successful uid={} origin={}",
|
origin = %origin_val,
|
||||||
uid,
|
"WS universal: token auth successful"
|
||||||
origin_val
|
|
||||||
);
|
);
|
||||||
uid
|
uid
|
||||||
}
|
}
|
||||||
Err(e) => {
|
Err(e) => {
|
||||||
slog::warn!(
|
tracing::warn!(
|
||||||
service.logs,
|
error = ?e,
|
||||||
"WS universal: token auth failed: {:?} token={}",
|
token = %token,
|
||||||
e,
|
"WS universal: token auth failed"
|
||||||
token
|
|
||||||
);
|
);
|
||||||
service
|
service
|
||||||
.room
|
.room
|
||||||
@ -147,11 +143,10 @@ pub async fn ws_universal(
|
|||||||
}
|
}
|
||||||
};
|
};
|
||||||
|
|
||||||
slog::debug!(
|
tracing::debug!(
|
||||||
service.logs,
|
user_id = %user_id,
|
||||||
"WS universal connection established user_id={} origin={}",
|
origin = %origin_val,
|
||||||
user_id,
|
"WS universal connection established"
|
||||||
origin_val
|
|
||||||
);
|
);
|
||||||
|
|
||||||
let service = service.get_ref().clone();
|
let service = service.get_ref().clone();
|
||||||
@ -159,7 +154,6 @@ pub async fn ws_universal(
|
|||||||
manager.metrics.ws_connections_active.increment(1.0);
|
manager.metrics.ws_connections_active.increment(1.0);
|
||||||
manager.metrics.ws_connections_total.increment(1);
|
manager.metrics.ws_connections_total.increment(1);
|
||||||
|
|
||||||
let logs = service.logs.clone();
|
|
||||||
let (response, mut session, mut msg_stream) = actix_ws::handle(&req, stream)?;
|
let (response, mut session, mut msg_stream) = actix_ws::handle(&req, stream)?;
|
||||||
actix::spawn(async move {
|
actix::spawn(async move {
|
||||||
let handler = WsRequestHandler::new(Arc::new(service), user_id);
|
let handler = WsRequestHandler::new(Arc::new(service), user_id);
|
||||||
@ -175,13 +169,13 @@ pub async fn ws_universal(
|
|||||||
tokio::select! {
|
tokio::select! {
|
||||||
_ = heartbeat_interval.tick() => {
|
_ = heartbeat_interval.tick() => {
|
||||||
if last_heartbeat.elapsed() > HEARTBEAT_TIMEOUT {
|
if last_heartbeat.elapsed() > HEARTBEAT_TIMEOUT {
|
||||||
slog::warn!(logs, "WS universal heartbeat timeout for user {}", user_id);
|
tracing::warn!(user_id = %user_id, "WS universal heartbeat timeout");
|
||||||
manager.metrics.ws_heartbeat_timeout_total.increment(1);
|
manager.metrics.ws_heartbeat_timeout_total.increment(1);
|
||||||
let _ = session.close(Some(actix_ws::CloseCode::Policy.into())).await;
|
let _ = session.close(Some(actix_ws::CloseCode::Policy.into())).await;
|
||||||
break;
|
break;
|
||||||
}
|
}
|
||||||
if last_activity.elapsed() > MAX_IDLE_TIMEOUT {
|
if last_activity.elapsed() > MAX_IDLE_TIMEOUT {
|
||||||
slog::info!(logs, "WS universal idle timeout for user {}", user_id);
|
tracing::info!(user_id = %user_id, "WS universal idle timeout");
|
||||||
manager.metrics.ws_idle_timeout_total.increment(1);
|
manager.metrics.ws_idle_timeout_total.increment(1);
|
||||||
let _ = session.close(Some(actix_ws::CloseCode::Normal.into())).await;
|
let _ = session.close(Some(actix_ws::CloseCode::Normal.into())).await;
|
||||||
break;
|
break;
|
||||||
@ -192,7 +186,7 @@ pub async fn ws_universal(
|
|||||||
manager.metrics.ws_heartbeat_sent_total.increment(1);
|
manager.metrics.ws_heartbeat_sent_total.increment(1);
|
||||||
}
|
}
|
||||||
_ = shutdown_rx.recv() => {
|
_ = shutdown_rx.recv() => {
|
||||||
slog::info!(logs, "WS universal shutdown");
|
tracing::info!("WS universal shutdown");
|
||||||
let _ = session.close(Some(actix_ws::CloseCode::Normal.into())).await;
|
let _ = session.close(Some(actix_ws::CloseCode::Normal.into())).await;
|
||||||
break;
|
break;
|
||||||
}
|
}
|
||||||
@ -264,7 +258,7 @@ pub async fn ws_universal(
|
|||||||
Some(Ok(WsMessage::Pong(_))) => { last_heartbeat = Instant::now(); }
|
Some(Ok(WsMessage::Pong(_))) => { last_heartbeat = Instant::now(); }
|
||||||
Some(Ok(WsMessage::Text(text))) => {
|
Some(Ok(WsMessage::Text(text))) => {
|
||||||
if last_activity.elapsed() > MAX_IDLE_TIMEOUT {
|
if last_activity.elapsed() > MAX_IDLE_TIMEOUT {
|
||||||
slog::info!(logs, "WS universal idle timeout for user {}", user_id);
|
tracing::info!(user_id = %user_id, "WS universal idle timeout");
|
||||||
manager.metrics.ws_idle_timeout_total.increment(1);
|
manager.metrics.ws_idle_timeout_total.increment(1);
|
||||||
let _ = session.close(Some(actix_ws::CloseCode::Normal.into())).await;
|
let _ = session.close(Some(actix_ws::CloseCode::Normal.into())).await;
|
||||||
break;
|
break;
|
||||||
@ -277,14 +271,14 @@ pub async fn ws_universal(
|
|||||||
}
|
}
|
||||||
message_count += 1;
|
message_count += 1;
|
||||||
if message_count > MAX_MESSAGES_PER_SECOND {
|
if message_count > MAX_MESSAGES_PER_SECOND {
|
||||||
slog::warn!(logs, "WS universal rate limit exceeded for user {}", user_id);
|
tracing::warn!(user_id = %user_id, "WS universal rate limit exceeded");
|
||||||
manager.metrics.ws_rate_limit_hits.increment(1);
|
manager.metrics.ws_rate_limit_hits.increment(1);
|
||||||
let _ = session.text(serde_json::json!({"type":"error","error":"rate_limit_exceeded"}).to_string()).await;
|
let _ = session.text(serde_json::json!({"type":"error","error":"rate_limit_exceeded"}).to_string()).await;
|
||||||
continue;
|
continue;
|
||||||
}
|
}
|
||||||
|
|
||||||
if text.len() > MAX_TEXT_MESSAGE_LEN {
|
if text.len() > MAX_TEXT_MESSAGE_LEN {
|
||||||
slog::warn!(logs, "WS universal message too long from user {}: {} bytes", user_id, text.len());
|
tracing::warn!(user_id = %user_id, bytes = text.len(), "WS universal message too long");
|
||||||
let _ = session.text(serde_json::json!({"type":"error","error":"message_too_long"}).to_string()).await;
|
let _ = session.text(serde_json::json!({"type":"error","error":"message_too_long"}).to_string()).await;
|
||||||
continue;
|
continue;
|
||||||
}
|
}
|
||||||
@ -351,7 +345,7 @@ pub async fn ws_universal(
|
|||||||
}
|
}
|
||||||
}
|
}
|
||||||
Err(e) => {
|
Err(e) => {
|
||||||
slog::warn!(logs, "WS universal parse error from user {}: {}", user_id, e);
|
tracing::warn!(user_id = %user_id, error = %e, "WS universal parse error");
|
||||||
let _ = session.text(serde_json::json!({"type":"error","error":"parse_error"}).to_string()).await;
|
let _ = session.text(serde_json::json!({"type":"error","error":"parse_error"}).to_string()).await;
|
||||||
}
|
}
|
||||||
}
|
}
|
||||||
@ -360,7 +354,7 @@ pub async fn ws_universal(
|
|||||||
Some(Ok(WsMessage::Continuation(_))) => {}
|
Some(Ok(WsMessage::Continuation(_))) => {}
|
||||||
Some(Ok(WsMessage::Nop)) => {}
|
Some(Ok(WsMessage::Nop)) => {}
|
||||||
Some(Ok(WsMessage::Close(reason))) => { let _ = session.close(reason).await; break; }
|
Some(Ok(WsMessage::Close(reason))) => { let _ = session.close(reason).await; break; }
|
||||||
Some(Err(e)) => { slog::warn!(logs, "WS error: {}", e); break; }
|
Some(Err(e)) => { tracing::warn!(error = %e, "WS error"); break; }
|
||||||
None => break,
|
None => break,
|
||||||
}
|
}
|
||||||
}
|
}
|
||||||
|
|||||||
Loading…
Reference in New Issue
Block a user