Skip to content

Commit 83e32cc

Browse files
rishabhmalikMSrishabhmalikMS
authored
Adding logs for agent lifecycle for listener process (#5284)
* Adding logs for agnet lifecycle for listener process * minor fix * code cleaning | removing unnecessary comment * code cleaning * Minor fixes for PR comments * minor fixes * Fixes for comments in Agent.cs * PR comments fixes in program.cs in listener * job dispatcher comments fixes * added logs in agent configration steps in configureAsync call in configuration manager * Fixes to update logs in listener * Fix in job dispatcher log in run async function * Fixes in listener program.cs
1 parent 67794b4 commit 83e32cc

File tree

4 files changed

+159
-35
lines changed

4 files changed

+159
-35
lines changed

‎src/Agent.Listener/Agent.cs‎

Lines changed: 36 additions & 9 deletions
Original file line numberDiff line numberDiff line change
@@ -47,6 +47,7 @@ public async Task<int> ExecuteCommand(CommandSettings command)
4747
ArgUtil.NotNull(command, nameof(command));
4848
try
4949
{
50+
Trace.Verbose("Initializing core services...");
5051
var agentWebProxy = HostContext.GetService<IVstsAgentWebProxy>();
5152
var agentCertManager = HostContext.GetService<IAgentCertificateManager>();
5253
VssUtil.InitializeVssClientSettings(HostContext.UserAgent, agentWebProxy.WebProxy, agentCertManager.VssClientCertificateManager, agentCertManager.SkipServerCertificateValidation);
@@ -59,7 +60,6 @@ public async Task<int> ExecuteCommand(CommandSettings command)
5960
HostContext.Unloading += Agent_Unloading;
6061

6162
// TODO Unit test to cover this logic
62-
Trace.Info(nameof(ExecuteCommand));
6363
var configManager = HostContext.GetService<IConfigurationManager>();
6464

6565
// command is not required, if no command it just starts if configured
@@ -150,6 +150,7 @@ public async Task<int> ExecuteCommand(CommandSettings command)
150150
// this will optimizes the agent process startup time.
151151
if (command.IsWarmupCommand())
152152
{
153+
Trace.Info("Starting agent warmup process - pre-loading assemblies for optimal performance");
153154
var binDir = HostContext.GetDirectory(WellKnownDirectory.Bin);
154155
foreach (var assemblyFile in Directory.EnumerateFiles(binDir, "*.dll"))
155156
{
@@ -185,9 +186,11 @@ public async Task<int> ExecuteCommand(CommandSettings command)
185186
}
186187
}
187188

189+
Trace.Info("Agent warmup completed successfully - assemblies pre-loaded");
188190
return Constants.Agent.ReturnCode.Success;
189191
}
190192

193+
Trace.Info("Loading agent configuration from settings store");
191194
AgentSettings settings = configManager.LoadSettings();
192195

193196
var store = HostContext.GetService<IConfigurationStore>();
@@ -200,12 +203,13 @@ public async Task<int> ExecuteCommand(CommandSettings command)
200203
// Error if agent not configured.
201204
if (!configManager.IsConfigured())
202205
{
206+
Trace.Error("Agent configuration not found - agent needs to be configured before running");
203207
_term.WriteError(StringUtil.Loc("AgentIsNotConfigured"));
204208
PrintUsage(command);
205209
return Constants.Agent.ReturnCode.TerminatedError;
206210
}
207211

208-
Trace.Verbose($"Configured as service: '{configuredAsService}'");
212+
Trace.Verbose($"Agent configuration loaded successfully, Configured as service: '{configuredAsService}'");
209213

210214
//Get the startup type of the agent i.e., autostartup, service, manual
211215
StartupType startType;
@@ -355,7 +359,7 @@ private async Task<int> RunAsync(AgentSettings settings, bool runOnce = false)
355359
{
356360
try
357361
{
358-
Trace.Info(nameof(RunAsync));
362+
Trace.Info($"Entering main agent execution loop({0})", nameof(RunAsync));
359363

360364
var featureFlagProvider = HostContext.GetService<IFeatureFlagProvider>();
361365
var checkPsModulesFeatureFlag = await featureFlagProvider.GetFeatureFlagAsync(HostContext, "DistributedTask.Agent.CheckPsModulesLocations", Trace);
@@ -371,20 +375,24 @@ private async Task<int> RunAsync(AgentSettings settings, bool runOnce = false)
371375
}
372376
}
373377

378+
Trace.Info("Initializing message listener - establishing connection to Azure DevOps");
374379
_listener = HostContext.GetService<IMessageListener>();
375380
if (!await _listener.CreateSessionAsync(HostContext.AgentShutdownToken))
376381
{
382+
Trace.Error("Failed to create session with Azure DevOps");
377383
return Constants.Agent.ReturnCode.TerminatedError;
378384
}
379385

380386
HostContext.WritePerfCounter("SessionCreated");
387+
Trace.Info("Session created successfully - agent is now listening for jobs");
381388
_term.WriteLine(StringUtil.Loc("ListenForJobs", DateTime.UtcNow));
382389

383390
IJobDispatcher jobDispatcher = null;
384391
CancellationTokenSource messageQueueLoopTokenSource = CancellationTokenSource.CreateLinkedTokenSource(HostContext.AgentShutdownToken);
385392
CancellationTokenSource keepAliveToken = CancellationTokenSource.CreateLinkedTokenSource(HostContext.AgentShutdownToken);
386393
try
387394
{
395+
Trace.Info("Initializing job notification service for real-time updates");
388396
var notification = HostContext.GetService<IJobNotification>();
389397
if (!String.IsNullOrEmpty(settings.NotificationSocketAddress))
390398
{
@@ -393,7 +401,7 @@ private async Task<int> RunAsync(AgentSettings settings, bool runOnce = false)
393401
else
394402
{
395403
notification.StartClient(settings.NotificationPipeName, settings.MonitorSocketAddress, HostContext.AgentShutdownToken);
396-
}
404+
}
397405
// this is not a reliable way to disable auto update.
398406
// we need server side work to really enable the feature
399407
// https://github.com/Microsoft/vsts-agent/issues/446 (Feature: Allow agent / pool to opt out of automatic updates)
@@ -406,12 +414,14 @@ private async Task<int> RunAsync(AgentSettings settings, bool runOnce = false)
406414

407415
_ = _listener.KeepAlive(keepAliveToken.Token);
408416

417+
Trace.Info("Starting message processing loop - agent ready to receive jobs");
409418
while (!HostContext.AgentShutdownToken.IsCancellationRequested)
410419
{
411420
TaskAgentMessage message = null;
412421
bool skipMessageDeletion = false;
413422
try
414423
{
424+
Trace.Info("Next message wait initiated - Agent ready to receive next message from server");
415425
Task<TaskAgentMessage> getNextMessage = _listener.GetNextMessageAsync(messageQueueLoopTokenSource.Token);
416426
if (autoUpdateInProgress)
417427
{
@@ -487,12 +497,13 @@ private async Task<int> RunAsync(AgentSettings settings, bool runOnce = false)
487497
}
488498

489499
message ??= await getNextMessage; //get next message
500+
Trace.Info($"Next message wait completed - Received message from server: {message.MessageType}");
490501
HostContext.WritePerfCounter($"MessageReceived_{message.MessageType}");
491502
if (string.Equals(message.MessageType, AgentRefreshMessage.MessageType, StringComparison.OrdinalIgnoreCase))
492503
{
493504
if (disableAutoUpdate)
494505
{
495-
Trace.Info("Refresh message received, skip autoupdate since environment variable agent.disableupdate is set.");
506+
Trace.Info("Auto-update handling - Refresh message received but skipping autoupdate since agent.disableupdate is set");
496507
}
497508
else
498509
{
@@ -502,11 +513,11 @@ private async Task<int> RunAsync(AgentSettings settings, bool runOnce = false)
502513
var agentUpdateMessage = JsonUtility.FromString<AgentRefreshMessage>(message.Body);
503514
var selfUpdater = HostContext.GetService<ISelfUpdater>();
504515
selfUpdateTask = selfUpdater.SelfUpdate(agentUpdateMessage, jobDispatcher, !runOnce && HostContext.StartupType != StartupType.Service, HostContext.AgentShutdownToken);
505-
Trace.Info("Refresh message received, kick-off selfupdate background process.");
516+
Trace.Info("Agent update handling - Self-update task initiated, target version: {0}", agentUpdateMessage.TargetVersion);
506517
}
507518
else
508519
{
509-
Trace.Info("Refresh message received, skip autoupdate since a previous autoupdate is already running.");
520+
Trace.Info("Agent update message received, skip autoupdate since a previous autoupdate is already running.");
510521
}
511522
}
512523
}
@@ -529,14 +540,17 @@ private async Task<int> RunAsync(AgentSettings settings, bool runOnce = false)
529540
switch (message.MessageType)
530541
{
531542
case JobRequestMessageTypes.AgentJobRequest:
543+
Trace.Verbose("Converting legacy job message format to pipeline format");
532544
var legacyJobMessage = JsonUtility.FromString<AgentJobRequestMessage>(message.Body);
533545
pipelineJobMessage = Pipelines.AgentJobRequestMessageUtil.Convert(legacyJobMessage);
534546
break;
535547
case JobRequestMessageTypes.PipelineAgentJobRequest:
548+
Trace.Verbose("Processing pipeline job message for execution");
536549
pipelineJobMessage = JsonUtility.FromString<Pipelines.AgentJobRequestMessage>(message.Body);
537550
break;
538551
}
539552

553+
Trace.Info("Dispatching job to worker process for execution");
540554
jobDispatcher.Run(pipelineJobMessage, runOnce);
541555
if (runOnce)
542556
{
@@ -547,6 +561,7 @@ private async Task<int> RunAsync(AgentSettings settings, bool runOnce = false)
547561
}
548562
else if (string.Equals(message.MessageType, JobCancelMessage.MessageType, StringComparison.OrdinalIgnoreCase))
549563
{
564+
Trace.Verbose("Processing job cancellation request from Azure DevOps");
550565
var cancelJobMessage = JsonUtility.FromString<JobCancelMessage>(message.Body);
551566
bool jobCancelled = jobDispatcher.Cancel(cancelJobMessage);
552567
skipMessageDeletion = (autoUpdateInProgress || runOnceJobReceived) && !jobCancelled;
@@ -558,6 +573,7 @@ private async Task<int> RunAsync(AgentSettings settings, bool runOnce = false)
558573
}
559574
else if (string.Equals(message.MessageType, JobMetadataMessage.MessageType, StringComparison.OrdinalIgnoreCase))
560575
{
576+
Trace.Info("Processing job metadata update from Azure DevOps");
561577
var metadataMessage = JsonUtility.FromString<JobMetadataMessage>(message.Body);
562578
jobDispatcher.MetadataUpdate(metadataMessage);
563579
}
@@ -568,15 +584,18 @@ private async Task<int> RunAsync(AgentSettings settings, bool runOnce = false)
568584
}
569585
catch (AggregateException e)
570586
{
587+
Trace.Error($"Exception occurred while processing message from queue: {e.Message}");
571588
ExceptionsUtil.HandleAggregateException((AggregateException)e, Trace.Error);
572589
}
573590
finally
574591
{
575592
if (!skipMessageDeletion && message != null)
576593
{
594+
Trace.Info($"Message deletion from queue initiated - Deleting processed message: {message.MessageId}");
577595
try
578596
{
579597
await _listener.DeleteMessageAsync(message);
598+
Trace.Info($"Message deletion completed - Message {message.MessageId} successfully removed from queue");
580599
}
581600
catch (Exception ex)
582601
{
@@ -585,21 +604,29 @@ private async Task<int> RunAsync(AgentSettings settings, bool runOnce = false)
585604
}
586605
finally
587606
{
607+
Trace.Info("Message cleanup completed - Message reference cleared, ready for next message");
588608
message = null;
589609
}
590610
}
611+
else
612+
{
613+
Trace.Info("Message deletion skipped - Either skip flag set or no message to delete");
614+
}
591615
}
592616
}
593617
}
594618
finally
595619
{
620+
Trace.Info("Beginning agent shutdown sequence - cleaning up resources");
596621
keepAliveToken.Dispose();
597622

598623
if (jobDispatcher != null)
599624
{
625+
Trace.Info("Shutting down job dispatcher - terminating active jobs");
600626
await jobDispatcher.ShutdownAsync();
601627
}
602628

629+
Trace.Info("Cleaning up agent listener session - disconnecting from Azure DevOps");
603630
//TODO: make sure we don't mask more important exception
604631
await _listener.DeleteSessionAsync();
605632

@@ -608,9 +635,10 @@ private async Task<int> RunAsync(AgentSettings settings, bool runOnce = false)
608635
}
609636
catch (TaskAgentAccessTokenExpiredException)
610637
{
611-
Trace.Info("Agent OAuth token has been revoked. Shutting down.");
638+
Trace.Info("Agent OAuth token has been revoked - shutting down gracefully");
612639
}
613640

641+
Trace.Info("Agent run completed successfully - exiting with success code");
614642
return Constants.Agent.ReturnCode.Success;
615643
}
616644

@@ -621,7 +649,6 @@ private void PrintUsage(CommandSettings command)
621649
{
622650
ext = "cmd";
623651
}
624-
625652
string commonHelp = StringUtil.Loc("CommandLineHelp_Common");
626653
string envHelp = StringUtil.Loc("CommandLineHelp_Env");
627654
if (command.IsConfigureCommand())

0 commit comments

Comments
 (0)