From 3468d5dce45e34a63b52061b8aaa9c095f473cf4 Mon Sep 17 00:00:00 2001 From: Neels Hofmeyr Date: Thu, 22 Jun 2017 21:03:14 +0200 Subject: add/tweak various logging to help figure out complex routing Add function osmo_ss7_point_code_print2() to be able to print two point codes in the same log message. Change signatures of two static functions to aid logging: add invalid ref arg to sccp_scoc_rx_inval_src_ref(), pass conn instead of inst to sccp_scoc_rx_inval_opc(). Change-Id: Ia3243606d6cad7721f7da7f6caba2caa90ae2bbd --- include/osmocom/sigtran/osmo_ss7.h | 1 + src/m3ua.c | 28 ++++++++++++++++++++++++---- src/osmo_ss7.c | 33 ++++++++++++++++++++++++++------- src/osmo_ss7_hmrt.c | 23 ++++++++++++++++++++--- src/sccp_scoc.c | 19 ++++++++++++++----- 5 files changed, 85 insertions(+), 19 deletions(-) diff --git a/include/osmocom/sigtran/osmo_ss7.h b/include/osmocom/sigtran/osmo_ss7.h index 4e04352..caf12f5 100644 --- a/include/osmocom/sigtran/osmo_ss7.h +++ b/include/osmocom/sigtran/osmo_ss7.h @@ -24,6 +24,7 @@ bool osmo_ss7_pc_is_local(struct osmo_ss7_instance *inst, uint32_t pc); int osmo_ss7_pointcode_parse(struct osmo_ss7_instance *inst, const char *str); int osmo_ss7_pointcode_parse_mask_or_len(struct osmo_ss7_instance *inst, const char *in); const char *osmo_ss7_pointcode_print(struct osmo_ss7_instance *inst, uint32_t pc); +const char *osmo_ss7_pointcode_print2(struct osmo_ss7_instance *inst, uint32_t pc); /*********************************************************************** * SS7 Routing Tables diff --git a/src/m3ua.c b/src/m3ua.c index d96bd18..c43dfa4 100644 --- a/src/m3ua.c +++ b/src/m3ua.c @@ -536,18 +536,34 @@ static int m3ua_rx_xfer(struct osmo_ss7_asp *asp, struct xua_msg *xua) struct m3ua_data_hdr *dh; struct osmo_ss7_as *as; - if (xua->hdr.msg_type != M3UA_XFER_DATA) + LOGPASP(asp, DLM3UA, LOGL_DEBUG, "m3ua_rx_xfer\n"); + + if (xua->hdr.msg_type != M3UA_XFER_DATA) { + LOGPASP(asp, DLM3UA, LOGL_ERROR, + "%s(): unsupported message type: %s\n", + __func__, + get_value_string(m3ua_xfer_msgt_names, xua->hdr.msg_type)); return M3UA_ERR_UNSUPP_MSG_TYPE; + } /* Use routing context IE to look up the AS for which the * message was received. */ as = osmo_ss7_as_find_by_rctx(asp->inst, rctx); - if (!as) + if (!as) { + LOGPASP(asp, DLM3UA, LOGL_ERROR, + "%s(): invalid routing context: %u\n", + __func__, rctx); return M3UA_ERR_INVAL_ROUT_CTX; + } - /* Verify that this ASP ix part of the AS. */ - if (!osmo_ss7_as_has_asp(as, asp)) + /* Verify that this ASP is part of the AS. */ + if (!osmo_ss7_as_has_asp(as, asp)) { + LOGPASP(asp, DLM3UA, LOGL_ERROR, + "%s(): This Application Server Process is not part of the AS resolved by" + " routing context %u\n", + __func__, rctx); return M3UA_ERR_NO_CONFGD_AS_FOR_ASP; + } /* FIXME: check for AS state == ACTIVE */ @@ -556,6 +572,10 @@ static int m3ua_rx_xfer(struct osmo_ss7_asp *asp, struct xua_msg *xua) dh = data_hdr_from_m3ua(xua); OSMO_ASSERT(dh); m3ua_dh_to_xfer_param(&xua->mtp, dh); + LOGPASP(asp, DLM3UA, LOGL_DEBUG, + "%s(): M3UA data header: opc=%u=%s dpc=%u=%s\n", + __func__, xua->mtp.opc, osmo_ss7_pointcode_print(asp->inst, xua->mtp.opc), + xua->mtp.dpc, osmo_ss7_pointcode_print2(asp->inst, xua->mtp.dpc)); /* remove ROUTE_CTX as in the routing case we want to add a new * routing context on the outbound side */ diff --git a/src/osmo_ss7.c b/src/osmo_ss7.c index 9477543..c13c588 100644 --- a/src/osmo_ss7.c +++ b/src/osmo_ss7.c @@ -245,17 +245,14 @@ err: return -EINVAL; } -/* print a pointcode according to the structure configured for this - * ss7_instance */ -const char *osmo_ss7_pointcode_print(struct osmo_ss7_instance *inst, uint32_t pc) +const char *_osmo_ss7_pointcode_print(char *buf, size_t len, struct osmo_ss7_instance *inst, uint32_t pc) { - static char buf[MAX_PC_STR_LEN]; const struct osmo_ss7_pc_fmt *pc_fmt = inst ? &inst->cfg.pc_fmt : &default_pc_fmt; unsigned int num_comp_exp = num_pc_comp_exp(pc_fmt); const char *fmtstr = gen_pc_fmtstr(pc_fmt, &num_comp_exp); OSMO_ASSERT(fmtstr); - snprintf(buf, sizeof(buf), fmtstr, + snprintf(buf, len, fmtstr, pc_comp_shift_and_mask(pc_fmt, 0, pc), pc_comp_shift_and_mask(pc_fmt, 1, pc), pc_comp_shift_and_mask(pc_fmt, 2, pc)); @@ -263,6 +260,23 @@ const char *osmo_ss7_pointcode_print(struct osmo_ss7_instance *inst, uint32_t pc return buf; } + +/* print a pointcode according to the structure configured for this + * ss7_instance */ +const char *osmo_ss7_pointcode_print(struct osmo_ss7_instance *inst, uint32_t pc) +{ + static char buf[MAX_PC_STR_LEN]; + return _osmo_ss7_pointcode_print(buf, sizeof(buf), inst, pc); +} + +/* same as osmo_ss7_pointcode_print() but using a separate buffer, useful for multiple point codes in the + * same LOGP/printf. */ +const char *osmo_ss7_pointcode_print2(struct osmo_ss7_instance *inst, uint32_t pc) +{ + static char buf[MAX_PC_STR_LEN]; + return _osmo_ss7_pointcode_print(buf, sizeof(buf), inst, pc); +} + int osmo_ss7_pointcode_parse_mask_or_len(struct osmo_ss7_instance *inst, const char *in) { unsigned int width = get_pc_width(inst ? &inst->cfg.pc_fmt : &default_pc_fmt); @@ -740,10 +754,15 @@ osmo_ss7_route_create(struct osmo_ss7_route_table *rtbl, uint32_t pc, rt->cfg.pc = pc; rt->cfg.mask = mask; rt->cfg.linkset_name = talloc_strdup(rt, linkset_name); - if (lset) + if (lset) { rt->dest.linkset = lset; - else + LOGSS7(rtbl->inst, LOGL_INFO, "Creating route: pc=%u=%s mask=0x%x via linkset '%s'\n", + pc, osmo_ss7_pointcode_print(rtbl->inst, pc), mask, lset->cfg.name); + } else { rt->dest.as = as; + LOGSS7(rtbl->inst, LOGL_INFO, "Creating route: pc=%u=%s mask=0x%x via AS '%s'\n", + pc, osmo_ss7_pointcode_print(rtbl->inst, pc), mask, as->cfg.name); + } rt->rtable = rtbl; route_insert_sorted(rtbl, rt); diff --git a/src/osmo_ss7_hmrt.c b/src/osmo_ss7_hmrt.c index e66762d..8165a36 100644 --- a/src/osmo_ss7_hmrt.c +++ b/src/osmo_ss7_hmrt.c @@ -138,20 +138,33 @@ static int hmrt_message_for_routing(struct osmo_ss7_instance *inst, /* FIXME: Transmit over respective Link */ if (rt->dest.as) { struct osmo_ss7_as *as = rt->dest.as; + DEBUGP(DLSS7, + "Found route for dpc=%u=%s: pc=%u=%s mask=0x%x" + " via AS %s proto=%s\n", + dpc, osmo_ss7_pointcode_print(inst, dpc), + rt->cfg.pc, osmo_ss7_pointcode_print2(inst, rt->cfg.pc), rt->cfg.mask, + as->cfg.name, osmo_ss7_asp_protocol_name(as->cfg.proto)); + switch (as->cfg.proto) { case OSMO_SS7_ASP_PROT_M3UA: + DEBUGP(DLSS7, "rt->dest.as proto is M3UA for dpc=%u=%s\n", + dpc, osmo_ss7_pointcode_print(inst, dpc)); return m3ua_tx_xua_as(as,xua); case OSMO_SS7_ASP_PROT_IPA: return ipa_tx_xua_as(as, xua); default: LOGP(DLSS7, LOGL_ERROR, "MTP message " - "for ASP of unknown protocol%u\n", + "for ASP of unknown protocol %u\n", as->cfg.proto); break; } } else if (rt->dest.linkset) { - LOGP(DLSS7, LOGL_ERROR, "MTP-TRANSFER.req for linkset" - "%s unsupported\n",rt->dest.linkset->cfg.name); + LOGP(DLSS7, LOGL_ERROR, + "Found route for dpc=%u=%s: pc=%u=%s mask=0x%x" + " via linkset %s, but MTP-TRANSFER.req unsupported for linkset.\n", + dpc, osmo_ss7_pointcode_print(inst, dpc), + rt->cfg.pc, osmo_ss7_pointcode_print2(inst, rt->cfg.pc), rt->cfg.mask, + rt->dest.linkset->cfg.name); } else OSMO_ASSERT(0); } else { @@ -171,8 +184,12 @@ int m3ua_hmdc_rx_from_l2(struct osmo_ss7_instance *inst, struct xua_msg *xua) { uint32_t dpc = xua->mtp.dpc; if (osmo_ss7_pc_is_local(inst, dpc)) { + DEBUGP(DLSS7, "%s(): found dpc=%u=%s as local\n", __func__, + dpc, osmo_ss7_pointcode_print(inst, dpc)); return hmdt_message_for_distribution(inst, xua); } else { + DEBUGP(DLSS7, "%s(): dpc=%u=%s not local, message is for routing\n", __func__, + dpc, osmo_ss7_pointcode_print(inst, dpc)); return hmrt_message_for_routing(inst, xua); } } diff --git a/src/sccp_scoc.c b/src/sccp_scoc.c index fbb6ef8..9502953 100644 --- a/src/sccp_scoc.c +++ b/src/sccp_scoc.c @@ -1436,8 +1436,13 @@ static void sccp_scoc_rx_unass_local_ref(struct osmo_sccp_instance *inst, /* process received message for invalid source local reference */ static void sccp_scoc_rx_inval_src_ref(struct sccp_connection *conn, - struct xua_msg *xua) + struct xua_msg *xua, + uint32_t inval_src_ref) { + LOGP(DLSCCP, LOGL_NOTICE, + "Received message for source ref %u on conn with mismatching remote ref %u\n", + inval_src_ref, conn->remote_ref); + /* we have received a message with invalid source local * reference and thus apply the action indicated in Table * B.2/Q.714 */ @@ -1463,9 +1468,13 @@ static void sccp_scoc_rx_inval_src_ref(struct sccp_connection *conn, } /* process received message for invalid origin point code */ -static void sccp_scoc_rx_inval_opc(struct osmo_sccp_instance *inst, +static void sccp_scoc_rx_inval_opc(struct sccp_connection *conn, struct xua_msg *xua) { + LOGP(DLSCCP, LOGL_NOTICE, + "Received message for opc=%u=%s on conn with mismatching remote pc=%u=%s\n", + xua->mtp.opc, osmo_ss7_pointcode_print(conn->inst->ss7, xua->mtp.opc), + conn->remote_pc, osmo_ss7_pointcode_print2(conn->inst->ss7, conn->remote_pc)); /* we have received a message with invalid origin PC and thus * apply the action indiacted in Table B.2/Q.714 */ switch (xua->hdr.msg_type) { @@ -1473,7 +1482,7 @@ static void sccp_scoc_rx_inval_opc(struct osmo_sccp_instance *inst, case SUA_CO_RESRE: /* RSR */ case SUA_CO_RESCO: /* RSC */ /* Send ERR */ - tx_coerr_from_xua(inst, xua, SCCP_ERROR_POINT_CODE_MISMATCH); + tx_coerr_from_xua(conn->inst, xua, SCCP_ERROR_POINT_CODE_MISMATCH); break; case SUA_CO_RELCO: /* RLC */ case SUA_CO_CODT: /* DT1 */ @@ -1544,14 +1553,14 @@ void sccp_scoc_rx_from_scrc(struct osmo_sccp_instance *inst, * the one we saved in local state */ src_loc_ref = xua_msg_get_u32(xua, SUA_IEI_SRC_REF); if (src_loc_ref != conn->remote_ref) { - sccp_scoc_rx_inval_src_ref(conn, xua); + sccp_scoc_rx_inval_src_ref(conn, xua, src_loc_ref); return; } } /* Check if received OPC != the remote_pc we stored locally */ if (xua->mtp.opc != conn->remote_pc) { - sccp_scoc_rx_inval_opc(inst, xua); + sccp_scoc_rx_inval_opc(conn, xua); return; } } -- cgit v1.2.3