Better timestamp for invoice logs, fix bugs which can happen if invoice get deleted

BTCPayServer/BTCPayServer.csproj

@@ -2,7 +2,7 @@
   <PropertyGroup>
     <OutputType>Exe</OutputType>
     <TargetFramework>netcoreapp2.1</TargetFramework>
-		<Version>1.0.2.61</Version>
+		<Version>1.0.2.62</Version>
     <NoWarn>NU1701,CA1816,CA1308,CA1810,CA2208</NoWarn>
   </PropertyGroup>
   <ItemGroup>
@@ -40,10 +40,10 @@
     <PackageReference Include="Microsoft.EntityFrameworkCore.Sqlite" Version="2.1.0" />
     <PackageReference Include="Microsoft.Extensions.Logging.Filter" Version="1.1.2" />
     <PackageReference Include="Microsoft.NetCore.Analyzers" Version="2.6.0" />
-    <PackageReference Include="NBitcoin" Version="4.1.1.31" />
+    <PackageReference Include="NBitcoin" Version="4.1.1.32" />
     <PackageReference Include="NBitpayClient" Version="1.0.0.29" />	  
     <PackageReference Include="DBreeze" Version="1.87.0" />
-    <PackageReference Include="NBXplorer.Client" Version="1.0.2.14" />
+    <PackageReference Include="NBXplorer.Client" Version="1.0.2.15" />
     <PackageReference Include="NicolasDorier.CommandLine" Version="1.0.0.2" />
     <PackageReference Include="NicolasDorier.CommandLine.Configuration" Version="1.0.0.3" />
     <PackageReference Include="NicolasDorier.StandardConfiguration" Version="1.0.0.16" />

BTCPayServer/Controllers/InvoiceController.cs

@@ -84,6 +84,8 @@ namespace BTCPayServer.Controllers
 
         internal async Task<DataWrapper<InvoiceResponse>> CreateInvoiceCore(Invoice invoice, StoreData store, string serverUrl)
         {
+            InvoiceLogs logs = new InvoiceLogs();
+            logs.Write("Creation of invoice starting");
             var entity = new InvoiceEntity
             {
                 InvoiceTime = DateTimeOffset.UtcNow
@@ -136,6 +138,7 @@ namespace BTCPayServer.Controllers
             var rateRules = storeBlob.GetRateRules(_NetworkProvider);
             var fetchingByCurrencyPair = _RateProvider.FetchRates(currencyPairsToFetch, rateRules);
 
+            var fetchingAll = WhenAllFetched(logs, fetchingByCurrencyPair);
             var supportedPaymentMethods = store.GetSupportedPaymentMethods(_NetworkProvider)
                                                .Select(c =>
                                                 (Handler: (IPaymentMethodHandler)_ServiceProvider.GetService(typeof(IPaymentMethodHandler<>).MakeGenericType(c.GetType())),
@@ -144,59 +147,26 @@ namespace BTCPayServer.Controllers
                                                 .Where(c => c.Network != null)
                                                 .Select(o =>
                                                     (SupportedPaymentMethod: o.SupportedPaymentMethod,
-                                                    PaymentMethod: CreatePaymentMethodAsync(fetchingByCurrencyPair, o.Handler, o.SupportedPaymentMethod, o.Network, entity, store)))
+                                                    PaymentMethod: CreatePaymentMethodAsync(fetchingByCurrencyPair, o.Handler, o.SupportedPaymentMethod, o.Network, entity, store, logs)))
                                                 .ToList();
-
-            List<string> invoiceLogs = new List<string>();
             List<ISupportedPaymentMethod> supported = new List<ISupportedPaymentMethod>();
             var paymentMethods = new PaymentMethodDictionary();
-
-            foreach (var pair in fetchingByCurrencyPair)
-            {
-                var rateResult = await pair.Value;
-                invoiceLogs.Add($"{pair.Key}: The rating rule is {rateResult.Rule}");
-                invoiceLogs.Add($"{pair.Key}: The evaluated rating rule is {rateResult.EvaluatedRule}");
-                if (rateResult.Errors.Count != 0)
-                {
-                    var allRateRuleErrors = string.Join(", ", rateResult.Errors.ToArray());
-                    invoiceLogs.Add($"{pair.Key}: Rate rule error ({allRateRuleErrors})");
-                }
-                if (rateResult.ExchangeExceptions.Count != 0)
-                {
-                    foreach (var ex in rateResult.ExchangeExceptions)
-                    {
-                        invoiceLogs.Add($"{pair.Key}: Exception reaching exchange {ex.ExchangeName} ({ex.Exception.Message})");
-                    }
-                }
-            }
-
             foreach (var o in supportedPaymentMethods)
             {
-                try
+                var paymentMethod = await o.PaymentMethod;
-                {
+                if (paymentMethod == null)
-                    var paymentMethod = await o.PaymentMethod;
+                    continue;
-                    if (paymentMethod == null)
+                supported.Add(o.SupportedPaymentMethod);
-                        throw new PaymentMethodUnavailableException("Payment method unavailable");
+                paymentMethods.Add(paymentMethod);
-                    supported.Add(o.SupportedPaymentMethod);
-                    paymentMethods.Add(paymentMethod);
-                }
-                catch (PaymentMethodUnavailableException ex)
-                {
-                    invoiceLogs.Add($"{o.SupportedPaymentMethod.PaymentId.CryptoCode} ({o.SupportedPaymentMethod.PaymentId.PaymentType}): Payment method unavailable ({ex.Message})");
-                }
-                catch (Exception ex)
-                {
-                    invoiceLogs.Add($"{o.SupportedPaymentMethod.PaymentId.CryptoCode} ({o.SupportedPaymentMethod.PaymentId.PaymentType}): Unexpected exception ({ex.ToString()})");
-                }
             }
 
             if (supported.Count == 0)
             {
                 StringBuilder errors = new StringBuilder();
                 errors.AppendLine("No payment method available for this store");
-                foreach (var error in invoiceLogs)
+                foreach (var error in logs.ToList())
                 {
-                    errors.AppendLine(error);
+                    errors.AppendLine(error.ToString());
                 }
                 throw new BitpayHttpException(400, errors.ToString());
             }
@@ -204,71 +174,108 @@ namespace BTCPayServer.Controllers
             entity.SetSupportedPaymentMethods(supported);
             entity.SetPaymentMethods(paymentMethods);
             entity.PosData = invoice.PosData;
-            entity = await _InvoiceRepository.CreateInvoiceAsync(store.Id, entity, invoiceLogs, _NetworkProvider);
+            entity = await _InvoiceRepository.CreateInvoiceAsync(store.Id, entity, logs, _NetworkProvider);
-
+            await fetchingAll;
             _EventAggregator.Publish(new Events.InvoiceEvent(entity.EntityToDTO(_NetworkProvider), 1001, "invoice_created"));
             var resp = entity.EntityToDTO(_NetworkProvider);
             return new DataWrapper<InvoiceResponse>(resp) { Facade = "pos/invoice" };
         }
 
-        private async Task<PaymentMethod> CreatePaymentMethodAsync(Dictionary<CurrencyPair, Task<RateResult>> fetchingByCurrencyPair, IPaymentMethodHandler handler, ISupportedPaymentMethod supportedPaymentMethod, BTCPayNetwork network, InvoiceEntity entity, StoreData store)
+        private Task WhenAllFetched(InvoiceLogs logs, Dictionary<CurrencyPair, Task<RateResult>> fetchingByCurrencyPair)
         {
-            var storeBlob = store.GetStoreBlob();
+            return Task.WhenAll(fetchingByCurrencyPair.Select(async pair =>
-            var rate = await fetchingByCurrencyPair[new CurrencyPair(network.CryptoCode, entity.ProductInformation.Currency)];
-            if (rate.Value == null)
-                return null;
-            PaymentMethod paymentMethod = new PaymentMethod();
-            paymentMethod.ParentEntity = entity;
-            paymentMethod.Network = network;
-            paymentMethod.SetId(supportedPaymentMethod.PaymentId);
-            paymentMethod.Rate = rate.Value.Value;
-            var paymentDetails = await handler.CreatePaymentMethodDetails(supportedPaymentMethod, paymentMethod, store, network);
-            if (storeBlob.NetworkFeeDisabled)
-                paymentDetails.SetNoTxFee();
-            paymentMethod.SetPaymentMethodDetails(paymentDetails);
-
-            Func<Money, Money, bool> compare = null;
-            CurrencyValue limitValue = null;
-            string errorMessage = null;
-            if (supportedPaymentMethod.PaymentId.PaymentType == PaymentTypes.LightningLike &&
-               storeBlob.LightningMaxValue != null)
             {
-                compare = (a, b) => a > b;
+                var rateResult = await pair.Value;
-                limitValue = storeBlob.LightningMaxValue;
+                logs.Write($"{pair.Key}: The rating rule is {rateResult.Rule}");
-                errorMessage = "The amount of the invoice is too high to be paid with lightning";
+                logs.Write($"{pair.Key}: The evaluated rating rule is {rateResult.EvaluatedRule}");
-            }
+                if (rateResult.Errors.Count != 0)
-            else if (supportedPaymentMethod.PaymentId.PaymentType == PaymentTypes.BTCLike &&
-               storeBlob.OnChainMinValue != null)
-            {
-                compare = (a, b) => a < b;
-                limitValue = storeBlob.OnChainMinValue;
-                errorMessage = "The amount of the invoice is too low to be paid on chain";
-            }
-
-            if (compare != null)
-            {
-                var limitValueRate = await fetchingByCurrencyPair[new CurrencyPair(network.CryptoCode, limitValue.Currency)];
-                if (limitValueRate.Value.HasValue)
                 {
-                    var limitValueCrypto = Money.Coins(limitValue.Value / limitValueRate.Value.Value);
+                    var allRateRuleErrors = string.Join(", ", rateResult.Errors.ToArray());
-                    if (compare(paymentMethod.Calculate().Due, limitValueCrypto))
+                    logs.Write($"{pair.Key}: Rate rule error ({allRateRuleErrors})");
+                }
+                if (rateResult.ExchangeExceptions.Count != 0)
+                {
+                    foreach (var ex in rateResult.ExchangeExceptions)
                     {
-                        throw new PaymentMethodUnavailableException(errorMessage);
+                        logs.Write($"{pair.Key}: Exception reaching exchange {ex.ExchangeName} ({ex.Exception.Message})");
                     }
                 }
-            }
+            }).ToArray());
-            ///////////////
+        }
+
+        private async Task<PaymentMethod> CreatePaymentMethodAsync(Dictionary<CurrencyPair, Task<RateResult>> fetchingByCurrencyPair, IPaymentMethodHandler handler, ISupportedPaymentMethod supportedPaymentMethod, BTCPayNetwork network, InvoiceEntity entity, StoreData store, InvoiceLogs logs)
+        {
+            try
+            {
+                var storeBlob = store.GetStoreBlob();
+                var rate = await fetchingByCurrencyPair[new CurrencyPair(network.CryptoCode, entity.ProductInformation.Currency)];
+                if (rate.Value == null)
+                {
+                    return null;
+                }
+                PaymentMethod paymentMethod = new PaymentMethod();
+                paymentMethod.ParentEntity = entity;
+                paymentMethod.Network = network;
+                paymentMethod.SetId(supportedPaymentMethod.PaymentId);
+                paymentMethod.Rate = rate.Value.Value;
+                var paymentDetails = await handler.CreatePaymentMethodDetails(supportedPaymentMethod, paymentMethod, store, network);
+                if (storeBlob.NetworkFeeDisabled)
+                    paymentDetails.SetNoTxFee();
+                paymentMethod.SetPaymentMethodDetails(paymentDetails);
+
+                Func<Money, Money, bool> compare = null;
+                CurrencyValue limitValue = null;
+                string errorMessage = null;
+                if (supportedPaymentMethod.PaymentId.PaymentType == PaymentTypes.LightningLike &&
+                   storeBlob.LightningMaxValue != null)
+                {
+                    compare = (a, b) => a > b;
+                    limitValue = storeBlob.LightningMaxValue;
+                    errorMessage = "The amount of the invoice is too high to be paid with lightning";
+                }
+                else if (supportedPaymentMethod.PaymentId.PaymentType == PaymentTypes.BTCLike &&
+                   storeBlob.OnChainMinValue != null)
+                {
+                    compare = (a, b) => a < b;
+                    limitValue = storeBlob.OnChainMinValue;
+                    errorMessage = "The amount of the invoice is too low to be paid on chain";
+                }
+
+                if (compare != null)
+                {
+                    var limitValueRate = await fetchingByCurrencyPair[new CurrencyPair(network.CryptoCode, limitValue.Currency)];
+                    if (limitValueRate.Value.HasValue)
+                    {
+                        var limitValueCrypto = Money.Coins(limitValue.Value / limitValueRate.Value.Value);
+                        if (compare(paymentMethod.Calculate().Due, limitValueCrypto))
+                        {
+                            logs.Write($"{supportedPaymentMethod.PaymentId.CryptoCode}: {errorMessage}");
+                            return null;
+                        }
+                    }
+                }
+                ///////////////
 
 
 #pragma warning disable CS0618
-            if (paymentMethod.GetId().IsBTCOnChain)
+                if (paymentMethod.GetId().IsBTCOnChain)
-            {
+                {
-                entity.TxFee = paymentMethod.TxFee;
+                    entity.TxFee = paymentMethod.TxFee;
-                entity.Rate = paymentMethod.Rate;
+                    entity.Rate = paymentMethod.Rate;
-                entity.DepositAddress = paymentMethod.DepositAddress;
+                    entity.DepositAddress = paymentMethod.DepositAddress;
-            }
+                }
 #pragma warning restore CS0618
-            return paymentMethod;
+                return paymentMethod;
+            }
+            catch (PaymentMethodUnavailableException ex)
+            {
+                logs.Write($"{supportedPaymentMethod.PaymentId.CryptoCode}: Payment method unavailable ({ex.Message})");
+            }
+            catch (Exception ex)
+            {
+                logs.Write($"{supportedPaymentMethod.PaymentId.CryptoCode}: Unexpected exception ({ex.ToString()})");
+            }
+            return null;
         }
 
         private SpeedPolicy ParseSpeedPolicy(string transactionSpeed, SpeedPolicy defaultPolicy)

BTCPayServer/HostedServices/InvoiceNotificationManager.cs

@@ -309,6 +309,8 @@ namespace BTCPayServer.HostedServices
             leases.Add(_EventAggregator.Subscribe<InvoiceEvent>(async e =>
             {
                 var invoice = await _InvoiceRepository.GetInvoice(null, e.Invoice.Id);
+                if (invoice == null)
+                    return;
                 List<Task> tasks = new List<Task>();
 
                 // Awaiting this later help make sure invoices should arrive in order

BTCPayServer/Logging/InvoiceLog.cs

@@ -0,0 +1,37 @@
+using System;
+using System.Collections.Generic;
+using System.Linq;
+using System.Threading.Tasks;
+
+namespace BTCPayServer.Logging
+{
+    public class InvoiceLog
+    {
+        public DateTimeOffset Timestamp { get; set; }
+        public string Log { get; set; }
+
+        public override string ToString()
+        {
+            return $"{Timestamp.UtcDateTime}: {Log}";
+        }
+    }
+    public class InvoiceLogs
+    {
+        List<InvoiceLog> _InvoiceLogs = new List<InvoiceLog>();
+        public void Write(string data)
+        {
+            lock (_InvoiceLogs)
+            {
+                _InvoiceLogs.Add(new InvoiceLog() { Timestamp = DateTimeOffset.UtcNow, Log = data });
+            }
+        }
+
+        public List<InvoiceLog> ToList()
+        {
+            lock (_InvoiceLogs)
+            {
+                return _InvoiceLogs.ToList();
+            }
+        }
+    }
+}

BTCPayServer/Services/Invoices/InvoiceRepository.cs

@@ -19,6 +19,7 @@ using System.Globalization;
 using BTCPayServer.Models.InvoicingModels;
 using BTCPayServer.Logging;
 using BTCPayServer.Payments;
+using System.Data.Common;
 
 namespace BTCPayServer.Services.Invoices
 {
@@ -101,7 +102,7 @@ namespace BTCPayServer.Services.Invoices
             }
         }
 
-        public async Task<InvoiceEntity> CreateInvoiceAsync(string storeId, InvoiceEntity invoice, IEnumerable<string> creationLogs, BTCPayNetworkProvider networkProvider)
+        public async Task<InvoiceEntity> CreateInvoiceAsync(string storeId, InvoiceEntity invoice, InvoiceLogs creationLogs, BTCPayNetworkProvider networkProvider)
         {
             List<string> textSearch = new List<string>();
             invoice = Clone(invoice, null);
@@ -147,13 +148,13 @@ namespace BTCPayServer.Services.Invoices
                 }
                 context.PendingInvoices.Add(new PendingInvoiceData() { Id = invoice.Id });
 
-                foreach(var log in creationLogs)
+                foreach(var log in creationLogs.ToList())
                 {
                     context.InvoiceEvents.Add(new InvoiceEventData()
                     {
                         InvoiceDataId = invoice.Id,
-                        Message = log,
+                        Message = log.Log,
-                        Timestamp = invoice.InvoiceTime,
+                        Timestamp = log.Timestamp,
                         UniqueId = Encoders.Hex.EncodeData(RandomUtils.GetBytes(10))
                     });
                 }
@@ -244,7 +245,11 @@ namespace BTCPayServer.Services.Invoices
                     Timestamp = DateTimeOffset.UtcNow,
                     UniqueId = Encoders.Hex.EncodeData(RandomUtils.GetBytes(10))
                 });
-                await context.SaveChangesAsync();
+                try
+                {
+                    await context.SaveChangesAsync();
+                }
+                catch(DbUpdateException) { } // Probably the invoice does not exists anymore
             }
         }