Open Source Mobile Communications: Issueshttps://osmocom.org/https://osmocom.org/favicon.ico?16647414092023-06-02T15:08:09ZOpen Source Mobile Communications
Redmine OsmoSGSN - Feature #6050 (Closed): Add missing testcase to test GERAN originated RIM RAN informat...https://osmocom.org/issues/60502023-06-02T15:08:09Zdexter
<p>At the moment we only have a testcase for an EUTRAN originated RAN information request that targets a GERAN cell (TC_rim_eutran_to_geran). We have no testcase that tests the reverse direction, which is equally important. (We also have no testcase for requests that go from EUTRAN to EUTRAN.)</p>
<p>We should add those two missing testcases to the testsuite in order to be sure that RIM message forwarding is working correctly.</p> OsmoMGW - Bug #5984 (Closed): fix regression in TC_two_crcx_and_one_mdcx_rtp_hohttps://osmocom.org/issues/59842023-03-29T20:00:42Zdexter
<p>TC_two_crcx_and_one_mdcx_rtp_ho fails with reason: "RTP packets received while RX was disabled"</p> OsmoMSC - Bug #4160 (Rejected): osmo-msc segfaultshttps://osmocom.org/issues/41602019-08-20T11:40:11Zdexter
<pre>
Tue Aug 20 13:24:18 2019 DPAG <0005> paging.c:97 Paging: IMSI-001010000000102:MSISDN-23102 for MNCC: establish call: Starting paging
Tue Aug 20 13:24:18 2019 DMSC <0006> sgs_iface.c:470 XXXXXXXXXX state == 1 conf_by_radio_contact_ind == 1
Tue Aug 20 13:24:18 2019 DREF <000a> vlr_sgs.c:351 VLR subscr IMSI-001010000000102:MSISDN-23102 + SGs-paging-req: now used by 6 (2*SGs,attached,mncc_tx_to_gsm_cc,CC,SGs-paging-req)
Tue Aug 20 13:24:18 2019 DREF <000a> paging.c:107 VLR subscr IMSI-001010000000102:MSISDN-23102 + Paging: now used by 7 (2*SGs,attached,mncc_tx_to_gsm_cc,CC,SGs-paging-req,Paging)
Tue Aug 20 13:24:18 2019 DREF <000a> gsm_04_08_cc.c:1925 VLR subscr IMSI-001010000000102:MSISDN-23102 - mncc_tx_to_gsm_cc: now used by 6 (2*SGs,attached,CC,SGs-paging-req,Paging)
Tue Aug 20 13:24:19 2019 DREF <000a> sgs_iface.c:274 VLR subscr IMSI-001010000000102:MSISDN-23102 + check_sgs_association: now used by 7 (2*SGs,attached,CC,SGs-paging-req,Paging,check_sgs_association)
Tue Aug 20 13:24:19 2019 DREF <000a> sgs_iface.c:293 VLR subscr IMSI-001010000000102:MSISDN-23102 - check_sgs_association: now used by 6 (2*SGs,attached,CC,SGs-paging-req,Paging)
Tue Aug 20 13:24:19 2019 DREF <000a> sgs_iface.c:786 VLR subscr IMSI-001010000000102:MSISDN-23102 + sgs_rx_service_req: now used by 7 (2*SGs,attached,CC,SGs-paging-req,Paging,sgs_rx_service_req)
Tue Aug 20 13:24:19 2019 DREF <000a> vlr_sgs.c:263 VLR subscr IMSI-001010000000102:MSISDN-23102 + vlr_sgs_pag_ack: now used by 8 (2*SGs,attached,CC,SGs-paging-req,Paging,sgs_rx_service_req,vlr_sgs_pag_ack)
Tue Aug 20 13:24:19 2019 DREF <000a> vlr_sgs.c:270 VLR subscr IMSI-001010000000102:MSISDN-23102 - SGs-paging-req: now used by 7 (2*SGs,attached,CC,Paging,sgs_rx_service_req,vlr_sgs_pag_ack)
Tue Aug 20 13:24:19 2019 DREF <000a> vlr_sgs.c:272 VLR subscr IMSI-001010000000102:MSISDN-23102 - vlr_sgs_pag_ack: now used by 6 (2*SGs,attached,CC,Paging,sgs_rx_service_req)
Tue Aug 20 13:24:19 2019 DREF <000a> sgs_iface.c:823 VLR subscr IMSI-001010000000102:MSISDN-23102 - sgs_rx_service_req: now used by 5 (2*SGs,attached,CC,Paging)
Tue Aug 20 13:24:21 2019 DBSSAP <0010> sccp_ran.c:84 (GERAN-A-1 from RI=SSN_PC,PC=0.23.3,SSN=BSSAP) sccp_ran_sap_up(N-CONNECT.indication)
Tue Aug 20 13:24:21 2019 DRR <0003> ran_peer.c:596 ran_peer(GERAN-A:RI-SSN_PC:PC-0-23-3:SSN-BSSAP)[0x55d7abeed440]{READY}: Received Event RAN_PEER_EV_MSG_UP_CO_INITIAL
Tue Aug 20 13:24:21 2019 DMSC <0006> fsm.c:423 msub_fsm[0x55d7abeed2a0]{active}: Allocated
Tue Aug 20 13:24:21 2019 DMSC <0006> fsm.c:423 msc_i[0x55d7abeee460]{READY}: Allocated
Tue Aug 20 13:24:21 2019 DMSC <0006> fsm.c:453 msc_i[0x55d7abeee460]{READY}: is child of msub_fsm[0x55d7abeed2a0]
Tue Aug 20 13:24:21 2019 DMSC <0006> fsm.c:423 msc_a[0x55d7abeee920]{MSC_A_ST_VALIDATE_L3}: Allocated
Tue Aug 20 13:24:21 2019 DMSC <0006> fsm.c:453 msc_a[0x55d7abeee920]{MSC_A_ST_VALIDATE_L3}: is child of msub_fsm[0x55d7abeed2a0]
Tue Aug 20 13:24:21 2019 DMSC <0006> msc_a.c:1039 msc_a(unknown:GERAN-A-1:NONE)[0x55d7abeee920]{MSC_A_ST_VALIDATE_L3}: State change to MSC_A_ST_VALIDATE_L3 (X1, 5s)
Tue Aug 20 13:24:21 2019 DMSC <0006> ran_peer.c:392 msc_i(unknown:GERAN-A-1:NONE)[0x55d7abeee460]{READY}: Received Event MSC_EV_FROM_RAN_COMPLETE_LAYER_3
Tue Aug 20 13:24:21 2019 DMSC <0006> msc_i.c:103 msc_a(unknown:GERAN-A-1:NONE)[0x55d7abeee920]{MSC_A_ST_VALIDATE_L3}: Received Event MSC_A_EV_FROM_I_COMPLETE_LAYER_3
Tue Aug 20 13:24:21 2019 DREF <000a> msc_a.c:176 msc_a(unknown:GERAN-A-1:NONE)[0x55d7abeee920]{MSC_A_ST_VALIDATE_L3}: + msc_a_ran_dec: now used by 1 (msc_a_ran_dec)
Tue Aug 20 13:24:21 2019 DBSSAP <0010> ran_msg_a.c:783 msc_a(unknown:GERAN-A-1:NONE)[0x55d7abeee920]{MSC_A_ST_VALIDATE_L3}: RAN decode: BSSMAP: Rx BSSMAP DT1 COMPLETE LAYER 3
Tue Aug 20 13:24:21 2019 DBSSAP <0010> msc_a.c:1513 msc_a(unknown:GERAN-A-1:NONE)[0x55d7abeee920]{MSC_A_ST_VALIDATE_L3}: RAN decode: BSSMAP Complete Layer 3
Tue Aug 20 13:24:21 2019 DRLL <0000> msc_a.c:1160 msc_a(unknown:GERAN-A-1:NONE)[0x55d7abeee920]{MSC_A_ST_VALIDATE_L3}: Dispatching 04.08 message: RR GSM48_MT_RR_PAG_RESP
Tue Aug 20 13:24:21 2019 DRR <0003> gsm_04_08.c:1145 msc_a(TMSI-0x2009A35F:GERAN-A-1:PAGING_RESP)[0x55d7abeee920]{MSC_A_ST_VALIDATE_L3}: Rx PAGING RESPONSE
Tue Aug 20 13:24:21 2019 DREF <000a> gsm_04_08.c:1147 msc_a(TMSI-0x2009A35F:GERAN-A-1:PAGING_RESP)[0x55d7abeee920]{MSC_A_ST_VALIDATE_L3}: + paging-response: now used by 2 (msc_a_ran_dec,paging-response)
Tue Aug 20 13:24:21 2019 DVLR <000e> fsm.c:423 Process_Access_Request_VLR(TMSI-0x2009A35F:GERAN-A-1:PAGING_RESP)[0x55d7abeeebb0]{PR_ARQ_S_INIT}: Allocated
Tue Aug 20 13:24:21 2019 DVLR <000e> fsm.c:453 Process_Access_Request_VLR(TMSI-0x2009A35F:GERAN-A-1:PAGING_RESP)[0x55d7abeeebb0]{PR_ARQ_S_INIT}: is child of msc_a(TMSI-0x2009A35F:GERAN-A-1:PAGING_RESP)[0x55d7abeee920]
Tue Aug 20 13:24:21 2019 DVLR <000e> vlr_access_req_fsm.c:675 Process_Access_Request_VLR(TMSI-0x2009A35F:GERAN-A-1:PAGING_RESP)[0x55d7abeeebb0]{PR_ARQ_S_INIT}: rev=R99 net=GERAN (no Auth)
Tue Aug 20 13:24:21 2019 DVLR <000e> vlr_access_req_fsm.c:699 Process_Access_Request_VLR(TMSI-0x2009A35F:GERAN-A-1:PAGING_RESP)[0x55d7abeeebb0]{PR_ARQ_S_INIT}: Received Event PR_ARQ_E_START
Tue Aug 20 13:24:21 2019 DVLR <000e> vlr_access_req_fsm.c:402 Process_Access_Request_VLR(TMSI-0x2009A35F:GERAN-A-1:PAGING_RESP)[0x55d7abeeebb0]{PR_ARQ_S_INIT}: proc_arq_fsm_done(IMSI_UNKNOWN_IN_VLR)
Tue Aug 20 13:24:21 2019 DVLR <000e> vlr_access_req_fsm.c:103 Process_Access_Request_VLR(TMSI-0x2009A35F:GERAN-A-1:PAGING_RESP)[0x55d7abeeebb0]{PR_ARQ_S_INIT}: State change to PR_ARQ_S_DONE (no timeout)
Tue Aug 20 13:24:21 2019 DVLR <000e> vlr_access_req_fsm.c:112 Process_Access_Request_VLR(TMSI-0x2009A35F:GERAN-A-1:PAGING_RESP)[0x55d7abeeebb0]{PR_ARQ_S_DONE}: Process Access Request result: IMSI_UNKNOWN_IN_VLR
Tue Aug 20 13:24:21 2019 DMSC <0006> vlr_access_req_fsm.c:153 msc_a(TMSI-0x2009A35F:GERAN-A-1:PAGING_RESP)[0x55d7abeee920]{MSC_A_ST_VALIDATE_L3}: Received Event MSC_A_EV_CN_CLOSE
./start-msc_ext_mncc.sh: line 5: 8168 Segmentation fault sudo osmo-msc -c ./osmo-msc.cfg -M /tmp/bsc_mncc
</pre> OsmoGSMTester - Feature #3916 (Rejected): Format TTCN3 log output https://osmocom.org/issues/39162019-04-11T08:16:02Zdexter
<p>The TTCN3 log output that the tester currently delivers is not formatted. This means one has to format it manually before it can be viewed. Since we already do the logmerge directly on jenkins we could do the formatting as well. Then inspection of the build artifacts would be a lot easier.</p>
<p>Example commandline:<br />ttcn3_logformat ./MSC_Tests.TC_lu_and_mt_call.merged > formatted.log</p>
<p>(Attached one finds the two files from the example)</p> OsmoBTS - Feature #3530 (Rejected): merge PRIM_INFO_MEAS into PRIM_PH_DATA and PRIM_TCHhttps://osmocom.org/issues/35302018-09-06T16:07:43Zdexter
<p>At the moment measurement indication primitives are handed to the upper layers separately. However, they could also be integrated into the primitives that carry the actual data block to which the measurement belongs. This would make things a lot easier to handle and understand since whenever one gets data from the phy, there must be a measurement report attached to it.</p>
<p>When lookint into l1sap.c we can see that PRIM_INFO_MEAS is sent along in an PRIM_INFO_MEAS. PRIM_INFO_MEAS only carries the measurement indication and the time indication. We may decide to flatten this once the measurement indication is settled.</p>
<p>PRIM_PH_DATA and PRIM_TCH carry data and voice. Thats where we need to integrate the measurement indication.</p> OsmoBTS - Bug #3478 (Rejected): struct member lchan->meas.bts_tx_pwr is never sethttps://osmocom.org/issues/34782018-08-20T09:51:53Zdexter
<p>The struct member bts_tx_pwr is no where set, but it is included in the measurement report when rsl_tx_meas_res() in rsl.c runs. This is odd. It should have a value and since the transmit power of the BTS is fixed, this will a fixed value derived from the bts configuration. We also may check if RSL_IE_BS_POWER is optional and if it is optional we could just leave it out.</p> OsmoBTS - Bug #3299 (Closed): osmo_ortp: scheduler is not startedhttps://osmocom.org/issues/32992018-05-29T13:54:18Zdexter
<p>Apparently the scheduler of ortp is not started. Presumably older versions did not require starting the scheduler explicitly, so we just do not call the relevant function:</p>
<pre>
Tue May 29 15:41:00 2018 <0015> trau/osmo_ortp.c:180 osmo_rtp_socket_poll(101600): ERROR!
Tue May 29 15:41:00 2018 <0015> trau/osmo_ortp.c:180 osmo_rtp_socket_poll(80640): ERROR!
Tue May 29 15:41:00 2018 <0015> trau/osmo_ortp.c:180 osmo_rtp_socket_poll(101760): ERROR!
Tue May 29 15:41:00 2018 <0015> trau/osmo_ortp.c:180 osmo_rtp_socket_poll(80800): ERROR!
Tue May 29 15:41:00 2018 <0000> rsl.c:2633 (bts=0,trx=0,ts=3,ss=0) Handing RLL msg UNIT_DATA_IND from LAPDm to MEAS REP
Tue May 29 15:41:00 2018 <0000> rsl.c:2550 (bts=0,trx=0,ts=3,ss=0) chan_num:11 Tx MEAS RES valid(2), flags(03)
Tue May 29 15:41:00 2018 <0000> rsl.c:2568 (bts=0,trx=0,ts=3,ss=0) Send Meas RES: NUM:20, RXLEV_FULL:63, RXLEV_SUB:63, RXQUAL_FULL:0, RXQUAL_SUB:0, MS_PWR:56, UL_TA:0, L3_LEN:18, TimingOff:0
Tue May 29 15:41:00 2018 <0015> trau/osmo_ortp.c:180 osmo_rtp_socket_poll(101920): ERROR!
Tue May 29 15:41:00 2018 <0015> trau/osmo_ortp.c:0 Cannot use the scheduled mode: the scheduler is not started. Call ortp_scheduler_init() at the begginning of the application.Tue May 29 15:41:00 2018 <0015> trau/osmo_ortp.c:0 can't guess current timestamp because session is not scheduled.Tue May 29 15:41:00 2018 <0015> trau/osmo_ortp.c:145 osmo-ortp(16386): timestamp_jump, new TS 0, resyncing
Tue May 29 15:41:00 2018 <0015> trau/osmo_ortp.c:180 osmo_rtp_socket_poll(80960): ERROR!
Tue May 29 15:41:00 2018 <0015> trau/osmo_ortp.c:0 Cannot use the scheduled mode: the scheduler is not started. Call ortp_scheduler_init() at the begginning of the application.Tue May 29 15:41:00 2018 <0015> trau/osmo_ortp.c:0 can't guess current timestamp because session is not scheduled.Tue May 29 15:41:00 2018 <0015> trau/osmo_ortp.c:145 osmo-ortp(16384): timestamp_jump, new TS 0, resyncing
Tue May 29 15:41:00 2018 <0015> trau/osmo_ortp.c:180 osmo_rtp_socket_poll(102080): ERROR!
Tue May 29 15:41:00 2018 <0015> trau/osmo_ortp.c:180 osmo_rtp_socket_poll(81120): ERROR!
Tue May 29 15:41:00 2018 <0015> trau/osmo_ortp.c:180 osmo_rtp_socket_poll(102240): ERROR!
Tue May 29 15:41:00 2018 <0015> trau/osmo_ortp.c:180 osmo_rtp_socket_poll(81280): ERROR!
Tue May 29 15:41:00 2018 <0015> trau/osmo_ortp.c:180 osmo_rtp_socket_poll(102400): ERROR!
Tue May 29 15:41:00 2018 <0015> trau/osmo_ortp.c:180 osmo_rtp_socket_poll(81440): ERROR!
Tue May 29 15:41:00 2018 <0015> trau/osmo_ortp.c:180 osmo_rtp_socket_poll(102560): ERROR!
Tue May 29 15:41:00 2018 <0015> trau/osmo_ortp.c:180 osmo_rtp_socket_poll(81600): ERROR!
Tue May 29 15:41:00 2018 <0015> trau/osmo_ortp.c:180 osmo_rtp_socket_poll(102720): ERROR!
Tue May 29 15:41:00 2018 <0015> trau/osmo_ortp.c:180 osmo_rtp_socket_poll(82080): ERROR!
</pre> OsmoBTS - Bug #3016 (Rejected): octphy: tx power can not be modifiedhttps://osmocom.org/issues/30162018-02-28T12:11:25Zdexter
<p>See osmo-bts-octphy:l1_oml.c:bts_model_change_power(). The function is not implemented. This makes changing the TX power impossible. Presumably only changes after BTS startup are affected. It should still be possible to configure a specific transceiver output power but it is not possible to change it on the fly. As a result - for example - ramping can not work.</p> OsmoBTS - Bug #3015 (Rejected): octphy: Mode Modify is currently not supported for Octasic PHYhttps://osmocom.org/issues/30152018-02-28T12:00:59Zdexter
<p>osmo-bts-octphy seems not to support MODE MODIFY.</p>
<p>See osmo-bts-octphy:l1_if.c:mph_info_req(). The call to l1if_rsl_mode_modify(lchan) is commented out.</p> OsmoBTS - Bug #2976 (Rejected): octphy: no response to assignment command on RSL levelhttps://osmocom.org/issues/29762018-02-21T17:34:25Zdexter
<p>osmo-bts-octphy seems not to work with pmaier/fsm3. I narrowed the cause down to a missing assignment complete on RSL level. We use the assignment complete response as input for the GSCON FSM (see bsc_api.c:handle_ass_compl()).</p>
<p>Attached one finds a trace that illustrates the expected behavior (normal_call_example.pcapng). After the Assignment Request on the A-Interface a channel activation happens and then we can see Assignment Command and shortly after Assignment Complete. In assignment_complete_missing.pcapng we again see the Assignment Request on the A-Interface. The channel activation on RSL and then the Assignment Command, but no Assignmnet complete. What then happins is that T10 times out and the assignment fails.</p>
<p>Actually the Assignment Command von the RSL side is a Data-Request. When I get the things right this message is not touched by the BTS. It goes straight to the mobile and the assignment complete comes from the mobile and passes straight into the BSC.</p> OsmoMSC - Feature #2822 (Closed): work out MSC test scenarioshttps://osmocom.org/issues/28222018-01-08T20:43:22Zdexter
<p>We plan to test osmo-msc with TTCN3 as well. In Preparation of this we have to collect Ideas for test-cases.</p> libosmocore - Bug #2613 (Closed): vty crashes on tab-completionhttps://osmocom.org/issues/26132017-11-02T16:11:14Zdexter
<p>The problem is located in libosmocore, so it exists in all our products. It<br />looks like it is somehow liked to the tab-completion. The problem can be<br />triggered for example by logging into a vty and try to tab-complete some<br />items of the help menu, it seems to bail at the second level of tab completion.</p>
<pre>
Trying 127.0.0.1...
Connected to 127.0.0.1.
Escape character is '^]'.
Welcome to the osmo-stp control interface
Copyright (C) 2015-2017 by Harald Welte <laforge@gnumonks.org>
Contributions by Holger Freyther, Neels Hofmeyr
License GPLv2+: GNU GPL Version 2 or later <http://gnu.org/licenses/gpl-2.0.html>
This is free software: you are free ot change and redistribute it.
There is NO WARRANTY, to the extent permitted by law.
Free Software lives by contribution. If you use this, please contribute!
osmo-stp>
show Show running system information
list Print command list
exit Exit current mode and down to previous mode
help Description of the interactive help system
enable Turn on privileged mode command
terminal Set terminal line parameters
who Display who is on vty
logging Configure log message to this terminal
osmo-stp> h
osmo-stp> help
</pre>
<p>Attached the logtext including backtrace.</p> OsmoMGW - Bug #2598 (Closed): Choose correct interface/ip automaticallyhttps://osmocom.org/issues/25982017-10-27T11:11:27Zdexter
<p>If we run osmo-mgw in a setup where RTP streams are switched through more than a single interface will run into a problem. On startup osmo-mgw gets a statically configured IP-Address via VTY config. This IP-Address is returned with every MDCX/CRCX response. This works fine as long as all RTP traffic is passing through the configured interface.</p>
<p>In cases where a client tries to switch an RTP stream through an interface different from the configured one osmo-mgw still (binds to and) returns the IP-Address that has been configured. The problem is that the other side will then try to send the RTP traffic to that IP-Address, which will fail.</p>
<p>(e.g. osmo-mgw is bound to 1.1.1.1, 1.1.1.1 will be returned with any CRCX or MDCX, even when the remote host is connected through the interface with IP 2.2.2.2)</p>
<p>A solution could be to determine the correct interface/ip automatically. Then we could (bind to and) return the IP oft the interface that actually points to the remote side. All information we would need to do this is the IP-Address of the remote side. Then we can use osmo_sock_local_ip() from libosmocore to determine the IP we have to use.</p>
<p>However, this only works well if we can get the IP-Address of the remote side early with a CRCX message. Luckily this is the case with osmo-bsc, there we do a single phased connection assignment (one CRCX with remote IP, one response with local ip). For the other cases where we do not get the remote end IP with the CRCX we must fall back to the configured IP address.</p> OsmoMGW - Bug #2597 (Closed): revisit log categorieshttps://osmocom.org/issues/25972017-10-26T16:35:00Zdexter
<p>The network and the protocol part of osmo-mgw use the same logging category (DLMGCP). This is a problem because when we want to debug an MGCP protocol issue, we do not want to see all the network/rtp related output. DLMGCP is fine for the MGCP protocol part, but in network we should use a separete category (e.g. DLRTP or DLNET).</p> libosmocore - Feature #2587 (Closed): helper function to finde the right interface for a remote I...https://osmocom.org/issues/25872017-10-20T14:48:40Zdexter
<p>In some cases (mgcp-gw) it is important to know the IP-Address of the interface through which a remote IP-Address is reachable. This can be done using the syscalls connect() and getsockname(). Implement a helper function in socket.c that takes a remote ip-address as input and outputs the coresponding local interface</p> OsmoSGSN - Bug #2585 (Closed): build osmo-sgsn without libosmo-sigtranhttps://osmocom.org/issues/25852017-10-20T09:25:33Zdexter
<p>In its current state osmo-sgen depends on libosmo-sigtran even if it is not build for IU (3G-Support).</p> OsmoMSC - Bug #2573 (Closed): segfault in osmo-msc when subscriber silently vanisheshttps://osmocom.org/issues/25732017-10-12T16:56:16Zdexter
<p>Experiment: Use two mobiles, make a call from one to the other. While the call is running, remove the battery of the called mobile. After some time a segfault should occur on the MSC.</p>
<pre>
Thu Oct 12 18:50:29 2017 <000a> a_iface.c:527 N-DATA.ind(9, 00 04 22 04 01 01 )
Thu Oct 12 18:50:29 2017 <000a> a_iface_bssap.c:695 Rx BSC DT: 00 04 22 04 01 01
Thu Oct 12 18:50:29 2017 <000a> a_iface_bssap.c:625 Rx MSC DT1 BSSMAP CLEAR REQUEST
Thu Oct 12 18:50:29 2017 <000a> a_iface_bssap.c:225 BSC requested to clear connection (conn_id=9)
Thu Oct 12 18:50:29 2017 <000a> a_iface_bssap.c:79 Looking for A subscriber: conn_id 9
Thu Oct 12 18:50:29 2017 <001f> a_iface_bssap.c:87 Found A subscriber for conn_id 9
Thu Oct 12 18:50:29 2017 <0002> osmo_msc.c:340 Subscr_Conn(27736205)[0x5555558b39c0]{SUBSCR_CONN_S_COMMUNICATING}: Received Event SUBSCR_CONN_E_CN_CLOSE
Thu Oct 12 18:50:29 2017 <0002> subscr_conn.c:215 Subscr_Conn(27736205)[0x5555558b39c0]{SUBSCR_CONN_S_COMMUNICATING}: state_chg to SUBSCR_CONN_S_RELEASED
Thu Oct 12 18:50:29 2017 <0002> subscr_conn.c:242 Subscr_Conn(27736205)[0x5555558b39c0]{SUBSCR_CONN_S_RELEASED}: Terminating (cause = OSMO_FSM_TERM_REGULAR)
Thu Oct 12 18:50:29 2017 <001e> subscr_conn.c:242 Process_Access_Request_VLR(27736205)[0x5555558b23e0]{PR_ARQ_S_DONE}: Terminating (cause = OSMO_FSM_TERM_PARENT)
Thu Oct 12 18:50:29 2017 <001e> subscr_conn.c:242 Process_Access_Request_VLR(27736205)[0x5555558b23e0]{PR_ARQ_S_DONE}: Removing from parent Subscr_Conn(27736205)[0x5555558b39c0]
Thu Oct 12 18:50:29 2017 <001e> subscr_conn.c:242 Process_Access_Request_VLR(27736205)[0x5555558b23e0]{PR_ARQ_S_DONE}: Freeing instance
Thu Oct 12 18:50:29 2017 <001e> fsm.c:273 Process_Access_Request_VLR(27736205)[0x5555558b23e0]{PR_ARQ_S_DONE}: Deallocated
Thu Oct 12 18:50:29 2017 <0002> osmo_msc.c:328 msc_subscr_conn_close(vsub=MSISDN:23006, cause=2): no conn fsm, releasing directly without release event.
Thu Oct 12 18:50:29 2017 <0006> gsm_04_08.c:1270 transmit message MNCC_REL_IND
Thu Oct 12 18:50:29 2017 <0001> gsm_04_08.c:1293 Sending 'MNCC_REL_IND' to MNCC.
Thu Oct 12 18:50:29 2017 <0006> mncc_builtin.c:312 (call 5) Received message MNCC_REL_IND
Thu Oct 12 18:50:29 2017 <0006> mncc_builtin.c:242 (call 5) Releasing remote with cause 47
Thu Oct 12 18:50:29 2017 <0006> mncc_builtin.c:52 (call 5) Call removed.
Thu Oct 12 18:50:29 2017 <0006> gsm_04_08.c:2839 receive message MNCC_REL_REQ
Thu Oct 12 18:50:29 2017 <0001> gsm_04_08.c:3014 (ti 08 sub 23001) Received 'MNCC_REL_REQ' from MNCC in state 10 (ACTIVE)
Thu Oct 12 18:50:29 2017 <0001> gsm_04_08.c:1525 starting timer T308 with 10 seconds
Thu Oct 12 18:50:29 2017 <0001> gsm_04_08.c:1218 new state ACTIVE -> RELEASE_REQ
Thu Oct 12 18:50:29 2017 <000a> msc_ifaces.c:55 msc_tx 6 bytes to MSISDN:23001 via RAN_GERAN_A
Thu Oct 12 18:50:29 2017 <000a> a_iface.c:143 Passing DTAP message from MSC to BSC (conn_id=8)
Thu Oct 12 18:50:29 2017 <000a> a_iface.c:156 Message will be sent as BSSMAP DTAP message!
Thu Oct 12 18:50:29 2017 <000a> a_iface.c:158 N-DATA.req(8, 01 00 06 83 2d 08 02 81 af )
Thu Oct 12 18:50:29 2017 <0001> gsm_04_08.c:1218 new state ACTIVE -> NULL
Thu Oct 12 18:50:29 2017 <000e> transaction.c:134 VLR subscr MSISDN:23006 usage decreases to: 2
Thu Oct 12 18:50:29 2017 <000e> transaction.c:141 MSISDN:23006: MSC conn use - 1 == 0
Thu Oct 12 18:50:29 2017 <0000> osmo_msc.c:230 subscr MSISDN:23006: Freeing subscriber connection
Thu Oct 12 18:50:29 2017 <000e> osmo_msc.c:232 VLR subscr MSISDN:23006 usage decreases to: 1
Thu Oct 12 18:50:29 2017 <000a> a_iface.c:426 Sending clear command to BSC (conn_id=9)
Program received signal SIGSEGV, Segmentation fault.
vlr_subscr_name (vsub=0x90) at gsm_subscriber_base.c:45
45 if (vsub->msisdn[0])
(gdb) bt
#0 vlr_subscr_name (vsub=0x90) at gsm_subscriber_base.c:45
#1 0x0000555555574c72 in _msc_subscr_conn_put (conn=0x5555558b3ee0, file=0x55555558a6a9 "subscr_conn.c", line=228) at osmo_msc.c:375
#2 0x00007ffff733aef5 in _osmo_fsm_inst_term (fi=0x5555558b39c0, cause=OSMO_FSM_TERM_REGULAR, data=0x0, file=0x55555558a6a9 "subscr_conn.c", line=242) at fsm.c:479
#3 0x00007ffff733a77c in _osmo_fsm_inst_state_chg (fi=0x5555558b39c0, new_state=<optimized out>, timeout_secs=0, T=0, file=<optimized out>, line=<optimized out>) at fsm.c:382
#4 0x00007ffff733aa0d in _osmo_fsm_inst_dispatch (fi=0x5555558b39c0, event=event@entry=6, data=data@entry=0x7fffffffcb5c, file=file@entry=0x55555558a513 "osmo_msc.c", line=line@entry=340) at fsm.c:436
#5 0x0000555555574987 in msc_subscr_conn_close (conn=0x5555558b3ee0, cause=<optimized out>, cause@entry=1) at osmo_msc.c:340
#6 0x0000555555574b19 in msc_clear_request (conn=<optimized out>, cause=cause@entry=1) at osmo_msc.c:262
#7 0x000055555556115c in bssmap_rx_clear_rqst (scu=scu@entry=0x5555558974c0, msg=0x5555558b52b0, a_conn_info=<optimized out>, a_conn_info=<optimized out>) at a_iface_bssap.c:242
#8 0x00005555555621a3 in rx_bssmap (msg=<optimized out>, a_conn_info=0x7fffffffdbc8, scu=0x5555558974c0) at a_iface_bssap.c:629
#9 sccp_rx_dt (scu=scu@entry=0x7ffff6c7b880 <sccp_scoc_states>, a_conn_info=a_conn_info@entry=0x7fffffffdbd0, msg=<optimized out>) at a_iface_bssap.c:706
#10 0x000055555555f6b4 in sccp_sap_up (oph=0x7ffff6c7e5a0 <sccp_scoc_fsm>, _scu=0x7ffff6c7b880 <sccp_scoc_states>) at a_iface.c:528
#11 0x00007ffff733aa0d in _osmo_fsm_inst_dispatch (fi=0x5555558b1be0, event=11, data=data@entry=0x5555558b4f20, file=file@entry=0x7ffff6a6c4bd "sccp_scoc.c", line=line@entry=1579) at fsm.c:436
#12 0x00007ffff6a5d5cc in sccp_scoc_rx_from_scrc (inst=inst@entry=0x5555558973f0, xua=xua@entry=0x5555558b4f20) at sccp_scoc.c:1579
#13 0x00007ffff6a5b220 in scrc_rx_mtp_xfer_ind_xua (inst=inst@entry=0x5555558973f0, xua=0x5555558b4f20) at sccp_scrc.c:447
#14 0x00007ffff6a5e0f5 in mtp_user_prim_cb (oph=0x5555558a1c68, ctx=0x5555558973f0) at sccp_user.c:174
#15 0x00007ffff6a561c2 in m3ua_rx_xfer (xua=0x5555558a9580, asp=0x555555873230) at m3ua.c:584
#16 m3ua_rx_msg (asp=asp@entry=0x555555873230, msg=msg@entry=0x5555558a2ec0) at m3ua.c:736
#17 0x00007ffff6a6103b in xua_cli_read_cb (conn=<optimized out>) at osmo_ss7.c:1552
#18 0x00007ffff5c6c39b in osmo_stream_cli_read (cli=0x555555896e30) at stream.c:166
#19 osmo_stream_cli_fd_cb (ofd=<optimized out>, what=1) at stream.c:250
#20 0x00007ffff73376ee in osmo_fd_disp_fds (_eset=0x7fffffffdff0, _wset=0x7fffffffdf70, _rset=0x7fffffffdef0) at select.c:213
#21 osmo_select_main (polling=<optimized out>) at select.c:253
#22 0x000055555555ed6c in main (argc=3, argv=0x7fffffffe1d8) at msc_main.c:587
(gdb)
</pre> OsmoMGW - Bug #2535 (Closed): improve mgcp client APIhttps://osmocom.org/issues/25352017-10-04T16:51:06Zdexter
<p>The API of the mgcp client is not very optimal designed and we should change it. The problem is that the set of functions that return the generated MGCP message take all parameters separately. MGCP messages have plenty of parameters and when we need one more parameter we have to add another function. I already did this a few times now.</p>
<p>The solution to the problem would be just one (or at least one per message type) generator function that takes a struct. Depending on how the struct is populated the parameter will be included in the MGCP message or not.</p> OsmoMGW - Bug #2521 (Rejected): reduce levels in struct mgcp_conn_rtp https://osmocom.org/issues/25212017-09-25T21:21:54Zdexter
<p>See struct mgcp_conn_rtp in mgcp_internal.h. Struct member struct mgcp_rtp_end end could be eliminated by putting all struct members from struct mgcp_rtp_end to struct mgcp_conn_rtp. This would reduce one level when dereferencing the pointers. The code would become more readable.</p> OpenBSC - Feature #2515 (Closed): integrate osmo-mgw in osmo-bschttps://osmocom.org/issues/25152017-09-18T15:48:17Zdexter
<p>osmo-mgw has reached a development state, where it makes sens to try out how it performs in a real life situation. Osmo-bsc seems like a good test target for that and requires mgcp features anyway to support handover. The complexity can be limited by leaving osmo-msc on the legacy mgcp, while performing changes only to osmo-bsc. When done, osmo-bsc should not behave any different on the A-Interface.</p> OsmoMGW - Bug #2454 (Closed): Restructure existing codehttps://osmocom.org/issues/24542017-08-21T08:20:30Zdexter
<p>Large parts of the existing code (e.g. the protocol parser) can be reused. We need to identify the re-usable parts and structure them into modules, we also need tests for this modules.</p>
<p>mgcp_protocol.c seems to be a good starting point.</p> libosmo-sccp + libosmo-sigtran - Bug #2441 (Closed): chopped-off pointcodeshttps://osmocom.org/issues/24412017-08-15T11:16:54Zdexter
<p>It seems that that the pointcode data is chopped off when receiving unittdata.</p>
<p>When looking at the attached trace.pcapng file, one can see that the RESET<br />command is correctly transmitted, but the response, the RESET ACK is always<br />sent to the wrong destination address. (187 instead of 2235). When converting<br />those to numbers one can see that the addresses seem to be chopped off,<br />presumably at the 8th bit:</p>
<pre>
2235 = 100010111011
187 = 10111011
</pre>
<p>When investigating further it turns out that the pointcode is already chopped<br />off when the RESET is received:</p>
<pre>
Tue Aug 15 11:35:20 2017 <000a> a_iface.c:531 N-UNITDATA.ind(00 04 30 04 01 20 )
Tue Aug 15 11:35:20 2017 <000a> a_iface_bssap.c:184 Rx BSC UDT: 00 04 30 04 01 20
Tue Aug 15 11:35:20 2017 <000a> a_iface_bssap.c:157 Rx BSC UDT BSSMAP RESET
Tue Aug 15 11:35:20 2017 <000a> a_iface_bssap.c:110 Rx RESET from BSC RI=SSN_PC,PC=0.23.3,SSN=unknown 0xfe,GTI=NO_GT, sending RESET ACK
Tue Aug 15 11:35:20 2017 <000a> fsm.c:176 FSM RESET(FSM RESET INST)[0x55555589b7a0]{DISC}: Timeout of T0
Tue Aug 15 11:35:20 2017 <000a> a_reset.c:102 (RI=SSN_PC,PC=0.23.3,SSN=unknown 0xfe,GTI=NO_GT) reset-ack timeout (T0) in state ST_DISC (disconnected), resending...
Tue Aug 15 11:35:20 2017 <000a> a_iface.c:443 Sending RESET to BSC RI=SSN_PC,PC=0.23.3,SSN=unknown 0xfe,GTI=NO_GT
</pre>
<p>Presumably the upcoming primitive already contains the chopped pointcode.</p> OpenBSC - Bug #2424 (Closed): use osmo_sccp_addr_set_ssn() in osmo-bschttps://osmocom.org/issues/24242017-08-07T15:14:20Zdexter
<p><a class="external" href="https://gerrit.osmocom.org/#/c/3359/">https://gerrit.osmocom.org/#/c/3359/</a> is still in review, use the provided function osmo_sccp_addr_set_ssn() as soon as it is merged.</p> libosmo-sccp + libosmo-sigtran - Feature #2417 (Closed): function to check sccp-addresseshttps://osmocom.org/issues/24172017-08-01T10:37:29Zdexter
<p>sccp-addresses consist of a number of components. A presence bitmask denotes if a component has a valid value or not. Add a function that checks the presence field against a given value. Also check if the values fall into the correct range, so that a malformed sccp-address is detected early.</p> OpenBSC - Feature #2396 (Closed): Comfortable CS7/SS7 VTY configuration for osmo-bsc and osmo-mschttps://osmocom.org/issues/23962017-07-24T19:54:54Zdexter
<p>osmo-msc and osmo-bsc currently lack important SS7 related VTY configuration features. Add proper VTY configuration commands to both applications</p> libosmo-sccp + libosmo-sigtran - Bug #2381 (Closed): function to automatically generate a local S...https://osmocom.org/issues/23812017-07-20T08:27:17Zdexter
<p>In some cases it would be very helpful if the user could just ask the sccp API for a local address. Such an address can be derived from the configuration data we have set for the CS7 instance via VTY.</p> libosmo-sccp + libosmo-sigtran - Bug #2376 (Closed): search for an sscp-address and return ss7 in...https://osmocom.org/issues/23762017-07-19T08:09:09Zdexter
<p>By the current API definition, the user can limit the search range to a specific ss7 instance (if that instance is known). When the given ss7 instance pointer is NULL, the global list is searched. This scheme will be changed to:</p>
<p>When searching, always the global list is searched. If found, the address will be copied to the pointer which the caller has issued. We will also return the pointer to the ss7 instance. A returned NULL pointer indicates that the entry was not found. By creating a copy of the addressbook entry we also prevent that the caller might change the address data in the addressbook. The only legal way to change addressbook entries is the VTY.</p>
<p>The API should look like this:</p>
<p>struct osmo_ss7_instance *osmo_sccp_addr_by_name(const char *name, struct osmo_sccp_addr *dest);</p>
<p>const char *osmo_sccp_name_by_addr(const struct osmo_sccp_addr *addr);</p> libosmo-sccp + libosmo-sigtran - Bug #2375 (Closed): enforce unique names in sccp-addressbookhttps://osmocom.org/issues/23752017-07-19T07:56:56Zdexter
<p>Each sccp-addressbook entry is referenced by a name. Make sure that a name can not be used twice.</p>
<p>Inside a single ss7 instace, reusing a name twice is not possible, but a user could use the same name twice in different ss7 instance. This situation mus be prevented.</p> libosmo-sccp + libosmo-sigtran - Bug #2351 (Closed): unify sccp instance configurationhttps://osmocom.org/issues/23512017-07-06T09:41:55Zdexter
<p>The configuration of the sccp instance can be unified. The parameters of osmo_sccp_simple_client() which is used to create the sccp instance could be configured using the built in VTY of libosmo-sccp. This would unify the configuration of SCCP and offload the application specific VTY. It also would help to simplify the configuration from the users perspective. The user will not have to learn a new way to configur SS7 applications all the time.</p>
<pre>
struct osmo_sccp_instance *
osmo_sccp_simple_client(void *ctx, const char *name, uint32_t pc,
enum osmo_ss7_asp_protocol prot, int local_port,
const char *local_ip, int remote_port, const char *remote_ip);
</pre> OsmoPCU - Bug #1931 (Rejected): Downlink TBF allocation problem during PDP-Context Deact REQ on O...https://osmocom.org/issues/19312017-01-30T12:04:26Zdexter
<p>In some cases, primarily when a the MS requests to deactivate the PDP context a problem allocating a downlink TBF occurs:</p>
<p>The observation of the diag interface of the MS shows that that the MS is sending a PDP context deactivation request. The request reaches SGSN and the SGSN responds correctly with a PDP context deactivation ACK. The diag interface on the modem shows that the PDP context deactivation ACK is never received. The MS repeats the request 4 times until it finally gives up.</p>
<pre>
Thu Jan 19 11:27:19 2017 <0011> gprs_bssgp.c:379 BSSGP TLLI=0xd4d4ca34 Rx UPLINK-UNITDATA
Thu Jan 19 11:27:19 2017 <0012> gprs_llc_parse.c:82 LLC SAPI=1 C U GEA0 IOV-UI=0x000000 FCS=0x20b16a CMD=UI DATA
Thu Jan 19 11:27:19 2017 <0002> gprs_gmm.c:2444 MM(001010000000001/d4d4ca34) -> DEACTIVATE PDP CONTEXT REQ (cause: Regular deactivation)
Thu Jan 19 11:27:19 2017 <000f> sgsn_libgtp.c:286 PDP(001010000000001/0) Delete PDP Context
Thu Jan 19 11:27:19 2017 <000f> sgsn_libgtp.c:613 PDP Context was deleted
Thu Jan 19 11:27:19 2017 <000f> sgsn_libgtp.c:590 libgtp cb_conf(type=20, cause=128, pdp=(nil), cbp=0x1a2e010)
Thu Jan 19 11:27:19 2017 <000f> sgsn_libgtp.c:513 PDP(001010000000001/0) Received DELETE PDP CTX CONF, cause=128(Request accepted)
Thu Jan 19 11:27:19 2017 <0013> gprs_sndcp.c:509 SNSM-DEACTIVATE.ind (lle=0x1a2be20, TLLI=d4d4ca34, SAPI=3, NSAPI=5)
Thu Jan 19 11:27:19 2017 <0002> gprs_gmm.c:2127 MM(001010000000001/d4d4ca34) <- DEACTIVATE PDP CONTEXT ACK
Thu Jan 19 11:27:24 2017 <0011> gprs_bssgp.c:797 BSSGP BVCI=23 Rx Flow Control BVC
Thu Jan 19 11:27:27 2017 <0011> gprs_bssgp.c:379 BSSGP TLLI=0xd4d4ca34 Rx UPLINK-UNITDATA
Thu Jan 19 11:27:27 2017 <0012> gprs_llc_parse.c:82 LLC SAPI=1 C U GEA0 IOV-UI=0x000000 FCS=0xac2522 CMD=UI DATA
Thu Jan 19 11:27:27 2017 <0002> gprs_gmm.c:2444 MM(001010000000001/d4d4ca34) -> DEACTIVATE PDP CONTEXT REQ (cause: Regular deactivation)
Thu Jan 19 11:27:27 2017 <0002> gprs_gmm.c:2451 MM(001010000000001/d4d4ca34) Deactivate PDP Context Request for non-existing PDP Context (IMSI=001010000000001, TI=0)
Thu Jan 19 11:27:27 2017 <0002> gprs_gmm.c:2127 MM(001010000000001/d4d4ca34) <- DEACTIVATE PDP CONTEXT ACK
Thu Jan 19 11:27:30 2017 <000f> gprs_sgsn.c:870 Checking for inactive LLMEs, time = 126147
Thu Jan 19 11:27:34 2017 <0010> gprs_ns.c:528 NSEI=23 Tx NS ALIVE_ACK (NSVCI=23)
Thu Jan 19 11:27:34 2017 <0011> gprs_bssgp.c:797 BSSGP BVCI=23 Rx Flow Control BVC
Thu Jan 19 11:27:34 2017 <0010> gprs_ns.c:582 NSEI=23 Timer expired in mode tns-test (30 seconds)
Thu Jan 19 11:27:34 2017 <0010> gprs_ns.c:515 NSEI=23 Tx NS ALIVE (NSVCI=23)
Thu Jan 19 11:27:34 2017 <0010> gprs_ns.c:554 NSEI=23 Starting timer in mode tns-alive (3 seconds)
Thu Jan 19 11:27:34 2017 <0010> gprs_ns.c:554 NSEI=23 Starting timer in mode tns-test (30 seconds)
Thu Jan 19 11:27:35 2017 <0011> gprs_bssgp.c:379 BSSGP TLLI=0xd4d4ca34 Rx UPLINK-UNITDATA
Thu Jan 19 11:27:35 2017 <0012> gprs_llc_parse.c:82 LLC SAPI=1 C U GEA0 IOV-UI=0x000000 FCS=0xb55300 CMD=UI DATA
Thu Jan 19 11:27:35 2017 <0002> gprs_gmm.c:2444 MM(001010000000001/d4d4ca34) -> DEACTIVATE PDP CONTEXT REQ (cause: Regular deactivation)
Thu Jan 19 11:27:35 2017 <0002> gprs_gmm.c:2451 MM(001010000000001/d4d4ca34) Deactivate PDP Context Request for non-existing PDP Context (IMSI=001010000000001, TI=0)
Thu Jan 19 11:27:35 2017 <0002> gprs_gmm.c:2127 MM(001010000000001/d4d4ca34) <- DEACTIVATE PDP CONTEXT ACK
Thu Jan 19 11:27:43 2017 <0011> gprs_bssgp.c:379 BSSGP TLLI=0xd4d4ca34 Rx UPLINK-UNITDATA
Thu Jan 19 11:27:43 2017 <0012> gprs_llc_parse.c:82 LLC SAPI=1 C U GEA0 IOV-UI=0x000000 FCS=0x39c748 CMD=UI DATA
Thu Jan 19 11:27:43 2017 <0002> gprs_gmm.c:2444 MM(001010000000001/d4d4ca34) -> DEACTIVATE PDP CONTEXT REQ (cause: Regular deactivation)
Thu Jan 19 11:27:43 2017 <0002> gprs_gmm.c:2451 MM(001010000000001/d4d4ca34) Deactivate PDP Context Request for non-existing PDP Context (IMSI=001010000000001, TI=0)
Thu Jan 19 11:27:43 2017 <0002> gprs_gmm.c:2127 MM(001010000000001/d4d4ca34) <- DEACTIVATE PDP CONTEXT ACK
Thu Jan 19 11:27:44 2017 <0011> gprs_bssgp.c:797 BSSGP BVCI=23 Rx Flow Control BVC
Thu Jan 19 11:27:51 2017 <0011> gprs_bssgp.c:379 BSSGP TLLI=0xd4d4ca34 Rx UPLINK-UNITDATA
Thu Jan 19 11:27:51 2017 <0012> gprs_llc_parse.c:82 LLC SAPI=1 C U GEA0 IOV-UI=0x000000 FCS=0xf7702b CMD=UI DATA
Thu Jan 19 11:27:51 2017 <0002> gprs_gmm.c:2444 MM(001010000000001/d4d4ca34) -> DEACTIVATE PDP CONTEXT REQ (cause: Regular deactivation)
Thu Jan 19 11:27:51 2017 <0002> gprs_gmm.c:2451 MM(001010000000001/d4d4ca34) Deactivate PDP Context Request for non-existing PDP Context (IMSI=001010000000001, TI=0)
Thu Jan 19 11:27:51 2017 <0002> gprs_gmm.c:2127 MM(001010000000001/d4d4ca34) <- DEACTIVATE PDP CONTEXT ACK
Thu Jan 19 11:27:54 2017 <0011> gprs_bssgp.c:797 BSSGP BVCI=23 Rx Flow Control BVC
Thu Jan 19 11:28:00 2017 <000f> gprs_sgsn.c:870 Checking for inactive LLMEs, time = 126177
Thu Jan 19 11:28:04 2017 <0010> gprs_ns.c:528 NSEI=23 Tx NS ALIVE_ACK (NSVCI=23)
Thu Jan 19 11:28:04 2017 <0011> gprs_bssgp.c:797 BSSGP BVCI=23 Rx Flow Control BVC
Thu Jan 19 11:28:04 2017 <0010> gprs_ns.c:582 NSEI=23 Timer expired in mode tns-test (30 seconds)
</pre>
<p>By the diag log we see that the downlink assignment message, the PCU is sending is missing, while the log of the PCU confirms that the downlink assignment message is sent:</p>
<pre>
Thu Jan 19 11:27:51 2017 <0001> pcu_l1_if.cpp:350 RACH request received: sapi=1 qta=0, ra=123, fn=82125
Thu Jan 19 11:27:51 2017 <0002> bts.cpp:562 MS requests UL TBF on RACH, so we provide one
ra=0x7b Fn=82125 qta=0 is_11bit=0:
Thu Jan 19 11:27:51 2017 <0002> bts.cpp:708 pcu has not received burst type from bts
Thu Jan 19 11:27:51 2017 <0002> tbf.cpp:694 ********** TBF starts here **********
Thu Jan 19 11:27:51 2017 <0002> tbf.cpp:696 Allocating UL TBF: MS_CLASS=0/0
Thu Jan 19 11:27:51 2017 <0002> gprs_ms.cpp:115 Creating MS object, TLLI = 0x00000000
Thu Jan 19 11:27:51 2017 <0002> bts.cpp:454 Searching for first unallocated TFI: TRX=0
Thu Jan 19 11:27:51 2017 <0002> bts.cpp:464 Found TFI=0.
Thu Jan 19 11:27:51 2017 <0002> gprs_rlcmac_ts_alloc.cpp:525 Slot Allocation (Algorithm B) for unknown class (assuming 12)
Thu Jan 19 11:27:51 2017 <0002> gprs_rlcmac_ts_alloc.cpp:560 - Rx=4 Tx=4 Sum Rx+Tx=5 Tta=2 Ttb=1 Tra=2 Trb=1 Type=1
Thu Jan 19 11:27:51 2017 <0002> gprs_rlcmac_ts_alloc.cpp:157 - Skipping TS 0, because not enabled
Thu Jan 19 11:27:51 2017 <0002> gprs_rlcmac_ts_alloc.cpp:157 - Skipping TS 1, because not enabled
Thu Jan 19 11:27:51 2017 <0002> gprs_rlcmac_ts_alloc.cpp:157 - Skipping TS 2, because not enabled
Thu Jan 19 11:27:51 2017 <0002> gprs_rlcmac_ts_alloc.cpp:157 - Skipping TS 3, because not enabled
Thu Jan 19 11:27:51 2017 <0002> gprs_rlcmac_ts_alloc.cpp:157 - Skipping TS 4, because not enabled
Thu Jan 19 11:27:51 2017 <0002> gprs_rlcmac_ts_alloc.cpp:157 - Skipping TS 5, because not enabled
Thu Jan 19 11:27:51 2017 <0002> gprs_rlcmac_ts_alloc.cpp:157 - Skipping TS 6, because not enabled
Thu Jan 19 11:27:51 2017 <0002> gprs_rlcmac_ts_alloc.cpp:579 - Possible DL/UL slots: (TS=0)".......C"(TS=7)
Thu Jan 19 11:27:51 2017 <0002> gprs_rlcmac_ts_alloc.cpp:940 - Selected UL slots: (TS=0)".......U"(TS=7), single
Thu Jan 19 11:27:51 2017 <0002> gprs_rlcmac_ts_alloc.cpp:966 Using single slot at TS 7 for UL
Thu Jan 19 11:27:51 2017 <0002> gprs_rlcmac_ts_alloc.cpp:990 - Reserved DL/UL slots: (TS=0)".......C"(TS=7)
Thu Jan 19 11:27:51 2017 <0002> gprs_rlcmac_ts_alloc.cpp:1017 - Assigning UL TS 7
Thu Jan 19 11:27:51 2017 <0002> bts.cpp:1681 PDCH(TS 7, TRX 0): Attaching TBF(TFI=0 TLLI=0x00000000 DIR=UL STATE=NULL), 1 TBFs, USFs = 01, TFIs = 00000001.
Thu Jan 19 11:27:51 2017 <0002> tbf.cpp:399 - Setting Control TS 7
Thu Jan 19 11:27:51 2017 <0002> gprs_ms.cpp:268 Attaching TBF to MS object, TLLI = 0x00000000, TBF = TBF(TFI=0 TLLI=0x00000000 DIR=UL STATE=NULL)
Thu Jan 19 11:27:51 2017 <0002> tbf.cpp:647 Allocated TBF(TFI=0 TLLI=0x00000000 DIR=UL STATE=NULL): trx = 0, ul_slots = 80, dl_slots = 00
Thu Jan 19 11:27:51 2017 <0002> gprs_ms.cpp:471 Modifying MS object, TLLI = 0x00000000, TA 220 -> 0
Thu Jan 19 11:27:51 2017 <0002> bts.cpp:294 TBF(TFI=0 TLLI=0x00000000 DIR=UL STATE=NULL) changes state from NULL to FLOW
Thu Jan 19 11:27:51 2017 <0002> tbf.cpp:422 TBF(TFI=0 TLLI=0x00000000 DIR=UL STATE=FLOW) starting timer 3169.
Thu Jan 19 11:27:51 2017 <0002> bts.cpp:611 TBF(TFI=0 TLLI=0x00000000 DIR=UL STATE=FLOW) [UPLINK] START
Thu Jan 19 11:27:51 2017 <0002> bts.cpp:617 TBF(TFI=0 TLLI=0x00000000 DIR=UL STATE=FLOW) RX: [PCU <- BTS] RACH qbit-ta=0 ra=0x7b, Fn=82125 (29,15,17)
Thu Jan 19 11:27:51 2017 <0002> bts.cpp:620 TBF(TFI=0 TLLI=0x00000000 DIR=UL STATE=FLOW) TX: START Immediate Assignment Uplink (AGCH)
Thu Jan 19 11:27:51 2017 <0002> bts.cpp:640 - TRX=0 (866) TS=7 TA=0 TSC=7 TFI=0 USF=0
Thu Jan 19 11:27:51 2017 <0006> gprs_rlcmac_sched.cpp:109 Received RTS for PDCH: TRX=0 TS=7 FN=82134 block_nr=6 scheduling USF=0 for required uplink resource of UL TFI=0
Thu Jan 19 11:27:51 2017 <0006> gprs_rlcmac_sched.cpp:109 Received RTS for PDCH: TRX=0 TS=7 FN=82138 block_nr=7 scheduling USF=0 for required uplink resource of UL TFI=0
Thu Jan 19 11:27:51 2017 <0006> gprs_rlcmac_sched.cpp:109 Received RTS for PDCH: TRX=0 TS=7 FN=82142 block_nr=8 scheduling USF=0 for required uplink resource of UL TFI=0
Thu Jan 19 11:27:51 2017 <0006> gprs_rlcmac_sched.cpp:109 Received RTS for PDCH: TRX=0 TS=7 FN=82147 block_nr=9 scheduling USF=0 for required uplink resource of UL TFI=0
Thu Jan 19 11:27:51 2017 <0006> gprs_rlcmac_sched.cpp:109 Received RTS for PDCH: TRX=0 TS=7 FN=82151 block_nr=10 scheduling USF=0 for required uplink resource of UL TFI=0
Thu Jan 19 11:27:51 2017 <0006> gprs_rlcmac_sched.cpp:109 Received RTS for PDCH: TRX=0 TS=7 FN=82155 block_nr=11 scheduling USF=0 for required uplink resource of UL TFI=0
Thu Jan 19 11:27:51 2017 <0006> gprs_rlcmac_sched.cpp:109 Received RTS for PDCH: TRX=0 TS=7 FN=82160 block_nr=0 scheduling USF=0 for required uplink resource of UL TFI=0
Thu Jan 19 11:27:51 2017 <0006> gprs_rlcmac_sched.cpp:109 Received RTS for PDCH: TRX=0 TS=7 FN=82164 block_nr=1 scheduling USF=0 for required uplink resource of UL TFI=0
Thu Jan 19 11:27:51 2017 <0006> gprs_rlcmac_sched.cpp:109 Received RTS for PDCH: TRX=0 TS=7 FN=82168 block_nr=2 scheduling USF=0 for required uplink resource of UL TFI=0
Thu Jan 19 11:27:51 2017 <0006> gprs_rlcmac_sched.cpp:109 Received RTS for PDCH: TRX=0 TS=7 FN=82173 block_nr=3 scheduling USF=0 for required uplink resource of UL TFI=0
Thu Jan 19 11:27:51 2017 <0006> gprs_rlcmac_sched.cpp:109 Received RTS for PDCH: TRX=0 TS=7 FN=82177 block_nr=4 scheduling USF=0 for required uplink resource of UL TFI=0
Thu Jan 19 11:27:51 2017 <0006> gprs_rlcmac_sched.cpp:109 Received RTS for PDCH: TRX=0 TS=7 FN=82181 block_nr=5 scheduling USF=0 for required uplink resource of UL TFI=0
Thu Jan 19 11:27:51 2017 <0006> gprs_rlcmac_sched.cpp:109 Received RTS for PDCH: TRX=0 TS=7 FN=82186 block_nr=6 scheduling USF=0 for required uplink resource of UL TFI=0
Thu Jan 19 11:27:51 2017 <0002> tbf.cpp:426 TBF(TFI=0 TLLI=0x00000000 DIR=UL STATE=FLOW) restarting timer 3169 while old timer 3169 pending
Thu Jan 19 11:27:51 2017 <0002> gprs_ms.cpp:457 Modifying MS object, TLLI = 0x00000000, IMSI '' -> '001010000000001'
Thu Jan 19 11:27:51 2017 <0002> gprs_ms.cpp:361 Clearing MS object, TLLI: 0xd4d4ca34, IMSI: '001010000000001'
Thu Jan 19 11:27:51 2017 <0002> gprs_ms.cpp:396 Modifying MS object, UL TLLI: 0x00000000 -> 0xd4d4ca34, not yet confirmed
Thu Jan 19 11:27:51 2017 <0002> gprs_ms.cpp:141 Destroying MS object, TLLI = 0x00000000
Thu Jan 19 11:27:51 2017 <0009> tbf_ul.cpp:373 LLC [PCU -> SGSN] TBF(TFI=0 TLLI=0xd4d4ca34 DIR=UL STATE=FLOW) len=10
Thu Jan 19 11:27:51 2017 <0002> tbf_ul.cpp:294 TBF(TFI=0 TLLI=0xd4d4ca34 DIR=UL STATE=FLOW) changes state from FLOW to FINISHED
Thu Jan 19 11:27:51 2017 <0009> gprs_bssgp_pcu.cpp:180 LLC [SGSN -> PCU] = TLLI: 0xd4d4ca34 IMSI: 001010000000001 len: 8
Thu Jan 19 11:27:51 2017 <0002> tbf.cpp:775 ********** TBF starts here **********
Thu Jan 19 11:27:51 2017 <0002> tbf.cpp:777 Allocating DL TBF: MS_CLASS=0/0
Thu Jan 19 11:27:51 2017 <0002> bts.cpp:454 Searching for first unallocated TFI: TRX=0
Thu Jan 19 11:27:51 2017 <0002> bts.cpp:464 Found TFI=0.
Thu Jan 19 11:27:51 2017 <0002> gprs_rlcmac_ts_alloc.cpp:902 - Selected DL slots: (TS=0)".......D"(TS=7), single
Thu Jan 19 11:27:51 2017 <0002> gprs_rlcmac_ts_alloc.cpp:966 Using single slot at TS 7 for DL
Thu Jan 19 11:27:51 2017 <0002> gprs_rlcmac_ts_alloc.cpp:1004 - Assigning DL TS 7
Thu Jan 19 11:27:51 2017 <0002> bts.cpp:1681 PDCH(TS 7, TRX 0): Attaching TBF(TFI=0 TLLI=0x00000000 DIR=DL STATE=NULL), 1 TBFs, USFs = 01, TFIs = 00000001.
Thu Jan 19 11:27:51 2017 <0002> tbf.cpp:399 - Setting Control TS 7
Thu Jan 19 11:27:51 2017 <0002> gprs_ms.cpp:287 Attaching TBF to MS object, TLLI = 0xd4d4ca34, TBF = TBF(TFI=0 TLLI=0xd4d4ca34 DIR=DL STATE=NULL)
Thu Jan 19 11:27:51 2017 <0002> tbf.cpp:647 Allocated TBF(TFI=0 TLLI=0xd4d4ca34 DIR=DL STATE=NULL): trx = 0, ul_slots = 80, dl_slots = 80
Thu Jan 19 11:27:51 2017 <0002> gprs_ms.cpp:430 Modifying MS object, TLLI: 0xd4d4ca34 confirmed
Thu Jan 19 11:27:51 2017 <0002> tbf_dl.cpp:161 TBF(TFI=0 TLLI=0xd4d4ca34 DIR=DL STATE=NULL) [DOWNLINK] START
Thu Jan 19 11:27:51 2017 <0002> bts.cpp:749 Send dowlink assignment for TBF(TFI=0 TLLI=0xd4d4ca34 DIR=DL STATE=NULL) on PCH, no TBF exist (IMSI=001010000000001)
Thu Jan 19 11:27:51 2017 <0002> bts.cpp:294 TBF(TFI=0 TLLI=0xd4d4ca34 DIR=DL STATE=NULL) changes state from NULL to ASSIGN
Thu Jan 19 11:27:51 2017 <0002> gprs_rlcmac.cpp:35 TX: [PCU -> BTS] Paging Request (CCCH)
Thu Jan 19 11:27:51 2017 <0002> bts.cpp:770 TX: START TBF(TFI=0 TLLI=0xd4d4ca34 DIR=DL STATE=ASSIGN) Immediate Assignment Downlink (PCH)
Thu Jan 19 11:27:51 2017 <0002> bts.cpp:777 - TRX=0 (866) TS=7 TA=0 pollFN=-1
Thu Jan 19 11:27:51 2017 <0002> tbf.cpp:422 TBF(TFI=0 TLLI=0xd4d4ca34 DIR=DL STATE=ASSIGN) starting timer 0.
Thu Jan 19 11:27:51 2017 <0002> tbf_dl.cpp:90 TBF(TFI=0 TLLI=0xd4d4ca34 DIR=DL STATE=ASSIGN) append
Thu Jan 19 11:27:51 2017 <0002> tbf.cpp:487 TBF(TFI=0 TLLI=0xd4d4ca34 DIR=UL STATE=FINISHED): Scheduling polling at FN 82203 TS 7
Thu Jan 19 11:27:51 2017 <0006> gprs_rlcmac_sched.cpp:181 Scheduling control message at RTS for TBF(TFI=0 TLLI=0xd4d4ca34 DIR=UL STATE=FINISHED) (TRX=0, TS=7)
Thu Jan 19 11:27:51 2017 <0002> tbf.cpp:426 TBF(TFI=0 TLLI=0xd4d4ca34 DIR=UL STATE=FINISHED) restarting timer 3169 while old timer 3169 pending
Thu Jan 19 11:27:51 2017 <0002> tbf.cpp:426 TBF(TFI=0 TLLI=0xd4d4ca34 DIR=UL STATE=FINISHED) restarting timer 3169 while old timer 3169 pending
Thu Jan 19 11:27:51 2017 <0006> gprs_rlcmac_sched.cpp:329 Received RTS for PDCH: TRX=0 TS=7 FN=82199 block_nr=9 scheduling free USF for polling at FN=82203 of TBF(TFI=0 TLLI=0xd4d4ca34 DIR=UL STATE=FINISHED)
Thu Jan 19 11:27:51 2017 <0002> bts.cpp:1448 +++++++++++++++++++++++++ RX : Uplink Control Block +++++++++++++++++++++++++
Thu Jan 19 11:27:51 2017 <0002> bts.cpp:1451 ------------------------- RX : Uplink Control Block -------------------------
Thu Jan 19 11:27:51 2017 <0002> bts.cpp:955 RX: [PCU <- BTS] TBF(TFI=0 TLLI=0xd4d4ca34 DIR=UL STATE=FINISHED) Packet Control Ack
Thu Jan 19 11:27:51 2017 <0002> bts.cpp:960 TBF: [UPLINK] END TBF(TFI=0 TLLI=0xd4d4ca34 DIR=UL STATE=FINISHED)
Thu Jan 19 11:27:51 2017 <0007> gprs_rlcmac_meas.cpp:104 UL RSSI of TLLI=0xd4d4ca34: -103 dBm
Thu Jan 19 11:27:51 2017 <0002> tbf.cpp:342 TBF(TFI=0 TLLI=0xd4d4ca34 DIR=UL STATE=FINISHED) free
Thu Jan 19 11:27:51 2017 <0002> tbf.cpp:447 TBF(TFI=0 TLLI=0xd4d4ca34 DIR=UL STATE=FINISHED) stopping timer 3169.
Thu Jan 19 11:27:51 2017 <0002> bts.cpp:1701 PDCH(TS 7, TRX 0): Detaching TBF(TFI=0 TLLI=0xd4d4ca34 DIR=UL STATE=FINISHED), 0 TBFs, USFs = 00, TFIs = 00000000.
Thu Jan 19 11:27:51 2017 <0002> gprs_ms.cpp:324 Detaching TBF from MS object, TLLI = 0xd4d4ca34, TBF = TBF(TFI=0 TLLI=0xd4d4ca34 DIR=UL STATE=FINISHED)
Thu Jan 19 11:27:51 2017 <0002> tbf.cpp:363 ********** TBF ends here **********
Thu Jan 19 11:27:53 2017 <0002> tbf.cpp:829 TBF(TFI=0 TLLI=0xd4d4ca34 DIR=DL STATE=ASSIGN) timer 0 expired.
Thu Jan 19 11:27:53 2017 <0002> tbf.cpp:372 ********** TBF update **********
Thu Jan 19 11:27:53 2017 <0002> bts.cpp:1701 PDCH(TS 7, TRX 0): Detaching TBF(TFI=0 TLLI=0xd4d4ca34 DIR=DL STATE=ASSIGN), 0 TBFs, USFs = 00, TFIs = 00000000.
Thu Jan 19 11:27:53 2017 <0002> bts.cpp:454 Searching for first unallocated TFI: TRX=0
Thu Jan 19 11:27:53 2017 <0002> bts.cpp:464 Found TFI=0.
Thu Jan 19 11:27:53 2017 <0002> gprs_rlcmac_ts_alloc.cpp:902 - Selected DL slots: (TS=0)".......D"(TS=7)
Thu Jan 19 11:27:53 2017 <0002> gprs_rlcmac_ts_alloc.cpp:970 Using 1 slots for DL
Thu Jan 19 11:27:53 2017 <0002> gprs_rlcmac_ts_alloc.cpp:1004 - Assigning DL TS 7
Thu Jan 19 11:27:53 2017 <0002> bts.cpp:1681 PDCH(TS 7, TRX 0): Attaching TBF(TFI=0 TLLI=0xd4d4ca34 DIR=DL STATE=ASSIGN), 1 TBFs, USFs = 00, TFIs = 00000001.
Thu Jan 19 11:27:53 2017 <0002> bts.cpp:736 Send dowlink assignment on PACCH, because TBF(TFI=0 TLLI=0xd4d4ca34 DIR=DL STATE=ASSIGN) exists
Thu Jan 19 11:27:53 2017 <0002> bts.cpp:294 TBF(TFI=0 TLLI=0xd4d4ca34 DIR=DL STATE=ASSIGN) changes state from ASSIGN to ASSIGN
Thu Jan 19 11:27:53 2017 <0002> tbf.cpp:422 TBF(TFI=0 TLLI=0xd4d4ca34 DIR=DL STATE=ASSIGN) starting timer 0.
Thu Jan 19 11:27:53 2017 <0002> tbf.cpp:985 New and old TBF are the same TBF(TFI=0 TLLI=0xd4d4ca34 DIR=DL STATE=ASSIGN)
Thu Jan 19 11:27:53 2017 <0002> tbf.cpp:1007 TBF(TFI=0 TLLI=0xd4d4ca34 DIR=DL STATE=ASSIGN) start Packet Downlink Assignment (PACCH)
Thu Jan 19 11:27:53 2017 <0002> tbf.cpp:1014 +++++++++++++++++++++++++ TX : Packet Downlink Assignment +++++++++++++++++++++++++
Thu Jan 19 11:27:53 2017 <0002> tbf.cpp:1017 ------------------------- TX : Packet Downlink Assignment -------------------------
Thu Jan 19 11:27:53 2017 <0002> tbf.cpp:487 TBF(TFI=0 TLLI=0xd4d4ca34 DIR=DL STATE=ASSIGN): Scheduling polling at FN 82636 TS 7
Thu Jan 19 11:27:53 2017 <0006> gprs_rlcmac_sched.cpp:181 Scheduling control message at RTS for TBF(TFI=0 TLLI=0xd4d4ca34 DIR=DL STATE=ASSIGN) (TRX=0, TS=7)
Thu Jan 19 11:27:53 2017 <0006> gprs_rlcmac_sched.cpp:329 Received RTS for PDCH: TRX=0 TS=7 FN=82632 block_nr=1 scheduling free USF for polling at FN=82636 of TBF(TFI=0 TLLI=0xd4d4ca34 DIR=DL STATE=ASSIGN)
Thu Jan 19 11:27:54 2017 <0002> tbf.cpp:498 TBF(TFI=0 TLLI=0xd4d4ca34 DIR=DL STATE=ASSIGN) poll timeout for FN=82636, TS=7 (curr FN 82697)
Thu Jan 19 11:27:54 2017 <0002> tbf.cpp:553 - Timeout for polling PACKET CONTROL ACK for PACKET DOWNLINK ASSIGNMENT.
Thu Jan 19 11:27:54 2017 <0002> tbf.cpp:914 - Assignment was on PACCH
Thu Jan 19 11:27:54 2017 <0002> tbf.cpp:922 - No downlink ACK received yet
Thu Jan 19 11:27:54 2017 <0002> tbf.cpp:985 New and old TBF are the same TBF(TFI=0 TLLI=0xd4d4ca34 DIR=DL STATE=ASSIGN)
Thu Jan 19 11:27:54 2017 <0002> tbf.cpp:1007 TBF(TFI=0 TLLI=0xd4d4ca34 DIR=DL STATE=ASSIGN) start Packet Downlink Assignment (PACCH)
Thu Jan 19 11:27:54 2017 <0002> tbf.cpp:1014 +++++++++++++++++++++++++ TX : Packet Downlink Assignment +++++++++++++++++++++++++
Thu Jan 19 11:27:54 2017 <0002> tbf.cpp:1017 ------------------------- TX : Packet Downlink Assignment -------------------------
Thu Jan 19 11:27:54 2017 <0002> tbf.cpp:487 TBF(TFI=0 TLLI=0xd4d4ca34 DIR=DL STATE=ASSIGN): Scheduling polling at FN 82710 TS 7
Thu Jan 19 11:27:54 2017 <0006> gprs_rlcmac_sched.cpp:181 Scheduling control message at RTS for TBF(TFI=0 TLLI=0xd4d4ca34 DIR=DL STATE=ASSIGN) (TRX=0, TS=7)
Thu Jan 19 11:27:54 2017 <0006> gprs_rlcmac_sched.cpp:329 Received RTS for PDCH: TRX=0 TS=7 FN=82706 block_nr=6 scheduling free USF for polling at FN=82710 of TBF(TFI=0 TLLI=0xd4d4ca34 DIR=DL STATE=ASSIGN)
Thu Jan 19 11:27:54 2017 <0002> tbf.cpp:498 TBF(TFI=0 TLLI=0xd4d4ca34 DIR=DL STATE=ASSIGN) poll timeout for FN=82710, TS=7 (curr FN 82771)
Thu Jan 19 11:27:54 2017 <0002> tbf.cpp:985 New and old TBF are the same TBF(TFI=0 TLLI=0xd4d4ca34 DIR=DL STATE=ASSIGN)
Thu Jan 19 11:27:54 2017 <0002> tbf.cpp:1007 TBF(TFI=0 TLLI=0xd4d4ca34 DIR=DL STATE=ASSIGN) start Packet Downlink Assignment (PACCH)
Thu Jan 19 11:27:54 2017 <0002> tbf.cpp:1014 +++++++++++++++++++++++++ TX : Packet Downlink Assignment +++++++++++++++++++++++++
Thu Jan 19 11:27:54 2017 <0002> tbf.cpp:1017 ------------------------- TX : Packet Downlink Assignment -------------------------
Thu Jan 19 11:27:54 2017 <0002> tbf.cpp:487 TBF(TFI=0 TLLI=0xd4d4ca34 DIR=DL STATE=ASSIGN): Scheduling polling at FN 82784 TS 7
Thu Jan 19 11:27:54 2017 <0006> gprs_rlcmac_sched.cpp:181 Scheduling control message at RTS for TBF(TFI=0 TLLI=0xd4d4ca34 DIR=DL STATE=ASSIGN) (TRX=0, TS=7)
Thu Jan 19 11:27:54 2017 <0006> gprs_rlcmac_sched.cpp:329 Received RTS for PDCH: TRX=0 TS=7 FN=82779 block_nr=11 scheduling free USF for polling at FN=82784 of TBF(TFI=0 TLLI=0xd4d4ca34 DIR=DL STATE=ASSIGN)
Thu Jan 19 11:27:54 2017 <0002> tbf.cpp:498 TBF(TFI=0 TLLI=0xd4d4ca34 DIR=DL STATE=ASSIGN) poll timeout for FN=82784, TS=7 (curr FN 82849)
Thu Jan 19 11:27:54 2017 <0002> tbf.cpp:985 New and old TBF are the same TBF(TFI=0 TLLI=0xd4d4ca34 DIR=DL STATE=ASSIGN)
Thu Jan 19 11:27:54 2017 <0002> tbf.cpp:1007 TBF(TFI=0 TLLI=0xd4d4ca34 DIR=DL STATE=ASSIGN) start Packet Downlink Assignment (PACCH)
Thu Jan 19 11:27:54 2017 <0002> tbf.cpp:1014 +++++++++++++++++++++++++ TX : Packet Downlink Assignment +++++++++++++++++++++++++
Thu Jan 19 11:27:54 2017 <0002> tbf.cpp:1017 ------------------------- TX : Packet Downlink Assignment -------------------------
Thu Jan 19 11:27:54 2017 <0002> tbf.cpp:487 TBF(TFI=0 TLLI=0xd4d4ca34 DIR=DL STATE=ASSIGN): Scheduling polling at FN 82862 TS 7
Thu Jan 19 11:27:54 2017 <0006> gprs_rlcmac_sched.cpp:181 Scheduling control message at RTS for TBF(TFI=0 TLLI=0xd4d4ca34 DIR=DL STATE=ASSIGN) (TRX=0, TS=7)
Thu Jan 19 11:27:54 2017 <0006> gprs_rlcmac_sched.cpp:329 Received RTS for PDCH: TRX=0 TS=7 FN=82857 block_nr=5 scheduling free USF for polling at FN=82862 of TBF(TFI=0 TLLI=0xd4d4ca34 DIR=DL STATE=ASSIGN)
Thu Jan 19 11:27:55 2017 <0002> tbf.cpp:498 TBF(TFI=0 TLLI=0xd4d4ca34 DIR=DL STATE=ASSIGN) poll timeout for FN=82862, TS=7 (curr FN 82927)
Thu Jan 19 11:27:55 2017 <0002> tbf.cpp:985 New and old TBF are the same TBF(TFI=0 TLLI=0xd4d4ca34 DIR=DL STATE=ASSIGN)
Thu Jan 19 11:27:55 2017 <0002> tbf.cpp:1007 TBF(TFI=0 TLLI=0xd4d4ca34 DIR=DL STATE=ASSIGN) start Packet Downlink Assignment (PACCH)
Thu Jan 19 11:27:55 2017 <0002> tbf.cpp:1014 +++++++++++++++++++++++++ TX : Packet Downlink Assignment +++++++++++++++++++++++++
Thu Jan 19 11:27:55 2017 <0002> tbf.cpp:1017 ------------------------- TX : Packet Downlink Assignment -------------------------
Thu Jan 19 11:27:55 2017 <0002> tbf.cpp:487 TBF(TFI=0 TLLI=0xd4d4ca34 DIR=DL STATE=ASSIGN): Scheduling polling at FN 82940 TS 7
Thu Jan 19 11:27:55 2017 <0006> gprs_rlcmac_sched.cpp:181 Scheduling control message at RTS for TBF(TFI=0 TLLI=0xd4d4ca34 DIR=DL STATE=ASSIGN) (TRX=0, TS=7)
Thu Jan 19 11:27:55 2017 <0006> gprs_rlcmac_sched.cpp:329 Received RTS for PDCH: TRX=0 TS=7 FN=82935 block_nr=11 scheduling free USF for polling at FN=82940 of TBF(TFI=0 TLLI=0xd4d4ca34 DIR=DL STATE=ASSIGN)
Thu Jan 19 11:27:55 2017 <0002> tbf.cpp:498 TBF(TFI=0 TLLI=0xd4d4ca34 DIR=DL STATE=ASSIGN) poll timeout for FN=82940, TS=7 (curr FN 83005)
Thu Jan 19 11:27:55 2017 <0002> tbf.cpp:985 New and old TBF are the same TBF(TFI=0 TLLI=0xd4d4ca34 DIR=DL STATE=ASSIGN)
Thu Jan 19 11:27:55 2017 <0002> tbf.cpp:1007 TBF(TFI=0 TLLI=0xd4d4ca34 DIR=DL STATE=ASSIGN) start Packet Downlink Assignment (PACCH)
Thu Jan 19 11:27:55 2017 <0002> tbf.cpp:1014 +++++++++++++++++++++++++ TX : Packet Downlink Assignment +++++++++++++++++++++++++
Thu Jan 19 11:27:55 2017 <0002> tbf.cpp:1017 ------------------------- TX : Packet Downlink Assignment -------------------------
Thu Jan 19 11:27:55 2017 <0002> tbf.cpp:487 TBF(TFI=0 TLLI=0xd4d4ca34 DIR=DL STATE=ASSIGN): Scheduling polling at FN 83018 TS 7
Thu Jan 19 11:27:55 2017 <0006> gprs_rlcmac_sched.cpp:181 Scheduling control message at RTS for TBF(TFI=0 TLLI=0xd4d4ca34 DIR=DL STATE=ASSIGN) (TRX=0, TS=7)
Thu Jan 19 11:27:55 2017 <0006> gprs_rlcmac_sched.cpp:329 Received RTS for PDCH: TRX=0 TS=7 FN=83013 block_nr=5 scheduling free USF for polling at FN=83018 of TBF(TFI=0 TLLI=0xd4d4ca34 DIR=DL STATE=ASSIGN)
Thu Jan 19 11:27:55 2017 <0002> tbf.cpp:829 TBF(TFI=0 TLLI=0xd4d4ca34 DIR=DL STATE=ASSIGN) timer 0 expired.
Thu Jan 19 11:27:55 2017 <0002> tbf.cpp:838 TBF(TFI=0 TLLI=0xd4d4ca34 DIR=DL STATE=ASSIGN) releasing due to PACCH assignment timeout.
Thu Jan 19 11:27:55 2017 <0002> tbf_dl.cpp:294 TBF(TFI=0 TLLI=0xd4d4ca34 DIR=DL STATE=ASSIGN) changes state from ASSIGN to RELEASING
Thu Jan 19 11:27:55 2017 <0002> tbf.cpp:342 TBF(TFI=0 TLLI=0xd4d4ca34 DIR=DL STATE=RELEASING) free
Thu Jan 19 11:27:55 2017 <0002> tbf.cpp:354 TBF(TFI=0 TLLI=0xd4d4ca34 DIR=DL STATE=RELEASING) Software error: Pending downlink assignment. This may not happen, because the assignment message never gets transmitted. Please be sure not to free in this state. PLEASE FIX!
Thu Jan 19 11:27:55 2017 <0002> bts.cpp:1701 PDCH(TS 7, TRX 0): Detaching TBF(TFI=0 TLLI=0xd4d4ca34 DIR=DL STATE=RELEASING), 0 TBFs, USFs = 00, TFIs = 00000000.
Thu Jan 19 11:27:55 2017 <0002> gprs_ms.cpp:324 Detaching TBF from MS object, TLLI = 0xd4d4ca34, TBF = TBF(TFI=0 TLLI=0xd4d4ca34 DIR=DL STATE=RELEASING)
Thu Jan 19 11:27:55 2017 <0002> tbf.cpp:363 ********** TBF ends here **********
</pre>
<p>With some experimentation we found out that after changing "gprs mode gprs" to "gprs mode egprs" in nitb.cfg the problem seems to dissappear, this leads to the assumption that it is a timing problem between osmo-bts and osmo-pcu.</p>
<p>The problem has been observerd with an OCTBTS/Octphy, see also traces, logs and configuration files in the attachment.</p>