Go: Fix false positives when logging using `%T` #19053

owen-mc · 2025-03-18T15:06:46Z

LoggerCall::getAMessageComponent no longer returns arguments to logger calls which correspond to the verb %T in a format specifier. This will remove false positives in "Log entries created from user input" (go/log-injection) and "Clear-text logging of sensitive information" (go/clear-text-logging), and it may lead to more results in "Use of constant state value in OAuth 2.0 URL" (go/constant-oauth2-state).

I've made a library change note but may change it to a query change note, pending discussion with colleagues.

Prompted by #18926.

Copilot

Pull Request Overview

This PR updates several test files to properly flag logging calls that include the format specifier "%T", ensuring that arguments corresponding to "%T" are not mistakenly reported as vulnerabilities. Key changes include:

Insertion of a package-level variable "v" in LoggerCall/main.go to support usage of "%T" in tests.
Updates in multiple test files (glog.go, stdlib.go, logrus.go, and various query-tests) to mark logging calls with "%T" and adjust alert annotations.
Addition of a change note documenting the behavioral change for LoggerCall::getAMessageComponent.

Reviewed Changes

Copilot reviewed 11 out of 14 changed files in this pull request and generated no comments.

Show a summary per file

File	Description
go/ql/test/library-tests/semmle/go/concepts/LoggerCall/main.go	Added declaration for "v" and repositioned the main function to support updated logging tests.
go/ql/test/library-tests/semmle/go/concepts/LoggerCall/glog.go	Inserted additional logging calls with "%T" annotations.
go/ql/test/library-tests/semmle/go/concepts/LoggerCall/stdlib.go	Updated test cases for logging calls that use "%T".
go/ql/test/library-tests/semmle/go/concepts/LoggerCall/logrus.go	Added test cases for logrus calls using "%T".
go/ql/test/query-tests/Security/CWE-312/main.go	Revised logging calls and alert markers in various logging function calls.
go/ql/lib/change-notes/2025-03-18-loggercall-type-format-specifier.md	Added a change note documenting the new behavior regarding "%T".
go/ql/test/query-tests/Security/CWE-312/protobuf.go	Adjusted alert markers in logging the query description.
go/ql/test/query-tests/Security/CWE-312/passwords.go	Updated inline annotation markers for logging calls and their sources.
go/ql/test/query-tests/Security/CWE-312/klog.go	Revised alert markers in klog calls and added source annotation for header iteration.
go/ql/test/query-tests/Security/CWE-117/LogInjection.go	Updated logging calls to include both username and password in tests, with corresponding alert markers.
go/ql/test/query-tests/Security/CWE-312/overrides.go	Modified inline markers for overridden string methods and their usage.

Files not reviewed (3)

go/ql/lib/semmle/go/Concepts.qll: Language not supported
go/ql/test/query-tests/Security/CWE-312/CleartextLogging.expected: Language not supported
go/ql/test/query-tests/Security/CWE-312/CleartextLogging.qlref: Language not supported

Tip: If you use Visual Studio Code, you can request a review from Copilot before you push from the "Source Control" tab. Learn more

mbg

Thanks for tackling this FP! I have added a few comments and questions.

Additional questions:

There's a commit which makes the tests more "realistic". What prompted that and are there any concrete gaps in the test coverage that are addressed? If so, would it be worth capturing that in the commit message or description?

mbg · 2025-03-18T15:17:40Z

go/ql/lib/semmle/go/Concepts.qll

+   * Exclude components corresponding to the format specifier "%T" as this
+   * prints the type of the argument, which is not considered vulnerable.
+   */
+  DataFlow::Node getAMessageComponent() {
+    result = super.getAMessageComponent() and
+    not exists(string formatSpecifier |
+      formatSpecifier.regexpMatch("%[^%]*T") and
+      result = this.(StringOps::Formatting::StringFormatCall).getOperand(_, formatSpecifier)
+    )
+  }


Is this the right place for this? Given that it's in Concepts, I'd think this should be more general than what we need for one specific query?

This predicate is used in three places (outside of tests). Two of them are sinks of logging queries, where we want to exclude %T arguments. The last one is trying to rule out oauth flows that use printer calls and scan calls, which makes it likely that it's done in a terminal, and I think for that purpose it will make no difference but it's probably slightly better to rule out %T arguments. It seemed good to catch at least the first two cases. The alternative would be to add another predicate, getAPrintedMessageComponent, which has this new restriction, but the result would just be that we don't use getAMessageComponent anywhere any more. So I think it's okay to change the meaning of this predicate since it's making it closer to what anyone would want to use it for.

My concern is that introducing query-specific logic here could be quite confusing for anyone who wants to use getAMessageComponent in the future to query all the components of a LoggerCall. It's easy to miss the comment that explains that it has non-intuitive behaviour and it might not be obvious during testing (of a new query). So while it might be fine for current uses, I don't think it's a good move for maintainability.

Rather than adding a new predicate to LoggerCall, I think it would be better to add a new class that extends LoggerCalls which is specific to the go/clear-text-logging query (and others) where we then override getAMessageComponent and filter %T components out.

I don't agree. No one cares about things which have their type logged. I can make a new class, but it means the old one will literally not be used in our library. Anyone who wants that behaviour can make a copy of LoggerCall and change the behaviour of getAMessageComponent. I will make the comment more prominent so that the intention is clearer.

mbg · 2025-03-18T15:19:03Z

go/ql/test/library-tests/semmle/go/concepts/LoggerCall/main.go


+func main() {
+	stdlib()


What's the motivation for this change?

To remove linter warnings about lots of unused things 😆 .

mbg · 2025-03-18T15:22:07Z

go/ql/lib/change-notes/2025-03-18-loggercall-type-format-specifier.md

+---
+category: minorAnalysis
+---
+* `LoggerCall::getAMessageComponent` no longer returns arguments to logger calls which correspond to the verb `%T` in a format specifier. This will remove false positives in "Log entries created from user input" (`go/log-injection`) and "Clear-text logging of sensitive information" (`go/clear-text-logging`), and it may lead to more results in "Use of constant `state` value in OAuth 2.0 URL" (`go/constant-oauth2-state`).


Mirroring a review comment I think I wrote on another PR before: but this change note seems very implementation-oriented. Is that relevant to the target audience for this? I think if the goal is to address the FP in go/log-injection, then the change note should emphasise that. Otherwise, if we are communicating a change in the library, then we should consider whether the change has to be backwards compatible.

I'm in two minds about whether to describe it as a change to the library, which happens to affect two queries in a very direct way, or as a change to two queries, with few/no details for anyone who might be using the predicate in the library that has been changed.

I think that just reinforces my view in #19053 (comment) that this is a query change which is wrongly executed as a library change. If the intent is for this to fix the FP in the queries, then we should make sure that it is implemented and documented accordingly.

mbg · 2025-03-18T15:23:14Z

go/ql/test/library-tests/semmle/go/concepts/LoggerCall/glog.go

+	glog.Errorf("%s: found type %T", text, v)   // $ logger="%s: found type %T" logger=text
+	glog.Exitf("%s: found type %T", text, v)    // $ logger="%s: found type %T" logger=text
+	glog.Fatalf("%s: found type %T", text, v)   // $ logger="%s: found type %T" logger=text
+	glog.Infof("%s: found type %T", text, v)    // $ logger="%s: found type %T" logger=text
+	glog.Warningf("%s: found type %T", text, v) // $ logger="%s: found type %T" logger=text


Is this change because the tests in the first commit were written so that they pass without the fix?

Yes. I guess I could have marked them as SPURIOUS in the first commit.

I think it would be good to make sure that if we add tests before a fix is implemented (even in the same PR) to either mark them as SPURIOUS or just have them fail. Ideally the latter if there's a fix in the same PR (as is the case here) so that you don't add the tests in one commit and then change every line again in the next.

I marked them as SPURIOUS.

owen-mc · 2025-03-18T15:53:04Z

I had the "realistic" test changes stashed from when I converted go models to models-as-data. There aren't any concrete gaps that are covered by it. But it makes the tests closer to real code and exercises our models slightly more. For example, it makes it much clearer which functions use a format string, and if we ever treat those differently (as we kind of do in this PR) then it's easier to see what's going on. Another example: our tests tend to ignore that calls to fatal logging functions mean that all code after that is dead code, so if our analysis was more detailed then we might say "actually there isn't a result there because that's dead code". So it's better to put calls to fatal functions inside a conditional.

smowton · 2025-03-19T10:04:36Z

go/ql/lib/semmle/go/Concepts.qll

+   * components corresponding to the format specifier "%T" are excluded as
+   * their type is logged rather than their value.
+   */
+  DataFlow::Node getAMessageComponent() {


Suggesting keeping getAMessageComponent with the old semantics (i.e., get any formatted input, regardless of how it is formatted) and adding a new one, perhaps getAValueFormattedMessageComponent that excludes things formatted in such a way that disregards their value.

smowton · 2025-03-19T10:08:57Z

go/ql/lib/semmle/go/Concepts.qll

+  DataFlow::Node getAMessageComponent() {
+    result = super.getAMessageComponent() and
+    not exists(string formatSpecifier |
+      formatSpecifier.regexpMatch("%[^%]*T") and


Suggested change

formatSpecifier.regexpMatch("%[^%]*T") and

formatSpecifier.matches("%T") and

This is cheaper, and we already know format specifiers begin with %

owen-mc · 2025-03-20T15:12:15Z

@smowton I've addressed your review comments. I only force-pushed to edit history to mark the tests in the first commit as SPURIOUS.

smowton · 2025-03-20T15:20:52Z

go/ql/src/change-notes/2025-03-20-logging-false-positive-type-format-specifier.md

+---
+category: minorAnalysis
+---
+* False positives in "Log entries created from user input" (`go/log-injection`) and "Clear-text logging of sensitive information" (`go/clear-text-logging`) which correspond to the verb `%T` in a format specifier have been removed. There may also be more results in "Use of constant `state` value in OAuth 2.0 URL" (`go/constant-oauth2-state`).


Should this be less results, for the same reason?

In go/constant-oauth2-state, arguments to loggercalls are used to rule out some alerts. So less arguments to loggercalls means more alerts, potentially. (In practice I doubt there will be any alert changes for that query.)

mbg

The changes after @smowton's review now also address my two main concerns. I still think that a class extending LoggerCall would have been better (e.g. ValueLoggerCall) than an extra predicate in LoggerCall, but this is acceptable.

go/ql/src/change-notes/2025-03-20-logging-false-positive-type-format-specifier.md

Co-authored-by: Michael B. Gale <[email protected]>

owen-mc · 2025-03-25T10:42:03Z

@mbg Please re-review.

Copilot bot review requested due to automatic review settings March 18, 2025 15:06

owen-mc requested a review from a team as a code owner March 18, 2025 15:06

github-actions bot added documentation Go labels Mar 18, 2025

Copilot AI reviewed Mar 18, 2025

View reviewed changes

mbg reviewed Mar 18, 2025

View reviewed changes

smowton reviewed Mar 19, 2025

View reviewed changes

owen-mc added 11 commits March 20, 2025 15:05

Add tests for %T (passing but marked SPURIOUS)

f173305

Don't consider arguments with %T as logger call components

009e0e1

Make log injection tests more realistic

59d82b3

Convert cleartext logging tests to inline expectations

94c812c

Make cleartext logging tests more realistic

646d28f

Add log injection and cleartext logging tests for %T

11ff0a0

Add change note

bf78160

Make comment clearer

05a9480

Create getAValueFormattedMessageComponent

f944ff4

Do not use full regex match for %T

bc40a42

Change change note to query change note

da8ae84

owen-mc force-pushed the go/fp/log-type branch from b1bf2a2 to da8ae84 Compare March 20, 2025 15:10

smowton reviewed Mar 20, 2025

View reviewed changes

Update test expectations

662af6e

owen-mc assigned smowton Mar 21, 2025

smowton previously approved these changes Mar 21, 2025

View reviewed changes

mbg previously approved these changes Mar 21, 2025

View reviewed changes

go/ql/src/change-notes/2025-03-20-logging-false-positive-type-format-specifier.md Outdated Show resolved Hide resolved

Update wording of change note (accepting review suggestion)

f677ddd

Co-authored-by: Michael B. Gale <[email protected]>

owen-mc dismissed stale reviews from mbg and smowton via f677ddd March 21, 2025 11:26

mbg approved these changes Mar 25, 2025

View reviewed changes

owen-mc merged commit c3bc651 into github:main Mar 25, 2025
15 checks passed

owen-mc deleted the go/fp/log-type branch March 25, 2025 10:49

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

Go: Fix false positives when logging using `%T` #19053

Go: Fix false positives when logging using `%T` #19053

owen-mc commented Mar 18, 2025

Copilot AI left a comment

mbg left a comment

mbg Mar 18, 2025

owen-mc Mar 18, 2025

mbg Mar 18, 2025

owen-mc Mar 18, 2025

mbg Mar 18, 2025

owen-mc Mar 18, 2025

mbg Mar 18, 2025

owen-mc Mar 18, 2025

mbg Mar 18, 2025

mbg Mar 18, 2025

owen-mc Mar 18, 2025

mbg Mar 18, 2025 •

edited

Loading

owen-mc Mar 20, 2025

owen-mc commented Mar 18, 2025

smowton Mar 19, 2025

smowton Mar 19, 2025

owen-mc commented Mar 20, 2025

smowton Mar 20, 2025

owen-mc Mar 20, 2025 •

edited

Loading

mbg left a comment

owen-mc commented Mar 25, 2025

	formatSpecifier.regexpMatch("%[^%]*T") and
	formatSpecifier.matches("%T") and

Go: Fix false positives when logging using %T #19053

Go: Fix false positives when logging using %T #19053

Conversation

owen-mc commented Mar 18, 2025

Copilot AI left a comment

Choose a reason for hiding this comment

Pull Request Overview

Reviewed Changes

mbg left a 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

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

mbg Mar 18, 2025 • edited Loading

Choose a reason for hiding this comment

Choose a reason for hiding this comment

owen-mc commented Mar 18, 2025

Choose a reason for hiding this comment

Choose a reason for hiding this comment

owen-mc commented Mar 20, 2025

Choose a reason for hiding this comment

owen-mc Mar 20, 2025 • edited Loading

Choose a reason for hiding this comment

mbg left a comment

Choose a reason for hiding this comment

owen-mc commented Mar 25, 2025

Go: Fix false positives when logging using `%T` #19053

Go: Fix false positives when logging using `%T` #19053

mbg Mar 18, 2025 •

edited

Loading

owen-mc Mar 20, 2025 •

edited

Loading