Merge pull request #46134 from thaJeztah/24.0_backport_fix_daemon_integration_test

[24.0 backport] Improve test daemon logging, and fix TestDaemonProxy integration tests

integration/daemon/daemon_test.go

@@ -9,7 +9,6 @@ import (
 	"os/exec"
 	"path/filepath"
 	"runtime"
-	"strings"
 	"syscall"
 	"testing"
 
@@ -22,6 +21,7 @@ import (
 	"gotest.tools/v3/assert"
 	is "gotest.tools/v3/assert/cmp"
 	"gotest.tools/v3/icmd"
+	"gotest.tools/v3/poll"
 	"gotest.tools/v3/skip"
 )
 
@@ -169,27 +169,40 @@ func TestDaemonProxy(t *testing.T) {
 	skip.If(t, runtime.GOOS == "windows", "cannot start multiple daemons on windows")
 	skip.If(t, os.Getenv("DOCKER_ROOTLESS") != "", "cannot connect to localhost proxy in rootless environment")
 
-	var received string
-	proxyServer := httptest.NewServer(http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) {
-		received = r.Host
-		w.Header().Set("Content-Type", "application/json")
-		_, _ = w.Write([]byte("OK"))
-	}))
-	defer proxyServer.Close()
+	newProxy := func(rcvd *string, t *testing.T) *httptest.Server {
+		s := httptest.NewServer(http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) {
+			*rcvd = r.Host
+			w.Header().Set("Content-Type", "application/json")
+			_, _ = w.Write([]byte("OK"))
+		}))
+		t.Cleanup(s.Close)
+		return s
+	}
 
 	const userPass = "myuser:mypassword@"
 
 	// Configure proxy through env-vars
 	t.Run("environment variables", func(t *testing.T) {
-		t.Setenv("HTTP_PROXY", proxyServer.URL)
-		t.Setenv("HTTPS_PROXY", proxyServer.URL)
-		t.Setenv("NO_PROXY", "example.com")
+		t.Parallel()
 
-		d := daemon.New(t)
-		c := d.NewClientT(t)
-		defer func() { _ = c.Close() }()
 		ctx := context.Background()
-		d.Start(t)
+		var received string
+		proxyServer := newProxy(&received, t)
+
+		d := daemon.New(t, daemon.WithEnvVars(
+			"HTTP_PROXY="+proxyServer.URL,
+			"HTTPS_PROXY="+proxyServer.URL,
+			"NO_PROXY=example.com",
+		))
+		c := d.NewClientT(t)
+
+		d.Start(t, "--iptables=false")
+		defer d.Stop(t)
+
+		info := d.Info(t)
+		assert.Check(t, is.Equal(info.HTTPProxy, proxyServer.URL))
+		assert.Check(t, is.Equal(info.HTTPSProxy, proxyServer.URL))
+		assert.Check(t, is.Equal(info.NoProxy, "example.com"))
 
 		_, err := c.ImagePull(ctx, "example.org:5000/some/image:latest", types.ImagePullOptions{})
 		assert.ErrorContains(t, err, "", "pulling should have failed")
@@ -199,39 +212,49 @@ func TestDaemonProxy(t *testing.T) {
 		_, err = c.ImagePull(ctx, "example.com/some/image:latest", types.ImagePullOptions{})
 		assert.ErrorContains(t, err, "", "pulling should have failed")
 		assert.Equal(t, received, "example.org:5000", "should not have used proxy")
-
-		info := d.Info(t)
-		assert.Equal(t, info.HTTPProxy, proxyServer.URL)
-		assert.Equal(t, info.HTTPSProxy, proxyServer.URL)
-		assert.Equal(t, info.NoProxy, "example.com")
-		d.Stop(t)
 	})
 
 	// Configure proxy through command-line flags
 	t.Run("command-line options", func(t *testing.T) {
-		t.Setenv("HTTP_PROXY", "http://"+userPass+"from-env-http.invalid")
-		t.Setenv("http_proxy", "http://"+userPass+"from-env-http.invalid")
-		t.Setenv("HTTPS_PROXY", "https://"+userPass+"myuser:mypassword@from-env-https.invalid")
-		t.Setenv("https_proxy", "https://"+userPass+"myuser:mypassword@from-env-https.invalid")
-		t.Setenv("NO_PROXY", "ignore.invalid")
-		t.Setenv("no_proxy", "ignore.invalid")
+		t.Parallel()
 
-		d := daemon.New(t)
-		d.Start(t, "--http-proxy", proxyServer.URL, "--https-proxy", proxyServer.URL, "--no-proxy", "example.com")
-
-		logs, err := d.ReadLogFile()
-		assert.NilError(t, err)
-		assert.Assert(t, is.Contains(string(logs), "overriding existing proxy variable with value from configuration"))
-		for _, v := range []string{"http_proxy", "HTTP_PROXY", "https_proxy", "HTTPS_PROXY", "no_proxy", "NO_PROXY"} {
-			assert.Assert(t, is.Contains(string(logs), "name="+v))
-			assert.Assert(t, !strings.Contains(string(logs), userPass), "logs should not contain the non-sanitized proxy URL: %s", string(logs))
-		}
+		ctx := context.Background()
+		var received string
+		proxyServer := newProxy(&received, t)
+
+		d := daemon.New(t, daemon.WithEnvVars(
+			"HTTP_PROXY="+"http://"+userPass+"from-env-http.invalid",
+			"http_proxy="+"http://"+userPass+"from-env-http.invalid",
+			"HTTPS_PROXY="+"https://"+userPass+"myuser:mypassword@from-env-https-invalid",
+			"https_proxy="+"https://"+userPass+"myuser:mypassword@from-env-https-invalid",
+			"NO_PROXY=ignore.invalid",
+			"no_proxy=ignore.invalid",
+		))
+		d.Start(t, "--iptables=false", "--http-proxy", proxyServer.URL, "--https-proxy", proxyServer.URL, "--no-proxy", "example.com")
+		defer d.Stop(t)
 
 		c := d.NewClientT(t)
-		defer func() { _ = c.Close() }()
-		ctx := context.Background()
 
-		_, err = c.ImagePull(ctx, "example.org:5001/some/image:latest", types.ImagePullOptions{})
+		info := d.Info(t)
+		assert.Check(t, is.Equal(info.HTTPProxy, proxyServer.URL))
+		assert.Check(t, is.Equal(info.HTTPSProxy, proxyServer.URL))
+		assert.Check(t, is.Equal(info.NoProxy, "example.com"))
+
+		ok, _ := d.ScanLogsT(ctx, t, daemon.ScanLogsMatchAll(
+			"overriding existing proxy variable with value from configuration",
+			"http_proxy",
+			"HTTP_PROXY",
+			"https_proxy",
+			"HTTPS_PROXY",
+			"no_proxy",
+			"NO_PROXY",
+		))
+		assert.Assert(t, ok)
+
+		ok, logs := d.ScanLogsT(ctx, t, daemon.ScanLogsMatchString(userPass))
+		assert.Assert(t, !ok, "logs should not contain the non-sanitized proxy URL: %s", logs)
+
+		_, err := c.ImagePull(ctx, "example.org:5001/some/image:latest", types.ImagePullOptions{})
 		assert.ErrorContains(t, err, "", "pulling should have failed")
 		assert.Equal(t, received, "example.org:5001")
 
@@ -239,44 +262,49 @@ func TestDaemonProxy(t *testing.T) {
 		_, err = c.ImagePull(ctx, "example.com/some/image:latest", types.ImagePullOptions{})
 		assert.ErrorContains(t, err, "", "pulling should have failed")
 		assert.Equal(t, received, "example.org:5001", "should not have used proxy")
-
-		info := d.Info(t)
-		assert.Equal(t, info.HTTPProxy, proxyServer.URL)
-		assert.Equal(t, info.HTTPSProxy, proxyServer.URL)
-		assert.Equal(t, info.NoProxy, "example.com")
-
-		d.Stop(t)
 	})
 
 	// Configure proxy through configuration file
 	t.Run("configuration file", func(t *testing.T) {
-		t.Setenv("HTTP_PROXY", "http://"+userPass+"from-env-http.invalid")
-		t.Setenv("http_proxy", "http://"+userPass+"from-env-http.invalid")
-		t.Setenv("HTTPS_PROXY", "https://"+userPass+"myuser:mypassword@from-env-https.invalid")
-		t.Setenv("https_proxy", "https://"+userPass+"myuser:mypassword@from-env-https.invalid")
-		t.Setenv("NO_PROXY", "ignore.invalid")
-		t.Setenv("no_proxy", "ignore.invalid")
+		t.Parallel()
+		ctx := context.Background()
 
-		d := daemon.New(t)
+		var received string
+		proxyServer := newProxy(&received, t)
+
+		d := daemon.New(t, daemon.WithEnvVars(
+			"HTTP_PROXY="+"http://"+userPass+"from-env-http.invalid",
+			"http_proxy="+"http://"+userPass+"from-env-http.invalid",
+			"HTTPS_PROXY="+"https://"+userPass+"myuser:mypassword@from-env-https-invalid",
+			"https_proxy="+"https://"+userPass+"myuser:mypassword@from-env-https-invalid",
+			"NO_PROXY=ignore.invalid",
+			"no_proxy=ignore.invalid",
+		))
 		c := d.NewClientT(t)
-		defer func() { _ = c.Close() }()
-		ctx := context.Background()
 
 		configFile := filepath.Join(d.RootDir(), "daemon.json")
 		configJSON := fmt.Sprintf(`{"proxies":{"http-proxy":%[1]q, "https-proxy": %[1]q, "no-proxy": "example.com"}}`, proxyServer.URL)
 		assert.NilError(t, os.WriteFile(configFile, []byte(configJSON), 0644))
 
-		d.Start(t, "--config-file", configFile)
-
-		logs, err := d.ReadLogFile()
-		assert.NilError(t, err)
-		assert.Assert(t, is.Contains(string(logs), "overriding existing proxy variable with value from configuration"))
-		for _, v := range []string{"http_proxy", "HTTP_PROXY", "https_proxy", "HTTPS_PROXY", "no_proxy", "NO_PROXY"} {
-			assert.Assert(t, is.Contains(string(logs), "name="+v))
-			assert.Assert(t, !strings.Contains(string(logs), userPass), "logs should not contain the non-sanitized proxy URL: %s", string(logs))
-		}
+		d.Start(t, "--iptables=false", "--config-file", configFile)
+		defer d.Stop(t)
 
-		_, err = c.ImagePull(ctx, "example.org:5002/some/image:latest", types.ImagePullOptions{})
+		info := d.Info(t)
+		assert.Check(t, is.Equal(info.HTTPProxy, proxyServer.URL))
+		assert.Check(t, is.Equal(info.HTTPSProxy, proxyServer.URL))
+		assert.Check(t, is.Equal(info.NoProxy, "example.com"))
+
+		d.ScanLogsT(ctx, t, daemon.ScanLogsMatchAll(
+			"overriding existing proxy variable with value from configuration",
+			"http_proxy",
+			"HTTP_PROXY",
+			"https_proxy",
+			"HTTPS_PROXY",
+			"no_proxy",
+			"NO_PROXY",
+		))
+
+		_, err := c.ImagePull(ctx, "example.org:5002/some/image:latest", types.ImagePullOptions{})
 		assert.ErrorContains(t, err, "", "pulling should have failed")
 		assert.Equal(t, received, "example.org:5002")
 
@@ -284,17 +312,11 @@ func TestDaemonProxy(t *testing.T) {
 		_, err = c.ImagePull(ctx, "example.com/some/image:latest", types.ImagePullOptions{})
 		assert.ErrorContains(t, err, "", "pulling should have failed")
 		assert.Equal(t, received, "example.org:5002", "should not have used proxy")
-
-		info := d.Info(t)
-		assert.Equal(t, info.HTTPProxy, proxyServer.URL)
-		assert.Equal(t, info.HTTPSProxy, proxyServer.URL)
-		assert.Equal(t, info.NoProxy, "example.com")
-
-		d.Stop(t)
 	})
 
 	// Conflicting options (passed both through command-line options and config file)
 	t.Run("conflicting options", func(t *testing.T) {
+		ctx := context.Background()
 		const (
 			proxyRawURL = "https://" + userPass + "example.org"
 			proxyURL    = "https://xxxxx:xxxxx@example.org"
@@ -308,43 +330,34 @@ func TestDaemonProxy(t *testing.T) {
 
 		err := d.StartWithError("--http-proxy", proxyRawURL, "--https-proxy", proxyRawURL, "--no-proxy", "example.com", "--config-file", configFile, "--validate")
 		assert.ErrorContains(t, err, "daemon exited during startup")
-		logs, err := d.ReadLogFile()
-		assert.NilError(t, err)
+
 		expected := fmt.Sprintf(
 			`the following directives are specified both as a flag and in the configuration file: http-proxy: (from flag: %[1]s, from file: %[1]s), https-proxy: (from flag: %[1]s, from file: %[1]s), no-proxy: (from flag: example.com, from file: example.com)`,
 			proxyURL,
 		)
-		assert.Assert(t, is.Contains(string(logs), expected))
+		poll.WaitOn(t, d.PollCheckLogs(ctx, daemon.ScanLogsMatchString(expected)))
 	})
 
 	// Make sure values are sanitized when reloading the daemon-config
 	t.Run("reload sanitized", func(t *testing.T) {
+		t.Parallel()
+
+		ctx := context.Background()
 		const (
 			proxyRawURL = "https://" + userPass + "example.org"
 			proxyURL    = "https://xxxxx:xxxxx@example.org"
 		)
 
 		d := daemon.New(t)
-		d.Start(t, "--http-proxy", proxyRawURL, "--https-proxy", proxyRawURL, "--no-proxy", "example.com")
+		d.Start(t, "--iptables=false", "--http-proxy", proxyRawURL, "--https-proxy", proxyRawURL, "--no-proxy", "example.com")
 		defer d.Stop(t)
 		err := d.Signal(syscall.SIGHUP)
 		assert.NilError(t, err)
 
-		logs, err := d.ReadLogFile()
-		assert.NilError(t, err)
-
-		// FIXME: there appears to ba a race condition, which causes ReadLogFile
-		//        to not contain the full logs after signaling the daemon to reload,
-		//        causing the test to fail here. As a workaround, check if we
-		//        received the "reloaded" message after signaling, and only then
-		//        check that it's sanitized properly. For more details on this
-		//        issue, see https://github.com/moby/moby/pull/42835/files#r713120315
-		if !strings.Contains(string(logs), "Reloaded configuration:") {
-			t.Skip("Skipping test, because we did not find 'Reloaded configuration' in the logs")
-		}
+		poll.WaitOn(t, d.PollCheckLogs(ctx, daemon.ScanLogsMatchAll("Reloaded configuration:", proxyURL)))
 
-		assert.Assert(t, is.Contains(string(logs), proxyURL))
-		assert.Assert(t, !strings.Contains(string(logs), userPass), "logs should not contain the non-sanitized proxy URL: %s", string(logs))
+		ok, logs := d.ScanLogsT(ctx, t, daemon.ScanLogsMatchString(userPass))
+		assert.Assert(t, !ok, "logs should not contain the non-sanitized proxy URL: %s", logs)
 	})
 }
 

testutil/daemon/daemon.go

@@ -1,8 +1,10 @@
 package daemon // import "github.com/docker/docker/testutil/daemon"
 
 import (
+	"bufio"
 	"context"
 	"encoding/json"
+	"io"
 	"net/http"
 	"os"
 	"os/exec"
@@ -19,11 +21,13 @@ import (
 	"github.com/docker/docker/container"
 	"github.com/docker/docker/pkg/ioutils"
 	"github.com/docker/docker/pkg/stringid"
+	"github.com/docker/docker/pkg/tailfile"
 	"github.com/docker/docker/testutil/request"
 	"github.com/docker/go-connections/sockets"
 	"github.com/docker/go-connections/tlsconfig"
 	"github.com/pkg/errors"
 	"gotest.tools/v3/assert"
+	"gotest.tools/v3/poll"
 )
 
 // LogT is the subset of the testing.TB interface used by the daemon.
@@ -273,6 +277,7 @@ func (d *Daemon) NewClientT(t testing.TB, extraOpts ...client.Opt) *client.Clien
 
 	c, err := d.NewClient(extraOpts...)
 	assert.NilError(t, err, "[%s] could not create daemon client", d.id)
+	t.Cleanup(func() { c.Close() })
 	return c
 }
 
@@ -296,10 +301,105 @@ func (d *Daemon) Cleanup(t testing.TB) {
 	cleanupNetworkNamespace(t, d)
 }
 
+// TailLogsT attempts to tail N lines from the daemon logs.
+// If there is an error the error is only logged, it does not cause an error with the test.
+func (d *Daemon) TailLogsT(t LogT, n int) {
+	lines, err := d.TailLogs(n)
+	if err != nil {
+		t.Logf("[%s] %v", d.id, err)
+		return
+	}
+	for _, l := range lines {
+		t.Logf("[%s] %s", d.id, string(l))
+	}
+}
+
+// PollCheckLogs is a poll.Check that checks the daemon logs using the passed in match function.
+func (d *Daemon) PollCheckLogs(ctx context.Context, match func(s string) bool) poll.Check {
+	return func(t poll.LogT) poll.Result {
+		ok, _, err := d.ScanLogs(ctx, match)
+		if err != nil {
+			return poll.Error(err)
+		}
+		if !ok {
+			return poll.Continue("waiting for daemon logs match")
+		}
+		return poll.Success()
+	}
+}
+
+// ScanLogsMatchString returns a function that can be used to scan the daemon logs for the passed in string (`contains`).
+func ScanLogsMatchString(contains string) func(string) bool {
+	return func(line string) bool {
+		return strings.Contains(line, contains)
+	}
+}
+
+// ScanLogsMatchAll returns a function that can be used to scan the daemon logs until *all* the passed in strings are matched
+func ScanLogsMatchAll(contains ...string) func(string) bool {
+	matched := make(map[string]bool)
+	return func(line string) bool {
+		for _, c := range contains {
+			if strings.Contains(line, c) {
+				matched[c] = true
+			}
+		}
+		return len(matched) == len(contains)
+	}
+}
+
+// ScanLogsT uses `ScanLogs` to match the daemon logs using the passed in match function.
+// If there is an error or the match fails, the test will fail.
+func (d *Daemon) ScanLogsT(ctx context.Context, t testing.TB, match func(s string) bool) (bool, string) {
+	t.Helper()
+	ok, line, err := d.ScanLogs(ctx, match)
+	assert.NilError(t, err)
+	return ok, line
+}
+
+// ScanLogs scans the daemon logs and passes each line to the match function.
+func (d *Daemon) ScanLogs(ctx context.Context, match func(s string) bool) (bool, string, error) {
+	stat, err := d.logFile.Stat()
+	if err != nil {
+		return false, "", err
+	}
+	rdr := io.NewSectionReader(d.logFile, 0, stat.Size())
+
+	scanner := bufio.NewScanner(rdr)
+	for scanner.Scan() {
+		if match(scanner.Text()) {
+			return true, scanner.Text(), nil
+		}
+		select {
+		case <-ctx.Done():
+			return false, "", ctx.Err()
+		default:
+		}
+	}
+	return false, "", scanner.Err()
+}
+
+// TailLogs tails N lines from the daemon logs
+func (d *Daemon) TailLogs(n int) ([][]byte, error) {
+	logF, err := os.Open(d.logFile.Name())
+	if err != nil {
+		return nil, errors.Wrap(err, "error opening daemon log file after failed start")
+	}
+
+	defer logF.Close()
+	lines, err := tailfile.TailFile(logF, n)
+	if err != nil {
+		return nil, errors.Wrap(err, "error tailing log daemon logs")
+	}
+
+	return lines, nil
+}
+
 // Start starts the daemon and return once it is ready to receive requests.
 func (d *Daemon) Start(t testing.TB, args ...string) {
 	t.Helper()
 	if err := d.StartWithError(args...); err != nil {
+		d.TailLogsT(t, 20)
 		d.DumpStackAndQuit() // in case the daemon is stuck
 		t.Fatalf("[%s] failed to start daemon with arguments %v : %v", d.id, d.args, err)
 	}