Improving logs to make AUTH_DENIES easy to understand and fix

[Tianyin Xu <ti...@cs.ucsd.edu>]

Hi all,

I've been using httpd's authentication & authorization modules for several
weeks. Compared to many other modules I used in the past, the debugging of
"auth deny" issues (caused by these modules) is really a pain in the ass.
The key problem is that httpd often does not tell *why* certain requests
are denied, but only give a very general message like,
    "[auth_basic:error] AH01617: user tixu: authentication failure for "/":
"
    "[authz_core:error] AH01631: user tixu: authorization failure for "/":"

In many cases, these two log messages are the only ones available for
debugging. But they really do not pinpoint the reason beneath the
authn/authz failures. Yes, these two logs are printed in `mod_auth_basic`
and `mod_authz_core` where the authn/authz results from different providers
are aggregated.

Even worse, things got much more complicated and hard to debug when
multiple authn/authz providers are applied (e.g., file + ldap + ssl). In
fact, these're not uncommon,
https://httpd.apache.org/docs/2.4/howto/auth.html#multprovider
Note that, with AH01617 and AH01631, we can't even know which module
actually denied the request!

Certainly, there are awesome auth modules like `mod_authz_owner` and
`mod_authz_dbm` which have excellent logging ---before each AUTH_DENIED, it
has error logs to pinpoint the precise reason (checkout
`fileowner_check_authorization(..)` in `mod_authz_owner.c` and
`dbmgroup_check_authorization(..)` in `mod_authz_dbm.c`).
https://github.com/apache/httpd/blob/trunk/modules/aaa/mod_authz_owner.c
https://github.com/apache/httpd/blob/trunk/modules/aaa/mod_authz_dbm.c

With such precise log msgs, we sysadmins can understand the problems and
take actions immediately.

Unfortunately, in many other cases, the authn/z modules keep silent and
thus ending with AH01617 and AH01631. The following shows two of the
examples,

static authz_status ssl_authz_require_ssl_check(...) { /*
ssl_engine_kernel.c */
    ...
    if (ssl)
        return AUTHZ_GRANTED;
    else
        return AUTHZ_DENIED;
}

and

static authz_status dbdgroup_check_authorization(...) { /* mod_authz_dbd.c
*/
    while (...) {
        ...
        return AUTHZ_GRANTED;
    }
    return AUTHZ_DENIED;
}

Such cases are not rare, but prevalent across several authn/authz modules.

I propose to apply the same good practices (such as mod_authz_owner &
mod_authz_dbm) to all the authn/authz modules. Basically, I want to add log
messages before each AUTHN/Z_DENIES to pinpoint:

1) which module denied the request
2) the reason the request gets denied

In this way, sysadmins can immediately understand the causes and take
actions (if necessary).

Any advice or feedback on this proposal is highly welcomed (that's the
whole purpose of this email)!

Specially, I want to understand whether this is something worth doing
(besides scratching my own itch)? Is there any concerns, or did I miss any
important things? Let me know!

Thanks a lot!
Tianyin

Re: Improving logs to make AUTH_DENIES easy to understand and fix

[Stefan Fritsch <sf...@sfritsch.de>]

Hi,

sorry for the late response.

On Wednesday, 18 May 2016 02:12:39 CEST Tianyin Xu wrote:
> I propose to apply the same good practices (such as mod_authz_owner &
> mod_authz_dbm) to all the authn/authz modules. Basically, I want to add log
> messages before each AUTHN/Z_DENIES to pinpoint:
> 
> 1) which module denied the request
> 2) the reason the request gets denied
> 
> In this way, sysadmins can immediately understand the causes and take
> actions (if necessary).

The problem is, that when using RequireNone, RequireAny, RequireAll, or 
"Require not", the module does not know which result will lead to the request 
being denied. So, logging in each module at high loglevel would cause a lot of 
"denied" messages even for requests that are allowed in the end. With negation 
an AUTHZ_GRANTED could also lead to the request being denied, and that would 
then lack a log message.

The preferred way to debug this is to set "Loglevel authz_core debug", 
possibly only for the one URL that is interesting. This should give ample 
logging for debugging. This should probably be documented better. Someone 
wants to write a debugging section in http://httpd.apache.org/docs/trunk/
howto/auth.html ?

If more logging is needed, the authn/authz module should need to put the info 
somewhere and mod_authz_core should only log it if it actually causes the 
request to be denied. But this obviously would need more infrastructure that 
is not present now.

Cheers,
Stefan