[SR-Users] call disconnected between 15 to 45 minutes

Henning Westerholt hw at skalatan.de
Thu Dec 5 09:43:44 CET 2019


Hello Liu,

the module is tearing down dialogs that belongs to the deleted contact, this is the way it works (at least judging from a quick look to the code).

>From your logs:

3(18) DEBUG: ims_usrloc_scscf [udomain.c:406]: mem_timer_udomain(): deleting contact [sip:bob at ims.mnc001.mnc001.3gppnetwork.org]
13(18) DEBUG: ims_usrloc_scscf [impurecord.c:310]: mem_delete_ucontact(): Checking if dialog_data is there and needs to be torn down
13(18) DEBUG: ims_dialog [dlg_req_within.c:272]: send_bye(): sending BYE to caller

Have a look to the mem_timer_udomain function to see why it deletes the contact. Usually it is done by an internal timer if the contact is expired.

Cheers,

Henning

--
Henning Westerholt - https://skalatan.de/blog/
Kamailio services - https://gilawa.com<https://gilawa.com/>

From: sr-users <sr-users-bounces at lists.kamailio.org> On Behalf Of Liu, Charles
Sent: Wednesday, December 4, 2019 11:00 PM
To: Kamailio (SER) - Users Mailing List <sr-users at lists.kamailio.org>
Subject: [SR-Users] call disconnected between 15 to 45 minutes

Hi all,

I am still looking for some help to debug why S-CSCF send BYE to caller and callee after a call was connected. from wireshark, I just saw S-CSCF send BYE to both caller and callee. That matched the S-CSCF debug output. But the question is why S-CSCF delete contact and send BYE to a active call? There was no timer expire or something like that in the log...  Anyone can help?


Thanks,

--Charles


19(24) DEBUG: <core> [core/mem/q_malloc.c:519]: qm_free(): freeing frag. 0x7fb09413e6d0 alloc'ed from cdp: diameter_msg.c: AAATranslateMessage(484)
19(24) DEBUG: tm [t_lookup.c:1618]: t_lookup_ident(): transaction found
19(24) DEBUG: <core> [core/mem/q_malloc.c:367]: qm_malloc(): qm_malloc(0x7fb093db6000, 6872) called from core: core/sip_msg_clone.c: sip_msg_shm_clone(496)
19(24) DEBUG: <core> [core/mem/q_malloc.c:412]: qm_malloc(): qm_malloc(0x7fb093db6000, 6872) returns address 0x7fb09414d450 frag. 0x7fb09414d418 (size=6872) on 1 -th hit
19(24) ERROR: *** cfgtrace:failure_route=[REG_SAR_REPLY] c=[/etc/kamailio/kamailio.cfg] l=767 a=26 n=xlog
19(24) DEBUG: <script>: saa_return code is 1
19(24) ERROR: *** cfgtrace:failure_route=[REG_SAR_REPLY] c=[/etc/kamailio/kamailio.cfg] l=769 a=26 n=xlog
19(24) DEBUG: <script>: saa_return code (for scscf_save on register) is 1
19(24) ERROR: *** cfgtrace:failure_route=[REG_SAR_REPLY] c=[/etc/kamailio/kamailio.cfg] l=783 a=21 n=switch
19(24) ERROR: *** cfgtrace:failure_route=[REG_SAR_REPLY] c=[/etc/kamailio/kamailio.cfg] l=772 a=26 n=xlog
19(24) DEBUG: <script>: SAR success - 200 response sent from module
19(24) ERROR: *** cfgtrace:failure_route=[REG_SAR_REPLY] c=[/etc/kamailio/kamailio.cfg] l=773 a=2 n=exit
19(24) DEBUG: <core> [core/mem/q_malloc.c:475]: qm_free(): qm_free(0x7fb093db6000, 0x7fb09414d450), called from tm: t_reply.c: free_faked_req(948)
19(24) DEBUG: <core> [core/mem/q_malloc.c:519]: qm_free(): freeing frag. 0x7fb09414d418 alloc'ed from core: core/sip_msg_clone.c: sip_msg_shm_clone(496)
19(24) DEBUG: <core> [core/mem/q_malloc.c:475]: qm_free(): qm_free(0x7fb093db6000, 0x7fb09413e978), called from ims_registrar_scscf: cxdx_sar.c: free_saved_transaction_data(94)
19(24) DEBUG: <core> [core/mem/q_malloc.c:519]: qm_free(): freeing frag. 0x7fb09413e940 alloc'ed from ims_registrar_scscf: save.c: save(1414)
19(24) DEBUG: <core> [core/mem/q_malloc.c:475]: qm_free(): qm_free(0x7fb093db6000, 0x7fb09413e0b0), called from ims_registrar_scscf: reply.c: free_contact_buf(830)
19(24) DEBUG: <core> [core/mem/q_malloc.c:519]: qm_free(): freeing frag. 0x7fb09413e078 alloc'ed from ims_registrar_scscf: reply.c: build_contact(443)
19(24) DEBUG: <core> [core/mem/q_malloc.c:475]: qm_free(): qm_free(0x7fb093db6000, 0x7fb094145218), called from ims_registrar_scscf: reply.c: free_contact_buf(835)
19(24) DEBUG: <core> [core/mem/q_malloc.c:519]: qm_free(): freeing frag. 0x7fb0941451e0 alloc'ed from ims_registrar_scscf: reply.c: build_contact(435)
19(24) DEBUG: <core> [core/mem/q_malloc.c:475]: qm_free(): qm_free(0x7fb093db6000, 0x7fb094147dc0), called from ims_registrar_scscf: cxdx_sar.c: free_saved_transaction_data(98)
19(24) DEBUG: <core> [core/mem/q_malloc.c:519]: qm_free(): freeing frag. 0x7fb094147d88 alloc'ed from ims_registrar_scscf: save.c: save(1396)
19(24) DEBUG: <core> [core/mem/q_malloc.c:475]: qm_free(): qm_free(0x7fb093db6000, 0x7fb09415b4c8), called from cdp: transaction.c: cdp_free_trans(182)
19(24) DEBUG: <core> [core/mem/q_malloc.c:519]: qm_free(): freeing frag. 0x7fb09415b490 alloc'ed from cdp: transaction.c: cdp_add_trans(110)
19(24) DEBUG: <core> [core/mem/q_malloc.c:475]: qm_free(): qm_free(0x7fb093db6000, 0x7fb0941442a0), called from cdp: transaction.c: cdp_free_trans(183)
19(24) DEBUG: <core> [core/mem/q_malloc.c:519]: qm_free(): freeing frag. 0x7fb094144268 alloc'ed from cdp: transaction.c: cdp_add_trans(105)
13(18) DEBUG: ims_usrloc_scscf [ims_usrloc_scscf_mod.c:481]: timer(): Syncing cache
13(18) DEBUG: ims_usrloc_scscf [udomain.c:291]: mem_timer_udomain(): *** mem_timer_udomain - checking contacts - START ***
13(18) DEBUG: ims_usrloc_scscf [udomain.c:301]: mem_timer_udomain(): We have a [3gpp=0] contact in the new contact list in slot 95 = [sip:bob at ims.mnc001.mnc001.3gppnetwork.org] (sip:bob at 192.168.164.248:50448;rinstance=989f943bd5098a11;transport=UDP) which expires in -60.000000 seconds and has a ref count of 0 (state: Contact with delayed delete)
13(18) DEBUG: ims_usrloc_scscf [udomain.c:309]: mem_timer_udomain(): contact in state CONTACT_DELATED_DELETE is about to be deleted13(18) DEBUG: ims_usrloc_scscf [udomain.c:301]: mem_timer_udomain(): We have a [3gpp=0] contact in the new contact list in slot 464 = [sip:alice at ims.mnc001.mnc001.3gppnetwork.org] (sip:alice at 192.168.164.203:44640;rinstance=e35e9704884c3208;transport=UDP) which expires in 50.000000 seconds and has a ref count of 1 (state: Contact valid)
13(18) DEBUG: ims_usrloc_scscf [udomain.c:301]: mem_timer_udomain(): We have a [3gpp=0] contact in the new contact list in slot 478 = [sip:bob at ims.mnc001.mnc001.3gppnetwork.org] (sip:bob at 192.168.164.248:50448;rinstance=9e742618a5f6bcae;transport=UDP) which expires in 56.000000 seconds and has a ref count of 1 (state: Contact valid)
13(18) DEBUG: ims_usrloc_scscf [udomain.c:353]: mem_timer_udomain(): *** mem_timer_udomain - checking contacts - FINISHED ***
13(18) DEBUG: ims_usrloc_scscf [udomain.c:359]: mem_timer_udomain(): *** mem_timer_udomain - checking IMPUs - START ***
13(18) DEBUG: ims_usrloc_scscf [impurecord.c:372]: process_impurecord(): Checking validity of IMPU: <sip:alice at ims.mnc001.mnc001.3gppnetwork.org> registration subscriptions
13(18) DEBUG: ims_usrloc_scscf [impurecord.c:404]: process_impurecord():        Public Identity sip:alice at ims.mnc001.mnc001.3gppnetwork.org, Barred: [0], State: [registered], contacts [1], 3gppcontacts [0]
13(18) DEBUG: ims_usrloc_scscf [impurecord.c:441]: process_impurecord():                Contact #0 - sip:alice at 192.168.164.203:44640;rinstance=e35e9704884c3208;transport=UDP, Ref [1] (expires in 50 seconds) (State: 0)
13(18) DEBUG: ims_usrloc_scscf [impurecord.c:372]: process_impurecord(): Checking validity of IMPU: <sip:bob at ims.mnc001.mnc001.3gppnetwork.org> registration subscriptions
13(18) DEBUG: ims_usrloc_scscf [impurecord.c:404]: process_impurecord():        Public Identity sip:bob at ims.mnc001.mnc001.3gppnetwork.org, Barred: [0], State: [registered], contacts [1], 3gppcontacts [0]

3(18) DEBUG: ims_usrloc_scscf [impurecord.c:441]: process_impurecord():                 Contact #0 - sip:bob at 192.168.164.248:50448;rinstance=9e742618a5f6bcae;transport=UDP, Ref [1] (expires in 56 seconds) (State: 0)
3(18) DEBUG: ims_usrloc_scscf [udomain.c:384]: mem_timer_udomain(): *** mem_timer_udomain - checking IMPUs - FINISHED ***
3(18) DEBUG: ims_usrloc_scscf [udomain.c:406]: mem_timer_udomain(): deleting contact [sip:bob at ims.mnc001.mnc001.3gppnetwork.org]
13(18) DEBUG: ims_usrloc_scscf [impurecord.c:598]: delete_scontact(): Deleting contact: [sip:bob at 192.168.164.248:50448;rinstance=989f943bd5098a11;transport=UDP]
13(18) DEBUG: ims_usrloc_scscf [usrloc_db.c:370]: db_delete_ucontact(): Deleting ucontact [sip:bob at 192.168.164.248:50448;rinstance=989f943bd5098a11;transport=UDP]
13(18) DEBUG: ims_usrloc_scscf [impurecord.c:310]: mem_delete_ucontact(): Checking if dialog_data is there and needs to be torn down
13(18) DEBUG: ims_usrloc_scscf [impurecord.c:314]: mem_delete_ucontact(): first dialog is not 0
13(18) DEBUG: ims_usrloc_scscf [impurecord.c:317]: mem_delete_ucontact(): Going to tear down dialog with info h_entry [1694] h_id [3889]
13(18) DEBUG: ims_dialog [dlg_hash.c:887]: lookup_dlg(): ref dlg 0x7fb09414ce40 with 1 -> 3
13(18) DEBUG: ims_dialog [dlg_hash.c:889]: lookup_dlg(): dialog id=3889 found on entry 1694
13(18) DEBUG: ims_dialog [dlg_hash.c:1066]: unref_dlg(): unref dlg 0x7fb09414ce40 with 1 -> 2
13(18) DEBUG: ims_dialog [dlg_req_within.c:379]: dlg_terminate(): terminating confirmed dialog
13(18) DEBUG: <core> [core/mem/q_malloc.c:367]: qm_malloc(): qm_malloc(0x7fb09b5ae010, 18) called from ims_dialog: dlg_req_within.c: build_extra_hdr(229)
13(18) DEBUG: <core> [core/mem/q_malloc.c:412]: qm_malloc(): qm_malloc(0x7fb09b5ae010, 24) returns address 0x7fb09b640c30 frag. 0x7fb09b640bf8 (size=64) on 1 -th hit
13(18) DEBUG: <core> [core/mem/q_malloc.c:367]: qm_malloc(): qm_malloc(0x7fb09b5ae010, 248) called from ims_dialog: dlg_req_within.c: build_dlg_t(81)
13(18) DEBUG: <core> [core/mem/q_malloc.c:412]: qm_malloc(): qm_malloc(0x7fb09b5ae010, 248) returns address 0x7fb09b74b100 frag. 0x7fb09b74b0c8 (size=248) on 1 -th hit
13(18) DEBUG: <core> [core/mem/q_malloc.c:367]: qm_malloc(): qm_malloc(0x7fb09b5ae010, 72) called from core: core/parser/parse_rr.c: do_parse_rr_body(68)
13(18) DEBUG: <core> [core/mem/q_malloc.c:412]: qm_malloc(): qm_malloc(0x7fb09b5ae010, 72) returns address 0x7fb09b74b048 frag. 0x7fb09b74b010 (size=80) on 1 -th hit
13(18) DEBUG: ims_dialog [dlg_req_within.c:272]: send_bye(): sending BYE to caller
13(18) DEBUG: ims_dialog [dlg_hash.c:1047]: ref_dlg(): ref dlg 0x7fb09414ce40 with 1 -> 3




CONFIDENTIALITY NOTICE: This email and any attachments are for the sole use of the intended recipient and may contain material that is proprietary, confidential, privileged or otherwise legally protected or restricted under applicable government laws. Any review, disclosure, distributing or other use without expressed permission of the sender is strictly prohibited. If you are not the intended recipient, please contact the sender and delete all copies without reading, printing, or saving.

-------------- next part --------------
An HTML attachment was scrubbed...
URL: <http://lists.kamailio.org/pipermail/sr-users/attachments/20191205/22774c66/attachment.html>


More information about the sr-users mailing list