[SSSD] [PATCH] [HBAC]: Better libhbac debuging

Pavel Reichl preichl at redhat.com
Tue Sep 1 09:00:11 UTC 2015


>> In https://fedorahosted.org/sssd/wiki/FAQ SSSDBG_FATAL_FAILURE is
>> described as:
>>
>>             0x0010: Fatal failures. Anything that would prevent SSSD 
>> from
>>             starting up or causes it to cease running.
>>
>> Are you sure that such errors can happen in HBAC?
> HBAC_DBG_FATAL isn't used in HBAC code. It is there for completeness 
> of HBAC debug system.
OK
>
>>> + debug_fn(__FILE__, __LINE__, "hbac", loglevel, "[%s:%i] %s\n",
>> I noticed that you add '\n' here. DEBUG macro doesn't explicitly add
>> '\n'. I don't say it's bad, it's just different. I would like if some
>> other developer agreed to this.
> I listened to the opinion of another engineer and I reworked it.
Thanks.
>>
>>
>> Petr I noticed that you use spaces in debug messages to make logs
>> readable which I like, I'm just thing whether '\t' would be better than
>> just for spaces "    ", or you could #define INDENT "    "
>>
>> What do you think?
> I rewrote it to '\t'.
>
>
IMO it's better, thanks!

Please see comments inline.


>
> 0002-HBAC-Better-libhbac-debugging.patch
>
>
>  From 6b1c6cac7123e78a2c55c51019b66a6bcf97ec29 Mon Sep 17 00:00:00 2001
> From: Petr Cech<pcech at redhat.com>
> Date: Fri, 24 Jul 2015 10:56:49 -0400
> Subject: [PATCH 2/2] HBAC: Better libhbac debugging
>
> Added support for logging via external log function.
> Log provides information about rules evaluating (HBAC_DBG_INFO level)
> and additionally can describe rules (HBAC_DBG_TRACE level).
>
> Resolves:
> https://fedorahosted.org/sssd/ticket/2703
> ---
>   src/providers/ipa/hbac_evaluator.c | 152 +++++++++++++++++++++++++++++++++++++
>   src/providers/ipa/ipa_access.c     |  49 ++++++++++++
>   src/providers/ipa/ipa_hbac.exports |   3 +-
>   src/providers/ipa/ipa_hbac.h       |  22 ++++++
>   4 files changed, 225 insertions(+), 1 deletion(-)
>
> diff --git a/src/providers/ipa/hbac_evaluator.c b/src/providers/ipa/hbac_evaluator.c
> index f40f9e0a7f16f5e012079c637b89c8e49ec5d15b..6f236058a4a9711cf9bfba1db1447789bbb2d4b5 100644
> --- a/src/providers/ipa/hbac_evaluator.c
> +++ b/src/providers/ipa/hbac_evaluator.c
> @@ -38,6 +38,39 @@ typedef int errno_t;
>   #define EOK 0
>   #endif
>   
> +/* HBAC logging system */
> +
> +/* debug macro */
> +#define HBAC_DEBUG(level, format, ...) do { \
> +    if (hbac_debug_fn != NULL) { \
> +        hbac_debug_fn(__FILE__, __LINE__, level, format, ##__VA_ARGS__); \
> +    } \
> +} while (0)
> +
> +/* static pointer to external logging function */
> +static hbac_debug_fn_t hbac_debug_fn = NULL;
> +
> +/* setup function for external logging function */
> +void hbac_enable_debug(hbac_debug_fn_t external_debug_fn)
> +{
> +    hbac_debug_fn = external_debug_fn;
> +}
> +
> +/* auxiliary function for hbac_request_element logging */
> +static void hbac_request_element_debug_print(struct hbac_request_element *el,
> +                                             const char *label);
> +
> +/* auxiliary function for hbac_eval_req logging */
> +static void hbac_req_debug_print(struct hbac_eval_req *req);
> +
> +/* auxiliary function for hbac_rule_element logging */
> +static void hbac_rule_element_debug_print(struct hbac_rule_element *el,
> +                                          const char *label);
> +
> +/* auxiliary function for hbac_rule logging */
> +static void hbac_rule_debug_print(struct hbac_rule *rule);
> +
> +
>   /* Placeholder structure for future HBAC time-based
>    * evaluation rules
>    */
> @@ -114,9 +147,13 @@ enum hbac_eval_result hbac_evaluate(struct hbac_rule **rules,
>       enum hbac_eval_result result = HBAC_EVAL_DENY;
>       enum hbac_eval_result_int intermediate_result;
>   
> +    HBAC_DEBUG(HBAC_DBG_INFO, "[< hbac_evaluate()\n");
> +    hbac_req_debug_print(hbac_req);
> +
>       if (info) {
>           *info = malloc(sizeof(struct hbac_info));
>           if (!*info) {
> +            HBAC_DEBUG(HBAC_DBG_ERROR, "Out of memory.\n");
>               return HBAC_EVAL_OOM;
>           }
>           (*info)->code = HBAC_ERROR_UNKNOWN;
> @@ -125,20 +162,25 @@ enum hbac_eval_result hbac_evaluate(struct hbac_rule **rules,
>       uint32_t i;
I know that you haven't changed this code, but could you move the 
definition of i into for cycle or to he beginning of the block?
>   
>       for (i = 0; rules[i]; i++) {
> +        hbac_rule_debug_print(rules[i]);
>           intermediate_result = hbac_evaluate_rule(rules[i], hbac_req, &ret);
>           if (intermediate_result == HBAC_EVAL_UNMATCHED) {
>               /* This rule did not match at all. Skip it */
> +            HBAC_DEBUG(HBAC_DBG_INFO, "DISALLOWED by rule [%s].\n",
> +                       rules[i]->name);
I think this log message is wrong. Rule did not match - it was not 
relevant for this user, host or service.  There are no deny rules. "The 
rule [%s] did not match" is fine by me, do you agree?
>               continue;
>           } else if (intermediate_result == HBAC_EVAL_MATCHED) {
>               /* This request matched an ALLOW rule
>                * Set the result to ALLOW but continue checking
>                * the other rules in case a DENY rule trumps it.
>                */
> +            HBAC_DEBUG(HBAC_DBG_INFO, "ALLOWED by rule [%s].\n", rules[i]->name);
>               result = HBAC_EVAL_ALLOW;
>               if (info) {
>                   (*info)->code = HBAC_SUCCESS;
>                   (*info)->rule_name = strdup(rules[i]->name);
>                   if (!(*info)->rule_name) {
> +                    HBAC_DEBUG(HBAC_DBG_ERROR, "Out of memory.\n");
>                       result = HBAC_EVAL_ERROR;
>                       (*info)->code = HBAC_ERROR_OUT_OF_MEMORY;
>                   }
> @@ -146,6 +188,9 @@ enum hbac_eval_result hbac_evaluate(struct hbac_rule **rules,
>               break;
>           } else {
>               /* An error occurred processing this rule */
> +            HBAC_DEBUG(HBAC_DBG_ERROR,
> +                       "Error occurred during evaluating of rule [%s].\n",
> +                       rules[i]->name);
>               result = HBAC_EVAL_ERROR;
>               if (info) {
>                   (*info)->code = ret;
> @@ -163,6 +208,7 @@ enum hbac_eval_result hbac_evaluate(struct hbac_rule **rules,
>        */
>   done:
>   
> +    HBAC_DEBUG(HBAC_DBG_INFO, "hbac_evaluate() >]\n");
>       return result;
>   }
>   
> @@ -333,3 +379,109 @@ const char *hbac_error_string(enum hbac_error_code code)
>           return "Unknown error code";
>       }
>   }
> +
> +static void hbac_request_element_debug_print(struct hbac_request_element *el,
> +                                             const char *label)
> +{
> +    if (el) {
> +        if (el->name) {
> +            HBAC_DEBUG(HBAC_DBG_TRACE, "\t\t%s [%s]\n", label, el->name);
> +        }
add empty line
> +        if (el->groups) {
> +            if (el->groups[0]) {
> +                HBAC_DEBUG(HBAC_DBG_TRACE, "\t\t%s_group:\n", label);
> +                for (int i = 0; el->groups[i]; i++) {
> +                    HBAC_DEBUG(HBAC_DBG_TRACE, "\t\t\t[%s]\n", el->groups[i]);
> +                }
> +            } else {
> +                HBAC_DEBUG(HBAC_DBG_TRACE, "\t\t%s_group (none)\n", label);
> +            }
> +        }
> +    } else {
> +        HBAC_DEBUG(HBAC_DBG_TRACE, "\t%s (none)\n", label);
> +    }
> +}
> +
> +static void hbac_req_debug_print(struct hbac_eval_req *req)
> +{
> +    HBAC_DEBUG(HBAC_DBG_TRACE, "\tREQUEST:\n");
> +    if (req) {
> +        char time_buff[100];
IMO use const size_t size; or something like that here
> +
> +        hbac_request_element_debug_print(req->service, "service");
> +        hbac_request_element_debug_print(req->user, "user");
> +        hbac_request_element_debug_print(req->targethost, "targethost");
> +        hbac_request_element_debug_print(req->srchost, "srchost");
> +        strftime(time_buff, sizeof time_buff, "%Y-%m-%d %H:%M:%S",
IMO use 'size' here. Please check return value of both strftime() and 
localtime()
> +                 localtime(&req->request_time));
> +        HBAC_DEBUG(HBAC_DBG_TRACE, "\t\trequest time %s\n", time_buff);
> +    } else {
> +        HBAC_DEBUG(HBAC_DBG_TRACE, "\tRequest is EMPTY.\n");
> +    }
> +}
> +
> +static void hbac_rule_element_debug_print(struct hbac_rule_element *el,
> +                                          const char *label)
> +{
> +    if (el) {
> +        HBAC_DEBUG(HBAC_DBG_TRACE, "\t\tcategory [%#x] [%s]\n", el->category,
> +                   (el->category == HBAC_CATEGORY_ALL) ? "ALL" : "NONE");
> +
> +        if (el->names) {
> +            if (el->names[0]) {
> +                HBAC_DEBUG(HBAC_DBG_TRACE, "\t\t%s_names:\n", label);
> +                for (int i = 0; el->names[i]; i++) {
> +                    HBAC_DEBUG(HBAC_DBG_TRACE, "\t\t\t[%s]\n", el->names[i]);
> +                }
> +            } else {
> +                HBAC_DEBUG(HBAC_DBG_TRACE, "\t\t%s_names (none)\n", label);
> +            }
> +        }
> +
> +        if (el->groups) {
> +            if (el->groups[0]) {
> +                HBAC_DEBUG(HBAC_DBG_TRACE, "\t\t%s_groups:\n", label);
> +                for (int i = 0; el->groups[i]; i++) {
> +                    HBAC_DEBUG(HBAC_DBG_TRACE, "\t\t\t[%s]\n", el->groups[i]);
> +                }
> +            } else {
> +                HBAC_DEBUG(HBAC_DBG_TRACE, "\t\t%s_groups (none)\n", label);
> +            }
> +        }
> +    }
> +}
> +
> +static void hbac_rule_debug_print(struct hbac_rule *rule)
> +{
> +    if (rule) {
> +        HBAC_DEBUG(HBAC_DBG_TRACE, "\tRULE [%s] [%s]:\n",
> +                   rule->name, (rule->enabled) ? "ENABLED" : "DISABLED");
> +        if (rule->services) {
> +            HBAC_DEBUG(HBAC_DBG_TRACE, "\tservices:\n");
> +            hbac_rule_element_debug_print(rule->services, "services");
> +        } else {
> +            HBAC_DEBUG(HBAC_DBG_TRACE, "\tservices (none)\n");
> +        }
> +
> +        if (rule->users) {
> +            HBAC_DEBUG(HBAC_DBG_TRACE, "\tusers:\n");
> +            hbac_rule_element_debug_print(rule->users, "users");
> +        } else {
> +            HBAC_DEBUG(HBAC_DBG_TRACE, "\tusers (none)\n");
> +        }
> +
> +        if (rule->targethosts) {
> +            HBAC_DEBUG(HBAC_DBG_TRACE, "\ttargethosts:\n");
> +            hbac_rule_element_debug_print(rule->targethosts, "targethosts");
> +        } else {
> +            HBAC_DEBUG(HBAC_DBG_TRACE, "\ttargethosts (none)\n");
> +        }
> +
> +        if (rule->srchosts) {
> +            HBAC_DEBUG(HBAC_DBG_TRACE, "\tsrchosts:\n");
> +            hbac_rule_element_debug_print(rule->srchosts, "srchosts");
> +        } else {
> +            HBAC_DEBUG(HBAC_DBG_TRACE, "\tsrchosts (none)\n");
> +        }
> +    }
> +}
> diff --git a/src/providers/ipa/ipa_access.c b/src/providers/ipa/ipa_access.c
> index 3198e2bd2a4c8355eeccc129c85ae3d7d67f61b0..77b5ffcb8e4f7ac15ab9aa1cbc503594a7ee760b 100644
> --- a/src/providers/ipa/ipa_access.c
> +++ b/src/providers/ipa/ipa_access.c
> @@ -35,6 +35,53 @@
>   #include "providers/ipa/ipa_hbac_private.h"
>   #include "providers/ipa/ipa_hbac_rules.h"
>   
> +/* External logging function for HBAC. */
> +void hbac_debug_messages(const char *file, int line,
> +                         enum hbac_debug_level level,
> +                         const char *fmt, ...)
> +{
> +    int loglevel = SSSDBG_UNRESOLVED;
Would you move this assignment to the default clause in the switch 
statement?
> +
> +    switch(level) {
> +    case HBAC_DBG_FATAL:
> +        loglevel = SSSDBG_FATAL_FAILURE;
> +        break;
> +    case HBAC_DBG_ERROR:
> +        loglevel = SSSDBG_OP_FAILURE;
> +        break;
> +    case HBAC_DBG_WARNING:
> +        loglevel = SSSDBG_MINOR_FAILURE;
> +        break;
> +    case HBAC_DBG_INFO:
> +        loglevel = SSSDBG_CONF_SETTINGS;
> +        break;
> +    case HBAC_DBG_TRACE:
> +        loglevel = SSSDBG_TRACE_INTERNAL;
> +        break;
> +    default:
> +        break;
> +    }
> +
> +    if (DEBUG_IS_SET(loglevel)) {
> +        va_list ap;
> +        char *message = NULL;
> +        int ret;
> +
> +        va_start(ap, fmt);
> +        ret = vasprintf(&message, fmt, ap);
> +        va_end(ap);
> +        if (ret < 0) {
> +            /* ENOMEM */
> +            free(message);
> +            return;
> +        }
> +
> +        debug_fn(__FILE__, __LINE__, "hbac", loglevel, "[%s:%i] %s",
> +                 file, line, message);
> +        free(message);
> +    }
> +}
> +
>   static void ipa_access_reply(struct hbac_ctx *hbac_ctx, int pam_status)
>   {
>       struct be_req *be_req = hbac_ctx->be_req;
> @@ -635,6 +682,8 @@ void ipa_hbac_evaluate_rules(struct hbac_ctx *hbac_ctx)
>           return;
>       }
>   
> +    hbac_enable_debug(hbac_debug_messages);
> +
>       result = hbac_evaluate(hbac_rules, eval_req, &info);
>       if (result == HBAC_EVAL_ALLOW) {
>           DEBUG(SSSDBG_MINOR_FAILURE, "Access granted by HBAC rule [%s]\n",
> diff --git a/src/providers/ipa/ipa_hbac.exports b/src/providers/ipa/ipa_hbac.exports
> index 0115084e2b3a66569f97c4e7c035dffdb6450b43..63b6a5cd673d7b7f3096794648483d280a6bb47f 100644
> --- a/src/providers/ipa/ipa_hbac.exports
> +++ b/src/providers/ipa/ipa_hbac.exports
> @@ -1,4 +1,4 @@
> -IPA_HBAC_0.0.1 {
> +IPA_HBAC_0.0.2 {
>   
>       # public functions
>       global:
> @@ -8,6 +8,7 @@ IPA_HBAC_0.0.1 {
>           hbac_error_string;
>           hbac_free_info;
>           hbac_rule_is_complete;
> +        hbac_enable_debug;
>   
>       # everything else is local
>       local:
> diff --git a/src/providers/ipa/ipa_hbac.h b/src/providers/ipa/ipa_hbac.h
> index f43611351c8a5dfb20ca3d075f0bcd7bb71798c9..57947e7bb8509a8280e43259bbaf1b75599e0484 100644
> --- a/src/providers/ipa/ipa_hbac.h
> +++ b/src/providers/ipa/ipa_hbac.h
> @@ -41,6 +41,28 @@
>   #include <stdbool.h>
>   #include <time.h>
>   
> +/** Debug levels for HBAC. */
> +enum hbac_debug_level {
> +    HBAC_DBG_FATAL,     /** Fatal failure (not used). */
> +    HBAC_DBG_ERROR,     /** Serious failure (out of memory, for example). */
> +    HBAC_DBG_WARNING,   /** Warnings (not used). */
> +    HBAC_DBG_INFO,      /** HBAC allow/disallow info. */
> +    HBAC_DBG_TRACE      /** Vesrbose description of rules. */
typo s/Vesrbose/Verbose/
Generally - why 2 asterisks at the beginning of the comment?  But as I 
see we use it at hundreds of other places, so no need to change it.
> +};
> +
> +/**
> + * Function pointer to HBAC external debugging function.
> + */
> +typedef void (*hbac_debug_fn_t)(const char *file, int line,
> +                                enum hbac_debug_level, const char *format,
> +                                ...);
> +
> +/**
> + *  HBAC uses external_debug_fn for logging messages.
> + *  @param[in|out] external_debug_void Pointer to external logging function.
> + */
> +void hbac_enable_debug(hbac_debug_fn_t external_debug_fn);
> +
>   /** Result of HBAC evaluation */
>   enum hbac_eval_result {
>       /** An error occurred
> -- 2.4.3

-------------- next part --------------
An HTML attachment was scrubbed...
URL: <https://lists.fedorahosted.org/pipermail/sssd-devel/attachments/20150901/a70a6246/attachment-0001.html>


More information about the sssd-devel mailing list