Open Source Mobile Communications: Issues
https://osmocom.org/
https://osmocom.org/favicon.ico?1664741409
2024-02-13T00:34:55Z
Open Source Mobile Communications
Redmine
OsmoMSC - Bug #6358 (Closed): SMS from 4G fails - RP-DATA (MO) without DST or TPDU ?!?
https://osmocom.org/issues/6358
2024-02-13T00:34:55Z
keith
<p>WE currently cannot send SMS from a UE on 4G RAN</p>
<p>RP-DATA (MO) without DST or TPDU ?!?</p>
<pre>
20240213001943906 DLSMS DEBUG trans(SMS IMSI-334070000000968:MSISDN-68070122968:TMSI-0x1DCB852B:EUTRAN-SGs:CM_SERVICE_REQ callref-0x4000000c tid-8) RX_RP-DATA: src_len=0, dst_len=0 ud_len=15 (gsm_04_11.c:768)
20240213001943906 DLSMS ERROR trans(SMS IMSI-334070000000968:MSISDN-68070122968:TMSI-0x1DCB852B:EUTRAN-SGs:CM_SERVICE_REQ callref-0x4000000c tid-8) RP-DATA (MO) without DST or TPDU ?!? (gsm_04_11.c:775)
20240213001943906 DLSMS NOTICE trans(SMS IMSI-334070000000968:MSISDN-68070122968:TMSI-0x1DCB852B:EUTRAN-SGs:CM_SERVICE_REQ callref-0x4000000c tid-8) TX: SMS RP ERROR, cause 96 (Invalid Mandatory Information) (gsm_04_11.c:714)
</pre>
<p>Maybe this is due to a change in latest open5gs?</p>
OsmoPCU - Bug #6179 (Feedback): ASSERT in st_wait_release
https://osmocom.org/issues/6179
2023-09-14T19:25:37Z
keith
<p>osmo-pcu from the recent release:</p>
<p>Here's a backtrace (from sysmobts with osmo-pcu-dbg and libosmocore-dbg symbols installed)<br /><pre>
Assert failed 0 ../../git/src/tbf_dl_fsm.c:309
backtrace() returned 0 addresses
Program received signal SIGABRT, Aborted.
0x432dcf74 in raise () from /lib/libc.so.6
(gdb) bt
#0 0x432dcf74 in raise () from /lib/libc.so.6
#1 0x432de358 in abort () from /lib/libc.so.6
#2 0xb6eb38d4 in osmo_panic_default (args=..., fmt=0x0)
at /usr/src/debug/libosmocore/1.9.0+gitrAUTOINC+aca2c724ae-r2.18.0/git/src/core/panic.c:45
#3 osmo_panic (fmt=0x66fd4 "Assert failed %s %s:%d\n")
at /usr/src/debug/libosmocore/1.9.0+gitrAUTOINC+aca2c724ae-r2.18.0/git/src/core/panic.c:80
#4 0x00040f5c in st_wait_release (fi=<optimized out>, event=<optimized out>, data=<optimized out>)
at /usr/src/debug/osmo-pcu/1.3.0+gitAUTOINC+3ef173b980-r0.18/git/src/tbf_dl_fsm.c:309
#5 0xb6ea7824 in _osmo_fsm_inst_dispatch (fi=0x15e420, event=0, event@entry=3, data=data@entry=0x0, file=0x70098 "../../git/src/tbf.cpp",
line=line@entry=540) at /usr/src/debug/libosmocore/1.9.0+gitrAUTOINC+aca2c724ae-r2.18.0/git/src/core/fsm.c:875
#6 0x000356cc in gprs_rlcmac_tbf::poll_timeout (this=0x162920, pdch=0x154e64, poll_fn=223816, reason=<optimized out>)
at /usr/src/debug/osmo-pcu/1.3.0+gitAUTOINC+3ef173b980-r0.18/git/src/tbf.cpp:540
#7 0x0003585c in tbf_poll_timeout (tbf=<optimized out>, pdch=<optimized out>, poll_fn=<optimized out>, reason=<optimized out>)
at /usr/src/debug/osmo-pcu/1.3.0+gitAUTOINC+3ef173b980-r0.18/git/src/tbf.cpp:828
#8 0x0004cdf8 in pdch_ulc_expire_fn (ulc=0x1549d0, fn=223816, fn@entry=1395928)
at /usr/src/debug/osmo-pcu/1.3.0+gitAUTOINC+3ef173b980-r0.18/git/src/pdch_ul_controller.c:331
#9 0x00026a70 in pcu_rx_data_ind_pdtch (bts=bts@entry=0x154cd8, pdch=0x154e64, data=0x0, len=<optimized out>, fn=223816, meas=0xbefffb80,
meas@entry=0xbefffb78) at /usr/src/debug/osmo-pcu/1.3.0+gitAUTOINC+3ef173b980-r0.18/git/src/pcu_l1_if.cpp:396
#10 0x00015d70 in handle_ph_data_ind (fl1h=0x15de28, fl1h=0x15de28, l1p_msg=0x202ef8, data_ind=0x202fc0)
at /usr/src/debug/osmo-pcu/1.3.0+gitAUTOINC+3ef173b980-r0.18/git/src/osmo-bts-sysmo/sysmo_l1_if.c:220
</pre></p>
<p>It's always happening at line 540 in tbf.cpp:<br /><pre><code class="c syntaxhl"><span class="n">osmo_fsm_inst_dispatch</span><span class="p">(</span><span class="n">this</span><span class="o">-></span><span class="n">state_fi</span><span class="p">,</span> <span class="n">TBF_EV_MAX_N3105</span><span class="p">,</span> <span class="nb">NULL</span><span class="p">);</span>
</code></pre></p>
<p>Logs are messy, there's a lot going on.<br />Maybe attached log (at INFO) helps.</p>
OsmoPCU - Bug #6002 (Resolved): retention or rapid re-creation of ms entries.
https://osmocom.org/issues/6002
2023-04-14T19:02:56Z
keith
<p>I mailed (privately) <a class="user active" href="https://osmocom.org/users/30187">pespin</a> about this a couple of weeks ago.. because I saw a case where there were over 100,000 ms entries. It was in spanish so I won't repost here.</p>
<p><img src="https://osmocom.org/attachments/download/6801/clipboard-202304142058-4itci.png" alt="" /></p>
<p>Can't really add more now anyway, other than just point that the issue exists. Those stats are not latest release, but the 100,000 was with latest.</p>
<p>This is just the latest to be added:</p>
<pre>
MS TLLI=92f209e0, IMSI=
Timing advance (TA): 7
Coding scheme uplink: MCS-1
Coding scheme downlink: MCS-7
Mode: EGPRS
MS class: 12
EGPRS MS class: 12
PACCH: 5
LLC queue length: 4
LLC queue octets: 36
RSSI: -110 dBm
Bit error rate: 0 %
Link quality: 7 dB
Burst timing offset: 3/4 bit
MS C value: 7 dB
Downlink TBF: TFI=1, state=ASSIGN
Current DL Throughput: 0 Kbps
MS Statistics:
Amount of DL CTRL messages scheduled: 113 (0/s 0/m 0/h 113/d)
</pre>
OsmoPCU - Feature #5833 (New): A "meas-feed" for osmo-pcu
https://osmocom.org/issues/5833
2022-12-18T18:32:10Z
keith
<p>It might be interesting to observe real-time display of some parameters available from the PCU;<br />such as:</p>
<ul>
<li>RSSI </li>
<li>Link Quality</li>
<li>Coding Scheme</li>
<li>DL Throughput.</li>
</ul>
<p>This could be integrated into the "meas web" app<sup><a href="#fn1">1</a></sup>.</p>
<p>[1] <a class="external" href="https://gitlab.tic-ac.org/keith/meas_web">https://gitlab.tic-ac.org/keith/meas_web</a></p>
OsmoSGSN - Bug #5725 (Resolved): Assert failed mm->gb.mm_state_fsm->state != ST_MM_IDLE sgsn_libg...
https://osmocom.org/issues/5725
2022-10-24T19:16:44Z
keith
<p>Just happened to notice a coredump due to hitting this in sgsn_libgtp.c:771</p>
<pre><code class="c syntaxhl"><span class="n">OSMO_ASSERT</span><span class="p">(</span><span class="n">mm</span><span class="o">-></span><span class="n">gb</span><span class="p">.</span><span class="n">mm_state_fsm</span><span class="o">-></span><span class="n">state</span> <span class="o">!=</span> <span class="n">ST_MM_IDLE</span><span class="p">);</span>
</code></pre>
OsmoSGSN - Bug #5349 (In Progress): Message for non-existing SNDCP Entity
https://osmocom.org/issues/5349
2021-12-09T20:57:14Z
keith
<p>It seems pretty easy to get into a state where the TLLI in the MM context is not matching that in the SNDCP.</p>
<pre>
MM Context for IMSI 262423203000396, IMEI 013895003719350, P-TMSI ecc8a829
MSISDN: 57057157010, TLLI: ecc8a829 HLR:
GMM State: Registered.NORMAL, Routeing Area: 334-07-1101-21, Cell ID: 0
MM State: Standby, RAN Type: GPRS/EDGE via Gb
SGSN MM Context Statistics:
Signalling Messages ( In): 45 (0/s 0/m 45/h 0/d)
Signalling Messages (Out): 21 (0/s 0/m 21/h 0/d)
User Data Messages ( In): 369 (0/s 0/m 369/h 0/d)
User Data Messages (Out): 288 (0/s 0/m 288/h 0/d)
User Data Bytes ( In): 37388 (0/s 0/m 37388/h 0/d)
User Data Bytes (Out): 56465 (0/s 0/m 56465/h 0/d)
PDP Context Activations : 1 (0/s 0/m 1/h 0/d)
SUSPEND Count : 0 (0/s 0/m 0/h 0/d)
Paging Packet Switched : 2 (0/s 0/m 2/h 0/d)
Paging Circuit Switched : 0 (0/s 0/m 0/h 0/d)
Routing Area Update : 14 (0/s 0/m 14/h 0/d)
OsmoSGSN# show snd
OsmoSGSN# show sndcp
State of SNDCP Entities
TLLI c6ada2d6 SAPI=3 NSAPI=5:
Defrag: npdu=289 highest_seg=2 seg_have=0x00000007 tot_len=1233
TLLI e9d026da SAPI=3 NSAPI=5:
Defrag: npdu=339 highest_seg=1 seg_have=0x00000003 tot_len=793
</pre>
<p>resulting in:</p>
<pre>
20211209214900128 DSNDCP ERROR Message for non-existing SNDCP Entity (lle=0x55672ad42848, TLLI=ecc8a829, SAPI=3, NSAPI=5) (gprs_sndcp.c:812)
20211209214900148 DSNDCP ERROR Message for non-existing SNDCP Entity (lle=0x55672ad42848, TLLI=ecc8a829, SAPI=3, NSAPI=5) (gprs_sndcp.c:812)
20211209214900149 DSNDCP ERROR Message for non-existing SNDCP Entity (lle=0x55672ad42848, TLLI=ecc8a829, SAPI=3, NSAPI=5) (gprs_sndcp.c:812)
20211209214900170 DSNDCP ERROR Message for non-existing SNDCP Entity (lle=0x55672ad42848, TLLI=ecc8a829, SAPI=3, NSAPI=5) (gprs_sndcp.c:812)
20211209214900170 DSNDCP ERROR Message for non-existing SNDCP Entity (lle=0x55672ad42848, TLLI=ecc8a829, SAPI=3, NSAPI=5) (gprs_sndcp.c:812)
20211209214900188 DSNDCP ERROR Message for non-existing SNDCP Entity (lle=0x55672ad42848, TLLI=ecc8a829, SAPI=3, NSAPI=5) (gprs_sndcp.c:812)
20211209214900210 DSNDCP ERROR Message for non-existing SNDCP Entity (lle=0x55672ad42848, TLLI=ecc8a829, SAPI=3, NSAPI=5) (gprs_sndcp.c:812)
20211209214900210 DSNDCP ERROR Message for non-existing SNDCP Entity (lle=0x55672ad42848, TLLI=ecc8a829, SAPI=3, NSAPI=5) (gprs_sndcp.c:812)
20211209214900230 DSNDCP ERROR Message for non-existing SNDCP Entity (lle=0x55672ad42848, TLLI=ecc8a829, SAPI=3, NSAPI=5) (gprs_sndcp.c:812)
20211209214900231 DSNDCP ERROR Message for non-existing SNDCP Entity (lle=0x55672ad42848, TLLI=ecc8a829, SAPI=3, NSAPI=5) (gprs_sndcp.c:812)
20211209214900248 DSNDCP ERROR Message for non-existing SNDCP Entity (lle=0x55672ad42848, TLLI=ecc8a829, SAPI=3, NSAPI=5) (gprs_sndcp.c:812)
20211209214900248 DSNDCP ERROR Message for non-existing SNDCP Entity (lle=0x55672ad42848, TLLI=ecc8a829, SAPI=3, NSAPI=5) (gprs_sndcp.c:812)
20211209214900267 DSNDCP ERROR Message for non-existing SNDCP Entity (lle=0x55672ad42848, TLLI=ecc8a829, SAPI=3, NSAPI=5) (gprs_sndcp.c:812)
20211209214900267 DSNDCP ERROR Message for non-existing SNDCP Entity (lle=0x55672ad42848, TLLI=ecc8a829, SAPI=3, NSAPI=5) (gprs_sndcp.c:812)
</pre>
<p>My apologies - Over the last year or so I've suffered a memory leak for all the GRPS workings, I'll need to read up again to further debug this myself, but in the meantime, it should be reproducible if anyone wishes to take a look.</p>
<p><del>One way to trigger it seems to be cause a GPRS suspend by making a call</del> . In fact I can't reproduce this so easily. Something else is in the mix.</p>
<p>See the notes I erroneously posted on related issue <a class="issue tracker-1 status-3 priority-3 priority-high3 closed" title="Bug: vty comand "show sndcp" can cause SEGV in vty_dump_sne() (Resolved)" href="https://osmocom.org/issues/4824">#4824</a> , especially <a class="issue tracker-1 status-3 priority-3 priority-high3 closed" title="Bug: vty comand "show sndcp" can cause SEGV in vty_dump_sne() (Resolved)" href="https://osmocom.org/issues/4824#note-13">#4824-13</a></p>
<p>Marking high priority as I am observing this as a show stopper in production. <br />Thanks.</p>
OsmoPCU - Bug #5293 (Resolved): Assert failed pdch != NULL encoding.cpp:561
https://osmocom.org/issues/5293
2021-11-06T00:09:06Z
keith
<p>This one is happening repeatedly:</p>
<pre>
#0 0x425bcf74 in raise () from /lib/libc.so.6
#1 0x425be358 in abort () from /lib/libc.so.6
#2 0xb6eba0d8 in osmo_panic () from /usr/lib/libosmocore.so.17
#3 0x0004f51c in gen_freq_params(Frequency_Parameters_t*, gprs_rlcmac_tbf const*) ()
#4 0x0004f8d4 in write_packet_uplink_assignment ()
#5 0x0003a1a0 in create_packet_ul_assign ()
#6 0x0003a540 in st_send_ass ()
#7 0xb6eb0480 in _osmo_fsm_inst_dispatch () from /usr/lib/libosmocore.so.17
#8 0x0003a5e8 in tbf_ul_ass_create_rlcmac_msg ()
#9 0x0005c2a0 in sched_select_ctrl_msg(gprs_rlcmac_pdch*, unsigned int, unsigned char, tbf_sched_candidates*) ()
#10 0x0005d448 in gprs_rlcmac_rcv_rts_block(gprs_rlcmac_bts*, unsigned char, unsigned char, unsigned int, unsigned char) ()
#11 0x00023888 in pcu_rx_rts_req_pdtch ()
#12 0x00015e7c in l1if_handle_l1prim ()
#13 0xb6eabe10 in ?? () from /usr/lib/libosmocore.so.17
Backtrace stopped: previous frame identical to this frame (corrupt stack?)
</pre>
OsmoPCU - Bug #5265 (Resolved): SIGSEGV pdch_ulc_release_tbf (ulc=0x0, tbf=tbf@entry=0x1bac98)
https://osmocom.org/issues/5265
2021-10-14T14:22:52Z
keith
<p>Log leading up (not at level INFO, sorry. Will try to grab more next time we hit this one.)</p>
<pre>
<0002> ../../git/src/pdch_ul_controller.c:330 PDCH(bts=0,trx=0,ts=5) Timeout for registered POLL (FN=351069, reason=DL_ACK): TBF(TFI=4 TLLI=0xf8b95a7d DIR=DL STATE=FLOW EGPRS)
<0008> ../../git/src/tbf.cpp:550 TBF(TFI=4 TLLI=0xf8b95a7d DIR=DL STATE=FLOW EGPRS) poll timeout for FN=351069, TS=5 (curr FN 351069)
<0008> ../../git/src/tbf.cpp:628 TBF(TFI=4 TLLI=0xf8b95a7d DIR=DL STATE=FLOW EGPRS) Timeout for polling PACKET DOWNLINK ACK: |Assignment was on PACCH|Downlink ACK was received|
<0002> ../../git/src/pdch_ul_controller.c:330 PDCH(bts=0,trx=0,ts=5) Timeout for registered POLL (FN=351073, reason=DL_ACK): TBF(TFI=5 TLLI=0xd44ced11 DIR=DL STATE=FLOW EGPRS)
<0008> ../../git/src/tbf.cpp:550 TBF(TFI=5 TLLI=0xd44ced11 DIR=DL STATE=FLOW EGPRS) poll timeout for FN=351073, TS=5 (curr FN 351073)
<0008> ../../git/src/tbf.cpp:628 TBF(TFI=5 TLLI=0xd44ced11 DIR=DL STATE=FLOW EGPRS) Timeout for polling PACKET DOWNLINK ACK: |Assignment was on PACCH|Downlink ACK was received|
<0005> ../../git/src/pdch.cpp:1005 PDCH(bts=0,trx=0,ts=6) FN=351073 Rx UL DATA from unexpected TBF(TFI=0 TLLI=0x8e859ef4 DIR=UL STATE=ASSIGN EGPRS)
<0005> ../../git/src/pdch.cpp:990 PDCH(bts=0,trx=0,ts=5) FN=351078 Rx UL DATA from unexpected TBF(TFI=6 TLLI=0x955aadcf DIR=UL STATE=RELEASING EGPRS) vs expected TBF(TFI=1 TLLI=0xd44ced11
DIR=UL STATE=FLOW EGPRS)
<0002> ../../git/src/pdch_ul_controller.c:330 PDCH(bts=0,trx=0,ts=7) Timeout for registered POLL (FN=351078, reason=UL_ASS): TBF(TFI=0 TLLI=0x8e859ef4 DIR=UL STATE=ASSIGN EGPRS)
<0008> ../../git/src/tbf.cpp:550 TBF(TFI=0 TLLI=0x8e859ef4 DIR=UL STATE=ASSIGN EGPRS) poll timeout for FN=351078, TS=7 (curr FN 351078)
<0008> ../../git/src/tbf_ul_ass_fsm.c:224 TBF(TFI=0 TLLI=0x8e859ef4 DIR=UL STATE=ASSIGN EGPRS) Timeout for polling PACKET CONTROL ACK for PACKET UPLINK ASSIGNMENT: |Assignment was on PACCH
|Uplink data was received|
<0002> ../../git/src/pdch_ul_controller.c:330 PDCH(bts=0,trx=0,ts=7) Timeout for registered POLL (FN=351082, reason=UL_ASS): TBF(TFI=6 TLLI=0xf1566875 DIR=DL STATE=FLOW EGPRS)
<0008> ../../git/src/tbf.cpp:550 TBF(TFI=6 TLLI=0xf1566875 DIR=DL STATE=FLOW EGPRS) poll timeout for FN=351082, TS=7 (curr FN 351082)
<0008> ../../git/src/tbf_ul_ass_fsm.c:224 TBF(TFI=6 TLLI=0xf1566875 DIR=DL STATE=FLOW EGPRS) Timeout for polling PACKET CONTROL ACK for PACKET UPLINK ASSIGNMENT: |Assignment was on PACCH|D
ownlink ACK was received|
<0005> ../../git/src/pdch.cpp:1005 PDCH(bts=0,trx=0,ts=6) FN=351086 Rx UL DATA from unexpected TBF(TFI=9 TLLI=0xd323cdc1 DIR=UL STATE=RELEASING EGPRS)
<0002> ../../git/src/pdch_ul_controller.c:330 PDCH(bts=0,trx=0,ts=5) Timeout for registered POLL (FN=351095, reason=DL_ACK): TBF(TFI=4 TLLI=0xf8b95a7d DIR=DL STATE=FLOW EGPRS)
<0008> ../../git/src/tbf.cpp:550 TBF(TFI=4 TLLI=0xf8b95a7d DIR=DL STATE=FLOW EGPRS) poll timeout for FN=351095, TS=5 (curr FN 351095)
<0008> ../../git/src/tbf.cpp:628 TBF(TFI=4 TLLI=0xf8b95a7d DIR=DL STATE=FLOW EGPRS) Timeout for polling PACKET DOWNLINK ACK: |Assignment was on PACCH|Downlink ACK was received|
<0005> ../../git/src/pdch.cpp:995 PDCH(bts=0,trx=0,ts=6) FN=351095 Rx UL DATA from unexpected TBF(TFI=0 TLLI=0x8e859ef4 DIR=UL STATE=ASSIGN EGPRS) vs expected POLL TBF(TFI=7 TLLI=0xfe4e478
f DIR=DL STATE=FLOW EGPRS)
<0002> ../../git/src/pdch_ul_controller.c:330 PDCH(bts=0,trx=0,ts=6) Timeout for registered POLL (FN=351095, reason=DL_ACK): TBF(TFI=7 TLLI=0xfe4e478f DIR=DL STATE=FLOW EGPRS)
<0008> ../../git/src/tbf.cpp:550 TBF(TFI=7 TLLI=0xfe4e478f DIR=DL STATE=FLOW EGPRS) poll timeout for FN=351095, TS=6 (curr FN 351095)
<0008> ../../git/src/tbf.cpp:628 TBF(TFI=7 TLLI=0xfe4e478f DIR=DL STATE=FLOW EGPRS) Timeout for polling PACKET DOWNLINK ACK: |Assignment was on PACCH|No downlink ACK received yet|
</pre>
<pre>
#0 0xb6ebd674 in rb_first () from /usr/lib/libosmocore.so.17
#1 0x0003d418 in pdch_ulc_release_tbf (ulc=0x0, tbf=tbf@entry=0x1bac98)
at /usr/src/debug/osmo-pcu/0.9.0+gitAUTOINC+b9fede74ef-r0.18/git/src/pdch_ul_controller.c:273
#2 0x00039bf8 in gprs_rlcmac_pdch::detach_tbf (this=0x1380b4, tbf=tbf@entry=0x1bac98)
at /usr/src/debug/osmo-pcu/0.9.0+gitAUTOINC+b9fede74ef-r0.18/git/src/pdch.cpp:1148
#3 0x0002b7d4 in tbf_unlink_pdch (tbf=tbf@entry=0x1bac98)
at /usr/src/debug/osmo-pcu/0.9.0+gitAUTOINC+b9fede74ef-r0.18/git/src/tbf.cpp:260
#4 0x0002ba50 in tbf_free (tbf=0x1bac98)
at /usr/src/debug/osmo-pcu/0.9.0+gitAUTOINC+b9fede74ef-r0.18/git/src/tbf.cpp:293
#5 0x00020ab4 in pcu_rx_susp_req (susp_req=0xbefff3b4, bts=0x137b20)
at /usr/src/debug/osmo-pcu/0.9.0+gitAUTOINC+b9fede74ef-r0.18/git/src/pcu_l1_if.cpp:974
#6 pcu_rx (pcu_prim=pcu_prim@entry=0xbefff3b0, pcu_prim_length=pcu_prim_length@entry=1006)
at /usr/src/debug/osmo-pcu/0.9.0+gitAUTOINC+b9fede74ef-r0.18/git/src/pcu_l1_if.cpp:1135
#7 0x00044584 in pcu_sock_read (bfd=<optimized out>)
at /usr/src/debug/osmo-pcu/0.9.0+gitAUTOINC+b9fede74ef-r0.18/git/src/osmobts_sock.c:156
#8 0x0004476c in pcu_sock_cb (bfd=0x8ddfc <pcu_sock_state>, flags=1)
at /usr/src/debug/osmo-pcu/0.9.0+gitAUTOINC+b9fede74ef-r0.18/git/src/osmobts_sock.c:211
#9 0xb6eadddc in ?? () from /usr/lib/libosmocore.so.17
Backtrace stopped: previous frame identical to this frame (corrupt stack?)
</pre>
OsmoPCU - Bug #5264 (Resolved): ASSERT in encoding.cpp:561
https://osmocom.org/issues/5264
2021-10-14T13:29:12Z
keith
<pre>
Assert failed pdch != NULL ../../git/src/encoding.cpp:561
</pre>
<p>Last (level ERROR) log line was:<br /><pre>
DRLCMAC ERROR <0002> ../../git/src/pdch_ul_controller.c:159 PDCH(bts=0,trx=0,ts=7) FN=396881 Failed allocating POLL, all RRBP values are already reserved!
</pre></p>
<p><strong>OsmoPCU 0.9.0.212-b9fe</strong></p>
<p>BTS is 1.3.0 (release)<br />BSC, SGSN also are -latest (release)</p>
<p>Currently waiting for reproduction of this to add more info.</p>
OsmoPCU - Bug #5226 (Closed): ulc NULL in pdch_ulc_release_tbf()
https://osmocom.org/issues/5226
2021-09-02T21:36:22Z
keith
<pre>
(gdb) bt
#0 0xb6ebe3f8 in rb_first () from /usr/lib/libosmocore.so.17
#1 0x0003c394 in pdch_ulc_release_tbf (ulc=0x0, tbf=tbf@entry=0x187208) at /usr/src/debug/osmo-pcu/0.9.0+gitAUTOINC+bf7bde1cbb-r0.18/git/src/pdch_ul_controller.c:273
#2 0x00038eec in gprs_rlcmac_pdch::detach_tbf (this=0x137a34, tbf=tbf@entry=0x187208) at /usr/src/debug/osmo-pcu/0.9.0+gitAUTOINC+bf7bde1cbb-r0.18/git/src/pdch.cpp:1074
#3 0x0002b1c4 in tbf_unlink_pdch (tbf=0x187208) at /usr/src/debug/osmo-pcu/0.9.0+gitAUTOINC+bf7bde1cbb-r0.18/git/src/tbf.cpp:247
#4 tbf_free (tbf=0x187208) at /usr/src/debug/osmo-pcu/0.9.0+gitAUTOINC+bf7bde1cbb-r0.18/git/src/tbf.cpp:280
#5 0x0002c130 in tbf_fsm_timer_cb (fi=<optimized out>) at /usr/src/debug/osmo-pcu/0.9.0+gitAUTOINC+bf7bde1cbb-r0.18/git/src/tbf_fsm.c:368
#6 0xb6eb4090 in ?? () from /usr/lib/libosmocore.so.17
</pre>
OsmoPCU - Bug #5222 (Resolved): SIGSEGV on call establishment
https://osmocom.org/issues/5222
2021-08-30T17:51:14Z
keith
<p>segfault in pdch_ulc_get_node()</p>
<p>ulc is NULL:</p>
<pre>
Program received signal SIGSEGV, Segmentation fault.
pdch_ulc_get_node (ulc=0x0, fn=fn@entry=55453) at /usr/src/debug/osmo-pcu/0.9.0+gitAUTOINC+c4fe1f97b4-r0.18/git/src/pdch_ul_controller.c:78
</pre>
<p>Currently looking at an optimised binary running on the sysmoBTS;</p>
<p>Up the stack in handle_ph_data_ind() osmo-bts-sysmo/sysmo_l1_if.c:196</p>
<pre>
(gdb) p bts->trx[0].pdch[0]->ulc
$41 = (struct pdch_ulc *) 0x0
(gdb) p bts->trx[0].pdch[1]->ulc
$42 = (struct pdch_ulc *) 0x0
(gdb) p bts->trx[0].pdch[2]->ulc
$43 = (struct pdch_ulc *) 0x0
(gdb) p bts->trx[0].pdch[3]->ulc
$44 = (struct pdch_ulc *) 0x0
(gdb) p bts->trx[0].pdch[4]->ulc
$45 = (struct pdch_ulc *) 0x0
(gdb) p bts->trx[0].pdch[5]->ulc
$46 = (struct pdch_ulc *) 0x140a40
(gdb) p bts->trx[0].pdch[6]->ulc
$47 = (struct pdch_ulc *) 0x1418f0
(gdb) p bts->trx[0].pdch[7]->ulc
$48 = (struct pdch_ulc *) 0x1427a0
</pre>
<p>osmo-bsc Timeslot Config:</p>
<pre>
timeslot 0
phys_chan_config CCCH
hopping enabled 0
timeslot 1
phys_chan_config SDCCH8
hopping enabled 0
timeslot 2
phys_chan_config TCH/H
hopping enabled 0
timeslot 3
phys_chan_config TCH/H
hopping enabled 0
timeslot 4
phys_chan_config TCH/F_TCH/H_PDCH
hopping enabled 0
timeslot 5
phys_chan_config TCH/F_TCH/H_PDCH
hopping enabled 0
timeslot 6
phys_chan_config TCH/F_TCH/H_PDCH
hopping enabled 0
timeslot 7
phys_chan_config PDCH
hopping enabled 0
</pre>
<p>I changed timeslot 4 to a TCH/H and then the crash happens again in the same place, only now, ulc for timeslot 5 is NULL!<br /><pre>
(gdb) p bts->trx[0].pdch[5]->ulc
$63 = (struct pdch_ulc *) 0x0
(gdb) p bts->trx[0].pdch[6]->ulc
$64 = (struct pdch_ulc *) 0x140a40
</pre></p>
<p>to be clear:</p>
<pre>
#2 0x0001589c in handle_ph_data_ind (fl1h=0x13f430, fl1h=0x13f430, l1p_msg=0x13f620, data_ind=0x13f6e8)
at /usr/src/debug/osmo-pcu/0.9.0+gitAUTOINC+c4fe1f97b4-r0.18/git/src/osmo-bts-sysmo/sysmo_l1_if.c:196
196 in /usr/src/debug/osmo-pcu/0.9.0+gitAUTOINC+c4fe1f97b4-r0.18/git/src/osmo-bts-sysmo/sysmo_l1_if.c
(gdb) p data_ind->u8Tn
$68 = 5 '\005'
</pre>
OsmoSTP - Bug #5186 (Resolved): local-ip config parameter can cause unclear behaviour on dual IP ...
https://osmocom.org/issues/5186
2021-06-18T20:44:28Z
keith
<p><em>keyphrase from osmo-bsc log for search engines:</em></p>
<pre>
DLSS7 ERROR m3ua.c:507 XUA_AS(as-clnt-A-0-m3ua) {AS_DOWN}: Event AS-TRANSFER.req not permitted
</pre>
<p>In osmo-stp.cfg we have typically have something like:</p>
<pre>
cs7 instance 0
xua rkm routing-key-allocation dynamic-permitted
route-table system
listen m3ua 2905
local-ip ::
accept-asp-connections dynamic-permitted
</pre>
<p>This is actually fine.</p>
<p>But, the configuration VTY tells us:</p>
<pre>
OsmoSTP(config-cs7-listen)# local-ip
A.B.C.D IPv4 Address to use for XUA
X:X::X:X IPv6 Address to use for XUA
</pre>
<p>and so the user might think, ah OK I want to use 127.0.0.1 resulting in a config of</p>
<pre>
cs7 instance 0
xua rkm routing-key-allocation dynamic-permitted
route-table system
listen m3ua 2905
local-ip 127.0.0.1
accept-asp-connections dynamic-permitted
</pre>
<p>Actually local-ip 0.0.0.0 will also trigger this issue.</p>
<p>Now let's start osmo-bsc and osmo-msc with the minimal configuration files needed to start up, leaving the rest to default values for the sake of clarify here, although this issue can be observed with a fully configured BSC/MSC:</p>
<p><strong>osmo-bsc.cfg:</strong><br /><pre>
msc 0
mgw remote-ip 127.0.0.1
</pre></p>
<p><strong>osmo-msc.cfg:</strong><br />BLANK - Use all defaults.</p>
<p>osmo-bsc will constantly log: Event AS-TRANSFER.req not permitted</p>
<p>although osmo-bsc vty will show:</p>
<pre>
OsmoBSC# show msc
0 m3ua RI=SSN_PC,PC=0.23.3,SSN=BSSAP RI=SSN_PC,PC=0.23.1,SSN=BSSAP
</pre>
<p>osmo-msc vty will show:<br /><pre>
OsmoMSC# show bsc
OsmoMSC#
</pre></p>
<p>So one should <strong>NOT</strong> use an ipv4 address in local-ip, <strong>UNLESS</strong> ipv6 stack is disabled with:</p>
<pre>
sysctl net.ipv6.conf.all.disable_ipv6=1
</pre>
<p>If you have OSMO-STP config with an IPv4 address in local-ip, as soon as you disable the ipv6 stack, you'll see:<br /><pre>
[other log messages leading up to...]
DMSC NOTICE (msc0) BSSMAP assocation is up
</pre></p>
<p>To confirm:</p>
<p>with <strong>local-ip ::</strong></p>
<p>there's no problem with ipv4/ipv6 being enabled or not.</p>
OsmoPCU - Bug #5125 (Rejected): segfault in pdch_ul_controller.c:pdch_ulc_get_node()
https://osmocom.org/issues/5125
2021-04-20T21:25:46Z
keith
<pre>
Program received signal SIGSEGV, Segmentation fault.
pdch_ulc_get_node (ulc=<optimized out>, fn=fn@entry=95849) at /usr/src/debug/osmo-pcu/0.9.0+gitAUTOINC+16e1678bfc-r0.18/git/src/pdch_ul_controller.c:75
</pre>
<p>[Binary from nightly today Tue 20th April.]</p>
<p>osmo-pcu is most of the time crashing within a few seconds of start up</p>
<p>Attached is a capture of startup and debugging session. due to getting <opimized out> in gdb I went back up the trace to look for relevant data.</p>
<p>I think this might be relevant?:</p>
<pre>
(gdb) p *bts->trx[0].pdch[5]->ulc
$12 = {pdch = 0x2b2b2b2b, last_fn = 724249387, tree_root = {rb_node = 0x2b2b2b2b}, pool_ctx = 0x2b2b2b2b}
</pre>
OsmoPCU - Bug #4973 (Resolved): NULL m_dl_egprs_ctrs passed to rate_ctr_add()
https://osmocom.org/issues/4973
2021-01-25T00:01:15Z
keith
<pre>
(gdb) bt
#0 0xb6eddda0 in rate_ctr_add () from /usr/lib/libosmocore.so.16
#1 0x0002f274 in gprs_rlcmac_dl_tbf::create_dl_acked_block (this=this@entry=0x5da078, fn=338684, fn@entry=124215, ts=ts@entry=7 '\a', index=0, index@entry=79, index2=-1)
at /usr/src/debug/osmo-pcu/0.8.0+gitAUTOINC+a100a6bc56-r0.18/git/src/tbf_dl.cpp:837
#2 0x0002f574 in gprs_rlcmac_dl_tbf::create_dl_acked_block (this=this@entry=0x5da078, fn=124215, fn@entry=1167128, ts=ts@entry=7 '\a', req_mcs_kind=EGPRS,
req_mcs_kind@entry=(unknown: 1169532)) at /usr/src/debug/osmo-pcu/0.8.0+gitAUTOINC+a100a6bc56-r0.18/git/src/tbf_dl.cpp:599
#3 0x0003ea5c in sched_select_downlink (bts=0x426d3628, block_nr=55 '7', is_egprs=<synthetic pointer>, req_mcs_kind=(unknown: 1169532), pdch=0x11d87c, fn=1167128,
ts=7 '\a', trx=<optimized out>) at /usr/src/debug/osmo-pcu/0.8.0+gitAUTOINC+a100a6bc56-r0.18/git/src/gprs_rlcmac_sched.cpp:343
#4 gprs_rlcmac_rcv_rts_block (bts=0x426d3628, trx=<optimized out>, ts=<optimized out>, fn=1167128, block_nr=9 '\t')
at /usr/src/debug/osmo-pcu/0.8.0+gitAUTOINC+a100a6bc56-r0.18/git/src/gprs_rlcmac_sched.cpp:477
#5 0x0001e514 in pcu_rx_rts_req_pdtch (bts=<optimized out>, trx=<optimized out>, ts=<optimized out>, fn=<optimized out>, block_nr=9 '\t')
at /usr/src/debug/osmo-pcu/0.8.0+gitAUTOINC+a100a6bc56-r0.18/git/src/pcu_l1_if.cpp:384
#6 0x000151f4 in handle_ph_readytosend_ind (fl1h=0x11cc28, rts_ind=0x2ddc28)
at /usr/src/debug/osmo-pcu/0.8.0+gitAUTOINC+a100a6bc56-r0.18/git/src/osmo-bts-sysmo/sysmo_l1_if.c:148
#7 l1if_handle_l1prim (wq=<optimized out>, fl1h=0x11cc28, msg=0x2ddb60) at /usr/src/debug/osmo-pcu/0.8.0+gitAUTOINC+a100a6bc56-r0.18/git/src/osmo-bts-sysmo/sysmo_l1_if.c:288
#8 0xb6ed0c94 in ?? () from /usr/lib/libosmocore.so.16
</pre>
OsmoPCU - Bug #4955 (Closed): CSN1 Error observed: NEED_MORE BITS TO UNPACK (-5) at DL_DualCarrie...
https://osmocom.org/issues/4955
2021-01-18T07:30:43Z
keith
<p>Repeats 4 times. Also no newline at the end of this log line:</p>
<pre>
DCSN1 <0000> ../../git/src/csn1.c:1468 csnStreamDecoder: error NEED_MORE BITS TO UNPACK (-5) at DL_DualCarrierForDTM (idx 71)DCSN1 <0000> ../../git/src/csn1.c:1468 csnStreamDecoder: error NEED_MORE BITS TO UNPACK (-5) at DL_DualCarrierForDTM (idx 71)DCSN1 <0000> ../../git/src/csn1.c:1468 csnStreamDecoder: error NEED_MORE BITS TO UNPACK (-5) at DL_DualCarrierForDTM (idx 71)DCSN1 <0000> ../../git/src/csn1.c:1468 csnStreamDecoder: error NEED_MORE BITS TO UNPACK (-5) at DL_DualCarrierForDTM (idx 71)
</pre>
<p>Assigning to myself at least until I add a pcap.</p>
OsmoPCU - Bug #4856 (Feedback): PCU is running but has no NS connection and does not retry.
https://osmocom.org/issues/4856
2020-11-09T19:00:47Z
keith
<p>It has been noticed that at times osmo-bts, osmo-pcu are up and running on a sysmobts, GPRS is configured but there is no NS connection to the SGSN.</p>
<p>What I don't have about this:</p>
<ul>
<li>A method to reproduce.</li>
<li>logs leading up to failure.</li>
<li>I don't know if the NS was up and failed, or if it never came up on pcu startup.</li>
<li>osmo-bts and pcu are not current master, if fact there are some various versions installed.. (BSC is nitb)</li>
</ul>
<p>As I am writing this, I have one case of running osmo-pcu with no connection.</p>
<p>pcu is not logging ANYTHING. (logging level set-all debug) <br />version: OsmoPCU 0.8.0.152-b90d<br />show stats: all counters are zero.</p>
<p>ntib shows all of the "states" <strong>Oper 'Enabled', Admin 'Unlocked', Avail 'OK'</strong><br />as does the associated <del>pcu</del> osmo-bts</p>
<p>also, shows PCU connected:<br /><pre>
OpenBSC# show bts 2
BTS 2 is of sysmobts type in band GSM850, has CI 2 LAC 269, BSIC 63 (NCC=7, BCC=7) and 1 TRX
Description: (null)
PCU version 0.8.0.152-b90d connected
</pre></p>
<p>To possibly simplify a little: <br />It seems to be that the PCU is in a states where it "knows" that the NS is down<br /><pre>
OsmoPCU# show ns
Encapsulation NS-UDP-IP Local IP: 0.0.0.0, UDP Port: 0
</pre></p>
<p>yet it it not trying to bring it up.<br />Maybe the bts did not inform the PCU of the config?</p>
<p>show bts statistics: also all counters at ZERO.<br />all rate-counters are zero.</p>
<p>really looks like it was never initialised.</p>
<p>Maybe needless to say, but worth adding - systemctl restart osmo-pcu restores service.</p>
OsmoSGSN - Bug #4824 (Resolved): vty comand "show sndcp" can cause SEGV in vty_dump_sne()
https://osmocom.org/issues/4824
2020-10-21T15:11:06Z
keith
<pre>
(gdb) bt
#0 vty_dump_sne (vty=0x558339e52010, sne=0x558339e57360) at gprs_sndcp_vty.c:44
#1 0x000055833916afb7 in show_sndcp (self=0x55833939aac0 <show_sndcp_cmd>, vty=0x558339e52010, argc=0, argv=0x7ffcb165cf50) at gprs_sndcp_vty.c:60
</pre>
OsmoSGSN - Bug #4820 (Resolved): gsn_restart is created in CWD
https://osmocom.org/issues/4820
2020-10-19T15:46:28Z
keith
<p>Similar to osmo-msc issue <a class="issue tracker-1 status-5 priority-2 priority-default closed" title="Bug: sms.db is created in cwd, which from systemd's point of view is / (Closed)" href="https://osmocom.org/issues/4735">#4735</a>, cwd is / when run from systemd, so we get gsn_restart file created in the system root.</p>
OsmoSGSN - Bug #4817 (Closed): gtp_delete_context_req2() called with NULL pctx->ggsn
https://osmocom.org/issues/4817
2020-10-18T16:56:49Z
keith
<p>SGSN in production still seems to be crashing often. I enabled core dumps on one system and caught this Backtrace:</p>
<pre>
Program terminated with signal SIGSEGV, Segmentation fault.
#0 0x00005627bb8c9c7d in sgsn_delete_pdp_ctx (pctx=0x5627bdafacc0) at sgsn_libgtp.c:321
321 sgsn_libgtp.c: No such file or directory.
(gdb) bt
#0 0x00005627bb8c9c7d in sgsn_delete_pdp_ctx (pctx=0x5627bdafacc0) at sgsn_libgtp.c:321
#1 0x00005627bb8be8ff in gsm48_rx_gsm_deact_pdp_req (msg=0x0, mm=0x5627bdb5bb30) at gprs_sm.c:642
#2 gsm0408_rcv_gsm (mmctx=mmctx@entry=0x5627bdb5bb30, msg=msg@entry=0x5627bda33550, llme=llme@entry=0x5627bdb30c20) at gprs_sm.c:730
#3 0x00005627bb8b414e in gsm0408_gprs_rcvmsg_gb (msg=msg@entry=0x5627bda33550, llme=0x5627bdb30c20, drop_cipherable=drop_cipherable@entry=false) at gprs_gb.c:69
#4 0x00005627bb8cbe95 in gprs_llc_rcvmsg (msg=0x5627bda33550, tv=<optimized out>) at gprs_llc.c:1011
#5 0x00007f3b2ae8dc51 in bssgp_rcvmsg () from /lib/x86_64-linux-gnu/libosmogb.so.11
#6 0x00007f3b2ae87744 in ?? () from /lib/x86_64-linux-gnu/libosmogb.so.11
#7 0x00007f3b2ae8936a in gprs_ns_rcvmsg () from /lib/x86_64-linux-gnu/libosmogb.so.11
#8 0x00007f3b2ae894d9 in ?? () from /lib/x86_64-linux-gnu/libosmogb.so.11
#9 0x00007f3b2ae2f514 in ?? () from /lib/x86_64-linux-gnu/libosmocore.so.16
#10 0x00007f3b2ae2fc26 in osmo_select_main () from /lib/x86_64-linux-gnu/libosmocore.so.16
#11 0x00005627bb8b3d6a in main (argc=<optimized out>, argv=0x7fffba9dbbd8) at sgsn_main.c:556
</pre>
<pre>
(gdb) p *pctx
$1 = {list = {next = 0x5627bdb5bcc8, prev = 0x5627bdb5bcc8}, g_list = {next = 0x5627bda82940, prev = 0x5627bdb736f0}, mm = 0x5627bdb5bb30, destroy_ggsn = 0, ggsn = 0x0,
ggsn_list = {next = 0x100100, prev = 0x200200}, ctrg = 0x5627bd99ca50, lib = 0x0, state = PDP_STATE_CR_REQ, type = PDP_TYPE_NONE, address = 0, apn_subscribed = 0x0,
nsapi = 5, sapi = 11, ti = 0 '\000', vplmn_allowed = 0, qos_profile_subscr = 0, radio_prio = 0 '\000', timer = {node = {rb_parent_color = 94728684322873,
rb_right = 0x5627bd942938, rb_left = 0x5627bd95b0e0}, list = {next = 0x5627bdafad60, prev = 0x5627bdafad60}, timeout = {tv_sec = 1603034867, tv_usec = 862976},
active = 1, cb = 0x5627bb8bd0d0 <pdpctx_timer_cb>, data = 0x5627bdafacc0}, T = 3395, num_T_exp = 0, cdr_timer = {node = {rb_parent_color = 94728686758337,
rb_right = 0x0, rb_left = 0x0}, list = {next = 0x5627bdafadb8, prev = 0x5627bdafadb8}, timeout = {tv_sec = 1603035414, tv_usec = 613457}, active = 1,
cb = 0x5627bb8d00d0 <cdr_pdp_timeout>, data = 0x5627bdafacc0}, cdr_start = {tv_sec = 55141, tv_nsec = 130687750}, cdr_bytes_in = 12878, cdr_bytes_out = 17074,
cdr_charging_id = 99}
</pre>
<p><sup>^^</sup> <strong>ggsn = 0x0</strong></p>
<p>Sorry, no leading log available right now.</p>
OsmoPCU - Bug #4524 (Closed): Assert failed ws >= RLC_GPRS_SNS/2 src/rlc.cpp:255
https://osmocom.org/issues/4524
2020-05-02T02:51:59Z
keith
<p>PCU in <strong>EGRPS mode</strong> is crashing within 10 to 20 seconds on a BTS with many UE.</p>
<p>The log leading up to this generally looks like:</p>
<pre>
<0008> ../../git/src/tbf.cpp:996 Allocating UL TBF: MS_CLASS=12/12
<0008> ../../git/src/tbf.cpp:1012 TBF(TFI=0 TLLI=0x00000000 DIR=UL STATE=NULL EGPRS) Enabled EGPRS, mode EGPRS
<0002> ../../git/src/gprs_rlcmac_ts_alloc.cpp:749 No USF available
<0002> ../../git/src/gprs_rlcmac_ts_alloc.cpp:396 [UL] algo A <single> (suggested TRX: 0): failed to allocate a TS, no USF available
<000a> ../../git/src/tbf_ul.cpp:606 TBF(TFI=0 TLLI=0x00000000 DIR=UL STATE=NULL EGPRS) setting EGPRS UL window size to 0, base(64) slots(0) ws_pdch(0)
</pre>
<p>Assert failed ws >= RLC_GPRS_SNS/2 ../../git/src/rlc.cpp:255<br />backtrace() returned 0 addresses<br />Signal 6 received.</p>
OsmoSGSN - Bug #4506 (Closed): MediaTek MT6*** will not initiate Packet Access
https://osmocom.org/issues/4506
2020-04-20T04:01:39Z
keith
<p>I'm filing this under PCU but i'm not convinced it does not have to do with another component.</p>
<p>With recent improvements to all the PS components PS performance is great with most UE I have tested, however not so with these:</p>
<p><strong>htc Desire 628 dual sim</strong> (MT6753)</p>
<p><strong>htc Desire 626G dual sim</strong> (MT6592)</p>
<p>What happens in the attached pcaps is the following:</p>
<ul>
<li>htc exits airplane mode, does GPRS MM attach. </li>
<li>Activate mobile data, does PDP context activate, followed by some apps attempting data access, which is successful as long as the TBF from the PDP activate is still there.</li>
<li>Normally here we would see some IP traffic for 30 seconds or a minute or so as apps update themselves, but in this trial case, IP traffic is rejected and ICMP unreachable is sent back. (firewalled at the ggsn) </li>
<li>The TBF expires shortly after. </li>
<li>At this point, I try to ping the ggsn IP from a shell on the htc, I try access from apps, browser etc. Nothing happens. I'm monitoring the uplink RF which is totally quiet. There is no RF transmission from the phone whatsoever.</li>
<li>I ping the phone IP from the ggsn VM. We see paging, TBF establishment, once again, apps on the phone kick into gear. ping replies come back. I kill the ping. TBF expires. </li>
<li>Rinse and repeat....</li>
</ul>
<p>What else i've done:</p>
<ul>
<li>compared the MS Network caps and RA caps with those of the phones that work and looked up everything that stands out as distintive in the spec, but nothing would appear to have to do with this issue, certainly not in GPRS mode.</li>
</ul>
<ul>
<li>tested the desire 628 on a commercial network with EGPRS from a user perspective, appear to work fine.</li>
</ul>
<p>This is the only GPRS class 12 phone I have:</p>
<pre><code>GPRS multislot class: Max Rx-Slot/TDMA:4 Max Tx-Slot/TDMA:4 Max-Sum-Slot/TDMA:5 Tta:2 Ttb:1 Tra:2 Trb:1 Type:1 (12)</code></pre>
<p>UPDATE:</p>
<p>Debugging tools on the UE side show the following messages after DL TBF is released:</p>
<p>On requesting a DNS lookup and identifying the corresponding request from the upper layer in the trace, this is shortly followed by:</p>
<ul>
<li>MSG_ID_GRR_DATA_REQ <--- DNS request observed in payload</li>
<li>MSG_ID_MAC_RMPC_PKT_ACCESS_REQ</li>
<li>TBF: 0, Orig RES_REQ Status <RES_REQ_INVALID>, New REQ_RES Status <RES_REQ_RLC_IN_RACH_IDLE></li>
<li>rmpc call mac_fn_cell_status_hdlr: rel cause ACCESS_NOT_ALLOWED</li>
<li>ACS_DENY_ACS_REQ_FOR_RP_OR_CTRL_CLASS_NOT_ALLOW</li>
</ul>
<p>I went down a track originally of wondering if maybe the phone expects some kind of access class information (TS 144.060 7.1 ) but I didn't manage to figure out where I might experiment with PSI messages on PBCCH, if at all.</p>
<p>I programmed a SIM card [ACC] with access levels 0-7 on and also level 15, this had no affect.</p>
<p>In EGPRS mode there is something of note that happens quite often, which is that when there is no more IP traffic, the phone keeps sending a LLC block with no payload (that might not be the right terminology) This can go on for some time. (several hundred transmissions)<br /> In the next session I will grab pcaps in EGPRS mode.</p>
<p>The pcap does not contain all levels and categories of bts/pcu log and gsmtap. Please ask for other cats/levels if desired, I can repeat the procedure.</p>
OsmoSGSN - Bug #3964 (New): SIGSEGV in sndcp_sm_deactivate_ind()
https://osmocom.org/issues/3964
2019-04-29T08:41:30Z
keith
<pre>
(gdb) bt
#0 0x000055555556989c in sndcp_sm_deactivate_ind (lle=0x358, nsapi=5 '\005') at gprs_sndcp.c:507
#1 0x000055555556703c in sgsn_pdp_ctx_terminate (pdp=0x5555559a3d00) at gprs_sgsn.c:445
#2 0x0000555555566ac9 in sgsn_mm_ctx_cleanup_free (mm=0x55555591f5e0) at gprs_sgsn.c:337
#3 0x000055555555d658 in mm_ctx_cleanup_free (ctx=0x55555591f5e0, log_text=0x555555589416 "T3350") at gprs_gmm.c:326
#4 0x0000555555562d45 in mmctx_timer_cb (_mm=0x55555591f5e0) at gprs_gmm.c:2156
#5 0x00007ffff7308526 in osmo_timers_update () at timer.c:257
#6 0x00007ffff7308d9a in osmo_select_main (polling=0) at select.c:260
#7 0x0000555555572d21 in main (argc=1, argv=0x7fffffffe618) at sgsn_main.c:524
</pre>
<p>Log leading up to this:</p>
<pre>
DMM NOTICE <0002> gprs_gmm.c:2155 MM(334020160307203/f05ed185) T3350 expired >= 5 times
DMM INFO <0002> gprs_gmm.c:319 MM(334020160307203/f05ed185) Cleaning MM context due to T3350
DMM NOTICE <0002> gprs_sgsn.c:336 MM(334020160307203/f05ed185) Dropping PDP context for NSAPI=5
DGPRS INFO <000e> gprs_sgsn.c:441 PDP(334020160307203/0) Forcing release of PDP context
</pre>
<p>in sgsn_pdp_ctx_terminate<br /><pre>
(gdb) print pdp->mm->gb.llme
$7 = (struct gprs_llc_llme *) 0x0
</pre></p>
OsmoSGSN - Bug #3957 (Closed): ABORT from gprs_sndcp_comp_free()
https://osmocom.org/issues/3957
2019-04-24T12:23:57Z
keith
<pre>
(gdb) bt
#0 signal_handler (signal=6) at sgsn_main.c:144
#1 <signal handler called>
#2 0x00007ffff5402067 in __GI_raise (sig=sig@entry=6) at ../nptl/sysdeps/unix/sysv/linux/raise.c:56
#3 0x00007ffff5403448 in __GI_abort () at abort.c:89
#4 0x00007ffff59ae69c in ?? () from /usr/lib/x86_64-linux-gnu/libtalloc.so.2
#5 0x00007ffff59ada37 in _talloc_free () from /usr/lib/x86_64-linux-gnu/libtalloc.so.2
#6 0x0000555555567f9d in gprs_sndcp_comp_free (comp_entities=<optimized out>) at gprs_sndcp_comp.c:176
#7 0x0000555555573658 in llme_free (llme=0x555555a1b800) at gprs_llc.c:577
#8 gprs_llgmm_assign (llme=llme@entry=0x555555a1b800, old_tlli=old_tlli@entry=2708627144, new_tlli=new_tlli@entry=4294967295) at gprs_llc.c:1064
#9 0x0000555555565485 in sgsn_mm_ctx_cleanup_free (mm=0x0) at gprs_sgsn.c:365
#10 0x00007ffff7308526 in osmo_timers_update () from /usr/lib/x86_64-linux-gnu/libosmocore.so.12
#11 0x00007ffff7308d9a in osmo_select_main () from /usr/lib/x86_64-linux-gnu/libosmocore.so.12
#12 0x000055555555b9e7 in main (argc=1, argv=0x7fffffffe668) at sgsn_main.c:524
</pre>
<p>llme in llme_free()</p>
<pre>
$85 = {list = {next = 0x100100, prev = 0x200200}, state = GPRS_LLMS_UNASSIGNED,
tlli = 0, old_tlli = 0, algo = GPRS_ALGO_GEA0, kc = '\000' <repeats 15 times>,
cksn = 7 '\a', iov_ui = 3547929860, bvci = 4, nsei = 4, lle = {{list = {
next = 0x0, prev = 0x0}, sapi = 0, llme = 0x555555a1b800,
state = GPRS_LLES_UNASSIGNED, t200 = {node = {rb_parent_color = 0,
rb_right = 0x0, rb_left = 0x0}, list = {next = 0x0, prev = 0x0},
timeout = {tv_sec = 0, tv_usec = 0}, active = 0, cb = 0x0, data = 0x0},
t201 = {node = {rb_parent_color = 0, rb_right = 0x0, rb_left = 0x0}, list = {
next = 0x0, prev = 0x0}, timeout = {tv_sec = 0, tv_usec = 0},
active = 0, cb = 0x0, data = 0x0}, v_sent = 0, v_ack = 0, v_recv = 0,
vu_send = 0, vu_recv = 0, vu_recv_last = 0, vu_recv_duplicates = 0,
oc_i_send = 0, oc_i_recv = 0, oc_ui_send = 0, oc_ui_recv = 0,
retrans_ctr = 0, params = {iov_i_exp = 0, t200_201 = 0, n200 = 0,
n201_u = 0, n201_i = 0, mD = 0, mU = 0, kD = 0, kU = 0}}, {list = {
next = 0x0, prev = 0x0}, sapi = 1, llme = 0x555555a1b800,
state = GPRS_LLES_UNASSIGNED, t200 = {node = {rb_parent_color = 0,
rb_right = 0x0, rb_left = 0x0}, list = {next = 0x0, prev = 0x0},
timeout = {tv_sec = 0, tv_usec = 0}, active = 0, cb = 0x0, data = 0x0},
t201 = {node = {rb_parent_color = 0, rb_right = 0x0, rb_left = 0x0}, list = {
next = 0x0, prev = 0x0}, timeout = {tv_sec = 0, tv_usec = 0},
active = 0, cb = 0x0, data = 0x0}, v_sent = 0, v_ack = 0, v_recv = 0,
vu_send = 1, vu_recv = 0, vu_recv_last = 0, vu_recv_duplicates = 0,
oc_i_send = 0, oc_i_recv = 0, oc_ui_send = 0, oc_ui_recv = 0,
retrans_ctr = 0, params = {iov_i_exp = 0, t200_201 = 5, n200 = 3,
n201_u = 400, n201_i = 0, mD = 0, mU = 0, kD = 0, kU = 0}}, {list = {
next = 0x0, prev = 0x0}, sapi = 2, llme = 0x555555a1b800,
state = GPRS_LLES_UNASSIGNED, t200 = {node = {rb_parent_color = 0,
rb_right = 0x0, rb_left = 0x0}, list = {next = 0x0, prev = 0x0},
timeout = {tv_sec = 0, tv_usec = 0}, active = 0, cb = 0x0, data = 0x0},
t201 = {node = {rb_parent_color = 0, rb_right = 0x0, rb_left = 0x0}, list = {
next = 0x0, prev = 0x0}, timeout = {tv_sec = 0, tv_usec = 0},
active = 0, cb = 0x0, data = 0x0}, v_sent = 0, v_ack = 0, v_recv = 0,
vu_send = 0, vu_recv = 0, vu_recv_last = 0, vu_recv_duplicates = 0,
oc_i_send = 0, oc_i_recv = 0, oc_ui_send = 0, oc_ui_recv = 0,
retrans_ctr = 0, params = {iov_i_exp = 0, t200_201 = 5, n200 = 3,
n201_u = 270, n201_i = 0, mD = 0, mU = 0, kD = 0, kU = 0}}, {list = {
next = 0x0, prev = 0x0}, sapi = 3, llme = 0x555555a1b800,
state = GPRS_LLES_UNASSIGNED, t200 = {node = {rb_parent_color = 0,
rb_right = 0x0, rb_left = 0x0}, list = {next = 0x0, prev = 0x0},
timeout = {tv_sec = 0, tv_usec = 0}, active = 0, cb = 0x0, data = 0x0},
t201 = {node = {rb_parent_color = 0, rb_right = 0x0, rb_left = 0x0}, list = {
next = 0x0, prev = 0x0}, timeout = {tv_sec = 0, tv_usec = 0},
active = 0, cb = 0x0, data = 0x0}, v_sent = 0, v_ack = 0, v_recv = 0,
vu_send = 0, vu_recv = 0, vu_recv_last = 0, vu_recv_duplicates = 0,
oc_i_send = 0, oc_i_recv = 0, oc_ui_send = 0, oc_ui_recv = 0,
retrans_ctr = 0, params = {iov_i_exp = 27, t200_201 = 5, n200 = 3,
n201_u = 500, n201_i = 1503, mD = 1520, mU = 1520, kD = 16, kU = 16}}, {
list = {next = 0x0, prev = 0x0}, sapi = 4, llme = 0x555555a1b800,
state = GPRS_LLES_UNASSIGNED, t200 = {node = {rb_parent_color = 0,
rb_right = 0x0, rb_left = 0x0}, list = {next = 0x0, prev = 0x0},
timeout = {tv_sec = 0, tv_usec = 0}, active = 0, cb = 0x0, data = 0x0},
t201 = {node = {rb_parent_color = 0, rb_right = 0x0, rb_left = 0x0}, list = {
next = 0x0, prev = 0x0}, timeout = {tv_sec = 0, tv_usec = 0},
active = 0, cb = 0x0, data = 0x0}, v_sent = 0, v_ack = 0, v_recv = 0,
vu_send = 0, vu_recv = 0, vu_recv_last = 0, vu_recv_duplicates = 0,
oc_i_send = 0, oc_i_recv = 0, oc_ui_send = 0, oc_ui_recv = 0,
retrans_ctr = 0, params = {iov_i_exp = 0, t200_201 = 0, n200 = 0,
n201_u = 0, n201_i = 0, mD = 0, mU = 0, kD = 0, kU = 0}}, {list = {
next = 0x0, prev = 0x0}, sapi = 5, llme = 0x555555a1b800,
state = GPRS_LLES_UNASSIGNED, t200 = {node = {rb_parent_color = 0,
rb_right = 0x0, rb_left = 0x0}, list = {next = 0x0, prev = 0x0},
timeout = {tv_sec = 0, tv_usec = 0}, active = 0, cb = 0x0, data = 0x0},
t201 = {node = {rb_parent_color = 0, rb_right = 0x0, rb_left = 0x0}, list = {
next = 0x0, prev = 0x0}, timeout = {tv_sec = 0, tv_usec = 0},
active = 0, cb = 0x0, data = 0x0}, v_sent = 0, v_ack = 0, v_recv = 0,
vu_send = 0, vu_recv = 0, vu_recv_last = 0, vu_recv_duplicates = 0,
oc_i_send = 0, oc_i_recv = 0, oc_ui_send = 0, oc_ui_recv = 0,
retrans_ctr = 0, params = {iov_i_exp = 27, t200_201 = 10, n200 = 3,
n201_u = 500, n201_i = 1503, mD = 760, mU = 760, kD = 8, kU = 8}}, {
list = {next = 0x0, prev = 0x0}, sapi = 6, llme = 0x555555a1b800,
state = GPRS_LLES_UNASSIGNED, t200 = {node = {rb_parent_color = 0,
rb_right = 0x0, rb_left = 0x0}, list = {next = 0x0, prev = 0x0},
timeout = {tv_sec = 0, tv_usec = 0}, active = 0, cb = 0x0, data = 0x0},
t201 = {node = {rb_parent_color = 0, rb_right = 0x0, rb_left = 0x0}, list = {
next = 0x0, prev = 0x0}, timeout = {tv_sec = 0, tv_usec = 0},
active = 0, cb = 0x0, data = 0x0}, v_sent = 0, v_ack = 0, v_recv = 0,
vu_send = 0, vu_recv = 0, vu_recv_last = 0, vu_recv_duplicates = 0,
oc_i_send = 0, oc_i_recv = 0, oc_ui_send = 0, oc_ui_recv = 0,
retrans_ctr = 0, params = {iov_i_exp = 0, t200_201 = 0, n200 = 0,
n201_u = 0, n201_i = 0, mD = 0, mU = 0, kD = 0, kU = 0}}, {list = {
next = 0x0, prev = 0x0}, sapi = 7, llme = 0x555555a1b800,
state = GPRS_LLES_UNASSIGNED, t200 = {node = {rb_parent_color = 0,
rb_right = 0x0, rb_left = 0x0}, list = {next = 0x0, prev = 0x0},
timeout = {tv_sec = 0, tv_usec = 0}, active = 0, cb = 0x0, data = 0x0},
t201 = {node = {rb_parent_color = 0, rb_right = 0x0, rb_left = 0x0}, list = {
next = 0x0, prev = 0x0}, timeout = {tv_sec = 0, tv_usec = 0},
active = 0, cb = 0x0, data = 0x0}, v_sent = 0, v_ack = 0, v_recv = 0,
vu_send = 0, vu_recv = 0, vu_recv_last = 0, vu_recv_duplicates = 0,
oc_i_send = 0, oc_i_recv = 0, oc_ui_send = 0, oc_ui_recv = 0,
retrans_ctr = 0, params = {iov_i_exp = 0, t200_201 = 20, n200 = 3,
n201_u = 270, n201_i = 0, mD = 0, mU = 0, kD = 0, kU = 0}}, {list = {
next = 0x0, prev = 0x0}, sapi = 8, llme = 0x555555a1b800,
state = GPRS_LLES_UNASSIGNED, t200 = {node = {rb_parent_color = 0,
rb_right = 0x0, rb_left = 0x0}, list = {next = 0x0, prev = 0x0},
timeout = {tv_sec = 0, tv_usec = 0}, active = 0, cb = 0x0, data = 0x0},
t201 = {node = {rb_parent_color = 0, rb_right = 0x0, rb_left = 0x0}, list = {
next = 0x0, prev = 0x0}, timeout = {tv_sec = 0, tv_usec = 0},
active = 0, cb = 0x0, data = 0x0}, v_sent = 0, v_ack = 0, v_recv = 0,
vu_send = 0, vu_recv = 0, vu_recv_last = 0, vu_recv_duplicates = 0,
oc_i_send = 0, oc_i_recv = 0, oc_ui_send = 0, oc_ui_recv = 0,
retrans_ctr = 0, params = {iov_i_exp = 0, t200_201 = 20, n200 = 3,
n201_u = 270, n201_i = 0, mD = 0, mU = 0, kD = 0, kU = 0}}, {list = {
next = 0x0, prev = 0x0}, sapi = 9, llme = 0x555555a1b800,
state = GPRS_LLES_UNASSIGNED, t200 = {node = {rb_parent_color = 0,
rb_right = 0x0, rb_left = 0x0}, list = {next = 0x0, prev = 0x0},
timeout = {tv_sec = 0, tv_usec = 0}, active = 0, cb = 0x0, data = 0x0},
t201 = {node = {rb_parent_color = 0, rb_right = 0x0, rb_left = 0x0}, list = {
next = 0x0, prev = 0x0}, timeout = {tv_sec = 0, tv_usec = 0},
active = 0, cb = 0x0, data = 0x0}, v_sent = 0, v_ack = 0, v_recv = 0,
vu_send = 0, vu_recv = 0, vu_recv_last = 0, vu_recv_duplicates = 0,
oc_i_send = 0, oc_i_recv = 0, oc_ui_send = 0, oc_ui_recv = 0,
retrans_ctr = 0, params = {iov_i_exp = 27, t200_201 = 20, n200 = 3,
n201_u = 500, n201_i = 1503, mD = 380, mU = 380, kD = 4, kU = 4}}, {
list = {next = 0x0, prev = 0x0}, sapi = 10, llme = 0x555555a1b800,
state = GPRS_LLES_UNASSIGNED, t200 = {node = {rb_parent_color = 0,
rb_right = 0x0, rb_left = 0x0}, list = {next = 0x0, prev = 0x0},
timeout = {tv_sec = 0, tv_usec = 0}, active = 0, cb = 0x0, data = 0x0},
t201 = {node = {rb_parent_color = 0, rb_right = 0x0, rb_left = 0x0}, list = {
next = 0x0, prev = 0x0}, timeout = {tv_sec = 0, tv_usec = 0},
active = 0, cb = 0x0, data = 0x0}, v_sent = 0, v_ack = 0, v_recv = 0,
vu_send = 0, vu_recv = 0, vu_recv_last = 0, vu_recv_duplicates = 0,
oc_i_send = 0, oc_i_recv = 0, oc_ui_send = 0, oc_ui_recv = 0,
retrans_ctr = 0, params = {iov_i_exp = 0, t200_201 = 0, n200 = 0,
n201_u = 0, n201_i = 0, mD = 0, mU = 0, kD = 0, kU = 0}}, {list = {
next = 0x0, prev = 0x0}, sapi = 11, llme = 0x555555a1b800,
state = GPRS_LLES_UNASSIGNED, t200 = {node = {rb_parent_color = 0,
rb_right = 0x0, rb_left = 0x0}, list = {next = 0x0, prev = 0x0},
timeout = {tv_sec = 0, tv_usec = 0}, active = 0, cb = 0x0, data = 0x0},
t201 = {node = {rb_parent_color = 0, rb_right = 0x0, rb_left = 0x0}, list = {
next = 0x0, prev = 0x0}, timeout = {tv_sec = 0, tv_usec = 0},
active = 0, cb = 0x0, data = 0x0}, v_sent = 0, v_ack = 0, v_recv = 0,
vu_send = 0, vu_recv = 0, vu_recv_last = 0, vu_recv_duplicates = 0,
oc_i_send = 0, oc_i_recv = 0, oc_ui_send = 0, oc_ui_recv = 0,
retrans_ctr = 0, params = {iov_i_exp = 27, t200_201 = 40, n200 = 3,
n201_u = 500, n201_i = 1503, mD = 190, mU = 190, kD = 2, kU = 2}}, {
list = {next = 0x0, prev = 0x0}, sapi = 12, llme = 0x555555a1b800,
state = GPRS_LLES_UNASSIGNED, t200 = {node = {rb_parent_color = 0,
rb_right = 0x0, rb_left = 0x0}, list = {next = 0x0, prev = 0x0},
timeout = {tv_sec = 0, tv_usec = 0}, active = 0, cb = 0x0, data = 0x0},
t201 = {node = {rb_parent_color = 0, rb_right = 0x0, rb_left = 0x0}, list = {
next = 0x0, prev = 0x0}, timeout = {tv_sec = 0, tv_usec = 0},
active = 0, cb = 0x0, data = 0x0}, v_sent = 0, v_ack = 0, v_recv = 0,
vu_send = 0, vu_recv = 0, vu_recv_last = 0, vu_recv_duplicates = 0,
oc_i_send = 0, oc_i_recv = 0, oc_ui_send = 0, oc_ui_recv = 0,
retrans_ctr = 0, params = {iov_i_exp = 0, t200_201 = 0, n200 = 0,
n201_u = 0, n201_i = 0, mD = 0, mU = 0, kD = 0, kU = 0}}, {list = {
next = 0x0, prev = 0x0}, sapi = 13, llme = 0x555555a1b800,
state = GPRS_LLES_UNASSIGNED, t200 = {node = {rb_parent_color = 0,
rb_right = 0x0, rb_left = 0x0}, list = {next = 0x0, prev = 0x0},
timeout = {tv_sec = 0, tv_usec = 0}, active = 0, cb = 0x0, data = 0x0},
t201 = {node = {rb_parent_color = 0, rb_right = 0x0, rb_left = 0x0}, list = {
next = 0x0, prev = 0x0}, timeout = {tv_sec = 0, tv_usec = 0},
active = 0, cb = 0x0, data = 0x0}, v_sent = 0, v_ack = 0, v_recv = 0,
vu_send = 0, vu_recv = 0, vu_recv_last = 0, vu_recv_duplicates = 0,
oc_i_send = 0, oc_i_recv = 0, oc_ui_send = 0, oc_ui_recv = 0,
retrans_ctr = 0, params = {iov_i_exp = 0, t200_201 = 0, n200 = 0,
n201_u = 0, n201_i = 0, mD = 0, mU = 0, kD = 0, kU = 0}}, {list = {
next = 0x0, prev = 0x0}, sapi = 14, llme = 0x555555a1b800,
state = GPRS_LLES_UNASSIGNED, t200 = {node = {rb_parent_color = 0,
rb_right = 0x0, rb_left = 0x0}, list = {next = 0x0, prev = 0x0},
timeout = {tv_sec = 0, tv_usec = 0}, active = 0, cb = 0x0, data = 0x0},
t201 = {node = {rb_parent_color = 0, rb_right = 0x0, rb_left = 0x0}, list = {
next = 0x0, prev = 0x0}, timeout = {tv_sec = 0, tv_usec = 0},
active = 0, cb = 0x0, data = 0x0}, v_sent = 0, v_ack = 0, v_recv = 0,
vu_send = 0, vu_recv = 0, vu_recv_last = 0, vu_recv_duplicates = 0,
oc_i_send = 0, oc_i_recv = 0, oc_ui_send = 0, oc_ui_recv = 0,
retrans_ctr = 0, params = {iov_i_exp = 0, t200_201 = 0, n200 = 0,
n201_u = 0, n201_i = 0, mD = 0, mU = 0, kD = 0, kU = 0}}, {list = {
next = 0x0, prev = 0x0}, sapi = 15, llme = 0x555555a1b800,
state = GPRS_LLES_UNASSIGNED, t200 = {node = {rb_parent_color = 0,
rb_right = 0x0, rb_left = 0x0}, list = {next = 0x0, prev = 0x0},
timeout = {tv_sec = 0, tv_usec = 0}, active = 0, cb = 0x0, data = 0x0},
t201 = {node = {rb_parent_color = 0, rb_right = 0x0, rb_left = 0x0}, list = {
next = 0x0, prev = 0x0}, timeout = {tv_sec = 0, tv_usec = 0},
active = 0, cb = 0x0, data = 0x0}, v_sent = 0, v_ack = 0, v_recv = 0,
vu_send = 0, vu_recv = 0, vu_recv_last = 0, vu_recv_duplicates = 0,
oc_i_send = 0, oc_i_recv = 0, oc_ui_send = 0, oc_ui_recv = 0,
retrans_ctr = 0, params = {iov_i_exp = 0, t200_201 = 0, n200 = 0,
n201_u = 0, n201_i = 0, mD = 0, mU = 0, kD = 0, kU = 0}}},
xid = 0x555555c6d200, comp = {proto = 0x5555559b2e10, data = 0x5555559f9b90},
age_timestamp = 0}
</pre>
OsmoSGSN - Bug #3956 (Resolved): SIGSEGV in rate_ctr_group_free()
https://osmocom.org/issues/3956
2019-04-24T11:27:54Z
keith
<p>Limited context: all i got :(</p>
<pre>
<0023> gtp.c:2653 Packet from 192.168.100.2:2123, length: 14 content: 32 15 00 06 00 00 00 00 59 47 00 00 01 c0 : Unknown PDP context: 0 (expected if gtp_delete_context_
req is used)
<000e> sgsn_libgtp.c:627 libgtp EOF (type=20, pdp=(nil), cbp=0x555555cfeca0)
<0012> gprs_sndcp.c:514 SNSM-DEACTIVATE.ind for non-existing TLLI=f38f648c SAPI=3 NSAPI=6
Program received signal SIGSEGV, Segmentation fault.
</pre>
<p>backtrace:</p>
<pre>
#0 0x00007ffff7313531 in rate_ctr_group_free () from /usr/lib/x86_64-linux-gnu/libosmocore.so.12
#1 0x00005555555651ae in sgsn_pdp_ctx_free (pdp=pdp@entry=0x555555cfeca0) at gprs_sgsn.c:471
#2 0x0000555555570363 in delete_pdp_conf (pdp=0x0, cause=-1, cbp=0x555555cfeca0) at sgsn_libgtp.c:574
#3 cb_conf (type=20, cause=-1, pdp=0x0, cbp=0x555555cfeca0) at sgsn_libgtp.c:636
#4 0x00007ffff66a6401 in gtp_delete_pdp_conf () from /usr/lib/x86_64-linux-gnu/libgtp.so.4
#5 0x00007ffff66a921c in gtp_decaps1c () from /usr/lib/x86_64-linux-gnu/libgtp.so.4
#6 0x00007ffff7308dd4 in osmo_select_main () from /usr/lib/x86_64-linux-gnu/libosmocore.so.12
#7 0x000055555555b9e7 in main (argc=1, argv=0x7fffffffe668) at sgsn_main.c:524
</pre>
<p>pdp in sgsn_pdp_ctx_free():</p>
<pre>
(gdb) print *pdp
$6 = {list = {next = 0x100100, prev = 0x200200}, g_list = {next = 0x100100,
prev = 0x200200}, mm = 0x555555d1c7d0, destroy_ggsn = 0, ggsn = 0x0,
ggsn_list = {next = 0x100100, prev = 0x200200}, ctrg = 0x555555ce9ad0,
lib = 0x0, state = PDP_STATE_CR_REQ, type = PDP_TYPE_NONE, address = 0,
apn_subscribed = 0x0, nsapi = 6, sapi = 3, ti = 0 '\000', vplmn_allowed = 0,
qos_profile_subscr = 0, radio_prio = 0 '\000', timer = {node = {
rb_parent_color = 0, rb_right = 0x0, rb_left = 0x0}, list = {next = 0x0,
prev = 0x0}, timeout = {tv_sec = 0, tv_usec = 0}, active = 0, cb = 0x0,
data = 0x0}, T = 0, num_T_exp = 0, cdr_timer = {node = {
rb_parent_color = 93824998219265, rb_right = 0x0, rb_left = 0x0}, list = {
next = 0x555555cfed98, prev = 0x555555cfed98}, timeout = {
tv_sec = 1556101766, tv_usec = 498923}, active = 0,
cb = 0x555555577650 <cdr_pdp_timeout>, data = 0x555555cfeca0}, cdr_start = {
tv_sec = 55042, tv_nsec = 956618094}, cdr_bytes_in = 59, cdr_bytes_out = 318,
cdr_charging_id = 448}
</pre>
<p>pdp->ctrg:</p>
<pre>
desc = 0x555555790240 <pdpctx_ctrg_desc>, idx = 109, ctr = 0x555555ce9af0}
(gdb) print &pdp->ctrg->list
$51 = (struct llist_head *) 0x555555ce9ad0
(gdb) print *&pdp->ctrg->list
$52 = {next = 0x100100, prev = 0x200200}
(gdb)
I'm a bit lost in the llist things.
</pre>
OsmoSGSN - Bug #3952 (Resolved): MSGB_ABORT in msgb_l3trim called from gprs_llc_rcvmsg()
https://osmocom.org/issues/3952
2019-04-23T15:52:11Z
keith
<p>crash is observed with a large number and variey of phones attaching. <br />Happens within a few minutes of startup of SGSN</p>
<p>The offending msgb passed to gprs_llc_rcvmsg():</p>
<pre>
(gdb) print *msg
$2 = {list = {next = 0x0, prev = 0x0}, {dst = 0x0, trx = 0x0}, lchan = 0x0, l1h = 0x0, l2h = 0x84c3fc "", l3h = 0x0, l4h = 0x0, cb = {8700928, 8700951, 8700938,
12350589634047246338, 0}, data_len = 3072, len = 32, head = 0x84c3e8 "", tail = 0x84c41c "", data = 0x84c3fc "", _data = 0x84c3e8 ""}
</pre>
<p>from gprs_llc_hdr_parse() :</p>
<pre>
(gdb) print llhp
$3 = {sapi = 1 '\001', is_cmd = 1 '\001', ack_req = 0 '\000', is_encrypted = 0 '\000', seq_rx = 0, seq_tx = 0, fcs = 11772444, fcs_calc = 11772444, data = 0x0, data_len = 0,
crc_length = 2, cmd = GPRS_LLC_NULL}
</pre>
<p>Then we do: <br /> msg->l3h = llhp.data; (0x0)<br /> msgb_l3trim(msg, llhp.data_len); (0)</p>
<p>and so in msgb_l3trim(msg, l3len)</p>
<pre><code>msgb_trim(msg, (msg->l3h - msg->data) + l3len);</code></pre>
<p>that is to say (0x0 - 0x84c3fc) + 0) results in passing a negative length to msgb_trim and so...</p>
<pre><code>if (len < 0)<br /> MSGB_ABORT(msg, "Negative length is not allowed\n");</code></pre>
<p>backtrace:</p>
<pre>
(gdb) bt
#0 0x00007ffff5402067 in __GI_raise (sig=sig@entry=6) at ../nptl/sysdeps/unix/sysv/linux/raise.c:56
#1 0x00007ffff5403448 in __GI_abort () at abort.c:89
#2 0x00007ffff7314310 in osmo_panic () from /usr/lib/x86_64-linux-gnu/libosmocore.so.12
#3 0x000000000041c31c in msgb_trim (len=<optimized out>, msg=<optimized out>) at /usr/include/osmocom/core/msgb.h:487
#4 msgb_l3trim (l3len=<optimized out>, msg=<optimized out>) at /usr/include/osmocom/core/msgb.h:504
#5 gprs_llc_rcvmsg (msg=0x84c360, tv=0x72ea) at gprs_llc.c:950
#6 0x00007ffff775df5b in bssgp_rcvmsg () from /usr/lib/x86_64-linux-gnu/libosmogb.so.6
#7 0x00007ffff7757e3a in ?? () from /usr/lib/x86_64-linux-gnu/libosmogb.so.6
#8 0x00007ffff77597fa in gprs_ns_rcvmsg () from /usr/lib/x86_64-linux-gnu/libosmogb.so.6
#9 0x00007ffff7759974 in ?? () from /usr/lib/x86_64-linux-gnu/libosmogb.so.6
#10 0x00007ffff7308dd4 in osmo_select_main () from /usr/lib/x86_64-linux-gnu/libosmocore.so.12
#11 0x00000000004050d7 in main (argc=1, argv=0x0) at sgsn_main.c:524
</pre>
<p>LLC debug log leading up to this was:</p>
<pre>
<0011> gprs_llc_parse.c:81 LLC SAPI=1 C U GEA0 IOV-UI=0x000000 FCS=0x172bab CMD=UI DATA
<0011> gprs_llc.c:342 Sending XID type NULL (8 bytes) request to MS...
<0011> gprs_llc_parse.c:81 LLC SAPI=1 C U GEA0 IOV-UI=0x000000 FCS=0xea1c55 CMD=UI DATA
<0011> gprs_llc_parse.c:81 LLC SAPI=1 C U GEA0 IOV-UI=0x000000 FCS=0xb3a21c
msgb(0x84c360): Negative length is not allowed
</pre>
OsmoPCU - Bug #3499 (Resolved): pcu is logging "Allocating DL TBF: MS_CLASS=0/0" ; TLV parsing co...
https://osmocom.org/issues/3499
2018-08-24T14:36:14Z
keith
<p>This also relates to this error seen with EGPRS capable phone:<br />"Not accepting non-EGPRS phone in EGPRS-only mode"</p>
<p>However, in GPRS mode, this does not appear to make any immediately obvious difference to functionality, but all the same, <strong>MS_CLASS=0/0</strong> is obviously wrong.</p>
<p>This is because the code to parse the MS RA Cap is commented, with a note:</p>
<p>"Do not rely on this IE."</p>
<p>As far as I can tell from analysis of NS trace, the BSSGP contains correct Radio Access Capability IE, that is to say, It is corresponding with what the MS sent in the Attach Request.</p>
<p>So why "do not rely?" Why is the code commented? Perhaps in 2016, this information from the BSSGP was not reliable?</p>
<p>See <a class="external" href="http://git.osmocom.org/osmo-pcu/commit/?id=741d25cb6f8c0c1522cf6d1be2fea49356ecd4bd">http://git.osmocom.org/osmo-pcu/commit/?id=741d25cb6f8c0c1522cf6d1be2fea49356ecd4bd</a><br />and the two previous commits.</p>
OsmoPCU - Bug #3472 (Closed): GPRS connection is in a state where pdp-context is active, but data...
https://osmocom.org/issues/3472
2018-08-18T13:47:10Z
keith
<p>Very vague analysis here, just wanted to save this (limited but hopefully clear) log in public place.</p>
<p>TODO: Get a full trace of this behaviour.</p>
<p>As the title says, the pdp-context is active, generating traffic from the network side results in:</p>
<pre>
DTBF <0008> ../../git/src/tbf.cpp:1065 ********** DL-TBF starts here **********
DTBF <0008> ../../git/src/tbf.cpp:1067 Allocating DL TBF: MS_CLASS=0/0
DTBF <0008> ../../git/src/tbf.cpp:537 TBF(TFI=0 TLLI=0x00000000 DIR=DL STATE=NULL) Setting Control TS 6
DTBF <0008> ../../git/src/tbf.cpp:922 TBF(TFI=0 TLLI=0xf6dafa25 DIR=DL STATE=NULL) Allocated: trx = 0, ul_slots = 40, dl_slots = 40
DTBF <0008> ../../git/src/tbf_dl.cpp:510 TBF(TFI=0 TLLI=0xf6dafa25 DIR=DL STATE=NULL) changes state from NULL to ASSIGN
DTBF <0008> ../../git/src/bts.cpp:799 TBF(TFI=0 TLLI=0xf6dafa25 DIR=DL STATE=ASSIGN) TX: START Immediate Assignment Downlink (PCH)
DTBF <0008> ../../git/src/bts.cpp:556 TBF(TFI=0 TLLI=0xf6dafa25 DIR=DL STATE=ASSIGN) starting timer T0 [assignment (AGCH)] with 0 sec. 200000 microsec, cur_fn=1779843
DTBF <0008> ../../git/src/tbf.cpp:1133 TBF(TFI=0 TLLI=0xf6dafa25 DIR=DL STATE=ASSIGN) timer 0 expired. cur_fn=1779886
DTBF <0008> ../../git/src/tbf.cpp:514 ********** DL-TBF update **********
DTBF <0008> ../../git/src/tbf_dl.cpp:496 TBF(TFI=0 TLLI=0xf6dafa25 DIR=DL STATE=ASSIGN) changes DL ASS state from GPRS_RLCMAC_DL_ASS_NONE to GPRS_RLCMAC_DL_ASS_SEND_ASS
DTBF <0008> ../../git/src/tbf_dl.cpp:500 TBF(TFI=0 TLLI=0xf6dafa25 DIR=DL STATE=ASSIGN) changes state from ASSIGN to ASSIGN
DTBF <0008> ../../git/src/tbf_dl.cpp:500 TBF(TFI=0 TLLI=0xf6dafa25 DIR=DL STATE=ASSIGN) set ass. type PACCH [prev CCCH:0, PACCH:0]
DTBF <0008> ../../git/src/tbf_dl.cpp:503 TBF(TFI=0 TLLI=0xf6dafa25 DIR=DL STATE=ASSIGN) starting timer T0 [assignment (PACCH)] with 2 sec. 0 microsec, cur_fn=1779886
DTBF <0008> ../../git/src/tbf.cpp:1245 TBF(TFI=0 TLLI=0xf6dafa25 DIR=DL STATE=ASSIGN) New and old TBF are the same.
DTBF <0008> ../../git/src/tbf.cpp:1266 TBF(TFI=0 TLLI=0xf6dafa25 DIR=DL STATE=ASSIGN) start Packet Downlink Assignment (PACCH)
DTBF <0008> ../../git/src/tbf.cpp:1273 +++++++++++++++++++++++++ TX : Packet Downlink Assignment +++++++++++++++++++++++++
DTBF <0008> ../../git/src/tbf.cpp:1276 ------------------------- TX : Packet Downlink Assignment -------------------------
DTBF <0008> ../../git/src/tbf.cpp:784 TBF(TFI=0 TLLI=0xf6dafa25 DIR=DL STATE=ASSIGN) poll timeout for FN=1779903, TS=6 (curr FN 1779916)
DTBF <0008> ../../git/src/tbf.cpp:834 TBF(TFI=0 TLLI=0xf6dafa25 DIR=DL STATE=ASSIGN) Timeout for polling PACKET CONTROL ACK for PACKET DOWNLINK ASSIGNMENT.
DTBF <0008> ../../git/src/tbf.cpp:1179 TBF(TFI=0 TLLI=0xf6dafa25 DIR=DL STATE=ASSIGN) Assignment was on PACCH
DTBF <0008> ../../git/src/tbf.cpp:1187 TBF(TFI=0 TLLI=0xf6dafa25 DIR=DL STATE=ASSIGN) No downlink ACK received yet
DTBF <0008> ../../git/src/tbf.cpp:1245 TBF(TFI=0 TLLI=0xf6dafa25 DIR=DL STATE=ASSIGN) New and old TBF are the same.
DTBF <0008> ../../git/src/tbf.cpp:1266 TBF(TFI=0 TLLI=0xf6dafa25 DIR=DL STATE=ASSIGN) start Packet Downlink Assignment (PACCH)
DTBF <0008> ../../git/src/tbf.cpp:1273 +++++++++++++++++++++++++ TX : Packet Downlink Assignment +++++++++++++++++++++++++
DTBF <0008> ../../git/src/tbf.cpp:1276 ------------------------- TX : Packet Downlink Assignment -------------------------
DTBF <0008> ../../git/src/tbf.cpp:784 TBF(TFI=0 TLLI=0xf6dafa25 DIR=DL STATE=ASSIGN) poll timeout for FN=1779934, TS=6 (curr FN 1779951)
DTBF <0008> ../../git/src/tbf.cpp:1245 TBF(TFI=0 TLLI=0xf6dafa25 DIR=DL STATE=ASSIGN) New and old TBF are the same.
DTBF <0008> ../../git/src/tbf.cpp:1266 TBF(TFI=0 TLLI=0xf6dafa25 DIR=DL STATE=ASSIGN) start Packet Downlink Assignment (PACCH)
DTBF <0008> ../../git/src/tbf.cpp:1273 +++++++++++++++++++++++++ TX : Packet Downlink Assignment +++++++++++++++++++++++++
DTBF <0008> ../../git/src/tbf.cpp:1276 ------------------------- TX : Packet Downlink Assignment -------------------------
DTBF <0008> ../../git/src/tbf.cpp:784 TBF(TFI=0 TLLI=0xf6dafa25 DIR=DL STATE=ASSIGN) poll timeout for FN=1779968, TS=6 (curr FN 1779986)
DTBF <0008> ../../git/src/tbf.cpp:1245 TBF(TFI=0 TLLI=0xf6dafa25 DIR=DL STATE=ASSIGN) New and old TBF are the same.
DTBF <0008> ../../git/src/tbf.cpp:1266 TBF(TFI=0 TLLI=0xf6dafa25 DIR=DL STATE=ASSIGN) start Packet Downlink Assignment (PACCH)
DTBF <0008> ../../git/src/tbf.cpp:1273 +++++++++++++++++++++++++ TX : Packet Downlink Assignment +++++++++++++++++++++++++
DTBF <0008> ../../git/src/tbf.cpp:1276 ------------------------- TX : Packet Downlink Assignment -------------------------
DTBF <0008> ../../git/src/tbf.cpp:784 TBF(TFI=0 TLLI=0xf6dafa25 DIR=DL STATE=ASSIGN) poll timeout for FN=1780003, TS=6 (curr FN 1780016)
DTBF <0008> ../../git/src/tbf.cpp:1245 TBF(TFI=0 TLLI=0xf6dafa25 DIR=DL STATE=ASSIGN) New and old TBF are the same.
DTBF <0008> ../../git/src/tbf.cpp:1266 TBF(TFI=0 TLLI=0xf6dafa25 DIR=DL STATE=ASSIGN) start Packet Downlink Assignment (PACCH)
DTBF <0008> ../../git/src/tbf.cpp:1273 +++++++++++++++++++++++++ TX : Packet Downlink Assignment +++++++++++++++++++++++++
DTBF <0008> ../../git/src/tbf.cpp:1276 ------------------------- TX : Packet Downlink Assignment -------------------------
DTBF <0008> ../../git/src/tbf.cpp:784 TBF(TFI=0 TLLI=0xf6dafa25 DIR=DL STATE=ASSIGN) poll timeout for FN=1780033, TS=6 (curr FN 1780046)
DTBF <0008> ../../git/src/tbf.cpp:1245 TBF(TFI=0 TLLI=0xf6dafa25 DIR=DL STATE=ASSIGN) New and old TBF are the same.
DTBF <0008> ../../git/src/tbf.cpp:1266 TBF(TFI=0 TLLI=0xf6dafa25 DIR=DL STATE=ASSIGN) start Packet Downlink Assignment (PACCH)
DTBF <0008> ../../git/src/tbf.cpp:1273 +++++++++++++++++++++++++ TX : Packet Downlink Assignment +++++++++++++++++++++++++
DTBF <0008> ../../git/src/tbf.cpp:1276 ------------------------- TX : Packet Downlink Assignment -------------------------
DTBF <0008> ../../git/src/tbf.cpp:784 TBF(TFI=0 TLLI=0xf6dafa25 DIR=DL STATE=ASSIGN) poll timeout for FN=1780064, TS=6 (curr FN 1780077)
DTBF <0008> ../../git/src/tbf.cpp:1245 TBF(TFI=0 TLLI=0xf6dafa25 DIR=DL STATE=ASSIGN) New and old TBF are the same.
DTBF <0008> ../../git/src/tbf.cpp:1266 TBF(TFI=0 TLLI=0xf6dafa25 DIR=DL STATE=ASSIGN) start Packet Downlink Assignment (PACCH)
DTBF <0008> ../../git/src/tbf.cpp:1273 +++++++++++++++++++++++++ TX : Packet Downlink Assignment +++++++++++++++++++++++++
DTBF <0008> ../../git/src/tbf.cpp:1276 ------------------------- TX : Packet Downlink Assignment -------------------------
DTBF <0008> ../../git/src/tbf.cpp:784 TBF(TFI=0 TLLI=0xf6dafa25 DIR=DL STATE=ASSIGN) poll timeout for FN=1780094, TS=6 (curr FN 1780111)
DTBF <0008> ../../git/src/tbf.cpp:1245 TBF(TFI=0 TLLI=0xf6dafa25 DIR=DL STATE=ASSIGN) New and old TBF are the same.
DTBF <0008> ../../git/src/tbf.cpp:1266 TBF(TFI=0 TLLI=0xf6dafa25 DIR=DL STATE=ASSIGN) start Packet Downlink Assignment (PACCH)
DTBF <0008> ../../git/src/tbf.cpp:1273 +++++++++++++++++++++++++ TX : Packet Downlink Assignment +++++++++++++++++++++++++
DTBF <0008> ../../git/src/tbf.cpp:1276 ------------------------- TX : Packet Downlink Assignment -------------------------
DTBF <0008> ../../git/src/tbf.cpp:784 TBF(TFI=0 TLLI=0xf6dafa25 DIR=DL STATE=ASSIGN) poll timeout for FN=1780129, TS=6 (curr FN 1780146)
DTBF <0008> ../../git/src/tbf.cpp:597 TBF(TFI=0 TLLI=0xf6dafa25 DIR=DL STATE=ASSIGN) N3105 exceeded MAX (8)
DTBF <0008> ../../git/src/tbf.cpp:842 TBF(TFI=0 TLLI=0xf6dafa25 DIR=DL STATE=ASSIGN) changes state from ASSIGN to RELEASING
DTBF <0008> ../../git/src/tbf.cpp:843 TBF(TFI=0 TLLI=0xf6dafa25 DIR=DL STATE=RELEASING) starting timer T3195 [MAX N3105 reached] with 5 sec. 0 microsec, cur_fn=1780146
DTBF <0008> ../../git/src/tbf.cpp:1133 TBF(TFI=0 TLLI=0xf6dafa25 DIR=DL STATE=RELEASING) timer 0 expired. cur_fn=1780319
DTBF <0008> ../../git/src/tbf.cpp:1142 TBF(TFI=0 TLLI=0xf6dafa25 DIR=DL STATE=RELEASING) Error: TBF is not in assign state
DTBF <0008> ../../git/src/tbf.cpp:646 TBF(TFI=0 TLLI=0xf6dafa25 DIR=DL STATE=RELEASING) T3195 timeout expired, freeing TBF
DTBF <0008> ../../git/src/tbf.cpp:1179 TBF(TFI=0 TLLI=0xf6dafa25 DIR=DL STATE=RELEASING) Assignment was on PACCH
DTBF <0008> ../../git/src/tbf.cpp:1187 TBF(TFI=0 TLLI=0xf6dafa25 DIR=DL STATE=RELEASING) No downlink ACK received yet
DTBF <0008> ../../git/src/tbf_dl.cpp:1138 TBF(TFI=0 TLLI=0xf6dafa25 DIR=DL STATE=RELEASING) changes state from RELEASING to RELEASING
DTBF <0008> ../../git/src/tbf.cpp:481 TBF(TFI=0 TLLI=0xf6dafa25 DIR=DL STATE=RELEASING) free
DTBF <0008> ../../git/src/tbf.cpp:494 ********** DL-TBF ends here **********
</pre>
<p>This repeats for as long as the network side has traffic..</p>
<p>Initiating traffic from the phone side then results in:</p>
<pre>
DL1IF <0001> ../../git/src/pcu_l1_if.cpp:389 RACH request received: sapi=1 qta=0, ra=122, fn=1786070, cur_fn=1786074, is_11bit=0
DTBF <0008> ../../git/src/tbf.cpp:974 ********** UL-TBF starts here **********
DTBF <0008> ../../git/src/tbf.cpp:976 Allocating UL TBF: MS_CLASS=0/0
DTBF <0008> ../../git/src/tbf.cpp:537 TBF(TFI=0 TLLI=0x00000000 DIR=UL STATE=NULL) Setting Control TS 6
DTBF <0008> ../../git/src/tbf.cpp:922 TBF(TFI=0 TLLI=0x00000000 DIR=UL STATE=NULL) Allocated: trx = 0, ul_slots = 40, dl_slots = 00
DTBF <0008> ../../git/src/bts.cpp:745 TBF(TFI=0 TLLI=0x00000000 DIR=UL STATE=NULL) changes state from NULL to FLOW
DTBF <0008> ../../git/src/bts.cpp:746 TBF(TFI=0 TLLI=0x00000000 DIR=UL STATE=FLOW) set ass. type CCCH [prev CCCH:0, PACCH:0]
DTBF <0008> ../../git/src/bts.cpp:747 TBF(TFI=0 TLLI=0x00000000 DIR=UL STATE=FLOW) starting timer T3169 [RACH (new UL-TBF)] with 5 sec. 0 microsec, cur_fn=1786074
DTBF <0008> ../../git/src/bts.cpp:748 TBF(TFI=0 TLLI=0x00000000 DIR=UL STATE=FLOW) [UPLINK] START
DTBF <0008> ../../git/src/bts.cpp:753 TBF(TFI=0 TLLI=0x00000000 DIR=UL STATE=FLOW) RX: [PCU <- BTS] RACH qbit-ta=0 ra=0x7a, Fn=1786070 (2,50,0)
DTBF <0008> ../../git/src/bts.cpp:754 TBF(TFI=0 TLLI=0x00000000 DIR=UL STATE=FLOW) TX: START Immediate Assignment Uplink (AGCH)
DTBF <0008> ../../git/src/tbf_ul.cpp:200 TBF(TFI=0 TLLI=0x00000000 DIR=UL STATE=FLOW) restarting timer T3169 [acked (data)] with 5 sec. 0 microsec, cur_fn=1786104
DTBF <0008> ../../git/src/tbf_ul.cpp:375 TBF(TFI=0 TLLI=0xf6dafa25 DIR=UL STATE=FLOW) changes UL ACK state from GPRS_RLCMAC_UL_ACK_NONE to GPRS_RLCMAC_UL_ACK_SEND_ACK
DTBF <0008> ../../git/src/tbf_ul.cpp:169 TBF(TFI=0 TLLI=0xf6dafa25 DIR=UL STATE=FLOW) changes UL ACK state from GPRS_RLCMAC_UL_ACK_SEND_ACK to GPRS_RLCMAC_UL_ACK_NONE
DTBF <0008> ../../git/src/tbf_ul.cpp:200 TBF(TFI=0 TLLI=0xf6dafa25 DIR=UL STATE=FLOW) restarting timer T3169 [acked (data)] with 5 sec. 0 microsec, cur_fn=1786109
DTBF <0008> ../../git/src/tbf_ul.cpp:375 TBF(TFI=0 TLLI=0xf6dafa25 DIR=UL STATE=FLOW) changes UL ACK state from GPRS_RLCMAC_UL_ACK_NONE to GPRS_RLCMAC_UL_ACK_SEND_ACK
DTBF <0008> ../../git/src/tbf_ul.cpp:169 TBF(TFI=0 TLLI=0xf6dafa25 DIR=UL STATE=FLOW) changes UL ACK state from GPRS_RLCMAC_UL_ACK_SEND_ACK to GPRS_RLCMAC_UL_ACK_NONE
DTBF <0008> ../../git/src/tbf_ul.cpp:200 TBF(TFI=0 TLLI=0xf6dafa25 DIR=UL STATE=FLOW) restarting timer T3169 [acked (data)] with 5 sec. 0 microsec, cur_fn=1786113
DTBF <0008> ../../git/src/tbf_ul.cpp:334 TBF(TFI=0 TLLI=0xf6dafa25 DIR=UL STATE=FLOW) changes state from FLOW to FINISHED
DTBF <0008> ../../git/src/tbf_ul.cpp:375 TBF(TFI=0 TLLI=0xf6dafa25 DIR=UL STATE=FINISHED) changes UL ACK state from GPRS_RLCMAC_UL_ACK_NONE to GPRS_RLCMAC_UL_ACK_SEND_ACK
DTBF <0008> ../../git/src/tbf.cpp:1065 ********** DL-TBF starts here **********
DTBF <0008> ../../git/src/tbf.cpp:1067 Allocating DL TBF: MS_CLASS=0/0
DTBF <0008> ../../git/src/tbf.cpp:537 TBF(TFI=0 TLLI=0x00000000 DIR=DL STATE=NULL) Setting Control TS 6
DTBF <0008> ../../git/src/tbf.cpp:922 TBF(TFI=0 TLLI=0xf6dafa25 DIR=DL STATE=NULL) Allocated: trx = 0, ul_slots = 40, dl_slots = e0
DTBF <0008> ../../git/src/tbf_dl.cpp:496 TBF(TFI=0 TLLI=0xf6dafa25 DIR=UL STATE=FINISHED) changes DL ASS state from GPRS_RLCMAC_DL_ASS_NONE to GPRS_RLCMAC_DL_ASS_SEND_ASS
DTBF <0008> ../../git/src/tbf_dl.cpp:500 TBF(TFI=0 TLLI=0xf6dafa25 DIR=DL STATE=NULL) changes state from NULL to ASSIGN
DTBF <0008> ../../git/src/tbf_dl.cpp:500 TBF(TFI=0 TLLI=0xf6dafa25 DIR=DL STATE=ASSIGN) set ass. type PACCH [prev CCCH:0, PACCH:0]
DTBF <0008> ../../git/src/tbf_dl.cpp:503 TBF(TFI=0 TLLI=0xf6dafa25 DIR=DL STATE=ASSIGN) starting timer T0 [assignment (PACCH)] with 2 sec. 0 microsec, cur_fn=1786113
DTBF <0008> ../../git/src/tbf.cpp:1266 TBF(TFI=0 TLLI=0xf6dafa25 DIR=DL STATE=ASSIGN) start Packet Downlink Assignment (PACCH)
DTBF <0008> ../../git/src/tbf.cpp:1273 +++++++++++++++++++++++++ TX : Packet Downlink Assignment +++++++++++++++++++++++++
DTBF <0008> ../../git/src/tbf.cpp:1276 ------------------------- TX : Packet Downlink Assignment -------------------------
DTBF <0008> ../../git/src/tbf_ul.cpp:200 TBF(TFI=0 TLLI=0xf6dafa25 DIR=UL STATE=FINISHED) restarting timer T3169 [acked (data)] with 5 sec. 0 microsec, cur_fn=1786117
DTBF <0008> ../../git/src/tbf.cpp:717 TBF(TFI=0 TLLI=0xf6dafa25 DIR=UL STATE=FINISHED) Polling is already scheduled
DTBF <0008> ../../git/src/tbf_ul.cpp:200 TBF(TFI=0 TLLI=0xf6dafa25 DIR=UL STATE=FINISHED) restarting timer T3169 [acked (data)] with 5 sec. 0 microsec, cur_fn=1786122
DTBF <0008> ../../git/src/tbf.cpp:717 TBF(TFI=0 TLLI=0xf6dafa25 DIR=UL STATE=FINISHED) Polling is already scheduled
DTBF <0008> ../../git/src/tbf_ul.cpp:200 TBF(TFI=0 TLLI=0xf6dafa25 DIR=UL STATE=FINISHED) restarting timer T3169 [acked (data)] with 5 sec. 0 microsec, cur_fn=1786126
DTBF <0008> ../../git/src/tbf.cpp:717 TBF(TFI=0 TLLI=0xf6dafa25 DIR=UL STATE=FINISHED) Polling is already scheduled
DTBF <0008> ../../git/src/tbf.cpp:717 TBF(TFI=0 TLLI=0xf6dafa25 DIR=UL STATE=FINISHED) Polling is already scheduled
DTBF <0008> ../../git/src/tbf.cpp:717 TBF(TFI=0 TLLI=0xf6dafa25 DIR=UL STATE=FINISHED) Polling is already scheduled
DL1IF <0001> ../../git/src/bts.cpp:848 PH-DATA-IND is updating TLLI=0xf6dafa25: TA 0 -> 0 on TRX = 0, TS = 6, FN = 1786130
DTBF <0008> ../../git/src/pdch.cpp:297 TBF(TFI=0 TLLI=0xf6dafa25 DIR=UL STATE=FINISHED) RX: [PCU <- BTS] Packet Control Ack
DTBF <0008> ../../git/src/pdch.cpp:298 TBF(TFI=0 TLLI=0xf6dafa25 DIR=UL STATE=FINISHED) changes poll state from GPRS_RLCMAC_POLL_SCHED to GPRS_RLCMAC_POLL_NONE
DTBF <0008> ../../git/src/pdch.cpp:311 TBF(TFI=0 TLLI=0xf6dafa25 DIR=UL STATE=FINISHED) [UPLINK] DOWNLINK ASSIGNED
DTBF <0008> ../../git/src/pdch.cpp:314 TBF(TFI=0 TLLI=0xf6dafa25 DIR=UL STATE=FINISHED) changes DL ASS state from GPRS_RLCMAC_DL_ASS_WAIT_ACK to GPRS_RLCMAC_DL_ASS_NONE
DTBF <0008> ../../git/src/pdch.cpp:333 TBF(TFI=0 TLLI=0xf6dafa25 DIR=DL STATE=ASSIGN) changes state from ASSIGN to FLOW
DTBF <0008> ../../git/src/tbf.cpp:614 TBF(TFI=0 TLLI=0xf6dafa25 DIR=DL STATE=FLOW) stopping timer T0 [control acked (DL-TBF)]
DL1IF <0001> ../../git/src/bts.cpp:848 PH-DATA-IND is updating TLLI=0xf6dafa25: TA 0 -> 0 on TRX = 0, TS = 6, FN = 1786156
DTBF <0008> ../../git/src/pdch.cpp:297 TBF(TFI=0 TLLI=0xf6dafa25 DIR=UL STATE=FINISHED) RX: [PCU <- BTS] Packet Control Ack
DTBF <0008> ../../git/src/pdch.cpp:298 TBF(TFI=0 TLLI=0xf6dafa25 DIR=UL STATE=FINISHED) changes poll state from GPRS_RLCMAC_POLL_SCHED to GPRS_RLCMAC_POLL_NONE
DTBF <0008> ../../git/src/tbf_ul.cpp:119 TBF(TFI=0 TLLI=0xf6dafa25 DIR=UL STATE=FINISHED) changes UL ACK state from GPRS_RLCMAC_UL_ACK_WAIT_ACK to GPRS_RLCMAC_UL_ACK_NONE
DTBF <0008> ../../git/src/pdch.cpp:303 TBF(TFI=0 TLLI=0xf6dafa25 DIR=UL STATE=FINISHED) [UPLINK] END
DRLCMACMEAS <0007> ../../git/src/gprs_rlcmac_meas.cpp:104 UL RSSI of TLLI=0xf6dafa25: -41 dBm
DTBF <0008> ../../git/src/tbf.cpp:481 TBF(TFI=0 TLLI=0xf6dafa25 DIR=UL STATE=FINISHED) free
DTBF <0008> ../../git/src/tbf.cpp:614 TBF(TFI=0 TLLI=0xf6dafa25 DIR=UL STATE=FINISHED) stopping timer T3169 [freeing TBF]
DTBF <0008> ../../git/src/tbf.cpp:494 ********** UL-TBF ends here **********
</pre>
OsmoSGSN - Bug #3426 (Resolved): gprs_llc_process_xid_ind() does not echo L3_PAR, breaks PDP acti...
https://osmocom.org/issues/3426
2018-07-27T11:23:21Z
keith
<p>In gprs_llc_process_xid_ind()<br /> (at the time of writing) <a class="external" href="http://cgit.osmocom.org/osmo-sgsn/tree/src/gprs/gprs_llc.c#n227">http://cgit.osmocom.org/osmo-sgsn/tree/src/gprs/gprs_llc.c#n227</a></p>
<p>We check if (xid_field->type != GPRS_LLC_XID_T_L3_PAR) <br />before echoing the XID to the MS</p>
<p>The Motorola KRZR responds by sending the XID list again and repeats 4 times before giving up and sending PDP deactivate context, with a cause 25 "LLC or SNDCP Failure"</p>
<p>Removing the check for xid_field->type != GPRS_LLC_XID_T_L3_PAR and echoing the L3 parameter back results in PDP activation success and GPRS session works.</p>
<p>Why this check? Why do we not echo all the xid fields back? Did it break with some other phone?</p>
OsmoNITB - Bug #2938 (Closed): osmo-nitb version 1.0.0 in 'latest' constantly logs LIBDBI error
https://osmocom.org/issues/2938
2018-02-13T11:00:52Z
keith
<p>The version of the osmo-nitb in the 'latest' repository on download.opensuse.org is built from the release tag 1.0.0<br />which is earlier than <a class="external" href="https://git.osmocom.org/openbsc/commit/?id=5825e5cfb245f32a409c7784e51fb1e774adf799">https://git.osmocom.org/openbsc/commit/?id=5825e5cfb245f32a409c7784e51fb1e774adf799</a><br />which fixes the below:</p>
<p>This is output to the log at regular intervals:<br /><pre>
DDB <000d> db.c:190 DBI: -6: An invalid or out-of-range index was passed to libdbi
DDB <000d> backtrace.c:45 backtrace() returned 11 addresses
[snip]
</pre></p>
<p><strong>Suggested action:</strong> TAG the a release (1.0.1) post commit 5825e5cfb245f32a409c7784e51fb1e774adf799<br /><strong>Question:</strong> Will tagging a release result in a automatic build of the new version in 'latest'?</p>
OsmoNITB - Bug #2595 (Closed): db: find the best way to allocate unused random extension and avoi...
https://osmocom.org/issues/2595
2017-10-25T19:01:07Z
keith
<p>in libmsc/db.c<br />db_subscriber_alloc_exten() runs an infinite loop that will never exit <br />if an unused extension cannot be allocated between GSM_MAX_EXTEN and GSM_MIN_EXTEN</p>
<p>A routine is required that efficiently finds a free extension.</p>
<p>Some suggestions as to how it might be done and comments were posted here:<br /><a class="external" href="https://gerrit.osmocom.org/#/c/3910/">https://gerrit.osmocom.org/#/c/3910/</a></p>