This is merely a historical archive of years 2008-2021, before the migration to mailman3.
A maintained and still updated list archive can be found at https://lists.osmocom.org/hyperkitty/list/osmocom-net-gprs@lists.osmocom.org/.
Vladimir Rolbin vrolbin at gmail.comHi 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.htm>