Add some verbose logs to detect delay

source/Octopus.Tentacle.Client/Execution/RpcCallExecutor.cs

@@ -67,7 +67,9 @@ public async Task<T> ExecuteWithRetries<T>(
 
                             try
                             {
+                                logger.Verbose("Before action");
                                 var response = await action(ct);
+                                logger.Verbose("After action");
 
                                 rpcCallMetricsBuilder.WithAttempt(TimedOperation.Success(start));
                                 return response;
@@ -82,7 +84,9 @@ public async Task<T> ExecuteWithRetries<T>(
                         {
                             await Task.CompletedTask;
 
+                            logger.Verbose("Before error action");
                             onErrorAction?.Invoke(lastException);
+                            logger.Verbose("After error action");
 
                             var remainingDurationInSeconds = (int)(totalRetryDuration - elapsedDuration).TotalSeconds;
                             logger.Info($"An error occurred communicating with Tentacle. This action will be retried after {(int)sleepDuration.TotalSeconds} seconds. Retry attempt {retryCount}. Retries will be performed for up to {remainingDurationInSeconds} seconds.");
@@ -101,7 +105,8 @@ public async Task<T> ExecuteWithRetries<T>(
                                 logger.Info($"Could not communicate with Tentacle after {(int)elapsedDuration.TotalSeconds} seconds.");
                             }
                         },
-                        cancellationToken);
+                        cancellationToken,
+                        logger);
 
                 return response;
             }

source/Octopus.Tentacle.Client/Retries/RpcCallRetryHandler.cs

@@ -3,6 +3,7 @@
 using System.Threading;
 using System.Threading.Tasks;
 using Octopus.Tentacle.Client.Scripts;
+using Octopus.Tentacle.Contracts.Logging;
 using Polly;
 using Polly.Timeout;
 
@@ -37,13 +38,16 @@ public async Task<T> ExecuteWithRetries<T>(
             Func<CancellationToken, Task<T>> action,
             OnRetryAction? onRetryAction,
             OnTimeoutAction? onTimeoutAction,
-            CancellationToken cancellationToken)
+            CancellationToken cancellationToken,
+            ITentacleClientTaskLog? logger = null)
         {
             Exception? lastException = null;
             var started = new Stopwatch();
             var nextSleepDuration = TimeSpan.Zero;
             var totalRetryCount = 0;
 
+            logger ??= new EmptyLog();
+
             async Task OnRetryAction(Exception exception, TimeSpan sleepDuration, int retryCount, Context context)
             {
                 if (lastException == null)
@@ -53,11 +57,11 @@ async Task OnRetryAction(Exception exception, TimeSpan sleepDuration, int retryC
                 // Cancellation/Retry Timeout will result in a TransferringRequestCancelledException or ConnectingRequestCancelledException
                 // which will hide the original exception. We ignore a cancellation/retry timeout triggered exception so we don't hide the last real exception
                 // that occurred during the retry process
-                else if(cancellationToken.IsCancellationRequested || !exception.IsConnectingOrTransferringRequestCancelledException())
+                else if (cancellationToken.IsCancellationRequested || !exception.IsConnectingOrTransferringRequestCancelledException())
                 {
                     lastException = exception;
                 }
-                
+
                 nextSleepDuration = sleepDuration;
                 var elapsedDuration = started.Elapsed;
                 var remainingRetryDuration = RetryTimeout - elapsedDuration - sleepDuration;
@@ -83,12 +87,16 @@ async Task OnTimeoutAction(Context? context, TimeSpan timeout, Task? task, Excep
                 }
             }
 
+            Stopwatch sw = new();
+            sw.Start();
             var policyBuilder = new RpcCallRetryPolicyBuilder()
                 .WithRetryTimeout(RetryTimeout)
                 .WithOnRetryAction(OnRetryAction)
                 .WithOnTimeoutAction(OnTimeoutAction);
-
             var retryPolicy = policyBuilder.BuildRetryPolicy();
+            sw.Stop();
+            logger.VerboseTimed(sw, "Built retry policy");
+
             var isInitialAction = true;
 
             // This ensures the timeout policy does not apply to the initial request and only applies to retries
@@ -97,32 +105,46 @@ async Task<T> ExecuteAction(CancellationToken ct)
                 if (isInitialAction)
                 {
                     isInitialAction = false;
-                    return await action(ct).ConfigureAwait(false);
+                    sw.Start();
+                    var result = await action(ct).ConfigureAwait(false);
+                    sw.Stop();
+                    logger.VerboseTimed(sw, "ExecuteAction - initial action");
+                    return result;
                 }
 
                 var remainingRetryDuration = RetryTimeout - started.Elapsed - nextSleepDuration;
 
                 if (!ShouldRetryWithRemainingDuration(remainingRetryDuration))
                 {
                     // We are short circuiting as the retry duration has elapsed
+                    sw.Start();
                     await OnTimeoutAction(null, RetryTimeout, null, null).ConfigureAwait(false);
+                    sw.Stop();
+                    logger.VerboseTimed(sw, "ExecuteAction - timeout action");
                     throw new TimeoutRejectedException("The delegate executed asynchronously through TimeoutPolicy did not complete within the timeout.");
                 }
 
+                sw.Start();
                 var timeoutPolicy = policyBuilder
                     // Ensure the remaining retry time excludes the elapsed time
                     .WithRetryTimeout(remainingRetryDuration)
                     .BuildTimeoutPolicy();
-
-                return await timeoutPolicy.ExecuteAsync(action, ct).ConfigureAwait(false);
+                sw.Stop();
+                logger.VerboseTimed(sw, "ExecuteAction - built retry policy for remaining timeout");
+
+                sw.Start();
+                var timeoutResult = await timeoutPolicy.ExecuteAsync(action, ct).ConfigureAwait(false);
+                sw.Stop();
+                logger.VerboseTimed(sw, "ExecuteAction - execute action with new retry timeout");
+                return timeoutResult;
             }
 
             try
             {
                 started.Start();
                 return await retryPolicy.ExecuteAsync(ExecuteAction, cancellationToken);
             }
-            catch (Exception ex) when (ex is TimeoutRejectedException or TaskCanceledException || 
+            catch (Exception ex) when (ex is TimeoutRejectedException or TaskCanceledException ||
                                        ex.IsConnectingOrTransferringRequestCancelledException())
             {
                 // If the timeout policy timed out or the cancellation token caused a generic task cancellation 

source/Octopus.Tentacle.Contracts/Logging/ITentacleClientTaskLog.cs

@@ -1,4 +1,5 @@
 using System;
+using System.Diagnostics;
 
 namespace Octopus.Tentacle.Contracts.Logging
 {
@@ -10,4 +11,36 @@ public interface ITentacleClientTaskLog
         void Warn(string message);
         void Warn(Exception exception, string message);
     }
-}
+
+    public static class TentacleClientTaskLogExtensions
+    {
+        public static void VerboseTimed(this ITentacleClientTaskLog log, Stopwatch sw, string message)
+        {
+            log.Verbose($"{message} ({sw.ElapsedMilliseconds}ms elapsed)");
+            sw.Reset();
+        }
+    }
+
+    public class EmptyLog : ITentacleClientTaskLog
+    {
+        public void Info(string message)
+        {
+        }
+
+        public void Verbose(string message)
+        {
+        }
+
+        public void Verbose(Exception exception)
+        {
+        }
+
+        public void Warn(string message)
+        {
+        }
+
+        public void Warn(Exception exception, string message)
+        {
+        }
+    }
+}