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 "
<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.
....
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