static async Task WriteAsync(ILogWriter writer, FunctionInstanceLogItem item) { await writer.AddAsync(item); // Start item.EndTime = item.StartTime.AddSeconds(1); await writer.AddAsync(item); // end }
public async Task LogStart() { // Make some very precise writes and verify we read exactly what we'd expect. var table = GetNewLoggingTable(); try { ILogWriter writer = LogFactory.NewWriter("c1", table); ILogReader reader = LogFactory.NewReader(table); string Func1 = "alpha"; var t1a = new DateTime(2010, 3, 6, 10, 11, 20, DateTimeKind.Utc); FunctionInstanceLogItem l1 = new FunctionInstanceLogItem { FunctionInstanceId = Guid.NewGuid(), FunctionName = Func1, StartTime = t1a, LogOutput = "one" // inferred as Running since no end time. }; await writer.AddAsync(l1); await writer.FlushAsync(); // Start event should exist. var entries = await GetRecentAsync(reader, Func1); Assert.Equal(1, entries.Length); Assert.Equal(entries[0].Status, FunctionInstanceStatus.Running); Assert.Equal(entries[0].EndTime, null); l1.EndTime = l1.StartTime.Add(TimeSpan.FromSeconds(1)); l1.Status = FunctionInstanceStatus.CompletedSuccess; await writer.AddAsync(l1); await writer.FlushAsync(); // Should overwrite the previous row. entries = await GetRecentAsync(reader, Func1); Assert.Equal(1, entries.Length); Assert.Equal(entries[0].Status, FunctionInstanceStatus.CompletedSuccess); Assert.Equal(entries[0].EndTime.Value.DateTime, l1.EndTime); } finally { // Cleanup table.DeleteIfExists(); } }
static async Task WriteAsync(ILogWriter writer, FunctionInstanceLogItem item) { item.Status = FunctionInstanceStatus.Running; await writer.AddAsync(item); // Start if (item.ErrorDetails == null) { item.Status = FunctionInstanceStatus.CompletedSuccess; } else { item.Status = FunctionInstanceStatus.CompletedFailure; } item.EndTime = item.StartTime.AddSeconds(1); await writer.AddAsync(item); // end }
// Write logs. Return what we wrote. // This is baseline data. REader will verify against it exactly. This helps in aggressively catching subtle breaking changes. private async Task <FunctionInstanceLogItem[]> WriteTestLoggingDataAsync(ILogTableProvider provider) { ILogWriter writer = LogFactory.NewWriter("c1", provider); string Func1 = "alpha"; var time = new DateTime(2010, 3, 6, 10, 11, 20); List <FunctionInstanceLogItem> list = new List <FunctionInstanceLogItem>(); list.Add(new FunctionInstanceLogItem { FunctionInstanceId = Guid.NewGuid(), FunctionName = Func1, StartTime = time, EndTime = time.AddMinutes(2), LogOutput = "one", Status = Microsoft.Azure.WebJobs.Logging.FunctionInstanceStatus.CompletedSuccess }); foreach (var item in list) { await writer.AddAsync(item); } await writer.FlushAsync(); return(list.ToArray()); }
public async Task AddAsync(FunctionInstanceLogEntry item, CancellationToken cancellationToken = default(CancellationToken)) { if (item.IsStart) { StartFunction(item); } else if (item.IsCompleted) { EndFunction(item); } if (_writer != null) { await _writer.AddAsync(new FunctionInstanceLogItem { FunctionInstanceId = item.FunctionInstanceId, FunctionName = item.LogName, StartTime = item.StartTime, EndTime = item.EndTime, TriggerReason = item.TriggerReason, Arguments = item.Arguments, ErrorDetails = item.ErrorDetails, LogOutput = item.LogOutput, ParentId = item.ParentId }); } }
public async Task LogStart() { // Make some very precise writes and verify we read exactly what we'd expect. ILogWriter writer = LogFactory.NewWriter(defaultHost, "c1", this); ILogReader reader = LogFactory.NewReader(this); string Func1 = "alpha"; var t1a = new DateTime(2010, 3, 6, 10, 11, 20, DateTimeKind.Utc); FunctionInstanceLogItem l1 = new FunctionInstanceLogItem { FunctionInstanceId = Guid.NewGuid(), FunctionName = Func1, StartTime = t1a, LogOutput = "one" // inferred as Running since no end time. }; await writer.AddAsync(l1); await writer.FlushAsync(); // Start event should exist. var entries = await GetRecentAsync(reader, l1.FunctionId); Assert.Single(entries); Assert.Equal(entries[0].GetStatus(), FunctionInstanceStatus.Running); Assert.Equal(entries[0].EndTime, null); l1.EndTime = l1.StartTime.Add(TimeSpan.FromSeconds(1)); await writer.AddAsync(l1); await writer.FlushAsync(); // Should overwrite the previous row. entries = await GetRecentAsync(reader, l1.FunctionId); Assert.Single(entries); Assert.Equal(entries[0].GetStatus(), FunctionInstanceStatus.CompletedSuccess); Assert.Equal(entries[0].EndTime.Value, l1.EndTime); }
public async Task Casing() { // Make some very precise writes and verify we read exactly what we'd expect. var table = GetNewLoggingTable(); try { ILogWriter writer = LogFactory.NewWriter("c1", table); ILogReader reader = LogFactory.NewReader(table); string FuncOriginal = "UPPER-lower"; string Func2 = FuncOriginal.ToLower(); // casing permutations string Func3 = Func2.ToLower(); var t1a = new DateTime(2010, 3, 6, 10, 11, 20, DateTimeKind.Utc); FunctionInstanceLogItem l1 = new FunctionInstanceLogItem { FunctionInstanceId = Guid.NewGuid(), FunctionName = FuncOriginal, StartTime = t1a, LogOutput = "one" // inferred as Running since no end time. }; await writer.AddAsync(l1); await writer.FlushAsync(); // Start event should exist. var definitionSegment = await reader.GetFunctionDefinitionsAsync(null); Assert.Equal(1, definitionSegment.Results.Length); Assert.Equal(FuncOriginal, definitionSegment.Results[0].Name); // Lookup various casings foreach (var name in new string[] { FuncOriginal, Func2, Func3 }) { var entries = await GetRecentAsync(reader, name); Assert.Equal(1, entries.Length); Assert.Equal(entries[0].Status, FunctionInstanceStatus.Running); Assert.Equal(entries[0].EndTime, null); Assert.Equal(entries[0].FunctionName, FuncOriginal); // preserving. } } finally { // Cleanup table.DeleteIfExists(); } }
public async Task AddAsync(FunctionInstanceLogEntry item, CancellationToken cancellationToken = default(CancellationToken)) { // Convert Host to Protocol so we can log it var settings = new JsonSerializerSettings { NullValueHandling = NullValueHandling.Ignore }; var jsonClone = JsonConvert.SerializeObject(item, settings); var item2 = JsonConvert.DeserializeObject <FunctionInstanceLogItem>(jsonClone); item2.FunctionName = Utility.GetFunctionShortName(item2.FunctionName); await _writer.AddAsync(item2); }
public async Task AddAsync(FunctionInstanceLogEntry item, CancellationToken cancellationToken = default(CancellationToken)) { FunctionInstanceMonitor state; item.Properties.TryGetValue(Key, out state); if (item.EndTime.HasValue) { // Completed bool success = item.ErrorDetails == null; state.End(success); } else { // Started if (state == null) { string shortName = Utility.GetFunctionShortName(item.FunctionName); FunctionDescriptor descr = _funcLookup(shortName); if (descr == null) { // This exception will cause the function to not get executed. throw new InvalidOperationException($"Missing function.json for '{shortName}'."); } FunctionLogger logInfo = descr.Invoker.LogInfo; state = new FunctionInstanceMonitor(descr.Metadata, _metrics, item.FunctionInstanceId, logInfo); item.Properties[Key] = state; state.Start(); } } if (_writer != null) { await _writer.AddAsync(new FunctionInstanceLogItem { FunctionInstanceId = item.FunctionInstanceId, FunctionName = Utility.GetFunctionShortName(item.FunctionName), StartTime = item.StartTime, EndTime = item.EndTime, TriggerReason = item.TriggerReason, Arguments = item.Arguments, ErrorDetails = item.ErrorDetails, LogOutput = item.LogOutput, ParentId = item.ParentId }); } }
public async Task LargeWritesWithParametersAreTruncated() { ILogWriter writer = LogFactory.NewWriter(defaultHost, "c1", this); ILogReader reader = LogFactory.NewReader(this); // Max table request size is 4mb. That gives roughly 40kb per row. string largeValue = new string('x', 100 * 1000); string truncatedPrefix = largeValue.Substring(0, 100); List <Guid> functionIds = new List <Guid>(); for (int i = 0; i < 90; i++) { var functionId = Guid.NewGuid(); functionIds.Add(functionId); var now = DateTime.UtcNow; var item = new FunctionInstanceLogItem { FunctionInstanceId = functionId, Arguments = new Dictionary <string, string>(), StartTime = now, EndTime = now.AddSeconds(3), FunctionName = "tst2", LogOutput = largeValue, ErrorDetails = largeValue, TriggerReason = largeValue }; for (int j = 0; j < 1000; j++) { string paramName = "p" + j.ToString(); item.Arguments[paramName] = largeValue; } await writer.AddAsync(item); } // If we didn't truncate, then this would throw with a 413 "too large" exception. await writer.FlushAsync(); // If we got here without an exception, then we successfully truncated the rows. // Lookup and verify var instance = await reader.LookupFunctionInstanceAsync(functionIds[0]); Assert.True(instance.LogOutput.StartsWith(truncatedPrefix)); Assert.True(instance.ErrorDetails.StartsWith(truncatedPrefix)); Assert.True(instance.TriggerReason.StartsWith(truncatedPrefix)); Assert.Equal(0, instance.Arguments.Count); // totally truncated. }
public async Task AddAsync(FunctionInstanceLogEntry item, CancellationToken cancellationToken = default(CancellationToken)) { await _writer.AddAsync(new FunctionInstanceLogItem { FunctionInstanceId = item.FunctionInstanceId, FunctionName = Utility.GetFunctionShortName(item.FunctionName), StartTime = item.StartTime, EndTime = item.EndTime, TriggerReason = item.TriggerReason, Arguments = item.Arguments, ErrorDetails = item.ErrorDetails, LogOutput = item.LogOutput, ParentId = item.ParentId }); }
public async Task AddAsync(FunctionInstanceLogEntry item, CancellationToken cancellationToken = default(CancellationToken)) { FunctionInstanceMonitor monitor; item.Properties.TryGetValue(Key, out monitor); if (item.EndTime.HasValue) { // Function Completed bool success = item.ErrorDetails == null; monitor.End(success); } else { // Function Started if (monitor == null) { if (_metadataManager.TryGetFunctionMetadata(item.LogName, out FunctionMetadata function)) { monitor = new FunctionInstanceMonitor(function, _metrics, item.FunctionInstanceId); item.Properties[Key] = monitor; monitor.Start(); } else { // This exception will cause the function to not get executed. throw new InvalidOperationException($"Missing function.json for '{item.LogName}'."); } } } if (_writer != null) { await _writer.AddAsync(new FunctionInstanceLogItem { FunctionInstanceId = item.FunctionInstanceId, FunctionName = item.LogName, StartTime = item.StartTime, EndTime = item.EndTime, TriggerReason = item.TriggerReason, Arguments = item.Arguments, ErrorDetails = item.ErrorDetails, LogOutput = item.LogOutput, ParentId = item.ParentId }); } }
public async Task OnExceptionCalled_WhenFlushFails() { Exception exToThrow = new InvalidOperationException("Some storage exception"); Mock <CloudTable> mockTable = new Mock <CloudTable>(MockBehavior.Strict, new Uri("https://fakeaccount.table.core.windows.net/sometable")); mockTable .Setup(t => t.ExecuteAsync(It.IsAny <TableOperation>(), null, null)) .ReturnsAsync(new TableResult()); mockTable .Setup(t => t.ExecuteAsync(It.IsAny <TableOperation>())) .ReturnsAsync(new TableResult()); mockTable .Setup(t => t.ExecuteBatchAsync(It.IsAny <TableBatchOperation>())) .ThrowsAsync(exToThrow); Mock <ILogTableProvider> mockProvider = new Mock <ILogTableProvider>(MockBehavior.Strict); mockProvider .Setup(c => c.GetTable(It.IsAny <string>())) .Returns(mockTable.Object); Exception caughtException = null; ILogWriter writer = LogFactory.NewWriter(defaultHost, "exceptions", mockProvider.Object, (ex) => { caughtException = ex; }); FunctionInstanceLogItem item = new FunctionInstanceLogItem { FunctionInstanceId = Guid.NewGuid(), FunctionName = "test", StartTime = DateTime.UtcNow, LogOutput = "three", ErrorDetails = "this failed" }; await writer.AddAsync(item); var thrownEx = await Assert.ThrowsAsync <InvalidOperationException>(() => writer.FlushAsync()); Assert.Same(exToThrow, thrownEx); Assert.Same(exToThrow, caughtException); }
// Write a function entry. Don't care about any other details. async Task <Guid> QuickWriteAsync(ILogWriter writer, string functionName) { FunctionInstanceLogItem l1 = new FunctionInstanceLogItem { FunctionInstanceId = Guid.NewGuid(), FunctionName = functionName, StartTime = _quickTimestamp, EndTime = _quickTimestamp.AddMinutes(1) // inferred as Running since no end time. }; _quickTimestamp = _quickTimestamp.AddMinutes(2); await writer.AddAsync(l1); await writer.FlushAsync(); return(l1.FunctionInstanceId); }
// Write logs. Return what we wrote. // This is baseline data. REader will verify against it exactly. This helps in aggressively catching subtle breaking changes. private async Task WriteTestLoggingDataAsync(ILogTableProvider provider) { ILogWriter writer = LogFactory.NewWriter(HostName, "c1", provider); string Func1 = "alpha"; var time = new DateTime(2010, 3, 6, 18, 11, 20, DateTimeKind.Utc); List <FunctionInstanceLogItem> list = new List <FunctionInstanceLogItem>(); List <InvocationLogViewModel> expected = new List <InvocationLogViewModel>(); this.ExpectedItems = expected; this.Data = list; // List in reverse chronology. // Completed Success { var item = new FunctionInstanceLogItem { FunctionInstanceId = Guid.NewGuid(), FunctionName = Func1, StartTime = time, EndTime = time.AddMinutes(2), // Completed LogOutput = "one", }; list.Add(item); expected.Add(new InvocationLogViewModel { id = item.FunctionInstanceId.ToString(), status = "CompletedSuccess", whenUtc = "2010-03-06T18:13:20Z", // since it's completed, specifies end-time duration = 120000.0 }); } // Completed Error { time = time.AddMinutes(-1); var item = new FunctionInstanceLogItem { FunctionInstanceId = Guid.NewGuid(), FunctionName = Func1, StartTime = time, EndTime = time.AddMinutes(2), ErrorDetails = "some failure", // signifies failure LogOutput = "two", }; list.Add(item); expected.Add(new InvocationLogViewModel { id = item.FunctionInstanceId.ToString(), status = "CompletedFailed", whenUtc = "2010-03-06T18:12:20Z", // end-time. duration = 120000.0 }); } // Still running { time = time.AddMinutes(-1); var item = new FunctionInstanceLogItem { FunctionInstanceId = Guid.NewGuid(), FunctionName = Func1, StartTime = time, // Recent heartbeat LogOutput = "two", }; list.Add(item); expected.Add(new InvocationLogViewModel { id = item.FunctionInstanceId.ToString(), status = "Running", whenUtc = "2010-03-06T18:09:20Z", // specifies start-time }); } // Never Finished { time = time.AddMinutes(-1); var item = new TestFunctionInstanceLogItem { FunctionInstanceId = Guid.NewGuid(), FunctionName = Func1, StartTime = time, // Never Finished LogOutput = "two", OnRefresh = (me) => { me.FunctionInstanceHeartbeatExpiry = time; }, // stale heartbeat }; list.Add(item); expected.Add(new InvocationLogViewModel { id = item.FunctionInstanceId.ToString(), status = "NeverFinished", whenUtc = "2010-03-06T18:08:20Z", // starttime duration = null }); } // No heartbeat (legacy example) { time = time.AddMinutes(-1); var item = new TestFunctionInstanceLogItem { FunctionInstanceId = Guid.NewGuid(), FunctionName = Func1, StartTime = time, // Never Finished LogOutput = "two", OnRefresh = (me) => { } // No heart beat }; list.Add(item); expected.Add(new InvocationLogViewModel { id = item.FunctionInstanceId.ToString(), status = "Running", whenUtc = "2010-03-06T18:07:20Z", // starttime }); } foreach (var item in list) { await writer.AddAsync(item); } await writer.FlushAsync(); }