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

[Pavel Reichl]

> SSSDBG_TRACE_ALL produces:
>
> ...hbac_evaluator.c:150] [< hbac_evaluate()
> ...hbac_evaluator.c:410]   REQUEST:
> ...hbac_evaluator.c:391]     service [sshd]
> ...hbac_evaluator.c:400]     service_group (none)
> ...hbac_evaluator.c:391]     user [csikos]
> ...hbac_evaluator.c:395]     user_group:

I think it could be useful to move user and might be user_group to less 
verbose level - I think it could be hard to navigate in less verbose 
logs otherwise, do you agree?
> ...hbac_evaluator.c:397]       [ipausers]
> ...hbac_evaluator.c:391]     targethost [albireo.cygnus.dev]
> ...hbac_evaluator.c:400]     targethost_group (none)
> ...hbac_evaluator.c:391]     srchost [192.168.122.106]
> ...hbac_evaluator.c:400]     srchost_group (none)
> ...hbac_evaluator.c:417]     request time Fri Jul 24 14:29:36 2015
> ...hbac_evaluator.c:454]   RULE [szabo_allowed] [ENABLED]:
> ...hbac_evaluator.c:456]     services:
> ...hbac_evaluator.c:427]       category [0] [NONE]
> ...hbac_evaluator.c:435]       services_names (none)
> ...hbac_evaluator.c:440]       services_groups:
> ...hbac_evaluator.c:442]         [Sudo]
> ...hbac_evaluator.c:462]     users:

On 08/26/2015 09:44 AM, Petr Cech wrote:
> 0001-TESTS-Fixing-of-uninitialized-pointer.patch
>
> From e83b609924ed2f6ff35b70355f3c330ec2586a15 Mon Sep 17 00:00:00 2001
> From: Petr Cech
> Date: Wed, 26 Aug 2015 02:50:26 -0400
> Subject: [PATCH 1/2] TESTS: Fixing of uninitialized pointer.
>
> There was a bug with uninitialized pointer during solving ticket 2703.
>
> More details:
> rules[0]->services->names[1] is initialized on line 361, but
> initializing of rules[0]->srchosts->names[1] was missing.
>
> Resolves:
> https://fedorahosted.org/sssd/ticket/2703
>
> src/tests/ipa_hbac-tests.c | 2 +-
>   1 file changed, 1 insertion(+), 1 deletion(-)
>
> diff --git a/src/tests/ipa_hbac-tests.c b/src/tests/ipa_hbac-tests.c
> index bd56c8f107b05f07b1ba8913fc14a03419d679f7..f2192a6fbc5188a7a7f6b204e03ca5961bb53f75 100644
> --- a/src/tests/ipa_hbac-tests.c
> +++ b/src/tests/ipa_hbac-tests.c
> @@ -367,7 +367,7 @@ START_TEST(ipa_hbac_test_allow_utf8)
>       fail_if(rules[0]->services->names == NULL);
>   rules[0]->srchosts->names[0] = (const char *) &srchost_utf8_upcase;
> rules[0]->services->names[1] = NULL;
>
> rules[0]->srchosts->names[1] = NULL;
>
> rules[1] = NULL;
>
> -- 2.4.3

Nice catch! Ci passed. ACK to this patch
> 0002-HBAC-Better-libhbac-debugging.patch
>
> From 75d97a5336e2b66d4bb187ce024ad9be9b2702b9 Mon Sep 17 00:00:00 2001
> From: Petr Cech
> 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 | 149 +++++++++++++++++++++++++++++++++++++
>   src/providers/ipa/ipa_access.c     |  45 +++++++++++
>   src/providers/ipa/ipa_hbac.exports |   3 +-
>   src/providers/ipa/ipa_hbac.h       |  22 ++++++
>   4 files changed, 218 insertions(+), 1 deletion(-)
>
> diff --git a/src/providers/ipa/hbac_evaluator.c b/src/providers/ipa/hbac_evaluator.c
> index f40f9e0a7f16f5e012079c637b89c8e49ec5d15b..976d5887baeecbb45d660c0de5ca54c914fc6367 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>

Are these header files really needed? What do we need from them? I'm 
just asking as code seems to compile fine even without them.
> #include <string.h>
>   #include <errno.h>
>   #include "providers/ipa/ipa_hbac.h"
> @@ -38,6 +40,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 +149,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()");
> hbac_req_debug_print(hbac_req);
> 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 +164,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 +190,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].",
>                   rules[i]->name);
>         result = HBAC_EVAL_ERROR;
>         if (info) {
>             (*info)->code = ret;
>
> @@ -163,6 +210,7 @@ enum hbac_eval_result hbac_evaluate(struct hbac_rule **rules,
>        */
>   done:
> HBAC_DEBUG(HBAC_DBG_INFO, "hbac_evaluate() >]");
>  return result;
> }
>
> @@ -333,3 +381,104 @@ 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, "    %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++) {

We do no like vars declared in 'for' , please move it to the beginning 
of the if block, thanks!
>                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)));

Could we use directly ctime() here? Anyway please check that you don't 
pass NULL.
> } else {
>    HBAC_DEBUG(HBAC_DBG_TRACE, "  Request is EMPTY.");
> }
>
> +}
>
> +static void hbac_rule_element_debug_print(struct hbac_rule_element *el,
>                                      const char *label)
>
> +{
> if (el) {

indent the whole block please
> HBAC_DEBUG(HBAC_DBG_TRACE, "      category [%#x] [%s]", el->category,
>           (el->category == HBAC_CATEGORY_ALL) ? "ALL" : "NONE");

new line here
> if (el->names) {
>    if (el->names[0]) {
>        HBAC_DEBUG(HBAC_DBG_TRACE, "      %s_names:", label);
>        for (int i = 0; el->names[i]; i++) {

move the def. of i please
>            HBAC_DEBUG(HBAC_DBG_TRACE, "        [%s]", el->names[i]);
>        }
>    } else {
>        HBAC_DEBUG(HBAC_DBG_TRACE, "      %s_names (none)", label);
>    }
> }

new line here
> if (el->groups) {
>    if (el->groups[0]) {
>        HBAC_DEBUG(HBAC_DBG_TRACE, "      %s_groups:", label);
>        for (int i = 0; el->groups[i]; i++) {

defin. of 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)");
>    }
>    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)");
>    }
>    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)");
>    }
>    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..0e0716ad05a86a4acd57673c6944d5af9d22e71b 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;
> switch(level) {
> case HBAC_DBG_FATAL:
>    loglevel = SSSDBG_FATAL_FAILURE;

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?
>    break;
> case HBAC_DBG_ERROR:
>    loglevel = SSSDBG_CRIT_FAILURE;
>    break;
> case HBAC_DBG_WARNING:
>    loglevel = SSSDBG_OP_FAILURE;

I would lower this less severe level.
>    break;
> case HBAC_DBG_INFO:
>    loglevel = SSSDBG_MINOR_FAILURE;
>    break;
> case HBAC_DBG_TRACE:
>    loglevel = SSSDBG_TRACE_ALL;
>    break;
> }

Please rethink the log severity mapping, I think that generally you 
should lower the severity.
> 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)) {

Please move this test at the beginning of the function - so dynamic 
allocations can be skipped if possible.
>    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.
>             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..f307778fa6d0b10364f4bc8f4151fda3f4a38dab 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,
> HBAC_DBG_ERROR,
> HBAC_DBG_WARNING,
> HBAC_DBG_INFO,
> HBAC_DBG_TRACE
>
> +};
>
> +/**
> 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

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?