Hi Anthony,

In a system I have 3rd party registrations work, so I was curious what happens in your case. My conclusion is that you have a version of the code prior to this patches here below:

https://github.com/kamailio/kamailio/commit/2067f110336244826b183a649cb987fac94ffe1c

https://github.com/kamailio/kamailio/commit/89421e184a8b47557dcfc6c348d60dde347a9417

You need those patches, actually just update the modules you use to the latest because I am not sure of all the dependencies and the tm module...

If you do have those patches your log makes no sense to me :D.

Here explained:

The S-CSCF in the file save.c line 1474 calls t_suspend from the TM module which sets the transaction to suspended (we are on the reply to the REGISTER here). When it receives the Successful Diameter answer for the SAR then it tries to recover that transaction calling t_continue_skip_timer from the TM module (line 289 in file cxdx_sar.c), this one calls t_continue_helper (tm/t_suspend.c ) which ends up calling t_lookup_ident_filter  ... this function is from 2019, before it was only t_lookup_ident which doesn't exist anymore and calls t_lookup_ident_filter.  

Best regards

alberto

El 20/10/2022 a las 12:25, Anthony Blandin escribió:

Hello,

 

Here are the logs. It seems that after the save("PRE_REG_SAR_REPLY","location") function, the route PRE_REG_SAR_REPLY is not applied.

 

 

scscf1-airnity-slice-data-par  3(45) ERROR: <script>: Not REGISTERED

scscf1-airnity-slice-data-par  3(45) DEBUG: ims_registrar_scscf [save.c:1269]: save(): Looking for route block [PRE_REG_SAR_REPLY]

scscf1-airnity-slice-data-par  3(45) DEBUG: ims_registrar_scscf [save.c:1326]: save(): preparing for SAR assignment for new REGISTRATION sip:901810000000022@ims.mnc081.mcc901.3gppnetwork.org

scscf1-airnity-slice-data-par  3(45) DEBUG: tm [t_lookup.c:1328]: t_newtran(): msg (0x7f77335df348) id=3/45 global id=3/45 T start=(nil)

scscf1-airnity-slice-data-par  3(45) DEBUG: tm [t_lookup.c:497]: t_lookup_request(): start searching: hash=5727, isACK=0

scscf1-airnity-slice-data-par  3(45) DEBUG: tm [t_lookup.c:455]: matching_3261(): RFC3261 transaction matching failed - via branch [z9hG4bKf561.0ec3b0f8ee4f189c6053ab447b478699.0]

scscf1-airnity-slice-data-par  3(45) DEBUG: tm [t_lookup.c:675]: t_lookup_request(): no transaction found

scscf1-airnity-slice-data-par  3(45) DEBUG: tm [t_hooks.c:336]: run_reqin_callbacks_internal(): trans=0x7f772c08aad0, callback type 1, id 0 entered

scscf1-airnity-slice-data-par  3(45) INFO: ims_registrar_scscf [cxdx_sar.c:84]: create_return_code(): created AVP successfully : [saa_return_code] - [-2]

scscf1-airnity-slice-data-par  3(45) DEBUG: ims_registrar_scscf [save.c:1430]: save(): Suspending SIP TM transaction with index [0] and label [0]

scscf1-airnity-slice-data-par  3(45) DEBUG: cdp [session.c:284]: cdp_add_session(): adding a session with id scscf.ims.mnc081.mcc901.3gppnetwork.org;3181552081;2

scscf1-airnity-slice-data-par  3(45) DEBUG: tm [t_lookup.c:1034]: t_check_msg(): msg (0x7f77335df348) id=3/45 global id=3/45 T start=0x7f772c08aad0

scscf1-airnity-slice-data-par  3(45) DEBUG: tm [t_lookup.c:1109]: t_check_msg(): T (0x7f772c08aad0) already found for msg (0x7f77335df348)!

scscf1-airnity-slice-data-par  3(45) DEBUG: cdp [session.c:305]: cdp_get_session(): called get session with id scscf.ims.mnc081.mcc901.3gppnetwork.org;3181552081;2 and hash 12

scscf1-airnity-slice-data-par  3(45) DEBUG: cdp [session.c:314]: cdp_get_session(): no session found

scscf1-airnity-slice-data-par  3(45) DEBUG: cdp [routing.c:202]: get_routing_peer(): getting diameter routing peer for realm: [ims.mnc081.mcc901.3gppnetwork.org]

scscf1-airnity-slice-data-par  3(45) DEBUG: cdp [routing.c:271]: get_routing_peer(): no routing peer found, trying default route

scscf1-airnity-slice-data-par  3(45) DEBUG: cdp [routing.c:128]: get_first_connected_route(): The peer dra2_slice_par01.epc.mnc081.mcc901.3gppnetwork.org state is opened

scscf1-airnity-slice-data-par  3(45) DEBUG: cdp [routing.c:83]: peer_handles_application(): Checking if peer dra2_slice_par01.epc.mnc081.mcc901.3gppnetwork.org handles application 16777216 for vendord 10415

scscf1-airnity-slice-data-par  3(45) DEBUG: cdp [routing.c:131]: get_first_connected_route(): The peer dra2_slice_par01.epc.mnc081.mcc901.3gppnetwork.org matches - will forward there

scscf1-airnity-slice-data-par  3(45) DEBUG: cdp [routing.c:128]: get_first_connected_route(): The peer dra1_slice_par01.epc.mnc081.mcc901.3gppnetwork.org state is opened

scscf1-airnity-slice-data-par  3(45) DEBUG: cdp [routing.c:83]: peer_handles_application(): Checking if peer dra1_slice_par01.epc.mnc081.mcc901.3gppnetwork.org handles application 16777216 for vendord 10415

scscf1-airnity-slice-data-par  3(45) DEBUG: cdp [routing.c:131]: get_first_connected_route(): The peer dra1_slice_par01.epc.mnc081.mcc901.3gppnetwork.org matches - will forward there

scscf1-airnity-slice-data-par  3(45) DEBUG: cdp [routing.c:149]: get_first_connected_route(): peer [dra2_slice_par01.epc.mnc081.mcc901.3gppnetwork.org] was last used @ 1666163272179072

scscf1-airnity-slice-data-par  3(45) DEBUG: cdp [routing.c:152]: get_first_connected_route(): Peer [dra1_slice_par01.epc.mnc081.mcc901.3gppnetwork.org] was last used at [0]

scscf1-airnity-slice-data-par  3(45) DEBUG: cdp [routing.c:162]: get_first_connected_route(): chosen peer [dra1_slice_par01.epc.mnc081.mcc901.3gppnetwork.org]

scscf1-airnity-slice-data-par  3(45) DEBUG: cdp [diameter_comm.c:145]: AAASendMessage(): Found diameter peer [dra1_slice_par01.epc.mnc081.mcc901.3gppnetwork.org] from routing table

scscf1-airnity-slice-data-par  3(45) DEBUG: cdp [peerstatemachine.c:89]: sm_process(): sm_process(): Peer dra1_slice_par01.epc.mnc081.mcc901.3gppnetwork.org State I_Open Event Send_Message

scscf1-airnity-slice-data-par  3(45) DEBUG: cdp [peerstatemachine.c:1158]: Snd_Message(): Snd_Message called to peer [dra1_slice_par01.epc.mnc081.mcc901.3gppnetwork.org] for request with code 301

scscf1-airnity-slice-data-par  3(45) DEBUG: cdp [session.c:305]: cdp_get_session(): called get session with id scscf.ims.mnc081.mcc901.3gppnetwork.org;3181552081;2 and hash 12

scscf1-airnity-slice-data-par  3(45) DEBUG: cdp [session.c:314]: cdp_get_session(): no session found

scscf1-airnity-slice-data-par  3(45) DEBUG: cdp [diameter_msg.c:81]: AAABuildMsgBuffer(): AAABuildMsgBuffer(): len=528

scscf1-airnity-slice-data-par  3(45) DEBUG: cdp [receiver.c:1013]: peer_send_msg(): peer_send_msg(): Pipe push [0x7f772c085e10]

scscf1-airnity-slice-data-par 26(68) DEBUG: cdp [receiver.c:756]: receive_loop(): select_recv(): There is something on the send pipe

scscf1-airnity-slice-data-par 26(68) DEBUG: cdp [receiver.c:769]: receive_loop(): select_recv(): Send pipe says [0x7f772c085e10] 8

scscf1-airnity-slice-data-par 26(68) DEBUG: cdp [diameter_msg.c:410]: AAAFreeMessage(): AAAFreeMessage: Freeing message (0x7f772c085e10) 301

scscf1-airnity-slice-data-par 26(68) DEBUG: cdp [receiver.c:575]: do_receive(): receive_loop(): [dra1_slice_par01.epc.mnc081.mcc901.3gppnetwork.org] Recv Version 1 Length 1980

scscf1-airnity-slice-data-par 26(68) DEBUG: cdp [receiver.c:1104]: receive_message(): receive_message(): [dra1_slice_par01.epc.mnc081.mcc901.3gppnetwork.org] Recv msg 301

scscf1-airnity-slice-data-par 26(68) DEBUG: cdp [peerstatemachine.c:89]: sm_process(): sm_process(): Peer dra1_slice_par01.epc.mnc081.mcc901.3gppnetwork.org State I_Open Event I_Rcv_Message

scscf1-airnity-slice-data-par 26(68) DEBUG: cdp [session.c:305]: cdp_get_session(): called get session with id scscf.ims.mnc081.mcc901.3gppnetwork.org;3181552081;2 and hash 12

scscf1-airnity-slice-data-par 26(68) DEBUG: cdp [session.c:314]: cdp_get_session(): no session found

scscf1-airnity-slice-data-par 10(52) DEBUG: cdp [worker.c:343]: worker_process(): worker_process(): [1] got task Q(2/2)

scscf1-airnity-slice-data-par 10(52) DEBUG: ims_registrar_scscf [cxdx_sar.c:142]: async_cdp_callback(): There is transaction data this must have been called from save or assign server unreg10(52) DEBUG: tm [t_lookup.c:1611]: t_lookup_ident_filter(): transaction found

scscf1-airnity-slice-data-par 10(52) DEBUG: ims_registrar_scscf [cxdx_sar.c:189]: async_cdp_callback(): callid for found transaction is [1578740844_1601297404@192.168.101.3]

scscf1-airnity-slice-data-par 10(52) INFO: ims_registrar_scscf [cxdx_avp.c:138]: cxdx_get_avp(): cxdx_get_experimental_result_code: Failed finding avp

scscf1-airnity-slice-data-par 10(52) INFO: ims_registrar_scscf [cxdx_avp.c:138]: cxdx_get_avp(): cxdx_get_charging_info: Failed finding avp

scscf1-airnity-slice-data-par 10(52) DEBUG: ims_registrar_scscf [cxdx_sar.c:214]: async_cdp_callback(): received AAA success for SAR - SAA

scscf1-airnity-slice-data-par 10(52) DEBUG: ims_registrar_scscf [cxdx_sar.c:233]: async_cdp_callback(): Parsing user data string from SAA

scscf1-airnity-slice-data-par 10(52) ERROR: ims_registrar_scscf [userdata_parser.c:935]: parse_user_data(): sum is 151162 calculated len 1667 xml.l 166710(52) DEBUG: ims_registrar_scscf [userdata_parser.c:760]: parse_service_profile(): child name is [PublicIdentity]

scscf1-airnity-slice-data-par 10(52) DEBUG: ims_registrar_scscf [userdata_parser.c:760]: parse_service_profile(): child name is [PublicIdentity]

scscf1-airnity-slice-data-par 10(52) DEBUG: ims_registrar_scscf [userdata_parser.c:760]: parse_service_profile(): child name is [PublicIdentity]

scscf1-airnity-slice-data-par 10(52) DEBUG: ims_registrar_scscf [userdata_parser.c:760]: parse_service_profile(): child name is [InitialFilterCriteria]

scscf1-airnity-slice-data-par 10(52) DEBUG: ims_registrar_scscf [userdata_parser.c:760]: parse_service_profile(): child name is [InitialFilterCriteria]

scscf1-airnity-slice-data-par 10(52) DEBUG: ims_registrar_scscf [userdata_parser.c:1022]: print_user_data(): IMSSubscription:

scscf1-airnity-slice-data-par 10(52) DEBUG: ims_registrar_scscf [userdata_parser.c:1025]: print_user_data(): Private Identity: 901810000000022@ims.mnc081.mcc901.3gppnetwork.org

scscf1-airnity-slice-data-par 10(52) DEBUG: ims_registrar_scscf [userdata_parser.c:1027]: print_user_data():     Service Profile:

scscf1-airnity-slice-data-par 10(52) DEBUG: ims_registrar_scscf [userdata_parser.c:1029]: print_user_data():         Public Identity: Barring [1] sip:901810000000022@ims.mnc081.mcc901.3gppnetwork.org

scscf1-airnity-slice-data-par 10(52) DEBUG: ims_registrar_scscf [userdata_parser.c:1029]: print_user_data():         Public Identity: Barring [0] sip:+883390000010022@ims.mnc081.mcc901.3gppnetwork.org

scscf1-airnity-slice-data-par 10(52) DEBUG: ims_registrar_scscf [userdata_parser.c:1029]: print_user_data():         Public Identity: Barring [0] tel:+883390000010022

scscf1-airnity-slice-data-par 10(52) DEBUG: ims_registrar_scscf [userdata_parser.c:1035]: print_user_data():         Filter Criteria: Priority [1]ProfilePartInd [-1]

scscf1-airnity-slice-data-par 10(52) DEBUG: ims_registrar_scscf [userdata_parser.c:1040]: print_user_data():             Trigger Point: CNF [X] (_|_)&(_|_)

scscf1-airnity-slice-data-par 10(52) DEBUG: ims_registrar_scscf [userdata_parser.c:1045]: print_user_data():                 SPT: Grp[1] NOT[ ] RegType[0]

scscf1-airnity-slice-data-par 10(52) DEBUG: ims_registrar_scscf [userdata_parser.c:1057]: print_user_data():                      Method == <REGISTER>

scscf1-airnity-slice-data-par 10(52) DEBUG: ims_registrar_scscf [userdata_parser.c:1083]: print_user_data():             AS: sip:ip-sm-gw.ims.mnc081.mcc901.3gppnetwork.org Handling [1] SrvInfo: <>

scscf1-airnity-slice-data-par 10(52) DEBUG: ims_registrar_scscf [userdata_parser.c:1035]: print_user_data():         Filter Criteria: Priority [2]ProfilePartInd [-1]

scscf1-airnity-slice-data-par 10(52) DEBUG: ims_registrar_scscf [userdata_parser.c:1040]: print_user_data():             Trigger Point: CNF [ ] (_&_)|(_&_)

scscf1-airnity-slice-data-par 10(52) DEBUG: ims_registrar_scscf [userdata_parser.c:1045]: print_user_data():                 SPT: Grp[0] NOT[ ] RegType[0]

scscf1-airnity-slice-data-par 10(52) DEBUG: ims_registrar_scscf [userdata_parser.c:1057]: print_user_data():                      Method == <MESSAGE>

scscf1-airnity-slice-data-par 10(52) DEBUG: ims_registrar_scscf [userdata_parser.c:1045]: print_user_data():                 SPT: Grp[0] NOT[ ] RegType[0]

scscf1-airnity-slice-data-par 10(52) DEBUG: ims_registrar_scscf [userdata_parser.c:1062]: print_user_data():                      Hdr(Content-Type(11)) == <application/vnd.3gpp.sms>

scscf1-airnity-slice-data-par 10(52) DEBUG: ims_registrar_scscf [userdata_parser.c:1045]: print_user_data():                 SPT: Grp[0] NOT[ ] RegType[0]

scscf1-airnity-slice-data-par 10(52) DEBUG: ims_registrar_scscf [userdata_parser.c:1070]: print_user_data():                      SessionCase [0]

scscf1-airnity-slice-data-par 10(52) DEBUG: ims_registrar_scscf [userdata_parser.c:1083]: print_user_data():             AS: sip:ip-sm-gw.ims.mnc081.mcc901.3gppnetwork.org:5060 Handling [1] SrvInfo: <>

scscf1-airnity-slice-data-par 10(52) DEBUG: ims_registrar_scscf [cxdx_sar.c:240]: async_cdp_callback(): Successfully parse user data XML setting ref to 1 (we are referencing it)

scscf1-airnity-slice-data-par 10(52) DEBUG: ims_registrar_scscf [save.c:790]: update_contacts(): updating contacts in REGISTRATION state

scscf1-airnity-slice-data-par 10(52) DEBUG: ims_usrloc_scscf [impurecord.c:943]: update_impurecord(): No subscription yet for [901810000000022@ims.mnc081.mcc901.3gppnetwork.org]... adding

scscf1-airnity-slice-data-par 10(52) DEBUG: ims_usrloc_scscf [impurecord.c:1274]: ref_subscription_unsafe(): Reffing subscription [901810000000022@ims.mnc081.mcc901.3gppnetwork.org] - was [1]

scscf1-airnity-slice-data-par 10(52) DEBUG: ims_usrloc_scscf [impurecord.c:971]: update_impurecord(): No existing impu record for sip:901810000000022@ims.mnc081.mcc901.3gppnetwork.org.... creating new one

scscf1-airnity-slice-data-par 10(52) DEBUG: ims_usrloc_scscf [impurecord.c:1274]: ref_subscription_unsafe(): Reffing subscription [901810000000022@ims.mnc081.mcc901.3gppnetwork.org] - was [2]

scscf1-airnity-slice-data-par 10(52) DEBUG: ims_usrloc_scscf [udomain.c:238]: mem_insert_impurecord(): inserted new impurecord into memory [sip:901810000000022@ims.mnc081.mcc901.3gppnetwork.org]

scscf1-airnity-slice-data-par 10(52) DEBUG: ims_usrloc_scscf [ul_callback.h:119]: run_ul_callbacks(): impurecord=0x7f772c08f280, contact=(nil), callback type 256/256, id 0 entered

scscf1-airnity-slice-data-par 10(52) DEBUG: ims_registrar_scscf [usrloc_cb.c:53]: ul_impu_inserted(): Received notification of UL IMPU insert for IMPU sip:901810000000022@ims.mnc081.mcc901.3gppnetwork.org

scscf1-airnity-slice-data-par 10(52) DEBUG: ims_registrar_scscf [usrloc_cb.c:55]: ul_impu_inserted(): Registering for callbacks on this IMPU for contact insert, update, delete or expire to send notifications if there are any subscriptions

scscf1-airnity-slice-data-par 10(52) DEBUG: ims_usrloc_scscf [ul_callback.c:168]: register_ulcb(): installing callback for SCSCF IMPU record with type [1024]

scscf1-airnity-slice-data-par 10(52) DEBUG: ims_usrloc_scscf [ul_callback.c:168]: register_ulcb(): installing callback for SCSCF IMPU record with type [30720]

scscf1-airnity-slice-data-par 10(52) DEBUG: ims_registrar_scscf [usrloc_cb.c:59]: ul_impu_inserted(): Selectively asking for expire or no contact delete callbacks only on the anchor of the implicit set so that we only send one SAR per implicit set

scscf1-airnity-slice-data-par 10(52) DEBUG: ims_usrloc_scscf [impurecord.c:1285]: unref_subscription_unsafe(): un-reffing subscription [901810000000022@ims.mnc081.mcc901.3gppnetwork.org] - was [3]

scscf1-airnity-slice-data-par 10(52) DEBUG: ims_registrar_scscf [save.c:519]: update_contacts_helper(): updating the contacts for IMPU sip:901810000000022@ims.mnc081.mcc901.3gppnetwork.org

scscf1-airnity-slice-data-par 10(52) DEBUG: ims_registrar_scscf [save.c:137]: calc_contact_expires(): Calculated expires for contact is 600000

scscf1-airnity-slice-data-par 10(52) DEBUG: ims_registrar_scscf [save.c:545]: update_contacts_helper(): Need to update contact: sip:75bb2112-e5ef-47cc-ad1c-872ae629c493@192.168.101.3:43715;alias=192.168.101.3~44457~2: q_value [-1],sos: [0],expires [600000]

scscf1-airnity-slice-data-par 10(52) DEBUG: ims_registrar_scscf [save.c:550]: update_contacts_helper(): packing contact information

scscf1-airnity-slice-data-par 10(52) DEBUG: ims_registrar_scscf [save.c:556]: update_contacts_helper(): adding/updating contact based on prior existence

scscf1-airnity-slice-data-par 10(52) DEBUG: ims_usrloc_scscf [impurecord.c:748]: get_scontact(): looking for contact [sip:75bb2112-e5ef-47cc-ad1c-872ae629c493@192.168.101.3:43715;alias=192.168.101.3~44457~2] in slot 230

scscf1-airnity-slice-data-par 10(52) DEBUG: ims_registrar_scscf [save.c:562]: update_contacts_helper(): inserting new contact

scscf1-airnity-slice-data-par 10(52) DEBUG: ims_usrloc_scscf [impurecord.c:562]: insert_scontact(): INSERTing ucontact in usrloc module

scscf1-airnity-slice-data-par 10(52) DEBUG: ims_usrloc_scscf [ucontact.c:118]: new_ucontact(): Checking param [+g.3gpp.accesstype]

scscf1-airnity-slice-data-par 10(52) DEBUG: ims_usrloc_scscf [ucontact.c:118]: new_ucontact(): Checking param [+sip.instance]

scscf1-airnity-slice-data-par 10(52) DEBUG: ims_usrloc_scscf [ucontact.c:118]: new_ucontact(): Checking param [audio]

scscf1-airnity-slice-data-par 10(52) DEBUG: ims_usrloc_scscf [ucontact.c:118]: new_ucontact(): Checking param [+g.3gpp.smsip]

scscf1-airnity-slice-data-par 10(52) DEBUG: ims_usrloc_scscf [ucontact.c:118]: new_ucontact(): Checking param [+g.3gpp.icsi-ref]

scscf1-airnity-slice-data-par 10(52) DEBUG: ims_usrloc_scscf [ucontact.c:173]: new_ucontact(): generating hash based on [sip:75bb2112-e5ef-47cc-ad1c-872ae629c493@192.168.101.3:43715;alias=192.168.101.3~44457~2]

scscf1-airnity-slice-data-par 10(52) DEBUG: ims_usrloc_scscf [impurecord.c:280]: mem_insert_scontact(): Created new contact in memory with AOR: [sip:75bb2112-e5ef-47cc-ad1c-872ae629c493@192.168.101.3:43715;alias=192.168.101.3~44457~2] and hash [230]

scscf1-airnity-slice-data-par 10(52) DEBUG: ims_usrloc_scscf [udomain.c:843]: ref_contact_unsafe(): incrementing ref count on contact [sip:75bb2112-e5ef-47cc-ad1c-872ae629c493@192.168.101.3:43715;alias=192.168.101.3~44457~2], was 1

scscf1-airnity-slice-data-par 10(52) DEBUG: ims_usrloc_scscf [impurecord.c:1226]: link_contact_to_impu(): number of contacts for IMPU [sip:901810000000022@ims.mnc081.mcc901.3gppnetwork.org] is 1

scscf1-airnity-slice-data-par 10(52) DEBUG: ims_usrloc_scscf [udomain.c:852]: unref_contact_unsafe(): decrementing ref count on contact [sip:75bb2112-e5ef-47cc-ad1c-872ae629c493@192.168.101.3:43715;alias=192.168.101.3~44457~2], was 2

scscf1-airnity-slice-data-par 10(52) DEBUG: ims_usrloc_scscf [ul_callback.h:119]: run_ul_callbacks(): impurecord=0x7f772c08f280, contact=0x7f772c08f690, callback type 1024/1024, id 0 entered

scscf1-airnity-slice-data-par 10(52) DEBUG: ims_registrar_scscf [usrloc_cb.c:88]: ul_contact_changed(): Received notification of type 1024 on contact Address sip:75bb2112-e5ef-47cc-ad1c-872ae629c493@192.168.101.3:43715;alias=192.168.101.3~44457~2

scscf1-airnity-slice-data-par 10(52) DEBUG: ims_registrar_scscf [usrloc_cb.c:91]: ul_contact_changed(): There are no subscriptions for this IMPU therefore breaking out now as nothing to do

scscf1-airnity-slice-data-par 10(52) DEBUG: ims_usrloc_scscf [udomain.c:792]: get_subscription(): found an existing subscription for IMPI [901810000000022@ims.mnc081.mcc901.3gppnetwork.org]

scscf1-airnity-slice-data-par 10(52) DEBUG: ims_usrloc_scscf [impurecord.c:1274]: ref_subscription_unsafe(): Reffing subscription [901810000000022@ims.mnc081.mcc901.3gppnetwork.org] - was [2]

scscf1-airnity-slice-data-par 10(52) DEBUG: ims_usrloc_scscf [impurecord.c:878]: compare_subscription(): Comparing subscription for IMPI [901810000000022@ims.mnc081.mcc901.3gppnetwork.org]

scscf1-airnity-slice-data-par 10(52) DEBUG: ims_usrloc_scscf [impurecord.c:883]: compare_subscription(): new sip:901810000000022@ims.mnc081.mcc901.3gppnetwork.org (53) vs. orig sip:901810000000022@ims.mnc081.mcc901.3gppnetwork.org (53)

scscf1-airnity-slice-data-par 10(52) DEBUG: ims_usrloc_scscf [impurecord.c:971]: update_impurecord(): No existing impu record for sip:+883390000010022@ims.mnc081.mcc901.3gppnetwork.org.... creating new one

scscf1-airnity-slice-data-par 10(52) DEBUG: ims_usrloc_scscf [impurecord.c:1274]: ref_subscription_unsafe(): Reffing subscription [901810000000022@ims.mnc081.mcc901.3gppnetwork.org] - was [3]

scscf1-airnity-slice-data-par 10(52) DEBUG: ims_usrloc_scscf [udomain.c:238]: mem_insert_impurecord(): inserted new impurecord into memory [sip:+883390000010022@ims.mnc081.mcc901.3gppnetwork.org]

scscf1-airnity-slice-data-par 10(52) DEBUG: ims_usrloc_scscf [ul_callback.h:119]: run_ul_callbacks(): impurecord=0x7f772c090410, contact=(nil), callback type 256/256, id 0 entered

scscf1-airnity-slice-data-par 10(52) DEBUG: ims_registrar_scscf [usrloc_cb.c:53]: ul_impu_inserted(): Received notification of UL IMPU insert for IMPU sip:+883390000010022@ims.mnc081.mcc901.3gppnetwork.org

scscf1-airnity-slice-data-par 10(52) DEBUG: ims_registrar_scscf [usrloc_cb.c:55]: ul_impu_inserted(): Registering for callbacks on this IMPU for contact insert, update, delete or expire to send notifications if there are any subscriptions

scscf1-airnity-slice-data-par 10(52) DEBUG: ims_usrloc_scscf [ul_callback.c:168]: register_ulcb(): installing callback for SCSCF IMPU record with type [1024]

scscf1-airnity-slice-data-par 10(52) DEBUG: ims_usrloc_scscf [ul_callback.c:168]: register_ulcb(): installing callback for SCSCF IMPU record with type [30720]

scscf1-airnity-slice-data-par 10(52) DEBUG: ims_registrar_scscf [usrloc_cb.c:59]: ul_impu_inserted(): Selectively asking for expire or no contact delete callbacks only on the anchor of the implicit set so that we only send one SAR per implicit set

scscf1-airnity-slice-data-par 10(52) DEBUG: ims_usrloc_scscf [ul_callback.c:168]: register_ulcb(): installing callback for SCSCF IMPU record with type [80]

scscf1-airnity-slice-data-par 10(52) DEBUG: ims_usrloc_scscf [impurecord.c:1285]: unref_subscription_unsafe(): un-reffing subscription [901810000000022@ims.mnc081.mcc901.3gppnetwork.org] - was [4]

scscf1-airnity-slice-data-par 10(52) DEBUG: ims_registrar_scscf [save.c:519]: update_contacts_helper(): updating the contacts for IMPU sip:+883390000010022@ims.mnc081.mcc901.3gppnetwork.org

scscf1-airnity-slice-data-par 10(52) DEBUG: ims_registrar_scscf [save.c:137]: calc_contact_expires(): Calculated expires for contact is 600000

scscf1-airnity-slice-data-par 10(52) DEBUG: ims_registrar_scscf [save.c:545]: update_contacts_helper(): Need to update contact: sip:75bb2112-e5ef-47cc-ad1c-872ae629c493@192.168.101.3:43715;alias=192.168.101.3~44457~2: q_value [-1],sos: [0],expires [600000]

scscf1-airnity-slice-data-par 10(52) DEBUG: ims_registrar_scscf [save.c:550]: update_contacts_helper(): packing contact information

scscf1-airnity-slice-data-par 10(52) DEBUG: ims_registrar_scscf [save.c:556]: update_contacts_helper(): adding/updating contact based on prior existence

scscf1-airnity-slice-data-par 10(52) DEBUG: ims_usrloc_scscf [impurecord.c:748]: get_scontact(): looking for contact [sip:75bb2112-e5ef-47cc-ad1c-872ae629c493@192.168.101.3:43715;alias=192.168.101.3~44457~2] in slot 230

scscf1-airnity-slice-data-par 10(52) DEBUG: ims_usrloc_scscf [impurecord.c:774]: get_scontact(): have partially found a contact

scscf1-airnity-slice-data-par 10(52) DEBUG: ims_usrloc_scscf [impurecord.c:783]: get_scontact(): contact found p=[0x7f772c08f690], aor:[sip:901810000000022@ims.mnc081.mcc901.3gppnetwork.org] and contact:[sip:75bb2112-e5ef-47cc-ad1c-872ae629c493@192.168.101.3:43715;alias=192.168.101.3~44457~2], state [0]

scscf1-airnity-slice-data-par 10(52) DEBUG: ims_usrloc_scscf [udomain.c:843]: ref_contact_unsafe(): incrementing ref count on contact [sip:75bb2112-e5ef-47cc-ad1c-872ae629c493@192.168.101.3:43715;alias=192.168.101.3~44457~2], was 1

scscf1-airnity-slice-data-par 10(52) DEBUG: ims_registrar_scscf [save.c:570]: update_contacts_helper(): Contact already exists - updating - it's currently in state [0]

scscf1-airnity-slice-data-par 10(52) DEBUG: ims_usrloc_scscf [ucontact.c:423]: update_scontact(): Updating contact aor: [sip:901810000000022@ims.mnc081.mcc901.3gppnetwork.org] and contact uri: [sip:75bb2112-e5ef-47cc-ad1c-872ae629c493@192.168.101.3:43715;alias=192.168.101.3~44457~2]

scscf1-airnity-slice-data-par 10(52) DEBUG: ims_usrloc_scscf [ucontact.c:351]: mem_update_ucontact(): Setting contact expires to 1666763272 which is in 600000 seconds time

scscf1-airnity-slice-data-par 10(52) DEBUG: ims_usrloc_scscf [udomain.c:843]: ref_contact_unsafe(): incrementing ref count on contact [sip:75bb2112-e5ef-47cc-ad1c-872ae629c493@192.168.101.3:43715;alias=192.168.101.3~44457~2], was 2

scscf1-airnity-slice-data-par 10(52) DEBUG: ims_usrloc_scscf [impurecord.c:1226]: link_contact_to_impu(): number of contacts for IMPU [sip:+883390000010022@ims.mnc081.mcc901.3gppnetwork.org] is 1

scscf1-airnity-slice-data-par 10(52) DEBUG: ims_usrloc_scscf [ucontact.c:439]: update_scontact(): exists callback for type= UL_CONTACT_UPDATE

scscf1-airnity-slice-data-par 10(52) DEBUG: ims_usrloc_scscf [ul_callback.h:119]: run_ul_callbacks(): impurecord=0x7f772c090410, contact=0x7f772c08f690, callback type 2048/30720, id 1 entered

scscf1-airnity-slice-data-par 10(52) DEBUG: ims_registrar_scscf [usrloc_cb.c:88]: ul_contact_changed(): Received notification of type 2048 on contact Address sip:75bb2112-e5ef-47cc-ad1c-872ae629c493@192.168.101.3:43715;alias=192.168.101.3~44457~2

scscf1-airnity-slice-data-par 10(52) DEBUG: ims_registrar_scscf [usrloc_cb.c:91]: ul_contact_changed(): There are no subscriptions for this IMPU therefore breaking out now as nothing to do

scscf1-airnity-slice-data-par 10(52) DEBUG: ims_usrloc_scscf [udomain.c:852]: unref_contact_unsafe(): decrementing ref count on contact [sip:75bb2112-e5ef-47cc-ad1c-872ae629c493@192.168.101.3:43715;alias=192.168.101.3~44457~2], was 3

scscf1-airnity-slice-data-par 10(52) DEBUG: ims_usrloc_scscf [udomain.c:792]: get_subscription(): found an existing subscription for IMPI [901810000000022@ims.mnc081.mcc901.3gppnetwork.org]

scscf1-airnity-slice-data-par 10(52) DEBUG: ims_usrloc_scscf [impurecord.c:1274]: ref_subscription_unsafe(): Reffing subscription [901810000000022@ims.mnc081.mcc901.3gppnetwork.org] - was [3]

scscf1-airnity-slice-data-par 10(52) DEBUG: ims_usrloc_scscf [impurecord.c:878]: compare_subscription(): Comparing subscription for IMPI [901810000000022@ims.mnc081.mcc901.3gppnetwork.org]

scscf1-airnity-slice-data-par 10(52) DEBUG: ims_usrloc_scscf [impurecord.c:883]: compare_subscription(): new sip:901810000000022@ims.mnc081.mcc901.3gppnetwork.org (53) vs. orig sip:901810000000022@ims.mnc081.mcc901.3gppnetwork.org (53)

scscf1-airnity-slice-data-par 10(52) DEBUG: ims_usrloc_scscf [impurecord.c:971]: update_impurecord(): No existing impu record for tel:+883390000010022.... creating new one

scscf1-airnity-slice-data-par 10(52) DEBUG: ims_usrloc_scscf [impurecord.c:1274]: ref_subscription_unsafe(): Reffing subscription [901810000000022@ims.mnc081.mcc901.3gppnetwork.org] - was [4]

scscf1-airnity-slice-data-par 10(52) DEBUG: ims_usrloc_scscf [udomain.c:238]: mem_insert_impurecord(): inserted new impurecord into memory [tel:+883390000010022]

scscf1-airnity-slice-data-par 10(52) DEBUG: ims_usrloc_scscf [ul_callback.h:119]: run_ul_callbacks(): impurecord=0x7f772c090928, contact=(nil), callback type 256/256, id 0 entered

scscf1-airnity-slice-data-par 10(52) DEBUG: ims_registrar_scscf [usrloc_cb.c:53]: ul_impu_inserted(): Received notification of UL IMPU insert for IMPU tel:+883390000010022

scscf1-airnity-slice-data-par 10(52) DEBUG: ims_registrar_scscf [usrloc_cb.c:55]: ul_impu_inserted(): Registering for callbacks on this IMPU for contact insert, update, delete or expire to send notifications if there are any subscriptions

scscf1-airnity-slice-data-par 10(52) DEBUG: ims_usrloc_scscf [ul_callback.c:168]: register_ulcb(): installing callback for SCSCF IMPU record with type [1024]

scscf1-airnity-slice-data-par 10(52) DEBUG: ims_usrloc_scscf [ul_callback.c:168]: register_ulcb(): installing callback for SCSCF IMPU record with type [30720]

scscf1-airnity-slice-data-par 10(52) DEBUG: ims_registrar_scscf [usrloc_cb.c:59]: ul_impu_inserted(): Selectively asking for expire or no contact delete callbacks only on the anchor of the implicit set so that we only send one SAR per implicit set

scscf1-airnity-slice-data-par 10(52) DEBUG: ims_usrloc_scscf [impurecord.c:1285]: unref_subscription_unsafe(): un-reffing subscription [901810000000022@ims.mnc081.mcc901.3gppnetwork.org] - was [5]

scscf1-airnity-slice-data-par 10(52) DEBUG: ims_registrar_scscf [save.c:519]: update_contacts_helper(): updating the contacts for IMPU tel:+883390000010022

scscf1-airnity-slice-data-par 10(52) DEBUG: ims_registrar_scscf [save.c:137]: calc_contact_expires(): Calculated expires for contact is 600000

scscf1-airnity-slice-data-par 10(52) DEBUG: ims_registrar_scscf [save.c:545]: update_contacts_helper(): Need to update contact: sip:75bb2112-e5ef-47cc-ad1c-872ae629c493@192.168.101.3:43715;alias=192.168.101.3~44457~2: q_value [-1],sos: [0],expires [600000]

scscf1-airnity-slice-data-par 10(52) DEBUG: ims_registrar_scscf [save.c:550]: update_contacts_helper(): packing contact information

scscf1-airnity-slice-data-par 10(52) DEBUG: ims_registrar_scscf [save.c:556]: update_contacts_helper(): adding/updating contact based on prior existence

scscf1-airnity-slice-data-par 10(52) DEBUG: ims_usrloc_scscf [impurecord.c:748]: get_scontact(): looking for contact [sip:75bb2112-e5ef-47cc-ad1c-872ae629c493@192.168.101.3:43715;alias=192.168.101.3~44457~2] in slot 230

scscf1-airnity-slice-data-par 10(52) DEBUG: ims_usrloc_scscf [impurecord.c:774]: get_scontact(): have partially found a contact

scscf1-airnity-slice-data-par 10(52) DEBUG: ims_usrloc_scscf [impurecord.c:783]: get_scontact(): contact found p=[0x7f772c08f690], aor:[sip:901810000000022@ims.mnc081.mcc901.3gppnetwork.org] and contact:[sip:75bb2112-e5ef-47cc-ad1c-872ae629c493@192.168.101.3:43715;alias=192.168.101.3~44457~2], state [0]

scscf1-airnity-slice-data-par 10(52) DEBUG: ims_usrloc_scscf [udomain.c:843]: ref_contact_unsafe(): incrementing ref count on contact [sip:75bb2112-e5ef-47cc-ad1c-872ae629c493@192.168.101.3:43715;alias=192.168.101.3~44457~2], was 2

scscf1-airnity-slice-data-par 10(52) DEBUG: ims_registrar_scscf [save.c:570]: update_contacts_helper(): Contact already exists - updating - it's currently in state [0]

scscf1-airnity-slice-data-par 10(52) DEBUG: ims_usrloc_scscf [ucontact.c:423]: update_scontact(): Updating contact aor: [sip:901810000000022@ims.mnc081.mcc901.3gppnetwork.org] and contact uri: [sip:75bb2112-e5ef-47cc-ad1c-872ae629c493@192.168.101.3:43715;alias=192.168.101.3~44457~2]

scscf1-airnity-slice-data-par 10(52) DEBUG: ims_usrloc_scscf [ucontact.c:351]: mem_update_ucontact(): Setting contact expires to 1666763272 which is in 600000 seconds time

scscf1-airnity-slice-data-par 10(52) DEBUG: ims_usrloc_scscf [udomain.c:843]: ref_contact_unsafe(): incrementing ref count on contact [sip:75bb2112-e5ef-47cc-ad1c-872ae629c493@192.168.101.3:43715;alias=192.168.101.3~44457~2], was 3

scscf1-airnity-slice-data-par 10(52) DEBUG: ims_usrloc_scscf [impurecord.c:1226]: link_contact_to_impu(): number of contacts for IMPU [tel:+883390000010022] is 1

scscf1-airnity-slice-data-par 10(52) DEBUG: ims_usrloc_scscf [ucontact.c:439]: update_scontact(): exists callback for type= UL_CONTACT_UPDATE

scscf1-airnity-slice-data-par 10(52) DEBUG: ims_usrloc_scscf [ul_callback.h:119]: run_ul_callbacks(): impurecord=0x7f772c090928, contact=0x7f772c08f690, callback type 2048/30720, id 1 entered

scscf1-airnity-slice-data-par 10(52) DEBUG: ims_registrar_scscf [usrloc_cb.c:88]: ul_contact_changed(): Received notification of type 2048 on contact Address sip:75bb2112-e5ef-47cc-ad1c-872ae629c493@192.168.101.3:43715;alias=192.168.101.3~44457~2

scscf1-airnity-slice-data-par 10(52) DEBUG: ims_registrar_scscf [usrloc_cb.c:91]: ul_contact_changed(): There are no subscriptions for this IMPU therefore breaking out now as nothing to do

scscf1-airnity-slice-data-par 10(52) DEBUG: ims_usrloc_scscf [udomain.c:852]: unref_contact_unsafe(): decrementing ref count on contact [sip:75bb2112-e5ef-47cc-ad1c-872ae629c493@192.168.101.3:43715;alias=192.168.101.3~44457~2], was 4

scscf1-airnity-slice-data-par 10(52) DEBUG: ims_registrar_scscf [reply.c:541]: build_contact(): created Contact HF: Contact: sip:75bb2112-e5ef-47cc-ad1c-872ae629c493@192.168.101.3:43715;alias=192.168.101.3~44457~2;expires=540000;+g.3gpp.accesstype="cellular2";+sip.instance="<urn:gsma:imei:86210804-091779-0>";audio;+g.3gpp.smsip;+g.3gpp.icsi-ref="urn%3Aurn-7%3A3gpp-service.ims.icsi.mmtel"

scscf1-airnity-slice-data-par 10(52) DEBUG: ims_registrar_scscf [reply.c:584]: build_p_associated_uri(): Building P-Associated-URI

scscf1-airnity-slice-data-par 10(52) DEBUG: ims_registrar_scscf [reply.c:633]: build_p_associated_uri(): Created P-Associated-URI HF P-Associated-URI: sip:+883390000010022@ims.mnc081.mcc901.3gppnetwork.org, tel:+883390000010022

scscf1-airnity-slice-data-par 10(52) DEBUG: ims_registrar_scscf [registrar_notify.c:451]: event_reg(): Sending Reg event notifies

scscf1-airnity-slice-data-par 10(52) DEBUG: ims_registrar_scscf [registrar_notify.c:452]: event_reg(): Switching on event type: 7

scscf1-airnity-slice-data-par 10(52) DEBUG: ims_usrloc_scscf [udomain.c:690]: get_impus_from_subscription_as_string(): getting IMPU subscription set

scscf1-airnity-slice-data-par 10(52) DEBUG: ims_usrloc_scscf [udomain.c:706]: get_impus_from_subscription_as_string(): Got Record sip:901810000000022@ims.mnc081.mcc901.3gppnetwork.org (53)

scscf1-airnity-slice-data-par 10(52) DEBUG: ims_usrloc_scscf [udomain.c:706]: get_impus_from_subscription_as_string(): Got Record sip:+883390000010022@ims.mnc081.mcc901.3gppnetwork.org (54)

scscf1-airnity-slice-data-par 10(52) DEBUG: ims_usrloc_scscf [udomain.c:706]: get_impus_from_subscription_as_string(): Got Record tel:+883390000010022 (20)

scscf1-airnity-slice-data-par 10(52) DEBUG: ims_usrloc_scscf [udomain.c:722]: get_impus_from_subscription_as_string(): num of records returned is 2 and we need 74 bytes

scscf1-airnity-slice-data-par 10(52) DEBUG: ims_registrar_scscf [registrar_notify.c:523]: event_reg(): About to create notification

scscf1-airnity-slice-data-par 10(52) DEBUG: ims_registrar_scscf [registrar_notify.c:1415]: create_notifications(): Creating notification

scscf1-airnity-slice-data-par 10(52) DEBUG: ims_registrar_scscf [registrar_notify.c:1418]: create_notifications(): r_passed and c_passed are valid and presentity uri and watcher_contact is 0 - this must be a ul callback no need to lock domain

scscf1-airnity-slice-data-par 10(52) DEBUG: ims_registrar_scscf [cxdx_sar.c:259]: async_cdp_callback(): Updated contacts: Contact: sip:75bb2112-e5ef-47cc-ad1c-872ae629c493@192.168.101.3:43715;alias=192.168.101.3~44457~2;expires=540000;+g.3gpp.accesstype="cellular2";+sip.instance="<urn:gsma:imei:86210804-091779-0>";audio;+g.3gpp.smsip;+g.3gpp.icsi-ref="urn%3Aurn-7%3A3gpp-service.ims.icsi.mmtel"

scscf1-airnity-slice-data-par 10(52) DEBUG: ims_registrar_scscf [reply.c:648]: reg_send_reply_transactional(): Contacts: Contact: sip:75bb2112-e5ef-47cc-ad1c-872ae629c493@192.168.101.3:43715;alias=192.168.101.3~44457~2;expires=540000;+g.3gpp.accesstype="cellular2";+sip.instance="<urn:gsma:imei:86210804-091779-0>";audio;+g.3gpp.smsip;+g.3gpp.icsi-ref="urn%3Aurn-7%3A3gpp-service.ims.icsi.mmtel"

scscf1-airnity-slice-data-par 10(52) DEBUG: tm [t_reply.c:1667]: cleanup_uac_timers(): RETR/FR timers reset

scscf1-airnity-slice-data-par 10(52) DEBUG: tm [t_reply.c:610]: _reply_light(): reply sent out. buf=0x7f77335e2030: SIP/2.0 200 OK

scscf1-airnity-slice-data-par From..., shmem=0x7f772c090fa0: SIP/2.0 200 OK

scscf1-airnity-slice-data-par From

scscf1-airnity-slice-data-par 10(52) DEBUG: tm [t_reply.c:621]: _reply_light(): finished

scscf1-airnity-slice-data-par 10(52) DEBUG: ims_registrar_scscf [cxdx_sar.c:272]: async_cdp_callback(): DBG:SAR Async CDP callback: ... Done resuming transaction

scscf1-airnity-slice-data-par 10(52) INFO: ims_registrar_scscf [cxdx_sar.c:84]: create_return_code(): created AVP successfully : [saa_return_code] - [1]

scscf1-airnity-slice-data-par 10(52) DEBUG: ims_usrloc_scscf [impurecord.c:1285]: unref_subscription_unsafe(): un-reffing subscription [901810000000022@ims.mnc081.mcc901.3gppnetwork.org] - was [4]

scscf1-airnity-slice-data-par 10(52) DEBUG: cdp [diameter_msg.c:410]: AAAFreeMessage(): AAAFreeMessage: Freeing message (0x7f772c089f50) 301

scscf1-airnity-slice-data-par 10(52) DEBUG: tm [t_lookup.c:1603]: t_lookup_ident_filter(): transaction in terminated phase - skipping

scscf1-airnity-slice-data-par 10(52) WARNING: tm [t_suspend.c:192]: t_continue_helper(): active transaction not found

 

Could you help me on this issue?

Regards,

 

Anthony

 

From: Anthony Blandin
Sent: Wednesday, 19 October 2022 15:15
To: sr-users@lists.kamailio.org
Subject: No REGISTER sent to third party AS from scscf

 

Hi Community,

 

I am using scscf from Kamailio and I need that scscf sent a REGISTER to a third party AS during the registration phase.

When scscf received a new registration, no REGISTER is sent to the AS.

SAR-SAA is well processed but only 200 OK is sent for the REGISTER to the pcscf.

REGISTER is well sent to the AS only for Re-Registration or De-registration.

Do you have any idea to handle this case?

Regards

 

Anthony


__________________________________________________________
Kamailio - Users Mailing List - Non Commercial Discussions
sr-users@lists.kamailio.org
Important: keep the mailing list in the recipients, do not reply only to the sender!
Edit mailing list options or unsubscribe:
https://lists.kamailio.org/cgi-bin/mailman/listinfo/sr-users