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 static FunctionInstanceSnapshot ConvertToSnapshot(this FunctionInstanceLogItem entity)
{
var arguments = new Dictionary <string, FunctionInstanceArgument>();
foreach (var kv in entity.Arguments)
{
arguments[kv.Key] = new FunctionInstanceArgument {
Value = kv.Value
};
}
return(new FunctionInstanceSnapshot
{
Id = entity.FunctionInstanceId,
ParentId = entity.ParentId,
FunctionFullName = entity.FunctionName,
FunctionShortName = entity.FunctionName,
StartTime = entity.StartTime,
EndTime = entity.EndTime,
Reason = entity.TriggerReason,
InlineOutputText = entity.LogOutput,
Succeeded = entity.IsSucceeded(),
ExceptionMessage = entity.ErrorDetails,
ExceptionType = "Failure", // generic failure message
Arguments = arguments
});
}
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();
}
}
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 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.
}
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
}
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);
}
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);
}
// 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();
}
public async Task LogExactWriteAndRead()
{
// 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";
string Func2 = "beta";
var t1a = new DateTime(2010, 3, 6, 10, 11, 20);
var t1b = new DateTime(2010, 3, 6, 10, 11, 21); // same time bucket as t1a
var t2 = new DateTime(2010, 3, 7, 10, 11, 21);
FunctionInstanceLogItem l1 = new FunctionInstanceLogItem
{
FunctionInstanceId = Guid.NewGuid(),
FunctionName = Func1,
StartTime = t1a,
LogOutput = "one"
};
await WriteAsync(writer, l1);
await writer.FlushAsync(); // Multiple flushes; test starting & stopping the backgrounf worker.
FunctionInstanceLogItem l2 = new FunctionInstanceLogItem
{
FunctionInstanceId = Guid.NewGuid(),
FunctionName = Func2,
StartTime = t1b,
LogOutput = "two"
};
await WriteAsync(writer, l2);
FunctionInstanceLogItem l3 = new FunctionInstanceLogItem
{
FunctionInstanceId = Guid.NewGuid(),
FunctionName = Func1,
StartTime = t2,
LogOutput = "three",
ErrorDetails = "this failed"
};
await WriteAsync(writer, l3);
await writer.FlushAsync();
// Now read
var definitionSegment = await reader.GetFunctionDefinitionsAsync(null, null);
string[] functionNames = Array.ConvertAll(definitionSegment.Results, definition => definition.Name);
Array.Sort(functionNames);
Assert.Equal(Func1, functionNames[0]);
Assert.Equal(Func2, functionNames[1]);
// Read Func1
{
var segment1 = await reader.GetAggregateStatsAsync(l3.FunctionId, DateTime.MinValue, DateTime.MaxValue, null);
Assert.Null(segment1.ContinuationToken);
var stats1 = segment1.Results;
Assert.Equal(2, stats1.Length); // includes t1 and t2
// First bucket has l1, second bucket has l3
Assert.Equal(stats1[0].TotalPass, 1);
Assert.Equal(stats1[0].TotalRun, 1);
Assert.Equal(stats1[0].TotalFail, 0);
Assert.Equal(stats1[1].TotalPass, 0);
Assert.Equal(stats1[1].TotalRun, 1);
Assert.Equal(stats1[1].TotalFail, 1);
// reverse order. So l3 latest function, is listed first.
var recent1 = await GetRecentAsync(reader, l3.FunctionId);
Assert.Equal(2, recent1.Length);
Assert.Equal(recent1[0].FunctionInstanceId, l3.FunctionInstanceId);
Assert.Equal(recent1[1].FunctionInstanceId, l1.FunctionInstanceId);
}
// Read Func2
{
var segment2 = await reader.GetAggregateStatsAsync(l2.FunctionId, DateTime.MinValue, DateTime.MaxValue, null);
var stats2 = segment2.Results;
Assert.Single(stats2);
Assert.Equal(stats2[0].TotalPass, 1);
Assert.Equal(stats2[0].TotalRun, 1);
Assert.Equal(stats2[0].TotalFail, 0);
var recent2 = await GetRecentAsync(reader, l2.FunctionId);
Assert.Single(recent2);
Assert.Equal(recent2[0].FunctionInstanceId, l2.FunctionInstanceId);
}
}
public async Task OnExceptionBackgroundFlushResumesOnNextAdd()
{
Exception exToThrow1 = new InvalidOperationException("First storage exception");
Exception exToThrow2 = new InvalidOperationException("Second storage exception");
Mock <CloudTable> mockTable = new Mock <CloudTable>(MockBehavior.Strict, new Uri("https://fakeaccount.table.core.windows.net/sometable"));
mockTable
.SetupSequence(t => t.ExecuteBatchAsync(It.IsAny <TableBatchOperation>()))
// First background flush
.ReturnsAsync(new List <TableResult> {
new TableResult()
})
.ThrowsAsync(exToThrow1)
// Second background flush
.ReturnsAsync(new List <TableResult> {
new TableResult()
})
.ThrowsAsync(exToThrow2);
Mock <ILogTableProvider> mockProvider = new Mock <ILogTableProvider>(MockBehavior.Strict);
mockProvider
.Setup(c => c.GetTable(It.IsAny <string>()))
.Returns(mockTable.Object);
List <Exception> caughtExceptions = new List <Exception>();
LogWriter writer = (LogWriter)LogFactory.NewWriter(defaultHost, "exceptions", mockProvider.Object, (ex) =>
{
caughtExceptions.Add(ex);
});
writer.FlushInterval = TimeSpan.FromMilliseconds(500);
FunctionInstanceLogItem item1 = new FunctionInstanceLogItem
{
FunctionInstanceId = Guid.NewGuid(),
FunctionName = "test",
StartTime = DateTime.UtcNow,
LogOutput = "output 1",
};
FunctionInstanceLogItem item2 = new FunctionInstanceLogItem
{
FunctionInstanceId = item1.FunctionInstanceId,
FunctionName = item1.FunctionName,
StartTime = item1.StartTime,
LogOutput = "output 2"
};
await writer.AddAsync(item1);
await TestHelpers.Await(() => caughtExceptions.Count == 1, timeout : 5000, pollingInterval : 100, userMessageCallback : () => $"Expected caughtExceptions == 1; Actual: {caughtExceptions.Count}");
// Without fixes to the error handling in the background flusher task, this second condition would never be met because no further flushes would occur after the first exception.
await writer.AddAsync(item2);
await TestHelpers.Await(() => caughtExceptions.Count == 2, timeout : 5000, pollingInterval : 100, userMessageCallback : () => $"Expected caughtExceptions == 2; Actual: {caughtExceptions.Count}");
Assert.Same(exToThrow1, caughtExceptions[0]);
Assert.Same(exToThrow2, caughtExceptions[1]);
mockTable.VerifyAll();
}
public async Task LogExactWriteAndRead()
{
// 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";
string Func2 = "beta";
var t1a = new DateTime(2010, 3, 6, 10, 11, 20);
var t1b = new DateTime(2010, 3, 6, 10, 11, 21); // same time bucket as t1a
var t2 = new DateTime(2010, 3, 7, 10, 11, 21);
FunctionInstanceLogItem l1 = new FunctionInstanceLogItem
{
FunctionInstanceId = Guid.NewGuid(),
FunctionName = Func1,
StartTime = t1a,
LogOutput = "one"
};
await WriteAsync(writer, l1);
FunctionInstanceLogItem l2 = new FunctionInstanceLogItem
{
FunctionInstanceId = Guid.NewGuid(),
FunctionName = Func2,
StartTime = t1b,
LogOutput = "two"
};
await WriteAsync(writer, l2);
FunctionInstanceLogItem l3 = new FunctionInstanceLogItem
{
FunctionInstanceId = Guid.NewGuid(),
FunctionName = Func1,
StartTime = t2,
LogOutput = "three",
ErrorDetails = "this failed"
};
await WriteAsync(writer, l3);
await writer.FlushAsync();
// Now read
string[] functionNames = await reader.GetFunctionNamesAsync();
Array.Sort(functionNames);
Assert.Equal(Func1, functionNames[0]);
Assert.Equal(Func2, functionNames[1]);
// Read Func1
{
var segment1 = await reader.GetAggregateStatsAsync(Func1, DateTime.MinValue, DateTime.MaxValue, null);
Assert.Null(segment1.ContinuationToken);
var stats1 = segment1.Results;
Assert.Equal(2, stats1.Length); // includes t1 and t2
// First bucket has l1, second bucket has l3
Assert.Equal(stats1[0].TotalPass, 1);
Assert.Equal(stats1[0].TotalRun, 1);
Assert.Equal(stats1[0].TotalFail, 0);
Assert.Equal(stats1[1].TotalPass, 0);
Assert.Equal(stats1[1].TotalRun, 1);
Assert.Equal(stats1[1].TotalFail, 1);
// reverse order. So l3 latest function, is listed first.
var recent1 = await GetRecentAsync(reader, Func1);
Assert.Equal(2, recent1.Length);
Assert.Equal(recent1[0].FunctionInstanceId, l3.FunctionInstanceId);
Assert.Equal(recent1[1].FunctionInstanceId, l1.FunctionInstanceId);
}
// Read Func2
{
var segment2 = await reader.GetAggregateStatsAsync(Func2, DateTime.MinValue, DateTime.MaxValue, null);
var stats2 = segment2.Results;
Assert.Equal(1, stats2.Length);
Assert.Equal(stats2[0].TotalPass, 1);
Assert.Equal(stats2[0].TotalRun, 1);
Assert.Equal(stats2[0].TotalFail, 0);
var recent2 = await GetRecentAsync(reader, Func2);
Assert.Equal(1, recent2.Length);
Assert.Equal(recent2[0].FunctionInstanceId, l2.FunctionInstanceId);
}
}
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
}
private string BuildFunctionDisplayTitle()
{
IEnumerable <string> argumentValues = Arguments.Values.Select(v => v.Value);
return(FunctionInstanceLogItem.BuildFunctionDisplayTitle(this.FunctionShortName, argumentValues));
}