neels has uploaded this change for review. ( https://gerrit.osmocom.org/c/osmo-hnbgw/+/33171 )
Change subject: tweak lots of logging ......................................................................
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; }
-
neels