[Jun 15 16:44:35] VERBOSE[702] config.c: [Jun 15 16:44:35] == Parsing '/etc/asterisk/logger.conf': [Jun 15 16:44:35] DEBUG[702] config.c: Parsing /etc/asterisk/logger.conf [Jun 15 16:44:35] VERBOSE[702] config.c: [Jun 15 16:44:35] == Found [Jun 15 16:44:35] VERBOSE[702] logger.c: [Jun 15 16:44:35] Asterisk Queue Logger restarted [Jun 15 16:44:36] VERBOSE[686] chan_sip.c: [Jun 15 16:44:36] <--- SIP read from UDP:x.x.x.134:42225 ---> OPTIONS <-------------> [Jun 15 16:44:36] DEBUG[686] chan_sip.c: Header 0 [ 7]: OPTIONS [Jun 15 16:44:38] VERBOSE[686] chan_sip.c: [Jun 15 16:44:38] <--- SIP read from UDP:x.x.x.138:5060 ---> INVITE sip:+15555550002@x.x.x.6 SIP/2.0 Record-Route: Via: SIP/2.0/UDP x.x.x.138;branch=z9hG4bK0e32.112ada56.0 Via: SIP/2.0/UDP x.x.x.134:5060;branch=z9hG4bK13977b02;rport=5060 Max-Forwards: 69 From: "user1" ;tag=as465405d3 To: Contact: Call-ID: 7b8cc12540233d03459e98a54f7dd5ac@x.x.x.134:5060 CSeq: 102 INVITE User-Agent: Asterisk PBX 1.8.14.0-rc1 Date: Fri, 15 Jun 2012 21:44:38 GMT Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO, PUBLISH Supported: replaces, timer Content-Type: application/sdp Content-Length: 272 v=0 o=root 1358820355 1358820355 IN IP4 x.x.x.134 s=Asterisk PBX 1.8.14.0-rc1 c=IN IP4 x.x.x.134 t=0 0 m=audio 16824 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 <-------------> [Jun 15 16:44:38] DEBUG[686] chan_sip.c: Header 0 [ 44]: INVITE sip:+15555550002@x.x.x.6 SIP/2.0 [Jun 15 16:44:38] DEBUG[686] chan_sip.c: Header 1 [ 40]: Record-Route: [Jun 15 16:44:38] DEBUG[686] chan_sip.c: Header 2 [ 61]: Via: SIP/2.0/UDP x.x.x.138;branch=z9hG4bK0e32.112ada56.0 [Jun 15 16:44:38] DEBUG[686] chan_sip.c: Header 3 [ 70]: Via: SIP/2.0/UDP x.x.x.134:5060;branch=z9hG4bK13977b02;rport=5060 [Jun 15 16:44:38] DEBUG[686] chan_sip.c: Header 4 [ 16]: Max-Forwards: 69 [Jun 15 16:44:38] DEBUG[686] chan_sip.c: Header 5 [ 72]: From: "user1" ;tag=as465405d3 [Jun 15 16:44:38] DEBUG[686] chan_sip.c: Header 6 [ 37]: To: [Jun 15 16:44:38] DEBUG[686] chan_sip.c: Header 7 [ 47]: Contact: [Jun 15 16:44:38] DEBUG[686] chan_sip.c: Header 8 [ 61]: Call-ID: 7b8cc12540233d03459e98a54f7dd5ac@x.x.x.134:5060 [Jun 15 16:44:38] DEBUG[686] chan_sip.c: Header 9 [ 16]: CSeq: 102 INVITE [Jun 15 16:44:38] DEBUG[686] chan_sip.c: Header 10 [ 37]: User-Agent: Asterisk PBX 1.8.14.0-rc1 [Jun 15 16:44:38] DEBUG[686] chan_sip.c: Header 11 [ 35]: Date: Fri, 15 Jun 2012 21:44:38 GMT [Jun 15 16:44:38] DEBUG[686] chan_sip.c: Header 12 [ 81]: Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO, PUBLISH [Jun 15 16:44:38] DEBUG[686] chan_sip.c: Header 13 [ 26]: Supported: replaces, timer [Jun 15 16:44:38] DEBUG[686] chan_sip.c: Header 14 [ 29]: Content-Type: application/sdp [Jun 15 16:44:38] DEBUG[686] chan_sip.c: Header 15 [ 19]: Content-Length: 272 [Jun 15 16:44:38] DEBUG[686] chan_sip.c: Header 16 [ 0]: [Jun 15 16:44:38] DEBUG[686] chan_sip.c: Body 0 [ 3]: v=0 [Jun 15 16:44:38] DEBUG[686] chan_sip.c: Body 1 [ 50]: o=root 1358820355 1358820355 IN IP4 x.x.x.134 [Jun 15 16:44:38] DEBUG[686] chan_sip.c: Body 2 [ 27]: s=Asterisk PBX 1.8.14.0-rc1 [Jun 15 16:44:38] DEBUG[686] chan_sip.c: Body 3 [ 23]: c=IN IP4 x.x.x.134 [Jun 15 16:44:38] DEBUG[686] chan_sip.c: Body 4 [ 5]: t=0 0 [Jun 15 16:44:38] DEBUG[686] chan_sip.c: Body 5 [ 27]: m=audio 16824 RTP/AVP 0 101 [Jun 15 16:44:38] DEBUG[686] chan_sip.c: Body 6 [ 20]: a=rtpmap:0 PCMU/8000 [Jun 15 16:44:38] DEBUG[686] chan_sip.c: Body 7 [ 33]: a=rtpmap:101 telephone-event/8000 [Jun 15 16:44:38] DEBUG[686] chan_sip.c: Body 8 [ 15]: a=fmtp:101 0-16 [Jun 15 16:44:38] DEBUG[686] chan_sip.c: Body 9 [ 25]: a=silenceSupp:off - - - - [Jun 15 16:44:38] DEBUG[686] chan_sip.c: Body 10 [ 10]: a=ptime:20 [Jun 15 16:44:38] DEBUG[686] chan_sip.c: Body 11 [ 10]: a=sendrecv [Jun 15 16:44:38] VERBOSE[686] chan_sip.c: [Jun 15 16:44:38] --- (16 headers 12 lines) --- [Jun 15 16:44:38] DEBUG[686] chan_sip.c: = Looking for Call ID: 7b8cc12540233d03459e98a54f7dd5ac@x.x.x.134:5060 (Checking From) --From tag as465405d3 --To-tag [Jun 15 16:44:38] DEBUG[686] acl.c: For destination 'x.x.x.138', our source address is 'x.x.x.6'. [Jun 15 16:44:38] DEBUG[686] chan_sip.c: Setting SIP_TRANSPORT_UDP with address x.x.x.6:5060 [Jun 15 16:44:38] DEBUG[686] chan_sip.c: Allocating new SIP dialog for 7b8cc12540233d03459e98a54f7dd5ac@x.x.x.134:5060 - INVITE (No RTP) [Jun 15 16:44:38] DEBUG[686] chan_sip.c: **** Received INVITE (5) - Command in SIP INVITE [Jun 15 16:44:38] DEBUG[686] sip/reqresp_parser.c: Begin: parsing SIP "Supported: replaces, timer" [Jun 15 16:44:38] DEBUG[686] sip/reqresp_parser.c: Found SIP option: -replaces- [Jun 15 16:44:38] DEBUG[686] sip/reqresp_parser.c: Matched SIP option: replaces [Jun 15 16:44:38] DEBUG[686] sip/reqresp_parser.c: Found SIP option: -timer- [Jun 15 16:44:38] DEBUG[686] sip/reqresp_parser.c: Matched SIP option: timer [Jun 15 16:44:38] DEBUG[686] netsock2.c: Splitting 'x.x.x.138' into... [Jun 15 16:44:38] DEBUG[686] netsock2.c: ...host 'x.x.x.138' and port ''. [Jun 15 16:44:38] VERBOSE[686] chan_sip.c: [Jun 15 16:44:38] Sending to x.x.x.138:5060 (NAT) [Jun 15 16:44:38] DEBUG[686] chan_sip.c: Initializing initreq for method INVITE - callid 7b8cc12540233d03459e98a54f7dd5ac@x.x.x.134:5060 [Jun 15 16:44:38] VERBOSE[686] chan_sip.c: [Jun 15 16:44:38] Using INVITE request as basis request - 7b8cc12540233d03459e98a54f7dd5ac@x.x.x.134:5060 [Jun 15 16:44:38] DEBUG[686] netsock2.c: Splitting 'x.x.x.134' into... [Jun 15 16:44:38] DEBUG[686] netsock2.c: ...host 'x.x.x.134' and port ''. [Jun 15 16:44:38] VERBOSE[686] chan_sip.c: [Jun 15 16:44:38] Found peer 'mypeer1' for '+15555550001' from x.x.x.138:5060 [Jun 15 16:44:38] DEBUG[686] rtp_engine.c: Using engine 'asterisk' for RTP instance '0x9f517f8' [Jun 15 16:44:38] DEBUG[686] res_rtp_asterisk.c: Allocated port 12770 for RTP instance '0x9f517f8' [Jun 15 16:44:38] DEBUG[686] rtp_engine.c: RTP instance '0x9f517f8' is setup and ready to go [Jun 15 16:44:38] DEBUG[686] res_rtp_asterisk.c: Setup RTCP on RTP instance '0x9f517f8' [Jun 15 16:44:38] VERBOSE[686] netsock2.c: [Jun 15 16:44:38] == Using SIP RTP TOS bits 184 [Jun 15 16:44:38] VERBOSE[686] netsock2.c: [Jun 15 16:44:38] == Using SIP RTP CoS mark 5 [Jun 15 16:44:38] DEBUG[686] chan_sip.c: Setting NAT on RTP to On [Jun 15 16:44:38] DEBUG[686] chan_sip.c: Processing session-level SDP v=0... UNSUPPORTED OR FAILED. [Jun 15 16:44:38] DEBUG[686] chan_sip.c: Processing session-level SDP o=root 1358820355 1358820355 IN IP4 x.x.x.134... UNSUPPORTED OR FAILED. [Jun 15 16:44:38] DEBUG[686] chan_sip.c: Processing session-level SDP s=Asterisk PBX 1.8.14.0-rc1... UNSUPPORTED OR FAILED. [Jun 15 16:44:38] DEBUG[686] netsock2.c: Splitting 'x.x.x.134' into... [Jun 15 16:44:38] DEBUG[686] netsock2.c: ...host 'x.x.x.134' and port ''. [Jun 15 16:44:38] DEBUG[686] chan_sip.c: Processing session-level SDP c=IN IP4 x.x.x.134... OK. [Jun 15 16:44:38] DEBUG[686] chan_sip.c: Processing session-level SDP t=0 0... UNSUPPORTED OR FAILED. [Jun 15 16:44:38] VERBOSE[686] chan_sip.c: [Jun 15 16:44:38] Found RTP audio format 0 [Jun 15 16:44:38] DEBUG[686] rtp_engine.c: Setting payload 0 based on m type on 0xb10a52fc [Jun 15 16:44:38] VERBOSE[686] chan_sip.c: [Jun 15 16:44:38] Found RTP audio format 101 [Jun 15 16:44:38] DEBUG[686] rtp_engine.c: Setting payload 101 based on m type on 0xb10a52fc [Jun 15 16:44:38] VERBOSE[686] chan_sip.c: [Jun 15 16:44:38] Found audio description format PCMU for ID 0 [Jun 15 16:44:38] DEBUG[686] chan_sip.c: Processing media-level (audio) SDP a=rtpmap:0 PCMU/8000... OK. [Jun 15 16:44:38] VERBOSE[686] chan_sip.c: [Jun 15 16:44:38] Found audio description format telephone-event for ID 101 [Jun 15 16:44:38] DEBUG[686] chan_sip.c: Processing media-level (audio) SDP a=rtpmap:101 telephone-event/8000... OK. [Jun 15 16:44:38] DEBUG[686] chan_sip.c: Processing media-level (audio) SDP a=fmtp:101 0-16... UNSUPPORTED OR FAILED. [Jun 15 16:44:38] DEBUG[686] chan_sip.c: Processing media-level (audio) SDP a=silenceSupp:off - - - -... UNSUPPORTED OR FAILED. [Jun 15 16:44:38] DEBUG[686] chan_sip.c: Processing media-level (audio) SDP a=ptime:20... OK. [Jun 15 16:44:38] DEBUG[686] chan_sip.c: Processing media-level (audio) SDP a=sendrecv... OK. [Jun 15 16:44:38] DEBUG[686] rtp_engine.c: Incorporating payload 0 on 0xb10a52fc [Jun 15 16:44:38] DEBUG[686] rtp_engine.c: Incorporating payload 101 on 0xb10a52fc [Jun 15 16:44:38] VERBOSE[686] chan_sip.c: [Jun 15 16:44:38] Capabilities: us - 0x4 (ulaw), peer - audio=0x4 (ulaw)/video=0x0 (nothing)/text=0x0 (nothing), combined - 0x4 (ulaw) [Jun 15 16:44:38] VERBOSE[686] chan_sip.c: [Jun 15 16:44:38] Non-codec capabilities (dtmf): us - 0x1 (telephone-event|), peer - 0x1 (telephone-event|), combined - 0x1 (telephone-event|) [Jun 15 16:44:38] DEBUG[686] res_rtp_asterisk.c: Setting RTCP address on RTP instance '0x9f517f8' [Jun 15 16:44:38] VERBOSE[686] chan_sip.c: [Jun 15 16:44:38] Peer audio RTP is at port x.x.x.134:16824 [Jun 15 16:44:38] DEBUG[686] rtp_engine.c: Copying payload 0 from 0xb10a52fc to 0x9f519a4 [Jun 15 16:44:38] DEBUG[686] rtp_engine.c: Copying payload 101 from 0xb10a52fc to 0x9f519a4 [Jun 15 16:44:38] DEBUG[686] res_rtp_asterisk.c: Ignoring duplicate RTCP property on RTP instance '0x9f517f8' [Jun 15 16:44:38] DEBUG[686] chan_sip.c: We're settling with these formats: 0x4 (ulaw) [Jun 15 16:44:38] DEBUG[686] chan_sip.c: Checking SIP call limits for device [Jun 15 16:44:38] DEBUG[686] chan_sip.c: Updating call counter for incoming call [Jun 15 16:44:38] DEBUG[686] netsock2.c: Splitting 'x.x.x.6' into... [Jun 15 16:44:38] DEBUG[686] netsock2.c: ...host 'x.x.x.6' and port ''. [Jun 15 16:44:38] DEBUG[686] netsock2.c: Splitting 'x.x.x.134' into... [Jun 15 16:44:38] DEBUG[686] netsock2.c: ...host 'x.x.x.134' and port ''. [Jun 15 16:44:38] VERBOSE[686] chan_sip.c: [Jun 15 16:44:38] Looking for +15555550002 in prepincoming (domain x.x.x.6) [Jun 15 16:44:38] DEBUG[686] chan_sip.c: *** Our native formats are 0x4 (ulaw) [Jun 15 16:44:38] DEBUG[686] chan_sip.c: *** Joint capabilities are 0x4 (ulaw) [Jun 15 16:44:38] DEBUG[686] chan_sip.c: *** Our capabilities are 0x4 (ulaw) [Jun 15 16:44:38] DEBUG[686] chan_sip.c: *** AST_CODEC_CHOOSE formats are 0x4 (ulaw) [Jun 15 16:44:38] DEBUG[686] chan_sip.c: This channel will not be able to handle video. [Jun 15 16:44:38] DEBUG[686] chan_sip.c: build_route: Record-Route hop: [Jun 15 16:44:38] VERBOSE[686] chan_sip.c: [Jun 15 16:44:38] list_route: hop: [Jun 15 16:44:38] DEBUG[686] chan_sip.c: SIP/mypeer1-00000000: New call is still down.... Trying... [Jun 15 16:44:38] VERBOSE[686] chan_sip.c: [Jun 15 16:44:38] <--- Transmitting (NAT) to x.x.x.138:5060 ---> SIP/2.0 100 Trying Via: SIP/2.0/UDP x.x.x.138;branch=z9hG4bK0e32.112ada56.0;received=x.x.x.138;rport=5060 Via: SIP/2.0/UDP x.x.x.134:5060;branch=z9hG4bK13977b02;rport=5060 Record-Route: From: "user1" ;tag=as465405d3 To: Call-ID: 7b8cc12540233d03459e98a54f7dd5ac@x.x.x.134:5060 CSeq: 102 INVITE Server: Asterisk PBX 1.8.14.0-rc1 Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO, PUBLISH Supported: replaces, timer Contact: Content-Length: 0 <------------> [Jun 15 16:44:38] DEBUG[686] chan_sip.c: Trying to put 'SIP/2.0 100' onto UDP socket destined for x.x.x.138:5060 [Jun 15 16:44:38] DEBUG[667] devicestate.c: No provider found, checking channel drivers for SIP - mypeer1 [Jun 15 16:44:38] DEBUG[667] chan_sip.c: Checking device state for peer mypeer1 [Jun 15 16:44:38] DEBUG[667] devicestate.c: Changing state for SIP/mypeer1 - state 1 (Not in use) [Jun 15 16:44:38] DEBUG[667] devicestate.c: device 'SIP/mypeer1' state '1' [Jun 15 16:44:38] DEBUG[841] pbx.c: Launching 'Macro' [Jun 15 16:44:38] VERBOSE[841] pbx.c: [Jun 15 16:44:38] -- Executing [+15555550002@prepincoming:1] Macro("SIP/mypeer1-00000000", "prepnumber") in new stack [Jun 15 16:44:38] DEBUG[841] pbx.c: Result of 'MACRO_EXTEN' is '+15555550002' [Jun 15 16:44:38] DEBUG[699] app_queue.c: Device 'SIP/mypeer1' changed to state '1' (Not in use) but we don't care because they're not a member of any queue. [Jun 15 16:44:38] DEBUG[841] pbx.c: Function result is '12' [Jun 15 16:44:38] DEBUG[841] pbx.c: Result of 'MACRO_EXTEN' is '+15555550002' [Jun 15 16:44:38] DEBUG[841] pbx.c: Expression result is '1' [Jun 15 16:44:38] DEBUG[841] pbx.c: Result of 'MACRO_EXTEN' is '+15555550002' [Jun 15 16:44:38] DEBUG[841] pbx.c: Launching 'ExecIf' [Jun 15 16:44:38] VERBOSE[841] pbx.c: [Jun 15 16:44:38] -- Executing [s@macro-prepnumber:1] ExecIf("SIP/mypeer1-00000000", "1?Set(MACRO_EXTEN=15555550002)") in new stack [Jun 15 16:44:38] DEBUG[841] app_macro.c: Executed application: ExecIf [Jun 15 16:44:38] DEBUG[841] pbx.c: Evaluating 'LEN(${MACRO_EXTEN})' (from 'LEN(${MACRO_EXTEN})} > 0 & "${MACRO_EXTEN:0:1}" = "+"' len 19) [Jun 15 16:44:38] DEBUG[841] pbx.c: Evaluating 'MACRO_EXTEN' (from 'MACRO_EXTEN})' len 11) [Jun 15 16:44:38] DEBUG[841] pbx.c: Result of 'MACRO_EXTEN' is '15555550002' [Jun 15 16:44:38] DEBUG[841] pbx.c: Function result is '11' [Jun 15 16:44:38] DEBUG[841] pbx.c: Evaluating 'MACRO_EXTEN:0:1' (from 'MACRO_EXTEN:0:1}" = "+"' len 15) [Jun 15 16:44:38] DEBUG[841] pbx.c: Result of 'MACRO_EXTEN' is '15555550002' [Jun 15 16:44:38] DEBUG[841] pbx.c: Expression result is '0' [Jun 15 16:44:38] DEBUG[841] pbx.c: Evaluating 'MACRO_EXTEN:1' (from 'MACRO_EXTEN:1})' len 13) [Jun 15 16:44:38] DEBUG[841] pbx.c: Result of 'MACRO_EXTEN' is '15555550002' [Jun 15 16:44:38] DEBUG[841] pbx.c: Result of 'MACRO_EXTEN' is '15555550002' [Jun 15 16:44:38] DEBUG[841] pbx.c: Function result is '11' [Jun 15 16:44:38] DEBUG[841] pbx.c: Result of 'MACRO_EXTEN' is '15555550002' [Jun 15 16:44:38] DEBUG[841] pbx.c: Expression result is '0' [Jun 15 16:44:38] DEBUG[841] pbx.c: Launching 'GotoIf' [Jun 15 16:44:38] VERBOSE[841] pbx.c: [Jun 15 16:44:38] -- Executing [s@macro-prepnumber:2] GotoIf("SIP/mypeer1-00000000", "0?cidblock,1") in new stack [Jun 15 16:44:38] DEBUG[841] pbx.c: Not taking any branch [Jun 15 16:44:38] DEBUG[841] app_macro.c: Executed application: GotoIf [Jun 15 16:44:38] DEBUG[841] pbx.c: Result of 'MACRO_EXTEN' is '15555550002' [Jun 15 16:44:38] DEBUG[841] pbx.c: Function result is '11' [Jun 15 16:44:38] DEBUG[841] pbx.c: Result of 'MACRO_EXTEN' is '15555550002' [Jun 15 16:44:38] DEBUG[841] pbx.c: Expression result is '1' [Jun 15 16:44:38] DEBUG[841] pbx.c: Launching 'GotoIf' [Jun 15 16:44:38] VERBOSE[841] pbx.c: [Jun 15 16:44:38] -- Executing [s@macro-prepnumber:3] GotoIf("SIP/mypeer1-00000000", "1?fixnatlprefix,1") in new stack [Jun 15 16:44:38] VERBOSE[841] pbx.c: [Jun 15 16:44:38] -- Goto (macro-prepnumber,fixnatlprefix,1) [Jun 15 16:44:38] DEBUG[841] app_macro.c: Executed application: GotoIf [Jun 15 16:44:38] DEBUG[841] pbx.c: Result of 'MACRO_EXTEN' is '15555550002' [Jun 15 16:44:38] DEBUG[841] pbx.c: Launching 'Set' [Jun 15 16:44:38] VERBOSE[841] pbx.c: [Jun 15 16:44:38] -- Executing [fixnatlprefix@macro-prepnumber:1] Set("SIP/mypeer1-00000000", "MACRO_EXTEN=5555550002") in new stack [Jun 15 16:44:38] DEBUG[841] app_macro.c: Executed application: Set [Jun 15 16:44:38] DEBUG[841] pbx.c: Launching 'Goto' [Jun 15 16:44:38] VERBOSE[841] pbx.c: [Jun 15 16:44:38] -- Executing [fixnatlprefix@macro-prepnumber:2] Goto("SIP/mypeer1-00000000", "s,1") in new stack [Jun 15 16:44:38] VERBOSE[841] pbx.c: [Jun 15 16:44:38] -- Goto (macro-prepnumber,s,1) [Jun 15 16:44:38] DEBUG[841] app_macro.c: Executed application: Goto [Jun 15 16:44:38] DEBUG[841] pbx.c: Result of 'MACRO_EXTEN' is '5555550002' [Jun 15 16:44:38] DEBUG[841] pbx.c: Function result is '10' [Jun 15 16:44:38] DEBUG[841] pbx.c: Result of 'MACRO_EXTEN' is '5555550002' [Jun 15 16:44:38] DEBUG[841] pbx.c: Expression result is '0' [Jun 15 16:44:38] DEBUG[841] pbx.c: Result of 'MACRO_EXTEN' is '5555550002' [Jun 15 16:44:38] DEBUG[841] pbx.c: Launching 'ExecIf' [Jun 15 16:44:38] VERBOSE[841] pbx.c: [Jun 15 16:44:38] -- Executing [s@macro-prepnumber:1] ExecIf("SIP/mypeer1-00000000", "0?Set(MACRO_EXTEN=307233079)") in new stack [Jun 15 16:44:38] DEBUG[841] app_macro.c: Executed application: ExecIf [Jun 15 16:44:38] DEBUG[841] pbx.c: Evaluating 'LEN(${MACRO_EXTEN})' (from 'LEN(${MACRO_EXTEN})} > 0 & "${MACRO_EXTEN:0:1}" = "+"' len 19) [Jun 15 16:44:38] DEBUG[841] pbx.c: Evaluating 'MACRO_EXTEN' (from 'MACRO_EXTEN})' len 11) [Jun 15 16:44:38] DEBUG[841] pbx.c: Result of 'MACRO_EXTEN' is '5555550002' [Jun 15 16:44:38] DEBUG[841] pbx.c: Function result is '10' [Jun 15 16:44:38] DEBUG[841] pbx.c: Evaluating 'MACRO_EXTEN:0:1' (from 'MACRO_EXTEN:0:1}" = "+"' len 15) [Jun 15 16:44:38] DEBUG[841] pbx.c: Result of 'MACRO_EXTEN' is '5555550002' [Jun 15 16:44:38] DEBUG[841] pbx.c: Expression result is '0' [Jun 15 16:44:38] DEBUG[841] pbx.c: Evaluating 'MACRO_EXTEN:1' (from 'MACRO_EXTEN:1})' len 13) [Jun 15 16:44:38] DEBUG[841] pbx.c: Result of 'MACRO_EXTEN' is '5555550002' [Jun 15 16:44:38] DEBUG[841] pbx.c: Result of 'MACRO_EXTEN' is '5555550002' [Jun 15 16:44:38] DEBUG[841] pbx.c: Function result is '10' [Jun 15 16:44:38] DEBUG[841] pbx.c: Result of 'MACRO_EXTEN' is '5555550002' [Jun 15 16:44:38] DEBUG[841] pbx.c: Expression result is '0' [Jun 15 16:44:38] DEBUG[841] pbx.c: Launching 'GotoIf' [Jun 15 16:44:38] VERBOSE[841] pbx.c: [Jun 15 16:44:38] -- Executing [s@macro-prepnumber:2] GotoIf("SIP/mypeer1-00000000", "0?cidblock,1") in new stack [Jun 15 16:44:38] DEBUG[841] pbx.c: Not taking any branch [Jun 15 16:44:38] DEBUG[841] app_macro.c: Executed application: GotoIf [Jun 15 16:44:38] DEBUG[841] pbx.c: Result of 'MACRO_EXTEN' is '5555550002' [Jun 15 16:44:38] DEBUG[841] pbx.c: Function result is '10' [Jun 15 16:44:38] DEBUG[841] pbx.c: Result of 'MACRO_EXTEN' is '5555550002' [Jun 15 16:44:38] DEBUG[841] pbx.c: Expression result is '0' [Jun 15 16:44:38] DEBUG[841] pbx.c: Launching 'GotoIf' [Jun 15 16:44:38] VERBOSE[841] pbx.c: [Jun 15 16:44:38] -- Executing [s@macro-prepnumber:3] GotoIf("SIP/mypeer1-00000000", "0?fixnatlprefix,1") in new stack [Jun 15 16:44:38] DEBUG[841] pbx.c: Not taking any branch [Jun 15 16:44:38] DEBUG[841] app_macro.c: Executed application: GotoIf [Jun 15 16:44:38] DEBUG[841] pbx.c: Result of 'MACRO_CONTEXT' is 'prepincoming' [Jun 15 16:44:38] DEBUG[841] pbx.c: Result of 'MACRO_EXTEN' is '5555550002' [Jun 15 16:44:38] DEBUG[841] pbx.c: Result of 'MACRO_PRIORITY' is '1' [Jun 15 16:44:38] DEBUG[841] pbx.c: Expression result is '2' [Jun 15 16:44:38] DEBUG[841] pbx.c: Launching 'Goto' [Jun 15 16:44:38] VERBOSE[841] pbx.c: [Jun 15 16:44:38] -- Executing [s@macro-prepnumber:4] Goto("SIP/mypeer1-00000000", "prepincoming,5555550002,2") in new stack [Jun 15 16:44:38] VERBOSE[841] pbx.c: [Jun 15 16:44:38] -- Goto (prepincoming,5555550002,2) [Jun 15 16:44:38] DEBUG[841] app_macro.c: Executed application: Goto [Jun 15 16:44:38] VERBOSE[841] app_macro.c: [Jun 15 16:44:38] == Channel 'SIP/mypeer1-00000000' jumping out of macro 'prepnumber' [Jun 15 16:44:38] DEBUG[841] pbx.c: Launching 'Playback' [Jun 15 16:44:38] VERBOSE[841] pbx.c: [Jun 15 16:44:38] -- Executing [5555550002@prepincoming:2] Playback("SIP/mypeer1-00000000", "silencehalf") in new stack [Jun 15 16:44:38] DEBUG[841] chan_sip.c: SIP answering channel: SIP/mypeer1-00000000 [Jun 15 16:44:38] DEBUG[667] devicestate.c: No provider found, checking channel drivers for SIP - mypeer1 [Jun 15 16:44:38] DEBUG[841] res_rtp_asterisk.c: Setting the marker bit due to a source update [Jun 15 16:44:38] DEBUG[667] chan_sip.c: Checking device state for peer mypeer1 [Jun 15 16:44:38] DEBUG[841] chan_sip.c: Setting framing from config on incoming call [Jun 15 16:44:38] DEBUG[667] devicestate.c: Changing state for SIP/mypeer1 - state 1 (Not in use) [Jun 15 16:44:38] DEBUG[667] devicestate.c: device 'SIP/mypeer1' state '1' [Jun 15 16:44:38] DEBUG[699] app_queue.c: Device 'SIP/mypeer1' changed to state '1' (Not in use) but we don't care because they're not a member of any queue. [Jun 15 16:44:38] DEBUG[841] chan_sip.c: ** Our capability: 0x4 (ulaw) Video flag: True Text flag: True [Jun 15 16:44:38] DEBUG[841] chan_sip.c: ** Our prefcodec: 0x0 (nothing) [Jun 15 16:44:38] VERBOSE[841] chan_sip.c: [Jun 15 16:44:38] Audio is at 12770 [Jun 15 16:44:38] VERBOSE[841] chan_sip.c: [Jun 15 16:44:38] Adding codec 0x4 (ulaw) to SDP [Jun 15 16:44:38] VERBOSE[841] chan_sip.c: [Jun 15 16:44:38] Adding non-codec 0x1 (telephone-event) to SDP [Jun 15 16:44:38] DEBUG[841] chan_sip.c: -- Done with adding codecs to SDP [Jun 15 16:44:38] DEBUG[841] chan_sip.c: Done building SDP. Settling with this capability: 0x4 (ulaw) [Jun 15 16:44:38] VERBOSE[841] chan_sip.c: [Jun 15 16:44:38] <--- Reliably Transmitting (NAT) to x.x.x.138:5060 ---> SIP/2.0 200 OK Via: SIP/2.0/UDP x.x.x.138;branch=z9hG4bK0e32.112ada56.0;received=x.x.x.138;rport=5060 Via: SIP/2.0/UDP x.x.x.134:5060;branch=z9hG4bK13977b02;rport=5060 Record-Route: From: "user1" ;tag=as465405d3 To: ;tag=as05e16768 Call-ID: 7b8cc12540233d03459e98a54f7dd5ac@x.x.x.134:5060 CSeq: 102 INVITE Server: Asterisk PBX 1.8.14.0-rc1 Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO, PUBLISH Supported: replaces, timer Contact: Content-Type: application/sdp Content-Length: 266 v=0 o=root 391983381 391983381 IN IP4 x.x.x.6 s=Asterisk PBX 1.8.14.0-rc1 c=IN IP4 x.x.x.6 t=0 0 m=audio 12770 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 <------------> [Jun 15 16:44:38] DEBUG[841] chan_sip.c: *** SIP TIMER: Initializing retransmit timer on packet: Id #101 [Jun 15 16:44:38] DEBUG[841] chan_sip.c: Trying to put 'SIP/2.0 200' onto UDP socket destined for x.x.x.138:5060 [Jun 15 16:44:38] VERBOSE[686] chan_sip.c: [Jun 15 16:44:38] <--- SIP read from UDP:x.x.x.138:5060 ---> ACK sip:+15555550002@x.x.x.6:5060 SIP/2.0 Record-Route: Via: SIP/2.0/UDP x.x.x.138;branch=0 Via: SIP/2.0/UDP x.x.x.134:5060;branch=z9hG4bK58d38187;rport=5060 Max-Forwards: 69 From: "user1" ;tag=as465405d3 To: ;tag=as05e16768 Contact: Call-ID: 7b8cc12540233d03459e98a54f7dd5ac@x.x.x.134:5060 CSeq: 102 ACK User-Agent: Asterisk PBX 1.8.14.0-rc1 Content-Length: 0 <-------------> [Jun 15 16:44:38] DEBUG[686] chan_sip.c: Header 0 [ 46]: ACK sip:+15555550002@x.x.x.6:5060 SIP/2.0 [Jun 15 16:44:38] DEBUG[686] chan_sip.c: Header 1 [ 40]: Record-Route: [Jun 15 16:44:38] DEBUG[686] chan_sip.c: Header 2 [ 40]: Via: SIP/2.0/UDP x.x.x.138;branch=0 [Jun 15 16:44:38] DEBUG[686] chan_sip.c: Header 3 [ 70]: Via: SIP/2.0/UDP x.x.x.134:5060;branch=z9hG4bK58d38187;rport=5060 [Jun 15 16:44:38] DEBUG[686] chan_sip.c: Header 4 [ 16]: Max-Forwards: 69 [Jun 15 16:44:38] DEBUG[686] chan_sip.c: Header 5 [ 72]: From: "user1" ;tag=as465405d3 [Jun 15 16:44:38] DEBUG[686] chan_sip.c: Header 6 [ 52]: To: ;tag=as05e16768 [Jun 15 16:44:38] DEBUG[686] chan_sip.c: Header 7 [ 47]: Contact: [Jun 15 16:44:38] DEBUG[686] chan_sip.c: Header 8 [ 61]: Call-ID: 7b8cc12540233d03459e98a54f7dd5ac@x.x.x.134:5060 [Jun 15 16:44:38] DEBUG[686] chan_sip.c: Header 9 [ 13]: CSeq: 102 ACK [Jun 15 16:44:38] DEBUG[686] chan_sip.c: Header 10 [ 37]: User-Agent: Asterisk PBX 1.8.14.0-rc1 [Jun 15 16:44:38] DEBUG[686] chan_sip.c: Header 11 [ 17]: Content-Length: 0 [Jun 15 16:44:38] VERBOSE[686] chan_sip.c: [Jun 15 16:44:38] --- (12 headers 0 lines) --- [Jun 15 16:44:38] DEBUG[686] chan_sip.c: = Looking for Call ID: 7b8cc12540233d03459e98a54f7dd5ac@x.x.x.134:5060 (Checking From) --From tag as465405d3 --To-tag as05e16768 [Jun 15 16:44:38] DEBUG[686] chan_sip.c: **** Received ACK (6) - Command in SIP ACK [Jun 15 16:44:38] DEBUG[686] chan_sip.c: ** SIP TIMER: Cancelling retransmit of packet (reply received) Retransid #101 [Jun 15 16:44:38] DEBUG[686] chan_sip.c: Stopping retransmission on '7b8cc12540233d03459e98a54f7dd5ac@x.x.x.134:5060' of Response 102: Match Found [Jun 15 16:44:38] DEBUG[841] channel.c: Set channel SIP/mypeer1-00000000 to write format slin [Jun 15 16:44:38] DEBUG[841] res_rtp_asterisk.c: Ooh, format changed from unknown to ulaw [Jun 15 16:44:38] DEBUG[841] res_rtp_asterisk.c: Created smoother: format: ulaw ms: 20 len: 160 [Jun 15 16:44:38] VERBOSE[841] file.c: [Jun 15 16:44:38] -- Playing 'silencehalf.slin' (language 'en') [Jun 15 16:44:39] DEBUG[841] channel.c: Set channel SIP/mypeer1-00000000 to write format ulaw [Jun 15 16:44:39] DEBUG[841] pbx.c: Function result is 'Fri Jun 15 16:44:39 2012' [Jun 15 16:44:39] DEBUG[841] pbx.c: Launching 'NoOp' [Jun 15 16:44:39] VERBOSE[841] pbx.c: [Jun 15 16:44:39] -- Executing [5555550002@prepincoming:3] NoOp("SIP/mypeer1-00000000", "Fri Jun 15 16:44:39 2012") in new stack [Jun 15 16:44:39] DEBUG[841] pbx.c: Launching 'AGI' [Jun 15 16:44:39] VERBOSE[841] pbx.c: [Jun 15 16:44:39] -- Executing [5555550002@prepincoming:4] AGI("SIP/mypeer1-00000000", "calleridnamelookup.php") in new stack [Jun 15 16:44:39] VERBOSE[841] res_agi.c: [Jun 15 16:44:39] -- Launched AGI Script /var/asterisk/agi-bin/calleridnamelookup.php [Jun 15 16:44:39] VERBOSE[841] res_agi.c: [Jun 15 16:44:39] calleridnamelookup.php: Located caller name for number [5555550001] ==> user2 [Jun 15 16:44:39] VERBOSE[841] res_agi.c: [Jun 15 16:44:39] -- AGI Script calleridnamelookup.php completed, returning 0 [Jun 15 16:44:39] DEBUG[841] pbx.c: Result of 'EXTEN' is '5555550002' [Jun 15 16:44:39] DEBUG[841] pbx.c: Launching 'Macro' [Jun 15 16:44:39] VERBOSE[841] pbx.c: [Jun 15 16:44:39] -- Executing [5555550002@prepincoming:5] Macro("SIP/mypeer1-00000000", "setinboundcdr,5555550002") in new stack [Jun 15 16:44:39] DEBUG[841] pbx.c: Result of 'ARG1' is '5555550002' [Jun 15 16:44:39] DEBUG[841] pbx.c: Expression result is '1' [Jun 15 16:44:39] DEBUG[841] pbx.c: Launching 'GotoIf' [Jun 15 16:44:39] VERBOSE[841] pbx.c: [Jun 15 16:44:39] -- Executing [s@macro-setinboundcdr:1] GotoIf("SIP/mypeer1-00000000", "1?exten,1") in new stack [Jun 15 16:44:39] VERBOSE[841] pbx.c: [Jun 15 16:44:39] -- Goto (macro-setinboundcdr,exten,1) [Jun 15 16:44:39] DEBUG[841] app_macro.c: Executed application: GotoIf [Jun 15 16:44:39] DEBUG[841] pbx.c: Result of 'ARG1' is '5555550002' [Jun 15 16:44:39] DEBUG[841] pbx.c: Launching 'Set' [Jun 15 16:44:39] VERBOSE[841] pbx.c: [Jun 15 16:44:39] -- Executing [exten@macro-setinboundcdr:1] Set("SIP/mypeer1-00000000", "CDR(userfield)=inbound-5555550002") in new stack [Jun 15 16:44:39] DEBUG[841] app_macro.c: Executed application: Set [Jun 15 16:44:39] DEBUG[841] pbx.c: Launching 'Set' [Jun 15 16:44:39] VERBOSE[841] pbx.c: [Jun 15 16:44:39] -- Executing [5555550002@prepincoming:6] Set("SIP/mypeer1-00000000", "TIMEOUT(absolute)=14400") in new stack [Jun 15 16:44:39] VERBOSE[841] func_timeout.c: [Jun 15 16:44:39] Channel will hangup at 2012-06-15 20:44:39.146 CDT. [Jun 15 16:44:39] DEBUG[841] pbx.c: Launching 'Set' [Jun 15 16:44:39] VERBOSE[841] pbx.c: [Jun 15 16:44:39] -- Executing [5555550002@prepincoming:7] Set("SIP/mypeer1-00000000", "TIMEOUT(digit)=2") in new stack [Jun 15 16:44:39] VERBOSE[841] func_timeout.c: [Jun 15 16:44:39] -- Digit timeout set to 2.000 [Jun 15 16:44:39] DEBUG[841] pbx.c: Launching 'BackGround' [Jun 15 16:44:39] VERBOSE[841] pbx.c: [Jun 15 16:44:39] -- Executing [5555550002@prepincoming:8] BackGround("SIP/mypeer1-00000000", "hpbx/14") in new stack [Jun 15 16:44:39] DEBUG[841] channel.c: Set channel SIP/mypeer1-00000000 to write format slin [Jun 15 16:44:39] DEBUG[841] res_rtp_asterisk.c: Difference is 1112, ms is 159 [Jun 15 16:44:39] VERBOSE[841] file.c: [Jun 15 16:44:39] -- Playing 'hpbx/14.slin' (language 'en') [Jun 15 16:44:39] DEBUG[841] res_rtp_asterisk.c: - RTP 2833 Event: 00000001 (len = 4) [Jun 15 16:44:39] DEBUG[841] res_rtp_asterisk.c: Sending dtmf: 49 (1), at x.x.x.134:16824 [Jun 15 16:44:39] DTMF[841] channel.c: DTMF begin '1' received on SIP/mypeer1-00000000 [Jun 15 16:44:39] DTMF[841] channel.c: DTMF begin ignored '1' on SIP/mypeer1-00000000 [Jun 15 16:44:39] DEBUG[841] res_rtp_asterisk.c: - RTP 2833 Event: 00000001 (len = 4) [Jun 15 16:44:39] DEBUG[841] res_rtp_asterisk.c: - RTP 2833 Event: 00000001 (len = 4) [Jun 15 16:44:39] DEBUG[841] res_rtp_asterisk.c: - RTP 2833 Event: 00000001 (len = 4) [Jun 15 16:44:39] DEBUG[841] res_rtp_asterisk.c: - RTP 2833 Event: 00000001 (len = 4) [Jun 15 16:44:39] DEBUG[841] res_rtp_asterisk.c: - RTP 2833 Event: 00000001 (len = 4) [Jun 15 16:44:39] DEBUG[841] res_rtp_asterisk.c: - RTP 2833 Event: 00000001 (len = 4) [Jun 15 16:44:39] DEBUG[841] res_rtp_asterisk.c: - RTP 2833 Event: 00000001 (len = 4) [Jun 15 16:44:39] DEBUG[841] res_rtp_asterisk.c: - RTP 2833 Event: 00000001 (len = 4) [Jun 15 16:44:39] DEBUG[841] res_rtp_asterisk.c: Sending dtmf: 49 (1), at x.x.x.134:16824 [Jun 15 16:44:39] DTMF[841] channel.c: DTMF end '1' received on SIP/mypeer1-00000000, duration 180 ms [Jun 15 16:44:39] DTMF[841] channel.c: DTMF end passthrough '1' on SIP/mypeer1-00000000 [Jun 15 16:44:39] DEBUG[841] channel.c: Set channel SIP/mypeer1-00000000 to write format ulaw [Jun 15 16:44:39] DEBUG[841] pbx.c: Oooh, got something to jump out with ('1')! [Jun 15 16:44:39] DEBUG[841] res_rtp_asterisk.c: - RTP 2833 Event: 00000001 (len = 4) [Jun 15 16:44:39] DEBUG[841] res_rtp_asterisk.c: - RTP 2833 Event: 00000001 (len = 4) [Jun 15 16:44:40] DEBUG[841] res_rtp_asterisk.c: - RTP 2833 Event: 00000002 (len = 4) [Jun 15 16:44:40] DEBUG[841] res_rtp_asterisk.c: Sending dtmf: 50 (2), at x.x.x.134:16824 [Jun 15 16:44:40] DTMF[841] channel.c: DTMF begin '2' received on SIP/mypeer1-00000000 [Jun 15 16:44:40] DTMF[841] channel.c: DTMF begin ignored '2' on SIP/mypeer1-00000000 [Jun 15 16:44:40] DEBUG[841] res_rtp_asterisk.c: - RTP 2833 Event: 00000002 (len = 4) [Jun 15 16:44:40] DEBUG[841] res_rtp_asterisk.c: - RTP 2833 Event: 00000002 (len = 4) [Jun 15 16:44:40] DEBUG[841] res_rtp_asterisk.c: Sending dtmf: 50 (2), at x.x.x.134:16824 [Jun 15 16:44:40] DTMF[841] channel.c: DTMF end '2' received on SIP/mypeer1-00000000, duration 191 ms [Jun 15 16:44:40] DTMF[841] channel.c: DTMF end passthrough '2' on SIP/mypeer1-00000000 [Jun 15 16:44:40] DEBUG[841] res_rtp_asterisk.c: - RTP 2833 Event: 00000002 (len = 4) [Jun 15 16:44:40] DEBUG[841] res_rtp_asterisk.c: - RTP 2833 Event: 00000002 (len = 4) [Jun 15 16:44:40] DEBUG[841] res_rtp_asterisk.c: - RTP 2833 Event: 00000009 (len = 4) [Jun 15 16:44:40] DEBUG[841] res_rtp_asterisk.c: Sending dtmf: 57 (9), at x.x.x.134:16824 [Jun 15 16:44:40] DTMF[841] channel.c: DTMF begin '9' received on SIP/mypeer1-00000000 [Jun 15 16:44:40] DTMF[841] channel.c: DTMF begin ignored '9' on SIP/mypeer1-00000000 [Jun 15 16:44:40] DEBUG[841] res_rtp_asterisk.c: - RTP 2833 Event: 00000009 (len = 4) [Jun 15 16:44:41] DEBUG[841] res_rtp_asterisk.c: - RTP 2833 Event: 00000009 (len = 4) [Jun 15 16:44:41] DEBUG[841] res_rtp_asterisk.c: Sending dtmf: 57 (9), at x.x.x.134:16824 [Jun 15 16:44:41] DTMF[841] channel.c: DTMF end '9' received on SIP/mypeer1-00000000, duration 187 ms [Jun 15 16:44:41] DTMF[841] channel.c: DTMF end passthrough '9' on SIP/mypeer1-00000000 [Jun 15 16:44:41] DEBUG[841] res_rtp_asterisk.c: - RTP 2833 Event: 00000009 (len = 4) [Jun 15 16:44:41] DEBUG[841] res_rtp_asterisk.c: - RTP 2833 Event: 00000009 (len = 4) [Jun 15 16:44:41] VERBOSE[686] chan_sip.c: [Jun 15 16:44:41] <--- SIP read from UDP:x.x.x.5:55010 ---> OPTIONS sip:x.x.x.6 SIP/2.0 Via: SIP/2.0/UDP x.x.x.5:55028;branch=z9hG4bK-95b3bb19 From: "test1" ;tag=85813c2523621f1fo0 To: Call-ID: d7a897ad-11933937@x.x.x.5 CSeq: 166 OPTIONS Max-Forwards: 70 Contact: "test1" Event: keep-alive User-Agent: Cisco/SPA525G2-7.4.9c Content-Length: 0 <-------------> [Jun 15 16:44:41] DEBUG[686] chan_sip.c: Header 0 [ 32]: OPTIONS sip:x.x.x.6 SIP/2.0 [Jun 15 16:44:41] DEBUG[686] chan_sip.c: Header 1 [ 60]: Via: SIP/2.0/UDP x.x.x.5:55028;branch=z9hG4bK-95b3bb19 [Jun 15 16:44:41] DEBUG[686] chan_sip.c: Header 2 [ 57]: From: "test1" ;tag=85813c2523621f1fo0 [Jun 15 16:44:41] DEBUG[686] chan_sip.c: Header 3 [ 22]: To: [Jun 15 16:44:41] DEBUG[686] chan_sip.c: Header 4 [ 40]: Call-ID: d7a897ad-11933937@x.x.x.5 [Jun 15 16:44:41] DEBUG[686] chan_sip.c: Header 5 [ 17]: CSeq: 166 OPTIONS [Jun 15 16:44:41] DEBUG[686] chan_sip.c: Header 6 [ 16]: Max-Forwards: 70 [Jun 15 16:44:41] DEBUG[686] chan_sip.c: Header 7 [ 44]: Contact: "test1" [Jun 15 16:44:41] DEBUG[686] chan_sip.c: Header 8 [ 17]: Event: keep-alive [Jun 15 16:44:41] DEBUG[686] chan_sip.c: Header 9 [ 33]: User-Agent: Cisco/SPA525G2-7.4.9c [Jun 15 16:44:41] DEBUG[686] chan_sip.c: Header 10 [ 17]: Content-Length: 0 [Jun 15 16:44:41] VERBOSE[686] chan_sip.c: [Jun 15 16:44:41] --- (11 headers 0 lines) --- [Jun 15 16:44:41] DEBUG[686] chan_sip.c: = Looking for Call ID: d7a897ad-11933937@x.x.x.5 (Checking From) --From tag 85813c2523621f1fo0 --To-tag [Jun 15 16:44:41] DEBUG[686] chan_sip.c: **** Received OPTIONS (3) - Command in SIP OPTIONS [Jun 15 16:44:41] DEBUG[686] netsock2.c: Splitting 'x.x.x.6' into... [Jun 15 16:44:41] DEBUG[686] netsock2.c: ...host 'x.x.x.6' and port ''. [Jun 15 16:44:41] DEBUG[686] netsock2.c: Splitting 'x.x.x.6' into... [Jun 15 16:44:41] DEBUG[686] netsock2.c: ...host 'x.x.x.6' and port ''. [Jun 15 16:44:41] VERBOSE[686] chan_sip.c: [Jun 15 16:44:41] Looking for s in unauthorized (domain x.x.x.6) [Jun 15 16:44:41] VERBOSE[686] chan_sip.c: [Jun 15 16:44:41] <--- Transmitting (NAT) to x.x.x.5:55010 ---> SIP/2.0 404 Not Found Via: SIP/2.0/UDP x.x.x.5:55028;branch=z9hG4bK-95b3bb19;received=x.x.x.5;rport=55010 From: "test1" ;tag=85813c2523621f1fo0 To: ;tag=as3df6dbad Call-ID: d7a897ad-11933937@x.x.x.5 CSeq: 166 OPTIONS Server: Asterisk PBX 1.8.14.0-rc1 Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO, PUBLISH Supported: replaces, timer Accept: application/sdp Content-Length: 0 <------------> [Jun 15 16:44:41] DEBUG[686] chan_sip.c: Trying to put 'SIP/2.0 404' onto UDP socket destined for x.x.x.5:55010 [Jun 15 16:44:41] VERBOSE[686] chan_sip.c: [Jun 15 16:44:41] Scheduling destruction of SIP dialog 'd7a897ad-11933937@x.x.x.5' in 32000 ms (Method: OPTIONS) [Jun 15 16:44:43] VERBOSE[841] pbx.c: [Jun 15 16:44:43] == CDR updated on SIP/mypeer1-00000000 [Jun 15 16:44:43] DEBUG[841] pbx.c: Launching 'NoOp' [Jun 15 16:44:43] VERBOSE[841] pbx.c: [Jun 15 16:44:43] -- Executing [test1@prepincoming:1] NoOp("SIP/mypeer1-00000000", "") in new stack [Jun 15 16:44:43] DEBUG[841] pbx.c: Result of 'EXTEN' is 'test1' [Jun 15 16:44:43] DEBUG[841] pbx.c: Launching 'Gosub' [Jun 15 16:44:43] VERBOSE[841] pbx.c: [Jun 15 16:44:43] -- Executing [test1@prepincoming:2] Gosub("SIP/mypeer1-00000000", "macro-dialext,s,1(test1,5,0,0,1)") in new stack [Jun 15 16:44:43] DEBUG[841] app_stack.c: Channel SIP/mypeer1-00000000 has no datastore, so we're allocating one. [Jun 15 16:44:43] DEBUG[841] app_stack.c: Setting 'ARG1' to 'test1' [Jun 15 16:44:43] DEBUG[841] app_stack.c: Setting 'ARG2' to '5' [Jun 15 16:44:43] DEBUG[841] app_stack.c: Setting 'ARG3' to '0' [Jun 15 16:44:43] DEBUG[841] app_stack.c: Setting 'ARG4' to '0' [Jun 15 16:44:43] DEBUG[841] app_stack.c: Setting 'ARG5' to '1' [Jun 15 16:44:43] DEBUG[841] pbx.c: Launching 'Set' [Jun 15 16:44:43] VERBOSE[841] pbx.c: [Jun 15 16:44:43] -- Executing [s@macro-dialext:1] Set("SIP/mypeer1-00000000", "LIMIT_WARNING_FILE=beep") in new stack [Jun 15 16:44:43] DEBUG[841] pbx.c: Launching 'Set' [Jun 15 16:44:43] VERBOSE[841] pbx.c: [Jun 15 16:44:43] -- Executing [s@macro-dialext:2] Set("SIP/mypeer1-00000000", "LIMIT_PLAYAUDIO_CALLEE=yes") in new stack [Jun 15 16:44:43] DEBUG[841] pbx.c: Launching 'NoOp' [Jun 15 16:44:43] VERBOSE[841] pbx.c: [Jun 15 16:44:43] -- Executing [s@macro-dialext:3] NoOp("SIP/mypeer1-00000000", "") in new stack [Jun 15 16:44:43] DEBUG[841] pbx.c: Result of 'ARG2' is '5' [Jun 15 16:44:43] DEBUG[841] pbx.c: Expression result is '0' [Jun 15 16:44:43] DEBUG[841] pbx.c: Launching 'ExecIf' [Jun 15 16:44:43] VERBOSE[841] pbx.c: [Jun 15 16:44:43] -- Executing [s@macro-dialext:4] ExecIf("SIP/mypeer1-00000000", "0?Set(ARG2=0)") in new stack [Jun 15 16:44:43] DEBUG[841] pbx.c: Result of 'ARG3' is '0' [Jun 15 16:44:43] DEBUG[841] pbx.c: Expression result is '0' [Jun 15 16:44:43] DEBUG[841] pbx.c: Launching 'ExecIf' [Jun 15 16:44:43] VERBOSE[841] pbx.c: [Jun 15 16:44:43] -- Executing [s@macro-dialext:5] ExecIf("SIP/mypeer1-00000000", "0?Set(ARG3=0)") in new stack [Jun 15 16:44:43] DEBUG[841] pbx.c: Result of 'ARG4' is '0' [Jun 15 16:44:43] DEBUG[841] pbx.c: Expression result is '0' [Jun 15 16:44:43] DEBUG[841] pbx.c: Launching 'ExecIf' [Jun 15 16:44:43] VERBOSE[841] pbx.c: [Jun 15 16:44:43] -- Executing [s@macro-dialext:6] ExecIf("SIP/mypeer1-00000000", "0?Set(ARG4=0)") in new stack [Jun 15 16:44:43] DEBUG[841] pbx.c: Result of 'ARG5' is '1' [Jun 15 16:44:43] DEBUG[841] pbx.c: Expression result is '0' [Jun 15 16:44:43] DEBUG[841] pbx.c: Launching 'ExecIf' [Jun 15 16:44:43] VERBOSE[841] pbx.c: [Jun 15 16:44:43] -- Executing [s@macro-dialext:7] ExecIf("SIP/mypeer1-00000000", "0?Set(ARG5=0)") in new stack [Jun 15 16:44:43] DEBUG[841] pbx.c: Function result is 'Fri Jun 15 16:44:43 2012' [Jun 15 16:44:43] DEBUG[841] pbx.c: Launching 'NoOp' [Jun 15 16:44:43] VERBOSE[841] pbx.c: [Jun 15 16:44:43] -- Executing [s@macro-dialext:8] NoOp("SIP/mypeer1-00000000", "Fri Jun 15 16:44:43 2012") in new stack [Jun 15 16:44:43] DEBUG[841] pbx.c: Result of 'ARG1' is 'test1' [Jun 15 16:44:43] DEBUG[841] pbx.c: Result of 'ARG4' is '0' [Jun 15 16:44:43] DEBUG[841] pbx.c: Result of 'ARG4' is '0' [Jun 15 16:44:43] DEBUG[841] pbx.c: Function result is '' [Jun 15 16:44:43] DEBUG[841] pbx.c: Result of 'ARG2' is '5' [Jun 15 16:44:43] DEBUG[841] pbx.c: Expression result is '0' [Jun 15 16:44:43] DEBUG[841] pbx.c: Result of 'ARG2' is '5' [Jun 15 16:44:43] DEBUG[841] pbx.c: Expression result is '30' [Jun 15 16:44:43] DEBUG[841] pbx.c: Function result is '30' [Jun 15 16:44:43] DEBUG[841] pbx.c: Result of 'ARG5' is '1' [Jun 15 16:44:43] DEBUG[841] pbx.c: Result of 'ARG3' is '0' [Jun 15 16:44:43] DEBUG[841] pbx.c: Function result is '5555550001' [Jun 15 16:44:43] DEBUG[841] pbx.c: Function result is '5555550001' [Jun 15 16:44:43] DEBUG[841] pbx.c: Function result is 'rtwWM(record^5555550001)' [Jun 15 16:44:43] DEBUG[841] pbx.c: Result of 'ARG3' is '0' [Jun 15 16:44:43] DEBUG[841] pbx.c: Function result is 'wWrt' [Jun 15 16:44:43] DEBUG[841] pbx.c: Function result is 'rtwWM(record^5555550001)' [Jun 15 16:44:43] DEBUG[841] pbx.c: Result of 'MYLIMIT' is NULL [Jun 15 16:44:43] DEBUG[841] pbx.c: Launching 'Dial' [Jun 15 16:44:43] VERBOSE[841] pbx.c: [Jun 15 16:44:43] -- Executing [s@macro-dialext:9] Dial("SIP/mypeer1-00000000", "SIP/test1,30,rtwWM(record^5555550001)") in new stack [Jun 15 16:44:43] DEBUG[841] chan_sip.c: Asked to create a SIP channel with formats: 0x4 (ulaw) [Jun 15 16:44:43] DEBUG[841] chan_sip.c: Allocating new SIP dialog for 56e276ef6120e27b441c7c2244e1da63@x.x.x.6:5060 - INVITE (No RTP) [Jun 15 16:44:43] DEBUG[841] rtp_engine.c: Using engine 'asterisk' for RTP instance '0x9f61758' [Jun 15 16:44:43] DEBUG[841] res_rtp_asterisk.c: Allocated port 11186 for RTP instance '0x9f61758' [Jun 15 16:44:43] DEBUG[841] rtp_engine.c: RTP instance '0x9f61758' is setup and ready to go [Jun 15 16:44:43] DEBUG[841] res_rtp_asterisk.c: Setup RTCP on RTP instance '0x9f61758' [Jun 15 16:44:43] VERBOSE[841] netsock2.c: [Jun 15 16:44:43] == Using SIP RTP TOS bits 184 [Jun 15 16:44:43] VERBOSE[841] netsock2.c: [Jun 15 16:44:43] == Using SIP RTP CoS mark 5 [Jun 15 16:44:43] DEBUG[841] chan_sip.c: Setting NAT on RTP to On [Jun 15 16:44:43] DEBUG[841] chan_sip.c: OBPROXY: Not applying OBproxy to this call [Jun 15 16:44:43] DEBUG[841] acl.c: For destination 'x.x.x.5', our source address is 'x.x.x.6'. [Jun 15 16:44:43] DEBUG[841] chan_sip.c: Setting SIP_TRANSPORT_UDP with address x.x.x.6:5060 [Jun 15 16:44:43] DEBUG[841] chan_sip.c: *** Our native formats are 0x4 (ulaw) [Jun 15 16:44:43] DEBUG[841] chan_sip.c: *** Joint capabilities are 0x4 (ulaw) [Jun 15 16:44:43] DEBUG[841] chan_sip.c: *** Our capabilities are 0x1004 (ulaw|g722) [Jun 15 16:44:43] DEBUG[841] chan_sip.c: *** AST_CODEC_CHOOSE formats are 0x4 (ulaw) [Jun 15 16:44:43] DEBUG[841] chan_sip.c: *** Our preferred formats from the incoming channel are 0x4 (ulaw) [Jun 15 16:44:43] DEBUG[841] chan_sip.c: This channel will not be able to handle video. [Jun 15 16:44:43] DEBUG[841] channel.c: Not copying variable DIALEDTIME. [Jun 15 16:44:43] DEBUG[841] channel.c: Not copying variable ANSWEREDTIME. [Jun 15 16:44:43] DEBUG[841] channel.c: Not copying variable DIALEDPEERNAME. [Jun 15 16:44:43] DEBUG[841] channel.c: Not copying variable DIALEDPEERNUMBER. [Jun 15 16:44:43] DEBUG[841] channel.c: Not copying variable DIALSTATUS. [Jun 15 16:44:43] DEBUG[841] channel.c: Not copying variable LIMIT_PLAYAUDIO_CALLEE. [Jun 15 16:44:43] DEBUG[841] channel.c: Not copying variable LIMIT_WARNING_FILE. [Jun 15 16:44:43] DEBUG[841] channel.c: Not copying variable ARGC. [Jun 15 16:44:43] DEBUG[841] channel.c: Not copying variable ARG5. [Jun 15 16:44:43] DEBUG[841] channel.c: Not copying variable ARG4. [Jun 15 16:44:43] DEBUG[841] channel.c: Not copying variable ARG3. [Jun 15 16:44:43] DEBUG[841] channel.c: Not copying variable ARG2. [Jun 15 16:44:43] DEBUG[841] channel.c: Not copying variable ARG1. [Jun 15 16:44:43] DEBUG[841] channel.c: Not copying variable BACKGROUNDSTATUS. [Jun 15 16:44:43] DEBUG[841] channel.c: Not copying variable MACRO_DEPTH. [Jun 15 16:44:43] DEBUG[841] channel.c: Not copying variable AGISTATUS. [Jun 15 16:44:43] DEBUG[841] channel.c: Not copying variable PLAYBACKSTATUS. [Jun 15 16:44:43] DEBUG[841] channel.c: Not copying variable SIPCALLID. [Jun 15 16:44:43] DEBUG[841] channel.c: Not copying variable SIPDOMAIN. [Jun 15 16:44:43] DEBUG[841] channel.c: Not copying variable SIPURI. [Jun 15 16:44:43] DEBUG[841] chan_sip.c: Outgoing Call for test1 [Jun 15 16:44:43] DEBUG[841] chan_sip.c: Updating call counter for outgoing call [Jun 15 16:44:43] DEBUG[841] chan_sip.c: Call to peer 'test1' is 1 out of 100 [Jun 15 16:44:43] DEBUG[667] devicestate.c: No provider found, checking channel drivers for SIP - test1 [Jun 15 16:44:43] DEBUG[667] chan_sip.c: Checking device state for peer test1 [Jun 15 16:44:43] DEBUG[667] devicestate.c: Changing state for SIP/test1 - state 6 (Ringing) [Jun 15 16:44:43] DEBUG[841] chan_sip.c: ** Our capability: 0x1004 (ulaw|g722) Video flag: False Text flag: False [Jun 15 16:44:43] DEBUG[667] devicestate.c: device 'SIP/test1' state '6' [Jun 15 16:44:43] DEBUG[841] chan_sip.c: ** Our prefcodec: 0x4 (ulaw) [Jun 15 16:44:43] VERBOSE[841] chan_sip.c: [Jun 15 16:44:43] Audio is at 11186 [Jun 15 16:44:43] DEBUG[699] app_queue.c: Device 'SIP/test1' changed to state '6' (Ringing) [Jun 15 16:44:43] VERBOSE[841] chan_sip.c: [Jun 15 16:44:43] Adding codec 0x4 (ulaw) to SDP [Jun 15 16:44:43] VERBOSE[841] chan_sip.c: [Jun 15 16:44:43] Adding codec 0x1000 (g722) to SDP [Jun 15 16:44:43] VERBOSE[841] chan_sip.c: [Jun 15 16:44:43] Adding non-codec 0x1 (telephone-event) to SDP [Jun 15 16:44:43] DEBUG[841] chan_sip.c: -- Done with adding codecs to SDP [Jun 15 16:44:43] DEBUG[841] chan_sip.c: Done building SDP. Settling with this capability: 0x1004 (ulaw|g722) [Jun 15 16:44:43] DEBUG[841] chan_sip.c: Initializing initreq for method INVITE - callid 4912056e767be8ec2685723436484077@x.x.x.6:5060 [Jun 15 16:44:43] DEBUG[841] chan_sip.c: Header 0 [ 42]: INVITE sip:test1@x.x.x.5:55028 SIP/2.0 [Jun 15 16:44:43] DEBUG[841] chan_sip.c: Header 1 [ 63]: Via: SIP/2.0/UDP x.x.x.6:5060;branch=z9hG4bK1272eb06;rport [Jun 15 16:44:43] DEBUG[841] chan_sip.c: Header 2 [ 16]: Max-Forwards: 70 [Jun 15 16:44:43] DEBUG[841] chan_sip.c: Header 3 [ 65]: From: "user2" ;tag=as22ef64a2 [Jun 15 16:44:43] DEBUG[841] chan_sip.c: Header 4 [ 33]: To: [Jun 15 16:44:43] DEBUG[841] chan_sip.c: Header 5 [ 43]: Contact: [Jun 15 16:44:43] DEBUG[841] chan_sip.c: Header 6 [ 59]: Call-ID: 4912056e767be8ec2685723436484077@x.x.x.6:5060 [Jun 15 16:44:43] DEBUG[668] app_queue.c: Extension 'test1@localusers' changed to state '6' (Ringing) but we don't care because they're not a member of any queue. [Jun 15 16:44:43] DEBUG[841] chan_sip.c: Header 7 [ 16]: CSeq: 102 INVITE [Jun 15 16:44:43] DEBUG[841] chan_sip.c: Header 8 [ 37]: User-Agent: Asterisk PBX 1.8.14.0-rc1 [Jun 15 16:44:43] DEBUG[841] chan_sip.c: Header 9 [ 35]: Date: Fri, 15 Jun 2012 21:44:43 GMT [Jun 15 16:44:43] DEBUG[841] chan_sip.c: Header 10 [ 81]: Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO, PUBLISH [Jun 15 16:44:43] DEBUG[841] chan_sip.c: Header 11 [ 26]: Supported: replaces, timer [Jun 15 16:44:43] DEBUG[841] chan_sip.c: Header 12 [ 29]: Content-Type: application/sdp [Jun 15 16:44:43] VERBOSE[841] chan_sip.c: [Jun 15 16:44:43] Reliably Transmitting (NAT) to x.x.x.5:55010: INVITE sip:test1@x.x.x.5:55028 SIP/2.0 Via: SIP/2.0/UDP x.x.x.6:5060;branch=z9hG4bK1272eb06;rport Max-Forwards: 70 From: "user2" ;tag=as22ef64a2 To: Contact: Call-ID: 4912056e767be8ec2685723436484077@x.x.x.6:5060 CSeq: 102 INVITE User-Agent: Asterisk PBX 1.8.14.0-rc1 Date: Fri, 15 Jun 2012 21:44:43 GMT Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO, PUBLISH Supported: replaces, timer Content-Type: application/sdp Content-Length: 290 v=0 o=root 869735453 869735453 IN IP4 x.x.x.6 s=Asterisk PBX 1.8.14.0-rc1 c=IN IP4 x.x.x.6 t=0 0 m=audio 11186 RTP/AVP 0 9 101 a=rtpmap:0 PCMU/8000 a=rtpmap:9 G722/8000 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-16 a=silenceSupp:off - - - - a=ptime:20 a=sendrecv --- [Jun 15 16:44:43] DEBUG[841] chan_sip.c: *** SIP TIMER: Initializing retransmit timer on packet: Id #104 [Jun 15 16:44:43] DEBUG[841] chan_sip.c: Trying to put 'INVITE sip:' onto UDP socket destined for x.x.x.5:55010 [Jun 15 16:44:43] VERBOSE[841] app_dial.c: [Jun 15 16:44:43] -- Called SIP/test1 [Jun 15 16:44:43] DEBUG[841] channel.c: Driver for channel 'SIP/mypeer1-00000000' does not support indication 3, emulating it [Jun 15 16:44:43] DEBUG[841] channel.c: Set channel SIP/mypeer1-00000000 to write format slin [Jun 15 16:44:43] DEBUG[841] res_rtp_asterisk.c: Difference is 25912, ms is 3259 [Jun 15 16:44:43] VERBOSE[686] chan_sip.c: [Jun 15 16:44:43] <--- SIP read from UDP:x.x.x.5:55010 ---> SIP/2.0 100 Trying To: From: "user2" ;tag=as22ef64a2 Call-ID: 4912056e767be8ec2685723436484077@x.x.x.6:5060 CSeq: 102 INVITE Via: SIP/2.0/UDP x.x.x.6:5060;branch=z9hG4bK1272eb06 Server: Cisco/SPA525G2-7.4.9c Content-Length: 0 <-------------> [Jun 15 16:44:43] DEBUG[686] chan_sip.c: Header 0 [ 18]: SIP/2.0 100 Trying [Jun 15 16:44:43] DEBUG[686] chan_sip.c: Header 1 [ 33]: To: [Jun 15 16:44:43] DEBUG[686] chan_sip.c: Header 2 [ 65]: From: "user2" ;tag=as22ef64a2 [Jun 15 16:44:43] DEBUG[686] chan_sip.c: Header 3 [ 59]: Call-ID: 4912056e767be8ec2685723436484077@x.x.x.6:5060 [Jun 15 16:44:43] DEBUG[686] chan_sip.c: Header 4 [ 16]: CSeq: 102 INVITE [Jun 15 16:44:43] DEBUG[686] chan_sip.c: Header 5 [ 57]: Via: SIP/2.0/UDP x.x.x.6:5060;branch=z9hG4bK1272eb06 [Jun 15 16:44:43] DEBUG[686] chan_sip.c: Header 6 [ 29]: Server: Cisco/SPA525G2-7.4.9c [Jun 15 16:44:43] DEBUG[686] chan_sip.c: Header 7 [ 17]: Content-Length: 0 [Jun 15 16:44:43] VERBOSE[686] chan_sip.c: [Jun 15 16:44:43] --- (8 headers 0 lines) --- [Jun 15 16:44:43] DEBUG[686] chan_sip.c: = Looking for Call ID: 4912056e767be8ec2685723436484077@x.x.x.6:5060 (Checking To) --From tag as22ef64a2 --To-tag [Jun 15 16:44:43] DEBUG[686] chan_sip.c: *** SIP TIMER: Cancelling retransmission #104 - INVITE (got response) [Jun 15 16:44:43] DEBUG[686] chan_sip.c: (Provisional) Stopping retransmission (but retaining packet) on '4912056e767be8ec2685723436484077@x.x.x.6:5060' Request 102: Found [Jun 15 16:44:43] DEBUG[686] chan_sip.c: SIP response 100 to standard invite [Jun 15 16:44:43] VERBOSE[686] chan_sip.c: [Jun 15 16:44:43] <--- SIP read from UDP:x.x.x.5:55010 ---> SIP/2.0 180 Ringing To: ;tag=f5326c15812d0f49i0 From: "user2" ;tag=as22ef64a2 Call-ID: 4912056e767be8ec2685723436484077@x.x.x.6:5060 CSeq: 102 INVITE Via: SIP/2.0/UDP x.x.x.6:5060;branch=z9hG4bK1272eb06 Contact: "test1" Server: Cisco/SPA525G2-7.4.9c Content-Length: 0 <-------------> [Jun 15 16:44:43] DEBUG[686] chan_sip.c: Header 0 [ 19]: SIP/2.0 180 Ringing [Jun 15 16:44:43] DEBUG[686] chan_sip.c: Header 1 [ 56]: To: ;tag=f5326c15812d0f49i0 [Jun 15 16:44:43] DEBUG[686] chan_sip.c: Header 2 [ 65]: From: "user2" ;tag=as22ef64a2 [Jun 15 16:44:43] DEBUG[686] chan_sip.c: Header 3 [ 59]: Call-ID: 4912056e767be8ec2685723436484077@x.x.x.6:5060 [Jun 15 16:44:43] DEBUG[686] chan_sip.c: Header 4 [ 16]: CSeq: 102 INVITE [Jun 15 16:44:43] DEBUG[686] chan_sip.c: Header 5 [ 57]: Via: SIP/2.0/UDP x.x.x.6:5060;branch=z9hG4bK1272eb06 [Jun 15 16:44:43] DEBUG[686] chan_sip.c: Header 6 [ 44]: Contact: "test1" [Jun 15 16:44:43] DEBUG[686] chan_sip.c: Header 7 [ 29]: Server: Cisco/SPA525G2-7.4.9c [Jun 15 16:44:43] DEBUG[686] chan_sip.c: Header 8 [ 17]: Content-Length: 0 [Jun 15 16:44:43] VERBOSE[686] chan_sip.c: [Jun 15 16:44:43] --- (9 headers 0 lines) --- [Jun 15 16:44:43] DEBUG[686] chan_sip.c: = Looking for Call ID: 4912056e767be8ec2685723436484077@x.x.x.6:5060 (Checking To) --From tag as22ef64a2 --To-tag f5326c15812d0f49i0 [Jun 15 16:44:43] DEBUG[686] chan_sip.c: (Provisional) Stopping retransmission (but retaining packet) on '4912056e767be8ec2685723436484077@x.x.x.6:5060' Request 102: Found [Jun 15 16:44:43] DEBUG[686] chan_sip.c: SIP response 180 to standard invite [Jun 15 16:44:43] DEBUG[686] chan_sip.c: build_route: Contact hop: "test1" [Jun 15 16:44:43] VERBOSE[686] chan_sip.c: [Jun 15 16:44:43] list_route: hop: [Jun 15 16:44:43] DEBUG[667] devicestate.c: No provider found, checking channel drivers for SIP - test1 [Jun 15 16:44:43] DEBUG[667] chan_sip.c: Checking device state for peer test1 [Jun 15 16:44:43] VERBOSE[841] app_dial.c: [Jun 15 16:44:43] -- SIP/test1-00000001 is ringing [Jun 15 16:44:43] DEBUG[667] devicestate.c: Changing state for SIP/test1 - state 6 (Ringing) [Jun 15 16:44:43] DEBUG[841] channel.c: Driver for channel 'SIP/mypeer1-00000000' does not support indication 3, emulating it [Jun 15 16:44:43] DEBUG[667] devicestate.c: device 'SIP/test1' state '6' [Jun 15 16:44:43] DEBUG[841] channel.c: Set channel SIP/mypeer1-00000000 to write format ulaw [Jun 15 16:44:43] DEBUG[841] channel.c: Set channel SIP/mypeer1-00000000 to write format slin [Jun 15 16:44:43] DEBUG[699] app_queue.c: Device 'SIP/test1' changed to state '6' (Ringing) [Jun 15 16:44:43] DEBUG[841] res_rtp_asterisk.c: Got RTCP report of 64 bytes [Jun 15 16:44:43] VERBOSE[686] chan_sip.c: [Jun 15 16:44:43] <--- SIP read from UDP:x.x.x.5:55010 ---> SIP/2.0 200 OK To: ;tag=f5326c15812d0f49i0 From: "user2" ;tag=as22ef64a2 Call-ID: 4912056e767be8ec2685723436484077@x.x.x.6:5060 CSeq: 102 INVITE Via: SIP/2.0/UDP x.x.x.6:5060;branch=z9hG4bK1272eb06 Contact: "test1" Server: Cisco/SPA525G2-7.4.9c Content-Length: 208 Allow: ACK, BYE, CANCEL, INFO, INVITE, NOTIFY, OPTIONS, REFER, UPDATE Supported: replaces Content-Type: application/sdp v=0 o=- 254427 254427 IN IP4 x.x.x.103 s=- c=IN IP4 x.x.x.5 t=0 0 m=audio 16480 RTP/AVP 9 101 a=rtpmap:9 G722/8000 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-15 a=ptime:30 a=sendrecv <-------------> [Jun 15 16:44:43] DEBUG[686] chan_sip.c: Header 0 [ 14]: SIP/2.0 200 OK [Jun 15 16:44:43] DEBUG[686] chan_sip.c: Header 1 [ 56]: To: ;tag=f5326c15812d0f49i0 [Jun 15 16:44:43] DEBUG[686] chan_sip.c: Header 2 [ 65]: From: "user2" ;tag=as22ef64a2 [Jun 15 16:44:43] DEBUG[686] chan_sip.c: Header 3 [ 59]: Call-ID: 4912056e767be8ec2685723436484077@x.x.x.6:5060 [Jun 15 16:44:43] DEBUG[686] chan_sip.c: Header 4 [ 16]: CSeq: 102 INVITE [Jun 15 16:44:43] DEBUG[686] chan_sip.c: Header 5 [ 57]: Via: SIP/2.0/UDP x.x.x.6:5060;branch=z9hG4bK1272eb06 [Jun 15 16:44:43] DEBUG[686] chan_sip.c: Header 6 [ 44]: Contact: "test1" [Jun 15 16:44:43] DEBUG[686] chan_sip.c: Header 7 [ 29]: Server: Cisco/SPA525G2-7.4.9c [Jun 15 16:44:43] DEBUG[686] chan_sip.c: Header 8 [ 19]: Content-Length: 208 [Jun 15 16:44:43] DEBUG[686] chan_sip.c: Header 9 [ 69]: Allow: ACK, BYE, CANCEL, INFO, INVITE, NOTIFY, OPTIONS, REFER, UPDATE [Jun 15 16:44:43] DEBUG[686] chan_sip.c: Header 10 [ 19]: Supported: replaces [Jun 15 16:44:43] DEBUG[686] chan_sip.c: Header 11 [ 29]: Content-Type: application/sdp [Jun 15 16:44:43] DEBUG[686] chan_sip.c: Header 12 [ 0]: [Jun 15 16:44:43] DEBUG[686] chan_sip.c: Body 0 [ 3]: v=0 [Jun 15 16:44:43] DEBUG[686] chan_sip.c: Body 1 [ 38]: o=- 254427 254427 IN IP4 x.x.x.103 [Jun 15 16:44:43] DEBUG[686] chan_sip.c: Body 2 [ 3]: s=- [Jun 15 16:44:43] DEBUG[686] chan_sip.c: Body 3 [ 22]: c=IN IP4 x.x.x.5 [Jun 15 16:44:43] DEBUG[686] chan_sip.c: Body 4 [ 5]: t=0 0 [Jun 15 16:44:43] DEBUG[686] chan_sip.c: Body 5 [ 27]: m=audio 16480 RTP/AVP 9 101 [Jun 15 16:44:43] DEBUG[686] chan_sip.c: Body 6 [ 20]: a=rtpmap:9 G722/8000 [Jun 15 16:44:43] DEBUG[686] chan_sip.c: Body 7 [ 33]: a=rtpmap:101 telephone-event/8000 [Jun 15 16:44:43] DEBUG[686] chan_sip.c: Body 8 [ 15]: a=fmtp:101 0-15 [Jun 15 16:44:43] DEBUG[686] chan_sip.c: Body 9 [ 10]: a=ptime:30 [Jun 15 16:44:43] DEBUG[686] chan_sip.c: Body 10 [ 10]: a=sendrecv [Jun 15 16:44:43] VERBOSE[686] chan_sip.c: [Jun 15 16:44:43] --- (12 headers 11 lines) --- [Jun 15 16:44:43] DEBUG[686] chan_sip.c: = Looking for Call ID: 4912056e767be8ec2685723436484077@x.x.x.6:5060 (Checking To) --From tag as22ef64a2 --To-tag f5326c15812d0f49i0 [Jun 15 16:44:43] DEBUG[686] chan_sip.c: Acked pending invite 102 [Jun 15 16:44:43] DEBUG[686] chan_sip.c: Stopping retransmission on '4912056e767be8ec2685723436484077@x.x.x.6:5060' of Request 102: Match Found [Jun 15 16:44:43] DEBUG[686] chan_sip.c: SIP response 200 to standard invite [Jun 15 16:44:43] DEBUG[686] chan_sip.c: Processing session-level SDP v=0... UNSUPPORTED OR FAILED. [Jun 15 16:44:43] DEBUG[686] chan_sip.c: Processing session-level SDP o=- 254427 254427 IN IP4 x.x.x.103... UNSUPPORTED OR FAILED. [Jun 15 16:44:43] DEBUG[686] chan_sip.c: Processing session-level SDP s=-... UNSUPPORTED OR FAILED. [Jun 15 16:44:43] DEBUG[686] netsock2.c: Splitting 'x.x.x.5' into... [Jun 15 16:44:43] DEBUG[686] netsock2.c: ...host 'x.x.x.5' and port ''. [Jun 15 16:44:43] DEBUG[686] chan_sip.c: Processing session-level SDP c=IN IP4 x.x.x.5... OK. [Jun 15 16:44:43] DEBUG[686] chan_sip.c: Processing session-level SDP t=0 0... UNSUPPORTED OR FAILED. [Jun 15 16:44:43] VERBOSE[686] chan_sip.c: [Jun 15 16:44:43] Found RTP audio format 9 [Jun 15 16:44:43] DEBUG[686] rtp_engine.c: Setting payload 9 based on m type on 0xb10a545c [Jun 15 16:44:43] VERBOSE[686] chan_sip.c: [Jun 15 16:44:43] Found RTP audio format 101 [Jun 15 16:44:43] DEBUG[686] rtp_engine.c: Setting payload 101 based on m type on 0xb10a545c [Jun 15 16:44:43] VERBOSE[686] chan_sip.c: [Jun 15 16:44:43] Found audio description format G722 for ID 9 [Jun 15 16:44:43] DEBUG[686] chan_sip.c: Processing media-level (audio) SDP a=rtpmap:9 G722/8000... OK. [Jun 15 16:44:43] VERBOSE[686] chan_sip.c: [Jun 15 16:44:43] Found audio description format telephone-event for ID 101 [Jun 15 16:44:43] DEBUG[686] chan_sip.c: Processing media-level (audio) SDP a=rtpmap:101 telephone-event/8000... OK. [Jun 15 16:44:43] DEBUG[686] chan_sip.c: Processing media-level (audio) SDP a=fmtp:101 0-15... UNSUPPORTED OR FAILED. [Jun 15 16:44:43] DEBUG[686] chan_sip.c: Processing media-level (audio) SDP a=ptime:30... OK. [Jun 15 16:44:43] DEBUG[686] chan_sip.c: Processing media-level (audio) SDP a=sendrecv... OK. [Jun 15 16:44:43] DEBUG[686] rtp_engine.c: Incorporating payload 9 on 0xb10a545c [Jun 15 16:44:43] DEBUG[686] rtp_engine.c: Incorporating payload 101 on 0xb10a545c [Jun 15 16:44:43] VERBOSE[686] chan_sip.c: [Jun 15 16:44:43] Capabilities: us - 0x1004 (ulaw|g722), peer - audio=0x1000 (g722)/video=0x0 (nothing)/text=0x0 (nothing), combined - 0x1000 (g722) [Jun 15 16:44:43] VERBOSE[686] chan_sip.c: [Jun 15 16:44:43] Non-codec capabilities (dtmf): us - 0x1 (telephone-event|), peer - 0x1 (telephone-event|), combined - 0x1 (telephone-event|) [Jun 15 16:44:43] DEBUG[686] res_rtp_asterisk.c: Setting RTCP address on RTP instance '0x9f61758' [Jun 15 16:44:43] VERBOSE[686] chan_sip.c: [Jun 15 16:44:43] Peer audio RTP is at port x.x.x.5:16480 [Jun 15 16:44:43] DEBUG[686] rtp_engine.c: Copying payload 9 from 0xb10a545c to 0x9f61904 [Jun 15 16:44:43] DEBUG[686] rtp_engine.c: Copying payload 101 from 0xb10a545c to 0x9f61904 [Jun 15 16:44:43] DEBUG[686] res_rtp_asterisk.c: Ignoring duplicate RTCP property on RTP instance '0x9f61758' [Jun 15 16:44:43] DEBUG[686] chan_sip.c: We're settling with these formats: 0x1000 (g722) [Jun 15 16:44:43] DEBUG[686] chan_sip.c: We have an owner, now see if we need to change this call [Jun 15 16:44:43] DEBUG[686] chan_sip.c: Oooh, we need to change our audio formats since our peer supports only 0x1000 (g722) and not 0x4 (ulaw) [Jun 15 16:44:43] DEBUG[686] channel.c: Set channel SIP/test1-00000001 to read format ulaw [Jun 15 16:44:43] DEBUG[686] channel.c: Set channel SIP/test1-00000001 to write format ulaw [Jun 15 16:44:43] DEBUG[686] chan_sip.c: Updating call counter for outgoing call [Jun 15 16:44:43] DEBUG[667] devicestate.c: No provider found, checking channel drivers for SIP - test1 [Jun 15 16:44:43] DEBUG[686] chan_sip.c: build_route: Contact hop: "test1" [Jun 15 16:44:43] DEBUG[667] chan_sip.c: Checking device state for peer test1 [Jun 15 16:44:43] VERBOSE[686] chan_sip.c: [Jun 15 16:44:43] list_route: hop: [Jun 15 16:44:43] DEBUG[667] devicestate.c: Changing state for SIP/test1 - state 2 (In use) [Jun 15 16:44:43] DEBUG[667] devicestate.c: device 'SIP/test1' state '2' [Jun 15 16:44:43] DEBUG[686] chan_sip.c: Strict routing enforced for session 4912056e767be8ec2685723436484077@x.x.x.6:5060 [Jun 15 16:44:43] VERBOSE[686] chan_sip.c: [Jun 15 16:44:43] set_destination: Parsing for address/port to send to [Jun 15 16:44:43] DEBUG[686] netsock2.c: Splitting 'x.x.x.5:55028' into... [Jun 15 16:44:43] DEBUG[686] netsock2.c: ...host 'x.x.x.5' and port '55028'. [Jun 15 16:44:43] DEBUG[699] app_queue.c: Device 'SIP/test1' changed to state '2' (In use) [Jun 15 16:44:43] VERBOSE[686] chan_sip.c: [Jun 15 16:44:43] set_destination: set destination to x.x.x.5:55028 [Jun 15 16:44:43] VERBOSE[686] chan_sip.c: [Jun 15 16:44:43] Transmitting (NAT) to x.x.x.5:55010: ACK sip:test1@x.x.x.5:55028 SIP/2.0 Via: SIP/2.0/UDP x.x.x.6:5060;branch=z9hG4bK5ad9ead3;rport Max-Forwards: 70 From: "user2" ;tag=as22ef64a2 To: ;tag=f5326c15812d0f49i0 Contact: Call-ID: 4912056e767be8ec2685723436484077@x.x.x.6:5060 CSeq: 102 ACK User-Agent: Asterisk PBX 1.8.14.0-rc1 Content-Length: 0 --- [Jun 15 16:44:43] DEBUG[686] chan_sip.c: Trying to put 'ACK sip:test1' onto UDP socket destined for x.x.x.5:55010 [Jun 15 16:44:43] DEBUG[667] devicestate.c: No provider found, checking channel drivers for SIP - test1 [Jun 15 16:44:43] VERBOSE[841] app_dial.c: [Jun 15 16:44:43] -- SIP/test1-00000001 answered SIP/mypeer1-00000000 [Jun 15 16:44:43] DEBUG[668] app_queue.c: Extension 'test1@localusers' changed to state '2' (In use) but we don't care because they're not a member of any queue. [Jun 15 16:44:43] DEBUG[667] chan_sip.c: Checking device state for peer test1 [Jun 15 16:44:43] DEBUG[667] devicestate.c: Changing state for SIP/test1 - state 2 (In use) [Jun 15 16:44:43] DEBUG[667] devicestate.c: device 'SIP/test1' state '2' [Jun 15 16:44:43] DEBUG[699] app_queue.c: Device 'SIP/test1' changed to state '2' (In use) [Jun 15 16:44:43] DEBUG[841] pbx.c: Launching 'AGI' [Jun 15 16:44:43] VERBOSE[841] pbx.c: [Jun 15 16:44:43] -- Executing [s@macro-record:1] AGI("SIP/test1-00000001", "macrohelper.agi") in new stack [Jun 15 16:44:43] VERBOSE[841] res_agi.c: [Jun 15 16:44:43] -- Launched AGI Script /var/asterisk/agi-bin/macrohelper.agi [Jun 15 16:44:43] VERBOSE[841] res_agi.c: [Jun 15 16:44:43] -- AGI Script macrohelper.agi completed, returning 0 [Jun 15 16:44:43] DEBUG[841] app_macro.c: Executed application: AGI [Jun 15 16:44:43] DEBUG[841] pbx.c: Result of 'RECORD_EXEC' is '1' [Jun 15 16:44:43] DEBUG[841] pbx.c: Expression result is '1' [Jun 15 16:44:43] DEBUG[841] pbx.c: Result of 'RECORD_EXTEN' is 'test1' [Jun 15 16:44:43] DEBUG[841] pbx.c: Result of 'EPOCH' is '1339796683' [Jun 15 16:44:43] DEBUG[841] pbx.c: Result of 'ARG1' is '5555550001' [Jun 15 16:44:43] DEBUG[841] pbx.c: Launching 'ExecIf' [Jun 15 16:44:43] VERBOSE[841] pbx.c: [Jun 15 16:44:43] -- Executing [s@macro-record:2] ExecIf("SIP/test1-00000001", "1?Monitor(wav,inbound-test1-1339796683-5555550001,bm)") in new stack [Jun 15 16:44:43] DEBUG[841] app_macro.c: Executed application: ExecIf [Jun 15 16:44:43] DEBUG[841] pbx.c: Evaluating 'RECORD_EXEC' (from 'RECORD_EXEC}" = "1"' len 11) [Jun 15 16:44:43] DEBUG[841] pbx.c: Result of 'RECORD_EXEC' is '1' [Jun 15 16:44:43] DEBUG[841] pbx.c: Expression result is '1' [Jun 15 16:44:43] DEBUG[841] pbx.c: Evaluating 'RECORD_EXTEN' (from 'RECORD_EXTEN}-${EPOCH}-${ARG1},bm)' len 12) [Jun 15 16:44:43] DEBUG[841] pbx.c: Result of 'RECORD_EXTEN' is 'test1' [Jun 15 16:44:43] DEBUG[841] pbx.c: Evaluating 'EPOCH' (from 'EPOCH}-${ARG1},bm)' len 5) [Jun 15 16:44:43] DEBUG[841] pbx.c: Result of 'EPOCH' is '1339796683' [Jun 15 16:44:43] DEBUG[841] pbx.c: Evaluating 'ARG1' (from 'ARG1},bm)' len 4) [Jun 15 16:44:43] DEBUG[841] pbx.c: Result of 'ARG1' is '5555550001' [Jun 15 16:44:43] DEBUG[841] pbx.c: Result of 'ARG2' is NULL [Jun 15 16:44:43] DEBUG[841] pbx.c: Expression result is '0' [Jun 15 16:44:43] DEBUG[841] pbx.c: Launching 'ExecIf' [Jun 15 16:44:43] VERBOSE[841] pbx.c: [Jun 15 16:44:43] -- Executing [s@macro-record:3] ExecIf("SIP/test1-00000001", "0?Macro(ishuman)") in new stack [Jun 15 16:44:43] DEBUG[841] app_macro.c: Executed application: ExecIf [Jun 15 16:44:43] DEBUG[841] pbx.c: Evaluating 'ARG2' (from 'ARG2}" = "humandetect"' len 4) [Jun 15 16:44:43] DEBUG[841] pbx.c: Result of 'ARG2' is NULL [Jun 15 16:44:43] DEBUG[841] pbx.c: Expression result is '0' [Jun 15 16:44:43] DEBUG[841] app_dial.c: Macro exited with status 0 [Jun 15 16:44:44] DEBUG[841] channel.c: Set channel SIP/mypeer1-00000000 to write format ulaw [Jun 15 16:44:44] DEBUG[841] features.c: bridge answer set, chan answer set [Jun 15 16:44:44] DEBUG[841] features.c: Removing dialed interfaces datastore on SIP/test1-00000001 since we're bridging [Jun 15 16:44:44] DEBUG[841] res_rtp_asterisk.c: Setting the marker bit due to a source update [Jun 15 16:44:44] DEBUG[841] res_rtp_asterisk.c: Setting the marker bit due to a source update [Jun 15 16:44:44] DEBUG[841] res_rtp_asterisk.c: Ooh, format changed from unknown to g722 [Jun 15 16:44:44] DEBUG[841] res_rtp_asterisk.c: Created smoother: format: g722 ms: 20 len: 160 [Jun 15 16:44:45] DEBUG[841] res_rtp_asterisk.c: - RTP 2833 Event: 0000000b (len = 4) [Jun 15 16:44:45] DEBUG[841] res_rtp_asterisk.c: Sending dtmf: 35 (#), at x.x.x.5:16480 [Jun 15 16:44:45] DTMF[841] channel.c: DTMF begin '#' received on SIP/test1-00000001 [Jun 15 16:44:45] DTMF[841] channel.c: DTMF begin passthrough '#' on SIP/test1-00000001 [Jun 15 16:44:45] DEBUG[841] channel.c: Got DTMF begin on channel (SIP/test1-00000001) [Jun 15 16:44:45] DEBUG[841] res_rtp_asterisk.c: Setting the marker bit due to a source update [Jun 15 16:44:45] DEBUG[841] res_rtp_asterisk.c: Setting the marker bit due to a source update [Jun 15 16:44:45] DEBUG[841] channel.c: Bridge stops bridging channels SIP/mypeer1-00000000 and SIP/test1-00000001 [Jun 15 16:44:45] DEBUG[841] features.c: Feature detected: fname=Blind Transfer sname=blindxfer exten=# [Jun 15 16:44:45] DEBUG[841] channel.c: Set channel SIP/mypeer1-00000000 to write format slin [Jun 15 16:44:45] DEBUG[841] channel.c: Started silence generator on 'SIP/mypeer1-00000000' [Jun 15 16:44:45] DEBUG[841] features.c: Not passing DTMF through, since it may be a feature code [Jun 15 16:44:45] DEBUG[841] res_rtp_asterisk.c: Setting the marker bit due to a source update [Jun 15 16:44:45] DEBUG[841] res_rtp_asterisk.c: Setting the marker bit due to a source update [Jun 15 16:44:45] DEBUG[841] res_rtp_asterisk.c: - RTP 2833 Event: 0000000b (len = 4) [Jun 15 16:44:45] DEBUG[841] res_rtp_asterisk.c: - RTP 2833 Event: 0000000b (len = 4) [Jun 15 16:44:45] DEBUG[841] res_rtp_asterisk.c: Difference is 736, ms is 112 [Jun 15 16:44:45] DEBUG[841] res_rtp_asterisk.c: - RTP 2833 Event: 0000000b (len = 4) [Jun 15 16:44:45] DEBUG[841] res_rtp_asterisk.c: - RTP 2833 Event: 0000000b (len = 4) [Jun 15 16:44:45] DEBUG[841] res_rtp_asterisk.c: - RTP 2833 Event: 0000000b (len = 4) [Jun 15 16:44:45] DEBUG[841] res_rtp_asterisk.c: - RTP 2833 Event: 0000000b (len = 4) [Jun 15 16:44:45] DEBUG[841] res_rtp_asterisk.c: - RTP 2833 Event: 0000000b (len = 4) [Jun 15 16:44:45] DEBUG[841] res_rtp_asterisk.c: - RTP 2833 Event: 0000000b (len = 4) [Jun 15 16:44:45] DEBUG[841] res_rtp_asterisk.c: - RTP 2833 Event: 0000000b (len = 4) [Jun 15 16:44:45] DEBUG[841] res_rtp_asterisk.c: Sending dtmf: 35 (#), at x.x.x.5:16480 [Jun 15 16:44:45] DTMF[841] channel.c: DTMF end '#' received on SIP/test1-00000001, duration 90 ms [Jun 15 16:44:45] DTMF[841] channel.c: DTMF end accepted with begin '#' on SIP/test1-00000001 [Jun 15 16:44:45] DTMF[841] channel.c: DTMF end '#' detected to have actual duration 74 on the wire, emulation will be triggered on SIP/test1-00000001 [Jun 15 16:44:45] DTMF[841] channel.c: DTMF end '#' has duration 74 but want minimum 180, emulating on SIP/test1-00000001 [Jun 15 16:44:45] DEBUG[841] res_rtp_asterisk.c: - RTP 2833 Event: 0000000b (len = 4) [Jun 15 16:44:45] DEBUG[841] res_rtp_asterisk.c: - RTP 2833 Event: 0000000b (len = 4) [Jun 15 16:44:45] DTMF[841] channel.c: DTMF end emulation of '#' queued on SIP/test1-00000001 [Jun 15 16:44:45] DEBUG[841] channel.c: Got DTMF end on channel (SIP/test1-00000001) [Jun 15 16:44:45] DEBUG[841] res_rtp_asterisk.c: Setting the marker bit due to a source update [Jun 15 16:44:45] DEBUG[841] res_rtp_asterisk.c: Setting the marker bit due to a source update [Jun 15 16:44:45] DEBUG[841] channel.c: Bridge stops bridging channels SIP/mypeer1-00000000 and SIP/test1-00000001 [Jun 15 16:44:45] DEBUG[841] channel.c: Stopped silence generator on 'SIP/mypeer1-00000000' [Jun 15 16:44:45] DEBUG[841] channel.c: Set channel SIP/mypeer1-00000000 to write format ulaw [Jun 15 16:44:45] DEBUG[841] features.c: Feature interpret: chan=SIP/mypeer1-00000000, peer=SIP/test1-00000001, code=#, sense=2, features=18, dynamic=automon#automon [Jun 15 16:44:45] DEBUG[841] features.c: Feature detected: fname=Blind Transfer sname=blindxfer exten=# [Jun 15 16:44:45] DEBUG[841] features.c: Executing Blind Transfer SIP/mypeer1-00000000, SIP/test1-00000001 (sense=2) [Jun 15 16:44:45] DEBUG[841] res_rtp_asterisk.c: Setting the marker bit due to a source update [Jun 15 16:44:45] VERBOSE[841] res_musiconhold.c: [Jun 15 16:44:45] -- Started music on hold, class 'default', on SIP/mypeer1-00000000 [Jun 15 16:44:45] DEBUG[843] channel.c: Set channel SIP/mypeer1-00000000 to write format slin [Jun 15 16:44:45] DEBUG[841] channel.c: Set channel SIP/test1-00000001 to write format gsm [Jun 15 16:44:45] DEBUG[843] res_musiconhold.c: SIP/mypeer1-00000000 Opened file 0 '/var/asterisk/moh-native/1/30' [Jun 15 16:44:45] VERBOSE[841] file.c: [Jun 15 16:44:45] -- Playing 'pbx-transfer.gsm' (language 'en') [Jun 15 16:44:46] DEBUG[841] channel.c: Set channel SIP/test1-00000001 to write format ulaw [Jun 15 16:44:46] DEBUG[841] channel.c: Set channel SIP/test1-00000001 to write format slin [Jun 15 16:44:46] DEBUG[841] res_rtp_asterisk.c: - RTP 2833 Event: 00000003 (len = 4) [Jun 15 16:44:46] DEBUG[841] res_rtp_asterisk.c: Sending dtmf: 51 (3), at x.x.x.5:16480 [Jun 15 16:44:46] DTMF[841] channel.c: DTMF begin '3' received on SIP/test1-00000001 [Jun 15 16:44:46] DTMF[841] channel.c: DTMF begin ignored '3' on SIP/test1-00000001 [Jun 15 16:44:46] DEBUG[841] res_rtp_asterisk.c: - RTP 2833 Event: 00000003 (len = 4) [Jun 15 16:44:46] DEBUG[841] res_rtp_asterisk.c: - RTP 2833 Event: 00000003 (len = 4) [Jun 15 16:44:46] DEBUG[841] res_rtp_asterisk.c: - RTP 2833 Event: 00000003 (len = 4) [Jun 15 16:44:46] DEBUG[841] res_rtp_asterisk.c: - RTP 2833 Event: 00000003 (len = 4) [Jun 15 16:44:46] DEBUG[841] res_rtp_asterisk.c: - RTP 2833 Event: 00000003 (len = 4) [Jun 15 16:44:46] DEBUG[841] res_rtp_asterisk.c: - RTP 2833 Event: 00000003 (len = 4) [Jun 15 16:44:47] DEBUG[841] res_rtp_asterisk.c: - RTP 2833 Event: 00000003 (len = 4) [Jun 15 16:44:47] DEBUG[841] res_rtp_asterisk.c: - RTP 2833 Event: 00000003 (len = 4) [Jun 15 16:44:47] DEBUG[841] res_rtp_asterisk.c: - RTP 2833 Event: 00000003 (len = 4) [Jun 15 16:44:47] DEBUG[841] res_rtp_asterisk.c: - RTP 2833 Event: 00000003 (len = 4) [Jun 15 16:44:47] DEBUG[841] res_rtp_asterisk.c: Sending dtmf: 51 (3), at x.x.x.5:16480 [Jun 15 16:44:47] DTMF[841] channel.c: DTMF end '3' received on SIP/test1-00000001, duration 90 ms [Jun 15 16:44:47] DTMF[841] channel.c: DTMF end passthrough '3' on SIP/test1-00000001 [Jun 15 16:44:47] DEBUG[841] channel.c: Set channel SIP/test1-00000001 to write format ulaw [Jun 15 16:44:47] DEBUG[841] res_rtp_asterisk.c: - RTP 2833 Event: 00000003 (len = 4) [Jun 15 16:44:47] DEBUG[841] res_rtp_asterisk.c: - RTP 2833 Event: 00000003 (len = 4) [Jun 15 16:44:47] DEBUG[841] res_rtp_asterisk.c: - RTP 2833 Event: 00000000 (len = 4) [Jun 15 16:44:47] DEBUG[841] res_rtp_asterisk.c: Sending dtmf: 48 (0), at x.x.x.5:16480 [Jun 15 16:44:47] DTMF[841] channel.c: DTMF begin '0' received on SIP/test1-00000001 [Jun 15 16:44:47] DTMF[841] channel.c: DTMF begin ignored '0' on SIP/test1-00000001 [Jun 15 16:44:47] DEBUG[841] res_rtp_asterisk.c: - RTP 2833 Event: 00000000 (len = 4) [Jun 15 16:44:47] DEBUG[841] res_rtp_asterisk.c: - RTP 2833 Event: 00000000 (len = 4) [Jun 15 16:44:47] DEBUG[841] res_rtp_asterisk.c: - RTP 2833 Event: 00000000 (len = 4) [Jun 15 16:44:47] DEBUG[841] res_rtp_asterisk.c: - RTP 2833 Event: 00000000 (len = 4) [Jun 15 16:44:47] DEBUG[841] res_rtp_asterisk.c: - RTP 2833 Event: 00000000 (len = 4) [Jun 15 16:44:47] DEBUG[841] res_rtp_asterisk.c: - RTP 2833 Event: 00000000 (len = 4) [Jun 15 16:44:47] DEBUG[841] res_rtp_asterisk.c: - RTP 2833 Event: 00000000 (len = 4) [Jun 15 16:44:47] DEBUG[841] res_rtp_asterisk.c: - RTP 2833 Event: 00000000 (len = 4) [Jun 15 16:44:47] DEBUG[841] res_rtp_asterisk.c: - RTP 2833 Event: 00000000 (len = 4) [Jun 15 16:44:47] DEBUG[841] res_rtp_asterisk.c: - RTP 2833 Event: 00000000 (len = 4) [Jun 15 16:44:47] DEBUG[841] res_rtp_asterisk.c: Sending dtmf: 48 (0), at x.x.x.5:16480 [Jun 15 16:44:47] DTMF[841] channel.c: DTMF end '0' received on SIP/test1-00000001, duration 90 ms [Jun 15 16:44:47] DTMF[841] channel.c: DTMF end passthrough '0' on SIP/test1-00000001 [Jun 15 16:44:47] DEBUG[841] res_rtp_asterisk.c: - RTP 2833 Event: 00000000 (len = 4) [Jun 15 16:44:48] DEBUG[843] res_rtp_asterisk.c: Got RTCP report of 64 bytes [Jun 15 16:44:48] VERBOSE[681] chan_iax2.c: [Jun 15 16:44:48] Rx-Frame Retry[ No] -- OSeqno: 000 ISeqno: 000 Type: IAX Subclass: REGREQ [Jun 15 16:44:48] VERBOSE[681] chan_iax2.c: [Jun 15 16:44:48] Timestamp: 00003ms SCall: 06657 DCall: 00000 [127.0.0.1:4572] [Jun 15 16:44:48] VERBOSE[681] chan_iax2.c: [Jun 15 16:44:48] USERNAME : fax002 [Jun 15 16:44:48] VERBOSE[681] chan_iax2.c: [Jun 15 16:44:48] REFRESH : 60 [Jun 15 16:44:48] VERBOSE[681] chan_iax2.c: [Jun 15 16:44:48] [Jun 15 16:44:48] DEBUG[681] chan_iax2.c: Determining if address 127.0.0.1 with username fax002 requires calltoken validation. Optional = 0 calltoken_required = 3 [Jun 15 16:44:48] DEBUG[681] chan_iax2.c: ip callno count incremented to 11 for 127.0.0.1 [Jun 15 16:44:48] DEBUG[681] chan_iax2.c: Creating new call structure 1892 [Jun 15 16:44:48] DEBUG[681] chan_iax2.c: Received packet 0, (6, 13) [Jun 15 16:44:48] DEBUG[681] chan_iax2.c: IAX subclass 13 received [Jun 15 16:44:48] DEBUG[681] chan_iax2.c: For call=1892, set last=3 [Jun 15 16:44:48] DEBUG[667] devicestate.c: No provider found, checking channel drivers for IAX2 - fax002 [Jun 15 16:44:48] DEBUG[667] chan_iax2.c: Checking device state for device fax002 [Jun 15 16:44:48] DEBUG[673] chan_iax2.c: Sending 14 on 1892/6657 to 127.0.0.1:4572 [Jun 15 16:44:48] DEBUG[667] chan_iax2.c: iax2_devicestate: Found peer. What's device state of fax002? addr=2130706433, defaddr=0 maxms=0, lastms=0 [Jun 15 16:44:48] VERBOSE[673] chan_iax2.c: [Jun 15 16:44:48] Tx-Frame Retry[000] -- OSeqno: 000 ISeqno: 001 Type: IAX Subclass: REGAUTH [Jun 15 16:44:48] VERBOSE[673] chan_iax2.c: [Jun 15 16:44:48] Timestamp: 00014ms SCall: 01892 DCall: 06657 [127.0.0.1:4572] [Jun 15 16:44:48] VERBOSE[673] chan_iax2.c: [Jun 15 16:44:48] AUTHMETHODS : 3 [Jun 15 16:44:48] DEBUG[667] devicestate.c: Changing state for IAX2/fax002 - state 0 (Unknown) [Jun 15 16:44:48] VERBOSE[673] chan_iax2.c: [Jun 15 16:44:48] CHALLENGE : \x34\x38\x36\x38\x35\x37\x36\x34\x32 [Jun 15 16:44:48] VERBOSE[673] chan_iax2.c: [Jun 15 16:44:48] USERNAME : fax002 [Jun 15 16:44:48] DEBUG[667] devicestate.c: device 'IAX2/fax002' state '0' [Jun 15 16:44:48] VERBOSE[673] chan_iax2.c: [Jun 15 16:44:48] [Jun 15 16:44:48] VERBOSE[680] chan_iax2.c: [Jun 15 16:44:48] Rx-Frame Retry[ No] -- OSeqno: 001 ISeqno: 001 Type: IAX Subclass: REGREQ [Jun 15 16:44:48] DEBUG[699] app_queue.c: Device 'IAX2/fax002' changed to state '0' (Unknown) but we don't care because they're not a member of any queue. [Jun 15 16:44:48] VERBOSE[680] chan_iax2.c: [Jun 15 16:44:48] Timestamp: 00010ms SCall: 06657 DCall: 01892 [127.0.0.1:4572] [Jun 15 16:44:48] VERBOSE[680] chan_iax2.c: [Jun 15 16:44:48] USERNAME : fax002 [Jun 15 16:44:48] VERBOSE[680] chan_iax2.c: [Jun 15 16:44:48] MD5 RESULT : 984f9e359817417628f4f1bcb135b700 [Jun 15 16:44:48] VERBOSE[680] chan_iax2.c: [Jun 15 16:44:48] REFRESH : 60 [Jun 15 16:44:48] VERBOSE[680] chan_iax2.c: [Jun 15 16:44:48] [Jun 15 16:44:48] DEBUG[680] chan_iax2.c: Received packet 1, (6, 13) [Jun 15 16:44:48] DEBUG[680] chan_iax2.c: Cancelling transmission of packet 0 [Jun 15 16:44:48] DEBUG[680] chan_iax2.c: IAX subclass 13 received [Jun 15 16:44:48] DEBUG[680] chan_iax2.c: For call=1892, set last=10 [Jun 15 16:44:48] DEBUG[667] devicestate.c: No provider found, checking channel drivers for IAX2 - fax002 [Jun 15 16:44:48] DEBUG[667] chan_iax2.c: Checking device state for device fax002 [Jun 15 16:44:48] DEBUG[667] chan_iax2.c: iax2_devicestate: Found peer. What's device state of fax002? addr=2130706433, defaddr=0 maxms=0, lastms=0 [Jun 15 16:44:48] DEBUG[667] devicestate.c: Changing state for IAX2/fax002 - state 0 (Unknown) [Jun 15 16:44:48] DEBUG[667] devicestate.c: device 'IAX2/fax002' state '0' [Jun 15 16:44:48] DEBUG[673] chan_iax2.c: Sending 29 on 1892/6657 to 127.0.0.1:4572 [Jun 15 16:44:48] DEBUG[699] app_queue.c: Device 'IAX2/fax002' changed to state '0' (Unknown) but we don't care because they're not a member of any queue. [Jun 15 16:44:48] VERBOSE[673] chan_iax2.c: [Jun 15 16:44:48] Tx-Frame Retry[000] -- OSeqno: 001 ISeqno: 002 Type: IAX Subclass: REGACK [Jun 15 16:44:48] VERBOSE[673] chan_iax2.c: [Jun 15 16:44:48] Timestamp: 00029ms SCall: 01892 DCall: 06657 [127.0.0.1:4572] [Jun 15 16:44:48] VERBOSE[673] chan_iax2.c: [Jun 15 16:44:48] USERNAME : fax002 [Jun 15 16:44:48] VERBOSE[673] chan_iax2.c: [Jun 15 16:44:48] DATE TIME : 2012-06-15 16:44:48 [Jun 15 16:44:48] VERBOSE[673] chan_iax2.c: [Jun 15 16:44:48] REFRESH : 60 [Jun 15 16:44:48] VERBOSE[673] chan_iax2.c: [Jun 15 16:44:48] APPARENT ADDRES : IPV4 127.0.0.1:4572 [Jun 15 16:44:48] VERBOSE[673] chan_iax2.c: [Jun 15 16:44:48] CALLING NUMBER : 8476039009 [Jun 15 16:44:48] VERBOSE[673] chan_iax2.c: [Jun 15 16:44:48] CALLING NAME : Fax002 [Jun 15 16:44:48] VERBOSE[673] chan_iax2.c: [Jun 15 16:44:48] [Jun 15 16:44:48] VERBOSE[682] chan_iax2.c: [Jun 15 16:44:48] Rx-Frame Retry[ No] -- OSeqno: 002 ISeqno: 002 Type: IAX Subclass: ACK [Jun 15 16:44:48] VERBOSE[682] chan_iax2.c: [Jun 15 16:44:48] Timestamp: 00029ms SCall: 06657 DCall: 01892 [127.0.0.1:4572] [Jun 15 16:44:48] DEBUG[682] chan_iax2.c: Received packet 2, (6, 4) [Jun 15 16:44:48] DEBUG[682] chan_iax2.c: Cancelling transmission of packet 1 [Jun 15 16:44:48] DEBUG[682] chan_iax2.c: Really destroying 1892, having been acked on final message [Jun 15 16:44:48] DEBUG[682] chan_iax2.c: schedule decrement of callno used for 127.0.0.1 in 60 seconds [Jun 15 16:44:50] DEBUG[841] features.c: Checking if 30@outbound is a parking exten [Jun 15 16:44:50] DEBUG[841] features.c: Found Parking lot: parkinglot_test [Jun 15 16:44:50] DEBUG[841] res_rtp_asterisk.c: Setting the marker bit due to a source update [Jun 15 16:44:50] VERBOSE[841] res_musiconhold.c: [Jun 15 16:44:50] -- Stopped music on hold on SIP/mypeer1-00000000 [Jun 15 16:44:50] DEBUG[841] channel.c: Set channel SIP/mypeer1-00000000 to write format ulaw [Jun 15 16:44:50] DEBUG[841] features.c: Multiparking: parkinglot_test refcount now 3 [Jun 15 16:44:50] DEBUG[841] features.c: Parking lot: parkinglot_test [Jun 15 16:44:50] DEBUG[841] channel.c: Planning to masquerade channel SIP/mypeer1-00000000 into the structure of Parked/SIP/mypeer1-00000000 [Jun 15 16:44:50] DEBUG[841] channel.c: Done planning to masquerade channel SIP/mypeer1-00000000 into the structure of Parked/SIP/mypeer1-00000000 [Jun 15 16:44:50] DEBUG[841] channel.c: Actually Masquerading SIP/mypeer1-00000000(6) into the structure of Parked/SIP/mypeer1-00000000(0) [Jun 15 16:44:50] DEBUG[841] channel.c: Putting channel SIP/mypeer1-00000000 in ulaw/ulaw formats [Jun 15 16:44:50] DEBUG[841] chan_sip.c: SIP Fixup: New owner for dialogue 7b8cc12540233d03459e98a54f7dd5ac@x.x.x.134:5060: SIP/mypeer1-00000000 (Old parent: Parked/SIP/mypeer1-00000000) [Jun 15 16:44:50] DEBUG[841] channel.c: Done Masquerading SIP/mypeer1-00000000 (6) [Jun 15 16:44:50] DEBUG[841] res_rtp_asterisk.c: Changing ssrc from 465352744 to 1982088603 due to a source change [Jun 15 16:44:50] DEBUG[841] res_rtp_asterisk.c: Setting the marker bit due to a source update [Jun 15 16:44:50] VERBOSE[841] res_musiconhold.c: [Jun 15 16:44:50] -- Started music on hold, class 'default', on SIP/mypeer1-00000000 [Jun 15 16:44:50] VERBOSE[841] features.c: [Jun 15 16:44:50] == Parked SIP/mypeer1-00000000 on 58 (lot parkinglot_test). Will timeout back to extension [macro-dialext] s, 9 in 15 seconds [Jun 15 16:44:50] DEBUG[841] features.c: peer->name: SIP/test1-00000001 [Jun 15 16:44:50] DEBUG[841] features.c: args->orig_chan_name: -none- [Jun 15 16:44:50] DEBUG[841] features.c: pu->peername: SIP/test1-00000001 [Jun 15 16:44:50] DEBUG[841] features.c: AMI ParkedCall Channel: SIP/mypeer1-00000000 [Jun 15 16:44:50] DEBUG[841] features.c: AMI ParkedCall From: SIP/test1-00000001 [Jun 15 16:44:50] DEBUG[841] pbx.c: Added extension '58' priority 1 to parkedcallshidden_2 (0xb79e6810) [Jun 15 16:44:50] VERBOSE[841] pbx.c: [Jun 15 16:44:50] -- Added extension '58' priority 1 to parkedcallshidden_2 [Jun 15 16:44:50] DEBUG[841] features.c: Notification of state change to metermaids 58@parkedcallshidden_2 to state 'In use'[Jun 15 16:44:50] DEBUG[841] devicestate.c: device 'park:58@parkedcallshidden_2' state '2' [Jun 15 16:44:50] DEBUG[841] channel.c: Set channel SIP/test1-00000001 to write format gsm [Jun 15 16:44:50] DEBUG[699] app_queue.c: Device 'park:58@parkedcallshidden_2' changed to state '2' (In use) but we don't care because they're not a member of any queue. [Jun 15 16:44:50] DEBUG[841] res_rtp_asterisk.c: Difference is 27856, ms is 3502 [Jun 15 16:44:50] VERBOSE[841] file.c: [Jun 15 16:44:50] -- Playing 'digits/5.gsm' (language 'en') [Jun 15 16:44:50] VERBOSE[675] chan_iax2.c: [Jun 15 16:44:50] Rx-Frame Retry[ No] -- OSeqno: 000 ISeqno: 000 Type: IAX Subclass: REGREQ [Jun 15 16:44:50] VERBOSE[675] chan_iax2.c: [Jun 15 16:44:50] Timestamp: 00003ms SCall: 06657 DCall: 00000 [127.0.0.1:4575] [Jun 15 16:44:50] VERBOSE[675] chan_iax2.c: [Jun 15 16:44:50] USERNAME : fax005 [Jun 15 16:44:50] VERBOSE[675] chan_iax2.c: [Jun 15 16:44:50] REFRESH : 60 [Jun 15 16:44:50] VERBOSE[675] chan_iax2.c: [Jun 15 16:44:50] [Jun 15 16:44:50] DEBUG[675] chan_iax2.c: Determining if address 127.0.0.1 with username fax005 requires calltoken validation. Optional = 0 calltoken_required = 3 [Jun 15 16:44:50] DEBUG[675] chan_iax2.c: ip callno count incremented to 12 for 127.0.0.1 [Jun 15 16:44:50] DEBUG[675] chan_iax2.c: Creating new call structure 5717 [Jun 15 16:44:50] DEBUG[675] chan_iax2.c: Received packet 0, (6, 13) [Jun 15 16:44:50] DEBUG[675] chan_iax2.c: IAX subclass 13 received [Jun 15 16:44:50] DEBUG[675] chan_iax2.c: For call=5717, set last=3 [Jun 15 16:44:50] DEBUG[667] devicestate.c: No provider found, checking channel drivers for IAX2 - fax005 [Jun 15 16:44:50] DEBUG[667] chan_iax2.c: Checking device state for device fax005 [Jun 15 16:44:50] DEBUG[673] chan_iax2.c: Sending 10 on 5717/6657 to 127.0.0.1:4575 [Jun 15 16:44:50] DEBUG[667] chan_iax2.c: iax2_devicestate: Found peer. What's device state of fax005? addr=2130706433, defaddr=0 maxms=0, lastms=0 [Jun 15 16:44:50] VERBOSE[673] chan_iax2.c: [Jun 15 16:44:50] Tx-Frame Retry[000] -- OSeqno: 000 ISeqno: 001 Type: IAX Subclass: REGAUTH [Jun 15 16:44:50] VERBOSE[673] chan_iax2.c: [Jun 15 16:44:50] Timestamp: 00010ms SCall: 05717 DCall: 06657 [127.0.0.1:4575] [Jun 15 16:44:50] VERBOSE[673] chan_iax2.c: [Jun 15 16:44:50] AUTHMETHODS : 3 [Jun 15 16:44:50] VERBOSE[673] chan_iax2.c: [Jun 15 16:44:50] CHALLENGE : \x31\x31\x35\x36\x36\x37\x34\x37\x31 [Jun 15 16:44:50] VERBOSE[673] chan_iax2.c: [Jun 15 16:44:50] USERNAME : fax005 [Jun 15 16:44:50] VERBOSE[673] chan_iax2.c: [Jun 15 16:44:50] [Jun 15 16:44:50] VERBOSE[676] chan_iax2.c: [Jun 15 16:44:50] Rx-Frame Retry[ No] -- OSeqno: 001 ISeqno: 001 Type: IAX Subclass: REGREQ [Jun 15 16:44:50] VERBOSE[676] chan_iax2.c: [Jun 15 16:44:50] Timestamp: 00006ms SCall: 06657 DCall: 05717 [127.0.0.1:4575] [Jun 15 16:44:50] VERBOSE[676] chan_iax2.c: [Jun 15 16:44:50] USERNAME : fax005 [Jun 15 16:44:50] DEBUG[667] devicestate.c: Changing state for IAX2/fax005 - state 0 (Unknown) [Jun 15 16:44:50] VERBOSE[676] chan_iax2.c: [Jun 15 16:44:50] MD5 RESULT : be54e8e5b4490ca12fd94c7daeafdb81 [Jun 15 16:44:50] DEBUG[667] devicestate.c: device 'IAX2/fax005' state '0' [Jun 15 16:44:50] VERBOSE[676] chan_iax2.c: [Jun 15 16:44:50] REFRESH : 60 [Jun 15 16:44:50] VERBOSE[676] chan_iax2.c: [Jun 15 16:44:50] [Jun 15 16:44:50] DEBUG[676] chan_iax2.c: Received packet 1, (6, 13) [Jun 15 16:44:50] DEBUG[676] chan_iax2.c: Cancelling transmission of packet 0 [Jun 15 16:44:50] DEBUG[676] chan_iax2.c: IAX subclass 13 received [Jun 15 16:44:50] DEBUG[699] app_queue.c: Device 'IAX2/fax005' changed to state '0' (Unknown) but we don't care because they're not a member of any queue. [Jun 15 16:44:50] DEBUG[676] chan_iax2.c: For call=5717, set last=6 [Jun 15 16:44:50] DEBUG[667] devicestate.c: No provider found, checking channel drivers for IAX2 - fax005 [Jun 15 16:44:50] DEBUG[667] chan_iax2.c: Checking device state for device fax005 [Jun 15 16:44:50] DEBUG[667] chan_iax2.c: iax2_devicestate: Found peer. What's device state of fax005? addr=2130706433, defaddr=0 maxms=0, lastms=0 [Jun 15 16:44:50] DEBUG[667] devicestate.c: Changing state for IAX2/fax005 - state 0 (Unknown) [Jun 15 16:44:50] DEBUG[667] devicestate.c: device 'IAX2/fax005' state '0' [Jun 15 16:44:50] DEBUG[673] chan_iax2.c: Sending 22 on 5717/6657 to 127.0.0.1:4575 [Jun 15 16:44:50] VERBOSE[673] chan_iax2.c: [Jun 15 16:44:50] Tx-Frame Retry[000] -- OSeqno: 001 ISeqno: 002 Type: IAX Subclass: REGACK [Jun 15 16:44:50] VERBOSE[673] chan_iax2.c: [Jun 15 16:44:50] Timestamp: 00022ms SCall: 05717 DCall: 06657 [127.0.0.1:4575] [Jun 15 16:44:50] DEBUG[699] app_queue.c: Device 'IAX2/fax005' changed to state '0' (Unknown) but we don't care because they're not a member of any queue. [Jun 15 16:44:50] VERBOSE[673] chan_iax2.c: [Jun 15 16:44:50] USERNAME : fax005 [Jun 15 16:44:50] VERBOSE[673] chan_iax2.c: [Jun 15 16:44:50] DATE TIME : 2012-06-15 16:44:50 [Jun 15 16:44:50] VERBOSE[673] chan_iax2.c: [Jun 15 16:44:50] REFRESH : 60 [Jun 15 16:44:50] VERBOSE[673] chan_iax2.c: [Jun 15 16:44:50] APPARENT ADDRES : IPV4 127.0.0.1:4575 [Jun 15 16:44:50] VERBOSE[673] chan_iax2.c: [Jun 15 16:44:50] CALLING NUMBER : 8476039009 [Jun 15 16:44:50] VERBOSE[673] chan_iax2.c: [Jun 15 16:44:50] CALLING NAME : Fax005 [Jun 15 16:44:50] VERBOSE[673] chan_iax2.c: [Jun 15 16:44:50] [Jun 15 16:44:50] VERBOSE[677] chan_iax2.c: [Jun 15 16:44:50] Rx-Frame Retry[ No] -- OSeqno: 002 ISeqno: 002 Type: IAX Subclass: ACK [Jun 15 16:44:50] VERBOSE[677] chan_iax2.c: [Jun 15 16:44:50] Timestamp: 00022ms SCall: 06657 DCall: 05717 [127.0.0.1:4575] [Jun 15 16:44:50] DEBUG[677] chan_iax2.c: Received packet 2, (6, 4) [Jun 15 16:44:50] DEBUG[677] chan_iax2.c: Cancelling transmission of packet 1 [Jun 15 16:44:50] DEBUG[677] chan_iax2.c: Really destroying 5717, having been acked on final message [Jun 15 16:44:50] DEBUG[677] chan_iax2.c: schedule decrement of callno used for 127.0.0.1 in 60 seconds [Jun 15 16:44:51] VERBOSE[686] chan_sip.c: [Jun 15 16:44:51] <--- SIP read from UDP:x.x.x.134:42225 ---> OPTIONS <-------------> [Jun 15 16:44:51] DEBUG[686] chan_sip.c: Header 0 [ 7]: OPTIONS [Jun 15 16:44:51] DEBUG[841] channel.c: Set channel SIP/test1-00000001 to write format ulaw [Jun 15 16:44:51] DEBUG[841] channel.c: Set channel SIP/test1-00000001 to write format gsm [Jun 15 16:44:51] VERBOSE[841] file.c: [Jun 15 16:44:51] -- Playing 'digits/8.gsm' (language 'en') [Jun 15 16:44:51] DEBUG[841] channel.c: Set channel SIP/test1-00000001 to write format ulaw [Jun 15 16:44:51] DEBUG[841] features.c: Multiparking: parkinglot_test refcount now 2 [Jun 15 16:44:51] DEBUG[841] cdr_mysql.c: Inserting a CDR record. [Jun 15 16:44:51] DEBUG[841] cdr_mysql.c: SQL command as follows: INSERT INTO cdr (`calldate`,`clid`,`src`,`dst`,`dcontext`,`channel`,`dstchannel`,`lastapp`,`lastdata`,`duration`,`billsec`,`disposition`,`amaflags`,`uniqueid`) VALUES ('2012-06-15 16:44:38','\"user2\" <+15555550001>','+15555550001','s','macro-dialext','SIP/mypeer1-00000000','SIP/test1-00000001','Dial','SIP/test1,30,rtwWM(record^5555550001)','13','8','ANSWERED','3','1339796678.0') [Jun 15 16:44:51] DEBUG[841] channel.c: Hanging up channel 'SIP/test1-00000001' [Jun 15 16:44:51] DEBUG[841] chan_sip.c: Hanging up zombie call. Be scared. [Jun 15 16:44:51] DEBUG[841] chan_sip.c: update_call_counter(test1) - decrement call limit counter on hangup [Jun 15 16:44:51] DEBUG[841] chan_sip.c: Updating call counter for outgoing call [Jun 15 16:44:51] DEBUG[841] chan_sip.c: Call to peer 'test1' removed from call limit 100 [Jun 15 16:44:51] DEBUG[667] devicestate.c: No provider found, checking channel drivers for SIP - test1 [Jun 15 16:44:51] DEBUG[841] res_rtp_asterisk.c: Setting RTCP address on RTP instance '0x9f61758' [Jun 15 16:44:51] DEBUG[667] chan_sip.c: Checking device state for peer test1 [Jun 15 16:44:51] DEBUG[667] devicestate.c: Changing state for SIP/test1 - state 1 (Not in use) [Jun 15 16:44:51] DEBUG[667] devicestate.c: device 'SIP/test1' state '1' [Jun 15 16:44:51] VERBOSE[841] chan_sip.c: [Jun 15 16:44:51] Scheduling destruction of SIP dialog '4912056e767be8ec2685723436484077@x.x.x.6:5060' in 6400 ms (Method: INVITE) [Jun 15 16:44:51] DEBUG[841] chan_sip.c: Strict routing enforced for session 4912056e767be8ec2685723436484077@x.x.x.6:5060 [Jun 15 16:44:51] VERBOSE[841] chan_sip.c: [Jun 15 16:44:51] set_destination: Parsing for address/port to send to [Jun 15 16:44:51] DEBUG[841] netsock2.c: Splitting 'x.x.x.5:55028' into... [Jun 15 16:44:51] DEBUG[699] app_queue.c: Device 'SIP/test1' changed to state '1' (Not in use) [Jun 15 16:44:51] DEBUG[668] app_queue.c: Extension 'test1@localusers' changed to state '1' (Not in use) but we don't care because they're not a member of any queue. [Jun 15 16:44:51] DEBUG[841] netsock2.c: ...host 'x.x.x.5' and port '55028'. [Jun 15 16:44:51] VERBOSE[841] chan_sip.c: [Jun 15 16:44:51] set_destination: set destination to x.x.x.5:55028 [Jun 15 16:44:51] VERBOSE[841] chan_sip.c: [Jun 15 16:44:51] Reliably Transmitting (NAT) to x.x.x.5:55010: BYE sip:test1@x.x.x.5:55028 SIP/2.0 Via: SIP/2.0/UDP x.x.x.6:5060;branch=z9hG4bK6117cb9d;rport Max-Forwards: 70 From: "user2" ;tag=as22ef64a2 To: ;tag=f5326c15812d0f49i0 Call-ID: 4912056e767be8ec2685723436484077@x.x.x.6:5060 CSeq: 103 BYE User-Agent: Asterisk PBX 1.8.14.0-rc1 X-Asterisk-HangupCause: Normal Clearing X-Asterisk-HangupCauseCode: 16 Content-Length: 0 --- [Jun 15 16:44:51] DEBUG[841] chan_sip.c: *** SIP TIMER: Initializing retransmit timer on packet: Id #108 [Jun 15 16:44:51] DEBUG[841] chan_sip.c: Trying to put 'BYE sip:test1' onto UDP socket destined for x.x.x.5:55010 [Jun 15 16:44:51] DEBUG[841] res_monitor.c: monitor executing ( nice -n 19 soxmix "/var/spool/asterisk/monitor/inbound-test1-1339796683-5555550001-in.wav" "/var/spool/asterisk/monitor/inbound-test1-1339796683-5555550001-out.wav" "/var/spool/asterisk/monitor/inbound-test1-1339796683-5555550001.wav" && rm -f "/var/spool/asterisk/monitor/inbound-test1-1339796683-5555550001-"* ) & [Jun 15 16:44:51] DEBUG[667] devicestate.c: No provider found, checking channel drivers for SIP - test1 [Jun 15 16:44:51] DEBUG[841] app_dial.c: Exiting with DIALSTATUS=ANSWER. [Jun 15 16:44:51] DEBUG[667] chan_sip.c: Checking device state for peer test1 [Jun 15 16:44:51] DEBUG[667] devicestate.c: Changing state for SIP/test1 - state 1 (Not in use) [Jun 15 16:44:51] DEBUG[667] devicestate.c: device 'SIP/test1' state '1' [Jun 15 16:44:51] DEBUG[841] pbx.c: Spawn extension (macro-dialext,s,9) exited non-zero on 'Parked/SIP/mypeer1-00000000' [Jun 15 16:44:51] VERBOSE[841] pbx.c: [Jun 15 16:44:51] == Spawn extension (macro-dialext, s, 9) exited non-zero on 'Parked/SIP/mypeer1-00000000' [Jun 15 16:44:51] DEBUG[841] channel.c: Soft-Hanging up channel 'Parked/SIP/mypeer1-00000000' [Jun 15 16:44:51] DEBUG[841] channel.c: Hanging up zombie 'Parked/SIP/mypeer1-00000000' [Jun 15 16:44:51] DEBUG[699] app_queue.c: Device 'SIP/test1' changed to state '1' (Not in use) [Jun 15 16:44:51] DEBUG[667] devicestate.c: No provider found, checking channel drivers for Parked - SIP/mypeer1 [Jun 15 16:44:51] DEBUG[667] devicestate.c: Changing state for Parked/SIP/mypeer1 - state 4 (Invalid) [Jun 15 16:44:51] DEBUG[667] devicestate.c: device 'Parked/SIP/mypeer1' state '4' [Jun 15 16:44:51] DEBUG[699] app_queue.c: Device 'Parked/SIP/mypeer1' changed to state '4' (Invalid) but we don't care because they're not a member of any queue. [Jun 15 16:44:51] VERBOSE[686] chan_sip.c: [Jun 15 16:44:51] <--- SIP read from UDP:x.x.x.5:55010 ---> SIP/2.0 200 OK To: ;tag=f5326c15812d0f49i0 From: "user2" ;tag=as22ef64a2 Call-ID: 4912056e767be8ec2685723436484077@x.x.x.6:5060 CSeq: 103 BYE Via: SIP/2.0/UDP x.x.x.6:5060;branch=z9hG4bK6117cb9d Server: Cisco/SPA525G2-7.4.9c Content-Length: 0 <-------------> [Jun 15 16:44:51] DEBUG[686] chan_sip.c: Header 0 [ 14]: SIP/2.0 200 OK [Jun 15 16:44:51] DEBUG[686] chan_sip.c: Header 1 [ 56]: To: ;tag=f5326c15812d0f49i0 [Jun 15 16:44:51] DEBUG[686] chan_sip.c: Header 2 [ 65]: From: "user2" ;tag=as22ef64a2 [Jun 15 16:44:51] DEBUG[686] chan_sip.c: Header 3 [ 59]: Call-ID: 4912056e767be8ec2685723436484077@x.x.x.6:5060 [Jun 15 16:44:51] DEBUG[686] chan_sip.c: Header 4 [ 13]: CSeq: 103 BYE [Jun 15 16:44:51] DEBUG[686] chan_sip.c: Header 5 [ 57]: Via: SIP/2.0/UDP x.x.x.6:5060;branch=z9hG4bK6117cb9d [Jun 15 16:44:51] DEBUG[686] chan_sip.c: Header 6 [ 29]: Server: Cisco/SPA525G2-7.4.9c [Jun 15 16:44:51] DEBUG[686] chan_sip.c: Header 7 [ 17]: Content-Length: 0 [Jun 15 16:44:51] VERBOSE[686] chan_sip.c: [Jun 15 16:44:51] --- (8 headers 0 lines) --- [Jun 15 16:44:51] DEBUG[686] chan_sip.c: = Looking for Call ID: 4912056e767be8ec2685723436484077@x.x.x.6:5060 (Checking To) --From tag as22ef64a2 --To-tag f5326c15812d0f49i0 [Jun 15 16:44:51] DEBUG[686] chan_sip.c: ** SIP TIMER: Cancelling retransmit of packet (reply received) Retransid #108 [Jun 15 16:44:51] DEBUG[686] chan_sip.c: Stopping retransmission on '4912056e767be8ec2685723436484077@x.x.x.6:5060' of Request 103: Match Found [Jun 15 16:44:51] DEBUG[686] chan_sip.c: Destroying SIP dialog 4912056e767be8ec2685723436484077@x.x.x.6:5060 [Jun 15 16:44:51] VERBOSE[686] chan_sip.c: [Jun 15 16:44:51] Really destroying SIP dialog '4912056e767be8ec2685723436484077@x.x.x.6:5060' Method: INVITE [Jun 15 16:44:51] DEBUG[686] rtp_engine.c: Destroyed RTP instance '0x9f61758' [Jun 15 16:44:51] VERBOSE[678] chan_iax2.c: [Jun 15 16:44:51] Rx-Frame Retry[ No] -- OSeqno: 000 ISeqno: 000 Type: IAX Subclass: REGREQ [Jun 15 16:44:51] VERBOSE[678] chan_iax2.c: [Jun 15 16:44:51] Timestamp: 00003ms SCall: 06657 DCall: 00000 [127.0.0.1:4576] [Jun 15 16:44:51] VERBOSE[678] chan_iax2.c: [Jun 15 16:44:51] USERNAME : fax006 [Jun 15 16:44:51] VERBOSE[678] chan_iax2.c: [Jun 15 16:44:51] REFRESH : 60 [Jun 15 16:44:51] VERBOSE[678] chan_iax2.c: [Jun 15 16:44:51] [Jun 15 16:44:51] DEBUG[678] chan_iax2.c: Determining if address 127.0.0.1 with username fax006 requires calltoken validation. Optional = 0 calltoken_required = 3 [Jun 15 16:44:51] DEBUG[678] chan_iax2.c: ip callno count incremented to 13 for 127.0.0.1 [Jun 15 16:44:51] DEBUG[678] chan_iax2.c: Creating new call structure 16058 [Jun 15 16:44:51] DEBUG[678] chan_iax2.c: Received packet 0, (6, 13) [Jun 15 16:44:51] DEBUG[678] chan_iax2.c: IAX subclass 13 received [Jun 15 16:44:51] DEBUG[678] chan_iax2.c: For call=16058, set last=3 [Jun 15 16:44:51] DEBUG[667] devicestate.c: No provider found, checking channel drivers for IAX2 - fax006 [Jun 15 16:44:51] DEBUG[673] chan_iax2.c: Sending 19 on 16058/6657 to 127.0.0.1:4576 [Jun 15 16:44:51] VERBOSE[673] chan_iax2.c: [Jun 15 16:44:51] Tx-Frame Retry[000] -- OSeqno: 000 ISeqno: 001 Type: IAX Subclass: REGAUTH [Jun 15 16:44:51] VERBOSE[673] chan_iax2.c: [Jun 15 16:44:51] Timestamp: 00019ms SCall: 16058 DCall: 06657 [127.0.0.1:4576] [Jun 15 16:44:51] DEBUG[667] chan_iax2.c: Checking device state for device fax006 [Jun 15 16:44:51] VERBOSE[673] chan_iax2.c: [Jun 15 16:44:51] AUTHMETHODS : 3 [Jun 15 16:44:51] DEBUG[667] chan_iax2.c: iax2_devicestate: Found peer. What's device state of fax006? addr=2130706433, defaddr=0 maxms=0, lastms=0 [Jun 15 16:44:51] VERBOSE[673] chan_iax2.c: [Jun 15 16:44:51] CHALLENGE : \x31\x33\x39\x35\x32\x36\x37\x31\x38 [Jun 15 16:44:51] VERBOSE[673] chan_iax2.c: [Jun 15 16:44:51] USERNAME : fax006 [Jun 15 16:44:51] DEBUG[667] devicestate.c: Changing state for IAX2/fax006 - state 0 (Unknown) [Jun 15 16:44:51] VERBOSE[673] chan_iax2.c: [Jun 15 16:44:51] [Jun 15 16:44:51] DEBUG[667] devicestate.c: device 'IAX2/fax006' state '0' [Jun 15 16:44:51] VERBOSE[679] chan_iax2.c: [Jun 15 16:44:51] Rx-Frame Retry[ No] -- OSeqno: 001 ISeqno: 001 Type: IAX Subclass: REGREQ [Jun 15 16:44:51] VERBOSE[679] chan_iax2.c: [Jun 15 16:44:51] Timestamp: 00008ms SCall: 06657 DCall: 16058 [127.0.0.1:4576] [Jun 15 16:44:51] VERBOSE[679] chan_iax2.c: [Jun 15 16:44:51] USERNAME : fax006 [Jun 15 16:44:51] VERBOSE[679] chan_iax2.c: [Jun 15 16:44:51] MD5 RESULT : 0bb7a3d75f30d13c706c084aa961b563 [Jun 15 16:44:51] VERBOSE[679] chan_iax2.c: [Jun 15 16:44:51] REFRESH : 60 [Jun 15 16:44:51] VERBOSE[679] chan_iax2.c: [Jun 15 16:44:51] [Jun 15 16:44:51] DEBUG[699] app_queue.c: Device 'IAX2/fax006' changed to state '0' (Unknown) but we don't care because they're not a member of any queue. [Jun 15 16:44:51] DEBUG[679] chan_iax2.c: Received packet 1, (6, 13) [Jun 15 16:44:51] DEBUG[679] chan_iax2.c: Cancelling transmission of packet 0 [Jun 15 16:44:51] DEBUG[679] chan_iax2.c: IAX subclass 13 received [Jun 15 16:44:51] DEBUG[679] chan_iax2.c: For call=16058, set last=8 [Jun 15 16:44:51] DEBUG[667] devicestate.c: No provider found, checking channel drivers for IAX2 - fax006 [Jun 15 16:44:51] DEBUG[667] chan_iax2.c: Checking device state for device fax006 [Jun 15 16:44:51] DEBUG[667] chan_iax2.c: iax2_devicestate: Found peer. What's device state of fax006? addr=2130706433, defaddr=0 maxms=0, lastms=0 [Jun 15 16:44:51] DEBUG[673] chan_iax2.c: Sending 31 on 16058/6657 to 127.0.0.1:4576 [Jun 15 16:44:51] DEBUG[667] devicestate.c: Changing state for IAX2/fax006 - state 0 (Unknown) [Jun 15 16:44:51] VERBOSE[673] chan_iax2.c: [Jun 15 16:44:51] Tx-Frame Retry[000] -- OSeqno: 001 ISeqno: 002 Type: IAX Subclass: REGACK [Jun 15 16:44:51] DEBUG[667] devicestate.c: device 'IAX2/fax006' state '0' [Jun 15 16:44:51] VERBOSE[673] chan_iax2.c: [Jun 15 16:44:51] Timestamp: 00031ms SCall: 16058 DCall: 06657 [127.0.0.1:4576] [Jun 15 16:44:51] VERBOSE[673] chan_iax2.c: [Jun 15 16:44:51] USERNAME : fax006 [Jun 15 16:44:51] VERBOSE[673] chan_iax2.c: [Jun 15 16:44:51] DATE TIME : 2012-06-15 16:44:50 [Jun 15 16:44:51] VERBOSE[673] chan_iax2.c: [Jun 15 16:44:51] REFRESH : 60 [Jun 15 16:44:51] VERBOSE[673] chan_iax2.c: [Jun 15 16:44:51] APPARENT ADDRES : IPV4 127.0.0.1:4576 [Jun 15 16:44:51] VERBOSE[673] chan_iax2.c: [Jun 15 16:44:51] CALLING NUMBER : 8476039009 [Jun 15 16:44:51] VERBOSE[673] chan_iax2.c: [Jun 15 16:44:51] CALLING NAME : Fax006 [Jun 15 16:44:51] VERBOSE[673] chan_iax2.c: [Jun 15 16:44:51] [Jun 15 16:44:51] DEBUG[699] app_queue.c: Device 'IAX2/fax006' changed to state '0' (Unknown) but we don't care because they're not a member of any queue. [Jun 15 16:44:51] VERBOSE[681] chan_iax2.c: [Jun 15 16:44:51] Rx-Frame Retry[ No] -- OSeqno: 002 ISeqno: 002 Type: IAX Subclass: ACK [Jun 15 16:44:51] VERBOSE[681] chan_iax2.c: [Jun 15 16:44:51] Timestamp: 00031ms SCall: 06657 DCall: 16058 [127.0.0.1:4576] [Jun 15 16:44:51] DEBUG[681] chan_iax2.c: Received packet 2, (6, 4) [Jun 15 16:44:51] DEBUG[681] chan_iax2.c: Cancelling transmission of packet 1 [Jun 15 16:44:51] DEBUG[681] chan_iax2.c: Really destroying 16058, having been acked on final message [Jun 15 16:44:51] DEBUG[681] chan_iax2.c: schedule decrement of callno used for 127.0.0.1 in 60 seconds [Jun 15 16:44:53] DEBUG[674] chan_iax2.c: ip callno count decremented to 12 for 127.0.0.1 [Jun 15 16:44:53] DEBUG[686] chan_sip.c: Allocating new SIP dialog for 233fcca6136aa90e59991e550aa73e47@x.x.x.6:5060 - OPTIONS (No RTP) [Jun 15 16:44:53] DEBUG[686] acl.c: For destination 'x.x.x.134', our source address is 'x.x.x.6'. [Jun 15 16:44:53] DEBUG[686] chan_sip.c: Setting SIP_TRANSPORT_UDP with address x.x.x.6:5060 [Jun 15 16:44:53] DEBUG[686] chan_sip.c: Initializing initreq for method OPTIONS - callid 477a93d3394b6c9c0a1adc0b7fa8790e@x.x.x.6:5060 [Jun 15 16:44:53] DEBUG[686] chan_sip.c: Header 0 [ 41]: OPTIONS sip:1026@10.10.1.test1:5060 SIP/2.0 [Jun 15 16:44:53] DEBUG[686] chan_sip.c: Header 1 [ 63]: Via: SIP/2.0/UDP x.x.x.6:5060;branch=z9hG4bK36f3e568;rport [Jun 15 16:44:53] DEBUG[686] chan_sip.c: Header 2 [ 16]: Max-Forwards: 70 [Jun 15 16:44:53] DEBUG[686] chan_sip.c: Header 3 [ 57]: From: "Unknown" ;tag=as71707300 [Jun 15 16:44:53] DEBUG[686] chan_sip.c: Header 4 [ 31]: To: [Jun 15 16:44:53] DEBUG[686] chan_sip.c: Header 5 [ 40]: Contact: [Jun 15 16:44:53] DEBUG[686] chan_sip.c: Header 6 [ 59]: Call-ID: 477a93d3394b6c9c0a1adc0b7fa8790e@x.x.x.6:5060 [Jun 15 16:44:53] DEBUG[686] chan_sip.c: Header 7 [ 17]: CSeq: 102 OPTIONS [Jun 15 16:44:53] DEBUG[686] chan_sip.c: Header 8 [ 37]: User-Agent: Asterisk PBX 1.8.14.0-rc1 [Jun 15 16:44:53] DEBUG[686] chan_sip.c: Header 9 [ 35]: Date: Fri, 15 Jun 2012 21:44:53 GMT [Jun 15 16:44:53] DEBUG[686] chan_sip.c: Header 10 [ 81]: Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO, PUBLISH [Jun 15 16:44:53] DEBUG[686] chan_sip.c: Header 11 [ 26]: Supported: replaces, timer [Jun 15 16:44:53] VERBOSE[686] chan_sip.c: [Jun 15 16:44:53] Reliably Transmitting (NAT) to x.x.x.134:42225: OPTIONS sip:1026@10.10.1.test1:5060 SIP/2.0 Via: SIP/2.0/UDP x.x.x.6:5060;branch=z9hG4bK36f3e568;rport Max-Forwards: 70 From: "Unknown" ;tag=as71707300 To: Contact: Call-ID: 477a93d3394b6c9c0a1adc0b7fa8790e@x.x.x.6:5060 CSeq: 102 OPTIONS User-Agent: Asterisk PBX 1.8.14.0-rc1 Date: Fri, 15 Jun 2012 21:44:53 GMT Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO, PUBLISH Supported: replaces, timer Content-Length: 0 --- [Jun 15 16:44:53] DEBUG[686] chan_sip.c: *** SIP TIMER: Initializing retransmit timer on packet: Id #109 [Jun 15 16:44:53] DEBUG[686] chan_sip.c: Trying to put 'OPTIONS sip' onto UDP socket destined for x.x.x.134:42225 [Jun 15 16:44:53] VERBOSE[686] chan_sip.c: [Jun 15 16:44:53] <--- SIP read from UDP:x.x.x.134:42225 ---> SIP/2.0 200 OK To: ;tag=ec3d3a6726e37001i0 From: "Unknown" ;tag=as71707300 Call-ID: 477a93d3394b6c9c0a1adc0b7fa8790e@x.x.x.6:5060 CSeq: 102 OPTIONS Via: SIP/2.0/UDP x.x.x.6:5060;branch=z9hG4bK36f3e568 Server: Cisco/SPA303-7.4.8a Content-Length: 0 Allow: ACK, BYE, CANCEL, INFO, INVITE, NOTIFY, OPTIONS, REFER, UPDATE Supported: replaces <-------------> [Jun 15 16:44:53] DEBUG[686] chan_sip.c: Header 0 [ 14]: SIP/2.0 200 OK [Jun 15 16:44:53] DEBUG[686] chan_sip.c: Header 1 [ 54]: To: ;tag=ec3d3a6726e37001i0 [Jun 15 16:44:53] DEBUG[686] chan_sip.c: Header 2 [ 57]: From: "Unknown" ;tag=as71707300 [Jun 15 16:44:53] DEBUG[686] chan_sip.c: Header 3 [ 59]: Call-ID: 477a93d3394b6c9c0a1adc0b7fa8790e@x.x.x.6:5060 [Jun 15 16:44:53] DEBUG[686] chan_sip.c: Header 4 [ 17]: CSeq: 102 OPTIONS [Jun 15 16:44:53] DEBUG[686] chan_sip.c: Header 5 [ 57]: Via: SIP/2.0/UDP x.x.x.6:5060;branch=z9hG4bK36f3e568 [Jun 15 16:44:53] DEBUG[686] chan_sip.c: Header 6 [ 27]: Server: Cisco/SPA303-7.4.8a [Jun 15 16:44:53] DEBUG[686] chan_sip.c: Header 7 [ 17]: Content-Length: 0 [Jun 15 16:44:53] DEBUG[686] chan_sip.c: Header 8 [ 69]: Allow: ACK, BYE, CANCEL, INFO, INVITE, NOTIFY, OPTIONS, REFER, UPDATE [Jun 15 16:44:53] DEBUG[686] chan_sip.c: Header 9 [ 19]: Supported: replaces [Jun 15 16:44:53] VERBOSE[686] chan_sip.c: [Jun 15 16:44:53] --- (10 headers 0 lines) --- [Jun 15 16:44:53] DEBUG[686] chan_sip.c: = Looking for Call ID: 477a93d3394b6c9c0a1adc0b7fa8790e@x.x.x.6:5060 (Checking To) --From tag as71707300 --To-tag ec3d3a6726e37001i0 [Jun 15 16:44:53] DEBUG[686] chan_sip.c: ** SIP TIMER: Cancelling retransmit of packet (reply received) Retransid #109 [Jun 15 16:44:53] DEBUG[686] chan_sip.c: Stopping retransmission on '477a93d3394b6c9c0a1adc0b7fa8790e@x.x.x.6:5060' of Request 102: Match Found [Jun 15 16:44:53] DEBUG[686] chan_sip.c: Destroying SIP dialog 477a93d3394b6c9c0a1adc0b7fa8790e@x.x.x.6:5060 [Jun 15 16:44:53] VERBOSE[686] chan_sip.c: [Jun 15 16:44:53] Really destroying SIP dialog '477a93d3394b6c9c0a1adc0b7fa8790e@x.x.x.6:5060' Method: OPTIONS [Jun 15 16:44:53] DEBUG[686] chan_sip.c: Allocating new SIP dialog for 743d917342380eca7f3bcc802edc5ead@x.x.x.6:5060 - OPTIONS (No RTP) [Jun 15 16:44:53] DEBUG[686] acl.c: For destination 'x.x.x.5', our source address is 'x.x.x.6'. [Jun 15 16:44:53] DEBUG[686] chan_sip.c: Setting SIP_TRANSPORT_UDP with address x.x.x.6:5060 [Jun 15 16:44:53] DEBUG[686] chan_sip.c: Initializing initreq for method OPTIONS - callid 3a1f65444763426100d85001504a718b@x.x.x.6:5060 [Jun 15 16:44:53] DEBUG[686] chan_sip.c: Header 0 [ 43]: OPTIONS sip:test1@x.x.x.5:55028 SIP/2.0 [Jun 15 16:44:53] DEBUG[686] chan_sip.c: Header 1 [ 63]: Via: SIP/2.0/UDP x.x.x.6:5060;branch=z9hG4bK69f404d4;rport [Jun 15 16:44:53] DEBUG[686] chan_sip.c: Header 2 [ 16]: Max-Forwards: 70 [Jun 15 16:44:53] DEBUG[686] chan_sip.c: Header 3 [ 57]: From: "Unknown" ;tag=as0e8f785e [Jun 15 16:44:53] DEBUG[686] chan_sip.c: Header 4 [ 33]: To: [Jun 15 16:44:53] DEBUG[686] chan_sip.c: Header 5 [ 40]: Contact: [Jun 15 16:44:53] DEBUG[686] chan_sip.c: Header 6 [ 59]: Call-ID: 3a1f65444763426100d85001504a718b@x.x.x.6:5060 [Jun 15 16:44:53] DEBUG[686] chan_sip.c: Header 7 [ 17]: CSeq: 102 OPTIONS [Jun 15 16:44:53] DEBUG[686] chan_sip.c: Header 8 [ 37]: User-Agent: Asterisk PBX 1.8.14.0-rc1 [Jun 15 16:44:53] DEBUG[686] chan_sip.c: Header 9 [ 35]: Date: Fri, 15 Jun 2012 21:44:53 GMT [Jun 15 16:44:53] DEBUG[686] chan_sip.c: Header 10 [ 81]: Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO, PUBLISH [Jun 15 16:44:53] DEBUG[686] chan_sip.c: Header 11 [ 26]: Supported: replaces, timer [Jun 15 16:44:53] VERBOSE[686] chan_sip.c: [Jun 15 16:44:53] Reliably Transmitting (NAT) to x.x.x.5:55010: OPTIONS sip:test1@x.x.x.5:55028 SIP/2.0 Via: SIP/2.0/UDP x.x.x.6:5060;branch=z9hG4bK69f404d4;rport Max-Forwards: 70 From: "Unknown" ;tag=as0e8f785e To: Contact: Call-ID: 3a1f65444763426100d85001504a718b@x.x.x.6:5060 CSeq: 102 OPTIONS User-Agent: Asterisk PBX 1.8.14.0-rc1 Date: Fri, 15 Jun 2012 21:44:53 GMT Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO, PUBLISH Supported: replaces, timer Content-Length: 0 --- [Jun 15 16:44:53] DEBUG[686] chan_sip.c: *** SIP TIMER: Initializing retransmit timer on packet: Id #112 [Jun 15 16:44:53] DEBUG[686] chan_sip.c: Trying to put 'OPTIONS sip' onto UDP socket destined for x.x.x.5:55010 [Jun 15 16:44:53] VERBOSE[686] chan_sip.c: [Jun 15 16:44:53] <--- SIP read from UDP:x.x.x.5:55010 ---> SIP/2.0 200 OK To: ;tag=6ca6cd1d72350287i0 From: "Unknown" ;tag=as0e8f785e Call-ID: 3a1f65444763426100d85001504a718b@x.x.x.6:5060 CSeq: 102 OPTIONS Via: SIP/2.0/UDP x.x.x.6:5060;branch=z9hG4bK69f404d4 Server: Cisco/SPA525G2-7.4.9c Content-Length: 0 Allow: ACK, BYE, CANCEL, INFO, INVITE, NOTIFY, OPTIONS, REFER, UPDATE Supported: replaces <-------------> [Jun 15 16:44:53] DEBUG[686] chan_sip.c: Header 0 [ 14]: SIP/2.0 200 OK [Jun 15 16:44:53] DEBUG[686] chan_sip.c: Header 1 [ 56]: To: ;tag=6ca6cd1d72350287i0 [Jun 15 16:44:53] DEBUG[686] chan_sip.c: Header 2 [ 57]: From: "Unknown" ;tag=as0e8f785e [Jun 15 16:44:53] DEBUG[686] chan_sip.c: Header 3 [ 59]: Call-ID: 3a1f65444763426100d85001504a718b@x.x.x.6:5060 [Jun 15 16:44:53] DEBUG[686] chan_sip.c: Header 4 [ 17]: CSeq: 102 OPTIONS [Jun 15 16:44:53] DEBUG[686] chan_sip.c: Header 5 [ 57]: Via: SIP/2.0/UDP x.x.x.6:5060;branch=z9hG4bK69f404d4 [Jun 15 16:44:53] DEBUG[686] chan_sip.c: Header 6 [ 29]: Server: Cisco/SPA525G2-7.4.9c [Jun 15 16:44:53] DEBUG[686] chan_sip.c: Header 7 [ 17]: Content-Length: 0 [Jun 15 16:44:53] DEBUG[686] chan_sip.c: Header 8 [ 69]: Allow: ACK, BYE, CANCEL, INFO, INVITE, NOTIFY, OPTIONS, REFER, UPDATE [Jun 15 16:44:53] DEBUG[686] chan_sip.c: Header 9 [ 19]: Supported: replaces [Jun 15 16:44:53] VERBOSE[686] chan_sip.c: [Jun 15 16:44:53] --- (10 headers 0 lines) --- [Jun 15 16:44:53] DEBUG[686] chan_sip.c: = Looking for Call ID: 3a1f65444763426100d85001504a718b@x.x.x.6:5060 (Checking To) --From tag as0e8f785e --To-tag 6ca6cd1d72350287i0 [Jun 15 16:44:53] DEBUG[686] chan_sip.c: ** SIP TIMER: Cancelling retransmit of packet (reply received) Retransid #112 [Jun 15 16:44:53] DEBUG[686] chan_sip.c: Stopping retransmission on '3a1f65444763426100d85001504a718b@x.x.x.6:5060' of Request 102: Match Found [Jun 15 16:44:53] DEBUG[686] chan_sip.c: Destroying SIP dialog 3a1f65444763426100d85001504a718b@x.x.x.6:5060 [Jun 15 16:44:53] VERBOSE[686] chan_sip.c: [Jun 15 16:44:53] Really destroying SIP dialog '3a1f65444763426100d85001504a718b@x.x.x.6:5060' Method: OPTIONS [Jun 15 16:44:55] DEBUG[686] chan_sip.c: Allocating new SIP dialog for 7f12e3c536bba6c2584506de6b97e446@x.x.x.6:5060 - OPTIONS (No RTP) [Jun 15 16:44:55] DEBUG[686] acl.c: For destination 'x.x.x.90', our source address is 'x.x.x.6'. [Jun 15 16:44:55] DEBUG[686] chan_sip.c: Setting SIP_TRANSPORT_UDP with address x.x.x.6:5060 [Jun 15 16:44:55] DEBUG[686] chan_sip.c: Initializing initreq for method OPTIONS - callid 2c153aba2758942772f52b241a35cddf@x.x.x.6:5060 [Jun 15 16:44:55] DEBUG[686] chan_sip.c: Header 0 [ 33]: OPTIONS sip:x.x.x.90 SIP/2.0 [Jun 15 16:44:55] DEBUG[686] chan_sip.c: Header 1 [ 63]: Via: SIP/2.0/UDP x.x.x.6:5060;branch=z9hG4bK7674649e;rport [Jun 15 16:44:55] DEBUG[686] chan_sip.c: Header 2 [ 16]: Max-Forwards: 70 [Jun 15 16:44:55] DEBUG[686] chan_sip.c: Header 3 [ 57]: From: "Unknown" ;tag=as444545e3 [Jun 15 16:44:55] DEBUG[686] chan_sip.c: Header 4 [ 23]: To: [Jun 15 16:44:55] DEBUG[686] chan_sip.c: Header 5 [ 40]: Contact: [Jun 15 16:44:55] DEBUG[686] chan_sip.c: Header 6 [ 59]: Call-ID: 2c153aba2758942772f52b241a35cddf@x.x.x.6:5060 [Jun 15 16:44:55] DEBUG[686] chan_sip.c: Header 7 [ 17]: CSeq: 102 OPTIONS [Jun 15 16:44:55] DEBUG[686] chan_sip.c: Header 8 [ 37]: User-Agent: Asterisk PBX 1.8.14.0-rc1 [Jun 15 16:44:55] DEBUG[686] chan_sip.c: Header 9 [ 35]: Date: Fri, 15 Jun 2012 21:44:55 GMT [Jun 15 16:44:55] DEBUG[686] chan_sip.c: Header 10 [ 81]: Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO, PUBLISH [Jun 15 16:44:55] DEBUG[686] chan_sip.c: Header 11 [ 26]: Supported: replaces, timer [Jun 15 16:44:55] VERBOSE[686] chan_sip.c: [Jun 15 16:44:55] Reliably Transmitting (NAT) to x.x.x.90:5060: OPTIONS sip:x.x.x.90 SIP/2.0 Via: SIP/2.0/UDP x.x.x.6:5060;branch=z9hG4bK7674649e;rport Max-Forwards: 70 From: "Unknown" ;tag=as444545e3 To: Contact: Call-ID: 2c153aba2758942772f52b241a35cddf@x.x.x.6:5060 CSeq: 102 OPTIONS User-Agent: Asterisk PBX 1.8.14.0-rc1 Date: Fri, 15 Jun 2012 21:44:55 GMT Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO, PUBLISH Supported: replaces, timer Content-Length: 0 --- [Jun 15 16:44:55] DEBUG[686] chan_sip.c: *** SIP TIMER: Initializing retransmit timer on packet: Id #115 [Jun 15 16:44:55] DEBUG[686] chan_sip.c: Trying to put 'OPTIONS sip' onto UDP socket destined for x.x.x.90:5060 [Jun 15 16:44:55] VERBOSE[686] chan_sip.c: [Jun 15 16:44:55] <--- SIP read from UDP:x.x.x.90:5060 ---> SIP/2.0 484 Address Incomplete Via: SIP/2.0/UDP x.x.x.6:5060;branch=z9hG4bK7674649e;rport=5060 From: "Unknown" ;tag=as444545e3 To: ;tag=b27e1a1d33761e85846fc98f5f3a7e58.1968 Call-ID: 2c153aba2758942772f52b241a35cddf@x.x.x.6:5060 CSeq: 102 OPTIONS Server: kamailio (3.1.4 (i386/linux)) Content-Length: 0 <-------------> [Jun 15 16:44:55] DEBUG[686] chan_sip.c: Header 0 [ 30]: SIP/2.0 484 Address Incomplete [Jun 15 16:44:55] DEBUG[686] chan_sip.c: Header 1 [ 68]: Via: SIP/2.0/UDP x.x.x.6:5060;branch=z9hG4bK7674649e;rport=5060 [Jun 15 16:44:55] DEBUG[686] chan_sip.c: Header 2 [ 57]: From: "Unknown" ;tag=as444545e3 [Jun 15 16:44:55] DEBUG[686] chan_sip.c: Header 3 [ 65]: To: ;tag=b27e1a1d33761e85846fc98f5f3a7e58.1968 [Jun 15 16:44:55] DEBUG[686] chan_sip.c: Header 4 [ 59]: Call-ID: 2c153aba2758942772f52b241a35cddf@x.x.x.6:5060 [Jun 15 16:44:55] DEBUG[686] chan_sip.c: Header 5 [ 17]: CSeq: 102 OPTIONS [Jun 15 16:44:55] DEBUG[686] chan_sip.c: Header 6 [ 37]: Server: kamailio (3.1.4 (i386/linux)) [Jun 15 16:44:55] DEBUG[686] chan_sip.c: Header 7 [ 17]: Content-Length: 0 [Jun 15 16:44:55] VERBOSE[686] chan_sip.c: [Jun 15 16:44:55] --- (8 headers 0 lines) --- [Jun 15 16:44:55] DEBUG[686] chan_sip.c: = Looking for Call ID: 2c153aba2758942772f52b241a35cddf@x.x.x.6:5060 (Checking To) --From tag as444545e3 --To-tag b27e1a1d33761e85846fc98f5f3a7e58.1968 [Jun 15 16:44:55] DEBUG[686] chan_sip.c: ** SIP TIMER: Cancelling retransmit of packet (reply received) Retransid #115 [Jun 15 16:44:55] DEBUG[686] chan_sip.c: Stopping retransmission on '2c153aba2758942772f52b241a35cddf@x.x.x.6:5060' of Request 102: Match Found [Jun 15 16:44:55] DEBUG[686] chan_sip.c: Destroying SIP dialog 2c153aba2758942772f52b241a35cddf@x.x.x.6:5060 [Jun 15 16:44:55] VERBOSE[686] chan_sip.c: [Jun 15 16:44:55] Really destroying SIP dialog '2c153aba2758942772f52b241a35cddf@x.x.x.6:5060' Method: OPTIONS [Jun 15 16:44:55] DEBUG[674] chan_iax2.c: ip callno count decremented to 11 for 127.0.0.1 [Jun 15 16:44:55] DEBUG[686] chan_sip.c: Allocating new SIP dialog for 6d25218c2da8fed5064925744540779c@x.x.x.6:5060 - OPTIONS (No RTP) [Jun 15 16:44:55] DEBUG[686] acl.c: For destination 'x.x.x.138', our source address is 'x.x.x.6'. [Jun 15 16:44:55] DEBUG[686] chan_sip.c: Setting SIP_TRANSPORT_UDP with address x.x.x.6:5060 [Jun 15 16:44:55] DEBUG[686] chan_sip.c: Initializing initreq for method OPTIONS - callid 02e06d5759095585605edc462ce0a8d2@x.x.x.6:5060 [Jun 15 16:44:55] DEBUG[686] chan_sip.c: Header 0 [ 34]: OPTIONS sip:x.x.x.138 SIP/2.0 [Jun 15 16:44:55] DEBUG[686] chan_sip.c: Header 1 [ 63]: Via: SIP/2.0/UDP x.x.x.6:5060;branch=z9hG4bK46a5b9bb;rport [Jun 15 16:44:55] DEBUG[686] chan_sip.c: Header 2 [ 16]: Max-Forwards: 70 [Jun 15 16:44:55] DEBUG[686] chan_sip.c: Header 3 [ 57]: From: "Unknown" ;tag=as725c9cde [Jun 15 16:44:55] DEBUG[686] chan_sip.c: Header 4 [ 24]: To: [Jun 15 16:44:55] DEBUG[686] chan_sip.c: Header 5 [ 40]: Contact: [Jun 15 16:44:55] DEBUG[686] chan_sip.c: Header 6 [ 59]: Call-ID: 02e06d5759095585605edc462ce0a8d2@x.x.x.6:5060 [Jun 15 16:44:55] DEBUG[686] chan_sip.c: Header 7 [ 17]: CSeq: 102 OPTIONS [Jun 15 16:44:55] DEBUG[686] chan_sip.c: Header 8 [ 37]: User-Agent: Asterisk PBX 1.8.14.0-rc1 [Jun 15 16:44:55] DEBUG[686] chan_sip.c: Header 9 [ 35]: Date: Fri, 15 Jun 2012 21:44:55 GMT [Jun 15 16:44:55] DEBUG[686] chan_sip.c: Header 10 [ 81]: Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO, PUBLISH [Jun 15 16:44:55] DEBUG[686] chan_sip.c: Header 11 [ 26]: Supported: replaces, timer [Jun 15 16:44:55] VERBOSE[686] chan_sip.c: [Jun 15 16:44:55] Reliably Transmitting (NAT) to x.x.x.138:5060: OPTIONS sip:x.x.x.138 SIP/2.0 Via: SIP/2.0/UDP x.x.x.6:5060;branch=z9hG4bK46a5b9bb;rport Max-Forwards: 70 From: "Unknown" ;tag=as725c9cde To: Contact: Call-ID: 02e06d5759095585605edc462ce0a8d2@x.x.x.6:5060 CSeq: 102 OPTIONS User-Agent: Asterisk PBX 1.8.14.0-rc1 Date: Fri, 15 Jun 2012 21:44:55 GMT Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO, PUBLISH Supported: replaces, timer Content-Length: 0 --- [Jun 15 16:44:55] DEBUG[686] chan_sip.c: *** SIP TIMER: Initializing retransmit timer on packet: Id #118 [Jun 15 16:44:55] DEBUG[686] chan_sip.c: Trying to put 'OPTIONS sip' onto UDP socket destined for x.x.x.138:5060 [Jun 15 16:44:55] VERBOSE[686] chan_sip.c: [Jun 15 16:44:55] <--- SIP read from UDP:x.x.x.138:5060 ---> SIP/2.0 484 Address Incomplete Via: SIP/2.0/UDP x.x.x.6:5060;branch=z9hG4bK46a5b9bb;rport=5060 From: "Unknown" ;tag=as725c9cde To: ;tag=b27e1a1d33761e85846fc98f5f3a7e58.bf44 Call-ID: 02e06d5759095585605edc462ce0a8d2@x.x.x.6:5060 CSeq: 102 OPTIONS Server: kamailio (3.1.4 (i386/linux)) Content-Length: 0 <-------------> [Jun 15 16:44:55] DEBUG[686] chan_sip.c: Header 0 [ 30]: SIP/2.0 484 Address Incomplete [Jun 15 16:44:55] DEBUG[686] chan_sip.c: Header 1 [ 68]: Via: SIP/2.0/UDP x.x.x.6:5060;branch=z9hG4bK46a5b9bb;rport=5060 [Jun 15 16:44:55] DEBUG[686] chan_sip.c: Header 2 [ 57]: From: "Unknown" ;tag=as725c9cde [Jun 15 16:44:55] DEBUG[686] chan_sip.c: Header 3 [ 66]: To: ;tag=b27e1a1d33761e85846fc98f5f3a7e58.bf44 [Jun 15 16:44:55] DEBUG[686] chan_sip.c: Header 4 [ 59]: Call-ID: 02e06d5759095585605edc462ce0a8d2@x.x.x.6:5060 [Jun 15 16:44:55] DEBUG[686] chan_sip.c: Header 5 [ 17]: CSeq: 102 OPTIONS [Jun 15 16:44:55] DEBUG[686] chan_sip.c: Header 6 [ 37]: Server: kamailio (3.1.4 (i386/linux)) [Jun 15 16:44:55] DEBUG[686] chan_sip.c: Header 7 [ 17]: Content-Length: 0 [Jun 15 16:44:55] VERBOSE[686] chan_sip.c: [Jun 15 16:44:55] --- (8 headers 0 lines) --- [Jun 15 16:44:55] DEBUG[686] chan_sip.c: = Looking for Call ID: 02e06d5759095585605edc462ce0a8d2@x.x.x.6:5060 (Checking To) --From tag as725c9cde --To-tag b27e1a1d33761e85846fc98f5f3a7e58.bf44 [Jun 15 16:44:55] DEBUG[686] chan_sip.c: ** SIP TIMER: Cancelling retransmit of packet (reply received) Retransid #118 [Jun 15 16:44:55] DEBUG[686] chan_sip.c: Stopping retransmission on '02e06d5759095585605edc462ce0a8d2@x.x.x.6:5060' of Request 102: Match Found [Jun 15 16:44:55] DEBUG[686] chan_sip.c: Destroying SIP dialog 02e06d5759095585605edc462ce0a8d2@x.x.x.6:5060 [Jun 15 16:44:55] VERBOSE[686] chan_sip.c: [Jun 15 16:44:55] Really destroying SIP dialog '02e06d5759095585605edc462ce0a8d2@x.x.x.6:5060' Method: OPTIONS [Jun 15 16:44:56] DEBUG[674] chan_iax2.c: ip callno count decremented to 10 for 127.0.0.1 [Jun 15 16:44:57] VERBOSE[686] chan_sip.c: [Jun 15 16:44:57] <--- SIP read from UDP:x.x.x.5:55010 ---> OPTIONS sip:x.x.x.6 SIP/2.0 Via: SIP/2.0/UDP x.x.x.5:55028;branch=z9hG4bK-822a6647 From: "test1" ;tag=85813c2523621f1fo0 To: Call-ID: d7a897ad-11933937@x.x.x.5 CSeq: 167 OPTIONS Max-Forwards: 70 Contact: "test1" Event: keep-alive User-Agent: Cisco/SPA525G2-7.4.9c Content-Length: 0 <-------------> [Jun 15 16:44:57] DEBUG[686] chan_sip.c: Header 0 [ 32]: OPTIONS sip:x.x.x.6 SIP/2.0 [Jun 15 16:44:57] DEBUG[686] chan_sip.c: Header 1 [ 60]: Via: SIP/2.0/UDP x.x.x.5:55028;branch=z9hG4bK-822a6647 [Jun 15 16:44:57] DEBUG[686] chan_sip.c: Header 2 [ 57]: From: "test1" ;tag=85813c2523621f1fo0 [Jun 15 16:44:57] DEBUG[686] chan_sip.c: Header 3 [ 22]: To: [Jun 15 16:44:57] DEBUG[686] chan_sip.c: Header 4 [ 40]: Call-ID: d7a897ad-11933937@x.x.x.5 [Jun 15 16:44:57] DEBUG[686] chan_sip.c: Header 5 [ 17]: CSeq: 167 OPTIONS [Jun 15 16:44:57] DEBUG[686] chan_sip.c: Header 6 [ 16]: Max-Forwards: 70 [Jun 15 16:44:57] DEBUG[686] chan_sip.c: Header 7 [ 44]: Contact: "test1" [Jun 15 16:44:57] DEBUG[686] chan_sip.c: Header 8 [ 17]: Event: keep-alive [Jun 15 16:44:57] DEBUG[686] chan_sip.c: Header 9 [ 33]: User-Agent: Cisco/SPA525G2-7.4.9c [Jun 15 16:44:57] DEBUG[686] chan_sip.c: Header 10 [ 17]: Content-Length: 0 [Jun 15 16:44:57] VERBOSE[686] chan_sip.c: [Jun 15 16:44:57] --- (11 headers 0 lines) --- [Jun 15 16:44:57] DEBUG[686] chan_sip.c: = Looking for Call ID: d7a897ad-11933937@x.x.x.5 (Checking From) --From tag 85813c2523621f1fo0 --To-tag [Jun 15 16:44:57] DEBUG[686] chan_sip.c: **** Received OPTIONS (3) - Command in SIP OPTIONS [Jun 15 16:44:57] DEBUG[686] netsock2.c: Splitting 'x.x.x.6' into... [Jun 15 16:44:57] DEBUG[686] netsock2.c: ...host 'x.x.x.6' and port ''. [Jun 15 16:44:57] DEBUG[686] netsock2.c: Splitting 'x.x.x.6' into... [Jun 15 16:44:57] DEBUG[686] netsock2.c: ...host 'x.x.x.6' and port ''. [Jun 15 16:44:57] VERBOSE[686] chan_sip.c: [Jun 15 16:44:57] Looking for s in unauthorized (domain x.x.x.6) [Jun 15 16:44:57] VERBOSE[686] chan_sip.c: [Jun 15 16:44:57] <--- Transmitting (NAT) to x.x.x.5:55010 ---> SIP/2.0 404 Not Found Via: SIP/2.0/UDP x.x.x.5:55028;branch=z9hG4bK-822a6647;received=x.x.x.5;rport=55010 From: "test1" ;tag=85813c2523621f1fo0 To: ;tag=as3df6dbad Call-ID: d7a897ad-11933937@x.x.x.5 CSeq: 167 OPTIONS Server: Asterisk PBX 1.8.14.0-rc1 Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO, PUBLISH Supported: replaces, timer Accept: application/sdp Content-Length: 0 <------------> [Jun 15 16:44:57] DEBUG[686] chan_sip.c: Trying to put 'SIP/2.0 404' onto UDP socket destined for x.x.x.5:55010 [Jun 15 16:44:57] VERBOSE[686] chan_sip.c: [Jun 15 16:44:57] Scheduling destruction of SIP dialog 'd7a897ad-11933937@x.x.x.5' in 32000 ms (Method: OPTIONS) [Jun 15 16:45:01] DEBUG[864] manager.c: Running action 'Login' [Jun 15 16:45:06] VERBOSE[686] chan_sip.c: [Jun 15 16:45:06] <--- SIP read from UDP:x.x.x.134:42225 ---> OPTIONS <-------------> [Jun 15 16:45:06] DEBUG[686] chan_sip.c: Header 0 [ 7]: OPTIONS [Jun 15 16:45:12] VERBOSE[686] chan_sip.c: [Jun 15 16:45:12] <--- SIP read from UDP:x.x.x.5:55010 ---> OPTIONS sip:x.x.x.6 SIP/2.0 Via: SIP/2.0/UDP x.x.x.5:55028;branch=z9hG4bK-4a891605 From: "test1" ;tag=85813c2523621f1fo0 To: Call-ID: d7a897ad-11933937@x.x.x.5 CSeq: 168 OPTIONS Max-Forwards: 70 Contact: "test1" Event: keep-alive User-Agent: Cisco/SPA525G2-7.4.9c Content-Length: 0 <-------------> [Jun 15 16:45:12] DEBUG[686] chan_sip.c: Header 0 [ 32]: OPTIONS sip:x.x.x.6 SIP/2.0 [Jun 15 16:45:12] DEBUG[686] chan_sip.c: Header 1 [ 60]: Via: SIP/2.0/UDP x.x.x.5:55028;branch=z9hG4bK-4a891605 [Jun 15 16:45:12] DEBUG[686] chan_sip.c: Header 2 [ 57]: From: "test1" ;tag=85813c2523621f1fo0 [Jun 15 16:45:12] DEBUG[686] chan_sip.c: Header 3 [ 22]: To: [Jun 15 16:45:12] DEBUG[686] chan_sip.c: Header 4 [ 40]: Call-ID: d7a897ad-11933937@x.x.x.5 [Jun 15 16:45:12] DEBUG[686] chan_sip.c: Header 5 [ 17]: CSeq: 168 OPTIONS [Jun 15 16:45:12] DEBUG[686] chan_sip.c: Header 6 [ 16]: Max-Forwards: 70 [Jun 15 16:45:12] DEBUG[686] chan_sip.c: Header 7 [ 44]: Contact: "test1" [Jun 15 16:45:12] DEBUG[686] chan_sip.c: Header 8 [ 17]: Event: keep-alive [Jun 15 16:45:12] DEBUG[686] chan_sip.c: Header 9 [ 33]: User-Agent: Cisco/SPA525G2-7.4.9c [Jun 15 16:45:12] DEBUG[686] chan_sip.c: Header 10 [ 17]: Content-Length: 0 [Jun 15 16:45:12] VERBOSE[686] chan_sip.c: [Jun 15 16:45:12] --- (11 headers 0 lines) --- [Jun 15 16:45:12] DEBUG[686] chan_sip.c: = Looking for Call ID: d7a897ad-11933937@x.x.x.5 (Checking From) --From tag 85813c2523621f1fo0 --To-tag [Jun 15 16:45:12] DEBUG[686] chan_sip.c: **** Received OPTIONS (3) - Command in SIP OPTIONS [Jun 15 16:45:12] DEBUG[686] netsock2.c: Splitting 'x.x.x.6' into... [Jun 15 16:45:12] DEBUG[686] netsock2.c: ...host 'x.x.x.6' and port ''. [Jun 15 16:45:12] DEBUG[686] netsock2.c: Splitting 'x.x.x.6' into... [Jun 15 16:45:12] DEBUG[686] netsock2.c: ...host 'x.x.x.6' and port ''. [Jun 15 16:45:12] VERBOSE[686] chan_sip.c: [Jun 15 16:45:12] Looking for s in unauthorized (domain x.x.x.6) [Jun 15 16:45:12] VERBOSE[686] chan_sip.c: [Jun 15 16:45:12] <--- Transmitting (NAT) to x.x.x.5:55010 ---> SIP/2.0 404 Not Found Via: SIP/2.0/UDP x.x.x.5:55028;branch=z9hG4bK-4a891605;received=x.x.x.5;rport=55010 From: "test1" ;tag=85813c2523621f1fo0 To: ;tag=as3df6dbad Call-ID: d7a897ad-11933937@x.x.x.5 CSeq: 168 OPTIONS Server: Asterisk PBX 1.8.14.0-rc1 Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO, PUBLISH Supported: replaces, timer Accept: application/sdp Content-Length: 0 <------------> [Jun 15 16:45:12] DEBUG[686] chan_sip.c: Trying to put 'SIP/2.0 404' onto UDP socket destined for x.x.x.5:55010 [Jun 15 16:45:12] VERBOSE[686] chan_sip.c: [Jun 15 16:45:12] Scheduling destruction of SIP dialog 'd7a897ad-11933937@x.x.x.5' in 32000 ms (Method: OPTIONS) [Jun 15 16:45:14] VERBOSE[675] chan_iax2.c: [Jun 15 16:45:14] Rx-Frame Retry[ No] -- OSeqno: 000 ISeqno: 000 Type: IAX Subclass: REGREQ [Jun 15 16:45:14] VERBOSE[675] chan_iax2.c: [Jun 15 16:45:14] Timestamp: 00003ms SCall: 06657 DCall: 00000 [127.0.0.1:4571] [Jun 15 16:45:14] VERBOSE[675] chan_iax2.c: [Jun 15 16:45:14] USERNAME : fax001 [Jun 15 16:45:14] VERBOSE[675] chan_iax2.c: [Jun 15 16:45:14] REFRESH : 60 [Jun 15 16:45:14] VERBOSE[675] chan_iax2.c: [Jun 15 16:45:14] [Jun 15 16:45:14] DEBUG[675] chan_iax2.c: Determining if address 127.0.0.1 with username fax001 requires calltoken validation. Optional = 0 calltoken_required = 3 [Jun 15 16:45:14] DEBUG[675] chan_iax2.c: ip callno count incremented to 11 for 127.0.0.1 [Jun 15 16:45:14] DEBUG[675] chan_iax2.c: Creating new call structure 156 [Jun 15 16:45:14] DEBUG[675] chan_iax2.c: Received packet 0, (6, 13) [Jun 15 16:45:14] DEBUG[675] chan_iax2.c: IAX subclass 13 received [Jun 15 16:45:14] DEBUG[675] chan_iax2.c: For call=156, set last=3 [Jun 15 16:45:14] DEBUG[667] devicestate.c: No provider found, checking channel drivers for IAX2 - fax001 [Jun 15 16:45:14] DEBUG[667] chan_iax2.c: Checking device state for device fax001 [Jun 15 16:45:14] DEBUG[673] chan_iax2.c: Sending 11 on 156/6657 to 127.0.0.1:4571 [Jun 15 16:45:14] DEBUG[667] chan_iax2.c: iax2_devicestate: Found peer. What's device state of fax001? addr=2130706433, defaddr=0 maxms=0, lastms=0 [Jun 15 16:45:14] VERBOSE[673] chan_iax2.c: [Jun 15 16:45:14] Tx-Frame Retry[000] -- OSeqno: 000 ISeqno: 001 Type: IAX Subclass: REGAUTH [Jun 15 16:45:14] DEBUG[667] devicestate.c: Changing state for IAX2/fax001 - state 0 (Unknown) [Jun 15 16:45:14] VERBOSE[673] chan_iax2.c: [Jun 15 16:45:14] Timestamp: 00011ms SCall: 00156 DCall: 06657 [127.0.0.1:4571] [Jun 15 16:45:14] VERBOSE[673] chan_iax2.c: [Jun 15 16:45:14] AUTHMETHODS : 3 [Jun 15 16:45:14] VERBOSE[673] chan_iax2.c: [Jun 15 16:45:14] CHALLENGE : \x34\x30\x38\x32\x39\x32\x39\x34\x33 [Jun 15 16:45:14] DEBUG[667] devicestate.c: device 'IAX2/fax001' state '0' [Jun 15 16:45:14] VERBOSE[673] chan_iax2.c: [Jun 15 16:45:14] USERNAME : fax001 [Jun 15 16:45:14] VERBOSE[673] chan_iax2.c: [Jun 15 16:45:14] [Jun 15 16:45:14] VERBOSE[676] chan_iax2.c: [Jun 15 16:45:14] Rx-Frame Retry[ No] -- OSeqno: 001 ISeqno: 001 Type: IAX Subclass: REGREQ [Jun 15 16:45:14] VERBOSE[676] chan_iax2.c: [Jun 15 16:45:14] Timestamp: 00008ms SCall: 06657 DCall: 00156 [127.0.0.1:4571] [Jun 15 16:45:14] VERBOSE[676] chan_iax2.c: [Jun 15 16:45:14] USERNAME : fax001 [Jun 15 16:45:14] VERBOSE[676] chan_iax2.c: [Jun 15 16:45:14] MD5 RESULT : 9cf79860a9fe89e32e7c41bb1ded6572 [Jun 15 16:45:14] VERBOSE[676] chan_iax2.c: [Jun 15 16:45:14] REFRESH : 60 [Jun 15 16:45:14] VERBOSE[676] chan_iax2.c: [Jun 15 16:45:14] [Jun 15 16:45:14] DEBUG[676] chan_iax2.c: Received packet 1, (6, 13) [Jun 15 16:45:14] DEBUG[676] chan_iax2.c: Cancelling transmission of packet 0 [Jun 15 16:45:14] DEBUG[676] chan_iax2.c: IAX subclass 13 received [Jun 15 16:45:14] DEBUG[676] chan_iax2.c: For call=156, set last=8 [Jun 15 16:45:14] DEBUG[699] app_queue.c: Device 'IAX2/fax001' changed to state '0' (Unknown) but we don't care because they're not a member of any queue. [Jun 15 16:45:14] DEBUG[667] devicestate.c: No provider found, checking channel drivers for IAX2 - fax001 [Jun 15 16:45:14] DEBUG[667] chan_iax2.c: Checking device state for device fax001 [Jun 15 16:45:14] DEBUG[667] chan_iax2.c: iax2_devicestate: Found peer. What's device state of fax001? addr=2130706433, defaddr=0 maxms=0, lastms=0 [Jun 15 16:45:14] DEBUG[667] devicestate.c: Changing state for IAX2/fax001 - state 0 (Unknown) [Jun 15 16:45:14] DEBUG[667] devicestate.c: device 'IAX2/fax001' state '0' [Jun 15 16:45:14] DEBUG[673] chan_iax2.c: Sending 26 on 156/6657 to 127.0.0.1:4571 [Jun 15 16:45:14] VERBOSE[673] chan_iax2.c: [Jun 15 16:45:14] Tx-Frame Retry[000] -- OSeqno: 001 ISeqno: 002 Type: IAX Subclass: REGACK [Jun 15 16:45:14] VERBOSE[673] chan_iax2.c: [Jun 15 16:45:14] Timestamp: 00026ms SCall: 00156 DCall: 06657 [127.0.0.1:4571] [Jun 15 16:45:14] VERBOSE[673] chan_iax2.c: [Jun 15 16:45:14] USERNAME : fax001 [Jun 15 16:45:14] VERBOSE[673] chan_iax2.c: [Jun 15 16:45:14] DATE TIME : 2012-06-15 16:45:14 [Jun 15 16:45:14] DEBUG[699] app_queue.c: Device 'IAX2/fax001' changed to state '0' (Unknown) but we don't care because they're not a member of any queue. [Jun 15 16:45:14] VERBOSE[673] chan_iax2.c: [Jun 15 16:45:14] REFRESH : 60 [Jun 15 16:45:14] VERBOSE[673] chan_iax2.c: [Jun 15 16:45:14] APPARENT ADDRES : IPV4 127.0.0.1:4571 [Jun 15 16:45:14] VERBOSE[673] chan_iax2.c: [Jun 15 16:45:14] CALLING NUMBER : 8476039009 [Jun 15 16:45:14] VERBOSE[673] chan_iax2.c: [Jun 15 16:45:14] CALLING NAME : Fax001 [Jun 15 16:45:14] VERBOSE[673] chan_iax2.c: [Jun 15 16:45:14] [Jun 15 16:45:14] VERBOSE[677] chan_iax2.c: [Jun 15 16:45:14] Rx-Frame Retry[ No] -- OSeqno: 002 ISeqno: 002 Type: IAX Subclass: ACK [Jun 15 16:45:14] VERBOSE[677] chan_iax2.c: [Jun 15 16:45:14] Timestamp: 00026ms SCall: 06657 DCall: 00156 [127.0.0.1:4571] [Jun 15 16:45:14] DEBUG[677] chan_iax2.c: Received packet 2, (6, 4) [Jun 15 16:45:14] DEBUG[677] chan_iax2.c: Cancelling transmission of packet 1 [Jun 15 16:45:14] DEBUG[677] chan_iax2.c: Really destroying 156, having been acked on final message [Jun 15 16:45:14] DEBUG[677] chan_iax2.c: schedule decrement of callno used for 127.0.0.1 in 60 seconds [Jun 15 16:45:16] VERBOSE[681] chan_iax2.c: [Jun 15 16:45:16] Rx-Frame Retry[ No] -- OSeqno: 000 ISeqno: 000 Type: IAX Subclass: REGREQ [Jun 15 16:45:16] VERBOSE[681] chan_iax2.c: [Jun 15 16:45:16] Timestamp: 00003ms SCall: 06658 DCall: 00000 [127.0.0.1:4574] [Jun 15 16:45:16] VERBOSE[681] chan_iax2.c: [Jun 15 16:45:16] USERNAME : fax004 [Jun 15 16:45:16] VERBOSE[681] chan_iax2.c: [Jun 15 16:45:16] REFRESH : 60 [Jun 15 16:45:16] VERBOSE[681] chan_iax2.c: [Jun 15 16:45:16] [Jun 15 16:45:16] DEBUG[681] chan_iax2.c: Determining if address 127.0.0.1 with username fax004 requires calltoken validation. Optional = 0 calltoken_required = 3 [Jun 15 16:45:16] DEBUG[681] chan_iax2.c: ip callno count incremented to 12 for 127.0.0.1 [Jun 15 16:45:16] DEBUG[681] chan_iax2.c: Creating new call structure 1812 [Jun 15 16:45:16] DEBUG[681] chan_iax2.c: Received packet 0, (6, 13) [Jun 15 16:45:16] DEBUG[681] chan_iax2.c: IAX subclass 13 received [Jun 15 16:45:16] DEBUG[681] chan_iax2.c: For call=1812, set last=3 [Jun 15 16:45:16] DEBUG[667] devicestate.c: No provider found, checking channel drivers for IAX2 - fax004 [Jun 15 16:45:16] DEBUG[667] chan_iax2.c: Checking device state for device fax004 [Jun 15 16:45:16] DEBUG[673] chan_iax2.c: Sending 8 on 1812/6658 to 127.0.0.1:4574 [Jun 15 16:45:16] DEBUG[667] chan_iax2.c: iax2_devicestate: Found peer. What's device state of fax004? addr=2130706433, defaddr=0 maxms=0, lastms=0 [Jun 15 16:45:16] VERBOSE[673] chan_iax2.c: [Jun 15 16:45:16] Tx-Frame Retry[000] -- OSeqno: 000 ISeqno: 001 Type: IAX Subclass: REGAUTH [Jun 15 16:45:16] DEBUG[667] devicestate.c: Changing state for IAX2/fax004 - state 0 (Unknown) [Jun 15 16:45:16] VERBOSE[673] chan_iax2.c: [Jun 15 16:45:16] Timestamp: 00008ms SCall: 01812 DCall: 06658 [127.0.0.1:4574] [Jun 15 16:45:16] DEBUG[667] devicestate.c: device 'IAX2/fax004' state '0' [Jun 15 16:45:16] VERBOSE[673] chan_iax2.c: [Jun 15 16:45:16] AUTHMETHODS : 3 [Jun 15 16:45:16] VERBOSE[673] chan_iax2.c: [Jun 15 16:45:16] CHALLENGE : \x34\x35\x39\x33\x34\x33\x37\x33\x36 [Jun 15 16:45:16] VERBOSE[673] chan_iax2.c: [Jun 15 16:45:16] USERNAME : fax004 [Jun 15 16:45:16] VERBOSE[673] chan_iax2.c: [Jun 15 16:45:16] [Jun 15 16:45:16] DEBUG[699] app_queue.c: Device 'IAX2/fax004' changed to state '0' (Unknown) but we don't care because they're not a member of any queue. [Jun 15 16:45:16] VERBOSE[680] chan_iax2.c: [Jun 15 16:45:16] Rx-Frame Retry[ No] -- OSeqno: 001 ISeqno: 001 Type: IAX Subclass: REGREQ [Jun 15 16:45:16] VERBOSE[680] chan_iax2.c: [Jun 15 16:45:16] Timestamp: 00008ms SCall: 06658 DCall: 01812 [127.0.0.1:4574] [Jun 15 16:45:16] VERBOSE[680] chan_iax2.c: [Jun 15 16:45:16] USERNAME : fax004 [Jun 15 16:45:16] VERBOSE[680] chan_iax2.c: [Jun 15 16:45:16] MD5 RESULT : c03d4fc5f70f3c3a830b2ae0449c3641 [Jun 15 16:45:16] VERBOSE[680] chan_iax2.c: [Jun 15 16:45:16] REFRESH : 60 [Jun 15 16:45:16] VERBOSE[680] chan_iax2.c: [Jun 15 16:45:16] [Jun 15 16:45:16] DEBUG[680] chan_iax2.c: Received packet 1, (6, 13) [Jun 15 16:45:16] DEBUG[680] chan_iax2.c: Cancelling transmission of packet 0 [Jun 15 16:45:16] DEBUG[680] chan_iax2.c: IAX subclass 13 received [Jun 15 16:45:16] DEBUG[680] chan_iax2.c: For call=1812, set last=8 [Jun 15 16:45:16] DEBUG[667] devicestate.c: No provider found, checking channel drivers for IAX2 - fax004 [Jun 15 16:45:16] DEBUG[667] chan_iax2.c: Checking device state for device fax004 [Jun 15 16:45:16] DEBUG[667] chan_iax2.c: iax2_devicestate: Found peer. What's device state of fax004? addr=2130706433, defaddr=0 maxms=0, lastms=0 [Jun 15 16:45:16] DEBUG[667] devicestate.c: Changing state for IAX2/fax004 - state 0 (Unknown) [Jun 15 16:45:16] DEBUG[667] devicestate.c: device 'IAX2/fax004' state '0' [Jun 15 16:45:16] DEBUG[673] chan_iax2.c: Sending 21 on 1812/6658 to 127.0.0.1:4574 [Jun 15 16:45:16] VERBOSE[673] chan_iax2.c: [Jun 15 16:45:16] Tx-Frame Retry[000] -- OSeqno: 001 ISeqno: 002 Type: IAX Subclass: REGACK [Jun 15 16:45:16] VERBOSE[673] chan_iax2.c: [Jun 15 16:45:16] Timestamp: 00021ms SCall: 01812 DCall: 06658 [127.0.0.1:4574] [Jun 15 16:45:16] DEBUG[699] app_queue.c: Device 'IAX2/fax004' changed to state '0' (Unknown) but we don't care because they're not a member of any queue. [Jun 15 16:45:16] VERBOSE[673] chan_iax2.c: [Jun 15 16:45:16] USERNAME : fax004 [Jun 15 16:45:16] VERBOSE[673] chan_iax2.c: [Jun 15 16:45:16] DATE TIME : 2012-06-15 16:45:16 [Jun 15 16:45:16] VERBOSE[673] chan_iax2.c: [Jun 15 16:45:16] REFRESH : 60 [Jun 15 16:45:16] VERBOSE[673] chan_iax2.c: [Jun 15 16:45:16] APPARENT ADDRES : IPV4 127.0.0.1:4574 [Jun 15 16:45:16] VERBOSE[673] chan_iax2.c: [Jun 15 16:45:16] CALLING NUMBER : 8476039009 [Jun 15 16:45:16] VERBOSE[673] chan_iax2.c: [Jun 15 16:45:16] CALLING NAME : Fax004 [Jun 15 16:45:16] VERBOSE[673] chan_iax2.c: [Jun 15 16:45:16] [Jun 15 16:45:16] VERBOSE[682] chan_iax2.c: [Jun 15 16:45:16] Rx-Frame Retry[ No] -- OSeqno: 002 ISeqno: 002 Type: IAX Subclass: ACK [Jun 15 16:45:16] VERBOSE[682] chan_iax2.c: [Jun 15 16:45:16] Timestamp: 00021ms SCall: 06658 DCall: 01812 [127.0.0.1:4574] [Jun 15 16:45:16] DEBUG[682] chan_iax2.c: Received packet 2, (6, 4) [Jun 15 16:45:16] DEBUG[682] chan_iax2.c: Cancelling transmission of packet 1 [Jun 15 16:45:16] DEBUG[682] chan_iax2.c: Really destroying 1812, having been acked on final message [Jun 15 16:45:16] DEBUG[682] chan_iax2.c: schedule decrement of callno used for 127.0.0.1 in 60 seconds [Jun 15 16:45:18] VERBOSE[675] chan_iax2.c: [Jun 15 16:45:18] Rx-Frame Retry[ No] -- OSeqno: 000 ISeqno: 000 Type: IAX Subclass: REGREQ [Jun 15 16:45:18] VERBOSE[675] chan_iax2.c: [Jun 15 16:45:18] Timestamp: 00003ms SCall: 06657 DCall: 00000 [127.0.0.1:4579] [Jun 15 16:45:18] VERBOSE[675] chan_iax2.c: [Jun 15 16:45:18] USERNAME : fax009 [Jun 15 16:45:18] VERBOSE[675] chan_iax2.c: [Jun 15 16:45:18] REFRESH : 60 [Jun 15 16:45:18] VERBOSE[675] chan_iax2.c: [Jun 15 16:45:18] [Jun 15 16:45:18] DEBUG[675] chan_iax2.c: Determining if address 127.0.0.1 with username fax009 requires calltoken validation. Optional = 0 calltoken_required = 3 [Jun 15 16:45:18] DEBUG[675] chan_iax2.c: ip callno count incremented to 13 for 127.0.0.1 [Jun 15 16:45:18] DEBUG[675] chan_iax2.c: Creating new call structure 8095 [Jun 15 16:45:18] DEBUG[675] chan_iax2.c: Received packet 0, (6, 13) [Jun 15 16:45:18] DEBUG[675] chan_iax2.c: IAX subclass 13 received [Jun 15 16:45:18] DEBUG[675] chan_iax2.c: For call=8095, set last=3 [Jun 15 16:45:18] DEBUG[667] devicestate.c: No provider found, checking channel drivers for IAX2 - fax009 [Jun 15 16:45:18] DEBUG[667] chan_iax2.c: Checking device state for device fax009 [Jun 15 16:45:18] DEBUG[673] chan_iax2.c: Sending 10 on 8095/6657 to 127.0.0.1:4579 [Jun 15 16:45:18] VERBOSE[673] chan_iax2.c: [Jun 15 16:45:18] Tx-Frame Retry[000] -- OSeqno: 000 ISeqno: 001 Type: IAX Subclass: REGAUTH [Jun 15 16:45:18] DEBUG[667] chan_iax2.c: iax2_devicestate: Found peer. What's device state of fax009? addr=2130706433, defaddr=0 maxms=0, lastms=0 [Jun 15 16:45:18] VERBOSE[673] chan_iax2.c: [Jun 15 16:45:18] Timestamp: 00010ms SCall: 08095 DCall: 06657 [127.0.0.1:4579] [Jun 15 16:45:18] VERBOSE[673] chan_iax2.c: [Jun 15 16:45:18] AUTHMETHODS : 3 [Jun 15 16:45:18] DEBUG[667] devicestate.c: Changing state for IAX2/fax009 - state 0 (Unknown) [Jun 15 16:45:18] DEBUG[667] devicestate.c: device 'IAX2/fax009' state '0' [Jun 15 16:45:18] VERBOSE[673] chan_iax2.c: [Jun 15 16:45:18] CHALLENGE : \x31\x32\x31\x34\x35\x37\x39\x31\x35 [Jun 15 16:45:18] VERBOSE[673] chan_iax2.c: [Jun 15 16:45:18] USERNAME : fax009 [Jun 15 16:45:18] VERBOSE[673] chan_iax2.c: [Jun 15 16:45:18] [Jun 15 16:45:18] VERBOSE[676] chan_iax2.c: [Jun 15 16:45:18] Rx-Frame Retry[ No] -- OSeqno: 001 ISeqno: 001 Type: IAX Subclass: REGREQ [Jun 15 16:45:18] VERBOSE[676] chan_iax2.c: [Jun 15 16:45:18] Timestamp: 00011ms SCall: 06657 DCall: 08095 [127.0.0.1:4579] [Jun 15 16:45:18] DEBUG[699] app_queue.c: Device 'IAX2/fax009' changed to state '0' (Unknown) but we don't care because they're not a member of any queue. [Jun 15 16:45:18] VERBOSE[676] chan_iax2.c: [Jun 15 16:45:18] USERNAME : fax009 [Jun 15 16:45:18] VERBOSE[676] chan_iax2.c: [Jun 15 16:45:18] MD5 RESULT : 9916bf9fec249511d70f1315ff3b5224 [Jun 15 16:45:18] VERBOSE[676] chan_iax2.c: [Jun 15 16:45:18] REFRESH : 60 [Jun 15 16:45:18] VERBOSE[676] chan_iax2.c: [Jun 15 16:45:18] [Jun 15 16:45:18] DEBUG[676] chan_iax2.c: Received packet 1, (6, 13) [Jun 15 16:45:18] DEBUG[676] chan_iax2.c: Cancelling transmission of packet 0 [Jun 15 16:45:18] DEBUG[676] chan_iax2.c: IAX subclass 13 received [Jun 15 16:45:18] DEBUG[676] chan_iax2.c: For call=8095, set last=11 [Jun 15 16:45:18] DEBUG[667] devicestate.c: No provider found, checking channel drivers for IAX2 - fax009 [Jun 15 16:45:18] DEBUG[667] chan_iax2.c: Checking device state for device fax009 [Jun 15 16:45:18] DEBUG[667] chan_iax2.c: iax2_devicestate: Found peer. What's device state of fax009? addr=2130706433, defaddr=0 maxms=0, lastms=0 [Jun 15 16:45:18] DEBUG[667] devicestate.c: Changing state for IAX2/fax009 - state 0 (Unknown) [Jun 15 16:45:18] DEBUG[667] devicestate.c: device 'IAX2/fax009' state '0' [Jun 15 16:45:18] DEBUG[673] chan_iax2.c: Sending 25 on 8095/6657 to 127.0.0.1:4579 [Jun 15 16:45:18] VERBOSE[673] chan_iax2.c: [Jun 15 16:45:18] Tx-Frame Retry[000] -- OSeqno: 001 ISeqno: 002 Type: IAX Subclass: REGACK [Jun 15 16:45:18] VERBOSE[673] chan_iax2.c: [Jun 15 16:45:18] Timestamp: 00025ms SCall: 08095 DCall: 06657 [127.0.0.1:4579] [Jun 15 16:45:18] VERBOSE[673] chan_iax2.c: [Jun 15 16:45:18] USERNAME : fax009 [Jun 15 16:45:18] VERBOSE[673] chan_iax2.c: [Jun 15 16:45:18] DATE TIME : 2012-06-15 16:45:18 [Jun 15 16:45:18] DEBUG[699] app_queue.c: Device 'IAX2/fax009' changed to state '0' (Unknown) but we don't care because they're not a member of any queue. [Jun 15 16:45:18] VERBOSE[673] chan_iax2.c: [Jun 15 16:45:18] REFRESH : 60 [Jun 15 16:45:18] VERBOSE[673] chan_iax2.c: [Jun 15 16:45:18] APPARENT ADDRES : IPV4 127.0.0.1:4579 [Jun 15 16:45:18] VERBOSE[673] chan_iax2.c: [Jun 15 16:45:18] CALLING NUMBER : 8476039009 [Jun 15 16:45:18] VERBOSE[673] chan_iax2.c: [Jun 15 16:45:18] CALLING NAME : Fax009 [Jun 15 16:45:18] VERBOSE[673] chan_iax2.c: [Jun 15 16:45:18] [Jun 15 16:45:18] VERBOSE[677] chan_iax2.c: [Jun 15 16:45:18] Rx-Frame Retry[ No] -- OSeqno: 002 ISeqno: 002 Type: IAX Subclass: ACK [Jun 15 16:45:18] VERBOSE[677] chan_iax2.c: [Jun 15 16:45:18] Timestamp: 00025ms SCall: 06657 DCall: 08095 [127.0.0.1:4579] [Jun 15 16:45:18] DEBUG[677] chan_iax2.c: Received packet 2, (6, 4) [Jun 15 16:45:18] DEBUG[677] chan_iax2.c: Cancelling transmission of packet 1 [Jun 15 16:45:18] DEBUG[677] chan_iax2.c: Really destroying 8095, having been acked on final message [Jun 15 16:45:18] DEBUG[677] chan_iax2.c: schedule decrement of callno used for 127.0.0.1 in 60 seconds [Jun 15 16:45:19] VERBOSE[678] chan_iax2.c: [Jun 15 16:45:19] Rx-Frame Retry[ No] -- OSeqno: 000 ISeqno: 000 Type: IAX Subclass: REGREQ [Jun 15 16:45:19] VERBOSE[678] chan_iax2.c: [Jun 15 16:45:19] Timestamp: 00003ms SCall: 06657 DCall: 00000 [127.0.0.1:4578] [Jun 15 16:45:19] VERBOSE[678] chan_iax2.c: [Jun 15 16:45:19] USERNAME : fax008 [Jun 15 16:45:19] VERBOSE[678] chan_iax2.c: [Jun 15 16:45:19] REFRESH : 60 [Jun 15 16:45:19] VERBOSE[678] chan_iax2.c: [Jun 15 16:45:19] [Jun 15 16:45:19] DEBUG[678] chan_iax2.c: Determining if address 127.0.0.1 with username fax008 requires calltoken validation. Optional = 0 calltoken_required = 3 [Jun 15 16:45:19] DEBUG[678] chan_iax2.c: ip callno count incremented to 14 for 127.0.0.1 [Jun 15 16:45:19] DEBUG[678] chan_iax2.c: Creating new call structure 8081 [Jun 15 16:45:19] DEBUG[678] chan_iax2.c: Received packet 0, (6, 13) [Jun 15 16:45:19] DEBUG[678] chan_iax2.c: IAX subclass 13 received [Jun 15 16:45:19] DEBUG[678] chan_iax2.c: For call=8081, set last=3 [Jun 15 16:45:19] DEBUG[667] devicestate.c: No provider found, checking channel drivers for IAX2 - fax008 [Jun 15 16:45:19] DEBUG[667] chan_iax2.c: Checking device state for device fax008 [Jun 15 16:45:19] DEBUG[667] chan_iax2.c: iax2_devicestate: Found peer. What's device state of fax008? addr=2130706433, defaddr=0 maxms=0, lastms=0 [Jun 15 16:45:19] DEBUG[673] chan_iax2.c: Sending 3 on 8081/6657 to 127.0.0.1:4578 [Jun 15 16:45:19] VERBOSE[673] chan_iax2.c: [Jun 15 16:45:19] Tx-Frame Retry[000] -- OSeqno: 000 ISeqno: 001 Type: IAX Subclass: REGAUTH [Jun 15 16:45:19] VERBOSE[673] chan_iax2.c: [Jun 15 16:45:19] Timestamp: 00003ms SCall: 08081 DCall: 06657 [127.0.0.1:4578] [Jun 15 16:45:19] DEBUG[667] devicestate.c: Changing state for IAX2/fax008 - state 0 (Unknown) [Jun 15 16:45:19] VERBOSE[673] chan_iax2.c: [Jun 15 16:45:19] AUTHMETHODS : 3 [Jun 15 16:45:19] DEBUG[667] devicestate.c: device 'IAX2/fax008' state '0' [Jun 15 16:45:19] VERBOSE[673] chan_iax2.c: [Jun 15 16:45:19] CHALLENGE : \x31\x33\x34\x30\x36\x39\x34\x38\x35 [Jun 15 16:45:19] VERBOSE[673] chan_iax2.c: [Jun 15 16:45:19] USERNAME : fax008 [Jun 15 16:45:19] VERBOSE[673] chan_iax2.c: [Jun 15 16:45:19] [Jun 15 16:45:19] DEBUG[699] app_queue.c: Device 'IAX2/fax008' changed to state '0' (Unknown) but we don't care because they're not a member of any queue. [Jun 15 16:45:19] VERBOSE[679] chan_iax2.c: [Jun 15 16:45:19] Rx-Frame Retry[ No] -- OSeqno: 001 ISeqno: 001 Type: IAX Subclass: REGREQ [Jun 15 16:45:19] VERBOSE[679] chan_iax2.c: [Jun 15 16:45:19] Timestamp: 00010ms SCall: 06657 DCall: 08081 [127.0.0.1:4578] [Jun 15 16:45:19] VERBOSE[679] chan_iax2.c: [Jun 15 16:45:19] USERNAME : fax008 [Jun 15 16:45:19] VERBOSE[679] chan_iax2.c: [Jun 15 16:45:19] MD5 RESULT : 6fbfdd0abd679f91639fa4f894b0ea32 [Jun 15 16:45:19] VERBOSE[679] chan_iax2.c: [Jun 15 16:45:19] REFRESH : 60 [Jun 15 16:45:19] VERBOSE[679] chan_iax2.c: [Jun 15 16:45:19] [Jun 15 16:45:19] DEBUG[679] chan_iax2.c: Received packet 1, (6, 13) [Jun 15 16:45:19] DEBUG[679] chan_iax2.c: Cancelling transmission of packet 0 [Jun 15 16:45:19] DEBUG[679] chan_iax2.c: IAX subclass 13 received [Jun 15 16:45:19] DEBUG[679] chan_iax2.c: For call=8081, set last=10 [Jun 15 16:45:19] DEBUG[667] devicestate.c: No provider found, checking channel drivers for IAX2 - fax008 [Jun 15 16:45:19] DEBUG[667] chan_iax2.c: Checking device state for device fax008 [Jun 15 16:45:19] DEBUG[667] chan_iax2.c: iax2_devicestate: Found peer. What's device state of fax008? addr=2130706433, defaddr=0 maxms=0, lastms=0 [Jun 15 16:45:19] DEBUG[667] devicestate.c: Changing state for IAX2/fax008 - state 0 (Unknown) [Jun 15 16:45:19] DEBUG[667] devicestate.c: device 'IAX2/fax008' state '0' [Jun 15 16:45:19] DEBUG[673] chan_iax2.c: Sending 16 on 8081/6657 to 127.0.0.1:4578 [Jun 15 16:45:19] VERBOSE[673] chan_iax2.c: [Jun 15 16:45:19] Tx-Frame Retry[000] -- OSeqno: 001 ISeqno: 002 Type: IAX Subclass: REGACK [Jun 15 16:45:19] VERBOSE[673] chan_iax2.c: [Jun 15 16:45:19] Timestamp: 00016ms SCall: 08081 DCall: 06657 [127.0.0.1:4578] [Jun 15 16:45:19] VERBOSE[673] chan_iax2.c: [Jun 15 16:45:19] USERNAME : fax008 [Jun 15 16:45:19] VERBOSE[673] chan_iax2.c: [Jun 15 16:45:19] DATE TIME : 2012-06-15 16:45:18 [Jun 15 16:45:19] VERBOSE[673] chan_iax2.c: [Jun 15 16:45:19] REFRESH : 60 [Jun 15 16:45:19] VERBOSE[673] chan_iax2.c: [Jun 15 16:45:19] APPARENT ADDRES : IPV4 127.0.0.1:4578 [Jun 15 16:45:19] VERBOSE[673] chan_iax2.c: [Jun 15 16:45:19] CALLING NUMBER : 8476039009 [Jun 15 16:45:19] VERBOSE[673] chan_iax2.c: [Jun 15 16:45:19] CALLING NAME : Fax008 [Jun 15 16:45:19] VERBOSE[673] chan_iax2.c: [Jun 15 16:45:19] [Jun 15 16:45:19] VERBOSE[681] chan_iax2.c: [Jun 15 16:45:19] Rx-Frame Retry[ No] -- OSeqno: 002 ISeqno: 002 Type: IAX Subclass: ACK [Jun 15 16:45:19] DEBUG[699] app_queue.c: Device 'IAX2/fax008' changed to state '0' (Unknown) but we don't care because they're not a member of any queue. [Jun 15 16:45:19] VERBOSE[681] chan_iax2.c: [Jun 15 16:45:19] Timestamp: 00016ms SCall: 06657 DCall: 08081 [127.0.0.1:4578] [Jun 15 16:45:19] DEBUG[681] chan_iax2.c: Received packet 2, (6, 4) [Jun 15 16:45:19] DEBUG[681] chan_iax2.c: Cancelling transmission of packet 1 [Jun 15 16:45:19] DEBUG[681] chan_iax2.c: Really destroying 8081, having been acked on final message [Jun 15 16:45:19] DEBUG[681] chan_iax2.c: schedule decrement of callno used for 127.0.0.1 in 60 seconds [Jun 15 16:45:19] DEBUG[674] chan_iax2.c: ip callno count decremented to 13 for 127.0.0.1 [Jun 15 16:45:20] VERBOSE[680] chan_iax2.c: [Jun 15 16:45:20] Rx-Frame Retry[ No] -- OSeqno: 000 ISeqno: 000 Type: IAX Subclass: REGREQ [Jun 15 16:45:20] VERBOSE[680] chan_iax2.c: [Jun 15 16:45:20] Timestamp: 00003ms SCall: 06658 DCall: 00000 [127.0.0.1:4573] [Jun 15 16:45:20] VERBOSE[680] chan_iax2.c: [Jun 15 16:45:20] USERNAME : fax003 [Jun 15 16:45:20] VERBOSE[680] chan_iax2.c: [Jun 15 16:45:20] REFRESH : 60 [Jun 15 16:45:20] VERBOSE[680] chan_iax2.c: [Jun 15 16:45:20] [Jun 15 16:45:20] DEBUG[680] chan_iax2.c: Determining if address 127.0.0.1 with username fax003 requires calltoken validation. Optional = 0 calltoken_required = 3 [Jun 15 16:45:20] DEBUG[680] chan_iax2.c: ip callno count incremented to 14 for 127.0.0.1 [Jun 15 16:45:20] DEBUG[680] chan_iax2.c: Creating new call structure 4695 [Jun 15 16:45:20] DEBUG[680] chan_iax2.c: Received packet 0, (6, 13) [Jun 15 16:45:20] DEBUG[680] chan_iax2.c: IAX subclass 13 received [Jun 15 16:45:20] DEBUG[680] chan_iax2.c: For call=4695, set last=3 [Jun 15 16:45:20] DEBUG[667] devicestate.c: No provider found, checking channel drivers for IAX2 - fax003 [Jun 15 16:45:20] DEBUG[667] chan_iax2.c: Checking device state for device fax003 [Jun 15 16:45:20] DEBUG[673] chan_iax2.c: Sending 18 on 4695/6658 to 127.0.0.1:4573 [Jun 15 16:45:20] DEBUG[667] chan_iax2.c: iax2_devicestate: Found peer. What's device state of fax003? addr=2130706433, defaddr=0 maxms=0, lastms=0 [Jun 15 16:45:20] VERBOSE[673] chan_iax2.c: [Jun 15 16:45:20] Tx-Frame Retry[000] -- OSeqno: 000 ISeqno: 001 Type: IAX Subclass: REGAUTH [Jun 15 16:45:20] DEBUG[667] devicestate.c: Changing state for IAX2/fax003 - state 0 (Unknown) [Jun 15 16:45:20] DEBUG[667] devicestate.c: device 'IAX2/fax003' state '0' [Jun 15 16:45:20] VERBOSE[673] chan_iax2.c: [Jun 15 16:45:20] Timestamp: 00018ms SCall: 04695 DCall: 06658 [127.0.0.1:4573] [Jun 15 16:45:20] VERBOSE[673] chan_iax2.c: [Jun 15 16:45:20] AUTHMETHODS : 3 [Jun 15 16:45:20] VERBOSE[673] chan_iax2.c: [Jun 15 16:45:20] CHALLENGE : \x35\x31\x32\x38\x34\x36\x39 [Jun 15 16:45:20] VERBOSE[673] chan_iax2.c: [Jun 15 16:45:20] USERNAME : fax003 [Jun 15 16:45:20] VERBOSE[673] chan_iax2.c: [Jun 15 16:45:20] [Jun 15 16:45:20] VERBOSE[682] chan_iax2.c: [Jun 15 16:45:20] Rx-Frame Retry[ No] -- OSeqno: 001 ISeqno: 001 Type: IAX Subclass: REGREQ [Jun 15 16:45:20] VERBOSE[682] chan_iax2.c: [Jun 15 16:45:20] Timestamp: 00010ms SCall: 06658 DCall: 04695 [127.0.0.1:4573] [Jun 15 16:45:20] VERBOSE[682] chan_iax2.c: [Jun 15 16:45:20] USERNAME : fax003 [Jun 15 16:45:20] DEBUG[699] app_queue.c: Device 'IAX2/fax003' changed to state '0' (Unknown) but we don't care because they're not a member of any queue. [Jun 15 16:45:20] VERBOSE[682] chan_iax2.c: [Jun 15 16:45:20] MD5 RESULT : a067da683d742f5a430614bf817fa774 [Jun 15 16:45:20] VERBOSE[682] chan_iax2.c: [Jun 15 16:45:20] REFRESH : 60 [Jun 15 16:45:20] VERBOSE[682] chan_iax2.c: [Jun 15 16:45:20] [Jun 15 16:45:20] DEBUG[682] chan_iax2.c: Received packet 1, (6, 13) [Jun 15 16:45:20] DEBUG[682] chan_iax2.c: Cancelling transmission of packet 0 [Jun 15 16:45:20] DEBUG[682] chan_iax2.c: IAX subclass 13 received [Jun 15 16:45:20] DEBUG[682] chan_iax2.c: For call=4695, set last=10 [Jun 15 16:45:20] DEBUG[667] devicestate.c: No provider found, checking channel drivers for IAX2 - fax003 [Jun 15 16:45:20] DEBUG[667] chan_iax2.c: Checking device state for device fax003 [Jun 15 16:45:20] DEBUG[667] chan_iax2.c: iax2_devicestate: Found peer. What's device state of fax003? addr=2130706433, defaddr=0 maxms=0, lastms=0 [Jun 15 16:45:20] DEBUG[667] devicestate.c: Changing state for IAX2/fax003 - state 0 (Unknown) [Jun 15 16:45:20] DEBUG[667] devicestate.c: device 'IAX2/fax003' state '0' [Jun 15 16:45:20] DEBUG[673] chan_iax2.c: Sending 32 on 4695/6658 to 127.0.0.1:4573 [Jun 15 16:45:20] VERBOSE[673] chan_iax2.c: [Jun 15 16:45:20] Tx-Frame Retry[000] -- OSeqno: 001 ISeqno: 002 Type: IAX Subclass: REGACK [Jun 15 16:45:20] VERBOSE[673] chan_iax2.c: [Jun 15 16:45:20] Timestamp: 00032ms SCall: 04695 DCall: 06658 [127.0.0.1:4573] [Jun 15 16:45:20] VERBOSE[673] chan_iax2.c: [Jun 15 16:45:20] USERNAME : fax003 [Jun 15 16:45:20] VERBOSE[673] chan_iax2.c: [Jun 15 16:45:20] DATE TIME : 2012-06-15 16:45:20 [Jun 15 16:45:20] VERBOSE[673] chan_iax2.c: [Jun 15 16:45:20] REFRESH : 60 [Jun 15 16:45:20] VERBOSE[673] chan_iax2.c: [Jun 15 16:45:20] APPARENT ADDRES : IPV4 127.0.0.1:4573 [Jun 15 16:45:20] VERBOSE[673] chan_iax2.c: [Jun 15 16:45:20] CALLING NUMBER : 8476039009 [Jun 15 16:45:20] VERBOSE[673] chan_iax2.c: [Jun 15 16:45:20] CALLING NAME : Fax003 [Jun 15 16:45:20] VERBOSE[673] chan_iax2.c: [Jun 15 16:45:20] [Jun 15 16:45:20] VERBOSE[683] chan_iax2.c: [Jun 15 16:45:20] Rx-Frame Retry[ No] -- OSeqno: 002 ISeqno: 002 Type: IAX Subclass: ACK [Jun 15 16:45:20] VERBOSE[683] chan_iax2.c: [Jun 15 16:45:20] Timestamp: 00032ms SCall: 06658 DCall: 04695 [127.0.0.1:4573] [Jun 15 16:45:20] DEBUG[683] chan_iax2.c: Received packet 2, (6, 4) [Jun 15 16:45:20] DEBUG[683] chan_iax2.c: Cancelling transmission of packet 1 [Jun 15 16:45:20] DEBUG[683] chan_iax2.c: Really destroying 4695, having been acked on final message [Jun 15 16:45:20] DEBUG[683] chan_iax2.c: schedule decrement of callno used for 127.0.0.1 in 60 seconds [Jun 15 16:45:20] DEBUG[699] app_queue.c: Device 'IAX2/fax003' changed to state '0' (Unknown) but we don't care because they're not a member of any queue. [Jun 15 16:45:21] VERBOSE[686] chan_sip.c: [Jun 15 16:45:21] <--- SIP read from UDP:x.x.x.134:42225 ---> OPTIONS <-------------> [Jun 15 16:45:21] DEBUG[686] chan_sip.c: Header 0 [ 7]: OPTIONS [Jun 15 16:45:21] VERBOSE[676] chan_iax2.c: [Jun 15 16:45:21] Rx-Frame Retry[ No] -- OSeqno: 000 ISeqno: 000 Type: IAX Subclass: REGREQ [Jun 15 16:45:21] VERBOSE[676] chan_iax2.c: [Jun 15 16:45:21] Timestamp: 00003ms SCall: 06665 DCall: 00000 [127.0.0.1:4570] [Jun 15 16:45:21] VERBOSE[676] chan_iax2.c: [Jun 15 16:45:21] USERNAME : fax000 [Jun 15 16:45:21] VERBOSE[676] chan_iax2.c: [Jun 15 16:45:21] REFRESH : 60 [Jun 15 16:45:21] VERBOSE[676] chan_iax2.c: [Jun 15 16:45:21] [Jun 15 16:45:21] DEBUG[676] chan_iax2.c: Determining if address 127.0.0.1 with username fax000 requires calltoken validation. Optional = 0 calltoken_required = 3 [Jun 15 16:45:21] DEBUG[676] chan_iax2.c: ip callno count incremented to 15 for 127.0.0.1 [Jun 15 16:45:21] DEBUG[676] chan_iax2.c: Creating new call structure 1729 [Jun 15 16:45:21] DEBUG[676] chan_iax2.c: Received packet 0, (6, 13) [Jun 15 16:45:21] DEBUG[676] chan_iax2.c: IAX subclass 13 received [Jun 15 16:45:21] DEBUG[676] chan_iax2.c: For call=1729, set last=3 [Jun 15 16:45:21] DEBUG[667] devicestate.c: No provider found, checking channel drivers for IAX2 - fax000 [Jun 15 16:45:21] DEBUG[667] chan_iax2.c: Checking device state for device fax000 [Jun 15 16:45:21] DEBUG[673] chan_iax2.c: Sending 3 on 1729/6665 to 127.0.0.1:4570 [Jun 15 16:45:21] DEBUG[667] chan_iax2.c: iax2_devicestate: Found peer. What's device state of fax000? addr=2130706433, defaddr=0 maxms=0, lastms=0 [Jun 15 16:45:21] VERBOSE[673] chan_iax2.c: [Jun 15 16:45:21] Tx-Frame Retry[000] -- OSeqno: 000 ISeqno: 001 Type: IAX Subclass: REGAUTH [Jun 15 16:45:21] VERBOSE[673] chan_iax2.c: [Jun 15 16:45:21] Timestamp: 00003ms SCall: 01729 DCall: 06665 [127.0.0.1:4570] [Jun 15 16:45:21] VERBOSE[673] chan_iax2.c: [Jun 15 16:45:21] AUTHMETHODS : 3 [Jun 15 16:45:21] DEBUG[667] devicestate.c: Changing state for IAX2/fax000 - state 0 (Unknown) [Jun 15 16:45:21] DEBUG[667] devicestate.c: device 'IAX2/fax000' state '0' [Jun 15 16:45:21] VERBOSE[673] chan_iax2.c: [Jun 15 16:45:21] CHALLENGE : \x38\x32\x32\x34\x32\x34\x31\x34\x39 [Jun 15 16:45:21] VERBOSE[673] chan_iax2.c: [Jun 15 16:45:21] USERNAME : fax000 [Jun 15 16:45:21] VERBOSE[673] chan_iax2.c: [Jun 15 16:45:21] [Jun 15 16:45:21] VERBOSE[677] chan_iax2.c: [Jun 15 16:45:21] Rx-Frame Retry[ No] -- OSeqno: 001 ISeqno: 001 Type: IAX Subclass: REGREQ [Jun 15 16:45:21] VERBOSE[677] chan_iax2.c: [Jun 15 16:45:21] Timestamp: 00009ms SCall: 06665 DCall: 01729 [127.0.0.1:4570] [Jun 15 16:45:21] VERBOSE[677] chan_iax2.c: [Jun 15 16:45:21] USERNAME : fax000 [Jun 15 16:45:21] VERBOSE[677] chan_iax2.c: [Jun 15 16:45:21] MD5 RESULT : 6bbb9e1d730fe3e2699039c12b0a89c2 [Jun 15 16:45:21] DEBUG[699] app_queue.c: Device 'IAX2/fax000' changed to state '0' (Unknown) but we don't care because they're not a member of any queue. [Jun 15 16:45:21] VERBOSE[677] chan_iax2.c: [Jun 15 16:45:21] REFRESH : 60 [Jun 15 16:45:21] VERBOSE[677] chan_iax2.c: [Jun 15 16:45:21] [Jun 15 16:45:21] DEBUG[677] chan_iax2.c: Received packet 1, (6, 13) [Jun 15 16:45:21] DEBUG[677] chan_iax2.c: Cancelling transmission of packet 0 [Jun 15 16:45:21] DEBUG[677] chan_iax2.c: IAX subclass 13 received [Jun 15 16:45:21] DEBUG[677] chan_iax2.c: For call=1729, set last=9 [Jun 15 16:45:21] DEBUG[667] devicestate.c: No provider found, checking channel drivers for IAX2 - fax000 [Jun 15 16:45:21] DEBUG[667] chan_iax2.c: Checking device state for device fax000 [Jun 15 16:45:21] DEBUG[667] chan_iax2.c: iax2_devicestate: Found peer. What's device state of fax000? addr=2130706433, defaddr=0 maxms=0, lastms=0 [Jun 15 16:45:21] DEBUG[673] chan_iax2.c: Sending 13 on 1729/6665 to 127.0.0.1:4570 [Jun 15 16:45:21] VERBOSE[673] chan_iax2.c: [Jun 15 16:45:21] Tx-Frame Retry[000] -- OSeqno: 001 ISeqno: 002 Type: IAX Subclass: REGACK [Jun 15 16:45:21] DEBUG[667] devicestate.c: Changing state for IAX2/fax000 - state 0 (Unknown) [Jun 15 16:45:21] DEBUG[667] devicestate.c: device 'IAX2/fax000' state '0' [Jun 15 16:45:21] VERBOSE[673] chan_iax2.c: [Jun 15 16:45:21] Timestamp: 00013ms SCall: 01729 DCall: 06665 [127.0.0.1:4570] [Jun 15 16:45:21] VERBOSE[673] chan_iax2.c: [Jun 15 16:45:21] USERNAME : fax000 [Jun 15 16:45:21] VERBOSE[673] chan_iax2.c: [Jun 15 16:45:21] DATE TIME : 2012-06-15 16:45:20 [Jun 15 16:45:21] DEBUG[699] app_queue.c: Device 'IAX2/fax000' changed to state '0' (Unknown) but we don't care because they're not a member of any queue. [Jun 15 16:45:21] VERBOSE[673] chan_iax2.c: [Jun 15 16:45:21] REFRESH : 60 [Jun 15 16:45:21] VERBOSE[673] chan_iax2.c: [Jun 15 16:45:21] APPARENT ADDRES : IPV4 127.0.0.1:4570 [Jun 15 16:45:21] VERBOSE[673] chan_iax2.c: [Jun 15 16:45:21] CALLING NUMBER : 8476039009 [Jun 15 16:45:21] VERBOSE[673] chan_iax2.c: [Jun 15 16:45:21] CALLING NAME : Fax000 [Jun 15 16:45:21] VERBOSE[673] chan_iax2.c: [Jun 15 16:45:21] [Jun 15 16:45:21] VERBOSE[678] chan_iax2.c: [Jun 15 16:45:21] Rx-Frame Retry[ No] -- OSeqno: 002 ISeqno: 002 Type: IAX Subclass: ACK [Jun 15 16:45:21] VERBOSE[678] chan_iax2.c: [Jun 15 16:45:21] Timestamp: 00013ms SCall: 06665 DCall: 01729 [127.0.0.1:4570] [Jun 15 16:45:21] DEBUG[678] chan_iax2.c: Received packet 2, (6, 4) [Jun 15 16:45:21] DEBUG[678] chan_iax2.c: Cancelling transmission of packet 1 [Jun 15 16:45:21] DEBUG[678] chan_iax2.c: Really destroying 1729, having been acked on final message [Jun 15 16:45:21] DEBUG[678] chan_iax2.c: schedule decrement of callno used for 127.0.0.1 in 60 seconds [Jun 15 16:45:21] DEBUG[674] chan_iax2.c: ip callno count decremented to 14 for 127.0.0.1 [Jun 15 16:45:21] VERBOSE[680] chan_iax2.c: [Jun 15 16:45:21] Rx-Frame Retry[ No] -- OSeqno: 000 ISeqno: 000 Type: IAX Subclass: REGREQ [Jun 15 16:45:21] VERBOSE[680] chan_iax2.c: [Jun 15 16:45:21] Timestamp: 00003ms SCall: 06657 DCall: 00000 [127.0.0.1:4577] [Jun 15 16:45:21] VERBOSE[680] chan_iax2.c: [Jun 15 16:45:21] USERNAME : fax007 [Jun 15 16:45:21] VERBOSE[680] chan_iax2.c: [Jun 15 16:45:21] REFRESH : 60 [Jun 15 16:45:21] VERBOSE[680] chan_iax2.c: [Jun 15 16:45:21] [Jun 15 16:45:21] DEBUG[680] chan_iax2.c: Determining if address 127.0.0.1 with username fax007 requires calltoken validation. Optional = 0 calltoken_required = 3 [Jun 15 16:45:21] DEBUG[680] chan_iax2.c: ip callno count incremented to 15 for 127.0.0.1 [Jun 15 16:45:21] DEBUG[680] chan_iax2.c: Creating new call structure 3190 [Jun 15 16:45:21] DEBUG[680] chan_iax2.c: Received packet 0, (6, 13) [Jun 15 16:45:21] DEBUG[680] chan_iax2.c: IAX subclass 13 received [Jun 15 16:45:21] DEBUG[680] chan_iax2.c: For call=3190, set last=3 [Jun 15 16:45:21] DEBUG[667] devicestate.c: No provider found, checking channel drivers for IAX2 - fax007 [Jun 15 16:45:21] DEBUG[667] chan_iax2.c: Checking device state for device fax007 [Jun 15 16:45:21] DEBUG[673] chan_iax2.c: Sending 11 on 3190/6657 to 127.0.0.1:4577 [Jun 15 16:45:21] VERBOSE[673] chan_iax2.c: [Jun 15 16:45:21] Tx-Frame Retry[000] -- OSeqno: 000 ISeqno: 001 Type: IAX Subclass: REGAUTH [Jun 15 16:45:21] VERBOSE[673] chan_iax2.c: [Jun 15 16:45:21] Timestamp: 00011ms SCall: 03190 DCall: 06657 [127.0.0.1:4577] [Jun 15 16:45:21] VERBOSE[673] chan_iax2.c: [Jun 15 16:45:21] AUTHMETHODS : 3 [Jun 15 16:45:21] VERBOSE[673] chan_iax2.c: [Jun 15 16:45:21] CHALLENGE : \x31\x35\x39\x36\x32\x30\x39\x37\x38 [Jun 15 16:45:21] VERBOSE[673] chan_iax2.c: [Jun 15 16:45:21] USERNAME : fax007 [Jun 15 16:45:21] VERBOSE[673] chan_iax2.c: [Jun 15 16:45:21] [Jun 15 16:45:21] DEBUG[667] chan_iax2.c: iax2_devicestate: Found peer. What's device state of fax007? addr=2130706433, defaddr=0 maxms=0, lastms=0 [Jun 15 16:45:21] VERBOSE[682] chan_iax2.c: [Jun 15 16:45:21] Rx-Frame Retry[ No] -- OSeqno: 001 ISeqno: 001 Type: IAX Subclass: REGREQ [Jun 15 16:45:21] DEBUG[667] devicestate.c: Changing state for IAX2/fax007 - state 0 (Unknown) [Jun 15 16:45:21] VERBOSE[682] chan_iax2.c: [Jun 15 16:45:21] Timestamp: 00006ms SCall: 06657 DCall: 03190 [127.0.0.1:4577] [Jun 15 16:45:21] DEBUG[667] devicestate.c: device 'IAX2/fax007' state '0' [Jun 15 16:45:21] VERBOSE[682] chan_iax2.c: [Jun 15 16:45:21] USERNAME : fax007 [Jun 15 16:45:21] VERBOSE[682] chan_iax2.c: [Jun 15 16:45:21] MD5 RESULT : bfdeb4d85975d4155bea9f3d6a29c60f [Jun 15 16:45:21] VERBOSE[682] chan_iax2.c: [Jun 15 16:45:21] REFRESH : 60 [Jun 15 16:45:21] DEBUG[699] app_queue.c: Device 'IAX2/fax007' changed to state '0' (Unknown) but we don't care because they're not a member of any queue. [Jun 15 16:45:21] VERBOSE[682] chan_iax2.c: [Jun 15 16:45:21] [Jun 15 16:45:21] DEBUG[682] chan_iax2.c: Received packet 1, (6, 13) [Jun 15 16:45:21] DEBUG[682] chan_iax2.c: Cancelling transmission of packet 0 [Jun 15 16:45:21] DEBUG[682] chan_iax2.c: IAX subclass 13 received [Jun 15 16:45:21] DEBUG[682] chan_iax2.c: For call=3190, set last=6 [Jun 15 16:45:21] DEBUG[667] devicestate.c: No provider found, checking channel drivers for IAX2 - fax007 [Jun 15 16:45:21] DEBUG[667] chan_iax2.c: Checking device state for device fax007 [Jun 15 16:45:21] DEBUG[667] chan_iax2.c: iax2_devicestate: Found peer. What's device state of fax007? addr=2130706433, defaddr=0 maxms=0, lastms=0 [Jun 15 16:45:21] DEBUG[667] devicestate.c: Changing state for IAX2/fax007 - state 0 (Unknown) [Jun 15 16:45:21] DEBUG[667] devicestate.c: device 'IAX2/fax007' state '0' [Jun 15 16:45:21] DEBUG[673] chan_iax2.c: Sending 23 on 3190/6657 to 127.0.0.1:4577 [Jun 15 16:45:21] VERBOSE[673] chan_iax2.c: [Jun 15 16:45:21] Tx-Frame Retry[000] -- OSeqno: 001 ISeqno: 002 Type: IAX Subclass: REGACK [Jun 15 16:45:21] VERBOSE[673] chan_iax2.c: [Jun 15 16:45:21] Timestamp: 00023ms SCall: 03190 DCall: 06657 [127.0.0.1:4577] [Jun 15 16:45:21] VERBOSE[673] chan_iax2.c: [Jun 15 16:45:21] USERNAME : fax007 [Jun 15 16:45:21] VERBOSE[673] chan_iax2.c: [Jun 15 16:45:21] DATE TIME : 2012-06-15 16:45:20 [Jun 15 16:45:21] DEBUG[699] app_queue.c: Device 'IAX2/fax007' changed to state '0' (Unknown) but we don't care because they're not a member of any queue. [Jun 15 16:45:21] VERBOSE[673] chan_iax2.c: [Jun 15 16:45:21] REFRESH : 60 [Jun 15 16:45:21] VERBOSE[673] chan_iax2.c: [Jun 15 16:45:21] APPARENT ADDRES : IPV4 127.0.0.1:4577 [Jun 15 16:45:21] VERBOSE[673] chan_iax2.c: [Jun 15 16:45:21] CALLING NUMBER : 8476039009 [Jun 15 16:45:21] VERBOSE[673] chan_iax2.c: [Jun 15 16:45:21] CALLING NAME : Fax007 [Jun 15 16:45:21] VERBOSE[673] chan_iax2.c: [Jun 15 16:45:21] [Jun 15 16:45:21] VERBOSE[683] chan_iax2.c: [Jun 15 16:45:21] Rx-Frame Retry[ No] -- OSeqno: 002 ISeqno: 002 Type: IAX Subclass: ACK [Jun 15 16:45:21] VERBOSE[683] chan_iax2.c: [Jun 15 16:45:21] Timestamp: 00023ms SCall: 06657 DCall: 03190 [127.0.0.1:4577] [Jun 15 16:45:21] DEBUG[683] chan_iax2.c: Received packet 2, (6, 4) [Jun 15 16:45:21] DEBUG[683] chan_iax2.c: Cancelling transmission of packet 1 [Jun 15 16:45:21] DEBUG[683] chan_iax2.c: Really destroying 3190, having been acked on final message [Jun 15 16:45:21] DEBUG[683] chan_iax2.c: schedule decrement of callno used for 127.0.0.1 in 60 seconds [Jun 15 16:45:23] DEBUG[674] chan_iax2.c: ip callno count decremented to 14 for 127.0.0.1 [Jun 15 16:45:24] DEBUG[674] chan_iax2.c: ip callno count decremented to 13 for 127.0.0.1 [Jun 15 16:45:25] DEBUG[674] chan_iax2.c: ip callno count decremented to 12 for 127.0.0.1 [Jun 15 16:45:26] DEBUG[674] chan_iax2.c: ip callno count decremented to 11 for 127.0.0.1 [Jun 15 16:45:26] DEBUG[674] chan_iax2.c: ip callno count decremented to 10 for 127.0.0.1 [Jun 15 16:45:27] VERBOSE[686] chan_sip.c: [Jun 15 16:45:27] <--- SIP read from UDP:x.x.x.5:55010 ---> OPTIONS sip:x.x.x.6 SIP/2.0 Via: SIP/2.0/UDP x.x.x.5:55028;branch=z9hG4bK-f3fcff3f From: "test1" ;tag=85813c2523621f1fo0 To: Call-ID: d7a897ad-11933937@x.x.x.5 CSeq: 169 OPTIONS Max-Forwards: 70 Contact: "test1" Event: keep-alive User-Agent: Cisco/SPA525G2-7.4.9c Content-Length: 0 <-------------> [Jun 15 16:45:27] DEBUG[686] chan_sip.c: Header 0 [ 32]: OPTIONS sip:x.x.x.6 SIP/2.0 [Jun 15 16:45:27] DEBUG[686] chan_sip.c: Header 1 [ 60]: Via: SIP/2.0/UDP x.x.x.5:55028;branch=z9hG4bK-f3fcff3f [Jun 15 16:45:27] DEBUG[686] chan_sip.c: Header 2 [ 57]: From: "test1" ;tag=85813c2523621f1fo0 [Jun 15 16:45:27] DEBUG[686] chan_sip.c: Header 3 [ 22]: To: [Jun 15 16:45:27] DEBUG[686] chan_sip.c: Header 4 [ 40]: Call-ID: d7a897ad-11933937@x.x.x.5 [Jun 15 16:45:27] DEBUG[686] chan_sip.c: Header 5 [ 17]: CSeq: 169 OPTIONS [Jun 15 16:45:27] DEBUG[686] chan_sip.c: Header 6 [ 16]: Max-Forwards: 70 [Jun 15 16:45:27] DEBUG[686] chan_sip.c: Header 7 [ 44]: Contact: "test1" [Jun 15 16:45:27] DEBUG[686] chan_sip.c: Header 8 [ 17]: Event: keep-alive [Jun 15 16:45:27] DEBUG[686] chan_sip.c: Header 9 [ 33]: User-Agent: Cisco/SPA525G2-7.4.9c [Jun 15 16:45:27] DEBUG[686] chan_sip.c: Header 10 [ 17]: Content-Length: 0 [Jun 15 16:45:27] VERBOSE[686] chan_sip.c: [Jun 15 16:45:27] --- (11 headers 0 lines) --- [Jun 15 16:45:27] DEBUG[686] chan_sip.c: = Looking for Call ID: d7a897ad-11933937@x.x.x.5 (Checking From) --From tag 85813c2523621f1fo0 --To-tag [Jun 15 16:45:27] DEBUG[686] chan_sip.c: **** Received OPTIONS (3) - Command in SIP OPTIONS [Jun 15 16:45:27] DEBUG[686] netsock2.c: Splitting 'x.x.x.6' into... [Jun 15 16:45:27] DEBUG[686] netsock2.c: ...host 'x.x.x.6' and port ''. [Jun 15 16:45:27] DEBUG[686] netsock2.c: Splitting 'x.x.x.6' into... [Jun 15 16:45:27] DEBUG[686] netsock2.c: ...host 'x.x.x.6' and port ''. [Jun 15 16:45:27] VERBOSE[686] chan_sip.c: [Jun 15 16:45:27] Looking for s in unauthorized (domain x.x.x.6) [Jun 15 16:45:27] VERBOSE[686] chan_sip.c: [Jun 15 16:45:27] <--- Transmitting (NAT) to x.x.x.5:55010 ---> SIP/2.0 404 Not Found Via: SIP/2.0/UDP x.x.x.5:55028;branch=z9hG4bK-f3fcff3f;received=x.x.x.5;rport=55010 From: "test1" ;tag=85813c2523621f1fo0 To: ;tag=as3df6dbad Call-ID: d7a897ad-11933937@x.x.x.5 CSeq: 169 OPTIONS Server: Asterisk PBX 1.8.14.0-rc1 Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO, PUBLISH Supported: replaces, timer Accept: application/sdp Content-Length: 0 <------------> [Jun 15 16:45:27] DEBUG[686] chan_sip.c: Trying to put 'SIP/2.0 404' onto UDP socket destined for x.x.x.5:55010 [Jun 15 16:45:27] VERBOSE[686] chan_sip.c: [Jun 15 16:45:27] Scheduling destruction of SIP dialog 'd7a897ad-11933937@x.x.x.5' in 32000 ms (Method: OPTIONS) [Jun 15 16:45:28] VERBOSE[686] chan_sip.c: [Jun 15 16:45:28] <--- SIP read from UDP:x.x.x.138:5060 ---> BYE sip:+15555550002@x.x.x.6:5060 SIP/2.0 Record-Route: Via: SIP/2.0/UDP x.x.x.138;branch=z9hG4bK1e32.aa4f1241.0 Via: SIP/2.0/UDP x.x.x.134:5060;branch=z9hG4bK127475cf;rport=5060 Max-Forwards: 69 From: "user1" ;tag=as465405d3 To: ;tag=as05e16768 Call-ID: 7b8cc12540233d03459e98a54f7dd5ac@x.x.x.134:5060 CSeq: 103 BYE User-Agent: Asterisk PBX 1.8.14.0-rc1 X-Asterisk-HangupCause: Normal Clearing X-Asterisk-HangupCauseCode: 16 Content-Length: 0 <-------------> [Jun 15 16:45:28] DEBUG[686] chan_sip.c: Header 0 [ 46]: BYE sip:+15555550002@x.x.x.6:5060 SIP/2.0 [Jun 15 16:45:28] DEBUG[686] chan_sip.c: Header 1 [ 40]: Record-Route: [Jun 15 16:45:28] DEBUG[686] chan_sip.c: Header 2 [ 61]: Via: SIP/2.0/UDP x.x.x.138;branch=z9hG4bK1e32.aa4f1241.0 [Jun 15 16:45:28] DEBUG[686] chan_sip.c: Header 3 [ 70]: Via: SIP/2.0/UDP x.x.x.134:5060;branch=z9hG4bK127475cf;rport=5060 [Jun 15 16:45:28] DEBUG[686] chan_sip.c: Header 4 [ 16]: Max-Forwards: 69 [Jun 15 16:45:28] DEBUG[686] chan_sip.c: Header 5 [ 72]: From: "user1" ;tag=as465405d3 [Jun 15 16:45:28] DEBUG[686] chan_sip.c: Header 6 [ 52]: To: ;tag=as05e16768 [Jun 15 16:45:28] DEBUG[686] chan_sip.c: Header 7 [ 61]: Call-ID: 7b8cc12540233d03459e98a54f7dd5ac@x.x.x.134:5060 [Jun 15 16:45:28] DEBUG[686] chan_sip.c: Header 8 [ 13]: CSeq: 103 BYE [Jun 15 16:45:28] DEBUG[686] chan_sip.c: Header 9 [ 37]: User-Agent: Asterisk PBX 1.8.14.0-rc1 [Jun 15 16:45:28] DEBUG[686] chan_sip.c: Header 10 [ 39]: X-Asterisk-HangupCause: Normal Clearing [Jun 15 16:45:28] DEBUG[686] chan_sip.c: Header 11 [ 30]: X-Asterisk-HangupCauseCode: 16 [Jun 15 16:45:28] DEBUG[686] chan_sip.c: Header 12 [ 17]: Content-Length: 0 [Jun 15 16:45:28] VERBOSE[686] chan_sip.c: [Jun 15 16:45:28] --- (13 headers 0 lines) --- [Jun 15 16:45:28] DEBUG[686] chan_sip.c: = Looking for Call ID: 7b8cc12540233d03459e98a54f7dd5ac@x.x.x.134:5060 (Checking From) --From tag as465405d3 --To-tag as05e16768 [Jun 15 16:45:28] DEBUG[686] chan_sip.c: **** Received BYE (8) - Command in SIP BYE [Jun 15 16:45:28] DEBUG[686] chan_sip.c: Initializing initreq for method BYE - callid 7b8cc12540233d03459e98a54f7dd5ac@x.x.x.134:5060 [Jun 15 16:45:28] DEBUG[686] netsock2.c: Splitting 'x.x.x.138' into... [Jun 15 16:45:28] DEBUG[686] netsock2.c: ...host 'x.x.x.138' and port ''. [Jun 15 16:45:28] VERBOSE[686] chan_sip.c: [Jun 15 16:45:28] Sending to x.x.x.138:5060 (NAT) [Jun 15 16:45:28] DEBUG[686] chan_sip.c: Setting SIP_ALREADYGONE on dialog 7b8cc12540233d03459e98a54f7dd5ac@x.x.x.134:5060 [Jun 15 16:45:28] DEBUG[686] res_rtp_asterisk.c: Setting RTCP address on RTP instance '0x9f517f8' [Jun 15 16:45:28] VERBOSE[686] chan_sip.c: [Jun 15 16:45:28] Scheduling destruction of SIP dialog '7b8cc12540233d03459e98a54f7dd5ac@x.x.x.134:5060' in 6400 ms (Method: BYE) [Jun 15 16:45:28] DEBUG[686] chan_sip.c: Received bye, issuing owner hangup [Jun 15 16:45:28] VERBOSE[686] chan_sip.c: [Jun 15 16:45:28] <--- Transmitting (NAT) to x.x.x.138:5060 ---> SIP/2.0 200 OK Via: SIP/2.0/UDP x.x.x.138;branch=z9hG4bK1e32.aa4f1241.0;received=x.x.x.138;rport=5060 Via: SIP/2.0/UDP x.x.x.134:5060;branch=z9hG4bK127475cf;rport=5060 Record-Route: From: "user1" ;tag=as465405d3 To: ;tag=as05e16768 Call-ID: 7b8cc12540233d03459e98a54f7dd5ac@x.x.x.134:5060 CSeq: 103 BYE Server: Asterisk PBX 1.8.14.0-rc1 Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO, PUBLISH Supported: replaces, timer Content-Length: 0 <------------> [Jun 15 16:45:28] DEBUG[686] chan_sip.c: Trying to put 'SIP/2.0 200' onto UDP socket destined for x.x.x.138:5060 [Jun 15 16:45:34] WARNING[686] chan_sip.c: Autodestruct on dialog '7b8cc12540233d03459e98a54f7dd5ac@x.x.x.134:5060' with owner in place (Method: BYE). Rescheduling destruction for 10000 ms [Jun 15 16:45:36] VERBOSE[686] chan_sip.c: [Jun 15 16:45:36] <--- SIP read from UDP:x.x.x.134:42225 ---> OPTIONS <-------------> [Jun 15 16:45:36] DEBUG[686] chan_sip.c: Header 0 [ 7]: OPTIONS [Jun 15 16:45:41] WARNING[686] chan_sip.c: Autodestruct on dialog '7b8cc12540233d03459e98a54f7dd5ac@x.x.x.134:5060' with owner in place (Method: BYE). Rescheduling destruction for 10000 ms [Jun 15 16:45:42] VERBOSE[686] chan_sip.c: [Jun 15 16:45:42] <--- SIP read from UDP:x.x.x.5:55010 ---> OPTIONS sip:x.x.x.6 SIP/2.0 Via: SIP/2.0/UDP x.x.x.5:55028;branch=z9hG4bK-a3529d2d From: "test1" ;tag=85813c2523621f1fo0 To: Call-ID: d7a897ad-11933937@x.x.x.5 CSeq: 170 OPTIONS Max-Forwards: 70 Contact: "test1" Event: keep-alive User-Agent: Cisco/SPA525G2-7.4.9c Content-Length: 0 <-------------> [Jun 15 16:45:42] DEBUG[686] chan_sip.c: Header 0 [ 32]: OPTIONS sip:x.x.x.6 SIP/2.0 [Jun 15 16:45:42] DEBUG[686] chan_sip.c: Header 1 [ 60]: Via: SIP/2.0/UDP x.x.x.5:55028;branch=z9hG4bK-a3529d2d [Jun 15 16:45:42] DEBUG[686] chan_sip.c: Header 2 [ 57]: From: "test1" ;tag=85813c2523621f1fo0 [Jun 15 16:45:42] DEBUG[686] chan_sip.c: Header 3 [ 22]: To: [Jun 15 16:45:42] DEBUG[686] chan_sip.c: Header 4 [ 40]: Call-ID: d7a897ad-11933937@x.x.x.5 [Jun 15 16:45:42] DEBUG[686] chan_sip.c: Header 5 [ 17]: CSeq: 170 OPTIONS [Jun 15 16:45:42] DEBUG[686] chan_sip.c: Header 6 [ 16]: Max-Forwards: 70 [Jun 15 16:45:42] DEBUG[686] chan_sip.c: Header 7 [ 44]: Contact: "test1" [Jun 15 16:45:42] DEBUG[686] chan_sip.c: Header 8 [ 17]: Event: keep-alive [Jun 15 16:45:42] DEBUG[686] chan_sip.c: Header 9 [ 33]: User-Agent: Cisco/SPA525G2-7.4.9c [Jun 15 16:45:42] DEBUG[686] chan_sip.c: Header 10 [ 17]: Content-Length: 0 [Jun 15 16:45:42] VERBOSE[686] chan_sip.c: [Jun 15 16:45:42] --- (11 headers 0 lines) --- [Jun 15 16:45:42] DEBUG[686] chan_sip.c: = Looking for Call ID: d7a897ad-11933937@x.x.x.5 (Checking From) --From tag 85813c2523621f1fo0 --To-tag [Jun 15 16:45:42] DEBUG[686] chan_sip.c: **** Received OPTIONS (3) - Command in SIP OPTIONS [Jun 15 16:45:42] DEBUG[686] netsock2.c: Splitting 'x.x.x.6' into... [Jun 15 16:45:42] DEBUG[686] netsock2.c: ...host 'x.x.x.6' and port ''. [Jun 15 16:45:42] DEBUG[686] netsock2.c: Splitting 'x.x.x.6' into... [Jun 15 16:45:42] DEBUG[686] netsock2.c: ...host 'x.x.x.6' and port ''. [Jun 15 16:45:42] VERBOSE[686] chan_sip.c: [Jun 15 16:45:42] Looking for s in unauthorized (domain x.x.x.6) [Jun 15 16:45:42] VERBOSE[686] chan_sip.c: [Jun 15 16:45:42] <--- Transmitting (NAT) to x.x.x.5:55010 ---> SIP/2.0 404 Not Found Via: SIP/2.0/UDP x.x.x.5:55028;branch=z9hG4bK-a3529d2d;received=x.x.x.5;rport=55010 From: "test1" ;tag=85813c2523621f1fo0 To: ;tag=as3df6dbad Call-ID: d7a897ad-11933937@x.x.x.5 CSeq: 170 OPTIONS Server: Asterisk PBX 1.8.14.0-rc1 Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO, PUBLISH Supported: replaces, timer Accept: application/sdp Content-Length: 0 <------------> [Jun 15 16:45:42] DEBUG[686] chan_sip.c: Trying to put 'SIP/2.0 404' onto UDP socket destined for x.x.x.5:55010 [Jun 15 16:45:42] VERBOSE[686] chan_sip.c: [Jun 15 16:45:42] Scheduling destruction of SIP dialog 'd7a897ad-11933937@x.x.x.5' in 32000 ms (Method: OPTIONS) [Jun 15 16:45:43] VERBOSE[681] chan_iax2.c: [Jun 15 16:45:43] Rx-Frame Retry[ No] -- OSeqno: 000 ISeqno: 000 Type: IAX Subclass: REGREQ [Jun 15 16:45:43] VERBOSE[681] chan_iax2.c: [Jun 15 16:45:43] Timestamp: 00003ms SCall: 06658 DCall: 00000 [127.0.0.1:4572] [Jun 15 16:45:43] VERBOSE[681] chan_iax2.c: [Jun 15 16:45:43] USERNAME : fax002 [Jun 15 16:45:43] VERBOSE[681] chan_iax2.c: [Jun 15 16:45:43] REFRESH : 60 [Jun 15 16:45:43] VERBOSE[681] chan_iax2.c: [Jun 15 16:45:43] [Jun 15 16:45:43] DEBUG[681] chan_iax2.c: Determining if address 127.0.0.1 with username fax002 requires calltoken validation. Optional = 0 calltoken_required = 3 [Jun 15 16:45:43] DEBUG[681] chan_iax2.c: ip callno count incremented to 11 for 127.0.0.1 [Jun 15 16:45:43] DEBUG[681] chan_iax2.c: Creating new call structure 106 [Jun 15 16:45:43] DEBUG[681] chan_iax2.c: Received packet 0, (6, 13) [Jun 15 16:45:43] DEBUG[681] chan_iax2.c: IAX subclass 13 received [Jun 15 16:45:43] DEBUG[681] chan_iax2.c: For call=106, set last=3 [Jun 15 16:45:43] DEBUG[667] devicestate.c: No provider found, checking channel drivers for IAX2 - fax002 [Jun 15 16:45:43] DEBUG[667] chan_iax2.c: Checking device state for device fax002 [Jun 15 16:45:43] DEBUG[673] chan_iax2.c: Sending 14 on 106/6658 to 127.0.0.1:4572 [Jun 15 16:45:43] DEBUG[667] chan_iax2.c: iax2_devicestate: Found peer. What's device state of fax002? addr=2130706433, defaddr=0 maxms=0, lastms=0 [Jun 15 16:45:43] VERBOSE[673] chan_iax2.c: [Jun 15 16:45:43] Tx-Frame Retry[000] -- OSeqno: 000 ISeqno: 001 Type: IAX Subclass: REGAUTH [Jun 15 16:45:43] VERBOSE[673] chan_iax2.c: [Jun 15 16:45:43] Timestamp: 00014ms SCall: 00106 DCall: 06658 [127.0.0.1:4572] [Jun 15 16:45:43] DEBUG[667] devicestate.c: Changing state for IAX2/fax002 - state 0 (Unknown) [Jun 15 16:45:43] VERBOSE[673] chan_iax2.c: [Jun 15 16:45:43] AUTHMETHODS : 3 [Jun 15 16:45:43] DEBUG[667] devicestate.c: device 'IAX2/fax002' state '0' [Jun 15 16:45:43] VERBOSE[673] chan_iax2.c: [Jun 15 16:45:43] CHALLENGE : \x31\x32\x34\x32\x39\x31\x39\x32\x33 [Jun 15 16:45:43] VERBOSE[673] chan_iax2.c: [Jun 15 16:45:43] USERNAME : fax002 [Jun 15 16:45:43] VERBOSE[673] chan_iax2.c: [Jun 15 16:45:43] [Jun 15 16:45:43] VERBOSE[680] chan_iax2.c: [Jun 15 16:45:43] Rx-Frame Retry[ No] -- OSeqno: 001 ISeqno: 001 Type: IAX Subclass: REGREQ [Jun 15 16:45:43] VERBOSE[680] chan_iax2.c: [Jun 15 16:45:43] Timestamp: 00009ms SCall: 06658 DCall: 00106 [127.0.0.1:4572] [Jun 15 16:45:43] VERBOSE[680] chan_iax2.c: [Jun 15 16:45:43] USERNAME : fax002 [Jun 15 16:45:43] VERBOSE[680] chan_iax2.c: [Jun 15 16:45:43] MD5 RESULT : 3845bb5653a5aa33b7f83d2d855a93b1 [Jun 15 16:45:43] VERBOSE[680] chan_iax2.c: [Jun 15 16:45:43] REFRESH : 60 [Jun 15 16:45:43] VERBOSE[680] chan_iax2.c: [Jun 15 16:45:43] [Jun 15 16:45:43] DEBUG[680] chan_iax2.c: Received packet 1, (6, 13) [Jun 15 16:45:43] DEBUG[680] chan_iax2.c: Cancelling transmission of packet 0 [Jun 15 16:45:43] DEBUG[699] app_queue.c: Device 'IAX2/fax002' changed to state '0' (Unknown) but we don't care because they're not a member of any queue. [Jun 15 16:45:43] DEBUG[680] chan_iax2.c: IAX subclass 13 received [Jun 15 16:45:43] DEBUG[680] chan_iax2.c: For call=106, set last=9 [Jun 15 16:45:43] DEBUG[667] devicestate.c: No provider found, checking channel drivers for IAX2 - fax002 [Jun 15 16:45:43] DEBUG[667] chan_iax2.c: Checking device state for device fax002 [Jun 15 16:45:43] DEBUG[667] chan_iax2.c: iax2_devicestate: Found peer. What's device state of fax002? addr=2130706433, defaddr=0 maxms=0, lastms=0 [Jun 15 16:45:43] DEBUG[667] devicestate.c: Changing state for IAX2/fax002 - state 0 (Unknown) [Jun 15 16:45:43] DEBUG[667] devicestate.c: device 'IAX2/fax002' state '0' [Jun 15 16:45:43] DEBUG[673] chan_iax2.c: Sending 28 on 106/6658 to 127.0.0.1:4572 [Jun 15 16:45:43] VERBOSE[673] chan_iax2.c: [Jun 15 16:45:43] Tx-Frame Retry[000] -- OSeqno: 001 ISeqno: 002 Type: IAX Subclass: REGACK [Jun 15 16:45:43] VERBOSE[673] chan_iax2.c: [Jun 15 16:45:43] Timestamp: 00028ms SCall: 00106 DCall: 06658 [127.0.0.1:4572] [Jun 15 16:45:43] VERBOSE[673] chan_iax2.c: [Jun 15 16:45:43] USERNAME : fax002 [Jun 15 16:45:43] VERBOSE[673] chan_iax2.c: [Jun 15 16:45:43] DATE TIME : 2012-06-15 16:45:42 [Jun 15 16:45:43] VERBOSE[673] chan_iax2.c: [Jun 15 16:45:43] REFRESH : 60 [Jun 15 16:45:43] DEBUG[699] app_queue.c: Device 'IAX2/fax002' changed to state '0' (Unknown) but we don't care because they're not a member of any queue. [Jun 15 16:45:43] VERBOSE[673] chan_iax2.c: [Jun 15 16:45:43] APPARENT ADDRES : IPV4 127.0.0.1:4572 [Jun 15 16:45:43] VERBOSE[673] chan_iax2.c: [Jun 15 16:45:43] CALLING NUMBER : 8476039009 [Jun 15 16:45:43] VERBOSE[673] chan_iax2.c: [Jun 15 16:45:43] CALLING NAME : Fax002 [Jun 15 16:45:43] VERBOSE[673] chan_iax2.c: [Jun 15 16:45:43] [Jun 15 16:45:43] VERBOSE[682] chan_iax2.c: [Jun 15 16:45:43] Rx-Frame Retry[ No] -- OSeqno: 002 ISeqno: 002 Type: IAX Subclass: ACK [Jun 15 16:45:43] VERBOSE[682] chan_iax2.c: [Jun 15 16:45:43] Timestamp: 00028ms SCall: 06658 DCall: 00106 [127.0.0.1:4572] [Jun 15 16:45:43] DEBUG[682] chan_iax2.c: Received packet 2, (6, 4) [Jun 15 16:45:43] DEBUG[682] chan_iax2.c: Cancelling transmission of packet 1 [Jun 15 16:45:43] DEBUG[682] chan_iax2.c: Really destroying 106, having been acked on final message [Jun 15 16:45:43] DEBUG[682] chan_iax2.c: schedule decrement of callno used for 127.0.0.1 in 60 seconds [Jun 15 16:45:45] VERBOSE[675] chan_iax2.c: [Jun 15 16:45:45] Rx-Frame Retry[ No] -- OSeqno: 000 ISeqno: 000 Type: IAX Subclass: REGREQ [Jun 15 16:45:45] VERBOSE[675] chan_iax2.c: [Jun 15 16:45:45] Timestamp: 00003ms SCall: 06658 DCall: 00000 [127.0.0.1:4575] [Jun 15 16:45:45] VERBOSE[675] chan_iax2.c: [Jun 15 16:45:45] USERNAME : fax005 [Jun 15 16:45:45] VERBOSE[675] chan_iax2.c: [Jun 15 16:45:45] REFRESH : 60 [Jun 15 16:45:45] VERBOSE[675] chan_iax2.c: [Jun 15 16:45:45] [Jun 15 16:45:45] DEBUG[675] chan_iax2.c: Determining if address 127.0.0.1 with username fax005 requires calltoken validation. Optional = 0 calltoken_required = 3 [Jun 15 16:45:45] DEBUG[675] chan_iax2.c: ip callno count incremented to 12 for 127.0.0.1 [Jun 15 16:45:45] DEBUG[675] chan_iax2.c: Creating new call structure 2489 [Jun 15 16:45:45] DEBUG[675] chan_iax2.c: Received packet 0, (6, 13) [Jun 15 16:45:45] DEBUG[675] chan_iax2.c: IAX subclass 13 received [Jun 15 16:45:45] DEBUG[675] chan_iax2.c: For call=2489, set last=3 [Jun 15 16:45:45] DEBUG[667] devicestate.c: No provider found, checking channel drivers for IAX2 - fax005 [Jun 15 16:45:45] DEBUG[667] chan_iax2.c: Checking device state for device fax005 [Jun 15 16:45:45] DEBUG[667] chan_iax2.c: iax2_devicestate: Found peer. What's device state of fax005? addr=2130706433, defaddr=0 maxms=0, lastms=0 [Jun 15 16:45:45] DEBUG[673] chan_iax2.c: Sending 10 on 2489/6658 to 127.0.0.1:4575 [Jun 15 16:45:45] DEBUG[667] devicestate.c: Changing state for IAX2/fax005 - state 0 (Unknown) [Jun 15 16:45:45] VERBOSE[673] chan_iax2.c: [Jun 15 16:45:45] Tx-Frame Retry[000] -- OSeqno: 000 ISeqno: 001 Type: IAX Subclass: REGAUTH [Jun 15 16:45:45] DEBUG[667] devicestate.c: device 'IAX2/fax005' state '0' [Jun 15 16:45:45] VERBOSE[673] chan_iax2.c: [Jun 15 16:45:45] Timestamp: 00010ms SCall: 02489 DCall: 06658 [127.0.0.1:4575] [Jun 15 16:45:45] VERBOSE[673] chan_iax2.c: [Jun 15 16:45:45] AUTHMETHODS : 3 [Jun 15 16:45:45] DEBUG[699] app_queue.c: Device 'IAX2/fax005' changed to state '0' (Unknown) but we don't care because they're not a member of any queue. [Jun 15 16:45:45] VERBOSE[673] chan_iax2.c: [Jun 15 16:45:45] CHALLENGE : \x32\x30\x34\x37\x38\x34\x37\x37\x31 [Jun 15 16:45:45] VERBOSE[673] chan_iax2.c: [Jun 15 16:45:45] USERNAME : fax005 [Jun 15 16:45:45] VERBOSE[673] chan_iax2.c: [Jun 15 16:45:45] [Jun 15 16:45:45] VERBOSE[676] chan_iax2.c: [Jun 15 16:45:45] Rx-Frame Retry[ No] -- OSeqno: 001 ISeqno: 001 Type: IAX Subclass: REGREQ [Jun 15 16:45:45] VERBOSE[676] chan_iax2.c: [Jun 15 16:45:45] Timestamp: 00010ms SCall: 06658 DCall: 02489 [127.0.0.1:4575] [Jun 15 16:45:45] VERBOSE[676] chan_iax2.c: [Jun 15 16:45:45] USERNAME : fax005 [Jun 15 16:45:45] VERBOSE[676] chan_iax2.c: [Jun 15 16:45:45] MD5 RESULT : d07aa33240a84fd4b8b42dfb47db1541 [Jun 15 16:45:45] VERBOSE[676] chan_iax2.c: [Jun 15 16:45:45] REFRESH : 60 [Jun 15 16:45:45] VERBOSE[676] chan_iax2.c: [Jun 15 16:45:45] [Jun 15 16:45:45] DEBUG[676] chan_iax2.c: Received packet 1, (6, 13) [Jun 15 16:45:45] DEBUG[676] chan_iax2.c: Cancelling transmission of packet 0 [Jun 15 16:45:45] DEBUG[676] chan_iax2.c: IAX subclass 13 received [Jun 15 16:45:45] DEBUG[676] chan_iax2.c: For call=2489, set last=10 [Jun 15 16:45:45] DEBUG[667] devicestate.c: No provider found, checking channel drivers for IAX2 - fax005 [Jun 15 16:45:45] DEBUG[667] chan_iax2.c: Checking device state for device fax005 [Jun 15 16:45:45] DEBUG[667] chan_iax2.c: iax2_devicestate: Found peer. What's device state of fax005? addr=2130706433, defaddr=0 maxms=0, lastms=0 [Jun 15 16:45:45] DEBUG[667] devicestate.c: Changing state for IAX2/fax005 - state 0 (Unknown) [Jun 15 16:45:45] DEBUG[667] devicestate.c: device 'IAX2/fax005' state '0' [Jun 15 16:45:45] DEBUG[673] chan_iax2.c: Sending 22 on 2489/6658 to 127.0.0.1:4575 [Jun 15 16:45:45] VERBOSE[673] chan_iax2.c: [Jun 15 16:45:45] Tx-Frame Retry[000] -- OSeqno: 001 ISeqno: 002 Type: IAX Subclass: REGACK [Jun 15 16:45:45] VERBOSE[673] chan_iax2.c: [Jun 15 16:45:45] Timestamp: 00022ms SCall: 02489 DCall: 06658 [127.0.0.1:4575] [Jun 15 16:45:45] DEBUG[699] app_queue.c: Device 'IAX2/fax005' changed to state '0' (Unknown) but we don't care because they're not a member of any queue. [Jun 15 16:45:45] VERBOSE[673] chan_iax2.c: [Jun 15 16:45:45] USERNAME : fax005 [Jun 15 16:45:45] VERBOSE[673] chan_iax2.c: [Jun 15 16:45:45] DATE TIME : 2012-06-15 16:45:44 [Jun 15 16:45:45] VERBOSE[673] chan_iax2.c: [Jun 15 16:45:45] REFRESH : 60 [Jun 15 16:45:45] VERBOSE[673] chan_iax2.c: [Jun 15 16:45:45] APPARENT ADDRES : IPV4 127.0.0.1:4575 [Jun 15 16:45:45] VERBOSE[673] chan_iax2.c: [Jun 15 16:45:45] CALLING NUMBER : 8476039009 [Jun 15 16:45:45] VERBOSE[673] chan_iax2.c: [Jun 15 16:45:45] CALLING NAME : Fax005 [Jun 15 16:45:45] VERBOSE[673] chan_iax2.c: [Jun 15 16:45:45] [Jun 15 16:45:45] VERBOSE[677] chan_iax2.c: [Jun 15 16:45:45] Rx-Frame Retry[ No] -- OSeqno: 002 ISeqno: 002 Type: IAX Subclass: ACK [Jun 15 16:45:45] VERBOSE[677] chan_iax2.c: [Jun 15 16:45:45] Timestamp: 00022ms SCall: 06658 DCall: 02489 [127.0.0.1:4575] [Jun 15 16:45:45] DEBUG[677] chan_iax2.c: Received packet 2, (6, 4) [Jun 15 16:45:45] DEBUG[677] chan_iax2.c: Cancelling transmission of packet 1 [Jun 15 16:45:45] DEBUG[677] chan_iax2.c: Really destroying 2489, having been acked on final message [Jun 15 16:45:45] DEBUG[677] chan_iax2.c: schedule decrement of callno used for 127.0.0.1 in 60 seconds [Jun 15 16:45:46] VERBOSE[678] chan_iax2.c: [Jun 15 16:45:46] Rx-Frame Retry[ No] -- OSeqno: 000 ISeqno: 000 Type: IAX Subclass: REGREQ [Jun 15 16:45:46] VERBOSE[678] chan_iax2.c: [Jun 15 16:45:46] Timestamp: 00003ms SCall: 06658 DCall: 00000 [127.0.0.1:4576] [Jun 15 16:45:46] VERBOSE[678] chan_iax2.c: [Jun 15 16:45:46] USERNAME : fax006 [Jun 15 16:45:46] VERBOSE[678] chan_iax2.c: [Jun 15 16:45:46] REFRESH : 60 [Jun 15 16:45:46] VERBOSE[678] chan_iax2.c: [Jun 15 16:45:46] [Jun 15 16:45:46] DEBUG[678] chan_iax2.c: Determining if address 127.0.0.1 with username fax006 requires calltoken validation. Optional = 0 calltoken_required = 3 [Jun 15 16:45:46] DEBUG[678] chan_iax2.c: ip callno count incremented to 13 for 127.0.0.1 [Jun 15 16:45:46] DEBUG[678] chan_iax2.c: Creating new call structure 1841 [Jun 15 16:45:46] DEBUG[678] chan_iax2.c: Received packet 0, (6, 13) [Jun 15 16:45:46] DEBUG[678] chan_iax2.c: IAX subclass 13 received [Jun 15 16:45:46] DEBUG[678] chan_iax2.c: For call=1841, set last=3 [Jun 15 16:45:46] DEBUG[667] devicestate.c: No provider found, checking channel drivers for IAX2 - fax006 [Jun 15 16:45:46] DEBUG[673] chan_iax2.c: Sending 19 on 1841/6658 to 127.0.0.1:4576 [Jun 15 16:45:46] VERBOSE[673] chan_iax2.c: [Jun 15 16:45:46] Tx-Frame Retry[000] -- OSeqno: 000 ISeqno: 001 Type: IAX Subclass: REGAUTH [Jun 15 16:45:46] VERBOSE[673] chan_iax2.c: [Jun 15 16:45:46] Timestamp: 00019ms SCall: 01841 DCall: 06658 [127.0.0.1:4576] [Jun 15 16:45:46] VERBOSE[673] chan_iax2.c: [Jun 15 16:45:46] AUTHMETHODS : 3 [Jun 15 16:45:46] VERBOSE[673] chan_iax2.c: [Jun 15 16:45:46] CHALLENGE : \x34\x33\x34\x34\x31\x30\x39\x34\x39 [Jun 15 16:45:46] VERBOSE[673] chan_iax2.c: [Jun 15 16:45:46] USERNAME : fax006 [Jun 15 16:45:46] VERBOSE[673] chan_iax2.c: [Jun 15 16:45:46] [Jun 15 16:45:46] DEBUG[667] chan_iax2.c: Checking device state for device fax006 [Jun 15 16:45:46] VERBOSE[679] chan_iax2.c: [Jun 15 16:45:46] Rx-Frame Retry[ No] -- OSeqno: 001 ISeqno: 001 Type: IAX Subclass: REGREQ [Jun 15 16:45:46] DEBUG[667] chan_iax2.c: iax2_devicestate: Found peer. What's device state of fax006? addr=2130706433, defaddr=0 maxms=0, lastms=0 [Jun 15 16:45:46] VERBOSE[679] chan_iax2.c: [Jun 15 16:45:46] Timestamp: 00006ms SCall: 06658 DCall: 01841 [127.0.0.1:4576] [Jun 15 16:45:46] VERBOSE[679] chan_iax2.c: [Jun 15 16:45:46] USERNAME : fax006 [Jun 15 16:45:46] DEBUG[667] devicestate.c: Changing state for IAX2/fax006 - state 0 (Unknown) [Jun 15 16:45:46] VERBOSE[679] chan_iax2.c: [Jun 15 16:45:46] MD5 RESULT : a438080e1fa4983213bad10960ea6455 [Jun 15 16:45:46] DEBUG[667] devicestate.c: device 'IAX2/fax006' state '0' [Jun 15 16:45:46] VERBOSE[679] chan_iax2.c: [Jun 15 16:45:46] REFRESH : 60 [Jun 15 16:45:46] VERBOSE[679] chan_iax2.c: [Jun 15 16:45:46] [Jun 15 16:45:46] DEBUG[679] chan_iax2.c: Received packet 1, (6, 13) [Jun 15 16:45:46] DEBUG[679] chan_iax2.c: Cancelling transmission of packet 0 [Jun 15 16:45:46] DEBUG[679] chan_iax2.c: IAX subclass 13 received [Jun 15 16:45:46] DEBUG[679] chan_iax2.c: For call=1841, set last=6 [Jun 15 16:45:46] DEBUG[667] devicestate.c: No provider found, checking channel drivers for IAX2 - fax006 [Jun 15 16:45:46] DEBUG[667] chan_iax2.c: Checking device state for device fax006 [Jun 15 16:45:46] DEBUG[667] chan_iax2.c: iax2_devicestate: Found peer. What's device state of fax006? addr=2130706433, defaddr=0 maxms=0, lastms=0 [Jun 15 16:45:46] DEBUG[667] devicestate.c: Changing state for IAX2/fax006 - state 0 (Unknown) [Jun 15 16:45:46] DEBUG[667] devicestate.c: device 'IAX2/fax006' state '0' [Jun 15 16:45:46] DEBUG[673] chan_iax2.c: Sending 28 on 1841/6658 to 127.0.0.1:4576 [Jun 15 16:45:46] VERBOSE[673] chan_iax2.c: [Jun 15 16:45:46] Tx-Frame Retry[000] -- OSeqno: 001 ISeqno: 002 Type: IAX Subclass: REGACK [Jun 15 16:45:46] VERBOSE[673] chan_iax2.c: [Jun 15 16:45:46] Timestamp: 00028ms SCall: 01841 DCall: 06658 [127.0.0.1:4576] [Jun 15 16:45:46] VERBOSE[673] chan_iax2.c: [Jun 15 16:45:46] USERNAME : fax006 [Jun 15 16:45:46] VERBOSE[673] chan_iax2.c: [Jun 15 16:45:46] DATE TIME : 2012-06-15 16:45:46 [Jun 15 16:45:46] VERBOSE[673] chan_iax2.c: [Jun 15 16:45:46] REFRESH : 60 [Jun 15 16:45:46] VERBOSE[673] chan_iax2.c: [Jun 15 16:45:46] APPARENT ADDRES : IPV4 127.0.0.1:4576 [Jun 15 16:45:46] VERBOSE[673] chan_iax2.c: [Jun 15 16:45:46] CALLING NUMBER : 8476039009 [Jun 15 16:45:46] VERBOSE[673] chan_iax2.c: [Jun 15 16:45:46] CALLING NAME : Fax006 [Jun 15 16:45:46] DEBUG[699] app_queue.c: Device 'IAX2/fax006' changed to state '0' (Unknown) but we don't care because they're not a member of any queue. [Jun 15 16:45:46] VERBOSE[673] chan_iax2.c: [Jun 15 16:45:46] [Jun 15 16:45:46] VERBOSE[681] chan_iax2.c: [Jun 15 16:45:46] Rx-Frame Retry[ No] -- OSeqno: 002 ISeqno: 002 Type: IAX Subclass: ACK [Jun 15 16:45:46] VERBOSE[681] chan_iax2.c: [Jun 15 16:45:46] Timestamp: 00028ms SCall: 06658 DCall: 01841 [127.0.0.1:4576] [Jun 15 16:45:46] DEBUG[699] app_queue.c: Device 'IAX2/fax006' changed to state '0' (Unknown) but we don't care because they're not a member of any queue. [Jun 15 16:45:46] DEBUG[681] chan_iax2.c: Received packet 2, (6, 4) [Jun 15 16:45:46] DEBUG[681] chan_iax2.c: Cancelling transmission of packet 1 [Jun 15 16:45:46] DEBUG[681] chan_iax2.c: Really destroying 1841, having been acked on final message [Jun 15 16:45:46] DEBUG[681] chan_iax2.c: schedule decrement of callno used for 127.0.0.1 in 60 seconds [Jun 15 16:45:47] WARNING[686] chan_sip.c: Autodestruct on dialog '7b8cc12540233d03459e98a54f7dd5ac@x.x.x.134:5060' with owner in place (Method: BYE). Rescheduling destruction for 10000 ms [Jun 15 16:45:48] DEBUG[674] chan_iax2.c: ip callno count decremented to 12 for 127.0.0.1