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 5f6fa9c6a19b88fd43e10311dbc8d64dfc511977..936fb93523271aee2d52fab6191d222e0f9b7c56 100644 (file)
--- 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 199f33d26854b5c4dcdc8c586c08325fffcdb77a..f4978b618a8fdbbeacdd1990e7a9e59944865446 100644 (file)
--- 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 5ba80f66d2b7e7d9e48947c51d59f3b80451eb2c..f734f1d86947137404711ced6f15835023462d2e 100644 (file)
--- 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 cb978e836aaff6b03986c630a4dda73948c9f0de..7fecc65ba42f3eedc7b7a36bb17a3c8b0ceaea38 100644 (file)
--- 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 896e49842ea33956a645b56a1a0877b2a83997c3..bcbce2f664728837d750dadcba47e2465a55b64f 100644 (file)
--- 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;