[PATCH] [HBAC]: Better libhbac debuging

[Petr Cech]

Hi,

according to
https://fedorahosted.org/sssd/ticket/2703

I tried to add logging to the library HBAC.

A)
Logging is performed using an external function, which you can set by:
# hbac_enable_debug(...)

B)
The specific implementation of such a function, you can see
# hbac_debug_messages(...)

C)
You can specify debug level:

'...' stands for
sssd_cygnus.dev.log:(Fri Jul 24 10:29:36 2015) [sssd[be[cygnus.dev]]] 
[hbac] (0x0080): [../src/providers/ipa/

* SSSDBG_MINOR_FAILURE produces:

Question: What kind of information could I add for request into this level?

...hbac_evaluator.c:150] [< hbac_evaluate()
...hbac_evaluator.c:173] DISALLOWED by rule [szabo_allowed].
...hbac_evaluator.c:180] ALLOWED by rule [Test_rule].
...hbac_evaluator.c:214] hbac_evaluate() >]
...hbac_evaluator.c:150] [< hbac_evaluate()
...hbac_evaluator.c:173] DISALLOWED by rule [szabo_allowed].
...hbac_evaluator.c:173] DISALLOWED by rule [Test_rule].
...hbac_evaluator.c:214] hbac_evaluate() >]
...hbac_evaluator.c:150] [< hbac_evaluate()
...hbac_evaluator.c:173] DISALLOWED by rule [szabo_allowed].
...hbac_evaluator.c:173] DISALLOWED by rule [Test_rule].
...hbac_evaluator.c:214] hbac_evaluate() >]

* 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:
...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:
...hbac_evaluator.c:427]       category [0] [NONE]
...hbac_evaluator.c:435]       users_names (none)
...hbac_evaluator.c:445]       users_groups (none)
...hbac_evaluator.c:468]     targethosts:
...hbac_evaluator.c:427]       category [0] [NONE]
...hbac_evaluator.c:430]       targethosts_names:
...hbac_evaluator.c:432]         [albireo.cygnus.dev]
...hbac_evaluator.c:445]       targethosts_groups (none)
...hbac_evaluator.c:474]     srchosts:
...hbac_evaluator.c:427]       category [0x1] [ALL]
...hbac_evaluator.c:173] DISALLOWED by rule [szabo_allowed].
...hbac_evaluator.c:454]   RULE [Test_rule] [ENABLED]:
...hbac_evaluator.c:456]     services:
...hbac_evaluator.c:427]       category [0] [NONE]
...hbac_evaluator.c:430]       services_names:
...hbac_evaluator.c:432]         [login]
...hbac_evaluator.c:432]         [sshd]
...hbac_evaluator.c:432]         [su]
...hbac_evaluator.c:445]       services_groups (none)
...hbac_evaluator.c:462]     users:
...hbac_evaluator.c:427]       category [0] [NONE]
...hbac_evaluator.c:430]       users_names:
...hbac_evaluator.c:432]         [csikos]
...hbac_evaluator.c:445]       users_groups (none)
...hbac_evaluator.c:468]     targethosts:
...hbac_evaluator.c:427]       category [0] [NONE]
...hbac_evaluator.c:430]       targethosts_names:
...hbac_evaluator.c:432]         [albireo.cygnus.dev]
...hbac_evaluator.c:445]       targethosts_groups (none)
...hbac_evaluator.c:474]     srchosts:
...hbac_evaluator.c:427]       category [0x1] [ALL]
...hbac_evaluator.c:180] ALLOWED by rule [Test_rule].
...hbac_evaluator.c:214] hbac_evaluate() >]
...hbac_evaluator.c:150] [< hbac_evaluate()
...hbac_evaluator.c:410]   REQUEST:
...hbac_evaluator.c:391]     service [systemd-user]
...hbac_evaluator.c:400]     service_group (none)
...hbac_evaluator.c:391]     user [csikos]
...hbac_evaluator.c:395]     user_group:
...hbac_evaluator.c:397]       [ipausers]
...hbac_evaluator.c:391]     targethost [albireo.cygnus.dev]
...hbac_evaluator.c:400]     targethost_group (none)
...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:
...hbac_evaluator.c:427]       category [0] [NONE]
...hbac_evaluator.c:435]       users_names (none)
...hbac_evaluator.c:445]       users_groups (none)
...hbac_evaluator.c:468]     targethosts:
...hbac_evaluator.c:427]       category [0] [NONE]
...hbac_evaluator.c:430]       targethosts_names:
...hbac_evaluator.c:432]         [albireo.cygnus.dev]
...hbac_evaluator.c:445]       targethosts_groups (none)
...hbac_evaluator.c:474]     srchosts:
...hbac_evaluator.c:427]       category [0x1] [ALL]
...hbac_evaluator.c:173] DISALLOWED by rule [szabo_allowed].
...hbac_evaluator.c:454]   RULE [Test_rule] [ENABLED]:
...hbac_evaluator.c:456]     services:
...hbac_evaluator.c:427]       category [0] [NONE]
...hbac_evaluator.c:430]       services_names:
...hbac_evaluator.c:432]         [login]
...hbac_evaluator.c:432]         [sshd]
...hbac_evaluator.c:432]         [su]
...hbac_evaluator.c:445]       services_groups (none)
...hbac_evaluator.c:462]     users:
...hbac_evaluator.c:427]       category [0] [NONE]
...hbac_evaluator.c:430]       users_names:
...hbac_evaluator.c:432]         [csikos]
...hbac_evaluator.c:445]       users_groups (none)
...hbac_evaluator.c:468]     targethosts:
...hbac_evaluator.c:427]       category [0] [NONE]
...hbac_evaluator.c:430]       targethosts_names:
...hbac_evaluator.c:432]         [albireo.cygnus.dev]
...hbac_evaluator.c:445]       targethosts_groups (none)
...hbac_evaluator.c:474]     srchosts:
...hbac_evaluator.c:427]       category [0x1] [ALL]
...hbac_evaluator.c:173] DISALLOWED by rule [Test_rule].
...hbac_evaluator.c:214] hbac_evaluate() >]
...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 [szabo]
...hbac_evaluator.c:395]     user_group:
...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:46 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:
...hbac_evaluator.c:427]       category [0] [NONE]
...hbac_evaluator.c:430]       users_names:
...hbac_evaluator.c:432]         [szabo]
...hbac_evaluator.c:445]       users_groups (none)
...hbac_evaluator.c:468]     targethosts:
...hbac_evaluator.c:427]       category [0] [NONE]
...hbac_evaluator.c:430]       targethosts_names:
...hbac_evaluator.c:432]         [albireo.cygnus.dev]
...hbac_evaluator.c:445]       targethosts_groups (none)
...hbac_evaluator.c:474]     srchosts:
...hbac_evaluator.c:427]       category [0x1] [ALL]
...hbac_evaluator.c:173] DISALLOWED by rule [szabo_allowed].
...hbac_evaluator.c:454]   RULE [Test_rule] [ENABLED]:
...hbac_evaluator.c:456]     services:
...hbac_evaluator.c:427]       category [0] [NONE]
...hbac_evaluator.c:430]       services_names:
...hbac_evaluator.c:432]         [login]
...hbac_evaluator.c:432]         [sshd]
...hbac_evaluator.c:432]         [su]
...hbac_evaluator.c:445]       services_groups (none)
...hbac_evaluator.c:462]     users:
...hbac_evaluator.c:427]       category [0] [NONE]
...hbac_evaluator.c:430]       users_names:
...hbac_evaluator.c:432]         [csikos]
...hbac_evaluator.c:445]       users_groups (none)
...hbac_evaluator.c:468]     targethosts:
...hbac_evaluator.c:427]       category [0] [NONE]
...hbac_evaluator.c:430]       targethosts_names:
...hbac_evaluator.c:432]         [albireo.cygnus.dev]
...hbac_evaluator.c:445]       targethosts_groups (none)
...hbac_evaluator.c:474]     srchosts:
...hbac_evaluator.c:427]       category [0x1] [ALL]
...hbac_evaluator.c:173] DISALLOWED by rule [Test_rule].
...hbac_evaluator.c:214] hbac_evaluate() >]

Thanks.

Petr

[Petr Cech]

ping :-)

[Pavel Reichl]

On 07/24/2015 06:20 PM, Petr Cech wrote:
> From 2fcf13ef59f00b460afa77b27ef6cc2789b06393 Mon Sep 17 00:00:00 2001
> From: Petr Cech
> Date: Fri, 24 Jul 2015 10:56:49 -0400
> Subject: [PATCH] [HBAC]: Better libhbac debuging

s/debuging/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 | 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?
> +/* 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.
> +/* auxiliary function for hbac_request_element logging */
> +static void hbac_request_element_debug_print(struct hbac_request_element *el,
>    const char *label);

bad indentation
> +/* 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?
>   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/
>                   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?
>   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
> +{
> 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?
>    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
>    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
>    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 *
> 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?
> #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)

[Petr Cech]

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
> > 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
> [e-mail]
> https://lists.fedorahosted.org/mailman/listinfo/sssd-devel

[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?

[Petr Cech]

On 08/27/2015 10:42 AM, Pavel Reichl wrote:
> > 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:

Hi Pavel,

there is better example. Do you have any suggestion how to improve the 
levels?

Regards

Petr

[Pavel Reichl]

On 08/31/2015 01:18 PM, Petr Cech wrote:
> 0x0080
>
> (Mon Aug 31 06:57:09 2015) [sssd[be[cygnus.dev]]] [ipa_hbac_evaluate_rules] (0x0080): Access granted by HBAC rule [Test_rule]
> (Mon Aug 31 06:57:09 2015) [sssd[be[cygnus.dev]]] [ipa_hbac_evaluate_rules] (0x0080): Access denied by HBAC rules
>
> 0x0100
>
> (Mon Aug 31 06:58:33 2015) [sssd[be[cygnus.dev]]] [hbac] (0x0100): [../src/providers/ipa/hbac_evaluator.c:152] [< hbac_evaluate()
> (Mon Aug 31 06:58:33 2015) [sssd[be[cygnus.dev]]] [hbac] (0x0100): [../src/providers/ipa/hbac_evaluator.c:172] DISALLOWED by rule [szabo_allowed].
> (Mon Aug 31 06:58:33 2015) [sssd[be[cygnus.dev]]] [hbac] (0x0100): [../src/providers/ipa/hbac_evaluator.c:179] ALLOWED by rule [Test_rule].
> (Mon Aug 31 06:58:33 2015) [sssd[be[cygnus.dev]]] [hbac] (0x0100): [../src/providers/ipa/hbac_evaluator.c:213] hbac_evaluate() >]
> (Mon Aug 31 06:58:34 2015) [sssd[be[cygnus.dev]]] [hbac] (0x0100): [../src/providers/ipa/hbac_evaluator.c:152] [< hbac_evaluate()
> (Mon Aug 31 06:58:34 2015) [sssd[be[cygnus.dev]]] [hbac] (0x0100): [../src/providers/ipa/hbac_evaluator.c:172] DISALLOWED by rule [szabo_allowed].
> (Mon Aug 31 06:58:34 2015) [sssd[be[cygnus.dev]]] [hbac] (0x0100): [../src/providers/ipa/hbac_evaluator.c:172] DISALLOWED by rule [Test_rule].
> (Mon Aug 31 06:58:34 2015) [sssd[be[cygnus.dev]]] [hbac] (0x0100): [../src/providers/ipa/hbac_evaluator.c:213] hbac_evaluate() >]
>
> 0x2000
>
> (Mon Aug 31 07:03:04 2015) [sssd[be[cygnus.dev]]] [hbac] (0x0100): [../src/providers/ipa/hbac_evaluator.c:152] [< hbac_evaluate()
> (Mon Aug 31 07:03:04 2015) [sssd[be[cygnus.dev]]] [hbac] (0x2000): [../src/providers/ipa/hbac_evaluator.c:409]   REQUEST:
> (Mon Aug 31 07:03:04 2015) [sssd[be[cygnus.dev]]] [hbac] (0x2000): [../src/providers/ipa/hbac_evaluator.c:390]     service [sshd]
> (Mon Aug 31 07:03:04 2015) [sssd[be[cygnus.dev]]] [hbac] (0x2000): [../src/providers/ipa/hbac_evaluator.c:399]     service_group (none)
> (Mon Aug 31 07:03:04 2015) [sssd[be[cygnus.dev]]] [hbac] (0x2000): [../src/providers/ipa/hbac_evaluator.c:390]     user [csikos]

I think it would be useful to print this line
> (Mon Aug 31 07:03:04 2015) [sssd[be[cygnus.dev]]] [hbac] (0x2000): [../src/providers/ipa/hbac_evaluator.c:394]     user_group:
> (Mon Aug 31 07:03:04 2015) [sssd[be[cygnus.dev]]] [hbac] (0x2000): [../src/providers/ipa/hbac_evaluator.c:396]       [ipausers]

and this line even for debug_level 0x0100

But I don't insist. I won't delay patch for this.
> (Mon Aug 31 07:03:04 2015) [sssd[be[cygnus.dev]]] [hbac] (0x2000): [../src/providers/ipa/hbac_evaluator.c:390]     targethost [albireo.cygnus.dev]
> (Mon Aug 31 07:03:04 2015) [sssd[be[cygnus.dev]]] [hbac] (0x2000): [../src/providers/ipa/hbac_evaluator.c:399]     targethost_group (none)
> (Mon Aug 31 07:03:04 2015) [sssd[be[cygnus.dev]]] [hbac] (0x2000): [../src/providers/ipa/hbac_evaluator.c:390]     srchost [192.168.122.106]
> (Mon Aug 31 07:03:04 2015) [sssd[be[cygnus.dev]]] [hbac] (0x2000): [../src/providers/ipa/hbac_evaluator.c:399]     srchost_group (none)
> (Mon Aug 31 07:03:04 2015) [sssd[be[cygnus.dev]]] [hbac] (0x2000): [../src/providers/ipa/hbac_evaluator.c:416]     request time Mon Aug 31 11:03:04 2015
> (Mon Aug 31 07:03:04 2015) [sssd[be[cygnus.dev]]] [hbac] (0x2000): [../src/providers/ipa/hbac_evaluator.c:455]   RULE [szabo_allowed] [ENABLED]:
> (Mon Aug 31 07:03:04 2015) [sssd[be[cygnus.dev]]] [hbac] (0x2000): [../src/providers/ipa/hbac_evaluator.c:457]     services:
> (Mon Aug 31 07:03:04 2015) [sssd[be[cygnus.dev]]] [hbac] (0x2000): [../src/providers/ipa/hbac_evaluator.c:427]       category [0] [NONE]
> (Mon Aug 31 07:03:04 2015) [sssd[be[cygnus.dev]]] [hbac] (0x2000): [../src/providers/ipa/hbac_evaluator.c:435]       services_names (none)
> (Mon Aug 31 07:03:04 2015) [sssd[be[cygnus.dev]]] [hbac] (0x2000): [../src/providers/ipa/hbac_evaluator.c:440]       services_groups:
> (Mon Aug 31 07:03:04 2015) [sssd[be[cygnus.dev]]] [hbac] (0x2000): [../src/providers/ipa/hbac_evaluator.c:442]         [Sudo]
> (Mon Aug 31 07:03:04 2015) [sssd[be[cygnus.dev]]] [hbac] (0x2000): [../src/providers/ipa/hbac_evaluator.c:464]     users:
> (Mon Aug 31 07:03:04 2015) [sssd[be[cygnus.dev]]] [hbac] (0x2000): [../src/providers/ipa/hbac_evaluator.c:427]       category [0] [NONE]
> (Mon Aug 31 07:03:04 2015) [sssd[be[cygnus.dev]]] [hbac] (0x2000): [../src/providers/ipa/hbac_evaluator.c:435]       users_names (none)
> (Mon Aug 31 07:03:04 2015) [sssd[be[cygnus.dev]]] [hbac] (0x2000): [../src/providers/ipa/hbac_evaluator.c:445]       users_groups (none)
> (Mon Aug 31 07:03:04 2015) [sssd[be[cygnus.dev]]] [hbac] (0x2000): [../src/providers/ipa/hbac_evaluator.c:471]     targethosts:
> (Mon Aug 31 07:03:04 2015) [sssd[be[cygnus.dev]]] [hbac] (0x2000): [../src/providers/ipa/hbac_evaluator.c:427]       category [0] [NONE]
> (Mon Aug 31 07:03:04 2015) [sssd[be[cygnus.dev]]] [hbac] (0x2000): [../src/providers/ipa/hbac_evaluator.c:430]       targethosts_names:
> (Mon Aug 31 07:03:04 2015) [sssd[be[cygnus.dev]]] [hbac] (0x2000): [../src/providers/ipa/hbac_evaluator.c:432]         [albireo.cygnus.dev]
> (Mon Aug 31 07:03:04 2015) [sssd[be[cygnus.dev]]] [hbac] (0x2000): [../src/providers/ipa/hbac_evaluator.c:445]       targethosts_groups (none)
> (Mon Aug 31 07:03:04 2015) [sssd[be[cygnus.dev]]] [hbac] (0x2000): [../src/providers/ipa/hbac_evaluator.c:478]     srchosts:
> (Mon Aug 31 07:03:04 2015) [sssd[be[cygnus.dev]]] [hbac] (0x2000): [../src/providers/ipa/hbac_evaluator.c:427]       category [0x1] [ALL]
> (Mon Aug 31 07:03:04 2015) [sssd[be[cygnus.dev]]] [hbac] (0x0100): [../src/providers/ipa/hbac_evaluator.c:172] DISALLOWED by rule [szabo_allowed].
> (Mon Aug 31 07:03:04 2015) [sssd[be[cygnus.dev]]] [hbac] (0x2000): [../src/providers/ipa/hbac_evaluator.c:455]   RULE [Test_rule] [ENABLED]:
> (Mon Aug 31 07:03:04 2015) [sssd[be[cygnus.dev]]] [hbac] (0x2000): [../src/providers/ipa/hbac_evaluator.c:457]     services:
> (Mon Aug 31 07:03:04 2015) [sssd[be[cygnus.dev]]] [hbac] (0x2000): [../src/providers/ipa/hbac_evaluator.c:427]       category [0] [NONE]
> (Mon Aug 31 07:03:04 2015) [sssd[be[cygnus.dev]]] [hbac] (0x2000): [../src/providers/ipa/hbac_evaluator.c:430]       services_names:
> (Mon Aug 31 07:03:04 2015) [sssd[be[cygnus.dev]]] [hbac] (0x2000): [../src/providers/ipa/hbac_evaluator.c:432]         [login]
> (Mon Aug 31 07:03:04 2015) [sssd[be[cygnus.dev]]] [hbac] (0x2000): [../src/providers/ipa/hbac_evaluator.c:432]         [sshd]
> (Mon Aug 31 07:03:04 2015) [sssd[be[cygnus.dev]]] [hbac] (0x2000): [../src/providers/ipa/hbac_evaluator.c:432]         [su]
> (Mon Aug 31 07:03:04 2015) [sssd[be[cygnus.dev]]] [hbac] (0x2000): [../src/providers/ipa/hbac_evaluator.c:445]       services_groups (none)
> (Mon Aug 31 07:03:04 2015) [sssd[be[cygnus.dev]]] [hbac] (0x2000): [../src/providers/ipa/hbac_evaluator.c:464]     users:
> (Mon Aug 31 07:03:04 2015) [sssd[be[cygnus.dev]]] [hbac] (0x2000): [../src/providers/ipa/hbac_evaluator.c:427]       category [0] [NONE]
> (Mon Aug 31 07:03:04 2015) [sssd[be[cygnus.dev]]] [hbac] (0x2000): [../src/providers/ipa/hbac_evaluator.c:430]       users_names:
> (Mon Aug 31 07:03:04 2015) [sssd[be[cygnus.dev]]] [hbac] (0x2000): [../src/providers/ipa/hbac_evaluator.c:432]         [csikos]
> (Mon Aug 31 07:03:04 2015) [sssd[be[cygnus.dev]]] [hbac] (0x2000): [../src/providers/ipa/hbac_evaluator.c:445]       users_groups (none)
> (Mon Aug 31 07:03:04 2015) [sssd[be[cygnus.dev]]] [hbac] (0x2000): [../src/providers/ipa/hbac_evaluator.c:471]     targethosts:
> (Mon Aug 31 07:03:04 2015) [sssd[be[cygnus.dev]]] [hbac] (0x2000): [../src/providers/ipa/hbac_evaluator.c:427]       category [0] [NONE]
> (Mon Aug 31 07:03:04 2015) [sssd[be[cygnus.dev]]] [hbac] (0x2000): [../src/providers/ipa/hbac_evaluator.c:430]       targethosts_names:
> (Mon Aug 31 07:03:04 2015) [sssd[be[cygnus.dev]]] [hbac] (0x2000): [../src/providers/ipa/hbac_evaluator.c:432]         [albireo.cygnus.dev]
> (Mon Aug 31 07:03:04 2015) [sssd[be[cygnus.dev]]] [hbac] (0x2000): [../src/providers/ipa/hbac_evaluator.c:445]       targethosts_groups (none)
> (Mon Aug 31 07:03:04 2015) [sssd[be[cygnus.dev]]] [hbac] (0x2000): [../src/providers/ipa/hbac_evaluator.c:478]     srchosts:
> (Mon Aug 31 07:03:04 2015) [sssd[be[cygnus.dev]]] [hbac] (0x2000): [../src/providers/ipa/hbac_evaluator.c:427]       category [0x1] [ALL]
> (Mon Aug 31 07:03:04 2015) [sssd[be[cygnus.dev]]] [hbac] (0x0100): [../src/providers/ipa/hbac_evaluator.c:179] ALLOWED by rule [Test_rule].
> (Mon Aug 31 07:03:04 2015) [sssd[be[cygnus.dev]]] [hbac] (0x0100): [../src/providers/ipa/hbac_evaluator.c:213] hbac_evaluate() >]
> (Mon Aug 31 07:03:04 2015) [sssd[be[cygnus.dev]]] [ipa_hbac_evaluate_rules] (0x0080): Access granted by HBAC rule [Test_rule]
> (Mon Aug 31 07:03:04 2015) [sssd[be[cygnus.dev]]] [hbac] (0x0100): [../src/providers/ipa/hbac_evaluator.c:152] [< hbac_evaluate()
> (Mon Aug 31 07:03:04 2015) [sssd[be[cygnus.dev]]] [hbac] (0x2000): [../src/providers/ipa/hbac_evaluator.c:409]   REQUEST:
> (Mon Aug 31 07:03:04 2015) [sssd[be[cygnus.dev]]] [hbac] (0x2000): [../src/providers/ipa/hbac_evaluator.c:390]     service [systemd-user]
> (Mon Aug 31 07:03:04 2015) [sssd[be[cygnus.dev]]] [hbac] (0x2000): [../src/providers/ipa/hbac_evaluator.c:399]     service_group (none)
> (Mon Aug 31 07:03:04 2015) [sssd[be[cygnus.dev]]] [hbac] (0x2000): [../src/providers/ipa/hbac_evaluator.c:390]     user [csikos]
> (Mon Aug 31 07:03:04 2015) [sssd[be[cygnus.dev]]] [hbac] (0x2000): [../src/providers/ipa/hbac_evaluator.c:394]     user_group:
> (Mon Aug 31 07:03:04 2015) [sssd[be[cygnus.dev]]] [hbac] (0x2000): [../src/providers/ipa/hbac_evaluator.c:396]       [ipausers]
> (Mon Aug 31 07:03:04 2015) [sssd[be[cygnus.dev]]] [hbac] (0x2000): [../src/providers/ipa/hbac_evaluator.c:390]     targethost [albireo.cygnus.dev]
> (Mon Aug 31 07:03:04 2015) [sssd[be[cygnus.dev]]] [hbac] (0x2000): [../src/providers/ipa/hbac_evaluator.c:399]     targethost_group (none)
> (Mon Aug 31 07:03:04 2015) [sssd[be[cygnus.dev]]] [hbac] (0x2000): [../src/providers/ipa/hbac_evaluator.c:399]     srchost_group (none)
> (Mon Aug 31 07:03:04 2015) [sssd[be[cygnus.dev]]] [hbac] (0x2000): [../src/providers/ipa/hbac_evaluator.c:416]     request time Mon Aug 31 11:03:04 2015
> (Mon Aug 31 07:03:04 2015) [sssd[be[cygnus.dev]]] [hbac] (0x2000): [../src/providers/ipa/hbac_evaluator.c:455]   RULE [szabo_allowed] [ENABLED]:
> (Mon Aug 31 07:03:04 2015) [sssd[be[cygnus.dev]]] [hbac] (0x2000): [../src/providers/ipa/hbac_evaluator.c:457]     services:
> (Mon Aug 31 07:03:04 2015) [sssd[be[cygnus.dev]]] [hbac] (0x2000): [../src/providers/ipa/hbac_evaluator.c:427]       category [0] [NONE]
> (Mon Aug 31 07:03:04 2015) [sssd[be[cygnus.dev]]] [hbac] (0x2000): [../src/providers/ipa/hbac_evaluator.c:435]       services_names (none)
> (Mon Aug 31 07:03:04 2015) [sssd[be[cygnus.dev]]] [hbac] (0x2000): [../src/providers/ipa/hbac_evaluator.c:440]       services_groups:
> (Mon Aug 31 07:03:04 2015) [sssd[be[cygnus.dev]]] [hbac] (0x2000): [../src/providers/ipa/hbac_evaluator.c:442]         [Sudo]
> (Mon Aug 31 07:03:04 2015) [sssd[be[cygnus.dev]]] [hbac] (0x2000): [../src/providers/ipa/hbac_evaluator.c:464]     users:
> (Mon Aug 31 07:03:04 2015) [sssd[be[cygnus.dev]]] [hbac] (0x2000): [../src/providers/ipa/hbac_evaluator.c:427]       category [0] [NONE]
> (Mon Aug 31 07:03:04 2015) [sssd[be[cygnus.dev]]] [hbac] (0x2000): [../src/providers/ipa/hbac_evaluator.c:435]       users_names (none)
> (Mon Aug 31 07:03:04 2015) [sssd[be[cygnus.dev]]] [hbac] (0x2000): [../src/providers/ipa/hbac_evaluator.c:445]       users_groups (none)
> (Mon Aug 31 07:03:04 2015) [sssd[be[cygnus.dev]]] [hbac] (0x2000): [../src/providers/ipa/hbac_evaluator.c:471]     targethosts:
> (Mon Aug 31 07:03:04 2015) [sssd[be[cygnus.dev]]] [hbac] (0x2000): [../src/providers/ipa/hbac_evaluator.c:427]       category [0] [NONE]
> (Mon Aug 31 07:03:04 2015) [sssd[be[cygnus.dev]]] [hbac] (0x2000): [../src/providers/ipa/hbac_evaluator.c:430]       targethosts_names:
> (Mon Aug 31 07:03:04 2015) [sssd[be[cygnus.dev]]] [hbac] (0x2000): [../src/providers/ipa/hbac_evaluator.c:432]         [albireo.cygnus.dev]
> (Mon Aug 31 07:03:04 2015) [sssd[be[cygnus.dev]]] [hbac] (0x2000): [../src/providers/ipa/hbac_evaluator.c:445]       targethosts_groups (none)
> (Mon Aug 31 07:03:04 2015) [sssd[be[cygnus.dev]]] [hbac] (0x2000): [../src/providers/ipa/hbac_evaluator.c:478]     srchosts:
> (Mon Aug 31 07:03:04 2015) [sssd[be[cygnus.dev]]] [hbac] (0x2000): [../src/providers/ipa/hbac_evaluator.c:427]       category [0x1] [ALL]
> (Mon Aug 31 07:03:04 2015) [sssd[be[cygnus.dev]]] [hbac] (0x0100): [../src/providers/ipa/hbac_evaluator.c:172] DISALLOWED by rule [szabo_allowed].
> (Mon Aug 31 07:03:04 2015) [sssd[be[cygnus.dev]]] [hbac] (0x2000): [../src/providers/ipa/hbac_evaluator.c:455]   RULE [Test_rule] [ENABLED]:
> (Mon Aug 31 07:03:04 2015) [sssd[be[cygnus.dev]]] [hbac] (0x2000): [../src/providers/ipa/hbac_evaluator.c:457]     services:
> (Mon Aug 31 07:03:04 2015) [sssd[be[cygnus.dev]]] [hbac] (0x2000): [../src/providers/ipa/hbac_evaluator.c:427]       category [0] [NONE]
> (Mon Aug 31 07:03:04 2015) [sssd[be[cygnus.dev]]] [hbac] (0x2000): [../src/providers/ipa/hbac_evaluator.c:430]       services_names:
> (Mon Aug 31 07:03:04 2015) [sssd[be[cygnus.dev]]] [hbac] (0x2000): [../src/providers/ipa/hbac_evaluator.c:432]         [login]
> (Mon Aug 31 07:03:04 2015) [sssd[be[cygnus.dev]]] [hbac] (0x2000): [../src/providers/ipa/hbac_evaluator.c:432]         [sshd]
> (Mon Aug 31 07:03:04 2015) [sssd[be[cygnus.dev]]] [hbac] (0x2000): [../src/providers/ipa/hbac_evaluator.c:432]         [su]
> (Mon Aug 31 07:03:04 2015) [sssd[be[cygnus.dev]]] [hbac] (0x2000): [../src/providers/ipa/hbac_evaluator.c:445]       services_groups (none)
> (Mon Aug 31 07:03:04 2015) [sssd[be[cygnus.dev]]] [hbac] (0x2000): [../src/providers/ipa/hbac_evaluator.c:464]     users:
> (Mon Aug 31 07:03:04 2015) [sssd[be[cygnus.dev]]] [hbac] (0x2000): [../src/providers/ipa/hbac_evaluator.c:427]       category [0] [NONE]
> (Mon Aug 31 07:03:04 2015) [sssd[be[cygnus.dev]]] [hbac] (0x2000): [../src/providers/ipa/hbac_evaluator.c:430]       users_names:
> (Mon Aug 31 07:03:04 2015) [sssd[be[cygnus.dev]]] [hbac] (0x2000): [../src/providers/ipa/hbac_evaluator.c:432]         [csikos]
> (Mon Aug 31 07:03:04 2015) [sssd[be[cygnus.dev]]] [hbac] (0x2000): [../src/providers/ipa/hbac_evaluator.c:445]       users_groups (none)
> (Mon Aug 31 07:03:04 2015) [sssd[be[cygnus.dev]]] [hbac] (0x2000): [../src/providers/ipa/hbac_evaluator.c:471]     targethosts:
> (Mon Aug 31 07:03:04 2015) [sssd[be[cygnus.dev]]] [hbac] (0x2000): [../src/providers/ipa/hbac_evaluator.c:427]       category [0] [NONE]
> (Mon Aug 31 07:03:04 2015) [sssd[be[cygnus.dev]]] [hbac] (0x2000): [../src/providers/ipa/hbac_evaluator.c:430]       targethosts_names:
> (Mon Aug 31 07:03:04 2015) [sssd[be[cygnus.dev]]] [hbac] (0x2000): [../src/providers/ipa/hbac_evaluator.c:432]         [albireo.cygnus.dev]
> (Mon Aug 31 07:03:04 2015) [sssd[be[cygnus.dev]]] [hbac] (0x2000): [../src/providers/ipa/hbac_evaluator.c:445]       targethosts_groups (none)
> (Mon Aug 31 07:03:04 2015) [sssd[be[cygnus.dev]]] [hbac] (0x2000): [../src/providers/ipa/hbac_evaluator.c:478]     srchosts:
> (Mon Aug 31 07:03:04 2015) [sssd[be[cygnus.dev]]] [hbac] (0x2000): [../src/providers/ipa/hbac_evaluator.c:427]       category [0x1] [ALL]
> (Mon Aug 31 07:03:04 2015) [sssd[be[cygnus.dev]]] [hbac] (0x0100): [../src/providers/ipa/hbac_evaluator.c:172] DISALLOWED by rule [Test_rule].
> (Mon Aug 31 07:03:04 2015) [sssd[be[cygnus.dev]]] [hbac] (0x0100): [../src/providers/ipa/hbac_evaluator.c:213] hbac_evaluate() >]
> (Mon Aug 31 07:03:04 2015) [sssd[be[cygnus.dev]]] [ipa_hbac_evaluate_rules] (0x0080): Access denied by HBAC rules

[Petr Cech]

On 08/31/2015 01:32 PM, Pavel Reichl wrote:
> > 0x2000
> >
> > (Mon Aug 31 07:03:04 2015) [sssd[be[cygnus.dev]]] [hbac] (0x0100): [../src/providers/ipa/hbac_evaluator.c:152] [< hbac_evaluate()
> > (Mon Aug 31 07:03:04 2015) [sssd[be[cygnus.dev]]] [hbac] (0x2000): [../src/providers/ipa/hbac_evaluator.c:409]   REQUEST:
> > (Mon Aug 31 07:03:04 2015) [sssd[be[cygnus.dev]]] [hbac] (0x2000): [../src/providers/ipa/hbac_evaluator.c:390]     service [sshd]
> > (Mon Aug 31 07:03:04 2015) [sssd[be[cygnus.dev]]] [hbac] (0x2000): [../src/providers/ipa/hbac_evaluator.c:399]     service_group (none)
> > (Mon Aug 31 07:03:04 2015) [sssd[be[cygnus.dev]]] [hbac] (0x2000): [../src/providers/ipa/hbac_evaluator.c:390]     user [csikos]
>
> I think it would be useful to print this line
> > (Mon Aug 31 07:03:04 2015) [sssd[be[cygnus.dev]]] [hbac] (0x2000): [../src/providers/ipa/hbac_evaluator.c:394]     user_group:
> > (Mon Aug 31 07:03:04 2015) [sssd[be[cygnus.dev]]] [hbac] (0x2000): [../src/providers/ipa/hbac_evaluator.c:396]       [ipausers]
>
> and this line even for debug_level 0x0100
>
> But I don't insist. I won't delay patch for this.

I would like to do it, but it is not so easy. New HBAC logging system 
provides two new levels.

The first level goes throw all rules and it says if allows or disallows. 
The second writes all informations---about request, about each rules.

The simple solution is compromis. I could switch all request information 
from level 2 to level 1. So we could have those informations, see 
attachement.

Petr

[Petr Cech]

On 08/27/2015 10:42 AM, Pavel Reichl wrote:
> > 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:

It was commented in previous mail. I agree.
> On 08/26/2015 09:44 AM, Petr Cech wrote:
> > 0001-TESTS-Fixing-of-uninitialized-pointer.patch
>
> Nice catch! Ci passed. ACK to this patch

Thanks.
> > 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.

Amazingly, it works. The reason were things like ## __ VA_ARGS__ in new 
HBAC_DEBUG macro.
> > #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!

I asked community over mailing list for it. I think, we could try it.
> >                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.

Fixed.
> > } 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

Fixed.
> > HBAC_DEBUG(HBAC_DBG_TRACE, "      category [%#x] [%s]", el->category,
> >           (el->category == HBAC_CATEGORY_ALL) ? "ALL" : "NONE");
>
> new line here

Added.
> > 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

It is new style.
> >            HBAC_DEBUG(HBAC_DBG_TRACE, "        [%s]", el->names[i]);
> >        }
> >    } else {
> >        HBAC_DEBUG(HBAC_DBG_TRACE, "      %s_names (none)", label);
> >    }
> > }
>
> new line here

Fixed.
> > 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

New style.
> >            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?

HBAC_DBG_FATAL isn't used in HBAC code. It is there for completeness of 
HBAC debug system.
> >    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.

(I will write about it down at this mail.)
> >    break;
> > case HBAC_DBG_INFO:
> >    loglevel = SSSDBG_MINOR_FAILURE;
> >    break;
> > case HBAC_DBG_TRACE:
> >    loglevel = SSSDBG_TRACE_ALL;
> >    break;
> > }
>
> Please add default here (http://www.freeipa.org/page/Coding_Style#Switch)

Fixed.
> Please rethink the log severity mapping, I think that generally you
> should lower the severity.

I did some changes:
HBAC_DBG_ERROR:
-        loglevel = SSSDBG_CRIT_FAILURE;
+        loglevel = SSSDBG_OP_FAILURE;
HBAC_DBG_WARNING:
-        loglevel = SSSDBG_OP_FAILURE;
+        loglevel = SSSDBG_MINOR_FAILURE;
HBAC_DBG_INFO:
-        loglevel = SSSDBG_MINOR_FAILURE;
+        loglevel = SSSDBG_CONF_SETTINGS;
HBAC_DBG_TRACE:
-        loglevel = SSSDBG_TRACE_ALL;
+        loglevel = SSSDBG_TRACE_INTERNAL;
Is it OK?
> > 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.

Fixed.
> >    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.
> >             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?

I rewrote it to '\t'.

Petr

[Pavel Reichl]

> > 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
> 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

[Petr Cech]

On 09/01/2015 11:00 AM, Pavel Reichl wrote:
> > From 6b1c6cac7123e78a2c55c51019b66a6bcf97ec29 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 | 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?

Fixed.
> >   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?

Fixed.
> >           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

Fixed.
> >    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

Fixed.
> >    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()

Fixed.
> >             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?

Fixed.
> > 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.

Fixed. 2 asterisks come from doxygen format.
> > +};
> >
> > +/**
> > 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

PS: I attached both patches. The 0001-TESTS-Fixing... was ACK in past.

[Pavel Reichl]

All my concerns were addressed.
CI passed: http://sssd-ci.duckdns.org/logs/job/24/37/summary.html
Code is fine by me and my testing passed.

ACK

I think that this patch will be a real improvement for debugging HBAC issues, thanks Petr.

[Lukas Slebodnik]

On (01/09/15 16:15), Petr Cech wrote:
> On 09/01/2015 11:00 AM, Pavel Reichl wrote:
> > > From 6b1c6cac7123e78a2c55c51019b66a6bcf97ec29 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 | 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?
>
> Fixed.
> > >  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?
>
> Fixed.
> > >          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
>
> Fixed.
> > >    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
>
> Fixed.
> > >    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()
>
> Fixed.
> > >             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?
>
> Fixed.
> > > 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.
>
> Fixed. 2 asterisks come from doxygen format.
> > > +};
> > >
> > > +/**
> > > 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
>
> PS: I attached both patches. The 0001-TESTS-Fixing... was ACK in past.
> From d8d12580c3f1c047e51a4e149c9351bcf03ee0bd 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
> From 5043aea0f1ce6968d3c06245205fa666f2f96ab9 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 | 168 ++++++++++++++++++++++++++++++++++++-
> src/providers/ipa/ipa_access.c     |  50 +++++++++++
> src/providers/ipa/ipa_hbac.exports |   3 +-
> src/providers/ipa/ipa_hbac.h       |  22 +++++
> 4 files changed, 240 insertions(+), 3 deletions(-)
>
> diff --git a/src/providers/ipa/hbac_evaluator.c b/src/providers/ipa/hbac_evaluator.c
> index f40f9e0a7f16f5e012079c637b89c8e49ec5d15b..28d802bc1d3729eee98cfe66ea420043cbd9f40a 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,31 +147,39 @@ 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;
>   (*info)->rule_name = NULL;
> }
>
> uint32_t i;
>
> for (i = 0; rules[i]; i++) {
> for (uint32_t 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, "The rule [%s] did not match.\n",
>                   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].\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 +187,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 +207,7 @@ enum hbac_eval_result hbac_evaluate(struct hbac_rule **rules,
>      */
> done:
> HBAC_DEBUG(HBAC_DBG_INFO, "hbac_evaluate() >]\n");
> return result;
>
> }
>
> @@ -333,3 +378,122 @@ 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);
>    }
>    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) {
>    struct tm *local_time = NULL;
>    size_t ret;
>    const size_t buff_size = 100;
>    char time_buff[buff_size];
>    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");
>    local_time = localtime(&req->request_time);
>    if (local_time == NULL) {
>        return;
>    }
>    ret = strftime(time_buff, buff_size, "%Y-%m-%d %H:%M:%S", local_time);
>    if (ret <= 0) {
>        return;
>    }
>    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..65a791c3fe4b56d0f50d6e501a69d6d4b13f1d9a 100644
> --- a/src/providers/ipa/ipa_access.c
> +++ b/src/providers/ipa/ipa_access.c
> @@ -35,6 +35,54 @@
> #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;
> 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:
>    loglevel = SSSDBG_UNRESOLVED;
>    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 +683,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;

This change is not correct.
new functions should not be added to the the existing version
which was released.

You also forgot to update version-info for library.

@see more details about version script files in the thread which
introduced them to sssd
https://lists.fedorahosted.org/pipermail/sssd-devel/2014-July/019693.html

On Thu, Jun 26, 2014 at 10:31:27AM +0200, Lukas Slebodnik wrote:
> ehlo,
>
> attached patch fixes ticket #2194.
>
> If you wan to know more about version script (version maps) here are links:
>
> http://people.redhat.com/drepper/dsohowto.pdf
>     (sections 2.2.5 .. 2.2.7, 3.4, 3.5)
> https://www.gnu.org/software/gnulib/manual/html_node/LD-Version-Scripts.html
> ftp://ftp.gnu.org/old-gnu/Manuals/ld-2.9.1/html_node/ld_25.html

BTW all these links were provided off the lists few weeks ago.
and for symplification attached is a patch which shoudl be squashed
to your 2nd patch :-)

LS

[Petr Cech]

On 09/11/2015 05:24 PM, Lukas Slebodnik wrote:
> > --- 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;
>
> This change is not correct.
> new functions should not be added to the the existing version
> which was released.
>
> You also forgot to update version-info for library.
>
> @see more details about version script files in the thread which
> introduced them to sssd
> https://lists.fedorahosted.org/pipermail/sssd-devel/2014-July/019693.html
>
> On Thu, Jun 26, 2014 at 10:31:27AM +0200, Lukas Slebodnik wrote:
> > > ehlo,
> > >
> > > attached patch fixes ticket #2194.
> > >
> > > If you wan to know more about version script (version maps) here are links:
> > >
> > > http://people.redhat.com/drepper/dsohowto.pdf
> > >     (sections 2.2.5 .. 2.2.7, 3.4, 3.5)
> > > https://www.gnu.org/software/gnulib/manual/html_node/LD-Version-Scripts.html
> > > ftp://ftp.gnu.org/old-gnu/Manuals/ld-2.9.1/html_node/ld_25.html
>
> BTW all these links were provided off the lists few weeks ago.
> and for symplification attached is a patch which shoudl be squashed
> to your 2nd patch:-)
>
> LS

Hello Lukas,
thanks for comment and for patch too. I attached fixed patch.
Petr
> 0001-squash_me.patch
>
> From 4246d5cd91c4c34b8524be5bfce38c57163a6e2b Mon Sep 17 00:00:00 2001
> From: Lukas Slebodnik
> Date: Fri, 11 Sep 2015 17:04:58 +0200
> Subject: [PATCH] squash_me
>
> Makefile.am                        | 2 +-
>   src/providers/ipa/ipa_hbac.exports | 8 ++++++--
>   2 files changed, 7 insertions(+), 3 deletions(-)
>
> diff --git a/Makefile.am b/Makefile.am
> index 851f943a4c57b70cee4f4f34e83457e7d204aff1..a2a868455f91fac212fcfa7b41681086145c06f9 100644
> --- a/Makefile.am
> +++ b/Makefile.am
> @@ -928,7 +928,7 @@ libipa_hbac_la_LIBADD = \
>       $(UNICODE_LIBS)
>   libipa_hbac_la_LDFLAGS = \
>       -Wl,--version-script,$(srcdir)/src/providers/ipa/ipa_hbac.exports \
> -version-info 0:1:0
> -version-info 1:0:1

Lukas, are you sure this version number 1:0:1? If you're really sure 
this number, I have not understood it properly.
> dist_noinst_DATA += src/providers/ipa/ipa_hbac.exports
>
> diff --git a/src/providers/ipa/ipa_hbac.exports b/src/providers/ipa/ipa_hbac.exports
> index 63b6a5cd673d7b7f3096794648483d280a6bb47f..b7945e139b9ab81b7c1d68eb707acaaff7163a2e 100644
> --- a/src/providers/ipa/ipa_hbac.exports
> +++ b/src/providers/ipa/ipa_hbac.exports
> @@ -1,4 +1,4 @@
> -IPA_HBAC_0.0.2 {
> +IPA_HBAC_0.0.1 {
>   # public functions
>   global:
>
> @@ -8,9 +8,13 @@ IPA_HBAC_0.0.2 {
>           hbac_error_string;
>           hbac_free_info;
>           hbac_rule_is_complete;
>    hbac_enable_debug;
>
> # everything else is local
> local:
>     *;
>
> };
>
> +IPA_HBAC_0.1.0 {
> global:
>    hbac_evaluate;
> +} IPA_HBAC_0.0.1;

[Jakub Hrozek]

On Mon, Sep 14, 2015 at 02:15:39PM +0200, Petr Cech wrote:
> > From 4246d5cd91c4c34b8524be5bfce38c57163a6e2b Mon Sep 17 00:00:00 2001
> > From: Lukas Slebodnik
> > Date: Fri, 11 Sep 2015 17:04:58 +0200
> > Subject: [PATCH] squash_me
> >
> > Makefile.am                        | 2 +-
> >  src/providers/ipa/ipa_hbac.exports | 8 ++++++--
> >  2 files changed, 7 insertions(+), 3 deletions(-)
> >
> > diff --git a/Makefile.am b/Makefile.am
> > index 851f943a4c57b70cee4f4f34e83457e7d204aff1..a2a868455f91fac212fcfa7b41681086145c06f9 100644
> > --- a/Makefile.am
> > +++ b/Makefile.am
> > @@ -928,7 +928,7 @@ libipa_hbac_la_LIBADD = \
> >      $(UNICODE_LIBS)
> >  libipa_hbac_la_LDFLAGS = \
> >      -Wl,--version-script,$(srcdir)/src/providers/ipa/ipa_hbac.exports \
> > -version-info 0:1:0
> > -version-info 1:0:1
>
> Lukas, are you sure this version number 1:0:1? If you're really sure this
> number, I have not understood it properly.

I have not read the patch at all, just adding a link about version info
    https://www.gnu.org/software/libtool/manual/libtool.html#Updating-version-in...

The trick to follow this guide is that it's really an algorithm, so you
shouldn't stop at the first change, but continue (potentially reverting
or overwriting previous changes)

[Petr Cech]

On 09/14/2015 03:25 PM, Jakub Hrozek wrote:
> On Mon, Sep 14, 2015 at 02:15:39PM +0200, Petr Cech wrote:
> > > From 4246d5cd91c4c34b8524be5bfce38c57163a6e2b Mon Sep 17 00:00:00 2001
> > > From: Lukas Slebodnik
> > > Date: Fri, 11 Sep 2015 17:04:58 +0200
> > > Subject: [PATCH] squash_me
> > >
> > > Makefile.am                        | 2 +-
> > >   src/providers/ipa/ipa_hbac.exports | 8 ++++++--
> > >   2 files changed, 7 insertions(+), 3 deletions(-)
> > >
> > > diff --git a/Makefile.am b/Makefile.am
> > > index 851f943a4c57b70cee4f4f34e83457e7d204aff1..a2a868455f91fac212fcfa7b41681086145c06f9 100644
> > > --- a/Makefile.am
> > > +++ b/Makefile.am
> > > @@ -928,7 +928,7 @@ libipa_hbac_la_LIBADD = \
> > >       $(UNICODE_LIBS)
> > >   libipa_hbac_la_LDFLAGS = \
> > >       -Wl,--version-script,$(srcdir)/src/providers/ipa/ipa_hbac.exports \
> > > -version-info 0:1:0
> > > -version-info 1:0:1
> >
> > Lukas, are you sure this version number 1:0:1? If you're really sure this
> > number, I have not understood it properly.
>
> I have not read the patch at all, just adding a link about version info

[1]
>  https://www.gnu.org/software/libtool/manual/libtool.html#Updating-version-info
>
> The trick to follow this guide is that it's really an algorithm, so you
> shouldn't stop at the first change, but continue (potentially reverting
> or overwriting previous changes)
> _______________________________________________
> sssd-devel mailing list
> [e-mail]
> https://lists.fedorahosted.org/mailman/listinfo/sssd-devel

I understand, how we changed -version-info (it is exactly by steps as 
described in [1]), but I don't understand clearly changes in .exports.
Petr

[Lukas Slebodnik]

On (15/09/15 09:54), Petr Cech wrote:
> On 09/14/2015 03:25 PM, Jakub Hrozek wrote:
> > On Mon, Sep 14, 2015 at 02:15:39PM +0200, Petr Cech wrote:
> > > > From 4246d5cd91c4c34b8524be5bfce38c57163a6e2b Mon Sep 17 00:00:00 2001
> > > > From: Lukas Slebodnik
> > > > Date: Fri, 11 Sep 2015 17:04:58 +0200
> > > > Subject: [PATCH] squash_me
> > > >
> > > > Makefile.am                        | 2 +-
> > > >  src/providers/ipa/ipa_hbac.exports | 8 ++++++--
> > > >  2 files changed, 7 insertions(+), 3 deletions(-)
> > > >
> > > > diff --git a/Makefile.am b/Makefile.am
> > > > index 851f943a4c57b70cee4f4f34e83457e7d204aff1..a2a868455f91fac212fcfa7b41681086145c06f9 100644
> > > > --- a/Makefile.am
> > > > +++ b/Makefile.am
> > > > @@ -928,7 +928,7 @@ libipa_hbac_la_LIBADD = \
> > > >      $(UNICODE_LIBS)
> > > >  libipa_hbac_la_LDFLAGS = \
> > > >      -Wl,--version-script,$(srcdir)/src/providers/ipa/ipa_hbac.exports \
> > > > -version-info 0:1:0
> > > > -version-info 1:0:1
> > >
> > > Lukas, are you sure this version number 1:0:1? If you're really sure this
> > > number, I have not understood it properly.

You might also look into generated library name for old version-info and for
new version-info. The SONAME should be the same.

sh$ objdump -p /lib64/libipa_hbac.so | grep SONAME
  SONAME               libipa_hbac.so.0
> > I have not read the patch at all, just adding a link about version info
>
> [1]
> > https://www.gnu.org/software/libtool/manual/libtool.html#Updating-version-info
> >
> > The trick to follow this guide is that it's really an algorithm, so you
> > shouldn't stop at the first change, but continue (potentially reverting
> > or overwriting previous changes)
>
> I understand, how we changed -version-info (it is exactly by steps as
> described in [1]), but I don't understand clearly changes in .exports.
> Petr

because there was a copy&paste bug in diff.
As I wrote in previous mail; new function should not be added
to old version block.

I'm sorry for confusion.

//slightly offtopic
hbac_evaluate could be in oth section IPA_HBAC_0.0.1 and IPA_HBAC_0.1.0.
But it is used mainly in cases if you want to introduce backward incompatible
changes and do not break old behaviour. It is described in dso document.

One of examples is in glibc

sh$ objdump -T /lib64/libc.so.6 | grep " memcpy"
00000000000936d0 g   iD  .text  0000000000000051  GLIBC_2.14  memcpy
000000000008e48b g   iD  .text  0000000000000051 (GLIBC_2.2.5) memcpy

diff --git a/src/providers/ipa/ipa_hbac.exports b/src/providers/ipa/ipa_hbac.exports
index 63b6a5cd673d7b7f3096794648483d280a6bb47f..b7945e139b9ab81b7c1d68eb707acaaff7163a2e 100644
--- a/src/providers/ipa/ipa_hbac.exports
+++ b/src/providers/ipa/ipa_hbac.exports
@@ -1,4 +1,4 @@
-IPA_HBAC_0.0.2 {
+IPA_HBAC_0.0.1 {

# public functions
     global:
@@ -8,9 +8,13 @@ IPA_HBAC_0.0.2 {
         hbac_error_string;
         hbac_free_info;
         hbac_rule_is_complete;
-        hbac_enable_debug;

# everything else is local
     local:
         *;
 };
+
+IPA_HBAC_0.1.0 {
+    global:
+        hbac_enable_debug;
+} IPA_HBAC_0.0.1;

LS

[Petr Cech]

Hello,

there are fixed patches attached.

On 09/18/2015 11:08 AM, Lukas Slebodnik wrote:
> > > > > > >>>-    -version-info 0:1:0
> > > > > > >>>+    -version-info 1:0:1
> > > > > > >Lukas, are you sure this version number 1:0:1? If you're really sure this
> > > > > > >number, I have not understood it properly.
>
> You might also look into generated library name for old version-info and for
> new version-info. The SONAME should be the same.
>
> sh$ objdump -p /lib64/libipa_hbac.so | grep SONAME
>    SONAME               libipa_hbac.so.0

I checked it, thanks.
> > > > > I have not read the patch at all, just adding a link about version info
> > >
> > > [1]
> > > > > https://www.gnu.org/software/libtool/manual/libtool.html#Updating-version-info
> > > > >
> > > > > The trick to follow this guide is that it's really an algorithm, so you
> > > > > shouldn't stop at the first change, but continue (potentially reverting
> > > > > or overwriting previous changes)
> > >
> > > I understand, how we changed -version-info (it is exactly by steps as
> > > described in [1]), but I don't understand clearly changes in .exports.
> > > Petr
>
> because there was a copy&paste bug in diff.

Well, it's OK. I was afraid that I didn't understand anything.
> As I wrote in previous mail; new function should not be added
> to old version block.

It looks more clear for me now.

Petr

[Petr Cech]

On 09/18/2015 04:30 PM, Petr Cech wrote:
> Hello,
>
> there are fixed patches attached.

Bump.

[Michal Židek]

On 10/01/2015 12:37 PM, Petr Cech wrote:
> On 09/18/2015 04:30 PM, Petr Cech wrote:
> > Hello,
> >
> > there are fixed patches attached.
>
> Bump.

The code was already acked by PavelR, the
only problem was with the version info change
and the version script.

I checked the last iteration and both
version info and version script are correct
now.

Will give the patches last run through CI
before acking.

Michal

[Pavel Reichl]

On 10/01/2015 12:59 PM, Michal Židek wrote:
> On 10/01/2015 12:37 PM, Petr Cech wrote:
> > On 09/18/2015 04:30 PM, Petr Cech wrote:
> > > Hello,
> > >
> > > there are fixed patches attached.
> >
> > Bump.
>
> The code was already acked by PavelR, the
> only problem was with the version info change
> and the version script.
>
> I checked the last iteration and both
> version info and version script are correct
> now.

Thanks for doing that Michal!
> Will give the patches last run through CI
> before acking.
>
> Michal
> _______________________________________________
> sssd-devel mailing list
> [e-mail]
> https://lists.fedorahosted.org/mailman/listinfo/sssd-devel

[Michal Židek]

On 10/01/2015 01:03 PM, Pavel Reichl wrote:
> On 10/01/2015 12:59 PM, Michal Židek wrote:
> > On 10/01/2015 12:37 PM, Petr Cech wrote:
> > > On 09/18/2015 04:30 PM, Petr Cech wrote:
> > > > Hello,
> > > >
> > > > there are fixed patches attached.
> > >
> > > Bump.
> >
> > The code was already acked by PavelR, the
> > only problem was with the version info change
> > and the version script.
> >
> > I checked the last iteration and both
> > version info and version script are correct
> > now.
>
> Thanks for doing that Michal!
> > Will give the patches last run through CI
> > before acking.
> >
> > Michal

Link to CI:
http://sssd-ci.duckdns.org/logs/job/28/25/summary.html

Ack.

Michal

[Jakub Hrozek]

On Thu, Oct 01, 2015 at 01:40:34PM +0200, Michal Židek wrote:
> On 10/01/2015 01:03 PM, Pavel Reichl wrote:
> > On 10/01/2015 12:59 PM, Michal Židek wrote:
> > > On 10/01/2015 12:37 PM, Petr Cech wrote:
> > > > On 09/18/2015 04:30 PM, Petr Cech wrote:
> > > > > Hello,
> > > > >
> > > > > there are fixed patches attached.
> > > >
> > > > Bump.
> > >
> > > The code was already acked by PavelR, the
> > > only problem was with the version info change
> > > and the version script.
> > >
> > > I checked the last iteration and both
> > > version info and version script are correct
> > > now.
> >
> > Thanks for doing that Michal!
> > > Will give the patches last run through CI
> > > before acking.
> > >
> > > Michal
>
> Link to CI:
> http://sssd-ci.duckdns.org/logs/job/28/25/summary.html
>
> Ack.
>
> Michal

* master:
 * e1622d0d430a2ae4fca4fe4f9a83caf95500a853
 * 65ce66c43141f7e5c8482a8f8e7e217a23791588

[Pavel Reichl]

On 08/26/2015 09:44 AM, Petr Cech wrote:
> +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;
>    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;
> }

Please add default here (http://www.freeipa.org/page/Coding_Style#Switch)
> 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);
>
> +}