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:
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(a)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(a)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(a)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(a)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(a)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(a)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(a)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(a)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(a)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(a)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(a)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(a)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(a)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(a)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(a)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(a)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(a)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(a)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(a)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