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

Petr Cech pcech at redhat.com
Wed Aug 26 07:44:16 UTC 2015



On 08/24/2015 03:45 PM, Pavel Reichl wrote:
> On 07/24/2015 06:20 PM, Petr Cech wrote:
>>  From 2fcf13ef59f00b460afa77b27ef6cc2789b06393 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] [HBAC]: Better libhbac debuging
> s/debuging/debugging
Fixed.
>> 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 | 146 +++++++++++++++++++++++++++++++++++++
>>   src/providers/ipa/ipa_access.c     |  45 ++++++++++++
>>   src/providers/ipa/ipa_hbac.exports |   3 +-
>>   src/providers/ipa/ipa_hbac.h       |  23 ++++++
>>   4 files changed, 216 insertions(+), 1 deletion(-)
>>
>> diff --git a/src/providers/ipa/hbac_evaluator.c b/src/providers/ipa/hbac_evaluator.c
>> index f40f9e0a7f16f5e012079c637b89c8e49ec5d15b..66d3512937702b5955f333c0c837807ee9e13deb 100644
>> --- a/src/providers/ipa/hbac_evaluator.c
>> +++ b/src/providers/ipa/hbac_evaluator.c
>> @@ -24,6 +24,8 @@
>>   */
>>   
>>   #include <stdlib.h>
>> +#include <stdio.h>
>> +#include <stdarg.h>
>>   #include <string.h>
>>   #include <errno.h>
>>   #include "providers/ipa/ipa_hbac.h"
>> @@ -38,6 +40,41 @@ typedef int errno_t;
>>   #define EOK 0
>>   #endif
>>   
>> +/* HBAC logging system */
>> +
>> +/* static pointer to external logging function */
>> +static void (*hbac_debug_fn)(const char *file, int line, enum hbac_debug_level,
>> +                             const char *format, ...) = NULL;
> Do you think that introducing a new type using typedef for this type 
> of callback would be more readable?
Yes, I do.
Fixed.
>> +
>> +/* setup function for external logging function */
>> +void hbac_enable_debug(void (*external_debug_fn)(const char *file, int line,
>> +                       enum hbac_debug_level, const char *format, ...))
>> +{
>> +    hbac_debug_fn = external_debug_fn;
>> +}
>> +
>> +/* debug macro */
>> +#define HBAC_DEBUG(level, format, ...) do { \
>> +    if (hbac_debug_fn != NULL) { \
>> +        hbac_debug_fn(__FILE__, __LINE__, level, format, ##__VA_ARGS__); \
>> +    } \
>> +} while (0)
> IMO macro should be defined after includes and before function 
> definitions, but I haven't check if we are 100 % consistent about this 
> in SSSD.
Fixed.
>> +
>> +/* auxiliary function for hbac_request_element logging */
>> +static void hbac_request_element_debug_print(struct hbac_request_element *el,
>> +        const char *label);
> bad indentation
Fixed.
>> +
>> +/* 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
>>    */
>> @@ -110,6 +147,9 @@ enum hbac_eval_result hbac_evaluate(struct hbac_rule **rules,
>>                                       struct hbac_eval_req *hbac_req,
>>                                       struct hbac_info **info)
>>   {
>> +    HBAC_DEBUG(HBAC_DBG_INFO, "[< hbac_evaluate()");
>> +    hbac_req_debug_print(hbac_req);
>> +
> We generally do not add any code before variable definitions, I 
> understand that logging is kinda special, but I would prefer to add it 
> after the definitions, do you agree?
Fixed.
>>       enum hbac_error_code ret;
>>       enum hbac_eval_result result = HBAC_EVAL_DENY;
>>       enum hbac_eval_result_int intermediate_result;
>> @@ -117,6 +157,7 @@ enum hbac_eval_result hbac_evaluate(struct hbac_rule **rules,
>>       if (info) {
>>           *info = malloc(sizeof(struct hbac_info));
>>           if (!*info) {
>> +            HBAC_DEBUG(HBAC_DBG_ERROR, "Out of memory.");
>>               return HBAC_EVAL_OOM;
>>           }
>>           (*info)->code = HBAC_ERROR_UNKNOWN;
>> @@ -125,20 +166,25 @@ enum hbac_eval_result hbac_evaluate(struct hbac_rule **rules,
>>       uint32_t i;
>>   
>>       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].",
>> +                       rules[i]->name);
>>               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].", 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.");
>>                       result = HBAC_EVAL_ERROR;
>>                       (*info)->code = HBAC_ERROR_OUT_OF_MEMORY;
>>                   }
>> @@ -146,6 +192,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 occured during evaluating of rule [%s].",
> s/occured/occurred/
Fixed.
>> +                       rules[i]->name);
>>               result = HBAC_EVAL_ERROR;
>>               if (info) {
>>                   (*info)->code = ret;
>> @@ -163,6 +212,7 @@ enum hbac_eval_result hbac_evaluate(struct hbac_rule **rules,
>>        */
>>   done:
>>   
>> +    HBAC_DEBUG(HBAC_DBG_INFO, "hbac_evaluate() >] ");
> trialing ' ' in string?
Fixed.
>>       return result;
>>   }
>>   
>> @@ -333,3 +383,99 @@ 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)
> indentation
Fixed.
>> +{
>> +    if (el) {
>> +        if (el->name) {
>> +            HBAC_DEBUG(HBAC_DBG_TRACE, "    %s [%s]", label, el->name);
>> +        }
>> +        if (el->groups) {
>> +            if (el->groups[0]) {
>> +                HBAC_DEBUG(HBAC_DBG_TRACE, "    %s_group:", label);
>> +                for (int i = 0; el->groups[i]; i++) {
>> +                    HBAC_DEBUG(HBAC_DBG_TRACE, "      [%s]", el->groups[i]);
>> +                }
>> +            } else {
>> +                HBAC_DEBUG(HBAC_DBG_TRACE, "    %s_group (none)", label);
>> +            }
>> +        }
>> +    } else {
>> +        HBAC_DEBUG(HBAC_DBG_TRACE, "    %s (none)", label);
>> +    }
>> +}
>> +
>> +static void hbac_req_debug_print(struct hbac_eval_req *req)
>> +{
>> +    HBAC_DEBUG(HBAC_DBG_TRACE, "  REQUEST:");
>> +    if (req) {
>> +        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");
>> +        HBAC_DEBUG(HBAC_DBG_TRACE, "    request time %s",
>> +                   asctime(gmtime(&req->request_time)));
>> +    } else {
>> +        HBAC_DEBUG(HBAC_DBG_TRACE, "  Request is EMPTY.");
>> +    }
>> +}
>> +
>> +static void hbac_rule_element_debug_print(struct hbac_rule_element *el,
>> +                                          const char *label)
>> +{
>> +    HBAC_DEBUG(HBAC_DBG_TRACE, "      category [%#x] [%s]", el->category,
>> +               (el->category == HBAC_CATEGORY_ALL) ? "ALL" : "NONE");
>> +    if (el->names) {
>> +        if (el->names[0]) {
>> +            HBAC_DEBUG(HBAC_DBG_TRACE, "      %s_names:", label);
>> +            for (int i = 0; el->names[i]; i++) {
>> +                HBAC_DEBUG(HBAC_DBG_TRACE, "        [%s]", el->names[i]);
>> +            }
>> +        } else {
>> +            HBAC_DEBUG(HBAC_DBG_TRACE, "      %s_names (none)", label);
>> +        }
>> +    }
>> +    if (el->groups) {
>> +        if (el->groups[0]) {
>> +            HBAC_DEBUG(HBAC_DBG_TRACE, "      %s_groups:", label);
>> +            for (int i = 0; el->groups[i]; i++) {
>> +                HBAC_DEBUG(HBAC_DBG_TRACE, "        [%s]", el->groups[i]);
>> +            }
>> +        } else {
>> +            HBAC_DEBUG(HBAC_DBG_TRACE, "      %s_groups (none)", label);
>> +        }
>> +    }
>> +}
>> +
>> +static void hbac_rule_debug_print(struct hbac_rule *rule)
>> +{
>> +    if (rule) {
>> +        HBAC_DEBUG(HBAC_DBG_TRACE, "  RULE [%s] [%s]:",
>> +                   rule->name, (rule->enabled) ? "ENABLED" : "DISABLED");
>> +        if (rule->services) {
>> +            HBAC_DEBUG(HBAC_DBG_TRACE, "    services:");
>> +            hbac_rule_element_debug_print(rule->services, "services");
>> +        } else {
>> +            HBAC_DEBUG(HBAC_DBG_TRACE, "    services (none)");
>> +        }
> could you add empty line here?
Fixed.
>> +        if (rule->users) {
>> +            HBAC_DEBUG(HBAC_DBG_TRACE, "    users:");
>> +            hbac_rule_element_debug_print(rule->users, "users");
>> +        } else {
>> +            HBAC_DEBUG(HBAC_DBG_TRACE, "    users (none)");
>> +        }
> same here
Fixed.
>> +        if (rule->targethosts) {
>> +            HBAC_DEBUG(HBAC_DBG_TRACE, "    targethosts:");
>> +            hbac_rule_element_debug_print(rule->targethosts, "targethosts");
>> +        } else {
>> +            HBAC_DEBUG(HBAC_DBG_TRACE, "    targethosts (none)");
>> +        }
> same here
Fixed.
>> +        if (rule->srchosts) {
>> +            HBAC_DEBUG(HBAC_DBG_TRACE, "    srchosts:");
>> +            hbac_rule_element_debug_print(rule->srchosts, "srchosts");
>> +        } else {
>> +            HBAC_DEBUG(HBAC_DBG_TRACE, "    srchosts (none)");
>> +        }
>> +    }
>> +}
>> diff --git a/src/providers/ipa/ipa_access.c b/src/providers/ipa/ipa_access.c
>> index 3198e2bd2a4c8355eeccc129c85ae3d7d67f61b0..55c79744a430969a84bafc4ae1ff46780b9701dc 100644
>> --- a/src/providers/ipa/ipa_access.c
>> +++ b/src/providers/ipa/ipa_access.c
>> @@ -35,6 +35,49 @@
>>   #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;
>> +    int ret;
>> +    char * message = NULL;
> space after *
Fixed.
>> +
>> +    switch(level) {
>> +    case HBAC_DBG_FATAL:
>> +        loglevel = SSSDBG_FATAL_FAILURE;
>> +        break;
>> +    case HBAC_DBG_ERROR:
>> +        loglevel = SSSDBG_CRIT_FAILURE;
>> +        break;
>> +    case HBAC_DBG_WARNING:
>> +        loglevel = SSSDBG_OP_FAILURE;
>> +        break;
>> +    case HBAC_DBG_INFO:
>> +        loglevel = SSSDBG_MINOR_FAILURE;
>> +        break;
>> +    case HBAC_DBG_TRACE:
>> +        loglevel = SSSDBG_TRACE_ALL;
>> +        break;
>> +    }
>> +
>> +    va_list ap;
>> +    va_start(ap, fmt);
>> +    ret = vasprintf(&message, fmt, ap);
>> +    va_end(ap);
>> +    if (ret < 0) {
>> +        /* ENOMEM */
>> +        return;
>> +    }
>> +
>> +    if (DEBUG_IS_SET(loglevel)) {
>> +        debug_fn(__FILE__, __LINE__, "hbac", loglevel, "[%s:%i] %s\n",
>> +                 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 +678,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..f82f8dbb55c72bc1b011a87759c1bdb932cc2672 100644
>> --- a/src/providers/ipa/ipa_hbac.h
>> +++ b/src/providers/ipa/ipa_hbac.h
>> @@ -37,10 +37,33 @@
>>    * @{
>>    */
>>   
>> +#include <stdio.h>
>> +#include <stdarg.h>
> are you sure that both headers have to be included here?
Fixed.
>>   #include <stdint.h>
>>   #include <stdbool.h>
>>   #include <time.h>
>>   
>> +/** Debug levels for HBAC. */
>> +enum hbac_debug_level {
>> +    HBAC_DBG_FATAL,
>> +    HBAC_DBG_ERROR,
>> +    HBAC_DBG_WARNING,
>> +    HBAC_DBG_INFO,
>> +    HBAC_DBG_TRACE
>> +};
>> +
>> +/**
>> + *  HBAC uses external_debug_fn for logging messages.
>> + *  @param[in|out] external_debug_void Pointer to external logging function.
>> + *  Note: Internal HBAC logging function provides:
>> + *        __FILE__ as file
>> + *        __LINE__ as line
>> + *        hbac_debug_level as level
>> + *        format and ellipsis
>> + */
>> +void hbac_enable_debug(void (*external_debug_fn)(const char*  file, int line,
>> +                       enum hbac_debug_level level, const char* format, ...));
>> +
>>   /** Result of HBAC evaluation */
>>   enum hbac_eval_result {
>>       /** An error occurred
>> -- 2.4.3
> Petr I just quickly scrolled through the code and added some comments. 
> I haven't tested the code yet, but  ci fails.
>
> ===================================
>    sssd 1.13.1: ./test-suite.log
> ===================================
>
> # TOTAL: 72
> # PASS:  71
> # SKIP:  0
> # XFAIL: 0
> # FAIL:  0
> # XPASS: 0
> # ERROR: 1
>
> .. contents:: :depth: 2
>
> ERROR: ipa_hbac-tests
> =====================
>
> Running suite(s): HBAC
> 100%: Checks: 9, Failures: 0, Errors: 0
> ERROR ipa_hbac-tests (exit status: 99)
>
Yes, tests was broken. There was uninitialized pointer. Patch [1] fixes it.
The second patch [2] is new debugging for libhbac.

Petr

[1] 0001-TESTS-Fixing-of-uninitialized-pointer.patch
[2] 0002-HBAC-Better-libhbac-debugging.patch
>
>
> _______________________________________________
> sssd-devel mailing list
> sssd-devel at lists.fedorahosted.org
> https://lists.fedorahosted.org/mailman/listinfo/sssd-devel

-------------- next part --------------
An HTML attachment was scrubbed...
URL: <https://lists.fedorahosted.org/pipermail/sssd-devel/attachments/20150826/052c9536/attachment-0001.html>
-------------- next part --------------
A non-text attachment was scrubbed...
Name: 0001-TESTS-Fixing-of-uninitialized-pointer.patch
Type: text/x-patch
Size: 1085 bytes
Desc: not available
URL: <https://lists.fedorahosted.org/pipermail/sssd-devel/attachments/20150826/052c9536/attachment-0002.bin>
-------------- next part --------------
A non-text attachment was scrubbed...
Name: 0002-HBAC-Better-libhbac-debugging.patch
Type: text/x-patch
Size: 12022 bytes
Desc: not available
URL: <https://lists.fedorahosted.org/pipermail/sssd-devel/attachments/20150826/052c9536/attachment-0003.bin>


More information about the sssd-devel mailing list