utils: Add LogTrace and improve structured logging helpers

Move logging-related functions from the generic `libs/utils` package
to the `libs/logging` package.

- Introduce LogTrace, a helper for logging at high verbosity (level 5).
- Add LogW and LogDeprecation to provide structured warning messages.
- Refactor LogD to delegate to an internal logAtLevel function.
- Replace all ctrl.Log.V(5).Info calls with LogTrace.
- Add unit tests for LogI, LogD, LogTrace, LogW, LogDeprecation, and LogE.

Change-Id: Id3e777983883100890fdc937992b8787dcf672bb

Author: calancha

cli/cmd/dev/gerrit/gerrit.go

@@ -46,6 +46,7 @@ import (
 
 	cliutils "github.com/softwarefactory-project/sf-operator/cli/cmd/utils"
 	"github.com/softwarefactory-project/sf-operator/controllers/libs/base"
+	"github.com/softwarefactory-project/sf-operator/controllers/libs/logging"
 	cutils "github.com/softwarefactory-project/sf-operator/controllers/libs/utils"
 )
 
@@ -526,7 +527,7 @@ func GetAdminRepoURL(env *cliutils.ENV, fqdn string, repoName string) string {
 		os.Exit(1)
 	}
 	apiKey := string(gerritAPIKey.Data["gerrit-admin-api-key"])
-	ctrl.Log.V(5).Info("API Key: " + apiKey)
+	logging.LogTrace("API Key: " + apiKey)
 	repoURL := fmt.Sprintf("https://admin:%s@gerrit.%s/a/%s", apiKey, fqdn, repoName)
 	return repoURL
 }
@@ -544,9 +545,9 @@ func CloneAsAdmin(env *cliutils.ENV, fqdn string, repoName string, dest string,
 		}
 		args = append(args, "clone", repoURL, dest)
 		output = cliutils.RunCmdOrDie("git", args...)
-		ctrl.Log.V(5).Info("captured output:\n" + output)
+		logging.LogTrace("captured output:\n" + output)
 		output = cliutils.RunCmdOrDie("git", "-C", dest, "remote", "add", "gerrit", repoURL)
-		ctrl.Log.V(5).Info("captured output:\n" + output)
+		logging.LogTrace("captured output:\n" + output)
 	} else {
 		ctrl.Log.Info("Repository exists. Resetting remotes...")
 		for _, o := range []string{
@@ -555,7 +556,7 @@ func CloneAsAdmin(env *cliutils.ENV, fqdn string, repoName string, dest string,
 			cliutils.RunCmdOrDie("git", "-C", dest, "fetch", "origin"),
 		} {
 			if o != "" {
-				ctrl.Log.V(5).Info("captured output:\n" + o)
+				logging.LogTrace("captured output:\n" + o)
 			}
 		}
 	}
@@ -573,14 +574,14 @@ func CloneAsAdmin(env *cliutils.ENV, fqdn string, repoName string, dest string,
 	} {
 		output = cliutils.RunCmdOrDie("git", _args...)
 		if output != "" {
-			ctrl.Log.V(5).Info("captured output:\n" + output)
+			logging.LogTrace("captured output:\n" + output)
 		}
 	}
 	if !verify {
 		output = cliutils.RunCmdOrDie("git",
 			"-C", dest, "config", "http.sslverify", "false")
 		if output != "" {
-			ctrl.Log.V(5).Info("captured output:\n" + output)
+			logging.LogTrace("captured output:\n" + output)
 		}
 	}
 }

cli/cmd/nodepool.go

@@ -22,6 +22,7 @@ import (
 
 	cliutils "github.com/softwarefactory-project/sf-operator/cli/cmd/utils"
 	"github.com/softwarefactory-project/sf-operator/controllers"
+	"github.com/softwarefactory-project/sf-operator/controllers/libs/logging"
 	"github.com/spf13/cobra"
 	"k8s.io/client-go/tools/clientcmd"
 	ctrl "sigs.k8s.io/controller-runtime"
@@ -70,9 +71,9 @@ func npCreate(kmd *cobra.Command, args []string) {
 		skipProvidersSecrets, _ := kmd.Flags().GetBool("skip-providers-secrets")
 
 		if nodepoolContext == kubeContext {
-			ctrl.Log.Info("Warning: Nodepool will use the same cluster context as SF")
+			logging.LogW("Nodepool will use the same cluster context as SF")
 			if nodepoolNamespace == ns {
-				ctrl.Log.Info("Warning: Nodepool will manage resources in the same namespace as the Software Factory deployment")
+				logging.LogW("Nodepool will manage resources in the same namespace as the Software Factory deployment")
 			}
 		}
 		CreateNamespaceForNodepool(&sfEnv, nodepoolContext, nodepoolNamespace, skipProvidersSecrets)

cli/cmd/utils/utils.go

@@ -60,7 +60,7 @@ import (
 	opv1 "github.com/operator-framework/api/pkg/operators/v1alpha1"
 	sfv1 "github.com/softwarefactory-project/sf-operator/api/v1"
 	controllers "github.com/softwarefactory-project/sf-operator/controllers"
-	ctrlutils "github.com/softwarefactory-project/sf-operator/controllers/libs/utils"
+	"github.com/softwarefactory-project/sf-operator/controllers/libs/logging"
 
 	"k8s.io/client-go/kubernetes"
 
@@ -167,10 +167,10 @@ func GetCLIContext(command *cobra.Command) (SoftwareFactoryConfigContext, error)
 	if configPath != "" {
 		ctxName, cliContext, err = getContextFromFile(command)
 		if err != nil {
-			ctrlutils.LogE(err, "Could not load config file")
+			logging.LogE(err, "Could not load config file")
 			os.Exit(1)
 		} else {
-			ctrlutils.LogD("Using configuration context " + ctxName)
+			logging.LogD("Using configuration context " + ctxName)
 		}
 	}
 	// Override with defaults
@@ -217,12 +217,12 @@ func GetCLIContext(command *cobra.Command) (SoftwareFactoryConfigContext, error)
 	if cliContext.Dev.SFOperatorRepositoryPath == "" {
 		defaultSFOperatorRepositoryPath, getwdErr := os.Getwd()
 		if getwdErr != nil {
-			ctrlutils.LogE(getwdErr,
+			logging.LogE(getwdErr,
 				"sf-operator-repository-path is not set in `dev` section of the configuration file and unable to determine the current working directory")
 			os.Exit(1)
 		}
 		cliContext.Dev.SFOperatorRepositoryPath = defaultSFOperatorRepositoryPath
-		ctrlutils.LogD("Using current working directory for sf-operator-repository-path: " + cliContext.Dev.SFOperatorRepositoryPath)
+		logging.LogD("Using current working directory for sf-operator-repository-path: " + cliContext.Dev.SFOperatorRepositoryPath)
 	}
 	return cliContext, nil
 }
@@ -267,7 +267,7 @@ func CreateKubernetesClient(contextName string) (client.Client, error) {
 func CreateKubernetesClientOrDie(contextName string) client.Client {
 	cli, err := CreateKubernetesClient(contextName)
 	if err != nil {
-		ctrlutils.LogE(err, "Error creating Kubernetes client")
+		logging.LogE(err, "Error creating Kubernetes client")
 		os.Exit(1)
 	}
 	return cli
@@ -277,7 +277,7 @@ func GetCLIENV(kmd *cobra.Command) (string, ENV) {
 
 	cliCtx, err := GetCLIContext(kmd)
 	if err != nil {
-		ctrlutils.LogE(err, "Error initializing CLI:")
+		logging.LogE(err, "Error initializing CLI:")
 		os.Exit(1)
 	}
 
@@ -311,7 +311,7 @@ func DeleteOrDie(env *ENV, obj client.Object, opts ...client.DeleteOption) bool
 		return false
 	} else if err != nil {
 		msg := fmt.Sprintf("Error while deleting %s \"%s\"", reflect.TypeOf(obj).Name(), obj.GetName())
-		ctrlutils.LogE(err, msg)
+		logging.LogE(err, msg)
 		os.Exit(1)
 	}
 	return true
@@ -323,49 +323,49 @@ func GetMOrDie(env *ENV, name string, obj client.Object) bool {
 		return false
 	} else if err != nil {
 		msg := fmt.Sprintf("Error while fetching %s \"%s\"", reflect.TypeOf(obj).Name(), name)
-		ctrlutils.LogE(err, msg)
+		logging.LogE(err, msg)
 		os.Exit(1)
 	}
 	return true
 }
 
 func UpdateROrDie(env *ENV, obj client.Object) {
 	var msg = fmt.Sprintf("Updating %s \"%s\" in %s", reflect.TypeOf(obj).Name(), obj.GetName(), env.Ns)
-	ctrlutils.LogI(msg)
+	logging.LogI(msg)
 	if err := env.Cli.Update(env.Ctx, obj); err != nil {
 		msg = fmt.Sprintf("Error while updating %s \"%s\"", reflect.TypeOf(obj).Name(), obj.GetName())
-		ctrlutils.LogE(err, msg)
+		logging.LogE(err, msg)
 		os.Exit(1)
 	}
 	msg = fmt.Sprintf("%s \"%s\" updated", reflect.TypeOf(obj).Name(), obj.GetName())
-	ctrlutils.LogI(msg)
+	logging.LogI(msg)
 }
 
 func CreateROrDie(env *ENV, obj client.Object) {
 	var msg = fmt.Sprintf("Creating %s \"%s\" in %s", reflect.TypeOf(obj).Name(), obj.GetName(), env.Ns)
-	ctrlutils.LogI(msg)
+	logging.LogI(msg)
 	obj.SetNamespace(env.Ns)
 	if err := env.Cli.Create(env.Ctx, obj); err != nil {
 		msg = fmt.Sprintf("Error while creating %s \"%s\"", reflect.TypeOf(obj).Name(), obj.GetName())
-		ctrlutils.LogE(err, msg)
+		logging.LogE(err, msg)
 		os.Exit(1)
 	}
 	msg = fmt.Sprintf("%s \"%s\" created", reflect.TypeOf(obj).Name(), obj.GetName())
-	ctrlutils.LogI(msg)
+	logging.LogI(msg)
 }
 
 func DeleteAllOfOrDie(env *ENV, obj client.Object, opts ...client.DeleteAllOfOption) {
 	if err := env.Cli.DeleteAllOf(env.Ctx, obj, opts...); err != nil {
 		var msg = "Error while deleting"
-		ctrlutils.LogE(err, msg)
+		logging.LogE(err, msg)
 		os.Exit(1)
 	}
 }
 
 func GetCLIctxOrDie(kmd *cobra.Command, args []string, allowedArgs []string) SoftwareFactoryConfigContext {
 	cliCtx, err := GetCLIContext(kmd)
 	if err != nil {
-		ctrlutils.LogE(err, "Error initializing:")
+		logging.LogE(err, "Error initializing:")
 		os.Exit(1)
 	}
 	if len(allowedArgs) == 0 {
@@ -374,15 +374,15 @@ func GetCLIctxOrDie(kmd *cobra.Command, args []string, allowedArgs []string) Sof
 	} else {
 		argumentError := errors.New("argument must be in: " + strings.Join(allowedArgs, ", "))
 		if len(args) != 1 {
-			ctrlutils.LogE(argumentError, "Need one argument")
+			logging.LogE(argumentError, "Need one argument")
 			os.Exit(1)
 		}
 		for _, a := range allowedArgs {
 			if args[0] == a {
 				return cliCtx
 			}
 		}
-		ctrlutils.LogE(argumentError, "Unknown argument "+args[0])
+		logging.LogE(argumentError, "Unknown argument "+args[0])
 		os.Exit(1)
 	}
 	return SoftwareFactoryConfigContext{}
@@ -408,8 +408,8 @@ func RunCmdWithEnvOrDie(environ []string, cmd string, args ...string) string {
 	kmd.Env = append(os.Environ(), environ...)
 	out, err := kmd.CombinedOutput()
 	if err != nil {
-		ctrlutils.LogE(err, "Could not run command '"+cmd+"'")
-		ctrlutils.LogI("Captured output:\n" + string(out))
+		logging.LogE(err, "Could not run command '"+cmd+"'")
+		logging.LogI("Captured output:\n" + string(out))
 		os.Exit(1)
 	}
 	return string(out)
@@ -425,7 +425,7 @@ func EnsureNamespaceOrDie(env *ENV, name string) {
 		ns.Name = name
 		CreateROrDie(env, &ns)
 	} else if err != nil {
-		ctrlutils.LogE(err, "Error checking namespace "+name)
+		logging.LogE(err, "Error checking namespace "+name)
 		os.Exit(1)
 	}
 }
@@ -440,7 +440,7 @@ func EnsureServiceAccountOrDie(env *ENV, name string) {
 func WriteContentToFile(filePath string, content []byte, mode fs.FileMode) {
 	err := os.WriteFile(filePath, content, mode)
 	if err != nil {
-		ctrlutils.LogE(err, "Can not write a file "+filePath)
+		logging.LogE(err, "Can not write a file "+filePath)
 		os.Exit(1)
 	}
 }
@@ -453,7 +453,7 @@ func VarListToMap(varsList []string) map[string]string {
 		tokens := strings.Split(v, "=")
 
 		if len(tokens) != 2 {
-			ctrlutils.LogE(errors.New("parse error"), "parsed value `"+v+"` needs to be defined as 'foo=bar'")
+			logging.LogE(errors.New("parse error"), "parsed value `"+v+"` needs to be defined as 'foo=bar'")
 			os.Exit(1)
 		}
 		vars[tokens[0]] = tokens[1]
@@ -464,7 +464,7 @@ func VarListToMap(varsList []string) map[string]string {
 func CreateDirectory(dirPath string, mode fs.FileMode) {
 	err := os.MkdirAll(dirPath, mode)
 	if err != nil {
-		ctrlutils.LogE(err, "Can not create directory "+dirPath)
+		logging.LogE(err, "Can not create directory "+dirPath)
 		os.Exit(1)
 	}
 }
@@ -482,7 +482,7 @@ func GetClientset(kubeContext string) (*rest.Config, *kubernetes.Clientset) {
 	restConfig := controllers.GetConfigContextOrDie(kubeContext)
 	kubeClientset, err := kubernetes.NewForConfig(restConfig)
 	if err != nil {
-		ctrlutils.LogE(err, "Could not instantiate Clientset")
+		logging.LogE(err, "Could not instantiate Clientset")
 		os.Exit(1)
 	}
 	return restConfig, kubeClientset
@@ -510,7 +510,7 @@ func RunRemoteCmd(kubeContext string, namespace string, podName string, containe
 	if err != nil {
 		errMsg := fmt.Sprintf("Command \"%s\" [Pod: %s - Container: %s] failed with the following stderr: %s",
 			strings.Join(cmdArgs, " "), podName, containerName, errorBuffer.String())
-		ctrlutils.LogE(err, errMsg)
+		logging.LogE(err, errMsg)
 		os.Exit(1)
 	}
 	return buffer
@@ -521,10 +521,10 @@ func ReadYAMLToMapOrDie(filePath string) map[string]interface{} {
 	secretContent := make(map[string]interface{})
 	err := yaml.Unmarshal(readFile, &secretContent)
 	if err != nil {
-		ctrlutils.LogE(err, "Problem on reading the file content")
+		logging.LogE(err, "Problem on reading the file content")
 	}
 	if len(secretContent) == 0 {
-		ctrlutils.LogE(errors.New("file is empty"), "The file is empty or it does not exist!")
+		logging.LogE(errors.New("file is empty"), "The file is empty or it does not exist!")
 		os.Exit(1)
 	}
 	return secretContent
@@ -533,7 +533,7 @@ func ReadYAMLToMapOrDie(filePath string) map[string]interface{} {
 func GetKubectlPath() string {
 	kubectlPath, err := exec.LookPath("kubectl")
 	if err != nil {
-		ctrlutils.LogE(errors.New("no kubectl binary"),
+		logging.LogE(errors.New("no kubectl binary"),
 			"No 'kubectl' binary found. Please install the 'kubectl' binary before attempting a restore")
 		os.Exit(1)
 	}
@@ -547,7 +547,7 @@ func ExecuteKubectlClient(ns string, podName string, containerName string, execu
 
 	err := cmd.Run()
 	if err != nil {
-		ctrlutils.LogE(err, "There is an issue on executing command: "+executeCommand)
+		logging.LogE(err, "There is an issue on executing command: "+executeCommand)
 		os.Exit(1)
 	}
 
@@ -556,7 +556,7 @@ func ExecuteKubectlClient(ns string, podName string, containerName string, execu
 func GetKubeConfig() *clientcmdapi.Config {
 	clientCfg, err := clientcmd.NewDefaultClientConfigLoadingRules().Load()
 	if err != nil {
-		ctrlutils.LogE(err, "Could not find the kubeconfig")
+		logging.LogE(err, "Could not find the kubeconfig")
 		os.Exit(1)
 	}
 	return clientCfg
@@ -580,7 +580,7 @@ func GetKubeConfigContextByName(contextName string) (*clientcmdapi.Context, stri
 	// Load the context
 	context, err := clientCfg.Contexts[contextName]
 	if !err {
-		ctrlutils.LogD("could not find the context " + contextName)
+		logging.LogD("could not find the context " + contextName)
 	}
 	return context, contextName
 }

controllers/config.go

@@ -9,6 +9,7 @@ import (
 	_ "embed"
 
 	"github.com/softwarefactory-project/sf-operator/controllers/libs/base"
+	"github.com/softwarefactory-project/sf-operator/controllers/libs/logging"
 	"github.com/softwarefactory-project/sf-operator/controllers/libs/utils"
 	batchv1 "k8s.io/api/batch/v1"
 	apiv1 "k8s.io/api/core/v1"
@@ -91,7 +92,7 @@ func (r *SFController) SetupBaseSecrets(internalTenantSecretsVersion string) boo
 	var secret apiv1.Secret
 	secretName := "config-update-secrets"
 	if !r.GetM(secretName, &secret) {
-		utils.LogI("Creating the config-update service account secret")
+		logging.LogI("Creating the config-update service account secret")
 		secret = apiv1.Secret{
 			Type: "kubernetes.io/service-account-token",
 			ObjectMeta: metav1.ObjectMeta{
@@ -129,13 +130,13 @@ func (r *SFController) SetupBaseSecrets(internalTenantSecretsVersion string) boo
 	}
 
 	if !found {
-		utils.LogI("Creating base secret job")
+		logging.LogI("Creating base secret job")
 		r.CreateR(r.RunCommand(jobName, []string{"config-create-zuul-secrets"}, extraCmdVars))
 		return false
 	} else if job.Status.Succeeded >= 1 {
 		return true
 	} else {
-		utils.LogI("Waiting for base secret job result")
+		logging.LogI("Waiting for base secret job result")
 		return false
 	}
 }
@@ -213,7 +214,7 @@ func (r *SFController) SetupConfigJob() bool {
 		// This ensures that the zuul-scheduler loaded the provisionned Zuul config
 		// for the 'internal' tenant
 		if needReconfigureTenant {
-			utils.LogI("Running tenant-reconfigure for the 'internal' tenant")
+			logging.LogI("Running tenant-reconfigure for the 'internal' tenant")
 			if r.runZuulInternalTenantReconfigure() {
 				// Create an empty ConfigMap to keep note the reconfigure has been already done
 				zsInternalTenantReconfigure.ObjectMeta = metav1.ObjectMeta{

controllers/gateway.go

@@ -9,6 +9,7 @@ import (
 	_ "embed"
 
 	"github.com/softwarefactory-project/sf-operator/controllers/libs/base"
+	"github.com/softwarefactory-project/sf-operator/controllers/libs/logging"
 	"github.com/softwarefactory-project/sf-operator/controllers/libs/utils"
 	appsv1 "k8s.io/api/apps/v1"
 	apiv1 "k8s.io/api/core/v1"
@@ -55,7 +56,7 @@ func (r *SFController) DeployHTTPDGateway() bool {
 	current := appsv1.Deployment{}
 	if r.GetM(ident, &current) {
 		if !utils.MapEquals(&current.Spec.Template.ObjectMeta.Annotations, &annotations) {
-			utils.LogI("gateway configuration changed, rollout gateway pods ...")
+			logging.LogI("gateway configuration changed, rollout gateway pods ...")
 			current.Spec = dep.DeepCopy().Spec
 			r.UpdateR(&current)
 			return false