diff --git a/src/alpine_bits_python/api.py b/src/alpine_bits_python/api.py index 422e26b..273d763 100644 --- a/src/alpine_bits_python/api.py +++ b/src/alpine_bits_python/api.py @@ -128,14 +128,16 @@ async def push_listener(customer: DBCustomer, reservation: DBReservation, hotel) # save push request to file - logs_dir = "logs/push_requests" - if not Path.exists(logs_dir): - Path.mkdir(logs_dir, mode=0o755, exist_ok=True) + logs_dir = Path("logs/push_requests") + if not logs_dir.exists(): + logs_dir.mkdir(parents=True, mode=0o755, exist_ok=True) stat_info = os.stat(logs_dir) _LOGGER.info( - f"Created directory owner: uid:{stat_info.st_uid}, gid:{stat_info.st_gid}" + "Created directory owner: uid:%s, gid:%s", + stat_info.st_uid, + stat_info.st_gid ) - _LOGGER.info(f"Directory mode: {oct(stat_info.st_mode)[-3:]}") + _LOGGER.info("Directory mode: %s", oct(stat_info.st_mode)[-3:]) log_filename = f"{logs_dir}/alpinebits_push_{hotel_id}_{reservation.unique_id}_{datetime.now().strftime('%Y%m%d_%H%M%S')}.xml" with open(log_filename, "w", encoding="utf-8") as f: @@ -154,16 +156,21 @@ async def push_listener(customer: DBCustomer, reservation: DBReservation, hotel) push_endpoint["url"], json=payload, headers=headers, timeout=10 ) _LOGGER.info( - f"Push event fired to {push_endpoint['url']} for hotel {hotel['hotel_id']}, status: {resp.status_code}" + "Push event fired to %s for hotel %s, status: %s", + push_endpoint['url'], + hotel['hotel_id'], + resp.status_code ) if resp.status_code not in [200, 201, 202]: _LOGGER.warning( - f"Push endpoint returned non-success status {resp.status_code}: {resp.text}" + "Push endpoint returned non-success status %s: %s", + resp.status_code, + resp.text ) except Exception as e: - _LOGGER.exception(f"Push event failed for hotel {hotel['hotel_id']}: {e}") + _LOGGER.exception("Push event failed for hotel %s: %s", hotel['hotel_id'], e) # Optionally implement retry logic here@asynccontextmanager @@ -308,34 +315,7 @@ async def process_wix_form_submission(request: Request, data: dict[str, Any], db """Shared business logic for handling Wix form submissions (test and production).""" timestamp = datetime.now().isoformat() - _LOGGER.info(f"Received Wix form data at {timestamp}") - # _LOGGER.info(f"Data keys: {list(data.keys())}") - # _LOGGER.info(f"Full data: {json.dumps(data, indent=2)}") - log_entry = { - "timestamp": timestamp, - "client_ip": request.client.host if request.client else "unknown", - "headers": dict(request.headers), - "data": data, - "origin_header": request.headers.get("origin"), - "all_headers": dict(request.headers), - } - logs_dir = "logs" - if not os.path.exists(logs_dir): - os.makedirs(logs_dir, mode=0o755, exist_ok=True) - stat_info = os.stat(logs_dir) - _LOGGER.info( - f"Created directory owner: uid:{stat_info.st_uid}, gid:{stat_info.st_gid}" - ) - _LOGGER.info(f"Directory mode: {oct(stat_info.st_mode)[-3:]}") - log_filename = ( - f"{logs_dir}/wix_test_data_{datetime.now().strftime('%Y%m%d_%H%M%S')}.json" - ) - with open(log_filename, "w", encoding="utf-8") as f: - json.dump(log_entry, f, indent=2, default=str, ensure_ascii=False) - file_stat = os.stat(log_filename) - _LOGGER.info(f"Created file owner: uid:{file_stat.st_uid}, gid:{file_stat.st_gid}") - _LOGGER.info(f"File mode: {oct(file_stat.st_mode)[-3:]}") - _LOGGER.info(f"Data logged to: {log_filename}") + _LOGGER.info("Received Wix form data at %s", timestamp) data = data.get("data") # Handle nested "data" key if present @@ -384,7 +364,7 @@ async def process_wix_form_submission(request: Request, data: dict[str, Any], db age = int(data[k]) children_ages.append(age) except ValueError: - _LOGGER.warning(f"Invalid age value for {k}: {data[k]}") + _LOGGER.warning("Invalid age value for %s: %s", k, data[k]) offer = data.get("field:angebot_auswaehlen") @@ -448,12 +428,12 @@ async def process_wix_form_submission(request: Request, data: dict[str, Any], db # Determine hotel_code and hotel_name # Priority: 1) Form field, 2) Configuration default, 3) Hardcoded fallback - hotel_code = ( - data.get("field:hotelid") - or data.get("hotelid") - or request.app.state.config.get("default_hotel_code") - or "123" # fallback - ) + hotel_code = data.get("field:hotelid", None) + + if hotel_code is None: + _LOGGER.warning("No hotel_code provided in form data, using default") + + hotel_code = request.app.state.config.get("default_hotel_code", "123") hotel_name = ( data.get("field:hotelname") @@ -517,13 +497,16 @@ async def process_wix_form_submission(request: Request, data: dict[str, Any], db "No hotel_code in reservation, skipping push notifications" ) - asyncio.create_task(push_event()) + # Create task and store reference to prevent it from being garbage collected + # The task runs independently and we don't need to await it here + task = asyncio.create_task(push_event()) + # Add done callback to log any exceptions that occur in the background task + task.add_done_callback(lambda t: t.exception() if not t.cancelled() else None) return { "status": "success", "message": "Wix form data received successfully", "received_keys": list(data.keys()), - "data_logged_to": log_filename, "timestamp": timestamp, "note": "No authentication required for this endpoint", } @@ -579,11 +562,31 @@ async def handle_wix_form( return await process_wix_form_submission(request, data, db_session) except Exception as e: _LOGGER.exception("Error in handle_wix_form: %s", e) - # log stacktrace + + # Log error data to file asynchronously import traceback - traceback_str = traceback.format_exc() - _LOGGER.exception("Stack trace for handle_wix_form: %s", traceback_str) + log_entry = { + "timestamp": datetime.now().isoformat(), + "client_ip": request.client.host if request.client else "unknown", + "headers": dict(request.headers), + "data": data, + "error": str(e), + "traceback": traceback.format_exc(), + } + + # Use asyncio to run file I/O in thread pool to avoid blocking + logs_dir = Path("logs/errors") + await asyncio.to_thread(logs_dir.mkdir, parents=True, mode=0o755, exist_ok=True) + + log_filename = logs_dir / f"wix_error_{datetime.now().strftime('%Y%m%d_%H%M%S')}.json" + await asyncio.to_thread( + log_filename.write_text, + json.dumps(log_entry, indent=2, default=str, ensure_ascii=False), + encoding="utf-8" + ) + + _LOGGER.error("Error data logged to: %s", log_filename) raise HTTPException(status_code=500, detail="Error processing Wix form data") @@ -599,7 +602,32 @@ async def handle_wix_form_test( try: return await process_wix_form_submission(request, data, db_session) except Exception as e: - _LOGGER.exception(f"Error in handle_wix_form_test: {e!s}") + _LOGGER.exception("Error in handle_wix_form_test: %s", e) + + # Log error data to file asynchronously + import traceback + + log_entry = { + "timestamp": datetime.now().isoformat(), + "client_ip": request.client.host if request.client else "unknown", + "headers": dict(request.headers), + "data": data, + "error": str(e), + "traceback": traceback.format_exc(), + } + + # Use asyncio to run file I/O in thread pool to avoid blocking + logs_dir = Path("logs/errors") + await asyncio.to_thread(logs_dir.mkdir, parents=True, mode=0o755, exist_ok=True) + + log_filename = logs_dir / f"wix_test_error_{datetime.now().strftime('%Y%m%d_%H%M%S')}.json" + await asyncio.to_thread( + log_filename.write_text, + json.dumps(log_entry, indent=2, default=str, ensure_ascii=False), + encoding="utf-8" + ) + + _LOGGER.error("Error data logged to: %s", log_filename) raise HTTPException(status_code=500, detail="Error processing test data") @@ -877,7 +905,7 @@ async def alpinebits_server_handshake( status_code=400, detail="ERROR: Missing required 'action' parameter" ) - _LOGGER.info(f"AlpineBits action: {action}") + _LOGGER.info("AlpineBits action: %s", action) # Get optional request XML request_xml = form_data.get("request") @@ -923,7 +951,7 @@ async def alpinebits_server_handshake( # Re-raise HTTP exceptions (auth errors, etc.) raise except Exception as e: - _LOGGER.exception(f"Error in AlpineBits handshake: {e!s}") + _LOGGER.exception("Error in AlpineBits handshake: %s", e) raise HTTPException(status_code=500, detail="Internal server error") diff --git a/tests/test_api.py b/tests/test_api.py index 1fc75dd..f70e736 100644 --- a/tests/test_api.py +++ b/tests/test_api.py @@ -195,7 +195,6 @@ class TestWixWebhookEndpoint: data = response.json() assert data["status"] == "success" assert "timestamp" in data - assert "data_logged_to" in data def test_wix_webhook_creates_customer_and_reservation( self, client, sample_wix_form_data @@ -320,7 +319,6 @@ class TestWixWebhookEndpoint: engine = client.app.state.engine async_session = async_sessionmaker(engine, expire_on_commit=False) async with async_session() as session: - # Check only one customer exists result = await session.execute(select(Customer)) customers = result.scalars().all() @@ -330,9 +328,9 @@ class TestWixWebhookEndpoint: # Verify customer was updated with new information assert customer.given_name == "John" assert customer.surname == "Smith", "Last name updated" - assert ( - customer.email_address == "john.smith@example.com" - ), "Email updated" + assert customer.email_address == "john.smith@example.com", ( + "Email updated" + ) assert customer.phone == "+9876543210", "Phone updated" assert customer.name_prefix == "Dr.", "Prefix updated" assert customer.language == "de", "Language updated" @@ -630,9 +628,7 @@ class TestAuthentication: class TestEventDispatcher: """Test event dispatcher and push notifications.""" - def test_form_submission_triggers_event( - self, client, sample_wix_form_data - ): + def test_form_submission_triggers_event(self, client, sample_wix_form_data): """Test that form submission triggers event dispatcher.""" # Just verify the endpoint works with the event dispatcher # The async task runs in background and doesn't affect response