Project

General

Profile

Bug #4829

OsmocomBB Rx bit errors in dedicated mode

Added by laforge about 1 month ago. Updated about 1 month ago.

Status:
In Progress
Priority:
High
Assignee:
Category:
-
Target version:
-
Start date:
10/24/2020
Due date:
% Done:

40%

Resolution:
Spec Reference:

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.

sky77324.pdf View sky77324.pdf 3.75 MB PA data sheet laforge, 10/25/2020 08:28 AM
Sch_C118_A2_C_L3_1.0.pdf View Sch_C118_A2_C_L3_1.0.pdf 583 KB C118 schematics laforge, 10/25/2020 08:29 AM
SF_C118_A3_C_L3_1.2.pdf View SF_C118_A3_C_L3_1.2.pdf 593 KB C118 component placement (position of resistors) laforge, 10/25/2020 08:29 AM

Related issues

Related to OsmoBSC - Bug #4832: osmo-bsc hard-releases lchan if no MSC is foundFeedback10/25/2020

History

#1 Updated by laforge about 1 month ago

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:

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?

#2 Updated by laforge about 1 month 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 errors

We can see:
  1. BCCH and PCH/AGCH blocks always have 0/0 (num_biterr/fire_crc)
  2. we get a strange "PCH/AGCH on TS1" block while switching to dedicated mode
  3. the first SDCCH/8(0) block is received with 0/0
  4. 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).

#3 Updated by laforge about 1 month 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

#4 Updated by laforge about 1 month 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.

#5 Updated by laforge about 1 month ago

  • Related to Bug #4832: osmo-bsc hard-releases lchan if no MSC is found added

Also available in: Atom PDF

Add picture from clipboard (Maximum size: 48.8 MB)