<p>pespin has uploaded this change for <strong>review</strong>.</p><p><a href="https://gerrit.osmocom.org/c/osmo-bts/+/14373">View Change</a></p><pre style="font-family: monospace,monospace; white-space: pre-wrap;">bts-trx: trx_if.c: Introduce logging macro LOGPL1H<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 src/osmo-bts-trx/trx_if.c<br>1 file changed, 33 insertions(+), 40 deletions(-)<br><br></pre><pre style="font-family: monospace,monospace; white-space: pre-wrap;">git pull ssh://gerrit.osmocom.org:29418/osmo-bts refs/changes/73/14373/1</pre><pre style="font-family: monospace,monospace; white-space: pre-wrap;"><span>diff --git a/src/osmo-bts-trx/trx_if.c b/src/osmo-bts-trx/trx_if.c</span><br><span>index ec879c7..8d9fedb 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>@@ -58,6 +58,8 @@</span><br><span> * socket helper functions</span><br><span> */</span><br><span> </span><br><span style="color: hsl(120, 100%, 40%);">+#define LOGPL1H(l1h, section, lvl, fmt, args...) LOGP(section, lvl, "%s: " fmt, phy_instance_name(l1h->phy_inst), ##args)</span><br><span style="color: hsl(120, 100%, 40%);">+</span><br><span> /*! convenience wrapper to open socket + fill in osmo_fd */</span><br><span> static int trx_udp_open(void *priv, struct osmo_fd *ofd, const char *host_local,</span><br><span> uint16_t port_local, const char *host_remote, uint16_t port_remote,</span><br><span>@@ -155,7 +157,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%);">+ LOGPL1H(l1h, 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 +175,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%);">+ LOGPL1H(l1h, 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 +209,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%);">+ LOGPL1H(l1h, 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 +242,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%);">+ LOGPL1H(l1h, 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>@@ -445,18 +446,16 @@</span><br><span> static int trx_ctrl_rx_rsp_setslot(struct trx_l1h *l1h, struct trx_ctrl_rsp *rsp)</span><br><span> {</span><br><span> trx_if_cmd_setslot_cb *cb = (trx_if_cmd_setslot_cb*) rsp->cb;</span><br><span style="color: hsl(0, 100%, 40%);">- struct phy_instance *pinst = l1h->phy_inst;</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%);">+ LOGPL1H(l1h, 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%);">+ LOGPL1H(l1h, 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 +480,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%);">+ LOGPL1H(l1h, 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 +492,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%);">+ LOGPL1H(l1h, 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 +520,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%);">+ LOGPL1H(l1h, 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 +530,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%);">+ LOGPL1H(l1h, 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%);">+ LOGPL1H(l1h, 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 +544,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%);">+ LOGPL1H(l1h, 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%);">+ LOGPL1H(l1h, 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 +607,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%);">+ LOGPL1H(l1h, 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 +625,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%);">+ LOGPL1H(l1h, 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%);">+ LOGPL1H(l1h, 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%);">+ LOGPL1H(l1h, 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 +665,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%);">+ LOGPL1H(l1h, 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%);">+ LOGPL1H(l1h, 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 +686,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%);">+ LOGPL1H(l1h, 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 +714,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%);">+ LOGPL1H(l1h, DTRX, LOGL_NOTICE, "Close transceiver\n");</span><br><span> </span><br><span> trx_if_flush(l1h);</span><br><span> </span><br><span>@@ -749,8 +745,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%);">+ LOGPL1H(l1h, 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 +801,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%);">+ LOGPL1H(l1h, 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%);">+ LOGPL1H(l1h, 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: 1 </div>
<div style="display:none"> Gerrit-Owner: pespin <pespin@sysmocom.de> </div>
<div style="display:none"> Gerrit-MessageType: newchange </div>