Native auth safe logging test #2092

Yuki-YuXin · 2024-04-29T14:43:31Z

Comments and Changes Summary:

Setup external logger and remove it for every test under @Before and @After.
Use Regex rules to filter the log message under verify().log(). There are two pools for the regex rules: sensitivePIIMessages - items should not exist in the log regardless of allowPII value; permittedPIIMessages - items should not exist in the log when allowPII=false but can exist when allowPII=true
Use @ParameterizedRobolectricTestRunner.Parameters in order to test both allow=false & allowPII=true for RunWith(ParameterizedRobolectricTestRunner::class) NativeAuthPublicClientApplicationKotlinTest(private val allowPII: Boolean)
verifyLogDoesNotContain checks message and 'containsPII'. verifyLogDoesNotContain checks message.

...c/test/java/com/microsoft/identity/nativeauth/NativeAuthPublicClientApplicationKotlinTest.kt

SammyO · 2024-04-29T14:55:03Z

...c/test/java/com/microsoft/identity/nativeauth/NativeAuthPublicClientApplicationKotlinTest.kt

+
+    private fun checkSafeLogging() {
+        val piiTrueToCheck = listOf(
+            "password:","password=",


let's make this list longer.

"password" (so without : and =)

'"password"' (so looking for the password value that includes " in the string, for example when JSON is outputted it will contain ")

the above 2 points also for code and username

attributes is another PII field

channel target label is another

add check for access token, ID token and refresh token

add snake_case as well as camelCase for multi-word values like continuation token.

Have updated the rules and scopes.

Should (user) attributes be added?

SammyO · 2024-04-29T15:23:04Z

...c/test/java/com/microsoft/identity/nativeauth/NativeAuthPublicClientApplicationKotlinTest.kt

+        Logger.getInstance().setExternalLogger(null)
+    }
+    private fun verifyLogDoesNotContain(tag: String, element: String) {
+        verify(externalLogger, never()).log(contains(tag), any(), contains(element), eq(true))


I think containsPII should be any(). Without it, I believe Mockito is looking for something like:
-> assert that the callback is never called with values tag and and and containsPII=true.
whereas what might be happening is that is called, but PII=false. If that happens, it won't trigger this I think.

Furthermore, you're actually doing many tests in 1 statement here. While it's efficient from a coding perspective, it may not be logistically. if this test fails, it's hard to determine why, because so many things happen in the same statement.

Consider something like:

attach a real logger callback interface (make it a Spy, so the method is actually called, but you can also play around with its behaviour the way you can with a Mock)

within the callback, perform a number of assertions all on different fields and callback configurations, each in a separate statement.

Updated according to the suggestions.

SammyO · 2024-04-29T15:29:24Z

...c/test/java/com/microsoft/identity/nativeauth/NativeAuthPublicClientApplicationKotlinTest.kt

+        Logger.getInstance().setExternalLogger(null)
+    }
+    private fun verifyLogDoesNotContain(tag: String, element: String) {
+        verify(externalLogger, never()).log(contains(tag), any(), contains(element), eq(true))


I believe we want to do 2 types of checks:

some values should never be in the callback

some values may be, but only if also containsPII=true (and if the log configuration has allowPII enabled)

Modify from eq(true) to any(). However, the value of allowPII is defined variable of true status.

SammyO · 2024-04-29T15:34:51Z

...c/test/java/com/microsoft/identity/nativeauth/NativeAuthPublicClientApplicationKotlinTest.kt

+        }
+
+        elementsToCheck.forEach { element ->
+            verifyLogDoesNotContain("Command", element)


Why do we only care about TAG=Command? I think we should make the tag matcher any(), as we don't care what the tag value is in this context.

Narrowing down the tag contributes to easier regex definition. Modify from "Command|Indicator" to any()

SammyO · 2024-04-29T16:05:01Z

...c/test/java/com/microsoft/identity/nativeauth/NativeAuthPublicClientApplicationKotlinTest.kt

+            "(?i)access_token|\baccessToken(?![:=])\b", // access_token, accessToken
+            "(?i)refresh_token|\brefreshToken(?![:=])\b",
+            "(?i)id_token|\bidToken(?![:=])\b",
+            "(?i)client_secret|clientSecret",


do we need client secret?

No, we currently don't. Removed.

SammyO · 2024-04-30T08:34:34Z

...c/test/java/com/microsoft/identity/nativeauth/NativeAuthPublicClientApplicationKotlinTest.kt

+        }
+
+        elementsToCheck.forEach { regex ->
+            verifyLogDoesNotContain("""\S*(Command|Interactor)\S*""", regex)


why not any()?

Modify from regex to any()

This reverts commit 761a77f.

SammyO · 2024-05-01T11:19:13Z

...c/test/java/com/microsoft/identity/nativeauth/NativeAuthPublicClientApplicationKotlinTest.kt

+                elementsToCheck.forEach { regex ->
+                    if (RegexMatcher(regex).matches(message)) {
+                        failCalled = true
+                        fail("PII $regex found in log message: $message")


This is a smart setup, but I'm 100% sure it's going to work. Some thoughts:

I see we can't rely on only fail, as this callback is executed on a thread that's different from the thread that the test is executed on. I see that's why you've introduced the failCalled check, that's smart.

however, given the fact that failCalled is set to true on a different thread, I expect there might be race conditions where the test thread is looking for spyLoggerCallback.failCalled (to perform assertFalse), before the callback has finished and set the value to true. given that the default is false, that means the test "thinks" failCalled wasn't set. Whereas in reality it hasn't been set yet

you can try this out by adding a delay to the logger callback (e.g. Thread.sleep(5000)).

this setup will cause flaky tests: sometimes they'll pass, sometimes they'll fail. They're not deterministic, due to the race condition.

typically a good way to deal with these async processes in tests is through for example CountDownLatch. Take a look at LoggerTest.java. Another good way in general when dealing with callbacks vs. coroutines is suspendCancellableCoroutine (this might not work here, but is interesting for you to look into).

Thanks a million for this valuable guidance. Have added CountDownLatch into the loggercallback. But I just make changes for scenario 1 for reviewing first.

SammyO · 2024-05-01T11:22:50Z

...c/test/java/com/microsoft/identity/nativeauth/NativeAuthPublicClientApplicationKotlinTest.kt

@@ -101,6 +107,46 @@ class NativeAuthPublicClientApplicationKotlinTest : PublicClientApplicationAbstr
    private val password = "verySafePassword".toCharArray()
    private val code = "1234"
    private val emptyString = ""
+    private val allowPII = true


We will need tests for both true and false, right? I.e. in theory, every use case (test) should be performed with both PII enabled and disabled. Brute force way would be to duplicate every test (perhaps using a parameterised JUnit setup, e.g. see CommandResultUtilTest). Not ideal. Can we think of a smarter way to do this?

Use Parameterized for this.

SammyO · 2024-05-01T12:46:17Z

...c/test/java/com/microsoft/identity/nativeauth/NativeAuthPublicClientApplicationKotlinTest.kt

+            }
+        }
+    }
+    private val spyLoggerCallback = spy(loggerCallback)


it's actually not necessary to make this a spy I think.

… for runTest{}

Yuki-YuXin · 2024-05-03T15:59:40Z

...c/test/java/com/microsoft/identity/nativeauth/NativeAuthPublicClientApplicationKotlinTest.kt

+        containsPII: Boolean
+    ) {
+        if (allowPII) {
+            allowPIIFalseToCheck.forEach { regex ->


This part might be not necessary because LoggerTest takes the responsibility of validating containsPII.

Not exactly. LoggerTest validates whether, if a native auth object states that it contains PII (through ILoggable), the callback's containsPII is set to true (and vice versa). But there are more ways through which containsPII can be set. Moreover: these tests validate whether containsPII is correctly set according to actual fields (like username, attributes, etc.), and they're run on a wide range of scenarios. This is more of an E2E test, whereas LoggerTest is a unit test that tests the ILoggable interface specifically.

Add verifyLogCouldContain function to validate whether containsPII is correctly set according to actual fields.

SammyO · 2024-05-07T14:23:55Z

...c/test/java/com/microsoft/identity/nativeauth/NativeAuthPublicClientApplicationKotlinTest.kt

@@ -101,10 +112,31 @@ class NativeAuthPublicClientApplicationKotlinTest : PublicClientApplicationAbstr
    private val password = "verySafePassword".toCharArray()
    private val code = "1234"
    private val emptyString = ""
+    private val infoPIIToCheck = listOf(


nit: why is this variable called info?

Short for information. Renamed as sensitivePIIMessages as Robert suggested.

SammyO · 2024-05-07T14:24:56Z

...c/test/java/com/microsoft/identity/nativeauth/NativeAuthPublicClientApplicationKotlinTest.kt

+    private val allowPIIFalseToCheck = listOf(
+        """(?<![\(])username[:=]""",
+        """(?i)\b(challengeTargetLabel|challenge_target_label)[:=]""",
+        """(?i)\b(grantType|grant_type)[:=]"""


IMO grant type is not PII. It's a developer setting, just like authority URL.

SammyO · 2024-05-07T14:31:41Z

...c/test/java/com/microsoft/identity/nativeauth/NativeAuthPublicClientApplicationKotlinTest.kt

@@ -181,8 +221,21 @@ class NativeAuthPublicClientApplicationKotlinTest : PublicClientApplicationAbstr
            MockApiResponseType.TOKEN_SUCCESS
        )

+        val loggingNumber = if (allowPII) 137 else 127


What is this used for? Did you manually count the amount of logs that are produced in a certain flow, and you're counting them down? If so, let's think of an alternative strategy as this is not scalable. This test would need to be updated very frequently, and the means to get to this count (i.e. manually counting logs) is time consuming.

Yes, counting first then counting down then. Have updated according to the offline discussion.

...c/test/java/com/microsoft/identity/nativeauth/NativeAuthPublicClientApplicationKotlinTest.kt

SammyO · 2024-05-10T11:16:06Z

...c/test/java/com/microsoft/identity/nativeauth/NativeAuthPublicClientApplicationJavaTest.java

+        this.allowPII = allowPII;
+    }
+
+    private final List<String> sensitivePIIMessages = Arrays.asList(


can we add one more item here? A regex for a JWT, which would cover access tokens and ID tokens. For that regex you can omit the = and : parts.

Done. a JWT token or similar structure."""^[A-Za-z0-9_-]+\\.[A-Za-z0-9_-]+\\.[A-Za-z0-9_-]+$""" // JWT token

SammyO · 2024-05-10T11:19:51Z

...c/test/java/com/microsoft/identity/nativeauth/NativeAuthPublicClientApplicationJavaTest.java

+        checkSafeLogging();
+    }
+
+    private void checkSafeLogging() {


Since this is used in both tests, and potentially more tests moving forward: can this be extracted into a dedicated component, so that reusability becomes more straight forward? Along with the permittedPIIMessages and sensitivePIIMessages lists. So that we have 1 source of truth.

Create a component called as LoggerCheckHelper which has all logger related stuff inside.

SammyO · 2024-05-10T11:20:02Z

...c/test/java/com/microsoft/identity/nativeauth/NativeAuthPublicClientApplicationJavaTest.java

+            disableList.addAll(permittedPIIMessages);
+        }
+
+        for (String regex : allowList) {


nice and clean 👍

SammyO · 2024-05-13T08:55:59Z

azure-pipelines/pull-request-validation/pr-msal.yml

@@ -66,7 +67,7 @@ jobs:
  - task: Gradle@2
    displayName: Run Unit tests
    inputs:
-      tasks: msal:testLocalDebugUnitTest -Plabtest -PlabSecret=$(LabVaultAppSecret) -ProbolectricSdkVersion=${{variables.robolectricSdkVersion}}
+      tasks: msal:testLocalDebugUnitTest -Plabtest -PlabSecret=$(LabVaultAppCert) -ProbolectricSdkVersion=${{variables.robolectricSdkVersion}}


Are you sure about this change?

There is opening PR (and has not merged) from MSAL to update the expired secret. I include their changes to see if that's the reason for the failed pipeline verification. I personally think we need to wait that PR to be merged in order to merge our work.

Agree. Let's not introduce changes with this PR that don't belong here. Let's mark this PR as "draft" in the meantime.

This reverts commit f12c022.

This reverts commit 7c97e54.

Safe logging test

7b69ea5

github-actions bot added the msal label Apr 29, 2024

SammyO reviewed Apr 29, 2024

View reviewed changes

...c/test/java/com/microsoft/identity/nativeauth/NativeAuthPublicClientApplicationKotlinTest.kt Outdated Show resolved Hide resolved

SammyO reviewed Apr 29, 2024

View reviewed changes

minor fix

93d0805

SammyO reviewed Apr 29, 2024

View reviewed changes

Use regex rules to filter the logs

66679a6

SammyO reviewed Apr 29, 2024

View reviewed changes

Yuki-YuXin added 2 commits April 29, 2024 17:46

Modify rules and pass tests

3e545b2

Update tag to use regex

aad4fc5

SammyO reviewed Apr 30, 2024

View reviewed changes

Modify regex rules and use any() in tag log.

c8072e4

Yuki-YuXin marked this pull request as ready for review April 30, 2024 08:56

Yuki-YuXin requested review from a team as code owners April 30, 2024 08:56

Yuki-YuXin added 9 commits April 30, 2024 12:46

spy(ILoggerCallback) + assertFalse(regex.matches)

d3df120

variable order

21d4910

assertFalse(spyLoggerCallback.failCalled) in every test to fail test.

1fead78

remove blank line

0f67b09

Java version sample

761a77f

Merge branch 'dev' into yuki/logging-check

c6a08a6

Revert "Java version sample"

1d542e6

This reverts commit 761a77f.

Fix for password regex rule

9939418

Narrow down the regex scopes and pass tests.

248a338

SammyO reviewed May 1, 2024

View reviewed changes

First version for CountDownLatch but the callback takes too much time…

4c2ba7c

… for runTest{}

Yuki-YuXin commented May 3, 2024

View reviewed changes

Merge branch 'dev' into yuki/logging-check

a7d6908

SammyO reviewed May 7, 2024

View reviewed changes

rmccahill reviewed May 8, 2024

View reviewed changes

...c/test/java/com/microsoft/identity/nativeauth/NativeAuthPublicClientApplicationKotlinTest.kt Outdated Show resolved Hide resolved

Use verify instead of fail

7404a79

rmccahill reviewed May 8, 2024

View reviewed changes

...c/test/java/com/microsoft/identity/nativeauth/NativeAuthPublicClientApplicationKotlinTest.kt Outdated Show resolved Hide resolved

Yuki-YuXin added 4 commits May 8, 2024 13:59

Add containPii check

eedb6b1

Rename variables

b6a5c76

Update Java version

c061727

Minor in Kotlin version: fix any()->anyBoolean()

1a7d1bf

SammyO reviewed May 10, 2024

View reviewed changes

Yuki-YuXin added 4 commits May 10, 2024 13:12

Create a component for the logger safe checking

c539cfd

JWT token regex rule

7750639

Remove redundant blank line

6816d2d

Remove redundant remove logger in Java version

0a05fff

Yuki-YuXin added the No-Changelog This change does not update the changelog. label May 10, 2024

rmccahill approved these changes May 10, 2024

View reviewed changes

Yuki-YuXin added 3 commits May 10, 2024 17:18

Add black line for the new class

3c2dc77

Use the updated secret

f12c022

Use the updated secret

7c97e54

SammyO reviewed May 13, 2024

View reviewed changes

Yuki-YuXin added 3 commits May 13, 2024 10:39

Revert "Use the updated secret"

9bcd81c

This reverts commit f12c022.

Revert "Use the updated secret"

bd552ed

This reverts commit 7c97e54.

Merge branch 'dev' into yuki/logging-check

e03b9da

SammyO approved these changes May 14, 2024

View reviewed changes

Yuki-YuXin merged commit c207fcc into dev May 14, 2024
8 checks passed

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

Native auth safe logging test #2092

Native auth safe logging test #2092

Yuki-YuXin commented Apr 29, 2024 •

edited

SammyO Apr 29, 2024 •

edited

Yuki-YuXin Apr 29, 2024

SammyO May 1, 2024

SammyO Apr 29, 2024 •

edited

Yuki-YuXin Apr 30, 2024

SammyO Apr 29, 2024

Yuki-YuXin Apr 30, 2024 •

edited

SammyO Apr 29, 2024

Yuki-YuXin Apr 30, 2024

SammyO Apr 29, 2024

Yuki-YuXin Apr 29, 2024

SammyO Apr 30, 2024

Yuki-YuXin Apr 30, 2024

SammyO May 1, 2024

Yuki-YuXin May 2, 2024

SammyO May 1, 2024

Yuki-YuXin May 3, 2024

SammyO May 1, 2024

Yuki-YuXin May 3, 2024

SammyO May 7, 2024

Yuki-YuXin May 8, 2024

SammyO May 7, 2024

Yuki-YuXin May 8, 2024 •

edited

SammyO May 7, 2024

SammyO May 7, 2024

Yuki-YuXin May 8, 2024

SammyO May 10, 2024

Yuki-YuXin May 10, 2024

SammyO May 10, 2024 •

edited

Yuki-YuXin May 10, 2024

SammyO May 10, 2024

SammyO May 13, 2024

Yuki-YuXin May 13, 2024

SammyO May 13, 2024

Native auth safe logging test #2092

Native auth safe logging test #2092

Conversation

Yuki-YuXin commented Apr 29, 2024 • edited

Comments and Changes Summary:

SammyO Apr 29, 2024 • edited

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

SammyO Apr 29, 2024 • edited

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Yuki-YuXin Apr 30, 2024 • edited

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

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

Yuki-YuXin May 8, 2024 • edited

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

SammyO May 10, 2024 • edited

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

Yuki-YuXin commented Apr 29, 2024 •

edited

SammyO Apr 29, 2024 •

edited

SammyO Apr 29, 2024 •

edited

Yuki-YuXin Apr 30, 2024 •

edited

Yuki-YuXin May 8, 2024 •

edited

SammyO May 10, 2024 •

edited