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, here is the log with debug info: Welcome to the Osmo-PCU control interface Copyright (C) 2012 by ... License GNU GPL version 2 or later This is free software: you are free to change and redistribute it. There is NO WARRANTY, to the extent permitted by law. Osmo-PCU> Osmo-PCU> Osmo-PCU> Osmo-PCU> Osmo-PCU> Osmo-PCU> log Osmo-PCU> loglogging en Osmo-PCU> logging enenable 1 % Unknown command. Osmo-PCU> logging enable 1 Osmo-PCU> log Osmo-PCU> loglogging fil Osmo-PCU> logging filfilter all 1 Osmo-PCU> log Osmo-PCU> loglogging lev Osmo-PCU> logging levlevel rl Osmo-PCU> logging level rlrlcmac f de Osmo-PCU> logging level rlcmac dedebug Osmo-PCU> Osmo-PCU> Osmo-PCU> Osmo-PCU> Osmo-PCU> Osmo-PCU> [1;32m<0001> pcu_l1_if.cpp:334 BTS available [0;m [1;32m<0001> pcu_l1_if.cpp:335 mcc=452 [0;m [1;32m<0001> pcu_l1_if.cpp:336 mnc=2 [0;m [1;32m<0001> pcu_l1_if.cpp:337 lac=1000 [0;m [1;32m<0001> pcu_l1_if.cpp:338 rac=0 [0;m [1;32m<0001> pcu_l1_if.cpp:339 cell_id=0 [0;m [1;32m<0001> pcu_l1_if.cpp:340 nsei=8 [0;m [1;32m<0001> pcu_l1_if.cpp:345 nse_timer=0 0 0 0 0 0 0 [0;m [1;32m<0001> pcu_l1_if.cpp:353 cell_timer=0 0 0 0 0 0 0 0 0 0 0 [0;m [1;32m<0001> pcu_l1_if.cpp:354 repeat_time=5 [0;m [1;32m<0001> pcu_l1_if.cpp:355 repeat_count=10 [0;m [1;32m<0001> pcu_l1_if.cpp:356 bvci=7 [0;m [1;32m<0001> pcu_l1_if.cpp:357 t3142=20 [0;m [1;32m<0001> pcu_l1_if.cpp:358 t3169=5 [0;m [1;32m<0001> pcu_l1_if.cpp:359 t3191=5 [0;m [1;32m<0001> pcu_l1_if.cpp:360 t3193=1000 (ms) [0;m [1;32m<0001> pcu_l1_if.cpp:361 t3195=5 [0;m [1;32m<0001> pcu_l1_if.cpp:362 n3101=10 [0;m [1;32m<0001> pcu_l1_if.cpp:363 n3103=4 [0;m [1;32m<0001> pcu_l1_if.cpp:364 n3105=8 [0;m [1;32m<0001> pcu_l1_if.cpp:365 cv_countdown=15 [0;m [1;32m<0001> pcu_l1_if.cpp:366 dl_tbf_ext=0 [0;m [1;32m<0001> pcu_l1_if.cpp:367 ul_tbf_ext=0 [0;m [1;32m<0001> pcu_l1_if.cpp:376 initial_cs=1 [0;m [1;32m<0001> pcu_l1_if.cpp:377 initial_mcs=0 [0;m [1;32m<0001> pcu_l1_if.cpp:378 nsvci=4 [0;m [1;32m<0001> pcu_l1_if.cpp:379 local_port=5944 [0;m [1;32m<0001> pcu_l1_if.cpp:380 remote_port=23000 [0;m [1;32m<0001> pcu_l1_if.cpp:381 remote_ip=2130706433 [0;m [1;32m<0001> pcu_l1_if.cpp:82 Sending activate request: trx=0 ts=7 [0;m [1;32m<0001> pcu_l1_if.cpp:429 PDCH: trx=0 ts=7 [0;m [1;35m<0009> gprs_bssgp_pcu.cpp:491 NS-VC 4 is unblocked. [0;m [1;34m<0008> gprs_bssgp_pcu.cpp:532 Sending reset on BVCI 0 [0;m [1;34m<0008> gprs_bssgp_pcu.cpp:540 Sending reset on BVCI 7 [0;m [1;34m<0008> gprs_bssgp_pcu.cpp:548 Sending unblock on BVCI 7 [0;m [1;32m<0001> pcu_l1_if.cpp:256 RACH request received: sapi=1 qta=0, ra=120, fn=1280580 [0;m [0;33m<0002> gprs_rlcmac_data.cpp:1116 MS requests UL TBF on RACH, so we provide one: [0;m [0;33m<0002> gprs_rlcmac.cpp:214 Searching for first unallocated TFI: TRX=0 first TS=7 [0;m [0;33m<0002> gprs_rlcmac.cpp:225 Found TFI=0. [0;m [0;33m<0002> gprs_rlcmac.cpp:351 ********** TBF starts here ********** [0;m [0;33m<0002> gprs_rlcmac.cpp:354 Allocating UL TBF: TFI=0 TRX=0 MS_CLASS=0 [0;m [0;33m<0002> gprs_rlcmac.cpp:421 Slot Allocation (Algorithm A) for class 0 [0;m [0;33m<0002> gprs_rlcmac.cpp:434 - Assign uplink TS=7 USF=0 [0;m [0;33m<0002> gprs_rlcmac.cpp:948 - Setting Control TS 7 [0;m [0;33m<0002> gprs_rlcmac.cpp:973 UL TBF=0 changes state from NULL to FLOW [0;m [0;33m<0002> gprs_rlcmac.cpp:983 Starting UL TBF=0 timer 3169. [0;m [0;33m<0002> gprs_rlcmac_data.cpp:1159 TBF: [UPLINK] START TFI: 0 [0;m [0;33m<0002> gprs_rlcmac_data.cpp:1162 RX: [PCU <- BTS] TFI: 0 RACH qbit-ta=0 ra=0x78, Fn=1280580 (5,21,2) [0;m [0;33m<0002> gprs_rlcmac_data.cpp:1164 TX: START TFI: 0 Immediate Assignment Uplink (AGCH) [0;m [1;36m<0005> gprs_rlcmac_data.cpp:877 Decoded premier TLLI=0xace80214 of UL DATA TBF=0. [0;m [0;33m<0002> gprs_rlcmac.cpp:988 Restarting UL TBF=0 timer 3169 while old timer 3169 pending [0;m [0;33m<0002> gprs_rlcmac.cpp:988 Restarting UL TBF=0 timer 3169 while old timer 3169 pending [0;m [0;33m<0002> gprs_rlcmac.cpp:988 Restarting UL TBF=0 timer 3169 while old timer 3169 pending [0;m [1;36m<0005> gprs_rlcmac_data.cpp:740 Complete UL frame for TBF=0: len=43 [0;m [1;34m<0008> gprs_rlcmac.cpp:1760 LLC [PCU -> SGSN] TFI: 0 TLLI: 0xace80214 len=43 [0;m [0;33m<0002> gprs_rlcmac.cpp:973 UL TBF=0 changes state from FLOW to FINISHED [0;m [1;34m<0008> gprs_bssgp_pcu.cpp:145 LLC [SGSN -> PCU] = TLLI: 0xace80214 IMSI: 000 len: 9 [0;m [0;33m<0002> gprs_rlcmac.cpp:214 Searching for first unallocated TFI: TRX=0 first TS=7 [0;m [0;33m<0002> gprs_rlcmac.cpp:225 Found TFI=0. [0;m [0;33m<0002> gprs_rlcmac.cpp:351 ********** TBF starts here ********** [0;m [0;33m<0002> gprs_rlcmac.cpp:354 Allocating DL TBF: TFI=0 TRX=0 MS_CLASS=10 [0;m [0;33m<0002> gprs_rlcmac.cpp:421 Slot Allocation (Algorithm A) for class 10 [0;m [0;33m<0002> gprs_rlcmac.cpp:444 - Assign downlink TS=7 [0;m [0;33m<0002> gprs_rlcmac.cpp:948 - Setting Control TS 7 [0;m [0;33m<0002> gprs_bssgp_pcu.cpp:233 TBF: [DOWNLINK] START TFI: 0 TLLI: 0xace80214 [0;m [0;33m<0002> gprs_rlcmac_data.cpp:1837 Send dowlink assignment on PACCH, because UL TBF=0 exists for TLLI=0xace80214 [0;m [0;33m<0002> gprs_rlcmac.cpp:973 DL TBF=0 changes state from NULL to ASSIGN [0;m [0;33m<0002> gprs_rlcmac.cpp:983 Starting DL TBF=0 timer 0. [0;m [0;33m<0002> gprs_rlcmac_data.cpp:1764 TBF: START TFI: 0 TLLI: 0xace80214 Packet Downlink Assignment (PACCH) [0;m [0;33m<0002> gprs_rlcmac_data.cpp:1769 +++++++++++++++++++++++++ TX : Packet Downlink Assignment +++++++++++++++++++++++++ [0;m [0;33m<0002> gprs_rlcmac_data.cpp:1772 ------------------------- TX : Packet Downlink Assignment ------------------------- [0;m [0;33m<0002> gprs_rlcmac.cpp:988 Restarting UL TBF=0 timer 3169 while old timer 3169 pending [0;m [0;36m<0006> gprs_rlcmac_sched.cpp:260 Received RTS for PDCH: TRX=0 TS=7 FN=1280660 block_nr=1 scheduling free USF for polling at FN=1280664 of UL TFI=0 [0;m [0;33m<0002> gprs_rlcmac.cpp:988 Restarting UL TBF=0 timer 3169 while old timer 3169 pending [0;m [0;33m<0002> gprs_rlcmac.cpp:988 Restarting UL TBF=0 timer 3169 while old timer 3169 pending [0;m [0;33m<0002> gprs_rlcmac_data.cpp:270 +++++++++++++++++++++++++ RX : Uplink Control Block +++++++++++++++++++++++++ [0;m [0;33m<0002> gprs_rlcmac_data.cpp:273 ------------------------- RX : Uplink Control Block ------------------------- [0;m [0;33m<0002> gprs_rlcmac_data.cpp:288 PACKET CONTROL ACK with expected FN=1280664 TLL=0xace80214 (TRX 0 TS 7) [0;m [0;33m<0002> gprs_rlcmac_data.cpp:297 RX: [PCU <- BTS] TFI: 0 TLLI: 0xace80214 Packet Control Ack [0;m [0;33m<0002> gprs_rlcmac_data.cpp:316 TBF: [UPLINK] DOWNLINK ASSIGNED TFI: 0 TLLI: 0xace80214 [0;m [0;33m<0002> gprs_rlcmac.cpp:973 DL TBF=0 changes state from ASSIGN to FLOW [0;m [0;33m<0002> gprs_rlcmac.cpp:1005 Stopping DL TBF=0 timer 0. [0;m [1;33m<0004> gprs_rlcmac_data.cpp:1453 Complete DL frame for TBF=0: len=9 [0;m [0;33m<0002> gprs_rlcmac.cpp:973 DL TBF=0 changes state from FLOW to FINISHED [0;m [0;33m<0002> gprs_rlcmac_data.cpp:1532 Polling sheduled in this TS 7 [0;m [0;33m<0002> gprs_rlcmac.cpp:983 Starting DL TBF=0 timer 3191. [0;m [0;36m<0006> gprs_rlcmac_sched.cpp:260 Received RTS for PDCH: TRX=0 TS=7 FN=1280686 block_nr=7 scheduling free USF for polling at FN=1280690 of UL TFI=0 [0;m [0;36m<0006> gprs_rlcmac_sched.cpp:260 Received RTS for PDCH: TRX=0 TS=7 FN=1280690 block_nr=8 scheduling free USF for polling at FN=1280695 of DL TFI=0 [0;m [0;33m<0002> gprs_rlcmac_data.cpp:270 +++++++++++++++++++++++++ RX : Uplink Control Block +++++++++++++++++++++++++ [0;m [0;33m<0002> gprs_rlcmac_data.cpp:273 ------------------------- RX : Uplink Control Block ------------------------- [0;m [0;33m<0002> gprs_rlcmac_data.cpp:288 PACKET CONTROL ACK with expected FN=1280690 TLL=0xace80214 (TRX 0 TS 7) [0;m [0;33m<0002> gprs_rlcmac_data.cpp:297 RX: [PCU <- BTS] TFI: 0 TLLI: 0xace80214 Packet Control Ack [0;m [0;33m<0002> gprs_rlcmac_data.cpp:302 TBF: [UPLINK] END TFI: 0 TLLI: 0xace80214 [0;m [0;33m<0002> gprs_rlcmac.cpp:895 Free UL TBF=0 with TLLI=0xace80214. [0;m [0;33m<0002> gprs_rlcmac.cpp:1005 Stopping UL TBF=0 timer 3169. [0;m [0;33m<0002> gprs_rlcmac.cpp:911 ********** TBF ends here ********** [0;m [0;33m<0002> gprs_rlcmac_data.cpp:270 +++++++++++++++++++++++++ RX : Uplink Control Block +++++++++++++++++++++++++ [0;m [0;33m<0002> gprs_rlcmac_data.cpp:273 ------------------------- RX : Uplink Control Block ------------------------- [0;m [0;33m<0002> gprs_rlcmac.cpp:1005 Stopping DL TBF=0 timer 3191. [0;m [0;33m<0002> gprs_rlcmac_data.cpp:395 RX: [PCU <- BTS] TFI: 0 TLLI: 0xace80214 Packet Downlink Ack/Nack [0;m [0;33m<0002> gprs_rlcmac.cpp:983 Starting DL TBF=0 timer 3193. [0;m [0;33m<0002> gprs_rlcmac.cpp:973 DL TBF=0 changes state from FINISHED to WAIT RELEASE [0;m [1;32m<0001> pcu_l1_if.cpp:256 RACH request received: sapi=1 qta=0, ra=120, fn=1280840 [0;m [0;33m<0002> gprs_rlcmac_data.cpp:1116 MS requests UL TBF on RACH, so we provide one: [0;m [0;33m<0002> gprs_rlcmac.cpp:214 Searching for first unallocated TFI: TRX=0 first TS=7 [0;m [0;33m<0002> gprs_rlcmac.cpp:225 Found TFI=0. [0;m [0;33m<0002> gprs_rlcmac.cpp:351 ********** TBF starts here ********** [0;m [0;33m<0002> gprs_rlcmac.cpp:354 Allocating UL TBF: TFI=0 TRX=0 MS_CLASS=0 [0;m [0;33m<0002> gprs_rlcmac.cpp:421 Slot Allocation (Algorithm A) for class 0 [0;m [0;33m<0002> gprs_rlcmac.cpp:434 - Assign uplink TS=7 USF=0 [0;m [0;33m<0002> gprs_rlcmac.cpp:948 - Setting Control TS 7 [0;m [0;33m<0002> gprs_rlcmac.cpp:973 UL TBF=0 changes state from NULL to FLOW [0;m [0;33m<0002> gprs_rlcmac.cpp:983 Starting UL TBF=0 timer 3169. [0;m [0;33m<0002> gprs_rlcmac_data.cpp:1159 TBF: [UPLINK] START TFI: 0 [0;m [0;33m<0002> gprs_rlcmac_data.cpp:1162 RX: [PCU <- BTS] TFI: 0 RACH qbit-ta=0 ra=0x78, Fn=1280840 (5,26,2) [0;m [0;33m<0002> gprs_rlcmac_data.cpp:1164 TX: START TFI: 0 Immediate Assignment Uplink (AGCH) [0;m [1;36m<0005> gprs_rlcmac_data.cpp:877 Decoded premier TLLI=0xace80214 of UL DATA TBF=0. [0;m [1;36m<0005> gprs_rlcmac_data.cpp:882 Got RACH from TLLI=0xace80214 while DL TBF=0 still exists. Killing pending DL TBF [0;m [0;33m<0002> gprs_rlcmac.cpp:895 Free DL TBF=0 with TLLI=0xace80214. [0;m [0;33m<0002> gprs_rlcmac.cpp:1005 Stopping DL TBF=0 timer 3193. [0;m [0;33m<0002> gprs_rlcmac.cpp:911 ********** TBF ends here ********** [0;m [0;33m<0002> gprs_rlcmac.cpp:988 Restarting UL TBF=0 timer 3169 while old timer 3169 pending [0;m [0;33m<0002> gprs_rlcmac.cpp:988 Restarting UL TBF=0 timer 3169 while old timer 3169 pending [0;m [1;36m<0005> gprs_rlcmac_data.cpp:740 Complete UL frame for TBF=0: len=17 [0;m [1;34m<0008> gprs_rlcmac.cpp:1760 LLC [PCU -> SGSN] TFI: 0 TLLI: 0xace80214 len=17 [0;m [0;33m<0002> gprs_rlcmac.cpp:973 UL TBF=0 changes state from FLOW to FINISHED [0;m [1;34m<0008> gprs_bssgp_pcu.cpp:145 LLC [SGSN -> PCU] = TLLI: 0xace80214 IMSI: 000 len: 9 [0;m [0;33m<0002> gprs_rlcmac.cpp:214 Searching for first unallocated TFI: TRX=0 first TS=7 [0;m [0;33m<0002> gprs_rlcmac.cpp:225 Found TFI=0. [0;m [0;33m<0002> gprs_rlcmac.cpp:351 ********** TBF starts here ********** [0;m [0;33m<0002> gprs_rlcmac.cpp:354 Allocating DL TBF: TFI=0 TRX=0 MS_CLASS=10 [0;m [0;33m<0002> gprs_rlcmac.cpp:421 Slot Allocation (Algorithm A) for class 10 [0;m [0;33m<0002> gprs_rlcmac.cpp:444 - Assign downlink TS=7 [0;m [0;33m<0002> gprs_rlcmac.cpp:948 - Setting Control TS 7 [0;m [0;33m<0002> gprs_bssgp_pcu.cpp:233 TBF: [DOWNLINK] START TFI: 0 TLLI: 0xace80214 [0;m [0;33m<0002> gprs_rlcmac_data.cpp:1848 Send dowlink assignment for TBF=0 on PCH, no TBF exist (IMSI=000) [0;m [0;33m<0002> gprs_rlcmac.cpp:973 DL TBF=0 changes state from NULL to ASSIGN [0;m [0;33m<0002> gprs_rlcmac_data.cpp:1801 TX: START TFI: 0 TLLI: 0xace80214 Immediate Assignment Downlink (PCH) [0;m [0;33m<0002> gprs_rlcmac_data.cpp:1894 Got IMM.ASS confirm for TLLI=ace80214 [0;m [0;33m<0002> gprs_rlcmac.cpp:983 Starting DL TBF=0 timer 0. [0;m [0;33m<0002> gprs_rlcmac.cpp:988 Restarting UL TBF=0 timer 3169 while old timer 3169 pending [0;m [0;36m<0006> gprs_rlcmac_sched.cpp:260 Received RTS for PDCH: TRX=0 TS=7 FN=1280907 block_nr=10 scheduling free USF for polling at FN=1280911 of UL TFI=0 [0;m [0;33m<0002> gprs_rlcmac.cpp:988 Restarting UL TBF=0 timer 3169 while old timer 3169 pending [0;m [0;33m<0002> gprs_rlcmac.cpp:988 Restarting UL TBF=0 timer 3169 while old timer 3169 pending [0;m [0;33m<0002> gprs_rlcmac_data.cpp:270 +++++++++++++++++++++++++ RX : Uplink Control Block +++++++++++++++++++++++++ [0;m [0;33m<0002> gprs_rlcmac_data.cpp:273 ------------------------- RX : Uplink Control Block ------------------------- [0;m [0;33m<0002> gprs_rlcmac_data.cpp:281 PACKET CONTROL ACK with unknown FN=1280907 TLL=0xace80214 (TRX 0 TS 7) [0;m [0;33m<0002> gprs_rlcmac_data.cpp:501 DL TBF=0 timer 0 expired. [0;m [0;33m<0002> gprs_rlcmac.cpp:973 DL TBF=0 changes state from ASSIGN to FLOW [0;m [1;33m<0004> gprs_rlcmac_data.cpp:1453 Complete DL frame for TBF=0: len=9 [0;m [0;33m<0002> gprs_rlcmac.cpp:973 DL TBF=0 changes state from FLOW to FINISHED [0;m [0;33m<0002> gprs_rlcmac_data.cpp:1532 Polling sheduled in this TS 7 [0;m [0;33m<0002> gprs_rlcmac.cpp:983 Starting DL TBF=0 timer 3191. [0;m [0;36m<0006> gprs_rlcmac_sched.cpp:260 Received RTS for PDCH: TRX=0 TS=7 FN=1280955 block_nr=9 scheduling free USF for polling at FN=1280959 of DL TFI=0 [0;m [0;33m<0002> gprs_rlcmac_data.cpp:270 +++++++++++++++++++++++++ RX : Uplink Control Block +++++++++++++++++++++++++ [0;m [0;33m<0002> gprs_rlcmac_data.cpp:273 ------------------------- RX : Uplink Control Block ------------------------- [0;m [0;33m<0002> gprs_rlcmac.cpp:1005 Stopping DL TBF=0 timer 3191. [0;m [0;33m<0002> gprs_rlcmac_data.cpp:395 RX: [PCU <- BTS] TFI: 0 TLLI: 0xace80214 Packet Downlink Ack/Nack [0;m [0;33m<0002> gprs_rlcmac.cpp:983 Starting DL TBF=0 timer 3193. [0;m [0;33m<0002> gprs_rlcmac.cpp:973 DL TBF=0 changes state from FINISHED to WAIT RELEASE [0;m [0;33m<0002> gprs_rlcmac_data.cpp:100 Poll timeout for UL TBF=0 [0;m [0;33m<0002> gprs_rlcmac_data.cpp:107 - Timeout for polling PACKET CONTROL ACK for PACKET UPLINK ACK [0;m [0;33m<0002> gprs_rlcmac_data.cpp:82 - Assignment was on CCCH [0;m [0;33m<0002> gprs_rlcmac_data.cpp:86 - Uplink data was received [0;m [0;36m<0006> gprs_rlcmac_sched.cpp:260 Received RTS for PDCH: TRX=0 TS=7 FN=1281093 block_nr=5 scheduling free USF for polling at FN=1281098 of UL TFI=0 [0;m [0;33m<0002> gprs_rlcmac_data.cpp:100 Poll timeout for UL TBF=0 [0;m [0;36m<0006> gprs_rlcmac_sched.cpp:260 Received RTS for PDCH: TRX=0 TS=7 FN=1281145 block_nr=5 scheduling free USF for polling at FN=1281150 of UL TFI=0 [0;m [1;32m<0001> pcu_l1_if.cpp:256 RACH request received: sapi=1 qta=0, ra=122, fn=1281151 [0;m [0;33m<0002> gprs_rlcmac_data.cpp:1116 MS requests UL TBF on RACH, so we provide one: [0;m [0;33m<0002> gprs_rlcmac.cpp:214 Searching for first unallocated TFI: TRX=0 first TS=7 [0;m [0;33m<0002> gprs_rlcmac.cpp:225 Found TFI=1. [0;m [0;33m<0002> gprs_rlcmac.cpp:351 ********** TBF starts here ********** [0;m [0;33m<0002> gprs_rlcmac.cpp:354 Allocating UL TBF: TFI=1 TRX=0 MS_CLASS=0 [0;m [0;33m<0002> gprs_rlcmac.cpp:421 Slot Allocation (Algorithm A) for class 0 [0;m [0;33m<0002> gprs_rlcmac.cpp:434 - Assign uplink TS=7 USF=1 [0;m [0;33m<0002> gprs_rlcmac.cpp:948 - Setting Control TS 7 [0;m [0;33m<0002> gprs_rlcmac.cpp:973 UL TBF=1 changes state from NULL to FLOW [0;m [0;33m<0002> gprs_rlcmac.cpp:983 Starting UL TBF=1 timer 3169. [0;m [0;33m<0002> gprs_rlcmac_data.cpp:1159 TBF: [UPLINK] START TFI: 1 [0;m [0;33m<0002> gprs_rlcmac_data.cpp:1162 RX: [PCU <- BTS] TFI: 1 RACH qbit-ta=0 ra=0x7a, Fn=1281151 (6,31,1) [0;m [0;33m<0002> gprs_rlcmac_data.cpp:1164 TX: START TFI: 1 Immediate Assignment Uplink (AGCH) [0;m [0;33m<0002> gprs_rlcmac_data.cpp:501 DL TBF=0 timer 3193 expired. [0;m [0;33m<0002> gprs_rlcmac_data.cpp:542 TBF will be freed due to timeout [0;m [0;33m<0002> gprs_rlcmac.cpp:895 Free DL TBF=0 with TLLI=0xace80214. [0;m [0;33m<0002> gprs_rlcmac.cpp:911 ********** TBF ends here ********** [0;m [1;36m<0005> gprs_rlcmac_data.cpp:877 Decoded premier TLLI=0xace80214 of UL DATA TBF=1. [0;m [1;36m<0005> gprs_rlcmac_data.cpp:891 Got RACH from TLLI=0xace80214 while UL TBF=0 still exists. Killing pending UL TBF [0;m [0;33m<0002> gprs_rlcmac.cpp:895 Free UL TBF=0 with TLLI=0xace80214. [0;m [0;33m<0002> gprs_rlcmac.cpp:1005 Stopping UL TBF=0 timer 3169. [0;m [0;33m<0002> gprs_rlcmac.cpp:911 ********** TBF ends here ********** [0;m [0;33m<0002> gprs_rlcmac.cpp:988 Restarting UL TBF=1 timer 3169 while old timer 3169 pending [0;m [0;33m<0002> gprs_rlcmac.cpp:988 Restarting UL TBF=1 timer 3169 while old timer 3169 pending [0;m [1;36m<0005> gprs_rlcmac_data.cpp:740 Complete UL frame for TBF=1: len=17 [0;m [1;34m<0008> gprs_rlcmac.cpp:1760 LLC [PCU -> SGSN] TFI: 1 TLLI: 0xace80214 len=17 [0;m [0;33m<0002> gprs_rlcmac.cpp:973 UL TBF=1 changes state from FLOW to FINISHED [0;m [1;34m<0008> gprs_bssgp_pcu.cpp:145 LLC [SGSN -> PCU] = TLLI: 0xace80214 IMSI: 452022112638582 len: 24 [0;m [0;33m<0002> gprs_rlcmac.cpp:214 Searching for first unallocated TFI: TRX=0 first TS=7 [0;m [0;33m<0002> gprs_rlcmac.cpp:225 Found TFI=0. [0;m [0;33m<0002> gprs_rlcmac.cpp:351 ********** TBF starts here ********** [0;m [0;33m<0002> gprs_rlcmac.cpp:354 Allocating DL TBF: TFI=0 TRX=0 MS_CLASS=10 [0;m [0;33m<0002> gprs_rlcmac.cpp:421 Slot Allocation (Algorithm A) for class 10 [0;m [0;33m<0002> gprs_rlcmac.cpp:444 - Assign downlink TS=7 [0;m [0;33m<0002> gprs_rlcmac.cpp:948 - Setting Control TS 7 [0;m [0;33m<0002> gprs_bssgp_pcu.cpp:233 TBF: [DOWNLINK] START TFI: 0 TLLI: 0xace80214 [0;m [0;33m<0002> gprs_rlcmac_data.cpp:1848 Send dowlink assignment for TBF=0 on PCH, no TBF exist (IMSI=452022112638582) [0;m [0;33m<0002> gprs_rlcmac.cpp:973 DL TBF=0 changes state from NULL to ASSIGN [0;m [0;33m<0002> gprs_rlcmac_data.cpp:1801 TX: START TFI: 0 TLLI: 0xace80214 Immediate Assignment Downlink (PCH) [0;m [0;33m<0002> gprs_rlcmac_data.cpp:1894 Got IMM.ASS confirm for TLLI=ace80214 [0;m [0;33m<0002> gprs_rlcmac.cpp:983 Starting DL TBF=0 timer 0. [0;m [0;33m<0002> gprs_rlcmac.cpp:988 Restarting UL TBF=1 timer 3169 while old timer 3169 pending [0;m [0;36m<0006> gprs_rlcmac_sched.cpp:260 Received RTS for PDCH: TRX=0 TS=7 FN=1281215 block_nr=9 scheduling free USF for polling at FN=1281219 of UL TFI=1 [0;m [0;33m<0002> gprs_rlcmac.cpp:988 Restarting UL TBF=1 timer 3169 while old timer 3169 pending [0;m [0;33m<0002> gprs_rlcmac.cpp:988 Restarting UL TBF=1 timer 3169 while old timer 3169 pending [0;m [0;33m<0002> gprs_rlcmac_data.cpp:270 +++++++++++++++++++++++++ RX : Uplink Control Block +++++++++++++++++++++++++ [0;m [0;33m<0002> gprs_rlcmac_data.cpp:273 ------------------------- RX : Uplink Control Block ------------------------- [0;m [0;33m<0002> gprs_rlcmac_data.cpp:288 PACKET CONTROL ACK with expected FN=1281219 TLL=0xace80214 (TRX 0 TS 7) [0;m [0;33m<0002> gprs_rlcmac_data.cpp:297 RX: [PCU <- BTS] TFI: 1 TLLI: 0xace80214 Packet Control Ack [0;m [0;33m<0002> gprs_rlcmac_data.cpp:302 TBF: [UPLINK] END TFI: 1 TLLI: 0xace80214 [0;m [0;33m<0002> gprs_rlcmac.cpp:895 Free UL TBF=1 with TLLI=0xace80214. [0;m [0;33m<0002> gprs_rlcmac.cpp:1005 Stopping UL TBF=1 timer 3169. [0;m [0;33m<0002> gprs_rlcmac.cpp:911 ********** TBF ends here ********** [0;m [0;33m<0002> gprs_rlcmac_data.cpp:501 DL TBF=0 timer 0 expired. [0;m [0;33m<0002> gprs_rlcmac.cpp:973 DL TBF=0 changes state from ASSIGN to FLOW [0;m [1;33m<0004> gprs_rlcmac_data.cpp:1453 Complete DL frame for TBF=0: len=24 [0;m [0;33m<0002> gprs_rlcmac.cpp:973 DL TBF=0 changes state from FLOW to FINISHED [0;m [0;33m<0002> gprs_rlcmac_data.cpp:1532 Polling sheduled in this TS 7 [0;m [0;33m<0002> gprs_rlcmac.cpp:983 Starting DL TBF=0 timer 3191. [0;m [0;36m<0006> gprs_rlcmac_sched.cpp:260 Received RTS for PDCH: TRX=0 TS=7 FN=1281267 block_nr=9 scheduling free USF for polling at FN=1281271 of DL TFI=0 [0;m [0;33m<0002> gprs_rlcmac_data.cpp:270 +++++++++++++++++++++++++ RX : Uplink Control Block +++++++++++++++++++++++++ [0;m [0;33m<0002> gprs_rlcmac_data.cpp:273 ------------------------- RX : Uplink Control Block ------------------------- [0;m [0;33m<0002> gprs_rlcmac.cpp:1005 Stopping DL TBF=0 timer 3191. [0;m [0;33m<0002> gprs_rlcmac_data.cpp:395 RX: [PCU <- BTS] TFI: 0 TLLI: 0xace80214 Packet Downlink Ack/Nack [0;m [0;33m<0002> gprs_rlcmac.cpp:983 Starting DL TBF=0 timer 3193. [0;m [0;33m<0002> gprs_rlcmac.cpp:973 DL TBF=0 changes state from FINISHED to WAIT RELEASE [0;m [1;32m<0001> pcu_l1_if.cpp:256 RACH request received: sapi=1 qta=0, ra=120, fn=1281444 [0;m [0;33m<0002> gprs_rlcmac_data.cpp:1116 MS requests UL TBF on RACH, so we provide one: [0;m [0;33m<0002> gprs_rlcmac.cpp:214 Searching for first unallocated TFI: TRX=0 first TS=7 [0;m [0;33m<0002> gprs_rlcmac.cpp:225 Found TFI=0. [0;m [0;33m<0002> gprs_rlcmac.cpp:351 ********** TBF starts here ********** [0;m [0;33m<0002> gprs_rlcmac.cpp:354 Allocating UL TBF: TFI=0 TRX=0 MS_CLASS=0 [0;m [0;33m<0002> gprs_rlcmac.cpp:421 Slot Allocation (Algorithm A) for class 0 [0;m [0;33m<0002> gprs_rlcmac.cpp:434 - Assign uplink TS=7 USF=0 [0;m [0;33m<0002> gprs_rlcmac.cpp:948 - Setting Control TS 7 [0;m [0;33m<0002> gprs_rlcmac.cpp:973 UL TBF=0 changes state from NULL to FLOW [0;m [0;33m<0002> gprs_rlcmac.cpp:983 Starting UL TBF=0 timer 3169. [0;m [0;33m<0002> gprs_rlcmac_data.cpp:1159 TBF: [UPLINK] START TFI: 0 [0;m [0;33m<0002> gprs_rlcmac_data.cpp:1162 RX: [PCU <- BTS] TFI: 0 RACH qbit-ta=0 ra=0x78, Fn=1281444 (6,18,8) [0;m [0;33m<0002> gprs_rlcmac_data.cpp:1164 TX: START TFI: 0 Immediate Assignment Uplink (AGCH) [0;m [0;33m<0002> gprs_rlcmac_data.cpp:501 DL TBF=0 timer 3193 expired. [0;m [0;33m<0002> gprs_rlcmac_data.cpp:542 TBF will be freed due to timeout [0;m [0;33m<0002> gprs_rlcmac.cpp:895 Free DL TBF=0 with TLLI=0xace80214. [0;m [0;33m<0002> gprs_rlcmac.cpp:911 ********** TBF ends here ********** [0;m [1;36m<0005> gprs_rlcmac_data.cpp:877 Decoded premier TLLI=0xcb46771f of UL DATA TBF=0. [0;m [0;33m<0002> gprs_rlcmac.cpp:988 Restarting UL TBF=0 timer 3169 while old timer 3169 pending [0;m [1;36m<0005> gprs_rlcmac_data.cpp:740 Complete UL frame for TBF=0: len=8 [0;m [1;34m<0008> gprs_rlcmac.cpp:1760 LLC [PCU -> SGSN] TFI: 0 TLLI: 0xcb46771f len=8 [0;m [0;33m<0002> gprs_rlcmac.cpp:973 UL TBF=0 changes state from FLOW to FINISHED [0;m [0;33m<0002> gprs_rlcmac.cpp:988 Restarting UL TBF=0 timer 3169 while old timer 3169 pending [0;m [0;33m<0002> gprs_rlcmac.cpp:988 Restarting UL TBF=0 timer 3169 while old timer 3169 pending [0;m [0;36m<0006> gprs_rlcmac_sched.cpp:260 Received RTS for PDCH: TRX=0 TS=7 FN=1281518 block_nr=7 scheduling free USF for polling at FN=1281522 of UL TFI=0 [0;m [0;33m<0002> gprs_rlcmac.cpp:988 Restarting UL TBF=0 timer 3169 while old timer 3169 pending [0;m [0;33m<0002> gprs_rlcmac.cpp:988 Restarting UL TBF=0 timer 3169 while old timer 3169 pending [0;m [0;33m<0002> gprs_rlcmac_data.cpp:270 +++++++++++++++++++++++++ RX : Uplink Control Block +++++++++++++++++++++++++ [0;m [0;33m<0002> gprs_rlcmac_data.cpp:273 ------------------------- RX : Uplink Control Block ------------------------- [0;m [0;33m<0002> gprs_rlcmac_data.cpp:288 PACKET CONTROL ACK with expected FN=1281522 TLL=0xcb46771f (TRX 0 TS 7) [0;m [0;33m<0002> gprs_rlcmac_data.cpp:297 RX: [PCU <- BTS] TFI: 0 TLLI: 0xcb46771f Packet Control Ack [0;m [0;33m<0002> gprs_rlcmac_data.cpp:302 TBF: [UPLINK] END TFI: 0 TLLI: 0xcb46771f [0;m [0;33m<0002> gprs_rlcmac.cpp:895 Free UL TBF=0 with TLLI=0xcb46771f. [0;m [0;33m<0002> gprs_rlcmac.cpp:1005 Stopping UL TBF=0 timer 3169. [0;m [0;33m<0002> gprs_rlcmac.cpp:911 ********** TBF ends here ********** [0;m [1;32m<0001> pcu_l1_if.cpp:256 RACH request received: sapi=1 qta=0, ra=123, fn=1288588 [0;m [0;33m<0002> gprs_rlcmac_data.cpp:1116 MS requests UL TBF on RACH, so we provide one: [0;m [0;33m<0002> gprs_rlcmac.cpp:214 Searching for first unallocated TFI: TRX=0 first TS=7 [0;m [0;33m<0002> gprs_rlcmac.cpp:225 Found TFI=0. [0;m [0;33m<0002> gprs_rlcmac.cpp:351 ********** TBF starts here ********** [0;m [0;33m<0002> gprs_rlcmac.cpp:354 Allocating UL TBF: TFI=0 TRX=0 MS_CLASS=0 [0;m [0;33m<0002> gprs_rlcmac.cpp:421 Slot Allocation (Algorithm A) for class 0 [0;m [0;33m<0002> gprs_rlcmac.cpp:434 - Assign uplink TS=7 USF=0 [0;m [0;33m<0002> gprs_rlcmac.cpp:948 - Setting Control TS 7 [0;m [0;33m<0002> gprs_rlcmac.cpp:973 UL TBF=0 changes state from NULL to FLOW [0;m [0;33m<0002> gprs_rlcmac.cpp:983 Starting UL TBF=0 timer 3169. [0;m [0;33m<0002> gprs_rlcmac_data.cpp:1159 TBF: [UPLINK] START TFI: 0 [0;m [0;33m<0002> gprs_rlcmac_data.cpp:1162 RX: [PCU <- BTS] TFI: 0 RACH qbit-ta=0 ra=0x7b, Fn=1288588 (11,22,2) [0;m [0;33m<0002> gprs_rlcmac_data.cpp:1164 TX: START TFI: 0 Immediate Assignment Uplink (AGCH) [0;m [1;36m<0005> gprs_rlcmac_data.cpp:877 Decoded premier TLLI=0xcb46771f of UL DATA TBF=0. [0;m [0;33m<0002> gprs_rlcmac.cpp:988 Restarting UL TBF=0 timer 3169 while old timer 3169 pending [0;m [0;33m<0002> gprs_rlcmac.cpp:988 Restarting UL TBF=0 timer 3169 while old timer 3169 pending [0;m [0;33m<0002> gprs_rlcmac.cpp:988 Restarting UL TBF=0 timer 3169 while old timer 3169 pending [0;m [0;33m<0002> gprs_rlcmac.cpp:988 Restarting UL TBF=0 timer 3169 while old timer 3169 pending [0;m [0;33m<0002> gprs_rlcmac.cpp:988 Restarting UL TBF=0 timer 3169 while old timer 3169 pending [0;m [0;33m<0002> gprs_rlcmac.cpp:988 Restarting UL TBF=0 timer 3169 while old timer 3169 pending [0;m [0;33m<0002> gprs_rlcmac.cpp:988 Restarting UL TBF=0 timer 3169 while old timer 3169 pending [0;m [0;33m<0002> gprs_rlcmac.cpp:988 Restarting UL TBF=0 timer 3169 while old timer 3169 pending [0;m [0;33m<0002> gprs_rlcmac.cpp:988 Restarting UL TBF=0 timer 3169 while old timer 3169 pending [0;m [1;36m<0005> gprs_rlcmac_data.cpp:740 Complete UL frame for TBF=0: len=150 [0;m [1;34m<0008> gprs_rlcmac.cpp:1760 LLC [PCU -> SGSN] TFI: 0 TLLI: 0xcb46771f len=150 [0;m [0;33m<0002> gprs_rlcmac.cpp:973 UL TBF=0 changes state from FLOW to FINISHED [0;m [1;34m<0008> gprs_bssgp_pcu.cpp:145 LLC [SGSN -> PCU] = TLLI: 0xcb46771f IMSI: 452022112638582 len: 55 [0;m [0;33m<0002> gprs_rlcmac.cpp:214 Searching for first unallocated TFI: TRX=0 first TS=7 [0;m [0;33m<0002> gprs_rlcmac.cpp:225 Found TFI=0. [0;m [0;33m<0002> gprs_rlcmac.cpp:351 ********** TBF starts here ********** [0;m [0;33m<0002> gprs_rlcmac.cpp:354 Allocating DL TBF: TFI=0 TRX=0 MS_CLASS=10 [0;m [0;33m<0002> gprs_rlcmac.cpp:421 Slot Allocation (Algorithm A) for class 10 [0;m [0;33m<0002> gprs_rlcmac.cpp:444 - Assign downlink TS=7 [0;m [0;33m<0002> gprs_rlcmac.cpp:948 - Setting Control TS 7 [0;m [0;33m<0002> gprs_bssgp_pcu.cpp:233 TBF: [DOWNLINK] START TFI: 0 TLLI: 0xcb46771f [0;m [0;33m<0002> gprs_rlcmac_data.cpp:1837 Send dowlink assignment on PACCH, because UL TBF=0 exists for TLLI=0xcb46771f [0;m [0;33m<0002> gprs_rlcmac.cpp:973 DL TBF=0 changes state from NULL to ASSIGN [0;m [0;33m<0002> gprs_rlcmac.cpp:983 Starting DL TBF=0 timer 0. [0;m [0;33m<0002> gprs_rlcmac.cpp:988 Restarting UL TBF=0 timer 3169 while old timer 3169 pending [0;m [0;33m<0002> gprs_rlcmac_data.cpp:1764 TBF: START TFI: 0 TLLI: 0xcb46771f Packet Downlink Assignment (PACCH) [0;m [0;33m<0002> gprs_rlcmac_data.cpp:1769 +++++++++++++++++++++++++ TX : Packet Downlink Assignment +++++++++++++++++++++++++ [0;m [0;33m<0002> gprs_rlcmac_data.cpp:1772 ------------------------- TX : Packet Downlink Assignment ------------------------- [0;m [0;33m<0002> gprs_rlcmac.cpp:988 Restarting UL TBF=0 timer 3169 while old timer 3169 pending [0;m [0;36m<0006> gprs_rlcmac_sched.cpp:260 Received RTS for PDCH: TRX=0 TS=7 FN=1288694 block_nr=7 scheduling free USF for polling at FN=1288698 of UL TFI=0 [0;m [0;33m<0002> gprs_rlcmac.cpp:988 Restarting UL TBF=0 timer 3169 while old timer 3169 pending [0;m [0;33m<0002> gprs_rlcmac.cpp:988 Restarting UL TBF=0 timer 3169 while old timer 3169 pending [0;m [0;33m<0002> gprs_rlcmac_data.cpp:270 +++++++++++++++++++++++++ RX : Uplink Control Block +++++++++++++++++++++++++ [0;m [0;33m<0002> gprs_rlcmac_data.cpp:273 ------------------------- RX : Uplink Control Block ------------------------- [0;m [0;33m<0002> gprs_rlcmac_data.cpp:288 PACKET CONTROL ACK with expected FN=1288698 TLL=0xcb46771f (TRX 0 TS 7) [0;m [0;33m<0002> gprs_rlcmac_data.cpp:297 RX: [PCU <- BTS] TFI: 0 TLLI: 0xcb46771f Packet Control Ack [0;m [0;33m<0002> gprs_rlcmac_data.cpp:316 TBF: [UPLINK] DOWNLINK ASSIGNED TFI: 0 TLLI: 0xcb46771f [0;m [0;33m<0002> gprs_rlcmac.cpp:973 DL TBF=0 changes state from ASSIGN to FLOW [0;m [0;33m<0002> gprs_rlcmac.cpp:1005 Stopping DL TBF=0 timer 0. [0;m [0;36m<0006> gprs_rlcmac_sched.cpp:260 Received RTS for PDCH: TRX=0 TS=7 FN=1288724 block_nr=2 scheduling free USF for polling at FN=1288729 of UL TFI=0 [0;m [1;33m<0004> gprs_rlcmac_data.cpp:1453 Complete DL frame for TBF=0: len=55 [0;m [0;33m<0002> gprs_rlcmac.cpp:973 DL TBF=0 changes state from FLOW to FINISHED [0;m [0;33m<0002> gprs_rlcmac_data.cpp:1532 Polling sheduled in this TS 7 [0;m [0;33m<0002> gprs_rlcmac.cpp:983 Starting DL TBF=0 timer 3191. [0;m [0;36m<0006> gprs_rlcmac_sched.cpp:260 Received RTS for PDCH: TRX=0 TS=7 FN=1288737 block_nr=5 scheduling free USF for polling at FN=1288742 of DL TFI=0 [0;m [0;33m<0002> gprs_rlcmac_data.cpp:270 +++++++++++++++++++++++++ RX : Uplink Control Block +++++++++++++++++++++++++ [0;m [0;33m<0002> gprs_rlcmac_data.cpp:273 ------------------------- RX : Uplink Control Block ------------------------- [0;m [0;33m<0002> gprs_rlcmac_data.cpp:288 PACKET CONTROL ACK with expected FN=1288729 TLL=0xcb46771f (TRX 0 TS 7) [0;m [0;33m<0002> gprs_rlcmac_data.cpp:297 RX: [PCU <- BTS] TFI: 0 TLLI: 0xcb46771f Packet Control Ack [0;m [0;33m<0002> gprs_rlcmac_data.cpp:302 TBF: [UPLINK] END TFI: 0 TLLI: 0xcb46771f [0;m [0;33m<0002> gprs_rlcmac.cpp:895 Free UL TBF=0 with TLLI=0xcb46771f. [0;m [0;33m<0002> gprs_rlcmac.cpp:1005 Stopping UL TBF=0 timer 3169. [0;m [0;33m<0002> gprs_rlcmac.cpp:911 ********** TBF ends here ********** [0;m [0;33m<0002> gprs_rlcmac_data.cpp:270 +++++++++++++++++++++++++ RX : Uplink Control Block +++++++++++++++++++++++++ [0;m [0;33m<0002> gprs_rlcmac_data.cpp:273 ------------------------- RX : Uplink Control Block ------------------------- [0;m [0;33m<0002> gprs_rlcmac.cpp:1005 Stopping DL TBF=0 timer 3191. [0;m [0;33m<0002> gprs_rlcmac_data.cpp:395 RX: [PCU <- BTS] TFI: 0 TLLI: 0xcb46771f Packet Downlink Ack/Nack [0;m [0;33m<0002> gprs_rlcmac.cpp:983 Starting DL TBF=0 timer 3193. [0;m [0;33m<0002> gprs_rlcmac.cpp:973 DL TBF=0 changes state from FINISHED to WAIT RELEASE [0;m [1;32m<0001> pcu_l1_if.cpp:256 RACH request received: sapi=1 qta=0, ra=117, fn=1288901 [0;m [0;33m<0002> gprs_rlcmac_data.cpp:1116 MS requests UL TBF on RACH, so we provide one: [0;m [0;33m<0002> gprs_rlcmac_data.cpp:1119 MS requests single block allocation [0;m [0;33m<0002> gprs_rlcmac_data.cpp:1136 RX: [PCU <- BTS] RACH qbit-ta=0 ra=0x75, Fn=1288901 (12,29,3) [0;m [0;33m<0002> gprs_rlcmac_data.cpp:1138 TX: Immediate Assignment Uplink (AGCH) [0;m [0;33m<0002> gprs_rlcmac_data.cpp:501 DL TBF=0 timer 3193 expired. [0;m [0;33m<0002> gprs_rlcmac_data.cpp:542 TBF will be freed due to timeout [0;m [0;33m<0002> gprs_rlcmac.cpp:895 Free DL TBF=0 with TLLI=0xcb46771f. [0;m [0;33m<0002> gprs_rlcmac.cpp:911 ********** TBF ends here ********** [0;m [0;33m<0002> gprs_rlcmac_data.cpp:270 +++++++++++++++++++++++++ RX : Uplink Control Block +++++++++++++++++++++++++ [0;m [0;33m<0002> gprs_rlcmac_data.cpp:273 ------------------------- RX : Uplink Control Block ------------------------- [0;m [0;33m<0002> gprs_rlcmac_data.cpp:442 MS requests UL TBF in packet ressource request of single block, so we provide one: [0;m [0;33m<0002> gprs_rlcmac.cpp:214 Searching for first unallocated TFI: TRX=0 first TS=7 [0;m [0;33m<0002> gprs_rlcmac.cpp:225 Found TFI=0. [0;m [0;33m<0002> gprs_rlcmac.cpp:351 ********** TBF starts here ********** [0;m [0;33m<0002> gprs_rlcmac.cpp:354 Allocating UL TBF: TFI=0 TRX=0 MS_CLASS=10 [0;m [0;33m<0002> gprs_rlcmac.cpp:421 Slot Allocation (Algorithm A) for class 10 [0;m [0;33m<0002> gprs_rlcmac.cpp:434 - Assign uplink TS=7 USF=0 [0;m [0;33m<0002> gprs_rlcmac.cpp:948 - Setting Control TS 7 [0;m [0;33m<0002> gprs_rlcmac.cpp:973 UL TBF=0 changes state from NULL to ASSIGN [0;m [0;33m<0002> gprs_rlcmac.cpp:983 Starting UL TBF=0 timer 3169. [0;m [0;33m<0002> gprs_rlcmac_data.cpp:452 Change control TS to 7 until assinment is complete. [0;m [0;33m<0002> gprs_rlcmac_data.cpp:1069 TBF: START TFI: 0 TLLI: 0xcb46771f Packet Uplink Assignment (PACCH) [0;m [0;33m<0002> gprs_rlcmac_data.cpp:1083 +++++++++++++++++++++++++ TX : Packet Uplink Assignment +++++++++++++++++++++++++ [0;m [0;33m<0002> gprs_rlcmac_data.cpp:1086 ------------------------- TX : Packet Uplink Assignment ------------------------- [0;m [0;36m<0006> gprs_rlcmac_sched.cpp:260 Received RTS for PDCH: TRX=0 TS=7 FN=1288989 block_nr=3 scheduling free USF for polling at FN=1288993 of UL TFI=0 [0;m [0;33m<0002> gprs_rlcmac_data.cpp:270 +++++++++++++++++++++++++ RX : Uplink Control Block +++++++++++++++++++++++++ [0;m [0;33m<0002> gprs_rlcmac_data.cpp:273 ------------------------- RX : Uplink Control Block ------------------------- [0;m [0;33m<0002> gprs_rlcmac_data.cpp:288 PACKET CONTROL ACK with expected FN=1288993 TLL=0xcb46771f (TRX 0 TS 7) [0;m [0;33m<0002> gprs_rlcmac_data.cpp:297 RX: [PCU <- BTS] TFI: 0 TLLI: 0xcb46771f Packet Control Ack [0;m [0;33m<0002> gprs_rlcmac_data.cpp:343 TBF: [DOWNLINK] UPLINK ASSIGNED TFI: 0 TLLI: 0xcb46771f [0;m [0;33m<0002> gprs_rlcmac.cpp:973 UL TBF=0 changes state from ASSIGN to FLOW [0;m [0;33m<0002> gprs_rlcmac.cpp:988 Restarting UL TBF=0 timer 3169 while old timer 3169 pending [0;m [0;33m<0002> gprs_rlcmac.cpp:988 Restarting UL TBF=0 timer 3169 while old timer 3169 pending [0;m [0;33m<0002> gprs_rlcmac.cpp:988 Restarting UL TBF=0 timer 3169 while old timer 3169 pending [0;m [0;33m<0002> gprs_rlcmac.cpp:988 Restarting UL TBF=0 timer 3169 while old timer 3169 pending [0;m [1;36m<0005> gprs_rlcmac_data.cpp:740 Complete UL frame for TBF=0: len=72 [0;m [1;34m<0008> gprs_rlcmac.cpp:1760 LLC [PCU -> SGSN] TFI: 0 TLLI: 0xcb46771f len=72 [0;m [0;33m<0002> gprs_rlcmac.cpp:973 UL TBF=0 changes state from FLOW to FINISHED [0;m [1;34m<0008> gprs_bssgp_pcu.cpp:145 LLC [SGSN -> PCU] = TLLI: 0xcb46771f IMSI: 452022112638582 len: 111 [0;m [0;33m<0002> gprs_rlcmac.cpp:214 Searching for first unallocated TFI: TRX=0 first TS=7 [0;m [0;33m<0002> gprs_rlcmac.cpp:225 Found TFI=0. [0;m [0;33m<0002> gprs_rlcmac.cpp:351 ********** TBF starts here ********** [0;m [0;33m<0002> gprs_rlcmac.cpp:354 Allocating DL TBF: TFI=0 TRX=0 MS_CLASS=10 [0;m [0;33m<0002> gprs_rlcmac.cpp:421 Slot Allocation (Algorithm A) for class 10 [0;m [0;33m<0002> gprs_rlcmac.cpp:444 - Assign downlink TS=7 [0;m [0;33m<0002> gprs_rlcmac.cpp:948 - Setting Control TS 7 [0;m [0;33m<0002> gprs_bssgp_pcu.cpp:233 TBF: [DOWNLINK] START TFI: 0 TLLI: 0xcb46771f [0;m [0;33m<0002> gprs_rlcmac_data.cpp:1837 Send dowlink assignment on PACCH, because UL TBF=0 exists for TLLI=0xcb46771f [0;m [0;33m<0002> gprs_rlcmac.cpp:973 DL TBF=0 changes state from NULL to ASSIGN [0;m [0;33m<0002> gprs_rlcmac.cpp:983 Starting DL TBF=0 timer 0. [0;m [0;33m<0002> gprs_rlcmac_data.cpp:1764 TBF: START TFI: 0 TLLI: 0xcb46771f Packet Downlink Assignment (PACCH) [0;m [0;33m<0002> gprs_rlcmac_data.cpp:1769 +++++++++++++++++++++++++ TX : Packet Downlink Assignment +++++++++++++++++++++++++ [0;m [0;33m<0002> gprs_rlcmac_data.cpp:1772 ------------------------- TX : Packet Downlink Assignment ------------------------- [0;m [0;33m<0002> gprs_rlcmac.cpp:988 Restarting UL TBF=0 timer 3169 while old timer 3169 pending [0;m [0;33m<0002> gprs_rlcmac.cpp:988 Restarting UL TBF=0 timer 3169 while old timer 3169 pending [0;m [0;36m<0006> gprs_rlcmac_sched.cpp:260 Received RTS for PDCH: TRX=0 TS=7 FN=1289054 block_nr=6 scheduling free USF for polling at FN=1289058 of UL TFI=0 [0;m [0;33m<0002> gprs_rlcmac.cpp:988 Restarting UL TBF=0 timer 3169 while old timer 3169 pending [0;m [0;33m<0002> gprs_rlcmac.cpp:988 Restarting UL TBF=0 timer 3169 while old timer 3169 pending [0;m [0;33m<0002> gprs_rlcmac_data.cpp:270 +++++++++++++++++++++++++ RX : Uplink Control Block +++++++++++++++++++++++++ [0;m [0;33m<0002> gprs_rlcmac_data.cpp:273 ------------------------- RX : Uplink Control Block ------------------------- [0;m [0;33m<0002> gprs_rlcmac_data.cpp:288 PACKET CONTROL ACK with expected FN=1289058 TLL=0xcb46771f (TRX 0 TS 7) [0;m [0;33m<0002> gprs_rlcmac_data.cpp:297 RX: [PCU <- BTS] TFI: 0 TLLI: 0xcb46771f Packet Control Ack [0;m [0;33m<0002> gprs_rlcmac_data.cpp:316 TBF: [UPLINK] DOWNLINK ASSIGNED TFI: 0 TLLI: 0xcb46771f [0;m [0;33m<0002> gprs_rlcmac.cpp:973 DL TBF=0 changes state from ASSIGN to FLOW [0;m [0;33m<0002> gprs_rlcmac.cpp:1005 Stopping DL TBF=0 timer 0. [0;m [0;36m<0006> gprs_rlcmac_sched.cpp:260 Received RTS for PDCH: TRX=0 TS=7 FN=1289084 block_nr=1 scheduling free USF for polling at FN=1289088 of UL TFI=0 [0;m [0;33m<0002> gprs_rlcmac_data.cpp:270 +++++++++++++++++++++++++ RX : Uplink Control Block +++++++++++++++++++++++++ [0;m [0;33m<0002> gprs_rlcmac_data.cpp:273 ------------------------- RX : Uplink Control Block ------------------------- [0;m [0;33m<0002> gprs_rlcmac_data.cpp:288 PACKET CONTROL ACK with expected FN=1289088 TLL=0xcb46771f (TRX 0 TS 7) [0;m [0;33m<0002> gprs_rlcmac_data.cpp:297 RX: [PCU <- BTS] TFI: 0 TLLI: 0xcb46771f Packet Control Ack [0;m [0;33m<0002> gprs_rlcmac_data.cpp:302 TBF: [UPLINK] END TFI: 0 TLLI: 0xcb46771f [0;m [0;33m<0002> gprs_rlcmac.cpp:895 Free UL TBF=0 with TLLI=0xcb46771f. [0;m [0;33m<0002> gprs_rlcmac.cpp:1005 Stopping UL TBF=0 timer 3169. [0;m [0;33m<0002> gprs_rlcmac.cpp:911 ********** TBF ends here ********** [0;m [1;33m<0004> gprs_rlcmac_data.cpp:1453 Complete DL frame for TBF=0: len=111 [0;m [0;33m<0002> gprs_rlcmac.cpp:973 DL TBF=0 changes state from FLOW to FINISHED [0;m [0;33m<0002> gprs_rlcmac_data.cpp:1532 Polling sheduled in this TS 7 [0;m [0;33m<0002> gprs_rlcmac.cpp:983 Starting DL TBF=0 timer 3191. [0;m [0;36m<0006> gprs_rlcmac_sched.cpp:260 Received RTS for PDCH: TRX=0 TS=7 FN=1289110 block_nr=7 scheduling free USF for polling at FN=1289114 of DL TFI=0 [0;m [0;33m<0002> gprs_rlcmac_data.cpp:270 +++++++++++++++++++++++++ RX : Uplink Control Block +++++++++++++++++++++++++ [0;m [0;33m<0002> gprs_rlcmac_data.cpp:273 ------------------------- RX : Uplink Control Block ------------------------- [0;m [0;33m<0002> gprs_rlcmac.cpp:1005 Stopping DL TBF=0 timer 3191. [0;m [0;33m<0002> gprs_rlcmac_data.cpp:395 RX: [PCU <- BTS] TFI: 0 TLLI: 0xcb46771f Packet Downlink Ack/Nack [0;m [0;33m<0002> gprs_rlcmac.cpp:983 Starting DL TBF=0 timer 3193. [0;m [0;33m<0002> gprs_rlcmac.cpp:973 DL TBF=0 changes state from FINISHED to WAIT RELEASE [0;m [1;32m<0001> pcu_l1_if.cpp:256 RACH request received: sapi=1 qta=0, ra=118, fn=1289261 [0;m [0;33m<0002> gprs_rlcmac_data.cpp:1116 MS requests UL TBF on RACH, so we provide one: [0;m [0;33m<0002> gprs_rlcmac_data.cpp:1119 MS requests single block allocation [0;m [0;33m<0002> gprs_rlcmac_data.cpp:1136 RX: [PCU <- BTS] RACH qbit-ta=0 ra=0x76, Fn=1289261 (12,32,25) [0;m [0;33m<0002> gprs_rlcmac_data.cpp:1138 TX: Immediate Assignment Uplink (AGCH) [0;m [0;33m<0002> gprs_rlcmac_data.cpp:270 +++++++++++++++++++++++++ RX : Uplink Control Block +++++++++++++++++++++++++ [0;m [0;33m<0002> gprs_rlcmac_data.cpp:273 ------------------------- RX : Uplink Control Block ------------------------- [0;m [1;36m<0005> gprs_rlcmac_data.cpp:437 Got RACH from TLLI=0xcb46771f while DL TBF=0 still exists. Killing pending DL TBF [0;m [0;33m<0002> gprs_rlcmac.cpp:895 Free DL TBF=0 with TLLI=0xcb46771f. [0;m [0;33m<0002> gprs_rlcmac.cpp:1005 Stopping DL TBF=0 timer 3193. [0;m [0;33m<0002> gprs_rlcmac.cpp:911 ********** TBF ends here ********** [0;m [0;33m<0002> gprs_rlcmac_data.cpp:442 MS requests UL TBF in packet ressource request of single block, so we provide one: [0;m [0;33m<0002> gprs_rlcmac.cpp:214 Searching for first unallocated TFI: TRX=0 first TS=7 [0;m [0;33m<0002> gprs_rlcmac.cpp:225 Found TFI=0. [0;m [0;33m<0002> gprs_rlcmac.cpp:351 ********** TBF starts here ********** [0;m [0;33m<0002> gprs_rlcmac.cpp:354 Allocating UL TBF: TFI=0 TRX=0 MS_CLASS=10 [0;m [0;33m<0002> gprs_rlcmac.cpp:421 Slot Allocation (Algorithm A) for class 10 [0;m [0;33m<0002> gprs_rlcmac.cpp:434 - Assign uplink TS=7 USF=0 [0;m [0;33m<0002> gprs_rlcmac.cpp:948 - Setting Control TS 7 [0;m [0;33m<0002> gprs_rlcmac.cpp:973 UL TBF=0 changes state from NULL to ASSIGN [0;m [0;33m<0002> gprs_rlcmac.cpp:983 Starting UL TBF=0 timer 3169. [0;m [0;33m<0002> gprs_rlcmac_data.cpp:452 Change control TS to 7 until assinment is complete. [0;m [0;33m<0002> gprs_rlcmac_data.cpp:1069 TBF: START TFI: 0 TLLI: 0xcb46771f Packet Uplink Assignment (PACCH) [0;m [0;33m<0002> gprs_rlcmac_data.cpp:1083 +++++++++++++++++++++++++ TX : Packet Uplink Assignment +++++++++++++++++++++++++ [0;m [0;33m<0002> gprs_rlcmac_data.cpp:1086 ------------------------- TX : Packet Uplink Assignment ------------------------- [0;m [0;36m<0006> gprs_rlcmac_sched.cpp:260 Received RTS for PDCH: TRX=0 TS=7 FN=1289348 block_nr=2 scheduling free USF for polling at FN=1289353 of UL TFI=0 [0;m [0;33m<0002> gprs_rlcmac_data.cpp:270 +++++++++++++++++++++++++ RX : Uplink Control Block +++++++++++++++++++++++++ [0;m [0;33m<0002> gprs_rlcmac_data.cpp:273 ------------------------- RX : Uplink Control Block ------------------------- [0;m [0;33m<0002> gprs_rlcmac_data.cpp:288 PACKET CONTROL ACK with expected FN=1289353 TLL=0xcb46771f (TRX 0 TS 7) [0;m [0;33m<0002> gprs_rlcmac_data.cpp:297 RX: [PCU <- BTS] TFI: 0 TLLI: 0xcb46771f Packet Control Ack [0;m [0;33m<0002> gprs_rlcmac_data.cpp:343 TBF: [DOWNLINK] UPLINK ASSIGNED TFI: 0 TLLI: 0xcb46771f [0;m [0;33m<0002> gprs_rlcmac.cpp:973 UL TBF=0 changes state from ASSIGN to FLOW [0;m [0;33m<0002> gprs_rlcmac.cpp:988 Restarting UL TBF=0 timer 3169 while old timer 3169 pending [0;m [0;33m<0002> gprs_rlcmac.cpp:988 Restarting UL TBF=0 timer 3169 while old timer 3169 pending [0;m [0;33m<0002> gprs_rlcmac.cpp:988 Restarting UL TBF=0 timer 3169 while old timer 3169 pending [0;m [0;33m<0002> gprs_rlcmac.cpp:988 Restarting UL TBF=0 timer 3169 while old timer 3169 pending [0;m [1;36m<0005> gprs_rlcmac_data.cpp:740 Complete UL frame for TBF=0: len=70 [0;m [1;34m<0008> gprs_rlcmac.cpp:1760 LLC [PCU -> SGSN] TFI: 0 TLLI: 0xcb46771f len=70 [0;m [0;33m<0002> gprs_rlcmac.cpp:973 UL TBF=0 changes state from FLOW to FINISHED [0;m [0;33m<0002> gprs_rlcmac.cpp:988 Restarting UL TBF=0 timer 3169 while old timer 3169 pending [0;m [0;36m<0006> gprs_rlcmac_sched.cpp:260 Received RTS for PDCH: TRX=0 TS=7 FN=1289409 block_nr=4 scheduling free USF for polling at FN=1289413 of UL TFI=0 [0;m [0;33m<0002> gprs_rlcmac.cpp:988 Restarting UL TBF=0 timer 3169 while old timer 3169 pending [0;m [0;33m<0002> gprs_rlcmac.cpp:988 Restarting UL TBF=0 timer 3169 while old timer 3169 pending [0;m [0;33m<0002> gprs_rlcmac_data.cpp:270 +++++++++++++++++++++++++ RX : Uplink Control Block +++++++++++++++++++++++++ [0;m [0;33m<0002> gprs_rlcmac_data.cpp:273 ------------------------- RX : Uplink Control Block ------------------------- [0;m [0;33m<0002> gprs_rlcmac_data.cpp:281 PACKET CONTROL ACK with unknown FN=1289409 TLL=0xcb46771f (TRX 0 TS 7) [0;m [1;34m<0008> gprs_bssgp_pcu.cpp:145 LLC [SGSN -> PCU] = TLLI: 0xcb46771f IMSI: 452022112638582 len: 70 [0;m [0;33m<0002> gprs_rlcmac.cpp:214 Searching for first unallocated TFI: TRX=0 first TS=7 [0;m [0;33m<0002> gprs_rlcmac.cpp:225 Found TFI=0. [0;m [0;33m<0002> gprs_rlcmac.cpp:351 ********** TBF starts here ********** [0;m [0;33m<0002> gprs_rlcmac.cpp:354 Allocating DL TBF: TFI=0 TRX=0 MS_CLASS=10 [0;m [0;33m<0002> gprs_rlcmac.cpp:421 Slot Allocation (Algorithm A) for class 10 [0;m [0;33m<0002> gprs_rlcmac.cpp:444 - Assign downlink TS=7 [0;m [0;33m<0002> gprs_rlcmac.cpp:948 - Setting Control TS 7 [0;m [0;33m<0002> gprs_bssgp_pcu.cpp:233 TBF: [DOWNLINK] START TFI: 0 TLLI: 0xcb46771f [0;m [0;33m<0002> gprs_rlcmac_data.cpp:1848 Send dowlink assignment for TBF=0 on PCH, no TBF exist (IMSI=452022112638582) [0;m [0;33m<0002> gprs_rlcmac.cpp:973 DL TBF=0 changes state from NULL to ASSIGN [0;m [0;33m<0002> gprs_rlcmac_data.cpp:1801 TX: START TFI: 0 TLLI: 0xcb46771f Immediate Assignment Downlink (PCH) [0;m [0;33m<0002> gprs_rlcmac_data.cpp:1894 Got IMM.ASS confirm for TLLI=cb46771f [0;m [0;33m<0002> gprs_rlcmac.cpp:983 Starting DL TBF=0 timer 0. [0;m [0;33m<0002> gprs_rlcmac_data.cpp:501 DL TBF=0 timer 0 expired. [0;m [0;33m<0002> gprs_rlcmac.cpp:973 DL TBF=0 changes state from ASSIGN to FLOW [0;m [1;33m<0004> gprs_rlcmac_data.cpp:1453 Complete DL frame for TBF=0: len=70 [0;m [0;33m<0002> gprs_rlcmac.cpp:973 DL TBF=0 changes state from FLOW to FINISHED [0;m [0;33m<0002> gprs_rlcmac_data.cpp:1532 Polling sheduled in this TS 7 [0;m [0;33m<0002> gprs_rlcmac.cpp:983 Starting DL TBF=0 timer 3191. [0;m [0;36m<0006> gprs_rlcmac_sched.cpp:260 Received RTS for PDCH: TRX=0 TS=7 FN=1289517 block_nr=5 scheduling free USF for polling at FN=1289522 of DL TFI=0 [0;m [0;33m<0002> gprs_rlcmac_data.cpp:270 +++++++++++++++++++++++++ RX : Uplink Control Block +++++++++++++++++++++++++ [0;m [0;33m<0002> gprs_rlcmac_data.cpp:273 ------------------------- RX : Uplink Control Block ------------------------- [0;m [0;33m<0002> gprs_rlcmac.cpp:1005 Stopping DL TBF=0 timer 3191. [0;m [0;33m<0002> gprs_rlcmac_data.cpp:395 RX: [PCU <- BTS] TFI: 0 TLLI: 0xcb46771f Packet Downlink Ack/Nack [0;m [0;33m<0002> gprs_rlcmac.cpp:983 Starting DL TBF=0 timer 3193. [0;m [0;33m<0002> gprs_rlcmac.cpp:973 DL TBF=0 changes state from FINISHED to WAIT RELEASE [0;m [0;33m<0002> gprs_rlcmac_data.cpp:100 Poll timeout for UL TBF=0 [0;m [0;33m<0002> gprs_rlcmac_data.cpp:107 - Timeout for polling PACKET CONTROL ACK for PACKET UPLINK ACK [0;m [0;33m<0002> gprs_rlcmac_data.cpp:84 - Assignment was on PACCH [0;m [0;33m<0002> gprs_rlcmac_data.cpp:86 - Uplink data was received [0;m [0;36m<0006> gprs_rlcmac_sched.cpp:260 Received RTS for PDCH: TRX=0 TS=7 FN=1289548 block_nr=0 scheduling free USF for polling at FN=1289552 of UL TFI=0 [0;m [1;34m<0008> gprs_bssgp_pcu.cpp:145 LLC [SGSN -> PCU] = TLLI: 0xcb46771f IMSI: 452022112638582 len: 70 [0;m [0;33m<0002> gprs_bssgp_pcu.cpp:149 TBF: APPEND TFI: 0 TLLI: 0xcb46771f [0;m [0;33m<0002> gprs_bssgp_pcu.cpp:152 TBF in WAIT RELEASE state (T3193), so reuse TBF [0;m [0;33m<0002> gprs_rlcmac.cpp:921 ********** TBF update ********** [0;m [0;33m<0002> gprs_rlcmac.cpp:421 Slot Allocation (Algorithm A) for class 10 [0;m [0;33m<0002> gprs_rlcmac.cpp:444 - Assign downlink TS=7 [0;m [0;33m<0002> gprs_rlcmac.cpp:1005 Stopping DL TBF=0 timer 3193. [0;m [0;33m<0002> gprs_rlcmac_data.cpp:1837 Send dowlink assignment on PACCH, because DL TBF=0 exists for TLLI=0xcb46771f [0;m [0;33m<0002> gprs_rlcmac.cpp:973 DL TBF=0 changes state from WAIT RELEASE to ASSIGN [0;m [0;33m<0002> gprs_rlcmac.cpp:983 Starting DL TBF=0 timer 0. [0;m [0;33m<0002> gprs_rlcmac_data.cpp:1764 TBF: START TFI: 0 TLLI: 0xcb46771f Packet Downlink Assignment (PACCH) [0;m [0;33m<0002> gprs_rlcmac_data.cpp:1769 +++++++++++++++++++++++++ TX : Packet Downlink Assignment +++++++++++++++++++++++++ [0;m [0;33m<0002> gprs_rlcmac_data.cpp:1772 ------------------------- TX : Packet Downlink Assignment ------------------------- [0;m [0;36m<0006> gprs_rlcmac_sched.cpp:260 Received RTS for PDCH: TRX=0 TS=7 FN=1289604 block_nr=1 scheduling free USF for polling at FN=1289608 of DL TFI=0 [0;m [0;33m<0002> gprs_rlcmac_data.cpp:270 +++++++++++++++++++++++++ RX : Uplink Control Block +++++++++++++++++++++++++ [0;m [0;33m<0002> gprs_rlcmac_data.cpp:273 ------------------------- RX : Uplink Control Block ------------------------- [0;m [0;33m<0002> gprs_rlcmac_data.cpp:288 PACKET CONTROL ACK with expected FN=1289608 TLL=0xcb46771f (TRX 0 TS 7) [0;m [0;33m<0002> gprs_rlcmac_data.cpp:297 RX: [PCU <- BTS] TFI: 0 TLLI: 0xcb46771f Packet Control Ack [0;m [0;33m<0002> gprs_rlcmac_data.cpp:316 TBF: [UPLINK] DOWNLINK ASSIGNED TFI: 0 TLLI: 0xcb46771f [0;m [0;33m<0002> gprs_rlcmac.cpp:973 DL TBF=0 changes state from ASSIGN to FLOW [0;m [0;33m<0002> gprs_rlcmac.cpp:1005 Stopping DL TBF=0 timer 0. [0;m [1;33m<0004> gprs_rlcmac_data.cpp:1453 Complete DL frame for TBF=0: len=70 [0;m [0;33m<0002> gprs_rlcmac.cpp:973 DL TBF=0 changes state from FLOW to FINISHED [0;m [0;33m<0002> gprs_rlcmac_data.cpp:1532 Polling sheduled in this TS 7 [0;m [0;33m<0002> gprs_rlcmac.cpp:983 Starting DL TBF=0 timer 3191. [0;m [0;36m<0006> gprs_rlcmac_sched.cpp:260 Received RTS for PDCH: TRX=0 TS=7 FN=1289647 block_nr=11 scheduling free USF for polling at FN=1289652 of DL TFI=0 [0;m [0;33m<0002> gprs_rlcmac_data.cpp:270 +++++++++++++++++++++++++ RX : Uplink Control Block +++++++++++++++++++++++++ [0;m [0;33m<0002> gprs_rlcmac_data.cpp:273 ------------------------- RX : Uplink Control Block ------------------------- [0;m [0;33m<0002> gprs_rlcmac.cpp:1005 Stopping DL TBF=0 timer 3191. [0;m [0;33m<0002> gprs_rlcmac_data.cpp:395 RX: [PCU <- BTS] TFI: 0 TLLI: 0xcb46771f Packet Downlink Ack/Nack [0;m [0;33m<0002> gprs_rlcmac.cpp:983 Starting DL TBF=0 timer 3193. [0;m [0;33m<0002> gprs_rlcmac.cpp:973 DL TBF=0 changes state from FINISHED to WAIT RELEASE [0;m [0;33m<0002> gprs_rlcmac_data.cpp:410 MS requests UL TBF in ack message, so we provide one: [0;m [0;33m<0002> gprs_rlcmac.cpp:214 Searching for first unallocated TFI: TRX=0 first TS=7 [0;m [0;33m<0002> gprs_rlcmac.cpp:225 Found TFI=1. [0;m [0;33m<0002> gprs_rlcmac.cpp:351 ********** TBF starts here ********** [0;m [0;33m<0002> gprs_rlcmac.cpp:354 Allocating UL TBF: TFI=1 TRX=0 MS_CLASS=10 [0;m [0;33m<0002> gprs_rlcmac.cpp:421 Slot Allocation (Algorithm A) for class 10 [0;m [0;33m<0002> gprs_rlcmac.cpp:434 - Assign uplink TS=7 USF=1 [0;m [0;33m<0002> gprs_rlcmac.cpp:948 - Setting Control TS 7 [0;m [0;33m<0002> gprs_rlcmac.cpp:973 UL TBF=1 changes state from NULL to ASSIGN [0;m [0;33m<0002> gprs_rlcmac.cpp:983 Starting UL TBF=1 timer 3169. [0;m [0;33m<0002> gprs_rlcmac_data.cpp:100 Poll timeout for UL TBF=0 [0;m [0;33m<0002> gprs_rlcmac_data.cpp:1069 TBF: START TFI: 1 TLLI: 0xcb46771f Packet Uplink Assignment (PACCH) [0;m [0;33m<0002> gprs_rlcmac_data.cpp:1083 +++++++++++++++++++++++++ TX : Packet Uplink Assignment +++++++++++++++++++++++++ [0;m [0;33m<0002> gprs_rlcmac_data.cpp:1086 ------------------------- TX : Packet Uplink Assignment ------------------------- [0;m [0;36m<0006> gprs_rlcmac_sched.cpp:260 Received RTS for PDCH: TRX=0 TS=7 FN=1289678 block_nr=6 scheduling free USF for polling at FN=1289682 of DL TFI=0 [0;m [0;36m<0006> gprs_rlcmac_sched.cpp:260 Received RTS for PDCH: TRX=0 TS=7 FN=1289682 block_nr=7 scheduling free USF for polling at FN=1289686 of UL TFI=0 [0;m [0;33m<0002> gprs_rlcmac_data.cpp:270 +++++++++++++++++++++++++ RX : Uplink Control Block +++++++++++++++++++++++++ [0;m [0;33m<0002> gprs_rlcmac_data.cpp:273 ------------------------- RX : Uplink Control Block ------------------------- [0;m [0;33m<0002> gprs_rlcmac_data.cpp:288 PACKET CONTROL ACK with expected FN=1289682 TLL=0xcb46771f (TRX 0 TS 7) [0;m [0;33m<0002> gprs_rlcmac_data.cpp:297 RX: [PCU <- BTS] TFI: 0 TLLI: 0xcb46771f Packet Control Ack [0;m [0;33m<0002> gprs_rlcmac_data.cpp:343 TBF: [DOWNLINK] UPLINK ASSIGNED TFI: 0 TLLI: 0xcb46771f [0;m [0;33m<0002> gprs_rlcmac.cpp:973 UL TBF=1 changes state from ASSIGN to FLOW [0;m [0;33m<0002> gprs_rlcmac.cpp:988 Restarting UL TBF=1 timer 3169 while old timer 3169 pending [0;m [0;33m<0002> gprs_rlcmac_data.cpp:100 Poll timeout for UL TBF=0 [0;m [0;33m<0002> gprs_rlcmac.cpp:988 Restarting UL TBF=1 timer 3169 while old timer 3169 pending [0;m [1;34m<0008> gprs_bssgp_pcu.cpp:145 LLC [SGSN -> PCU] = TLLI: 0xcb46771f IMSI: 452022112638582 len: 70 [0;m [0;33m<0002> gprs_bssgp_pcu.cpp:149 TBF: APPEND TFI: 0 TLLI: 0xcb46771f [0;m [0;33m<0002> gprs_bssgp_pcu.cpp:152 TBF in WAIT RELEASE state (T3193), so reuse TBF [0;m [0;33m<0002> gprs_rlcmac.cpp:921 ********** TBF update ********** [0;m [0;33m<0002> gprs_rlcmac.cpp:421 Slot Allocation (Algorithm A) for class 10 [0;m [0;33m<0002> gprs_rlcmac.cpp:444 - Assign downlink TS=7 [0;m [0;33m<0002> gprs_rlcmac.cpp:1005 Stopping DL TBF=0 timer 3193. [0;m [0;33m<0002> gprs_rlcmac_data.cpp:1837 Send dowlink assignment on PACCH, because DL TBF=0 exists for TLLI=0xcb46771f [0;m [0;33m<0002> gprs_rlcmac.cpp:973 DL TBF=0 changes state from WAIT RELEASE to ASSIGN [0;m [0;33m<0002> gprs_rlcmac.cpp:983 Starting DL TBF=0 timer 0. [0;m [0;33m<0002> gprs_rlcmac.cpp:988 Restarting UL TBF=1 timer 3169 while old timer 3169 pending [0;m [0;33m<0002> gprs_rlcmac_data.cpp:1764 TBF: START TFI: 0 TLLI: 0xcb46771f Packet Downlink Assignment (PACCH) [0;m [0;33m<0002> gprs_rlcmac_data.cpp:1769 +++++++++++++++++++++++++ TX : Packet Downlink Assignment +++++++++++++++++++++++++ [0;m [0;33m<0002> gprs_rlcmac_data.cpp:1772 ------------------------- TX : Packet Downlink Assignment ------------------------- [0;m [0;36m<0006> gprs_rlcmac_sched.cpp:260 Received RTS for PDCH: TRX=0 TS=7 FN=1289730 block_nr=6 scheduling free USF for polling at FN=1289734 of UL TFI=0 [0;m [0;33m<0002> gprs_rlcmac.cpp:988 Restarting UL TBF=1 timer 3169 while old timer 3169 pending [0;m [1;36m<0005> gprs_rlcmac_data.cpp:740 Complete UL frame for TBF=1: len=62 [0;m [1;34m<0008> gprs_rlcmac.cpp:1760 LLC [PCU -> SGSN] TFI: 1 TLLI: 0xcb46771f len=62 [0;m [0;36m<0006> gprs_rlcmac_sched.cpp:260 Received RTS for PDCH: TRX=0 TS=7 FN=1289734 block_nr=7 scheduling free USF for polling at FN=1289738 of DL TFI=0 [0;m [0;33m<0002> gprs_rlcmac.cpp:988 Restarting UL TBF=1 timer 3169 while old timer 3169 pending [0;m [0;33m<0002> gprs_rlcmac.cpp:988 Restarting UL TBF=1 timer 3169 while old timer 3169 pending [0;m [0;33m<0002> gprs_rlcmac.cpp:988 Restarting UL TBF=1 timer 3169 while old timer 3169 pending [0;m [0;33m<0002> gprs_rlcmac_data.cpp:270 +++++++++++++++++++++++++ RX : Uplink Control Block +++++++++++++++++++++++++ [0;m [0;33m<0002> gprs_rlcmac_data.cpp:273 ------------------------- RX : Uplink Control Block ------------------------- [0;m [0;33m<0002> gprs_rlcmac_data.cpp:288 PACKET CONTROL ACK with expected FN=1289738 TLL=0xcb46771f (TRX 0 TS 7) [0;m [0;33m<0002> gprs_rlcmac_data.cpp:297 RX: [PCU <- BTS] TFI: 0 TLLI: 0xcb46771f Packet Control Ack [0;m [0;33m<0002> gprs_rlcmac_data.cpp:316 TBF: [UPLINK] DOWNLINK ASSIGNED TFI: 0 TLLI: 0xcb46771f [0;m [0;33m<0002> gprs_rlcmac.cpp:973 DL TBF=0 changes state from ASSIGN to FLOW [0;m [0;33m<0002> gprs_rlcmac.cpp:1005 Stopping DL TBF=0 timer 0. [0;m [0;33m<0002> gprs_rlcmac.cpp:988 Restarting UL TBF=1 timer 3169 while old timer 3169 pending [0;m [0;33m<0002> gprs_rlcmac.cpp:988 Restarting UL TBF=1 timer 3169 while old timer 3169 pending [0;m [0;33m<0002> gprs_rlcmac.cpp:988 Restarting UL TBF=1 timer 3169 while old timer 3169 pending [0;m [1;33m<0004> gprs_rlcmac_data.cpp:1453 Complete DL frame for TBF=0: len=70 [0;m [0;33m<0002> gprs_rlcmac.cpp:973 DL TBF=0 changes state from FLOW to FINISHED [0;m [0;33m<0002> gprs_rlcmac_data.cpp:1532 Polling sheduled in this TS 7 [0;m [0;33m<0002> gprs_rlcmac.cpp:983 Starting DL TBF=0 timer 3191. [0;m [0;33m<0002> gprs_rlcmac.cpp:988 Restarting UL TBF=1 timer 3169 while old timer 3169 pending [0;m [0;33m<0002> gprs_rlcmac_data.cpp:100 Poll timeout for UL TBF=0 [0;m [0;33m<0002> gprs_rlcmac_data.cpp:119 - N3103 exceeded [0;m [0;33m<0002> gprs_rlcmac.cpp:973 UL TBF=0 changes state from FINISHED to RELEASING [0;m [0;33m<0002> gprs_rlcmac.cpp:988 Restarting UL TBF=0 timer 3169 while old timer 3169 pending [0;m [0;33m<0002> gprs_rlcmac.cpp:988 Restarting UL TBF=1 timer 3169 while old timer 3169 pending [0;m [0;36m<0006> gprs_rlcmac_sched.cpp:260 Received RTS for PDCH: TRX=0 TS=7 FN=1289777 block_nr=5 scheduling free USF for polling at FN=1289782 of DL TFI=0 [0;m [0;33m<0002> gprs_rlcmac.cpp:988 Restarting UL TBF=1 timer 3169 while old timer 3169 pending [0;m [0;33m<0002> gprs_rlcmac.cpp:988 Restarting UL TBF=1 timer 3169 while old timer 3169 pending [0;m [0;33m<0002> gprs_rlcmac.cpp:988 Restarting UL TBF=1 timer 3169 while old timer 3169 pending [0;m [0;33m<0002> gprs_rlcmac.cpp:988 Restarting UL TBF=1 timer 3169 while old timer 3169 pending [0;m [0;33m<0002> gprs_rlcmac_data.cpp:270 +++++++++++++++++++++++++ RX : Uplink Control Block +++++++++++++++++++++++++ [0;m [0;33m<0002> gprs_rlcmac_data.cpp:273 ------------------------- RX : Uplink Control Block ------------------------- [0;m [0;33m<0002> gprs_rlcmac.cpp:1005 Stopping DL TBF=0 timer 3191. [0;m [0;33m<0002> gprs_rlcmac_data.cpp:395 RX: [PCU <- BTS] TFI: 0 TLLI: 0xcb46771f Packet Downlink Ack/Nack [0;m [0;33m<0002> gprs_rlcmac.cpp:983 Starting DL TBF=0 timer 3193. [0;m [0;33m<0002> gprs_rlcmac.cpp:973 DL TBF=0 changes state from FINISHED to WAIT RELEASE [0;m [0;33m<0002> gprs_rlcmac.cpp:988 Restarting UL TBF=1 timer 3169 while old timer 3169 pending [0;m [0;33m<0002> gprs_rlcmac.cpp:988 Restarting UL TBF=1 timer 3169 while old timer 3169 pending [0;m [0;33m<0002> gprs_rlcmac.cpp:988 Restarting UL TBF=1 timer 3169 while old timer 3169 pending [0;m [0;33m<0002> gprs_rlcmac.cpp:988 Restarting UL TBF=1 timer 3169 while old timer 3169 pending [0;m [0;33m<0002> gprs_rlcmac.cpp:988 Restarting UL TBF=1 timer 3169 while old timer 3169 pending [0;m [0;33m<0002> gprs_rlcmac.cpp:988 Restarting UL TBF=1 timer 3169 while old timer 3169 pending [0;m [0;33m<0002> gprs_rlcmac.cpp:988 Restarting UL TBF=1 timer 3169 while old timer 3169 pending [0;m [0;33m<0002> gprs_rlcmac.cpp:988 Restarting UL TBF=1 timer 3169 while old timer 3169 pending [0;m [0;33m<0002> gprs_rlcmac.cpp:988 Restarting UL TBF=1 timer 3169 while old timer 3169 pending [0;m [0;33m<0002> gprs_rlcmac.cpp:988 Restarting UL TBF=1 timer 3169 while old timer 3169 pending [0;m [0;33m<0002> gprs_rlcmac.cpp:988 Restarting UL TBF=1 timer 3169 while old timer 3169 pending [0;m [0;33m<0002> gprs_rlcmac.cpp:988 Restarting UL TBF=1 timer 3169 while old timer 3169 pending [0;m [0;33m<0002> gprs_rlcmac.cpp:988 Restarting UL TBF=1 timer 3169 while old timer 3169 pending [0;m [1;36m<0005> gprs_rlcmac_data.cpp:740 Complete UL frame for TBF=1: len=506 [0;m [1;34m<0008> gprs_rlcmac.cpp:1760 LLC [PCU -> SGSN] TFI: 1 TLLI: 0xcb46771f len=506 [0;m [0;33m<0002> gprs_rlcmac.cpp:988 Restarting UL TBF=1 timer 3169 while old timer 3169 pending [0;m [0;33m<0002> gprs_rlcmac.cpp:988 Restarting UL TBF=1 timer 3169 while old timer 3169 pending [0;m [0;33m<0002> gprs_rlcmac.cpp:988 Restarting UL TBF=1 timer 3169 while old timer 3169 pending [0;m [0;33m<0002> gprs_rlcmac.cpp:988 Restarting UL TBF=1 timer 3169 while old timer 3169 pending [0;m [0;33m<0002> gprs_rlcmac.cpp:988 Restarting UL TBF=1 timer 3169 while old timer 3169 pending [0;m [0;33m<0002> gprs_rlcmac.cpp:988 Restarting UL TBF=1 timer 3169 while old timer 3169 pending [0;m [1;36m<0005> gprs_rlcmac_data.cpp:740 Complete UL frame for TBF=1: len=110 [0;m [1;34m<0008> gprs_rlcmac.cpp:1760 LLC [PCU -> SGSN] TFI: 1 TLLI: 0xcb46771f len=110 [0;m [0;33m<0002> gprs_rlcmac.cpp:988 Restarting UL TBF=1 timer 3169 while old timer 3169 pending [0;m [0;33m<0002> gprs_rlcmac.cpp:988 Restarting UL TBF=1 timer 3169 while old timer 3169 pending [0;m [0;33m<0002> gprs_rlcmac.cpp:988 Restarting UL TBF=1 timer 3169 while old timer 3169 pending [0;m [1;36m<0005> gprs_rlcmac_data.cpp:740 Complete UL frame for TBF=1: len=62 [0;m [1;34m<0008> gprs_rlcmac.cpp:1760 LLC [PCU -> SGSN] TFI: 1 TLLI: 0xcb46771f len=62 [0;m [0;33m<0002> gprs_rlcmac.cpp:988 Restarting UL TBF=1 timer 3169 while old timer 3169 pending [0;m [0;33m<0002> gprs_rlcmac.cpp:988 Restarting UL TBF=1 timer 3169 while old timer 3169 pending [0;m [0;33m<0002> gprs_rlcmac.cpp:988 Restarting UL TBF=1 timer 3169 while old timer 3169 pending [0;m [1;36m<0005> gprs_rlcmac_data.cpp:740 Complete UL frame for TBF=1: len=62 [0;m [1;34m<0008> gprs_rlcmac.cpp:1760 LLC [PCU -> SGSN] TFI: 1 TLLI: 0xcb46771f len=62 [0;m [0;33m<0002> gprs_rlcmac.cpp:973 UL TBF=1 changes state from FLOW to FINISHED [0;m [0;33m<0002> gprs_rlcmac.cpp:988 Restarting UL TBF=1 timer 3169 while old timer 3169 pending [0;m [0;33m<0002> gprs_rlcmac.cpp:988 Restarting UL TBF=1 timer 3169 while old timer 3169 pending [0;m [0;36m<0006> gprs_rlcmac_sched.cpp:260 Received RTS for PDCH: TRX=0 TS=7 FN=1289916 block_nr=1 scheduling free USF for polling at FN=1289920 of UL TFI=1 [0;m [0;33m<0002> gprs_rlcmac.cpp:988 Restarting UL TBF=1 timer 3169 while old timer 3169 pending [0;m [0;33m<0002> gprs_rlcmac.cpp:988 Restarting UL TBF=1 timer 3169 while old timer 3169 pending [0;m [0;33m<0002> gprs_rlcmac_data.cpp:270 +++++++++++++++++++++++++ RX : Uplink Control Block +++++++++++++++++++++++++ [0;m [0;33m<0002> gprs_rlcmac_data.cpp:273 ------------------------- RX : Uplink Control Block ------------------------- [0;m [0;33m<0002> gprs_rlcmac_data.cpp:288 PACKET CONTROL ACK with expected FN=1289920 TLL=0xcb46771f (TRX 0 TS 7) [0;m [0;33m<0002> gprs_rlcmac_data.cpp:297 RX: [PCU <- BTS] TFI: 1 TLLI: 0xcb46771f Packet Control Ack [0;m [0;33m<0002> gprs_rlcmac_data.cpp:302 TBF: [UPLINK] END TFI: 1 TLLI: 0xcb46771f [0;m [0;33m<0002> gprs_rlcmac.cpp:895 Free UL TBF=1 with TLLI=0xcb46771f. [0;m [0;33m<0002> gprs_rlcmac.cpp:1005 Stopping UL TBF=1 timer 3169. [0;m [0;33m<0002> gprs_rlcmac.cpp:911 ********** TBF ends here ********** [0;m [1;34m<0008> gprs_bssgp_pcu.cpp:145 LLC [SGSN -> PCU] = TLLI: 0xcb46771f IMSI: 452022112638582 len: 62 [0;m [0;33m<0002> gprs_bssgp_pcu.cpp:149 TBF: APPEND TFI: 0 TLLI: 0xcb46771f [0;m [0;33m<0002> gprs_bssgp_pcu.cpp:152 TBF in WAIT RELEASE state (T3193), so reuse TBF [0;m [0;33m<0002> gprs_rlcmac.cpp:921 ********** TBF update ********** [0;m [0;33m<0002> gprs_rlcmac.cpp:421 Slot Allocation (Algorithm A) for class 10 [0;m [0;33m<0002> gprs_rlcmac.cpp:444 - Assign downlink TS=7 [0;m [0;33m<0002> gprs_rlcmac.cpp:1005 Stopping DL TBF=0 timer 3193. [0;m [0;33m<0002> gprs_rlcmac_data.cpp:1837 Send dowlink assignment on PACCH, because DL TBF=0 exists for TLLI=0xcb46771f [0;m [0;33m<0002> gprs_rlcmac.cpp:973 DL TBF=0 changes state from WAIT RELEASE to ASSIGN [0;m [0;33m<0002> gprs_rlcmac.cpp:983 Starting DL TBF=0 timer 0. [0;m [1;34m<0008> gprs_bssgp_pcu.cpp:145 LLC [SGSN -> PCU] = TLLI: 0xcb46771f IMSI: 452022112638582 len: 454 [0;m [0;33m<0002> gprs_bssgp_pcu.cpp:149 TBF: APPEND TFI: 0 TLLI: 0xcb46771f [0;m [0;33m<0002> gprs_rlcmac_data.cpp:1764 TBF: START TFI: 0 TLLI: 0xcb46771f Packet Downlink Assignment (PACCH) [0;m [0;33m<0002> gprs_rlcmac_data.cpp:1769 +++++++++++++++++++++++++ TX : Packet Downlink Assignment +++++++++++++++++++++++++ [0;m [0;33m<0002> gprs_rlcmac_data.cpp:1772 ------------------------- TX : Packet Downlink Assignment ------------------------- [0;m [0;36m<0006> gprs_rlcmac_sched.cpp:260 Received RTS for PDCH: TRX=0 TS=7 FN=1289959 block_nr=11 scheduling free USF for polling at FN=1289964 of DL TFI=0 [0;m [0;33m<0002> gprs_rlcmac_data.cpp:100 Poll timeout for DL TBF=0 [0;m [0;33m<0002> gprs_rlcmac_data.cpp:158 - Timeout for polling PACKET CONTROL ACK for PACKET DOWNLINK ASSIGNMENT. [0;m [0;33m<0002> gprs_rlcmac_data.cpp:84 - Assignment was on PACCH [0;m [0;33m<0002> gprs_rlcmac_data.cpp:92 - No downlink ACK received yet [0;m [0;33m<0002> gprs_rlcmac_data.cpp:1764 TBF: START TFI: 0 TLLI: 0xcb46771f Packet Downlink Assignment (PACCH) [0;m [0;33m<0002> gprs_rlcmac_data.cpp:1769 +++++++++++++++++++++++++ TX : Packet Downlink Assignment +++++++++++++++++++++++++ [0;m [0;33m<0002> gprs_rlcmac_data.cpp:1772 ------------------------- TX : Packet Downlink Assignment ------------------------- [0;m [0;36m<0006> gprs_rlcmac_sched.cpp:260 Received RTS for PDCH: TRX=0 TS=7 FN=1290024 block_nr=2 scheduling free USF for polling at FN=1290029 of DL TFI=0 [0;m [0;33m<0002> gprs_rlcmac_data.cpp:100 Poll timeout for DL TBF=0 [0;m [0;33m<0002> gprs_rlcmac_data.cpp:1764 TBF: START TFI: 0 TLLI: 0xcb46771f Packet Downlink Assignment (PACCH) [0;m [0;33m<0002> gprs_rlcmac_data.cpp:1769 +++++++++++++++++++++++++ TX : Packet Downlink Assignment +++++++++++++++++++++++++ [0;m [0;33m<0002> gprs_rlcmac_data.cpp:1772 ------------------------- TX : Packet Downlink Assignment ------------------------- [0;m [0;36m<0006> gprs_rlcmac_sched.cpp:260 Received RTS for PDCH: TRX=0 TS=7 FN=1290141 block_nr=5 scheduling free USF for polling at FN=1290146 of DL TFI=0 [0;m [0;33m<0002> gprs_rlcmac_data.cpp:100 Poll timeout for DL TBF=0 [0;m [0;33m<0002> gprs_rlcmac_data.cpp:1764 TBF: START TFI: 0 TLLI: 0xcb46771f Packet Downlink Assignment (PACCH) [0;m [0;33m<0002> gprs_rlcmac_data.cpp:1769 +++++++++++++++++++++++++ TX : Packet Downlink Assignment +++++++++++++++++++++++++ [0;m [0;33m<0002> gprs_rlcmac_data.cpp:1772 ------------------------- TX : Packet Downlink Assignment ------------------------- [0;m [0;36m<0006> gprs_rlcmac_sched.cpp:260 Received RTS for PDCH: TRX=0 TS=7 FN=1290193 block_nr=5 scheduling free USF for polling at FN=1290198 of DL TFI=0 [0;m [0;33m<0002> gprs_rlcmac_data.cpp:100 Poll timeout for DL TBF=0 [0;m [0;33m<0002> gprs_rlcmac_data.cpp:1764 TBF: START TFI: 0 TLLI: 0xcb46771f Packet Downlink Assignment (PACCH) [0;m [0;33m<0002> gprs_rlcmac_data.cpp:1769 +++++++++++++++++++++++++ TX : Packet Downlink Assignment +++++++++++++++++++++++++ [0;m [0;33m<0002> gprs_rlcmac_data.cpp:1772 ------------------------- TX : Packet Downlink Assignment ------------------------- [0;m [0;36m<0006> gprs_rlcmac_sched.cpp:260 Received RTS for PDCH: TRX=0 TS=7 FN=1290237 block_nr=3 scheduling free USF for polling at FN=1290241 of DL TFI=0 [0;m [0;33m<0002> gprs_rlcmac_data.cpp:100 Poll timeout for DL TBF=0 [0;m [0;33m<0002> gprs_rlcmac_data.cpp:1764 TBF: START TFI: 0 TLLI: 0xcb46771f Packet Downlink Assignment (PACCH) [0;m [0;33m<0002> gprs_rlcmac_data.cpp:1769 +++++++++++++++++++++++++ TX : Packet Downlink Assignment +++++++++++++++++++++++++ [0;m [0;33m<0002> gprs_rlcmac_data.cpp:1772 ------------------------- TX : Packet Downlink Assignment ------------------------- [0;m [0;36m<0006> gprs_rlcmac_sched.cpp:260 Received RTS for PDCH: TRX=0 TS=7 FN=1290328 block_nr=0 scheduling free USF for polling at FN=1290332 of DL TFI=0 [0;m [0;33m<0002> gprs_rlcmac_data.cpp:501 DL TBF=0 timer 0 expired. [0;m [0;33m<0002> gprs_rlcmac_data.cpp:515 Releasing due to PACCH assignment timeout. [0;m [0;33m<0002> gprs_rlcmac.cpp:895 Free DL TBF=0 with TLLI=0xcb46771f. [0;m [0;33m<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! [0;m [0;33m<0002> gprs_rlcmac.cpp:911 ********** TBF ends here ********** [0;m [1;32m<0001> pcu_l1_if.cpp:256 RACH request received: sapi=1 qta=0, ra=116, fn=1290786 [0;m [0;33m<0002> gprs_rlcmac_data.cpp:1116 MS requests UL TBF on RACH, so we provide one: [0;m [0;33m<0002> gprs_rlcmac_data.cpp:1119 MS requests single block allocation [0;m [0;33m<0002> gprs_rlcmac_data.cpp:1136 RX: [PCU <- BTS] RACH qbit-ta=0 ra=0x74, Fn=1290786 (13,27,16) [0;m [0;33m<0002> gprs_rlcmac_data.cpp:1138 TX: Immediate Assignment Uplink (AGCH) [0;m [0;33m<0002> gprs_rlcmac_data.cpp:501 UL TBF=0 timer 3169 expired. [0;m [0;33m<0002> gprs_rlcmac_data.cpp:536 TBF T3169 timeout during transsmission [0;m [0;33m<0002> gprs_rlcmac_data.cpp:84 - Assignment was on PACCH [0;m [0;33m<0002> gprs_rlcmac_data.cpp:86 - Uplink data was received [0;m [0;33m<0002> gprs_rlcmac_data.cpp:542 TBF will be freed due to timeout [0;m [0;33m<0002> gprs_rlcmac.cpp:895 Free UL TBF=0 with TLLI=0xcb46771f. [0;m [0;33m<0002> gprs_rlcmac.cpp:911 ********** TBF ends here ********** [0;m [0;33m<0002> gprs_rlcmac_data.cpp:270 +++++++++++++++++++++++++ RX : Uplink Control Block +++++++++++++++++++++++++ [0;m [0;33m<0002> gprs_rlcmac_data.cpp:273 ------------------------- RX : Uplink Control Block ------------------------- [0;m [0;33m<0002> gprs_rlcmac_data.cpp:442 MS requests UL TBF in packet ressource request of single block, so we provide one: [0;m [0;33m<0002> gprs_rlcmac.cpp:214 Searching for first unallocated TFI: TRX=0 first TS=7 [0;m [0;33m<0002> gprs_rlcmac.cpp:225 Found TFI=0. [0;m [0;33m<0002> gprs_rlcmac.cpp:351 ********** TBF starts here ********** [0;m [0;33m<0002> gprs_rlcmac.cpp:354 Allocating UL TBF: TFI=0 TRX=0 MS_CLASS=10 [0;m [0;33m<0002> gprs_rlcmac.cpp:421 Slot Allocation (Algorithm A) for class 10 [0;m [0;33m<0002> gprs_rlcmac.cpp:434 - Assign uplink TS=7 USF=0 [0;m [0;33m<0002> gprs_rlcmac.cpp:948 - Setting Control TS 7 [0;m [0;33m<0002> gprs_rlcmac.cpp:973 UL TBF=0 changes state from NULL to ASSIGN [0;m [0;33m<0002> gprs_rlcmac.cpp:983 Starting UL TBF=0 timer 3169. [0;m [0;33m<0002> gprs_rlcmac_data.cpp:452 Change control TS to 7 until assinment is complete. [0;m [0;33m<0002> gprs_rlcmac_data.cpp:1069 TBF: START TFI: 0 TLLI: 0xcb46771f Packet Uplink Assignment (PACCH) [0;m [0;33m<0002> gprs_rlcmac_data.cpp:1083 +++++++++++++++++++++++++ TX : Packet Uplink Assignment +++++++++++++++++++++++++ [0;m [0;33m<0002> gprs_rlcmac_data.cpp:1086 ------------------------- TX : Packet Uplink Assignment ------------------------- [0;m [0;36m<0006> gprs_rlcmac_sched.cpp:260 Received RTS for PDCH: TRX=0 TS=7 FN=1290874 block_nr=6 scheduling free USF for polling at FN=1290878 of UL TFI=0 [0;m [0;33m<0002> gprs_rlcmac_data.cpp:270 +++++++++++++++++++++++++ RX : Uplink Control Block +++++++++++++++++++++++++ [0;m [0;33m<0002> gprs_rlcmac_data.cpp:273 ------------------------- RX : Uplink Control Block ------------------------- [0;m [0;33m<0002> gprs_rlcmac_data.cpp:288 PACKET CONTROL ACK with expected FN=1290878 TLL=0xcb46771f (TRX 0 TS 7) [0;m [0;33m<0002> gprs_rlcmac_data.cpp:297 RX: [PCU <- BTS] TFI: 0 TLLI: 0xcb46771f Packet Control Ack [0;m [0;33m<0002> gprs_rlcmac_data.cpp:343 TBF: [DOWNLINK] UPLINK ASSIGNED TFI: 0 TLLI: 0xcb46771f [0;m [0;33m<0002> gprs_rlcmac.cpp:973 UL TBF=0 changes state from ASSIGN to FLOW [0;m [0;33m<0002> gprs_rlcmac.cpp:988 Restarting UL TBF=0 timer 3169 while old timer 3169 pending [0;m [0;33m<0002> gprs_rlcmac.cpp:988 Restarting UL TBF=0 timer 3169 while old timer 3169 pending [0;m [0;33m<0002> gprs_rlcmac.cpp:988 Restarting UL TBF=0 timer 3169 while old timer 3169 pending [0;m [0;33m<0002> gprs_rlcmac.cpp:988 Restarting UL TBF=0 timer 3169 while old timer 3169 pending [0;m [0;33m<0002> gprs_rlcmac.cpp:988 Restarting UL TBF=0 timer 3169 while old timer 3169 pending [0;m [0;33m<0002> gprs_rlcmac.cpp:988 Restarting UL TBF=0 timer 3169 while old timer 3169 pending [0;m [0;33m<0002> gprs_rlcmac.cpp:988 Restarting UL TBF=0 timer 3169 while old timer 3169 pending [0;m [0;33m<0002> gprs_rlcmac.cpp:988 Restarting UL TBF=0 timer 3169 while old timer 3169 pending [0;m [0;33m<0002> gprs_rlcmac.cpp:988 Restarting UL TBF=0 timer 3169 while old timer 3169 pending [0;m [0;33m<0002> gprs_rlcmac.cpp:988 Restarting UL TBF=0 timer 3169 while old timer 3169 pending [0;m [0;33m<0002> gprs_rlcmac.cpp:988 Restarting UL TBF=0 timer 3169 while old timer 3169 pending [0;m [0;33m<0002> gprs_rlcmac.cpp:988 Restarting UL TBF=0 timer 3169 while old timer 3169 pending [0;m [0;33m<0002> gprs_rlcmac.cpp:988 Restarting UL TBF=0 timer 3169 while old timer 3169 pending [0;m [0;33m<0002> gprs_rlcmac.cpp:988 Restarting UL TBF=0 timer 3169 while old timer 3169 pending [0;m [0;33m<0002> gprs_rlcmac.cpp:988 Restarting UL TBF=0 timer 3169 while old timer 3169 pending [0;m [1;34m<0008> gprs_bssgp_pcu.cpp:145 LLC [SGSN -> PCU] = TLLI: 0xcb46771f IMSI: 452022112638582 len: 454 [0;m [0;33m<0002> gprs_rlcmac.cpp:214 Searching for first unallocated TFI: TRX=0 first TS=7 [0;m [0;33m<0002> gprs_rlcmac.cpp:225 Found TFI=0. [0;m [0;33m<0002> gprs_rlcmac.cpp:351 ********** TBF starts here ********** [0;m [0;33m<0002> gprs_rlcmac.cpp:354 Allocating DL TBF: TFI=0 TRX=0 MS_CLASS=10 [0;m [0;33m<0002> gprs_rlcmac.cpp:421 Slot Allocation (Algorithm A) for class 10 [0;m [0;33m<0002> gprs_rlcmac.cpp:444 - Assign downlink TS=7 [0;m [0;33m<0002> gprs_rlcmac.cpp:948 - Setting Control TS 7 [0;m [0;33m<0002> gprs_bssgp_pcu.cpp:233 TBF: [DOWNLINK] START TFI: 0 TLLI: 0xcb46771f [0;m [0;33m<0002> gprs_rlcmac_data.cpp:1837 Send dowlink assignment on PACCH, because UL TBF=0 exists for TLLI=0xcb46771f [0;m [0;33m<0002> gprs_rlcmac.cpp:973 DL TBF=0 changes state from NULL to ASSIGN [0;m [0;33m<0002> gprs_rlcmac.cpp:983 Starting DL TBF=0 timer 0. [0;m [0;33m<0002> gprs_rlcmac.cpp:988 Restarting UL TBF=0 timer 3169 while old timer 3169 pending [0;m [0;33m<0002> gprs_rlcmac_data.cpp:1764 TBF: START TFI: 0 TLLI: 0xcb46771f Packet Downlink Assignment (PACCH) [0;m [0;33m<0002> gprs_rlcmac_data.cpp:1769 +++++++++++++++++++++++++ TX : Packet Downlink Assignment +++++++++++++++++++++++++ [0;m [0;33m<0002> gprs_rlcmac_data.cpp:1772 ------------------------- TX : Packet Downlink Assignment ------------------------- [0;m [0;33m<0002> gprs_rlcmac.cpp:988 Restarting UL TBF=0 timer 3169 while old timer 3169 pending [0;m [0;33m<0002> gprs_rlcmac.cpp:988 Restarting UL TBF=0 timer 3169 while old timer 3169 pending [0;m [0;36m<0006> gprs_rlcmac_sched.cpp:260 Received RTS for PDCH: TRX=0 TS=7 FN=1290991 block_nr=9 scheduling free USF for polling at FN=1290995 of UL TFI=0 [0;m [0;33m<0002> gprs_rlcmac.cpp:988 Restarting UL TBF=0 timer 3169 while old timer 3169 pending [0;m [0;33m<0002> gprs_rlcmac.cpp:988 Restarting UL TBF=0 timer 3169 while old timer 3169 pending [0;m [0;33m<0002> gprs_rlcmac.cpp:988 Restarting UL TBF=0 timer 3169 while old timer 3169 pending [0;m [0;33m<0002> gprs_rlcmac.cpp:988 Restarting UL TBF=0 timer 3169 while old timer 3169 pending [0;m [0;33m<0002> gprs_rlcmac_data.cpp:270 +++++++++++++++++++++++++ RX : Uplink Control Block +++++++++++++++++++++++++ [0;m [0;33m<0002> gprs_rlcmac_data.cpp:273 ------------------------- RX : Uplink Control Block ------------------------- [0;m [0;33m<0002> gprs_rlcmac_data.cpp:288 PACKET CONTROL ACK with expected FN=1290995 TLL=0xcb46771f (TRX 0 TS 7) [0;m [0;33m<0002> gprs_rlcmac_data.cpp:297 RX: [PCU <- BTS] TFI: 0 TLLI: 0xcb46771f Packet Control Ack [0;m [0;33m<0002> gprs_rlcmac_data.cpp:316 TBF: [UPLINK] DOWNLINK ASSIGNED TFI: 0 TLLI: 0xcb46771f [0;m [0;33m<0002> gprs_rlcmac.cpp:973 DL TBF=0 changes state from ASSIGN to FLOW [0;m [0;33m<0002> gprs_rlcmac.cpp:1005 Stopping DL TBF=0 timer 0. [0;m [0;33m<0002> gprs_rlcmac.cpp:988 Restarting UL TBF=0 timer 3169 while old timer 3169 pending [0;m [0;33m<0002> gprs_rlcmac.cpp:988 Restarting UL TBF=0 timer 3169 while old timer 3169 pending [0;m [0;33m<0002> gprs_rlcmac.cpp:988 Restarting UL TBF=0 timer 3169 while old timer 3169 pending [0;m [0;33m<0002> gprs_rlcmac.cpp:988 Restarting UL TBF=0 timer 3169 while old timer 3169 pending [0;m [1;36m<0005> gprs_rlcmac_data.cpp:740 Complete UL frame for TBF=0: len=506 [0;m [1;34m<0008> gprs_rlcmac.cpp:1760 LLC [PCU -> SGSN] TFI: 0 TLLI: 0xcb46771f len=506 [0;m [0;33m<0002> gprs_rlcmac.cpp:988 Restarting UL TBF=0 timer 3169 while old timer 3169 pending [0;m [0;33m<0002> gprs_rlcmac.cpp:988 Restarting UL TBF=0 timer 3169 while old timer 3169 pending [0;m [0;33m<0002> gprs_rlcmac.cpp:988 Restarting UL TBF=0 timer 3169 while old timer 3169 pending [0;m [0;33m<0002> gprs_rlcmac.cpp:988 Restarting UL TBF=0 timer 3169 while old timer 3169 pending [0;m [0;33m<0002> gprs_rlcmac.cpp:988 Restarting UL TBF=0 timer 3169 while old timer 3169 pending [0;m [1;36m<0005> gprs_rlcmac_data.cpp:740 Complete UL frame for TBF=0: len=110 [0;m [1;34m<0008> gprs_rlcmac.cpp:1760 LLC [PCU -> SGSN] TFI: 0 TLLI: 0xcb46771f len=110 [0;m [0;33m<0002> gprs_rlcmac.cpp:973 UL TBF=0 changes state from FLOW to FINISHED [0;m [0;33m<0002> gprs_rlcmac.cpp:988 Restarting UL TBF=0 timer 3169 while old timer 3169 pending [0;m [0;33m<0002> gprs_rlcmac.cpp:988 Restarting UL TBF=0 timer 3169 while old timer 3169 pending [0;m [0;36m<0006> gprs_rlcmac_sched.cpp:260 Received RTS for PDCH: TRX=0 TS=7 FN=1291060 block_nr=1 scheduling free USF for polling at FN=1291064 of UL TFI=0 [0;m [0;33m<0002> gprs_rlcmac.cpp:988 Restarting UL TBF=0 timer 3169 while old timer 3169 pending [0;m [0;33m<0002> gprs_rlcmac.cpp:988 Restarting UL TBF=0 timer 3169 while old timer 3169 pending [0;m [0;33m<0002> gprs_rlcmac_data.cpp:270 +++++++++++++++++++++++++ RX : Uplink Control Block +++++++++++++++++++++++++ [0;m [0;33m<0002> gprs_rlcmac_data.cpp:273 ------------------------- RX : Uplink Control Block ------------------------- [0;m [0;33m<0002> gprs_rlcmac_data.cpp:288 PACKET CONTROL ACK with expected FN=1291064 TLL=0xcb46771f (TRX 0 TS 7) [0;m [0;33m<0002> gprs_rlcmac_data.cpp:297 RX: [PCU <- BTS] TFI: 0 TLLI: 0xcb46771f Packet Control Ack [0;m [0;33m<0002> gprs_rlcmac_data.cpp:302 TBF: [UPLINK] END TFI: 0 TLLI: 0xcb46771f [0;m [0;33m<0002> gprs_rlcmac.cpp:895 Free UL TBF=0 with TLLI=0xcb46771f. [0;m [0;33m<0002> gprs_rlcmac.cpp:1005 Stopping UL TBF=0 timer 3169. [0;m [0;33m<0002> gprs_rlcmac.cpp:911 ********** TBF ends here ********** [0;m [0;33m<0002> gprs_rlcmac_data.cpp:1532 Polling sheduled in this TS 7 [0;m [0;36m<0006> gprs_rlcmac_sched.cpp:260 Received RTS for PDCH: TRX=0 TS=7 FN=1291112 block_nr=1 scheduling free USF for polling at FN=1291116 of DL TFI=0 [0;m [1;33m<0004> gprs_rlcmac_data.cpp:1453 Complete DL frame for TBF=0: len=454 [0;m [0;33m<0002> gprs_rlcmac.cpp:973 DL TBF=0 changes state from FLOW to FINISHED [0;m [0;33m<0002> gprs_rlcmac_data.cpp:1521 Polling is already sheduled for TBF=0, so we must wait for requesting downlink ack [0;m [1;34m<0008> gprs_bssgp_pcu.cpp:145 LLC [SGSN -> PCU] = TLLI: 0xcb46771f IMSI: 452022112638582 len: 62 [0;m [0;33m<0002> gprs_bssgp_pcu.cpp:149 TBF: APPEND TFI: 0 TLLI: 0xcb46771f [0;m [0;33m<0002> gprs_rlcmac_data.cpp:270 +++++++++++++++++++++++++ RX : Uplink Control Block +++++++++++++++++++++++++ [0;m [0;33m<0002> gprs_rlcmac_data.cpp:273 ------------------------- RX : Uplink Control Block ------------------------- [0;m [0;33m<0002> gprs_rlcmac_data.cpp:395 RX: [PCU <- BTS] TFI: 0 TLLI: 0xcb46771f Packet Downlink Ack/Nack [0;m [0;33m<0002> gprs_rlcmac_data.cpp:1532 Polling sheduled in this TS 7 [0;m [0;36m<0006> gprs_rlcmac_sched.cpp:260 Received RTS for PDCH: TRX=0 TS=7 FN=1291203 block_nr=10 scheduling free USF for polling at FN=1291207 of DL TFI=0 [0;m [0;33m<0002> gprs_rlcmac_data.cpp:270 +++++++++++++++++++++++++ RX : Uplink Control Block +++++++++++++++++++++++++ [0;m [0;33m<0002> gprs_rlcmac_data.cpp:273 ------------------------- RX : Uplink Control Block ------------------------- [0;m [0;33m<0002> gprs_rlcmac_data.cpp:376 PACKET DOWNLINK ACK with unknown FN=1291203 TFI=0 (TRX 0 TS 7) [0;m [0;33m<0002> gprs_rlcmac_data.cpp:100 Poll timeout for DL TBF=0 [0;m [0;33m<0002> gprs_rlcmac_data.cpp:180 - Timeout for polling PACKET DOWNLINK ACK. [0;m [0;33m<0002> gprs_rlcmac_data.cpp:84 - Assignment was on PACCH [0;m [0;33m<0002> gprs_rlcmac_data.cpp:90 - Downlink ACK was received [0;m [0;33m<0002> gprs_rlcmac_data.cpp:1532 Polling sheduled in this TS 7 [0;m [0;36m<0006> gprs_rlcmac_sched.cpp:260 Received RTS for PDCH: TRX=0 TS=7 FN=1291290 block_nr=6 scheduling free USF for polling at FN=1291294 of DL TFI=0 [0;m [0;33m<0002> gprs_rlcmac_data.cpp:270 +++++++++++++++++++++++++ RX : Uplink Control Block +++++++++++++++++++++++++ [0;m [0;33m<0002> gprs_rlcmac_data.cpp:273 ------------------------- RX : Uplink Control Block ------------------------- [0;m [0;33m<0002> gprs_rlcmac_data.cpp:388 Recovered downlink ack for DL TBF=0 [0;m [0;33m<0002> gprs_rlcmac_data.cpp:395 RX: [PCU <- BTS] TFI: 0 TLLI: 0xcb46771f Packet Downlink Ack/Nack [0;m [1;33m<0004> gprs_rlcmac_data.cpp:1660 Received acknowledge of all blocks, but without final ack inidcation (don't worry) [0;m [0;33m<0002> gprs_rlcmac_data.cpp:1532 Polling sheduled in this TS 7 [0;m [0;33m<0002> gprs_rlcmac.cpp:983 Starting DL TBF=0 timer 3191. [0;m [0;36m<0006> gprs_rlcmac_sched.cpp:260 Received RTS for PDCH: TRX=0 TS=7 FN=1291376 block_nr=2 scheduling free USF for polling at FN=1291381 of DL TFI=0 [0;m [0;33m<0002> gprs_rlcmac_data.cpp:270 +++++++++++++++++++++++++ RX : Uplink Control Block +++++++++++++++++++++++++ [0;m [0;33m<0002> gprs_rlcmac_data.cpp:273 ------------------------- RX : Uplink Control Block ------------------------- [0;m [0;33m<0002> gprs_rlcmac.cpp:1005 Stopping DL TBF=0 timer 3191. [0;m [0;33m<0002> gprs_rlcmac_data.cpp:395 RX: [PCU <- BTS] TFI: 0 TLLI: 0xcb46771f Packet Downlink Ack/Nack [0;m [0;33m<0002> gprs_rlcmac_data.cpp:1692 Trigger dowlink assignment on PACCH, because another LLC PDU has arrived in between [0;m [0;33m<0002> gprs_rlcmac.cpp:921 ********** TBF update ********** [0;m [0;33m<0002> gprs_rlcmac.cpp:421 Slot Allocation (Algorithm A) for class 10 [0;m [0;33m<0002> gprs_rlcmac.cpp:444 - Assign downlink TS=7 [0;m [0;33m<0002> gprs_rlcmac_data.cpp:1837 Send dowlink assignment on PACCH, because DL TBF=0 exists for TLLI=0xcb46771f [0;m [0;33m<0002> gprs_rlcmac.cpp:973 DL TBF=0 changes state from FINISHED to ASSIGN [0;m [0;33m<0002> gprs_rlcmac.cpp:983 Starting DL TBF=0 timer 0. [0;m [0;33m<0002> gprs_rlcmac_data.cpp:1764 TBF: START TFI: 0 TLLI: 0xcb46771f Packet Downlink Assignment (PACCH) [0;m [0;33m<0002> gprs_rlcmac_data.cpp:1769 +++++++++++++++++++++++++ TX : Packet Downlink Assignment +++++++++++++++++++++++++ [0;m [0;33m<0002> gprs_rlcmac_data.cpp:1772 ------------------------- TX : Packet Downlink Assignment ------------------------- [0;m [0;36m<0006> gprs_rlcmac_sched.cpp:260 Received RTS for PDCH: TRX=0 TS=7 FN=1291407 block_nr=9 scheduling free USF for polling at FN=1291411 of DL TFI=0 [0;m [0;33m<0002> gprs_rlcmac_data.cpp:270 +++++++++++++++++++++++++ RX : Uplink Control Block +++++++++++++++++++++++++ [0;m [0;33m<0002> gprs_rlcmac_data.cpp:273 ------------------------- RX : Uplink Control Block ------------------------- [0;m [0;33m<0002> gprs_rlcmac_data.cpp:288 PACKET CONTROL ACK with expected FN=1291411 TLL=0xcb46771f (TRX 0 TS 7) [0;m [0;33m<0002> gprs_rlcmac_data.cpp:297 RX: [PCU <- BTS] TFI: 0 TLLI: 0xcb46771f Packet Control Ack [0;m [0;33m<0002> gprs_rlcmac_data.cpp:316 TBF: [UPLINK] DOWNLINK ASSIGNED TFI: 0 TLLI: 0xcb46771f [0;m [0;33m<0002> gprs_rlcmac.cpp:973 DL TBF=0 changes state from ASSIGN to FLOW [0;m [0;33m<0002> gprs_rlcmac.cpp:1005 Stopping DL TBF=0 timer 0. [0;m [1;33m<0004> gprs_rlcmac_data.cpp:1453 Complete DL frame for TBF=0: len=62 [0;m [0;33m<0002> gprs_rlcmac.cpp:973 DL TBF=0 changes state from FLOW to FINISHED [0;m [0;33m<0002> gprs_rlcmac_data.cpp:1532 Polling sheduled in this TS 7 [0;m [0;33m<0002> gprs_rlcmac.cpp:983 Starting DL TBF=0 timer 3191. [0;m [0;36m<0006> gprs_rlcmac_sched.cpp:260 Received RTS for PDCH: TRX=0 TS=7 FN=1291450 block_nr=7 scheduling free USF for polling at FN=1291454 of DL TFI=0 [0;m [0;33m<0002> gprs_rlcmac_data.cpp:270 +++++++++++++++++++++++++ RX : Uplink Control Block +++++++++++++++++++++++++ [0;m [0;33m<0002> gprs_rlcmac_data.cpp:273 ------------------------- RX : Uplink Control Block ------------------------- [0;m [0;33m<0002> gprs_rlcmac.cpp:1005 Stopping DL TBF=0 timer 3191. [0;m [0;33m<0002> gprs_rlcmac_data.cpp:395 RX: [PCU <- BTS] TFI: 0 TLLI: 0xcb46771f Packet Downlink Ack/Nack [0;m [0;33m<0002> gprs_rlcmac.cpp:983 Starting DL TBF=0 timer 3193. [0;m [0;33m<0002> gprs_rlcmac.cpp:973 DL TBF=0 changes state from FINISHED to WAIT RELEASE [0;m [1;32m<0001> pcu_l1_if.cpp:256 RACH request received: sapi=1 qta=0, ra=117, fn=1291621 [0;m [0;33m<0002> gprs_rlcmac_data.cpp:1116 MS requests UL TBF on RACH, so we provide one: [0;m [0;33m<0002> gprs_rlcmac_data.cpp:1119 MS requests single block allocation [0;m [0;33m<0002> gprs_rlcmac_data.cpp:1136 RX: [PCU <- BTS] RACH qbit-ta=0 ra=0x75, Fn=1291621 (14,46,19) [0;m [0;33m<0002> gprs_rlcmac_data.cpp:1138 TX: Immediate Assignment Uplink (AGCH) [0;m [0;33m<0002> gprs_rlcmac_data.cpp:501 DL TBF=0 timer 3193 expired. [0;m [0;33m<0002> gprs_rlcmac_data.cpp:542 TBF will be freed due to timeout [0;m [0;33m<0002> gprs_rlcmac.cpp:895 Free DL TBF=0 with TLLI=0xcb46771f. [0;m [0;33m<0002> gprs_rlcmac.cpp:911 ********** TBF ends here ********** [0;m [0;33m<0002> gprs_rlcmac_data.cpp:270 +++++++++++++++++++++++++ RX : Uplink Control Block +++++++++++++++++++++++++ [0;m [0;33m<0002> gprs_rlcmac_data.cpp:273 ------------------------- RX : Uplink Control Block ------------------------- [0;m [0;33m<0002> gprs_rlcmac_data.cpp:442 MS requests UL TBF in packet ressource request of single block, so we provide one: [0;m [0;33m<0002> gprs_rlcmac.cpp:214 Searching for first unallocated TFI: TRX=0 first TS=7 [0;m [0;33m<0002> gprs_rlcmac.cpp:225 Found TFI=0. [0;m [0;33m<0002> gprs_rlcmac.cpp:351 ********** TBF starts here ********** [0;m [0;33m<0002> gprs_rlcmac.cpp:354 Allocating UL TBF: TFI=0 TRX=0 MS_CLASS=10 [0;m [0;33m<0002> gprs_rlcmac.cpp:421 Slot Allocation (Algorithm A) for class 10 [0;m [0;33m<0002> gprs_rlcmac.cpp:434 - Assign uplink TS=7 USF=0 [0;m [0;33m<0002> gprs_rlcmac.cpp:948 - Setting Control TS 7 [0;m [0;33m<0002> gprs_rlcmac.cpp:973 UL TBF=0 changes state from NULL to ASSIGN [0;m [0;33m<0002> gprs_rlcmac.cpp:983 Starting UL TBF=0 timer 3169. [0;m [0;33m<0002> gprs_rlcmac_data.cpp:452 Change control TS to 7 until assinment is complete. [0;m [0;33m<0002> gprs_rlcmac_data.cpp:1069 TBF: START TFI: 0 TLLI: 0xcb46771f Packet Uplink Assignment (PACCH) [0;m [0;33m<0002> gprs_rlcmac_data.cpp:1083 +++++++++++++++++++++++++ TX : Packet Uplink Assignment +++++++++++++++++++++++++ [0;m [0;33m<0002> gprs_rlcmac_data.cpp:1086 ------------------------- TX : Packet Uplink Assignment ------------------------- [0;m [0;36m<0006> gprs_rlcmac_sched.cpp:260 Received RTS for PDCH: TRX=0 TS=7 FN=1291706 block_nr=6 scheduling free USF for polling at FN=1291710 of UL TFI=0 [0;m [0;33m<0002> gprs_rlcmac_data.cpp:270 +++++++++++++++++++++++++ RX : Uplink Control Block +++++++++++++++++++++++++ [0;m [0;33m<0002> gprs_rlcmac_data.cpp:273 ------------------------- RX : Uplink Control Block ------------------------- [0;m [0;33m<0002> gprs_rlcmac_data.cpp:288 PACKET CONTROL ACK with expected FN=1291710 TLL=0xcb46771f (TRX 0 TS 7) [0;m [0;33m<0002> gprs_rlcmac_data.cpp:297 RX: [PCU <- BTS] TFI: 0 TLLI: 0xcb46771f Packet Control Ack [0;m [0;33m<0002> gprs_rlcmac_data.cpp:343 TBF: [DOWNLINK] UPLINK ASSIGNED TFI: 0 TLLI: 0xcb46771f [0;m [0;33m<0002> gprs_rlcmac.cpp:973 UL TBF=0 changes state from ASSIGN to FLOW [0;m [0;33m<0002> gprs_rlcmac.cpp:988 Restarting UL TBF=0 timer 3169 while old timer 3169 pending [0;m [0;33m<0002> gprs_rlcmac.cpp:988 Restarting UL TBF=0 timer 3169 while old timer 3169 pending [0;m [0;33m<0002> gprs_rlcmac.cpp:988 Restarting UL TBF=0 timer 3169 while old timer 3169 pending [0;m [0;33m<0002> gprs_rlcmac.cpp:988 Restarting UL TBF=0 timer 3169 while old timer 3169 pending [0;m [1;36m<0005> gprs_rlcmac_data.cpp:740 Complete UL frame for TBF=0: len=70 [0;m [1;34m<0008> gprs_rlcmac.cpp:1760 LLC [PCU -> SGSN] TFI: 0 TLLI: 0xcb46771f len=70 [0;m [0;33m<0002> gprs_rlcmac.cpp:988 Restarting UL TBF=0 timer 3169 while old timer 3169 pending [0;m [0;33m<0002> gprs_rlcmac.cpp:988 Restarting UL TBF=0 timer 3169 while old timer 3169 pending [0;m [0;33m<0002> gprs_rlcmac.cpp:988 Restarting UL TBF=0 timer 3169 while old timer 3169 pending [0;m [1;36m<0005> gprs_rlcmac_data.cpp:740 Complete UL frame for TBF=0: len=62 [0;m [1;34m<0008> gprs_rlcmac.cpp:1760 LLC [PCU -> SGSN] TFI: 0 TLLI: 0xcb46771f len=62 [0;m [0;33m<0002> gprs_rlcmac.cpp:973 UL TBF=0 changes state from FLOW to FINISHED [0;m [0;33m<0002> gprs_rlcmac.cpp:988 Restarting UL TBF=0 timer 3169 while old timer 3169 pending [0;m [0;33m<0002> gprs_rlcmac.cpp:988 Restarting UL TBF=0 timer 3169 while old timer 3169 pending [0;m [0;36m<0006> gprs_rlcmac_sched.cpp:260 Received RTS for PDCH: TRX=0 TS=7 FN=1291784 block_nr=0 scheduling free USF for polling at FN=1291788 of UL TFI=0 [0;m [0;33m<0002> gprs_rlcmac.cpp:988 Restarting UL TBF=0 timer 3169 while old timer 3169 pending [0;m [1;34m<0008> gprs_bssgp_pcu.cpp:145 LLC [SGSN -> PCU] = TLLI: 0xcb46771f IMSI: 452022112638582 len: 107 [0;m [0;33m<0002> gprs_rlcmac.cpp:214 Searching for first unallocated TFI: TRX=0 first TS=7 [0;m [0;33m<0002> gprs_rlcmac.cpp:225 Found TFI=0. [0;m [0;33m<0002> gprs_rlcmac.cpp:351 ********** TBF starts here ********** [0;m [0;33m<0002> gprs_rlcmac.cpp:354 Allocating DL TBF: TFI=0 TRX=0 MS_CLASS=10 [0;m [0;33m<0002> gprs_rlcmac.cpp:421 Slot Allocation (Algorithm A) for class 10 [0;m [0;33m<0002> gprs_rlcmac.cpp:444 - Assign downlink TS=7 [0;m [0;33m<0002> gprs_rlcmac.cpp:948 - Setting Control TS 7 [0;m [0;33m<0002> gprs_bssgp_pcu.cpp:233 TBF: [DOWNLINK] START TFI: 0 TLLI: 0xcb46771f [0;m [0;33m<0002> gprs_rlcmac_data.cpp:1848 Send dowlink assignment for TBF=0 on PCH, no TBF exist (IMSI=452022112638582) [0;m [0;33m<0002> gprs_rlcmac.cpp:973 DL TBF=0 changes state from NULL to ASSIGN [0;m [0;33m<0002> gprs_rlcmac_data.cpp:1801 TX: START TFI: 0 TLLI: 0xcb46771f Immediate Assignment Downlink (PCH) [0;m [0;33m<0002> gprs_rlcmac_data.cpp:1894 Got IMM.ASS confirm for TLLI=cb46771f [0;m [0;33m<0002> gprs_rlcmac.cpp:983 Starting DL TBF=0 timer 0. [0;m [0;33m<0002> gprs_rlcmac.cpp:988 Restarting UL TBF=0 timer 3169 while old timer 3169 pending [0;m [0;33m<0002> gprs_rlcmac_data.cpp:270 +++++++++++++++++++++++++ RX : Uplink Control Block +++++++++++++++++++++++++ [0;m [0;33m<0002> gprs_rlcmac_data.cpp:273 ------------------------- RX : Uplink Control Block ------------------------- [0;m [0;33m<0002> gprs_rlcmac_data.cpp:288 PACKET CONTROL ACK with expected FN=1291788 TLL=0xcb46771f (TRX 0 TS 7) [0;m [0;33m<0002> gprs_rlcmac_data.cpp:297 RX: [PCU <- BTS] TFI: 0 TLLI: 0xcb46771f Packet Control Ack [0;m [0;33m<0002> gprs_rlcmac_data.cpp:302 TBF: [UPLINK] END TFI: 0 TLLI: 0xcb46771f [0;m [0;33m<0002> gprs_rlcmac.cpp:895 Free UL TBF=0 with TLLI=0xcb46771f. [0;m [0;33m<0002> gprs_rlcmac.cpp:1005 Stopping UL TBF=0 timer 3169. [0;m [0;33m<0002> gprs_rlcmac.cpp:911 ********** TBF ends here ********** [0;m [0;33m<0002> gprs_rlcmac_data.cpp:501 DL TBF=0 timer 0 expired. [0;m [0;33m<0002> gprs_rlcmac.cpp:973 DL TBF=0 changes state from ASSIGN to FLOW [0;m [1;33m<0004> gprs_rlcmac_data.cpp:1453 Complete DL frame for TBF=0: len=107 [0;m [0;33m<0002> gprs_rlcmac.cpp:973 DL TBF=0 changes state from FLOW to FINISHED [0;m [0;33m<0002> gprs_rlcmac_data.cpp:1532 Polling sheduled in this TS 7 [0;m [0;33m<0002> gprs_rlcmac.cpp:983 Starting DL TBF=0 timer 3191. [0;m [0;36m<0006> gprs_rlcmac_sched.cpp:260 Received RTS for PDCH: TRX=0 TS=7 FN=1291862 block_nr=6 scheduling free USF for polling at FN=1291866 of DL TFI=0 [0;m [0;33m<0002> gprs_rlcmac_data.cpp:270 +++++++++++++++++++++++++ RX : Uplink Control Block +++++++++++++++++++++++++ [0;m [0;33m<0002> gprs_rlcmac_data.cpp:273 ------------------------- RX : Uplink Control Block ------------------------- [0;m [0;33m<0002> gprs_rlcmac.cpp:1005 Stopping DL TBF=0 timer 3191. [0;m [0;33m<0002> gprs_rlcmac_data.cpp:395 RX: [PCU <- BTS] TFI: 0 TLLI: 0xcb46771f Packet Downlink Ack/Nack [0;m [0;33m<0002> gprs_rlcmac_data.cpp:1532 Polling sheduled in this TS 7 [0;m [0;36m<0006> gprs_rlcmac_sched.cpp:260 Received RTS for PDCH: TRX=0 TS=7 FN=1291948 block_nr=2 scheduling free USF for polling at FN=1291953 of DL TFI=0 [0;m [0;33m<0002> gprs_rlcmac_data.cpp:270 +++++++++++++++++++++++++ RX : Uplink Control Block +++++++++++++++++++++++++ [0;m [0;33m<0002> gprs_rlcmac_data.cpp:273 ------------------------- RX : Uplink Control Block ------------------------- [0;m [0;33m<0002> gprs_rlcmac_data.cpp:395 RX: [PCU <- BTS] TFI: 0 TLLI: 0xcb46771f Packet Downlink Ack/Nack [0;m [0;33m<0002> gprs_rlcmac.cpp:983 Starting DL TBF=0 timer 3193. [0;m [0;33m<0002> gprs_rlcmac.cpp:973 DL TBF=0 changes state from FINISHED to WAIT RELEASE [0;m [0;33m<0002> gprs_rlcmac_data.cpp:410 MS requests UL TBF in ack message, so we provide one: [0;m [0;33m<0002> gprs_rlcmac.cpp:214 Searching for first unallocated TFI: TRX=0 first TS=7 [0;m [0;33m<0002> gprs_rlcmac.cpp:225 Found TFI=0. [0;m [0;33m<0002> gprs_rlcmac.cpp:351 ********** TBF starts here ********** [0;m [0;33m<0002> gprs_rlcmac.cpp:354 Allocating UL TBF: TFI=0 TRX=0 MS_CLASS=10 [0;m [0;33m<0002> gprs_rlcmac.cpp:421 Slot Allocation (Algorithm A) for class 10 [0;m [0;33m<0002> gprs_rlcmac.cpp:434 - Assign uplink TS=7 USF=0 [0;m [0;33m<0002> gprs_rlcmac.cpp:948 - Setting Control TS 7 [0;m [0;33m<0002> gprs_rlcmac.cpp:973 UL TBF=0 changes state from NULL to ASSIGN [0;m [0;33m<0002> gprs_rlcmac.cpp:983 Starting UL TBF=0 timer 3169. [0;m [0;33m<0002> gprs_rlcmac_data.cpp:1069 TBF: START TFI: 0 TLLI: 0xcb46771f Packet Uplink Assignment (PACCH) [0;m [0;33m<0002> gprs_rlcmac_data.cpp:1083 +++++++++++++++++++++++++ TX : Packet Uplink Assignment +++++++++++++++++++++++++ [0;m [0;33m<0002> gprs_rlcmac_data.cpp:1086 ------------------------- TX : Packet Uplink Assignment ------------------------- [0;m [0;36m<0006> gprs_rlcmac_sched.cpp:260 Received RTS for PDCH: TRX=0 TS=7 FN=1291979 block_nr=9 scheduling free USF for polling at FN=1291983 of DL TFI=0 [0;m [0;33m<0002> gprs_rlcmac_data.cpp:270 +++++++++++++++++++++++++ RX : Uplink Control Block +++++++++++++++++++++++++ [0;m [0;33m<0002> gprs_rlcmac_data.cpp:273 ------------------------- RX : Uplink Control Block ------------------------- [0;m [0;33m<0002> gprs_rlcmac_data.cpp:288 PACKET CONTROL ACK with expected FN=1291983 TLL=0xcb46771f (TRX 0 TS 7) [0;m [0;33m<0002> gprs_rlcmac_data.cpp:297 RX: [PCU <- BTS] TFI: 0 TLLI: 0xcb46771f Packet Control Ack [0;m [0;33m<0002> gprs_rlcmac_data.cpp:343 TBF: [DOWNLINK] UPLINK ASSIGNED TFI: 0 TLLI: 0xcb46771f [0;m [0;33m<0002> gprs_rlcmac.cpp:973 UL TBF=0 changes state from ASSIGN to FLOW [0;m [0;33m<0002> gprs_rlcmac.cpp:988 Restarting UL TBF=0 timer 3169 while old timer 3169 pending [0;m [0;33m<0002> gprs_rlcmac.cpp:988 Restarting UL TBF=0 timer 3169 while old timer 3169 pending [0;m [0;33m<0002> gprs_rlcmac.cpp:988 Restarting UL TBF=0 timer 3169 while old timer 3169 pending [0;m [0;33m<0002> gprs_rlcmac.cpp:988 Restarting UL TBF=0 timer 3169 while old timer 3169 pending [0;m [1;36m<0005> gprs_rlcmac_data.cpp:740 Complete UL frame for TBF=0: len=70 [0;m [1;34m<0008> gprs_rlcmac.cpp:1760 LLC [PCU -> SGSN] TFI: 0 TLLI: 0xcb46771f len=70 [0;m [0;33m<0002> gprs_rlcmac.cpp:973 UL TBF=0 changes state from FLOW to FINISHED [0;m [0;33m<0002> gprs_rlcmac.cpp:988 Restarting UL TBF=0 timer 3169 while old timer 3169 pending [0;m [0;33m<0002> gprs_rlcmac.cpp:988 Restarting UL TBF=0 timer 3169 while old timer 3169 pending [0;m [0;36m<0006> gprs_rlcmac_sched.cpp:260 Received RTS for PDCH: TRX=0 TS=7 FN=1292044 block_nr=0 scheduling free USF for polling at FN=1292048 of UL TFI=0 [0;m [0;33m<0002> gprs_rlcmac.cpp:988 Restarting UL TBF=0 timer 3169 while old timer 3169 pending [0;m [0;33m<0002> gprs_rlcmac.cpp:988 Restarting UL TBF=0 timer 3169 while old timer 3169 pending [0;m [0;33m<0002> gprs_rlcmac_data.cpp:270 +++++++++++++++++++++++++ RX : Uplink Control Block +++++++++++++++++++++++++ [0;m [0;33m<0002> gprs_rlcmac_data.cpp:273 ------------------------- RX : Uplink Control Block ------------------------- [0;m [0;33m<0002> gprs_rlcmac_data.cpp:288 PACKET CONTROL ACK with expected FN=1292048 TLL=0xcb46771f (TRX 0 TS 7) [0;m [0;33m<0002> gprs_rlcmac_data.cpp:297 RX: [PCU <- BTS] TFI: 0 TLLI: 0xcb46771f Packet Control Ack [0;m [0;33m<0002> gprs_rlcmac_data.cpp:302 TBF: [UPLINK] END TFI: 0 TLLI: 0xcb46771f [0;m [0;33m<0002> gprs_rlcmac.cpp:895 Free UL TBF=0 with TLLI=0xcb46771f. [0;m [0;33m<0002> gprs_rlcmac.cpp:1005 Stopping UL TBF=0 timer 3169. [0;m [0;33m<0002> gprs_rlcmac.cpp:911 ********** TBF ends here ********** [0;m [1;34m<0008> gprs_bssgp_pcu.cpp:145 LLC [SGSN -> PCU] = TLLI: 0xcb46771f IMSI: 452022112638582 len: 70 [0;m [0;33m<0002> gprs_bssgp_pcu.cpp:149 TBF: APPEND TFI: 0 TLLI: 0xcb46771f [0;m [0;33m<0002> gprs_bssgp_pcu.cpp:152 TBF in WAIT RELEASE state (T3193), so reuse TBF [0;m [0;33m<0002> gprs_rlcmac.cpp:921 ********** TBF update ********** [0;m [0;33m<0002> gprs_rlcmac.cpp:421 Slot Allocation (Algorithm A) for class 10 [0;m [0;33m<0002> gprs_rlcmac.cpp:444 - Assign downlink TS=7 [0;m [0;33m<0002> gprs_rlcmac.cpp:1005 Stopping DL TBF=0 timer 3193. [0;m [0;33m<0002> gprs_rlcmac_data.cpp:1837 Send dowlink assignment on PACCH, because DL TBF=0 exists for TLLI=0xcb46771f [0;m [0;33m<0002> gprs_rlcmac.cpp:973 DL TBF=0 changes state from WAIT RELEASE to ASSIGN [0;m [0;33m<0002> gprs_rlcmac.cpp:983 Starting DL TBF=0 timer 0. [0;m [0;33m<0002> gprs_rlcmac_data.cpp:1764 TBF: START TFI: 0 TLLI: 0xcb46771f Packet Downlink Assignment (PACCH) [0;m [0;33m<0002> gprs_rlcmac_data.cpp:1769 +++++++++++++++++++++++++ TX : Packet Downlink Assignment +++++++++++++++++++++++++ [0;m [0;33m<0002> gprs_rlcmac_data.cpp:1772 ------------------------- TX : Packet Downlink Assignment ------------------------- [0;m [0;36m<0006> gprs_rlcmac_sched.cpp:260 Received RTS for PDCH: TRX=0 TS=7 FN=1292100 block_nr=1 scheduling free USF for polling at FN=1292104 of DL TFI=0 [0;m [0;33m<0002> gprs_rlcmac_data.cpp:100 Poll timeout for DL TBF=0 [0;m [0;33m<0002> gprs_rlcmac_data.cpp:158 - Timeout for polling PACKET CONTROL ACK for PACKET DOWNLINK ASSIGNMENT. [0;m [0;33m<0002> gprs_rlcmac_data.cpp:84 - Assignment was on PACCH [0;m [0;33m<0002> gprs_rlcmac_data.cpp:92 - No downlink ACK received yet [0;m [0;33m<0002> gprs_rlcmac_data.cpp:1764 TBF: START TFI: 0 TLLI: 0xcb46771f Packet Downlink Assignment (PACCH) [0;m [0;33m<0002> gprs_rlcmac_data.cpp:1769 +++++++++++++++++++++++++ TX : Packet Downlink Assignment +++++++++++++++++++++++++ [0;m [0;33m<0002> gprs_rlcmac_data.cpp:1772 ------------------------- TX : Packet Downlink Assignment ------------------------- [0;m [0;36m<0006> gprs_rlcmac_sched.cpp:260 Received RTS for PDCH: TRX=0 TS=7 FN=1292143 block_nr=11 scheduling free USF for polling at FN=1292148 of DL TFI=0 [0;m [0;33m<0002> gprs_rlcmac_data.cpp:100 Poll timeout for DL TBF=0 [0;m [0;33m<0002> gprs_rlcmac_data.cpp:1764 TBF: START TFI: 0 TLLI: 0xcb46771f Packet Downlink Assignment (PACCH) [0;m [0;33m<0002> gprs_rlcmac_data.cpp:1769 +++++++++++++++++++++++++ TX : Packet Downlink Assignment +++++++++++++++++++++++++ [0;m [0;33m<0002> gprs_rlcmac_data.cpp:1772 ------------------------- TX : Packet Downlink Assignment ------------------------- [0;m [0;36m<0006> gprs_rlcmac_sched.cpp:260 Received RTS for PDCH: TRX=0 TS=7 FN=1292195 block_nr=11 scheduling free USF for polling at FN=1292200 of DL TFI=0 [0;m [1;34m<0008> gprs_bssgp_pcu.cpp:145 LLC [SGSN -> PCU] = TLLI: 0xcb46771f IMSI: 452022112638582 len: 70 [0;m [0;33m<0002> gprs_bssgp_pcu.cpp:149 TBF: APPEND TFI: 0 TLLI: 0xcb46771f [0;m [0;33m<0002> gprs_rlcmac_data.cpp:100 Poll timeout for DL TBF=0 [0;m [0;33m<0002> gprs_rlcmac_data.cpp:1764 TBF: START TFI: 0 TLLI: 0xcb46771f Packet Downlink Assignment (PACCH) [0;m [0;33m<0002> gprs_rlcmac_data.cpp:1769 +++++++++++++++++++++++++ TX : Packet Downlink Assignment +++++++++++++++++++++++++ [0;m [0;33m<0002> gprs_rlcmac_data.cpp:1772 ------------------------- TX : Packet Downlink Assignment ------------------------- [0;m [0;36m<0006> gprs_rlcmac_sched.cpp:260 Received RTS for PDCH: TRX=0 TS=7 FN=1292265 block_nr=3 scheduling free USF for polling at FN=1292269 of DL TFI=0 [0;m [1;34m<0008> gprs_bssgp_pcu.cpp:145 LLC [SGSN -> PCU] = TLLI: 0xcb46771f IMSI: 452022112638582 len: 70 [0;m [0;33m<0002> gprs_bssgp_pcu.cpp:149 TBF: APPEND TFI: 0 TLLI: 0xcb46771f [0;m [0;33m<0002> gprs_rlcmac_data.cpp:100 Poll timeout for DL TBF=0 [0;m [0;33m<0002> gprs_rlcmac_data.cpp:1764 TBF: START TFI: 0 TLLI: 0xcb46771f Packet Downlink Assignment (PACCH) [0;m [0;33m<0002> gprs_rlcmac_data.cpp:1769 +++++++++++++++++++++++++ TX : Packet Downlink Assignment +++++++++++++++++++++++++ [0;m [0;33m<0002> gprs_rlcmac_data.cpp:1772 ------------------------- TX : Packet Downlink Assignment ------------------------- [0;m [0;36m<0006> gprs_rlcmac_sched.cpp:260 Received RTS for PDCH: TRX=0 TS=7 FN=1292390 block_nr=8 scheduling free USF for polling at FN=1292395 of DL TFI=0 [0;m [1;34m<0008> gprs_bssgp_pcu.cpp:145 LLC [SGSN -> PCU] = TLLI: 0xcb46771f IMSI: 452022112638582 len: 70 [0;m [0;33m<0002> gprs_bssgp_pcu.cpp:149 TBF: APPEND TFI: 0 TLLI: 0xcb46771f [0;m [0;33m<0002> gprs_rlcmac_data.cpp:501 DL TBF=0 timer 0 expired. [0;m [0;33m<0002> gprs_rlcmac_data.cpp:515 Releasing due to PACCH assignment timeout. [0;m [0;33m<0002> gprs_rlcmac.cpp:895 Free DL TBF=0 with TLLI=0xcb46771f. [0;m [0;33m<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! [0;m [0;33m<0002> gprs_rlcmac.cpp:911 ********** TBF ends here ********** [0;m [1;34m<0008> gprs_bssgp_pcu.cpp:145 LLC [SGSN -> PCU] = TLLI: 0xcb46771f IMSI: 452022112638582 len: 70 [0;m [0;33m<0002> gprs_rlcmac.cpp:214 Searching for first unallocated TFI: TRX=0 first TS=7 [0;m [0;33m<0002> gprs_rlcmac.cpp:225 Found TFI=0. [0;m [0;33m<0002> gprs_rlcmac.cpp:351 ********** TBF starts here ********** [0;m [0;33m<0002> gprs_rlcmac.cpp:354 Allocating DL TBF: TFI=0 TRX=0 MS_CLASS=10 [0;m [0;33m<0002> gprs_rlcmac.cpp:421 Slot Allocation (Algorithm A) for class 10 [0;m [0;33m<0002> gprs_rlcmac.cpp:444 - Assign downlink TS=7 [0;m [0;33m<0002> gprs_rlcmac.cpp:948 - Setting Control TS 7 [0;m [0;33m<0002> gprs_bssgp_pcu.cpp:233 TBF: [DOWNLINK] START TFI: 0 TLLI: 0xcb46771f [0;m [0;33m<0002> gprs_rlcmac_data.cpp:1848 Send dowlink assignment for TBF=0 on PCH, no TBF exist (IMSI=452022112638582) [0;m [0;33m<0002> gprs_rlcmac.cpp:973 DL TBF=0 changes state from NULL to ASSIGN [0;m [0;33m<0002> gprs_rlcmac_data.cpp:1801 TX: START TFI: 0 TLLI: 0xcb46771f Immediate Assignment Downlink (PCH) [0;m [0;33m<0002> gprs_rlcmac_data.cpp:1894 Got IMM.ASS confirm for TLLI=cb46771f [0;m [0;33m<0002> gprs_rlcmac.cpp:983 Starting DL TBF=0 timer 0. [0;m [1;32m<0001> pcu_l1_if.cpp:256 RACH request received: sapi=1 qta=0, ra=117, fn=1292613 [0;m [0;33m<0002> gprs_rlcmac_data.cpp:1116 MS requests UL TBF on RACH, so we provide one: [0;m [0;33m<0002> gprs_rlcmac_data.cpp:1119 MS requests single block allocation [0;m [0;33m<0002> gprs_rlcmac_data.cpp:1136 RX: [PCU <- BTS] RACH qbit-ta=0 ra=0x75, Fn=1292613 (14,18,23) [0;m [0;33m<0002> gprs_rlcmac_data.cpp:1138 TX: Immediate Assignment Uplink (AGCH) [0;m [0;33m<0002> gprs_rlcmac_data.cpp:501 DL TBF=0 timer 0 expired. [0;m [0;33m<0002> gprs_rlcmac.cpp:973 DL TBF=0 changes state from ASSIGN to FLOW [0;m [1;33m<0004> gprs_rlcmac_data.cpp:1453 Complete DL frame for TBF=0: len=70 [0;m [0;33m<0002> gprs_rlcmac.cpp:973 DL TBF=0 changes state from FLOW to FINISHED [0;m [0;33m<0002> gprs_rlcmac_data.cpp:1532 Polling sheduled in this TS 7 [0;m [0;33m<0002> gprs_rlcmac.cpp:983 Starting DL TBF=0 timer 3191. [0;m [0;36m<0006> gprs_rlcmac_sched.cpp:260 Received RTS for PDCH: TRX=0 TS=7 FN=1292676 block_nr=2 scheduling free USF for polling at FN=1292681 of DL TFI=0 [0;m [0;33m<0002> gprs_rlcmac_data.cpp:270 +++++++++++++++++++++++++ RX : Uplink Control Block +++++++++++++++++++++++++ [0;m [0;33m<0002> gprs_rlcmac_data.cpp:273 ------------------------- RX : Uplink Control Block ------------------------- [0;m [0;33m<0002> gprs_rlcmac.cpp:1005 Stopping DL TBF=0 timer 3191. [0;m [0;33m<0002> gprs_rlcmac_data.cpp:395 RX: [PCU <- BTS] TFI: 0 TLLI: 0xcb46771f Packet Downlink Ack/Nack [0;m [0;33m<0002> gprs_rlcmac.cpp:983 Starting DL TBF=0 timer 3193. [0;m [0;33m<0002> gprs_rlcmac.cpp:973 DL TBF=0 changes state from FINISHED to WAIT RELEASE [0;m [0;33m<0002> gprs_rlcmac_data.cpp:410 MS requests UL TBF in ack message, so we provide one: [0;m [0;33m<0002> gprs_rlcmac.cpp:214 Searching for first unallocated TFI: TRX=0 first TS=7 [0;m [0;33m<0002> gprs_rlcmac.cpp:225 Found TFI=0. [0;m [0;33m<0002> gprs_rlcmac.cpp:351 ********** TBF starts here ********** [0;m [0;33m<0002> gprs_rlcmac.cpp:354 Allocating UL TBF: TFI=0 TRX=0 MS_CLASS=10 [0;m [0;33m<0002> gprs_rlcmac.cpp:421 Slot Allocation (Algorithm A) for class 10 [0;m [0;33m<0002> gprs_rlcmac.cpp:434 - Assign uplink TS=7 USF=0 [0;m [0;33m<0002> gprs_rlcmac.cpp:948 - Setting Control TS 7 [0;m [0;33m<0002> gprs_rlcmac.cpp:973 UL TBF=0 changes state from NULL to ASSIGN [0;m [0;33m<0002> gprs_rlcmac.cpp:983 Starting UL TBF=0 timer 3169. [0;m [0;33m<0002> gprs_rlcmac_data.cpp:1069 TBF: START TFI: 0 TLLI: 0xcb46771f Packet Uplink Assignment (PACCH) [0;m [0;33m<0002> gprs_rlcmac_data.cpp:1083 +++++++++++++++++++++++++ TX : Packet Uplink Assignment +++++++++++++++++++++++++ [0;m [0;33m<0002> gprs_rlcmac_data.cpp:1086 ------------------------- TX : Packet Uplink Assignment ------------------------- [0;m [0;36m<0006> gprs_rlcmac_sched.cpp:260 Received RTS for PDCH: TRX=0 TS=7 FN=1292707 block_nr=9 scheduling free USF for polling at FN=1292711 of DL TFI=0 [0;m [0;33m<0002> gprs_rlcmac_data.cpp:270 +++++++++++++++++++++++++ RX : Uplink Control Block +++++++++++++++++++++++++ [0;m [0;33m<0002> gprs_rlcmac_data.cpp:273 ------------------------- RX : Uplink Control Block ------------------------- [0;m [0;33m<0002> gprs_rlcmac_data.cpp:288 PACKET CONTROL ACK with expected FN=1292711 TLL=0xcb46771f (TRX 0 TS 7) [0;m [0;33m<0002> gprs_rlcmac_data.cpp:297 RX: [PCU <- BTS] TFI: 0 TLLI: 0xcb46771f Packet Control Ack [0;m [0;33m<0002> gprs_rlcmac_data.cpp:343 TBF: [DOWNLINK] UPLINK ASSIGNED TFI: 0 TLLI: 0xcb46771f [0;m [0;33m<0002> gprs_rlcmac.cpp:973 UL TBF=0 changes state from ASSIGN to FLOW [0;m [1;34m<0008> gprs_bssgp_pcu.cpp:145 LLC [SGSN -> PCU] = TLLI: 0xcb46771f IMSI: 452022112638582 len: 70 [0;m [0;33m<0002> gprs_bssgp_pcu.cpp:149 TBF: APPEND TFI: 0 TLLI: 0xcb46771f [0;m [0;33m<0002> gprs_bssgp_pcu.cpp:152 TBF in WAIT RELEASE state (T3193), so reuse TBF [0;m [0;33m<0002> gprs_rlcmac.cpp:921 ********** TBF update ********** [0;m [0;33m<0002> gprs_rlcmac.cpp:421 Slot Allocation (Algorithm A) for class 10 [0;m [0;33m<0002> gprs_rlcmac.cpp:444 - Assign downlink TS=7 [0;m [0;33m<0002> gprs_rlcmac.cpp:1005 Stopping DL TBF=0 timer 3193. [0;m [0;33m<0002> gprs_rlcmac_data.cpp:1837 Send dowlink assignment on PACCH, because DL TBF=0 exists for TLLI=0xcb46771f [0;m [0;33m<0002> gprs_rlcmac.cpp:973 DL TBF=0 changes state from WAIT RELEASE to ASSIGN [0;m [0;33m<0002> gprs_rlcmac.cpp:983 Starting DL TBF=0 timer 0. [0;m [0;33m<0002> gprs_rlcmac_data.cpp:1764 TBF: START TFI: 0 TLLI: 0xcb46771f Packet Downlink Assignment (PACCH) [0;m [0;33m<0002> gprs_rlcmac_data.cpp:1769 +++++++++++++++++++++++++ TX : Packet Downlink Assignment +++++++++++++++++++++++++ [0;m [0;33m<0002> gprs_rlcmac_data.cpp:1772 ------------------------- TX : Packet Downlink Assignment ------------------------- [0;m [0;33m<0002> gprs_rlcmac.cpp:988 Restarting UL TBF=0 timer 3169 while old timer 3169 pending [0;m [0;36m<0006> gprs_rlcmac_sched.cpp:260 Received RTS for PDCH: TRX=0 TS=7 FN=1292750 block_nr=7 scheduling free USF for polling at FN=1292754 of DL TFI=0 [0;m [0;33m<0002> gprs_rlcmac.cpp:988 Restarting UL TBF=0 timer 3169 while old timer 3169 pending [0;m [0;33m<0002> gprs_rlcmac.cpp:988 Restarting UL TBF=0 timer 3169 while old timer 3169 pending [0;m [0;33m<0002> gprs_rlcmac.cpp:988 Restarting UL TBF=0 timer 3169 while old timer 3169 pending [0;m [1;36m<0005> gprs_rlcmac_data.cpp:740 Complete UL frame for TBF=0: len=70 [0;m [1;34m<0008> gprs_rlcmac.cpp:1760 LLC [PCU -> SGSN] TFI: 0 TLLI: 0xcb46771f len=70 [0;m [0;33m<0002> gprs_rlcmac.cpp:988 Restarting UL TBF=0 timer 3169 while old timer 3169 pending [0;m [0;33m<0002> gprs_rlcmac_data.cpp:270 +++++++++++++++++++++++++ RX : Uplink Control Block +++++++++++++++++++++++++ [0;m [0;33m<0002> gprs_rlcmac_data.cpp:273 ------------------------- RX : Uplink Control Block ------------------------- [0;m [0;33m<0002> gprs_rlcmac_data.cpp:288 PACKET CONTROL ACK with expected FN=1292754 TLL=0xcb46771f (TRX 0 TS 7) [0;m [0;33m<0002> gprs_rlcmac_data.cpp:297 RX: [PCU <- BTS] TFI: 0 TLLI: 0xcb46771f Packet Control Ack [0;m [0;33m<0002> gprs_rlcmac_data.cpp:316 TBF: [UPLINK] DOWNLINK ASSIGNED TFI: 0 TLLI: 0xcb46771f [0;m [0;33m<0002> gprs_rlcmac.cpp:973 DL TBF=0 changes state from ASSIGN to FLOW [0;m [0;33m<0002> gprs_rlcmac.cpp:1005 Stopping DL TBF=0 timer 0. [0;m [0;33m<0002> gprs_rlcmac.cpp:988 Restarting UL TBF=0 timer 3169 while old timer 3169 pending [0;m [0;33m<0002> gprs_rlcmac.cpp:988 Restarting UL TBF=0 timer 3169 while old timer 3169 pending [0;m [1;36m<0005> gprs_rlcmac_data.cpp:740 Complete UL frame for TBF=0: len=62 [0;m [1;34m<0008> gprs_rlcmac.cpp:1760 LLC [PCU -> SGSN] TFI: 0 TLLI: 0xcb46771f len=62 [0;m [0;33m<0002> gprs_rlcmac.cpp:988 Restarting UL TBF=0 timer 3169 while old timer 3169 pending [0;m [1;33m<0004> gprs_rlcmac_data.cpp:1453 Complete DL frame for TBF=0: len=70 [0;m [0;33m<0002> gprs_rlcmac.cpp:973 DL TBF=0 changes state from FLOW to FINISHED [0;m [0;33m<0002> gprs_rlcmac_data.cpp:1532 Polling sheduled in this TS 7 [0;m [0;33m<0002> gprs_rlcmac.cpp:983 Starting DL TBF=0 timer 3191. [0;m [0;33m<0002> gprs_rlcmac.cpp:988 Restarting UL TBF=0 timer 3169 while old timer 3169 pending [0;m [0;33m<0002> gprs_rlcmac.cpp:988 Restarting UL TBF=0 timer 3169 while old timer 3169 pending [0;m [0;36m<0006> gprs_rlcmac_sched.cpp:260 Received RTS for PDCH: TRX=0 TS=7 FN=1292793 block_nr=5 scheduling free USF for polling at FN=1292798 of DL TFI=0 [0;m [0;33m<0002> gprs_rlcmac.cpp:988 Restarting UL TBF=0 timer 3169 while old timer 3169 pending [0;m [0;33m<0002> gprs_rlcmac.cpp:988 Restarting UL TBF=0 timer 3169 while old timer 3169 pending [0;m [0;33m<0002> gprs_rlcmac.cpp:988 Restarting UL TBF=0 timer 3169 while old timer 3169 pending [0;m [0;33m<0002> gprs_rlcmac.cpp:988 Restarting UL TBF=0 timer 3169 while old timer 3169 pending [0;m [1;34m<0008> gprs_bssgp_pcu.cpp:145 LLC [SGSN -> PCU] = TLLI: 0xcb46771f IMSI: 452022112638582 len: 70 [0;m [0;33m<0002> gprs_bssgp_pcu.cpp:149 TBF: APPEND TFI: 0 TLLI: 0xcb46771f [0;m [0;33m<0002> gprs_rlcmac_data.cpp:270 +++++++++++++++++++++++++ RX : Uplink Control Block +++++++++++++++++++++++++ [0;m [0;33m<0002> gprs_rlcmac_data.cpp:273 ------------------------- RX : Uplink Control Block ------------------------- [0;m [0;33m<0002> gprs_rlcmac.cpp:1005 Stopping DL TBF=0 timer 3191. [0;m [0;33m<0002> gprs_rlcmac_data.cpp:395 RX: [PCU <- BTS] TFI: 0 TLLI: 0xcb46771f Packet Downlink Ack/Nack [0;m [0;33m<0002> gprs_rlcmac_data.cpp:1692 Trigger dowlink assignment on PACCH, because another LLC PDU has arrived in between [0;m [0;33m<0002> gprs_rlcmac.cpp:921 ********** TBF update ********** [0;m [0;33m<0002> gprs_rlcmac.cpp:421 Slot Allocation (Algorithm A) for class 10 [0;m [0;33m<0002> gprs_rlcmac.cpp:444 - Assign downlink TS=7 [0;m [0;33m<0002> gprs_rlcmac_data.cpp:1837 Send dowlink assignment on PACCH, because DL TBF=0 exists for TLLI=0xcb46771f [0;m [0;33m<0002> gprs_rlcmac.cpp:973 DL TBF=0 changes state from FINISHED to ASSIGN [0;m [0;33m<0002> gprs_rlcmac.cpp:983 Starting DL TBF=0 timer 0. [0;m [0;33m<0002> gprs_rlcmac_data.cpp:1764 TBF: START TFI: 0 TLLI: 0xcb46771f Packet Downlink Assignment (PACCH) [0;m [0;33m<0002> gprs_rlcmac_data.cpp:1769 +++++++++++++++++++++++++ TX : Packet Downlink Assignment +++++++++++++++++++++++++ [0;m [0;33m<0002> gprs_rlcmac_data.cpp:1772 ------------------------- TX : Packet Downlink Assignment ------------------------- [0;m [0;33m<0002> gprs_rlcmac.cpp:988 Restarting UL TBF=0 timer 3169 while old timer 3169 pending [0;m [0;33m<0002> gprs_rlcmac.cpp:988 Restarting UL TBF=0 timer 3169 while old timer 3169 pending [0;m [0;36m<0006> gprs_rlcmac_sched.cpp:260 Received RTS for PDCH: TRX=0 TS=7 FN=1292824 block_nr=0 scheduling free USF for polling at FN=1292828 of DL TFI=0 [0;m [0;33m<0002> gprs_rlcmac.cpp:988 Restarting UL TBF=0 timer 3169 while old timer 3169 pending [0;m [0;33m<0002> gprs_rlcmac.cpp:988 Restarting UL TBF=0 timer 3169 while old timer 3169 pending [0;m [0;33m<0002> gprs_rlcmac.cpp:988 Restarting UL TBF=0 timer 3169 while old timer 3169 pending [0;m [0;33m<0002> gprs_rlcmac.cpp:988 Restarting UL TBF=0 timer 3169 while old timer 3169 pending [0;m [0;33m<0002> gprs_rlcmac_data.cpp:270 +++++++++++++++++++++++++ RX : Uplink Control Block +++++++++++++++++++++++++ [0;m [0;33m<0002> gprs_rlcmac_data.cpp:273 ------------------------- RX : Uplink Control Block ------------------------- [0;m [0;33m<0002> gprs_rlcmac_data.cpp:288 PACKET CONTROL ACK with expected FN=1292828 TLL=0xcb46771f (TRX 0 TS 7) [0;m [0;33m<0002> gprs_rlcmac_data.cpp:297 RX: [PCU <- BTS] TFI: 0 TLLI: 0xcb46771f Packet Control Ack [0;m [0;33m<0002> gprs_rlcmac_data.cpp:316 TBF: [UPLINK] DOWNLINK ASSIGNED TFI: 0 TLLI: 0xcb46771f [0;m [0;33m<0002> gprs_rlcmac.cpp:973 DL TBF=0 changes state from ASSIGN to FLOW [0;m [0;33m<0002> gprs_rlcmac.cpp:1005 Stopping DL TBF=0 timer 0. [0;m [0;33m<0002> gprs_rlcmac.cpp:988 Restarting UL TBF=0 timer 3169 while old timer 3169 pending [0;m [0;33m<0002> gprs_rlcmac.cpp:988 Restarting UL TBF=0 timer 3169 while old timer 3169 pending [0;m [0;33m<0002> gprs_rlcmac.cpp:988 Restarting UL TBF=0 timer 3169 while old timer 3169 pending [0;m [1;33m<0004> gprs_rlcmac_data.cpp:1453 Complete DL frame for TBF=0: len=70 [0;m [0;33m<0002> gprs_rlcmac.cpp:973 DL TBF=0 changes state from FLOW to FINISHED [0;m [0;33m<0002> gprs_rlcmac_data.cpp:1532 Polling sheduled in this TS 7 [0;m [0;33m<0002> gprs_rlcmac.cpp:983 Starting DL TBF=0 timer 3191. [0;m [0;33m<0002> gprs_rlcmac.cpp:988 Restarting UL TBF=0 timer 3169 while old timer 3169 pending [0;m [0;33m<0002> gprs_rlcmac.cpp:988 Restarting UL TBF=0 timer 3169 while old timer 3169 pending [0;m [0;36m<0006> gprs_rlcmac_sched.cpp:260 Received RTS for PDCH: TRX=0 TS=7 FN=1292867 block_nr=10 scheduling free USF for polling at FN=1292871 of DL TFI=0 [0;m [0;33m<0002> gprs_rlcmac.cpp:988 Restarting UL TBF=0 timer 3169 while old timer 3169 pending [0;m [0;33m<0002> gprs_rlcmac.cpp:988 Restarting UL TBF=0 timer 3169 while old timer 3169 pending [0;m [0;33m<0002> gprs_rlcmac.cpp:988 Restarting UL TBF=0 timer 3169 while old timer 3169 pending [0;m [0;33m<0002> gprs_rlcmac_data.cpp:270 +++++++++++++++++++++++++ RX : Uplink Control Block +++++++++++++++++++++++++ [0;m [0;33m<0002> gprs_rlcmac_data.cpp:273 ------------------------- RX : Uplink Control Block ------------------------- [0;m [0;33m<0002> gprs_rlcmac_data.cpp:376 PACKET DOWNLINK ACK with unknown FN=1292867 TFI=0 (TRX 0 TS 7) [0;m [0;33m<0002> gprs_rlcmac.cpp:988 Restarting UL TBF=0 timer 3169 while old timer 3169 pending [0;m [0;33m<0002> gprs_rlcmac.cpp:988 Restarting UL TBF=0 timer 3169 while old timer 3169 pending [0;m [0;33m<0002> gprs_rlcmac.cpp:988 Restarting UL TBF=0 timer 3169 while old timer 3169 pending [0;m [0;33m<0002> gprs_rlcmac.cpp:988 Restarting UL TBF=0 timer 3169 while old timer 3169 pending [0;m [0;33m<0002> gprs_rlcmac_data.cpp:100 Poll timeout for DL TBF=0 [0;m [0;33m<0002> gprs_rlcmac_data.cpp:180 - Timeout for polling PACKET DOWNLINK ACK. [0;m [0;33m<0002> gprs_rlcmac_data.cpp:84 - Assignment was on PACCH [0;m [0;33m<0002> gprs_rlcmac_data.cpp:92 - No downlink ACK received yet [0;m [0;33m<0002> gprs_rlcmac.cpp:988 Restarting UL TBF=0 timer 3169 while old timer 3169 pending [0;m [1;36m<0005> gprs_rlcmac_data.cpp:740 Complete UL frame for TBF=0: len=506 [0;m [1;34m<0008> gprs_rlcmac.cpp:1760 LLC [PCU -> SGSN] TFI: 0 TLLI: 0xcb46771f len=506 [0;m [0;33m<0002> gprs_rlcmac.cpp:988 Restarting UL TBF=0 timer 3169 while old timer 3169 pending [0;m [0;33m<0002> gprs_rlcmac.cpp:988 Restarting UL TBF=0 timer 3169 while old timer 3169 pending [0;m [0;33m<0002> gprs_rlcmac.cpp:988 Restarting UL TBF=0 timer 3169 while old timer 3169 pending [0;m [0;33m<0002> gprs_rlcmac.cpp:988 Restarting UL TBF=0 timer 3169 while old timer 3169 pending [0;m [0;33m<0002> gprs_rlcmac.cpp:988 Restarting UL TBF=0 timer 3169 while old timer 3169 pending [0;m [0;33m<0002> gprs_rlcmac.cpp:988 Restarting UL TBF=0 timer 3169 while old timer 3169 pending [0;m [0;33m<0002> gprs_rlcmac.cpp:988 Restarting UL TBF=0 timer 3169 while old timer 3169 pending [0;m [1;36m<0005> gprs_rlcmac_data.cpp:740 Complete UL frame for TBF=0: len=153 [0;m [1;34m<0008> gprs_rlcmac.cpp:1760 LLC [PCU -> SGSN] TFI: 0 TLLI: 0xcb46771f len=153 [0;m [0;33m<0002> gprs_rlcmac.cpp:988 Restarting UL TBF=0 timer 3169 while old timer 3169 pending [0;m [0;33m<0002> gprs_rlcmac.cpp:988 Restarting UL TBF=0 timer 3169 while old timer 3169 pending [0;m [0;33m<0002> gprs_rlcmac_data.cpp:1532 Polling sheduled in this TS 7 [0;m [0;33m<0002> gprs_rlcmac.cpp:988 Restarting DL TBF=0 timer 3191 while old timer 3191 pending [0;m [0;33m<0002> gprs_rlcmac.cpp:988 Restarting UL TBF=0 timer 3169 while old timer 3169 pending [0;m [1;36m<0005> gprs_rlcmac_data.cpp:740 Complete UL frame for TBF=0: len=62 [0;m [1;34m<0008> gprs_rlcmac.cpp:1760 LLC [PCU -> SGSN] TFI: 0 TLLI: 0xcb46771f len=62 [0;m [0;33m<0002> gprs_rlcmac.cpp:973 UL TBF=0 changes state from FLOW to FINISHED [0;m [0;33m<0002> gprs_rlcmac.cpp:988 Restarting UL TBF=0 timer 3169 while old timer 3169 pending [0;m [0;36m<0006> gprs_rlcmac_sched.cpp:260 Received RTS for PDCH: TRX=0 TS=7 FN=1292958 block_nr=7 scheduling free USF for polling at FN=1292962 of DL TFI=0 [0;m [0;33m<0002> gprs_rlcmac.cpp:988 Restarting UL TBF=0 timer 3169 while old timer 3169 pending [0;m [0;36m<0006> gprs_rlcmac_sched.cpp:260 Received RTS for PDCH: TRX=0 TS=7 FN=1292962 block_nr=8 scheduling free USF for polling at FN=1292967 of UL TFI=0 [0;m [0;33m<0002> gprs_rlcmac.cpp:988 Restarting UL TBF=0 timer 3169 while old timer 3169 pending [0;m [0;33m<0002> gprs_rlcmac.cpp:988 Restarting UL TBF=0 timer 3169 while old timer 3169 pending [0;m [0;33m<0002> gprs_rlcmac_data.cpp:270 +++++++++++++++++++++++++ RX : Uplink Control Block +++++++++++++++++++++++++ [0;m [0;33m<0002> gprs_rlcmac_data.cpp:273 ------------------------- RX : Uplink Control Block ------------------------- [0;m [0;33m<0002> gprs_rlcmac_data.cpp:388 Recovered downlink ack for DL TBF=0 [0;m [0;33m<0002> gprs_rlcmac.cpp:1005 Stopping DL TBF=0 timer 3191. [0;m [0;33m<0002> gprs_rlcmac_data.cpp:395 RX: [PCU <- BTS] TFI: 0 TLLI: 0xcb46771f Packet Downlink Ack/Nack [0;m [0;33m<0002> gprs_rlcmac.cpp:983 Starting DL TBF=0 timer 3193. [0;m [0;33m<0002> gprs_rlcmac.cpp:973 DL TBF=0 changes state from FINISHED to WAIT RELEASE [0;m [0;33m<0002> gprs_rlcmac_data.cpp:270 +++++++++++++++++++++++++ RX : Uplink Control Block +++++++++++++++++++++++++ [0;m [0;33m<0002> gprs_rlcmac_data.cpp:273 ------------------------- RX : Uplink Control Block ------------------------- [0;m [0;33m<0002> gprs_rlcmac_data.cpp:288 PACKET CONTROL ACK with expected FN=1292967 TLL=0xcb46771f (TRX 0 TS 7) [0;m [0;33m<0002> gprs_rlcmac_data.cpp:297 RX: [PCU <- BTS] TFI: 0 TLLI: 0xcb46771f Packet Control Ack [0;m [0;33m<0002> gprs_rlcmac_data.cpp:302 TBF: [UPLINK] END TFI: 0 TLLI: 0xcb46771f [0;m [0;33m<0002> gprs_rlcmac.cpp:895 Free UL TBF=0 with TLLI=0xcb46771f. [0;m [0;33m<0002> gprs_rlcmac.cpp:1005 Stopping UL TBF=0 timer 3169. [0;m [0;33m<0002> gprs_rlcmac.cpp:911 ********** TBF ends here ********** [0;m [1;34m<0008> gprs_bssgp_pcu.cpp:145 LLC [SGSN -> PCU] = TLLI: 0xcb46771f IMSI: 452022112638582 len: 62 [0;m [0;33m<0002> gprs_bssgp_pcu.cpp:149 TBF: APPEND TFI: 0 TLLI: 0xcb46771f [0;m [0;33m<0002> gprs_bssgp_pcu.cpp:152 TBF in WAIT RELEASE state (T3193), so reuse TBF [0;m [0;33m<0002> gprs_rlcmac.cpp:921 ********** TBF update ********** [0;m [0;33m<0002> gprs_rlcmac.cpp:421 Slot Allocation (Algorithm A) for class 10 [0;m [0;33m<0002> gprs_rlcmac.cpp:444 - Assign downlink TS=7 [0;m [0;33m<0002> gprs_rlcmac.cpp:1005 Stopping DL TBF=0 timer 3193. [0;m [0;33m<0002> gprs_rlcmac_data.cpp:1837 Send dowlink assignment on PACCH, because DL TBF=0 exists for TLLI=0xcb46771f [0;m [0;33m<0002> gprs_rlcmac.cpp:973 DL TBF=0 changes state from WAIT RELEASE to ASSIGN [0;m [0;33m<0002> gprs_rlcmac.cpp:983 Starting DL TBF=0 timer 0. [0;m [0;33m<0002> gprs_rlcmac_data.cpp:1764 TBF: START TFI: 0 TLLI: 0xcb46771f Packet Downlink Assignment (PACCH) [0;m [0;33m<0002> gprs_rlcmac_data.cpp:1769 +++++++++++++++++++++++++ TX : Packet Downlink Assignment +++++++++++++++++++++++++ [0;m [0;33m<0002> gprs_rlcmac_data.cpp:1772 ------------------------- TX : Packet Downlink Assignment ------------------------- [0;m [1;34m<0008> gprs_bssgp_pcu.cpp:145 LLC [SGSN -> PCU] = TLLI: 0xcb46771f IMSI: 452022112638582 len: 506 [0;m [0;33m<0002> gprs_bssgp_pcu.cpp:149 TBF: APPEND TFI: 0 TLLI: 0xcb46771f [0;m [1;34m<0008> gprs_bssgp_pcu.cpp:145 LLC [SGSN -> PCU] = TLLI: 0xcb46771f IMSI: 452022112638582 len: 506 [0;m [0;33m<0002> gprs_bssgp_pcu.cpp:149 TBF: APPEND TFI: 0 TLLI: 0xcb46771f [0;m [1;34m<0008> gprs_bssgp_pcu.cpp:145 LLC [SGSN -> PCU] = TLLI: 0xcb46771f IMSI: 452022112638582 len: 416 [0;m [0;33m<0002> gprs_bssgp_pcu.cpp:149 TBF: APPEND TFI: 0 TLLI: 0xcb46771f [0;m [1;34m<0008> gprs_bssgp_pcu.cpp:145 LLC [SGSN -> PCU] = TLLI: 0xcb46771f IMSI: 452022112638582 len: 506 [0;m [0;33m<0002> gprs_bssgp_pcu.cpp:149 TBF: APPEND TFI: 0 TLLI: 0xcb46771f [0;m [1;34m<0008> gprs_bssgp_pcu.cpp:145 LLC [SGSN -> PCU] = TLLI: 0xcb46771f IMSI: 452022112638582 len: 506 [0;m [0;33m<0002> gprs_bssgp_pcu.cpp:149 TBF: APPEND TFI: 0 TLLI: 0xcb46771f [0;m [1;34m<0008> gprs_bssgp_pcu.cpp:145 LLC [SGSN -> PCU] = TLLI: 0xcb46771f IMSI: 452022112638582 len: 416 [0;m [0;33m<0002> gprs_bssgp_pcu.cpp:149 TBF: APPEND TFI: 0 TLLI: 0xcb46771f [0;m [1;34m<0008> gprs_bssgp_pcu.cpp:145 LLC [SGSN -> PCU] = TLLI: 0xcb46771f IMSI: 452022112638582 len: 506 [0;m [0;33m<0002> gprs_bssgp_pcu.cpp:149 TBF: APPEND TFI: 0 TLLI: 0xcb46771f [0;m [1;34m<0008> gprs_bssgp_pcu.cpp:145 LLC [SGSN -> PCU] = TLLI: 0xcb46771f IMSI: 452022112638582 len: 506 [0;m [0;33m<0002> gprs_bssgp_pcu.cpp:149 TBF: APPEND TFI: 0 TLLI: 0xcb46771f [0;m [1;34m<0008> gprs_bssgp_pcu.cpp:145 LLC [SGSN -> PCU] = TLLI: 0xcb46771f IMSI: 452022112638582 len: 268 [0;m [0;33m<0002> gprs_bssgp_pcu.cpp:149 TBF: APPEND TFI: 0 TLLI: 0xcb46771f [0;m [0;36m<0006> gprs_rlcmac_sched.cpp:260 Received RTS for PDCH: TRX=0 TS=7 FN=1292997 block_nr=4 scheduling free USF for polling at FN=1293001 of DL TFI=0 [0;m [0;33m<0002> gprs_rlcmac_data.cpp:270 +++++++++++++++++++++++++ RX : Uplink Control Block +++++++++++++++++++++++++ [0;m [0;33m<0002> gprs_rlcmac_data.cpp:273 ------------------------- RX : Uplink Control Block ------------------------- [0;m [0;33m<0002> gprs_rlcmac_data.cpp:281 PACKET CONTROL ACK with unknown FN=1292997 TLL=0xcb46771f (TRX 0 TS 7) [0;m [0;33m<0002> gprs_rlcmac_data.cpp:100 Poll timeout for DL TBF=0 [0;m [0;33m<0002> gprs_rlcmac_data.cpp:158 - Timeout for polling PACKET CONTROL ACK for PACKET DOWNLINK ASSIGNMENT. [0;m [0;33m<0002> gprs_rlcmac_data.cpp:84 - Assignment was on PACCH [0;m [0;33m<0002> gprs_rlcmac_data.cpp:92 - No downlink ACK received yet [0;m [0;33m<0002> gprs_rlcmac_data.cpp:1764 TBF: START TFI: 0 TLLI: 0xcb46771f Packet Downlink Assignment (PACCH) [0;m [0;33m<0002> gprs_rlcmac_data.cpp:1769 +++++++++++++++++++++++++ TX : Packet Downlink Assignment +++++++++++++++++++++++++ [0;m [0;33m<0002> gprs_rlcmac_data.cpp:1772 ------------------------- TX : Packet Downlink Assignment ------------------------- [0;m [0;36m<0006> gprs_rlcmac_sched.cpp:260 Received RTS for PDCH: TRX=0 TS=7 FN=1293157 block_nr=5 scheduling free USF for polling at FN=1293162 of DL TFI=0 [0;m [0;33m<0002> gprs_rlcmac_data.cpp:270 +++++++++++++++++++++++++ RX : Uplink Control Block +++++++++++++++++++++++++ [0;m [0;33m<0002> gprs_rlcmac_data.cpp:273 ------------------------- RX : Uplink Control Block ------------------------- [0;m [0;33m<0002> gprs_rlcmac_data.cpp:288 PACKET CONTROL ACK with expected FN=1293162 TLL=0xcb46771f (TRX 0 TS 7) [0;m [0;33m<0002> gprs_rlcmac_data.cpp:297 RX: [PCU <- BTS] TFI: 0 TLLI: 0xcb46771f Packet Control Ack [0;m [0;33m<0002> gprs_rlcmac_data.cpp:316 TBF: [UPLINK] DOWNLINK ASSIGNED TFI: 0 TLLI: 0xcb46771f [0;m [0;33m<0002> gprs_rlcmac.cpp:973 DL TBF=0 changes state from ASSIGN to FLOW [0;m [0;33m<0002> gprs_rlcmac.cpp:1005 Stopping DL TBF=0 timer 0. [0;m [0;33m<0002> gprs_rlcmac_data.cpp:337 Recovered downlink assignment for DL TBF=0 [0;m [1;33m<0004> gprs_rlcmac_data.cpp:1453 Complete DL frame for TBF=0: len=62 [0;m [1;33m<0004> gprs_rlcmac_data.cpp:1461 - Dequeue next LLC for TBF=0 (len=506) [0;m [0;33m<0002> gprs_rlcmac_data.cpp:1532 Polling sheduled in this TS 7 [0;m [0;36m<0006> gprs_rlcmac_sched.cpp:260 Received RTS for PDCH: TRX=0 TS=7 FN=1293274 block_nr=8 scheduling free USF for polling at FN=1293279 of DL TFI=0 [0;m [0;33m<0002> gprs_rlcmac_data.cpp:270 +++++++++++++++++++++++++ RX : Uplink Control Block +++++++++++++++++++++++++ [0;m [0;33m<0002> gprs_rlcmac_data.cpp:273 ------------------------- RX : Uplink Control Block ------------------------- [0;m [0;33m<0002> gprs_rlcmac_data.cpp:395 RX: [PCU <- BTS] TFI: 0 TLLI: 0xcb46771f Packet Downlink Ack/Nack [0;m [0;33m<0002> gprs_rlcmac_data.cpp:410 MS requests UL TBF in ack message, so we provide one: [0;m [0;33m<0002> gprs_rlcmac.cpp:214 Searching for first unallocated TFI: TRX=0 first TS=7 [0;m [0;33m<0002> gprs_rlcmac.cpp:225 Found TFI=0. [0;m [0;33m<0002> gprs_rlcmac.cpp:351 ********** TBF starts here ********** [0;m [0;33m<0002> gprs_rlcmac.cpp:354 Allocating UL TBF: TFI=0 TRX=0 MS_CLASS=10 [0;m [0;33m<0002> gprs_rlcmac.cpp:421 Slot Allocation (Algorithm A) for class 10 [0;m [0;33m<0002> gprs_rlcmac.cpp:434 - Assign uplink TS=7 USF=0 [0;m [0;33m<0002> gprs_rlcmac.cpp:948 - Setting Control TS 7 [0;m [0;33m<0002> gprs_rlcmac.cpp:973 UL TBF=0 changes state from NULL to ASSIGN [0;m [0;33m<0002> gprs_rlcmac.cpp:983 Starting UL TBF=0 timer 3169. [0;m [0;33m<0002> gprs_rlcmac_data.cpp:1069 TBF: START TFI: 0 TLLI: 0xcb46771f Packet Uplink Assignment (PACCH) [0;m [0;33m<0002> gprs_rlcmac_data.cpp:1083 +++++++++++++++++++++++++ TX : Packet Uplink Assignment +++++++++++++++++++++++++ [0;m [0;33m<0002> gprs_rlcmac_data.cpp:1086 ------------------------- TX : Packet Uplink Assignment ------------------------- [0;m [0;36m<0006> gprs_rlcmac_sched.cpp:260 Received RTS for PDCH: TRX=0 TS=7 FN=1293305 block_nr=3 scheduling free USF for polling at FN=1293309 of DL TFI=0 [0;m [1;33m<0004> gprs_rlcmac_data.cpp:1453 Complete DL frame for TBF=0: len=506 [0;m [1;33m<0004> gprs_rlcmac_data.cpp:1461 - Dequeue next LLC for TBF=0 (len=506) [0;m [0;33m<0002> gprs_rlcmac_data.cpp:270 +++++++++++++++++++++++++ RX : Uplink Control Block +++++++++++++++++++++++++ [0;m [0;33m<0002> gprs_rlcmac_data.cpp:273 ------------------------- RX : Uplink Control Block ------------------------- [0;m [0;33m<0002> gprs_rlcmac_data.cpp:288 PACKET CONTROL ACK with expected FN=1293309 TLL=0xcb46771f (TRX 0 TS 7) [0;m [0;33m<0002> gprs_rlcmac_data.cpp:297 RX: [PCU <- BTS] TFI: 0 TLLI: 0xcb46771f Packet Control Ack [0;m [0;33m<0002> gprs_rlcmac_data.cpp:343 TBF: [DOWNLINK] UPLINK ASSIGNED TFI: 0 TLLI: 0xcb46771f [0;m [0;33m<0002> gprs_rlcmac.cpp:973 UL TBF=0 changes state from ASSIGN to FLOW [0;m [0;33m<0002> gprs_rlcmac.cpp:988 Restarting UL TBF=0 timer 3169 while old timer 3169 pending [0;m [0;33m<0002> gprs_rlcmac.cpp:988 Restarting UL TBF=0 timer 3169 while old timer 3169 pending [0;m [0;33m<0002> gprs_rlcmac.cpp:988 Restarting UL TBF=0 timer 3169 while old timer 3169 pending [0;m [0;33m<0002> gprs_rlcmac_data.cpp:1532 Polling sheduled in this TS 7 [0;m [0;33m<0002> gprs_rlcmac.cpp:988 Restarting UL TBF=0 timer 3169 while old timer 3169 pending [0;m [1;36m<0005> gprs_rlcmac_data.cpp:740 Complete UL frame for TBF=0: len=62 [0;m [1;34m<0008> gprs_rlcmac.cpp:1760 LLC [PCU -> SGSN] TFI: 0 TLLI: 0xcb46771f len=62 [0;m [0;33m<0002> gprs_rlcmac.cpp:973 UL TBF=0 changes state from FLOW to FINISHED [0;m [0;33m<0002> gprs_rlcmac.cpp:988 Restarting UL TBF=0 timer 3169 while old timer 3169 pending [0;m [0;36m<0006> gprs_rlcmac_sched.cpp:260 Received RTS for PDCH: TRX=0 TS=7 FN=1293365 block_nr=5 scheduling free USF for polling at FN=1293370 of DL TFI=0 [0;m [0;33m<0002> gprs_rlcmac.cpp:988 Restarting UL TBF=0 timer 3169 while old timer 3169 pending [0;m [0;36m<0006> gprs_rlcmac_sched.cpp:260 Received RTS for PDCH: TRX=0 TS=7 FN=1293370 block_nr=6 scheduling free USF for polling at FN=1293374 of UL TFI=0 [0;m [0;33m<0002> gprs_rlcmac.cpp:988 Restarting UL TBF=0 timer 3169 while old timer 3169 pending [0;m [0;33m<0002> gprs_rlcmac.cpp:988 Restarting UL TBF=0 timer 3169 while old timer 3169 pending [0;m [0;33m<0002> gprs_rlcmac_data.cpp:270 +++++++++++++++++++++++++ RX : Uplink Control Block +++++++++++++++++++++++++ [0;m [0;33m<0002> gprs_rlcmac_data.cpp:273 ------------------------- RX : Uplink Control Block ------------------------- [0;m [0;33m<0002> gprs_rlcmac_data.cpp:395 RX: [PCU <- BTS] TFI: 0 TLLI: 0xcb46771f Packet Downlink Ack/Nack [0;m [0;33m<0002> gprs_rlcmac_data.cpp:270 +++++++++++++++++++++++++ RX : Uplink Control Block +++++++++++++++++++++++++ [0;m [0;33m<0002> gprs_rlcmac_data.cpp:273 ------------------------- RX : Uplink Control Block ------------------------- [0;m [0;33m<0002> gprs_rlcmac_data.cpp:288 PACKET CONTROL ACK with expected FN=1293374 TLL=0xcb46771f (TRX 0 TS 7) [0;m [0;33m<0002> gprs_rlcmac_data.cpp:297 RX: [PCU <- BTS] TFI: 0 TLLI: 0xcb46771f Packet Control Ack [0;m [0;33m<0002> gprs_rlcmac_data.cpp:302 TBF: [UPLINK] END TFI: 0 TLLI: 0xcb46771f [0;m [0;33m<0002> gprs_rlcmac.cpp:895 Free UL TBF=0 with TLLI=0xcb46771f. [0;m [0;33m<0002> gprs_rlcmac.cpp:1005 Stopping UL TBF=0 timer 3169. [0;m [0;33m<0002> gprs_rlcmac.cpp:911 ********** TBF ends here ********** [0;m [1;33m<0004> gprs_rlcmac_data.cpp:1453 Complete DL frame for TBF=0: len=506 [0;m [1;33m<0004> gprs_rlcmac_data.cpp:1461 - Dequeue next LLC for TBF=0 (len=416) [0;m [0;33m<0002> gprs_rlcmac_data.cpp:1532 Polling sheduled in this TS 7 [0;m [0;36m<0006> gprs_rlcmac_sched.cpp:260 Received RTS for PDCH: TRX=0 TS=7 FN=1293456 block_nr=2 scheduling free USF for polling at FN=1293461 of DL TFI=0 [0;m [0;33m<0002> gprs_rlcmac_data.cpp:270 +++++++++++++++++++++++++ RX : Uplink Control Block +++++++++++++++++++++++++ [0;m [0;33m<0002> gprs_rlcmac_data.cpp:273 ------------------------- RX : Uplink Control Block ------------------------- [0;m [0;33m<0002> gprs_rlcmac_data.cpp:395 RX: [PCU <- BTS] TFI: 0 TLLI: 0xcb46771f Packet Downlink Ack/Nack [0;m [1;33m<0004> gprs_rlcmac_data.cpp:1453 Complete DL frame for TBF=0: len=416 [0;m [1;33m<0004> gprs_rlcmac_data.cpp:1461 - Dequeue next LLC for TBF=0 (len=506) [0;m [0;33m<0002> gprs_rlcmac_data.cpp:1532 Polling sheduled in this TS 7 [0;m [0;36m<0006> gprs_rlcmac_sched.cpp:260 Received RTS for PDCH: TRX=0 TS=7 FN=1293543 block_nr=10 scheduling free USF for polling at FN=1293547 of DL TFI=0 [0;m [0;33m<0002> gprs_rlcmac_data.cpp:270 +++++++++++++++++++++++++ RX : Uplink Control Block +++++++++++++++++++++++++ [0;m [0;33m<0002> gprs_rlcmac_data.cpp:273 ------------------------- RX : Uplink Control Block ------------------------- [0;m [0;33m<0002> gprs_rlcmac_data.cpp:376 PACKET DOWNLINK ACK with unknown FN=1293543 TFI=0 (TRX 0 TS 7) [0;m [0;33m<0002> gprs_rlcmac_data.cpp:100 Poll timeout for DL TBF=0 [0;m [0;33m<0002> gprs_rlcmac_data.cpp:180 - Timeout for polling PACKET DOWNLINK ACK. [0;m [0;33m<0002> gprs_rlcmac_data.cpp:84 - Assignment was on PACCH [0;m [0;33m<0002> gprs_rlcmac_data.cpp:90 - Downlink ACK was received [0;m [1;33m<0004> gprs_rlcmac_data.cpp:1453 Complete DL frame for TBF=0: len=506 [0;m [1;33m<0004> gprs_rlcmac_data.cpp:1461 - Dequeue next LLC for TBF=0 (len=506) [0;m [0;33m<0002> gprs_rlcmac_data.cpp:1532 Polling sheduled in this TS 7 [0;m [0;36m<0006> gprs_rlcmac_sched.cpp:260 Received RTS for PDCH: TRX=0 TS=7 FN=1293630 block_nr=6 scheduling free USF for polling at FN=1293634 of DL TFI=0 [0;m [0;33m<0002> gprs_rlcmac_data.cpp:270 +++++++++++++++++++++++++ RX : Uplink Control Block +++++++++++++++++++++++++ [0;m [0;33m<0002> gprs_rlcmac_data.cpp:273 ------------------------- RX : Uplink Control Block ------------------------- [0;m [0;33m<0002> gprs_rlcmac_data.cpp:388 Recovered downlink ack for DL TBF=0 [0;m [0;33m<0002> gprs_rlcmac_data.cpp:395 RX: [PCU <- BTS] TFI: 0 TLLI: 0xcb46771f Packet Downlink Ack/Nack [0;m [0;33m<0002> gprs_rlcmac_data.cpp:410 MS requests UL TBF in ack message, so we provide one: [0;m [0;33m<0002> gprs_rlcmac.cpp:214 Searching for first unallocated TFI: TRX=0 first TS=7 [0;m [0;33m<0002> gprs_rlcmac.cpp:225 Found TFI=0. [0;m [0;33m<0002> gprs_rlcmac.cpp:351 ********** TBF starts here ********** [0;m [0;33m<0002> gprs_rlcmac.cpp:354 Allocating UL TBF: TFI=0 TRX=0 MS_CLASS=10 [0;m [0;33m<0002> gprs_rlcmac.cpp:421 Slot Allocation (Algorithm A) for class 10 [0;m [0;33m<0002> gprs_rlcmac.cpp:434 - Assign uplink TS=7 USF=0 [0;m [0;33m<0002> gprs_rlcmac.cpp:948 - Setting Control TS 7 [0;m [0;33m<0002> gprs_rlcmac.cpp:973 UL TBF=0 changes state from NULL to ASSIGN [0;m [0;33m<0002> gprs_rlcmac.cpp:983 Starting UL TBF=0 timer 3169. [0;m [0;33m<0002> gprs_rlcmac_data.cpp:1069 TBF: START TFI: 0 TLLI: 0xcb46771f Packet Uplink Assignment (PACCH) [0;m [0;33m<0002> gprs_rlcmac_data.cpp:1083 +++++++++++++++++++++++++ TX : Packet Uplink Assignment +++++++++++++++++++++++++ [0;m [0;33m<0002> gprs_rlcmac_data.cpp:1086 ------------------------- TX : Packet Uplink Assignment ------------------------- [0;m [0;36m<0006> gprs_rlcmac_sched.cpp:260 Received RTS for PDCH: TRX=0 TS=7 FN=1293660 block_nr=1 scheduling free USF for polling at FN=1293664 of DL TFI=0 [0;m [1;34m<0008> gprs_bssgp_pcu.cpp:145 LLC [SGSN -> PCU] = TLLI: 0xcb46771f IMSI: 452022112638582 len: 506 [0;m [0;33m<0002> gprs_bssgp_pcu.cpp:149 TBF: APPEND TFI: 0 TLLI: 0xcb46771f [0;m [1;34m<0008> gprs_bssgp_pcu.cpp:145 LLC [SGSN -> PCU] = TLLI: 0xcb46771f IMSI: 452022112638582 len: 506 [0;m [0;33m<0002> gprs_bssgp_pcu.cpp:149 TBF: APPEND TFI: 0 TLLI: 0xcb46771f [0;m [1;34m<0008> gprs_bssgp_pcu.cpp:145 LLC [SGSN -> PCU] = TLLI: 0xcb46771f IMSI: 452022112638582 len: 416 [0;m [0;33m<0002> gprs_bssgp_pcu.cpp:149 TBF: APPEND TFI: 0 TLLI: 0xcb46771f [0;m [0;33m<0002> gprs_rlcmac_data.cpp:270 +++++++++++++++++++++++++ RX : Uplink Control Block +++++++++++++++++++++++++ [0;m [0;33m<0002> gprs_rlcmac_data.cpp:273 ------------------------- RX : Uplink Control Block ------------------------- [0;m [0;33m<0002> gprs_rlcmac_data.cpp:288 PACKET CONTROL ACK with expected FN=1293664 TLL=0xcb46771f (TRX 0 TS 7) [0;m [0;33m<0002> gprs_rlcmac_data.cpp:297 RX: [PCU <- BTS] TFI: 0 TLLI: 0xcb46771f Packet Control Ack [0;m [0;33m<0002> gprs_rlcmac_data.cpp:343 TBF: [DOWNLINK] UPLINK ASSIGNED TFI: 0 TLLI: 0xcb46771f [0;m [0;33m<0002> gprs_rlcmac.cpp:973 UL TBF=0 changes state from ASSIGN to FLOW [0;m [0;33m<0002> gprs_rlcmac.cpp:988 Restarting UL TBF=0 timer 3169 while old timer 3169 pending [0;m [0;33m<0002> gprs_rlcmac.cpp:988 Restarting UL TBF=0 timer 3169 while old timer 3169 pending [0;m [0;33m<0002> gprs_rlcmac.cpp:988 Restarting UL TBF=0 timer 3169 while old timer 3169 pending [0;m [0;33m<0002> gprs_rlcmac_data.cpp:1532 Polling sheduled in this TS 7 [0;m [0;33m<0002> gprs_rlcmac.cpp:988 Restarting UL TBF=0 timer 3169 while old timer 3169 pending [0;m [1;36m<0005> gprs_rlcmac_data.cpp:740 Complete UL frame for TBF=0: len=62 [0;m [1;34m<0008> gprs_rlcmac.cpp:1760 LLC [PCU -> SGSN] TFI: 0 TLLI: 0xcb46771f len=62 [0;m [0;33m<0002> gprs_rlcmac.cpp:973 UL TBF=0 changes state from FLOW to FINISHED [0;m [0;33m<0002> gprs_rlcmac.cpp:988 Restarting UL TBF=0 timer 3169 while old timer 3169 pending [0;m [0;36m<0006> gprs_rlcmac_sched.cpp:260 Received RTS for PDCH: TRX=0 TS=7 FN=1293721 block_nr=3 scheduling free USF for polling at FN=1293725 of DL TFI=0 [0;m [0;33m<0002> gprs_rlcmac.cpp:988 Restarting UL TBF=0 timer 3169 while old timer 3169 pending [0;m [0;36m<0006> gprs_rlcmac_sched.cpp:260 Received RTS for PDCH: TRX=0 TS=7 FN=1293725 block_nr=4 scheduling free USF for polling at FN=1293729 of UL TFI=0 [0;m [0;33m<0002> gprs_rlcmac.cpp:988 Restarting UL TBF=0 timer 3169 while old timer 3169 pending [0;m [0;33m<0002> gprs_rlcmac.cpp:988 Restarting UL TBF=0 timer 3169 while old timer 3169 pending [0;m [1;33m<0004> gprs_rlcmac_data.cpp:1453 Complete DL frame for TBF=0: len=506 [0;m [1;33m<0004> gprs_rlcmac_data.cpp:1461 - Dequeue next LLC for TBF=0 (len=416) [0;m [0;33m<0002> gprs_rlcmac_data.cpp:270 +++++++++++++++++++++++++ RX : Uplink Control Block +++++++++++++++++++++++++ [0;m [0;33m<0002> gprs_rlcmac_data.cpp:273 ------------------------- RX : Uplink Control Block ------------------------- [0;m [0;33m<0002> gprs_rlcmac_data.cpp:288 PACKET CONTROL ACK with expected FN=1293725 TLL=0xcb46771f (TRX 0 TS 7) [0;m [0;33m<0002> gprs_rlcmac_data.cpp:297 RX: [PCU <- BTS] TFI: 0 TLLI: 0xcb46771f Packet Control Ack [0;m [0;33m<0002> gprs_rlcmac_data.cpp:368 Error: received PACET CONTROL ACK at no request [0;m [0;33m<0002> gprs_rlcmac_data.cpp:1532 Polling sheduled in this TS 7 [0;m [0;33m<0002> gprs_rlcmac_data.cpp:100 Poll timeout for UL TBF=0 [0;m [0;33m<0002> gprs_rlcmac_data.cpp:107 - Timeout for polling PACKET CONTROL ACK for PACKET UPLINK ACK [0;m [0;33m<0002> gprs_rlcmac_data.cpp:84 - Assignment was on PACCH [0;m [0;33m<0002> gprs_rlcmac_data.cpp:86 - Uplink data was received [0;m [0;36m<0006> gprs_rlcmac_sched.cpp:260 Received RTS for PDCH: TRX=0 TS=7 FN=1293812 block_nr=0 scheduling free USF for polling at FN=1293816 of DL TFI=0 [0;m [0;36m<0006> gprs_rlcmac_sched.cpp:260 Received RTS for PDCH: TRX=0 TS=7 FN=1293820 block_nr=2 scheduling free USF for polling at FN=1293825 of UL TFI=0 [0;m [0;33m<0002> gprs_rlcmac_data.cpp:270 +++++++++++++++++++++++++ RX : Uplink Control Block +++++++++++++++++++++++++ [0;m [0;33m<0002> gprs_rlcmac_data.cpp:273 ------------------------- RX : Uplink Control Block ------------------------- [0;m [0;33m<0002> gprs_rlcmac_data.cpp:395 RX: [PCU <- BTS] TFI: 0 TLLI: 0xcb46771f Packet Downlink Ack/Nack [0;m [1;33m<0004> gprs_rlcmac_data.cpp:1453 Complete DL frame for TBF=0: len=416 [0;m [1;33m<0004> gprs_rlcmac_data.cpp:1461 - Dequeue next LLC for TBF=0 (len=506) [0;m [0;33m<0002> gprs_rlcmac_data.cpp:1532 Polling sheduled in this TS 7 [0;m [0;36m<0006> gprs_rlcmac_sched.cpp:260 Received RTS for PDCH: TRX=0 TS=7 FN=1293903 block_nr=9 scheduling free USF for polling at FN=1293907 of DL TFI=0 [0;m [0;33m<0002> gprs_rlcmac_data.cpp:270 +++++++++++++++++++++++++ RX : Uplink Control Block +++++++++++++++++++++++++ [0;m [0;33m<0002> gprs_rlcmac_data.cpp:273 ------------------------- RX : Uplink Control Block ------------------------- [0;m [0;33m<0002> gprs_rlcmac_data.cpp:395 RX: [PCU <- BTS] TFI: 0 TLLI: 0xcb46771f Packet Downlink Ack/Nack [0;m [1;33m<0004> gprs_rlcmac_data.cpp:1453 Complete DL frame for TBF=0: len=506 [0;m [1;33m<0004> gprs_rlcmac_data.cpp:1461 - Dequeue next LLC for TBF=0 (len=506) [0;m [0;33m<0002> gprs_rlcmac_data.cpp:1532 Polling sheduled in this TS 7 [0;m [0;36m<0006> gprs_rlcmac_sched.cpp:260 Received RTS for PDCH: TRX=0 TS=7 FN=1293989 block_nr=5 scheduling free USF for polling at FN=1293994 of DL TFI=0 [0;m [0;33m<0002> gprs_rlcmac_data.cpp:270 +++++++++++++++++++++++++ RX : Uplink Control Block +++++++++++++++++++++++++ [0;m [0;33m<0002> gprs_rlcmac_data.cpp:273 ------------------------- RX : Uplink Control Block ------------------------- [0;m [0;33m<0002> gprs_rlcmac_data.cpp:395 RX: [PCU <- BTS] TFI: 0 TLLI: 0xcb46771f Packet Downlink Ack/Nack [0;m [0;33m<0002> gprs_rlcmac_data.cpp:410 MS requests UL TBF in ack message, so we provide one: [0;m [0;33m<0002> gprs_rlcmac.cpp:214 Searching for first unallocated TFI: TRX=0 first TS=7 [0;m [0;33m<0002> gprs_rlcmac.cpp:225 Found TFI=1. [0;m [0;33m<0002> gprs_rlcmac.cpp:351 ********** TBF starts here ********** [0;m [0;33m<0002> gprs_rlcmac.cpp:354 Allocating UL TBF: TFI=1 TRX=0 MS_CLASS=10 [0;m [0;33m<0002> gprs_rlcmac.cpp:421 Slot Allocation (Algorithm A) for class 10 [0;m [0;33m<0002> gprs_rlcmac.cpp:434 - Assign uplink TS=7 USF=1 [0;m [0;33m<0002> gprs_rlcmac.cpp:948 - Setting Control TS 7 [0;m [0;33m<0002> gprs_rlcmac.cpp:973 UL TBF=1 changes state from NULL to ASSIGN [0;m [0;33m<0002> gprs_rlcmac.cpp:983 Starting UL TBF=1 timer 3169. [0;m [0;33m<0002> gprs_rlcmac_data.cpp:100 Poll timeout for UL TBF=0 [0;m [0;33m<0002> gprs_rlcmac_data.cpp:1069 TBF: START TFI: 1 TLLI: 0xcb46771f Packet Uplink Assignment (PACCH) [0;m [0;33m<0002> gprs_rlcmac_data.cpp:1083 +++++++++++++++++++++++++ TX : Packet Uplink Assignment +++++++++++++++++++++++++ [0;m [0;33m<0002> gprs_rlcmac_data.cpp:1086 ------------------------- TX : Packet Uplink Assignment ------------------------- [0;m [0;36m<0006> gprs_rlcmac_sched.cpp:260 Received RTS for PDCH: TRX=0 TS=7 FN=1294020 block_nr=0 scheduling free USF for polling at FN=1294024 of DL TFI=0 [0;m [0;36m<0006> gprs_rlcmac_sched.cpp:260 Received RTS for PDCH: TRX=0 TS=7 FN=1294024 block_nr=1 scheduling free USF for polling at FN=1294028 of UL TFI=0 [0;m [0;33m<0002> gprs_rlcmac_data.cpp:270 +++++++++++++++++++++++++ RX : Uplink Control Block +++++++++++++++++++++++++ [0;m [0;33m<0002> gprs_rlcmac_data.cpp:273 ------------------------- RX : Uplink Control Block ------------------------- [0;m [0;33m<0002> gprs_rlcmac_data.cpp:288 PACKET CONTROL ACK with expected FN=1294024 TLL=0xcb46771f (TRX 0 TS 7) [0;m [0;33m<0002> gprs_rlcmac_data.cpp:297 RX: [PCU <- BTS] TFI: 0 TLLI: 0xcb46771f Packet Control Ack [0;m [0;33m<0002> gprs_rlcmac_data.cpp:343 TBF: [DOWNLINK] UPLINK ASSIGNED TFI: 0 TLLI: 0xcb46771f [0;m [0;33m<0002> gprs_rlcmac.cpp:973 UL TBF=1 changes state from ASSIGN to FLOW [0;m [0;33m<0002> gprs_rlcmac_data.cpp:100 Poll timeout for UL TBF=0 [0;m [0;33m<0002> gprs_rlcmac.cpp:988 Restarting UL TBF=1 timer 3169 while old timer 3169 pending [0;m [1;33m<0004> gprs_rlcmac_data.cpp:1453 Complete DL frame for TBF=0: len=506 [0;m [1;33m<0004> gprs_rlcmac_data.cpp:1461 - Dequeue next LLC for TBF=0 (len=268) [0;m [0;33m<0002> gprs_rlcmac.cpp:988 Restarting UL TBF=1 timer 3169 while old timer 3169 pending [0;m [0;33m<0002> gprs_rlcmac.cpp:988 Restarting UL TBF=1 timer 3169 while old timer 3169 pending [0;m [0;36m<0006> gprs_rlcmac_sched.cpp:260 Received RTS for PDCH: TRX=0 TS=7 FN=1294067 block_nr=11 scheduling free USF for polling at FN=1294072 of UL TFI=0 [0;m [0;33m<0002> gprs_rlcmac.cpp:988 Restarting UL TBF=1 timer 3169 while old timer 3169 pending [0;m [1;36m<0005> gprs_rlcmac_data.cpp:740 Complete UL frame for TBF=1: len=62 [0;m [1;34m<0008> gprs_rlcmac.cpp:1760 LLC [PCU -> SGSN] TFI: 1 TLLI: 0xcb46771f len=62 [0;m [0;33m<0002> gprs_rlcmac.cpp:973 UL TBF=1 changes state from FLOW to FINISHED [0;m [0;33m<0002> gprs_rlcmac.cpp:988 Restarting UL TBF=1 timer 3169 while old timer 3169 pending [0;m [0;33m<0002> gprs_rlcmac.cpp:988 Restarting UL TBF=1 timer 3169 while old timer 3169 pending [0;m [0;36m<0006> gprs_rlcmac_sched.cpp:260 Received RTS for PDCH: TRX=0 TS=7 FN=1294085 block_nr=3 scheduling free USF for polling at FN=1294089 of UL TFI=1 [0;m [0;33m<0002> gprs_rlcmac_data.cpp:1532 Polling sheduled in this TS 7 [0;m [0;33m<0002> gprs_rlcmac.cpp:988 Restarting UL TBF=1 timer 3169 while old timer 3169 pending [0;m [0;36m<0006> gprs_rlcmac_sched.cpp:260 Received RTS for PDCH: TRX=0 TS=7 FN=1294093 block_nr=5 scheduling free USF for polling at FN=1294098 of DL TFI=0 [0;m [0;33m<0002> gprs_rlcmac_data.cpp:270 +++++++++++++++++++++++++ RX : Uplink Control Block +++++++++++++++++++++++++ [0;m [0;33m<0002> gprs_rlcmac_data.cpp:273 ------------------------- RX : Uplink Control Block ------------------------- [0;m [0;33m<0002> gprs_rlcmac_data.cpp:288 PACKET CONTROL ACK with expected FN=1294089 TLL=0xcb46771f (TRX 0 TS 7) [0;m [0;33m<0002> gprs_rlcmac_data.cpp:297 RX: [PCU <- BTS] TFI: 1 TLLI: 0xcb46771f Packet Control Ack [0;m [0;33m<0002> gprs_rlcmac_data.cpp:302 TBF: [UPLINK] END TFI: 1 TLLI: 0xcb46771f [0;m [0;33m<0002> gprs_rlcmac.cpp:895 Free UL TBF=1 with TLLI=0xcb46771f. [0;m [0;33m<0002> gprs_rlcmac.cpp:1005 Stopping UL TBF=1 timer 3169. [0;m [0;33m<0002> gprs_rlcmac.cpp:911 ********** TBF ends here ********** [0;m [0;33m<0002> gprs_rlcmac_data.cpp:270 +++++++++++++++++++++++++ RX : Uplink Control Block +++++++++++++++++++++++++ [0;m [0;33m<0002> gprs_rlcmac_data.cpp:273 ------------------------- RX : Uplink Control Block ------------------------- [0;m [0;33m<0002> gprs_rlcmac_data.cpp:395 RX: [PCU <- BTS] TFI: 0 TLLI: 0xcb46771f Packet Downlink Ack/Nack [0;m [1;33m<0004> gprs_rlcmac_data.cpp:1453 Complete DL frame for TBF=0: len=268 [0;m [1;33m<0004> gprs_rlcmac_data.cpp:1461 - Dequeue next LLC for TBF=0 (len=506) [0;m [0;33m<0002> gprs_rlcmac_data.cpp:1532 Polling sheduled in this TS 7 [0;m [0;36m<0006> gprs_rlcmac_sched.cpp:260 Received RTS for PDCH: TRX=0 TS=7 FN=1294180 block_nr=1 scheduling free USF for polling at FN=1294184 of DL TFI=0 [0;m [0;33m<0002> gprs_rlcmac_data.cpp:270 +++++++++++++++++++++++++ RX : Uplink Control Block +++++++++++++++++++++++++ [0;m [0;33m<0002> gprs_rlcmac_data.cpp:273 ------------------------- RX : Uplink Control Block ------------------------- [0;m [0;33m<0002> gprs_rlcmac_data.cpp:395 RX: [PCU <- BTS] TFI: 0 TLLI: 0xcb46771f Packet Downlink Ack/Nack [0;m [0;33m<0002> gprs_rlcmac_data.cpp:100 Poll timeout for UL TBF=0 [0;m [0;33m<0002> gprs_rlcmac_data.cpp:119 - N3103 exceeded [0;m [0;33m<0002> gprs_rlcmac.cpp:973 UL TBF=0 changes state from FINISHED to RELEASING [0;m [0;33m<0002> gprs_rlcmac.cpp:988 Restarting UL TBF=0 timer 3169 while old timer 3169 pending [0;m [1;33m<0004> gprs_rlcmac_data.cpp:1453 Complete DL frame for TBF=0: len=506 [0;m [1;33m<0004> gprs_rlcmac_data.cpp:1461 - Dequeue next LLC for TBF=0 (len=506) [0;m [0;33m<0002> gprs_rlcmac_data.cpp:1532 Polling sheduled in this TS 7 [0;m [0;36m<0006> gprs_rlcmac_sched.cpp:260 Received RTS for PDCH: TRX=0 TS=7 FN=1294267 block_nr=9 scheduling free USF for polling at FN=1294271 of DL TFI=0 [0;m [0;33m<0002> gprs_rlcmac_data.cpp:270 +++++++++++++++++++++++++ RX : Uplink Control Block +++++++++++++++++++++++++ [0;m [0;33m<0002> gprs_rlcmac_data.cpp:273 ------------------------- RX : Uplink Control Block ------------------------- [0;m [0;33m<0002> gprs_rlcmac_data.cpp:395 RX: [PCU <- BTS] TFI: 0 TLLI: 0xcb46771f Packet Downlink Ack/Nack [0;m [0;33m<0002> gprs_rlcmac_data.cpp:410 MS requests UL TBF in ack message, so we provide one: [0;m [0;33m<0002> gprs_rlcmac.cpp:214 Searching for first unallocated TFI: TRX=0 first TS=7 [0;m [0;33m<0002> gprs_rlcmac.cpp:225 Found TFI=1. [0;m [0;33m<0002> gprs_rlcmac.cpp:351 ********** TBF starts here ********** [0;m [0;33m<0002> gprs_rlcmac.cpp:354 Allocating UL TBF: TFI=1 TRX=0 MS_CLASS=10 [0;m [0;33m<0002> gprs_rlcmac.cpp:421 Slot Allocation (Algorithm A) for class 10 [0;m [0;33m<0002> gprs_rlcmac.cpp:434 - Assign uplink TS=7 USF=1 [0;m [0;33m<0002> gprs_rlcmac.cpp:948 - Setting Control TS 7 [0;m [0;33m<0002> gprs_rlcmac.cpp:973 UL TBF=1 changes state from NULL to ASSIGN [0;m [0;33m<0002> gprs_rlcmac.cpp:983 Starting UL TBF=1 timer 3169. [0;m [0;33m<0002> gprs_rlcmac_data.cpp:1069 TBF: START TFI: 1 TLLI: 0xcb46771f Packet Uplink Assignment (PACCH) [0;m [0;33m<0002> gprs_rlcmac_data.cpp:1083 +++++++++++++++++++++++++ TX : Packet Uplink Assignment +++++++++++++++++++++++++ [0;m [0;33m<0002> gprs_rlcmac_data.cpp:1086 ------------------------- TX : Packet Uplink Assignment ------------------------- [0;m [0;36m<0006> gprs_rlcmac_sched.cpp:260 Received RTS for PDCH: TRX=0 TS=7 FN=1294297 block_nr=4 scheduling free USF for polling at FN=1294301 of DL TFI=0 [0;m [0;33m<0002> gprs_rlcmac_data.cpp:270 +++++++++++++++++++++++++ RX : Uplink Control Block +++++++++++++++++++++++++ [0;m [0;33m<0002> gprs_rlcmac_data.cpp:273 ------------------------- RX : Uplink Control Block ------------------------- [0;m [0;33m<0002> gprs_rlcmac_data.cpp:281 PACKET CONTROL ACK with unknown FN=1294297 TLL=0xcb46771f (TRX 0 TS 7) [0;m [0;33m<0002> gprs_rlcmac_data.cpp:1521 Polling is already sheduled for TBF=0, so we must wait for requesting downlink ack [0;m [1;33m<0004> gprs_rlcmac_data.cpp:1453 Complete DL frame for TBF=0: len=506 [0;m [1;33m<0004> gprs_rlcmac_data.cpp:1461 - Dequeue next LLC for TBF=0 (len=416) [0;m [0;33m<0002> gprs_rlcmac_data.cpp:1521 Polling is already sheduled for TBF=0, so we must wait for requesting downlink ack [0;m [0;33m<0002> gprs_rlcmac_data.cpp:1521 Polling is already sheduled for TBF=0, so we must wait for requesting downlink ack [0;m [0;33m<0002> gprs_rlcmac_data.cpp:1521 Polling is already sheduled for TBF=0, so we must wait for requesting downlink ack [0;m [0;33m<0002> gprs_rlcmac_data.cpp:1521 Polling is already sheduled for TBF=0, so we must wait for requesting downlink ack [0;m [0;33m<0002> gprs_rlcmac_data.cpp:100 Poll timeout for DL TBF=0 [0;m [0;33m<0002> gprs_rlcmac_data.cpp:135 - Timeout for polling PACKET CONTROL ACK for PACKET UPLINK ASSIGNMENT. [0;m [0;33m<0002> gprs_rlcmac_data.cpp:84 - Assignment was on PACCH [0;m [0;33m<0002> gprs_rlcmac_data.cpp:90 - Downlink ACK was received [0;m [0;33m<0002> gprs_rlcmac_data.cpp:1069 TBF: START TFI: 1 TLLI: 0xcb46771f Packet Uplink Assignment (PACCH) [0;m [0;33m<0002> gprs_rlcmac_data.cpp:1083 +++++++++++++++++++++++++ TX : Packet Uplink Assignment +++++++++++++++++++++++++ [0;m [0;33m<0002> gprs_rlcmac_data.cpp:1086 ------------------------- TX : Packet Uplink Assignment ------------------------- [0;m [0;33m<0002> gprs_rlcmac_data.cpp:1521 Polling is already sheduled for TBF=0, so we must wait for requesting downlink ack [0;m [0;36m<0006> gprs_rlcmac_sched.cpp:260 Received RTS for PDCH: TRX=0 TS=7 FN=1294379 block_nr=11 scheduling free USF for polling at FN=1294384 of DL TFI=0 [0;m [0;33m<0002> gprs_rlcmac_data.cpp:1521 Polling is already sheduled for TBF=0, so we must wait for requesting downlink ack [0;m [0;33m<0002> gprs_rlcmac_data.cpp:1521 Polling is already sheduled for TBF=0, so we must wait for requesting downlink ack [0;m [0;33m<0002> gprs_rlcmac_data.cpp:1521 Polling is already sheduled for TBF=0, so we must wait for requesting downlink ack [0;m [0;33m<0002> gprs_rlcmac_data.cpp:1521 Polling is already sheduled for TBF=0, so we must wait for requesting downlink ack [0;m [0;33m<0002> gprs_rlcmac_data.cpp:1521 Polling is already sheduled for TBF=0, so we must wait for requesting downlink ack [0;m [0;33m<0002> gprs_rlcmac_data.cpp:270 +++++++++++++++++++++++++ RX : Uplink Control Block +++++++++++++++++++++++++ [0;m [0;33m<0002> gprs_rlcmac_data.cpp:273 ------------------------- RX : Uplink Control Block ------------------------- [0;m [0;33m<0002> gprs_rlcmac_data.cpp:288 PACKET CONTROL ACK with expected FN=1294384 TLL=0xcb46771f (TRX 0 TS 7) [0;m [0;33m<0002> gprs_rlcmac_data.cpp:297 RX: [PCU <- BTS] TFI: 0 TLLI: 0xcb46771f Packet Control Ack [0;m [0;33m<0002> gprs_rlcmac_data.cpp:343 TBF: [DOWNLINK] UPLINK ASSIGNED TFI: 0 TLLI: 0xcb46771f [0;m [0;33m<0002> gprs_rlcmac.cpp:973 UL TBF=1 changes state from ASSIGN to FLOW [0;m [0;33m<0002> gprs_rlcmac_data.cpp:1532 Polling sheduled in this TS 7 [0;m [0;36m<0006> gprs_rlcmac_sched.cpp:260 Received RTS for PDCH: TRX=0 TS=7 FN=1294410 block_nr=6 scheduling free USF for polling at FN=1294414 of DL TFI=0 [0;m [0;33m<0002> gprs_rlcmac.cpp:988 Restarting UL TBF=1 timer 3169 while old timer 3169 pending [0;m [0;33m<0002> gprs_rlcmac.cpp:988 Restarting UL TBF=1 timer 3169 while old timer 3169 pending [0;m [0;33m<0002> gprs_rlcmac_data.cpp:270 +++++++++++++++++++++++++ RX : Uplink Control Block +++++++++++++++++++++++++ [0;m [0;33m<0002> gprs_rlcmac_data.cpp:273 ------------------------- RX : Uplink Control Block ------------------------- [0;m [0;33m<0002> gprs_rlcmac_data.cpp:395 RX: [PCU <- BTS] TFI: 0 TLLI: 0xcb46771f Packet Downlink Ack/Nack [0;m [0;33m<0002> gprs_rlcmac.cpp:988 Restarting UL TBF=1 timer 3169 while old timer 3169 pending [0;m [0;33m<0002> gprs_rlcmac.cpp:988 Restarting UL TBF=1 timer 3169 while old timer 3169 pending [0;m [1;36m<0005> gprs_rlcmac_data.cpp:740 Complete UL frame for TBF=1: len=62 [0;m [1;34m<0008> gprs_rlcmac.cpp:1760 LLC [PCU -> SGSN] TFI: 1 TLLI: 0xcb46771f len=62 [0;m [0;33m<0002> gprs_rlcmac.cpp:973 UL TBF=1 changes state from FLOW to FINISHED [0;m [0;33m<0002> gprs_rlcmac.cpp:988 Restarting UL TBF=1 timer 3169 while old timer 3169 pending [0;m [0;33m<0002> gprs_rlcmac.cpp:988 Restarting UL TBF=1 timer 3169 while old timer 3169 pending [0;m [0;36m<0006> gprs_rlcmac_sched.cpp:260 Received RTS for PDCH: TRX=0 TS=7 FN=1294449 block_nr=3 scheduling free USF for polling at FN=1294453 of UL TFI=1 [0;m [1;33m<0004> gprs_rlcmac_data.cpp:1453 Complete DL frame for TBF=0: len=416 [0;m [0;33m<0002> gprs_rlcmac.cpp:973 DL TBF=0 changes state from FLOW to FINISHED [0;m [0;33m<0002> gprs_rlcmac_data.cpp:1532 Polling sheduled in this TS 7 [0;m [0;33m<0002> gprs_rlcmac.cpp:983 Starting DL TBF=0 timer 3191. [0;m [0;33m<0002> gprs_rlcmac.cpp:988 Restarting UL TBF=1 timer 3169 while old timer 3169 pending [0;m [0;33m<0002> gprs_rlcmac.cpp:988 Restarting UL TBF=1 timer 3169 while old timer 3169 pending [0;m [0;36m<0006> gprs_rlcmac_sched.cpp:260 Received RTS for PDCH: TRX=0 TS=7 FN=1294457 block_nr=5 scheduling free USF for polling at FN=1294462 of DL TFI=0 [0;m [0;33m<0002> gprs_rlcmac_data.cpp:270 +++++++++++++++++++++++++ RX : Uplink Control Block +++++++++++++++++++++++++ [0;m [0;33m<0002> gprs_rlcmac_data.cpp:273 ------------------------- RX : Uplink Control Block ------------------------- [0;m [0;33m<0002> gprs_rlcmac_data.cpp:288 PACKET CONTROL ACK with expected FN=1294453 TLL=0xcb46771f (TRX 0 TS 7) [0;m [0;33m<0002> gprs_rlcmac_data.cpp:297 RX: [PCU <- BTS] TFI: 1 TLLI: 0xcb46771f Packet Control Ack [0;m [0;33m<0002> gprs_rlcmac_data.cpp:302 TBF: [UPLINK] END TFI: 1 TLLI: 0xcb46771f [0;m [0;33m<0002> gprs_rlcmac.cpp:895 Free UL TBF=1 with TLLI=0xcb46771f. [0;m [0;33m<0002> gprs_rlcmac.cpp:1005 Stopping UL TBF=1 timer 3169. [0;m [0;33m<0002> gprs_rlcmac.cpp:911 ********** TBF ends here ********** [0;m [0;33m<0002> gprs_rlcmac_data.cpp:270 +++++++++++++++++++++++++ RX : Uplink Control Block +++++++++++++++++++++++++ [0;m [0;33m<0002> gprs_rlcmac_data.cpp:273 ------------------------- RX : Uplink Control Block ------------------------- [0;m [0;33m<0002> gprs_rlcmac.cpp:1005 Stopping DL TBF=0 timer 3191. [0;m [0;33m<0002> gprs_rlcmac_data.cpp:395 RX: [PCU <- BTS] TFI: 0 TLLI: 0xcb46771f Packet Downlink Ack/Nack [0;m [0;33m<0002> gprs_rlcmac.cpp:983 Starting DL TBF=0 timer 3193. [0;m [0;33m<0002> gprs_rlcmac.cpp:973 DL TBF=0 changes state from FINISHED to WAIT RELEASE [0;m [1;32m<0001> pcu_l1_if.cpp:256 RACH request received: sapi=1 qta=0, ra=116, fn=1294650 [0;m [0;33m<0002> gprs_rlcmac_data.cpp:1116 MS requests UL TBF on RACH, so we provide one: [0;m [0;33m<0002> gprs_rlcmac_data.cpp:1119 MS requests single block allocation [0;m [0;33m<0002> gprs_rlcmac_data.cpp:1136 RX: [PCU <- BTS] RACH qbit-ta=0 ra=0x74, Fn=1294650 (16,15,6) [0;m [0;33m<0002> gprs_rlcmac_data.cpp:1138 TX: Immediate Assignment Uplink (AGCH) [0;m [0;33m<0002> gprs_rlcmac_data.cpp:501 DL TBF=0 timer 3193 expired. [0;m [0;33m<0002> gprs_rlcmac_data.cpp:542 TBF will be freed due to timeout [0;m [0;33m<0002> gprs_rlcmac.cpp:895 Free DL TBF=0 with TLLI=0xcb46771f. [0;m [0;33m<0002> gprs_rlcmac.cpp:911 ********** TBF ends here ********** [0;m [0;33m<0002> gprs_rlcmac_data.cpp:270 +++++++++++++++++++++++++ RX : Uplink Control Block +++++++++++++++++++++++++ [0;m [0;33m<0002> gprs_rlcmac_data.cpp:273 ------------------------- RX : Uplink Control Block ------------------------- [0;m [0;33m<0002> gprs_rlcmac_data.cpp:442 MS requests UL TBF in packet ressource request of single block, so we provide one: [0;m [0;33m<0002> gprs_rlcmac.cpp:214 Searching for first unallocated TFI: TRX=0 first TS=7 [0;m [0;33m<0002> gprs_rlcmac.cpp:225 Found TFI=1. [0;m [0;33m<0002> gprs_rlcmac.cpp:351 ********** TBF starts here ********** [0;m [0;33m<0002> gprs_rlcmac.cpp:354 Allocating UL TBF: TFI=1 TRX=0 MS_CLASS=10 [0;m [0;33m<0002> gprs_rlcmac.cpp:421 Slot Allocation (Algorithm A) for class 10 [0;m [0;33m<0002> gprs_rlcmac.cpp:434 - Assign uplink TS=7 USF=1 [0;m [0;33m<0002> gprs_rlcmac.cpp:948 - Setting Control TS 7 [0;m [0;33m<0002> gprs_rlcmac.cpp:973 UL TBF=1 changes state from NULL to ASSIGN [0;m [0;33m<0002> gprs_rlcmac.cpp:983 Starting UL TBF=1 timer 3169. [0;m [0;33m<0002> gprs_rlcmac_data.cpp:452 Change control TS to 7 until assinment is complete. [0;m [0;33m<0002> gprs_rlcmac_data.cpp:1069 TBF: START TFI: 1 TLLI: 0xcb46771f Packet Uplink Assignment (PACCH) [0;m [0;33m<0002> gprs_rlcmac_data.cpp:1083 +++++++++++++++++++++++++ TX : Packet Uplink Assignment +++++++++++++++++++++++++ [0;m [0;33m<0002> gprs_rlcmac_data.cpp:1086 ------------------------- TX : Packet Uplink Assignment ------------------------- [0;m [0;36m<0006> gprs_rlcmac_sched.cpp:260 Received RTS for PDCH: TRX=0 TS=7 FN=1294739 block_nr=10 scheduling free USF for polling at FN=1294743 of UL TFI=1 [0;m [0;33m<0002> gprs_rlcmac_data.cpp:270 +++++++++++++++++++++++++ RX : Uplink Control Block +++++++++++++++++++++++++ [0;m [0;33m<0002> gprs_rlcmac_data.cpp:273 ------------------------- RX : Uplink Control Block ------------------------- [0;m [0;33m<0002> gprs_rlcmac_data.cpp:288 PACKET CONTROL ACK with expected FN=1294743 TLL=0xcb46771f (TRX 0 TS 7) [0;m [0;33m<0002> gprs_rlcmac_data.cpp:297 RX: [PCU <- BTS] TFI: 1 TLLI: 0xcb46771f Packet Control Ack [0;m [0;33m<0002> gprs_rlcmac_data.cpp:343 TBF: [DOWNLINK] UPLINK ASSIGNED TFI: 1 TLLI: 0xcb46771f [0;m [0;33m<0002> gprs_rlcmac.cpp:973 UL TBF=1 changes state from ASSIGN to FLOW [0;m [0;33m<0002> gprs_rlcmac.cpp:988 Restarting UL TBF=1 timer 3169 while old timer 3169 pending [0;m [0;33m<0002> gprs_rlcmac.cpp:988 Restarting UL TBF=1 timer 3169 while old timer 3169 pending [0;m [0;33m<0002> gprs_rlcmac.cpp:988 Restarting UL TBF=1 timer 3169 while old timer 3169 pending [0;m [0;33m<0002> gprs_rlcmac.cpp:988 Restarting UL TBF=1 timer 3169 while old timer 3169 pending [0;m [1;36m<0005> gprs_rlcmac_data.cpp:740 Complete UL frame for TBF=1: len=62 [0;m [1;34m<0008> gprs_rlcmac.cpp:1760 LLC [PCU -> SGSN] TFI: 1 TLLI: 0xcb46771f len=62 [0;m [0;33m<0002> gprs_rlcmac.cpp:973 UL TBF=1 changes state from FLOW to FINISHED [0;m [0;33m<0002> gprs_rlcmac.cpp:988 Restarting UL TBF=1 timer 3169 while old timer 3169 pending [0;m [0;33m<0002> gprs_rlcmac.cpp:988 Restarting UL TBF=1 timer 3169 while old timer 3169 pending [0;m [0;36m<0006> gprs_rlcmac_sched.cpp:260 Received RTS for PDCH: TRX=0 TS=7 FN=1294804 block_nr=1 scheduling free USF for polling at FN=1294808 of UL TFI=1 [0;m [0;33m<0002> gprs_rlcmac.cpp:988 Restarting UL TBF=1 timer 3169 while old timer 3169 pending [0;m [0;33m<0002> gprs_rlcmac.cpp:988 Restarting UL TBF=1 timer 3169 while old timer 3169 pending [0;m [0;33m<0002> gprs_rlcmac_data.cpp:270 +++++++++++++++++++++++++ RX : Uplink Control Block +++++++++++++++++++++++++ [0;m [0;33m<0002> gprs_rlcmac_data.cpp:273 ------------------------- RX : Uplink Control Block ------------------------- [0;m [0;33m<0002> gprs_rlcmac_data.cpp:288 PACKET CONTROL ACK with expected FN=1294808 TLL=0xcb46771f (TRX 0 TS 7) [0;m [0;33m<0002> gprs_rlcmac_data.cpp:297 RX: [PCU <- BTS] TFI: 1 TLLI: 0xcb46771f Packet Control Ack [0;m [0;33m<0002> gprs_rlcmac_data.cpp:302 TBF: [UPLINK] END TFI: 1 TLLI: 0xcb46771f [0;m [0;33m<0002> gprs_rlcmac.cpp:895 Free UL TBF=1 with TLLI=0xcb46771f. [0;m [0;33m<0002> gprs_rlcmac.cpp:1005 Stopping UL TBF=1 timer 3169. [0;m [0;33m<0002> gprs_rlcmac.cpp:911 ********** TBF ends here ********** [0;m [0;33m<0002> gprs_rlcmac_data.cpp:501 UL TBF=0 timer 3169 expired. [0;m [0;33m<0002> gprs_rlcmac_data.cpp:536 TBF T3169 timeout during transsmission [0;m [0;33m<0002> gprs_rlcmac_data.cpp:84 - Assignment was on PACCH [0;m [0;33m<0002> gprs_rlcmac_data.cpp:86 - Uplink data was received [0;m [0;33m<0002> gprs_rlcmac_data.cpp:542 TBF will be freed due to timeout [0;m [0;33m<0002> gprs_rlcmac.cpp:895 Free UL TBF=0 with TLLI=0xcb46771f. [0;m [0;33m<0002> gprs_rlcmac.cpp:911 ********** TBF ends here ********** [0;m Osmo-PCU> quit % Unknown command. Osmo-PCU> exit Regards, Vladimir On Tue, Oct 30, 2012 at 10:24 AM, jolly <andreas at eversberg.eu> wrote: > ** > Vladimir Rolbin wrote: > > 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: > > hi vladimir, > > check out pcu_rx_data_cnf() at pcu_l1_if.cpp. it filters the confirm and > only passes PCU_IF_SAPI_PCH to gprs_rlcmac_imm_ass_cnf(). in your case > above, the uplink assignment on AGCH may result in a confirm, but in this > case it should have PCH sapi in order to be ignored: > > it might help to add this to pcu_rx_data_cnf(): > > case PCU_IF_SAPI_AGCH: > break; > > sysmobts is currently not sending an AGCH confirm via PCH interface, so > this is why i did not implement it. > > > <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) > > the packet control ack seems ok. it is polled at 2353693 with 13 bursts in > advance and therefore the block 2352706 is reserved for uplink. (the USF is > set accordingly 4 bursts earlier.) > > but the packet downlink ack is received 4 bursts too early. i would > suggest to set DRLCMAC debugging to DEBUG. at > gprs_rlcmac_send_data_block_acknowledged() the debugging shows in which FN > it is scheduled. then the frame number to be polled is set there: > > ... > LOGP(DRLCMAC, LOGL_DEBUG, "Polling sheduled in this " > "TS %d\n", ts); > ... > tbf->poll_state = GPRS_RLCMAC_POLL_SCHED; > tbf->poll_fn = (fn + 13) % 2715648; > ... > > you may also just change the log level of that debug line to LOGL_NOTICE. > > > regards, > > andreas > > -------------- next part -------------- An HTML attachment was scrubbed... URL: <http://lists.osmocom.org/pipermail/osmocom-net-gprs/attachments/20121030/b1d7587c/attachment.htm>