diff --git a/make_post_sell/lib/crypto_watcher.py b/make_post_sell/lib/crypto_watcher.py index fe7be80..9fafafa 100644 --- a/make_post_sell/lib/crypto_watcher.py +++ b/make_post_sell/lib/crypto_watcher.py @@ -184,6 +184,7 @@ def _should_process_late_payment(payment, tx): bool: True if this payment should be processed """ if not payment: + logger.debug("_should_process_late_payment: No payment object") return False # Get transaction amount (normalize for coin type) @@ -193,6 +194,11 @@ 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}" + ) + # 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: @@ -222,6 +228,9 @@ def _should_process_late_payment(payment, tx): f"Invalid multiple payment to {payment.status} payment {payment.id}" ) + logger.info( + f"_should_process_late_payment: ACCEPTING non-pending payment {payment.id}" + ) return True # Edge Case: First payment to a fresh quote (normal processing should handle this, but just in case) @@ -229,8 +238,15 @@ 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}" + ) 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}" + ) return False @@ -2367,9 +2383,21 @@ def scan_wallet_for_double_or_late_payments(request, settings): if coin_type == "XMR": try: # Get the minimum scan position across all processors to determine what's "new" - min_scan_position = min( - _get_scan_position_from_semaphore(p.last_scan_semaphore, coin_type) - for p in coin_processors + processor_positions = [] + for p in coin_processors: + pos = _get_scan_position_from_semaphore( + p.last_scan_semaphore, coin_type + ) + processor_positions.append( + (p.id, p.shop_id, p.last_scan_semaphore, pos) + ) + logger.info( + f"Processor {p.id} (shop {p.shop_id}) scan position: {p.last_scan_semaphore} → height {pos}" + ) + + min_scan_position = min(pos for _, _, _, pos in processor_positions) + logger.info( + f"Using minimum scan position {min_scan_position} across {len(processor_positions)} processors" ) # Build bounded query for XMR transfers @@ -2385,17 +2413,27 @@ def scan_wallet_for_double_or_late_payments(request, settings): if min_scan_position > 0: query_params["filter_by_height"] = True query_params["min_height"] = min_scan_position + logger.info( + f"Scanning for transfers with min_height >= {min_scan_position}" + ) + else: + logger.info("Scanning ALL transfers (no height filter)") # Get transfers from the wallet using bounded query + logger.info(f"Calling get_transfers with params: {query_params}") result = client._call("get_transfers", query_params) all_transfers = [] for transfer_type in ["in", "pending", "pool"]: if transfer_type in result: - all_transfers.extend(result[transfer_type]) + transfers_in_type = result[transfer_type] + all_transfers.extend(transfers_in_type) + logger.info( + f"Found {len(transfers_in_type)} transfers in '{transfer_type}' category" + ) if not all_transfers: - logger.debug(f"No {coin_type} transfers found") + logger.info(f"No {coin_type} transfers found in wallet scan") continue # Process all transfers returned by bounded query @@ -2406,20 +2444,39 @@ def scan_wallet_for_double_or_late_payments(request, settings): ) logger.info( - f"Found {len(new_transfers)} incoming {coin_type} transfers newer than scan position {min_scan_position}" + f"Found {len(new_transfers)} incoming {coin_type} transfers newer than scan position {min_scan_position}, max height: {max_height}" ) + # Log details of each transfer for debugging + for i, tx in enumerate(new_transfers): + subaddr = tx.get("subaddr_index", {}) + logger.info( + f"Transfer {i+1}: height={tx.get('height', 'unknown')}, " + f"amount={tx.get('amount', 0) / 1e12:.12f} XMR, " + f"confirmations={tx.get('confirmations', 0)}, " + f"subaddr={subaddr.get('major', 0)}.{subaddr.get('minor', 'unknown')}, " + f"txid={tx.get('txid', 'unknown')[:16]}..." + ) + # Process new transfers and match to payments late_payments_found = 0 + transfers_checked = 0 for tx in new_transfers: + transfers_checked += 1 subaddr = tx.get("subaddr_index", {}) if not subaddr: + logger.debug( + f"Transfer {transfers_checked}: skipping - no subaddr_index" + ) continue account_idx = subaddr.get("major", 0) subaddr_idx = subaddr.get("minor") if subaddr_idx is None: + logger.debug( + f"Transfer {transfers_checked}: skipping - no minor subaddr" + ) continue # Look up payment by subaddress @@ -2433,8 +2490,23 @@ def scan_wallet_for_double_or_late_payments(request, settings): .first() ) - if payment and _should_process_late_payment(payment, tx): - late_payments_found += 1 + logger.info( + f"Transfer {transfers_checked} to subaddr {account_idx}.{subaddr_idx}: " + f"{'FOUND' if payment else 'NO'} payment record" + + ( + f" (payment {payment.id}, status {payment.status})" + if payment + else "" + ) + ) + + if payment: + should_process = _should_process_late_payment(payment, tx) + logger.info( + f"Payment {payment.id} should_process_late_payment: {should_process}" + ) + if should_process: + late_payments_found += 1 # Check if this is a duplicate payment (original already has funds) if payment.received_amount > 0: