public async Task Pass_thru_when_context_not_in_services()
{
using (var database = SqlServerTestStore.CreateScratch())
{
var logProvider = new TestLoggerProvider();
var builder = new WebHostBuilder()
.Configure(app =>
{
app.UseDatabaseErrorPage();
app.UseMiddleware <ContextNotRegisteredInServicesMiddleware>();
app.ApplicationServices.GetService <ILoggerFactory>().AddProvider(logProvider);
})
.ConfigureServices(
services =>
{
services.AddEntityFramework().AddEntityFrameworkSqlServer();
var optionsBuilder = new DbContextOptionsBuilder();
if (!PlatformHelper.IsMono)
{
optionsBuilder.UseSqlServer(database.ConnectionString);
}
else
{
optionsBuilder.UseInMemoryDatabase();
}
services.AddSingleton <DbContextOptions>(optionsBuilder.Options);
});
var server = new TestServer(builder);
var ex = await Assert.ThrowsAsync <SqlException>(async() =>
await server.CreateClient().GetAsync("http://localhost/"));
Assert.True(logProvider.Logger.Messages.Any(m =>
m.StartsWith(StringsHelpers.GetResourceString("FormatDatabaseErrorPageMiddleware_ContextNotRegistered", typeof(BloggingContext)))));
}
}
public async Task InitializeAsync()
{
InitializeFiles();
LoggerProvider = new TestLoggerProvider();
var optionsFactory = new TestOptionsFactory <ScriptApplicationHostOptions>(ApplicationOptions);
var optionsMonitor = new OptionsMonitor <ScriptApplicationHostOptions>(optionsFactory, Array.Empty <IOptionsChangeTokenSource <ScriptApplicationHostOptions> >(), optionsFactory);
TestServer = new TestServer(AspNetCore.WebHost.CreateDefaultBuilder()
.ConfigureLogging(b =>
{
b.AddProvider(LoggerProvider);
})
.UseStartup <Startup>()
.ConfigureServices(services =>
{
services.Replace(new ServiceDescriptor(typeof(IOptions <ScriptApplicationHostOptions>), new OptionsWrapper <ScriptApplicationHostOptions>(ApplicationOptions)));
services.Replace(new ServiceDescriptor(typeof(ISecretManager), new TestSecretManager()));
services.Replace(new ServiceDescriptor(typeof(IOptionsMonitor <ScriptApplicationHostOptions>), optionsMonitor));
services.AddSingleton <IConfigureBuilder <ILoggingBuilder> >(new DelegatedConfigureBuilder <ILoggingBuilder>(b => b.AddProvider(LoggerProvider)));
services.AddSingleton <IConfigureBuilder <IWebJobsBuilder> >(new DelegatedConfigureBuilder <IWebJobsBuilder>(b =>
{
b.AddAzureStorage();
b.Services.Configure <ScriptJobHostOptions>(o => o.Functions = new[] { "TimerTrigger", "Invalid" });
}));
}));
var scriptConfig = TestServer.Host.Services.GetService <IOptions <ScriptJobHostOptions> >().Value;
HttpClient = TestServer.CreateClient();
HttpClient.BaseAddress = new Uri("https://localhost/");
Host = TestServer.Host;
await ScriptHostManager.DelayUntilHostReady();
}
public async Task ShouldSetTheSameIdWithLogEntity()
{
//Arrange
var logger = new TestLogger();
var loggerProvider = new TestLoggerProvider(logger);
var client = _factory.WithWebHostBuilder(b =>
{
b.ConfigureServices(services =>
{
services.AddMvc(o => o.AddExceptionProcessing());
services.AddLogging(c => c.AddProvider(loggerProvider));
});
}).CreateClient();
//Act
var response = await client.GetAsync("api/exception-hiding");
var content = await response.Content.ReadAsStringAsync();
InterlevelErrorDto dto;
try
{
dto = JsonConvert.DeserializeObject <InterlevelErrorDto>(content);
}
catch (Exception)
{
_output.WriteLine("Content: " + content);
throw;
}
//Assert
Assert.NotNull(logger.LastLog);
Assert.Equal(dto.Id, logger.LastLog.Facts[HttpTraceIdFact.Key]);
}
public async Task Pass_thru_when_context_not_in_services()
{
var logProvider = new TestLoggerProvider();
using var host = new HostBuilder()
.ConfigureWebHost(webHostBuilder =>
{
webHostBuilder
.UseTestServer()
.Configure(app =>
{
app.UseDatabaseErrorPage();
app.UseMiddleware <ContextNotRegisteredInServicesMiddleware>();
#pragma warning disable CS0618 // Type or member is obsolete
app.ApplicationServices.GetService <ILoggerFactory>().AddProvider(logProvider);
#pragma warning restore CS0618 // Type or member is obsolete
});
}).Build();
await host.StartAsync();
var server = host.GetTestServer();
try
{
await server.CreateClient().GetAsync("http://localhost/");
}
catch (Exception exception)
{
Assert.True(
exception.GetType().Name == "SqliteException" ||
exception.InnerException?.GetType().Name == "SqliteException");
}
Assert.Contains(logProvider.Logger.Messages.ToList(), m =>
m.StartsWith(StringsHelpers.GetResourceString("FormatDatabaseErrorPageMiddleware_ContextNotRegistered", typeof(BloggingContext))));
}
public async Task HostRestart_Specialization_Succeeds()
{
var metricsLogger = new TestMetricsLogger();
_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,
_mockScriptWebHostEnvironment.Object, _mockEnvironment.Object, _hostPerformanceManager, _healthMonitorOptions, metricsLogger, new Mock <IApplicationLifetime>().Object);
await _hostService.StartAsync(CancellationToken.None);
Assert.True(AreRequiredMetricsGenerated(metricsLogger));
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 ServiceBusListenerTests()
{
_mockExecutor = new Mock <ITriggeredFunctionExecutor>(MockBehavior.Strict);
var client = new ServiceBusClient(_testConnection);
ServiceBusProcessor processor = client.CreateProcessor(_entityPath);
ServiceBusReceiver receiver = client.CreateReceiver(_entityPath);
ServiceBusOptions config = new ServiceBusOptions
{
ExceptionHandler = ExceptionReceivedHandler
};
_mockMessageProcessor = new Mock <MessageProcessor>(MockBehavior.Strict, processor);
_mockMessagingProvider = new Mock <MessagingProvider>(MockBehavior.Strict, new OptionsWrapper <ServiceBusOptions>(config));
_mockMessagingProvider
.Setup(p => p.CreateMessageProcessor(_entityPath, _testConnection))
.Returns(_mockMessageProcessor.Object);
_mockMessagingProvider
.Setup(p => p.CreateBatchMessageReceiver(_entityPath, _testConnection))
.Returns(receiver);
Mock <ServiceBusAccount> mockServiceBusAccount = new Mock <ServiceBusAccount>(MockBehavior.Strict);
mockServiceBusAccount.Setup(a => a.ConnectionString).Returns(_testConnection);
_loggerFactory = new LoggerFactory();
_loggerProvider = new TestLoggerProvider();
_loggerFactory.AddProvider(_loggerProvider);
_listener = new ServiceBusListener(_functionId, EntityType.Queue, _entityPath, false, _mockExecutor.Object, config, mockServiceBusAccount.Object,
_mockMessagingProvider.Object, _loggerFactory, false);
}
private void FilterTest(Func <string, bool> filter, params string[] expected)
{
var loggerFactory = new LoggerFactory();
var loggerProvider = new TestLoggerProvider(filter);
loggerFactory.AddProvider(loggerProvider);
var dbLogger = new DiagnosticsLogger <DbLoggerCategory.Database>(loggerFactory, new LoggingOptions(), new DiagnosticListener("Fake"));
var sqlLogger = new DiagnosticsLogger <DbLoggerCategory.Database.Command>(loggerFactory, new LoggingOptions(), new DiagnosticListener("Fake"));
var queryLogger = new DiagnosticsLogger <DbLoggerCategory.Query>(loggerFactory, new LoggingOptions(), new DiagnosticListener("Fake"));
var randomLogger = loggerFactory.CreateLogger("Random");
dbLogger.Logger.LogInformation(1, "DB1");
sqlLogger.Logger.LogInformation(2, "SQL1");
queryLogger.Logger.LogInformation(3, "Query1");
randomLogger.LogInformation(4, "Random1");
dbLogger.Logger.LogInformation(1, "DB2");
sqlLogger.Logger.LogInformation(2, "SQL2");
queryLogger.Logger.LogInformation(3, "Query2");
randomLogger.LogInformation(4, "Random2");
Assert.Equal(loggerProvider.Messages, expected);
}
public async Task CreateClient_NoServerCallContextOnHttpContextIgnoreError_Success()
{
// Arrange
var testSink = new TestSink();
var testProvider = new TestLoggerProvider(testSink);
var baseAddress = new Uri("http://localhost");
var services = new ServiceCollection();
services.AddLogging(o => o.AddProvider(testProvider).SetMinimumLevel(LogLevel.Debug));
services.AddOptions();
services.AddSingleton(CreateHttpContextAccessor(new DefaultHttpContext()));
services
.AddGrpcClient <Greeter.GreeterClient>(o =>
{
o.Address = baseAddress;
})
.EnableCallContextPropagation(o => o.SuppressContextNotFoundErrors = true)
.AddHttpMessageHandler(() => ClientTestHelpers.CreateTestMessageHandler(new HelloReply()));
var serviceProvider = services.BuildServiceProvider(validateScopes: true);
var clientFactory = new DefaultGrpcClientFactory(
serviceProvider,
serviceProvider.GetRequiredService <IHttpClientFactory>());
var client = clientFactory.CreateClient <Greeter.GreeterClient>(nameof(Greeter.GreeterClient));
// Act
await client.SayHelloAsync(new HelloRequest(), new CallOptions()).ResponseAsync.DefaultTimeout();
// Assert
var log = testSink.Writes.Single(w => w.EventId.Name == "PropagateServerCallContextFailure");
Assert.AreEqual("Unable to propagate server context values to the call. Can't find the gRPC ServerCallContext on the current HttpContext.", log.Message);
}
private void FilterTest(Func <string, bool> filter, params string[] expected)
{
var loggerFactory = new LoggerFactory();
var loggerProvider = new TestLoggerProvider(filter);
loggerFactory.AddProvider(loggerProvider);
var dbLogger = new InterceptingLogger <LoggerCategory.Database>(loggerFactory, new LoggingOptions());
var sqlLogger = new InterceptingLogger <LoggerCategory.Database.Sql>(loggerFactory, new LoggingOptions());
var queryLogger = new InterceptingLogger <LoggerCategory.Query>(loggerFactory, new LoggingOptions());
var randomLogger = loggerFactory.CreateLogger("Random");
dbLogger.LogInformation("DB1");
sqlLogger.LogInformation("SQL1");
queryLogger.LogInformation("Query1");
randomLogger.LogInformation("Random1");
dbLogger.LogInformation("DB2");
sqlLogger.LogInformation("SQL2");
queryLogger.LogInformation("Query2");
randomLogger.LogInformation("Random2");
Assert.Equal(loggerProvider.Messages, expected);
}
public async Task Pass_thru_when_exception_in_logic()
{
using (var database = SqlTestStore.CreateScratch())
{
var logProvider = new TestLoggerProvider();
using var host = await SetupServer <BloggingContextWithSnapshotThatThrows, ExceptionInLogicMiddleware>(database, logProvider);
try
{
using var server = host.GetTestServer();
await server.CreateClient().GetAsync("http://localhost/");
}
catch (Exception exception)
{
Assert.True(
exception.GetType().Name == "SqliteException" ||
exception.InnerException?.GetType().Name == "SqliteException");
}
Assert.Contains(logProvider.Logger.Messages.ToList(), m =>
m.StartsWith(StringsHelpers.GetResourceString("DatabaseErrorPageMiddleware_Exception"), StringComparison.Ordinal));
}
}
private JobHost CreateTestJobHost()
{
ExplicitTypeLocator locator = new ExplicitTypeLocator(typeof(FilesTestJobs));
var resolver = new TestNameResolver();
resolver.Values.Add("test", "TestValue");
ILoggerFactory loggerFactory = new LoggerFactory();
TestLoggerProvider provider = new TestLoggerProvider();
loggerFactory.AddProvider(provider);
IHost host = new HostBuilder()
.ConfigureWebJobs(builder =>
{
builder.AddAzureStorageCoreServices()
.AddFiles(o =>
{
o.RootPath = this.rootPath;
});
})
.ConfigureServices(services =>
{
services.AddSingleton <IWebJobsExceptionHandler>(new TestExceptionHandler());
services.AddSingleton <INameResolver>(resolver);
services.AddSingleton <ITypeLocator>(locator);
})
.ConfigureLogging(logging =>
{
logging.ClearProviders();
logging.AddProvider(provider);
})
.Build();
return(host.GetJobHost());
}
public void SplunkLoggerOptions_WhenUseAuthTokenAsQueryStringIsTrue_SetsTokenInQueryParameterInMiddle()
{
// arrange
var mockedHttpHandler = new MockHttpMessageHandler();
var httpClientFactory = Mock.Of <IHttpClientProvider>();
Mock.Get(httpClientFactory).Setup(s => s.CreateClient())
.Returns(new HttpClient(mockedHttpHandler));
var optionsMonitor = Mock.Of <IOptionsMonitor <SplunkLoggerOptions> >();
Mock.Get(optionsMonitor).Setup(s => s.OnChange(It.IsAny <Action <SplunkLoggerOptions, string> >()))
.Returns(Mock.Of <IDisposable>());
var splunkLoggerProcessor = Mock.Of <ISplunkLoggerProcessor>();
Mock.Get(optionsMonitor).SetupGet(s => s.CurrentValue)
.Returns(
new SplunkLoggerOptions
{
SplunkCollectorUrl = "https://server/collector/events",
AuthenticationToken = "AuthToken",
UseAuthTokenAsQueryString = true
});
var rawPayloadTransformer = Mock.Of <ISplunkRawPayloadTransformer>();
Mock.Get(rawPayloadTransformer).Setup(s => s.Transform(It.IsAny <LogData>())).Returns("Message");
var externalScopeProvider = Mock.Of <IExternalScopeProvider>();
Mock.Get(externalScopeProvider).Setup(s => s.Push("state1")).Verifiable();
using (var actor = new TestLoggerProvider(httpClientFactory, optionsMonitor, splunkLoggerProcessor, "test"))
{
// act
// assert
Assert.Contains("?token=AuthToken", actor.GetHttpClientForTestInspection().BaseAddress.ToString());
}
}
public static void AssertLogMessageSequence(
ITestOutputHelper testOutput,
TestLoggerProvider loggerProvider,
string testName,
string instanceId,
bool filterOutReplayLogs,
string[] orchestratorFunctionNames,
string activityFunctionName = null)
{
List <string> messageIds;
string timeStamp;
var logMessages = GetLogMessages(loggerProvider, testName, instanceId, out messageIds, out timeStamp);
var expectedLogMessages = GetExpectedLogMessages(
testName,
messageIds,
orchestratorFunctionNames,
filterOutReplayLogs,
activityFunctionName,
timeStamp);
var actualLogMessages = logMessages.Select(m => m.FormattedMessage).ToList();
AssertLogMessages(expectedLogMessages, actualLogMessages, testOutput);
}
public void SetUp()
{
_mockQueue = new Mock <QueueClient>(new Uri("https://test.queue.core.windows.net/testqueue"), new QueueClientOptions());
_mockQueue.Setup(x => x.Name).Returns("testqueue");
_mockTriggerExecutor = new Mock <ITriggerExecutor <QueueMessage> >(MockBehavior.Strict);
_mockExceptionDispatcher = new Mock <IWebJobsExceptionHandler>(MockBehavior.Strict);
_loggerFactory = new LoggerFactory();
_loggerProvider = new TestLoggerProvider();
_loggerFactory.AddProvider(_loggerProvider);
_queuesOptions = new QueuesOptions
{
MaxDequeueCount = 5
};
QueueProcessorOptions context = new QueueProcessorOptions(_mockQueue.Object, _loggerFactory, _queuesOptions);
_mockQueueProcessor = new Mock <QueueProcessor>(MockBehavior.Strict, context);
var concurrencyManagerMock = new Mock <ConcurrencyManager>(MockBehavior.Strict);
_listener = new QueueListener(_mockQueue.Object, null, _mockTriggerExecutor.Object, _mockExceptionDispatcher.Object, _loggerFactory, null, _queuesOptions, _mockQueueProcessor.Object, new FunctionDescriptor {
Id = TestFunctionId
}, concurrencyManagerMock.Object);
_queueMessage = QueuesModelFactory.QueueMessage("TestId", "TestPopReceipt", "TestMessage", 0);
}
public async Task Pass_thru_when_exception_in_logic()
{
using (var database = SqlServerTestStore.CreateScratch())
{
var logProvider = new TestLoggerProvider();
var server = SetupTestServer <BloggingContextWithSnapshotThatThrows, ExceptionInLogicMiddleware>(database, logProvider);
var ex = await Assert.ThrowsAsync <SqlException>(async() =>
{
try
{
await server.CreateClient().GetAsync("http://localhost/");
}
catch (InvalidOperationException exception) when(exception.InnerException != null)
{
throw exception.InnerException;
}
});
Assert.Contains(logProvider.Logger.Messages.ToList(), m =>
m.StartsWith(StringsHelpers.GetResourceString("FormatDatabaseErrorPageMiddleware_Exception")));
}
}
public void ListCheckpointsAsync_LogsOnRequestErrors()
{
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>()))
.Throws(new RequestFailedException("Uh oh"));
BlobsCheckpointStore store = new BlobsCheckpointStore(
containerClientMock.Object,
new BasicRetryPolicy(new EventHubsRetryOptions()),
_functionId,
testLoggerProvider.CreateLogger("TestLogger")
);
Assert.ThrowsAsync <RequestFailedException>(async() => 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 exception occurred when listing checkpoints for " +
"FullyQualifiedNamespace: 'TestNamespace'; EventHubName: 'TestEventHubName'; ConsumerGroup: 'TestConsumerGroup'.";
Assert.AreEqual(expectedWarning, warning.FormattedMessage);
testLoggerProvider.ClearAllLogMessages();
}
public async Task BadQueueMessageE2ETests()
{
// This test ensures that the host does not crash on a bad message (it previously did)
// Insert a bad message into a queue that should:
// - trigger BadMessage_CloudQueueMessage, which will put it into a second queue that will
// - trigger BadMessage_String, which should fail
// - BadMessage_String should fail repeatedly until it is moved to the poison queue
// The test will watch that poison queue to know when to complete
// Reinitialize the name resolver to avoid conflicts
_resolver = new RandomNameResolver();
IHost host = new HostBuilder()
.ConfigureDefaultTestHost <AzureStorageEndToEndTests>(b =>
{
b.AddAzureStorageBlobs().AddAzureStorageQueues();
})
.ConfigureServices(services =>
{
// use a custom processor so we can grab the Id and PopReceipt
services.AddSingleton <IQueueProcessorFactory>(new TestQueueProcessorFactory());
services.AddSingleton <INameResolver>(_resolver);
})
.Build();
TestLoggerProvider loggerProvider = host.GetTestLoggerProvider();
// The jobs host is started
host.Start();
// Construct a bad message:
// - use a GUID as the content, which is not a valid base64 string
// - pass 'true', to indicate that it is a base64 string
string messageContent = Guid.NewGuid().ToString();
// var message = new CloudQueueMessage(messageContent, true); // TODO (kasobol-msft) check this base64 thing
var queue = _queueServiceClient.GetQueueClient(_resolver.ResolveInString(BadMessageQueue1));
await queue.CreateIfNotExistsAsync();
await queue.ClearMessagesAsync();
// the poison queue will end up off of the second queue
var poisonQueue = _queueServiceClient.GetQueueClient(_resolver.ResolveInString(BadMessageQueue2) + "-poison");
await poisonQueue.DeleteIfExistsAsync();
await queue.SendMessageAsync(messageContent);
QueueMessage poisonMessage = null;
await TestHelpers.Await(async() =>
{
bool done = false;
if (await poisonQueue.ExistsAsync())
{
poisonMessage = (await poisonQueue.ReceiveMessagesAsync(1)).Value.FirstOrDefault();
done = poisonMessage != null;
if (done)
{
// Sleep briefly, then make sure the other message has been deleted.
// If so, trying to delete it again will throw an error.
Thread.Sleep(1000);
// The message is in the second queue
var queue2 = _queueServiceClient.GetQueueClient(_resolver.ResolveInString(BadMessageQueue2));
RequestFailedException ex = Assert.ThrowsAsync <RequestFailedException>(
() => queue2.DeleteMessageAsync(_lastMessageId, _lastMessagePopReceipt));
Assert.AreEqual("MessageNotFound", ex.ErrorCode);
}
}
var logs = loggerProvider.GetAllLogMessages();
return(done);
});
await host.StopAsync();
// find the raw string to compare it to the original
Assert.NotNull(poisonMessage);
Assert.AreEqual(messageContent, poisonMessage.MessageText);
// Make sure the functions were called correctly
Assert.AreEqual(1, _badMessage1Calls);
Assert.AreEqual(0, _badMessage2Calls);
// Validate Logger
var loggerErrors = loggerProvider.GetAllLogMessages().Where(l => l.Level == Microsoft.Extensions.Logging.LogLevel.Error);
Assert.True(loggerErrors.All(t => t.Exception.InnerException.InnerException is FormatException));
}
public FunctionsSyncManagerTests()
{
_testRootScriptPath = Path.GetTempPath();
_testHostConfigFilePath = Path.Combine(_testRootScriptPath, ScriptConstants.HostMetadataFileName);
FileUtility.DeleteFileSafe(_testHostConfigFilePath);
_hostOptions = new ScriptApplicationHostOptions
{
ScriptPath = @"x:\root",
IsSelfHost = false,
LogPath = @"x:\tmp\log",
SecretsPath = @"x:\secrets",
TestDataPath = @"x:\sampledata"
};
var jobHostOptions = new ScriptJobHostOptions
{
RootScriptPath = _hostOptions.ScriptPath,
RootLogPath = _hostOptions.LogPath
};
string testHostName = "appName.azurewebsites.net";
_vars = new Dictionary <string, string>
{
{ EnvironmentSettingNames.WebSiteAuthEncryptionKey, TestHelpers.GenerateKeyHexString() },
{ EnvironmentSettingNames.AzureWebsiteHostName, testHostName }
};
ResetMockFileSystem();
_loggerProvider = new TestLoggerProvider();
var loggerFactory = new LoggerFactory();
loggerFactory.AddProvider(_loggerProvider);
_contentBuilder = new StringBuilder();
_mockHttpHandler = new MockHttpHandler(_contentBuilder);
var httpClient = CreateHttpClient(_mockHttpHandler);
var factory = new TestOptionsFactory <ScriptApplicationHostOptions>(_hostOptions);
var tokenSource = new TestChangeTokenSource <ScriptApplicationHostOptions>();
var changeTokens = new[] { tokenSource };
var optionsMonitor = new OptionsMonitor <ScriptApplicationHostOptions>(factory, changeTokens, factory);
var secretManagerProviderMock = new Mock <ISecretManagerProvider>(MockBehavior.Strict);
var secretManagerMock = new Mock <ISecretManager>(MockBehavior.Strict);
secretManagerProviderMock.SetupGet(p => p.Current).Returns(secretManagerMock.Object);
var hostSecretsInfo = new HostSecretsInfo();
hostSecretsInfo.MasterKey = "aaa";
hostSecretsInfo.FunctionKeys = new Dictionary <string, string>
{
{ "TestHostFunctionKey1", "aaa" },
{ "TestHostFunctionKey2", "bbb" }
};
hostSecretsInfo.SystemKeys = new Dictionary <string, string>
{
{ "TestSystemKey1", "aaa" },
{ "TestSystemKey2", "bbb" }
};
secretManagerMock.Setup(p => p.GetHostSecretsAsync()).ReturnsAsync(hostSecretsInfo);
Dictionary <string, string> functionSecretsResponse = new Dictionary <string, string>()
{
{ "TestFunctionKey1", "aaa" },
{ "TestFunctionKey2", "bbb" }
};
secretManagerMock.Setup(p => p.GetFunctionSecretsAsync("function1", false)).ReturnsAsync(functionSecretsResponse);
var configuration = ScriptSettingsManager.BuildDefaultConfiguration();
var hostIdProviderMock = new Mock <IHostIdProvider>(MockBehavior.Strict);
hostIdProviderMock.Setup(p => p.GetHostIdAsync(CancellationToken.None)).ReturnsAsync("testhostid123");
_mockWebHostEnvironment = new Mock <IScriptWebHostEnvironment>(MockBehavior.Strict);
_mockWebHostEnvironment.SetupGet(p => p.InStandbyMode).Returns(false);
_mockEnvironment = new Mock <IEnvironment>(MockBehavior.Strict);
_mockEnvironment.Setup(p => p.GetEnvironmentVariable(EnvironmentSettingNames.AzureWebsiteArmCacheEnabled)).Returns("1");
_mockEnvironment.Setup(p => p.GetEnvironmentVariable(EnvironmentSettingNames.AzureWebsiteContainerReady)).Returns("1");
_mockEnvironment.Setup(p => p.GetEnvironmentVariable(EnvironmentSettingNames.CoreToolsEnvironment)).Returns((string)null);
_mockEnvironment.Setup(p => p.GetEnvironmentVariable(EnvironmentSettingNames.WebSiteAuthEncryptionKey)).Returns("1");
_mockEnvironment.Setup(p => p.GetEnvironmentVariable(EnvironmentSettingNames.AzureWebsiteInstanceId)).Returns("1");
_mockEnvironment.Setup(p => p.GetEnvironmentVariable(EnvironmentSettingNames.AzureWebsiteHostName)).Returns(testHostName);
_mockEnvironment.Setup(p => p.GetEnvironmentVariable(EnvironmentSettingNames.SkipSslValidation)).Returns((string)null);
_mockEnvironment.Setup(p => p.GetEnvironmentVariable(EnvironmentSettingNames.AzureWebJobsSecretStorageType)).Returns("blob");
_mockEnvironment.Setup(p => p.GetEnvironmentVariable(EnvironmentSettingNames.KubernetesServiceHost)).Returns("");
_mockEnvironment.Setup(p => p.GetEnvironmentVariable(EnvironmentSettingNames.PodNamespace)).Returns("");
_hostNameProvider = new HostNameProvider(_mockEnvironment.Object);
var functionMetadataProvider = new FunctionMetadataProvider(optionsMonitor, NullLogger <FunctionMetadataProvider> .Instance, new TestMetricsLogger());
var functionMetadataManager = TestFunctionMetadataManager.GetFunctionMetadataManager(new OptionsWrapper <ScriptJobHostOptions>(jobHostOptions), functionMetadataProvider, null, new OptionsWrapper <HttpWorkerOptions>(new HttpWorkerOptions()), loggerFactory, new OptionsWrapper <LanguageWorkerOptions>(CreateLanguageWorkerConfigSettings()));
_functionsSyncManager = new FunctionsSyncManager(configuration, hostIdProviderMock.Object, optionsMonitor, loggerFactory.CreateLogger <FunctionsSyncManager>(), httpClient, secretManagerProviderMock.Object, _mockWebHostEnvironment.Object, _mockEnvironment.Object, _hostNameProvider, functionMetadataManager);
}
public async Task BadQueueMessageE2ETests()
{
// This test ensures that the host does not crash on a bad message (it previously did)
// Insert a bad message into a queue that should:
// - trigger BadMessage_String, which should fail
// - BadMessage_String should be transfered to poison queue.
// The test will watch that poison queue to know when to complete
// Reinitialize the name resolver to avoid conflicts
_resolver = new RandomNameResolver();
IHost host = new HostBuilder()
.ConfigureDefaultTestHost <AzureStorageEndToEndTests>(b =>
{
b.AddAzureStorageBlobs().AddAzureStorageQueues();
})
.ConfigureServices(services =>
{
// use a custom processor so we can grab the Id and PopReceipt
services.AddSingleton <IQueueProcessorFactory>(new TestQueueProcessorFactory());
services.AddSingleton <INameResolver>(_resolver);
})
.Build();
TestLoggerProvider loggerProvider = host.GetTestLoggerProvider();
// The jobs host is started
host.Start();
// Construct a bad message:
// - use a GUID as the content, which is not a valid base64 string
// - pass 'true', to indicate that it is a base64 string
string messageContent = Guid.NewGuid().ToString();
var queue = _queueServiceClientWithoutEncoding.GetQueueClient(_resolver.ResolveInString(BadMessageQueue));
await queue.CreateIfNotExistsAsync();
await queue.ClearMessagesAsync();
var poisonQueue = _queueServiceClientWithoutEncoding.GetQueueClient(_resolver.ResolveInString(BadMessageQueue) + "-poison");
await poisonQueue.DeleteIfExistsAsync();
await queue.SendMessageAsync(messageContent);
QueueMessage poisonMessage = null;
await TestHelpers.Await(async() =>
{
bool done = false;
if (await poisonQueue.ExistsAsync())
{
poisonMessage = await poisonQueue.ReceiveMessageAsync();
done = poisonMessage != null;
}
var logs = loggerProvider.GetAllLogMessages();
return(done);
});
await host.StopAsync();
// find the raw string to compare it to the original
Assert.NotNull(poisonMessage);
Assert.AreEqual(messageContent, poisonMessage.MessageText);
// Make sure the functions were called correctly
Assert.AreEqual(0, _badMessageCalls);
// Validate Logger
var loggerErrors = loggerProvider.GetAllLogMessages().Where(l => l.Level == Microsoft.Extensions.Logging.LogLevel.Error);
Assert.True(loggerErrors.All(t => t.Exception.InnerException.InnerException is FormatException));
}
public MetricsEventManagerTests()
{
_loggerFactory = new LoggerFactory();
_testLoggerProvider = new TestLoggerProvider();
_loggerFactory.AddProvider(_testLoggerProvider);
_functionExecutionEventArguments = new List <FunctionExecutionEventArguments>();
_mockEventGenerator = new Mock <IEventGenerator>();
_mockEventGenerator.Setup(e => e.LogFunctionExecutionEvent(
It.IsAny <string>(),
It.IsAny <string>(),
It.IsAny <int>(),
It.IsAny <string>(),
It.IsAny <string>(),
It.IsAny <string>(),
It.IsAny <long>(),
It.IsAny <bool>()))
.Callback((string executionId, string siteName, int concurrency, string functionName, string invocationId, string executionStage, long executionTimeSpan, bool success) =>
{
if (_throwOnExecutionEvent && executionStage == ExecutionStage.InProgress.ToString())
{
_throwOnExecutionEvent = false;
throw new Exception("Kaboom!");
}
lock (_syncLock)
{
_functionExecutionEventArguments.Add(new FunctionExecutionEventArguments(executionId, siteName, concurrency, functionName, invocationId, executionStage, executionTimeSpan, success));
}
});
_events = new List <SystemMetricEvent>();
_mockEventGenerator.Setup(p => p.LogFunctionMetricEvent(
It.IsAny <string>(),
It.IsAny <string>(),
It.IsAny <string>(),
It.IsAny <string>(),
It.IsAny <long>(),
It.IsAny <long>(),
It.IsAny <long>(),
It.IsAny <long>(),
It.IsAny <DateTime>(),
It.IsAny <string>(),
It.IsAny <string>(),
It.IsAny <string>()))
.Callback((string subscriptionId, string appName, string functionName, string eventName, long average, long min, long max, long count, DateTime eventTimestamp, string data, string runtimeSiteName, string slotName) =>
{
var evt = new SystemMetricEvent
{
FunctionName = functionName,
EventName = eventName,
Average = average,
Minimum = min,
Maximum = max,
Count = count,
Data = data,
RuntimeSiteName = runtimeSiteName,
SlotName = slotName
};
lock (_syncLock)
{
_events.Add(evt);
}
});
_mockEventPublisher = new Mock <IMetricsPublisher>();
_mockAppServiceOptions = new Mock <IOptionsMonitor <AppServiceOptions> >();
_mockAppServiceOptions.Setup(a => a.CurrentValue).Returns(new AppServiceOptions {
AppName = "RandomAppName", SubscriptionId = Guid.NewGuid().ToString()
});
_linuxFunctionExecutionActivityPublisher = new Mock <ILinuxContainerActivityPublisher>();
var logger = _loggerFactory.CreateLogger <MetricsEventManager>();
_metricsEventManager = new MetricsEventManager(_mockAppServiceOptions.Object, _mockEventGenerator.Object, MinimumLongRunningDurationInMs / 1000, _mockEventPublisher.Object, _linuxFunctionExecutionActivityPublisher.Object, logger);
_metricsLogger = new WebHostMetricsLogger(_metricsEventManager);
}
public FunctionListenerTests()
{
_loggerFactory = new LoggerFactory();
_loggerProvider = new TestLoggerProvider();
_loggerFactory.AddProvider(_loggerProvider);
}
public async Task InvocationsContainDifferentOperationIds()
{
// Verify that when a request specializes the host we don't capture the context
// of that request. Application Insights uses this context to correlate telemetry
// so it had a confusing effect. Previously all TimerTrigger traces would have the
// operation id of this request and all host logs would as well.
// Start a host in standby mode.
StandbyManager.ResetChangeToken();
string standbyPath = Path.Combine(Path.GetTempPath(), "functions", "standby", "wwwroot");
string specializedScriptRoot = @"TestScripts\CSharp";
string scriptRootConfigPath = ConfigurationPath.Combine(ConfigurationSectionNames.WebHost, nameof(ScriptApplicationHostOptions.ScriptPath));
var settings = new Dictionary <string, string>()
{
{ EnvironmentSettingNames.AzureWebsitePlaceholderMode, "1" },
{ EnvironmentSettingNames.AzureWebsiteContainerReady, null },
};
var environment = new TestEnvironment(settings);
var loggerProvider = new TestLoggerProvider();
var channel = new TestTelemetryChannel();
var builder = Program.CreateWebHostBuilder()
.ConfigureLogging(b =>
{
b.AddProvider(loggerProvider);
})
.ConfigureAppConfiguration(c =>
{
c.AddInMemoryCollection(new Dictionary <string, string>
{
{ scriptRootConfigPath, specializedScriptRoot }
});
})
.ConfigureServices((bc, s) =>
{
s.AddSingleton <IEnvironment>(environment);
// Ensure that we don't have a race between the timer and the
// request for triggering specialization.
s.AddSingleton <IStandbyManager, InfiniteTimerStandbyManager>();
})
.AddScriptHostBuilder(webJobsBuilder =>
{
webJobsBuilder.Services.AddSingleton <ITelemetryChannel>(_ => channel);
webJobsBuilder.Services.Configure <FunctionResultAggregatorOptions>(o =>
{
o.IsEnabled = false;
});
webJobsBuilder.Services.PostConfigure <ApplicationInsightsLoggerOptions>(o =>
{
o.SamplingSettings = null;
});
webJobsBuilder.Services.PostConfigure <ScriptJobHostOptions>(o =>
{
// Only load the function we care about, but not during standby
if (o.RootScriptPath != standbyPath)
{
o.Functions = new[]
{
"OneSecondTimer",
"FunctionExecutionContext"
};
}
});
})
.ConfigureScriptHostAppConfiguration(c =>
{
c.AddInMemoryCollection(new Dictionary <string, string>
{
[EnvironmentSettingNames.AppInsightsInstrumentationKey] = "some_key"
});
});
using (var testServer = new TestServer(builder))
{
var client = testServer.CreateClient();
HttpResponseMessage response = await client.GetAsync("api/warmup");
Assert.True(response.IsSuccessStatusCode, loggerProvider.GetLog());
// Now that standby mode is warmed up, set the specialization properties...
environment.SetEnvironmentVariable(EnvironmentSettingNames.AzureWebsiteContainerReady, "1");
environment.SetEnvironmentVariable(EnvironmentSettingNames.AzureWebsitePlaceholderMode, "0");
// ...and issue a request which will force specialization.
response = await client.GetAsync("api/functionexecutioncontext");
Assert.True(response.IsSuccessStatusCode, loggerProvider.GetLog());
// Wait until we have a few logs from the timer trigger.
IEnumerable <TraceTelemetry> timerLogs = null;
await TestHelpers.Await(() =>
{
timerLogs = channel.Telemetries
.OfType <TraceTelemetry>()
.Where(p => p.Message == "OneSecondTimer fired!");
return(timerLogs.Count() >= 3);
});
var startupRequest = channel.Telemetries
.OfType <RequestTelemetry>()
.Where(p => p.Name == "FunctionExecutionContext")
.Single();
// Make sure that auto-Http tracking worked with this request.
Assert.Equal("200", startupRequest.ResponseCode);
// The host logs should not be associated with this request.
var logsWithRequestId = channel.Telemetries
.OfType <TraceTelemetry>()
.Select(p => p.Context.Operation.Id)
.Where(p => p == startupRequest.Context.Operation.Id);
// Just expect the "Executing" and "Executed" logs from the actual request.
Assert.Equal(2, logsWithRequestId.Count());
// And each of the timer invocations should have a different operation id, and none
// should match the request id.
var distinctOpIds = timerLogs.Select(p => p.Context.Operation.Id).Distinct();
Assert.Equal(timerLogs.Count(), distinctOpIds.Count());
Assert.Empty(timerLogs.Where(p => p.Context.Operation.Id == startupRequest.Context.Operation.Id));
}
}
public async Task StandbyMode_EndToEnd_LinuxContainer()
{
byte[] bytes = TestHelpers.GenerateKeyBytes();
var encryptionKey = Convert.ToBase64String(bytes);
var vars = new Dictionary <string, string>
{
{ EnvironmentSettingNames.ContainerName, "TestContainer" },
{ EnvironmentSettingNames.ContainerEncryptionKey, encryptionKey },
{ EnvironmentSettingNames.AzureWebsiteContainerReady, null },
{ "AzureWebEncryptionKey", "0F75CA46E7EBDD39E4CA6B074D1F9A5972B849A55F91A248" }
};
using (var env = new TestScopedEnvironmentVariable(vars))
{
var httpConfig = new HttpConfiguration();
var testRootPath = Path.Combine(Path.GetTempPath(), "StandbyModeTest_Linux");
await FileUtility.DeleteDirectoryAsync(testRootPath, true);
var loggerProvider = new TestLoggerProvider();
var loggerProviderFactory = new TestLoggerProviderFactory(loggerProvider);
var webHostSettings = new WebHostSettings
{
IsSelfHost = true,
LogPath = Path.Combine(testRootPath, "Logs"),
SecretsPath = Path.Combine(testRootPath, "Secrets"),
ScriptPath = Path.Combine(testRootPath, "WWWRoot")
};
var loggerFactory = new LoggerFactory();
loggerFactory.AddProvider(loggerProvider);
var webHostBuilder = Program.CreateWebHostBuilder()
.ConfigureServices(c =>
{
c.AddSingleton(webHostSettings)
.AddSingleton <ILoggerProviderFactory>(loggerProviderFactory)
.AddSingleton <ILoggerFactory>(loggerFactory);
});
var httpServer = new TestServer(webHostBuilder);
var 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("Starting Host (HostId=placeholder-host")));
Assert.NotNull(traces.Single(p => p.FormattedMessage.StartsWith("Host is in standby mode")));
// issue warmup request and verify
var request = new HttpRequestMessage(HttpMethod.Get, "api/warmup");
var response = await httpClient.SendAsync(request);
Assert.Equal(HttpStatusCode.OK, response.StatusCode);
string responseBody = await response.Content.ReadAsStringAsync();
Assert.Equal("WarmUp complete.", responseBody);
// issue warmup request with restart and verify
request = new HttpRequestMessage(HttpMethod.Get, "api/warmup?restart=1");
response = await httpClient.SendAsync(request);
Assert.Equal(HttpStatusCode.OK, response.StatusCode);
responseBody = await response.Content.ReadAsStringAsync();
Assert.Equal("WarmUp complete.", responseBody);
// Now specialize the host by invoking assign
var secretManager = httpServer.Host.Services.GetService <ISecretManager>();
var masterKey = (await secretManager.GetHostSecretsAsync()).MasterKey;
string uri = "admin/instance/assign";
request = new HttpRequestMessage(HttpMethod.Post, uri);
var environment = new Dictionary <string, string>();
var assignmentContext = new HostAssignmentContext
{
SiteId = 1234,
SiteName = "TestSite",
Environment = environment
};
var encryptedAssignmentContext = EncryptedHostAssignmentContext.Create(assignmentContext, encryptionKey);
string json = JsonConvert.SerializeObject(encryptedAssignmentContext);
request.Content = new StringContent(json, Encoding.UTF8, "application/json");
request.Headers.Add(AuthenticationLevelHandler.FunctionsKeyHeaderName, masterKey);
response = await httpClient.SendAsync(request);
Assert.Equal(HttpStatusCode.Accepted, response.StatusCode);
// give time for the specialization to happen
string[] logLines = null;
await TestHelpers.Await(() =>
{
// wait for the trace indicating that the host has been specialized
logLines = loggerProvider.GetAllLogMessages().Where(p => p.FormattedMessage != null).Select(p => p.FormattedMessage).ToArray();
return(logLines.Contains("Generating 0 job function(s)"));
}, userMessageCallback : () => string.Join(Environment.NewLine, loggerProvider.GetAllLogMessages().Select(p => $"[{p.Timestamp.ToString("HH:mm:ss.fff")}] {p.FormattedMessage}")));
httpServer.Dispose();
httpClient.Dispose();
await Task.Delay(2000);
var hostConfig = WebHostResolver.CreateScriptHostConfiguration(webHostSettings, true);
var expectedHostId = hostConfig.HostConfig.HostId;
// verify the rest of the expected logs
string text = string.Join(Environment.NewLine, logLines);
Assert.True(logLines.Count(p => p.Contains("Stopping Host")) >= 1);
Assert.Equal(1, logLines.Count(p => p.Contains("Creating StandbyMode placeholder function directory")));
Assert.Equal(1, logLines.Count(p => p.Contains("StandbyMode placeholder function directory created")));
Assert.Equal(2, logLines.Count(p => p.Contains("Starting Host (HostId=placeholder-host")));
Assert.Equal(2, logLines.Count(p => p.Contains("Host is in standby mode")));
Assert.Equal(2, logLines.Count(p => p.Contains("Executed 'Functions.WarmUp' (Succeeded")));
Assert.Equal(1, logLines.Count(p => p.Contains("Starting host specialization")));
Assert.Equal(1, logLines.Count(p => p.Contains($"Starting Host (HostId={expectedHostId}")));
Assert.Contains("Generating 0 job function(s)", logLines);
WebScriptHostManager.ResetStandbyMode();
}
}
public CapabilitiesTests()
{
_loggerProvider = new TestLoggerProvider();
_loggerFactory.AddProvider(_loggerProvider);
_capabilities = new Capabilities(_loggerFactory.CreateLogger <Capabilities>());
}
public async Task RecoveryTest(int expectedNumberOfAttempts, bool isFailureScenario)
{
ILoggerFactory loggerFactory = new LoggerFactory();
TestLoggerProvider loggerProvider = new TestLoggerProvider();
loggerFactory.AddProvider(loggerProvider);
using (var directory = new TempDirectory())
using (var watcher = new AutoRecoveringFileSystemWatcher(directory.Path, loggerFactory: loggerFactory))
{
Directory.Delete(directory.Path, true);
string fileWatcherLogSuffix = $"(path: '{directory.Path}')";
// 1 recovery initiating trace + 1 trace per attempt + 1 trace per failed attempt
int expectedTracesBeforeRecovery = 1 + ((expectedNumberOfAttempts - 1) * 2);
// Non failure: expected traces + last attempt + recovery trace
// Failure: expected traces + abort/failure trace
int expectedTracesAfterRecovery = expectedTracesBeforeRecovery + (isFailureScenario ? 1 : 2);
await TestHelpers.Await(() =>
{
return(loggerProvider.GetAllLogMessages().Count() == expectedTracesBeforeRecovery);
}, pollingInterval : 500);
if (isFailureScenario)
{
watcher.Dispose();
}
else
{
Directory.CreateDirectory(directory.Path);
}
await TestHelpers.Await(() =>
{
return(loggerProvider.GetAllLogMessages().Count() == expectedTracesAfterRecovery);
}, pollingInterval : 500);
LogMessage failureEvent = loggerProvider.GetAllLogMessages().First();
Assert.Equal(LogLevel.Warning, failureEvent.Level);
Assert.Contains("Failure detected", failureEvent.FormattedMessage);
var retryEvents = loggerProvider.GetAllLogMessages().Where(t => t.Level == LogLevel.Warning).Skip(1).ToList();
if (isFailureScenario)
{
// If this is a failed scenario, we've aborted before the last attempt
expectedNumberOfAttempts--;
}
Assert.Equal(expectedNumberOfAttempts, retryEvents.Count);
// Validate that our the events happened with the expected intervals
DateTime previoustTimeStamp = failureEvent.Timestamp;
for (int i = 0; i < retryEvents.Count; i++)
{
long expectedInterval = Convert.ToInt64((Math.Pow(2, i + 1) - 1) / 2);
LogMessage currentEvent = retryEvents[i];
var actualInterval = currentEvent.Timestamp - previoustTimeStamp;
previoustTimeStamp = currentEvent.Timestamp;
int roundedIntervalInSeconds = (int)Math.Round(actualInterval.TotalSeconds, 0, MidpointRounding.ToEven);
Assert.True(expectedInterval == roundedIntervalInSeconds,
$"Recovering interval did not meet the expected interval (expected '{expectedInterval}', rounded '{roundedIntervalInSeconds}', actual '{actualInterval.Seconds}')");
}
Assert.True(loggerProvider.GetAllLogMessages().All(t => t.FormattedMessage.EndsWith(fileWatcherLogSuffix)));
if (isFailureScenario)
{
Assert.Contains("Recovery process aborted.", loggerProvider.GetAllLogMessages().Last().FormattedMessage);
}
else
{
Assert.Contains("File watcher recovered.", loggerProvider.GetAllLogMessages().Last().FormattedMessage);
}
Assert.Equal($"Host.{ScriptConstants.TraceSourceFileWatcher}", loggerProvider.GetAllLogMessages().Last().Category);
}
}
public async Task GetHostSecrets_WhenTooManyBackups_ThrowsException()
{
using (var directory = new TempDirectory())
{
string functionName = "testfunction";
string expectedTraceMessage = string.Format(Resources.ErrorTooManySecretBackups, ScriptConstants.MaximumSecretBackupCount, functionName,
string.Format(Resources.ErrorSameSecrets, "test0,test1"));
string functionSecretsJson =
@"{
'keys': [
{
'name': 'Key1',
'value': 'FunctionValue1',
'encrypted': true
},
{
'name': 'Key2',
'value': 'FunctionValue2',
'encrypted': false
}
]
}";
ILoggerFactory loggerFactory = new LoggerFactory();
TestLoggerProvider loggerProvider = new TestLoggerProvider();
loggerFactory.AddProvider(loggerProvider);
var logger = loggerFactory.CreateLogger(LogCategories.CreateFunctionCategory("Test1"));
IDictionary <string, string> functionSecrets;
ISecretsRepository repository = new FileSystemSecretsRepository(directory.Path);
using (var secretManager = new SecretManager(repository, logger, new TestMetricsLogger(), _hostNameProvider))
{
InvalidOperationException ioe = null;
try
{
for (int i = 0; i < ScriptConstants.MaximumSecretBackupCount + 20; i++)
{
File.WriteAllText(Path.Combine(directory.Path, functionName + ".json"), functionSecretsJson);
// If we haven't hit the exception yet, pause to ensure the file contents are being flushed.
if (i >= ScriptConstants.MaximumSecretBackupCount)
{
await Task.Delay(500);
}
// reset hostname provider and set a new hostname to force another backup
_hostNameProvider.Reset();
string hostName = "test" + (i % 2).ToString();
_testEnvironment.SetEnvironmentVariable(EnvironmentSettingNames.AzureWebsiteHostName, hostName);
functionSecrets = await secretManager.GetFunctionSecretsAsync(functionName);
}
}
catch (InvalidOperationException ex)
{
ioe = ex;
}
}
Assert.True(Directory.GetFiles(directory.Path, $"{functionName}.{ScriptConstants.Snapshot}*").Length >= ScriptConstants.MaximumSecretBackupCount);
Assert.True(loggerProvider.GetAllLogMessages().Any(
t => t.Level == LogLevel.Debug && t.FormattedMessage.IndexOf(expectedTraceMessage, StringComparison.OrdinalIgnoreCase) > -1),
"Expected Trace message not found");
}
}
public async Task HostRestart_DuringInitialization_Recovers()
{
SemaphoreSlim semaphore = new SemaphoreSlim(1, 1);
await semaphore.WaitAsync();
// Have the first host start, but pause. We'll issue a restart, wait for the
// second host to be running, then let this first host throw an exception.
var hostA = CreateMockHost();
hostA
.Setup(h => h.StartAsync(It.IsAny <CancellationToken>()))
.Returns(async() =>
{
await semaphore.WaitAsync();
throw new InvalidOperationException("Something happened at startup!");
});
var hostB = CreateMockHost();
hostB
.Setup(h => h.StartAsync(It.IsAny <CancellationToken>()))
.Returns(() => Task.CompletedTask);
var hostBuilder = new Mock <IScriptHostBuilder>();
hostBuilder.SetupSequence(b => b.BuildHost(It.IsAny <bool>(), It.IsAny <bool>()))
.Returns(hostA.Object)
.Returns(hostB.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);
Task initialStart = _hostService.StartAsync(CancellationToken.None);
Thread restartHostThread = new Thread(new ThreadStart(RestartHost));
restartHostThread.Start();
restartHostThread.Join();
await TestHelpers.Await(() => _hostService.State == ScriptHostState.Running);
// Now let the first host throw its startup exception.
semaphore.Release();
await initialStart;
// Note that HostA is disposed so its services cannot be accessed. Logging will fall
// back to using the WebHost's logger.
Assert.Throws <ObjectDisposedException>(() => hostA.Object.GetTestLoggerProvider());
TestLoggerProvider hostBLogger = hostB.Object.GetTestLoggerProvider();
// Make sure the error was logged to the correct logger
Assert.Contains(_webHostLoggerProvider.GetAllLogMessages(), m => m.FormattedMessage != null && m.FormattedMessage.Contains("A host error has occurred on an inactive host"));
Assert.DoesNotContain(hostBLogger.GetAllLogMessages(), m => m.FormattedMessage != null && m.FormattedMessage.Contains("A host error has occurred"));
// Make sure we orphaned the correct host when the exception was thrown. This will happen
// twice: once during Restart and once during the Orphan call when handling the exception.
hostA.Verify(m => m.StopAsync(It.IsAny <CancellationToken>()), Times.Exactly(2));
hostA.Verify(m => m.Dispose(), Times.Exactly(2));
// We should not be calling Orphan on the good host
hostB.Verify(m => m.StopAsync(It.IsAny <CancellationToken>()), Times.Never);
hostB.Verify(m => m.Dispose(), Times.Never);
// The "late" exception from the first host shouldn't bring things down
Assert.Equal(ScriptHostState.Running, _hostService.State);
}
public BindingTests(ITestOutputHelper output)
{
this.output = output;
this.loggerProvider = new TestLoggerProvider(output);
}
public CorrelationEndToEndTests(ITestOutputHelper output)
{
this.output = output;
this.loggerProvider = new TestLoggerProvider(output);
}
public async Task StandbyMode_EndToEnd()
{
var vars = new Dictionary <string, string>
{
{ EnvironmentSettingNames.AzureWebsitePlaceholderMode, "1" },
{ EnvironmentSettingNames.AzureWebsiteContainerReady, null },
{ EnvironmentSettingNames.AzureWebsiteInstanceId, "87654639876900123453445678890144" },
{ "AzureWebEncryptionKey", "0F75CA46E7EBDD39E4CA6B074D1F9A5972B849A55F91A248" }
};
using (var env = new TestScopedEnvironmentVariable(vars))
{
var httpConfig = new HttpConfiguration();
var testRootPath = Path.Combine(Path.GetTempPath(), "StandbyModeTest");
await FileUtility.DeleteDirectoryAsync(testRootPath, true);
var loggerProvider = new TestLoggerProvider();
var loggerProviderFactory = new TestLoggerProviderFactory(loggerProvider);
var webHostSettings = new WebHostSettings
{
IsSelfHost = true,
LogPath = Path.Combine(testRootPath, "Logs"),
SecretsPath = Path.Combine(testRootPath, "Secrets"),
ScriptPath = Path.Combine(testRootPath, "WWWRoot")
};
var loggerFactory = new LoggerFactory();
loggerFactory.AddProvider(loggerProvider);
var webHostBuilder = Program.CreateWebHostBuilder()
.ConfigureServices(c => {
c.AddSingleton(webHostSettings)
.AddSingleton <ILoggerProviderFactory>(loggerProviderFactory)
.AddSingleton <ILoggerFactory>(loggerFactory);
});
var httpServer = new TestServer(webHostBuilder);
var 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("Starting Host (HostId=placeholder-host")));
Assert.NotNull(traces.Single(p => p.FormattedMessage.StartsWith("Host is in standby mode")));
// issue warmup request and verify
var request = new HttpRequestMessage(HttpMethod.Get, "api/warmup");
var response = await httpClient.SendAsync(request);
Assert.Equal(HttpStatusCode.OK, response.StatusCode);
string responseBody = await response.Content.ReadAsStringAsync();
Assert.Equal("WarmUp complete.", responseBody);
// issue warmup request with restart and verify
request = new HttpRequestMessage(HttpMethod.Get, "api/warmup?restart=1");
response = await httpClient.SendAsync(request);
Assert.Equal(HttpStatusCode.OK, response.StatusCode);
responseBody = await response.Content.ReadAsStringAsync();
Assert.Equal("WarmUp complete.", responseBody);
// Now specialize the host
ScriptSettingsManager.Instance.SetSetting(EnvironmentSettingNames.AzureWebsitePlaceholderMode, "0");
ScriptSettingsManager.Instance.SetSetting(EnvironmentSettingNames.AzureWebsiteContainerReady, "1");
Assert.False(WebScriptHostManager.InStandbyMode);
Assert.True(ScriptSettingsManager.Instance.ContainerReady);
// give time for the specialization to happen
string[] logLines = null;
await TestHelpers.Await(() =>
{
// wait for the trace indicating that the host has been specialized
logLines = loggerProvider.GetAllLogMessages().Where(p => p.FormattedMessage != null).Select(p => p.FormattedMessage).ToArray();
return(logLines.Contains("Generating 0 job function(s)"));
}, userMessageCallback : () => string.Join(Environment.NewLine, loggerProvider.GetAllLogMessages().Select(p => $"[{p.Timestamp.ToString("HH:mm:ss.fff")}] {p.FormattedMessage}")));
httpServer.Dispose();
httpClient.Dispose();
await Task.Delay(2000);
var hostConfig = WebHostResolver.CreateScriptHostConfiguration(webHostSettings, true);
var expectedHostId = hostConfig.HostConfig.HostId;
// verify the rest of the expected logs
string text = string.Join(Environment.NewLine, logLines);
Assert.True(logLines.Count(p => p.Contains("Stopping Host")) >= 1);
Assert.Equal(1, logLines.Count(p => p.Contains("Creating StandbyMode placeholder function directory")));
Assert.Equal(1, logLines.Count(p => p.Contains("StandbyMode placeholder function directory created")));
Assert.Equal(2, logLines.Count(p => p.Contains("Starting Host (HostId=placeholder-host")));
Assert.Equal(2, logLines.Count(p => p.Contains("Host is in standby mode")));
Assert.Equal(2, logLines.Count(p => p.Contains("Executed 'Functions.WarmUp' (Succeeded")));
Assert.Equal(1, logLines.Count(p => p.Contains("Starting host specialization")));
Assert.Equal(1, logLines.Count(p => p.Contains($"Starting Host (HostId={expectedHostId}")));
Assert.Contains("Generating 0 job function(s)", logLines);
WebScriptHostManager.ResetStandbyMode();
}
}