pedidos-express/routes/orders.py

import time
from logging import getLogger
from threading import Thread
from uuid import uuid4

from fastapi import HTTPException, APIRouter, Depends
from fastapi.responses import JSONResponse

from fudo import fudo
from models.sales import ItemWeb, OrderWeb
from models.items import Item, Order
from models.user import User
from services.fudo_service import add_product_to_fudo
from services.email_service import get_email_sender
from services.logging_service import log_order, structured_logger, LogLevel
import services.print_service as ps
from services.data_service import DataServiceFactory
from config.mails import PRINTER_DISCONNECTED_MAIL
from config.messages import ErrorResponse, SuccessResponse, UserResponse
from config.settings import DEVELOPMENT
from auth.security import get_current_user

logger = getLogger(__name__)

# Data services initialization
user_data_service = DataServiceFactory.get_user_service()
product_data_service = DataServiceFactory.get_product_service()
sale_data_service = DataServiceFactory.get_sales_service()

# Global variables
printer_orders = []
order_router = APIRouter()
name_promo = "Shop"

@order_router.post("/send")
async def printer_order(order: OrderWeb, current_user: User = Depends(get_current_user)):
    """Process printer order"""
    logger.info(f"Printer order received from user {current_user.email} for table {order.table}")
    
    structured_logger.log_order_event(
        f"Print order received for table {order.table}",
        LogLevel.INFO,
        {
            "table": order.table,
            "items_count": len(order.items),
            "customer_id": order.customerId,
            "total_amount": order.totalAmount,
            "order_date": order.orderDate
        },
        user_id=current_user.id,
        user_email=current_user.email
    )
    
    # Printer status validation
    if not DEVELOPMENT:
        try:
            printer_status = ps.get_status()
            if not printer_status:
                logger.error(f"Printer is not connected. Order from user {current_user.email} cannot be processed.")
                
                structured_logger.log_print_event(
                    f"Order rejected due to printer disconnection",
                    LogLevel.ERROR,
                    {
                        "table": order.table,
                        "user_id": current_user.id,
                        "user_email": current_user.email,
                        "items_count": len(order.items)
                    },
                    user_id=current_user.id,
                    user_email=current_user.email
                )
                
                # Send notification email to admins
                email_thread = Thread(
                    target=get_email_sender().send_email,
                    args=(
                        PRINTER_DISCONNECTED_MAIL["subject"], 
                        PRINTER_DISCONNECTED_MAIL["body"], 
                        ["erwinjacimino2003@gmail.com", "mompyn@gmail.com"]
                    ),
                    daemon=True
                )
                email_thread.start()
                
                structured_logger.log_email_event(
                    "Printer disconnection notification sent to admins",
                    LogLevel.WARNING,
                    {
                        "trigger_user": current_user.email,
                        "admin_emails": ["erwinjacimino2003@gmail.com", "mompyn@gmail.com"]
                    },
                    user_id=current_user.id,
                    user_email=current_user.email
                )
                
                return JSONResponse(status_code=424, content={"message": ErrorResponse.PRINTER_DISCONNECTED})
                
        except Exception as e:
            logger.error(f"Error checking printer status: {e}")
            structured_logger.log_print_event(
                "Printer status check failed",
                LogLevel.ERROR,
                {
                    "error": str(e),
                    "error_type": type(e).__name__,
                    "user_id": current_user.id
                },
                user_id=current_user.id,
                user_email=current_user.email
            )
            return JSONResponse(status_code=500, content={"message": "Error interno del servidor"})

    # Extract order data
    items = order.items
    table = order.table

    # Input validation
    if not items or not table:
        logger.warning(f"Invalid order data from user {current_user.email}: missing items or table")
        structured_logger.log_order_event(
            "Order validation failed: missing items or table",
            LogLevel.WARNING,
            {
                "has_items": bool(items),
                "table": table,
                "items_count": len(items) if items else 0
            },
            user_id=current_user.id,
            user_email=current_user.email
        )
        return JSONResponse(status_code=400, content={"message": ErrorResponse.MISSING_FIELDS})

    if not isinstance(table, int):
        logger.warning(f"Invalid table type from user {current_user.email}: {type(table)}")
        structured_logger.log_order_event(
            "Order validation failed: invalid table type",
            LogLevel.WARNING,
            {
                "table": table,
                "table_type": str(type(table))
            },
            user_id=current_user.id,
            user_email=current_user.email
        )
        return JSONResponse(status_code=400, content={"message": ErrorResponse.INVALID_TABLE_TYPE})

    logger.info(f"Processing order for table {table} with {len(items)} items")
    structured_logger.log_order_event(
        f"Starting order processing for table {table}",
        LogLevel.INFO,
        {
            "table": table,
            "items_count": len(items),
            "item_ids": [item.id for item in items],
            "item_quantities": [item.quantity for item in items]
        },
        user_id=current_user.id,
        user_email=current_user.email
    )

    # Add products to Fudo
    product_errors = []

    # Get products data
    try:
        products = product_data_service.get_products([item.id for item in items])
        logger.info(f"Retrieved {len(products)} products from database")
        
        structured_logger.log_order_event(
            f"Retrieved products for order processing",
            LogLevel.INFO,
            {
                "table": table,
                "requested_products": len(items),
                "found_products": len(products),
                "product_ids": [p.id for p in products]
            },
            user_id=current_user.id,
            user_email=current_user.email
        )
        
    except Exception as e:
        error_msg = f"Error retrieving products: {e}"
        logger.error(error_msg)
        structured_logger.log_database_event(
            "Failed to retrieve products for order",
            LogLevel.ERROR,
            {
                "table": table,
                "requested_product_ids": [item.id for item in items],
                "error": str(e),
                "error_type": type(e).__name__
            },
            user_id=current_user.id,
            user_email=current_user.email
        )
        return JSONResponse(status_code=500, content={"message": "Error interno del servidor"})

    beers_for_promo = 0
    
    try:
        fudo.get_token()
        logger.info("Fudo token obtained successfully")
        
        for item, product in zip(items, products):
            try:
                # Si es dia de promo
                if time.localtime().tm_wday + 1 == product.promo_day and product.promo_id:
                    logger.info(f"Applying promotion for product {product.id} on table {table}")
                    fudo_product = add_product_to_fudo(product.promo_id, item.quantity, table)
                    
                    structured_logger.log_order_event(
                        f"Promotion applied for product {product.name}",
                        LogLevel.INFO,
                        {
                            "product_id": product.id,
                            "promo_id": product.promo_id,
                            "table": table,
                            "quantity": item.quantity,
                            "promo_day": product.promo_day,
                            "current_day": time.localtime().tm_wday + 1
                        },
                        user_id=current_user.id,
                        user_email=current_user.email
                    )
                #en caso contrario
                else:
                    if product.type == name_promo:
                        beers_for_promo += item.quantity
                        logger.debug(f"Added {item.quantity} beers for promotion calculation")
                    
                    fudo_product = add_product_to_fudo(item.id, item.quantity, table)
                    
                    structured_logger.log_order_event(
                        f"Added product {product.name} to Fudo",
                        LogLevel.INFO,
                        {
                            "product_id": item.id,
                            "product_name": product.name,
                            "product_type": product.type,
                            "table": table,
                            "quantity": item.quantity,
                            "is_beer": product.type == name_promo
                        },
                        user_id=current_user.id,
                        user_email=current_user.email
                    )
                
                if not fudo_product:
                    error_msg = f"Error adding product {item.id} to table {table}."
                    product_errors.append(error_msg)
                    logger.error(error_msg)
                    
                    structured_logger.log_order_event(
                        f"Failed to add product to Fudo",
                        LogLevel.ERROR,
                        {
                            "product_id": item.id,
                            "table": table,
                            "quantity": item.quantity
                        },
                        user_id=current_user.id,
                        user_email=current_user.email
                    )
                    
            except Exception as e:
                error_msg = f"Error processing product {item.id}: {e}"
                logger.error(error_msg)
                product_errors.append(error_msg)
                
                structured_logger.log_order_event(
                    f"Error processing product {item.id}",
                    LogLevel.ERROR,
                    {
                        "product_id": item.id,
                        "table": table,
                        "error": str(e),
                        "error_type": type(e).__name__
                    },
                    user_id=current_user.id,
                    user_email=current_user.email
                )
                
    except Exception as e:
        error_msg = f"Error with Fudo integration: {e}"
        logger.error(error_msg)
        structured_logger.log_order_event(
            "Fudo integration error",
            LogLevel.ERROR,
            {
                "table": table,
                "error": str(e),
                "error_type": type(e).__name__
            },
            user_id=current_user.id,
            user_email=current_user.email
        )
        return JSONResponse(status_code=500, content={"message": "Error interno del servidor"})

    if product_errors:
        logger.error(f"Product errors occurred: {product_errors}")
        structured_logger.log_order_event(
            "Order processing failed due to product errors",
            LogLevel.ERROR,
            {
                "table": table,
                "product_errors": product_errors,
                "error_count": len(product_errors)
            },
            user_id=current_user.id,
            user_email=current_user.email
        )
        return JSONResponse(
            status_code=424, 
            content={"message": ErrorResponse.PRODUCT_ADD_ERROR, "errors": product_errors}
        )

    # User validation
    try:
        user = user_data_service.get_by_id(order.customerId)
        if not user:
            logger.warning(f"User not found: {order.customerId}")
            structured_logger.log_user_event(
                f"Order rejected: user not found",
                LogLevel.WARNING,
                {
                    "requested_user_id": order.customerId,
                    "table": table
                },
                user_id=current_user.id,
                user_email=current_user.email
            )
            return JSONResponse(status_code=404, content={"message": UserResponse.USER_NOT_FOUND.format(user_id=order.customerId)})
        
        logger.info(f"Order customer validated: {user.email}")
        structured_logger.log_user_event(
            f"Order customer validated",
            LogLevel.INFO,
            {
                "customer_id": user.id,
                "customer_email": user.email,
                "customer_name": user.name,
                "table": table
            },
            user_id=current_user.id,
            user_email=current_user.email
        )
        
    except Exception as e:
        error_msg = f"Error validating user {order.customerId}: {e}"
        logger.error(error_msg)
        structured_logger.log_database_event(
            "User validation error during order processing",
            LogLevel.ERROR,
            {
                "requested_user_id": order.customerId,
                "table": table,
                "error": str(e),
                "error_type": type(e).__name__
            },
            user_id=current_user.id,
            user_email=current_user.email
        )
        return JSONResponse(status_code=500, content={"message": "Error interno del servidor"})
    
    # Get active sale
    try:
        active_sale_id = fudo.get_active_sale(fudo.get_table(table))
        if not active_sale_id:
            error_msg = f"No active sale found for table {table}"
            logger.error(error_msg)
            structured_logger.log_order_event(
                "Order failed: no active sale found",
                LogLevel.ERROR,
                {
                    "table": table,
                    "customer_id": order.customerId
                },
                user_id=current_user.id,
                user_email=current_user.email
            )
            raise HTTPException(status_code=404, detail=error_msg)
            
        active_sale_id = active_sale_id['id']
        logger.info(f"Active sale found for table {table}: {active_sale_id}")
        
        structured_logger.log_order_event(
            f"Active sale retrieved for table {table}",
            LogLevel.INFO,
            {
                "table": table,
                "sale_id": active_sale_id
            },
            user_id=current_user.id,
            user_email=current_user.email
        )
        
    except HTTPException:
        raise
    except Exception as e:
        error_msg = f"Error retrieving active sale for table {table}: {e}"
        logger.error(error_msg)
        structured_logger.log_order_event(
            "Error retrieving active sale",
            LogLevel.ERROR,
            {
                "table": table,
                "error": str(e),
                "error_type": type(e).__name__
            },
            user_id=current_user.id,
            user_email=current_user.email
        )
        raise HTTPException(status_code=500, detail="Error interno del servidor")

    # Update user reward progress
    try:
        new_progress = user.reward_progress + beers_for_promo * 10
        user_data_service.set_reward_progress(user.id, new_progress)
        
        logger.info(f"Updated reward progress for user {user.email}: {user.reward_progress} -> {new_progress}")
        structured_logger.log_user_event(
            f"Reward progress updated",
            LogLevel.INFO,
            {
                "user_id": user.id,
                "old_progress": user.reward_progress,
                "new_progress": new_progress,
                "beers_count": beers_for_promo,
                "points_added": beers_for_promo * 10,
                "table": table
            },
            user_id=user.id,
            user_email=user.email
        )
        
    except Exception as e:
        error_msg = f"Error updating reward progress for user {user.id}: {e}"
        logger.error(error_msg)
        structured_logger.log_database_event(
            "Failed to update reward progress",
            LogLevel.ERROR,
            {
                "user_id": user.id,
                "beers_for_promo": beers_for_promo,
                "error": str(e),
                "error_type": type(e).__name__
            },
            user_id=user.id,
            user_email=user.email
        )
        # Don't fail the order for this, just log it
        new_progress = user.reward_progress

    # Create sale record
    try:
        sale = sale_data_service.create(
            order.customerId,
            active_sale_id or uuid4().hex,
            order.totalAmount,
            order.table,
            [item.id for item in items],
            [item.quantity for item in items]
        )   
        
        if sale > 0:
            logger.info(f"Sale created successfully: ID {sale}")
            structured_logger.log_order_event(
                f"Sale record created successfully",
                LogLevel.INFO,
                {
                    "sale_id": sale,
                    "customer_id": order.customerId,
                    "table": table,
                    "total_amount": order.totalAmount,
                    "fudo_sale_id": active_sale_id,
                    "items_count": len(items)
                },
                user_id=current_user.id,
                user_email=current_user.email
            )
        else:
            error_msg = "Failed to create sale record"
            logger.error(error_msg)
            structured_logger.log_database_event(
                "Sale creation failed",
                LogLevel.ERROR,
                {
                    "customer_id": order.customerId,
                    "table": table,
                    "total_amount": order.totalAmount,
                    "fudo_sale_id": active_sale_id
                },
                user_id=current_user.id,
                user_email=current_user.email
            )
            return JSONResponse(status_code=500, content={"message": "Error interno del servidor"})
            
    except Exception as e:
        error_msg = f"Error creating sale record: {e}"
        logger.error(error_msg)
        structured_logger.log_database_event(
            "Sale creation error",
            LogLevel.ERROR,
            {
                "customer_id": order.customerId,
                "table": table,
                "error": str(e),
                "error_type": type(e).__name__
            },
            user_id=current_user.id,
            user_email=current_user.email
        )
        return JSONResponse(status_code=500, content={"message": "Error interno del servidor"})

    # Print order
    try:
        order_for_print = Order(
            table=table,
            items=[Item(name=product.name, price=product.price or 0, quantity=item.quantity) for product, item in zip(products, items)],
            customerName=user.name,
            totalAmount=order.totalAmount,
            orderDate=order.orderDate
        )
        
        ps.print_order(order_for_print)
        
        logger.info(f"Order printed successfully for table {table}")
        structured_logger.log_print_event(
            f"Order printed successfully for table {table}",
            LogLevel.INFO,
            {
                "table": table,
                "customer_name": user.name,
                "total_amount": order.totalAmount,
                "items_count": len(items),
                "sale_id": sale
            },
            user_id=current_user.id,
            user_email=current_user.email
        )
        
    except Exception as e:
        error_msg = f"Error printing order for table {table}: {e}"
        logger.error(error_msg)
        structured_logger.log_print_event(
            f"Order print failed for table {table}",
            LogLevel.ERROR,
            {
                "table": table,
                "customer_name": user.name,
                "error": str(e),
                "error_type": type(e).__name__,
                "sale_id": sale
            },
            user_id=current_user.id,
            user_email=current_user.email
        )
        # Don't fail the order for print issues, just log it

    # Log order (legacy function)
    try:
        log_order(user.name, order.table, order_date=order.orderDate, items=[product.name for product in products])
        
        structured_logger.log_order_event(
            f"Order completed successfully for table {table}",
            LogLevel.INFO,
            {
                "table": table,
                "customer_id": user.id,
                "customer_name": user.name,
                "customer_email": user.email,
                "total_amount": order.totalAmount,
                "items": [{"name": product.name, "quantity": item.quantity, "price": product.price} for product, item in zip(products, items)],
                "sale_id": sale,
                "new_reward_progress": new_progress,
                "beers_for_promo": beers_for_promo
            },
            user_id=user.id,
            user_email=user.email
        )
        
    except Exception as e:
        logger.error(f"Error in legacy order logging: {e}")
        # Don't fail the order for logging issues

    logger.info(f"Order processing completed successfully for table {table}, sale ID: {sale}")
    return JSONResponse({"message": SuccessResponse.ORDER_SUCCESS, "new_progress": new_progress})