neels has uploaded this change for review.
tweak lots of logging
Make lots of small tweaks in logging around RUA to SCCP context maps, CN
link selection and HNBAP:
- remove duplicate log context (e.g. LOGHNB() already shows the HNB Id)
- bring more sense into logging categories and levels / reduce noise
- add and clarify the details being logged at what points in time
Related: SYS#6412
Change-Id: I41275d8c3e272177976a9302795884666c35cd06
---
M include/osmocom/hnbgw/context_map.h
M src/osmo-hnbgw/context_map.c
M src/osmo-hnbgw/context_map_sccp.c
M src/osmo-hnbgw/hnbgw.c
M src/osmo-hnbgw/hnbgw_cn.c
M src/osmo-hnbgw/hnbgw_hnbap.c
M src/osmo-hnbgw/hnbgw_l3.c
M src/osmo-hnbgw/hnbgw_rua.c
8 files changed, 97 insertions(+), 41 deletions(-)
git pull ssh://gerrit.osmocom.org:29418/osmo-hnbgw refs/changes/71/33171/1
diff --git a/include/osmocom/hnbgw/context_map.h b/include/osmocom/hnbgw/context_map.h
index 7017491..f7335a7 100644
--- a/include/osmocom/hnbgw/context_map.h
+++ b/include/osmocom/hnbgw/context_map.h
@@ -7,8 +7,9 @@
#define LOG_MAP(HNB_CTX_MAP, SUBSYS, LEVEL, FMT, ARGS...) \
LOGHNB((HNB_CTX_MAP) ? (HNB_CTX_MAP)->hnb_ctx : NULL, \
- SUBSYS, LEVEL, "RUA-%u %s MI=%s%s%s: " FMT, \
+ SUBSYS, LEVEL, "RUA-%u SCCP-%u %s MI=%s%s%s: " FMT, \
(HNB_CTX_MAP) ? (HNB_CTX_MAP)->rua_ctx_id : 0, \
+ (HNB_CTX_MAP) ? (HNB_CTX_MAP)->scu_conn_id : 0, \
(HNB_CTX_MAP) ? \
((HNB_CTX_MAP)->cnlink ? (HNB_CTX_MAP)->cnlink->name \
: ((HNB_CTX_MAP)->is_ps ? "PS" : "CS")) \
diff --git a/src/osmo-hnbgw/context_map.c b/src/osmo-hnbgw/context_map.c
index 13aae0e..045053c 100644
--- a/src/osmo-hnbgw/context_map.c
+++ b/src/osmo-hnbgw/context_map.c
@@ -26,6 +26,8 @@
#include <osmocom/core/timer.h>
+#include <osmocom/netif/stream.h>
+
#include <osmocom/sigtran/sccp_helpers.h>
#include <osmocom/hnbgw/hnbgw_cn.h>
@@ -92,7 +94,7 @@
llist_add_tail(&map->hnb_list, &hnb->map_list);
- LOG_MAP(map, DRUA, LOGL_INFO, "New RUA CTX\n");
+ LOG_MAP(map, DRUA, LOGL_DEBUG, "New RUA CTX\n");
return map;
}
@@ -117,12 +119,23 @@
map->cnlink = cnlink_selected;
map->scu_conn_id = new_scu_conn_id;
+ map_sccp_fsm_alloc(map);
+
llist_add_tail(&map->hnbgw_cnlink_entry, &cnlink_selected->map_list);
hash_add(hsu->hnbgw_context_map_by_conn_id, &map->hnbgw_sccp_user_entry, new_scu_conn_id);
- LOG_MAP(map, DMAIN, LOGL_INFO, "Creating new Mapping RUA CTX %u <-> SCU Conn ID %u to %s on %s\n",
- map->rua_ctx_id, new_scu_conn_id, cnlink_selected->name, hsu->name);
+ LOGP(DRUA, LOGL_NOTICE, "New conn: %s '%s' RUA-%u <-> SCCP-%u %s%s%s %s l=%s<->r=%s\n",
+ osmo_sock_get_name2_c(OTC_SELECT, osmo_stream_srv_get_ofd(map->hnb_ctx->conn)->fd),
+ hnb_context_name(map->hnb_ctx), map->rua_ctx_id,
+ new_scu_conn_id,
+ cnlink_selected->name,
+ cnlink_selected->use.remote_addr_name ? " ": "",
+ cnlink_selected->use.remote_addr_name ? : "",
+ hsu->name,
+ osmo_ss7_pointcode_print(hsu->ss7, hsu->local_addr.pc),
+ osmo_ss7_pointcode_print2(hsu->ss7, cnlink_selected->remote_addr.pc)
+ );
return 0;
}
diff --git a/src/osmo-hnbgw/context_map_sccp.c b/src/osmo-hnbgw/context_map_sccp.c
index 3bdec8c..1f2cd09 100644
--- a/src/osmo-hnbgw/context_map_sccp.c
+++ b/src/osmo-hnbgw/context_map_sccp.c
@@ -81,7 +81,8 @@
struct osmo_fsm_inst *fi = osmo_fsm_inst_alloc(&map_sccp_fsm, map, map, LOGL_DEBUG, NULL);
OSMO_ASSERT(fi);
osmo_fsm_inst_update_id_f_sanitize(fi, '-', "%s-%s-SCCP-%u", hnb_context_name(map->hnb_ctx),
- map->is_ps ? "PS" : "CS", map->scu_conn_id);
+ map->cnlink ? map->cnlink->name : (map->is_ps ? "PS" : "CS"),
+ map->scu_conn_id);
OSMO_ASSERT(map->sccp_fi == NULL);
map->sccp_fi = fi;
diff --git a/src/osmo-hnbgw/hnbgw.c b/src/osmo-hnbgw/hnbgw.c
index f435043..dfeda53 100644
--- a/src/osmo-hnbgw/hnbgw.c
+++ b/src/osmo-hnbgw/hnbgw.c
@@ -351,13 +351,30 @@
const char *hnb_context_name(struct hnb_context *ctx)
{
+ char *result;
if (!ctx)
return "NULL";
+ if (ctx->conn) {
+ char hostbuf_r[INET6_ADDRSTRLEN];
+ char portbuf_r[6];
+ int fd = osmo_stream_srv_get_ofd(ctx->conn)->fd;
+
+ /* get remote addr */
+ if (osmo_sock_get_ip_and_port(fd, hostbuf_r, sizeof(hostbuf_r), portbuf_r, sizeof(portbuf_r), false) == 0)
+ result = talloc_asprintf(OTC_SELECT, "%s:%s", hostbuf_r, portbuf_r);
+ else
+ result = "?";
+ }
+ else {
+ result = "disconnected";
+ }
+
if (g_hnbgw->config.log_prefix_hnb_id)
- return ctx->identity_info;
+ result = talloc_asprintf(OTC_SELECT, "%s %s", result, ctx->identity_info);
else
- return umts_cell_id_name(&ctx->id);
+ result = talloc_asprintf(OTC_SELECT, "%s %s", result, umts_cell_id_name(&ctx->id));
+ return result;
}
void hnb_context_release_ue_state(struct hnb_context *ctx)
diff --git a/src/osmo-hnbgw/hnbgw_cn.c b/src/osmo-hnbgw/hnbgw_cn.c
index f33023e..d577fb4 100644
--- a/src/osmo-hnbgw/hnbgw_cn.c
+++ b/src/osmo-hnbgw/hnbgw_cn.c
@@ -298,7 +298,7 @@
return -ENOENT;
if (param->called_addr.ssn != OSMO_SCCP_SSN_RANAP) {
- LOGP(DMAIN, LOGL_NOTICE, "N-UNITDATA.ind for unknown SSN %u\n",
+ LOGP(DCN, LOGL_NOTICE, "N-UNITDATA.ind for unknown SSN %u\n",
param->called_addr.ssn);
return -1;
}
@@ -316,7 +316,7 @@
if (!map || !map->cnlink)
return -ENOENT;
- LOGP(DMAIN, LOGL_DEBUG, "handle_cn_conn_conf() conn_id=%d, addrs: called=%s calling=%s responding=%s\n",
+ LOGP(DCN, LOGL_DEBUG, "handle_cn_conn_conf() conn_id=%d, addrs: called=%s calling=%s responding=%s\n",
param->conn_id,
cnlink_sccp_addr_to_str(map->cnlink, ¶m->called_addr),
cnlink_sccp_addr_to_str(map->cnlink, ¶m->calling_addr),
@@ -349,7 +349,7 @@
if (!map || !map->cnlink)
return -ENOENT;
- LOGP(DMAIN, LOGL_DEBUG, "handle_cn_disc_ind() conn_id=%u responding_addr=%s\n",
+ LOGP(DCN, LOGL_DEBUG, "handle_cn_disc_ind() conn_id=%u responding_addr=%s\n",
param->conn_id,
cnlink_sccp_addr_to_str(map->cnlink, ¶m->responding_addr));
@@ -364,10 +364,10 @@
struct osmo_scu_prim *prim = (struct osmo_scu_prim *) oph;
int rc = 0;
- LOGP(DMAIN, LOGL_DEBUG, "sccp_sap_up(%s)\n", osmo_scu_prim_name(oph));
+ LOGP(DCN, LOGL_DEBUG, "sccp_sap_up(%s)\n", osmo_scu_prim_name(oph));
if (!scu) {
- LOGP(DMAIN, LOGL_ERROR,
+ LOGP(DCN, LOGL_ERROR,
"sccp_sap_up(): NULL osmo_sccp_user, cannot send prim (sap %u prim %u op %d)\n",
oph->sap, oph->primitive, oph->operation);
return -1;
@@ -375,7 +375,7 @@
hsu = osmo_sccp_user_get_priv(scu);
if (!hsu) {
- LOGP(DMAIN, LOGL_ERROR,
+ LOGP(DCN, LOGL_ERROR,
"sccp_sap_up(): NULL hnbgw_sccp_user, cannot send prim (sap %u prim %u op %d)\n",
oph->sap, oph->primitive, oph->operation);
return -1;
@@ -397,11 +397,11 @@
rc = handle_cn_disc_ind(hsu, &prim->u.disconnect, oph);
break;
case OSMO_PRIM(OSMO_SCU_PRIM_N_PCSTATE, PRIM_OP_INDICATION):
- LOGP(DMAIN, LOGL_DEBUG, "Ignoring prim %s from SCCP USER SAP\n",
+ LOGP(DCN, LOGL_DEBUG, "Ignoring prim %s from SCCP USER SAP\n",
osmo_scu_prim_hdr_name_c(OTC_SELECT, oph));
break;
default:
- LOGP(DMAIN, LOGL_ERROR,
+ LOGP(DCN, LOGL_ERROR,
"Received unknown prim %u from SCCP USER SAP\n",
OSMO_PRIM_HDR(oph));
break;
@@ -426,7 +426,7 @@
if (!addr_name) {
osmo_sccp_make_addr_pc_ssn(dest, default_pc, OSMO_SCCP_SSN_RANAP);
if (label)
- LOGP(DMAIN, LOGL_INFO, "%s remote addr not configured, using default: %s\n", label,
+ LOGP(DCN, LOGL_INFO, "%s remote addr not configured, using default: %s\n", label,
osmo_sccp_addr_name(*ss7, dest));
return 0;
}
@@ -434,7 +434,7 @@
*ss7 = osmo_sccp_addr_by_name(dest, addr_name);
if (!*ss7) {
if (label)
- LOGP(DMAIN, LOGL_ERROR, "%s remote addr: no such SCCP address book entry: '%s'\n",
+ LOGP(DCN, LOGL_ERROR, "%s remote addr: no such SCCP address book entry: '%s'\n",
label, addr_name);
return -1;
}
@@ -443,14 +443,11 @@
if (!addr_has_pc_and_ssn(dest)) {
if (label)
- LOGP(DMAIN, LOGL_ERROR, "Invalid/incomplete %s remote-addr: %s\n",
+ LOGP(DCN, LOGL_ERROR, "Invalid/incomplete %s remote-addr: %s\n",
label, osmo_sccp_addr_name(*ss7, dest));
return -1;
}
- if (label)
- LOGP(DRANAP, LOGL_NOTICE, "Remote %s SCCP addr: %s\n",
- label, osmo_sccp_addr_name(*ss7, dest));
return 0;
}
@@ -512,6 +509,17 @@
cnlink->hnbgw_sccp_user = NULL;
}
+static void hnbgw_cnlink_log_self(struct hnbgw_cnlink *cnlink)
+{
+ struct osmo_ss7_instance *ss7 = cnlink->hnbgw_sccp_user->ss7;
+ LOG_CNLINK(cnlink, DCN, LOGL_NOTICE, "using: cs7-%u %s <-> %s %s %s\n",
+ ss7->cfg.id,
+ /* printing the entire SCCP address is quite long, rather just print the point-code */
+ osmo_ss7_pointcode_print(ss7, cnlink->hnbgw_sccp_user->local_addr.pc),
+ osmo_ss7_pointcode_print2(ss7, cnlink->remote_addr.pc),
+ cnlink->name, cnlink->use.remote_addr_name);
+}
+
/* If not present yet, set up all of osmo_ss7_instance, osmo_sccp_instance and hnbgw_sccp_user for the given cnlink.
* The cs7 instance nr to use is determined by cnlink->remote_addr_name, or cs7 instance 0 if that is not present.
* Set cnlink->hnbgw_sccp_user to the new SCCP instance. Return 0 on success, negative on error. */
@@ -570,8 +578,9 @@
if (hsu->ss7 != ss7)
continue;
cnlink->hnbgw_sccp_user = hsu;
- LOG_CNLINK(cnlink, DCN, LOGL_NOTICE, "using existing SCCP instance %s on cs7 instance %u\n",
+ LOG_CNLINK(cnlink, DCN, LOGL_DEBUG, "using existing SCCP instance %s on cs7 instance %u\n",
hsu->name, ss7->cfg.id);
+ hnbgw_cnlink_log_self(cnlink);
return 0;
}
/* else cnlink->hnbgw_sccp_user stays NULL and is set up below. */
@@ -605,7 +614,7 @@
sccp_user = osmo_sccp_user_bind_pc(sccp, "OsmoHNBGW", sccp_sap_up, OSMO_SCCP_SSN_RANAP, local_pc);
if (!sccp_user) {
- LOGP(DMAIN, LOGL_ERROR, "Failed to init SCCP User\n");
+ LOGP(DCN, LOGL_ERROR, "Failed to init SCCP User\n");
return -1;
}
@@ -622,6 +631,8 @@
llist_add_tail(&hsu->entry, &g_hnbgw->sccp.users);
cnlink->hnbgw_sccp_user = hsu;
+
+ hnbgw_cnlink_log_self(cnlink);
return 0;
}
@@ -661,6 +672,7 @@
INIT_LLIST_HEAD(&cnlink->map_list);
llist_add_tail(&cnlink->entry, &cnpool->cnlinks);
+ LOG_CNLINK(cnlink, DCN, LOGL_DEBUG, "allocated\n");
return cnlink;
}
@@ -831,8 +843,7 @@
return NULL;
}
- LOGP(DCN, LOGL_DEBUG, "New subscriber MI=%s: CN link round-robin selects %s %d\n",
- osmo_mobile_identity_to_str_c(OTC_SELECT, &map->l3.mi), cnpool->peer_name, cnlink->nr);
+ LOG_MAP(map, DCN, LOGL_INFO, "CN link round-robin selects %s %d\n", cnpool->peer_name, cnlink->nr);
if (is_null_nri)
rate_ctr_inc(rate_ctr_group_get_ctr(cnlink->ctrs, CNLINK_CTR_CNPOOL_SUBSCR_REATTACH));
diff --git a/src/osmo-hnbgw/hnbgw_hnbap.c b/src/osmo-hnbgw/hnbgw_hnbap.c
index 85adccd..06d1a9d 100644
--- a/src/osmo-hnbgw/hnbgw_hnbap.c
+++ b/src/osmo-hnbgw/hnbgw_hnbap.c
@@ -119,7 +119,7 @@
ASN_STRUCT_FREE_CONTENTS_ONLY(asn_DEF_HNBAP_HNBRegisterAccept, &accept_out);
- LOGHNB(ctx, DHNBAP, LOGL_NOTICE, "Accepting HNB-REGISTER-REQ from %s\n", ctx->identity_info);
+ LOGHNB(ctx, DHNBAP, LOGL_NOTICE, "Accepting HNB-REGISTER-REQ\n");
return hnbgw_hnbap_tx(ctx, msg);
}
@@ -409,14 +409,10 @@
int rc;
struct osmo_plmn_id plmn;
struct osmo_fd *ofd = osmo_stream_srv_get_ofd(ctx->conn);
- char name[OSMO_SOCK_NAME_MAXLEN];
-
- osmo_sock_get_name_buf(name, sizeof(name), ofd->fd);
rc = hnbap_decode_hnbregisterrequesties(&ies, in);
if (rc < 0) {
- LOGHNB(ctx, DHNBAP, LOGL_ERROR, "Failure to decode HNB-REGISTER-REQ %s from %s: rc=%d\n",
- ctx->identity_info, name, rc);
+ LOGHNB(ctx, DHNBAP, LOGL_ERROR, "Failure to decode HNB-REGISTER-REQ: rc=%d\n", rc);
return rc;
}
@@ -460,17 +456,15 @@
/* If new conn registering same HNB is from anoter remote addr+port, let's reject it to avoid
* misconfigurations or someone trying to impersonate an already working HNB: */
- LOGHNB(ctx, DHNBAP, LOGL_ERROR, "rejecting HNB-REGISTER-REQ with duplicate cell identity "
- "MCC=%u,MNC=%u,LAC=%u,RAC=%u,SAC=%u,CID=%u from %s\n",
- ctx->id.mcc, ctx->id.mnc, ctx->id.lac, ctx->id.rac, ctx->id.sac, ctx->id.cid, name);
+ LOGHNB(ctx, DHNBAP, LOGL_ERROR, "rejecting HNB-REGISTER-REQ with duplicate cell identity %s\n",
+ umts_cell_id_name(&ctx->id));
hnbap_free_hnbregisterrequesties(&ies);
return hnbgw_tx_hnb_register_rej(ctx);
}
}
- LOGHNB(ctx, DHNBAP, LOGL_DEBUG, "HNB-REGISTER-REQ %s MCC=%u,MNC=%u,LAC=%u,RAC=%u,SAC=%u,CID=%u from %s%s\n",
- ctx->identity_info, ctx->id.mcc, ctx->id.mnc, ctx->id.lac, ctx->id.rac, ctx->id.sac, ctx->id.cid,
- name, ctx->hnb_registered ? " (re-connecting)" : "");
+ LOGHNB(ctx, DHNBAP, LOGL_DEBUG, "HNB-REGISTER-REQ %s %s%s\n",
+ ctx->identity_info, umts_cell_id_name(&ctx->id), ctx->hnb_registered ? " (re-connecting)" : "");
/* The HNB is already registered, and we are seeing a new HNB Register Request. The HNB has restarted
* without us noticing. Clearly, the HNB does not expect any UE state to be active here, so discard any
diff --git a/src/osmo-hnbgw/hnbgw_l3.c b/src/osmo-hnbgw/hnbgw_l3.c
index 4547419..607bfc5 100644
--- a/src/osmo-hnbgw/hnbgw_l3.c
+++ b/src/osmo-hnbgw/hnbgw_l3.c
@@ -193,17 +193,20 @@
gsm48_decode_lai2(&lu->lai, &old_lai);
map->l3.from_other_plmn = (osmo_plmn_cmp(&old_lai.plmn, local_plmn) != 0);
- LOGP(DCN, LOGL_DEBUG, "LU from_other_plmn=%d\n", map->l3.from_other_plmn);
+ if (map->l3.from_other_plmn)
+ LOGP(DRUA, LOGL_INFO, "LU from other PLMN: old LAI=%s my PLMN=%s\n",
+ osmo_plmn_name_c(OTC_SELECT, &old_lai.plmn),
+ osmo_plmn_name_c(OTC_SELECT, local_plmn));
break;
case GSM48_MT_MM_CM_SERV_REQ:
if (len < sizeof(*gh) + sizeof(*cm)) {
- LOGP(DCN, LOGL_ERROR, "CM Service Req message too short\n");
+ LOGP(DRUA, LOGL_ERROR, "CM Service Req message too short\n");
break;
}
cm = (struct gsm48_service_request *)&gh->data[0];
map->l3.is_emerg = (cm->cm_service_type == GSM48_CMSERV_EMERGENCY);
- LOGP(DCN, LOGL_DEBUG, "CM Service is_emerg=%d\n", map->l3.is_emerg);
+ LOGP(DRUA, LOGL_DEBUG, "CM Service is_emerg=%d\n", map->l3.is_emerg);
break;
default:
diff --git a/src/osmo-hnbgw/hnbgw_rua.c b/src/osmo-hnbgw/hnbgw_rua.c
index 2a7dc20..4e75c91 100644
--- a/src/osmo-hnbgw/hnbgw_rua.c
+++ b/src/osmo-hnbgw/hnbgw_rua.c
@@ -231,7 +231,6 @@
return NULL;
}
- LOG_MAP(map, DCN, LOGL_INFO, "establishing SCCP link: selected %s\n", cnlink->name);
return map;
}
To view, visit change 33171. To unsubscribe, or for help writing mail filters, visit settings.