From de2b10441c7835d4221dea3b4414478f72c549f6 Mon Sep 17 00:00:00 2001 From: Dimitri Staessens Date: Wed, 30 Aug 2023 16:07:03 +0200 Subject: 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 Signed-off-by: Sander Vrijders --- src/ipcpd/broadcast/dt.c | 21 +++-- src/ipcpd/broadcast/main.c | 9 +- src/ipcpd/common/connmgr.c | 127 ++++++++++++++++----------- src/ipcpd/common/enroll.c | 4 +- src/ipcpd/eth/eth.c | 78 ++++++++--------- src/ipcpd/ipcp.c | 214 +++++++++++++++++++++++++++------------------ src/ipcpd/local/main.c | 11 +-- src/ipcpd/shim-data.c | 4 +- src/ipcpd/udp/main.c | 60 +++++++------ src/ipcpd/unicast/dt.c | 23 +++-- src/ipcpd/unicast/fa.c | 30 +++++-- src/ipcpd/unicast/main.c | 4 +- src/ipcpd/unicast/pff.c | 4 +- 13 files changed, 344 insertions(+), 245 deletions(-) diff --git a/src/ipcpd/broadcast/dt.c b/src/ipcpd/broadcast/dt.c index db184e89..935ac384 100644 --- a/src/ipcpd/broadcast/dt.c +++ b/src/ipcpd/broadcast/dt.c @@ -78,15 +78,16 @@ static int dt_add_nb(int fd) list_for_each(p, &fwd.nbs) { struct nb * el = list_entry(p, struct nb, next); if (el->fd == fd) { - log_dbg("Already know neighbor."); pthread_rwlock_unlock(&fwd.nbs_lock); - return -EPERM; + log_warn("Already know neighbor on fd %d.", fd); + return 0; } } nb = malloc(sizeof(*nb)); if (nb == NULL) { pthread_rwlock_unlock(&fwd.nbs_lock); + log_err("Failed to malloc neighbor struct."); return -ENOMEM; } @@ -96,10 +97,10 @@ static int dt_add_nb(int fd) ++fwd.nbs_len; - log_dbg("Neighbor %d added.", fd); - pthread_rwlock_unlock(&fwd.nbs_lock); + log_dbg("Neighbor %d added.", fd); + return 0; } @@ -124,6 +125,8 @@ static int dt_del_nb(int fd) pthread_rwlock_unlock(&fwd.nbs_lock); + log_err("Neighbor not found on fd %d.", fd); + return -EPERM; } @@ -191,7 +194,7 @@ static void * dt_reader(void * o) while (true) { ret = fevent(fwd.set, fq, NULL); if (ret < 0) { - log_warn("Event error: %d.", ret); + log_warn("Event warning: %d.", ret); continue; } @@ -226,13 +229,13 @@ static void handle_event(void * self, switch (event) { case NOTIFY_DT_CONN_ADD: - if (dt_add_nb(c->flow_info.fd)) - log_dbg("Failed to add neighbor."); + if (dt_add_nb(c->flow_info.fd) < 0) + log_err("Failed to add neighbor."); fset_add(fwd.set, c->flow_info.fd); break; case NOTIFY_DT_CONN_DEL: - if (dt_del_nb(c->flow_info.fd)) - log_dbg("Failed to delete neighbor."); + if (dt_del_nb(c->flow_info.fd) < 0) + log_err("Failed to delete neighbor."); fset_del(fwd.set, c->flow_info.fd); break; default: diff --git a/src/ipcpd/broadcast/main.c b/src/ipcpd/broadcast/main.c index b0cbc6a7..de1feeb2 100644 --- a/src/ipcpd/broadcast/main.c +++ b/src/ipcpd/broadcast/main.c @@ -146,7 +146,6 @@ static int broadcast_ipcp_enroll(const char * dst, log_info_id(id, "Enrolled with %s.", dst); - info->dir_hash_algo = ipcpi.dir_hash_algo; strcpy(info->layer_name, ipcpi.layer_name); @@ -178,8 +177,6 @@ static int broadcast_ipcp_bootstrap(const struct ipcp_config * conf) goto fail_start; } - log_dbg("Bootstrapped in layer %s.", conf->layer_info.layer_name); - return 0; fail_start: @@ -221,8 +218,10 @@ static int broadcast_ipcp_join(int fd, conn.flow_info.fd = fd; - if (name_check(dst) != 0) + if (name_check(dst) != 0) { + log_err("Failed to check name."); return -1; + } notifier_event(NOTIFY_DT_CONN_ADD, &conn); @@ -264,7 +263,7 @@ int main(int argc, char * argv[]) { if (ipcp_init(argc, argv, &broadcast_ops, THIS_TYPE) < 0) { - log_err("Failed to init IPCP."); + log_err("Failed to initialize IPCP."); goto fail_init; } diff --git a/src/ipcpd/common/connmgr.c b/src/ipcpd/common/connmgr.c index 6ee41384..408d7de6 100644 --- a/src/ipcpd/common/connmgr.c +++ b/src/ipcpd/common/connmgr.c @@ -143,38 +143,43 @@ static void * flow_acceptor(void * o) fd = flow_accept(&qs, NULL); if (fd < 0) { if (fd != -EIRMD) - log_warn("Flow accept failed: %d", fd); + log_err("Flow accept failed: %d", fd); continue; } + log_info("Handling incoming flow %d",fd); + if (cacep_rcv(fd, &rcv_info)) { - log_dbg("Error establishing application connection."); + log_err("Error receiving CACEP info."); flow_dealloc(fd); continue; } + log_info("Request to connect to %s.", rcv_info.comp_name); + id = get_id_by_name(rcv_info.comp_name); if (id < 0) { - log_dbg("Connection request for unknown component %s.", + log_err("Connection request for unknown component %s.", rcv_info.comp_name); cacep_snd(fd, &fail_info); flow_dealloc(fd); continue; } - assert(id < COMPID_MAX); - if (cacep_snd(fd, &connmgr.comps[id].info)) { - log_dbg("Failed to respond to request."); + log_err("Failed to respond to CACEP request."); flow_dealloc(fd); continue; } if (add_comp_conn(id, fd, qs, &rcv_info)) { - log_dbg("Failed to add new connection."); + log_err("Failed to add new connection."); flow_dealloc(fd); continue; } + + log_info("Finished handling incoming flow %d for %s: 0.", + fd, rcv_info.comp_name); } return (void *) 0; @@ -215,8 +220,10 @@ int connmgr_init(void) { connmgr.state = CONNMGR_INIT; - if (notifier_reg(handle_event, NULL)) + if (notifier_reg(handle_event, NULL)) { + log_err("Failed to register notifier."); return -1; + } return 0; } @@ -236,8 +243,10 @@ void connmgr_fini(void) int connmgr_start(void) { - if (pthread_create(&connmgr.acceptor, NULL, flow_acceptor, NULL)) + if (pthread_create(&connmgr.acceptor, NULL, flow_acceptor, NULL)) { + log_err("Failed to create pthread: %s.", strerror(errno)); return -1; + } connmgr.state = CONNMGR_RUNNING; @@ -259,12 +268,14 @@ int connmgr_comp_init(enum comp_id id, comp = connmgr.comps + id; - if (pthread_mutex_init(&comp->lock, NULL)) - return -1; + if (pthread_mutex_init(&comp->lock, NULL)) { + log_err("Failed to initialize mutex: %s.", strerror(errno)); + goto fail_mutex; + } if (pthread_cond_init(&comp->cond, NULL)) { - pthread_mutex_destroy(&comp->lock); - return -1; + log_err("Failed to initialize condvar: %s.", strerror(errno)); + goto fail_cond; } list_head_init(&comp->conns); @@ -273,6 +284,11 @@ int connmgr_comp_init(enum comp_id id, memcpy(&connmgr.comps[id].info, info, sizeof(connmgr.comps[id].info)); return 0; + + fail_cond: + pthread_mutex_destroy(&comp->lock); + fail_mutex: + return -1; } void connmgr_comp_fini(enum comp_id id) @@ -322,20 +338,19 @@ int connmgr_ipcp_connect(const char * dst, ce = malloc(sizeof(*ce)); if (ce == NULL) { - log_dbg("Out of memory."); - return -1; + log_err("Out of memory."); + goto fail_malloc; } id = get_id_by_name(component); if (id < 0) { - log_dbg("No such component: %s", component); - free(ce); - return -1; + log_err("No such component: %s", component); + goto fail_id; } if (connmgr_alloc(id, dst, &qs, &ce->conn)) { - free(ce); - return -1; + log_err("Failed to allocate flow."); + goto fail_id; } if (strlen(dst) > DST_MAX_STRLEN) { @@ -353,6 +368,11 @@ int connmgr_ipcp_connect(const char * dst, pthread_mutex_unlock(&connmgr.comps[id].lock); return 0; + + fail_id: + free(ce); + fail_malloc: + return -1; } int connmgr_ipcp_disconnect(const char * dst, @@ -366,8 +386,10 @@ int connmgr_ipcp_disconnect(const char * dst, assert(component); id = get_id_by_name(component); - if (id < 0) + if (id < 0) { + log_err("No such component: %s.", component); return -1; + } pthread_mutex_lock(&connmgr.comps[id].lock); @@ -393,54 +415,55 @@ int connmgr_alloc(enum comp_id id, qosspec_t * qs, struct conn * conn) { + struct comp * comp; + int fd; + assert(id >= 0 && id < COMPID_MAX); assert(dst); - conn->flow_info.fd = flow_alloc(dst, qs, NULL); - if (conn->flow_info.fd < 0) { - log_dbg("Failed to allocate flow to %s.", dst); - return -1; + comp = connmgr.comps + id; + + fd = flow_alloc(dst, qs, NULL); + if (fd < 0) { + log_err("Failed to allocate flow to %s.", dst); + goto fail_alloc; } + conn->flow_info.fd = fd; + if (qs != NULL) conn->flow_info.qs = *qs; else memset(&conn->flow_info.qs, 0, sizeof(conn->flow_info.qs)); log_dbg("Sending cacep info for protocol %s to fd %d.", - connmgr.comps[id].info.protocol, conn->flow_info.fd); + comp->info.protocol, conn->flow_info.fd); - if (cacep_snd(conn->flow_info.fd, &connmgr.comps[id].info)) { - log_dbg("Failed to create application connection."); - flow_dealloc(conn->flow_info.fd); - return -1; + if (cacep_snd(fd, &comp->info)) { + log_err("Failed to send CACEP info."); + goto fail_cacep; } - if (cacep_rcv(conn->flow_info.fd, &conn->conn_info)) { - log_dbg("Failed to connect to application."); - flow_dealloc(conn->flow_info.fd); - return -1; + if (cacep_rcv(fd, &conn->conn_info)) { + log_err("Failed to receive CACEP info."); + goto fail_cacep; } - if (strcmp(connmgr.comps[id].info.protocol, conn->conn_info.protocol)) { - log_dbg("Unknown protocol (requested %s, got %s).", - connmgr.comps[id].info.protocol, - conn->conn_info.protocol); - flow_dealloc(conn->flow_info.fd); - return -1; + if (strcmp(comp->info.protocol, conn->conn_info.protocol)) { + log_err("Unknown protocol (requested %s, got %s).", + comp->info.protocol, conn->conn_info.protocol); + goto fail_cacep; } - if (connmgr.comps[id].info.pref_version != - conn->conn_info.pref_version) { - log_dbg("Unknown protocol version."); - flow_dealloc(conn->flow_info.fd); - return -1; + if (comp->info.pref_version != conn->conn_info.pref_version) { + log_err("Unknown protocol version %d.", + conn->conn_info.pref_version); + goto fail_cacep; } - if (connmgr.comps[id].info.pref_syntax != conn->conn_info.pref_syntax) { - log_dbg("Unknown protocol syntax."); - flow_dealloc(conn->flow_info.fd); - return -1; + if (comp->info.pref_syntax != conn->conn_info.pref_syntax) { + log_err("Unknown protocol syntax."); + goto fail_cacep; } switch (id) { @@ -458,6 +481,11 @@ int connmgr_alloc(enum comp_id id, } return 0; + + fail_cacep: + flow_dealloc(conn->flow_info.fd); + fail_alloc: + return -1; } int connmgr_dealloc(enum comp_id id, @@ -503,6 +531,7 @@ int connmgr_wait(enum comp_id id, el = list_first_entry((&comp->pending), struct conn_el, next); if (el == NULL) { pthread_mutex_unlock(&comp->lock); + log_err("Failed to get connection element."); return -1; } diff --git a/src/ipcpd/common/enroll.c b/src/ipcpd/common/enroll.c index eeff391a..033ae23c 100644 --- a/src/ipcpd/common/enroll.c +++ b/src/ipcpd/common/enroll.c @@ -94,7 +94,7 @@ static void * enroll_handle(void * o) len = flow_read(fd, buf.data, buf.len); if (len < 0) { - log_warn("Failed to read from flow %d.", fd); + log_err("Failed to read from flow %d.", fd); goto finish_flow; } @@ -102,7 +102,7 @@ static void * enroll_handle(void * o) msg.len = (size_t) len; if (enroll_req_des(&req, msg) < 0) { - log_warn("Failed to unpack request message."); + log_err("Failed to unpack request message."); goto finish_flow; } diff --git a/src/ipcpd/eth/eth.c b/src/ipcpd/eth/eth.c index ef64c07e..3b357067 100644 --- a/src/ipcpd/eth/eth.c +++ b/src/ipcpd/eth/eth.c @@ -649,11 +649,12 @@ static int eth_ipcp_alloc_reply(uint8_t * r_addr, #elif defined(BUILD_ETH_LLC) log_dbg("Flow reply, fd %d, SSAP %d, DSAP %d.", fd, ssap, dsap); #endif - if ((ret = ipcp_flow_alloc_reply(fd, response, mpl, data, len)) < 0) + if ((ret = ipcp_flow_alloc_reply(fd, response, mpl, data, len)) < 0) { + log_err("Failed to reply to flow allocation."); return -1; + } return ret; - } static int eth_ipcp_name_query_req(const uint8_t * hash, @@ -856,7 +857,7 @@ static void * eth_ipcp_packet_reader(void * o) buf = nm_nextpkt(eth_data.nmd, &hdr); if (buf == NULL) { - log_err("Bad read from netmap device."); + log_dbg("Bad read from netmap device."); continue; } #else @@ -887,6 +888,7 @@ static void * eth_ipcp_packet_reader(void * o) ETH_MTU + ETH_HEADER_TOT_SIZE, 0); #endif if (frame_len <= 0) { + log_dbg("Failed to receive frame."); ipcp_sdb_release(sdb); continue; } @@ -939,10 +941,8 @@ static void * eth_ipcp_packet_reader(void * o) #endif frame = malloc(sizeof(*frame)); if (frame == NULL) { -#ifndef HAVE_NETMAP - ipcp_sdb_release(sdb); -#endif - continue; + log_err("Failed to allocate frame."); + goto fail_frame; } memcpy(frame->buf, &e_frame->payload, length); @@ -954,9 +954,6 @@ static void * eth_ipcp_packet_reader(void * o) pthread_cond_signal(ð_data.mgmt_cond); pthread_mutex_unlock(ð_data.mgmt_lock); -#ifndef HAVE_NETMAP - ipcp_sdb_release(sdb); -#endif } else { pthread_rwlock_rdlock(ð_data.flows_lock); @@ -967,10 +964,7 @@ static void * eth_ipcp_packet_reader(void * o) #endif if (fd < 0) { pthread_rwlock_unlock(ð_data.flows_lock); -#ifndef HAVE_NETMAP - ipcp_sdb_release(sdb); -#endif - continue; + goto fail_frame; } #ifdef BUILD_ETH_LLC @@ -978,10 +972,7 @@ static void * eth_ipcp_packet_reader(void * o) || memcmp(eth_data.fd_to_ef[fd].r_addr, e_frame->src_hwaddr, MAC_SIZE)) { pthread_rwlock_unlock(ð_data.flows_lock); -#ifndef HAVE_NETMAP - ipcp_sdb_release(sdb); -#endif - continue; + goto fail_frame; } #endif pthread_rwlock_unlock(ð_data.flows_lock); @@ -998,6 +989,12 @@ static void * eth_ipcp_packet_reader(void * o) #endif if (np1_flow_write(fd, sdb) < 0) ipcp_sdb_release(sdb); + + continue; + fail_frame: +#ifndef HAVE_NETMAP + ipcp_sdb_release(sdb); +#endif } } @@ -1455,7 +1452,8 @@ static int eth_ipcp_bootstrap(const struct ipcp_config * conf) NULL, eth_ipcp_if_monitor, NULL)) { - ipcp_set_state(IPCP_INIT); + log_err("Failed to create monitor thread: %s.", + strerror(errno)); goto fail_device; } #endif @@ -1464,7 +1462,8 @@ static int eth_ipcp_bootstrap(const struct ipcp_config * conf) NULL, eth_ipcp_mgmt_handler, NULL)) { - ipcp_set_state(IPCP_INIT); + log_err("Failed to create mgmt handler thread: %s.", + strerror(errno)); goto fail_mgmt_handler; } @@ -1473,7 +1472,8 @@ static int eth_ipcp_bootstrap(const struct ipcp_config * conf) NULL, eth_ipcp_packet_reader, NULL)) { - ipcp_set_state(IPCP_INIT); + log_err("Failed to create packet reader thread: %s", + strerror(errno)); goto fail_packet_reader; } } @@ -1483,7 +1483,8 @@ static int eth_ipcp_bootstrap(const struct ipcp_config * conf) NULL, eth_ipcp_packet_writer, NULL)) { - ipcp_set_state(IPCP_INIT); + log_err("Failed to create packet writer thread: %s", + strerror(errno)); goto fail_packet_writer; } } @@ -1537,8 +1538,6 @@ static int eth_ipcp_reg(const uint8_t * hash) return -1; } - log_dbg("Registered " HASH_FMT32 ".", HASH_VAL32(hash)); - return 0; } @@ -1617,12 +1616,11 @@ static int eth_ipcp_flow_alloc(int fd, uint8_t r_addr[MAC_SIZE]; uint64_t addr = 0; - log_dbg("Allocating flow to " HASH_FMT32 ".", HASH_VAL32(hash)); - assert(hash); if (!shim_data_dir_has(eth_data.shim_data, hash)) { - log_err("Destination unreachable."); + log_err("Destination "HASH_FMT32 "unreachable.", + HASH_VAL32(hash)); return -1; } addr = shim_data_dir_get_addr(eth_data.shim_data, hash); @@ -1632,6 +1630,7 @@ static int eth_ipcp_flow_alloc(int fd, ssap = bmp_allocate(eth_data.saps); if (!bmp_is_id_valid(eth_data.saps, ssap)) { pthread_rwlock_unlock(ð_data.flows_lock); + log_err("Failed to allocate SSAP."); return -1; } @@ -1658,15 +1657,14 @@ static int eth_ipcp_flow_alloc(int fd, eth_data.fd_to_ef[fd].sap = -1; eth_data.ef_to_fd[ssap] = -1; pthread_rwlock_unlock(ð_data.flows_lock); + log_err("Failed to allocate with peer."); #endif return -1; } fset_add(eth_data.np1_flows, fd); -#if defined(BUILD_ETH_DIX) - log_dbg("Pending flow with fd %d.", fd); -#elif defined(BUILD_ETH_LLC) - log_dbg("Pending flow with fd %d on SAP %d.", fd, ssap); +#if defined(BUILD_ETH_LLC) + log_dbg("Assigned SAP %d for fd %d.", ssap, fd); #endif return 0; } @@ -1684,8 +1682,10 @@ static int eth_ipcp_flow_alloc_resp(int fd, #endif uint8_t r_addr[MAC_SIZE]; - if (ipcp_wait_flow_resp(fd) < 0) + if (ipcp_wait_flow_resp(fd) < 0) { + log_err("Failed to wait for flow response."); return -1; + } pthread_rwlock_wrlock(ð_data.flows_lock); #if defined(BUILD_ETH_DIX) @@ -1694,6 +1694,7 @@ static int eth_ipcp_flow_alloc_resp(int fd, ssap = bmp_allocate(eth_data.saps); if (!bmp_is_id_valid(eth_data.saps, ssap)) { pthread_rwlock_unlock(ð_data.flows_lock); + log_err("Failed to allocate SSAP."); return -1; } @@ -1719,14 +1720,13 @@ static int eth_ipcp_flow_alloc_resp(int fd, bmp_release(eth_data.saps, eth_data.fd_to_ef[fd].sap); pthread_rwlock_unlock(ð_data.flows_lock); #endif + log_err("Failed to respond to peer."); return -1; } fset_add(eth_data.np1_flows, fd); -#if defined(BUILD_ETH_DIX) - log_dbg("Accepted flow, fd %d.", fd); -#elif defined(BUILD_ETH_LLC) - log_dbg("Accepted flow, fd %d, SAP %d.", fd, (uint8_t)ssap); +#if defined(BUILD_ETH_LLC) + log_dbg("Assigned SAP %d for fd %d.", ssap, fd); #endif return 0; } @@ -1757,8 +1757,6 @@ static int eth_ipcp_flow_dealloc(int fd) flow_dealloc(fd); - log_dbg("Flow with fd %d deallocated.", fd); - return 0; } @@ -1790,8 +1788,10 @@ int main(int argc, goto fail_data_init; } - if (ipcp_init(argc, argv, ð_ops, THIS_TYPE) < 0) + if (ipcp_init(argc, argv, ð_ops, THIS_TYPE) < 0) { + log_err("Failed to initialize IPCP."); goto fail_init; + } if (ipcp_start() < 0) { log_err("Failed to start IPCP."); diff --git a/src/ipcpd/ipcp.c b/src/ipcpd/ipcp.c index eb83f3cc..5c1ffd03 100644 --- a/src/ipcpd/ipcp.c +++ b/src/ipcpd/ipcp.c @@ -339,23 +339,23 @@ static void free_msg(void * o) } -static void handle_bootstrap(ipcp_config_msg_t * conf_msg, - ipcp_msg_t * ret_msg) +static void do_bootstrap(ipcp_config_msg_t * conf_msg, + ipcp_msg_t * ret_msg) { struct ipcp_config conf; - assert(ipcp_get_state() == IPCP_INIT); + log_info("Bootstrapping..."); if (ipcpi.ops->ipcp_bootstrap == NULL) { log_err("Bootstrap unsupported."); ret_msg->result = -ENOTSUP; - return; + goto finish; } if (ipcp_get_state() != IPCP_INIT) { log_err("IPCP in wrong state."); ret_msg->result = -EIPCPSTATE; - return; + goto finish; } conf = ipcp_config_msg_to_s(conf_msg); @@ -364,25 +364,27 @@ static void handle_bootstrap(ipcp_config_msg_t * conf_msg, ret_msg->layer_info = layer_info_s_to_msg(&conf.layer_info); ipcp_set_state(IPCP_OPERATIONAL); } + finish: + log_info("Finished bootstrapping: %d.", ret_msg->result); } -static void handle_enroll(const char * dst, - ipcp_msg_t * ret_msg) +static void do_enroll(const char * dst, + ipcp_msg_t * ret_msg) { struct layer_info info; - assert(ipcp_get_state() == IPCP_INIT); + log_info("Enrolling with %s...", dst); if (ipcpi.ops->ipcp_enroll == NULL) { log_err("Enroll unsupported."); ret_msg->result = -ENOTSUP; - return; + goto finish; } if (ipcp_get_state() != IPCP_INIT) { log_err("IPCP in wrong state."); ret_msg->result = -EIPCPSTATE; - return; + goto finish; } ret_msg->result = ipcpi.ops->ipcp_enroll(dst, &info); @@ -390,63 +392,87 @@ static void handle_enroll(const char * dst, ret_msg->layer_info = layer_info_s_to_msg(&info); ipcp_set_state(IPCP_OPERATIONAL); } + finish: + log_info("Finished enrolling with %s: %d.", dst, ret_msg->result); } -static void handle_connect(const char * dst, - const char * comp, - qosspec_t qs, - ipcp_msg_t * ret_msg) +static void do_connect(const char * dst, + const char * comp, + qosspec_t qs, + ipcp_msg_t * ret_msg) { + log_info("Connecting %s to %s...", comp, dst); + if (ipcpi.ops->ipcp_connect == NULL) { log_err("Connect unsupported."); ret_msg->result = -ENOTSUP; - return; + goto finish; } ret_msg->result = ipcpi.ops->ipcp_connect(dst, comp, qs); + finish: + log_info("Finished connecting: %d.", ret_msg->result); } -static void handle_disconnect(const char * dst, - const char * comp, - ipcp_msg_t * ret_msg) +static void do_disconnect(const char * dst, + const char * comp, + ipcp_msg_t * ret_msg) { + log_info("Disconnecting %s from %s...", comp, dst); + if (ipcpi.ops->ipcp_disconnect == NULL) { log_err("Disconnect unsupported."); ret_msg->result = -ENOTSUP; - return; + goto finish; } ret_msg->result = ipcpi.ops->ipcp_disconnect(dst, comp); + + finish: + log_info("Finished disconnecting %s from %s: %d.", + comp, dst, ret_msg->result); } -static void handle_reg(const uint8_t * hash, - ipcp_msg_t * ret_msg) +static void do_reg(const uint8_t * hash, + ipcp_msg_t * ret_msg) { + log_info("Registering " HASH_FMT32 "...", HASH_VAL32(hash)); + if (ipcpi.ops->ipcp_reg == NULL) { log_err("Registration unsupported."); ret_msg->result = -ENOTSUP; - return; + goto finish; } ret_msg->result = ipcpi.ops->ipcp_reg(hash); + finish: + log_info("Finished registering " HASH_FMT32 " : %d.", + HASH_VAL32(hash), ret_msg->result); } -static void handle_unreg(const uint8_t * hash, - ipcp_msg_t * ret_msg) +static void do_unreg(const uint8_t * hash, + ipcp_msg_t * ret_msg) { + log_info("Unregistering " HASH_FMT32 "...", HASH_VAL32(hash)); + if (ipcpi.ops->ipcp_unreg == NULL) { log_err("Unregistration unsupported."); ret_msg->result = -ENOTSUP; - return; + goto finish; } ret_msg->result = ipcpi.ops->ipcp_unreg(hash); + finish: + log_info("Finished unregistering " HASH_FMT32 ": %d.", + HASH_VAL32(hash), ret_msg->result); } -static void handle_query(const uint8_t * hash, - ipcp_msg_t * ret_msg) +static void do_query(const uint8_t * hash, + ipcp_msg_t * ret_msg) { + /* TODO: Log this operation when IRMd has internal caches. */ + if (ipcpi.ops->ipcp_query == NULL) { log_err("Directory query unsupported."); ret_msg->result = -ENOTSUP; @@ -462,87 +488,99 @@ static void handle_query(const uint8_t * hash, ret_msg->result = ipcpi.ops->ipcp_query(hash); } -static void handle_flow_alloc(pid_t pid, - int flow_id, - uint8_t * dst, - qosspec_t qs, - void * data, - size_t len, - ipcp_msg_t * ret_msg) +static void do_flow_alloc(pid_t pid, + int flow_id, + uint8_t * dst, + qosspec_t qs, + void * data, + size_t len, + ipcp_msg_t * ret_msg) { int fd; + log_info("Allocating flow %d to " HASH_FMT32 ".", + flow_id, HASH_VAL32(dst)); + if (ipcpi.ops->ipcp_flow_alloc == NULL) { log_err("Flow allocation unsupported."); ret_msg->result = -ENOTSUP; - return; + goto finish; } if (ipcp_get_state() != IPCP_OPERATIONAL) { log_err("IPCP in wrong state."); ret_msg->result = -EIPCPSTATE; - return; + goto finish; } fd = np1_flow_alloc(pid, flow_id); if (fd < 0) { - log_err("Failed allocating fd on flow_id %d.", flow_id); + log_err("Failed allocating n + 1 fd on flow_id %d.", flow_id); ret_msg->result = -EFLOWDOWN; - return; + goto finish; } ret_msg->result = ipcpi.ops->ipcp_flow_alloc(fd, dst, qs, data, len); + finish: + log_info("Finished allocating flow %d to " HASH_FMT32 ": %d.", + flow_id, HASH_VAL32(dst), ret_msg->result); } -static void handle_flow_join(pid_t pid, - int flow_id, - const uint8_t * dst, - qosspec_t qs, - ipcp_msg_t * ret_msg) +static void do_flow_join(pid_t pid, + int flow_id, + const uint8_t * dst, + qosspec_t qs, + ipcp_msg_t * ret_msg) { int fd; + log_info("Joining layer " HASH_FMT32 ".", HASH_VAL32(dst)); + if (ipcpi.ops->ipcp_flow_join == NULL) { log_err("Broadcast unsupported."); ret_msg->result = -ENOTSUP; - return; + goto finish; } if (ipcp_get_state() != IPCP_OPERATIONAL) { log_err("IPCP in wrong state."); ret_msg->result = -EIPCPSTATE; - return; + goto finish; } fd = np1_flow_alloc(pid, flow_id); if (fd < 0) { - log_err("Failed allocating fd on flow_id %d.", flow_id); + log_err("Failed allocating n + 1 fd on flow_id %d.", flow_id); ret_msg->result = -1; - return; + goto finish; } ret_msg->result = ipcpi.ops->ipcp_flow_join(fd, dst, qs); + finish: + log_info("Finished joining layer " HASH_FMT32 ".", HASH_VAL32(dst)); } -static void handle_flow_alloc_resp(int resp, - int flow_id, - const void * data, - size_t len, - ipcp_msg_t * ret_msg) +static void do_flow_alloc_resp(int resp, + int flow_id, + const void * data, + size_t len, + ipcp_msg_t * ret_msg) { int fd = -1; + log_info("Responding %d to alloc on flow_id %d.", resp, flow_id); + if (ipcpi.ops->ipcp_flow_alloc_resp == NULL) { log_err("Flow_alloc_resp unsupported."); ret_msg->result = -ENOTSUP; - return; + goto finish; } if (ipcp_get_state() != IPCP_OPERATIONAL) { log_err("IPCP in wrong state."); ret_msg->result = -EIPCPSTATE; - return; + goto finish; } if (resp == 0) { @@ -550,39 +588,47 @@ static void handle_flow_alloc_resp(int resp, if (fd < 0) { log_warn("Flow_id %d is not known.", flow_id); ret_msg->result = -1; - return; + goto finish; } } ret_msg->result = ipcpi.ops->ipcp_flow_alloc_resp(fd, resp, data, len); + finish: + log_info("Finished responding to allocation request: %d", + ret_msg->result); } -static void handle_flow_dealloc(int flow_id, - int timeo_sec, - ipcp_msg_t * ret_msg) +static void do_flow_dealloc(int flow_id, + int timeo_sec, + ipcp_msg_t * ret_msg) { int fd; + log_info("Deallocating flow %d.", flow_id); + if (ipcpi.ops->ipcp_flow_dealloc == NULL) { log_err("Flow deallocation unsupported."); ret_msg->result = -ENOTSUP; - return; + goto finish; } if (ipcp_get_state() != IPCP_OPERATIONAL) { log_err("IPCP in wrong state."); ret_msg->result = -EIPCPSTATE; - return; + goto finish; } fd = np1_flow_dealloc(flow_id, timeo_sec); if (fd < 0) { log_warn("Could not deallocate flow_id %d.", flow_id); ret_msg->result = -1; - return; + goto finish; } ret_msg->result = ipcpi.ops->ipcp_flow_dealloc(fd); + finish: + log_info("Finished deallocating flow %d: %d.", + flow_id, ret_msg->result); } @@ -632,60 +678,59 @@ static void * mainloop(void * o) switch (msg->code) { case IPCP_MSG_CODE__IPCP_BOOTSTRAP: - handle_bootstrap(msg->conf, &ret_msg); + do_bootstrap(msg->conf, &ret_msg); break; case IPCP_MSG_CODE__IPCP_ENROLL: - handle_enroll(msg->dst, &ret_msg); + do_enroll(msg->dst, &ret_msg); break; case IPCP_MSG_CODE__IPCP_CONNECT: qs = qos_spec_msg_to_s(msg->qosspec); - handle_connect(msg->dst, msg->comp, qs, &ret_msg); + do_connect(msg->dst, msg->comp, qs, &ret_msg); break; case IPCP_MSG_CODE__IPCP_DISCONNECT: - handle_disconnect(msg->dst, msg->comp, &ret_msg); + do_disconnect(msg->dst, msg->comp, &ret_msg); break; case IPCP_MSG_CODE__IPCP_REG: assert(msg->hash.len == ipcp_dir_hash_len()); - handle_reg(msg->hash.data, &ret_msg); + do_reg(msg->hash.data, &ret_msg); break; case IPCP_MSG_CODE__IPCP_UNREG: assert(msg->hash.len == ipcp_dir_hash_len()); - handle_unreg(msg->hash.data, &ret_msg); + do_unreg(msg->hash.data, &ret_msg); break; case IPCP_MSG_CODE__IPCP_QUERY: assert(msg->hash.len == ipcp_dir_hash_len()); - handle_query(msg->hash.data, &ret_msg); + do_query(msg->hash.data, &ret_msg); break; case IPCP_MSG_CODE__IPCP_FLOW_ALLOC: assert(msg->hash.len == ipcp_dir_hash_len()); assert(msg->pk.len > 0 ? msg->pk.data != NULL : msg->pk.data == NULL); qs = qos_spec_msg_to_s(msg->qosspec); - handle_flow_alloc(msg->pid, msg->flow_id, - msg->hash.data, qs, - msg->pk.data, msg->pk.len, - &ret_msg); + do_flow_alloc(msg->pid, msg->flow_id, + msg->hash.data, qs, + msg->pk.data, msg->pk.len, + &ret_msg); break; case IPCP_MSG_CODE__IPCP_FLOW_JOIN: assert(msg->hash.len == ipcp_dir_hash_len()); qs = qos_spec_msg_to_s(msg->qosspec); - handle_flow_join(msg->pid, msg->flow_id, - msg->hash.data, qs, &ret_msg); + do_flow_join(msg->pid, msg->flow_id, + msg->hash.data, qs, &ret_msg); break; case IPCP_MSG_CODE__IPCP_FLOW_ALLOC_RESP: assert(msg->pk.len > 0 ? msg->pk.data != NULL : msg->pk.data == NULL); - handle_flow_alloc_resp(msg->response, msg->flow_id, - msg->pk.data, msg->pk.len, - &ret_msg); + do_flow_alloc_resp(msg->response, msg->flow_id, + msg->pk.data, msg->pk.len, + &ret_msg); break; case IPCP_MSG_CODE__IPCP_FLOW_DEALLOC: - handle_flow_dealloc(msg->flow_id, msg->timeo_sec, - &ret_msg); + do_flow_dealloc(msg->flow_id, msg->timeo_sec, &ret_msg); break; default: - ret_msg.result = -1; + ret_msg.result = -1; log_err("Unknown message code: %d.", msg->code); break; } @@ -830,14 +875,17 @@ int ipcp_init(int argc, goto fail_rib_init; } - if (rib_reg(IPCP_INFO, &r_ops)) + if (rib_reg(IPCP_INFO, &r_ops)) { + log_err("Failed to register rib."); goto fail_rib_reg; + } ipcpi.tpm = tpm_create(IPCP_MIN_THREADS, IPCP_ADD_THREADS, mainloop, NULL); - if (ipcpi.tpm == NULL) + if (ipcpi.tpm == NULL) { + log_err("Failed to create threadpool manager."); goto fail_tpm_create; - + } list_head_init(&ipcpi.cmds); diff --git a/src/ipcpd/local/main.c b/src/ipcpd/local/main.c index a2f8c6dc..ef1c679b 100644 --- a/src/ipcpd/local/main.c +++ b/src/ipcpd/local/main.c @@ -149,25 +149,22 @@ static int local_ipcp_bootstrap(const struct ipcp_config * conf) if (pthread_create(&local_data.packet_loop, NULL, local_ipcp_packet_loop, NULL)) { + log_err("Failed to create pthread: %s", strerror(errno)); ipcp_set_state(IPCP_INIT); return -1; } - log_info("Bootstrapped local IPCP with pid %d.", getpid()); - return 0; } static int local_ipcp_reg(const uint8_t * hash) { if (shim_data_reg_add_entry(local_data.shim_data, hash)) { - log_dbg("Failed to add " HASH_FMT32 " to local registry.", + log_err("Failed to add " HASH_FMT32 " to local registry.", HASH_VAL32(hash)); return -1; } - log_info("Registered " HASH_FMT32 ".", HASH_VAL32(hash)); - return 0; } @@ -226,8 +223,8 @@ static int local_ipcp_flow_alloc_resp(int fd, const void * data, size_t len) { - int out_fd = -1; - time_t mpl = IPCP_LOCAL_MPL; + int out_fd; + time_t mpl = IPCP_LOCAL_MPL; if (ipcp_wait_flow_resp(fd) < 0) return -1; diff --git a/src/ipcpd/shim-data.c b/src/ipcpd/shim-data.c index 840b8224..34f875b1 100644 --- a/src/ipcpd/shim-data.c +++ b/src/ipcpd/shim-data.c @@ -30,7 +30,7 @@ #define OUROBOROS_PREFIX "shim-data" -#include +#include #include #include #include @@ -446,9 +446,9 @@ uint64_t shim_data_dir_get_addr(struct shim_data * data, pthread_rwlock_rdlock(&data->dir_lock); entry = find_dir_entry_any(data, hash); - if (entry == NULL) { pthread_rwlock_unlock(&data->dir_lock); + log_warn("No address for " HASH_FMT32 ".", HASH_VAL32(hash)); return 0; /* undefined behaviour, 0 may be a valid address */ } diff --git a/src/ipcpd/udp/main.c b/src/ipcpd/udp/main.c index aacf976e..8decb9be 100644 --- a/src/ipcpd/udp/main.c +++ b/src/ipcpd/udp/main.c @@ -323,8 +323,8 @@ static int udp_ipcp_port_alloc_reply(const struct sockaddr_in * saddr, if (memcmp(&udp_data.fd_to_uf[s_eid].r_saddr, saddr, sizeof(*saddr))) { pthread_rwlock_unlock(&udp_data.flows_lock); - log_warn("Flow allocation reply for %u from wrong source.", - s_eid); + log_err("Flow allocation reply for %u from wrong source.", + s_eid); return -1; } @@ -334,7 +334,7 @@ static int udp_ipcp_port_alloc_reply(const struct sockaddr_in * saddr, pthread_rwlock_unlock(&udp_data.flows_lock); if (ipcp_flow_alloc_reply(s_eid, response, mpl, data, len) < 0) { - log_dbg("Failed to reply to flow allocation."); + log_err("Failed to reply to flow allocation."); return -1; } @@ -596,17 +596,17 @@ static int udp_ipcp_bootstrap(const struct ipcp_config * conf) strcpy(ipcpi.layer_name, conf->layer_info.layer_name); if (inet4_ntop(&conf->udp.ip_addr, ipstr) == NULL) { - log_err("Failed to convert IP address"); + log_err("Failed to convert IP address."); return -1; } if (conf->udp.dns_addr != 0) { if (inet4_ntop(&conf->udp.dns_addr, dnsstr) == NULL) { - log_err("Failed to convert DNS address"); + log_err("Failed to convert DNS address."); return -1; } #ifndef HAVE_DDNS - log_warn("DNS disabled at compile time, address ignored"); + log_warn("DNS disabled at compile time, address ignored."); #endif } else { strcpy(dnsstr, "not set"); @@ -633,14 +633,14 @@ static int udp_ipcp_bootstrap(const struct ipcp_config * conf) if (pthread_create(&udp_data.mgmt_handler, NULL, udp_ipcp_mgmt_handler, NULL)) { - ipcp_set_state(IPCP_INIT); + log_err("Failed to create management thread."); goto fail_bind; } for (i = 0; i < IPCP_UDP_RD_THR; ++i) { if (pthread_create(&udp_data.packet_reader[i], NULL, udp_ipcp_packet_reader, NULL)) { - ipcp_set_state(IPCP_INIT); + log_err("Failed to create reader thread."); goto fail_packet_reader; } } @@ -648,7 +648,7 @@ static int udp_ipcp_bootstrap(const struct ipcp_config * conf) for (i = 0; i < IPCP_UDP_WR_THR; ++i) { if (pthread_create(&udp_data.packet_writer[i], NULL, udp_ipcp_packet_writer, NULL)) { - ipcp_set_state(IPCP_INIT); + log_err("failed to create writer thread."); goto fail_packet_writer; } } @@ -822,8 +822,10 @@ static int udp_ipcp_reg(const uint8_t * hash) char * hashstr; hashstr = malloc(ipcp_dir_hash_strlen() + 1); - if (hashstr == NULL) + if (hashstr == NULL) { + log_err("Failed to malloc hashstr."); return -1; + } assert(hash); @@ -845,11 +847,13 @@ static int udp_ipcp_reg(const uint8_t * hash) ip_addr = udp_data.s_saddr.sin_addr.s_addr; if (inet4_ntop(&ip_addr, ipstr) == NULL) { + log_err("Failed to convert IP address to string."); free(hashstr); return -1; } if (inet4_ntop(&dns_addr, dnsstr) == NULL) { + log_err("Failed to convert DNS address to string."); free(hashstr); return -1; } @@ -858,14 +862,13 @@ static int udp_ipcp_reg(const uint8_t * hash) dnsstr, hashstr, DNS_TTL, ipstr); if (ddns_send(cmd)) { + log_err("Failed to send DDNS message."); shim_data_reg_del_entry(udp_data.shim_data, hash); free(hashstr); return -1; } } #endif - log_dbg("Registered " HASH_FMT32 ".", HASH_VAL32(hash)); - free(hashstr); return 0; @@ -884,8 +887,10 @@ static int udp_ipcp_unreg(const uint8_t * hash) assert(hash); hashstr = malloc(ipcp_dir_hash_strlen() + 1); - if (hashstr == NULL) + if (hashstr == NULL) { + log_err("Failed to malloc hashstr."); return -1; + } ipcp_hash_str(hashstr, hash); @@ -896,6 +901,7 @@ static int udp_ipcp_unreg(const uint8_t * hash) if (dns_addr != 0) { if (inet4_ntop(&dns_addr, dnsstr) == NULL) { + log_err("Failed to convert DNS address to string."); free(hashstr); return -1; } @@ -908,8 +914,6 @@ static int udp_ipcp_unreg(const uint8_t * hash) shim_data_reg_del_entry(udp_data.shim_data, hash); - log_dbg("Unregistered " HASH_FMT32 ".", HASH_VAL32(hash)); - free(hashstr); return 0; @@ -926,8 +930,10 @@ static int udp_ipcp_query(const uint8_t * hash) assert(hash); hashstr = malloc(ipcp_dir_hash_strlen() + 1); - if (hashstr == NULL) + if (hashstr == NULL) { + log_err("Failed to malloc hashstr."); return -ENOMEM; + } ipcp_hash_str(hashstr, hash); @@ -942,7 +948,7 @@ static int udp_ipcp_query(const uint8_t * hash) if (dns_addr != 0) { ip_addr = ddns_resolve(hashstr, dns_addr); if (ip_addr == 0) { - log_dbg("Could not resolve %s.", hashstr); + log_err("Could not resolve %s.", hashstr); free(hashstr); return -1; } @@ -950,7 +956,7 @@ static int udp_ipcp_query(const uint8_t * hash) #endif h = gethostbyname(hashstr); if (h == NULL) { - log_dbg("Could not resolve %s.", hashstr); + log_err("Could not resolve %s.", hashstr); free(hashstr); return -1; } @@ -981,8 +987,6 @@ static int udp_ipcp_flow_alloc(int fd, uint32_t ip_addr = 0; char ipstr[INET_ADDRSTRLEN]; - log_dbg("Allocating flow to " HASH_FMT32 ".", HASH_VAL32(dst)); - (void) qs; assert(dst); @@ -998,6 +1002,7 @@ static int udp_ipcp_flow_alloc(int fd, log_err("Could not convert IP address."); return -1; } + log_dbg("Destination UDP ipcp resolved at %s.", ipstr); memset((char *) &r_saddr, 0, sizeof(r_saddr)); @@ -1019,8 +1024,6 @@ static int udp_ipcp_flow_alloc(int fd, fset_add(udp_data.np1_flows, fd); - log_dbg("Flow to %s pending on fd %d.", ipstr, fd); - return 0; } @@ -1032,8 +1035,10 @@ static int udp_ipcp_flow_alloc_resp(int fd, struct sockaddr_in saddr; int d_eid; - if (ipcp_wait_flow_resp(fd) < 0) + if (ipcp_wait_flow_resp(fd) < 0) { + log_err("Failed to wait for flow response."); return -1; + } pthread_rwlock_rdlock(&udp_data.flows_lock); @@ -1050,9 +1055,6 @@ static int udp_ipcp_flow_alloc_resp(int fd, fset_add(udp_data.np1_flows, fd); - log_dbg("Accepted flow, fd %d on eid %d.", - fd, d_eid); - return 0; } @@ -1071,8 +1073,6 @@ static int udp_ipcp_flow_dealloc(int fd) flow_dealloc(fd); - log_dbg("Flow with fd %d deallocated.", fd); - return 0; } @@ -1101,8 +1101,10 @@ int main(int argc, goto fail_data_init; } - if (ipcp_init(argc, argv, &udp_ops, THIS_TYPE) < 0) + if (ipcp_init(argc, argv, &udp_ops, THIS_TYPE) < 0) { + log_err("Failed to initialize IPCP."); goto fail_init; + } if (ipcp_start() < 0) { log_err("Failed to start IPCP."); 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: -- cgit v1.2.3