[Jun 22 13:37:03] VERBOSE[27829] config.c: == Parsing '/etc/asterisk/logger.conf': [Jun 22 13:37:03] DEBUG[27829] config.c: Parsing /etc/asterisk/logger.conf [Jun 22 13:37:03] VERBOSE[27829] config.c: == Found [Jun 22 13:37:03] VERBOSE[27829] logger.c: Asterisk Event Logger restarted [Jun 22 13:37:03] VERBOSE[27829] logger.c: Asterisk Queue Logger restarted [Jun 22 13:37:06] VERBOSE[27843] chan_sip.c: <--- SIP read from UDP:99.99.49.125:5060 ---> INVITE sip:311@99.99.63.208;user=phone SIP/2.0 To: Call-ID: DL0f837860f5-5572063@Dell4-PC From: "dave 001" ;tag=DLda8f5d1c96;epid=02F57A80 CSeq: 1 INVITE Max-Forwards: 69 Via: SIP/2.0/UDP 99.99.118.91:5060;rport;branch=z9hG4bK1494c5cbc020a51431b0b-c8619815-f6dcc727 Via: SIP/2.0/UDP 192.168.100.9:5060;branch=z9hG4bK-cb85b1808b-DL;received=99.99.208.204 Contact: "dave001" Allow: INVITE,CANCEL,ACK,OPTIONS,INFO,SUBSCRIBE,NOTIFY,BYE,MESSAGE,UPDATE,REFER Supported: replaces,norefersub User-Agent: Dylogic Mirial 7.0.24 P-Behind-NAT: Yes Record-Route: Content-Type: application/sdp Content-Length: 525 v=0 o=dave001 2029038238 0 IN IP4 99.99.118.91 s=- i=Dylogic Mirial 7.0.24 c=IN IP4 99.99.118.91 b=AS:512 t=0 0 m=audio 10364 RTP/AVP 0 101 a=rtpmap:0 PCMU/8000 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-16 a=x-mpdp:192.168.100.9:56428 m=video 10366 RTP/AVP 96 34 a=rtpmap:96 H263-1998/90000 a=fmtp:96 CIF=1; D=1; F=1; I=1; J=1; L=1; S=1; T=1 a=rtpmap:34 H263/90000 a=fmtp:34 CIF=1 a=x-mpdp:192.168.100.9:56430 m=application 10296 RTP/AVP 97 a=rtpmap:97 H224/4800 a=x-mpdp:192.168.100.9:56432 <-------------> [Jun 22 13:37:06] DEBUG[27843] chan_sip.c: Header 0 [ 47]: INVITE sip:311@99.99.63.208;user=phone SIP/2.0 [Jun 22 13:37:06] DEBUG[27843] chan_sip.c: Header 1 [ 38]: To: [Jun 22 13:37:06] DEBUG[27843] chan_sip.c: Header 2 [ 38]: Call-ID: DL0f837860f5-5572063@Dell4-PC [Jun 22 13:37:06] DEBUG[27843] chan_sip.c: Header 3 [ 85]: From: "dave 001" ;tag=DLda8f5d1c96;epid=02F57A80 [Jun 22 13:37:06] DEBUG[27843] chan_sip.c: Header 4 [ 14]: CSeq: 1 INVITE [Jun 22 13:37:06] DEBUG[27843] chan_sip.c: Header 5 [ 16]: Max-Forwards: 69 [Jun 22 13:37:06] DEBUG[27843] chan_sip.c: Header 6 [ 96]: Via: SIP/2.0/UDP 99.99.118.91:5060;rport;branch=z9hG4bK1494c5cbc020a51431b0b-c8619815-f6dcc727 [Jun 22 13:37:06] DEBUG[27843] chan_sip.c: Header 7 [ 88]: Via: SIP/2.0/UDP 192.168.100.9:5060;branch=z9hG4bK-cb85b1808b-DL;received=99.99.208.204 [Jun 22 13:37:06] DEBUG[27843] chan_sip.c: Header 8 [ 58]: Contact: "dave001" [Jun 22 13:37:06] DEBUG[27843] chan_sip.c: Header 9 [ 79]: Allow: INVITE,CANCEL,ACK,OPTIONS,INFO,SUBSCRIBE,NOTIFY,BYE,MESSAGE,UPDATE,REFER [Jun 22 13:37:06] DEBUG[27843] chan_sip.c: Header 10 [ 30]: Supported: replaces,norefersub [Jun 22 13:37:06] DEBUG[27843] chan_sip.c: Header 11 [ 33]: User-Agent: Dylogic Mirial 7.0.24 [Jun 22 13:37:06] DEBUG[27843] chan_sip.c: Header 12 [ 17]: P-Behind-NAT: Yes [Jun 22 13:37:06] DEBUG[27843] chan_sip.c: Header 13 [ 42]: Record-Route: [Jun 22 13:37:06] DEBUG[27843] chan_sip.c: Header 14 [ 29]: Content-Type: application/sdp [Jun 22 13:37:06] DEBUG[27843] chan_sip.c: Header 15 [ 19]: Content-Length: 525 [Jun 22 13:37:06] DEBUG[27843] chan_sip.c: Header 16 [ 0]: [Jun 22 13:37:06] DEBUG[27843] chan_sip.c: Body 0 [ 3]: v=0 [Jun 22 13:37:06] DEBUG[27843] chan_sip.c: Body 1 [ 47]: o=dave001 2029038238 0 IN IP4 99.99.118.91 [Jun 22 13:37:06] DEBUG[27843] chan_sip.c: Body 2 [ 3]: s=- [Jun 22 13:37:06] DEBUG[27843] chan_sip.c: Body 3 [ 23]: i=Dylogic Mirial 7.0.24 [Jun 22 13:37:06] DEBUG[27843] chan_sip.c: Body 4 [ 23]: c=IN IP4 99.99.118.91 [Jun 22 13:37:06] DEBUG[27843] chan_sip.c: Body 5 [ 8]: b=AS:512 [Jun 22 13:37:06] DEBUG[27843] chan_sip.c: Body 6 [ 5]: t=0 0 [Jun 22 13:37:06] DEBUG[27843] chan_sip.c: Body 7 [ 27]: m=audio 10364 RTP/AVP 0 101 [Jun 22 13:37:06] DEBUG[27843] chan_sip.c: Body 8 [ 20]: a=rtpmap:0 PCMU/8000 [Jun 22 13:37:06] DEBUG[27843] chan_sip.c: Body 9 [ 33]: a=rtpmap:101 telephone-event/8000 [Jun 22 13:37:06] DEBUG[27843] chan_sip.c: Body 10 [ 15]: a=fmtp:101 0-16 [Jun 22 13:37:06] DEBUG[27843] chan_sip.c: Body 11 [ 28]: a=x-mpdp:192.168.100.9:56428 [Jun 22 13:37:06] DEBUG[27843] chan_sip.c: Body 12 [ 27]: m=video 10366 RTP/AVP 96 34 [Jun 22 13:37:06] DEBUG[27843] chan_sip.c: Body 13 [ 27]: a=rtpmap:96 H263-1998/90000 [Jun 22 13:37:06] DEBUG[27843] chan_sip.c: Body 14 [ 50]: a=fmtp:96 CIF=1; D=1; F=1; I=1; J=1; L=1; S=1; T=1 [Jun 22 13:37:06] DEBUG[27843] chan_sip.c: Body 15 [ 22]: a=rtpmap:34 H263/90000 [Jun 22 13:37:06] DEBUG[27843] chan_sip.c: Body 16 [ 15]: a=fmtp:34 CIF=1 [Jun 22 13:37:06] DEBUG[27843] chan_sip.c: Body 17 [ 28]: a=x-mpdp:192.168.100.9:56430 [Jun 22 13:37:06] DEBUG[27843] chan_sip.c: Body 18 [ 30]: m=application 10296 RTP/AVP 97 [Jun 22 13:37:06] DEBUG[27843] chan_sip.c: Body 19 [ 21]: a=rtpmap:97 H224/4800 [Jun 22 13:37:06] DEBUG[27843] chan_sip.c: Body 20 [ 28]: a=x-mpdp:192.168.100.9:56432 [Jun 22 13:37:06] VERBOSE[27843] chan_sip.c: --- (16 headers 21 lines) --- [Jun 22 13:37:06] DEBUG[27843] acl.c: Found IP address for this socket [Jun 22 13:37:06] DEBUG[27843] chan_sip.c: Setting SIP_TRANSPORT_UDP with address 99.99.63.208:5060 [Jun 22 13:37:06] VERBOSE[27843] netsock.c: == Using SIP RTP CoS mark 5 [Jun 22 13:37:06] VERBOSE[27843] netsock.c: == Using SIP VRTP CoS mark 6 [Jun 22 13:37:06] DEBUG[27843] chan_sip.c: Setting NAT on RTP to Off [Jun 22 13:37:06] DEBUG[27843] chan_sip.c: Setting NAT on VRTP to Off [Jun 22 13:37:06] DEBUG[27843] chan_sip.c: Allocating new SIP dialog for DL0f837860f5-5572063@Dell4-PC - INVITE (With RTP) [Jun 22 13:37:06] DEBUG[27843] chan_sip.c: **** Received INVITE (5) - Command in SIP INVITE [Jun 22 13:37:06] DEBUG[27843] chan_sip.c: Begin: parsing SIP "Supported: replaces,norefersub" [Jun 22 13:37:06] DEBUG[27843] chan_sip.c: Found SIP option: -replaces- [Jun 22 13:37:06] DEBUG[27843] chan_sip.c: Matched SIP option: replaces [Jun 22 13:37:06] DEBUG[27843] chan_sip.c: Found SIP option: -norefersub- [Jun 22 13:37:06] DEBUG[27843] chan_sip.c: Matched SIP option: norefersub [Jun 22 13:37:06] VERBOSE[27843] chan_sip.c: Sending to 99.99.118.91 : 5060 (no NAT) [Jun 22 13:37:06] DEBUG[27843] chan_sip.c: Initializing initreq for method INVITE - callid DL0f837860f5-5572063@Dell4-PC [Jun 22 13:37:06] VERBOSE[27843] chan_sip.c: Using INVITE request as basis request - DL0f837860f5-5572063@Dell4-PC [Jun 22 13:37:06] VERBOSE[27843] chan_sip.c: No matching peer for 'dave001' from '99.99.49.125:5060' [Jun 22 13:37:06] DEBUG[27843] chan_sip.c: Processing session-level SDP v=0... UNSUPPORTED. [Jun 22 13:37:06] DEBUG[27843] chan_sip.c: Processing session-level SDP o=dave001 2029038238 0 IN IP4 99.99.118.91... UNSUPPORTED. [Jun 22 13:37:06] DEBUG[27843] chan_sip.c: Processing session-level SDP s=-... UNSUPPORTED. [Jun 22 13:37:06] DEBUG[27843] chan_sip.c: Processing session-level SDP i=Dylogic Mirial 7.0.24... UNSUPPORTED. [Jun 22 13:37:06] DEBUG[27843] chan_sip.c: Processing session-level SDP c=IN IP4 99.99.118.91... OK. [Jun 22 13:37:06] DEBUG[27843] chan_sip.c: Processing session-level SDP b=AS:512... UNSUPPORTED. [Jun 22 13:37:06] DEBUG[27843] chan_sip.c: Processing session-level SDP t=0 0... UNSUPPORTED. [Jun 22 13:37:06] VERBOSE[27843] chan_sip.c: Found RTP audio format 0 [Jun 22 13:37:06] VERBOSE[27843] chan_sip.c: Found RTP audio format 101 [Jun 22 13:37:06] VERBOSE[27843] chan_sip.c: Found audio description format PCMU for ID 0 [Jun 22 13:37:06] DEBUG[27843] chan_sip.c: Processing media-level (audio) SDP a=rtpmap:0 PCMU/8000... OK. [Jun 22 13:37:06] VERBOSE[27843] chan_sip.c: Found audio description format telephone-event for ID 101 [Jun 22 13:37:06] DEBUG[27843] chan_sip.c: Processing media-level (audio) SDP a=rtpmap:101 telephone-event/8000... OK. [Jun 22 13:37:06] DEBUG[27843] chan_sip.c: Processing media-level (audio) SDP a=fmtp:101 0-16... UNSUPPORTED. [Jun 22 13:37:06] DEBUG[27843] chan_sip.c: Processing media-level (audio) SDP a=x-mpdp:192.168.100.9:56428... UNSUPPORTED. [Jun 22 13:37:06] VERBOSE[27843] chan_sip.c: Found RTP video format 96 [Jun 22 13:37:06] VERBOSE[27843] chan_sip.c: Found RTP video format 34 [Jun 22 13:37:06] VERBOSE[27843] chan_sip.c: Found video description format H263-1998 for ID 96 [Jun 22 13:37:06] DEBUG[27843] chan_sip.c: Processing media-level (video) SDP a=rtpmap:96 H263-1998/90000... OK. [Jun 22 13:37:06] DEBUG[27843] chan_sip.c: Processing media-level (video) SDP a=fmtp:96 CIF=1; D=1; F=1; I=1; J=1; L=1; S=1; T=1... UNSUPPORTED. [Jun 22 13:37:06] VERBOSE[27843] chan_sip.c: Found video description format H263 for ID 34 [Jun 22 13:37:06] DEBUG[27843] chan_sip.c: Processing media-level (video) SDP a=rtpmap:34 H263/90000... OK. [Jun 22 13:37:06] DEBUG[27843] chan_sip.c: Processing media-level (video) SDP a=fmtp:34 CIF=1... UNSUPPORTED. [Jun 22 13:37:06] DEBUG[27843] chan_sip.c: Processing media-level (video) SDP a=x-mpdp:192.168.100.9:56430... UNSUPPORTED. [Jun 22 13:37:06] WARNING[27843] chan_sip.c: Unsupported SDP media type in offer: application 10296 RTP/AVP 97 [Jun 22 13:37:06] VERBOSE[27843] chan_sip.c: Capabilities: us - 0x80104 (ulaw|g729|h263), peer - audio=0x4 (ulaw)/video=0x180000 (h263|h263p)/text=0x0 (nothing), combined - 0x80004 (ulaw|h263) [Jun 22 13:37:06] VERBOSE[27843] chan_sip.c: Non-codec capabilities (dtmf): us - 0x1 (telephone-event), peer - 0x1 (telephone-event), combined - 0x1 (telephone-event) [Jun 22 13:37:06] VERBOSE[27843] chan_sip.c: Peer audio RTP is at port 99.99.118.91:10364 [Jun 22 13:37:06] VERBOSE[27843] chan_sip.c: Peer video RTP is at port 99.99.118.91:10366 [Jun 22 13:37:06] DEBUG[27843] chan_sip.c: We're settling with these formats: 0x80004 (ulaw|h263) [Jun 22 13:37:06] DEBUG[27843] chan_sip.c: Checking SIP call limits for device [Jun 22 13:37:06] DEBUG[27843] chan_sip.c: Updating call counter for incoming call [Jun 22 13:37:06] VERBOSE[27843] chan_sip.c: Looking for 311 in default (domain 99.99.63.208) [Jun 22 13:37:06] DEBUG[27843] chan_sip.c: *** Our native formats are 0x80004 (ulaw|h263) [Jun 22 13:37:06] DEBUG[27843] chan_sip.c: *** Joint capabilities are 0x80004 (ulaw|h263) [Jun 22 13:37:06] DEBUG[27843] chan_sip.c: *** Our capabilities are 0x80104 (ulaw|g729|h263) [Jun 22 13:37:06] DEBUG[27843] chan_sip.c: *** AST_CODEC_CHOOSE formats are 0x4 (ulaw) [Jun 22 13:37:06] DEBUG[27843] chan_sip.c: This channel can handle video! HOLLYWOOD next! [Jun 22 13:37:06] DEBUG[27843] chan_sip.c: build_route: Record-Route hop: [Jun 22 13:37:06] VERBOSE[27843] chan_sip.c: list_route: hop: [Jun 22 13:37:06] DEBUG[27843] chan_sip.c: SIP/sip.str.net-0000000d: New call is still down.... Trying... [Jun 22 13:37:06] VERBOSE[27843] chan_sip.c: <--- Transmitting (NAT) to 99.99.49.125:5060 ---> SIP/2.0 100 Trying Via: SIP/2.0/UDP 99.99.118.91:5060;branch=z9hG4bK1494c5cbc020a51431b0b-c8619815-f6dcc727;received=99.99.49.125;rport=5060 Via: SIP/2.0/UDP 192.168.100.9:5060;branch=z9hG4bK-cb85b1808b-DL;received=99.99.208.204 Record-Route: From: "dave 001" ;tag=DLda8f5d1c96;epid=02F57A80 To: Call-ID: DL0f837860f5-5572063@Dell4-PC CSeq: 1 INVITE Server: Asterisk PBX SVN-branch-1.6.2-r271555 Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO Supported: replaces, timer Contact: Content-Length: 0 <------------> [Jun 22 13:37:06] DEBUG[27843] chan_sip.c: Trying to put 'SIP/2.0 100' onto UDP socket destined for 99.99.49.125:5060 [Jun 22 13:37:06] DEBUG[27835] devicestate.c: No provider found, checking channel drivers for SIP - sip.str.net [Jun 22 13:37:06] DEBUG[27835] chan_sip.c: Checking device state for peer sip.str.net [Jun 22 13:37:06] DEBUG[27835] channel.c: Avoiding initial deadlock for channel '0x7f4054324f00' [Jun 22 13:37:06] DEBUG[30475] pbx.c: Launching 'NoOp' [Jun 22 13:37:06] VERBOSE[30475] pbx.c: -- Executing [311@default:1] NoOp("SIP/sip.str.net-0000000d", ""We got a call. Sending it to the queue"") in new stack [Jun 22 13:37:06] DEBUG[30475] pbx.c: Launching 'Answer' [Jun 22 13:37:06] VERBOSE[30475] pbx.c: -- Executing [311@default:2] Answer("SIP/sip.str.net-0000000d", "") in new stack [Jun 22 13:37:06] DEBUG[30475] chan_sip.c: SIP answering channel: SIP/sip.str.net-0000000d [Jun 22 13:37:06] DEBUG[30475] rtp.c: Setting the marker bit due to a source update [Jun 22 13:37:06] DEBUG[30475] chan_sip.c: Setting framing from config on incoming call [Jun 22 13:37:06] DEBUG[30475] chan_sip.c: This call needs video offers! [Jun 22 13:37:06] DEBUG[30475] chan_sip.c: ** Our capability: 0x80004 (ulaw|h263) Video flag: False Text flag: True [Jun 22 13:37:06] DEBUG[30475] chan_sip.c: ** Our prefcodec: 0x0 (nothing) [Jun 22 13:37:06] VERBOSE[30475] chan_sip.c: Audio is at 99.99.63.208 port 16042 [Jun 22 13:37:06] VERBOSE[30475] chan_sip.c: Video is at 99.99.63.208 port 14592 [Jun 22 13:37:06] VERBOSE[30475] chan_sip.c: Adding codec 0x4 (ulaw) to SDP [Jun 22 13:37:06] VERBOSE[30475] chan_sip.c: Adding video codec 0x80000 (h263) to SDP [Jun 22 13:37:06] VERBOSE[30475] chan_sip.c: Adding non-codec 0x1 (telephone-event) to SDP [Jun 22 13:37:06] DEBUG[30475] chan_sip.c: -- Done with adding codecs to SDP [Jun 22 13:37:06] DEBUG[30475] chan_sip.c: Done building SDP. Settling with this capability: 0x80004 (ulaw|h263) [Jun 22 13:37:06] VERBOSE[30475] chan_sip.c: <--- Reliably Transmitting (NAT) to 99.99.49.125:5060 ---> SIP/2.0 200 OK Via: SIP/2.0/UDP 99.99.118.91:5060;branch=z9hG4bK1494c5cbc020a51431b0b-c8619815-f6dcc727;received=99.99.49.125;rport=5060 Via: SIP/2.0/UDP 192.168.100.9:5060;branch=z9hG4bK-cb85b1808b-DL;received=99.99.208.204 Record-Route: From: "dave 001" ;tag=DLda8f5d1c96;epid=02F57A80 To: ;tag=as72fdb909 Call-ID: DL0f837860f5-5572063@Dell4-PC CSeq: 1 INVITE Server: Asterisk PBX SVN-branch-1.6.2-r271555 Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO Supported: replaces, timer Contact: Content-Type: application/sdp Content-Length: 354 v=0 o=root 1974018281 1974018281 IN IP4 99.99.63.208 s=Asterisk PBX SVN-branch-1.6.2-r271555 c=IN IP4 99.99.63.208 b=CT:384 t=0 0 m=audio 16042 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 m=video 14592 RTP/AVP 34 a=rtpmap:34 H263/90000 a=sendrecv <------------> [Jun 22 13:37:06] DEBUG[30475] chan_sip.c: *** SIP TIMER: Initializing retransmit timer on packet: Id #5940 [Jun 22 13:37:06] DEBUG[30475] chan_sip.c: Trying to put 'SIP/2.0 200' onto UDP socket destined for 99.99.49.125:5060 [Jun 22 13:37:06] DEBUG[27835] devicestate.c: Changing state for SIP/sip.str.net - state 2 (In use) [Jun 22 13:37:06] DEBUG[27835] devicestate.c: device 'SIP/sip.str.net' state '2' [Jun 22 13:37:06] DEBUG[27835] devicestate.c: No provider found, checking channel drivers for SIP - sip.str.net [Jun 22 13:37:06] DEBUG[27835] chan_sip.c: Checking device state for peer sip.str.net [Jun 22 13:37:06] DEBUG[27835] devicestate.c: Changing state for SIP/sip.str.net - state 2 (In use) [Jun 22 13:37:06] DEBUG[27835] devicestate.c: device 'SIP/sip.str.net' state '2' [Jun 22 13:37:06] DEBUG[27844] app_queue.c: Device 'SIP/sip.str.net' changed to state '2' (In use) but we don't care because they're not a member of any queue. [Jun 22 13:37:06] DEBUG[27844] app_queue.c: Device 'SIP/sip.str.net' changed to state '2' (In use) but we don't care because they're not a member of any queue. [Jun 22 13:37:07] DEBUG[30475] pbx.c: Launching 'Queue' [Jun 22 13:37:07] VERBOSE[30475] pbx.c: -- Executing [311@default:3] Queue("SIP/sip.str.net-0000000d", "callcenter") in new stack [Jun 22 13:37:07] DEBUG[30475] app_queue.c: NO QUEUE_PRIO variable found. Using default. [Jun 22 13:37:07] DEBUG[30475] app_queue.c: queue: callcenter, options: (null), url: (null), announce: (null), expires: 0, priority: 0 [Jun 22 13:37:07] DEBUG[30475] app_queue.c: Queue callcenter has no realtime members defined. No need for update [Jun 22 13:37:07] DEBUG[30475] app_queue.c: Queue 'callcenter' Join, Channel 'SIP/sip.str.net-0000000d', Position '1' [Jun 22 13:37:07] VERBOSE[30475] res_musiconhold.c: -- Started music on hold, class 'default', on SIP/sip.str.net-0000000d [Jun 22 13:37:07] DEBUG[30475] channel.c: Scheduling timer at (50 requested / 50 actual) timer ticks per second [Jun 22 13:37:07] DEBUG[30475] app_queue.c: There is 1 available member. [Jun 22 13:37:07] DEBUG[30475] app_queue.c: It's our turn (SIP/sip.str.net-0000000d). [Jun 22 13:37:07] DEBUG[30475] app_queue.c: SIP/sip.str.net-0000000d is trying to call a queue member. [Jun 22 13:37:07] DEBUG[30475] app_queue.c: Trying 'LOCAL/dave+f003@agents' with metric 1000 [Jun 22 13:37:07] DEBUG[30475] channel.c: Not copying variable SIPCALLID. [Jun 22 13:37:07] DEBUG[30475] channel.c: Not copying variable SIPDOMAIN. [Jun 22 13:37:07] DEBUG[30475] channel.c: Not copying variable SIPURI. [Jun 22 13:37:07] DEBUG[30475] devicestate.c: No provider found, checking channel drivers for LOCAL - dave+f003@agents [Jun 22 13:37:07] DEBUG[30475] chan_local.c: Checking if extension dave+f003@agents exists (devicestate) [Jun 22 13:37:07] DEBUG[30476] pbx.c: Launching 'NoOp' [Jun 22 13:37:07] VERBOSE[30476] pbx.c: -- Executing [dave+f003@agents:1] NoOp("Local/dave+f003@agents-73cf;2", ""New call for extension dave+f003"") in new stack [Jun 22 13:37:07] DEBUG[30476] pbx.c: Function result is 'f003' [Jun 22 13:37:07] DEBUG[30476] pbx.c: Launching 'Set' [Jun 22 13:37:07] VERBOSE[30476] pbx.c: -- Executing [dave+f003@agents:2] Set("Local/dave+f003@agents-73cf;2", "AGENTURI=f003") in new stack [Jun 22 13:37:07] DEBUG[30476] pbx.c: Function result is 'dave' [Jun 22 13:37:07] DEBUG[30476] pbx.c: Launching 'Set' [Jun 22 13:37:07] VERBOSE[30476] pbx.c: -- Executing [dave+f003@agents:3] Set("Local/dave+f003@agents-73cf;2", "AGENT=dave") in new stack [Jun 22 13:37:07] DEBUG[30476] pbx.c: Launching 'NoOp' [Jun 22 13:37:07] VERBOSE[30476] pbx.c: -- Executing [dave+f003@agents:4] NoOp("Local/dave+f003@agents-73cf;2", ""Calling agent dave at f003"") in new stack [Jun 22 13:37:07] DEBUG[30476] pbx.c: Launching 'Dial' [Jun 22 13:37:07] VERBOSE[30476] pbx.c: -- Executing [dave+f003@agents:5] Dial("Local/dave+f003@agents-73cf;2", "SIP/f003,45,G(conferences^dave^1)") in new stack [Jun 22 13:37:07] DEBUG[30476] chan_sip.c: Asked to create a SIP channel with formats: 0x80004 (ulaw|h263) [Jun 22 13:37:07] VERBOSE[30476] netsock.c: == Using SIP RTP CoS mark 5 [Jun 22 13:37:07] VERBOSE[30476] netsock.c: == Using SIP VRTP CoS mark 6 [Jun 22 13:37:07] DEBUG[30476] chan_sip.c: Allocating new SIP dialog for 4d94c6a05f36bd1f4c5a71da6c634004@99.99.104.95 - INVITE (With RTP) [Jun 22 13:37:07] DEBUG[30476] chan_sip.c: Setting NAT on RTP to On [Jun 22 13:37:07] DEBUG[30476] chan_sip.c: Setting NAT on VRTP to On [Jun 22 13:37:07] DEBUG[30476] chan_sip.c: OBPROXY: Not applying OBproxy to this call [Jun 22 13:37:07] DEBUG[30476] acl.c: Found IP address for this socket [Jun 22 13:37:07] DEBUG[30476] chan_sip.c: Setting SIP_TRANSPORT_UDP with address 99.99.104.95:5060 [Jun 22 13:37:07] DEBUG[30476] chan_sip.c: *** Our native formats are 0x80004 (ulaw|h263) [Jun 22 13:37:07] DEBUG[30476] chan_sip.c: *** Joint capabilities are 0x80004 (ulaw|h263) [Jun 22 13:37:07] DEBUG[30476] chan_sip.c: *** Our capabilities are 0x80104 (ulaw|g729|h263) [Jun 22 13:37:07] DEBUG[30476] chan_sip.c: *** AST_CODEC_CHOOSE formats are 0x4 (ulaw) [Jun 22 13:37:07] DEBUG[30476] chan_sip.c: *** Our preferred formats from the incoming channel are 0x80004 (ulaw|h263) [Jun 22 13:37:07] DEBUG[30476] chan_sip.c: This channel can handle video! HOLLYWOOD next! [Jun 22 13:37:07] DEBUG[30476] rtp.c: Channel 'Local/dave+f003@agents-73cf;2' has no RTP, not doing anything [Jun 22 13:37:07] DEBUG[30476] channel.c: Not copying variable DIALEDTIME. [Jun 22 13:37:07] DEBUG[30476] channel.c: Not copying variable ANSWEREDTIME. [Jun 22 13:37:07] DEBUG[30476] channel.c: Not copying variable DIALEDPEERNAME. [Jun 22 13:37:07] DEBUG[30476] channel.c: Not copying variable DIALEDPEERNUMBER. [Jun 22 13:37:07] DEBUG[30476] channel.c: Not copying variable DIALSTATUS. [Jun 22 13:37:07] DEBUG[30476] channel.c: Not copying variable AGENT. [Jun 22 13:37:07] DEBUG[30476] channel.c: Not copying variable AGENTURI. [Jun 22 13:37:07] DEBUG[30476] chan_sip.c: Outgoing Call for f003 [Jun 22 13:37:07] DEBUG[30476] chan_sip.c: Updating call counter for outgoing call [Jun 22 13:37:07] DEBUG[30476] chan_sip.c: Call to peer 'f003' is 1 out of 2147483647 [Jun 22 13:37:07] DEBUG[27835] devicestate.c: No provider found, checking channel drivers for SIP - f003 [Jun 22 13:37:07] DEBUG[27835] chan_sip.c: Checking device state for peer f003 [Jun 22 13:37:07] DEBUG[27835] devicestate.c: Changing state for SIP/f003 - state 6 (Ringing) [Jun 22 13:37:07] DEBUG[27835] devicestate.c: device 'SIP/f003' state '6' [Jun 22 13:37:07] DEBUG[30476] chan_sip.c: This call needs video offers! [Jun 22 13:37:07] DEBUG[27844] app_queue.c: Device 'SIP/f003' changed to state '6' (Ringing) but we don't care because they're not a member of any queue. [Jun 22 13:37:07] DEBUG[30476] chan_sip.c: ** Our capability: 0x80004 (ulaw|h263) Video flag: False Text flag: False [Jun 22 13:37:07] DEBUG[30476] chan_sip.c: ** Our prefcodec: 0x80004 (ulaw|h263) [Jun 22 13:37:07] VERBOSE[30476] chan_sip.c: Audio is at 99.99.104.95 port 11400 [Jun 22 13:37:07] VERBOSE[30476] chan_sip.c: Video is at 99.99.104.95 port 12860 [Jun 22 13:37:07] VERBOSE[30476] chan_sip.c: Adding codec 0x4 (ulaw) to SDP [Jun 22 13:37:07] VERBOSE[30476] chan_sip.c: Adding video codec 0x80000 (h263) to SDP [Jun 22 13:37:07] VERBOSE[30476] chan_sip.c: Adding non-codec 0x1 (telephone-event) to SDP [Jun 22 13:37:07] DEBUG[30476] chan_sip.c: -- Done with adding codecs to SDP [Jun 22 13:37:07] DEBUG[30476] chan_sip.c: Done building SDP. Settling with this capability: 0x80004 (ulaw|h263) [Jun 22 13:37:07] DEBUG[30476] chan_sip.c: Initializing initreq for method INVITE - callid 47177042333abb710c1956cd794aba46@99.99.104.95 [Jun 22 13:37:07] DEBUG[30476] chan_sip.c: Header 0 [ 43]: INVITE sip:f003@192.168.100.19:5060 SIP/2.0 [Jun 22 13:37:07] DEBUG[30476] chan_sip.c: Header 1 [ 65]: Via: SIP/2.0/UDP 99.99.104.95:5060;branch=z9hG4bK446227b7;rport [Jun 22 13:37:07] DEBUG[30476] chan_sip.c: Header 2 [ 16]: Max-Forwards: 70 [Jun 22 13:37:07] DEBUG[30476] chan_sip.c: Header 3 [ 66]: From: "dave 001" ;tag=as42d6fd99 [Jun 22 13:37:07] DEBUG[30476] chan_sip.c: Header 4 [ 34]: To: [Jun 22 13:37:07] DEBUG[30476] chan_sip.c: Header 5 [ 40]: Contact: [Jun 22 13:37:07] DEBUG[30476] chan_sip.c: Header 6 [ 56]: Call-ID: 47177042333abb710c1956cd794aba46@99.99.104.95 [Jun 22 13:37:07] DEBUG[30476] chan_sip.c: Header 7 [ 16]: CSeq: 102 INVITE [Jun 22 13:37:07] DEBUG[30476] chan_sip.c: Header 8 [ 49]: User-Agent: Asterisk PBX SVN-branch-1.6.2-r271555 [Jun 22 13:37:07] DEBUG[30476] chan_sip.c: Header 9 [ 35]: Date: Tue, 22 Jun 2010 13:37:07 GMT [Jun 22 13:37:07] DEBUG[30476] chan_sip.c: Header 10 [ 72]: Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO [Jun 22 13:37:07] DEBUG[30476] chan_sip.c: Header 11 [ 26]: Supported: replaces, timer [Jun 22 13:37:07] DEBUG[30476] chan_sip.c: Header 12 [ 29]: Content-Type: application/sdp [Jun 22 13:37:07] DEBUG[30476] chan_sip.c: Header 13 [ 19]: Content-Length: 356 [Jun 22 13:37:07] DEBUG[30476] chan_sip.c: Header 14 [ 0]: [Jun 22 13:37:07] DEBUG[30476] chan_sip.c: Body 0 [ 3]: v=0 [Jun 22 13:37:07] DEBUG[30476] chan_sip.c: Body 1 [ 50]: o=root 1972317852 1972317852 IN IP4 99.99.104.95 [Jun 22 13:37:07] DEBUG[30476] chan_sip.c: Body 2 [ 39]: s=Asterisk PBX SVN-branch-1.6.2-r271555 [Jun 22 13:37:07] DEBUG[30476] chan_sip.c: Body 3 [ 23]: c=IN IP4 99.99.104.95 [Jun 22 13:37:07] DEBUG[30476] chan_sip.c: Body 4 [ 8]: b=CT:512 [Jun 22 13:37:07] DEBUG[30476] chan_sip.c: Body 5 [ 5]: t=0 0 [Jun 22 13:37:07] DEBUG[30476] chan_sip.c: Body 6 [ 27]: m=audio 11400 RTP/AVP 0 101 [Jun 22 13:37:07] DEBUG[30476] chan_sip.c: Body 7 [ 20]: a=rtpmap:0 PCMU/8000 [Jun 22 13:37:07] DEBUG[30476] chan_sip.c: Body 8 [ 33]: a=rtpmap:101 telephone-event/8000 [Jun 22 13:37:07] DEBUG[30476] chan_sip.c: Body 9 [ 15]: a=fmtp:101 0-16 [Jun 22 13:37:07] DEBUG[30476] chan_sip.c: Body 10 [ 25]: a=silenceSupp:off - - - - [Jun 22 13:37:07] DEBUG[30476] chan_sip.c: Body 11 [ 10]: a=ptime:20 [Jun 22 13:37:07] DEBUG[30476] chan_sip.c: Body 12 [ 10]: a=sendrecv [Jun 22 13:37:07] DEBUG[30476] chan_sip.c: Body 13 [ 24]: m=video 12860 RTP/AVP 34 [Jun 22 13:37:07] DEBUG[30476] chan_sip.c: Body 14 [ 22]: a=rtpmap:34 H263/90000 [Jun 22 13:37:07] DEBUG[30476] chan_sip.c: Body 15 [ 10]: a=sendrecv [Jun 22 13:37:07] VERBOSE[30476] chan_sip.c: Reliably Transmitting (NAT) to 99.99.208.204:41156: INVITE sip:f003@192.168.100.19:5060 SIP/2.0 Via: SIP/2.0/UDP 99.99.104.95:5060;branch=z9hG4bK446227b7;rport Max-Forwards: 70 From: "dave 001" ;tag=as42d6fd99 To: Contact: Call-ID: 47177042333abb710c1956cd794aba46@99.99.104.95 CSeq: 102 INVITE User-Agent: Asterisk PBX SVN-branch-1.6.2-r271555 Date: Tue, 22 Jun 2010 13:37:07 GMT Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO Supported: replaces, timer Content-Type: application/sdp Content-Length: 356 v=0 o=root 1972317852 1972317852 IN IP4 99.99.104.95 s=Asterisk PBX SVN-branch-1.6.2-r271555 c=IN IP4 99.99.104.95 b=CT:512 t=0 0 m=audio 11400 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 m=video 12860 RTP/AVP 34 a=rtpmap:34 H263/90000 a=sendrecv --- [Jun 22 13:37:07] DEBUG[30476] chan_sip.c: *** SIP TIMER: Initializing retransmit timer on packet: Id #5942 [Jun 22 13:37:07] DEBUG[30476] chan_sip.c: Trying to put 'INVITE sip:' onto UDP socket destined for 99.99.208.204:41156 [Jun 22 13:37:07] VERBOSE[30476] app_dial.c: -- Called f003 [Jun 22 13:37:07] DEBUG[30475] channel.c: Generator got voice, switching to phase locked mode [Jun 22 13:37:07] DEBUG[30475] channel.c: Scheduling timer at (0 requested / 0 actual) timer ticks per second [Jun 22 13:37:07] DEBUG[30475] res_musiconhold.c: SIP/sip.str.net-0000000d Opened file 0 '/var/lib/asterisk/moh/manolo_camp-morning_coffee' [Jun 22 13:37:07] DEBUG[30475] rtp.c: Ooh, format changed from unknown to ulaw [Jun 22 13:37:07] DEBUG[30475] rtp.c: Created smoother: format: 4 ms: 20 len: 160 [Jun 22 13:37:07] VERBOSE[27843] chan_sip.c: <--- SIP read from UDP:99.99.49.125:5060 ---> ACK sip:311@99.99.63.208 SIP/2.0 CSeq: 1 ACK Via: SIP/2.0/UDP 99.99.118.91:5060;rport;branch=z9hG4bK9de9c03e87a1351431b0b-c8619815-2a8eb666 Via: SIP/2.0/UDP 192.168.100.9:5060;branch=z9hG4bK-6fcadb70e1-DL;received=99.99.208.204 To: ;tag=as72fdb909 From: "dave001" ;tag=DLda8f5d1c96;epid=02F57A80 Call-ID: DL0f837860f5-5572063@Dell4-PC Max-Forwards: 69 Contact: "dave001" P-Behind-NAT: Yes Record-Route: Content-Length: 0 <-------------> [Jun 22 13:37:07] DEBUG[27843] chan_sip.c: Header 0 [ 33]: ACK sip:311@99.99.63.208 SIP/2.0 [Jun 22 13:37:07] DEBUG[27843] chan_sip.c: Header 1 [ 11]: CSeq: 1 ACK [Jun 22 13:37:07] DEBUG[27843] chan_sip.c: Header 2 [ 96]: Via: SIP/2.0/UDP 99.99.118.91:5060;rport;branch=z9hG4bK9de9c03e87a1351431b0b-c8619815-2a8eb666 [Jun 22 13:37:07] DEBUG[27843] chan_sip.c: Header 3 [ 88]: Via: SIP/2.0/UDP 192.168.100.9:5060;branch=z9hG4bK-6fcadb70e1-DL;received=99.99.208.204 [Jun 22 13:37:07] DEBUG[27843] chan_sip.c: Header 4 [ 53]: To: ;tag=as72fdb909 [Jun 22 13:37:07] DEBUG[27843] chan_sip.c: Header 5 [ 84]: From: "dave001" ;tag=DLda8f5d1c96;epid=02F57A80 [Jun 22 13:37:07] DEBUG[27843] chan_sip.c: Header 6 [ 38]: Call-ID: DL0f837860f5-5572063@Dell4-PC [Jun 22 13:37:07] DEBUG[27843] chan_sip.c: Header 7 [ 16]: Max-Forwards: 69 [Jun 22 13:37:07] DEBUG[27843] chan_sip.c: Header 8 [ 58]: Contact: "dave001" [Jun 22 13:37:07] DEBUG[27843] chan_sip.c: Header 9 [ 17]: P-Behind-NAT: Yes [Jun 22 13:37:07] DEBUG[27843] chan_sip.c: Header 10 [ 42]: Record-Route: [Jun 22 13:37:07] DEBUG[27843] chan_sip.c: Header 11 [ 17]: Content-Length: 0 [Jun 22 13:37:07] DEBUG[27843] chan_sip.c: Header 12 [ 0]: [Jun 22 13:37:07] VERBOSE[27843] chan_sip.c: --- (12 headers 0 lines) --- [Jun 22 13:37:07] DEBUG[27843] chan_sip.c: **** Received ACK (6) - Command in SIP ACK [Jun 22 13:37:07] DEBUG[27843] chan_sip.c: ** SIP TIMER: Cancelling retransmit of packet (reply received) Retransid #5940 [Jun 22 13:37:07] DEBUG[27843] chan_sip.c: Stopping retransmission on 'DL0f837860f5-5572063@Dell4-PC' of Response 1: Match Found [Jun 22 13:37:07] VERBOSE[27843] chan_sip.c: <--- SIP read from UDP:99.99.208.204:41156 ---> SIP/2.0 100 TRYING From: "dave 001" ;tag=as42d6fd99;epid=0x4b70530 Call-ID: 47177042333abb710c1956cd794aba46@99.99.104.95 CSeq: 102 INVITE Via: SIP/2.0/UDP 99.99.104.95:5060;branch=z9hG4bK446227b7;rport=5060;received=99.99.104.95 To: ;tag=DL48aab446f7 Allow: INVITE,CANCEL,ACK,OPTIONS,INFO,SUBSCRIBE,NOTIFY,BYE,MESSAGE,UPDATE,REFER Contact: "f003" User-Agent: Dylogic Mirial 7.0.23 Content-Length: 0 <-------------> [Jun 22 13:37:07] DEBUG[27843] chan_sip.c: Header 0 [ 18]: SIP/2.0 100 TRYING [Jun 22 13:37:07] DEBUG[27843] chan_sip.c: Header 1 [ 81]: From: "dave 001" ;tag=as42d6fd99;epid=0x4b70530 [Jun 22 13:37:07] DEBUG[27843] chan_sip.c: Header 2 [ 56]: Call-ID: 47177042333abb710c1956cd794aba46@99.99.104.95 [Jun 22 13:37:07] DEBUG[27843] chan_sip.c: Header 3 [ 16]: CSeq: 102 INVITE [Jun 22 13:37:07] DEBUG[27843] chan_sip.c: Header 4 [ 94]: Via: SIP/2.0/UDP 99.99.104.95:5060;branch=z9hG4bK446227b7;rport=5060;received=99.99.104.95 [Jun 22 13:37:07] DEBUG[27843] chan_sip.c: Header 5 [ 51]: To: ;tag=DL48aab446f7 [Jun 22 13:37:07] DEBUG[27843] chan_sip.c: Header 6 [ 79]: Allow: INVITE,CANCEL,ACK,OPTIONS,INFO,SUBSCRIBE,NOTIFY,BYE,MESSAGE,UPDATE,REFER [Jun 22 13:37:07] DEBUG[27843] chan_sip.c: Header 7 [ 46]: Contact: "f003" [Jun 22 13:37:07] DEBUG[27843] chan_sip.c: Header 8 [ 33]: User-Agent: Dylogic Mirial 7.0.23 [Jun 22 13:37:07] DEBUG[27843] chan_sip.c: Header 9 [ 17]: Content-Length: 0 [Jun 22 13:37:07] DEBUG[27843] chan_sip.c: Header 10 [ 0]: [Jun 22 13:37:07] VERBOSE[27843] chan_sip.c: --- (10 headers 0 lines) --- [Jun 22 13:37:07] DEBUG[27843] chan_sip.c: *** SIP TIMER: Cancelling retransmission #5942 - INVITE (got response) [Jun 22 13:37:07] DEBUG[27843] chan_sip.c: (Provisional) Stopping retransmission (but retaining packet) on '47177042333abb710c1956cd794aba46@99.99.104.95' Request 102: Found [Jun 22 13:37:07] DEBUG[27843] chan_sip.c: SIP response 100 to standard invite [Jun 22 13:37:07] VERBOSE[27843] chan_sip.c: <--- SIP read from UDP:99.99.208.204:41156 ---> SIP/2.0 180 RINGING From: "dave 001" ;tag=as42d6fd99;epid=0x4b70530 Call-ID: 47177042333abb710c1956cd794aba46@99.99.104.95 CSeq: 102 INVITE Via: SIP/2.0/UDP 99.99.104.95:5060;branch=z9hG4bK446227b7;rport=5060;received=99.99.104.95 To: ;tag=DL48aab446f7 Contact: "f003" Allow: INVITE,CANCEL,ACK,OPTIONS,INFO,SUBSCRIBE,NOTIFY,BYE,MESSAGE,UPDATE,REFER User-Agent: Dylogic Mirial 7.0.23 Content-Length: 0 <-------------> [Jun 22 13:37:07] DEBUG[27843] chan_sip.c: Header 0 [ 19]: SIP/2.0 180 RINGING [Jun 22 13:37:07] DEBUG[27843] chan_sip.c: Header 1 [ 81]: From: "dave 001" ;tag=as42d6fd99;epid=0x4b70530 [Jun 22 13:37:07] DEBUG[27843] chan_sip.c: Header 2 [ 56]: Call-ID: 47177042333abb710c1956cd794aba46@99.99.104.95 [Jun 22 13:37:07] DEBUG[27843] chan_sip.c: Header 3 [ 16]: CSeq: 102 INVITE [Jun 22 13:37:07] DEBUG[27843] chan_sip.c: Header 4 [ 94]: Via: SIP/2.0/UDP 99.99.104.95:5060;branch=z9hG4bK446227b7;rport=5060;received=99.99.104.95 [Jun 22 13:37:07] DEBUG[27843] chan_sip.c: Header 5 [ 51]: To: ;tag=DL48aab446f7 [Jun 22 13:37:07] DEBUG[27843] chan_sip.c: Header 6 [ 46]: Contact: "f003" [Jun 22 13:37:07] DEBUG[27843] chan_sip.c: Header 7 [ 79]: Allow: INVITE,CANCEL,ACK,OPTIONS,INFO,SUBSCRIBE,NOTIFY,BYE,MESSAGE,UPDATE,REFER [Jun 22 13:37:07] DEBUG[27843] chan_sip.c: Header 8 [ 33]: User-Agent: Dylogic Mirial 7.0.23 [Jun 22 13:37:07] DEBUG[27843] chan_sip.c: Header 9 [ 17]: Content-Length: 0 [Jun 22 13:37:07] DEBUG[27843] chan_sip.c: Header 10 [ 0]: [Jun 22 13:37:07] VERBOSE[27843] chan_sip.c: --- (10 headers 0 lines) --- [Jun 22 13:37:07] DEBUG[27843] chan_sip.c: (Provisional) Stopping retransmission (but retaining packet) on '47177042333abb710c1956cd794aba46@99.99.104.95' Request 102: Found [Jun 22 13:37:07] DEBUG[27843] chan_sip.c: SIP response 180 to standard invite [Jun 22 13:37:07] DEBUG[27835] devicestate.c: No provider found, checking channel drivers for SIP - f003 [Jun 22 13:37:07] DEBUG[27835] chan_sip.c: Checking device state for peer f003 [Jun 22 13:37:07] DEBUG[27835] devicestate.c: Changing state for SIP/f003 - state 6 (Ringing) [Jun 22 13:37:07] DEBUG[27835] devicestate.c: device 'SIP/f003' state '6' [Jun 22 13:37:07] DEBUG[27844] app_queue.c: Device 'SIP/f003' changed to state '6' (Ringing) but we don't care because they're not a member of any queue. [Jun 22 13:37:07] VERBOSE[30476] app_dial.c: -- SIP/f003-0000000e is ringing [Jun 22 13:37:07] DEBUG[27835] devicestate.c: No provider found, checking channel drivers for Local - dave+f003@agents [Jun 22 13:37:07] DEBUG[27835] chan_local.c: Checking if extension dave+f003@agents exists (devicestate) [Jun 22 13:37:07] DEBUG[27835] devicestate.c: Changing state for Local/dave+f003@agents - state 2 (In use) [Jun 22 13:37:07] DEBUG[27835] devicestate.c: device 'Local/dave+f003@agents' state '2' [Jun 22 13:37:07] DEBUG[27844] app_queue.c: Device 'Local/dave+f003@agents' changed to state '2' (In use) [Jun 22 13:37:07] VERBOSE[30475] app_queue.c: -- Local/dave+f003@agents-73cf;1 is ringing [Jun 22 13:37:10] DEBUG[27843] chan_sip.c: Auto destroying SIP dialog '1616fdc1-e76e0645-3ac0244@70.167.153.136' [Jun 22 13:37:10] DEBUG[27843] chan_sip.c: Destroying SIP dialog 1616fdc1-e76e0645-3ac0244@70.167.153.136 [Jun 22 13:37:10] VERBOSE[27843] chan_sip.c: Really destroying SIP dialog '1616fdc1-e76e0645-3ac0244@70.167.153.136' Method: OPTIONS [Jun 22 13:37:11] DEBUG[27843] chan_sip.c: Auto destroying SIP dialog '707b1a1-87002db5-229ee@216.115.69.131' [Jun 22 13:37:11] DEBUG[27843] chan_sip.c: Destroying SIP dialog 707b1a1-87002db5-229ee@216.115.69.131 [Jun 22 13:37:11] VERBOSE[27843] chan_sip.c: Really destroying SIP dialog '707b1a1-87002db5-229ee@216.115.69.131' Method: OPTIONS [Jun 22 13:37:14] DEBUG[27845] channel.c: Soft-Hanging up channel 'SIP/f003-0000000e' [Jun 22 13:37:14] DEBUG[27845] channel.c: Soft-Hanging up channel 'Local/dave+f003@agents-73cf;2' [Jun 22 13:37:14] DEBUG[27845] channel.c: Soft-Hanging up channel 'Local/dave+f003@agents-73cf;1' [Jun 22 13:37:14] DEBUG[27845] channel.c: Soft-Hanging up channel 'SIP/sip.str.net-0000000d' [Jun 22 13:37:14] VERBOSE[27845] asterisk.c: Beginning asterisk shutdown.... [Jun 22 13:37:14] VERBOSE[30475] res_musiconhold.c: -- Stopped music on hold on SIP/sip.str.net-0000000d [Jun 22 13:37:14] DEBUG[30475] channel.c: Scheduling timer at (0 requested / 0 actual) timer ticks per second [Jun 22 13:37:14] DEBUG[30475] app_queue.c: SIP/sip.str.net-0000000d: Nobody answered. [Jun 22 13:37:14] DEBUG[30475] channel.c: Hanging up channel 'Local/dave+f003@agents-73cf;1' [Jun 22 13:37:14] DEBUG[30475] cdr.c: Dropping CDR ! [Jun 22 13:37:14] DEBUG[27835] devicestate.c: No provider found, checking channel drivers for Local - dave+f003@agents [Jun 22 13:37:14] DEBUG[27835] chan_local.c: Checking if extension dave+f003@agents exists (devicestate) [Jun 22 13:37:14] DEBUG[27835] devicestate.c: Changing state for Local/dave+f003@agents - state 1 (Not in use) [Jun 22 13:37:14] DEBUG[27835] devicestate.c: device 'Local/dave+f003@agents' state '1' [Jun 22 13:37:14] DEBUG[27844] app_queue.c: Device 'Local/dave+f003@agents' changed to state '1' (Not in use) [Jun 22 13:37:14] DEBUG[30475] app_queue.c: Queue 'callcenter' Leave, Channel 'SIP/sip.str.net-0000000d' [Jun 22 13:37:14] DEBUG[30475] pbx.c: Spawn extension (default,311,3) exited non-zero on 'SIP/sip.str.net-0000000d' [Jun 22 13:37:14] VERBOSE[30475] pbx.c: == Spawn extension (default, 311, 3) exited non-zero on 'SIP/sip.str.net-0000000d' [Jun 22 13:37:14] DEBUG[30475] channel.c: Soft-Hanging up channel 'SIP/sip.str.net-0000000d' [Jun 22 13:37:14] DEBUG[30475] pbx.c: Launching 'NoOp' [Jun 22 13:37:14] VERBOSE[30475] pbx.c: -- Executing [h@default:1] NoOp("SIP/sip.str.net-0000000d", ""Hanging up now..."") in new stack [Jun 22 13:37:14] DEBUG[30475] pbx.c: Launching 'Hangup' [Jun 22 13:37:14] VERBOSE[30475] pbx.c: -- Executing [h@default:2] Hangup("SIP/sip.str.net-0000000d", "") in new stack [Jun 22 13:37:14] DEBUG[30475] pbx.c: Spawn extension (default,h,2) exited non-zero on 'SIP/sip.str.net-0000000d' [Jun 22 13:37:14] VERBOSE[30475] pbx.c: == Spawn extension (default, h, 2) exited non-zero on 'SIP/sip.str.net-0000000d' [Jun 22 13:37:14] DEBUG[30475] channel.c: Hanging up channel 'SIP/sip.str.net-0000000d' [Jun 22 13:37:14] DEBUG[30475] chan_sip.c: Hangup call SIP/sip.str.net-0000000d, SIP callid DL0f837860f5-5572063@Dell4-PC [Jun 22 13:37:14] VERBOSE[30475] chan_sip.c: Scheduling destruction of SIP dialog 'DL0f837860f5-5572063@Dell4-PC' in 32000 ms (Method: ACK) [Jun 22 13:37:14] VERBOSE[30475] chan_sip.c: set_destination: Parsing for address/port to send to [Jun 22 13:37:14] VERBOSE[30475] chan_sip.c: set_destination: set destination to 99.99.118.91, port 5060 [Jun 22 13:37:14] VERBOSE[30475] chan_sip.c: Reliably Transmitting (NAT) to 99.99.49.125:5060: BYE sip:dave001@99.99.118.91:5060 SIP/2.0 Via: SIP/2.0/UDP 99.99.63.208:5060;branch=z9hG4bK6bf2f935;rport Route: Max-Forwards: 70 From: ;tag=as72fdb909 To: "dave 001" ;tag=DLda8f5d1c96;epid=02F57A80 Call-ID: DL0f837860f5-5572063@Dell4-PC CSeq: 102 BYE User-Agent: Asterisk PBX SVN-branch-1.6.2-r271555 X-Asterisk-HangupCause: Normal Clearing X-Asterisk-HangupCauseCode: 16 Content-Length: 0 --- [Jun 22 13:37:14] DEBUG[30475] chan_sip.c: *** SIP TIMER: Initializing retransmit timer on packet: Id #5946 [Jun 22 13:37:14] DEBUG[30475] chan_sip.c: Trying to put 'BYE sip:cla' onto UDP socket destined for 99.99.49.125:5060 [Jun 22 13:37:14] DEBUG[30475] cdr.c: Dropping CDR ! [Jun 22 13:37:14] DEBUG[27835] devicestate.c: No provider found, checking channel drivers for SIP - sip.str.net [Jun 22 13:37:14] DEBUG[27835] chan_sip.c: Checking device state for peer sip.str.net [Jun 22 13:37:14] DEBUG[27835] devicestate.c: Changing state for SIP/sip.str.net - state 0 (Unknown) [Jun 22 13:37:14] DEBUG[27835] devicestate.c: device 'SIP/sip.str.net' state '0' [Jun 22 13:37:14] DEBUG[27844] app_queue.c: Device 'SIP/sip.str.net' changed to state '0' (Unknown) but we don't care because they're not a member of any queue. [Jun 22 13:37:14] DEBUG[30476] channel.c: Hanging up channel 'SIP/f003-0000000e' [Jun 22 13:37:14] DEBUG[30476] chan_sip.c: Hangup call SIP/f003-0000000e, SIP callid 47177042333abb710c1956cd794aba46@99.99.104.95 [Jun 22 13:37:14] DEBUG[30476] chan_sip.c: update_call_counter(f003) - decrement call limit counter on hangup [Jun 22 13:37:14] DEBUG[30476] chan_sip.c: Updating call counter for outgoing call [Jun 22 13:37:14] DEBUG[30476] chan_sip.c: Call to peer 'f003' removed from call limit 2147483647 [Jun 22 13:37:14] DEBUG[30476] chan_sip.c: Hanging up channel in state Ringing (not UP) [Jun 22 13:37:14] VERBOSE[30476] chan_sip.c: Scheduling destruction of SIP dialog '47177042333abb710c1956cd794aba46@99.99.104.95' in 6400 ms (Method: INVITE) [Jun 22 13:37:14] DEBUG[30476] chan_sip.c: (Provisional) Stopping retransmission (but retaining packet) on '47177042333abb710c1956cd794aba46@99.99.104.95' Request 102: Found [Jun 22 13:37:14] VERBOSE[30476] chan_sip.c: Reliably Transmitting (NAT) to 99.99.208.204:41156: CANCEL sip:f003@192.168.100.19:5060 SIP/2.0 Via: SIP/2.0/UDP 99.99.104.95:5060;branch=z9hG4bK446227b7;rport Max-Forwards: 70 From: "dave 001" ;tag=as42d6fd99 To: Call-ID: 47177042333abb710c1956cd794aba46@99.99.104.95 CSeq: 102 CANCEL User-Agent: Asterisk PBX SVN-branch-1.6.2-r271555 Content-Length: 0 --- [Jun 22 13:37:14] DEBUG[30476] chan_sip.c: *** SIP TIMER: Initializing retransmit timer on packet: Id #5948 [Jun 22 13:37:14] DEBUG[30476] chan_sip.c: Trying to put 'CANCEL sip:' onto UDP socket destined for 99.99.208.204:41156 [Jun 22 13:37:14] VERBOSE[30476] chan_sip.c: Scheduling destruction of SIP dialog '47177042333abb710c1956cd794aba46@99.99.104.95' in 6400 ms (Method: INVITE) [Jun 22 13:37:14] DEBUG[30476] cdr.c: Dropping CDR ! [Jun 22 13:37:14] VERBOSE[30476] app_dial.c: -- No one is available to answer at this time (1:0/0/0) [Jun 22 13:37:14] DEBUG[30476] app_dial.c: Exiting with DIALSTATUS=NOANSWER. [Jun 22 13:37:14] DEBUG[30476] pbx.c: Extension dave+f003, priority 5 returned normally even though call was hung up [Jun 22 13:37:14] DEBUG[30476] channel.c: Soft-Hanging up channel 'Local/dave+f003@agents-73cf;2' [Jun 22 13:37:14] DEBUG[30476] pbx.c: Launching 'NoOp' [Jun 22 13:37:14] VERBOSE[30476] pbx.c: -- Executing [h@agents:1] NoOp("Local/dave+f003@agents-73cf;2", ""Hanging up now..."") in new stack [Jun 22 13:37:14] DEBUG[27835] devicestate.c: No provider found, checking channel drivers for SIP - f003 [Jun 22 13:37:14] DEBUG[27835] chan_sip.c: Checking device state for peer f003 [Jun 22 13:37:14] DEBUG[27835] devicestate.c: Changing state for SIP/f003 - state 1 (Not in use) [Jun 22 13:37:14] DEBUG[30476] pbx.c: Launching 'Hangup' [Jun 22 13:37:14] DEBUG[27835] devicestate.c: device 'SIP/f003' state '1' [Jun 22 13:37:14] VERBOSE[30476] pbx.c: -- Executing [h@agents:2] Hangup("Local/dave+f003@agents-73cf;2", "") in new stack [Jun 22 13:37:14] DEBUG[27835] devicestate.c: No provider found, checking channel drivers for SIP - f003 [Jun 22 13:37:14] DEBUG[27835] chan_sip.c: Checking device state for peer f003 [Jun 22 13:37:14] DEBUG[27835] devicestate.c: Changing state for SIP/f003 - state 1 (Not in use) [Jun 22 13:37:14] DEBUG[30476] pbx.c: Spawn extension (agents,h,2) exited non-zero on 'Local/dave+f003@agents-73cf;2' [Jun 22 13:37:14] DEBUG[27835] devicestate.c: device 'SIP/f003' state '1' [Jun 22 13:37:14] VERBOSE[30476] pbx.c: == Spawn extension (agents, h, 2) exited non-zero on 'Local/dave+f003@agents-73cf;2' [Jun 22 13:37:14] DEBUG[30476] channel.c: Hanging up channel 'Local/dave+f003@agents-73cf;2' [Jun 22 13:37:14] DEBUG[27844] app_queue.c: Device 'SIP/f003' changed to state '1' (Not in use) but we don't care because they're not a member of any queue. [Jun 22 13:37:14] DEBUG[30476] cdr.c: Dropping CDR ! [Jun 22 13:37:14] DEBUG[27844] app_queue.c: Device 'SIP/f003' changed to state '1' (Not in use) but we don't care because they're not a member of any queue. [Jun 22 13:37:14] DEBUG[27835] devicestate.c: No provider found, checking channel drivers for Local - dave+f003@agents [Jun 22 13:37:14] DEBUG[27835] chan_local.c: Checking if extension dave+f003@agents exists (devicestate) [Jun 22 13:37:14] DEBUG[27835] devicestate.c: Changing state for Local/dave+f003@agents - state 1 (Not in use) [Jun 22 13:37:14] DEBUG[27835] devicestate.c: device 'Local/dave+f003@agents' state '1' [Jun 22 13:37:14] DEBUG[27844] app_queue.c: Device 'Local/dave+f003@agents' changed to state '1' (Not in use) [Jun 22 13:37:15] VERBOSE[27843] chan_sip.c: <--- SIP read from UDP:99.99.49.125:5060 ---> SIP/2.0 200 OK Via: SIP/2.0/UDP 99.99.63.208:5060;branch=z9hG4bK6bf2f935;rport=5060 From: ;tag=as72fdb909;epid=02F57A80 Call-ID: DL0f837860f5-5572063@Dell4-PC CSeq: 102 BYE To: "dave 001" ;tag=DLda8f5d1c96;epid=02F57A80 Allow: INVITE,CANCEL,ACK,OPTIONS,INFO,SUBSCRIBE,NOTIFY,BYE,MESSAGE,UPDATE,REFER Contact: "dave001" User-Agent: Dylogic Mirial 7.0.24 Content-Length: 0 <-------------> [Jun 22 13:37:15] DEBUG[27843] chan_sip.c: Header 0 [ 14]: SIP/2.0 200 OK [Jun 22 13:37:15] DEBUG[27843] chan_sip.c: Header 1 [ 69]: Via: SIP/2.0/UDP 99.99.63.208:5060;branch=z9hG4bK6bf2f935;rport=5060 [Jun 22 13:37:15] DEBUG[27843] chan_sip.c: Header 2 [ 69]: From: ;tag=as72fdb909;epid=02F57A80 [Jun 22 13:37:15] DEBUG[27843] chan_sip.c: Header 3 [ 38]: Call-ID: DL0f837860f5-5572063@Dell4-PC [Jun 22 13:37:15] DEBUG[27843] chan_sip.c: Header 4 [ 13]: CSeq: 102 BYE [Jun 22 13:37:15] DEBUG[27843] chan_sip.c: Header 5 [ 80]: To: "dave 001" ;tag=DLda8f5d1c96;epid=02F57A80 [Jun 22 13:37:15] DEBUG[27843] chan_sip.c: Header 6 [ 79]: Allow: INVITE,CANCEL,ACK,OPTIONS,INFO,SUBSCRIBE,NOTIFY,BYE,MESSAGE,UPDATE,REFER [Jun 22 13:37:15] DEBUG[27843] chan_sip.c: Header 7 [ 58]: Contact: "dave001" [Jun 22 13:37:15] DEBUG[27843] chan_sip.c: Header 8 [ 33]: User-Agent: Dylogic Mirial 7.0.24 [Jun 22 13:37:15] DEBUG[27843] chan_sip.c: Header 9 [ 17]: Content-Length: 0 [Jun 22 13:37:15] DEBUG[27843] chan_sip.c: Header 10 [ 0]: [Jun 22 13:37:15] VERBOSE[27843] chan_sip.c: --- (10 headers 0 lines) --- [Jun 22 13:37:15] DEBUG[27843] chan_sip.c: ** SIP TIMER: Cancelling retransmit of packet (reply received) Retransid #5946 [Jun 22 13:37:15] DEBUG[27843] chan_sip.c: Stopping retransmission on 'DL0f837860f5-5572063@Dell4-PC' of Request 102: Match Found [Jun 22 13:37:15] VERBOSE[27843] chan_sip.c: SIP Response message for INCOMING dialog BYE arrived [Jun 22 13:37:15] DEBUG[27843] chan_sip.c: Destroying SIP dialog DL0f837860f5-5572063@Dell4-PC [Jun 22 13:37:15] VERBOSE[27843] chan_sip.c: Really destroying SIP dialog 'DL0f837860f5-5572063@Dell4-PC' Method: ACK [Jun 22 13:37:15] VERBOSE[27843] chan_sip.c: <--- SIP read from UDP:99.99.208.204:41156 ---> SIP/2.0 200 OK From: "dave 001" ;tag=as42d6fd99;epid=0x4b70530 Call-ID: 47177042333abb710c1956cd794aba46@99.99.104.95 CSeq: 102 CANCEL Via: SIP/2.0/UDP 99.99.104.95:5060;branch=z9hG4bK446227b7;rport=5060;received=99.99.104.95 To: ;tag=DL77412f7e80 User-Agent: Dylogic Mirial 7.0.23 Content-Length: 0 <-------------> [Jun 22 13:37:15] DEBUG[27843] chan_sip.c: Header 0 [ 14]: SIP/2.0 200 OK [Jun 22 13:37:15] DEBUG[27843] chan_sip.c: Header 1 [ 81]: From: "dave 001" ;tag=as42d6fd99;epid=0x4b70530 [Jun 22 13:37:15] DEBUG[27843] chan_sip.c: Header 2 [ 56]: Call-ID: 47177042333abb710c1956cd794aba46@99.99.104.95 [Jun 22 13:37:15] DEBUG[27843] chan_sip.c: Header 3 [ 16]: CSeq: 102 CANCEL [Jun 22 13:37:15] DEBUG[27843] chan_sip.c: Header 4 [ 94]: Via: SIP/2.0/UDP 99.99.104.95:5060;branch=z9hG4bK446227b7;rport=5060;received=99.99.104.95 [Jun 22 13:37:15] DEBUG[27843] chan_sip.c: Header 5 [ 51]: To: ;tag=DL77412f7e80 [Jun 22 13:37:15] DEBUG[27843] chan_sip.c: Header 6 [ 33]: User-Agent: Dylogic Mirial 7.0.23 [Jun 22 13:37:15] DEBUG[27843] chan_sip.c: Header 7 [ 17]: Content-Length: 0 [Jun 22 13:37:15] DEBUG[27843] chan_sip.c: Header 8 [ 0]: [Jun 22 13:37:15] VERBOSE[27843] chan_sip.c: --- (8 headers 0 lines) --- [Jun 22 13:37:15] DEBUG[27843] chan_sip.c: Acked pending invite 102 [Jun 22 13:37:15] DEBUG[27843] chan_sip.c: ** SIP TIMER: Cancelling retransmit of packet (reply received) Retransid #5948 [Jun 22 13:37:15] DEBUG[27843] chan_sip.c: Stopping retransmission on '47177042333abb710c1956cd794aba46@99.99.104.95' of Request 102: Match Found [Jun 22 13:37:15] VERBOSE[27845] asterisk.c: Executing last minute cleanups [Jun 22 13:37:15] VERBOSE[27845] res_musiconhold.c: == Destroying musiconhold processes [Jun 22 13:37:15] DEBUG[27845] res_musiconhold.c: Destroying MOH class 'default' [Jun 22 13:37:15] VERBOSE[27843] chan_sip.c: <--- SIP read from UDP:99.99.208.204:41156 ---> SIP/2.0 487 REQUEST TERMINATED From: "dave 001" ;tag=as42d6fd99;epid=0x4b70530 Call-ID: 47177042333abb710c1956cd794aba46@99.99.104.95 CSeq: 102 INVITE Via: SIP/2.0/UDP 99.99.104.95:5060;branch=z9hG4bK446227b7;rport=5060;received=99.99.104.95 To: ;tag=DL48aab446f7 Allow: INVITE,CANCEL,ACK,OPTIONS,INFO,SUBSCRIBE,NOTIFY,BYE,MESSAGE,UPDATE,REFER Contact: "f003" User-Agent: Dylogic Mirial 7.0.23 Content-Length: 0 <-------------> [Jun 22 13:37:15] DEBUG[27843] chan_sip.c: Header 0 [ 30]: SIP/2.0 487 REQUEST TERMINATED [Jun 22 13:37:15] DEBUG[27843] chan_sip.c: Header 1 [ 81]: From: "dave 001" ;tag=as42d6fd99;epid=0x4b70530 [Jun 22 13:37:15] DEBUG[27843] chan_sip.c: Header 2 [ 56]: Call-ID: 47177042333abb710c1956cd794aba46@99.99.104.95 [Jun 22 13:37:15] DEBUG[27843] chan_sip.c: Header 3 [ 16]: CSeq: 102 INVITE [Jun 22 13:37:15] DEBUG[27843] chan_sip.c: Header 4 [ 94]: Via: SIP/2.0/UDP 99.99.104.95:5060;branch=z9hG4bK446227b7;rport=5060;received=99.99.104.95 [Jun 22 13:37:15] DEBUG[27843] chan_sip.c: Header 5 [ 51]: To: ;tag=DL48aab446f7 [Jun 22 13:37:15] DEBUG[27843] chan_sip.c: Header 6 [ 79]: Allow: INVITE,CANCEL,ACK,OPTIONS,INFO,SUBSCRIBE,NOTIFY,BYE,MESSAGE,UPDATE,REFER [Jun 22 13:37:15] DEBUG[27843] chan_sip.c: Header 7 [ 46]: Contact: "f003" [Jun 22 13:37:15] DEBUG[27843] chan_sip.c: Header 8 [ 33]: User-Agent: Dylogic Mirial 7.0.23 [Jun 22 13:37:15] DEBUG[27843] chan_sip.c: Header 9 [ 17]: Content-Length: 0 [Jun 22 13:37:15] DEBUG[27843] chan_sip.c: Header 10 [ 0]: [Jun 22 13:37:15] VERBOSE[27843] chan_sip.c: --- (10 headers 0 lines) --- [Jun 22 13:37:15] DEBUG[27843] chan_sip.c: Stopping retransmission on '47177042333abb710c1956cd794aba46@99.99.104.95' of Request 102: Match Found [Jun 22 13:37:15] DEBUG[27843] chan_sip.c: SIP response 487 to standard invite [Jun 22 13:37:15] VERBOSE[27843] chan_sip.c: Transmitting (NAT) to 99.99.208.204:41156: ACK sip:f003@192.168.100.19:5060 SIP/2.0 Via: SIP/2.0/UDP 99.99.104.95:5060;branch=z9hG4bK446227b7;rport Max-Forwards: 70 From: "dave 001" ;tag=as42d6fd99 To: ;tag=DL48aab446f7 Contact: Call-ID: 47177042333abb710c1956cd794aba46@99.99.104.95 CSeq: 102 ACK User-Agent: Asterisk PBX SVN-branch-1.6.2-r271555 Content-Length: 0 --- [Jun 22 13:37:15] DEBUG[27843] chan_sip.c: Trying to put 'ACK sip:f00' onto UDP socket destined for 99.99.208.204:41156 [Jun 22 13:37:15] DEBUG[27843] chan_sip.c: Updating call counter for outgoing call [Jun 22 13:37:15] DEBUG[27843] chan_sip.c: Call to peer 'f003' removed from call limit 2147483647 [Jun 22 13:37:15] DEBUG[27843] chan_sip.c: Setting SIP_ALREADYGONE on dialog 47177042333abb710c1956cd794aba46@99.99.104.95 [Jun 22 13:37:15] DEBUG[27843] chan_sip.c: Destroying SIP dialog 47177042333abb710c1956cd794aba46@99.99.104.95 [Jun 22 13:37:15] VERBOSE[27843] chan_sip.c: Really destroying SIP dialog '47177042333abb710c1956cd794aba46@99.99.104.95' Method: INVITE [Jun 22 13:37:15] DEBUG[27835] devicestate.c: No provider found, checking channel drivers for SIP - f003 [Jun 22 13:37:15] DEBUG[27835] chan_sip.c: Checking device state for peer f003 [Jun 22 13:37:15] DEBUG[27835] devicestate.c: Changing state for SIP/f003 - state 1 (Not in use) [Jun 22 13:37:15] DEBUG[27835] devicestate.c: device 'SIP/f003' state '1' [Jun 22 13:37:15] DEBUG[27844] app_queue.c: Device 'SIP/f003' changed to state '1' (Not in use) but we don't care because they're not a member of any queue. [Jun 22 13:37:15] VERBOSE[27845] asterisk.c: Asterisk cleanly ending (0). [Jun 22 13:37:15] DEBUG[27845] asterisk.c: Asterisk ending (0).