Add comprehensive logging to crypto payment scanner for production debugging
The late payment scanner stopped finding payments after double payment fixes. Added detailed logging to diagnose the issue: - Log each processor's scan position and calculated height - Log minimum scan position used for wallet queries - Log exact RPC query parameters sent to wallet - Log all transfers found with height, amount, confirmations, subaddress - Log payment lookup results for each transfer - Log late payment decision logic with accept/reject reasons This will reveal if: - Scan positions are too high and skipping late payments - Transfers are found but not matched to payment records - Payments are found but rejected by late payment logic Critical for debugging production issue where real customer funds may not be getting processed due to missed late payments.
This commit is contained in:
parent
c1a936539e
commit
b776d1cd7e
1 changed files with 80 additions and 8 deletions
|
|
@ -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:
|
||||
|
|
|
|||
Loading…
Add table
Add a link
Reference in a new issue