From 549ebc7d6c001b9ce134c7462f621335dbf671b9 Mon Sep 17 00:00:00 2001 From: Max Date: Fri, 18 Nov 2016 14:07:04 +0100 Subject: [PATCH] Improve GPRS logging * log xid type as string instead of int * log packet encryption status, algorithm and IOV-UI in debug mode * print encryption parameters when dumping llme via vty * log key propagation from MM to LLC Related: OS#1794 Change-Id: I30c38fdeb0b88bb39bdb9928851300bc79e6aec6 --- openbsc/include/openbsc/gprs_llc.h | 4 +++- openbsc/src/gprs/gprs_gb_parse.c | 2 +- openbsc/src/gprs/gprs_llc.c | 28 +++++++++++++++++++--------- openbsc/src/gprs/gprs_llc_parse.c | 16 ++++++++++++---- openbsc/src/gprs/gprs_llc_vty.c | 8 +++++--- openbsc/src/gprs/gprs_llc_xid.c | 23 +++++++++++++++++++++-- openbsc/src/gprs/gprs_sgsn.c | 2 ++ 7 files changed, 63 insertions(+), 20 deletions(-) diff --git a/openbsc/include/openbsc/gprs_llc.h b/openbsc/include/openbsc/gprs_llc.h index 8b014670d..8bc226781 100644 --- a/openbsc/include/openbsc/gprs_llc.h +++ b/openbsc/include/openbsc/gprs_llc.h @@ -46,6 +46,8 @@ enum gprs_llc_xid_type { GPRS_LLC_XID_T_RESET = 12, }; +extern const struct value_string gprs_llc_xid_type_names[]; + /* TS 04.64 Section 7.1.2 Table 7: LLC layer primitives (GMM/SNDCP/SMS/TOM) */ /* TS 04.65 Section 5.1.2 Table 2: Service primitives used by SNDCP */ enum gprs_llc_primitive { @@ -270,7 +272,7 @@ void gprs_llme_copy_key(struct sgsn_mm_ctx *mm, struct gprs_llc_llme *llme); /* parse a GPRS LLC header, also check for invalid frames */ int gprs_llc_hdr_parse(struct gprs_llc_hdr_parsed *ghp, uint8_t *llc_hdr, int len); -void gprs_llc_hdr_dump(struct gprs_llc_hdr_parsed *gph); +void gprs_llc_hdr_dump(struct gprs_llc_hdr_parsed *gph, struct gprs_llc_lle *lle); int gprs_llc_fcs(uint8_t *data, unsigned int len); diff --git a/openbsc/src/gprs/gprs_gb_parse.c b/openbsc/src/gprs/gprs_gb_parse.c index f11d93aef..9befa3958 100644 --- a/openbsc/src/gprs/gprs_gb_parse.c +++ b/openbsc/src/gprs/gprs_gb_parse.c @@ -398,7 +398,7 @@ int gprs_gb_parse_llc(uint8_t *llc, size_t llc_len, /* parse LLC */ rc = gprs_llc_hdr_parse(ghp, llc, llc_len); - gprs_llc_hdr_dump(ghp); + gprs_llc_hdr_dump(ghp, NULL); if (rc != 0) { LOGP(DLLC, LOGL_NOTICE, "Error during LLC header parsing\n"); return 0; diff --git a/openbsc/src/gprs/gprs_llc.c b/openbsc/src/gprs/gprs_llc.c index 021502932..c2c3900e6 100644 --- a/openbsc/src/gprs/gprs_llc.c +++ b/openbsc/src/gprs/gprs_llc.c @@ -39,6 +39,7 @@ #include #include #include +#include #include #include #include @@ -178,8 +179,10 @@ static int gprs_llc_process_xid_conf(uint8_t *bytes, int bytes_len, * inquiry. There is a remainig risk of * malfunction! */ LOGP(DLLC, LOGL_NOTICE, - "Ignoring XID-Field: XID: type=%d, data_len=%d, data=%s\n", - xid_field->type, xid_field->data_len, + "Ignoring XID-Field: XID: type %s, data_len=%d, data=%s\n", + get_value_string(gprs_llc_xid_type_names, + xid_field->type), + xid_field->data_len, osmo_hexdump_nospc(xid_field->data, xid_field->data_len)); } @@ -232,8 +235,10 @@ static int gprs_llc_process_xid_ind(uint8_t *bytes_request, * when a phone submits values which defer from * the default! */ LOGP(DLLC, LOGL_NOTICE, - "Echoing XID-Field: XID: type=%d, data_len=%d, data=%s\n", - xid_field->type, xid_field->data_len, + "Echoing XID-Field: XID: type %s, data_len=%d, data=%s\n", + get_value_string(gprs_llc_xid_type_names, + xid_field->type), + xid_field->data_len, osmo_hexdump_nospc(xid_field->data, xid_field->data_len)); xid_field_response = @@ -308,7 +313,6 @@ static void rx_llc_xid(struct gprs_llc_lle *lle, } } - /* Set of LL-XID negotiation (See also: TS 101 351, Section 7.2.2.4) */ int gprs_ll_xid_req(struct gprs_llc_lle *lle, struct gprs_llc_xid_field *l3_xid_field) @@ -319,6 +323,7 @@ int gprs_ll_xid_req(struct gprs_llc_lle *lle, int xid_bytes_len; uint8_t *xid; struct msgb *msg; + const char *ftype; /* Generate XID */ xid_bytes_len = @@ -331,7 +336,13 @@ int gprs_ll_xid_req(struct gprs_llc_lle *lle, msg = msgb_alloc_headroom(4096, 1024, "LLC_XID"); xid = msgb_put(msg, xid_bytes_len); memcpy(xid, xid_bytes, xid_bytes_len); - LOGP(DLLC, LOGL_NOTICE, "Sending XID request to phone...\n"); + if (l3_xid_field) + ftype = get_value_string(gprs_llc_xid_type_names, + l3_xid_field->type); + else + ftype = "NULL"; + LOGP(DLLC, LOGL_NOTICE, "Sending XID type %s (%d bytes) request" + " to phone...\n", ftype, xid_bytes_len); gprs_llc_tx_xid(lle, msg, 1); } else { LOGP(DLLC, LOGL_ERROR, @@ -858,7 +869,7 @@ int gprs_llc_rcvmsg(struct msgb *msg, struct tlv_parsed *tv) { struct gprs_llc_hdr *lh = (struct gprs_llc_hdr *) msgb_llch(msg); struct gprs_llc_hdr_parsed llhp; - struct gprs_llc_lle *lle; + struct gprs_llc_lle *lle = NULL; bool drop_cipherable = false; int rc = 0; @@ -866,7 +877,6 @@ int gprs_llc_rcvmsg(struct msgb *msg, struct tlv_parsed *tv) memset(&llhp, 0, sizeof(llhp)); rc = gprs_llc_hdr_parse(&llhp, (uint8_t *) lh, TLVP_LEN(tv, BSSGP_IE_LLC_PDU)); - gprs_llc_hdr_dump(&llhp); if (rc < 0) { LOGP(DLLC, LOGL_NOTICE, "Error during LLC header parsing\n"); return rc; @@ -899,7 +909,7 @@ int gprs_llc_rcvmsg(struct msgb *msg, struct tlv_parsed *tv) } return 0; } - + gprs_llc_hdr_dump(&llhp, lle); /* reset age computation */ lle->llme->age_timestamp = GPRS_LLME_RESET_AGE; diff --git a/openbsc/src/gprs/gprs_llc_parse.c b/openbsc/src/gprs/gprs_llc_parse.c index b1f1a56dd..a5a7a7122 100644 --- a/openbsc/src/gprs/gprs_llc_parse.c +++ b/openbsc/src/gprs/gprs_llc_parse.c @@ -67,11 +67,19 @@ int gprs_llc_fcs(uint8_t *data, unsigned int len) return fcs_calc; } -void gprs_llc_hdr_dump(struct gprs_llc_hdr_parsed *gph) +void gprs_llc_hdr_dump(struct gprs_llc_hdr_parsed *gph, struct gprs_llc_lle *lle) { - DEBUGP(DLLC, "LLC SAPI=%u %c %c FCS=0x%06x", - gph->sapi, gph->is_cmd ? 'C' : 'R', gph->ack_req ? 'A' : ' ', - gph->fcs); + const char *gea; + uint32_t iov_ui = 0; + if (lle) { + gea = get_value_string(gprs_cipher_names, lle->llme->algo); + iov_ui = lle->llme->iov_ui; + } else + gea = "GEA?"; + DEBUGP(DLLC, "LLC SAPI=%u %c %c %c %s IOV-UI=0x%06x FCS=0x%06x ", + gph->sapi, gph->is_cmd ? 'C' : 'R', gph->ack_req ? 'A' : ' ', + gph->is_encrypted ? 'E' : 'U', + gea, iov_ui, gph->fcs); if (gph->cmd) DEBUGPC(DLLC, "CMD=%s ", get_value_string(llc_cmd_strs, gph->cmd)); diff --git a/openbsc/src/gprs/gprs_llc_vty.c b/openbsc/src/gprs/gprs_llc_vty.c index f399b2752..e97416ba5 100644 --- a/openbsc/src/gprs/gprs_llc_vty.c +++ b/openbsc/src/gprs/gprs_llc_vty.c @@ -73,9 +73,11 @@ static void vty_dump_llme(struct vty *vty, struct gprs_llc_llme *llme) struct timespec now_tp = {0}; clock_gettime(CLOCK_MONOTONIC, &now_tp); - vty_out(vty, "TLLI %08x (Old TLLI %08x) BVCI=%u NSEI=%u Age=%d: State %s%s", - llme->tlli, llme->old_tlli, llme->bvci, llme->nsei, - llme->age_timestamp == GPRS_LLME_RESET_AGE ? 0 : + vty_out(vty, "TLLI %08x (Old TLLI %08x) BVCI=%u NSEI=%u %s: " + "IOV-UI=0x%06x CKSN=%d Age=%d: State %s%s", llme->tlli, + llme->old_tlli, llme->bvci, llme->nsei, + get_value_string(gprs_cipher_names, llme->algo), llme->iov_ui, + llme->cksn, llme->age_timestamp == GPRS_LLME_RESET_AGE ? 0 : (int)(now_tp.tv_sec - (time_t)llme->age_timestamp), get_value_string(gprs_llc_state_strs, llme->state), VTY_NEWLINE); diff --git a/openbsc/src/gprs/gprs_llc_xid.c b/openbsc/src/gprs/gprs_llc_xid.c index 4b1685ebe..fe631715a 100644 --- a/openbsc/src/gprs/gprs_llc_xid.c +++ b/openbsc/src/gprs/gprs_llc_xid.c @@ -35,6 +35,23 @@ #include #include +const struct value_string gprs_llc_xid_type_names[] = { + { GPRS_LLC_XID_T_VERSION, "VERSION"}, + { GPRS_LLC_XID_T_IOV_UI, "IOV_UI"}, + { GPRS_LLC_XID_T_IOV_I, "IOV_I"}, + { GPRS_LLC_XID_T_T200, "T200"}, + { GPRS_LLC_XID_T_N200, "N200"}, + { GPRS_LLC_XID_T_N201_U, "N201_"}, + { GPRS_LLC_XID_T_N201_I, "N201_I"}, + { GPRS_LLC_XID_T_mD, "mD"}, + { GPRS_LLC_XID_T_mU, "mU"}, + { GPRS_LLC_XID_T_kD, "kD"}, + { GPRS_LLC_XID_T_kU, "kU"}, + { GPRS_LLC_XID_T_L3_PAR, "L3_PAR"}, + { GPRS_LLC_XID_T_RESET, "RESET"}, + { 0, NULL }, +}; + /* Parse XID parameter field */ static int decode_xid_field(struct gprs_llc_xid_field *xid_field, const uint8_t *src, uint8_t src_len) @@ -249,8 +266,10 @@ void gprs_llc_dump_xid_fields(const struct llist_head *xid_fields, if (xid_field->data_len) { OSMO_ASSERT(xid_field->data); LOGP(DLLC, logl, - "XID: type=%d, data_len=%d, data=%s\n", - xid_field->type, xid_field->data_len, + "XID: type %s, data_len=%d, data=%s\n", + get_value_string(gprs_llc_xid_type_names, + xid_field->type), + xid_field->data_len, osmo_hexdump_nospc(xid_field->data, xid_field->data_len)); } else { diff --git a/openbsc/src/gprs/gprs_sgsn.c b/openbsc/src/gprs/gprs_sgsn.c index e5a54d9b4..e85e1a9ce 100644 --- a/openbsc/src/gprs/gprs_sgsn.c +++ b/openbsc/src/gprs/gprs_sgsn.c @@ -225,6 +225,8 @@ struct sgsn_mm_ctx *sgsn_mm_ctx_alloc(uint32_t tlli, ctx->mm_state = GMM_DEREGISTERED; ctx->auth_triplet.key_seq = GSM_KEY_SEQ_INVAL; ctx->ciph_algo = sgsn->cfg.cipher; + LOGMMCTXP(LOGL_DEBUG, ctx, "Allocated with %s cipher.\n", + get_value_string(gprs_cipher_names, ctx->ciph_algo)); ctx->ctrg = rate_ctr_group_alloc(ctx, &mmctx_ctrg_desc, tlli); INIT_LLIST_HEAD(&ctx->pdp_list);