Open Source Mobile Communications: Issueshttps://osmocom.org/https://osmocom.org/favicon.ico?16647414092024-01-24T09:43:35ZOpen Source Mobile Communications
Redmine pySim - Bug #6340 (New): exception when using osmo-smdpp with python 3.9https://osmocom.org/issues/63402024-01-24T09:43:35Zdexter
<p>There is an exception when starting osmo-smdpp with python 3.9. This exception does not occur with python 3.10.</p>
<pre>
owner@osmotest:~/git_master/pysim$ python3.9 ./osmo-smdpp.py
Traceback (most recent call last):
File "/home/owner/git_master/pysim/./osmo-smdpp.py", line 100, in <module>
class SmDppHttpServer:
File "/home/owner/git_master/pysim/./osmo-smdpp.py", line 196, in SmDppHttpServer
def initiateAutentication(self, request: IRequest, content: dict) -> dict:
TypeError: 'staticmethod' object is not callable
</pre>
<p>Commit hash: af87cd544f784e51a41cea303cb57001d9954d9c</p> pySim - Bug #6271 (Resolved): do not execute a startup script on initialization errorshttps://osmocom.org/issues/62712023-11-23T10:42:26Zdexter
<p>When there is an error at initialization (e.g. card is not present) and a startup script is passed with the command line option, then the script will execute anyway. This cause a lot of unnecessary error messages and confusion. pySim-shell should not continue executing a starup script when there were initialization errors!</p> OsmoBTS - Bug #6142 (Resolved): channels are opened, but nothing happens, sometimes strange DTAP ...https://osmocom.org/issues/61422023-08-23T14:41:41Zdexter
<p>This behavior was observed with osmo-bts-trx. A channel gets assigned, we see measurement reports and rarely some strange DTAP messages. The channel stays open for a while and then closes. (see attached trace)</p>
<p>When libosmocore change Id62c18f49f270449067b25b7104eb8b47f1955ec is reverted, then everything appears to be normal again.</p> 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> OsmoPCU - Feature #6044 (Resolved): Extend osmo-pcu and related TTCN3 tests so that PacketCellCha...https://osmocom.org/issues/60442023-05-25T10:18:53Zdexter
<p>At the moment we only test PacketCellChangeNotification (which triggers the RAN information request cascade) with 2G cells. Also osmo-pcu is currently only able to understand PacketCellChangeNotification requests that contain 2G cells as well.</p>
<p>In order to improve NACC/CCO support towards 3G and most importantly 4G we must extend the TTCN3 tests and osmo-pcu. On the TTCN3 testsuite this essentially means to complete the missing bits in the message records of RLCMAC_CSN1_Types.ttcn. Once that is done we can complete the testcases and use those to complete osmo-pcu. There we mainly have to take care that the 3G/4G target cell information is properly encapsulated in RIM messages. There may also be missing bits in the reverse path when the cell information is encapsulated in PacketNeighbourCellData messages and passed back to the MS/UE.</p> OsmoMSC - Bug #4214 (Resolved): Also accept messages with unknown TLV Information elementshttps://osmocom.org/issues/42142019-09-24T09:22:37Zdexter
<p>3GPP TS 29.118, chapter 7.5 states: "The receiving entity shall ignore all information elements unknown or unforeseen in a message." Unfortunately we currently send a STATUS message back and ignore the message. This is not as the standard specifies.</p> OsmoMSC - Bug #3959 (Resolved): Extranous SGsAP-PAGING-REQUEST after MT CSFB call (TC_sgsap_lu_an...https://osmocom.org/issues/39592019-04-25T11:47:59Zdexter
<p>There is an SGsAP-PAGING-REQUEST visible just after the CSFB call is complete. This behaviour seems not to be catched by the testsuite, but it looks problematic. Attached one finds a trace from TC_sgsap_lu_and_mt_call</p> OsmoBSC - Bug #3864 (Resolved): Do not execute S15-S0 related tests in ttcn3-bsc-test-sccplitehttps://osmocom.org/issues/38642019-03-26T16:48:58Zdexter
<p>The information element that contains S15-S0 is not present in sccplite, therefore it does not make sense to execute the related tests in ttcn3-bsc-test-sccplite. Those tests should be disabled here</p> OsmoBTS - Bug #3843 (Resolved): clean up sending of OML failure event reportshttps://osmocom.org/issues/38432019-03-15T12:41:11Zdexter
<p>When osmo-bts sends a failure event report to the BSC either a signal to SS_FAIL is dispatched or the function oml_fail_rep() is called. There should be only one way to send failure event reports. Dispatching a signal seems to complicated for the task.</p> OsmoBTS - Bug #3803 (Resolved): fix frame number calculation in scheduler_trxhttps://osmocom.org/issues/38032019-02-15T16:46:32Zdexter
<p>In rx_tchh_fn() and rx_tchh_fn() there is a formula used to calculate the frame number of the block that is passed up to the higher layers. The two functions collect a set of bursts and when complete, it is passed up. At the moment there are two indications generated when a block is completed. A measurement indication and a tch indication. Both should use the same fn. But the current implementation uses the stored *first_fn for the measurement indication and a formular that gets the fn of the last received block for the tch indication. Both seems to be incorrect because we need to take into account that TCH blocks are interleaved over 8 bursts. We need to tag each block with its starting frame number. To get this correct we need to check the formulas and make sure that the measurement indication and the tch indication use the same fn.</p> OsmoMGW - Bug #3673 (Resolved): chopped LCOhttps://osmocom.org/issues/36732018-10-26T12:20:47Zdexter
<p>(see trace) The codec name that that is transmitted in the LCO of the first CRCX is expected to re-appear in the SDP of the following 200 OK message. When inspecting the SDP of the following/second message, one can see that the last character of the codec name is missing. Since such a behavior can not observed when the codec was transmitted via SDP, the problem presumably is in the LCO parser.</p> OsmoBSC - Bug #3548 (Resolved): COMPLETE LAYER 3 INFORMATION does not contain Codec List (BSS Sup...https://osmocom.org/issues/35482018-09-12T09:13:01Zdexter
<p>3GPP TS 48.008 3.2.1.32, COMPLETE LAYER 3 INFORMATION clearly states that the information element Codec List (BSS Supported) must be included when AoIP is used. "Codec List (BSS Supported) shall be included, if the radio access network supports an IP based user plane interface."</p>
<p>The lack of the mentioned information element may cause interop problems with thrid party MSCs.</p> OsmoMGW - Bug #3443 (New): Check audio-payload options in osmo-mgw VTYhttps://osmocom.org/issues/34432018-08-02T14:14:54Zdexter
<p>The VTY in osmo-mgw has some strange audio-payload settings, which can set payload number, name, ptime. Normally those are parameters that are set via LCO and SDP by the call agent. Why do we need to set those information in the VTY? We need to check back if those options are still used in a meaningful way and what they are for. Maybe this is a leftover from the refactoring which requires fixing/removal.</p>
<p>Here are some examples:</p>
<p>sdp audio-payload number<br />sdp audio-payload name NAME<br />sdp audio-payload send-ptime",</p> pySim - Bug #3376 (Resolved): create test scripts to verify pysim-prog ans sysmo-usim-tool with j...https://osmocom.org/issues/33762018-07-04T09:01:19Zdexter
<p>At the moment pysim, nor sysmo-usim-tool does have integration tests on jenkins. Especially for pysim-prog.py this is a problem. pysim-prog.py supports various types of simcards now and its becoming hard to check every single one of them during development. We need a script that can automatically verify various card types.</p>
<p>The setup should consist of multiple physical cards and readers. The script then should execute a test write/read operation on each of the cards.</p>
<p>For sysmo-usim-tool the task is similar but with the exception that only one card type is checked and the script can be much simpler</p> OsmoGGSN (former OpenGGSN) - Bug #3319 (Resolved): also handle PCOs that contain primary and seco...https://osmocom.org/issues/33192018-06-04T20:25:53Zdexter
<p>On GTP level in the CREATE PDP CONTEXT message, one finds a field Protocol Configuration Options. This field contains among other info the primary and secondary DNS server address inside an IPCP container. Usually primary and secondary DNS are packed into on IPCP container. However it seems also to be legal to have primary and secondary DNS server in two separate IPCP container. At the moment the parser can only handle one IPCP container so we will loose the secondary DNS in the two-container case. We now have to extend the parser so that it handles IPCP containers flexible.</p>
<p>Attached one finds an example packet where primary and secondary DNS are in two separate IPCP containers.</p> OsmoMSC - Bug #3266 (Resolved): CM Service reject with wrong cause-codehttps://osmocom.org/issues/32662018-05-15T13:23:26Zdexter
<p>When the msc reboots all MS get implicitly detached. On the next CM SERVICE REQUEST the MS will get a CM SERVICE REJECT and by the cause code it knows that it has to perform a LOCATION UPDATE in order to get detached again. Unfortunately the cause code that the MSC returns with the CM SERVICE REJECT (GSM48_REJECT_MS_IDENTITY_NOT_DERVIVABLE = 9) is incorrect because this is a cause code from the GMM domain and is interpreted GSM48_REJECT_SRV_OPT_TMP_OUT_OF_ORDER by the MS, which also will not do any location update then.</p> OsmoBSC - Bug #3112 (Resolved): Clean up / fix osmo_bsc_filter.chttps://osmocom.org/issues/31122018-03-26T13:25:58Zdexter
<p>There are some leftovers from the time where osmo-bsc had an SCCPLITE/IPA based A interface. There is still an msc_con->is_connected and an msc_con->is_authenticated flag which is hard coded to 1. These flags are used by osmo_bsc_filter. Presumably the functionality in osmo_bsc_filter is presumably broken. We need to look into this and either fix it or remove it.</p>
<p>See also osmo_bsc_msc.c<br />data->msc_con->is_connected = 1;<br />data->msc_con->is_authenticated = 1;</p> OsmoMSC - Bug #3035 (Resolved): fix BSSMAP reset + add TTCN3 testcasehttps://osmocom.org/issues/30352018-03-06T09:08:22Zdexter
<p>There is a problem with the BSSMAP reset in osmo-msc. When osmo-msc receives BSSMAP data before reset it reaches a deadlock situation and the BSSMAP reset stops working properly. The problem has already been solved (see <a class="external" href="https://gerrit.osmocom.org/6840">https://gerrit.osmocom.org/6840</a>) but there is no TTCN3 test yet.</p> osmo-sip-connector - Feature #2950 (Resolved): create OE-Package for osmo-sip-connectorhttps://osmocom.org/issues/29502018-02-16T15:20:42Zdexter
<p>It appears to be that osmo-sip-connector is not built as OE package, so it is not available for easy install on sysmoBTS or sysmoNITB. However, having osmo-sip-connector available on those platform would make sense.</p>
<p>Dependencies:<br />SOFIASIP, sofia-sip-ua-glib >= 1.12.0</p> OsmoMSC - Bug #2777 (Resolved): Document that DTMF signalling does not work (with internal MNCC)https://osmocom.org/issues/27772017-12-21T19:11:17Zdexter
<p>The correct transmission of DTMF tones is currently not working. I have done a series of tests, here are the results:</p>
<ul>
<li>unsuccessful_ms_to_ms_dtmf_tone_(NG40).pcapng: Mobile to mobile DTMF tone signalling Start and stop of the DTMF tone is acknowledged. This looks good to my perspective, probably the DTMF forwarding is not properly configured inside the NG40 tester, otherwise I would expect to see the MSC at least trying to deliver the DTMF tones to the other mobile.</li>
</ul>
<ul>
<li>unsuccessful_ms_to_ms_dtmf_tone_with_external_mncc.pcapng: Here I can see the start command, which gets translated into a SIP message on the osmo-sip-connector. The tone also gets acknowledged and is stopped again. But again we see no response to the other MS whatsoever. This could also still be a problem with my PBX setup, since we would expect to see another SIP-Message that triggers the DTMF tone for the other MS.</li>
</ul>
<ul>
<li>unsuccessful_ms_to_ms_dtmf_tone_with_internal_mncc.pcapng: This trace was recorded with the internal MNCC active and really looks not ok. The DTMF tone gets actively rejected.</li>
</ul>
<ul>
<li>successful_ms_to_sip_dtmf_tone.pcapng: Here I see almost the same as in unsuccessful_ms_to_ms_dtmf_tone_with_external_mncc.pcapng, but the tone gets actually played on the other side. So I think sending DTMF tones should be fine, but receiving definetly has a problem.</li>
</ul>
<ul>
<li>When I press buttons on the sip phone actually nothing, not even a sip-message is transmitted. That also confirms that there may be problems with the PBX.</li>
</ul>
<p>However. I still wonder why the DTMF tones get rejected when osmo-msc is running on its internal MNCC. Something is definetly problematic there. The DTMF tone should travel back to the other end and not get rejected. I also attached the configuration files of osmo-bsc and osmo-msc. Maybe I am just lacking the right configuration options.</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> 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> OsmoSGSN - Bug #2577 (Resolved): Ensure meaningful default loglevels.https://osmocom.org/issues/25772017-10-17T09:52:24Zdexter
<p>There are some loglevels configured to LOGL_DEBUG by default in osmo-sgsn. Find meaningful defaults and also check the other products.</p>
<p>(We should also add a test that checks if some application registers odd log levels by default.)</p> OsmoMGW - Feature #2516 (Resolved): automatic testing of osmo-mgw / jenkins integrationhttps://osmocom.org/issues/25162017-09-18T21:45:01Zdexter
<p>Currently we test osmo-mgw with unit tests. It might make sense to run some more realistic tests. The idea is to start osmo-mgw in a testrig that then makes test connections and sends test data. The testrig could be a python program or even a TTCN3 test.</p>
Some ideas:
<ul>
<li>Send command (e.g. CRCX) and inspect resulting internal states via VTY also check response for plausibility</li>
<li>Send odd command sequences, check if the expected error codes are generated.</li>
<li>Send malformed messages or incomplete messages, check if the expected error codes are generated</li>
<li>Create a full connection, send RTP packets through, check if the RTP packets take the right path</li>
<li>Create a loopback connection, send RTP packets, check if the packets are reflected correctly</li>
</ul> 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 - 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 #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> OsmoMSC - Bug #2348 (Closed): AoIP: garbled RTP in call following a call to an unreachable subscr...https://osmocom.org/issues/23482017-07-03T20:14:14Zdexter
<p>There is a problem somewhere in the call control, probably also connected to MGCP. The problem succours very rarely, but it can be provoked by doing the following:</p>
<p>1) Make a call to an unreachable subscriber</p>
<p>2) Make a call to a reachable subscriber</p>
<p>The other phone will ring. When picked up on the calling phone playing a metallic noise sound (garbeled RTP traffic).</p>
<p>The problem needs to be investigated further. It might be a race condition between the connection that is still open from the failed call and the new established connection.</p>
<hr />
<p>In a_iface.c, see a_iface_tx_dtap(), the link_id is permanently set to 0x00. Looks like a candidate for the cause of the problem.</p> OsmoPCU - Bug #1957 (Closed): Fix calculation of absolute frame number from relative frame number...https://osmocom.org/issues/19572017-02-22T12:42:21Zdexter
<p>A RACH request that is forwarded to the PCU (usually) contains only a relative frame number. When a RACH request is processed by the BTS class, the absolute frame number is calculated from the relative framenumber. The current implementation lacks the handling of cornercases and race conditions.</p> 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>