ipcpd: Add IDs to enrollment

The enrollment messages now have a 64-bit ID to easier track
enrollments in the logs in larger scale tests.

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

4 files changed, 200 insertions, 171 deletions

diff --git a/src/ipcpd/broadcast/main.c b/src/ipcpd/broadcast/main.c
index 30cb49b0..ab8fc5bd 100644
--- a/src/ipcpd/broadcast/main.c
+++ b/src/ipcpd/broadcast/main.c
@@ -32,11 +32,11 @@
 #define THIS_TYPE IPCP_BROADCAST
 
 #include <ouroboros/errno.h>
-#include <ouroboros/hash.h>
 #include <ouroboros/dev.h>
 #include <ouroboros/ipcp-dev.h>
 #include <ouroboros/logs.h>
 #include <ouroboros/notifier.h>
+#include <ouroboros/random.h>
 #include <ouroboros/rib.h>
 #include <ouroboros/time_utils.h>
 
@@ -61,7 +61,7 @@ static int initialize_components(const struct ipcp_config * conf)
 
         assert(ipcp_dir_hash_len() != 0);
 
-        if (dt_init()) {
+        if (dt_init() < 0) {
                 log_err("Failed to initialize forwarding component.");
                 return -1;
         }
@@ -82,12 +82,12 @@ static int start_components(void)
 
         ipcp_set_state(IPCP_OPERATIONAL);
 
-        if (enroll_start()) {
+        if (enroll_start() < 0) {
                 log_err("Failed to start enrollment.");
                 goto fail_enroll_start;
         }
 
-        if (connmgr_start()) {
+        if (connmgr_start() < 0) {
                 log_err("Failed to start AP connection manager.");
                 goto fail_connmgr_start;
         }
@@ -117,35 +117,44 @@ static int broadcast_ipcp_enroll(const char *        dst,
                                  struct layer_info * info)
 {
         struct conn conn;
+        uint8_t     id[ENROLL_ID_LEN];
 
-        if (connmgr_alloc(COMPID_ENROLL, dst, NULL, &conn)) {
-                log_err("Failed to get connection.");
-                goto fail_er_flow;
+        if (random_buffer(id, ENROLL_ID_LEN) < 0) {
+                log_err("Failed to generate enrollment ID.");
+                goto fail_id;
+        }
+
+        log_info_id(id, "Requesting enrollment.");
+
+        if (connmgr_alloc(COMPID_ENROLL, dst, NULL, &conn) < 0) {
+                log_err_id(id, "Failed to get connection.");
+                goto fail_id;
         }
 
         /* Get boot state from peer. */
-        if (enroll_boot(&conn)) {
-                log_err("Failed to get boot information.");
+        if (enroll_boot(&conn, id) < 0) {
+                log_err_id(id, "Failed to get boot information.");
                 goto fail_enroll_boot;
         }
 
-        if (initialize_components(enroll_get_conf())) {
-                log_err("Failed to initialize IPCP components.");
+        if (initialize_components(enroll_get_conf()) < 0) {
+                log_err_id(id, "Failed to initialize components.");
                 goto fail_enroll_boot;
         }
 
-        if (start_components()) {
-                log_err("Failed to start components.");
+        if (start_components() < 0) {
+                log_err_id(id, "Failed to start components.");
                 goto fail_start_comp;
         }
 
-        if (enroll_ack(&conn, 0))
-                log_warn("Failed to confirm enrollment with peer.");
+        if (enroll_ack(&conn, id, 0) < 0)
+                log_err_id(id, "Failed to confirm enrollment.");
+
+        if (connmgr_dealloc(COMPID_ENROLL, &conn) < 0)
+                log_warn_id(id, "Failed to dealloc enrollment flow.");
 
-        if (connmgr_dealloc(COMPID_ENROLL, &conn))
-                log_warn("Failed to deallocate enrollment flow.");
+        log_info_id(id, "Enrolled with %s.", dst);
 
-        log_info("Enrolled with %s.", dst);
 
         info->dir_hash_algo = ipcpi.dir_hash_algo;
         strcpy(info->layer_name, ipcpi.layer_name);
@@ -156,7 +165,7 @@ static int broadcast_ipcp_enroll(const char *        dst,
         finalize_components();
  fail_enroll_boot:
         connmgr_dealloc(COMPID_ENROLL, &conn);
- fail_er_flow:
+ fail_id:
         return -1;
 }
 
diff --git a/src/ipcpd/common/enroll.c b/src/ipcpd/common/enroll.c
index 8f0fb929..4cc2fa42 100644
--- a/src/ipcpd/common/enroll.c
+++ b/src/ipcpd/common/enroll.c
@@ -28,7 +28,6 @@
 
 #define OUROBOROS_PREFIX "enrollment"
 
-#include <ouroboros/endian.h>
 #include <ouroboros/errno.h>
 #include <ouroboros/time_utils.h>
 #include <ouroboros/dev.h>
@@ -62,208 +61,219 @@ struct {
         pthread_t          listener;
 } enroll;
 
-static int send_rcv_enroll_msg(int fd)
-{
-        uint8_t            __buf[ENROLL_BUF_LEN];
-        buffer_t           buf;
-        buffer_t           msg;
-        ssize_t            len;
-        ssize_t            delta_t;
-        struct timespec    t0;
-        struct timespec    rtt;
-        int                ret;
-        struct enroll_resp resp;
-
-        buf.data = __buf;
-        buf.len  = sizeof(__buf);
-
-        len = enroll_req_ser(buf);
-        if (len < 0) {
-                log_dbg("Failed to pack request message.");
-                return -1;
-        }
-
-        clock_gettime(CLOCK_REALTIME, &t0);
-
-        log_dbg("Sending request message.");
-
-        if (flow_write(fd, buf.data, len) < 0) {
-                log_dbg("Failed to send request message.");
-                return -1;
-        }
-
-        log_dbg("Waiting for reply message.");
-
-        len = flow_read(fd, buf.data, buf.len);
-        if (len < 0) {
-                log_dbg("No reply received.");
-                return -1;
-        }
-
-        log_dbg("Received configuration info (%zd bytes).", len);
-
-        msg.data = buf.data;
-        msg.len  = len;
-
-        ret = enroll_resp_des(&resp, msg);
-        if (ret < 0) {
-                log_dbg("Failed to unpack response message.");
-                return -1;
-        }
-
-        if (resp.response < 0) {
-                log_dbg("Remote denied request: %d.", resp.response);
-                return -1;
-        }
-
-        if (resp.conf.type != ipcpi.type) {
-                log_dbg("Wrong type in enrollment response %d (%d).",
-                        resp.conf.type, ipcpi.type);
-                return -1;
-        }
-
-        clock_gettime(CLOCK_REALTIME, &rtt);
-
-        delta_t = ts_diff_ms(&t0, &rtt);
-
-        rtt.tv_sec  = resp.t.tv_sec;
-        rtt.tv_nsec = resp.t.tv_nsec;
-
-        if (labs(ts_diff_ms(&t0, &rtt)) - delta_t > ENROLL_WARN_TIME_OFFSET)
-                log_warn("Clock offset above threshold.");
-
-        enroll.conf = resp.conf;
-
-        return 0;
-}
-
-
 static void * enroll_handle(void * o)
 {
+        struct enroll_req  req;
         struct enroll_resp resp;
+        struct enroll_ack  ack;
         struct conn        conn;
         uint8_t             __buf[ENROLL_BUF_LEN];
         buffer_t           buf;
         ssize_t            len;
-        int                response;
 
         (void) o;
 
         buf.data = __buf;
         buf.len  = sizeof(__buf);
 
+        resp.response = 0;
         resp.conf = enroll.conf;
 
         while (true) {
                 buffer_t msg;
+                int      fd;
 
                 if (connmgr_wait(COMPID_ENROLL, &conn)) {
                         log_err("Failed to get next connection.");
                         continue;
                 }
 
-                log_info("New enrollment connection.");
+                fd = conn.flow_info.fd;
 
-                len = flow_read(conn.flow_info.fd, buf.data, buf.len);
+                log_info("Incoming enrollment connection on flow %d.", fd);
+
+                len = flow_read(fd, buf.data, buf.len);
                 if (len < 0) {
-                        log_err("Failed to read from flow.");
-                        connmgr_dealloc(COMPID_ENROLL, &conn);
-                        continue;
+                        log_warn("Failed to read from flow %d.", fd);
+                        goto finish_flow;
                 }
 
-                log_dbg("Read request from flow (%zd bytes).", len);
                 msg.data = buf.data;
                 msg.len = (size_t) len;
 
-                if (enroll_req_des(msg) < 0) {
-                        log_err("Failed to unpack request message.");
-                        connmgr_dealloc(COMPID_ENROLL, &conn);
-                        continue;
+                if (enroll_req_des(&req, msg) < 0) {
+                        log_warn("Failed to unpack request message.");
+                        goto finish_flow;
                 }
 
-                /* TODO: authentication */
+                log_info_id(req.id, "Handling incoming enrollment.");
+
+                /* TODO: authentication, timezone handling (UTC). */
 
-                log_dbg("Enrolling a new neighbor.");
+                ack.result = -100;
 
                 clock_gettime(CLOCK_REALTIME, &resp.t);
 
-                resp.response = 0;
+                memcpy(resp.id, req.id, ENROLL_ID_LEN);
 
                 len = enroll_resp_ser(&resp, buf);
                 if (len < 0) {
-                        log_err("Failed to pack reply.");
-                        connmgr_dealloc(COMPID_ENROLL, &conn);
-                        continue;
+                        log_err_id(req.id, "Failed to pack reply.");
+                        goto finish_enroll;
                 }
 
-                log_dbg("Sending enrollment info (%zd bytes).", len);
+                log_dbg_id(req.id, "Sending enrollment info (%zd bytes).", len);
 
                 if (flow_write(conn.flow_info.fd, buf.data, len) < 0) {
-                        log_err("Failed respond to request.");
-                        connmgr_dealloc(COMPID_ENROLL, &conn);
-                        continue;
+                        log_err_id(req.id, "Failed te send response.");
+                        goto finish_enroll;
                 }
 
                 len = flow_read(conn.flow_info.fd, buf.data, buf.len);
                 if (len < 0) {
-                        log_err("Failed to read from flow.");
-                        connmgr_dealloc(COMPID_ENROLL, &conn);
-                        continue;
+                        log_err_id(req.id, "Failed to read from flow.");
+                        goto finish_enroll;
+
                 }
 
                 msg.data = buf.data;
                 msg.len = (size_t) len;
 
-                if (enroll_ack_des(&response, msg) < 0) {
-                        log_err("Failed to unpack acknowledgment.");
-                        connmgr_dealloc(COMPID_ENROLL, &conn);
-                        continue;
+                if (enroll_ack_des(&ack, msg) < 0) {
+                        log_err_id(req.id, "Failed to unpack ack.");
+                        goto finish_enroll;
                 }
-                if (response == 0)
-                        log_info("Neighbor enrollment successful.");
-                else
-                        log_info("Neigbor enrolment failed at remote.");
 
+                if (memcmp(req.id, ack.id, ENROLL_ID_LEN) != 0)
+                       log_warn_id(req.id, "Enrollment ID mismatch.");
+
+         finish_enroll:
+                switch(ack.result) {
+                case 0:
+                        log_info_id(req.id, "Enrollment completed.");
+                        break;
+                case -100:
+                        log_warn_id(req.id, "Enrollment failed.");
+                        break;
+                default:
+                        log_warn_id(req.id, "Enrollment failed at remote.");
+                }
+         finish_flow:
                 connmgr_dealloc(COMPID_ENROLL, &conn);
 
-                log_info("Enrollment connection closed.");
+                log_info("Enrollment flow %d closed.", fd);
         }
 
         return 0;
 }
 
-int enroll_boot(struct conn * conn)
+int enroll_boot(struct conn *   conn,
+                const uint8_t * id)
 {
-        log_dbg("Starting enrollment.");
+        uint8_t            __buf[ENROLL_BUF_LEN];
+        buffer_t           buf;
+        buffer_t           msg;
+        ssize_t            len;
+        ssize_t            delta_t;
+        struct timespec    t0;
+        struct timespec    rtt;
+        int                fd;
+        int                ret;
+        struct enroll_req  req;
+        struct enroll_resp resp;
+
+        fd = conn->flow_info.fd;
+
+        buf.data = __buf;
+        buf.len  = sizeof(__buf);
+
+        memcpy(req.id, id, ENROLL_ID_LEN);
 
-        if (send_rcv_enroll_msg(conn->flow_info.fd)) {
-                log_err("Failed to enroll.");
+        len = enroll_req_ser(&req, buf);
+        if (len < 0) {
+                log_err_id(id, "Failed to pack request message.");
                 return -1;
         }
 
-        log_dbg("Enrollment complete.");
+        clock_gettime(CLOCK_REALTIME, &t0);
+
+        if (flow_write(fd, buf.data, len) < 0) {
+                log_err_id(id, "Failed to send request message.");
+                return -1;
+        }
+
+        len = flow_read(fd, buf.data, buf.len);
+        if (len < 0) {
+                log_err_id(id, "No reply received.");
+                return -1;
+        }
+
+        log_dbg_id(id, "Received configuration info (%zd bytes).", len);
+
+        msg.data = buf.data;
+        msg.len  = len;
+
+        ret = enroll_resp_des(&resp, msg);
+        if (ret < 0) {
+                log_err_id(id, "Failed to unpack response message.");
+                return -1;
+        }
+
+        if (memcmp(resp.id, id, ENROLL_ID_LEN) != 0) {
+                log_err_id(id, "Enrollment ID mismatch.");
+                return -1;
+        }
+
+        if (resp.response < 0) {
+                log_warn_id(id, "Remote denied request: %d.", resp.response);
+                return -1;
+        }
+
+        if (resp.conf.type != ipcpi.type) {
+                log_err_id(id, "Wrong type in enrollment response %d (%d).",
+                           resp.conf.type, ipcpi.type);
+                return -1;
+        }
+
+        clock_gettime(CLOCK_REALTIME, &rtt);
+
+        delta_t = ts_diff_ms(&t0, &rtt);
+
+        rtt.tv_sec  = resp.t.tv_sec;
+        rtt.tv_nsec = resp.t.tv_nsec;
+
+        if (labs(ts_diff_ms(&t0, &rtt)) - delta_t > ENROLL_WARN_TIME_OFFSET)
+                log_warn_id(id, "Clock offset above threshold.");
+
+        enroll.conf = resp.conf;
 
         return 0;
 }
 
-int enroll_ack(struct conn * conn,
-                int          result)
+int enroll_ack(struct conn *   conn,
+               const uint8_t * id,
+               const int       result)
 {
-        uint8_t            __buf[ENROLL_BUF_LEN];
-        buffer_t           buf;
-        ssize_t            len;
+        struct enroll_ack ack;
+        uint8_t           __buf[ENROLL_BUF_LEN];
+        buffer_t          buf;
+        ssize_t           len;
 
         buf.data = __buf;
         buf.len  = sizeof(__buf);
 
-        len = enroll_ack_ser(result, buf);
+        ack.result = result;
+
+        memcpy(ack.id, id, ENROLL_ID_LEN);
+
+        len = enroll_ack_ser(&ack, buf);
         if (len < 0) {
-                log_err("Failed to pack acknowledgement.");
+                log_err_id(id, "Failed to pack acknowledgement.");
                 return -1;
         }
 
         if (flow_write(conn->flow_info.fd, buf.data, len) < 0) {
-                log_dbg("Failed to send acknowledgment.");
+                log_err_id(id, "Failed to send acknowledgment.");
                 return -1;
         }
 
diff --git a/src/ipcpd/common/enroll.h b/src/ipcpd/common/enroll.h
index fa22923f..35af5f65 100644
--- a/src/ipcpd/common/enroll.h
+++ b/src/ipcpd/common/enroll.h
@@ -37,10 +37,12 @@ void                 enroll_stop(void);
 
 void                 enroll_bootstrap(const struct ipcp_config * conf);
 
-int                  enroll_boot(struct conn * conn);
+int                  enroll_boot(struct conn *   conn,
+                                 const uint8_t * id);
 
-int                  enroll_ack(struct conn * conn,
-                                int           result);
+int                  enroll_ack(struct conn *   conn,
+                                const uint8_t * id,
+                                const int       result);
 
 struct ipcp_config * enroll_get_conf(void);
 
diff --git a/src/ipcpd/unicast/main.c b/src/ipcpd/unicast/main.c
index 8092449b..994b1fd3 100644
--- a/src/ipcpd/unicast/main.c
+++ b/src/ipcpd/unicast/main.c
@@ -32,10 +32,10 @@
 #define THIS_TYPE IPCP_UNICAST
 
 #include <ouroboros/errno.h>
-#include <ouroboros/hash.h>
 #include <ouroboros/ipcp-dev.h>
 #include <ouroboros/logs.h>
 #include <ouroboros/notifier.h>
+#include <ouroboros/random.h>
 #include <ouroboros/rib.h>
 #include <ouroboros/time_utils.h>
 
@@ -133,22 +133,22 @@ static int start_components(void)
 
         ipcp_set_state(IPCP_OPERATIONAL);
 
-        if (dt_start()) {
+        if (dt_start() < 0) {
                 log_err("Failed to start data transfer.");
                 goto fail_dt_start;
         }
 
-        if (fa_start()) {
+        if (fa_start() < 0) {
                 log_err("Failed to start flow allocator.");
                 goto fail_fa_start;
         }
 
-        if (enroll_start()) {
+        if (enroll_start() < 0) {
                 log_err("Failed to start enrollment.");
                 goto fail_enroll_start;
         }
 
-        if (connmgr_start()) {
+        if (connmgr_start() < 0) {
                 log_err("Failed to start AP connection manager.");
                 goto fail_connmgr_start;
         }
@@ -196,35 +196,43 @@ static int unicast_ipcp_enroll(const char *        dst,
                                struct layer_info * info)
 {
         struct conn conn;
+        uint8_t     id[ENROLL_ID_LEN];
 
-        if (connmgr_alloc(COMPID_ENROLL, dst, NULL, &conn)) {
-                log_err("Failed to get connection.");
-                goto fail_er_flow;
+        if (random_buffer(id, ENROLL_ID_LEN) < 0) {
+                log_err("Failed to generate enrollment ID.");
+                goto fail_id;
+        }
+
+        log_info_id(id, "Requesting enrollment.");
+
+        if (connmgr_alloc(COMPID_ENROLL, dst, NULL, &conn) < 0) {
+                log_err_id(id, "Failed to get connection.");
+                goto fail_id;
         }
 
         /* Get boot state from peer. */
-        if (enroll_boot(&conn)) {
-                log_err("Failed to get boot information.");
+        if (enroll_boot(&conn, id) < 0) {
+                log_err_id(id, "Failed to get boot information.");
                 goto fail_enroll_boot;
         }
 
-        if (initialize_components(enroll_get_conf())) {
-                log_err("Failed to initialize IPCP components.");
+        if (initialize_components(enroll_get_conf()) < 0) {
+                log_err_id(id, "Failed to initialize components.");
                 goto fail_enroll_boot;
         }
 
-        if (start_components()) {
-                log_err("Failed to start components.");
+        if (start_components() < 0) {
+                log_err_id(id, "Failed to start components.");
                 goto fail_start_comp;
         }
 
-        if (enroll_ack(&conn, 0))
-                log_warn("Failed to confirm enrollment with peer.");
+        if (enroll_ack(&conn, id, 0) < 0)
+                log_err_id(id, "Failed to confirm enrollment.");
 
-        if (connmgr_dealloc(COMPID_ENROLL, &conn))
-                log_warn("Failed to deallocate enrollment flow.");
+        if (connmgr_dealloc(COMPID_ENROLL, &conn) < 0)
+                log_warn_id(id, "Failed to dealloc enrollment flow.");
 
-        log_info("Enrolled with %s.", dst);
+        log_info_id(id, "Enrolled with %s.", dst);
 
         info->dir_hash_algo = ipcpi.dir_hash_algo;
         strcpy(info->layer_name, ipcpi.layer_name);
@@ -235,7 +243,7 @@ static int unicast_ipcp_enroll(const char *        dst,
         finalize_components();
  fail_enroll_boot:
         connmgr_dealloc(COMPID_ENROLL, &conn);
- fail_er_flow:
+ fail_id:
         return -1;
 }
 
@@ -246,17 +254,17 @@ static int unicast_ipcp_bootstrap(const struct ipcp_config * conf)
 
         enroll_bootstrap(conf);
 
-        if (initialize_components(conf)) {
+        if (initialize_components(conf) < 0) {
                 log_err("Failed to init IPCP components.");
                 goto fail_init;
         }
 
-        if (start_components()) {
+        if (start_components() < 0) {
                 log_err("Failed to init IPCP components.");
                 goto fail_start;
         }
 
-        if (bootstrap_components()) {
+        if (bootstrap_components() < 0) {
                 log_err("Failed to bootstrap IPCP components.");
                 goto fail_bootstrap;
         }
@@ -300,17 +308,17 @@ int main(int    argc,
                 goto fail_init;
         }
 
-        if (notifier_init()) {
+        if (notifier_init() < 0) {
                 log_err("Failed to initialize notifier component.");
                 goto fail_notifier_init;
         }
 
-        if (connmgr_init()) {
+        if (connmgr_init() < 0) {
                 log_err("Failed to initialize connection manager.");
                 goto fail_connmgr_init;
         }
 
-        if (enroll_init()) {
+        if (enroll_init() < 0) {
                 log_err("Failed to initialize enrollment component.");
                 goto fail_enroll_init;
         }