Skip to content
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

Jump to bottom

MSBuild changes console colors when logging to a file #1792

Closed
natemcmaster opened this issue Mar 3, 2017 · 11 comments
Closed

MSBuild changes console colors when logging to a file #1792

natemcmaster opened this issue Mar 3, 2017 · 11 comments
Assignees
@rainersigwald
Labels
bug triaged

Comments

@natemcmaster
Copy link
Contributor

We started running into build failures on Travis CI using MSBuild. It appears the logger produces thousands of unnecessary ANSI color codes.

Example:
https://travis-ci.org/aspnet/DotNetTools/jobs/206846997
The log output appears normal:
image

But if you look at the raw log file, you'll see that hundreds of color codes have been logged.
https://s3.amazonaws.com/archive.travis-ci.org/jobs/206846997/log.txt

image

cc @dougbu
@natemcmaster natemcmaster mentioned this issue Mar 3, 2017
Closed
@natemcmaster natemcmaster changed the title Console logger emits hundreds of unnecessary ANSI color codes Console logger emits thousands of unnecessary ANSI color codes Mar 3, 2017
@natemcmaster
Copy link
Contributor Author

Severity: this is causing builds to fail because it overflows Travis's maximum logfile size.
Example: in this this build, MSBuild logged 306,775 ANSI color codes that were followed by another ANSI color code with no output between them.

@rainersigwald
Copy link
Member

Possibly related to #505?

@natemcmaster can you try setting /consoleloggerparameters:DisableConsoleColor in your build script to see if that is a viable workaround?

@natemcmaster
Copy link
Contributor Author

Yes, that is the workaround @dougbu is working on

@dougbu
Copy link
Member

dougbu commented Mar 3, 2017

As long as https://github.com/aspnet/KoreBuild/archive/dev.zip wasn't lagging (definitely up-to-date now), this workaround isn't working.

For example https://api.travis-ci.org/jobs/207448561 was started about 5 minutes ago and I checked in the workaround almost half an hour ago. Despite local testing to confirm colours aren't used when CI, TRAVIS, and so on are defined, the raw log (https://api.travis-ci.org/jobs/207448561/log.txt) still contains loads of ANSI escapes. (Of course https://api.travis-ci.org/jobs/207448561/log.txt?deansi=true looks better 😈.)

Any other suggestions? If the ANSI stuff isn't coming from MsBuild, gotta wonder why we're hitting the Travis 4MB log limit.

@dougbu
Copy link
Member

dougbu commented Mar 3, 2017

FYI the workaround relies on the environment variables Travis always sets. See https://docs.travis-ci.com/user/environment-variables/#Default-Environment-Variables I'll run a test in a smaller repo to make sure that page is correct.

@dougbu
Copy link
Member

dougbu commented Mar 3, 2017

My workaround is doing what it's designed to do. But, /clp:DisableConsoleColor isn't helping.

Skip to the bottom of https://travis-ci.org/aspnet/Antiforgery/jobs/207457375 to see the response files we're using when invoking MsBuild. Nonetheless https://api.travis-ci.org/jobs/207457375/log.txt and https://api.travis-ci.org/jobs/207457376/log.txt are really big. A few commands have a few ANSI codes in their output. But, the loads of colour coding happen only with the dotnet msbuild output.

@dougbu
Copy link
Member

dougbu commented Mar 3, 2017

We're using the 1.0.0-rc4-004913 SDK. @rainersigwald any other suggested workarounds with this tooling?

I'm curious how #505 could be related? That PR was merged nearly a year ago.

dougbu added a commit to aspnet/KoreBuild that referenced this issue Mar 5, 2017
@dougbu
Work around dotnet/msbuild#1792
7cd8443 
- piping MsBuild output into `tee` cleans up the excess ANSI character codes

Extend the related `/clp:DisableConsoleColor` fix in fc6f034 to Windows CI machines.
dougbu added a commit to aspnet/KoreBuild that referenced this issue Mar 5, 2017
@dougbu
Work around dotnet/msbuild#1792
f38132c 
- piping MsBuild output into `tee` cleans up the excess ANSI character codes

Extend the related `/clp:DisableConsoleColor` fix in fc6f034 to Windows CI machines.
@dougbu
Copy link
Member

dougbu commented Mar 5, 2017

Found a workaround that actually works: Piping dotnet msbuild output to tee /dev/null cleans the raw Travis logs up completely. See https://s3.amazonaws.com/archive.travis-ci.org/jobs/207844302/log.txt for example.

What is going on here? Are the excess characters coming from something in MsBuild that /clp:DisableConsoleColor doesn't control?

@dougbu dougbu mentioned this issue Mar 6, 2017
Closed
@natemcmaster natemcmaster mentioned this issue Mar 6, 2017
Closed
dougbu added a commit to aspnet/KoreBuild that referenced this issue Mar 6, 2017
@dougbu
Work around dotnet/msbuild#1792
0a4214d 
- piping MsBuild output into `tee` cleans up the excess ANSI character codes
- add `pipefail` option setting; ensure new pipeline doesn't cause false positives

Extend the related `/clp:DisableConsoleColor` fix in fc6f034 to Windows CI machines.
@dougbu dougbu mentioned this issue Mar 6, 2017
Closed
@rainersigwald rainersigwald self-assigned this Mar 8, 2017
@rainersigwald
Copy link
Member

This is very odd. There appear to be a combination of factors at play.

  • When a file logger is attached, MSBuild sets the color on stdout for every message written to the file logger, regardless of the state of /clp:DisableConsoleColor. This happens even on Windows and with Full Framework MSBuild--it just wasn't noticed until now.
  • MSBuild does (unnecessarily) set Console.ForegroundColor even when it doesn't need to. SetColor could easily have an "if not already that color" check.
  • CoreFX attempts to detect whether an output stream is redirected and avoid emitting colors but the implementation has a comment that it's "approximate". I assume the reason it's not causing the setter to be a no-op is that it's incorrect in the Travis case for some reason. I think using tee lets System.Console understand that the output is redirected and avoid emitting the control codes.

The first one is the real problem here. Tracking the second one as #1825.

@rainersigwald rainersigwald changed the title Console logger emits thousands of unnecessary ANSI color codes MSBuild changes console colors when logging to a file Mar 8, 2017
rainersigwald added a commit to rainersigwald/msbuild that referenced this issue Mar 8, 2017
@rainersigwald
Don't set console color from FileLogger
c61cd4d 
Because FileLogger used the default value of the SetColor and ResetColor
delegates, it was quietly changing and resetting console color for every
log message that was considered by the FileLogger. On Windows, this was
unnecessary but not too noticeable. On Unix systems, though, console
colors are set by emitting an escape code to the output stream, so this
became observable.

Explicitly passing the Dont* mechanisms to prevent the unnecessary work
from happening. I removed the null check for the `write` delegate from
ConsoleLogger's constructor because it seemed cleaner to set the
delegate to `null` from FileLogger than to explicitly specify the
default `Console.Out.Write`.

Fixes dotnet#1792.
@rainersigwald rainersigwald mentioned this issue Mar 8, 2017
Merged
@rainersigwald
Copy link
Member

Naturally, the reason for this ridiculous behavior is ridiculous: FileLogger inherits from ConsoleLogger. And didn't overwrite the color-setters.

@dougbu
Copy link
Member

dougbu commented Mar 9, 2017

Naturally 😺

rainersigwald added a commit that referenced this issue Mar 9, 2017
@rainersigwald
Don't set console color from FileLogger (#1827)
6477d90 
Because FileLogger used the default value of the SetColor and ResetColor
delegates, it was quietly changing and resetting console color for every
log message that was considered by the FileLogger. On Windows, this was
unnecessary but not too noticeable. On Unix systems, though, console
colors are set by emitting an escape code to the output stream, so this
became observable.

Explicitly passing the Dont* mechanisms to prevent the unnecessary work
from happening. I removed the null check for the `write` delegate from
ConsoleLogger's constructor because it seemed cleaner to set the
delegate to `null` from FileLogger than to explicitly specify the
default `Console.Out.Write`.

Fixes #1792.
@natemcmaster natemcmaster mentioned this issue Apr 27, 2017
Merged
@jzabroski jzabroski mentioned this issue Apr 10, 2019
Open
@AR-May AR-May added the triaged label Feb 21, 2024
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Assignees

@rainersigwald rainersigwald

Labels
bug triaged
Projects
None yet
Milestone
No milestone
Development

No branches or pull requests
4 participants
@natemcmaster @rainersigwald @dougbu @AR-May