GitVersion logging does not include newlines

[gitfool]

Something I've ignored to date but might as well capture for the record; for some reason GitVersion logging does not include newlines. It does in some places but generally not. Example ugliness:

2020-02-21T19:44:13.2433107Z Executing: /home/runner/work/build-cake/build-cake/tools/dotnet-gitversion -output json -verbosity Debug
2020-02-21T19:44:13.7026817Z INFO [02/21/20 19:44:13:46] Applicable build agent found: 'GitHubActions'.INFO [02/21/20 19:44:13:47] Working directory: /home/runner/work/build-cake/build-cakeINFO [02/21/20 19:44:13:47] IsDynamicGitRepository: FalseINFO [02/21/20 19:44:13:48] Returning Project Root from DotGitDirectory: /home/runner/work/build-cake/build-cake/.git/ - /home/runner/work/build-cake/build-cake/INFO [02/21/20 19:44:13:48] Running on Unix.INFO [02/21/20 19:44:13:48] Applicable build agent found: 'GitHubActions'.INFO [02/21/20 19:44:13:48] Branch from build environment: gitversion-betaINFO [02/21/20 19:44:13:49] Begin: Normalizing git directory for branch 'gitversion-beta'  INFO [02/21/20 19:44:13:52] One remote found (origin -> 'https://github.com/pharos/build-cake').  INFO [02/21/20 19:44:13:52] Fetching from remote 'origin' using the following refspecs: +refs/heads/*:refs/remotes/origin/*.  INFO [02/21/20 19:44:13:63] End: Normalizing git directory for branch 'gitversion-beta' (Took: 149.01ms)  ERROR [02/21/20 19:44:13:65] An unexpected error occurred:
2020-02-21T19:44:13.7027719Z LibGit2Sharp.LibGit2SharpException: remote authentication required but no callback set
2020-02-21T19:44:13.7027967Z    at LibGit2Sharp.Core.Ensure.HandleError(Int32 result)
2020-02-21T19:44:13.7028198Z    at LibGit2Sharp.Core.Ensure.ZeroResult(Int32 result)
2020-02-21T19:44:13.7028426Z    at LibGit2Sharp.Core.Proxy.git_remote_fetch(RemoteHandle remote, IEnumerable`1 refSpecs, GitFetchOptions fetchOptions, String logMessage)
2020-02-21T19:44:13.7028687Z    at LibGit2Sharp.Commands.Fetch(Repository repository, String remote, IEnumerable`1 refspecs, FetchOptions options, String logMessage)
2020-02-21T19:44:13.7028954Z    at GitVersion.Helpers.GitRepositoryHelper.Fetch(ILog log, AuthenticationInfo authentication, Remote remote, Repository repo) in D:\a\GitVersion\GitVersion\src\GitVersionCore\Helpers\GitRepositoryHelper.cs:line 145
2020-02-21T19:44:13.7029238Z    at GitVersion.Helpers.GitRepositoryHelper.NormalizeGitDirectory(ILog log, IEnvironment environment, String gitDirectory, AuthenticationInfo authentication, Boolean noFetch, String currentBranch, Boolean isDynamicRepository) in D:\a\GitVersion\GitVersion\src\GitVersionCore\Helpers\GitRepositoryHelper.cs:line 40
2020-02-21T19:44:13.7029521Z    at GitVersion.GitPreparer.NormalizeGitDirectory(AuthenticationInfo auth, String targetBranch, String gitDirectory, Boolean isDynamicRepository) in D:\a\GitVersion\GitVersion\src\GitVersionCore\GitPreparer.cs:line 190
2020-02-21T19:44:13.7029786Z    at GitVersion.GitPreparer.Prepare(Boolean normalizeGitDirectory, String currentBranch, Boolean shouldCleanUpRemotes) in D:\a\GitVersion\GitVersion\src\GitVersionCore\GitPreparer.cs:line 65
2020-02-21T19:44:13.7030040Z    at GitVersion.GitVersionCalculator.CalculateVersionVariables() in D:\a\GitVersion\GitVersion\src\GitVersionCore\GitVersionCalculator.cs:line 51
2020-02-21T19:44:13.7030272Z    at GitVersion.ExecCommand.Execute() in D:\a\GitVersion\GitVersion\src\GitVersionExe\ExecCommand.cs:line 39
2020-02-21T19:44:13.7031622Z    at GitVersion.GitVersionExecutor.VerifyArgumentsAndRun(Arguments arguments) in D:\a\GitVersion\GitVersion\src\GitVersionExe\GitVersionExecutor.cs:line 117  INFO [02/21/20 19:44:13:65]   INFO [02/21/20 19:44:13:65] Attempting to show the current git graph (please include in issue):   INFO [02/21/20 19:44:13:65] Showing max of 100 commits  INFO [02/21/20 19:44:13:68] * 0a7740c 2 minutes ago  (HEAD -> gitversion-beta, tag: 14.1.0-pre.1, origin/gitversion-beta)
...
2020-02-21T19:44:13.7498754Z Error: System.AggregateException: One or more errors occurred. (Expecting state 'Element'.. Encountered 'Text'  with name '', namespace ''.)
2020-02-21T19:44:13.7499245Z  ---> System.Runtime.Serialization.SerializationException: Expecting state 'Element'.. Encountered 'Text'  with name '', namespace ''.
2020-02-21T19:44:13.7500469Z    at System.Runtime.Serialization.XmlObjectSerializerReadContext.HandleMemberNotFound(XmlReaderDelegator xmlReader, ExtensionDataObject extensionData, Int32 memberIndex)
2020-02-21T19:44:13.7500689Z    at System.Runtime.Serialization.Json.XmlObjectSerializerReadContextComplexJson.GetJsonMemberIndex(XmlReaderDelegator xmlReader, XmlDictionaryString[] memberNames, Int32 memberIndex, ExtensionDataObject extensionData)
2020-02-21T19:44:13.7500866Z    at ReadGitVersionFromJson(XmlReaderDelegator , XmlObjectSerializerReadContextComplexJson , XmlDictionaryString , XmlDictionaryString[] )
2020-02-21T19:44:13.7501041Z    at System.Runtime.Serialization.Json.JsonClassDataContract.ReadJsonValueCore(XmlReaderDelegator jsonReader, XmlObjectSerializerReadContextComplexJson context)
2020-02-21T19:44:13.7501208Z    at System.Runtime.Serialization.Json.JsonDataContract.ReadJsonValue(XmlReaderDelegator jsonReader, XmlObjectSerializerReadContextComplexJson context)
2020-02-21T19:44:13.7501375Z    at System.Runtime.Serialization.Json.XmlObjectSerializerReadContextComplexJson.ReadDataContractValue(DataContract dataContract, XmlReaderDelegator reader)
2020-02-21T19:44:13.7501548Z    at System.Runtime.Serialization.XmlObjectSerializerReadContext.InternalDeserialize(XmlReaderDelegator reader, String name, String ns, Type declaredType, DataContract& dataContract)
2020-02-21T19:44:13.7501730Z    at System.Runtime.Serialization.XmlObjectSerializerReadContextComplex.InternalDeserialize(XmlReaderDelegator xmlReader, Type declaredType, DataContract dataContract, String name, String ns)
2020-02-21T19:44:13.7501898Z    at System.Runtime.Serialization.Json.DataContractJsonSerializerImpl.InternalReadObject(XmlReaderDelegator xmlReader, Boolean verifyObjectName)
2020-02-21T19:44:13.7502064Z    at System.Runtime.Serialization.XmlObjectSerializer.InternalReadObject(XmlReaderDelegator reader, Boolean verifyObjectName, DataContractResolver dataContractResolver)
2020-02-21T19:44:13.7502242Z    at System.Runtime.Serialization.XmlObjectSerializer.ReadObjectHandleExceptions(XmlReaderDelegator reader, Boolean verifyObjectName, DataContractResolver dataContractResolver)
2020-02-21T19:44:13.7502410Z    at System.Runtime.Serialization.Json.DataContractJsonSerializerImpl.ReadObject(XmlDictionaryReader reader)
2020-02-21T19:44:13.7502552Z    at System.Runtime.Serialization.Json.DataContractJsonSerializerImpl.ReadObject(Stream stream)
2020-02-21T19:44:13.7502696Z    at System.Runtime.Serialization.Json.DataContractJsonSerializer.ReadObject(Stream stream)
2020-02-21T19:44:13.7502852Z    at Cake.Common.Tools.GitVersion.GitVersionRunner.Run(GitVersionSettings settings) in C:\projects\cake\src\Cake.Common\Tools\GitVersion\GitVersionRunner.cs:line 65
2020-02-21T19:44:13.7503213Z    at Cake.Common.Tools.GitVersion.GitVersionAliases.GitVersion(ICakeContext context, GitVersionSettings settings) in C:\projects\cake\src\Cake.Common\Tools\GitVersion\GitVersionAliases.cs:line 121
2020-02-21T19:44:13.7503792Z    at Submission#0.Version..ctor(BuildSystem buildSystem, ICakeContext context) in /home/runner/work/build-cake/build-cake/scripts/version.cake:line 10
2020-02-21T19:44:13.7504344Z    at Submission#0.Builder.SetVersion() in /home/runner/work/build-cake/build-cake/scripts/builder.cake:line 291
2020-02-21T19:44:13.7504794Z    at Submission#0.Builder..ctor(BuildSystem buildSystem, ICakeContext context, Action`1 runTarget) in /home/runner/work/build-cake/build-cake/scripts/builder.cake:line 9
2020-02-21T19:44:13.7505199Z    at Submission#0.<<Initialize>>d__0.MoveNext() in /home/runner/work/build-cake/build-cake/scripts/bootstrap.cake:line 20
2020-02-21T19:44:13.7505618Z --- End of stack trace from previous location where exception was thrown ---
2020-02-21T19:44:13.7505796Z    at Microsoft.CodeAnalysis.Scripting.ScriptExecutionState.RunSubmissionsAsync[TResult](ImmutableArray`1 precedingExecutors, Func`2 currentExecutor, StrongBox`1 exceptionHolderOpt, Func`2 catchExceptionOpt, CancellationToken cancellationToken)
2020-02-21T19:44:13.7505991Z    at Microsoft.CodeAnalysis.Scripting.Script`1.RunSubmissionsAsync(ScriptExecutionState executionState, ImmutableArray`1 precedingExecutors, Func`2 currentExecutor, Func`2 catchExceptionOpt, CancellationToken cancellationToken)
2020-02-21T19:44:13.7506343Z    --- End of inner exception stack trace ---
2020-02-21T19:44:13.7506485Z    at System.Threading.Tasks.Task.Wait(Int32 millisecondsTimeout, CancellationToken cancellationToken)
2020-02-21T19:44:13.7506639Z    at Cake.Scripting.Roslyn.RoslynScriptSession.Execute(Script script) in C:\projects\cake\src\Cake\Scripting\Roslyn\RoslynScriptSession.cs:line 136
2020-02-21T19:44:13.7506809Z    at Cake.Core.Scripting.ScriptRunner.Run(IScriptHost host, FilePath scriptPath, IDictionary`2 arguments) in C:\projects\cake\src\Cake.Core\Scripting\ScriptRunner.cs:line 219
2020-02-21T19:44:13.7506972Z    at Cake.Commands.BuildCommand.Execute(CakeOptions options) in C:\projects\cake\src\Cake\Commands\BuildCommand.cs:line 41
2020-02-21T19:44:13.7507127Z    at Cake.CakeApplication.Run(CakeOptions options) in C:\projects\cake\src\Cake\CakeApplication.cs:line 45
2020-02-21T19:44:13.7507314Z    at Cake.Program.Main() in C:\projects\cake\src\Cake\Program.cs:line 80

Spot the INFO and ERROR messages from GitVersion.

Any fix should be cross platform and work on Windows, Mac and Linux.

[asbjornu]

Is it really missing newlines (LF) and not carriage returns (CR)?

[gitfool]

@asbjornu the above log was from a GitHub Actions runner on Linux. I see the same problem with a runner on Mac. Alas, I didn't get a log from Windows at the time, but I think there's enough evidence.

Also, note that the raw GitHub Actions logs above include the timestamp for every line of output, making it clear that the second line is very long with multiple INFO and ERROR messages from GitVersion.

[asbjornu]

Good points. Some of the log statements in question are found here:

GitVersion/src/GitVersionCore/GitPreparer.cs

Lines 80 to 98 in b3f3867

	public string GetProjectRootDirectoryInternal()
	{
	log.Info($"IsDynamicGitRepository: {IsDynamicGitRepository}");
	if (IsDynamicGitRepository)
	{
	log.Info($"Returning Project Root as {GetWorkingDirectory()}");
	return GetWorkingDirectory();
	}
	var dotGitDirectory = Repository.Discover(GetWorkingDirectory());
	if (string.IsNullOrEmpty(dotGitDirectory))
	throw new DirectoryNotFoundException($"Can't find the .git directory in {dotGitDirectory}");
	using var repo = new Repository(dotGitDirectory);
	var result = repo.Info.WorkingDirectory;
	log.Info($"Returning Project Root from DotGitDirectory: {dotGitDirectory} - {result}");
	return result;
	}

Which in turn is eventually invoking ILog.Write(), implemented by the following:

GitVersion/src/GitVersionCore/Logging/Log.cs

Lines 30 to 45 in b3f3867

	public void Write(Verbosity verbosity, LogLevel level, string format, params object[] args)
	{
	if (verbosity > Verbosity)
	{
	return;
	}
	var message = args.Any() ? string.Format(format, args) : format;
	var formattedString = FormatMessage(message, level.ToString().ToUpperInvariant());
	foreach (var appender in appenders)
	{
	appender.WriteTo(level, formattedString);
	}
	sb.Append(formattedString);
	}

Seeing how it's only doing StringBuilder.Append(), I wonder why there are any newlines in the log at all. 🤔

[gitfool]

That must be it; s/Append/AppendLine/g? 😛

[asbjornu]

Sure, it’s worth a try. 🙈

[gitfool]

Okay. I'll have a closer look and submit a PR soon. (Currently at work and the weekend awaits.)