NOTES FOR THE LOG: Our "external" IP address is replaced with 88.88.88.88 Peer's IP address is replaced with 99.99.99.99 Peer's name is changed to AcmeInc My comments start at the BOL with four pound charachers. The initial calls enters the dialplan from the trunk SIP/AcmeInc; the dialplan enables Monitor recording (not MixMonitor!) on the parent channel and places the call into a queue named AcmeInc. Agent dyn-AcmeInc-7228 picks up the call. After that we receive an INVITE with a Replaces: header that causes the recording to stop, which I believe is a bug. [2010-09-04 23:33:45.935] VERBOSE[25781] chan_sip.c: <--- SIP read from UDP:99.99.99.99:5060 ---> INVITE sip:572@88.88.88.88 SIP/2.0 Via: SIP/2.0/UDP 99.99.99.99:5060;branch=z9hG4bK4ff795ca5a8ca8c460468d98c5253863 Via: SIP/2.0/UDP 99.99.99.99:5060;branch=z9hG4bK4ff795ca5a8ca8c460468d98c5253863;received=99.99.99.99 Max-Forwards: 70 Record-Route: To: 572 From: 550 ;tag=c384c82d83058073 Call-ID: 8000000c14c82d83058261@99.99.99.99 CSeq: 18 INVITE Contact: 550 Content-Type: application/sdp Content-Length: 282 Supported: replaces v=0 o=550 1283643440 1283643440 IN IP4 99.99.99.99 s=- c=IN IP4 99.99.99.99 t=0 0 m=audio 16480 RTP/AVP 0 18 101 102 a=rtpmap:0 PCMU/8000 a=ptime:20 a=rtpmap:18 G729/8000 a=ptime:40 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-15 a=rtpmap:102 tone/8000 a=sendrecv <-------------> [2010-09-04 23:33:45.935] DEBUG[25781] chan_sip.c: Header 0 [ 36]: INVITE sip:572@88.88.88.88 SIP/2.0 [2010-09-04 23:33:45.935] DEBUG[25781] chan_sip.c: Header 1 [ 81]: Via: SIP/2.0/UDP 99.99.99.99:5060;branch=z9hG4bK4ff795ca5a8ca8c460468d98c5253863 [2010-09-04 23:33:45.935] DEBUG[25781] chan_sip.c: Header 2 [103]: Via: SIP/2.0/UDP 99.99.99.99:5060;branch=z9hG4bK4ff795ca5a8ca8c460468d98c5253863;received=99.99.99.99 [2010-09-04 23:33:45.935] DEBUG[25781] chan_sip.c: Header 3 [ 16]: Max-Forwards: 70 [2010-09-04 23:33:45.935] DEBUG[25781] chan_sip.c: Header 4 [ 32]: Record-Route: [2010-09-04 23:33:45.935] DEBUG[25781] chan_sip.c: Header 5 [ 30]: To: 572 [2010-09-04 23:33:45.935] DEBUG[25781] chan_sip.c: Header 6 [ 64]: From: 550 ;tag=c384c82d83058073 [2010-09-04 23:33:45.935] DEBUG[25781] chan_sip.c: Header 7 [ 44]: Call-ID: 8000000c14c82d83058261@99.99.99.99 [2010-09-04 23:33:45.935] DEBUG[25781] chan_sip.c: Header 8 [ 15]: CSeq: 18 INVITE [2010-09-04 23:33:45.935] DEBUG[25781] chan_sip.c: Header 9 [ 46]: Contact: 550 [2010-09-04 23:33:45.935] DEBUG[25781] chan_sip.c: Header 10 [ 29]: Content-Type: application/sdp [2010-09-04 23:33:45.935] DEBUG[25781] chan_sip.c: Header 11 [ 19]: Content-Length: 282 [2010-09-04 23:33:45.935] DEBUG[25781] chan_sip.c: Header 12 [ 19]: Supported: replaces [2010-09-04 23:33:45.935] DEBUG[25781] chan_sip.c: Header 13 [ 0]: [2010-09-04 23:33:45.935] DEBUG[25781] chan_sip.c: Body 0 [ 3]: v=0 [2010-09-04 23:33:45.935] DEBUG[25781] chan_sip.c: Body 1 [ 47]: o=550 1283643440 1283643440 IN IP4 99.99.99.99 [2010-09-04 23:33:45.935] DEBUG[25781] chan_sip.c: Body 2 [ 3]: s=- [2010-09-04 23:33:45.935] DEBUG[25781] chan_sip.c: Body 3 [ 21]: c=IN IP4 99.99.99.99 [2010-09-04 23:33:45.935] DEBUG[25781] chan_sip.c: Body 4 [ 5]: t=0 0 [2010-09-04 23:33:45.935] DEBUG[25781] chan_sip.c: Body 5 [ 34]: m=audio 16480 RTP/AVP 0 18 101 102 [2010-09-04 23:33:45.935] DEBUG[25781] chan_sip.c: Body 6 [ 20]: a=rtpmap:0 PCMU/8000 [2010-09-04 23:33:45.935] DEBUG[25781] chan_sip.c: Body 7 [ 10]: a=ptime:20 [2010-09-04 23:33:45.935] DEBUG[25781] chan_sip.c: Body 8 [ 21]: a=rtpmap:18 G729/8000 [2010-09-04 23:33:45.935] DEBUG[25781] chan_sip.c: Body 9 [ 10]: a=ptime:40 [2010-09-04 23:33:45.935] DEBUG[25781] chan_sip.c: Body 10 [ 33]: a=rtpmap:101 telephone-event/8000 [2010-09-04 23:33:45.935] DEBUG[25781] chan_sip.c: Body 11 [ 15]: a=fmtp:101 0-15 [2010-09-04 23:33:45.935] DEBUG[25781] chan_sip.c: Body 12 [ 22]: a=rtpmap:102 tone/8000 [2010-09-04 23:33:45.935] DEBUG[25781] chan_sip.c: Body 13 [ 10]: a=sendrecv [2010-09-04 23:33:45.935] VERBOSE[25781] chan_sip.c: --- (13 headers 14 lines) --- [2010-09-04 23:33:45.935] DEBUG[25781] acl.c: Found IP address for this socket [2010-09-04 23:33:45.935] DEBUG[25781] chan_sip.c: Target address 99.99.99.99 is not local, substituting externip [2010-09-04 23:33:45.935] DEBUG[25781] chan_sip.c: Setting SIP_TRANSPORT_UDP with address 88.88.88.88:5060 [2010-09-04 23:33:45.935] VERBOSE[25781] netsock.c: == Using SIP RTP CoS mark 5 [2010-09-04 23:33:45.935] DEBUG[25781] chan_sip.c: Setting NAT on RTP to Off [2010-09-04 23:33:45.935] DEBUG[25781] chan_sip.c: Allocating new SIP dialog for 8000000c14c82d83058261@99.99.99.99 - INVITE (With RTP) [2010-09-04 23:33:45.935] DEBUG[25781] chan_sip.c: **** Received INVITE (5) - Command in SIP INVITE [2010-09-04 23:33:45.935] DEBUG[25781] chan_sip.c: Begin: parsing SIP "Supported: replaces" [2010-09-04 23:33:45.935] DEBUG[25781] chan_sip.c: Found SIP option: -replaces- [2010-09-04 23:33:45.935] DEBUG[25781] chan_sip.c: Matched SIP option: replaces [2010-09-04 23:33:45.935] VERBOSE[25781] chan_sip.c: Sending to 99.99.99.99 : 5060 (no NAT) [2010-09-04 23:33:45.935] DEBUG[25781] chan_sip.c: Initializing initreq for method INVITE - callid 8000000c14c82d83058261@99.99.99.99 [2010-09-04 23:33:45.935] VERBOSE[25781] chan_sip.c: Using INVITE request as basis request - 8000000c14c82d83058261@99.99.99.99 [2010-09-04 23:33:45.935] VERBOSE[25781] chan_sip.c: Found peer 'AcmeInc' for '550' from 99.99.99.99:5060 [2010-09-04 23:33:45.935] DEBUG[25781] chan_sip.c: Setting NAT on RTP to Off [2010-09-04 23:33:45.935] DEBUG[25781] chan_sip.c: Processing session-level SDP v=0... UNSUPPORTED. [2010-09-04 23:33:45.935] DEBUG[25781] chan_sip.c: Processing session-level SDP o=550 1283643440 1283643440 IN IP4 99.99.99.99... UNSUPPORTED. [2010-09-04 23:33:45.935] DEBUG[25781] chan_sip.c: Processing session-level SDP s=-... UNSUPPORTED. [2010-09-04 23:33:45.935] DEBUG[25781] chan_sip.c: Processing session-level SDP c=IN IP4 99.99.99.99... OK. [2010-09-04 23:33:45.935] DEBUG[25781] chan_sip.c: Processing session-level SDP t=0 0... UNSUPPORTED. [2010-09-04 23:33:45.935] VERBOSE[25781] chan_sip.c: Found RTP audio format 0 [2010-09-04 23:33:45.935] VERBOSE[25781] chan_sip.c: Found RTP audio format 18 [2010-09-04 23:33:45.935] VERBOSE[25781] chan_sip.c: Found RTP audio format 101 [2010-09-04 23:33:45.935] VERBOSE[25781] chan_sip.c: Found RTP audio format 102 [2010-09-04 23:33:45.935] VERBOSE[25781] chan_sip.c: Found audio description format PCMU for ID 0 [2010-09-04 23:33:45.935] DEBUG[25781] chan_sip.c: Processing media-level (audio) SDP a=rtpmap:0 PCMU/8000... OK. [2010-09-04 23:33:45.935] DEBUG[25781] chan_sip.c: Processing media-level (audio) SDP a=ptime:20... OK. [2010-09-04 23:33:45.935] VERBOSE[25781] chan_sip.c: Found audio description format G729 for ID 18 [2010-09-04 23:33:45.935] DEBUG[25781] chan_sip.c: Processing media-level (audio) SDP a=rtpmap:18 G729/8000... OK. [2010-09-04 23:33:45.935] DEBUG[25781] chan_sip.c: Processing media-level (audio) SDP a=ptime:40... OK. [2010-09-04 23:33:45.935] VERBOSE[25781] chan_sip.c: Found audio description format telephone-event for ID 101 [2010-09-04 23:33:45.935] DEBUG[25781] chan_sip.c: Processing media-level (audio) SDP a=rtpmap:101 telephone-event/8000... OK. [2010-09-04 23:33:45.935] DEBUG[25781] chan_sip.c: Processing media-level (audio) SDP a=fmtp:101 0-15... UNSUPPORTED. [2010-09-04 23:33:45.935] VERBOSE[25781] chan_sip.c: Found audio description format tone for ID 102 [2010-09-04 23:33:45.935] DEBUG[25781] chan_sip.c: Processing media-level (audio) SDP a=rtpmap:102 tone/8000... OK. [2010-09-04 23:33:45.935] DEBUG[25781] chan_sip.c: Processing media-level (audio) SDP a=sendrecv... OK. [2010-09-04 23:33:45.935] VERBOSE[25781] chan_sip.c: Capabilities: us - 0x4 (ulaw), peer - audio=0x2104 (ulaw|g729|siren7)/video=0x0 (nothing)/text=0x0 (nothing), combined - 0x4 (ulaw) [2010-09-04 23:33:45.935] VERBOSE[25781] chan_sip.c: Non-codec capabilities (dtmf): us - 0x1 (telephone-event), peer - 0x1 (telephone-event), combined - 0x1 (telephone-event) [2010-09-04 23:33:45.935] VERBOSE[25781] chan_sip.c: Peer audio RTP is at port 99.99.99.99:16480 [2010-09-04 23:33:45.935] DEBUG[25781] chan_sip.c: We're settling with these formats: 0x4 (ulaw) [2010-09-04 23:33:45.935] DEBUG[25781] chan_sip.c: Checking SIP call limits for device [2010-09-04 23:33:45.935] DEBUG[25781] chan_sip.c: Updating call counter for incoming call [2010-09-04 23:33:45.935] DEBUG[25781] chan_sip.c: Call from peer 'AcmeInc' is 1 out of 2147483647 [2010-09-04 23:33:45.935] VERBOSE[25781] chan_sip.c: Looking for 572 in from-AcmeInc (domain 88.88.88.88) [2010-09-04 23:33:45.935] DEBUG[25771] devicestate.c: No provider found, checking channel drivers for SIP - AcmeInc [2010-09-04 23:33:45.935] DEBUG[25771] chan_sip.c: Checking device state for peer AcmeInc [2010-09-04 23:33:45.935] DEBUG[25771] devicestate.c: Changing state for SIP/AcmeInc - state 2 (In use) [2010-09-04 23:33:45.935] DEBUG[25771] devicestate.c: device 'SIP/AcmeInc' state '2' [2010-09-04 23:33:45.935] DEBUG[25781] chan_sip.c: *** Our native formats are 0x4 (ulaw) [2010-09-04 23:33:45.935] DEBUG[25781] chan_sip.c: *** Joint capabilities are 0x4 (ulaw) [2010-09-04 23:33:45.935] DEBUG[25781] chan_sip.c: *** Our capabilities are 0x4 (ulaw) [2010-09-04 23:33:45.935] DEBUG[25781] chan_sip.c: *** AST_CODEC_CHOOSE formats are 0x4 (ulaw) [2010-09-04 23:33:45.935] DEBUG[25781] chan_sip.c: This channel will not be able to handle video. [2010-09-04 23:33:45.935] DEBUG[25781] chan_sip.c: build_route: Record-Route hop: [2010-09-04 23:33:45.935] DEBUG[25781] chan_sip.c: build_route: Contact hop: 550 [2010-09-04 23:33:45.935] VERBOSE[25781] chan_sip.c: list_route: hop: [2010-09-04 23:33:45.935] VERBOSE[25781] chan_sip.c: list_route: hop: [2010-09-04 23:33:45.935] DEBUG[25781] chan_sip.c: SIP/AcmeInc-0001169f: New call is still down.... Trying... [2010-09-04 23:33:45.935] VERBOSE[25781] chan_sip.c: <--- Transmitting (no NAT) to 99.99.99.99:5060 ---> SIP/2.0 100 Trying Via: SIP/2.0/UDP 99.99.99.99:5060;branch=z9hG4bK4ff795ca5a8ca8c460468d98c5253863;received=99.99.99.99 Via: SIP/2.0/UDP 99.99.99.99:5060;branch=z9hG4bK4ff795ca5a8ca8c460468d98c5253863;received=99.99.99.99 Record-Route: From: 550 ;tag=c384c82d83058073 To: 572 Call-ID: 8000000c14c82d83058261@99.99.99.99 CSeq: 18 INVITE Server: AigoPBX-04/1.6.1 Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO Supported: replaces, timer Contact: Content-Length: 0 <------------> [2010-09-04 23:33:45.935] DEBUG[25781] chan_sip.c: Trying to put 'SIP/2.0 100' onto UDP socket destined for 99.99.99.99:5060 [2010-09-04 23:33:45.935] DEBUG[25782] app_queue.c: Device 'SIP/AcmeInc' changed to state '2' (In use) but we don't care because they're not a member of any queue. [2010-09-04 23:33:45.936] DEBUG[25771] devicestate.c: No provider found, checking channel drivers for SIP - AcmeInc [2010-09-04 23:33:45.936] DEBUG[25771] chan_sip.c: Checking device state for peer AcmeInc [2010-09-04 23:33:45.936] DEBUG[25771] devicestate.c: Changing state for SIP/AcmeInc - state 2 (In use) [2010-09-04 23:33:45.936] DEBUG[25771] devicestate.c: device 'SIP/AcmeInc' state '2' [2010-09-04 23:33:45.936] DEBUG[10246] pbx.c: Launching 'MSet' [2010-09-04 23:33:45.936] VERBOSE[10246] pbx.c: -- Executing [572@from-AcmeInc:1] MSet("SIP/AcmeInc-0001169f", "~~EXTEN~~=572") in new stack [2010-09-04 23:33:45.936] DEBUG[25782] app_queue.c: Device 'SIP/AcmeInc' changed to state '2' (In use) but we don't care because they're not a member of any queue. [2010-09-04 23:33:45.936] DEBUG[10246] pbx.c: Function result is '550' [2010-09-04 23:33:45.936] DEBUG[10246] pbx.c: Launching 'Goto' [2010-09-04 23:33:45.936] VERBOSE[10246] pbx.c: -- Executing [572@from-AcmeInc:2] Goto("SIP/AcmeInc-0001169f", "sw-937-550,10") in new stack [2010-09-04 23:33:45.936] VERBOSE[10246] pbx.c: -- Goto (from-AcmeInc,sw-937-550,10) [2010-09-04 23:33:45.936] DEBUG[10246] pbx.c: Launching 'Goto' [2010-09-04 23:33:45.936] VERBOSE[10246] pbx.c: -- Executing [sw-937-550@from-AcmeInc:10] Goto("SIP/AcmeInc-0001169f", "_[!-z].,3") in new stack [2010-09-04 23:33:45.936] VERBOSE[10246] pbx.c: -- Goto (from-AcmeInc,_[!-z].,3) [2010-09-04 23:33:45.936] DEBUG[10246] pbx.c: Launching 'NoOp' [2010-09-04 23:33:45.936] VERBOSE[10246] pbx.c: -- Executing [_[!-z].@from-AcmeInc:3] NoOp("SIP/AcmeInc-0001169f", "Finish switch-from-AcmeInc-937") in new stack [2010-09-04 23:33:45.936] DEBUG[10246] pbx.c: Launching 'Goto' [2010-09-04 23:33:45.936] VERBOSE[10246] pbx.c: -- Executing [_[!-z].@from-AcmeInc:4] Goto("SIP/AcmeInc-0001169f", "cust-billing,AcmeInc,1") in new stack [2010-09-04 23:33:45.936] VERBOSE[10246] pbx.c: -- Goto (cust-billing,AcmeInc,1) [2010-09-04 23:33:45.936] DEBUG[10246] pbx.c: Expression result is '"BILLING"' [2010-09-04 23:33:45.936] DEBUG[10246] pbx.c: Launching 'MSet' [2010-09-04 23:33:45.936] VERBOSE[10246] pbx.c: -- Executing [AcmeInc@cust-billing:1] MSet("SIP/AcmeInc-0001169f", "CDR(amaflags)="BILLING"") in new stack [2010-09-04 23:33:45.936] DEBUG[10246] pbx.c: Launching 'Goto' [2010-09-04 23:33:45.936] VERBOSE[10246] pbx.c: -- Executing [AcmeInc@cust-billing:2] Goto("SIP/AcmeInc-0001169f", "customer-common,AcmeInc,1") in new stack [2010-09-04 23:33:45.936] VERBOSE[10246] pbx.c: -- Goto (customer-common,AcmeInc,1) [2010-09-04 23:33:45.936] DEBUG[10246] pbx.c: Launching 'MSet' [2010-09-04 23:33:45.936] VERBOSE[10246] pbx.c: -- Executing [AcmeInc@customer-common:1] MSet("SIP/AcmeInc-0001169f", "~~EXTEN~~=AcmeInc") in new stack [2010-09-04 23:33:45.936] DEBUG[10246] pbx.c: Expression result is '"secureIN#unsecureIN"' [2010-09-04 23:33:45.936] DEBUG[10246] pbx.c: Launching 'MSet' [2010-09-04 23:33:45.936] VERBOSE[10246] pbx.c: -- Executing [AcmeInc@customer-common:2] MSet("SIP/AcmeInc-0001169f", "__DYNAMIC_FEATURES="secureIN#unsecureIN"") in new stack [2010-09-04 23:33:45.936] DEBUG[10246] pbx.c: Expression result is '"AcmeInc"' [2010-09-04 23:33:45.936] DEBUG[10246] pbx.c: Launching 'MSet' [2010-09-04 23:33:45.936] VERBOSE[10246] pbx.c: -- Executing [AcmeInc@customer-common:3] MSet("SIP/AcmeInc-0001169f", "__CUSTAPP="AcmeInc"") in new stack [2010-09-04 23:33:45.936] DEBUG[10246] pbx.c: Expression result is '"04-1283668425.71328"' [2010-09-04 23:33:45.936] DEBUG[10246] pbx.c: Launching 'MSet' [2010-09-04 23:33:45.936] VERBOSE[10246] pbx.c: -- Executing [AcmeInc@customer-common:4] MSet("SIP/AcmeInc-0001169f", "__TOP_UID="04-1283668425.71328"") in new stack [2010-09-04 23:33:45.936] DEBUG[10246] pbx.c: Expression result is '"SIP/AcmeInc-0001169f"' [2010-09-04 23:33:45.936] DEBUG[10246] pbx.c: Launching 'MSet' [2010-09-04 23:33:45.936] VERBOSE[10246] pbx.c: -- Executing [AcmeInc@customer-common:5] MSet("SIP/AcmeInc-0001169f", "__TOP_CHAN="SIP/AcmeInc-0001169f"") in new stack [2010-09-04 23:33:45.936] DEBUG[10246] pbx.c: Expression result is '3600' [2010-09-04 23:33:45.936] DEBUG[10246] pbx.c: Launching 'MSet' [2010-09-04 23:33:45.936] VERBOSE[10246] pbx.c: -- Executing [AcmeInc@customer-common:6] MSet("SIP/AcmeInc-0001169f", "QUETIME=3600") in new stack [2010-09-04 23:33:45.936] DEBUG[10246] pbx.c: Function result is '"550" <550>' [2010-09-04 23:33:45.936] DEBUG[10246] pbx.c: Function result is '572' [2010-09-04 23:33:45.936] DEBUG[10246] pbx.c: Function result is 'BILLING' [2010-09-04 23:33:45.936] DEBUG[10246] pbx.c: Launching 'Gosub' [2010-09-04 23:33:45.936] VERBOSE[10246] pbx.c: -- Executing [AcmeInc@customer-common:7] Gosub("SIP/AcmeInc-0001169f", "trace,s,1(Staring call from "550" <550> to 572; AF:BILLING)") in new stack [2010-09-04 23:33:45.936] DEBUG[10246] app_stack.c: Channel SIP/AcmeInc-0001169f has no datastore, so we're allocating one. [2010-09-04 23:33:45.936] DEBUG[10246] app_stack.c: Setting 'ARG1' to 'Staring call from "550" <550> to 572; AF:BILLING' [2010-09-04 23:33:45.936] DEBUG[10246] pbx.c: Launching 'MSet' [2010-09-04 23:33:45.936] VERBOSE[10246] pbx.c: -- Executing [s@trace:1] MSet("SIP/AcmeInc-0001169f", "LOCAL(msg)=Staring call from "550" <550> to 572; AF:BILLING") in new stack [2010-09-04 23:33:45.936] DEBUG[10246] pbx.c: Function result is '100904-233345' [2010-09-04 23:33:45.936] DEBUG[10246] pbx.c: Expression result is '1' [2010-09-04 23:33:45.936] DEBUG[10246] pbx.c: Function result is '04-1283668425.71328' [2010-09-04 23:33:45.936] DEBUG[10246] pbx.c: Launching 'Verbose' [2010-09-04 23:33:45.936] VERBOSE[10246] pbx.c: -- Executing [s@trace:2] Verbose("SIP/AcmeInc-0001169f", "1,* 100904-233345 04-1283668425.71328 AcmeInc Staring call from 550 <550> to 572; AF:BILLING") in new stack [2010-09-04 23:33:45.936] VERBOSE[10246] app_verbose.c: * 100904-233345 04-1283668425.71328 AcmeInc Staring call from 550 <550> to 572; AF:BILLING [2010-09-04 23:33:45.936] DEBUG[10246] pbx.c: Launching 'Return' [2010-09-04 23:33:45.936] VERBOSE[10246] pbx.c: -- Executing [s@trace:3] Return("SIP/AcmeInc-0001169f", "") in new stack [2010-09-04 23:33:45.936] DEBUG[10246] pbx.c: Expression result is '"AcmeInc"' [2010-09-04 23:33:45.936] DEBUG[10246] pbx.c: Launching 'MSet' [2010-09-04 23:33:45.936] VERBOSE[10246] pbx.c: -- Executing [AcmeInc@customer-common:8] MSet("SIP/AcmeInc-0001169f", "CDR(accountcode)="AcmeInc"") in new stack [2010-09-04 23:33:45.937] DEBUG[10246] pbx.c: Function result is '572' [2010-09-04 23:33:45.937] DEBUG[10246] pbx.c: Launching 'SIPAddHeader' [2010-09-04 23:33:45.937] VERBOSE[10246] pbx.c: -- Executing [AcmeInc@customer-common:9] SIPAddHeader("SIP/AcmeInc-0001169f", "X-Via-DID: 572") in new stack [2010-09-04 23:33:45.937] DEBUG[10246] chan_sip.c: SIP Header added "X-Via-DID: 572" as __SIPADDHEADER01 [2010-09-04 23:33:45.937] DEBUG[10246] pbx.c: Launching 'SIPAddHeader' [2010-09-04 23:33:45.937] VERBOSE[10246] pbx.c: -- Executing [AcmeInc@customer-common:10] SIPAddHeader("SIP/AcmeInc-0001169f", "X-Account-Code: AcmeInc") in new stack [2010-09-04 23:33:45.937] DEBUG[10246] chan_sip.c: SIP Header added "X-Account-Code: AcmeInc" as __SIPADDHEADER02 [2010-09-04 23:33:45.937] DEBUG[10246] pbx.c: Launching 'Gosub' [2010-09-04 23:33:45.937] VERBOSE[10246] pbx.c: -- Executing [AcmeInc@customer-common:11] Gosub("SIP/AcmeInc-0001169f", "prep-channel,s,1(AcmeInc,IN)") in new stack [2010-09-04 23:33:45.937] DEBUG[10246] app_stack.c: Setting 'ARG1' to 'AcmeInc' [2010-09-04 23:33:45.937] DEBUG[10246] app_stack.c: Setting 'ARG2' to 'IN' [2010-09-04 23:33:45.937] DEBUG[10246] pbx.c: Launching 'MSet' [2010-09-04 23:33:45.937] VERBOSE[10246] pbx.c: -- Executing [s@prep-channel:1] MSet("SIP/AcmeInc-0001169f", "LOCAL(chanid)=AcmeInc") in new stack [2010-09-04 23:33:45.937] DEBUG[10246] pbx.c: Launching 'MSet' [2010-09-04 23:33:45.937] VERBOSE[10246] pbx.c: -- Executing [s@prep-channel:2] MSet("SIP/AcmeInc-0001169f", "LOCAL(dir)=IN") in new stack [2010-09-04 23:33:45.937] DEBUG[10246] pbx.c: Launching 'MSet' [2010-09-04 23:33:45.937] VERBOSE[10246] pbx.c: -- Executing [s@prep-channel:3] MSet("SIP/AcmeInc-0001169f", "LOCAL(~~EXTEN~~)=s") in new stack [2010-09-04 23:33:45.937] DEBUG[10246] pbx.c: Launching 'MSet' [2010-09-04 23:33:45.937] VERBOSE[10246] pbx.c: -- Executing [s@prep-channel:4] MSet("SIP/AcmeInc-0001169f", "LOCAL(~~EXTEN~~)=s") in new stack [2010-09-04 23:33:45.937] DEBUG[10246] pbx.c: Expression result is '"secureIN#unsecureIN"' [2010-09-04 23:33:45.937] DEBUG[10246] pbx.c: Launching 'MSet' [2010-09-04 23:33:45.937] VERBOSE[10246] pbx.c: -- Executing [s@prep-channel:5] MSet("SIP/AcmeInc-0001169f", "__DYNAMIC_FEATURES="secureIN#unsecureIN"") in new stack [2010-09-04 23:33:45.937] DEBUG[10246] pbx.c: Expression result is '0' [2010-09-04 23:33:45.937] DEBUG[10246] pbx.c: Launching 'GotoIf' [2010-09-04 23:33:45.937] VERBOSE[10246] pbx.c: -- Executing [s@prep-channel:6] GotoIf("SIP/AcmeInc-0001169f", "0?7:8") in new stack [2010-09-04 23:33:45.937] VERBOSE[10246] pbx.c: -- Goto (prep-channel,s,8) [2010-09-04 23:33:45.937] DEBUG[10246] pbx.c: Launching 'NoOp' [2010-09-04 23:33:45.937] VERBOSE[10246] pbx.c: -- Executing [s@prep-channel:8] NoOp("SIP/AcmeInc-0001169f", "Finish if-prep-channel-966") in new stack [2010-09-04 23:33:45.937] DEBUG[10246] pbx.c: Expression result is '"04-1283668425.71328"' [2010-09-04 23:33:45.937] DEBUG[10246] pbx.c: Launching 'MSet' [2010-09-04 23:33:45.937] VERBOSE[10246] pbx.c: -- Executing [s@prep-channel:9] MSet("SIP/AcmeInc-0001169f", "CDR(associd)="04-1283668425.71328"") in new stack [2010-09-04 23:33:45.937] DEBUG[10246] pbx.c: Expression result is '1' [2010-09-04 23:33:45.937] DEBUG[10246] pbx.c: Launching 'GotoIf' [2010-09-04 23:33:45.937] VERBOSE[10246] pbx.c: -- Executing [s@prep-channel:10] GotoIf("SIP/AcmeInc-0001169f", "1?11:14") in new stack [2010-09-04 23:33:45.937] VERBOSE[10246] pbx.c: -- Goto (prep-channel,s,11) [2010-09-04 23:33:45.937] DEBUG[10246] pbx.c: Launching 'SIPAddHeader' [2010-09-04 23:33:45.937] VERBOSE[10246] pbx.c: -- Executing [s@prep-channel:11] SIPAddHeader("SIP/AcmeInc-0001169f", "X-Astid-Parent: 04-1283668425.71328") in new stack [2010-09-04 23:33:45.937] DEBUG[10246] chan_sip.c: SIP Header added "X-Astid-Parent: 04-1283668425.71328" as __SIPADDHEADER03 [2010-09-04 23:33:45.937] DEBUG[10246] pbx.c: Function result is '550' [2010-09-04 23:33:45.937] DEBUG[10246] pbx.c: Launching 'Goto' [2010-09-04 23:33:45.937] VERBOSE[10246] pbx.c: -- Executing [s@prep-channel:12] Goto("SIP/AcmeInc-0001169f", "sw-968-"550",10") in new stack [2010-09-04 23:33:45.937] VERBOSE[10246] pbx.c: -- Goto (prep-channel,sw-968-"550",10) [2010-09-04 23:33:45.937] DEBUG[10246] pbx.c: Function result is '20100904-233345' [2010-09-04 23:33:45.937] DEBUG[10246] pbx.c: Expression result is '"20100904-233345-04-1283668425.71328-AcmeInc"' [2010-09-04 23:33:45.937] DEBUG[10246] pbx.c: Launching 'MSet' [2010-09-04 23:33:45.937] VERBOSE[10246] pbx.c: -- Executing [sw-968-"550"@prep-channel:10] MSet("SIP/AcmeInc-0001169f", "MON_FILE="20100904-233345-04-1283668425.71328-AcmeInc"") in new stack [2010-09-04 23:33:45.937] DEBUG[10246] pbx.c: Launching 'Gosub' [2010-09-04 23:33:45.937] VERBOSE[10246] pbx.c: -- Executing [sw-968-"550"@prep-channel:11] Gosub("SIP/AcmeInc-0001169f", "trace,s,1(Start recording 20100904-233345-04-1283668425.71328-AcmeInc on SIP/AcmeInc-0001169f")") in new stack [2010-09-04 23:33:45.937] DEBUG[10246] app_stack.c: Setting 'ARG1' to 'Start recording 20100904-233345-04-1283668425.71328-AcmeInc on SIP/AcmeInc-0001169f"' [2010-09-04 23:33:45.937] DEBUG[10246] app_stack.c: Setting 'ARG2' to '' [2010-09-04 23:33:45.937] DEBUG[10246] pbx.c: Launching 'MSet' [2010-09-04 23:33:45.937] VERBOSE[10246] pbx.c: -- Executing [s@trace:1] MSet("SIP/AcmeInc-0001169f", "LOCAL(msg)=Start recording 20100904-233345-04-1283668425.71328-AcmeInc on SIP/AcmeInc-0001169f"") in new stack [2010-09-04 23:33:45.937] DEBUG[10246] pbx.c: Function result is '100904-233345' [2010-09-04 23:33:45.937] DEBUG[10246] pbx.c: Expression result is '1' [2010-09-04 23:33:45.937] DEBUG[10246] pbx.c: Function result is '04-1283668425.71328' [2010-09-04 23:33:45.937] DEBUG[10246] pbx.c: Launching 'Verbose' [2010-09-04 23:33:45.937] VERBOSE[10246] pbx.c: -- Executing [s@trace:2] Verbose("SIP/AcmeInc-0001169f", "1,* 100904-233345 04-1283668425.71328 AcmeInc Start recording 20100904-233345-04-1283668425.71328-AcmeInc on SIP/AcmeInc-0001169f") in new stack [2010-09-04 23:33:45.937] VERBOSE[10246] app_verbose.c: * 100904-233345 04-1283668425.71328 AcmeInc Start recording 20100904-233345-04-1283668425.71328-AcmeInc on SIP/AcmeInc-0001169f [2010-09-04 23:33:45.937] DEBUG[10246] pbx.c: Launching 'Return' [2010-09-04 23:33:45.937] VERBOSE[10246] pbx.c: -- Executing [s@trace:3] Return("SIP/AcmeInc-0001169f", "") in new stack [2010-09-04 23:33:45.938] DEBUG[10246] pbx.c: Launching 'Monitor' [2010-09-04 23:33:45.938] VERBOSE[10246] pbx.c: -- Executing [sw-968-"550"@prep-channel:12] Monitor("SIP/AcmeInc-0001169f", "wav,20100904-233345-04-1283668425.71328-AcmeInc,mb") in new stack [2010-09-04 23:33:45.938] DEBUG[10246] pbx.c: Expression result is '"20100904-233345-04-1283668425.71328-AcmeInc"' [2010-09-04 23:33:45.938] DEBUG[10246] pbx.c: Launching 'MSet' [2010-09-04 23:33:45.938] VERBOSE[10246] pbx.c: -- Executing [sw-968-"550"@prep-channel:13] MSet("SIP/AcmeInc-0001169f", "CDR(monitor)="20100904-233345-04-1283668425.71328-AcmeInc"") in new stack [2010-09-04 23:33:45.938] DEBUG[10246] pbx.c: Launching 'Goto' [2010-09-04 23:33:45.938] VERBOSE[10246] pbx.c: -- Executing [sw-968-"550"@prep-channel:14] Goto("SIP/AcmeInc-0001169f", "s,13") in new stack [2010-09-04 23:33:45.938] VERBOSE[10246] pbx.c: -- Goto (prep-channel,s,13) [2010-09-04 23:33:45.938] DEBUG[10246] pbx.c: Launching 'NoOp' [2010-09-04 23:33:45.938] VERBOSE[10246] pbx.c: -- Executing [s@prep-channel:13] NoOp("SIP/AcmeInc-0001169f", "Finish switch-if-prep-channel-967-968") in new stack [2010-09-04 23:33:45.938] DEBUG[10246] pbx.c: Launching 'NoOp' [2010-09-04 23:33:45.938] VERBOSE[10246] pbx.c: -- Executing [s@prep-channel:14] NoOp("SIP/AcmeInc-0001169f", "Finish if-prep-channel-967") in new stack [2010-09-04 23:33:45.938] DEBUG[10246] pbx.c: Launching 'Return' [2010-09-04 23:33:45.938] VERBOSE[10246] pbx.c: -- Executing [s@prep-channel:15] Return("SIP/AcmeInc-0001169f", "") in new stack [2010-09-04 23:33:45.938] DEBUG[10246] pbx.c: Function result is '0' [2010-09-04 23:33:45.938] DEBUG[10246] pbx.c: Expression result is '0' [2010-09-04 23:33:45.938] DEBUG[10246] pbx.c: Launching 'GotoIf' [2010-09-04 23:33:45.938] VERBOSE[10246] pbx.c: -- Executing [AcmeInc@customer-common:12] GotoIf("SIP/AcmeInc-0001169f", "0?13:15") in new stack [2010-09-04 23:33:45.938] VERBOSE[10246] pbx.c: -- Goto (customer-common,AcmeInc,15) [2010-09-04 23:33:45.938] DEBUG[10246] pbx.c: Launching 'NoOp' [2010-09-04 23:33:45.938] VERBOSE[10246] pbx.c: -- Executing [AcmeInc@customer-common:15] NoOp("SIP/AcmeInc-0001169f", "Finish if-customer-common-941") in new stack [2010-09-04 23:33:45.938] DEBUG[10246] app_queue.c: Queue AcmeInc has no realtime members defined. No need for update [2010-09-04 23:33:45.938] DEBUG[10246] pbx.c: Function result is '3' [2010-09-04 23:33:45.938] DEBUG[10246] pbx.c: Expression result is '0' [2010-09-04 23:33:45.938] DEBUG[10246] pbx.c: Launching 'GotoIf' [2010-09-04 23:33:45.938] VERBOSE[10246] pbx.c: -- Executing [AcmeInc@customer-common:16] GotoIf("SIP/AcmeInc-0001169f", "0?17:21") in new stack [2010-09-04 23:33:45.938] VERBOSE[10246] pbx.c: -- Goto (customer-common,AcmeInc,21) [2010-09-04 23:33:45.938] DEBUG[10246] pbx.c: Launching 'NoOp' [2010-09-04 23:33:45.938] VERBOSE[10246] pbx.c: -- Executing [AcmeInc@customer-common:21] NoOp("SIP/AcmeInc-0001169f", "Finish if-customer-common-942") in new stack [2010-09-04 23:33:45.938] DEBUG[10246] app_queue.c: Queue AcmeInc has no realtime members defined. No need for update [2010-09-04 23:33:45.938] DEBUG[10246] pbx.c: Function result is '3' [2010-09-04 23:33:45.938] DEBUG[10246] app_queue.c: Queue AcmeInc has no realtime members defined. No need for update [2010-09-04 23:33:45.938] DEBUG[10246] pbx.c: Function result is '3' [2010-09-04 23:33:45.938] DEBUG[10246] pbx.c: Expression result is '0' [2010-09-04 23:33:45.938] DEBUG[10246] pbx.c: Launching 'GotoIf' [2010-09-04 23:33:45.938] VERBOSE[10246] pbx.c: -- Executing [AcmeInc@customer-common:22] GotoIf("SIP/AcmeInc-0001169f", "0?23:25") in new stack [2010-09-04 23:33:45.938] VERBOSE[10246] pbx.c: -- Goto (customer-common,AcmeInc,25) [2010-09-04 23:33:45.938] DEBUG[10246] pbx.c: Launching 'NoOp' [2010-09-04 23:33:45.938] VERBOSE[10246] pbx.c: -- Executing [AcmeInc@customer-common:25] NoOp("SIP/AcmeInc-0001169f", "Finish if-customer-common-943") in new stack [2010-09-04 23:33:45.938] DEBUG[10246] pbx.c: Launching 'Gosub' [2010-09-04 23:33:45.938] VERBOSE[10246] pbx.c: -- Executing [AcmeInc@customer-common:26] Gosub("SIP/AcmeInc-0001169f", "queue-stats,s,1(AcmeInc)") in new stack [2010-09-04 23:33:45.938] DEBUG[10246] app_stack.c: Setting 'ARG1' to 'AcmeInc' [2010-09-04 23:33:45.938] DEBUG[10246] pbx.c: Launching 'MSet' [2010-09-04 23:33:45.938] VERBOSE[10246] pbx.c: -- Executing [s@queue-stats:1] MSet("SIP/AcmeInc-0001169f", "LOCAL(quename)=AcmeInc") in new stack [2010-09-04 23:33:45.938] DEBUG[10246] pbx.c: Function result is '0' [2010-09-04 23:33:45.938] DEBUG[10246] pbx.c: Expression result is '1' [2010-09-04 23:33:45.938] DEBUG[10246] pbx.c: Launching 'GotoIf' [2010-09-04 23:33:45.938] VERBOSE[10246] pbx.c: -- Executing [s@queue-stats:2] GotoIf("SIP/AcmeInc-0001169f", "1?3:5") in new stack [2010-09-04 23:33:45.938] VERBOSE[10246] pbx.c: -- Goto (queue-stats,s,3) [2010-09-04 23:33:45.938] DEBUG[10246] app_queue.c: Queue AcmeInc has no realtime members defined. No need for update [2010-09-04 23:33:45.938] DEBUG[10246] pbx.c: Function result is '3' [2010-09-04 23:33:45.938] DEBUG[10246] app_queue.c: Queue AcmeInc has no realtime members defined. No need for update [2010-09-04 23:33:45.938] DEBUG[10246] pbx.c: Function result is '3' [2010-09-04 23:33:45.938] DEBUG[10246] pbx.c: Expression result is 'Agt:3/3 Cls:0/0 C/A:36/0 Hld:0 SL:100.0' [2010-09-04 23:33:45.938] DEBUG[10246] pbx.c: Launching 'MSet' [2010-09-04 23:33:45.938] VERBOSE[10246] pbx.c: -- Executing [s@queue-stats:3] MSet("SIP/AcmeInc-0001169f", "QUEUE_STATS=Agt:3/3 Cls:0/0 C/A:36/0 Hld:0 SL:100.0") in new stack [2010-09-04 23:33:45.938] DEBUG[10246] pbx.c: Launching 'Goto' [2010-09-04 23:33:45.938] VERBOSE[10246] pbx.c: -- Executing [s@queue-stats:4] Goto("SIP/AcmeInc-0001169f", "6") in new stack [2010-09-04 23:33:45.938] VERBOSE[10246] pbx.c: -- Goto (queue-stats,s,6) [2010-09-04 23:33:45.938] DEBUG[10246] pbx.c: Launching 'NoOp' [2010-09-04 23:33:45.938] VERBOSE[10246] pbx.c: -- Executing [s@queue-stats:6] NoOp("SIP/AcmeInc-0001169f", "Finish if-queue-stats-953") in new stack [2010-09-04 23:33:45.938] DEBUG[10246] pbx.c: Launching 'Return' [2010-09-04 23:33:45.938] VERBOSE[10246] pbx.c: -- Executing [s@queue-stats:7] Return("SIP/AcmeInc-0001169f", "") in new stack [2010-09-04 23:33:45.938] DEBUG[10246] pbx.c: Launching 'Gosub' [2010-09-04 23:33:45.938] VERBOSE[10246] pbx.c: -- Executing [AcmeInc@customer-common:27] Gosub("SIP/AcmeInc-0001169f", "trace,s,1(Entering queue - Agt:3/3 Cls:0/0 C/A:36/0 Hld:0 SL:100.0)") in new stack [2010-09-04 23:33:45.939] DEBUG[10246] app_stack.c: Setting 'ARG1' to 'Entering queue - Agt:3/3 Cls:0/0 C/A:36/0 Hld:0 SL:100.0' [2010-09-04 23:33:45.939] DEBUG[10246] pbx.c: Launching 'MSet' [2010-09-04 23:33:45.939] VERBOSE[10246] pbx.c: -- Executing [s@trace:1] MSet("SIP/AcmeInc-0001169f", "LOCAL(msg)=Entering queue - Agt:3/3 Cls:0/0 C/A:36/0 Hld:0 SL:100.0") in new stack [2010-09-04 23:33:45.939] DEBUG[10246] pbx.c: Function result is '100904-233345' [2010-09-04 23:33:45.939] DEBUG[10246] pbx.c: Expression result is '1' [2010-09-04 23:33:45.939] DEBUG[10246] pbx.c: Function result is '04-1283668425.71328' [2010-09-04 23:33:45.939] DEBUG[10246] pbx.c: Launching 'Verbose' [2010-09-04 23:33:45.939] VERBOSE[10246] pbx.c: -- Executing [s@trace:2] Verbose("SIP/AcmeInc-0001169f", "1,* 100904-233345 04-1283668425.71328 AcmeInc Entering queue - Agt:3/3 Cls:0/0 C/A:36/0 Hld:0 SL:100.0") in new stack [2010-09-04 23:33:45.939] VERBOSE[10246] app_verbose.c: * 100904-233345 04-1283668425.71328 AcmeInc Entering queue - Agt:3/3 Cls:0/0 C/A:36/0 Hld:0 SL:100.0 [2010-09-04 23:33:45.939] DEBUG[10246] pbx.c: Launching 'Return' [2010-09-04 23:33:45.939] VERBOSE[10246] pbx.c: -- Executing [s@trace:3] Return("SIP/AcmeInc-0001169f", "") in new stack [2010-09-04 23:33:45.939] DEBUG[10246] pbx.c: Launching 'Answer' [2010-09-04 23:33:45.939] VERBOSE[10246] pbx.c: -- Executing [AcmeInc@customer-common:28] Answer("SIP/AcmeInc-0001169f", "0,nocdr") in new stack [2010-09-04 23:33:45.939] DEBUG[25771] devicestate.c: No provider found, checking channel drivers for SIP - AcmeInc [2010-09-04 23:33:45.939] DEBUG[10246] chan_sip.c: SIP answering channel: SIP/AcmeInc-0001169f [2010-09-04 23:33:45.939] DEBUG[10246] rtp.c: Setting the marker bit due to a source update [2010-09-04 23:33:45.939] DEBUG[25771] chan_sip.c: Checking device state for peer AcmeInc [2010-09-04 23:33:45.939] DEBUG[25771] devicestate.c: Changing state for SIP/AcmeInc - state 2 (In use) [2010-09-04 23:33:45.939] DEBUG[25771] devicestate.c: device 'SIP/AcmeInc' state '2' [2010-09-04 23:33:45.939] DEBUG[10246] chan_sip.c: Setting framing from config on incoming call [2010-09-04 23:33:45.939] DEBUG[10246] chan_sip.c: ** Our capability: 0x4 (ulaw) Video flag: True Text flag: True [2010-09-04 23:33:45.939] DEBUG[10246] chan_sip.c: ** Our prefcodec: 0x0 (nothing) [2010-09-04 23:33:45.939] VERBOSE[10246] chan_sip.c: Audio is at 88.88.88.88 port 17730 [2010-09-04 23:33:45.939] VERBOSE[10246] chan_sip.c: Adding codec 0x4 (ulaw) to SDP [2010-09-04 23:33:45.939] VERBOSE[10246] chan_sip.c: Adding non-codec 0x1 (telephone-event) to SDP [2010-09-04 23:33:45.939] DEBUG[10246] chan_sip.c: -- Done with adding codecs to SDP [2010-09-04 23:33:45.939] DEBUG[10246] chan_sip.c: Done building SDP. Settling with this capability: 0x4 (ulaw) [2010-09-04 23:33:45.939] VERBOSE[10246] chan_sip.c: <--- Reliably Transmitting (no NAT) to 99.99.99.99:5060 ---> SIP/2.0 200 OK Via: SIP/2.0/UDP 99.99.99.99:5060;branch=z9hG4bK4ff795ca5a8ca8c460468d98c5253863;received=99.99.99.99 Via: SIP/2.0/UDP 99.99.99.99:5060;branch=z9hG4bK4ff795ca5a8ca8c460468d98c5253863;received=99.99.99.99 Record-Route: From: 550 ;tag=c384c82d83058073 To: 572 ;tag=as3432aedc Call-ID: 8000000c14c82d83058261@99.99.99.99 CSeq: 18 INVITE Server: AigoPBX-04/1.6.1 Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO Supported: replaces, timer Contact: Content-Type: application/sdp Content-Length: 273 v=0 o=root 980849082 980849082 IN IP4 88.88.88.88 s=Asterisk PBX local/1.6.2/09@47 c=IN IP4 88.88.88.88 t=0 0 m=audio 17730 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 <------------> [2010-09-04 23:33:45.939] DEBUG[25782] app_queue.c: Device 'SIP/AcmeInc' changed to state '2' (In use) but we don't care because they're not a member of any queue. [2010-09-04 23:33:45.939] DEBUG[10246] chan_sip.c: *** SIP TIMER: Initializing retransmit timer on packet: Id #59346892 [2010-09-04 23:33:45.939] DEBUG[10246] chan_sip.c: Trying to put 'SIP/2.0 200' onto UDP socket destined for 99.99.99.99:5060 [2010-09-04 23:33:45.952] DEBUG[25781] chan_sip.c: Header 0 [ 0]: [2010-09-04 23:33:45.974] VERBOSE[25781] chan_sip.c: <--- SIP read from UDP:99.99.99.99:5060 ---> ACK sip:572@88.88.88.88 SIP/2.0 Via: SIP/2.0/UDP 99.99.99.99:5060;branch=z9hG4bKba28693642504b8c39837fba22b99aee Via: SIP/2.0/UDP 99.99.99.99:5060;branch=z9hG4bKba28693642504b8c39837fba22b99aee;received=99.99.99.99 Max-Forwards: 70 Record-Route: From: 550 ;tag=c384c82d83058073 To: 572 ;tag=as3432aedc Call-ID: 8000000c14c82d83058261@99.99.99.99 CSeq: 18 ACK Content-Length: 0 <-------------> [2010-09-04 23:33:45.974] DEBUG[25781] chan_sip.c: Header 0 [ 33]: ACK sip:572@88.88.88.88 SIP/2.0 [2010-09-04 23:33:45.974] DEBUG[25781] chan_sip.c: Header 1 [ 81]: Via: SIP/2.0/UDP 99.99.99.99:5060;branch=z9hG4bKba28693642504b8c39837fba22b99aee [2010-09-04 23:33:45.974] DEBUG[25781] chan_sip.c: Header 2 [103]: Via: SIP/2.0/UDP 99.99.99.99:5060;branch=z9hG4bKba28693642504b8c39837fba22b99aee;received=99.99.99.99 [2010-09-04 23:33:45.974] DEBUG[25781] chan_sip.c: Header 3 [ 16]: Max-Forwards: 70 [2010-09-04 23:33:45.974] DEBUG[25781] chan_sip.c: Header 4 [ 32]: Record-Route: [2010-09-04 23:33:45.974] DEBUG[25781] chan_sip.c: Header 5 [ 64]: From: 550 ;tag=c384c82d83058073 [2010-09-04 23:33:45.974] DEBUG[25781] chan_sip.c: Header 6 [ 45]: To: 572 ;tag=as3432aedc [2010-09-04 23:33:45.974] DEBUG[25781] chan_sip.c: Header 7 [ 44]: Call-ID: 8000000c14c82d83058261@99.99.99.99 [2010-09-04 23:33:45.974] DEBUG[25781] chan_sip.c: Header 8 [ 12]: CSeq: 18 ACK [2010-09-04 23:33:45.974] DEBUG[25781] chan_sip.c: Header 9 [ 17]: Content-Length: 0 [2010-09-04 23:33:45.974] DEBUG[25781] chan_sip.c: Header 10 [ 0]: [2010-09-04 23:33:45.974] VERBOSE[25781] chan_sip.c: --- (10 headers 0 lines) --- [2010-09-04 23:33:45.974] DEBUG[25781] chan_sip.c: **** Received ACK (6) - Command in SIP ACK [2010-09-04 23:33:45.974] DEBUG[25781] chan_sip.c: ** SIP TIMER: Cancelling retransmit of packet (reply received) Retransid #59346892 [2010-09-04 23:33:45.974] DEBUG[25781] chan_sip.c: Stopping retransmission on '8000000c14c82d83058261@99.99.99.99' of Response 18: Match Found [2010-09-04 23:33:46.161] DEBUG[10246] pbx.c: Launching 'Queue' [2010-09-04 23:33:46.161] VERBOSE[10246] pbx.c: -- Executing [AcmeInc@customer-common:29] Queue("SIP/AcmeInc-0001169f", "AcmeInc,ct,,,3600,,,on-queue-answer") in new stack [2010-09-04 23:33:46.161] DEBUG[10246] app_queue.c: NO QUEUE_PRIO variable found. Using default. [2010-09-04 23:33:46.161] DEBUG[10246] app_queue.c: queue: AcmeInc, options: ct, url: , announce: , expires: 1283672026, priority: 0 [2010-09-04 23:33:46.161] DEBUG[10246] app_queue.c: Queue AcmeInc has no realtime members defined. No need for update [2010-09-04 23:33:46.161] DEBUG[10246] app_queue.c: SIP/dyn-AcmeInc-7228 is available. [2010-09-04 23:33:46.161] DEBUG[10246] app_queue.c: Queue 'AcmeInc' Join, Channel 'SIP/AcmeInc-0001169f', Position '1' [2010-09-04 23:33:46.161] VERBOSE[10246] res_musiconhold.c: -- Started music on hold, class 'default', on SIP/AcmeInc-0001169f [2010-09-04 23:33:46.161] DEBUG[10246] channel.c: Scheduling timer at (50 requested / 50 actual) timer ticks per second [2010-09-04 23:33:46.161] DEBUG[10246] app_queue.c: There are 3 available members. [2010-09-04 23:33:46.161] DEBUG[10246] app_queue.c: It's our turn (SIP/AcmeInc-0001169f). [2010-09-04 23:33:46.161] DEBUG[10246] app_queue.c: SIP/AcmeInc-0001169f is trying to call a queue member. [2010-09-04 23:33:46.161] DEBUG[10246] app_queue.c: Trying 'SIP/dyn-AcmeInc-7228' with metric 0 [2010-09-04 23:33:46.161] DEBUG[10246] chan_sip.c: Asked to create a SIP channel with formats: 0x4 (ulaw) [2010-09-04 23:33:46.162] VERBOSE[10246] netsock.c: == Using SIP RTP CoS mark 5 [2010-09-04 23:33:46.162] DEBUG[10246] chan_sip.c: Allocating new SIP dialog for 39066ff01403a51b5dd334680472e796@10.20.0.104 - INVITE (With RTP) [2010-09-04 23:33:46.162] DEBUG[10246] chan_sip.c: Setting NAT on RTP to Off [2010-09-04 23:33:46.162] DEBUG[10246] chan_sip.c: OBPROXY: Not applying OBproxy to this call [2010-09-04 23:33:46.162] DEBUG[10246] acl.c: Found IP address for this socket [2010-09-04 23:33:46.162] DEBUG[10246] chan_sip.c: Setting SIP_TRANSPORT_UDP with address 10.20.0.104:5060 [2010-09-04 23:33:46.162] DEBUG[10246] chan_sip.c: *** Our native formats are 0x4 (ulaw) [2010-09-04 23:33:46.162] DEBUG[10246] chan_sip.c: *** Joint capabilities are 0x4 (ulaw) [2010-09-04 23:33:46.162] DEBUG[10246] chan_sip.c: *** Our capabilities are 0x4 (ulaw) [2010-09-04 23:33:46.162] DEBUG[10246] chan_sip.c: *** AST_CODEC_CHOOSE formats are 0x4 (ulaw) [2010-09-04 23:33:46.162] DEBUG[10246] chan_sip.c: *** Our preferred formats from the incoming channel are 0x4 (ulaw) [2010-09-04 23:33:46.162] DEBUG[10246] chan_sip.c: This channel will not be able to handle video. [2010-09-04 23:33:46.162] DEBUG[10246] channel.c: Not copying variable GOSUB_RETVAL. [2010-09-04 23:33:46.162] DEBUG[10246] channel.c: Not copying variable QUEUE_STATS. [2010-09-04 23:33:46.162] DEBUG[10246] channel.c: Not copying variable QUEUESRVLEVELPERF. [2010-09-04 23:33:46.162] DEBUG[10246] channel.c: Not copying variable QUEUESRVLEVEL. [2010-09-04 23:33:46.162] DEBUG[10246] channel.c: Not copying variable QUEUEABANDONED. [2010-09-04 23:33:46.162] DEBUG[10246] channel.c: Not copying variable QUEUECOMPLETED. [2010-09-04 23:33:46.162] DEBUG[10246] channel.c: Not copying variable QUEUETALKTIME. [2010-09-04 23:33:46.162] DEBUG[10246] channel.c: Not copying variable QUEUEHOLDTIME. [2010-09-04 23:33:46.162] DEBUG[10246] channel.c: Not copying variable QUEUECALLS. [2010-09-04 23:33:46.162] DEBUG[10246] channel.c: Not copying variable QUEUESTRATEGY. [2010-09-04 23:33:46.162] DEBUG[10246] channel.c: Not copying variable QUEUEMAX. [2010-09-04 23:33:46.162] DEBUG[10246] channel.c: Not copying variable AUTO_MONITOR. [2010-09-04 23:33:46.162] DEBUG[10246] channel.c: Not copying variable MON_FILE. [2010-09-04 23:33:46.162] DEBUG[10246] channel.c: Copying hard-transferable variable SIPADDHEADER03. [2010-09-04 23:33:46.162] DEBUG[10246] channel.c: Copying hard-transferable variable DYNAMIC_FEATURES. [2010-09-04 23:33:46.162] DEBUG[10246] channel.c: Copying hard-transferable variable SIPADDHEADER02. [2010-09-04 23:33:46.162] DEBUG[10246] channel.c: Copying hard-transferable variable SIPADDHEADER01. [2010-09-04 23:33:46.162] DEBUG[10246] channel.c: Not copying variable QUETIME. [2010-09-04 23:33:46.162] DEBUG[10246] channel.c: Copying hard-transferable variable TOP_CHAN. [2010-09-04 23:33:46.162] DEBUG[10246] channel.c: Copying hard-transferable variable TOP_UID. [2010-09-04 23:33:46.162] DEBUG[10246] channel.c: Copying hard-transferable variable CUSTAPP. [2010-09-04 23:33:46.162] DEBUG[10246] channel.c: Not copying variable ~~EXTEN~~. [2010-09-04 23:33:46.162] DEBUG[10246] channel.c: Not copying variable SIPCALLID. [2010-09-04 23:33:46.162] DEBUG[10246] channel.c: Not copying variable SIPDOMAIN. [2010-09-04 23:33:46.162] DEBUG[10246] channel.c: Not copying variable SIPURI. [2010-09-04 23:33:46.162] DEBUG[10246] chan_sip.c: Outgoing Call for dyn-AcmeInc-7228 [2010-09-04 23:33:46.162] DEBUG[10246] chan_sip.c: Updating call counter for outgoing call [2010-09-04 23:33:46.162] DEBUG[10246] chan_sip.c: Call to peer 'dyn-AcmeInc-7228' is 1 out of 2147483647 [2010-09-04 23:33:46.162] DEBUG[25771] devicestate.c: No provider found, checking channel drivers for SIP - dyn-AcmeInc-7228 [2010-09-04 23:33:46.162] DEBUG[25771] chan_sip.c: Checking device state for peer dyn-AcmeInc-7228 [2010-09-04 23:33:46.162] DEBUG[25771] devicestate.c: Changing state for SIP/dyn-AcmeInc-7228 - state 6 (Ringing) [2010-09-04 23:33:46.162] DEBUG[25771] devicestate.c: device 'SIP/dyn-AcmeInc-7228' state '6' [2010-09-04 23:33:46.162] DEBUG[10246] chan_sip.c: Adding SIP Header "X-Astid-Parent" with content :04-1283668425.71328: [2010-09-04 23:33:46.162] DEBUG[10246] chan_sip.c: Adding SIP Header "X-Account-Code" with content :AcmeInc: [2010-09-04 23:33:46.162] DEBUG[10246] chan_sip.c: Adding SIP Header "X-Via-DID" with content :572: [2010-09-04 23:33:46.162] DEBUG[10246] chan_sip.c: ** Our capability: 0x4 (ulaw) Video flag: False Text flag: False [2010-09-04 23:33:46.162] DEBUG[10246] chan_sip.c: ** Our prefcodec: 0x4 (ulaw) [2010-09-04 23:33:46.162] DEBUG[10246] chan_sip.c: -- Done with adding codecs to SDP [2010-09-04 23:33:46.162] DEBUG[10246] chan_sip.c: Done building SDP. Settling with this capability: 0x4 (ulaw) [2010-09-04 23:33:46.162] DEBUG[10246] chan_sip.c: Initializing initreq for method INVITE - callid 40689e8d6a3f5aa82684972e0f68f70a@10.20.0.104 [2010-09-04 23:33:46.162] DEBUG[10246] chan_sip.c: Header 0 [ 58]: INVITE sip:dyn-AcmeInc-7228@10.20.0.107:62819 SIP/2.0 [2010-09-04 23:33:46.162] DEBUG[10246] chan_sip.c: Header 1 [ 62]: Via: SIP/2.0/UDP 10.20.0.104:5060;branch=z9hG4bK172e471f;rport [2010-09-04 23:33:46.162] DEBUG[10246] chan_sip.c: Header 2 [ 16]: Max-Forwards: 70 [2010-09-04 23:33:46.162] DEBUG[10246] chan_sip.c: Header 3 [ 48]: From: "550" ;tag=as5972c89c [2010-09-04 23:33:46.162] DEBUG[10246] chan_sip.c: Header 4 [ 49]: To: [2010-09-04 23:33:46.162] DEBUG[10246] chan_sip.c: Header 5 [ 30]: Contact: [2010-09-04 23:33:46.162] DEBUG[10246] chan_sip.c: Header 6 [ 53]: Call-ID: 40689e8d6a3f5aa82684972e0f68f70a@10.20.0.104 [2010-09-04 23:33:46.162] DEBUG[10246] chan_sip.c: Header 7 [ 16]: CSeq: 102 INVITE [2010-09-04 23:33:46.162] DEBUG[10246] chan_sip.c: Header 8 [ 28]: User-Agent: AigoPBX-04/1.6.1 [2010-09-04 23:33:46.162] DEBUG[10246] chan_sip.c: Header 9 [ 35]: Date: Sun, 05 Sep 2010 06:33:46 GMT [2010-09-04 23:33:46.162] DEBUG[10246] chan_sip.c: Header 10 [ 72]: Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO [2010-09-04 23:33:46.162] DEBUG[10246] chan_sip.c: Header 11 [ 26]: Supported: replaces, timer [2010-09-04 23:33:46.162] DEBUG[10246] chan_sip.c: Header 12 [ 35]: X-Astid-Parent: 04-1283668425.71328 [2010-09-04 23:33:46.162] DEBUG[10246] chan_sip.c: Header 13 [ 28]: X-Account-Code: AcmeInc [2010-09-04 23:33:46.162] DEBUG[10246] chan_sip.c: Header 14 [ 14]: X-Via-DID: 572 [2010-09-04 23:33:46.162] DEBUG[10246] chan_sip.c: Header 15 [ 29]: Content-Type: application/sdp [2010-09-04 23:33:46.162] DEBUG[10246] chan_sip.c: Header 16 [ 19]: Content-Length: 269 [2010-09-04 23:33:46.162] DEBUG[10246] chan_sip.c: Header 17 [ 0]: [2010-09-04 23:33:46.162] DEBUG[10246] chan_sip.c: Body 0 [ 3]: v=0 [2010-09-04 23:33:46.162] DEBUG[10246] chan_sip.c: Body 1 [ 45]: o=root 379937172 379937172 IN IP4 10.20.0.104 [2010-09-04 23:33:46.162] DEBUG[10246] chan_sip.c: Body 2 [ 32]: s=Asterisk PBX local/1.6.2/09@47 [2010-09-04 23:33:46.162] DEBUG[10246] chan_sip.c: Body 3 [ 20]: c=IN IP4 10.20.0.104 [2010-09-04 23:33:46.162] DEBUG[10246] chan_sip.c: Body 4 [ 5]: t=0 0 [2010-09-04 23:33:46.162] DEBUG[10246] chan_sip.c: Body 5 [ 27]: m=audio 16952 RTP/AVP 0 101 [2010-09-04 23:33:46.162] DEBUG[10246] chan_sip.c: Body 6 [ 20]: a=rtpmap:0 PCMU/8000 [2010-09-04 23:33:46.162] DEBUG[10246] chan_sip.c: Body 7 [ 33]: a=rtpmap:101 telephone-event/8000 [2010-09-04 23:33:46.162] DEBUG[10246] chan_sip.c: Body 8 [ 15]: a=fmtp:101 0-16 [2010-09-04 23:33:46.162] DEBUG[10246] chan_sip.c: Body 9 [ 25]: a=silenceSupp:off - - - - [2010-09-04 23:33:46.162] DEBUG[25782] app_queue.c: Device 'SIP/dyn-AcmeInc-7228' changed to state '6' (Ringing) [2010-09-04 23:33:46.162] DEBUG[10246] chan_sip.c: Body 10 [ 10]: a=ptime:20 [2010-09-04 23:33:46.162] DEBUG[10246] chan_sip.c: Body 11 [ 10]: a=sendrecv [2010-09-04 23:33:46.162] DEBUG[10246] chan_sip.c: *** SIP TIMER: Initializing retransmit timer on packet: Id #59346903 [2010-09-04 23:33:46.162] DEBUG[10246] chan_sip.c: Trying to put 'INVITE sip:' onto UDP socket destined for 10.20.0.107:62819 [2010-09-04 23:33:46.162] DEBUG[10246] channel.c: Generator got voice, switching to phase locked mode [2010-09-04 23:33:46.162] DEBUG[10246] channel.c: Scheduling timer at (0 requested / 0 actual) timer ticks per second [2010-09-04 23:33:46.163] DEBUG[25781] chan_sip.c: Header 0 [ 18]: SIP/2.0 100 Trying [2010-09-04 23:33:46.163] DEBUG[25781] chan_sip.c: Header 1 [ 88]: Via: SIP/2.0/UDP 10.20.0.104:5060;rport=5060;received=10.20.0.104;branch=z9hG4bK172e471f [2010-09-04 23:33:46.163] DEBUG[25781] chan_sip.c: Header 2 [ 53]: Call-ID: 40689e8d6a3f5aa82684972e0f68f70a@10.20.0.104 [2010-09-04 23:33:46.163] DEBUG[25781] chan_sip.c: Header 3 [ 48]: From: "550" ;tag=as5972c89c [2010-09-04 23:33:46.163] DEBUG[25781] chan_sip.c: Header 4 [ 43]: To: [2010-09-04 23:33:46.163] DEBUG[25781] chan_sip.c: Header 5 [ 16]: CSeq: 102 INVITE [2010-09-04 23:33:46.163] DEBUG[25781] chan_sip.c: Header 6 [ 18]: Content-Length: 0 [2010-09-04 23:33:46.163] DEBUG[25781] chan_sip.c: Header 7 [ 0]: [2010-09-04 23:33:46.163] DEBUG[10246] channel.c: Set channel SIP/AcmeInc-0001169f to write format slin [2010-09-04 23:33:46.163] DEBUG[25781] chan_sip.c: *** SIP TIMER: Cancelling retransmission #59346903 - INVITE (got response) [2010-09-04 23:33:46.163] DEBUG[25781] chan_sip.c: (Provisional) Stopping retransmission (but retaining packet) on '40689e8d6a3f5aa82684972e0f68f70a@10.20.0.104' Request 102: Found [2010-09-04 23:33:46.163] DEBUG[25781] chan_sip.c: SIP response 100 to standard invite [2010-09-04 23:33:46.163] DEBUG[25781] chan_sip.c: Header 0 [ 14]: SIP/2.0 200 OK [2010-09-04 23:33:46.163] DEBUG[25781] chan_sip.c: Header 1 [ 88]: Via: SIP/2.0/UDP 10.20.0.104:5060;rport=5060;received=10.20.0.104;branch=z9hG4bK172e471f [2010-09-04 23:33:46.163] DEBUG[25781] chan_sip.c: Header 2 [ 53]: Call-ID: 40689e8d6a3f5aa82684972e0f68f70a@10.20.0.104 [2010-09-04 23:33:46.163] DEBUG[25781] chan_sip.c: Header 3 [ 48]: From: "550" ;tag=as5972c89c [2010-09-04 23:33:46.163] DEBUG[25781] chan_sip.c: Header 4 [ 80]: To: ;tag=4efa05fa0bcf48269bfb65e0b2cad5c6 [2010-09-04 23:33:46.163] DEBUG[25781] chan_sip.c: Header 5 [ 16]: CSeq: 102 INVITE [2010-09-04 23:33:46.163] DEBUG[25781] chan_sip.c: Header 6 [ 54]: Contact: [2010-09-04 23:33:46.163] DEBUG[25781] chan_sip.c: Header 7 [ 90]: Allow: PRACK, INVITE, ACK, BYE, CANCEL, UPDATE, SUBSCRIBE, NOTIFY, REFER, MESSAGE, OPTIONS [2010-09-04 23:33:46.163] DEBUG[25781] chan_sip.c: Header 8 [ 39]: Supported: replaces, 100rel, norefersub [2010-09-04 23:33:46.163] DEBUG[25781] chan_sip.c: Header 9 [ 29]: Content-Type: application/sdp [2010-09-04 23:33:46.163] DEBUG[25781] chan_sip.c: Header 10 [ 21]: Content-Length: 250 [2010-09-04 23:33:46.163] DEBUG[25781] chan_sip.c: Header 11 [ 0]: [2010-09-04 23:33:46.163] DEBUG[25781] chan_sip.c: Body 0 [ 3]: v=0 [2010-09-04 23:33:46.163] DEBUG[25781] chan_sip.c: Body 1 [ 44]: o=- 3492632026 3492632027 IN IP4 10.20.0.107 [2010-09-04 23:33:46.163] DEBUG[25781] chan_sip.c: Body 2 [ 9]: s=pjmedia [2010-09-04 23:33:46.163] DEBUG[25781] chan_sip.c: Body 3 [ 20]: c=IN IP4 10.20.0.107 [2010-09-04 23:33:46.163] DEBUG[25781] chan_sip.c: Body 4 [ 5]: t=0 0 [2010-09-04 23:33:46.163] DEBUG[25781] chan_sip.c: Body 5 [ 9]: a=X-nat:0 [2010-09-04 23:33:46.163] DEBUG[25781] chan_sip.c: Body 6 [ 27]: m=audio 51407 RTP/AVP 0 101 [2010-09-04 23:33:46.163] DEBUG[25781] chan_sip.c: Body 7 [ 31]: a=rtcp:51408 IN IP4 10.20.0.107 [2010-09-04 23:33:46.163] DEBUG[25781] chan_sip.c: Body 8 [ 20]: a=rtpmap:0 PCMU/8000 [2010-09-04 23:33:46.163] DEBUG[25781] chan_sip.c: Body 9 [ 10]: a=sendrecv [2010-09-04 23:33:46.163] DEBUG[25781] chan_sip.c: Body 10 [ 33]: a=rtpmap:101 telephone-event/8000 [2010-09-04 23:33:46.163] DEBUG[25781] chan_sip.c: Body 11 [ 15]: a=fmtp:101 0-15 [2010-09-04 23:33:46.163] DEBUG[25781] chan_sip.c: Acked pending invite 102 [2010-09-04 23:33:46.163] DEBUG[25781] chan_sip.c: Stopping retransmission on '40689e8d6a3f5aa82684972e0f68f70a@10.20.0.104' of Request 102: Match Found [2010-09-04 23:33:46.163] DEBUG[25781] chan_sip.c: SIP response 200 to standard invite [2010-09-04 23:33:46.163] DEBUG[10246] res_musiconhold.c: SIP/AcmeInc-0001169f Opened file 0 '/var/lib/asterisk/sounds/en/local/moh/default/fpm-world-mix' [2010-09-04 23:33:46.163] DEBUG[10246] rtp.c: Ooh, format changed from unknown to ulaw [2010-09-04 23:33:46.163] DEBUG[25781] chan_sip.c: Processing session-level SDP v=0... UNSUPPORTED. [2010-09-04 23:33:46.163] DEBUG[25781] chan_sip.c: Processing session-level SDP o=- 3492632026 3492632027 IN IP4 10.20.0.107... UNSUPPORTED. [2010-09-04 23:33:46.163] DEBUG[25781] chan_sip.c: Processing session-level SDP s=pjmedia... UNSUPPORTED. [2010-09-04 23:33:46.163] DEBUG[10246] rtp.c: Created smoother: format: 4 ms: 20 len: 160 [2010-09-04 23:33:46.163] DEBUG[25781] chan_sip.c: Processing session-level SDP c=IN IP4 10.20.0.107... OK. [2010-09-04 23:33:46.163] DEBUG[25781] chan_sip.c: Processing session-level SDP t=0 0... UNSUPPORTED. [2010-09-04 23:33:46.163] DEBUG[25781] chan_sip.c: Processing session-level SDP a=X-nat:0... UNSUPPORTED. [2010-09-04 23:33:46.163] DEBUG[25781] chan_sip.c: Processing media-level (audio) SDP a=rtcp:51408 IN IP4 10.20.0.107... UNSUPPORTED. [2010-09-04 23:33:46.163] DEBUG[25781] chan_sip.c: Processing media-level (audio) SDP a=rtpmap:0 PCMU/8000... OK. [2010-09-04 23:33:46.163] DEBUG[25781] chan_sip.c: Processing media-level (audio) SDP a=sendrecv... OK. [2010-09-04 23:33:46.163] DEBUG[25781] chan_sip.c: Processing media-level (audio) SDP a=rtpmap:101 telephone-event/8000... OK. [2010-09-04 23:33:46.163] DEBUG[25781] chan_sip.c: Processing media-level (audio) SDP a=fmtp:101 0-15... UNSUPPORTED. [2010-09-04 23:33:46.163] DEBUG[25781] chan_sip.c: We're settling with these formats: 0x4 (ulaw) [2010-09-04 23:33:46.163] DEBUG[25781] chan_sip.c: We have an owner, now see if we need to change this call [2010-09-04 23:33:46.163] DEBUG[25781] chan_sip.c: Updating call counter for outgoing call [2010-09-04 23:33:46.163] DEBUG[25781] chan_sip.c: build_route: Contact hop: [2010-09-04 23:33:46.163] DEBUG[25771] devicestate.c: No provider found, checking channel drivers for SIP - dyn-AcmeInc-7228 [2010-09-04 23:33:46.163] DEBUG[25771] chan_sip.c: Checking device state for peer dyn-AcmeInc-7228 [2010-09-04 23:33:46.163] DEBUG[25771] devicestate.c: Changing state for SIP/dyn-AcmeInc-7228 - state 2 (In use) [2010-09-04 23:33:46.163] DEBUG[25771] devicestate.c: device 'SIP/dyn-AcmeInc-7228' state '2' [2010-09-04 23:33:46.163] DEBUG[25781] chan_sip.c: Strict routing enforced for session 40689e8d6a3f5aa82684972e0f68f70a@10.20.0.104 [2010-09-04 23:33:46.163] DEBUG[25781] chan_sip.c: Trying to put 'ACK sip:dyn' onto UDP socket destined for 10.20.0.107:62819 [2010-09-04 23:33:46.163] VERBOSE[10246] app_queue.c: -- SIP/dyn-AcmeInc-7228-000116a0 answered SIP/AcmeInc-0001169f [2010-09-04 23:33:46.163] DEBUG[10246] app_queue.c: Next is 'SIP/dyn-AcmeInc-7229' with metric 1 [2010-09-04 23:33:46.163] VERBOSE[10246] res_musiconhold.c: -- Stopped music on hold on SIP/AcmeInc-0001169f [2010-09-04 23:33:46.163] DEBUG[10246] channel.c: Set channel SIP/AcmeInc-0001169f to write format ulaw [2010-09-04 23:33:46.163] DEBUG[10246] channel.c: Scheduling timer at (0 requested / 0 actual) timer ticks per second [2010-09-04 23:33:46.163] DEBUG[25771] devicestate.c: No provider found, checking channel drivers for SIP - dyn-AcmeInc-7228 [2010-09-04 23:33:46.163] DEBUG[25771] chan_sip.c: Checking device state for peer dyn-AcmeInc-7228 [2010-09-04 23:33:46.163] DEBUG[25771] devicestate.c: Changing state for SIP/dyn-AcmeInc-7228 - state 2 (In use) [2010-09-04 23:33:46.163] DEBUG[25771] devicestate.c: device 'SIP/dyn-AcmeInc-7228' state '2' [2010-09-04 23:33:46.163] DEBUG[25782] app_queue.c: Device 'SIP/dyn-AcmeInc-7228' changed to state '2' (In use) [2010-09-04 23:33:46.164] DEBUG[10246] app_queue.c: Queue 'AcmeInc' Leave, Channel 'SIP/AcmeInc-0001169f' [2010-09-04 23:33:46.164] DEBUG[10246] app_queue.c: app_queue: gosub=on-queue-answer. [2010-09-04 23:33:46.164] DEBUG[25782] app_queue.c: Device 'SIP/dyn-AcmeInc-7228' changed to state '2' (In use) [2010-09-04 23:33:46.164] DEBUG[10246] app_stack.c: Channel SIP/dyn-AcmeInc-7228-000116a0 has no datastore, so we're allocating one. [2010-09-04 23:33:46.164] DEBUG[10246] pbx.c: Function result is '0' [2010-09-04 23:33:46.164] DEBUG[10246] pbx.c: Function result is '0' [2010-09-04 23:33:46.164] DEBUG[10246] pbx.c: Expression result is '0' [2010-09-04 23:33:46.164] DEBUG[10246] pbx.c: Launching 'Gosub' [2010-09-04 23:33:46.164] VERBOSE[10246] pbx.c: -- Executing [s@on-queue-answer:1] Gosub("SIP/dyn-AcmeInc-7228-000116a0", "trace,s,1(Answering in 0s on SIP/dyn-AcmeInc-7228-000116a0)") in new stack [2010-09-04 23:33:46.164] DEBUG[10246] app_stack.c: Setting 'ARG1' to 'Answering in 0s on SIP/dyn-AcmeInc-7228-000116a0' [2010-09-04 23:33:46.164] DEBUG[10246] pbx.c: Launching 'MSet' [2010-09-04 23:33:46.164] VERBOSE[10246] pbx.c: -- Executing [s@trace:1] MSet("SIP/dyn-AcmeInc-7228-000116a0", "LOCAL(msg)=Answering in 0s on SIP/dyn-AcmeInc-7228-000116a0") in new stack [2010-09-04 23:33:46.164] DEBUG[10246] pbx.c: Function result is '100904-233346' [2010-09-04 23:33:46.164] DEBUG[10246] pbx.c: Expression result is '1' [2010-09-04 23:33:46.164] DEBUG[10246] pbx.c: Function result is '04-1283668425.71328' [2010-09-04 23:33:46.164] DEBUG[10246] pbx.c: Launching 'Verbose' [2010-09-04 23:33:46.164] VERBOSE[10246] pbx.c: -- Executing [s@trace:2] Verbose("SIP/dyn-AcmeInc-7228-000116a0", "1,* 100904-233346 04-1283668425.71328 AcmeInc Answering in 0s on SIP/dyn-AcmeInc-7228-000116a0") in new stack [2010-09-04 23:33:46.164] VERBOSE[10246] app_verbose.c: * 100904-233346 04-1283668425.71328 AcmeInc Answering in 0s on SIP/dyn-AcmeInc-7228-000116a0 [2010-09-04 23:33:46.164] DEBUG[10246] pbx.c: Launching 'Return' [2010-09-04 23:33:46.164] VERBOSE[10246] pbx.c: -- Executing [s@trace:3] Return("SIP/dyn-AcmeInc-7228-000116a0", "") in new stack [2010-09-04 23:33:46.164] DEBUG[10246] pbx.c: Launching 'Return' [2010-09-04 23:33:46.164] VERBOSE[10246] pbx.c: -- Executing [s@on-queue-answer:2] Return("SIP/dyn-AcmeInc-7228-000116a0", "") in new stack [2010-09-04 23:33:46.164] DEBUG[10246] pbx.c: Launching 'NoOp' [2010-09-04 23:33:46.164] VERBOSE[10246] pbx.c: -- Executing [s@app_queue_gosub_virtual_context:1] NoOp("SIP/dyn-AcmeInc-7228-000116a0", "") in new stack [2010-09-04 23:33:46.164] VERBOSE[10246] pbx.c: -- Auto fallthrough, channel 'SIP/dyn-AcmeInc-7228-000116a0' status is 'UNKNOWN' [2010-09-04 23:33:46.164] DEBUG[10246] app_queue.c: Gosub exited with status 0 [2010-09-04 23:33:46.166] DEBUG[10246] features.c: bridge answer set, chan answer set [2010-09-04 23:33:46.166] DEBUG[10246] rtp.c: Setting the marker bit due to a source update [2010-09-04 23:33:46.166] DEBUG[10246] rtp.c: Setting the marker bit due to a source update [2010-09-04 23:33:46.166] DEBUG[10246] rtp.c: Got RTCP report of 32 bytes [2010-09-04 23:33:46.181] DEBUG[10246] rtp.c: Ooh, format changed from unknown to ulaw [2010-09-04 23:33:46.181] DEBUG[10246] rtp.c: Created smoother: format: 4 ms: 20 len: 160 #### #### Here goes the INVITE with Replaces: #### [2010-09-04 23:33:47.232] VERBOSE[25781] chan_sip.c: <--- SIP read from UDP:99.99.99.99:5060 ---> INVITE sip:572@88.88.88.88 SIP/2.0 Via: SIP/2.0/UDP 99.99.99.99:5060;branch=z9hG4bKfc19a64fdd9a56204b70ca614599fa4f Via: SIP/2.0/UDP 99.99.99.99:5060;branch=z9hG4bKfc19a64fdd9a56204b70ca614599fa4f;received=99.99.99.99 Max-Forwards: 70 Record-Route: To: 572 From: CN3107769011 ;tag=102c4c82d831a03a0 Call-ID: 8000000c14c82d831a057f@99.99.99.99 CSeq: 2 INVITE Contact: CN3107769011 Content-Type: application/sdp Content-Length: 253 Supported: replaces Replaces: 8000000c14c82d83058261@99.99.99.99;from-tag=c384c82d83058073;to-tag=as3432aedc v=0 o=CN3107769011 1283643441 1283643441 IN IP4 99.99.99.99 s=- c=IN IP4 99.99.99.99 t=0 0 m=audio 16480 RTP/AVP 0 101 102 a=rtpmap:0 PCMU/8000 a=ptime:20 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-15 a=rtpmap:102 tone/8000 a=sendrecv <-------------> [2010-09-04 23:33:47.232] DEBUG[25781] chan_sip.c: Header 0 [ 36]: INVITE sip:572@88.88.88.88 SIP/2.0 [2010-09-04 23:33:47.232] DEBUG[25781] chan_sip.c: Header 1 [ 81]: Via: SIP/2.0/UDP 99.99.99.99:5060;branch=z9hG4bKfc19a64fdd9a56204b70ca614599fa4f [2010-09-04 23:33:47.232] DEBUG[25781] chan_sip.c: Header 2 [103]: Via: SIP/2.0/UDP 99.99.99.99:5060;branch=z9hG4bKfc19a64fdd9a56204b70ca614599fa4f;received=99.99.99.99 [2010-09-04 23:33:47.232] DEBUG[25781] chan_sip.c: Header 3 [ 16]: Max-Forwards: 70 [2010-09-04 23:33:47.232] DEBUG[25781] chan_sip.c: Header 4 [ 32]: Record-Route: [2010-09-04 23:33:47.232] DEBUG[25781] chan_sip.c: Header 5 [ 30]: To: 572 [2010-09-04 23:33:47.232] DEBUG[25781] chan_sip.c: Header 6 [ 83]: From: CN3107769011 ;tag=102c4c82d831a03a0 [2010-09-04 23:33:47.232] DEBUG[25781] chan_sip.c: Header 7 [ 44]: Call-ID: 8000000c14c82d831a057f@99.99.99.99 [2010-09-04 23:33:47.232] DEBUG[25781] chan_sip.c: Header 8 [ 14]: CSeq: 2 INVITE [2010-09-04 23:33:47.232] DEBUG[25781] chan_sip.c: Header 9 [ 64]: Contact: CN3107769011 [2010-09-04 23:33:47.232] DEBUG[25781] chan_sip.c: Header 10 [ 29]: Content-Type: application/sdp [2010-09-04 23:33:47.232] DEBUG[25781] chan_sip.c: Header 11 [ 19]: Content-Length: 253 [2010-09-04 23:33:47.232] DEBUG[25781] chan_sip.c: Header 12 [ 19]: Supported: replaces [2010-09-04 23:33:47.232] DEBUG[25781] chan_sip.c: Header 13 [ 89]: Replaces: 8000000c14c82d83058261@99.99.99.99;from-tag=c384c82d83058073;to-tag=as3432aedc [2010-09-04 23:33:47.232] DEBUG[25781] chan_sip.c: Header 14 [ 0]: [2010-09-04 23:33:47.232] DEBUG[25781] chan_sip.c: Body 0 [ 3]: v=0 [2010-09-04 23:33:47.232] DEBUG[25781] chan_sip.c: Body 1 [ 56]: o=CN3107769011 1283643441 1283643441 IN IP4 99.99.99.99 [2010-09-04 23:33:47.232] DEBUG[25781] chan_sip.c: Body 2 [ 3]: s=- [2010-09-04 23:33:47.232] DEBUG[25781] chan_sip.c: Body 3 [ 21]: c=IN IP4 99.99.99.99 [2010-09-04 23:33:47.232] DEBUG[25781] chan_sip.c: Body 4 [ 5]: t=0 0 [2010-09-04 23:33:47.232] DEBUG[25781] chan_sip.c: Body 5 [ 31]: m=audio 16480 RTP/AVP 0 101 102 [2010-09-04 23:33:47.232] DEBUG[25781] chan_sip.c: Body 6 [ 20]: a=rtpmap:0 PCMU/8000 [2010-09-04 23:33:47.232] DEBUG[25781] chan_sip.c: Body 7 [ 10]: a=ptime:20 [2010-09-04 23:33:47.232] DEBUG[25781] chan_sip.c: Body 8 [ 33]: a=rtpmap:101 telephone-event/8000 [2010-09-04 23:33:47.232] DEBUG[25781] chan_sip.c: Body 9 [ 15]: a=fmtp:101 0-15 [2010-09-04 23:33:47.232] DEBUG[25781] chan_sip.c: Body 10 [ 22]: a=rtpmap:102 tone/8000 [2010-09-04 23:33:47.232] DEBUG[25781] chan_sip.c: Body 11 [ 10]: a=sendrecv [2010-09-04 23:33:47.232] VERBOSE[25781] chan_sip.c: --- (14 headers 12 lines) --- [2010-09-04 23:33:47.232] DEBUG[25781] acl.c: Found IP address for this socket [2010-09-04 23:33:47.232] DEBUG[25781] chan_sip.c: Target address 99.99.99.99 is not local, substituting externip [2010-09-04 23:33:47.232] DEBUG[25781] chan_sip.c: Setting SIP_TRANSPORT_UDP with address 88.88.88.88:5060 [2010-09-04 23:33:47.232] VERBOSE[25781] netsock.c: == Using SIP RTP CoS mark 5 [2010-09-04 23:33:47.232] DEBUG[25781] chan_sip.c: Setting NAT on RTP to Off [2010-09-04 23:33:47.232] DEBUG[25781] chan_sip.c: Allocating new SIP dialog for 8000000c14c82d831a057f@99.99.99.99 - INVITE (With RTP) [2010-09-04 23:33:47.232] DEBUG[25781] chan_sip.c: **** Received INVITE (5) - Command in SIP INVITE [2010-09-04 23:33:47.232] DEBUG[25781] chan_sip.c: Begin: parsing SIP "Supported: replaces" [2010-09-04 23:33:47.232] DEBUG[25781] chan_sip.c: Found SIP option: -replaces- [2010-09-04 23:33:47.232] DEBUG[25781] chan_sip.c: Matched SIP option: replaces [2010-09-04 23:33:47.232] DEBUG[25781] chan_sip.c: INVITE part of call transfer. Replaces [8000000c14c82d83058261@99.99.99.99;from-tag=c384c82d83058073;to-tag=as3432aedc] [2010-09-04 23:33:47.232] DEBUG[25781] chan_sip.c: Invite/replaces: Will use Replace-Call-ID : 8000000c14c82d83058261@99.99.99.99 Fromtag: c384c82d83058073 Totag: as3432aedc [2010-09-04 23:33:47.232] DEBUG[25781] chan_sip.c: Looking for callid 8000000c14c82d83058261@99.99.99.99 (fromtag c384c82d83058073 totag as3432aedc) [2010-09-04 23:33:47.232] DEBUG[25781] chan_sip.c: Matched INCOMING call - their tag is c384c82d83058073 Our tag is as3432aedc [2010-09-04 23:33:47.232] VERBOSE[25781] chan_sip.c: Sending to 99.99.99.99 : 5060 (no NAT) [2010-09-04 23:33:47.232] DEBUG[25781] chan_sip.c: Initializing initreq for method INVITE - callid 8000000c14c82d831a057f@99.99.99.99 [2010-09-04 23:33:47.232] VERBOSE[25781] chan_sip.c: Using INVITE request as basis request - 8000000c14c82d831a057f@99.99.99.99 [2010-09-04 23:33:47.232] VERBOSE[25781] chan_sip.c: Found peer 'AcmeInc' for 'CN3107769011' from 99.99.99.99:5060 [2010-09-04 23:33:47.232] DEBUG[25781] chan_sip.c: Setting NAT on RTP to Off [2010-09-04 23:33:47.232] DEBUG[25781] chan_sip.c: Processing session-level SDP v=0... UNSUPPORTED. [2010-09-04 23:33:47.232] DEBUG[25781] chan_sip.c: Processing session-level SDP o=CN3107769011 1283643441 1283643441 IN IP4 99.99.99.99... UNSUPPORTED. [2010-09-04 23:33:47.232] DEBUG[25781] chan_sip.c: Processing session-level SDP s=-... UNSUPPORTED. [2010-09-04 23:33:47.232] DEBUG[25781] chan_sip.c: Processing session-level SDP c=IN IP4 99.99.99.99... OK. [2010-09-04 23:33:47.232] DEBUG[25781] chan_sip.c: Processing session-level SDP t=0 0... UNSUPPORTED. [2010-09-04 23:33:47.232] VERBOSE[25781] chan_sip.c: Found RTP audio format 0 [2010-09-04 23:33:47.232] VERBOSE[25781] chan_sip.c: Found RTP audio format 101 [2010-09-04 23:33:47.232] VERBOSE[25781] chan_sip.c: Found RTP audio format 102 [2010-09-04 23:33:47.232] VERBOSE[25781] chan_sip.c: Found audio description format PCMU for ID 0 [2010-09-04 23:33:47.232] DEBUG[25781] chan_sip.c: Processing media-level (audio) SDP a=rtpmap:0 PCMU/8000... OK. [2010-09-04 23:33:47.232] DEBUG[25781] chan_sip.c: Processing media-level (audio) SDP a=ptime:20... OK. [2010-09-04 23:33:47.232] VERBOSE[25781] chan_sip.c: Found audio description format telephone-event for ID 101 [2010-09-04 23:33:47.232] DEBUG[25781] chan_sip.c: Processing media-level (audio) SDP a=rtpmap:101 telephone-event/8000... OK. [2010-09-04 23:33:47.232] DEBUG[25781] chan_sip.c: Processing media-level (audio) SDP a=fmtp:101 0-15... UNSUPPORTED. [2010-09-04 23:33:47.232] VERBOSE[25781] chan_sip.c: Found audio description format tone for ID 102 [2010-09-04 23:33:47.232] DEBUG[25781] chan_sip.c: Processing media-level (audio) SDP a=rtpmap:102 tone/8000... OK. [2010-09-04 23:33:47.232] DEBUG[25781] chan_sip.c: Processing media-level (audio) SDP a=sendrecv... OK. [2010-09-04 23:33:47.232] VERBOSE[25781] chan_sip.c: Capabilities: us - 0x4 (ulaw), peer - audio=0x2004 (ulaw|siren7)/video=0x0 (nothing)/text=0x0 (nothing), combined - 0x4 (ulaw) [2010-09-04 23:33:47.232] VERBOSE[25781] chan_sip.c: Non-codec capabilities (dtmf): us - 0x1 (telephone-event), peer - 0x1 (telephone-event), combined - 0x1 (telephone-event) [2010-09-04 23:33:47.232] VERBOSE[25781] chan_sip.c: Peer audio RTP is at port 99.99.99.99:16480 [2010-09-04 23:33:47.232] DEBUG[25781] chan_sip.c: We're settling with these formats: 0x4 (ulaw) [2010-09-04 23:33:47.232] DEBUG[25781] chan_sip.c: Checking SIP call limits for device [2010-09-04 23:33:47.232] DEBUG[25781] chan_sip.c: Updating call counter for incoming call [2010-09-04 23:33:47.232] DEBUG[25781] chan_sip.c: Call from peer 'AcmeInc' is 2 out of 2147483647 [2010-09-04 23:33:47.232] VERBOSE[25781] chan_sip.c: Looking for 572 in from-AcmeInc (domain 88.88.88.88) [2010-09-04 23:33:47.232] DEBUG[25771] devicestate.c: No provider found, checking channel drivers for SIP - AcmeInc [2010-09-04 23:33:47.232] DEBUG[25771] chan_sip.c: Checking device state for peer AcmeInc [2010-09-04 23:33:47.232] DEBUG[25771] devicestate.c: Changing state for SIP/AcmeInc - state 2 (In use) [2010-09-04 23:33:47.232] DEBUG[25771] devicestate.c: device 'SIP/AcmeInc' state '2' [2010-09-04 23:33:47.232] DEBUG[25781] chan_sip.c: *** Our native formats are 0x4 (ulaw) [2010-09-04 23:33:47.232] DEBUG[25781] chan_sip.c: *** Joint capabilities are 0x4 (ulaw) [2010-09-04 23:33:47.232] DEBUG[25781] chan_sip.c: *** Our capabilities are 0x4 (ulaw) [2010-09-04 23:33:47.232] DEBUG[25781] chan_sip.c: *** AST_CODEC_CHOOSE formats are 0x4 (ulaw) [2010-09-04 23:33:47.232] DEBUG[25781] chan_sip.c: This channel will not be able to handle video. [2010-09-04 23:33:47.232] DEBUG[25781] chan_sip.c: build_route: Record-Route hop: [2010-09-04 23:33:47.232] DEBUG[25781] chan_sip.c: build_route: Contact hop: CN3107769011 [2010-09-04 23:33:47.232] VERBOSE[25781] chan_sip.c: list_route: hop: [2010-09-04 23:33:47.232] VERBOSE[25781] chan_sip.c: list_route: hop: [2010-09-04 23:33:47.232] DEBUG[25781] chan_sip.c: Sending this call to the invite/replcaes handler 8000000c14c82d831a057f@99.99.99.99 [2010-09-04 23:33:47.232] DEBUG[25781] chan_sip.c: SIP transfer: Invite Replace incoming channel should bridge to channel SIP/dyn-AcmeInc-7228-000116a0 while hanging up channel SIP/AcmeInc-0001169f [2010-09-04 23:33:47.232] DEBUG[25782] app_queue.c: Device 'SIP/AcmeInc' changed to state '2' (In use) but we don't care because they're not a member of any queue. [2010-09-04 23:33:47.232] VERBOSE[25781] chan_sip.c: <--- Transmitting (no NAT) to 99.99.99.99:5060 ---> SIP/2.0 100 Trying Via: SIP/2.0/UDP 99.99.99.99:5060;branch=z9hG4bKfc19a64fdd9a56204b70ca614599fa4f;received=99.99.99.99 Via: SIP/2.0/UDP 99.99.99.99:5060;branch=z9hG4bKfc19a64fdd9a56204b70ca614599fa4f;received=99.99.99.99 Record-Route: From: CN3107769011 ;tag=102c4c82d831a03a0 To: 572 Call-ID: 8000000c14c82d831a057f@99.99.99.99 CSeq: 2 INVITE Server: AigoPBX-04/1.6.1 Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO Supported: replaces, timer Contact: Content-Length: 0 <------------> [2010-09-04 23:33:47.232] DEBUG[25781] chan_sip.c: Trying to put 'SIP/2.0 100' onto UDP socket destined for 99.99.99.99:5060 [2010-09-04 23:33:47.232] DEBUG[25771] devicestate.c: No provider found, checking channel drivers for SIP - AcmeInc [2010-09-04 23:33:47.232] DEBUG[25771] chan_sip.c: Checking device state for peer AcmeInc [2010-09-04 23:33:47.232] DEBUG[25771] devicestate.c: Changing state for SIP/AcmeInc - state 2 (In use) [2010-09-04 23:33:47.232] DEBUG[25771] devicestate.c: device 'SIP/AcmeInc' state '2' [2010-09-04 23:33:47.232] DEBUG[25781] chan_sip.c: Setting framing from config on incoming call [2010-09-04 23:33:47.232] DEBUG[25781] chan_sip.c: ** Our capability: 0x4 (ulaw) Video flag: True Text flag: True [2010-09-04 23:33:47.232] DEBUG[25781] chan_sip.c: ** Our prefcodec: 0x0 (nothing) [2010-09-04 23:33:47.232] VERBOSE[25781] chan_sip.c: Audio is at 88.88.88.88 port 19360 [2010-09-04 23:33:47.232] VERBOSE[25781] chan_sip.c: Adding codec 0x4 (ulaw) to SDP [2010-09-04 23:33:47.232] VERBOSE[25781] chan_sip.c: Adding non-codec 0x1 (telephone-event) to SDP [2010-09-04 23:33:47.232] DEBUG[25781] chan_sip.c: -- Done with adding codecs to SDP [2010-09-04 23:33:47.232] DEBUG[25781] chan_sip.c: Done building SDP. Settling with this capability: 0x4 (ulaw) [2010-09-04 23:33:47.232] VERBOSE[25781] chan_sip.c: <--- Reliably Transmitting (no NAT) to 99.99.99.99:5060 ---> SIP/2.0 200 OK Via: SIP/2.0/UDP 99.99.99.99:5060;branch=z9hG4bKfc19a64fdd9a56204b70ca614599fa4f;received=99.99.99.99 Via: SIP/2.0/UDP 99.99.99.99:5060;branch=z9hG4bKfc19a64fdd9a56204b70ca614599fa4f;received=99.99.99.99 Record-Route: From: CN3107769011 ;tag=102c4c82d831a03a0 To: 572 ;tag=as492c05c1 Call-ID: 8000000c14c82d831a057f@99.99.99.99 CSeq: 2 INVITE Server: AigoPBX-04/1.6.1 Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO Supported: replaces, timer Contact: Content-Type: application/sdp Content-Length: 275 v=0 o=root 1723711911 1723711911 IN IP4 88.88.88.88 s=Asterisk PBX local/1.6.2/09@47 c=IN IP4 88.88.88.88 t=0 0 m=audio 19360 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 <------------> [2010-09-04 23:33:47.232] DEBUG[25781] chan_sip.c: *** SIP TIMER: Initializing retransmit timer on packet: Id #59346935 [2010-09-04 23:33:47.233] DEBUG[25781] chan_sip.c: Trying to put 'SIP/2.0 200' onto UDP socket destined for 99.99.99.99:5060 [2010-09-04 23:33:47.233] DEBUG[25782] app_queue.c: Device 'SIP/AcmeInc' changed to state '2' (In use) but we don't care because they're not a member of any queue. [2010-09-04 23:33:47.233] DEBUG[25771] devicestate.c: No provider found, checking channel drivers for SIP - AcmeInc [2010-09-04 23:33:47.233] DEBUG[25781] chan_sip.c: Invite/Replaces: preparing to masquerade SIP/AcmeInc-000116a1 into SIP/AcmeInc-0001169f [2010-09-04 23:33:47.233] DEBUG[25771] chan_sip.c: Checking device state for peer AcmeInc [2010-09-04 23:33:47.233] DEBUG[25781] channel.c: Planning to masquerade channel SIP/AcmeInc-000116a1 into the structure of SIP/AcmeInc-0001169f [2010-09-04 23:33:47.233] DEBUG[25771] devicestate.c: Changing state for SIP/AcmeInc - state 2 (In use) [2010-09-04 23:33:47.233] DEBUG[25771] devicestate.c: device 'SIP/AcmeInc' state '2' [2010-09-04 23:33:47.233] DEBUG[25781] channel.c: Done planning to masquerade channel SIP/AcmeInc-000116a1 into the structure of SIP/AcmeInc-0001169f [2010-09-04 23:33:47.233] DEBUG[25781] chan_sip.c: Invite/Replaces: Going to masquerade SIP/AcmeInc-000116a1 into SIP/AcmeInc-0001169f [2010-09-04 23:33:47.233] DEBUG[25781] channel.c: Actually Masquerading SIP/AcmeInc-000116a1(6) into the structure of SIP/AcmeInc-0001169f(6) [2010-09-04 23:33:47.233] DEBUG[25781] channel.c: Got clone lock for masquerade on 'SIP/AcmeInc-000116a1' at 0x17cf2c0 [2010-09-04 23:33:47.233] DEBUG[25781] chan_sip.c: SIP Fixup: New owner for dialogue 8000000c14c82d83058261@99.99.99.99: SIP/AcmeInc-000116a1 (Old parent: SIP/AcmeInc-000116a1) [2010-09-04 23:33:47.233] DEBUG[25781] chan_sip.c: update_call_counter() - decrement call limit counter on hangup [2010-09-04 23:33:47.233] DEBUG[25781] chan_sip.c: Updating call counter for incoming call [2010-09-04 23:33:47.233] DEBUG[25782] app_queue.c: Device 'SIP/AcmeInc' changed to state '2' (In use) but we don't care because they're not a member of any queue. [2010-09-04 23:33:47.233] DEBUG[25781] chan_sip.c: Call from peer 'AcmeInc' removed from call limit 2147483647 [2010-09-04 23:33:47.233] DEBUG[25781] chan_sip.c: SIP Transfer: Not hanging up right now... Rescheduling hangup for 8000000c14c82d83058261@99.99.99.99. [2010-09-04 23:33:47.233] VERBOSE[25781] chan_sip.c: Scheduling destruction of SIP dialog '8000000c14c82d83058261@99.99.99.99' in 32000 ms (Method: ACK) [2010-09-04 23:33:47.233] DEBUG[25771] devicestate.c: No provider found, checking channel drivers for SIP - AcmeInc [2010-09-04 23:33:47.233] DEBUG[25771] chan_sip.c: Checking device state for peer AcmeInc [2010-09-04 23:33:47.233] DEBUG[25771] devicestate.c: Changing state for SIP/AcmeInc - state 2 (In use) [2010-09-04 23:33:47.233] DEBUG[25771] devicestate.c: device 'SIP/AcmeInc' state '2' [2010-09-04 23:33:47.233] DEBUG[25781] channel.c: Putting channel SIP/AcmeInc-000116a1 in 4/4 formats [2010-09-04 23:33:47.233] DEBUG[25781] chan_sip.c: SIP Fixup: New owner for dialogue 8000000c14c82d831a057f@99.99.99.99: SIP/AcmeInc-000116a1 (Old parent: SIP/AcmeInc-0001169f) [2010-09-04 23:33:47.233] DEBUG[25781] channel.c: Released clone lock on 'SIP/AcmeInc-0001169f' [2010-09-04 23:33:47.233] DEBUG[25781] channel.c: Done Masquerading SIP/AcmeInc-000116a1 (6) [2010-09-04 23:33:47.233] DEBUG[25781] chan_sip.c: After transfer:---------------------------- [2010-09-04 23:33:47.233] DEBUG[25771] devicestate.c: No provider found, checking channel drivers for SIP - AcmeInc [2010-09-04 23:33:47.233] DEBUG[25781] chan_sip.c: -- C: SIP/AcmeInc-0001169f State Down [2010-09-04 23:33:47.233] DEBUG[25771] chan_sip.c: Checking device state for peer AcmeInc [2010-09-04 23:33:47.233] DEBUG[25781] chan_sip.c: -- replacecall: SIP/AcmeInc-000116a1 State Up [2010-09-04 23:33:47.233] DEBUG[25771] devicestate.c: Changing state for SIP/AcmeInc - state 2 (In use) [2010-09-04 23:33:47.233] DEBUG[25781] chan_sip.c: -- P->owner: SIP/AcmeInc-000116a1 State Up [2010-09-04 23:33:47.233] DEBUG[25771] devicestate.c: device 'SIP/AcmeInc' state '2' [2010-09-04 23:33:47.233] DEBUG[25781] chan_sip.c: -- Call bridged to P->owner: SIP/dyn-AcmeInc-7228-000116a0 State Up [2010-09-04 23:33:47.233] DEBUG[25781] chan_sip.c: End After transfer:---------------------------- [2010-09-04 23:33:47.233] DEBUG[25781] channel.c: Hanging up zombie 'SIP/AcmeInc-0001169f' [2010-09-04 23:33:47.233] DEBUG[25782] app_queue.c: Device 'SIP/AcmeInc' changed to state '2' (In use) but we don't care because they're not a member of any queue. [2010-09-04 23:33:47.233] DEBUG[25782] app_queue.c: Device 'SIP/AcmeInc' changed to state '2' (In use) but we don't care because they're not a member of any queue. [2010-09-04 23:33:47.238] DEBUG[10246] rtp.c: Ooh, format changed from unknown to ulaw [2010-09-04 23:33:47.238] DEBUG[10246] rtp.c: Created smoother: format: 4 ms: 20 len: 160 [2010-09-04 23:33:47.251] DEBUG[25781] res_odbc.c: odbc_release_obj2(0x7f1a34015018) called (obj->txf = (nil)) #### Yuck: Monitor ended!!! [2010-09-04 23:33:47.279] DEBUG[25781] res_monitor.c: monitor executing /usr/local/bin/soxmerge "/var/spool/asterisk/monitor/20100904-233345-04-1283668425.71328-AcmeInc-in.wav" "/var/spool/asterisk/monitor/20100904-233345-04-1283668425.71328-AcmeInc-out.wav" "/var/spool/asterisk/monitor/20100904-233345-04-1283668425.71328-AcmeInc.wav" /var/spool/asterisk/callrecord & [2010-09-04 23:33:47.292] DEBUG[25771] devicestate.c: No provider found, checking channel drivers for SIP - AcmeInc [2010-09-04 23:33:47.292] DEBUG[25771] chan_sip.c: Checking device state for peer AcmeInc [2010-09-04 23:33:47.292] DEBUG[25771] devicestate.c: Changing state for SIP/AcmeInc - state 2 (In use) [2010-09-04 23:33:47.292] DEBUG[25771] devicestate.c: device 'SIP/AcmeInc' state '2' [2010-09-04 23:33:47.292] VERBOSE[25781] chan_sip.c: <--- SIP read from UDP:99.99.99.99:5060 ---> ACK sip:572@88.88.88.88 SIP/2.0 Via: SIP/2.0/UDP 99.99.99.99:5060;branch=z9hG4bK5dfb93bbb9efb8ba6304503c5c1d3581 Via: SIP/2.0/UDP 99.99.99.99:5060;branch=z9hG4bK5dfb93bbb9efb8ba6304503c5c1d3581;received=99.99.99.99 Max-Forwards: 70 Record-Route: From: CN3107769011 ;tag=102c4c82d831a03a0 To: 572 ;tag=as492c05c1 Call-ID: 8000000c14c82d831a057f@99.99.99.99 CSeq: 2 ACK Content-Length: 0 <-------------> #### Snipped a few lines here [2010-09-04 23:33:47.292] VERBOSE[25781] chan_sip.c: <--- SIP read from UDP:99.99.99.99:5060 ---> BYE sip:572@88.88.88.88 SIP/2.0 Via: SIP/2.0/UDP 99.99.99.99:5060;branch=z9hG4bK4a6ab2418f557cd024832ff8978d390e Via: SIP/2.0/UDP 99.99.99.99:5060;branch=z9hG4bK4a6ab2418f557cd024832ff8978d390e;received=99.99.99.99 Max-Forwards: 70 Record-Route: To: 572 ;tag=as3432aedc From: 550 ;tag=c384c82d83058073 Call-ID: 8000000c14c82d83058261@99.99.99.99 CSeq: 19 BYE Content-Length: 0 <------------->