The tests were failing on CI running Windows Server 2019 because the output contains an unexpected backspace character:
\x1b[2J\x1b[?25l\x1b[m\x1b[Hthis is fine\b\x1b]0;C:\\bin\\sh.exe\x00\a\x1b[?25h\x1b[?25laccidents happen \b\x1b[?25h\x1b[Ht\x1b[1;29H
It looks like the weird backspacing only happens on Windows Server 2019. There are two distinct weird things in the logged string this is fine\b\x1b]0;C:\\bin\\sh.exe\x00\a: the backspace command before the OSC Set Window Title sequence, and the OSC command's argument is null-terminated when it shouldn't be. I booted up a Windows Server 2019 VM and played around a bit to characterize the issue. Note that I'm using Windows Powershell 5.1.
PS> docker build -t busybox --build-arg WINDOWS_BASE_IMAGE=mcr.microsoft.com/windows/servercore `
--build-arg WINDOWS_BASE_IMAGE_TAG=ltsc2019 `
.\contrib\busybox\
PS> docker run --rm -it busybox sh -c "echo -n this is fine; echo -n accidents happen >&2" | Format-Hex
00 01 02 03 04 05 06 07 08 09 0A 0B 0C 0D 0E 0F
00000000 1B 5B 32 4A 1B 5B 3F 32 35 6C 1B 5B 6D 1B 5B 48 .[2J.[?25l.[m.[H
00000010 74 68 69 73 20 69 73 20 66 69 6E 65 08 1B 5D 30 this is fine..]0
00000020 3B 43 3A 5C 62 69 6E 5C 73 68 2E 65 78 65 00 07 ;C:\bin\sh.exe..
00000030 1B 5B 3F 32 35 68 1B 5B 3F 32 35 6C 61 63 63 69 .[?25h.[?25lacci
00000040 64 65 6E 74 73 20 68 61 70 70 65 6E 20 08 1B 5B dents happen ..[
00000050 3F 32 35 68 ?25h
PS> docker run --rm -it busybox sh -c "echo -n this is fine; echo -n accidents happen >&2" | Write-Output
this is finaccidents happen
PS> docker run --rm -it busybox sh -c "echo -n this is fine; echo -n accidents happen >&2"
this is fineaccidents happen
PS> docker run --name logweird1 -t busybox sh -c "echo -n this is fine; echo -n accidents happen >&2"
this is fineaccidents happen
PS> docker logs logweird1
this is fineaccidents happen
PS> get-content (docker inspect logweird1 --format '{{.LogPath}}')
{"log":"\u001b[2J\u001b[?25l\u001b[m\u001b[H\r\n","stream":"stdout","time":"2022-06-07T19:01:11.8876173Z"}
{"log":"\r\n","stream":"stdout","time":"2022-06-07T19:01:11.8876173Z"}
{"log":"\r\n","stream":"stdout","time":"2022-06-07T19:01:11.8876173Z"}
{"log":"\r\n","stream":"stdout","time":"2022-06-07T19:01:11.8876173Z"}
{"log":"\r\n","stream":"stdout","time":"2022-06-07T19:01:11.8876173Z"}
{"log":"\r\n","stream":"stdout","time":"2022-06-07T19:01:11.8882043Z"}
{"log":"\r\n","stream":"stdout","time":"2022-06-07T19:01:11.8882043Z"}
{"log":"\r\n","stream":"stdout","time":"2022-06-07T19:01:11.8907976Z"}
{"log":"\r\n","stream":"stdout","time":"2022-06-07T19:01:11.8907976Z"}
{"log":"\r\n","stream":"stdout","time":"2022-06-07T19:01:11.8907976Z"}
{"log":"\r\n","stream":"stdout","time":"2022-06-07T19:01:11.8907976Z"}
{"log":"\r\n","stream":"stdout","time":"2022-06-07T19:01:11.8907976Z"}
{"log":"\r\n","stream":"stdout","time":"2022-06-07T19:01:11.8907976Z"}
{"log":"\r\n","stream":"stdout","time":"2022-06-07T19:01:11.8907976Z"}
{"log":"\r\n","stream":"stdout","time":"2022-06-07T19:01:11.8907976Z"}
{"log":"\r\n","stream":"stdout","time":"2022-06-07T19:01:11.8907976Z"}
{"log":"\r\n","stream":"stdout","time":"2022-06-07T19:01:11.8907976Z"}
{"log":"\r\n","stream":"stdout","time":"2022-06-07T19:01:11.8907976Z"}
{"log":"\r\n","stream":"stdout","time":"2022-06-07T19:01:11.8907976Z"}
{"log":"\r\n","stream":"stdout","time":"2022-06-07T19:01:11.8907976Z"}
{"log":"\r\n","stream":"stdout","time":"2022-06-07T19:01:11.8907976Z"}
{"log":"\r\n","stream":"stdout","time":"2022-06-07T19:01:11.8907976Z"}
{"log":"\r\n","stream":"stdout","time":"2022-06-07T19:01:11.8907976Z"}
{"log":"\r\n","stream":"stdout","time":"2022-06-07T19:01:11.8907976Z"}
{"log":"\r\n","stream":"stdout","time":"2022-06-07T19:01:11.8907976Z"}
{"log":"\r\n","stream":"stdout","time":"2022-06-07T19:01:11.8907976Z"}
{"log":"\r\n","stream":"stdout","time":"2022-06-07T19:01:11.8907976Z"}
{"log":"\r\n","stream":"stdout","time":"2022-06-07T19:01:11.8907976Z"}
{"log":"\r\n","stream":"stdout","time":"2022-06-07T19:01:11.8907976Z"}
{"log":"\r\n","stream":"stdout","time":"2022-06-07T19:01:11.8907976Z"}
{"log":"\r\n","stream":"stdout","time":"2022-06-07T19:01:11.8907976Z"}
{"log":"\r\n","stream":"stdout","time":"2022-06-07T19:01:11.8907976Z"}
{"log":"\r\n","stream":"stdout","time":"2022-06-07T19:01:11.8907976Z"}
{"log":"\r\n","stream":"stdout","time":"2022-06-07T19:01:11.8907976Z"}
{"log":"\r\n","stream":"stdout","time":"2022-06-07T19:01:11.8907976Z"}
{"log":"\r\n","stream":"stdout","time":"2022-06-07T19:01:11.8907976Z"}
{"log":"\r\n","stream":"stdout","time":"2022-06-07T19:01:11.8907976Z"}
{"log":"\r\n","stream":"stdout","time":"2022-06-07T19:01:11.8907976Z"}
{"log":"\r\n","stream":"stdout","time":"2022-06-07T19:01:11.8907976Z"}
{"log":"\r\n","stream":"stdout","time":"2022-06-07T19:01:11.8907976Z"}
{"log":"\r\n","stream":"stdout","time":"2022-06-07T19:01:11.8907976Z"}
{"log":"\r\n","stream":"stdout","time":"2022-06-07T19:01:11.8907976Z"}
{"log":"\r\n","stream":"stdout","time":"2022-06-07T19:01:11.8915006Z"}
{"log":"\r\n","stream":"stdout","time":"2022-06-07T19:01:11.8915006Z"}
{"log":"\r\n","stream":"stdout","time":"2022-06-07T19:01:11.8915006Z"}
{"log":"\r\n","stream":"stdout","time":"2022-06-07T19:01:11.8915006Z"}
{"log":"\r\n","stream":"stdout","time":"2022-06-07T19:01:11.8915006Z"}
{"log":"\r\n","stream":"stdout","time":"2022-06-07T19:01:11.8915006Z"}
{"log":"\r\n","stream":"stdout","time":"2022-06-07T19:01:11.8915006Z"}
{"log":"\u001b[H\u001b]0;C:\\bin\\sh.exe\u0000\u0007\u001b[?25h\u001b[?25lthis is fineaccidents happen \u0008\u001b[?25h\u001b[Ht\u001b[1;29H","stream":"stdout","time":"2022-06-07T19:01:12.5417731Z"}
PS> docker run --name logweird2 -t busybox sh -c "echo -n this is fine; echo -n accidents happen >&2" | write-output
this is finaccidents happen
PS> get-content (docker inspect logweird2 --format '{{.LogPath}}')
{"log":"\u001b[2J\u001b[?25l\u001b[m\u001b[Hthis is fine\u0008\u001b]0;C:\\bin\\sh.exe\u0000\u0007\u001b[?25h\u001b[?25laccidents happen \u0008\u001b[?25h","stream":"stdout","time":"2022-06-07T19:04:06.1768156Z"}
The console-attached logs might hold clues to what's going wrong. The sequence of VT commands preceding the first printed characters decodes as follows:
My terminal window was sized to be 50 lines tall when I ran the command, so I don't think the 49 CRLFs is a coincidence. That sequence of commands looks like how a somewhat naive renderer would "repaint" a VT terminal to the state of a cleared text-mode screen buffer. This should come as no surprise as rendering a Win32 Console API screen buffer to a stream of VT sequences is one of the jobs of conhost.exe. My theory is that perhaps the Windows Server 2019 conhost.exe (or the copy inside the base image?) VT renderer starts out in some bad state which results in backspace characters getting output in the wrong places and other rendering oddities, and that setting the ConPTY's terminal dimensions has a side effect of putting the renderer into a good state. The Docker CLI keeps the container PTY dimensions synced with the attached terminal dimensions when stdout is a console, which would explain the differences in behavior between attached and detached/redirected. I have occasionally seen the "e" in "fine" overtyped when the output is not redirected, which could be explained by my theory as there being a race between the container outputting to the PTY and the Docker CLI setting the terminal dimensions. I have witnessed several variations of output by repeatedly running the same container multiple times so there's quite a bit of non-determinism in the PTY rendering, which either uninitialized memory in conhost.exe or a race condition could both potentially explain. Sleeping for half a second seems to result in deterministic output when outputting to an attached console, which is consistent with my set terminal dimensions race-condition theory. But then again, I've also seen nondeterministic output on detached container runs that I couldn't reproduce when I added a sleep, so maybe there's more than one race in play?
In conclusion, the integration test found a bug with Windows containers, and conhost.exe might be involved.
This was detected with integration tests for logging:
The tests were failing on CI running Windows Server 2019 because the output contains an unexpected backspace character:
\x1b[2J\x1b[?25l\x1b[m\x1b[Hthis is fine\b\x1b]0;C:\\bin\\sh.exe\x00\a\x1b[?25h\x1b[?25laccidents happen \b\x1b[?25h\x1b[Ht\x1b[1;29Hwhich after parsing the escape sequences results in:
this is finaccidents happeninstead ofthis is fineaccidents happenIn-depth analysis by @corhere in the related PR #43669 (comment)
The
\acharacter is one of twoish ways to terminate an OSC sequence such asset title. (The other 7-bit way is the two-byte "ST" sequence0x1b 0x5c, a.k.a.ESC \.) So technically, the\ais part of theset titlecommand.It looks like the weird backspacing only happens on Windows Server 2019. There are two distinct weird things in the logged string
this is fine\b\x1b]0;C:\\bin\\sh.exe\x00\a: the backspace command before the OSC Set Window Title sequence, and the OSC command's argument is null-terminated when it shouldn't be. I booted up a Windows Server 2019 VM and played around a bit to characterize the issue. Note that I'm using Windows Powershell 5.1.AND IT GETS WEIRDER!
Redirecting the
docker runcommand's output affects what gets logged by the daemon! (docker run -dyields the same results as redirecting the output: erroneous backspace.) WHAT? HOW?? WHY??! 🤯 Since container logs always pass through the logging driver and the Engine API, there is no association between the CLI session and the container's pseudo-terminal which would be visible to the OS. The most likely explanation for this inconsistent behavior is that there is something different about the API calls the CLI makes when stdout is and is not a console which is necessary for the behavior to change. Curiously, I have found that writing a newline character to stdout first is sufficient to make redirected/detached output not backspace over the "e" in "fine."The console-attached logs might hold clues to what's going wrong. The sequence of VT commands preceding the first printed characters decodes as follows:
ED(2)-- erase entire displayDECTCEM(l)-- hide cursorSGR(0)-- set all text formatting attributes to defaultsCUP(0;0)-- move cursor to top-leftCR LF* 49 -- move cursor down by 49 linesCUP(0;0)-- move cursor to top-leftOSC(0;"C:\\bin\\sh.exe\x00")-- set window title toC:\bin\sh.exeDECTCEM(h)-- show cursorDECTCEM(l)-- hide cursorMy terminal window was sized to be 50 lines tall when I ran the command, so I don't think the 49 CRLFs is a coincidence. That sequence of commands looks like how a somewhat naive renderer would "repaint" a VT terminal to the state of a cleared text-mode screen buffer. This should come as no surprise as rendering a Win32 Console API screen buffer to a stream of VT sequences is one of the jobs of conhost.exe. My theory is that perhaps the Windows Server 2019 conhost.exe (or the copy inside the base image?) VT renderer starts out in some bad state which results in backspace characters getting output in the wrong places and other rendering oddities, and that setting the ConPTY's terminal dimensions has a side effect of putting the renderer into a good state. The Docker CLI keeps the container PTY dimensions synced with the attached terminal dimensions when stdout is a console, which would explain the differences in behavior between attached and detached/redirected. I have occasionally seen the "e" in "fine" overtyped when the output is not redirected, which could be explained by my theory as there being a race between the container outputting to the PTY and the Docker CLI setting the terminal dimensions. I have witnessed several variations of output by repeatedly running the same container multiple times so there's quite a bit of non-determinism in the PTY rendering, which either uninitialized memory in conhost.exe or a race condition could both potentially explain. Sleeping for half a second seems to result in deterministic output when outputting to an attached console, which is consistent with my set terminal dimensions race-condition theory. But then again, I've also seen nondeterministic output on detached container runs that I couldn't reproduce when I added a sleep, so maybe there's more than one race in play?
In conclusion, the integration test found a bug with Windows containers, and conhost.exe might be involved.