[VC-35738] Use klog and logr logger instead of log in the agent package #609

wallrj · 2024-11-07T13:17:07Z

The aim of this PR is to remove the stdlib log package and the use of the legacy github.com/jetstack/jetstack-secure/logs.Log variable, from the agent package.

I'll create followup PRs to remove logs.Log elsewhere in the code, and ultimately remove that global variable.

$ go test ./cmd/... -v
=== RUN   TestAgentRunOneShot
    agent_test.go:41: Running child process
    agent_test.go:59: STDOUT
        I1107 16:10:35.015613  305780 run.go:57] "Starting" logger="Run" version="development" commit=""
        I1107 16:10:35.017213  305780 config.go:395] "Using the Jetstack Secure API Token auth mode since --api-token was specified." logger="Run"
        I1107 16:10:35.017789  305780 run.go:115] "Healthz endpoints enabled" logger="Run.APIServer" addr=":8081" path="/healthz"
        I1107 16:10:35.017860  305780 run.go:119] "Readyz endpoints enabled" logger="Run.APIServer" addr=":8081" path="/readyz"
        I1107 16:10:35.017965  305780 run.go:457] "Starting" logger="Run.APIServer.ListenAndServe" addr=":8081"
        I1107 16:10:35.019399  305780 run.go:288] "Reading data from local file" logger="Run.gatherAndOutputData" inputPath="testdata/agent/one-shot/success/input.json"
        I1107 16:10:35.019913  305780 run.go:314] "Data saved to local file" logger="Run.gatherAndOutputData" outputPath="/dev/null"
        I1107 16:10:35.020000  305780 run.go:471] "Shutting down" logger="Run.APIServer.ListenAndServe" addr=":8081"
        I1107 16:10:35.020049  305780 run.go:486] "Shutdown complete" logger="Run.APIServer.ListenAndServe" addr=":8081"

    agent_test.go:60: STDERR

--- PASS: TestAgentRunOneShot (0.03s)
PASS
ok      github.com/jetstack/preflight/cmd       0.059s

$ ./hack/e2e/test.sh
...
{
  "ts": 1730995936301.0586,
  "caller": "agent/run.go:348",
  "msg": "Successfully gathered",
  "v": 0,
  "logger": "Run.gatherAndOutputData.gatherData",
  "count": 0,
  "name": "k8s/gateways"
}
{
  "ts": 1730995936301.145,
  "caller": "agent/run.go:348",
  "msg": "Successfully gathered",
  "v": 0,
  "logger": "Run.gatherAndOutputData.gatherData",
  "count": 0,
  "name": "k8s/virtualservices"
}
{
  "ts": 1730995936301.2642,
  "caller": "agent/run.go:381",
  "msg": "Posting data",
  "v": 0,
  "logger": "Run.gatherAndOutputData.postData",
  "baseURL": ""
}
{"ts":1730995937172.0322,"caller":"agent/run.go:392","msg":"Data sent successfully","v":0,"logger":"Run.gatherAndOutputData.postData"}

wallrj · 2024-11-07T15:29:46Z

pkg/agent/run.go

@@ -33,10 +35,7 @@ import (
 	"github.com/jetstack/preflight/pkg/client"
 	"github.com/jetstack/preflight/pkg/datagatherer"
 	"github.com/jetstack/preflight/pkg/kubeconfig"
-	"github.com/jetstack/preflight/pkg/logs"


This was the main goal of this PR; to remove the use of logs from this package.

wallrj · 2024-11-07T15:30:13Z

pkg/agent/config.go

@@ -3,11 +3,11 @@ package agent
 import (
 	"fmt"
 	"io"
-	"log"


And to remove the use of the log module in this package.

wallrj · 2024-11-07T15:36:06Z

pkg/agent/run.go

@@ -230,7 +225,7 @@ func Run(cmd *cobra.Command, args []string) (returnErr error) {
 	// TODO(wallrj): Pass a context to gatherAndOutputData, so that we don't
 	// have to wait for it to finish before exiting the process.
 	for {
-		if err := gatherAndOutputData(eventf, config, preflightClient, dataGatherers); err != nil {
+		if err := gatherAndOutputData(ctx, eventf, config, preflightClient, dataGatherers); err != nil {


For now, the context is only used to the logger into the function.
In a future PR, the context can be passed through to the http clients and used to cancel ongoing connections.
The TODO comment above therefore still stands.

wallrj · 2024-11-07T15:37:20Z

pkg/agent/run.go

@@ -262,7 +257,7 @@ func newEventf(installNS string) (Eventf, error) {
 	var eventf Eventf
 	if os.Getenv("POD_NAME") == "" {
 		eventf = func(eventType, reason, msg string, args ...interface{}) {}
-		logs.Log.Printf("error messages will not show in the pod's events because the POD_NAME environment variable is empty")
+		log.Error(nil, "Error messages will not show in the pod's events because the POD_NAME environment variable is empty")


I have made this an error so that administrators are more likely to see it and act upon it.

pkg/agent/run.go

wallrj · 2024-11-07T15:54:56Z

cmd/root.go

@@ -45,8 +46,9 @@ func init() {
 // will be logged and the process will exit with status 1.
 func Execute() {
 	logs.AddFlags(rootCmd.PersistentFlags())
+	ctx := klog.NewContext(context.Background(), klog.Background())


I was unsure whether calling klog.Background() here, before logs.Initialize() has been called in the PersistentPreRunE function (above); but it seems to work fine.
For example here is an example of the --logging-format=json flag having the desired effect:

$ ./preflight agent --one-shot --output-path=/dev/null --api-token=foo --install-namespace=default --logging-format=json 2>&1 | jl [2024-11-07 15:54:38] Starting [caller=agent/run.go:58 commit= logger=Run version=development] [2024-11-07 15:54:38] Using the Jetstack Secure API Token auth mode since --api-token was specified. [caller=agent/config.go:395 logger=Run] [2024-11-07 15:54:38] ignoring the venafi-cloud.uploader_id field in the config file. This field is not needed in Jetstack Secure API Token mode. [caller=agent/config.go:479 logger=Run] [2024-11-07 15:54:38] Healthz endpoints enabled [addr=:8081 caller=agent/run.go:116 logger=Run.APIServer path=/healthz] [2024-11-07 15:54:38] Readyz endpoints enabled [addr=:8081 caller=agent/run.go:120 logger=Run.APIServer path=/readyz] [2024-11-07 15:54:38] Error messages will not show in the pod's events because the POD_NAME environment variable is empty [caller=agent/run.go:262 logger=Run] [2024-11-07 15:54:38] Starting DataGatherer [caller=agent/run.go:179 logger=Run] [2024-11-07 15:54:38] Starting DataGatherer [caller=agent/run.go:179 logger=Run] [2024-11-07 15:54:38] Data saved to local file [caller=agent/run.go:315 outputPath=/dev/null]

wallrj · 2024-11-07T16:00:43Z

pkg/agent/config.go

+		var (
+			mode   AuthMode
+			reason string
+		)


I decided not to make these log messages structured, instead I just log the original message at Info level,
to avoid too many changes in the associated tests.
I moved the message to a reason var to make the diff a bit easier to read and makes it easier to turn these into structured logs in the future, e.g.

log.Info("Auth mode selected", "mode", mode, "reason", reason")

wallrj · 2024-11-12T09:27:24Z

pkg/agent/run.go

-		} else {
-			logs.Log.Printf("successfully gathered data from %q datagatherer", k)
-		}
+		log.Info("Successfully gathered", "count", count, "name", k)


The fetch count was introduced in #537. I decided to always include the count in the structured logs, to simplify the code a bit and so that it's clear to the user when 0 items are found.

fix(log): Some improvements to the logs #537

Oh, wait...I just looked closer. I see that the count may be -1.
This needs fixing.

cmd/agent_test.go

maelvls · 2024-11-12T11:12:49Z

pkg/agent/config_test.go

+			INFO Using the Jetstack Secure OAuth auth mode since --credentials-file was specified without --venafi-cloud.
+			INFO Both the 'period' field and --period are set. Using the value provided with --period.


Why is this output not matching the klog text format and uses a custom format? I'd prefer reviewing the logs as seen by the users

Because these tests are using the ktesting test logger which has a buffer containing simplified output format for easier testing and matching.
The log format of the preflight command is tested elsewhere.
I'll leave this as-is.

maelvls

I've reviewed the last commit of this stacked PR, and it looks good. I left two nits that aren't that important.

This PR seems to be low risk: I'm confident that nothing will break, and thus I haven't felt the need to perform manual tests (running the CLI locally or running the manual script ./hack/e2e/test.sh).

Feel free to fix the -1 issue above and merge this.

Signed-off-by: Richard Wall <richard.wall@venafi.com>

wallrj · 2024-11-12T14:41:38Z

Thanks @maelvls I added those suggested TODO comments and answered your other points.
Merging now into the feature branch.

wallrj changed the base branch from VC-35738/feature to VC-35738/more-realistic-logs-tests November 7, 2024 14:19

wallrj force-pushed the VC-35738/execute-context-logs branch from 066593e to 4197b28 Compare November 7, 2024 15:25

wallrj changed the title ~~WIP: [VC-35738] Use klog and logr logger instead of log in the agent module~~ WIP: [VC-35738] Use klog and logr logger instead of log in the agent package Nov 7, 2024

wallrj force-pushed the VC-35738/execute-context-logs branch from 4197b28 to 6b0e405 Compare November 7, 2024 15:42

wallrj force-pushed the VC-35738/more-realistic-logs-tests branch from 3d4876b to a8f16c7 Compare November 7, 2024 15:44

wallrj force-pushed the VC-35738/execute-context-logs branch 2 times, most recently from 3b4e136 to 5787c06 Compare November 7, 2024 15:56

wallrj commented Nov 7, 2024

View reviewed changes

wallrj force-pushed the VC-35738/execute-context-logs branch from 5787c06 to 2243d7f Compare November 7, 2024 16:11

wallrj mentioned this pull request Nov 7, 2024

[VC-35738] Feature Branch #602

Merged

12 tasks

wallrj changed the title ~~WIP: [VC-35738] Use klog and logr logger instead of log in the agent package~~ [VC-35738] Use klog and logr logger instead of log in the agent package Nov 7, 2024

wallrj requested a review from maelvls November 7, 2024 16:31

wallrj mentioned this pull request Nov 7, 2024

[VC-35738] Replace logs.Log with logr.Logger in the remaining code #612

Merged

wallrj force-pushed the VC-35738/more-realistic-logs-tests branch from a8f16c7 to c3b5306 Compare November 12, 2024 07:01

wallrj commented Nov 12, 2024

View reviewed changes

maelvls reviewed Nov 12, 2024

View reviewed changes

cmd/agent_test.go Outdated Show resolved Hide resolved

maelvls reviewed Nov 12, 2024

View reviewed changes

maelvls approved these changes Nov 12, 2024

View reviewed changes

Base automatically changed from VC-35738/more-realistic-logs-tests to VC-35738/feature November 12, 2024 14:11

Use klog and logr logger instead of log

1f19391

Signed-off-by: Richard Wall <richard.wall@venafi.com>

wallrj force-pushed the VC-35738/execute-context-logs branch from 2243d7f to 1f19391 Compare November 12, 2024 14:38

wallrj merged commit fd8d0de into VC-35738/feature Nov 12, 2024
2 checks passed

wallrj deleted the VC-35738/execute-context-logs branch November 12, 2024 14:41

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

[VC-35738] Use klog and logr logger instead of log in the agent package #609

[VC-35738] Use klog and logr logger instead of log in the agent package #609

wallrj commented Nov 7, 2024 •

edited

Loading

wallrj Nov 7, 2024

wallrj Nov 7, 2024

wallrj Nov 7, 2024

wallrj Nov 7, 2024

wallrj Nov 7, 2024

wallrj Nov 7, 2024

wallrj Nov 12, 2024

wallrj Nov 12, 2024

wallrj Nov 12, 2024

maelvls Nov 12, 2024 •

edited

Loading

wallrj Nov 12, 2024

maelvls left a comment •

edited

Loading

wallrj commented Nov 12, 2024

		INFO Using the Jetstack Secure OAuth auth mode since --credentials-file was specified without --venafi-cloud.
		INFO Both the 'period' field and --period are set. Using the value provided with --period.

[VC-35738] Use klog and logr logger instead of log in the agent package #609

[VC-35738] Use klog and logr logger instead of log in the agent package #609

Conversation

wallrj commented Nov 7, 2024 • edited Loading

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

maelvls Nov 12, 2024 • edited Loading

Choose a reason for hiding this comment

Choose a reason for hiding this comment

maelvls left a comment • edited Loading

Choose a reason for hiding this comment

wallrj commented Nov 12, 2024

wallrj commented Nov 7, 2024 •

edited

Loading

maelvls Nov 12, 2024 •

edited

Loading

maelvls left a comment •

edited

Loading