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();
}
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
}
