Bug #4829
openOsmocomBB Rx bit errors in dedicated mode
40%
Description
I'm observing quite a number of bit errors when receiving in dedicated mode.
Those bit errors are not present while in receive-only mode (CCCH/BCCH camping.
The bit errors can be observed on SDCCH/4, SDCCH/8 and TCH/F (didn't try TCH/H).
I've tried to roll back to old OsmocomBB firmware versions as old as 2012 (using old gnuarm-4.0.x toolchain) - the problem even exists in those old versions, so it doesn't look like a regression.
I've tested with perfect RF signals (coaxial connection via attenuators) to exclude any real-world impact.
I've tested both with sysmoBTS 1002 as well as with a commercial cellular network.
I've tested with C118, C121, C123 and C140.
In all situations, the problem persists and looks like this:
Camping with good signal level 0 BER / fire_crc = 2
<000c> l1ctl.c:237 BCCH on TS0 (0301/13/02) -56 dBm 0/0: 59 06 1a 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 ff e5 04 00 <000c> l1ctl.c:237 PCH/AGCH on TS0 (0301/17/06) -56 dBm 0/0: 03 03 01 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b <000c> l1ctl.c:237 PCH/AGCH on TS0 (0301/23/12) -56 dBm 0/0: 15 06 21 00 01 f0 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b <000c> l1ctl.c:237 PCH/AGCH on TS0 (0301/01/16) -56 dBm 0/0: 2d 06 3f 03 41 e3 67 00 68 8f 00 00 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b
Once switched to dedicated channel:
<000c> l1ctl.c:237 SDCCH/8(0) on TS1 (0301/10/00) -56 dBm 0/0: 03 03 01 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b <000c> l1ctl.c:237 SDCCH/8(0) on TS1 (0301/16/32) -56 dBm 66/2: a3 4b 33 0a 38 66 2a a4 57 cc 2e db 60 f7 e2 7e 9e cd ac d8 ee dc bd <000c> l1ctl.c:300 Dropping frame with 66 bit errors <000c> l1ctl.c:237 SDCCH/8(0) on TS1 (0301/09/00) -56 dBm 74/2: a3 35 0f 0a b8 79 13 2a 6b 5e c2 da 60 f7 e2 7e 9e cd ac d8 ee dc fd <000c> l1ctl.c:300 Dropping frame with 74 bit errors <000c> l1ctl.c:237 SDCCH/8(0) on TS1 (0301/08/00) -56 dBm 82/2: a3 35 0f 14 f1 f7 17 aa 57 cc 2e 12 67 f7 e2 7e 9e cd ac d8 7e 29 85 <000c> l1ctl.c:300 Dropping frame with 82 bit errors <000c> l1ctl.c:237 SDCCH/8(0) on TS1 (0301/14/32) -56 dBm 77/2: a3 4b 33 0a 38 66 2a a4 57 cc 2e 92 44 f8 e2 7e 9e cd ac d8 fe 85 2f <000c> l1ctl.c:300 Dropping frame with 77 bit errors <000c> l1ctl.c:237 SDCCH/8(0) on TS1 (0301/07/00) -56 dBm 74/2: a3 4b 33 0a 38 66 2a 24 6b 5e c2 da 60 f7 e2 7e 9e cd ac d8 fe 85 2f <000c> l1ctl.c:300 Dropping frame with 74 bit errors
so as we can see, he very first block is still received well, all other blocks have massive bit errors (typically in he 70..95 erroneous bit range)
Playing with the source code I could narrow it down to whether or not we are enabling the PA in the rffe_mode()
function by means of tspact | PA_ENABLE
If I enable the PA only for RACH / access burst, but not for any normal bursts, the SDCCH bit errors are not reported anymore.
I've played a lot with l1s_tx_win_ctrl in terms of ordering, etc. but the problem persists.
It cannot be a general scheduling problem, as the TX window duration is not affected by whether or not we enable the PA. There are just as many TPU instructions etc. even without that one bit.
Files
Related issues
Updated by laforge over 3 years ago
- File sky77324.pdf sky77324.pdf added
- File Sch_C118_A2_C_L3_1.0.pdf Sch_C118_A2_C_L3_1.0.pdf added
- File SF_C118_A3_C_L3_1.2.pdf SF_C118_A3_C_L3_1.2.pdf added
Ok, after another full day of debugging yesterday, I'll try to summarize my actions (and findings) here:
Bug in gsm48_rr showing SNR value as BER¶
I saw that some times, all blocks were reported with num_biterr=0 but the measurement summary still showed non-zero BER. That was just a display/printing bug (https://gerrit.osmocom.org/c/osmocom-bb/+/20864)
Nevertheless, I still see tons of blocks where the DSP reports num_biterr > 60 and fire_crc == 2 in perfect RF signal conditions, so the above was an unrelated, insignificant issue.
TPU_DEBUG¶
I extracted the TPU instructions using TPU_DEBUG. The latter first had to be fixed:- https://gerrit.osmocom.org/c/osmocom-bb/+/20880
- https://gerrit.osmocom.org/c/osmocom-bb/+/20885
- https://gerrit.osmocom.org/c/osmocom-bb/+/20886
In order to not overflow the UART, I used the non-standard high-baudrate patch from burst-ind
, see laforge/baudrate
.
A typical TPU window of a transmit burst looks like this:
TPU FN 1182503 0001 3284 AT 4740 4741 72e5 SYNCHRO 4837 4742 264b AT 1611 1612 8004 MOVE TSP_TX_1=0x0000 1613 9743 MOVE TSP_TX_2=0x00ba 1614 89e0 MOVE TSP_CTLR1=0x004f DEV_IDX=TRF6151, BITLEN=16 TSP_DATA=0x00ba 1615 8041 MOVE TSP_CTRL2=0x0002 WRITE 1616 92c4 MOVE TSP_TX_1=0x0096 1617 8e23 MOVE TSP_TX_2=0x0071 1618 89e0 MOVE TSP_CTLR1=0x004f DEV_IDX=TRF6151, BITLEN=16 TSP_DATA=0x9671 1619 8041 MOVE TSP_CTRL2=0x0002 WRITE 1620 9c84 MOVE TSP_TX_1=0x00e4 1621 9743 MOVE TSP_TX_2=0x00ba 1622 89e0 MOVE TSP_CTLR1=0x004f DEV_IDX=TRF6151, BITLEN=16 TSP_DATA=0xe4ba 1623 8041 MOVE TSP_CTRL2=0x0002 WRITE 1624 268e AT 1678 1679 9004 MOVE TSP_TX_1=0x0080 1680 80c0 MOVE TSP_CTLR1=0x0006 DEV_IDX=TWL3025, BITLEN=7 TSP_DATA=0x80 1681 8041 MOVE TSP_CTRL2=0x0002 WRITE 1682 a00b WAIT 11 1694 9804 MOVE TSP_TX_1=0x00c0 1695 80c0 MOVE TSP_CTLR1=0x0006 DEV_IDX=TWL3025, BITLEN=7 TSP_DATA=0xc0 1696 8041 MOVE TSP_CTRL2=0x0002 WRITE 1697 a089 WAIT 137 1835 9004 MOVE TSP_TX_1=0x0080 1836 80c0 MOVE TSP_CTLR1=0x0006 DEV_IDX=TWL3025, BITLEN=7 TSP_DATA=0x80 1837 8041 MOVE TSP_CTRL2=0x0002 WRITE 1838 a023 WAIT 35 1874 2763 AT 1891 1892 9404 MOVE TSP_TX_1=0x00a0 1893 80c0 MOVE TSP_CTLR1=0x0006 DEV_IDX=TWL3025, BITLEN=7 TSP_DATA=0xa0 1894 8041 MOVE TSP_CTRL2=0x0002 WRITE 1895 8066 MOVE TSPACT_L=0x0003 PA_ENABLE:0->1 TRENA:1->0 1896 29d7 AT 2519 2520 9004 MOVE TSP_TX_1=0x0080 2521 80c0 MOVE TSP_CTLR1=0x0006 DEV_IDX=TWL3025, BITLEN=7 TSP_DATA=0x80 2522 8041 MOVE TSP_CTRL2=0x0002 WRITE 2523 a023 WAIT 35 2559 8004 MOVE TSP_TX_1=0x0000 2560 80c0 MOVE TSP_CTLR1=0x0006 DEV_IDX=TWL3025, BITLEN=7 TSP_DATA=0x00 2561 8041 MOVE TSP_CTRL2=0x0002 WRITE 2562 8004 MOVE TSP_TX_1=0x0000 2563 9743 MOVE TSP_TX_2=0x00ba 2564 89e0 MOVE TSP_CTLR1=0x004f DEV_IDX=TRF6151, BITLEN=16 TSP_DATA=0x00ba 2565 8041 MOVE TSP_CTRL2=0x0002 WRITE 2566 8826 MOVE TSPACT_L=0x0041 PA_ENABLE:1->0 TRENA:0->1 2567 52e5 OFFSET 4837 2568 0000 SLEEP
As we can see, PA_ENABLE is present for 2566-1895 = 671 qbits only. That's 167 bits, i.e. just about one burst with a bit of lead time before and after. Exactly what is expected. PA_ENABLE is not present at times beyond that.
A typical receive TPU window looks like this:
TPU FN 1182517 0001 3284 AT 4740 4741 72e5 SYNCHRO 4837 4742 328e AT 4750 4751 8004 MOVE TSP_TX_1=0x0000 4752 9743 MOVE TSP_TX_2=0x00ba 4753 89e0 MOVE TSP_CTLR1=0x004f DEV_IDX=TRF6151, BITLEN=16 TSP_DATA=0x00ba 4754 8041 MOVE TSP_CTRL2=0x0002 WRITE 4755 94a4 MOVE TSP_TX_1=0x00a5 4756 8923 MOVE TSP_TX_2=0x0049 4757 89e0 MOVE TSP_CTLR1=0x004f DEV_IDX=TRF6151, BITLEN=16 TSP_DATA=0xa549 4758 8041 MOVE TSP_CTRL2=0x0002 WRITE 4759 93c4 MOVE TSP_TX_1=0x009e 4760 8003 MOVE TSP_TX_2=0x0000 4761 89e0 MOVE TSP_CTLR1=0x004f DEV_IDX=TRF6151, BITLEN=16 TSP_DATA=0x9e00 4762 8041 MOVE TSP_CTRL2=0x0002 WRITE 4763 8144 MOVE TSP_TX_1=0x000a 4764 9743 MOVE TSP_TX_2=0x00ba 4765 89e0 MOVE TSP_CTLR1=0x004f DEV_IDX=TRF6151, BITLEN=16 TSP_DATA=0x0aba 4766 8041 MOVE TSP_CTRL2=0x0002 WRITE 4767 3364 AT 4964 4965 8204 MOVE TSP_TX_1=0x0010 4966 80c0 MOVE TSP_CTLR1=0x0006 DEV_IDX=TWL3025, BITLEN=7 TSP_DATA=0x10 4967 8041 MOVE TSP_CTRL2=0x0002 WRITE 4968 a000 WAIT 0 4969 8304 MOVE TSP_TX_1=0x0018 4970 80c0 MOVE TSP_CTLR1=0x0006 DEV_IDX=TWL3025, BITLEN=7 TSP_DATA=0x18 4971 8041 MOVE TSP_CTRL2=0x0002 WRITE 4972 a03c WAIT 60 5033 8204 MOVE TSP_TX_1=0x0010 5034 80c0 MOVE TSP_CTLR1=0x0006 DEV_IDX=TWL3025, BITLEN=7 TSP_DATA=0x10 5035 8041 MOVE TSP_CTRL2=0x0002 WRITE 5036 2036 AT 54 0055 8284 MOVE TSP_TX_1=0x0014 0056 80c0 MOVE TSP_CTLR1=0x0006 DEV_IDX=TWL3025, BITLEN=7 TSP_DATA=0x14 0057 8041 MOVE TSP_CTRL2=0x0002 WRITE 0058 22b2 AT 690 0691 8204 MOVE TSP_TX_1=0x0010 0692 80c0 MOVE TSP_CTLR1=0x0006 DEV_IDX=TWL3025, BITLEN=7 TSP_DATA=0x10 0693 8041 MOVE TSP_CTRL2=0x0002 WRITE 0694 8004 MOVE TSP_TX_1=0x0000 0695 80c0 MOVE TSP_CTLR1=0x0006 DEV_IDX=TWL3025, BITLEN=7 TSP_DATA=0x00 0696 8041 MOVE TSP_CTRL2=0x0002 WRITE 0697 8004 MOVE TSP_TX_1=0x0000 0698 9743 MOVE TSP_TX_2=0x00ba 0699 89e0 MOVE TSP_CTLR1=0x004f DEV_IDX=TRF6151, BITLEN=16 TSP_DATA=0x00ba 0700 8041 MOVE TSP_CTRL2=0x0002 WRITE 0701 52e5 OFFSET 4837 0702 0000 SLEEP
As we can see, no fiddling with the PA enable line anywhere.
So nothing out of the ordinary is observed here.
hardware disabling PAENE signal¶
I excluded any impact by software by de-soldering R67 on my C123 (0-ohm resistor in-line with the PAEN signal). Unfortunately that of course means I can no longe send a RACH request and hence not establish a channel.
I used radio-link-timeout infinite
and manual activation of the SDCCH/8(0) on TS1 on the BTS/BSC side, and injected a fake "IMMEDIATE ASSIGN" to mobile
to get the channel activated on both sides.
Using an unmodified normal firmware with TX enabled and PAENA signal connected (R67 placed) always showed the bit errors. Removing R67 with identical firmware makes the bit errors go away. All downlink blocks are now received free of errors.
So we have concluded that it must be some kind of physical effect caused by the PA being enabled.
hardware disabling APC signal¶
With PAEN re-connected via R67, I soldered a 10 Ohms resistor parallel to C99. This effectively disable the APC bias voltage.
Interestingly, the results were different from the tests above with PAENA disabled.
With VAPC grounded, The MS was no longer able to transmit. However, the downlink BER problems still persisted!
So we can summarize:- Disabling the PA via PAENA: downlink BER disappears
- Disabling the PA via APC: downlink BER remains.
At least according to the C118 schematics (I don't think we ever had those for the C123), the PAENA signal doesn't connect anywhere else. so unless there's some hardware bug (appearing in multiple phones at the same time!), The PA must be causing the problem.
reducing /increasing transmit power¶
All previous tests of the past days were performed using 16 dBm MS-side transmit power (via ms power max
in osmo-bsc.cfg).
After re-enabling PAENA and APC:
I tested with 30dBm and 0dBm transmit power on the MS side. In all cases, even with the low 0dBm transmit power, the downlink BER problem appears.
Transmit power was actually confirmed to be reduced in the 0dBm case, as I had to remove lots of attenuation from the RF path to make the RACH actually still reach the BTS at 0dBm transmit power.
We can summarize:- the amount of gain / RF transmit power in the PA does not impact the number of BER in downlink
comparing commercial networks with osmo-bts-sysmo¶
It can be seen that the high downlink BER in the commercial network only appears on the SACCH of a SDCCH/8, while in my lab setup with osmo-bts-sysmo it appears on both SDCCH/8 and the associated SACCH. So there may be another problem there?
Updated by laforge over 3 years ago
Some more log output:
on osmo-bts-sysmo¶
<000c> l1ctl.c:237 BCCH on TS0 (0821/17/02) -70 dBm 0/0: 59 06 1a 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 ff e5 04 00 <0003> gsm48_rr.c:4835 Channel provides data. <0003> gsm322.c:703 Starting CS timer with 4 seconds. <0001> gsm48_rr.c:1829 New SYSTEM INFORMATION 2 <000c> l1ctl.c:237 BCCH on TS0 (0821/16/02) -70 dBm 0/0: 49 06 1b 1b 39 00 f1 10 00 01 c8 03 05 27 47 40 e5 04 00 2c 0b 2b 2b <0001> sysinfo.c:703 New SYSTEM INFORMATION 3 (mcc 001 mnc 01 lac 0x0001) <0001> gsm48_rr.c:1920 Changing CCCH_MODE to 1 <000c> l1ctl.c:237 PCH/AGCH on TS0 (0821/00/12) -70 dBm 0/0: 15 06 21 00 01 f0 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b <000c> l1ctl.c:237 PCH/AGCH on TS0 (0821/04/16) -70 dBm 0/0: 15 06 21 00 01 f0 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b <000c> l1ctl.c:237 PCH/AGCH on TS0 (0821/10/22) -70 dBm 0/0: 15 06 21 00 01 f0 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b <000c> l1ctl.c:237 PCH/AGCH on TS0 (0821/14/26) -70 dBm 0/0: 15 06 21 00 01 f0 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b <000c> l1ctl.c:237 PCH/AGCH on TS0 (0821/20/32) -70 dBm 0/0: 15 06 21 00 01 f0 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b <000c> l1ctl.c:237 PCH/AGCH on TS0 (0821/24/36) -70 dBm 0/0: 15 06 21 00 01 f0 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b <000c> l1ctl.c:237 PCH/AGCH on TS0 (0821/04/42) -70 dBm 0/0: 15 06 21 00 01 f0 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b <000c> l1ctl.c:237 PCH/AGCH on TS0 (0821/08/46) -70 dBm 0/0: 15 06 21 00 01 f0 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b <000c> l1ctl.c:237 BCCH on TS0 (0821/15/02) -70 dBm 0/0: 31 06 1c 00 f1 10 00 01 47 40 e5 04 00 01 2b 2b 2b 2b 2b 2b 2b 2b 2b <0001> gsm48_rr.c:1952 New SYSTEM INFORMATION 4 (mcc 001 mnc 01 lac 0x0001) <000c> l1ctl.c:237 PCH/AGCH on TS0 (0821/19/06) -70 dBm 0/0: 03 03 01 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b <000c> l1ctl.c:237 PCH/AGCH on TS0 (0821/25/12) -70 dBm 0/0: 15 06 21 00 01 f0 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b <000c> l1ctl.c:237 PCH/AGCH on TS0 (0821/03/16) -70 dBm 0/0: 15 06 21 00 01 f0 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b <000c> l1ctl.c:237 PCH/AGCH on TS0 (0821/09/22) -70 dBm 0/0: 15 06 21 00 01 f0 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b <000c> l1ctl.c:237 PCH/AGCH on TS0 (0821/13/26) -70 dBm 0/0: 15 06 21 00 01 f0 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b <000c> l1ctl.c:237 PCH/AGCH on TS0 (0821/19/32) -70 dBm 0/0: 15 06 21 00 01 f0 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b <000c> l1ctl.c:237 PCH/AGCH on TS0 (0821/23/36) -70 dBm 0/0: 15 06 21 00 01 f0 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b <000c> l1ctl.c:237 PCH/AGCH on TS0 (0821/03/42) -70 dBm 0/0: 15 06 21 00 01 f0 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b <000c> l1ctl.c:237 PCH/AGCH on TS0 (0821/07/46) -70 dBm 0/0: 15 06 21 00 01 f0 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b <000c> l1ctl.c:237 BCCH on TS0 (0821/14/02) -70 dBm 0/0: 55 06 19 8f b3 80 00 00 00 00 00 00 00 00 00 00 00 00 00 e5 04 00 2b <0001> sysinfo.c:615 Now updating previously received SYSTEM INFORMATION 4 <0001> gsm48_rr.c:1800 New SYSTEM INFORMATION 1 <0003> gsm322.c:2721 Received relevant sysinfo. <0003> gsm322.c:713 stopping pending CS timer. <0003> gsm322.c:2327 Scan frequency 871(DCS): Cell found. (rxlev -70 mcc 001 mnc 01 lac 0001) <0003> gsm322.c:1841 Select using access class <0003> gsm322.c:383 A (RLA_C (-70) - RXLEV_ACC_MIN (-110)) = 40 <0003> gsm322.c:385 B (MS_TXPWR_MAX_CCH (16) - p (30)) = -14 <0003> gsm322.c:387 C1 (A - MAX(B,0)) = 40 <0003> gsm322.c:1955 Cell ARFCN 871(DCS): Cell found, (rxlev=-70 mcc=001 mnc=01 lac=0001 Test, Test) <0003> gsm322.c:1970 Cell ARFCN 871(DCS) selected. <0003> gsm322.c:2428 Tune to frequency 871. <0003> gsm322.c:470 Sync to ARFCN=871(DCS) rxlev=-70 (Sysinfo, ccch mode NON-COMB) <0003> gsm322.c:2455 Cell available. <0003> gsm322.c:4060 (ms 1) Event 'EVENT_CELL_FOUND' for Cell selection in state 'C2 stored cell selection' <000e> gsm322.c:3392 Camping normally on cell (ARFCN=871(DCS) mcc=001 mnc=01 Test, Test) <0003> gsm322.c:833 new state 'C2 stored cell selection' -> 'C3 camped normally' <0005> gsm48_mm.c:4305 (ms 1) Received 'MM_EVENT_CELL_SELECTED' event in state MM IDLE, PLMN search <0005> gsm48_mm.c:904 new MM IDLE state PLMN search -> location updating needed <0005> gsm48_mm.c:904 new MM IDLE state location updating needed -> attempting to update <0005> gsm48_mm.c:424 starting T3212 (periodic loc. upd. delay) with 1800 seconds <0005> gsm48_mm.c:2289 Do normal Loc. upd. <000e> gsm48_mm.c:2204 Perform location update (MCC 001, MNC 01 LAC 0x0001) <0005> gsm48_mm.c:2340 LOCATION UPDATING REQUEST <0005> gsm48_mm.c:2360 using LAI (mcc 001 mnc 01 lac 0xfffe) <0005> gsm48_mm.c:2373 using IMSI 001010000000001 <0005> gsm48_mm.c:909 new state MM IDLE, attempting to update -> wait for RR connection (location updating) <0001> gsm48_rr.c:5462 (ms 1) Message 'RR_EST_REQ' received in state idle (sapi 0) <000e> gsm48_rr.c:1299 Establish radio link due to mobility management request <0003> gsm322.c:4060 (ms 1) Event 'EVENT_LEAVE_IDLE' for Cell selection in state 'C3 camped normally' <0003> gsm322.c:833 new state 'C3 camped normally' -> 'connected mode 1' <0003> gsm322.c:3677 Going to camping (normal) ARFCN 871(DCS). <0003> gsm322.c:456 Sync to ARFCN=871(DCS), but there is a sync already pending <0001> gsm48_rr.c:359 new state idle -> connection pending <0001> gsm48_rr.c:1446 CHANNEL REQUEST: 00 (Location Update with NECI) <0003> gsm322.c:2956 Channel synched. (ARFCN=871(DCS), snr=16, BSIC=63) <0001> gsm322.c:2979 using DSC of 90 <000c> l1ctl.c:237 PCH/AGCH on TS0 (0821/06/46) -70 dBm 0/0: 15 06 21 00 01 f0 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b <0003> gsm48_rr.c:4835 Channel provides data. <0001> gsm48_rr.c:1587 RANDOM ACCESS (requests left 8) <0001> gsm48_rr.c:1643 RANDOM ACCESS (Tx-integer 12 combined no S(lots) 0 ra 0x0c) <0001> gsm48_rr.c:1680 Use MS-TXPWR-MAX-CCH power value 7 (16 dBm) <000c> l1ctl.c:237 BCCH on TS0 (0821/13/02) -70 dBm 0/0: 59 06 1a 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 ff e5 04 00 <000c> l1ctl.c:237 PCH/AGCH on TS0 (0821/17/06) -70 dBm 0/0: 03 03 01 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b <0001> gsm48_rr.c:1587 RANDOM ACCESS (requests left 7) <0001> gsm48_rr.c:1643 RANDOM ACCESS (Tx-integer 12 combined no S(lots) 217 ra 0x0f) <0001> gsm48_rr.c:1680 Use MS-TXPWR-MAX-CCH power value 7 (16 dBm) <000c> l1ctl.c:237 PCH/AGCH on TS0 (0821/23/12) -70 dBm 0/0: 15 06 21 00 01 f0 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b <000c> l1ctl.c:237 PCH/AGCH on TS0 (0821/01/16) -70 dBm 0/0: 15 06 21 00 01 f0 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b <000c> l1ctl.c:237 PCH/AGCH on TS0 (0821/07/22) -70 dBm 0/0: 15 06 21 00 01 f0 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b <000c> l1ctl.c:237 PCH/AGCH on TS0 (0821/11/26) -70 dBm 0/0: 15 06 21 00 01 f0 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b <000c> l1ctl.c:237 PCH/AGCH on TS0 (0821/17/32) -70 dBm 0/0: 2d 06 3f 03 41 e3 67 0c a9 97 00 00 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b <0001> gsm48_rr.c:2439 IMMEDIATE ASSIGNMENT: <0001> gsm48_rr.c:2457 (ta 0/0m ra 0x0c chan_nr 0x41 ARFCN 871(DCS) TS 1 SS 0 TSC 7) <0001> gsm48_rr.c:2487 resetting scheduler <0001> gsm48_rr.c:3228 sending establish message <0001> gsm48_rr.c:231 Using and incrementing V(SD) = 0 (pdisc 5) <0001> gsm48_rr.c:2964 setting indicated TA 0 (actual TA 0) <0001> gsm48_rr.c:2979 using last BCCH timeout 32 <0001> gsm48_rr.c:825 stopping pending timer T_meas <0001> gsm48_rr.c:2860 MEAS REP: pwr=7 TA=0 meas-invalid=1 rxlev-full=-110 rxlev-sub=-110 rxqual-full=0 rxqual-sub=0 dtx 0 ba 0 no-ncell-n 7 <0001> gsm48_rr.c:2998 establishing channel in dedicated mode <0001> gsm48_rr.c:3000 Channel type 64, subch 0, ts 1, mode 0, audio-mode 5, cipher 1 <000c> l1ctl.c:237 PCH/AGCH on TS1 (0821/21/36) -70 dBm 0/0: 15 06 21 00 01 f0 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b <000c> l1ctl.c:237 SDCCH/8(0) on TS1 (0821/10/00) -70 dBm 0/0: 03 03 01 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b <000c> l1ctl.c:237 SDCCH/8(0) on TS1 (0821/16/32) -70 dBm 71/2: 23 4b a3 17 f1 f7 c7 24 fb 96 85 48 45 f8 e2 0c 32 f1 ac d8 7e 29 c5 <000c> l1ctl.c:300 Dropping frame with 71 bit errors <000c> l1ctl.c:237 SDCCH/8(0) on TS1 (0821/09/00) -70 dBm 73/2: 23 4b a3 17 f1 f7 37 63 19 5e c2 da 60 f7 e2 7e 9e cd ac d8 ee fc 2f <000c> l1ctl.c:300 Dropping frame with 73 bit errors <000c> l1ctl.c:237 SDCCH/8(0) on TS1 (0821/08/00) -70 dBm 69/2: 23 4b a3 17 f1 f7 47 63 3d 97 a1 c7 5d f9 e2 5e e7 b9 ac d8 b6 71 2e <000c> l1ctl.c:300 Dropping frame with 69 bit errors <000c> l1ctl.c:237 SDCCH/8(0) on TS1 (0821/14/32) -70 dBm 78/2: a3 6f da 0b 38 d4 6e aa 57 cc 2e 12 7e f8 e2 5e 87 f2 ac d8 ee dc bd <000c> l1ctl.c:300 Dropping frame with 78 bit errors <000c> l1ctl.c:237 SDCCH/8(0) on TS1 (0821/07/00) -70 dBm 71/2: a3 4b a3 17 f1 f7 37 63 19 5e a6 c7 79 f8 e2 5e 87 f2 ac d8 ee dc bd <000c> l1ctl.c:300 Dropping frame with 71 bit errors <0001> gsm48_rr.c:667 MON: f=871 lev=-70 snr=26 ber= 52 LAI=001 01 0001 ID=1b39 <0001> gsm48_rr.c:2860 MEAS REP: pwr=7 TA=0 meas-invalid=0 rxlev-full=-70 rxlev-sub=-70 rxqual-full=0 rxqual-sub=0 dtx 0 ba 0 no-ncell-n 7 <000c> l1ctl.c:237 SDCCH/8(0) on TS1 (0821/06/00) -70 dBm 71/2: a3 6f da 0b 38 d4 6e aa 17 de 17 00 67 f7 e2 ec 11 f1 ac d8 ee dc bd <000c> l1ctl.c:300 Dropping frame with 71 bit errors <000c> l1ctl.c:237 SDCCH/8(0) on TS1 (0821/12/32) -70 dBm 74/2: a3 6f 5a 2f f1 f7 5f b8 1e 5e a6 76 43 f8 22 ef ba 84 ac d8 ee dc c4 <000c> l1ctl.c:300 Dropping frame with 74 bit errors <000c> l1ctl.c:237 SDCCH/8(0) on TS1 (0821/05/00) -70 dBm 74/2: a3 6f da 0b 38 d4 4e 63 19 5e c2 da 60 f7 e2 5e 87 cc ac d8 7e a9 bd <000c> l1ctl.c:300 Dropping frame with 74 bit errors <000c> l1ctl.c:237 SDCCH/8(0) on TS1 (0821/04/00) -70 dBm 73/2: 23 4b a3 17 f1 f7 47 63 19 5e c2 da 60 f7 e2 5e 87 cc ac d8 7e b8 bd <000c> l1ctl.c:300 Dropping frame with 73 bit errors <000c> l1ctl.c:237 SDCCH/8(0) on TS1 (0821/10/32) -70 dBm 80/2: 87 4c a3 17 f1 f7 57 58 1f 5e e6 71 43 b0 54 42 bc cc ac d8 ee fc 2f <000c> l1ctl.c:300 Dropping frame with 80 bit errors <000c> l1ctl.c:237 SDCCH/8(0) on TS1 (0821/03/00) -70 dBm 71/2: 87 4c a3 17 f1 f7 37 63 19 5e c2 da 60 77 ff 45 bc 84 ac d8 ee dc bd <000c> l1ctl.c:300 Dropping frame with 71 bit errors <000c> l1ctl.c:237 SDCCH/8(0) on TS1 (0821/02/00) -70 dBm 72/2: 23 4b a3 17 f1 f7 c7 24 fb 96 85 48 45 f8 e2 7e 9e cd ac d8 ee dc bd <000c> l1ctl.c:300 Dropping frame with 72 bit errorsWe can see:
- BCCH and PCH/AGCH blocks always have 0/0 (num_biterr/fire_crc)
- we get a strange "PCH/AGCH on TS1" block while switching to dedicated mode
- the first SDCCH/8(0) block is received with 0/0
- all follow-up SDCCH/8(0) blocks both on SDCCH (/00) and on SACCH (/32) have massive num_biterr + fire_crc=2
on a commercial cell¶
<000c> l1ctl.c:237 BCCH on TS0 (0782/25/02) -91 dBm 0/0: 31 06 1c 62 f2 10 37 21 65 44 a4 00 00 43 2b 2b 2b 2b 2b 2b 2b 2b 2b <000c> l1ctl.c:237 PCH/AGCH on TS0 (0782/03/06) -91 dBm 0/0: 01 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b <000c> l1ctl.c:237 PCH/AGCH on TS0 (0782/09/12) -91 dBm 0/0: 15 06 21 00 01 f0 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b <000c> l1ctl.c:237 PCH/AGCH on TS0 (0782/13/16) -91 dBm 0/0: 15 06 21 00 01 f0 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b <000c> l1ctl.c:237 PCH/AGCH on TS0 (0782/19/22) -91 dBm 0/0: 15 06 21 00 01 f0 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b <000c> l1ctl.c:237 PCH/AGCH on TS0 (0782/23/26) -91 dBm 0/0: 2d 06 22 00 e3 cf 70 60 ef ce d0 d3 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b <0001> gsm48_rr.c:2214 PAGING ignored, we are not camping. <000c> l1ctl.c:237 PCH/AGCH on TS0 (0782/03/32) -91 dBm 0/0: 25 06 21 00 05 f4 de db 28 aa 23 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b <0001> gsm48_rr.c:2159 PAGING ignored, we are not camping. <000c> l1ctl.c:237 PCH/AGCH on TS0 (0782/07/36) -91 dBm 0/0: 55 06 22 00 f0 db 19 1d de df 99 a0 17 08 29 23 30 81 02 77 58 52 8b <0001> gsm48_rr.c:2214 PAGING ignored, we are not camping. <000c> l1ctl.c:237 PCH/AGCH on TS0 (0782/13/42) -91 dBm 0/0: 15 06 21 00 01 f0 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b <000c> l1ctl.c:237 PCH/AGCH on TS0 (0782/17/46) -91 dBm 0/0: 15 06 21 00 01 f0 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b <000c> l1ctl.c:237 BCCH on TS0 (0782/24/02) -91 dBm 0/0: 55 06 19 00 90 00 00 00 00 08 08 00 10 00 00 00 00 00 00 a4 00 00 2b <0001> sysinfo.c:615 Now updating previously received SYSTEM INFORMATION 4 <0001> gsm48_rr.c:1800 New SYSTEM INFORMATION 1 <0003> gsm322.c:2721 Received relevant sysinfo. <0003> gsm322.c:713 stopping pending CS timer. <0003> gsm322.c:2327 Scan frequency 120: Cell found. (rxlev <=-110 mcc 262 mnc 01 lac 3721) <0003> gsm322.c:1841 Select using access class <0003> gsm322.c:383 A (RLA_C (-110) - RXLEV_ACC_MIN (-106)) = -4 <0003> gsm322.c:385 B (MS_TXPWR_MAX_CCH (33) - p (33)) = 0 <0003> gsm322.c:387 C1 (A - MAX(B,0)) = -4 <0003> gsm322.c:1955 Cell ARFCN 120: Cell found, (rxlev=<=-110 mcc=262 mnc=01 lac=3721 Germany, T-Mobile) <0003> gsm322.c:1970 Cell ARFCN 120 selected. <0003> gsm322.c:2428 Tune to frequency 120. <0003> gsm322.c:470 Sync to ARFCN=120 rxlev=<=-110 (Sysinfo, ccch mode NON-COMB) <0003> gsm322.c:2455 Cell available. <0003> gsm322.c:4060 (ms 1) Event 'EVENT_CELL_FOUND' for Cell selection in state 'C2 stored cell selection' <000e> gsm322.c:3392 Camping normally on cell (ARFCN=120 mcc=262 mnc=01 Germany, T-Mobile) <0003> gsm322.c:833 new state 'C2 stored cell selection' -> 'C3 camped normally' <0005> gsm48_mm.c:4305 (ms 1) Received 'MM_EVENT_CELL_SELECTED' event in state MM IDLE, PLMN search <0005> gsm48_mm.c:904 new MM IDLE state PLMN search -> location updating needed <0005> gsm48_mm.c:904 new MM IDLE state location updating needed -> attempting to update <0005> gsm48_mm.c:424 starting T3212 (periodic loc. upd. delay) with 10800 seconds <0005> gsm48_mm.c:2289 Do normal Loc. upd. <000e> gsm48_mm.c:2204 Perform location update (MCC 262, MNC 01 LAC 0x3721) <0005> gsm48_mm.c:2340 LOCATION UPDATING REQUEST <0005> gsm48_mm.c:2360 using LAI (mcc 001 mnc 01 lac 0xfffe) <0005> gsm48_mm.c:2373 using IMSI 001010000000001 <0005> gsm48_mm.c:909 new state MM IDLE, attempting to update -> wait for RR connection (location updating) <0001> gsm48_rr.c:5462 (ms 1) Message 'RR_EST_REQ' received in state idle (sapi 0) <000e> gsm48_rr.c:1299 Establish radio link due to mobility management request <0003> gsm322.c:4060 (ms 1) Event 'EVENT_LEAVE_IDLE' for Cell selection in state 'C3 camped normally' <0003> gsm322.c:833 new state 'C3 camped normally' -> 'connected mode 1' <0003> gsm322.c:3677 Going to camping (normal) ARFCN 120. <0003> gsm322.c:456 Sync to ARFCN=120, but there is a sync already pending <0001> gsm48_rr.c:359 new state idle -> connection pending <0001> gsm48_rr.c:1446 CHANNEL REQUEST: 00 (Location Update with NECI) <0003> gsm322.c:2956 Channel synched. (ARFCN=120, snr=16, BSIC=10) <0001> gsm322.c:2979 using DSC of 90 <0001> gsm48_rr.c:667 MON: no cell info <000c> l1ctl.c:237 PCH/AGCH on TS0 (0782/16/46) -90 dBm 0/0: 49 06 22 00 c8 bd 18 93 d6 ae 29 23 17 05 f4 fd ca 08 ea 8a 2b 2b 2b <0003> gsm48_rr.c:4835 Channel provides data. <0001> gsm48_rr.c:1587 RANDOM ACCESS (requests left 5) <0001> gsm48_rr.c:1643 RANDOM ACCESS (Tx-integer 12 combined no S(lots) 0 ra 0x08) <0001> gsm48_rr.c:1680 Use MS-TXPWR-MAX-CCH power value 5 (33 dBm) <000c> l1ctl.c:237 BCCH on TS0 (0782/23/02) -90 dBm 0/0: 59 06 1a 0a 01 00 00 00 14 a0 83 01 84 00 00 00 00 00 00 8f a4 00 00 <0001> gsm48_rr.c:1587 RANDOM ACCESS (requests left 4) <0001> gsm48_rr.c:1643 RANDOM ACCESS (Tx-integer 12 combined no S(lots) 217 ra 0x01) <0001> gsm48_rr.c:1680 Use MS-TXPWR-MAX-CCH power value 5 (33 dBm) <000c> l1ctl.c:237 PCH/AGCH on TS0 (0782/01/06) -90 dBm 0/0: 01 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b <000c> l1ctl.c:237 PCH/AGCH on TS0 (0782/07/12) -90 dBm 0/0: 15 06 21 00 01 f0 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b <000c> l1ctl.c:237 PCH/AGCH on TS0 (0782/11/16) -90 dBm 0/0: 2d 06 3f 00 49 40 78 08 70 e2 01 00 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b <0001> gsm48_rr.c:2439 IMMEDIATE ASSIGNMENT: <0001> gsm48_rr.c:2457 (ta 1/553m ra 0x08 chan_nr 0x49 ARFCN 120 TS 1 SS 1 TSC 2) <0001> gsm48_rr.c:2487 resetting scheduler <0001> gsm48_rr.c:3228 sending establish message <0001> gsm48_rr.c:231 Using and incrementing V(SD) = 0 (pdisc 5) <0001> gsm48_rr.c:2964 setting indicated TA 1 (actual TA 1) <0001> gsm48_rr.c:2979 using last BCCH timeout 24 <0001> gsm48_rr.c:825 stopping pending timer T_meas <0001> gsm48_rr.c:2860 MEAS REP: pwr=5 TA=1 meas-invalid=1 rxlev-full=-110 rxlev-sub=-110 rxqual-full=0 rxqual-sub=0 dtx 0 ba 0 no-ncell-n 7 <0001> gsm48_rr.c:2998 establishing channel in dedicated mode <0001> gsm48_rr.c:3000 Channel type 64, subch 1, ts 1, mode 0, audio-mode 5, cipher 1 <000c> l1ctl.c:237 PCH/AGCH on TS1 (0782/17/22) -90 dBm 62/0: 25 06 21 00 05 f4 f4 af c2 da 23 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b <0001> gsm48_rr.c:2159 PAGING ignored, we are not camping. <000c> l1ctl.c:237 SDCCH/8(1) on TS1 (0782/24/04) -89 dBm 0/0: 03 03 01 2b 33 53 af ce 5e c3 09 f3 92 80 19 6d 18 ab ba 57 97 4c 4e <000c> l1ctl.c:237 SDCCH/8(1) on TS1 (0782/04/36) -90 dBm 0/0: 05 01 03 03 49 06 1d 0a 01 00 00 00 14 a0 83 01 84 00 00 00 00 00 00 <0015> lapdm.c:762 Received frame for unsupported SAPI 1! <000c> l1ctl.c:237 SDCCH/8(1) on TS1 (0782/23/04) -89 dBm 0/0: 01 73 49 05 08 70 00 f1 10 ff fe 30 08 09 10 10 00 00 00 00 10 2b 92 <000e> gsm48_rr.c:3356 Radio link is released <0001> gsm48_rr.c:779 starting T_rel_wait with 1.500 seconds <0001> gsm48_rr.c:359 new state connection pending -> release pending <0005> gsm48_mm.c:3902 (ms 1) Received 'RR_REL_IND' from RR in state wait for RR connection (location updating) (sapi 0) <0005> gsm48_mm.c:2739 RR link released after loc. upd. <000e> gsm48_mm.c:2683 Location update failed <0005> subscriber.c:1074 (ms 1) new state U2_NOT_UPDATED -> U2_NOT_UPDATED <000e> gsm48_mm.c:2722 Try location update later <0005> gsm48_mm.c:1086 Not camping, wait for CS process to camp, it sends us CELL_SELECTED then. <000c> l1ctl.c:237 SDCCH/8(1) on TS1 (0782/22/04) -90 dBm 0/0: 03 00 0d 05 04 0b 2b de 9d 98 69 aa ae ff 3c 40 11 f0 0c 44 05 f3 43 <0015> lapd_core.c:1498 (dl=0x62c000000bd8) I frame ignored in state LAPD_STATE_IDLE <000c> l1ctl.c:237 SDCCH/8(1) on TS1 (0782/02/36) -89 dBm 79/2: b1 14 86 36 ee 66 68 16 65 be 70 c0 0d 8a 96 d0 33 17 2c 70 08 5d 21 <000c> l1ctl.c:300 Dropping frame with 79 bit errors <000c> l1ctl.c:237 SDCCH/8(1) on TS1 (0782/21/04) -89 dBm 0/0: 03 03 01 2b 92 c7 2d 92 9d ad a9 bd be f1 b0 44 74 33 67 55 ea bf 0f <0001> gsm48_rr.c:667 MON: f=120 lev=-89 snr=57 ber= 20 LAI=262 01 3721 ID=21a2 <0001> gsm48_rr.c:2860 MEAS REP: pwr=5 TA=1 meas-invalid=0 rxlev-full=-89 rxlev-sub=-89 rxqual-full=0 rxqual-sub=0 dtx 0 ba 0 no-ncell-n 7 <000c> l1ctl.c:237 SDCCH/8(1) on TS1 (0782/20/04) -89 dBm 0/0: 03 10 0d 05 04 0b 2b de 9d 98 69 aa ae ff 3c 40 11 f0 0c 44 05 f3 43 <0015> lapd_core.c:1498 (dl=0x62c000000bd8) I frame ignored in state LAPD_STATE_IDLE <000c> l1ctl.c:237 SDCCH/8(1) on TS1 (0782/00/36) -89 dBm 82/2: f5 42 53 b8 04 77 e1 f5 bd 14 26 4e 45 a8 99 d0 c3 ff bd 6d 08 5d 21 <000c> l1ctl.c:300 Dropping frame with 82 bit errors <000c> l1ctl.c:237 SDCCH/8(1) on TS1 (0782/19/04) -90 dBm 0/0: 03 03 01 2b 41 f4 30 47 54 32 bf 55 b0 3f 34 10 17 4c 0e b5 c4 77 13 <000c> l1ctl.c:237 SDCCH/8(1) on TS1 (0782/18/04) -90 dBm 0/0: 03 10 0d 05 04 0b 2b de 9d 98 69 aa ae ff 3c 40 11 f0 0c 44 05 f3 43 <0015> lapd_core.c:1498 (dl=0x62c000000bd8) I frame ignored in state LAPD_STATE_IDLE <000c> l1ctl.c:237 SDCCH/8(1) on TS1 (0782/24/36) -89 dBm 85/2: 3d 31 6f 36 ee e6 54 1e bd 14 7f c0 29 95 4e f3 fa ed 64 db 14 86 02 <000c> l1ctl.c:300 Dropping frame with 85 bit errors <000c> l1ctl.c:237 SDCCH/8(1) on TS1 (0782/17/04) -90 dBm 0/0: 03 03 01 2b 0b 24 07 5b 42 bb 71 b3 64 75 eb 67 0f 6a 84 2f 23 5c 19
we can observe everything like in the above trace, but the num_biterr/fire_crc problems only on the SACCH (/36 here), and not on the main SDCCH (/04 here).
Updated by laforge over 3 years ago
re-tried with osmo-bts-trx - behavior is identical. no BER on SDCCH, and then significant number of bit errors on the dedicated channel
Updated by laforge over 3 years ago
- % Done changed from 0 to 40
So.... the problem is something else altogether, or at least a large part of the problem.
When testing RF related stuff, I typically never bother much about the CN. All I need is a working RAN with BTS + BSC, and the MS. After all, I don't care about what happens on L3 or higher.
For some reason, osmo-bsc these days immediately hard-releases the lchan if there is no MSC. There is no signalign sent back to the MS about this:- no spoofing of MM/CM (LU REJECT, CM SERV REJECT, ...) which is still understandable, as it's a layering violation and those messages normally originat e at the MSC
- No RR CHANNEL RELEASE is sent to the MS. That is a big fat bug.
Instead, we simply immedaitely close the lchan on the BTS side. This of course means that from that point onwards there re only bit-errors in downlink in the UE.
DRSL INFO <0003> ../../../git/src/osmo-bsc/abis_rsl.c:1453 (bts=0) CHAN RQD: reason: Location updating (ra=0x0f, neci=0x01, chreq_reason=0x03) DCHAN INFO <000f> ../../../git/src/osmo-bsc/lchan_select.c:247 lchan(0-0-0-CCCH_SDCCH4-0)[0x28a0d0]{UNUSED}: (type=SDCCH) Selected DCHAN DEBUG <000f> ../../../git/src/osmo-bsc/abis_rsl.c:1657 lchan(0-0-0-CCCH_SDCCH4-0)[0x28a0d0]{UNUSED}: (type=SDCCH) MS: Channel Request: reason=LOCATION_UPDATE ra=0x0f ta=0 DCHAN DEBUG <000f> ../../../git/src/osmo-bsc/lchan_fsm.c:329 lchan(0-0-0-CCCH_SDCCH4-0)[0x28a0d0]{UNUSED}: Received Event LCHAN_EV_ACTIVATE DCHAN DEBUG <000f> ../../../git/src/osmo-bsc/lchan_fsm.c:548 lchan(0-0-0-CCCH_SDCCH4-0)[0x28a0d0]{UNUSED}: state_chg to WAIT_TS_READY DCHAN DEBUG <000f> ../../../git/src/osmo-bsc/gsm_data.c:861 lchan(0-0-0-CCCH_SDCCH4-0)[0x28a0d0]{WAIT_TS_READY}: (type=SDCCH) MS Power level update requested: 15 dBm DCHAN DEBUG <000f> ../../../git/src/osmo-bsc/gsm_data.c:893 lchan(0-0-0-CCCH_SDCCH4-0)[0x28a0d0]{WAIT_TS_READY}: (type=SDCCH) MS Power level update (power class 0): 0 -> 7 DCHAN INFO <000f> ../../../git/src/osmo-bsc/lchan_fsm.c:626 lchan(0-0-0-CCCH_SDCCH4-0)[0x28a0d0]{WAIT_TS_READY}: (type=SDCCH) Activation requested: FOR_MS_CHANNEL_REQUEST voice=no MGW-ci=none type=SDCCH tch-mode=SIGNALLING encr-alg=A5/0 ck=none DCHAN DEBUG <000f> ../../../git/src/osmo-bsc/timeslot_fsm.c:106 lchan(0-0-0-CCCH_SDCCH4-0)[0x28a0d0]{WAIT_TS_READY}: Received Event LCHAN_EV_TS_READY DCHAN DEBUG <000f> ../../../git/src/osmo-bsc/lchan_fsm.c:644 lchan(0-0-0-CCCH_SDCCH4-0)[0x28a0d0]{WAIT_TS_READY}: state_chg to WAIT_ACTIV_ACK DRSL DEBUG <0003> ../../../git/src/osmo-bsc/abis_rsl.c:476 (bts=0,trx=0,ts=0,pchan=CCCH+SDCCH4,state=IN_USE) Tx RSL Channel Activate with act_type=INITIAL DCHAN DEBUG <000f> ../../../git/src/osmo-bsc/abis_rsl.c:1152 lchan(0-0-0-CCCH_SDCCH4-0)[0x28a0d0]{WAIT_ACTIV_ACK}: (type=SDCCH) Rx CHAN_ACTIV_ACK DCHAN DEBUG <000f> ../../../git/src/osmo-bsc/abis_rsl.c:1164 lchan(0-0-0-CCCH_SDCCH4-0)[0x28a0d0]{WAIT_ACTIV_ACK}: Received Event LCHAN_EV_RSL_CHAN_ACTIV_ACK DCHAN DEBUG <000f> ../../../git/src/osmo-bsc/lchan_fsm.c:772 lchan(0-0-0-CCCH_SDCCH4-0)[0x28a0d0]{WAIT_ACTIV_ACK}: (type=SDCCH) Tx RR Immediate Assignment DCHAN DEBUG <000f> ../../../git/src/osmo-bsc/lchan_fsm.c:822 lchan(0-0-0-CCCH_SDCCH4-0)[0x28a0d0]{WAIT_ACTIV_ACK}: state_chg to WAIT_RLL_RTP_ESTABLISH DCHAN DEBUG <000f> ../../../git/src/osmo-bsc/abis_rsl.c:1899 lchan(0-0-0-CCCH_SDCCH4-0)[0x28a0d0]{WAIT_RLL_RTP_ESTABLISH}: (type=SDCCH) SAPI=0 ESTABLISH INDICATION DCHAN DEBUG <000f> ../../../git/src/osmo-bsc/abis_rsl.c:1932 lchan(0-0-0-CCCH_SDCCH4-0)[0x28a0d0]{WAIT_RLL_RTP_ESTABLISH}: Received Event LCHAN_EV_RLL_ESTABLISH_IND DCHAN DEBUG <000f> ../../../git/src/osmo-bsc/lchan_fsm.c:850 lchan(0-0-0-CCCH_SDCCH4-0)[0x28a0d0]{WAIT_RLL_RTP_ESTABLISH}: state_chg to ESTABLISHED DRSL ERROR <0003> ../../../git/src/osmo-bsc/gsm_08_08.c:483 MM GSM48_MT_MM_LOC_UPD_REQUEST: IMSI-001010000000001: No suitable MSC for this Complete Layer 3 request found DRSL DEBUG <0003> ../../../git/src/osmo-bsc/abis_rsl.c:644 (bts=0,trx=0,ts=0,ss=0) DEACTivate SACCH CMD DCHAN DEBUG <000f> ../../../git/src/osmo-bsc/lchan_fsm.c:1595 lchan(0-0-0-CCCH_SDCCH4-0)[0x28a0d0]{ESTABLISHED}: state_chg to WAIT_RF_RELEASE_ACK DCHAN DEBUG <000f> ../../../git/src/osmo-bsc/bsc_subscr_conn_fsm.c:778 lchan(0-0-0-CCCH_SDCCH4-0)[0x28a0d0]{WAIT_RF_RELEASE_ACK}: conn SUBSCR_CONN(msc4294967295-conn4294967295_subscr-IMSI-001010000000001)[0x28adc0] detaches lchan (primary lchan) DMSC ERROR <0007> ../../../git/src/osmo-bsc/bsc_subscr_conn_fsm.c:153 SUBSCR_CONN(msc4294967295-conn4294967295_subscr-IMSI-001010000000001)[0x28adc0]{INIT}: Unable to deliver BSSMAP Clear Request message, no MSC for this conn DCHAN DEBUG <000f> ../../../git/src/osmo-bsc/lchan_fsm.c:1644 lchan(0-0-0-CCCH_SDCCH4-0)[0x28a0d0]{WAIT_RF_RELEASE_ACK}: lchan detaches from conn SUBSCR_CONN(msc4294967295-conn4294967295_subscr-IMSI-001010000000001)[0x28adc0] DLINP ERROR <0017> ../../git/src/input/ipaccess.c:412 Bad signalling message, sign_link returned error: No such file or directory. DCHAN DEBUG <000f> ../../../git/src/osmo-bsc/abis_rsl.c:1152 lchan(0-0-0-CCCH_SDCCH4-0)[0x28a0d0]{WAIT_RF_RELEASE_ACK}: (type=SDCCH) Rx RF_CHAN_REL_ACK DCHAN DEBUG <000f> ../../../git/src/osmo-bsc/abis_rsl.c:1184 lchan(0-0-0-CCCH_SDCCH4-0)[0x28a0d0]{WAIT_RF_RELEASE_ACK}: Received Event LCHAN_EV_RSL_RF_CHAN_REL_ACK DCHAN DEBUG <000f> ../../../git/src/osmo-bsc/lchan_fsm.c:1206 lchan(0-0-0-CCCH_SDCCH4-0)[0x28a0d0]{WAIT_RF_RELEASE_ACK}: state_chg to WAIT_AFTER_ERROR DLSS7 ERROR <0021> ../../git/src/m3ua.c:507 XUA_AS(as-clnt-A-0-m3ua)[0x253d70]{AS_DOWN}: Event AS-TRANSFER.req not permitted DCHAN DEBUG <000f> ../../git/src/fsm.c:322 lchan(0-0-0-CCCH_SDCCH4-0)[0x28a0d0]{WAIT_AFTER_ERROR}: Timeout of X3111 DCHAN DEBUG <000f> ../../../git/src/osmo-bsc/lchan_fsm.c:1550 lchan(0-0-0-CCCH_SDCCH4-0)[0x28a0d0]{WAIT_AFTER_ERROR}: state_chg to UNUSED DCHAN DEBUG <000f> ../../../git/src/osmo-bsc/lchan_fsm.c:382 lchan(0-0-0-CCCH_SDCCH4-0)[0x28a0d0]{UNUSED}: (type=SDCCH) Clearing lchan state
Now if I disable transmit in the UE (by disabling the PA), then of course the first uplink message is never sent, which means the BSC keeps the channel open, which means there are no bit errors. doh.
Updated by laforge over 3 years ago
- Related to Bug #4832: osmo-bsc hard-releases lchan if no MSC is found added