Updated how wix forms are logged.

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"
+    logs_dir = Path("logs/push_requests")
-    if not Path.exists(logs_dir):
+    if not logs_dir.exists():
-        Path.mkdir(logs_dir, mode=0o755, exist_ok=True)
+        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("Received Wix form data at %s", 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}")
 
     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 = (
+    hotel_code = data.get("field:hotelid", None)
-        data.get("field:hotelid")
+
-        or data.get("hotelid")
+    if hotel_code is None:
-        or request.app.state.config.get("default_hotel_code")
+        _LOGGER.warning("No hotel_code provided in form data, using default")
-        or "123"  # fallback
+
-    )
+        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()
+        log_entry = {
-        _LOGGER.exception("Stack trace for handle_wix_form: %s", traceback_str)
+            "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")
 
 

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 (
+                assert customer.email_address == "john.smith@example.com", (
-                    customer.email_address == "john.smith@example.com"
+                    "Email updated"
-                ), "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(
+    def test_form_submission_triggers_event(self, client, sample_wix_form_data):
-        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