From: pcarana Date: Fri, 19 Jun 2020 22:30:43 +0000 (-0500) Subject: Fix several bugs related to sync errors, update some log messages X-Git-Tag: v1.3.0~6 X-Git-Url: http://git.ipfire.org/gitweb/gitweb.cgi?a=commitdiff_plain;h=d4e4987363df97e259681df8301783fb547a90e6;p=thirdparty%2FFORT-validator.git Fix several bugs related to sync errors, update some log messages +Fix bug: an endless loop when a requested URI error was removed. +Fix bug: some error'd URIs could be logged despite that their repository data was successfully fetched with another access method. +Fig bug: if a TAL has more than one URI and there was an error fetching an URI, the following URIs in the list weren't considered to get the TA certificate. +Only 'stderr' rsync output will be sent to operation log considering '--stale-repository-period', the 'stdout' rsync output will be sent to validation log at level info. +Messages of rsync/rrdp retries are 'upgraded' from level info to warn (all on validation logs). +Add a warning message (validation log) whenever local data is going to be utilized due to previous errors fetching repositories or TA certificates. +Log all communication errors if 'log.level=debug'. --- diff --git a/src/object/certificate.c b/src/object/certificate.c index 5f6fa9c6..936fb935 100644 --- a/src/object/certificate.c +++ b/src/object/certificate.c @@ -9,6 +9,7 @@ #include "extension.h" #include "log.h" #include "nid.h" +#include "reqs_errors.h" #include "str.h" #include "thread_var.h" #include "asn1/decode.h" @@ -1894,25 +1895,13 @@ verify_mft_loc(struct rpki_uri *mft_uri) static int exec_rrdp_method(struct sia_ca_uris *sia_uris) { - int error; - - error = rrdp_load(sia_uris->rpkiNotify.uri); - if (error) - return error; - - return verify_mft_loc(sia_uris->mft.uri); + return rrdp_load(sia_uris->rpkiNotify.uri); } static int exec_rsync_method(struct sia_ca_uris *sia_uris) { - int error; - - error = download_files(sia_uris->caRepository.uri, false, false); - if (error) - return error; - - return verify_mft_loc(sia_uris->mft.uri); + return download_files(sia_uris->caRepository.uri, false, false); } /* @@ -1937,13 +1926,16 @@ use_access_method(struct sia_ca_uris *sia_uris, * care of that. */ (*rsync_utilized) = true; - if (sia_uris->rpkiNotify.uri == NULL || !config_get_rrdp_enabled()) - return rsync_cb(sia_uris); + if (sia_uris->rpkiNotify.uri == NULL || !config_get_rrdp_enabled()) { + error = rsync_cb(sia_uris); + goto verify_mft; + } /* RSYNC disabled, and RRDP is present, use it */ if (!config_get_rsync_enabled()) { (*rsync_utilized) = false; - return rrdp_cb(sia_uris); + error = rrdp_cb(sia_uris); + goto verify_mft; } /* @@ -1982,7 +1974,7 @@ use_access_method(struct sia_ca_uris *sia_uris, error = cb_primary(sia_uris); if (!error) { (*rsync_utilized) = !primary_rrdp; - return 0; + goto verify_mft; } if (primary_rrdp) { @@ -2007,7 +1999,22 @@ use_access_method(struct sia_ca_uris *sia_uris, /* No need to remember the working repository anymore */ working_repo_pop(); - return error; +verify_mft: + switch (error) { + case 0: + /* Remove the error'd URI, since we got the repo files */ + if (working_repo_peek() != NULL) + reqs_errors_rem_uri(working_repo_peek()); + break; + case EREQFAILED: + /* Log that we'll try to work with a local copy */ + pr_val_warn("Trying to work with the local cache files."); + break; + default: + return error; + } + /* Look for the manifest */ + return verify_mft_loc(sia_uris->mft.uri); } /* diff --git a/src/object/tal.c b/src/object/tal.c index 199f33d2..f4978b61 100644 --- a/src/object/tal.c +++ b/src/object/tal.c @@ -51,6 +51,13 @@ struct validation_thread { */ pthread_t pid; char *tal_file; + /* + * Try to use the TA from the local cache? Only if none of the URIs + * was sync'd. + */ + bool retry_local; + /* Try to sync the current TA URI? */ + bool sync_files; void *arg; int exit_status; /* This should also only be manipulated by the parent thread. */ @@ -476,6 +483,7 @@ handle_tal_uri(struct tal *tal, struct rpki_uri *uri, void *arg) * A "hard error" is any other error. */ + struct validation_thread *thread_arg = arg; struct validation_handler validation_handler; struct validation *state; struct cert_stack *certstack; @@ -485,28 +493,39 @@ handle_tal_uri(struct tal *tal, struct rpki_uri *uri, void *arg) 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 = arg; + validation_handler.arg = thread_arg->arg; error = validation_prepare(&state, tal, &validation_handler); if (error) return ENSURE_NEGATIVE(error); - if (uri_is_rsync(uri)) - error = download_files(uri, true, false); - else - error = handle_https_uri(uri); + if (thread_arg->sync_files) { + if (uri_is_rsync(uri)) + error = download_files(uri, true, false); + else + error = handle_https_uri(uri); + } else if (!valid_file_or_dir(uri_get_local(uri), true, false, + pr_val_errno)) { + return 0; /* Error already logged */ + } - /* FIXME (NOW) Try to work with local data on the first run? */ + /* Friendly reminder: there's a positive error - EREQFAILED */ if (error) { + working_repo_push(uri_get_global(uri)); validation_destroy(state); - return pr_val_warn("TAL '%s' could not be downloaded.", + return pr_val_warn("TAL URI '%s' could not be downloaded.", uri_val_get_printable(uri)); } + /* At least one URI was sync'd */ + thread_arg->retry_local = false; + if (thread_arg->sync_files && working_repo_peek() != NULL) + reqs_errors_rem_uri(working_repo_peek()); + pr_val_debug("TAL URI '%s' {", uri_val_get_printable(uri)); if (!uri_is_certificate(uri)) { - error = pr_op_err("TAL file does not point to a certificate. (Expected .cer, got '%s')", + error = pr_op_err("TAL URI does not point to a certificate. (Expected .cer, got '%s')", uri_op_get_printable(uri)); goto fail; } @@ -571,6 +590,25 @@ end: validation_destroy(state); return error; } +static int +__handle_tal_uri_sync(struct tal *tal, struct rpki_uri *uri, void *arg) +{ + int error; + + error = handle_tal_uri(tal, uri, arg); + if (error) + return error; + working_repo_push(uri_get_global(uri)); + + return 0; +} + +static int +__handle_tal_uri_local(struct tal *tal, struct rpki_uri *uri, void *arg) +{ + return handle_tal_uri(tal, uri, arg); +} + static void * do_file_validation(void *thread_arg) { @@ -589,13 +627,30 @@ do_file_validation(void *thread_arg) if (config_get_shuffle_tal_uris()) tal_shuffle_uris(tal); - error = foreach_uri(tal, handle_tal_uri, thread->arg); + error = foreach_uri(tal, __handle_tal_uri_sync, thread_arg); + if (error > 0) { + error = 0; + goto destroy_tal; + } else if (error < 0) + goto destroy_tal; + + if (!thread->retry_local) { + error = pr_op_err("None of the URIs of the TAL '%s' yielded a successful traversal.", + thread->tal_file); + goto destroy_tal; + } + + thread->sync_files = false; + pr_val_warn("Looking for the TA certificate at the local files."); + + error = foreach_uri(tal, __handle_tal_uri_local, thread_arg); if (error > 0) error = 0; else if (error == 0) error = pr_op_err("None of the URIs of the TAL '%s' yielded a successful traversal.", thread->tal_file); +destroy_tal: tal_destroy(tal); end: working_repo_cleanup(); @@ -636,6 +691,8 @@ __do_file_validation(char const *tal_file, void *arg) } thread->arg = t_param->db; thread->exit_status = -EINTR; + thread->retry_local = true; + thread->sync_files = true; errno = pthread_create(&thread->pid, NULL, do_file_validation, thread); if (errno) { @@ -710,7 +767,7 @@ perform_standalone_validation(struct db_table *table) /* The parameter isn't needed anymore */ free(param); - /* FIXME (NOW) Clarify if this really belongs here */ + /* Log the error'd URIs summary */ reqs_errors_log_summary(); /* One thread has errors, validation can't keep the resulting table */ diff --git a/src/reqs_errors.c b/src/reqs_errors.c index 5ba80f66..f734f1d8 100644 --- a/src/reqs_errors.c +++ b/src/reqs_errors.c @@ -189,7 +189,7 @@ reqs_errors_rem_uri(char const *uri) return; while (found_uri->uri_related != NULL) - found_uri = find_error_uri(uri); + found_uri = find_error_uri(found_uri->uri_related); rwlock_write_lock(&db_lock); do { @@ -211,6 +211,9 @@ reqs_errors_log_uri(char const *uri) unsigned int config_period; int error; + if (log_op_debug_enabled()) + return true; + if (working_repo_peek_level() > LOG_REPO_LEVEL) return false; diff --git a/src/rrdp/rrdp_parser.c b/src/rrdp/rrdp_parser.c index cb978e83..7fecc65b 100644 --- a/src/rrdp/rrdp_parser.c +++ b/src/rrdp/rrdp_parser.c @@ -129,7 +129,7 @@ download_file(struct rpki_uri *uri, long last_update, bool log_operation) return error; if (retries == config_get_rrdp_retry_count()) { - pr_val_info("Max RRDP retries (%u) reached fetching '%s', won't retry again.", + pr_val_warn("Max RRDP retries (%u) reached fetching '%s', won't retry again.", retries, uri_get_global(uri)); /* * Since distinct files can be downloaded (notification, @@ -139,7 +139,7 @@ download_file(struct rpki_uri *uri, long last_update, bool log_operation) */ return EREQFAILED; } - pr_val_info("Retrying RRDP file download '%s' in %u seconds, %u attempts remaining.", + pr_val_warn("Retrying RRDP file download '%s' in %u seconds, %u attempts remaining.", uri_get_global(uri), config_get_rrdp_retry_interval(), config_get_rrdp_retry_count() - retries); diff --git a/src/rsync/rsync.c b/src/rsync/rsync.c index 896e4984..bcbce2f6 100644 --- a/src/rsync/rsync.c +++ b/src/rsync/rsync.c @@ -278,8 +278,6 @@ log_buffer(char const *buffer, ssize_t read, int type, bool log_operation) pr_op_err(PRE_RSYNC "%s", cur); pr_val_err(PRE_RSYNC "%s", cur); } else { - if (log_operation) - pr_op_info(PRE_RSYNC "%s", cur); pr_val_info(PRE_RSYNC "%s", cur); } cur = tmp + 1; @@ -324,8 +322,8 @@ read_pipes(int fds[2][2], bool log_operation) if (error) return error; - /* stdout pipe */ - return read_pipe(fds, 1, log_operation); + /* stdout pipe, always logs to info */ + return read_pipe(fds, 1, true); } /* @@ -385,12 +383,12 @@ do_rsync(struct rpki_uri *uri, bool is_ta, bool log_operation) return 0; } if (retries == config_get_rsync_retry_count()) { - pr_val_info("Max RSYNC retries (%u) reached on '%s', won't retry again.", + pr_val_warn("Max RSYNC retries (%u) reached on '%s', won't retry again.", retries, uri_get_global(uri)); return EREQFAILED; } - pr_val_info("Retrying RSYNC '%s' in %u seconds, %u attempts remaining.", + pr_val_warn("Retrying RSYNC '%s' in %u seconds, %u attempts remaining.", uri_get_global(uri), config_get_rsync_retry_interval(), config_get_rsync_retry_count() - retries); @@ -485,6 +483,9 @@ download_files(struct rpki_uri *requested_uri, bool is_ta, bool force) if (error) break; error = mark_as_downloaded(rsync_uri, visited_uris); + /* Everything went ok? Return the original error */ + if (!error) + error = EREQFAILED; break; default: break;