From 6f8925bed5a1d203a925a68fc872bfa75dcb929b Mon Sep 17 00:00:00 2001 From: Vincent Bernat Date: Sun, 16 Dec 2012 15:10:54 +0100 Subject: [PATCH] log: convert LLOG_* to log_* and add more debug logs Convert all call to LLOG_* to log_* with prefix. Also convert fatal/fatalx calls. Add more debugging since we will soon be able to filter them. --- src/client/actions.c | 36 +++---- src/client/display.c | 4 +- src/client/kv_writer.c | 8 +- src/client/lldpctl.c | 10 +- src/client/xml_writer.c | 12 +-- src/ctl.c | 29 ++++-- src/daemon/agent.c | 26 ++++- src/daemon/agent_priv.c | 8 +- src/daemon/cdp.c | 59 ++++++------ src/daemon/client.c | 36 +++++-- src/daemon/dmi.c | 7 +- src/daemon/edp.c | 59 ++++++------ src/daemon/event.c | 56 ++++++----- src/daemon/interfaces.c | 184 +++++++++++++++++++++++++---------- src/daemon/lldp.c | 72 +++++++------- src/daemon/lldpd.c | 185 ++++++++++++++++++++++++++---------- src/daemon/priv.c | 50 +++++----- src/daemon/privsep_fdpass.c | 12 +-- src/daemon/sonmp.c | 34 ++++--- src/lib/atom-private.c | 2 +- src/lib/connection.c | 2 +- src/lldpd-structs.c | 11 +++ src/log.c | 16 ++-- src/log.h | 9 +- src/marshal.c | 24 +++-- 25 files changed, 605 insertions(+), 346 deletions(-) diff --git a/src/client/actions.c b/src/client/actions.c index da903c59..d8932f01 100644 --- a/src/client/actions.c +++ b/src/client/actions.c @@ -43,7 +43,7 @@ get_next(lldpctl_atom_t *atom, char *string, if (*e1 == '\0') { if (mandatory) - LLOG_WARNX("unable to find %s in `%s' at pos %d", + log_warnx(NULL, "unable to find %s in `%s' at pos %d", what, string, pos); return NULL; } @@ -60,7 +60,7 @@ get_next_and_set(lldpctl_atom_t *atom, char *string, char *e1 = get_next(atom, string, what, mandatory); if (e1 == NULL) return -1; if (lldpctl_atom_set_str(atom, key, e1) == NULL) { - LLOG_WARNX("unable to set %s. %s.", what, + log_warnx(NULL, "unable to set %s. %s.", what, lldpctl_last_strerror(lldpctl_atom_get_connection(atom))); return 0; } @@ -199,13 +199,13 @@ parse_med_location(char *value, lldpctl_atom_t *location) lldpctl_k_med_civicaddress_value, 1) == 1) { if (lldpctl_atom_set(location, lldpctl_k_med_location_ca_elements, cael) == NULL) { - LLOG_WARNX("unable to add a civic address element. %s", + log_warnx(NULL, "unable to add a civic address element. %s", lldpctl_last_strerror(lldpctl_atom_get_connection(location))); stop = 1; } } else stop = 1; } else { - LLOG_WARNX("unable to set civic address type. %s.", + log_warnx(NULL, "unable to set civic address type. %s.", lldpctl_last_strerror(lldpctl_atom_get_connection(cael))); stop = 1; } @@ -220,7 +220,7 @@ parse_med_location(char *value, lldpctl_atom_t *location) return 0; return 1; default: - LLOG_WARNX("unable to determine the requested location format"); + log_warnx(NULL, "unable to determine the requested location format"); return 0; } @@ -246,7 +246,7 @@ modify_interfaces(lldpctl_conn_t *conn, ifaces = lldpctl_get_interfaces(conn); if (!ifaces) { - LLOG_WARNX("not able to get the list of interfaces: %s", lldpctl_strerror(lldpctl_last_error(conn))); + log_warnx(NULL, "not able to get the list of interfaces: %s", lldpctl_strerror(lldpctl_last_error(conn))); return; } @@ -278,16 +278,16 @@ modify_interfaces(lldpctl_conn_t *conn, /* Dot3 power */ dot3_power = lldpctl_atom_get(port, lldpctl_k_port_dot3_power); if (dot3_power == NULL) { - LLOG_WARNX("unable to set Dot3 power: support seems unavailable"); + log_warnx(NULL, "unable to set Dot3 power: support seems unavailable"); break; } if (parse_dot3_power(optarg, dot3_power)) { if (lldpctl_atom_set(port, lldpctl_k_port_dot3_power, dot3_power) == NULL) - LLOG_WARNX("unable to set Dot3 power. %s", + log_warnx(NULL, "unable to set Dot3 power. %s", lldpctl_strerror(lldpctl_last_error(conn))); else - LLOG_INFO("Dot3 power has been set for port %s", + log_info(NULL, "Dot3 power has been set for port %s", iface_name); } lldpctl_atom_dec_ref(dot3_power); @@ -296,16 +296,16 @@ modify_interfaces(lldpctl_conn_t *conn, /* LLDP-MED power */ med_power = lldpctl_atom_get(port, lldpctl_k_port_med_power); if (med_power == NULL) { - LLOG_WARNX("unable to set LLDP-MED power: support seems unavailable"); + log_warnx(NULL, "unable to set LLDP-MED power: support seems unavailable"); break; } if (parse_med_power(optarg, med_power)) { if (lldpctl_atom_set(port, lldpctl_k_port_med_power, med_power) == NULL) - LLOG_WARNX("unable to set LLDP-MED power. %s", + log_warnx(NULL, "unable to set LLDP-MED power. %s", lldpctl_strerror(lldpctl_last_error(conn))); else - LLOG_INFO("LLDP-MED power has been set for port %s", + log_info(NULL, "LLDP-MED power has been set for port %s", iface_name); } lldpctl_atom_dec_ref(med_power); @@ -314,7 +314,7 @@ modify_interfaces(lldpctl_conn_t *conn, /* LLDP-MED network policy */ med_policies = lldpctl_atom_get(port, lldpctl_k_port_med_policies); if (med_policies == NULL) { - LLOG_WARNX("unable to set LLDP-MED policy: support seems unavailable"); + log_warnx(NULL, "unable to set LLDP-MED policy: support seems unavailable"); break; } /* We select the first policy. Since we will @@ -327,10 +327,10 @@ modify_interfaces(lldpctl_conn_t *conn, if (parse_med_policy(optarg, med_policy)) { if (lldpctl_atom_set(port, lldpctl_k_port_med_policies, med_policy) == NULL) - LLOG_WARNX("unable to set LLDP-MED policy. %s", + log_warnx(NULL, "unable to set LLDP-MED policy. %s", lldpctl_strerror(lldpctl_last_error(conn))); else - LLOG_INFO("LLDP-MED policy has been set for port %s", + log_info(NULL, "LLDP-MED policy has been set for port %s", iface_name); } lldpctl_atom_dec_ref(med_policy); @@ -340,7 +340,7 @@ modify_interfaces(lldpctl_conn_t *conn, /* LLDP-MED location */ med_locations = lldpctl_atom_get(port, lldpctl_k_port_med_locations); if (med_locations == NULL) { - LLOG_WARNX("unable to set LLDP-MED location: support seems unavailable"); + log_warnx(NULL, "unable to set LLDP-MED location: support seems unavailable"); break; } /* As for policy, we pick the first and it will @@ -352,10 +352,10 @@ modify_interfaces(lldpctl_conn_t *conn, if (parse_med_location(optarg, med_location)) { if (lldpctl_atom_set(port, lldpctl_k_port_med_locations, med_location) == NULL) - LLOG_WARNX("unable to set LLDP-MED location. %s", + log_warnx(NULL, "unable to set LLDP-MED location. %s", lldpctl_strerror(lldpctl_last_error(conn))); else - LLOG_INFO("LLDP-MED location has been set for port %s", + log_info(NULL, "LLDP-MED location has been set for port %s", iface_name); } lldpctl_atom_dec_ref(med_location); diff --git a/src/client/display.c b/src/client/display.c index a1f788fb..b60ebf0a 100644 --- a/src/client/display.c +++ b/src/client/display.c @@ -558,7 +558,7 @@ display_interfaces(lldpctl_conn_t *conn, struct writer *w, int hidden, iface_list = lldpctl_get_interfaces(conn); if (!iface_list) { - LLOG_WARNX("not able to get the list of interfaces. %s", + log_warnx(NULL, "not able to get the list of interfaces. %s", lldpctl_last_strerror(conn)); return; } @@ -599,7 +599,7 @@ display_configuration(lldpctl_conn_t *conn, struct writer *w) configuration = lldpctl_get_configuration(conn); if (!configuration) { - LLOG_WARNX("not able to get configuration. %s", + log_warnx(NULL, "not able to get configuration. %s", lldpctl_last_strerror(conn)); return; } diff --git a/src/client/kv_writer.c b/src/client/kv_writer.c index 3897caaf..b8a87e64 100644 --- a/src/client/kv_writer.c +++ b/src/client/kv_writer.c @@ -39,7 +39,7 @@ kv_start(struct writer *w , const char *tag, const char *descr) s = strlen(p->prefix) + 1 + strlen(tag); if ((newprefix = malloc(s+1)) == NULL) - fatal(NULL); + fatal(NULL, NULL); if (strlen(p->prefix) > 0) snprintf(newprefix, s+1, "%s\1%s", p->prefix, tag); else @@ -54,7 +54,7 @@ kv_data(struct writer *w, const char *data) struct kv_writer_private *p = w->priv; char *key = strdup(p->prefix); char *dot; - if (!key) fatal(NULL); + if (!key) fatal(NULL, NULL); while ((dot = strchr(key, '\1')) != NULL) *dot=SEP; fprintf(p->fh, "%s=%s\n", key, data); free(key); @@ -106,13 +106,13 @@ kv_init(FILE *fh) struct kv_writer_private *priv; if ((priv = malloc(sizeof(*priv))) == NULL) - fatal(NULL); + fatal(NULL, NULL); priv->fh = fh; priv->prefix = strdup(""); if ((result = malloc(sizeof(struct writer))) == NULL) - fatal(NULL); + fatal(NULL, NULL); result->priv = priv; result->start = kv_start; diff --git a/src/client/lldpctl.c b/src/client/lldpctl.c index 75f733b6..8a701020 100644 --- a/src/client/lldpctl.c +++ b/src/client/lldpctl.c @@ -173,7 +173,7 @@ main(int argc, char *argv[]) args.argv = argv; if (watch) { if (lldpctl_watch_callback(conn, watchcb, &args) < 0) { - LLOG_WARNX("unable to watch for neighbors. %s", + log_warnx(NULL, "unable to watch for neighbors. %s", lldpctl_last_strerror(conn)); exit(EXIT_FAILURE); } @@ -198,7 +198,7 @@ main(int argc, char *argv[]) modify_interfaces(conn, argc, argv, optind); } else if (watch) { if (lldpctl_watch(conn) < 0) { - LLOG_WARNX("unable to watch for neighbors. %s", + log_warnx(NULL, "unable to watch for neighbors. %s", lldpctl_last_strerror(conn)); watch = 0; } @@ -207,15 +207,15 @@ main(int argc, char *argv[]) } else if (now) { lldpctl_atom_t *config = lldpctl_get_configuration(conn); if (config == NULL) { - LLOG_WARNX("unable to get configuration from lldpd. %s", + log_warnx(NULL, "unable to get configuration from lldpd. %s", lldpctl_last_strerror(conn)); } else { if (lldpctl_atom_set_int(config, lldpctl_k_config_tx_interval, -1) == NULL) { - LLOG_WARNX("unable to ask lldpd for immediate retransmission. %s", + log_warnx(NULL, "unable to ask lldpd for immediate retransmission. %s", lldpctl_last_strerror(conn)); } else - LLOG_INFO("immediate retransmission requested successfuly"); + log_info(NULL, "immediate retransmission requested successfuly"); lldpctl_atom_dec_ref(config); } } else { diff --git a/src/client/xml_writer.c b/src/client/xml_writer.c index 9192fd70..6ed116ce 100644 --- a/src/client/xml_writer.c +++ b/src/client/xml_writer.c @@ -34,11 +34,11 @@ void xml_start(struct writer * w , const char * tag, const char * descr ) { struct xml_writer_private * p = w->priv; if (xmlTextWriterStartElement(p->xw, BAD_CAST tag) < 0) - LLOG_WARNX("cannot start '%s' element", tag); + log_warnx(NULL, "cannot start '%s' element", tag); if ( descr && (strlen(descr) > 0) ) { if (xmlTextWriterWriteFormatAttribute(p->xw, BAD_CAST "label", "%s", descr) < 0) - LLOG_WARNX("cannot add attribute 'label' to element %s", tag); + log_warnx(NULL, "cannot add attribute 'label' to element %s", tag); } } @@ -46,20 +46,20 @@ void xml_attr(struct writer * w, const char * tag, const char * descr, const cha struct xml_writer_private * p = w->priv; if (xmlTextWriterWriteFormatAttribute(p->xw, BAD_CAST tag, "%s", value) < 0) - LLOG_WARNX("cannot add attribute %s with value %s", tag, value); + log_warnx(NULL, "cannot add attribute %s with value %s", tag, value); } void xml_data(struct writer * w, const char * data) { struct xml_writer_private * p = w->priv; if (xmlTextWriterWriteString(p->xw, BAD_CAST data) < 0 ) - LLOG_WARNX("cannot add '%s' as data to element", data); + log_warnx(NULL, "cannot add '%s' as data to element", data); } void xml_end(struct writer * w) { struct xml_writer_private * p = w->priv; if (xmlTextWriterEndElement(p->xw) < 0 ) - LLOG_WARNX("cannot end element\n"); + log_warnx(NULL, "cannot end element\n"); } #define MY_ENCODING "UTF-8" @@ -69,7 +69,7 @@ void xml_finish(struct writer * w) { int failed = 0; if (xmlTextWriterEndDocument(p->xw) < 0 ) { - LLOG_WARNX("cannot finish document"); + log_warnx(NULL, "cannot finish document"); failed = 1; } diff --git a/src/ctl.c b/src/ctl.c index 8c5df93b..937da07e 100644 --- a/src/ctl.c +++ b/src/ctl.c @@ -43,6 +43,8 @@ ctl_create(char *name) struct sockaddr_un su; int rc; + log_debug("control", "create control socket %s", name); + if ((s = socket(PF_UNIX, SOCK_STREAM, 0)) == -1) return -1; su.sun_family = AF_UNIX; @@ -51,8 +53,11 @@ ctl_create(char *name) rc = errno; close(s); errno = rc; return -1; } + + log_debug("control", "listen to control socket %s", name); if (listen(s, 5) == -1) { rc = errno; close(s); errno = rc; + log_debug("control", "cannot listen to control socket %s", name); return -1; } return s; @@ -71,13 +76,15 @@ ctl_connect(char *name) struct sockaddr_un su; int rc; + log_debug("control", "connect to control socket %s", name); + if ((s = socket(PF_UNIX, SOCK_STREAM, 0)) == -1) return -1; su.sun_family = AF_UNIX; strlcpy(su.sun_path, name, UNIX_PATH_MAX); if (connect(s, (struct sockaddr *)&su, sizeof(struct sockaddr_un)) == -1) { rc = errno; - LLOG_WARN("unable to connect to socket %s", name); + log_warn("control", "unable to connect to socket %s", name); errno = rc; return -1; } return s; @@ -91,8 +98,9 @@ ctl_connect(char *name) void ctl_cleanup(char *name) { + log_debug("control", "cleanup control socket"); if (unlink(name) == -1) - LLOG_WARN("unable to unlink %s", name); + log_warn("control", "unable to unlink %s", name); } /** @@ -121,10 +129,11 @@ ctl_msg_send_unserialized(uint8_t **output_buffer, size_t *output_len, size_t len = 0, newlen; void *buffer = NULL; + log_debug("control", "send a message through control socket"); if (t) { len = marshal_serialize_(mi, t, &buffer, 0, NULL, 0); if (len <= 0) { - LLOG_WARNX("unable to serialize data"); + log_warnx("control", "unable to serialize data"); return -1; } } @@ -134,14 +143,14 @@ ctl_msg_send_unserialized(uint8_t **output_buffer, size_t *output_len, if (*output_buffer == NULL) { *output_len = 0; if ((*output_buffer = malloc(newlen)) == NULL) { - LLOG_WARN("no memory available"); + log_warn("control", "no memory available"); free(buffer); return -1; } } else { void *new = realloc(*output_buffer, *output_len + newlen); if (new == NULL) { - LLOG_WARN("no memory available"); + log_warn("control", "no memory available"); free(buffer); return -1; } @@ -197,9 +206,11 @@ ctl_msg_recv_unserialized(uint8_t **input_buffer, size_t *input_len, /* Not enough data. */ return sizeof(struct hmsg_header) - *input_len; } + + log_debug("control", "receive a message through control socket"); hdr = (struct hmsg_header *)*input_buffer; if (hdr->len > HMSG_MAX_SIZE) { - LLOG_WARNX("message received is too large"); + log_warnx("control", "message received is too large"); /* We discard the whole buffer */ free(*input_buffer); *input_buffer = NULL; @@ -212,20 +223,20 @@ ctl_msg_recv_unserialized(uint8_t **input_buffer, size_t *input_len, } if (hdr->type != expected_type) { if (expected_type == NOTIFICATION) return -1; - LLOG_WARNX("incorrect received message type (expected: %d, received: %d)", + log_warnx("control", "incorrect received message type (expected: %d, received: %d)", expected_type, hdr->type); goto end; } if (t && !hdr->len) { - LLOG_WARNX("no payload available in answer"); + log_warnx("control", "no payload available in answer"); goto end; } if (t) { /* We have data to unserialize. */ if (marshal_unserialize_(mi, *input_buffer + sizeof(struct hmsg_header), hdr->len, t, NULL, 0, 0) <= 0) { - LLOG_WARNX("unable to deserialize received data"); + log_warnx("control", "unable to deserialize received data"); goto end; } } diff --git a/src/daemon/agent.c b/src/daemon/agent.c index 5bc37737..0c06a479 100644 --- a/src/daemon/agent.c +++ b/src/daemon/agent.c @@ -1724,6 +1724,21 @@ agent_notify(struct lldpd_hardware *hardware, int type, if (!hardware->h_cfg->g_snmp) return; + switch (type) { + case NEIGHBOR_CHANGE_DELETED: + log_debug("snmp", "send notification for neighbor deleted on %s", + hardware->h_ifname); + break; + case NEIGHBOR_CHANGE_UPDATED: + log_debug("snmp", "send notification for neighbor updated on %s", + hardware->h_ifname); + break; + case NEIGHBOR_CHANGE_ADDED: + log_debug("snmp", "send notification for neighbor added on %s", + hardware->h_ifname); + break; + } + TAILQ_FOREACH(h, &hardware->h_cfg->g_hardware, h_entries) { inserts += h->h_insert_cnt; deletes += h->h_delete_cnt; @@ -1781,7 +1796,7 @@ agent_notify(struct lldpd_hardware *hardware, int type, } } - LLOG_DEBUG("sending SNMP trap (%ld, %ld, %ld)", + log_debug("snmp", "sending SNMP trap (%ld, %ld, %ld)", inserts, deletes, ageouts); send_v2trap(notification_vars); snmp_free_varbind(notification_vars); @@ -1816,8 +1831,10 @@ agent_init(struct lldpd *cfg, char *agentx) { int rc; - LLOG_INFO("Enable SNMP subagent"); + log_info("snmp", "enable SNMP subagent"); netsnmp_enable_subagent(); + + log_debug("snmp", "enable logging"); snmp_disable_log(); snmp_enable_calllog(); snmp_register_callback(SNMP_CALLBACK_LIBRARY, @@ -1835,6 +1852,7 @@ agent_init(struct lldpd *cfg, char *agentx) setenv("MIBDIRS", "/dev/null", 1); /* We provide our UNIX domain transport */ + log_debug("snmp", "register UNIX domain transport"); agent_priv_register_domain(); if (agentx) @@ -1844,14 +1862,16 @@ agent_init(struct lldpd *cfg, char *agentx) REGISTER_MIB("lldp", agent_lldp_vars, variable8, lldp_oid); init_snmp("lldpAgent"); + log_debug("snmp", "register to sysORTable"); if ((rc = register_sysORTable(lldp_oid, OID_LENGTH(lldp_oid), "lldpMIB implementation by lldpd")) != 0) - LLOG_WARNX("Unable to register to sysORTable (%d)", rc); + log_warnx("snmp", "unable to register to sysORTable (%d)", rc); } void agent_shutdown() { + log_debug("snmp", "agent shutdown"); unregister_sysORTable(lldp_oid, OID_LENGTH(lldp_oid)); snmp_shutdown("lldpAgent"); } diff --git a/src/daemon/agent_priv.c b/src/daemon/agent_priv.c index 2b8cbc95..10f0e729 100644 --- a/src/daemon/agent_priv.c +++ b/src/daemon/agent_priv.c @@ -60,7 +60,7 @@ agent_priv_unix_recv(netsnmp_transport *t, void *buf, int size, while (rc < 0) { rc = recv(t->sock, buf, size, 0); if (rc < 0 && errno != EINTR) { - LLOG_WARN("unable to receive from fd %d", + log_warn("snmp", "unable to receive from fd %d", t->sock); goto recv_error; } @@ -108,7 +108,7 @@ agent_priv_unix_close(netsnmp_transport *t) static int agent_priv_unix_accept(netsnmp_transport *t) { - LLOG_WARNX("should not have been called"); + log_warnx("snmp", "should not have been called"); return -1; } @@ -119,7 +119,7 @@ agent_priv_unix_transport(const char *string, int len, int local) netsnmp_transport *t = NULL; if (local) { - LLOG_WARNX("should not have been called for local transport"); + log_warnx("snmp", "should not have been called for local transport"); return NULL; } if (!string) @@ -129,7 +129,7 @@ agent_priv_unix_transport(const char *string, int len, int local) memset(addr.sun_path, 0, sizeof(addr.sun_path)); strncpy(addr.sun_path, string, len); } else { - LLOG_WARNX("path too long for Unix domain transport"); + log_warnx("snmp", "path too long for Unix domain transport"); return NULL; } diff --git a/src/daemon/cdp.c b/src/daemon/cdp.c index 47bfa17f..ebf09c71 100644 --- a/src/daemon/cdp.c +++ b/src/daemon/cdp.c @@ -45,6 +45,8 @@ cdp_send(struct lldpd *global, u_int8_t *packet; u_int8_t *pos, *pos_len_eh, *pos_llc, *pos_cdp, *pos_checksum, *tlv, *end; + log_debug("cdp", "send CDP frame on %s", hardware->h_ifname); + chassis = hardware->h_lport.p_chassis; #ifdef ENABLE_FDP @@ -206,7 +208,7 @@ cdp_send(struct lldpd *global, if (hardware->h_ops->send(global, hardware, (char *)packet, end - packet) == -1) { - LLOG_WARN("unable to send packet on real device for %s", + log_warn("cdp", "unable to send packet on real device for %s", hardware->h_ifname); free(packet); return ENETDOWN; @@ -223,7 +225,7 @@ cdp_send(struct lldpd *global, #define CHECK_TLV_SIZE(x, name) \ do { if (tlv_len < (x)) { \ - LLOG_WARNX(name " CDP/FDP TLV too short received on %s",\ + log_warnx("cdp", name " CDP/FDP TLV too short received on %s", \ hardware->h_ifname); \ goto malformed; \ } } while (0) @@ -253,13 +255,16 @@ cdp_decode(struct lldpd *cfg, char *frame, int s, struct lldpd_vlan *vlan; #endif + log_debug("cdp", "decode CDP frame received on %s", + hardware->h_ifname); + if ((chassis = calloc(1, sizeof(struct lldpd_chassis))) == NULL) { - LLOG_WARN("failed to allocate remote chassis"); + log_warn("cdp", "failed to allocate remote chassis"); return -1; } TAILQ_INIT(&chassis->c_mgmt); if ((port = calloc(1, sizeof(struct lldpd_port))) == NULL) { - LLOG_WARN("failed to allocate remote port"); + log_warn("cdp", "failed to allocate remote port"); free(chassis); return -1; } @@ -272,7 +277,7 @@ cdp_decode(struct lldpd *cfg, char *frame, int s, if (length < 2*ETH_ALEN + sizeof(u_int16_t) /* Ethernet */ + 8 /* LLC */ + 4 /* CDP header */) { - LLOG_WARNX("too short CDP/FDP frame received on %s", hardware->h_ifname); + log_warn("cdp", "too short CDP/FDP frame received on %s", hardware->h_ifname); goto malformed; } @@ -283,7 +288,7 @@ cdp_decode(struct lldpd *cfg, char *frame, int s, fdp = 1; else { #endif - LLOG_INFO("frame not targeted at CDP/FDP multicast address received on %s", + log_info("cdp", "frame not targeted at CDP/FDP multicast address received on %s", hardware->h_ifname); goto malformed; #ifdef ENABLE_FDP @@ -293,7 +298,7 @@ cdp_decode(struct lldpd *cfg, char *frame, int s, PEEK_DISCARD(ETH_ALEN); /* Don't care of source address */ len_eth = PEEK_UINT16; if (len_eth > length) { - LLOG_WARNX("incorrect 802.3 frame size reported on %s", + log_warnx("cdp", "incorrect 802.3 frame size reported on %s", hardware->h_ifname); goto malformed; } @@ -307,7 +312,7 @@ cdp_decode(struct lldpd *cfg, char *frame, int s, (proto != LLC_PID_VTP) && (proto != LLC_PID_DTP) && (proto != LLC_PID_STP)) - LLOG_DEBUG("incorrect LLC protocol ID received on %s", + log_debug("cdp", "incorrect LLC protocol ID received on %s", hardware->h_ifname); goto malformed; } @@ -323,7 +328,7 @@ cdp_decode(struct lldpd *cfg, char *frame, int s, ); /* An off-by-one error may happen. Just ignore it */ if ((cksum != 0) && (cksum != 0xfffe)) { - LLOG_INFO("incorrect CDP/FDP checksum for frame received on %s (%d)", + log_info("cdp", "incorrect CDP/FDP checksum for frame received on %s (%d)", hardware->h_ifname, cksum); goto malformed; } @@ -332,7 +337,7 @@ cdp_decode(struct lldpd *cfg, char *frame, int s, /* Check version */ version = PEEK_UINT8; if ((version != 1) && (version != 2)) { - LLOG_WARNX("incorrect CDP/FDP version (%d) for frame received on %s", + log_warnx("cdp", "incorrect CDP/FDP version (%d) for frame received on %s", version, hardware->h_ifname); goto malformed; } @@ -341,7 +346,7 @@ cdp_decode(struct lldpd *cfg, char *frame, int s, while (length) { if (length < 4) { - LLOG_WARNX("CDP/FDP TLV header is too large for " + log_warnx("cdp", "CDP/FDP TLV header is too large for " "frame received on %s", hardware->h_ifname); goto malformed; @@ -350,7 +355,7 @@ cdp_decode(struct lldpd *cfg, char *frame, int s, tlv_len = PEEK_UINT16 - 4; PEEK_SAVE(tlv); if ((tlv_len < 0) || (length < tlv_len)) { - LLOG_WARNX("incorrect size in CDP/FDP TLV header for frame " + log_warnx("cdp", "incorrect size in CDP/FDP TLV header for frame " "received on %s", hardware->h_ifname); goto malformed; @@ -358,13 +363,13 @@ cdp_decode(struct lldpd *cfg, char *frame, int s, switch (tlv_type) { case CDP_TLV_CHASSIS: if ((chassis->c_name = (char *)calloc(1, tlv_len + 1)) == NULL) { - LLOG_WARN("unable to allocate memory for chassis name"); + log_warn("cdp", "unable to allocate memory for chassis name"); goto malformed; } PEEK_BYTES(chassis->c_name, tlv_len); chassis->c_id_subtype = LLDP_CHASSISID_SUBTYPE_LOCAL; if ((chassis->c_id = (char *)malloc(tlv_len)) == NULL) { - LLOG_WARN("unable to allocate memory for chassis ID"); + log_warn("cdp", "unable to allocate memory for chassis ID"); goto malformed; } memcpy(chassis->c_id, chassis->c_name, tlv_len); @@ -377,7 +382,7 @@ cdp_decode(struct lldpd *cfg, char *frame, int s, PEEK_SAVE(pos_address); /* We first try to get the real length of the packet */ if (addresses_len < 2) { - LLOG_WARN("too short address subframe " + log_warn("cdp", "too short address subframe " "received on %s", hardware->h_ifname); goto malformed; @@ -385,7 +390,7 @@ cdp_decode(struct lldpd *cfg, char *frame, int s, PEEK_DISCARD_UINT8; addresses_len--; address_len = PEEK_UINT8; addresses_len--; if (addresses_len < address_len + 2) { - LLOG_WARN("too short address subframe " + log_warn("cdp", "too short address subframe " "received on %s", hardware->h_ifname); goto malformed; @@ -394,7 +399,7 @@ cdp_decode(struct lldpd *cfg, char *frame, int s, addresses_len -= address_len; address_len = PEEK_UINT16; addresses_len -= 2; if (addresses_len < address_len) { - LLOG_WARN("too short address subframe " + log_warn("cdp", "too short address subframe " "received on %s", hardware->h_ifname); goto malformed; @@ -412,7 +417,7 @@ cdp_decode(struct lldpd *cfg, char *frame, int s, sizeof(struct in_addr), 0); if (mgmt == NULL) { assert(errno == ENOMEM); - LLOG_WARN("unable to allocate memory for management address"); + log_warn("cdp", "unable to allocate memory for management address"); goto malformed; } TAILQ_INSERT_TAIL(&chassis->c_mgmt, mgmt, m_entries); @@ -423,13 +428,13 @@ cdp_decode(struct lldpd *cfg, char *frame, int s, break; case CDP_TLV_PORT: if ((port->p_descr = (char *)calloc(1, tlv_len + 1)) == NULL) { - LLOG_WARN("unable to allocate memory for port description"); + log_warn("cdp", "unable to allocate memory for port description"); goto malformed; } PEEK_BYTES(port->p_descr, tlv_len); port->p_id_subtype = LLDP_PORTID_SUBTYPE_IFNAME; if ((port->p_id = (char *)calloc(1, tlv_len)) == NULL) { - LLOG_WARN("unable to allocate memory for port ID"); + log_warn("cdp", "unable to allocate memory for port ID"); goto malformed; } memcpy(port->p_id, port->p_descr, tlv_len); @@ -474,7 +479,7 @@ cdp_decode(struct lldpd *cfg, char *frame, int s, CHECK_TLV_SIZE(2, "Native VLAN"); if ((vlan = (struct lldpd_vlan *)calloc(1, sizeof(struct lldpd_vlan))) == NULL) { - LLOG_WARN("unable to alloc vlan " + log_warn("cdp", "unable to alloc vlan " "structure for " "tlv received on %s", hardware->h_ifname); @@ -482,7 +487,7 @@ cdp_decode(struct lldpd *cfg, char *frame, int s, } vlan->v_vid = port->p_pvid = PEEK_UINT16; if (asprintf(&vlan->v_name, "VLAN #%d", vlan->v_vid) == -1) { - LLOG_WARN("unable to alloc VLAN name for " + log_warn("cdp", "unable to alloc VLAN name for " "TLV received on %s", hardware->h_ifname); free(vlan); @@ -493,7 +498,7 @@ cdp_decode(struct lldpd *cfg, char *frame, int s, break; #endif default: - LLOG_DEBUG("unknown CDP/FDP TLV type (%d) received on %s", + log_debug("cdp", "unknown CDP/FDP TLV type (%d) received on %s", ntohs(tlv_type), hardware->h_ifname); hardware->h_rx_unrecognized_cnt++; } @@ -502,14 +507,14 @@ cdp_decode(struct lldpd *cfg, char *frame, int s, if (!software && platform) { if ((chassis->c_descr = (char *)calloc(1, platform_len + 1)) == NULL) { - LLOG_WARN("unable to allocate memory for chassis description"); + log_warn("cdp", "unable to allocate memory for chassis description"); goto malformed; } memcpy(chassis->c_descr, platform, platform_len); } else if (software && !platform) { if ((chassis->c_descr = (char *)calloc(1, software_len + 1)) == NULL) { - LLOG_WARN("unable to allocate memory for chassis description"); + log_warn("cdp", "unable to allocate memory for chassis description"); goto malformed; } memcpy(chassis->c_descr, software, software_len); @@ -518,7 +523,7 @@ cdp_decode(struct lldpd *cfg, char *frame, int s, if ((chassis->c_descr = (char *)calloc(1, software_len + platform_len + strlen(CONCAT_PLATFORM) + 1)) == NULL) { - LLOG_WARN("unable to allocate memory for chassis description"); + log_warn("cdp", "unable to allocate memory for chassis description"); goto malformed; } memcpy(chassis->c_descr, platform, platform_len); @@ -534,7 +539,7 @@ cdp_decode(struct lldpd *cfg, char *frame, int s, (port->p_descr == NULL) || (chassis->c_ttl == 0) || (chassis->c_cap_enabled == 0)) { - LLOG_WARNX("some mandatory CDP/FDP tlv are missing for frame received on %s", + log_warnx("cdp", "some mandatory CDP/FDP tlv are missing for frame received on %s", hardware->h_ifname); goto malformed; } diff --git a/src/daemon/client.c b/src/daemon/client.c index 9677708f..e48216e4 100644 --- a/src/daemon/client.c +++ b/src/daemon/client.c @@ -21,7 +21,7 @@ static int client_handle_none(struct lldpd *cfg, enum hmsg_type *type, void *input, int input_len, void **output, int *subscribed) { - LLOG_INFO("received noop request from client"); + log_info("rpc", "received noop request from client"); *type = NONE; return 0; } @@ -32,6 +32,7 @@ client_handle_get_configuration(struct lldpd *cfg, enum hmsg_type *type, void *input, int input_len, void **output, int *subscribed) { ssize_t output_len; + log_debug("rpc", "client requested configuration"); output_len = marshal_serialize(lldpd_config, &cfg->g_config, output); if (output_len <= 0) { output_len = 0; @@ -47,6 +48,7 @@ client_handle_set_configuration(struct lldpd *cfg, enum hmsg_type *type, { struct lldpd_config *config; + log_debug("rpc", "client request a change in configuration"); /* Get the proposed configuration. */ if (marshal_unserialize(lldpd_config, input, input_len, &config) <= 0) { *type = NONE; @@ -56,10 +58,12 @@ client_handle_set_configuration(struct lldpd *cfg, enum hmsg_type *type, /* What needs to be done? Currently, we only support setting the * transmit delay. */ if (config->c_tx_interval > 0) { + log_debug("rpc", "client change transmit interval to %d", + config->c_tx_interval); cfg->g_config.c_tx_interval = config->c_tx_interval; } if (config->c_tx_interval < 0) { - LLOG_DEBUG("client asked for immediate retransmission"); + log_debug("rpc", "client asked for immediate retransmission"); levent_send_now(cfg); } @@ -82,11 +86,13 @@ client_handle_get_interfaces(struct lldpd *cfg, enum hmsg_type *type, /* Build the list of interfaces */ struct lldpd_interface_list ifs; + + log_debug("rpc", "client request the list of interfaces"); TAILQ_INIT(&ifs); TAILQ_FOREACH(hardware, &cfg->g_hardware, h_entries) { if ((iff = (struct lldpd_interface*)malloc(sizeof( struct lldpd_interface))) == NULL) - fatal(NULL); + fatal("rpc", NULL); iff->name = hardware->h_ifname; TAILQ_INSERT_TAIL(&ifs, iff, next); } @@ -127,6 +133,7 @@ client_handle_get_interface(struct lldpd *cfg, enum hmsg_type *type, } /* Search appropriate hardware */ + log_debug("rpc", "client request interface %s", name); TAILQ_FOREACH(hardware, &cfg->g_hardware, h_entries) if (!strcmp(hardware->h_ifname, name)) { int output_len = marshal_serialize(lldpd_hardware, hardware, output); @@ -140,7 +147,7 @@ client_handle_get_interface(struct lldpd *cfg, enum hmsg_type *type, } free(name); - LLOG_WARNX("no interface %s found", name); + log_warnx("rpc", "no interface %s found", name); *type = NONE; return 0; } @@ -165,19 +172,21 @@ client_handle_set_port(struct lldpd *cfg, enum hmsg_type *type, return 0; } if (!set->ifname) { - LLOG_WARNX("no interface provided"); + log_warnx("rpc", "no interface provided"); goto set_port_finished; } /* Search the appropriate hardware */ + log_debug("rpc", "client request change to port %s", set->ifname); TAILQ_FOREACH(hardware, &cfg->g_hardware, h_entries) if (!strcmp(hardware->h_ifname, set->ifname)) { struct lldpd_port *port = &hardware->h_lport; (void)port; #ifdef ENABLE_LLDPMED if (set->med_policy && set->med_policy->type > 0) { + log_debug("rpc", "requested change to MED policy"); if (set->med_policy->type > LLDP_MED_APPTYPE_LAST) { - LLOG_WARNX("invalid policy provided: %d", + log_warnx("rpc", "invalid policy provided: %d", set->med_policy->type); goto set_port_finished; } @@ -187,8 +196,9 @@ client_handle_set_port(struct lldpd *cfg, enum hmsg_type *type, } if (set->med_location && set->med_location->format > 0) { char *newdata = NULL; + log_debug("rpc", "requested change to MED location"); if (set->med_location->format > LLDP_MED_LOCFORMAT_LAST) { - LLOG_WARNX("invalid location format provided: %d", + log_warnx("rpc", "invalid location format provided: %d", set->med_location->format); goto set_port_finished; } @@ -202,6 +212,7 @@ client_handle_set_port(struct lldpd *cfg, enum hmsg_type *type, port->p_med_cap_enabled |= LLDP_MED_CAP_LOCATION; } if (set->med_power) { + log_debug("rpc", "requested change to MED power"); memcpy(&port->p_med_power, set->med_power, sizeof(struct lldpd_med_power)); switch (set->med_power->devicetype) { @@ -217,16 +228,18 @@ client_handle_set_port(struct lldpd *cfg, enum hmsg_type *type, } #endif #ifdef ENABLE_DOT3 - if (set->dot3_power) + if (set->dot3_power) { + log_debug("rpc", "requested change to Dot3 power"); memcpy(&port->p_power, set->dot3_power, sizeof(struct lldpd_dot3_power)); + } #endif ret = 1; break; } if (ret == 0) - LLOG_WARN("no interface %s found", set->ifname); + log_warn("rpc", "no interface %s found", set->ifname); set_port_finished: if (!ret) *type = NONE; @@ -248,6 +261,7 @@ static int client_handle_subscribe(struct lldpd *cfg, enum hmsg_type *type, void *input, int input_len, void **output, int *subscribed) { + log_debug("rpc", "client subscribe to changes"); *subscribed = 1; return 0; } @@ -277,6 +291,8 @@ client_handle_client(struct lldpd *cfg, { struct client_handle *ch; void *answer; size_t len, sent; + + log_debug("rpc", "handle client request"); for (ch = client_handles; ch->handle != NULL; ch++) { if (ch->type == type) { answer = NULL; len = 0; @@ -288,7 +304,7 @@ client_handle_client(struct lldpd *cfg, } } - LLOG_WARNX("unknown message request (%d) received", + log_warnx("rpc", "unknown message request (%d) received", type); return -1; } diff --git a/src/daemon/dmi.c b/src/daemon/dmi.c index ed364e0a..54e6b583 100644 --- a/src/daemon/dmi.c +++ b/src/daemon/dmi.c @@ -36,14 +36,15 @@ dmi_get(char *file) { int dmi, s; char buffer[100]; - + + log_debug("localchassis", "DMI request for file %s", file); if ((dmi = priv_open(file)) < 0) { - LLOG_DEBUG("cannot get DMI file %s", file); + log_debug("localchassis", "cannot get DMI file %s", file); return NULL; } memset(buffer, 0, sizeof(buffer)); if ((s = read(dmi, buffer, sizeof(buffer))) == -1) { - LLOG_DEBUG("cannot read DMI file %s", file); + log_debug("localchassis", "cannot read DMI file %s", file); close(dmi); return NULL; } diff --git a/src/daemon/edp.c b/src/daemon/edp.c index a3a23b25..7c54e8e7 100644 --- a/src/daemon/edp.c +++ b/src/daemon/edp.c @@ -49,6 +49,8 @@ edp_send(struct lldpd *global, invariant with version changes. */ char *deviceslot[] = { "eth", "veth", "XXX", "XXX", "XXX", "XXX", "XXX", "XXX", "", NULL }; + log_debug("edp", "send EDP frame on port %s", hardware->h_ifname); + chassis = hardware->h_lport.p_chassis; #ifdef ENABLE_DOT1 while (state != 2) { @@ -85,7 +87,7 @@ edp_send(struct lldpd *global, /* EDP header */ if ((chassis->c_id_len != ETH_ALEN) || (chassis->c_id_subtype != LLDP_CHASSISID_SUBTYPE_LLADDR)) { - LLOG_WARNX("local chassis does not use MAC address as chassis ID!?"); + log_warnx("edp", "local chassis does not use MAC address as chassis ID!?"); free(packet); return EINVAL; } @@ -198,7 +200,7 @@ edp_send(struct lldpd *global, if (hardware->h_ops->send(global, hardware, (char *)packet, end - packet) == -1) { - LLOG_WARN("unable to send packet on real device for %s", + log_warn("edp", "unable to send packet on real device for %s", hardware->h_ifname); free(packet); return ENETDOWN; @@ -219,7 +221,7 @@ edp_send(struct lldpd *global, #define CHECK_TLV_SIZE(x, name) \ do { if (tlv_len < (x)) { \ - LLOG_WARNX(name " EDP TLV too short received on %s",\ + log_warnx("edp", name " EDP TLV too short received on %s", \ hardware->h_ifname); \ goto malformed; \ } } while (0) @@ -245,13 +247,16 @@ edp_decode(struct lldpd *cfg, char *frame, int s, struct lldpd_port *oport; #endif + log_debug("edp", "decode EDP frame on port %s", + hardware->h_ifname); + if ((chassis = calloc(1, sizeof(struct lldpd_chassis))) == NULL) { - LLOG_WARN("failed to allocate remote chassis"); + log_warn("edp", "failed to allocate remote chassis"); return -1; } TAILQ_INIT(&chassis->c_mgmt); if ((port = calloc(1, sizeof(struct lldpd_port))) == NULL) { - LLOG_WARN("failed to allocate remote port"); + log_warn("edp", "failed to allocate remote port"); free(chassis); return -1; } @@ -264,26 +269,26 @@ edp_decode(struct lldpd *cfg, char *frame, int s, if (length < 2*ETH_ALEN + sizeof(u_int16_t) + 8 /* LLC */ + 10 + ETH_ALEN /* EDP header */) { - LLOG_WARNX("too short EDP frame received on %s", hardware->h_ifname); + log_warnx("edp", "too short EDP frame received on %s", hardware->h_ifname); goto malformed; } if (PEEK_CMP(edpaddr, sizeof(edpaddr)) != 0) { - LLOG_INFO("frame not targeted at EDP multicast address received on %s", + log_info("edp", "frame not targeted at EDP multicast address received on %s", hardware->h_ifname); goto malformed; } PEEK_DISCARD(ETH_ALEN); PEEK_DISCARD_UINT16; PEEK_DISCARD(6); /* LLC: DSAP + SSAP + control + org */ if (PEEK_UINT16 != LLC_PID_EDP) { - LLOG_DEBUG("incorrect LLC protocol ID received on %s", + log_debug("edp", "incorrect LLC protocol ID received on %s", hardware->h_ifname); goto malformed; } PEEK_SAVE(pos_edp); /* Save the start of EDP packet */ if (PEEK_UINT8 != 1) { - LLOG_WARNX("incorrect EDP version for frame received on %s", + log_warnx("edp", "incorrect EDP version for frame received on %s", hardware->h_ifname); goto malformed; } @@ -292,12 +297,12 @@ edp_decode(struct lldpd *cfg, char *frame, int s, PEEK_DISCARD_UINT16; /* Checksum */ PEEK_DISCARD_UINT16; /* Sequence */ if (PEEK_UINT16 != 0) { /* ID Type = 0 = MAC */ - LLOG_WARNX("incorrect device id type for frame received on %s", + log_warnx("edp", "incorrect device id type for frame received on %s", hardware->h_ifname); goto malformed; } if (edp_len > length + 10) { - LLOG_WARNX("incorrect size for EDP frame received on %s", + log_warnx("edp", "incorrect size for EDP frame received on %s", hardware->h_ifname); goto malformed; } @@ -305,27 +310,27 @@ edp_decode(struct lldpd *cfg, char *frame, int s, chassis->c_id_subtype = LLDP_CHASSISID_SUBTYPE_LLADDR; chassis->c_id_len = ETH_ALEN; if ((chassis->c_id = (char *)malloc(ETH_ALEN)) == NULL) { - LLOG_WARN("unable to allocate memory for chassis ID"); + log_warn("edp", "unable to allocate memory for chassis ID"); goto malformed; } PEEK_BYTES(chassis->c_id, ETH_ALEN); /* Let's check checksum */ if (frame_checksum(pos_edp, edp_len, 0) != 0) { - LLOG_WARNX("incorrect EDP checksum for frame received on %s", + log_warnx("edp", "incorrect EDP checksum for frame received on %s", hardware->h_ifname); goto malformed; } while (length && !gotend) { if (length < 4) { - LLOG_WARNX("EDP TLV header is too large for " + log_warnx("edp", "EDP TLV header is too large for " "frame received on %s", hardware->h_ifname); goto malformed; } if (PEEK_UINT8 != EDP_TLV_MARKER) { - LLOG_WARNX("incorrect marker starting EDP TLV header for frame " + log_warnx("edp", "incorrect marker starting EDP TLV header for frame " "received on %s", hardware->h_ifname); goto malformed; @@ -334,7 +339,7 @@ edp_decode(struct lldpd *cfg, char *frame, int s, tlv_len = PEEK_UINT16 - 4; PEEK_SAVE(tlv); if ((tlv_len < 0) || (tlv_len > length)) { - LLOG_DEBUG("incorrect size in EDP TLV header for frame " + log_debug("edp", "incorrect size in EDP TLV header for frame " "received on %s", hardware->h_ifname); /* Some poor old Extreme Summit are quite bogus */ @@ -348,14 +353,14 @@ edp_decode(struct lldpd *cfg, char *frame, int s, edp_slot = PEEK_UINT16; edp_port = PEEK_UINT16; if (asprintf(&port->p_id, "%d/%d", edp_slot + 1, edp_port + 1) == -1) { - LLOG_WARN("unable to allocate memory for " + log_warn("edp", "unable to allocate memory for " "port ID"); goto malformed; } port->p_id_len = strlen(port->p_id); if (asprintf(&port->p_descr, "Slot %d / Port %d", edp_slot + 1, edp_port + 1) == -1) { - LLOG_WARN("unable to allocate memory for " + log_warn("edp", "unable to allocate memory for " "port description"); goto malformed; } @@ -366,14 +371,14 @@ edp_decode(struct lldpd *cfg, char *frame, int s, "EDP enabled device, version %d.%d.%d.%d", version[0], version[1], version[2], version[3]) == -1) { - LLOG_WARN("unable to allocate memory for " + log_warn("edp", "unable to allocate memory for " "chassis description"); goto malformed; } break; case EDP_TLV_DISPLAY: if ((chassis->c_name = (char *)calloc(1, tlv_len + 1)) == NULL) { - LLOG_WARN("unable to allocate memory for chassis " + log_warn("edp", "unable to allocate memory for chassis " "name"); goto malformed; } @@ -382,13 +387,13 @@ edp_decode(struct lldpd *cfg, char *frame, int s, break; case EDP_TLV_NULL: if (tlv_len != 0) { - LLOG_WARNX("null tlv with incorrect size in frame " + log_warnx("edp", "null tlv with incorrect size in frame " "received on %s", hardware->h_ifname); goto malformed; } if (length) - LLOG_DEBUG("extra data after edp frame on %s", + log_debug("edp", "extra data after edp frame on %s", hardware->h_ifname); gotend = 1; break; @@ -397,7 +402,7 @@ edp_decode(struct lldpd *cfg, char *frame, int s, CHECK_TLV_SIZE(12, "VLAN"); if ((lvlan = (struct lldpd_vlan *)calloc(1, sizeof(struct lldpd_vlan))) == NULL) { - LLOG_WARN("unable to allocate vlan"); + log_warn("edp", "unable to allocate vlan"); goto malformed; } PEEK_DISCARD_UINT16; /* Flags + reserved */ @@ -407,7 +412,7 @@ edp_decode(struct lldpd *cfg, char *frame, int s, if ((lvlan->v_name = (char *)calloc(1, tlv_len + 1 - 12)) == NULL) { - LLOG_WARN("unable to allocate vlan name"); + log_warn("edp", "unable to allocate vlan name"); free(lvlan); goto malformed; } @@ -418,7 +423,7 @@ edp_decode(struct lldpd *cfg, char *frame, int s, sizeof(struct in_addr), 0); if (mgmt == NULL) { assert(errno == ENOMEM); - LLOG_WARN("Out of memory"); + log_warn("edp", "Out of memory"); goto malformed; } TAILQ_INSERT_TAIL(&chassis->c_mgmt, mgmt, m_entries); @@ -429,7 +434,7 @@ edp_decode(struct lldpd *cfg, char *frame, int s, gotvlans = 1; break; default: - LLOG_DEBUG("unknown EDP TLV type (%d) received on %s", + log_debug("edp", "unknown EDP TLV type (%d) received on %s", tlv_type, hardware->h_ifname); hardware->h_rx_unrecognized_cnt++; } @@ -486,7 +491,7 @@ edp_decode(struct lldpd *cfg, char *frame, int s, if (gotvlans) goto malformed; #endif - LLOG_WARNX("some mandatory tlv are missing for frame received on %s", + log_warnx("edp", "some mandatory tlv are missing for frame received on %s", hardware->h_ifname); goto malformed; } diff --git a/src/daemon/event.c b/src/daemon/event.c index 0c9e2c67..55402e16 100644 --- a/src/daemon/event.c +++ b/src/daemon/event.c @@ -100,7 +100,7 @@ levent_snmp_add_fd(struct lldpd *cfg, int fd) struct event_base *base = cfg->g_base; struct lldpd_events *snmpfd = calloc(1, sizeof(struct lldpd_events)); if (!snmpfd) { - LLOG_WARN("unable to allocate memory for new SNMP event"); + log_warn("event", "unable to allocate memory for new SNMP event"); return; } evutil_make_socket_nonblocking(fd); @@ -108,12 +108,12 @@ levent_snmp_add_fd(struct lldpd *cfg, int fd) EV_READ | EV_PERSIST, levent_snmp_read, cfg)) == NULL) { - LLOG_WARNX("unable to allocate a new SNMP event for FD %d", fd); + log_warnx("event", "unable to allocate a new SNMP event for FD %d", fd); free(snmpfd); return; } if (event_add(snmpfd->ev, NULL) == -1) { - LLOG_WARNX("unable to schedule new SNMP event for FD %d", fd); + log_warnx("event", "unable to schedule new SNMP event for FD %d", fd); event_free(snmpfd->ev); free(snmpfd); return; @@ -181,14 +181,14 @@ levent_snmp_update(struct lldpd *cfg) } current += added; if (howmany != current) { - LLOG_DEBUG("added %d events, removed %d events, total of %d events", + log_debug("event", "added %d events, removed %d events, total of %d events", added, removed, current); howmany = current; } /* If needed, handle timeout */ if (evtimer_add(cfg->g_snmp_timeout, block?NULL:&timeout) == -1) - LLOG_WARNX("unable to schedule timeout function for SNMP"); + log_warnx("event", "unable to schedule timeout function for SNMP"); } #endif /* USE_SNMP */ @@ -218,7 +218,7 @@ levent_ctl_send(struct lldpd_one_client *client, int type, void *data, size_t le bufferevent_disable(bev, EV_WRITE); if (bufferevent_write(bev, &hdr, sizeof(struct hmsg_header)) == -1 || (len > 0 && bufferevent_write(bev, data, len) == -1)) { - LLOG_WARNX("unable to create answer to client"); + log_warnx("event", "unable to create answer to client"); levent_ctl_free_client(client); return -1; } @@ -239,6 +239,7 @@ levent_ctl_notify(char *ifname, int state, struct lldpd_port *neighbor) ssize_t output_len = 0; /* Don't use TAILQ_FOREACH, the client may be deleted in case of errors. */ + log_debug("control", "notify clients of neighbor changes"); for (client = TAILQ_FIRST(&lldpd_clients); client; client = client_next) { @@ -259,7 +260,7 @@ levent_ctl_notify(char *ifname, int state, struct lldpd_port *neighbor) sizeof(backup_p_entries)); if (output_len <= 0) { - LLOG_WARNX("unable to serialize changed neighbor"); + log_warnx("event", "unable to serialize changed neighbor"); return; } } @@ -286,22 +287,23 @@ levent_ctl_recv(struct bufferevent *bev, void *ptr) struct hmsg_header hdr; void *data = NULL; + log_debug("control", "receive data on Unix socket"); if (buffer_len < sizeof(struct hmsg_header)) return; /* Not enough data yet */ if (evbuffer_copyout(buffer, &hdr, sizeof(struct hmsg_header)) != sizeof(struct hmsg_header)) { - LLOG_WARNX("not able to read header"); + log_warnx("event", "not able to read header"); return; } if (hdr.len > HMSG_MAX_SIZE) { - LLOG_WARNX("message received is too large"); + log_warnx("event", "message received is too large"); goto recv_error; } if (buffer_len < hdr.len + sizeof(struct hmsg_header)) return; /* Not enough data yet */ if (hdr.len > 0 && (data = malloc(hdr.len)) == NULL) { - LLOG_WARNX("not enough memory"); + log_warnx("event", "not enough memory"); goto recv_error; } evbuffer_drain(buffer, sizeof(struct hmsg_header)); @@ -327,11 +329,11 @@ levent_ctl_event(struct bufferevent *bev, short events, void *ptr) { struct lldpd_one_client *client = ptr; if (events & BEV_EVENT_ERROR) { - LLOG_WARNX("an error occurred with client: %s", + log_warnx("event", "an error occurred with client: %s", evutil_socket_error_to_string(EVUTIL_SOCKET_ERROR())); levent_ctl_free_client(client); } else if (events & BEV_EVENT_EOF) { - LLOG_DEBUG("client has been disconnected"); + log_debug("event", "client has been disconnected"); levent_ctl_free_client(client); } } @@ -344,13 +346,14 @@ levent_ctl_accept(evutil_socket_t fd, short what, void *arg) int s; (void)what; + log_debug("control", "accept a new connection"); if ((s = accept(fd, NULL, NULL)) == -1) { - LLOG_WARN("unable to accept connection from socket"); + log_warn("event", "unable to accept connection from socket"); return; } client = calloc(1, sizeof(struct lldpd_one_client)); if (!client) { - LLOG_WARNX("unable to allocate memory for new client"); + log_warnx("event", "unable to allocate memory for new client"); close(s); goto accept_failed; } @@ -358,7 +361,7 @@ levent_ctl_accept(evutil_socket_t fd, short what, void *arg) evutil_make_socket_nonblocking(s); if ((client->bev = bufferevent_socket_new(cfg->g_base, s, BEV_OPT_CLOSE_ON_FREE)) == NULL) { - LLOG_WARNX("unable to allocate a new buffer event for new client"); + log_warnx("event", "unable to allocate a new buffer event for new client"); close(s); goto accept_failed; } @@ -366,7 +369,7 @@ levent_ctl_accept(evutil_socket_t fd, short what, void *arg) levent_ctl_recv, NULL, levent_ctl_event, client); bufferevent_enable(client->bev, EV_READ | EV_WRITE); - LLOG_DEBUG("new client accepted"); + log_debug("event", "new client accepted"); TAILQ_INSERT_TAIL(&lldpd_clients, client, next); return; accept_failed: @@ -378,6 +381,7 @@ levent_dump(evutil_socket_t fd, short what, void *arg) { struct event_base *base = arg; (void)fd; (void)what; + log_debug("event", "dumping all events"); event_base_dump_events(base, stderr); } static void @@ -408,10 +412,11 @@ static void levent_init(struct lldpd *cfg) { /* Setup libevent */ + log_debug("event", "initialize libevent"); event_set_log_callback(levent_log_cb); if (!(cfg->g_base = event_base_new())) fatalx("unable to create a new libevent base"); - LLOG_INFO("libevent %s initialized with %s method", + log_info("event", "libevent %s initialized with %s method", event_get_version(), event_base_get_method(cfg->g_base)); @@ -430,8 +435,9 @@ levent_init(struct lldpd *cfg) TAILQ_INIT(levent_snmp_fds(cfg)); } #endif - + /* Setup loop that will run every 30 seconds. */ + log_debug("event", "register loop timer"); if (!(cfg->g_main_loop = event_new(cfg->g_base, -1, 0, levent_update_and_send, cfg))) @@ -439,6 +445,7 @@ levent_init(struct lldpd *cfg) levent_send_now(cfg); /* Setup unix socket */ + log_debug("event", "register Unix socket"); TAILQ_INIT(&lldpd_clients); evutil_make_socket_nonblocking(cfg->g_ctl); if ((cfg->g_ctl_event = event_new(cfg->g_base, cfg->g_ctl, @@ -447,6 +454,7 @@ levent_init(struct lldpd *cfg) event_add(cfg->g_ctl_event, NULL); /* Signals */ + log_debug("event", "register signals"); evsignal_add(evsignal_new(cfg->g_base, SIGUSR1, levent_dump, cfg->g_base), NULL); @@ -498,15 +506,18 @@ levent_hardware_recv(evutil_socket_t fd, short what, void *arg) struct lldpd_hardware *hardware = arg; struct lldpd *cfg = hardware->h_cfg; (void)what; + log_debug("event", "received something for %s", + hardware->h_ifname); lldpd_recv(cfg, hardware, fd); } void levent_hardware_init(struct lldpd_hardware *hardware) { + log_debug("event", "initialize events for %s", hardware->h_ifname); if ((hardware->h_recv = malloc(sizeof(struct ev_l))) == NULL) { - LLOG_WARNX("unable to allocate memory for %s", + log_warnx("event", "unable to allocate memory for %s", hardware->h_ifname); return; } @@ -521,7 +532,7 @@ levent_hardware_add_fd(struct lldpd_hardware *hardware, int fd) hfd = calloc(1, sizeof(struct lldpd_events)); if (!hfd) { - LLOG_WARNX("unable to allocate new event for %s", + log_warnx("event", "unable to allocate new event for %s", hardware->h_ifname); return; } @@ -530,13 +541,13 @@ levent_hardware_add_fd(struct lldpd_hardware *hardware, int fd) EV_READ | EV_PERSIST, levent_hardware_recv, hardware)) == NULL) { - LLOG_WARNX("unable to allocate a new event for %s", + log_warnx("event", "unable to allocate a new event for %s", hardware->h_ifname); free(hfd); return; } if (event_add(hfd->ev, NULL) == -1) { - LLOG_WARNX("unable to schedule new event for %s", + log_warnx("event", "unable to schedule new event for %s", hardware->h_ifname); event_free(hfd->ev); free(hfd); @@ -551,6 +562,7 @@ levent_hardware_release(struct lldpd_hardware *hardware) struct lldpd_events *ev, *ev_next; if (!hardware->h_recv) return; + log_debug("event", "release events for %s", hardware->h_ifname); for (ev = TAILQ_FIRST(levent_hardware_fds(hardware)); ev; ev = ev_next) { diff --git a/src/daemon/interfaces.c b/src/daemon/interfaces.c index 7441080a..c8533c0e 100644 --- a/src/daemon/interfaces.c +++ b/src/daemon/interfaces.c @@ -100,7 +100,7 @@ pattern_match(char *iface, char *list, int found) char *pattern; if ((interfaces = strdup(list)) == NULL) { - LLOG_WARNX("unable to allocate memory"); + log_warnx("interfaces", "unable to allocate memory"); return 0; } @@ -136,7 +136,7 @@ old_iface_is_bridge(struct lldpd *cfg, const char *name) return 0; for (i = 0; i < num; i++) { if (if_indextoname(ifindices[i], ifname) == NULL) - LLOG_INFO("unable to get name of interface %d", + log_info("interfaces", "unable to get name of interface %d", ifindices[i]); else if (strncmp(name, ifname, IFNAMSIZ) == 0) return 1; @@ -153,7 +153,7 @@ iface_is_bridge(struct lldpd *cfg, const char *name) if ((snprintf(path, SYSFS_PATH_MAX, SYSFS_CLASS_NET "%s/" SYSFS_BRIDGE_FDB, name)) >= SYSFS_PATH_MAX) - LLOG_WARNX("path truncated"); + log_warnx("interfaces", "path truncated"); if ((f = priv_open(path)) < 0) { return old_iface_is_bridge(cfg, name); } @@ -205,7 +205,7 @@ iface_is_bridged_to(struct lldpd *cfg, const char *slave, const char *master) if (snprintf(path, SYSFS_PATH_MAX, SYSFS_CLASS_NET "%s/" SYSFS_BRIDGE_PORT_SUBDIR "/%s/port_no", master, slave) >= SYSFS_PATH_MAX) - LLOG_WARNX("path truncated"); + log_warnx("interfaces", "path truncated"); if ((f = priv_open(path)) < 0) { return old_iface_is_bridged_to(cfg, slave, master); } @@ -225,7 +225,7 @@ iface_is_vlan(struct lldpd *cfg, const char *name) ifv.cmd = GET_VLAN_REALDEV_NAME_CMD; if ((strlcpy(ifv.device1, name, sizeof(ifv.device1))) >= sizeof(ifv.device1)) - LLOG_WARNX("device name truncated"); + log_warnx("interfaces", "device name truncated"); if (ioctl(cfg->g_sock, SIOCGIFVLAN, &ifv) >= 0) return 1; return 0; @@ -291,7 +291,7 @@ iface_is_enslaved(struct lldpd *cfg, const char *name) int master; if (getifaddrs(&ifap) != 0) { - LLOG_WARN("unable to get interface list"); + log_warn("interfaces", "unable to get interface list"); return -1; } for (ifa = ifap; ifa != NULL; ifa = ifa->ifa_next) { @@ -316,34 +316,38 @@ iface_get_permanent_mac(struct lldpd *cfg, struct lldpd_hardware *hardware) char bond[IFNAMSIZ]; char path[SYSFS_PATH_MAX]; char line[100]; + + log_debug("interfaces", "get MAC address for %s", + hardware->h_ifname); + if ((master = iface_is_enslaved(cfg, hardware->h_ifname)) == -1) return; /* We have a bond, we need to query it to get real MAC addresses */ if ((if_indextoname(master, bond)) == NULL) { - LLOG_WARNX("unable to get bond name"); + log_warnx("interfaces", "unable to get bond name"); return; } if (snprintf(path, SYSFS_PATH_MAX, "/proc/net/bonding/%s", bond) >= SYSFS_PATH_MAX) { - LLOG_WARNX("path truncated"); + log_warnx("interfaces", "path truncated"); return; } if ((f = priv_open(path)) < 0) { if (snprintf(path, SYSFS_PATH_MAX, "/proc/self/net/bonding/%s", bond) >= SYSFS_PATH_MAX) { - LLOG_WARNX("path truncated"); + log_warnx("interfaces", "path truncated"); return; } f = priv_open(path); } if (f < 0) { - LLOG_WARNX("unable to find %s in /proc/net/bonding or /proc/self/net/bonding", + log_warnx("interfaces", "unable to find %s in /proc/net/bonding or /proc/self/net/bonding", bond); return; } if ((netbond = fdopen(f, "r")) == NULL) { - LLOG_WARN("unable to read stream from %s", path); + log_warn("interfaces", "unable to read stream from %s", path); close(f); return; } @@ -375,7 +379,7 @@ iface_get_permanent_mac(struct lldpd *cfg, struct lldpd_hardware *hardware) &mac[0], &mac[1], &mac[2], &mac[3], &mac[4], &mac[5]) != ETHER_ADDR_LEN) { - LLOG_WARN("unable to parse %s", + log_warn("interfaces", "unable to parse %s", line + strlen(hwaddr)); fclose(netbond); return; @@ -388,7 +392,7 @@ iface_get_permanent_mac(struct lldpd *cfg, struct lldpd_hardware *hardware) break; } } - LLOG_WARNX("unable to find real mac address for %s", + log_warnx("interfaces", "unable to find real mac address for %s", bond); fclose(netbond); } @@ -411,32 +415,51 @@ iface_minimal_checks(struct lldpd *cfg, struct ifaddrs *ifa) int is_bridge = iface_is_bridge(cfg, ifa->ifa_name); + log_debug("interfaces", "minimal checks for %s", ifa->ifa_name); + if (!(LOCAL_CHASSIS(cfg)->c_cap_enabled & LLDP_CAP_BRIDGE) && is_bridge) { + log_debug("interfaces", "skip %s: is a bridge", + ifa->ifa_name); LOCAL_CHASSIS(cfg)->c_cap_enabled |= LLDP_CAP_BRIDGE; return 0; } - + if (!(LOCAL_CHASSIS(cfg)->c_cap_enabled & LLDP_CAP_WLAN) && iface_is_wireless(cfg, ifa->ifa_name)) LOCAL_CHASSIS(cfg)->c_cap_enabled |= LLDP_CAP_WLAN; - + /* First, check if this interface has already been handled */ - if (!ifa->ifa_flags) + if (!ifa->ifa_flags) { + log_debug("interfaces", "skip %s: already been handled", + ifa->ifa_name); return 0; + } - if (ifa->ifa_addr == NULL || - ifa->ifa_addr->sa_family != PF_PACKET) - return 0; + if (ifa->ifa_addr == NULL) { + if (ifa->ifa_addr->sa_family != PF_PACKET) { + log_debug("interfaces", "skip %s: address family is %d and not PF_PACKET", + ifa->ifa_name, ifa->ifa_addr->sa_family); + return 0; + } + log_debug("interfaces", "skip %s: no address", + ifa->ifa_name); + } memcpy(&sdl, ifa->ifa_addr, sizeof(struct sockaddr_ll)); - if (sdl.sll_hatype != ARPHRD_ETHER || !sdl.sll_halen) + if (sdl.sll_hatype != ARPHRD_ETHER || !sdl.sll_halen) { + log_debug("interfaces", "skip %s: not an Ethernet device", + ifa->ifa_name); return 0; + } /* We request that the interface is able to do either multicast * or broadcast to be able to send discovery frames. */ - if (!(ifa->ifa_flags & (IFF_MULTICAST|IFF_BROADCAST))) + if (!(ifa->ifa_flags & (IFF_MULTICAST|IFF_BROADCAST))) { + log_debug("interfaces", "skip %s: not able to do multicast nor broadcast", + ifa->ifa_name); return 0; + } /* Check if the driver is whitelisted */ memset(&ifr, 0, sizeof(ifr)); @@ -448,24 +471,44 @@ iface_minimal_checks(struct lldpd *cfg, struct ifaddrs *ifa) for (rif = regular_interfaces; *rif; rif++) { if (strcmp(ethc.driver, *rif) == 0) { /* White listed! */ + log_debug("interfaces", "accept %s: whitelisted", + ifa->ifa_name); return 1; } } } + log_debug("interfaces", "keep %s: not whitelisted", + ifa->ifa_name); /* Check queue len. If no queue, this usually means that this is not a "real" interface. */ memset(&ifr, 0, sizeof(ifr)); strcpy(ifr.ifr_name, ifa->ifa_name); - if ((ioctl(cfg->g_sock, SIOCGIFTXQLEN, &ifr) < 0) || !ifr.ifr_qlen) + if ((ioctl(cfg->g_sock, SIOCGIFTXQLEN, &ifr) < 0) || !ifr.ifr_qlen) { + log_debug("interfaces", "skip %s: no queue", + ifa->ifa_name); return 0; + } /* Don't handle bond and VLAN, nor bridge */ - if ((iface_is_vlan(cfg, ifa->ifa_name)) || - (iface_is_bond(cfg, ifa->ifa_name)) || - is_bridge) + if (iface_is_vlan(cfg, ifa->ifa_name)) { + log_debug("interfaces", "skip %s: is a VLAN", + ifa->ifa_name); + return 0; + } + if (iface_is_bond(cfg, ifa->ifa_name)) { + log_debug("interfaces", "skip %s: is a bond", + ifa->ifa_name); return 0; + } + if (is_bridge) { + log_debug("interfaces", "skip %s: is a bridge", + ifa->ifa_name); + return 0; + } + log_debug("interface", "%s passes the minimal checks", + ifa->ifa_name); return 1; } @@ -473,13 +516,15 @@ static int iface_set_filter(const char *name, int fd) { struct sock_fprog prog; + log_debug("interfaces", "set BPF filter for %s", name); + memset(&prog, 0, sizeof(struct sock_fprog)); prog.filter = lldpd_filter_f; prog.len = sizeof(lldpd_filter_f) / sizeof(struct sock_filter); if (setsockopt(fd, SOL_SOCKET, SO_ATTACH_FILTER, &prog, sizeof(prog)) < 0) { - LLOG_WARN("unable to change filter for %s", name); + log_info("interfaces", "unable to change filter for %s", name); return ENETDOWN; } return 0; @@ -506,15 +551,17 @@ iface_port_name_desc(struct lldpd_hardware *hardware) if ((snprintf(path, SYSFS_PATH_MAX, SYSFS_CLASS_NET "%s/ifalias", hardware->h_ifname)) >= SYSFS_PATH_MAX) - LLOG_WARNX("path truncated"); + log_warnx("interfaces", "path truncated"); memset(buffer, 0, sizeof(buffer)); if (((f = priv_open(path)) < 0) || (read(f, buffer, sizeof(buffer)-1) < 1)) { /* Case 2: MAC address and port name */ close(f); + log_debug("interfaces", "use ifname and MAC address for %s", + hardware->h_ifname); port->p_id_subtype = LLDP_PORTID_SUBTYPE_LLADDR; if ((port->p_id = calloc(1, sizeof(hardware->h_lladdr))) == NULL) - fatal(NULL); + fatal("interfaces", NULL); memcpy(port->p_id, hardware->h_lladdr, sizeof(hardware->h_lladdr)); port->p_id_len = sizeof(hardware->h_lladdr); @@ -523,11 +570,13 @@ iface_port_name_desc(struct lldpd_hardware *hardware) } /* Case 1: port name and port description */ close(f); + log_debug("interfaces", "use ifname and ifalias for %s", + hardware->h_ifname); port->p_id_subtype = LLDP_PORTID_SUBTYPE_IFNAME; port->p_id_len = strlen(hardware->h_ifname); if ((port->p_id = calloc(1, port->p_id_len)) == NULL) - fatal(NULL); + fatal("interfaces", NULL); memcpy(port->p_id, hardware->h_ifname, port->p_id_len); if (buffer[strlen(buffer) - 1] == '\n') buffer[strlen(buffer) - 1] = '\0'; @@ -555,6 +604,8 @@ iface_macphy(struct lldpd_hardware *hardware) {ADVERTISED_2500baseX_Full, LLDP_DOT3_LINK_AUTONEG_OTHER}, {0,0}}; + log_debug("interfaces", "ask ethtool for the appropriate MAC/PHY for %s", + hardware->h_ifname); if (priv_ethtool(hardware->h_ifname, ðc) == 0) { port->p_macphy.autoneg_support = (ethc.supported & SUPPORTED_Autoneg) ? 1 : 0; port->p_macphy.autoneg_enabled = (ethc.autoneg == AUTONEG_DISABLE) ? 0 : 1; @@ -608,7 +659,7 @@ iface_mtu(struct lldpd *cfg, struct lldpd_hardware *hardware) memset(&ifr, 0, sizeof(ifr)); strlcpy(ifr.ifr_name, hardware->h_ifname, sizeof(ifr.ifr_name)); if (ioctl(cfg->g_sock, SIOCGIFMTU, (char*)&ifr) == -1) { - LLOG_WARN("unable to get MTU of %s, using 1500", hardware->h_ifname); + log_warn("interfaces", "unable to get MTU of %s, using 1500", hardware->h_ifname); hardware->h_mtu = 1500; } else hardware->h_mtu = ifr.ifr_mtu; @@ -625,7 +676,7 @@ iface_multicast(struct lldpd *cfg, const char *name, int remove) cfg->g_protocols[i].mac, !remove)) != 0) { errno = rc; if (errno != ENOENT) - LLOG_INFO("unable to %s %s address to multicast filter for %s", + log_info("interfaces", "unable to %s %s address to multicast filter for %s", (remove)?"delete":"add", cfg->g_protocols[i].name, name); @@ -638,6 +689,8 @@ iface_eth_init(struct lldpd *cfg, struct lldpd_hardware *hardware) { int fd, status; + log_debug("interfaces", "initialize ethernet device %s", + hardware->h_ifname); if ((fd = priv_iface_init(hardware->h_ifname)) == -1) return -1; hardware->h_sendfd = fd; /* Send */ @@ -651,7 +704,7 @@ iface_eth_init(struct lldpd *cfg, struct lldpd_hardware *hardware) iface_multicast(cfg, hardware->h_ifname, 0); levent_hardware_add_fd(hardware, fd); /* Receive */ - LLOG_DEBUG("interface %s initialized (fd=%d)", hardware->h_ifname, + log_debug("interfaces", "interface %s initialized (fd=%d)", hardware->h_ifname, fd); return 0; } @@ -660,6 +713,8 @@ static int iface_eth_send(struct lldpd *cfg, struct lldpd_hardware *hardware, char *buffer, size_t size) { + log_debug("interfaces", "send PDU to ethernet device %s", + hardware->h_ifname); return write(hardware->h_sendfd, buffer, size); } @@ -672,13 +727,15 @@ iface_eth_recv(struct lldpd *cfg, struct lldpd_hardware *hardware, struct sockaddr_ll from; socklen_t fromlen; + log_debug("interfaces", "receive PDU from ethernet device %s", + hardware->h_ifname); fromlen = sizeof(from); if ((n = recvfrom(fd, buffer, size, 0, (struct sockaddr *)&from, &fromlen)) == -1) { - LLOG_WARN("error while receiving frame on %s", + log_warn("interfaces", "error while receiving frame on %s", hardware->h_ifname); hardware->h_rx_discarded_cnt++; return -1; @@ -691,6 +748,8 @@ iface_eth_recv(struct lldpd *cfg, struct lldpd_hardware *hardware, static int iface_eth_close(struct lldpd *cfg, struct lldpd_hardware *hardware) { + log_debug("interfaces", "close ethernet device %s", + hardware->h_ifname); iface_multicast(cfg, hardware->h_ifname, 1); return 0; } @@ -705,18 +764,20 @@ lldpd_ifh_eth(struct lldpd *cfg, struct ifaddrs *ifap) if (!iface_minimal_checks(cfg, ifa)) continue; + log_debug("interfaces", "%s is an acceptable ethernet device", + ifa->ifa_name); if ((hardware = lldpd_get_hardware(cfg, ifa->ifa_name, if_nametoindex(ifa->ifa_name), ð_ops)) == NULL) { if ((hardware = lldpd_alloc_hardware(cfg, ifa->ifa_name)) == NULL) { - LLOG_WARNX("Unable to allocate space for %s", + log_warnx("interfaces", "Unable to allocate space for %s", ifa->ifa_name); continue; } if (iface_eth_init(cfg, hardware) != 0) { - LLOG_WARN("unable to initialize %s", hardware->h_ifname); + log_warn("interfaces", "unable to initialize %s", hardware->h_ifname); lldpd_hardware_cleanup(cfg, hardware); continue; } @@ -761,7 +822,7 @@ lldpd_ifh_whitelist(struct lldpd *cfg, struct ifaddrs *ifap) if (ifa->ifa_flags == 0) continue; /* Already handled by someone else */ if (!pattern_match(ifa->ifa_name, cfg->g_config.c_iface_pattern, 0)) { /* This interface was not found. We flag it. */ - LLOG_DEBUG("blacklist %s", ifa->ifa_name); + log_debug("interfaces", "blacklist %s", ifa->ifa_name); ifa->ifa_flags = 0; } } @@ -776,6 +837,9 @@ iface_bond_init(struct lldpd *cfg, struct lldpd_hardware *hardware) if (!mastername) return -1; + log_debug("interfaces", "initialize bonded device %s", + hardware->h_ifname); + /* First, we get a socket to the raw physical interface */ if ((fd = priv_iface_init(hardware->h_ifname)) == -1) return -1; @@ -802,7 +866,7 @@ iface_bond_init(struct lldpd *cfg, struct lldpd_hardware *hardware) * 2.6.24). */ if (setsockopt(fd, SOL_PACKET, PACKET_ORIGDEV, &un, sizeof(un)) == -1) { - LLOG_DEBUG("[priv]: unable to setsockopt for master bonding device of %s. " + log_debug("interfaces", "unable to setsockopt for master bonding device of %s. " "You will get inaccurate results", hardware->h_ifname); } @@ -810,7 +874,7 @@ iface_bond_init(struct lldpd *cfg, struct lldpd_hardware *hardware) levent_hardware_add_fd(hardware, hardware->h_sendfd); levent_hardware_add_fd(hardware, fd); - LLOG_DEBUG("interface %s initialized (fd=%d,master=%s[%d])", + log_debug("interfaces", "interface %s initialized (fd=%d,master=%s[%d])", hardware->h_ifname, hardware->h_sendfd, mastername, fd); @@ -826,15 +890,17 @@ iface_bond_send(struct lldpd *cfg, struct lldpd_hardware *hardware, * an inactive slave. */ char *master = (char*)hardware->h_data; int active; + log_debug("interfaces", "send PDU to bonded device %s", + hardware->h_ifname); if (!iface_is_bond_slave(cfg, hardware->h_ifname, master, &active)) { - LLOG_WARNX("%s seems to not be enslaved anymore?", + log_warnx("interfaces", "%s seems to not be enslaved anymore?", hardware->h_ifname); return 0; } if (active) { /* We need to modify the source MAC address */ if (size < 2 * ETH_ALEN) { - LLOG_WARNX("packet to send on %s is too small!", + log_warnx("interfaces", "packet to send on %s is too small!", hardware->h_ifname); return 0; } @@ -852,11 +918,13 @@ iface_bond_recv(struct lldpd *cfg, struct lldpd_hardware *hardware, struct sockaddr_ll from; socklen_t fromlen; + log_debug("interfaces", "receive PDU from bonded device %s", + hardware->h_ifname); fromlen = sizeof(from); if ((n = recvfrom(fd, buffer, size, 0, (struct sockaddr *)&from, &fromlen)) == -1) { - LLOG_WARN("error while receiving frame on %s", + log_warn("interfaces", "error while receiving frame on %s", hardware->h_ifname); hardware->h_rx_discarded_cnt++; return -1; @@ -880,6 +948,8 @@ iface_bond_recv(struct lldpd *cfg, struct lldpd_hardware *hardware, static int iface_bond_close(struct lldpd *cfg, struct lldpd_hardware *hardware) { + log_debug("interfaces", "closing bonded device %s", + hardware->h_ifname); iface_multicast(cfg, hardware->h_ifname, 1); iface_multicast(cfg, (char*)hardware->h_data, 1); free(hardware->h_data); @@ -898,20 +968,22 @@ lldpd_ifh_bond(struct lldpd *cfg, struct ifaddrs *ifap) if ((master = iface_is_enslaved(cfg, ifa->ifa_name)) == -1) continue; + log_debug("interface", "%s is an acceptable bonded device (master=%d)", + ifa->ifa_name, master); if ((hardware = lldpd_get_hardware(cfg, ifa->ifa_name, if_nametoindex(ifa->ifa_name), &bond_ops)) == NULL) { if ((hardware = lldpd_alloc_hardware(cfg, ifa->ifa_name)) == NULL) { - LLOG_WARNX("Unable to allocate space for %s", + log_warnx("interfaces", "Unable to allocate space for %s", ifa->ifa_name); continue; } hardware->h_data = (char *)calloc(1, IFNAMSIZ); if_indextoname(master, hardware->h_data); if (iface_bond_init(cfg, hardware) != 0) { - LLOG_WARN("unable to initialize %s", + log_warn("interfaces", "unable to initialize %s", hardware->h_ifname); lldpd_hardware_cleanup(cfg, hardware); continue; @@ -974,6 +1046,9 @@ iface_append_vlan(struct lldpd *cfg, return; } vlan->v_vid = ifv.u.VID; + log_debug("interfaces", "append VLAN %s for %s", + vlan->v_name, + hardware->h_ifname); TAILQ_INSERT_TAIL(&port->p_vlans, vlan, v_entries); } @@ -992,6 +1067,8 @@ lldpd_ifh_vlan(struct lldpd *cfg, struct ifaddrs *ifap) /* We need to find the physical interfaces of this vlan, through bonds and bridges. */ + log_debug("interfaces", "search physical interface for VLAN interface %s", + ifa->ifa_name); memset(&ifv, 0, sizeof(ifv)); ifv.cmd = GET_VLAN_REALDEV_NAME_CMD; strlcpy(ifv.device1, ifa->ifa_name, sizeof(ifv.device1)); @@ -1010,17 +1087,27 @@ lldpd_ifh_vlan(struct lldpd *cfg, struct ifaddrs *ifap) h_entries) if (iface_is_bond_slave(cfg, hardware->h_ifname, - ifv.u.device2, NULL)) + ifv.u.device2, NULL)) { + log_debug("interfaces", + "VLAN %s on bond %s", + hardware->h_ifname, + ifv.u.device2); iface_append_vlan(cfg, hardware, ifa); + } } else if (iface_is_bridge(cfg, ifv.u.device2)) { TAILQ_FOREACH(hardware, &cfg->g_hardware, h_entries) if (iface_is_bridged_to(cfg, hardware->h_ifname, - ifv.u.device2)) + ifv.u.device2)) { + log_debug("interfaces", + "VLAN %s on bridge %s", + hardware->h_ifname, + ifv.u.device2); iface_append_vlan(cfg, hardware, ifa); + } } } else iface_append_vlan(cfg, hardware, ifa); @@ -1102,7 +1189,7 @@ lldpd_ifh_mgmt(struct lldpd *cfg, struct ifaddrs *ifap) } if (inet_ntop(lldpd_af(af), sin_addr_ptr, addrstrbuf, sizeof(addrstrbuf)) == NULL) { - LLOG_WARN("unable to convert IP address to a string"); + log_warn("interfaces", "unable to convert IP address to a string"); continue; } if (cfg->g_config.c_mgmt_pattern == NULL || @@ -1111,9 +1198,10 @@ lldpd_ifh_mgmt(struct lldpd *cfg, struct ifaddrs *ifap) if_nametoindex(ifa->ifa_name)); if (mgmt == NULL) { assert(errno == ENOMEM); /* anything else is a bug */ - LLOG_WARN("out of memory error"); + log_warn("interfaces", "out of memory error"); return; } + log_debug("interfaces", "add management address %s", addrstrbuf); TAILQ_INSERT_TAIL(&LOCAL_CHASSIS(cfg)->c_mgmt, mgmt, m_entries); /* Don't take additional address if the pattern is all negative. */ @@ -1151,7 +1239,7 @@ lldpd_ifh_chassis(struct lldpd *cfg, struct ifaddrs *ifap) name = malloc(sizeof(hardware->h_lladdr)); if (!name) { - LLOG_WARN("Not enough memory for chassis ID"); + log_warn("interfaces", "not enough memory for chassis ID"); return; } free(LOCAL_CHASSIS(cfg)->c_id); diff --git a/src/daemon/lldp.c b/src/daemon/lldp.c index f7162d89..0b979cb6 100644 --- a/src/daemon/lldp.c +++ b/src/daemon/lldp.c @@ -81,6 +81,9 @@ lldp_send(struct lldpd *global, const u_int8_t med[] = LLDP_TLV_ORG_MED; #endif + log_debug("lldp", "send LLDP PDU to %s", + hardware->h_ifname); + port = &hardware->h_lport; chassis = port->p_chassis; length = hardware->h_mtu; @@ -426,7 +429,7 @@ lldp_send(struct lldpd *global, if (hardware->h_ops->send(global, hardware, (char *)packet, pos - packet) == -1) { - LLOG_WARN("unable to send packet on real device for %s", + log_warn("lldp", "unable to send packet on real device for %s", hardware->h_ifname); free(packet); return ENETDOWN; @@ -460,7 +463,7 @@ toobig: #define CHECK_TLV_SIZE(x, name) \ do { if (tlv_size < (x)) { \ - LLOG_WARNX(name " TLV too short received on %s",\ + log_warnx("lldp", name " TLV too short received on %s", \ hardware->h_ifname); \ goto malformed; \ } } while (0) @@ -493,13 +496,16 @@ lldp_decode(struct lldpd *cfg, char *frame, int s, u_int8_t addr_family, addr_length, *addr_ptr, iface_subtype; u_int32_t iface_number, iface; + log_debug("lldp", "receive LLDP PDU on %s", + hardware->h_ifname); + if ((chassis = calloc(1, sizeof(struct lldpd_chassis))) == NULL) { - LLOG_WARN("failed to allocate remote chassis"); + log_warn("lldp", "failed to allocate remote chassis"); return -1; } TAILQ_INIT(&chassis->c_mgmt); if ((port = calloc(1, sizeof(struct lldpd_port))) == NULL) { - LLOG_WARN("failed to allocate remote port"); + log_warn("lldp", "failed to allocate remote port"); free(chassis); return -1; } @@ -513,24 +519,24 @@ lldp_decode(struct lldpd *cfg, char *frame, int s, pos = (u_int8_t*)frame; if (length < 2*ETH_ALEN + sizeof(u_int16_t)) { - LLOG_WARNX("too short frame received on %s", hardware->h_ifname); + log_warnx("lldp", "too short frame received on %s", hardware->h_ifname); goto malformed; } if (PEEK_CMP(lldpaddr, ETH_ALEN) != 0) { - LLOG_INFO("frame not targeted at LLDP multicast address received on %s", + log_info("lldp", "frame not targeted at LLDP multicast address received on %s", hardware->h_ifname); goto malformed; } PEEK_DISCARD(ETH_ALEN); /* Skip source address */ if (PEEK_UINT16 != ETHERTYPE_LLDP) { - LLOG_INFO("non LLDP frame received on %s", + log_info("lldp", "non LLDP frame received on %s", hardware->h_ifname); goto malformed; } while (length && (!gotend)) { if (length < 2) { - LLOG_WARNX("tlv header too short received on %s", + log_warnx("lldp", "tlv header too short received on %s", hardware->h_ifname); goto malformed; } @@ -539,19 +545,19 @@ lldp_decode(struct lldpd *cfg, char *frame, int s, tlv_size = tlv_size & 0x1ff; PEEK_SAVE(tlv); if (length < tlv_size) { - LLOG_WARNX("frame too short for tlv received on %s", + log_warnx("lldp", "frame too short for tlv received on %s", hardware->h_ifname); goto malformed; } switch (tlv_type) { case LLDP_TLV_END: if (tlv_size != 0) { - LLOG_WARNX("lldp end received with size not null on %s", + log_warnx("lldp", "lldp end received with size not null on %s", hardware->h_ifname); goto malformed; } if (length) - LLOG_DEBUG("extra data after lldp end on %s", + log_debug("lldp", "extra data after lldp end on %s", hardware->h_ifname); gotend = 1; break; @@ -560,12 +566,12 @@ lldp_decode(struct lldpd *cfg, char *frame, int s, CHECK_TLV_SIZE(2, "Port Id"); tlv_subtype = PEEK_UINT8; if ((tlv_subtype == 0) || (tlv_subtype > 7)) { - LLOG_WARNX("unknown subtype for tlv id received on %s", + log_warnx("lldp", "unknown subtype for tlv id received on %s", hardware->h_ifname); goto malformed; } if ((b = (char *)calloc(1, tlv_size - 1)) == NULL) { - LLOG_WARN("unable to allocate memory for id tlv " + log_warn("lldp", "unable to allocate memory for id tlv " "received on %s", hardware->h_ifname); goto malformed; @@ -589,12 +595,12 @@ lldp_decode(struct lldpd *cfg, char *frame, int s, case LLDP_TLV_SYSTEM_NAME: case LLDP_TLV_SYSTEM_DESCR: if (tlv_size < 1) { - LLOG_DEBUG("empty tlv received on %s", + log_debug("lldp", "empty tlv received on %s", hardware->h_ifname); break; } if ((b = (char *)calloc(1, tlv_size + 1)) == NULL) { - LLOG_WARN("unable to allocate memory for string tlv " + log_warn("lldp", "unable to allocate memory for string tlv " "received on %s", hardware->h_ifname); goto malformed; @@ -633,7 +639,7 @@ lldp_decode(struct lldpd *cfg, char *frame, int s, mgmt = lldpd_alloc_mgmt(af, addr_ptr, addr_length, iface); if (mgmt == NULL) { assert(errno == ENOMEM); - LLOG_WARN("unable to allocate memory " + log_warn("lldp", "unable to allocate memory " "for management address"); goto malformed; } @@ -653,7 +659,7 @@ lldp_decode(struct lldpd *cfg, char *frame, int s, CHECK_TLV_SIZE(7, "VLAN"); if ((vlan = (struct lldpd_vlan *)calloc(1, sizeof(struct lldpd_vlan))) == NULL) { - LLOG_WARN("unable to alloc vlan " + log_warn("lldp", "unable to alloc vlan " "structure for " "tlv received on %s", hardware->h_ifname); @@ -664,7 +670,7 @@ lldp_decode(struct lldpd *cfg, char *frame, int s, CHECK_TLV_SIZE(7 + vlan_len, "VLAN"); if ((vlan->v_name = (char *)calloc(1, vlan_len + 1)) == NULL) { - LLOG_WARN("unable to alloc vlan name for " + log_warn("lldp", "unable to alloc vlan name for " "tlv received on %s", hardware->h_ifname); goto malformed; @@ -689,7 +695,7 @@ lldp_decode(struct lldpd *cfg, char *frame, int s, /* if PPVID > 4096 - bad and discard */ if ((ppvid = (struct lldpd_ppvid *)calloc(1, sizeof(struct lldpd_ppvid))) == NULL) { - LLOG_WARN("unable to alloc ppvid " + log_warn("lldp", "unable to alloc ppvid " "structure for " "tlv received on %s", hardware->h_ifname); @@ -708,7 +714,7 @@ lldp_decode(struct lldpd *cfg, char *frame, int s, CHECK_TLV_SIZE(5, "PI"); if ((pi = (struct lldpd_pi *)calloc(1, sizeof(struct lldpd_pi))) == NULL) { - LLOG_WARN("unable to alloc PI " + log_warn("lldp", "unable to alloc PI " "structure for " "tlv received on %s", hardware->h_ifname); @@ -718,7 +724,7 @@ lldp_decode(struct lldpd *cfg, char *frame, int s, CHECK_TLV_SIZE(1 + pi->p_pi_len, "PI"); if ((pi->p_pi = (char *)calloc(1, pi->p_pi_len)) == NULL) { - LLOG_WARN("unable to alloc pid name for " + log_warn("lldp", "unable to alloc pid name for " "tlv received on %s", hardware->h_ifname); goto malformed; @@ -816,7 +822,7 @@ lldp_decode(struct lldpd *cfg, char *frame, int s, policy = PEEK_UINT32; if (((policy >> 24) < 1) || ((policy >> 24) > LLDP_MED_APPTYPE_LAST)) { - LLOG_INFO("unknown policy field %d " + log_info("lldp", "unknown policy field %d " "received on %s", policy, hardware->h_ifname); @@ -842,14 +848,14 @@ lldp_decode(struct lldpd *cfg, char *frame, int s, loctype = PEEK_UINT8; if ((loctype < 1) || (loctype > LLDP_MED_LOCFORMAT_LAST)) { - LLOG_INFO("unknown location type " + log_info("lldp", "unknown location type " "received on %s", hardware->h_ifname); break; } if ((port->p_med_location[loctype - 1].data = (char*)malloc(tlv_size - 5)) == NULL) { - LLOG_WARN("unable to allocate memory " + log_warn("lldp", "unable to allocate memory " "for LLDP-MED location for " "frame received on %s", hardware->h_ifname); @@ -936,7 +942,7 @@ lldp_decode(struct lldpd *cfg, char *frame, int s, else { if ((b = (char*)malloc(tlv_size - 3)) == NULL) { - LLOG_WARN("unable to allocate " + log_warn("lldp", "unable to allocate " "memory for LLDP-MED " "inventory for frame " "received on %s", @@ -969,7 +975,7 @@ lldp_decode(struct lldpd *cfg, char *frame, int s, chassis->c_med_asset = b; break; default: - LLOG_WARNX("should not be there!"); + log_warnx("lldp", "should not be there!"); free(b); break; } @@ -982,18 +988,18 @@ lldp_decode(struct lldpd *cfg, char *frame, int s, } #endif /* ENABLE_LLDPMED */ } else { - LLOG_INFO("unknown org tlv received on %s", + log_info("lldp", "unknown org tlv received on %s", hardware->h_ifname); hardware->h_rx_unrecognized_cnt++; } break; default: - LLOG_WARNX("unknown tlv (%d) received on %s", + log_warnx("lldp", "unknown tlv (%d) received on %s", tlv_type, hardware->h_ifname); goto malformed; } if (pos > tlv + tlv_size) { - LLOG_WARNX("BUG: already past TLV!"); + log_warnx("lldp", "BUG: already past TLV!"); goto malformed; } PEEK_DISCARD(tlv + tlv_size - pos); @@ -1004,28 +1010,28 @@ lldp_decode(struct lldpd *cfg, char *frame, int s, (port->p_id == NULL) || (chassis->c_ttl == 0) || (gotend == 0)) { - LLOG_WARNX("some mandatory tlv are missing for frame received on %s", + log_warnx("lldp", "some mandatory tlv are missing for frame received on %s", hardware->h_ifname); goto malformed; } #define NOTRECEIVED "Not received" if (chassis->c_name == NULL) { if ((chassis->c_name = (char *)calloc(1, strlen(NOTRECEIVED) + 1)) == NULL) { - LLOG_WARNX("unable to allocate null chassis name"); + log_warnx("lldp", "unable to allocate null chassis name"); goto malformed; } memcpy(chassis->c_name, NOTRECEIVED, strlen(NOTRECEIVED)); } if (chassis->c_descr == NULL) { if ((chassis->c_descr = (char *)calloc(1, strlen(NOTRECEIVED) + 1)) == NULL) { - LLOG_WARNX("unable to allocate null chassis description"); + log_warnx("lldp", "unable to allocate null chassis description"); goto malformed; } memcpy(chassis->c_descr, NOTRECEIVED, strlen(NOTRECEIVED)); } if (port->p_descr == NULL) { if ((port->p_descr = (char *)calloc(1, strlen(NOTRECEIVED) + 1)) == NULL) { - LLOG_WARNX("unable to allocate null port description"); + log_warnx("lldp", "unable to allocate null port description"); goto malformed; } memcpy(port->p_descr, NOTRECEIVED, strlen(NOTRECEIVED)); diff --git a/src/daemon/lldpd.c b/src/daemon/lldpd.c index 49a8b103..8a22b4eb 100644 --- a/src/daemon/lldpd.c +++ b/src/daemon/lldpd.c @@ -142,6 +142,8 @@ lldpd_alloc_hardware(struct lldpd *cfg, char *name) { struct lldpd_hardware *hardware; + log_debug("alloc", "allocate a new local port (%s)", name); + if ((hardware = (struct lldpd_hardware *) calloc(1, sizeof(struct lldpd_hardware))) == NULL) return NULL; @@ -173,7 +175,9 @@ struct lldpd_mgmt * lldpd_alloc_mgmt(int family, void *addrptr, size_t addrsize, u_int32_t iface) { struct lldpd_mgmt *mgmt; - + + log_debug("alloc", "allocate a new management address (family: %d)", family); + if (family <= LLDPD_AF_UNSPEC || family >= LLDPD_AF_LAST) { errno = EAFNOSUPPORT; return NULL; @@ -198,6 +202,8 @@ lldpd_alloc_mgmt(int family, void *addrptr, size_t addrsize, u_int32_t iface) void lldpd_hardware_cleanup(struct lldpd *cfg, struct lldpd_hardware *hardware) { + log_debug("alloc", "cleanup hardware port %s", hardware->h_ifname); + lldpd_port_cleanup(&hardware->h_lport, 1); if (hardware->h_ops->cleanup) hardware->h_ops->cleanup(cfg, hardware); @@ -222,6 +228,8 @@ lldpd_cleanup(struct lldpd *cfg) struct lldpd_hardware *hardware, *hardware_next; struct lldpd_chassis *chassis, *chassis_next; + log_debug("alloc", "cleanup all local ports"); + for (hardware = TAILQ_FIRST(&cfg->g_hardware); hardware != NULL; hardware = hardware_next) { hardware_next = TAILQ_NEXT(hardware, h_entries); @@ -233,6 +241,8 @@ lldpd_cleanup(struct lldpd *cfg) lldpd_remote_cleanup(hardware, notify_clients_deletion); } + log_debug("alloc", "cleanup all chassis"); + for (chassis = TAILQ_FIRST(&cfg->g_chassis); chassis; chassis = chassis_next) { chassis_next = TAILQ_NEXT(chassis, c_entries); @@ -293,11 +303,17 @@ lldpd_guess_type(struct lldpd *cfg, char *frame, int s) if (!cfg->g_protocols[i].enabled) continue; if (cfg->g_protocols[i].guess == NULL) { - if (memcmp(frame, cfg->g_protocols[i].mac, ETH_ALEN) == 0) + if (memcmp(frame, cfg->g_protocols[i].mac, ETH_ALEN) == 0) { + log_debug("decode", "guessed protocol is %s (from MAC address)", + cfg->g_protocols[i].name); return cfg->g_protocols[i].mode; + } } else { - if (cfg->g_protocols[i].guess(frame, s)) + if (cfg->g_protocols[i].guess(frame, s)) { + log_debug("decode", "guessed protocol is %s (from detector function)", + cfg->g_protocols[i].name); return cfg->g_protocols[i].mode; + } } } return -1; @@ -312,6 +328,9 @@ lldpd_decode(struct lldpd *cfg, char *frame, int s, struct lldpd_port *port, *oport = NULL, *aport; int guess = LLDPD_MODE_LLDP; + log_debug("decode", "decode a received frame on %s", + hardware->h_ifname); + if (s < sizeof(struct ethhdr) + 4) /* Too short, just discard it */ return; @@ -328,6 +347,7 @@ lldpd_decode(struct lldpd *cfg, char *frame, int s, (oport->p_lastframe->size == s) && (memcmp(oport->p_lastframe->frame, frame, s) == 0)) { /* Already received the same frame */ + log_debug("decode", "duplicate frame, no need to decode"); oport->p_lastupdate = time(NULL); return; } @@ -338,21 +358,27 @@ lldpd_decode(struct lldpd *cfg, char *frame, int s, if (!cfg->g_protocols[i].enabled) continue; if (cfg->g_protocols[i].mode == guess) { + log_debug("decode", "using decode function for %s protocol", + cfg->g_protocols[i].name); if ((result = cfg->g_protocols[i].decode(cfg, frame, - s, hardware, &chassis, &port)) == -1) + s, hardware, &chassis, &port)) == -1) { + log_debug("decode", "function for %s protocol did not decode this frame", + cfg->g_protocols[i].name); return; + } chassis->c_protocol = port->p_protocol = cfg->g_protocols[i].mode; break; } } if (cfg->g_protocols[i].mode == 0) { - LLOG_DEBUG("unable to guess frame type on %s", + log_debug("decode", "unable to guess frame type on %s", hardware->h_ifname); return; } /* Do we already have the same MSAP somewhere? */ + log_debug("decode", "search for the same MSAP"); TAILQ_FOREACH(oport, &hardware->h_rports, p_entries) { if ((port->p_protocol == oport->p_protocol) && (port->p_id_subtype == oport->p_id_subtype) && @@ -363,11 +389,13 @@ lldpd_decode(struct lldpd *cfg, char *frame, int s, (memcmp(chassis->c_id, oport->p_chassis->c_id, chassis->c_id_len) == 0)) { ochassis = oport->p_chassis; + log_debug("decode", "MSAP is already known"); break; } } /* No, but do we already know the system? */ if (!oport) { + log_debug("decode", "MSAP is unknown, search for the chassis"); TAILQ_FOREACH(ochassis, &cfg->g_chassis, c_entries) { if ((chassis->c_protocol == ochassis->c_protocol) && (chassis->c_id_subtype == ochassis->c_id_subtype) && @@ -389,11 +417,12 @@ lldpd_decode(struct lldpd *cfg, char *frame, int s, chassis = ochassis; } else { /* Chassis not known, add it */ + log_debug("decode", "unknown chassis, add it to the list"); chassis->c_index = ++cfg->g_lastrid; chassis->c_refcount = 0; TAILQ_INSERT_TAIL(&cfg->g_chassis, chassis, c_entries); i = 0; TAILQ_FOREACH(ochassis, &cfg->g_chassis, c_entries) i++; - LLOG_DEBUG("Currently, we know %d different systems", i); + log_debug("decode", "%d different systems are known", i); } /* Add port */ port->p_lastchange = port->p_lastupdate = time(NULL); @@ -420,12 +449,14 @@ lldpd_decode(struct lldpd *cfg, char *frame, int s, */ i = 0; TAILQ_FOREACH(aport, &hardware->h_rports, p_entries) i++; - LLOG_DEBUG("Currently, %s knows %d neighbors", - hardware->h_ifname, i); + log_debug("decode", "%d neighbors for %s", i, + hardware->h_ifname); if (!oport) hardware->h_insert_cnt++; /* Notify */ + log_debug("decode", "send notifications for changes on %s", + hardware->h_ifname); i = oport?NEIGHBOR_CHANGE_UPDATED:NEIGHBOR_CHANGE_ADDED; levent_ctl_notify(hardware->h_ifname, i, port); #ifdef USE_SNMP @@ -445,13 +476,15 @@ lldpd_get_lsb_release() { int pid, status, devnull, count; int pipefd[2]; + log_debug("localchassis", "grab LSB release"); + if (pipe(pipefd)) { - LLOG_WARN("unable to get a pair of pipes"); + log_warn("localchassis", "unable to get a pair of pipes"); return NULL; } if ((pid = fork()) < 0) { - LLOG_WARN("unable to fork"); + log_warn("localchassis", "unable to fork"); return NULL; } switch (pid) { @@ -479,14 +512,14 @@ lldpd_get_lsb_release() { count += status; } while (count < sizeof(release) && (status > 0)); if (status < 0) { - LLOG_WARN("unable to read from lsb_release"); + log_info("localchassis", "unable to read from lsb_release"); close(pipefd[0]); waitpid(pid, &status, 0); return NULL; } close(pipefd[0]); if (count >= sizeof(release)) { - LLOG_INFO("output of lsb_release is too large"); + log_info("localchassis", "output of lsb_release is too large"); waitpid(pid, &status, 0); return NULL; } @@ -494,11 +527,11 @@ lldpd_get_lsb_release() { if (waitpid(pid, &status, 0) != pid) return NULL; if (!WIFEXITED(status) || (WEXITSTATUS(status) != 0)) { - LLOG_INFO("lsb_release information not available"); + log_info("localchassis", "lsb_release information not available"); return NULL; } if (!count) { - LLOG_INFO("lsb_release returned an empty string"); + log_info("localchassis", "lsb_release returned an empty string"); return NULL; } release[count] = '\0'; @@ -518,8 +551,9 @@ lldpd_get_os_release() { char *ptr2 = release; FILE *fp = fopen("/etc/os-release", "r"); + log_debug("localchassis", "grab OS release"); if (!fp) { - LLOG_WARN("could not open /etc/os-release"); + log_info("localchassis", "could not open /etc/os-release"); return NULL; } @@ -555,6 +589,9 @@ lldpd_hide_ports(struct lldpd *cfg, struct lldpd_hardware *hardware, int mask) { int i, j, k, found; unsigned int min; + log_debug("smartfilter", "apply smart filter for port %s", + hardware->h_ifname); + /* Compute the number of occurrences of each protocol */ for (i = 0; i <= LLDPD_MODE_MAX; i++) protocols[i] = 0; TAILQ_FOREACH(port, &hardware->h_rports, p_entries) @@ -629,9 +666,12 @@ lldpd_hide_ports(struct lldpd *cfg, struct lldpd_hardware *hardware, int mask) { strcat(buffer, cfg->g_protocols[i].name); } } - LLOG_DEBUG("[%s] %s: %d visible neigh / %d. Protocols: %s.", - (mask == SMART_OUTGOING)?"out filter":"in filter", - hardware->h_ifname, k, j, buffer[0]?buffer:"(none)"); + log_debug("smartfilter", "%s: %s: %d visible neighbors (out of %d)", + hardware->h_ifname, + (mask == SMART_OUTGOING)?"out filter":"in filter", + k, j); + log_debug("smartfilter", "%s: protocols: %s", + hardware->h_ifname, buffer[0]?buffer:"(none)"); } /* Hide unwanted ports depending on smart mode set by the user */ @@ -642,6 +682,7 @@ lldpd_hide_all(struct lldpd *cfg) if (!cfg->g_config.c_smart) return; + log_debug("smartfilter", "apply smart filter results on all ports"); TAILQ_FOREACH(hardware, &cfg->g_hardware, h_entries) { if (cfg->g_config.c_smart & SMART_INCOMING_FILTER) lldpd_hide_ports(cfg, hardware, SMART_INCOMING); @@ -655,17 +696,23 @@ lldpd_recv(struct lldpd *cfg, struct lldpd_hardware *hardware, int fd) { char *buffer = NULL; int n; + log_debug("receive", "receive a frame on %s", + hardware->h_ifname); if ((buffer = (char *)malloc(hardware->h_mtu)) == NULL) { - LLOG_WARN("failed to alloc reception buffer"); + log_warn("receive", "failed to alloc reception buffer"); return; } if ((n = hardware->h_ops->recv(cfg, hardware, fd, buffer, hardware->h_mtu)) == -1) { + log_debug("receive", "unable to receive a frame on %s", + hardware->h_ifname); free(buffer); return; } hardware->h_rx_cnt++; + log_debug("receive", "decode received frame on %s", + hardware->h_ifname); lldpd_decode(cfg, buffer, n, hardware); lldpd_hide_all(cfg); /* Immediatly hide */ free(buffer); @@ -680,11 +727,14 @@ lldpd_send_all(struct lldpd *cfg) cfg->g_lastsent = time(NULL); if (cfg->g_config.c_receiveonly) return; + + log_debug("send", "send PDU on all ports"); TAILQ_FOREACH(hardware, &cfg->g_hardware, h_entries) { /* Ignore if interface is down */ if ((hardware->h_flags & IFF_RUNNING) == 0) continue; + log_debug("send", "send PDU on %s", hardware->h_ifname); sent = 0; for (i=0; cfg->g_protocols[i].mode != 0; i++) { if (!cfg->g_protocols[i].enabled) @@ -703,6 +753,9 @@ lldpd_send_all(struct lldpd *cfg) continue; if (port->p_protocol == cfg->g_protocols[i].mode) { + log_debug("send", "send PDU on %s with protocol %s", + hardware->h_ifname, + cfg->g_protocols[i].name); cfg->g_protocols[i].send(cfg, hardware); sent++; @@ -716,12 +769,14 @@ lldpd_send_all(struct lldpd *cfg) * available protocol. */ for (i = 0; cfg->g_protocols[i].mode != 0; i++) { if (!cfg->g_protocols[i].enabled) continue; + log_debug("send", "fallback to protocol %s for %s", + cfg->g_protocols[i].name, hardware->h_ifname); cfg->g_protocols[i].send(cfg, hardware); break; } if (cfg->g_protocols[i].mode == 0) - LLOG_WARNX("no protocol enabled, dunno what to send"); + log_warnx("send", "no protocol enabled, dunno what to send"); } } } @@ -753,41 +808,48 @@ lldpd_update_localchassis(struct lldpd *cfg) int f; char status; + log_debug("localchassis", "update information for local chassis"); + /* Set system name and description */ if (uname(&un) != 0) - fatal("failed to get system information"); + fatal("localchassis", "failed to get system information"); if ((hp = priv_gethostbyname()) == NULL) - fatal("failed to get system name"); + fatal("localchassis", "failed to get system name"); free(LOCAL_CHASSIS(cfg)->c_name); free(LOCAL_CHASSIS(cfg)->c_descr); if ((LOCAL_CHASSIS(cfg)->c_name = strdup(hp)) == NULL) - fatal(NULL); + fatal("localchassis", NULL); if (cfg->g_config.c_description) { + log_debug("localchassis", "use overriden description `%s`", cfg->g_config.c_description); if (asprintf(&LOCAL_CHASSIS(cfg)->c_descr, "%s", cfg->g_config.c_description) == -1) - fatal("failed to set full system description"); + fatal("localchassis", "failed to set full system description"); } else { if (cfg->g_config.c_advertise_version) { + log_debug("localchassis", "advertise system version"); if (asprintf(&LOCAL_CHASSIS(cfg)->c_descr, "%s %s %s %s %s", cfg->g_lsb_release?cfg->g_lsb_release:"", un.sysname, un.release, un.version, un.machine) == -1) - fatal("failed to set full system description"); + fatal("localchassis", "failed to set full system description"); } else { + log_debug("localchassis", "do not advertise system version"); if (asprintf(&LOCAL_CHASSIS(cfg)->c_descr, "%s", cfg->g_lsb_release?cfg->g_lsb_release:un.sysname) == -1) - fatal("failed to set minimal system description"); + fatal("localchassis", "failed to set minimal system description"); } } /* Check forwarding */ if ((f = priv_open("/proc/sys/net/ipv4/ip_forward")) >= 0) { - if ((read(f, &status, 1) == 1) && (status == '1')) + if ((read(f, &status, 1) == 1) && (status == '1')) { + log_debug("localchassis", "forwarding is enabled, enable router capability"); LOCAL_CHASSIS(cfg)->c_cap_enabled |= LLDP_CAP_ROUTER; - else + } else LOCAL_CHASSIS(cfg)->c_cap_enabled &= ~LLDP_CAP_ROUTER; close(f); - } + } else + log_debug("localchassis", "unable to check if forwarding is enabled"); #ifdef ENABLE_LLDPMED if (LOCAL_CHASSIS(cfg)->c_cap_available & LLDP_CAP_TELEPHONE) LOCAL_CHASSIS(cfg)->c_cap_enabled |= LLDP_CAP_TELEPHONE; @@ -804,8 +866,9 @@ lldpd_update_localchassis(struct lldpd *cfg) interface for example) */ if (LOCAL_CHASSIS(cfg)->c_id == NULL) { + log_debug("localchassis", "no chassis ID is currently set, use chassis name"); if (!(LOCAL_CHASSIS(cfg)->c_id = strdup(LOCAL_CHASSIS(cfg)->c_name))) - fatal(NULL); + fatal("localchassis", NULL); LOCAL_CHASSIS(cfg)->c_id_len = strlen(LOCAL_CHASSIS(cfg)->c_name); LOCAL_CHASSIS(cfg)->c_id_subtype = LLDP_CHASSISID_SUBTYPE_LOCAL; } @@ -829,6 +892,8 @@ lldpd_update_localports(struct lldpd *cfg) }; lldpd_ifhandlers *ifh; + log_debug("localports", "update information for local ports"); + /* h_flags is set to 0 for each port. If the port is updated, h_flags * will be set to a non-zero value. This will allow us to clean up any * non up-to-date port */ @@ -836,7 +901,7 @@ lldpd_update_localports(struct lldpd *cfg) hardware->h_flags = 0; if (getifaddrs(&ifap) != 0) - fatal("lldpd_update_localports: failed to get interface list"); + fatal("localports", "failed to get interface list"); /* We will run the list of interfaces through a list of interface * handlers. Each handler will create or update some hardware port (and @@ -855,18 +920,21 @@ void lldpd_loop(struct lldpd *cfg) { /* Main loop. - 1. Update local ports information 2. Clean unwanted (removed) local ports 3. Update local chassis information 4. Send packets 5. Update events */ - LLOG_DEBUG("start new loop"); + log_debug("loop", "start new loop"); LOCAL_CHASSIS(cfg)->c_cap_enabled = 0; + log_debug("loop", "update information for local ports"); lldpd_update_localports(cfg); + log_debug("loop", "cleanup pass"); lldpd_cleanup(cfg); + log_debug("loop", "update information for local chassis"); lldpd_update_localchassis(cfg); + log_debug("loop", "send appropriate PDU on all interfaces"); lldpd_send_all(cfg); } @@ -874,11 +942,14 @@ static void lldpd_exit(struct lldpd *cfg) { struct lldpd_hardware *hardware, *hardware_next; + log_debug("exit", "exit lldpd"); close(cfg->g_ctl); priv_ctl_cleanup(); + log_debug("exit", "cleanup hardware information"); for (hardware = TAILQ_FIRST(&cfg->g_hardware); hardware != NULL; hardware = hardware_next) { hardware_next = TAILQ_NEXT(hardware, h_entries); + log_debug("exit", "cleanup interface %s", hardware->h_ifname); lldpd_remote_cleanup(hardware, NULL); lldpd_hardware_cleanup(cfg, hardware); } @@ -1056,31 +1127,34 @@ lldpd_main(int argc, char *argv[]) usage(); } smart = filters[i].b; - + log_init(debug, __progname); tzset(); /* Get timezone info before chroot */ + log_debug("main", "lldpd starting..."); + /* Grab uid and gid to use for priv sep */ if ((user = getpwnam(PRIVSEP_USER)) == NULL) - fatal("no " PRIVSEP_USER " user for privilege separation"); + fatal("main", "no " PRIVSEP_USER " user for privilege separation"); uid = user->pw_uid; if ((group = getgrnam(PRIVSEP_GROUP)) == NULL) - fatal("no " PRIVSEP_GROUP " group for privilege separation"); + fatal("main", "no " PRIVSEP_GROUP " group for privilege separation"); gid = group->gr_gid; /* Create and setup socket */ + log_debug("main", "creating control socket"); if ((ctl = ctl_create(LLDPD_CTL_SOCKET)) == -1) { - LLOG_WARN ("unable to create control socket"); - LLOG_WARNX("If another instance is running, please stop it."); - LLOG_WARNX("Otherwise, remove " LLDPD_CTL_SOCKET); - fatalx("Giving up"); + log_warn ("main", "unable to create control socket"); + log_warnx("main", "If another instance is running, please stop it."); + log_warnx("main", "Otherwise, remove " LLDPD_CTL_SOCKET); + fatalx("giving up"); } if (chown(LLDPD_CTL_SOCKET, uid, gid) == -1) - LLOG_WARN("unable to chown control socket"); + log_warn("main", "unable to chown control socket"); if (chmod(LLDPD_CTL_SOCKET, S_IRUSR | S_IWUSR | S_IXUSR | S_IRGRP | S_IWGRP | S_IXGRP) == -1) - LLOG_WARN("unable to chmod control socket"); + log_warn("main", "unable to chmod control socket"); /* Disable SIGPIPE */ signal(SIGPIPE, SIG_IGN); @@ -1089,32 +1163,35 @@ lldpd_main(int argc, char *argv[]) if (!debug) { int pid; char *spid; + log_debug("main", "daemonize"); if (daemon(0, 0) != 0) - fatal("failed to detach daemon"); + fatal("main", "failed to detach daemon"); if ((pid = open(LLDPD_PID_FILE, O_TRUNC | O_CREAT | O_WRONLY, 0644)) == -1) - fatal("unable to open pid file " LLDPD_PID_FILE); + fatal("main", "unable to open pid file " LLDPD_PID_FILE); if (asprintf(&spid, "%d\n", getpid()) == -1) - fatal("unable to create pid file " LLDPD_PID_FILE); + fatal("main", "unable to create pid file " LLDPD_PID_FILE); if (write(pid, spid, strlen(spid)) == -1) - fatal("unable to write pid file " LLDPD_PID_FILE); + fatal("main", "unable to write pid file " LLDPD_PID_FILE); free(spid); close(pid); } /* Try to read system information from /etc/os-release if possible. Fall back to lsb_release for compatibility. */ + log_debug("main", "get OS/LSB release information"); lsb_release = lldpd_get_os_release(); if (!lsb_release) { lsb_release = lldpd_get_lsb_release(); } + log_debug("main", "initialize privilege separation"); priv_init(PRIVSEP_CHROOT, ctl, uid, gid); /* Initialization of global configuration */ if ((cfg = (struct lldpd *) calloc(1, sizeof(struct lldpd))) == NULL) - fatal(NULL); + fatal("main", NULL); cfg->g_ctl = ctl; cfg->g_config.c_mgmt_pattern = mgmtp; @@ -1128,8 +1205,9 @@ lldpd_main(int argc, char *argv[]) #endif /* USE_SNMP */ /* Get ioctl socket */ + log_debug("main", "get an ioctl socket"); if ((cfg->g_sock = socket(AF_INET, SOCK_DGRAM, 0)) == -1) - fatal("failed to get ioctl socket"); + fatal("main", "failed to get ioctl socket"); cfg->g_config.c_tx_interval = LLDPD_TX_INTERVAL; /* Description */ @@ -1144,9 +1222,10 @@ lldpd_main(int argc, char *argv[]) cfg->g_config.c_platform = platform_override; /* Set system capabilities */ + log_debug("main", "set system capabilities"); if ((lchassis = (struct lldpd_chassis*) calloc(1, sizeof(struct lldpd_chassis))) == NULL) - fatal(NULL); + fatal("localchassis", NULL); lchassis->c_cap_available = LLDP_CAP_BRIDGE | LLDP_CAP_WLAN | LLDP_CAP_ROUTER; TAILQ_INIT(&lchassis->c_mgmt); @@ -1166,14 +1245,15 @@ lldpd_main(int argc, char *argv[]) /* Set TTL */ lchassis->c_ttl = LLDPD_TTL; + log_debug("main", "initialize protocols"); cfg->g_protocols = protos; for (i=0; protos[i].mode != 0; i++) if (protos[i].enabled > 1) - LLOG_INFO("protocol %s enabled and forced", protos[i].name); + log_info("main", "protocol %s enabled and forced", protos[i].name); else if (protos[i].enabled) - LLOG_INFO("protocol %s enabled", protos[i].name); + log_info("main", "protocol %s enabled", protos[i].name); else - LLOG_INFO("protocol %s disabled", protos[i].name); + log_info("main", "protocol %s disabled", protos[i].name); TAILQ_INIT(&cfg->g_hardware); TAILQ_INIT(&cfg->g_chassis); @@ -1181,6 +1261,7 @@ lldpd_main(int argc, char *argv[]) lchassis->c_refcount++; /* We should always keep a reference to local chassis */ /* Main loop */ + log_debug("main", "start main loop"); levent_loop(cfg); lldpd_exit(cfg); diff --git a/src/daemon/priv.c b/src/daemon/priv.c index 000c5769..3014e629 100644 --- a/src/daemon/priv.c +++ b/src/daemon/priv.c @@ -81,7 +81,7 @@ priv_ping() cmd = PRIV_PING; must_write(remote, &cmd, sizeof(int)); must_read(remote, &rc, sizeof(int)); - LLOG_DEBUG("monitor ready"); + log_debug("privsep", "monitor ready"); } /* Proxy for ctl_cleanup */ @@ -104,7 +104,7 @@ priv_gethostbyname() must_write(remote, &cmd, sizeof(int)); must_read(remote, &rc, sizeof(int)); if ((buf = (char*)realloc(buf, rc+1)) == NULL) - fatal(NULL); + fatal("privsep", NULL); must_read(remote, buf, rc+1); return buf; } @@ -204,9 +204,9 @@ asroot_gethostbyname() struct hostent *hp; int len; if (uname(&un) != 0) - fatal("[priv]: failed to get system information"); + fatal("privsep", "failed to get system information"); if ((hp = gethostbyname(un.nodename)) == NULL) { - LLOG_INFO("[priv]: unable to get system name"); + log_info("privsep", "unable to get system name"); res_init(); len = strlen(un.nodename); must_write(remote, &len, sizeof(int)); @@ -244,14 +244,14 @@ asroot_open() must_read(remote, &len, sizeof(len)); if ((file = (char *)malloc(len + 1)) == NULL) - fatal(NULL); + fatal("privsep", NULL); must_read(remote, file, len); file[len] = '\0'; for (f=authorized; *f != NULL; f++) { if (regcomp(&preg, *f, REG_NOSUB) != 0) /* Should not happen */ - fatal("unable to compile a regex"); + fatal("privsep", "unable to compile a regex"); if (regexec(&preg, file, 0, NULL, 0) == 0) { regfree(&preg); break; @@ -259,7 +259,7 @@ asroot_open() regfree(&preg); } if (*f == NULL) { - LLOG_WARNX("[priv]: not authorized to open %s", file); + log_warnx("privsep", "not authorized to open %s", file); rc = -1; must_write(remote, &rc, sizeof(int)); free(file); @@ -289,7 +289,7 @@ asroot_ethtool() memset(ðc, 0, sizeof(ethc)); must_read(remote, &len, sizeof(int)); if ((ifname = (char*)malloc(len + 1)) == NULL) - fatal(NULL); + fatal("privsep", NULL); must_read(remote, ifname, len); ifname[len] = '\0'; strlcpy(ifr.ifr_name, ifname, sizeof(ifr.ifr_name)); @@ -369,17 +369,17 @@ asroot_snmp_socket() * connect to the same socket. */ must_read(remote, &bogus, sizeof(struct sockaddr_un)); if (addr->sun_family != AF_UNIX) - fatal("someone is trying to trick me"); + fatal("privsep", "someone is trying to trick me"); addr->sun_path[sizeof(addr->sun_path)-1] = '\0'; if ((sock = socket(PF_UNIX, SOCK_STREAM, 0)) < 0) { - LLOG_WARN("[priv]: cannot open socket"); + log_warn("privsep", "cannot open socket"); must_write(remote, &sock, sizeof(int)); return; } if ((rc = connect(sock, (struct sockaddr *) addr, sizeof(struct sockaddr_un))) != 0) { - LLOG_INFO("[priv]: cannot connect to %s: %s", + log_info("privsep", "cannot connect to %s: %s", addr->sun_path, strerror(errno)); close(sock); rc = -1; @@ -423,7 +423,7 @@ priv_loop() } } if (a->function == NULL) - fatal("[priv]: bogus message received"); + fatal("privsep", "bogus message received"); } /* Should never be there */ } @@ -434,12 +434,12 @@ priv_exit() int status; int rc; if ((rc = waitpid(monitored, &status, WNOHANG)) == 0) { - LLOG_DEBUG("[priv]: killing child"); + log_debug("privsep", "killing child"); kill(monitored, SIGTERM); } if ((rc = waitpid(monitored, &status, WNOHANG)) == -1) _exit(0); - LLOG_DEBUG("[priv]: waiting for child %d to terminate", monitored); + log_debug("privsep", "waiting for child %d to terminate", monitored); } /* If priv parent gets a TERM or HUP, pass it through to child instead */ @@ -456,7 +456,7 @@ sig_pass_to_chld(int sig) static void sig_chld(int sig) { - LLOG_DEBUG("[priv]: received signal %d, exiting", sig); + log_debug("privsep", "received signal %d, exiting", sig); priv_exit(); } @@ -471,28 +471,28 @@ priv_init(char *chrootdir, int ctl, uid_t uid, gid_t gid) /* Create socket pair */ if (socketpair(AF_LOCAL, SOCK_DGRAM, PF_UNSPEC, pair) < 0) - fatal("[priv]: unable to create socket pair for privilege separation"); + fatal("privsep", "unable to create socket pair for privilege separation"); /* Spawn off monitor */ if ((monitored = fork()) < 0) - fatal("[priv]: unable to fork monitor"); + fatal("privsep", "unable to fork monitor"); switch (monitored) { case 0: /* We are in the children, drop privileges */ if (RUNNING_ON_VALGRIND) - LLOG_WARNX("[priv]: running on valgrind, keep privileges"); + log_warnx("privsep", "running on valgrind, keep privileges"); else { if (chroot(chrootdir) == -1) - fatal("[priv]: unable to chroot"); + fatal("privsep", "unable to chroot"); if (chdir("/") != 0) - fatal("[priv]: unable to chdir"); + fatal("privsep", "unable to chdir"); gidset[0] = gid; if (setresgid(gid, gid, gid) == -1) - fatal("[priv]: setresgid() failed"); + fatal("privsep", "setresgid() failed"); if (setgroups(1, gidset) == -1) - fatal("[priv]: setgroups() failed"); + fatal("privsep", "setgroups() failed"); if (setresuid(uid, uid, uid) == -1) - fatal("[priv]: setresuid() failed"); + fatal("privsep", "setresuid() failed"); } remote = pair[0]; close(pair[1]); @@ -504,9 +504,9 @@ priv_init(char *chrootdir, int ctl, uid_t uid, gid_t gid) remote = pair[1]; close(pair[0]); if (atexit(priv_exit) != 0) - fatal("[priv]: unable to set exit function"); + fatal("privsep", "unable to set exit function"); if ((sock = socket(AF_INET, SOCK_DGRAM, 0)) == -1) { - fatal("[priv]: unable to get a socket"); + fatal("privsep", "unable to get a socket"); } signal(SIGALRM, sig_pass_to_chld); diff --git a/src/daemon/privsep_fdpass.c b/src/daemon/privsep_fdpass.c index 5f19d671..0e09f085 100644 --- a/src/daemon/privsep_fdpass.c +++ b/src/daemon/privsep_fdpass.c @@ -81,9 +81,9 @@ send_fd(int sock, int fd) msg.msg_iovlen = 1; if ((n = sendmsg(sock, &msg, 0)) == -1) - LLOG_WARN("sendmsg(%d)", sock); + log_warn("privsep", "sendmsg(%d)", sock); if (n != sizeof(int)) - LLOG_WARNX("sendmsg: expected sent 1 got %ld", + log_warnx("privsep", "sendmsg: expected sent 1 got %ld", (long)n); } @@ -110,18 +110,18 @@ receive_fd(int sock) msg.msg_controllen = sizeof(cmsgbuf.buf); if ((n = recvmsg(sock, &msg, 0)) == -1) - LLOG_WARN("recvmsg"); + log_warn("privsep", "recvmsg"); if (n != sizeof(int)) - LLOG_WARNX("recvmsg: expected received 1 got %ld", + log_warnx("privsep", "recvmsg: expected received 1 got %ld", (long)n); if (result == 0) { cmsg = CMSG_FIRSTHDR(&msg); if (cmsg == NULL) { - LLOG_WARNX("no message header"); + log_warnx("privsep", "no message header"); return -1; } if (cmsg->cmsg_type != SCM_RIGHTS) - LLOG_WARNX("expected type %d got %d", + log_warnx("privsep", "expected type %d got %d", SCM_RIGHTS, cmsg->cmsg_type); memcpy(&fd, CMSG_DATA(cmsg), sizeof(int)); return fd; diff --git a/src/daemon/sonmp.c b/src/daemon/sonmp.c index 541c682c..79fedf0c 100644 --- a/src/daemon/sonmp.c +++ b/src/daemon/sonmp.c @@ -193,6 +193,9 @@ sonmp_send(struct lldpd *global, int length; struct in_addr address; + log_debug("sonmp", "send SONMP PDU to %s", + hardware->h_ifname); + chassis = hardware->h_lport.p_chassis; length = hardware->h_mtu; if ((packet = (u_int8_t*)malloc(length)) == NULL) @@ -249,7 +252,7 @@ sonmp_send(struct lldpd *global, if (hardware->h_ops->send(global, hardware, (char *)packet, end - packet) == -1) { - LLOG_WARN("unable to send packet on real device for %s", + log_warn("sonmp", "unable to send packet on real device for %s", hardware->h_ifname); free(packet); return ENETDOWN; @@ -263,7 +266,7 @@ sonmp_send(struct lldpd *global, if (hardware->h_ops->send(global, hardware, (char *)packet, end - packet) == -1) { - LLOG_WARN("unable to send second SONMP packet on real device for %s", + log_warn("sonmp", "unable to send second SONMP packet on real device for %s", hardware->h_ifname); free(packet); return ENETDOWN; @@ -291,13 +294,16 @@ sonmp_decode(struct lldpd *cfg, char *frame, int s, u_int8_t seg[3], rchassis; struct in_addr address; + log_debug("sonmp", "decode SONMP PDU from %s", + hardware->h_ifname); + if ((chassis = calloc(1, sizeof(struct lldpd_chassis))) == NULL) { - LLOG_WARN("failed to allocate remote chassis"); + log_warn("sonmp", "failed to allocate remote chassis"); return -1; } TAILQ_INIT(&chassis->c_mgmt); if ((port = calloc(1, sizeof(struct lldpd_port))) == NULL) { - LLOG_WARN("failed to allocate remote port"); + log_warn("sonmp", "failed to allocate remote port"); free(chassis); return -1; } @@ -308,7 +314,7 @@ sonmp_decode(struct lldpd *cfg, char *frame, int s, length = s; pos = (u_int8_t*)frame; if (length < SONMP_SIZE) { - LLOG_WARNX("too short SONMP frame received on %s", hardware->h_ifname); + log_warnx("sonmp", "too short SONMP frame received on %s", hardware->h_ifname); goto malformed; } if (PEEK_CMP(mcastaddr, sizeof(mcastaddr)) != 0) @@ -319,14 +325,14 @@ sonmp_decode(struct lldpd *cfg, char *frame, int s, PEEK_DISCARD(ETH_ALEN); PEEK_DISCARD_UINT16; PEEK_DISCARD(6); if (PEEK_UINT16 != LLC_PID_SONMP_HELLO) { - LLOG_DEBUG("incorrect LLC protocol ID received for SONMP on %s", + log_debug("sonmp", "incorrect LLC protocol ID received for SONMP on %s", hardware->h_ifname); goto malformed; } chassis->c_id_subtype = LLDP_CHASSISID_SUBTYPE_ADDR; if ((chassis->c_id = calloc(1, sizeof(struct in_addr) + 1)) == NULL) { - LLOG_WARN("unable to allocate memory for chassis id on %s", + log_warn("sonmp", "unable to allocate memory for chassis id on %s", hardware->h_ifname); goto malformed; } @@ -335,7 +341,7 @@ sonmp_decode(struct lldpd *cfg, char *frame, int s, PEEK_BYTES(&address, sizeof(struct in_addr)); memcpy(chassis->c_id + 1, &address, sizeof(struct in_addr)); if (asprintf(&chassis->c_name, "%s", inet_ntoa(address)) == -1) { - LLOG_WARNX("unable to write chassis name for %s", + log_warnx("sonmp", "unable to write chassis name for %s", hardware->h_ifname); goto malformed; } @@ -347,14 +353,14 @@ sonmp_decode(struct lldpd *cfg, char *frame, int s, } if (asprintf(&chassis->c_descr, "%s", sonmp_chassis_types[i].description) == -1) { - LLOG_WARNX("unable to write chassis description for %s", + log_warnx("sonmp", "unable to write chassis description for %s", hardware->h_ifname); goto malformed; } mgmt = lldpd_alloc_mgmt(LLDPD_AF_IPV4, &address, sizeof(struct in_addr), 0); if (mgmt == NULL) { assert(errno == ENOMEM); - LLOG_WARN("unable to allocate memory for management address"); + log_warn("sonmp", "unable to allocate memory for management address"); goto malformed; } TAILQ_INSERT_TAIL(&chassis->c_mgmt, mgmt, m_entries); @@ -363,7 +369,7 @@ sonmp_decode(struct lldpd *cfg, char *frame, int s, port->p_id_subtype = LLDP_PORTID_SUBTYPE_LOCAL; if (asprintf(&port->p_id, "%02x-%02x-%02x", seg[0], seg[1], seg[2]) == -1) { - LLOG_WARN("unable to allocate memory for port id on %s", + log_warn("sonmp", "unable to allocate memory for port id on %s", hardware->h_ifname); goto malformed; } @@ -373,21 +379,21 @@ sonmp_decode(struct lldpd *cfg, char *frame, int s, if ((seg[0] == 0) && (seg[1] == 0)) { if (asprintf(&port->p_descr, "port %d", seg[2]) == -1) { - LLOG_WARNX("unable to write port description for %s", + log_warnx("sonmp", "unable to write port description for %s", hardware->h_ifname); goto malformed; } } else if (seg[0] == 0) { if (asprintf(&port->p_descr, "port %d/%d", seg[1], seg[2]) == -1) { - LLOG_WARNX("unable to write port description for %s", + log_warnx("sonmp", "unable to write port description for %s", hardware->h_ifname); goto malformed; } } else { if (asprintf(&port->p_descr, "port %x:%x:%x", seg[0], seg[1], seg[2]) == -1) { - LLOG_WARNX("unable to write port description for %s", + log_warnx("sonmp", "unable to write port description for %s", hardware->h_ifname); goto malformed; } diff --git a/src/lib/atom-private.c b/src/lib/atom-private.c index 926e9336..8257dd79 100644 --- a/src/lib/atom-private.c +++ b/src/lib/atom-private.c @@ -2553,7 +2553,7 @@ _lldpctl_new_atom(lldpctl_conn_t *conn, atom_t type, ...) va_end(ap); return atom; } - LLOG_WARNX("unknown atom type: %d", type); + log_warnx("atom", "unknown atom type: %d", type); SET_ERROR(conn, LLDPCTL_ERR_FATAL); return NULL; } diff --git a/src/lib/connection.c b/src/lib/connection.c index 85536e36..1aa3d370 100644 --- a/src/lib/connection.c +++ b/src/lib/connection.c @@ -183,7 +183,7 @@ check_for_notification(lldpctl_conn_t *conn) case NEIGHBOR_CHANGE_ADDED: type = lldpctl_c_added; break; case NEIGHBOR_CHANGE_UPDATED: type = lldpctl_c_updated; break; default: - LLOG_WARNX("unknown notification type (%d)", + log_warnx("control", "unknown notification type (%d)", change->state); goto end; } diff --git a/src/lldpd-structs.c b/src/lldpd-structs.c index b142ff07..cef86056 100644 --- a/src/lldpd-structs.c +++ b/src/lldpd-structs.c @@ -19,11 +19,16 @@ #include #include #include "lldpd-structs.h" +#include "log.h" void lldpd_chassis_mgmt_cleanup(struct lldpd_chassis *chassis) { struct lldpd_mgmt *mgmt, *mgmt_next; + + log_debug("alloc", "cleanup management addresses for chassis %s", + chassis->c_name ? chassis->c_name : "(unknwon)"); + for (mgmt = TAILQ_FIRST(&chassis->c_mgmt); mgmt != NULL; mgmt = mgmt_next) { @@ -36,6 +41,8 @@ lldpd_chassis_mgmt_cleanup(struct lldpd_chassis *chassis) void lldpd_chassis_cleanup(struct lldpd_chassis *chassis, int all) { + log_debug("alloc", "cleanup chassis %s", + chassis->c_name ? chassis->c_name : "(unknwon)"); #ifdef ENABLE_LLDPMED free(chassis->c_med_hw); free(chassis->c_med_sw); @@ -105,6 +112,9 @@ lldpd_remote_cleanup(struct lldpd_hardware *hardware, { struct lldpd_port *port, *port_next; int del; + + log_debug("alloc", "cleanup remote port on %s", + hardware->h_ifname); for (port = TAILQ_FIRST(&hardware->h_rports); port != NULL; port = port_next) { @@ -157,6 +167,7 @@ lldpd_port_cleanup(struct lldpd_port *port, int all) void lldpd_config_cleanup(struct lldpd_config *config) { + log_debug("alloc", "general configuration cleanup"); free(config->c_mgmt_pattern); free(config->c_cid_pattern); free(config->c_iface_pattern); diff --git a/src/log.c b/src/log.c index 1916b74f..35a557c3 100644 --- a/src/log.c +++ b/src/log.c @@ -35,7 +35,7 @@ static int debug = 1; static void (*logh)(int severity, const char *msg) = NULL; static void vlog(int, const char *, const char *, va_list); -static void logit(int, const char *, ...); +static void logit(int, const char *, const char *, ...); void log_init(int n_debug, const char *progname) @@ -56,12 +56,12 @@ log_register(void (*cb)(int, const char*)) static void -logit(int pri, const char *fmt, ...) +logit(int pri, const char *token, const char *fmt, ...) { va_list ap; va_start(ap, fmt); - vlog(pri, NULL, fmt, ap); + vlog(pri, token, fmt, ap); va_end(ap); } @@ -200,16 +200,16 @@ log_debug(const char *token, const char *emsg, ...) } void -fatal(const char *emsg) +fatal(const char *token, const char *emsg) { if (emsg == NULL) - logit(LOG_CRIT, "fatal: %s", strerror(errno)); + logit(LOG_CRIT, token ? token : "fatal", "%s", strerror(errno)); else if (errno) - logit(LOG_CRIT, "fatal: %s: %s", + logit(LOG_CRIT, token ? token : "fatal", "%s: %s", emsg, strerror(errno)); else - logit(LOG_CRIT, "fatal: %s", emsg); + logit(LOG_CRIT, token ? token : "fatal", "%s", emsg); exit(1); } @@ -218,5 +218,5 @@ void fatalx(const char *emsg) { errno = 0; - fatal(emsg); + fatal(NULL, emsg); } diff --git a/src/log.h b/src/log.h index 3f9598e0..05a2b748 100644 --- a/src/log.h +++ b/src/log.h @@ -19,19 +19,12 @@ #define _LOG_H /* log.c */ -#include -#define __FILENAME__ (strrchr(__FILE__, '/') ? strrchr(__FILE__, '/') + 1 : __FILE__) - void log_init(int, const char *); void log_warn(const char *, const char *, ...) __attribute__ ((format (printf, 2, 3))); -#define LLOG_WARN(x,...) log_warn(__FILENAME__, x, ## __VA_ARGS__) void log_warnx(const char *, const char *, ...) __attribute__ ((format (printf, 2, 3))); -#define LLOG_WARNX(x,...) log_warnx(__FILENAME__, x, ## __VA_ARGS__) void log_info(const char *, const char *, ...) __attribute__ ((format (printf, 2, 3))); -#define LLOG_INFO(x,...) log_info(__FILENAME__, x, ## __VA_ARGS__) void log_debug(const char *, const char *, ...) __attribute__ ((format (printf, 2, 3))); -#define LLOG_DEBUG(x,...) log_debug(__FILENAME__, x, ## __VA_ARGS__) -void fatal(const char *); +void fatal(const char*, const char *); void fatalx(const char *); void log_register(void (*cb)(int, const char*)); diff --git a/src/marshal.c b/src/marshal.c index 993d6543..f154af93 100644 --- a/src/marshal.c +++ b/src/marshal.c @@ -71,11 +71,13 @@ marshal_serialize_(struct marshal_info *mi, void *unserialized, void **input, struct marshal_subinfo *current; struct marshal_serialized *new = NULL, *serialized = NULL; + log_debug("marshal", "start serialization of %s", mi->name); + /* Check if we have already serialized this one. */ if (!refs) { refs = calloc(1, sizeof(struct ref_l)); if (!refs) { - LLOG_WARNX("unable to allocate memory for list of references"); + log_warnx("marshal", "unable to allocate memory for list of references"); return -1; } TAILQ_INIT(refs); @@ -96,7 +98,7 @@ marshal_serialize_(struct marshal_info *mi, void *unserialized, void **input, len = sizeof(struct marshal_serialized) + (skip?0:size); serialized = calloc(1, len); if (!serialized) { - LLOG_WARNX("unable to allocate memory to serialize structure %s", + log_warnx("marshal", "unable to allocate memory to serialize structure %s", mi->name); len = -1; goto marshal_error; @@ -105,7 +107,7 @@ marshal_serialize_(struct marshal_info *mi, void *unserialized, void **input, /* Append the new reference */ if (!(cref = calloc(1, sizeof(struct ref)))) { - LLOG_WARNX("unable to allocate memory for list of references"); + log_warnx("marshal", "unable to allocate memory for list of references"); free(serialized); len = -1; goto marshal_error; @@ -136,7 +138,7 @@ marshal_serialize_(struct marshal_info *mi, void *unserialized, void **input, source, &target, current->kind == substruct, refs, osize); if (sublen == -1) { - LLOG_WARNX("unable to serialize substructure %s for %s", + log_warnx("marshal", "unable to serialize substructure %s for %s", current->mi->name, mi->name); free(serialized); return -1; @@ -145,7 +147,7 @@ marshal_serialize_(struct marshal_info *mi, void *unserialized, void **input, /* Append the result */ new = realloc(serialized, len + sublen); if (!new) { - LLOG_WARNX("unable to allocate more memory to serialize structure %s", + log_warnx("marshal", "unable to allocate more memory to serialize structure %s", mi->name); free(serialized); free(target); @@ -229,8 +231,10 @@ marshal_unserialize_(struct marshal_info *mi, void *buffer, size_t len, void **o struct marshal_subinfo *current; struct gc *apointer; + log_debug("marshal", "start unserialization of %s", mi->name); + if (len < sizeof(struct marshal_serialized) || len < total_len) { - LLOG_WARNX("data to deserialize is too small (%zu) for structure %s", + log_warnx("marshal", "data to deserialize is too small (%zu) for structure %s", len, mi->name); return 0; } @@ -239,7 +243,7 @@ marshal_unserialize_(struct marshal_info *mi, void *buffer, size_t len, void **o if (!pointers) { pointers = calloc(1, sizeof(struct gc_l)); if (!pointers) { - LLOG_WARNX("unable to allocate memory for garbage collection"); + log_warnx("marshal", "unable to allocate memory for garbage collection"); return 0; } TAILQ_INIT(pointers); @@ -255,7 +259,7 @@ marshal_unserialize_(struct marshal_info *mi, void *buffer, size_t len, void **o the string is null terminated. */ } if (size > len - sizeof(struct marshal_serialized)) { - LLOG_WARNX("data to deserialize contains a string too long"); + log_warnx("marshal", "data to deserialize contains a string too long"); total_len = 0; goto unmarshal_error; } @@ -265,7 +269,7 @@ marshal_unserialize_(struct marshal_info *mi, void *buffer, size_t len, void **o /* First, the main structure */ if (!skip) { if ((*output = marshal_alloc(pointers, size + extra, serialized->orig)) == NULL) { - LLOG_WARNX("unable to allocate memory to unserialize structure %s", + log_warnx("marshal", "unable to allocate memory to unserialize structure %s", mi->name); total_len = 0; goto unmarshal_error; @@ -303,7 +307,7 @@ marshal_unserialize_(struct marshal_info *mi, void *buffer, size_t len, void **o (unsigned char *)buffer + total_len, len - total_len, &new, pointers, current->kind == substruct, osize); if (sublen == 0) { - LLOG_WARNX("unable to serialize substructure %s for %s", + log_warnx("marshal", "unable to serialize substructure %s for %s", current->mi->name, mi->name); total_len = 0; goto unmarshal_error; -- 2.39.5