From 8c303928d570d75838eb91af1b815bb70159361a Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?Jos=C3=A9=20A=2EP?= <53834183+Jossec101@users.noreply.github.com> Date: Wed, 13 May 2026 18:08:38 +0200 Subject: [PATCH] Add logging for rebalance creation, execution, and status updates in RebalanceService and MonitorRebalancesJob stack-info: PR: https://github.com/Elenpay/NodeGuard/pull/515, branch: Jossec101/stack/12 --- src/Jobs/MonitorRebalancesJob.cs | 42 +++++++++++++++++++-- src/Services/RebalanceService.cs | 63 +++++++++++++++++++++++++++++++- 2 files changed, 100 insertions(+), 5 deletions(-) diff --git a/src/Jobs/MonitorRebalancesJob.cs b/src/Jobs/MonitorRebalancesJob.cs index 9b790af1..9f49acca 100644 --- a/src/Jobs/MonitorRebalancesJob.cs +++ b/src/Jobs/MonitorRebalancesJob.cs @@ -59,6 +59,10 @@ public async Task Execute(IJobExecutionContext context) var window = TimeSpan.FromHours(Constants.REBALANCE_RECONCILE_TERMINAL_WINDOW_HOURS); var rebalances = await _rebalanceRepository.GetReconcilable(window); + _logger.LogInformation( + "{JobName} found {Count} reconcilable rebalance(s) within window {WindowHours}h", + nameof(MonitorRebalancesJob), rebalances.Count, window.TotalHours); + foreach (var rebalance in rebalances) { try @@ -85,7 +89,12 @@ public async Task Execute(IJobExecutionContext context) private async Task ReconcileAsync(Rebalance rebalance, CancellationToken ct) { if (string.IsNullOrEmpty(rebalance.PaymentHashHex)) + { + _logger.LogDebug( + "Rebalance {RebalanceId} (status={Status}) has no PaymentHashHex; nothing to reconcile against LND", + rebalance.Id, rebalance.Status); return; + } if (rebalance.Node == null) { @@ -100,11 +109,15 @@ private async Task ReconcileAsync(Rebalance rebalance, CancellationToken ct) } catch (FormatException) { - _logger.LogWarning("Rebalance {RebalanceId} has malformed PaymentHashHex; skipping reconciliation", - rebalance.Id); + _logger.LogWarning("Rebalance {RebalanceId} has malformed PaymentHashHex {PaymentHashHex}; skipping reconciliation", + rebalance.Id, rebalance.PaymentHashHex); return; } + _logger.LogInformation( + "Reconciling rebalance {RebalanceId} (node={NodeId}, status={Status}, hash={PaymentHashHex}, attempt={Attempt}) against LND", + rebalance.Id, rebalance.NodeId, rebalance.Status, rebalance.PaymentHashHex, rebalance.AttemptNumber); + var payment = await _lightningService.TrackPaymentV2Async(rebalance.Node, paymentHash, ct); if (payment == null) @@ -118,6 +131,9 @@ private async Task ReconcileAsync(Rebalance rebalance, CancellationToken ct) var oldStatus = rebalance.Status; rebalance.Status = RebalanceStatus.Failed; _rebalanceRepository.Update(rebalance); + _logger.LogWarning( + "Rebalance {RebalanceId} has no record in LND for hash {PaymentHashHex}; flipping {OldStatus} -> Failed", + rebalance.Id, rebalance.PaymentHashHex, oldStatus); await _auditService.LogSystemAsync( AuditActionType.RebalanceCompleted, AuditEventType.Failure, @@ -131,13 +147,23 @@ await _auditService.LogSystemAsync( NewStatus = rebalance.Status.ToString(), }); } + else + { + _logger.LogInformation( + "Rebalance {RebalanceId} TrackPaymentV2 returned no payment; row already terminal ({Status}), leaving as-is", + rebalance.Id, rebalance.Status); + } return; } if (IsNonTerminalLndStatus(payment.Status)) { - // LND still in flight — nothing to reconcile yet. + // LND still in flight — emitted at info so an operator can spot rebalances stuck + // in flight across monitor sweeps (same RebalanceId appearing tick after tick). + _logger.LogInformation( + "Rebalance {RebalanceId} still {LndStatus} in LND (db status={DbStatus}, attempt={Attempt}, hash={PaymentHashHex}); skipping update", + rebalance.Id, payment.Status, rebalance.Status, rebalance.AttemptNumber, rebalance.PaymentHashHex); return; } @@ -145,7 +171,12 @@ await _auditService.LogSystemAsync( RebalanceService.ApplyTerminalPayment(rebalance, payment); if (rebalance.Status == previousStatus) + { + _logger.LogInformation( + "Rebalance {RebalanceId} terminal status {Status} matches LND ({LndStatus}); no update needed", + rebalance.Id, rebalance.Status, payment.Status); return; + } _rebalanceRepository.Update(rebalance); @@ -153,6 +184,11 @@ await _auditService.LogSystemAsync( ? AuditEventType.Success : AuditEventType.Failure; + _logger.LogInformation( + "Rebalance {RebalanceId} reconciled: {OldStatus} -> {NewStatus} (LND status={LndStatus}, failureReason={LndFailureReason}, feeSats={FeeSats}, ppm={Ppm})", + rebalance.Id, previousStatus, rebalance.Status, payment.Status, payment.FailureReason, + rebalance.FeePaidSats, rebalance.EffectivePpm); + await _auditService.LogSystemAsync( AuditActionType.RebalanceCompleted, eventType, diff --git a/src/Services/RebalanceService.cs b/src/Services/RebalanceService.cs index 12c1a4d8..0452d2fc 100644 --- a/src/Services/RebalanceService.cs +++ b/src/Services/RebalanceService.cs @@ -150,6 +150,11 @@ public async Task RebalanceAsync(RebalanceRequest request, Cancellati throw new InvalidOperationException($"Failed to persist rebalance: {addError}"); } + _logger.LogInformation( + "Rebalance {RebalanceId} created (node={NodeId} '{NodeName}', amount={AmountSats} sats, maxFeePct={MaxFeePct}, sourceChanId={SourceChanIdLnd}, targetPubkey={TargetPubkey}, isManual={IsManual})", + rebalance.Id, node.Id, node.Name, rebalance.RequestedAmountSats, rebalance.MaxFeePct, + rebalance.SourceChanIdLnd, rebalance.TargetPubkey, rebalance.IsManual); + await _auditService.LogAsync( AuditActionType.RebalanceInitiated, AuditEventType.Attempt, @@ -179,13 +184,21 @@ public async Task ExecuteAsync(int rebalanceId, CancellationToken ct if (node == null) throw new InvalidOperationException($"Node {rebalance.NodeId} not found for rebalance {rebalanceId}"); + _logger.LogInformation( + "Executing rebalance {RebalanceId} attempt {Attempt}/{MaxAttempts} (node={NodeId} '{NodeName}', amount={AmountSats} sats, maxFeePct={MaxFeePct}, timeoutSeconds={TimeoutSeconds})", + rebalance.Id, rebalance.AttemptNumber, rebalance.MaxAttempts ?? Constants.REBALANCE_MAX_ATTEMPTS, + node.Id, node.Name, rebalance.SatsAmount, rebalance.MaxFeePct, rebalance.TimeoutSeconds); + try { var memo = $"NG rebalance #{rebalance.Id} attempt {rebalance.AttemptNumber}"; - var invoice = await _lightningService.AddInvoiceAsync(node, rebalance.SatsAmount, memo, - ComputeInvoiceExpirySeconds(rebalance)); + var invoiceExpiry = ComputeInvoiceExpirySeconds(rebalance); + var invoice = await _lightningService.AddInvoiceAsync(node, rebalance.SatsAmount, memo, invoiceExpiry); if (invoice == null || string.IsNullOrEmpty(invoice.PaymentRequest)) { + _logger.LogWarning( + "Rebalance {RebalanceId} failed to create self-invoice on node {NodeId}", + rebalance.Id, node.Id); rebalance.Status = RebalanceStatus.Failed; _rebalanceRepository.Update(rebalance); await _auditService.LogAsync(AuditActionType.RebalanceCompleted, AuditEventType.Failure, @@ -200,10 +213,18 @@ await _auditService.LogAsync(AuditActionType.RebalanceCompleted, AuditEventType. rebalance.PaymentHashHex = Convert.ToHexString(invoice.RHash.ToByteArray()).ToLowerInvariant(); _rebalanceRepository.Update(rebalance); + _logger.LogInformation( + "Rebalance {RebalanceId} self-invoice created (hash={PaymentHashHex}, expirySeconds={ExpirySeconds})", + rebalance.Id, rebalance.PaymentHashHex, invoiceExpiry); + var feeLimitMsat = ComputeFeeLimitMsat(rebalance.SatsAmount, rebalance.MaxFeePct); rebalance.Status = RebalanceStatus.Probing; _rebalanceRepository.Update(rebalance); + _logger.LogInformation( + "Rebalance {RebalanceId} probing for route (amount={AmountSats} sats, feeLimitMsat={FeeLimitMsat}, probeBackoffRatio={ProbeBackoffRatio})", + rebalance.Id, rebalance.SatsAmount, feeLimitMsat, + rebalance.ProbeBackoffRatio ?? Constants.REBALANCE_PROBE_BACKOFF_RATIO); await _auditService.LogAsync(AuditActionType.RebalanceProbing, AuditEventType.Attempt, AuditObjectType.Rebalance, rebalance.Id.ToString(), new { rebalance.AttemptNumber, rebalance.SatsAmount, FeeLimitMsat = feeLimitMsat }); @@ -214,6 +235,9 @@ await _auditService.LogAsync(AuditActionType.RebalanceProbing, AuditEventType.At if (probe is ProbeResult.NoRoute noRoute) { + _logger.LogInformation( + "Rebalance {RebalanceId} probe returned NoRoute: {Reason}", + rebalance.Id, noRoute.Reason); rebalance.Status = RebalanceStatus.NoRoute; _rebalanceRepository.Update(rebalance); await _auditService.LogAsync(AuditActionType.RebalanceProbing, AuditEventType.Failure, @@ -227,12 +251,18 @@ await _auditService.LogAsync(AuditActionType.RebalanceCompleted, AuditEventType. } var success = (ProbeResult.Success)probe; + _logger.LogInformation( + "Rebalance {RebalanceId} probe succeeded (probedAmountSats={ProbedAmountSats}, routeHops={RouteHops})", + rebalance.Id, success.AmountSats, success.Route.Hops.Count); await _auditService.LogAsync(AuditActionType.RebalanceProbing, AuditEventType.Success, AuditObjectType.Rebalance, rebalance.Id.ToString(), new { ProbedAmountSats = success.AmountSats, RouteHops = success.Route.Hops.Count }); if (success.AmountSats < rebalance.SatsAmount) { + _logger.LogInformation( + "Rebalance {RebalanceId} probe shrunk amount from {OriginalSats} to {ProbedSats} sats", + rebalance.Id, rebalance.SatsAmount, success.AmountSats); rebalance.SatsAmount = success.AmountSats; feeLimitMsat = ComputeFeeLimitMsat(rebalance.SatsAmount, rebalance.MaxFeePct); } @@ -244,6 +274,10 @@ await _auditService.LogAsync(AuditActionType.RebalanceProbing, AuditEventType.Su ? [rebalance.SourceChanIdLnd.Value] : Array.Empty(); + _logger.LogInformation( + "Rebalance {RebalanceId} dispatching SendPaymentV2 (amount={AmountSats} sats, feeLimitMsat={FeeLimitMsat}, timeoutSeconds={TimeoutSeconds}, hash={PaymentHashHex})", + rebalance.Id, rebalance.SatsAmount, feeLimitMsat, rebalance.TimeoutSeconds, rebalance.PaymentHashHex); + // Probe gave us feasibility + (possibly shrunk) amount; the actual settle goes // through LND's full pathfinder via SendPaymentV2 — that gives us MPP and // built-in per-route retries inside one payment, which the SendToRouteV2 path @@ -259,6 +293,11 @@ await _auditService.LogAsync(AuditActionType.RebalanceProbing, AuditEventType.Su ApplyTerminalPayment(rebalance, payment); + _logger.LogInformation( + "Rebalance {RebalanceId} payment terminal: lndStatus={LndStatus}, failureReason={FailureReason}, dbStatus={DbStatus}, feeSats={FeeSats}, ppm={Ppm}", + rebalance.Id, payment.Status, payment.FailureReason, rebalance.Status, + rebalance.FeePaidSats, rebalance.EffectivePpm); + // Defensive post-hoc ppm guard. Should never fire because feeLimitMsat clamps, // but if it does we surface a distinct status for operators / Grafana. var maxFeePpmCap = (long)Math.Round(rebalance.MaxFeePct * 10_000d, MidpointRounding.AwayFromZero); @@ -266,6 +305,9 @@ await _auditService.LogAsync(AuditActionType.RebalanceProbing, AuditEventType.Su && rebalance.EffectivePpm.HasValue && rebalance.EffectivePpm.Value > maxFeePpmCap) { + _logger.LogWarning( + "Rebalance {RebalanceId} effective ppm {EffectivePpm} exceeded cap {MaxFeePpmCap}; flipping Succeeded -> ExceededFeeLimit", + rebalance.Id, rebalance.EffectivePpm.Value, maxFeePpmCap); rebalance.Status = RebalanceStatus.ExceededFeeLimit; } @@ -273,6 +315,10 @@ await _auditService.LogAsync(AuditActionType.RebalanceProbing, AuditEventType.Su if (rebalance.Status == RebalanceStatus.Succeeded) { + _logger.LogInformation( + "Rebalance {RebalanceId} SUCCEEDED on attempt {Attempt} (feeSats={FeeSats}, ppm={Ppm}, actualAmountSats={ActualAmountSats})", + rebalance.Id, rebalance.AttemptNumber, rebalance.FeePaidSats, rebalance.EffectivePpm, + rebalance.SatsAmount); await _auditService.LogAsync(AuditActionType.RebalanceCompleted, AuditEventType.Success, AuditObjectType.Rebalance, rebalance.Id.ToString(), new @@ -285,6 +331,9 @@ await _auditService.LogAsync(AuditActionType.RebalanceCompleted, AuditEventType. } else { + _logger.LogInformation( + "Rebalance {RebalanceId} attempt {Attempt} ended status={Status} (lndFailureReason={FailureReason})", + rebalance.Id, rebalance.AttemptNumber, rebalance.Status, payment.FailureReason); await _auditService.LogAsync(AuditActionType.RebalanceCompleted, AuditEventType.Failure, AuditObjectType.Rebalance, rebalance.Id.ToString(), new @@ -380,12 +429,18 @@ private async Task ScheduleRetryIfEligibleAsync(Rebalance rebalance) or RebalanceStatus.InsufficientBalance or RebalanceStatus.ExceededFeeLimit) { + _logger.LogInformation( + "Rebalance {RebalanceId} not eligible for retry due to terminal status {Status}", + rebalance.Id, rebalance.Status); return; } var maxAttempts = rebalance.MaxAttempts ?? Constants.REBALANCE_MAX_ATTEMPTS; if (rebalance.AttemptNumber >= maxAttempts) { + _logger.LogInformation( + "Rebalance {RebalanceId} exhausted retry budget at attempt {Attempt}/{MaxAttempts} (status={Status})", + rebalance.Id, rebalance.AttemptNumber, maxAttempts, rebalance.Status); return; } @@ -421,6 +476,10 @@ or RebalanceStatus.InsufficientBalance await scheduler.ScheduleJob(job, trigger); + _logger.LogInformation( + "Rebalance {RebalanceId} retry scheduled: attempt {NextAttempt}/{MaxAttempts} in {DelaySeconds}s (newMaxFeePct={NewMaxFeePct}, fireAt={FireAt:O})", + rebalance.Id, nextAttempt, maxAttempts, delaySeconds, rebalance.MaxFeePct, fireAt); + await _auditService.LogAsync(AuditActionType.RebalanceRetryScheduled, AuditEventType.Attempt, AuditObjectType.Rebalance, rebalance.Id.ToString(), new