Read Factory %p was pretty quick last time Delays 2way Audio

skelly · February 17, 2009, 5:54pm

Hello,

I’m new to the forum and very much a novice with Asterisk, so if I don’t provide all the right info or need some things explained to me, please don’t hate me haha.

We’re having a bit of a problem with the following error message coming up only on one of our servers (1.4.23), and its running numbers through more than 1 provider (Vitelity, Icall, Etc).

Occasionally, with no currently discerned pattern, calls will take on average 8 seconds(but upwards of 17) to fully bridge 2 way audio. Searching online, I find alot of people who seem to have a similiar problem, but no solutions (With the exception of turning off recording, which is not an option). As an example, the scenario usually plays out like this:

Phone Rings
Person Answers
8 seconds of "Hello? Hello?"
2 way audio finally established.

My guess is that since turning recording off is will remove the problem, it has something to do possibly with a delayed response from the request to create the new file, or possibly access a scratch-file that gets used internally to cache some audio data? (That’s essentially my first thought, based on what seems to be happening, but I could be way off)

The message itself comes from line 207 of Audiohook.c

Does anyone know anything that may account for this occuring randomly (or what seems like randomly) across our calls? From the code, it seems like it would occur when the difference between right now and the last time the audio-hook read audio was too small, compared to the amount of samples we’d expect to receive.

That said, it doesn’t exactly help me figure out the problem haha. Unfortunately, our guy who is the expert with Asterisk (Who had also started to look into the problem) is not in this week, but I do know we have a 1.2.16 server (i think… it’s in the 1.2s for certain, but that server is outside the scope of this issue) where this problem has never occurred (To our knowledge…)

Any possible help anyone can provide to shed some light on this subject would be a huge help.

Thanks in advance

skelly · February 19, 2009, 6:14pm

Noone has any idea of what may be behind this?

ianplain · February 19, 2009, 8:00pm

Hi.

A sip trace may help here so we can see if all the messages are getting through

Ian

skelly · February 20, 2009, 6:03pm

The problem appears intermittently - I currently don’t have any SIP Traces saved that I can show unless I capture a large area of time and “hope” it occurs.

I will try to capture the error occurring in the wild and post back here with a trace when it’s available

skelly · March 6, 2009, 10:48pm

Sorry for the delay - Please find a trace containing the problem provided below

For quickly finding the lines in question where the error occurs, please search for:

audiohook.c: Read factory 0x9b17768 was pretty quick last time, waiting for them.

It appears numerous times during the lifetime of the trace

[Mar 6 17:04:06] VERBOSE[13033] logger.c: Asterisk Event Logger restarted
[Mar 6 17:04:06] VERBOSE[13033] logger.c: Asterisk Queue Logger restarted
[Mar 6 17:04:22] DEBUG[16390] chan_sip.c: Setting NAT on RTP to Off
[Mar 6 17:04:22] DEBUG[16390] chan_sip.c: Allocating new SIP dialog for BOSMGC0320090306221543019314@209.244.63.175 - INVITE (With RTP)
[Mar 6 17:04:22] DEBUG[16390] chan_sip.c: **** Received INVITE (5) - Command in SIP INVITE
[Mar 6 17:04:22] DEBUG[16390] chan_sip.c: Setting NAT on RTP to Off
[Mar 6 17:04:22] DEBUG[16390] chan_sip.c: T38 state changed to 0 on channel
[Mar 6 17:04:22] DEBUG[16390] chan_sip.c: We’re settling with these formats: 0x4 (ulaw)
[Mar 6 17:04:22] DEBUG[16390] chan_sip.c: Checking SIP call limits for device
[Mar 6 17:04:22] DEBUG[16390] chan_sip.c: Updating call counter for incoming call
[Mar 6 17:04:22] DEBUG[16390] chan_sip.c: *** Our native formats are 0x4 (ulaw)
[Mar 6 17:04:22] DEBUG[16390] chan_sip.c: *** Joint capabilities are 0x4 (ulaw)
[Mar 6 17:04:22] DEBUG[16390] chan_sip.c: *** Our capabilities are 0x8000e (gsm|ulaw|alaw|h263)
[Mar 6 17:04:22] DEBUG[16390] chan_sip.c: *** AST_CODEC_CHOOSE formats are 0x4 (ulaw)
[Mar 6 17:04:22] DEBUG[16390] chan_sip.c: This channel will not be able to handle video.
[Mar 6 17:04:22] DEBUG[16390] chan_sip.c: build_route: Record-Route hop: sip:216.82.224.202;lr;ftag=VPSF506071629460
[Mar 6 17:04:22] DEBUG[16390] chan_sip.c: build_route: Record-Route hop: sip:4.79.212.229;lr;ftag=VPSF506071629460
[Mar 6 17:04:22] DEBUG[16390] chan_sip.c: SIP/4.68.250.148-09b3a900: New call is still down… Trying…
[Mar 6 17:04:22] DEBUG[16390] devicestate.c: Notification of state change to be queued on device/channel SIP/4.68.250.148
[Mar 6 17:04:22] DEBUG[16384] devicestate.c: No provider found, checking channel drivers for SIP - 4.68.250.148
[Mar 6 17:04:22] DEBUG[16384] chan_sip.c: Checking device state for peer 4.68.250.148
[Mar 6 17:04:22] DEBUG[16384] devicestate.c: Changing state for SIP/4.68.250.148 - state 2 (In use)
[Mar 6 17:04:22] DEBUG[16409] app_queue.c: Device ‘SIP/4.68.250.148’ changed to state ‘2’ (In use) but we don’t care because they’re not a member of any queue.
[Mar 6 17:04:22] DEBUG[13034] pbx.c: Launching ‘Goto’
[Mar 6 17:04:22] VERBOSE[13034] logger.c: – Executing [+1INBOUND_NUMBER@default:1] Goto(“SIP/4.68.250.148-09b3a900”, “from-trunk|INBOUND_NUMBER|1”) in new stack
[Mar 6 17:04:22] VERBOSE[13034] logger.c: – Goto (from-trunk,INBOUND_NUMBER,1)
[Mar 6 17:04:22] DEBUG[13034] pbx.c: Function result is ‘FORWARDING_NUMBER’
[Mar 6 17:04:22] DEBUG[13034] pbx.c: Launching ‘Set’
[Mar 6 17:04:22] VERBOSE[13034] logger.c: – Executing [INBOUND_NUMBER@from-trunk:1] Set(“SIP/4.68.250.148-09b3a900”, “MAP5=FORWARDING_NUMBER”) in new stack
[Mar 6 17:04:22] DEBUG[13034] pbx.c: Launching ‘GotoIf’
[Mar 6 17:04:22] VERBOSE[13034] logger.c: – Executing [INBOUND_NUMBER@from-trunk:2] GotoIf(“SIP/4.68.250.148-09b3a900”, “FORWARDING_NUMBER?V2DASH|INBOUND_NUMBER|1”) in new stack
[Mar 6 17:04:22] VERBOSE[13034] logger.c: – Goto (V2DASH,INBOUND_NUMBER,1)
[Mar 6 17:04:22] DEBUG[13034] pbx.c: Launching ‘NoOp’
[Mar 6 17:04:22] VERBOSE[13034] logger.c: – Executing [INBOUND_NUMBER@V2DASH:1] NoOp(“SIP/4.68.250.148-09b3a900”, “ctx: V2DASH”) in new stack
[Mar 6 17:04:22] DEBUG[13034] pbx.c: Function result is ‘+1CALLERID[NUMBER]’
[Mar 6 17:04:22] DEBUG[13034] pbx.c: Launching ‘Set’
[Mar 6 17:04:22] VERBOSE[13034] logger.c: – Executing [INBOUND_NUMBER@V2DASH:2] Set(“SIP/4.68.250.148-09b3a900”, “NUM=+1CALLERID[NUMBER]”) in new stack
[Mar 6 17:04:22] DEBUG[13034] pbx.c: Expression result is ‘1’
[Mar 6 17:04:22] DEBUG[13034] pbx.c: Expression result is ‘0’
[Mar 6 17:04:22] DEBUG[13034] pbx.c: Function result is ‘+1CALLERID[NUMBER]’
[Mar 6 17:04:22] DEBUG[13034] pbx.c: Function result is ‘CALLERID[NUMBER]’
[Mar 6 17:04:22] DEBUG[13034] pbx.c: Launching ‘Set’
[Mar 6 17:04:22] VERBOSE[13034] logger.c: – Executing [INBOUND_NUMBER@V2DASH:3] Set(“SIP/4.68.250.148-09b3a900”, “CID=CALLERID[NUMBER]”) in new stack
[Mar 6 17:04:22] DEBUG[13034] pbx.c: Launching ‘Verbose’
[Mar 6 17:04:22] VERBOSE[13034] logger.c: – Executing [INBOUND_NUMBER@V2DASH:4] Verbose(“SIP/4.68.250.148-09b3a900”, “trimmed caller id is CALLERID[NUMBER]”) in new stack
[Mar 6 17:04:22] VERBOSE[13034] logger.c: trimmed caller id is CALLERID[NUMBER]
[Mar 6 17:04:22] DEBUG[13034] pbx.c: Launching ‘Set’
[Mar 6 17:04:22] VERBOSE[13034] logger.c: – Executing [INBOUND_NUMBER@V2DASH:5] Set(“SIP/4.68.250.148-09b3a900”, “CALLEDNUMBER=INBOUND_NUMBER”) in new stack
[Mar 6 17:04:22] DEBUG[13034] pbx.c: Launching ‘Goto’
[Mar 6 17:04:22] VERBOSE[13034] logger.c: – Executing [INBOUND_NUMBER@V2DASH:6] Goto(“SIP/4.68.250.148-09b3a900”, “CAP-FORWARDING|s|1”) in new stack
[Mar 6 17:04:22] VERBOSE[13034] logger.c: – Goto (CAP-FORWARDING,s,1)
[Mar 6 17:04:22] DEBUG[13034] pbx.c: Launching ‘Verbose’
[Mar 6 17:04:22] VERBOSE[13034] logger.c: – Executing [s@CAP-FORWARDING:1] Verbose(“SIP/4.68.250.148-09b3a900”, “CID is CALLERID[NUMBER]”) in new stack
[Mar 6 17:04:22] VERBOSE[13034] logger.c: CID is CALLERID[NUMBER]
[Mar 6 17:04:22] DEBUG[13034] pbx.c: Launching ‘Verbose’
[Mar 6 17:04:22] VERBOSE[13034] logger.c: – Executing [s@CAP-FORWARDING:2] Verbose(“SIP/4.68.250.148-09b3a900”, “CALLED NUMBER is INBOUND_NUMBER”) in new stack
[Mar 6 17:04:22] VERBOSE[13034] logger.c: CALLED NUMBER is INBOUND_NUMBER
[Mar 6 17:04:22] DEBUG[13034] pbx.c: Launching ‘Set’
[Mar 6 17:04:22] VERBOSE[13034] logger.c: – Executing [s@CAP-FORWARDING:3] Set(“SIP/4.68.250.148-09b3a900”, “fullurl=XX_CALL_START_URL_XX”) in new stack
[Mar 6 17:04:22] DEBUG[13034] pbx.c: Function result is ‘52592’
[Mar 6 17:04:22] DEBUG[13034] pbx.c: Launching ‘Set’
[Mar 6 17:04:22] VERBOSE[13034] logger.c: – Executing [s@CAP-FORWARDING:4] Set(“SIP/4.68.250.148-09b3a900”, “CALLID=52592”) in new stack
[Mar 6 17:04:22] DEBUG[13034] pbx.c: Launching ‘Verbose’
[Mar 6 17:04:22] VERBOSE[13034] logger.c: – Executing [s@CAP-FORWARDING:5] Verbose(“SIP/4.68.250.148-09b3a900”, “call id is 52592”) in new stack
[Mar 6 17:04:22] VERBOSE[13034] logger.c: call id is 52592
[Mar 6 17:04:22] DEBUG[13034] pbx.c: Launching ‘Answer’
[Mar 6 17:04:22] VERBOSE[13034] logger.c: – Executing [s@CAP-FORWARDING:6] Answer(“SIP/4.68.250.148-09b3a900”, “”) in new stack
[Mar 6 17:04:22] DEBUG[13034] devicestate.c: Notification of state change to be queued on device/channel SIP/4.68.250.148
[Mar 6 17:04:22] DEBUG[13034] chan_sip.c: SIP answering channel: SIP/4.68.250.148-09b3a900
[Mar 6 17:04:22] DEBUG[13034] chan_sip.c: Setting framing from config on incoming call
[Mar 6 17:04:22] DEBUG[13034] chan_sip.c: ** Our capability: 0x4 (ulaw) Video flag: True
[Mar 6 17:04:22] DEBUG[13034] chan_sip.c: ** Our prefcodec: 0x0 (nothing)
[Mar 6 17:04:22] VERBOSE[13034] logger.c: Audio is at AST_SERVER_IP port 13070
[Mar 6 17:04:22] VERBOSE[13034] logger.c: Adding codec 0x4 (ulaw) to SDP
[Mar 6 17:04:22] VERBOSE[13034] logger.c: Adding non-codec 0x1 (telephone-event) to SDP
[Mar 6 17:04:22] DEBUG[13034] chan_sip.c: – Done with adding codecs to SDP
[Mar 6 17:04:22] DEBUG[13034] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=-1)
[Mar 6 17:04:22] DEBUG[13034] chan_sip.c: Done building SDP. Settling with this capability: 0x4 (ulaw)
[Mar 6 17:04:22] VERBOSE[13034] logger.c:
<— Reliably Transmitting (no NAT) to 216.82.224.202:5060 —>
SIP/2.0 200 OK
Via: SIP/2.0/UDP 216.82.224.202;branch=z9hG4bKe1e3.390f93a.0;received=216.82.224.202
Via: SIP/2.0/UDP 4.79.212.229;branch=z9hG4bKe1e3.9ef7d212.0
Via: SIP/2.0/UDP 4.68.250.148:5060;branch=z9hG4bK506071629460-1207494130614
Record-Route: sip:216.82.224.202;lr;ftag=VPSF506071629460
Record-Route: sip:4.79.212.229;lr;ftag=VPSF506071629460
From: “CALLERID NAME” sip:+1CALLERID[NUMBER]@4.68.250.148;isup-oli=62;tag=VPSF506071629460
To: sip:+1INBOUND_NUMBER@4.79.212.229:5060;tag=as369c3467
Call-ID: BOSMGC0320090306221543019314@209.244.63.175
CSeq: 1 INVITE
User-Agent: Asterisk PBX
Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY
Supported: replaces
Contact: sip:+1INBOUND_NUMBER@AST_SERVER_IP
Content-Type: application/sdp
Content-Length: 242

v=0
o=root 16382 16382 IN IP4 AST_SERVER_IP
s=session
c=IN IP4 AST_SERVER_IP
t=0 0
m=audio 13070 RTP/AVP 0 101
a=rtpmap:0 PCMU/8000
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-16
a=silenceSupp:off - - - -
a=ptime:20
a=sendrecv

<------------>
[Mar 6 17:04:22] DEBUG[13034] chan_sip.c: Header 0: SIP/2.0 200 OK (14)
[Mar 6 17:04:22] DEBUG[13034] chan_sip.c: Header 1: Via: SIP/2.0/UDP 216.82.224.202;branch=z9hG4bKe1e3.390f93a.0;received=216.82.224.202 (84)
[Mar 6 17:04:22] DEBUG[13034] chan_sip.c: Header 2: Via: SIP/2.0/UDP 4.79.212.229;branch=z9hG4bKe1e3.9ef7d212.0 (59)
[Mar 6 17:04:22] DEBUG[13034] chan_sip.c: Header 3: Via: SIP/2.0/UDP 4.68.250.148:5060;branch=z9hG4bK506071629460-1207494130614 (75)
[Mar 6 17:04:22] DEBUG[13034] chan_sip.c: Header 4: Record-Route: sip:216.82.224.202;lr;ftag=VPSF506071629460 (59)
[Mar 6 17:04:22] DEBUG[13034] chan_sip.c: Header 5: Record-Route: sip:4.79.212.229;lr;ftag=VPSF506071629460 (57)
[Mar 6 17:04:22] DEBUG[13034] chan_sip.c: Header 6: From: “CALLERID NAME” sip:+1CALLERID[NUMBER]@4.68.250.148;isup-oli=62;tag=VPSF506071629460 (89)
[Mar 6 17:04:22] DEBUG[13034] chan_sip.c: Header 7: To: sip:+1INBOUND_NUMBER@4.79.212.229:5060;tag=as369c3467 (55)
[Mar 6 17:04:22] DEBUG[13034] chan_sip.c: Header 8: Call-ID: BOSMGC0320090306221543019314@209.244.63.175 (52)
[Mar 6 17:04:22] DEBUG[13034] chan_sip.c: Header 9: CSeq: 1 INVITE (14)
[Mar 6 17:04:22] DEBUG[13034] chan_sip.c: Header 10: User-Agent: Asterisk PBX (24)
[Mar 6 17:04:22] DEBUG[13034] chan_sip.c: Header 11: Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY (66)
[Mar 6 17:04:22] DEBUG[13034] chan_sip.c: Header 12: Supported: replaces (19)
[Mar 6 17:04:22] DEBUG[13034] chan_sip.c: Header 13: Contact: sip:+1INBOUND_NUMBER@AST_SERVER_IP (41)
[Mar 6 17:04:22] DEBUG[13034] chan_sip.c: Header 14: Content-Type: application/sdp (29)
[Mar 6 17:04:22] DEBUG[13034] chan_sip.c: Header 15: Content-Length: 242 (19)
[Mar 6 17:04:22] DEBUG[13034] chan_sip.c: Header 16: (0)
[Mar 6 17:04:22] DEBUG[13034] chan_sip.c: Line: v=0 (3)
[Mar 6 17:04:22] DEBUG[13034] chan_sip.c: Line: o=root 16382 16382 IN IP4 AST_SERVER_IP (39)
[Mar 6 17:04:22] DEBUG[13034] chan_sip.c: Line: s=session (9)
[Mar 6 17:04:22] DEBUG[13034] chan_sip.c: Line: c=IN IP4 AST_SERVER_IP (22)
[Mar 6 17:04:22] DEBUG[13034] chan_sip.c: Line: t=0 0 (5)
[Mar 6 17:04:22] DEBUG[13034] chan_sip.c: Line: m=audio 13070 RTP/AVP 0 101 (27)
[Mar 6 17:04:22] DEBUG[13034] chan_sip.c: Line: a=rtpmap:0 PCMU/8000 (20)
[Mar 6 17:04:22] DEBUG[13034] chan_sip.c: Line: a=rtpmap:101 telephone-event/8000 (33)
[Mar 6 17:04:22] DEBUG[13034] chan_sip.c: Line: a=fmtp:101 0-16 (15)
[Mar 6 17:04:22] DEBUG[13034] chan_sip.c: Line: a=silenceSupp:off - - - - (25)
[Mar 6 17:04:22] DEBUG[13034] chan_sip.c: Line: a=ptime:20 (10)
[Mar 6 17:04:22] DEBUG[13034] chan_sip.c: Line: a=sendrecv (10)
[Mar 6 17:04:22] DEBUG[13034] chan_sip.c: *** SIP TIMER: Initializing retransmit timer on packet: Id #-1
[Mar 6 17:04:22] DEBUG[13034] pbx.c: Launching ‘Wait’
[Mar 6 17:04:22] VERBOSE[13034] logger.c: – Executing [s@CAP-FORWARDING:7] Wait(“SIP/4.68.250.148-09b3a900”, “1”) in new stack
[Mar 6 17:04:22] DEBUG[16384] devicestate.c: No provider found, checking channel drivers for SIP - 4.68.250.148
[Mar 6 17:04:22] DEBUG[16384] chan_sip.c: Checking device state for peer 4.68.250.148
[Mar 6 17:04:22] DEBUG[16384] devicestate.c: Changing state for SIP/4.68.250.148 - state 2 (In use)
[Mar 6 17:04:22] DEBUG[16409] app_queue.c: Device ‘SIP/4.68.250.148’ changed to state ‘2’ (In use) but we don’t care because they’re not a member of any queue.
[Mar 6 17:04:22] VERBOSE[16390] logger.c:
<— SIP read from 216.82.224.202:5060 —>
ACK sip:+1INBOUND_NUMBER@AST_SERVER_IP SIP/2.0
Record-Route: sip:216.82.224.202;lr;ftag=VPSF506071629460
Via: SIP/2.0/UDP 216.82.224.202;branch=z9hG4bKe1e3.390f93a.2
Via: SIP/2.0/UDP 4.79.212.229;branch=z9hG4bKe1e3.9ef7d212.2
Via: SIP/2.0/UDP 4.68.250.148:5060;branch=z9hG4bK506071629460-1207494130624
From: “CALLERID NAME” sip:+1CALLERID[NUMBER]@4.68.250.148;isup-oli=62;tag=VPSF506071629460
To: sip:+1INBOUND_NUMBER@4.79.212.229:5060;tag=as369c3467
Call-ID: BOSMGC0320090306221543019314@209.244.63.175
CSeq: 1 ACK
Contact: sip:4.68.250.148:5060;transport=udp
Max-Forwards: 68
Content-Length: 0

<------------->
[Mar 6 17:04:22] DEBUG[16390] chan_sip.c: Header 0: ACK sip:+1INBOUND_NUMBER@AST_SERVER_IP SIP/2.0 (42)
[Mar 6 17:04:22] DEBUG[16390] chan_sip.c: Header 1: Record-Route: sip:216.82.224.202;lr;ftag=VPSF506071629460 (59)
[Mar 6 17:04:22] DEBUG[16390] chan_sip.c: Header 2: Via: SIP/2.0/UDP 216.82.224.202;branch=z9hG4bKe1e3.390f93a.2 (60)
[Mar 6 17:04:22] DEBUG[16390] chan_sip.c: Header 3: Via: SIP/2.0/UDP 4.79.212.229;branch=z9hG4bKe1e3.9ef7d212.2 (59)
[Mar 6 17:04:22] DEBUG[16390] chan_sip.c: Header 4: Via: SIP/2.0/UDP 4.68.250.148:5060;branch=z9hG4bK506071629460-1207494130624 (75)
[Mar 6 17:04:22] DEBUG[16390] chan_sip.c: Header 5: From: “CALLERID NAME” sip:+1CALLERID[NUMBER]@4.68.250.148;isup-oli=62;tag=VPSF506071629460 (89)
[Mar 6 17:04:22] DEBUG[16390] chan_sip.c: Header 6: To: sip:+1INBOUND_NUMBER@4.79.212.229:5060;tag=as369c3467 (55)
[Mar 6 17:04:22] DEBUG[16390] chan_sip.c: Header 7: Call-ID: BOSMGC0320090306221543019314@209.244.63.175 (52)
[Mar 6 17:04:22] DEBUG[16390] chan_sip.c: Header 8: CSeq: 1 ACK (11)
[Mar 6 17:04:22] DEBUG[16390] chan_sip.c: Header 9: Contact: sip:4.68.250.148:5060;transport=udp (46)
[Mar 6 17:04:22] DEBUG[16390] chan_sip.c: Header 10: Max-Forwards: 68 (16)
[Mar 6 17:04:22] DEBUG[16390] chan_sip.c: Header 11: Content-Length: 0 (17)
[Mar 6 17:04:22] DEBUG[16390] chan_sip.c: Header 12: (0)
[Mar 6 17:04:22] VERBOSE[16390] logger.c: — (12 headers 0 lines) —
[Mar 6 17:04:22] DEBUG[16390] chan_sip.c: = Found Their Call ID: BOSMGC0320090306221543019314@209.244.63.175 Their Tag VPSF506071629460 Our tag: as369c3467
[Mar 6 17:04:22] DEBUG[16390] chan_sip.c: **** Received ACK (6) - Command in SIP ACK
[Mar 6 17:04:22] DEBUG[16390] chan_sip.c: ** SIP TIMER: Cancelling retransmit of packet (reply received) Retransid #34300
[Mar 6 17:04:22] DEBUG[16390] chan_sip.c: Stopping retransmission on ‘BOSMGC0320090306221543019314@209.244.63.175’ of Response 1: Match Found
[Mar 6 17:04:23] DEBUG[13034] pbx.c: Function result is ‘FORWARDING_NUMBER’
[Mar 6 17:04:23] DEBUG[13034] pbx.c: Launching ‘Set’
[Mar 6 17:04:23] VERBOSE[13034] logger.c: – Executing [s@CAP-FORWARDING:8] Set(“SIP/4.68.250.148-09b3a900”, “FWD_NUM=FORWARDING_NUMBER”) in new stack
[Mar 6 17:04:23] DEBUG[13034] pbx.c: Function result is ‘20090307030423’
[Mar 6 17:04:23] DEBUG[13034] pbx.c: Launching ‘Set’
[Mar 6 17:04:23] VERBOSE[13034] logger.c: – Executing [s@CAP-FORWARDING:9] Set(“SIP/4.68.250.148-09b3a900”, “TIMESTAMP=20090307030423”) in new stack
[Mar 6 17:04:23] DEBUG[13034] pbx.c: Launching ‘Set’
[Mar 6 17:04:23] VERBOSE[13034] logger.c: – Executing [s@CAP-FORWARDING:10] Set(“SIP/4.68.250.148-09b3a900”, “CALLFILENAME=DASHCALL-CALLERID[NUMBER]-INBOUND_NUMBER-20090307030423”) in new stack
[Mar 6 17:04:23] DEBUG[13034] pbx.c: Launching ‘Set’
[Mar 6 17:04:23] VERBOSE[13034] logger.c: – Executing [s@CAP-FORWARDING:11] Set(“SIP/4.68.250.148-09b3a900”, “EXT=wav”) in new stack
[Mar 6 17:04:23] DEBUG[13034] pbx.c: Function result is ‘T’
[Mar 6 17:04:23] DEBUG[13034] pbx.c: Launching ‘Set’
[Mar 6 17:04:23] VERBOSE[13034] logger.c: – Executing [s@CAP-FORWARDING:12] Set(“SIP/4.68.250.148-09b3a900”, “REC=T”) in new stack
[Mar 6 17:04:23] DEBUG[13034] pbx.c: Function result is ‘0000’
[Mar 6 17:04:23] DEBUG[13034] pbx.c: Launching ‘Set’
[Mar 6 17:04:23] VERBOSE[13034] logger.c: – Executing [s@CAP-FORWARDING:13] Set(“SIP/4.68.250.148-09b3a900”, “GREET=0000”) in new stack
[Mar 6 17:04:23] DEBUG[13034] pbx.c: Launching ‘Verbose’
[Mar 6 17:04:23] VERBOSE[13034] logger.c: – Executing [s@CAP-FORWARDING:14] Verbose(“SIP/4.68.250.148-09b3a900”, “0000”) in new stack
[Mar 6 17:04:23] VERBOSE[13034] logger.c: 0000
[Mar 6 17:04:23] DEBUG[13034] pbx.c: Expression result is ‘1’
[Mar 6 17:04:23] DEBUG[13034] pbx.c: Launching ‘GotoIf’
[Mar 6 17:04:23] VERBOSE[13034] logger.c: – Executing [s@CAP-FORWARDING:15] GotoIf(“SIP/4.68.250.148-09b3a900”, “1?record:greet”) in new stack
[Mar 6 17:04:23] VERBOSE[13034] logger.c: – Goto (CAP-FORWARDING,s,16)
[Mar 6 17:04:23] DEBUG[13034] pbx.c: Launching ‘MixMonitor’
[Mar 6 17:04:23] VERBOSE[13034] logger.c: – Executing [s@CAP-FORWARDING:16] MixMonitor(“SIP/4.68.250.148-09b3a900”, “DASHCALL-CALLERID[NUMBER]-INBOUND_NUMBER-20090307030423.wav||/var/spool/asterisk/monitor/v2putmp3.sh DASHCALL-CALLERID[NUMBER]-INBOUND_NUMBER-20090307030423.wav >> /var/log/asterisk/v2log.log 2>&1”) in new stack
[Mar 6 17:04:23] DEBUG[13034] pbx.c: Expression result is ‘1’
[Mar 6 17:04:23] DEBUG[13034] pbx.c: Launching ‘GotoIf’
[Mar 6 17:04:23] VERBOSE[13034] logger.c: – Executing [s@CAP-FORWARDING:17] GotoIf(“SIP/4.68.250.148-09b3a900”, “1?defaultgreet:checkcustom”) in new stack
[Mar 6 17:04:23] VERBOSE[13034] logger.c: – Goto (CAP-FORWARDING,s,18)
[Mar 6 17:04:23] DEBUG[13034] pbx.c: Launching ‘Playback’
[Mar 6 17:04:23] VERBOSE[13034] logger.c: – Executing [s@CAP-FORWARDING:18] Playback(“SIP/4.68.250.148-09b3a900”, “welcome”) in new stack
[Mar 6 17:04:23] DEBUG[13034] rtp.c: Ooh, format changed from unknown to ulaw
[Mar 6 17:04:23] DEBUG[13034] rtp.c: Created smoother: format: 4 ms: 20 len: 160
[Mar 6 17:04:23] VERBOSE[13034] logger.c: – <SIP/4.68.250.148-09b3a900> Playing ‘welcome’ (language ‘en’)
[Mar 6 17:04:23] VERBOSE[13035] logger.c: == Begin MixMonitor Recording SIP/4.68.250.148-09b3a900
[Mar 6 17:04:23] DEBUG[13035] audiohook.c: Read factory 0x9b17768 was pretty quick last time, waiting for them.
… 44 lines …
[Mar 6 17:04:24] DEBUG[13035] audiohook.c: Read factory 0x9b17768 was pretty quick last time, waiting for them.
[Mar 6 17:04:24] DEBUG[13034] pbx.c: Launching ‘Playback’
[Mar 6 17:04:24] VERBOSE[13034] logger.c: – Executing [s@CAP-FORWARDING:19] Playback(“SIP/4.68.250.148-09b3a900”, “for-quality-purposes”) in new stack
[Mar 6 17:04:24] VERBOSE[13034] logger.c: – <SIP/4.68.250.148-09b3a900> Playing ‘for-quality-purposes’ (language ‘en’)
[Mar 6 17:04:24] DEBUG[13035] audiohook.c: Read factory 0x9b17768 was pretty quick last time, waiting for them.
… 103 lines …
[Mar 6 17:04:26] DEBUG[13035] audiohook.c: Read factory 0x9b17768 was pretty quick last time, waiting for them.
[Mar 6 17:04:26] DEBUG[13034] pbx.c: Launching ‘Playback’
[Mar 6 17:04:26] VERBOSE[13034] logger.c: – Executing [s@CAP-FORWARDING:20] Playback(“SIP/4.68.250.148-09b3a900”, “this-call-may-be-monitored-or-recorded”) in new stack
[Mar 6 17:04:26] VERBOSE[13034] logger.c: – <SIP/4.68.250.148-09b3a900> Playing ‘this-call-may-be-monitored-or-recorded’ (language ‘en’)
[Mar 6 17:04:26] DEBUG[13035] audiohook.c: Read factory 0x9b17768 was pretty quick last time, waiting for them.
… 128 Lines …
[Mar 6 17:04:29] DEBUG[13035] audiohook.c: Read factory 0x9b17768 was pretty quick last time, waiting for them.
[Mar 6 17:04:29] DEBUG[13034] pbx.c: Launching ‘Goto’
[Mar 6 17:04:29] VERBOSE[13034] logger.c: – Executing [s@CAP-FORWARDING:21] Goto(“SIP/4.68.250.148-09b3a900”, “s|callerid”) in new stack
[Mar 6 17:04:29] VERBOSE[13034] logger.c: – Goto (CAP-FORWARDING,s,24)
[Mar 6 17:04:29] DEBUG[13034] pbx.c: Launching ‘Set’
[Mar 6 17:04:29] VERBOSE[13034] logger.c: – Executing [s@CAP-FORWARDING:24] Set(“SIP/4.68.250.148-09b3a900”, “CALLERID(num)=CALLERID[NUMBER]”) in new stack
[Mar 6 17:04:29] DEBUG[13034] db.c: Unable to find key ‘INBOUND_NUMBER’ in family ‘CACALLERID’
[Mar 6 17:04:29] DEBUG[13034] func_db.c: DB: CACALLERID/INBOUND_NUMBER not found in database.
[Mar 6 17:04:29] DEBUG[13034] pbx.c: Function result is ‘’
[Mar 6 17:04:29] DEBUG[13034] pbx.c: Launching ‘Set’
[Mar 6 17:04:29] VERBOSE[13034] logger.c: – Executing [s@CAP-FORWARDING:25] Set(“SIP/4.68.250.148-09b3a900”, “CACALLERID=”) in new stack
[Mar 6 17:04:29] DEBUG[13034] pbx.c: Expression result is ‘0’
[Mar 6 17:04:29] DEBUG[13034] pbx.c: Launching ‘ExecIf’
[Mar 6 17:04:29] VERBOSE[13034] logger.c: – Executing [s@CAP-FORWARDING:26] ExecIf(“SIP/4.68.250.148-09b3a900”, “0|SET|CALLERID(number)=”) in new stack
[Mar 6 17:04:29] DEBUG[13034] pbx.c: Launching ‘Dial’
[Mar 6 17:04:29] VERBOSE[13034] logger.c: – Executing [s@CAP-FORWARDING:27] Dial(“SIP/4.68.250.148-09b3a900”, “SIP/+FORWARDING_NUMBER@bandwidth|240|r”) in new stack
[Mar 6 17:04:29] DEBUG[13034] chan_sip.c: Asked to create a SIP channel with formats: 0x4 (ulaw)
[Mar 6 17:04:29] DEBUG[13034] chan_sip.c: Allocating new SIP dialog for (No Call-ID) - INVITE (With RTP)
[Mar 6 17:04:29] DEBUG[13034] chan_sip.c: Setting NAT on RTP to Off
[Mar 6 17:04:29] DEBUG[13034] chan_sip.c: *** Our native formats are 0x80004 (ulaw|h263)
[Mar 6 17:04:29] DEBUG[13034] chan_sip.c: *** Joint capabilities are 0x0 (nothing)
[Mar 6 17:04:29] DEBUG[13034] chan_sip.c: *** Our capabilities are 0x8000e (gsm|ulaw|alaw|h263)
[Mar 6 17:04:29] DEBUG[13034] chan_sip.c: *** AST_CODEC_CHOOSE formats are 0x4 (ulaw)
[Mar 6 17:04:29] DEBUG[13034] chan_sip.c: *** Our preferred formats from the incoming channel are 0x4 (ulaw)
[Mar 6 17:04:29] DEBUG[13034] chan_sip.c: This channel will not be able to handle video.
[Mar 6 17:04:29] DEBUG[13034] channel.c: Not copying variable DIALEDTIME.
[Mar 6 17:04:29] DEBUG[13034] channel.c: Not copying variable ANSWEREDTIME.
[Mar 6 17:04:29] DEBUG[13034] channel.c: Not copying variable DIALEDPEERNAME.
[Mar 6 17:04:29] DEBUG[13034] channel.c: Not copying variable DIALEDPEERNUMBER.
[Mar 6 17:04:29] DEBUG[13034] channel.c: Not copying variable DIALSTATUS.
[Mar 6 17:04:29] DEBUG[13034] channel.c: Not copying variable CACALLERID.
[Mar 6 17:04:29] DEBUG[13034] channel.c: Not copying variable PLAYBACKSTATUS.
[Mar 6 17:04:29] DEBUG[13034] channel.c: Not copying variable MIXMONITOR_FILENAME.
[Mar 6 17:04:29] DEBUG[13034] channel.c: Not copying variable GREET.
[Mar 6 17:04:29] DEBUG[13034] channel.c: Not copying variable REC.
[Mar 6 17:04:29] DEBUG[13034] channel.c: Not copying variable EXT.
[Mar 6 17:04:29] DEBUG[13034] channel.c: Not copying variable CALLFILENAME.
[Mar 6 17:04:29] DEBUG[13034] channel.c: Not copying variable TIMESTAMP.
[Mar 6 17:04:29] DEBUG[13034] channel.c: Not copying variable FWD_NUM.
[Mar 6 17:04:29] DEBUG[13034] channel.c: Not copying variable DB_RESULT.
[Mar 6 17:04:29] DEBUG[13034] channel.c: Not copying variable CALLID.
[Mar 6 17:04:29] DEBUG[13034] channel.c: Not copying variable fullurl.
[Mar 6 17:04:29] DEBUG[13034] channel.c: Not copying variable CALLEDNUMBER.
[Mar 6 17:04:29] DEBUG[13034] channel.c: Not copying variable CID.
[Mar 6 17:04:29] DEBUG[13034] channel.c: Not copying variable NUM.
[Mar 6 17:04:29] DEBUG[13034] channel.c: Not copying variable MAP5.
[Mar 6 17:04:29] DEBUG[13034] channel.c: Not copying variable SIPCALLID.
[Mar 6 17:04:29] DEBUG[13034] channel.c: Not copying variable SIPDOMAIN.
[Mar 6 17:04:29] DEBUG[13034] channel.c: Not copying variable SIPURI.
[Mar 6 17:04:29] DEBUG[13034] chan_sip.c: Outgoing Call for +FORWARDING_NUMBER
[Mar 6 17:04:29] DEBUG[13034] chan_sip.c: Updating call counter for outgoing call
[Mar 6 17:04:29] DEBUG[13034] chan_sip.c: Our T38 capability (0), joint T38 capability (0)
[Mar 6 17:04:29] DEBUG[13034] chan_sip.c: ** Our capability: 0x8000e (gsm|ulaw|alaw|h263) Video flag: False
[Mar 6 17:04:29] DEBUG[13034] chan_sip.c: ** Our prefcodec: 0x4 (ulaw)
[Mar 6 17:04:29] DEBUG[13034] chan_sip.c: This call needs video offers, but there’s no video support enabled!
[Mar 6 17:04:29] VERBOSE[13034] logger.c: Audio is at AST_SERVER_IP port 10468
[Mar 6 17:04:29] VERBOSE[13034] logger.c: Adding codec 0x4 (ulaw) to SDP
[Mar 6 17:04:29] VERBOSE[13034] logger.c: Adding codec 0x2 (gsm) to SDP
[Mar 6 17:04:29] VERBOSE[13034] logger.c: Adding codec 0x8 (alaw) to SDP
[Mar 6 17:04:29] VERBOSE[13034] logger.c: Adding non-codec 0x1 (telephone-event) to SDP
[Mar 6 17:04:29] DEBUG[13034] chan_sip.c: – Done with adding codecs to SDP
[Mar 6 17:04:29] DEBUG[13034] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=-1)
[Mar 6 17:04:29] DEBUG[13034] chan_sip.c: Done building SDP. Settling with this capability: 0x8000e (gsm|ulaw|alaw|h263)
[Mar 6 17:04:29] DEBUG[13034] chan_sip.c: Header 0: INVITE sip:+FORWARDING_NUMBER@216.82.224.202 SIP/2.0 (46)
[Mar 6 17:04:29] DEBUG[13034] chan_sip.c: Header 1: Via: SIP/2.0/UDP AST_SERVER_IP:5060;branch=z9hG4bK04db289e;rport (64)
[Mar 6 17:04:29] DEBUG[13034] chan_sip.c: Header 2: From: “CALLERID NAME” sip:CALLERID[NUMBER]@AST_SERVER_IP;tag=as083655ce (69)
[Mar 6 17:04:29] DEBUG[13034] chan_sip.c: Header 3: To: sip:+FORWARDING_NUMBER@216.82.224.202 (37)
[Mar 6 17:04:29] DEBUG[13034] chan_sip.c: Header 4: Contact: sip:CALLERID[NUMBER]@AST_SERVER_IP (39)
[Mar 6 17:04:29] DEBUG[13034] chan_sip.c: Header 5: Call-ID: 5b451ce8380242be181a03de69dfcfff@AST_SERVER_IP (55)
[Mar 6 17:04:29] DEBUG[13034] chan_sip.c: Header 6: CSeq: 102 INVITE (16)
[Mar 6 17:04:29] DEBUG[13034] chan_sip.c: Header 7: User-Agent: Asterisk PBX (24)
[Mar 6 17:04:29] DEBUG[13034] chan_sip.c: Header 8: Max-Forwards: 70 (16)
[Mar 6 17:04:29] DEBUG[13034] chan_sip.c: Header 9: Date: Fri, 06 Mar 2009 22:04:29 GMT (35)
[Mar 6 17:04:29] DEBUG[13034] chan_sip.c: Header 10: Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY (66)
[Mar 6 17:04:29] DEBUG[13034] chan_sip.c: Header 11: Supported: replaces (19)
[Mar 6 17:04:29] DEBUG[13034] chan_sip.c: Header 12: Content-Type: application/sdp (29)
[Mar 6 17:04:29] DEBUG[13034] chan_sip.c: Header 13: Content-Length: 289 (19)
[Mar 6 17:04:29] DEBUG[13034] chan_sip.c: Header 14: (0)
[Mar 6 17:04:29] DEBUG[13034] chan_sip.c: Line: v=0 (3)
[Mar 6 17:04:29] DEBUG[13034] chan_sip.c: Line: o=root 16382 16382 IN IP4 AST_SERVER_IP (39)
[Mar 6 17:04:29] DEBUG[13034] chan_sip.c: Line: s=session (9)
[Mar 6 17:04:29] DEBUG[13034] chan_sip.c: Line: c=IN IP4 AST_SERVER_IP (22)
[Mar 6 17:04:29] DEBUG[13034] chan_sip.c: Line: t=0 0 (5)
[Mar 6 17:04:29] DEBUG[13034] chan_sip.c: Line: m=audio 10468 RTP/AVP 0 3 8 101 (31)
[Mar 6 17:04:29] DEBUG[13034] chan_sip.c: Line: a=rtpmap:0 PCMU/8000 (20)
[Mar 6 17:04:29] DEBUG[13034] chan_sip.c: Line: a=rtpmap:3 GSM/8000 (19)
[Mar 6 17:04:29] DEBUG[13034] chan_sip.c: Line: a=rtpmap:8 PCMA/8000 (20)
[Mar 6 17:04:29] DEBUG[13034] chan_sip.c: Line: a=rtpmap:101 telephone-event/8000 (33)
[Mar 6 17:04:29] DEBUG[13034] chan_sip.c: Line: a=fmtp:101 0-16 (15)
[Mar 6 17:04:29] DEBUG[13034] chan_sip.c: Line: a=silenceSupp:off - - - - (25)
[Mar 6 17:04:29] DEBUG[13034] chan_sip.c: Line: a=ptime:20 (10)
[Mar 6 17:04:29] DEBUG[13034] chan_sip.c: Line: a=sendrecv (10)
[Mar 6 17:04:29] VERBOSE[13034] logger.c: Reliably Transmitting (no NAT) to 216.82.224.202:5060:
INVITE sip:+FORWARDING_NUMBER@216.82.224.202 SIP/2.0
Via: SIP/2.0/UDP AST_SERVER_IP:5060;branch=z9hG4bK04db289e;rport
From: “CALLERID NAME” sip:CALLERID[NUMBER]@AST_SERVER_IP;tag=as083655ce
To: sip:+FORWARDING_NUMBER@216.82.224.202
Contact: sip:CALLERID[NUMBER]@AST_SERVER_IP
Call-ID: 5b451ce8380242be181a03de69dfcfff@AST_SERVER_IP
CSeq: 102 INVITE
User-Agent: Asterisk PBX
Max-Forwards: 70
Date: Fri, 06 Mar 2009 22:04:29 GMT
Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY
Supported: replaces
Content-Type: application/sdp
Content-Length: 289

v=0
o=root 16382 16382 IN IP4 AST_SERVER_IP
s=session
c=IN IP4 AST_SERVER_IP
t=0 0
m=audio 10468 RTP/AVP 0 3 8 101
a=rtpmap:0 PCMU/8000
a=rtpmap:3 GSM/8000
a=rtpmap:8 PCMA/8000
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-16
a=silenceSupp:off - - - -
a=ptime:20
a=sendrecv

[Mar 6 17:04:29] DEBUG[13034] chan_sip.c: Header 0: INVITE sip:+FORWARDING_NUMBER@216.82.224.202 SIP/2.0 (46)
[Mar 6 17:04:29] DEBUG[13034] chan_sip.c: Header 1: Via: SIP/2.0/UDP AST_SERVER_IP:5060;branch=z9hG4bK04db289e;rport (64)
[Mar 6 17:04:29] DEBUG[13034] chan_sip.c: Header 2: From: “CALLERID NAME” sip:CALLERID[NUMBER]@AST_SERVER_IP;tag=as083655ce (69)
[Mar 6 17:04:29] DEBUG[13034] chan_sip.c: Header 3: To: sip:+FORWARDING_NUMBER@216.82.224.202 (37)
[Mar 6 17:04:29] DEBUG[13034] chan_sip.c: Header 4: Contact: sip:CALLERID[NUMBER]@AST_SERVER_IP (39)
[Mar 6 17:04:29] DEBUG[13034] chan_sip.c: Header 5: Call-ID: 5b451ce8380242be181a03de69dfcfff@AST_SERVER_IP (55)
[Mar 6 17:04:29] DEBUG[13034] chan_sip.c: Header 6: CSeq: 102 INVITE (16)
[Mar 6 17:04:29] DEBUG[13034] chan_sip.c: Header 7: User-Agent: Asterisk PBX (24)
[Mar 6 17:04:29] DEBUG[13034] chan_sip.c: Header 8: Max-Forwards: 70 (16)
[Mar 6 17:04:29] DEBUG[13034] chan_sip.c: Header 9: Date: Fri, 06 Mar 2009 22:04:29 GMT (35)
[Mar 6 17:04:29] DEBUG[13034] chan_sip.c: Header 10: Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY (66)
[Mar 6 17:04:29] DEBUG[13034] chan_sip.c: Header 11: Supported: replaces (19)
[Mar 6 17:04:29] DEBUG[13034] chan_sip.c: Header 12: Content-Type: application/sdp (29)
[Mar 6 17:04:29] DEBUG[13034] chan_sip.c: Header 13: Content-Length: 289 (19)
[Mar 6 17:04:29] DEBUG[13034] chan_sip.c: Header 14: (0)
[Mar 6 17:04:29] DEBUG[13034] chan_sip.c: Line: v=0 (3)
[Mar 6 17:04:29] DEBUG[13034] chan_sip.c: Line: o=root 16382 16382 IN IP4 AST_SERVER_IP (39)
[Mar 6 17:04:29] DEBUG[13034] chan_sip.c: Line: s=session (9)
[Mar 6 17:04:29] DEBUG[13034] chan_sip.c: Line: c=IN IP4 AST_SERVER_IP (22)
[Mar 6 17:04:29] DEBUG[13034] chan_sip.c: Line: t=0 0 (5)
[Mar 6 17:04:29] DEBUG[13034] chan_sip.c: Line: m=audio 10468 RTP/AVP 0 3 8 101 (31)
[Mar 6 17:04:29] DEBUG[13034] chan_sip.c: Line: a=rtpmap:0 PCMU/8000 (20)
[Mar 6 17:04:29] DEBUG[13034] chan_sip.c: Line: a=rtpmap:3 GSM/8000 (19)
[Mar 6 17:04:29] DEBUG[13034] chan_sip.c: Line: a=rtpmap:8 PCMA/8000 (20)
[Mar 6 17:04:29] DEBUG[13034] chan_sip.c: Line: a=rtpmap:101 telephone-event/8000 (33)
[Mar 6 17:04:29] DEBUG[13034] chan_sip.c: Line: a=fmtp:101 0-16 (15)
[Mar 6 17:04:29] DEBUG[13034] chan_sip.c: Line: a=silenceSupp:off - - - - (25)
[Mar 6 17:04:29] DEBUG[13034] chan_sip.c: Line: a=ptime:20 (10)
[Mar 6 17:04:29] DEBUG[13034] chan_sip.c: Line: a=sendrecv (10)
[Mar 6 17:04:29] DEBUG[13034] chan_sip.c: *** SIP TIMER: Initializing retransmit timer on packet: Id #-1
[Mar 6 17:04:29] VERBOSE[13034] logger.c: – Called +FORWARDING_NUMBER@bandwidth
[Mar 6 17:04:29] DEBUG[13034] channel.c: Driver for channel ‘SIP/4.68.250.148-09b3a900’ does not support indication 3, emulating it
[Mar 6 17:04:29] DEBUG[13034] channel.c: Set channel SIP/4.68.250.148-09b3a900 to write format slin
[Mar 6 17:04:29] DEBUG[13034] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=-1)
[Mar 6 17:04:29] DEBUG[13034] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=-1)
[Mar 6 17:04:29] VERBOSE[16390] logger.c:
<— SIP read from 216.82.224.202:5060 —>
SIP/2.0 100 Giving a try
Via: SIP/2.0/UDP AST_SERVER_IP:5060;branch=z9hG4bK04db289e;rport=5060
From: “CALLERID NAME” sip:CALLERID[NUMBER]@AST_SERVER_IP;tag=as083655ce
To: sip:+FORWARDING_NUMBER@216.82.224.202
Call-ID: 5b451ce8380242be181a03de69dfcfff@AST_SERVER_IP
CSeq: 102 INVITE
Server: Bandwidth.com TRM (bw7.gold.13)
Content-Length: 0

<------------->
[Mar 6 17:04:29] DEBUG[16390] chan_sip.c: Header 0: SIP/2.0 100 Giving a try (24)
[Mar 6 17:04:29] DEBUG[16390] chan_sip.c: Header 1: Via: SIP/2.0/UDP AST_SERVER_IP:5060;branch=z9hG4bK04db289e;rport=5060 (69)
[Mar 6 17:04:29] DEBUG[16390] chan_sip.c: Header 2: From: “CALLERID NAME” sip:CALLERID[NUMBER]@AST_SERVER_IP;tag=as083655ce (69)
[Mar 6 17:04:29] DEBUG[16390] chan_sip.c: Header 3: To: sip:+FORWARDING_NUMBER@216.82.224.202 (37)
[Mar 6 17:04:29] DEBUG[16390] chan_sip.c: Header 4: Call-ID: 5b451ce8380242be181a03de69dfcfff@AST_SERVER_IP (55)
[Mar 6 17:04:29] DEBUG[16390] chan_sip.c: Header 5: CSeq: 102 INVITE (16)
[Mar 6 17:04:29] DEBUG[16390] chan_sip.c: Header 6: Server: Bandwidth.com TRM (bw7.gold.13) (39)
[Mar 6 17:04:29] DEBUG[16390] chan_sip.c: Header 7: Content-Length: 0 (17)
[Mar 6 17:04:29] DEBUG[16390] chan_sip.c: Header 8: (0)
[Mar 6 17:04:29] VERBOSE[16390] logger.c: — (8 headers 0 lines) —
[Mar 6 17:04:29] DEBUG[16390] chan_sip.c: = Found Their Call ID: 5b451ce8380242be181a03de69dfcfff@AST_SERVER_IP Their Tag Our tag: as083655ce
[Mar 6 17:04:29] DEBUG[16390] chan_sip.c: *** SIP TIMER: Cancelling retransmission #34302 - INVITE (got response)
[Mar 6 17:04:29] DEBUG[16390] chan_sip.c: (Provisional) Stopping retransmission (but retaining packet) on ‘5b451ce8380242be181a03de69dfcfff@AST_SERVER_IP’ Request 102: Found
[Mar 6 17:04:29] DEBUG[16390] chan_sip.c: SIP response 100 to standard invite
[Mar 6 17:04:29] DEBUG[13034] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=-1)
… 120 lines …
[Mar 6 17:04:31] DEBUG[13034] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=-1)
[Mar 6 17:04:31] VERBOSE[16390] logger.c:
<— SIP read from 216.82.224.202:5060 —>
SIP/2.0 183 Session Progress
Via: SIP/2.0/UDP AST_SERVER_IP:5060;received=AST_SERVER_IP;branch=z9hG4bK04db289e;rport=5060
From: “CALLERID NAME” sip:CALLERID[NUMBER]@AST_SERVER_IP;tag=as083655ce
To: sip:+FORWARDING_NUMBER@216.82.224.202;tag=SD2f4f999-gK06bcd966
Call-ID: 5b451ce8380242be181a03de69dfcfff@AST_SERVER_IP
CSeq: 102 INVITE
Record-Route: sip:216.82.224.202;lr;ftag=as083655ce
Contact: sip:6172023222@72.166.216.140:5060;band4682pv01=Band4682Pv01-4phknml6sf68e;transport=udp
Allow: INVITE,ACK,CANCEL,BYE,REGISTER,INFO,SUBSCRIBE,NOTIFY,PRACK,UPDATE,OPTIONS
Content-Length: 237
Content-Disposition: session; handling=required
Content-Type: application/sdp

v=0
o=Sonus_UAC 14055 27978 IN IP4 72.166.216.140
s=SIP Media Capabilities
c=IN IP4 72.166.216.140
t=0 0
m=audio 10900 RTP/AVP 0 101
a=rtpmap:0 PCMU/8000
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-15
a=sendrecv
a=ptime:20

<------------->
[Mar 6 17:04:31] DEBUG[16390] chan_sip.c: Header 0: SIP/2.0 183 Session Progress (28)
[Mar 6 17:04:31] DEBUG[16390] chan_sip.c: Header 1: Via: SIP/2.0/UDP AST_SERVER_IP:5060;received=AST_SERVER_IP;branch=z9hG4bK04db289e;rport=5060 (92)
[Mar 6 17:04:31] DEBUG[16390] chan_sip.c: Header 2: From: “CALLERID NAME” sip:CALLERID[NUMBER]@AST_SERVER_IP;tag=as083655ce (69)
[Mar 6 17:04:31] DEBUG[16390] chan_sip.c: Header 3: To: sip:+FORWARDING_NUMBER@216.82.224.202;tag=SD2f4f999-gK06bcd966 (62)
[Mar 6 17:04:31] DEBUG[16390] chan_sip.c: Header 4: Call-ID: 5b451ce8380242be181a03de69dfcfff@AST_SERVER_IP (55)
[Mar 6 17:04:31] DEBUG[16390] chan_sip.c: Header 5: CSeq: 102 INVITE (16)
[Mar 6 17:04:31] DEBUG[16390] chan_sip.c: Header 6: Record-Route: sip:216.82.224.202;lr;ftag=as083655ce (53)
[Mar 6 17:04:31] DEBUG[16390] chan_sip.c: Header 7: Contact: sip:6172023222@72.166.216.140:5060;band4682pv01=Band4682Pv01-4phknml6sf68e;transport=udp (99)
[Mar 6 17:04:31] DEBUG[16390] chan_sip.c: Header 8: Allow: INVITE,ACK,CANCEL,BYE,REGISTER,INFO,SUBSCRIBE,NOTIFY,PRACK,UPDATE,OPTIONS (80)
[Mar 6 17:04:31] DEBUG[16390] chan_sip.c: Header 9: Content-Length: 237 (19)
[Mar 6 17:04:31] DEBUG[16390] chan_sip.c: Header 10: Content-Disposition: session; handling=required (47)
[Mar 6 17:04:31] DEBUG[16390] chan_sip.c: Header 11: Content-Type: application/sdp (29)
[Mar 6 17:04:31] DEBUG[16390] chan_sip.c: Header 12: (0)
[Mar 6 17:04:31] DEBUG[16390] chan_sip.c: Line: v=0 (3)
[Mar 6 17:04:31] DEBUG[16390] chan_sip.c: Line: o=Sonus_UAC 14055 27978 IN IP4 72.166.216.140 (45)
[Mar 6 17:04:31] DEBUG[16390] chan_sip.c: Line: s=SIP Media Capabilities (24)
[Mar 6 17:04:31] DEBUG[16390] chan_sip.c: Line: c=IN IP4 72.166.216.140 (23)
[Mar 6 17:04:31] DEBUG[16390] chan_sip.c: Line: t=0 0 (5)
[Mar 6 17:04:31] DEBUG[16390] chan_sip.c: Line: m=audio 10900 RTP/AVP 0 101 (27)
[Mar 6 17:04:31] DEBUG[16390] chan_sip.c: Line: a=rtpmap:0 PCMU/8000 (20)
[Mar 6 17:04:31] DEBUG[16390] chan_sip.c: Line: a=rtpmap:101 telephone-event/8000 (33)
[Mar 6 17:04:31] DEBUG[16390] chan_sip.c: Line: a=fmtp:101 0-15 (15)
[Mar 6 17:04:31] DEBUG[16390] chan_sip.c: Line: a=sendrecv (10)
[Mar 6 17:04:31] DEBUG[16390] chan_sip.c: Line: a=ptime:20 (10)
[Mar 6 17:04:31] VERBOSE[16390] logger.c: — (12 headers 11 lines) —
[Mar 6 17:04:31] DEBUG[16390] chan_sip.c: = Found Their Call ID: 5b451ce8380242be181a03de69dfcfff@AST_SERVER_IP Their Tag Our tag: as083655ce
[Mar 6 17:04:31] DEBUG[16390] chan_sip.c: (Provisional) Stopping retransmission (but retaining packet) on ‘5b451ce8380242be181a03de69dfcfff@AST_SERVER_IP’ Request 102: Found
[Mar 6 17:04:31] DEBUG[16390] chan_sip.c: SIP response 183 to standard invite
[Mar 6 17:04:31] VERBOSE[16390] logger.c: Found RTP audio format 0
[Mar 6 17:04:31] VERBOSE[16390] logger.c: Found RTP audio format 101
[Mar 6 17:04:31] VERBOSE[16390] logger.c: Peer audio RTP is at port 72.166.216.140:10900
[Mar 6 17:04:31] VERBOSE[16390] logger.c: Found audio description format PCMU for ID 0
[Mar 6 17:04:31] VERBOSE[16390] logger.c: Found audio description format telephone-event for ID 101
[Mar 6 17:04:31] VERBOSE[16390] logger.c: Got unsupported a:fmtp in SDP offer
[Mar 6 17:04:31] DEBUG[16390] chan_sip.c: T38 state changed to 0 on channel SIP/bandwidth-09b40610
[Mar 6 17:04:31] VERBOSE[16390] logger.c: Capabilities: us - 0x8000e (gsm|ulaw|alaw|h263), peer - audio=0x4 (ulaw)/video=0x0 (nothing), combined - 0x4 (ulaw)
[Mar 6 17:04:31] VERBOSE[16390] logger.c: Non-codec capabilities (dtmf): us - 0x1 (telephone-event), peer - 0x1 (telephone-event), combined - 0x1 (telephone-event)
[Mar 6 17:04:31] VERBOSE[16390] logger.c: Peer audio RTP is at port 72.166.216.140:10900
[Mar 6 17:04:31] DEBUG[16390] chan_sip.c: We’re settling with these formats: 0x4 (ulaw)
[Mar 6 17:04:31] DEBUG[16390] chan_sip.c: We have an owner, now see if we need to change this call
[Mar 6 17:04:31] VERBOSE[13034] logger.c: – SIP/bandwidth-09b40610 is making progress passing it to SIP/4.68.250.148-09b3a900
[Mar 6 17:04:31] DEBUG[13034] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=-1)
… 157 lines …
[Mar 6 17:04:34] DEBUG[13034] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=-1)
[Mar 6 17:04:34] VERBOSE[16390] logger.c:
<— SIP read from 216.82.224.202:5060 —>
SIP/2.0 200 OK
Via: SIP/2.0/UDP AST_SERVER_IP:5060;received=AST_SERVER_IP;branch=z9hG4bK04db289e;rport=5060
From: “CALLERID NAME” sip:CALLERID[NUMBER]@AST_SERVER_IP;tag=as083655ce
To: sip:+FORWARDING_NUMBER@216.82.224.202;tag=SD2f4f999-gK06bcd966
Call-ID: 5b451ce8380242be181a03de69dfcfff@AST_SERVER_IP
CSeq: 102 INVITE
Record-Route: sip:216.82.224.202;lr;ftag=as083655ce
Accept: application/sdp, application/isup, application/dtmf, application/dtmf-relay, multipart/mixed
Contact: sip:6172023222@72.166.216.140:5060;band4682pv01=Band4682Pv01-4phknml6sf68e;transport=udp
Allow: INVITE,ACK,CANCEL,BYE,REGISTER,INFO,SUBSCRIBE,NOTIFY,PRACK,UPDATE,OPTIONS
Content-Length: 237
Content-Disposition: session; handling=required
Content-Type: application/sdp

v=0
o=Sonus_UAC 14055 27978 IN IP4 72.166.216.140
s=SIP Media Capabilities
c=IN IP4 72.166.216.140
t=0 0
m=audio 10900 RTP/AVP 0 101
a=rtpmap:0 PCMU/8000
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-15
a=sendrecv
a=ptime:20

<------------->
[Mar 6 17:04:34] DEBUG[16390] chan_sip.c: Header 0: SIP/2.0 200 OK (14)
[Mar 6 17:04:34] DEBUG[16390] chan_sip.c: Header 1: Via: SIP/2.0/UDP AST_SERVER_IP:5060;received=AST_SERVER_IP;branch=z9hG4bK04db289e;rport=5060 (92)
[Mar 6 17:04:34] DEBUG[16390] chan_sip.c: Header 2: From: “CALLERID NAME” sip:CALLERID[NUMBER]@AST_SERVER_IP;tag=as083655ce (69)
[Mar 6 17:04:34] DEBUG[16390] chan_sip.c: Header 3: To: sip:+FORWARDING_NUMBER@216.82.224.202;tag=SD2f4f999-gK06bcd966 (62)
[Mar 6 17:04:34] DEBUG[16390] chan_sip.c: Header 4: Call-ID: 5b451ce8380242be181a03de69dfcfff@AST_SERVER_IP (55)
[Mar 6 17:04:34] DEBUG[16390] chan_sip.c: Header 5: CSeq: 102 INVITE (16)
[Mar 6 17:04:34] DEBUG[16390] chan_sip.c: Header 6: Record-Route: sip:216.82.224.202;lr;ftag=as083655ce (53)
[Mar 6 17:04:34] DEBUG[16390] chan_sip.c: Header 7: Accept: application/sdp, application/isup, application/dtmf, application/dtmf-relay, multipart/mixed (101)
[Mar 6 17:04:34] DEBUG[16390] chan_sip.c: Header 8: Contact: sip:6172023222@72.166.216.140:5060;band4682pv01=Band4682Pv01-4phknml6sf68e;transport=udp (99)
[Mar 6 17:04:34] DEBUG[16390] chan_sip.c: Header 9: Allow: INVITE,ACK,CANCEL,BYE,REGISTER,INFO,SUBSCRIBE,NOTIFY,PRACK,UPDATE,OPTIONS (80)
[Mar 6 17:04:34] DEBUG[16390] chan_sip.c: Header 10: Content-Length: 237 (19)
[Mar 6 17:04:34] DEBUG[16390] chan_sip.c: Header 11: Content-Disposition: session; handling=required (47)
[Mar 6 17:04:34] DEBUG[16390] chan_sip.c: Header 12: Content-Type: application/sdp (29)
[Mar 6 17:04:34] DEBUG[16390] chan_sip.c: Header 13: (0)
[Mar 6 17:04:34] DEBUG[16390] chan_sip.c: Line: v=0 (3)
[Mar 6 17:04:34] DEBUG[16390] chan_sip.c: Line: o=Sonus_UAC 14055 27978 IN IP4 72.166.216.140 (45)
[Mar 6 17:04:34] DEBUG[16390] chan_sip.c: Line: s=SIP Media Capabilities (24)
[Mar 6 17:04:34] DEBUG[16390] chan_sip.c: Line: c=IN IP4 72.166.216.140 (23)
[Mar 6 17:04:34] DEBUG[16390] chan_sip.c: Line: t=0 0 (5)
[Mar 6 17:04:34] DEBUG[16390] chan_sip.c: Line: m=audio 10900 RTP/AVP 0 101 (27)
[Mar 6 17:04:34] DEBUG[16390] chan_sip.c: Line: a=rtpmap:0 PCMU/8000 (20)
[Mar 6 17:04:34] DEBUG[16390] chan_sip.c: Line: a=rtpmap:101 telephone-event/8000 (33)
[Mar 6 17:04:34] DEBUG[16390] chan_sip.c: Line: a=fmtp:101 0-15 (15)
[Mar 6 17:04:34] DEBUG[16390] chan_sip.c: Line: a=sendrecv (10)
[Mar 6 17:04:34] DEBUG[16390] chan_sip.c: Line: a=ptime:20 (10)
[Mar 6 17:04:34] VERBOSE[16390] logger.c: — (13 headers 11 lines) —
[Mar 6 17:04:34] DEBUG[16390] chan_sip.c: = Found Their Call ID: 5b451ce8380242be181a03de69dfcfff@AST_SERVER_IP Their Tag SD2f4f999-gK06bcd966 Our tag: as083655ce
[Mar 6 17:04:34] DEBUG[16390] chan_sip.c: Acked pending invite 102
[Mar 6 17:04:34] DEBUG[16390] chan_sip.c: Stopping retransmission on ‘5b451ce8380242be181a03de69dfcfff@AST_SERVER_IP’ of Request 102: Match Found
[Mar 6 17:04:34] DEBUG[16390] chan_sip.c: SIP response 200 to standard invite
[Mar 6 17:04:34] VERBOSE[16390] logger.c: Found RTP audio format 0
[Mar 6 17:04:34] VERBOSE[16390] logger.c: Found RTP audio format 101
[Mar 6 17:04:34] VERBOSE[16390] logger.c: Peer audio RTP is at port 72.166.216.140:10900
[Mar 6 17:04:34] VERBOSE[16390] logger.c: Found audio description format PCMU for ID 0
[Mar 6 17:04:34] VERBOSE[16390] logger.c: Found audio description format telephone-event for ID 101
[Mar 6 17:04:34] VERBOSE[16390] logger.c: Got unsupported a:fmtp in SDP offer
[Mar 6 17:04:34] DEBUG[16390] chan_sip.c: T38 state changed to 0 on channel SIP/bandwidth-09b40610
[Mar 6 17:04:34] VERBOSE[16390] logger.c: Capabilities: us - 0x8000e (gsm|ulaw|alaw|h263), peer - audio=0x4 (ulaw)/video=0x0 (nothing), combined - 0x4 (ulaw)
[Mar 6 17:04:34] VERBOSE[16390] logger.c: Non-codec capabilities (dtmf): us - 0x1 (telephone-event), peer - 0x1 (telephone-event), combined - 0x1 (telephone-event)
[Mar 6 17:04:34] VERBOSE[16390] logger.c: Peer audio RTP is at port 72.166.216.140:10900
[Mar 6 17:04:34] DEBUG[16390] chan_sip.c: We’re settling with these formats: 0x4 (ulaw)
[Mar 6 17:04:34] DEBUG[16390] chan_sip.c: We have an owner, now see if we need to change this call
[Mar 6 17:04:34] DEBUG[16390] chan_sip.c: Updating call counter for outgoing call
[Mar 6 17:04:34] DEBUG[16390] chan_sip.c: build_route: Record-Route hop: sip:216.82.224.202;lr;ftag=as083655ce
[Mar 6 17:04:34] VERBOSE[16390] logger.c: list_route: hop: sip:216.82.224.202;lr;ftag=as083655ce
[Mar 6 17:04:34] VERBOSE[16390] logger.c: set_destination: Parsing sip:216.82.224.202;lr;ftag=as083655ce for address/port to send to
[Mar 6 17:04:34] VERBOSE[16390] logger.c: set_destination: set destination to 216.82.224.202, port 5060
[Mar 6 17:04:34] VERBOSE[16390] logger.c: Transmitting (no NAT) to 216.82.224.202:5060:
ACK sip:6172023222@72.166.216.140:5060;band4682pv01=Band4682Pv01-4phknml6sf68e;transport=udp SIP/2.0
Via: SIP/2.0/UDP AST_SERVER_IP:5060;branch=z9hG4bK0838fbd7;rport
Route: sip:216.82.224.202;lr;ftag=as083655ce
From: “CALLERID NAME” sip:CALLERID[NUMBER]@AST_SERVER_IP;tag=as083655ce
To: sip:+FORWARDING_NUMBER@216.82.224.202;tag=SD2f4f999-gK06bcd966
Contact: sip:CALLERID[NUMBER]@AST_SERVER_IP
Call-ID: 5b451ce8380242be181a03de69dfcfff@AST_SERVER_IP
CSeq: 102 ACK
User-Agent: Asterisk PBX
Max-Forwards: 70
Content-Length: 0

[Mar 6 17:04:34] DEBUG[16390] chan_sip.c: Header 0: ACK sip:6172023222@72.166.216.140:5060;band4682pv01=Band4682Pv01-4phknml6sf68e;transport=udp SIP/2.0 (100)
[Mar 6 17:04:34] DEBUG[16390] chan_sip.c: Header 1: Via: SIP/2.0/UDP AST_SERVER_IP:5060;branch=z9hG4bK0838fbd7;rport (64)
[Mar 6 17:04:34] DEBUG[16390] chan_sip.c: Header 2: Route: sip:216.82.224.202;lr;ftag=as083655ce (46)
[Mar 6 17:04:34] DEBUG[16390] chan_sip.c: Header 3: From: “CALLERID NAME” sip:CALLERID[NUMBER]@AST_SERVER_IP;tag=as083655ce (69)
[Mar 6 17:04:34] DEBUG[16390] chan_sip.c: Header 4: To: sip:+FORWARDING_NUMBER@216.82.224.202;tag=SD2f4f999-gK06bcd966 (62)
[Mar 6 17:04:34] DEBUG[16390] chan_sip.c: Header 5: Contact: sip:CALLERID[NUMBER]@AST_SERVER_IP (39)
[Mar 6 17:04:34] DEBUG[16390] chan_sip.c: Header 6: Call-ID: 5b451ce8380242be181a03de69dfcfff@AST_SERVER_IP (55)
[Mar 6 17:04:34] DEBUG[16390] chan_sip.c: Header 7: CSeq: 102 ACK (13)
[Mar 6 17:04:34] DEBUG[16390] chan_sip.c: Header 8: User-Agent: Asterisk PBX (24)
[Mar 6 17:04:34] DEBUG[16390] chan_sip.c: Header 9: Max-Forwards: 70 (16)
[Mar 6 17:04:34] DEBUG[16390] chan_sip.c: Header 10: Content-Length: 0 (17)
[Mar 6 17:04:34] DEBUG[16390] chan_sip.c: Header 11: (0)
[Mar 6 17:04:34] DEBUG[13034] devicestate.c: Notification of state change to be queued on device/channel SIP/bandwidth
[Mar 6 17:04:34] DEBUG[16384] devicestate.c: No provider found, checking channel drivers for SIP - bandwidth
[Mar 6 17:04:34] VERBOSE[13034] logger.c: – SIP/bandwidth-09b40610 answered SIP/4.68.250.148-09b3a900
[Mar 6 17:04:34] DEBUG[16384] chan_sip.c: Checking device state for peer bandwidth
[Mar 6 17:04:34] DEBUG[13034] channel.c: Set channel SIP/4.68.250.148-09b3a900 to write format ulaw
[Mar 6 17:04:34] DEBUG[16384] devicestate.c: Changing state for SIP/bandwidth - state 1 (Not in use)
[Mar 6 17:04:34] DEBUG[16409] app_queue.c: Device ‘SIP/bandwidth’ changed to state ‘1’ (Not in use) but we don’t care because they’re not a member of any queue.
[Mar 6 17:04:34] DEBUG[13035] audiohook.c: Read factory 0x9b17768 was pretty quick last time, waiting for them.
[Mar 6 17:04:34] DEBUG[13034] rtp.c: Ooh, format changed from unknown to ulaw
[Mar 6 17:04:34] DEBUG[13034] rtp.c: Created smoother: format: 4 ms: 20 len: 160
[Mar 6 17:04:34] DEBUG[13035] audiohook.c: Read factory 0x9b17768 was pretty quick last time, waiting for them.
… 431 lines …
[Mar 6 17:04:43] DEBUG[13035] audiohook.c: Read factory 0x9b17768 was pretty quick last time, waiting for them.
[Mar 6 17:04:43] VERBOSE[16390] logger.c:
<— SIP read from 216.82.224.202:5060 —>
BYE sip:+1INBOUND_NUMBER@AST_SERVER_IP SIP/2.0
Record-Route: sip:216.82.224.202;lr;ftag=VPSF506071629460
Via: SIP/2.0/UDP 216.82.224.202;branch=z9hG4bKb1e3.d4c3ccf5.0
Via: SIP/2.0/UDP 4.79.212.229;branch=z9hG4bKb1e3.8e21dd8.0
Via: SIP/2.0/UDP 4.68.250.148:5060;branch=z9hG4bK506071629460-1207494131736
From: “CALLERID NAME” sip:+1CALLERID[NUMBER]@4.68.250.148;isup-oli=62;tag=VPSF506071629460
To: sip:+1INBOUND_NUMBER@4.79.212.229:5060;tag=as369c3467
Call-ID: BOSMGC0320090306221543019314@209.244.63.175
CSeq: 2 BYE
Contact: sip:4.68.250.148:5060;transport=udp
Max-Forwards: 67
Content-Length: 0

<------------->
[Mar 6 17:04:43] DEBUG[16390] chan_sip.c: Header 0: BYE sip:+1INBOUND_NUMBER@AST_SERVER_IP SIP/2.0 (42)
[Mar 6 17:04:43] DEBUG[16390] chan_sip.c: Header 1: Record-Route: sip:216.82.224.202;lr;ftag=VPSF506071629460 (59)
[Mar 6 17:04:43] DEBUG[16390] chan_sip.c: Header 2: Via: SIP/2.0/UDP 216.82.224.202;branch=z9hG4bKb1e3.d4c3ccf5.0 (61)
[Mar 6 17:04:43] DEBUG[16390] chan_sip.c: Header 3: Via: SIP/2.0/UDP 4.79.212.229;branch=z9hG4bKb1e3.8e21dd8.0 (58)
[Mar 6 17:04:43] DEBUG[16390] chan_sip.c: Header 4: Via: SIP/2.0/UDP 4.68.250.148:5060;branch=z9hG4bK506071629460-1207494131736 (75)
[Mar 6 17:04:43] DEBUG[16390] chan_sip.c: Header 5: From: “CALLERID NAME” sip:+1CALLERID[NUMBER]@4.68.250.148;isup-oli=62;tag=VPSF506071629460 (89)
[Mar 6 17:04:43] DEBUG[16390] chan_sip.c: Header 6: To: sip:+1INBOUND_NUMBER@4.79.212.229:5060;tag=as369c3467 (55)
[Mar 6 17:04:43] DEBUG[16390] chan_sip.c: Header 7: Call-ID: BOSMGC0320090306221543019314@209.244.63.175 (52)
[Mar 6 17:04:43] DEBUG[16390] chan_sip.c: Header 8: CSeq: 2 BYE (11)
[Mar 6 17:04:43] DEBUG[16390] chan_sip.c: Header 9: Contact: sip:4.68.250.148:5060;transport=udp (46)
[Mar 6 17:04:43] DEBUG[16390] chan_sip.c: Header 10: Max-Forwards: 67 (16)
[Mar 6 17:04:43] DEBUG[16390] chan_sip.c: Header 11: Content-Length: 0 (17)
[Mar 6 17:04:43] DEBUG[16390] chan_sip.c: Header 12: (0)
[Mar 6 17:04:43] VERBOSE[16390] logger.c: — (12 headers 0 lines) —
[Mar 6 17:04:43] DEBUG[16390] chan_sip.c: = No match Their Call ID: 5b451ce8380242be181a03de69dfcfff@AST_SERVER_IP Their Tag SD2f4f999-gK06bcd966 Our tag: as083655ce
[Mar 6 17:04:43] DEBUG[16390] chan_sip.c: = Found Their Call ID: BOSMGC0320090306221543019314@209.244.63.175 Their Tag VPSF506071629460 Our tag: as369c3467
[Mar 6 17:04:43] DEBUG[16390] chan_sip.c: **** Received BYE (8) - Command in SIP BYE
[Mar 6 17:04:43] VERBOSE[16390] logger.c: Sending to 216.82.224.202 : 5060 (no NAT)
[Mar 6 17:04:43] DEBUG[16390] chan_sip.c: Setting SIP_ALREADYGONE on dialog BOSMGC0320090306221543019314@209.244.63.175
[Mar 6 17:04:43] DEBUG[16390] chan_sip.c: Received bye, issuing owner hangup
[Mar 6 17:04:43] VERBOSE[16390] logger.c:
<— Transmitting (no NAT) to 216.82.224.202:5060 —>
SIP/2.0 200 OK
Via: SIP/2.0/UDP 216.82.224.202;branch=z9hG4bKb1e3.d4c3ccf5.0;received=216.82.224.202
Via: SIP/2.0/UDP 4.79.212.229;branch=z9hG4bKb1e3.8e21dd8.0
Via: SIP/2.0/UDP 4.68.250.148:5060;branch=z9hG4bK506071629460-1207494131736
Record-Route: sip:216.82.224.202;lr;ftag=VPSF506071629460
From: “CALLERID NAME” sip:+1CALLERID[NUMBER]@4.68.250.148;isup-oli=62;tag=VPSF506071629460
To: sip:+1INBOUND_NUMBER@4.79.212.229:5060;tag=as369c3467
Call-ID: BOSMGC0320090306221543019314@209.244.63.175
CSeq: 2 BYE
User-Agent: Asterisk PBX
Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY
Supported: replaces
Contact: sip:+1INBOUND_NUMBER@AST_SERVER_IP
Content-Length: 0

<------------>
[Mar 6 17:04:43] DEBUG[16390] chan_sip.c: Header 0: SIP/2.0 200 OK (14)
[Mar 6 17:04:43] DEBUG[16390] chan_sip.c: Header 1: Via: SIP/2.0/UDP 216.82.224.202;branch=z9hG4bKb1e3.d4c3ccf5.0;received=216.82.224.202 (85)
[Mar 6 17:04:43] DEBUG[16390] chan_sip.c: Header 2: Via: SIP/2.0/UDP 4.79.212.229;branch=z9hG4bKb1e3.8e21dd8.0 (58)
[Mar 6 17:04:43] DEBUG[16390] chan_sip.c: Header 3: Via: SIP/2.0/UDP 4.68.250.148:5060;branch=z9hG4bK506071629460-1207494131736 (75)
[Mar 6 17:04:43] DEBUG[16390] chan_sip.c: Header 4: Record-Route: sip:216.82.224.202;lr;ftag=VPSF506071629460 (59)
[Mar 6 17:04:43] DEBUG[16390] chan_sip.c: Header 5: From: “CALLERID NAME” sip:+1CALLERID[NUMBER]@4.68.250.148;isup-oli=62;tag=VPSF506071629460 (89)
[Mar 6 17:04:43] DEBUG[16390] chan_sip.c: Header 6: To: sip:+1INBOUND_NUMBER@4.79.212.229:5060;tag=as369c3467 (55)
[Mar 6 17:04:43] DEBUG[16390] chan_sip.c: Header 7: Call-ID: BOSMGC0320090306221543019314@209.244.63.175 (52)
[Mar 6 17:04:43] DEBUG[16390] chan_sip.c: Header 8: CSeq: 2 BYE (11)
[Mar 6 17:04:43] DEBUG[16390] chan_sip.c: Header 9: User-Agent: Asterisk PBX (24)
[Mar 6 17:04:43] DEBUG[16390] chan_sip.c: Header 10: Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY (66)
[Mar 6 17:04:43] DEBUG[16390] chan_sip.c: Header 11: Supported: replaces (19)
[Mar 6 17:04:43] DEBUG[16390] chan_sip.c: Header 12: Contact: sip:+1INBOUND_NUMBER@AST_SERVER_IP (41)
[Mar 6 17:04:43] DEBUG[16390] chan_sip.c: Header 13: Content-Length: 0 (17)
[Mar 6 17:04:43] DEBUG[16390] chan_sip.c: Header 14: (0)
[Mar 6 17:04:43] DEBUG[13034] channel.c: Didn’t get a frame from channel: SIP/4.68.250.148-09b3a900
[Mar 6 17:04:43] DEBUG[13034] channel.c: Bridge stops bridging channels SIP/4.68.250.148-09b3a900 and SIP/bandwidth-09b40610
[Mar 6 17:04:43] VERBOSE[16390] logger.c:
<— SIP read from 216.82.224.202:5060 —>
BYE sip:CALLERID[NUMBER]@AST_SERVER_IP SIP/2.0
Record-Route: sip:216.82.224.202;lr;ftag=SD2f4f999-gK06bcd966
Via: SIP/2.0/UDP 216.82.224.202;branch=z9hG4bKf7fa.80f76cf3.0
Via: SIP/2.0/UDP 72.166.216.140:5060;branch=z9hG4bK0o4smb2018chpd03a1k0sd000s7c3.1
From: sip:+FORWARDING_NUMBER@216.82.224.202;tag=SD2f4f999-gK06bcd966
To: “CALLERID NAME” sip:CALLERID[NUMBER]@AST_SERVER_IP;tag=as083655ce
Call-ID: 5b451ce8380242be181a03de69dfcfff@AST_SERVER_IP
CSeq: 32472 BYE
Max-Forwards: 68
Content-Length: 0

<------------->
[Mar 6 17:04:43] DEBUG[16390] chan_sip.c: Header 0: BYE sip:CALLERID[NUMBER]@AST_SERVER_IP SIP/2.0 (40)
[Mar 6 17:04:43] DEBUG[16390] chan_sip.c: Header 1: Record-Route: sip:216.82.224.202;lr;ftag=SD2f4f999-gK06bcd966 (63)
[Mar 6 17:04:43] DEBUG[16390] chan_sip.c: Header 2: Via: SIP/2.0/UDP 216.82.224.202;branch=z9hG4bKf7fa.80f76cf3.0 (61)
[Mar 6 17:04:43] DEBUG[16390] chan_sip.c: Header 3: Via: SIP/2.0/UDP 72.166.216.140:5060;branch=z9hG4bK0o4smb2018chpd03a1k0sd000s7c3.1 (82)
[Mar 6 17:04:43] DEBUG[16390] chan_sip.c: Header 4: From: sip:+FORWARDING_NUMBER@216.82.224.202;tag=SD2f4f999-gK06bcd966 (64)
[Mar 6 17:04:43] DEBUG[16390] chan_sip.c: Header 5: To: “CALLERID NAME” sip:CALLERID[NUMBER]@AST_SERVER_IP;tag=as083655ce (67)
[Mar 6 17:04:43] DEBUG[16390] chan_sip.c: Header 6: Call-ID: 5b451ce8380242be181a03de69dfcfff@AST_SERVER_IP (55)
[Mar 6 17:04:43] DEBUG[16390] chan_sip.c: Header 7: CSeq: 32472 BYE (15)
[Mar 6 17:04:43] DEBUG[16390] chan_sip.c: Header 8: Max-Forwards: 68 (16)
[Mar 6 17:04:43] DEBUG[16390] chan_sip.c: Header 9: Content-Length: 0 (17)
[Mar 6 17:04:43] DEBUG[16390] chan_sip.c: Header 10: (0)
[Mar 6 17:04:43] VERBOSE[16390] logger.c: — (10 headers 0 lines) —
[Mar 6 17:04:43] DEBUG[16390] chan_sip.c: = Found Their Call ID: 5b451ce8380242be181a03de69dfcfff@AST_SERVER_IP Their Tag SD2f4f999-gK06bcd966 Our tag: as083655ce
[Mar 6 17:04:43] DEBUG[16390] chan_sip.c: **** Received BYE (8) - Command in SIP BYE
[Mar 6 17:04:43] VERBOSE[16390] logger.c: Sending to 216.82.224.202 : 5060 (no NAT)
[Mar 6 17:04:43] DEBUG[16390] chan_sip.c: Setting SIP_ALREADYGONE on dialog 5b451ce8380242be181a03de69dfcfff@AST_SERVER_IP
[Mar 6 17:04:43] DEBUG[16390] chan_sip.c: Received bye, issuing owner hangup
[Mar 6 17:04:43] VERBOSE[16390] logger.c:
<— Transmitting (no NAT) to 216.82.224.202:5060 —>
SIP/2.0 200 OK
Via: SIP/2.0/UDP 216.82.224.202;branch=z9hG4bKf7fa.80f76cf3.0;received=216.82.224.202
Via: SIP/2.0/UDP 72.166.216.140:5060;branch=z9hG4bK0o4smb2018chpd03a1k0sd000s7c3.1
Record-Route: sip:216.82.224.202;lr;ftag=SD2f4f999-gK06bcd966
From: sip:+FORWARDING_NUMBER@216.82.224.202;tag=SD2f4f999-gK06bcd966
To: “CALLERID NAME” sip:CALLERID[NUMBER]@AST_SERVER_IP;tag=as083655ce
Call-ID: 5b451ce8380242be181a03de69dfcfff@AST_SERVER_IP
CSeq: 32472 BYE
User-Agent: Asterisk PBX
Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY
Supported: replaces
Contact: sip:CALLERID[NUMBER]@AST_SERVER_IP
Content-Length: 0

<------------>
[Mar 6 17:04:43] DEBUG[16390] chan_sip.c: Header 0: SIP/2.0 200 OK (14)
[Mar 6 17:04:43] DEBUG[16390] chan_sip.c: Header 1: Via: SIP/2.0/UDP 216.82.224.202;branch=z9hG4bKf7fa.80f76cf3.0;received=216.82.224.202 (85)
[Mar 6 17:04:43] DEBUG[16390] chan_sip.c: Header 2: Via: SIP/2.0/UDP 72.166.216.140:5060;branch=z9hG4bK0o4smb2018chpd03a1k0sd000s7c3.1 (82)
[Mar 6 17:04:43] DEBUG[16390] chan_sip.c: Header 3: Record-Route: sip:216.82.224.202;lr;ftag=SD2f4f999-gK06bcd966 (63)
[Mar 6 17:04:43] DEBUG[16390] chan_sip.c: Header 4: From: sip:+FORWARDING_NUMBER@216.82.224.202;tag=SD2f4f999-gK06bcd966 (64)
[Mar 6 17:04:43] DEBUG[16390] chan_sip.c: Header 5: To: “CALLERID NAME” sip:CALLERID[NUMBER]@AST_SERVER_IP;tag=as083655ce (67)
[Mar 6 17:04:43] DEBUG[16390] chan_sip.c: Header 6: Call-ID: 5b451ce8380242be181a03de69dfcfff@AST_SERVER_IP (55)
[Mar 6 17:04:43] DEBUG[16390] chan_sip.c: Header 7: CSeq: 32472 BYE (15)
[Mar 6 17:04:43] DEBUG[16390] chan_sip.c: Header 8: User-Agent: Asterisk PBX (24)
[Mar 6 17:04:43] DEBUG[16390] chan_sip.c: Header 9: Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY (66)
[Mar 6 17:04:43] DEBUG[16390] chan_sip.c: Header 10: Supported: replaces (19)
[Mar 6 17:04:43] DEBUG[16390] chan_sip.c: Header 11: Contact: sip:CALLERID[NUMBER]@AST_SERVER_IP (39)
[Mar 6 17:04:43] DEBUG[16390] chan_sip.c: Header 12: Content-Length: 0 (17)
[Mar 6 17:04:43] DEBUG[16390] chan_sip.c: Header 13: (0)
[Mar 6 17:04:43] DEBUG[13034] pbx.c: Function result is ‘1’
[Mar 6 17:04:43] DEBUG[13034] pbx.c: Launching ‘Set’
[Mar 6 17:04:43] VERBOSE[13034] logger.c: – Executing [h@CAP-FORWARDING:1] Set(“SIP/4.68.250.148-09b3a900”, “DONE=1”) in new stack
[Mar 6 17:04:43] DEBUG[13034] channel.c: Hanging up channel ‘SIP/bandwidth-09b40610’
[Mar 6 17:04:43] DEBUG[13034] chan_sip.c: Hangup call SIP/bandwidth-09b40610, SIP callid 5b451ce8380242be181a03de69dfcfff@AST_SERVER_IP)
[Mar 6 17:04:43] DEBUG[13034] devicestate.c: Notification of state change to be queued on device/channel SIP/bandwidth
[Mar 6 17:04:43] DEBUG[16384] devicestate.c: No provider found, checking channel drivers for SIP - bandwidth
[Mar 6 17:04:43] DEBUG[16384] chan_sip.c: Checking device state for peer bandwidth
[Mar 6 17:04:43] DEBUG[16384] devicestate.c: Changing state for SIP/bandwidth - state 1 (Not in use)
[Mar 6 17:04:43] DEBUG[13034] rtp.c: Channel ‘’ has no RTP, not doing anything
[Mar 6 17:04:43] DEBUG[16409] app_queue.c: Device ‘SIP/bandwidth’ changed to state ‘1’ (Not in use) but we don’t care because they’re not a member of any queue.
[Mar 6 17:04:43] DEBUG[13034] app_dial.c: Exiting with DIALSTATUS=ANSWER.
[Mar 6 17:04:43] DEBUG[13034] pbx.c: Spawn extension (CAP-FORWARDING,s,27) exited non-zero on ‘SIP/4.68.250.148-09b3a900’
[Mar 6 17:04:43] VERBOSE[13034] logger.c: == Spawn extension (CAP-FORWARDING, s, 27) exited non-zero on ‘SIP/4.68.250.148-09b3a900’
[Mar 6 17:04:43] DEBUG[13034] channel.c: Soft-Hanging up channel ‘SIP/4.68.250.148-09b3a900’
[Mar 6 17:04:43] DEBUG[13034] channel.c: Hanging up channel ‘SIP/4.68.250.148-09b3a900’
[Mar 6 17:04:43] DEBUG[13034] chan_sip.c: Hangup call SIP/4.68.250.148-09b3a900, SIP callid BOSMGC0320090306221543019314@209.244.63.175)
[Mar 6 17:04:43] VERBOSE[13035] logger.c: == End MixMonitor Recording SIP/4.68.250.148-09b3a900
[Mar 6 17:04:43] DEBUG[13034] devicestate.c: Notification of state change to be queued on device/channel SIP/4.68.250.148
[Mar 6 17:04:43] VERBOSE[13035] logger.c: == Executing [/var/spool/asterisk/monitor/v2putmp3.sh DASHCALL-CALLERID[NUMBER]-INBOUND_NUMBER-20090307030423.wav >> /var/log/asterisk/v2log.log 2>&1]
[Mar 6 17:04:43] DEBUG[16384] devicestate.c: No provider found, checking channel drivers for SIP - 4.68.250.148
[Mar 6 17:04:43] DEBUG[16384] chan_sip.c: Checking device state for peer 4.68.250.148
[Mar 6 17:04:43] DEBUG[16384] devicestate.c: Changing state for SIP/4.68.250.148 - state 1 (Not in use)
[Mar 6 17:04:43] DEBUG[16409] app_queue.c: Device ‘SIP/4.68.250.148’ changed to state ‘1’ (Not in use) but we don’t care because they’re not a member of any queue.
[Mar 6 17:04:44] VERBOSE[16390] logger.c: Really destroying SIP dialog ‘5b451ce8380242be181a03de69dfcfff@AST_SERVER_IP’ Method: BYE
[Mar 6 17:04:44] DEBUG[16390] chan_sip.c:
---------- SIP HISTORY for ‘5b451ce8380242be181a03de69dfcfff@AST_SERVER_IP’
[Mar 6 17:04:44] DEBUG[16390] chan_sip.c: * SIP Call
[Mar 6 17:04:44] DEBUG[16390] chan_sip.c: 001. NewChan Channel SIP/bandwidth-09b40610 - from 5b451ce8380242be181a03de6
[Mar 6 17:04:44] DEBUG[16390] chan_sip.c: 002. TxReqRel INVITE / 102 INVITE - -UNKNOWN-
[Mar 6 17:04:44] DEBUG[16390] chan_sip.c: 003. Rx SIP/2.0 / 102 INVITE / 100 Giving a try
[Mar 6 17:04:44] DEBUG[16390] chan_sip.c: 004. Rx SIP/2.0 / 102 INVITE / 183 Session Progress
[Mar 6 17:04:44] DEBUG[16390] chan_sip.c: 005. Rx SIP/2.0 / 102 INVITE / 200 OK
[Mar 6 17:04:44] DEBUG[16390] chan_sip.c: 006. TxReq ACK / 102 ACK - -UNKNOWN-
[Mar 6 17:04:44] DEBUG[16390] chan_sip.c: 007. Rx BYE / 32472 BYE / sip:CALLERID[NUMBER]@AST_SERVER_IP
[Mar 6 17:04:44] DEBUG[16390] chan_sip.c: 008. RTCPaudio Quality:ssrc=1282922489;themssrc=3466834023;lp=0;rxjitter=0.000
[Mar 6 17:04:44] DEBUG[16390] chan_sip.c: 009. TxResp SIP/2.0 / 32472 BYE - 200 OK
[Mar 6 17:04:44] DEBUG[16390] chan_sip.c: 010. Hangup Cause Normal Clearing
[Mar 6 17:04:44] DEBUG[16390] chan_sip.c:
---------- END SIP HISTORY for ‘5b451ce8380242be181a03de69dfcfff@AST_SERVER_IP’
[Mar 6 17:04:44] VERBOSE[16390] logger.c: Really destroying SIP dialog ‘BOSMGC0320090306221543019314@209.244.63.175’ Method: BYE
[Mar 6 17:04:44] DEBUG[16390] chan_sip.c:
---------- SIP HISTORY for ‘BOSMGC0320090306221543019314@209.244.63.175’
[Mar 6 17:04:44] DEBUG[16390] chan_sip.c: * SIP Call
[Mar 6 17:04:44] DEBUG[16390] chan_sip.c: 001. Rx INVITE / 1 INVITE / sip:+1INBOUND_NUMBER@gil.conversionassociates.c
[Mar 6 17:04:44] DEBUG[16390] chan_sip.c: 002. NewChan Channel SIP/4.68.250.148-09b3a900 - from BOSMGC0320090306221543
[Mar 6 17:04:44] DEBUG[16390] chan_sip.c: 003. TxResp SIP/2.0 / 1 INVITE - 100 Trying
[Mar 6 17:04:44] DEBUG[16390] chan_sip.c: 004. TxRespRel SIP/2.0 / 1 INVITE - 200 OK
[Mar

Topic		Replies	Views
Cracking menu audio issue Asterisk Support	2	252	January 11, 2008
One-way Audio, very intermittent and with timeout Asterisk Support	1	271	December 14, 2010
Delay in hearing the initial audio for 0.5-1 sec Asterisk Support	8	579	December 4, 2018
One Second break in audio every so often Asterisk Support	2	249	February 6, 2013
Dropped Calls Asterisk Support	4	444	July 14, 2009

Read Factory %p was pretty quick last time Delays 2way Audio

Related topics