From 9f2baf3e04445e70439ac1a68eff27dcb7874c59 Mon Sep 17 00:00:00 2001 From: Pau Espin Pedrol Date: Thu, 19 Dec 2019 21:03:03 +0100 Subject: Transceiver.cpp: Introduce and use new logging categories Take the chance to clean up logging lines in this file: * Use LOGCHAN in more places where chan is useful * Replace inherited (old osmo-trx) categories such as WARNING with osmocom ones. Change-Id: Ic8c218f050f35d48046ccf1561fb0bfc505d4f63 --- CommonLibs/debug.c | 18 +++++++++++ CommonLibs/debug.h | 3 ++ Transceiver52M/Transceiver.cpp | 70 +++++++++++++++++++++--------------------- 3 files changed, 56 insertions(+), 35 deletions(-) diff --git a/CommonLibs/debug.c b/CommonLibs/debug.c index 09dab2b..cc5be44 100644 --- a/CommonLibs/debug.c +++ b/CommonLibs/debug.c @@ -35,12 +35,30 @@ static const struct log_info_cat default_categories[] = { .color = NULL, .enabled = 1, .loglevel = LOGL_NOTICE, }, + [DTRXCLK] = { + .name = "DTRXCLK", + .description = "TRX Master Clock", + .color = NULL, + .enabled = 1, .loglevel = LOGL_NOTICE, + }, [DTRXCTRL] = { .name = "DTRXCTRL", .description = "TRX CTRL interface", .color = "\033[1;33m", .enabled = 1, .loglevel = LOGL_NOTICE, }, + [DTRXDDL] = { + .name = "DTRXDDL", + .description = "TRX Data interface Downlink", + .color = NULL, + .enabled = 1, .loglevel = LOGL_NOTICE, + }, + [DTRXDUL] = { + .name = "DTRXDUL", + .description = "TRX CTRL interface Uplink", + .color = NULL, + .enabled = 1, .loglevel = LOGL_NOTICE, + }, [DDEV] = { .name = "DDEV", .description = "Device/Driver specific code", diff --git a/CommonLibs/debug.h b/CommonLibs/debug.h index ad12bb8..3837329 100644 --- a/CommonLibs/debug.h +++ b/CommonLibs/debug.h @@ -10,7 +10,10 @@ extern const struct log_info log_info; /* Debug Areas of the code */ enum { DMAIN, + DTRXCLK, DTRXCTRL, + DTRXDDL, + DTRXDUL, DDEV, DLMS, }; diff --git a/Transceiver52M/Transceiver.cpp b/Transceiver52M/Transceiver.cpp index 27049b9..dc218d7 100644 --- a/Transceiver52M/Transceiver.cpp +++ b/Transceiver52M/Transceiver.cpp @@ -180,12 +180,12 @@ bool Transceiver::init(FillerType filler, size_t rtsc, unsigned rach_delay, int d_srcport, d_dstport, c_srcport, c_dstport; if (!mChans) { - LOG(ALERT) << "No channels assigned"; + LOG(FATAL) << "No channels assigned"; return false; } if (!sigProcLibSetup()) { - LOG(ALERT) << "Failed to initialize signal processing library"; + LOG(FATAL) << "Failed to initialize signal processing library"; return false; } @@ -285,7 +285,7 @@ bool Transceiver::start() mLatencyUpdateTime = time; if (!mRadioInterface->start()) { - LOG(ALERT) << "Device failed to start"; + LOG(FATAL) << "Device failed to start"; return false; } @@ -371,12 +371,12 @@ void Transceiver::addRadioVector(size_t chan, BitVector &bits, radioVector *radio_burst; if (chan >= mTxPriorityQueues.size()) { - LOG(ALERT) << "Invalid channel " << chan; + LOGCHAN(chan, DTRXDDL, FATAL) << "Invalid channel"; return; } if (wTime.TN() > 7) { - LOG(ALERT) << "Received burst with invalid slot " << wTime.TN(); + LOGCHAN(chan, DTRXDDL, FATAL) << "Received burst with invalid slot " << wTime.TN(); return; } @@ -419,7 +419,7 @@ void Transceiver::pushRadioVector(GSM::Time &nowTime) state = &mStates[i]; while ((burst = mTxPriorityQueues[i].getStaleBurst(nowTime))) { - LOGCHAN(i, DMAIN, NOTICE) << "dumping STALE burst in TRX->SDR interface (" + LOGCHAN(i, DTRXDDL, NOTICE) << "dumping STALE burst in TRX->SDR interface (" << burst->getTime() <<" vs " << nowTime << "), retrans=" << state->mRetrans; if (state->mRetrans) updateFillerTable(i, burst); @@ -606,7 +606,7 @@ int Transceiver::pullRadioVector(size_t chan, struct trx_ul_burst_ind *bi) /* Blocking FIFO read */ radioVector *radio_burst = mReceiveFIFO[chan]->read(); if (!radio_burst) { - LOGCHAN(chan, DMAIN, ERROR) << "ReceiveFIFO->read() returned no burst"; + LOGCHAN(chan, DTRXDUL, ERROR) << "ReceiveFIFO->read() returned no burst"; return -EIO; } @@ -651,7 +651,7 @@ int Transceiver::pullRadioVector(size_t chan, struct trx_ul_burst_ind *bi) } if (max_i < 0) { - LOG(ALERT) << "Received empty burst"; + LOGCHAN(chan, DTRXDUL, FATAL) << "Received empty burst"; goto ret_idle; } @@ -678,9 +678,9 @@ int Transceiver::pullRadioVector(size_t chan, struct trx_ul_burst_ind *bi) rc = detectAnyBurst(*burst, mTSC, BURST_THRESH, mSPSRx, type, max_toa, &ebp); if (rc <= 0) { if (rc == -SIGERR_CLIP) - LOG(WARNING) << "Clipping detected on received RACH or Normal Burst"; + LOGCHAN(chan, DTRXDUL, NOTICE) << "Clipping detected on received RACH or Normal Burst"; else if (rc != SIGERR_NONE) - LOG(WARNING) << "Unhandled RACH or Normal Burst detection error"; + LOGCHAN(chan, DTRXDUL, NOTICE) << "Unhandled RACH or Normal Burst detection error"; goto ret_idle; } @@ -760,7 +760,7 @@ bool Transceiver::driveControl(size_t chan) /* Attempt to read from control socket */ msgLen = read(mCtrlSockets[chan], buffer, MAX_PACKET_LENGTH); if (msgLen <= 0) { - LOGCHAN(chan, DTRXCTRL, WARNING) << "mCtrlSockets read(" << mCtrlSockets[chan] << ") failed: " << msgLen; + LOGCHAN(chan, DTRXCTRL, NOTICE) << "mCtrlSockets read(" << mCtrlSockets[chan] << ") failed: " << msgLen; return false; } @@ -769,7 +769,7 @@ bool Transceiver::driveControl(size_t chan) /* Verify a command signature */ if (strncmp(buffer, "CMD ", 4)) { - LOGC(DTRXCTRL, WARNING) << "bogus message on control interface"; + LOGCHAN(chan, DTRXCTRL, NOTICE) << "bogus message on control interface"; return false; } @@ -854,7 +854,7 @@ bool Transceiver::driveControl(size_t chan) sscanf(params, "%d", &freqKhz); mRxFreq = freqKhz * 1e3; if (!mRadioInterface->tuneRx(mRxFreq, chan)) { - LOGC(DTRXCTRL, ALERT) << "RX failed to tune"; + LOGCHAN(chan, DTRXCTRL, FATAL) << "RX failed to tune"; sprintf(response,"RSP RXTUNE 1 %d",freqKhz); } else @@ -865,7 +865,7 @@ bool Transceiver::driveControl(size_t chan) sscanf(params, "%d", &freqKhz); mTxFreq = freqKhz * 1e3; if (!mRadioInterface->tuneTx(mTxFreq, chan)) { - LOGC(DTRXCTRL, ALERT) << "TX failed to tune"; + LOGCHAN(chan, DTRXCTRL, FATAL) << "TX failed to tune"; sprintf(response,"RSP TXTUNE 1 %d",freqKhz); } else @@ -887,7 +887,7 @@ bool Transceiver::driveControl(size_t chan) int timeslot; sscanf(params, "%d %d", ×lot, &corrCode); if ((timeslot < 0) || (timeslot > 7)) { - LOGC(DTRXCTRL, WARNING) << "bogus message on control interface"; + LOGCHAN(chan, DTRXCTRL, NOTICE) << "bogus message on control interface"; sprintf(response,"RSP SETSLOT 1 %d %d",timeslot,corrCode); return true; } @@ -916,14 +916,14 @@ bool Transceiver::driveControl(size_t chan) mWriteBurstToDiskMask = mask; sprintf(response,"RSP _SETBURSTTODISKMASK 0 %d",mask); } else { - LOGC(DTRXCTRL, WARNING) << "bogus command " << command << " on control interface."; + LOGCHAN(chan, DTRXCTRL, NOTICE) << "bogus command " << command << " on control interface."; sprintf(response,"RSP ERR 1"); } LOGCHAN(chan, DTRXCTRL, INFO) << "response is '" << response << "'"; msgLen = write(mCtrlSockets[chan], response, strlen(response) + 1); if (msgLen <= 0) { - LOGCHAN(chan, DTRXCTRL, WARNING) << "mCtrlSockets write(" << mCtrlSockets[chan] << ") failed: " << msgLen; + LOGCHAN(chan, DTRXCTRL, NOTICE) << "mCtrlSockets write(" << mCtrlSockets[chan] << ") failed: " << msgLen; return false; } return true; @@ -940,7 +940,7 @@ bool Transceiver::driveTxPriorityQueue(size_t chan) // check data socket msgLen = read(mDataSockets[chan], buffer, sizeof(buffer)); if (msgLen <= 0) { - LOGCHAN(chan, DTRXCTRL, WARNING) << "mDataSockets read(" << mCtrlSockets[chan] << ") failed: " << msgLen; + LOGCHAN(chan, DTRXDDL, NOTICE) << "mDataSockets read(" << mCtrlSockets[chan] << ") failed: " << msgLen; return false; } @@ -950,13 +950,13 @@ bool Transceiver::driveTxPriorityQueue(size_t chan) break; case sizeof(*dl) + EDGE_BURST_NBITS: /* EDGE burst */ if (mSPSTx != 4) { - LOG(ERR) << "EDGE burst received but SPS is set to " << mSPSTx; + LOGCHAN(chan, DTRXDDL, ERROR) << "EDGE burst received but SPS is set to " << mSPSTx; return false; } burstLen = EDGE_BURST_NBITS; break; default: - LOG(ERR) << "badly formatted packet on GSM->TRX interface (len="<< msgLen << ")"; + LOGCHAN(chan, DTRXDDL, ERROR) << "badly formatted packet on GSM->TRX interface (len="<< msgLen << ")"; return false; } @@ -972,13 +972,12 @@ bool Transceiver::driveTxPriorityQueue(size_t chan) case 1: break; default: - LOG(ERR) << "Rx TRXD message with unknown header version " << unsigned(dl->common.version); + LOGCHAN(chan, DTRXDDL, ERROR) << "Rx TRXD message with unknown header version " << unsigned(dl->common.version); return false; } - LOG(DEBUG) << "Rx TRXD message (hdr_ver=" << unsigned(dl->common.version) << "): " - << "fn=" << fn << ", tn=" << unsigned(dl->common.tn) << ", " - << "burst_len=" << burstLen; + LOGCHAN(chan, DTRXDDL, DEBUG) << "Rx TRXD message (hdr_ver=" << unsigned(dl->common.version) + << "): fn=" << fn << ", tn=" << unsigned(dl->common.tn) << ", burst_len=" << burstLen; BitVector newBurst(burstLen); BitVector::iterator itr = newBurst.begin(); @@ -1020,7 +1019,7 @@ void Transceiver::logRxBurst(size_t chan, const struct trx_ul_burst_ind *bi) else os << "-"; } - LOGCHAN(chan, DMAIN, DEBUG) << std::fixed << std::right + LOGCHAN(chan, DTRXDUL, DEBUG) << std::fixed << std::right << " time: " << unsigned(bi->tn) << ":" << bi->fn << " RSSI: " << std::setw(5) << std::setprecision(1) << (bi->rssi - rssiOffset) << "dBFS/" << std::setw(6) << -bi->rssi << "dBm" @@ -1038,7 +1037,7 @@ bool Transceiver::driveReceiveFIFO(size_t chan) if ((rc = pullRadioVector(chan, &bi)) < 0) { if (rc == -ENOENT) { /* timeslot off, continue processing */ - LOGCHAN(chan, DMAIN, DEBUG) << unsigned(bi.tn) << ":" << bi.fn << " timeslot is off"; + LOGCHAN(chan, DTRXDUL, DEBUG) << unsigned(bi.tn) << ":" << bi.fn << " timeslot is off"; return true; } return false; /* other errors: we want to stop the process */ @@ -1075,7 +1074,7 @@ void Transceiver::driveTxFIFO() if (mOn) { //radioClock->wait(); // wait until clock updates - LOG(DEBUG) << "radio clock " << radioClock->get(); + LOGC(DTRXCLK, DEBUG) << "radio clock " << radioClock->get(); while (radioClock->get() + mTransmitLatency > mTransmitDeadlineClock) { // if underrun, then we're not providing bursts to radio/USRP fast // enough. Need to increase latency by one GSM frame. @@ -1084,8 +1083,9 @@ void Transceiver::driveTxFIFO() // only update latency at the defined frame interval if (radioClock->get() > mLatencyUpdateTime + GSM::Time(USB_LATENCY_INTRVL)) { mTransmitLatency = mTransmitLatency + GSM::Time(1,0); - LOG(INFO) << "new latency: " << mTransmitLatency << " (underrun " - << radioClock->get() << " vs " << mLatencyUpdateTime + GSM::Time(USB_LATENCY_INTRVL) << ")"; + LOGC(DTRXCLK, INFO) << "new latency: " << mTransmitLatency << " (underrun " + << radioClock->get() << " vs " + << mLatencyUpdateTime + GSM::Time(USB_LATENCY_INTRVL) << ")"; mLatencyUpdateTime = radioClock->get(); } } @@ -1095,7 +1095,7 @@ void Transceiver::driveTxFIFO() if (mTransmitLatency > mRadioInterface->minLatency()) { if (radioClock->get() > mLatencyUpdateTime + GSM::Time(216,0)) { mTransmitLatency.decTN(); - LOG(INFO) << "reduced latency: " << mTransmitLatency; + LOGC(DTRXCLK, INFO) << "reduced latency: " << mTransmitLatency; mLatencyUpdateTime = radioClock->get(); } } @@ -1119,11 +1119,11 @@ bool Transceiver::writeClockInterface() // FIXME -- This should be adaptive. sprintf(command,"IND CLOCK %llu",(unsigned long long) (mTransmitDeadlineClock.FN()+2)); - LOG(INFO) << "ClockInterface: sending " << command; + LOGC(DTRXCLK, INFO) << "sending " << command; msgLen = write(mClockSocket, command, strlen(command) + 1); if (msgLen <= 0) { - LOG(ERROR) << "mClockSocket write(" << mClockSocket << ") failed: " << msgLen; + LOGC(DTRXCLK, ERROR) << "mClockSocket write(" << mClockSocket << ") failed: " << msgLen; return false; } @@ -1144,7 +1144,7 @@ void *RxUpperLoopAdapter(TrxChanThParams *params) while (1) { if (!trx->driveReceiveFIFO(num)) { - LOGCHAN(num, DMAIN, FATAL) << "Something went wrong in thread " << thread_name << ", requesting stop"; + LOGCHAN(num, DTRXDUL, FATAL) << "Something went wrong in thread " << thread_name << ", requesting stop"; osmo_signal_dispatch(SS_MAIN, S_MAIN_STOP_REQUIRED, NULL); break; } @@ -1159,7 +1159,7 @@ void *RxLowerLoopAdapter(Transceiver *transceiver) while (1) { if (!transceiver->driveReceiveRadio()) { - LOG(FATAL) << "Something went wrong in thread RxLower, requesting stop"; + LOGC(DTRXDUL, FATAL) << "Something went wrong in thread RxLower, requesting stop"; osmo_signal_dispatch(SS_MAIN, S_MAIN_STOP_REQUIRED, NULL); break; } @@ -1214,7 +1214,7 @@ void *TxUpperLoopAdapter(TrxChanThParams *params) while (1) { if (!trx->driveTxPriorityQueue(num)) { - LOGCHAN(num, DMAIN, FATAL) << "Something went wrong in thread " << thread_name << ", requesting stop"; + LOGCHAN(num, DTRXDDL, FATAL) << "Something went wrong in thread " << thread_name << ", requesting stop"; osmo_signal_dispatch(SS_MAIN, S_MAIN_STOP_REQUIRED, NULL); break; } -- cgit v1.2.3