From 131637883cb99cd505a07630a988394b6ccd8d27 Mon Sep 17 00:00:00 2001 From: Cheick Keita Date: Tue, 16 May 2023 11:59:43 -0700 Subject: [PATCH 01/10] testing --- src/ApiService/ApiService/Functions/Jobs.cs | 2 + src/ApiService/ApiService/Log.cs | 10 -- src/ApiService/ApiService/Program.cs | 105 ++++++++++++++++++-- src/cli/onefuzz/backend.py | 2 + 4 files changed, 100 insertions(+), 19 deletions(-) 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/cli/onefuzz/backend.py b/src/cli/onefuzz/backend.py index 7f23e7de03..387703e64b 100644 --- a/src/cli/onefuzz/backend.py +++ b/src/cli/onefuzz/backend.py @@ -345,6 +345,8 @@ def config_params( response = self.session.request("GET", endpoint + "/api/config") + print(response) + endpoint_params = responses.Config.parse_obj(response.json()) # Will override values in storage w/ provided values for SP use From 2ef7b2b3fab72ad21a9720d6aca663a021c176fb Mon Sep 17 00:00:00 2001 From: Cheick Keita Date: Tue, 17 Oct 2023 16:03:53 -0700 Subject: [PATCH 02/10] fix --- src/cli/onefuzz/backend.py | 2 -- 1 file changed, 2 deletions(-) diff --git a/src/cli/onefuzz/backend.py b/src/cli/onefuzz/backend.py index 387703e64b..7f23e7de03 100644 --- a/src/cli/onefuzz/backend.py +++ b/src/cli/onefuzz/backend.py @@ -345,8 +345,6 @@ def config_params( response = self.session.request("GET", endpoint + "/api/config") - print(response) - endpoint_params = responses.Config.parse_obj(response.json()) # Will override values in storage w/ provided values for SP use From 13012592b6982d814d00656cdc1a18b205848789 Mon Sep 17 00:00:00 2001 From: Cheick Keita Date: Wed, 18 Oct 2023 10:48:48 -0700 Subject: [PATCH 03/10] logging stop jobs error in the integration test --- src/integration-tests/integration-test.py | 5 ++++- 1 file changed, 4 insertions(+), 1 deletion(-) diff --git a/src/integration-tests/integration-test.py b/src/integration-tests/integration-test.py index 5d2e6809a9..4070f0c542 100755 --- a/src/integration-tests/integration-test.py +++ b/src/integration-tests/integration-test.py @@ -944,7 +944,10 @@ 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: + return (True, str(err), False) del jobs[job_id] msg = "waiting on: %s" % ",".join( From 37ec441d45660f8162fc9cb3fc4725cf759bad24 Mon Sep 17 00:00:00 2001 From: Cheick Keita Date: Wed, 18 Oct 2023 11:38:41 -0700 Subject: [PATCH 04/10] more logging --- src/cli/onefuzz/backend.py | 5 ++++- 1 file changed, 4 insertions(+), 1 deletion(-) diff --git a/src/cli/onefuzz/backend.py b/src/cli/onefuzz/backend.py index 7f23e7de03..21b96231a0 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 @@ -635,6 +635,9 @@ def wait(func: Callable[[], Tuple[bool, str, A]], frequency: float = 1.0) -> A: waited = True time.sleep(frequency) frames.sort(key=frames[0].__eq__) + except Exception as err: + print(f"*** error in wait : {err}", flush=True) + raise err finally: if waited and isatty: print(flush=True) From 9e840199f332856354050736fca45d6a2776e1f6 Mon Sep 17 00:00:00 2001 From: Cheick Keita Date: Wed, 18 Oct 2023 19:12:57 -0700 Subject: [PATCH 05/10] more logging --- src/cli/onefuzz/backend.py | 6 +++++- src/integration-tests/integration-test.py | 1 + 2 files changed, 6 insertions(+), 1 deletion(-) diff --git a/src/cli/onefuzz/backend.py b/src/cli/onefuzz/backend.py index 21b96231a0..133694e102 100644 --- a/src/cli/onefuzz/backend.py +++ b/src/cli/onefuzz/backend.py @@ -623,19 +623,23 @@ 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: diff --git a/src/integration-tests/integration-test.py b/src/integration-tests/integration-test.py index 4070f0c542..1d50b5a42a 100755 --- a/src/integration-tests/integration-test.py +++ b/src/integration-tests/integration-test.py @@ -947,6 +947,7 @@ def check_jobs_impl() -> Tuple[bool, str, bool]: 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] From aef1c37c98149077ec80c260f646b8bab72fb63c Mon Sep 17 00:00:00 2001 From: Cheick Keita Date: Wed, 18 Oct 2023 20:36:44 -0700 Subject: [PATCH 06/10] more logs --- src/cli/onefuzz/backend.py | 1 + src/integration-tests/integration-test.py | 3 ++- 2 files changed, 3 insertions(+), 1 deletion(-) diff --git a/src/cli/onefuzz/backend.py b/src/cli/onefuzz/backend.py index 133694e102..45c14fcc9c 100644 --- a/src/cli/onefuzz/backend.py +++ b/src/cli/onefuzz/backend.py @@ -646,4 +646,5 @@ def wait(func: Callable[[], Tuple[bool, str, A]], frequency: float = 1.0) -> A: 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 1d50b5a42a..bcb8595507 100755 --- a/src/integration-tests/integration-test.py +++ b/src/integration-tests/integration-test.py @@ -861,6 +861,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: @@ -1315,7 +1316,7 @@ def check_jobs( job_ids=job_ids, ) if not result: - raise Exception("jobs failed") + raise Exception("jobs failed !!!!!") def setup( self, From 61cb95fb0b8318f41eff32d02f55001c4f7100ac Mon Sep 17 00:00:00 2001 From: Cheick Keita Date: Thu, 19 Oct 2023 10:52:47 -0700 Subject: [PATCH 07/10] more logging --- src/ApiService/ApiService/onefuzzlib/JobOperations.cs | 1 + 1 file changed, 1 insertion(+) 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); From 787de6de442a1b179d8aeee5b542f9395b657cc5 Mon Sep 17 00:00:00 2001 From: Cheick Keita Date: Thu, 19 Oct 2023 13:34:58 -0700 Subject: [PATCH 08/10] don't fail on cancelled task --- src/integration-tests/integration-test.py | 5 ++++- 1 file changed, 4 insertions(+), 1 deletion(-) diff --git a/src/integration-tests/integration-test.py b/src/integration-tests/integration-test.py index bcb8595507..2503ffe182 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, From b0da11dc78826fbe3bd9f8a581d7f4679da576dd Mon Sep 17 00:00:00 2001 From: Cheick Keita Date: Thu, 19 Oct 2023 16:21:46 -0700 Subject: [PATCH 09/10] kanan's fix --- src/agent/onefuzz-task/src/tasks/report/dotnet/generic.rs | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) 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)?; From 18678177f0c66fafe12d8e77f20363757d8ae6f7 Mon Sep 17 00:00:00 2001 From: Cheick Keita Date: Thu, 19 Oct 2023 18:42:37 -0700 Subject: [PATCH 10/10] more logs --- src/integration-tests/integration-test.py | 5 +++++ 1 file changed, 5 insertions(+) diff --git a/src/integration-tests/integration-test.py b/src/integration-tests/integration-test.py index 2503ffe182..0dd76254cc 100755 --- a/src/integration-tests/integration-test.py +++ b/src/integration-tests/integration-test.py @@ -1440,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,