test: fix the missing controller logs (#3117)

Author: jrsmroz

internal/cmd/rootcmd/run.go

@@ -3,9 +3,12 @@ package rootcmd
 import (
 	"fmt"
 
+	"github.com/sirupsen/logrus"
+
 	"github.com/kong/kubernetes-ingress-controller/v2/internal/manager"
 )
 
+// Run starts the controller manager.
 func Run(c *manager.Config) error {
 	ctx, err := SetupSignalHandler(c)
 	if err != nil {
@@ -18,3 +21,18 @@ func Run(c *manager.Config) error {
 	}
 	return manager.Run(ctx, c, diag.ConfigDumps)
 }
+
+// RunWithLogger starts the controller manager.
+// This function is intended for use in tests, where the logger can be injected.
+func RunWithLogger(c *manager.Config, l logrus.FieldLogger) error {
+	ctx, err := SetupSignalHandler(c)
+	if err != nil {
+		return fmt.Errorf("failed to setup signal handler: %w", err)
+	}
+
+	diag, err := StartDiagnosticsServer(ctx, manager.DiagnosticsPort, c)
+	if err != nil {
+		return fmt.Errorf("failed to start diagnostics server: %w", err)
+	}
+	return manager.RunWithLogger(ctx, c, diag.ConfigDumps, l)
+}

internal/manager/run.go

@@ -12,6 +12,7 @@ import (
 	"github.com/avast/retry-go/v4"
 	"github.com/blang/semver/v4"
 	"github.com/kong/go-kong/kong"
+	"github.com/sirupsen/logrus"
 	"k8s.io/apimachinery/pkg/runtime"
 	utilruntime "k8s.io/apimachinery/pkg/util/runtime"
 	clientgoscheme "k8s.io/client-go/kubernetes/scheme"
@@ -39,10 +40,16 @@ import (
 
 // Run starts the controller manager and blocks until it exits.
 func Run(ctx context.Context, c *Config, diagnostic util.ConfigDumpDiagnostic) error {
-	deprecatedLogger, _, err := setupLoggers(c)
+	deprecatedLogger, _, err := SetupLoggers(c)
 	if err != nil {
 		return err
 	}
+	return RunWithLogger(ctx, c, diagnostic, deprecatedLogger)
+}
+
+// RunWithLogger starts the controller manager and blocks until it exits.
+// This function is intended for use in tests, where the logger can be injected.
+func RunWithLogger(ctx context.Context, c *Config, diagnostic util.ConfigDumpDiagnostic, deprecatedLogger logrus.FieldLogger) error {
 	setupLog := ctrl.Log.WithName("setup")
 	setupLog.Info("starting controller manager", "release", metadata.Release, "repo", metadata.Repo, "commit", metadata.Commit)
 	setupLog.V(util.DebugLevel).Info("the ingress class name has been set", "value", c.IngressClassName)

internal/manager/setup.go

@@ -30,7 +30,8 @@ import (
 // Controller Manager - Setup Utility Functions
 // -----------------------------------------------------------------------------
 
-func setupLoggers(c *Config) (logrus.FieldLogger, logr.Logger, error) {
+// SetupLoggers sets up the loggers for the controller manager.
+func SetupLoggers(c *Config) (logrus.FieldLogger, logr.Logger, error) {
 	deprecatedLogger, err := util.MakeLogger(c.LogLevel, c.LogFormat)
 	if err != nil {
 		return nil, logr.Logger{}, fmt.Errorf("failed to make logger: %w", err)

internal/util/test/controller_manager.go

@@ -5,8 +5,10 @@ import (
 	"fmt"
 	"os"
 
+	"github.com/go-logr/logr"
 	"github.com/kong/kubernetes-testing-framework/pkg/clusters"
 	"github.com/kong/kubernetes-testing-framework/pkg/clusters/addons/kong"
+	"github.com/sirupsen/logrus"
 
 	"github.com/kong/kubernetes-ingress-controller/v2/internal/cmd/rootcmd"
 	"github.com/kong/kubernetes-ingress-controller/v2/internal/manager"
@@ -23,7 +25,7 @@ import (
 // Controller managers started this way will run in the background in a goroutine:
 // The caller must use the provided context.Context to stop the controller manager
 // from running when they're done with it.
-func DeployControllerManagerForCluster(ctx context.Context, cluster clusters.Cluster, additionalFlags ...string) error {
+func DeployControllerManagerForCluster(ctx context.Context, l logrus.FieldLogger, cluster clusters.Cluster, additionalFlags ...string) error {
 	// ensure that the provided test cluster has a kongAddon deployed to it
 	var kongAddon *kong.Addon
 	for _, addon := range cluster.ListAddons() {
@@ -79,10 +81,27 @@ func DeployControllerManagerForCluster(ctx context.Context, cluster clusters.Clu
 	go func() {
 		defer os.Remove(kubeconfig.Name())
 		fmt.Fprintf(os.Stderr, "INFO: Starting Controller Manager for Cluster %s with Configuration: %+v\n", cluster.Name(), config)
-		if err := rootcmd.Run(&config); err != nil {
+		if err := rootcmd.RunWithLogger(&config, l); err != nil {
 			panic(err)
 		}
 	}()
 
 	return nil
 }
+
+// SetupLoggers sets up the loggers for the controller manager.
+// The controller manager logs needs to be setup before the 30s timeout passes.
+// Given the cluster deployment takes time, there is a chance that the timeout
+// will pass before the controller manager logs are setup.
+// This function can be used to sets up the loggers for the controller manager
+// before the cluster deployment.
+func SetupLoggers(logLevel string, logFormat string, logReduceRedundancy bool) (logrus.FieldLogger, logr.Logger, error) {
+	// construct the config for the logger
+	config := manager.Config{
+		LogLevel:            logLevel,
+		LogFormat:           logFormat,
+		LogReduceRedundancy: logReduceRedundancy,
+	}
+
+	return manager.SetupLoggers(&config)
+}

test/conformance/gateway_conformance_test.go

@@ -50,7 +50,8 @@ func TestGatewayConformance(t *testing.T) {
 		"--feature-gates=GatewayAlpha=true",
 		"--anonymous-reports=false",
 	}
-	require.NoError(t, testutils.DeployControllerManagerForCluster(ctx, env.Cluster(), args...))
+
+	require.NoError(t, testutils.DeployControllerManagerForCluster(ctx, globalLogger, env.Cluster(), args...))
 
 	t.Log("creating GatewayClass for gateway conformance tests")
 	gwc := &gatewayv1beta1.GatewayClass{

test/conformance/suite_test.go

@@ -14,26 +14,41 @@ import (
 	"github.com/kong/kubernetes-testing-framework/pkg/clusters/addons/metallb"
 	"github.com/kong/kubernetes-testing-framework/pkg/clusters/types/kind"
 	"github.com/kong/kubernetes-testing-framework/pkg/environments"
+	"github.com/sirupsen/logrus"
+
+	testutils "github.com/kong/kubernetes-ingress-controller/v2/internal/util/test"
 )
 
 var (
 	existingCluster = os.Getenv("KONG_TEST_CLUSTER")
 	ingressClass    = "kong-conformance-tests"
 
-	env environments.Environment
-	ctx context.Context
+	env          environments.Environment
+	ctx          context.Context
+	globalLogger logrus.FieldLogger
 )
 
 func TestMain(m *testing.M) {
 	var cancel context.CancelFunc
 	ctx, cancel = context.WithCancel(context.Background())
 	defer cancel()
 
+	// Logger needs to be configured before anything else happens.
+	// This is because the controller manager has a timeout for
+	// logger initialization, and if the logger isn't configured
+	// after 30s from the start of controller manager package init function,
+	// the controller manager will set up a no op logger and continue.
+	// The logger cannot be configured after that point.
+	logger, _, err := testutils.SetupLoggers("trace", "text", false)
+	if err != nil {
+		exitOnErr(fmt.Errorf("failed to setup loggers: %w", err))
+	}
+	globalLogger = logger
+
 	kongAddon := kong.NewBuilder().WithControllerDisabled().WithProxyAdminServiceTypeLoadBalancer().Build()
 	builder := environments.NewBuilder().WithAddons(metallb.New(), kongAddon)
 	useExistingClusterIfPresent(builder)
 
-	var err error
 	env, err = builder.Build(ctx)
 	exitOnErr(err)
 	defer func() {

test/e2e/istio_test.go

@@ -59,6 +59,15 @@ func TestIstioWithKongIngressGateway(t *testing.T) {
 	ctx, cancel := context.WithCancel(context.Background())
 	defer cancel()
 
+	// Logger needs to be configured before anything else happens.
+	// This is because the controller manager has a timeout for
+	// logger initialization, and if the logger isn't configured
+	// after 30s from the start of controller manager package init function,
+	// the controller manager will set up a no op logger and continue.
+	// The logger cannot be configured after that point.
+	logger, _, err := testutils.SetupLoggers("trace", "text", false)
+	require.NoError(t, err, "failed to configure logger")
+
 	t.Log("configuring cluster addons for the testing environment")
 	metallbAddon := metallb.New()
 	kongBuilder := kong.NewBuilder().
@@ -111,7 +120,7 @@ func TestIstioWithKongIngressGateway(t *testing.T) {
 	}, time.Minute, time.Second)
 
 	t.Log("starting the controller manager")
-	require.NoError(t, testutils.DeployControllerManagerForCluster(ctx, env.Cluster(), "--log-level=debug"))
+	require.NoError(t, testutils.DeployControllerManagerForCluster(ctx, logger, env.Cluster(), "--log-level=debug"))
 
 	t.Log("creating a new mesh-enabled namespace for testing http traffic")
 	namespace := &corev1.Namespace{

test/integration/suite_test.go

@@ -83,6 +83,17 @@ func TestMain(m *testing.M) {
 	ctx, cancel = context.WithCancel(context.Background())
 	defer cancel()
 
+	// Logger needs to be configured before anything else happens.
+	// This is because the controller manager has a timeout for
+	// logger initialization, and if the logger isn't configured
+	// after 30s from the start of controller manager package init function,
+	// the controller manager will set up a no op logger and continue.
+	// The logger cannot be configured after that point.
+	logger, _, err := testutils.SetupLoggers("trace", "text", false)
+	if err != nil {
+		exitOnErrWithCode(fmt.Errorf("failed to setup loggers: %w", err), ExitCodeCantCreateLogger)
+	}
+
 	fmt.Println("INFO: setting up test environment")
 	kongbuilder, extraControllerArgs := generateKongBuilder()
 	kongAddon := kongbuilder.Build()
@@ -129,7 +140,6 @@ func TestMain(m *testing.M) {
 	}
 
 	fmt.Println("INFO: building test environment")
-	var err error
 	env, err = builder.Build(ctx)
 	exitOnErr(err)
 	k8sClient = env.Cluster().Client()
@@ -200,14 +210,14 @@ func TestMain(m *testing.M) {
 			fmt.Sprintf("--admission-webhook-listen=0.0.0.0:%d", testutils.AdmissionWebhookListenPort),
 			"--profiling",
 			"--dump-config",
-			"--log-level=trace",
-			"--debug-log-reduce-redundancy",
+			"--log-level=trace",             // not used, as controller logger is configured separately
+			"--debug-log-reduce-redundancy", // not used, as controller logger is configured separately
 			"--anonymous-reports=false",
 			fmt.Sprintf("--feature-gates=%s", controllerFeatureGates),
 			fmt.Sprintf("--election-namespace=%s", kongAddon.Namespace()),
 		}
 		allControllerArgs := append(standardControllerArgs, extraControllerArgs...)
-		exitOnErr(testutils.DeployControllerManagerForCluster(ctx, env.Cluster(), allControllerArgs...))
+		exitOnErr(testutils.DeployControllerManagerForCluster(ctx, logger, env.Cluster(), allControllerArgs...))
 	}
 
 	gatewayClient, err := gatewayclient.NewForConfig(env.Cluster().Config())

test/integration/utils_test.go

@@ -175,6 +175,10 @@ const (
 	// problems setting up the testing environment and/or cluster.
 	ExitCodeEnvSetupFailed = 104
 
+	// ExitCodeCentCreateLogger is a POSIX compliant exit code for the test suite to indicate
+	// that a failure occurred when trying to create a logger for the test suite.
+	ExitCodeCantCreateLogger = 105
+
 	// kongTestPassword is used as a password only within the context of transient integration test runs
 	// and is left static to help developers debug failures in those testing environments.
 	kongTestPassword = "password"