<p>Harald Welte <strong>merged</strong> this change.</p><p><a href="https://gerrit.osmocom.org/c/osmo-bts/+/14373">View Change</a></p><div style="white-space:pre-wrap">Approvals:
Jenkins Builder: Verified
Harald Welte: Looks good to me, approved
</div><pre style="font-family: monospace,monospace; white-space: pre-wrap;">bts-trx: trx_if.c: Introduce logging macro LOGPPHI<br><br>This way we unify format. We take the chance to add related information<br>to some log messages which were not printing that information (and was<br>confusing when using more than one phy instance).<br><br>Change-Id: I5b17a01638ade9a6c41da73e550d5947fa92f568<br>---<br>M include/osmo-bts/phy_link.h<br>M src/osmo-bts-trx/l1_if.c<br>M src/osmo-bts-trx/trx_if.c<br>3 files changed, 38 insertions(+), 44 deletions(-)<br><br></pre><pre style="font-family: monospace,monospace; white-space: pre-wrap;"><span>diff --git a/include/osmo-bts/phy_link.h b/include/osmo-bts/phy_link.h</span><br><span>index 812f186..273103c 100644</span><br><span>--- a/include/osmo-bts/phy_link.h</span><br><span>+++ b/include/osmo-bts/phy_link.h</span><br><span>@@ -173,3 +173,5 @@</span><br><span> }</span><br><span> </span><br><span> int bts_model_phy_link_open(struct phy_link *plink);</span><br><span style="color: hsl(120, 100%, 40%);">+</span><br><span style="color: hsl(120, 100%, 40%);">+#define LOGPPHI(pinst, section, lvl, fmt, args...) LOGP(section, lvl, "%s: " fmt, phy_instance_name(pinst), ##args)</span><br><span>diff --git a/src/osmo-bts-trx/l1_if.c b/src/osmo-bts-trx/l1_if.c</span><br><span>index 290ceee..e6e384a 100644</span><br><span>--- a/src/osmo-bts-trx/l1_if.c</span><br><span>+++ b/src/osmo-bts-trx/l1_if.c</span><br><span>@@ -159,20 +159,20 @@</span><br><span> enum gsm_phys_chan_config pchan;</span><br><span> </span><br><span> if (tn >= TRX_NR_TS) {</span><br><span style="color: hsl(0, 100%, 40%);">- LOGP(DL1C, LOGL_ERROR, "transceiver (%s) SETSLOT invalid param TN (%" PRIu8 ")\n",</span><br><span style="color: hsl(0, 100%, 40%);">- phy_instance_name(pinst), tn);</span><br><span style="color: hsl(120, 100%, 40%);">+ LOGPPHI(pinst, DL1C, LOGL_ERROR, "transceiver SETSLOT invalid param TN (%" PRIu8 ")\n",</span><br><span style="color: hsl(120, 100%, 40%);">+ tn);</span><br><span> return;</span><br><span> }</span><br><span> </span><br><span> pchan = transceiver_chan_type_2_pchan(type);</span><br><span> if (pchan == GSM_PCHAN_UNKNOWN) {</span><br><span style="color: hsl(0, 100%, 40%);">- LOGP(DL1C, LOGL_ERROR, "transceiver (%s) SETSLOT invalid param TS_TYPE (%" PRIu8 ")\n",</span><br><span style="color: hsl(0, 100%, 40%);">- phy_instance_name(pinst), type);</span><br><span style="color: hsl(120, 100%, 40%);">+ LOGPPHI(pinst, DL1C, LOGL_ERROR, "transceiver SETSLOT invalid param TS_TYPE (%" PRIu8 ")\n",</span><br><span style="color: hsl(120, 100%, 40%);">+ type);</span><br><span> return;</span><br><span> }</span><br><span> </span><br><span> ts = &trx->ts[tn];</span><br><span style="color: hsl(0, 100%, 40%);">- LOGP(DL1C, LOGL_DEBUG, "%s l1if_setslot_cb(as_pchan=%s),"</span><br><span style="color: hsl(120, 100%, 40%);">+ LOGPPHI(pinst, DL1C, LOGL_DEBUG, "%s l1if_setslot_cb(as_pchan=%s),"</span><br><span> " calling cb_ts_connected(rc=%d)\n",</span><br><span> gsm_ts_name(ts), gsm_pchan_name(pchan), rc);</span><br><span> cb_ts_connected(ts, rc);</span><br><span>diff --git a/src/osmo-bts-trx/trx_if.c b/src/osmo-bts-trx/trx_if.c</span><br><span>index ec879c7..2805260 100644</span><br><span>--- a/src/osmo-bts-trx/trx_if.c</span><br><span>+++ b/src/osmo-bts-trx/trx_if.c</span><br><span>@@ -155,7 +155,7 @@</span><br><span> len = snprintf(buf, sizeof(buf), "CMD %s%s%s", tcm->cmd, tcm->params_len ? " ":"", tcm->params);</span><br><span> OSMO_ASSERT(len < sizeof(buf));</span><br><span> </span><br><span style="color: hsl(0, 100%, 40%);">- LOGP(DTRX, LOGL_DEBUG, "Sending control '%s' to %s\n", buf, phy_instance_name(l1h->phy_inst));</span><br><span style="color: hsl(120, 100%, 40%);">+ LOGPPHI(l1h->phy_inst, DTRX, LOGL_DEBUG, "Sending control '%s'\n", buf);</span><br><span> /* send command */</span><br><span> send(l1h->trx_ofd_ctrl.fd, buf, len+1, 0);</span><br><span> </span><br><span>@@ -173,8 +173,7 @@</span><br><span> OSMO_ASSERT(!llist_empty(&l1h->trx_ctrl_list));</span><br><span> tcm = llist_entry(l1h->trx_ctrl_list.next, struct trx_ctrl_msg, list);</span><br><span> </span><br><span style="color: hsl(0, 100%, 40%);">- LOGP(DTRX, LOGL_NOTICE, "No satisfactory response from transceiver for %s (CMD %s%s%s)\n",</span><br><span style="color: hsl(0, 100%, 40%);">- phy_instance_name(l1h->phy_inst),</span><br><span style="color: hsl(120, 100%, 40%);">+ LOGPPHI(l1h->phy_inst, DTRX, LOGL_NOTICE, "No satisfactory response from transceiver(CMD %s%s%s)\n",</span><br><span> tcm->cmd, tcm->params_len ? " ":"", tcm->params);</span><br><span> </span><br><span> trx_ctrl_send(l1h);</span><br><span>@@ -208,8 +207,8 @@</span><br><span> </span><br><span> if (!transceiver_available &&</span><br><span> !(!strcmp(cmd, "POWEROFF") || !strcmp(cmd, "POWERON"))) {</span><br><span style="color: hsl(0, 100%, 40%);">- LOGP(DTRX, LOGL_ERROR, "CTRL %s ignored: No clock from "</span><br><span style="color: hsl(0, 100%, 40%);">- "transceiver, please fix!\n", cmd);</span><br><span style="color: hsl(120, 100%, 40%);">+ LOGPPHI(l1h->phy_inst, DTRX, LOGL_ERROR, "CTRL %s ignored: No clock from "</span><br><span style="color: hsl(120, 100%, 40%);">+ "transceiver, please fix!\n", cmd);</span><br><span> return -EIO;</span><br><span> }</span><br><span> </span><br><span>@@ -241,7 +240,7 @@</span><br><span> </span><br><span> if (!pending ||</span><br><span> !(strcmp(tcm->cmd, prev->cmd) == 0 && strcmp(tcm->params, prev->params) == 0)) {</span><br><span style="color: hsl(0, 100%, 40%);">- LOGP(DTRX, LOGL_INFO, "Enqueuing TRX control command 'CMD %s%s%s'\n",</span><br><span style="color: hsl(120, 100%, 40%);">+ LOGPPHI(l1h->phy_inst, DTRX, LOGL_INFO, "Enqueuing TRX control command 'CMD %s%s%s'\n",</span><br><span> tcm->cmd, tcm->params_len ? " ":"", tcm->params);</span><br><span> llist_add_tail(&tcm->list, &l1h->trx_ctrl_list);</span><br><span> }</span><br><span>@@ -449,14 +448,13 @@</span><br><span> unsigned int tn, ts_type;</span><br><span> </span><br><span> if (rsp->status)</span><br><span style="color: hsl(0, 100%, 40%);">- LOGP(DTRX, LOGL_ERROR, "transceiver (%s) SETSLOT failed with status %d\n",</span><br><span style="color: hsl(0, 100%, 40%);">- phy_instance_name(pinst), rsp->status);</span><br><span style="color: hsl(120, 100%, 40%);">+ LOGPPHI(pinst, DTRX, LOGL_ERROR, "transceiver SETSLOT failed with status %d\n",</span><br><span style="color: hsl(120, 100%, 40%);">+ rsp->status);</span><br><span> </span><br><span> /* Since message was already validated against CMD we sent, we know format</span><br><span> * of params is: "<TN> <TS_TYPE>" */</span><br><span> if (sscanf(rsp->params, "%u %u", &tn, &ts_type) < 2) {</span><br><span style="color: hsl(0, 100%, 40%);">- LOGP(DTRX, LOGL_ERROR, "transceiver (%s) SETSLOT unable to parse params\n",</span><br><span style="color: hsl(0, 100%, 40%);">- phy_instance_name(pinst));</span><br><span style="color: hsl(120, 100%, 40%);">+ LOGPPHI(pinst, DTRX, LOGL_ERROR, "transceiver SETSLOT unable to parse params\n");</span><br><span> return -EINVAL;</span><br><span> }</span><br><span> </span><br><span>@@ -481,9 +479,9 @@</span><br><span> phy_link_state_set(pinst->phy_link, PHY_LINK_CONNECTED);</span><br><span> return 0;</span><br><span> } else {</span><br><span style="color: hsl(0, 100%, 40%);">- LOGP(DTRX, LOGL_NOTICE,</span><br><span style="color: hsl(0, 100%, 40%);">- "transceiver (%s) rejected POWERON command (%d), re-trying in a few seconds\n",</span><br><span style="color: hsl(0, 100%, 40%);">- phy_instance_name(pinst), rsp->status);</span><br><span style="color: hsl(120, 100%, 40%);">+ LOGPPHI(l1h->phy_inst, DTRX, LOGL_NOTICE,</span><br><span style="color: hsl(120, 100%, 40%);">+ "transceiver rejected POWERON command (%d), re-trying in a few seconds\n",</span><br><span style="color: hsl(120, 100%, 40%);">+ rsp->status);</span><br><span> if (pinst->phy_link->state != PHY_LINK_SHUTDOWN)</span><br><span> phy_link_state_set(pinst->phy_link, PHY_LINK_SHUTDOWN);</span><br><span> return 5;</span><br><span>@@ -493,10 +491,10 @@</span><br><span> }</span><br><span> </span><br><span> if (rsp->status) {</span><br><span style="color: hsl(0, 100%, 40%);">- LOGP(DTRX, critical ? LOGL_FATAL : LOGL_NOTICE,</span><br><span style="color: hsl(0, 100%, 40%);">- "transceiver (%s) rejected TRX command with response: '%s%s%s %d'\n",</span><br><span style="color: hsl(0, 100%, 40%);">- phy_instance_name(pinst), rsp->cmd, rsp->params[0] != '\0' ? " ":"",</span><br><span style="color: hsl(0, 100%, 40%);">- rsp->params, rsp->status);</span><br><span style="color: hsl(120, 100%, 40%);">+ LOGPPHI(l1h->phy_inst, DTRX, critical ? LOGL_FATAL : LOGL_NOTICE,</span><br><span style="color: hsl(120, 100%, 40%);">+ "transceiver rejected TRX command with response: '%s%s%s %d'\n",</span><br><span style="color: hsl(120, 100%, 40%);">+ rsp->cmd, rsp->params[0] != '\0' ? " ":"",</span><br><span style="color: hsl(120, 100%, 40%);">+ rsp->params, rsp->status);</span><br><span> if (critical)</span><br><span> return -EINVAL;</span><br><span> }</span><br><span>@@ -521,7 +519,7 @@</span><br><span> if (parse_rsp(buf, len, &rsp) < 0)</span><br><span> return 0;</span><br><span> </span><br><span style="color: hsl(0, 100%, 40%);">- LOGP(DTRX, LOGL_INFO, "Response message: '%s'\n", buf);</span><br><span style="color: hsl(120, 100%, 40%);">+ LOGPPHI(l1h->phy_inst, DTRX, LOGL_INFO, "Response message: '%s'\n", buf);</span><br><span> </span><br><span> /* abort timer and send next message, if any */</span><br><span> if (osmo_timer_pending(&l1h->trx_ctrl_timer))</span><br><span>@@ -531,12 +529,11 @@</span><br><span> if (llist_empty(&l1h->trx_ctrl_list)) {</span><br><span> /* RSP from a retransmission, skip it */</span><br><span> if (l1h->last_acked && cmd_matches_rsp(l1h->last_acked, &rsp)) {</span><br><span style="color: hsl(0, 100%, 40%);">- LOGP(DTRX, LOGL_NOTICE, "Discarding duplicated RSP "</span><br><span style="color: hsl(120, 100%, 40%);">+ LOGPPHI(l1h->phy_inst, DTRX, LOGL_NOTICE, "Discarding duplicated RSP "</span><br><span> "from old CMD '%s'\n", buf);</span><br><span> return 0;</span><br><span> }</span><br><span style="color: hsl(0, 100%, 40%);">- LOGP(DTRX, LOGL_NOTICE, "Response message without "</span><br><span style="color: hsl(0, 100%, 40%);">- "command\n");</span><br><span style="color: hsl(120, 100%, 40%);">+ LOGPPHI(l1h->phy_inst, DTRX, LOGL_NOTICE, "Response message without command\n");</span><br><span> return -EINVAL;</span><br><span> }</span><br><span> tcm = llist_entry(l1h->trx_ctrl_list.next, struct trx_ctrl_msg,</span><br><span>@@ -546,11 +543,11 @@</span><br><span> if (!cmd_matches_rsp(tcm, &rsp)) {</span><br><span> /* RSP from a retransmission, skip it */</span><br><span> if (l1h->last_acked && cmd_matches_rsp(l1h->last_acked, &rsp)) {</span><br><span style="color: hsl(0, 100%, 40%);">- LOGP(DTRX, LOGL_NOTICE, "Discarding duplicated RSP "</span><br><span style="color: hsl(120, 100%, 40%);">+ LOGPPHI(l1h->phy_inst, DTRX, LOGL_NOTICE, "Discarding duplicated RSP "</span><br><span> "from old CMD '%s'\n", buf);</span><br><span> return 0;</span><br><span> }</span><br><span style="color: hsl(0, 100%, 40%);">- LOGP(DTRX, (tcm->critical) ? LOGL_FATAL : LOGL_NOTICE,</span><br><span style="color: hsl(120, 100%, 40%);">+ LOGPPHI(l1h->phy_inst, DTRX, (tcm->critical) ? LOGL_FATAL : LOGL_NOTICE,</span><br><span> "Response message '%s' does not match command "</span><br><span> "message 'CMD %s%s%s'\n",</span><br><span> buf, tcm->cmd, tcm->params_len ? " ":"", tcm->params);</span><br><span>@@ -609,7 +606,7 @@</span><br><span> burst_len = EGPRS_BURST_LEN;</span><br><span> /* Accept bursts ending with 2 bytes of padding (OpenBTS compatible trx) or without them: */</span><br><span> } else if (len != GSM_BURST_LEN + 10 && len != GSM_BURST_LEN + 8) {</span><br><span style="color: hsl(0, 100%, 40%);">- LOGP(DTRX, LOGL_NOTICE, "Got data message with invalid lenght "</span><br><span style="color: hsl(120, 100%, 40%);">+ LOGPPHI(l1h->phy_inst, DTRX, LOGL_NOTICE, "Got data message with invalid lenght "</span><br><span> "'%d'\n", len);</span><br><span> return -EINVAL;</span><br><span> }</span><br><span>@@ -627,15 +624,15 @@</span><br><span> }</span><br><span> </span><br><span> if (tn >= 8) {</span><br><span style="color: hsl(0, 100%, 40%);">- LOGP(DTRX, LOGL_ERROR, "Illegal TS %d\n", tn);</span><br><span style="color: hsl(120, 100%, 40%);">+ LOGPPHI(l1h->phy_inst, DTRX, LOGL_ERROR, "Illegal TS %d\n", tn);</span><br><span> return -EINVAL;</span><br><span> }</span><br><span> if (fn >= GSM_HYPERFRAME) {</span><br><span style="color: hsl(0, 100%, 40%);">- LOGP(DTRX, LOGL_ERROR, "Illegal FN %u\n", fn);</span><br><span style="color: hsl(120, 100%, 40%);">+ LOGPPHI(l1h->phy_inst, DTRX, LOGL_ERROR, "Illegal FN %u\n", fn);</span><br><span> return -EINVAL;</span><br><span> }</span><br><span> </span><br><span style="color: hsl(0, 100%, 40%);">- LOGP(DTRX, LOGL_DEBUG, "RX burst tn=%u fn=%u rssi=%d toa256=%d\n",</span><br><span style="color: hsl(120, 100%, 40%);">+ LOGPPHI(l1h->phy_inst, DTRX, LOGL_DEBUG, "RX burst tn=%u fn=%u rssi=%d toa256=%d\n",</span><br><span> tn, fn, rssi, toa256);</span><br><span> </span><br><span> #ifdef TOA_RSSI_DEBUG</span><br><span>@@ -667,11 +664,11 @@</span><br><span> uint8_t buf[TRX_MAX_BURST_LEN];</span><br><span> </span><br><span> if ((nbits != GSM_BURST_LEN) && (nbits != EGPRS_BURST_LEN)) {</span><br><span style="color: hsl(0, 100%, 40%);">- LOGP(DTRX, LOGL_ERROR, "Tx burst length %u invalid\n", nbits);</span><br><span style="color: hsl(120, 100%, 40%);">+ LOGPPHI(l1h->phy_inst, DTRX, LOGL_ERROR, "Tx burst length %u invalid\n", nbits);</span><br><span> return -1;</span><br><span> }</span><br><span> </span><br><span style="color: hsl(0, 100%, 40%);">- LOGP(DTRX, LOGL_DEBUG, "TX burst tn=%u fn=%u pwr=%u\n", tn, fn, pwr);</span><br><span style="color: hsl(120, 100%, 40%);">+ LOGPPHI(l1h->phy_inst, DTRX, LOGL_DEBUG, "TX burst tn=%u fn=%u pwr=%u\n", tn, fn, pwr);</span><br><span> </span><br><span> buf[0] = tn;</span><br><span> buf[1] = (fn >> 24) & 0xff;</span><br><span>@@ -688,7 +685,7 @@</span><br><span> if (transceiver_available && llist_empty(&l1h->trx_ctrl_list)) {</span><br><span> send(l1h->trx_ofd_data.fd, buf, nbits + 6, 0);</span><br><span> } else</span><br><span style="color: hsl(0, 100%, 40%);">- LOGP(DTRX, LOGL_ERROR, "Ignoring TX data, transceiver offline.\n");</span><br><span style="color: hsl(120, 100%, 40%);">+ LOGPPHI(l1h->phy_inst, DTRX, LOGL_ERROR, "Ignoring TX data, transceiver offline.\n");</span><br><span> </span><br><span> return 0;</span><br><span> }</span><br><span>@@ -716,9 +713,7 @@</span><br><span> /*! close the TRX for given handle (data + control socket) */</span><br><span> void trx_if_close(struct trx_l1h *l1h)</span><br><span> {</span><br><span style="color: hsl(0, 100%, 40%);">- struct phy_instance *pinst = l1h->phy_inst;</span><br><span style="color: hsl(0, 100%, 40%);">- LOGP(DTRX, LOGL_NOTICE, "Close transceiver for %s\n",</span><br><span style="color: hsl(0, 100%, 40%);">- phy_instance_name(pinst));</span><br><span style="color: hsl(120, 100%, 40%);">+ LOGPPHI(l1h->phy_inst, DTRX, LOGL_NOTICE, "Close transceiver\n");</span><br><span> </span><br><span> trx_if_flush(l1h);</span><br><span> </span><br><span>@@ -749,8 +744,7 @@</span><br><span> struct phy_link *plink = pinst->phy_link;</span><br><span> int rc;</span><br><span> </span><br><span style="color: hsl(0, 100%, 40%);">- LOGP(DTRX, LOGL_NOTICE, "Open transceiver for %s\n",</span><br><span style="color: hsl(0, 100%, 40%);">- phy_instance_name(pinst));</span><br><span style="color: hsl(120, 100%, 40%);">+ LOGPPHI(l1h->phy_inst, DTRX, LOGL_NOTICE, "Open transceiver\n");</span><br><span> </span><br><span> /* initialize ctrl queue */</span><br><span> INIT_LLIST_HEAD(&l1h->trx_ctrl_list);</span><br><span>@@ -806,15 +800,13 @@</span><br><span> </span><br><span> rc = trx_sched_init(&l1h->l1s, pinst->trx);</span><br><span> if (rc < 0) {</span><br><span style="color: hsl(0, 100%, 40%);">- LOGP(DL1C, LOGL_FATAL, "Cannot initialize scheduler for phy "</span><br><span style="color: hsl(0, 100%, 40%);">- "instance %d\n", pinst->num);</span><br><span style="color: hsl(120, 100%, 40%);">+ LOGPPHI(l1h->phy_inst, DL1C, LOGL_FATAL, "Cannot initialize scheduler\n");</span><br><span> return -EIO;</span><br><span> }</span><br><span> </span><br><span> rc = trx_if_open(l1h);</span><br><span> if (rc < 0) {</span><br><span style="color: hsl(0, 100%, 40%);">- LOGP(DL1C, LOGL_FATAL, "Cannot open TRX interface for phy "</span><br><span style="color: hsl(0, 100%, 40%);">- "instance %d\n", pinst->num);</span><br><span style="color: hsl(120, 100%, 40%);">+ LOGPPHI(l1h->phy_inst, DL1C, LOGL_FATAL, "Cannot open TRX interface\n");</span><br><span> trx_phy_inst_close(pinst);</span><br><span> return -EIO;</span><br><span> }</span><br><span></span><br></pre><p>To view, visit <a href="https://gerrit.osmocom.org/c/osmo-bts/+/14373">change 14373</a>. To unsubscribe, or for help writing mail filters, visit <a href="https://gerrit.osmocom.org/settings">settings</a>.</p><div itemscope itemtype="http://schema.org/EmailMessage"><div itemscope itemprop="action" itemtype="http://schema.org/ViewAction"><link itemprop="url" href="https://gerrit.osmocom.org/c/osmo-bts/+/14373"/><meta itemprop="name" content="View Change"/></div></div>
<div style="display:none"> Gerrit-Project: osmo-bts </div>
<div style="display:none"> Gerrit-Branch: master </div>
<div style="display:none"> Gerrit-Change-Id: I5b17a01638ade9a6c41da73e550d5947fa92f568 </div>
<div style="display:none"> Gerrit-Change-Number: 14373 </div>
<div style="display:none"> Gerrit-PatchSet: 2 </div>
<div style="display:none"> Gerrit-Owner: pespin <pespin@sysmocom.de> </div>
<div style="display:none"> Gerrit-Reviewer: Harald Welte <laforge@gnumonks.org> </div>
<div style="display:none"> Gerrit-Reviewer: Jenkins Builder </div>
<div style="display:none"> Gerrit-MessageType: merged </div>