Travis logs and .NET Core console output

This is a blog post rather than a bug report, partly because I really don't know what's at fault. Others with more knowledge of how the console works in .NET Core, or exactly what the Travis log does, might be able to dig deeper.

TL;DR: If you're running jobs using .NET Core 3.1 on Travis and you care about the console output, you might want to set the TERM environment variable to avoid information being swallowed.

Much of my time is spent in the Google Cloud Libraries for .NET repository. That single repository hosts a lot of libraries, and many of the pull requests are from autogenerated code where the impact on the public API surface may not be immediately obvious. (It would be easy to miss one breaking change within dozens of comment changes, for example.) Our Travis build includes a job to work out the public API changes, which is fantastically useful. (Example)

When we updated our .NET Core SDK to 3.1 - or at least around that time; it may have been coincidence - we noticed that some of the log lines in our Travis jobs seemed to be missing. They were actually missing from all the jobs, but it was particularly noticeable for that change detection" job because the output can often be small, but should always contain a Diff level" line. It's really obvious when that line is missing.

I spent rather longer trying to diagnose what was going wrong than I should have done. A colleague noted that clicking on Raw log" showed that we were getting all the output - it's just that Travis was swallowing some of it, due to control characters being emitted. This blog post is a distillation of what I learned when trying to work out what was going on.

A simple set of Travis jobs

In my DemoCode repository I've created a Travis setup for the sake of this post.

Here are the various files involved:

.travis.yml:

dist: xenial language: csharp mono: none dotnet: 3.1.301 jobs: include: - name: "Default terminal, no-op program" script: TravisConsole/run-dotnet.sh 0 - name: "Default terminal, write two lines" script: TravisConsole/run-dotnet.sh 2 - name: "Mystery terminal, no-op program" env: TERM=mystery script: TravisConsole/run-dotnet.sh 0 - name: "Mystery terminal, write two lines" env: TERM=mystery script: TravisConsole/run-dotnet.sh 2 - name: "Mystery terminal, write two lines, no logo" env: TERM=mystery DOTNET_NOLOGO=true script: TravisConsole/run-dotnet.sh 2

TravisConsole/run-dotnet.sh:

#!/bin/bash set -e cd $(readlink -f $(dirname ${BASH_SOURCE})) echo "Before dotnet run (first)" dotnet run -- $1 echo "After dotnet run (first)" echo "Before dotnet run (second)" dotnet run -- $1 echo "After dotnet run (second)"

TravisConsole/Program.cs:

using System; class Program { static void Main(string[] args) { int count = int.Parse(args[0]); for (int i = 1; i <= count; i++) { Console.WriteLine($"Line {i}"); } } }

So each job runs the same .NET Core console application twice with the same command line argument - either 0 (in which case nothing is printed out) or 2 (in which case two it prints out Line 1" then Line 2"). The shell script also logs before and after executing the console application. The only other differences are in terms of the environment variables:

• Some jobs use TERM=mystery instead of the default
• The final job uses DOTNET_NOLOGO=true

I'll come back to the final job right at the end - we'll concentrate on the impact of the TERM environment variable first, as that's the main point of the post. Next we'll look at the output of the jobs - in each case showing it in the pretty" log first, then in the raw" log. The pretty log has colour, and I haven't tried to reproduce that. I've also only shown the relevant bit - the call to run-dotnet.sh.

You can see all of the output shown here in the Travis UI, of course.

Job 1: Default terminal, no-op programPretty log

$ TravisConsole/run-dotnet.sh 0Before dotnet run (first)Welcome to .NET Core 3.1!---------------------SDK Version: 3.1.301----------------Explore documentation: https://aka.ms/dotnet-docsReport issues and find source on GitHub: https://github.com/dotnet/coreFind out what's new: https://aka.ms/dotnet-whats-newLearn about the installed HTTPS developer cert: https://aka.ms/aspnet-core-httpsUse 'dotnet --help' to see available commands or visit: https://aka.ms/dotnet-cli-docsWrite your first app: https://aka.ms/first-net-core-app--------------------------------------------------------------------------------------Before dotnet run (second)The command "TravisConsole/run-dotnet.sh 0" exited with 0.

Note the lack of After dotnet run in each case.

Raw log

[0K$ TravisConsole/run-dotnet.sh 0Before dotnet run (first)Welcome to .NET Core 3.1!---------------------SDK Version: 3.1.301----------------Explore documentation: https://aka.ms/dotnet-docsReport issues and find source on GitHub: https://github.com/dotnet/coreFind out what's new: https://aka.ms/dotnet-whats-newLearn about the installed HTTPS developer cert: https://aka.ms/aspnet-core-httpsUse 'dotnet --help' to see available commands or visit: https://aka.ms/dotnet-cli-docsWrite your first app: https://aka.ms/first-net-core-app--------------------------------------------------------------------------------------[?1h=[?1h=[?1h=[?1h=[?1h=[?1h=[?1h=After dotnet run (first)Before dotnet run (second)[?1h=[?1h=[?1h=[?1h=[?1h=[?1h=[?1h=After dotnet run (second)travis_time:end:18aa556c:start=1595144448336834755,finish=1595144452475616837,duration=4138782082,event=script[0K[32;1mThe command "TravisConsole/run-dotnet.sh 0" exited with 0.[0m

In the raw log, we can see that After dotnet run is present each time, but with [?1h=[?1h=[?1h=[?1h=[?1h=[?1h=[?1h= before it. Let's see what happens when our console application actually writes to the console.

Job 2: Default terminal, write two linesPretty log

$ TravisConsole/run-dotnet.sh 2Before dotnet run (first)Welcome to .NET Core 3.1!---------------------SDK Version: 3.1.301----------------Explore documentation: https://aka.ms/dotnet-docsReport issues and find source on GitHub: https://github.com/dotnet/coreFind out what's new: https://aka.ms/dotnet-whats-newLearn about the installed HTTPS developer cert: https://aka.ms/aspnet-core-httpsUse 'dotnet --help' to see available commands or visit: https://aka.ms/dotnet-cli-docsWrite your first app: https://aka.ms/first-net-core-app--------------------------------------------------------------------------------------Line 2Before dotnet run (second)Line 2The command "TravisConsole/run-dotnet.sh 2" exited with 0.

This time we don't have After dotnet run - and we don't have Line 1 either. As expected, they are present in the raw log, but with control characters before them:

[0K$ TravisConsole/run-dotnet.sh 2Before dotnet run (first)Welcome to .NET Core 3.1!---------------------SDK Version: 3.1.301----------------Explore documentation: https://aka.ms/dotnet-docsReport issues and find source on GitHub: https://github.com/dotnet/coreFind out what's new: https://aka.ms/dotnet-whats-newLearn about the installed HTTPS developer cert: https://aka.ms/aspnet-core-httpsUse 'dotnet --help' to see available commands or visit: https://aka.ms/dotnet-cli-docsWrite your first app: https://aka.ms/first-net-core-app--------------------------------------------------------------------------------------[?1h=[?1h=[?1h=[?1h=[?1h=[?1h=Line 1Line 2[?1h=After dotnet run (first)Before dotnet run (second)[?1h=[?1h=[?1h=[?1h=[?1h=[?1h=Line 1Line 2[?1h=After dotnet run (second)travis_time:end:00729828:start=1595144445905196926,finish=1595144450121508733,duration=4216311807,event=script[0K[32;1mThe command "TravisConsole/run-dotnet.sh 2" exited with 0.[0m

Now let's try with the TERM environment variable set.

Job 3: Mystery terminal, no-op program

$ TravisConsole/run-dotnet.sh 0Before dotnet run (first)Welcome to .NET Core 3.1!---------------------SDK Version: 3.1.301----------------Explore documentation: https://aka.ms/dotnet-docsReport issues and find source on GitHub: https://github.com/dotnet/coreFind out what's new: https://aka.ms/dotnet-whats-newLearn about the installed HTTPS developer cert: https://aka.ms/aspnet-core-httpsUse 'dotnet --help' to see available commands or visit: https://aka.ms/dotnet-cli-docsWrite your first app: https://aka.ms/first-net-core-app--------------------------------------------------------------------------------------After dotnet run (first)Before dotnet run (second)After dotnet run (second)The command "TravisConsole/run-dotnet.sh 0" exited with 0.

That's more like it! This time the raw log doesn't contain any characters within the script execution itself. (There are still blank lines in the logo" part, admittedly. Not sure why, but we'll get rid of that later anyway.)

[0K$ TravisConsole/run-dotnet.sh 0Before dotnet run (first)Welcome to .NET Core 3.1!---------------------SDK Version: 3.1.301----------------Explore documentation: https://aka.ms/dotnet-docsReport issues and find source on GitHub: https://github.com/dotnet/coreFind out what's new: https://aka.ms/dotnet-whats-newLearn about the installed HTTPS developer cert: https://aka.ms/aspnet-core-httpsUse 'dotnet --help' to see available commands or visit: https://aka.ms/dotnet-cli-docsWrite your first app: https://aka.ms/first-net-core-app--------------------------------------------------------------------------------------After dotnet run (first)Before dotnet run (second)After dotnet run (second)travis_time:end:11222e41:start=1595144449188901003,finish=1595144453242229433,duration=4053328430,event=script[0K[32;1mThe command "TravisConsole/run-dotnet.sh 0" exited with 0.[0m

Let's just check that it still works with actual output:

Job 4: Mystery terminal, write two linesPretty log

4.45s$ TravisConsole/run-dotnet.sh 2Before dotnet run (first)Welcome to .NET Core 3.1!---------------------SDK Version: 3.1.301----------------Explore documentation: https://aka.ms/dotnet-docsReport issues and find source on GitHub: https://github.com/dotnet/coreFind out what's new: https://aka.ms/dotnet-whats-newLearn about the installed HTTPS developer cert: https://aka.ms/aspnet-core-httpsUse 'dotnet --help' to see available commands or visit: https://aka.ms/dotnet-cli-docsWrite your first app: https://aka.ms/first-net-core-app--------------------------------------------------------------------------------------Line 1Line 2After dotnet run (first)Before dotnet run (second)Line 1Line 2After dotnet run (second)The command "TravisConsole/run-dotnet.sh 2" exited with 0.

Exactly what we'd expect from inspection. The raw log doesn't hold any surprises either.

Raw log

[0K$ TravisConsole/run-dotnet.sh 2Before dotnet run (first)Welcome to .NET Core 3.1!---------------------SDK Version: 3.1.301----------------Explore documentation: https://aka.ms/dotnet-docsReport issues and find source on GitHub: https://github.com/dotnet/coreFind out what's new: https://aka.ms/dotnet-whats-newLearn about the installed HTTPS developer cert: https://aka.ms/aspnet-core-httpsUse 'dotnet --help' to see available commands or visit: https://aka.ms/dotnet-cli-docsWrite your first app: https://aka.ms/first-net-core-app--------------------------------------------------------------------------------------Line 1Line 2After dotnet run (first)Before dotnet run (second)Line 1Line 2After dotnet run (second)travis_time:end:0203f787:start=1595144444502091825,finish=1595144448950945977,duration=4448854152,event=script[0K[32;1mThe command "TravisConsole/run-dotnet.sh 2" exited with 0.[0m

Job 5: Mystery terminal, write two lines, no logo

While job 4 is almost exactly what we want, it's still got the annoying Welcome to .NET Core 3.1!" section. That's a friendly welcome for users in an interactive context, but pointless for continuous integration. Fortunately it's now easy to turn off by setting DOTNET_NOLOGO=true. We now have exactly the log we'd want:

Pretty log

$ TravisConsole/run-dotnet.sh 2Before dotnet run (first)Line 1Line 2After dotnet run (first)Before dotnet run (second)Line 1Line 2After dotnet run (second)The command "TravisConsole/run-dotnet.sh 2" exited with 0.

Raw log

[0K$ TravisConsole/run-dotnet.sh 2Before dotnet run (first)Line 1Line 2After dotnet run (first)Before dotnet run (second)Line 1Line 2After dotnet run (second)travis_time:end:0bb5a6d4:start=1595144448986411002,finish=1595144453476210113,duration=4489799111,event=script[0K[32;1mThe command "TravisConsole/run-dotnet.sh 2" exited with 0.[0m

Conclusion

The use of mystery as the value of the TERM environment variable isn't special, other than not being a terminal that either Travis or .NET Core will have any fixed expectations about". I expect that .NET Core is trying to be clever with its output based on the TERM environment variable, and that Travis isn't handling the control characters in quite the way that .NET Core expects it to. Which one is right, and which one is wrong? It doesn't really matter to me, so long as I can fix it.

This does potentially have a cost, of course. Anything which would actually produce prettier output based on the TERM environment variable is being hampered by this change. But so far we haven't seen any problems. (It certainly isn't stopping our Travis logs from using colour, for example.)

I discovered the DOTNET_NOLOGO environment variable - introduced in .NET Core 3.1.301, I think - incidentally while researching this problem. It's not strictly related to the core problem, but it is related to the matter of making CI logs readable" so I thought I'd include it here.

I was rather surprised not to see complaints about this all over the place. As you can see from the code above, it's not like I'm doing anything particularly special" - just writing lines out to the console. Are other developers not having the same problem, or just not noticing the problem? Either way, I hope this post helps either the .NET Core team to dive deeper, find out what's going on and fix it (talking to the Travis team if appropriate), or at least raise awareness of the issue so that others can apply the same workaround.