diff --git a/src/Elastic.Documentation/ExternalCommands/ExternalCommandExecutor.cs b/src/Elastic.Documentation/ExternalCommands/ExternalCommandExecutor.cs index a75c3673f..ccdc9821c 100644 --- a/src/Elastic.Documentation/ExternalCommands/ExternalCommandExecutor.cs +++ b/src/Elastic.Documentation/ExternalCommands/ExternalCommandExecutor.cs @@ -4,12 +4,23 @@ 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 logAction) + { + if (string.IsNullOrWhiteSpace(Environment.GetEnvironmentVariable("CI"))) + return; + logAction(Logger); + } + protected IDirectoryInfo WorkingDirectory => workingDirectory; protected IDiagnosticsCollector Collector => collector; protected void ExecIn(Dictionary environmentVars, string binary, params string[] args) @@ -17,7 +28,8 @@ protected void ExecIn(Dictionary environmentVars, string binary, var arguments = new ExecArguments(binary, args) { WorkingDirectory = workingDirectory.FullName, - Environment = environmentVars + Environment = environmentVars, + Timeout = timeout }; var result = Proc.Exec(arguments); if (result != 0) @@ -30,7 +42,8 @@ protected void ExecInSilent(Dictionary 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) @@ -38,7 +51,8 @@ protected void ExecInSilent(Dictionary environmentVars, string b } 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; @@ -46,11 +60,11 @@ protected string[] CaptureMultiple(bool muteExceptions, int attempts, string bin { 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; } @@ -58,71 +72,53 @@ protected string[] CaptureMultiple(bool muteExceptions, int attempts, string bin 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), - 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}")); } } diff --git a/src/authoring/Elastic.Documentation.Refactor/Tracking/LocalChangesService.cs b/src/authoring/Elastic.Documentation.Refactor/Tracking/LocalChangesService.cs index 79a1b4aae..946ce843e 100644 --- a/src/authoring/Elastic.Documentation.Refactor/Tracking/LocalChangesService.cs +++ b/src/authoring/Elastic.Documentation.Refactor/Tracking/LocalChangesService.cs @@ -46,7 +46,9 @@ public Task 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 => { diff --git a/src/authoring/Elastic.Documentation.Refactor/Tracking/LocalGitRepositoryTracker.cs b/src/authoring/Elastic.Documentation.Refactor/Tracking/LocalGitRepositoryTracker.cs index c13451630..12a29c9e3 100644 --- a/src/authoring/Elastic.Documentation.Refactor/Tracking/LocalGitRepositoryTracker.cs +++ b/src/authoring/Elastic.Documentation.Refactor/Tracking/LocalGitRepositoryTracker.cs @@ -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 { + /// + protected override ILogger Logger { get; } = logFactory.CreateLogger(); + private string LookupPath { get; } = lookupPath.Trim('\\', '/'); public IReadOnlyCollection GetChangedFiles() @@ -30,9 +35,9 @@ public IReadOnlyCollection 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(); } diff --git a/src/services/Elastic.Documentation.Assembler/Deploying/Redirects/AwsCloudFrontKeyValueStoreProxy.cs b/src/services/Elastic.Documentation.Assembler/Deploying/Redirects/AwsCloudFrontKeyValueStoreProxy.cs index 49fb42790..480d6503a 100644 --- a/src/services/Elastic.Documentation.Assembler/Deploying/Redirects/AwsCloudFrontKeyValueStoreProxy.cs +++ b/src/services/Elastic.Documentation.Assembler/Deploying/Redirects/AwsCloudFrontKeyValueStoreProxy.cs @@ -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(); + /// + protected override ILogger Logger { get; } = logFactory.CreateLogger(); public void UpdateRedirects(string kvsName, IReadOnlyDictionary sourcedRedirects) { @@ -50,7 +51,7 @@ public void UpdateRedirects(string kvsName, IReadOnlyDictionary 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); @@ -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); @@ -103,7 +104,7 @@ private string AcquireETag(string kvsArn) private bool TryListAllKeys(string kvsArn, out HashSet 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; @@ -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)) @@ -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); diff --git a/src/services/Elastic.Documentation.Assembler/Sourcing/GitFacade.cs b/src/services/Elastic.Documentation.Assembler/Sourcing/GitFacade.cs index 00a632c43..c75b0f5e8 100644 --- a/src/services/Elastic.Documentation.Assembler/Sourcing/GitFacade.cs +++ b/src/services/Elastic.Documentation.Assembler/Sourcing/GitFacade.cs @@ -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; @@ -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 { + /// + protected override ILogger Logger { get; } = logFactory.CreateLogger(); + private static readonly Dictionary EnvironmentVars = new() { // Disable git editor prompts: diff --git a/src/services/Elastic.Documentation.Assembler/Sourcing/RepositorySourcesFetcher.cs b/src/services/Elastic.Documentation.Assembler/Sourcing/RepositorySourcesFetcher.cs index 72cbebb61..5f7fa220e 100644 --- a/src/services/Elastic.Documentation.Assembler/Sourcing/RepositorySourcesFetcher.cs +++ b/src/services/Elastic.Documentation.Assembler/Sourcing/RepositorySourcesFetcher.cs @@ -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"); @@ -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) {