search

herlesupreeth / docker_open5gs

Docker files to run open5gs + IMS + eNB + gNB + NR-UE in a docker
BSD 2-Clause "Simplified" License
319 stars 177 forks source link

osmohlr kicks me off my network #74

Closed nllz closed 1 year ago

nllz commented 2 years ago

Thanks a lot for this excellent work. I am running docker_open5gs on Ubuntu 22.04 with a B210.

Registration with my programmable OSMOCOM simcard that is registered in the HSS database runs fine, until I run into the osmohlr:

mme | 03/12 19:13:58.292: [mme] INFO: InitialUEMessage (../src/mme/s1ap-handler.c:223) mme | 03/12 19:13:58.292: [mme] INFO: [Added] Number of eNB-UEs is now 1 (../src/mme/mme-context.c:3276) mme | 03/12 19:13:58.292: [mme] INFO: ENB_UE_S1AP_ID[18] MME_UE_S1AP_ID[18] TAC[1] CellID[0x19b01] (../src/mme/s1ap-handler.c:363) mme | 03/12 19:13:58.292: [mme] INFO: [204420000000002] Unknown UE by IMSI (../src/mme/mme-context.c:2318) mme | 03/12 19:13:58.293: [mme] INFO: [Added] Number of MME-UEs is now 1 (../src/mme/mme-context.c:2151) mme | 03/12 19:13:58.293: [emm] WARNING: [] Attach request (../src/mme/emm-sm.c:203) mme | 03/12 19:13:58.293: [emm] INFO: IMSI[204420000000002] (../src/mme/emm-handler.c:188) mme | 03/12 19:13:58.375: [mme] INFO: [Added] Number of MME-Sessions is now 1 (../src/mme/mme-context.c:3288) sgwc | 03/12 19:13:58.412: [sgwc] INFO: [Removed] Number of SGWC-UEs is now 0 (../src/sgwc/context.c:228) sgwc | 03/12 19:13:58.412: [sgwc] INFO: [Added] Number of SGWC-UEs is now 1 (../src/sgwc/context.c:210) sgwc | 03/12 19:13:58.412: [sgwc] INFO: [Added] Number of SGWC-Sessions is now 1 (../src/sgwc/context.c:863) sgwu | 03/12 19:13:58.413: [sgwu] INFO: UE F-SEID[CP:0x8 UP:0x8] (../src/sgwu/context.c:144) sgwu | 03/12 19:13:58.413: [sgwu] INFO: [Added] Number of SGWU-Sessions is now 1 (../src/sgwu/context.c:149) smf | 03/12 19:13:58.413: [smf] INFO: [Added] Number of SMF-UEs is now 1 (../src/smf/context.c:819) smf | 03/12 19:13:58.413: [smf] INFO: [Added] Number of SMF-Sessions is now 1 (../src/smf/context.c:2610) smf | 03/12 19:13:58.413: [smf] INFO: UE IMSI[204420000000002] APN[internet] IPv4[172.22.0.100] IPv6[2001:230:cafe:8::9] (../src/smf/s5c-handler.c:219) upf | 03/12 19:13:58.416: [upf] INFO: [Added] Number of UPF-Sessions is now 1 (../src/upf/context.c:160) upf | 03/12 19:13:58.416: [upf] INFO: UE F-SEID[CP:0x8 UP:0x8] APN[internet] PDN-Type[3] IPv4[172.22.0.100] IPv6[2001:230:cafe:8::9] (../src/upf/context.c:361) osmohlr | 20220312191358417 DLINP <000a> input/ipa.c:412 connected read/write osmohlr | 20220312191358417 DLINP <000a> input/ipa.c:368 172.22.0.31:34311 message received osmomsc | <000f> gsm_04_08.c:1524 SUBSCR(IMSI-204420000000002:TMSInew-0x18D75978) VLR: update for IMSI=204420000000002 (MSISDN=) (NO CONN!) osmohlr | 20220312191358417 DLGSUP <0012> gsup_req.c:138 GSUP 8: MSC-00-00-00-00-00-00: IMSI-204420000000002 OSMO_GSUP_MSGT_UPDATE_LOCATION_REQUEST: new request: {Subscriber-Management OSMO_GSUP_MSGT_UPDATE_LOCATION_REQUEST: imsi="204420000000002" cn_domain=CS} mme | 03/12 19:13:58.417: [mme] WARNING: [SGSAP] LOCATION-UPDATE-REJECT (../src/mme/sgsap-handler.c:136) osmohlr | 20220312191358417 DLU <0006> fsm.c:461 lu(204420000000002)[0x55d5519ad300]{UNVALIDATED}: Allocated osmohlr | 20220312191358417 DLGSUP <0012> lu_fsm.c:139 GSUP 8: MSC-00-00-00-00-00-00: IMSI-204420000000002 OSMO_GSUP_MSGT_UPDATE_LOCATION_REQUEST: IMSI unknown in HLR: Subscriber does not exist osmohlr | 20220312191358417 DLGSUP <0012> gsup_req.c:274 GSUP 8: MSC-00-00-00-00-00-00: IMSI-204420000000002 OSMO_GSUP_MSGT_UPDATE_LOCATION_REQUEST: Tx response: {Subscriber-Management OSMO_GSUP_MSGT_UPDATE_LOCATION_ERROR: imsi="204420000000002" cause=IMSI unknown in HLR} osmohlr | 20220312191358417 DLGSUP <0012> gsup_req.c:171 GSUP 8: MSC-00-00-00-00-00-00: IMSI-204420000000002 OSMO_GSUP_MSGT_UPDATE_LOCATION_REQUEST: free osmohlr | 20220312191358417 DLU <0006> lu_fsm.c:139 lu(CS:IMSI-204420000000002)[0x55d5519ad300]{UNVALIDATED}: Terminating (cause = OSMO_FSM_TERM_REGULAR) osmohlr | 20220312191358417 DLU <0006> lu_fsm.c:139 lu(CS:IMSI-204420000000002)[0x55d5519ad300]{UNVALIDATED}: Freeing instance osmohlr | 20220312191358417 DLU <0006> fsm.c:573 lu(CS:IMSI-204420000000002)[0x55d5519ad300]{UNVALIDATED}: Deallocated osmohlr | 20220312191358417 DLINP <000a> input/ipa.c:412 connected read/write osmohlr | 20220312191358417 DLINP <000a> input/ipa.c:392 172.22.0.31:34311 sending data osmohlr | 20220312191358417 DLINP <000a> input/ipa.c:412 connected read/write osmohlr | 20220312191358417 DLINP <000a> input/ipa.c:392 172.22.0.31:34311 sending data upf | 03/12 19:13:58.420: [upf] INFO: [Removed] Number of UPF-sessions is now 0 (../src/upf/context.c:190) smf | 03/12 19:13:58.420: [smf] INFO: Removed Session: UE IMSI:[204420000000002] DNN:[internet:0] IPv4:[172.22.0.100] IPv6:[2001:230:cafe:8::9] (../src/smf/context.c:1407) smf | 03/12 19:13:58.420: [smf] INFO: [Removed] Number of SMF-Sessions is now 0 (../src/smf/context.c:2616) sgwu | 03/12 19:13:58.420: [sgwu] INFO: [Removed] Number of SGWU-sessions is now 0 (../src/sgwu/context.c:169) mme | 03/12 19:13:58.420: [mme] INFO: [Removed] Number of MME-Sessions is now 0 (../src/mme/mme-context.c:3294) sgwc | 03/12 19:13:58.420: [sgwc] INFO: [Removed] Number of SGWC-Sessions is now 0 (../src/sgwc/context.c:869) smf | 03/12 19:13:58.420: [smf] INFO: [Removed] Number of SMF-UEs is now 0 (../src/smf/context.c:844) mme | 03/12 19:13:58.421: [mme] INFO: UE Context Release [Action:3] (../src/mme/s1ap-handler.c:1448) mme | 03/12 19:13:58.421: [mme] INFO: ENB_UE_S1AP_ID[18] MME_UE_S1AP_ID[18] (../src/mme/s1ap-handler.c:1449) mme | 03/12 19:13:58.421: [mme] INFO: IMSI[204420000000002] (../src/mme/s1ap-handler.c:1452) mme | 03/12 19:13:58.421: [mme] INFO: [Removed] Number of eNB-UEs is now 0 (../src/mme/mme-context.c:3282) mme | 03/12 19:13:58.421: [mme] INFO: [Removed] Number of MME-UEs is now 0 (../src/mme/mme-context.c:2213)

I subsequently logged into the osmohlr docker as root and added a subscriber to the osmohlr database, but to no avail:

osmohlr | 20220312192911382 DLINP <000a> input/ipa.c:412 connected read/write osmohlr | 20220312192911382 DLINP <000a> input/ipa.c:368 172.22.0.31:34311 message received osmohlr | 20220312192911382 DLGSUP <0012> gsup_req.c:138 GSUP 20: MSC-00-00-00-00-00-00: IMSI-204420000000002 OSMO_GSUP_MSGT_UPDATE_LOCATION_REQUEST: new request: {Subscriber-Management OSMO_GSUP_MSGT_UPDATE_LOCATION_REQUEST: imsi="204420000000002" cn_domain=CS} osmohlr | 20220312192911382 DLU <0006> fsm.c:461 lu(204420000000002)[0x55d5519ad300]{UNVALIDATED}: Allocated osmohlr | 20220312192911382 DLGSUP <0012> lu_fsm.c:172 GSUP 20: MSC-00-00-00-00-00-00: IMSI-204420000000002 OSMO_GSUP_MSGT_UPDATE_LOCATION_REQUEST: storing VLR number = MSC-00-00-00-00-00-00 osmohlr | 20220312192911386 DLU <0006> lu_fsm.c:200 lu(CS:IMSI-204420000000002)[0x55d5519ad300]{UNVALIDATED}: state_chg to WAIT_INSERT_DATA_RESULT osmohlr | 20220312192911386 DLGSUP <0012> lu_fsm.c:255 GSUP 20: MSC-00-00-00-00-00-00: IMSI-204420000000002 OSMO_GSUP_MSGT_UPDATE_LOCATION_REQUEST: Tx response: {Subscriber-Management OSMO_GSUP_MSGT_INSERT_DATA_REQUEST: imsi="204420000000002" cn_domain=CS} osmohlr | 20220312192911386 DLINP <000a> input/ipa.c:412 connected read/write osmohlr | 20220312192911386 DLINP <000a> input/ipa.c:392 172.22.0.31:34311 sending data osmomsc | <000f> gsm_04_08.c:1524 SUBSCR(IMSI-204420000000002:TMSInew-0x9462198B) VLR: update for IMSI=204420000000002 (MSISDN=) (NO CONN!) osmohlr | 20220312192911386 DLINP <000a> input/ipa.c:412 connected read/write osmohlr | 20220312192911386 DLINP <000a> input/ipa.c:392 172.22.0.31:34311 sending data osmohlr | 20220312192911386 DLINP <000a> input/ipa.c:412 connected read/write osmohlr | 20220312192911387 DLINP <000a> input/ipa.c:368 172.22.0.31:34311 message received osmohlr | 20220312192911387 DLGSUP <0012> gsup_req.c:138 GSUP 21: MSC-00-00-00-00-00-00: IMSI-204420000000002 OSMO_GSUP_MSGT_INSERT_DATA_RESULT: new request: {Subscriber-Management OSMO_GSUP_MSGT_INSERT_DATA_RESULT: imsi="204420000000002"} osmohlr | 20220312192911387 DLU <0006> lu_fsm.c:212 lu(CS:IMSI-204420000000002)[0x55d5519ad300]{WAIT_INSERT_DATA_RESULT}: Received Event LU_EV_RX_GSUP osmohlr | 20220312192911387 DLGSUP <0012> gsup_req.c:171 GSUP 21: MSC-00-00-00-00-00-00: IMSI-204420000000002 OSMO_GSUP_MSGT_INSERT_DATA_RESULT: free osmohlr | 20220312192911387 DLGSUP <0012> lu_fsm.c:91 GSUP 20: MSC-00-00-00-00-00-00: IMSI-204420000000002 OSMO_GSUP_MSGT_UPDATE_LOCATION_REQUEST: Tx response: {Subscriber-Management OSMO_GSUP_MSGT_UPDATE_LOCATION_RESULT: imsi="204420000000002"} osmohlr | 20220312192911387 DLGSUP <0012> gsup_req.c:171 GSUP 20: MSC-00-00-00-00-00-00: IMSI-204420000000002 OSMO_GSUP_MSGT_UPDATE_LOCATION_REQUEST: free osmohlr | 20220312192911387 DLU <0006> lu_fsm.c:93 lu(CS:IMSI-204420000000002)[0x55d5519ad300]{WAIT_INSERT_DATA_RESULT}: Terminating (cause = OSMO_FSM_TERM_REGULAR) osmohlr | 20220312192911387 DLU <0006> lu_fsm.c:93 lu(CS:IMSI-204420000000002)[0x55d5519ad300]{WAIT_INSERT_DATA_RESULT}: Freeing instance osmohlr | 20220312192911387 DLU <0006> fsm.c:573 lu(CS:IMSI-204420000000002)[0x55d5519ad300]{WAIT_INSERT_DATA_RESULT}: Deallocated osmohlr | 20220312192911387 DLINP <000a> input/ipa.c:412 connected read/write osmohlr | 20220312192911387 DLINP <000a> input/ipa.c:392 172.22.0.31:34311 sending data osmohlr | 20220312192911387 DLINP <000a> input/ipa.c:412 connected read/write osmohlr | 20220312192911387 DLINP <000a> input/ipa.c:392 172.22.0.31:34311 sending data mme | 03/12 19:29:11.638: [mme] INFO: UE Context Release [Action:2] (../src/mme/s1ap-handler.c:1448) mme | 03/12 19:29:11.638: [mme] INFO: ENB_UE_S1AP_ID[26] MME_UE_S1AP_ID[26] (../src/mme/s1ap-handler.c:1449) mme | 03/12 19:29:11.638: [mme] INFO: IMSI[204420000000002] (../src/mme/s1ap-handler.c:1452) mme | 03/12 19:29:11.638: [mme] INFO: [Removed] Number of eNB-UEs is now 0 (../src/mme/mme-context.c:3282)

I then also tried to add this to osmhlr.cfg:

hlr subscriber-create-on-demand 5 cs+ps

but that did not really work either:

osmohlr | 20220312194405838 DLINP <000a> input/ipa.c:412 connected read/write osmohlr | 20220312194405838 DLINP <000a> input/ipa.c:368 172.22.0.31:40037 message received osmohlr | 20220312194405838 DLGSUP <0012> gsup_req.c:138 GSUP 9: MSC-00-00-00-00-00-00: IMSI-204420000000002 OSMO_GSUP_MSGT_UPDATE_LOCATION_REQUEST: new request: {Subscriber-Management OSMO_GSUP_MSGT_UPDATE_LOCATION_REQUEST: imsi="204420000000002" cn_domain=CS} osmohlr | 20220312194405838 DLU <0006> fsm.c:461 lu(204420000000002)[0x55898cd122f0]{UNVALIDATED}: Allocated osmohlr | 20220312194405838 DLGSUP <0012> lu_fsm.c:172 GSUP 9: MSC-00-00-00-00-00-00: IMSI-204420000000002 OSMO_GSUP_MSGT_UPDATE_LOCATION_REQUEST: storing VLR number = MSC-00-00-00-00-00-00 osmohlr | 20220312194405847 DLU <0006> lu_fsm.c:200 lu(CS:IMSI-204420000000002)[0x55898cd122f0]{UNVALIDATED}: state_chg to WAIT_INSERT_DATA_RESULT osmohlr | 20220312194405847 DLGSUP <0012> lu_fsm.c:255 GSUP 9: MSC-00-00-00-00-00-00: IMSI-204420000000002 OSMO_GSUP_MSGT_UPDATE_LOCATION_REQUEST: Tx response: {Subscriber-Management OSMO_GSUP_MSGT_INSERT_DATA_REQUEST: imsi="204420000000002" cn_domain=CS} osmohlr | 20220312194405847 DLINP <000a> input/ipa.c:412 connected read/write osmohlr | 20220312194405847 DLINP <000a> input/ipa.c:392 172.22.0.31:40037 sending data osmohlr | 20220312194405847 DLINP <000a> input/ipa.c:412 connected read/write osmohlr | 20220312194405847 DLINP <000a> input/ipa.c:392 172.22.0.31:40037 sending data osmomsc | <000f> gsm_04_08.c:1524 SUBSCR(IMSI-204420000000002:TMSInew-0x388C30A6) VLR: update for IMSI=204420000000002 (MSISDN=) (NO CONN!) osmohlr | 20220312194405848 DLINP <000a> input/ipa.c:412 connected read/write osmohlr | 20220312194405848 DLINP <000a> input/ipa.c:368 172.22.0.31:40037 message received osmohlr | 20220312194405848 DLGSUP <0012> gsup_req.c:138 GSUP 10: MSC-00-00-00-00-00-00: IMSI-204420000000002 OSMO_GSUP_MSGT_INSERT_DATA_RESULT: new request: {Subscriber-Management OSMO_GSUP_MSGT_INSERT_DATA_RESULT: imsi="204420000000002"} osmohlr | 20220312194405848 DLU <0006> lu_fsm.c:212 lu(CS:IMSI-204420000000002)[0x55898cd122f0]{WAIT_INSERT_DATA_RESULT}: Received Event LU_EV_RX_GSUP osmohlr | 20220312194405848 DLGSUP <0012> gsup_req.c:171 GSUP 10: MSC-00-00-00-00-00-00: IMSI-204420000000002 OSMO_GSUP_MSGT_INSERT_DATA_RESULT: free osmohlr | 20220312194405848 DLGSUP <0012> lu_fsm.c:91 GSUP 9: MSC-00-00-00-00-00-00: IMSI-204420000000002 OSMO_GSUP_MSGT_UPDATE_LOCATION_REQUEST: Tx response: {Subscriber-Management OSMO_GSUP_MSGT_UPDATE_LOCATION_RESULT: imsi="204420000000002"} osmohlr | 20220312194405848 DLGSUP <0012> gsup_req.c:171 GSUP 9: MSC-00-00-00-00-00-00: IMSI-204420000000002 OSMO_GSUP_MSGT_UPDATE_LOCATION_REQUEST: free osmohlr | 20220312194405848 DLU <0006> lu_fsm.c:93 lu(CS:IMSI-204420000000002)[0x55898cd122f0]{WAIT_INSERT_DATA_RESULT}: Terminating (cause = OSMO_FSM_TERM_REGULAR) osmohlr | 20220312194405848 DLU <0006> lu_fsm.c:93 lu(CS:IMSI-204420000000002)[0x55898cd122f0]{WAIT_INSERT_DATA_RESULT}: Freeing instance osmohlr | 20220312194405848 DLU <0006> fsm.c:573 lu(CS:IMSI-204420000000002)[0x55898cd122f0]{WAIT_INSERT_DATA_RESULT}: Deallocated osmohlr | 20220312194405848 DLINP <000a> input/ipa.c:412 connected read/write osmohlr | 20220312194405848 DLINP <000a> input/ipa.c:392 172.22.0.31:40037 sending data osmohlr | 20220312194405848 DLINP <000a> input/ipa.c:412 connected read/write osmohlr | 20220312194405848 DLINP <000a> input/ipa.c:392 172.22.0.31:40037 sending data mme | 03/12 19:44:06.118: [mme] INFO: UE Context Release [Action:2] (../src/mme/s1ap-handler.c:1448) mme | 03/12 19:44:06.118: [mme] INFO: ENB_UE_S1AP_ID[33] MME_UE_S1AP_ID[33] (../src/mme/s1ap-handler.c:1449) mme | 03/12 19:44:06.118: [mme] INFO: IMSI[204420000000002] (../src/mme/s1ap-handler.c:1452) mme | 03/12 19:44:06.118: [mme] INFO: [Removed] Number of eNB-UEs is now 0 (../src/mme/mme-context.c:3282)

all suggestions are very welcome.

nllz commented 2 years ago

and the logfiles:

ausf.log nssf.log amf.log bsf.log nrf.log pcf.log udm.log udr.log pcrf.log hss.log sgwc.log sgwu.log smf.log upf.log mme.log

herlesupreeth commented 2 years ago

I have added a new feature of sending sms over sgs interface and it requires adding insi and corresponding msisdn in osmohlr

nllz commented 2 years ago

Have you documented how and where this should be done? I could not find it in the readme. Thanks in advance.

s5uishida commented 2 years ago

Hi @nllz

Please login to the osmohlr container and register the IMSI and MSISDN by referring to the following.

6.1 Example: Add/Update/Delete Subscriber via VTY https://downloads.osmocom.org/docs/latest/osmohlr-usermanual.pdf

If you would like, please also refer to the following little note I wrote.

https://github.com/s5uishida/docker_open5gs_volte_sms_config

herlesupreeth commented 2 years ago

Thanks @s5uishida

The solution for above issue is the following section:

https://github.com/s5uishida/docker_open5gs_volte_sms_config#register-the-imsi-and-msisdn-with-osmohlr

Then, dettach the UE from network and re-attach

nllz commented 2 years ago

Thanks @herlesupreeth and @s5uishida .

I went ahead and did the following as described:

gagarin@sputnik ~  docker exec -it osmohlr /bin/bash
root@bf8c589a6971:/# telnet localhost 4258
Trying 127.0.0.1...
Connected to localhost.
Escape character is '^]'.
Welcome to the OsmoHLR VTY interface

Copyright (C) 2016, 2017 by Harald Welte, sysmocom s.f.m.c. GmbH
License AGPLv3+: GNU AGPL version 3 or later <http://gnu.org/licenses/agpl-3.0.html>
This is free software: you are free to change and redistribute it.
There is NO WARRANTY, to the extent permitted by law.
OsmoHLR> enable
OsmoHLR# subscriber imsi 204420000000001 create
% Created subscriber 204420000000001
    ID: 2
    IMSI: 204420000000001
    MSISDN: none
OsmoHLR# subscriber imsi 204420000000001 update msisdn 0001
% Updated subscriber IMSI='204420000000001' to MSISDN='0001'
OsmoHLR# show subscribers all
ID     MSISDN        IMSI              IMEI              NAM
-----  ------------  ----------------  ----------------  -----
1      none          204420000000002    -------------    CSPS  
2      0001          204420000000001    -------------    CSPS  
 Subscribers Shown: 2
OsmoHLR# subscriber imsi 204420000000002 create
% Error (rc=-5): cannot create subscriber for IMSI = 204420000000002
OsmoHLR# subscriber imsi 204420000000002 update msisdn 0002
% Updated subscriber IMSI='204420000000002' to MSISDN='0002'
OsmoHLR# show subscribers all                              
ID     MSISDN        IMSI              IMEI              NAM
-----  ------------  ----------------  ----------------  -----
1      0002          204420000000002    -------------    CSPS  
2      0001          204420000000001    -------------    CSPS  
 Subscribers Shown: 2

But when I ran the stack I again got kicked off because of osmohlr:

mme          | 11/01 16:15:39.182: [mme] INFO: [Added] Number of MME-Sessions is now 1 (../src/mme/mme-context.c:3288)
sgwc         | 11/01 16:15:39.220: [sgwc] INFO: [Removed] Number of SGWC-UEs is now 0 (../src/sgwc/context.c:228)
sgwc         | 11/01 16:15:39.220: [sgwc] INFO: [Added] Number of SGWC-UEs is now 1 (../src/sgwc/context.c:210)
sgwc         | 11/01 16:15:39.220: [sgwc] INFO: [Added] Number of SGWC-Sessions is now 1 (../src/sgwc/context.c:863)
sgwu         | 11/01 16:15:39.220: [sgwu] INFO: UE F-SEID[CP:0x5 UP:0x5] (../src/sgwu/context.c:144)
sgwu         | 11/01 16:15:39.220: [sgwu] INFO: [Added] Number of SGWU-Sessions is now 1 (../src/sgwu/context.c:149)
smf          | 11/01 16:15:39.220: [smf] INFO: [Added] Number of SMF-UEs is now 1 (../src/smf/context.c:819)
smf          | 11/01 16:15:39.220: [smf] INFO: [Added] Number of SMF-Sessions is now 1 (../src/smf/context.c:2610)
smf          | 11/01 16:15:39.220: [smf] INFO: UE IMSI[204420000000002] APN[internet] IPv4[172.22.0.100] IPv6[2001:230:cafe:5::6] (../src/smf/s5c-handler.c:219)
upf          | 11/01 16:15:39.223: [upf] INFO: [Added] Number of UPF-Sessions is now 1 (../src/upf/context.c:160)
upf          | 11/01 16:15:39.223: [upf] INFO: UE F-SEID[CP:0x5 UP:0x5] APN[internet] PDN-Type[3] IPv4[172.22.0.100] IPv6[2001:230:cafe:5::6] (../src/upf/context.c:361)
osmomsc      | <000f> gsm_04_08.c:1524 SUBSCR(IMSI-204420000000002:MSISDN-0002:TMSInew-0x0C5A95A8) VLR: update for IMSI=204420000000002 (MSISDN=0002) (NO CONN!)
osmohlr      | 20221101161539224 DLINP <000a> input/ipa.c:412 connected read/write
osmohlr      | 20221101161539224 DLINP <000a> input/ipa.c:368 172.22.0.31:45037 message received
osmohlr      | 20221101161539224 DLGSUP <0012> gsup_req.c:138 GSUP 9: MSC-00-00-00-00-00-00: IMSI-204420000000002 OSMO_GSUP_MSGT_UPDATE_LOCATION_REQUEST: new request: {Subscriber-Management OSMO_GSUP_MSGT_UPDATE_LOCATION_REQUEST: imsi="204420000000002" cn_domain=CS}
osmohlr      | 20221101161539224 DLU <0006> fsm.c:461 lu(204420000000002)[0x560d6f644310]{UNVALIDATED}: Allocated
osmohlr      | 20221101161539224 DLGSUP <0012> lu_fsm.c:172 GSUP 9: MSC-00-00-00-00-00-00: IMSI-204420000000002 OSMO_GSUP_MSGT_UPDATE_LOCATION_REQUEST: storing VLR number = MSC-00-00-00-00-00-00
osmohlr      | 20221101161539228 DLU <0006> lu_fsm.c:200 lu(CS:IMSI-204420000000002)[0x560d6f644310]{UNVALIDATED}: state_chg to WAIT_INSERT_DATA_RESULT
osmohlr      | 20221101161539228 DLGSUP <0012> lu_fsm.c:255 GSUP 9: MSC-00-00-00-00-00-00: IMSI-204420000000002 OSMO_GSUP_MSGT_UPDATE_LOCATION_REQUEST: Tx response: {Subscriber-Management OSMO_GSUP_MSGT_INSERT_DATA_REQUEST: imsi="204420000000002" cn_domain=CS}
osmohlr      | 20221101161539228 DLINP <000a> input/ipa.c:412 connected read/write
osmohlr      | 20221101161539228 DLINP <000a> input/ipa.c:392 172.22.0.31:45037 sending data
osmomsc      | <000f> gsm_04_08.c:1524 SUBSCR(IMSI-204420000000002:MSISDN-0002:TMSInew-0x0C5A95A8) VLR: update for IMSI=204420000000002 (MSISDN=0002) (NO CONN!)
osmohlr      | 20221101161539228 DLINP <000a> input/ipa.c:412 connected read/write
osmohlr      | 20221101161539228 DLINP <000a> input/ipa.c:392 172.22.0.31:45037 sending data
osmohlr      | 20221101161539229 DLINP <000a> input/ipa.c:412 connected read/write
osmohlr      | 20221101161539229 DLINP <000a> input/ipa.c:368 172.22.0.31:45037 message received
osmohlr      | 20221101161539229 DLGSUP <0012> gsup_req.c:138 GSUP 10: MSC-00-00-00-00-00-00: IMSI-204420000000002 OSMO_GSUP_MSGT_INSERT_DATA_RESULT: new request: {Subscriber-Management OSMO_GSUP_MSGT_INSERT_DATA_RESULT: imsi="204420000000002"}
osmohlr      | 20221101161539229 DLU <0006> lu_fsm.c:212 lu(CS:IMSI-204420000000002)[0x560d6f644310]{WAIT_INSERT_DATA_RESULT}: Received Event LU_EV_RX_GSUP
osmohlr      | 20221101161539229 DLGSUP <0012> gsup_req.c:171 GSUP 10: MSC-00-00-00-00-00-00: IMSI-204420000000002 OSMO_GSUP_MSGT_INSERT_DATA_RESULT: free
osmohlr      | 20221101161539229 DLGSUP <0012> lu_fsm.c:91 GSUP 9: MSC-00-00-00-00-00-00: IMSI-204420000000002 OSMO_GSUP_MSGT_UPDATE_LOCATION_REQUEST: Tx response: {Subscriber-Management OSMO_GSUP_MSGT_UPDATE_LOCATION_RESULT: imsi="204420000000002"}
osmohlr      | 20221101161539229 DLGSUP <0012> gsup_req.c:171 GSUP 9: MSC-00-00-00-00-00-00: IMSI-204420000000002 OSMO_GSUP_MSGT_UPDATE_LOCATION_REQUEST: free
osmohlr      | 20221101161539229 DLU <0006> lu_fsm.c:93 lu(CS:IMSI-204420000000002)[0x560d6f644310]{WAIT_INSERT_DATA_RESULT}: Terminating (cause = OSMO_FSM_TERM_REGULAR)
osmohlr      | 20221101161539229 DLU <0006> lu_fsm.c:93 lu(CS:IMSI-204420000000002)[0x560d6f644310]{WAIT_INSERT_DATA_RESULT}: Freeing instance
osmohlr      | 20221101161539229 DLU <0006> fsm.c:573 lu(CS:IMSI-204420000000002)[0x560d6f644310]{WAIT_INSERT_DATA_RESULT}: Deallocated
osmohlr      | 20221101161539229 DLINP <000a> input/ipa.c:412 connected read/write
osmohlr      | 20221101161539229 DLINP <000a> input/ipa.c:392 172.22.0.31:45037 sending data
osmohlr      | 20221101161539229 DLINP <000a> input/ipa.c:412 connected read/write
osmohlr      | 20221101161539229 DLINP <000a> input/ipa.c:392 172.22.0.31:45037 sending data
mme          | 11/01 16:15:39.485: [mme] INFO: UE Context Release [Action:2] (../src/mme/s1ap-handler.c:1448)
mme          | 11/01 16:15:39.485: [mme] INFO:     ENB_UE_S1AP_ID[5] MME_UE_S1AP_ID[5] (../src/mme/s1ap-handler.c:1449)
mme          | 11/01 16:15:39.485: [mme] INFO:     IMSI[204420000000002] (../src/mme/s1ap-handler.c:1452)
mme          | 11/01 16:15:39.485: [mme] INFO: [Removed] Number of eNB-UEs is now 0 (../src/mme/mme-context.c:3282)

Suggestions are very welcome and appreciated! udr.log amf.log udm.log nssf.log bsf.log ausf.log nrf.log smf.log hss.log mme.log sgwu.log sgwc.log upf.log pcrf.log pcf.log

herlesupreeth commented 2 years ago

In your logs I see that you are running the network with PLMN 001 01 but the IMSI you are trying to connect is having PLMN 204 42. This would be a roaming scenario for MSC. I would suggest you to either change the MNC and MCC in .env file to 42 and 204 or re-program the SIM card to have IMSI starting with 00101

nllz commented 2 years ago

hmmmm, my .env says: 

MCC=204
MNC=42

But i have started it with: "$ docker-compose up "

should I run "$ source .env" every time before it run "$ docker-compose up "?

Will try again when I am in the lab. Many thanks!

env.txt (changed the file name of .env because else it wouldn't attach here)

herlesupreeth commented 2 years ago

should I run "$ source .env" every time before it run "$ docker-compose up "?

Yes

nllz commented 2 years ago

hmmm, I ran:

set -a
source .env
docker-compose build --no-cache
docker-compose up

but I am still getting:

mme          | 11/03 13:49:13.264: [mme] INFO: InitialUEMessage (../src/mme/s1ap-handler.c:223)
mme          | 11/03 13:49:13.264: [mme] INFO: [Added] Number of eNB-UEs is now 1 (../src/mme/mme-context.c:3276)
mme          | 11/03 13:49:13.264: [mme] INFO:     ENB_UE_S1AP_ID[1] MME_UE_S1AP_ID[1] TAC[1] CellID[0x19b01] (../src/mme/s1ap-handler.c:363)
mme          | 11/03 13:49:13.272: [mme] INFO: [204420000000002] Unknown UE by IMSI (../src/mme/mme-context.c:2318)
mme          | 11/03 13:49:13.272: [mme] INFO: [Added] Number of MME-UEs is now 1 (../src/mme/mme-context.c:2151)
mme          | 11/03 13:49:13.272: [emm] WARNING: [] Attach request (../src/mme/emm-sm.c:203)
mme          | 11/03 13:49:13.272: [emm] INFO:     IMSI[204420000000002] (../src/mme/emm-handler.c:188)
mme          | 11/03 13:49:13.358: [mme] INFO: [Added] Number of MME-Sessions is now 1 (../src/mme/mme-context.c:3288)
sgwc         | 11/03 13:49:13.396: [sgwc] INFO: [Added] Number of SGWC-UEs is now 1 (../src/sgwc/context.c:210)
sgwc         | 11/03 13:49:13.396: [sgwc] INFO: [Added] Number of SGWC-Sessions is now 1 (../src/sgwc/context.c:863)
sgwu         | 11/03 13:49:13.397: [sgwu] INFO: UE F-SEID[CP:0x1 UP:0x1] (../src/sgwu/context.c:144)
sgwu         | 11/03 13:49:13.397: [sgwu] INFO: [Added] Number of SGWU-Sessions is now 1 (../src/sgwu/context.c:149)
sgwc         | 11/03 13:49:13.397: [gtp] INFO: gtp_connect() [172.22.0.7]:2123 (../lib/gtp/path.c:58)
smf          | 11/03 13:49:13.397: [smf] INFO: [Added] Number of SMF-UEs is now 1 (../src/smf/context.c:819)
smf          | 11/03 13:49:13.397: [smf] INFO: [Added] Number of SMF-Sessions is now 1 (../src/smf/context.c:2610)
smf          | 11/03 13:49:13.397: [smf] INFO: UE IMSI[204420000000002] APN[internet] IPv4[172.22.0.100] IPv6[2001:230:cafe:1::2] (../src/smf/s5c-handler.c:219)
upf          | 11/03 13:49:13.400: [upf] INFO: [Added] Number of UPF-Sessions is now 1 (../src/upf/context.c:160)
upf          | 11/03 13:49:13.400: [gtp] INFO: gtp_connect() [172.22.0.6]:2152 (../lib/gtp/path.c:58)
upf          | 11/03 13:49:13.400: [gtp] INFO: gtp_connect() [172.22.0.7]:2152 (../lib/gtp/path.c:58)
upf          | 11/03 13:49:13.400: [upf] INFO: UE F-SEID[CP:0x1 UP:0x1] APN[internet] PDN-Type[3] IPv4[172.22.0.100] IPv6[2001:230:cafe:1::2] (../src/upf/context.c:361)
sgwu         | 11/03 13:49:13.401: [gtp] INFO: gtp_connect() [172.22.0.8]:2152 (../lib/gtp/path.c:58)
smf          | 11/03 13:49:13.401: [gtp] INFO: gtp_connect() [172.22.0.8]:2152 (../lib/gtp/path.c:58)
osmohlr      | 20221103134913401 DLINP <000b> input/ipa.c:412 connected read/write
osmohlr      | 20221103134913401 DLINP <000b> input/ipa.c:368 172.22.0.31:43681 message received
osmomsc      | <000f> gsm_04_08.c:1538 SUBSCR(IMSI-204420000000002:TMSInew-0x9666B2A6) VLR: update for IMSI=204420000000002 (MSISDN=) (NO CONN!)
osmohlr      | 20221103134913401 DLGSUP <0013> gsup_req.c:138 GSUP 1: MSC-00-00-00-00-00-00: IMSI-204420000000002 OSMO_GSUP_MSGT_UPDATE_LOCATION_REQUEST: new request: {Subscriber-Management OSMO_GSUP_MSGT_UPDATE_LOCATION_REQUEST: imsi="204420000000002" cn_domain=CS}
osmohlr      | 20221103134913402 DLU <0006> fsm.c:456 lu(204420000000002)[0x55d08cd33ff0]{UNVALIDATED}: Allocated
osmohlr      | 20221103134913402 DLGSUP <0013> lu_fsm.c:172 GSUP 1: MSC-00-00-00-00-00-00: IMSI-204420000000002 OSMO_GSUP_MSGT_UPDATE_LOCATION_REQUEST: storing VLR number = MSC-00-00-00-00-00-00
osmohlr      | 20221103134913405 DLU <0006> lu_fsm.c:200 lu(CS:IMSI-204420000000002)[0x55d08cd33ff0]{UNVALIDATED}: state_chg to WAIT_INSERT_DATA_RESULT
osmohlr      | 20221103134913405 DLGSUP <0013> lu_fsm.c:255 GSUP 1: MSC-00-00-00-00-00-00: IMSI-204420000000002 OSMO_GSUP_MSGT_UPDATE_LOCATION_REQUEST: Tx response: {Subscriber-Management OSMO_GSUP_MSGT_INSERT_DATA_REQUEST: imsi="204420000000002" cn_domain=CS}
osmohlr      | 20221103134913405 DLINP <000b> input/ipa.c:412 connected read/write
osmohlr      | 20221103134913405 DLINP <000b> input/ipa.c:392 172.22.0.31:43681 sending data
osmomsc      | <000f> gsm_04_08.c:1538 SUBSCR(IMSI-204420000000002:MSISDN-0002:TMSInew-0x9666B2A6) VLR: update for IMSI=204420000000002 (MSISDN=0002) (NO CONN!)
osmohlr      | 20221103134913405 DLINP <000b> input/ipa.c:412 connected read/write
osmohlr      | 20221103134913405 DLINP <000b> input/ipa.c:392 172.22.0.31:43681 sending data
osmohlr      | 20221103134913405 DLINP <000b> input/ipa.c:412 connected read/write
osmohlr      | 20221103134913405 DLINP <000b> input/ipa.c:368 172.22.0.31:43681 message received
osmohlr      | 20221103134913405 DLGSUP <0013> gsup_req.c:138 GSUP 2: MSC-00-00-00-00-00-00: IMSI-204420000000002 OSMO_GSUP_MSGT_INSERT_DATA_RESULT: new request: {Subscriber-Management OSMO_GSUP_MSGT_INSERT_DATA_RESULT: imsi="204420000000002"}
osmohlr      | 20221103134913405 DLU <0006> lu_fsm.c:212 lu(CS:IMSI-204420000000002)[0x55d08cd33ff0]{WAIT_INSERT_DATA_RESULT}: Received Event LU_EV_RX_GSUP
osmohlr      | 20221103134913405 DLGSUP <0013> gsup_req.c:171 GSUP 2: MSC-00-00-00-00-00-00: IMSI-204420000000002 OSMO_GSUP_MSGT_INSERT_DATA_RESULT: free
osmohlr      | 20221103134913405 DLGSUP <0013> lu_fsm.c:91 GSUP 1: MSC-00-00-00-00-00-00: IMSI-204420000000002 OSMO_GSUP_MSGT_UPDATE_LOCATION_REQUEST: Tx response: {Subscriber-Management OSMO_GSUP_MSGT_UPDATE_LOCATION_RESULT: imsi="204420000000002"}
osmohlr      | 20221103134913405 DLGSUP <0013> gsup_req.c:171 GSUP 1: MSC-00-00-00-00-00-00: IMSI-204420000000002 OSMO_GSUP_MSGT_UPDATE_LOCATION_REQUEST: free
osmohlr      | 20221103134913405 DLU <0006> lu_fsm.c:93 lu(CS:IMSI-204420000000002)[0x55d08cd33ff0]{WAIT_INSERT_DATA_RESULT}: Terminating (cause = OSMO_FSM_TERM
osmohlr      | 20221103134913405 DLU <0006> lu_fsm.c:93 lu(CS:IMSI-204420000000002)[0x55d08cd33ff0]{WAIT_INSERT_DATA_RESULT}: Terminating (cause = OSMO_FSM_TERM_REGULAR)
osmohlr      | 20221103134913405 DLU <0006> lu_fsm.c:93 lu(CS:IMSI-204420000000002)[0x55d08cd33ff0]{WAIT_INSERT_DATA_RESULT}: Freeing instance
osmohlr      | 20221103134913405 DLU <0006> fsm.c:568 lu(CS:IMSI-204420000000002)[0x55d08cd33ff0]{WAIT_INSERT_DATA_RESULT}: Deallocated
osmohlr      | 20221103134913405 DLINP <000b> input/ipa.c:412 connected read/write
osmohlr      | 20221103134913405 DLINP <000b> input/ipa.c:392 172.22.0.31:43681 sending data
osmohlr      | 20221103134913405 DLINP <000b> input/ipa.c:412 connected read/write
osmohlr      | 20221103134913405 DLINP <000b> input/ipa.c:392 172.22.0.31:43681 sending data
mme          | 11/03 13:49:13.658: [mme] INFO: UE Context Release [Action:2] (../src/mme/s1ap-handler.c:1448)
mme          | 11/03 13:49:13.658: [mme] INFO:     ENB_UE_S1AP_ID[1] MME_UE_S1AP_ID[1] (../src/mme/s1ap-handler.c:1449)
mme          | 11/03 13:49:13.658: [mme] INFO:     IMSI[204420000000002] (../src/mme/s1ap-handler.c:1452)
mme          | 11/03 13:49:13.658: [mme] INFO: [Removed] Number of eNB-UEs is now 0 (../src/mme/mme-context.c:3282)

ausf.log nrf.log smf.log hss.log mme.log sgwu.log sgwc.log upf.log pcrf.log pcf.log amf.log bsf.log udr.log udm.log nssf.log

herlesupreeth commented 2 years ago

Can you take a trace and send it? Its hard to debug with logs. I did check the logs of MME and I don't see any issues there.

nllz commented 2 years ago

It made a trace with script, I hope that is what you're looking for. output.txt

herlesupreeth commented 2 years ago

Not the logs. I meant a wireshark/tcpdump packet capture take on 'any' interface without any filters

nllz commented 2 years ago

Here you go output.zip

herlesupreeth commented 2 years ago

I don't think its due to osmohlr your UE is kicked off the network. As you can see in below screenshot, its the srsRAN which is failing to setup the default bearer for 'internet' APN (packet 14275). I am guessing it has to do with pre-emption capability + vulnerability setting in your open5gs WebUI. It should be disabled.

image

herlesupreeth commented 1 year ago

Closing due to inactivity. Please re-open the issue with pcaps and logs if you still face issue.