Scatter more specific debugging messages near the bug

Iterates from the previous commit.

diff --git a/src/http/http.c b/src/http/http.c
index 30bf491d680c6a2373a76c936a639a148d796161..45f293f6752d87c9b07609c05547fa789e878985 100644 (file)
--- a/src/http/http.c
+++ b/src/http/http.c
@@ -10,6 +10,11 @@
 #include "file.h"
 #include "log.h"
 
+#define TA_DEBUG \
+       do { if (is_ta) PR_DEBUG; } while (0)
+#define TA_DEBUG_MSG(fmt, ...) \
+       do { if (is_ta) PR_DEBUG_MSG(fmt, ##__VA_ARGS__); } while (0)
+
 /* HTTP Response Code 200 (OK) */
 #define HTTP_OK                        200
 /* HTTP Response Code 304 (Not Modified) */
@@ -149,28 +154,36 @@ curl_err_string(struct http_handler *handler, CURLcode res)
  */
 static int
 http_fetch(struct http_handler *handler, char const *uri, long *response_code,
-    long *cond_met, bool log_operation, http_write_cb cb, void *arg)
+    long *cond_met, bool log_operation, http_write_cb cb, void *arg, bool is_ta)
 {
        CURLcode res, res2;
        long unmet = 0;
 
+       TA_DEBUG;
+       TA_DEBUG_MSG("%s %d", uri, log_operation);
+
        handler->errbuf[0] = 0;
        setopt_str(handler->curl, CURLOPT_URL, uri);
        setopt_writefunction(handler->curl, cb, arg);
 
-       pr_val_debug("HTTP GET: %s", uri);
+       TA_DEBUG_MSG("HTTP GET: %s", uri);
        res = curl_easy_perform(handler->curl);
+       TA_DEBUG_MSG("%d", res);
 
        res2 = curl_easy_getinfo(handler->curl, CURLINFO_RESPONSE_CODE,
            response_code);
+       TA_DEBUG_MSG("%d", res2);
        if (res2 != CURLE_OK) {
                return pr_op_err("curl_easy_getinfo(CURLINFO_RESPONSE_CODE) returned %d (%s). I think this is supposed to be illegal, so I'll have to drop URI '%s'.",
                    res2, curl_err_string(handler, res2), uri);
        }
 
+       TA_DEBUG_MSG("%ld", *response_code);
        if (res == CURLE_OK) {
-               if (*response_code != HTTP_OK)
+               if (*response_code != HTTP_OK) {
+                       TA_DEBUG;
                        return 0;
+               }
 
                /*
                 * Scenario: Received an OK code, but the time condition
@@ -207,22 +220,29 @@ http_fetch(struct http_handler *handler, char const *uri, long *response_code,
                 *              unmet: 0
                 *              writefunction called
                 */
+               TA_DEBUG;
                res = curl_easy_getinfo(handler->curl, CURLINFO_CONDITION_UNMET,
                    &unmet);
                if (res == CURLE_OK && unmet == 1)
                        *cond_met = 0;
+               TA_DEBUG_MSG("%ld", unmet);
                return 0;
        }
 
-       if (*response_code >= HTTP_BAD_REQUEST)
+       if (*response_code >= HTTP_BAD_REQUEST) {
+               TA_DEBUG;
                return pr_val_err("Error requesting URL %s (received HTTP code %ld): %s",
                    uri, *response_code, curl_err_string(handler, res));
+       }
 
        pr_val_err("Error requesting URL %s: %s", uri,
            curl_err_string(handler, res));
-       if (log_operation)
+       TA_DEBUG;
+       if (log_operation) {
+               TA_DEBUG;
                pr_op_err("Error requesting URL %s: %s", uri,
                    curl_err_string(handler, res));
+       }
 
        return EREQFAILED;
 }
@@ -249,7 +269,7 @@ write_cb(unsigned char *content, size_t size, size_t nmemb, void *arg)
 
 static int
 __http_download_file(struct rpki_uri *uri, long *response_code, long ims_value,
-    long *cond_met, bool log_operation)
+    long *cond_met, bool log_operation, bool is_ta)
 {
        char const *tmp_suffix = "_tmp";
        struct http_handler handler;
@@ -264,16 +284,24 @@ __http_download_file(struct rpki_uri *uri, long *response_code, long ims_value,
        *cond_met = 1;
        if (!config_get_http_enabled()) {
                *response_code = 0; /* Not 200 code, but also not an error */
+               TA_DEBUG;
                return 0;
        }
 
+       TA_DEBUG;
+
        original_file = uri_get_local(uri);
        tmp_file = strdup(original_file);
-       if (tmp_file == NULL)
+       if (tmp_file == NULL) {
+               TA_DEBUG;
                return pr_enomem();
+       }
+
+       TA_DEBUG;
 
        tmp = realloc(tmp_file, strlen(tmp_file) + strlen(tmp_suffix) + 1);
        if (tmp == NULL) {
+               TA_DEBUG;
                error = pr_enomem();
                goto release_tmp;
        }
@@ -281,35 +309,55 @@ __http_download_file(struct rpki_uri *uri, long *response_code, long ims_value,
        tmp_file = tmp;
        strcat(tmp_file, tmp_suffix);
 
+       TA_DEBUG;
+
        error = create_dir_recursive(tmp_file);
-       if (error)
+       if (error) {
+               TA_DEBUG_MSG("%d", error);
                goto release_tmp;
+       }
+
+       TA_DEBUG;
 
        error = file_write(tmp_file, &out, &stat);
-       if (error)
+       if (error) {
+               TA_DEBUG_MSG("%d", error);
                goto delete_dir;
+       }
 
        do {
+               TA_DEBUG;
+
                error = http_easy_init(&handler);
-               if (error)
+               if (error) {
+                       TA_DEBUG_MSG("%d", error);
                        goto close_file;
+               }
 
                /* Set "If-Modified-Since" header only if a value is specified */
                if (ims_value > 0) {
+                       TA_DEBUG_MSG("%ld", ims_value);
                        setopt_long(handler.curl, CURLOPT_TIMEVALUE, ims_value);
                        setopt_long(handler.curl, CURLOPT_TIMECONDITION,
                            CURL_TIMECOND_IFMODSINCE);
+                       TA_DEBUG;
                }
                error = http_fetch(&handler, uri_get_global(uri), response_code,
-                   cond_met, log_operation, write_cb, out);
-               if (error != EREQFAILED)
+                   cond_met, log_operation, write_cb, out, is_ta);
+               if (error != EREQFAILED) {
+                       TA_DEBUG_MSG("%d", error);
                        break;
+               }
+
+               TA_DEBUG_MSG("%d", error);
 
                if (retries == config_get_http_retry_count()) {
+                       TA_DEBUG_MSG("%u", retries);
                        pr_val_warn("Max HTTP retries (%u) reached requesting for '%s', won't retry again.",
                            retries, uri_get_global(uri));
                        break;
                }
+               TA_DEBUG;
                pr_val_warn("Retrying HTTP request '%s' in %u seconds, %u attempts remaining.",
                    uri_get_global(uri),
                    config_get_http_retry_interval(),
@@ -322,18 +370,26 @@ __http_download_file(struct rpki_uri *uri, long *response_code, long ims_value,
        http_easy_cleanup(&handler);
        file_close(out);
 
-       if (error)
+       if (error) {
+               TA_DEBUG_MSG("%d", error);
                goto delete_dir;
+       }
+
+       TA_DEBUG;
+       TA_DEBUG_MSG("%s %s", tmp_file, original_file);
 
        /* Overwrite the original file */
        error = rename(tmp_file, original_file);
        if (error) {
                error = errno;
+               TA_DEBUG_MSG("%d", error);
                pr_val_errno(error, "Renaming temporal file from '%s' to '%s'",
                    tmp_file, original_file);
                goto delete_dir;
        }
 
+       TA_DEBUG;
+
        free(tmp_file);
        return 0;
 close_file:
@@ -342,6 +398,7 @@ delete_dir:
        delete_dir_recursive_bottom_up(tmp_file);
 release_tmp:
        free(tmp_file);
+       TA_DEBUG_MSG("%d", error);
        return ENSURE_NEGATIVE(error);
 }
 
@@ -353,12 +410,12 @@ release_tmp:
  * request to the server failed.
  */
 int
-http_download_file(struct rpki_uri *uri, bool log_operation)
+http_download_file(struct rpki_uri *uri, bool log_operation, bool is_ta)
 {
        long response;
        long cond_met;
        return __http_download_file(uri, &response, 0, &cond_met,
-           log_operation);
+           log_operation, is_ta);
 }
 
 /*
@@ -383,7 +440,7 @@ http_download_file_with_ims(struct rpki_uri *uri, long value,
        int error;
 
        error = __http_download_file(uri, &response, value, &cond_met,
-           log_operation);
+           log_operation, false);
        if (error)
                return error;
 
@@ -414,7 +471,7 @@ http_download_file_with_ims(struct rpki_uri *uri, long value,
         */
 
        return __http_download_file(uri, &response, 0, &cond_met,
-           log_operation);
+           log_operation, false);
 
 }
 
@@ -458,7 +515,7 @@ http_direct_download(char const *remote, char const *dest)
        response_code = 0;
        cond_met = 0;
        error = http_fetch(&handler, remote, &response_code, &cond_met, true,
-           write_cb, out);
+           write_cb, out, false);
        http_easy_cleanup(&handler);
        file_close(out);
        if (error)

diff --git a/src/http/http.h b/src/http/http.h
index 717119d90c969e78763982e559ff102d8b5e8b9d..8cb3b0efe873a217bd52e669865de65bddd3833e 100644 (file)
--- a/src/http/http.h
+++ b/src/http/http.h
@@ -9,7 +9,7 @@
 int http_init(void);
 void http_cleanup(void);
 
-int http_download_file(struct rpki_uri *, bool);
+int http_download_file(struct rpki_uri *, bool, bool);
 int http_download_file_with_ims(struct rpki_uri *, long, bool);
 
 int http_direct_download(char const *, char const *);

diff --git a/src/log.c b/src/log.c
index 21f0c7b4447bb7e0f756d4aed0a64d97540c5bb3..d2c3d2432eb159a3f76844ec7872a3f724f4639d 100644 (file)
--- a/src/log.c
+++ b/src/log.c
@@ -546,6 +546,7 @@ val_crypto_err(const char *format, ...)
 int
 pr_enomem(void)
 {
+       /* TODO this being a critical is not acceptable */
        pr_crit("Out of memory.");
 }
 

diff --git a/src/object/tal.c b/src/object/tal.c
index e209446392629f5a56d4d861d744ef8a42425a5d..bb8dec0a9973faab37769059a6ff971bdb7928c0 100644 (file)
--- a/src/object/tal.c
+++ b/src/object/tal.c
@@ -519,25 +519,18 @@ handle_tal_uri(struct tal *tal, struct rpki_uri *uri, void *arg)
        struct deferred_cert deferred;
        int error;
 
-       PR_DEBUG;
-
        validation_handler.handle_roa_v4 = handle_roa_v4;
        validation_handler.handle_roa_v6 = handle_roa_v6;
        validation_handler.handle_router_key = handle_router_key;
        validation_handler.arg = thread_arg->arg;
 
-       PR_DEBUG;
-
        error = validation_prepare(&state, tal, &validation_handler);
-       if (error) {
-               PR_DEBUG_MSG("%d", error);
+       if (error)
                return ENSURE_NEGATIVE(error);
-       }
-
-       PR_DEBUG;
 
        if (thread_arg->sync_files) {
                PR_DEBUG;
+               PR_DEBUG_MSG("%s", uri_op_get_printable(uri));
 
                if (uri_is_rsync(uri)) {
                        if (!config_get_rsync_enabled()) {
@@ -553,15 +546,13 @@ handle_tal_uri(struct tal *tal, struct rpki_uri *uri, void *arg)
                                return 0; /* Try some other TAL URI */
                        }
                        error = http_download_file(uri,
-                           reqs_errors_log_uri(uri_get_global(uri)));
+                           reqs_errors_log_uri(uri_get_global(uri)), true);
                }
 
                PR_DEBUG;
 
                /* Reminder: there's a positive error: EREQFAILED */
                if (error) {
-                       PR_DEBUG_MSG("%d", error);
-
                        working_repo_push(uri_get_global(uri));
                        validation_destroy(state);
                        return pr_val_warn(
@@ -569,20 +560,13 @@ handle_tal_uri(struct tal *tal, struct rpki_uri *uri, void *arg)
                            uri_val_get_printable(uri));
                }
 
-               PR_DEBUG;
-
        } else {
-               PR_DEBUG;
-
                /* Look for local files */
                if (!valid_file_or_dir(uri_get_local(uri), true, false,
                    __pr_val_err)) {
-                       PR_DEBUG;
                        validation_destroy(state);
                        return 0; /* Error already logged */
                }
-
-               PR_DEBUG;
        }
 
        /* At least one URI was sync'd */
@@ -664,8 +648,6 @@ __handle_tal_uri_sync(struct tal *tal, struct rpki_uri *uri, void *arg)
 {
        int error;
 
-       PR_DEBUG;
-
        error = handle_tal_uri(tal, uri, arg);
        if (error)
                return error;
@@ -687,41 +669,27 @@ do_file_validation(void *thread_arg)
        struct tal *tal;
        int error;
 
-       PR_DEBUG;
-
        fnstack_init();
        fnstack_push(thread->tal_file);
 
-       PR_DEBUG;
-
        working_repo_init();
 
-       PR_DEBUG;
-
        error = tal_load(thread->tal_file, &tal);
        if (error)
                goto end;
 
-       PR_DEBUG;
-
        error = tal_order_uris(tal);
        if (error)
                goto destroy_tal;
 
-       PR_DEBUG;
-
        error = foreach_uri(tal, __handle_tal_uri_sync, thread_arg);
        if (error > 0) {
-               PR_DEBUG_MSG("error: %d", error);
                error = 0;
                goto destroy_tal;
        } else if (error < 0) {
-               PR_DEBUG_MSG("error: %d", error);
                goto destroy_tal;
        }
 
-       PR_DEBUG;
-
        if (!thread->retry_local) {
                error = pr_op_err("None of the URIs of the TAL '%s' yielded a successful traversal.",
                    thread->tal_file);

diff --git a/src/rrdp/rrdp_parser.c b/src/rrdp/rrdp_parser.c
index e1c4428c7e5aa9d57d21efb9332b22c9e5a9bc1f..6b59ad15f2a98bd19ce1cd9f42a6331f102ac5dc 100644 (file)
--- a/src/rrdp/rrdp_parser.c
+++ b/src/rrdp/rrdp_parser.c
@@ -104,7 +104,7 @@ download_file(struct rpki_uri *uri, long last_update, bool log_operation)
                error = http_download_file_with_ims(uri, last_update,
                    log_operation);
        else
-               error = http_download_file(uri, log_operation);
+               error = http_download_file(uri, log_operation, false);
 
        /*
         * Since distinct files can be downloaded (notification, snapshot,

diff --git a/src/rsync/rsync.c b/src/rsync/rsync.c
index 74d87bb34d356a31ca25198e7a45efb71fb38105..45b9ea1676a36ebfe63fd1fb712e68c33d78c714 100644 (file)
--- a/src/rsync/rsync.c
+++ b/src/rsync/rsync.c
@@ -15,6 +15,11 @@
 #include "str_token.h"
 #include "thread_var.h"
 
+#define TA_DEBUG \
+       do { if (is_ta) PR_DEBUG; } while (0)
+#define TA_DEBUG_MSG(fmt, ...) \
+       do { if (is_ta) PR_DEBUG_MSG(fmt, ##__VA_ARGS__); } while (0)
+
 struct uri {
        struct rpki_uri *uri;
        SLIST_ENTRY(uri) next;
@@ -164,7 +169,7 @@ get_rsync_uri(struct rpki_uri *requested_uri, bool is_ta,
                    : handle_root_strategy(requested_uri, rsync_uri);
        case RSYNC_STRICT:
                return handle_strict_strategy(requested_uri, rsync_uri);
-       default:
+       case RSYNC_OFF:
                break;
        }
 
@@ -381,9 +386,10 @@ do_rsync(struct rpki_uri *uri, bool is_ta, bool log_operation)
        if (error)
                return error;
 
-       pr_val_debug("Executing RSYNC:");
-       for (i = 0; i < args_len + 1; i++)
-               pr_val_debug("    %s", args[i]);
+       TA_DEBUG_MSG("Executing RSYNC:");
+       for (i = 0; i < args_len + 1; i++) {
+               TA_DEBUG_MSG("    %s", args[i]);
+       }
 
        retries = 0;
        do {
@@ -392,13 +398,19 @@ do_rsync(struct rpki_uri *uri, bool is_ta, bool log_operation)
                if (error)
                        goto release_args;
 
+               TA_DEBUG;
+
                error = create_pipes(fork_fds);
-               if (error)
+               if (error) {
+                       TA_DEBUG_MSG("%d", error);
                        goto release_args;
+               }
 
                /* Flush output (avoid locks between father and child) */
                log_flush();
 
+               TA_DEBUG;
+
                /* We need to fork because execvp() magics the thread away. */
                child_pid = fork();
                if (child_pid == 0) {
@@ -425,15 +437,21 @@ do_rsync(struct rpki_uri *uri, bool is_ta, bool log_operation)
                        goto release_args;
                }
 
+               TA_DEBUG;
+
                /* This code is run by us. */
                error = read_pipes(fork_fds, log_operation);
-               if (error)
+               if (error) {
+                       TA_DEBUG;
                        kill(child_pid, SIGCHLD); /* Stop the child */
+                       TA_DEBUG;
+               }
 
                error = waitpid(child_pid, &child_status, 0);
                do {
                        if (error == -1) {
                                error = errno;
+                               TA_DEBUG_MSG("%d", error);
                                pr_op_err("The rsync sub-process returned error %d (%s)",
                                    error, strerror(error));
                                if (child_status > 0)
@@ -445,6 +463,7 @@ do_rsync(struct rpki_uri *uri, bool is_ta, bool log_operation)
                if (WIFEXITED(child_status)) {
                        /* Happy path (but also sad path sometimes). */
                        error = WEXITSTATUS(child_status);
+                       TA_DEBUG_MSG("%d", error);
                        pr_val_debug("Child terminated with error code %d.",
                            error);
                        if (error == -ENOMEM)
@@ -454,6 +473,7 @@ do_rsync(struct rpki_uri *uri, bool is_ta, bool log_operation)
                                goto release_args;
 
                        if (retries == config_get_rsync_retry_count()) {
+                               PR_DEBUG_MSG("%u", retries);
                                pr_val_warn("Max RSYNC retries (%u) reached on '%s', won't retry again.",
                                    retries, uri_get_global(uri));
                                error = EREQFAILED;
@@ -463,6 +483,7 @@ do_rsync(struct rpki_uri *uri, bool is_ta, bool log_operation)
                            uri_get_global(uri),
                            config_get_rsync_retry_interval(),
                            config_get_rsync_retry_count() - retries);
+                       PR_DEBUG;
                        retries++;
                        sleep(config_get_rsync_retry_interval());
                        continue;
@@ -473,6 +494,7 @@ do_rsync(struct rpki_uri *uri, bool is_ta, bool log_operation)
        release_args(args, args_len);
 
        if (WIFSIGNALED(child_status)) {
+               TA_DEBUG_MSG("%d", WTERMSIG(child_status));
                switch (WTERMSIG(child_status)) {
                case SIGINT:
                        pr_op_err("RSYNC was user-interrupted. Guess I'll interrupt myself too.");
@@ -491,9 +513,11 @@ do_rsync(struct rpki_uri *uri, bool is_ta, bool log_operation)
                return -EINTR; /* Meh? */
        }
 
+       TA_DEBUG_MSG("%d", WIFSIGNALED(child_status));
        pr_op_err("The RSYNC command died in a way I don't have a handler for. Dunno; guess I'll die as well.");
        return -EINVAL;
 release_args:
+       TA_DEBUG_MSG("%d", error);
        /* The happy path also falls here */
        release_args(args, args_len);
        return error;
@@ -572,59 +596,87 @@ rsync_download_files(struct rpki_uri *requested_uri, bool is_ta, bool force)
        bool to_op_log;
        int error;
 
-       if (!config_get_rsync_enabled())
+       if (!config_get_rsync_enabled()) {
+               TA_DEBUG;
                return 0;
+       }
+       TA_DEBUG;
 
        state = state_retrieve();
-       if (state == NULL)
+       if (state == NULL) {
+               TA_DEBUG;
                return -EINVAL;
+       }
+       TA_DEBUG;
 
        visited_uris = validation_rsync_visited_uris(state);
 
+       TA_DEBUG;
+
        if (!force && is_already_downloaded(requested_uri, visited_uris)) {
                pr_val_debug("No need to redownload '%s'.",
                    uri_val_get_printable(requested_uri));
+               TA_DEBUG;
                return check_ancestor_error(requested_uri);
        }
 
-       if (!force)
+       if (!force) {
+               TA_DEBUG;
                error = get_rsync_uri(requested_uri, is_ta, &rsync_uri);
-       else {
+               TA_DEBUG_MSG("%d", error);
+       } else {
+               TA_DEBUG;
                error = check_ancestor_error(requested_uri);
-               if (error)
+               if (error) {
+                       TA_DEBUG;
                        return error;
+               }
+               TA_DEBUG;
                error = handle_strict_strategy(requested_uri, &rsync_uri);
+               TA_DEBUG_MSG("%d", error);
        }
 
-       if (error)
+       if (error) {
+               TA_DEBUG;
                return error;
+       }
 
        pr_val_debug("Going to RSYNC '%s'.", uri_val_get_printable(rsync_uri));
+       TA_DEBUG;
 
        to_op_log = reqs_errors_log_uri(uri_get_global(rsync_uri));
+       TA_DEBUG_MSG("%d", to_op_log);
        error = do_rsync(rsync_uri, is_ta, to_op_log);
+       TA_DEBUG_MSG("%d", error);
        switch(error) {
        case 0:
                /* Don't store when "force" and if its already downloaded */
-               if (!(force && is_already_downloaded(rsync_uri, visited_uris)))
+               if (!(force && is_already_downloaded(rsync_uri, visited_uris))) {
+                       TA_DEBUG;
                        error = mark_as_downloaded(rsync_uri, visited_uris);
+                       TA_DEBUG_MSG("%d", error);
+               }
                reqs_errors_rem_uri(uri_get_global(rsync_uri));
+               TA_DEBUG;
                break;
        case EREQFAILED:
                /* All attempts failed, avoid future requests */
                error = reqs_errors_add_uri(uri_get_global(rsync_uri));
-               if (error)
+               if (error) {
+                       TA_DEBUG_MSG("%d", error);
                        break;
+               }
+               TA_DEBUG;
                error = mark_as_downloaded(rsync_uri, visited_uris);
+               TA_DEBUG_MSG("%d", error);
                /* Everything went ok? Return the original error */
                if (!error)
                        error = EREQFAILED;
                break;
-       default:
-               break;
        }
 
        uri_refput(rsync_uri);
+       TA_DEBUG;
        return error;
 }
 

diff --git a/src/thread/thread_pool.c b/src/thread/thread_pool.c
index 1d11af3ac971c7cacdb5505a34dcd1ecebd76f5a..e3c04380f025b04a337171a2dd48ec1328a873aa 100644 (file)
--- a/src/thread/thread_pool.c
+++ b/src/thread/thread_pool.c
@@ -215,7 +215,6 @@ tasks_poll(void *arg)
                mutex_unlock(pool);
 
                if (task != NULL) {
-                       PR_DEBUG;
                        task->cb(task->arg);
                        pr_op_debug("Thread %s.%u: Task '%s' ended", pool->name,
                            thread_id, task->name);