OpenBSC April 2019

openbsc@lists.osmocom.org

21 participants
26 discussions

dynamic traffic channels
by Neels Hofmeyr 20 May '25

20 May '25

On Tue, Jun 28, 2016 at 10:05:28AM +0200, Harald Welte wrote: > [translated from german] > is it certain that we switch a channel to PDCH only when > gprs mode != none? A TS can be GSM_PCHAN_TCH_F_PDCH; those are the only ones for which we send a PDCH ACT message. We send a PDCH ACT message - during init (CHANNEL OML's state changed to enabled -> send PDCH ACT), - and upon channel release ack when pchan == GSM_PCHAN_TCH_F_PDCH. So the question is, when we receive a channel release ack, could that be the PDCH release and we switch PDCH right back on by accident? No, because we only receive a chan rel ack when the *TCH/F* is being released. That is because the PDCH release is initiated "internally" from the PDCH DEACT, and thus this condition in common/rsl.c rsl_tx_rf_rel_ack() catches on, which existed before dyn PDCH: if (lchan->rel_act_kind != LCHAN_REL_ACT_RSL) { LOGP(DRSL, LOGL_NOTICE, "%s not sending REL ACK\n", gsm_lchan_name(lchan)); return 0; } In rsl_rx_rf_chan_rel() the rel_act_kind is set to LCHAN_REL_ACT_RSL, but not in the rsl_rx_dyn_pdch(). This is analogous to the ip.access way -- the ip.access nanobts replies to a PDCH DEACT with a PDCH DEACT ACK and doesn't send a separate channel release ack. Maybe we could set rel_act_kind to some new LCHAN_REL_ACT_IPAC_DYN_PDCH for clarity? (But we shouldn't actually send a release ack, to stay compatible.) Even though it works as-is, we should indeed add another flag check: - We do check the flags that no ACT/DEACT is already pending; - And we do send a PDCH DEACT only if ts->flags & TS_F_PDCH_ACTIVE; - But we would send a PDCH ACT despite ts->flags & TS_F_PDCH_ACTIVE. This should never happen, but it would make sense to ensure that. ~Neels

3 5

Problem while running NIB on Open Cellular Base sation
by Brackley Casinga 31 Jan '24

31 Jan '24

Hi, My name is Brackley Cassinga Form DRC, we run a community network called pamoja net where we offer gsm services using osmocom open source software and OC Base station. Recently I have tried to install another base station as the same installed but I could not find any resource guiding through all the steps to take to run NIB on a base station. I'm currently running Ubuntu and I will appreciate if you could guide me on the installation of BSC,hlr,MSC , in order to run a basic gsm network. Thank you. Regards -- *Ir Brackley heshima Casinga **Pacifique* *CEO and Founder of kwanzatechnologie* KwanzaTechnologies ,GlobalElectronics +243977265291 | +243977265291 | Pcassinga(a)gmail.com/ brackley(a)ensemblepourladifference.org www.kwantechnologies.jimdosite.com <http://www.kwantechnologies.com/> | Skype: Brackley cassinga <https://webapp.wisestamp.com/#> Av Semliki N 43

2 1

OpenBSC on 3rd party MSC
by wyao＠corrections.com 30 Jul '19

30 Jul '19

Hello All, I am working on get OpenBSC connected to a 3rd party MSC, I read from the Osmo document that I can use the bsc only mode and the osm-bsc instead of the osmo-nitb. Currently I had osmo-trx-uhd, osmo-bts-trx, osmo-bsc, and osmo-stp configured and and running, but I see a lot of below error logs in the osmo-stp console: ``````````````````````````` DLSS7 <000c> osmo_ss7.c:1468 asp-asp-dyn-0: xua_srv_conn_cb(): sctp_recvmsg() returned 56 (flags=0x80) DLM3UA <000f> m3ua.c:722 asp-asp-dyn-0: Received M3UA Message (XFER:DATA) DLM3UA <000f> m3ua.c:541 asp-asp-dyn-0: m3ua_rx_xfer DLM3UA <000f> m3ua.c:580 asp-asp-dyn-0: m3ua_rx_xfer(): M3UA data header: opc=337=0.42.1 dpc=185=0.23.1 DLSS7 <000c> osmo_ss7_hmrt.c:278 m3ua_hmdc_rx_from_l2(): dpc=185=0.23.1 not local, message is for routing DLSS7 <000c> osmo_ss7_hmrt.c:258 MTP-TRANSFER.req for DPC 185: no route! ```````````````````````````` On the BSC console, I am seeing a lot of: ``````````````````````````````` <0007> a_reset.c:106 A-RESET(msc-0)[0xb76ce0]{DISC}: (re)sending BSSMAP RESET message... <0007> osmo_bsc_sigtran.c:93 Sending RESET to MSC: RI=SSN_PC,PC=0.23.1,SSN=BSSAP ``````````````````````````````` Can anyone identify what is the issue here? Appreciates! Regards, Weiqi

3 4

osmo_quote_str_c()
by Neels Hofmeyr 08 May '19

08 May '19

I think here is a bug: char *osmo_quote_str_c(const void *ctx, const char *str, int in_len) { char *buf = talloc_size(ctx, OSMO_MAX(in_len+2, 32)); if (!buf) return NULL; return osmo_quote_str_buf2(buf, 32, str, in_len); } We may allocate more than 32 bytes (see OSMO_MAX()) but still allow to write only 32 bytes? Looks like the allocated len should be stored in a local variable to pass to osmo_quote_str_buf2(). And if I'm right, what is the 32 for? At least 32?? ~N

3 2

Hard-dropping a PDP Context (SGSN)
by Mykola Shchetinin 24 Apr '19

24 Apr '19

Dear Osmocom community, A question about this part of code - function sgsn_ggsn_ctx_drop_pdp: http://git.osmocom.org/osmo-sgsn/tree/src/gprs/gprs_sgsn.c#n720 The second branch of the condition (hard-dropping) is called even when the phone is registered, and hence no Deactivate PDP Context Request is sent to the phone. Due to that, the phone doesn't know that the PDP Context was deleted on the network side and keeps acting as if it is still active -> the PS isn't working when this happens. Any suggestions/thoughts on how this can be fixed? Thanks Kind regards, Mykola

2 1

LimeNet Micro for BTS
by Rafael Diniz 16 Apr '19

16 Apr '19

Hi all, Have anyone tried Osmo GSM stack (including the trx) with the LimeNet Micro with the Pi compute module? My question is if it is stable enough for any real deployment or just another toy for the lab. With the USB3 LimeSDR, after a few hours I _always_ get a broken trx, with lots of failure messages... Thanks, Rafael Diniz Rhizomatica

5 7

gsmtap design/extensions?
by Johannes Berg 15 Apr '19

15 Apr '19

Hi, As I'm looking into adding a generic cell modem framework to the linux kernel (to create session netdevs etc.), I started looking for a metadata encapsulation, a la Radiotap (I'm a wifi guy :-) ). So obviously, I found gsmtap, but for my use case it doesn't really address most of the interesting data, and it got me wondering. So a few questions, if I may: 1) Why the design with encapsulating it in UDP? Radiotap is just a raw header without IP etc. in front, and you use it with tcpdump, wireshark or similar tools on the local system. What's the value in having something "network transparent"? 2) The format of gsmtap doesn't seem very extensible, but I guess a new version could be made that has a TLV-based format or so. I'd have argued that a new version isn't even needed, but the length field is only 8 bits right now which seems too short. (speaking of versions - the docs say "version, set to 0x01 currently" but "#define GSMTAP_VERSION 0x02") 3) Does the packet data follow the gsmtap header? It's not really clear to me based on reading the wireshark code. In particular, the data I'm thinking of is higher-level things, like the session ID for a frame when it's going through the kernel, or perhaps a flow label on RX, etc. Also, vendor-specific data would be useful, e.g. to encapsulate the device-specific headers like QMI, where such metadata is encapsulated in a vendor- or device-specific way, which you'd want to see for debugging certain things, but for other things the generic "session ID" type information - encoded in a vendor-agnostic way - would be better to show in wireshark. Since it doesn't seem possible to use gsmtap in the current version, would it make sense to define a new gsmtap that (say) has version 3 or something, followed by an overall length and TLVs? I do note that this wouldn't be compatible with the current wireshark code as it doesn't check the version, just shows it... Or would it make more sense to define a new ARPHDR_WWANTAP like ARPHDR_IEEE80211_RADIOTAP and just use that instead of encapsulating in IP/UDP, and then have a completely new (extensible) protocol inside of that? I'm not really sure I see the point of UDP encapsulation anyway. Thanks, johannes

6 22

sccp conn_id weirdness
by Neels Hofmeyr 12 Apr '19

12 Apr '19

I noticed some odd behavior in our SCCP stack, let me outline. Should this become a new issue? Because the osmo_scu_prim conn_id patches aren't merged yet, I put a temporary shim in place like we have in osmo-bsc to figure out new outgoing conn_ids. With this shim I noticed that some conn_ids work better than others: struct ran_conn *ran_conn_create_outgoing(struct ran_peer *ran_peer) { /* FIXME use method being developed in gerrit id Ifd55c6b7ed2558ff072042079cf45f5068a971de */ static uint32_t next_outgoing_conn_id = 0x80000000; uint32_t conn_id = 0; int attempts = 1000; bool already_used = true; while (attempts--) { struct ran_conn *conn; conn_id = next_outgoing_conn_id; next_outgoing_conn_id++; already_used = false; llist_for_each_entry(conn, &ran_peer->sri->ran_conns, entry) { if (conn->sccp_conn_id == conn_id) { already_used = true; break; } } if (!already_used) break; } if (already_used) return NULL; LOG_RAN_PEER(ran_peer, LOGL_DEBUG, "Outgoing conn id: %u\n", conn_id); return ran_conn_create_incoming(ran_peer, conn_id); } The weird thing is that the conn_id of 0x80000000 does *NOT* work and gets me a log line of: DLSCCP NOTICE Cannot find connection for local reference 0 (sccp_scoc.c:1636) where the MSC should be sending out the initial N-CONNECT to osmo-bsc. However, if I set the initial value to: next_outgoing_conn_id = 2342; then everything works out fine. I am at a loss to understand why this would happen, and currently don't have the cycles left to investigate. Maybe someone else wants to investigate why this happens... Logging for the failing case with 0x80000000: (the source file numbers might be a bit off current master) 20190412033755322 DBSSAP DEBUG ran_peer(GERAN-A:RI-SSN_PC:PC-1-23-4:SSN-BSSAP)[0x61200000aea0]{READY}: Outgoing conn id: 2147483648 (ran_conn.c:81) [...] 20190412033755327 DBSSAP DEBUG msc_t(IMSI-901700000014705:GERAN-A-2147483648:NONE)[0x61200001b220]{WAIT_HO_REQUEST_ACK}: NAS encode: BSSMAP: HANDOVER_REQUEST (nas_a.c:1159) 20190412033755328 DRR DEBUG ran_peer(GERAN-A:RI-SSN_PC:PC-1-23-4:SSN-BSSAP)[0x61200000aea0]{READY}: Received Event RAN_PEER_EV_MSG_DOWN_CO_INITIAL (ran_conn.c:119) 20190412033755328 DLSCCP DEBUG Received SCCP User Primitive (N-CONNECT.request) (sccp_scoc.c:1712) 20190412033755328 DLSCCP DEBUG SCCP-SCOC(2147483648)[0x6120000201a0]{IDLE}: Allocated (fsm.c:423) 20190412033755328 DLSCCP DEBUG SCCP-SCOC(2147483648)[0x6120000201a0]{IDLE}: Received Event N-CONNECT.req (sccp_scoc.c:1753) 20190412033755328 DLSS7 DEBUG sccp_scrc_rx_scoc_conn_msg: HDR=(CO:CORE,V=0,LEN=0), PART(T=Routing Context,L=4,D=00000000), PART(T=Protocol Class,L=4,D=00000002), PART(T=Source Reference,L=4,D=80000000), PART(T=Destination Address,L=20,D=0002000380020008000008bc80030008000000fe), PART(T=Sequence Control,L=4,D=00000000), PART(T=Source Address,L=20,D=0002000380020008000008b980030008000000fe), PART(T=Data,L=83,D=0051100b07010aa19181a5050a09004ad48954cb991d2912035058a605080062f224002a000005080009f1070046000104010c130a6014042f6500200240422c04080899100700001074507c06c0a80204a418) (sccp_scrc.c:398) 20190412033755328 DLSUA DEBUG sua_addr_parse_part(IEI=0x0103) (20) 00 02 00 03 80 02 00 08 00 00 08 bc 80 03 00 08 00 00 00 fe (sua.c:385) 20190412033755328 DLSUA DEBUG SUA IEI 0x0103 pos 4/20: subpart tag 0x8002, len 8 (sua.c:439) 20190412033755328 DLSUA DEBUG SUA IEI 0x0103 pos 12/20: subpart tag 0x8003, len 8 (sua.c:439) 20190412033755328 DLSUA DEBUG sua_addr_parse_part(IEI=0x0103) (20) 00 02 00 03 80 02 00 08 00 00 08 bc 80 03 00 08 00 00 00 fe (sua.c:385) 20190412033755328 DLSUA DEBUG SUA IEI 0x0103 pos 4/20: subpart tag 0x8002, len 8 (sua.c:439) 20190412033755328 DLSUA DEBUG SUA IEI 0x0103 pos 12/20: subpart tag 0x8003, len 8 (sua.c:439) 20190412033755328 DLSUA DEBUG sua_addr_parse_part(IEI=0x0102) (20) 00 02 00 03 80 02 00 08 00 00 08 b9 80 03 00 08 00 00 00 fe (sua.c:385) 20190412033755328 DLSUA DEBUG SUA IEI 0x0102 pos 4/20: subpart tag 0x8002, len 8 (sua.c:439) 20190412033755328 DLSUA DEBUG SUA IEI 0x0102 pos 12/20: subpart tag 0x8003, len 8 (sua.c:439) 20190412033755328 DLSS7 DEBUG m3ua_hmdc_rx_from_l2(): dpc=2236=1.23.4 not local, message is for routing (osmo_ss7_hmrt.c:278) 20190412033755328 DLSS7 DEBUG Found route for dpc=2236=1.23.4: pc=0=0.0.0 mask=0x0=0.0.0 via AS as-clnt-OsmoMSC-A-Iu proto=m3ua (osmo_ss7_hmrt.c:227) 20190412033755328 DLSS7 DEBUG rt->dest.as proto is M3UA for dpc=2236=1.23.4 (osmo_ss7_hmrt.c:233) 20190412033755328 DLSS7 DEBUG XUA_AS(as-clnt-OsmoMSC-A-Iu)[0x61200000a720]{AS_ACTIVE}: Received Event AS-TRANSFER.req (m3ua.c:507) 20190412033755329 DLSCCP DEBUG SCCP-SCOC(2147483648)[0x6120000201a0]{IDLE}: State change to CONN_PEND_OUT (no timeout) (sccp_scoc.c:829) 20190412033755329 DLMGCP DEBUG mgw-endpoint(IMSI-901700000014705:GERAN-A-2147483648:NONE)[0x61200001b6a0]{WAIT_MGW_RESPONSE}: rtpbridge/2@msc CI[0] RTP_TO_RAN CI=88A322A7: CRCX: done (rtpbridge/2@msc:192.168.2.4:42008) (mgcp_client_endpoint_fsm.c:651) 20190412033755329 DLMGCP DEBUG mgw-endpoint(IMSI-901700000014705:GERAN-A-2147483648:NONE)[0x61200001b6a0]{WAIT_MGW_RESPONSE}: rtpbridge/2@msc CI[1] RTP_TO_CN CI=55D5651B: CRCX: done (rtpbridge/2@msc:192.168.2.4:42010) (mgcp_client_endpoint_fsm.c:651) 20190412033755329 DLMGCP DEBUG mgw-endpoint(IMSI-901700000014705:GERAN-A-2147483648:NONE)[0x61200001b6a0]{WAIT_MGW_RESPONSE}: rtpbridge/2@msc CI in use: 2, waiting for response: 0 (mgcp_client_endpoint_fsm.c:669) 20190412033755329 DLMGCP DEBUG mgw-endpoint(IMSI-901700000014705:GERAN-A-2147483648:NONE)[0x61200001b6a0]{WAIT_MGW_RESPONSE}: State change to IN_USE (no timeout) (mgcp_client_endpoint_fsm.c:680) 20190412033755329 DLMGCP DEBUG mgw-endpoint(IMSI-901700000014705:GERAN-A-2147483648:NONE)[0x61200001b6a0]{IN_USE}: rtpbridge/2@msc CI[0] RTP_TO_RAN CI=88A322A7: CRCX: done (rtpbridge/2@msc:192.168.2.4:42008) (mgcp_client_endpoint_fsm.c:651) 20190412033755329 DLMGCP DEBUG mgw-endpoint(IMSI-901700000014705:GERAN-A-2147483648:NONE)[0x61200001b6a0]{IN_USE}: rtpbridge/2@msc CI[1] RTP_TO_CN CI=55D5651B: CRCX: done (rtpbridge/2@msc:192.168.2.4:42010) (mgcp_client_endpoint_fsm.c:651) 20190412033755329 DLINP DEBUG [ CONNECTED] osmo_stream_cli_fd_cb(): connected write (stream.c:300) 20190412033755329 DLINP DEBUG [ CONNECTED] osmo_stream_cli_write(): sending data (stream.c:225) 20190412033755329 DLINP DEBUG [ CONNECTED] osmo_stream_cli_fd_cb(): connected write (stream.c:300) 20190412033755329 DLINP DEBUG [ CONNECTED] osmo_stream_cli_write(): sending data (stream.c:225) 20190412033755332 DLINP DEBUG [ CONNECTED] osmo_stream_cli_fd_cb(): connected read (stream.c:296) 20190412033755332 DLINP DEBUG [ CONNECTED] osmo_stream_cli_read(): message received (stream.c:210) 20190412033755332 DLSS7 DEBUG asp-asp-clnt-OsmoMSC-A-Iu: xua_cli_read_cb(): sctp_recvmsg() returned 48 (flags=0x80) (osmo_ss7.c:1609) 20190412033755333 DLM3UA DEBUG asp-asp-clnt-OsmoMSC-A-Iu: Received M3UA Message (XFER:DATA) (m3ua.c:722) 20190412033755333 DLM3UA DEBUG asp-asp-clnt-OsmoMSC-A-Iu: m3ua_rx_xfer (m3ua.c:541) 20190412033755333 DLM3UA DEBUG asp-asp-clnt-OsmoMSC-A-Iu: m3ua_rx_xfer(): M3UA data header: opc=2236=1.23.4 dpc=2233=1.23.1 (m3ua.c:580) 20190412033755333 DLSS7 DEBUG m3ua_hmdc_rx_from_l2(): found dpc=2233=1.23.1 as local (osmo_ss7_hmrt.c:274) 20190412033755333 DLSUA DEBUG IEI 259: Parsed Addr: RI=2,PC=2236,SSN=254 (sccp2sua.c:333) 20190412033755333 DLSS7 DEBUG scrc_rx_mtp_xfer_ind_xua: HDR=(CO:COAK,V=0,LEN=0), PART(T=Protocol Class,L=4,D=00000002), PART(T=Destination Reference,L=4,D=00000000), PART(T=Source Reference,L=4,D=00000000), PART(T=Destination Address,L=20,D=0002000380020008000008bc80030008000000fe) (sccp_scrc.c:450) 20190412033755333 DLSCCP NOTICE Cannot find connection for local reference 0 (sccp_scoc.c:1636) 20190412033755333 DLSS7 DEBUG sccp_scrc_rx_scoc_conn_msg: HDR=(CO:COERR,V=0,LEN=0), PART(T=Routing Context,L=4,D=00000000), PART(T=Destination Reference,L=4,D=00000000), PART(T=Cause,L=4,D=00000500) (sccp_scrc.c:398) 20190412033755333 DLSS7 DEBUG m3ua_hmdc_rx_from_l2(): dpc=2236=1.23.4 not local, message is for routing (osmo_ss7_hmrt.c:278) 20190412033755333 DLSS7 DEBUG Found route for dpc=2236=1.23.4: pc=0=0.0.0 mask=0x0=0.0.0 via AS as-clnt-OsmoMSC-A-Iu proto=m3ua (osmo_ss7_hmrt.c:227) 20190412033755333 DLSS7 DEBUG rt->dest.as proto is M3UA for dpc=2236=1.23.4 (osmo_ss7_hmrt.c:233) 20190412033755333 DLSS7 DEBUG XUA_AS(as-clnt-OsmoMSC-A-Iu)[0x61200000a720]{AS_ACTIVE}: Received Event AS-TRANSFER.req (m3ua.c:507) 20190412033755333 DLINP DEBUG [ CONNECTED] osmo_stream_cli_fd_cb(): connected write (stream.c:300) 20190412033755333 DLINP DEBUG [ CONNECTED] osmo_stream_cli_write(): sending data (stream.c:225) 20190412033755334 DLINP DEBUG [ CONNECTED] osmo_stream_cli_fd_cb(): connected write (stream.c:300) 20190412033755334 DLINP DEBUG [ CONNECTED] osmo_stream_cli_write(): sending data (stream.c:225) 20190412033755337 DLINP DEBUG [ CONNECTED] osmo_stream_cli_fd_cb(): connected read (stream.c:296) 20190412033755337 DLINP DEBUG [ CONNECTED] osmo_stream_cli_read(): message received (stream.c:210) 20190412033755337 DLSS7 DEBUG asp-asp-clnt-OsmoMSC-A-Iu: xua_cli_read_cb(): sctp_recvmsg() returned 48 (flags=0x80) (osmo_ss7.c:1609) 20190412033755337 DLM3UA DEBUG asp-asp-clnt-OsmoMSC-A-Iu: Received M3UA Message (XFER:DATA) (m3ua.c:722) 20190412033755337 DLM3UA DEBUG asp-asp-clnt-OsmoMSC-A-Iu: m3ua_rx_xfer (m3ua.c:541) 20190412033755337 DLM3UA DEBUG asp-asp-clnt-OsmoMSC-A-Iu: m3ua_rx_xfer(): M3UA data header: opc=2236=1.23.4 dpc=2233=1.23.1 (m3ua.c:580) 20190412033755337 DLSS7 DEBUG m3ua_hmdc_rx_from_l2(): found dpc=2233=1.23.1 as local (osmo_ss7_hmrt.c:274) 20190412033755338 DLSS7 DEBUG scrc_rx_mtp_xfer_ind_xua: HDR=(CO:CODT,V=0,LEN=0), PART(T=Destination Reference,L=4,D=00000000), PART(T=Segmentation,L=4,D=00000000), PART(T=Data,L=6,D=000422040120) (sccp_scrc.c:450) 20190412033755338 DLSCCP NOTICE Cannot find connection for local reference 0 (sccp_scoc.c:1636) The same logging for the exact same code and situation, only with 2342 instead of 0x80000000: 20190412040110445 DBSSAP DEBUG ran_peer(GERAN-A:RI-SSN_PC:PC-1-23-4:SSN-BSSAP)[0x61200000aea0]{READY}: Outgoing conn id: 2342 (ran_conn.c:81) [...] 20190412040110451 DBSSAP DEBUG msc_t(IMSI-901700000014705:GERAN-A-2342:NONE)[0x61200001a920]{WAIT_HO_REQUEST_ACK}: NAS encode: BSSMAP: HANDOVER_REQUEST (nas_a.c:1159) 20190412040110451 DRR DEBUG ran_peer(GERAN-A:RI-SSN_PC:PC-1-23-4:SSN-BSSAP)[0x61200000aea0]{READY}: Received Event RAN_PEER_EV_MSG_DOWN_CO_INITIAL (ran_conn.c:119) 20190412040110451 DLSCCP DEBUG Received SCCP User Primitive (N-CONNECT.request) (sccp_scoc.c:1712) 20190412040110451 DLSCCP DEBUG SCCP-SCOC(2342)[0x61200001b820]{IDLE}: Allocated (fsm.c:423) 20190412040110451 DLSCCP DEBUG SCCP-SCOC(2342)[0x61200001b820]{IDLE}: Received Event N-CONNECT.req (sccp_scoc.c:1753) 20190412040110451 DLSS7 DEBUG sccp_scrc_rx_scoc_conn_msg: HDR=(CO:CORE,V=0,LEN=0), PART(T=Routing Context,L=4,D=00000000), PART(T=Protocol Class,L=4,D=00000002), PART(T=Source Reference,L=4,D=00000926), PART(T=Destination Address,L=20,D=0002000380020008000008bc80030008000000fe), PART(T=Sequence Control,L=4,D=00000000), PART(T=Source Address,L=20,D=0002000380020008000008b980030008000000fe), PART(T=Data,L=83,D=0051100b07010aa19181a5050a090086dc7f8e3f4115be12035058a605080062f224002a000005080009f1070046000104010c130a6014042f6500200240422c04080899100700001074507c06c0a80204a418) (sccp_scrc.c:398) 20190412040110451 DLSUA DEBUG sua_addr_parse_part(IEI=0x0103) (20) 00 02 00 03 80 02 00 08 00 00 08 bc 80 03 00 08 00 00 00 fe (sua.c:385) 20190412040110451 DLSUA DEBUG SUA IEI 0x0103 pos 4/20: subpart tag 0x8002, len 8 (sua.c:439) 20190412040110451 DLSUA DEBUG SUA IEI 0x0103 pos 12/20: subpart tag 0x8003, len 8 (sua.c:439) 20190412040110451 DLSUA DEBUG sua_addr_parse_part(IEI=0x0103) (20) 00 02 00 03 80 02 00 08 00 00 08 bc 80 03 00 08 00 00 00 fe (sua.c:385) 20190412040110451 DLSUA DEBUG SUA IEI 0x0103 pos 4/20: subpart tag 0x8002, len 8 (sua.c:439) 20190412040110452 DLSUA DEBUG SUA IEI 0x0103 pos 12/20: subpart tag 0x8003, len 8 (sua.c:439) 20190412040110452 DLSUA DEBUG sua_addr_parse_part(IEI=0x0102) (20) 00 02 00 03 80 02 00 08 00 00 08 b9 80 03 00 08 00 00 00 fe (sua.c:385) 20190412040110452 DLSUA DEBUG SUA IEI 0x0102 pos 4/20: subpart tag 0x8002, len 8 (sua.c:439) 20190412040110452 DLSUA DEBUG SUA IEI 0x0102 pos 12/20: subpart tag 0x8003, len 8 (sua.c:439) 20190412040110452 DLSS7 DEBUG m3ua_hmdc_rx_from_l2(): dpc=2236=1.23.4 not local, message is for routing (osmo_ss7_hmrt.c:278) 20190412040110452 DLSS7 DEBUG Found route for dpc=2236=1.23.4: pc=0=0.0.0 mask=0x0=0.0.0 via AS as-clnt-OsmoMSC-A-Iu proto=m3ua (osmo_ss7_hmrt.c:227) 20190412040110452 DLSS7 DEBUG rt->dest.as proto is M3UA for dpc=2236=1.23.4 (osmo_ss7_hmrt.c:233) 20190412040110452 DLSS7 DEBUG XUA_AS(as-clnt-OsmoMSC-A-Iu)[0x61200000a720]{AS_ACTIVE}: Received Event AS-TRANSFER.req (m3ua.c:507) 20190412040110452 DLSCCP DEBUG SCCP-SCOC(2342)[0x61200001b820]{IDLE}: State change to CONN_PEND_OUT (no timeout) (sccp_scoc.c:829) 20190412040110452 DLMGCP DEBUG mgw-endpoint(IMSI-901700000014705:GERAN-A-2342:NONE)[0x61200001ada0]{WAIT_MGW_RESPONSE}: rtpbridge/2@msc CI[0] RTP_TO_RAN CI=D1035D6D: CRCX: done (rtpbridge/2@msc:192.168.2.4:42008) (mgcp_client_endpoint_fsm.c:651) 20190412040110452 DLMGCP DEBUG mgw-endpoint(IMSI-901700000014705:GERAN-A-2342:NONE)[0x61200001ada0]{WAIT_MGW_RESPONSE}: rtpbridge/2@msc CI[1] RTP_TO_CN CI=A01EF28B: CRCX: done (rtpbridge/2@msc:192.168.2.4:42010) (mgcp_client_endpoint_fsm.c:651) 20190412040110452 DLMGCP DEBUG mgw-endpoint(IMSI-901700000014705:GERAN-A-2342:NONE)[0x61200001ada0]{WAIT_MGW_RESPONSE}: rtpbridge/2@msc CI in use: 2, waiting for response: 0 (mgcp_client_endpoint_fsm.c:669) 20190412040110452 DLMGCP DEBUG mgw-endpoint(IMSI-901700000014705:GERAN-A-2342:NONE)[0x61200001ada0]{WAIT_MGW_RESPONSE}: State change to IN_USE (no timeout) (mgcp_client_endpoint_fsm.c:680) 20190412040110452 DLMGCP DEBUG mgw-endpoint(IMSI-901700000014705:GERAN-A-2342:NONE)[0x61200001ada0]{IN_USE}: rtpbridge/2@msc CI[0] RTP_TO_RAN CI=D1035D6D: CRCX: done (rtpbridge/2@msc:192.168.2.4:42008) (mgcp_client_endpoint_fsm.c:651) 20190412040110452 DLMGCP DEBUG mgw-endpoint(IMSI-901700000014705:GERAN-A-2342:NONE)[0x61200001ada0]{IN_USE}: rtpbridge/2@msc CI[1] RTP_TO_CN CI=A01EF28B: CRCX: done (rtpbridge/2@msc:192.168.2.4:42010) (mgcp_client_endpoint_fsm.c:651) 20190412040110452 DLINP DEBUG [ CONNECTED] osmo_stream_cli_fd_cb(): connected write (stream.c:300) 20190412040110453 DLINP DEBUG [ CONNECTED] osmo_stream_cli_write(): sending data (stream.c:225) 20190412040110453 DLINP DEBUG [ CONNECTED] osmo_stream_cli_fd_cb(): connected write (stream.c:300) 20190412040110453 DLINP DEBUG [ CONNECTED] osmo_stream_cli_write(): sending data (stream.c:225) 20190412040110457 DLINP DEBUG [ CONNECTED] osmo_stream_cli_fd_cb(): connected read (stream.c:296) 20190412040110457 DLINP DEBUG [ CONNECTED] osmo_stream_cli_read(): message received (stream.c:210) 20190412040110457 DLSS7 DEBUG asp-asp-clnt-OsmoMSC-A-Iu: xua_cli_read_cb(): sctp_recvmsg() returned 48 (flags=0x80) (osmo_ss7.c:1609) 20190412040110457 DLM3UA DEBUG asp-asp-clnt-OsmoMSC-A-Iu: Received M3UA Message (XFER:DATA) (m3ua.c:722) 20190412040110457 DLM3UA DEBUG asp-asp-clnt-OsmoMSC-A-Iu: m3ua_rx_xfer (m3ua.c:541) 20190412040110457 DLM3UA DEBUG asp-asp-clnt-OsmoMSC-A-Iu: m3ua_rx_xfer(): M3UA data header: opc=2236=1.23.4 dpc=2233=1.23.1 (m3ua.c:580) 20190412040110457 DLSS7 DEBUG m3ua_hmdc_rx_from_l2(): found dpc=2233=1.23.1 as local (osmo_ss7_hmrt.c:274) 20190412040110457 DLSUA DEBUG IEI 259: Parsed Addr: RI=2,PC=2236,SSN=254 (sccp2sua.c:333) 20190412040110457 DLSS7 DEBUG scrc_rx_mtp_xfer_ind_xua: HDR=(CO:COAK,V=0,LEN=0), PART(T=Protocol Class,L=4,D=00000002), PART(T=Destination Reference,L=4,D=00000926), PART(T=Source Reference,L=4,D=00000000), PART(T=Destination Address,L=20,D=0002000380020008000008bc80030008000000fe) (sccp_scrc.c:450) [this is where above, the "Cannot find" error occurs] 20190412040110457 DLSCCP DEBUG Received CO:COAK for local reference 2342 (sccp_scoc.c:1645) 20190412040110457 DLSCCP DEBUG SCCP-SCOC(2342)[0x61200001b820]{CONN_PEND_OUT}: Received Event RCOC-CONNECT_CONFIRM.ind (sccp_scoc.c:1678) 20190412040110457 DLSCCP DEBUG SCCP-SCOC(2342)[0x61200001b820]{CONN_PEND_OUT}: State change to ACTIVE (no timeout) (sccp_scoc.c:980) 20190412040110458 DLSCCP DEBUG Delivering N-CONNECT.confirm to SCCP User 'OsmoMSC-A' (sccp_user.c:156) 20190412040110458 DBSSAP DEBUG (GERAN-A) sccp_ran_sap_up(N-CONNECT.confirm) (sccp_ran.c:143) 20190412040110464 DLINP DEBUG [ CONNECTED] osmo_stream_cli_fd_cb(): connected read (stream.c:296) 20190412040110464 DLINP DEBUG [ CONNECTED] osmo_stream_cli_read(): message received (stream.c:210) 20190412040110464 DLSS7 DEBUG asp-asp-clnt-OsmoMSC-A-Iu: xua_cli_read_cb(): sctp_recvmsg() returned 76 (flags=0x80) (osmo_ss7.c:1609) 20190412040110464 DLM3UA DEBUG asp-asp-clnt-OsmoMSC-A-Iu: Received M3UA Message (XFER:DATA) (m3ua.c:722) 20190412040110464 DLM3UA DEBUG asp-asp-clnt-OsmoMSC-A-Iu: m3ua_rx_xfer (m3ua.c:541) 20190412040110464 DLM3UA DEBUG asp-asp-clnt-OsmoMSC-A-Iu: m3ua_rx_xfer(): M3UA data header: opc=2236=1.23.4 dpc=2233=1.23.1 (m3ua.c:580) 20190412040110464 DLSS7 DEBUG m3ua_hmdc_rx_from_l2(): found dpc=2233=1.23.1 as local (osmo_ss7_hmrt.c:274) 20190412040110464 DLSS7 DEBUG scrc_rx_mtp_xfer_ind_xua: HDR=(CO:CODT,V=0,LEN=0), PART(T=Destination Reference,L=4,D=00000926), PART(T=Segmentation,L=4,D=00000000), PART(T=Data,L=34,D=002012170f062bc1660b2366010763410302280821982c0440217c06c0a8020359e4) (sccp_scrc.c:450) 20190412040110464 DLSCCP DEBUG Received CO:CODT for local reference 2342 (sccp_scoc.c:1645) 20190412040110464 DLSCCP DEBUG SCCP-SCOC(2342)[0x61200001b820]{ACTIVE}: Received Event RCOC-DT1.ind (sccp_scoc.c:1678) 20190412040110464 DLSCCP DEBUG Delivering N-DATA.indication to SCCP User 'OsmoMSC-A' (sccp_user.c:156) 20190412040110464 DBSSAP DEBUG (GERAN-A-2342) sccp_ran_sap_up(N-DATA.indication) (sccp_ran.c:106) 20190412040110464 DRR DEBUG ran_peer(GERAN-A:RI-SSN_PC:PC-1-23-4:SSN-BSSAP)[0x61200000aea0]{READY}: Received Event RAN_PEER_EV_MSG_UP_CO (ran_peer.c:529) 20190412040110464 DMSC DEBUG msc_t(IMSI-901700000014705:GERAN-A-2342:NONE)[0x61200001a920]{WAIT_HO_REQUEST_ACK}: Received Event MSC_EV_FROM_RAN_UP_L2 (ran_peer.c:346) 20190412040110464 DBSSAP DEBUG msc_t(IMSI-901700000014705:GERAN-A-2342:NONE)[0x61200001a920]{WAIT_HO_REQUEST_ACK}: NAS decode: BSSMAP: Rx BSSMAP DT1 HANDOVER REQ ACK (nas_a.c:779) I can only suspect that somewhere the value range is stripped?? I have pcaps for these two if anyone is interested. It was tested with current libosmo-sccp master, as well as with the last commit reverted ("sccp_scoc: conn_create{,_id}() user arg, not inst"), identical results. ~N

2 1

RFC: FSM instance IDs / log context / log filters
by Neels Hofmeyr 12 Apr '19

12 Apr '19

This is an idea about logging context, the logging filter and FSM instances. The idea is to make logging context a first-class citizen of osmo_fsm_inst and of LOGP(), in order to get cleaner FSM ids, better configurable logging and a more universal and reliable approach to logging filters. At events like 35c3 I want to, and hence any production operator wants to have useful filters for logging. The attempt with this RFC is to get this in an elegant way that also improves current logging context and saves FSM IDs. == Status quo == - Log filters: Since a long time ago, we have a logging filter mechanism which requires setting a global "context pointer" to some object, for every code path. It is not trivial to use and we mostly neglected using and testing it, so it doesn't work well in practice. See enum log_filter_index, enum log_ctx_index, log_set_context() in libosmocore and the filter_fn() in msc_main.c as an example. - Logging context: For a long time, we added logging context to each and every LOGP() line, like: LOGP(DMSC, LOGL_DEBUG, "(%s %s %d %d) Actual message", subscr->ctx1, osmo_foo_name(subscr->ctx2), trans->ctx3, another->ctx); Since the osmo_fsm_inst showed up, I have more and more used the FSM instance's id as logging context: #define LOG_MY_OBJ(my_obj, loglevel, fmt, args...) \ LOGPFSML(my_obj->fi, loglevel, fmt, ##args) my_obj_update_id(my_obj) { osmo_fsm_inst_update_id_f(my_obj->fi, "%s-%s-%d-%d", my_obj->ctx1, osmo_foo_name(my_obj->ctx2), my_obj->ctx3, my_obj->ctx); } stuff() { LOG_MY_OBJ(my_obj, LOGL_DEBUG, "Actual message"); } The advantages are obvious: - less time spent composing log message context when developing code. - context string is composed only once and re-used, less cpu cycles used to compose. - it is now made hard to forget adding useful log context. But this also has disadvantages: - Long lines Since I want to be able to trace logging output by various items, my logging context has often grown to a size that makes the log uncomfortable to read unless the terminal is really wide. For example, in osmo-msc, the context now often looks like this: DMSC DEBUG msc_a(IMSI-901700000014705:MSISDN-1001:TMSI-0x8D91D71B:GERAN-A-0:LU)[0x61200000b620]{MSC_A_ST_AUTH_CIPH}: Received Event MSC_A_EV_AUTHENTICATED (vlr_lu_fsm.c:741) It includes the IMSI, MSISDN, TMSI, the RAN conn info and the complete-l3 type. An extreme example is DCC DEBUG rtp_stream(IMSI-901700000014705:MSISDN-1001:TMSI-0x8D91D71B:GERAN-A-1:CM_SERVICE_REQ:trans-8:call-2147483649:RTP_TO_RAN:CI-BBBD5102:remote-port-not-sent:codec-not-sent:local-192-168-2-4-42000:remote-192-168-2-3-23004)[0x612000015e20]{ESTABLISHING}: Committing: Tx MDCX to update the MGW: updating remote-RTP-IP-port codec (rtp_stream.c:330) WTF. But of course, for an RTP stream, it is interesting to see what subscriber it is for, but also what callref and CC transaction, also the MGW's endpoint CI, whether it is to RAN or CN, and which RTP address and ports are involved. Now, a log line like this is pretty much guaranteed to be truncated in the display of gsmtap_log in wireshark. Very irritating. We would have to remove select items of logging context from the FSM instance ID to strike a good balance of length and usefulness. Each time we tweak it, all the logging output in test programs changes ... ugh. - Special characters Since an FSM instance can only have a limited set of characters for id, we can't add IP addresses as 1.2.3.4, but need to use 1-2-3-4. And so on and so on. - ID obfuscation If I want to address a specific osmo_fsm_inst on the CTRL interface, I need to pass the entire long id. I don't know of anyone using this in practice, but abusing the id as logging context makes this really hard. I think this is the worst side effect of me adding elaborate logging context to FSM instance ids. - log reading Various lengths of logging context make the log line's actual message show on various "indentation" levels. Instead I would like to be able to configure the log context part of a log message to show in the *end* of a log line instead of at the start, so that the short messages like "New conn" or "Rx Location Updating Request" show lined up one below each other; or alternatively introduce a common chunk of indentation spacing to line things up. That's currently not possible if both the log context and log message are just one arbitrary string fed to LOGP(). == IDEA == Reflecting on this, I formed the idea of moving logging context to a separate array of strings for each object. The most common usage would be to tie this array of context information to an osmo_fsm_inst. I'm not sure how far we could take this before we start producing too much load. It would of course be the aim to find a good balance of effort and usefulness, or think of nifty simplifications or optimizations. It's just a vague idea, but I guess it would look something like this in pseudo code: my_obj_update_id(my_obj) { set_log_context(my_obj->logctx, "IMSI", my_obj->imsi); set_log_context(my_obj->logctx, "MSISDN", my_obj->vlr->msisdn); set_log_context(my_obj->logctx, "RTP-local", osmo_sockaddr_str_name(my_obj->rtp_stream->rtp_local)); ... } set_log_context(ctx, name, val) { slot = log_context_find_or_create_slot(ctx, name); osmo_talloc_replace_str(ctx, &ctx[slot], val); /* or osmo_strlcpy() to a fixed-size char[]? */ } #define LOG_MY_OBJ(my_obj, level, fmt, args...) \ LOGP_CTX(DMSC, my_obj->ctx, level, fmt, ##args) use() { LOG_MY_OBJ(my_obj, LOGL_DEBUG, "Actual message"); /* i.e. most current log macros would be invoked in the same way */ } And then allow logging configuration like % hide all logging context in log output, except MSISDN and RTP-local: > logging print context none > logging print context MSISDN > logging print context RTP-local % show only logging lines where this exact IMSI is part of the context > logging filter-rule IMSI == 901700000014705 In gsmtap_log packets, we could add a listing of key-value items for log context, hopefully allowing to show / hide each individual context by name in a wireshark UI. Instead of repeating context like the IMSI in various FSM instance IDs, the logging context could be made chainable, i.e. internally, we could reference one logging context from another. For example, the rtp_stream FSM instance would only add the RTP address to its logging context, and then "upwards" reference the call_leg FSM's context. That would add the callref, and "upwards" reference the subscriber's context, which adds IMSI, MSISDN and RAN conn info to the rtp_stream logging context. (We might be able to do this implicitly from osmo_fsm_inst parent/child relations that we already have.) It might even be thinkable to allow traversing all across related context info, so that filtering for a given RTP port could cause even high level objects (like the vlr_subscr) to search through all childrens' log ctx information to see whether anyone defines this RTP-local context, thus show all logging for a conn that currently uses this RTP port. Premature optimization... To run each log line through a set of filters would potentially take up a lot of CPU cycles. For that I also have an idea to resolve the decision to log or not to log only once per target object and cache that result. For example, when I change the logging filter to pick a specific MSISDN, an internal token is incremented. If I hit an object's logging, I decide whether it passes the logging filter, and store the outcome as true/false with the current filter's token value in the object. Next time I hit that object and the token is still the same, the filter must also have the same result, and I can just use the stored true/false. If the user changes the filter, the token increments and on next logging, each object notices that the filter needs to be re-run in full. If the object's context info changes, reset the object's stored token to also rerun the filter on next logging. This is quite vague, especially not clear whether each object with logging context would have to store tokens for each and every log target separately... Premature optimization: require the log context names to be compile-time string literals, so that we can just compare name_a == name_b without invoking strcmp(). A general advantage is that we would always see the relevant context for logging, and we would immediately notice bugs in the context, thus we would always ensure reliable logging filters "for free". An easy way out of implementing log filters in osmocom would be to simply not have them, just provide well-defined log context in gsmtap_log, in a way that wireshark can parse. Users can then use wireshark rules to filter the log. The disadvantage here is that we would have to first compose all logging, instead of nicely skipping entire log lines before they are even composed. So, this is so far just an idea I would like to run by you. Even if the solutions might still be unworthy, I think it is worthwhile to be aware of the implications I highlighted above. ~N

2 2

LimeNet Micro as GSM BTS
by Rafael Diniz 12 Apr '19

12 Apr '19

1 0

2026

2025

2024

2023

2022

2021

2020

2019

2018

2017

2016

2015

2014

2013

2012

2011

2010

2009

OpenBSC April 2019