diff --git a/src/ApiService/ApiService/Functions/Jobs.cs b/src/ApiService/ApiService/Functions/Jobs.cs index 3f8746df1f..f710a81d29 100644 --- a/src/ApiService/ApiService/Functions/Jobs.cs +++ b/src/ApiService/ApiService/Functions/Jobs.cs @@ -93,6 +93,8 @@ private async Task Delete(HttpRequestData req) { return await _context.RequestHandling.NotOk(req, request.ErrorV, "jobs delete"); } + _logTracer.LogInformation("*** Deleting job: {JobId}", request.OkV.JobId); + var jobId = request.OkV.JobId; var job = await _context.JobOperations.Get(jobId); if (job is null) { diff --git a/src/ApiService/ApiService/Log.cs b/src/ApiService/ApiService/Log.cs index 10209e33b3..11e427e17e 100644 --- a/src/ApiService/ApiService/Log.cs +++ b/src/ApiService/ApiService/Log.cs @@ -309,16 +309,6 @@ public static void LogPageView(this ILogger logger, string pageName) { logger.Log(LogLevel.Information, EmptyEventId, pageView, null, (state, exception) => state.ToString() ?? $"Failed to convert pageView {pageView}"); } - /// - /// - /// - /// - /// - /// - public static void LogRequest(this ILogger logger, string name, DateTimeOffset startTime, TimeSpan duration, string responseCode, bool success) { - var request = new RequestTelemetry(name, startTime, duration, responseCode, success); - logger.Log(LogLevel.Information, EmptyEventId, request, null, (state, exception) => state.ToString() ?? $"Failed to convert request {request}"); - } } diff --git a/src/ApiService/ApiService/Program.cs b/src/ApiService/ApiService/Program.cs index f26463883b..ee62d47563 100644 --- a/src/ApiService/ApiService/Program.cs +++ b/src/ApiService/ApiService/Program.cs @@ -3,11 +3,16 @@ global using System.Linq; // to avoid collision with Task in model.cs global using Async = System.Threading.Tasks; +using System.IO; +using System.Text; using System.Text.Json; using ApiService.OneFuzzLib.Orm; using Azure.Core.Serialization; using Azure.Identity; +using Microsoft.ApplicationInsights.Channel; +using Microsoft.ApplicationInsights.DataContracts; using Microsoft.ApplicationInsights.DependencyCollector; +using Microsoft.ApplicationInsights.Extensibility; using Microsoft.Azure.Functions.Worker; using Microsoft.Azure.Functions.Worker.Middleware; using Microsoft.Extensions.Configuration; @@ -19,16 +24,17 @@ using Microsoft.Graph; using Microsoft.OneFuzz.Service.OneFuzzLib.Orm; using Semver; + namespace Microsoft.OneFuzz.Service; public class Program { /// - /// + /// /// public class LoggingMiddleware : IFunctionsWorkerMiddleware { /// - /// + /// /// /// /// @@ -36,7 +42,6 @@ public class LoggingMiddleware : IFunctionsWorkerMiddleware { public async Async.Task Invoke(FunctionContext context, FunctionExecutionDelegate next) { //https://learn.microsoft.com/en-us/azure/azure-monitor/app/custom-operations-tracking#applicationinsights-operations-vs-systemdiagnosticsactivity using var activity = OneFuzzLogger.Activity; - // let azure functions identify the headers for us if (context.TraceContext is not null && !string.IsNullOrEmpty(context.TraceContext.TraceParent)) { activity.TraceStateString = context.TraceContext.TraceState; @@ -120,12 +125,87 @@ public async Async.Task Invoke(FunctionContext context, FunctionExecutionDelegat } } + // public interface IAsyncTelemetryInitializer { + // public Async.Task Initialize(ITelemetry telemetry); + // } + + public interface IOnefuzzRequestStore { + void AddRequestTelemetry(RequestTelemetry telemetry); + List RequestTelemetries { get; } + } + + public class OnefuzzRequestStore : IOnefuzzRequestStore { + public List RequestTelemetries { get; } = new(); + + public void AddRequestTelemetry(RequestTelemetry telemetry) { + RequestTelemetries.Add(telemetry); + + } + } + + + public class OnefuzzTelemetryInitializer : ITelemetryInitializer { + IServiceProvider services; + + + public OnefuzzTelemetryInitializer(IServiceProvider services) { + + this.services = services; + } + + public void Initialize(ITelemetry telemetry) { + var requestTelemetry = telemetry as RequestTelemetry; + + if (requestTelemetry == null) + return; + + var requestStore = services.GetRequiredService(); + + requestStore.AddRequestTelemetry(requestTelemetry); + } + } + + public class RequestBodyLogger : IFunctionsWorkerMiddleware { + + public async Async.Task Invoke(FunctionContext context, FunctionExecutionDelegate next) { + + var requestStore = context.InstanceServices.GetRequiredService(); + + var requestTelemetry = requestStore.RequestTelemetries.FirstOrDefault(); + + if (requestTelemetry != null) { + var requestData = await context.GetHttpRequestDataAsync(); + var body = requestData?.Body; + if (body is { CanRead: true, CanSeek: true }) { + const int MAX_BODY_SIZE = 4096; + var bufferSize = Math.Max(MAX_BODY_SIZE, body.Length); + var buffer = new byte[bufferSize]; + var count = body.Read(buffer); + _ = body.Seek(0, SeekOrigin.Begin); + var bodyText = Encoding.UTF8.GetString(buffer); + + // var tc = context.InstanceServices.GetServices().FirstOrDefault() ?? throw new Exception("No Telemtry client"); + + + // var requestTelemetry = context.Features.Get() ?? + // throw new Exception("No request telemetry"); + + // var requestTelemetry = context.InstanceServices.Get() ?? + // throw new Exception("No request telemetry"); + requestTelemetry.Properties.Add("RequestBody", bodyText); + } + + await next(context); + } + } + } //Move out expensive resources into separate class, and add those as Singleton // ArmClient, Table Client(s), Queue Client(s), HttpClient, etc. public static async Async.Task Main() { var configuration = new ServiceConfiguration(); + using var host = new HostBuilder() @@ -198,6 +278,7 @@ public static async Async.Task Main() { .AddScoped() .AddScoped() .AddScoped() + .AddScoped() .AddSingleton(new GraphServiceClient(new DefaultAzureCredential())) .AddSingleton() .AddSingleton() @@ -211,13 +292,13 @@ public static async Async.Task Main() { _ = services.AddFeatureManagement(); }) .ConfigureLogging(loggingBuilder => { + + var appInsightsConnectionString = $"InstrumentationKey={configuration.ApplicationInsightsInstrumentationKey}"; + var tc = new ApplicationInsights.TelemetryClient(new ApplicationInsights.Extensibility.TelemetryConfiguration() { ConnectionString = appInsightsConnectionString }); loggingBuilder.Services.TryAddEnumerable(ServiceDescriptor.Singleton( - x => { - var appInsightsConnectionString = $"InstrumentationKey={configuration.ApplicationInsightsInstrumentationKey}"; - var tc = new ApplicationInsights.TelemetryClient(new ApplicationInsights.Extensibility.TelemetryConfiguration() { ConnectionString = appInsightsConnectionString }); - return new OneFuzzLoggerProvider(new List() { new TelemetryConfig(tc) }); - } - )); + x => new OneFuzzLoggerProvider(new List() { new TelemetryConfig(tc) }))); + + // loggingBuilder.Services.AddScoped(typeof(Telemetry)) }) .ConfigureFunctionsWorkerDefaults(builder => { builder.UseMiddleware(); @@ -227,6 +308,7 @@ public static async Async.Task Main() { //this is a must, to tell the host that worker logging is done by us builder.Services.Configure(workerOptions => workerOptions.Capabilities["WorkerApplicationInsightsLoggingEnabled"] = bool.TrueString); + builder.Services.TryAddEnumerable(ServiceDescriptor.Singleton()); builder.AddApplicationInsights(options => { #if DEBUG options.DeveloperMode = true; @@ -234,8 +316,13 @@ public static async Async.Task Main() { options.DeveloperMode = false; #endif options.EnableDependencyTrackingTelemetryModule = true; + }); builder.AddApplicationInsightsLogger(); + // builder.UseMiddleware(); + + // builder.Services.AddSingleton(); + }) .Build(); diff --git a/src/ApiService/ApiService/onefuzzlib/JobOperations.cs b/src/ApiService/ApiService/onefuzzlib/JobOperations.cs index 781df97943..1b51a82e27 100644 --- a/src/ApiService/ApiService/onefuzzlib/JobOperations.cs +++ b/src/ApiService/ApiService/onefuzzlib/JobOperations.cs @@ -104,6 +104,7 @@ public async Async.Task Init(Job job) { } public async Async.Task Stopping(Job job) { + _logTracer.LogInformation("Stopping job: {JobId} {StackTrace}", job.JobId, Environment.StackTrace); job = job with { State = JobState.Stopping }; var tasks = await _context.TaskOperations.QueryAsync(Query.PartitionKey(job.JobId.ToString())).ToListAsync(); var taskNotStopped = tasks.ToLookup(task => task.State != TaskState.Stopped); diff --git a/src/agent/onefuzz-task/src/tasks/report/dotnet/generic.rs b/src/agent/onefuzz-task/src/tasks/report/dotnet/generic.rs index 036b20d028..e547e7a88b 100644 --- a/src/agent/onefuzz-task/src/tasks/report/dotnet/generic.rs +++ b/src/agent/onefuzz-task/src/tasks/report/dotnet/generic.rs @@ -207,7 +207,7 @@ impl AsanProcessor { let mut args = vec![target_exe]; args.extend(self.config.target_options.clone()); - let expand = self.config.get_expand(); + let expand = self.config.get_expand().input_path(input); let expanded_args = expand.evaluate(&args)?; diff --git a/src/cli/onefuzz/backend.py b/src/cli/onefuzz/backend.py index 7f23e7de03..45c14fcc9c 100644 --- a/src/cli/onefuzz/backend.py +++ b/src/cli/onefuzz/backend.py @@ -607,7 +607,7 @@ def wait(func: Callable[[], Tuple[bool, str, A]], frequency: float = 1.0) -> A: Provides user feedback via a spinner if stdout is a TTY. """ - isatty = sys.stdout.isatty() + isatty = True frames = ["-", "\\", "|", "/"] waited = False last_message = None @@ -623,20 +623,28 @@ def wait(func: Callable[[], Tuple[bool, str, A]], frequency: float = 1.0) -> A: if isatty: if last_message: if last_message == message: + LOGGER.info("\b" * (len(last_message) + 2)) sys.stdout.write("\b" * (len(last_message) + 2)) else: + LOGGER.info("\n") sys.stdout.write("\n") + LOGGER.info("%s %s" % (frames[0], message)) sys.stdout.write("%s %s" % (frames[0], message)) sys.stdout.flush() elif last_message != message: - print(message, flush=True) + LOGGER.info(message) last_message = message waited = True time.sleep(frequency) frames.sort(key=frames[0].__eq__) + except Exception as err: + LOGGER.info(f"*** error in wait : {err}") + print(f"*** error in wait : {err}", flush=True) + raise err finally: if waited and isatty: print(flush=True) + LOGGER.info(f"wait result: {result}") return result[2] diff --git a/src/integration-tests/integration-test.py b/src/integration-tests/integration-test.py index 5d2e6809a9..0dd76254cc 100755 --- a/src/integration-tests/integration-test.py +++ b/src/integration-tests/integration-test.py @@ -35,7 +35,7 @@ import requests import yaml -from onefuzztypes.enums import OS, ContainerType, ScalesetState, TaskState, VmState +from onefuzztypes.enums import OS, ContainerType, ErrorCode, ScalesetState, TaskState, VmState from onefuzztypes.models import Job, Pool, Repro, Scaleset, Task from onefuzztypes.primitives import Container, Directory, File, PoolName, Region from pydantic import BaseModel, Field @@ -787,6 +787,9 @@ def check_task( # check if the task itself has an error if task.error is not None: + if task.error == ErrorCode.TASK_CANCELLED: + return TaskTestState.stopped + self.logger.error( "task failed: %s - %s (%s) - %s", job.config.name, @@ -861,6 +864,7 @@ def check_jobs_impl() -> Tuple[bool, str, bool]: job_task_states: Dict[UUID, Set[TaskTestState]] = {} if datetime.datetime.utcnow() - start > timeout: + self.logger.info("timed out while checking jobs") return (True, "timed out while checking jobs", False) for job_id in check_containers: @@ -944,7 +948,11 @@ def check_jobs_impl() -> Tuple[bool, str, bool]: for job_id in to_remove: if stop_on_complete_check: - self.stop_job(jobs[job_id]) + try: + self.stop_job(jobs[job_id]) + except Exception as err: + self.logger.error("unable to stop job: %s", err) + return (True, str(err), False) del jobs[job_id] msg = "waiting on: %s" % ",".join( @@ -1311,7 +1319,7 @@ def check_jobs( job_ids=job_ids, ) if not result: - raise Exception("jobs failed") + raise Exception("jobs failed !!!!!") def setup( self, @@ -1432,6 +1440,11 @@ def check_results( test_id: UUID, job_ids: List[UUID] = [], ) -> None: + if job_ids: + self.logger.info(f"checking results for jobs: {job_ids}", ) + else: + self.logger.info("checking results for all jobs") + self.check_jobs( test_id, endpoint=endpoint,