SECRETS: Add DEBUG messages to the sssd-secrets provider

Previously, it was not possible to follow the flow of the secrets
responder or find out what went wrong on error. This patch adds DEBUG
messages so that most failure cases have their own message. At the same
time, running sssd-secrets with debug_level <= 3 does not emit any
messages at all.

Reviewed-by: Fabiano Fidêncio <fidencio@redhat.com>

4 files changed, 441 insertions, 59 deletions

diff --git a/src/responder/secrets/local.c b/src/responder/secrets/local.c
index ec8453798..295001c16 100644
--- a/src/responder/secrets/local.c
+++ b/src/responder/secrets/local.c
@@ -39,23 +39,34 @@ static int local_decrypt(struct local_context *lctx, TALLOC_CTX *mem_ctx,
     char *output;
 
     if (enctype && strcmp(enctype, "masterkey") == 0) {
+        DEBUG(SSSDBG_TRACE_INTERNAL, "Decrypting with masterkey\n");
+
         struct sec_data _secret;
         size_t outlen;
         int ret;
 
         _secret.data = (char *)sss_base64_decode(mem_ctx, secret,
                                                  &_secret.length);
-        if (!_secret.data) return EINVAL;
+        if (!_secret.data) {
+            DEBUG(SSSDBG_OP_FAILURE, "sss_base64_decode failed\n");
+            return EINVAL;
+        }
 
         ret = sss_decrypt(mem_ctx, AES256CBC_HMAC_SHA256,
                           (uint8_t *)lctx->master_key.data,
                           lctx->master_key.length,
                           (uint8_t *)_secret.data, _secret.length,
                           (uint8_t **)&output, &outlen);
-        if (ret) return ret;
+        if (ret) {
+            DEBUG(SSSDBG_OP_FAILURE,
+                  "sss_decrypt failed [%d]: %s\n", ret, sss_strerror(ret));
+            return ret;
+        }
 
         if (((strnlen(output, outlen) + 1) != outlen) ||
             output[outlen - 1] != '\0') {
+            DEBUG(SSSDBG_CRIT_FAILURE,
+                  "Output length mismatch or output not NULL-terminated\n");
             return EIO;
         }
     } else {
@@ -75,14 +86,26 @@ static int local_encrypt(struct local_context *lctx, TALLOC_CTX *mem_ctx,
     char *output;
     int ret;
 
-    if (!enctype || strcmp(enctype, "masterkey") != 0) return EINVAL;
+    if (enctype == NULL) {
+        DEBUG(SSSDBG_CRIT_FAILURE, "No encryption type\n");
+        return EINVAL;
+    }
+
+    if (strcmp(enctype, "masterkey") != 0) {
+        DEBUG(SSSDBG_CRIT_FAILURE, "Uknown encryption type '%s'\n", enctype);
+        return EINVAL;
+    }
 
     ret = sss_encrypt(mem_ctx, AES256CBC_HMAC_SHA256,
                       (uint8_t *)lctx->master_key.data,
                       lctx->master_key.length,
                       (const uint8_t *)secret, strlen(secret) + 1,
                       (uint8_t **)&_secret.data, &_secret.length);
-    if (ret) return ret;
+    if (ret) {
+        DEBUG(SSSDBG_OP_FAILURE,
+              "sss_encrypt failed [%d]: %s\n", ret, sss_strerror(ret));
+        return ret;
+    }
 
     output = sss_base64_encode(mem_ctx,
                                (uint8_t *)_secret.data, _secret.length);
@@ -130,6 +153,9 @@ static int local_db_dn(TALLOC_CTX *mem_ctx,
         }
     }
 
+    DEBUG(SSSDBG_TRACE_INTERNAL,
+          "Local path for [%s] is [%s]\n",
+          req_path, ldb_dn_get_linearized(dn));
     *req_dn = dn;
     ret = EOK;
 
@@ -165,6 +191,9 @@ static char *local_dn_to_path(TALLOC_CTX *mem_ctx,
         if (!path) return NULL;
     }
 
+    DEBUG(SSSDBG_TRACE_INTERNAL,
+          "Secrets path for [%s] is [%s]\n",
+          ldb_dn_get_linearized(dn), path);
     return path;
 }
 
@@ -184,32 +213,48 @@ static int local_db_get_simple(TALLOC_CTX *mem_ctx,
     const char *attr_enctype;
     int ret;
 
+    DEBUG(SSSDBG_TRACE_FUNC, "Retrieving a secret from [%s]\n", req_path);
+
     tmp_ctx = talloc_new(mem_ctx);
     if (!tmp_ctx) return ENOMEM;
 
     ret = local_db_dn(tmp_ctx, lctx->ldb, req_path, &dn);
-    if (ret != EOK) goto done;
+    if (ret != EOK) {
+        DEBUG(SSSDBG_OP_FAILURE,
+              "local_db_dn failed [%d]: %s\n", ret, sss_strerror(ret));
+        goto done;
+    }
+
+    DEBUG(SSSDBG_TRACE_INTERNAL,
+          "Searching for [%s] at [%s] with scope=base\n",
+          LOCAL_SIMPLE_FILTER, ldb_dn_get_linearized(dn));
 
     ret = ldb_search(lctx->ldb, tmp_ctx, &res, dn, LDB_SCOPE_BASE,
                      attrs, "%s", LOCAL_SIMPLE_FILTER);
     if (ret != EOK) {
+        DEBUG(SSSDBG_TRACE_LIBS,
+              "ldb_search returned [%d]: %s\n", ret, ldb_strerror(ret));
         ret = ENOENT;
         goto done;
     }
 
     switch (res->count) {
     case 0:
+        DEBUG(SSSDBG_TRACE_LIBS, "No secret found\n");
         ret = ENOENT;
         goto done;
     case 1:
         break;
     default:
+        DEBUG(SSSDBG_OP_FAILURE,
+              "Too many secrets returned with BASE search\n");
         ret = E2BIG;
         goto done;
     }
 
     attr_secret = ldb_msg_find_attr_as_string(res->msgs[0], "secret", NULL);
     if (!attr_secret) {
+        DEBUG(SSSDBG_CRIT_FAILURE, "The 'secret' attribute is missing\n");
         ret = ENOENT;
         goto done;
     }
@@ -245,17 +290,30 @@ static int local_db_list_keys(TALLOC_CTX *mem_ctx,
     tmp_ctx = talloc_new(mem_ctx);
     if (!tmp_ctx) return ENOMEM;
 
+    DEBUG(SSSDBG_TRACE_FUNC, "Listing keys at [%s]\n", req_path);
+
     ret = local_db_dn(tmp_ctx, lctx->ldb, req_path, &dn);
-    if (ret != EOK) goto done;
+    if (ret != EOK) {
+        DEBUG(SSSDBG_OP_FAILURE,
+              "local_db_dn failed [%d]: %s\n", ret, sss_strerror(ret));
+        goto done;
+    }
+
+    DEBUG(SSSDBG_TRACE_INTERNAL,
+          "Searching for [%s] at [%s] with scope=subtree\n",
+          LOCAL_SIMPLE_FILTER, ldb_dn_get_linearized(dn));
 
     ret = ldb_search(lctx->ldb, tmp_ctx, &res, dn, LDB_SCOPE_SUBTREE,
                      attrs, "%s", LOCAL_SIMPLE_FILTER);
     if (ret != EOK) {
+        DEBUG(SSSDBG_TRACE_LIBS,
+              "ldb_search returned [%d]: %s\n", ret, ldb_strerror(ret));
         ret = ENOENT;
         goto done;
     }
 
     if (res->count == 0) {
+        DEBUG(SSSDBG_TRACE_LIBS, "No secrets found\n");
         ret = ENOENT;
         goto done;
     }
@@ -275,6 +333,7 @@ static int local_db_list_keys(TALLOC_CTX *mem_ctx,
     }
 
     *_keys = keys;
+    DEBUG(SSSDBG_TRACE_LIBS, "Returning %d secrets\n", res->count);
     *num_keys = res->count;
     ret = EOK;
 
@@ -314,15 +373,16 @@ static int local_db_check_containers(TALLOC_CTX *mem_ctx,
         if (!ldb_dn_remove_child_components(dn, 1)) return EFAULT;
 
         /* and check the parent container exists */
+        DEBUG(SSSDBG_TRACE_INTERNAL,
+              "Searching for [%s] at [%s] with scope=base\n",
+              LOCAL_CONTAINER_FILTER, ldb_dn_get_linearized(dn));
+
         ret = ldb_search(lctx->ldb, tmp_ctx, &res, dn, LDB_SCOPE_BASE,
                          attrs, LOCAL_CONTAINER_FILTER);
-        if (ret != LDB_SUCCESS) {
-            ret = ENOENT;
-            goto done;
-        }
-        if (res->count != 1) {
-            ret = ENOENT;
-            goto done;
+        if (ret != LDB_SUCCESS || res->count != 1) {
+            DEBUG(SSSDBG_TRACE_LIBS,
+                  "DN [%s] does not exist\n", ldb_dn_get_linearized(dn));
+            return ENOENT;
         }
     }
 
@@ -369,37 +429,80 @@ static int local_db_put_simple(TALLOC_CTX *mem_ctx,
         goto done;
     }
 
+    DEBUG(SSSDBG_TRACE_FUNC, "Adding a secret to [%s]\n", req_path);
+
     ret = local_db_dn(msg, lctx->ldb, req_path, &msg->dn);
-    if (ret != EOK) goto done;
+    if (ret != EOK) {
+        DEBUG(SSSDBG_OP_FAILURE,
+              "local_db_dn failed [%d]: %s\n", ret, sss_strerror(ret));
+        goto done;
+    }
 
     /* make sure containers exist */
     ret = local_db_check_containers(msg, lctx, msg->dn);
-    if (ret != EOK) goto done;
+    if (ret != EOK) {
+        DEBUG(SSSDBG_OP_FAILURE,
+              "local_db_check_containers failed for [%s]: [%d]: %s\n",
+              ldb_dn_get_linearized(msg->dn), ret, sss_strerror(ret));
+        goto done;
+    }
 
     ret = local_encrypt(lctx, msg, secret, enctype, &enc_secret);
-    if (ret != EOK) goto done;
+    if (ret != EOK) {
+        DEBUG(SSSDBG_OP_FAILURE,
+              "local_encrypt failed [%d]: %s\n", ret, sss_strerror(ret));
+        goto done;
+    }
 
     ret = ldb_msg_add_string(msg, "type", "simple");
-    if (ret != EOK) goto done;
+    if (ret != EOK) {
+        DEBUG(SSSDBG_OP_FAILURE,
+              "ldb_msg_add_string failed adding type:simple [%d]: %s\n",
+              ret, sss_strerror(ret));
+        goto done;
+    }
 
     ret = ldb_msg_add_string(msg, "enctype", enctype);
-    if (ret != EOK) goto done;
+    if (ret != EOK) {
+        DEBUG(SSSDBG_OP_FAILURE,
+              "ldb_msg_add_string failed adding enctype [%d]: %s\n",
+              ret, sss_strerror(ret));
+        goto done;
+    }
 
     ret = ldb_msg_add_string(msg, "secret", enc_secret);
-    if (ret != EOK) goto done;
+    if (ret != EOK) {
+        DEBUG(SSSDBG_OP_FAILURE,
+              "ldb_msg_add_string failed adding secret [%d]: %s\n",
+              ret, sss_strerror(ret));
+        goto done;
+    }
+
 
     ret = ldb_msg_add_fmt(msg, "creationTime", "%lu", time(NULL));
-    if (ret != EOK) goto done;
+    if (ret != EOK) {
+        DEBUG(SSSDBG_OP_FAILURE,
+              "ldb_msg_add_string failed adding creationTime [%d]: %s\n",
+              ret, sss_strerror(ret));
+        goto done;
+    }
 
     ret = ldb_add(lctx->ldb, msg);
     if (ret != EOK) {
-        if (ret == LDB_ERR_ENTRY_ALREADY_EXISTS) ret = EEXIST;
-        else ret = EIO;
+        if (ret == LDB_ERR_ENTRY_ALREADY_EXISTS) {
+            DEBUG(SSSDBG_OP_FAILURE,
+                  "Secret %s already exists\n", ldb_dn_get_linearized(msg->dn));
+            ret = EEXIST;
+        } else {
+            DEBUG(SSSDBG_CRIT_FAILURE,
+                  "Failed to add secret [%s]: [%d]: %s\n",
+                  ldb_dn_get_linearized(msg->dn), ret, ldb_strerror(ret));
+            ret = EIO;
+        }
         goto done;
     }
 
     ret = EOK;
-
 done:
     talloc_free(msg);
     return ret;
@@ -415,20 +518,40 @@ static int local_db_delete(TALLOC_CTX *mem_ctx,
     struct ldb_result *res;
     int ret;
 
+    DEBUG(SSSDBG_TRACE_FUNC, "Removing a secret from [%s]\n", req_path);
+
     tmp_ctx = talloc_new(mem_ctx);
     if (!tmp_ctx) return ENOMEM;
 
     ret = local_db_dn(mem_ctx, lctx->ldb, req_path, &dn);
-    if (ret != EOK) goto done;
+    if (ret != EOK) {
+        DEBUG(SSSDBG_OP_FAILURE,
+              "local_db_dn failed [%d]: %s\n", ret, sss_strerror(ret));
+        goto done;
+    }
+
+    DEBUG(SSSDBG_TRACE_INTERNAL,
+          "Searching for [%s] at [%s] with scope=base\n",
+          LOCAL_CONTAINER_FILTER, ldb_dn_get_linearized(dn));
 
     ret = ldb_search(lctx->ldb, tmp_ctx, &res, dn, LDB_SCOPE_BASE,
                     attrs, LOCAL_CONTAINER_FILTER);
-    if (ret != EOK) goto done;
+    if (ret != EOK) {
+        DEBUG(SSSDBG_TRACE_LIBS,
+              "ldb_search returned %d: %s\n", ret, ldb_strerror(ret));
+        goto done;
+    }
 
     if (res->count == 1) {
+        DEBUG(SSSDBG_TRACE_INTERNAL,
+              "Searching for children of [%s]\n", ldb_dn_get_linearized(dn));
         ret = ldb_search(lctx->ldb, tmp_ctx, &res, dn, LDB_SCOPE_ONELEVEL,
                          attrs, NULL);
-        if (ret != EOK) goto done;
+        if (ret != EOK) {
+            DEBUG(SSSDBG_TRACE_LIBS,
+                  "ldb_search returned %d: %s\n", ret, ldb_strerror(ret));
+            goto done;
+        }
 
         if (res->count > 0) {
             ret = EEXIST;
@@ -441,6 +564,11 @@ static int local_db_delete(TALLOC_CTX *mem_ctx,
     }
 
     ret = ldb_delete(lctx->ldb, dn);
+    if (ret != EOK) {
+        DEBUG(SSSDBG_TRACE_LIBS,
+              "ldb_delete returned %d: %s\n", ret, ldb_strerror(ret));
+        /* fallthrough */
+    }
     ret = sysdb_error_to_errno(ret);
 
 done:
@@ -461,26 +589,55 @@ static int local_db_create(TALLOC_CTX *mem_ctx,
         goto done;
     }
 
+    DEBUG(SSSDBG_TRACE_FUNC, "Creating a container at [%s]\n", req_path);
+
     ret = local_db_dn(msg, lctx->ldb, req_path, &msg->dn);
-    if (ret != EOK) goto done;
+    if (ret != EOK) {
+        DEBUG(SSSDBG_OP_FAILURE,
+              "local_db_dn failed [%d]: %s\n", ret, sss_strerror(ret));
+        goto done;
+    }
 
     /* make sure containers exist */
     ret = local_db_check_containers(msg, lctx, msg->dn);
-    if (ret != EOK) goto done;
+    if (ret != EOK) {
+        DEBUG(SSSDBG_OP_FAILURE,
+              "local_db_check_containers failed for [%s]: [%d]: %s\n",
+              ldb_dn_get_linearized(msg->dn), ret, sss_strerror(ret));
+        goto done;
+    }
 
     ret = local_db_check_containers_nest_level(lctx, msg->dn);
     if (ret != EOK) goto done;
 
     ret = ldb_msg_add_string(msg, "type", "container");
-    if (ret != EOK) goto done;
+    if (ret != EOK) {
+        DEBUG(SSSDBG_OP_FAILURE,
+              "ldb_msg_add_string failed adding type:container [%d]: %s\n",
+              ret, sss_strerror(ret));
+        goto done;
+    }
 
     ret = ldb_msg_add_fmt(msg, "creationTime", "%lu", time(NULL));
-    if (ret != EOK) goto done;
+    if (ret != EOK) {
+        DEBUG(SSSDBG_OP_FAILURE,
+              "ldb_msg_add_string failed adding creationTime [%d]: %s\n",
+              ret, sss_strerror(ret));
+        goto done;
+    }
 
     ret = ldb_add(lctx->ldb, msg);
     if (ret != EOK) {
-        if (ret == LDB_ERR_ENTRY_ALREADY_EXISTS) ret = EEXIST;
-        else ret = EIO;
+        if (ret == LDB_ERR_ENTRY_ALREADY_EXISTS) {
+            DEBUG(SSSDBG_OP_FAILURE,
+                  "Secret %s already exists\n", ldb_dn_get_linearized(msg->dn));
+            ret = EEXIST;
+        } else {
+            DEBUG(SSSDBG_CRIT_FAILURE,
+                  "Failed to add secret [%s]: [%d]: %s\n",
+                  ldb_dn_get_linearized(msg->dn), ret, ldb_strerror(ret));
+            ret = EIO;
+        }
         goto done;
     }
 
@@ -532,6 +689,7 @@ static int local_secrets_map_path(TALLOC_CTX *mem_ctx,
         return ENOMEM;
     }
 
+    DEBUG(SSSDBG_TRACE_LIBS, "Local DB path is %s\n", *local_db_path);
     return EOK;
 }
 
@@ -571,6 +729,8 @@ static struct tevent_req *local_secret_req(TALLOC_CTX *mem_ctx,
         goto done;
     }
 
+    DEBUG(SSSDBG_TRACE_INTERNAL, "Received a local secrets request\n");
+
     if (sec_req_has_header(secreq, "Content-Type",
                                   "application/json")) {
         body_is_json = true;
@@ -580,15 +740,18 @@ static struct tevent_req *local_secret_req(TALLOC_CTX *mem_ctx,
         body_is_json = false;
         content_type = "application/octet-stream";
     } else {
+        DEBUG(SSSDBG_OP_FAILURE, "No or uknown Content-Type\n");
         ret = EINVAL;
         goto done;
     }
+    DEBUG(SSSDBG_TRACE_LIBS, "Content-Type: %s\n", content_type);
 
     ret = local_secrets_map_path(state, secreq, &req_path);
     if (ret) goto done;
 
     switch (secreq->method) {
     case HTTP_GET:
+        DEBUG(SSSDBG_TRACE_LIBS, "Processing HTTP GET at [%s]\n", req_path);
         if (req_path[strlen(req_path) - 1] == '/') {
             ret = local_db_list_keys(state, lctx, req_path, &keys, &nkeys);
             if (ret) goto done;
@@ -617,6 +780,7 @@ static struct tevent_req *local_secret_req(TALLOC_CTX *mem_ctx,
         break;
 
     case HTTP_PUT:
+        DEBUG(SSSDBG_TRACE_LIBS, "Processing HTTP PUT at [%s]\n", req_path);
         if (body_is_json) {
             ret = sec_json_to_simple_secret(state, secreq->body.data,
                                             &secret);
@@ -637,6 +801,7 @@ static struct tevent_req *local_secret_req(TALLOC_CTX *mem_ctx,
         break;
 
     case HTTP_POST:
+        DEBUG(SSSDBG_TRACE_LIBS, "Processing HTTP POST at [%s]\n", req_path);
         plen = strlen(req_path);
 
         if (req_path[plen - 1] != '/') {
@@ -664,10 +829,18 @@ static struct tevent_req *local_secret_req(TALLOC_CTX *mem_ctx,
 
 done:
     if (ret != EOK) {
+        if (ret == ENOENT) {
+            DEBUG(SSSDBG_TRACE_LIBS, "Did not find the requested data\n");
+        } else {
+            DEBUG(SSSDBG_OP_FAILURE,
+                  "Local secrets request error [%d]: %s\n",
+                  ret, sss_strerror(ret));
+        }
         tevent_req_error(req, ret);
     } else {
         /* shortcircuit the request here as all called functions are
          * synchronous and final and no further subrequests are made */
+        DEBUG(SSSDBG_TRACE_INTERNAL, "Local secrets request done\n");
         tevent_req_done(req);
     }
     return tevent_req_post(req, state->ev);
@@ -681,14 +854,30 @@ static int generate_master_key(const char *filename, size_t size)
     int fd;
 
     ret = generate_csprng_buffer(buf, size);
-    if (ret) return ret;
+    if (ret) {
+        DEBUG(SSSDBG_OP_FAILURE,
+              "generate_csprng_buffer failed [%d]: %s\n",
+              ret, sss_strerror(ret));
+        return ret;
+    }
 
     fd = open(filename, O_CREAT|O_EXCL|O_WRONLY, 0600);
-    if (fd == -1) return errno;
+    if (fd == -1) {
+        ret = errno;
+        DEBUG(SSSDBG_OP_FAILURE,
+              "open(%s) failed [%d]: %s\n",
+              filename, ret, strerror(ret));
+        return ret;
+    }
 
     rsize = sss_atomic_write_s(fd, buf, size);
     close(fd);
     if (rsize != size) {
+        ret = errno;
+        DEBUG(SSSDBG_OP_FAILURE,
+              "sss_atomic_write_s failed [%d]: %s\n",
+              ret, strerror(ret));
+
         ret = unlink(filename);
         /* non-fatal failure */
         if (ret != EOK) {
@@ -714,6 +903,8 @@ int local_secrets_provider_handle(struct sec_ctx *sctx,
     int mfd;
     int ret;
 
+    DEBUG(SSSDBG_TRACE_INTERNAL, "Creating a local provider handle\n");
+
     handle = talloc_zero(sctx, struct provider_handle);
     if (!handle) return ENOMEM;
 
@@ -728,6 +919,9 @@ int local_secrets_provider_handle(struct sec_ctx *sctx,
 
     ret = ldb_connect(lctx->ldb, dbpath, 0, NULL);
     if (ret != LDB_SUCCESS) {
+        DEBUG(SSSDBG_TRACE_LIBS,
+              "ldb_connect(%s) returned %d: %s\n",
+              dbpath, ret, ldb_strerror(ret));
         talloc_free(lctx->ldb);
         return EIO;
     }
@@ -741,20 +935,29 @@ int local_secrets_provider_handle(struct sec_ctx *sctx,
     ret = check_and_open_readonly(mkey, &mfd, 0, 0,
                                   S_IFREG|S_IRUSR|S_IWUSR, 0);
     if (ret == ENOENT) {
+        DEBUG(SSSDBG_TRACE_FUNC, "No master key, generating a new one..\n");
+
         ret = generate_master_key(mkey, MKEY_SIZE);
         if (ret) return EFAULT;
         ret = check_and_open_readonly(mkey, &mfd, 0, 0,
                                       S_IFREG|S_IRUSR|S_IWUSR, 0);
     }
-    if (ret) return EFAULT;
+    if (ret) {
+        DEBUG(SSSDBG_OP_FAILURE, "Cannot generate a master key: %d\n", ret);
+        return EFAULT;
+    }
 
     size = sss_atomic_read_s(mfd, lctx->master_key.data,
                              lctx->master_key.length);
     close(mfd);
-    if (size < 0 || size != lctx->master_key.length) return EIO;
+    if (size < 0 || size != lctx->master_key.length) {
+        DEBUG(SSSDBG_OP_FAILURE, "Cannot read a master key: %d\n", ret);
+        return EIO;
+    }
 
     handle->context = lctx;
 
     *out_handle = handle;
+    DEBUG(SSSDBG_TRACE_INTERNAL, "Local provider handle created\n");
     return EOK;
 }
diff --git a/src/responder/secrets/providers.c b/src/responder/secrets/providers.c
index aedb49a15..404d08277 100644
--- a/src/responder/secrets/providers.c
+++ b/src/responder/secrets/providers.c
@@ -42,6 +42,7 @@ static int sec_map_url_to_user_path(struct sec_req_ctx *secreq,
         return ENOMEM;
     }
 
+    DEBUG(SSSDBG_TRACE_LIBS, "User-specific path is [%s]\n", *mapped_path);
     return EOK;
 }
 
@@ -76,11 +77,18 @@ int sec_req_routing(TALLOC_CTX *mem_ctx, struct sec_req_ctx *secreq,
                             &def_provider);
     if (ret) return EIO;
 
+    DEBUG(SSSDBG_TRACE_INTERNAL,
+          "The default provider is '%s'\n", def_provider);
+
     ret = confdb_get_sub_sections(mem_ctx, secreq->cctx->rctx->cdb,
                                   CONFDB_SEC_CONF_ENTRY, &sections,
                                   &num_sections);
     if (ret != EOK) return ret;
 
+    DEBUG(SSSDBG_TRACE_INTERNAL,
+          "confdb section %s has %d sub-sections\n",
+          CONFDB_SEC_CONF_ENTRY, num_sections);
+
     provider = def_provider;
 
     // TODO order by length ?
@@ -91,6 +99,9 @@ int sec_req_routing(TALLOC_CTX *mem_ctx, struct sec_req_ctx *secreq,
         if (!secreq->base_path) return ENOMEM;
         slen = strlen(secreq->base_path);
 
+        DEBUG(SSSDBG_TRACE_INTERNAL,
+              "matching subsection [%s]\n", sections[i]);
+
         if (strncmp(secreq->base_path, secreq->mapped_path, slen) == 0) {
             char *secname;
 
@@ -104,6 +115,10 @@ int sec_req_routing(TALLOC_CTX *mem_ctx, struct sec_req_ctx *secreq,
                                     &provider);
             if (ret || !provider) return EIO;
 
+            DEBUG(SSSDBG_TRACE_INTERNAL,
+                  "matched subsection %s with provider %s\n",
+                  sections[i], provider);
+
             secreq->cfg_section = talloc_steal(secreq, secname);
             if (!secreq->cfg_section) return ENOMEM;
             break;
@@ -113,6 +128,11 @@ int sec_req_routing(TALLOC_CTX *mem_ctx, struct sec_req_ctx *secreq,
 
     if (!secreq->base_path) secreq->base_path = SEC_BASEPATH;
 
+    DEBUG(SSSDBG_TRACE_INTERNAL,
+          "Request base path is [%s]\n", secreq->base_path);
+    DEBUG(SSSDBG_TRACE_INTERNAL,
+          "Request provider is [%s]\n", provider);
+
     ret = sec_get_provider(sctx, provider, handle);
     if (ret == ENOENT) {
         if (strcasecmp(provider, "LOCAL") == 0) {
@@ -134,6 +154,7 @@ int sec_req_routing(TALLOC_CTX *mem_ctx, struct sec_req_ctx *secreq,
 
 int sec_provider_recv(struct tevent_req *req) {
     TEVENT_REQ_RETURN_ON_ERROR(req);
+    DEBUG(SSSDBG_TRACE_INTERNAL, "Request finished\n");
     return EOK;
 }
 
@@ -191,6 +212,11 @@ int sec_http_status_reply(TALLOC_CTX *mem_ctx, struct sec_data *reply,
 
     reply->length = strlen(reply->data);
 
+    DEBUG(SSSDBG_TRACE_LIBS,
+          "HTTP reply %d: %s\n",
+          sec_http_status_format_table[code].status,
+          sec_http_status_format_table[code].text);
+
     return EOK;
 }
 
@@ -220,6 +246,11 @@ int sec_http_reply_with_body(TALLOC_CTX *mem_ctx, struct sec_data *reply,
     memcpy(&reply->data[head_size], body->data, body->length);
     reply->length = head_size + body->length;
 
+    DEBUG(SSSDBG_TRACE_LIBS,
+          "HTTP reply %d: %s\n",
+          sec_http_status_format_table[code].status,
+          sec_http_status_format_table[code].text);
+
     return EOK;
 }
 
@@ -252,6 +283,8 @@ int sec_http_reply_with_headers(TALLOC_CTX *mem_ctx, struct sec_data *reply,
                                   status_code, reason_phrase);
     if (!reply->data) return ENOMEM;
 
+    DEBUG(SSSDBG_TRACE_LIBS, "HTTP reply %d: %s\n", status_code, reason_phrase);
+
     /* Headers */
     for (int i = 0; i < num_headers; i++) {
         if (strcasecmp(headers[i].name, "Content-Length") == 0) {
@@ -264,7 +297,10 @@ int sec_http_reply_with_headers(TALLOC_CTX *mem_ctx, struct sec_data *reply,
         if (ret) return ret;
     }
 
-    if (!has_content_type) return EINVAL;
+    if (!has_content_type) {
+        DEBUG(SSSDBG_OP_FAILURE, "No Content-Type header\n");
+        return EINVAL;
+    }
 
     if (add_content_length) {
         reply->data = talloc_asprintf_append_buffer(reply->data,
@@ -292,6 +328,8 @@ int sec_http_reply_with_headers(TALLOC_CTX *mem_ctx, struct sec_data *reply,
 
 enum sec_http_status_codes sec_errno_to_http_status(errno_t err)
 {
+    DEBUG(SSSDBG_TRACE_LIBS, "Request errno: %d\n", err);
+
     switch (err) {
     case EOK:
         return STATUS_200;
@@ -388,10 +426,14 @@ int sec_simple_secret_to_json(TALLOC_CTX *mem_ctx,
     int ret;
 
     root = json_pack("{s:s, s:s}", "type", "simple", "value", secret);
-    if (!root) return ENOMEM;
+    if (!root) {
+        DEBUG(SSSDBG_OP_FAILURE, "Failed to pack Json object\n");
+        return ENOMEM;
+    }
 
     jsonized = json_dumps(root, JSON_INDENT(4));
     if (!jsonized) {
+        DEBUG(SSSDBG_OP_FAILURE, "Failed to dump Json object\n");
         ret = ENOMEM;
         goto done;
     }
@@ -419,6 +461,11 @@ int sec_array_to_json(TALLOC_CTX *mem_ctx,
     int ret;
 
     root = json_array();
+    if (root == NULL) {
+        DEBUG(SSSDBG_OP_FAILURE, "Failed to create Json array\n");
+        ret = ENOMEM;
+        goto done;
+    }
 
     for (int i = 0; i < count; i++) {
         // FIXME: json_string mem leak ?
@@ -428,6 +475,7 @@ int sec_array_to_json(TALLOC_CTX *mem_ctx,
 
     jsonized = json_dumps(root, JSON_INDENT(4));
     if (!jsonized) {
+        DEBUG(SSSDBG_OP_FAILURE, "Failed to dump Json object\n");
         ret = ENOMEM;
         goto done;
     }
@@ -459,6 +507,8 @@ int sec_get_provider(struct sec_ctx *sctx, const char *name,
         *out_handle = handle;
         return EOK;
     }
+
+    DEBUG(SSSDBG_MINOR_FAILURE, "No handle for provider %s\n", name);
     return ENOENT;
 }
 
diff --git a/src/responder/secrets/proxy.c b/src/responder/secrets/proxy.c
index 13321c13e..ba34b2822 100644
--- a/src/responder/secrets/proxy.c
+++ b/src/responder/secrets/proxy.c
@@ -85,16 +85,21 @@ static int proxy_sec_get_cfg(struct proxy_context *pctx,
     ret = proxy_get_config_string(pctx, cfg, true, secreq,
                                   "proxy_url", &cfg->url);
     if (ret) goto done;
+    DEBUG(SSSDBG_CONF_SETTINGS, "proxy_url: %s\n", cfg->url);
 
     ret = proxy_get_config_string(pctx, cfg, false, secreq,
                                   "auth_type", &auth_type);
     if (ret) goto done;
+    DEBUG(SSSDBG_CONF_SETTINGS, "auth_type: %s\n", auth_type);
 
     if (auth_type) {
         if (strcmp(auth_type, "basic_auth") == 0) {
             cfg->auth_type = PAT_BASIC_AUTH;
             ret = proxy_get_config_string(pctx, cfg, true, secreq, "username",
                                           &cfg->auth.basic.username);
+            DEBUG(SSSDBG_CONF_SETTINGS,
+                  "username: %s\n", cfg->auth.basic.username);
+
             if (ret) goto done;
             ret = proxy_get_config_string(pctx, cfg, true, secreq, "password",
                                           &cfg->auth.basic.password);
@@ -104,12 +109,16 @@ static int proxy_sec_get_cfg(struct proxy_context *pctx,
             ret = proxy_get_config_string(pctx, cfg, true, secreq,
                                           "auth_header_name",
                                           &cfg->auth.header.name);
+            DEBUG(SSSDBG_CONF_SETTINGS,
+                  "auth_header_name: %s\n", cfg->auth.basic.username);
+
             if (ret) goto done;
             ret = proxy_get_config_string(pctx, cfg, true, secreq,
                                           "auth_header_value",
                                           &cfg->auth.header.value);
             if (ret) goto done;
         } else {
+            DEBUG(SSSDBG_CRIT_FAILURE, "Unknown auth type!\n");
             ret = EINVAL;
             goto done;
         }
@@ -120,6 +129,8 @@ static int proxy_sec_get_cfg(struct proxy_context *pctx,
     if ((ret != 0) && (ret != ENOENT)) goto done;
 
     while (cfg->fwd_headers && cfg->fwd_headers[cfg->num_headers]) {
+        DEBUG(SSSDBG_CONF_SETTINGS,
+              "Forwarding header: %s\n", cfg->fwd_headers[cfg->num_headers]);
         cfg->num_headers++;
     }
 
@@ -176,7 +187,10 @@ int proxy_sec_map_url(TALLOC_CTX *mem_ctx, struct sec_req_ctx *secreq,
 
     if (SECREQ_HAS_PORT(secreq)) {
         ret = snprintf(port, 6, "%d", SECREQ_PORT(secreq));
-        if (ret < 1 || ret > 5) return EINVAL;
+        if (ret < 1 || ret > 5) {
+            DEBUG(SSSDBG_CRIT_FAILURE, "snprintf failed\n");
+            return EINVAL;
+        }
     }
 
     blen = strlen(secreq->base_path);
@@ -196,6 +210,8 @@ int proxy_sec_map_url(TALLOC_CTX *mem_ctx, struct sec_req_ctx *secreq,
                           SECREQ_PART(secreq, fragment));
     if (!url) return ENOMEM;
 
+    DEBUG(SSSDBG_TRACE_INTERNAL, "URL: %s\n", url);
+
     *req_url = url;
     return EOK;
 }
@@ -215,18 +231,32 @@ int proxy_sec_map_headers(TALLOC_CTX *mem_ctx, struct sec_req_ctx *secreq,
             }
         }
         if (forward) {
+            DEBUG(SSSDBG_TRACE_LIBS, "Forwarding header %s:%s\n",
+                  secreq->headers[i].name, secreq->headers[i].value);
+
             ret = sec_http_append_header(mem_ctx, req_headers,
                                          secreq->headers[i].name,
                                          secreq->headers[i].value);
-            if (ret) return ret;
+            if (ret) {
+                DEBUG(SSSDBG_CRIT_FAILURE,
+                      "Couldn't append header %s\n", secreq->headers[i].name);
+                return ret;
+            }
         }
     }
 
     if (pcfg->auth_type == PAT_HEADER) {
+        DEBUG(SSSDBG_TRACE_LIBS,
+              "Forwarding header %s\n", pcfg->auth.header.name);
+
         ret = sec_http_append_header(mem_ctx, req_headers,
                                      pcfg->auth.header.name,
                                      pcfg->auth.header.value);
-        if (ret) return ret;
+        if (ret) {
+            DEBUG(SSSDBG_CRIT_FAILURE,
+                  "Couldn't append header %s\n", pcfg->auth.header.name);
+            return ret;
+        }
     }
 
     return EOK;
@@ -254,7 +284,10 @@ static int proxy_http_create_request(TALLOC_CTX *mem_ctx,
 
     /* Headers */
     ret = proxy_sec_map_headers(req, secreq, pcfg, &req->data);
-    if (ret) goto done;
+    if (ret) {
+        DEBUG(SSSDBG_CRIT_FAILURE, "Couldn't map headers\n");
+        goto done;
+    }
 
     /* CRLF separator before body */
     req->data = talloc_strdup_append_buffer(req->data, "\r\n");
@@ -347,9 +380,14 @@ struct tevent_req *proxy_http_req_send(struct proxy_context *pctx,
 
     /* STEP1: reparse URL to get hostname and port */
     ret = http_parser_parse_url(http_uri, strlen(http_uri), 0, &parsed);
-    if (ret) goto done;
+    if (ret) {
+        DEBUG(SSSDBG_CRIT_FAILURE, "Failed to parse URL [%s]: %d: %s\n",
+                                   http_uri, ret, sss_strerror(ret));
+        goto done;
+    }
 
     if (!(parsed.field_set & (1 << UF_HOST))) {
+        DEBUG(SSSDBG_CRIT_FAILURE, "No UF_HOST flag found\n");
         ret = EINVAL;
         goto done;
     }
@@ -361,6 +399,7 @@ struct tevent_req *proxy_http_req_send(struct proxy_context *pctx,
         ret = ENOMEM;
         goto done;
     }
+    DEBUG(SSSDBG_TRACE_LIBS, "proxy name: %s\n", state->proxyname);
 
     if (parsed.field_set & (1 << UF_PORT)) {
         state->port = parsed.port;
@@ -376,6 +415,7 @@ struct tevent_req *proxy_http_req_send(struct proxy_context *pctx,
             state->port = 80;
         }
     }
+    DEBUG(SSSDBG_TRACE_LIBS, "proxy port: %d\n", state->port);
 
     /* STEP2: resolve hostname first */
     subreq = resolv_gethostbyname_send(state, ev, pctx->resctx,
@@ -579,7 +619,11 @@ static int proxy_wire_send(int fd, struct proxy_http_request *req)
     data.length = req->data->length - req->written;
 
     ret = sec_send_data(fd, &data);
-    if (ret != EOK && ret != EAGAIN) return ret;
+    if (ret != EOK && ret != EAGAIN) {
+        DEBUG(SSSDBG_CRIT_FAILURE,
+              "sec_send_data failed [%zu]: %s\n", ret, sss_strerror(ret));
+        return ret;
+    }
 
     req->written = req->data->length - data.length;
     return ret;
@@ -885,14 +929,29 @@ struct tevent_req *proxy_secret_req(TALLOC_CTX *mem_ctx,
     }
 
     ret = proxy_sec_get_cfg(pctx, state, state->secreq, &state->pcfg);
-    if (ret) goto done;
+    if (ret) {
+        DEBUG(SSSDBG_CRIT_FAILURE,
+              "proxy_sec_get_cfg failed [%d]: %s\n", ret, sss_strerror(ret));
+        goto done;
+    }
 
     ret = proxy_sec_map_url(state, secreq, state->pcfg, &http_uri);
-    if (ret) goto done;
+    if (ret) {
+        DEBUG(SSSDBG_CRIT_FAILURE,
+              "proxy_sec_map_url failed [%d]: %s\n", ret, sss_strerror(ret));
+        goto done;
+    }
+
 
     ret = proxy_http_create_request(state, state->secreq, state->pcfg,
                                     http_uri, &http_req);
-    if (ret) goto done;
+    if (ret) {
+        DEBUG(SSSDBG_CRIT_FAILURE,
+              "proxy_http_create_request failed [%d]: %s\n",
+              ret, sss_strerror(ret));
+        goto done;
+    }
+
 
     subreq = proxy_http_req_send(pctx, state, ev, state->secreq,
                                  http_uri, http_req);
@@ -932,6 +991,9 @@ static void proxy_secret_req_done(struct tevent_req *subreq)
     talloc_zfree(subreq);
 
     if (ret != EOK) {
+        DEBUG(SSSDBG_OP_FAILURE,
+              "proxy_http request failed [%d]: %s\n",
+              ret, sss_strerror(ret));
         tevent_req_error(req, ret);
         return;
     }
@@ -943,6 +1005,9 @@ static void proxy_secret_req_done(struct tevent_req *subreq)
     if (ret == EOK) {
         tevent_req_done(req);
     } else {
+        DEBUG(SSSDBG_OP_FAILURE,
+              "sec_http_reply_with_headers request failed [%d]: %s\n",
+              ret, sss_strerror(ret));
         tevent_req_error(req, ret);
     }
 }
diff --git a/src/responder/secrets/secsrv_cmd.c b/src/responder/secrets/secsrv_cmd.c
index 58340bae4..de6b1cb61 100644
--- a/src/responder/secrets/secsrv_cmd.c
+++ b/src/responder/secrets/secsrv_cmd.c
@@ -54,7 +54,11 @@ static struct tevent_req *sec_http_request_send(TALLOC_CTX *mem_ctx,
 
     /* 1. mapping and path conversion */
     ret = sec_req_routing(state, secreq, &provider_handle);
-    if (ret) goto done;
+    if (ret) {
+        DEBUG(SSSDBG_OP_FAILURE,
+              "sec_req_routing failed [%d]: %s\n", ret, sss_strerror(ret));
+        goto done;
+    }
 
     /* 2. backend invocation */
     subreq = provider_handle->fn(state, state->ev,
@@ -83,10 +87,15 @@ static void sec_http_request_pipeline_done(struct tevent_req *subreq)
 
     /* 3. reply construction */
     ret = sec_provider_recv(subreq);
-
-    if (ret != EOK) {
+    if (ret == ENOENT) {
+        DEBUG(SSSDBG_TRACE_LIBS, "Did not find the requested data\n");
+        tevent_req_error(req, ret);
+    } else if (ret != EOK) {
+        DEBUG(SSSDBG_OP_FAILURE,
+              "sec request failed [%d]: %s\n", ret, sss_strerror(ret));
         tevent_req_error(req, ret);
     } else {
+        DEBUG(SSSDBG_TRACE_INTERNAL, "sec request done\n");
         tevent_req_done(req);
     }
 }
@@ -113,6 +122,13 @@ sec_http_request_done(struct tevent_req *req)
     ret = sec_http_request_recv(req);
 
     if (ret != EOK) {
+        if (ret == ENOENT) {
+            DEBUG(SSSDBG_TRACE_LIBS, "Did not find the requested data\n");
+        } else {
+            DEBUG(SSSDBG_OP_FAILURE,
+                  "sec_http_request_recv failed [%d]: %s\n",
+                  ret, sss_strerror(ret));
+        }
         /* Always return an error if we get here */
         ret = sec_http_status_reply(secreq, &secreq->reply,
                                     sec_errno_to_http_status(ret));
@@ -315,57 +331,95 @@ static int sec_on_message_complete(http_parser *parser)
     ret = http_parser_parse_url(req->request_url,
                                 strlen(req->request_url),
                                 0, &parsed);
-    if (ret) return ret;
+    if (ret) {
+        DEBUG(SSSDBG_CRIT_FAILURE,
+              "Failed to parse URL %s\n", req->request_url);
+        return ret;
+    }
 
     if (parsed.field_set & (1 << UF_SCHEMA)) {
         ret = sec_get_parsed_filed(req, UF_SCHEMA, &parsed,
                                    req->request_url,
                                    &req->parsed_url.schema);
-        if (ret) return -1;
+        if (ret) {
+            DEBUG(SSSDBG_CRIT_FAILURE,
+                  "Failed to retrieve schema from %s\n", req->request_url);
+            return -1;
+        }
+        DEBUG(SSSDBG_TRACE_INTERNAL, "schema: %s\n", req->parsed_url.schema);
     }
 
     if (parsed.field_set & (1 << UF_HOST)) {
         ret = sec_get_parsed_filed(req, UF_HOST, &parsed,
                                    req->request_url,
                                    &req->parsed_url.host);
-        if (ret) return -1;
+        if (ret) {
+            DEBUG(SSSDBG_CRIT_FAILURE,
+                  "Failed to retrieve host from %s\n", req->request_url);
+            return -1;
+        }
+        DEBUG(SSSDBG_TRACE_INTERNAL, "host: %s\n", req->parsed_url.host);
     }
 
     if (parsed.field_set & (1 << UF_PORT)) {
         req->parsed_url.port = parsed.port;
+        DEBUG(SSSDBG_TRACE_INTERNAL, "port: %d\n", req->parsed_url.port);
     }
 
     if (parsed.field_set & (1 << UF_PATH)) {
         ret = sec_get_parsed_filed(req, UF_PATH, &parsed,
                                    req->request_url,
                                    &req->parsed_url.path);
-        if (ret) return -1;
+        if (ret) {
+            DEBUG(SSSDBG_CRIT_FAILURE,
+                  "Failed to retrieve path from %s\n", req->request_url);
+            return -1;
+        }
+        DEBUG(SSSDBG_TRACE_INTERNAL, "path: %s\n", req->parsed_url.path);
     }
 
     if (parsed.field_set & (1 << UF_QUERY)) {
         ret = sec_get_parsed_filed(req, UF_QUERY, &parsed,
                                    req->request_url,
                                    &req->parsed_url.query);
-        if (ret) return -1;
+        if (ret) {
+            DEBUG(SSSDBG_CRIT_FAILURE,
+                  "Failed to retrieve query from %s\n", req->request_url);
+            return -1;
+        }
+        DEBUG(SSSDBG_TRACE_INTERNAL, "query: %s\n", req->parsed_url.query);
     }
 
     if (parsed.field_set & (1 << UF_FRAGMENT)) {
         ret = sec_get_parsed_filed(req, UF_FRAGMENT, &parsed,
                                    req->request_url,
                                    &req->parsed_url.fragment);
-        if (ret) return -1;
+        if (ret) {
+            DEBUG(SSSDBG_CRIT_FAILURE,
+                  "Failed to retrieve fragment from %s\n", req->request_url);
+            return -1;
+        }
+        DEBUG(SSSDBG_TRACE_INTERNAL,
+              "fragment: %s\n", req->parsed_url.fragment);
     }
 
     if (parsed.field_set & (1 << UF_USERINFO)) {
         ret = sec_get_parsed_filed(req, UF_USERINFO, &parsed,
                                    req->request_url,
                                    &req->parsed_url.userinfo);
-        if (ret) return -1;
+        if (ret) {
+            DEBUG(SSSDBG_CRIT_FAILURE,
+                  "Failed to retrieve userinfo from %s\n", req->request_url);
+            return -1;
+        }
+        DEBUG(SSSDBG_TRACE_INTERNAL,
+              "userinfo: %s\n", req->parsed_url.userinfo);
     }
 
     req->method = parser->method;
 
     req->complete = true;
+    DEBUG(SSSDBG_TRACE_INTERNAL, "parsing complete\n");
 
     return 0;
 }
@@ -376,6 +430,7 @@ static int sec_on_message_complete(http_parser *parser)
 int sec_send_data(int fd, struct sec_data *data)
 {
     ssize_t len;
+    errno_t ret;
 
     errno = 0;
     len = send(fd, data->data, data->length, 0);
@@ -383,7 +438,10 @@ int sec_send_data(int fd, struct sec_data *data)
         if (errno == EAGAIN || errno == EWOULDBLOCK || errno == EINTR) {
             return EAGAIN;
         } else {
-            return errno;
+            ret = errno;
+            DEBUG(SSSDBG_CRIT_FAILURE,
+                  "send failed [%d]: %s\n", ret, strerror(ret));
+            return ret;
         }
     }
 
@@ -393,6 +451,7 @@ int sec_send_data(int fd, struct sec_data *data)
 
     data->length -= len;
     data->data += len;
+    DEBUG(SSSDBG_TRACE_INTERNAL, "sent %zu bytes\n", data->length);
     return EOK;
 }
 
@@ -424,6 +483,7 @@ static void sec_send(struct cli_ctx *cctx)
 int sec_recv_data(int fd, struct sec_data *data)
 {
     ssize_t len;
+    errno_t ret;
 
     errno = 0;
     len = recv(fd, data->data, data->length, 0);
@@ -431,7 +491,10 @@ int sec_recv_data(int fd, struct sec_data *data)
         if (errno == EAGAIN || errno == EWOULDBLOCK || errno == EINTR) {
             return EAGAIN;
         } else {
-            return errno;
+            ret = errno;
+            DEBUG(SSSDBG_CRIT_FAILURE,
+                  "send failed [%d]: %s\n", ret, strerror(ret));
+            return ret;
         }
     }
 
@@ -441,6 +504,7 @@ int sec_recv_data(int fd, struct sec_data *data)
     }
 
     data->length = len;
+    DEBUG(SSSDBG_TRACE_INTERNAL, "received %zu bytes\n", data->length);
     return EOK;
 }