]> git.proxmox.com Git - mirror_kronosnet.git/commitdiff
libknet: first big hammer on logging
authorFabio M. Di Nitto <fdinitto@redhat.com>
Fri, 2 Nov 2012 15:39:35 +0000 (16:39 +0100)
committerFabio M. Di Nitto <fdinitto@redhat.com>
Fri, 2 Nov 2012 15:39:35 +0000 (16:39 +0100)
still needs fine tuning as we go to understand exactly what to log
in debugging mode

Signed-off-by: Fabio M. Di Nitto <fdinitto@redhat.com>
kronosnetd/vty_cli_cmds.c
libknet/common.c
libknet/crypto.c
libknet/crypto.h
libknet/handle.c
libknet/host.c
libknet/libknet.h
libknet/listener.c
libknet/nsscrypto.c
libknet/nsscrypto.h
tests/ping_test.c

index ad4707a36b2169adf124c9979d545fdda6bad411..7d216136a1288c1d49fd4ac3cb90d682596a5010 100644 (file)
@@ -805,6 +805,8 @@ static int knet_cmd_link_dyn(struct knet_vty *vty)
 
 static int knet_cmd_link_timer(struct knet_vty *vty)
 {
+       struct knet_cfg *knet_iface = (struct knet_cfg *)vty->iface;
+       struct knet_host *host = (struct knet_host *)vty->host;
        struct knet_link *klink = (struct knet_link *)vty->link;
        int paramlen = 0, paramoffset = 0;
        char *param = NULL;
@@ -816,7 +818,7 @@ static int knet_cmd_link_timer(struct knet_vty *vty)
        get_param(vty, 2, &param, &paramlen, &paramoffset);
        holdtime = param_to_int(param, paramlen);
 
-       knet_link_timeout(klink, keepalive, holdtime, 2048);
+       knet_link_timeout(knet_iface->cfg_ring.knet_h, host->node_id, klink, keepalive, holdtime, 2048);
 
        return 0;
 }
@@ -928,7 +930,7 @@ static int knet_cmd_link(struct knet_vty *vty)
                        klink->sock = host->listener4->sock;
                }
 
-               knet_link_timeout(klink, 1000, 5000, 2048);
+               knet_link_timeout(knet_iface->cfg_ring.knet_h, host->node_id, klink, 1000, 5000, 2048);
 
                knet_link_enable(knet_iface->cfg_ring.knet_h, host->node_id, klink, 1);
        }
index 925faf03305aaaa4d1484feef7cce497c4b6c01c..4ffa7b3d37fdc07b8b0ff6c43891e679475b6ed4 100644 (file)
@@ -52,6 +52,7 @@ try_again:
                        write_retry++;
                        goto try_again;
                } else {
+                       log_debug(knet_h, KNET_SUB_COMMON, "Unable to write to comm pipe");
                        return -1;
                }
        }
index 5cd3c7a8161e8f46452902e4d2ede967b7861b77..a6d31322ae8d0c48bbcb71a6627db3a9c632ded9 100644 (file)
@@ -5,14 +5,7 @@
 
 #include "crypto.h"
 #include "nsscrypto.h"
-#include "libknet.h"
-
-#ifdef CRYPTO_DEBUG
-#include <stdio.h>
-#define log_printf(format, args...) fprintf(stderr, format "\n", ##args);
-#else
-#define log_printf(format, args...);
-#endif
+#include "libknet-private.h"
 
 /*
  * internal module switch data
@@ -40,28 +33,29 @@ static int get_model(const char *model)
  */
 
 int crypto_encrypt_and_sign (
-       struct crypto_instance *instance,
+       knet_handle_t knet_h,
        const unsigned char *buf_in,
        const ssize_t buf_in_len,
        unsigned char *buf_out,
        ssize_t *buf_out_len)
 {
-       return modules_cmds[instance->model].crypt(instance->model_instance,
-                                         buf_in, buf_in_len, buf_out, buf_out_len);
+       return modules_cmds[knet_h->crypto_instance->model].crypt(knet_h, buf_in, buf_in_len, buf_out, buf_out_len);
 }
 
-int crypto_authenticate_and_decrypt (struct crypto_instance *instance,
+int crypto_authenticate_and_decrypt (
+       knet_handle_t knet_h,
        unsigned char *buf,
        ssize_t *buf_len)
 {
-       return modules_cmds[instance->model].decrypt(instance->model_instance, buf, buf_len);
+       return modules_cmds[knet_h->crypto_instance->model].decrypt(knet_h, buf, buf_len);
 }
 
 int crypto_init(
        knet_handle_t knet_h,
        struct knet_handle_crypto_cfg *knet_handle_crypto_cfg)
 {
-       log_printf("Initizializing crypto module [%s/%s/%s]",
+       log_debug(knet_h, KNET_SUB_CRYPTO,
+                 "Initizializing crypto module [%s/%s/%s]",
                  knet_handle_crypto_cfg->crypto_model,
                  knet_handle_crypto_cfg->crypto_cipher_type,
                  knet_handle_crypto_cfg->crypto_hash_type);
@@ -69,13 +63,13 @@ int crypto_init(
        knet_h->crypto_instance = malloc(sizeof(struct crypto_instance));
 
        if (!knet_h->crypto_instance) {
-               log_printf("no memory from crypto");
+               log_err(knet_h, KNET_SUB_CRYPTO, "Unable to allocate memory for crypto instance");
                return -1;
        }
 
        knet_h->crypto_instance->model = get_model(knet_handle_crypto_cfg->crypto_model);
        if (knet_h->crypto_instance->model < 0) {
-               log_printf("model %s not supported", knet_handle_crypto_cfg->crypto_model);
+               log_err(knet_h, KNET_SUB_CRYPTO, "model %s not supported", knet_handle_crypto_cfg->crypto_model);
                goto out_err;
        }
 
index 4a82f1c606d3e0cfa552953d0428e963faa8e7db..70000805edad2a86a3aed2a1e18a168ff83175ae 100644 (file)
@@ -11,19 +11,26 @@ struct crypto_instance {
 
 typedef struct {
        const char      *model_name;
-       int (*init)     (knet_handle_t knet_h, struct knet_handle_crypto_cfg *knet_handle_crypto_cfg);
+       int (*init)     (knet_handle_t knet_h,
+                        struct knet_handle_crypto_cfg *knet_handle_crypto_cfg);
        void (*fini)    (knet_handle_t knet_h);
-       int (*crypt)    (void *model_instance, const unsigned char *buf_in, const ssize_t buf_in_len, unsigned char *buf_out, ssize_t *buf_out_len);
-       int (*decrypt)  (void *model_instance, unsigned char *buf, ssize_t *buf_len);
+       int (*crypt)    (knet_handle_t knet_h,
+                        const unsigned char *buf_in,
+                        const ssize_t buf_in_len,
+                        unsigned char *buf_out,
+                        ssize_t *buf_out_len);
+       int (*decrypt)  (knet_handle_t knet_h,
+                        unsigned char *buf,
+                        ssize_t *buf_len);
 } crypto_model_t;
 
 int crypto_authenticate_and_decrypt (
-       struct crypto_instance *instance,
+       knet_handle_t knet_h,
        unsigned char *buf,
        ssize_t *buf_len);
 
 int crypto_encrypt_and_sign (
-       struct crypto_instance *instance,
+       knet_handle_t knet_h,
        const unsigned char *buf_in,
        const ssize_t buf_in_len,
        unsigned char *buf_out, 
index d82eda5822ec381622d6c9c05b5f8445bdf63b1f..7eb6c5e9b186b9c0cb0d2d2fb4bcc42b2ad163f4 100644 (file)
@@ -54,38 +54,52 @@ knet_handle_t knet_handle_new(const struct knet_handle_cfg *knet_handle_cfg)
                }
        }
 
-       if (pipe(knet_h->pipefd))
+       if (pipe(knet_h->pipefd)) {
+               log_err(knet_h, KNET_SUB_HANDLE, "Unable to initialize internal comm pipe");
                goto exit_fail1;
+       }
 
        if ((_fdset_cloexec(knet_h->pipefd[0])) ||
            (_fdset_cloexec(knet_h->pipefd[1])) ||
            (_fdset_nonblock(knet_h->pipefd[0])) ||
-           (_fdset_nonblock(knet_h->pipefd[1])))
+           (_fdset_nonblock(knet_h->pipefd[1]))) {
+               log_err(knet_h, KNET_SUB_HANDLE, "Unable to set internal comm pipe sockopts");
                goto exit_fail2;
+       }
 
        knet_h->dst_host_filter = knet_handle_cfg->dst_host_filter;
        knet_h->dst_host_filter_fn = knet_handle_cfg->dst_host_filter_fn;
 
-       if ((knet_h->dst_host_filter) && (!knet_h->dst_host_filter_fn))
+       if ((knet_h->dst_host_filter) && (!knet_h->dst_host_filter_fn)) {
+               log_err(knet_h, KNET_SUB_HANDLE, "Incorrect dst_host_filter config requested");
                goto exit_fail2;
+       }
 
-       if ((knet_h->tap_to_links_buf = malloc(KNET_DATABUFSIZE))== NULL)
+       if ((knet_h->tap_to_links_buf = malloc(KNET_DATABUFSIZE))== NULL) {
+               log_err(knet_h, KNET_SUB_HANDLE, "Unable to allocate memory for tap to link buffer");
                goto exit_fail2;
+       }
 
        memset(knet_h->tap_to_links_buf, 0, KNET_DATABUFSIZE);
 
-       if ((knet_h->recv_from_links_buf = malloc(KNET_DATABUFSIZE))== NULL)
+       if ((knet_h->recv_from_links_buf = malloc(KNET_DATABUFSIZE))== NULL) {
+               log_err(knet_h, KNET_SUB_HANDLE, "Unable to allocate memory for link to tap buffer");
                goto exit_fail3;
+       }
 
        memset(knet_h->recv_from_links_buf, 0, KNET_DATABUFSIZE);
 
-       if ((knet_h->pingbuf = malloc(KNET_PINGBUFSIZE))== NULL)
+       if ((knet_h->pingbuf = malloc(KNET_PINGBUFSIZE))== NULL) {
+               log_err(knet_h, KNET_SUB_HANDLE, "Unable to allocate memory for hearbeat buffer");
                goto exit_fail4;
+       }
 
        memset(knet_h->pingbuf, 0, KNET_PINGBUFSIZE);
 
-       if (pthread_rwlock_init(&knet_h->list_rwlock, NULL) != 0)
+       if (pthread_rwlock_init(&knet_h->list_rwlock, NULL) != 0) {
+               log_err(knet_h, KNET_SUB_HANDLE, "Unable to initialize locks");
                goto exit_fail5;
+       }
 
        knet_h->tap_to_links_epollfd = epoll_create(KNET_MAX_EVENTS);
        knet_h->recv_from_links_epollfd = epoll_create(KNET_MAX_EVENTS);
@@ -93,13 +107,17 @@ knet_handle_t knet_handle_new(const struct knet_handle_cfg *knet_handle_cfg)
 
        if ((knet_h->tap_to_links_epollfd < 0) ||
            (knet_h->recv_from_links_epollfd < 0) ||
-           (knet_h->dst_link_handler_epollfd < 0))
+           (knet_h->dst_link_handler_epollfd < 0)) {
+               log_err(knet_h, KNET_SUB_HANDLE, "Unable to create epoll(s) fd(s)");
                goto exit_fail6;
+       }
 
        if ((_fdset_cloexec(knet_h->tap_to_links_epollfd) != 0) ||
            (_fdset_cloexec(knet_h->recv_from_links_epollfd) != 0) ||
-           (_fdset_cloexec(knet_h->dst_link_handler_epollfd) != 0))
+           (_fdset_cloexec(knet_h->dst_link_handler_epollfd) != 0)) {
+               log_err(knet_h, KNET_SUB_HANDLE, "Unable to set epoll(s) fd(s) opt(s)");
                goto exit_fail6;
+       }
 
        memset(&ev, 0, sizeof(struct epoll_event));
 
@@ -107,8 +125,10 @@ knet_handle_t knet_handle_new(const struct knet_handle_cfg *knet_handle_cfg)
        ev.data.fd = knet_h->sockfd;
 
        if (epoll_ctl(knet_h->tap_to_links_epollfd,
-                               EPOLL_CTL_ADD, knet_h->sockfd, &ev) != 0)
+                               EPOLL_CTL_ADD, knet_h->sockfd, &ev) != 0) {
+               log_err(knet_h, KNET_SUB_HANDLE, "Unable to add tapfd to epoll pool");
                goto exit_fail6;
+       }
 
        memset(&ev, 0, sizeof(struct epoll_event));
 
@@ -116,24 +136,34 @@ knet_handle_t knet_handle_new(const struct knet_handle_cfg *knet_handle_cfg)
        ev.data.fd = knet_h->pipefd[0];
 
        if (epoll_ctl(knet_h->dst_link_handler_epollfd,
-                               EPOLL_CTL_ADD, knet_h->pipefd[0], &ev) != 0)
+                               EPOLL_CTL_ADD, knet_h->pipefd[0], &ev) != 0) {
+               log_err(knet_h, KNET_SUB_HANDLE, "Unable to add pipefd to epoll pool");
                goto exit_fail6;
+       }
 
        if (pthread_create(&knet_h->dst_link_handler_thread, 0,
-                               _handle_dst_link_handler_thread, (void *) knet_h) != 0)
+                               _handle_dst_link_handler_thread, (void *) knet_h) != 0) {
+               log_err(knet_h, KNET_SUB_HANDLE, "Unable to start switching manager thread");
                goto exit_fail6;
+       }
 
        if (pthread_create(&knet_h->tap_to_links_thread, 0,
-                               _handle_tap_to_links_thread, (void *) knet_h) != 0)
+                               _handle_tap_to_links_thread, (void *) knet_h) != 0) {
+               log_err(knet_h, KNET_SUB_HANDLE, "Unable to start sending thread");
                goto exit_fail7;
+       }
 
        if (pthread_create(&knet_h->recv_from_links_thread, 0,
-                               _handle_recv_from_links_thread, (void *) knet_h) != 0)
+                               _handle_recv_from_links_thread, (void *) knet_h) != 0) {
+               log_err(knet_h, KNET_SUB_HANDLE, "Unable to start receiving thread");
                goto exit_fail8;
+       }
 
        if (pthread_create(&knet_h->heartbt_thread, 0,
-                               _handle_heartbt_thread, (void *) knet_h) != 0)
+                               _handle_heartbt_thread, (void *) knet_h) != 0) {
+               log_err(knet_h, KNET_SUB_HANDLE, "Unable to start heartbeat thread");
                goto exit_fail9;
+       }
 
        return knet_h;
 
@@ -178,31 +208,41 @@ int knet_handle_free(knet_handle_t knet_h)
 {
        void *retval;
 
-       if ((knet_h->host_head != NULL) || (knet_h->listener_head != NULL))
+       if ((knet_h->host_head != NULL) || (knet_h->listener_head != NULL)) {
+               log_err(knet_h, KNET_SUB_HANDLE, "Unable to free handle: host(s) or listener(s) are still active");
                goto exit_busy;
+       }
 
        pthread_cancel(knet_h->heartbt_thread);
        pthread_join(knet_h->heartbt_thread, &retval);
 
-       if (retval != PTHREAD_CANCELED)
+       if (retval != PTHREAD_CANCELED) {
+               log_err(knet_h, KNET_SUB_HANDLE, "Unable to stop heartbeat thread");
                goto exit_busy;
+       }
 
        pthread_cancel(knet_h->tap_to_links_thread);
        pthread_join(knet_h->tap_to_links_thread, &retval);
-       if (retval != PTHREAD_CANCELED)
+       if (retval != PTHREAD_CANCELED) {
+               log_err(knet_h, KNET_SUB_HANDLE, "Unable to stop sending thread");
                goto exit_busy;
+       }
 
        pthread_cancel(knet_h->recv_from_links_thread);
        pthread_join(knet_h->recv_from_links_thread, &retval);
 
-       if (retval != PTHREAD_CANCELED)
+       if (retval != PTHREAD_CANCELED) {
+               log_err(knet_h, KNET_SUB_HANDLE, "Unable to stop receiving thread");
                goto exit_busy;
+       }
 
        pthread_cancel(knet_h->dst_link_handler_thread);
        pthread_join(knet_h->dst_link_handler_thread, &retval);
 
-       if (retval != PTHREAD_CANCELED)
+       if (retval != PTHREAD_CANCELED) {
+               log_err(knet_h, KNET_SUB_HANDLE, "Unable to stop switching manager thread");
                goto exit_busy;
+       }
 
        close(knet_h->tap_to_links_epollfd);
        close(knet_h->recv_from_links_epollfd);
@@ -234,14 +274,17 @@ void knet_handle_setfwd(knet_handle_t knet_h, int enabled)
 
 int knet_handle_crypto(knet_handle_t knet_h, struct knet_handle_crypto_cfg *knet_handle_crypto_cfg)
 {
-       if (knet_h->enabled)
+       if (knet_h->enabled) {
+               log_err(knet_h, KNET_SUB_CRYPTO, "Cannot enable crypto while forwarding is enabled");
                return -1;
+       }
 
        crypto_fini(knet_h);
 
        if ((!strncmp("none", knet_handle_crypto_cfg->crypto_model, 4)) || 
            ((!strncmp("none", knet_handle_crypto_cfg->crypto_cipher_type, 4)) &&
             (!strncmp("none", knet_handle_crypto_cfg->crypto_hash_type, 4)))) {
+               log_debug(knet_h, KNET_SUB_CRYPTO, "crypto is not enabled");
                return 0;
        }
 
@@ -261,6 +304,12 @@ static int knet_link_updown(knet_handle_t knet_h, uint16_t node_id,
        lnk->connected = connected;
 
        if (_dst_cache_update(knet_h, node_id)) {
+               log_debug(knet_h, KNET_SUB_LINK,
+                         "Unable to update link status (host: %s link: %s configured: %u connected: %u)",
+                         knet_h->host_index[node_id]->name,
+                         lnk->ipaddr,
+                         lnk->configured,
+                         lnk->connected);
                lnk->configured = old_configured;
                lnk->connected = old_connected;
                return -1;
@@ -274,6 +323,8 @@ static int knet_link_updown(knet_handle_t knet_h, uint16_t node_id,
 
 int knet_link_enable(knet_handle_t knet_h, uint16_t node_id, struct knet_link *lnk, int configured)
 {
+       log_debug(knet_h, KNET_SUB_LINK, "host: %s link: %s is enabled",
+                 knet_h->host_index[node_id]->name, lnk->ipaddr);
        return knet_link_updown(knet_h, node_id, lnk, configured, lnk->connected);
 }
 
@@ -287,14 +338,25 @@ int knet_link_priority(knet_handle_t knet_h, uint16_t node_id, struct knet_link
        lnk->priority = priority;
 
        if (_dst_cache_update(knet_h, node_id)) {
+               log_debug(knet_h, KNET_SUB_LINK,
+                         "Unable to update link priority (host: %s link: %s priority: %u)",
+                         knet_h->host_index[node_id]->name,
+                         lnk->ipaddr,
+                         lnk->priority);
                lnk->priority = old_priority;
                return -1;
        }
 
+       log_debug(knet_h, KNET_SUB_LINK,
+                 "host: %s link: %s priority set to: %u",
+                 knet_h->host_index[node_id]->name,
+                 lnk->ipaddr,
+                 lnk->priority);
+
        return 0;
 }
 
-void knet_link_timeout(struct knet_link *lnk,
+void knet_link_timeout(knet_handle_t knet_h, uint16_t node_id, struct knet_link *lnk,
                                time_t interval, time_t timeout, int precision)
 {
        lnk->ping_interval = interval * 1000; /* microseconds */
@@ -302,6 +364,10 @@ void knet_link_timeout(struct knet_link *lnk,
        lnk->latency_fix = precision;
        lnk->latency_exp = precision - \
                                ((lnk->ping_interval * precision) / 8000000);
+       log_debug(knet_h, KNET_SUB_LINK,
+                 "host: %s link: %s timeout update - interval: %llu timeout: %llu precision: %d",
+                 knet_h->host_index[node_id]->name, lnk->ipaddr,
+                 lnk->ping_interval, lnk->pong_timeout, precision);
 }
 
 static void _handle_tap_to_links(knet_handle_t knet_h)
@@ -318,6 +384,7 @@ static void _handle_tap_to_links(knet_handle_t knet_h)
                                        KNET_DATABUFSIZE - (KNET_FRAME_SIZE + sizeof(seq_num_t)));
 
        if (inlen == 0) {
+               log_err(knet_h, KNET_SUB_TAP_T, "Unrecoverable error! Got 0 bytes from tap device!");
                /* TODO: disconnection, should never happen! */
                return;
        }
@@ -334,32 +401,41 @@ static void _handle_tap_to_links(knet_handle_t knet_h)
                                knet_h->tap_to_links_buf->kf_node,
                                dst_host_ids,
                                &dst_host_ids_entries);
-               if (bcast < 0)
+               if (bcast < 0) {
+                       log_debug(knet_h, KNET_SUB_TAP_T, "Error from dst_host_filter_fn: %d", bcast);
                        return;
+               }
 
-               if ((!bcast) && (!dst_host_ids_entries))
+               if ((!bcast) && (!dst_host_ids_entries)) {
+                       log_debug(knet_h, KNET_SUB_TAP_T, "Message is unicast but no dst_host_ids_entries");
                        return;
+               }
        }
 
-       if (pthread_rwlock_rdlock(&knet_h->list_rwlock) != 0)
+       if (pthread_rwlock_rdlock(&knet_h->list_rwlock) != 0) {
+               log_debug(knet_h, KNET_SUB_TAP_T, "Unable to get read lock");
                return;
+       }
 
        if (!bcast) {
                int host_idx;
 
                for (host_idx = 0; host_idx < dst_host_ids_entries; host_idx++) {
                        dst_host = knet_h->host_index[dst_host_ids[host_idx]];
-                       if (!dst_host)
+                       if (!dst_host) {
+                               log_debug(knet_h, KNET_SUB_TAP_T, "unicast packet, host not found");
                                continue;
+                       }
 
                        knet_h->tap_to_links_buf->kf_seq_num = htons(++dst_host->ucast_seq_num_tx);
 
                        if (knet_h->crypto_instance) {
-                               if (crypto_encrypt_and_sign(knet_h->crypto_instance,
+                               if (crypto_encrypt_and_sign(knet_h,
                                                    (const unsigned char *)knet_h->tap_to_links_buf,
                                                    len,
                                                    knet_h->tap_to_links_buf_crypt,
                                                    &outlen) < 0) {
+                                       log_debug(knet_h, KNET_SUB_TAP_T, "Unable to encrypt unicast packet");
                                        pthread_rwlock_unlock(&knet_h->list_rwlock);
                                        return;
                                }
@@ -387,11 +463,12 @@ static void _handle_tap_to_links(knet_handle_t knet_h)
                knet_h->tap_to_links_buf->kf_seq_num = htons(++knet_h->bcast_seq_num_tx);
 
                if (knet_h->crypto_instance) {
-                       if (crypto_encrypt_and_sign(knet_h->crypto_instance,
+                       if (crypto_encrypt_and_sign(knet_h,
                                            (const unsigned char *)knet_h->tap_to_links_buf,
                                            len,
                                            knet_h->tap_to_links_buf_crypt,
                                            &outlen) < 0) {
+                               log_debug(knet_h, KNET_SUB_TAP_T, "Unable to encrypt mcast/bcast packet");
                                pthread_rwlock_unlock(&knet_h->list_rwlock);
                                return;
                        }
@@ -434,32 +511,43 @@ static void _handle_recv_from_links(knet_handle_t knet_h, int sockfd)
        struct timespec recvtime;
        unsigned char *outbuf = (unsigned char *)knet_h->recv_from_links_buf;
 
-       if (pthread_rwlock_rdlock(&knet_h->list_rwlock) != 0)
+       if (pthread_rwlock_rdlock(&knet_h->list_rwlock) != 0) {
+               log_debug(knet_h, KNET_SUB_LINK_T, "Unable to get read lock");
                return;
+       }
 
        addrlen = sizeof(struct sockaddr_storage);
        len = recvfrom(sockfd, knet_h->recv_from_links_buf, KNET_DATABUFSIZE,
                MSG_DONTWAIT, (struct sockaddr *) &address, &addrlen);
 
        if (knet_h->crypto_instance) {
-               if (crypto_authenticate_and_decrypt(knet_h->crypto_instance,
+               if (crypto_authenticate_and_decrypt(knet_h,
                                                    (unsigned char *)knet_h->recv_from_links_buf,
-                                                   &len) < 0)
+                                                   &len) < 0) {
+                       log_debug(knet_h, KNET_SUB_LINK_T, "Unable to decrypt/auth packet");
                        goto exit_unlock;
+               }
        }
 
-       if (len < (KNET_FRAME_SIZE + 1))
+       if (len < (KNET_FRAME_SIZE + 1)) {
+               log_debug(knet_h, KNET_SUB_LINK_T, "Packet is too short");
                goto exit_unlock;
+       }
 
-       if (ntohl(knet_h->recv_from_links_buf->kf_magic) != KNET_FRAME_MAGIC)
+       if (ntohl(knet_h->recv_from_links_buf->kf_magic) != KNET_FRAME_MAGIC) {
+               log_debug(knet_h, KNET_SUB_LINK_T, "Packet does not contain knet magic number");
                goto exit_unlock;
+       }
 
-       if (knet_h->recv_from_links_buf->kf_version != KNET_FRAME_VERSION)
+       if (knet_h->recv_from_links_buf->kf_version != KNET_FRAME_VERSION) {
+               log_debug(knet_h, KNET_SUB_LINK_T, "Packet version does not match");
                goto exit_unlock;
+       }
 
        knet_h->recv_from_links_buf->kf_node = ntohs(knet_h->recv_from_links_buf->kf_node);
        src_host = knet_h->host_index[knet_h->recv_from_links_buf->kf_node];
        if (src_host == NULL) {  /* host not found */
+               log_debug(knet_h, KNET_SUB_LINK_T, "Unable to find source host for this packet");
                goto exit_unlock;
        }
 
@@ -497,11 +585,15 @@ static void _handle_recv_from_links(knet_handle_t knet_h, int sockfd)
                                        knet_h->recv_from_links_buf->kf_node,
                                        dst_host_ids,
                                        &dst_host_ids_entries);
-                       if (bcast < 0)
+                       if (bcast < 0) {
+                               log_debug(knet_h, KNET_SUB_LINK_T, "Error from dst_host_filter_fn: %d", bcast);
                                goto exit_unlock;
+                       }
 
-                       if ((!bcast) && (!dst_host_ids_entries))
+                       if ((!bcast) && (!dst_host_ids_entries)) {
+                               log_debug(knet_h, KNET_SUB_LINK_T, "Message is unicast but no dst_host_ids_entries");
                                goto exit_unlock;
+                       }
 
                        /* check if we are dst for this packet */
                        if (!bcast) {
@@ -511,18 +603,25 @@ static void _handle_recv_from_links(knet_handle_t knet_h, int sockfd)
                                                break;
                                        }
                                }
-                               if (!found)
+                               if (!found) {
+                                       log_debug(knet_h, KNET_SUB_LINK_T, "Packet is not for us");
                                        goto exit_unlock;
+                               }
                        }
                }
 
-               if (!knet_should_deliver(src_host, bcast, knet_h->recv_from_links_buf->kf_seq_num))
+               if (!knet_should_deliver(src_host, bcast, knet_h->recv_from_links_buf->kf_seq_num)) {
+                       log_debug(knet_h, KNET_SUB_LINK_T, "Packet has already been delivered");
                        goto exit_unlock;
+               }
 
                if (write(knet_h->sockfd,
                          knet_h->recv_from_links_buf->kf_data,
-                         len - (KNET_FRAME_SIZE + sizeof(seq_num_t))) == len - (KNET_FRAME_SIZE + sizeof(seq_num_t)))
+                         len - (KNET_FRAME_SIZE + sizeof(seq_num_t))) == len - (KNET_FRAME_SIZE + sizeof(seq_num_t))) {
                        knet_has_been_delivered(src_host, bcast, knet_h->recv_from_links_buf->kf_seq_num);
+               } else {
+                       log_debug(knet_h, KNET_SUB_LINK_T, "Packet has not been delivered");
+               }
 
                break;
        case KNET_FRAME_PING:
@@ -531,13 +630,14 @@ static void _handle_recv_from_links(knet_handle_t knet_h, int sockfd)
                knet_h->recv_from_links_buf->kf_node = htons(knet_h->node_id);
 
                if (knet_h->crypto_instance) {
-                       if (crypto_encrypt_and_sign(knet_h->crypto_instance,
+                       if (crypto_encrypt_and_sign(knet_h,
                                                    (const unsigned char *)knet_h->recv_from_links_buf,
                                                    len,
                                                    knet_h->recv_from_links_buf_crypt,
-                                                   &outlen) < 0)
+                                                   &outlen) < 0) {
+                               log_debug(knet_h, KNET_SUB_LINK_T, "Unable to encrypt pong packet");
                                break;
-
+                       }
                        outbuf = knet_h->recv_from_links_buf_crypt;
                }
 
@@ -561,6 +661,8 @@ static void _handle_recv_from_links(knet_handle_t knet_h, int sockfd)
 
                if (src_link->latency < src_link->pong_timeout) {
                        if (!src_link->connected) {
+                               log_info(knet_h, KNET_SUB_LINK, "host: %s link: %s is up",
+                                        src_host->name, src_link->ipaddr);
                                knet_link_updown(knet_h, src_host->node_id, src_link, src_link->configured, 1);
                        }
                }
@@ -581,15 +683,21 @@ static void _handle_dst_link_updates(knet_handle_t knet_h)
        int link_idx;
        int best_priority = -1;
 
-       if (read(knet_h->pipefd[0], &dst_host_id, sizeof(dst_host_id)) != sizeof(dst_host_id))
+       if (read(knet_h->pipefd[0], &dst_host_id, sizeof(dst_host_id)) != sizeof(dst_host_id)) {
+               log_debug(knet_h, KNET_SUB_SWITCH_T, "Short read on pipe");
                return;
+       }
 
-       if (pthread_rwlock_wrlock(&knet_h->list_rwlock) != 0)
+       if (pthread_rwlock_wrlock(&knet_h->list_rwlock) != 0) {
+               log_debug(knet_h, KNET_SUB_SWITCH_T, "Unable to get read lock");
                return;
+       }
 
        dst_host = knet_h->host_index[dst_host_id];
-       if (!dst_host)
+       if (!dst_host) {
+               log_debug(knet_h, KNET_SUB_SWITCH_T, "Unable to find host");
                goto out_unlock;
+       }
 
        dst_host->active_link_entries = 0;
 
@@ -613,8 +721,18 @@ static void _handle_dst_link_updates(knet_handle_t knet_h)
                }
        }
 
+       if (dst_host->link_handler_policy == KNET_LINK_POLICY_PASSIVE) {
+               log_debug(knet_h, KNET_SUB_SWITCH_T, "host: %s (passive) best link: %s (%u)",
+                         dst_host->name, dst_host->link[dst_host->active_links[0]].ipaddr,
+                         dst_host->link[dst_host->active_links[0]].priority);
+       } else {
+               log_debug(knet_h, KNET_SUB_SWITCH_T, "host: %s has %u active links",
+                         dst_host->name, dst_host->active_link_entries);
+       }
+
        /* no active links, we can clean the circular buffers and indexes */
        if (!dst_host->active_link_entries) {
+               log_warn(knet_h, KNET_SUB_SWITCH_T, "host: %s has no active links", dst_host->name);
                memset(dst_host->bcast_circular_buffer, 0, KNET_CBUFFER_SIZE);
                memset(dst_host->ucast_circular_buffer, 0, KNET_CBUFFER_SIZE);
                dst_host->bcast_seq_num_rx = 0;
@@ -638,8 +756,10 @@ static void _handle_check_each(knet_handle_t knet_h, struct knet_host *dst_host,
        /* caching last pong to avoid race conditions */
        pong_last = dst_link->pong_last;
 
-       if (clock_gettime(CLOCK_MONOTONIC, &clock_now) != 0)
+       if (clock_gettime(CLOCK_MONOTONIC, &clock_now) != 0) {
+               log_debug(knet_h, KNET_SUB_HB_T, "Unable to get monotonic clock");
                return;
+       }
 
        timespec_diff(dst_link->ping_last, clock_now, &diff_ping);
 
@@ -649,12 +769,14 @@ static void _handle_check_each(knet_handle_t knet_h, struct knet_host *dst_host,
                knet_h->pingbuf->kf_dyn = dst_link->dynamic;
 
                if (knet_h->crypto_instance) {
-                       if (crypto_encrypt_and_sign(knet_h->crypto_instance,
+                       if (crypto_encrypt_and_sign(knet_h,
                                                    (const unsigned char *)knet_h->pingbuf,
                                                    KNET_PINGBUFSIZE,
                                                    knet_h->pingbuf_crypt,
-                                                   &outlen) < 0)
+                                                   &outlen) < 0) {
+                               log_debug(knet_h, KNET_SUB_HB_T, "Unable to crypto ping packet");
                                return;
+                       }
 
                        outbuf = knet_h->pingbuf_crypt;
                }
@@ -663,14 +785,19 @@ static void _handle_check_each(knet_handle_t knet_h, struct knet_host *dst_host,
                        MSG_DONTWAIT, (struct sockaddr *) &dst_link->address,
                        sizeof(struct sockaddr_storage));
 
-               if (len == outlen)
+               if (len == outlen) {
                        dst_link->ping_last = clock_now;
+               } else {
+                       log_warn(knet_h, KNET_SUB_HB_T, "Unable to send ping packet");
+               }
        }
 
        if (dst_link->connected == 1) {
                timespec_diff(pong_last, clock_now, &diff_ping);
 
                if (diff_ping >= (dst_link->pong_timeout * 1000llu)) {
+                       log_info(knet_h, KNET_SUB_LINK, "host: %s link: %s is down",
+                                dst_host->name, dst_link->ipaddr);
                        knet_link_updown(knet_h, dst_host->node_id, dst_link, dst_link->configured, 0);
                }
        }
@@ -693,8 +820,10 @@ static void *_handle_heartbt_thread(void *data)
        while (1) {
                usleep(KNET_PING_TIMERES);
 
-               if (pthread_rwlock_rdlock(&knet_h->list_rwlock) != 0)
+               if (pthread_rwlock_rdlock(&knet_h->list_rwlock) != 0) {
+                       log_debug(knet_h, KNET_SUB_HB_T, "Unable to get read lock");
                        continue;
+               }
 
                for (dst_host = knet_h->host_head; dst_host != NULL; dst_host = dst_host->next) {
                        for (link_idx = 0; link_idx < KNET_MAX_LINK; link_idx++) {
index 80e82d237e3df1a8da94f4e70c2f0f3b3eed49ca..a3214831487ce1d4c706075d68b4f585be6641d8 100644 (file)
@@ -12,8 +12,10 @@ int knet_host_get(knet_handle_t knet_h, uint16_t node_id, struct knet_host **hos
 {
        int ret;
 
-       if ((ret = pthread_rwlock_rdlock(&knet_h->list_rwlock)) != 0)
+       if ((ret = pthread_rwlock_rdlock(&knet_h->list_rwlock)) != 0) {
+               log_debug(knet_h, KNET_SUB_HOST, "host_get: Unable to get read lock");
                return ret;
+       }
 
        *host = knet_h->host_index[node_id];
 
@@ -30,8 +32,10 @@ int knet_host_acquire(knet_handle_t knet_h, struct knet_host **host)
 {
        int ret;
 
-       if ((ret = pthread_rwlock_rdlock(&knet_h->list_rwlock)) != 0)
+       if ((ret = pthread_rwlock_rdlock(&knet_h->list_rwlock)) != 0) {
+               log_debug(knet_h, KNET_SUB_HOST, "host_acquire: Unable to get read lock");
                return ret;
+       }
 
        *host = knet_h->host_head;
 
@@ -44,8 +48,10 @@ int knet_host_release(knet_handle_t knet_h, struct knet_host **host)
 
        *host = NULL;
 
-       if ((ret = pthread_rwlock_unlock(&knet_h->list_rwlock)) != 0)
+       if ((ret = pthread_rwlock_unlock(&knet_h->list_rwlock)) != 0) {
+               log_debug(knet_h, KNET_SUB_HOST, "host_release: Unable to release lock");
                return ret;
+       }
 
        return 0;
 }
@@ -57,8 +63,10 @@ int knet_host_foreach(knet_handle_t knet_h, knet_link_fn_t linkfun, struct knet_
 
        lockstatus = pthread_rwlock_rdlock(&knet_h->list_rwlock);
 
-       if ((lockstatus != 0) && (lockstatus != EDEADLK))
+       if ((lockstatus != 0) && (lockstatus != EDEADLK)) {
+               log_debug(knet_h, KNET_SUB_HOST, "host_foreach: Unable to get lock");
                return lockstatus;
+       }
 
        for (host = knet_h->host_head; host != NULL; host = host->next) {
                if ((linkfun(knet_h, host, data)) != KNET_HOST_FOREACH_NEXT)
@@ -76,16 +84,21 @@ int knet_host_add(knet_handle_t knet_h, uint16_t node_id)
        int link_idx, ret = 0; /* success */
        struct knet_host *host;
 
-       if ((ret = pthread_rwlock_wrlock(&knet_h->list_rwlock)) != 0)
+       if ((ret = pthread_rwlock_wrlock(&knet_h->list_rwlock)) != 0) {
+               log_debug(knet_h, KNET_SUB_HOST, "host_add: Unable to get write lock");
                goto exit_clean;
+       }
 
        if (knet_h->host_index[node_id] != NULL) {
+               log_debug(knet_h, KNET_SUB_HOST, "host_add: host already exists");
                errno = ret = EEXIST;
                goto exit_unlock;
        }
 
-       if ((host = malloc(sizeof(struct knet_host))) == NULL)
+       if ((host = malloc(sizeof(struct knet_host))) == NULL) {
+               log_debug(knet_h, KNET_SUB_HOST, "host_add: unable to allocate memory for host");
                goto exit_unlock;
+       }
 
        memset(host, 0, sizeof(struct knet_host));
 
@@ -117,10 +130,13 @@ int knet_host_remove(knet_handle_t knet_h, uint16_t node_id)
        int ret = 0; /* success */
        struct knet_host *host, *removed;
 
-       if ((ret = pthread_rwlock_wrlock(&knet_h->list_rwlock)) != 0)
+       if ((ret = pthread_rwlock_wrlock(&knet_h->list_rwlock)) != 0) {
+               log_debug(knet_h, KNET_SUB_HOST, "host_remove: Unable to get write lock");
                goto exit_clean;
+       }
 
        if (knet_h->host_index[node_id] == NULL) {
+               log_debug(knet_h, KNET_SUB_HOST, "host_remove: host unknown");
                errno = ret = EINVAL;
                goto exit_unlock;
        }
@@ -159,11 +175,14 @@ int knet_host_set_policy(knet_handle_t knet_h, uint16_t node_id, int policy)
        struct knet_host *host = NULL;
        int old_policy;
 
-       if ((ret = pthread_rwlock_wrlock(&knet_h->list_rwlock)) != 0)
+       if ((ret = pthread_rwlock_wrlock(&knet_h->list_rwlock)) != 0) {
+               log_debug(knet_h, KNET_SUB_HOST, "host_set_policy: Unable to get write lock");
                goto exit_clean;
+       }
 
        host = knet_h->host_index[node_id];
        if (host == NULL) {
+               log_debug(knet_h, KNET_SUB_HOST, "host_set_policy: host not found");
                errno = ret = EINVAL;
                goto exit_unlock;
        }
@@ -172,6 +191,7 @@ int knet_host_set_policy(knet_handle_t knet_h, uint16_t node_id, int policy)
        host->link_handler_policy = policy;
 
        if (_dst_cache_update(knet_h, node_id)) {
+               log_debug(knet_h, KNET_SUB_HOST, "host_set_policy: unable to update switch cache");
                ret = -1;
                host->link_handler_policy = old_policy;
        }
index ca37642bf8e01cb819a2ff17393f7f0d55ada3cb..33734c7ffda5e68d98331771558d88945c713d31 100644 (file)
@@ -132,9 +132,10 @@ struct knet_frame {
 #define KNET_SUB_TAP_T       5 /* tap thread */
 #define KNET_SUB_LINK_T      6 /* link thread */
 #define KNET_SUB_SWITCH_T    7 /* switching thread */
-#define KNET_SUB_FILTER      8 /* (ether)filter errors */
-#define KNET_SUB_CRYPTO      9 /* crypto.c generic layer */
-#define KNET_SUB_NSSCRYPTO  10 /* nsscrypto.c */
+#define KNET_SUB_HB_T        8 /* heartbeat thread */
+#define KNET_SUB_FILTER      9 /* (ether)filter errors */
+#define KNET_SUB_CRYPTO     10 /* crypto.c generic layer */
+#define KNET_SUB_NSSCRYPTO  11 /* nsscrypto.c */
 #define KNET_SUB_LAST        KNET_SUB_NSSCRYPTO
 #define KNET_MAX_SUBSYSTEMS KNET_SUB_LAST + 1
 
@@ -193,7 +194,7 @@ int knet_host_remove(knet_handle_t knet_h, uint16_t node_id);
 int knet_host_set_policy(knet_handle_t knet_h, uint16_t node_id, int policy);
 
 int knet_link_enable(knet_handle_t knet_h, uint16_t node_id, struct knet_link *lnk, int configured);
-void knet_link_timeout(struct knet_link *lnk, time_t interval, time_t timeout, int precision);
+void knet_link_timeout(knet_handle_t knet_h, uint16_t node_id, struct knet_link *lnk, time_t interval, time_t timeout, int precision);
 int knet_link_priority(knet_handle_t knet_h, uint16_t node_id, struct knet_link *lnk, uint8_t priority);
 
 #define KNET_HOST_FOREACH_NEXT 0       /* next host */
index 3e7a06dd6d7f3192daa69da9f45d7e4545a2a504..9fb800f02b0185ca1bc194cbb1037f09ae21c7fe 100644 (file)
@@ -20,6 +20,9 @@ int knet_listener_acquire(knet_handle_t knet_h, struct knet_listener **head, int
        if (head)
                *head = (ret == 0) ? knet_h->listener_head : NULL;
 
+       if (ret)
+               log_debug(knet_h, KNET_SUB_LISTENER, "listener_acquire: Unable to acquire lock (%d)", writelock);
+
        return ret;
 }
 
@@ -36,8 +39,10 @@ int knet_listener_add(knet_handle_t knet_h, struct knet_listener *listener)
 
        listener->sock = socket(listener->address.ss_family, SOCK_DGRAM, 0);
 
-       if (listener->sock < 0)
+       if (listener->sock < 0) {
+               log_err(knet_h, KNET_SUB_LISTENER, "Unable to create listener socket");
                return listener->sock;
+       }
 
        value = KNET_RING_RCVBUFF;
        setsockopt(listener->sock, SOL_SOCKET, SO_RCVBUFFORCE, &value, sizeof(value));
@@ -49,12 +54,14 @@ int knet_listener_add(knet_handle_t knet_h, struct knet_listener *listener)
        }
 
        if (_fdset_cloexec(listener->sock) != 0) {
+               log_err(knet_h, KNET_SUB_LISTENER, "Unable to set listener socket opts");
                save_errno = errno;
                goto exit_fail1;
        }
 
        if (bind(listener->sock, (struct sockaddr *) &listener->address,
                                        sizeof(struct sockaddr_storage)) != 0) {
+               log_err(knet_h, KNET_SUB_LISTENER, "Unable to bind listener socket");
                save_errno = errno;
                goto exit_fail1;
        }
@@ -65,11 +72,13 @@ int knet_listener_add(knet_handle_t knet_h, struct knet_listener *listener)
        ev.data.fd = listener->sock;
 
        if (epoll_ctl(knet_h->recv_from_links_epollfd, EPOLL_CTL_ADD, listener->sock, &ev) != 0) {
+               log_err(knet_h, KNET_SUB_LISTENER, "Unable to add listener to epoll pool");
                save_errno = errno;
                goto exit_fail1;
        }
 
        if (pthread_rwlock_wrlock(&knet_h->list_rwlock) != 0) {
+               log_err(knet_h, KNET_SUB_LISTENER, "listener_add: Unable to get write lock");
                save_errno = errno;
                goto exit_fail2;
        }
@@ -98,8 +107,10 @@ int knet_listener_remove(knet_handle_t knet_h, struct knet_listener *listener)
        struct knet_host *host;
        struct knet_listener *tmp_listener;
 
-       if (pthread_rwlock_wrlock(&knet_h->list_rwlock) != 0)
+       if (pthread_rwlock_wrlock(&knet_h->list_rwlock) != 0) {
+               log_err(knet_h, KNET_SUB_LISTENER, "listener_remove: Unable to get write lock");
                return -EINVAL;
+       }
 
        ret = 0;
 
@@ -110,6 +121,7 @@ int knet_listener_remove(knet_handle_t knet_h, struct knet_listener *listener)
                                continue;
 
                        if (host->link[link_idx].sock == listener->sock) {
+                               log_err(knet_h, KNET_SUB_LISTENER, "listener_remove: listener in use");
                                ret = -EBUSY;
                                goto exit_fail1;
                        }
index 42489b9de210aff648c91f324842389f9ce91cc3..c23198bacd92715102f0b7ce4816b77e740a55a3 100644 (file)
 #include "nsscrypto.h"
 #include "libknet-private.h"
 
-#ifdef CRYPTO_DEBUG
-#include <stdio.h>
-#define log_printf(format, args...) fprintf(stderr, format "\n", ##args);
-#else
-#define log_printf(format, args...);
-#endif
-
 /*
  * crypto definitions and conversion tables
  */
@@ -145,10 +138,11 @@ static int string_to_crypto_cipher_type(const char* crypto_cipher_type)
        return -1;
 }
 
-static int init_nss_crypto(struct nsscrypto_instance *instance)
+static int init_nss_crypto(knet_handle_t knet_h)
 {
        PK11SlotInfo*   crypt_slot = NULL;
        SECItem         crypt_param;
+       struct nsscrypto_instance *instance = knet_h->crypto_instance->model_instance;
 
        if (!cipher_to_nss[instance->crypto_cipher_type]) {
                return 0;
@@ -160,7 +154,7 @@ static int init_nss_crypto(struct nsscrypto_instance *instance)
 
        crypt_slot = PK11_GetBestSlot(cipher_to_nss[instance->crypto_cipher_type], NULL);
        if (crypt_slot == NULL) {
-               log_printf("Unable to find security slot (err %d)",
+               log_err(knet_h, KNET_SUB_NSSCRYPTO, "Unable to find security slot (err %d)",
                           PR_GetError());
                return -1;
        }
@@ -170,7 +164,7 @@ static int init_nss_crypto(struct nsscrypto_instance *instance)
                                                  PK11_OriginUnwrap, CKA_ENCRYPT|CKA_DECRYPT,
                                                  &crypt_param, NULL);
        if (instance->nss_sym_key == NULL) {
-               log_printf("Failure to import key into NSS (err %d)",
+               log_err(knet_h, KNET_SUB_NSSCRYPTO, "Failure to import key into NSS (err %d)",
                           PR_GetError());
                return -1;
        }
@@ -181,12 +175,13 @@ static int init_nss_crypto(struct nsscrypto_instance *instance)
 }
 
 static int encrypt_nss(
-       struct nsscrypto_instance *instance,
+       knet_handle_t knet_h,
        const unsigned char *buf_in,
        const ssize_t buf_in_len,
        unsigned char *buf_out,
        ssize_t *buf_out_len)
 {
+       struct nsscrypto_instance *instance = knet_h->crypto_instance->model_instance;
        PK11Context*    crypt_context = NULL;
        SECItem         crypt_param;
        SECItem         *nss_sec_param = NULL;
@@ -197,7 +192,7 @@ static int encrypt_nss(
        int             err = -1;
 
        if (PK11_GenerateRandom (salt, SALT_SIZE) != SECSuccess) {
-               log_printf("Failure to generate a random number %d",
+               log_err(knet_h, KNET_SUB_NSSCRYPTO, "Failure to generate a random number %d",
                           PR_GetError());
                goto out;
        }
@@ -209,7 +204,7 @@ static int encrypt_nss(
        nss_sec_param = PK11_ParamFromIV (cipher_to_nss[instance->crypto_cipher_type],
                                          &crypt_param);
        if (nss_sec_param == NULL) {
-               log_printf("Failure to set up PKCS11 param (err %d)",
+               log_err(knet_h, KNET_SUB_NSSCRYPTO, "Failure to set up PKCS11 param (err %d)",
                           PR_GetError());
                goto out;
        }
@@ -222,7 +217,7 @@ static int encrypt_nss(
                                                    instance->nss_sym_key,
                                                    nss_sec_param);
        if (!crypt_context) {
-               log_printf("PK11_CreateContext failed (encrypt) crypt_type=%d (err %d)",
+               log_err(knet_h, KNET_SUB_NSSCRYPTO, "PK11_CreateContext failed (encrypt) crypt_type=%d (err %d)",
                           (int)cipher_to_nss[instance->crypto_cipher_type],
                           PR_GetError());
                goto out;
@@ -232,7 +227,7 @@ static int encrypt_nss(
                          &tmp1_outlen,
                          KNET_DATABUFSIZE_CRYPT,
                          (unsigned char *)buf_in, buf_in_len) != SECSuccess) {
-               log_printf("PK11_CipherOp failed (encrypt) crypt_type=%d (err %d)",
+               log_err(knet_h, KNET_SUB_NSSCRYPTO, "PK11_CipherOp failed (encrypt) crypt_type=%d (err %d)",
                           (int)cipher_to_nss[instance->crypto_cipher_type],
                           PR_GetError());
                goto out;
@@ -240,7 +235,7 @@ static int encrypt_nss(
 
        if (PK11_DigestFinal(crypt_context, data + tmp1_outlen,
                             &tmp2_outlen, KNET_DATABUFSIZE_CRYPT - tmp1_outlen) != SECSuccess) {
-               log_printf("PK11_DigestFinal failed (encrypt) crypt_type=%d (err %d)",
+               log_err(knet_h, KNET_SUB_NSSCRYPTO, "PK11_DigestFinal failed (encrypt) crypt_type=%d (err %d)",
                           (int)cipher_to_nss[instance->crypto_cipher_type],
                           PR_GetError());
                goto out;
@@ -262,10 +257,11 @@ out:
 }
 
 static int decrypt_nss (
-       struct nsscrypto_instance *instance,
+       knet_handle_t knet_h,
        unsigned char *buf,
        ssize_t *buf_len)
 {
+       struct nsscrypto_instance *instance = knet_h->crypto_instance->model_instance;
        PK11Context*    decrypt_context = NULL;
        SECItem         decrypt_param;
        int             tmp1_outlen = 0;
@@ -286,21 +282,21 @@ static int decrypt_nss (
                                                     CKA_DECRYPT,
                                                     instance->nss_sym_key, &decrypt_param);
        if (!decrypt_context) {
-               log_printf("PK11_CreateContext (decrypt) failed (err %d)",
+               log_err(knet_h, KNET_SUB_NSSCRYPTO, "PK11_CreateContext (decrypt) failed (err %d)",
                           PR_GetError());
                goto out;
        }
 
        if (PK11_CipherOp(decrypt_context, outbuf, &tmp1_outlen,
                          sizeof(outbuf), data, datalen) != SECSuccess) {
-               log_printf("PK11_CipherOp (decrypt) failed (err %d)",
+               log_err(knet_h, KNET_SUB_NSSCRYPTO, "PK11_CipherOp (decrypt) failed (err %d)",
                           PR_GetError());
                goto out;
        }
 
        if (PK11_DigestFinal(decrypt_context, outbuf + tmp1_outlen, &tmp2_outlen,
                             sizeof(outbuf) - tmp1_outlen) != SECSuccess) {
-               log_printf("PK11_DigestFinal (decrypt) failed (err %d)",
+               log_err(knet_h, KNET_SUB_NSSCRYPTO, "PK11_DigestFinal (decrypt) failed (err %d)",
                           PR_GetError()); 
                goto out;
        }
@@ -346,10 +342,11 @@ static int string_to_crypto_hash_type(const char* crypto_hash_type)
        return -1;
 }
 
-static int init_nss_hash(struct nsscrypto_instance *instance)
+static int init_nss_hash(knet_handle_t knet_h)
 {
        PK11SlotInfo*   hash_slot = NULL;
        SECItem         hash_param;
+       struct nsscrypto_instance *instance = knet_h->crypto_instance->model_instance;
 
        if (!hash_to_nss[instance->crypto_hash_type]) {
                return 0;
@@ -361,7 +358,7 @@ static int init_nss_hash(struct nsscrypto_instance *instance)
 
        hash_slot = PK11_GetBestSlot(hash_to_nss[instance->crypto_hash_type], NULL);
        if (hash_slot == NULL) {
-               log_printf("Unable to find security slot (err %d)",
+               log_err(knet_h, KNET_SUB_NSSCRYPTO, "Unable to find security slot (err %d)",
                           PR_GetError());
                return -1;
        }
@@ -371,7 +368,7 @@ static int init_nss_hash(struct nsscrypto_instance *instance)
                                                       PK11_OriginUnwrap, CKA_SIGN,
                                                       &hash_param, NULL);
        if (instance->nss_sym_key_sign == NULL) {
-               log_printf("Failure to import key into NSS (err %d)",
+               log_err(knet_h, KNET_SUB_NSSCRYPTO, "Failure to import key into NSS (err %d)",
                           PR_GetError());
                return -1;
        }
@@ -382,11 +379,12 @@ static int init_nss_hash(struct nsscrypto_instance *instance)
 }
 
 static int calculate_nss_hash(
-       struct nsscrypto_instance *instance,
+       knet_handle_t knet_h,
        const unsigned char *buf,
        const size_t buf_len,
        unsigned char *hash)
 {
+       struct nsscrypto_instance *instance = knet_h->crypto_instance->model_instance;
        PK11Context*    hash_context = NULL;
        SECItem         hash_param;
        unsigned int    hash_tmp_outlen = 0;
@@ -404,14 +402,14 @@ static int calculate_nss_hash(
                                                 &hash_param);
 
        if (!hash_context) {
-               log_printf("PK11_CreateContext failed (hash) hash_type=%d (err %d)",
+               log_err(knet_h, KNET_SUB_NSSCRYPTO, "PK11_CreateContext failed (hash) hash_type=%d (err %d)",
                           (int)hash_to_nss[instance->crypto_hash_type],
                           PR_GetError());
                goto out;
        }
 
        if (PK11_DigestBegin(hash_context) != SECSuccess) {
-               log_printf("PK11_DigestBegin failed (hash) hash_type=%d (err %d)",
+               log_err(knet_h, KNET_SUB_NSSCRYPTO, "PK11_DigestBegin failed (hash) hash_type=%d (err %d)",
                           (int)hash_to_nss[instance->crypto_hash_type],
                           PR_GetError());
                goto out;
@@ -420,7 +418,7 @@ static int calculate_nss_hash(
        if (PK11_DigestOp(hash_context,
                          buf,
                          buf_len) != SECSuccess) {
-               log_printf("PK11_DigestOp failed (hash) hash_type=%d (err %d)",
+               log_err(knet_h, KNET_SUB_NSSCRYPTO, "PK11_DigestOp failed (hash) hash_type=%d (err %d)",
                           (int)hash_to_nss[instance->crypto_hash_type],
                           PR_GetError());
                goto out;
@@ -430,7 +428,7 @@ static int calculate_nss_hash(
                             hash_block,
                             &hash_tmp_outlen,
                             hash_block_len[instance->crypto_hash_type]) != SECSuccess) {
-               log_printf("PK11_DigestFinale failed (hash) hash_type=%d (err %d)",
+               log_err(knet_h, KNET_SUB_NSSCRYPTO, "PK11_DigestFinale failed (hash) hash_type=%d (err %d)",
                           (int)hash_to_nss[instance->crypto_hash_type],
                           PR_GetError());
                goto out;
@@ -451,15 +449,17 @@ out:
  * global/glue nss functions
  */
 
-static int init_nss_db(struct nsscrypto_instance *instance)
+static int init_nss_db(knet_handle_t knet_h)
 {
+       struct nsscrypto_instance *instance = knet_h->crypto_instance->model_instance;
+
        if ((!cipher_to_nss[instance->crypto_cipher_type]) &&
            (!hash_to_nss[instance->crypto_hash_type])) {
                return 0;
        }
 
        if (NSS_NoDB_Init(".") != SECSuccess) {
-               log_printf("NSS DB initialization failed (err %d)",
+               log_err(knet_h, KNET_SUB_NSSCRYPTO, "NSS DB initialization failed (err %d)",
                           PR_GetError());
                return -1;
        }
@@ -467,17 +467,17 @@ static int init_nss_db(struct nsscrypto_instance *instance)
        return 0;
 }
 
-static int init_nss(struct nsscrypto_instance *instance)
+static int init_nss(knet_handle_t knet_h)
 {
-       if (init_nss_db(instance) < 0) {
+       if (init_nss_db(knet_h) < 0) {
                return -1;
        }
 
-       if (init_nss_crypto(instance) < 0) {
+       if (init_nss_crypto(knet_h) < 0) {
                return -1;
        }
 
-       if (init_nss_hash(instance) < 0) {
+       if (init_nss_hash(knet_h) < 0) {
                return -1;
        }
 
@@ -489,16 +489,16 @@ static int init_nss(struct nsscrypto_instance *instance)
  */
 
 int nsscrypto_encrypt_and_sign (
-       void *model_instance,
+       knet_handle_t knet_h,
        const unsigned char *buf_in,
        const ssize_t buf_in_len,
        unsigned char *buf_out,
        ssize_t *buf_out_len)
 {
-       struct nsscrypto_instance *instance = model_instance;
+       struct nsscrypto_instance *instance = knet_h->crypto_instance->model_instance;
 
        if (cipher_to_nss[instance->crypto_cipher_type]) {
-               if (encrypt_nss(instance, buf_in, buf_in_len, buf_out, buf_out_len) < 0) {
+               if (encrypt_nss(knet_h, buf_in, buf_in_len, buf_out, buf_out_len) < 0) {
                        return -1;
                }
        } else {
@@ -507,7 +507,7 @@ int nsscrypto_encrypt_and_sign (
        }
 
        if (hash_to_nss[instance->crypto_hash_type]) {
-               if (calculate_nss_hash(instance, buf_out, *buf_out_len, buf_out + *buf_out_len) < 0) {
+               if (calculate_nss_hash(knet_h, buf_out, *buf_out_len, buf_out + *buf_out_len) < 0) {
                        return -1;
                }
                *buf_out_len = *buf_out_len + hash_len[instance->crypto_hash_type];
@@ -517,21 +517,21 @@ int nsscrypto_encrypt_and_sign (
 }
 
 int nsscrypto_authenticate_and_decrypt (
-       void *model_instance,
+       knet_handle_t knet_h,
        unsigned char *buf,
        ssize_t *buf_len)
 {
-       struct nsscrypto_instance *instance = model_instance;
+       struct nsscrypto_instance *instance = knet_h->crypto_instance->model_instance;
 
        if (hash_to_nss[instance->crypto_hash_type]) {
                unsigned char   tmp_hash[hash_len[instance->crypto_hash_type]];
 
-               if (calculate_nss_hash(instance, buf, *buf_len - hash_len[instance->crypto_hash_type], tmp_hash) < 0) {
+               if (calculate_nss_hash(knet_h, buf, *buf_len - hash_len[instance->crypto_hash_type], tmp_hash) < 0) {
                        return -1;
                }
 
                if (memcmp(tmp_hash, buf + (*buf_len - hash_len[instance->crypto_hash_type]), hash_len[instance->crypto_hash_type]) != 0) {
-                       log_printf("Digest does not match");
+                       log_err(knet_h, KNET_SUB_NSSCRYPTO, "Digest does not match");
                        return -1;
                }
 
@@ -539,7 +539,7 @@ int nsscrypto_authenticate_and_decrypt (
        }
 
        if (cipher_to_nss[instance->crypto_cipher_type]) {
-               if (decrypt_nss(instance, buf, buf_len) < 0) {
+               if (decrypt_nss(knet_h, buf, buf_len) < 0) {
                        return -1;
                }
        }
@@ -553,12 +553,14 @@ int nsscrypto_init(
 {
        struct nsscrypto_instance *nsscrypto_instance = NULL;
 
-       log_printf("Initizializing nss crypto module [%s/%s]",
+       log_debug(knet_h, KNET_SUB_NSSCRYPTO,
+                 "Initizializing nss crypto module [%s/%s]",
                  knet_handle_crypto_cfg->crypto_cipher_type,
                  knet_handle_crypto_cfg->crypto_hash_type);
 
        knet_h->crypto_instance->model_instance = malloc(sizeof(struct nsscrypto_instance));
        if (!knet_h->crypto_instance->model_instance) {
+               log_err(knet_h, KNET_SUB_NSSCRYPTO, "Unable to allocate memory for nss model instance");
                return -1;
        }
 
@@ -567,20 +569,24 @@ int nsscrypto_init(
        memset(nsscrypto_instance, 0, sizeof(struct nsscrypto_instance));
 
        if (!knet_handle_crypto_cfg->crypto_cipher_type) {
+               log_err(knet_h, KNET_SUB_NSSCRYPTO, "no crypto cipher type specified");
                goto out_err;
        }
 
        nsscrypto_instance->crypto_cipher_type = string_to_crypto_cipher_type(knet_handle_crypto_cfg->crypto_cipher_type);
        if (nsscrypto_instance->crypto_cipher_type < 0) {
+               log_err(knet_h, KNET_SUB_NSSCRYPTO, "unknown crypto cipher type requested");
                goto out_err;
        }
 
        if (!knet_handle_crypto_cfg->crypto_hash_type) {
+               log_err(knet_h, KNET_SUB_NSSCRYPTO, "no crypto hash type specified");
                goto out_err;
        }
 
        nsscrypto_instance->crypto_hash_type = string_to_crypto_hash_type(knet_handle_crypto_cfg->crypto_hash_type);
        if (nsscrypto_instance->crypto_hash_type < 0) {
+               log_err(knet_h, KNET_SUB_NSSCRYPTO, "unknown crypto hash type requested");
                goto out_err;
        }
 
@@ -592,26 +598,33 @@ int nsscrypto_init(
                if ((!nsscrypto_instance->private_key) ||
                    (nsscrypto_instance->private_key_len < KNET_MIN_KEY_LEN) ||
                    (nsscrypto_instance->private_key_len > KNET_MAX_KEY_LEN)) {
+                       log_err(knet_h, KNET_SUB_NSSCRYPTO, "crypto private key parameters are incorrect");
                        goto out_err;
                }
        }
 
        knet_h->tap_to_links_buf_crypt = malloc(KNET_DATABUFSIZE_CRYPT);
-       if (!knet_h->tap_to_links_buf_crypt)
+       if (!knet_h->tap_to_links_buf_crypt) {
+               log_err(knet_h, KNET_SUB_NSSCRYPTO, "unable to allocate memory for crypto send buffer");
                goto out_err;
+       }
 
        knet_h->pingbuf_crypt = malloc(KNET_DATABUFSIZE_CRYPT);
-       if (!knet_h->pingbuf_crypt)
+       if (!knet_h->pingbuf_crypt) {
+               log_err(knet_h, KNET_SUB_NSSCRYPTO, "unable to allocate memory for crypto hb buffer");
                goto out_err;
+       }
 
        knet_h->recv_from_links_buf_crypt = malloc(KNET_DATABUFSIZE_CRYPT);
-       if (!knet_h->recv_from_links_buf_crypt)
+       if (!knet_h->recv_from_links_buf_crypt) {
+               log_err(knet_h, KNET_SUB_NSSCRYPTO, "unable to allocate memory for crypto recv buffer");
                goto out_err;
+       }
 
        nsscrypto_instance->private_key = knet_handle_crypto_cfg->private_key;
        nsscrypto_instance->private_key_len = knet_handle_crypto_cfg->private_key_len;
 
-       if (init_nss(nsscrypto_instance) < 0) {
+       if (init_nss(knet_h) < 0) {
                goto out_err;
        }
 
index 0c815eabe69bdc4b6964da4b334352847416ad40..ffbe132cc9f3df41ecd208b8360779e81bb30f82 100644 (file)
@@ -7,12 +7,12 @@
 struct nsscrypto_instance;
 
 int nsscrypto_authenticate_and_decrypt (
-       void *model_instance,
+       knet_handle_t knet_h,
        unsigned char *buf,
        ssize_t *buf_len);
 
 int nsscrypto_encrypt_and_sign (
-       void *model_instance,
+       knet_handle_t knet_h,
        const unsigned char *buf_in,
        const ssize_t buf_in_len,
        unsigned char *buf_out, 
index 6bc65211274f2810aac32972890f722479eb3d40..53a2ff81516ae55b522c9881fb9c078990eb158f 100644 (file)
@@ -130,6 +130,8 @@ static void argv_to_hosts(int argc, char *argv[])
        for (i = 2; i < argc; i++) {
                if (!strncmp(argv[i], "crypto", 6))
                        continue;
+               if (!strncmp(argv[i], "debug", 5))
+                       continue;
 
                if (knet_host_add(knet_h, i - 1) != 0) {
                        printf("Unable to add new knet_host\n");
@@ -141,7 +143,7 @@ static void argv_to_hosts(int argc, char *argv[])
                host->link[0].sock = listener->sock;
                host->link[0].address.ss_family = AF_INET;
 
-               knet_link_timeout(&host->link[0], 1000, 5000, 2048);
+               knet_link_timeout(knet_h, host->node_id, &host->link[0], 1000, 5000, 2048);
 
                knet_link_enable(knet_h, host->node_id, &host->link[0], 1);