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

Commit f724741

Browse files
stishkinstas
stishkin
and
stas
authored
Port current implementation to ILogger (#3173)
* Port logging to ILogger * addressing pr comments * enable tracking telemetry * solving merge conflicts * if debug enable developer mode * format * resolving more merging issues * add reference links to comments --------- Co-authored-by: stas <statis@microsoft.com>
1 parent 8e2e11f commit f724741

File tree

122 files changed

+1989
-1578
lines changed

Some content is hidden

Large Commits have some content hidden by default. Use the searchbox below for content that may be hidden.

122 files changed

+1989
-1578
lines changed

‎src/ApiService/ApiService/ApiService.csproj‎

Lines changed: 6 additions & 3 deletions
Original file line numberDiff line numberDiff line change
@@ -8,7 +8,10 @@
88
<ItemGroup>
99
<PackageReference Include="Azure.ResourceManager.Monitor" Version="1.0.0-beta.2" />
1010
<PackageReference Include="Faithlife.Utility" Version="0.12.2" />
11-
<PackageReference Include="Microsoft.Azure.Functions.Worker.ApplicationInsights" Version="1.0.0-preview3" />
11+
12+
<PackageReference Include="Microsoft.Extensions.Logging.ApplicationInsights" Version="2.21.0" />
13+
<PackageReference Include="Microsoft.Azure.Functions.Worker.ApplicationInsights" Version="1.0.0-preview4" />
14+
1215
<PackageReference Include="Semver" Version="2.1.0" />
1316
<PackageReference Include="Azure.Security.KeyVault.Secrets" Version="4.3.0" />
1417
<PackageReference Include="Microsoft.Azure.AppConfiguration.Functions.Worker" Version="6.0.0" />
@@ -23,8 +26,8 @@
2326
<PackageReference Include="Microsoft.Azure.Management.OperationalInsights" Version="0.24.0-preview" />
2427
<PackageReference Include="Microsoft.Azure.Management.Monitor" Version="0.28.0-preview" />
2528

26-
<PackageReference Include="Microsoft.Azure.Functions.Worker.Sdk" Version="1.7.0" OutputItemType="Analyzer" />
27-
<PackageReference Include="Microsoft.Azure.Functions.Worker" Version="1.10.0" />
29+
<PackageReference Include="Microsoft.Azure.Functions.Worker.Sdk" Version="1.10.0" OutputItemType="Analyzer" />
30+
<PackageReference Include="Microsoft.Azure.Functions.Worker" Version="1.14.1" />
2831
<PackageReference Include="Azure.Data.Tables" Version="12.8.0" />
2932
<PackageReference Include="Azure.ResourceManager.Compute" Version="1.0.0-beta.8" />
3033
<PackageReference Include="Azure.Identity" Version="1.8.2" />

‎src/ApiService/ApiService/Auth/AuthenticationMiddleware.cs‎

Lines changed: 4 additions & 3 deletions
Original file line numberDiff line numberDiff line change
@@ -4,14 +4,15 @@
44
using Microsoft.Azure.Functions.Worker;
55
using Microsoft.Azure.Functions.Worker.Http;
66
using Microsoft.Azure.Functions.Worker.Middleware;
7+
using Microsoft.Extensions.Logging;
78

89
namespace Microsoft.OneFuzz.Service.Auth;
910

1011
public sealed class AuthenticationMiddleware : IFunctionsWorkerMiddleware {
1112
private readonly IConfigOperations _config;
12-
private readonly ILogTracer _log;
13+
private readonly ILogger _log;
1314

14-
public AuthenticationMiddleware(IConfigOperations config, ILogTracer log) {
15+
public AuthenticationMiddleware(IConfigOperations config, ILogger<AuthenticationMiddleware> log) {
1516
_config = config;
1617
_log = log;
1718
}
@@ -64,7 +65,7 @@ private async Async.ValueTask BadIssuer(
6465
IEnumerable<string> allowedTenants) {
6566

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

6970
var response = HttpResponseData.CreateResponse(request);
7071
var status = HttpStatusCode.BadRequest;

‎src/ApiService/ApiService/Auth/AuthorizationMiddleware.cs‎

Lines changed: 3 additions & 3 deletions
Original file line numberDiff line numberDiff line change
@@ -5,14 +5,14 @@
55
using Microsoft.Azure.Functions.Worker;
66
using Microsoft.Azure.Functions.Worker.Http;
77
using Microsoft.Azure.Functions.Worker.Middleware;
8-
8+
using Microsoft.Extensions.Logging;
99
namespace Microsoft.OneFuzz.Service.Auth;
1010

1111
public sealed class AuthorizationMiddleware : IFunctionsWorkerMiddleware {
1212
private readonly IEndpointAuthorization _auth;
13-
private readonly ILogTracer _log;
13+
private readonly ILogger _log;
1414

15-
public AuthorizationMiddleware(IEndpointAuthorization auth, ILogTracer log) {
15+
public AuthorizationMiddleware(IEndpointAuthorization auth, ILogger<AuthorizationMiddleware> log) {
1616
_auth = auth;
1717
_log = log;
1818
}

‎src/ApiService/ApiService/Functions/AgentCanSchedule.cs‎

Lines changed: 16 additions & 13 deletions
Original file line numberDiff line numberDiff line change
@@ -1,14 +1,14 @@
11
using Microsoft.Azure.Functions.Worker;
22
using Microsoft.Azure.Functions.Worker.Http;
3+
using Microsoft.Extensions.Logging;
34
using Microsoft.OneFuzz.Service.Auth;
4-
55
namespace Microsoft.OneFuzz.Service.Functions;
66

77
public class AgentCanSchedule {
8-
private readonly ILogTracer _log;
8+
private readonly ILogger _log;
99
private readonly IOnefuzzContext _context;
1010

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

2727
var canScheduleRequest = request.OkV;
2828

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

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

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

6262
if (allowed) {
63-
_log.Metric($"TaskAllowedToSchedule", 1, new Dictionary<string, string> {
64-
{"MachineId", node.MachineId.ToString()},
65-
{"TaskId", task is not null ? task.TaskId.ToString() : string.Empty}
66-
});
63+
using (_log.BeginScope("TaskAllowedToSchedule")) {
64+
_log.AddTags(
65+
new Dictionary<string, string> {
66+
{"MachineId", node.MachineId.ToString()},
67+
{"TaskId", task is not null ? task.TaskId.ToString() : string.Empty} }
68+
);
69+
_log.LogMetric("TaskAllowedToSchedule", 1);
70+
}
6771
}
68-
6972
return await RequestHandling.Ok(req, new CanSchedule(Allowed: allowed, WorkStopped: workStopped, Reason: reason));
7073
}
7174
}

‎src/ApiService/ApiService/Functions/AgentCommands.cs‎

Lines changed: 5 additions & 5 deletions
Original file line numberDiff line numberDiff line change
@@ -1,14 +1,14 @@
11
using Microsoft.Azure.Functions.Worker;
22
using Microsoft.Azure.Functions.Worker.Http;
3+
using Microsoft.Extensions.Logging;
34
using Microsoft.OneFuzz.Service.Auth;
4-
55
namespace Microsoft.OneFuzz.Service.Functions;
66

77
public class AgentCommands {
8-
private readonly ILogTracer _log;
8+
private readonly ILogger _log;
99
private readonly IOnefuzzContext _context;
1010

11-
public AgentCommands(ILogTracer log, IOnefuzzContext context) {
11+
public AgentCommands(ILogger<AgentCommands> log, IOnefuzzContext context) {
1212
_log = log;
1313
_context = context;
1414
}
@@ -53,9 +53,9 @@ private async Async.Task<HttpResponseData> Delete(HttpRequestData req) {
5353
if (message != null) {
5454
await _context.NodeMessageOperations.Delete(message).IgnoreResult();
5555
} else {
56-
_log.WithTag("HttpRequest", "DELETE").Verbose($"failed to find {nodeCommand.MachineId:Tag:MachineId} for {nodeCommand.MessageId:Tag:MessageId}");
56+
_log.AddTag("HttpRequest", "DELETE");
57+
_log.LogDebug("failed to find {MachineId} for {MessageId}", nodeCommand.MachineId, nodeCommand.MessageId);
5758
}
58-
5959
return await RequestHandling.Ok(req, new BoolResult(true));
6060
}
6161
}

‎src/ApiService/ApiService/Functions/AgentEvents.cs‎

Lines changed: 29 additions & 21 deletions
Original file line numberDiff line numberDiff line change
@@ -1,16 +1,16 @@
11
using System.Threading.Tasks;
22
using Microsoft.Azure.Functions.Worker;
33
using Microsoft.Azure.Functions.Worker.Http;
4+
using Microsoft.Extensions.Logging;
45
using Microsoft.OneFuzz.Service.Auth;
56
using Microsoft.OneFuzz.Service.OneFuzzLib.Orm;
6-
77
namespace Microsoft.OneFuzz.Service.Functions;
88

99
public class AgentEvents {
10-
private readonly ILogTracer _log;
10+
private readonly ILogger _log;
1111
private readonly IOnefuzzContext _context;
1212

13-
public AgentEvents(ILogTracer log, IOnefuzzContext context) {
13+
public AgentEvents(ILogger<AgentEvents> log, IOnefuzzContext context) {
1414
_log = log;
1515
_context = context;
1616
}
@@ -26,7 +26,8 @@ public async Async.Task<HttpResponseData> Run(
2626
}
2727

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

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

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

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

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

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

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

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

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

209212
if (task.State.ShuttingDown()) {
210-
_log.Info($"ignoring task start from node. {machineId:Tag:MachineId} {task.JobId:Tag:JobId} {task.TaskId:Tag:TaskId} ({task.State:Tag:State})");
213+
_log.LogInformation("ignoring task start from node. {MachineId} {JobId} {TaskId} ({State})", machineId, task.JobId, task.TaskId, task.State);
211214
return null;
212215
}
213216

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

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

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

248252
if (done.ExitStatus.Success) {
249-
_log.Info($"task done. {task.JobId:Tag:JobId}:{task.TaskId:Tag:TaskId} {done.ExitStatus:Tag:Status}");
253+
_log.LogInformation("task done. {JobId}:{TaskId} {Status}", task.JobId, task.TaskId, done.ExitStatus);
250254
await _context.TaskOperations.MarkStopping(task, "task is done");
251255

252256
// keep node if keep-on-completion is set
253257
if (task.Config.Debug?.Contains(TaskDebugFlag.KeepNodeOnCompletion) == true) {
254258
node = node with { DebugKeepNode = true };
255259
var r = await _context.NodeOperations.Replace(node);
256260
if (!r.IsOk) {
257-
_log.WithHttpStatus(r.ErrorV).Error($"keepNodeOnCompletion: failed to replace node {node.MachineId:Tag:MachineId} when setting debug keep node to true");
261+
_log.AddHttpStatus(r.ErrorV);
262+
_log.LogError("keepNodeOnCompletion: failed to replace node {MachineId} when setting debug keep node to true", node.MachineId);
258263
}
259264
}
260265
} else {
@@ -273,22 +278,25 @@ await _context.TaskOperations.MarkFailed(
273278
node = node with { DebugKeepNode = true };
274279
var r = await _context.NodeOperations.Replace(node);
275280
if (!r.IsOk) {
276-
_log.WithHttpStatus(r.ErrorV).Error($"keepNodeOnfFailure: failed to replace node {node.MachineId:Tag:MachineId} when setting debug keep node to true");
281+
_log.AddHttpStatus(r.ErrorV);
282+
_log.LogError("keepNodeOnfFailure: failed to replace node {MachineId} when setting debug keep node to true", node.MachineId);
277283
}
278284
}
279285
}
280286

281287
if (!node.DebugKeepNode) {
282288
var r = await _context.NodeTasksOperations.Delete(new NodeTasks(machineId, done.TaskId));
283289
if (!r.IsOk) {
284-
_log.WithHttpStatus(r.ErrorV).Error($"failed to deleting node task {done.TaskId:Tag:TaskId} for: {machineId:Tag:MachineId} since DebugKeepNode is false");
290+
_log.AddHttpStatus(r.ErrorV);
291+
_log.LogError("failed to deleting node task {TaskId} for: {MachineId} since DebugKeepNode is false", done.TaskId, machineId);
285292
}
286293
}
287294

288295
var taskEvent = new TaskEvent(done.TaskId, machineId, new WorkerEvent { Done = done });
289296
var r1 = await _context.TaskEventOperations.Replace(taskEvent);
290297
if (!r1.IsOk) {
291-
_log.WithHttpStatus(r1.ErrorV).Error($"failed to update task event for done task {done.TaskId:Tag:TaskId}");
298+
_log.AddHttpStatus(r1.ErrorV);
299+
_log.LogError("failed to update task event for done task {TaskId}", done.TaskId);
292300
}
293301
return null;
294302
}

0 commit comments

Comments
 (0)