3

I have a strange problem when using System.Diagnostics.Process (on a linux system).

Something outputs ANSI escape sequences each time a Process is started.
The sequence is <ESC>[?1h<ESC>= (DECCKM, DECKPAM), but that isn't produced by the called program, I used pwd here, but the sequence is created with any other program, too.

The sequence seems to be produced outside of the process, as the standard and error output streams can't fetch it.

And the strange thing is, it only occurs after I started a web host!

I build a minimal code example.

using System;
using System.Diagnostics;
using System.Threading;

using Microsoft.Extensions.Hosting;

class Program
{
    static int count;
    static void Main(string[] args)
    {
        CancellationTokenSource cancellationTokenSource = new CancellationTokenSource();

        execTest();

        Host.CreateDefaultBuilder().Build().RunAsync(cancellationTokenSource.Token);
        Thread.Sleep(2000);

        execTest();
        cancellationTokenSource.Cancel();
        Thread.Sleep(2000);

        execTest();
    }

    private static void execTest()
    {
        for (var i = 0; i < 3; i++)
        {
            executeCommand("pwd");
            Console.WriteLine($"Exectest {++count}");
        }
    }

    static void executeCommand(string cmd)
    {
        var process = new Process();
        process.StartInfo.FileName = cmd;
        process.StartInfo.RedirectStandardOutput = true;
        process.StartInfo.RedirectStandardError = true;
        process.Start();
        process.WaitForExit();
    }
}

To see the effect you need a special logging, piping or redirection disables the effect.
And the escape sequences are invisible when xterm interprets them.

Therefore I use script -c myTestProg output.log; cat -A output.log

In the output you can see, that the first three ExecuteTests works as expected, but Exectest 4 to 9 produces this unexpected output.

Exectest 1
Exectest 2
Exectest 3
^[[?1h^[=^[[40m^[[32minfo^[[39m^[[22m^[[49m: Microsoft.Hosting.Lifetime[0]
      Application started. Press Ctrl+C to shut down.
^[[40m^[[32minfo^[[39m^[[22m^[[49m: Microsoft.Hosting.Lifetime[0]
      Hosting environment: Production
^[[40m^[[32minfo^[[39m^[[22m^[[49m: Microsoft.Hosting.Lifetime[0]
      Content root path: /home/jeb/xx/csharp-test
^[[?1h^[=Exectest 4
^[[?1h^[=Exectest 5
^[[?1h^[=Exectest 6
^[[40m^[[32minfo^[[39m^[[22m^[[49m: Microsoft.Hosting.Lifetime[0]
      Application is shutting down...
^[[?1h^[=Exectest 7
^[[?1h^[=Exectest 8
^[[?1h^[=Exectest 9

My main problem is that my program uses Microsoft.Hosting and calls a Process each second, that results in flooding my log files. Even when I disable the output logging of the Host by

.ConfigureLogging(loggingBuilder =>
{
  loggingBuilder.ClearProviders();
});

the problem persists.

What causes the output and how to avoid or suppress it?
Where is the relation between a System.Diagnostics.Process and Microsoft.Extensions.Hosting?

PS: The sequence is produces after Process.Start() and the call program ends, but before the WaitForExit is called, tested with some Thread.Sleep(100)

Thomas Dickey
  • 51,086
  • 7
  • 70
  • 105
jeb
  • 78,592
  • 17
  • 171
  • 225
  • Look like colored log output directed to the console. – Klaus Gütter Aug 13 '21 at 18:12
  • @KlausGütter Yes, the `info` of `Microsoft.Hosting.Lifetime` is green, but the `^[[?1h` seems to be [DECCKM - Enable Cursor Keys Application Mode](https://learn.microsoft.com/en-us/windows/console/console-virtual-terminal-sequences) and `^[=` is `DECKPAM - Enable Keypad Application Mode` but why it is produced by `WaitForExit()`? – jeb Aug 13 '21 at 19:36
  • Did you try to disable colors using `Logging.Console.DisableColors` to `true` inside `appsettings.json`? Check this issue [Logs include control characters (in place of coloring) in Visual Studio output window when using Docker](https://github.com/dotnet/extensions/issues/673) and this PR [Add DisableColors option (#764)](https://github.com/aspnet/Logging/pull/772). Or maybe using environment variable `ASPNETCORE_LOGGING__CONSOLE__DISABLECOLORS` could disavle ANSI escape characters. – Christos Lytras Aug 16 '21 at 09:43
  • @ChristosLytras Thanks for the hint, but disabling the color only removes the escape sequences from the `info: Microsoft.Hosting.Lifetime[0]` but the puzzling `^[[?1h^[=` are still present. – jeb Aug 16 '21 at 11:50

1 Answers1

4

I see the same behaviour that you describe with netcoreapp3.1.

However, as of net5.0 onwards it seems that all calls to Console.WriteLine write the DECCKM|DECPAM sequence first on linux, no need to Host.CreateDefaultBuilder() first.

I couldn't find why older runtime versions triggered the behaviour only after Host.CreateDefaultBuilder() - maybe something to do with the setup of ILoggerFactory.

These escapes enable DEC VT100 Cursor key mode and Keypad Application Mode.

I guess this is done so that keyboards without dedicated cursor / PgUp / PgDn keys can use the keypad.

On ubuntu 1804 you can view the escape sequences configured for the current terminal with infocmp -i:

smkx: {DEC+CKM}{DECPAM}

A simple way to stop this from happening is to reduce the capability level of the terminal with

export TERM=ansi

A netcore app will read the terminal capabilities and skip emitting sequences that aren't supported.

A more targeted way is to remove the offending sequence from the current terminal definition:

infocmp | sed 's/smkx=\\E\[?1h\\E=,//g' | sed 's/$TERM/nosmkx/g' > ~/infocmp.mod
TERM=nosmkx; export TERM
tic -o ~ ~/infocmp.mod
TERMINFO=~/n/nosmkx; export TERMINFO

Some systems use TERMCAP instead of TERMINFO but I assume a similar process can be followed there.

Peter Wishart
  • 11,600
  • 1
  • 26
  • 45
  • Thanks, both solutions work. But still, I can't see why Microsoft think that it was a good idea in the first place – jeb Aug 19 '21 at 07:33
  • 1
    As far as I can tell, its for [VT-100](https://vt100.net/docs/vt100-ug/chapter3.html) compatibility. I'm sure someone is excited that this is finally enabled by default in .net5.0!! – Peter Wishart Aug 19 '21 at 10:32