Skip to content

Add more logging to CLI invocations on CI and ensure CLI invocations have timeouts on CI #1964

New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Merged
merged 1 commit into from
Sep 30, 2025
Merged

Add more logging to CLI invocations on CI and ensure CLI invocations have timeouts on CI #1964

Show file tree
Hide file tree
Changes from all commits
Commits
Show all changes
1 commit
Select commit
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
102 changes: 49 additions & 53 deletions src/Elastic.Documentation/ExternalCommands/ExternalCommandExecutor.cs
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -4,20 +4,32 @@

using System.IO.Abstractions;
using Elastic.Documentation.Diagnostics;
using Microsoft.Extensions.Logging;
using ProcNet;
using ProcNet.Std;

namespace Elastic.Documentation.ExternalCommands;

public abstract class ExternalCommandExecutor(IDiagnosticsCollector collector, IDirectoryInfo workingDirectory)
public abstract class ExternalCommandExecutor(IDiagnosticsCollector collector, IDirectoryInfo workingDirectory, TimeSpan? timeout = null)
{
protected abstract ILogger Logger { get; }

private void Log(Action<ILogger> logAction)
{
if (string.IsNullOrWhiteSpace(Environment.GetEnvironmentVariable("CI")))
return;
logAction(Logger);
}

protected IDirectoryInfo WorkingDirectory => workingDirectory;
protected IDiagnosticsCollector Collector => collector;
protected void ExecIn(Dictionary<string, string> environmentVars, string binary, params string[] args)
{
var arguments = new ExecArguments(binary, args)
{
WorkingDirectory = workingDirectory.FullName,
Environment = environmentVars
Environment = environmentVars,
Timeout = timeout
};
Comment on lines 28 to 33
Copy link

Copilot AI Sep 30, 2025

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

The timeout is only applied when environmentVars is provided, but not in the regular Exec methods without environment variables. This creates inconsistent timeout behavior across different execution paths.

Copilot uses AI. Check for mistakes.

Copy link
Member Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

This is false timeout is always provided for ExecIn*

var result = Proc.Exec(arguments);
if (result != 0)
Expand All @@ -30,99 +42,83 @@ protected void ExecInSilent(Dictionary<string, string> environmentVars, string b
{
Environment = environmentVars,
WorkingDirectory = workingDirectory.FullName,
ConsoleOutWriter = NoopConsoleWriter.Instance
ConsoleOutWriter = NoopConsoleWriter.Instance,
Timeout = timeout
};
var result = Proc.Start(arguments);
if (result.ExitCode != 0)
collector.EmitError("", $"Exit code: {result.ExitCode} while executing {binary} {string.Join(" ", args)} in {workingDirectory}");
}

protected string[] CaptureMultiple(string binary, params string[] args) => CaptureMultiple(false, 10, binary, args);
protected string[] CaptureMultiple(bool muteExceptions, int attempts, string binary, params string[] args)
protected string[] CaptureMultiple(int attempts, string binary, params string[] args) => CaptureMultiple(false, attempts, binary, args);
private string[] CaptureMultiple(bool muteExceptions, int attempts, string binary, params string[] args)
{
// Try 10 times to capture the output of the command, if it fails, we'll throw an exception on the last try
Exception? e = null;
for (var i = 1; i <= attempts; i++)
{
try
{
return CaptureOutput();
return CaptureOutput(e, i, attempts);
}
catch (Exception ex)
{
collector.EmitWarning("", $"An exception occurred on attempt {i} to capture output of {binary}: {ex?.Message}");
collector.EmitGlobalWarning($"An exception occurred on attempt {i} to capture output of {binary}: {ex?.Message}");
if (ex is not null)
e = ex;
}
}

if (e is not null && !muteExceptions)
collector.EmitError("", "failure capturing stdout", e);
if (e is not null)
Log(l => l.LogError(e, "[{Binary} {Args}] failure capturing stdout executing in {WorkingDirectory}", binary, string.Join(" ", args), workingDirectory.FullName));

return [];

string[] CaptureOutput()
string[] CaptureOutput(Exception? previousException, int iteration, int max)
{
var arguments = new StartArguments(binary, args)
{
WorkingDirectory = workingDirectory.FullName,
Timeout = TimeSpan.FromSeconds(3),
WaitForExit = TimeSpan.FromSeconds(3),
Comment on lines 82 to 86
Copy link

Copilot AI Sep 30, 2025

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

The hardcoded 3-second timeout in CaptureOutput conflicts with the configurable timeout parameter. Consider using the configurable timeout or a derived value to maintain consistency.

Suggested change
var arguments = new StartArguments(binary, args)
{
WorkingDirectory = workingDirectory.FullName,
Timeout = TimeSpan.FromSeconds(3),
WaitForExit = TimeSpan.FromSeconds(3),
var effectiveTimeout = timeout ?? TimeSpan.FromSeconds(3);
var arguments = new StartArguments(binary, args)
{
WorkingDirectory = workingDirectory.FullName,
Timeout = effectiveTimeout,
WaitForExit = effectiveTimeout,

Copilot uses AI. Check for mistakes.

Copy link
Member Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

This is by design, capturing is retried and is expected to run quickly.

ConsoleOutWriter = NoopConsoleWriter.Instance
ConsoleOutWriter = new ConsoleOutWriter()
};
var result = Proc.Start(arguments);

var output = (result.ExitCode, muteExceptions) switch
string[]? output;
switch (result.ExitCode, muteExceptions)
{
(0, _) or (not 0, true) => result.ConsoleOut.Select(x => x.Line).ToArray() ?? throw new Exception($"No output captured for {binary}: {workingDirectory}"),
(not 0, false) => throw new Exception($"Exit code is not 0. Received {result.ExitCode} from {binary}: {workingDirectory}")
};
case (0, _) or (not 0, true):
output = result.ConsoleOut.Select(x => x.Line).ToArray();
if (output.Length == 0)
{
Log(l => l.LogInformation("[{Binary} {Args}] captured no output. ({Iteration}/{MaxIteration}) pwd: {WorkingDirectory}",
binary, string.Join(" ", args), iteration, max, workingDirectory.FullName)
);
throw new Exception($"No output captured executing in pwd: {workingDirectory} from {binary} {string.Join(" ", args)}", previousException);
}
break;
case (not 0, false):
Log(l => l.LogInformation("[{Binary} {Args}] Exit code is not 0 but {ExitCode}. ({Iteration}/{MaxIteration}) pwd: {WorkingDirectory}",
binary, string.Join(" ", args), result.ExitCode, iteration, max, workingDirectory.FullName)
);
throw new Exception($"Exit code not 0. Received {result.ExitCode} in pwd: {workingDirectory} from {binary} {string.Join(" ", args)}", previousException);
}

return output;
}
}


protected string CaptureQuiet(string binary, params string[] args) => Capture(true, 10, binary, args);
protected string Capture(string binary, params string[] args) => Capture(false, 10, binary, args);
protected string Capture(bool muteExceptions, string binary, params string[] args) => Capture(muteExceptions, 10, binary, args);
protected string Capture(bool muteExceptions, int attempts, string binary, params string[] args)
{
// Try 10 times to capture the output of the command, if it fails, we'll throw an exception on the last try
Exception? e = null;
for (var i = 1; i <= attempts; i++)
{
try
{
return CaptureOutput();
}
catch (Exception ex)
{
if (ex is not null)
e = ex;
}
}

if (e is not null && !muteExceptions)
collector.EmitError("", "failure capturing stdout", e);

return string.Empty;

string CaptureOutput()
{
var arguments = new StartArguments(binary, args)
{
WorkingDirectory = workingDirectory.FullName,
Timeout = TimeSpan.FromSeconds(3),
WaitForExit = TimeSpan.FromSeconds(3),
ConsoleOutWriter = NoopConsoleWriter.Instance,
OnlyPrintBinaryInExceptionMessage = false
};
var result = Proc.Start(arguments);
var line = (result.ExitCode, muteExceptions) switch
{
(0, _) or (not 0, true) => result.ConsoleOut.FirstOrDefault()?.Line ?? throw new Exception($"No output captured for {binary}: {workingDirectory}"),
(not 0, false) => throw new Exception($"Exit code is not 0. Received {result.ExitCode} from {binary}: {workingDirectory}")
};
return line;
}
private string Capture(bool muteExceptions, int attempts, string binary, params string[] args)
{
var lines = CaptureMultiple(muteExceptions, attempts, binary, args);
return lines.FirstOrDefault() ??
(muteExceptions ? string.Empty : throw new Exception($"[{binary} {string.Join(" ", args)}] No output captured executing in : {workingDirectory}"));
}
}
4 changes: 3 additions & 1 deletion src/authoring/Elastic.Documentation.Refactor/Tracking/LocalChangesService.cs
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -46,7 +46,9 @@ public Task<bool> ValidateRedirects(IDiagnosticsCollector collector, string? pat
}
var relativePath = Path.GetRelativePath(root.FullName, buildContext.DocumentationSourceDirectory.FullName);
_logger.LogInformation("Using relative path {RelativePath} for validating changes", relativePath);
IRepositoryTracker tracker = runningOnCi ? new IntegrationGitRepositoryTracker(relativePath) : new LocalGitRepositoryTracker(collector, root, relativePath);
IRepositoryTracker tracker = runningOnCi
? new IntegrationGitRepositoryTracker(relativePath)
: new LocalGitRepositoryTracker(logFactory, collector, root, relativePath);
var changed = tracker.GetChangedFiles()
.Where(c =>
{
Expand Down
11 changes: 8 additions & 3 deletions src/authoring/Elastic.Documentation.Refactor/Tracking/LocalGitRepositoryTracker.cs
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -5,11 +5,16 @@
using System.IO.Abstractions;
using Elastic.Documentation.Diagnostics;
using Elastic.Documentation.ExternalCommands;
using Microsoft.Extensions.Logging;

namespace Elastic.Documentation.Refactor.Tracking;

public class LocalGitRepositoryTracker(IDiagnosticsCollector collector, IDirectoryInfo workingDirectory, string lookupPath) : ExternalCommandExecutor(collector, workingDirectory), IRepositoryTracker
public class LocalGitRepositoryTracker(ILoggerFactory logFactory, IDiagnosticsCollector collector, IDirectoryInfo workingDirectory, string lookupPath)
: ExternalCommandExecutor(collector, workingDirectory), IRepositoryTracker
{
/// <inheritdoc />
protected override ILogger Logger { get; } = logFactory.CreateLogger<LocalGitRepositoryTracker>();

private string LookupPath { get; } = lookupPath.Trim('\\', '/');

public IReadOnlyCollection<GitChange> GetChangedFiles()
Expand All @@ -30,9 +35,9 @@ public IReadOnlyCollection<GitChange> GetChangedFiles()

private string GetDefaultBranch()
{
if (!Capture(true, "git", "merge-base", "-a", "HEAD", "main").StartsWith("fatal", StringComparison.InvariantCulture))
if (!CaptureQuiet("git", "merge-base", "-a", "HEAD", "main").StartsWith("fatal", StringComparison.InvariantCulture))
return "main";
if (!Capture(true, "git", "merge-base", "-a", "HEAD", "master").StartsWith("fatal", StringComparison.InvariantCulture))
if (!CaptureQuiet("git", "merge-base", "-a", "HEAD", "master").StartsWith("fatal", StringComparison.InvariantCulture))
return "master";
return Capture("git", "symbolic-ref", "refs/remotes/origin/HEAD").Split('/').Last();
}
Expand Down
13 changes: 7 additions & 6 deletions ...es/Elastic.Documentation.Assembler/Deploying/Redirects/AwsCloudFrontKeyValueStoreProxy.cs
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -19,7 +19,8 @@ internal enum KvsOperation
public class AwsCloudFrontKeyValueStoreProxy(IDiagnosticsCollector collector, ILoggerFactory logFactory, IDirectoryInfo workingDirectory)
: ExternalCommandExecutor(collector, workingDirectory)
{
private readonly ILogger _logger = logFactory.CreateLogger<AwsCloudFrontKeyValueStoreProxy>();
/// <inheritdoc />
protected override ILogger Logger { get; } = logFactory.CreateLogger<AwsCloudFrontKeyValueStoreProxy>();

public void UpdateRedirects(string kvsName, IReadOnlyDictionary<string, string> sourcedRedirects)
{
Expand Down Expand Up @@ -50,7 +51,7 @@ public void UpdateRedirects(string kvsName, IReadOnlyDictionary<string, string>

private string DescribeKeyValueStore(string kvsName)
{
_logger.LogInformation("Describing KeyValueStore");
Logger.LogInformation("Describing KeyValueStore");
try
{
var json = CaptureMultiple("aws", "cloudfront", "describe-key-value-store", "--name", kvsName);
Expand All @@ -77,7 +78,7 @@ private string DescribeKeyValueStore(string kvsName)

private string AcquireETag(string kvsArn)
{
_logger.LogInformation("Acquiring ETag for updates");
Logger.LogInformation("Acquiring ETag for updates");
try
{
var json = CaptureMultiple("aws", "cloudfront-keyvaluestore", "describe-key-value-store", "--kvs-arn", kvsArn);
Expand All @@ -103,7 +104,7 @@ private string AcquireETag(string kvsArn)

private bool TryListAllKeys(string kvsArn, out HashSet<string> keys)
{
_logger.LogInformation("Acquiring existing redirects");
Logger.LogInformation("Acquiring existing redirects");
keys = [];
string[] baseArgs = ["cloudfront-keyvaluestore", "list-keys", "--kvs-arn", kvsArn, "--page-size", "50", "--max-items", "50"];
string? nextToken = null;
Expand Down Expand Up @@ -145,7 +146,7 @@ private string ProcessBatchUpdates(
KvsOperation operation)
{
const int batchSize = 50;
_logger.LogInformation("Processing {Count} items in batches of {BatchSize} for {Operation} update operation.", items.Count, batchSize, operation);
Logger.LogInformation("Processing {Count} items in batches of {BatchSize} for {Operation} update operation.", items.Count, batchSize, operation);
try
{
foreach (var batch in items.Chunk(batchSize))
Expand All @@ -158,7 +159,7 @@ private string ProcessBatchUpdates(
AwsCloudFrontKeyValueStoreJsonContext.Default.ListDeleteKeyRequestListItem),
_ => string.Empty
};
var responseJson = CaptureMultiple(false, 1, "aws", "cloudfront-keyvaluestore", "update-keys", "--kvs-arn", kvsArn, "--if-match", eTag,
var responseJson = CaptureMultiple(1, "aws", "cloudfront-keyvaluestore", "update-keys", "--kvs-arn", kvsArn, "--if-match", eTag,
$"--{operation.ToString().ToLowerInvariant()}", payload);

var concatJson = string.Concat(responseJson);
Expand Down
8 changes: 7 additions & 1 deletion src/services/Elastic.Documentation.Assembler/Sourcing/GitFacade.cs
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -5,6 +5,7 @@
using System.IO.Abstractions;
using Elastic.Documentation.Diagnostics;
using Elastic.Documentation.ExternalCommands;
using Microsoft.Extensions.Logging;

namespace Elastic.Documentation.Assembler.Sourcing;

Expand All @@ -23,8 +24,13 @@ public interface IGitRepository

// This git repository implementation is optimized for pull and fetching single commits.
// It uses `git pull --depth 1` and `git fetch --depth 1` to minimize the amount of data transferred.
public class SingleCommitOptimizedGitRepository(IDiagnosticsCollector collector, IDirectoryInfo workingDirectory) : ExternalCommandExecutor(collector, workingDirectory), IGitRepository
public class SingleCommitOptimizedGitRepository(ILoggerFactory logFactory, IDiagnosticsCollector collector, IDirectoryInfo workingDirectory)
: ExternalCommandExecutor(collector, workingDirectory, Environment.GetEnvironmentVariable("CI") is null or "" ? null : TimeSpan.FromMinutes(10))
, IGitRepository
{
/// <inheritdoc />
protected override ILogger Logger { get; } = logFactory.CreateLogger<SingleCommitOptimizedGitRepository>();

private static readonly Dictionary<string, string> EnvironmentVars = new()
{
// Disable git editor prompts:
Expand Down
4 changes: 2 additions & 2 deletions src/services/Elastic.Documentation.Assembler/Sourcing/RepositorySourcesFetcher.cs
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -42,7 +42,7 @@ public CheckoutResult GetAll()
_logger.LogInformation("{RepositoryName}: Using local override path for {RepositoryName} at {Path}", repo.Name, repo.Name, repo.Path);
checkoutFolder = fs.DirectoryInfo.New(repo.Path);
}
IGitRepository gitFacade = new SingleCommitOptimizedGitRepository(context.Collector, checkoutFolder);
IGitRepository gitFacade = new SingleCommitOptimizedGitRepository(logFactory, context.Collector, checkoutFolder);
if (!checkoutFolder.Exists)
{
context.Collector.EmitError(checkoutFolder.FullName, $"'{repo.Name}' does not exist in link index checkout directory");
Expand Down Expand Up @@ -156,7 +156,7 @@ public Checkout CloneRef(Repository repository, string gitRef, bool pull = false
_logger.LogInformation("{RepositoryName}: Using override path for {RepositoryName}@{Commit} at {CheckoutFolder}", repository.Name, repository.Name, gitRef, checkoutFolder.FullName);
}

IGitRepository git = new SingleCommitOptimizedGitRepository(collector, checkoutFolder);
IGitRepository git = new SingleCommitOptimizedGitRepository(logFactory, collector, checkoutFolder);

if (assumeCloned && checkoutFolder.Exists)
{
Expand Down
Loading