openbts-p2.8-gprs-exp and pcu issues

Vladimir Rolbin vrolbin at gmail.com
Sun Oct 28 12:20:05 UTC 2012


Hi Andreas,

1. If I see well the pcu expects PCU_IF_MSG_DATA_CNF data starting from
plen..
   This error:

   <0002> gprs_rlcmac_data.cpp:1138 TX: Immediate Assignment Uplink (AGCH)
<0002> gprs_rlcmac_data.cpp:1876 Got IMM.ASS confirm, but rest octets do
not start with bit sequence 'HH01' (Packet Downlink Assignment)

is caused by openBTS's confirm from PCU_IF_SAPI_AGCH handler, the example
of the frame sent back to the pcu:

1351419034.590852 3048246128: [ PCU -> BTS ] AGCH: L2Length 11
primitive=UNIT_DATA raw=(063f100f400279cbe40000c8001d002b2b2b2b2b2b2b)
1351419034.590927 3048246128: [ BTS -> PCU ] PhPchCnf:
2d063f100f400279cbe40000c8001d002b2b2b2b2b2b2b
If decoded the rest octets realy do not start with expected bit sequence
(HH01) :
    [Protocols in frame: user_dlt:gsm_a_ccch]
DLT: 147, Payload: gsm_a_ccch (GSM CCCH)
GSM CCCH - Immediate Assignment
    L2 Pseudo Length
        0010 11.. = L2 Pseudo Length value: 11
    Protocol Discriminator: Radio Resources Management messages
        .... 0110 = Protocol discriminator: Radio Resources Management
messages (0x06)
        0000 .... = Skip Indicator: 0
    Message Type: Immediate Assignment
    Page Mode
        .... 0000 = Page Mode: Normal paging (0)
    Dedicated mode or TBF
        0001 .... = Dedicated mode or TBF: This message assigns an uplink
TBF or is the second message of two in a two-message assignment of an
uplink or downlink TBF (1)
    Packet Channel Description
        0000 1... = Spare bits (ignored by receiver)
        .... .111 = Timeslot: 7
        010. .... = Training Sequence: 2
        ...0 .... = Hopping channel: No
        .... 00.. = Spare
        Single channel : ARFCN 2
    Request Reference
        Random Access Information (RA): 121
        1100 1... = T1': 25
        .... .011 111. .... = T3: 31
        ...0 0100 = T2: 4
        [RFN: 33232]
    Timing Advance
        Timing advance value: 0
    Mobile Allocation
        Length: 0
    IA Rest Octets
        H... ....: First Discriminator Bit: High
        .H.. ....: Second Discriminator Bit: High
        ..0. ....: Discriminator Bit: Packet Assignment
        ...0 ....: Discriminator Bit: Packet Uplink Assignment
        Packet Uplink Assignment
            .... 1...: Packet Uplink Assignment: Normal
            .... .000  00.. .... = TFI_Assignment: 0
            ..0. .... = Polling: no action is required from MS
            ...0 ....: Allocation Type: Dynamic Allocation (mandatory after
Rel-4)
            .... 000. = USF: 0
            .... ...0 = USF_granularity: the mobile station shall transmit
one RLC/MAC block
            0... ....: P0: Not Present
            .00. .... = Channel_Coding_Command: CS-1 (0)
            ...1 .... = TLLI_Block_Channel_Coding: mobile station shall use
coding scheme as specified by the corresponding CHANNEL CODING COMMAND or
EGPRS CHANNEL CODING COMMAND field
            .... 1...: Alpha: Present
            .... .101  0... .... = Alpha: 1.0 (10)
            .000 00.. = Gamma: 0 dB (0)
            .... ..0.: Timing Advance Index: Not Present
            .... ...0: TBF Starting Time: Not Present
            L... ....: Additions in R99: Not Present
            .L.. ....: Additions in Rel-6: Not Present
        Padding Bits: default padding

2. To make things clearer I've added several additional prints:
diff -i -w ./osmo-pcu-jolly_git_11_10_12/src/gprs_rlcmac_data.cpp
./temp/osmo-pcu-jolly_git_20_08_12/src/gprs_rlcmac_data.cpp
283a284,290
>   else
>   {
>    LOGP(DRLCMAC, LOGL_NOTICE, "PACKET CONTROL ACK with "
>     "expected FN=%u TLL=0x%08x (TRX %d TS %d)\n",
>     fn, tlli, trx, ts);
>   }
>
472a480,483
>  case MT_PACKET_UPLINK_DUMMY_CONTROL_BLOCK: //vr, added
>   LOGP(DRLCMAC, LOGL_NOTICE, "RX: [PCU <- BTS] FIXME: Packet uplink dummy
control block\n");
>   break;
>
474c485
<   LOGP(DRLCMAC, LOGL_NOTICE, "RX: [PCU <- BTS] unknown control block
received\n");
---
>   LOGP(DRLCMAC, LOGL_NOTICE, "RX: [PCU <- BTS] unknown control block
received %d\n", ul_control_block->u.MESSAGE_TYPE);

and
diff -i -w ./osmo-pcu-jolly_git_11_10_12/src/gprs_rlcmac_sched.cpp
./temp/osmo-pcu-jolly_git_20_08_12/src/gprs_rlcmac_sched.cpp
255c255
<   LOGP(DRLCMACSCHED, LOGL_DEBUG, "Received RTS for PDCH: TRX=%d "
---
>   LOGP(DRLCMACSCHED, LOGL_INFO, "Received RTS for PDCH: TRX=%d "
Packet uplink dummy control block is sent by Nokia 5000d, possibly requires
handling..
So in the following example (the full pcu and bts log I'll put later):
<0006> gprs_rlcmac_sched.cpp:260 Received RTS for PDCH: TRX=0 TS=7
FN=2353693 block_nr=4 scheduling free USF for polling at FN=2353697 of DL
TFI=0
...
<0002> gprs_rlcmac_data.cpp:376 PACKET DOWNLINK ACK with unknown FN=2353693
TFI=0 (TRX 0 TS 7)
we have a clue that the ack was expected on FN=2353697 but received erlier
on  FN=2353693.
 I will add drlcmac debugging  to inverstigate it...

Regards,
Vladimir Rolbin

p.s.


<0008> gprs_bssgp_pcu.cpp:145 LLC [SGSN -> PCU] = TLLI: 0xec8157f3 IMSI:
452022112638582 len: 288

<0002> gprs_bssgp_pcu.cpp:149 TBF: APPEND TFI: 0 TLLI: 0xec8157f3

<0004> gprs_rlcmac_data.cpp:1453 Complete DL frame for TBF=0: len=416

<0004> gprs_rlcmac_data.cpp:1461 - Dequeue next LLC for TBF=0 (len=506)

<0006> gprs_rlcmac_sched.cpp:260 Received RTS for PDCH: TRX=0 TS=7
FN=2353515 block_nr=11 scheduling free USF for polling at FN=2353520 of DL
TFI=0

<0006> gprs_rlcmac_sched.cpp:260 Received RTS for PDCH: TRX=0 TS=7
FN=2353602 block_nr=7 scheduling free USF for polling at FN=2353606 of DL
TFI=0

<0004> gprs_rlcmac_data.cpp:1453 Complete DL frame for TBF=0: len=506

<0004> gprs_rlcmac_data.cpp:1461 - Dequeue next LLC for TBF=0 (len=506)

<0002> gprs_rlcmac.cpp:354 Allocating UL TBF: TFI=0 TRX=0 MS_CLASS=10

<0002> gprs_rlcmac.cpp:948 - Setting Control TS 7

<0002> gprs_rlcmac_data.cpp:1069 TBF: START TFI: 0 TLLI: 0xec8157f3 Packet
Uplink Assignment (PACCH)

<0006> gprs_rlcmac_sched.cpp:260 Received RTS for PDCH: TRX=0 TS=7
FN=2353628 block_nr=1 scheduling free USF for polling at FN=2353632 of DL
TFI=0

<0002> gprs_rlcmac_data.cpp:288 PACKET CONTROL ACK with expected FN=2353632
TLL=0xec8157f3 (TRX 0 TS 7)

<0005> gprs_rlcmac_data.cpp:740 Complete UL frame for TBF=0: len=75

<0008> gprs_rlcmac.cpp:1760 LLC [PCU -> SGSN] TFI: 0 TLLI: 0xec8157f3 len=75

<0005> gprs_rlcmac_data.cpp:740 Complete UL frame for TBF=0: len=62

<0008> gprs_rlcmac.cpp:1760 LLC [PCU -> SGSN] TFI: 0 TLLI: 0xec8157f3 len=62

<0008> gprs_bssgp_pcu.cpp:145 LLC [SGSN -> PCU] = TLLI: 0xec8157f3 IMSI:
452022112638582 len: 233

<0002> gprs_bssgp_pcu.cpp:149 TBF: APPEND TFI: 0 TLLI: 0xec8157f3

<0006> gprs_rlcmac_sched.cpp:260 Received RTS for PDCH: TRX=0 TS=7
FN=2353693 block_nr=4 scheduling free USF for polling at FN=2353697 of DL
TFI=0

<0006> gprs_rlcmac_sched.cpp:260 Received RTS for PDCH: TRX=0 TS=7
FN=2353702 block_nr=6 scheduling free USF for polling at FN=2353706 of UL
TFI=0

<0002> gprs_rlcmac_data.cpp:376 PACKET DOWNLINK ACK with unknown FN=2353693
TFI=0 (TRX 0 TS 7)

<0002> gprs_rlcmac_data.cpp:288 PACKET CONTROL ACK with expected FN=2353706
TLL=0xec8157f3 (TRX 0 TS 7)

<0002> gprs_rlcmac.cpp:895 Free UL TBF=0 with TLLI=0xec8157f3.

<0002> gprs_rlcmac_data.cpp:100 Poll timeout for DL TBF=0

<0002> gprs_rlcmac_data.cpp:180 - Timeout for polling PACKET DOWNLINK ACK.

<0002> gprs_rlcmac_data.cpp:82 - Assignment was on CCCH

<0002> gprs_rlcmac_data.cpp:90 - Downlink ACK was received

<0004> gprs_rlcmac_data.cpp:1453 Complete DL frame for TBF=0: len=506

<0004> gprs_rlcmac_data.cpp:1461 - Dequeue next LLC for TBF=0 (len=288)

<0006> gprs_rlcmac_sched.cpp:260 Received RTS for PDCH: TRX=0 TS=7
FN=2353784 block_nr=1 scheduling free USF for polling at FN=2353788 of DL
TFI=0

<0004> gprs_rlcmac_data.cpp:1453 Complete DL frame for TBF=0: len=288

<0004> gprs_rlcmac_data.cpp:1461 - Dequeue next LLC for TBF=0 (len=233)

<0002> gprs_rlcmac_data.cpp:388 Recovered downlink ack for DL TBF=0

<0004> gprs_rlcmac_data.cpp:1453 Complete DL frame for TBF=0: len=233

<0006> gprs_rlcmac_sched.cpp:260 Received RTS for PDCH: TRX=0 TS=7
FN=2353853 block_nr=5 scheduling free USF for polling at FN=2353858 of DL
TFI=0

<0001> pcu_l1_if.cpp:256 RACH request received: sapi=1 qta=0, ra=114,
fn=2354039

<0002> gprs_rlcmac_data.cpp:1138 TX: Immediate Assignment Uplink (AGCH)

<0002> gprs_rlcmac_data.cpp:1876 Got IMM.ASS confirm, but rest octets do
not start with bit sequence 'HH01' (Packet Downlink Assignment)

<0002> gprs_rlcmac.cpp:895 Free DL TBF=0 with TLLI=0xec8157f3.

<0002> gprs_rlcmac.cpp:354 Allocating UL TBF: TFI=0 TRX=0 MS_CLASS=10

<0002> gprs_rlcmac.cpp:948 - Setting Control TS 7

<0002> gprs_rlcmac_data.cpp:1069 TBF: START TFI: 0 TLLI: 0xec8157f3 Packet
Uplink Assignment (PACCH)

<0006> gprs_rlcmac_sched.cpp:260 Received RTS for PDCH: TRX=0 TS=7
FN=2354126 block_nr=8 scheduling free USF for polling at FN=2354131 of UL
TFI=0

<0002> gprs_rlcmac_data.cpp:288 PACKET CONTROL ACK with expected FN=2354131
TLL=0xec8157f3 (TRX 0 TS 7)

<0005> gprs_rlcmac_data.cpp:740 Complete UL frame for TBF=0: len=70

<0008> gprs_rlcmac.cpp:1760 LLC [PCU -> SGSN] TFI: 0 TLLI: 0xec8157f3 len=70

<0005> gprs_rlcmac_data.cpp:740 Complete UL frame for TBF=0: len=62

<0008> gprs_rlcmac.cpp:1760 LLC [PCU -> SGSN] TFI: 0 TLLI: 0xec8157f3 len=62

<0006> gprs_rlcmac_sched.cpp:260 Received RTS for PDCH: TRX=0 TS=7
FN=2354204 block_nr=2 scheduling free USF for polling at FN=2354209 of UL
TFI=0

<0002> gprs_rlcmac_data.cpp:288 PACKET CONTROL ACK with expected FN=2354209
TLL=0xec8157f3 (TRX 0 TS 7)

<0002> gprs_rlcmac.cpp:895 Free UL TBF=0 with TLLI=0xec8157f3.

<0008> gprs_bssgp_pcu.cpp:145 LLC [SGSN -> PCU] = TLLI: 0xec8157f3 IMSI:
452022112638582 len: 70

<0002> gprs_rlcmac.cpp:354 Allocating DL TBF: TFI=0 TRX=0 MS_CLASS=10

<0002> gprs_rlcmac.cpp:948 - Setting Control TS 7

<0002> gprs_rlcmac_data.cpp:1801 TX: START TFI: 0 TLLI: 0xec8157f3
Immediate Assignment Downlink (PCH)

<0004> gprs_rlcmac_data.cpp:1453 Complete DL frame for TBF=0: len=70

<0006> gprs_rlcmac_sched.cpp:260 Received RTS for PDCH: TRX=0 TS=7
FN=2354295 block_nr=11 scheduling free USF for polling at FN=2354300 of DL
TFI=0

<0008> gprs_bssgp_pcu.cpp:145 LLC [SGSN -> PCU] = TLLI: 0xec8157f3 IMSI:
452022112638582 len: 70

<0002> gprs_bssgp_pcu.cpp:149 TBF: APPEND TFI: 0 TLLI: 0xec8157f3

<0002> gprs_rlcmac_data.cpp:1764 TBF: START TFI: 0 TLLI: 0xec8157f3 Packet
Downlink Assignment (PACCH)

<0006> gprs_rlcmac_sched.cpp:260 Received RTS for PDCH: TRX=0 TS=7
FN=2354477 block_nr=5 scheduling free USF for polling at FN=2354482 of DL
TFI=0

<0001> pcu_l1_if.cpp:256 RACH request received: sapi=1 qta=0, ra=118,
fn=2354491

<0002> gprs_rlcmac_data.cpp:1138 TX: Immediate Assignment Uplink (AGCH)

<0002> gprs_rlcmac_data.cpp:1876 Got IMM.ASS confirm, but rest octets do
not start with bit sequence 'HH01' (Packet Downlink Assignment)

<0002> gprs_rlcmac_data.cpp:100 Poll timeout for DL TBF=0

<0002> gprs_rlcmac_data.cpp:158 - Timeout for polling PACKET CONTROL ACK
for PACKET DOWNLINK ASSIGNMENT.

<0002> gprs_rlcmac_data.cpp:84 - Assignment was on PACCH

<0002> gprs_rlcmac_data.cpp:92 - No downlink ACK received yet

<0002> gprs_rlcmac_data.cpp:1764 TBF: START TFI: 0 TLLI: 0xec8157f3 Packet
Downlink Assignment (PACCH)

<0006> gprs_rlcmac_sched.cpp:260 Received RTS for PDCH: TRX=0 TS=7
FN=2354529 block_nr=5 scheduling free USF for polling at FN=2354534 of DL
TFI=0

<0005> gprs_rlcmac_data.cpp:437 Got RACH from TLLI=0xec8157f3 while DL
TBF=0 still exists. Killing pending DL TBF

<0002> gprs_rlcmac.cpp:895 Free DL TBF=0 with TLLI=0xec8157f3.

<0002> gprs_rlcmac.cpp:905 Software error: Pending downlink assignment.
This may not happen, because the assignment message never gets transmitted.
Please be shure not to free in this state. PLEASE FIX!

<0002> gprs_rlcmac.cpp:354 Allocating UL TBF: TFI=0 TRX=0 MS_CLASS=10

<0002> gprs_rlcmac.cpp:948 - Setting Control TS 7

<0002> gprs_rlcmac_data.cpp:1069 TBF: START TFI: 0 TLLI: 0xec8157f3 Packet
Uplink Assignment (PACCH)

<0006> gprs_rlcmac_sched.cpp:260 Received RTS for PDCH: TRX=0 TS=7
FN=2354577 block_nr=4 scheduling free USF for polling at FN=2354581 of UL
TFI=0

<0002> gprs_rlcmac_data.cpp:288 PACKET CONTROL ACK with expected FN=2354581
TLL=0xec8157f3 (TRX 0 TS 7)

<0005> gprs_rlcmac_data.cpp:740 Complete UL frame for TBF=0: len=62

<0008> gprs_rlcmac.cpp:1760 LLC [PCU -> SGSN] TFI: 0 TLLI: 0xec8157f3 len=62

<0005> gprs_rlcmac_data.cpp:740 Complete UL frame for TBF=0: len=506

<0008> gprs_rlcmac.cpp:1760 LLC [PCU -> SGSN] TFI: 0 TLLI: 0xec8157f3
len=506

<0005> gprs_rlcmac_data.cpp:740 Complete UL frame for TBF=0: len=184

<0008> gprs_rlcmac.cpp:1760 LLC [PCU -> SGSN] TFI: 0 TLLI: 0xec8157f3
len=184

<0006> gprs_rlcmac_sched.cpp:260 Received RTS for PDCH: TRX=0 TS=7
FN=2354789 block_nr=5 scheduling free USF for polling at FN=2354794 of UL
TFI=0

<0008> gprs_bssgp_pcu.cpp:145 LLC [SGSN -> PCU] = TLLI: 0xec8157f3 IMSI:
452022112638582 len: 62

<0002> gprs_rlcmac.cpp:354 Allocating DL TBF: TFI=0 TRX=0 MS_CLASS=10

<0002> gprs_rlcmac.cpp:948 - Setting Control TS 7

<0002> gprs_rlcmac_data.cpp:1801 TX: START TFI: 0 TLLI: 0xec8157f3
Immediate Assignment Downlink (PCH)

<0008> gprs_bssgp_pcu.cpp:145 LLC [SGSN -> PCU] = TLLI: 0xec8157f3 IMSI:
452022112638582 len: 506

<0002> gprs_bssgp_pcu.cpp:149 TBF: APPEND TFI: 0 TLLI: 0xec8157f3

<0008> gprs_bssgp_pcu.cpp:145 LLC [SGSN -> PCU] = TLLI: 0xec8157f3 IMSI:
452022112638582 len: 468

<0002> gprs_bssgp_pcu.cpp:149 TBF: APPEND TFI: 0 TLLI: 0xec8157f3

<0002> gprs_rlcmac_data.cpp:288 PACKET CONTROL ACK with expected FN=2354794
TLL=0xec8157f3 (TRX 0 TS 7)

<0002> gprs_rlcmac.cpp:895 Free UL TBF=0 with TLLI=0xec8157f3.

<0004> gprs_rlcmac_data.cpp:1453 Complete DL frame for TBF=0: len=62

<0004> gprs_rlcmac_data.cpp:1461 - Dequeue next LLC for TBF=0 (len=506)

<0006> gprs_rlcmac_sched.cpp:260 Received RTS for PDCH: TRX=0 TS=7
FN=2354941 block_nr=4 scheduling free USF for polling at FN=2354945 of DL
TFI=0

<0002> gprs_rlcmac_data.cpp:376 PACKET DOWNLINK ACK with unknown FN=2354941
TFI=0 (TRX 0 TS 7)

<0004> gprs_rlcmac_data.cpp:1453 Complete DL frame for TBF=0: len=506

<0004> gprs_rlcmac_data.cpp:1461 - Dequeue next LLC for TBF=0 (len=468)

<0002> gprs_rlcmac_data.cpp:100 Poll timeout for DL TBF=0

<0002> gprs_rlcmac_data.cpp:180 - Timeout for polling PACKET DOWNLINK ACK.

<0002> gprs_rlcmac_data.cpp:82 - Assignment was on CCCH

<0002> gprs_rlcmac_data.cpp:92 - No downlink ACK received yet

<0002> gprs_rlcmac_data.cpp:1801 TX: START TFI: 0 TLLI: 0xec8157f3
Immediate Assignment Downlink (PCH)

<0002> gprs_rlcmac_data.cpp:529 Continue flow after IMM.ASS confirm

<0006> gprs_rlcmac_sched.cpp:260 Received RTS for PDCH: TRX=0 TS=7
FN=2355106 block_nr=6 scheduling free USF for polling at FN=2355110 of DL
TFI=0

<0004> gprs_rlcmac_data.cpp:1453 Complete DL frame for TBF=0: len=468

<0002> gprs_rlcmac_data.cpp:388 Recovered downlink ack for DL TBF=0

<0006> gprs_rlcmac_sched.cpp:260 Received RTS for PDCH: TRX=0 TS=7
FN=2355197 block_nr=3 scheduling free USF for polling at FN=2355201 of DL
TFI=0

<0001> pcu_l1_if.cpp:256 RACH request received: sapi=1 qta=0, ra=113,
fn=2355401

<0002> gprs_rlcmac_data.cpp:1138 TX: Immediate Assignment Uplink (AGCH)

<0002> gprs_rlcmac_data.cpp:1876 Got IMM.ASS confirm, but rest octets do
not start with bit sequence 'HH01' (Packet Downlink Assignment)

<0002> gprs_rlcmac.cpp:895 Free DL TBF=0 with TLLI=0xec8157f3.

<0002> gprs_rlcmac.cpp:354 Allocating UL TBF: TFI=0 TRX=0 MS_CLASS=10

<0002> gprs_rlcmac.cpp:948 - Setting Control TS 7

<0002> gprs_rlcmac_data.cpp:1069 TBF: START TFI: 0 TLLI: 0xec8157f3 Packet
Uplink Assignment (PACCH)

<0006> gprs_rlcmac_sched.cpp:260 Received RTS for PDCH: TRX=0 TS=7
FN=2355487 block_nr=10 scheduling free USF for polling at FN=2355491 of UL
TFI=0

<0002> gprs_rlcmac_data.cpp:288 PACKET CONTROL ACK with expected FN=2355491
TLL=0xec8157f3 (TRX 0 TS 7)

<0005> gprs_rlcmac_data.cpp:740 Complete UL frame for TBF=0: len=62

<0008> gprs_rlcmac.cpp:1760 LLC [PCU -> SGSN] TFI: 0 TLLI: 0xec8157f3 len=62

<0006> gprs_rlcmac_sched.cpp:260 Received RTS for PDCH: TRX=0 TS=7
FN=2355552 block_nr=1 scheduling free USF for polling at FN=2355556 of UL
TFI=0

<0002> gprs_rlcmac_data.cpp:288 PACKET CONTROL ACK with expected FN=2355556
TLL=0xec8157f3 (TRX 0 TS 7)

<0002> gprs_rlcmac.cpp:895 Free UL TBF=0 with TLLI=0xec8157f3.

<0001> pcu_l1_if.cpp:256 RACH request received: sapi=1 qta=0, ra=117,
fn=2357508

<0002> gprs_rlcmac_data.cpp:1138 TX: Immediate Assignment Uplink (AGCH)

<0002> gprs_rlcmac_data.cpp:1876 Got IMM.ASS confirm, but rest octets do
not start with bit sequence 'HH01' (Packet Downlink Assignment)

<0002> gprs_rlcmac.cpp:354 Allocating UL TBF: TFI=0 TRX=0 MS_CLASS=10

<0002> gprs_rlcmac.cpp:948 - Setting Control TS 7

<0002> gprs_rlcmac_data.cpp:1069 TBF: START TFI: 0 TLLI: 0xec8157f3 Packet
Uplink Assignment (PACCH)

<0006> gprs_rlcmac_sched.cpp:260 Received RTS for PDCH: TRX=0 TS=7
FN=2357593 block_nr=4 scheduling free USF for polling at FN=2357597 of UL
TFI=0

<0002> gprs_rlcmac_data.cpp:288 PACKET CONTROL ACK with expected FN=2357597
TLL=0xec8157f3 (TRX 0 TS 7)

<0005> gprs_rlcmac_data.cpp:740 Complete UL frame for TBF=0: len=70

<0008> gprs_rlcmac.cpp:1760 LLC [PCU -> SGSN] TFI: 0 TLLI: 0xec8157f3 len=70

<0008> gprs_bssgp_pcu.cpp:145 LLC [SGSN -> PCU] = TLLI: 0xec8157f3 IMSI:
452022112638582 len: 86

<0002> gprs_rlcmac.cpp:354 Allocating DL TBF: TFI=0 TRX=0 MS_CLASS=10

<0002> gprs_rlcmac.cpp:948 - Setting Control TS 7

<0002> gprs_rlcmac_data.cpp:1764 TBF: START TFI: 0 TLLI: 0xec8157f3 Packet
Downlink Assignment (PACCH)

<0006> gprs_rlcmac_sched.cpp:260 Received RTS for PDCH: TRX=0 TS=7
FN=2357654 block_nr=6 scheduling free USF for polling at FN=2357658 of UL
TFI=0

<0002> gprs_rlcmac_data.cpp:288 PACKET CONTROL ACK with expected FN=2357658
TLL=0xec8157f3 (TRX 0 TS 7)

<0006> gprs_rlcmac_sched.cpp:260 Received RTS for PDCH: TRX=0 TS=7
FN=2357684 block_nr=1 scheduling free USF for polling at FN=2357688 of UL
TFI=0

<0004> gprs_rlcmac_data.cpp:1453 Complete DL frame for TBF=0: len=86

<0002> gprs_rlcmac_data.cpp:288 PACKET CONTROL ACK with expected FN=2357688
TLL=0xec8157f3 (TRX 0 TS 7)

<0002> gprs_rlcmac.cpp:895 Free UL TBF=0 with TLLI=0xec8157f3.

<0006> gprs_rlcmac_sched.cpp:260 Received RTS for PDCH: TRX=0 TS=7
FN=2357706 block_nr=6 scheduling free USF for polling at FN=2357710 of DL
TFI=0

<0001> pcu_l1_if.cpp:256 RACH request received: sapi=1 qta=0, ra=117,
fn=2357860

<0002> gprs_rlcmac_data.cpp:1138 TX: Immediate Assignment Uplink (AGCH)

<0002> gprs_rlcmac_data.cpp:1876 Got IMM.ASS confirm, but rest octets do
not start with bit sequence 'HH01' (Packet Downlink Assignment)

<0005> gprs_rlcmac_data.cpp:437 Got RACH from TLLI=0xec8157f3 while DL
TBF=0 still exists. Killing pending DL TBF

<0002> gprs_rlcmac.cpp:895 Free DL TBF=0 with TLLI=0xec8157f3.

<0002> gprs_rlcmac.cpp:354 Allocating UL TBF: TFI=0 TRX=0 MS_CLASS=10

<0002> gprs_rlcmac.cpp:948 - Setting Control TS 7

<0002> gprs_rlcmac_data.cpp:1069 TBF: START TFI: 0 TLLI: 0xec8157f3 Packet
Uplink Assignment (PACCH)

<0006> gprs_rlcmac_sched.cpp:260 Received RTS for PDCH: TRX=0 TS=7
FN=2357944 block_nr=1 scheduling free USF for polling at FN=2357948 of UL
TFI=0

<0002> gprs_rlcmac_data.cpp:288 PACKET CONTROL ACK with expected FN=2357948
TLL=0xec8157f3 (TRX 0 TS 7)

<0005> gprs_rlcmac_data.cpp:740 Complete UL frame for TBF=0: len=506

<0008> gprs_rlcmac.cpp:1760 LLC [PCU -> SGSN] TFI: 0 TLLI: 0xec8157f3
len=506

<0005> gprs_rlcmac_data.cpp:740 Complete UL frame for TBF=0: len=327

<0008> gprs_rlcmac.cpp:1760 LLC [PCU -> SGSN] TFI: 0 TLLI: 0xec8157f3
len=327

<0006> gprs_rlcmac_sched.cpp:260 Received RTS for PDCH: TRX=0 TS=7
FN=2358174 block_nr=6 scheduling free USF for polling at FN=2358178 of UL
TFI=0

<0002> gprs_rlcmac_data.cpp:288 PACKET CONTROL ACK with expected FN=2358178
TLL=0xec8157f3 (TRX 0 TS 7)

<0002> gprs_rlcmac.cpp:895 Free UL TBF=0 with TLLI=0xec8157f3.

<0008> gprs_bssgp_pcu.cpp:145 LLC [SGSN -> PCU] = TLLI: 0xec8157f3 IMSI:
452022112638582 len: 62

<0002> gprs_rlcmac.cpp:354 Allocating DL TBF: TFI=0 TRX=0 MS_CLASS=10

<0002> gprs_rlcmac.cpp:948 - Setting Control TS 7

<0002> gprs_rlcmac_data.cpp:1801 TX: START TFI: 0 TLLI: 0xec8157f3
Immediate Assignment Downlink (PCH)

<0008> gprs_bssgp_pcu.cpp:145 LLC [SGSN -> PCU] = TLLI: 0xec8157f3 IMSI:
452022112638582 len: 506

<0002> gprs_bssgp_pcu.cpp:149 TBF: APPEND TFI: 0 TLLI: 0xec8157f3

<0008> gprs_bssgp_pcu.cpp:145 LLC [SGSN -> PCU] = TLLI: 0xec8157f3 IMSI:
452022112638582 len: 164

<0002> gprs_bssgp_pcu.cpp:149 TBF: APPEND TFI: 0 TLLI: 0xec8157f3

<0004> gprs_rlcmac_data.cpp:1453 Complete DL frame for TBF=0: len=62

<0004> gprs_rlcmac_data.cpp:1461 - Dequeue next LLC for TBF=0 (len=506)

<0006> gprs_rlcmac_sched.cpp:260 Received RTS for PDCH: TRX=0 TS=7
FN=2358347 block_nr=10 scheduling free USF for polling at FN=2358351 of DL
TFI=0

<0002> gprs_rlcmac_data.cpp:376 PACKET DOWNLINK ACK with unknown FN=2358347
TFI=0 (TRX 0 TS 7)

<0004> gprs_rlcmac_data.cpp:1453 Complete DL frame for TBF=0: len=506

<0004> gprs_rlcmac_data.cpp:1461 - Dequeue next LLC for TBF=0 (len=164)

<0004> gprs_rlcmac_data.cpp:1453 Complete DL frame for TBF=0: len=164

<0002> gprs_rlcmac_data.cpp:100 Poll timeout for DL TBF=0

<0002> gprs_rlcmac_data.cpp:180 - Timeout for polling PACKET DOWNLINK ACK.

<0002> gprs_rlcmac_data.cpp:82 - Assignment was on CCCH

<0002> gprs_rlcmac_data.cpp:92 - No downlink ACK received yet

<0002> gprs_rlcmac_data.cpp:1801 TX: START TFI: 0 TLLI: 0xec8157f3
Immediate Assignment Downlink (PCH)

<0002> gprs_rlcmac_data.cpp:529 Continue flow after IMM.ASS confirm

<0006> gprs_rlcmac_sched.cpp:260 Received RTS for PDCH: TRX=0 TS=7
FN=2358568 block_nr=1 scheduling free USF for polling at FN=2358572 of DL
TFI=0

<0002> gprs_rlcmac_data.cpp:388 Recovered downlink ack for DL TBF=0

<0004> gprs_rlcmac_data.cpp:1660 Received acknowledge of all blocks, but
without final ack inidcation (don't worry)

<0002> gprs_rlcmac.cpp:354 Allocating UL TBF: TFI=0 TRX=0 MS_CLASS=10

<0002> gprs_rlcmac.cpp:948 - Setting Control TS 7

<0002> gprs_rlcmac_data.cpp:1069 TBF: START TFI: 0 TLLI: 0xec8157f3 Packet
Uplink Assignment (PACCH)

<0006> gprs_rlcmac_sched.cpp:260 Received RTS for PDCH: TRX=0 TS=7
FN=2358598 block_nr=8 scheduling free USF for polling at FN=2358603 of DL
TFI=0

<0002> gprs_rlcmac_data.cpp:288 PACKET CONTROL ACK with expected FN=2358603
TLL=0xec8157f3 (TRX 0 TS 7)

<0005> gprs_rlcmac_data.cpp:740 Complete UL frame for TBF=0: len=62

<0008> gprs_rlcmac.cpp:1760 LLC [PCU -> SGSN] TFI: 0 TLLI: 0xec8157f3 len=62

<0006> gprs_rlcmac_sched.cpp:260 Received RTS for PDCH: TRX=0 TS=7
FN=2358659 block_nr=10 scheduling free USF for polling at FN=2358663 of DL
TFI=0

<0006> gprs_rlcmac_sched.cpp:260 Received RTS for PDCH: TRX=0 TS=7
FN=2358663 block_nr=11 scheduling free USF for polling at FN=2358668 of UL
TFI=0

<0002> gprs_rlcmac_data.cpp:376 PACKET DOWNLINK ACK with unknown FN=2358659
TFI=0 (TRX 0 TS 7)

<0002> gprs_rlcmac_data.cpp:288 PACKET CONTROL ACK with expected FN=2358668
TLL=0xec8157f3 (TRX 0 TS 7)

<0002> gprs_rlcmac.cpp:895 Free UL TBF=0 with TLLI=0xec8157f3.

<0002> gprs_rlcmac_data.cpp:100 Poll timeout for DL TBF=0

<0002> gprs_rlcmac_data.cpp:180 - Timeout for polling PACKET DOWNLINK ACK.

<0002> gprs_rlcmac_data.cpp:82 - Assignment was on CCCH

<0002> gprs_rlcmac_data.cpp:90 - Downlink ACK was received

<0006> gprs_rlcmac_sched.cpp:260 Received RTS for PDCH: TRX=0 TS=7
FN=2358750 block_nr=7 scheduling free USF for polling at FN=2358754 of DL
TFI=0

<0002> gprs_rlcmac_data.cpp:388 Recovered downlink ack for DL TBF=0

<0002> gprs_rlcmac.cpp:895 Free DL TBF=0 with TLLI=0xec8157f3.

<0001> pcu_l1_if.cpp:256 RACH request received: sapi=1 qta=0, ra=116,
fn=2369528

<0002> gprs_rlcmac_data.cpp:1138 TX: Immediate Assignment Uplink (AGCH)

<0002> gprs_rlcmac_data.cpp:1876 Got IMM.ASS confirm, but rest octets do
not start with bit sequence 'HH01' (Packet Downlink Assignment)

<0002> gprs_rlcmac.cpp:354 Allocating UL TBF: TFI=0 TRX=0 MS_CLASS=10

<0002> gprs_rlcmac.cpp:948 - Setting Control TS 7

<0002> gprs_rlcmac_data.cpp:1069 TBF: START TFI: 0 TLLI: 0xec8157f3 Packet
Uplink Assignment (PACCH)

<0006> gprs_rlcmac_sched.cpp:260 Received RTS for PDCH: TRX=0 TS=7
FN=2369614 block_nr=6 scheduling free USF for polling at FN=2369618 of UL
TFI=0

<0002> gprs_rlcmac_data.cpp:288 PACKET CONTROL ACK with expected FN=2369618
TLL=0xec8157f3 (TRX 0 TS 7)

<0005> gprs_rlcmac_data.cpp:740 Complete UL frame for TBF=0: len=62

<0008> gprs_rlcmac.cpp:1760 LLC [PCU -> SGSN] TFI: 0 TLLI: 0xec8157f3 len=62

<0006> gprs_rlcmac_sched.cpp:260 Received RTS for PDCH: TRX=0 TS=7
FN=2369679 block_nr=9 scheduling free USF for polling at FN=2369683 of UL
TFI=0

<0002> gprs_rlcmac_data.cpp:288 PACKET CONTROL ACK with expected FN=2369683
TLL=0xec8157f3 (TRX 0 TS 7)

<0002> gprs_rlcmac.cpp:895 Free UL TBF=0 with TLLI=0xec8157f3.

<0008> gprs_bssgp_pcu.cpp:145 LLC [SGSN -> PCU] = TLLI: 0xec8157f3 IMSI:
452022112638582 len: 62

<0002> gprs_rlcmac.cpp:354 Allocating DL TBF: TFI=0 TRX=0 MS_CLASS=10

<0002> gprs_rlcmac.cpp:948 - Setting Control TS 7

<0002> gprs_rlcmac_data.cpp:1801 TX: START TFI: 0 TLLI: 0xec8157f3
Immediate Assignment Downlink (PCH)

<0008> gprs_bssgp_pcu.cpp:145 LLC [SGSN -> PCU] = TLLI: 0xec8157f3 IMSI:
452022112638582 len: 62

<0002> gprs_bssgp_pcu.cpp:149 TBF: APPEND TFI: 0 TLLI: 0xec8157f3

<0004> gprs_rlcmac_data.cpp:1453 Complete DL frame for TBF=0: len=62

<0004> gprs_rlcmac_data.cpp:1461 - Dequeue next LLC for TBF=0 (len=62)

<0004> gprs_rlcmac_data.cpp:1453 Complete DL frame for TBF=0: len=62

<0006> gprs_rlcmac_sched.cpp:260 Received RTS for PDCH: TRX=0 TS=7
FN=2369800 block_nr=1 scheduling free USF for polling at FN=2369804 of DL
TFI=0

<0008> gprs_bssgp_pcu.cpp:145 LLC [SGSN -> PCU] = TLLI: 0xec8157f3 IMSI:
452022112638582 len: 62

<0002> gprs_bssgp_pcu.cpp:149 TBF: APPEND TFI: 0 TLLI: 0xec8157f3

<0002> gprs_rlcmac_data.cpp:1764 TBF: START TFI: 0 TLLI: 0xec8157f3 Packet
Downlink Assignment (PACCH)

<0006> gprs_rlcmac_sched.cpp:260 Received RTS for PDCH: TRX=0 TS=7
FN=2369848 block_nr=0 scheduling free USF for polling at FN=2369852 of DL
TFI=0

<0002> gprs_rlcmac_data.cpp:288 PACKET CONTROL ACK with expected FN=2369852
TLL=0xec8157f3 (TRX 0 TS 7)

<0004> gprs_rlcmac_data.cpp:1453 Complete DL frame for TBF=0: len=62

<0006> gprs_rlcmac_sched.cpp:260 Received RTS for PDCH: TRX=0 TS=7
FN=2369891 block_nr=10 scheduling free USF for polling at FN=2369895 of DL
TFI=0

<0002> gprs_rlcmac_data.cpp:376 PACKET DOWNLINK ACK with unknown FN=2369891
TFI=0 (TRX 0 TS 7)

<0002> gprs_rlcmac_data.cpp:100 Poll timeout for DL TBF=0

<0002> gprs_rlcmac_data.cpp:180 - Timeout for polling PACKET DOWNLINK ACK.

<0002> gprs_rlcmac_data.cpp:84 - Assignment was on PACCH

<0002> gprs_rlcmac_data.cpp:92 - No downlink ACK received yet

<0006> gprs_rlcmac_sched.cpp:260 Received RTS for PDCH: TRX=0 TS=7
FN=2369978 block_nr=6 scheduling free USF for polling at FN=2369982 of DL
TFI=0

<0002> gprs_rlcmac_data.cpp:388 Recovered downlink ack for DL TBF=0

<0001> pcu_l1_if.cpp:256 RACH request received: sapi=1 qta=0, ra=116,
fn=2370143

<0002> gprs_rlcmac_data.cpp:1138 TX: Immediate Assignment Uplink (AGCH)

<0002> gprs_rlcmac_data.cpp:1876 Got IMM.ASS confirm, but rest octets do
not start with bit sequence 'HH01' (Packet Downlink Assignment)

<0002> gprs_rlcmac.cpp:895 Free DL TBF=0 with TLLI=0xec8157f3.

<0002> gprs_rlcmac.cpp:354 Allocating UL TBF: TFI=0 TRX=0 MS_CLASS=10

<0002> gprs_rlcmac.cpp:948 - Setting Control TS 7

<0002> gprs_rlcmac_data.cpp:1069 TBF: START TFI: 0 TLLI: 0xec8157f3 Packet
Uplink Assignment (PACCH)

<0006> gprs_rlcmac_sched.cpp:260 Received RTS for PDCH: TRX=0 TS=7
FN=2370225 block_nr=3 scheduling free USF for polling at FN=2370229 of UL
TFI=0

<0002> gprs_rlcmac_data.cpp:288 PACKET CONTROL ACK with expected FN=2370229
TLL=0xec8157f3 (TRX 0 TS 7)

<0005> gprs_rlcmac_data.cpp:740 Complete UL frame for TBF=0: len=50

<0008> gprs_rlcmac.cpp:1760 LLC [PCU -> SGSN] TFI: 0 TLLI: 0xec8157f3 len=50

<0005> gprs_rlcmac_data.cpp:740 Complete UL frame for TBF=0: len=62

<0008> gprs_rlcmac.cpp:1760 LLC [PCU -> SGSN] TFI: 0 TLLI: 0xec8157f3 len=62

<0006> gprs_rlcmac_sched.cpp:260 Received RTS for PDCH: TRX=0 TS=7
FN=2370303 block_nr=9 scheduling free USF for polling at FN=2370307 of UL
TFI=0

<0002> gprs_rlcmac_data.cpp:288 PACKET CONTROL ACK with expected FN=2370307
TLL=0xec8157f3 (TRX 0 TS 7)

<0002> gprs_rlcmac.cpp:895 Free UL TBF=0 with TLLI=0xec8157f3.

<0008> gprs_bssgp_pcu.cpp:145 LLC [SGSN -> PCU] = TLLI: 0xec8157f3 IMSI:
452022112638582 len: 62

<0002> gprs_rlcmac.cpp:354 Allocating DL TBF: TFI=0 TRX=0 MS_CLASS=10

<0002> gprs_rlcmac.cpp:948 - Setting Control TS 7

<0002> gprs_rlcmac_data.cpp:1801 TX: START TFI: 0 TLLI: 0xec8157f3
Immediate Assignment Downlink (PCH)

<0004> gprs_rlcmac_data.cpp:1453 Complete DL frame for TBF=0: len=62

<0006> gprs_rlcmac_sched.cpp:260 Received RTS for PDCH: TRX=0 TS=7
FN=2370394 block_nr=6 scheduling free USF for polling at FN=2370398 of DL
TFI=0

<0002> gprs_rlcmac.cpp:895 Free DL TBF=0 with TLLI=0xec8157f3.

<0001> pcu_l1_if.cpp:256 RACH request received: sapi=1 qta=0, ra=118,
fn=2378009

<0002> gprs_rlcmac_data.cpp:1138 TX: Immediate Assignment Uplink (AGCH)

<0002> gprs_rlcmac_data.cpp:1876 Got IMM.ASS confirm, but rest octets do
not start with bit sequence 'HH01' (Packet Downlink Assignment)

<0002> gprs_rlcmac.cpp:354 Allocating UL TBF: TFI=0 TRX=0 MS_CLASS=10

<0002> gprs_rlcmac.cpp:948 - Setting Control TS 7

<0002> gprs_rlcmac_data.cpp:1069 TBF: START TFI: 0 TLLI: 0xec8157f3 Packet
Uplink Assignment (PACCH)

<0006> gprs_rlcmac_sched.cpp:260 Received RTS for PDCH: TRX=0 TS=7
FN=2378094 block_nr=7 scheduling free USF for polling at FN=2378098 of UL
TFI=0

<0002> gprs_rlcmac_data.cpp:288 PACKET CONTROL ACK with expected FN=2378098
TLL=0xec8157f3 (TRX 0 TS 7)

<0005> gprs_rlcmac_data.cpp:740 Complete UL frame for TBF=0: len=62

<0008> gprs_rlcmac.cpp:1760 LLC [PCU -> SGSN] TFI: 0 TLLI: 0xec8157f3 len=62

<0006> gprs_rlcmac_sched.cpp:260 Received RTS for PDCH: TRX=0 TS=7
FN=2378159 block_nr=10 scheduling free USF for polling at FN=2378163 of UL
TFI=0

<0002> gprs_rlcmac_data.cpp:281 PACKET CONTROL ACK with unknown FN=2378159
TLL=0xec8157f3 (TRX 0 TS 7)

<0002> gprs_rlcmac_data.cpp:100 Poll timeout for UL TBF=0

<0002> gprs_rlcmac_data.cpp:107 - Timeout for polling PACKET CONTROL ACK
for PACKET UPLINK ACK

<0002> gprs_rlcmac_data.cpp:84 - Assignment was on PACCH

<0002> gprs_rlcmac_data.cpp:86 - Uplink data was received

<0006> gprs_rlcmac_sched.cpp:260 Received RTS for PDCH: TRX=0 TS=7
FN=2378228 block_nr=2 scheduling free USF for polling at FN=2378233 of UL
TFI=0

<0002> gprs_rlcmac_data.cpp:100 Poll timeout for UL TBF=0

<0006> gprs_rlcmac_sched.cpp:260 Received RTS for PDCH: TRX=0 TS=7
FN=2378410 block_nr=8 scheduling free USF for polling at FN=2378415 of UL
TFI=0

<0002> gprs_rlcmac_data.cpp:100 Poll timeout for UL TBF=0

<0006> gprs_rlcmac_sched.cpp:260 Received RTS for PDCH: TRX=0 TS=7
FN=2378488 block_nr=2 scheduling free USF for polling at FN=2378493 of UL
TFI=0

<0002> gprs_rlcmac_data.cpp:100 Poll timeout for UL TBF=0

<0002> gprs_rlcmac_data.cpp:119 - N3103 exceeded

<0001> pcu_l1_if.cpp:256 RACH request received: sapi=1 qta=0, ra=116,
fn=2379067

<0002> gprs_rlcmac_data.cpp:1138 TX: Immediate Assignment Uplink (AGCH)

<0002> gprs_rlcmac_data.cpp:1876 Got IMM.ASS confirm, but rest octets do
not start with bit sequence 'HH01' (Packet Downlink Assignment)

<0002> gprs_rlcmac.cpp:354 Allocating UL TBF: TFI=1 TRX=0 MS_CLASS=10

<0002> gprs_rlcmac.cpp:948 - Setting Control TS 7

<0002> gprs_rlcmac_data.cpp:1069 TBF: START TFI: 1 TLLI: 0xec8157f3 Packet
Uplink Assignment (PACCH)

<0006> gprs_rlcmac_sched.cpp:260 Received RTS for PDCH: TRX=0 TS=7
FN=2379156 block_nr=0 scheduling free USF for polling at FN=2379160 of UL
TFI=1

<0002> gprs_rlcmac_data.cpp:288 PACKET CONTROL ACK with expected FN=2379160
TLL=0xec8157f3 (TRX 0 TS 7)

<0005> gprs_rlcmac_data.cpp:740 Complete UL frame for TBF=1: len=62

<0008> gprs_rlcmac.cpp:1760 LLC [PCU -> SGSN] TFI: 1 TLLI: 0xec8157f3 len=62

<0006> gprs_rlcmac_sched.cpp:260 Received RTS for PDCH: TRX=0 TS=7
FN=2379221 block_nr=3 scheduling free USF for polling at FN=2379225 of UL
TFI=1

<0002> gprs_rlcmac_data.cpp:288 PACKET CONTROL ACK with expected FN=2379225
TLL=0xec8157f3 (TRX 0 TS 7)

<0002> gprs_rlcmac.cpp:895 Free UL TBF=1 with TLLI=0xec8157f3.

<0002> gprs_rlcmac_data.cpp:536 TBF T3169 timeout during transsmission

<0002> gprs_rlcmac_data.cpp:84 - Assignment was on PACCH

<0002> gprs_rlcmac_data.cpp:86 - Uplink data was received

<0002> gprs_rlcmac.cpp:895 Free UL TBF=0 with TLLI=0xec8157f3.

<0001> pcu_l1_if.cpp:256 RACH request received: sapi=1 qta=0, ra=112,
fn=2381154

<0002> gprs_rlcmac_data.cpp:1138 TX: Immediate Assignment Uplink (AGCH)

<0002> gprs_rlcmac_data.cpp:1876 Got IMM.ASS confirm, but rest octets do
not start with bit sequence 'HH01' (Packet Downlink Assignment)

<0002> gprs_rlcmac.cpp:354 Allocating UL TBF: TFI=0 TRX=0 MS_CLASS=10

<0002> gprs_rlcmac.cpp:948 - Setting Control TS 7

<0002> gprs_rlcmac_data.cpp:1069 TBF: START TFI: 0 TLLI: 0xec8157f3 Packet
Uplink Assignment (PACCH)

<0006> gprs_rlcmac_sched.cpp:260 Received RTS for PDCH: TRX=0 TS=7
FN=2381240 block_nr=1 scheduling free USF for polling at FN=2381244 of UL
TFI=0

<0002> gprs_rlcmac_data.cpp:288 PACKET CONTROL ACK with expected FN=2381244
TLL=0xec8157f3 (TRX 0 TS 7)

<0005> gprs_rlcmac_data.cpp:740 Complete UL frame for TBF=0: len=62

<0008> gprs_rlcmac.cpp:1760 LLC [PCU -> SGSN] TFI: 0 TLLI: 0xec8157f3 len=62

<0006> gprs_rlcmac_sched.cpp:260 Received RTS for PDCH: TRX=0 TS=7
FN=2381301 block_nr=3 scheduling free USF for polling at FN=2381305 of UL
TFI=0

<0002> gprs_rlcmac_data.cpp:288 PACKET CONTROL ACK with expected FN=2381305
TLL=0xec8157f3 (TRX 0 TS 7)

<0002> gprs_rlcmac.cpp:895 Free UL TBF=0 with TLLI=0xec8157f3.

<0001> pcu_l1_if.cpp:256 RACH request received: sapi=1 qta=0, ra=115,
fn=2385350

<0002> gprs_rlcmac_data.cpp:1138 TX: Immediate Assignment Uplink (AGCH)

<0002> gprs_rlcmac_data.cpp:1876 Got IMM.ASS confirm, but rest octets do
not start with bit sequence 'HH01' (Packet Downlink Assignment)

<0002> gprs_rlcmac.cpp:354 Allocating UL TBF: TFI=0 TRX=0 MS_CLASS=10

<0002> gprs_rlcmac.cpp:948 - Setting Control TS 7

<0002> gprs_rlcmac_data.cpp:1069 TBF: START TFI: 0 TLLI: 0xec8157f3 Packet
Uplink Assignment (PACCH)

<0006> gprs_rlcmac_sched.cpp:260 Received RTS for PDCH: TRX=0 TS=7
FN=2385435 block_nr=9 scheduling free USF for polling at FN=2385439 of UL
TFI=0

<0002> gprs_rlcmac_data.cpp:288 PACKET CONTROL ACK with expected FN=2385439
TLL=0xec8157f3 (TRX 0 TS 7)

<0005> gprs_rlcmac_data.cpp:740 Complete UL frame for TBF=0: len=62

<0008> gprs_rlcmac.cpp:1760 LLC [PCU -> SGSN] TFI: 0 TLLI: 0xec8157f3 len=62

<0006> gprs_rlcmac_sched.cpp:260 Received RTS for PDCH: TRX=0 TS=7
FN=2385500 block_nr=0 scheduling free USF for polling at FN=2385504 of UL
TFI=0

<0002> gprs_rlcmac_data.cpp:288 PACKET CONTROL ACK with expected FN=2385504
TLL=0xec8157f3 (TRX 0 TS 7)

<0002> gprs_rlcmac.cpp:895 Free UL TBF=0 with TLLI=0xec8157f3.

<0001> pcu_l1_if.cpp:256 RACH request received: sapi=1 qta=0, ra=116,
fn=2393714

<0002> gprs_rlcmac_data.cpp:1138 TX: Immediate Assignment Uplink (AGCH)

<0002> gprs_rlcmac_data.cpp:1876 Got IMM.ASS confirm, but rest octets do
not start with bit sequence 'HH01' (Packet Downlink Assignment)

<0002> gprs_rlcmac.cpp:354 Allocating UL TBF: TFI=0 TRX=0 MS_CLASS=10

<0002> gprs_rlcmac.cpp:948 - Setting Control TS 7

<0002> gprs_rlcmac_data.cpp:1069 TBF: START TFI: 0 TLLI: 0xec8157f3 Packet
Uplink Assignment (PACCH)

<0006> gprs_rlcmac_sched.cpp:260 Received RTS for PDCH: TRX=0 TS=7
FN=2393798 block_nr=7 scheduling free USF for polling at FN=2393802 of UL
TFI=0

<0002> gprs_rlcmac_data.cpp:288 PACKET CONTROL ACK with expected FN=2393802
TLL=0xec8157f3 (TRX 0 TS 7)

<0005> gprs_rlcmac_data.cpp:740 Complete UL frame for TBF=0: len=62

<0008> gprs_rlcmac.cpp:1760 LLC [PCU -> SGSN] TFI: 0 TLLI: 0xec8157f3 len=62

<0006> gprs_rlcmac_sched.cpp:260 Received RTS for PDCH: TRX=0 TS=7
FN=2393863 block_nr=10 scheduling free USF for polling at FN=2393867 of UL
TFI=0

<0002> gprs_rlcmac_data.cpp:281 PACKET CONTROL ACK with unknown FN=2393863
TLL=0xec8157f3 (TRX 0 TS 7)

<0002> gprs_rlcmac_data.cpp:100 Poll timeout for UL TBF=0

<0002> gprs_rlcmac_data.cpp:107 - Timeout for polling PACKET CONTROL ACK
for PACKET UPLINK ACK

<0002> gprs_rlcmac_data.cpp:84 - Assignment was on PACCH

<0002> gprs_rlcmac_data.cpp:86 - Uplink data was received

<0006> gprs_rlcmac_sched.cpp:260 Received RTS for PDCH: TRX=0 TS=7
FN=2393984 block_nr=2 scheduling free USF for polling at FN=2393989 of UL
TFI=0

<0002> gprs_rlcmac_data.cpp:100 Poll timeout for UL TBF=0

<0006> gprs_rlcmac_sched.cpp:260 Received RTS for PDCH: TRX=0 TS=7
FN=2394028 block_nr=0 scheduling free USF for polling at FN=2394032 of UL
TFI=0

<0002> gprs_rlcmac_data.cpp:100 Poll timeout for UL TBF=0

<0006> gprs_rlcmac_sched.cpp:260 Received RTS for PDCH: TRX=0 TS=7
FN=2394075 block_nr=11 scheduling free USF for polling at FN=2394080 of UL
TFI=0

<0002> gprs_rlcmac_data.cpp:100 Poll timeout for UL TBF=0

<0002> gprs_rlcmac_data.cpp:119 - N3103 exceeded

<0002> gprs_rlcmac_data.cpp:536 TBF T3169 timeout during transsmission

<0002> gprs_rlcmac_data.cpp:84 - Assignment was on PACCH

<0002> gprs_rlcmac_data.cpp:86 - Uplink data was received

<0002> gprs_rlcmac.cpp:895 Free UL TBF=0 with TLLI=0xec8157f3.

....
On Sat, Oct 27, 2012 at 7:15 AM, jolly <andreas at eversberg.eu> wrote:

> Vladimir Rolbin wrote:
> > <0002> gprs_rlcmac_data.cpp:1183 TX: START TFI: 0 Immediate Assignment
> > Uplink (AGCH)
> > <0002> gprs_rlcmac_data.cpp:1895 Got IMM.ASS confirm, but rest octets
> > do not start with bit sequence 'HH01' (Packet Downlink Assignment)
> > <0006> gprs_rlcmac_sched.cpp:260 Received RTS for PDCH: TRX=0 TS=7
> > FN=168510 block_nr=7 scheduling free USF for polling at FN=168514 of
> > DL TFI=1
> > <0002> gprs_rlcmac_data.cpp:395 PACKET DOWNLINK ACK with unknown
> > FN=168519 TFI=1 (TRX 0 TS 7)
> > <0002> gprs_rlcmac_data.cpp:100 Poll timeout for DL TBF=1
> hi vladimir,
>
> there seems to be several problems. i can clearly see the two above:
>
> PCU sends immediate assignment message to BTS. it consists of three
> bytes with the last three digits of the IMSI, plus the complete IMM.ASS
> message including pseudo length byte and padding. the assignment seems
> ok, because the phone follows the assignment. the IMM.ASS confirm from
> BTS must not include the three digits of IMSI, but the complete message.
> the confirm must be sent to PCU after the assignment is sent (or
> sheduled) on PCH. this is required, because it may take seconds,
> depending on paging group configuration.
>
> the second problem is wrong scheduling. if you would have set drlcmac
> debugging, you would see when polling is scheduled. the scheduled FN
> must be 13 bursts (3 blocks) in advance of the RTS FN. 8 or 9 bursts
> later, the scheduler must schedule "free USF for polling" for the next
> block, which is 4 or 5 bursts later. since i don't see the drlcmac
> debugging in your log, i cannot verify it.
>
> regards,
>
> andreas
>
>
>
-------------- next part --------------
An HTML attachment was scrubbed...
URL: <http://lists.osmocom.org/pipermail/osmocom-net-gprs/attachments/20121028/9c1f0bb2/attachment.html>


More information about the osmocom-net-gprs mailing list