Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

proposal: cmd/vet: report printf calls with non-const format and no args #60529

Open
adonovan opened this issue May 31, 2023 · 12 comments
Open
Labels
Analysis Issues related to static analysis (vet, x/tools/go/analysis) gopls/analysis Issues related to running analysis in gopls help wanted NeedsInvestigation Someone must examine and confirm this is a valid issue and not a duplicate of an existing one. Proposal
Milestone

Comments

@adonovan
Copy link
Member

adonovan commented May 31, 2023

A common mistake not caught by the existing printf vet checker is Printf(v), where v is a variable, when the user intended Printf("%s", v). If the value of v contains an unexpected percent sign, the program has a bug.

I feel like I see this mistake in Google Go readability reviews at least once a week, and the Google corpus shows up hundreds of violations with what looks like close to 100% precision:
https://source.corp.google.com/search?q=%5B.%5DPrintf%5C(%5Ba-z%5D*%5C)%20lang:go&sq=
(Apologies, link to Google internal service.)

Printf and similar functions are usually called with a literal format string, followed by zero or more arguments. Occasionally the format string argument is a variable, either because preceding logic chooses between two alternative formats, or because the call appears in a wrapper function that takes both the format and its arguments as parameters, but in both those cases the format is followed by other arguments. It's hard to imagine any good reason one would call printf with a variable format string and no arguments.

We should make the printf checker report this error.

@timothy-king @findleyr

@adonovan adonovan added help wanted gopls/analysis Issues related to running analysis in gopls Analysis Issues related to static analysis (vet, x/tools/go/analysis) labels May 31, 2023
@adonovan
Copy link
Member Author

adonovan commented May 31, 2023

It's hard to imagine any good reason one would call printf with a variable format string and no arguments.

Ok, I imagined one (having found https://github.com/golang/tools/blob/master/gopls/internal/lsp/cache/load.go#L378):
you want to call a printf wrapper function such as fmt.Errorf with a choice of two format strings both of which you know are percent-free, and there is no non-Printf variant ("fmt.Error") of the function in question.

var msg string
if cond {
    msg = "percent-free error message a"
} else {
    msg = "percent-free error message b"
}
return fmt.Errorf(msg)

The code would be improved by calling fmt.Errorf("%s", msg), since it would be safer in the face of later changes to the logic that assigns msg, but it's not actually wrong.

@robpike
Copy link
Contributor

robpike commented May 31, 2023

The technique you're forbidding is used to generate messages in different languages:

greet := map[string]string{ "en": "hello", "fr": "bonjour"}
fmt.Printf(greet[lang])

(In fact, the $[1] notation is there precisely for the general form of this when word order can vary between languages.)

I realize in this case you're arguing for the case with zero arguments, and my example is a bit contrived that way, but still, to me it feels too useful a technique to be forbidden outright. And there are other ways to do this, of course. Yet, one person's bad code is another's useful technique.

@ianlancetaylor
Copy link
Contributor

@robpike Sorry, I'm not sure I understand your example. The proposed checker wouldn't report anything for that code.
And wouldn't that use fmt.Println, not fmt.Printf?

@findleyr
Copy link
Contributor

findleyr commented May 31, 2023

I guess the question is whether it should be OK to use fmt.Printf when fmt.Print would do. By comparison, it is generally accepted that fmt.Errorf is OK to use instead of errors.New even when there are no formatted arguments. Of course, that is typically with a constant error string.

I am not sure if this rule should be applied to Printf wrappers (as with other checks in the printf analyzer). Often Printf wrappers have no corresponding Print wrapper alternative. EDIT: of course the user could always convert to ...Printf("%s", msg), but may require a lot of code to be updated.

@mknyszek mknyszek added this to the Backlog milestone May 31, 2023
@mknyszek mknyszek added the NeedsInvestigation Someone must examine and confirm this is a valid issue and not a duplicate of an existing one. label May 31, 2023
@robpike
Copy link
Contributor

robpike commented Jun 1, 2023

@robpike Sorry, I'm not sure I understand your example. The proposed checker wouldn't report anything for that code. And wouldn't that use fmt.Println, not fmt.Printf?

Sorry, editing mistake. Example updated to drop the user name. And yes, you could use Println instead, but @findleyr gets to the nub: Do we force (through vet) people to use a different printer when there are no arguments? That's really what this is about.

@timothy-king
Copy link
Contributor

If the value of v contains an unexpected percent sign, the program has a bug.

If we know "v" contains a verb this is clearly a bug. Maybe it is okay to warn if v may conditionally contain a verb?

I feel like I see this mistake in Google Go readability reviews at least once a week, and the Google corpus shows up hundreds of violations with what looks like close to 100% precision:

For the handful I have looked at (~5), I am a bit wishy-washy on whether these are buggy. This particular pattern seems common:

        msg := fmt.Sprintf(format, args...)
	// do something else with msg
	logger.Printf(msg)

Printf("%s", msg) or Print does seem like what is intended the examples I have seen. To know that this is bug though seems to require knowing about args, which is often out of scope.

(Another example I have seen is when msg is a constant. The existing checker should already work IIUC.)

@adonovan
Copy link
Member Author

adonovan commented Apr 8, 2024

To know that this is bug though seems to require knowing about args, which is often out of scope.

That's true, but in all the examples I've looked it, it requires knowledge of a non-local and undocumented invariant that the args are percent-free.

I would usually run a measurement over the module mirror corpus and then analyze the rate of true and false positives, but a quick experiment on a single repo (kubernetes) turned up plenty of findings, nearly all bugs.

Here's the new logic:

tools$ git diff
diff --git a/go/analysis/passes/printf/printf.go b/go/analysis/passes/printf/printf.go
index 3235019258..a0ecc5d2eb 100644
--- a/go/analysis/passes/printf/printf.go
+++ b/go/analysis/passes/printf/printf.go
@@ -536,6 +536,18 @@ type formatState struct {
 
 // checkPrintf checks a call to a formatted print routine such as Printf.
 func checkPrintf(pass *analysis.Pass, kind Kind, call *ast.CallExpr, fn *types.Func) {
+       // Calls to fmt.Printf(msg), with a non-constant
+       // format string and no arguments, seem to be a common
+       // mistake.
+       if len(call.Args) == 1 && pass.TypesInfo.Types[call.Args[0]].Value == nil {
+               pass.Reportf(call.Lparen,
+                       "non-constant format string in call to %s (did you mean %s(\"%%s\", %s)?)",
+                       fn.FullName(),
+                       fn.Name(),
+                       analysisutil.Format(pass.Fset, call.Args[0]))
+               return
+       }
+

And here are a random 25 of its 182 findings:

https://go-mod-viewer.appspot.com/k8s.io/kubernetes@v1.29.3/pkg/controller/statefulset/stateful_set_test.go#L894: non-constant format string in call to (*testing.common).Errorf (did you mean Errorf("%s", onPolicy("Expected set to stay at two replicas"))?)
https://go-mod-viewer.appspot.com/k8s.io/kubernetes@v1.29.3/pkg/controller/volume/expand/expand_controller.go#L266: non-constant format string in call to fmt.Errorf (did you mean Errorf("%s", errorMsg)?)
https://go-mod-viewer.appspot.com/k8s.io/kubernetes@v1.29.3/pkg/volume/secret/secret.go#L286: non-constant format string in call to fmt.Errorf (did you mean Errorf("%s", errMsg)?)
https://go-mod-viewer.appspot.com/k8s.io/kubernetes@v1.29.3/test/e2e_node/util_sriov.go#L47: non-constant format string in call to k8s.io/kubernetes/test/e2e/framework/skipper.Skipf (did you mean Skipf("%s", msg)?)
https://go-mod-viewer.appspot.com/k8s.io/kubernetes@v1.29.3/test/images/agnhost/crd-conversion-webhook/converter/framework.go#L129: non-constant format string in call to k8s.io/klog/v2.Errorf (did you mean Errorf("%s", msg)?)
https://go-mod-viewer.appspot.com/k8s.io/kubernetes@v1.29.3/pkg/controller/nodelifecycle/node_lifecycle_controller_test.go#L2562: non-constant format string in call to (*testing.common).Errorf (did you mean Errorf("%s", err.Error())?)
https://go-mod-viewer.appspot.com/k8s.io/kubernetes@v1.29.3/test/e2e/framework/statefulset/rest.go#L53: non-constant format string in call to fmt.Sprintf (did you mean Sprintf("%s", "creating " + ss.Name + " service")?)
https://go-mod-viewer.appspot.com/k8s.io/kubernetes@v1.29.3/pkg/volume/util/operationexecutor/operation_generator.go#L1610: non-constant format string in call to k8s.io/klog/v2.Warningf (did you mean Warningf("%s", volumeToDetach.GenerateMsgDetailed("Node not found on API server. DetachVolume will skip safe to detach check", ""))?)
https://go-mod-viewer.appspot.com/k8s.io/kubernetes@v1.29.3/pkg/volume/downwardapi/downwardapi_test.go#L361: non-constant format string in call to (*testing.common).Errorf (did you mean Errorf("%s", err.Error())?)
https://go-mod-viewer.appspot.com/k8s.io/kubernetes@v1.29.3/pkg/volume/csi/csi_block.go#L411: non-constant format string in call to (k8s.io/klog/v2.Verbose).Infof (did you mean Infof("%s", log("blockMapper.unpublishVolumeForBlock NodeUnpublished successfully [%s]", publishPath))?)
https://go-mod-viewer.appspot.com/k8s.io/kubernetes@v1.29.3/pkg/volume/csi/csi_block.go#L215: non-constant format string in call to (k8s.io/klog/v2.Verbose).Infof (did you mean Infof("%s", log("blockMapper.publishVolumeForBlock called"))?)
https://go-mod-viewer.appspot.com/k8s.io/kubernetes@v1.29.3/pkg/controller/statefulset/stateful_set_test.go#L891: non-constant format string in call to (*testing.common).Errorf (did you mean Errorf("%s", onPolicy("Could not get scaled down StatefulSet: %v", err))?)
https://go-mod-viewer.appspot.com/k8s.io/kubernetes@v1.29.3/test/integration/garbagecollector/garbage_collector_test.go#L698: non-constant format string in call to (*testing.common).Fatalf (did you mean Fatalf("%s", errString)?)
https://go-mod-viewer.appspot.com/k8s.io/kubernetes@v1.29.3/test/e2e/upgrades/apps/etcd.go#L149: non-constant format string in call to fmt.Errorf (did you mean Errorf("%s", string(b))?)
https://go-mod-viewer.appspot.com/k8s.io/kubernetes@v1.29.3/pkg/volume/util/operationexecutor/operation_generator.go#L831: non-constant format string in call to k8s.io/klog/v2.Errorf (did you mean Errorf("%s", volumeToMount.GenerateErrorDetailed("MountVolume.MarkVolumeMountAsUncertain failed", t).Error())?)
https://go-mod-viewer.appspot.com/k8s.io/kubernetes@v1.29.3/test/e2e/windows/gmsa_full.go#L194: non-constant format string in call to k8s.io/kubernetes/test/e2e/framework.Failf (did you mean Failf("%s", err.Error())?)
https://go-mod-viewer.appspot.com/k8s.io/kubernetes@v1.29.3/pkg/volume/csi/csi_block.go#L140: non-constant format string in call to (k8s.io/klog/v2.Verbose).Infof (did you mean Infof("%s", log("blockMapper.GetPodDeviceMapPath [path=%s; name=%s]", path, m.specName))?)
https://go-mod-viewer.appspot.com/k8s.io/kubernetes@v1.29.3/pkg/controller/statefulset/stateful_set_test.go#L913: non-constant format string in call to (*testing.common).Errorf (did you mean Errorf("%s", onPolicy("Claim ref unexpectedly changed: %v", refs))?)
https://go-mod-viewer.appspot.com/k8s.io/kubernetes@v1.29.3/pkg/volume/csi/csi_mounter.go#L445: non-constant format string in call to (k8s.io/klog/v2.Verbose).Infof (did you mean Infof("%s", log("Unmounter.TearDownAt successfully unmounted dir [%s]", dir))?)
https://go-mod-viewer.appspot.com/k8s.io/kubernetes@v1.29.3/pkg/volume/csi/csi_plugin.go#L842: non-constant format string in call to (k8s.io/klog/v2.Verbose).Infof (did you mean Infof("%s", log("CSIDriver %q not found, not adding pod information", driverName))?)
https://go-mod-viewer.appspot.com/k8s.io/kubernetes@v1.29.3/pkg/volume/util/operationexecutor/operation_generator.go#L1239: non-constant format string in call to k8s.io/klog/v2.Errorf (did you mean Errorf("%s", volumeToMount.GenerateErrorDetailed("MountVolume.MarkVolumeMountAsUncertain failed", err).Error())?)
https://go-mod-viewer.appspot.com/k8s.io/kubernetes@v1.29.3/pkg/volume/util/operationexecutor/operation_generator.go#L1467: non-constant format string in call to k8s.io/klog/v2.Infof (did you mean Infof("%s", deviceToDetach.GenerateMsgDetailed("UnmapDevice succeeded", ""))?)
https://go-mod-viewer.appspot.com/k8s.io/kubernetes@v1.29.3/pkg/volume/util/operationexecutor/operation_executor.go#L367: non-constant format string in call to fmt.Errorf (did you mean Errorf("%s", detailedMsg)?)
https://go-mod-viewer.appspot.com/k8s.io/kubernetes@v1.29.3/pkg/controller/podautoscaler/horizontal.go#L416: non-constant format string in call to fmt.Errorf (did you mean Errorf("%s", errMsg)?)
https://go-mod-viewer.appspot.com/k8s.io/kubernetes@v1.29.3/pkg/controller/statefulset/stateful_set_test.go#L903: non-constant format string in call to (*testing.common).Errorf (did you mean Errorf("%s", onPolicy("Unexpected change to condemned pvc ownerRefs: %v", refs))?)

All but one are true positives: bugs (sometimes more than one in the same call!). The one false positive was of the form:

var s = "benign"
fmt.Printf(s)

So that's a 96% success rate.

@adonovan adonovan changed the title cmd/vet: printf: report calls to printf(format) with variable format and no arguments proposal: cmd/vet: printf: report calls to printf(format) with variable format and no arguments Apr 8, 2024
@timothy-king
Copy link
Contributor

I was looking into https://go-mod-viewer.appspot.com/k8s.io/kubernetes@v1.29.3/pkg/controller/statefulset/stateful_set_test.go#L891: non-constant format string in call to (*testing.common).Errorf (did you mean Errorf("%s", onPolicy("Could not get scaled down StatefulSet: %v", err))?)

   834  		onPolicy := func(msg string, args ...interface{}) string {
   835  			return fmt.Sprintf(fmt.Sprintf("(%s) %s", policy, msg), args...)
   836  		}
   ...
   891  			t.Errorf(onPolicy("Could not get scaled down StatefulSet: %v", err))

The diagnostic given on t.Errorf seems correct to me. Should be t.Error. (Diagnostic should maybe say that.) The outer fmt.Sprintf(...) is debatable though. The intention here is to copy the %v from msg and use it as a formatting string. This is debatable style, but it should work. Just kinda interesting that something immediately adjacent to the example illustrated something that should not be warned on. This example would not be warned on due to len(call.Args) == 1.

@timothy-king
Copy link
Contributor

+       if len(call.Args) == 1 && pass.TypesInfo.Types[call.Args[0]].Value == nil {

call.Args[0] could be a function call. We should also check that if call.Args[0]'s type is a tuple, that it is 1 element.

@adonovan
Copy link
Member Author

adonovan commented Apr 9, 2024

The outer fmt.Sprintf(...) is debatable though. The intention here is to copy the %v from msg and use it as a formatting string. This is debatable style, but it should work.

The code assumes that that the result of applying %s to policy (i.e. calling the String method of StatefulSetPersistentVolumeClaimRetentionPolicy, a protocol message) is percent-free. In this particular test, that is true, but in general, the string of this type contains arbitrary characters, and would cause this formatting to fail. So I would describe this as a latent bug just waiting for someone to add a new row to the test table.

Just kinda interesting that something immediately adjacent to the example illustrated something that should not be warned on. This example would not be warned on due to len(call.Args) == 1.

Yes, the lesson is that non-const formats are often a mistake for any value of len(Args), but they are nearly always a mistake for len(Args)=0.

@rsc rsc changed the title proposal: cmd/vet: printf: report calls to printf(format) with variable format and no arguments proposal: cmd/vet: report printf calls with non-const format and no args Apr 10, 2024
@rsc
Copy link
Contributor

rsc commented Apr 10, 2024

Side note but please do not add "did you mean" to error messages. Report the problem, then stop.

@rsc
Copy link
Contributor

rsc commented Apr 10, 2024

This proposal has been added to the active column of the proposals project
and will now be reviewed at the weekly proposal review meetings.
— rsc for the proposal review group

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
Analysis Issues related to static analysis (vet, x/tools/go/analysis) gopls/analysis Issues related to running analysis in gopls help wanted NeedsInvestigation Someone must examine and confirm this is a valid issue and not a duplicate of an existing one. Proposal
Projects
Status: Active
Development

No branches or pull requests

8 participants