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@ims.mnc001.mnc001.3gppnetwork.org] (sip:bob@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@ims.mnc001.mnc001.3gppnetwork.org] (sip:alice@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@ims.mnc001.mnc001.3gppnetwork.org] (sip:bob@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@ims.mnc001.mnc001.3gppnetwork.org> registration subscriptions
13(18) DEBUG: ims_usrloc_scscf [impurecord.c:404]: process_impurecord(): Public Identity sip:alice@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@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@ims.mnc001.mnc001.3gppnetwork.org> registration subscriptions
13(18) DEBUG: ims_usrloc_scscf [impurecord.c:404]: process_impurecord(): Public Identity sip:bob@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@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@ims.mnc001.mnc001.3gppnetwork.org]
13(18) DEBUG: ims_usrloc_scscf [impurecord.c:598]: delete_scontact(): Deleting contact: [sip:bob@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@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