Skip to content
This repository has been archived by the owner on Nov 1, 2023. It is now read-only.

Port current implementation to ILogger #3173

Merged
merged 8 commits into from
Jun 7, 2023
Merged

Port current implementation to ILogger #3173

Show file tree
Hide file tree
Changes from 6 commits
Commits
Show all changes
8 commits
Select commit Hold shift + click to select a range
4b07e26
Port logging to ILogger
Jun 1, 2023
4c4832d
addressing pr comments
Jun 6, 2023
d2ed37f
enable tracking telemetry
Jun 6, 2023
71b98c2
solving merge conflicts
Jun 7, 2023
257e0e3
if debug enable developer mode
Jun 7, 2023
a2054f8
format
Jun 7, 2023
d89abc4
resolving more merging issues
Jun 7, 2023
e25e8e3
add reference links to comments
Jun 7, 2023
File filter

Filter by extension

Filter by extension
Conversations
Failed to load comments.
Loading
Jump to
Jump to file
Failed to load files.
Loading
Diff view
Diff view
9 changes: 6 additions & 3 deletions src/ApiService/ApiService/ApiService.csproj
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -8,7 +8,10 @@
<ItemGroup>
<PackageReference Include="Azure.ResourceManager.Monitor" Version="1.0.0-beta.2" />
<PackageReference Include="Faithlife.Utility" Version="0.12.2" />
<PackageReference Include="Microsoft.Azure.Functions.Worker.ApplicationInsights" Version="1.0.0-preview3" />

<PackageReference Include="Microsoft.Extensions.Logging.ApplicationInsights" Version="2.21.0" />
<PackageReference Include="Microsoft.Azure.Functions.Worker.ApplicationInsights" Version="1.0.0-preview4" />

<PackageReference Include="Semver" Version="2.1.0" />
<PackageReference Include="Azure.Security.KeyVault.Secrets" Version="4.3.0" />
<PackageReference Include="Microsoft.Azure.AppConfiguration.Functions.Worker" Version="6.0.0" />
Expand All @@ -23,8 +26,8 @@
<PackageReference Include="Microsoft.Azure.Management.OperationalInsights" Version="0.24.0-preview" />
<PackageReference Include="Microsoft.Azure.Management.Monitor" Version="0.28.0-preview" />

<PackageReference Include="Microsoft.Azure.Functions.Worker.Sdk" Version="1.7.0" OutputItemType="Analyzer" />
<PackageReference Include="Microsoft.Azure.Functions.Worker" Version="1.10.0" />
<PackageReference Include="Microsoft.Azure.Functions.Worker.Sdk" Version="1.10.0" OutputItemType="Analyzer" />
<PackageReference Include="Microsoft.Azure.Functions.Worker" Version="1.14.1" />
<PackageReference Include="Azure.Data.Tables" Version="12.8.0" />
<PackageReference Include="Azure.ResourceManager.Compute" Version="1.0.0-beta.8" />
<PackageReference Include="Azure.Identity" Version="1.8.2" />
Expand Down
7 changes: 4 additions & 3 deletions src/ApiService/ApiService/Auth/AuthenticationMiddleware.cs
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -4,14 +4,15 @@
using Microsoft.Azure.Functions.Worker;
using Microsoft.Azure.Functions.Worker.Http;
using Microsoft.Azure.Functions.Worker.Middleware;
using Microsoft.Extensions.Logging;

namespace Microsoft.OneFuzz.Service.Auth;

public sealed class AuthenticationMiddleware : IFunctionsWorkerMiddleware {
private readonly IConfigOperations _config;
private readonly ILogTracer _log;
private readonly ILogger _log;

public AuthenticationMiddleware(IConfigOperations config, ILogTracer log) {
public AuthenticationMiddleware(IConfigOperations config, ILogger<AuthenticationMiddleware> log) {
_config = config;
_log = log;
}
Expand Down Expand Up @@ -64,7 +65,7 @@ private async Async.ValueTask BadIssuer(
IEnumerable<string> allowedTenants) {

var tenantsStr = string.Join("; ", allowedTenants);
_log.Error($"issuer not from allowed tenant. issuer: {token.Issuer:Tag:Issuer} - tenants: {tenantsStr:Tag:Tenants}");
_log.LogError($"issuer not from allowed tenant. issuer: {token.Issuer:Tag:Issuer} - tenants: {tenantsStr:Tag:Tenants}");

var response = HttpResponseData.CreateResponse(request);
var status = HttpStatusCode.BadRequest;
Expand Down
6 changes: 3 additions & 3 deletions src/ApiService/ApiService/Auth/AuthorizationMiddleware.cs
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -5,14 +5,14 @@
using Microsoft.Azure.Functions.Worker;
using Microsoft.Azure.Functions.Worker.Http;
using Microsoft.Azure.Functions.Worker.Middleware;

using Microsoft.Extensions.Logging;
namespace Microsoft.OneFuzz.Service.Auth;

public sealed class AuthorizationMiddleware : IFunctionsWorkerMiddleware {
private readonly IEndpointAuthorization _auth;
private readonly ILogTracer _log;
private readonly ILogger _log;

public AuthorizationMiddleware(IEndpointAuthorization auth, ILogTracer log) {
public AuthorizationMiddleware(IEndpointAuthorization auth, ILogger<AuthorizationMiddleware> log) {
_auth = auth;
_log = log;
}
Expand Down
29 changes: 16 additions & 13 deletions src/ApiService/ApiService/Functions/AgentCanSchedule.cs
View file
Open in desktop
Original file line number Diff line number Diff line change
@@ -1,14 +1,14 @@
using Microsoft.Azure.Functions.Worker;
using Microsoft.Azure.Functions.Worker.Http;
using Microsoft.Extensions.Logging;
using Microsoft.OneFuzz.Service.Auth;

namespace Microsoft.OneFuzz.Service.Functions;

public class AgentCanSchedule {
private readonly ILogTracer _log;
private readonly ILogger _log;
private readonly IOnefuzzContext _context;

public AgentCanSchedule(ILogTracer log, IOnefuzzContext context) {
public AgentCanSchedule(ILogger<AgentCanSchedule> log, IEndpointAuthorization auth, IOnefuzzContext context) {
_log = log;
_context = context;
}
Expand All @@ -20,15 +20,15 @@ public async Async.Task<HttpResponseData> Run(
HttpRequestData req) {
var request = await RequestHandling.ParseRequest<CanScheduleRequest>(req);
if (!request.IsOk) {
_log.Warning($"Cannot schedule due to {request.ErrorV}");
_log.LogWarning("Cannot schedule due to {error}", request.ErrorV);
return await _context.RequestHandling.NotOk(req, request.ErrorV, typeof(CanScheduleRequest).ToString());
}

var canScheduleRequest = request.OkV;

var node = await _context.NodeOperations.GetByMachineId(canScheduleRequest.MachineId);
if (node == null) {
_log.Warning($"Unable to find {canScheduleRequest.MachineId:Tag:MachineId}");
_log.LogWarning("Unable to find {MachineId}", canScheduleRequest.MachineId);
return await _context.RequestHandling.NotOk(
req,
Error.Create(ErrorCode.UNABLE_TO_FIND, "unable to find node"),
Expand All @@ -43,29 +43,32 @@ public async Async.Task<HttpResponseData> Run(
var task = await _context.TaskOperations.GetByTaskId(canScheduleRequest.TaskId);
var workStopped = task == null || task.State.ShuttingDown();
if (!allowed) {
_log.Info($"Node cannot process new work {node.PoolName:Tag:PoolName} {node.ScalesetId:Tag:ScalesetId} - {node.MachineId:Tag:MachineId} ");
_log.LogInformation("Node cannot process new work {PoolName} {ScalesetId} - {MachineId} ", node.PoolName, node.ScalesetId, node.MachineId);
return await RequestHandling.Ok(req, new CanSchedule(Allowed: allowed, WorkStopped: workStopped, Reason: reason));
}

if (workStopped) {
_log.Info($"Work stopped for: {canScheduleRequest.MachineId:Tag:MachineId} and {canScheduleRequest.TaskId:Tag:TaskId}");
_log.LogInformation("Work stopped for: {MachineId} and {TaskId}", canScheduleRequest.MachineId, canScheduleRequest.TaskId);
return await RequestHandling.Ok(req, new CanSchedule(Allowed: false, WorkStopped: workStopped, Reason: "Work stopped"));
}

var scp = await _context.NodeOperations.AcquireScaleInProtection(node);
if (!scp.IsOk) {
_log.Warning($"Failed to acquire scale in protection for: {node.MachineId:Tag:MachineId} in: {node.PoolName:Tag:PoolName} due to {scp.ErrorV:Tag:Error}");
_log.LogWarning("Failed to acquire scale in protection for: {MachineId} in: {PoolName} due to {Error}", node.MachineId, node.PoolName, scp.ErrorV);
}
_ = scp.OkV; // node could be updated but we don't use it after this
allowed = scp.IsOk;

if (allowed) {
_log.Metric($"TaskAllowedToSchedule", 1, new Dictionary<string, string> {
{"MachineId", node.MachineId.ToString()},
{"TaskId", task is not null ? task.TaskId.ToString() : string.Empty}
});
using (_log.BeginScope("TaskAllowedToSchedule")) {
_log.AddTags(
new Dictionary<string, string> {
{"MachineId", node.MachineId.ToString()},
{"TaskId", task is not null ? task.TaskId.ToString() : string.Empty} }
);
_log.LogMetric("TaskAllowedToSchedule", 1);
}
}

return await RequestHandling.Ok(req, new CanSchedule(Allowed: allowed, WorkStopped: workStopped, Reason: reason));
}
}
10 changes: 5 additions & 5 deletions src/ApiService/ApiService/Functions/AgentCommands.cs
View file
Open in desktop
Original file line number Diff line number Diff line change
@@ -1,14 +1,14 @@
using Microsoft.Azure.Functions.Worker;
using Microsoft.Azure.Functions.Worker.Http;
using Microsoft.Extensions.Logging;
using Microsoft.OneFuzz.Service.Auth;

namespace Microsoft.OneFuzz.Service.Functions;

public class AgentCommands {
private readonly ILogTracer _log;
private readonly ILogger _log;
private readonly IOnefuzzContext _context;

public AgentCommands(ILogTracer log, IOnefuzzContext context) {
public AgentCommands(ILogger log, IOnefuzzContext context) {
_log = log;
_context = context;
}
Expand Down Expand Up @@ -53,9 +53,9 @@ private async Async.Task<HttpResponseData> Delete(HttpRequestData req) {
if (message != null) {
await _context.NodeMessageOperations.Delete(message).IgnoreResult();
} else {
_log.WithTag("HttpRequest", "DELETE").Verbose($"failed to find {nodeCommand.MachineId:Tag:MachineId} for {nodeCommand.MessageId:Tag:MessageId}");
_log.AddTag("HttpRequest", "DELETE");
_log.LogDebug("failed to find {MachineId} for {MessageId}", nodeCommand.MachineId, nodeCommand.MessageId);
}

return await RequestHandling.Ok(req, new BoolResult(true));
}
}
50 changes: 29 additions & 21 deletions src/ApiService/ApiService/Functions/AgentEvents.cs
View file
Open in desktop
Original file line number Diff line number Diff line change
@@ -1,16 +1,16 @@
using System.Threading.Tasks;
using Microsoft.Azure.Functions.Worker;
using Microsoft.Azure.Functions.Worker.Http;
using Microsoft.Extensions.Logging;
using Microsoft.OneFuzz.Service.Auth;
using Microsoft.OneFuzz.Service.OneFuzzLib.Orm;

namespace Microsoft.OneFuzz.Service.Functions;

public class AgentEvents {
private readonly ILogTracer _log;
private readonly ILogger _log;
private readonly IOnefuzzContext _context;

public AgentEvents(ILogTracer log, IOnefuzzContext context) {
public AgentEvents(ILogger<AgentEvents> log, IOnefuzzContext context) {
_log = log;
_context = context;
}
Expand All @@ -26,7 +26,8 @@ public async Async.Task<HttpResponseData> Run(
}

var envelope = request.OkV;
_log.WithTag("HttpRequest", "POST").Info($"node event: {envelope.MachineId:Tag:MachineId} {EntityConverter.ToJsonString(envelope):Tag:Event}");
_log.AddTag("HttpRequest", "POST");
_log.LogInformation("node event: {MachineId} {Event}", envelope.MachineId, EntityConverter.ToJsonString(envelope));

var error = envelope.Event switch {
NodeStateUpdate updateEvent => await OnStateUpdate(envelope.MachineId, updateEvent),
Expand Down Expand Up @@ -63,7 +64,7 @@ public async Async.Task<HttpResponseData> Run(
private async Async.Task<Error?> OnStateUpdate(Guid machineId, NodeStateUpdate ev) {
var node = await _context.NodeOperations.GetByMachineId(machineId);
if (node is null) {
_log.Warning($"unable to process state update event. {machineId:Tag:MachineId} {ev:Tag:Event}");
_log.LogWarning("unable to process state update event. {MachineId} {Event}", machineId, ev);
return null;
}

Expand All @@ -72,14 +73,14 @@ public async Async.Task<HttpResponseData> Run(
if (!node.Managed) {
return null;
}
_log.Info($"stopping free node with reset flags: {machineId:Tag:MachineId}");
_log.LogInformation("stopping free node with reset flags: {MachineId}", machineId);
// discard result: node not used after this point
_ = await _context.NodeOperations.Stop(node);
return null;
}

if (await _context.NodeOperations.CouldShrinkScaleset(node)) {
_log.Info($"stopping free node to resize scaleset: {machineId:Tag:MachineId}");
_log.LogInformation("stopping free node to resize scaleset: {MachineId}", machineId);
// discard result: node not used after this point
_ = await _context.NodeOperations.SetHalt(node);
return null;
Expand All @@ -88,7 +89,7 @@ public async Async.Task<HttpResponseData> Run(

if (ev.State == NodeState.Init) {
if (node.DeleteRequested) {
_log.Info($"stopping node (init and delete_requested): {machineId:Tag:MachineId}");
_log.LogInformation("stopping node (init and delete_requested): {MachineId}", machineId);
// discard result: node not used after this point
_ = await _context.NodeOperations.Stop(node);
return null;
Expand All @@ -106,7 +107,7 @@ public async Async.Task<HttpResponseData> Run(
node = await _context.NodeOperations.SetState(node, ev.State);

if (ev.State == NodeState.Free) {
_log.Info($"node now available for work: {machineId:Tag:MachineId}");
_log.LogInformation("node now available for work: {MachineId}", machineId);
} else if (ev.State == NodeState.SettingUp) {
if (ev.Data is NodeSettingUpEventData settingUpData) {
if (!settingUpData.Tasks.Any()) {
Expand All @@ -123,7 +124,7 @@ public async Async.Task<HttpResponseData> Run(
$"unable to find task: {taskId}");
}

_log.Info($"node starting task. {machineId:Tag:MachineId} {task.JobId:Tag:JobId} {task.TaskId:Tag:TaskId}");
_log.LogInformation("node starting task. {MachineId} {JobId} {TaskId}", machineId, task.JobId, task.TaskId);

// The task state may be `running` if it has `vm_count` > 1, and
// another node is concurrently executing the task. If so, leave
Expand All @@ -141,7 +142,8 @@ public async Async.Task<HttpResponseData> Run(
State: NodeTaskState.SettingUp);
var r = await _context.NodeTasksOperations.Replace(nodeTask);
if (!r.IsOk) {
_log.WithHttpStatus(r.ErrorV).Error($"Failed to replace node task {task.TaskId:Tag:TaskId}");
_log.AddHttpStatus(r.ErrorV);
_log.LogError("Failed to replace node task {TaskId}", task.TaskId);
}
}
}
Expand All @@ -151,7 +153,7 @@ public async Async.Task<HttpResponseData> Run(
if (doneData.Error is not null) {
var errorText = EntityConverter.ToJsonString(doneData);
error = Error.Create(ErrorCode.TASK_FAILED, errorText);
_log.Error($"node 'done' {machineId:Tag:MachineId} - {errorText:Tag:Error}");
_log.LogError("node 'done' {MachineId} - {Error}", machineId, errorText);
}
}

Expand Down Expand Up @@ -203,15 +205,16 @@ public async Async.Task<HttpResponseData> Run(
State: NodeTaskState.Running);
var r = await _context.NodeTasksOperations.Replace(nodeTask);
if (!r.IsOk) {
_log.WithHttpStatus(r.ErrorV).Error($"failed to replace node task {nodeTask.TaskId:Tag:TaskId}");
_log.AddHttpStatus(r.ErrorV);
_log.LogError("failed to replace node task {TaskId}", nodeTask.TaskId);
}

if (task.State.ShuttingDown()) {
_log.Info($"ignoring task start from node. {machineId:Tag:MachineId} {task.JobId:Tag:JobId} {task.TaskId:Tag:TaskId} ({task.State:Tag:State})");
_log.LogInformation("ignoring task start from node. {MachineId} {JobId} {TaskId} ({State})", machineId, task.JobId, task.TaskId, task.State);
return null;
}

_log.Info($"task started on node. {machineId:Tag:MachineId} {task.JobId:Tag:JobId} {task.TaskId:Tag:TaskId}");
_log.LogInformation("task started on node. {MachineId} {JobId} {TaskId}", machineId, task.JobId, task.TaskId);
task = await _context.TaskOperations.SetState(task, TaskState.Running);

var taskEvent = new TaskEvent(
Expand All @@ -220,7 +223,8 @@ public async Async.Task<HttpResponseData> Run(
EventData: new WorkerEvent(Running: running));
r = await _context.TaskEventOperations.Replace(taskEvent);
if (!r.IsOk) {
_log.WithHttpStatus(r.ErrorV).Error($"failed to replace taskEvent {taskEvent.TaskId:Tag:TaskId}");
_log.AddHttpStatus(r.ErrorV);
_log.LogError("failed to replace taskEvent {TaskId}", taskEvent.TaskId);
}

return null;
Expand All @@ -246,15 +250,16 @@ public async Async.Task<HttpResponseData> Run(
};

if (done.ExitStatus.Success) {
_log.Info($"task done. {task.JobId:Tag:JobId}:{task.TaskId:Tag:TaskId} {done.ExitStatus:Tag:Status}");
_log.LogInformation("task done. {JobId}:{TaskId} {Status}", task.JobId, task.TaskId, done.ExitStatus);
await _context.TaskOperations.MarkStopping(task, "task is done");

// keep node if keep-on-completion is set
if (task.Config.Debug?.Contains(TaskDebugFlag.KeepNodeOnCompletion) == true) {
node = node with { DebugKeepNode = true };
var r = await _context.NodeOperations.Replace(node);
if (!r.IsOk) {
_log.WithHttpStatus(r.ErrorV).Error($"keepNodeOnCompletion: failed to replace node {node.MachineId:Tag:MachineId} when setting debug keep node to true");
_log.AddHttpStatus(r.ErrorV);
_log.LogError("keepNodeOnCompletion: failed to replace node {MachineId} when setting debug keep node to true", node.MachineId);
}
}
} else {
Expand All @@ -273,22 +278,25 @@ await _context.TaskOperations.MarkFailed(
node = node with { DebugKeepNode = true };
var r = await _context.NodeOperations.Replace(node);
if (!r.IsOk) {
_log.WithHttpStatus(r.ErrorV).Error($"keepNodeOnfFailure: failed to replace node {node.MachineId:Tag:MachineId} when setting debug keep node to true");
_log.AddHttpStatus(r.ErrorV);
_log.LogError("keepNodeOnfFailure: failed to replace node {MachineId} when setting debug keep node to true", node.MachineId);
}
}
}

if (!node.DebugKeepNode) {
var r = await _context.NodeTasksOperations.Delete(new NodeTasks(machineId, done.TaskId));
if (!r.IsOk) {
_log.WithHttpStatus(r.ErrorV).Error($"failed to deleting node task {done.TaskId:Tag:TaskId} for: {machineId:Tag:MachineId} since DebugKeepNode is false");
_log.AddHttpStatus(r.ErrorV);
_log.LogError("failed to deleting node task {TaskId} for: {MachineId} since DebugKeepNode is false", done.TaskId, machineId);
}
}

var taskEvent = new TaskEvent(done.TaskId, machineId, new WorkerEvent { Done = done });
var r1 = await _context.TaskEventOperations.Replace(taskEvent);
if (!r1.IsOk) {
_log.WithHttpStatus(r1.ErrorV).Error($"failed to update task event for done task {done.TaskId:Tag:TaskId}");
_log.AddHttpStatus(r1.ErrorV);
_log.LogError("failed to update task event for done task {TaskId}", done.TaskId);
}
return null;
}
Expand Down
Loading