Harald Welte has submitted this change and it was merged. Change subject: Introduce + use LOG/DEBUGP with frame number prefixing/printing ......................................................................
Introduce + use LOG/DEBUGP with frame number prefixing/printing Let's make sure whenever we do have a frame number, we print it as context in the related log line Change-Id: I751d5ddb3322fce489bc241459738cbcc55c890b --- M include/osmo-bts/logging.h M src/common/l1sap.c M src/osmo-bts-litecell15/l1_if.c M src/osmo-bts-litecell15/tch.c M src/osmo-bts-octphy/l1_if.c M src/osmo-bts-octphy/l1_tch.c M src/osmo-bts-sysmo/l1_if.c M src/osmo-bts-sysmo/tch.c M src/osmo-bts-virtual/l1_if.c 9 files changed, 118 insertions(+), 125 deletions(-) Approvals: Harald Welte: Looks good to me, approved Jenkins Builder: Verified diff --git a/include/osmo-bts/logging.h b/include/osmo-bts/logging.h index b1b44d5..68f379c 100644 --- a/include/osmo-bts/logging.h +++ b/include/osmo-bts/logging.h @@ -27,4 +27,16 @@ int bts_log_init(const char *category_mask); +/* LOGP with gsm_time prefix */ +#define LOGPGT(ss, lvl, gt, fmt, args...) \ + LOGP(ss, lvl, "%s " fmt, osmo_dump_gsmtime(gt), ## args) +#define DEBUGPGT(ss, gt, fmt, args...) \ + LOGP(ss, LOGL_DEBUG, "%s " fmt, osmo_dump_gsmtime(gt), ## args) + +/* LOGP with frame number prefix */ +#define LOGPFN(ss, lvl, fn, fmt, args...) \ + LOGP(ss, lvl, "%s " fmt, gsm_fn_as_gsmtime_str(fn), ## args) +#define DEBUGPFN(ss, fn, fmt, args...) \ + LOGP(ss, LOGL_DEBUG, "%s " fmt, gsm_fn_as_gsmtime_str(fn), ## args) + #endif /* _LOGGING_H */ diff --git a/src/common/l1sap.c b/src/common/l1sap.c index 1deee83..01b454c 100644 --- a/src/common/l1sap.c +++ b/src/common/l1sap.c @@ -451,13 +451,13 @@ struct gsm_bts_role_bts *btsb = bts->role; int frames_expired; - DEBUGP(DL1P, "MPH_INFO time ind %u\n", info_time_ind->fn); + DEBUGPFN(DL1P, info_time_ind->fn, "Rx MPH_INFO time ind\n"); /* Calculate and check frame difference */ frames_expired = info_time_ind->fn - btsb->gsm_time.fn; if (frames_expired > 1) { if (btsb->gsm_time.fn) - LOGP(DL1P, LOGL_ERROR, + LOGPFN(DL1P, LOGL_ERROR, info_time_ind->fn, "Invalid condition detected: Frame difference is %"PRIu32"-%"PRIu32"=%d > 1!\n", info_time_ind->fn, btsb->gsm_time.fn, frames_expired); } @@ -506,12 +506,13 @@ lchan = get_active_lchan_by_chan_nr(trx, info_meas_ind->chan_nr); if (!lchan) { - LOGP(DL1P, LOGL_ERROR, "No lchan for MPH INFO MEAS IND (chan_nr=%u)\n", - info_meas_ind->chan_nr); + LOGPFN(DL1P, LOGL_ERROR, info_meas_ind->fn, + "No lchan for MPH INFO MEAS IND (chan_nr=%u)\n", info_meas_ind->chan_nr); return 0; } - DEBUGP(DL1P, "%s MPH_INFO meas ind, ta_offs_qbits=%d, ber10k=%d, inv_rssi=%u\n", + DEBUGPFN(DL1P, info_meas_ind->fn, + "%s MPH_INFO meas ind, ta_offs_qbits=%d, ber10k=%d, inv_rssi=%u\n", gsm_lchan_name(lchan), info_meas_ind->ta_offs_qbits, info_meas_ind->ber10k, info_meas_ind->inv_rssi); @@ -546,9 +547,9 @@ switch (info->type) { case PRIM_INFO_TIME: if (trx != trx->bts->c0) { - LOGP(DL1P, LOGL_NOTICE, "BTS model is sending us " - "PRIM_INFO_TIME for TRX %u, please fix it\n", - trx->nr); + LOGPFN(DL1P, LOGL_NOTICE, info->u.time_ind.fn, + "BTS model is sending us PRIM_INFO_TIME for TRX %u, please fix it\n", + trx->nr); rc = -1; } else rc = l1sap_info_time_ind(trx->bts, l1sap, @@ -654,14 +655,14 @@ /* de-queue response message (loopback) */ loop_msg = msgb_dequeue(&lchan->dl_tch_queue); if (!loop_msg) { - LOGP(DL1P, LOGL_NOTICE, "%s %s: no looped PDTCH message, sending empty\n", - gsm_lchan_name(lchan), osmo_dump_gsmtime(tm)); + LOGPGT(DL1P, LOGL_NOTICE, tm, "%s: no looped PDTCH message, sending empty\n", + gsm_lchan_name(lchan)); /* empty downlink message */ p = msgb_put(msg, GSM_MACBLOCK_LEN); memset(p, 0, GSM_MACBLOCK_LEN); } else { - LOGP(DL1P, LOGL_NOTICE, "%s %s: looped PDTCH message of %u bytes\n", - gsm_lchan_name(lchan), osmo_dump_gsmtime(tm), msgb_l2len(loop_msg)); + LOGPGT(DL1P, LOGL_NOTICE, tm, "%s: looped PDTCH message of %u bytes\n", + gsm_lchan_name(lchan), msgb_l2len(loop_msg)); /* copy over data from queued response message */ p = msgb_put(msg, msgb_l2len(loop_msg)); memcpy(p, msgb_l2(loop_msg), msgb_l2len(loop_msg)); @@ -693,13 +694,11 @@ gsm_fn2gsmtime(&g_time, fn); - DEBUGP(DL1P, "Rx PH-RTS.ind %s chan_nr=0x%02x link_id=0x%02xd\n", - osmo_dump_gsmtime(&g_time), chan_nr, link_id); + DEBUGPGT(DL1P, &g_time, "Rx PH-RTS.ind chan_nr=0x%02x link_id=0x%02xd\n", chan_nr, link_id); /* reuse PH-RTS.ind for PH-DATA.req */ if (!msg) { - LOGP(DL1P, LOGL_FATAL, "RTS without msg to be reused. Please " - "fix!\n"); + LOGPGT(DL1P, LOGL_FATAL, &g_time, "RTS without msg to be reused. Please fix!\n"); abort(); } msgb_trim(msg, sizeof(*l1sap)); @@ -736,7 +735,7 @@ } else if (!(chan_nr & 0x80)) { /* only TCH/F, TCH/H, SDCCH/4 and SDCCH/8 have C5 bit cleared */ lchan = get_active_lchan_by_chan_nr(trx, chan_nr); if (!lchan) { - LOGP(DL1P, LOGL_ERROR, "No lchan for PH-RTS.ind (chan_nr=%u)\n", chan_nr); + LOGPGT(DL1P, LOGL_ERROR, &g_time, "No lchan for PH-RTS.ind (chan_nr=%u)\n", chan_nr); return 0; } if (L1SAP_IS_LINK_SACCH(link_id)) { @@ -789,8 +788,7 @@ memcpy(p, fill_frame, GSM_MACBLOCK_LEN); } - DEBUGP(DL1P, "Tx PH-DATA.req %s chan_nr=0x%02x link_id=0x%02x\n", - osmo_dump_gsmtime(&g_time), chan_nr, link_id); + DEBUGPGT(DL1P, &g_time, "Tx PH-DATA.req chan_nr=0x%02x link_id=0x%02x\n", chan_nr, link_id); l1sap_down(trx, l1sap); @@ -877,11 +875,11 @@ gsm_fn2gsmtime(&g_time, fn); - DEBUGP(DL1P, "Rx TCH-RTS.ind %s chan_nr=0x%02x\n", osmo_dump_gsmtime(&g_time), chan_nr); + DEBUGPGT(DL1P, &g_time, "Rx TCH-RTS.ind chan_nr=0x%02x\n", chan_nr); lchan = get_active_lchan_by_chan_nr(trx, chan_nr); if (!lchan) { - LOGP(DL1P, LOGL_ERROR, "No lchan for PH-RTS.ind (chan_nr=%u)\n", chan_nr); + LOGPGT(DL1P, LOGL_ERROR, &g_time, "No lchan for PH-RTS.ind (chan_nr=%u)\n", chan_nr); return 0; } @@ -898,8 +896,7 @@ /* get a msgb from the dl_tx_queue */ resp_msg = msgb_dequeue(&lchan->dl_tch_queue); if (!resp_msg) { - LOGP(DL1P, LOGL_DEBUG, "%s DL TCH Tx queue underrun\n", - gsm_lchan_name(lchan)); + DEBUGPGT(DL1P, &g_time, "%s DL TCH Tx queue underrun\n", gsm_lchan_name(lchan)); resp_l1sap = &empty_l1sap; } else if(!rtppayload_is_valid(lchan, resp_msg)) { msgb_free(resp_msg); @@ -917,7 +914,7 @@ /* check for pending REL_IND */ if (lchan->pending_rel_ind_msg) { - LOGP(DRSL, LOGL_INFO, "%s Forward REL_IND to L3\n", gsm_lchan_name(lchan)); + LOGPGT(DRSL, LOGL_INFO, &g_time, "%s Forward REL_IND to L3\n", gsm_lchan_name(lchan)); /* Forward it to L3 */ rc = abis_bts_rsl_sendmsg(lchan->pending_rel_ind_msg); lchan->pending_rel_ind_msg = NULL; @@ -932,7 +929,7 @@ resp_l1sap->u.tch.fn = fn; resp_l1sap->u.tch.marker = marker; - DEBUGP(DL1P, "Tx TCH.req %s chan_nr=0x%02x\n", osmo_dump_gsmtime(&g_time), chan_nr); + DEBUGPGT(DL1P, &g_time, "Tx TCH.req chan_nr=0x%02x\n", chan_nr); l1sap_down(trx, resp_l1sap); @@ -1034,13 +1031,13 @@ gsm_fn2gsmtime(&g_time, fn); - DEBUGP(DL1P, "Rx PH-DATA.ind %s chan_nr=0x%02x link_id=0x%02x len=%d\n", - osmo_dump_gsmtime(&g_time), chan_nr, link_id, len); + DEBUGPGT(DL1P, &g_time, "Rx PH-DATA.ind chan_nr=0x%02x link_id=0x%02x len=%d\n", + chan_nr, link_id, len); if (ts_is_pdch(&trx->ts[tn])) { lchan = get_lchan_by_chan_nr(trx, chan_nr); if (!lchan) - LOGP(DL1P, LOGL_ERROR, "No lchan for chan_nr=0x%02x\n", chan_nr); + LOGPGT(DL1P, LOGL_ERROR, &g_time, "No lchan for chan_nr=0x%02x\n", chan_nr); if (lchan && lchan->loopback && !L1SAP_IS_PTCCH(fn)) { /* we are in loopback mode (for BER testing) * mode and need to enqeue the frame to be @@ -1076,7 +1073,7 @@ lchan = get_active_lchan_by_chan_nr(trx, chan_nr); if (!lchan) { - LOGP(DL1P, LOGL_ERROR, "No lchan for chan_nr=%d\n", chan_nr); + LOGPGT(DL1P, LOGL_ERROR, &g_time, "No lchan for chan_nr=%d\n", chan_nr); return 0; } @@ -1096,8 +1093,7 @@ le = &lchan->lapdm_ch.lapdm_acch; /* save the SACCH L1 header in the lchan struct for RSL MEAS RES */ if (len < 2) { - LOGP(DL1P, LOGL_NOTICE, "SACCH with size %u<2 !?!\n", - len); + LOGPGT(DL1P, LOGL_NOTICE, &g_time, "SACCH with size %u<2 !?!\n", len); return -EINVAL; } /* Some brilliant engineer decided that the ordering of @@ -1141,11 +1137,11 @@ gsm_fn2gsmtime(&g_time, fn); - LOGP(DL1P, LOGL_INFO, "Rx TCH.ind %s chan_nr=0x%02x\n", osmo_dump_gsmtime(&g_time), chan_nr); + LOGPGT(DL1P, LOGL_INFO, &g_time, "Rx TCH.ind chan_nr=0x%02x\n", chan_nr); lchan = get_active_lchan_by_chan_nr(trx, chan_nr); if (!lchan) { - LOGP(DL1P, LOGL_ERROR, "No lchan for TCH.ind (chan_nr=%u)\n", chan_nr); + LOGPGT(DL1P, LOGL_ERROR, &g_time, "No lchan for TCH.ind (chan_nr=%u)\n", chan_nr); return 0; } @@ -1172,7 +1168,8 @@ /* Only clear the marker bit once we have sent a RTP packet with it */ lchan->rtp_tx_marker = false; } else { - DEBUGP(DRTP, "Skipping RTP frame with lost payload\n"); + DEBUGPGT(DRTP, &g_time, "Skipping RTP frame with lost payload (chan_nr=0x%02x)\n", + chan_nr); if (lchan->abis_ip.rtp_socket) osmo_rtp_skipped_frame(lchan->abis_ip.rtp_socket, fn_ms_adj(fn, lchan)); lchan->rtp_tx_marker = true; @@ -1191,13 +1188,13 @@ struct lapdm_channel *lc; uint8_t acc_delay; - DEBUGP(DL1P, "Rx PH-RA.ind"); + DEBUGPFN(DL1P, rach_ind->fn, "Rx PH-RA.ind"); lc = &trx->ts[0].lchan[CCCH_LCHAN].lapdm_ch; /* check for under/overflow / sign */ if (!check_acc_delay(rach_ind, btsb, &acc_delay)) { - LOGP(DL1C, LOGL_INFO, "ignoring RACH request %u > max_ta(%u)\n", + LOGPFN(DL1C, LOGL_INFO, rach_ind->fn, "ignoring RACH request %u > max_ta(%u)\n", acc_delay, btsb->max_ta); return 0; } @@ -1213,7 +1210,7 @@ if ((trx == bts->c0 && L1SAP_IS_PACKET_RACH(rach_ind->ra)) || (trx == bts->c0 && rach_ind->is_11bit)) { - LOGP(DL1P, LOGL_INFO, "RACH for packet access (toa=%d, ra=%d)\n", + LOGPFN(DL1P, LOGL_INFO, rach_ind->fn, "RACH for packet access (toa=%d, ra=%d)\n", rach_ind->acc_delay, rach_ind->ra); pcu_tx_rach_ind(bts, rach_ind->acc_delay << 2, @@ -1222,7 +1219,7 @@ return 0; } - LOGP(DL1P, LOGL_INFO, "RACH for RR access (toa=%d, ra=%d)\n", + LOGPFN(DL1P, LOGL_INFO, rach_ind->fn, "RACH for RR access (toa=%d, ra=%d)\n", rach_ind->acc_delay, rach_ind->ra); lapdm_phsap_up(&l1sap->oph, &lc->lapdm_dcch); diff --git a/src/osmo-bts-litecell15/l1_if.c b/src/osmo-bts-litecell15/l1_if.c index 12c2470..35d31f4 100644 --- a/src/osmo-bts-litecell15/l1_if.c +++ b/src/osmo-bts-litecell15/l1_if.c @@ -343,8 +343,7 @@ int len; if (!msg) { - LOGP(DL1C, LOGL_FATAL, "PH-DATA.req without msg. " - "Please fix!\n"); + LOGPFN(DL1C, LOGL_FATAL, l1sap->u.data.fn, "PH-DATA.req without msg. Please fix!\n"); abort(); } @@ -394,7 +393,7 @@ else sapi = GsmL1_Sapi_Agch; } else { - LOGP(DL1C, LOGL_NOTICE, "unknown prim %d op %d " + LOGPFN(DL1C, LOGL_NOTICE, u32Fn, "unknown prim %d op %d " "chan_nr %d link_id %d\n", l1sap->oph.primitive, l1sap->oph.operation, chan_nr, link_id); msgb_free(l1msg); @@ -457,7 +456,7 @@ memcpy(l1p->u.phDataReq.msgUnitParam.u8Buffer, msg->l2h, msgb_l2len(msg)); } - LOGP(DL1P, LOGL_DEBUG, "PH-DATA.req(%s)\n", + LOGPFN(DL1P, LOGL_DEBUG, u32Fn, "PH-DATA.req(%s)\n", osmo_hexdump(l1p->u.phDataReq.msgUnitParam.u8Buffer, l1p->u.phDataReq.msgUnitParam.u8Size)); } else { @@ -469,7 +468,7 @@ /* send message to DSP's queue */ if (osmo_wqueue_enqueue(&fl1->write_q[MQ_L1_WRITE], l1msg) != 0) { - LOGP(DL1P, LOGL_ERROR, "MQ_L1_WRITE queue full. Dropping msg.\n"); + LOGPFN(DL1P, LOGL_ERROR, u32Fn, "MQ_L1_WRITE queue full. Dropping msg.\n"); msgb_free(l1msg); } else dtx_int_signal(lchan); @@ -838,8 +837,7 @@ gsm_fn2gsmtime(&g_time, rts_ind->u32Fn); - DEBUGP(DL1P, "Rx PH-RTS.ind %02u/%02u/%02u SAPI=%s\n", - g_time.t1, g_time.t2, g_time.t3, + DEBUGPGT(DL1P, &g_time, "Rx PH-RTS.ind SAPI=%s\n", get_value_string(lc15bts_l1sapi_names, rts_ind->sapi)); /* in all other cases, we need to allocate a new PH-DATA.ind @@ -877,7 +875,7 @@ /* transmit */ if (osmo_wqueue_enqueue(&fl1->write_q[MQ_L1_WRITE], resp_msg) != 0) { - LOGP(DL1C, LOGL_ERROR, "MQ_L1_WRITE queue full. Dropping msg.\n"); + LOGPGT(DL1C, LOGL_ERROR, &g_time, "MQ_L1_WRITE queue full. Dropping msg.\n"); msgb_free(resp_msg); } @@ -933,24 +931,23 @@ chan_nr = chan_nr_by_sapi(&trx->ts[data_ind->u8Tn], data_ind->sapi, data_ind->subCh, data_ind->u8Tn, data_ind->u32Fn); + fn = data_ind->u32Fn; + link_id = (data_ind->sapi == GsmL1_Sapi_Sacch) ? LID_SACCH : LID_DEDIC; + gsm_fn2gsmtime(&g_time, fn); + if (!chan_nr) { - LOGP(DL1C, LOGL_ERROR, "PH-DATA-INDICATION for unknown sapi %s (%d)\n", + LOGPGT(DL1C, LOGL_ERROR, &g_time, "PH-DATA-INDICATION for unknown sapi %s (%d)\n", get_value_string(lc15bts_l1sapi_names, data_ind->sapi), data_ind->sapi); msgb_free(l1p_msg); return ENOTSUP; } - fn = data_ind->u32Fn; - link_id = (data_ind->sapi == GsmL1_Sapi_Sacch) ? LID_SACCH : LID_DEDIC; process_meas_res(trx, chan_nr, &data_ind->measParam, fn); - gsm_fn2gsmtime(&g_time, fn); - DEBUGP(DL1P, "Rx PH-DATA.ind %s %s (hL2 %08x): %s\n", - get_value_string(lc15bts_l1sapi_names, data_ind->sapi), - osmo_dump_gsmtime(&g_time), (uint32_t)data_ind->hLayer2, - osmo_hexdump(data_ind->msgUnitParam.u8Buffer, - data_ind->msgUnitParam.u8Size)); + DEBUGPGT(DL1P, &g_time, "Rx PH-DATA.ind %s (hL2 %08x): %s\n", + get_value_string(lc15bts_l1sapi_names, data_ind->sapi), (uint32_t)data_ind->hLayer2, + osmo_hexdump(data_ind->msgUnitParam.u8Buffer, data_ind->msgUnitParam.u8Size)); dump_meas_res(LOGL_DEBUG, &data_ind->measParam); /* check for TCH */ @@ -1028,12 +1025,10 @@ if ((ra_ind->msgUnitParam.u8Size != 1) && (ra_ind->msgUnitParam.u8Size != 2)) { - LOGP(DL1C, LOGL_ERROR, "PH-RACH-INDICATION has %d bits\n", - ra_ind->sapi); + LOGPFN(DL1P, LOGL_ERROR, ra_ind->u32Fn, "PH-RACH-INDICATION has %d bits\n", ra_ind->sapi); msgb_free(l1p_msg); return 0; } - if (ra_ind->msgUnitParam.u8Size == 2) { is_11bit = 1; diff --git a/src/osmo-bts-litecell15/tch.c b/src/osmo-bts-litecell15/tch.c index c61712f..0becfc4 100644 --- a/src/osmo-bts-litecell15/tch.c +++ b/src/osmo-bts-litecell15/tch.c @@ -369,7 +369,7 @@ return -EAGAIN; if (data_ind->msgUnitParam.u8Size < 1) { - LOGP(DL1P, LOGL_DEBUG, "chan_nr %d Rx Payload size 0\n", chan_nr); + LOGPFN(DL1P, LOGL_DEBUG, data_ind->u32Fn, "chan_nr %d Rx Payload size 0\n", chan_nr); /* Push empty payload to upper layers */ rmsg = msgb_alloc_headroom(256, 128, "L1P-to-RTP"); return add_l1sap_header(trx, rmsg, lchan, chan_nr, data_ind->u32Fn, @@ -408,31 +408,31 @@ case GsmL1_TchPlType_Amr_SidFirstP1: if (lchan->type != GSM_LCHAN_TCH_H) goto err_payload_match; - LOGP(DL1P, LOGL_DEBUG, "DTX: received SID_FIRST_P1 from L1 " + LOGPFN(DL1P, LOGL_DEBUG, data_ind->u32Fn, "DTX: received SID_FIRST_P1 from L1 " "(%d bytes)\n", payload_len); break; case GsmL1_TchPlType_Amr_SidFirstP2: if (lchan->type != GSM_LCHAN_TCH_H) goto err_payload_match; - LOGP(DL1P, LOGL_DEBUG, "DTX: received SID_FIRST_P2 from L1 " + LOGPFN(DL1P, LOGL_DEBUG, data_ind->u32Fn, "DTX: received SID_FIRST_P2 from L1 " "(%d bytes)\n", payload_len); break; case GsmL1_TchPlType_Amr_SidFirstInH: if (lchan->type != GSM_LCHAN_TCH_H) goto err_payload_match; lchan->rtp_tx_marker = true; - LOGP(DL1P, LOGL_DEBUG, "DTX: received SID_FIRST_INH from L1 " + LOGPFN(DL1P, LOGL_DEBUG, data_ind->u32Fn, "DTX: received SID_FIRST_INH from L1 " "(%d bytes)\n", payload_len); break; case GsmL1_TchPlType_Amr_SidUpdateInH: if (lchan->type != GSM_LCHAN_TCH_H) goto err_payload_match; lchan->rtp_tx_marker = true; - LOGP(DL1P, LOGL_DEBUG, "DTX: received SID_UPDATE_INH from L1 " + LOGPFN(DL1P, LOGL_DEBUG, data_ind->u32Fn, "DTX: received SID_UPDATE_INH from L1 " "(%d bytes)\n", payload_len); break; default: - LOGP(DL1P, LOGL_NOTICE, "%s Rx Payload Type %s is unsupported\n", + LOGPFN(DL1P, LOGL_NOTICE, data_ind->u32Fn, "%s Rx Payload Type %s is unsupported\n", gsm_lchan_name(lchan), get_value_string(lc15bts_tch_pl_names, payload_type)); break; @@ -469,9 +469,8 @@ return 0; err_payload_match: - LOGP(DL1P, LOGL_ERROR, "%s Rx Payload Type %s incompatible with lchan\n", - gsm_lchan_name(lchan), - get_value_string(lc15bts_tch_pl_names, payload_type)); + LOGPFN(DL1P, LOGL_ERROR, data_ind->u32Fn, "%s Rx Payload Type %s incompatible with lchan\n", + gsm_lchan_name(lchan), get_value_string(lc15bts_tch_pl_names, payload_type)); return -EINVAL; } diff --git a/src/osmo-bts-octphy/l1_if.c b/src/osmo-bts-octphy/l1_if.c index 8dc3e8f..cb0ea05 100644 --- a/src/osmo-bts-octphy/l1_if.c +++ b/src/osmo-bts-octphy/l1_if.c @@ -478,7 +478,7 @@ int rc; if (!msg) { - LOGP(DL1C, LOGL_FATAL, "L1SAP PH-DATA.req without msg. " + LOGPFN(DL1C, LOGL_FATAL, l1sap->u.data.fn, "L1SAP PH-DATA.req without msg. " "Please fix!\n"); abort(); } @@ -518,10 +518,8 @@ } else if (L1SAP_IS_CHAN_AGCH_PCH(chan_nr)) { sapi = cOCTVC1_GSM_SAPI_ENUM_PCH_AGCH; } else { - LOGP(DL1C, LOGL_NOTICE, "unknown prim %d op %d " - "chan_nr %d link_id %d\n", - l1sap->oph.primitive, l1sap->oph.operation, - chan_nr, link_id); + LOGPFN(DL1C, LOGL_NOTICE, u32Fn, "unknown prim %d op %d chan_nr %d link_id %d\n", + l1sap->oph.primitive, l1sap->oph.operation, chan_nr, link_id); rc = -EINVAL; goto done; } @@ -531,7 +529,7 @@ l1msg = l1p_msgb_alloc(); if (!l1msg) { - LOGP(DL1C, LOGL_FATAL, "L1SAP PH-DATA.req msg alloc failed\n"); + LOGPFN(DL1C, LOGL_FATAL, u32Fn, "L1SAP PH-DATA.req msg alloc failed\n"); rc = -ENOMEM; goto done; } @@ -593,7 +591,7 @@ if (msg) { nmsg = l1p_msgb_alloc(); if (!nmsg) { - LOGP(DL1C, LOGL_FATAL, "L1SAP PH-TCH.req msg alloc failed\n"); + LOGPFN(DL1C, LOGL_FATAL, u32Fn, "L1SAP PH-TCH.req msg alloc failed\n"); return -ENOMEM; } @@ -950,8 +948,7 @@ gsm_fn2gsmtime(&g_time, fn); - DEBUGP(DL1P, "Rx PH-RTS.ind %02u/%02u/%02u SAPI=%s\n", - g_time.t1, g_time.t2, g_time.t3, + DEBUGPGT(DL1P, &g_time, "Rx PH-RTS.ind SAPI=%s\n", get_value_string(octphy_l1sapi_names, sapi)); /* in case we need to forward primitive to common part */ @@ -1032,14 +1029,14 @@ /* send empty frame request */ rc = Logical_Channel_Empty_Frame_Cmd(empty_frame_req); if (cOCTVC1_RC_OK != rc) { - LOGP(DL1P, LOGL_ERROR, + LOGPGT(DL1P, LOGL_ERROR, &g_time, "Sending Empty Frame Request Failed! (%s)\n", octvc1_rc2string(rc)); } break; #endif default: - LOGP(DL1P, LOGL_ERROR, "SAPI %s not handled via L1SAP!\n", + LOGPGT(DL1P, LOGL_ERROR, &g_time, "SAPI %s not handled via L1SAP!\n", get_value_string(octphy_l1sapi_names, sapi)); #if 0 data_req->Data.ulDataLength = GSM_MACBLOCK_LEN; @@ -1078,8 +1075,7 @@ /* chan_nr and link_id */ chan_nr = chan_nr_by_sapi(&trx->ts[ts_num], sapi, sc, ts_num, fn); if (!chan_nr) { - LOGP(DL1C, LOGL_ERROR, - "Rx PH-DATA.ind for unknown L1 SAPI %s\n", + LOGPFN(DL1C, LOGL_ERROR, fn, "Rx PH-DATA.ind for unknown L1 SAPI %s\n", get_value_string(octphy_l1sapi_names, sapi)); return ENOTSUP; } @@ -1095,11 +1091,10 @@ process_meas_res(trx, chan_nr, fn, data_ind->Data.ulDataLength, &data_ind->MeasurementInfo); - DEBUGP(DL1C, "Rx PH-DATA.ind %s: %s data_len:%d \n", - get_value_string(octphy_l1sapi_names, sapi), - osmo_hexdump(data_ind->Data.abyDataContent, - data_ind->Data.ulDataLength), - data_ind->Data.ulDataLength); + DEBUGPFN(DL1C, fn, "Rx PH-DATA.ind %s: %s data_len:%d \n", + get_value_string(octphy_l1sapi_names, sapi), + osmo_hexdump(data_ind->Data.abyDataContent, data_ind->Data.ulDataLength), + data_ind->Data.ulDataLength); /* check for TCH */ if (sapi == cOCTVC1_GSM_SAPI_ENUM_TCHF || @@ -1187,15 +1182,15 @@ dump_meas_res(LOGL_DEBUG, &ra_ind->MeasurementInfo); + fn = ra_ind->ulFrameNumber; + ra = ra_ind->abyMsg[0]; + if (ra_ind->ulMsgLength != 1) { - LOGP(DL1C, LOGL_ERROR, "Rx PH-RACH.ind has lenghth %d > 1\n", - ra_ind->ulMsgLength); + LOGPFN(DL1C, LOGL_ERROR, fn, "Rx PH-RACH.ind has lenghth %d > 1\n", ra_ind->ulMsgLength); msgb_free(l1p_msg); return 0; } - fn = ra_ind->ulFrameNumber; - ra = ra_ind->abyMsg[0]; /* check for under/overflow / sign */ if (ra_ind->MeasurementInfo.sBurstTiming < 0) acc_delay = 0; diff --git a/src/osmo-bts-octphy/l1_tch.c b/src/osmo-bts-octphy/l1_tch.c index 38fb9fb..eee24aa 100644 --- a/src/osmo-bts-octphy/l1_tch.c +++ b/src/osmo-bts-octphy/l1_tch.c @@ -188,6 +188,7 @@ uint32_t payload_type = data_ind->Data.ulPayloadType; uint8_t *payload = data_ind->Data.abyDataContent; + uint32_t fn = data_ind->Data.ulFrameNumber; uint16_t b_total = data_ind->MeasurementInfo.usBERTotalBitCnt; uint16_t b_error = data_ind->MeasurementInfo.usBERCnt; uint16_t ber10k = b_total ? BER_10K * b_error / b_total : 0; @@ -199,7 +200,7 @@ &trx->ts[L1SAP_CHAN2TS(chan_nr)].lchan[l1sap_chan2ss(chan_nr)]; if (data_ind->Data.ulDataLength < 1) { - LOGP(DL1P, LOGL_DEBUG, "chan_nr %d Rx Payload size 0\n", chan_nr); + LOGPFN(DL1P, LOGL_DEBUG, fn, "chan_nr %d Rx Payload size 0\n", chan_nr); /* Push empty payload to upper layers */ rmsg = msgb_alloc_headroom(256, 128, "L1P-to-RTP"); return add_l1sap_header(trx, rmsg, lchan, chan_nr, @@ -226,15 +227,13 @@ goto err_payload_match; break; default: - LOGP(DL1P, LOGL_NOTICE, - "%s Rx Payload Type %d is unsupported\n", + LOGPFN(DL1P, LOGL_NOTICE, fn, "%s Rx Payload Type %d is unsupported\n", gsm_lchan_name(lchan), payload_type); break; } - LOGP(DL1P, LOGL_DEBUG, "%s Rx codec frame (%u): %s\n", - gsm_lchan_name(lchan), payload_len, osmo_hexdump(payload, - payload_len)); + LOGPFN(DL1P, LOGL_DEBUG, fn, "%s Rx codec frame (%u): %s\n", gsm_lchan_name(lchan), + payload_len, osmo_hexdump(payload, payload_len)); switch (payload_type) { case cOCTVC1_GSM_PAYLOAD_TYPE_ENUM_FULL_RATE: @@ -256,7 +255,7 @@ rmsg = l1_to_rtppayload_amr(payload, payload_len, &lchan->tch.amr_mr); #else - LOGP(DL1P, LOGL_ERROR, "OctPHY only supports FR!\n"); + LOGPFN(DL1P, LOGL_ERROR, fn, "OctPHY only supports FR!\n"); return -1; #endif break; @@ -270,8 +269,7 @@ return 0; err_payload_match: - LOGP(DL1P, LOGL_ERROR, - "%s Rx Payload Type %d incompatible with lchan\n", + LOGPFN(DL1P, LOGL_ERROR, fn, "%s Rx Payload Type %d incompatible with lchan\n", gsm_lchan_name(lchan), payload_type); return -EINVAL; } diff --git a/src/osmo-bts-sysmo/l1_if.c b/src/osmo-bts-sysmo/l1_if.c index 44ba3de..cc1337b 100644 --- a/src/osmo-bts-sysmo/l1_if.c +++ b/src/osmo-bts-sysmo/l1_if.c @@ -390,7 +390,7 @@ else sapi = GsmL1_Sapi_Agch; } else { - LOGP(DL1C, LOGL_NOTICE, "unknown prim %d op %d " + LOGPFN(DL1C, LOGL_NOTICE, u32Fn, "unknown prim %d op %d " "chan_nr %d link_id %d\n", l1sap->oph.primitive, l1sap->oph.operation, chan_nr, link_id); msgb_free(l1msg); @@ -453,7 +453,7 @@ memcpy(l1p->u.phDataReq.msgUnitParam.u8Buffer, msg->l2h, msgb_l2len(msg)); } - LOGP(DL1P, LOGL_DEBUG, "PH-DATA.req(%s)\n", + LOGPFN(DL1P, LOGL_DEBUG, u32Fn, "PH-DATA.req(%s)\n", osmo_hexdump(l1p->u.phDataReq.msgUnitParam.u8Buffer, l1p->u.phDataReq.msgUnitParam.u8Size)); } else { @@ -465,7 +465,7 @@ /* send message to DSP's queue */ if (osmo_wqueue_enqueue(&fl1->write_q[MQ_L1_WRITE], l1msg) != 0) { - LOGP(DL1P, LOGL_ERROR, "MQ_L1_WRITE queue full. Dropping msg.\n"); + LOGPFN(DL1P, LOGL_ERROR, u32Fn, "MQ_L1_WRITE queue full. Dropping msg.\n"); msgb_free(l1msg); } else dtx_int_signal(lchan); @@ -834,8 +834,7 @@ gsm_fn2gsmtime(&g_time, rts_ind->u32Fn); - DEBUGP(DL1P, "Rx PH-RTS.ind %02u/%02u/%02u SAPI=%s\n", - g_time.t1, g_time.t2, g_time.t3, + DEBUGPGT(DL1P, &g_time, "Rx PH-RTS.ind SAPI=%s\n", get_value_string(femtobts_l1sapi_names, rts_ind->sapi)); /* in all other cases, we need to allocate a new PH-DATA.ind @@ -873,7 +872,7 @@ /* transmit */ if (osmo_wqueue_enqueue(&fl1->write_q[MQ_L1_WRITE], resp_msg) != 0) { - LOGP(DL1C, LOGL_ERROR, "MQ_L1_WRITE queue full. Dropping msg.\n"); + LOGPGT(DL1C, LOGL_ERROR, &g_time, "MQ_L1_WRITE queue full. Dropping msg.\n"); msgb_free(resp_msg); } @@ -929,7 +928,7 @@ chan_nr = chan_nr_by_sapi(&trx->ts[data_ind->u8Tn], data_ind->sapi, data_ind->subCh, data_ind->u8Tn, data_ind->u32Fn); if (!chan_nr) { - LOGP(DL1C, LOGL_ERROR, "PH-DATA-INDICATION for unknown sapi %s (%d)\n", + LOGPFN(DL1C, LOGL_ERROR, data_ind->u32Fn, "PH-DATA-INDICATION for unknown sapi %s (%d)\n", get_value_string(femtobts_l1sapi_names, data_ind->sapi), data_ind->sapi); msgb_free(l1p_msg); return ENOTSUP; @@ -941,11 +940,9 @@ gsm_fn2gsmtime(&g_time, fn); - DEBUGP(DL1P, "Rx PH-DATA.ind %s %s (hL2 %08x): %s\n", - get_value_string(femtobts_l1sapi_names, data_ind->sapi), - osmo_dump_gsmtime(&g_time), data_ind->hLayer2, - osmo_hexdump(data_ind->msgUnitParam.u8Buffer, - data_ind->msgUnitParam.u8Size)); + DEBUGPGT(DL1P, &g_time, "Rx PH-DATA.ind %s (hL2 %08x): %s\n", + get_value_string(femtobts_l1sapi_names, data_ind->sapi), data_ind->hLayer2, + osmo_hexdump(data_ind->msgUnitParam.u8Buffer, data_ind->msgUnitParam.u8Size)); dump_meas_res(LOGL_DEBUG, &data_ind->measParam); /* check for TCH */ @@ -1018,7 +1015,7 @@ if ((ra_ind->msgUnitParam.u8Size != 1) && (ra_ind->msgUnitParam.u8Size != 2)) { - LOGP(DL1C, LOGL_ERROR, "PH-RACH-INDICATION has %d bits\n", + LOGPFN(DL1C, LOGL_ERROR, ra_ind->u32Fn, "PH-RACH-INDICATION has %d bits\n", ra_ind->sapi); msgb_free(l1p_msg); return 0; diff --git a/src/osmo-bts-sysmo/tch.c b/src/osmo-bts-sysmo/tch.c index b65628f..4e6e246 100644 --- a/src/osmo-bts-sysmo/tch.c +++ b/src/osmo-bts-sysmo/tch.c @@ -514,7 +514,7 @@ return -EAGAIN; if (data_ind->msgUnitParam.u8Size < 1) { - LOGP(DL1P, LOGL_DEBUG, "chan_nr %d Rx Payload size 0\n", chan_nr); + LOGPFN(DL1P, LOGL_DEBUG, data_ind->u32Fn, "chan_nr %d Rx Payload size 0\n", chan_nr); /* Push empty payload to upper layers */ rmsg = msgb_alloc_headroom(256, 128, "L1P-to-RTP"); return add_l1sap_header(trx, rmsg, lchan, chan_nr, data_ind->u32Fn, @@ -555,31 +555,31 @@ case GsmL1_TchPlType_Amr_SidFirstP1: if (lchan->type != GSM_LCHAN_TCH_H) goto err_payload_match; - LOGP(DL1P, LOGL_DEBUG, "DTX: received SID_FIRST_P1 from L1 " + LOGPFN(DL1P, LOGL_DEBUG, data_ind->u32Fn, "DTX: received SID_FIRST_P1 from L1 " "(%d bytes)\n", payload_len); break; case GsmL1_TchPlType_Amr_SidFirstP2: if (lchan->type != GSM_LCHAN_TCH_H) goto err_payload_match; - LOGP(DL1P, LOGL_DEBUG, "DTX: received SID_FIRST_P2 from L1 " + LOGPFN(DL1P, LOGL_DEBUG, data_ind->u32Fn, "DTX: received SID_FIRST_P2 from L1 " "(%d bytes)\n", payload_len); break; case GsmL1_TchPlType_Amr_SidFirstInH: if (lchan->type != GSM_LCHAN_TCH_H) goto err_payload_match; lchan->rtp_tx_marker = true; - LOGP(DL1P, LOGL_DEBUG, "DTX: received SID_FIRST_INH from L1 " + LOGPFN(DL1P, LOGL_DEBUG, data_ind->u32Fn, "DTX: received SID_FIRST_INH from L1 " "(%d bytes)\n", payload_len); break; case GsmL1_TchPlType_Amr_SidUpdateInH: if (lchan->type != GSM_LCHAN_TCH_H) goto err_payload_match; lchan->rtp_tx_marker = true; - LOGP(DL1P, LOGL_DEBUG, "DTX: received SID_UPDATE_INH from L1 " + LOGPFN(DL1P, LOGL_DEBUG, data_ind->u32Fn, "DTX: received SID_UPDATE_INH from L1 " "(%d bytes)\n", payload_len); break; default: - LOGP(DL1P, LOGL_NOTICE, "%s Rx Payload Type %s is unsupported\n", + LOGPFN(DL1P, LOGL_NOTICE, data_ind->u32Fn, "%s Rx Payload Type %s is unsupported\n", gsm_lchan_name(lchan), get_value_string(femtobts_tch_pl_names, payload_type)); break; @@ -619,7 +619,7 @@ return 0; err_payload_match: - LOGP(DL1P, LOGL_ERROR, "%s Rx Payload Type %s incompatible with lchan\n", + LOGPFN(DL1P, LOGL_ERROR, data_ind->u32Fn, "%s Rx Payload Type %s incompatible with lchan\n", gsm_lchan_name(lchan), get_value_string(femtobts_tch_pl_names, payload_type)); return -EINVAL; diff --git a/src/osmo-bts-virtual/l1_if.c b/src/osmo-bts-virtual/l1_if.c index 55c7ee4..01314fa 100644 --- a/src/osmo-bts-virtual/l1_if.c +++ b/src/osmo-bts-virtual/l1_if.c @@ -98,7 +98,7 @@ /* ... or not uplink */ if (!(arfcn & GSMTAP_ARFCN_F_UPLINK)) { - LOGP(DL1P, LOGL_NOTICE, "Ignoring incoming msg - no uplink flag\n"); + LOGPFN(DL1P, LOGL_NOTICE, fn, "Ignoring incoming msg - no uplink flag\n"); goto nomessage; } @@ -153,22 +153,22 @@ case GSMTAP_CHANNEL_AGCH: case GSMTAP_CHANNEL_PCH: case GSMTAP_CHANNEL_BCCH: - LOGP(DL1P, LOGL_NOTICE, "Ignore incoming msg - channel type downlink only!\n"); + LOGPFN(DL1P, LOGL_NOTICE, fn, "Ignore incoming msg - channel type downlink only!\n"); goto nomessage; case GSMTAP_CHANNEL_SDCCH: case GSMTAP_CHANNEL_CCCH: case GSMTAP_CHANNEL_CBCH51: case GSMTAP_CHANNEL_CBCH52: - LOGP(DL1P, LOGL_NOTICE, "Ignore incoming msg - channel type not supported!\n"); + LOGPFN(DL1P, LOGL_NOTICE, fn, "Ignore incoming msg - channel type not supported!\n"); goto nomessage; default: - LOGP(DL1P, LOGL_NOTICE, "Ignore incoming msg - channel type unknown\n"); + LOGPFN(DL1P, LOGL_NOTICE, fn, "Ignore incoming msg - channel type unknown\n"); goto nomessage; } /* forward primitive, lsap takes ownership of the msgb. */ l1sap_up(pinst->trx, &l1sap); - DEBUGP(DL1P, "Message forwarded to layer 2.\n"); + DEBUGPFN(DL1P, fn, "Message forwarded to layer 2.\n"); return; nomessage: @@ -316,9 +316,9 @@ /* 100% BER is n_bits_total is 0 */ float ber = n_bits_total==0 ? 1.0 : (float)n_errors / (float)n_bits_total; - LOGP(DMEAS, LOGL_DEBUG, "RX L1 frame %s fn=%u chan_nr=0x%02x MS pwr=%ddBm rssi=%.1f dBFS " + DEBUGPFN(DMEAS, fn, "RX L1 frame %s chan_nr=0x%02x MS pwr=%ddBm rssi=%.1f dBFS " "ber=%.2f%% (%d/%d bits) L1_ta=%d rqd_ta=%d toa=%.2f\n", - gsm_lchan_name(lchan), fn, chan_nr, ms_pwr_dbm(lchan->ts->trx->bts->band, lchan->ms_power), + gsm_lchan_name(lchan), chan_nr, ms_pwr_dbm(lchan->ts->trx->bts->band, lchan->ms_power), rssi, ber*100, n_errors, n_bits_total, lchan->meas.l1_info[1], lchan->rqd_ta, toa); l1if_fill_meas_res(&l1sap, chan_nr, lchan->rqd_ta + toa, ber, rssi); -- To view, visit https://gerrit.osmocom.org/6676 To unsubscribe, visit https://gerrit.osmocom.org/settings Gerrit-MessageType: merged Gerrit-Change-Id: I751d5ddb3322fce489bc241459738cbcc55c890b Gerrit-PatchSet: 2 Gerrit-Project: osmo-bts Gerrit-Branch: master Gerrit-Owner: Harald Welte <lafo...@gnumonks.org> Gerrit-Reviewer: Harald Welte <lafo...@gnumonks.org> Gerrit-Reviewer: Jenkins Builder