From 926fd3cb7e2366aa797fedf3ccdefa2511238960 Mon Sep 17 00:00:00 2001 From: Alberto Leiva Popper Date: Fri, 4 Jun 2021 00:37:21 -0500 Subject: [PATCH] Scatter more specific debugging messages near the bug Iterates from the previous commit. --- src/http/http.c | 93 ++++++++++++++++++++++++++++++++-------- src/http/http.h | 2 +- src/log.c | 1 + src/object/tal.c | 38 ++-------------- src/rrdp/rrdp_parser.c | 2 +- src/rsync/rsync.c | 84 +++++++++++++++++++++++++++++------- src/thread/thread_pool.c | 1 - 7 files changed, 149 insertions(+), 72 deletions(-) diff --git a/src/http/http.c b/src/http/http.c index 30bf491d..45f293f6 100644 --- 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 717119d9..8cb3b0ef 100644 --- 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 21f0c7b4..d2c3d243 100644 --- 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 e2094463..bb8dec0a 100644 --- 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 e1c4428c..6b59ad15 100644 --- 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 74d87bb3..45b9ea16 100644 --- 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 1d11af3a..e3c04380 100644 --- 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); -- 2.47.3