private void FireSyncTriggers(ITracer tracer)
{
tracer.Trace("FunctionController.FireSyncTriggers");
// create background tracer independent of request lifetime
var bgTracer = new XmlTracer(_environment.TracePath, tracer.TraceLevel);
// start new task to detach from request sync context
Task.Run(async() =>
{
using (bgTracer.Step(XmlTracer.BackgroundTrace, new Dictionary <string, string>
{
{ "url", "/api/functions/synctriggers" },
{ "method", "POST" }
}))
{
try
{
await PostDeploymentHelper.SyncFunctionsTriggers(_environment.RequestId, new PostDeploymentTraceListener(bgTracer));
}
catch (Exception ex)
{
bgTracer.TraceError(ex);
}
}
});
}
public void TracerMaxXmlFilesTest()
{
// Mock
var path = @"x:\kudu\trace";
var tracer = new XmlTracer(path, TraceLevel.Verbose);
FileSystemHelpers.Instance = GetMockFileSystem();
var total = XmlTracer.MaxXmlFiles + 10;
for (int i = 0; i < total; ++i)
{
tracer.Trace(Guid.NewGuid().ToString(), new Dictionary <string, string>());
}
var files = FileSystemHelpers.GetFiles(path, "*.xml");
Assert.Equal(total, files.Length);
// wait till interval and write another trace
typeof(XmlTracer).GetField("_lastCleanup", BindingFlags.Static | BindingFlags.NonPublic).SetValue(null, DateTime.MinValue);
tracer.Trace(Guid.NewGuid().ToString(), new Dictionary <string, string>());
files = FileSystemHelpers.GetFiles(path, "*.xml");
Assert.True(files.Length < XmlTracer.MaxXmlFiles);
}
public void TracerRequestsTest(TraceLevel traceLevel, RequestInfo[] requests)
{
// Mock
var path = @"x:\kudu\trace";
var tracer = new XmlTracer(path, traceLevel);
FileSystemHelpers.Instance = GetMockFileSystem();
try
{
foreach (var request in requests)
{
Dictionary <string, string> attribs = new Dictionary <string, string>
{
{ "type", "request" },
{ "url", request.Url },
{ "method", "GET" },
{ "statusCode", ((int)request.StatusCode).ToString() },
};
using (tracer.Step("Incoming Request", attribs))
{
tracer.Trace("Outgoing response", attribs);
}
}
var traces = new List <RequestInfo>();
foreach (var file in FileSystemHelpers.GetFiles(path, "*s.xml").OrderBy(n => n))
{
var document = XDocument.Load(FileSystemHelpers.OpenRead(file));
var trace = new RequestInfo {
Url = document.Root.Attribute("url").Value
};
var elapsed = document.Root.Nodes().Last();
// Assert
Assert.Equal(XmlNodeType.Comment, elapsed.NodeType);
Assert.Contains("duration:", ((XComment)elapsed).Value);
traces.Add(trace);
}
// Assert
Assert.Equal(requests.Where(r => r.Traced), traces, RequestInfoComparer.Instance);
}
catch (Exception)
{
FileSystemHelpers.Instance = null;
throw;
}
}
private static ITracer GetTracer(IEnvironment env, TraceLevel level)
{
if (level > TraceLevel.Off)
{
var tracer = new XmlTracer(env.TracePath, level);
string logFile = System.Environment.GetEnvironmentVariable(Constants.TraceFileEnvKey);
if (!String.IsNullOrEmpty(logFile))
{
// Kudu.exe is executed as part of git.exe (post-receive), giving its initial depth of 4 indentations
string logPath = Path.Combine(env.TracePath, logFile);
return(new CascadeTracer(tracer, new TextTracer(logPath, level, 4)));
}
return(tracer);
}
return(NullTracer.Instance);
}
private static ITracer GetTracer(IEnvironment env, TraceLevel level)
{
if (level > TraceLevel.Off)
{
var tracer = new XmlTracer(env.TracePath, level);
string logFile = System.Environment.GetEnvironmentVariable(Constants.TraceFileEnvKey);
if (!String.IsNullOrEmpty(logFile))
{
// Kudu.exe is executed as part of git.exe (post-receive), giving its initial depth of 4 indentations
string logPath = Path.Combine(env.TracePath, logFile);
// since git push is "POST", which then run kudu.exe
return(new CascadeTracer(tracer, new TextTracer(logPath, level, 4), new ETWTracer(env.RequestId, requestMethod: HttpMethod.Post.Method)));
}
return(tracer);
}
return(NullTracer.Instance);
}
public async Task <HttpResponseMessage> InstallExtension(string id, SiteExtensionInfo requestInfo)
{
var startTime = DateTime.UtcNow;
var tracer = _traceFactory.GetTracer();
if (IsInstallationLockHeldSafeCheck(id))
{
tracer.Trace("{0} is installing with another request, reject current request with Conflict status.", id);
throw new HttpResponseException(Request.CreateErrorResponse(HttpStatusCode.Conflict, id));
}
if (requestInfo == null)
{
requestInfo = new SiteExtensionInfo();
}
tracer.Trace("Installing {0}, version: {1} from feed: {2}", id, requestInfo.Version, requestInfo.FeedUrl);
SiteExtensionInfo result = await InitInstallSiteExtension(id, requestInfo.Type);
if (ArmUtils.IsArmRequest(Request))
{
// create a context free tracer
ITracer backgroundTracer = NullTracer.Instance;
IDictionary <string, string> traceAttributes = new Dictionary <string, string>();
if (tracer.TraceLevel == TraceLevel.Off)
{
backgroundTracer = NullTracer.Instance;
}
if (tracer.TraceLevel > TraceLevel.Off)
{
backgroundTracer = new XmlTracer(_environment.TracePath, tracer.TraceLevel);
traceAttributes = new Dictionary <string, string>()
{
{ "url", Request.RequestUri.AbsolutePath },
{ "method", Request.Method.Method }
};
foreach (var item in Request.Headers)
{
if (!traceAttributes.ContainsKey(item.Key))
{
traceAttributes.Add(item.Key, string.Join(",", item.Value));
}
}
}
AutoResetEvent installationSignal = new AutoResetEvent(false);
// trigger installation, but do not wait. Expecting poll for status
ThreadPool.QueueUserWorkItem((object stateInfo) =>
{
using (backgroundTracer.Step(XmlTracer.BackgroundTrace, attributes: traceAttributes))
{
try
{
using (backgroundTracer.Step("Background thread started for {0} installation", id))
{
_manager.InstallExtension(id, requestInfo.Version, requestInfo.FeedUrl, requestInfo.Type, backgroundTracer).Wait();
}
}
finally
{
installationSignal.Set();
// will be a few millionseconds off if task finshed within 15 seconds.
LogEndEvent(id, (DateTime.UtcNow - startTime), backgroundTracer);
}
}
});
SiteExtensionStatus armSettings = new SiteExtensionStatus(_environment.SiteExtensionSettingsPath, id, tracer);
if (installationSignal.WaitOne(TimeSpan.FromSeconds(15)))
{
if (!armSettings.IsRestartRequired(_siteExtensionRoot))
{
// only skip polling if current installation doesn`t require restart, to avoid making race condition common
// TODO: re-visit if we want to skip polling for case that need to restart
tracer.Trace("Installation finish quick and not require restart, skip async polling, invoking GET to return actual status to caller.");
return(await GetLocalExtension(id));
}
}
// do not log end event here, since it is not done yet
return(Request.CreateResponse(HttpStatusCode.Created, ArmUtils.AddEnvelopeOnArmRequest <SiteExtensionInfo>(result, Request)));
}
else
{
result = await _manager.InstallExtension(id, requestInfo.Version, requestInfo.FeedUrl, requestInfo.Type, tracer);
if (string.Equals(Constants.SiteExtensionProvisioningStateFailed, result.ProvisioningState, StringComparison.OrdinalIgnoreCase))
{
SiteExtensionStatus armSettings = new SiteExtensionStatus(_environment.SiteExtensionSettingsPath, id, tracer);
throw new HttpResponseException(Request.CreateErrorResponse(armSettings.Status, result.Comment));
}
var response = Request.CreateResponse(HttpStatusCode.OK, result);
LogEndEvent(id, (DateTime.UtcNow - startTime), tracer);
return(response);
}
}
public void TraceFiltersTests(bool expected, TraceLevel level, TraceInfo info, int statusCode)
{
Assert.Equal(expected, XmlTracer.ShouldTrace(level, info, statusCode));
}
