ipcpd: Revise logging

This revises the logging in the IPCPs to be a more consistent and
reduce duplicate messages in nested functions.

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

4 files changed, 41 insertions, 20 deletions

diff --git a/src/ipcpd/unicast/dt.c b/src/ipcpd/unicast/dt.c
index 60975aed..f62b0d5b 100644
--- a/src/ipcpd/unicast/dt.c
+++ b/src/ipcpd/unicast/dt.c
@@ -399,26 +399,28 @@ static void handle_event(void *       self,
                          const void * o)
 {
         struct conn * c;
+        int           fd;
 
         (void) self;
 
         c = (struct conn *) o;
 
+        fd = c->flow_info.fd;
+
         switch (event) {
         case NOTIFY_DT_CONN_ADD:
 #ifdef IPCP_FLOW_STATS
-                stat_used(c->flow_info.fd, c->conn_info.addr);
+                stat_used(fd, c->conn_info.addr);
 #endif
-                psched_add(dt.psched, c->flow_info.fd);
-                log_dbg("Added fd %d to packet scheduler.", c->flow_info.fd);
+                psched_add(dt.psched, fd);
+                log_dbg("Added fd %d to packet scheduler.", fd);
                 break;
         case NOTIFY_DT_CONN_DEL:
 #ifdef IPCP_FLOW_STATS
-                stat_used(c->flow_info.fd, INVALID_ADDR);
+                stat_used(fd, INVALID_ADDR);
 #endif
-                psched_del(dt.psched, c->flow_info.fd);
-                log_dbg("Removed fd %d from "
-                        "packet scheduler.", c->flow_info.fd);
+                psched_del(dt.psched, fd);
+                log_dbg("Removed fd %d from packet scheduler.", fd);
                 break;
         default:
                 break;
@@ -642,6 +644,7 @@ int dt_init(struct dt_config cfg)
 
         for (i = 0; i < PROG_MAX_FLOWS; ++i)
                 if (pthread_mutex_init(&dt.stat[i].lock, NULL)) {
+                        log_err("Failed to init mutex for flow %d.", i);
                         for (j = 0; j < i; ++j)
                                 pthread_mutex_destroy(&dt.stat[j].lock);
                         goto fail_stat_lock;
@@ -650,8 +653,10 @@ int dt_init(struct dt_config cfg)
         dt.n_flows = 0;
 #endif
         sprintf(dtstr, "%s.%" PRIu64, DT, ipcpi.dt_addr);
-        if (rib_reg(dtstr, &r_ops))
+        if (rib_reg(dtstr, &r_ops)) {
+                log_err("Failed to register RIB.");
                 goto fail_rib_reg;
+        }
 
         return 0;
 
@@ -744,7 +749,7 @@ int dt_reg_comp(void * comp,
 
         eid = bmp_allocate(dt.res_fds);
         if (!bmp_is_id_valid(dt.res_fds, eid)) {
-                log_warn("Reserved EIDs depleted.");
+                log_err("Cannot allocate EID.");
                 pthread_rwlock_unlock(&dt.lock);
                 return -EBADF;
         }
diff --git a/src/ipcpd/unicast/fa.c b/src/ipcpd/unicast/fa.c
index c1560de0..f5fcdf87 100644
--- a/src/ipcpd/unicast/fa.c
+++ b/src/ipcpd/unicast/fa.c
@@ -359,7 +359,7 @@ static void packet_handler(int                  fd,
 
         if (dt_write_packet(r_addr, qc, r_eid, sdb)) {
                 ipcp_sdb_release(sdb);
-                log_warn("Failed to forward packet.");
+                log_dbg("Failed to forward packet.");
 #ifdef IPCP_FLOW_STATS
                 pthread_rwlock_wrlock(&fa.flows_lock);
                 ++flow->p_snd_f;
@@ -456,7 +456,7 @@ static size_t fa_wait_for_fa_msg(struct fa_msg * msg)
 
         len = shm_du_buff_len(cmd->sdb);
         if (len > MSGBUFSZ || len < sizeof(*msg)) {
-                log_warn("Invalid flow allocation message (len: %zd)\n", len);
+                log_warn("Invalid flow allocation message (len: %zd).", len);
                 free(cmd);
                 return 0; /* No valid message */
         }
@@ -539,6 +539,8 @@ static int fa_handle_flow_reply(struct fa_msg * msg,
         fd = eid_to_fd(ntoh64(msg->r_eid));
         if (fd < 0) {
                 pthread_rwlock_unlock(&fa.flows_lock);
+                log_err("Flow reply for unknown EID %" PRIu64 ".",
+                        ntoh64(msg->r_eid));
                 return -ENOTALLOC;
         }
 
@@ -553,8 +555,10 @@ static int fa_handle_flow_reply(struct fa_msg * msg,
 
         pthread_rwlock_unlock(&fa.flows_lock);
 
-        if (ipcp_flow_alloc_reply(fd, msg->response, mpl, data, dlen))
+        if (ipcp_flow_alloc_reply(fd, msg->response, mpl, data, dlen) < 0) {
+                log_err("Failed to reply for flow allocation on fd %d.", fd);
                 return -EIRMD;
+        }
 
         return 0;
 }
@@ -573,6 +577,8 @@ static int fa_handle_flow_update(struct fa_msg * msg,
         fd = eid_to_fd(ntoh64(msg->r_eid));
         if (fd < 0) {
                 pthread_rwlock_unlock(&fa.flows_lock);
+                log_err("Flow update for unknown EID %" PRIu64 ".",
+                        ntoh64(msg->r_eid));
                 return -EPERM;
         }
 
@@ -665,7 +671,7 @@ int fa_init(void)
  fail_mtx:
         pthread_rwlock_destroy(&fa.flows_lock);
  fail_rwlock:
-        log_err("Failed to initialize flow allocator.");
+
         return -1;
 }
 
@@ -721,7 +727,6 @@ int fa_start(void)
  fail_thread:
         psched_destroy(fa.psched);
  fail_psched:
-        log_err("Failed to start flow allocator.");
         return -1;
 }
 
@@ -779,6 +784,7 @@ int fa_alloc(int             fd,
                 memcpy(shm_du_buff_head(sdb) + len, data, dlen);
 
         if (dt_write_packet(addr, qc, fa.eid, sdb)) {
+                log_err("Failed to send flow allocation request packet.");
                 ipcp_sdb_release(sdb);
                 return -1;
         }
@@ -808,10 +814,14 @@ int fa_alloc_resp(int          fd,
 
         flow = &fa.flows[fd];
 
-        if (ipcp_wait_flow_resp(fd) < 0)
+        if (ipcp_wait_flow_resp(fd) < 0) {
+                log_err("Failed to wait for flow response.");
                 goto fail_alloc_resp;
+        }
 
         if (ipcp_sdb_reserve(&sdb, sizeof(*msg) + len)) {
+                log_err("Failed to reserve sdb (%zu  bytes).",
+                        sizeof(*msg) + len);
                 goto fail_reserve;
         }
 
@@ -830,8 +840,10 @@ int fa_alloc_resp(int          fd,
 
         pthread_rwlock_unlock(&fa.flows_lock);
 
-        if (dt_write_packet(flow->r_addr, qc, fa.eid, sdb))
+        if (dt_write_packet(flow->r_addr, qc, fa.eid, sdb)) {
+                log_err("Failed to send flow allocation response packet.");
                 goto fail_packet;
+        }
 
         if (response < 0) {
                 pthread_rwlock_rdlock(&fa.flows_lock);
@@ -881,6 +893,7 @@ static int fa_update_remote(int      fd,
         uint64_t             r_addr;
 
         if (ipcp_sdb_reserve(&sdb, sizeof(*msg))) {
+                log_err("Failed to reserve sdb (%zu  bytes).", sizeof(*msg));
                 return -1;
         }
 
@@ -904,6 +917,7 @@ static int fa_update_remote(int      fd,
 
 
         if (dt_write_packet(r_addr, qc, fa.eid, sdb)) {
+                log_err("Failed to send flow update packet.");
                 ipcp_sdb_release(sdb);
                 return -1;
         }
@@ -928,6 +942,7 @@ void  fa_np1_rcv(uint64_t             eid,
         fd = eid_to_fd(eid);
         if (fd < 0) {
                 pthread_rwlock_unlock(&fa.flows_lock);
+                log_dbg("Received packet for unknown EID %" PRIu64 ".", eid);
                 ipcp_sdb_release(sdb);
                 return;
         }
@@ -943,6 +958,7 @@ void  fa_np1_rcv(uint64_t             eid,
         pthread_rwlock_unlock(&fa.flows_lock);
 
         if (ipcp_flow_write(fd, sdb) < 0) {
+                log_dbg("Failed to write to flow %d.", fd);
                 ipcp_sdb_release(sdb);
 #ifdef IPCP_FLOW_STATS
                 pthread_rwlock_wrlock(&fa.flows_lock);
diff --git a/src/ipcpd/unicast/main.c b/src/ipcpd/unicast/main.c
index e1c3d5d0..83504168 100644
--- a/src/ipcpd/unicast/main.c
+++ b/src/ipcpd/unicast/main.c
@@ -76,7 +76,7 @@ static int initialize_components(const struct ipcp_config * conf)
                 goto fail_addr_auth;
         }
 
-        log_dbg("IPCP got address %" PRIu64 ".", ipcpi.dt_addr);
+        log_info("IPCP got address %" PRIu64 ".", ipcpi.dt_addr);
 
         if (ca_init(conf->unicast.cong_avoid)) {
                 log_err("Failed to initialize congestion avoidance.");
@@ -262,8 +262,6 @@ static int unicast_ipcp_bootstrap(const struct ipcp_config * conf)
                 goto fail_bootstrap;
         }
 
-        log_dbg("Bootstrapped in layer %s.", conf->layer_info.layer_name);
-
         return 0;
 
  fail_bootstrap:
diff --git a/src/ipcpd/unicast/pff.c b/src/ipcpd/unicast/pff.c
index 14c84449..0af17421 100644
--- a/src/ipcpd/unicast/pff.c
+++ b/src/ipcpd/unicast/pff.c
@@ -59,8 +59,10 @@ struct pff * pff_create(enum pol_pff pol)
         }
 
         pff->pff_i = pff->ops->create();
-        if (pff->pff_i == NULL)
+        if (pff->pff_i == NULL) {
+                log_err("Failed to create PFF instance.");
                 goto err;
+        }
 
         return pff;
  err: