obelix*CLI> Jul 5 16:42:35 DEBUG[131080]: chan_sip.c:2392 find_call: Calling sip_alloc con CallID=a6QzI-R*G0Af2@192.168.2.175 Jul 5 16:42:35 NOTICE[131080]: chan_sip.c:781 sip_cancel_destroy: Cancel destruction of SIP call name=(null) autokillid=-1 Jul 5 16:42:35 DEBUG[131080]: chan_sip.c:5164 check_user_full: Before searching local user: fromuser= 0192 our_contact= callerid="Planet" <0192> Jul 5 16:42:35 DEBUG[131080]: chan_sip.c:5185 check_user_full: Setting NAT on RTP to 0 Jul 5 16:42:35 DEBUG[131080]: chan_sip.c:4479 check_auth: check_auth rand: username: 0192 secret: pbxip method: INVITE uri: sip:*8@192.168.2.175 ignore:0 Jul 5 16:42:36 DEBUG[131080]: chan_sip.c:817 __sip_ack: Stopping retransmission on 'a6QzI-R*G0Af2@192.168.2.175' of Response 17: Found Jul 5 16:42:36 NOTICE[131080]: chan_sip.c:781 sip_cancel_destroy: Cancel destruction of SIP call name=(null) autokillid=11 Jul 5 16:42:36 DEBUG[131080]: chan_sip.c:5164 check_user_full: Before searching local user: fromuser= 0192 our_contact= callerid="Planet" <0192> Jul 5 16:42:36 DEBUG[131080]: chan_sip.c:5185 check_user_full: Setting NAT on RTP to 0 Jul 5 16:42:36 DEBUG[131080]: chan_sip.c:4479 check_auth: check_auth rand: 7d6f0423 username: 0192 secret: pbxip method: INVITE uri: sip:*8@192.168.2.175 ignore:0 Jul 5 16:42:36 NOTICE[131080]: chan_sip.c:781 sip_cancel_destroy: Cancel destruction of SIP call name=(null) autokillid=-1 Jul 5 16:42:36 DEBUG[131080]: chan_sip.c:6873 handle_request: Update user count for 0192 Jul 5 16:42:36 DEBUG[131080]: chan_sip.c:1603 update_user_counter: Call from user '0192' is 1 out of 0 Jul 5 16:42:36 DEBUG[131080]: chan_sip.c:4795 get_destination: Call from 0192@192.168.2.175 looking for *8 in local Jul 5 16:42:36 DEBUG[131080]: chan_sip.c:6887 handle_request: Values for response uri=sip:0192@192.168.2.192:5061 domain=192.168.2.175 our_contact= Jul 5 16:42:36 DEBUG[131080]: chan_sip.c:1961 sip_new: Creating new sip channel Jul 5 16:42:36 DEBUG[131080]: chan_sip.c:1975 sip_new: New local sip channel host= 0192 Jul 5 16:42:36 NOTICE[131080]: channel.c:2391 ast_setstate: Channel SIP/0192@ipcontact-cb69: state changed from:Down to state:Down Jul 5 16:42:36 DEBUG[131080]: chan_sip.c:4412 build_route: build_route: Contact hop: Planet Jul 5 16:42:36 NOTICE[131080]: channel.c:2391 ast_setstate: Channel SIP/0192@ipcontact-cb69: state changed from:Down to state:Ring Jul 5 16:42:36 DEBUG[131080]: res_parking.c:751 ast_pickup_call: Call pickup on chan 'SIP/0195@ipcontact-f4cc' by 'SIP/0192@ipcontact-cb69' Jul 5 16:42:36 DEBUG[131080]: chan_sip.c:1781 sip_answer: sip_answer called in SIP/0192@ipcontact-cb69 Jul 5 16:42:36 NOTICE[131080]: channel.c:2391 ast_setstate: Channel SIP/0192@ipcontact-cb69: state changed from:Ring to state:Up Jul 5 16:42:36 DEBUG[131080]: chan_sip.c:3496 transmit_response_with_sdp: Adding UniqueId: 1089056556.2 to sip header Jul 5 16:42:36 NOTICE[131080]: channel.c:2391 ast_setstate: Channel SIP/0192@ipcontact-cb69: state changed from:Up to state:Up Jul 5 16:42:36 DEBUG[131080]: channel.c:2126 ast_channel_masquerade: Planning to masquerade SIP/0192@ipcontact-cb69 into the structure of SIP/0195@ipcontact-f4cc Jul 5 16:42:36 DEBUG[131080]: channel.c:2139 ast_channel_masquerade: Done planning to masquerade SIP/0195@ipcontact-f4cc into the structure of SIP/0192@ipcontact-cb69 Jul 5 16:42:36 WARNING[213005]: channel.c:1180 ast_read: Calling ast_do_masquerade on SIP/0195@ipcontact-f4cc Jul 5 16:42:36 DEBUG[213005]: channel.c:2172 ast_do_masquerade: Actually Masquerading SIP/0192@ipcontact-cb69(6) into the structure of SIP/0195@ipcontact-f4cc(5) Jul 5 16:42:36 DEBUG[213005]: channel.c:2183 ast_do_masquerade: Got clone lock on 'SIP/0192@ipcontact-cb69' at 0x816b590 ########## Order changed from here on: entering NEW THREAD(chan_sip.c:handle_request) ##################################### #### In this case ast_setstate(c, AST_STATE_DOWN); called from handle_request() after ast_pickup_call() fix the problem #### ############################################################################################################################ Jul 5 16:42:36 NOTICE[131080]: channel.c:2391 ast_setstate: Channel SIP/0192@ipcontact-cb69: state changed from:Up to state:Down Jul 5 16:42:36 NOTICE[131080]: chan_sip.c:6965 handle_request: Calling Hangup in channel: SIP/0192@ipcontact-cb69 Jul 5 16:42:36 DEBUG[213005]: chan_sip.c:1856 sip_fixup: sip_fixup called in SIP/0192@ipcontact-cb69 to SIP/0192@ipcontact-cb69 Jul 5 16:42:36 DEBUG[213005]: chan_sip.c:1699 sip_hangup: update_user_counter(0195) - decrement outUse counter ########## state = 0 (AST_STATE_DOWN) => CANCEL is sent ################################################# Jul 5 16:42:36 WARNING[213005]: chan_sip.c:1726 sip_hangup: Hangup on channel:SIP/0192@ipcontact-cb69 peername:0195 needcancel=1 state=0 alreadygone=0 from= ourcontact= ######################################################################################################### Jul 5 16:42:36 WARNING[213005]: chan_sip.c:1731 sip_hangup: Channel SIP/0192@ipcontact-cb69 startin disconnect Jul 5 16:42:36 WARNING[213005]: chan_sip.c:1733 sip_hangup: Channel SIP/0192@ipcontact-cb69 needcancel Jul 5 16:42:36 WARNING[213005]: chan_sip.c:1735 sip_hangup: Channel SIP/0192@ipcontact-cb69 is outgoing, request CANCEL Jul 5 16:42:36 DEBUG[213005]: channel.c:2324 ast_do_masquerade: Putting channel SIP/0192@ipcontact-cb69 in 16/16 formats Jul 5 16:42:36 DEBUG[213005]: chan_sip.c:1856 sip_fixup: sip_fixup called in SIP/0195@ipcontact-f4cc to SIP/0192@ipcontact-cb69 Jul 5 16:42:36 DEBUG[213005]: channel.c:2349 ast_do_masquerade: Released clone lock on 'SIP/0195@ipcontact-f4cc' Jul 5 16:42:36 DEBUG[213005]: channel.c:2357 ast_do_masquerade: Done Masquerading SIP/0192@ipcontact-cb69 (0) Jul 5 16:42:36 NOTICE[213005]: channel.c:2391 ast_setstate: Channel SIP/0192@ipcontact-cb69: state changed from:Down to state:Up -- SIP/0192@ipcontact-cb69 answered SIP/0190@ipcontact-f733 Jul 5 16:42:36 DEBUG[213005]: chan_sip.c:1903 sip_indicate: sip_indicate called in SIP/0190@ipcontact-f733 Jul 5 16:42:36 DEBUG[213005]: chan_sip.c:1781 sip_answer: sip_answer called in SIP/0190@ipcontact-f733 Jul 5 16:42:36 NOTICE[213005]: channel.c:2391 ast_setstate: Channel SIP/0190@ipcontact-f733: state changed from:Ring to state:Up Jul 5 16:42:36 DEBUG[213005]: chan_sip.c:3496 transmit_response_with_sdp: Adding UniqueId: 1089056540.0 to sip header Jul 5 16:42:36 NOTICE[213005]: channel.c:2391 ast_setstate: Channel SIP/0190@ipcontact-f733: state changed from:Up to state:Up -- Attempting native bridge of SIP/0190@ipcontact-f733 and SIP/0192@ipcontact-cb69 Jul 5 16:42:36 DEBUG[131080]: chan_sip.c:799 __sip_ack: Acked pending invite 102 Jul 5 16:42:36 DEBUG[131080]: chan_sip.c:817 __sip_ack: Stopping retransmission on '326db5f35ffd95df44c7a8831921dc6b@192.168.2.175' of Request 102: Found Jul 5 16:42:36 DEBUG[131080]: chan_sip.c:817 __sip_ack: Stopping retransmission on '326db5f35ffd95df44c7a8831921dc6b@192.168.2.175' of Request 102: Found Jul 5 16:42:36 WARNING[131080]: chan_sip.c:3100 reqprep: Cancel request From:'' To:'' Jul 5 16:42:36 DEBUG[131080]: chan_sip.c:817 __sip_ack: Stopping retransmission on '51b1bc-c0a802be-13c4-febad-3e30a2d0-7601@192.168.2.175' of Response 2: Found Jul 5 16:42:36 DEBUG[131080]: chan_sip.c:817 __sip_ack: Stopping retransmission on 'a6QzI-R*G0Af2@192.168.2.175' of Response 18: Found Jul 5 16:42:36 DEBUG[213005]: rtp.c:1132 ast_rtp_write: Ooh, format changed from UNKN to ULAW Jul 5 16:42:36 DEBUG[213005]: rtp.c:1132 ast_rtp_write: Ooh, format changed from UNKN to G726 obelix*CLI>