28 Oct
2012
28 Oct
'12
1:20 p.m.
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(a)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