[Jan 31 10:14:01] VERBOSE[17358] chan_sip.c: <--- SIP read from UDP:10.10.10.125:5060 ---> INVITE sip:+12148888500@10.10.10.125:5061 SIP/2.0 Record-Route: Record-Route: Via: SIP/2.0/UDP 10.10.10.125:5060;branch=z9hG4bK8d2d.84e844e4.0 Via: SIP/2.0/UDP 10.10.10.106;branch=z9hG4bK8d2d.7ddbfcf45173e64029d01350fe46a4ca.0 Via: SIP/2.0/UDP 192.168.2.48:5065;rport=5065;received=10.11.11.250;branch=z9hG4bK-32f8f9e6 To: From: ;tag=dd17eb17dabf1f1eo5 Call-ID: ed9a614b-b09fe7a@192.168.2.48 CSeq: 102 INVITE Max-Forwards: 10 Contact: Expires: 240 Referred-By: Replaces:207af371-6a71d8ba-5c260fdb@192.168.2.55;to-tag=as05de1b60;from-tag=D8AD073-6DE3EC User-Agent: Cisco/SPA509G-7.4.9c Content-Length: 213 Allow: ACK, BYE, CANCEL, INFO, INVITE, NOTIFY, OPTIONS, REFER, SUBSCRIBE, UPDATE Allow-Events: dialog Content-Type: application/sdp X-CX-AProxy: 10.10.10.106 Refer-CT-Type: ACT v=0 o=- 8271050 8271050 IN IP4 10.10.10.92 s=- c=IN IP4 10.10.10.92 t=0 0 m=audio 10986 RTP/AVP 18 101 a=rtpmap:18 G729a/8000 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-15 a=ptime:30 a=sendrecv <-------------> [Jan 31 10:14:01] DEBUG[17358] chan_sip.c: Header 0 [ 51]: INVITE sip:+12148888500@10.10.10.125:5061 SIP/2.0 [Jan 31 10:14:01] DEBUG[17358] chan_sip.c: Header 1 [ 61]: Record-Route: [Jan 31 10:14:01] DEBUG[17358] chan_sip.c: Header 2 [ 37]: Record-Route: [Jan 31 10:14:01] DEBUG[17358] chan_sip.c: Header 3 [ 66]: Via: SIP/2.0/UDP 10.10.10.125:5060;branch=z9hG4bK8d2d.84e844e4.0 [Jan 31 10:14:01] DEBUG[17358] chan_sip.c: Header 4 [ 85]: Via: SIP/2.0/UDP 10.10.10.106;branch=z9hG4bK8d2d.7ddbfcf45173e64029d01350fe46a4ca.0 [Jan 31 10:14:01] DEBUG[17358] chan_sip.c: Header 5 [ 92]: Via: SIP/2.0/UDP 192.168.2.48:5065;rport=5065;received=10.11.11.250;branch=z9hG4bK-32f8f9e6 [Jan 31 10:14:01] DEBUG[17358] chan_sip.c: Header 6 [ 41]: To: [Jan 31 10:14:01] DEBUG[17358] chan_sip.c: Header 7 [ 70]: From: ;tag=dd17eb17dabf1f1eo5 [Jan 31 10:14:01] DEBUG[17358] chan_sip.c: Header 8 [ 38]: Call-ID: ed9a614b-b09fe7a@192.168.2.48 [Jan 31 10:14:01] DEBUG[17358] chan_sip.c: Header 9 [ 16]: CSeq: 102 INVITE [Jan 31 10:14:01] DEBUG[17358] chan_sip.c: Header 10 [ 16]: Max-Forwards: 10 [Jan 31 10:14:01] DEBUG[17358] chan_sip.c: Header 11 [ 50]: Contact: [Jan 31 10:14:01] DEBUG[17358] chan_sip.c: Header 12 [ 12]: Expires: 240 [Jan 31 10:14:01] DEBUG[17358] chan_sip.c: Header 13 [ 42]: Referred-By: [Jan 31 10:14:01] DEBUG[17358] chan_sip.c: Header 14 [ 90]: Replaces:207af371-6a71d8ba-5c260fdb@192.168.2.55;to-tag=as05de1b60;from-tag=D8AD073-6DE3EC [Jan 31 10:14:01] DEBUG[17358] chan_sip.c: Header 15 [ 32]: User-Agent: Cisco/SPA509G-7.4.9c [Jan 31 10:14:01] DEBUG[17358] chan_sip.c: Header 16 [ 19]: Content-Length: 213 [Jan 31 10:14:01] DEBUG[17358] chan_sip.c: Header 17 [ 80]: Allow: ACK, BYE, CANCEL, INFO, INVITE, NOTIFY, OPTIONS, REFER, SUBSCRIBE, UPDATE [Jan 31 10:14:01] DEBUG[17358] chan_sip.c: Header 18 [ 20]: Allow-Events: dialog [Jan 31 10:14:01] DEBUG[17358] chan_sip.c: Header 19 [ 29]: Content-Type: application/sdp [Jan 31 10:14:01] DEBUG[17358] chan_sip.c: Header 20 [ 27]: X-CX-AProxy: 10.10.10.106 [Jan 31 10:14:01] DEBUG[17358] chan_sip.c: Header 21 [ 18]: Refer-CT-Type: ACT [Jan 31 10:14:01] DEBUG[17358] chan_sip.c: Header 22 [ 0]: [Jan 31 10:14:01] DEBUG[17358] chan_sip.c: Body 0 [ 3]: v=0 [Jan 31 10:14:01] DEBUG[17358] chan_sip.c: Body 1 [ 40]: o=- 8271050 8271050 IN IP4 10.10.10.92 [Jan 31 10:14:01] DEBUG[17358] chan_sip.c: Body 2 [ 3]: s=- [Jan 31 10:14:01] DEBUG[17358] chan_sip.c: Body 3 [ 22]: c=IN IP4 10.10.10.92 [Jan 31 10:14:01] DEBUG[17358] chan_sip.c: Body 4 [ 5]: t=0 0 [Jan 31 10:14:01] DEBUG[17358] chan_sip.c: Body 5 [ 28]: m=audio 10986 RTP/AVP 18 101 [Jan 31 10:14:01] DEBUG[17358] chan_sip.c: Body 6 [ 22]: a=rtpmap:18 G729a/8000 [Jan 31 10:14:01] DEBUG[17358] chan_sip.c: Body 7 [ 33]: a=rtpmap:101 telephone-event/8000 [Jan 31 10:14:01] DEBUG[17358] chan_sip.c: Body 8 [ 15]: a=fmtp:101 0-15 [Jan 31 10:14:01] DEBUG[17358] chan_sip.c: Body 9 [ 10]: a=ptime:30 [Jan 31 10:14:01] DEBUG[17358] chan_sip.c: Body 10 [ 10]: a=sendrecv [Jan 31 10:14:01] VERBOSE[17358] chan_sip.c: --- (22 headers 11 lines) --- [Jan 31 10:14:01] DEBUG[17358] chan_sip.c: = Looking for Call ID: ed9a614b-b09fe7a@192.168.2.48 (Checking From) --From tag dd17eb17dabf1f1eo5 --To-tag [Jan 31 10:14:01] DEBUG[17358] acl.c: For destination '10.10.10.125', our source address is '10.10.10.125'. [Jan 31 10:14:01] DEBUG[17358] chan_sip.c: Target address 10.10.10.125:5060 is not local, substituting externaddr [Jan 31 10:14:01] DEBUG[17358] chan_sip.c: Setting SIP_TRANSPORT_UDP with address 10.10.10.125:5061 [Jan 31 10:14:01] DEBUG[17358] chan_sip.c: Allocating new SIP dialog for ed9a614b-b09fe7a@192.168.2.48 - INVITE (No RTP) [Jan 31 10:14:01] DEBUG[17358] chan_sip.c: **** Received INVITE (5) - Command in SIP INVITE [Jan 31 10:14:01] DEBUG[17358] chan_sip.c: INVITE part of call transfer. Replaces [207af371-6a71d8ba-5c260fdb@192.168.2.55;to-tag=as05de1b60;from-tag=D8AD073-6DE3EC] [Jan 31 10:14:01] DEBUG[17358] chan_sip.c: Invite/replaces: Will use Replace-Call-ID : 207af371-6a71d8ba-5c260fdb@192.168.2.55 Fromtag: D8AD073-6DE3EC Totag: as05de1b60 [Jan 31 10:14:01] DEBUG[17358] chan_sip.c: Looking for callid 207af371-6a71d8ba-5c260fdb@192.168.2.55 (fromtag D8AD073-6DE3EC totag as05de1b60) [Jan 31 10:14:01] DEBUG[17358] chan_sip.c: Matched INCOMING call - their tag is D8AD073-6DE3EC Our tag is as05de1b60 [Jan 31 10:14:01] DEBUG[17358] netsock2.c: Splitting '10.10.10.125:5060' into... [Jan 31 10:14:01] DEBUG[17358] netsock2.c: ...host '10.10.10.125' and port '5060'. [Jan 31 10:14:01] VERBOSE[17358] chan_sip.c: Sending to 10.10.10.125:5060 (NAT) [Jan 31 10:14:01] DEBUG[17358] chan_sip.c: Initializing initreq for method INVITE - callid ed9a614b-b09fe7a@192.168.2.48 [Jan 31 10:14:01] VERBOSE[17358] chan_sip.c: Using INVITE request as basis request - ed9a614b-b09fe7a@192.168.2.48 [Jan 31 10:14:01] DEBUG[17358] netsock2.c: Splitting 'sip.domain' into... [Jan 31 10:14:01] DEBUG[17358] netsock2.c: ...host 'sip.domain' and port ''. [Jan 31 10:14:01] VERBOSE[17358] chan_sip.c: No matching peer for 'AbB' from '10.10.10.125:5060' [Jan 31 10:14:01] DEBUG[17358] rtp_engine.c: Using engine 'asterisk' for RTP instance '0xb3cb6f18' [Jan 31 10:14:01] DEBUG[17358] res_rtp_asterisk.c: Allocated port 15750 for RTP instance '0xb3cb6f18' [Jan 31 10:14:01] DEBUG[17358] rtp_engine.c: RTP instance '0xb3cb6f18' is setup and ready to go [Jan 31 10:14:01] DEBUG[17358] res_rtp_asterisk.c: Setup RTCP on RTP instance '0xb3cb6f18' [Jan 31 10:14:01] VERBOSE[17358] netsock2.c: == Using SIP RTP CoS mark 5 [Jan 31 10:14:01] DEBUG[17358] chan_sip.c: Setting NAT on RTP to On [Jan 31 10:14:01] DEBUG[17358] chan_sip.c: Processing session-level SDP v=0... UNSUPPORTED. [Jan 31 10:14:01] DEBUG[17358] chan_sip.c: Processing session-level SDP o=- 8271050 8271050 IN IP4 10.10.10.92... UNSUPPORTED. [Jan 31 10:14:01] DEBUG[17358] chan_sip.c: Processing session-level SDP s=-... UNSUPPORTED. [Jan 31 10:14:01] DEBUG[17358] netsock2.c: Splitting '10.10.10.92' into... [Jan 31 10:14:01] DEBUG[17358] netsock2.c: ...host '10.10.10.92' and port ''. [Jan 31 10:14:01] DEBUG[17358] chan_sip.c: Processing session-level SDP c=IN IP4 10.10.10.92... OK. [Jan 31 10:14:01] DEBUG[17358] chan_sip.c: Processing session-level SDP t=0 0... UNSUPPORTED. [Jan 31 10:14:01] VERBOSE[17358] chan_sip.c: Found RTP audio format 18 [Jan 31 10:14:01] DEBUG[17358] rtp_engine.c: Setting payload 18 based on m type on 0xb432ae58 [Jan 31 10:14:01] VERBOSE[17358] chan_sip.c: Found RTP audio format 101 [Jan 31 10:14:01] DEBUG[17358] rtp_engine.c: Setting payload 101 based on m type on 0xb432ae58 [Jan 31 10:14:01] VERBOSE[17358] chan_sip.c: Found audio description format G729a for ID 18 [Jan 31 10:14:01] DEBUG[17358] chan_sip.c: Processing media-level (audio) SDP a=rtpmap:18 G729a/8000... OK. [Jan 31 10:14:01] VERBOSE[17358] chan_sip.c: Found audio description format telephone-event for ID 101 [Jan 31 10:14:01] DEBUG[17358] chan_sip.c: Processing media-level (audio) SDP a=rtpmap:101 telephone-event/8000... OK. [Jan 31 10:14:01] DEBUG[17358] chan_sip.c: Processing media-level (audio) SDP a=fmtp:101 0-15... UNSUPPORTED. [Jan 31 10:14:01] DEBUG[17358] chan_sip.c: Processing media-level (audio) SDP a=ptime:30... OK. [Jan 31 10:14:01] DEBUG[17358] chan_sip.c: Processing media-level (audio) SDP a=sendrecv... OK. [Jan 31 10:14:01] DEBUG[17358] rtp_engine.c: Incorporating payload 18 on 0xb432ae58 [Jan 31 10:14:01] DEBUG[17358] rtp_engine.c: Incorporating payload 101 on 0xb432ae58 [Jan 31 10:14:01] VERBOSE[17358] chan_sip.c: Capabilities: us - 0x91e (gsm|ulaw|alaw|g726|g729|g726aal2), peer - audio=0x100 (g729)/video=0x0 (nothing)/text=0x0 (nothing), combined - 0x100 (g729) [Jan 31 10:14:01] VERBOSE[17358] chan_sip.c: Non-codec capabilities (dtmf): us - 0x1 (telephone-event|), peer - 0x1 (telephone-event|), combined - 0x1 (telephone-event|) [Jan 31 10:14:01] DEBUG[17358] res_rtp_asterisk.c: Setting RTCP address on RTP instance '0xb3cb6f18' [Jan 31 10:14:01] VERBOSE[17358] chan_sip.c: Peer audio RTP is at port 10.10.10.92:10986 [Jan 31 10:14:01] DEBUG[17358] rtp_engine.c: Copying payload 18 from 0xb432ae58 to 0xb3cb70c4 [Jan 31 10:14:01] DEBUG[17358] rtp_engine.c: Copying payload 101 from 0xb432ae58 to 0xb3cb70c4 [Jan 31 10:14:01] DEBUG[17358] res_rtp_asterisk.c: Ignoring duplicate RTCP property on RTP instance '0xb3cb6f18' [Jan 31 10:14:01] DEBUG[17358] chan_sip.c: We're settling with these formats: 0x100 (g729) [Jan 31 10:14:01] DEBUG[17358] chan_sip.c: Checking SIP call limits for device [Jan 31 10:14:01] DEBUG[17358] chan_sip.c: Updating call counter for incoming call [Jan 31 10:14:01] DEBUG[17358] netsock2.c: Splitting '10.10.10.125:5061' into... [Jan 31 10:14:01] DEBUG[17358] netsock2.c: ...host '10.10.10.125' and port ''. [Jan 31 10:14:01] DEBUG[17358] netsock2.c: Splitting 'sip.domain' into... [Jan 31 10:14:01] DEBUG[17358] netsock2.c: ...host 'sip.domain' and port ''. [Jan 31 10:14:01] VERBOSE[17358] chan_sip.c: Looking for +12148888500 in default (domain 10.10.10.125) [Jan 31 10:14:01] DEBUG[17358] chan_sip.c: *** Our native formats are 0x100 (g729) [Jan 31 10:14:01] DEBUG[17358] chan_sip.c: *** Joint capabilities are 0x100 (g729) [Jan 31 10:14:01] DEBUG[17358] chan_sip.c: *** Our capabilities are 0x91e (gsm|ulaw|alaw|g726|g729|g726aal2) [Jan 31 10:14:01] DEBUG[17358] chan_sip.c: *** AST_CODEC_CHOOSE formats are 0x100 (g729) [Jan 31 10:14:01] DEBUG[17358] chan_sip.c: This channel will not be able to handle video. [Jan 31 10:14:01] DEBUG[17358] chan_sip.c: build_route: Record-Route hop: [Jan 31 10:14:01] DEBUG[17358] chan_sip.c: build_route: Record-Route hop: [Jan 31 10:14:01] VERBOSE[17358] chan_sip.c: list_route: hop: [Jan 31 10:14:01] VERBOSE[17358] chan_sip.c: list_route: hop: [Jan 31 10:14:01] DEBUG[17358] chan_sip.c: Sending this call to the invite/replcaes handler ed9a614b-b09fe7a@192.168.2.48 [Jan 31 10:14:01] DEBUG[17358] chan_sip.c: SIP transfer: Invite Replace incoming channel should bridge to channel SIP/ext_2-000045e1 while hanging up channel SIP/int_2-000045e0 [Jan 31 10:14:01] VERBOSE[17358] chan_sip.c: <--- Transmitting (NAT) to 10.10.10.125:5060 ---> SIP/2.0 100 Trying Via: SIP/2.0/UDP 10.10.10.125:5060;branch=z9hG4bK8d2d.84e844e4.0;received=10.10.10.125;rport=5060 Via: SIP/2.0/UDP 10.10.10.106;branch=z9hG4bK8d2d.7ddbfcf45173e64029d01350fe46a4ca.0 Via: SIP/2.0/UDP 192.168.2.48:5065;rport=5065;received=10.11.11.250;branch=z9hG4bK-32f8f9e6 Record-Route: Record-Route: From: ;tag=dd17eb17dabf1f1eo5 To: Call-ID: ed9a614b-b09fe7a@192.168.2.48 CSeq: 102 INVITE Server: Carier-eX: gx01 Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO, PUBLISH Supported: replaces, timer Contact: Content-Length: 0 <------------> [Jan 31 10:14:01] DEBUG[17358] chan_sip.c: Trying to put 'SIP/2.0 100' onto UDP socket destined for 10.10.10.125:5060 [Jan 31 10:14:01] DEBUG[17351] devicestate.c: No provider found, checking channel drivers for SIP - sip.domain [Jan 31 10:14:01] DEBUG[17358] chan_sip.c: Setting framing from config on incoming call [Jan 31 10:14:01] DEBUG[17351] chan_sip.c: Checking device state for peer sip.domain [Jan 31 10:14:01] DEBUG[17358] chan_sip.c: ** Our capability: 0x100 (g729) Video flag: True Text flag: True [Jan 31 10:14:01] DEBUG[17358] chan_sip.c: ** Our prefcodec: 0x0 (nothing) [Jan 31 10:14:01] VERBOSE[17358] chan_sip.c: Audio is at 15750 [Jan 31 10:14:01] VERBOSE[17358] chan_sip.c: Adding codec 0x100 (g729) to SDP [Jan 31 10:14:01] VERBOSE[17358] chan_sip.c: Adding non-codec 0x1 (telephone-event) to SDP [Jan 31 10:14:01] DEBUG[17358] chan_sip.c: -- Done with adding codecs to SDP [Jan 31 10:14:01] DEBUG[17358] chan_sip.c: Done building SDP. Settling with this capability: 0x100 (g729) [Jan 31 10:14:01] VERBOSE[17358] chan_sip.c: <--- Reliably Transmitting (NAT) to 10.10.10.125:5060 ---> SIP/2.0 200 OK Via: SIP/2.0/UDP 10.10.10.125:5060;branch=z9hG4bK8d2d.84e844e4.0;received=10.10.10.125;rport=5060 Via: SIP/2.0/UDP 10.10.10.106;branch=z9hG4bK8d2d.7ddbfcf45173e64029d01350fe46a4ca.0 Via: SIP/2.0/UDP 192.168.2.48:5065;rport=5065;received=10.11.11.250;branch=z9hG4bK-32f8f9e6 Record-Route: Record-Route: From: ;tag=dd17eb17dabf1f1eo5 To: ;tag=as5ec872c0 Call-ID: ed9a614b-b09fe7a@192.168.2.48 CSeq: 102 INVITE Server: Carier-eX: gx01 Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO, PUBLISH Supported: replaces, timer Contact: Content-Type: application/sdp Content-Length: 277 v=0 o=root 1479236887 1479236887 IN IP4 10.10.10.125 s=Asterisk PBX 1.8.11.1-datera-sbc.3 c=IN IP4 10.10.10.125 t=0 0 m=audio 15750 RTP/AVP 18 101 a=rtpmap:18 G729/8000 a=fmtp:18 annexb=no a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-16 a=ptime:20 a=sendrecv <------------> [Jan 31 10:14:01] DEBUG[17358] chan_sip.c: *** SIP TIMER: Initializing retransmit timer on packet: Id #79974 [Jan 31 10:14:01] DEBUG[17358] chan_sip.c: Trying to put 'SIP/2.0 200' onto UDP socket destined for 10.10.10.125:5060 [Jan 31 10:14:01] DEBUG[17358] chan_sip.c: Invite/Replaces: preparing to masquerade SIP/sip.domain-000045e2 into SIP/int_2-000045e0 [Jan 31 10:14:01] DEBUG[17358] channel.c: Planning to masquerade channel SIP/sip.domain-000045e2 into the structure of SIP/int_2-000045e0 [Jan 31 10:14:01] DEBUG[17358] channel.c: Done planning to masquerade channel SIP/sip.domain-000045e2 into the structure of SIP/int_2-000045e0 [Jan 31 10:14:01] DEBUG[17358] chan_sip.c: Invite/Replaces: Going to masquerade SIP/sip.domain-000045e2 into SIP/int_2-000045e0 [Jan 31 10:14:01] DEBUG[17351] devicestate.c: Changing state for SIP/sip.domain - state 2 (In use) [Jan 31 10:14:01] DEBUG[17351] devicestate.c: device 'SIP/sip.domain' state '2' [Jan 31 10:14:01] DEBUG[17351] devicestate.c: No provider found, checking channel drivers for SIP - sip.domain [Jan 31 10:14:01] DEBUG[17351] chan_sip.c: Checking device state for peer sip.domain [Jan 31 10:14:01] DEBUG[17351] devicestate.c: Changing state for SIP/sip.domain - state 2 (In use) [Jan 31 10:14:01] DEBUG[17351] devicestate.c: device 'SIP/sip.domain' state '2' [Jan 31 10:14:01] DEBUG[17358] channel.c: Actually Masquerading SIP/sip.domain-000045e2(6) into the structure of SIP/int_2-000045e0(6) [Jan 31 10:14:01] DEBUG[17358] chan_sip.c: SIP Fixup: New owner for dialogue 207af371-6a71d8ba-5c260fdb@192.168.2.55: SIP/sip.domain-000045e2 (Old parent: SIP/sip.domain-000045e2) [Jan 31 10:14:01] DEBUG[17358] chan_sip.c: SIP Transfer: Not hanging up right now... Rescheduling hangup for 207af371-6a71d8ba-5c260fdb@192.168.2.55. [Jan 31 10:14:01] DEBUG[17384] app_queue.c: Device 'SIP/sip.domain' changed to state '2' (In use) but we don't care because they're not a member of any queue. [Jan 31 10:14:01] DEBUG[17384] app_queue.c: Device 'SIP/sip.domain' changed to state '2' (In use) but we don't care because they're not a member of any queue. [Jan 31 10:14:01] VERBOSE[17358] chan_sip.c: Scheduling destruction of SIP dialog '207af371-6a71d8ba-5c260fdb@192.168.2.55' in 32000 ms (Method: ACK) [Jan 31 10:14:01] DEBUG[17358] channel.c: Set channel SIP/sip.domain-000045e2 to write format slin [Jan 31 10:14:01] DEBUG[17358] channel.c: Set channel SIP/sip.domain-000045e2 to read format slin [Jan 31 10:14:01] DEBUG[17358] channel.c: Putting channel SIP/sip.domain-000045e2 in slin/slin formats [Jan 31 10:14:01] DEBUG[17358] chan_sip.c: SIP Fixup: New owner for dialogue ed9a614b-b09fe7a@192.168.2.48: SIP/sip.domain-000045e2 (Old parent: SIP/int_2-000045e0) [Jan 31 10:14:01] DEBUG[17358] channel.c: Released clone lock on 'SIP/int_2-000045e0' [Jan 31 10:14:01] DEBUG[17358] channel.c: Done Masquerading SIP/sip.domain-000045e2 (6) [Jan 31 10:14:01] DEBUG[17358] res_rtp_asterisk.c: Changing ssrc from 1988624754 to 811244685 due to a source change [Jan 31 10:14:01] DEBUG[17358] res_rtp_asterisk.c: Not changing SSRC since we haven't sent any RTP yet [Jan 31 10:14:01] DEBUG[17358] channel.c: Hanging up zombie 'SIP/int_2-000045e0' [Jan 31 10:14:01] DEBUG[17351] devicestate.c: No provider found, checking channel drivers for SIP - int_2 [Jan 31 10:14:01] DEBUG[17351] chan_sip.c: Checking device state for peer int_2 [Jan 31 10:14:01] DEBUG[17351] devicestate.c: Changing state for SIP/int_2 - state 1 (Not in use) [Jan 31 10:14:01] DEBUG[17358] pbx.c: Evaluating 'CDR(clid)' (from 'CDR(clid)}","${CDR(src)}","${CDR(dst)}","${CDR(dcontext)}","${CDR(channel)}","${CDR(dstchannel)}","${CDR(lastapp)}","${CDR(lastdata)}","${CDR(start)}","${CDR(answer)}","${CDR(end)}","${CDR(duration)}","${CDR(billsec)}","${CDR(disposition)}","${CDR(amaflags)}","${CDR(accountcode)}","${CDR(uniqueid)}","${CDR(rtpstats2)}" ' len 9) [Jan 31 10:14:01] DEBUG[17351] devicestate.c: device 'SIP/int_2' state '1' [Jan 31 10:14:01] DEBUG[17358] pbx.c: Function result is '"9043230501" <+19043230501>' [Jan 31 10:14:01] DEBUG[17358] pbx.c: Evaluating 'CDR(src)' (from 'CDR(src)}","${CDR(dst)}","${CDR(dcontext)}","${CDR(channel)}","${CDR(dstchannel)}","${CDR(lastapp)}","${CDR(lastdata)}","${CDR(start)}","${CDR(answer)}","${CDR(end)}","${CDR(duration)}","${CDR(billsec)}","${CDR(disposition)}","${CDR(amaflags)}","${CDR(accountcode)}","${CDR(uniqueid)}","${CDR(rtpstats2)}" ' len 8) [Jan 31 10:14:01] DEBUG[17358] pbx.c: Function result is '+19043230501' [Jan 31 10:14:01] DEBUG[17358] pbx.c: Evaluating 'CDR(dst)' (from 'CDR(dst)}","${CDR(dcontext)}","${CDR(channel)}","${CDR(dstchannel)}","${CDR(lastapp)}","${CDR(lastdata)}","${CDR(start)}","${CDR(answer)}","${CDR(end)}","${CDR(duration)}","${CDR(billsec)}","${CDR(disposition)}","${CDR(amaflags)}","${CDR(accountcode)}","${CDR(uniqueid)}","${CDR(rtpstats2)}" ' len 8) [Jan 31 10:14:01] DEBUG[17358] pbx.c: Function result is '+12148888500' [Jan 31 10:14:01] DEBUG[17384] app_queue.c: Device 'SIP/int_2' changed to state '1' (Not in use) but we don't care because they're not a member of any queue. [Jan 31 10:14:01] DEBUG[17358] pbx.c: Evaluating 'CDR(dcontext)' (from 'CDR(dcontext)}","${CDR(channel)}","${CDR(dstchannel)}","${CDR(lastapp)}","${CDR(lastdata)}","${CDR(start)}","${CDR(answer)}","${CDR(end)}","${CDR(duration)}","${CDR(billsec)}","${CDR(disposition)}","${CDR(amaflags)}","${CDR(accountcode)}","${CDR(uniqueid)}","${CDR(rtpstats2)}" ' len 13) [Jan 31 10:14:01] DEBUG[17358] pbx.c: Function result is 'ToPeer' [Jan 31 10:14:01] DEBUG[17358] pbx.c: Evaluating 'CDR(channel)' (from 'CDR(channel)}","${CDR(dstchannel)}","${CDR(lastapp)}","${CDR(lastdata)}","${CDR(start)}","${CDR(answer)}","${CDR(end)}","${CDR(duration)}","${CDR(billsec)}","${CDR(disposition)}","${CDR(amaflags)}","${CDR(accountcode)}","${CDR(uniqueid)}","${CDR(rtpstats2)}" ' len 12) [Jan 31 10:14:01] DEBUG[17358] pbx.c: Function result is 'SIP/int_2-000045e0' [Jan 31 10:14:01] DEBUG[17358] pbx.c: Evaluating 'CDR(dstchannel)' (from 'CDR(dstchannel)}","${CDR(lastapp)}","${CDR(lastdata)}","${CDR(start)}","${CDR(answer)}","${CDR(end)}","${CDR(duration)}","${CDR(billsec)}","${CDR(disposition)}","${CDR(amaflags)}","${CDR(accountcode)}","${CDR(uniqueid)}","${CDR(rtpstats2)}" ' len 15) [Jan 31 10:14:01] DEBUG[17358] pbx.c: Function result is 'SIP/ext_2-000045e1' [Jan 31 10:14:01] DEBUG[17358] pbx.c: Evaluating 'CDR(lastapp)' (from 'CDR(lastapp)}","${CDR(lastdata)}","${CDR(start)}","${CDR(answer)}","${CDR(end)}","${CDR(duration)}","${CDR(billsec)}","${CDR(disposition)}","${CDR(amaflags)}","${CDR(accountcode)}","${CDR(uniqueid)}","${CDR(rtpstats2)}" ' len 12) [Jan 31 10:14:01] DEBUG[17358] pbx.c: Function result is 'Dial' [Jan 31 10:14:01] DEBUG[17358] pbx.c: Evaluating 'CDR(lastdata)' (from 'CDR(lastdata)}","${CDR(start)}","${CDR(answer)}","${CDR(end)}","${CDR(duration)}","${CDR(billsec)}","${CDR(disposition)}","${CDR(amaflags)}","${CDR(accountcode)}","${CDR(uniqueid)}","${CDR(rtpstats2)}" ' len 13) [Jan 31 10:14:01] DEBUG[17358] pbx.c: Function result is 'SIP/0012148888500@ext_2,,L(69499000:30000:10000),' [Jan 31 10:14:01] DEBUG[17358] pbx.c: Evaluating 'CDR(start)' (from 'CDR(start)}","${CDR(answer)}","${CDR(end)}","${CDR(duration)}","${CDR(billsec)}","${CDR(disposition)}","${CDR(amaflags)}","${CDR(accountcode)}","${CDR(uniqueid)}","${CDR(rtpstats2)}" ' len 10) [Jan 31 10:14:01] DEBUG[17358] pbx.c: Function result is '2013-01-31 10:13:55' [Jan 31 10:14:01] DEBUG[17358] pbx.c: Evaluating 'CDR(answer)' (from 'CDR(answer)}","${CDR(end)}","${CDR(duration)}","${CDR(billsec)}","${CDR(disposition)}","${CDR(amaflags)}","${CDR(accountcode)}","${CDR(uniqueid)}","${CDR(rtpstats2)}" ' len 11) [Jan 31 10:14:01] DEBUG[17358] pbx.c: Function result is '2013-01-31 10:13:59' [Jan 31 10:14:01] DEBUG[17358] pbx.c: Evaluating 'CDR(end)' (from 'CDR(end)}","${CDR(duration)}","${CDR(billsec)}","${CDR(disposition)}","${CDR(amaflags)}","${CDR(accountcode)}","${CDR(uniqueid)}","${CDR(rtpstats2)}" ' len 8) [Jan 31 10:14:01] DEBUG[17358] pbx.c: Function result is '2013-01-31 10:14:01' [Jan 31 10:14:01] DEBUG[17358] pbx.c: Evaluating 'CDR(duration)' (from 'CDR(duration)}","${CDR(billsec)}","${CDR(disposition)}","${CDR(amaflags)}","${CDR(accountcode)}","${CDR(uniqueid)}","${CDR(rtpstats2)}" ' len 13) [Jan 31 10:14:01] DEBUG[17358] pbx.c: Function result is '6' [Jan 31 10:14:01] DEBUG[17358] pbx.c: Evaluating 'CDR(billsec)' (from 'CDR(billsec)}","${CDR(disposition)}","${CDR(amaflags)}","${CDR(accountcode)}","${CDR(uniqueid)}","${CDR(rtpstats2)}" ' len 12) [Jan 31 10:14:01] DEBUG[17358] pbx.c: Function result is '2' [Jan 31 10:14:01] DEBUG[17358] pbx.c: Evaluating 'CDR(disposition)' (from 'CDR(disposition)}","${CDR(amaflags)}","${CDR(accountcode)}","${CDR(uniqueid)}","${CDR(rtpstats2)}" ' len 16) [Jan 31 10:14:01] DEBUG[17358] pbx.c: Function result is 'ANSWERED' [Jan 31 10:14:01] DEBUG[17358] pbx.c: Evaluating 'CDR(amaflags)' (from 'CDR(amaflags)}","${CDR(accountcode)}","${CDR(uniqueid)}","${CDR(rtpstats2)}" ' len 13) [Jan 31 10:14:01] DEBUG[17358] pbx.c: Function result is 'DOCUMENTATION' [Jan 31 10:14:01] DEBUG[17358] pbx.c: Evaluating 'CDR(accountcode)' (from 'CDR(accountcode)}","${CDR(uniqueid)}","${CDR(rtpstats2)}" ' len 16) [Jan 31 10:14:01] DEBUG[17358] pbx.c: Function result is '(null)' [Jan 31 10:14:01] DEBUG[17358] pbx.c: Evaluating 'CDR(uniqueid)' (from 'CDR(uniqueid)}","${CDR(rtpstats2)}" ' len 13) [Jan 31 10:14:01] DEBUG[17358] pbx.c: Function result is '1359627235.17898' [Jan 31 10:14:01] DEBUG[17358] pbx.c: Evaluating 'CDR(rtpstats2)' (from 'CDR(rtpstats2)}" ' len 14) [Jan 31 10:14:01] DEBUG[17358] pbx.c: Function result is '(null)' [Jan 31 10:14:01] DEBUG[23893] rtp_engine.c: Channel codec0 = g729 is not codec1 = ulaw, cannot native bridge in RTP. [Jan 31 10:14:01] DEBUG[23893] res_rtp_asterisk.c: Ooh, format changed from unknown to g729 [Jan 31 10:14:01] DEBUG[23893] res_rtp_asterisk.c: Created smoother: format: g729 ms: 20 len: 20 [Jan 31 10:14:01] DEBUG[23893] res_rtp_asterisk.c: Starting RTCP transmission on RTP instance '0xb3cb6f18' [Jan 31 10:14:01] DEBUG[17358] cdr_radius.c: Unable to create RADIUS record. CDR not recorded! [Jan 31 10:14:01] DEBUG[17351] devicestate.c: No provider found, checking channel drivers for SIP - int_2 [Jan 31 10:14:01] DEBUG[17351] chan_sip.c: Checking device state for peer int_2 [Jan 31 10:14:01] DEBUG[17351] devicestate.c: Changing state for SIP/int_2 - state 1 (Not in use) [Jan 31 10:14:01] DEBUG[17351] devicestate.c: device 'SIP/int_2' state '1' [Jan 31 10:14:01] DEBUG[17384] app_queue.c: Device 'SIP/int_2' changed to state '1' (Not in use) but we don't care because they're not a member of any queue. [Jan 31 10:14:01] VERBOSE[17358] chan_sip.c: <--- SIP read from UDP:10.10.10.125:5060 ---> ACK sip:+12148888500@10.10.10.125:5061 SIP/2.0 Via: SIP/2.0/UDP 10.10.10.125:5060;branch=z9hG4bKcydzigwkX Via: SIP/2.0/UDP 10.10.10.106;branch=z9hG4bK8d2d.f3da26c84d47e6d442007a6fc310a556.0 Via: SIP/2.0/UDP 192.168.2.48:5065;rport=5065;received=10.11.11.250;branch=z9hG4bK-f06146c1 To: ;tag=as5ec872c0;tag=as5ec872c0 From: ;tag=dd17eb17dabf1f1eo5 Call-ID: ed9a614b-b09fe7a@192.168.2.48 CSeq: 102 ACK Max-Forwards: 10 Proxy-Authorization: Digest username="AbB",realm="sip.domain",nonce="UQpFFFEKQ+girRZ20Ojr//N9alO66Yk0",uri="sip:Anonymous@10.10.10.106",algorithm=MD5,response="3e817fba2572dd774120ff6c10c16320" Contact: User-Agent: Cisco/SPA509G-7.4.9c Content-Length: 0 Allow-Events: dialog <-------------> [Jan 31 10:14:01] DEBUG[17358] chan_sip.c: Header 0 [ 48]: ACK sip:+12148888500@10.10.10.125:5061 SIP/2.0 [Jan 31 10:14:01] DEBUG[17358] chan_sip.c: Header 1 [ 60]: Via: SIP/2.0/UDP 10.10.10.125:5060;branch=z9hG4bKcydzigwkX [Jan 31 10:14:01] DEBUG[17358] chan_sip.c: Header 2 [ 85]: Via: SIP/2.0/UDP 10.10.10.106;branch=z9hG4bK8d2d.f3da26c84d47e6d442007a6fc310a556.0 [Jan 31 10:14:01] DEBUG[17358] chan_sip.c: Header 3 [ 92]: Via: SIP/2.0/UDP 192.168.2.48:5065;rport=5065;received=10.11.11.250;branch=z9hG4bK-f06146c1 [Jan 31 10:14:01] DEBUG[17358] chan_sip.c: Header 4 [ 71]: To: ;tag=as5ec872c0;tag=as5ec872c0 [Jan 31 10:14:01] DEBUG[17358] chan_sip.c: Header 5 [ 70]: From: ;tag=dd17eb17dabf1f1eo5 [Jan 31 10:14:01] DEBUG[17358] chan_sip.c: Header 6 [ 38]: Call-ID: ed9a614b-b09fe7a@192.168.2.48 [Jan 31 10:14:01] DEBUG[17358] chan_sip.c: Header 7 [ 13]: CSeq: 102 ACK [Jan 31 10:14:01] DEBUG[17358] chan_sip.c: Header 8 [ 16]: Max-Forwards: 10 [Jan 31 10:14:01] DEBUG[17358] chan_sip.c: Header 9 [216]: Proxy-Authorization: Digest username="AbB",realm="sip.domain",nonce="UQpFFFEKQ+girRZ20Ojr//N9alO66Yk0",uri="sip:Anonymous@10.10.10.106",algorithm=MD5,response="3e817fba2572dd774120ff6c10c16320" [Jan 31 10:14:01] DEBUG[17358] chan_sip.c: Header 10 [ 50]: Contact: [Jan 31 10:14:01] DEBUG[17358] chan_sip.c: Header 11 [ 32]: User-Agent: Cisco/SPA509G-7.4.9c [Jan 31 10:14:01] DEBUG[17358] chan_sip.c: Header 12 [ 17]: Content-Length: 0 [Jan 31 10:14:01] DEBUG[17358] chan_sip.c: Header 13 [ 20]: Allow-Events: dialog [Jan 31 10:14:01] VERBOSE[17358] chan_sip.c: --- (14 headers 0 lines) --- [Jan 31 10:14:01] DEBUG[17358] chan_sip.c: = Looking for Call ID: ed9a614b-b09fe7a@192.168.2.48 (Checking From) --From tag dd17eb17dabf1f1eo5 --To-tag as5ec872c0 [Jan 31 10:14:01] DEBUG[17358] chan_sip.c: **** Received ACK (6) - Command in SIP ACK [Jan 31 10:14:01] DEBUG[17358] chan_sip.c: ** SIP TIMER: Cancelling retransmit of packet (reply received) Retransid #79974 [Jan 31 10:14:01] DEBUG[17358] chan_sip.c: Stopping retransmission on 'ed9a614b-b09fe7a@192.168.2.48' of Response 102: Match Found [Jan 31 10:14:04] DEBUG[17358] chan_sip.c: Auto destroying SIP dialog '5a6dced3-bb38db4c-c0acf61d@192.168.2.55' [Jan 31 10:14:08] DEBUG[17358] chan_sip.c: Auto destroying SIP dialog 'ae73644b-1acccb02@192.168.2.48' [Jan 31 10:14:08] DEBUG[17358] chan_sip.c: Destroying SIP dialog ae73644b-1acccb02@192.168.2.48 [Jan 31 10:14:08] VERBOSE[17358] chan_sip.c: Really destroying SIP dialog 'ae73644b-1acccb02@192.168.2.48' Method: BYE [Jan 31 10:14:08] DEBUG[17358] rtp_engine.c: Destroyed RTP instance '0xb62ee370' [Jan 31 10:14:33] DEBUG[17358] chan_sip.c: Auto destroying SIP dialog '207af371-6a71d8ba-5c260fdb@192.168.2.55'