public void MissingHostJson_CreatesHostJson_withDefaultExtensionBundleId()
{
Assert.False(File.Exists(_hostJsonFile));
TestMetricsLogger testMetricsLogger = new TestMetricsLogger();
BuildHostJsonConfiguration(testMetricsLogger);
AreExpectedMetricsGenerated(testMetricsLogger);
Assert.Equal(_hostJsonWithBundles, File.ReadAllText(_hostJsonFile));
var log = _loggerProvider.GetAllLogMessages().Single(l => l.FormattedMessage == "No host configuration file found. Creating a default host.json file.");
Assert.Equal(LogLevel.Information, log.Level);
}
public async Task Starting_MultipleJobhostChannels_Failed()
{
_testLoggerProvider.ClearAllLogMessages();
int expectedProcessCount = 3;
RpcFunctionInvocationDispatcher functionDispatcher = GetTestFunctionDispatcher(expectedProcessCount, throwOnProcessStartUp: true);
await functionDispatcher.InitializeAsync(GetTestFunctionsList(RpcWorkerConstants.NodeLanguageWorkerName));
var finalChannelCount = await WaitForJobhostWorkerChannelsToStartup(functionDispatcher, expectedProcessCount, false);
Assert.Equal(expectedProcessCount, finalChannelCount);
var logMessages = _testLoggerProvider.GetAllLogMessages().ToList();
Assert.Equal(logMessages.Where(x => x.FormattedMessage
.Contains("Failed to start a new language worker")).Count(), 3);
}
public void LogExceptionReceivedEvent_NonTransientEvent_LoggedAsError()
{
var ex = new ServiceBusException(false);
Assert.False(ex.IsTransient);
ExceptionReceivedEventArgs e = new ExceptionReceivedEventArgs(ex, "TestAction", "TestEndpoint", "TestEntity", "TestClient");
ServiceBusExtensionConfigProvider.LogExceptionReceivedEvent(e, _loggerFactory);
var expectedMessage = $"MessageReceiver error (Action=TestAction, ClientId=TestClient, EntityPath=TestEntity, Endpoint=TestEndpoint)";
var logMessage = _loggerProvider.GetAllLogMessages().Single();
Assert.Equal(LogLevel.Error, logMessage.Level);
Assert.Same(ex, logMessage.Exception);
Assert.Equal(expectedMessage, logMessage.FormattedMessage);
}
public async Task HostRestart_Specialization_Succeeds()
{
_host.Setup(h => h.StartAsync(It.IsAny <CancellationToken>()))
.Returns(Task.CompletedTask);
var hostBuilder = new Mock <IScriptHostBuilder>();
hostBuilder.Setup(b => b.BuildHost(It.IsAny <bool>(), It.IsAny <bool>()))
.Returns(_host.Object);
_webHostLoggerProvider = new TestLoggerProvider();
_loggerFactory = new LoggerFactory();
_loggerFactory.AddProvider(_webHostLoggerProvider);
_hostService = new WebJobsScriptHostService(
_monitor, hostBuilder.Object, _loggerFactory, _mockRootServiceProvider.Object, _mockRootScopeFactory.Object,
_mockScriptWebHostEnvironment.Object, _mockEnvironment.Object, _hostPerformanceManager, _healthMonitorOptions);
await _hostService.StartAsync(CancellationToken.None);
Thread restartHostThread = new Thread(new ThreadStart(RestartHost));
Thread specializeHostThread = new Thread(new ThreadStart(SpecializeHost));
restartHostThread.Start();
specializeHostThread.Start();
restartHostThread.Join();
specializeHostThread.Join();
var logMessages = _webHostLoggerProvider.GetAllLogMessages().Where(m => m.FormattedMessage.Contains("Restarting host."));
Assert.Equal(2, logMessages.Count());
}
public async Task HostRestart_BeforeStart_WaitsForStartToContinue()
{
_host = CreateMockHost();
var hostBuilder = new Mock <IScriptHostBuilder>();
hostBuilder.SetupSequence(b => b.BuildHost(It.IsAny <bool>(), It.IsAny <bool>()))
.Returns(_host.Object)
.Returns(_host.Object);
_webHostLoggerProvider = new TestLoggerProvider();
_loggerFactory = new LoggerFactory();
_loggerFactory.AddProvider(_webHostLoggerProvider);
_hostService = new WebJobsScriptHostService(
_monitor, hostBuilder.Object, _loggerFactory, _mockRootServiceProvider.Object, _mockRootScopeFactory.Object,
_mockScriptWebHostEnvironment.Object, _mockEnvironment.Object, _hostPerformanceManager, _healthMonitorOptions);
// Simulate a call to specialize coming from the PlaceholderSpecializationMiddleware. This
// can happen before we ever start the service, which could create invalid state.
Task restartTask = _hostService.RestartHostAsync(CancellationToken.None);
await _hostService.StartAsync(CancellationToken.None);
await restartTask;
var messages = _webHostLoggerProvider.GetAllLogMessages();
// The CancellationToken is canceled quick enough that we never build the initial host, so the
// only one we start is the restarted/specialized one.
Assert.NotNull(messages.Single(p => p.EventId.Id == 513)); // "Building" message
Assert.NotNull(messages.Single(p => p.EventId.Id == 514)); // "StartupWasCanceled" message
Assert.NotNull(messages.Single(p => p.EventId.Id == 520)); // "RestartBeforeStart" message
_host.Verify(p => p.StartAsync(It.IsAny <CancellationToken>()), Times.Once);
}
public async Task GetExtensionsStartupTypes_UnableToDownloadExtensionBundle_ReturnsNull()
{
var mockExtensionBundleManager = new Mock <IExtensionBundleManager>();
mockExtensionBundleManager.Setup(e => e.IsExtensionBundleConfigured()).Returns(true);
mockExtensionBundleManager.Setup(e => e.GetExtensionBundlePath()).ReturnsAsync(string.Empty);
TestLoggerProvider testLoggerProvider = new TestLoggerProvider();
LoggerFactory factory = new LoggerFactory();
TestMetricsLogger testMetricsLogger = new TestMetricsLogger();
factory.AddProvider(testLoggerProvider);
var testLogger = factory.CreateLogger <ScriptStartupTypeLocator>();
var mockFunctionMetadataManager = GetTestFunctionMetadataManager(ImmutableArray <FunctionMetadata> .Empty);
var discoverer = new ScriptStartupTypeLocator(string.Empty, testLogger, mockExtensionBundleManager.Object, mockFunctionMetadataManager, testMetricsLogger);
// Act
var types = await discoverer.GetExtensionsStartupTypesAsync();
var traces = testLoggerProvider.GetAllLogMessages();
// Assert
Assert.True(traces.Any(m => string.Equals(m.FormattedMessage, $"Unable to find or download extension bundle")));
AreExpectedMetricsGenerated(testMetricsLogger);
Assert.NotNull(types);
Assert.Equal(types.Count(), 0);
}
public async Task RunAndBlock_SelfHost_Succeeds()
{
var loggerProvider = new TestLoggerProvider();
var loggerProviderFactory = new TestLoggerProviderFactory(loggerProvider);
ScriptHostConfiguration config = new ScriptHostConfiguration()
{
RootScriptPath = Environment.CurrentDirectory,
IsSelfHost = true
};
ScriptHostManager manager = null;
LogMessage[] logs = null;
using (manager = new ScriptHostManager(config, loggerProviderFactory: loggerProviderFactory))
{
var tIgnore = Task.Run(() => manager.RunAndBlock());
await TestHelpers.Await(() =>
{
logs = loggerProvider.GetAllLogMessages().Where(p => p.FormattedMessage != null).ToArray();
return(manager.State == ScriptHostState.Error || logs.Any(p => p.FormattedMessage.Contains("Job host started")));
});
Assert.Equal(ScriptHostState.Running, manager.State);
Assert.Equal(0, logs.Count(p => p.Level == LogLevel.Error));
}
}
public void Capability_Handled_Correctly(string value)
{
MapField <string, string> addedCapabilities = new MapField <string, string>
{
{ testCapability2, value }
};
_capabilities.UpdateCapabilities(addedCapabilities);
Assert.Equal(value, _capabilities.GetCapabilityState(testCapability2));
var logs = _loggerProvider.GetAllLogMessages().Select(p => p.FormattedMessage).ToArray();
Assert.Collection(logs,
p => Assert.Equal($"Updating capabilities: {{ \"{testCapability2}\": \"{value}\" }}", p));
}
public async Task GetExtensionsStartupTypes_FiltersBuiltinExtensionsAsync()
{
var references = new[]
{
new ExtensionReference {
Name = "Http", TypeName = typeof(HttpWebJobsStartup).AssemblyQualifiedName
},
new ExtensionReference {
Name = "Timers", TypeName = typeof(ExtensionsWebJobsStartup).AssemblyQualifiedName
},
new ExtensionReference {
Name = "Storage", TypeName = typeof(AzureStorageWebJobsStartup).AssemblyQualifiedName
},
};
var extensions = new JObject
{
{ "extensions", JArray.FromObject(references) }
};
var mockExtensionBundleManager = new Mock <IExtensionBundleManager>();
mockExtensionBundleManager.Setup(e => e.IsExtensionBundleConfigured()).Returns(false);
using (var directory = new TempDirectory())
{
var binPath = Path.Combine(directory.Path, "bin");
Directory.CreateDirectory(binPath);
void CopyToBin(string path)
{
File.Copy(path, Path.Combine(binPath, Path.GetFileName(path)));
}
CopyToBin(typeof(HttpWebJobsStartup).Assembly.Location);
CopyToBin(typeof(ExtensionsWebJobsStartup).Assembly.Location);
CopyToBin(typeof(AzureStorageWebJobsStartup).Assembly.Location);
File.WriteAllText(Path.Combine(binPath, "extensions.json"), extensions.ToString());
TestLoggerProvider testLoggerProvider = new TestLoggerProvider();
LoggerFactory factory = new LoggerFactory();
factory.AddProvider(testLoggerProvider);
var testLogger = factory.CreateLogger <ScriptStartupTypeLocator>();
var mockFunctionMetadataProvider = GetTestFunctionMetadataProvider(ImmutableArray <FunctionMetadata> .Empty);
var discoverer = new ScriptStartupTypeLocator(directory.Path, testLogger, mockExtensionBundleManager.Object, mockFunctionMetadataProvider);
// Act
var types = await discoverer.GetExtensionsStartupTypesAsync();
var traces = testLoggerProvider.GetAllLogMessages();
// Assert
Assert.Single(types);
Assert.Equal(typeof(AzureStorageWebJobsStartup).FullName, types.Single().FullName);
Assert.True(traces.Any(m => string.Equals(m.FormattedMessage, $"The extension startup type '{references[0].TypeName}' belongs to a builtin extension")));
Assert.True(traces.Any(m => string.Equals(m.FormattedMessage, $"The extension startup type '{references[1].TypeName}' belongs to a builtin extension")));
}
}
public async Task ListCheckpointsAsync_LogsOnInvalidCheckpoints()
{
var testLoggerProvider = new TestLoggerProvider();
Mock <BlobContainerClient> containerClientMock = new Mock <BlobContainerClient>(MockBehavior.Strict);
containerClientMock.Setup(c => c.GetBlobsAsync(It.IsAny <BlobTraits>(), It.IsAny <BlobStates>(), It.IsAny <string>(), It.IsAny <CancellationToken>()))
.Returns(AsyncPageable <BlobItem> .FromPages(new[]
{
Page <BlobItem> .FromValues(new[]
{
BlobsModelFactory.BlobItem("testnamespace/testeventhubname/testconsumergroup/checkpoint/0", false, BlobsModelFactory.BlobItemProperties(false), metadata: new Dictionary <string, string>())
}, null, Mock.Of <Response>())
}));
BlobsCheckpointStore store = new BlobsCheckpointStore(
containerClientMock.Object,
new BasicRetryPolicy(new EventHubsRetryOptions()),
_functionId,
testLoggerProvider.CreateLogger("TestLogger")
);
await store.ListCheckpointsAsync(_namespace, _eventHubName, _consumerGroup, CancellationToken.None);
var warning = testLoggerProvider.GetAllLogMessages().Single(p => p.Level == Extensions.Logging.LogLevel.Warning);
var expectedWarning = "Function 'EventHubsTriggerFunction': An invalid checkpoint was found for partition: '0' of " +
"FullyQualifiedNamespace: 'TestNamespace'; EventHubName: 'TestEventHubName'; ConsumerGroup: 'TestConsumerGroup'. " +
"This checkpoint is not valid and will be ignored.";
Assert.AreEqual(expectedWarning, warning.FormattedMessage);
testLoggerProvider.ClearAllLogMessages();
}
public void Initialize_AppliesLoggerConfig()
{
// Default mininum level is Information, so set this to Warning and make
// sure Information-level logs are filtered
TestLoggerProvider loggerProvider = new TestLoggerProvider();
IHost host = new HostBuilder()
.ConfigureAppConfiguration(c =>
{
c.AddInMemoryCollection(new Dictionary <string, string>
{
{ ConfigurationPath.Combine(_loggingPath, "LogLevel", "Default"), "Warning" },
});
})
.ConfigureDefaultTestWebScriptHost()
.ConfigureLogging(l =>
{
l.AddProvider(loggerProvider);
})
.Build();
ILogger logger = host.Services.GetService <ILogger <LoggingConfigurationTests> >();
logger.LogInformation("Information");
logger.LogWarning("Warning");
LogMessage messages = loggerProvider.GetAllLogMessages().Single();
Assert.Equal("Warning", messages.FormattedMessage);
}
public async Task GetExtensionsStartupTypes_ExtensionBundleReturnsNullPath_ReturnsNull()
{
var mockExtensionBundleManager = new Mock <IExtensionBundleManager>();
mockExtensionBundleManager.Setup(e => e.IsExtensionBundleConfigured()).Returns(true);
mockExtensionBundleManager.Setup(e => e.GetExtensionBundlePath()).ReturnsAsync(string.Empty);
using (var directory = new TempDirectory())
{
TestLoggerProvider testLoggerProvider = new TestLoggerProvider();
LoggerFactory factory = new LoggerFactory();
factory.AddProvider(testLoggerProvider);
var testLogger = factory.CreateLogger <ScriptStartupTypeLocator>();
var discoverer = new ScriptStartupTypeLocator(string.Empty, testLogger, mockExtensionBundleManager.Object);
// Act
var types = await discoverer.GetExtensionsStartupTypesAsync();
var traces = testLoggerProvider.GetAllLogMessages();
// Assert
Assert.Null(types);
Assert.True(traces.Any(m => string.Equals(m.FormattedMessage, $"Unable to find or download extension bundle")));
}
}
public async Task Invoke_HandlesHttpExceptions()
{
var ex = new HttpException(StatusCodes.Status502BadGateway);
using (var server = GetTestServer(_ => throw ex))
{
var client = server.CreateClient();
HttpResponseMessage response = await client.GetAsync(string.Empty);
Assert.Equal(ex.StatusCode, (int)response.StatusCode);
var log = _loggerProvider.GetAllLogMessages().Single(p => p.Category.Contains(nameof(ExceptionMiddleware)));
Assert.Equal("An unhandled host error has occurred.", log.FormattedMessage);
Assert.Same(ex, log.Exception);
}
}
public async Task GetExtensionsStartupTypes_RejectsBundleBelowMinimumVersion()
{
using (var directory = GetTempDirectory())
{
TestMetricsLogger testMetricsLogger = new TestMetricsLogger();
TestLoggerProvider testLoggerProvider = new TestLoggerProvider();
LoggerFactory factory = new LoggerFactory();
factory.AddProvider(testLoggerProvider);
var testLogger = factory.CreateLogger <ScriptStartupTypeLocator>();
var binPath = Path.Combine(directory.Path, "bin");
var mockExtensionBundleManager = new Mock <IExtensionBundleManager>();
mockExtensionBundleManager.Setup(e => e.IsExtensionBundleConfigured()).Returns(true);
mockExtensionBundleManager.Setup(e => e.GetExtensionBundleBinPathAsync()).Returns(Task.FromResult(binPath));
mockExtensionBundleManager.Setup(e => e.IsLegacyExtensionBundle()).Returns(false);
mockExtensionBundleManager.Setup(e => e.GetExtensionBundleDetails()).Returns(Task.FromResult(GetV2BundleDetails("2.1.0")));
var mockFunctionMetadataManager = GetTestFunctionMetadataManager();
var languageWorkerOptions = new OptionsWrapper <LanguageWorkerOptions>(new LanguageWorkerOptions());
var discoverer = new ScriptStartupTypeLocator(directory.Path, testLogger, mockExtensionBundleManager.Object, mockFunctionMetadataManager, testMetricsLogger, languageWorkerOptions);
// Act
var exception = await Assert.ThrowsAsync <HostInitializationException>(async() => await discoverer.GetExtensionsStartupTypesAsync());
var traces = testLoggerProvider.GetAllLogMessages();
// Assert
Assert.True(traces.Any(m => string.Equals(m.FormattedMessage, $"Referenced bundle Microsoft.Azure.Functions.ExtensionBundle of version 2.1.0 does not meet the required minimum version of 2.6.1. Update your extension bundle reference in host.json to reference 2.6.1 or later.")));
}
}
public async Task CustomMessageProcessorTest()
{
try
{
// Pass in a separate LoggerFactory to the CusomtMessagingProvider to make validation easier.
LoggerFactory loggerFactory = new LoggerFactory();
TestLoggerProvider loggerProvider = new TestLoggerProvider();
loggerFactory.AddProvider(loggerProvider);
_serviceBusConfig = new ServiceBusConfiguration();
_serviceBusConfig.MessagingProvider = new CustomMessagingProvider(_serviceBusConfig, loggerFactory);
JobHostConfiguration config = new JobHostConfiguration()
{
NameResolver = _nameResolver,
TypeLocator = new FakeTypeLocator(typeof(ServiceBusTestJobs)),
LoggerFactory = _loggerFactory
};
config.UseServiceBus(_serviceBusConfig);
JobHost host = new JobHost(config);
await ServiceBusEndToEndInternal(typeof(ServiceBusTestJobs), host : host);
// in addition to verifying that our custom processor was called, we're also
// verifying here that extensions can log
IEnumerable <LogMessage> messages = loggerProvider.GetAllLogMessages();
Assert.Equal(4, messages.Count(p => p.FormattedMessage.Contains("Custom processor Begin called!")));
Assert.Equal(4, messages.Count(p => p.FormattedMessage.Contains("Custom processor End called!")));
}
finally
{
await Cleanup();
}
}
public async Task AsyncChainEndToEnd()
{
using (_functionCompletedEvent = new ManualResetEvent(initialState: false))
{
TestLoggerProvider loggerProvider = await AsyncChainEndToEndInternal(_hostBuilder);
string firstQueueName = _resolver.ResolveInString(Queue1Name);
string secondQueueName = _resolver.ResolveInString(Queue2Name);
string blobContainerName = _resolver.ResolveInString(ContainerName);
string[] loggerOutputLines = loggerProvider.GetAllLogMessages()
.Where(p => p.FormattedMessage != null)
.SelectMany(p => p.FormattedMessage.Split(Environment.NewLine, StringSplitOptions.RemoveEmptyEntries))
.OrderBy(p => p)
.ToArray();
string[] expectedOutputLines = new string[]
{
"Found the following functions:",
"Microsoft.Azure.WebJobs.Host.EndToEndTests.AsyncChainEndToEndTests.WriteStartDataMessageToQueue",
"Microsoft.Azure.WebJobs.Host.EndToEndTests.AsyncChainEndToEndTests.QueueToQueueAsync",
"Microsoft.Azure.WebJobs.Host.EndToEndTests.AsyncChainEndToEndTests.QueueToBlobAsync",
"Microsoft.Azure.WebJobs.Host.EndToEndTests.AsyncChainEndToEndTests.AlwaysFailJob",
"Microsoft.Azure.WebJobs.Host.EndToEndTests.AsyncChainEndToEndTests.DisabledJob",
"Microsoft.Azure.WebJobs.Host.EndToEndTests.AsyncChainEndToEndTests.TimeoutJob",
"Microsoft.Azure.WebJobs.Host.EndToEndTests.AsyncChainEndToEndTests.TimeoutJob_Throw",
"Microsoft.Azure.WebJobs.Host.EndToEndTests.AsyncChainEndToEndTests.TimeoutJob_Throw_NoToken",
"Microsoft.Azure.WebJobs.Host.EndToEndTests.AsyncChainEndToEndTests.BlobToBlobAsync",
"Microsoft.Azure.WebJobs.Host.EndToEndTests.AsyncChainEndToEndTests.ReadResultBlob",
"Microsoft.Azure.WebJobs.Host.EndToEndTests.AsyncChainEndToEndTests.SystemParameterBindingOutput",
"Function 'AsyncChainEndToEndTests.DisabledJob' is disabled",
"Job host started",
"Executing 'AsyncChainEndToEndTests.WriteStartDataMessageToQueue' (Reason='This function was programmatically called via the host APIs.', Id=",
"Executed 'AsyncChainEndToEndTests.WriteStartDataMessageToQueue' (Succeeded, Id=",
string.Format("Executing 'AsyncChainEndToEndTests.QueueToQueueAsync' (Reason='New queue message detected on '{0}'.', Id=", firstQueueName),
"Executed 'AsyncChainEndToEndTests.QueueToQueueAsync' (Succeeded, Id=",
string.Format("Executing 'AsyncChainEndToEndTests.QueueToBlobAsync' (Reason='New queue message detected on '{0}'.', Id=", secondQueueName),
"Executed 'AsyncChainEndToEndTests.QueueToBlobAsync' (Succeeded, Id=",
string.Format("Executing 'AsyncChainEndToEndTests.BlobToBlobAsync' (Reason='New blob detected: {0}/Blob1', Id=", blobContainerName),
"Executed 'AsyncChainEndToEndTests.BlobToBlobAsync' (Succeeded, Id=",
"Job host stopped",
"Executing 'AsyncChainEndToEndTests.ReadResultBlob' (Reason='This function was programmatically called via the host APIs.', Id=",
"Executed 'AsyncChainEndToEndTests.ReadResultBlob' (Succeeded, Id=",
"User ILogger log",
"User TraceWriter log 1",
"User TraceWriter log 2",
"Starting JobHost",
"Stopping JobHost"
}.OrderBy(p => p).ToArray();
bool hasError = loggerOutputLines.Any(p => p.Contains("Function had errors"));
Assert.False(hasError);
// Validate logger output
for (int i = 0; i < expectedOutputLines.Length; i++)
{
Assert.StartsWith(expectedOutputLines[i], loggerOutputLines[i]);
}
}
}
public async Task Initialize_PerformsExpectedRegistrations()
{
JobHostConfiguration config = new JobHostConfiguration();
config.AddService <INameResolver>(new RandomNameResolver());
TestLoggerProvider loggerProvider = new TestLoggerProvider();
ILoggerFactory loggerFactory = new LoggerFactory();
loggerFactory.AddProvider(loggerProvider);
config.LoggerFactory = loggerFactory;
ServiceBusConfiguration serviceBusConfig = new ServiceBusConfiguration();
ServiceBusExtensionConfig serviceBusExtensionConfig = new ServiceBusExtensionConfig(serviceBusConfig);
IExtensionRegistry extensions = config.GetService <IExtensionRegistry>();
ITriggerBindingProvider[] triggerBindingProviders = extensions.GetExtensions <ITriggerBindingProvider>().ToArray();
Assert.Empty(triggerBindingProviders);
IBindingProvider[] bindingProviders = extensions.GetExtensions <IBindingProvider>().ToArray();
Assert.Empty(bindingProviders);
ExtensionConfigContext context = new ExtensionConfigContext
{
Config = config,
};
serviceBusExtensionConfig.Initialize(context);
// ensure the ServiceBusTriggerAttributeBindingProvider was registered
triggerBindingProviders = extensions.GetExtensions <ITriggerBindingProvider>().ToArray();
Assert.Single(triggerBindingProviders);
ServiceBusTriggerAttributeBindingProvider triggerBindingProvider = (ServiceBusTriggerAttributeBindingProvider)triggerBindingProviders[0];
Assert.NotNull(triggerBindingProvider);
// ensure the ServiceBusAttributeBindingProvider was registered
bindingProviders = extensions.GetExtensions <IBindingProvider>().ToArray();
Assert.Single(bindingProviders);
ServiceBusAttributeBindingProvider bindingProvider = (ServiceBusAttributeBindingProvider)bindingProviders[0];
Assert.NotNull(bindingProvider);
// ensure the default MessageOptions exception handler is wired up
var messageOptions = serviceBusConfig.MessageOptions;
var ex = new ServiceBusException(false);
var args = new ExceptionReceivedEventArgs(ex, "TestAction", "TestEndpoint", "TestEntityPath", "TestClientId");
Assert.NotNull(serviceBusConfig.ExceptionHandler);
// invoke the handler and make sure it logs
await serviceBusConfig.MessageOptions.ExceptionReceivedHandler(args);
string expectedMessage = "MessageReceiver error (Action=TestAction, ClientId=TestClientId, EntityPath=TestEntityPath, Endpoint=TestEndpoint)";
var logMessage = loggerProvider.GetAllLogMessages().Single();
Assert.Equal(LogLevel.Error, logMessage.Level);
Assert.Equal(expectedMessage, logMessage.FormattedMessage);
Assert.Same(ex, logMessage.Exception);
}
public void LogExceptionReceivedEvent_NonTransientEvent_LoggedAsError()
{
var ex = new ServiceBusException(isTransient: false, message: "message");
Assert.False(ex.IsTransient);
ProcessErrorEventArgs e = new ProcessErrorEventArgs(ex, ServiceBusErrorSource.Abandon, "TestEndpoint", "TestEntity", CancellationToken.None);
ServiceBusExtensionConfigProvider.LogExceptionReceivedEvent(e, _loggerFactory);
var expectedMessage = $"Message processing error (Action=Abandon, EntityPath=TestEntity, Endpoint=TestEndpoint)";
var logMessage = _loggerProvider.GetAllLogMessages().Single();
Assert.AreEqual(LogLevel.Error, logMessage.Level);
Assert.AreSame(ex, logMessage.Exception);
Assert.AreEqual(expectedMessage, logMessage.FormattedMessage);
}
private async Task <LogMessage> RunTest(Action <IServiceCollection> configure = null)
{
LogMessage invalidServicesMessage = null;
TestLoggerProvider loggerProvider = new TestLoggerProvider();
var builder = Program.CreateWebHostBuilder(null)
.ConfigureLogging(b =>
{
b.AddProvider(loggerProvider);
})
.ConfigureServices(s =>
{
s.AddSingleton <IConfigureBuilder <ILoggingBuilder> >(new DelegatedConfigureBuilder <ILoggingBuilder>(b =>
{
b.AddProvider(loggerProvider);
configure?.Invoke(b.Services);
}));
string uniqueTestRootPath = Path.Combine(Path.GetTempPath(), "FunctionsTest", "DependencyValidatorTests");
s.PostConfigureAll <ScriptApplicationHostOptions>(o =>
{
o.IsSelfHost = true;
o.LogPath = Path.Combine(uniqueTestRootPath, "logs");
o.SecretsPath = Path.Combine(uniqueTestRootPath, "secrets");
o.ScriptPath = uniqueTestRootPath;
});
});
using (var host = builder.Build())
{
await host.StartAsync();
await TestHelpers.Await(() =>
{
return(loggerProvider.GetAllLogMessages()
.FirstOrDefault(p => p.FormattedMessage.StartsWith("Host initialization")) != null);
}, userMessageCallback : () => loggerProvider.GetLog());
invalidServicesMessage = loggerProvider.GetAllLogMessages()
.FirstOrDefault(m => m.Category.EndsWith(nameof(DependencyValidator)));
await host.StopAsync();
}
return(invalidServicesMessage);
}
public async Task FunctionListener_RetriesOnListenerFailure_WhenPartialHostStartupEnabled()
{
Mock <IListener> badListener = new Mock <IListener>(MockBehavior.Strict);
int failureCount = 0;
badListener.Setup(bl => bl.StartAsync(It.IsAny <CancellationToken>()))
.Callback <CancellationToken>((ct) =>
{
if (failureCount++ < 3)
{
throw new Exception("Listener Exploded!");
}
})
.Returns(Task.CompletedTask);
badListener.Setup(bl => bl.StopAsync(It.IsAny <CancellationToken>())).Returns(Task.CompletedTask);
var listener = new FunctionListener(badListener.Object, fd, _loggerFactory, allowPartialHostStartup: true, minRetryInterval: TimeSpan.FromMilliseconds(10), maxRetryInterval: TimeSpan.FromMilliseconds(100));
// we should return right away with the listener
// attempting to restart in the background
await listener.StartAsync(ct);
string[] logs = null;
await TestHelpers.Await(() =>
{
logs = _loggerProvider.GetAllLogMessages().Select(p => p.FormattedMessage).ToArray();
return(logs.Last() == "Listener successfully started for function 'testfunc' after 3 retries.");
});
badListener.Verify(p => p.StartAsync(It.IsAny <CancellationToken>()), Times.Exactly(4));
var validators = new Action <string>[]
{
p => Assert.Equal("The listener for function 'testfunc' was unable to start.", p),
p => Assert.Equal("Retrying to start listener for function 'testfunc' (Attempt 1)", p),
p => Assert.Equal("The listener for function 'testfunc' was unable to start.", p),
p => Assert.Equal("Retrying to start listener for function 'testfunc' (Attempt 2)", p),
p => Assert.Equal("The listener for function 'testfunc' was unable to start.", p),
p => Assert.Equal("Retrying to start listener for function 'testfunc' (Attempt 3)", p),
p => Assert.Equal("Listener successfully started for function 'testfunc' after 3 retries.", p)
};
Assert.Collection(logs, validators);
await listener.StopAsync(ct);
badListener.Verify(p => p.StopAsync(It.IsAny <CancellationToken>()), Times.Once());
}
public async Task StartAssignment_AppliesAssignmentContext()
{
var envValue = new
{
Name = Path.GetTempFileName().Replace(".", string.Empty),
Value = Guid.NewGuid().ToString()
};
_settingsManager.SetSetting(EnvironmentSettingNames.AzureWebsitePlaceholderMode, "1");
WebScriptHostManager.ResetStandbyMode();
var context = new HostAssignmentContext
{
Environment = new Dictionary <string, string>
{
{ envValue.Name, envValue.Value }
}
};
bool result = _instanceManager.StartAssignment(context);
Assert.True(result);
Assert.True(WebScriptHostManager.InStandbyMode);
// specialization is done in the background
await Task.Delay(500);
var value = Environment.GetEnvironmentVariable(envValue.Name);
Assert.Equal(value, envValue.Value);
// verify logs
var logs = _loggerProvider.GetAllLogMessages().Select(p => p.FormattedMessage).ToArray();
Assert.Collection(logs,
p => Assert.StartsWith("Starting Assignment", p),
p => Assert.StartsWith("Applying 1 app setting(s)", p),
p => Assert.StartsWith("Triggering specialization", p));
// calling again should return false, since we're no longer
// in placeholder mode
_loggerProvider.ClearAllLogMessages();
result = _instanceManager.StartAssignment(context);
Assert.False(result);
logs = _loggerProvider.GetAllLogMessages().Select(p => p.FormattedMessage).ToArray();
Assert.Collection(logs,
p => Assert.StartsWith("Assign called while host is not in placeholder mode", p));
}
public void Synchronize_UpdatesValue()
{
_mockEnvironment.Setup(p => p.GetEnvironmentVariable(EnvironmentSettingNames.AzureWebsiteHostName)).Returns((string)null);
_mockEnvironment.Setup(p => p.GetEnvironmentVariable(EnvironmentSettingNames.AzureWebsiteName)).Returns((string)null);
Assert.Equal(null, _hostNameProvider.Value);
// no header present
HttpRequest request = new DefaultHttpContext().Request;
_hostNameProvider.Synchronize(request, _logger);
Assert.Equal(null, _hostNameProvider.Value);
// empty header value
request = new DefaultHttpContext().Request;
request.Headers.Add(ScriptConstants.AntaresDefaultHostNameHeader, string.Empty);
_hostNameProvider.Synchronize(request, _logger);
Assert.Equal(null, _hostNameProvider.Value);
// host provided via header - expect update
request = new DefaultHttpContext().Request;
request.Headers.Add(ScriptConstants.AntaresDefaultHostNameHeader, "test.azurewebsites.net");
_hostNameProvider.Synchronize(request, _logger);
Assert.Equal("test.azurewebsites.net", _hostNameProvider.Value);
var logs = _loggerProvider.GetAllLogMessages();
Assert.Equal(1, logs.Count);
Assert.Equal("HostName updated from '(null)' to 'test.azurewebsites.net'", logs[0].FormattedMessage);
// no change in header value - no update expected
_loggerProvider.ClearAllLogMessages();
_hostNameProvider.Synchronize(request, _logger);
Assert.Equal("test.azurewebsites.net", _hostNameProvider.Value);
Assert.Equal("test.azurewebsites.net", _hostNameProvider.Value);
logs = _loggerProvider.GetAllLogMessages();
Assert.Equal(0, logs.Count);
// another change - expect update
request = new DefaultHttpContext().Request;
request.Headers.Add(ScriptConstants.AntaresDefaultHostNameHeader, "test2.azurewebsites.net");
_hostNameProvider.Synchronize(request, _logger);
Assert.Equal("test2.azurewebsites.net", _hostNameProvider.Value);
logs = _loggerProvider.GetAllLogMessages();
Assert.Equal(1, logs.Count);
Assert.Equal("HostName updated from 'test.azurewebsites.net' to 'test2.azurewebsites.net'", logs[0].FormattedMessage);
}
public void LogExceptionReceivedEvent_NonTransientEvent_LoggedAsError()
{
var ex = new EventHubsException(false);
Assert.False(ex.IsTransient);
var ctor = typeof(ExceptionReceivedEventArgs).GetConstructors(BindingFlags.NonPublic | BindingFlags.Instance).Single();
var e = (ExceptionReceivedEventArgs)ctor.Invoke(new object[] { "TestHostName", "TestPartitionId", ex, "TestAction" });
EventHubExtensionConfigProvider.LogExceptionReceivedEvent(e, _loggerFactory);
string expectedMessage = "EventProcessorHost error (Action=TestAction, HostName=TestHostName, PartitionId=TestPartitionId)";
var logMessage = _loggerProvider.GetAllLogMessages().Single();
Assert.Equal(LogLevel.Error, logMessage.Level);
Assert.Same(ex, logMessage.Exception);
Assert.Equal(expectedMessage, logMessage.FormattedMessage);
}
public void LogExceptionReceivedEvent_NonTransientEvent_LoggedAsError()
{
var ex = new ServiceBusException(false);
Assert.False(ex.IsTransient);
ExceptionReceivedEventArgs e = new ExceptionReceivedEventArgs(ex, "TestAction", "TestEndpoint", "TestEntity", "TestClient");
ServiceBusTriggerAttributeBindingProvider.LogExceptionReceivedEvent(e, "TestFunction", _loggerFactory);
var expectedMessage = $"Message processing error (Action=TestAction, ClientId=TestClient, EntityPath=TestEntity, Endpoint=TestEndpoint)";
var logMessage = _loggerProvider.GetAllLogMessages().Single();
Assert.Equal(LogLevel.Error, logMessage.Level);
Assert.Same(ex, logMessage.Exception);
Assert.Equal(expectedMessage, logMessage.FormattedMessage);
Assert.True(logMessage.Category.Contains("TestFunction"));
}
public async Task SecretMigrate_Successful()
{
using (var directory = new TempDirectory())
{
try
{
await _fixture.TestInitialize(SecretsRepositoryType.FileSystem, directory.Path);
var loggerProvider = new TestLoggerProvider();
var fileRepo = _fixture.GetFileSystemSecretsRepository();
string hostContent = Guid.NewGuid().ToString();
string functionContent = Guid.NewGuid().ToString();
await fileRepo.WriteAsync(ScriptSecretsType.Host, "host", hostContent);
await fileRepo.WriteAsync(ScriptSecretsType.Function, "test1", functionContent);
_settingsManager.SetSetting(EnvironmentSettingNames.AzureWebsiteSlotName, "Production");
_settingsManager.SetSetting(EnvironmentSettingNames.AzureWebsiteName, "test-app");
var blobRepoMigration = _fixture.GetBlobStorageSecretsMigrationRepository(loggerProvider.CreateLogger(ScriptConstants.LogCategoryMigration));
await blobRepoMigration.ReadAsync(ScriptSecretsType.Host, "host");
var logs = loggerProvider.GetAllLogMessages().ToArray();
Assert.Contains(logs[logs.Length - 1].FormattedMessage, "Finished successfully.");
string hostContentFromBlob = await blobRepoMigration.ReadAsync(ScriptSecretsType.Host, "");
Assert.Equal(hostContent, hostContentFromBlob);
string hostContentFromFunction = await blobRepoMigration.ReadAsync(ScriptSecretsType.Function, "test1");
Assert.Equal(functionContent, hostContentFromFunction);
var blobRepoMigration2 = _fixture.GetBlobStorageSecretsMigrationRepository(loggerProvider.CreateLogger(""));
await blobRepoMigration2.ReadAsync(ScriptSecretsType.Host, "host");
logs = loggerProvider.GetAllLogMessages().ToArray();
Assert.Contains(logs[logs.Length - 1].FormattedMessage, "Sentinel file is detected.");
}
finally
{
_settingsManager.SetSetting(EnvironmentSettingNames.AzureWebsiteSlotName, null);
_settingsManager.SetSetting(EnvironmentSettingNames.AzureWebsiteName, null);
}
}
}
private async Task InitializeTestHostAsync(string testDirName, IEnvironment environment)
{
var httpConfig = new HttpConfiguration();
var uniqueTestRootPath = Path.Combine(_testRootPath, testDirName, Guid.NewGuid().ToString());
_loggerProvider = new TestLoggerProvider();
if (environment.IsAppServiceEnvironment())
{
// if the test is mocking App Service environment, we need
// to also set the HOME and WEBSITE_SITE_NAME variables
environment.SetEnvironmentVariable(EnvironmentSettingNames.AzureWebsiteHomePath, uniqueTestRootPath);
environment.SetEnvironmentVariable(EnvironmentSettingNames.AzureWebsiteName, "test-host-name");
}
var webHostBuilder = Program.CreateWebHostBuilder()
.ConfigureAppConfiguration(c =>
{
// This source reads from AzureWebJobsScriptRoot, which does not work
// with the custom paths that these tests are using.
var source = c.Sources.OfType <WebScriptHostConfigurationSource>().SingleOrDefault();
if (source != null)
{
c.Sources.Remove(source);
}
})
.ConfigureLogging(c =>
{
c.AddProvider(_loggerProvider);
})
.ConfigureServices(c =>
{
c.ConfigureAll <ScriptApplicationHostOptions>(o =>
{
o.IsSelfHost = true;
o.LogPath = Path.Combine(uniqueTestRootPath, "logs");
o.SecretsPath = Path.Combine(uniqueTestRootPath, "secrets");
o.ScriptPath = _expectedScriptPath = Path.Combine(uniqueTestRootPath, "wwwroot");
});
c.AddSingleton <IEnvironment>(_ => environment);
c.AddSingleton <IConfigureBuilder <ILoggingBuilder> >(new DelegatedConfigureBuilder <ILoggingBuilder>(b => b.AddProvider(_loggerProvider)));
});
_httpServer = new TestServer(webHostBuilder);
_httpClient = _httpServer.CreateClient();
_httpClient.BaseAddress = new Uri("https://localhost/");
TestHelpers.WaitForWebHost(_httpClient);
var traces = _loggerProvider.GetAllLogMessages().ToArray();
Assert.NotNull(traces.Single(p => p.FormattedMessage.StartsWith("Host is in standby mode")));
_expectedHostId = await _httpServer.Host.Services.GetService <IHostIdProvider>().GetHostIdAsync(CancellationToken.None);
}
public async Task DisposesScriptHost()
{
var metricsLogger = new TestMetricsLogger();
var services = new ServiceCollection()
.AddLogging(l =>
{
l.Services.AddSingleton <ILoggerProvider, TestLoggerProvider>();
l.AddFilter(_ => true);
})
.BuildServiceProvider();
var host = new Mock <IHost>();
host.Setup(h => h.Services)
.Returns(services);
host.Setup(h => h.Dispose())
.Callback(() =>
{
services.Dispose();
});
var hostBuilder = new Mock <IScriptHostBuilder>();
hostBuilder.Setup(b => b.BuildHost(It.IsAny <bool>(), It.IsAny <bool>()))
.Returns(host.Object);
_webHostLoggerProvider = new TestLoggerProvider();
_loggerFactory = new LoggerFactory();
_loggerFactory.AddProvider(_webHostLoggerProvider);
_hostService = new WebJobsScriptHostService(
_monitor, hostBuilder.Object, _loggerFactory,
_mockScriptWebHostEnvironment.Object, _mockEnvironment.Object,
_hostPerformanceManager, _healthMonitorOptions,
metricsLogger, new Mock <IApplicationLifetime>().Object,
_mockConfig, new TestScriptEventManager());
var hostLogger = host.Object.GetTestLoggerProvider();
await _hostService.StartAsync(CancellationToken.None);
await _hostService.RestartHostAsync(CancellationToken.None);
Assert.True(AreRequiredMetricsGenerated(metricsLogger));
host.Verify(m => m.StopAsync(It.IsAny <CancellationToken>()), Times.Exactly(1));
host.Verify(m => m.Dispose(), Times.Exactly(1));
var allLogMessages = _webHostLoggerProvider.GetAllLogMessages();
Assert.Contains(allLogMessages,
m => m.FormattedMessage != null &&
m.FormattedMessage.Contains("ScriptHost disposed"));
}
public async Task ValidateContext_InvalidZipUrl_WebsiteUseZip_ReturnsError()
{
var environmentSettings = new Dictionary <string, string>()
{
{ EnvironmentSettingNames.AzureWebsiteZipDeployment, "http://invalid.com/invalid/dne" }
};
var environment = new TestEnvironment();
foreach (var(key, value) in environmentSettings)
{
environment.SetEnvironmentVariable(key, value);
}
var scriptWebEnvironment = new ScriptWebHostEnvironment(environment);
var loggerFactory = new LoggerFactory();
var loggerProvider = new TestLoggerProvider();
loggerFactory.AddProvider(loggerProvider);
var handlerMock = new Mock <HttpMessageHandler>(MockBehavior.Strict);
handlerMock.Protected().Setup <Task <HttpResponseMessage> >("SendAsync",
ItExpr.IsAny <HttpRequestMessage>(),
ItExpr.IsAny <CancellationToken>()).ReturnsAsync(new HttpResponseMessage
{
StatusCode = HttpStatusCode.NotFound
});
var instanceManager = new InstanceManager(_optionsFactory, new HttpClient(handlerMock.Object),
scriptWebEnvironment, environment, loggerFactory.CreateLogger <InstanceManager>(),
new TestMetricsLogger(), null);
var assignmentContext = new HostAssignmentContext
{
SiteId = 1234,
SiteName = "TestSite",
Environment = environmentSettings,
IsWarmupRequest = false
};
string error = await instanceManager.ValidateContext(assignmentContext);
Assert.Equal("Invalid zip url specified (StatusCode: NotFound)", error);
var logs = loggerProvider.GetAllLogMessages().Select(p => p.FormattedMessage).ToArray();
Assert.Collection(logs,
p => Assert.StartsWith("Validating host assignment context (SiteId: 1234, SiteName: 'TestSite'. IsWarmup: 'False')", p),
p => Assert.StartsWith($"Will be using {EnvironmentSettingNames.AzureWebsiteZipDeployment} app setting as zip url. IsWarmup: 'False'", p),
p => Assert.StartsWith("linux.container.specialization.zip.head failed", p),
p => Assert.StartsWith("linux.container.specialization.zip.head failed", p),
p => Assert.StartsWith("linux.container.specialization.zip.head failed", p),
p => Assert.StartsWith("ValidateContext failed", p));
}
public async Task Invoke_HandlesHttpExceptions()
{
var ex = new HttpException(StatusCodes.Status502BadGateway);
RequestDelegate next = (ctxt) =>
{
throw ex;
};
var middleware = new ExceptionMiddleware(next, _logger);
var context = new DefaultHttpContext();
await middleware.Invoke(context);
Assert.Equal(ex.StatusCode, context.Response.StatusCode);
var log = _loggerProvider.GetAllLogMessages().Single();
Assert.Equal("An unhandled host error has occurred.", log.FormattedMessage);
Assert.Same(ex, log.Exception);
}
public async Task LoggerLogging()
{
using (_functionCompletedEvent = new ManualResetEvent(initialState: false))
{
TestLoggerProvider loggerProvider = await AsyncChainEndToEndInternal(_hostBuilder);
// Validate Logger
bool hasError = loggerProvider.GetAllLogMessages().Where(p => p.FormattedMessage != null && p.FormattedMessage.Contains("Error")).Any();
Assert.False(hasError);
IEnumerable <string> userLogMessages = loggerProvider.GetAllLogMessages()
.Where(p => p.Category.StartsWith("Function.") && p.Category.EndsWith(".User"))
.Select(p => p.FormattedMessage);
Assert.Equal(3, userLogMessages.Count());
Assert.NotNull(userLogMessages.SingleOrDefault(p => p == "User TraceWriter log 1"));
Assert.NotNull(userLogMessages.SingleOrDefault(p => p == "User TraceWriter log 2"));
Assert.NotNull(userLogMessages.SingleOrDefault(p => p == "User ILogger log"));
}
}
