demo_context_logging.py 5.73 KB
#!/usr/bin/env python3
"""
Demonstration of the Request Context and Logging system

This script demonstrates how the request-scoped context management
and structured logging work together to provide complete visibility
into search request processing.
"""

import time
import sys
import os

# Add the project root to Python path
sys.path.insert(0, os.path.dirname(os.path.abspath(__file__)))

# Setup the environment (use the conda environment)
os.system('source /home/tw/miniconda3/etc/profile.d/conda.sh && conda activate searchengine')

def demo_request_context():
    """Demonstrate RequestContext functionality"""
    print("๐Ÿš€ Starting Request Context and Logging Demo")
    print("=" * 60)

    try:
        from utils.logger import get_logger, setup_logging
        from context.request_context import create_request_context, RequestContextStage

        # Setup logging
        setup_logging(log_level="INFO", log_dir="demo_logs")
        logger = get_logger("demo")

        print("โœ… Logging infrastructure initialized")

        # Create a request context
        context = create_request_context("demo123", "demo_user")
        print(f"โœ… Created request context: reqid={context.reqid}, uid={context.uid}")

        # Simulate a complete search pipeline
        with context:  # Use context manager for automatic timing
            logger.info("ๅผ€ๅง‹ๆจกๆ‹Ÿๆœ็ดข่ฏทๆฑ‚ๅค„็†", extra={'reqid': context.reqid, 'uid': context.uid})

            # Stage 1: Query parsing
            context.start_stage(RequestContextStage.QUERY_PARSING)
            time.sleep(0.02)  # Simulate work

            # Store query analysis results
            context.store_query_analysis(
                original_query="็บข่‰ฒ้ซ˜่ทŸ้ž‹ ๅ“็‰Œ:Nike",
                normalized_query="็บข่‰ฒ ้ซ˜่ทŸ้ž‹ ๅ“็‰Œ:Nike",
                rewritten_query="็บข่‰ฒ ้ซ˜่ทŸ้ž‹ ๅ“็‰Œ:nike",
                detected_language="zh",
                translations={"en": "red high heels brand:nike"},
                domain="brand"
            )

            context.store_intermediate_result("query_vector_shape", (1024,))
            context.end_stage(RequestContextStage.QUERY_PARSING)

            # Stage 2: Boolean parsing
            context.start_stage(RequestContextStage.BOOLEAN_PARSING)
            time.sleep(0.005)  # Simulate work
            context.store_intermediate_result("boolean_ast", "AND(็บข่‰ฒ, ้ซ˜่ทŸ้ž‹, BRAND:nike)")
            context.end_stage(RequestContextStage.BOOLEAN_PARSING)

            # Stage 3: Query building
            context.start_stage(RequestContextStage.QUERY_BUILDING)
            time.sleep(0.01)  # Simulate work
            es_query = {
                "query": {"bool": {"must": [{"match": {"title": "็บข่‰ฒ ้ซ˜่ทŸ้ž‹"}}]}},
                "knn": {"field": "text_embedding", "query_vector": [0.1] * 1024}
            }
            context.store_intermediate_result("es_query", es_query)
            context.end_stage(RequestContextStage.QUERY_BUILDING)

            # Stage 4: Elasticsearch search
            context.start_stage(RequestContextStage.ELASTICSEARCH_SEARCH)
            time.sleep(0.05)  # Simulate work
            es_response = {
                "hits": {"total": {"value": 42}, "max_score": 0.95, "hits": []},
                "took": 15
            }
            context.store_intermediate_result("es_response", es_response)
            context.end_stage(RequestContextStage.ELASTICSEARCH_SEARCH)

            # Stage 5: Result processing
            context.start_stage(RequestContextStage.RESULT_PROCESSING)
            time.sleep(0.01)  # Simulate work
            context.store_intermediate_result("processed_hits", [
                {"_id": "1", "_score": 0.95},
                {"_id": "2", "_score": 0.87}
            ])
            context.end_stage(RequestContextStage.RESULT_PROCESSING)

            # Add a warning to demonstrate warning tracking
            context.add_warning("ๆŸฅ่ฏข่ขซ้‡ๅ†™: '็บข่‰ฒ ้ซ˜่ทŸ้ž‹ ๅ“็‰Œ:Nike' -> 'red high heels brand:nike'")

        # Get and display summary
        summary = context.get_summary()
        print("\n๐Ÿ“Š Request Summary:")
        print("-" * 40)
        print(f"Request ID: {summary['request_info']['reqid']}")
        print(f"User ID: {summary['request_info']['uid']}")
        print(f"Total Duration: {summary['performance']['total_duration_ms']:.2f}ms")
        print("\nโฑ๏ธ Stage Breakdown:")
        for stage, duration in summary['performance']['stage_timings_ms'].items():
            percentage = summary['performance']['stage_percentages'].get(stage, 0)
            print(f"  {stage}: {duration:.2f}ms ({percentage}%)")

        print("\n๐Ÿ” Query Analysis:")
        print(f"  Original: '{summary['query_analysis']['original_query']}'")
        print(f"  Rewritten: '{summary['query_analysis']['rewritten_query']}'")
        print(f"  Language: {summary['query_analysis']['detected_language']}")
        print(f"  Domain: {summary['query_analysis']['domain']}")
        print(f"  Has Vector: {summary['query_analysis']['has_vector']}")

        print("\n๐Ÿ“ˆ Results:")
        print(f"  Total Hits: {summary['results']['total_hits']}")
        print(f"  ES Query Size: {summary['results']['es_query_size']} chars")

        print("\nโš ๏ธ Warnings:")
        print(f"  Count: {summary['request_info']['warnings_count']}")

        print("\nโœ… Demo completed successfully!")
        print(f"๐Ÿ“ Logs are available in: demo_logs/")

    except Exception as e:
        print(f"โŒ Demo failed: {e}")
        import traceback
        traceback.print_exc()
        return False

    return True

if __name__ == "__main__":
    success = demo_request_context()
    if success:
        print("\n๐ŸŽ‰ Request Context and Logging system is ready for production!")
    else:
        print("\n๐Ÿ’ฅ Please check the errors above")
        sys.exit(1)