[Jul 16 15:31:00] VERBOSE[24869] chan_sip.c: <--- SIP read from UDP:192.168.77.230:5060 ---> INVITE sip:8775551212@appserver.invalid SIP/2.0 Via: SIP/2.0/UDP 192.168.77.230:5060;branch=z9hG4bK5859d942;rport From: "Victoria BC" ;tag=as717a7b2b To: Contact: Call-ID: 74a69a3b429799ff5369c69b3103f718@192.168.77.230 CSeq: 102 INVITE User-Agent: AVNet Max-Forwards: 70 Remote-Party-ID: "Victoria BC" ;privacy=off;screen=no Date: Fri, 16 Jul 2010 22:34:08 GMT Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO Supported: replaces Content-Type: application/sdp Content-Length: 236 v=0 o=root 22177 22177 IN IP4 192.168.77.230 s=session c=IN IP4 192.168.77.230 t=0 0 m=audio 10566 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 <-------------> [Jul 16 15:31:00] DEBUG[24869] chan_sip.c: Header 0 [ 39]: INVITE sip:8775551212@appserver.invalid SIP/2.0 [Jul 16 15:31:00] DEBUG[24869] chan_sip.c: Header 1 [ 61]: Via: SIP/2.0/UDP 192.168.77.230:5060;branch=z9hG4bK5859d942;rport [Jul 16 15:31:00] DEBUG[24869] chan_sip.c: Header 2 [ 66]: From: "Victoria BC" ;tag=as717a7b2b [Jul 16 15:31:00] DEBUG[24869] chan_sip.c: Header 3 [ 30]: To: [Jul 16 15:31:00] DEBUG[24869] chan_sip.c: Header 4 [ 36]: Contact: [Jul 16 15:31:00] DEBUG[24869] chan_sip.c: Header 5 [ 52]: Call-ID: 74a69a3b429799ff5369c69b3103f718@192.168.77.230 [Jul 16 15:31:00] DEBUG[24869] chan_sip.c: Header 6 [ 16]: CSeq: 102 INVITE [Jul 16 15:31:00] DEBUG[24869] chan_sip.c: Header 7 [ 21]: User-Agent: AVNet [Jul 16 15:31:00] DEBUG[24869] chan_sip.c: Header 8 [ 16]: Max-Forwards: 70 [Jul 16 15:31:00] DEBUG[24869] chan_sip.c: Header 9 [ 84]: Remote-Party-ID: "Victoria BC" ;privacy=off;screen=no [Jul 16 15:31:00] DEBUG[24869] chan_sip.c: Header 10 [ 35]: Date: Fri, 16 Jul 2010 22:34:08 GMT [Jul 16 15:31:00] DEBUG[24869] chan_sip.c: Header 11 [ 72]: Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO [Jul 16 15:31:00] DEBUG[24869] chan_sip.c: Header 12 [ 19]: Supported: replaces [Jul 16 15:31:00] DEBUG[24869] chan_sip.c: Header 13 [ 29]: Content-Type: application/sdp [Jul 16 15:31:00] DEBUG[24869] chan_sip.c: Header 14 [ 19]: Content-Length: 236 [Jul 16 15:31:00] DEBUG[24869] chan_sip.c: Header 15 [ 0]: [Jul 16 15:31:00] DEBUG[24869] chan_sip.c: Body 0 [ 3]: v=0 [Jul 16 15:31:00] DEBUG[24869] chan_sip.c: Body 1 [ 36]: o=root 22177 22177 IN IP4 192.168.77.230 [Jul 16 15:31:00] DEBUG[24869] chan_sip.c: Body 2 [ 9]: s=session [Jul 16 15:31:00] DEBUG[24869] chan_sip.c: Body 3 [ 19]: c=IN IP4 192.168.77.230 [Jul 16 15:31:00] DEBUG[24869] chan_sip.c: Body 4 [ 5]: t=0 0 [Jul 16 15:31:00] DEBUG[24869] chan_sip.c: Body 5 [ 27]: m=audio 10566 RTP/AVP 0 101 [Jul 16 15:31:00] DEBUG[24869] chan_sip.c: Body 6 [ 20]: a=rtpmap:0 PCMU/8000 [Jul 16 15:31:00] DEBUG[24869] chan_sip.c: Body 7 [ 33]: a=rtpmap:101 telephone-event/8000 [Jul 16 15:31:00] DEBUG[24869] chan_sip.c: Body 8 [ 15]: a=fmtp:101 0-16 [Jul 16 15:31:00] DEBUG[24869] chan_sip.c: Body 9 [ 25]: a=silenceSupp:off - - - - [Jul 16 15:31:00] DEBUG[24869] chan_sip.c: Body 10 [ 10]: a=ptime:20 [Jul 16 15:31:00] DEBUG[24869] chan_sip.c: Body 11 [ 10]: a=sendrecv [Jul 16 15:31:00] VERBOSE[24869] chan_sip.c: --- (15 headers 12 lines) --- [Jul 16 15:31:00] DEBUG[24869] acl.c: Found IP address for this socket [Jul 16 15:31:00] DEBUG[24869] chan_sip.c: Setting SIP_TRANSPORT_UDP with address 192.168.77.226:5060 [Jul 16 15:31:00] VERBOSE[24869] netsock.c: == Using SIP RTP CoS mark 5 [Jul 16 15:31:00] DEBUG[24869] chan_sip.c: Setting NAT on RTP to Off [Jul 16 15:31:00] DEBUG[24869] chan_sip.c: Allocating new SIP dialog for 74a69a3b429799ff5369c69b3103f718@192.168.77.230 - INVITE (With RTP) [Jul 16 15:31:00] DEBUG[24869] chan_sip.c: **** Received INVITE (5) - Command in SIP INVITE [Jul 16 15:31:00] DEBUG[24869] chan_sip.c: Begin: parsing SIP "Supported: replaces" [Jul 16 15:31:00] DEBUG[24869] chan_sip.c: Found SIP option: -replaces- [Jul 16 15:31:00] DEBUG[24869] chan_sip.c: Matched SIP option: replaces [Jul 16 15:31:00] VERBOSE[24869] chan_sip.c: Sending to 192.168.77.230 : 5060 (no NAT) [Jul 16 15:31:00] DEBUG[24869] chan_sip.c: Initializing initreq for method INVITE - callid 74a69a3b429799ff5369c69b3103f718@192.168.77.230 [Jul 16 15:31:00] VERBOSE[24869] chan_sip.c: Using INVITE request as basis request - 74a69a3b429799ff5369c69b3103f718@192.168.77.230 [Jul 16 15:31:00] VERBOSE[24869] chan_sip.c: Found peer 'ted' for '2505551212' from 192.168.77.230:5060 [Jul 16 15:31:00] DEBUG[24869] chan_sip.c: Setting NAT on RTP to Off [Jul 16 15:31:00] DEBUG[24869] chan_sip.c: Processing session-level SDP v=0... UNSUPPORTED. [Jul 16 15:31:00] DEBUG[24869] chan_sip.c: Processing session-level SDP o=root 22177 22177 IN IP4 192.168.77.230... UNSUPPORTED. [Jul 16 15:31:00] DEBUG[24869] chan_sip.c: Processing session-level SDP s=session... UNSUPPORTED. [Jul 16 15:31:00] DEBUG[24869] chan_sip.c: Processing session-level SDP c=IN IP4 192.168.77.230... OK. [Jul 16 15:31:00] DEBUG[24869] chan_sip.c: Processing session-level SDP t=0 0... UNSUPPORTED. [Jul 16 15:31:00] VERBOSE[24869] chan_sip.c: Found RTP audio format 0 [Jul 16 15:31:00] VERBOSE[24869] chan_sip.c: Found RTP audio format 101 [Jul 16 15:31:00] VERBOSE[24869] chan_sip.c: Found audio description format PCMU for ID 0 [Jul 16 15:31:00] DEBUG[24869] chan_sip.c: Processing media-level (audio) SDP a=rtpmap:0 PCMU/8000... OK. [Jul 16 15:31:00] VERBOSE[24869] chan_sip.c: Found audio description format telephone-event for ID 101 [Jul 16 15:31:00] DEBUG[24869] chan_sip.c: Processing media-level (audio) SDP a=rtpmap:101 telephone-event/8000... OK. [Jul 16 15:31:00] DEBUG[24869] chan_sip.c: Processing media-level (audio) SDP a=fmtp:101 0-16... UNSUPPORTED. [Jul 16 15:31:00] DEBUG[24869] chan_sip.c: Processing media-level (audio) SDP a=silenceSupp:off - - - -... UNSUPPORTED. [Jul 16 15:31:00] DEBUG[24869] chan_sip.c: Processing media-level (audio) SDP a=ptime:20... OK. [Jul 16 15:31:00] DEBUG[24869] chan_sip.c: Processing media-level (audio) SDP a=sendrecv... OK. [Jul 16 15:31:00] VERBOSE[24869] chan_sip.c: Capabilities: us - 0x4 (ulaw), peer - audio=0x4 (ulaw)/video=0x0 (nothing)/text=0x0 (nothing), combined - 0x4 (ulaw) [Jul 16 15:31:00] VERBOSE[24869] chan_sip.c: Non-codec capabilities (dtmf): us - 0x1 (telephone-event), peer - 0x1 (telephone-event), combined - 0x1 (telephone-event) [Jul 16 15:31:00] VERBOSE[24869] chan_sip.c: Peer audio RTP is at port 192.168.77.230:10566 [Jul 16 15:31:00] DEBUG[24869] chan_sip.c: We're settling with these formats: 0x4 (ulaw) [Jul 16 15:31:00] DEBUG[24869] chan_sip.c: Checking SIP call limits for device [Jul 16 15:31:00] DEBUG[24869] chan_sip.c: Updating call counter for incoming call [Jul 16 15:31:00] VERBOSE[24869] chan_sip.c: Looking for 8775551212 in trusted (domain appserver.invalid) [Jul 16 15:31:00] DEBUG[24869] chan_sip.c: *** Our native formats are 0x4 (ulaw) [Jul 16 15:31:00] DEBUG[24869] chan_sip.c: *** Joint capabilities are 0x4 (ulaw) [Jul 16 15:31:00] DEBUG[24869] chan_sip.c: *** Our capabilities are 0x4 (ulaw) [Jul 16 15:31:00] DEBUG[24869] chan_sip.c: *** AST_CODEC_CHOOSE formats are 0x4 (ulaw) [Jul 16 15:31:00] DEBUG[24869] chan_sip.c: This channel will not be able to handle video. [Jul 16 15:31:00] DEBUG[24869] chan_sip.c: build_route: Contact hop: [Jul 16 15:31:00] VERBOSE[24869] chan_sip.c: list_route: hop: [Jul 16 15:31:00] DEBUG[24869] chan_sip.c: SIP/ted-00000070: New call is still down.... Trying... [Jul 16 15:31:00] VERBOSE[24869] chan_sip.c: <--- Transmitting (no NAT) to 192.168.77.230:5060 ---> SIP/2.0 100 Trying v: SIP/2.0/UDP 192.168.77.230:5060;branch=z9hG4bK5859d942;received=192.168.77.230;rport=5060 f: "Victoria BC" ;tag=as717a7b2b t: i: 74a69a3b429799ff5369c69b3103f718@192.168.77.230 CSeq: 102 INVITE Server: Asterisk PBX Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO k: replaces, timer m: l: 0 <------------> [Jul 16 15:31:00] DEBUG[24869] chan_sip.c: Trying to put 'SIP/2.0 100' onto UDP socket destined for 192.168.77.230:5060 [Jul 16 15:31:00] DEBUG[1222] pbx.c: Launching 'Goto' [Jul 16 15:31:00] VERBOSE[1222] pbx.c: -- Executing [8775551212@trusted:1] Goto("SIP/ted-00000070", "eln,8775551212,1") in new stack [Jul 16 15:31:00] VERBOSE[1222] pbx.c: -- Goto (eln,8775551212,1) [Jul 16 15:31:00] DEBUG[24860] devicestate.c: No provider found, checking channel drivers for SIP - ted [Jul 16 15:31:00] DEBUG[1222] pbx.c: Launching 'Set' [Jul 16 15:31:00] DEBUG[24860] chan_sip.c: Checking device state for peer ted [Jul 16 15:31:00] VERBOSE[1222] pbx.c: -- Executing [8775551212@eln:1] Set("SIP/ted-00000070", "_identity=cln") in new stack [Jul 16 15:31:00] DEBUG[24860] devicestate.c: Changing state for SIP/ted - state 1 (Not in use) [Jul 16 15:31:00] DEBUG[24860] devicestate.c: device 'SIP/ted' state '1' [Jul 16 15:31:00] DEBUG[1222] pbx.c: Launching 'Goto' [Jul 16 15:31:00] VERBOSE[1222] pbx.c: -- Executing [8775551212@eln:2] Goto("SIP/ted-00000070", "s,1") in new stack [Jul 16 15:31:00] VERBOSE[1222] pbx.c: -- Goto (eln,s,1) [Jul 16 15:31:00] DEBUG[1222] pbx.c: Launching 'Playback' [Jul 16 15:31:00] VERBOSE[1222] pbx.c: -- Executing [s@eln:1] Playback("SIP/ted-00000070", "silence/1") in new stack [Jul 16 15:31:00] DEBUG[1222] chan_sip.c: SIP answering channel: SIP/ted-00000070 [Jul 16 15:31:00] DEBUG[1222] rtp.c: Setting the marker bit due to a source update [Jul 16 15:31:00] DEBUG[1222] chan_sip.c: Setting framing from config on incoming call [Jul 16 15:31:00] DEBUG[1222] chan_sip.c: ** Our capability: 0x4 (ulaw) Video flag: True Text flag: True [Jul 16 15:31:00] DEBUG[1222] chan_sip.c: ** Our prefcodec: 0x0 (nothing) [Jul 16 15:31:00] VERBOSE[1222] chan_sip.c: Audio is at 192.168.77.226 port 25902 [Jul 16 15:31:00] VERBOSE[1222] chan_sip.c: Adding codec 0x4 (ulaw) to SDP [Jul 16 15:31:00] VERBOSE[1222] chan_sip.c: Adding non-codec 0x1 (telephone-event) to SDP [Jul 16 15:31:00] DEBUG[1222] chan_sip.c: -- Done with adding codecs to SDP [Jul 16 15:31:00] DEBUG[1222] chan_sip.c: Done building SDP. Settling with this capability: 0x4 (ulaw) [Jul 16 15:31:00] VERBOSE[1222] chan_sip.c: <--- Reliably Transmitting (no NAT) to 192.168.77.230:5060 ---> SIP/2.0 200 OK v: SIP/2.0/UDP 192.168.77.230:5060;branch=z9hG4bK5859d942;received=192.168.77.230;rport=5060 f: "Victoria BC" ;tag=as717a7b2b t: ;tag=as009f06d8 i: 74a69a3b429799ff5369c69b3103f718@192.168.77.230 CSeq: 102 INVITE Server: Asterisk PBX Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO k: replaces, timer m: c: application/sdp l: 251 v=0 o=root 2000361184 2000361184 IN IP4 192.168.77.226 s=Asterisk PBX c=IN IP4 192.168.77.226 t=0 0 m=audio 25902 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 <------------> [Jul 16 15:31:00] DEBUG[1222] chan_sip.c: *** SIP TIMER: Initializing retransmit timer on packet: Id #4879 [Jul 16 15:31:00] DEBUG[1222] chan_sip.c: Trying to put 'SIP/2.0 200' onto UDP socket destined for 192.168.77.230:5060 [Jul 16 15:31:00] DEBUG[24860] devicestate.c: No provider found, checking channel drivers for SIP - ted [Jul 16 15:31:00] DEBUG[24860] chan_sip.c: Checking device state for peer ted [Jul 16 15:31:00] DEBUG[24860] devicestate.c: Changing state for SIP/ted - state 1 (Not in use) [Jul 16 15:31:00] DEBUG[24860] devicestate.c: device 'SIP/ted' state '1' [Jul 16 15:31:00] VERBOSE[24869] chan_sip.c: <--- SIP read from UDP:192.168.77.230:5060 ---> ACK sip:8775551212@192.168.77.226 SIP/2.0 Via: SIP/2.0/UDP 192.168.77.230:5060;branch=z9hG4bK0fbf734a;rport From: "Victoria BC" ;tag=as717a7b2b To: ;tag=as009f06d8 Contact: Call-ID: 74a69a3b429799ff5369c69b3103f718@192.168.77.230 CSeq: 102 ACK User-Agent: AVNet Max-Forwards: 70 Remote-Party-ID: "Victoria BC" ;privacy=off;screen=no Content-Length: 0 <-------------> [Jul 16 15:31:00] DEBUG[24869] chan_sip.c: Header 0 [ 37]: ACK sip:8775551212@192.168.77.226 SIP/2.0 [Jul 16 15:31:00] DEBUG[24869] chan_sip.c: Header 1 [ 61]: Via: SIP/2.0/UDP 192.168.77.230:5060;branch=z9hG4bK0fbf734a;rport [Jul 16 15:31:00] DEBUG[24869] chan_sip.c: Header 2 [ 66]: From: "Victoria BC" ;tag=as717a7b2b [Jul 16 15:31:00] DEBUG[24869] chan_sip.c: Header 3 [ 45]: To: ;tag=as009f06d8 [Jul 16 15:31:00] DEBUG[24869] chan_sip.c: Header 4 [ 36]: Contact: [Jul 16 15:31:00] DEBUG[24869] chan_sip.c: Header 5 [ 52]: Call-ID: 74a69a3b429799ff5369c69b3103f718@192.168.77.230 [Jul 16 15:31:00] DEBUG[24869] chan_sip.c: Header 6 [ 13]: CSeq: 102 ACK [Jul 16 15:31:00] DEBUG[24869] chan_sip.c: Header 7 [ 21]: User-Agent: AVNet [Jul 16 15:31:00] DEBUG[24869] chan_sip.c: Header 8 [ 16]: Max-Forwards: 70 [Jul 16 15:31:00] DEBUG[24869] chan_sip.c: Header 9 [ 84]: Remote-Party-ID: "Victoria BC" ;privacy=off;screen=no [Jul 16 15:31:00] DEBUG[24869] chan_sip.c: Header 10 [ 17]: Content-Length: 0 [Jul 16 15:31:00] DEBUG[24869] chan_sip.c: Header 11 [ 0]: [Jul 16 15:31:00] VERBOSE[24869] chan_sip.c: --- (11 headers 0 lines) --- [Jul 16 15:31:00] DEBUG[24869] chan_sip.c: **** Received ACK (6) - Command in SIP ACK [Jul 16 15:31:00] DEBUG[24869] chan_sip.c: ** SIP TIMER: Cancelling retransmit of packet (reply received) Retransid #4879 [Jul 16 15:31:00] DEBUG[24869] chan_sip.c: Stopping retransmission on '74a69a3b429799ff5369c69b3103f718@192.168.77.230' of Response 102: Match Found [Jul 16 15:31:00] VERBOSE[24869] chan_sip.c: <--- SIP read from UDP:192.168.77.230:5060 ---> INVITE sip:8775551212@192.168.77.226 SIP/2.0 Via: SIP/2.0/UDP 192.168.77.230:5060;branch=z9hG4bK355cf3d9;rport From: "Victoria BC" ;tag=as717a7b2b To: ;tag=as009f06d8 Contact: Call-ID: 74a69a3b429799ff5369c69b3103f718@192.168.77.230 CSeq: 103 INVITE User-Agent: AVNet Max-Forwards: 70 Remote-Party-ID: "Victoria BC" ;privacy=off;screen=no Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO Supported: replaces Content-Type: application/sdp Content-Length: 244 v=0 o=root 22177 22178 IN IP4 192.168.88.104 s=session c=IN IP4 192.168.88.104 t=0 0 m=audio 32876 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 <-------------> [Jul 16 15:31:00] DEBUG[24869] chan_sip.c: Header 0 [ 40]: INVITE sip:8775551212@192.168.77.226 SIP/2.0 [Jul 16 15:31:00] DEBUG[24869] chan_sip.c: Header 1 [ 61]: Via: SIP/2.0/UDP 192.168.77.230:5060;branch=z9hG4bK355cf3d9;rport [Jul 16 15:31:00] DEBUG[24869] chan_sip.c: Header 2 [ 66]: From: "Victoria BC" ;tag=as717a7b2b [Jul 16 15:31:00] DEBUG[24869] chan_sip.c: Header 3 [ 45]: To: ;tag=as009f06d8 [Jul 16 15:31:00] DEBUG[24869] chan_sip.c: Header 4 [ 36]: Contact: [Jul 16 15:31:00] DEBUG[24869] chan_sip.c: Header 5 [ 52]: Call-ID: 74a69a3b429799ff5369c69b3103f718@192.168.77.230 [Jul 16 15:31:00] DEBUG[24869] chan_sip.c: Header 6 [ 16]: CSeq: 103 INVITE [Jul 16 15:31:00] DEBUG[24869] chan_sip.c: Header 7 [ 21]: User-Agent: AVNet [Jul 16 15:31:00] DEBUG[24869] chan_sip.c: Header 8 [ 16]: Max-Forwards: 70 [Jul 16 15:31:00] DEBUG[24869] chan_sip.c: Header 9 [ 84]: Remote-Party-ID: "Victoria BC" ;privacy=off;screen=no [Jul 16 15:31:00] DEBUG[24869] chan_sip.c: Header 10 [ 72]: Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO [Jul 16 15:31:00] DEBUG[24869] chan_sip.c: Header 11 [ 19]: Supported: replaces [Jul 16 15:31:00] DEBUG[24869] chan_sip.c: Header 12 [ 29]: Content-Type: application/sdp [Jul 16 15:31:00] DEBUG[24869] chan_sip.c: Header 13 [ 19]: Content-Length: 244 [Jul 16 15:31:00] DEBUG[24869] chan_sip.c: Header 14 [ 0]: [Jul 16 15:31:00] DEBUG[24869] chan_sip.c: Body 0 [ 3]: v=0 [Jul 16 15:31:00] DEBUG[24869] chan_sip.c: Body 1 [ 40]: o=root 22177 22178 IN IP4 192.168.88.104 [Jul 16 15:31:00] DEBUG[24869] chan_sip.c: Body 2 [ 9]: s=session [Jul 16 15:31:00] DEBUG[24869] chan_sip.c: Body 3 [ 23]: c=IN IP4 192.168.88.104 [Jul 16 15:31:00] DEBUG[24869] chan_sip.c: Body 4 [ 5]: t=0 0 [Jul 16 15:31:00] DEBUG[24869] chan_sip.c: Body 5 [ 27]: m=audio 32876 RTP/AVP 0 101 [Jul 16 15:31:00] DEBUG[24869] chan_sip.c: Body 6 [ 20]: a=rtpmap:0 PCMU/8000 [Jul 16 15:31:00] DEBUG[24869] chan_sip.c: Body 7 [ 33]: a=rtpmap:101 telephone-event/8000 [Jul 16 15:31:00] DEBUG[24869] chan_sip.c: Body 8 [ 15]: a=fmtp:101 0-16 [Jul 16 15:31:00] DEBUG[24869] chan_sip.c: Body 9 [ 25]: a=silenceSupp:off - - - - [Jul 16 15:31:00] DEBUG[24869] chan_sip.c: Body 10 [ 10]: a=ptime:20 [Jul 16 15:31:00] DEBUG[24869] chan_sip.c: Body 11 [ 10]: a=sendrecv [Jul 16 15:31:00] VERBOSE[24869] chan_sip.c: --- (14 headers 12 lines) --- [Jul 16 15:31:00] DEBUG[24869] chan_sip.c: **** Received INVITE (5) - Command in SIP INVITE [Jul 16 15:31:00] VERBOSE[24869] chan_sip.c: Sending to 192.168.77.230 : 5060 (no NAT) [Jul 16 15:31:00] DEBUG[24869] chan_sip.c: Initializing initreq for method INVITE - callid 74a69a3b429799ff5369c69b3103f718@192.168.77.230 [Jul 16 15:31:00] DEBUG[24869] chan_sip.c: Processing session-level SDP v=0... UNSUPPORTED. [Jul 16 15:31:00] DEBUG[24869] chan_sip.c: Processing session-level SDP o=root 22177 22178 IN IP4 192.168.88.104... UNSUPPORTED. [Jul 16 15:31:00] DEBUG[24869] chan_sip.c: Processing session-level SDP s=session... UNSUPPORTED. [Jul 16 15:31:00] DEBUG[24869] chan_sip.c: Processing session-level SDP c=IN IP4 192.168.88.104... OK. [Jul 16 15:31:00] DEBUG[24869] chan_sip.c: Processing session-level SDP t=0 0... UNSUPPORTED. [Jul 16 15:31:00] VERBOSE[24869] chan_sip.c: Found RTP audio format 0 [Jul 16 15:31:00] VERBOSE[24869] chan_sip.c: Found RTP audio format 101 [Jul 16 15:31:00] VERBOSE[24869] chan_sip.c: Found audio description format PCMU for ID 0 [Jul 16 15:31:00] DEBUG[24869] chan_sip.c: Processing media-level (audio) SDP a=rtpmap:0 PCMU/8000... OK. [Jul 16 15:31:00] VERBOSE[24869] chan_sip.c: Found audio description format telephone-event for ID 101 [Jul 16 15:31:00] DEBUG[24869] chan_sip.c: Processing media-level (audio) SDP a=rtpmap:101 telephone-event/8000... OK. [Jul 16 15:31:00] DEBUG[24869] chan_sip.c: Processing media-level (audio) SDP a=fmtp:101 0-16... UNSUPPORTED. [Jul 16 15:31:00] DEBUG[24869] chan_sip.c: Processing media-level (audio) SDP a=silenceSupp:off - - - -... UNSUPPORTED. [Jul 16 15:31:00] DEBUG[24869] chan_sip.c: Processing media-level (audio) SDP a=ptime:20... OK. [Jul 16 15:31:00] DEBUG[24869] chan_sip.c: Processing media-level (audio) SDP a=sendrecv... OK. [Jul 16 15:31:00] VERBOSE[24869] chan_sip.c: Capabilities: us - 0x4 (ulaw), peer - audio=0x4 (ulaw)/video=0x0 (nothing)/text=0x0 (nothing), combined - 0x4 (ulaw) [Jul 16 15:31:00] VERBOSE[24869] chan_sip.c: Non-codec capabilities (dtmf): us - 0x1 (telephone-event), peer - 0x1 (telephone-event), combined - 0x1 (telephone-event) [Jul 16 15:31:00] VERBOSE[24869] chan_sip.c: Peer audio RTP is at port 192.168.88.104:32876 [Jul 16 15:31:00] DEBUG[24869] chan_sip.c: We're settling with these formats: 0x4 (ulaw) [Jul 16 15:31:00] DEBUG[24869] chan_sip.c: We have an owner, now see if we need to change this call [Jul 16 15:31:00] DEBUG[24869] chan_sip.c: Got a SIP re-invite for call 74a69a3b429799ff5369c69b3103f718@192.168.77.230 [Jul 16 15:31:00] DEBUG[24869] chan_sip.c: SIP/ted-00000070: This call is UP.... [Jul 16 15:31:00] VERBOSE[24869] chan_sip.c: <--- Transmitting (no NAT) to 192.168.77.230:5060 ---> SIP/2.0 100 Trying v: SIP/2.0/UDP 192.168.77.230:5060;branch=z9hG4bK355cf3d9;received=192.168.77.230;rport=5060 f: "Victoria BC" ;tag=as717a7b2b t: ;tag=as009f06d8 i: 74a69a3b429799ff5369c69b3103f718@192.168.77.230 CSeq: 103 INVITE Server: Asterisk PBX Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO k: replaces, timer m: l: 0 <------------> [Jul 16 15:31:00] DEBUG[24869] chan_sip.c: Trying to put 'SIP/2.0 100' onto UDP socket destined for 192.168.77.230:5060 [Jul 16 15:31:00] DEBUG[24869] chan_sip.c: Setting framing from config on incoming call [Jul 16 15:31:00] DEBUG[24869] chan_sip.c: ** Our capability: 0x4 (ulaw) Video flag: True Text flag: True [Jul 16 15:31:00] DEBUG[24869] chan_sip.c: ** Our prefcodec: 0x0 (nothing) [Jul 16 15:31:00] VERBOSE[24869] chan_sip.c: Audio is at 192.168.77.226 port 25902 [Jul 16 15:31:00] VERBOSE[24869] chan_sip.c: Adding codec 0x4 (ulaw) to SDP [Jul 16 15:31:00] VERBOSE[24869] chan_sip.c: Adding non-codec 0x1 (telephone-event) to SDP [Jul 16 15:31:00] DEBUG[24869] chan_sip.c: -- Done with adding codecs to SDP [Jul 16 15:31:00] DEBUG[24869] chan_sip.c: Done building SDP. Settling with this capability: 0x4 (ulaw) [Jul 16 15:31:00] VERBOSE[24869] chan_sip.c: <--- Reliably Transmitting (no NAT) to 192.168.77.230:5060 ---> SIP/2.0 200 OK v: SIP/2.0/UDP 192.168.77.230:5060;branch=z9hG4bK355cf3d9;received=192.168.77.230;rport=5060 f: "Victoria BC" ;tag=as717a7b2b t: ;tag=as009f06d8 i: 74a69a3b429799ff5369c69b3103f718@192.168.77.230 CSeq: 103 INVITE Server: Asterisk PBX Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO k: replaces, timer m: c: application/sdp l: 251 v=0 o=root 2000361184 2000361185 IN IP4 192.168.77.226 s=Asterisk PBX c=IN IP4 192.168.77.226 t=0 0 m=audio 25902 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 <------------> [Jul 16 15:31:00] DEBUG[24869] chan_sip.c: *** SIP TIMER: Initializing retransmit timer on packet: Id #4880 [Jul 16 15:31:00] DEBUG[24869] chan_sip.c: Trying to put 'SIP/2.0 200' onto UDP socket destined for 192.168.77.230:5060 [Jul 16 15:31:00] VERBOSE[24869] chan_sip.c: <--- SIP read from UDP:192.168.77.230:5060 ---> ACK sip:8775551212@192.168.77.226 SIP/2.0 Via: SIP/2.0/UDP 192.168.77.230:5060;branch=z9hG4bK062a5be6;rport From: "Victoria BC" ;tag=as717a7b2b To: ;tag=as009f06d8 Contact: Call-ID: 74a69a3b429799ff5369c69b3103f718@192.168.77.230 CSeq: 103 ACK User-Agent: AVNet Max-Forwards: 70 Remote-Party-ID: "Victoria BC" ;privacy=off;screen=no Content-Length: 0 <-------------> [Jul 16 15:31:00] DEBUG[24869] chan_sip.c: Header 0 [ 37]: ACK sip:8775551212@192.168.77.226 SIP/2.0 [Jul 16 15:31:00] DEBUG[24869] chan_sip.c: Header 1 [ 61]: Via: SIP/2.0/UDP 192.168.77.230:5060;branch=z9hG4bK062a5be6;rport [Jul 16 15:31:00] DEBUG[24869] chan_sip.c: Header 2 [ 66]: From: "Victoria BC" ;tag=as717a7b2b [Jul 16 15:31:00] DEBUG[24869] chan_sip.c: Header 3 [ 45]: To: ;tag=as009f06d8 [Jul 16 15:31:00] DEBUG[24869] chan_sip.c: Header 4 [ 36]: Contact: [Jul 16 15:31:00] DEBUG[24869] chan_sip.c: Header 5 [ 52]: Call-ID: 74a69a3b429799ff5369c69b3103f718@192.168.77.230 [Jul 16 15:31:00] DEBUG[24869] chan_sip.c: Header 6 [ 13]: CSeq: 103 ACK [Jul 16 15:31:00] DEBUG[24869] chan_sip.c: Header 7 [ 21]: User-Agent: AVNet [Jul 16 15:31:00] DEBUG[24869] chan_sip.c: Header 8 [ 16]: Max-Forwards: 70 [Jul 16 15:31:00] DEBUG[24869] chan_sip.c: Header 9 [ 84]: Remote-Party-ID: "Victoria BC" ;privacy=off;screen=no [Jul 16 15:31:00] DEBUG[24869] chan_sip.c: Header 10 [ 17]: Content-Length: 0 [Jul 16 15:31:00] DEBUG[24869] chan_sip.c: Header 11 [ 0]: [Jul 16 15:31:00] VERBOSE[24869] chan_sip.c: --- (11 headers 0 lines) --- [Jul 16 15:31:00] DEBUG[24869] chan_sip.c: **** Received ACK (6) - Command in SIP ACK [Jul 16 15:31:00] DEBUG[24869] chan_sip.c: ** SIP TIMER: Cancelling retransmit of packet (reply received) Retransid #4880 [Jul 16 15:31:00] DEBUG[24869] chan_sip.c: Stopping retransmission on '74a69a3b429799ff5369c69b3103f718@192.168.77.230' of Response 103: Match Found [Jul 16 15:31:00] DEBUG[1222] channel.c: Set channel SIP/ted-00000070 to write format slin16 [Jul 16 15:31:00] DEBUG[1222] rtp.c: Ooh, format changed from unknown to ulaw [Jul 16 15:31:00] DEBUG[1222] rtp.c: Created smoother: format: 4 ms: 20 len: 160 [Jul 16 15:31:00] DEBUG[1222] channel.c: Scheduling timer at (50 requested / 50 actual) timer ticks per second [Jul 16 15:31:00] VERBOSE[1222] file.c: -- Playing 'silence/1.slin16' (language 'en') [Jul 16 15:31:01] DEBUG[1222] rtp.c: Forcing Marker bit, because SSRC has changed [Jul 16 15:31:01] DEBUG[1222] channel.c: Scheduling timer at (0 requested / 0 actual) timer ticks per second [Jul 16 15:31:01] DEBUG[1222] channel.c: Scheduling timer at (0 requested / 0 actual) timer ticks per second [Jul 16 15:31:01] DEBUG[1222] channel.c: Scheduling timer at (0 requested / 0 actual) timer ticks per second [Jul 16 15:31:01] DEBUG[1222] channel.c: Set channel SIP/ted-00000070 to write format ulaw [Jul 16 15:31:01] DEBUG[1222] pbx.c: Launching 'Set' [Jul 16 15:31:01] VERBOSE[1222] pbx.c: -- Executing [s@eln:2] Set("SIP/ted-00000070", "CHANNEL(musicclass)=eln") in new stack [Jul 16 15:31:01] DEBUG[1222] pbx.c: Launching 'BackGround' [Jul 16 15:31:01] VERBOSE[1222] pbx.c: -- Executing [s@eln:3] BackGround("SIP/ted-00000070", "cln/rec1") in new stack [Jul 16 15:31:01] DEBUG[1222] channel.c: Set channel SIP/ted-00000070 to write format slin [Jul 16 15:31:01] DEBUG[1222] channel.c: Scheduling timer at (50 requested / 50 actual) timer ticks per second [Jul 16 15:31:01] VERBOSE[1222] file.c: -- Playing 'cln/rec1.slin' (language 'en') [Jul 16 15:31:02] DEBUG[1222] rtp.c: - RTP 2833 Event: 00000007 (len = 4) [Jul 16 15:31:02] DEBUG[1222] rtp.c: Sending dtmf: 55 (7), at 192.168.88.104 [Jul 16 15:31:02] DEBUG[1222] rtp.c: - RTP 2833 Event: 00000007 (len = 4) [Jul 16 15:31:02] DEBUG[1222] rtp.c: - RTP 2833 Event: 00000007 (len = 4) [Jul 16 15:31:02] DEBUG[1222] rtp.c: - RTP 2833 Event: 00000007 (len = 4) [Jul 16 15:31:02] DEBUG[1222] rtp.c: - RTP 2833 Event: 00000007 (len = 4) [Jul 16 15:31:02] DEBUG[1222] rtp.c: - RTP 2833 Event: 00000007 (len = 4) [Jul 16 15:31:02] DEBUG[1222] rtp.c: Sending dtmf: 55 (7), at 192.168.88.104 [Jul 16 15:31:02] DEBUG[1222] channel.c: Scheduling timer at (0 requested / 0 actual) timer ticks per second [Jul 16 15:31:02] DEBUG[1222] channel.c: Scheduling timer at (0 requested / 0 actual) timer ticks per second [Jul 16 15:31:02] DEBUG[1222] channel.c: Set channel SIP/ted-00000070 to write format ulaw [Jul 16 15:31:02] DEBUG[1222] pbx.c: Oooh, got something to jump out with ('7')! [Jul 16 15:31:02] DEBUG[1222] rtp.c: - RTP 2833 Event: 00000007 (len = 4) [Jul 16 15:31:02] DEBUG[1222] rtp.c: - RTP 2833 Event: 00000007 (len = 4) [Jul 16 15:31:03] DEBUG[1222] rtp.c: - RTP 2833 Event: 00000002 (len = 4) [Jul 16 15:31:03] DEBUG[1222] rtp.c: Sending dtmf: 50 (2), at 192.168.88.104 [Jul 16 15:31:03] DEBUG[1222] rtp.c: - RTP 2833 Event: 00000002 (len = 4) [Jul 16 15:31:03] DEBUG[1222] rtp.c: - RTP 2833 Event: 00000002 (len = 4) [Jul 16 15:31:03] DEBUG[1222] rtp.c: - RTP 2833 Event: 00000002 (len = 4) [Jul 16 15:31:03] DEBUG[1222] rtp.c: - RTP 2833 Event: 00000002 (len = 4) [Jul 16 15:31:03] DEBUG[1222] rtp.c: - RTP 2833 Event: 00000002 (len = 4) [Jul 16 15:31:03] DEBUG[1222] rtp.c: Sending dtmf: 50 (2), at 192.168.88.104 [Jul 16 15:31:03] DEBUG[1222] rtp.c: - RTP 2833 Event: 00000002 (len = 4) [Jul 16 15:31:03] DEBUG[1222] rtp.c: - RTP 2833 Event: 00000002 (len = 4) [Jul 16 15:31:03] DEBUG[1222] rtp.c: - RTP 2833 Event: 00000006 (len = 4) [Jul 16 15:31:03] DEBUG[1222] rtp.c: Sending dtmf: 54 (6), at 192.168.88.104 [Jul 16 15:31:03] DEBUG[1222] rtp.c: - RTP 2833 Event: 00000006 (len = 4) [Jul 16 15:31:03] DEBUG[1222] rtp.c: - RTP 2833 Event: 00000006 (len = 4) [Jul 16 15:31:03] DEBUG[1222] rtp.c: Got RTCP report of 80 bytes [Jul 16 15:31:03] DEBUG[1222] rtp.c: - RTP 2833 Event: 00000006 (len = 4) [Jul 16 15:31:03] DEBUG[1222] rtp.c: - RTP 2833 Event: 00000006 (len = 4) [Jul 16 15:31:03] DEBUG[1222] rtp.c: - RTP 2833 Event: 00000006 (len = 4) [Jul 16 15:31:03] DEBUG[1222] rtp.c: Sending dtmf: 54 (6), at 192.168.88.104 [Jul 16 15:31:03] VERBOSE[1222] pbx.c: == CDR updated on SIP/ted-00000070 [Jul 16 15:31:03] DEBUG[1222] pbx.c: Launching 'Macro' [Jul 16 15:31:03] VERBOSE[1222] pbx.c: -- Executing [726@eln:1] Macro("SIP/ted-00000070", "elnlocalextension") in new stack [Jul 16 15:31:03] DEBUG[1222] pbx.c: Launching 'NoOp' [Jul 16 15:31:03] VERBOSE[1222] pbx.c: -- Executing [s@macro-elnlocalextension:1] NoOp("SIP/ted-00000070", "Calling local extension") in new stack [Jul 16 15:31:03] DEBUG[1222] app_macro.c: Executed application: NoOp [Jul 16 15:31:03] DEBUG[1222] pbx.c: Function result is '0' [Jul 16 15:31:03] DEBUG[1222] pbx.c: Expression result is '1' [Jul 16 15:31:03] DEBUG[1222] pbx.c: Launching 'ExecIf' [Jul 16 15:31:03] VERBOSE[1222] pbx.c: -- Executing [s@macro-elnlocalextension:2] ExecIf("SIP/ted-00000070", "1?Playback(eln/rec4)") in new stack [Jul 16 15:31:03] DEBUG[1222] channel.c: Set channel SIP/ted-00000070 to write format slin [Jul 16 15:31:03] DEBUG[1222] rtp.c: Difference is 4328, ms is 561 [Jul 16 15:31:03] DEBUG[1222] channel.c: Scheduling timer at (50 requested / 50 actual) timer ticks per second [Jul 16 15:31:03] VERBOSE[1222] file.c: -- Playing 'eln/rec4.slin' (language 'en') [Jul 16 15:31:03] DEBUG[1222] rtp.c: - RTP 2833 Event: 00000006 (len = 4) [Jul 16 15:31:03] DEBUG[1222] rtp.c: - RTP 2833 Event: 00000006 (len = 4) [Jul 16 15:31:05] DEBUG[1222] rtp.c: Got RTCP report of 64 bytes [Jul 16 15:31:06] DEBUG[1222] channel.c: Scheduling timer at (113 requested / 100 actual) timer ticks per second [Jul 16 15:31:06] DEBUG[1222] channel.c: Scheduling timer at (0 requested / 0 actual) timer ticks per second [Jul 16 15:31:06] DEBUG[1222] channel.c: Scheduling timer at (0 requested / 0 actual) timer ticks per second [Jul 16 15:31:06] DEBUG[1222] channel.c: Scheduling timer at (0 requested / 0 actual) timer ticks per second [Jul 16 15:31:06] DEBUG[1222] channel.c: Set channel SIP/ted-00000070 to write format ulaw [Jul 16 15:31:06] DEBUG[1222] app_macro.c: Executed application: ExecIf [Jul 16 15:31:06] DEBUG[1222] pbx.c: Function result is '0' [Jul 16 15:31:06] DEBUG[1222] pbx.c: Expression result is '1' [Jul 16 15:31:06] DEBUG[1222] pbx.c: Expression result is '0' [Jul 16 15:31:06] DEBUG[1222] pbx.c: Function result is 'Victoria BC' [Jul 16 15:31:06] DEBUG[1222] pbx.c: Launching 'ExecIf' [Jul 16 15:31:06] VERBOSE[1222] pbx.c: -- Executing [s@macro-elnlocalextension:3] ExecIf("SIP/ted-00000070", "0?Set(CALLERID(name)=ELN-Victoria BC)") in new stack [Jul 16 15:31:06] DEBUG[1222] app_macro.c: Executed application: ExecIf [Jul 16 15:31:06] DEBUG[1222] pbx.c: Expression result is '0' [Jul 16 15:31:06] DEBUG[1222] pbx.c: Function result is 'Victoria BC' [Jul 16 15:31:06] DEBUG[1222] pbx.c: Expression result is '1' [Jul 16 15:31:06] DEBUG[1222] pbx.c: Function result is 'Victoria BC' [Jul 16 15:31:06] DEBUG[1222] pbx.c: Launching 'ExecIf' [Jul 16 15:31:06] VERBOSE[1222] pbx.c: -- Executing [s@macro-elnlocalextension:4] ExecIf("SIP/ted-00000070", "1?Set(CALLERID(name)=CLN-Victoria BC)") in new stack [Jul 16 15:31:06] DEBUG[1222] app_macro.c: Executed application: ExecIf [Jul 16 15:31:06] DEBUG[1222] pbx.c: Expression result is '1' [Jul 16 15:31:06] DEBUG[1222] pbx.c: Function result is 'CLN-Victoria BC' [Jul 16 15:31:06] DEBUG[1222] pbx.c: Launching 'Set' [Jul 16 15:31:06] VERBOSE[1222] pbx.c: -- Executing [s@macro-elnlocalextension:5] Set("SIP/ted-00000070", "skipmsg=") in new stack [Jul 16 15:31:06] DEBUG[1222] app_macro.c: Executed application: Set [Jul 16 15:31:06] DEBUG[1222] pbx.c: Launching 'Dial' [Jul 16 15:31:06] VERBOSE[1222] pbx.c: -- Executing [s@macro-elnlocalextension:6] Dial("SIP/ted-00000070", "SIP/eln-726,20,mt") in new stack [Jul 16 15:31:06] DEBUG[1222] chan_sip.c: Asked to create a SIP channel with formats: 0x4 (ulaw) [Jul 16 15:31:06] VERBOSE[1222] netsock.c: == Using SIP RTP CoS mark 5 [Jul 16 15:31:06] DEBUG[1222] chan_sip.c: Allocating new SIP dialog for 014bde2b22f952d2550da7ff7d127d5b@192.168.77.226 - INVITE (With RTP) [Jul 16 15:31:06] DEBUG[1222] chan_sip.c: Setting NAT on RTP to Off [Jul 16 15:31:06] DEBUG[1222] chan_sip.c: OBPROXY: Not applying OBproxy to this call [Jul 16 15:31:06] DEBUG[1222] acl.c: Found IP address for this socket [Jul 16 15:31:06] DEBUG[1222] chan_sip.c: Setting SIP_TRANSPORT_UDP with address 192.168.77.226:5060 [Jul 16 15:31:06] DEBUG[1222] chan_sip.c: *** Our native formats are 0x4 (ulaw) [Jul 16 15:31:06] DEBUG[1222] chan_sip.c: *** Joint capabilities are 0x4 (ulaw) [Jul 16 15:31:06] DEBUG[1222] chan_sip.c: *** Our capabilities are 0x4 (ulaw) [Jul 16 15:31:06] DEBUG[1222] chan_sip.c: *** AST_CODEC_CHOOSE formats are 0x4 (ulaw) [Jul 16 15:31:06] DEBUG[1222] chan_sip.c: *** Our preferred formats from the incoming channel are 0x4 (ulaw) [Jul 16 15:31:06] DEBUG[1222] chan_sip.c: This channel will not be able to handle video. [Jul 16 15:31:06] DEBUG[1222] dsp.c: Setup tone 1100 Hz, 500 ms, block_size=160, hits_required=21 [Jul 16 15:31:06] DEBUG[1222] dsp.c: Setup tone 2100 Hz, 2600 ms, block_size=160, hits_required=116 [Jul 16 15:31:06] DEBUG[1222] chan_sip.c: Early remote bridge setting SIP '266b8e870866e21c60edcce40a45df81@192.168.77.226' - Sending media to 192.168.88.104 [Jul 16 15:31:06] DEBUG[1222] rtp.c: Seeded SDP of 'SIP/eln-726-00000071' with that of 'SIP/ted-00000070' [Jul 16 15:31:06] DEBUG[1222] channel.c: Not copying variable DIALEDTIME. [Jul 16 15:31:06] DEBUG[1222] channel.c: Not copying variable ANSWEREDTIME. [Jul 16 15:31:06] DEBUG[1222] channel.c: Not copying variable DIALEDPEERNAME. [Jul 16 15:31:06] DEBUG[1222] channel.c: Not copying variable DIALEDPEERNUMBER. [Jul 16 15:31:06] DEBUG[1222] channel.c: Not copying variable DIALSTATUS. [Jul 16 15:31:06] DEBUG[1222] channel.c: Not copying variable MACRO_DEPTH. [Jul 16 15:31:06] DEBUG[1222] channel.c: Not copying variable skipmsg. [Jul 16 15:31:06] DEBUG[1222] channel.c: Not copying variable PLAYBACKSTATUS. [Jul 16 15:31:06] DEBUG[1222] channel.c: Not copying variable MACRO_PRIORITY. [Jul 16 15:31:06] DEBUG[1222] channel.c: Not copying variable MACRO_CONTEXT. [Jul 16 15:31:06] DEBUG[1222] channel.c: Not copying variable MACRO_EXTEN. [Jul 16 15:31:06] DEBUG[1222] channel.c: Not copying variable BACKGROUNDSTATUS. [Jul 16 15:31:06] DEBUG[1222] channel.c: Copying soft-transferable variable identity. [Jul 16 15:31:06] DEBUG[1222] channel.c: Not copying variable SIPCALLID. [Jul 16 15:31:06] DEBUG[1222] channel.c: Not copying variable SIPDOMAIN. [Jul 16 15:31:06] DEBUG[1222] channel.c: Not copying variable SIPURI. [Jul 16 15:31:06] DEBUG[1222] chan_sip.c: Outgoing Call for eln-726 [Jul 16 15:31:06] DEBUG[1222] chan_sip.c: Updating call counter for outgoing call [Jul 16 15:31:06] DEBUG[1222] chan_sip.c: ** Our capability: 0x4 (ulaw) Video flag: False Text flag: False [Jul 16 15:31:06] DEBUG[1222] chan_sip.c: ** Our prefcodec: 0x4 (ulaw) [Jul 16 15:31:06] VERBOSE[1222] chan_sip.c: Audio is at 192.168.77.226 port 23834 [Jul 16 15:31:06] VERBOSE[1222] chan_sip.c: Adding codec 0x4 (ulaw) to SDP [Jul 16 15:31:06] VERBOSE[1222] chan_sip.c: Adding non-codec 0x1 (telephone-event) to SDP [Jul 16 15:31:06] DEBUG[1222] chan_sip.c: -- Done with adding codecs to SDP [Jul 16 15:31:06] DEBUG[1222] chan_sip.c: Done building SDP. Settling with this capability: 0x4 (ulaw) [Jul 16 15:31:06] DEBUG[1222] chan_sip.c: Initializing initreq for method INVITE - callid 266b8e870866e21c60edcce40a45df81@192.168.77.226 [Jul 16 15:31:06] DEBUG[1222] chan_sip.c: Header 0 [ 85]: INVITE sip:eln-726@192.168.66.182:50241;transport=udp;srcadr=10.1.255.241:5060 SIP/2.0 [Jul 16 15:31:06] DEBUG[1222] chan_sip.c: Header 1 [ 59]: v: SIP/2.0/UDP 192.168.77.226:5060;branch=z9hG4bK5f2dbbb0;rport [Jul 16 15:31:06] DEBUG[1222] chan_sip.c: Header 2 [ 16]: Max-Forwards: 70 [Jul 16 15:31:06] DEBUG[1222] chan_sip.c: Header 3 [ 67]: f: "CLN-Victoria BC" ;tag=as494db74c [Jul 16 15:31:06] DEBUG[1222] chan_sip.c: Header 4 [ 75]: t: [Jul 16 15:31:06] DEBUG[1222] chan_sip.c: Header 5 [ 30]: m: [Jul 16 15:31:06] DEBUG[1222] chan_sip.c: Header 6 [ 46]: i: 266b8e870866e21c60edcce40a45df81@192.168.77.226 [Jul 16 15:31:06] DEBUG[1222] chan_sip.c: Header 7 [ 16]: CSeq: 102 INVITE [Jul 16 15:31:06] DEBUG[1222] chan_sip.c: Header 8 [ 24]: User-Agent: Asterisk PBX [Jul 16 15:31:06] DEBUG[1222] chan_sip.c: Header 9 [ 88]: Remote-Party-ID: "CLN-Victoria BC" ;privacy=off;screen=no [Jul 16 15:31:06] DEBUG[1222] chan_sip.c: Header 10 [ 35]: Date: Fri, 16 Jul 2010 22:31:06 GMT [Jul 16 15:31:06] DEBUG[1222] chan_sip.c: Header 11 [ 72]: Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO [Jul 16 15:31:06] DEBUG[1222] chan_sip.c: Header 12 [ 18]: k: replaces, timer [Jul 16 15:31:06] DEBUG[1222] chan_sip.c: Header 13 [ 18]: c: application/sdp [Jul 16 15:31:06] DEBUG[1222] chan_sip.c: Header 14 [ 6]: l: 259 [Jul 16 15:31:06] DEBUG[1222] chan_sip.c: Header 15 [ 0]: [Jul 16 15:31:06] DEBUG[1222] chan_sip.c: Body 0 [ 3]: v=0 [Jul 16 15:31:06] DEBUG[1222] chan_sip.c: Body 1 [ 50]: o=root 1354047046 1354047046 IN IP4 192.168.88.104 [Jul 16 15:31:06] DEBUG[1222] chan_sip.c: Body 2 [ 14]: s=Asterisk PBX [Jul 16 15:31:06] DEBUG[1222] chan_sip.c: Body 3 [ 23]: c=IN IP4 192.168.88.104 [Jul 16 15:31:06] DEBUG[1222] chan_sip.c: Body 4 [ 5]: t=0 0 [Jul 16 15:31:06] DEBUG[1222] chan_sip.c: Body 5 [ 27]: m=audio 32876 RTP/AVP 0 101 [Jul 16 15:31:06] DEBUG[1222] chan_sip.c: Body 6 [ 20]: a=rtpmap:0 PCMU/8000 [Jul 16 15:31:06] DEBUG[1222] chan_sip.c: Body 7 [ 33]: a=rtpmap:101 telephone-event/8000 [Jul 16 15:31:06] DEBUG[1222] chan_sip.c: Body 8 [ 15]: a=fmtp:101 0-16 [Jul 16 15:31:06] DEBUG[1222] chan_sip.c: Body 9 [ 25]: a=silenceSupp:off - - - - [Jul 16 15:31:06] DEBUG[1222] chan_sip.c: Body 10 [ 10]: a=ptime:20 [Jul 16 15:31:06] DEBUG[1222] chan_sip.c: Body 11 [ 10]: a=sendrecv [Jul 16 15:31:06] VERBOSE[1222] chan_sip.c: Reliably Transmitting (no NAT) to 192.168.66.182:50241: INVITE sip:eln-726@192.168.66.182:50241;transport=udp;srcadr=10.1.255.241:5060 SIP/2.0 v: SIP/2.0/UDP 192.168.77.226:5060;branch=z9hG4bK5f2dbbb0;rport Max-Forwards: 70 f: "CLN-Victoria BC" ;tag=as494db74c t: m: i: 266b8e870866e21c60edcce40a45df81@192.168.77.226 CSeq: 102 INVITE User-Agent: Asterisk PBX Remote-Party-ID: "CLN-Victoria BC" ;privacy=off;screen=no Date: Fri, 16 Jul 2010 22:31:06 GMT Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO k: replaces, timer c: application/sdp l: 259 v=0 o=root 1354047046 1354047046 IN IP4 192.168.88.104 s=Asterisk PBX c=IN IP4 192.168.88.104 t=0 0 m=audio 32876 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 --- [Jul 16 15:31:06] DEBUG[1222] chan_sip.c: *** SIP TIMER: Initializing retransmit timer on packet: Id #4882 [Jul 16 15:31:06] DEBUG[1222] chan_sip.c: Trying to put 'INVITE sip:' onto UDP socket destined for 192.168.66.182:50241 [Jul 16 15:31:06] VERBOSE[1222] app_dial.c: -- Called eln-726 [Jul 16 15:31:06] VERBOSE[1222] res_musiconhold.c: -- Started music on hold, class 'eln', on SIP/ted-00000070 [Jul 16 15:31:06] DEBUG[1222] channel.c: Scheduling timer at (50 requested / 50 actual) timer ticks per second [Jul 16 15:31:06] DEBUG[1222] channel.c: Generator got voice, switching to phase locked mode [Jul 16 15:31:06] DEBUG[1222] channel.c: Scheduling timer at (0 requested / 0 actual) timer ticks per second [Jul 16 15:31:06] DEBUG[1222] channel.c: Set channel SIP/ted-00000070 to write format slin [Jul 16 15:31:06] DEBUG[1222] res_musiconhold.c: SIP/ted-00000070 Opened file 1 '/var/lib/asterisk/custommoh/eln/eln-fpm-sunshine' [Jul 16 15:31:06] VERBOSE[24869] chan_sip.c: <--- SIP read from UDP:192.168.66.182:50241 ---> SIP/2.0 180 Ringing Via: SIP/2.0/UDP 192.168.77.226:5060;branch=z9hG4bK5f2dbbb0;rport=1838;received=192.168.77.226 Proxy-Require: com.nortelnetworks.firewall From: "CLN-Victoria BC" ;tag=as494db74c To: ;tag=3418123032 Call-ID: 266b8e870866e21c60edcce40a45df81@192.168.77.226 CSeq: 102 INVITE Allow: INVITE, ACK, CANCEL, BYE, NOTIFY, REFER, OPTIONS, UPDATE, PRACK, SUBSCRIBE, INFO Allow-Events: talk, hold, conference, LocalModeStatus Contact: "Keali @ x726" ;+sip.instance="" Server: Aastra 6730i/2.6.0.66 Supported: gruu, path Content-Length: 0 <-------------> [Jul 16 15:31:06] DEBUG[24869] chan_sip.c: Header 0 [ 19]: SIP/2.0 180 Ringing [Jul 16 15:31:06] DEBUG[24869] chan_sip.c: Header 1 [ 86]: Via: SIP/2.0/UDP 192.168.77.226:5060;branch=z9hG4bK5f2dbbb0;rport=1838;received=192.168.77.226 [Jul 16 15:31:06] DEBUG[24869] chan_sip.c: Header 2 [ 42]: Proxy-Require: com.nortelnetworks.firewall [Jul 16 15:31:06] DEBUG[24869] chan_sip.c: Header 3 [ 70]: From: "CLN-Victoria BC" ;tag=as494db74c [Jul 16 15:31:06] DEBUG[24869] chan_sip.c: Header 4 [ 91]: To: ;tag=3418123032 [Jul 16 15:31:06] DEBUG[24869] chan_sip.c: Header 5 [ 52]: Call-ID: 266b8e870866e21c60edcce40a45df81@192.168.77.226 [Jul 16 15:31:06] DEBUG[24869] chan_sip.c: Header 6 [ 16]: CSeq: 102 INVITE [Jul 16 15:31:06] DEBUG[24869] chan_sip.c: Header 7 [ 88]: Allow: INVITE, ACK, CANCEL, BYE, NOTIFY, REFER, OPTIONS, UPDATE, PRACK, SUBSCRIBE, INFO [Jul 16 15:31:06] DEBUG[24869] chan_sip.c: Header 8 [ 53]: Allow-Events: talk, hold, conference, LocalModeStatus [Jul 16 15:31:06] DEBUG[24869] chan_sip.c: Header 9 [160]: Contact: "Keali @ x726" ;+sip.instance="" [Jul 16 15:31:06] DEBUG[24869] chan_sip.c: Header 10 [ 29]: Server: Aastra 6730i/2.6.0.66 [Jul 16 15:31:06] DEBUG[24869] chan_sip.c: Header 11 [ 21]: Supported: gruu, path [Jul 16 15:31:06] DEBUG[24869] chan_sip.c: Header 12 [ 17]: Content-Length: 0 [Jul 16 15:31:06] DEBUG[24869] chan_sip.c: Header 13 [ 0]: [Jul 16 15:31:06] VERBOSE[24869] chan_sip.c: --- (13 headers 0 lines) --- [Jul 16 15:31:06] DEBUG[24869] chan_sip.c: *** SIP TIMER: Cancelling retransmission #4882 - INVITE (got response) [Jul 16 15:31:06] DEBUG[24869] chan_sip.c: (Provisional) Stopping retransmission (but retaining packet) on '266b8e870866e21c60edcce40a45df81@192.168.77.226' Request 102: Found [Jul 16 15:31:06] DEBUG[24869] chan_sip.c: SIP response 180 to standard invite [Jul 16 15:31:06] VERBOSE[1222] app_dial.c: -- SIP/eln-726-00000071 is ringing [Jul 16 15:31:06] DEBUG[24860] devicestate.c: No provider found, checking channel drivers for SIP - eln-726 [Jul 16 15:31:06] DEBUG[24860] chan_sip.c: Checking device state for peer eln-726 [Jul 16 15:31:06] DEBUG[24860] devicestate.c: Changing state for SIP/eln-726 - state 1 (Not in use) [Jul 16 15:31:06] DEBUG[24860] devicestate.c: device 'SIP/eln-726' state '1' [Jul 16 15:31:07] VERBOSE[24869] chan_sip.c: <--- SIP read from UDP:192.168.66.182:50241 ---> SIP/2.0 200 OK Via: SIP/2.0/UDP 192.168.77.226:5060;branch=z9hG4bK5f2dbbb0;rport=1838;received=192.168.77.226 Proxy-Require: com.nortelnetworks.firewall From: "CLN-Victoria BC" ;tag=as494db74c To: ;tag=3418123032 Call-ID: 266b8e870866e21c60edcce40a45df81@192.168.77.226 CSeq: 102 INVITE Allow: INVITE, ACK, CANCEL, BYE, NOTIFY, REFER, OPTIONS, UPDATE, PRACK, SUBSCRIBE, INFO Allow-Events: talk, hold, conference, LocalModeStatus Contact: "Keali @ x726" ;+sip.instance="" Server: Aastra 6730i/2.6.0.66 Supported: gruu, path, timer, replaces Content-Type: application/sdp Content-Length: 236 v=0 o=MxSIP 0 0 IN IP4 192.168.66.182 s=SIP Call c=IN IP4 192.168.66.182 t=0 0 m=audio 62410 RTP/AVP 0 101 a=rtpmap:0 PCMU/8000 a=rtpmap:101 telephone-event/8000 a=silenceSupp:off - - - - a=fmtp:101 0-15 a=ptime:20 a=sendrecv <-------------> [Jul 16 15:31:07] DEBUG[24869] chan_sip.c: Header 0 [ 14]: SIP/2.0 200 OK [Jul 16 15:31:07] DEBUG[24869] chan_sip.c: Header 1 [ 86]: Via: SIP/2.0/UDP 192.168.77.226:5060;branch=z9hG4bK5f2dbbb0;rport=1838;received=192.168.77.226 [Jul 16 15:31:07] DEBUG[24869] chan_sip.c: Header 2 [ 42]: Proxy-Require: com.nortelnetworks.firewall [Jul 16 15:31:07] DEBUG[24869] chan_sip.c: Header 3 [ 70]: From: "CLN-Victoria BC" ;tag=as494db74c [Jul 16 15:31:07] DEBUG[24869] chan_sip.c: Header 4 [ 91]: To: ;tag=3418123032 [Jul 16 15:31:07] DEBUG[24869] chan_sip.c: Header 5 [ 52]: Call-ID: 266b8e870866e21c60edcce40a45df81@192.168.77.226 [Jul 16 15:31:07] DEBUG[24869] chan_sip.c: Header 6 [ 16]: CSeq: 102 INVITE [Jul 16 15:31:07] DEBUG[24869] chan_sip.c: Header 7 [ 88]: Allow: INVITE, ACK, CANCEL, BYE, NOTIFY, REFER, OPTIONS, UPDATE, PRACK, SUBSCRIBE, INFO [Jul 16 15:31:07] DEBUG[24869] chan_sip.c: Header 8 [ 53]: Allow-Events: talk, hold, conference, LocalModeStatus [Jul 16 15:31:07] DEBUG[24869] chan_sip.c: Header 9 [160]: Contact: "Keali @ x726" ;+sip.instance="" [Jul 16 15:31:07] DEBUG[24869] chan_sip.c: Header 10 [ 29]: Server: Aastra 6730i/2.6.0.66 [Jul 16 15:31:07] DEBUG[24869] chan_sip.c: Header 11 [ 38]: Supported: gruu, path, timer, replaces [Jul 16 15:31:07] DEBUG[24869] chan_sip.c: Header 12 [ 29]: Content-Type: application/sdp [Jul 16 15:31:07] DEBUG[24869] chan_sip.c: Header 13 [ 19]: Content-Length: 236 [Jul 16 15:31:07] DEBUG[24869] chan_sip.c: Header 14 [ 0]: [Jul 16 15:31:07] DEBUG[24869] chan_sip.c: Body 0 [ 3]: v=0 [Jul 16 15:31:07] DEBUG[24869] chan_sip.c: Body 1 [ 32]: o=MxSIP 0 0 IN IP4 192.168.66.182 [Jul 16 15:31:07] DEBUG[24869] chan_sip.c: Body 2 [ 10]: s=SIP Call [Jul 16 15:31:07] DEBUG[24869] chan_sip.c: Body 3 [ 22]: c=IN IP4 192.168.66.182 [Jul 16 15:31:07] DEBUG[24869] chan_sip.c: Body 4 [ 5]: t=0 0 [Jul 16 15:31:07] DEBUG[24869] chan_sip.c: Body 5 [ 27]: m=audio 62410 RTP/AVP 0 101 [Jul 16 15:31:07] DEBUG[24869] chan_sip.c: Body 6 [ 20]: a=rtpmap:0 PCMU/8000 [Jul 16 15:31:07] DEBUG[24869] chan_sip.c: Body 7 [ 33]: a=rtpmap:101 telephone-event/8000 [Jul 16 15:31:07] DEBUG[24869] chan_sip.c: Body 8 [ 25]: a=silenceSupp:off - - - - [Jul 16 15:31:07] DEBUG[24869] chan_sip.c: Body 9 [ 15]: a=fmtp:101 0-15 [Jul 16 15:31:07] DEBUG[24869] chan_sip.c: Body 10 [ 10]: a=ptime:20 [Jul 16 15:31:07] DEBUG[24869] chan_sip.c: Body 11 [ 10]: a=sendrecv [Jul 16 15:31:07] VERBOSE[24869] chan_sip.c: --- (14 headers 12 lines) --- [Jul 16 15:31:07] DEBUG[24869] chan_sip.c: Acked pending invite 102 [Jul 16 15:31:07] DEBUG[24869] chan_sip.c: Stopping retransmission on '266b8e870866e21c60edcce40a45df81@192.168.77.226' of Request 102: Match Found [Jul 16 15:31:07] DEBUG[24869] chan_sip.c: SIP response 200 to standard invite [Jul 16 15:31:07] DEBUG[24869] chan_sip.c: Processing session-level SDP v=0... UNSUPPORTED. [Jul 16 15:31:07] DEBUG[24869] chan_sip.c: Processing session-level SDP o=MxSIP 0 0 IN IP4 192.168.66.182... UNSUPPORTED. [Jul 16 15:31:07] DEBUG[24869] chan_sip.c: Processing session-level SDP s=SIP Call... UNSUPPORTED. [Jul 16 15:31:07] DEBUG[24869] chan_sip.c: Processing session-level SDP c=IN IP4 192.168.66.182... OK. [Jul 16 15:31:07] DEBUG[24869] chan_sip.c: Processing session-level SDP t=0 0... UNSUPPORTED. [Jul 16 15:31:07] VERBOSE[24869] chan_sip.c: Found RTP audio format 0 [Jul 16 15:31:07] VERBOSE[24869] chan_sip.c: Found RTP audio format 101 [Jul 16 15:31:07] VERBOSE[24869] chan_sip.c: Found audio description format PCMU for ID 0 [Jul 16 15:31:07] DEBUG[24869] chan_sip.c: Processing media-level (audio) SDP a=rtpmap:0 PCMU/8000... OK. [Jul 16 15:31:07] VERBOSE[24869] chan_sip.c: Found audio description format telephone-event for ID 101 [Jul 16 15:31:07] DEBUG[24869] chan_sip.c: Processing media-level (audio) SDP a=rtpmap:101 telephone-event/8000... OK. [Jul 16 15:31:07] DEBUG[24869] chan_sip.c: Processing media-level (audio) SDP a=silenceSupp:off - - - -... UNSUPPORTED. [Jul 16 15:31:07] DEBUG[24869] chan_sip.c: Processing media-level (audio) SDP a=fmtp:101 0-15... UNSUPPORTED. [Jul 16 15:31:07] DEBUG[24869] chan_sip.c: Processing media-level (audio) SDP a=ptime:20... OK. [Jul 16 15:31:07] DEBUG[24869] chan_sip.c: Processing media-level (audio) SDP a=sendrecv... OK. [Jul 16 15:31:07] VERBOSE[24869] chan_sip.c: Capabilities: us - 0x4 (ulaw), peer - audio=0x4 (ulaw)/video=0x0 (nothing)/text=0x0 (nothing), combined - 0x4 (ulaw) [Jul 16 15:31:07] VERBOSE[24869] chan_sip.c: Non-codec capabilities (dtmf): us - 0x1 (telephone-event), peer - 0x1 (telephone-event), combined - 0x1 (telephone-event) [Jul 16 15:31:07] VERBOSE[24869] chan_sip.c: Peer audio RTP is at port 192.168.66.182:62410 [Jul 16 15:31:07] DEBUG[24869] chan_sip.c: We're settling with these formats: 0x4 (ulaw) [Jul 16 15:31:07] DEBUG[24869] chan_sip.c: We have an owner, now see if we need to change this call [Jul 16 15:31:07] DEBUG[24869] chan_sip.c: Updating call counter for outgoing call [Jul 16 15:31:07] DEBUG[24869] chan_sip.c: build_route: Contact hop: "Keali @ x726" ;+sip.instance="" [Jul 16 15:31:07] VERBOSE[24869] chan_sip.c: list_route: hop: [Jul 16 15:31:07] DEBUG[24869] chan_sip.c: Strict routing enforced for session 266b8e870866e21c60edcce40a45df81@192.168.77.226 [Jul 16 15:31:07] VERBOSE[24869] chan_sip.c: set_destination: Parsing for address/port to send to [Jul 16 15:31:07] VERBOSE[24869] chan_sip.c: set_destination: set destination to 192.168.66.182, port 50241 [Jul 16 15:31:07] VERBOSE[24869] chan_sip.c: Transmitting (no NAT) to 192.168.66.182:50241: ACK sip:eln-726@192.168.66.182:50241;transport=udp;srcadr=10.1.255.241:5060 SIP/2.0 v: SIP/2.0/UDP 192.168.77.226:5060;branch=z9hG4bK1dc8a7d4;rport Max-Forwards: 70 f: "CLN-Victoria BC" ;tag=as494db74c t: ;tag=3418123032 m: i: 266b8e870866e21c60edcce40a45df81@192.168.77.226 CSeq: 102 ACK User-Agent: Asterisk PBX Remote-Party-ID: "CLN-Victoria BC" ;privacy=off;screen=no l: 0 --- [Jul 16 15:31:07] DEBUG[24869] chan_sip.c: Trying to put 'ACK sip:eln' onto UDP socket destined for 192.168.66.182:50241 [Jul 16 15:31:07] VERBOSE[1222] app_dial.c: -- SIP/eln-726-00000071 answered SIP/ted-00000070 [Jul 16 15:31:07] VERBOSE[1222] res_musiconhold.c: -- Stopped music on hold on SIP/ted-00000070 [Jul 16 15:31:07] DEBUG[1222] channel.c: Set channel SIP/ted-00000070 to write format ulaw [Jul 16 15:31:07] DEBUG[1222] channel.c: Scheduling timer at (0 requested / 0 actual) timer ticks per second [Jul 16 15:31:07] DEBUG[1222] features.c: bridge answer set, chan answer set [Jul 16 15:31:07] DEBUG[1222] rtp.c: Setting the marker bit due to a source update [Jul 16 15:31:07] DEBUG[1222] rtp.c: Setting the marker bit due to a source update [Jul 16 15:31:07] DEBUG[24860] devicestate.c: No provider found, checking channel drivers for SIP - eln-726 [Jul 16 15:31:07] DEBUG[24860] chan_sip.c: Checking device state for peer eln-726 [Jul 16 15:31:07] DEBUG[24860] devicestate.c: Changing state for SIP/eln-726 - state 1 (Not in use) [Jul 16 15:31:07] DEBUG[24860] devicestate.c: device 'SIP/eln-726' state '1' [Jul 16 15:31:07] DEBUG[1222] rtp.c: Ooh, format changed from unknown to ulaw [Jul 16 15:31:07] DEBUG[1222] rtp.c: Created smoother: format: 4 ms: 20 len: 160 [Jul 16 15:31:07] DEBUG[1222] rtp.c: Got RTCP report of 80 bytes [Jul 16 15:31:09] VERBOSE[24869] chan_sip.c: <--- SIP read from UDP:192.168.66.182:5060 ---> BYE sip:2505551212@192.168.77.226 SIP/2.0 Via: SIP/2.0/UDP 192.168.66.182:50241;branch=z9hG4bK8f687084f8c573c7c.d774dd0abeb725132 Proxy-Require: com.nortelnetworks.firewall Max-Forwards: 70 From: ;tag=3418123032 To: "CLN-Victoria BC" ;tag=as494db74c Call-ID: 266b8e870866e21c60edcce40a45df81@192.168.77.226 CSeq: 30178 BYE Allow: INVITE, ACK, CANCEL, BYE, NOTIFY, REFER, OPTIONS, UPDATE, PRACK, SUBSCRIBE, INFO Allow-Events: talk, hold, conference, LocalModeStatus Supported: gruu, path, timer User-Agent: Aastra 6730i/2.6.0.66 Content-Length: 0 <-------------> [Jul 16 15:31:09] DEBUG[24869] chan_sip.c: Header 0 [ 37]: BYE sip:2505551212@192.168.77.226 SIP/2.0 [Jul 16 15:31:09] DEBUG[24869] chan_sip.c: Header 1 [ 86]: Via: SIP/2.0/UDP 192.168.66.182:50241;branch=z9hG4bK8f687084f8c573c7c.d774dd0abeb725132 [Jul 16 15:31:09] DEBUG[24869] chan_sip.c: Header 2 [ 42]: Proxy-Require: com.nortelnetworks.firewall [Jul 16 15:31:09] DEBUG[24869] chan_sip.c: Header 3 [ 16]: Max-Forwards: 70 [Jul 16 15:31:09] DEBUG[24869] chan_sip.c: Header 4 [ 93]: From: ;tag=3418123032 [Jul 16 15:31:09] DEBUG[24869] chan_sip.c: Header 5 [ 68]: To: "CLN-Victoria BC" ;tag=as494db74c [Jul 16 15:31:09] DEBUG[24869] chan_sip.c: Header 6 [ 52]: Call-ID: 266b8e870866e21c60edcce40a45df81@192.168.77.226 [Jul 16 15:31:09] DEBUG[24869] chan_sip.c: Header 7 [ 15]: CSeq: 30178 BYE [Jul 16 15:31:09] DEBUG[24869] chan_sip.c: Header 8 [ 88]: Allow: INVITE, ACK, CANCEL, BYE, NOTIFY, REFER, OPTIONS, UPDATE, PRACK, SUBSCRIBE, INFO [Jul 16 15:31:09] DEBUG[24869] chan_sip.c: Header 9 [ 53]: Allow-Events: talk, hold, conference, LocalModeStatus [Jul 16 15:31:09] DEBUG[24869] chan_sip.c: Header 10 [ 28]: Supported: gruu, path, timer [Jul 16 15:31:09] DEBUG[24869] chan_sip.c: Header 11 [ 33]: User-Agent: Aastra 6730i/2.6.0.66 [Jul 16 15:31:09] DEBUG[24869] chan_sip.c: Header 12 [ 17]: Content-Length: 0 [Jul 16 15:31:09] DEBUG[24869] chan_sip.c: Header 13 [ 0]: [Jul 16 15:31:09] VERBOSE[24869] chan_sip.c: --- (13 headers 0 lines) --- [Jul 16 15:31:09] DEBUG[24869] chan_sip.c: **** Received BYE (8) - Command in SIP BYE [Jul 16 15:31:09] DEBUG[24869] chan_sip.c: Initializing initreq for method BYE - callid 266b8e870866e21c60edcce40a45df81@192.168.77.226 [Jul 16 15:31:09] VERBOSE[24869] chan_sip.c: Sending to 192.168.66.182 : 50241 (no NAT) [Jul 16 15:31:09] DEBUG[24869] chan_sip.c: Setting SIP_ALREADYGONE on dialog 266b8e870866e21c60edcce40a45df81@192.168.77.226 [Jul 16 15:31:09] DEBUG[24869] chan_sip.c: Received bye, issuing owner hangup [Jul 16 15:31:09] VERBOSE[24869] chan_sip.c: <--- Transmitting (no NAT) to 192.168.66.182:50241 ---> SIP/2.0 200 OK v: SIP/2.0/UDP 192.168.66.182:50241;branch=z9hG4bK8f687084f8c573c7c.d774dd0abeb725132;received=192.168.66.182 f: ;tag=3418123032 t: "CLN-Victoria BC" ;tag=as494db74c i: 266b8e870866e21c60edcce40a45df81@192.168.77.226 CSeq: 30178 BYE Server: Asterisk PBX Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO k: replaces, timer l: 0 <------------> [Jul 16 15:31:09] DEBUG[24869] chan_sip.c: Trying to put 'SIP/2.0 200' onto UDP socket destined for 192.168.66.182:50241 [Jul 16 15:31:09] DEBUG[1222] channel.c: Didn't get a frame from channel: SIP/eln-726-00000071 [Jul 16 15:31:09] DEBUG[1222] rtp.c: Setting the marker bit due to a source update [Jul 16 15:31:09] DEBUG[1222] channel.c: Bridge stops bridging channels SIP/ted-00000070 and SIP/eln-726-00000071 [Jul 16 15:31:09] DEBUG[1222] res_odbc.c: odbc_release_obj2(0x8384dc0) called (obj->txf = (nil)) [Jul 16 15:31:09] DEBUG[1222] channel.c: Hanging up channel 'SIP/eln-726-00000071' [Jul 16 15:31:09] DEBUG[1222] chan_sip.c: Hangup call SIP/eln-726-00000071, SIP callid 266b8e870866e21c60edcce40a45df81@192.168.77.226 [Jul 16 15:31:09] DEBUG[1222] rtp.c: Channel '' has no RTP, not doing anything [Jul 16 15:31:09] DEBUG[1222] app_dial.c: Exiting with DIALSTATUS=ANSWER. [Jul 16 15:31:09] DEBUG[24860] devicestate.c: No provider found, checking channel drivers for SIP - eln-726 [Jul 16 15:31:09] DEBUG[1222] app_macro.c: Spawn extension (macro-elnlocalextension,s,6) exited non-zero on 'SIP/ted-00000070' in macro 'elnlocalextension' [Jul 16 15:31:09] VERBOSE[1222] app_macro.c: == Spawn extension (macro-elnlocalextension, s, 6) exited non-zero on 'SIP/ted-00000070' in macro 'elnlocalextension' [Jul 16 15:31:09] DEBUG[24860] chan_sip.c: Checking device state for peer eln-726 [Jul 16 15:31:09] DEBUG[24860] devicestate.c: Changing state for SIP/eln-726 - state 1 (Not in use) [Jul 16 15:31:09] DEBUG[1222] pbx.c: Spawn extension (eln,726,1) exited non-zero on 'SIP/ted-00000070' [Jul 16 15:31:09] VERBOSE[1222] pbx.c: == Spawn extension (eln, 726, 1) exited non-zero on 'SIP/ted-00000070' [Jul 16 15:31:09] DEBUG[24860] devicestate.c: device 'SIP/eln-726' state '1' [Jul 16 15:31:09] DEBUG[1222] channel.c: Soft-Hanging up channel 'SIP/ted-00000070' [Jul 16 15:31:09] DEBUG[1222] channel.c: Hanging up channel 'SIP/ted-00000070' [Jul 16 15:31:09] DEBUG[1222] chan_sip.c: Hangup call SIP/ted-00000070, SIP callid 74a69a3b429799ff5369c69b3103f718@192.168.77.230 [Jul 16 15:31:09] VERBOSE[1222] chan_sip.c: Scheduling destruction of SIP dialog '74a69a3b429799ff5369c69b3103f718@192.168.77.230' in 32000 ms (Method: ACK) [Jul 16 15:31:09] DEBUG[1222] chan_sip.c: Strict routing enforced for session 74a69a3b429799ff5369c69b3103f718@192.168.77.230 [Jul 16 15:31:09] VERBOSE[1222] chan_sip.c: set_destination: Parsing for address/port to send to [Jul 16 15:31:09] VERBOSE[1222] chan_sip.c: set_destination: set destination to 192.168.77.230, port 5060 [Jul 16 15:31:09] VERBOSE[1222] chan_sip.c: Reliably Transmitting (no NAT) to 192.168.77.230:5060: BYE sip:2505551212@192.168.77.230 SIP/2.0 v: SIP/2.0/UDP 192.168.77.226:5060;branch=z9hG4bK18418c86;rport Max-Forwards: 70 f: ;tag=as009f06d8 t: "Victoria BC" ;tag=as717a7b2b i: 74a69a3b429799ff5369c69b3103f718@192.168.77.230 CSeq: 102 BYE User-Agent: Asterisk PBX X-Asterisk-HangupCause: Normal Clearing X-Asterisk-HangupCauseCode: 16 l: 0 --- [Jul 16 15:31:09] DEBUG[1222] chan_sip.c: *** SIP TIMER: Initializing retransmit timer on packet: Id #4886 [Jul 16 15:31:09] DEBUG[1222] chan_sip.c: Trying to put 'BYE sip:250' onto UDP socket destined for 192.168.77.230:5060 [Jul 16 15:31:09] DEBUG[24860] devicestate.c: No provider found, checking channel drivers for SIP - ted [Jul 16 15:31:09] DEBUG[24860] chan_sip.c: Checking device state for peer ted [Jul 16 15:31:09] DEBUG[24860] devicestate.c: Changing state for SIP/ted - state 1 (Not in use) [Jul 16 15:31:09] DEBUG[24860] devicestate.c: device 'SIP/ted' state '1' [Jul 16 15:31:09] VERBOSE[24869] chan_sip.c: <--- SIP read from UDP:192.168.77.230:5060 ---> SIP/2.0 200 OK Via: SIP/2.0/UDP 192.168.77.226:5060;branch=z9hG4bK18418c86;received=192.168.77.226;rport=5060 From: ;tag=as009f06d8 To: "Victoria BC" ;tag=as717a7b2b Call-ID: 74a69a3b429799ff5369c69b3103f718@192.168.77.230 CSeq: 102 BYE User-Agent: AVNet Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO Supported: replaces Content-Length: 0 <-------------> [Jul 16 15:31:09] DEBUG[24869] chan_sip.c: Header 0 [ 14]: SIP/2.0 200 OK [Jul 16 15:31:09] DEBUG[24869] chan_sip.c: Header 1 [ 86]: Via: SIP/2.0/UDP 192.168.77.226:5060;branch=z9hG4bK18418c86;received=192.168.77.226;rport=5060 [Jul 16 15:31:09] DEBUG[24869] chan_sip.c: Header 2 [ 47]: From: ;tag=as009f06d8 [Jul 16 15:31:09] DEBUG[24869] chan_sip.c: Header 3 [ 64]: To: "Victoria BC" ;tag=as717a7b2b [Jul 16 15:31:09] DEBUG[24869] chan_sip.c: Header 4 [ 52]: Call-ID: 74a69a3b429799ff5369c69b3103f718@192.168.77.230 [Jul 16 15:31:09] DEBUG[24869] chan_sip.c: Header 5 [ 13]: CSeq: 102 BYE [Jul 16 15:31:09] DEBUG[24869] chan_sip.c: Header 6 [ 21]: User-Agent: AVNet [Jul 16 15:31:09] DEBUG[24869] chan_sip.c: Header 7 [ 72]: Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO [Jul 16 15:31:09] DEBUG[24869] chan_sip.c: Header 8 [ 19]: Supported: replaces [Jul 16 15:31:09] DEBUG[24869] chan_sip.c: Header 9 [ 17]: Content-Length: 0 [Jul 16 15:31:09] DEBUG[24869] chan_sip.c: Header 10 [ 0]: [Jul 16 15:31:09] VERBOSE[24869] chan_sip.c: --- (10 headers 0 lines) --- [Jul 16 15:31:09] DEBUG[24869] chan_sip.c: ** SIP TIMER: Cancelling retransmit of packet (reply received) Retransid #4886 [Jul 16 15:31:09] DEBUG[24869] chan_sip.c: Stopping retransmission on '74a69a3b429799ff5369c69b3103f718@192.168.77.230' of Request 102: Match Found [Jul 16 15:31:09] VERBOSE[24869] chan_sip.c: SIP Response message for INCOMING dialog BYE arrived [Jul 16 15:31:09] DEBUG[24869] chan_sip.c: Destroying SIP dialog 266b8e870866e21c60edcce40a45df81@192.168.77.226 [Jul 16 15:31:09] VERBOSE[24869] chan_sip.c: Really destroying SIP dialog '266b8e870866e21c60edcce40a45df81@192.168.77.226' Method: BYE [Jul 16 15:31:09] DEBUG[24869] chan_sip.c: Destroying SIP dialog 74a69a3b429799ff5369c69b3103f718@192.168.77.230 [Jul 16 15:31:09] VERBOSE[24869] chan_sip.c: Really destroying SIP dialog '74a69a3b429799ff5369c69b3103f718@192.168.77.230' Method: ACK [Jul 16 15:41:49] VERBOSE[24869] netsock.c: == Using SIP RTP CoS mark 5 [Jul 16 15:41:49] VERBOSE[10359] pbx.c: -- Executing [8887246114@trusted:1] Goto("SIP/ted-00000072", "eln,8887246114,1") in new stack [Jul 16 15:41:49] VERBOSE[10359] pbx.c: -- Goto (eln,8887246114,1) [Jul 16 15:41:49] VERBOSE[10359] pbx.c: -- Executing [8887246114@eln:1] Set("SIP/ted-00000072", "_identity=eln") in new stack [Jul 16 15:41:49] VERBOSE[10359] pbx.c: -- Executing [8887246114@eln:2] Goto("SIP/ted-00000072", "eln,s,1") in new stack [Jul 16 15:41:49] VERBOSE[10359] pbx.c: -- Goto (eln,s,1) [Jul 16 15:41:49] VERBOSE[10359] pbx.c: -- Executing [s@eln:1] Playback("SIP/ted-00000072", "silence/1") in new stack [Jul 16 15:41:49] VERBOSE[10359] file.c: -- Playing 'silence/1.slin16' (language 'en') [Jul 16 15:41:50] VERBOSE[10359] pbx.c: -- Executing [s@eln:2] Set("SIP/ted-00000072", "CHANNEL(musicclass)=eln") in new stack [Jul 16 15:41:50] VERBOSE[10359] pbx.c: -- Executing [s@eln:3] BackGround("SIP/ted-00000072", "eln/rec1") in new stack [Jul 16 15:41:50] VERBOSE[10359] file.c: -- Playing 'eln/rec1.slin' (language 'en') [Jul 16 15:42:05] VERBOSE[10359] pbx.c: == CDR updated on SIP/ted-00000072 [Jul 16 15:42:05] VERBOSE[10359] pbx.c: -- Executing [702@eln:1] Dial("SIP/ted-00000072", "SIP/ted/ets543,60,M(elnpromptanswer^3)mt") in new stack [Jul 16 15:42:05] VERBOSE[10359] netsock.c: == Using SIP RTP CoS mark 5 [Jul 16 15:42:05] VERBOSE[10359] app_dial.c: -- Called ted/ets543 [Jul 16 15:42:05] VERBOSE[10359] res_musiconhold.c: -- Started music on hold, class 'eln', on SIP/ted-00000072 [Jul 16 15:42:05] VERBOSE[10359] app_dial.c: -- SIP/ted-00000073 is ringing [Jul 16 15:42:16] VERBOSE[10359] app_dial.c: -- SIP/ted-00000073 answered SIP/ted-00000072 [Jul 16 15:42:16] VERBOSE[10359] pbx.c: -- Executing [s@macro-elnpromptanswer:1] NoOp("SIP/ted-00000073", "Prompting for an answer") in new stack [Jul 16 15:42:16] VERBOSE[10359] pbx.c: -- Executing [s@macro-elnpromptanswer:2] Set("SIP/ted-00000073", "MACRO_RESULT=CONTINUE") in new stack [Jul 16 15:42:16] VERBOSE[10359] pbx.c: -- Executing [s@macro-elnpromptanswer:3] Set("SIP/ted-00000073", "SPYGROUP=toagent") in new stack [Jul 16 15:42:16] VERBOSE[10359] pbx.c: -- Executing [s@macro-elnpromptanswer:4] Set("SIP/ted-00000073", "tries=2") in new stack [Jul 16 15:42:16] VERBOSE[10359] pbx.c: -- Executing [s@macro-elnpromptanswer:5] ExecIf("SIP/ted-00000073", "1?Set(tries=3)") in new stack [Jul 16 15:42:16] VERBOSE[10359] pbx.c: -- Executing [s@macro-elnpromptanswer:6] Read("SIP/ted-00000073", "resp,eln/rec7,1,,3,2") in new stack [Jul 16 15:42:16] VERBOSE[10359] app_read.c: -- Accepting a maximum of 1 digits. [Jul 16 15:42:16] VERBOSE[10359] file.c: -- Playing 'eln/rec7.slin' (language 'en') [Jul 16 15:42:25] VERBOSE[10359] app_read.c: -- User entered nothing, 2 chances left [Jul 16 15:42:25] VERBOSE[10359] file.c: -- Playing 'eln/rec7.slin' (language 'en') [Jul 16 15:42:35] VERBOSE[10359] app_read.c: -- User entered nothing, 1 chance left [Jul 16 15:42:35] VERBOSE[10359] file.c: -- Playing 'eln/rec7.slin' (language 'en')