Using Apache DBD sessions

[niki-eng]

Hi,

I'm trying to make mod_auth_gssapi to work with Apache dbd sessions.
If apache is configured to keep sessions with a client-side cookie (no dbd) everything works fine - sessions are established and users are authenticated correct. But when apache uses dbd to store sessions this causes the session to be reestablished on every request making them useless. DBD sessions are configured to use cookie with the directive
SessionDBDCookieName
When the browser makes a request it uses the last session cookie but the server responses with a new session cookie i.e. new session making authentication invalid and forcing browser to reauthenticate. This happens with every single request.
According to mysql logs (I use mysql as DBD backend) initially the session is correctly recognized but thereafter a new session is established and apache responses with a new cookie. Here is a mysql log snippet for a single request:

1437 Execute	select value from `apache_sessions` where `key` = '111101f4-ccf6-4a38-8bea-807c85bc949e' and (`expiry` = 0 or `expiry` > 1518937743578581)
1437 Execute	update `apache_sessions` set `value` = 'MagBearerToken=fjgFqGiD95ZkNoKiB4KdsIlCJKrsd8fR0l3CyhXe6YXJsrBodW6nsNGbeSVG4HNnxdlhOBrjBbsvrLohyQM%2bFZXhbTpkPtNxKIA9OMaBw2xooaf7I9sTSbfHByt4SRCjkdoE7kANAmbu2oWS4yqKVfN8XaoPIXClh8iuyY4Ef0rHbEgFLCOV3TssbJuT6mOd&expiry=1518939543580705', `expiry` = 1518939543580705, `key` = '111101f4-ccf6-4a38-8bea-807c85bc949e' where `key` = '111101f4-ccf6-4a38-8bea-807c85bc949e'
1437 Execute	select value from `apache_sessions` where `key` = '111101f4-ccf6-4a38-8bea-807c85bc949e' and (`expiry` = 0 or `expiry` > 1518937744554384)
1437 Execute	insert into `apache_sessions` (`value`, `expiry`, `key`) values ('expiry=1518939544638110', 1518939544638110, '9ad02365-751e-4ae7-abc5-2d3223d2092a')

As you can see the session is found in DB and expiry is updated but then a new cookie/session is generated

I'm digging with this issue for a long time - tried to disable mod_auth_gssapi and found that mod_rewrite also produces the same problem (my app uses rewrite rule for almost every URL). Modifying the rule to set the environment variable HTTP_SESSION seems to fix the issue in mod_rewrite:
RewriteRule ^(.*)$ index.php?/$1 [QSA,L,E=HTTP_SESSION:%{LA-F:HTTP_SESSION}]
With this rule mod_rewrite works corectly with DBD - sessions are not reestablished on every request but enabling mod_auth_gssapi again restores the problem.

Can you pls advise for a possible workaround or what is making the issue.

Best regards,
Nikolay

P.S. I use DBD for storing sessions because there are situations when I want to invalidate a valid apache session by hand, so deleting the cooike from mysql looks like an easy option

[simo5]

Please produce mag_auth_gssapi debug logs

[niki-eng]

Sorry for the delay but I was on a trip and had no access to server logs
Here is the apache log:

[Sun Mar 04 11:31:07.190075 2018] [core:debug] [pid 13321] protocol.c(2211): [client 192.168.2.33:57162] AH03155: select protocol from , choices=h2,http/1.1 for server base.example.net
[Sun Mar 04 11:31:07.211424 2018] [authz_core:debug] [pid 13321] mod_authz_core.c(809): [client 192.168.2.33:57162] AH01626: authorization result of Require valid-user : denied (no authenticated user yet), referer: https://base/
[Sun Mar 04 11:31:07.211450 2018] [authz_core:debug] [pid 13321] mod_authz_core.c(809): [client 192.168.2.33:57162] AH01626: authorization result of <RequireAll>: denied (no authenticated user yet), referer: https://base/
[Sun Mar 04 11:31:07.211459 2018] [authz_core:debug] [pid 13321] mod_authz_core.c(809): [client 192.168.2.33:57162] AH01626: authorization result of <RequireAny>: denied (no authenticated user yet), referer: https://base/
[Sun Mar 04 11:31:07.211470 2018] [auth_gssapi:debug] [pid 13321] mod_auth_gssapi.c(895): [client 192.168.2.33:57162] URI: /Users/activity, no main, no prev, referer: https://base/
[Sun Mar 04 11:31:07.212242 2018] [auth_gssapi:info] [pid 13321] [client 192.168.2.33:57162] NO AUTH DATA Client did not send any authentication headers, referer: https://base/
[Sun Mar 04 11:31:07.212380 2018] [authz_core:debug] [pid 13321] mod_authz_core.c(809): [client 192.168.2.33:57162] AH01626: authorization result of Require valid-user : denied (no authenticated user yet), referer: https://base/
[Sun Mar 04 11:31:07.212398 2018] [authz_core:debug] [pid 13321] mod_authz_core.c(809): [client 192.168.2.33:57162] AH01626: authorization result of <RequireAll>: denied (no authenticated user yet), referer: https://base/
[Sun Mar 04 11:31:07.212405 2018] [authz_core:debug] [pid 13321] mod_authz_core.c(809): [client 192.168.2.33:57162] AH01626: authorization result of <RequireAny>: denied (no authenticated user yet), referer: https://base/
[Sun Mar 04 11:31:07.212414 2018] [auth_gssapi:debug] [pid 13321] mod_auth_gssapi.c(895): [client 192.168.2.33:57162] URI: /unauthorized/index.php, no main, with prev, referer: https://base/
[Sun Mar 04 11:31:07.212421 2018] [auth_gssapi:error] [pid 13321] [client 192.168.2.33:57162] The main request is tasked to establish the security context, can't proceed!, referer: https://base/
[Sun Mar 04 11:31:07.213697 2018] [core:debug] [pid 13321] util_cookies.c(59): [client 192.168.2.33:57162] AH00007: ap_cookie: user '(null)' set cookie: 'gssapi_session=a2deaddc-7cbb-44f3-8287-0cacc8b4d961;Max-Age=1800;path=/;httponly;secure;', referer: https://base/
[Sun Mar 04 11:31:07.214762 2018] [core:debug] [pid 13321] util_cookies.c(59): [client 192.168.2.33:57162] AH00007: ap_cookie: user '(null)' set cookie: 'gssapi_session=f63dca49-f43a-4548-abe6-5b7d17727b6a;Max-Age=1800;path=/;httponly;secure;', referer: https://base/
[Sun Mar 04 11:31:07.341647 2018] [authz_core:debug] [pid 13321] mod_authz_core.c(809): [client 192.168.2.33:57162] AH01626: authorization result of Require valid-user : denied (no authenticated user yet), referer: https://base/
[Sun Mar 04 11:31:07.341671 2018] [authz_core:debug] [pid 13321] mod_authz_core.c(809): [client 192.168.2.33:57162] AH01626: authorization result of <RequireAll>: denied (no authenticated user yet), referer: https://base/
[Sun Mar 04 11:31:07.341679 2018] [authz_core:debug] [pid 13321] mod_authz_core.c(809): [client 192.168.2.33:57162] AH01626: authorization result of <RequireAny>: denied (no authenticated user yet), referer: https://base/
[Sun Mar 04 11:31:07.341690 2018] [auth_gssapi:debug] [pid 13321] mod_auth_gssapi.c(895): [client 192.168.2.33:57162] URI: /Users/activity, no main, no prev, referer: https://base/
[Sun Mar 04 11:31:07.344558 2018] [:debug] [pid 13321] environ.c(317): [client 192.168.2.33:57162] no name attributes found, referer: https://base/
[Sun Mar 04 11:31:07.344583 2018] [auth_gssapi:debug] [pid 13321] mod_auth_gssapi.c(1245): [client 192.168.2.33:57162] requester: senser@EXAMPLE.NET, referer: https://base/
[Sun Mar 04 11:31:07.345167 2018] [authz_core:debug] [pid 13321] mod_authz_core.c(809): [client 192.168.2.33:57162] AH01626: authorization result of Require valid-user : granted, referer: https://base/
[Sun Mar 04 11:31:07.345208 2018] [authz_core:debug] [pid 13321] mod_authz_core.c(809): [client 192.168.2.33:57162] AH01626: authorization result of <RequireAll>: granted, referer: https://base/
[Sun Mar 04 11:31:07.345217 2018] [authz_core:debug] [pid 13321] mod_authz_core.c(809): [client 192.168.2.33:57162] AH01626: authorization result of <RequireAny>: granted, referer: https://base/
[Sun Mar 04 11:31:07.345327 2018] [auth_gssapi:debug] [pid 13321] mod_auth_gssapi.c(727): [client 192.168.2.33:57162] GSSapiImpersonate not On, skipping impersonation., referer: https://base/
[Sun Mar 04 11:31:07.345365 2018] [auth_gssapi:debug] [pid 13321] mod_auth_gssapi.c(727): [client 192.168.2.33:57162] GSSapiImpersonate not On, skipping impersonation., referer: https://base/
[Sun Mar 04 11:31:07.345383 2018] [auth_gssapi:debug] [pid 13321] mod_auth_gssapi.c(727): [client 192.168.2.33:57162] GSSapiImpersonate not On, skipping impersonation., referer: https://base/
[Sun Mar 04 11:31:07.345478 2018] [authz_core:debug] [pid 13321] mod_authz_core.c(809): [client 192.168.2.33:57162] AH01626: authorization result of Require valid-user : denied (no authenticated user yet), referer: https://base/
[Sun Mar 04 11:31:07.345492 2018] [authz_core:debug] [pid 13321] mod_authz_core.c(809): [client 192.168.2.33:57162] AH01626: authorization result of <RequireAll>: denied (no authenticated user yet), referer: https://base/
[Sun Mar 04 11:31:07.345500 2018] [authz_core:debug] [pid 13321] mod_authz_core.c(809): [client 192.168.2.33:57162] AH01626: authorization result of <RequireAny>: denied (no authenticated user yet), referer: https://base/
[Sun Mar 04 11:31:07.345508 2018] [auth_gssapi:debug] [pid 13321] mod_auth_gssapi.c(895): [client 192.168.2.33:57162] URI: /index.php, no main, with prev, referer: https://base/
[Sun Mar 04 11:31:07.345518 2018] [authz_core:debug] [pid 13321] mod_authz_core.c(809): [client 192.168.2.33:57162] AH01626: authorization result of Require valid-user : granted, referer: https://base/
[Sun Mar 04 11:31:07.345525 2018] [authz_core:debug] [pid 13321] mod_authz_core.c(809): [client 192.168.2.33:57162] AH01626: authorization result of <RequireAll>: granted, referer: https://base/
[Sun Mar 04 11:31:07.345532 2018] [authz_core:debug] [pid 13321] mod_authz_core.c(809): [client 192.168.2.33:57162] AH01626: authorization result of <RequireAny>: granted, referer: https://base/
[Sun Mar 04 11:31:07.345562 2018] [auth_gssapi:debug] [pid 13321] mod_auth_gssapi.c(727): [client 192.168.2.33:57162] GSSapiImpersonate not On, skipping impersonation., referer: https://base/
[Sun Mar 04 11:31:07.614627 2018] [core:debug] [pid 13321] util_cookies.c(59): [client 192.168.2.33:57162] AH00007: ap_cookie: user 'senser' set cookie: 'gssapi_session=76961277-ffec-4f2b-802f-6c48d6b49055;Max-Age=1800;path=/;httponly;secure;', referer: https://base/
`

And the corresponding mysql log:
`11677 Execute	select value from `apache_sessions` where `key` = 'a2deaddc-7cbb-44f3-8287-0cacc8b4d961' and (`expiry` = 0 or `expiry` > 1520155867211488)
11677 Execute	update `apache_sessions` set `value` = 'expiry=1520157667212459', `expiry` = 1520157667212459, `key` = 'a2deaddc-7cbb-44f3-8287-0cacc8b4d961' where `key` = 'a2deaddc-7cbb-44f3-8287-0cacc8b4d961'
11677 Execute	insert into `apache_sessions` (`value`, `expiry`, `key`) values ('expiry=1520157667213728', 1520157667213728, 'f63dca49-f43a-4548-abe6-5b7d17727b6a')
11677 Execute	select value from `apache_sessions` where `key` = 'f63dca49-f43a-4548-abe6-5b7d17727b6a' and (`expiry` = 0 or `expiry` > 1520155867341706)
11677 Execute	insert into `apache_sessions` (`value`, `expiry`, `key`) values ('expiry=1520157667613595', 1520157667613595, '76961277-ffec-4f2b-802f-6c48d6b49055')

[simo5]

There is something suspicious here:

[Sun Mar 04 11:31:07.213697 2018] ... AH00007: ap_cookie: user '(null)' set cookie: 'gssapi_session= ...

If the user is set to null then the rest of the authz stack will not authorize the user and go through a new auth attempt, in fact the second time you get user 'senser'

Can you provide your configuration ?

[niki-eng]

Yes, of course:

    Options -Indexes +FollowSymLinks -MultiViews
    AllowOverride All
    ErrorDocument 401 /unauthorized/index.php
    Session On
    SessionEnv On
    SessionMaxAge 1800
    AuthType GSSAPI
    AuthName "GSSAPI Single Sign On"
    GssapiSSLonly On
    GssapiCredStore keytab:/etc/apache2/httpd.keytab
    GssapiDelegCcacheDir /var/run/apache2/krb5ccache
    GssapiCredStore ccache:/var/run/apache2/krb5ccache/gssapi
    GssapiAllowedMech krb5
    GssapiNegotiateOnce On
    GssapiBasicAuth Off
    GssapiBasicAuthMech krb5
    GssapiPublishErrors On
    GssapiNameAttributes AUTH_INDICATORS auth-indicators
    GssapiLocalName On
    GssapiImpersonate Off
    GssapiUseSessions On
    GssapiSessionKey key: xxxxxxxxxxxxxxxxxxx
    SessionCookieName gssapi_session path=/;httponly;secure;

[simo5]

Does it work if you turn off GssapiLocalName ?

[niki-eng]

Actually GssapiLocalName=Off doesn't make any difference:

[Thu Mar 08 07:29:08.146785 2018] [core:debug] [pid 10724] util_cookies.c(59): [client 192.168.2.33:49188] AH00007: ap_cookie: user '(null)' set cookie: 'gssapi_session=289f4baf-686a-4c36-9816-9298f3fab304;Max-Age=1800;path=/;httponly;secure;', referer: https://base

[simo5]

I am not sure what's interfeering here.
Seem like DBD sessions do something inherently different that breaks auth ?
In the FreeIPA project they do use RewriteRules sometimes because mod_session has an annoying bug where it sends the cookie twice, but I do not know if that would make a difference in your case.

[frozencemetery]

And there's no change with GssapiLocalName=Off in the logs? (Still null user?)

[niki-eng]

@frozencemetery

Here is the complete log of single request:

[Thu Mar 15 06:48:22.980496 2018] [core:debug] [pid 30344] protocol.c(2211): [client 192.168.2.33:36602] AH03155: select protocol from , choices=h2,http/1.1 for server example.net
[Thu Mar 15 06:48:23.003254 2018] [authz_core:debug] [pid 30344] mod_authz_core.c(809): [client 192.168.2.33:36602] AH01626: authorization result of Require valid-user : denied (no authenticated user yet), referer: https://example/
[Thu Mar 15 06:48:23.003283 2018] [authz_core:debug] [pid 30344] mod_authz_core.c(809): [client 192.168.2.33:36602] AH01626: authorization result of <RequireAny>: denied (no authenticated user yet), referer: https://example/
[Thu Mar 15 06:48:23.003298 2018] [auth_gssapi:debug] [pid 30344] mod_auth_gssapi.c(895): [client 192.168.2.33:36602] URI: /Users/activity, no main, no prev, referer: https://example/
[Thu Mar 15 06:48:23.003870 2018] [auth_gssapi:info] [pid 30344] [client 192.168.2.33:36602] NO AUTH DATA Client did not send any authentication headers, referer: https://example/
[Thu Mar 15 06:48:23.004232 2018] [core:debug] [pid 30344] util_cookies.c(59): [client 192.168.2.33:36602] AH00007: ap_cookie: user '(null)' set cookie: 'gssapi_session=f4147f04-9680-47cc-b09f-e9dafafb710f;path=/;httponly;secure;', referer: https://example/
[Thu Mar 15 06:48:23.093125 2018] [authz_core:debug] [pid 30344] mod_authz_core.c(809): [client 192.168.2.33:36602] AH01626: authorization result of Require valid-user : denied (no authenticated user yet), referer: https://example/
[Thu Mar 15 06:48:23.093155 2018] [authz_core:debug] [pid 30344] mod_authz_core.c(809): [client 192.168.2.33:36602] AH01626: authorization result of <RequireAny>: denied (no authenticated user yet), referer: https://example/
[Thu Mar 15 06:48:23.093170 2018] [auth_gssapi:debug] [pid 30344] mod_auth_gssapi.c(895): [client 192.168.2.33:36602] URI: /Users/activity, no main, no prev, referer: https://example/
[Thu Mar 15 06:48:23.096035 2018] [:debug] [pid 30344] environ.c(317): [client 192.168.2.33:36602] no name attributes found, referer: https://example/
[Thu Mar 15 06:48:23.096064 2018] [auth_gssapi:debug] [pid 30344] mod_auth_gssapi.c(1245): [client 192.168.2.33:36602] requester: senser@EXAMPLE.NET, referer: https://example/
[Thu Mar 15 06:48:23.096591 2018] [authz_core:debug] [pid 30344] mod_authz_core.c(809): [client 192.168.2.33:36602] AH01626: authorization result of Require valid-user : granted, referer: https://example/
[Thu Mar 15 06:48:23.096619 2018] [authz_core:debug] [pid 30344] mod_authz_core.c(809): [client 192.168.2.33:36602] AH01626: authorization result of <RequireAny>: granted, referer: https://example/
[Thu Mar 15 06:48:23.096757 2018] [auth_gssapi:debug] [pid 30344] mod_auth_gssapi.c(727): [client 192.168.2.33:36602] GSSapiImpersonate not On, skipping impersonation., referer: https://example/
[Thu Mar 15 06:48:23.096832 2018] [auth_gssapi:debug] [pid 30344] mod_auth_gssapi.c(727): [client 192.168.2.33:36602] GSSapiImpersonate not On, skipping impersonation., referer: https://example/
[Thu Mar 15 06:48:23.096875 2018] [auth_gssapi:debug] [pid 30344] mod_auth_gssapi.c(727): [client 192.168.2.33:36602] GSSapiImpersonate not On, skipping impersonation., referer: https://example/
[Thu Mar 15 06:48:23.096975 2018] [authz_core:debug] [pid 30344] mod_authz_core.c(809): [client 192.168.2.33:36602] AH01626: authorization result of Require valid-user : denied (no authenticated user yet), referer: https://example/
[Thu Mar 15 06:48:23.096996 2018] [authz_core:debug] [pid 30344] mod_authz_core.c(809): [client 192.168.2.33:36602] AH01626: authorization result of <RequireAny>: denied (no authenticated user yet), referer: https://example/
[Thu Mar 15 06:48:23.097013 2018] [auth_gssapi:debug] [pid 30344] mod_auth_gssapi.c(895): [client 192.168.2.33:36602] URI: /index.php, no main, with prev, referer: https://example/
[Thu Mar 15 06:48:23.097031 2018] [authz_core:debug] [pid 30344] mod_authz_core.c(809): [client 192.168.2.33:36602] AH01626: authorization result of Require valid-user : granted, referer: https://example/
[Thu Mar 15 06:48:23.097048 2018] [authz_core:debug] [pid 30344] mod_authz_core.c(809): [client 192.168.2.33:36602] AH01626: authorization result of <RequireAny>: granted, referer: https://example/
[Thu Mar 15 06:48:23.097091 2018] [auth_gssapi:debug] [pid 30344] mod_auth_gssapi.c(727): [client 192.168.2.33:36602] GSSapiImpersonate not On, skipping impersonation., referer: https://example/
[Thu Mar 15 06:48:23.360597 2018] [core:debug] [pid 30344] util_cookies.c(59): [client 192.168.2.33:36602] AH00007: ap_cookie: user 'senser' set cookie: 'gssapi_session=6714ab58-b384-40ff-bb26-828b826cf659;path=/;httponly;secure;', referer: https://example/

[simo5]

@niki-eng sounds like we dropped this one, do you still experience this issue, did you find out anything new ?
I am surprised to see that the cookie has been replace by a uuid with DBD sessions, is that expected?