test: Add tests for logging
Supersedes: 
- https://github.com/moby/moby/pull/43642

(extended with: https://github.com/moby/moby/issues/43647#issuecomment-1141393871)

Add integration tests for the ContainerLogs API call
Each test handle a distinct case of ContainerLogs output.
- Muxed stream, when container is started without tty
- Single stream, when container is started with tty

Add unit test for LogReader suite that tests concurrent logging
It checks that there are no race conditions when logging concurrently
from multiple goroutines.

The tests pass for master.

With the https://github.com/moby/moby/pull/43650 reverted they fail as expected.
In such case, also `TestReadLog/Concurrent` should also fail when not running
with `-race` due to checking if the read messages match those that were logged




**- What I did**
Write unit test for race condition when logging from multiple goroutines at once

**- How to verify it**
1. Run unit tests:
```
make TESTDIRS='github.com/docker/docker/daemon/logger/local'  BIND_DIR=. test-unit
make TESTDIRS='github.com/docker/docker/daemon/logger/jsonfilelog'  BIND_DIR=. test-unit
```
or (is there any way to pass -race to the test-unit?)
```
cd daemon/logger/local
go test -race .
cd -
cd daemon/logger/jsonfilelog
go test -race .
```

2. Run integration tests:
```
make BIND_DIR=. TEST_FILTER='TestLogs' test-integration
```


**- A picture of a cute animal (not mandatory but encouraged)**


integration/container/logs_test.go
package container // import "github.com/docker/docker/integration/container"

import (
	"context"
	"io"
	"testing"

	"github.com/docker/docker/api/types"
	"github.com/docker/docker/integration/internal/container"
	"github.com/docker/docker/pkg/stdcopy"
	"gotest.tools/v3/assert"
	"gotest.tools/v3/skip"
)

// Regression test for #35370
// Makes sure that when following we don't get an EOF error when there are no logs
func TestLogsFollowTailEmpty(t *testing.T) {
	// FIXME(vdemeester) fails on a e2e run on linux...
	skip.If(t, testEnv.IsRemoteDaemon)
	defer setupTest(t)()
	client := testEnv.APIClient()
	ctx := context.Background()

	id := container.Run(ctx, t, client, container.WithCmd("sleep", "100000"))

	logs, err := client.ContainerLogs(ctx, id, types.ContainerLogsOptions{ShowStdout: true, Tail: "2"})
	if logs != nil {
		defer logs.Close()
	}
	assert.Check(t, err)

	_, err = stdcopy.StdCopy(io.Discard, io.Discard, logs)
	assert.Check(t, err)
}

package container // import "github.com/docker/docker/integration/container"

import (
	"bytes"
	"context"
	"io"
	"strings"
	"testing"
	"time"

	"github.com/docker/docker/api/types"
	"github.com/docker/docker/daemon/logger/jsonfilelog"
	"github.com/docker/docker/daemon/logger/local"
	"github.com/docker/docker/integration/internal/container"
	"github.com/docker/docker/integration/internal/termtest"
	"github.com/docker/docker/pkg/stdcopy"
	"gotest.tools/v3/assert"
	"gotest.tools/v3/assert/cmp"
	"gotest.tools/v3/poll"
	"gotest.tools/v3/skip"
)

// Regression test for #35370
// Makes sure that when following we don't get an EOF error when there are no logs
func TestLogsFollowTailEmpty(t *testing.T) {
	// FIXME(vdemeester) fails on a e2e run on linux...
	skip.If(t, testEnv.IsRemoteDaemon)
	defer setupTest(t)()
	client := testEnv.APIClient()
	ctx := context.Background()

	id := container.Run(ctx, t, client, container.WithCmd("sleep", "100000"))

	logs, err := client.ContainerLogs(ctx, id, types.ContainerLogsOptions{ShowStdout: true, Tail: "2"})
	if logs != nil {
		defer logs.Close()
	}
	assert.Check(t, err)

	_, err = stdcopy.StdCopy(io.Discard, io.Discard, logs)
	assert.Check(t, err)
}

func TestLogs(t *testing.T) {
	drivers := []string{local.Name, jsonfilelog.Name}

	for _, logDriver := range drivers {
		t.Run("driver "+logDriver, func(t *testing.T) {
			testLogs(t, logDriver)
		})
	}
}

func testLogs(t *testing.T, logDriver string) {
	defer setupTest(t)()
	client := testEnv.APIClient()
	ctx := context.Background()

	testCases := []struct {
		desc        string
		logOps      types.ContainerLogsOptions
		expectedOut string
		expectedErr string
		tty         bool
	}{
		// TTY, only one output stream
		{
			desc: "tty/stdout and stderr",
			tty:  true,
			logOps: types.ContainerLogsOptions{
				ShowStdout: true,
				ShowStderr: true,
			},
			expectedOut: "this is fineaccidents happen",
		},
		{
			desc: "tty/only stdout",
			tty:  true,
			logOps: types.ContainerLogsOptions{
				ShowStdout: true,
				ShowStderr: false,
			},
			expectedOut: "this is fineaccidents happen",
		},
		{
			desc: "tty/only stderr",
			tty:  true,
			logOps: types.ContainerLogsOptions{
				ShowStdout: false,
				ShowStderr: true,
			},
			expectedOut: "",
		},
		// Without TTY, both stdout and stderr
		{
			desc: "without tty/stdout and stderr",
			tty:  false,
			logOps: types.ContainerLogsOptions{
				ShowStdout: true,
				ShowStderr: true,
			},
			expectedOut: "this is fine",
			expectedErr: "accidents happen",
		},
		{
			desc: "without tty/only stdout",
			tty:  false,
			logOps: types.ContainerLogsOptions{
				ShowStdout: true,
				ShowStderr: false,
			},
			expectedOut: "this is fine",
			expectedErr: "",
		},
		{
			desc: "without tty/only stderr",
			tty:  false,
			logOps: types.ContainerLogsOptions{
				ShowStdout: false,
				ShowStderr: true,
			},
			expectedOut: "",
			expectedErr: "accidents happen",
		},
	}

	for _, tC := range testCases {
		tC := tC
		t.Run(tC.desc, func(t *testing.T) {
			t.Parallel()
			tty := tC.tty
			id := container.Run(ctx, t, client,
				container.WithCmd("sh", "-c", "echo -n this is fine; echo -n accidents happen >&2"),
				container.WithTty(tty),
				container.WithLogDriver(logDriver),
			)
			defer client.ContainerRemove(ctx, id, types.ContainerRemoveOptions{Force: true})

			poll.WaitOn(t, container.IsStopped(ctx, client, id), poll.WithDelay(time.Millisecond*100))

			logs, err := client.ContainerLogs(ctx, id, tC.logOps)
			assert.NilError(t, err)
			defer logs.Close()

			var stdout, stderr bytes.Buffer
			if tty {
				// TTY, only one output stream
				_, err = io.Copy(&stdout, logs)
			} else {
				_, err = stdcopy.StdCopy(&stdout, &stderr, logs)
			}
			assert.NilError(t, err)

			stdoutStr := stdout.String()

			if tty && testEnv.OSType == "windows" {
				stdoutStr = stripEscapeCodes(t, stdoutStr)

				// Special case for Windows Server 2019
				// Check only that the raw output stream contains strings
				// that were printed to container's stdout and stderr.
				// This is a workaround for the backspace being outputted in an unexpected place
				// which breaks the parsed output: https://github.com/moby/moby/issues/43710
				if strings.Contains(testEnv.DaemonInfo.OperatingSystem, "Windows Server Version 1809") {
					if tC.logOps.ShowStdout {
						assert.Check(t, cmp.Contains(stdout.String(), "this is fine"))
						assert.Check(t, cmp.Contains(stdout.String(), "accidents happen"))
					} else {
						assert.DeepEqual(t, stdoutStr, "")
					}
					return
				}

			}

			assert.DeepEqual(t, stdoutStr, tC.expectedOut)
			assert.DeepEqual(t, stderr.String(), tC.expectedErr)
		})
	}
}

// This hack strips the escape codes that appear in the Windows TTY output and don't have
// any effect on the text content.
// This doesn't handle all escape sequences, only ones that were encountered during testing.
func stripEscapeCodes(t *testing.T, input string) string {
	t.Logf("Stripping: %q\n", input)
	output, err := termtest.StripANSICommands(input)
	assert.NilError(t, err)
	return output
}

> I thought that maybe the `\b` is somehow cancelled out by the use of the `set title` + `\a`

The `\a` character is one of two<sub>ish</sub> ways to terminate an OSC sequence such as `set title`. (The other 7-bit way is the two-byte "ST" sequence `0x1b 0x5c`, a.k.a. `ESC \`.) So technically, the `\a` is part of the `set title` command.

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
```

AND IT GETS WEIRDER!

```
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"}
```
Redirecting the `docker run` command's output **affects what gets logged by the daemon!** (`docker run -d` yields 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 display
* `DECTCEM(l)` -- hide cursor
* `SGR(0)` -- set all text formatting attributes to defaults
* `CUP(0;0)` -- move cursor to top-left
* `CR LF` * 49 -- move cursor down by 49 lines
* `CUP(0;0)` -- move cursor to top-left
* `OSC(0;"C:\\bin\\sh.exe\x00")` -- set window title to `C:\bin\sh.exe`
* `DECTCEM(h)` -- show cursor
* `DECTCEM(l)` -- hide cursor

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](https://devblogs.microsoft.com/commandline/windows-command-line-introducing-the-windows-pseudo-console-conpty/#conhost---investing-in-yesterday-for-tomorrow). 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.