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

[adonovan]

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]

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]

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]

@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]

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.

[robpike]

@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]

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]

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.