Tweak debug traces

diff --git a/src/cache.c b/src/cache.c
index f469413be451bd8d3011a2a8e85fb9222431ad39..4c615a9829eba71b821b15451d26cdbe6c220456 100644 (file)
--- a/src/cache.c
+++ b/src/cache.c
@@ -855,11 +855,11 @@ rm_metadata(struct cache_node *node)
        int error;
 
        filename = str_concat(node->path, ".json");
-       pr_trc("rm %s", filename);
+       pr_trc("rm -f %s", filename);
        if (unlink(filename) < 0) {
                error = errno;
                if (error == ENOENT)
-                       pr_trc("%s already doesn't exist.", filename);
+                       pr_clutter("%s already doesn't exist.", filename);
                else
                        pr_wrn("Cannot rm %s: %s", filename, strerror(errno));
        }
@@ -946,6 +946,7 @@ ongoing:    mutex_unlock(&tbl->lock);
                pr_trc("Refresh ongoing.");
                return VV_BUSY;
        case DLS_FRESH:
+               pr_trc("Already downloaded.");
                break;
        default:
                pr_panic("Unknown node state: %d", node->state);
@@ -1122,7 +1123,7 @@ node2file(struct cache_node const *node, struct uri const *url)
 
 /* Result needs free() */
 char *
-cage_map_file(struct cache_cage *cage, struct uri const *url)
+cage_map_file(struct cache_cage *cage, struct uri const *url, char const **type)
 {
        /*
         * Remember: In addition to honoring the consts of cache->refresh and
@@ -1133,10 +1134,18 @@ cage_map_file(struct cache_cage *cage, struct uri const *url)
        char *file;
 
        file = node2file(cage->refresh, url);
-       if (!file)
-               file = node2file(cage->fallback, url);
+       if (file) {
+               *type = cage->refresh->rrdp ? "RRDP refresh" : "rsync refresh";
+               return file;
+       }
+
+       file = node2file(cage->fallback, url);
+       if (file) {
+               *type = cage->fallback->rrdp ? "RRDP fallback" : "rsync fallback";
+               return file;
+       }
 
-       return file;
+       return NULL;
 }
 
 /*
@@ -1182,7 +1191,7 @@ cache_commit_rpp(struct uri const *rpkiNotify, struct uri const *caRepository,
 {
        struct cache_commit *commit;
 
-       pr_trc("Listing for commit: [%s, %s]",
+       pr_trc("Queuing RPP for commit: [%s, %s]",
            rpkiNotify ? uri_str(rpkiNotify) : "NULL",
            uri_str(caRepository));
 
@@ -1417,9 +1426,9 @@ commit_fallbacks(time_t now)
                STAILQ_REMOVE_HEAD(&commits, lh);
 
                if (uri_str(&commit->caRepository) != NULL) {
-                       pr_trc("Creating fallback for %s (%s)",
-                           uri_str(&commit->caRepository),
-                           uri_str(&commit->rpkiNotify));
+                       pr_trc("Creating fallback for [%s, %s]",
+                           uri_str(&commit->rpkiNotify),
+                           uri_str(&commit->caRepository));
 
                        fb = provide_node(&cache.fallback,
                            &commit->rpkiNotify,
@@ -1445,7 +1454,8 @@ commit_fallbacks(time_t now)
                } else { /* TA */
                        struct cache_mapping *map = &commit->files[0];
 
-                       pr_trc("Creating fallback for %s", uri_str(&map->url));
+                       pr_trc("Creating fallback for [NULL, %s]",
+                           uri_str(&map->url));
 
                        fb = provide_node(&cache.fallback, &map->url, NULL);
                        fb->attempt_ts = now;
@@ -1510,35 +1520,36 @@ cleanup_cache(void)
        time_t now = time_fatal();
 
        /* Delete the entirety of cache/tmp/. */
-       pr_trc("Cleaning up temporal files.");
+       pr_trc("- Cleaning up temporal files.");
        file_rm_rf(CACHE_TMPDIR);
 
        /*
         * Ensure valid RPPs and TAs are linked in fallback,
         * by hard-linking the new files.
         */
-       pr_trc("Committing fallbacks.");
+       pr_trc("- Committing fallbacks.");
        commit_fallbacks(now);
 
        /*
         * Delete refresh nodes that haven't been downloaded in a while,
         * and fallback nodes that haven't been valid in a while.
         */
-       pr_trc("Cleaning up abandoned cache files.");
+       pr_trc("- Cleaning up abandoned cache files.");
        foreach_node(remove_abandoned, &now);
 
        /* (Paranoid) Delete nodes that are no longer mapped to files. */
-       pr_trc("Cleaning up orphaned nodes.");
+       pr_trc("- Cleaning up orphaned nodes.");
        foreach_node(remove_orphaned_nodes, NULL);
 
        /* (Paranoid) Delete files that are no longer mapped to nodes. */
-       pr_trc("Cleaning up orphaned files.");
+       pr_trc("- Cleaning up orphaned files.");
        remove_orphaned_files();
 }
 
 void
 cache_commit(void)
 {
+       pr_trc("============ Committing cache ============");
        cleanup_cache();
        file_write_txt(METAFILE, "{ \"fort-version\": \"" PACKAGE_VERSION "\" }");
        unlock_cache();

diff --git a/src/cache.h b/src/cache.h
index bebd072acff745308d6adcea4e6ba2a94d98e509..258d6139cae822b9a9201fc9490f4643c9db1867 100644 (file)
--- a/src/cache.h
+++ b/src/cache.h
@@ -42,7 +42,7 @@ validation_verdict cache_get_fallback(struct uri const *, char **);
 struct cache_cage;
 validation_verdict cache_refresh_by_uris(struct extension_uris *,
     struct cache_cage **);
-char *cage_map_file(struct cache_cage *, struct uri const *);
+char *cage_map_file(struct cache_cage *, struct uri const *, char const **);
 bool cage_downgrade(struct cache_cage *);
 struct mft_meta const *cage_mft_fallback(struct cache_cage *);
 void cache_commit_rpp(struct uri const *, struct uri const *, struct rpp *);

diff --git a/src/common.c b/src/common.c
index 72520b08b95a3d59c7f042f084538764016324ee..ebbd7ddf472dcdde8efb5ff7284871c35554a3ec 100644 (file)
--- a/src/common.c
+++ b/src/common.c
@@ -14,7 +14,7 @@
 #include "alloc.h"
 #include "log.h"
 
-validation_verdict const VV_CONTINUE = "Continue";
+validation_verdict const VV_CONTINUE = "Success";
 validation_verdict const VV_FAIL = "Failure";
 validation_verdict const VV_BUSY = "Busy";
 

diff --git a/src/file.c b/src/file.c
index dca6ace9dcb2c1f3a301bce81e5b2e4e05bf060d..fad2e95920815f8ad59d6cf5f81a2e6b8515111d 100644 (file)
--- a/src/file.c
+++ b/src/file.c
@@ -90,7 +90,6 @@ file_write_txt(char const *path, char const *txt)
 int
 file_write_bin(char const *path, unsigned char const *bytes, size_t n)
 {
-       pr_trc("echo 'beep boop' > %s", path);
        return write_file(path, bytes, n);
 }
 

diff --git a/src/nid.c b/src/nid.c
index f3e1969d1f4a41ef7bb9a12e63eaf4fa74f19fad..cec2b85ebd0c7a2d82ba22949a51e3a205e8beca 100644 (file)
--- a/src/nid.c
+++ b/src/nid.c
@@ -32,10 +32,10 @@ register_oid(const char *oid, const char *sn, const char *ln)
                        pr_crypto_err("Unable to register the %s NID.", sn);
                        return 0;
                }
-               pr_trc("%s registered. Its nid is %d.", sn, nid);
+               pr_clutter("%s registered. Its nid is %d.", sn, nid);
 
        } else {
-               pr_trc("%s retrieved. Its nid is %d.", sn, nid);
+               pr_clutter("%s retrieved. Its nid is %d.", sn, nid);
        }
 
        return nid;

diff --git a/src/object/certificate.c b/src/object/certificate.c
index 181fde1fb6200a682e4555e76a9765d79c49b0a1..6eaf432e4b5370bb13ba6beede7f7a67c2a2df62 100644 (file)
--- a/src/object/certificate.c
+++ b/src/object/certificate.c
@@ -1988,12 +1988,15 @@ cer_traverse(struct rpki_certificate *ca)
 {
        struct cache_cage *cage;
        struct cache_mapping mft;
+       char const *rpp_type;
        array_index i;
        struct cache_mapping *map;
        unsigned int queued;
        validation_verdict vv;
        int error;
 
+       pr_trc("Checking certificate %s...", uri_str(&ca->map.url));
+
        if (!ca->x509) {
                if (validate_certificate(ca) != 0)
                        return VV_FAIL;
@@ -2001,6 +2004,8 @@ cer_traverse(struct rpki_certificate *ca)
                        return VV_CONTINUE;
        } /* else "we already did this, and returned VV_BUSY" */
 
+       pr_trc("Certificate seems correct; downloading RPP.");
+
        vv = cache_refresh_by_uris(&ca->uris, &cage);
        if (vv == VV_BUSY)
                return VV_BUSY;
@@ -2013,7 +2018,7 @@ cer_traverse(struct rpki_certificate *ca)
        }
 
        mft.url = ca->uris.rpkiManifest;
-retry: mft.path = cage_map_file(cage, &mft.url);
+retry: mft.path = cage_map_file(cage, &mft.url, &rpp_type);
        if (!mft.path) {
                if (cage_downgrade(cage))
                        goto retry;
@@ -2023,6 +2028,8 @@ retry:    mft.path = cage_map_file(cage, &mft.url);
                goto end;
        }
 
+       pr_trc("Checking %s RPP...", rpp_type);
+
        error = manifest_traverse(&mft, cage, ca);
        free(mft.path);
        if (error) {
@@ -2043,6 +2050,8 @@ retry:    mft.path = cage_map_file(cage, &mft.url);
                        ghostbusters_traverse(map, ca);
        }
 
+       pr_trc("RPP seems sufficiently correct.");
+
        if (queued > 0)
                task_wakeup();
        cache_commit_rpp(cage_rpkiNotify(cage), &ca->uris.caRepository,

diff --git a/src/object/manifest.c b/src/object/manifest.c
index e01233626d70464db55f4b1bb11545dcb3d4c719..8102b5b543f1b6a027c76066e4a1e8f85197eea0 100644 (file)
--- a/src/object/manifest.c
+++ b/src/object/manifest.c
@@ -334,7 +334,7 @@ collect_files(struct cache_mapping const *map,
                uri_child(&rpp_url, (char const *)src->file.buf, src->file.size,
                    &dst->url);
 
-               dst->path = cage_map_file(cage, &dst->url);
+               dst->path = cage_map_file(cage, &dst->url, &ext);
                if (!dst->path) {
                        error = pr_err(
                            "Manifest file '%s' is absent from the cache.",

diff --git a/src/object/tal.c b/src/object/tal.c
index 5260dd9b9fcd1914e177f52030712d5aef259b11..fa0831f24b1493ca20a1c071028419dd170a94ff 100644 (file)
--- a/src/object/tal.c
+++ b/src/object/tal.c
@@ -211,16 +211,20 @@ traverse_tal(char const *path)
        }
 
        /* Online attempts */
+       pr_trc("Trying HTTP refresh.");
        vv = try_urls(tal, uri_is_https, cache_refresh_by_url);
        if (vv != VV_FAIL)
                goto end2;
+       pr_trc("Trying rsync refresh.");
        vv = try_urls(tal, uri_is_rsync, cache_refresh_by_url);
        if (vv != VV_FAIL)
                goto end2;
        /* Offline fallback attempts */
+       pr_trc("Trying HTTP fallback.");
        vv = try_urls(tal, uri_is_https, cache_get_fallback);
        if (vv != VV_FAIL)
                goto end2;
+       pr_trc("Trying rsync fallback.");
        vv = try_urls(tal, uri_is_rsync, cache_get_fallback);
        if (vv != VV_FAIL)
                goto end2;
@@ -240,9 +244,12 @@ pick_up_work(void *arg)
        validation_verdict vv;
 
        while ((task = task_dequeue(task)) != NULL) {
+               pr_trc("Dequeued task: %s", task_name(task));
+
                switch (task->type) {
                case VTT_RPP:
-                       if (cer_traverse(task->u.ca) == VV_BUSY) {
+                       vv = cer_traverse(task->u.ca);
+                       if (vv == VV_BUSY) {
                                task_requeue_dormant(task);
                                task = NULL;
                        }
@@ -257,8 +264,11 @@ pick_up_work(void *arg)
                                task_wakeup();
                        }
                        break;
+               default:
+                       vv = VV_FAIL;
                }
 
+               pr_trc("Task ended. Status: %s", vv);
        }
 
        return NULL;

diff --git a/src/rrdp.c b/src/rrdp.c
index e6b39577ee12ca7b2fbd9c333bc02ee9ab80fe0a..5ce7bc63087542404a15bc22ee31d0da3756357b 100644 (file)
--- a/src/rrdp.c
+++ b/src/rrdp.c
@@ -633,6 +633,7 @@ handle_publish(xmlTextReaderPtr reader, struct parser_args *args)
                file = cache_file_add(args->state, &tag.meta.uri, path);
        }
 
+       pr_clutter("echo '$%s' > %s", file->map.url, file->map.path);
        error = file_write_bin(file->map.path, tag.content, tag.content_len);
 
 end:   metadata_cleanup(&tag.meta);
@@ -907,7 +908,14 @@ parse_snapshot(struct rrdp_session *session, char const *path,
     struct rrdp_state *state)
 {
        struct parser_args args = { .session = session, .state = state };
-       return relax_ng_parse(path, xml_read_snapshot, &args);
+       int error;
+
+       pr_trc("Exploding snapshot into %s...", state->seq.prefix);
+
+       error = relax_ng_parse(path, xml_read_snapshot, &args);
+
+       pr_trc("Snapshot exploded.");
+       return error;
 }
 
 static int
@@ -961,7 +969,6 @@ handle_snapshot(struct update_notification *new, struct rrdp_state *state)
        int error;
 
        url = &new->snapshot.uri;
-       pr_trc("Processing snapshot '%s'.", uri_str(url));
        fnstack_push(uri_str(url));
 
        error = dl_tmp(url, tmppath);
@@ -1018,12 +1025,16 @@ parse_delta(struct update_notification *notif, struct notification_delta *delta,
        if (error)
                return error;
 
+       pr_trc("Exploding delta into %s...", state->seq.prefix);
        session.session_id = notif->session.session_id;
        session.serial = delta->serial;
        args.session = &session;
        args.state = state;
 
-       return relax_ng_parse(path, xml_read_delta, &args);
+       error = relax_ng_parse(path, xml_read_delta, &args);
+
+       pr_trc("Delta exploded.");
+       return error;
 }
 
 static int
@@ -1240,7 +1251,6 @@ rrdp_update(struct uri const *notif, char const *path, time_t mtim,
        int error;
 
        fnstack_push(uri_str(notif));
-       pr_trc("Processing notification.");
 
        error = dl_notif(notif, mtim, changed, &new);
        if (error)

diff --git a/src/task.c b/src/task.c
index b4028a1528cf9bbf0cd5b6a7c1ee7efd5acfcf33..0fa4f055b939c28d6aed4cde865afe1e3d514ca2 100644 (file)
--- a/src/task.c
+++ b/src/task.c
@@ -22,7 +22,7 @@ static bool enabled = true;
 static pthread_mutex_t lock = PTHREAD_MUTEX_INITIALIZER;
 static pthread_cond_t awakener = PTHREAD_COND_INITIALIZER;
 
-static char const *
+char const *
 task_name(struct validation_task *task)
 {
        switch (task->type) {
@@ -243,36 +243,36 @@ task_dequeue(struct validation_task *prev)
        }
 
        while (ntasks > 0) {
-               pr_trc("task_dequeue(): %u existing tasks.", ntasks);
+               pr_clutter("task_dequeue(): %u existing tasks.", ntasks);
 
                task = STAILQ_FIRST(&waiting);
                if (task != NULL) {
                        STAILQ_REMOVE_HEAD(&waiting, lh);
                        mutex_unlock(&lock);
-                       pr_trc("task_dequeue(): Claimed task '%s'.",
+                       pr_clutter("task_dequeue(): Claimed task '%s'.",
                            task_name(task));
                        return task;
                }
 
-               pr_trc("task_dequeue(): Sleeping...");
+               pr_clutter("task_dequeue(): Sleeping...");
                timeout.tv_sec = time_fatal() + 10;
                error = pthread_cond_timedwait(&awakener, &lock, &timeout);
                switch (error) {
                case 0:
-                       pr_trc("task_dequeue(): Woke up by cond.");
+                       pr_clutter("task_dequeue(): Woke up by cond.");
                        break;
                case ETIMEDOUT:
-                       pr_trc("task_dequeue(): Woke up by timeout.");
+                       pr_clutter("task_dequeue(): Woke up by timeout.");
                        break;
                case EINTR:
-                       pr_trc("task_dequeue(): Interrupted by signal.");
+                       pr_clutter("task_dequeue(): Interrupted by signal.");
                        goto end;
                default:
                        panic_on_fail(error, "pthread_cond_wait");
                }
        }
 
-       pr_trc("task_dequeue(): No more tasks; done.");
+       pr_clutter("task_dequeue(): No more tasks; done.");
        panic_on_fail(pthread_cond_broadcast(&awakener),
            "pthread_cond_broadcast");
 end:   mutex_unlock(&lock);

diff --git a/src/task.h b/src/task.h
index 0d2ce245f6a012faf0a8fc350bb51c4675ead087..40a13a50ca8357ede91ec2f547ac95f5994101ad 100644 (file)
--- a/src/task.h
+++ b/src/task.h
@@ -26,6 +26,7 @@ void task_start(void);
 bool task_stop(void);
 void task_teardown(void);
 
+char const *task_name(struct validation_task *);
 unsigned int task_enqueue_tal(char const *);
 unsigned int task_enqueue_rpp(struct cache_mapping *, struct rpki_certificate *);
 void task_requeue_dormant(struct validation_task *);