Fix PayPal IPN Logging (#3768)

* Remove request logging, fix txn_id correlation

* Respond 400 when txn_id is missing

* More cleanup

src/Billing/Controllers/PayPalController.cs

@@ -75,6 +75,14 @@ public class PayPalController : Controller
 
         var transactionModel = new PayPalIPNTransactionModel(requestContent);
 
+        _logger.LogInformation("PayPal IPN: Transaction Type = {Type}", transactionModel.TransactionType);
+
+        if (string.IsNullOrEmpty(transactionModel.TransactionId))
+        {
+            _logger.LogError("PayPal IPN: Transaction ID is missing");
+            return Ok();
+        }
+
         var entityId = transactionModel.UserId ?? transactionModel.OrganizationId;
 
         if (!entityId.HasValue)
@@ -83,7 +91,7 @@ public class PayPalController : Controller
             return BadRequest();
         }
 
-        var verified = await _payPalIPNClient.VerifyIPN(entityId.Value, requestContent);
+        var verified = await _payPalIPNClient.VerifyIPN(transactionModel.TransactionId, requestContent);
 
         if (!verified)
         {

src/Billing/Services/IPayPalIPNClient.cs

@@ -2,5 +2,5 @@
 
 public interface IPayPalIPNClient
 {
-    Task<bool> VerifyIPN(Guid entityId, string formData);
+    Task<bool> VerifyIPN(string transactionId, string formData);
 }

src/Billing/Services/Implementations/PayPalIPNClient.cs

@@ -21,9 +21,9 @@ public class PayPalIPNClient : IPayPalIPNClient
         _logger = logger;
     }
 
-    public async Task<bool> VerifyIPN(Guid entityId, string formData)
+    public async Task<bool> VerifyIPN(string transactionId, string formData)
     {
-        LogInfo(entityId, $"Verifying IPN against {_ipnEndpoint}");
+        LogInfo(transactionId, $"Verifying IPN against {_ipnEndpoint}");
 
         if (string.IsNullOrEmpty(formData))
         {
@@ -34,8 +34,6 @@ public class PayPalIPNClient : IPayPalIPNClient
 
         var requestContent = string.Concat("cmd=_notify-validate&", formData);
 
-        LogInfo(entityId, $"Request Content: {requestContent}");
-
         requestMessage.Content = new StringContent(requestContent, Encoding.UTF8, "application/x-www-form-urlencoded");
 
         var response = await _httpClient.SendAsync(requestMessage);
@@ -52,35 +50,35 @@ public class PayPalIPNClient : IPayPalIPNClient
             };
         }
 
-        LogError(entityId, $"Unsuccessful Response | Status Code: {response.StatusCode} | Content: {responseContent}");
+        LogError(transactionId, $"Unsuccessful Response | Status Code: {response.StatusCode} | Content: {responseContent}");
 
         return false;
 
         bool Verified()
         {
-            LogInfo(entityId, "Verified");
+            LogInfo(transactionId, "Verified");
             return true;
         }
 
         bool Invalid()
         {
-            LogError(entityId, "Verification Invalid");
+            LogError(transactionId, "Verification Invalid");
             return false;
         }
 
         bool Unhandled(string content)
         {
-            LogWarning(entityId, $"Unhandled Response Content: {content}");
+            LogWarning(transactionId, $"Unhandled Response Content: {content}");
             return false;
         }
     }
 
-    private void LogInfo(Guid entityId, string message)
+    private void LogInfo(string transactionId, string message)
-        => _logger.LogInformation("Verify PayPal IPN ({RequestId}) | {Message}", entityId, message);
+        => _logger.LogInformation("Verify PayPal IPN ({Id}) | {Message}", transactionId, message);
 
-    private void LogWarning(Guid entityId, string message)
+    private void LogWarning(string transactionId, string message)
-        => _logger.LogWarning("Verify PayPal IPN ({RequestId}) | {Message}", entityId, message);
+        => _logger.LogWarning("Verify PayPal IPN ({Id}) | {Message}", transactionId, message);
 
-    private void LogError(Guid entityId, string message)
+    private void LogError(string transactionId, string message)
-        => _logger.LogError("Verify PayPal IPN ({RequestId}) | {Message}", entityId, message);
+        => _logger.LogError("Verify PayPal IPN ({Id}) | {Message}", transactionId, message);
 }

test/Billing.Test/Controllers/PayPalControllerTests.cs

@@ -129,7 +129,7 @@ public class PayPalControllerTests
 
         var ipnBody = await PayPalTestIPN.GetAsync(IPNBody.SuccessfulPayment);
 
-        _payPalIPNClient.VerifyIPN(organizationId, ipnBody).Returns(false);
+        _payPalIPNClient.VerifyIPN(Arg.Any<string>(), ipnBody).Returns(false);
 
         var controller = ConfigureControllerContextWith(logger, _defaultWebhookKey, ipnBody);
 
@@ -154,7 +154,7 @@ public class PayPalControllerTests
 
         var ipnBody = await PayPalTestIPN.GetAsync(IPNBody.UnsupportedTransactionType);
 
-        _payPalIPNClient.VerifyIPN(organizationId, ipnBody).Returns(true);
+        _payPalIPNClient.VerifyIPN(Arg.Any<string>(), ipnBody).Returns(true);
 
         var controller = ConfigureControllerContextWith(logger, _defaultWebhookKey, ipnBody);
 
@@ -183,7 +183,7 @@ public class PayPalControllerTests
 
         var ipnBody = await PayPalTestIPN.GetAsync(IPNBody.SuccessfulPayment);
 
-        _payPalIPNClient.VerifyIPN(organizationId, ipnBody).Returns(true);
+        _payPalIPNClient.VerifyIPN(Arg.Any<string>(), ipnBody).Returns(true);
 
         var controller = ConfigureControllerContextWith(logger, _defaultWebhookKey, ipnBody);
 
@@ -212,7 +212,7 @@ public class PayPalControllerTests
 
         var ipnBody = await PayPalTestIPN.GetAsync(IPNBody.RefundMissingParentTransaction);
 
-        _payPalIPNClient.VerifyIPN(organizationId, ipnBody).Returns(true);
+        _payPalIPNClient.VerifyIPN(Arg.Any<string>(), ipnBody).Returns(true);
 
         var controller = ConfigureControllerContextWith(logger, _defaultWebhookKey, ipnBody);
 
@@ -241,7 +241,7 @@ public class PayPalControllerTests
 
         var ipnBody = await PayPalTestIPN.GetAsync(IPNBody.ECheckPayment);
 
-        _payPalIPNClient.VerifyIPN(organizationId, ipnBody).Returns(true);
+        _payPalIPNClient.VerifyIPN(Arg.Any<string>(), ipnBody).Returns(true);
 
         var controller = ConfigureControllerContextWith(logger, _defaultWebhookKey, ipnBody);
 
@@ -270,7 +270,7 @@ public class PayPalControllerTests
 
         var ipnBody = await PayPalTestIPN.GetAsync(IPNBody.NonUSDPayment);
 
-        _payPalIPNClient.VerifyIPN(organizationId, ipnBody).Returns(true);
+        _payPalIPNClient.VerifyIPN(Arg.Any<string>(), ipnBody).Returns(true);
 
         var controller = ConfigureControllerContextWith(logger, _defaultWebhookKey, ipnBody);
 
@@ -299,7 +299,7 @@ public class PayPalControllerTests
 
         var ipnBody = await PayPalTestIPN.GetAsync(IPNBody.SuccessfulPayment);
 
-        _payPalIPNClient.VerifyIPN(organizationId, ipnBody).Returns(true);
+        _payPalIPNClient.VerifyIPN(Arg.Any<string>(), ipnBody).Returns(true);
 
         _transactionRepository.GetByGatewayIdAsync(
             GatewayType.PayPal,
@@ -332,7 +332,7 @@ public class PayPalControllerTests
 
         var ipnBody = await PayPalTestIPN.GetAsync(IPNBody.SuccessfulPayment);
 
-        _payPalIPNClient.VerifyIPN(organizationId, ipnBody).Returns(true);
+        _payPalIPNClient.VerifyIPN(Arg.Any<string>(), ipnBody).Returns(true);
 
         _transactionRepository.GetByGatewayIdAsync(
             GatewayType.PayPal,
@@ -367,7 +367,7 @@ public class PayPalControllerTests
 
         var ipnBody = await PayPalTestIPN.GetAsync(IPNBody.SuccessfulPaymentForOrganizationCredit);
 
-        _payPalIPNClient.VerifyIPN(organizationId, ipnBody).Returns(true);
+        _payPalIPNClient.VerifyIPN(Arg.Any<string>(), ipnBody).Returns(true);
 
         _transactionRepository.GetByGatewayIdAsync(
             GatewayType.PayPal,
@@ -417,7 +417,7 @@ public class PayPalControllerTests
 
         var ipnBody = await PayPalTestIPN.GetAsync(IPNBody.SuccessfulPaymentForUserCredit);
 
-        _payPalIPNClient.VerifyIPN(userId, ipnBody).Returns(true);
+        _payPalIPNClient.VerifyIPN(Arg.Any<string>(), ipnBody).Returns(true);
 
         _transactionRepository.GetByGatewayIdAsync(
             GatewayType.PayPal,
@@ -467,7 +467,7 @@ public class PayPalControllerTests
 
         var ipnBody = await PayPalTestIPN.GetAsync(IPNBody.SuccessfulRefund);
 
-        _payPalIPNClient.VerifyIPN(organizationId, ipnBody).Returns(true);
+        _payPalIPNClient.VerifyIPN(Arg.Any<string>(), ipnBody).Returns(true);
 
         _transactionRepository.GetByGatewayIdAsync(
             GatewayType.PayPal,
@@ -504,7 +504,7 @@ public class PayPalControllerTests
 
         var ipnBody = await PayPalTestIPN.GetAsync(IPNBody.SuccessfulRefund);
 
-        _payPalIPNClient.VerifyIPN(organizationId, ipnBody).Returns(true);
+        _payPalIPNClient.VerifyIPN(Arg.Any<string>(), ipnBody).Returns(true);
 
         _transactionRepository.GetByGatewayIdAsync(
             GatewayType.PayPal,
@@ -545,7 +545,7 @@ public class PayPalControllerTests
 
         var ipnBody = await PayPalTestIPN.GetAsync(IPNBody.SuccessfulRefund);
 
-        _payPalIPNClient.VerifyIPN(organizationId, ipnBody).Returns(true);
+        _payPalIPNClient.VerifyIPN(Arg.Any<string>(), ipnBody).Returns(true);
 
         _transactionRepository.GetByGatewayIdAsync(
             GatewayType.PayPal,

test/Billing.Test/Services/PayPalIPNClientTests.cs

@@ -34,7 +34,7 @@ public class PayPalIPNClientTests
 
     [Fact]
     public async Task VerifyIPN_FormDataNull_ThrowsArgumentNullException()
-        => await Assert.ThrowsAsync<ArgumentNullException>(() => _payPalIPNClient.VerifyIPN(Guid.NewGuid(), null));
+        => await Assert.ThrowsAsync<ArgumentNullException>(() => _payPalIPNClient.VerifyIPN(string.Empty, null));
 
     [Fact]
     public async Task VerifyIPN_Unauthorized_ReturnsFalse()
@@ -46,7 +46,7 @@ public class PayPalIPNClientTests
             .WithFormData(new Dictionary<string, string> { { "cmd", "_notify-validate" }, { "form", "data" } })
             .Respond(HttpStatusCode.Unauthorized);
 
-        var verified = await _payPalIPNClient.VerifyIPN(Guid.NewGuid(), formData);
+        var verified = await _payPalIPNClient.VerifyIPN(string.Empty, formData);
 
         Assert.False(verified);
         Assert.Equal(1, _mockHttpMessageHandler.GetMatchCount(request));
@@ -62,7 +62,7 @@ public class PayPalIPNClientTests
             .WithFormData(new Dictionary<string, string> { { "cmd", "_notify-validate" }, { "form", "data" } })
             .Respond("application/text", "INVALID");
 
-        var verified = await _payPalIPNClient.VerifyIPN(Guid.NewGuid(), formData);
+        var verified = await _payPalIPNClient.VerifyIPN(string.Empty, formData);
 
         Assert.False(verified);
         Assert.Equal(1, _mockHttpMessageHandler.GetMatchCount(request));
@@ -78,7 +78,7 @@ public class PayPalIPNClientTests
             .WithFormData(new Dictionary<string, string> { { "cmd", "_notify-validate" }, { "form", "data" } })
             .Respond("application/text", "VERIFIED");
 
-        var verified = await _payPalIPNClient.VerifyIPN(Guid.NewGuid(), formData);
+        var verified = await _payPalIPNClient.VerifyIPN(string.Empty, formData);
 
         Assert.True(verified);
         Assert.Equal(1, _mockHttpMessageHandler.GetMatchCount(request));