Issue: DB cache tests are randomly failing based depending on current time

[3v1n0]

Is there an existing issue for this?

• I have searched the existing issues and found none that matched mine

Describe the issue

We're randomly getting these failures:

--- FAIL: TestUpdateUserEntry (0.00s)
    --- FAIL: TestUpdateUserEntry/Remove_user_from_a_group_still_part_from_another_user (0.00s)
        db_test.go:239: 
            	Error Trace:	/home/runner/work/authd/authd/internal/users/cache/db_test.go:239
            	Error:      	Not equal: 
            	            	expected: "GroupByID:\n    \"11111\": '{\"Name\":\"group1\",\"GID\":11111}'\n    \"22222\": '{\"Name\":\"group2\",\"GID\":22222}'\n    \"33333\": '{\"Name\":\"group3\",\"GID\":33333}'\n    \"44444\": '{\"Name\":\"group4\",\"GID\":44444}'\n    \"99999\": '{\"Name\":\"commongroup\",\"GID\":99999}'\nGroupByName:\n    commongroup: '{\"Name\":\"commongroup\",\"GID\":99999}'\n    group1: '{\"Name\":\"group1\",\"GID\":11111}'\n    group2: '{\"Name\":\"group2\",\"GID\":22222}'\n    group3: '{\"Name\":\"group3\",\"GID\":33333}'\n    group4: '{\"Name\":\"group4\",\"GID\":44444}'\nGroupToUsers:\n    \"11111\": '{\"GID\":11111,\"UIDs\":[1111]}'\n    \"22222\": '{\"GID\":22222,\"UIDs\":[2222]}'\n    \"33333\": '{\"GID\":33333,\"UIDs\":[3333]}'\n    \"44444\": '{\"GID\":33333,\"UIDs\":[4444]}'\n    \"99999\": '{\"GID\":99999,\"UIDs\":[2222]}'\nUserByID:\n    \"1111\": '{\"Name\":\"user1\",\"UID\":1111,\"GID\":11111,\"Gecos\":\"User1 gecos\\nOn multiple lines\",\"Dir\":\"/home/user1\",\"Shell\":\"/
            	            	actual  : "GroupByID:\n    \"11111\": '{\"Name\":\"group1\",\"GID\":11111}'\n    \"22222\": '{\"Name\":\"group2\",\"GID\":22222}'\n    \"33333\": '{\"Name\":\"group3\",\"GID\":33333}'\n    \"44444\": '{\"Name\":\"group4\",\"GID\":44444}'\n    \"99999\": '{\"Name\":\"commongroup\",\"GID\":99999}'\nGroupByName:\n    commongroup: '{\"Name\":\"commongroup\",\"GID\":99999}'\n    group1: '{\"Name\":\"group1\",\"GID\":11111}'\n    group2: '{\"Name\":\"group2\",\"GID\":22222}'\n    group3: '{\"Name\":\"group3\",\"GID\":33333}'\n    group4: '{\"Name\":\"group4\",\"GID\":44444}'\nGroupToUsers:\n    \"11111\": '{\"GID\":11111,\"UIDs\":[1111]}'\n    \"22222\": '{\"GID\":22222,\"UIDs\":[2222]}'\n    \"33333\": '{\"GID\":33333,\"UIDs\":[3333]}'\n    \"44444\": '{\"GID\":33333,\"UIDs\":[4444]}'\n    \"99999\": '{\"GID\":99999,\"UIDs\":[2222]}'\nUserByID:\n    \"1111\": '{\"Name\":\"user1\",\"UID\":1111,\"GID\":11111,\"Gecos\":\"User1 gecos\\nOn multiple lines\",\"Dir\":\"/home/user1\",\"Shell\":\"/

--- Expected
+++ Actual
@@ -21,3 +21,3 @@
 "2222": '{"Name":"user2","UID":2222,"GID":22222,"Gecos":"User2","Dir":"/home/user2","Shell":"/bin/dash","LastPwdChange":-1,"MaxPwdAge":-1,"PwdWarnPeriod":-1,"PwdInactivity":-1,"MinPwdAge":-1,"ExpirationDate":-1,"LastLogin":"BBBBBTIME"}'
-    "3333": '{"Name":"user3","UID":3333,"GID":33333,"Gecos":"User3 gecos","Dir":"/home/user3","Shell":"/bin/zsh","LastPwdChange":-1,"MaxPwdAge":-1,"PwdWarnPeriod":-1,"PwdInactivity":-1,"MinPwdAge":-1,"ExpirationDate":-1,"LastLogin":"ABCDETIME"}'
+    "3333": '{"Name":"user3","UID":3333,"GID":33333,"Gecos":"User3 gecos","Dir":"/home/user3","Shell":"/bin/zsh","LastPwdChange":-1,"MaxPwdAge":-1,"PwdWarnPeriod":-1,"PwdInactivity":-1,"MinPwdAge":-1,"ExpirationDate":-1,"LastLogin":"2024-09-29T23:43:38.400{{CURRENT_UID}}67Z"}'
 "4444": '{"Name":"userwithoutbroker","UID":4444,"GID":44444,"Gecos":"userwithoutbroker","Dir":"/home/userwithoutbroker","Shell":"/bin/sh","LastPwdChange":-1,"MaxPwdAge":-1,"PwdWarnPeriod":-1,"PwdInactivity":-1,"MinPwdAge":-1,"ExpirationDate":-1,"LastLogin":"ABCDETIME"}'
@@ -26,3 +26,3 @@
 user2: '{"Name":"user2","UID":2222,"GID":22222,"Gecos":"User2","Dir":"/home/user2","Shell":"/bin/dash","LastPwdChange":-1,"MaxPwdAge":-1,"PwdWarnPeriod":-1,"PwdInactivity":-1,"MinPwdAge":-1,"ExpirationDate":-1,"LastLogin":"BBBBBTIME"}'
-    user3: '{"Name":"user3","UID":3333,"GID":33333,"Gecos":"User3 gecos","Dir":"/home/user3","Shell":"/bin/zsh","LastPwdChange":-1,"MaxPwdAge":-1,"PwdWarnPeriod":-1,"PwdInactivity":-1,"MinPwdAge":-1,"ExpirationDate":-1,"LastLogin":"ABCDETIME"}'
+    user3: '{"Name":"user3","UID":3333,"GID":33333,"Gecos":"User3 gecos","Dir":"/home/user3","Shell":"/bin/zsh","LastPwdChange":-1,"MaxPwdAge":-1,"PwdWarnPeriod":-1,"PwdInactivity":-1,"MinPwdAge":-1,"ExpirationDate":-1,"LastLogin":"2024-09-29T23:43:38.400{{CURRENT_UID}}67Z"}'
 userwithoutbroker: '{"Name":"userwithoutbroker","UID":4444,"GID":44444,"Gecos":"userwithoutbroker","Dir":"/home/userwithoutbroker","Shell":"/bin/sh","LastPwdChange":-1,"MaxPwdAge":-1,"PwdWarnPeriod":-1,"PwdInactivity":-1,"MinPwdAge":-1,"ExpirationDate":-1,"LastLogin":"ABCDETIME"}'

This is likely due to the fact we're not replacing properly the timestamp.

Steps to reproduce

No response

System information and logs

No response

Double check your logs

• I have redacted any sensitive information from the logs

[3v1n0]

FYI this can be reproduced by running something such as:

go test -C internal ./... -v -run TestUpdateUserEntry/Insert_new_user_without_optional_gecos_field -count 2000

[adombeck]

That happens because we replace all occurrences of the current UID in the keys and values of all buckets with {{CURRENT_UID}}, and it can happen that a timestamp also contains the current UID.

I found that it would require complicating the current code quite a bit to avoid that issue, and since we plan to migrate from bbolt to sqlite soon (which would solve the issue), I suggest we just wait until that.