Project

General

Profile

Actions

Bug #4779

closed

Pending downlink assignment in state GPRS_RLCMAC_DL_ASS_SEND_ASS

Added by laforge over 3 years ago. Updated about 3 years ago.

Status:
Closed
Priority:
Normal
Assignee:
Target version:
-
Start date:
10/05/2020
Due date:
% Done:

0%

Spec Reference:

Description

I'm seeing the following error message while executing PCU_Tests.TC_force_two_phase_access:

20201005093043676 DTBF ERROR TBF(TFI=0 TLLI=0x00000001 DIR=UL STATE=FLOW) FIXME: Software error: Pending downlink assignment in state GPRS_RLCMAC_DL_ASS_SEND_ASS. This may not happen, because the assignment message never gets transmitted. Please be sure not to free in this state. PLEASE FIX! (tbf.h:518)

20201005093038407 DLGLOBAL NOTICE Available via telnet 127.0.0.1 4240 (telnet_interface.c:104)
20201005093038408 DL1IF INFO Opening OsmoPCU L1 interface to OsmoBTS (osmobts_sock.cpp:211)
20201005093038408 DL1IF ERROR Failed to connect to the BTS (/tmp/pcu_bts). Retrying... (osmobts_sock.cpp:219)
20201005093042671 DLGLOBAL INFO Accept()ed new telnet connection r=127.0.0.1:47894<->l=127.0.0.1:4240 (telnet_interface.c:185)
20201005093042696 DLGLOBAL INFO Accept()ed new telnet connection r=127.0.0.1:47896<->l=127.0.0.1:4240 (telnet_interface.c:185)
20201005093043408 DL1IF INFO Opening OsmoPCU L1 interface to OsmoBTS (osmobts_sock.cpp:211)
20201005093043408 DL1IF NOTICE osmo-bts PCU socket /tmp/pcu_bts has been connected (osmobts_sock.cpp:229)
20201005093043408 DL1IF INFO Sending 0.6.0 TXT as PCU_VERSION to BTS (pcu_l1_if.cpp:139)
20201005093043445 DL1IF DEBUG Info indication received: (pcu_l1_if.cpp:506)
20201005093043445 DL1IF INFO BTS available (pcu_l1_if.cpp:523)
20201005093043445 DL1IF DEBUG  mcc=262 (pcu_l1_if.cpp:524)
20201005093043445 DL1IF DEBUG  mnc=42 (pcu_l1_if.cpp:525)
20201005093043445 DL1IF DEBUG  lac=13135 (pcu_l1_if.cpp:526)
20201005093043445 DL1IF DEBUG  rac=0 (pcu_l1_if.cpp:527)
20201005093043445 DL1IF DEBUG  cell_id=20960 (pcu_l1_if.cpp:528)
20201005093043445 DL1IF DEBUG  bsic=7 (pcu_l1_if.cpp:529)
20201005093043445 DL1IF DEBUG  nsei=1234 (pcu_l1_if.cpp:530)
20201005093043445 DL1IF DEBUG  nse_timer=3 3 3 3 30 3 10 (pcu_l1_if.cpp:531)
20201005093043445 DL1IF DEBUG  cell_timer=3 3 3 3 3 10 3 10 3 10 3 (pcu_l1_if.cpp:536)
20201005093043445 DL1IF DEBUG  repeat_time=250 (pcu_l1_if.cpp:544)
20201005093043445 DL1IF DEBUG  repeat_count=3 (pcu_l1_if.cpp:545)
20201005093043445 DL1IF DEBUG  bvci=1234 (pcu_l1_if.cpp:546)
20201005093043445 DL1IF DEBUG  t3142=20 (pcu_l1_if.cpp:547)
20201005093043445 DL1IF DEBUG  t3169=5 (pcu_l1_if.cpp:548)
20201005093043445 DL1IF DEBUG  t3191=5 (pcu_l1_if.cpp:549)
20201005093043445 DL1IF DEBUG  t3193=1600 (ms) (pcu_l1_if.cpp:550)
20201005093043445 DL1IF DEBUG  t3195=5 (pcu_l1_if.cpp:551)
20201005093043445 DL1IF DEBUG  n3101=10 (pcu_l1_if.cpp:552)
20201005093043445 DL1IF DEBUG  n3103=4 (pcu_l1_if.cpp:553)
20201005093043445 DL1IF DEBUG  n3105=8 (pcu_l1_if.cpp:554)
20201005093043445 DL1IF DEBUG  cv_countdown=15 (pcu_l1_if.cpp:555)
20201005093043445 DL1IF DEBUG  dl_tbf_ext=2500 (pcu_l1_if.cpp:556)
20201005093043445 DL1IF DEBUG  ul_tbf_ext=2500 (pcu_l1_if.cpp:557)
20201005093043445 DL1IF DEBUG  Use CS1 (pcu_l1_if.cpp:561)
20201005093043445 DL1IF DEBUG  Use CS2 (pcu_l1_if.cpp:561)
20201005093043445 DL1IF DEBUG  Use CS3 (pcu_l1_if.cpp:561)
20201005093043445 DL1IF DEBUG  Use CS4 (pcu_l1_if.cpp:561)
20201005093043445 DL1IF DEBUG  Use MCS1 (pcu_l1_if.cpp:565)
20201005093043445 DL1IF DEBUG  Use MCS2 (pcu_l1_if.cpp:565)
20201005093043445 DL1IF DEBUG  Use MCS3 (pcu_l1_if.cpp:565)
20201005093043445 DL1IF DEBUG  Use MCS4 (pcu_l1_if.cpp:565)
20201005093043445 DL1IF DEBUG  Use MCS5 (pcu_l1_if.cpp:565)
20201005093043445 DL1IF DEBUG  Use MCS6 (pcu_l1_if.cpp:565)
20201005093043445 DL1IF DEBUG  Use MCS7 (pcu_l1_if.cpp:565)
20201005093043445 DL1IF DEBUG  Use MCS8 (pcu_l1_if.cpp:565)
20201005093043445 DL1IF DEBUG  Use MCS9 (pcu_l1_if.cpp:565)
20201005093043445 DL1IF DEBUG  initial_cs=2 (pcu_l1_if.cpp:567)
20201005093043445 DL1IF DEBUG  initial_mcs=6 (pcu_l1_if.cpp:568)
20201005093043445 DL1IF DEBUG  nsvci=1234 (pcu_l1_if.cpp:569)
20201005093043445 DL1IF DEBUG  local_port=22000 (pcu_l1_if.cpp:570)
20201005093043445 DL1IF DEBUG  remote_port=23000 (pcu_l1_if.cpp:571)
20201005093043445 DL1IF DEBUG  remote_ip=127.0.0.1 (pcu_l1_if.cpp:573)
20201005093043445 DNS NOTICE Listening for nsip packets from 127.0.0.1:23000 on 0.0.0.0:22000 (gprs_ns.c:2073)
20201005093043447 DNS NOTICE NS UDP socket at 0.0.0.0:22000 (gprs_ns.c:2097)
20201005093043447 DNS INFO NSVCI=1234 Creating NS-VC with Signal weight 1, Data weight 1 (gprs_ns.c:321)
20201005093043447 DNS DEBUG NSEI 0 (NS-VCI=1234) setting state [DEAD,UNBLOCKED,UNRESET] -> [DEAD,BLOCKED,UNRESET] (gprs_ns.c:333)
20201005093043447 DLGLOBAL DEBUG validating counter group 0x7fb750546d80(ns:nsvc) with 12 counters (rate_ctr.c:87)
20201005093043447 DNS INFO NSEI=1234 RESET procedure based on API request (gprs_ns.c:2116)
20201005093043447 DNS DEBUG NSEI 1234 (NS-VCI=1234) setting state [DEAD,BLOCKED,UNRESET] -> [DEAD,BLOCKED,RESET] (gprs_ns.c:2120)
20201005093043447 DNS INFO NSEI=1234 Tx NS RESET (NSVCI=1234, cause=O&M intervention) (gprs_ns.c:553)
20201005093043447 DNS DEBUG NSEI=1234 Starting timer in mode tns-reset (3 seconds) (gprs_ns.c:749)
20201005093043447 DLGLOBAL DEBUG validating counter group 0x7fb750547080(bssgp:bss_ctx) with 7 counters (rate_ctr.c:87)
20201005093043447 DL1IF INFO Sending activate request: trx=0 ts=7 (pcu_l1_if.cpp:151)
20201005093043447 DL1IF INFO PDCH (trx=0, ts=7): tsc=7, hopping=no (pcu_l1_if.cpp:679)
20201005093043447 DL1IF INFO Sending activate request: trx=1 ts=7 (pcu_l1_if.cpp:151)
20201005093043447 DL1IF INFO PDCH (trx=1, ts=7): tsc=7, hopping=no (pcu_l1_if.cpp:679)
20201005093043447 DL1IF INFO Sending activate request: trx=2 ts=7 (pcu_l1_if.cpp:151)
20201005093043447 DL1IF INFO PDCH (trx=2, ts=7): tsc=7, hopping=no (pcu_l1_if.cpp:679)
20201005093043447 DL1IF INFO Sending activate request: trx=3 ts=7 (pcu_l1_if.cpp:151)
20201005093043447 DL1IF INFO PDCH (trx=3, ts=7): tsc=7, hopping=no (pcu_l1_if.cpp:679)
20201005093043447 DL1IF INFO Sending activate request: trx=4 ts=7 (pcu_l1_if.cpp:151)
20201005093043447 DL1IF INFO PDCH (trx=4, ts=7): tsc=7, hopping=no (pcu_l1_if.cpp:679)
20201005093043447 DL1IF INFO Sending activate request: trx=5 ts=7 (pcu_l1_if.cpp:151)
20201005093043447 DL1IF INFO PDCH (trx=5, ts=7): tsc=7, hopping=no (pcu_l1_if.cpp:679)
20201005093043447 DL1IF INFO Sending activate request: trx=6 ts=7 (pcu_l1_if.cpp:151)
20201005093043447 DL1IF INFO PDCH (trx=6, ts=7): tsc=7, hopping=no (pcu_l1_if.cpp:679)
20201005093043447 DL1IF INFO Sending activate request: trx=7 ts=7 (pcu_l1_if.cpp:151)
20201005093043447 DL1IF INFO PDCH (trx=7, ts=7): tsc=7, hopping=no (pcu_l1_if.cpp:679)
20201005093043447 DL1IF DEBUG Time indication received: 0 (pcu_l1_if.cpp:703)
20201005093043452 DNS INFO NSVCI=1234 Rx NS RESET ACK (NSEI=1234, NSVCI=1234) (gprs_ns.c:1348)
20201005093043452 DNS DEBUG NSEI 1234 (NS-VCI=1234) setting state [DEAD,BLOCKED,RESET] -> [ALIVE,BLOCKED,UNRESET] (gprs_ns.c:1431)
20201005093043452 DNS DEBUG NSEI 1234 (NS-VCI=1234) setting remote state [DEAD,UNBLOCKED,UNRESET] -> [ALIVE,BLOCKED,UNRESET] (gprs_ns.c:1432)
20201005093043452 DNS DEBUG NSEI=1234 Tx NS ALIVE (NSVCI=1234) (gprs_ns.c:711)
20201005093043452 DNS DEBUG NSEI=1234 Starting timer in mode tns-test (30 seconds) (gprs_ns.c:749)
20201005093043455 DNS DEBUG NSEI 1234 (NS-VCI=1234) setting state [ALIVE,BLOCKED,UNRESET] -> [ALIVE,BLOCKED,UNRESET] (gprs_ns.c:1763)
20201005093043455 DNS DEBUG NSEI=1234 Starting timer in mode tns-test (30 seconds) (gprs_ns.c:749)
20201005093043455 DNS INFO NSEI=1234 Tx NS UNBLOCK (NSVCI=1234) (gprs_ns.c:698)
20201005093043458 DNS INFO NSEI=1234 Rx NS UNBLOCK ACK (gprs_ns.c:1804)
20201005093043458 DNS DEBUG NSEI 1234 (NS-VCI=1234) setting state [ALIVE,BLOCKED,UNRESET] -> [ALIVE,UNBLOCKED,UNRESET] (gprs_ns.c:1806)
20201005093043458 DNS DEBUG NSEI 1234 (NS-VCI=1234) setting remote state [ALIVE,BLOCKED,UNRESET] -> [ALIVE,UNBLOCKED,UNRESET] (gprs_ns.c:1807)
20201005093043458 DPCU NOTICE NS-VC 1234 is unblocked. (gprs_bssgp_pcu.cpp:595)
20201005093043458 DBSSGP INFO Sending reset on BVCI 0 (gprs_bssgp_pcu.cpp:876)
20201005093043458 DBSSGP NOTICE BSSGP (BVCI=0) Tx BVC-RESET CAUSE=O&M intervention (gprs_bssgp_bss.c:301)
20201005093043461 DL1IF DEBUG Time indication received: 4 (pcu_l1_if.cpp:703)
20201005093043471 DBSSGP DEBUG rx BVCI_SIGNALLING gprs_bssgp_rx_sign (gprs_bssgp_pcu.cpp:473)
20201005093043471 DBSSGP NOTICE Rx BSSGP BVCI=0 (SIGN) BVC_RESET_ACK (gprs_bssgp_pcu.cpp:342)
20201005093043472 DBSSGP INFO Sending reset on BVCI 1234 (gprs_bssgp_pcu.cpp:884)
20201005093043472 DBSSGP NOTICE BSSGP (BVCI=1234) Tx BVC-RESET CAUSE=O&M intervention (gprs_bssgp_bss.c:301)
20201005093043481 DL1IF DEBUG Time indication received: 8 (pcu_l1_if.cpp:703)
20201005093043482 DBSSGP DEBUG rx BVCI_SIGNALLING gprs_bssgp_rx_sign (gprs_bssgp_pcu.cpp:473)
20201005093043482 DBSSGP NOTICE Rx BSSGP BVCI=0 (SIGN) BVC_RESET_ACK (gprs_bssgp_pcu.cpp:342)
20201005093043482 DBSSGP INFO Sending unblock on BVCI 1234 (gprs_bssgp_pcu.cpp:893)
20201005093043482 DBSSGP NOTICE BSSGP (BVCI=1234) Tx BVC-UNBLOCK (gprs_bssgp_bss.c:282)
20201005093043491 DBSSGP DEBUG rx BVCI_SIGNALLING gprs_bssgp_rx_sign (gprs_bssgp_pcu.cpp:473)
20201005093043491 DBSSGP NOTICE Rx BSSGP BVCI=0 (SIGN) BVC_UNBLOCK_ACK (gprs_bssgp_pcu.cpp:356)
20201005093043491 DBSSGP DEBUG Sending flow control info on BVCI 1234 (gprs_bssgp_pcu.cpp:901)
20201005093043491 DBSSGP DEBUG Computed BVC leak rate = 20000, num_pdch = 8, cs = CS-4 (gprs_bssgp_pcu.cpp:809)
20201005093043491 DBSSGP DEBUG Computed MS default leak rate = 10000, ms_num_pdch = 4, cs = CS-4 (gprs_bssgp_pcu.cpp:832)
20201005093043491 DBSSGP DEBUG Sending FLOW CONTROL BVC, Bmax = 200000, R = 20000, Bmax_MS = 100000, R_MS = 10000, avg_dly = 0 (gprs_bssgp_pcu.cpp:860)
20201005093043494 DL1IF INFO RACH request received: sapi=1 qta=0, ra=0x78, fn=1337, cur_fn=8, is_11bit=0 (pcu_l1_if.cpp:460)
20201005093043494 DRLCMAC DEBUG MS requests Uplink resource on CCCH/RACH: ra=0x78 (8 bit) Fn=1337 qta=0 (bts.cpp:830)
20201005093043494 DRLCMAC DEBUG MS requests single block allocation, but we force two phase access (bts.cpp:842)
20201005093043494 DRLCMAC DEBUG Allocated a single block at SBFn=52 TRX=0 TS=7 (bts.cpp:863)
20201005093043494 DRLCMAC DEBUG Tx Immediate Assignment on AGCH: TRX=0 (ARFCN 871) TS=7 TA=0 TSC=7 TFI=-1 USF=7 (bts.cpp:897)
20201005093043494 DL1IF DEBUG Sending data request: trx=0 ts=0 sapi=2 arfcn=0 fn=0 cur_fn=8 block=0 data=2d 06 3f 10 0f e3 67 78 09 6b 00 00 c0 08 01 03 2b 2b 2b 2b 2b 2b 2b  (pcu_l1_if.cpp:175)
20201005093043513 DL1IF DEBUG Time indication received: 13 (pcu_l1_if.cpp:703)
20201005093043523 DBSSGP DEBUG rx BVCI_PTP=1234 gprs_bssgp_rx_ptp (gprs_bssgp_pcu.cpp:483)
20201005093043523 DBSSGP DEBUG Rx BSSGP BVCI=1234 (PTP) FLOW-CONTROL-BVC-ACK (gprs_bssgp_pcu.cpp:279)
20201005093043529 DL1IF DEBUG Time indication received: 17 (pcu_l1_if.cpp:703)
20201005093043545 DL1IF DEBUG Data indication received: sapi=5 arfcn=871 fn=17 cur_fn=17 block=0 data=40 16 40 00 00 00 62 54 a2 8c 00 10 00 00 00 00 00 00 00 00 00 00 00  (pcu_l1_if.cpp:322)
20201005093043545 DL1IF DEBUG Data indication with raw measurements received: BER10k = 0, BTO = 0, Q = 0 (pcu_l1_if.cpp:335)
20201005093043545 DRLCMACUL DEBUG Got RLC block, coding scheme: CS-1, length: 23 (23)) (pdch.cpp:758)
20201005093043545 DRLCMAC DEBUG +++++++++++++++++++++++++ RX : Uplink Control Block +++++++++++++++++++++++++ (pdch.cpp:697)
20201005093043545 DCSN1 INFO csnStreamDecoder (type: Pkt Resource Req (5)): PayloadType = 1 | spare = 0 | R = 0 | MESSAGE_TYPE = 5 | Exist_ACCESS_TYPE = 1 | ACCESS_TYPE = 0 |  : ID | Choice PacketResourceRequestID = 1 | u.TLLI = 0x00000001 | : End ID | Exist_MS_Radio_Access_capability2 = 1 |  : MS_Radio_Access_capability2 | MS_RA_capability_value { | Choice MS_RA_capability_value_Choice = 1 | u.Content length = 21 | offset = 1 | RF_Power_Capability = 1 | Exist_A5_bits = 0 | ES_IND = 1 | PS = 0 | VGCS = 0 | VBS = 0 | Exist_Multislot_capability = 1 |  : Multislot_capability | Exist_HSCSD_multislot_class = 0 | Exist_GPRS_multislot_class = 1 | GPRS_multislot_class = 3 | GPRS_Extended_Dynamic_Allocation_Capability = 0 | Exist_SM = 0 | Exist_ECSD_multislot_class = 0 | Exist_EGPRS_multislot_class = 0 | Exist_DTM_GPRS_multislot_class = 0 | : End Multislot_capability | COMPACT_Interference_Measurement_Capability = NULL | Revision_Level_Indicator = NULL | UMTS_FDD_Radio_Access_Technology_Capability = NULL | UMTS_384_TDD_Radio_Access_Technology_Capability = NULL | CDMA2000_Radio_Access_Technology_Capability = NULL | UMTS_128_TDD_Radio_Access_Technology_Capability = NULL | GERAN_Feature_Package_1 = NULL | Modulation_based_multislot_class_support = NULL | GMSK_MultislotPowerProfile = NULL | EightPSK_MultislotProfile = NULL | MultipleTBF_Capability = NULL | DownlinkAdvancedReceiverPerformance = NULL | ExtendedRLC_MAC_ControlMessageSegmentionsCapability = NULL | DTM_EnhancementsCapability = NULL | PS_HandoverCapability = NULL | DTM_Handover_Capability = NULL | FlexibleTimeslotAssignment = NULL | GAN_PS_HandoverCapability = NULL | RLC_Non_persistentMode = NULL | ReducedLatencyCapability = NULL | UplinkEGPRS2 = NULL | DownlinkEGPRS2 = NULL | EUTRA_FDD_Support = NULL | EUTRA_TDD_Support = NULL | GERAN_To_EUTRAN_supportInGERAN_PTM = NULL | PriorityBasedReselectionSupport = NULL | MS_RA_capability_value } | : End MS_Radio_Access_capability2 |  : Channel_Request_Description | PEAK_THROUGHPUT_CLASS = 0 | RADIO_PRIORITY = 0 | RLC_MODE = 0 | LLC_PDU_TYPE = 1 | RLC_OCTET_COUNT = 0 | : End Channel_Request_Description | Exist_CHANGE_MARK = 0 | C_VALUE = 0 | Exist_SIGN_VAR = 0 | I_LEVEL_TN | Exist = 0 | I_LEVEL_TN | Exist = 0 | I_LEVEL_TN | Exist = 0 | I_LEVEL_TN | Exist = 0 | I_LEVEL_TN | Exist = 0 | I_LEVEL_TN | Exist = 0 | I_LEVEL_TN | Exist = 0 | I_LEVEL_TN | Exist = 0 | Exist_AdditionsR99 = 0 | Padding = 0|0|0|0|0|0|0|0| (gsm_rlcmac.c:5480)
20201005093043546 DRLCMAC DEBUG ------------------------- RX : Uplink Control Block ------------------------- (pdch.cpp:710)
20201005093043546 DRLCMAC INFO Creating MS object, TLLI = 0x00000000 (gprs_ms.cpp:121)
20201005093043546 DRLCMAC INFO Modifying MS object, UL TLLI: 0x00000000 -> 0x00000001, not yet confirmed (gprs_ms.cpp:403)
20201005093043546 DRLCMAC DEBUG MS requests UL TBF in packet resource request of single block, so we provide one: (pdch.cpp:577)
20201005093043546 DTBFUL NOTICE (no TBF) MS requests UL TBF in PACKET RESOURCE REQ of single block, but there is no resource request scheduled! (pdch.cpp:585)
20201005093043546 DRLCMAC INFO Modifying MS object, TLLI = 0x00000001, MS class 0 -> 3 (gprs_ms.cpp:493)
20201005093043546 DTBF DEBUG ********** UL-TBF starts here ********** (tbf.cpp:996)
20201005093043546 DTBF INFO Allocating UL TBF: MS_CLASS=3/0 (tbf.cpp:997)
20201005093043547 DRLCMAC DEBUG Searching for first unallocated TFI: TRX=0 (bts.cpp:589)
20201005093043547 DRLCMAC DEBUG  Found TFI=0. (bts.cpp:600)
20201005093043547 DRLCMAC DEBUG Slot Allocation (Algorithm B) for class 3 (gprs_rlcmac_ts_alloc.cpp:528)
20201005093043547 DRLCMAC DEBUG - Skipping TS 0, because not enabled (gprs_rlcmac_ts_alloc.cpp:77)
20201005093043547 DRLCMAC DEBUG - Skipping TS 1, because not enabled (gprs_rlcmac_ts_alloc.cpp:77)
20201005093043547 DRLCMAC DEBUG - Skipping TS 2, because not enabled (gprs_rlcmac_ts_alloc.cpp:77)
20201005093043547 DRLCMAC DEBUG - Skipping TS 3, because not enabled (gprs_rlcmac_ts_alloc.cpp:77)
20201005093043547 DRLCMAC DEBUG - Skipping TS 4, because not enabled (gprs_rlcmac_ts_alloc.cpp:77)
20201005093043547 DRLCMAC DEBUG - Skipping TS 5, because not enabled (gprs_rlcmac_ts_alloc.cpp:77)
20201005093043547 DRLCMAC DEBUG - Skipping TS 6, because not enabled (gprs_rlcmac_ts_alloc.cpp:77)
20201005093043547 DRLCMAC DEBUG - Possible DL/UL slots: (TS=0)".......C"(TS=7) (gprs_rlcmac_ts_alloc.cpp:550)
20201005093043547 DRLCMAC DEBUG Rx=2 Tx=2 Sum Rx+Tx=3, Tta=3 Ttb=2, Tra=3 Trb=1, Type=1 (mslot_class.c:196)
- Selected UL slots: (TS=0)"u......U"(TS=7), multi (gprs_rlcmac_ts_alloc.cpp:719)
20201005093043547 DRLCMAC INFO [UL] algo B <multi> (suggested TRX: 0): using 1 slots (gprs_rlcmac_ts_alloc.cpp:933)
20201005093043547 DRLCMAC DEBUG - Reserved DL/UL slots: (TS=0)"D......C"(TS=7) (gprs_rlcmac_ts_alloc.cpp:784)
20201005093043547 DRLCMAC DEBUG - Assigning UL TS 7 (gprs_rlcmac_ts_alloc.cpp:806)
20201005093043547 DRLCMAC INFO PDCH(TS 7, TRX 0): Attaching TBF(TFI=0 TLLI=0x00000000 DIR=UL STATE=NULL), 1 TBFs, USFs = 01, TFIs = 00000001. (pdch.cpp:925)
20201005093043547 DTBF INFO TBF(TFI=0 TLLI=0x00000000 DIR=UL STATE=NULL) Setting Control TS 7 (tbf.cpp:539)
20201005093043547 DRLCMAC INFO Attaching TBF to MS object, TLLI = 0x00000001, TBF = TBF(TFI=0 TLLI=0x00000001 DIR=UL STATE=NULL) (gprs_ms.cpp:274)
20201005093043547 DTBF INFO TBF(TFI=0 TLLI=0x00000001 DIR=UL STATE=NULL) Allocated: trx = 0, ul_slots = 80, dl_slots = 00 (tbf.cpp:952)
20201005093043547 DLGLOBAL DEBUG validating counter group 0x559bc1317b00(pcu:tbf) with 1 counters (rate_ctr.c:87)
20201005093043547 DLGLOBAL DEBUG validating counter group 0x559bc1317b80(tbf:egprs) with 9 counters (rate_ctr.c:87)
20201005093043547 DLGLOBAL DEBUG validating counter group 0x559bc1317b60(tbf:gprs) with 4 counters (rate_ctr.c:87)
20201005093043547 DTBF DEBUG TBF(TFI=0 TLLI=0x00000001 DIR=UL STATE=NULL) changes state from NULL to ASSIGN (tbf.cpp:432)
20201005093043547 DTBF DEBUG TBF(TFI=0 TLLI=0x00000001 DIR=UL STATE=ASSIGN) starting timer T3169 [allocation (UL-TBF)] with 5 sec. 0 microsec, cur_fn=17 (tbf.cpp:433)
20201005093043547 DTBF DEBUG TBF(TFI=0 TLLI=0x00000001 DIR=UL STATE=ASSIGN) change control TS 7 -> 7 until assignment is complete. (pdch.cpp:620)
20201005093043548 DTBF DEBUG TBF(TFI=0 TLLI=0x00000001 DIR=UL STATE=ASSIGN) changes UL ASS state from GPRS_RLCMAC_UL_ASS_NONE to GPRS_RLCMAC_UL_ASS_SEND_ASS (pdch.cpp:625)
20201005093043548 DRLCMACMEAS INFO MS(TLLI=0x00000001, IMSI=, TA=220, 3/0, UL) Link quality 0dB (old 0dB) left window [5, 8], modifying uplink CS level: CS-2 -> CS-1 (gprs_ms.cpp:688)
20201005093043554 DL1IF DEBUG RTS request received: trx=0 ts=7 sapi=5 arfcn=871 fn=21 cur_fn=17 block=0 (pcu_l1_if.cpp:416)
20201005093043554 DTBF INFO TBF(TFI=0 TLLI=0x00000001 DIR=UL STATE=ASSIGN) start Packet Uplink Assignment (PACCH) (tbf.cpp:1379)
20201005093043554 DTBF DEBUG +++++++++++++++++++++++++ TX : Packet Uplink Assignment +++++++++++++++++++++++++ (tbf.cpp:1386)
20201005093043554 DCSN1 INFO csnStreamEncoder (type: Pkt UL ASS (10)): MESSAGE_TYPE = 10 | PAGE_MODE = 0 | Exist_PERSISTENCE_LEVEL = 0 |  : ID | u.TLLI = 2 | u.TLLI = 1 |  : End ID | u.PUA_GPRS_Struct = 0 |  : u.PUA_GPRS_Struct | CHANNEL_CODING_COMMAND = 0 | TLLI_BLOCK_CHANNEL_CODING = 1 |  : Packet_Timing_Advance | Exist_TIMING_ADVANCE_VALUE = 0 | Exist_IndexAndtimeSlot = 0 |  : End Packet_Timing_Advance | Exist_Frequency_Parameters = 1 |  : Frequency_Parameters | TSC = 7 | u.ARFCN = 0 | u.ARFCN = 871 |  : End Frequency_Parameters | u.Dynamic_Allocation = 1 |  : u.Dynamic_Allocation | Extended_Dynamic_Allocation = 0 | Exist_P0 = 0 | USF_GRANULARITY = 0 | Exist_UPLINK_TFI_ASSIGNMENT = 1 | UPLINK_TFI_ASSIGNMENT = 0 | Exist_RLC_DATA_BLOCKS_GRANTED = 0 | Exist_TBF_Starting_Time = 0 | u.Timeslot_Allocation = 0 | u.Timeslot_Allocation : | Exist = 0 | u.Timeslot_Allocation : | Exist = 0 | u.Timeslot_Allocation : | Exist = 0 | u.Timeslot_Allocation : | Exist = 0 | u.Timeslot_Allocation : | Exist = 0 | u.Timeslot_Allocation : | Exist = 0 | u.Timeslot_Allocation : | Exist = 0 | u.Timeslot_Allocation : | Exist = 1 | USF_TN = 0 |  : End u.Dynamic_Allocation | Exist_AdditionsR99 = 0 |  : End u.PUA_GPRS_Struct | Padding = 11|43|43|43|43|43|43|43|43|43|43| (gsm_rlcmac.c:6013)
20201005093043555 DTBF DEBUG ------------------------- TX : Packet Uplink Assignment ------------------------- (tbf.cpp:1392)
20201005093043555 DTBFDL INFO TBF(TFI=0 TLLI=0x00000001 DIR=UL STATE=ASSIGN) Scheduled UL Assignment polling on PACCH (FN=34, TS=7) (tbf.cpp:785)
20201005093043555 DRLCMACSCHED DEBUG Scheduling control message at RTS for TBF(TFI=0 TLLI=0x00000001 DIR=UL STATE=ASSIGN) (TRX=0, TS=7) (gprs_rlcmac_sched.cpp:228)
20201005093043555 DL1IF DEBUG Sending data request: trx=0 ts=7 sapi=5 arfcn=871 fn=21 cur_fn=17 block=0 data=4f 28 40 00 00 00 22 79 b3 a2 00 02 0b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b  (pcu_l1_if.cpp:175)
20201005093043556 DL1IF DEBUG Time indication received: 21 (pcu_l1_if.cpp:703)
20201005093043575 DL1IF DEBUG Time indication received: 26 (pcu_l1_if.cpp:703)
20201005093043588 DL1IF DEBUG Data indication received: sapi=5 arfcn=871 fn=26 cur_fn=26 block=0 data=00 01 01 00 00 00 01 7d 9c 45 d8 6e 45 0f 2f 88 b2 00 00 00 00 00 00  (pcu_l1_if.cpp:322)
20201005093043588 DL1IF DEBUG Data indication with raw measurements received: BER10k = 0, BTO = 0, Q = 0 (pcu_l1_if.cpp:335)
20201005093043588 DRLCMACUL DEBUG Got RLC block, coding scheme: CS-1, length: 23 (23)) (pdch.cpp:758)
20201005093043588 DRLCMACUL DEBUG   UL data: 00 01 01 00 00 00 01 7d 9c 45 d8 6e 45 0f 2f 88 b2 00 00 00 00 00 00  (pdch.cpp:801)
20201005093043588 DRLCMACUL INFO Got CS-1 RLC block: R=0, SI=0, TFI=0, CPS=0, RSB=0, rc=184 (pdch.cpp:812)
20201005093043588 DTBFUL DEBUG TBF(TFI=0 TLLI=0x00000001 DIR=UL STATE=ASSIGN) UL DATA TFI=0 received (V(Q)=0 .. V(R)=0) (tbf_ul.cpp:199)
20201005093043588 DTBF DEBUG TBF(TFI=0 TLLI=0x00000001 DIR=UL STATE=ASSIGN) restarting timer T3169 [acked (data)] with 5 sec. 0 microsec, cur_fn=26 (tbf_ul.cpp:214)
20201005093043588 DTBFUL DEBUG TBF(TFI=0 TLLI=0x00000001 DIR=UL STATE=ASSIGN) Got CS-1 RLC data block: CV=0, BSN=0, SPB=0, PI=0, E=1, TI=1, bitoffs=24 (tbf_ul.cpp:226)
20201005093043588 DTBFUL DEBUG TBF(TFI=0 TLLI=0x00000001 DIR=UL STATE=ASSIGN) BSN 0 storing in window (0..63) (tbf_ul.cpp:259)
20201005093043588 DTBFUL DEBUG TBF(TFI=0 TLLI=0x00000001 DIR=UL STATE=ASSIGN) data_length=20, data=00 00 00 01 7d 9c 45 d8 6e 45 0f 2f 88 b2 00 00 00 00 00 00  (tbf_ul.cpp:282)
20201005093043588 DRLCMACUL DEBUG - Raising V(R) to 1 (rlc.cpp:279)
20201005093043588 DRLCMACUL DEBUG - Taking block 0 out, raising V(Q) to 1 (rlc.cpp:294)
20201005093043588 DTBFUL DEBUG TBF(TFI=0 TLLI=0x00000001 DIR=UL STATE=ASSIGN) Assembling frames: (len=20) (tbf_ul.cpp:83)
20201005093043588 DTBFUL DEBUG TBF(TFI=0 TLLI=0x00000001 DIR=UL STATE=ASSIGN) Frame 1 starts at offset 4, length=16, is_complete=1 (tbf_ul.cpp:96)
20201005093043588 DTBFUL DEBUG TBF(TFI=0 TLLI=0x00000001 DIR=UL STATE=ASSIGN) complete UL frame len=16 (tbf_ul.cpp:108)
20201005093043588 DBSSGP INFO LLC [PCU -> SGSN] TBF(TFI=0 TLLI=0x00000001 DIR=UL STATE=ASSIGN) len=16 (tbf_ul.cpp:412)
20201005093043589 DTBFUL DEBUG TBF(TFI=0 TLLI=0x00000001 DIR=UL STATE=ASSIGN) Scheduling Ack/Nack, because TLLI is included. (tbf_ul.cpp:372)
20201005093043589 DTBF DEBUG TBF(TFI=0 TLLI=0x00000001 DIR=UL STATE=ASSIGN) changes UL ACK state from GPRS_RLCMAC_UL_ACK_NONE to GPRS_RLCMAC_UL_ACK_SEND_ACK (tbf_ul.cpp:396)
20201005093043596 DL1IF DEBUG Time indication received: 30 (pcu_l1_if.cpp:703)
20201005093043614 DL1IF DEBUG Time indication received: 34 (pcu_l1_if.cpp:703)
20201005093043629 DL1IF DEBUG Data indication received: sapi=5 arfcn=871 fn=34 cur_fn=34 block=0 data=40 04 00 00 00 07 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00  (pcu_l1_if.cpp:322)
20201005093043629 DL1IF DEBUG Data indication with raw measurements received: BER10k = 0, BTO = 0, Q = 0 (pcu_l1_if.cpp:335)
20201005093043629 DRLCMACUL DEBUG Got RLC block, coding scheme: CS-1, length: 23 (23)) (pdch.cpp:758)
20201005093043629 DRLCMAC DEBUG +++++++++++++++++++++++++ RX : Uplink Control Block +++++++++++++++++++++++++ (pdch.cpp:697)
20201005093043629 DCSN1 INFO csnStreamDecoder (type: Pkt Control Ack (1)): PayloadType = 1 | spare = 0 | R = 0 | MESSAGE_TYPE = 1 | TLLI = 0x00000001 | CTRL_ACK = 3 | Exist_AdditionsR5 = 0 | Padding = 0|0|0|0|0|0|0|0|0|0|0|0|0|0|0|0|0| (gsm_rlcmac.c:5480)
20201005093043629 DRLCMAC DEBUG ------------------------- RX : Uplink Control Block ------------------------- (pdch.cpp:710)
20201005093043629 DTBF DEBUG TBF(TFI=0 TLLI=0x00000001 DIR=UL STATE=ASSIGN) RX: [PCU <- BTS] Packet Control Ack (pdch.cpp:322)
20201005093043629 DTBF DEBUG TBF(TFI=0 TLLI=0x00000001 DIR=UL STATE=ASSIGN) changes poll state from GPRS_RLCMAC_POLL_SCHED to GPRS_RLCMAC_POLL_NONE (pdch.cpp:323)
20201005093043629 DTBF DEBUG TBF(TFI=0 TLLI=0x00000001 DIR=UL STATE=ASSIGN) [DOWNLINK] UPLINK ASSIGNED (pdch.cpp:368)
20201005093043629 DTBF DEBUG TBF(TFI=0 TLLI=0x00000001 DIR=UL STATE=ASSIGN) changes UL ASS state from GPRS_RLCMAC_UL_ASS_WAIT_ACK to GPRS_RLCMAC_UL_ASS_NONE (pdch.cpp:371)
20201005093043629 DTBF DEBUG TBF(TFI=0 TLLI=0x00000001 DIR=UL STATE=ASSIGN) changes state from ASSIGN to FLOW (pdch.cpp:383)
20201005093043636 DBSSGP DEBUG rx BVCI_PTP=1234 gprs_bssgp_rx_ptp (gprs_bssgp_pcu.cpp:483)
20201005093043636 DBSSGP DEBUG Rx BSSGP BVCI=1234 (PTP) DL_UNITDATA (gprs_bssgp_pcu.cpp:272)
20201005093043636 DBSSGP INFO LLC [SGSN -> PCU] = TLLI: 0x00000001 IMSI: 000 len: 10 (gprs_bssgp_pcu.cpp:167)
20201005093043636 DTBF DEBUG ********** DL-TBF starts here ********** (tbf.cpp:1071)
20201005093043636 DTBF INFO Allocating DL TBF: MS_CLASS=3/0 (tbf.cpp:1072)
20201005093043637 DRLCMAC DEBUG Searching for first unallocated TFI: TRX=0 (bts.cpp:589)
20201005093043637 DRLCMAC DEBUG  Found TFI=0. (bts.cpp:600)
- Selected DL slots: (TS=0)"d......D"(TS=7), multi (gprs_rlcmac_ts_alloc.cpp:719)
20201005093043637 DRLCMAC INFO [DL] algo B <multi> (suggested TRX: 0): using 1 slots (gprs_rlcmac_ts_alloc.cpp:933)
20201005093043637 DRLCMAC DEBUG - Assigning DL TS 7 (gprs_rlcmac_ts_alloc.cpp:826)
20201005093043637 DRLCMAC INFO PDCH(TS 7, TRX 0): Attaching TBF(TFI=0 TLLI=0x00000000 DIR=DL STATE=NULL), 1 TBFs, USFs = 01, TFIs = 00000001. (pdch.cpp:925)
20201005093043637 DTBF INFO TBF(TFI=0 TLLI=0x00000000 DIR=DL STATE=NULL) Setting Control TS 7 (tbf.cpp:539)
20201005093043637 DRLCMAC INFO Attaching TBF to MS object, TLLI = 0x00000001, TBF = TBF(TFI=0 TLLI=0x00000001 DIR=DL STATE=NULL) (gprs_ms.cpp:293)
20201005093043637 DTBF INFO TBF(TFI=0 TLLI=0x00000001 DIR=DL STATE=NULL) Allocated: trx = 0, ul_slots = 80, dl_slots = 80 (tbf.cpp:952)
20201005093043637 DLGLOBAL DEBUG validating counter group 0x559bc1317b00(pcu:tbf) with 1 counters (rate_ctr.c:87)
20201005093043637 DLGLOBAL DEBUG validating counter group 0x559bc1317b20(tbf:gprs) with 4 counters (rate_ctr.c:87)
20201005093043637 DRLCMAC INFO Modifying MS object, TLLI: 0x00000001 confirmed (gprs_ms.cpp:439)
20201005093043637 DTBFDL DEBUG TBF(TFI=0 TLLI=0x00000001 DIR=DL STATE=NULL) [DOWNLINK] START (tbf_dl.cpp:177)
20201005093043637 DRLCMAC INFO Modifying MS object, TLLI = 0x00000001, IMSI '' -> '000' (gprs_ms.cpp:465)
20201005093043637 DTBFDL DEBUG TBF(TFI=0 TLLI=0x00000001 DIR=DL STATE=NULL) Send dowlink assignment on PACCH, because TBF(TFI=0 TLLI=0x00000001 DIR=UL STATE=FLOW) exists (tbf_dl.cpp:516)
20201005093043637 DTBF DEBUG TBF(TFI=0 TLLI=0x00000001 DIR=UL STATE=FLOW) changes DL ASS state from GPRS_RLCMAC_DL_ASS_NONE to GPRS_RLCMAC_DL_ASS_SEND_ASS (tbf_dl.cpp:517)
20201005093043637 DTBF DEBUG TBF(TFI=0 TLLI=0x00000001 DIR=DL STATE=NULL) changes state from NULL to ASSIGN (tbf_dl.cpp:521)
20201005093043637 DTBF INFO TBF(TFI=0 TLLI=0x00000001 DIR=DL STATE=ASSIGN) set ass. type PACCH [prev CCCH:0, PACCH:0] (tbf_dl.cpp:521)
20201005093043637 DTBF DEBUG TBF(TFI=0 TLLI=0x00000001 DIR=DL STATE=ASSIGN) starting timer T0 [assignment (PACCH)] with 2 sec. 0 microsec, cur_fn=34 (tbf_dl.cpp:524)
20201005093043637 DTBFDL DEBUG TBF(TFI=0 TLLI=0x00000001 DIR=DL STATE=ASSIGN) appending 10 bytes (tbf_dl.cpp:112)
20201005093043641 DL1IF DEBUG RTS request received: trx=0 ts=7 sapi=5 arfcn=871 fn=39 cur_fn=34 block=0 (pcu_l1_if.cpp:416)
20201005093043641 DRLCMACSCHED DEBUG Received RTS for PDCH: TRX=0 TS=7 FN=39 block_nr=0 scheduling USF=0 for required uplink resource of UL TFI=0 (gprs_rlcmac_sched.cpp:115)
20201005093043641 DTBF DEBUG TBF(TFI=0 TLLI=0x00000001 DIR=UL STATE=FLOW) Polling is already scheduled for single block allocation at FN 52 TS 7 ... (tbf.cpp:749)
20201005093043641 DTBF DEBUG TBF(TFI=0 TLLI=0x00000001 DIR=UL STATE=FLOW) Polling is already scheduled for single block allocation at FN 52 TS 7 ... (tbf.cpp:749)
20201005093043641 DTBF DEBUG TBF(TFI=0 TLLI=0x00000001 DIR=UL STATE=FLOW) Polling is already scheduled for single block allocation at FN 52 TS 7 ... (tbf.cpp:749)
20201005093043641 DL1IF DEBUG Sending data request: trx=0 ts=7 sapi=5 arfcn=871 fn=39 cur_fn=34 block=0 data=40 94 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b  (pcu_l1_if.cpp:175)
20201005093043641 DL1IF DEBUG Time indication received: 39 (pcu_l1_if.cpp:703)
20201005093043658 DLGLOBAL INFO Closing telnet connection r=127.0.0.1:47896<->l=127.0.0.1:4240 (telnet_interface.c:131)
20201005093043676 DL1IF NOTICE PCU socket has LOST connection (osmobts_sock.cpp:96)
20201005093043676 DRLCMACMEAS INFO MS(TLLI=0x00000001, IMSI=000, TA=220, 3/0, UL DL) UL RSSI: -48 dBm (gprs_rlcmac_meas.cpp:108)
20201005093043676 DTBF INFO TBF(TFI=0 TLLI=0x00000001 DIR=UL STATE=FLOW) free (tbf.cpp:484)
20201005093043676 DTBF ERROR TBF(TFI=0 TLLI=0x00000001 DIR=UL STATE=FLOW) FIXME: Software error: Pending downlink assignment in state GPRS_RLCMAC_DL_ASS_SEND_ASS. This may not happen, because the assignment message never gets transmitted. Please be sure not to free in this state. PLEASE FIX! (tbf.h:518)
20201005093043676 DTBF DEBUG TBF(TFI=0 TLLI=0x00000001 DIR=UL STATE=FLOW) stopping timer T3169 [freeing TBF] (tbf.cpp:616)
20201005093043676 DRLCMAC INFO PDCH(TS 7, TRX 0): Detaching TBF(TFI=0 TLLI=0x00000001 DIR=UL STATE=FLOW), 0 TBFs, USFs = 00, TFIs = 00000000. (pdch.cpp:945)
20201005093043676 DRLCMAC INFO Detaching TBF from MS object, TLLI = 0x00000001, TBF = TBF(TFI=0 TLLI=0x00000001 DIR=UL STATE=FLOW) (gprs_ms.cpp:330)
20201005093043676 DTBF DEBUG ********** UL-TBF ends here ********** (tbf.cpp:496)
20201005093043676 DTBF DEBUG TBF(TFI=0 TLLI=0x00000001 DIR=DL STATE=ASSIGN) changes state from ASSIGN to RELEASING (tbf_dl.cpp:1159)
20201005093043676 DTBF INFO TBF(TFI=0 TLLI=0x00000001 DIR=DL STATE=RELEASING) free (tbf.cpp:484)
20201005093043676 DTBF DEBUG TBF(TFI=0 TLLI=0x00000001 DIR=DL STATE=RELEASING) stopping timer T0 [freeing TBF] (tbf.cpp:616)
20201005093043676 DRLCMAC INFO PDCH(TS 7, TRX 0): Detaching TBF(TFI=0 TLLI=0x00000001 DIR=DL STATE=RELEASING), 0 TBFs, USFs = 00, TFIs = 00000000. (pdch.cpp:945)
20201005093043676 DRLCMAC INFO Detaching TBF from MS object, TLLI = 0x00000001, TBF = TBF(TFI=0 TLLI=0x00000001 DIR=DL STATE=RELEASING) (gprs_ms.cpp:330)
20201005093043676 DTBF DEBUG ********** DL-TBF ends here ********** (tbf.cpp:496)

I'm attaching a merged TTCN3 log here.

The test passes only sporiadically and fails most of the time. Not sure if that's related.


Files

test-log-merged.txt test-log-merged.txt 468 KB merged TTCN3 log of a failing test execution producing above-mentioned PCU log laforge, 10/05/2020 07:35 AM
Actions #1

Updated by fixeria over 3 years ago

Hi Harald,

I'm seeing the following error message while executing PCU_Tests.TC_force_two_phase_access:

I also see this error message quite often,

The test passes only sporiadically and fails most of the time. Not sure if that's related.

but I don't think it's related. From the attached log:

09:30:43.643073 mtc GPRS_Components.ttcn:681 dec_RlcmacDlCtrlBlock(): Decoded @RLCMAC_Types.RlcmacDlCtrlBlock: { mac_hdr := { payload_type := MAC_PT_RLCMAC_NO_OPT (1), rrbp := RRBP_Nplus13_mod_2715648 (0), rrbp_valid := false, usf := 0 }, opt := omit, payload := { msg_type := PACKET_DL_DUMMY_CTRL (37), u := { dl_dummy := { page_mode := PAGE_MODE_NORMAL (0), persistence_levels_present := '0'B, persistence_levels := omit } } } }
09:30:43.643127 mtc GPRS_Components.ttcn:681 Warning: dec_RlcmacDlCtrlBlock(): Data remained at the end of the stream after successful decoding: '2B2B2B2B2B2B2B2B2B2B2B2B2B2B2B2B2B2B2B2B2B'O ("+++++++++++++++++++++")
09:30:43.643732 mtc GPRS_Components.ttcn:318 setverdict(fail): pass -> fail reason: "Failed to match Packet Assignment:{ ctrl := { mac_hdr := { payload_type := (MAC_PT_RLCMAC_NO_OPT (1), MAC_PT_RLCMAC_OPT (2)), rrbp := ?, rrbp_valid := ?, usf := ? }, opt := *, payload := { msg_type := PACKET_DL_ASSIGNMENT (2), u := { dl_assignment := { page_mode := ?, pres1 := ?, persistence_levels := *, tfi_or_tlli := ?, egprs2 := '0'B, mac_mode := ?, rlc_mode := ?, control_ack := ?, timeslot_alloc := ?, pkt_ta := ?, p0_present := ?, p0 := *, reserved := *, pr_mode := *, freq_par_present := ?, freq_par := *, dl_tfi_ass_present := ?, dl_tfi_assignment := *, pwr_ctrl_present := ?, pwr_ctrl := *, tbf_starting_time_present := ?, tbf_starting_time := *, spare := '0'B, rel_additions := * } } } } }", new component reason: "Failed to match Packet Assignment:{ ctrl := { mac_hdr := { payload_type := (MAC_PT_RLCMAC_NO_OPT (1), MAC_PT_RLCMAC_OPT (2)), rrbp := ?, rrbp_valid := ?, usf := ? }, opt := *, payload := { msg_type := PACKET_DL_ASSIGNMENT (2), u := { dl_assignment := { page_mode := ?, pres1 := ?, persistence_levels := *, tfi_or_tlli := ?, egprs2 := '0'B, mac_mode := ?, rlc_mode := ?, control_ack := ?, timeslot_alloc := ?, pkt_ta := ?, p0_present := ?, p0 := *, reserved := *, pr_mode := *, freq_par_present := ?, freq_par := *, dl_tfi_ass_present := ?, dl_tfi_assignment := *, pwr_ctrl_present := ?, pwr_ctrl := *, tbf_starting_time_present := ?, tbf_starting_time := *, spare := '0'B, rel_additions := * } } } } }" 
09:30:43.644592 mtc GPRS_Components.ttcn:168 Test case "TC_force_two_phase_access" aborted at "GPRS_Components.ttcn":319

It's basically a race condition between BSSGP and RCUIF: AFAIU, RTS.req from the test suite arrives faster than DL DATA on BSSGP, so we get PACKET_DL_DUMMY_CTRL instead of expected PACKET_DL_ASSIGNMENT. The problem is in GPRS_Components.f_pcuif_rx_data_req(), where we don't expect any specific message, but simply receive any.

Actions #2

Updated by pespin about 3 years ago

  • Status changed from New to In Progress

Related to #4927, AFAIU the osmo-pcu errors show up when we hit the race condition and hence we are not acting properly towards the osmo-pcu.

During a successful run of the test, I cannot see any log line containing the "Software error" you mention.

In any case, I don't see why it should be a problem to free it under that scenario, AFAICT it's totally fine and nevertherless it sould always be possible to free a TBF.

Actions #3

Updated by pespin about 3 years ago

  • Status changed from In Progress to Closed

Merged, closing.

Actions

Also available in: Atom PDF

Add picture from clipboard (Maximum size: 48.8 MB)