diff --git a/make_post_sell/lib/crypto_payment_rescue.py b/make_post_sell/lib/crypto_payment_rescue.py index 950ec9f..eb2f8c7 100644 --- a/make_post_sell/lib/crypto_payment_rescue.py +++ b/make_post_sell/lib/crypto_payment_rescue.py @@ -7,9 +7,12 @@ Handles: - Expired quotes: Refund late payments minus 9% restocking fee """ +import logging from decimal import Decimal from ..models.user_crypto_refund_address import get_user_crypto_refund_address +logger = logging.getLogger(__name__) + RESTOCKING_FEE_PERCENT = Decimal("0.09") # 9% restocking fee OVERPAYMENT_THRESHOLD_PERCENT = Decimal("0.05") # 5% overpayment allowed before refund @@ -183,12 +186,20 @@ class PaymentRescue: else "koinu" if coin_type == "DOGE" else "atomic units" ) - logger.info(f"Attempting to refund payment {refund_details['payment_id']}") - logger.info( - f"Refund amount: {refund_amount_coin} {coin_type} ({refund_amount_atomic} {atomic_unit_name})" - ) - logger.info(f"Refund address: {refund_details['refund_address']}") - logger.info(f"Refund reason: {refund_details['reason']}") + if payment: + logger.info(f"Attempting to refund: {payment}") + logger.info( + f"Refund amount: {refund_amount_coin} {coin_type} ({refund_amount_atomic} {atomic_unit_name})" + ) + logger.info(f"Refund address: {refund_details['refund_address']}") + logger.info(f"Refund reason: {refund_details['reason']}") + else: + logger.info(f"Attempting to refund payment {refund_details['payment_id']}") + logger.info( + f"Refund amount: {refund_amount_coin} {coin_type} ({refund_amount_atomic} {atomic_unit_name})" + ) + logger.info(f"Refund address: {refund_details['refund_address']}") + logger.info(f"Refund reason: {refund_details['reason']}") # Check if incoming payment has enough confirmations before allowing refund from .crypto_watcher import get_coin_config @@ -197,9 +208,7 @@ class PaymentRescue: required_confirmations = coin_config.get("confirmations_required", 10) if payment and payment.current_confirmations < required_confirmations: - logger.info( - f"Refund delayed - incoming payment has {payment.current_confirmations}/{required_confirmations} confirmations" - ) + logger.info(f"Refund delayed - insufficient confirmations: {payment}") return { "success": False, "error": f"Incoming payment needs {required_confirmations - payment.current_confirmations} more confirmations before refund", @@ -283,7 +292,12 @@ class PaymentRescue: else: raise ValueError(f"Refund not supported for coin type: {coin_type}") - logger.info(f"Refund transaction successful: {tx_result}") + if payment: + logger.info(f"Refund transaction successful: {payment} - {tx_result}") + else: + logger.info( + f"Refund transaction successful for payment {refund_details['payment_id']}: {tx_result}" + ) return { "success": True, @@ -293,7 +307,10 @@ class PaymentRescue: } except Exception as e: - logger.error( - f"Refund failed for payment {refund_details['payment_id']}: {e}" - ) + if payment: + logger.error(f"Refund failed: {payment} - {e}") + else: + logger.error( + f"Refund failed for payment {refund_details['payment_id']}: {e}" + ) return {"success": False, "error": str(e), "refund_details": refund_details} diff --git a/make_post_sell/lib/crypto_watcher.py b/make_post_sell/lib/crypto_watcher.py index ce7a861..2813123 100644 --- a/make_post_sell/lib/crypto_watcher.py +++ b/make_post_sell/lib/crypto_watcher.py @@ -26,6 +26,89 @@ from ..models.user_crypto_refund_address import UserCryptoRefundAddress logger = logging.getLogger(__name__) +class CryptoWatcherLogger: + """Centralized logging helper for crypto watcher operations.""" + + def __init__(self, logger_instance=None): + self.logger = logger_instance or logger + + def payment_info(self, payment, message: str, **kwargs): + """Log payment-related info with standardized format.""" + context = f" {kwargs.get('context', '')}" if kwargs.get("context") else "" + self.logger.info(f"{message}: {payment}{context}") + + def payment_warning(self, payment, message: str, **kwargs): + """Log payment-related warning with standardized format.""" + context = f" {kwargs.get('context', '')}" if kwargs.get("context") else "" + self.logger.warning(f"{message}: {payment}{context}") + + def payment_error(self, payment, message: str, error=None, **kwargs): + """Log payment-related error with standardized format.""" + context = f" {kwargs.get('context', '')}" if kwargs.get("context") else "" + error_detail = f" - {error}" if error else "" + self.logger.error(f"{message}: {payment}{context}{error_detail}") + + def payment_debug(self, payment, message: str, **kwargs): + """Log payment-related debug with standardized format.""" + context = f" {kwargs.get('context', '')}" if kwargs.get("context") else "" + self.logger.debug(f"{message}: {payment}{context}") + + def transaction_processing( + self, payment, action: str, tx_hash: str = None, amount: int = None + ): + """Log transaction processing events.""" + tx_info = f" tx:{tx_hash[:16]}..." if tx_hash else "" + amount_info = f" amount:{amount}" if amount is not None else "" + self.logger.info(f"{action}: {payment}{tx_info}{amount_info}") + + def state_transition( + self, payment, old_status: str, new_status: str, reason: str = "" + ): + """Log state transitions with context.""" + reason_info = f" ({reason})" if reason else "" + self.logger.info( + f"State transition: {payment} {old_status} → {new_status}{reason_info}" + ) + + def refund_operation( + self, payment, operation: str, tx_hash: str = None, amount: int = None + ): + """Log refund operations.""" + tx_info = f" tx:{tx_hash[:16]}..." if tx_hash else "" + amount_info = f" amount:{amount}" if amount is not None else "" + self.logger.info(f"Refund {operation}: {payment}{tx_info}{amount_info}") + + def sweep_operation( + self, payment, operation: str, tx_hash: str = None, amount: int = None + ): + """Log sweep operations.""" + tx_info = f" tx:{tx_hash[:16]}..." if tx_hash else "" + amount_info = f" amount:{amount}" if amount is not None else "" + self.logger.info(f"Sweep {operation}: {payment}{tx_info}{amount_info}") + + def confirmation_update(self, payment, old_count: int, new_count: int): + """Log confirmation count updates.""" + self.logger.info(f"Confirmations updated: {payment} {old_count} → {new_count}") + + def processing_cycle( + self, message: str, payment_count: int = None, cycle_info: str = "" + ): + """Log processing cycle information.""" + count_info = f" ({payment_count} payments)" if payment_count is not None else "" + cycle_detail = f" {cycle_info}" if cycle_info else "" + self.logger.info(f"Processing cycle: {message}{count_info}{cycle_detail}") + + def error_with_context(self, message: str, error, payment=None, context: str = ""): + """Log errors with payment context when available.""" + payment_info = f" {payment}" if payment else "" + context_info = f" ({context})" if context else "" + self.logger.error(f"{message}{payment_info}{context_info} - {error}") + + +# Create logger instance for module use +log = CryptoWatcherLogger() + + def _get_user_refund_address(dbsession, user_id, coin_type): """Get user's saved refund address for the given coin type.""" if not user_id: @@ -152,8 +235,9 @@ def _create_duplicate_payment(original_payment, tx, coin_type, dbsession=None): dbsession, original_payment.user_id, coin_type ) if refund_address: - logger.info( - f"Using saved refund address for user {original_payment.user_id}: {refund_address[:16]}..." + log.payment_info( + original_payment, + f"Using saved refund address: {refund_address[:16]}...", ) # Create new payment object for this duplicate using proper constructor @@ -222,17 +306,15 @@ def _should_process_late_payment(payment, tx): # DOGE/BTC amount is already in atomic units tx_amount = int(float(tx.get("amount", 0)) * 1e8) - logger.info( - f"_should_process_late_payment check: payment {payment.id}, status={payment.status}, " - f"received_amount={payment.received_amount}, tx_amount={tx_amount}" - ) + log.payment_debug(payment, f"Late payment check - tx_amount={tx_amount}") # Edge Case: Any payment with non-pending status means invalid multiple payment # ALL multiple payments are invalid - no legitimate double payments exist if payment.status != CryptoPayment.STATUS_PENDING and tx_amount > 0: current_total = payment.received_amount + tx_amount - logger.info( - f"INVALID multiple payment detected for {payment.status} payment {payment.id}: received {payment.received_amount}, new {tx_amount}, total {current_total}" + log.payment_warning( + payment, + f"Invalid multiple payment detected - new {tx_amount}, total {current_total}", ) # Log specific scenarios for clarity @@ -240,25 +322,31 @@ def _should_process_late_payment(payment, tx): CryptoPayment.STATUS_EXPIRED, CryptoPayment.STATUS_CANCELLED, ]: - logger.info(f"Late payment to {payment.status} quote {payment.id}") + log.payment_info( + payment, "Late payment detected", context="expired/cancelled quote" + ) elif payment.status in [ CryptoPayment.STATUS_CONFIRMED, CryptoPayment.STATUS_CONFIRMED_OVERPAY, CryptoPayment.STATUS_CONFIRMED_OVERPAY_REFUNDED, CryptoPayment.STATUS_CONFIRMED_OVERPAY_REFUNDED_COMPLETE, ]: - logger.info(f"Double payment to completed order {payment.id}") + log.payment_info( + payment, "Double payment detected", context="completed order" + ) elif current_total > payment.expected_amount: - logger.info( - f"Overpayment detected for payment {payment.id}: expected {payment.expected_amount}, will receive {current_total}" + log.payment_info( + payment, + f"Overpayment detected", + context=f"expected {payment.expected_amount}, receiving {current_total}", ) else: - logger.info( - f"Invalid multiple payment to {payment.status} payment {payment.id}" + log.payment_warning( + payment, "Invalid multiple payment detected", context="unknown scenario" ) - logger.info( - f"_should_process_late_payment: ACCEPTING non-pending payment {payment.id}" + log.payment_info( + payment, "Accepting non-pending payment", context="late payment processing" ) return True @@ -267,14 +355,13 @@ def _should_process_late_payment(payment, tx): CryptoPayment.STATUS_PENDING, CryptoPayment.STATUS_CONFIRMED, ]: - logger.info( - f"_should_process_late_payment: ACCEPTING first payment to fresh quote {payment.id}" - ) + log.payment_info(payment, "Accepting first payment to fresh quote") return True - logger.info( - f"_should_process_late_payment: REJECTING payment {payment.id} - " - f"received_amount={payment.received_amount}, status={payment.status}, tx_amount={tx_amount}" + log.payment_info( + payment, + f"Rejecting late payment - tx_amount={tx_amount}", + context="validation failed", ) return False @@ -312,17 +399,17 @@ def delete_invoice_for_terminal_state(dbsession, crypto_payment): # Delete invoice for all other terminal states invoice = crypto_payment.invoice - logger.info( - f"Deleting invoice {invoice.id} for terminal payment {crypto_payment.id} " - f"with status {crypto_payment.status}" + log.payment_info( + crypto_payment, f"Deleting invoice {invoice.id}", context="terminal payment" ) # Delete the invoice first, then clear the reference try: delete_result = delete_invoice_by_id(dbsession, invoice.id) if delete_result.get("success", False): - logger.info( - f"Successfully deleted invoice {invoice.id}: {delete_result.get('message', '')}" + log.payment_info( + crypto_payment, + f"Successfully deleted invoice {invoice.id}: {delete_result.get('message', '')}", ) # Only clear the reference after successful deletion crypto_payment.invoice_id = None @@ -333,7 +420,7 @@ def delete_invoice_for_terminal_state(dbsession, crypto_payment): f"Failed to delete invoice {invoice.id}: {delete_result.get('message', 'Unknown error')}" ) except Exception as e: - logger.error(f"Error deleting invoice {invoice.id}: {e}") + log.error_with_context(f"Error deleting invoice {invoice.id}", e) def get_crypto_client(settings, coin_type): @@ -383,9 +470,9 @@ def sweep_restocking_fee(settings, payment, refund_details, dbsession, context=" current_confirmations = getattr(payment, "refund_confirmations", 0) or 0 if current_confirmations < required_confirmations: - logger.info( - f"Restocking fee sweep for {payment.id} requires {required_confirmations} confirmations, " - f"but refund only has {current_confirmations} - waiting" + log.payment_info( + payment, + f"Restocking fee sweep requires {required_confirmations} confirmations, refund has {current_confirmations} - waiting", ) return @@ -438,15 +525,14 @@ def sweep_restocking_fee(settings, payment, refund_details, dbsession, context=" ) fee_tx_hash = transfer_result.get("tx_hash") actual_swept = amount_to_send - logger.info( - f"XMR restocking fee: Sent {amount_to_send} (balance: {current_balance}, expected: {fee_amount}) from payment {payment.id}" + log.sweep_operation( + payment, + f"XMR restocking fee sent {amount_to_send} (balance: {current_balance}, expected: {fee_amount})", ) else: fee_tx_hash = None actual_swept = 0 - logger.warning( - f"XMR restocking fee: No balance available for payment {payment.id}" - ) + log.payment_warning(payment, "XMR restocking fee: No balance available") elif payment.coin_type == "DOGE": # Smart sweep: Use exact 9% amount with balance check for safety @@ -465,31 +551,31 @@ def sweep_restocking_fee(settings, payment, refund_details, dbsession, context=" payment.shop_sweep_to_address, amount_to_send_crypto ) actual_swept = amount_to_send_atomic - logger.info( - f"DOGE restocking fee: Sent {amount_to_send_atomic} (balance: {current_balance_atomic}, expected: {fee_amount}) from payment {payment.id}" + log.sweep_operation( + payment, + f"DOGE restocking fee sent {amount_to_send_atomic} (balance: {current_balance_atomic}, expected: {fee_amount})", ) else: fee_tx_hash = None actual_swept = 0 - logger.warning( - f"DOGE restocking fee: No balance available for payment {payment.id}" + log.payment_warning( + payment, "DOGE restocking fee: No balance available" ) else: - logger.warning( - f"Unsupported coin type for restocking fee sweep: {payment.coin_type}" + log.payment_warning( + payment, + f"Unsupported coin type for restocking fee sweep: {payment.coin_type}", ) return if fee_tx_hash: - logger.info( - f"{context} restocking fee swept for payment {payment.id}: " - f"{Decimal(actual_swept) / atomic_units} {payment.coin_type} " - f"TX: {fee_tx_hash}" + log.sweep_operation( + payment, f"{context} restocking fee swept", fee_tx_hash, actual_swept ) except Exception as e: - logger.error( - f"Failed to sweep {context.lower()} restocking fee for payment {payment.id}: {e}" + log.payment_error( + payment, f"Failed to sweep {context.lower()} restocking fee", e ) @@ -519,20 +605,20 @@ def process_confirmed_payment(env_request, crypto_payment, client, payment_rescu "final_status": None, } - logger.info( - f"Processing confirmed payment {crypto_payment.id} with proper order of operations" + log.payment_info( + crypto_payment, "Processing confirmed payment with proper order of operations" ) try: # STEP 1: Always finalize invoice first (customer gets their product) # Check if invoice already finalized to make this idempotent if not crypto_payment.is_finalized(): - logger.info(f"Step 1: Finalizing invoice for payment {crypto_payment.id}") + log.payment_info(crypto_payment, "Step 1: Finalizing invoice") finalize_invoice(env_request, crypto_payment, send_emails=True) results["invoice_finalized"] = True else: - logger.info( - f"Step 1: Invoice for payment {crypto_payment.id} already finalized - skipping" + log.payment_info( + crypto_payment, "Step 1: Invoice already finalized - skipping" ) results["invoice_finalized"] = True # Already done @@ -552,9 +638,7 @@ def process_confirmed_payment(env_request, crypto_payment, client, payment_rescu ) if refund_details: - logger.info( - f"Step 2: Processing overpayment refund for {crypto_payment.id}" - ) + log.refund_operation(crypto_payment, "processing overpayment") crypto_payment.status = CryptoPayment.STATUS_CONFIRMED_OVERPAY crypto_payment.refund_reason = refund_details["reason"] @@ -567,15 +651,17 @@ def process_confirmed_payment(env_request, crypto_payment, client, payment_rescu results["overpayment_refund"] = result else: # Refund already processed successfully in previous attempt - logger.info( - f"Overpayment refund for {crypto_payment.id} already processed - TX: {crypto_payment.refund_tx_hash}" + log.refund_operation( + crypto_payment, + "already processed", + crypto_payment.refund_tx_hash, ) result = {"success": True, "tx_hash": crypto_payment.refund_tx_hash} results["overpayment_refund"] = result if result["success"]: - logger.info( - f"Overpayment refund successful for {crypto_payment.id}: TX {result['tx_hash']}" + log.refund_operation( + crypto_payment, "successful", result["tx_hash"] ) # Set refund details but keep in overpaid status for now crypto_payment.refund_tx_hash = result["tx_hash"] @@ -587,24 +673,24 @@ def process_confirmed_payment(env_request, crypto_payment, client, payment_rescu ) # Will set final status at end of function else: - logger.error( - f"Overpayment refund failed for {crypto_payment.id}: {result['error']} - will retry" + log.payment_error( + crypto_payment, + "Overpayment refund failed - will retry", + result["error"], ) # Don't proceed to auto-sweep if refund failed - keep in overpaid status for retry results["final_status"] = CryptoPayment.STATUS_CONFIRMED_OVERPAY return results else: # Overpayment within threshold - will confirm normally at end - logger.info(f"Overpayment within 5% threshold for {crypto_payment.id}") + log.payment_info(crypto_payment, "Overpayment within 5% threshold") else: # Normal payment - will confirm at end pass # STEP 4: Auto-sweep only the invoice amount (not entire wallet) - LAST if crypto_payment.shop_sweep_to_address: - logger.info( - f"Step 4: Auto-sweeping invoice amount for payment {crypto_payment.id}" - ) + log.payment_info(crypto_payment, "Step 4: Auto-sweeping invoice amount") # Calculate exact amount to sweep (expected invoice amount only) coin_config = get_coin_config(crypto_payment.coin_type) @@ -619,18 +705,16 @@ def process_confirmed_payment(env_request, crypto_payment, client, payment_rescu results["auto_sweep"] = sweep_result if sweep_result and sweep_result.get("success"): - logger.info( - f"Invoice amount auto-sweep successful for {crypto_payment.id}: " - f"TX {sweep_result['tx_hash']}, Amount: {invoice_amount_crypto} {crypto_payment.coin_type}" + log.sweep_operation( + crypto_payment, + "successful", + sweep_result["tx_hash"], + f"{invoice_amount_crypto} {crypto_payment.coin_type}", ) else: - logger.error( - f"Auto-sweep failed for {crypto_payment.id}: {sweep_result}" - ) + log.payment_error(crypto_payment, "Auto-sweep failed", sweep_result) else: - logger.info( - f"No shop sweep address configured for payment {crypto_payment.id}" - ) + log.payment_info(crypto_payment, "No shop sweep address configured") # STEP 5: Set terminal status ONLY at the very end when everything succeeded if results.get("overpayment_refund") and results["overpayment_refund"].get( @@ -639,19 +723,19 @@ def process_confirmed_payment(env_request, crypto_payment, client, payment_rescu # Overpayment refund completed successfully crypto_payment.status = CryptoPayment.STATUS_CONFIRMED_OVERPAY_REFUNDED results["final_status"] = CryptoPayment.STATUS_CONFIRMED_OVERPAY_REFUNDED - logger.info( - f"Payment {crypto_payment.id} fully processed - overpayment refunded and completed" + log.payment_info( + crypto_payment, "Fully processed - overpayment refunded and completed" ) else: # Normal payment or overpayment within threshold crypto_payment.status = CryptoPayment.STATUS_CONFIRMED results["final_status"] = CryptoPayment.STATUS_CONFIRMED - logger.info(f"Payment {crypto_payment.id} fully processed - confirmed") + log.payment_info(crypto_payment, "Fully processed - confirmed") return results except Exception as e: - logger.error(f"Error processing confirmed payment {crypto_payment.id}: {e}") + log.payment_error(crypto_payment, "Error processing confirmed payment", e) results["error"] = str(e) return results @@ -728,12 +812,12 @@ def auto_sweep_doge_amount( try: dbsession.flush() except Exception as e: - logger.warning(f"Failed to update sweep info in database: {e}") + log.error_with_context("Failed to update sweep info in database", e) return {"success": True, "tx_hash": tx_hash, "amount_swept": amount_to_sweep} except Exception as e: - logger.error(f"DOGE amount sweep error for payment {crypto_payment.id}: {e}") + log.payment_error(crypto_payment, "DOGE amount sweep error", e) return {"success": False, "error": str(e)} @@ -792,18 +876,18 @@ def auto_sweep_xmr_amount( try: dbsession.flush() except Exception as e: - logger.warning(f"Failed to update sweep info in database: {e}") + log.error_with_context("Failed to update sweep info in database", e) return {"success": True, "tx_hash": tx_hash, "amount_swept": amount_to_sweep} except Exception as e: - logger.error(f"XMR amount sweep error for payment {crypto_payment.id}: {e}") + log.payment_error(crypto_payment, "XMR amount sweep error", e) return {"success": False, "error": str(e)} def auto_sweep_payment(client, crypto_payment: CryptoPayment, dbsession=None): """Auto-sweep funds from a confirmed payment to the shop's cold wallet.""" - logger.info(f"Starting auto-sweep check for payment {crypto_payment.id}") + log.payment_info(crypto_payment, "Starting auto-sweep check") # Dispatch to coin-specific sweep function if crypto_payment.coin_type == "XMR": @@ -811,20 +895,23 @@ def auto_sweep_payment(client, crypto_payment: CryptoPayment, dbsession=None): elif crypto_payment.coin_type == "DOGE": return auto_sweep_payment_doge(client, crypto_payment, dbsession) else: - logger.error(f"Unsupported coin type for sweep: {crypto_payment.coin_type}") + log.payment_error( + crypto_payment, + f"Unsupported coin type for sweep: {crypto_payment.coin_type}", + ) return False def auto_sweep_payment_xmr(client, crypto_payment: CryptoPayment, dbsession=None): """Auto-sweep XMR funds from a confirmed payment to the shop's cold wallet.""" - logger.info(f"Starting XMR auto-sweep check for payment {crypto_payment.id}") + log.payment_info(crypto_payment, "Starting XMR auto-sweep check") if not crypto_payment.shop_sweep_to_address: - logger.info(f"Payment {crypto_payment.id} has no sweep address configured") + log.payment_info(crypto_payment, "No sweep address configured") return False if crypto_payment.is_swept: - logger.info(f"Payment {crypto_payment.id} already swept") + log.payment_info(crypto_payment, "Already swept") return True logger.info( @@ -841,8 +928,9 @@ def auto_sweep_payment_xmr(client, crypto_payment: CryptoPayment, dbsession=None ) unlocked_balance = Decimal(result.get("unlocked_balance", 0)) / atomic_units - logger.info( - f"Account {crypto_payment.account_index} unlocked balance: {unlocked_balance} XMR" + log.payment_info( + crypto_payment, + f"Account {crypto_payment.account_index} unlocked balance: {unlocked_balance} XMR", ) # Calculate sweep amount for THIS SPECIFIC payment only @@ -850,8 +938,9 @@ def auto_sweep_payment_xmr(client, crypto_payment: CryptoPayment, dbsession=None # If no unlocked balance, funds are still locked (10-block lock time) if unlocked_balance == 0: - logger.info( - f"No unlocked balance for payment {crypto_payment.id} - funds still locked, will retry later" + log.payment_info( + crypto_payment, + "No unlocked balance - funds still locked, will retry later", ) # Don't mark as swept - funds are just locked! return False @@ -893,8 +982,9 @@ def auto_sweep_payment_xmr(client, crypto_payment: CryptoPayment, dbsession=None ) return False - logger.info( - f"Account has sufficient unlocked balance ({unlocked_balance} XMR) for payment amount ({payment_amount_xmr} XMR)" + log.payment_info( + crypto_payment, + f"Account has sufficient unlocked balance ({unlocked_balance} XMR) for payment amount ({payment_amount_xmr} XMR)", ) # Verify this subaddress has the expected transfer @@ -918,12 +1008,13 @@ def auto_sweep_payment_xmr(client, crypto_payment: CryptoPayment, dbsession=None ) return False - logger.info( - f"Found {len(transfers_result['in'])} incoming transfers for subaddress {crypto_payment.subaddress_index}" + log.payment_info( + crypto_payment, + f"Found {len(transfers_result['in'])} incoming transfers for subaddress {crypto_payment.subaddress_index}", ) except Exception as e: - logger.error(f"Failed to verify subaddress transfers: {e}") + log.error_with_context("Failed to verify subaddress transfers", e) return False # Use transfer but reduce amount to account for fees @@ -956,7 +1047,9 @@ def auto_sweep_payment_xmr(client, crypto_payment: CryptoPayment, dbsession=None except Exception as e: # Fallback to hardcoded fee if RPC call fails estimated_fee_piconero = int(Decimal("0.0001") * atomic_units) - logger.warning(f"Failed to get dynamic fee estimate, using fallback: {e}") + log.error_with_context( + "Failed to get dynamic fee estimate, using fallback", e + ) # Calculate transfer amount: payment minus fee and reserve for pending refunds reserved_for_refunds_piconero = int(pending_refund_amount_xmr * atomic_units) @@ -968,8 +1061,10 @@ def auto_sweep_payment_xmr(client, crypto_payment: CryptoPayment, dbsession=None transfer_amount_piconero = max(0, available_for_sweep) transfer_amount_xmr = Decimal(transfer_amount_piconero) / atomic_units - logger.info( - f"Transferring {transfer_amount_xmr} XMR (payment amount minus {estimated_fee_piconero / atomic_units} XMR estimated fee and {pending_refund_amount_xmr} XMR reserved for refunds)" + log.sweep_operation( + crypto_payment, + f"transferring {transfer_amount_xmr} XMR", + amount=transfer_amount_piconero, ) result = client._call( @@ -1003,29 +1098,29 @@ def auto_sweep_payment_xmr(client, crypto_payment: CryptoPayment, dbsession=None crypto_payment.swept_network_fee = fee if dbsession: dbsession.add(crypto_payment) - logger.info( - f"Auto-sweep successful for payment {crypto_payment.id}! TX: {tx_hash}, Swept: {total_swept} atomic units, Fee: {fee} atomic units" + log.sweep_operation( + crypto_payment, "auto-sweep successful", tx_hash, total_swept ) return True else: - logger.error(f"Sweep failed for payment {crypto_payment.id}: {result}") + log.payment_error(crypto_payment, "Sweep failed", result) return False except Exception as e: - logger.error(f"Auto-sweep error for payment {crypto_payment.id}: {e}") + log.payment_error(crypto_payment, "Auto-sweep error", e) return False def auto_sweep_payment_doge(client, crypto_payment: CryptoPayment, dbsession=None): """Auto-sweep DOGE funds from a confirmed payment to the shop's cold wallet.""" - logger.info(f"Starting DOGE auto-sweep check for payment {crypto_payment.id}") + log.payment_info(crypto_payment, "Starting DOGE auto-sweep check") if not crypto_payment.shop_sweep_to_address: - logger.info(f"Payment {crypto_payment.id} has no sweep address configured") + log.payment_info(crypto_payment, "No sweep address configured") return False if crypto_payment.is_swept: - logger.info(f"Payment {crypto_payment.id} already swept") + log.payment_info(crypto_payment, "Already swept") return True logger.info( @@ -1076,7 +1171,9 @@ def auto_sweep_payment_doge(client, crypto_payment: CryptoPayment, dbsession=Non else: # Fallback to reasonable fee if estimatesmartfee fails estimated_fee_doge = 0.002 # Matches quote fallback - logger.warning("estimatesmartfee failed, using fallback fee") + log.error_with_context( + "estimatesmartfee failed, using fallback fee", None + ) except Exception as e: # Fallback to reasonable fee if RPC call fails estimated_fee_doge = 0.002 # Matches quote fallback @@ -1143,11 +1240,11 @@ def auto_sweep_payment_doge(client, crypto_payment: CryptoPayment, dbsession=Non ) return True else: - logger.error(f"DOGE sweep failed for payment {crypto_payment.id}") + log.payment_error(crypto_payment, "DOGE sweep failed") return False except Exception as e: - logger.error(f"DOGE auto-sweep error for payment {crypto_payment.id}: {e}") + log.payment_error(crypto_payment, "DOGE auto-sweep error", e) return False @@ -1367,6 +1464,12 @@ def finalize_invoice(env_request, crypto_payment: CryptoPayment, send_emails=Tru tx_hash = None if tx_hash: + log.state_transition( + crypto_payment, + crypto_payment.status, + "OUT_OF_STOCK_REFUNDED", + f"TX: {tx_hash}", + ) crypto_payment.status = CryptoPayment.STATUS_OUT_OF_STOCK_REFUNDED crypto_payment.refund_tx_hash = tx_hash crypto_payment.refund_amount = crypto_payment.received_amount @@ -1459,6 +1562,12 @@ def finalize_invoice(env_request, crypto_payment: CryptoPayment, send_emails=Tru logger.error( f"CONFIGURATION ERROR: Out of stock payment {crypto_payment.id} has no refund address and no shop sweep address" ) + log.state_transition( + crypto_payment, + crypto_payment.status, + "OUT_OF_STOCK_NOT_REFUNDED", + "no refund or sweep address", + ) crypto_payment.status = CryptoPayment.STATUS_OUT_OF_STOCK_NOT_REFUNDED # Delete invoice for terminal state delete_invoice_for_terminal_state(env_request.dbsession, crypto_payment) @@ -1772,8 +1881,15 @@ def process_payment( f"Duplicate payment {crypto_payment.id} refund failed - will retry on next cycle" ) else: - logger.error( - f"DATA ERROR: Duplicate payment {crypto_payment.id} has no invoice or user - this should not happen" + log.payment_error( + crypto_payment, + "DATA ERROR: Duplicate payment has no invoice or user - this should not happen", + ) + log.state_transition( + crypto_payment, + crypto_payment.status, + "DOUBLEPAY_NOT_REFUNDED", + "no invoice or user", ) crypto_payment.status = CryptoPayment.STATUS_DOUBLEPAY_NOT_REFUNDED crypto_payment.refund_reason = ( @@ -1801,11 +1917,20 @@ def process_payment( # Check if refund address exists to determine final status immediately if crypto_payment.refund_address: - crypto_payment.status = CryptoPayment.STATUS_LATEPAY_REFUNDED - logger.info( - f"Expired payment {crypto_payment.id} marked for refund (will process when confirmed)" + log.state_transition( + crypto_payment, + crypto_payment.status, + "LATEPAY_REFUNDED", + "marked for refund", ) + crypto_payment.status = CryptoPayment.STATUS_LATEPAY_REFUNDED else: + log.state_transition( + crypto_payment, + crypto_payment.status, + "LATEPAY_NOT_REFUNDED", + "no refund address", + ) crypto_payment.status = CryptoPayment.STATUS_LATEPAY_NOT_REFUNDED crypto_payment.refund_reason = ( "Late payment - no refund address configured" @@ -1819,6 +1944,9 @@ def process_payment( ) else: # No funds received - just mark as expired + log.state_transition( + crypto_payment, crypto_payment.status, "EXPIRED", "no funds received" + ) crypto_payment.status = CryptoPayment.STATUS_EXPIRED env_request.dbsession.add(crypto_payment) @@ -2103,8 +2231,15 @@ def process_payment( ) elif payment_rescue: # Payment rescue available but no refund address configured - logger.warning( - f"Expired payment {crypto_payment.id} has no refund address configured - no refund possible" + log.payment_warning( + crypto_payment, + "Expired payment has no refund address configured - no refund possible", + ) + log.state_transition( + crypto_payment, + crypto_payment.status, + "LATEPAY_NOT_REFUNDED", + "no refund address", ) crypto_payment.status = CryptoPayment.STATUS_LATEPAY_NOT_REFUNDED crypto_payment.refund_reason = ( @@ -2324,10 +2459,13 @@ def process_payment( # Update status from pending to received if this is the first amount received if crypto_payment.status == CryptoPayment.STATUS_PENDING and new_sum > 0: - crypto_payment.status = CryptoPayment.STATUS_RECEIVED - logger.info( - f"Payment {crypto_payment.id} transitioned from pending to received with amount {crypto_payment.received_amount}" + log.state_transition( + crypto_payment, + "PENDING", + "RECEIVED", + f"amount {crypto_payment.received_amount}", ) + crypto_payment.status = CryptoPayment.STATUS_RECEIVED # Check if original payment should move to confirmed status if ( @@ -2345,15 +2483,21 @@ def process_payment( # Update status to confirmed if crypto_payment.received_amount > crypto_payment.expected_amount: + log.state_transition( + crypto_payment, + "RECEIVED", + "CONFIRMED_OVERPAY", + f"received {crypto_payment.received_amount}, expected {crypto_payment.expected_amount}", + ) crypto_payment.status = CryptoPayment.STATUS_CONFIRMED_OVERPAY - logger.info( - f"Payment {crypto_payment.id} overpaid: received {crypto_payment.received_amount}, expected {crypto_payment.expected_amount}" - ) else: - crypto_payment.status = CryptoPayment.STATUS_CONFIRMED - logger.info( - f"Payment {crypto_payment.id} confirmed with {crypto_payment.current_confirmations} confirmations" + log.state_transition( + crypto_payment, + "RECEIVED", + "CONFIRMED", + f"{crypto_payment.current_confirmations} confirmations", ) + crypto_payment.status = CryptoPayment.STATUS_CONFIRMED # Send confirmation emails if not already sent (independent of invoice finalization) if crypto_payment.invoice and crypto_payment.invoice.user: @@ -2454,13 +2598,13 @@ def process_payment( and crypto_payment.shop_sweep_to_address and not crypto_payment.is_swept ): - logger.info(f"Payment {crypto_payment.id} confirmed - attempting sweep") + log.payment_info(crypto_payment, "Confirmed - attempting sweep") try: sweep_success = auto_sweep_payment( client, crypto_payment, env_request.dbsession ) if sweep_success and crypto_payment.is_swept: - logger.info(f"Payment {crypto_payment.id} swept successfully") + log.payment_info(crypto_payment, "Swept successfully") except Exception as e: logger.error( f"Auto-sweep failed for confirmed payment {crypto_payment.id}: {e}" @@ -2593,6 +2737,12 @@ def process_payment( # Check if refund address is available if crypto_payment.refund_address: # Set status immediately to get out of active queue + log.state_transition( + crypto_payment, + crypto_payment.status, + "UNDERPAID_REFUNDED", + f"received {received_xmr}, expected {expected_xmr}", + ) crypto_payment.status = CryptoPayment.STATUS_UNDERPAID_REFUNDED crypto_payment.refund_reason = f"Underpayment: received {received_xmr} but expected {expected_xmr}" @@ -2642,6 +2792,12 @@ def process_payment( logger.warning( f"Underpayment {crypto_payment.id} has no refund address configured - marking as no-refund" ) + log.state_transition( + crypto_payment, + crypto_payment.status, + "UNDERPAID_NOT_REFUNDED", + "no refund address", + ) crypto_payment.status = CryptoPayment.STATUS_UNDERPAID_NOT_REFUNDED crypto_payment.refund_reason = ( "Underpayment - no refund address configured" @@ -2769,7 +2925,7 @@ def process_refund_confirmations(request, settings): Monitor refund transactions for confirmation status. Updates refund_confirmations and transitions status when fully confirmed. """ - logger.info("Starting refund confirmation monitoring") + log.processing_cycle("Starting refund confirmation monitoring") db = request.dbsession @@ -2791,10 +2947,10 @@ def process_refund_confirmations(request, settings): ) if not refund_queue: - logger.debug("No refund transactions need confirmation monitoring") + log.processing_cycle("No refund transactions need confirmation monitoring") return - logger.info(f"Found {len(refund_queue)} refund transactions to monitor") + log.processing_cycle("Found refund transactions to monitor", len(refund_queue)) # Group by coin type to get appropriate clients refunds_by_coin = {} @@ -2806,12 +2962,16 @@ def process_refund_confirmations(request, settings): # Process each coin type for coin_type, coin_refunds in refunds_by_coin.items(): - logger.info(f"Monitoring {len(coin_refunds)} {coin_type} refund transactions") + log.processing_cycle( + f"Monitoring {coin_type} refund transactions", len(coin_refunds) + ) try: client = get_crypto_client(settings, coin_type) except ValueError as e: - logger.error(f"Failed to get {coin_type} client for refund monitoring: {e}") + log.error_with_context( + f"Failed to get {coin_type} client for refund monitoring", e + ) continue for payment in coin_refunds: @@ -2828,8 +2988,9 @@ def process_refund_confirmations(request, settings): "confirmations_required", 10 ) # Default to 10 if not specified if payment.current_confirmations >= required_confirmations: - logger.info( - f"Retrying refund for payment {payment.id} - now has {payment.current_confirmations} confirmations" + log.payment_info( + payment, + f"Retrying refund - now has {payment.current_confirmations} confirmations", ) # Retry the refund process (import payment rescue here to avoid circular imports) @@ -2909,9 +3070,7 @@ def process_refund_confirmations(request, settings): payment.refund_confirmations = confirmations if confirmations != old_confirmations: - logger.info( - f"REFUND transaction confirmations for payment {payment.id}: {old_confirmations} → {confirmations} (TX: {payment.refund_tx_hash[:16]}...) [incoming: {payment.current_confirmations}]" - ) + log.confirmation_update(payment, old_confirmations, confirmations) # Check if refund is now fully confirmed (10+ confirmations) if confirmations >= 10: @@ -2922,8 +3081,11 @@ def process_refund_confirmations(request, settings): payment.status = ( CryptoPayment.STATUS_CONFIRMED_OVERPAY_REFUNDED_COMPLETE ) - logger.info( - f"REFUND FULLY CONFIRMED - Overpayment refund for payment {payment.id}: {old_status} → {payment.status} (refund TX: {payment.refund_tx_hash[:16]}... with {confirmations} confirmations)" + log.state_transition( + payment, + old_status, + payment.status, + f"refund confirmed with {confirmations} confirmations", ) # Sweep remaining funds (restocking fee) to shop sweep_restocking_fee( @@ -2940,8 +3102,11 @@ def process_refund_confirmations(request, settings): payment.status = ( CryptoPayment.STATUS_CONFIRMED_OVERPAY_REFUNDED_COMPLETE ) - logger.info( - f"REFUND FULLY CONFIRMED - Overpayment refund for payment {payment.id}: {old_status} → {payment.status} (refund TX: {payment.refund_tx_hash[:16]}... with {confirmations} confirmations)" + log.state_transition( + payment, + old_status, + payment.status, + f"refund confirmed with {confirmations} confirmations", ) # Sweep remaining funds (restocking fee) to shop sweep_restocking_fee( @@ -2955,8 +3120,11 @@ def process_refund_confirmations(request, settings): payment.status = CryptoPayment.STATUS_LATEPAY_REFUNDED_COMPLETE # Delete invoice for terminal state delete_invoice_for_terminal_state(db, payment) - logger.info( - f"REFUND FULLY CONFIRMED - Expired refund for payment {payment.id}: {old_status} → {payment.status} (refund TX: {payment.refund_tx_hash[:16]}... with {confirmations} confirmations)" + log.state_transition( + payment, + old_status, + payment.status, + f"refund confirmed with {confirmations} confirmations", ) # Sweep remaining funds (restocking fee) to shop sweep_restocking_fee( @@ -2972,8 +3140,11 @@ def process_refund_confirmations(request, settings): ) # Delete invoice for terminal state delete_invoice_for_terminal_state(db, payment) - logger.info( - f"REFUND FULLY CONFIRMED - Underpaid refund for payment {payment.id}: {old_status} → {payment.status} (refund TX: {payment.refund_tx_hash[:16]}... with {confirmations} confirmations)" + log.state_transition( + payment, + old_status, + payment.status, + f"refund confirmed with {confirmations} confirmations", ) # Sweep remaining funds (restocking fee) to shop sweep_restocking_fee( @@ -2989,14 +3160,22 @@ def process_refund_confirmations(request, settings): ) # Delete invoice for terminal state delete_invoice_for_terminal_state(db, payment) - logger.info( - f"REFUND FULLY CONFIRMED - Out-of-stock refund for payment {payment.id}: {old_status} → {payment.status} (refund TX: {payment.refund_tx_hash[:16]}... with {confirmations} confirmations)" + log.state_transition( + payment, + old_status, + payment.status, + f"refund confirmed with {confirmations} confirmations", ) elif payment.status == CryptoPayment.STATUS_DOUBLEPAY_REFUNDED: - payment.status = CryptoPayment.STATUS_DOUBLEPAY_REFUNDED_COMPLETE + payment.status = ( + CryptoPayment.STATUS_DOUBLEPAY_REFUNDED_COMPLETE + ) # No invoice to delete - duplicate payments don't have invoices - logger.info( - f"REFUND FULLY CONFIRMED - Double payment refund for payment {payment.id}: {old_status} → {payment.status} (refund TX: {payment.refund_tx_hash[:16]}... with {confirmations} confirmations)" + log.state_transition( + payment, + old_status, + payment.status, + f"refund confirmed with {confirmations} confirmations", ) # Sweep remaining funds (restocking fee) to shop sweep_restocking_fee( @@ -3017,9 +3196,7 @@ def process_refund_confirmations(request, settings): db.add(payment) except Exception as e: - logger.error( - f"Failed to check refund confirmations for payment {payment.id}: {e}" - ) + log.payment_error(payment, "Failed to check refund confirmations", e) continue @@ -3108,7 +3285,7 @@ def update_payment_confirmations_only(client, crypto_payment, coin_type): try: stored_txids = json.loads(crypto_payment.tx_hashes or "[]") if not stored_txids: - logger.debug(f"No tx_hashes for payment {crypto_payment.id}") + log.payment_debug(crypto_payment, "No tx_hashes") return # Get confirmation count for all transactions @@ -3154,7 +3331,7 @@ def scan_wallet_for_double_or_late_payments(request, settings): 2. Late payments to expired/cancelled quotes that aren't actively monitored Uses scan position tracking to avoid rescanning old transfers. """ - logger.info("Starting wallet scan for double or late payments") + log.processing_cycle("Starting wallet scan for double or late payments") db = request.dbsession # Import here to avoid circular imports @@ -3164,10 +3341,10 @@ def scan_wallet_for_double_or_late_payments(request, settings): processors = db.query(CryptoProcessor).filter(CryptoProcessor.enabled == True).all() if not processors: - logger.debug("No active crypto processors found for scanning") + log.processing_cycle("No active crypto processors found for scanning") return - logger.info(f"Found {len(processors)} active crypto processors to scan") + log.processing_cycle("Found processors to scan", len(processors)) # Group processors by coin type for efficient scanning processors_by_coin = {} @@ -3602,14 +3779,16 @@ def run_once(env, interval): request = env["request"] settings = request.registry.settings - logger.info("Crypto watcher starting payment processing cycle") + log.processing_cycle("Starting payment processing cycle") # First, do passive scan for late payments to expired/cancelled quotes with request.tm: try: scan_wallet_for_double_or_late_payments(request, settings) except Exception as e: - logger.error(f"Failed to scan wallet for double or late payments: {e}") + log.error_with_context( + "Failed to scan wallet for double or late payments", e + ) with request.tm: db = request.dbsession @@ -3645,7 +3824,7 @@ def run_once(env, interval): # Process each coin type separately for coin_type, coin_payments in payments_by_coin.items(): - logger.info(f"Processing {len(coin_payments)} {coin_type} payments") + log.processing_cycle(f"Processing {coin_type} payments", len(coin_payments)) try: client = get_crypto_client(settings, coin_type) @@ -3801,12 +3980,12 @@ def main(argv=sys.argv): while True: run_once(env, args.interval) if args.once: - logger.info("Crypto watcher finished single run") + log.processing_cycle("Finished single run") break - logger.info(f"Crypto watcher sleeping for {args.interval} seconds") + log.processing_cycle(f"Sleeping for {args.interval} seconds") time.sleep(args.interval) finally: - logger.info("Crypto watcher shutting down") + log.processing_cycle("Shutting down") env["closer"]() diff --git a/make_post_sell/models/crypto_payment.py b/make_post_sell/models/crypto_payment.py index e3f4dd6..0a25a83 100644 --- a/make_post_sell/models/crypto_payment.py +++ b/make_post_sell/models/crypto_payment.py @@ -532,3 +532,158 @@ class CryptoPayment(RBase, Base): bool: True if payment is in initial/waiting state, False otherwise """ return self.status in self.INITIAL_WAITING_STATUSES + + def __str__(self) -> str: + """ + Human-readable string representation for logging and debugging. + + Returns: + str: Concise payment description for logs + """ + return self._format_payment_summary() + + def __repr__(self) -> str: + """ + Developer-oriented string representation for debugging. + + Returns: + str: Detailed payment description for debugging + """ + return ( + f"CryptoPayment(id={self.uuid_str[:8]}, " + f"status={self.status}, " + f"coin={self.coin_type}, " + f"expected={self.expected_amount}, " + f"received={self.received_amount}, " + f"confirmations={self.current_confirmations or 0}/{self.confirmations_required}, " + f"invoice_id={self.invoice_id.hex[:8] if self.invoice_id else None})" + ) + + def _format_payment_summary(self) -> str: + """ + Format payment as a concise summary for logging. + + Returns: + str: Payment summary with key details + """ + # Get amount information + if self.coin_type == "XMR": + expected_display = f"{self.expected_amount / 1e12:.6f}" + received_display = f"{self.received_amount / 1e12:.6f}" + elif self.coin_type == "DOGE": + expected_display = f"{self.expected_amount / 1e8:.8f}" + received_display = f"{self.received_amount / 1e8:.8f}" + else: # BTC, LTC, BCH + expected_display = f"{self.expected_amount / 1e8:.8f}" + received_display = f"{self.received_amount / 1e8:.8f}" + + # Build status description + status_desc = self._get_status_description() + + # Format confirmations + conf_desc = f"{self.current_confirmations or 0}/{self.confirmations_required}" + + # Get user display name if available + user_display = "" + if self.user and hasattr(self.user, "display_name") and self.user.display_name: + user_display = f" user:{self.user.display_name}" + elif self.user and hasattr(self.user, "username") and self.user.username: + user_display = f" user:{self.user.username}" + + # Get shop name if available + shop_display = "" + if self.shop and hasattr(self.shop, "name") and self.shop.name: + shop_display = f" shop:{self.shop.name}" + + return ( + f"Payment {self.uuid_str[:8]} [{status_desc}] " + f"{self.coin_type} {received_display}/{expected_display} " + f"conf:{conf_desc} addr:{self.address[-8:]}{user_display}{shop_display}" + ) + + def _get_status_description(self) -> str: + """ + Get human-readable status description for logging. + + Returns: + str: Human-readable status description + """ + status_descriptions = { + # Initial/waiting states + self.STATUS_PENDING: "waiting", + # Active processing states + self.STATUS_RECEIVED: "received", + self.STATUS_CONFIRMED: "confirmed", + self.STATUS_CONFIRMED_OVERPAY: "overpaid", + # Refund processing states + self.STATUS_CONFIRMED_OVERPAY_REFUNDED: "overpay-refunding", + self.STATUS_LATEPAY_REFUNDED: "late-refunding", + self.STATUS_UNDERPAID_REFUNDED: "underpay-refunding", + self.STATUS_OUT_OF_STOCK_REFUNDED: "oos-refunding", + self.STATUS_DOUBLEPAY_REFUNDED: "duplicate-refunding", + # Completed refund states + self.STATUS_CONFIRMED_OVERPAY_REFUNDED_COMPLETE: "overpay-refunded", + self.STATUS_LATEPAY_REFUNDED_COMPLETE: "late-refunded", + self.STATUS_UNDERPAID_REFUNDED_COMPLETE: "underpay-refunded", + self.STATUS_OUT_OF_STOCK_REFUNDED_COMPLETE: "oos-refunded", + self.STATUS_DOUBLEPAY_REFUNDED_COMPLETE: "duplicate-refunded", + # No-refund states + self.STATUS_CONFIRMED_OVERPAY_NOT_REFUNDED: "overpay-no-refund", + self.STATUS_LATEPAY_NOT_REFUNDED: "late-no-refund", + self.STATUS_UNDERPAID_NOT_REFUNDED: "underpay-no-refund", + self.STATUS_OUT_OF_STOCK_NOT_REFUNDED: "oos-no-refund", + self.STATUS_DOUBLEPAY_NOT_REFUNDED: "duplicate-no-refund", + # Terminal states + self.STATUS_EXPIRED: "expired", + self.STATUS_CANCELLED: "cancelled", + } + + return status_descriptions.get(self.status, self.status) + + def format_transaction_log(self, context: str = "") -> str: + """ + Format payment for transaction logging with optional context. + + Args: + context: Optional context (e.g., "processing", "refunding") + + Returns: + str: Formatted transaction log entry + """ + base_msg = str(self) + if context: + return f"{context.capitalize()}: {base_msg}" + return base_msg + + def format_amount_details(self) -> str: + """ + Format detailed amount information for logging. + + Returns: + str: Detailed amount breakdown + """ + if self.coin_type == "XMR": + expected = f"{self.expected_amount / 1e12:.6f}" + received = f"{self.received_amount / 1e12:.6f}" + due = f"{self.due_amount / 1e12:.6f}" if self.due_amount > 0 else "0" + elif self.coin_type == "DOGE": + expected = f"{self.expected_amount / 1e8:.8f}" + received = f"{self.received_amount / 1e8:.8f}" + due = f"{self.due_amount / 1e8:.8f}" if self.due_amount > 0 else "0" + else: # BTC, LTC, BCH + expected = f"{self.expected_amount / 1e8:.8f}" + received = f"{self.received_amount / 1e8:.8f}" + due = f"{self.due_amount / 1e8:.8f}" if self.due_amount > 0 else "0" + + return f"expected:{expected} received:{received} due:{due} {self.coin_type}" + + def format_confirmation_status(self) -> str: + """ + Format confirmation status for logging. + + Returns: + str: Confirmation status description + """ + status = "confirmed" if self.is_fully_confirmed else "pending" + current = self.current_confirmations or 0 + return f"{status} ({current}/{self.confirmations_required})" diff --git a/make_post_sell/tests/test_crypto_payment_transitions.py b/make_post_sell/tests/test_crypto_payment_transitions.py index 87a2036..afb4b55 100644 --- a/make_post_sell/tests/test_crypto_payment_transitions.py +++ b/make_post_sell/tests/test_crypto_payment_transitions.py @@ -774,7 +774,9 @@ class TestCryptoPaymentTransitions(unittest.TestCase): payment.status = CryptoPayment.STATUS_DOUBLEPAY_REFUNDED self.assertTrue( - payment.is_valid_transition(CryptoPayment.STATUS_DOUBLEPAY_REFUNDED_COMPLETE) + payment.is_valid_transition( + CryptoPayment.STATUS_DOUBLEPAY_REFUNDED_COMPLETE + ) ) diff --git a/make_post_sell/tests/test_double_spend_integration.py b/make_post_sell/tests/test_double_spend_integration.py index cee8757..3b79cf2 100644 --- a/make_post_sell/tests/test_double_spend_integration.py +++ b/make_post_sell/tests/test_double_spend_integration.py @@ -430,7 +430,9 @@ class TestDoubleSpendIntegration(DatabaseIntegrationTests): p for p in all_payments if p.status == CryptoPayment.STATUS_CONFIRMED ] duplicate_payments = [ - p for p in all_payments if p.status == CryptoPayment.STATUS_DOUBLEPAY_REFUNDED + p + for p in all_payments + if p.status == CryptoPayment.STATUS_DOUBLEPAY_REFUNDED ] # Verify counts diff --git a/make_post_sell/tests/test_invoice_deletion_integration.py b/make_post_sell/tests/test_invoice_deletion_integration.py index 4896e20..30695ed 100644 --- a/make_post_sell/tests/test_invoice_deletion_integration.py +++ b/make_post_sell/tests/test_invoice_deletion_integration.py @@ -110,7 +110,9 @@ class InvoiceDeletionIntegrationTests(DatabaseIntegrationTests): def test_expired_payment_deletes_invoice(self): """Test that expired payments have their invoices deleted.""" - payment, invoice = self.create_crypto_payment_with_invoice(CryptoPayment.STATUS_EXPIRED) + payment, invoice = self.create_crypto_payment_with_invoice( + CryptoPayment.STATUS_EXPIRED + ) invoice_id = invoice.id payment_id = payment.id @@ -139,7 +141,9 @@ class InvoiceDeletionIntegrationTests(DatabaseIntegrationTests): def test_cancelled_payment_deletes_invoice(self): """Test that cancelled payments have their invoices deleted.""" - payment, invoice = self.create_crypto_payment_with_invoice(CryptoPayment.STATUS_CANCELLED) + payment, invoice = self.create_crypto_payment_with_invoice( + CryptoPayment.STATUS_CANCELLED + ) invoice_id = invoice.id @@ -153,7 +157,9 @@ class InvoiceDeletionIntegrationTests(DatabaseIntegrationTests): def test_no_refund_payment_deletes_invoice(self): """Test that no-refund payments have their invoices deleted.""" - payment, invoice = self.create_crypto_payment_with_invoice(CryptoPayment.STATUS_LATEPAY_NOT_REFUNDED) + payment, invoice = self.create_crypto_payment_with_invoice( + CryptoPayment.STATUS_LATEPAY_NOT_REFUNDED + ) invoice_id = invoice.id @@ -189,7 +195,9 @@ class InvoiceDeletionIntegrationTests(DatabaseIntegrationTests): def test_confirmed_payment_keeps_invoice(self): """Test that confirmed payments keep their invoices.""" - payment, invoice = self.create_crypto_payment_with_invoice(CryptoPayment.STATUS_CONFIRMED) + payment, invoice = self.create_crypto_payment_with_invoice( + CryptoPayment.STATUS_CONFIRMED + ) invoice_id = invoice.id payment_id = payment.id @@ -211,7 +219,9 @@ class InvoiceDeletionIntegrationTests(DatabaseIntegrationTests): def test_confirmed_overpaid_payment_keeps_invoice(self): """Test that confirmed-overpaid payments keep their invoices.""" - payment, invoice = self.create_crypto_payment_with_invoice(CryptoPayment.STATUS_CONFIRMED_OVERPAY) + payment, invoice = self.create_crypto_payment_with_invoice( + CryptoPayment.STATUS_CONFIRMED_OVERPAY + ) invoice_id = invoice.id @@ -296,7 +306,9 @@ class InvoiceDeletionIntegrationTests(DatabaseIntegrationTests): def test_state_transition_triggers_invoice_deletion(self): """Test that changing payment state to terminal triggers invoice deletion.""" - payment, invoice = self.create_crypto_payment_with_invoice(CryptoPayment.STATUS_PENDING) + payment, invoice = self.create_crypto_payment_with_invoice( + CryptoPayment.STATUS_PENDING + ) invoice_id = invoice.id diff --git a/make_post_sell/tests/test_models.py b/make_post_sell/tests/test_models.py index a347c8f..d3101f7 100644 --- a/make_post_sell/tests/test_models.py +++ b/make_post_sell/tests/test_models.py @@ -4,6 +4,8 @@ import uuid import mock from ..models import User, Coupon, Shop, is_user_name_valid +from ..models.crypto_payment import CryptoPayment +from ..models.invoice import Invoice from ..models.meta import now_timestamp, short_id_to_bytes, id_to_uuid mock_always_none = mock.Mock(return_value=None) @@ -1372,3 +1374,218 @@ class TestUserCryptoRefundAddress(unittest.TestCase): mock_session, self.user, self.shop, "XMR" ) self.assertEqual(result, expected_addr) + + +class TestCryptoPayment(unittest.TestCase): + """Unit tests for CryptoPayment model string representation methods.""" + + @mock.patch("make_post_sell.models.user.is_user_name_available", mock_always_true) + def setUp(self): + """Set up test fixtures.""" + self.user = User("alice@example.com") + self.user.display_name = "Alice" + + self.shop = Shop( + name="Alice's Shop", + phone_number="555-1234", + billing_address="123 Main St", + description="Test shop", + ) + + # Create test payment without invoice for simpler testing + self.payment = CryptoPayment( + invoice=None, # Skip invoice relationship for unit tests + user=self.user, + shop=self.shop, + address="44AFFq5kSiGBoZ4NMDwYtN18obc8AemS33DBLWs3H7otXft3XjrpDtQGv7SqSsaBYBb98uNbr2VBBEt7f2wfn3RVGQBEP3A", + account_index=0, + subaddress_index=1, + coin_type="XMR", + expected_amount=1000000000000, # 1.0 XMR in piconero + rate_locked_usd_per_coin=150.00, + quote_expires_at_ms=now_timestamp() + 3600000, # 1 hour from now + confirmations_required=10, + ) + + def test_str_basic_pending_payment(self): + """Test __str__ for basic pending payment.""" + result = str(self.payment) + + # Should include payment ID, status, coin type, amounts, confirmations, address, user, shop + self.assertIn(self.payment.uuid_str[:8], result) + self.assertIn("[waiting]", result) # pending status description + self.assertIn("XMR", result) + self.assertIn("0.000000/1.000000", result) # received/expected in XMR + self.assertIn("conf:0/10", result) + self.assertIn("addr:", result) + self.assertIn("user:Alice", result) + self.assertIn("shop:Alice's Shop", result) + + def test_str_received_payment_with_confirmations(self): + """Test __str__ for received payment with some confirmations.""" + self.payment.status = CryptoPayment.STATUS_RECEIVED + self.payment.received_amount = 800000000000 # 0.8 XMR + self.payment.current_confirmations = 5 + + result = str(self.payment) + + self.assertIn("[received]", result) + self.assertIn("0.800000/1.000000", result) + self.assertIn("conf:5/10", result) + + def test_str_confirmed_overpayment(self): + """Test __str__ for confirmed overpayment.""" + self.payment.status = CryptoPayment.STATUS_CONFIRMED_OVERPAY + self.payment.received_amount = 1200000000000 # 1.2 XMR + self.payment.current_confirmations = 12 + + result = str(self.payment) + + self.assertIn("[overpaid]", result) + self.assertIn("1.200000/1.000000", result) + self.assertIn("conf:12/10", result) + + def test_str_dogecoin_precision(self): + """Test __str__ with DOGE amounts (8 decimal places).""" + self.payment.coin_type = "DOGE" + self.payment.expected_amount = 100000000000 # 1000.0 DOGE in satoshis + self.payment.received_amount = 95000000000 # 950.0 DOGE + + result = str(self.payment) + + self.assertIn("DOGE", result) + self.assertIn("950.00000000/1000.00000000", result) + + def test_str_no_user_display_name_fallback_to_username(self): + """Test __str__ falls back to username when no display_name.""" + self.user.display_name = None + self.user.username = "alice_user" + + result = str(self.payment) + + self.assertIn("user:alice_user", result) + self.assertNotIn("user:Alice", result) + + def test_str_no_user_info(self): + """Test __str__ when user has no display name or username.""" + self.user.display_name = None + self.user.username = None + + result = str(self.payment) + + # Should not include user info but should still include shop + self.assertNotIn("user:", result) + self.assertIn("shop:Alice's Shop", result) + + def test_str_no_shop_name(self): + """Test __str__ when shop has no name.""" + self.shop.name = None + + result = str(self.payment) + + # Should not include shop info but should still include user + self.assertNotIn("shop:", result) + self.assertIn("user:Alice", result) + + def test_repr_method(self): + """Test __repr__ method for debugging.""" + result = repr(self.payment) + + self.assertIn("CryptoPayment(", result) + self.assertIn(f"id={self.payment.uuid_str[:8]}", result) + self.assertIn("status=pending", result) + self.assertIn("coin=XMR", result) + self.assertIn("expected=1000000000000", result) + self.assertIn("received=0", result) + self.assertIn("confirmations=0/10", result) # Should show 0 due to our fix + + def test_get_status_description_all_statuses(self): + """Test _get_status_description for all status types.""" + status_mapping = { + CryptoPayment.STATUS_PENDING: "waiting", + CryptoPayment.STATUS_RECEIVED: "received", + CryptoPayment.STATUS_CONFIRMED: "confirmed", + CryptoPayment.STATUS_CONFIRMED_OVERPAY: "overpaid", + CryptoPayment.STATUS_EXPIRED: "expired", + CryptoPayment.STATUS_CANCELLED: "cancelled", + CryptoPayment.STATUS_LATEPAY_REFUNDED: "late-refunding", + CryptoPayment.STATUS_UNDERPAID_REFUNDED: "underpay-refunding", + CryptoPayment.STATUS_DOUBLEPAY_REFUNDED: "duplicate-refunding", + CryptoPayment.STATUS_LATEPAY_REFUNDED_COMPLETE: "late-refunded", + CryptoPayment.STATUS_UNDERPAID_REFUNDED_COMPLETE: "underpay-refunded", + CryptoPayment.STATUS_DOUBLEPAY_REFUNDED_COMPLETE: "duplicate-refunded", + CryptoPayment.STATUS_LATEPAY_NOT_REFUNDED: "late-no-refund", + CryptoPayment.STATUS_UNDERPAID_NOT_REFUNDED: "underpay-no-refund", + CryptoPayment.STATUS_DOUBLEPAY_NOT_REFUNDED: "duplicate-no-refund", + } + + for status, expected_desc in status_mapping.items(): + self.payment.status = status + result = self.payment._get_status_description() + self.assertEqual( + result, expected_desc, f"Status {status} should map to {expected_desc}" + ) + + def test_format_transaction_log_with_context(self): + """Test format_transaction_log method with context.""" + self.payment.status = CryptoPayment.STATUS_RECEIVED + + result = self.payment.format_transaction_log("processing") + + self.assertIn("Processing:", result) + self.assertIn("[received]", result) + + def test_format_transaction_log_without_context(self): + """Test format_transaction_log method without context.""" + result = self.payment.format_transaction_log() + + # Should be same as str() when no context + self.assertEqual(result, str(self.payment)) + + def test_format_amount_details_xmr(self): + """Test format_amount_details for XMR.""" + self.payment.received_amount = 800000000000 # 0.8 XMR + + result = self.payment.format_amount_details() + + self.assertIn("expected:1.000000", result) + self.assertIn("received:0.800000", result) + self.assertIn("due:0.200000", result) + self.assertIn("XMR", result) + + def test_format_amount_details_doge(self): + """Test format_amount_details for DOGE.""" + self.payment.coin_type = "DOGE" + self.payment.expected_amount = 100000000000 # 1000.0 DOGE + self.payment.received_amount = 95000000000 # 950.0 DOGE + + result = self.payment.format_amount_details() + + self.assertIn("expected:1000.00000000", result) + self.assertIn("received:950.00000000", result) + self.assertIn("due:50.00000000", result) + self.assertIn("DOGE", result) + + def test_format_amount_details_no_due_amount(self): + """Test format_amount_details when fully paid.""" + self.payment.received_amount = 1000000000000 # 1.0 XMR - exactly expected + + result = self.payment.format_amount_details() + + self.assertIn("due:0", result) + + def test_format_confirmation_status_pending(self): + """Test format_confirmation_status for pending confirmations.""" + self.payment.current_confirmations = 5 + + result = self.payment.format_confirmation_status() + + self.assertEqual(result, "pending (5/10)") + + def test_format_confirmation_status_confirmed(self): + """Test format_confirmation_status for fully confirmed.""" + self.payment.current_confirmations = 15 # More than required + + result = self.payment.format_confirmation_status() + + self.assertEqual(result, "confirmed (15/10)") diff --git a/make_post_sell/views/crypto_processor.py b/make_post_sell/views/crypto_processor.py index 980d6d6..88bcbc4 100644 --- a/make_post_sell/views/crypto_processor.py +++ b/make_post_sell/views/crypto_processor.py @@ -55,7 +55,7 @@ def crypto_processor_settings(request): request.session.flash( ( f"Cannot remove {coin_type} cold wallet address. You can only replace it with a new address or disable {coin_type} payments.", - "error" + "error", ) ) return HTTPFound(f"/s/{shop.id}/settings")