irmd: Initial Flow Allocation Protocol Header

This adds the initial version for the flow allocation protocol header
between IRMd instances. This is a step towards flow authentication.

The header supports secure and authenticated flow allocation,
supporting certificate-based authentication and ephemeral key
exchange for end-to-end encryption.

 id:          128-bit identifier for the entity.
 timestamp:   64-bit timestamp (replay protection).
 certificate: Certificate for authentication.
 public key:  ECDHE public key for key exchange.
 data:        Application data.
 signature:   Signature for integrity/authenticity.

Authentication and encryption require OpenSSL to be installed.

The IRMd compares the allocation request delay with the MPL of the
Layer over which the flow allocation was sent. MPL is now reported by
the Layer in ms instead of seconds.

Time functions revised for consistency and adds some tests.

The TPM can now print thread running times in Debug builds
(TPM_DEBUG_REPORT_INTERVAL) and abort processes with hung threads
(TPM_DEBUG_ABORT_TIMEOUT). Long running threads waiting for input
should call tpm_wait_work() to avoid trigger a process abort.

Signed-off-by: Dimitri Staessens <dimitri@ouroboros.rocks>
Signed-off-by: Sander Vrijders <sander@ouroboros.rocks>

10 files changed, 642 insertions, 137 deletions

diff --git a/src/lib/CMakeLists.txt b/src/lib/CMakeLists.txt
index cc73a9fc..04a8f089 100644
--- a/src/lib/CMakeLists.txt
+++ b/src/lib/CMakeLists.txt
@@ -115,7 +115,7 @@ if (OPENSSL_FOUND)
     set(DISABLE_OPENSSL FALSE CACHE BOOL "Disable OpenSSL support")
     if (NOT DISABLE_OPENSSL)
       message(STATUS "OpenSSL support enabled")
-      set(HAVE_OPENSSL TRUE)
+      set(HAVE_OPENSSL TRUE CACHE INTERNAL "")
     else()
       message(STATUS "OpenSSL support disabled")
       unset(HAVE_OPENSSL)
@@ -234,6 +234,10 @@ set(ACK_WHEEL_SLOTS 256 CACHE STRING
   "Number of slots in the acknowledgment wheel, must be a power of 2")
 set(ACK_WHEEL_RESOLUTION 18 CACHE STRING
   "Minimum acknowledgment delay (ns), as a power to 2")
+set(TPM_DEBUG_REPORT_INTERVAL 0 CACHE STRING
+  "Interval at wich the TPM will report long running threads (s), 0 disables")
+set(TPM_DEBUG_ABORT_TIMEOUT 0 CACHE STRING
+  "TPM abort process after a thread reaches this timeout (s), 0 disables")
 
 if (HAVE_FUSE)
   set(PROC_FLOW_STATS TRUE CACHE BOOL
diff --git a/src/lib/config.h.in b/src/lib/config.h.in
index 21a30493..3fcac7b8 100644
--- a/src/lib/config.h.in
+++ b/src/lib/config.h.in
@@ -29,21 +29,24 @@
 #define HAVE_ENCRYPTION
 #endif
 
-#define SYS_MAX_FLOWS       @SYS_MAX_FLOWS@
-
-#cmakedefine                SHM_RBUFF_LOCKLESS
-#cmakedefine                SHM_RDRB_MULTI_BLOCK
-#cmakedefine                QOS_DISABLE_CRC
-#cmakedefine                HAVE_OPENSSL_RNG
-
-#define SHM_RBUFF_PREFIX    "@SHM_RBUFF_PREFIX@"
-#define SHM_LOCKFILE_NAME   "@SHM_LOCKFILE_NAME@"
-#define SHM_FLOW_SET_PREFIX "@SHM_FLOW_SET_PREFIX@"
-#define SHM_RDRB_NAME       "@SHM_RDRB_NAME@"
-#define SHM_RDRB_BLOCK_SIZE @SHM_RDRB_BLOCK_SIZE@
-#define SHM_BUFFER_SIZE     @SHM_BUFFER_SIZE@
-#define SHM_RBUFF_SIZE      @SHM_RBUFF_SIZE@
-#define FLOW_ALLOC_TIMEOUT  @FLOW_ALLOC_TIMEOUT@
+#define SYS_MAX_FLOWS            @SYS_MAX_FLOWS@
+
+#cmakedefine                     SHM_RBUFF_LOCKLESS
+#cmakedefine                     SHM_RDRB_MULTI_BLOCK
+#cmakedefine                     QOS_DISABLE_CRC
+#cmakedefine                     HAVE_OPENSSL_RNG
+
+#define SHM_RBUFF_PREFIX         "@SHM_RBUFF_PREFIX@"
+#define SHM_LOCKFILE_NAME        "@SHM_LOCKFILE_NAME@"
+#define SHM_FLOW_SET_PREFIX      "@SHM_FLOW_SET_PREFIX@"
+#define SHM_RDRB_NAME            "@SHM_RDRB_NAME@"
+#define SHM_RDRB_BLOCK_SIZE       @SHM_RDRB_BLOCK_SIZE@
+#define SHM_BUFFER_SIZE           @SHM_BUFFER_SIZE@
+#define SHM_RBUFF_SIZE            @SHM_RBUFF_SIZE@
+#define FLOW_ALLOC_TIMEOUT        @FLOW_ALLOC_TIMEOUT@
+
+#define TPM_DEBUG_REPORT_INTERVAL @TPM_DEBUG_REPORT_INTERVAL@
+#define TPM_DEBUG_ABORT_TIMEOUT   @TPM_DEBUG_ABORT_TIMEOUT@
 
 #if defined(__linux__) || (defined(__MACH__) && !defined(__APPLE__))
 /* Avoid a bug in robust mutex implementation of glibc 2.25 */
diff --git a/src/lib/crypt.c b/src/lib/crypt.c
index 756fcccc..e8c4d5ab 100644
--- a/src/lib/crypt.c
+++ b/src/lib/crypt.c
@@ -60,10 +60,13 @@ int crypt_dh_pkp_create(void **   pkp,
 
 void crypt_dh_pkp_destroy(void * pkp)
 {
+        if (pkp == NULL)
+                return;
 #ifdef HAVE_OPENSSL
         openssl_ecdh_pkp_destroy(pkp);
 #else
         (void) pkp;
+
         return;
 #endif
 }
@@ -179,7 +182,7 @@ int crypt_load_privkey_file(const char * path,
 }
 
 int crypt_load_privkey_str(const char * str,
-                       void **      key)
+                           void **      key)
 {
         *key = NULL;
 
@@ -232,6 +235,8 @@ void crypt_free_key(void * key)
 int crypt_load_crt_file(const char * path,
                         void **      crt)
 {
+        assert(crt != NULL);
+
         *crt = NULL;
 
 #ifdef HAVE_OPENSSL
@@ -246,6 +251,8 @@ int crypt_load_crt_file(const char * path,
 int crypt_load_crt_str(const char * str,
                        void **      crt)
 {
+        assert(crt != NULL);
+
         *crt = NULL;
 
 #ifdef HAVE_OPENSSL
@@ -257,6 +264,21 @@ int crypt_load_crt_str(const char * str,
 #endif
 }
 
+int crypt_load_crt_der(const buffer_t buf,
+                       void **        crt)
+{
+        assert(crt != NULL);
+#ifdef HAVE_OPENSSL
+        return openssl_load_crt_der(buf, crt);
+#else
+        *crt = NULL;
+
+        (void) buf;
+
+        return 0;
+#endif
+}
+
 int crypt_get_pubkey_crt(void *  crt,
                          void ** pk)
 {
@@ -283,8 +305,8 @@ void crypt_free_crt(void * crt)
 #endif
 }
 
-int crypt_crt_str(void * crt,
-                  char * buf)
+int crypt_crt_str(const void * crt,
+                  char *       buf)
 {
 #ifdef HAVE_OPENSSL
         return openssl_crt_str(crt, buf);
@@ -296,6 +318,23 @@ int crypt_crt_str(void * crt,
 #endif
 }
 
+int crypt_crt_der(const void * crt,
+                  buffer_t *   buf)
+{
+        assert(crt != NULL);
+        assert(buf != NULL);
+
+#ifdef HAVE_OPENSSL
+        return openssl_crt_der(crt, buf);
+#else
+        (void) crt;
+
+        clrbuf(*buf);
+
+        return 0;
+#endif
+}
+
 int crypt_check_crt_name(void *       crt,
                          const char * name)
 {
diff --git a/src/lib/crypt/openssl.c b/src/lib/crypt/openssl.c
index 6e7a5dab..1824d879 100644
--- a/src/lib/crypt/openssl.c
+++ b/src/lib/crypt/openssl.c
@@ -159,7 +159,7 @@ ssize_t openssl_ecdh_pkp_create(void **   pkp,
         if (__openssl_ecdh_gen_key(pkp) < 0)
                 goto fail_key;
 
-        pos = pk; /* i2d_PUBKEY increments the pointer, don't use buf! */
+        pos = pk; /* i2d_PUBKEY increments the pointer, don't use pk! */
         len = i2d_PUBKEY(*pkp, &pos);
         if (len < 0)
                 goto fail_pubkey;
@@ -388,6 +388,28 @@ int openssl_load_crt_str(const char * str,
         return -1;
 }
 
+int openssl_load_crt_der(buffer_t buf,
+                         void **  crt)
+{
+        const uint8_t * p;
+        X509 *          xcrt;
+
+        assert(crt != NULL);
+
+        p = buf.data;
+
+        xcrt = d2i_X509(NULL, &p, buf.len);
+        if (xcrt == NULL)
+                goto fail_crt;
+
+        *crt = (void *) xcrt;
+
+        return 0;
+ fail_crt:
+        *crt = NULL;
+        return -1;
+}
+
 int openssl_get_pubkey_crt(void *  crt,
                            void ** key)
 {
@@ -578,8 +600,8 @@ int openssl_check_crt_name(void *       crt,
         return -1;
 }
 
-int openssl_crt_str(void * crt,
-                    char * str)
+int openssl_crt_str(const void * crt,
+                    char *       str)
 {
         BIO *  bio;
         X509 * xcrt;
@@ -608,6 +630,28 @@ int openssl_crt_str(void * crt,
         return -1;
 }
 
+int openssl_crt_der(const void * crt,
+                    buffer_t *   buf)
+{
+        int len;
+
+        assert(crt != NULL);
+        assert(buf != NULL);
+
+        len = i2d_X509((X509 *) crt, &buf->data);
+        if (len < 0)
+                goto fail_der;
+
+        buf->len = (size_t) len;
+
+        return 0;
+
+ fail_der:
+        clrbuf(*buf);
+        return -1;
+}
+
+
 void * openssl_auth_create_store(void)
 {
         return X509_STORE_new();
diff --git a/src/lib/crypt/openssl.h b/src/lib/crypt/openssl.h
index 5d6f50dd..d4ee73b9 100644
--- a/src/lib/crypt/openssl.h
+++ b/src/lib/crypt/openssl.h
@@ -57,6 +57,9 @@ int     openssl_load_crt_file(const char * path,
 int     openssl_load_crt_str(const char * str,
                              void **      crt);
 
+int     openssl_load_crt_der(buffer_t buf,
+                             void **  crt);
+
 int     openssl_get_pubkey_crt(void *  crt,
                                void ** pk);
 
@@ -82,8 +85,11 @@ void    openssl_free_key(void * key);
 int     openssl_check_crt_name(void *       crt,
                                const char * name);
 
-int     openssl_crt_str(void * crt,
-                        char * str);
+int     openssl_crt_str(const void * crt,
+                        char *       str);
+
+int     openssl_crt_der(const void * crt,
+                        buffer_t *   buf);
 
 void *  openssl_auth_create_store(void);
 
diff --git a/src/lib/dev.c b/src/lib/dev.c
index cb35f3f9..c22b4f06 100644
--- a/src/lib/dev.c
+++ b/src/lib/dev.c
@@ -377,13 +377,13 @@ static void _flow_keepalive(struct flow * flow)
 
         clock_gettime(PTHREAD_COND_CLOCK, &now);
 
-        if (ts_diff_ns(&r_act, &now) > (int64_t) timeo * MILLION) {
+        if (ts_diff_ns(&now, &r_act) > (int64_t) timeo * MILLION) {
                 shm_rbuff_set_acl(flow->rx_rb, ACL_FLOWPEER);
                 shm_flow_set_notify(ai.fqset, flow_id, FLOW_PEER);
                 return;
         }
 
-        if (ts_diff_ns(&s_act, &now) > (int64_t) timeo * (MILLION >> 2)) {
+        if (ts_diff_ns(&now, &s_act) > (int64_t) timeo * (MILLION >> 2)) {
                 pthread_rwlock_unlock(&ai.lock);
 
                 flow_send_keepalive(flow, now);
diff --git a/src/lib/frct.c b/src/lib/frct.c
index d51cf006..4d871efe 100644
--- a/src/lib/frct.c
+++ b/src/lib/frct.c
@@ -159,11 +159,11 @@ static int frct_rib_read(const char * path,
                 frcti->rto,
                 frcti->snd_cr.lwe,
                 frcti->snd_cr.rwe,
-                ts_diff_ns(&frcti->snd_cr.act, &now),
+                ts_diff_ns(&now, &frcti->snd_cr.act),
                 frcti->snd_cr.seqno,
                 frcti->rcv_cr.lwe,
                 frcti->rcv_cr.rwe,
-                ts_diff_ns(&frcti->rcv_cr.act, &now),
+                ts_diff_ns(&now, &frcti->rcv_cr.act),
                 frcti->rcv_cr.seqno,
                 frcti->n_rtx,
                 frcti->n_prb,
@@ -303,13 +303,13 @@ static void send_frct_pkt(struct frcti * frcti)
         ackno = frcti->rcv_cr.lwe;
         rwe   = frcti->rcv_cr.rwe;
 
-        diff = ts_diff_ns(&frcti->rcv_cr.act, &now);
+        diff = ts_diff_ns(&now, &frcti->rcv_cr.act);
         if (diff > frcti->a) {
                 pthread_rwlock_unlock(&frcti->lock);
                 return;
         }
 
-        diff = ts_diff_ns(&frcti->snd_cr.act, &now);
+        diff = ts_diff_ns(&now, &frcti->snd_cr.act);
         if (diff < TICTIME) {
                 pthread_rwlock_unlock(&frcti->lock);
                 return;
@@ -339,7 +339,7 @@ static struct frcti * frcti_create(int    fd,
 #ifdef PROC_FLOW_STATS
         char                frctstr[FRCT_NAME_STRLEN + 1];
 #endif
-        mpl *= BILLION;
+        mpl *= MILLION;
         a   *= BILLION;
         r   *= BILLION;
 
@@ -517,14 +517,14 @@ static bool __frcti_is_window_open(struct frcti * frcti)
                         frcti->t_rdvs = now;
                 } else {
                         time_t diff;
-                        diff = ts_diff_ns(&frcti->t_wnd, &now);
+                        diff = ts_diff_ns(&now, &frcti->t_wnd);
                         if (diff > MAX_RDV) {
                                 pthread_mutex_unlock(&frcti->mtx);
                                 pthread_rwlock_unlock(&frcti->lock);
                                 return false;
                         }
 
-                        diff = ts_diff_ns(&frcti->t_rdvs, &now);
+                        diff = ts_diff_ns(&now, &frcti->t_rdvs);
                         if  (diff > frcti->rdv) {
                                 frcti->t_rdvs = now;
                                 __send_rdv(frcti->fd);
@@ -580,13 +580,13 @@ static int __frcti_window_wait(struct frcti *    frcti,
 
                         clock_gettime(PTHREAD_COND_CLOCK, &now);
 
-                        diff = ts_diff_ns(&frcti->t_wnd, &now);
+                        diff = ts_diff_ns(&now, &frcti->t_wnd);
                         if (diff > MAX_RDV) {
                                 pthread_mutex_unlock(&frcti->mtx);
                                 return -ECONNRESET; /* write fails! */
                         }
 
-                        diff = ts_diff_ns(&frcti->t_rdvs, &now);
+                        diff = ts_diff_ns(&now, &frcti->t_rdvs);
                         if  (diff > frcti->rdv) {
                                 frcti->t_rdvs = now;
                                 __send_rdv(frcti->fd);
@@ -855,7 +855,7 @@ static void __frcti_rcv(struct frcti *       frcti,
                         if (!(pci->flags & FRCT_DATA))
                                 frcti->n_dak++;
 #endif
-                        rtt_estimator(frcti, ts_diff_ns(&frcti->t_probe, &now));
+                        rtt_estimator(frcti, ts_diff_ns(&now, &frcti->t_probe));
                         frcti->probe = false;
                 }
         }
diff --git a/src/lib/tests/auth_test.c b/src/lib/tests/auth_test.c
index c3d42b8f..271fdabf 100644
--- a/src/lib/tests/auth_test.c
+++ b/src/lib/tests/auth_test.c
@@ -36,7 +36,7 @@
 *   https://community.f5.com/kb/technicalarticles/
 */
 
-/* Root certificate for CA ca.unittest.o7s */
+/* Root certificate for CA ca2.unittest.o7s */
 static const char * root_ca_crt = \
 "-----BEGIN CERTIFICATE-----\n"
 "MIICiTCCAi+gAwIBAgIUe4iFIymeUTgutBrdvcxFihOVHnowCgYIKoZIzj0EAwIw\n"
@@ -55,7 +55,7 @@ static const char * root_ca_crt = \
 "JSTSWB29kFFiM9ZdMV7M/tiZH9nSz1M8XhsTIGk=\n"
 "-----END CERTIFICATE-----\n";
 
-/* Certificate for intermediary im.unittest.o7s used for signing */
+/* Certificate for intermediary im2.unittest.o7s used for signing */
 static const char * intermediate_ca_crt = \
 "-----BEGIN CERTIFICATE-----\n"
 "MIIChTCCAiqgAwIBAgICEAIwCgYIKoZIzj0EAwIwgZExCzAJBgNVBAYTAkJFMQww\n"
@@ -74,7 +74,7 @@ static const char * intermediate_ca_crt = \
 "NnkLn+73oMj8w4pXGLNKAkX0z7yPJ4QhwA==\n"
 "-----END CERTIFICATE-----\n";
 
-/* Server server-1.unittest.o7s private-public key pair */
+/* Server server-2.unittest.o7s private-public key pair */
 static const char * server_ec_pkp = \
 "-----BEGIN EC PRIVATE KEY-----\n"
 "MHcCAQEEIC13y+5jdKe80HBJD7WITpQamcn3rrkTX1r0v+JwSk4NoAoGCCqGSM49\n"
@@ -89,7 +89,7 @@ static const char * server_ec_pk = \
 "uhDhqqrEcBO5+eob2xyqEaNknIV/86724zPptGRahWz0rzW2PvNppJdNBg==\n"
 "-----END PUBLIC KEY-----\n";
 
-/* Valid signed server certificate for server-1.unittest.o7s, SHA2 */
+/* Valid signed server certificate for server-2.unittest.o7s */
 static const char * signed_server_crt = \
 "-----BEGIN CERTIFICATE-----\n"
 "MIIDgjCCAyigAwIBAgICEAIwCgYIKoZIzj0EAwIwWzELMAkGA1UEBhMCQkUxDDAK\n"
diff --git a/src/lib/tests/time_test.c b/src/lib/tests/time_test.c
index 77fecdac..2b75b873 100644
--- a/src/lib/tests/time_test.c
+++ b/src/lib/tests/time_test.c
@@ -22,145 +22,508 @@
 
 #define _POSIX_C_SOURCE 200809L
 
+#include <ouroboros/test.h>
 #include <ouroboros/time.h>
 
 #include <stdio.h>
 
-static void ts_print(struct timespec * s)
+static int ts_check(struct timespec * s,
+                    time_t            sec,
+                    time_t            nsec)
 {
-        printf("timespec is %zd:%ld.\n",
-               (ssize_t) s->tv_sec, s->tv_nsec);
+        return s->tv_sec == sec && s->tv_nsec == nsec;
 }
 
-static void tv_print(struct timeval * v)
+static int tv_check(struct timeval * v,
+                    time_t           sec,
+                    time_t           usec)
 {
-        printf("timeval is %zd:%zu.\n",
-               (ssize_t) v->tv_sec, (size_t) v->tv_usec);
+        return v->tv_sec == sec && v->tv_usec == usec;
 }
 
-static void ts_init(struct timespec * s,
-                    time_t            sec,
-                    time_t            nsec)
+
+static int test_time_ts_init(void)
 {
-        s->tv_sec  = sec;
-        s->tv_nsec = nsec;
+        struct timespec s  = TIMESPEC_INIT_S (100);
+        struct timespec ms = TIMESPEC_INIT_MS(100);
+        struct timespec us = TIMESPEC_INIT_US(100);
+        struct timespec ns = TIMESPEC_INIT_NS(100);
+
+        TEST_START();
+
+        if (!ts_check(&s, 100, 0)) {
+                printf("timespec_init_s failed.\n");
+                goto fail;
+        }
+
+        if (!ts_check(&ms, 0, 100 * MILLION)) {
+                printf("timespec_init_ms failed.\n");
+                goto fail;
+        }
+
+        if (!ts_check(&us, 0, 100* 1000L)) {
+                printf("timespec_init_us failed.\n");
+                goto fail;
+        }
+
+        if (!ts_check(&ns, 0, 100)) {
+                printf("timespec_init_ns failed.\n");
+                goto fail;
+        }
+
+        TEST_SUCCESS();
+
+        return TEST_RC_SUCCESS;
+ fail:
+        TEST_FAIL();
+        return TEST_RC_FAIL;
 }
 
-static void tv_init(struct timeval * v,
-                    time_t           sec,
-                    time_t           usec)
+static int test_time_tv_init(void)
 {
-        v->tv_sec  = sec;
-        v->tv_usec = usec;
+        struct timeval s  = TIMEVAL_INIT_S (100);
+        struct timeval ms = TIMEVAL_INIT_MS(100);
+        struct timeval us = TIMEVAL_INIT_US(100);
+
+        TEST_START();
+
+        if (!tv_check(&s, 100, 0)) {
+                printf("timeval_init_s failed.\n");
+                goto fail;
+        }
+
+        if (!tv_check(&ms, 0, 100 * 1000L)) {
+                printf("timeval_init_ms failed.\n");
+                goto fail;
+        }
+
+        if (!tv_check(&us, 0, 100)) {
+                printf("timeval_init_us failed.\n");
+                goto fail;
+        }
+
+        TEST_SUCCESS();
+
+        return TEST_RC_SUCCESS;
+ fail:
+        TEST_FAIL();
+        return TEST_RC_FAIL;
 }
 
-static int ts_check(struct timespec * s,
-                    time_t            sec,
-                    time_t            nsec)
+static int test_ts_diff(void)
 {
-        return s->tv_sec == sec && s->tv_nsec == nsec;
+        struct timespec s0  = TIMESPEC_INIT_S (100);
+        struct timespec s1  = TIMESPEC_INIT_S (200);
+        struct timespec ms0 = TIMESPEC_INIT_MS(100);
+        struct timespec ms1 = TIMESPEC_INIT_MS(200);
+        struct timespec us0 = TIMESPEC_INIT_US(100);
+        struct timespec us1 = TIMESPEC_INIT_US(200);
+        struct timespec ns0 = TIMESPEC_INIT_NS(100);
+        struct timespec ns1 = TIMESPEC_INIT_NS(200);
+        struct timespec res;
+
+        TEST_START();
+
+        ts_diff(&s0, &s1, &res);
+        if (!ts_check(&res, -100, 0)) {
+                printf("timespec_diff failed at s0 - s1.\n");
+                goto fail;
+        }
+
+        ts_diff(&s1, &s0, &res);
+        if (!ts_check(&res, 100, 0)) {
+                printf("timespec_diff failed at s1 - s0.\n");
+                goto fail;
+        }
+
+        ts_diff(&ms0, &ms1, &res);
+        if (!ts_check(&res, -1, 900 * MILLION)) {
+                printf("timespec_diff failed at ms0 - ms1.\n");
+                goto fail;
+        }
+
+        ts_diff(&ms1, &ms0, &res);
+        if (!ts_check(&res, 0, 100 * MILLION)) {
+                printf("timespec_diff failed at ms1 - ms0.\n");
+                goto fail;
+        }
+
+        ts_diff(&us0, &us1, &res);
+        if (!ts_check(&res, -1, 999900 * 1000L)) {
+                printf("timespec_diff failed at us0 - us1.\n");
+                goto fail;
+        }
+
+        ts_diff(&us1, &us0, &res);
+        if (!ts_check(&res, 0, 100 * 1000L)) {
+                printf("timespec_diff failed at us1 - us0.\n");
+                goto fail;
+        }
+
+        ts_diff(&ns0, &ns1, &res);
+        if (!ts_check(&res, -1, 999999900)) {
+                printf("timespec_diff failed at ns0 - ns1.\n");
+                goto fail;
+        }
+
+        ts_diff(&ns1, &ns0, &res);
+        if (!ts_check(&res, 0, 100)) {
+                printf("timespec_diff failed at ns1 - ns0.\n");
+                goto fail;
+        }
+
+        ts_diff(&s0, &ms0, &res);
+        if (!ts_check(&res, 99, 900 * MILLION)) {
+                printf("timespec_diff failed at s0 - ms0.\n");
+                goto fail;
+        }
+
+        ts_diff(&s0, &us0, &res);
+        if (!ts_check(&res, 99, 999900 * 1000L)) {
+                printf("timespec_diff failed at s0 - us0.\n");
+                goto fail;
+        }
+
+        ts_diff(&s0, &ns0, &res);
+        if (!ts_check(&res, 99, 999999900)) {
+                printf("timespec_diff failed at s0 - ns0.\n");
+                goto fail;
+        }
+
+        ts_diff(&ms0, &us0, &res);
+        if (!ts_check(&res, 0, 99900 * 1000L)) {
+                printf("timespec_diff failed at ms0 - us0.\n");
+                goto fail;
+        }
+
+        ts_diff(&ms0, &ns0, &res);
+        if (!ts_check(&res, 0, 99999900)) {
+                printf("timespec_diff failed at ms0 - ns0.\n");
+                goto fail;
+        }
+
+        ts_diff(&us0, &ns0, &res);
+        if (!ts_check(&res, 0, 99900)) {
+                printf("timespec_diff failed at us0 - ns0.\n");
+                goto fail;
+        }
+
+        TEST_SUCCESS();
+
+        return TEST_RC_SUCCESS;
+ fail:
+        TEST_FAIL();
+        return TEST_RC_FAIL;
 }
 
-static int tv_check(struct timeval * v,
-                    time_t           sec,
-                    time_t           usec)
+static int test_tv_diff(void)
 {
-        return v->tv_sec == sec && v->tv_usec == usec;
+        struct timeval s0  = TIMEVAL_INIT_S (100);
+        struct timeval s1  = TIMEVAL_INIT_S (200);
+        struct timeval ms0 = TIMEVAL_INIT_MS(100);
+        struct timeval ms1 = TIMEVAL_INIT_MS(200);
+        struct timeval us0 = TIMEVAL_INIT_US(100);
+        struct timeval us1 = TIMEVAL_INIT_US(200);
+        struct timeval res;
+
+        TEST_START();
+
+        tv_diff(&s0, &s1, &res);
+        if (!tv_check(&res, -100, 0)) {
+                printf("timeval_diff failed at s0 - s1.\n");
+                goto fail;
+        }
+
+        tv_diff(&s1, &s0, &res);
+        if (!tv_check(&res, 100, 0)) {
+                printf("timeval_diff failed at s1 - s0.\n");
+                goto fail;
+        }
+
+        tv_diff(&ms0, &ms1, &res);
+        if (!tv_check(&res, -1, 900 * 1000L)) {
+                printf("timeval_diff failed at ms0 - ms1.\n");
+                goto fail;
+        }
+
+        tv_diff(&ms1, &ms0, &res);
+        if (!tv_check(&res, 0, 100 * 1000L)) {
+                printf("timeval_diff failed at ms1 - ms0.\n");
+                goto fail;
+        }
+
+        tv_diff(&us0, &us1, &res);
+        if (!tv_check(&res, -1, 999900)) {
+                printf("timeval_diff failed at us0 - us1.\n");
+                goto fail;
+        }
+
+        tv_diff(&us1, &us0, &res);
+        if (!tv_check(&res, 0, 100)) {
+                printf("timeval_diff failed at us1 - us0.\n");
+                goto fail;
+        }
+
+        tv_diff(&s0, &ms0, &res);
+        if (!tv_check(&res, 99, 900 * 1000L)) {
+                printf("timeval_diff failed at s0 - ms0.\n");
+                goto fail;
+        }
+
+        tv_diff(&s0, &us0, &res);
+        if (!tv_check(&res, 99, 999900)) {
+                printf("timeval_diff failed at s0 - us0.\n");
+                goto fail;
+        }
+
+        tv_diff(&ms0, &us0, &res);
+        if (!tv_check(&res, 0, 99900)) {
+                printf("timeval_diff failed at ms0 - us0.\n");
+                goto fail;
+        }
+
+        TEST_SUCCESS();
+
+        return TEST_RC_SUCCESS;
+ fail:
+        TEST_FAIL();
+        return TEST_RC_FAIL;
 }
 
-int time_test(int     argc,
-              char ** argv)
+static int test_ts_diff_time(void)
 {
-        struct timespec s0;
-        struct timespec s1;
-        struct timespec s2;
+        struct timespec s0  = TIMESPEC_INIT_S (100);
+        struct timespec s1  = TIMESPEC_INIT_S (200);
+        struct timespec ms0 = TIMESPEC_INIT_MS(100);
+        struct timespec ms1 = TIMESPEC_INIT_MS(200);
+        struct timespec us0 = TIMESPEC_INIT_US(100);
+        struct timespec us1 = TIMESPEC_INIT_US(200);
+        struct timespec ns0 = TIMESPEC_INIT_NS(100);
+        struct timespec ns1 = TIMESPEC_INIT_NS(200);
 
-        struct timeval v0;
-        struct timeval v1;
-        struct timeval v2;
+        TEST_START();
 
-        (void) argc;
-        (void) argv;
+        if (ts_diff_ms(&s0, &s1) != -100 * 1000L) {
+                printf("timespec_diff_ms failed at s0 - s1.\n");
+                goto fail;
+        }
+
+        if (ts_diff_ms(&s1, &s0) != 100 * 1000L) {
+                printf("timespec_diff_ms failed at s1 - s0.\n");
+                goto fail;
+        }
+
+        if (ts_diff_us(&s0, &s1) != -100 * MILLION) {
+                printf("timespec_diff_us failed at s1 - s0.\n");
+                goto fail;
+        }
+
+        if (ts_diff_us(&s1, &s0) != 100 * MILLION) {
+                printf("timespec_diff_us failed at s0 - s1.\n");
+                goto fail;
+        }
+
+        if (ts_diff_ns(&s0, &s1) != -100 * BILLION) {
+                printf("timespec_diff_ns failed at s0 - s1.\n");
+                goto fail;
+        }
+
+        if (ts_diff_ns(&s1, &s0) != 100 * BILLION) {
+                printf("timespec_diff_ns failed at s1 - s0.\n");
+                goto fail;
+        }
+
+        if (ts_diff_ms(&ms0, &ms1) != -100) {
+                printf("timespec_diff_ms failed at ms0 - ms1.\n");
+                goto fail;
+        }
+
+        if (ts_diff_ms(&ms1, &ms0) != 100) {
+                printf("timespec_diff_ms failed at ms1 - ms0.\n");
+                goto fail;
+        }
 
-        ts_init(&s0, 0, 0);
-        ts_init(&s1, 5, 0);
+        if (ts_diff_us(&ms0, &ms1) != -100 * 1000L) {
+                printf("timespec_diff_us failed at ms0 - ms1.\n");
+                goto fail;
+        }
 
-        ts_add(&s0, &s1, &s2);
-        if (!ts_check(&s2, 5, 0)) {
-                printf("ts_add failed.\n");
-                ts_print(&s2);
-                return -1;
+        if (ts_diff_us(&ms1, &ms0) != 100 * 1000L) {
+                printf("timespec_diff_us failed at ms1 - ms0.\n");
+                goto fail;
         }
 
-        tv_init(&v0, 0, 0);
-        tv_init(&v1, 5, 0);
+        if (ts_diff_ns(&ms0, &ms1) != -100 * MILLION) {
+                printf("timespec_diff_ns failed at ms0 - ms1.\n");
+                goto fail;
+        }
 
-        tv_add(&v0, &v1, &v2);
-        if (!tv_check(&v2, 5, 0)) {
-                printf("tv_add failed.\n");
-                tv_print(&v2);
-                return -1;
+        if (ts_diff_ns(&ms1, &ms0) != 100 * MILLION) {
+                printf("timespec_diff_ns failed at ms1 - ms0.\n");
+                goto fail;
         }
 
-        ts_init(&s0, 0, 500 * MILLION);
-        ts_init(&s1, 0, 600 * MILLION);
+        if (ts_diff_ms(&us0, &us1) != 0) {
+                printf("timespec_diff_ms failed at us0 - us1.\n");
+                goto fail;
+        }
 
-        ts_add(&s0, &s1, &s2);
-        if (!ts_check(&s2, 1, 100 * MILLION)) {
-                printf("ts_add with nano overflow failed.\n");
-                ts_print(&s2);
-                return -1;
+        if (ts_diff_ms(&us1, &us0) != 0) {
+                printf("timespec_diff_ms failed at us1 - us0.\n");
+                goto fail;
         }
 
-        tv_init(&v0, 0, 500 * 1000);
-        tv_init(&v1, 0, 600 * 1000);
+        if (ts_diff_us(&us0, &us1) != -100) {
+                printf("timespec_diff_us failed at us0 - us1.\n");
+                goto fail;
+        }
 
-        tv_add(&v0, &v1, &v2);
-        if (!tv_check(&v2, 1, 100 * 1000)) {
-                printf("tv_add with nano overflow failed.\n");
-                tv_print(&v2);
-                return -1;
+        if (ts_diff_us(&us1, &us0) != 100) {
+                printf("timespec_diff_us failed at us1 - us0.\n");
+                goto fail;
         }
 
-        ts_init(&s0, 0, 0);
-        ts_init(&s1, 5, 0);
+        if (ts_diff_ns(&us0, &us1) != -100 * 1000L) {
+                printf("timespec_diff_ns failed at us0 - us1.\n");
+                goto fail;
+        }
 
-        ts_diff(&s0, &s1, &s2);
-        if (!ts_check(&s2, -5, 0)) {
-                printf("ts_diff failed.\n");
-                ts_print(&s2);
-                return -1;
+        if (ts_diff_ns(&us1, &us0) != 100 * 1000L) {
+                printf("timespec_diff_ns failed at us1 - us0.\n");
+                goto fail;
         }
 
-        tv_init(&v0, 0, 0);
-        tv_init(&v1, 5, 0);
+        if (ts_diff_ms(&ns0, &ns1) != 0) {
+                printf("timespec_diff_ms failed at ns0 - ns1.\n");
+                goto fail;
+        }
 
-        tv_diff(&v0, &v1, &v2);
-        if (!tv_check(&v2, -5, 0)) {
-                printf("tv_diff failed.\n");
-                tv_print(&v2);
-                return -1;
+        if (ts_diff_ms(&ns1, &ns0) != 0) {
+                printf("timespec_diff_ms failed at ns1 - ns0.\n");
+                goto fail;
         }
 
-        ts_init(&s0, 0, 500 * MILLION);
-        ts_init(&s1, 0, 600 * MILLION);
+        if (ts_diff_us(&ns0, &ns1) != 0) {
+                printf("timespec_diff_us failed at ns0 - ns1.\n");
+                goto fail;
+        }
 
-        ts_diff(&s0, &s1, &s2);
-        if (!ts_check(&s2, -1, 900 * MILLION)) {
-                printf("ts_diff with nano underflow failed.\n");
-                ts_print(&s2);
-                return -1;
+        if (ts_diff_us(&ns1, &ns0) != 0) {
+                printf("timespec_diff_us failed at ns1 - ns0.\n");
+                goto fail;
         }
 
-        tv_init(&v0, 0, 500 * 1000);
-        tv_init(&v1, 0, 600 * 1000);
+        if (ts_diff_ns(&ns0, &ns1) != -100) {
+                printf("timespec_diff_ns failed at ns0 - ns1.\n");
+                goto fail;
+        }
 
-        tv_diff(&v0, &v1, &v2);
-        if (!tv_check(&v2, -1, 900 * 1000)) {
-                printf("tv_diff with nano underflow failed.\n");
-                tv_print(&v2);
-                return -1;
+        if (ts_diff_ns(&ns1, &ns0) != 100) {
+                printf("timespec_diff_ns failed at ns1 - ns0.\n");
+                goto fail;
         }
 
-        return 0;
+        TEST_SUCCESS();
+
+        return TEST_RC_SUCCESS;
+ fail:
+        TEST_FAIL();
+        return TEST_RC_FAIL;
+}
+
+static int test_tv_diff_time(void)
+{
+        struct timeval s0  = TIMEVAL_INIT_S (100);
+        struct timeval s1  = TIMEVAL_INIT_S (200);
+        struct timeval ms0 = TIMEVAL_INIT_MS(100);
+        struct timeval ms1 = TIMEVAL_INIT_MS(200);
+        struct timeval us0 = TIMEVAL_INIT_US(100);
+        struct timeval us1 = TIMEVAL_INIT_US(200);
+
+        TEST_START();
+
+        if (tv_diff_ms(&s0, &s1) != -100 * 1000L) {
+                printf("timeval_diff_ms failed at s0 - s1.\n");
+                goto fail;
+        }
+
+        if (tv_diff_ms(&s1, &s0) != 100 * 1000L) {
+                printf("timeval_diff_ms failed at s1 - s0.\n");
+                goto fail;
+        }
+
+        if (tv_diff_us(&s0, &s1) != -100 * MILLION) {
+                printf("timeval_diff_us failed at s0 - s1.\n");
+                goto fail;
+        }
+
+        if (tv_diff_us(&s1, &s0) != 100 * MILLION) {
+                printf("timeval_diff_us failed at s1 - s0.\n");
+                goto fail;
+        }
+
+        if (tv_diff_ms(&ms0, &ms1) != -100) {
+                printf("timeval_diff_ms failed at ms0 - ms1.\n");
+                goto fail;
+        }
+
+        if (tv_diff_ms(&ms1, &ms0) != 100) {
+                printf("timeval_diff_ms failed at ms1 - ms0.\n");
+                goto fail;
+        }
+
+        if (tv_diff_us(&ms0, &ms1) != -100 * 1000L) {
+                printf("timeval_diff_us failed at ms0 - ms1.\n");
+                goto fail;
+        }
+
+        if (tv_diff_us(&ms1, &ms0) != 100 * 1000L) {
+                printf("timeval_diff_us failed at ms1 - ms0.\n");
+                goto fail;
+        }
+
+        if (tv_diff_ms(&us0, &us1) != 0) {
+                printf("timeval_diff_ms failed at us0 - us1.\n");
+                goto fail;
+        }
+
+        if (tv_diff_ms(&us1, &us0) != 0) {
+                printf("timeval_diff_ms failed at us1 - us0.\n");
+                goto fail;
+        }
+
+        if (tv_diff_us(&us0, &us1) != -100) {
+                printf("timeval_diff_us failed at us0 - us1.\n");
+                goto fail;
+        }
+
+        if (tv_diff_us(&us1, &us0) != 100) {
+                printf("timeval_diff_us failed at us1 - us0.\n");
+                goto fail;
+        }
+
+        TEST_SUCCESS();
+
+        return TEST_RC_SUCCESS;
+ fail:
+        TEST_FAIL();
+        return TEST_RC_FAIL;
+}
+
+int time_test(int argc,
+              char ** argv)
+{
+        int ret = 0;
+
+        (void) argc;
+        (void) argv;
+
+        ret |= test_time_ts_init();
+        ret |= test_time_tv_init();
+        ret |= test_ts_diff();
+        ret |= test_tv_diff();
+        ret |= test_ts_diff_time();
+        ret |= test_tv_diff_time();
+
+        return ret;
 }
diff --git a/src/lib/tpm.c b/src/lib/tpm.c
index 64777815..a7391bd7 100644
--- a/src/lib/tpm.c
+++ b/src/lib/tpm.c
@@ -31,16 +31,23 @@
 
 #include <assert.h>
 #include <pthread.h>
+#include <stdio.h>
 #include <stdlib.h>
+#include <string.h>
+#include <unistd.h>
 
-#define TPM_TIMEOUT 1000
+#define TPM_TIMEOUT      1000
 
 struct pthr_el {
         struct list_head next;
 
         bool             kill;
         bool             busy;
-
+        bool             wait;
+#ifdef CONFIG_OUROBOROS_DEBUG
+        struct timespec  start;
+        struct timespec  last;
+#endif
         pthread_t        thr;
 };
 
@@ -72,6 +79,10 @@ static void tpm_join(struct tpm * tpm)
 {
         struct list_head * p;
         struct list_head * h;
+#ifdef CONFIG_OUROBOROS_DEBUG
+        struct timespec now;
+        clock_gettime(CLOCK_REALTIME, &now);
+#endif
 
         list_for_each_safe(p, h, &tpm->pool) {
                 struct pthr_el * e = list_entry(p, struct pthr_el, next);
@@ -86,6 +97,21 @@ static void tpm_join(struct tpm * tpm)
 
         list_for_each_safe(p, h, &tpm->pool) {
                 struct pthr_el * e = list_entry(p, struct pthr_el, next);
+#ifdef CONFIG_OUROBOROS_DEBUG
+                time_t diff = ts_diff_ms(&now, &e->start) / 1000;
+                bool hung;
+                if (TPM_DEBUG_REPORT_INTERVAL > 0) {
+                        time_t ldiff = ts_diff_ms(&now, &e->last) / 1000;
+                        if(e->busy && ldiff > TPM_DEBUG_REPORT_INTERVAL) {
+                                e->last = now;
+                                printf("Thread %d:%lx running for %ld s.\n",
+                                       getpid(),e->thr, diff);
+                        }
+                }
+                hung = e->busy && !e->wait && diff > TPM_DEBUG_ABORT_TIMEOUT;
+                if (TPM_DEBUG_ABORT_TIMEOUT > 0 && hung)
+                        assert(false); /* coredump */
+#endif
                 if (e->kill) {
                         pthread_t thr = e->thr;
                         list_del(&e->next);
@@ -139,11 +165,9 @@ static int __tpm(struct tpm * tpm)
                         if (e == NULL)
                                 break;
 
-                        e->kill = false;
-                        e->busy = false;
+                        memset(e, 0, sizeof(*e));
 
-                        if (pthread_create(&e->thr, NULL,
-                                                tpm->func, tpm->o)) {
+                        if (pthread_create(&e->thr, NULL, tpm->func, tpm->o)) {
                                 free(e);
                                 break;
                         }
@@ -280,12 +304,21 @@ void tpm_begin_work(struct tpm * tpm)
 {
         struct pthr_el * e;
 
+#ifdef CONFIG_OUROBOROS_DEBUG
+        struct timespec now;
+        clock_gettime(CLOCK_REALTIME, &now);
+#endif
+
         pthread_mutex_lock(&tpm->mtx);
 
         e = tpm_pthr_el(tpm, pthread_self());
         if (e != NULL) {
                 e->busy = true;
                 ++tpm->wrk;
+#ifdef CONFIG_OUROBOROS_DEBUG
+                e->start = now;
+                e->last  = now;
+#endif
         }
 
         pthread_cond_signal(&tpm->cond);
@@ -293,6 +326,19 @@ void tpm_begin_work(struct tpm * tpm)
         pthread_mutex_unlock(&tpm->mtx);
 }
 
+void tpm_wait_work(struct tpm * tpm)
+{
+        struct pthr_el * e;
+
+        pthread_mutex_lock(&tpm->mtx);
+
+        e = tpm_pthr_el(tpm, pthread_self());
+        if (e != NULL)
+                e->wait = true;
+
+        pthread_mutex_unlock(&tpm->mtx);
+}
+
 void tpm_end_work(struct tpm * tpm)
 {
         struct pthr_el * e;