[M] Change in libosmo-abis[master]: input/ipaccess: Always log with context, if we have any
laforge has submitted this change. ( https://gerrit.osmocom.org/c/libosmo-abis/+/36037?usp=email )
Change subject: input/ipaccess: Always log with context, if we have any ......................................................................
input/ipaccess: Always log with context, if we have any
Calling global LOGP/DEBUGP without giving any context (e.g. by using LOGPIL, LOGPITS, ...) will leave the user wonder *which* line or timeslot generated a certain log line. We should know better than that.
Change-Id: I5cd84c2d69c0db3be296cb5d9a62720f7b2c827e --- M src/input/ipaccess.c 1 file changed, 71 insertions(+), 95 deletions(-)
Approvals: pespin: Looks good to me, but someone else must approve osmith: Looks good to me, but someone else must approve Jenkins Builder: Verified laforge: Looks good to me, approved
diff --git a/src/input/ipaccess.c b/src/input/ipaccess.c index 7c91e70..9010f89 100644 --- a/src/input/ipaccess.c +++ b/src/input/ipaccess.c @@ -242,46 +242,40 @@ /* this is not an IPA control message, continue */ break; default: - LOGP(DLINP, LOGL_ERROR, "Unexpected return from " - "ipa_ccm_rcvmsg_base " - "(ret=%d)\n", ret); + LOGPITS(e1i_ts, DLINP, LOGL_ERROR, "Unexpected return from ipa_ccm_rcvmsg_base (ret=%d)\n", ret); goto err; }
switch (msg_type) { case IPAC_MSGT_ID_RESP: - DEBUGP(DLMI, "ID_RESP "); + LOGPITS(e1i_ts, DLMI, LOGL_DEBUG, "ID_RESP "); /* parse tags, search for Unit ID */ ret = ipa_ccm_id_resp_parse(&tlvp, (const uint8_t *)msg->l2h+1, msgb_l2len(msg)-1); DEBUGPC(DLMI, "\n"); if (ret < 0) { - LOGP(DLINP, LOGL_ERROR, "IPA response message " - "with malformed TLVs\n"); + LOGPITS(e1i_ts, DLINP, LOGL_ERROR, "IPA response message with malformed TLVs\n"); goto err; } if (!TLVP_PRESENT(&tlvp, IPAC_IDTAG_UNIT)) { - LOGP(DLINP, LOGL_ERROR, "IPA response message " - "without unit ID\n"); + LOGPITS(e1i_ts, DLINP, LOGL_ERROR, "IPA response message without unit ID\n"); goto err;
} len = TLVP_LEN(&tlvp, IPAC_IDTAG_UNIT); if (len < 1) { - LOGP(DLINP, LOGL_ERROR, "IPA response message " - "with too small unit ID\n"); + LOGPITS(e1i_ts, DLINP, LOGL_ERROR, "IPA response message with too small unit ID\n"); goto err; } unitid = (char *) TLVP_VAL(&tlvp, IPAC_IDTAG_UNIT); unitid[len - 1] = '\0'; ret = ipa_parse_unitid(unitid, &unit_data); if (ret) { - LOGP(DLINP, LOGL_ERROR, "Failed to parse unit ID '%s'\n", unitid); + LOGPITS(e1i_ts, DLINP, LOGL_ERROR, "Failed to parse unit ID '%s'\n", unitid); goto err; }
if (!line->ops->sign_link_up) { - LOGP(DLINP, LOGL_ERROR, - "Unable to set signal link, closing socket.\n"); + LOGPITS(e1i_ts, DLINP, LOGL_ERROR, "Unable to set signal link, closing socket.\n"); goto err; } /* the BSC creates the new sign links at this stage. */ @@ -290,9 +284,7 @@ line->ops->sign_link_up(&unit_data, line, E1INP_SIGN_OML); if (sign_link == NULL) { - LOGP(DLINP, LOGL_ERROR, - "Unable to set signal link, " - "closing socket.\n"); + LOGPITS(e1i_ts, DLINP, LOGL_ERROR, "Unable to set signal link, closing socket.\n"); goto err; }
@@ -308,9 +300,7 @@ line->ops->sign_link_up(&unit_data, line, E1INP_SIGN_RSL); if (sign_link == NULL) { - LOGP(DLINP, LOGL_ERROR, - "Unable to set signal link, " - "closing socket.\n"); + LOGPIL(line, DLINP, LOGL_ERROR, "Unable to set signal link, closing socket.\n"); goto err; } /* Finally, we know which OML link is associated with @@ -319,10 +309,8 @@ /* this is a bugtrap, the BSC should be using the * virtual E1 line used by OML for this RSL link. */ if (new_line == line) { - LOGP(DLINP, LOGL_ERROR, - "Fix your BSC, you should use the " - "E1 line used by the OML link for " - "your RSL link.\n"); + LOGPIL(line, DLINP, LOGL_ERROR, "Fix your BSC, you should use the " + "E1 line used by the OML link for your RSL link.\n"); return 0; } e1inp_line_get2(new_line, "ipa_bfd"); @@ -345,8 +333,7 @@
ret = osmo_fd_register(newbfd); if (ret < 0) { - LOGP(DLINP, LOGL_ERROR, - "could not register FD\n"); + LOGPITS(ts, DLINP, LOGL_ERROR, "could not register FD\n"); goto err; } snprintf(tcp_stat_name, sizeof(tcp_stat_name), "site.%u.bts.%u.ipa-rsl.%u", @@ -359,7 +346,7 @@ } break; default: - LOGP(DLINP, LOGL_ERROR, "Unknown IPA message type\n"); + LOGPIL(line, DLINP, LOGL_ERROR, "Unknown IPA message type\n"); goto err; } return 0; @@ -392,14 +379,14 @@ if (ret < 0) { if (ret == -EAGAIN) return 0; - LOGP(DLINP, LOGL_NOTICE, "Sign link problems, " - "closing socket. Reason: %s\n", strerror(-ret)); + LOGPITS(e1i_ts, DLINP, LOGL_NOTICE, "Sign link problems, closing socket. Reason: %s\n", + strerror(-ret)); goto err; } else if (ret == 0) { - LOGP(DLINP, LOGL_NOTICE, "Sign link vanished, dead socket\n"); + LOGPITS(e1i_ts, DLINP, LOGL_NOTICE, "Sign link vanished, dead socket\n"); goto err; } - DEBUGP(DLMI, "RX %u: %s\n", ts_nr, osmo_hexdump(msgb_l2(msg), msgb_l2len(msg))); + LOGPITS(e1i_ts, DLMI, LOGL_DEBUG, "RX %u: %s\n", ts_nr, osmo_hexdump(msgb_l2(msg), msgb_l2len(msg)));
hh = (struct ipaccess_head *) msg->data; if (hh->proto == IPAC_PROTO_IPACCESS) { @@ -410,22 +397,20 @@ return ret != 0 ? -EBADF : 0; } else if (e1i_ts->type == E1INP_TS_TYPE_NONE) { /* this sign link is not know yet.. complain. */ - LOGP(DLINP, LOGL_ERROR, "Timeslot is not configured.\n"); + LOGPITS(e1i_ts, DLINP, LOGL_ERROR, "Timeslot is not configured.\n"); goto err_msg; }
link = e1inp_lookup_sign_link(e1i_ts, hh->proto, 0); if (!link) { - LOGP(DLINP, LOGL_ERROR, "no matching signalling link for " - "hh->proto=0x%02x\n", hh->proto); + LOGPITS(e1i_ts, DLINP, LOGL_ERROR, "no matching signalling link for hh->proto=0x%02x\n", hh->proto); goto err_msg; } msg->dst = link;
/* XXX better use e1inp_ts_rx? */ if (!e1i_ts->line->ops->sign_link) { - LOGP(DLINP, LOGL_ERROR, "Fix your application, " - "no action set for signalling messages.\n"); + LOGPITS(e1i_ts, DLINP, LOGL_ERROR, "Fix your application, no action set for signalling messages.\n"); goto err_msg; } rc = e1i_ts->line->ops->sign_link(msg); @@ -434,8 +419,8 @@ * an error, that's too strict. BTW, the signalling layer is * resposible for releasing the message. */ - LOGP(DLINP, LOGL_ERROR, "Bad signalling message," - " sign_link returned error: %s.\n", strerror(-rc)); + LOGPITS(e1i_ts, DLINP, LOGL_ERROR, "Bad signalling message, sign_link returned error: %s.\n", + strerror(-rc)); }
return rc; @@ -610,10 +595,9 @@ val = 1; ret = setsockopt(fd, SOL_SOCKET, SO_KEEPALIVE, &val, sizeof(val)); if (ret < 0) - LOGP(DLINP, LOGL_ERROR, "Failed to set keepalive: %s\n", - strerror(errno)); + LOGPIL(line, DLINP, LOGL_ERROR, "Failed to set keepalive: %s\n", strerror(errno)); else - LOGP(DLINP, LOGL_NOTICE, "Keepalive is set: %i\n", ret); + LOGPIL(line, DLINP, LOGL_NOTICE, "Keepalive is set: %d\n", ret);
/* The following options are not portable! */ val = line->keepalive_idle_timeout > 0 ? @@ -622,42 +606,34 @@ ret = setsockopt(fd, IPPROTO_TCP, TCP_KEEPIDLE, &val, sizeof(val)); if (ret < 0) - LOGP(DLINP, LOGL_ERROR, - "Failed to set keepalive idle time: %s\n", - strerror(errno)); + LOGPIL(line, DLINP, LOGL_ERROR, "Failed to set keepalive idle time: %s\n", strerror(errno)); val = line->keepalive_probe_interval > -1 ? line->keepalive_probe_interval : DEFAULT_TCP_KEEPALIVE_INTERVAL; ret = setsockopt(fd, IPPROTO_TCP, TCP_KEEPINTVL, &val, sizeof(val)); if (ret < 0) - LOGP(DLINP, LOGL_ERROR, - "Failed to set keepalive interval: %s\n", - strerror(errno)); + LOGPIL(line, DLINP, LOGL_ERROR, "Failed to set keepalive interval: %s\n", strerror(errno)); val = line->keepalive_num_probes > 0 ? line->keepalive_num_probes : DEFAULT_TCP_KEEPALIVE_RETRY_COUNT; ret = setsockopt(fd, IPPROTO_TCP, TCP_KEEPCNT, &val, sizeof(val)); if (ret < 0) - LOGP(DLINP, LOGL_ERROR, - "Failed to set keepalive count: %s\n", - strerror(errno)); + LOGPIL(line, DLINP, LOGL_ERROR, "Failed to set keepalive count: %s\n", strerror(errno)); val = 1000 * line->keepalive_num_probes * line->keepalive_probe_interval + line->keepalive_idle_timeout; ret = setsockopt(fd, IPPROTO_TCP, TCP_USER_TIMEOUT, &val, sizeof(val)); if (ret < 0) - LOGP(DLINP, LOGL_ERROR, - "Failed to set user timoeut: %s\n", - strerror(errno)); + LOGPIL(line, DLINP, LOGL_ERROR, "Failed to set user timoeut: %s\n", strerror(errno)); }
val = 1; ret = setsockopt(fd, IPPROTO_TCP, TCP_NODELAY, &val, sizeof(val)); if (ret < 0) - LOGP(DLINP, LOGL_ERROR, "Failed to set TCP_NODELAY: %s\n", strerror(errno)); + LOGPIL(line, DLINP, LOGL_ERROR, "Failed to set TCP_NODELAY: %s\n", strerror(errno)); }
/* callback of the OML listening filedescriptor */ @@ -689,7 +665,7 @@ osmo_fd_setup(bfd, fd, OSMO_FD_READ, ipaccess_fd_cb, line, E1INP_SIGN_OML); ret = osmo_fd_register(bfd); if (ret < 0) { - LOGP(DLINP, LOGL_ERROR, "could not register FD\n"); + LOGPITS(e1i_ts, DLINP, LOGL_ERROR, "could not register FD\n"); goto err_line; } osmo_stats_tcp_osmo_fd_register(bfd, "ipa-oml"); @@ -699,8 +675,7 @@ /* Request ID. FIXME: request LOCATION, HW/SW VErsion, Unit Name, Serno */ ret = ipa_ccm_send_id_req(bfd->fd); if (ret < 0) { - LOGP(DLINP, LOGL_ERROR, "could not send ID REQ. Reason: %s\n", - strerror(errno)); + LOGPITS(e1i_ts, DLINP, LOGL_ERROR, "could not send ID REQ. Reason: %s\n", strerror(errno)); goto err_socket; } return ret; @@ -743,7 +718,7 @@ osmo_fd_setup(bfd, fd, OSMO_FD_READ, ipaccess_fd_cb, line, E1INP_SIGN_RSL); ret = osmo_fd_register(bfd); if (ret < 0) { - LOGP(DLINP, LOGL_ERROR, "could not register FD\n"); + LOGPITS(e1i_ts, DLINP, LOGL_ERROR, "could not register FD\n"); goto err_line; } osmo_stats_tcp_osmo_fd_register(bfd, "ipa-rsl"); @@ -751,8 +726,7 @@ /* Request ID. FIXME: request LOCATION, HW/SW VErsion, Unit Name, Serno */ ret = ipa_ccm_send_id_req(bfd->fd); if (ret < 0) { - LOGP(DLINP, LOGL_ERROR, "could not send ID REQ. Reason: %s\n", - strerror(errno)); + LOGPITS(e1i_ts, DLINP, LOGL_ERROR, "could not send ID REQ. Reason: %s\n", strerror(errno)); goto err_socket; } update_fd_settings(line, bfd->fd); @@ -920,13 +894,13 @@ if (link->ofd->priv_nr >= E1INP_SIGN_RSL) trx_nr = link->ofd->priv_nr - E1INP_SIGN_RSL;
- LOGP(DLINP, LOGL_NOTICE, "received ID_GET for unit ID %u/%u/%u\n", - dev->site_id, dev->bts_id, trx_nr); + LOGPIL(line, DLINP, LOGL_NOTICE, "received ID_GET for unit ID %u/%u/%u\n", + dev->site_id, dev->bts_id, trx_nr); rmsg = ipa_bts_id_resp(dev, data + 1, len - 1, trx_nr); ret = ipa_send(link->ofd->fd, rmsg->data, rmsg->len); if (ret != rmsg->len) { - LOGP(DLINP, LOGL_ERROR, "cannot send ID_RESP " - "message. Reason: %s\n", strerror(errno)); + LOGPIL(line, DLINP, LOGL_ERROR, "cannot send ID_RESP message. Reason: %s\n", + strerror(errno)); goto err_rmsg; } msgb_free(rmsg); @@ -935,8 +909,8 @@ rmsg = ipa_bts_id_ack(); ret = ipa_send(link->ofd->fd, rmsg->data, rmsg->len); if (ret != rmsg->len) { - LOGP(DLINP, LOGL_ERROR, "cannot send ID_ACK " - "message. Reason: %s\n", strerror(errno)); + LOGPIL(line, DLINP, LOGL_ERROR, "cannot send ID_ACK message. Reason: %s\n", + strerror(errno)); goto err_rmsg; } msgb_free(rmsg); @@ -1001,15 +975,15 @@ OSMO_ASSERT(e1i_ts != NULL);
if (e1i_ts->type == E1INP_TS_TYPE_NONE) { - LOGP(DLINP, LOGL_ERROR, "Signalling link not initialized. Discarding." - " port=%u msg_type=%u\n", link->port, msg_type); + LOGPITS(e1i_ts, DLINP, LOGL_ERROR, "Signalling link not initialized. Discarding." + " port=%u msg_type=%u\n", link->port, msg_type); goto err; }
/* look up for some existing signaling link. */ sign_link = e1inp_lookup_sign_link(e1i_ts, hh->proto, 0); if (sign_link == NULL) { - LOGP(DLINP, LOGL_ERROR, "no matching signalling link for " + LOGPITS(e1i_ts, DLINP, LOGL_ERROR, "no matching signalling link for " "hh->proto=0x%02x\n", hh->proto); goto err; } @@ -1017,7 +991,7 @@
/* XXX better use e1inp_ts_rx? */ if (!link->line->ops->sign_link) { - LOGP(DLINP, LOGL_ERROR, "Fix your application, " + LOGPITS(e1i_ts, DLINP, LOGL_ERROR, "Fix your application, " "no action set for signalling messages.\n"); goto err; } @@ -1043,7 +1017,7 @@ line->driver_data = talloc_zero(line, struct ipaccess_line);
if (!line->driver_data) { - LOGP(DLINP, LOGL_ERROR, "ipaccess: OOM in line update\n"); + LOGPIL(line, DLINP, LOGL_ERROR, "ipaccess: OOM in line update\n"); return -ENOMEM; } il = line->driver_data; @@ -1056,23 +1030,20 @@ struct ipa_server_link *oml_link, *rsl_link; const char *ipa = e1inp_ipa_get_bind_addr();
- LOGP(DLINP, LOGL_NOTICE, "enabling ipaccess BSC mode on %s " - "with OML %u and RSL %u TCP ports\n", ipa, - IPA_TCP_PORT_OML, IPA_TCP_PORT_RSL); + LOGPIL(line, DLINP, LOGL_NOTICE, "enabling ipaccess BSC mode on %s " + "with OML %u and RSL %u TCP ports\n", ipa, IPA_TCP_PORT_OML, IPA_TCP_PORT_RSL);
oml_link = ipa_server_link_create(tall_ipa_ctx, line, ipa, IPA_TCP_PORT_OML, ipaccess_bsc_oml_cb, NULL); if (oml_link == NULL) { - LOGP(DLINP, LOGL_ERROR, "cannot create OML " - "BSC link: %s\n", strerror(errno)); + LOGPIL(line, DLINP, LOGL_ERROR, "cannot create OML BSC link: %s\n", strerror(errno)); return -ENOMEM; } oml_link->dscp = g_e1inp_ipaccess_pars.oml.dscp; oml_link->priority = g_e1inp_ipaccess_pars.oml.priority; if (ipa_server_link_open(oml_link) < 0) { - LOGP(DLINP, LOGL_ERROR, "cannot open OML BSC link: %s\n", - strerror(errno)); + LOGPIL(line, DLINP, LOGL_ERROR, "cannot open OML BSC link: %s\n", strerror(errno)); ipa_server_link_destroy(oml_link); return -EIO; } @@ -1080,15 +1051,13 @@ IPA_TCP_PORT_RSL, ipaccess_bsc_rsl_cb, NULL); if (rsl_link == NULL) { - LOGP(DLINP, LOGL_ERROR, "cannot create RSL " - "BSC link: %s\n", strerror(errno)); + LOGPIL(line, DLINP, LOGL_ERROR, "cannot create RSL BSC link: %s\n", strerror(errno)); return -ENOMEM; } rsl_link->dscp = g_e1inp_ipaccess_pars.rsl.dscp; rsl_link->priority = g_e1inp_ipaccess_pars.rsl.priority; if (ipa_server_link_open(rsl_link) < 0) { - LOGP(DLINP, LOGL_ERROR, "cannot open RSL BSC link: %s\n", - strerror(errno)); + LOGPIL(line, DLINP, LOGL_ERROR, "cannot open RSL BSC link: %s\n", strerror(errno)); ipa_server_link_destroy(rsl_link); return -EIO; } @@ -1099,9 +1068,8 @@ struct ipa_client_conn *link; struct e1inp_ts *e1i_ts = e1inp_line_ipa_oml_ts(line);
- LOGP(DLINP, LOGL_NOTICE, "enabling ipaccess BTS mode, " - "OML connecting to %s:%u\n", line->ops->cfg.ipa.addr, - IPA_TCP_PORT_OML); + LOGPITS(e1i_ts, DLINP, LOGL_NOTICE, "enabling ipaccess BTS mode, " + "OML connecting to %s:%u\n", line->ops->cfg.ipa.addr, IPA_TCP_PORT_OML);
/* Drop previous line */ if (il->ipa_cli[0]) { @@ -1122,15 +1090,13 @@ ipaccess_bts_write_cb, line); if (link == NULL) { - LOGP(DLINP, LOGL_ERROR, "cannot create OML " - "BTS link: %s\n", strerror(errno)); + LOGPITS(e1i_ts, DLINP, LOGL_ERROR, "cannot create OML BTS link: %s\n", strerror(errno)); return -ENOMEM; } link->dscp = g_e1inp_ipaccess_pars.oml.dscp; link->priority = g_e1inp_ipaccess_pars.oml.priority; if (ipa_client_conn_open2(link, line->connect_timeout) < 0) { - LOGP(DLINP, LOGL_ERROR, "cannot open OML BTS link: %s\n", - strerror(errno)); + LOGPITS(e1i_ts, DLINP, LOGL_ERROR, "cannot open OML BTS link: %s\n", strerror(errno)); ipa_client_conn_close(link); ipa_client_conn_destroy(link); return -EIO; @@ -1166,7 +1132,7 @@ int rc;
if (E1INP_SIGN_RSL+trx_nr-1 >= NUM_E1_TS) { - LOGP(DLINP, LOGL_ERROR, "cannot create RSL BTS link: " + LOGPITS(e1i_ts, DLINP, LOGL_ERROR, "cannot create RSL BTS link: " "trx_nr (%d) out of range\n", trx_nr); return -EINVAL; } @@ -1189,15 +1155,13 @@ ipaccess_bts_write_cb, line); if (rsl_link == NULL) { - LOGP(DLINP, LOGL_ERROR, "cannot create RSL " - "BTS link: %s\n", strerror(errno)); + LOGPITS(e1i_ts, DLINP, LOGL_ERROR, "cannot create RSL BTS link: %s\n", strerror(errno)); return -ENOMEM; } rsl_link->dscp = g_e1inp_ipaccess_pars.rsl.dscp; rsl_link->priority = g_e1inp_ipaccess_pars.rsl.priority; if (ipa_client_conn_open2(rsl_link, line->connect_timeout) < 0) { - LOGP(DLINP, LOGL_ERROR, "cannot open RSL BTS link: %s\n", - strerror(errno)); + LOGPITS(e1i_ts, DLINP, LOGL_ERROR, "cannot open RSL BTS link: %s\n", strerror(errno)); ipa_client_conn_close(rsl_link); ipa_client_conn_destroy(rsl_link); return -EIO; @@ -1215,8 +1179,7 @@ struct e1inp_ts *e1i_ts;
if (E1INP_SIGN_RSL+trx_nr-1 >= NUM_E1_TS) { - LOGP(DLINP, LOGL_ERROR, - "cannot close RSL BTS link: trx_nr (%d) out of range\n", trx_nr); + LOGPIL(line, DLINP, LOGL_ERROR, "cannot close RSL BTS link: trx_nr (%d) out of range\n", trx_nr); return -EINVAL; }
-
laforge