import tempfile from flask import jsonify import subprocess import os import logging import hmac import hashlib import yaml import datetime import uuid import traceback from pathlib import Path from dotenv import load_dotenv from sqlalchemy.orm import joinedload from ..utils.db.models import Subscription, Payment from ..utils.db.operations import DatabaseManager from ..utils.db.models import SubscriptionStatus from ..utils.ansible_logger import AnsibleLogger load_dotenv() # Enhanced logging configuration logging.basicConfig( level=logging.INFO, format='%(asctime)s - %(name)s - %(levelname)s - %(message)s', handlers=[ logging.StreamHandler(), logging.FileHandler('vpn_provisioner.log') ] ) logger = logging.getLogger(__name__) ansible_logger = AnsibleLogger() # Constants BASE_DIR = Path(__file__).resolve().parent.parent.parent PLAYBOOK_PATH = BASE_DIR / 'ansible' / 'playbooks' / 'vpn_provision.yml' CLEANUP_PLAYBOOK = BASE_DIR / 'ansible' / 'playbooks' / 'vpn_cleanup.yml' class WebhookError(Exception): """Custom exception for webhook handling errors""" pass def get_vault_values(): """Get decrypted values from Ansible vault""" try: vault_pass = os.getenv('ANSIBLE_VAULT_PASSWORD') if not vault_pass: raise WebhookError("Vault password not found in environment variables") with tempfile.NamedTemporaryFile(mode='w', delete=False) as vault_pass_file: vault_pass_file.write(vault_pass) vault_pass_file.flush() # Execute ansible-vault with error checking result = subprocess.run( ['ansible-vault', 'view', str(BASE_DIR / 'ansible/group_vars/vpn_servers/vault.yml')], capture_output=True, text=True, env={**os.environ, 'ANSIBLE_VAULT_PASSWORD_FILE': vault_pass_file.name}, check=True # This will raise CalledProcessError if command fails ) os.unlink(vault_pass_file.name) try: vault_contents = yaml.safe_load(result.stdout) if not vault_contents: raise WebhookError("Empty vault contents") # Validate required vault values required_keys = ['btcpay_base_url', 'btcpay_api_key', 'btcpay_store_id', 'webhook_secret'] missing_keys = [key for key in required_keys if key not in vault_contents] if missing_keys: raise WebhookError(f"Missing required vault values: {', '.join(missing_keys)}") vault_contents['webhook_full_url'] = ( f"{vault_contents['btcpay_base_url']}" f"{vault_contents.get('btcpay_webhook_path', '/webhook/vpn')}" ) return vault_contents except yaml.YAMLError as e: raise WebhookError(f"Failed to parse vault contents: {str(e)}") except subprocess.CalledProcessError as e: logger.error(f"Ansible vault command failed: {e.stderr}") raise WebhookError("Failed to decrypt vault") except Exception as e: logger.error(f"Error reading vault: {traceback.format_exc()}") raise WebhookError(f"Vault operation failed: {str(e)}") def verify_signature(payload_body: bytes, signature_header: str) -> bool: """ Verify BTCPay webhook signature with proper error handling Args: payload_body: Raw request body bytes signature_header: BTCPay-Sig header value Returns: bool: True if signature is valid """ try: if not signature_header: logger.error("Missing signature header") return False vault_values = get_vault_values() webhook_secret = vault_values.get('webhook_secret') if not webhook_secret: logger.error("Webhook secret not found in vault") return False # Generate expected signature expected_signature = hmac.new( webhook_secret.encode('utf-8'), payload_body, hashlib.sha256 ).hexdigest() # Constant-time comparison return hmac.compare_digest( signature_header.lower(), f"sha256={expected_signature}".lower() ) except Exception as e: logger.error(f"Signature verification failed: {traceback.format_exc()}") return False def run_ansible_playbook(invoice_id: str, cleanup: bool = False, extra_vars: dict = None) -> subprocess.CompletedProcess: """Run the appropriate Ansible playbook with logging""" try: operation_type = 'cleanup' if cleanup else 'provision' vault_pass = os.getenv('ANSIBLE_VAULT_PASSWORD') if not vault_pass: raise WebhookError("Vault password not found in environment variables") with tempfile.NamedTemporaryFile(mode='w', delete=False) as vault_pass_file: vault_pass_file.write(vault_pass) vault_pass_file.flush() playbook = CLEANUP_PLAYBOOK if cleanup else PLAYBOOK_PATH cmd = [ 'ansible-playbook', str(playbook), '-i', str(BASE_DIR / 'inventory.ini'), '-e', f'invoice_id={invoice_id}' ] if extra_vars: for key, value in extra_vars.items(): cmd.extend(['-e', f'{key}={value}']) cmd.extend([ '--vault-password-file', vault_pass_file.name, '-vvv' ]) logger.info(f"Running ansible-playbook command: {' '.join(cmd)}") # Run ansible-playbook without check=True to handle errors better result = subprocess.run( cmd, capture_output=True, text=True ) # Log detailed output for debugging logger.info("Ansible STDOUT:") logger.info(result.stdout) if result.stderr: logger.error("Ansible STDERR:") logger.error(result.stderr) # Check return code manually if result.returncode != 0: logger.error(f"Ansible playbook failed with return code {result.returncode}") logger.error(f"Error output: {result.stderr}") raise WebhookError(f"Failed {operation_type} for subscription {invoice_id}") # Log successful operation is_test = bool(extra_vars and extra_vars.get('is_test')) ansible_logger.log_operation( invoice_id, operation_type, result, is_test=is_test ) # Check for fatal errors in output if "fatal:" in result.stdout or "fatal:" in result.stderr: logger.error("Fatal error detected in Ansible output") raise WebhookError("Ansible playbook reported fatal error") logger.info(f"Successfully completed {operation_type} for {invoice_id}") return result except subprocess.CalledProcessError as e: logger.error(f"Playbook execution failed: {e.stderr}") # Log failed operation ansible_logger.log_operation( invoice_id, operation_type, e, is_test=bool(extra_vars and extra_vars.get('is_test')) ) raise WebhookError(f"Failed {operation_type} for subscription {invoice_id}: {e.stderr}") except Exception as e: logger.error(f"Error running playbook: {traceback.format_exc()}") raise WebhookError(f"Playbook execution failed: {str(e)}") finally: if 'vault_pass_file' in locals(): os.unlink(vault_pass_file.name) def handle_subscription_status(data: dict) -> tuple: """Handle SubscriptionStatusUpdated webhook""" try: sub_id = data.get('subscriptionId') status = data.get('status') if not sub_id or not status: return jsonify({"error": "Missing required fields"}), 400 logger.info(f"Processing subscription status update: {sub_id} -> {status}") subscription = DatabaseManager.get_subscription_by_invoice(sub_id) if not subscription: logger.error(f"Subscription {sub_id} not found") return jsonify({"error": "Subscription not found"}), 404 if status == 'Active': DatabaseManager.activate_subscription(sub_id) else: # Run cleanup for inactive subscriptions try: result = run_ansible_playbook(sub_id, cleanup=True) logger.info(f"Cleanup playbook completed for {sub_id}: {result.stdout}") except WebhookError as e: logger.error(f"Failed to clean up subscription {sub_id}: {str(e)}") DatabaseManager.expire_subscription(subscription.id) logger.info(f"Subscription {sub_id} is no longer active") return jsonify({ "status": "success", "message": f"Subscription {sub_id} status updated to {status}" }), 200 except Exception as e: logger.error(f"Error handling subscription status: {traceback.format_exc()}") return jsonify({"error": str(e)}), 500 def handle_test_webhook(data, webhook_type): """Handle test webhook with proper Ansible execution and logging""" logger.info(f"Processing test webhook: {webhook_type}") invoice_id = data.get('invoiceId', '') if not invoice_id.startswith('__test__'): logger.error("Invalid test invoice ID format") return jsonify({"error": "Invalid test invoice ID"}), 400 # Process both types of invoice settlement webhooks if webhook_type in ['InvoiceSettled', 'InvoicePaymentSettled']: try: # For test invoices, create a 30-minute subscription test_duration = 30 # minutes test_user_id = f"test_{uuid.uuid4()}" test_pubkey = f"TEST_KEY_{uuid.uuid4()}" logger.info(f"Creating test subscription for {test_duration} minutes") # Create test subscription entry - now returns a dictionary subscription_data = DatabaseManager.create_subscription( user_id=test_user_id, invoice_id=invoice_id, public_key=test_pubkey, duration_hours=0.5 # 30 minutes ) if not subscription_data: logger.error("Failed to create test subscription") return jsonify({"error": "Failed to create test subscription"}), 500 logger.info(f"Created test subscription: {subscription_data['id']}") # Run the provisioning playbook with test flag try: logger.info("Running test VPN provision playbook") result = run_ansible_playbook( invoice_id=invoice_id, cleanup=False, extra_vars={ "is_test": True, "test_duration_minutes": test_duration, "test_public_key": test_pubkey } ) if result.returncode == 0: logger.info(f"Test VPN provisioned successfully for {test_duration} minutes") # Activate subscription and record payment activated_data = DatabaseManager.activate_subscription(invoice_id) if activated_data: DatabaseManager.record_payment( test_user_id, subscription_data['id'], # Use dictionary key instead of object attribute invoice_id, data.get('amount', 0) ) cleanup_time = datetime.datetime.utcnow() + datetime.timedelta(minutes=test_duration) logger.info(f"Scheduling cleanup for {cleanup_time}") return jsonify({ "status": "success", "message": f"Test VPN provisioned for {test_duration} minutes", "test_user_id": test_user_id, "subscription_id": subscription_data['id'], # Include subscription ID in response "assigned_ip": subscription_data['assigned_ip'], # Include assigned IP "cleanup_scheduled": cleanup_time.isoformat() }), 200 else: logger.error("Failed to activate subscription") return jsonify({"error": "Failed to activate subscription"}), 500 logger.error(f"Test provisioning failed: {result.stderr}") return jsonify({"error": "Test provisioning failed"}), 500 except WebhookError as e: logger.error(f"Error in test provision playbook: {str(e)}") return jsonify({"error": str(e)}), 500 except Exception as e: logger.error(f"Error in test provisioning: {str(e)}") logger.error(traceback.format_exc()) return jsonify({"error": str(e)}), 500 # Handle test subscription status updates elif webhook_type == 'SubscriptionStatusUpdated': return handle_subscription_status(data) # For other test webhook types, just acknowledge else: logger.info(f"Acknowledged test webhook: {webhook_type}") return jsonify({ "status": "success", "message": f"Test webhook {webhook_type} acknowledged" }), 200 def handle_payment_webhook(request) -> tuple: """Handle BTCPay Server webhook for VPN provisioning""" try: vault_values = get_vault_values() logger.info(f"Processing webhook on endpoint: {vault_values['webhook_full_url']}") # Verify signature signature = request.headers.get('BTCPay-Sig') if not signature: logger.error("Missing BTCPay-Sig header") return jsonify({"error": "Missing signature"}), 401 is_valid = verify_signature(request.get_data(), signature) if not is_valid: logger.error("Invalid signature") return jsonify({"error": "Invalid signature"}), 401 # Parse and validate payload try: data = request.json except Exception as e: logger.error(f"Invalid JSON payload: {str(e)}") return jsonify({"error": "Invalid JSON"}), 400 if not data: return jsonify({"error": "Empty payload"}), 400 logger.info(f"Received webhook data: {data}") # Extract webhook type and invoice ID webhook_type = data.get('type') invoice_id = data.get('invoiceId', '') if not webhook_type: return jsonify({"error": "Missing webhook type"}), 400 # Handle test webhooks with special processing if invoice_id.startswith('__test__'): return handle_test_webhook(data, webhook_type) # Handle different webhook types for production if webhook_type == 'SubscriptionStatusUpdated': return handle_subscription_status(data) elif webhook_type in ['InvoiceSettled', 'InvoicePaymentSettled']: if not invoice_id: logger.error("Missing invoiceId in webhook data") return jsonify({"error": "Missing invoiceId"}), 400 from ..utils.db import get_session with get_session() as session: try: # Check if payment already exists existing_payment = session.query(Payment).filter( Payment.invoice_id == invoice_id ).first() if existing_payment: logger.info(f"Payment already recorded for invoice {invoice_id}") return jsonify({ "status": "success", "message": "Payment already processed", "invoice_id": invoice_id }), 200 # Run VPN provisioning logger.info(f"Starting VPN provisioning for invoice {invoice_id}") result = run_ansible_playbook(invoice_id) # Update subscription status within session subscription = session.query(Subscription).filter( Subscription.invoice_id == invoice_id ).options(joinedload(Subscription.user)).first() if subscription: # Activate subscription subscription.status = SubscriptionStatus.ACTIVE # Record payment only if it doesn't exist payment = Payment( user_id=subscription.user_id, subscription_id=subscription.id, invoice_id=invoice_id, amount=data.get('amount', 0) ) session.add(payment) # Commit all changes session.commit() logger.info(f"VPN provisioning completed for invoice {invoice_id}") return jsonify({ "status": "success", "invoice_id": invoice_id, "message": "VPN provisioning completed" }), 200 else: logger.error(f"Subscription not found for invoice {invoice_id}") return jsonify({"error": "Subscription not found"}), 404 except Exception as e: session.rollback() logger.error(f"VPN provisioning failed: {str(e)}") logger.error(traceback.format_exc()) return jsonify({ "error": "Provisioning failed", "details": str(e) }), 500 else: logger.info(f"Received {webhook_type} webhook - no action required") return jsonify({ "status": "success", "message": f"Webhook {webhook_type} acknowledged" }), 200 except WebhookError as e: logger.error(f"Webhook error: {str(e)}") return jsonify({"error": str(e)}), 500 except Exception as e: logger.error(f"Unexpected error: {traceback.format_exc()}") return jsonify({"error": "Internal server error"}), 500