SIP call transfers

Hello,
I am using Asterisk@Home V2.6.
On one side it is connected to a Cisco Callmanager (CCM) and on the other a Voice Portal (VP).
This is because the Cisco Callmanager (CCM) in this Version does not support call transfers via SIP and the Voice Portal (VP) only has three channels.
The VPs task is to identify a destination phone number from a person connected to the CCM and then transfer the call to this destination.
I will try to give a short use case:
a cusomer calls in. This call is managed by the CCM. CCM calls 1002 on the Asterisk Server via SIP. Asterisk bridges the call to the VP. Here an other destination number is identified and this number is called on the Asterisk-Box, witch tryes to call this number on the CCM. If the connection is established the call should bridged in the Asterisk-Box and the connection to the VP should be released.

Here is the part of my extension.conf:


[from-sip-external]

exten => _Z.,1,NoOp(Calling ${EXTEN} from ${CALLERID(num)} Session ComeFromNumber: ${ComeFromNumber})
exten => _Z.,n,NoOp(extension: ${EXTEN})
exten => _Z.,n,NoOp(${CALLERID})
exten => _Z.,n,Dial(SIP/${EXTEN}@10.32.176.7,30,r)

exten => 1002,1,NoOp(Starting VP Extension from ${CALLERID} | ${CALLERID(num)})
exten => 1002,2,Set(ComeFromNumber=${CALLERID(num)})
exten => 1002,3,Dial(SIP/1004@10.32.176.14,10,tT)

exten => t,1,Hangup()
;exten => h,1,Hangup()


What happens:
The call with extension 1002 is bridged to the VP and the new destination is identified. The VP calls 3973@10.32.176.15 and the destination on the CCM is ringing. When the new destination answers the call one of two situations occure randomly:

  1. The both parties are connected and can speak together.
  2. Both connections are terminated.

I hope someone could help me with this configuration becaus I am very new to Asterisk.

I have attached some logger output. It seems to me that there are some problems with deadlocks (I do not realy know what this means).

Jürgen

Here is a not successfull call log from the fulllog:


Mar 24 11:59:38 DEBUG[30952] pbx.c: Function result is '3544’
Mar 24 11:59:38 VERBOSE[30952] logger.c: – Executing NoOp(“SIP/10.32.176.7-09f521a0”, “Starting VP from “VP” <3544> | 3544”) in new stack
Mar 24 11:59:38 DEBUG[30952] pbx.c: Function result is '3544’
Mar 24 11:59:38 VERBOSE[30952] logger.c: – Executing Set(“SIP/10.32.176.7-09f521a0”, “ComeFromNumber=3544”) in new stack
Mar 24 11:59:38 VERBOSE[30952] logger.c: – Executing Dial(“SIP/10.32.176.7-09f521a0”, “SIP/1004@10.32.176.14|10|tT”) in new stack
Mar 24 11:59:38 DEBUG[30952] chan_sip.c: Outgoing Call for 1004
Mar 24 11:59:38 DEBUG[29253] chan_sip.c: (Provisional) Stopping retransmission (but retaining packet) on ‘28160c7520348da4694d6d94084924b8@10.32.176.15’ Request 102: Found
Mar 24 11:59:38 VERBOSE[30952] logger.c: – Called 1004@10.32.176.14
Mar 24 11:59:38 DEBUG[29253] chan_sip.c: (Provisional) Stopping retransmission (but retaining packet) on ‘28160c7520348da4694d6d94084924b8@10.32.176.15’ Request 102: Found
Mar 24 11:59:38 DEBUG[29253] chan_sip.c: Acked pending invite 102
Mar 24 11:59:38 DEBUG[29253] chan_sip.c: Stopping retransmission on ‘28160c7520348da4694d6d94084924b8@10.32.176.15’ of Request 102: Match Found
Mar 24 11:59:38 DEBUG[29253] chan_sip.c: build_route: Contact hop:
Mar 24 11:59:38 VERBOSE[30952] logger.c: – SIP/10.32.176.14-348d is making progress passing it to SIP/10.32.176.7-09f521a0
Mar 24 11:59:38 DEBUG[29238] channel.c: Avoiding initial deadlock for 'SIP/10.32.176.14-348d’
Mar 24 11:59:38 DEBUG[29238] channel.c: Avoiding initial deadlock for 'SIP/10.32.176.14-348d’
Mar 24 11:59:38 DEBUG[29238] channel.c: Avoiding initial deadlock for 'SIP/10.32.176.14-348d’
Mar 24 11:59:38 DEBUG[29238] channel.c: Avoiding initial deadlock for 'SIP/10.32.176.14-348d’
Mar 24 11:59:38 DEBUG[29238] channel.c: Avoiding initial deadlock for 'SIP/10.32.176.14-348d’
Mar 24 11:59:38 DEBUG[29238] channel.c: Avoiding initial deadlock for 'SIP/10.32.176.14-348d’
Mar 24 11:59:38 DEBUG[29238] channel.c: Avoiding initial deadlock for 'SIP/10.32.176.14-348d’
Mar 24 11:59:38 DEBUG[29238] channel.c: Avoiding initial deadlock for 'SIP/10.32.176.14-348d’
Mar 24 11:59:38 DEBUG[29238] channel.c: Avoiding initial deadlock for 'SIP/10.32.176.14-348d’
Mar 24 11:59:38 DEBUG[29238] channel.c: Avoiding initial deadlock for 'SIP/10.32.176.14-348d’
Mar 24 11:59:38 WARNING[29238] channel.c: Avoided initial deadlock for ‘0x9f5d148’, 10 retries!
Mar 24 11:59:38 VERBOSE[30952] logger.c: – SIP/10.32.176.14-348d answered SIP/10.32.176.7-09f521a0
Mar 24 11:59:38 DEBUG[29238] channel.c: Avoiding initial deadlock for 'SIP/10.32.176.7-09f521a0’
Mar 24 11:59:38 DEBUG[29238] channel.c: Avoiding initial deadlock for 'SIP/10.32.176.7-09f521a0’
Mar 24 11:59:38 DEBUG[29238] channel.c: Avoiding initial deadlock for 'SIP/10.32.176.7-09f521a0’
Mar 24 11:59:38 DEBUG[29238] channel.c: Avoiding initial deadlock for 'SIP/10.32.176.7-09f521a0’
Mar 24 11:59:38 DEBUG[29238] channel.c: Avoiding initial deadlock for 'SIP/10.32.176.7-09f521a0’
Mar 24 11:59:38 DEBUG[29238] channel.c: Avoiding initial deadlock for 'SIP/10.32.176.7-09f521a0’
Mar 24 11:59:38 DEBUG[29238] channel.c: Avoiding initial deadlock for 'SIP/10.32.176.7-09f521a0’
Mar 24 11:59:38 DEBUG[29238] channel.c: Avoiding initial deadlock for ‘SIP/10.32.176.7-09f521a0’
Mar 24 11:59:38 DEBUG[29238] channel.c: Avoiding initial deadlock for ‘SIP/10.32.176.7-09f521a0’
Mar 24 11:59:38 DEBUG[29238] channel.c: Avoiding initial deadlock for ‘SIP/10.32.176.7-09f521a0’
Mar 24 11:59:38 WARNING[29238] channel.c: Avoided initial deadlock for ‘0x9f57578’, 10 retries!
Mar 24 11:59:38 DEBUG[29253] chan_sip.c: Stopping retransmission on ‘a29ea80-1db1d928-2f0-7b0200a@10.32.176.7’ of Response 101: Match Found
Mar 24 11:59:38 VERBOSE[30952] logger.c: – Attempting native bridge of SIP/10.32.176.7-09f521a0 and SIP/10.32.176.14-348d
Mar 24 11:59:42 DEBUG[29253] chan_sip.c: Checking SIP call limits for device
Mar 24 11:59:42 DEBUG[29253] chan_sip.c: build_route: Contact hop:
Mar 24 11:59:42 DEBUG[30956] pbx.c: Function result is ‘3544’
Mar 24 11:59:42 VERBOSE[30956] logger.c: – Executing NoOp(“SIP/5060-09f669c8”, "Calling 3973 from 3544 Session ComeFromNumber: ") in new stack
Mar 24 11:59:42 VERBOSE[30956] logger.c: – Executing NoOp(“SIP/5060-09f669c8”, “extension: 3973”) in new stack
Mar 24 11:59:42 VERBOSE[30956] logger.c: – Executing NoOp(“SIP/5060-09f669c8”, “3544”) in new stack
Mar 24 11:59:42 VERBOSE[30956] logger.c: – Executing Dial(“SIP/5060-09f669c8”, “SIP/3973@10.32.176.7|30|r”) in new stack
Mar 24 11:59:42 DEBUG[30956] chan_sip.c: Outgoing Call for 3973
Mar 24 11:59:42 VERBOSE[30956] logger.c: – Called 3973@10.32.176.7
Mar 24 11:59:42 DEBUG[29253] chan_sip.c: (Provisional) Stopping retransmission (but retaining packet) on ‘57a1bb4663bd6b0f1f5d71d83de178e2@10.32.176.15’ Request 102: Found
Mar 24 11:59:42 DEBUG[29253] chan_sip.c: (Provisional) Stopping retransmission (but retaining packet) on ‘57a1bb4663bd6b0f1f5d71d83de178e2@10.32.176.15’ Request 102: Found
Mar 24 11:59:42 VERBOSE[30956] logger.c: – SIP/10.32.176.7-8d76 is ringing
Mar 24 11:59:44 DEBUG[29253] chan_sip.c: Acked pending invite 102
Mar 24 11:59:44 DEBUG[29253] chan_sip.c: Stopping retransmission on ‘57a1bb4663bd6b0f1f5d71d83de178e2@10.32.176.15’ of Request 102: Match Found
Mar 24 11:59:44 DEBUG[29253] chan_sip.c: build_route: Contact hop:
Mar 24 11:59:44 VERBOSE[30956] logger.c: – SIP/10.32.176.7-8d76 answered SIP/5060-09f669c8
Mar 24 11:59:44 VERBOSE[30956] logger.c: – Attempting native bridge of SIP/5060-09f669c8 and SIP/10.32.176.7-8d76
Mar 24 11:59:44 DEBUG[29253] chan_sip.c: Stopping retransmission on ‘00020042-7C001DBD-5060@10.32.176.14’ of Response 1: Match Found
Mar 24 11:59:44 DEBUG[29253] chan_sip.c: Sending pending reinvite on ‘00020042-7C001DBD-5060@10.32.176.14’
Mar 24 11:59:44 DEBUG[29253] chan_sip.c: Assigning Replace-Call-ID Info 00020042-7C001DBD-5060@10.32.176.14 to REPLACE_CALL_ID
Mar 24 11:59:44 DEBUG[29253] chan_sip.c: 202 Accepted (supervised)
Mar 24 11:59:44 DEBUG[29253] channel.c: Planning to masquerade channel SIP/10.32.176.7-09f521a0 into the structure of SIP/5060-09f669c8
Mar 24 11:59:44 DEBUG[29253] channel.c: Done planning to masquerade channel SIP/10.32.176.7-09f521a0 into the structure of SIP/5060-09f669c8
Mar 24 11:59:44 DEBUG[29253] chan_sip.c: (Provisional) Stopping retransmission (but retaining packet) on ‘57a1bb4663bd6b0f1f5d71d83de178e2@10.32.176.15’ Request 103: Found
Mar 24 11:59:44 DEBUG[29253] chan_sip.c: Acked pending invite 102
Mar 24 11:59:44 DEBUG[29253] chan_sip.c: Stopping retransmission on ‘00020042-7C001DBD-5060@10.32.176.14’ of Request 102: Match Found
Mar 24 11:59:44 DEBUG[29253] chan_sip.c: build_route: Contact hop:
Mar 24 11:59:44 DEBUG[29253] chan_sip.c: Stopping retransmission on ‘28160c7520348da4694d6d94084924b8@10.32.176.15’ of Request 103: Match Found
Mar 24 11:59:44 WARNING[29253] chan_sip.c: Notify answer on an owned channel?
Mar 24 11:59:44 DEBUG[30952] channel.c: Didn’t get a frame from channel: SIP/10.32.176.14-348d
Mar 24 11:59:44 DEBUG[30952] channel.c: Bridge stops bridging channels SIP/10.32.176.7-09f521a0 and SIP/10.32.176.14-348d
Mar 24 11:59:44 DEBUG[30952] chan_sip.c: update_call_counter(1004) - decrement call limit counter
Mar 24 11:59:44 DEBUG[30952] app_dial.c: Exiting with DIALSTATUS=ANSWER.
Mar 24 11:59:44 VERBOSE[30952] logger.c: == Spawn extension (from-sip-external, 1002, 3) exited non-zero on ‘SIP/10.32.176.7-09f521a0’
Mar 24 11:59:44 DEBUG[29253] chan_sip.c: Stopping retransmission on ‘28160c7520348da4694d6d94084924b8@10.32.176.15’ of Request 104: Match Found
Mar 24 11:59:44 DEBUG[29253] chan_sip.c: Acked pending invite 103
Mar 24 11:59:44 DEBUG[29253] chan_sip.c: Stopping retransmission on ‘57a1bb4663bd6b0f1f5d71d83de178e2@10.32.176.15’ of Request 103: Match Found
Mar 24 11:59:44 DEBUG[29253] chan_sip.c: build_route: Retaining previous route:
Mar 24 11:59:44 DEBUG[30956] channel.c: Got clone lock for masquerade on ‘SIP/10.32.176.7-09f521a0’ at 0x9f57644
Mar 24 11:59:44 DEBUG[30956] chan_sip.c: update_call_counter() - decrement call limit counter
Mar 24 11:59:44 DEBUG[30956] channel.c: Putting channel SIP/10.32.176.7-09f521a0 in 4/4 formats
Mar 24 11:59:44 DEBUG[30956] channel.c: Destroying channel clone ‘SIP/5060-09f669c8’
Mar 24 11:59:44 DEBUG[30956] channel.c: Done Masquerading SIP/10.32.176.7-09f521a0 (6)
Mar 24 11:59:44 DEBUG[30956] rtp.c: Oooh, something is weird, backing out
Mar 24 11:59:44 DEBUG[30956] channel.c: Bridge stops because we’re zombie or need a soft hangup: c0=SIP/10.32.176.7-09f521a0, c1=SIP/10.32.176.7-8d76, flags: No,Yes,No,No
Mar 24 11:59:44 DEBUG[30956] channel.c: Bridge stops bridging channels SIP/10.32.176.7-09f521a0 and SIP/10.32.176.7-8d76
Mar 24 11:59:44 DEBUG[30956] chan_sip.c: update_call_counter(3973) - decrement call limit counter
Mar 24 11:59:44 DEBUG[30956] app_dial.c: Exiting with DIALSTATUS=ANSWER.
Mar 24 11:59:44 VERBOSE[30956] logger.c: == Spawn extension (from-sip-external, 3973, 4) exited non-zero on ‘SIP/10.32.176.7-09f521a0’
Mar 24 11:59:44 DEBUG[29253] chan_sip.c: (Provisional) Stopping retransmission (but retaining packet) on ‘57a1bb4663bd6b0f1f5d71d83de178e2@10.32.176.15’ Request 104: Found
Mar 24 11:59:44 DEBUG[30956] cdr_addon_mysql.c: cdr_mysql: inserting a CDR record.
Mar 24 11:59:44 DEBUG[30956] cdr_addon_mysql.c: cdr_mysql: SQL command as follows: INSERT INTO cdr (calldate,clid,src,dst,dcontext,channel,dstchannel,lastapp,lastdata,duration,billsec,disposition,amaflags,accountcode,uniqueid) VALUES (‘2006-03-24 11:59:42’,’“VP” <3544>’,‘3544’,‘3973’,‘from-sip-external’, ‘SIP/5060-09f669c8’,‘SIP/10.32.176.7-8d76’,‘Dial’,‘SIP/3973@10.32.176.7|30|r’,2,0,‘ANSWERED’,3,’’,‘1143197982.205’)
Mar 24 11:59:44 DEBUG[29253] chan_sip.c: Acked pending invite 104
Mar 24 11:59:44 DEBUG[29253] chan_sip.c: Stopping retransmission on ‘57a1bb4663bd6b0f1f5d71d83de178e2@10.32.176.15’ of Request 104: Match Found
Mar 24 11:59:44 DEBUG[29253] chan_sip.c: build_route: Retaining previous route:
Mar 24 11:59:44 DEBUG[30956] cdr_addon_mysql.c: cdr_mysql: inserting a CDR record.
Mar 24 11:59:44 DEBUG[30956] cdr_addon_mysql.c: cdr_mysql: SQL command as follows: INSERT INTO cdr (calldate,clid,src,dst,dcontext,channel,dstchannel,lastapp,lastdata,duration,billsec,disposition,amaflags,accountcode,uniqueid) VALUES (‘2006-03-24 11:59:38’,’“VP” <3544>’,‘3544’,‘3973’,‘from-sip-external’, ‘SIP/10.32.176.7-09f521a0’,‘SIP/10.32.176.14-348d’,‘Dial’,‘SIP/1004@10.32.176.14|10|tT’,6,6,‘ANSWERED’,3,’’,‘1143197978.203’)
Mar 24 11:59:44 DEBUG[30956] chan_sip.c: update_call_counter() - decrement call limit counter
Mar 24 11:59:44 DEBUG[29253] chan_sip.c: Stopping retransmission on ‘57a1bb4663bd6b0f1f5d71d83de178e2@10.32.176.15’ of Request 105: Match Found
Mar 24 11:59:44 DEBUG[29253] chan_sip.c: Stopping retransmission on ‘a29ea80-1db1d928-2f0-7b0200a@10.32.176.7’ of Request 102: Match Found
Mar 24 11:59:44 DEBUG[29253] chan_sip.c: Stopping retransmission on ‘a29ea80-1db1d928-2f0-7b0200a@10.32.176.7’ of Request 102: Match Found


And one of a sucessfull call:


Mar 24 12:15:11 DEBUG[29253] chan_sip.c: Checking SIP call limits for device
Mar 24 12:15:11 DEBUG[29253] chan_sip.c: build_route: Contact hop:
Mar 24 12:15:11 DEBUG[31042] pbx.c: Function result is '3544’
Mar 24 12:15:11 VERBOSE[31042] logger.c: – Executing NoOp(“SIP/10.32.176.7-09f522e0”, “Starting VP Extension from “VP” <3544> | 3544”) in new stack
Mar 24 12:15:11 DEBUG[31042] pbx.c: Function result is '3544’
Mar 24 12:15:11 VERBOSE[31042] logger.c: – Executing Set(“SIP/10.32.176.7-09f522e0”, “ComeFromNumber=3544”) in new stack
Mar 24 12:15:11 VERBOSE[31042] logger.c: – Executing Dial(“SIP/10.32.176.7-09f522e0”, “SIP/1004@10.32.176.14|10|tT”) in new stack
Mar 24 12:15:11 DEBUG[31042] chan_sip.c: Outgoing Call for 1004
Mar 24 12:15:11 VERBOSE[31042] logger.c: – Called 1004@10.32.176.14
Mar 24 12:15:11 DEBUG[29253] chan_sip.c: (Provisional) Stopping retransmission (but retaining packet) on ‘48add8826cc547f753e5673843d1ce0c@10.32.176.15’ Request 102: Found
Mar 24 12:15:11 DEBUG[29253] chan_sip.c: (Provisional) Stopping retransmission (but retaining packet) on ‘48add8826cc547f753e5673843d1ce0c@10.32.176.15’ Request 102: Found
Mar 24 12:15:11 DEBUG[29253] chan_sip.c: Acked pending invite 102
Mar 24 12:15:11 DEBUG[29253] chan_sip.c: Stopping retransmission on ‘48add8826cc547f753e5673843d1ce0c@10.32.176.15’ of Request 102: Match Found
Mar 24 12:15:11 DEBUG[29253] chan_sip.c: build_route: Contact hop:
Mar 24 12:15:11 VERBOSE[31042] logger.c: – SIP/10.32.176.14-7f4b is making progress passing it to SIP/10.32.176.7-09f522e0
Mar 24 12:15:11 VERBOSE[31042] logger.c: – SIP/10.32.176.14-7f4b answered SIP/10.32.176.7-09f522e0
Mar 24 12:15:11 VERBOSE[31042] logger.c: – Attempting native bridge of SIP/10.32.176.7-09f522e0 and SIP/10.32.176.14-7f4b
Mar 24 12:15:11 DEBUG[29253] chan_sip.c: Stopping retransmission on ‘10b96180-1db1d92a-2fa-7b0200a@10.32.176.7’ of Response 101: Match Found
Mar 24 12:15:16 DEBUG[29253] chan_sip.c: Checking SIP call limits for device
Mar 24 12:15:16 DEBUG[29253] chan_sip.c: build_route: Contact hop:
Mar 24 12:15:16 DEBUG[31046] pbx.c: Function result is '3544’
Mar 24 12:15:16 VERBOSE[31046] logger.c: – Executing NoOp(“SIP/5060-09f669c8”, "Calling 3973 from 3544 Session ComeFromNumber: ") in new stack
Mar 24 12:15:16 VERBOSE[31046] logger.c: – Executing NoOp(“SIP/5060-09f669c8”, “extension: 3973”) in new stack
Mar 24 12:15:16 VERBOSE[31046] logger.c: – Executing NoOp(“SIP/5060-09f669c8”, “3544”) in new stack
Mar 24 12:15:16 VERBOSE[31046] logger.c: – Executing Dial(“SIP/5060-09f669c8”, “SIP/3973@10.32.176.7|30|r”) in new stack
Mar 24 12:15:16 DEBUG[31046] chan_sip.c: Outgoing Call for 3973
Mar 24 12:15:16 VERBOSE[31046] logger.c: – Called 3973@10.32.176.7
Mar 24 12:15:16 DEBUG[29253] chan_sip.c: (Provisional) Stopping retransmission (but retaining packet) on ‘49cd4a5d263d1b4061ab67ec46d98a69@10.32.176.15’ Request 102: Found
Mar 24 12:15:16 DEBUG[29253] chan_sip.c: (Provisional) Stopping retransmission (but retaining packet) on ‘49cd4a5d263d1b4061ab67ec46d98a69@10.32.176.15’ Request 102: Found
Mar 24 12:15:16 VERBOSE[31046] logger.c: – SIP/10.32.176.7-e597 is ringing
Mar 24 12:15:17 DEBUG[29253] chan_sip.c: Acked pending invite 102
Mar 24 12:15:17 DEBUG[29253] chan_sip.c: Stopping retransmission on ‘49cd4a5d263d1b4061ab67ec46d98a69@10.32.176.15’ of Request 102: Match Found
Mar 24 12:15:17 DEBUG[29253] chan_sip.c: build_route: Contact hop:
Mar 24 12:15:17 DEBUG[29238] channel.c: Avoiding initial deadlock for 'SIP/10.32.176.7-e597’
Mar 24 12:15:17 VERBOSE[31046] logger.c: – SIP/10.32.176.7-e597 answered SIP/5060-09f669c8
Mar 24 12:15:17 VERBOSE[31046] logger.c: – Attempting native bridge of SIP/5060-09f669c8 and SIP/10.32.176.7-e597
Mar 24 12:15:17 DEBUG[29253] chan_sip.c: Stopping retransmission on ‘00020042-7C001DC2-5060@10.32.176.14’ of Response 1: Match Found
Mar 24 12:15:17 DEBUG[29253] chan_sip.c: Sending pending reinvite on '00020042-7C001DC2-5060@10.32.176.14’
Mar 24 12:15:17 DEBUG[29253] chan_sip.c: (Provisional) Stopping retransmission (but retaining packet) on ‘49cd4a5d263d1b4061ab67ec46d98a69@10.32.176.15’ Request 103: Found
Mar 24 12:15:17 DEBUG[29253] chan_sip.c: Assigning Replace-Call-ID Info 00020042-7C001DC2-5060@10.32.176.14 to REPLACE_CALL_ID
Mar 24 12:15:17 DEBUG[29253] chan_sip.c: 202 Accepted (supervised)
Mar 24 12:15:17 DEBUG[29253] channel.c: Planning to masquerade channel SIP/10.32.176.7-09f522e0 into the structure of SIP/5060-09f669c8
Mar 24 12:15:17 DEBUG[29253] channel.c: Done planning to masquerade channel SIP/10.32.176.7-09f522e0 into the structure of SIP/5060-09f669c8
Mar 24 12:15:17 DEBUG[29253] chan_sip.c: Acked pending invite 102
Mar 24 12:15:17 DEBUG[29253] chan_sip.c: Stopping retransmission on ‘00020042-7C001DC2-5060@10.32.176.14’ of Request 102: Match Found
Mar 24 12:15:17 DEBUG[29253] chan_sip.c: build_route: Contact hop:
Mar 24 12:15:17 DEBUG[29253] chan_sip.c: Acked pending invite 103
Mar 24 12:15:17 DEBUG[29253] chan_sip.c: Stopping retransmission on ‘49cd4a5d263d1b4061ab67ec46d98a69@10.32.176.15’ of Request 103: Match Found
Mar 24 12:15:17 DEBUG[29253] chan_sip.c: build_route: Retaining previous route:
Mar 24 12:15:17 DEBUG[31046] channel.c: Got clone lock for masquerade on ‘SIP/10.32.176.7-09f522e0’ at 0x9f57784
Mar 24 12:15:17 DEBUG[31046] chan_sip.c: update_call_counter() - decrement call limit counter
Mar 24 12:15:17 DEBUG[31046] channel.c: Putting channel SIP/10.32.176.7-09f522e0 in 4/4 formats
Mar 24 12:15:17 DEBUG[31046] channel.c: Released clone lock on 'SIP/5060-09f669c8’
Mar 24 12:15:17 DEBUG[31046] channel.c: Done Masquerading SIP/10.32.176.7-09f522e0 (6)
Mar 24 12:15:17 DEBUG[31046] rtp.c: Oooh, something is weird, backing out
Mar 24 12:15:17 VERBOSE[31046] logger.c: – Attempting native bridge of SIP/10.32.176.7-09f522e0 and SIP/10.32.176.7-e597
Mar 24 12:15:17 DEBUG[31042] channel.c: Bridge stops because we’re zombie or need a soft hangup: c0=SIP/5060-09f669c8, c1=SIP/10.32.176.14-7f4b, flags: Yes,Yes,No,No
Mar 24 12:15:17 DEBUG[31042] channel.c: Bridge stops bridging channels SIP/5060-09f669c8 and SIP/10.32.176.14-7f4b
Mar 24 12:15:17 DEBUG[31042] chan_sip.c: update_call_counter(1004) - decrement call limit counter
Mar 24 12:15:17 DEBUG[31042] app_dial.c: Exiting with DIALSTATUS=ANSWER.
Mar 24 12:15:17 VERBOSE[31042] logger.c: == Spawn extension (from-sip-external, 1002, 3) exited non-zero on ‘SIP/5060-09f669c8’
Mar 24 12:15:17 DEBUG[29253] chan_sip.c: Stopping retransmission on ‘48add8826cc547f753e5673843d1ce0c@10.32.176.15’ of Request 103: Match Found
Mar 24 12:15:17 DEBUG[29253] chan_sip.c: Stopping retransmission on ‘48add8826cc547f753e5673843d1ce0c@10.32.176.15’ of Request 104: Match Found
Mar 24 12:15:17 DEBUG[29253] chan_sip.c: Stopping retransmission on ‘00020042-7C001DC2-5060@10.32.176.14’ of Request 103: Match Found
Mar 24 12:15:17 VERBOSE[29253] logger.c: – Got SIP response 411 “Bad Request” back from 10.32.176.14
Mar 24 12:15:17 DEBUG[29253] chan_sip.c: (Provisional) Stopping retransmission (but retaining packet) on ‘49cd4a5d263d1b4061ab67ec46d98a69@10.32.176.15’ Request 104: Found
Mar 24 12:15:17 DEBUG[29253] chan_sip.c: (Provisional) Stopping retransmission (but retaining packet) on ‘10b96180-1db1d92a-2fa-7b0200a@10.32.176.7’ Request 102: Found
Mar 24 12:15:17 DEBUG[29253] chan_sip.c: Acked pending invite 104
Mar 24 12:15:17 DEBUG[29253] chan_sip.c: Stopping retransmission on ‘49cd4a5d263d1b4061ab67ec46d98a69@10.32.176.15’ of Request 104: Match Found
Mar 24 12:15:17 DEBUG[29253] chan_sip.c: build_route: Retaining previous route:
Mar 24 12:15:17 DEBUG[29253] chan_sip.c: Sending pending reinvite on ‘49cd4a5d263d1b4061ab67ec46d98a69@10.32.176.15’
Mar 24 12:15:17 DEBUG[29253] chan_sip.c: Acked pending invite 102
Mar 24 12:15:17 DEBUG[29253] chan_sip.c: Stopping retransmission on ‘10b96180-1db1d92a-2fa-7b0200a@10.32.176.7’ of Request 102: Match Found
Mar 24 12:15:17 DEBUG[29253] chan_sip.c: build_route: Contact hop:
Mar 24 12:15:17 DEBUG[29253] chan_sip.c: (Provisional) Stopping retransmission (but retaining packet) on ‘49cd4a5d263d1b4061ab67ec46d98a69@10.32.176.15’ Request 105: Found
Mar 24 12:15:17 DEBUG[29253] chan_sip.c: Acked pending invite 105
Mar 24 12:15:17 DEBUG[29253] chan_sip.c: Stopping retransmission on ‘49cd4a5d263d1b4061ab67ec46d98a69@10.32.176.15’ of Request 105: Match Found
Mar 24 12:15:17 DEBUG[29253] chan_sip.c: build_route: Retaining previous route:
Mar 24 12:15:21 DEBUG[31046] channel.c: Returning from native bridge, channels: SIP/10.32.176.7-09f522e0, SIP/10.32.176.7-e597
Mar 24 12:15:21 DEBUG[31046] chan_sip.c: update_call_counter(3973) - decrement call limit counter
Mar 24 12:15:21 DEBUG[31046] app_dial.c: Exiting with DIALSTATUS=ANSWER.
Mar 24 12:15:21 VERBOSE[31046] logger.c: == Spawn extension (from-sip-external, 3973, 4) exited non-zero on ‘SIP/10.32.176.7-09f522e0’
Mar 24 12:15:21 DEBUG[29238] channel.c: Avoiding initial deadlock for ‘SIP/10.32.176.7-09f522e0’
Mar 24 12:15:21 DEBUG[29253] chan_sip.c: Failed to grab lock, trying again…
Mar 24 12:15:21 DEBUG[31046] cdr_addon_mysql.c: cdr_mysql: inserting a CDR record.
Mar 24 12:15:21 DEBUG[31046] cdr_addon_mysql.c: cdr_mysql: SQL command as follows: INSERT INTO cdr (calldate,clid,src,dst,dcontext,channel,dstchannel,lastapp,lastdata,duration,billsec,disposition,amaflags,accountcode,uniqueid) VALUES (‘2006-03-24 12:15:16’,’“VP” <3544>’,‘3544’,‘3973’,‘from-sip-external’, ‘SIP/5060-09f669c8’,‘SIP/10.32.176.7-e597’,‘Dial’,‘SIP/3973@10.32.176.7|30|r’,5,4,‘ANSWERED’,3,’’,‘1143198916.225’)
Mar 24 12:15:21 DEBUG[29238] channel.c: Avoiding initial deadlock for ‘SIP/10.32.176.7-09f522e0’
Mar 24 12:15:21 DEBUG[29253] chan_sip.c: Failed to grab lock, trying again…
Mar 24 12:15:21 DEBUG[29253] chan_sip.c: Failed to grab lock, trying again…
Mar 24 12:15:21 DEBUG[29253] chan_sip.c: Failed to grab lock, trying again…
Mar 24 12:15:21 DEBUG[29238] channel.c: Avoiding initial deadlock for ‘SIP/10.32.176.7-09f522e0’
Mar 24 12:15:21 DEBUG[29253] chan_sip.c: Failed to grab lock, trying again…
Mar 24 12:15:21 DEBUG[29253] chan_sip.c: Failed to grab lock, trying again…
Mar 24 12:15:21 DEBUG[29253] chan_sip.c: Failed to grab lock, trying again…
Mar 24 12:15:21 DEBUG[29238] channel.c: Avoiding initial deadlock for ‘SIP/10.32.176.7-09f522e0’
Mar 24 12:15:21 DEBUG[29253] chan_sip.c: Failed to grab lock, trying again…
Mar 24 12:15:21 DEBUG[29253] chan_sip.c: Failed to grab lock, trying again…
Mar 24 12:15:21 DEBUG[29238] channel.c: Avoiding initial deadlock for ‘SIP/10.32.176.7-09f522e0’
Mar 24 12:15:21 DEBUG[29253] chan_sip.c: Failed to grab lock, trying again…
Mar 24 12:15:21 DEBUG[29253] chan_sip.c: Failed to grab lock, trying again…
Mar 24 12:15:21 DEBUG[29253] chan_sip.c: Failed to grab lock, trying again…
Mar 24 12:15:21 DEBUG[31046] cdr_addon_mysql.c: cdr_mysql: inserting a CDR record.
Mar 24 12:15:21 DEBUG[31046] cdr_addon_mysql.c: cdr_mysql: SQL command as follows: INSERT INTO cdr (calldate,clid,src,dst,dcontext,channel,dstchannel,lastapp,lastdata,duration,billsec,disposition,amaflags,accountcode,uniqueid) VALUES (‘2006-03-24 12:15:11’,’“VP” <3544>’,‘3544’,‘3973’,‘from-sip-external’, ‘SIP/10.32.176.7-09f522e0’,‘SIP/10.32.176.14-7f4b’,‘Dial’,‘SIP/1004@10.32.176.14|10|tT’,10,10,‘ANSWERED’,3,’’,‘1143198911.223’)
Mar 24 12:15:21 DEBUG[29238] channel.c: Avoiding initial deadlock for 'SIP/10.32.176.7-09f522e0’
Mar 24 12:15:21 DEBUG[29253] chan_sip.c: Failed to grab lock, trying again…
Mar 24 12:15:21 DEBUG[29253] chan_sip.c: Failed to grab lock, trying again…
Mar 24 12:15:21 DEBUG[29238] channel.c: Avoiding initial deadlock for 'SIP/10.32.176.7-09f522e0’
Mar 24 12:15:21 DEBUG[29253] chan_sip.c: Failed to grab lock, trying again…
Mar 24 12:15:21 DEBUG[29253] chan_sip.c: Failed to grab lock, trying again…
Mar 24 12:15:21 DEBUG[29253] chan_sip.c: Failed to grab lock, trying again…
Mar 24 12:15:21 DEBUG[31046] chan_sip.c: update_call_counter() - decrement call limit counter
Mar 24 12:15:21 DEBUG[29253] chan_sip.c: (Provisional) Stopping retransmission (but retaining packet) on ‘10b96180-1db1d92a-2fa-7b0200a@10.32.176.7’ Request 103: Found
Mar 24 12:15:21 DEBUG[29253] chan_sip.c: Acked pending invite 103
Mar 24 12:15:21 DEBUG[29253] chan_sip.c: Stopping retransmission on ‘10b96180-1db1d92a-2fa-7b0200a@10.32.176.7’ of Request 103: Match Found
Mar 24 12:15:21 DEBUG[29253] chan_sip.c: build_route: Retaining previous route:
Mar 24 12:15:21 DEBUG[29253] chan_sip.c: Stopping retransmission on ‘10b96180-1db1d92a-2fa-7b0200a@10.32.176.7’ of Request 104: Match Found
Mar 24 12:15:21 DEBUG[29253] chan_sip.c: Stopping retransmission on ‘10b96180-1db1d92a-2fa-7b0200a@10.32.176.7’ of Request 104: Match Found