https://projects.osmocom.org/https://projects.osmocom.org/favicon.ico?16647414092018-08-31T15:25:24ZOpen Source Mobile CommunicationsOsmoBTS - Bug #3513: unsolicited channel activation acknowledgehttps://projects.osmocom.org/issues/3513?journal_id=110912018-08-31T15:25:24Zstsp
<ul><li><strong>Assignee</strong> changed from <i>4368</i> to <i>stsp</i></li></ul> OsmoBTS - Bug #3513: unsolicited channel activation acknowledgehttps://projects.osmocom.org/issues/3513?journal_id=111082018-09-01T21:20:55Zneelsnhofmeyr@sysmocom.de
<ul></ul><p>That rings a bell, I've a number of times wondered about Chan Activ Ack right upon BTS startup (sysmoBTS). I kind of assumed it was some bootstrapping necessity and didn't pay closer attention, but of course a Chan Activ Ack without a request shouldn't happen, right?</p> OsmoBTS - Bug #3513: unsolicited channel activation acknowledgehttps://projects.osmocom.org/issues/3513?journal_id=111092018-09-02T07:30:07Zlaforge
<ul></ul><p>On Sat, Sep 01, 2018 at 09:20:55PM +0000, neels [REDMINE] wrote:</p>
<blockquote>
<p>That rings a bell, I've a number of times wondered about Chan Activ Ack right upon BTS startup (sysmoBTS). I kind of assumed it was some bootstrapping necessity and didn't pay closer attention, but of course a Chan Activ Ack without a request shouldn't happen, right?</p>
</blockquote>
<p>It shouldn't happen, but it's a known sysmoBTS oddity for many years (maybe forever).</p> OsmoBTS - Bug #3513: unsolicited channel activation acknowledgehttps://projects.osmocom.org/issues/3513?journal_id=121962018-10-15T18:00:57Zpespin
<ul></ul><p>I started adding support for osmo-bts-symo in the osmo-gsm-tester+TTCN3 setup, and I'm running into this issue when running most tests.</p>
<p>Here's related osmo-bts-sysmo log output:<br /><pre>
20180823154258527 DL1C <0006> oml.c:1083 (bts=0,trx=0,ts=0,ss=4) MPH-ACTIVATE.req (hL2=0x000004bb, FCCH TxDL)
20180823154258528 DLINP <0012> input/ipaccess.c:693 received ID get from 1/0/0
20180823154258529 DABIS <000d> abis.c:122 RSL Signalling link for TRX0 up
20180823154258529 DRSL <0000> rsl.c:271 Tx RSL RF RESource INDication
20180823154258530 DL1C <0006> oml.c:816 (bts=0,trx=0,ts=0,ss=4) MPH-ACTIVATE.conf (FCCH TxDL)
20180823154258531 DL1C <0006> oml.c:1083 (bts=0,trx=0,ts=0,ss=4) MPH-ACTIVATE.req (hL2=0x000004bb, SCH TxDL)
20180823154258532 DL1C <0006> oml.c:816 (bts=0,trx=0,ts=0,ss=4) MPH-ACTIVATE.conf (SCH TxDL)
20180823154258532 DL1C <0006> oml.c:1083 (bts=0,trx=0,ts=0,ss=4) MPH-ACTIVATE.req (hL2=0x000004bb, BCCH TxDL)
20180823154258533 DL1C <0006> oml.c:816 (bts=0,trx=0,ts=0,ss=4) MPH-ACTIVATE.conf (BCCH TxDL)
20180823154258533 DL1C <0006> oml.c:1083 (bts=0,trx=0,ts=0,ss=4) MPH-ACTIVATE.req (hL2=0x000004bb, AGCH TxDL)
20180823154258534 DL1C <0006> oml.c:816 (bts=0,trx=0,ts=0,ss=4) MPH-ACTIVATE.conf (AGCH TxDL)
20180823154258534 DL1C <0006> oml.c:1083 (bts=0,trx=0,ts=0,ss=4) MPH-ACTIVATE.req (hL2=0x000004bb, PCH TxDL)
20180823154258535 DL1C <0006> oml.c:816 (bts=0,trx=0,ts=0,ss=4) MPH-ACTIVATE.conf (PCH TxDL)
20180823154258536 DL1C <0006> oml.c:1083 (bts=0,trx=0,ts=0,ss=4) MPH-ACTIVATE.req (hL2=0x000004bb, RACH RxUL)
20180823154258536 DL1C <0006> oml.c:816 (bts=0,trx=0,ts=0,ss=4) MPH-ACTIVATE.conf (RACH RxUL)
20180823154258537 DL1C <0006> l1sap.c:622 activate confirm chan_nr=0x40 trx=0
20180823154258537 DRSL <0000> rsl.c:741 (bts=0,trx=0,ts=0,pchan=CCCH+SDCCH4) (ss=0) SDCCH Tx CHAN ACT ACK
20180823154258537 DL1C <0006> oml.c:1424 (bts=0,trx=0,ts=0,ss=4) SET_CIPHERING (ALG=0 TxDL)
20180823154258538 DL1C <0006> oml.c:1269 (bts=0,trx=0,ts=0,ss=4) MPH-CONFIG.conf (Configure ciphering params)
20180823154258538 DL1C <0006> oml.c:1424 (bts=0,trx=0,ts=0,ss=4) SET_CIPHERING (ALG=0 RxUL)
20180823154258539 DL1C <0006> oml.c:1269 (bts=0,trx=0,ts=0,ss=4) MPH-CONFIG.conf (Configure ciphering params)
20180823154258555 DLINP <0012> input/ipa.c:65 10.42.42.9:3003 connection closed with server
20180823154258555 DABIS <000d> abis.c:144 Signalling link down
</pre></p>
<p>The message is sent in l1sap.c <code>l1sap_info_act_cnf</code>, and it's triggered by this code:<br /><pre>
/* any L1 MPH_INFO confirm prim recevied from bts model */
static int l1sap_mph_info_cnf(struct gsm_bts_trx *trx,
struct osmo_phsap_prim *l1sap, struct mph_info_param *info)
{
int rc = 0;
switch (info->type) {
case PRIM_INFO_ACTIVATE:
rc = l1sap_info_act_cnf(trx, l1sap, &info->u.act_cnf);
break;
case PRIM_INFO_DEACTIVATE:
rc = l1sap_info_rel_cnf(trx, l1sap, &info->u.act_cnf);
break;
default:
LOGP(DL1C, LOGL_NOTICE, "unknown MPH_INFO cnf type %d\n",
info->type);
break;
}
return rc;
}
</pre></p>
<p>so my guess is that during initialization we get same notification from lower layer than when we receive a chan act, but in the first case we should avoid sending that.</p> OsmoBTS - Bug #3513: unsolicited channel activation acknowledgehttps://projects.osmocom.org/issues/3513?journal_id=122002018-10-15T20:30:07Zlaforge
<ul></ul><p>On Mon, Oct 15, 2018 at 06:00:57PM +0000, pespin [REDMINE] wrote:</p>
<blockquote>
<p>so my guess is that during initialization we get same notification from lower layer than when we receive a chan act, but in the first case we should avoid sending that.</p>
</blockquote>
<p>yes, it's very well undrstood what's causing this. We are "activating" the BCCH inside<br />osmo-bts using code that is normally used for activating dedicated channels via rsl.</p>
<p>I think we abuse ts->lchan<sup><a href="#fn4">4</a></sup> for the BCCH, as a BCCH-carrying PCHAN can only ever have<br />up to four dedicated channels (SDCCH 0..3) and 4 is the first free index.</p>
<p>And once the PHY acknowledges the activation, we unconditionally send the ACK, as we don't<br />have any state that tells us whether it was an internal activation, or one triggered by RSL.</p>
<p>But given that it's not really creating any problem,<br />it really should be at the lowest of priorities.</p> OsmoBTS - Bug #3513: unsolicited channel activation acknowledgehttps://projects.osmocom.org/issues/3513?journal_id=122132018-10-16T10:55:56Zpespin
<ul></ul><p>Well it makes almost all TTCN3 BTS_tests fail when running against a sysmobts. So either we fix this or we account for this in TTCN3.</p> OsmoBTS - Bug #3513: unsolicited channel activation acknowledgehttps://projects.osmocom.org/issues/3513?journal_id=122392018-10-16T15:12:09Zlaforge
<ul></ul><p>Hi Pau,</p>
<p>On Tue, Oct 16, 2018 at 10:55:56AM +0000, pespin [REDMINE] wrote:</p>
<blockquote>
<p>Well it makes almost all TTCN3 BTS_tests fail when running against a sysmobts. So either we fix this or we account for this in TTCN3.</p>
</blockquote>
<p>ok, then that's a new reason to fix it. So far, in real-world<br />installations/uses, it never has been a problem.</p>
<p>The related code is in osmo-bts/sysmo/oml.c around line 284:</p>
<blockquote>
<p>/* ugly hack to auto-activate all SAPIs for the BCCH/CCCH on TS0 */</p>
</blockquote>
<p>where we <br />1) set lchan->rel_act_kind = LCHAN_REL_ACT_OML</p>
<p>in the response path, we have rsl_tx_chan_act_acknack() being called, and<br />it checks if lchan->rel_act_kind != LCHAN_REL_ACT_RSL as a condition to<br />suppress the transmission of the RSL CHAN ACTIV ACK message. But<br />somehow that doesn't seem to work?</p> OsmoBTS - Bug #3513: unsolicited channel activation acknowledgehttps://projects.osmocom.org/issues/3513?journal_id=122452018-10-16T17:01:03Zpespin
<ul></ul><p>That's the path which seems to be followed by the activation originating the transmission of the Chan Act ACK:<br /><pre>
opstart_compl (mo->bts->c0->ts[0].lchan[CCCH_LCHAN].rel_act_kind = LCHAN_REL_ACT_OML)
lchan_activate
enqueue_sapi_act_cmd
queue_sapi_command (sapi_activate_cb)
sapi_queue_send
sapi_queue_exeute
mph_send_activate_req
l1if_gsm_req_compl (lchan_act_compl_cb)
_l1if_req_compl
[lchan_act_compl_cb]
sapi_queue_dispatch
[sapi_activate_cb]
lchan_set_state ?
mph_info_chan_confirm (cause=0) !!!!
l1sap_up (type=PRIM_INFO_ACTIVATE PRIM_MPH_INFO, PRIM_OP_CONFIR)
l1sap_mph_info_cnf
l1sap_info_act_cnf
rsl_tx_chan_act_acknack(lchan, info_act_cnf->cause);
if (lchan->rel_act_kind != LCHAN_REL_ACT_RSL) {
</pre></p>
<p>It seems only the last SAPI activated in <code>opstart_compl</code> is provoking the transmission, see lchan_activate using <code>sapis_for_lchan[lchan->type]</code>.<br /><pre>
static const struct sapi_dir ccch_sapis[] = {
{ GsmL1_Sapi_Fcch, GsmL1_Dir_TxDownlink },
{ GsmL1_Sapi_Sch, GsmL1_Dir_TxDownlink },
{ GsmL1_Sapi_Bcch, GsmL1_Dir_TxDownlink },
{ GsmL1_Sapi_Agch, GsmL1_Dir_TxDownlink },
{ GsmL1_Sapi_Pch, GsmL1_Dir_TxDownlink },
{ GsmL1_Sapi_Rach, GsmL1_Dir_RxUplink },
};
</pre></p>
<p>However, it seems they don't follow exactly the same path, otherwise if <code>rel_act_kind = LCHAN_REL_ACT_OML</code> was checked at the end in <code>rsl_tx_chan_act_acknack</code>, it would print following message, and we don't see it:<br /><pre>
LOGP(DRSL, LOGL_NOTICE, "%s not sending CHAN ACT %s\n",
gsm_lchan_name(lchan), cause ? "NACK" : "ACK");
</pre><br />They don't even reach <code>l1sap_info_act_cnf</code>, as otherwise we'd see "1sap.c:622 activate confirm chan_nr=..." as we do for UL RACH.</p>
<p>That's because this check in <code>oml.c:sapi_activate_cb</code>:<br /><pre>
if (!llist_empty(&lchan->sapi_cmds))
return 0;
</pre><br />so only last one is pushed to upper layers through later call to <code>mph_info_chan_confirm</code>.</p>
<p>I'll have a deeper look at how lchan->rel_act_kind is managed and also do some tests with L1P and L1C with more verbose debug levels.</p> OsmoBTS - Bug #3513: unsolicited channel activation acknowledgehttps://projects.osmocom.org/issues/3513?journal_id=122462018-10-16T17:45:48Zpespin
<ul><li><strong>File</strong> <a href="/attachments/3410">run.tar.bz</a> <a class="icon-only icon-download" title="Download" href="/attachments/download/3410/run.tar.bz">run.tar.bz</a> added</li></ul><p>Attaching run.tar.bz with related issue appearing when running a TTCN3 test.</p> OsmoBTS - Bug #3513: unsolicited channel activation acknowledgehttps://projects.osmocom.org/issues/3513?journal_id=123082018-10-22T09:13:15Zpespin
<ul><li><strong>Assignee</strong> changed from <i>stsp</i> to <i>pespin</i></li></ul> OsmoBTS - Bug #3513: unsolicited channel activation acknowledgehttps://projects.osmocom.org/issues/3513?journal_id=123092018-10-22T10:20:28Zpespin
<ul></ul><p>After adding extra logging, the issue seems to be how we convert lchan to chan_nr and back to lchan when passing it from sysmobts specific lower layers to l1sap. See how subslot is converted from 4 to 0 and lchan pointer thus changes:<br /><pre>
20180830081800820 DL1C <0006> /home/pespin/dev/sysmocom/git/osmo-bts/src/osmo-bts-sysmo/oml.c:291 ====> trying to activate lchans of BCCH
20180830081800820 DL1C <0006> /home/pespin/dev/sysmocom/git/osmo-bts/src/common/lchan.c:31 (bts=0,trx=0,ts=0,ss=4) state NONE -> ACTIVATION REQUESTED
...
20180830081800832 DL1C <0006> /home/pespin/dev/sysmocom/git/osmo-bts/src/osmo-bts-sysmo/oml.c:819 (bts=0,trx=0,ts=0,ss=4) MPH-ACTIVATE.conf (RACH RxUL)
20180830081800832 DL1C <0006> /home/pespin/dev/sysmocom/git/osmo-bts/src/osmo-bts-sysmo/oml.c:825 Successful activation of L1 SAPI RACH on TS 0
20180830081800833 DL1C <0006> /home/pespin/dev/sysmocom/git/osmo-bts/src/common/lchan.c:31 (bts=0,trx=0,ts=0,ss=4) state ACTIVATION REQUESTED -> ACTIVE
20180830081800833 DL1C <0006> /home/pespin/dev/sysmocom/git/osmo-bts/src/osmo-bts-sysmo/oml.c:60 Preparing L1 primitive chan_nr=SDCCH/8(0) on TS0 (0x40) lchan=(bts=0,trx=0,ts=0,ss=4) (0xb6d188c0)
20180830081800833 DL1C <0006> /home/pespin/dev/sysmocom/git/osmo-bts/src/common/l1sap.c:625 activate confirm chan_nr=SDCCH/8(0) on TS0 (0x40) trx=0 lchan=(bts=0,trx=0,ts=0,ss=0) (0xb6d0b1e0)
20180830081800833 DRSL <0000> /home/pespin/dev/sysmocom/git/osmo-bts/src/common/rsl.c:741 (bts=0,trx=0,ts=0,pchan=CCCH+SDCCH4) (ss=0) SDCCH Tx CHAN ACT ACK
</pre></p>
<p>So when checking for <code>lchan->rel_act_kind != LCHAN_REL_ACT_RSL</code> it checks for a different channel for which <code>LCHAN_REL_ACT_OML</code> was set in <code>opstart_compl</code>.</p> OsmoBTS - Bug #3513: unsolicited channel activation acknowledgehttps://projects.osmocom.org/issues/3513?journal_id=123102018-10-22T11:55:06Zpespin
<ul><li><strong>Status</strong> changed from <i>New</i> to <i>Feedback</i></li><li><strong>% Done</strong> changed from <i>0</i> to <i>90</i></li></ul><p>I submitted following commit which fixes the issue:<br /><a class="external" href="https://gerrit.osmocom.org/#/c/osmo-bts/+/11427">https://gerrit.osmocom.org/#/c/osmo-bts/+/11427</a> Convert lchan CCCH_LCHAN to chan_nr BCCH and viceversa</p> OsmoBTS - Bug #3513: unsolicited channel activation acknowledgehttps://projects.osmocom.org/issues/3513?journal_id=123162018-10-22T15:19:56Zpespin
<ul><li><strong>Status</strong> changed from <i>Feedback</i> to <i>Resolved</i></li><li><strong>% Done</strong> changed from <i>90</i> to <i>100</i></li></ul><p>Merged, closing.</p>