reducing host lease logs; adding debugging details on failure

Author: brettsam

src/WebJobs.Script/Host/BlobLeaseManager.cs

@@ -2,6 +2,7 @@
 // Licensed under the MIT License. See License.txt in the project root for license information.
 
 using System;
+using System.Globalization;
 using System.IO;
 using System.Threading;
 using System.Threading.Tasks;
@@ -27,6 +28,8 @@ internal sealed class BlobLeaseManager : IDisposable
         private string _leaseId;
         private bool _disposed;
         private bool _processingLease;
+        private DateTime _lastRenewal;
+        private TimeSpan _lastRenewalLatency;
 
         internal BlobLeaseManager(ICloudBlob lockBlob, TimeSpan leaseTimeout, string hostId, string instanceId, TraceWriter traceWriter, TimeSpan? renewalInterval = null)
         {
@@ -115,25 +118,40 @@ private async Task AcquireOrRenewLeaseAsync()
         {
             try
             {
+                DateTime requestStart = DateTime.UtcNow;
                 if (HasLease)
                 {
                     await _lockBlob.RenewLeaseAsync(new AccessCondition { LeaseId = LeaseId });
-                    _traceWriter.Verbose("Host lock lease renewed.");
+                    _lastRenewal = DateTime.UtcNow;
+                    _lastRenewalLatency = _lastRenewal - requestStart;
                 }
                 else
                 {
                     LeaseId = await _lockBlob.AcquireLeaseAsync(_leaseTimeout, _instanceId);
+                    _lastRenewal = DateTime.UtcNow;
+                    _lastRenewalLatency = _lastRenewal - requestStart;
+
                     _traceWriter.Info($"Host lock lease acquired by instance ID '{_instanceId}'.");
 
                     // We've successfully acquired the lease, change the timer to use our renewal interval
                     SetTimerInterval(_renewalInterval);
                 }
             }
             catch (StorageException exc)
-            {
+            {                
                 if (exc.RequestInformation.HttpStatusCode == 409)
                 {
-                    ProcessLeaseError("Another host has an active lease.");
+                    // If we did not have the lease already, a 409 indicates that another host had it. This is 
+                    // normal and does not warrant any logging.
+
+                    if (HasLease)
+                    {
+                        // The lease was 'stolen'. Log details for debugging.
+                        string lastRenewalFormatted = _lastRenewal.ToString("yyyy-MM-ddTHH:mm:ss.FFFZ", CultureInfo.InvariantCulture);
+                        int millisecondsSinceLastSuccess = (int)(DateTime.UtcNow - _lastRenewal).TotalMilliseconds;
+                        int lastRenewalMilliseconds = (int)_lastRenewalLatency.TotalMilliseconds;
+                        ProcessLeaseError($"Another host has acquired the lease. The last successful renewal completed at {lastRenewalFormatted} ({millisecondsSinceLastSuccess} milliseconds ago) with a duration of {lastRenewalMilliseconds} milliseconds.");
+                    }
                 }
                 else if (exc.RequestInformation.HttpStatusCode >= 500)
                 {

test/WebJobs.Script.Tests/BlobLeaseManagerTests.cs

@@ -6,6 +6,7 @@
 using System.Diagnostics;
 using System.IO;
 using System.Linq;
+using System.Text.RegularExpressions;
 using System.Threading;
 using System.Threading.Tasks;
 using Microsoft.Azure.WebJobs.Host;
@@ -235,53 +236,20 @@ public async Task TraceOutputsMessagesWhenLeaseIsAcquired()
 
             var blobMock = new Mock<ICloudBlob>();
             blobMock.Setup(b => b.AcquireLeaseAsync(It.IsAny<TimeSpan>(), It.IsAny<string>()))
-                .Returns(() => Task.FromResult(hostId));
-
-            blobMock.Setup(b => b.RenewLeaseAsync(It.IsAny<AccessCondition>()))
-                .Returns(() => Task.Delay(10).ContinueWith(t => renewResetEvent.Set()));
+                .Returns(() => Task.FromResult(hostId));            
 
             using (var manager = new BlobLeaseManager(blobMock.Object, TimeSpan.FromSeconds(5), hostId, instanceId, traceWriter))
             {
                 renewResetEvent.Wait(TimeSpan.FromSeconds(10));
 
                 // Make sure we have enough time to trace the renewal
-                await TestHelpers.Await(() => traceWriter.Traces.Count == 2, 5000, 500);
+                await TestHelpers.Await(() => traceWriter.Traces.Count == 1, 5000, 500);
             }
 
             TraceEvent acquisitionEvent = traceWriter.Traces.First();
             Assert.Contains($"Host lock lease acquired by instance ID '{instanceId}'.", acquisitionEvent.Message);
             Assert.Equal(TraceLevel.Info, acquisitionEvent.Level);
-
-            TraceEvent renewalEvent = traceWriter.Traces.Skip(1).First();
-            Assert.Contains("Host lock lease renewed.", renewalEvent.Message);
-            Assert.Equal(TraceLevel.Verbose, renewalEvent.Level);
-        }
-
-        [Fact]
-        public async Task TraceOutputsMessagesWhenLeaseAcquisitionFails()
-        {
-            string hostId = Guid.NewGuid().ToString();
-            string instanceId = Guid.NewGuid().ToString();
-            var traceWriter = new TestTraceWriter(TraceLevel.Verbose);
-            var acquisitionResetEvent = new ManualResetEventSlim();
-
-            var blobMock = new Mock<ICloudBlob>();
-            blobMock.Setup(b => b.AcquireLeaseAsync(It.IsAny<TimeSpan>(), It.IsAny<string>()))
-                .Returns(() => Task.FromException<string>(new StorageException(new RequestResult { HttpStatusCode = 409 }, "test", null)))
-                .Callback(() => acquisitionResetEvent.Set());
-
-            using (var manager = new BlobLeaseManager(blobMock.Object, TimeSpan.FromSeconds(10), hostId, instanceId, traceWriter))
-            {
-                acquisitionResetEvent.Wait(TimeSpan.FromSeconds(5));
-            }
-
-            // Make sure we have enough time to trace the renewal
-            await TestHelpers.Await(() => traceWriter.Traces.Count == 1, 5000, 500);
-
-            TraceEvent acquisitionEvent = traceWriter.Traces.First();
-            Assert.Contains($"Host instance '{instanceId}' failed to acquire host lock lease: Another host has an active lease.", acquisitionEvent.Message);
-            Assert.Equal(TraceLevel.Verbose, acquisitionEvent.Level);
-        }
+        }      
 
         [Fact]
         public async Task TraceOutputsMessagesWhenLeaseRenewalFails()
@@ -310,8 +278,9 @@ public async Task TraceOutputsMessagesWhenLeaseRenewalFails()
             Assert.Contains($"Host lock lease acquired by instance ID '{instanceId}'.", acquisitionEvent.Message);
             Assert.Equal(TraceLevel.Info, acquisitionEvent.Level);
 
-            TraceEvent renewalEvent = traceWriter.Traces.Skip(1).First();
-            Assert.Contains("Failed to renew host lock lease", renewalEvent.Message);
+            TraceEvent renewalEvent = traceWriter.Traces.Skip(1).First();            
+            string pattern = @"Failed to renew host lock lease: Another host has acquired the lease. The last successful renewal completed at (.+) \([0-9]+ milliseconds ago\) with a duration of [0-9]+ milliseconds.";
+            Assert.True(Regex.IsMatch(renewalEvent.Message, pattern), $"Expected trace event {pattern} not found.");            
             Assert.Equal(TraceLevel.Info, renewalEvent.Level);
         }