Duplicate Logging in SendBitcoin Method - Premature Success Logging #1

New Issue

Closed

opened 2025-05-26 16:47:32 +00:00 by saulteafarmer · 1 comment

saulteafarmer commented 2025-05-26 16:47:32 +00:00

Owner

Copy Link

The SendBitcoin method logs successful transactions before confirming payment status, leading to duplicate logging where payments are marked as successful even when they may later fail, and then logged again when actually confirmed.

Root Cause Analysis

Problem Flow in SendBitcoin Method (Lines ~340-400)

Step 1: Premature Success Logging (Lines ~380-395)

SendBitcoin(lightningAddress, amount * satsPerCurrencyUnit, (success, paymentHash) =>
{
    if (success && !string.IsNullOrEmpty(paymentHash))
    {
        // ❌ LOGS SUCCESS IMMEDIATELY - Before payment confirmation
        LogSellTransaction(
            new SellInvoiceLogEntry
            {
                SteamID = GetPlayerId(player),
                LightningAddress = lightningAddress,
                Success = true,  // ← Marked as successful prematurely
                SatsAmount = amount * satsPerCurrencyUnit,
                PaymentHash = paymentHash,
                CurrencyReturned = false,
                Timestamp = DateTime.UtcNow,
                RetryCount = 0
            }
        );

        // Payment is added to pending invoices for monitoring
        var pendingInvoice = new PendingInvoice { /* ... */ };
        pendingInvoices.Add(pendingInvoice);
    }
});

Step 2: Duplicate Success Logging (Lines ~470-490)

// Later in CheckPendingInvoices when payment is actually confirmed
CheckInvoicePaid(localPaymentHash, isPaid =>
{
    if (isPaid)
    {
        // ... process payment success
        
        if (invoice.Type == PurchaseType.SendBitcoin)
        {
            // ❌ LOGS SUCCESS AGAIN - Second time for same payment
            var logEntry = new SellInvoiceLogEntry
            {
                SteamID = GetPlayerId(invoice.Player),
                LightningAddress = ExtractLightningAddress(invoice.Memo),
                Success = true,  // ← Same payment logged as successful again
                SatsAmount = invoice.Amount,
                PaymentHash = invoice.RHash,
                CurrencyReturned = false,
                Timestamp = DateTime.UtcNow,
                RetryCount = retryCounts.ContainsKey(invoice.RHash) ? retryCounts[invoice.RHash] : 0
            };
            LogSellTransaction(logEntry);
        }
    }
});

The Logical Flow Problem

1. SendPayment() initiates Lightning payment → Returns payment hash
2. SendBitcoin() receives payment hash → Logs as "successful" immediately
3. Payment is actually still pending → Added to pendingInvoices for monitoring
4. CheckPendingInvoices() confirms payment → Logs "successful" again

Impact

• 📊 Inaccurate Analytics: Duplicate success entries skew payment statistics
• 🔍 Audit Trail Issues: Same payment appears successful twice in logs
• 💰 Accounting Problems: Revenue tracking may double-count payments
• 🐛 Debugging Confusion: Logs show more "successful" payments than actual
• 📈 False Metrics: Success rate appears higher than reality

Example Log Output

// First log (premature):
{
  "SteamID": "76561198123456789",
  "LightningAddress": "user@wallet.com", 
  "Success": true,
  "SatsAmount": 1000,
  "PaymentHash": "abc123...",
  "CurrencyReturned": false,
  "Timestamp": "2025-01-15T10:30:00Z",
  "RetryCount": 0
}

// Second log (actual confirmation):
{
  "SteamID": "76561198123456789", 
  "LightningAddress": "user@wallet.com",
  "Success": true,
  "SatsAmount": 1000, 
  "PaymentHash": "abc123...",
  "CurrencyReturned": false,
  "Timestamp": "2025-01-15T10:30:15Z",  // 15 seconds later
  "RetryCount": 3
}

Steps to Reproduce

1. Player uses /sendblood 100 user@wallet.com
2. Lightning payment is initiated successfully
3. First log entry is written immediately (Success: true)
4. Payment is still being processed by Lightning Network
5. 15 seconds later, payment confirmation arrives
6. Second log entry is written (Success: true, same payment)
7. Result: Same payment logged as successful twice

Root Cause: Misunderstanding of SendPayment Success

The issue stems from misinterpreting what "success" means in the SendPayment callback:

SendPayment(bolt11, satsAmount, (success, paymentHash) =>
{
    // "success" here means "payment initiated successfully"
    // NOT "payment completed successfully"
    if (success && !string.IsNullOrEmpty(paymentHash))
    {
        // This logs payment as complete, but it's only initiated
        LogSellTransaction(successEntry);
    }
});

Proposed Fix

Solution 1: Remove Premature Logging

Only log when payment is actually confirmed:

private void CmdSendCurrency(IPlayer player, string command, string[] args)
{
    // ... validation logic ...

    SendBitcoin(lightningAddress, amount * satsPerCurrencyUnit, (success, paymentHash) =>
    {
        if (success && !string.IsNullOrEmpty(paymentHash))
        {
            // ✅ DO NOT log success here - only log initiation
            var pendingInvoice = new PendingInvoice
            {
                RHash = paymentHash.ToLower(),
                Player = player,
                Amount = amount * satsPerCurrencyUnit,
                Memo = $"Sending {amount} {currencyName} to {lightningAddress}",
                CreatedAt = DateTime.UtcNow,
                Type = PurchaseType.SendBitcoin
            };
            pendingInvoices.Add(pendingInvoice);

            // ✅ Optional: Log payment initiation (not success)
            LogSellTransaction(new SellInvoiceLogEntry
            {
                SteamID = GetPlayerId(player),
                LightningAddress = lightningAddress,
                Success = false,  // ← Not successful yet, only initiated
                SatsAmount = amount * satsPerCurrencyUnit,
                PaymentHash = paymentHash,
                CurrencyReturned = false,
                Timestamp = DateTime.UtcNow,
                RetryCount = 0,
                Status = "INITIATED"  // Add status field to track state
            });

            Puts($"Outbound payment to {lightningAddress} initiated. PaymentHash: {paymentHash}");
        }
        else
        {
            // ✅ Log actual failures immediately
            LogSellTransaction(new SellInvoiceLogEntry
            {
                SteamID = GetPlayerId(player),
                LightningAddress = lightningAddress,
                Success = false,
                SatsAmount = amount * satsPerCurrencyUnit,
                PaymentHash = null,
                CurrencyReturned = true,
                Timestamp = DateTime.UtcNow,
                RetryCount = 0,
                Status = "FAILED_TO_INITIATE"
            });

            ReturnCurrency(basePlayer, amount);
        }
    });
}

Solution 2: Add Status Tracking to Avoid Duplicates

Enhance the logging system to track payment states:

private class SellInvoiceLogEntry
{
    public string SteamID { get; set; }
    public string LightningAddress { get; set; }
    public bool Success { get; set; }
    public int SatsAmount { get; set; }
    public string PaymentHash { get; set; }
    public bool CurrencyReturned { get; set; }
    public DateTime Timestamp { get; set; }
    public int RetryCount { get; set; }
    public string Status { get; set; }  // NEW: "INITIATED", "CONFIRMED", "FAILED"
}

private void LogSellTransaction(SellInvoiceLogEntry logEntry)
{
    var logs = LoadSellLogData();
    
    // ✅ Check for existing entries to avoid duplicates
    var existingEntry = logs.FirstOrDefault(l => 
        l.PaymentHash == logEntry.PaymentHash && 
        l.Status == logEntry.Status);
    
    if (existingEntry == null)
    {
        logs.Add(logEntry);
        SaveSellLogData(logs);
        Puts($"[Orangemart] Logged sell transaction: {JsonConvert.SerializeObject(logEntry)}");
    }
    else
    {
        Puts($"[Orangemart] Duplicate log entry prevented for PaymentHash: {logEntry.PaymentHash}");
    }
}

Solution 3: Update Confirmation Logic

Ensure only one success log per payment:

// In CheckPendingInvoices - only log final confirmation
if (invoice.Type == PurchaseType.SendBitcoin)
{
    var logEntry = new SellInvoiceLogEntry
    {
        SteamID = GetPlayerId(invoice.Player),
        LightningAddress = ExtractLightningAddress(invoice.Memo),
        Success = true,
        SatsAmount = invoice.Amount,
        PaymentHash = invoice.RHash,
        CurrencyReturned = false,
        Timestamp = DateTime.UtcNow,
        RetryCount = retryCounts.ContainsKey(invoice.RHash) ? retryCounts[invoice.RHash] : 0,
        Status = "CONFIRMED"  // ← Final confirmation status
    };
    LogSellTransaction(logEntry);
}

Environment

• Lightning Network: Payments have initiation vs confirmation phases
• Async Processing: Payment status checking happens separately
• Log Analysis: Duplicate entries affect reporting accuracy

Severity

🟡 Medium - Data integrity issue affecting logging and analytics

Additional Notes

This bug makes it appear that more payments are successful than actually are, and complicates audit trails. The fix ensures that:

• Payment initiation is logged separately from confirmation
• Only one success entry exists per payment
• Failed payments are properly tracked
• Audit trails are accurate and reliable

The `SendBitcoin` method **logs successful transactions before confirming payment status**, leading to **duplicate logging** where payments are marked as successful even when they may later fail, and then logged again when actually confirmed. ## Root Cause Analysis ### **Problem Flow in SendBitcoin Method** (Lines ~340-400) #### **Step 1: Premature Success Logging** (Lines ~380-395) ```csharp SendBitcoin(lightningAddress, amount * satsPerCurrencyUnit, (success, paymentHash) => { if (success && !string.IsNullOrEmpty(paymentHash)) { // ❌ LOGS SUCCESS IMMEDIATELY - Before payment confirmation LogSellTransaction( new SellInvoiceLogEntry { SteamID = GetPlayerId(player), LightningAddress = lightningAddress, Success = true, // ← Marked as successful prematurely SatsAmount = amount * satsPerCurrencyUnit, PaymentHash = paymentHash, CurrencyReturned = false, Timestamp = DateTime.UtcNow, RetryCount = 0 } ); // Payment is added to pending invoices for monitoring var pendingInvoice = new PendingInvoice { /* ... */ }; pendingInvoices.Add(pendingInvoice); } }); ``` #### **Step 2: Duplicate Success Logging** (Lines ~470-490) ```csharp // Later in CheckPendingInvoices when payment is actually confirmed CheckInvoicePaid(localPaymentHash, isPaid => { if (isPaid) { // ... process payment success if (invoice.Type == PurchaseType.SendBitcoin) { // ❌ LOGS SUCCESS AGAIN - Second time for same payment var logEntry = new SellInvoiceLogEntry { SteamID = GetPlayerId(invoice.Player), LightningAddress = ExtractLightningAddress(invoice.Memo), Success = true, // ← Same payment logged as successful again SatsAmount = invoice.Amount, PaymentHash = invoice.RHash, CurrencyReturned = false, Timestamp = DateTime.UtcNow, RetryCount = retryCounts.ContainsKey(invoice.RHash) ? retryCounts[invoice.RHash] : 0 }; LogSellTransaction(logEntry); } } }); ``` ### **The Logical Flow Problem** 1. **SendPayment()** initiates Lightning payment → Returns payment hash 2. **SendBitcoin()** receives payment hash → **Logs as "successful"** immediately 3. **Payment is actually still pending** → Added to `pendingInvoices` for monitoring 4. **CheckPendingInvoices()** confirms payment → **Logs "successful" again** ## Impact - 📊 **Inaccurate Analytics**: Duplicate success entries skew payment statistics - 🔍 **Audit Trail Issues**: Same payment appears successful twice in logs - 💰 **Accounting Problems**: Revenue tracking may double-count payments - 🐛 **Debugging Confusion**: Logs show more "successful" payments than actual - 📈 **False Metrics**: Success rate appears higher than reality ## Example Log Output ```json // First log (premature): { "SteamID": "76561198123456789", "LightningAddress": "user@wallet.com", "Success": true, "SatsAmount": 1000, "PaymentHash": "abc123...", "CurrencyReturned": false, "Timestamp": "2025-01-15T10:30:00Z", "RetryCount": 0 } // Second log (actual confirmation): { "SteamID": "76561198123456789", "LightningAddress": "user@wallet.com", "Success": true, "SatsAmount": 1000, "PaymentHash": "abc123...", "CurrencyReturned": false, "Timestamp": "2025-01-15T10:30:15Z", // 15 seconds later "RetryCount": 3 } ``` ## Steps to Reproduce 1. Player uses `/sendblood 100 user@wallet.com` 2. Lightning payment is initiated successfully 3. **First log entry** is written immediately (Success: true) 4. Payment is still being processed by Lightning Network 5. 15 seconds later, payment confirmation arrives 6. **Second log entry** is written (Success: true, same payment) 7. Result: Same payment logged as successful twice ## Root Cause: Misunderstanding of SendPayment Success The issue stems from misinterpreting what "success" means in the SendPayment callback: ```csharp SendPayment(bolt11, satsAmount, (success, paymentHash) => { // "success" here means "payment initiated successfully" // NOT "payment completed successfully" if (success && !string.IsNullOrEmpty(paymentHash)) { // This logs payment as complete, but it's only initiated LogSellTransaction(successEntry); } }); ``` ## Proposed Fix ### **Solution 1: Remove Premature Logging** Only log when payment is actually confirmed: ```csharp private void CmdSendCurrency(IPlayer player, string command, string[] args) { // ... validation logic ... SendBitcoin(lightningAddress, amount * satsPerCurrencyUnit, (success, paymentHash) => { if (success && !string.IsNullOrEmpty(paymentHash)) { // ✅ DO NOT log success here - only log initiation var pendingInvoice = new PendingInvoice { RHash = paymentHash.ToLower(), Player = player, Amount = amount * satsPerCurrencyUnit, Memo = $"Sending {amount} {currencyName} to {lightningAddress}", CreatedAt = DateTime.UtcNow, Type = PurchaseType.SendBitcoin }; pendingInvoices.Add(pendingInvoice); // ✅ Optional: Log payment initiation (not success) LogSellTransaction(new SellInvoiceLogEntry { SteamID = GetPlayerId(player), LightningAddress = lightningAddress, Success = false, // ← Not successful yet, only initiated SatsAmount = amount * satsPerCurrencyUnit, PaymentHash = paymentHash, CurrencyReturned = false, Timestamp = DateTime.UtcNow, RetryCount = 0, Status = "INITIATED" // Add status field to track state }); Puts($"Outbound payment to {lightningAddress} initiated. PaymentHash: {paymentHash}"); } else { // ✅ Log actual failures immediately LogSellTransaction(new SellInvoiceLogEntry { SteamID = GetPlayerId(player), LightningAddress = lightningAddress, Success = false, SatsAmount = amount * satsPerCurrencyUnit, PaymentHash = null, CurrencyReturned = true, Timestamp = DateTime.UtcNow, RetryCount = 0, Status = "FAILED_TO_INITIATE" }); ReturnCurrency(basePlayer, amount); } }); } ``` ### **Solution 2: Add Status Tracking to Avoid Duplicates** Enhance the logging system to track payment states: ```csharp private class SellInvoiceLogEntry { public string SteamID { get; set; } public string LightningAddress { get; set; } public bool Success { get; set; } public int SatsAmount { get; set; } public string PaymentHash { get; set; } public bool CurrencyReturned { get; set; } public DateTime Timestamp { get; set; } public int RetryCount { get; set; } public string Status { get; set; } // NEW: "INITIATED", "CONFIRMED", "FAILED" } private void LogSellTransaction(SellInvoiceLogEntry logEntry) { var logs = LoadSellLogData(); // ✅ Check for existing entries to avoid duplicates var existingEntry = logs.FirstOrDefault(l => l.PaymentHash == logEntry.PaymentHash && l.Status == logEntry.Status); if (existingEntry == null) { logs.Add(logEntry); SaveSellLogData(logs); Puts($"[Orangemart] Logged sell transaction: {JsonConvert.SerializeObject(logEntry)}"); } else { Puts($"[Orangemart] Duplicate log entry prevented for PaymentHash: {logEntry.PaymentHash}"); } } ``` ### **Solution 3: Update Confirmation Logic** Ensure only one success log per payment: ```csharp // In CheckPendingInvoices - only log final confirmation if (invoice.Type == PurchaseType.SendBitcoin) { var logEntry = new SellInvoiceLogEntry { SteamID = GetPlayerId(invoice.Player), LightningAddress = ExtractLightningAddress(invoice.Memo), Success = true, SatsAmount = invoice.Amount, PaymentHash = invoice.RHash, CurrencyReturned = false, Timestamp = DateTime.UtcNow, RetryCount = retryCounts.ContainsKey(invoice.RHash) ? retryCounts[invoice.RHash] : 0, Status = "CONFIRMED" // ← Final confirmation status }; LogSellTransaction(logEntry); } ``` ## Environment - **Lightning Network**: Payments have initiation vs confirmation phases - **Async Processing**: Payment status checking happens separately - **Log Analysis**: Duplicate entries affect reporting accuracy ## Severity 🟡 **Medium** - Data integrity issue affecting logging and analytics ## Additional Notes This bug makes it appear that more payments are successful than actually are, and complicates audit trails. The fix ensures that: - Payment initiation is logged separately from confirmation - Only one success entry exists per payment - Failed payments are properly tracked - Audit trails are accurate and reliable

saulteafarmer commented 2025-06-20 18:49:04 +00:00

Author

Owner

Copy Link

Fixed on 0.4.0

Fixed on 0.4.0

saulteafarmer closed this issue 2025-06-20 18:49:04 +00:00

Sign in to join this conversation.

No Branch/Tag Specified

Branches Tags

main

0.4.0

0.3.0

Labels

No items

No Label

Milestone

No items

No Milestone

Projects

Clear projects

No project

Assignees

Clear assignees

saulteafarmer

No Assignees

1 Participants

Notifications

Subscribe

Due Date

No due date set.

Dependencies

No dependencies set.

Reference: rustysats/orangemart.cs#1

No description provided.