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

Ivan Kluchnikov Ivan.Kluchnikov at fairwaves.ru
Tue Oct 30 13:12:36 UTC 2012


Hi, Vladimir!

I added gsmtap support for PDCH channel in OpenBTS.
Please update your OpenBTS repository and capture gsmtap pcap file
with your bug.
You should use wireshark to capture data on localhost and apply gsmtap filter.
The most important, that in gsmtap header you can find frame number,
it is the number of frame in which block was received (for uplink) or
sent (for downlink).
I think it will help us to understand, where we should fix the problem
in OpenBTS or PCU.


2012/10/30 Vladimir Rolbin <vrolbin at gmail.com>:
> Hi, 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
>>
>



-- 
Regards,
Ivan Kluchnikov.
http://fairwaves.ru




More information about the osmocom-net-gprs mailing list