Race condition in mod_auth_openidc filecache

[dbakker]

We've been getting random errors from mod_auth_openidc like this:

[client XXXXX:0] oidc_cache_file_read: could not read enough bytes from: "PATH", bytes_read (0) != len (16),

We suspect this might be caused by a race condition in src/cache/file.c. Our appliction is javascript based and fires tens of json requests at the same time, potentially triggering multiple oidc_cache_file_set's / oidc_cache_file_get's at once.

The way that oidc_cache_file_set works now is that it always opens the file with APR_FOPEN_TRUNCATE and only after does an APR_FLOCK_EXCLUSIVE. This means that after oidc_cache_file_get gets a lock it might find an empty file because of a oidc_cache_file_set that has preemptively emptied the file.

As a suggested fix, perhaps the file could be truncated after locking instead of before.

Additional info:
mod_auth_openidc version: 2.4.10 (latest)

config settings:

OIDCCacheType file
OIDCCacheDir /var/cache/apache2/mod_auth_openidc/cache
OIDCSessionType server-cache

OIDCSessionInactivityTimeout 28800
OIDCSessionMaxDuration 28800

OIDCHTTPTimeoutShort 30

OIDCStateMaxNumberOfCookies 7 true

OIDCProviderMetadataURL https://URL
OIDCRedirectURI https://URL
OIDCCryptoPassphrase 123securekey123
OIDCClientID apache2
OIDCClientSecret 123securekey123
OIDCRemoteUserClaim preferred_username
OIDCHTMLErrorTemplate /srv/www/authentication.html

[zandbelt]

just a few questions about that:
a) did you replace the actual filename with "PATH" yourself?
b) would you be able to test a fix by building from source?

[dbakker]

a) Yes I replaced it with "PATH", the actual filenames exist and contain data (by the time we look at it)
b) We cannot easily test a fix because the error occurs seldomly. And we will try the redis backend to try to avoid this problem.

Perhaps it might be possible for you to reproduce this problem in a test setup by putting a sleep before apr_file_lock(fd, APR_FLOCK_EXCLUSIVE) and run oidc_cache_file_set and oidc_cache_file_get in parallel?

[zandbelt]

Ok, thanks, I confirmed the issue with the suggested sleep indeed:

file.c(113): oidc_cache_file_read: could not read from: PATH (End of file found)
file.c(120): oidc_cache_file_read: could not read enough bytes from: "PATH", bytes_read (0) != len (16)
file.c(235): oidc_cache_file_get: return error status 20014 (Internal error (specific information not available))

and fixed it in 244afa7; let me know if you want a release candidate build for a particular platform

[blackwhiser1]

Good evening,

I happened to see that same error:
[Fri Feb 25 17:49:46 2022] [error:auth_openidc] [pid 22598] oidc_cache_file_read: could not read from: /usr2/vdxfiles.shared/versaterm/apache2/oidc_sessions/mod-auth-openidc-s-AY82NPUUw3QiYVYxKs4qqcTBJu-yYyG6hb9fZB1cDwc (End of file found)
[Fri Feb 25 17:49:46 2022] [error:auth_openidc] [pid 22598] oidc_cache_file_read: could not read enough bytes from: "/usr2/vdxfiles.shared/versaterm/apache2/oidc_sessions/mod-auth-openidc-s-AY82NPUUw3QiYVYxKs4qqcTBJu-yYyG6hb9fZB1cDwc", bytes_read (0) != len (16)
[Fri Feb 25 17:49:46 2022] [error:auth_openidc] [pid 22598] oidc_cache_file_get: return error status 20014 (Internal error (specific information not available))
[Fri Feb 25 17:49:46 2022] [warn:auth_openidc] [pid 22598] oidc_cache_get: error retrieving value from file cache backend for encrypted key AY82NPUUw3QiYVYxKs4qqcTBJu-yYyG6hb9fZB1cDwc
[Fri Feb 25 17:49:46 2022] [error:auth_openidc] [pid 22598] oidc_session_load_cache: cache backend failure for key 35ed18fa-9663-11ec-b47d-a327be314527

So I decided to update to the new version v2.4.11. But I still see the same error, less frequently. It still appears, and we are not certain how to fix this issue.

The current architecture is as follow, we have 2 application servers using this module in apache sitting behind a load balancer. Additionally, the cache sessions are stored on a NFS, so that the sessions are shared between both servers.

If you need more information, please let me know.

Thank you very much!

[zandbelt]

I can see a path that would lead to the file being deleted whilst being read but also in that case, the session would have been expired anyway and the user would have to relogin anyhow. Is that conformant with your observations? (i.e. sessions aren't terminated permanently)

[blackwhiser1]

@zandbelt ,

Assumption 1:
Well we are running in a cluster and that session is stored on a NFS. So my thought is that the cleanup process from server B would cleanup a session that would be used by server A (the user connected to). I am not sure how your process determines that a session is inactive/expired. I would imagine that the expiry would be written in the session file. But additionally, when this cleanup happen, does it require a lock on the file? So when server B is doing a cleanup, it locks the file that server A requires when it reads it to validate the current user logged in on server A.

Assumption 2:
I am wondering how is this locking mechanism work? Since we are in a cluster (2 instances with this example), is it possible that the server B (the one not having the user connected to) would try to read the lock? Which would prevent the server A to read the file. Since server A could not read the file, it would log the user out.

Let me know if I make any sense. These are really just assumption, since I have not looked at the code, I am just going by the documentation and giving possible scenarios. Let me know your thoughts.

[zandbelt]

are you still seeing expired sessions that should not be expired, or just errors in the log about sessions that are expected to be expired anyhow?

[blackwhiser1]

I see expired sessions that should not be expired

[dbakker]

@blackwhiser1 Currently the cache files are locked, then truncated, then written. Perhaps in your case NFS does not care about the lock and is propagating truncated files?

[zandbelt]

I still don't see why non-expired sessions would expire, but at least one other potential race condition was fixed in:
d0c632a
can you guys try from source or do you need a specific build?

[blackwhiser1]

I can try from source and follow your instructions. I will let you know if I need a build. Thanks to you guys! @dbakker @zandbelt

[blackwhiser1]

@zandbelt ,
So after compiling the new patch, I get this error quite frequently which prevent me from navigating through my webapp correctly. At first I thought it was a permission issue, but the permissions are set as 777 or 666, which should not prevent any user on the server to read or write to these files. Not sure if this is related to your changes, but it was not doing this before.

[Fri Mar 11 13:42:19 2022] [error:auth_openidc] [pid 32127] oidc_cache_file_set: cache file: /usr2/vdxfiles.shared/versaterm/apache2/oidc_sessions/mod-auth-openidc-s-7IDuUnMlaKyvLfkh24859xabclbtjTSM1L5feLRhEcU.tmp could not be renamed to: /usr2/vdxfiles.shared/versaterm/apache2/oidc_sessions/mod-auth-openidc-s-7IDuUnMlaKyvLfkh24859xabclbtjTSM1L5feLRhEcU
[Fri Mar 11 13:42:19 2022] [warn:auth_openidc] [pid 32127] oidc_cache_set: could NOT store 11695 bytes in file cache backend for encrypted key 7IDuUnMlaKyvLfkh24859xabclbtjTSM1L5feLRhEcU
[Fri Mar 11 13:42:19 2022] [warn:auth_openidc] [pid 32127] oidc_check_userid_openidc: error saving session

[dbakker]

I think the problem is that the filename should not be [targetfilename].tmp but instead something like [targetfilename].[randomstring].tmp

In this patch what happens is:

1. [targetfilename].tmp is created/opened
2. it is locked
3. content is written
4. it is unlocked
5. it is renamed

In @blackwhiser1's case it could for example be that:

• thread a runs steps 1-4 (not yet renamed file)
• thread b runs steps 1-5 (renames the file)
• thread a runs step 5 (fails because file is already renamed)

Something different that could also happen is:

• thread a runs steps 1-4
• thread b runs step 1 (opens the file)
• thread a runs steps 5 (renames the file)
• now thread b runs steps 2-5, truncating the file, writing it, tries to rename a non-existing file

So in short the temporary filename should be unique.

[zandbelt]

Thanks for reporting and suggesting, I'll adapt according to the suggestion

[zandbelt]

please try 8e7284f

[blackwhiser1]

Thank you so much @zandbelt and @dbakker.
So far it looks good, I will get back to you when I can confirm 100% that this fix works.

When are you planning to push a new version?

Thanks!

[blackwhiser1]

I can confirm that this fix works well.

[zandbelt]

ok, thanks; @dbakker your problems are solved as well with that?

[dbakker]

@zandbelt Yes this seems like a great fix!

[moschlar]

I just discovered something funny:

On 2.4.9.4, so before most of the fixes mentioned in this thread it seems to help to add local_lock=flock to the NFS mount options.

Now this doesn't really make sense to me at all, but maybe that's a valid workaround to someone else.

[zandbelt]

@moschlar thanks for chiming in, I guess that option changes the timing and thus impacts the race condition (positively in this case)

[zandbelt]

for the record, the complete fix is included in release 2.4.11.1 and upwards

edit: it needed another fix in #955

[moschlar]

Which - for those using it from the Debian repositorys - I have just prepared as a proper upload to the bullseye-backports archive.