Fix: Websocket communication misunderstanding error
This commit is contained in:
ziesorx
parent
9967bff6dc
commit
42a8325faf
8 changed files with 1109 additions and 63 deletions
|
|
@ -34,6 +34,10 @@ logger = logging.getLogger("detector_worker.websocket_handler")
|
|||
ws_logger = logging.getLogger("websocket")
|
||||
ws_rxtx_logger = logging.getLogger("websocket.rxtx") # Dedicated RX/TX logger
|
||||
|
||||
# Import enhanced loggers
|
||||
from ..utils.logging_utils import get_websocket_logger
|
||||
enhanced_ws_logger = get_websocket_logger()
|
||||
|
||||
# Type definitions for callbacks
|
||||
MessageHandler = Callable[[Dict[str, Any]], asyncio.coroutine]
|
||||
DetectionHandler = Callable[[str, Dict[str, Any], Any, WebSocket, Any, Dict[str, Any]], asyncio.coroutine]
|
||||
|
|
@ -113,12 +117,19 @@ class WebSocketHandler:
|
|||
self.websocket = websocket
|
||||
self.connected = True
|
||||
|
||||
# Log connection details
|
||||
# Log connection details with bulletproof logging
|
||||
client_host = getattr(websocket.client, 'host', 'unknown')
|
||||
client_port = getattr(websocket.client, 'port', 'unknown')
|
||||
logger.info(f"🔗 WebSocket connection accepted from {client_host}:{client_port}")
|
||||
connection_msg = f"🔗 WebSocket connection accepted from {client_host}:{client_port}"
|
||||
|
||||
print(f"\n{connection_msg}") # Print to console (always visible)
|
||||
logger.info(connection_msg)
|
||||
ws_rxtx_logger.info(f"CONNECT -> Client: {client_host}:{client_port}")
|
||||
|
||||
print("🔄 WebSocket handler ready - waiting for messages from CMS backend...")
|
||||
print("📡 All RX/TX communication will be logged below:")
|
||||
print("=" * 80)
|
||||
|
||||
# Create concurrent tasks
|
||||
stream_task = asyncio.create_task(self._process_streams())
|
||||
heartbeat_task = asyncio.create_task(self._send_heartbeat())
|
||||
|
|
@ -136,6 +147,9 @@ class WebSocketHandler:
|
|||
self.connected = False
|
||||
client_host = getattr(websocket.client, 'host', 'unknown') if websocket.client else 'unknown'
|
||||
client_port = getattr(websocket.client, 'port', 'unknown') if websocket.client else 'unknown'
|
||||
|
||||
print(f"\n🔗 WEBSOCKET CONNECTION CLOSED: {client_host}:{client_port}")
|
||||
print("=" * 80)
|
||||
ws_rxtx_logger.info(f"DISCONNECT -> Client: {client_host}:{client_port}")
|
||||
await self._cleanup()
|
||||
|
||||
|
|
@ -210,9 +224,14 @@ class WebSocketHandler:
|
|||
"cameraConnections": camera_connections
|
||||
}
|
||||
|
||||
# Compact JSON for RX/TX logging
|
||||
compact_json = json.dumps(state_data, separators=(',', ':'))
|
||||
ws_rxtx_logger.info(f"TX -> {compact_json}")
|
||||
# BULLETPROOF TX LOGGING - Multiple methods to ensure visibility
|
||||
tx_json = json.dumps(state_data, separators=(',', ':'))
|
||||
print(f"\n🟢 WEBSOCKET TX -> {tx_json}") # Print to console (always visible)
|
||||
logger.info(f"🟢 TX -> {tx_json}") # Standard logging
|
||||
ws_rxtx_logger.info(f"TX -> {tx_json}") # WebSocket specific logging
|
||||
|
||||
# Enhanced TX logging
|
||||
enhanced_ws_logger.log_tx(state_data)
|
||||
await self.websocket.send_json(state_data)
|
||||
|
||||
await asyncio.sleep(HEARTBEAT_INTERVAL)
|
||||
|
|
@ -229,28 +248,41 @@ class WebSocketHandler:
|
|||
while self.connected:
|
||||
try:
|
||||
text_data = await self.websocket.receive_text()
|
||||
ws_rxtx_logger.info(f"RX <- {text_data}")
|
||||
|
||||
# BULLETPROOF RX LOGGING - Multiple methods to ensure visibility
|
||||
print(f"\n🔵 WEBSOCKET RX <- {text_data}") # Print to console (always visible)
|
||||
logger.info(f"🔵 RX <- {text_data}") # Standard logging
|
||||
ws_rxtx_logger.info(f"RX <- {text_data}") # WebSocket specific logging
|
||||
|
||||
# Enhanced RX logging with correlation
|
||||
correlation_id = enhanced_ws_logger.log_rx(text_data)
|
||||
|
||||
data = json.loads(text_data)
|
||||
msg_type = data.get("type")
|
||||
|
||||
# Log message processing
|
||||
logger.debug(f"📥 Processing message type: {msg_type}")
|
||||
# Log message processing - FORCE INFO LEVEL
|
||||
logger.info(f"📥 Processing message type: {msg_type} [corr:{correlation_id}]")
|
||||
|
||||
if msg_type in self.message_handlers:
|
||||
handler = self.message_handlers[msg_type]
|
||||
await handler(data)
|
||||
logger.debug(f"✅ Message {msg_type} processed successfully")
|
||||
logger.info(f"✅ Message {msg_type} processed successfully [corr:{correlation_id}]")
|
||||
else:
|
||||
logger.error(f"❌ Unknown message type: {msg_type}")
|
||||
logger.error(f"❌ Unknown message type: {msg_type} [corr:{correlation_id}]")
|
||||
ws_rxtx_logger.error(f"UNKNOWN_MSG_TYPE -> {msg_type}")
|
||||
|
||||
except json.JSONDecodeError:
|
||||
logger.error("Received invalid JSON message")
|
||||
except json.JSONDecodeError as e:
|
||||
print(f"\n❌ WEBSOCKET ERROR - Invalid JSON received: {e}")
|
||||
print(f"🔍 Raw message data: {text_data}")
|
||||
logger.error(f"Received invalid JSON message: {e}")
|
||||
logger.error(f"Raw message data: {text_data}")
|
||||
enhanced_ws_logger.correlation_logger.error("Failed to parse JSON in received message")
|
||||
except (WebSocketDisconnect, ConnectionClosedError) as e:
|
||||
print(f"\n🔌 WEBSOCKET DISCONNECTED: {e}")
|
||||
logger.warning(f"WebSocket disconnected: {e}")
|
||||
break
|
||||
except Exception as e:
|
||||
print(f"\n💥 WEBSOCKET ERROR: {e}")
|
||||
logger.error(f"Error handling message: {e}")
|
||||
traceback.print_exc()
|
||||
break
|
||||
|
|
@ -381,6 +413,41 @@ class WebSocketHandler:
|
|||
"""
|
||||
subscriptions = data.get("subscriptions", [])
|
||||
|
||||
# DETAILED DEBUG LOGGING - Log the entire message payload
|
||||
print(f"\n📋 RECEIVED setSubscriptionList with {len(subscriptions)} subscriptions")
|
||||
logger.info(f"🔍 RECEIVED setSubscriptionList - Full payload: {json.dumps(data, indent=2)}")
|
||||
logger.info(f"📋 Number of subscriptions: {len(subscriptions)}")
|
||||
|
||||
# Extract unique model URLs for download
|
||||
unique_models = {} # model_id -> model_url
|
||||
valid_subscriptions = []
|
||||
|
||||
for i, sub_config in enumerate(subscriptions):
|
||||
sub_id = sub_config.get("subscriptionIdentifier")
|
||||
model_id = sub_config.get("modelId")
|
||||
model_url = sub_config.get("modelUrl")
|
||||
|
||||
print(f"📦 Subscription {i+1}: {sub_id} | Model {model_id}")
|
||||
|
||||
# Track unique models for download
|
||||
if model_id and model_url:
|
||||
if model_id not in unique_models:
|
||||
unique_models[model_id] = model_url
|
||||
print(f"🎯 New model found: ID {model_id}")
|
||||
else:
|
||||
print(f"🔄 Model {model_id} already tracked")
|
||||
|
||||
logger.info(f"📦 Subscription {i+1}: {json.dumps(sub_config, indent=2)}")
|
||||
sub_id = sub_config.get("subscriptionIdentifier")
|
||||
logger.info(f"🏷️ Subscription ID: '{sub_id}' (type: {type(sub_id)})")
|
||||
|
||||
print(f"📚 Unique models to download: {list(unique_models.keys())}")
|
||||
|
||||
# Download unique models first (before processing subscriptions)
|
||||
if unique_models:
|
||||
print(f"⬇️ Starting download of {len(unique_models)} unique models...")
|
||||
await self._download_unique_models(unique_models)
|
||||
|
||||
try:
|
||||
# Get current subscription identifiers
|
||||
current_subscriptions = set(subscription_to_camera.keys())
|
||||
|
|
@ -391,6 +458,31 @@ class WebSocketHandler:
|
|||
|
||||
for sub_config in subscriptions:
|
||||
sub_id = sub_config.get("subscriptionIdentifier")
|
||||
|
||||
# Enhanced validation with detailed logging
|
||||
logger.info(f"🔍 Processing subscription config: subscriptionIdentifier='{sub_id}'")
|
||||
|
||||
# Handle null/None subscription IDs
|
||||
if sub_id is None or sub_id == "null" or sub_id == "None" or not sub_id:
|
||||
logger.error(f"❌ Invalid subscription ID received: '{sub_id}' (type: {type(sub_id)})")
|
||||
logger.error(f"📋 Full subscription config: {json.dumps(sub_config, indent=2)}")
|
||||
|
||||
# Try to construct a valid subscription ID from available data
|
||||
display_id = sub_config.get("displayId") or sub_config.get("displayIdentifier") or "unknown-display"
|
||||
camera_id = sub_config.get("cameraId") or sub_config.get("camera") or "unknown-camera"
|
||||
constructed_id = f"{display_id};{camera_id}"
|
||||
|
||||
logger.warning(f"🔧 Attempting to construct subscription ID: '{constructed_id}'")
|
||||
logger.warning(f"📝 Available config keys: {list(sub_config.keys())}")
|
||||
|
||||
# Use constructed ID if it looks valid
|
||||
if display_id != "unknown-display" or camera_id != "unknown-camera":
|
||||
sub_id = constructed_id
|
||||
logger.info(f"✅ Using constructed subscription ID: '{sub_id}'")
|
||||
else:
|
||||
logger.error(f"💥 Cannot construct valid subscription ID, skipping this subscription")
|
||||
continue
|
||||
|
||||
if sub_id:
|
||||
desired_subscriptions.add(sub_id)
|
||||
subscription_configs[sub_id] = sub_config
|
||||
|
|
@ -447,32 +539,136 @@ class WebSocketHandler:
|
|||
logger.info(f"Subscription list reconciliation completed. Active: {len(desired_subscriptions)}")
|
||||
|
||||
except Exception as e:
|
||||
print(f"💥 Error handling setSubscriptionList: {e}")
|
||||
logger.error(f"Error handling setSubscriptionList: {e}")
|
||||
traceback.print_exc()
|
||||
|
||||
async def _download_unique_models(self, unique_models: Dict[int, str]) -> None:
|
||||
"""
|
||||
Download unique models to models/{model_id}/ folders.
|
||||
|
||||
Args:
|
||||
unique_models: Dictionary of model_id -> model_url
|
||||
"""
|
||||
try:
|
||||
# Use model manager to download models
|
||||
download_tasks = []
|
||||
|
||||
for model_id, model_url in unique_models.items():
|
||||
print(f"🚀 Queuing download: Model {model_id} from {model_url[:50]}...")
|
||||
|
||||
# Create download task using model manager
|
||||
task = asyncio.create_task(
|
||||
self._download_single_model(model_id, model_url)
|
||||
)
|
||||
download_tasks.append(task)
|
||||
|
||||
# Wait for all downloads to complete
|
||||
if download_tasks:
|
||||
print(f"⏳ Downloading {len(download_tasks)} models concurrently...")
|
||||
results = await asyncio.gather(*download_tasks, return_exceptions=True)
|
||||
|
||||
# Check results
|
||||
successful = 0
|
||||
failed = 0
|
||||
for i, result in enumerate(results):
|
||||
model_id = list(unique_models.keys())[i]
|
||||
if isinstance(result, Exception):
|
||||
print(f"❌ Model {model_id} download failed: {result}")
|
||||
failed += 1
|
||||
else:
|
||||
print(f"✅ Model {model_id} downloaded successfully")
|
||||
successful += 1
|
||||
|
||||
print(f"📊 Download summary: {successful} successful, {failed} failed")
|
||||
else:
|
||||
print("📭 No models to download")
|
||||
|
||||
except Exception as e:
|
||||
print(f"💥 Error in bulk model download: {e}")
|
||||
logger.error(f"Error downloading unique models: {e}")
|
||||
|
||||
async def _download_single_model(self, model_id: int, model_url: str) -> None:
|
||||
"""
|
||||
Download a single model using the model manager.
|
||||
|
||||
Args:
|
||||
model_id: Model identifier
|
||||
model_url: URL to download from
|
||||
"""
|
||||
try:
|
||||
# Create a temporary camera ID for the download
|
||||
temp_camera_id = f"download_temp_{model_id}_{int(time.time())}"
|
||||
|
||||
print(f"📥 Downloading model {model_id}...")
|
||||
|
||||
# Use model manager to load (download) the model
|
||||
await self.model_manager.load_model(
|
||||
camera_id=temp_camera_id,
|
||||
model_id=str(model_id),
|
||||
model_url=model_url,
|
||||
force_reload=False # Use cached if already downloaded
|
||||
)
|
||||
|
||||
# Clean up the temporary model reference
|
||||
self.model_manager.unload_models(temp_camera_id)
|
||||
|
||||
print(f"✅ Model {model_id} successfully downloaded to models/{model_id}/")
|
||||
|
||||
except Exception as e:
|
||||
print(f"❌ Failed to download model {model_id}: {e}")
|
||||
raise # Re-raise for gather() to catch
|
||||
|
||||
async def _start_subscription(self, subscription_id: str, config: Dict[str, Any]) -> None:
|
||||
"""Start a single subscription with given configuration."""
|
||||
"""Start a single subscription with given configuration and enhanced validation."""
|
||||
try:
|
||||
# Extract camera ID from subscription identifier
|
||||
# Validate subscription_id
|
||||
if not subscription_id:
|
||||
raise ValueError("Empty subscription_id provided")
|
||||
|
||||
# Extract camera ID from subscription identifier with enhanced validation
|
||||
parts = subscription_id.split(";")
|
||||
camera_id = parts[1] if len(parts) >= 2 else subscription_id
|
||||
if len(parts) >= 2:
|
||||
camera_id = parts[1]
|
||||
else:
|
||||
# Fallback to using subscription_id as camera_id if format is unexpected
|
||||
camera_id = subscription_id
|
||||
logger.warning(f"Subscription ID format unexpected: '{subscription_id}', using as camera_id")
|
||||
|
||||
# Validate camera_id
|
||||
if not camera_id or camera_id == "null" or camera_id == "None":
|
||||
raise ValueError(f"Invalid camera_id extracted from subscription_id '{subscription_id}': '{camera_id}'")
|
||||
|
||||
logger.info(f"Starting subscription {subscription_id} for camera {camera_id}")
|
||||
logger.debug(f"Config keys for camera {camera_id}: {list(config.keys())}")
|
||||
|
||||
# Store subscription mapping
|
||||
subscription_to_camera[subscription_id] = camera_id
|
||||
|
||||
# Start camera stream
|
||||
await self.stream_manager.start_stream(camera_id, config)
|
||||
# Start camera stream with enhanced config validation
|
||||
if not config:
|
||||
raise ValueError(f"Empty config provided for camera {camera_id}")
|
||||
|
||||
stream_started = await self.stream_manager.start_stream(camera_id, config)
|
||||
if not stream_started:
|
||||
raise RuntimeError(f"Failed to start stream for camera {camera_id}")
|
||||
|
||||
# Load model
|
||||
model_id = config.get("modelId")
|
||||
model_url = config.get("modelUrl")
|
||||
|
||||
if model_id and model_url:
|
||||
logger.info(f"Loading model {model_id} for camera {camera_id} from {model_url}")
|
||||
await self.model_manager.load_model(camera_id, model_id, model_url)
|
||||
elif model_id or model_url:
|
||||
logger.warning(f"Incomplete model config for camera {camera_id}: modelId={model_id}, modelUrl={model_url}")
|
||||
else:
|
||||
logger.info(f"No model specified for camera {camera_id}")
|
||||
|
||||
except Exception as e:
|
||||
logger.error(f"Error starting subscription {subscription_id}: {e}")
|
||||
raise
|
||||
traceback.print_exc()
|
||||
raise
|
||||
|
||||
async def _handle_request_state(self, data: Dict[str, Any]) -> None:
|
||||
"""Handle state request message."""
|
||||
|
|
@ -504,7 +700,11 @@ class WebSocketHandler:
|
|||
"sessionId": session_id
|
||||
}
|
||||
}
|
||||
ws_rxtx_logger.info(f"TX -> {json.dumps(response, separators=(',', ':'))}")
|
||||
# BULLETPROOF TX LOGGING for responses
|
||||
response_json = json.dumps(response, separators=(',', ':'))
|
||||
print(f"\n🟢 WEBSOCKET TX -> {response_json}") # Print to console (always visible)
|
||||
enhanced_ws_logger.log_tx(response)
|
||||
ws_rxtx_logger.info(f"TX -> {response_json}")
|
||||
await self.websocket.send_json(response)
|
||||
|
||||
logger.info(f"Set session {session_id} for display {display_id}")
|
||||
|
|
@ -530,7 +730,11 @@ class WebSocketHandler:
|
|||
"patchData": patch_data
|
||||
}
|
||||
}
|
||||
ws_rxtx_logger.info(f"TX -> {json.dumps(response, separators=(',', ':'))}")
|
||||
# BULLETPROOF TX LOGGING for responses
|
||||
response_json = json.dumps(response, separators=(',', ':'))
|
||||
print(f"\n🟢 WEBSOCKET TX -> {response_json}") # Print to console (always visible)
|
||||
enhanced_ws_logger.log_tx(response)
|
||||
ws_rxtx_logger.info(f"TX -> {response_json}")
|
||||
await self.websocket.send_json(response)
|
||||
|
||||
async def _handle_set_progression_stage(self, data: Dict[str, Any]) -> None:
|
||||
|
|
@ -632,7 +836,11 @@ class WebSocketHandler:
|
|||
}
|
||||
|
||||
try:
|
||||
ws_rxtx_logger.info(f"TX -> {json.dumps(detection_data, separators=(',', ':'))}")
|
||||
# BULLETPROOF TX LOGGING for detection results
|
||||
detection_json = json.dumps(detection_data, separators=(',', ':'))
|
||||
print(f"\n🟢 WEBSOCKET TX -> {detection_json}") # Print to console (always visible)
|
||||
enhanced_ws_logger.log_tx(detection_data)
|
||||
ws_rxtx_logger.info(f"TX -> {detection_json}")
|
||||
await self.websocket.send_json(detection_data)
|
||||
except RuntimeError as e:
|
||||
if "websocket.close" in str(e):
|
||||
|
|
@ -664,7 +872,11 @@ class WebSocketHandler:
|
|||
}
|
||||
|
||||
try:
|
||||
ws_rxtx_logger.info(f"TX -> {json.dumps(detection_data, separators=(',', ':'))}")
|
||||
# BULLETPROOF TX LOGGING for detection results
|
||||
detection_json = json.dumps(detection_data, separators=(',', ':'))
|
||||
print(f"\n🟢 WEBSOCKET TX -> {detection_json}") # Print to console (always visible)
|
||||
enhanced_ws_logger.log_tx(detection_data)
|
||||
ws_rxtx_logger.info(f"TX -> {detection_json}")
|
||||
await self.websocket.send_json(detection_data)
|
||||
except RuntimeError as e:
|
||||
if "websocket.close" in str(e):
|
||||
|
|
@ -676,25 +888,31 @@ class WebSocketHandler:
|
|||
logger.info(f"📡 SENT DISCONNECTION SIGNAL - detection: null for camera {camera_id}, backend should clear session")
|
||||
|
||||
async def _handle_subscribe(self, data: Dict[str, Any]) -> None:
|
||||
"""Handle individual subscription message."""
|
||||
"""Handle individual subscription message - often initial null data from CMS."""
|
||||
try:
|
||||
payload = data.get("payload", {})
|
||||
subscription_id = payload.get("subscriptionIdentifier")
|
||||
|
||||
if not subscription_id:
|
||||
logger.error("Subscribe message missing subscriptionIdentifier")
|
||||
print(f"📥 SUBSCRIBE MESSAGE RECEIVED - subscriptionIdentifier: '{subscription_id}'")
|
||||
|
||||
# CMS often sends initial "null" subscribe messages during startup/verification
|
||||
# These should be ignored as they contain no useful data
|
||||
if not subscription_id or subscription_id == "null" or subscription_id == "None":
|
||||
print(f"🔍 IGNORING initial subscribe message with null/empty subscriptionIdentifier")
|
||||
print(f"📋 This is normal - CMS will send proper setSubscriptionList later")
|
||||
return
|
||||
|
||||
# Convert single subscription to setSubscriptionList format
|
||||
# If we get a valid subscription ID, convert to setSubscriptionList format
|
||||
subscription_list_data = {
|
||||
"type": "setSubscriptionList",
|
||||
"subscriptions": [payload]
|
||||
}
|
||||
|
||||
# Delegate to existing setSubscriptionList handler
|
||||
print(f"✅ Processing valid subscribe message: {subscription_id}")
|
||||
await self._handle_set_subscription_list(subscription_list_data)
|
||||
|
||||
except Exception as e:
|
||||
print(f"💥 Error handling subscribe message: {e}")
|
||||
logger.error(f"Error handling subscribe: {e}")
|
||||
traceback.print_exc()
|
||||
|
||||
|
|
|
|||
Loading…
Add table
Add a link
Reference in a new issue