[Jan 21 15:48:35] DEBUG[28940] netsock2.c: Splitting '192.168.1.20:5060' into... [Jan 21 15:48:35] DEBUG[28940] netsock2.c: ...host '192.168.1.20' and port '5060'. [Jan 21 15:48:35] DEBUG[28940] chan_sip.c: build_route: Retaining previous route: [Jan 21 15:48:35] DEBUG[28940] netsock2.c: Splitting '192.168.1.200' into... [Jan 21 15:48:35] DEBUG[28940] netsock2.c: ...host '192.168.1.200' and port ''. [Jan 21 15:48:35] DEBUG[28940] chan_sip.c: Trying to put 'SIP/2.0 404' onto UDP socket destined for 192.168.1.20:5060 [Jan 21 15:48:35] NOTICE[28940] chan_sip.c: Received SIP subscribe for peer without mailbox: 1005 [Jan 21 15:48:35] DEBUG[28940] chan_sip.c: Destroying SIP dialog 8d203a8d9d6b78d6@192.168.1.20 [Jan 21 15:48:39] DEBUG[28940] chan_sip.c: Auto destroying SIP dialog 'C065150487CA405F830EB3F44796F6CA0xc0a80114' [Jan 21 15:48:39] DEBUG[28940] chan_sip.c: Destroying SIP dialog C065150487CA405F830EB3F44796F6CA0xc0a80114 [Jan 21 15:48:45] DEBUG[28974] manager.c: Running action 'QueueStatus' [Jan 21 15:48:45] DEBUG[28940] chan_sip.c: = Looking for Call ID: 8d203a8dfd50c7ca@192.168.1.20 (Checking From) --From tag 8d203a8dfd50c7c9 --To-tag [Jan 21 15:48:45] DEBUG[28940] acl.c: For destination '192.168.1.20', our source address is '192.168.1.200'. [Jan 21 15:48:45] DEBUG[28940] chan_sip.c: Setting AST_TRANSPORT_UDP with address 192.168.1.200:5060 [Jan 21 15:48:45] DEBUG[28940] netsock2.c: Splitting '192.168.1.20:5060' into... [Jan 21 15:48:45] DEBUG[28940] netsock2.c: ...host '192.168.1.20' and port '5060'. [Jan 21 15:48:45] DEBUG[28940] chan_sip.c: Allocating new SIP dialog for 8d203a8dfd50c7ca@192.168.1.20 - OPTIONS (No RTP) [Jan 21 15:48:45] DEBUG[28940] chan_sip.c: **** Received OPTIONS (3) - Command in SIP OPTIONS [Jan 21 15:48:45] DEBUG[28940] netsock2.c: Splitting '192.168.1.200' into... [Jan 21 15:48:45] DEBUG[28940] netsock2.c: ...host '192.168.1.200' and port ''. [Jan 21 15:48:45] DEBUG[28940] netsock2.c: Splitting '192.168.1.200' into... [Jan 21 15:48:45] DEBUG[28940] netsock2.c: ...host '192.168.1.200' and port ''. [Jan 21 15:48:45] DEBUG[28940] chan_sip.c: Trying to put 'SIP/2.0 404' onto UDP socket destined for 192.168.1.20:5060 [Jan 21 15:48:47] DEBUG[28940] chan_sip.c: = Looking for Call ID: ZjM1ZTJhOWVkMDc2YzhiYjEwNDA3NjYzM2VkOWI5YTc (Checking From) --From tag 20972818 --To-tag [Jan 21 15:48:47] DEBUG[28940] acl.c: For destination '192.168.1.20', our source address is '192.168.1.200'. [Jan 21 15:48:47] DEBUG[28940] chan_sip.c: Setting AST_TRANSPORT_UDP with address 192.168.1.200:5060 [Jan 21 15:48:47] DEBUG[28940] netsock2.c: Splitting '192.168.1.20:43604' into... [Jan 21 15:48:47] DEBUG[28940] netsock2.c: ...host '192.168.1.20' and port '43604'. [Jan 21 15:48:47] DEBUG[28940] chan_sip.c: Allocating new SIP dialog for ZjM1ZTJhOWVkMDc2YzhiYjEwNDA3NjYzM2VkOWI5YTc - INVITE (No RTP) [Jan 21 15:48:47] DEBUG[28940][C-00000001] chan_sip.c: **** Received INVITE (5) - Command in SIP INVITE [Jan 21 15:48:47] DEBUG[28940][C-00000001] sip/reqresp_parser.c: Begin: parsing SIP "Supported: replaces" [Jan 21 15:48:47] DEBUG[28940][C-00000001] sip/reqresp_parser.c: Found SIP option: -replaces- [Jan 21 15:48:47] DEBUG[28940][C-00000001] sip/reqresp_parser.c: Matched SIP option: replaces [Jan 21 15:48:47] DEBUG[28940][C-00000001] netsock2.c: Splitting '192.168.1.20:43604' into... [Jan 21 15:48:47] DEBUG[28940][C-00000001] netsock2.c: ...host '192.168.1.20' and port '43604'. [Jan 21 15:48:47] DEBUG[28940][C-00000001] netsock2.c: Splitting '192.168.1.200' into... [Jan 21 15:48:47] DEBUG[28940][C-00000001] netsock2.c: ...host '192.168.1.200' and port ''. [Jan 21 15:48:47] DEBUG[28940][C-00000001] chan_sip.c: Trying to put 'SIP/2.0 401' onto UDP socket destined for 192.168.1.20:43604 [Jan 21 15:48:47] DEBUG[28940] chan_sip.c: = Looking for Call ID: ZjM1ZTJhOWVkMDc2YzhiYjEwNDA3NjYzM2VkOWI5YTc (Checking From) --From tag 20972818 --To-tag as4fbae4d0 [Jan 21 15:48:47] DEBUG[28940][C-00000001] chan_sip.c: **** Received ACK (6) - Command in SIP ACK [Jan 21 15:48:47] DEBUG[28940][C-00000001] chan_sip.c: Stopping retransmission on 'ZjM1ZTJhOWVkMDc2YzhiYjEwNDA3NjYzM2VkOWI5YTc' of Response 1: Match Found [Jan 21 15:48:47] DEBUG[28940] chan_sip.c: = Looking for Call ID: ZjM1ZTJhOWVkMDc2YzhiYjEwNDA3NjYzM2VkOWI5YTc (Checking From) --From tag 20972818 --To-tag [Jan 21 15:48:47] DEBUG[28940] netsock2.c: Splitting '192.168.1.200' into... [Jan 21 15:48:47] DEBUG[28940] netsock2.c: ...host '192.168.1.200' and port ''. [Jan 21 15:48:47] DEBUG[28940] netsock2.c: Splitting '192.168.1.200' into... [Jan 21 15:48:47] DEBUG[28940] netsock2.c: ...host '192.168.1.200' and port ''. [Jan 21 15:48:47] DEBUG[28940][C-00000001] chan_sip.c: **** Received INVITE (5) - Command in SIP INVITE [Jan 21 15:48:47] DEBUG[28940][C-00000001] netsock2.c: Splitting '192.168.1.20:43604' into... [Jan 21 15:48:47] DEBUG[28940][C-00000001] netsock2.c: ...host '192.168.1.20' and port '43604'. [Jan 21 15:48:47] DEBUG[28940][C-00000001] netsock2.c: Splitting '192.168.1.200' into... [Jan 21 15:48:47] DEBUG[28940][C-00000001] netsock2.c: ...host '192.168.1.200' and port ''. [Jan 21 15:48:47] DEBUG[28940][C-00000001] rtp_engine.c: Using engine 'asterisk' for RTP instance '0xb45ffddc' [Jan 21 15:48:47] DEBUG[28940][C-00000001] res_rtp_asterisk.c: Allocated port 13756 for RTP instance '0xb45ffddc' [Jan 21 15:48:47] DEBUG[28940][C-00000001] rtp_engine.c: RTP instance '0xb45ffddc' is setup and ready to go [Jan 21 15:48:47] DEBUG[28940][C-00000001] res_rtp_asterisk.c: Setup RTCP on RTP instance '0xb45ffddc' [Jan 21 15:48:47] VERBOSE[28940][C-00000001] netsock2.c: Using SIP RTP CoS mark 5 [Jan 21 15:48:47] DEBUG[28940][C-00000001] chan_sip.c: Setting NAT on RTP to Off [Jan 21 15:48:47] DEBUG[28940][C-00000001] chan_sip.c: Processing session-level SDP v=0... UNSUPPORTED OR FAILED. [Jan 21 15:48:47] DEBUG[28940][C-00000001] chan_sip.c: Processing session-level SDP o=- 13066328927026984 1 IN IP4 192.168.1.20... OK. [Jan 21 15:48:47] DEBUG[28940][C-00000001] chan_sip.c: Processing session-level SDP s=X-Lite release 4.7.1 stamp 74247... UNSUPPORTED OR FAILED. [Jan 21 15:48:47] DEBUG[28940][C-00000001] netsock2.c: Splitting '192.168.1.20' into... [Jan 21 15:48:47] DEBUG[28940][C-00000001] netsock2.c: ...host '192.168.1.20' and port ''. [Jan 21 15:48:47] DEBUG[28940][C-00000001] chan_sip.c: Processing session-level SDP c=IN IP4 192.168.1.20... OK. [Jan 21 15:48:47] DEBUG[28940][C-00000001] chan_sip.c: Processing session-level SDP t=0 0... UNSUPPORTED OR FAILED. [Jan 21 15:48:47] DEBUG[28940][C-00000001] rtp_engine.c: Setting payload 125 (0xb45fe5c4) based on m type on 0xb4c18be0 [Jan 21 15:48:47] DEBUG[28940][C-00000001] rtp_engine.c: Setting payload 100 (0xb45fe60c) based on m type on 0xb4c18be0 [Jan 21 15:48:47] DEBUG[28940][C-00000001] rtp_engine.c: Setting payload 0 (0xb3f04fc4) based on m type on 0xb4c18be0 [Jan 21 15:48:47] DEBUG[28940][C-00000001] rtp_engine.c: Setting payload 8 (0xb3f053e4) based on m type on 0xb4c18be0 [Jan 21 15:48:47] DEBUG[28940][C-00000001] rtp_engine.c: Setting payload 9 (0xb3f05804) based on m type on 0xb4c18be0 [Jan 21 15:48:47] DEBUG[28940][C-00000001] rtp_engine.c: Setting payload 101 (0xb3f05c24) based on m type on 0xb4c18be0 [Jan 21 15:48:47] DEBUG[28940][C-00000001] chan_sip.c: Processing media-level (audio) SDP a=rtpmap:125 opus/48000/2... OK. [Jan 21 15:48:47] DEBUG[28940][C-00000001] rtp_engine.c: Unsetting payload 125 on 0xb4c18be0 [Jan 21 15:48:47] DEBUG[28940][C-00000001] chan_sip.c: Processing media-level (audio) SDP a=fmtp:125 useinbandfec=1... UNSUPPORTED OR FAILED. [Jan 21 15:48:47] DEBUG[28940][C-00000001] chan_sip.c: Processing media-level (audio) SDP a=rtpmap:100 speex/16000... OK. [Jan 21 15:48:47] DEBUG[28940][C-00000001] chan_sip.c: Processing media-level (audio) SDP a=rtpmap:101 telephone-event/8000... OK. [Jan 21 15:48:47] DEBUG[28940][C-00000001] chan_sip.c: Processing media-level (audio) SDP a=fmtp:101 0-15... UNSUPPORTED OR FAILED. [Jan 21 15:48:47] DEBUG[28940][C-00000001] chan_sip.c: Processing media-level (audio) SDP a=sendrecv... OK. [Jan 21 15:48:47] DEBUG[28940][C-00000001] res_rtp_asterisk.c: Setting RTCP address on RTP instance '0xb45ffddc' [Jan 21 15:48:47] DEBUG[28940][C-00000001] rtp_engine.c: Copying payload 0 (0xb3f04fc4) from 0xb4c18be0 to 0xb45fff04 [Jan 21 15:48:47] DEBUG[28940][C-00000001] rtp_engine.c: Copying payload 8 (0xb3f053e4) from 0xb4c18be0 to 0xb45fff04 [Jan 21 15:48:47] DEBUG[28940][C-00000001] rtp_engine.c: Copying payload 9 (0xb3f05804) from 0xb4c18be0 to 0xb45fff04 [Jan 21 15:48:47] DEBUG[28940][C-00000001] rtp_engine.c: Copying payload 100 (0xb3f06044) from 0xb4c18be0 to 0xb45fff04 [Jan 21 15:48:47] DEBUG[28940][C-00000001] rtp_engine.c: Copying payload 101 (0xb45fe5ec) from 0xb4c18be0 to 0xb45fff04 [Jan 21 15:48:47] DEBUG[28940][C-00000001] res_rtp_asterisk.c: Ignoring duplicate RTCP property on RTP instance '0xb45ffddc' [Jan 21 15:48:47] DEBUG[28940][C-00000001] chan_sip.c: We're settling with these formats: (alaw) [Jan 21 15:48:47] DEBUG[28940][C-00000001] chan_sip.c: Checking SIP call limits for device 1003 [Jan 21 15:48:47] DEBUG[28940][C-00000001] chan_sip.c: Updating call counter for incoming call [Jan 21 15:48:47] DEBUG[28915] devicestate.c: No provider found, checking channel drivers for SIP - 1003 [Jan 21 15:48:47] DEBUG[28915] chan_sip.c: Checking device state for peer 1003 [Jan 21 15:48:47] DEBUG[28915] devicestate.c: Changing state for SIP/1003 - state 2 (In use) [Jan 21 15:48:47] DEBUG[28970] app_queue.c: Device 'SIP/1003' changed to state '2' (In use) but we don't care because they're not a member of any queue. [Jan 21 15:48:47] DEBUG[28974] manager.c: Examining AMI event: Event: DeviceStateChange Privilege: call,all Device: SIP/1003 State: INUSE [Jan 21 15:48:47] DEBUG[28940][C-00000001] netsock2.c: Splitting '192.168.1.200' into... [Jan 21 15:48:47] DEBUG[28940][C-00000001] netsock2.c: ...host '192.168.1.200' and port ''. [Jan 21 15:48:47] DEBUG[28940][C-00000001] netsock2.c: Splitting '192.168.1.200' into... [Jan 21 15:48:47] DEBUG[28940][C-00000001] netsock2.c: ...host '192.168.1.200' and port ''. [Jan 21 15:48:47] DEBUG[28974] manager.c: Examining AMI event: Event: Newchannel Privilege: call,all Channel: SIP/1003-00000002 ChannelState: 0 ChannelStateDesc: Down CallerIDNum: 1003 CallerIDName: 1003 ConnectedLineNum: ConnectedLineName: AccountCode: Context: main Exten: 2001 Priority: 1 Uniqueid: 1421855327.6 [Jan 21 15:48:47] DEBUG[28940][C-00000001] chan_sip.c: *** Our native formats are (alaw) [Jan 21 15:48:47] DEBUG[28940][C-00000001] chan_sip.c: *** Joint capabilities are (alaw) [Jan 21 15:48:47] DEBUG[28940][C-00000001] chan_sip.c: *** Our capabilities are (alaw) [Jan 21 15:48:47] DEBUG[28940][C-00000001] chan_sip.c: *** AST_CODEC_CHOOSE formats are alaw [Jan 21 15:48:47] DEBUG[28940][C-00000001] chan_sip.c: This channel will not be able to handle video. [Jan 21 15:48:47] DEBUG[28974] manager.c: Examining AMI event: Event: VarSet Privilege: dialplan,all Channel: SIP/1003-00000002 ChannelState: 0 ChannelStateDesc: Down CallerIDNum: 1003 CallerIDName: 1003 ConnectedLineNum: ConnectedLineName: AccountCode: Context: main Exten: 2001 Priority: 1 Uniqueid: 1421855327.6 Variable: SIPURI Value: sip:1003@192.168.1.20:43604 [Jan 21 15:48:47] DEBUG[28974] manager.c: Examining AMI event: Event: VarSet Privilege: dialplan,all Channel: SIP/1003-00000002 ChannelState: 0 ChannelStateDesc: Down CallerIDNum: 1003 CallerIDName: 1003 ConnectedLineNum: ConnectedLineName: AccountCode: Context: main Exten: 2001 Priority: 1 Uniqueid: 1421855327.6 Variable: SIPDOMAIN Value: 192.168.1.200 [Jan 21 15:48:47] DEBUG[28974] manager.c: Examining AMI event: Event: VarSet Privilege: dialplan,all Channel: SIP/1003-00000002 ChannelState: 0 ChannelStateDesc: Down CallerIDNum: 1003 CallerIDName: 1003 ConnectedLineNum: ConnectedLineName: AccountCode: Context: main Exten: 2001 Priority: 1 Uniqueid: 1421855327.6 Variable: SIPCALLID Value: ZjM1ZTJhOWVkMDc2YzhiYjEwNDA3NjYzM2VkOWI5YTc [Jan 21 15:48:47] DEBUG[28940][C-00000001] chan_sip.c: SIP/1003-00000002: New call is still down.... Trying... [Jan 21 15:48:47] DEBUG[28940][C-00000001] chan_sip.c: Trying to put 'SIP/2.0 100' onto UDP socket destined for 192.168.1.20:43604 [Jan 21 15:48:47] DEBUG[28974] manager.c: Examining AMI event: Event: Newstate Privilege: call,all Channel: SIP/1003-00000002 ChannelState: 4 ChannelStateDesc: Ring CallerIDNum: 1003 CallerIDName: 1003 ConnectedLineNum: ConnectedLineName: AccountCode: Context: main Exten: 2001 Priority: 1 Uniqueid: 1421855327.6 [Jan 21 15:48:47] DEBUG[28915] devicestate.c: No provider found, checking channel drivers for SIP - 1003 [Jan 21 15:48:47] DEBUG[28915] chan_sip.c: Checking device state for peer 1003 [Jan 21 15:48:47] DEBUG[28915] devicestate.c: Changing state for SIP/1003 - state 2 (In use) [Jan 21 15:48:47] DEBUG[28997][C-00000001] pbx.c: Result of 'EXTEN' is '2001' [Jan 21 15:48:47] DEBUG[28997][C-00000001] pbx.c: Launching 'NoOp' [Jan 21 15:48:47] VERBOSE[28997][C-00000001] pbx.c: Executing [2001@main:1] NoOp("SIP/1003-00000002", "This is the first priority of 2001") in new stack [Jan 21 15:48:47] DEBUG[28974] manager.c: Examining AMI event: Event: Newexten Privilege: call,all Channel: SIP/1003-00000002 ChannelState: 4 ChannelStateDesc: Ring CallerIDNum: 1003 CallerIDName: 1003 ConnectedLineNum: ConnectedLineName: AccountCode: Context: main Exten: 2001 Priority: 1 Uniqueid: 1421855327.6 Extension: 2001 Application: NoOp AppData: This is the first priority of 2001 [Jan 21 15:48:47] DEBUG[28997][C-00000001] pbx.c: Result of 'EXTEN' is '2001' [Jan 21 15:48:47] DEBUG[28997][C-00000001] pbx.c: Result of 'EXTEN' is '2001' [Jan 21 15:48:47] DEBUG[28997][C-00000001] pbx.c: Launching 'NoOp' [Jan 21 15:48:47] VERBOSE[28997][C-00000001] pbx.c: Executing [2001@main:2] NoOp("SIP/1003-00000002", "This is the second priority of 2001 - about to dial SIP/1001") in new stack [Jan 21 15:48:47] DEBUG[28974] manager.c: Examining AMI event: Event: Newexten Privilege: call,all Channel: SIP/1003-00000002 ChannelState: 4 ChannelStateDesc: Ring CallerIDNum: 1003 CallerIDName: 1003 ConnectedLineNum: ConnectedLineName: AccountCode: Context: main Exten: 2001 Priority: 2 Uniqueid: 1421855327.6 Extension: 2001 Application: NoOp AppData: This is the second priority of 2001 - about to dial SIP/1001 [Jan 21 15:48:47] DEBUG[28997][C-00000001] pbx.c: Result of 'EXTEN' is '2001' [Jan 21 15:48:47] DEBUG[28997][C-00000001] pbx.c: Launching 'Dial' [Jan 21 15:48:47] VERBOSE[28997][C-00000001] pbx.c: Executing [2001@main:3] Dial("SIP/1003-00000002", "SIP/1001,,rotwh") in new stack [Jan 21 15:48:47] DEBUG[28974] manager.c: Examining AMI event: Event: Newexten Privilege: call,all Channel: SIP/1003-00000002 ChannelState: 4 ChannelStateDesc: Ring CallerIDNum: 1003 CallerIDName: 1003 ConnectedLineNum: ConnectedLineName: AccountCode: Context: main Exten: 2001 Priority: 3 Uniqueid: 1421855327.6 Extension: 2001 Application: Dial AppData: SIP/1001,,rotwh [Jan 21 15:48:47] DEBUG[28974] manager.c: Examining AMI event: Event: VarSet Privilege: dialplan,all Channel: SIP/1003-00000002 ChannelState: 4 ChannelStateDesc: Ring CallerIDNum: 1003 CallerIDName: 1003 ConnectedLineNum: ConnectedLineName: AccountCode: Context: main Exten: 2001 Priority: 3 Uniqueid: 1421855327.6 Variable: DIALSTATUS Value: [Jan 21 15:48:47] DEBUG[28974] manager.c: Examining AMI event: Event: VarSet Privilege: dialplan,all Channel: SIP/1003-00000002 ChannelState: 4 ChannelStateDesc: Ring CallerIDNum: 1003 CallerIDName: 1003 ConnectedLineNum: ConnectedLineName: AccountCode: Context: main Exten: 2001 Priority: 3 Uniqueid: 1421855327.6 Variable: DIALEDPEERNUMBER Value: [Jan 21 15:48:47] DEBUG[28974] manager.c: Examining AMI event: Event: VarSet Privilege: dialplan,all Channel: SIP/1003-00000002 ChannelState: 4 ChannelStateDesc: Ring CallerIDNum: 1003 CallerIDName: 1003 ConnectedLineNum: ConnectedLineName: AccountCode: Context: main Exten: 2001 Priority: 3 Uniqueid: 1421855327.6 Variable: DIALEDPEERNAME Value: [Jan 21 15:48:47] DEBUG[28974] manager.c: Examining AMI event: Event: VarSet Privilege: dialplan,all Channel: SIP/1003-00000002 ChannelState: 4 ChannelStateDesc: Ring CallerIDNum: 1003 CallerIDName: 1003 ConnectedLineNum: ConnectedLineName: AccountCode: Context: main Exten: 2001 Priority: 3 Uniqueid: 1421855327.6 Variable: ANSWEREDTIME Value: [Jan 21 15:48:47] DEBUG[28974] manager.c: Examining AMI event: Event: VarSet Privilege: dialplan,all Channel: SIP/1003-00000002 ChannelState: 4 ChannelStateDesc: Ring CallerIDNum: 1003 CallerIDName: 1003 ConnectedLineNum: ConnectedLineName: AccountCode: Context: main Exten: 2001 Priority: 3 Uniqueid: 1421855327.6 Variable: DIALEDTIME Value: [Jan 21 15:48:47] DEBUG[28997][C-00000001] chan_sip.c: Asked to create a SIP channel with formats: (alaw) [Jan 21 15:48:47] DEBUG[28997][C-00000001] chan_sip.c: Allocating new SIP dialog for 195319bd7ac0c6956b882a274e2e37b6@192.168.1.200:5060 - INVITE (No RTP) [Jan 21 15:48:47] DEBUG[28997][C-00000001] rtp_engine.c: Using engine 'asterisk' for RTP instance '0xa3995cc' [Jan 21 15:48:47] DEBUG[28997][C-00000001] res_rtp_asterisk.c: Allocated port 17082 for RTP instance '0xa3995cc' [Jan 21 15:48:47] DEBUG[28997][C-00000001] rtp_engine.c: RTP instance '0xa3995cc' is setup and ready to go [Jan 21 15:48:47] DEBUG[28997][C-00000001] res_rtp_asterisk.c: Setup RTCP on RTP instance '0xa3995cc' [Jan 21 15:48:47] VERBOSE[28997][C-00000001] netsock2.c: Using SIP RTP CoS mark 5 [Jan 21 15:48:47] DEBUG[28997][C-00000001] chan_sip.c: Setting NAT on RTP to Off [Jan 21 15:48:47] DEBUG[28997][C-00000001] acl.c: For destination '192.168.1.20', our source address is '192.168.1.200'. [Jan 21 15:48:47] DEBUG[28997][C-00000001] chan_sip.c: Setting AST_TRANSPORT_UDP with address 192.168.1.200:5060 [Jan 21 15:48:47] DEBUG[28997][C-00000001] netsock2.c: Splitting '192.168.1.20:5070' into... [Jan 21 15:48:47] DEBUG[28997][C-00000001] netsock2.c: ...host '192.168.1.20' and port '5070'. [Jan 21 15:48:47] DEBUG[28997][C-00000001] chan_sip.c: Setting NAT on RTP to Off [Jan 21 15:48:47] DEBUG[28997][C-00000001] chan_sip.c: SIP call-id changed from '195319bd7ac0c6956b882a274e2e37b6@192.168.1.200:5060' to '3704122f21547d9b4ea7c725515be0ae@192.168.1.200:5060' [Jan 21 15:48:47] DEBUG[28974] manager.c: Examining AMI event: Event: Newchannel Privilege: call,all Channel: SIP/1001-00000003 ChannelState: 0 ChannelStateDesc: Down CallerIDNum: 1001 CallerIDName: 1001 ConnectedLineNum: ConnectedLineName: AccountCode: Context: main Exten: s Priority: 1 Uniqueid: 1421855327.7 [Jan 21 15:48:47] DEBUG[28997][C-00000001] chan_sip.c: *** Our native formats are (alaw) [Jan 21 15:48:47] DEBUG[28997][C-00000001] chan_sip.c: *** Joint capabilities are (alaw) [Jan 21 15:48:47] DEBUG[28997][C-00000001] chan_sip.c: *** Our capabilities are (alaw) [Jan 21 15:48:47] DEBUG[28997][C-00000001] chan_sip.c: *** AST_CODEC_CHOOSE formats are alaw [Jan 21 15:48:47] DEBUG[28997][C-00000001] chan_sip.c: *** Our preferred formats from the incoming channel are (alaw) [Jan 21 15:48:47] DEBUG[28997][C-00000001] chan_sip.c: This channel will not be able to handle video. [Jan 21 15:48:47] DEBUG[28974] manager.c: Examining AMI event: Event: VarSet Privilege: dialplan,all Channel: SIP/1001-00000003 ChannelState: 0 ChannelStateDesc: Down CallerIDNum: 1001 CallerIDName: 1001 ConnectedLineNum: ConnectedLineName: AccountCode: Context: main Exten: s Priority: 1 Uniqueid: 1421855327.7 Variable: SIPCALLID Value: 3704122f21547d9b4ea7c725515be0ae@192.168.1.200:5060 [Jan 21 15:48:47] DEBUG[28997][C-00000001] channel_internal_api.c: Channel Call ID changing from [C-00000001] to [C-00000001] [Jan 21 15:48:47] DEBUG[28974] manager.c: Examining AMI event: Event: VarSet Privilege: dialplan,all Channel: SIP/1001-00000003 ChannelState: 0 ChannelStateDesc: Down CallerIDNum: 1001 CallerIDName: 1001 ConnectedLineNum: ConnectedLineName: AccountCode: Context: main Exten: Priority: 1 Uniqueid: 1421855327.7 Variable: DIALEDPEERNUMBER Value: 1001 [Jan 21 15:48:47] DEBUG[28997][C-00000001] rtp_engine.c: Copying payload 0 (0xb3f04fc4) from 0xb45fff04 to 0xa3996f4 [Jan 21 15:48:47] DEBUG[28997][C-00000001] rtp_engine.c: Copying payload 8 (0xb3f053e4) from 0xb45fff04 to 0xa3996f4 [Jan 21 15:48:47] DEBUG[28997][C-00000001] rtp_engine.c: Copying payload 9 (0xb3f05804) from 0xb45fff04 to 0xa3996f4 [Jan 21 15:48:47] DEBUG[28997][C-00000001] rtp_engine.c: Copying payload 100 (0xb3f06044) from 0xb45fff04 to 0xa3996f4 [Jan 21 15:48:47] DEBUG[28997][C-00000001] rtp_engine.c: Copying payload 101 (0xb45fe5ec) from 0xb45fff04 to 0xa3996f4 [Jan 21 15:48:47] DEBUG[28997][C-00000001] rtp_engine.c: Seeded SDP of 'SIP/1001-00000003' with that of 'SIP/1003-00000002' [Jan 21 15:48:47] DEBUG[28974] manager.c: Examining AMI event: Event: Newexten Privilege: call,all Channel: SIP/1001-00000003 ChannelState: 0 ChannelStateDesc: Down CallerIDNum: 1003 CallerIDName: 1003 ConnectedLineNum: 1003 ConnectedLineName: 1003 AccountCode: Context: main Exten: 2001 Priority: 1 Uniqueid: 1421855327.7 Extension: 2001 Application: AppDial AppData: (Outgoing Line) [Jan 21 15:48:47] DEBUG[28974] manager.c: Examining AMI event: Event: NewCallerid Privilege: call,all Channel: SIP/1001-00000003 ChannelState: 0 ChannelStateDesc: Down CallerIDNum: 1003 CallerIDName: 1003 ConnectedLineNum: 1003 ConnectedLineName: 1003 AccountCode: Context: main Exten: 2001 Priority: 1 Uniqueid: 1421855327.7 CID-CallingPres: 0 (Presentation Allowed, Not Screened) [Jan 21 15:48:47] DEBUG[28997][C-00000001] chan_sip.c: Outgoing Call for 1001 [Jan 21 15:48:47] DEBUG[28997][C-00000001] chan_sip.c: Updating call counter for outgoing call [Jan 21 15:48:47] DEBUG[28915] devicestate.c: No provider found, checking channel drivers for SIP - 1001 [Jan 21 15:48:47] DEBUG[28915] chan_sip.c: Checking device state for peer 1001 [Jan 21 15:48:47] DEBUG[28915] devicestate.c: Changing state for SIP/1001 - state 6 (Ringing) [Jan 21 15:48:47] DEBUG[28970] app_queue.c: Device 'SIP/1001' changed to state '6' (Ringing) [Jan 21 15:48:47] DEBUG[28974] manager.c: Examining AMI event: Event: DeviceStateChange Privilege: call,all Device: SIP/1001 State: RINGING [Jan 21 15:48:47] DEBUG[28974] manager.c: Examining AMI event: Event: QueueMemberStatus Privilege: agent,all MemberName: Local/1001@main/n Interface: Local/1001@main/n Membership: dynamic Queue: PlainAE StateInterface: SIP/1001 Penalty: 0 CallsTaken: 0 LastCall: 0 Status: 6 Ringinuse: 1 Paused: 0 [Jan 21 15:48:47] DEBUG[28974] manager.c: Examining AMI event: Event: QueueMemberStatus Privilege: agent,all MemberName: Local/1001@main/n Interface: Local/1001@main/n Membership: dynamic Queue: Sales StateInterface: SIP/1001 Penalty: 0 CallsTaken: 0 LastCall: 0 Status: 6 Ringinuse: 1 Paused: 0 [Jan 21 15:48:47] DEBUG[28974] manager.c: Examining AMI event: Event: QueueMemberStatus Privilege: agent,all MemberName: Local/1001@main/n Interface: Local/1001@main/n Membership: dynamic Queue: CustServ StateInterface: SIP/1001 Penalty: 0 CallsTaken: 0 LastCall: 0 Status: 6 Ringinuse: 1 Paused: 0 [Jan 21 15:48:47] DEBUG[28974] manager.c: Examining AMI event: Event: QueueMemberStatus Privilege: agent,all MemberName: Local/1001@main/n Interface: Local/1001@main/n Membership: dynamic Queue: Plain StateInterface: SIP/1001 Penalty: 0 CallsTaken: 0 LastCall: 0 Status: 6 Ringinuse: 1 Paused: 0 [Jan 21 15:48:47] DEBUG[28997][C-00000001] chan_sip.c: ** Our capability: (alaw) Video flag: False Text flag: False [Jan 21 15:48:47] DEBUG[28997][C-00000001] chan_sip.c: ** Our prefcodec: (alaw) [Jan 21 15:48:47] DEBUG[28997][C-00000001] chan_sip.c: -- Done with adding codecs to SDP [Jan 21 15:48:47] DEBUG[28997][C-00000001] chan_sip.c: Done building SDP. Settling with this capability: (alaw) [Jan 21 15:48:47] DEBUG[28997][C-00000001] chan_sip.c: Initializing initreq for method INVITE - callid 3704122f21547d9b4ea7c725515be0ae@192.168.1.200:5060 [Jan 21 15:48:47] DEBUG[28997][C-00000001] chan_sip.c: Trying to put 'INVITE sip:' onto UDP socket destined for 192.168.1.20:5070 [Jan 21 15:48:47] DEBUG[28974] manager.c: Examining AMI event: Event: DialBegin Privilege: call,all Channel: SIP/1003-00000002 ChannelState: 4 ChannelStateDesc: Ring CallerIDNum: 1003 CallerIDName: 1003 ConnectedLineNum: ConnectedLineName: AccountCode: Context: main Exten: 2001 Priority: 3 Uniqueid: 1421855327.6 DestChannel: SIP/1001-00000003 DestChannelState: 0 DestChannelStateDesc: Down DestCallerIDNum: 1003 DestCallerIDName: 1003 DestConnectedLineNum: 1003 DestConnectedLineName: 1003 DestAccountCode: DestContext: main DestExten: 2001 DestPriority: 1 DestUniqueid: 1421855327.7 DialString: 1001 [Jan 21 15:48:47] VERBOSE[28997][C-00000001] app_dial.c: Called SIP/1001 [Jan 21 15:48:47] DEBUG[28997][C-00000001] chan_sip.c: Trying to put 'SIP/2.0 180' onto UDP socket destined for 192.168.1.20:43604 [Jan 21 15:48:47] DEBUG[28940] chan_sip.c: = Looking for Call ID: 3704122f21547d9b4ea7c725515be0ae@192.168.1.200:5060 (Checking To) --From tag as64db9253 --To-tag 9905 [Jan 21 15:48:47] DEBUG[28940][C-00000001] chan_sip.c: (Provisional) Stopping retransmission (but retaining packet) on '3704122f21547d9b4ea7c725515be0ae@192.168.1.200:5060' Request 102: Found [Jan 21 15:48:47] DEBUG[28940][C-00000001] chan_sip.c: SIP response 180 to standard invite [Jan 21 15:48:47] VERBOSE[28997][C-00000001] app_dial.c: SIP/1001-00000003 is ringing [Jan 21 15:48:47] DEBUG[28997][C-00000001] chan_sip.c: Trying to put 'SIP/2.0 180' onto UDP socket destined for 192.168.1.20:43604 [Jan 21 15:48:47] DEBUG[28915] devicestate.c: No provider found, checking channel drivers for SIP - 1001 [Jan 21 15:48:47] DEBUG[28915] chan_sip.c: Checking device state for peer 1001 [Jan 21 15:48:47] DEBUG[28915] devicestate.c: Changing state for SIP/1001 - state 6 (Ringing) [Jan 21 15:48:47] DEBUG[28974] manager.c: Examining AMI event: Event: Newstate Privilege: call,all Channel: SIP/1001-00000003 ChannelState: 5 ChannelStateDesc: Ringing CallerIDNum: 1003 CallerIDName: 1003 ConnectedLineNum: 1003 ConnectedLineName: 1003 AccountCode: Context: main Exten: 2001 Priority: 1 Uniqueid: 1421855327.7 [Jan 21 15:48:47] DEBUG[28940] chan_sip.c: = Looking for Call ID: 3704122f21547d9b4ea7c725515be0ae@192.168.1.200:5060 (Checking To) --From tag as64db9253 --To-tag 9905 [Jan 21 15:48:47] DEBUG[28940][C-00000001] chan_sip.c: (Provisional) Stopping retransmission (but retaining packet) on '3704122f21547d9b4ea7c725515be0ae@192.168.1.200:5060' Request 102: Found [Jan 21 15:48:47] DEBUG[28940][C-00000001] chan_sip.c: SIP response 180 to standard invite [Jan 21 15:48:47] VERBOSE[28997][C-00000001] app_dial.c: SIP/1001-00000003 is ringing [Jan 21 15:48:48] DEBUG[28940] chan_sip.c: = Looking for Call ID: 3704122f21547d9b4ea7c725515be0ae@192.168.1.200:5060 (Checking To) --From tag as64db9253 --To-tag 9905 [Jan 21 15:48:48] DEBUG[28940][C-00000001] chan_sip.c: Acked pending invite 102 [Jan 21 15:48:48] DEBUG[28940][C-00000001] chan_sip.c: Stopping retransmission on '3704122f21547d9b4ea7c725515be0ae@192.168.1.200:5060' of Request 102: Match Found [Jan 21 15:48:48] DEBUG[28940][C-00000001] chan_sip.c: SIP response 200 to standard invite [Jan 21 15:48:48] DEBUG[28940][C-00000001] chan_sip.c: Processing session-level SDP v=0... UNSUPPORTED OR FAILED. [Jan 21 15:48:48] DEBUG[28940][C-00000001] chan_sip.c: Processing session-level SDP o=NCHSoftware-Talk 1421530503 1421530577 IN IP4 192.168.1.20... OK. [Jan 21 15:48:48] DEBUG[28940][C-00000001] chan_sip.c: Processing session-level SDP s=Express Talk Call... UNSUPPORTED OR FAILED. [Jan 21 15:48:48] DEBUG[28940][C-00000001] netsock2.c: Splitting '192.168.1.20' into... [Jan 21 15:48:48] DEBUG[28940][C-00000001] netsock2.c: ...host '192.168.1.20' and port ''. [Jan 21 15:48:48] DEBUG[28940][C-00000001] chan_sip.c: Processing session-level SDP c=IN IP4 192.168.1.20... OK. [Jan 21 15:48:48] DEBUG[28940][C-00000001] chan_sip.c: Processing session-level SDP t=0 0... UNSUPPORTED OR FAILED. [Jan 21 15:48:48] DEBUG[28940][C-00000001] rtp_engine.c: Setting payload 8 (0xb45fdaf4) based on m type on 0xb4c17c60 [Jan 21 15:48:48] DEBUG[28940][C-00000001] rtp_engine.c: Setting payload 101 (0xb45fdb3c) based on m type on 0xb4c17c60 [Jan 21 15:48:48] DEBUG[28940][C-00000001] chan_sip.c: Processing media-level (audio) SDP a=rtpmap:8 PCMA/8000... OK. [Jan 21 15:48:48] DEBUG[28940][C-00000001] chan_sip.c: Processing media-level (audio) SDP a=rtpmap:101 telephone-event/8000... OK. [Jan 21 15:48:48] DEBUG[28940][C-00000001] chan_sip.c: Processing media-level (audio) SDP a=fmtp:101 0-16... UNSUPPORTED OR FAILED. [Jan 21 15:48:48] DEBUG[28940][C-00000001] chan_sip.c: Processing media-level (audio) SDP a=sendrecv... OK. [Jan 21 15:48:48] DEBUG[28940][C-00000001] res_rtp_asterisk.c: Setting RTCP address on RTP instance '0xa3995cc' [Jan 21 15:48:48] DEBUG[28940][C-00000001] rtp_engine.c: Copying payload 8 (0xb3f05744) from 0xb4c17c60 to 0xa3996f4 [Jan 21 15:48:48] DEBUG[28940][C-00000001] rtp_engine.c: Copying payload 101 (0xb45fdaf4) from 0xb4c17c60 to 0xa3996f4 [Jan 21 15:48:48] DEBUG[28940][C-00000001] res_rtp_asterisk.c: Ignoring duplicate RTCP property on RTP instance '0xa3995cc' [Jan 21 15:48:48] DEBUG[28940][C-00000001] chan_sip.c: We're settling with these formats: (alaw) [Jan 21 15:48:48] DEBUG[28940][C-00000001] chan_sip.c: We have an owner, now see if we need to change this call [Jan 21 15:48:48] DEBUG[28940][C-00000001] chan_sip.c: Updating call counter for outgoing call [Jan 21 15:48:48] DEBUG[28940][C-00000001] netsock2.c: Splitting '192.168.1.20:5070' into... [Jan 21 15:48:48] DEBUG[28940][C-00000001] netsock2.c: ...host '192.168.1.20' and port '5070'. [Jan 21 15:48:48] DEBUG[28940][C-00000001] netsock2.c: Splitting '192.168.1.20:5070' into... [Jan 21 15:48:48] DEBUG[28940][C-00000001] netsock2.c: ...host '192.168.1.20' and port '5070'. [Jan 21 15:48:48] DEBUG[28940][C-00000001] chan_sip.c: Trying to put 'ACK sip:100' onto UDP socket destined for 192.168.1.20:5070 [Jan 21 15:48:48] DEBUG[28997][C-00000001] channel.c: SIP/1003-00000002: Dropping redundant connected line update "1001" <1001>. [Jan 21 15:48:48] VERBOSE[28997][C-00000001] app_dial.c: SIP/1001-00000003 answered SIP/1003-00000002 [Jan 21 15:48:48] DEBUG[28997][C-00000001] chan_sip.c: SIP answering channel: SIP/1003-00000002 [Jan 21 15:48:48] DEBUG[28997][C-00000001] res_rtp_asterisk.c: Setting the marker bit due to a source update [Jan 21 15:48:48] DEBUG[28997][C-00000001] chan_sip.c: Setting framing from config on incoming call [Jan 21 15:48:48] DEBUG[28997][C-00000001] chan_sip.c: ** Our capability: (alaw) Video flag: True Text flag: True [Jan 21 15:48:48] DEBUG[28997][C-00000001] chan_sip.c: ** Our prefcodec: (nothing) [Jan 21 15:48:48] DEBUG[28997][C-00000001] chan_sip.c: -- Done with adding codecs to SDP [Jan 21 15:48:48] DEBUG[28997][C-00000001] chan_sip.c: Done building SDP. Settling with this capability: (alaw) [Jan 21 15:48:48] DEBUG[28997][C-00000001] chan_sip.c: Trying to put 'SIP/2.0 200' onto UDP socket destined for 192.168.1.20:43604 [Jan 21 15:48:48] DEBUG[28997][C-00000001] features.c: Removing dialed interfaces datastore on SIP/1001-00000003 since we're bridging [Jan 21 15:48:48] DEBUG[28997][C-00000001] dahdi/bridge_native_dahdi.c: Bridge 7d6127b5-7b28-4d6b-b736-0622d802761e: Cannot use native DAHDI. Must have two channels. [Jan 21 15:48:48] DEBUG[28997][C-00000001] bridge.c: Bridge technology native_dahdi is not compatible with properties of existing bridge. [Jan 21 15:48:48] DEBUG[28997][C-00000001] bridge.c: Bridge technology holding_bridge does not have any capabilities we want. [Jan 21 15:48:48] DEBUG[28997][C-00000001] bridge_native_rtp.c: Bridge '7d6127b5-7b28-4d6b-b736-0622d802761e' can not use native RTP bridge as two channels are required [Jan 21 15:48:48] DEBUG[28997][C-00000001] bridge.c: Bridge technology native_rtp is not compatible with properties of existing bridge. [Jan 21 15:48:48] DEBUG[28997][C-00000001] bridge.c: Chose bridge technology simple_bridge [Jan 21 15:48:48] DEBUG[28997][C-00000001] bridge.c: Bridge 7d6127b5-7b28-4d6b-b736-0622d802761e: calling simple_bridge technology constructor [Jan 21 15:48:48] DEBUG[28997][C-00000001] bridge.c: Bridge 7d6127b5-7b28-4d6b-b736-0622d802761e: calling simple_bridge technology start [Jan 21 15:48:48] DEBUG[28997][C-00000001] bridge_channel.c: Bridge 7d6127b5-7b28-4d6b-b736-0622d802761e: 0xa047ac4(SIP/1003-00000002) is joining [Jan 21 15:48:48] DEBUG[28997][C-00000001] bridge_channel.c: Bridge 7d6127b5-7b28-4d6b-b736-0622d802761e: pushing 0xa047ac4(SIP/1003-00000002) [Jan 21 15:48:48] VERBOSE[28997][C-00000001] bridge_channel.c: Channel SIP/1003-00000002 joined 'simple_bridge' basic-bridge <7d6127b5-7b28-4d6b-b736-0622d802761e> [Jan 21 15:48:48] DEBUG[28997][C-00000001] dahdi/bridge_native_dahdi.c: Bridge 7d6127b5-7b28-4d6b-b736-0622d802761e: Cannot use native DAHDI. Must have two channels. [Jan 21 15:48:48] DEBUG[28997][C-00000001] bridge.c: Bridge technology native_dahdi is not compatible with properties of existing bridge. [Jan 21 15:48:48] DEBUG[28997][C-00000001] bridge.c: Bridge technology holding_bridge does not have any capabilities we want. [Jan 21 15:48:48] DEBUG[28997][C-00000001] bridge.c: Bridge technology softmix does not have any capabilities we want. [Jan 21 15:48:48] DEBUG[28997][C-00000001] bridge_native_rtp.c: Bridge '7d6127b5-7b28-4d6b-b736-0622d802761e' can not use native RTP bridge as two channels are required [Jan 21 15:48:48] DEBUG[28997][C-00000001] bridge.c: Bridge technology native_rtp is not compatible with properties of existing bridge. [Jan 21 15:48:48] DEBUG[28997][C-00000001] bridge.c: Chose bridge technology simple_bridge [Jan 21 15:48:48] DEBUG[28997][C-00000001] bridge.c: Bridge 7d6127b5-7b28-4d6b-b736-0622d802761e is already using the new technology. [Jan 21 15:48:48] DEBUG[28997][C-00000001] bridge.c: Bridge 7d6127b5-7b28-4d6b-b736-0622d802761e is happy that channel SIP/1003-00000002 already has read format alaw [Jan 21 15:48:48] DEBUG[28997][C-00000001] bridge.c: Bridge 7d6127b5-7b28-4d6b-b736-0622d802761e is happy that channel SIP/1003-00000002 already has write format alaw [Jan 21 15:48:48] DEBUG[28997][C-00000001] bridge.c: Bridge 7d6127b5-7b28-4d6b-b736-0622d802761e: 0xa047ac4(SIP/1003-00000002) is joining simple_bridge technology [Jan 21 15:48:48] DEBUG[28997][C-00000001] res_rtp_asterisk.c: Not changing SSRC since we haven't sent any RTP yet [Jan 21 15:48:48] DEBUG[28915] devicestate.c: No provider found, checking channel drivers for SIP - 1001 [Jan 21 15:48:48] DEBUG[28915] chan_sip.c: Checking device state for peer 1001 [Jan 21 15:48:48] DEBUG[28915] devicestate.c: Changing state for SIP/1001 - state 2 (In use) [Jan 21 15:48:48] DEBUG[28915] devicestate.c: No provider found, checking channel drivers for SIP - 1001 [Jan 21 15:48:48] DEBUG[28915] chan_sip.c: Checking device state for peer 1001 [Jan 21 15:48:48] DEBUG[28915] devicestate.c: Changing state for SIP/1001 - state 2 (In use) [Jan 21 15:48:48] DEBUG[28915] devicestate.c: No provider found, checking channel drivers for SIP - 1003 [Jan 21 15:48:48] DEBUG[28915] chan_sip.c: Checking device state for peer 1003 [Jan 21 15:48:48] DEBUG[28915] devicestate.c: Changing state for SIP/1003 - state 2 (In use) [Jan 21 15:48:48] DEBUG[28970] app_queue.c: Device 'SIP/1001' changed to state '2' (In use) [Jan 21 15:48:48] DEBUG[28974] manager.c: Examining AMI event: Event: Newstate Privilege: call,all Channel: SIP/1001-00000003 ChannelState: 6 ChannelStateDesc: Up CallerIDNum: 1003 CallerIDName: 1003 ConnectedLineNum: 1003 ConnectedLineName: 1003 AccountCode: Context: main Exten: 2001 Priority: 1 Uniqueid: 1421855327.7 [Jan 21 15:48:48] DEBUG[28974] manager.c: Examining AMI event: Event: VarSet Privilege: dialplan,all Channel: SIP/1003-00000002 ChannelState: 4 ChannelStateDesc: Ring CallerIDNum: 1003 CallerIDName: 1003 ConnectedLineNum: ConnectedLineName: AccountCode: Context: main Exten: 2001 Priority: 3 Uniqueid: 1421855327.6 Variable: DIALSTATUS Value: ANSWER [Jan 21 15:48:48] DEBUG[28974] manager.c: Examining AMI event: Event: VarSet Privilege: dialplan,all Channel: SIP/1003-00000002 ChannelState: 4 ChannelStateDesc: Ring CallerIDNum: 1003 CallerIDName: 1003 ConnectedLineNum: ConnectedLineName: AccountCode: Context: main Exten: 2001 Priority: 3 Uniqueid: 1421855327.6 Variable: DIALEDPEERNAME Value: SIP/1001-00000003 [Jan 21 15:48:48] DEBUG[28974] manager.c: Examining AMI event: Event: VarSet Privilege: dialplan,all Channel: SIP/1003-00000002 ChannelState: 4 ChannelStateDesc: Ring CallerIDNum: 1003 CallerIDName: 1003 ConnectedLineNum: ConnectedLineName: AccountCode: Context: main Exten: 2001 Priority: 3 Uniqueid: 1421855327.6 Variable: DIALEDPEERNUMBER Value: 1001 [Jan 21 15:48:48] DEBUG[28974] manager.c: Examining AMI event: Event: DialEnd Privilege: call,all Channel: SIP/1003-00000002 ChannelState: 4 ChannelStateDesc: Ring CallerIDNum: 1003 CallerIDName: 1003 ConnectedLineNum: 1001 ConnectedLineName: 1001 AccountCode: Context: main Exten: 2001 Priority: 3 Uniqueid: 1421855327.6 DestChannel: SIP/1001-00000003 DestChannelState: 6 DestChannelStateDesc: Up DestCallerIDNum: 1003 DestCallerIDName: 1003 DestConnectedLineNum: 1003 DestConnectedLineName: 1003 DestAccountCode: DestContext: main DestExten: DestPriority: 1 DestUniqueid: 1421855327.7 DialStatus: ANSWER [Jan 21 15:48:48] DEBUG[28974] manager.c: Examining AMI event: Event: Newstate Privilege: call,all Channel: SIP/1003-00000002 ChannelState: 6 ChannelStateDesc: Up CallerIDNum: 1003 CallerIDName: 1003 ConnectedLineNum: 1001 ConnectedLineName: 1001 AccountCode: Context: main Exten: 2001 Priority: 3 Uniqueid: 1421855327.6 [Jan 21 15:48:48] DEBUG[28974] manager.c: Examining AMI event: Event: BridgeCreate Privilege: call,all BridgeUniqueid: 7d6127b5-7b28-4d6b-b736-0622d802761e BridgeType: basic BridgeTechnology: simple_bridge BridgeCreator: BridgeName: BridgeNumChannels: 0 [Jan 21 15:48:48] DEBUG[28974] manager.c: Examining AMI event: Event: BridgeEnter Privilege: call,all BridgeUniqueid: 7d6127b5-7b28-4d6b-b736-0622d802761e BridgeType: basic BridgeTechnology: simple_bridge BridgeCreator: BridgeName: BridgeNumChannels: 1 Channel: SIP/1003-00000002 ChannelState: 6 ChannelStateDesc: Up CallerIDNum: 1003 CallerIDName: 1003 ConnectedLineNum: 1001 ConnectedLineName: 1001 AccountCode: Context: main Exten: 2001 Priority: 3 Uniqueid: 1421855327.6 [Jan 21 15:48:48] DEBUG[28974] manager.c: Examining AMI event: Event: DeviceStateChange Privilege: call,all Device: SIP/1001 State: INUSE [Jan 21 15:48:48] DEBUG[28974] manager.c: Examining AMI event: Event: QueueMemberStatus Privilege: agent,all MemberName: Local/1001@main/n Interface: Local/1001@main/n Membership: dynamic Queue: PlainAE StateInterface: SIP/1001 Penalty: 0 CallsTaken: 0 LastCall: 0 Status: 2 Ringinuse: 1 Paused: 0 [Jan 21 15:48:48] DEBUG[28974] manager.c: Examining AMI event: Event: QueueMemberStatus Privilege: agent,all MemberName: Local/1001@main/n Interface: Local/1001@main/n Membership: dynamic Queue: Sales StateInterface: SIP/1001 Penalty: 0 CallsTaken: 0 LastCall: 0 Status: 2 Ringinuse: 1 Paused: 0 [Jan 21 15:48:48] DEBUG[28974] manager.c: Examining AMI event: Event: QueueMemberStatus Privilege: agent,all MemberName: Local/1001@main/n Interface: Local/1001@main/n Membership: dynamic Queue: CustServ StateInterface: SIP/1001 Penalty: 0 CallsTaken: 0 LastCall: 0 Status: 2 Ringinuse: 1 Paused: 0 [Jan 21 15:48:48] DEBUG[28974] manager.c: Examining AMI event: Event: QueueMemberStatus Privilege: agent,all MemberName: Local/1001@main/n Interface: Local/1001@main/n Membership: dynamic Queue: Plain StateInterface: SIP/1001 Penalty: 0 CallsTaken: 0 LastCall: 0 Status: 2 Ringinuse: 1 Paused: 0 [Jan 21 15:48:48] DEBUG[28998][C-00000001] bridge_channel.c: Bridge 7d6127b5-7b28-4d6b-b736-0622d802761e: 0xa39d9a4(SIP/1001-00000003) is joining [Jan 21 15:48:48] DEBUG[28974] manager.c: Examining AMI event: Event: Newexten Privilege: call,all Channel: SIP/1001-00000003 ChannelState: 6 ChannelStateDesc: Up CallerIDNum: 1003 CallerIDName: 1003 ConnectedLineNum: 1003 ConnectedLineName: 1003 AccountCode: Context: main Exten: Priority: 1 Uniqueid: 1421855327.7 Extension: Application: AppDial AppData: (Outgoing Line) [Jan 21 15:48:48] DEBUG[28998][C-00000001] bridge_channel.c: Bridge 7d6127b5-7b28-4d6b-b736-0622d802761e: pushing 0xa39d9a4(SIP/1001-00000003) [Jan 21 15:48:48] VERBOSE[28998][C-00000001] bridge_channel.c: Channel SIP/1001-00000003 joined 'simple_bridge' basic-bridge <7d6127b5-7b28-4d6b-b736-0622d802761e> [Jan 21 15:48:48] DEBUG[28916] cdr.c: Finalized CDR for SIP/1001-00000003 - start 1421855327.066148 answer 1421855328.917662 end 1421855328.929955 dispo ANSWERED [Jan 21 15:48:48] DEBUG[28974] manager.c: Examining AMI event: Event: BridgeEnter Privilege: call,all BridgeUniqueid: 7d6127b5-7b28-4d6b-b736-0622d802761e BridgeType: basic BridgeTechnology: simple_bridge BridgeCreator: BridgeName: BridgeNumChannels: 2 Channel: SIP/1001-00000003 ChannelState: 6 ChannelStateDesc: Up CallerIDNum: 1003 CallerIDName: 1003 ConnectedLineNum: 1003 ConnectedLineName: 1003 AccountCode: Context: main Exten: Priority: 1 Uniqueid: 1421855327.7 [Jan 21 15:48:48] DEBUG[28998][C-00000001] dahdi/bridge_native_dahdi.c: Channel 'SIP/1003-00000002' is not DAHDI. [Jan 21 15:48:48] DEBUG[28998][C-00000001] dahdi/bridge_native_dahdi.c: Bridge 7d6127b5-7b28-4d6b-b736-0622d802761e: Cannot use native DAHDI. Channel 'SIP/1003-00000002' not compatible. [Jan 21 15:48:48] DEBUG[28998][C-00000001] bridge.c: Bridge technology native_dahdi is not compatible with properties of existing bridge. [Jan 21 15:48:48] DEBUG[28998][C-00000001] bridge.c: Bridge technology holding_bridge does not have any capabilities we want. [Jan 21 15:48:48] DEBUG[28998][C-00000001] bridge.c: Bridge technology softmix does not have any capabilities we want. [Jan 21 15:48:48] DEBUG[28998][C-00000001] bridge_native_rtp.c: Bridge '7d6127b5-7b28-4d6b-b736-0622d802761e' can not use native RTP bridge as channel 'SIP/1001-00000003' has DTMF hooks [Jan 21 15:48:48] DEBUG[28998][C-00000001] bridge.c: Bridge technology native_rtp is not compatible with properties of existing bridge. [Jan 21 15:48:48] DEBUG[28998][C-00000001] bridge.c: Chose bridge technology simple_bridge [Jan 21 15:48:48] DEBUG[28998][C-00000001] bridge.c: Bridge 7d6127b5-7b28-4d6b-b736-0622d802761e is already using the new technology. [Jan 21 15:48:48] DEBUG[28998][C-00000001] bridge.c: Bridge 7d6127b5-7b28-4d6b-b736-0622d802761e is happy that channel SIP/1001-00000003 already has read format alaw [Jan 21 15:48:48] DEBUG[28998][C-00000001] bridge.c: Bridge 7d6127b5-7b28-4d6b-b736-0622d802761e is happy that channel SIP/1001-00000003 already has write format alaw [Jan 21 15:48:48] DEBUG[28998][C-00000001] bridge.c: Bridge 7d6127b5-7b28-4d6b-b736-0622d802761e: 0xa39d9a4(SIP/1001-00000003) is joining simple_bridge technology [Jan 21 15:48:48] DEBUG[28974] manager.c: Examining AMI event: Event: VarSet Privilege: dialplan,all Channel: SIP/1003-00000002 ChannelState: 6 ChannelStateDesc: Up CallerIDNum: 1003 CallerIDName: 1003 ConnectedLineNum: 1001 ConnectedLineName: 1001 AccountCode: Context: main Exten: 2001 Priority: 3 Uniqueid: 1421855327.6 Variable: BRIDGEPEER Value: SIP/1001-00000003 [Jan 21 15:48:48] DEBUG[28974] manager.c: Examining AMI event: Event: VarSet Privilege: dialplan,all Channel: SIP/1003-00000002 ChannelState: 6 ChannelStateDesc: Up CallerIDNum: 1003 CallerIDName: 1003 ConnectedLineNum: 1001 ConnectedLineName: 1001 AccountCode: Context: main Exten: 2001 Priority: 3 Uniqueid: 1421855327.6 Variable: BRIDGEPVTCALLID Value: 3704122f21547d9b4ea7c725515be0ae@192.168.1.200:5060 [Jan 21 15:48:48] DEBUG[28974] manager.c: Examining AMI event: Event: VarSet Privilege: dialplan,all Channel: SIP/1001-00000003 ChannelState: 6 ChannelStateDesc: Up CallerIDNum: 1003 CallerIDName: 1003 ConnectedLineNum: 1003 ConnectedLineName: 1003 AccountCode: Context: main Exten: Priority: 1 Uniqueid: 1421855327.7 Variable: BRIDGEPEER Value: SIP/1003-00000002 [Jan 21 15:48:48] DEBUG[28974] manager.c: Examining AMI event: Event: VarSet Privilege: dialplan,all Channel: SIP/1001-00000003 ChannelState: 6 ChannelStateDesc: Up CallerIDNum: 1003 CallerIDName: 1003 ConnectedLineNum: 1003 ConnectedLineName: 1003 AccountCode: Context: main Exten: Priority: 1 Uniqueid: 1421855327.7 Variable: BRIDGEPVTCALLID Value: ZjM1ZTJhOWVkMDc2YzhiYjEwNDA3NjYzM2VkOWI5YTc [Jan 21 15:48:48] DEBUG[28998][C-00000001] res_rtp_asterisk.c: Not changing SSRC since we haven't sent any RTP yet [Jan 21 15:48:48] DEBUG[28940] chan_sip.c: = Looking for Call ID: ZjM1ZTJhOWVkMDc2YzhiYjEwNDA3NjYzM2VkOWI5YTc (Checking From) --From tag 20972818 --To-tag as4e5f59ca [Jan 21 15:48:48] DEBUG[28940][C-00000001] chan_sip.c: **** Received ACK (6) - Command in SIP ACK [Jan 21 15:48:48] DEBUG[28940][C-00000001] chan_sip.c: Stopping retransmission on 'ZjM1ZTJhOWVkMDc2YzhiYjEwNDA3NjYzM2VkOWI5YTc' of Response 2: Match Found [Jan 21 15:48:48] DEBUG[28997][C-00000001] res_rtp_asterisk.c: 0xb3f00018 -- Probation learning mode pass with source address 192.168.1.20:51588 [Jan 21 15:48:48] DEBUG[28998][C-00000001] res_rtp_asterisk.c: Ooh, format changed from none to alaw [Jan 21 15:48:48] DEBUG[28998][C-00000001] res_rtp_asterisk.c: Starting RTCP transmission on RTP instance '0xa3995cc' [Jan 21 15:48:49] DEBUG[28998][C-00000001] res_rtp_asterisk.c: 0xaab9950 -- Probation learning mode pass with source address 192.168.1.20:8000 [Jan 21 15:48:49] DEBUG[28997][C-00000001] res_rtp_asterisk.c: Ooh, format changed from none to alaw [Jan 21 15:48:49] DEBUG[28997][C-00000001] res_rtp_asterisk.c: Got RTCP report of 80 bytes [Jan 21 15:48:49] DEBUG[28997][C-00000001] acl.c: Not an IPv4 nor IPv6 address, cannot get port. [Jan 21 15:48:49] DEBUG[28997][C-00000001] netsock2.c: Splitting 'dusty' into... [Jan 21 15:48:49] DEBUG[28997][C-00000001] netsock2.c: ...host 'dusty' and port ''. [Jan 21 15:48:49] DEBUG[28997][C-00000001] acl.c: Not an IPv4 nor IPv6 address, cannot get port. [Jan 21 15:48:49] DEBUG[28997][C-00000001] acl.c: Attached to given IP address [Jan 21 15:48:49] DEBUG[28968] netsock2.c: Splitting '192.168.1.20:51589' into... [Jan 21 15:48:49] DEBUG[28968] netsock2.c: ...host '192.168.1.20' and port '51589'. [Jan 21 15:48:49] DEBUG[28968] netsock2.c: Splitting '192.168.1.200:0' into... [Jan 21 15:48:49] DEBUG[28968] netsock2.c: ...host '192.168.1.200' and port '0'. [Jan 21 15:48:50] DEBUG[28998][C-00000001] res_rtp_asterisk.c: Creating BEGIN DTMF Frame: 35 (#), at 192.168.1.20:8000 [Jan 21 15:48:50] DTMF[28998][C-00000001] channel.c: DTMF begin '#' received on SIP/1001-00000003 [Jan 21 15:48:50] DTMF[28998][C-00000001] channel.c: DTMF begin passthrough '#' on SIP/1001-00000003 [Jan 21 15:48:50] DEBUG[28998][C-00000001] res_rtp_asterisk.c: Setting the marker bit due to a source update [Jan 21 15:48:50] DEBUG[28974] manager.c: Examining AMI event: Event: DTMFBegin Privilege: dtmf,all Channel: SIP/1001-00000003 ChannelState: 6 ChannelStateDesc: Up CallerIDNum: 1003 CallerIDName: 1003 ConnectedLineNum: 1003 ConnectedLineName: 1003 AccountCode: Context: main Exten: Priority: 1 Uniqueid: 1421855327.7 Digit: # Direction: Received [Jan 21 15:48:50] DEBUG[28998][C-00000001] res_rtp_asterisk.c: Creating END DTMF Frame: 35 (#), at 192.168.1.20:8000 [Jan 21 15:48:50] DTMF[28998][C-00000001] channel.c: DTMF end '#' received on SIP/1001-00000003, duration 200 ms [Jan 21 15:48:50] DTMF[28998][C-00000001] channel.c: DTMF end accepted with begin '#' on SIP/1001-00000003 [Jan 21 15:48:50] DTMF[28998][C-00000001] channel.c: DTMF end passthrough '#' on SIP/1001-00000003 [Jan 21 15:48:50] DEBUG[28998][C-00000001] bridge_channel.c: DTMF feature string on 0xa39d9a4(SIP/1001-00000003) is now '#' [Jan 21 15:48:50] DEBUG[28974] manager.c: Examining AMI event: Event: DTMFEnd Privilege: dtmf,all Channel: SIP/1001-00000003 ChannelState: 6 ChannelStateDesc: Up CallerIDNum: 1003 CallerIDName: 1003 ConnectedLineNum: 1003 ConnectedLineName: 1003 AccountCode: Context: main Exten: Priority: 1 Uniqueid: 1421855327.7 Digit: # DurationMs: 200 Direction: Received [Jan 21 15:48:50] NOTICE[28997][C-00000001] res_rtp_asterisk.c: Unknown RTP codec 126 received from '192.168.1.20:51588' [Jan 21 15:48:51] DEBUG[28998][C-00000001] res_rtp_asterisk.c: Creating BEGIN DTMF Frame: 49 (1), at 192.168.1.20:8000 [Jan 21 15:48:51] DTMF[28998][C-00000001] channel.c: DTMF begin '1' received on SIP/1001-00000003 [Jan 21 15:48:51] DTMF[28998][C-00000001] channel.c: DTMF begin ignored '1' on SIP/1001-00000003 [Jan 21 15:48:51] DEBUG[28974] manager.c: Examining AMI event: Event: DTMFBegin Privilege: dtmf,all Channel: SIP/1001-00000003 ChannelState: 6 ChannelStateDesc: Up CallerIDNum: 1003 CallerIDName: 1003 ConnectedLineNum: 1003 ConnectedLineName: 1003 AccountCode: Context: main Exten: Priority: 1 Uniqueid: 1421855327.7 Digit: 1 Direction: Received [Jan 21 15:48:51] DEBUG[28998][C-00000001] res_rtp_asterisk.c: Creating END DTMF Frame: 49 (1), at 192.168.1.20:8000 [Jan 21 15:48:51] DTMF[28998][C-00000001] channel.c: DTMF end '1' received on SIP/1001-00000003, duration 200 ms [Jan 21 15:48:51] DTMF[28998][C-00000001] channel.c: DTMF end passthrough '1' on SIP/1001-00000003 [Jan 21 15:48:51] DEBUG[28998][C-00000001] bridge_channel.c: DTMF feature string on 0xa39d9a4(SIP/1001-00000003) is now '#1' [Jan 21 15:48:51] DEBUG[28998][C-00000001] bridge_channel.c: DTMF feature hook 0xab1868c matched DTMF string '#1' on 0xa39d9a4(SIP/1001-00000003) [Jan 21 15:48:51] DEBUG[28998][C-00000001] channel.c: Set channel SIP/1001-00000003 to write format gsm [Jan 21 15:48:51] DEBUG[28998][C-00000001] res_rtp_asterisk.c: Difference is 5872, ms is 754 [Jan 21 15:48:51] DEBUG[28998][C-00000001] channel.c: Scheduling timer at (50 requested / 50 actual) timer ticks per second [Jan 21 15:48:51] VERBOSE[28998][C-00000001] file.c: Playing 'pbx-transfer.gsm' (language 'en') [Jan 21 15:48:51] DEBUG[28974] manager.c: Examining AMI event: Event: DTMFEnd Privilege: dtmf,all Channel: SIP/1001-00000003 ChannelState: 6 ChannelStateDesc: Up CallerIDNum: 1003 CallerIDName: 1003 ConnectedLineNum: 1003 ConnectedLineName: 1003 AccountCode: Context: main Exten: Priority: 1 Uniqueid: 1421855327.7 Digit: 1 DurationMs: 200 Direction: Received [Jan 21 15:48:51] DEBUG[28974] manager.c: Examining AMI event: Event: Hold Privilege: call,all Channel: SIP/1001-00000003 ChannelState: 6 ChannelStateDesc: Up CallerIDNum: 1003 CallerIDName: 1003 ConnectedLineNum: 1003 ConnectedLineName: 1003 AccountCode: Context: main Exten: Priority: 1 Uniqueid: 1421855327.7 [Jan 21 15:48:51] DEBUG[28997][C-00000001] res_rtp_asterisk.c: Setting the marker bit due to a source update [Jan 21 15:48:51] VERBOSE[28997][C-00000001] res_musiconhold.c: Started music on hold, class 'default', on channel 'SIP/1003-00000002' [Jan 21 15:48:51] DEBUG[28997][C-00000001] channel.c: Scheduling timer at (50 requested / 50 actual) timer ticks per second [Jan 21 15:48:51] DEBUG[28974] manager.c: Examining AMI event: Event: MusicOnHoldStart Privilege: call,all Channel: SIP/1003-00000002 ChannelState: 6 ChannelStateDesc: Up CallerIDNum: 1003 CallerIDName: 1003 ConnectedLineNum: 1001 ConnectedLineName: 1001 AccountCode: Context: main Exten: 2001 Priority: 3 Uniqueid: 1421855327.6 Class: default [Jan 21 15:48:51] DEBUG[28997][C-00000001] channel.c: Set channel SIP/1003-00000002 to write format slin [Jan 21 15:48:51] DEBUG[28997][C-00000001] res_musiconhold.c: SIP/1003-00000002 Opened file 0 '/var/lib/asterisk/moh/OrderlyQ/unity' [Jan 21 15:48:51] DEBUG[28997][C-00000001] res_rtp_asterisk.c: Difference is 5984, ms is 768 [Jan 21 15:48:52] DEBUG[28998][C-00000001] channel.c: Scheduling timer at (0 requested / 0 actual) timer ticks per second [Jan 21 15:48:52] DEBUG[28998][C-00000001] channel.c: Scheduling timer at (0 requested / 0 actual) timer ticks per second [Jan 21 15:48:52] DEBUG[28998][C-00000001] channel.c: Scheduling timer at (0 requested / 0 actual) timer ticks per second [Jan 21 15:48:52] DEBUG[28998][C-00000001] channel.c: Set channel SIP/1001-00000003 to write format alaw [Jan 21 15:48:52] DEBUG[28998][C-00000001] channel.c: Set channel SIP/1001-00000003 to write format slin [Jan 21 15:48:52] DEBUG[28998][C-00000001] channel.c: Scheduling timer at (50 requested / 50 actual) timer ticks per second [Jan 21 15:48:53] DEBUG[28998][C-00000001] res_rtp_asterisk.c: Creating BEGIN DTMF Frame: 50 (2), at 192.168.1.20:8000 [Jan 21 15:48:53] DEBUG[28974] manager.c: Examining AMI event: Event: DTMFBegin Privilege: dtmf,all Channel: SIP/1001-00000003 ChannelState: 6 ChannelStateDesc: Up CallerIDNum: 1003 CallerIDName: 1003 ConnectedLineNum: 1003 ConnectedLineName: 1003 AccountCode: Context: main Exten: Priority: 1 Uniqueid: 1421855327.7 Digit: 2 Direction: Received [Jan 21 15:48:53] DTMF[28998][C-00000001] channel.c: DTMF begin '2' received on SIP/1001-00000003 [Jan 21 15:48:53] DTMF[28998][C-00000001] channel.c: DTMF begin ignored '2' on SIP/1001-00000003 [Jan 21 15:48:53] DEBUG[28998][C-00000001] res_rtp_asterisk.c: Creating END DTMF Frame: 50 (2), at 192.168.1.20:8000 [Jan 21 15:48:53] DEBUG[28974] manager.c: Examining AMI event: Event: DTMFEnd Privilege: dtmf,all Channel: SIP/1001-00000003 ChannelState: 6 ChannelStateDesc: Up CallerIDNum: 1003 CallerIDName: 1003 ConnectedLineNum: 1003 ConnectedLineName: 1003 AccountCode: Context: main Exten: Priority: 1 Uniqueid: 1421855327.7 Digit: 2 DurationMs: 200 Direction: Received [Jan 21 15:48:53] DTMF[28998][C-00000001] channel.c: DTMF end '2' received on SIP/1001-00000003, duration 200 ms [Jan 21 15:48:53] DTMF[28998][C-00000001] channel.c: DTMF end passthrough '2' on SIP/1001-00000003 [Jan 21 15:48:53] DEBUG[28998][C-00000001] channel.c: Set channel SIP/1001-00000003 to write format alaw [Jan 21 15:48:53] DEBUG[28998][C-00000001] channel.c: Scheduling timer at (0 requested / 0 actual) timer ticks per second [Jan 21 15:48:53] DEBUG[28997][C-00000001] res_rtp_asterisk.c: Got RTCP report of 80 bytes [Jan 21 15:48:53] DEBUG[28997][C-00000001] acl.c: Not an IPv4 nor IPv6 address, cannot get port. [Jan 21 15:48:53] DEBUG[28997][C-00000001] netsock2.c: Splitting 'dusty' into... [Jan 21 15:48:53] DEBUG[28997][C-00000001] netsock2.c: ...host 'dusty' and port ''. [Jan 21 15:48:53] DEBUG[28998][C-00000001] res_rtp_asterisk.c: Creating BEGIN DTMF Frame: 48 (0), at 192.168.1.20:8000 [Jan 21 15:48:53] DTMF[28998][C-00000001] channel.c: DTMF begin '0' received on SIP/1001-00000003 [Jan 21 15:48:53] DTMF[28998][C-00000001] channel.c: DTMF begin ignored '0' on SIP/1001-00000003 [Jan 21 15:48:53] DEBUG[28974] manager.c: Examining AMI event: Event: DTMFBegin Privilege: dtmf,all Channel: SIP/1001-00000003 ChannelState: 6 ChannelStateDesc: Up CallerIDNum: 1003 CallerIDName: 1003 ConnectedLineNum: 1003 ConnectedLineName: 1003 AccountCode: Context: main Exten: Priority: 1 Uniqueid: 1421855327.7 Digit: 0 Direction: Received [Jan 21 15:48:53] DEBUG[28997][C-00000001] acl.c: Not an IPv4 nor IPv6 address, cannot get port. [Jan 21 15:48:53] DEBUG[28997][C-00000001] acl.c: Attached to given IP address [Jan 21 15:48:53] DEBUG[28968] netsock2.c: Splitting '192.168.1.20:51589' into... [Jan 21 15:48:53] DEBUG[28968] netsock2.c: ...host '192.168.1.20' and port '51589'. [Jan 21 15:48:53] DEBUG[28968] netsock2.c: Splitting '192.168.1.200:0' into... [Jan 21 15:48:53] DEBUG[28968] netsock2.c: ...host '192.168.1.200' and port '0'. [Jan 21 15:48:53] DEBUG[28940] acl.c: Not an IPv4 nor IPv6 address, cannot get port. [Jan 21 15:48:53] DEBUG[28940] netsock2.c: Splitting 'dusty' into... [Jan 21 15:48:53] DEBUG[28940] netsock2.c: ...host 'dusty' and port ''. [Jan 21 15:48:53] DEBUG[28940] acl.c: Not an IPv4 nor IPv6 address, cannot get port. [Jan 21 15:48:53] DEBUG[28940] acl.c: Attached to given IP address [Jan 21 15:48:53] DEBUG[28940] acl.c: Not an IPv4 nor IPv6 address, cannot get port. [Jan 21 15:48:53] DEBUG[28940] netsock2.c: Splitting 'dusty' into... [Jan 21 15:48:53] DEBUG[28940] netsock2.c: ...host 'dusty' and port ''. [Jan 21 15:48:53] DEBUG[28968] netsock2.c: Splitting '192.168.1.200:0' into... [Jan 21 15:48:53] DEBUG[28968] netsock2.c: ...host '192.168.1.200' and port '0'. [Jan 21 15:48:53] DEBUG[28968] netsock2.c: Splitting '192.168.1.20:51589' into... [Jan 21 15:48:53] DEBUG[28968] netsock2.c: ...host '192.168.1.20' and port '51589'. [Jan 21 15:48:53] DEBUG[28998][C-00000001] res_rtp_asterisk.c: Creating END DTMF Frame: 48 (0), at 192.168.1.20:8000 [Jan 21 15:48:53] DTMF[28998][C-00000001] channel.c: DTMF end '0' received on SIP/1001-00000003, duration 200 ms [Jan 21 15:48:53] DTMF[28998][C-00000001] channel.c: DTMF end passthrough '0' on SIP/1001-00000003 [Jan 21 15:48:53] DEBUG[28974] manager.c: Examining AMI event: Event: DTMFEnd Privilege: dtmf,all Channel: SIP/1001-00000003 ChannelState: 6 ChannelStateDesc: Up CallerIDNum: 1003 CallerIDName: 1003 ConnectedLineNum: 1003 ConnectedLineName: 1003 AccountCode: Context: main Exten: Priority: 1 Uniqueid: 1421855327.7 Digit: 0 DurationMs: 200 Direction: Received [Jan 21 15:48:54] DEBUG[28940] acl.c: Not an IPv4 nor IPv6 address, cannot get port. [Jan 21 15:48:54] DEBUG[28940] acl.c: Attached to given IP address [Jan 21 15:48:54] DEBUG[28968] netsock2.c: Splitting '192.168.1.200:0' into... [Jan 21 15:48:54] DEBUG[28968] netsock2.c: ...host '192.168.1.200' and port '0'. [Jan 21 15:48:54] DEBUG[28968] netsock2.c: Splitting '192.168.1.20:8001' into... [Jan 21 15:48:54] DEBUG[28968] netsock2.c: ...host '192.168.1.20' and port '8001'. [Jan 21 15:48:54] DEBUG[28998][C-00000001] res_rtp_asterisk.c: Creating BEGIN DTMF Frame: 48 (0), at 192.168.1.20:8000 [Jan 21 15:48:54] DTMF[28998][C-00000001] channel.c: DTMF begin '0' received on SIP/1001-00000003 [Jan 21 15:48:54] DTMF[28998][C-00000001] channel.c: DTMF begin ignored '0' on SIP/1001-00000003 [Jan 21 15:48:54] DEBUG[28974] manager.c: Examining AMI event: Event: DTMFBegin Privilege: dtmf,all Channel: SIP/1001-00000003 ChannelState: 6 ChannelStateDesc: Up CallerIDNum: 1003 CallerIDName: 1003 ConnectedLineNum: 1003 ConnectedLineName: 1003 AccountCode: Context: main Exten: Priority: 1 Uniqueid: 1421855327.7 Digit: 0 Direction: Received [Jan 21 15:48:54] DEBUG[28998][C-00000001] res_rtp_asterisk.c: Creating END DTMF Frame: 48 (0), at 192.168.1.20:8000 [Jan 21 15:48:54] DTMF[28998][C-00000001] channel.c: DTMF end '0' received on SIP/1001-00000003, duration 200 ms [Jan 21 15:48:54] DTMF[28998][C-00000001] channel.c: DTMF end passthrough '0' on SIP/1001-00000003 [Jan 21 15:48:54] DEBUG[28974] manager.c: Examining AMI event: Event: DTMFEnd Privilege: dtmf,all Channel: SIP/1001-00000003 ChannelState: 6 ChannelStateDesc: Up CallerIDNum: 1003 CallerIDName: 1003 ConnectedLineNum: 1003 ConnectedLineName: 1003 AccountCode: Context: main Exten: Priority: 1 Uniqueid: 1421855327.7 Digit: 0 DurationMs: 200 Direction: Received [Jan 21 15:48:54] DEBUG[28998][C-00000001] res_rtp_asterisk.c: Creating BEGIN DTMF Frame: 53 (5), at 192.168.1.20:8000 [Jan 21 15:48:54] DTMF[28998][C-00000001] channel.c: DTMF begin '5' received on SIP/1001-00000003 [Jan 21 15:48:54] DTMF[28998][C-00000001] channel.c: DTMF begin ignored '5' on SIP/1001-00000003 [Jan 21 15:48:54] DEBUG[28974] manager.c: Examining AMI event: Event: DTMFBegin Privilege: dtmf,all Channel: SIP/1001-00000003 ChannelState: 6 ChannelStateDesc: Up CallerIDNum: 1003 CallerIDName: 1003 ConnectedLineNum: 1003 ConnectedLineName: 1003 AccountCode: Context: main Exten: Priority: 1 Uniqueid: 1421855327.7 Digit: 5 Direction: Received [Jan 21 15:48:54] DEBUG[28998][C-00000001] res_rtp_asterisk.c: Creating END DTMF Frame: 53 (5), at 192.168.1.20:8000 [Jan 21 15:48:54] DTMF[28998][C-00000001] channel.c: DTMF end '5' received on SIP/1001-00000003, duration 200 ms [Jan 21 15:48:54] DTMF[28998][C-00000001] channel.c: DTMF end passthrough '5' on SIP/1001-00000003 [Jan 21 15:48:54] DEBUG[28998][C-00000001] parking/parking_bridge_features.c: Checking if 2005@main is a parking exten [Jan 21 15:48:54] DEBUG[28998][C-00000001] bridge_channel.c: Setting 0xa39d9a4(SIP/1001-00000003) state from:0 to:2 [Jan 21 15:48:54] DEBUG[28998][C-00000001] res_rtp_asterisk.c: Setting the marker bit due to a source update [Jan 21 15:48:54] DEBUG[28998][C-00000001] bridge_channel.c: Bridge 7d6127b5-7b28-4d6b-b736-0622d802761e: pulling 0xa39d9a4(SIP/1001-00000003) [Jan 21 15:48:54] VERBOSE[28998][C-00000001] bridge_channel.c: Channel SIP/1001-00000003 left 'simple_bridge' basic-bridge <7d6127b5-7b28-4d6b-b736-0622d802761e> [Jan 21 15:48:54] DEBUG[28998][C-00000001] bridge_channel.c: Bridge 7d6127b5-7b28-4d6b-b736-0622d802761e: 0xa39d9a4(SIP/1001-00000003) is leaving simple_bridge technology [Jan 21 15:48:54] DEBUG[28998][C-00000001] dahdi/bridge_native_dahdi.c: Bridge 7d6127b5-7b28-4d6b-b736-0622d802761e: Cannot use native DAHDI. Must have two channels. [Jan 21 15:48:54] DEBUG[28998][C-00000001] bridge.c: Bridge technology native_dahdi is not compatible with properties of existing bridge. [Jan 21 15:48:54] DEBUG[28998][C-00000001] bridge.c: Bridge technology holding_bridge does not have any capabilities we want. [Jan 21 15:48:54] DEBUG[28998][C-00000001] bridge.c: Bridge technology softmix does not have any capabilities we want. [Jan 21 15:48:54] DEBUG[28998][C-00000001] bridge_native_rtp.c: Bridge '7d6127b5-7b28-4d6b-b736-0622d802761e' can not use native RTP bridge as two channels are required [Jan 21 15:48:54] DEBUG[28998][C-00000001] bridge.c: Bridge technology native_rtp is not compatible with properties of existing bridge. [Jan 21 15:48:54] DEBUG[28998][C-00000001] bridge.c: Chose bridge technology simple_bridge [Jan 21 15:48:54] DEBUG[28998][C-00000001] bridge.c: Bridge 7d6127b5-7b28-4d6b-b736-0622d802761e is already using the new technology. [Jan 21 15:48:54] DEBUG[28998][C-00000001] res_rtp_asterisk.c: Changing ssrc from 2033270632 to 139886602 due to a source change [Jan 21 15:48:54] DEBUG[28998][C-00000001] channel.c: Hanging up channel 'SIP/1001-00000003' [Jan 21 15:48:54] DEBUG[28998][C-00000001] chan_sip.c: Hangup call SIP/1001-00000003, SIP callid 3704122f21547d9b4ea7c725515be0ae@192.168.1.200:5060 [Jan 21 15:48:54] DEBUG[28998][C-00000001] chan_sip.c: Updating call counter for outgoing call [Jan 21 15:48:54] DEBUG[28998][C-00000001] res_rtp_asterisk.c: Setting RTCP address on RTP instance '0xa3995cc' [Jan 21 15:48:54] DEBUG[28998][C-00000001] netsock2.c: Splitting '192.168.1.20:5070' into... [Jan 21 15:48:54] DEBUG[28998][C-00000001] netsock2.c: ...host '192.168.1.20' and port '5070'. [Jan 21 15:48:54] DEBUG[28998][C-00000001] chan_sip.c: Trying to put 'BYE sip:100' onto UDP socket destined for 192.168.1.20:5070 [Jan 21 15:48:54] DEBUG[28916] cdr.c: Finalized CDR for SIP/1003-00000002 - start 1421855327.049003 answer 1421855328.917698 end 1421855334.691299 dispo ANSWERED [Jan 21 15:48:54] DEBUG[28916] cdr.c: CDR for SIP/1001-00000003 is dialed and has no Party B; discarding [Jan 21 15:48:54] DEBUG[28915] devicestate.c: No provider found, checking channel drivers for SIP - 1001 [Jan 21 15:48:54] DEBUG[28915] chan_sip.c: Checking device state for peer 1001 [Jan 21 15:48:54] DEBUG[28915] devicestate.c: Changing state for SIP/1001 - state 1 (Not in use) [Jan 21 15:48:54] DEBUG[28915] devicestate.c: No provider found, checking channel drivers for SIP - 1001 [Jan 21 15:48:54] DEBUG[28915] chan_sip.c: Checking device state for peer 1001 [Jan 21 15:48:54] DEBUG[28915] devicestate.c: Changing state for SIP/1001 - state 1 (Not in use) [Jan 21 15:48:54] DEBUG[28974] manager.c: Examining AMI event: Event: DTMFEnd Privilege: dtmf,all Channel: SIP/1001-00000003 ChannelState: 6 ChannelStateDesc: Up CallerIDNum: 1003 CallerIDName: 1003 ConnectedLineNum: 1003 ConnectedLineName: 1003 AccountCode: Context: main Exten: Priority: 1 Uniqueid: 1421855327.7 Digit: 5 DurationMs: 200 Direction: Received [Jan 21 15:48:54] DEBUG[28974] manager.c: Examining AMI event: Event: Unhold Privilege: call,all Channel: SIP/1001-00000003 ChannelState: 6 ChannelStateDesc: Up CallerIDNum: 1003 CallerIDName: 1003 ConnectedLineNum: 1003 ConnectedLineName: 1003 AccountCode: Context: main Exten: Priority: 1 Uniqueid: 1421855327.7 [Jan 21 15:48:54] DEBUG[28974] manager.c: Examining AMI event: Event: VarSet Privilege: dialplan,all Channel: SIP/1003-00000002 ChannelState: 6 ChannelStateDesc: Up CallerIDNum: 1003 CallerIDName: 1003 ConnectedLineNum: 1001 ConnectedLineName: 1001 AccountCode: Context: main Exten: 2001 Priority: 3 Uniqueid: 1421855327.6 Variable: BLINDTRANSFER Value: SIP/1001-00000003 [Jan 21 15:48:54] DEBUG[28974] manager.c: Examining AMI event: Event: VarSet Privilege: dialplan,all Channel: SIP/1001-00000003 ChannelState: 6 ChannelStateDesc: Up CallerIDNum: 1003 CallerIDName: 1003 ConnectedLineNum: 1003 ConnectedLineName: 1003 AccountCode: Context: main Exten: Priority: 1 Uniqueid: 1421855327.7 Variable: BLINDTRANSFER Value: SIP/1003-00000002 [Jan 21 15:48:54] DEBUG[28974] manager.c: Examining AMI event: Event: BlindTransfer Privilege: call,all Result: Success TransfererChannel: SIP/1001-00000003 TransfererChannelState: 6 TransfererChannelStateDesc: Up TransfererCallerIDNum: 1003 TransfererCallerIDName: 1003 TransfererConnectedLineNum: 1003 TransfererConnectedLineName: 1003 TransfererAccountCode: TransfererContext: main TransfererExten: TransfererPriority: 1 TransfererUniqueid: 1421855327.7 TransfereeChannel: SIP/1003-00000002 TransfereeChannelState: 6 TransfereeChannelStateDesc: Up TransfereeCallerIDNum: 1003 TransfereeCallerIDName: 1003 TransfereeConnectedLineNum: 1001 TransfereeConnectedLineName: 1001 TransfereeAccountCode: TransfereeContext: main TransfereeExten: 2001 TransfereePriority: 3 TransfereeUniqueid: 1421855327.6 BridgeUniqueid: 7d6127b5-7b28-4d6b-b736-0622d802761e BridgeType: basic BridgeTechnology: simple_bridge BridgeCreator: BridgeName: BridgeNumChannels: 2 IsExternal: No Context: main Extension: 2005 [Jan 21 15:48:54] DEBUG[28974] manager.c: Examining AMI event: Event: BridgeLeave Privilege: call,all BridgeUniqueid: 7d6127b5-7b28-4d6b-b736-0622d802761e BridgeType: basic BridgeTechnology: simple_bridge BridgeCreator: BridgeName: BridgeNumChannels: 1 Channel: SIP/1001-00000003 ChannelState: 6 ChannelStateDesc: Up CallerIDNum: 1003 CallerIDName: 1003 ConnectedLineNum: 1003 ConnectedLineName: 1003 AccountCode: Context: main Exten: Priority: 1 Uniqueid: 1421855327.7 [Jan 21 15:48:54] DEBUG[28974] manager.c: Examining AMI event: Event: VarSet Privilege: dialplan,all Channel: SIP/1001-00000003 ChannelState: 6 ChannelStateDesc: Up CallerIDNum: 1003 CallerIDName: 1003 ConnectedLineNum: 1003 ConnectedLineName: 1003 AccountCode: Context: main Exten: Priority: 1 Uniqueid: 1421855327.7 Variable: RTPAUDIOQOS Value: ssrc=139886602;themssrc=1630341122;lp=0;rxjitter=0.000000;rxcount=262;txjitter=0.003851;txcount=178;rlp=0;rtt=0.000000 [Jan 21 15:48:54] DEBUG[28974] manager.c: Examining AMI event: Event: VarSet Privilege: dialplan,all Channel: SIP/1001-00000003 ChannelState: 6 ChannelStateDesc: Up CallerIDNum: 1003 CallerIDName: 1003 ConnectedLineNum: 1003 ConnectedLineName: 1003 AccountCode: Context: main Exten: Priority: 1 Uniqueid: 1421855327.7 Variable: RTPAUDIOQOSJITTER Value: minrxjitter=0.000000;maxrxjitter=0.000000;avgrxjitter=0.000000;stdevrxjitter=0.000000;reported_minjitter=0.000000;reported_maxjitter=0.000000;reported_avgjitter=0.000000;reported_stdevjitter=0.000000; [Jan 21 15:48:54] DEBUG[28974] manager.c: Examining AMI event: Event: VarSet Privilege: dialplan,all Channel: SIP/1001-00000003 ChannelState: 6 ChannelStateDesc: Up CallerIDNum: 1003 CallerIDName: 1003 ConnectedLineNum: 1003 ConnectedLineName: 1003 AccountCode: Context: main Exten: Priority: 1 Uniqueid: 1421855327.7 Variable: RTPAUDIOQOSLOSS Value: minrxlost=0.000000;maxrxlost=0.000000;avgrxlost=0.000000;stdevrxlost=0.000000;reported_minlost=0.000000;reported_maxlost=0.000000;reported_avglost=0.000000;reported_stdevlost=0.000000; [Jan 21 15:48:54] DEBUG[28974] manager.c: Examining AMI event: Event: VarSet Privilege: dialplan,all Channel: SIP/1001-00000003 ChannelState: 6 ChannelStateDesc: Up CallerIDNum: 1003 CallerIDName: 1003 ConnectedLineNum: 1003 ConnectedLineName: 1003 AccountCode: Context: main Exten: Priority: 1 Uniqueid: 1421855327.7 Variable: RTPAUDIOQOSRTT Value: minrtt=0.000000;maxrtt=0.000000;avgrtt=0.000000;stdevrtt=0.000000; [Jan 21 15:48:54] DEBUG[28974] manager.c: Examining AMI event: Event: VarSet Privilege: dialplan,all Channel: SIP/1001-00000003 ChannelState: 6 ChannelStateDesc: Up CallerIDNum: 1003 CallerIDName: 1003 ConnectedLineNum: 1003 ConnectedLineName: 1003 AccountCode: Context: main Exten: Priority: 1 Uniqueid: 1421855327.7 Variable: RTPAUDIOQOS Value: ssrc=139886602;themssrc=1630341122;lp=0;rxjitter=0.000000;rxcount=262;txjitter=0.003851;txcount=178;rlp=0;rtt=0.000000 [Jan 21 15:48:54] DEBUG[28974] manager.c: Examining AMI event: Event: Hangup Privilege: call,all Channel: SIP/1001-00000003 ChannelState: 6 ChannelStateDesc: Up CallerIDNum: 1003 CallerIDName: 1003 ConnectedLineNum: 1003 ConnectedLineName: 1003 AccountCode: Context: main Exten: Priority: 1 Uniqueid: 1421855327.7 Cause: 16 Cause-txt: Normal Clearing [Jan 21 15:48:54] DEBUG[28970] app_queue.c: Device 'SIP/1001' changed to state '1' (Not in use) [Jan 21 15:48:54] DEBUG[28974] manager.c: Examining AMI event: Event: DeviceStateChange Privilege: call,all Device: SIP/1001 State: NOT_INUSE [Jan 21 15:48:54] DEBUG[28974] manager.c: Examining AMI event: Event: QueueMemberStatus Privilege: agent,all MemberName: Local/1001@main/n Interface: Local/1001@main/n Membership: dynamic Queue: PlainAE StateInterface: SIP/1001 Penalty: 0 CallsTaken: 0 LastCall: 0 Status: 1 Ringinuse: 1 Paused: 0 [Jan 21 15:48:54] DEBUG[28974] manager.c: Examining AMI event: Event: QueueMemberStatus Privilege: agent,all MemberName: Local/1001@main/n Interface: Local/1001@main/n Membership: dynamic Queue: Sales StateInterface: SIP/1001 Penalty: 0 CallsTaken: 0 LastCall: 0 Status: 1 Ringinuse: 1 Paused: 0 [Jan 21 15:48:54] DEBUG[28974] manager.c: Examining AMI event: Event: QueueMemberStatus Privilege: agent,all MemberName: Local/1001@main/n Interface: Local/1001@main/n Membership: dynamic Queue: CustServ StateInterface: SIP/1001 Penalty: 0 CallsTaken: 0 LastCall: 0 Status: 1 Ringinuse: 1 Paused: 0 [Jan 21 15:48:54] DEBUG[28974] manager.c: Examining AMI event: Event: QueueMemberStatus Privilege: agent,all MemberName: Local/1001@main/n Interface: Local/1001@main/n Membership: dynamic Queue: Plain StateInterface: SIP/1001 Penalty: 0 CallsTaken: 0 LastCall: 0 Status: 1 Ringinuse: 1 Paused: 0 [Jan 21 15:48:54] DEBUG[28997][C-00000001] res_rtp_asterisk.c: Setting the marker bit due to a source update [Jan 21 15:48:54] VERBOSE[28997][C-00000001] res_musiconhold.c: Stopped music on hold on SIP/1003-00000002 [Jan 21 15:48:54] DEBUG[28997][C-00000001] channel.c: Set channel SIP/1003-00000002 to write format alaw [Jan 21 15:48:54] DEBUG[28997][C-00000001] channel.c: Scheduling timer at (0 requested / 0 actual) timer ticks per second [Jan 21 15:48:54] DEBUG[28997][C-00000001] channel.c: Soft-Hanging (0x02) up channel 'SIP/1003-00000002' [Jan 21 15:48:54] DEBUG[28997][C-00000001] bridge_channel.c: Setting 0xa047ac4(SIP/1003-00000002) state from:0 to:1 [Jan 21 15:48:54] DEBUG[28997][C-00000001] bridge_channel.c: Bridge 7d6127b5-7b28-4d6b-b736-0622d802761e: pulling 0xa047ac4(SIP/1003-00000002) [Jan 21 15:48:54] VERBOSE[28997][C-00000001] bridge_channel.c: Channel SIP/1003-00000002 left 'simple_bridge' basic-bridge <7d6127b5-7b28-4d6b-b736-0622d802761e> [Jan 21 15:48:54] DEBUG[28997][C-00000001] bridge_channel.c: Bridge 7d6127b5-7b28-4d6b-b736-0622d802761e: 0xa047ac4(SIP/1003-00000002) is leaving simple_bridge technology [Jan 21 15:48:54] DEBUG[28997][C-00000001] bridge.c: Bridge 7d6127b5-7b28-4d6b-b736-0622d802761e: dissolving bridge with cause 16(Normal Clearing) [Jan 21 15:48:54] DEBUG[28997][C-00000001] bridge.c: Bridge 7d6127b5-7b28-4d6b-b736-0622d802761e: queueing action type:13 sub:1001 [Jan 21 15:48:54] DEBUG[28997][C-00000001] bridge.c: Bridge 7d6127b5-7b28-4d6b-b736-0622d802761e is dissolved, not performing smart bridge operation. [Jan 21 15:48:54] DEBUG[28997][C-00000001] app_dial.c: Exiting with DIALSTATUS=ANSWER. [Jan 21 15:48:54] DEBUG[28997][C-00000001] pbx.c: Result of 'EXTEN' is '2005' [Jan 21 15:48:54] DEBUG[28997][C-00000001] pbx.c: Launching 'NoOp' [Jan 21 15:48:54] VERBOSE[28997][C-00000001] pbx.c: Executing [2005@main:1] NoOp("SIP/1003-00000002", "This is the first priority of 2005") in new stack [Jan 21 15:48:54] DEBUG[28997][C-00000001] pbx.c: Result of 'EXTEN' is '2005' [Jan 21 15:48:54] DEBUG[28997][C-00000001] pbx.c: Result of 'EXTEN' is '2005' [Jan 21 15:48:54] DEBUG[28997][C-00000001] pbx.c: Launching 'NoOp' [Jan 21 15:48:54] VERBOSE[28997][C-00000001] pbx.c: Executing [2005@main:2] NoOp("SIP/1003-00000002", "This is the second priority of 2005 - about to dial SIP/1005") in new stack [Jan 21 15:48:54] DEBUG[28997][C-00000001] pbx.c: Result of 'EXTEN' is '2005' [Jan 21 15:48:54] DEBUG[28997][C-00000001] pbx.c: Launching 'Dial' [Jan 21 15:48:54] VERBOSE[28997][C-00000001] pbx.c: Executing [2005@main:3] Dial("SIP/1003-00000002", "SIP/1005,,rotwh") in new stack [Jan 21 15:48:54] DEBUG[28997][C-00000001] chan_sip.c: Asked to create a SIP channel with formats: (alaw) [Jan 21 15:48:54] DEBUG[28997][C-00000001] chan_sip.c: Allocating new SIP dialog for 2a771f692a84af076fd7185f15bab63c@192.168.1.200:5060 - INVITE (No RTP) [Jan 21 15:48:54] DEBUG[28997][C-00000001] rtp_engine.c: Using engine 'asterisk' for RTP instance '0xa1a0cec' [Jan 21 15:48:54] DEBUG[28997][C-00000001] res_rtp_asterisk.c: Allocated port 12940 for RTP instance '0xa1a0cec' [Jan 21 15:48:54] DEBUG[28997][C-00000001] rtp_engine.c: RTP instance '0xa1a0cec' is setup and ready to go [Jan 21 15:48:54] DEBUG[28997][C-00000001] res_rtp_asterisk.c: Setup RTCP on RTP instance '0xa1a0cec' [Jan 21 15:48:54] VERBOSE[28997][C-00000001] netsock2.c: Using SIP RTP CoS mark 5 [Jan 21 15:48:54] DEBUG[28997][C-00000001] chan_sip.c: Setting NAT on RTP to Off [Jan 21 15:48:54] DEBUG[28997][C-00000001] acl.c: For destination '192.168.1.20', our source address is '192.168.1.200'. [Jan 21 15:48:54] DEBUG[28997][C-00000001] chan_sip.c: Setting AST_TRANSPORT_UDP with address 192.168.1.200:5060 [Jan 21 15:48:54] DEBUG[28997][C-00000001] netsock2.c: Splitting '192.168.1.20' into... [Jan 21 15:48:54] DEBUG[28997][C-00000001] netsock2.c: ...host '192.168.1.20' and port ''. [Jan 21 15:48:54] DEBUG[28997][C-00000001] chan_sip.c: Setting NAT on RTP to Off [Jan 21 15:48:54] DEBUG[28997][C-00000001] chan_sip.c: SIP call-id changed from '2a771f692a84af076fd7185f15bab63c@192.168.1.200:5060' to '5011dd5356e21c6c2be10539376f3cfe@192.168.1.200:5060' [Jan 21 15:48:54] DEBUG[28914][C-00000001] bridge.c: Bridge 7d6127b5-7b28-4d6b-b736-0622d802761e: actually destroying basic bridge, nobody wants it anymore [Jan 21 15:48:54] DEBUG[28914][C-00000001] bridge.c: Bridge 7d6127b5-7b28-4d6b-b736-0622d802761e: calling basic bridge destructor [Jan 21 15:48:54] DEBUG[28914][C-00000001] bridge.c: Bridge 7d6127b5-7b28-4d6b-b736-0622d802761e: calling simple_bridge technology stop [Jan 21 15:48:54] DEBUG[28914][C-00000001] bridge.c: Bridge 7d6127b5-7b28-4d6b-b736-0622d802761e: calling simple_bridge technology destructor [Jan 21 15:48:54] DEBUG[28974] manager.c: Examining AMI event: Event: MusicOnHoldStop Privilege: call,all Channel: SIP/1003-00000002 ChannelState: 6 ChannelStateDesc: Up CallerIDNum: 1003 CallerIDName: 1003 ConnectedLineNum: 1001 ConnectedLineName: 1001 AccountCode: Context: main Exten: 2001 Priority: 3 Uniqueid: 1421855327.6 [Jan 21 15:48:54] DEBUG[28974] manager.c: Examining AMI event: Event: BridgeLeave Privilege: call,all BridgeUniqueid: 7d6127b5-7b28-4d6b-b736-0622d802761e BridgeType: basic BridgeTechnology: simple_bridge BridgeCreator: BridgeName: BridgeNumChannels: 0 Channel: SIP/1003-00000002 ChannelState: 6 ChannelStateDesc: Up CallerIDNum: 1003 CallerIDName: 1003 ConnectedLineNum: 1001 ConnectedLineName: 1001 AccountCode: Context: main Exten: 2001 Priority: 3 Uniqueid: 1421855327.6 FAULT The next event is the broken one. [Jan 21 15:48:54] DEBUG[28974] manager.c: Examining AMI event: Event: Newexten Privilege: call,all Channel: SIP/1003-00000002 ChannelState: 6 ChannelStateDesc: Up CallerIDNum: 1003 CallerIDName: 1003 ConnectedLineNum: 1001 ConnectedLineName: 1001 AccountCode: Context: main Exten: 2005 Priority: 1 Uniqueid: 1421855327.6 Extension: 2005 Application: Dial AppData: SIP/1001,,rotwh [Jan 21 15:48:54] DEBUG[28974] manager.c: Examining AMI event: Event: VarSet Privilege: dialplan,all Channel: SIP/1003-00000002 ChannelState: 6 ChannelStateDesc: Up CallerIDNum: 1003 CallerIDName: 1003 ConnectedLineNum: 1001 ConnectedLineName: 1001 AccountCode: Context: main Exten: 2005 Priority: 1 Uniqueid: 1421855327.6 Variable: DIALSTATUS Value: ANSWER [Jan 21 15:48:54] DEBUG[28974] manager.c: Examining AMI event: Event: Newexten Privilege: call,all Channel: SIP/1003-00000002 ChannelState: 6 ChannelStateDesc: Up CallerIDNum: 1003 CallerIDName: 1003 ConnectedLineNum: 1001 ConnectedLineName: 1001 AccountCode: Context: main Exten: 2005 Priority: 2 Uniqueid: 1421855327.6 Extension: 2005 Application: NoOp AppData: This is the second priority of 2005 - about to dial SIP/1005 [Jan 21 15:48:54] DEBUG[28974] manager.c: Examining AMI event: Event: Newexten Privilege: call,all Channel: SIP/1003-00000002 ChannelState: 6 ChannelStateDesc: Up CallerIDNum: 1003 CallerIDName: 1003 ConnectedLineNum: 1001 ConnectedLineName: 1001 AccountCode: Context: main Exten: 2005 Priority: 3 Uniqueid: 1421855327.6 Extension: 2005 Application: Dial AppData: SIP/1005,,rotwh [Jan 21 15:48:54] DEBUG[28974] manager.c: Examining AMI event: Event: VarSet Privilege: dialplan,all Channel: SIP/1003-00000002 ChannelState: 6 ChannelStateDesc: Up CallerIDNum: 1003 CallerIDName: 1003 ConnectedLineNum: 1001 ConnectedLineName: 1001 AccountCode: Context: main Exten: 2005 Priority: 3 Uniqueid: 1421855327.6 Variable: DIALSTATUS Value: [Jan 21 15:48:54] DEBUG[28974] manager.c: Examining AMI event: Event: VarSet Privilege: dialplan,all Channel: SIP/1003-00000002 ChannelState: 6 ChannelStateDesc: Up CallerIDNum: 1003 CallerIDName: 1003 ConnectedLineNum: 1001 ConnectedLineName: 1001 AccountCode: Context: main Exten: 2005 Priority: 3 Uniqueid: 1421855327.6 Variable: DIALEDPEERNUMBER Value: [Jan 21 15:48:54] DEBUG[28974] manager.c: Examining AMI event: Event: VarSet Privilege: dialplan,all Channel: SIP/1003-00000002 ChannelState: 6 ChannelStateDesc: Up CallerIDNum: 1003 CallerIDName: 1003 ConnectedLineNum: 1001 ConnectedLineName: 1001 AccountCode: Context: main Exten: 2005 Priority: 3 Uniqueid: 1421855327.6 Variable: DIALEDPEERNAME Value: [Jan 21 15:48:54] DEBUG[28974] manager.c: Examining AMI event: Event: VarSet Privilege: dialplan,all Channel: SIP/1003-00000002 ChannelState: 6 ChannelStateDesc: Up CallerIDNum: 1003 CallerIDName: 1003 ConnectedLineNum: 1001 ConnectedLineName: 1001 AccountCode: Context: main Exten: 2005 Priority: 3 Uniqueid: 1421855327.6 Variable: ANSWEREDTIME Value: [Jan 21 15:48:54] DEBUG[28974] manager.c: Examining AMI event: Event: VarSet Privilege: dialplan,all Channel: SIP/1003-00000002 ChannelState: 6 ChannelStateDesc: Up CallerIDNum: 1003 CallerIDName: 1003 ConnectedLineNum: 1001 ConnectedLineName: 1001 AccountCode: Context: main Exten: 2005 Priority: 3 Uniqueid: 1421855327.6 Variable: DIALEDTIME Value: [Jan 21 15:48:54] DEBUG[28974] manager.c: Examining AMI event: Event: BridgeDestroy Privilege: call,all BridgeUniqueid: 7d6127b5-7b28-4d6b-b736-0622d802761e BridgeType: basic BridgeTechnology: simple_bridge BridgeCreator: BridgeName: BridgeNumChannels: 0 [Jan 21 15:48:54] DEBUG[28940] chan_sip.c: = Looking for Call ID: 3704122f21547d9b4ea7c725515be0ae@192.168.1.200:5060 (Checking To) --From tag as64db9253 --To-tag 9905 [Jan 21 15:48:54] DEBUG[28940][C-00000001] chan_sip.c: Stopping retransmission on '3704122f21547d9b4ea7c725515be0ae@192.168.1.200:5060' of Request 103: Match Found [Jan 21 15:48:54] DEBUG[28940] chan_sip.c: Destroying SIP dialog 3704122f21547d9b4ea7c725515be0ae@192.168.1.200:5060 [Jan 21 15:48:54] DEBUG[28940] rtp_engine.c: Destroyed RTP instance '0xa3995cc' [Jan 21 15:48:54] DEBUG[28974] manager.c: Examining AMI event: Event: Newchannel Privilege: call,all Channel: SIP/1005-00000004 ChannelState: 0 ChannelStateDesc: Down CallerIDNum: 1005 CallerIDName: 1005 ConnectedLineNum: ConnectedLineName: AccountCode: Context: main Exten: s Priority: 1 Uniqueid: 1421855334.8 [Jan 21 15:48:54] DEBUG[28997][C-00000001] chan_sip.c: *** Our native formats are (alaw) [Jan 21 15:48:54] DEBUG[28997][C-00000001] chan_sip.c: *** Joint capabilities are (alaw) [Jan 21 15:48:54] DEBUG[28997][C-00000001] chan_sip.c: *** Our capabilities are (alaw) [Jan 21 15:48:54] DEBUG[28997][C-00000001] chan_sip.c: *** AST_CODEC_CHOOSE formats are alaw [Jan 21 15:48:54] DEBUG[28997][C-00000001] chan_sip.c: *** Our preferred formats from the incoming channel are (alaw) [Jan 21 15:48:54] DEBUG[28997][C-00000001] chan_sip.c: This channel will not be able to handle video. [Jan 21 15:48:54] DEBUG[28974] manager.c: Examining AMI event: Event: VarSet Privilege: dialplan,all Channel: SIP/1005-00000004 ChannelState: 0 ChannelStateDesc: Down CallerIDNum: 1005 CallerIDName: 1005 ConnectedLineNum: ConnectedLineName: AccountCode: Context: main Exten: s Priority: 1 Uniqueid: 1421855334.8 Variable: SIPCALLID Value: 5011dd5356e21c6c2be10539376f3cfe@192.168.1.200:5060 [Jan 21 15:48:54] DEBUG[28997][C-00000001] channel_internal_api.c: Channel Call ID changing from [C-00000001] to [C-00000001] [Jan 21 15:48:54] DEBUG[28974] manager.c: Examining AMI event: Event: VarSet Privilege: dialplan,all Channel: SIP/1005-00000004 ChannelState: 0 ChannelStateDesc: Down CallerIDNum: 1005 CallerIDName: 1005 ConnectedLineNum: ConnectedLineName: AccountCode: Context: main Exten: Priority: 1 Uniqueid: 1421855334.8 Variable: DIALEDPEERNUMBER Value: 1005 [Jan 21 15:48:54] DEBUG[28997][C-00000001] rtp_engine.c: Copying payload 0 (0xb3f04fc4) from 0xb45fff04 to 0xa1a0e14 [Jan 21 15:48:54] DEBUG[28997][C-00000001] rtp_engine.c: Copying payload 8 (0xb3f053e4) from 0xb45fff04 to 0xa1a0e14 [Jan 21 15:48:54] DEBUG[28997][C-00000001] rtp_engine.c: Copying payload 9 (0xb3f05804) from 0xb45fff04 to 0xa1a0e14 [Jan 21 15:48:54] DEBUG[28997][C-00000001] rtp_engine.c: Copying payload 100 (0xb3f06044) from 0xb45fff04 to 0xa1a0e14 [Jan 21 15:48:54] DEBUG[28997][C-00000001] rtp_engine.c: Copying payload 101 (0xb45fe5ec) from 0xb45fff04 to 0xa1a0e14 [Jan 21 15:48:54] DEBUG[28997][C-00000001] rtp_engine.c: Seeded SDP of 'SIP/1005-00000004' with that of 'SIP/1003-00000002' [Jan 21 15:48:54] DEBUG[28974] manager.c: Examining AMI event: Event: Newexten Privilege: call,all Channel: SIP/1005-00000004 ChannelState: 0 ChannelStateDesc: Down CallerIDNum: 1003 CallerIDName: 1003 ConnectedLineNum: 1003 ConnectedLineName: 1003 AccountCode: Context: main Exten: 2005 Priority: 1 Uniqueid: 1421855334.8 Extension: 2005 Application: AppDial AppData: (Outgoing Line) [Jan 21 15:48:54] DEBUG[28974] manager.c: Examining AMI event: Event: NewCallerid Privilege: call,all Channel: SIP/1005-00000004 ChannelState: 0 ChannelStateDesc: Down CallerIDNum: 1003 CallerIDName: 1003 ConnectedLineNum: 1003 ConnectedLineName: 1003 AccountCode: Context: main Exten: 2005 Priority: 1 Uniqueid: 1421855334.8 CID-CallingPres: 0 (Presentation Allowed, Not Screened) [Jan 21 15:48:54] DEBUG[28997][C-00000001] chan_sip.c: Outgoing Call for 1005 [Jan 21 15:48:54] DEBUG[28997][C-00000001] chan_sip.c: Updating call counter for outgoing call [Jan 21 15:48:54] DEBUG[28915] devicestate.c: No provider found, checking channel drivers for SIP - 1005 [Jan 21 15:48:54] DEBUG[28915] chan_sip.c: Checking device state for peer 1005 [Jan 21 15:48:54] DEBUG[28915] devicestate.c: Changing state for SIP/1005 - state 6 (Ringing) [Jan 21 15:48:54] DEBUG[28970] app_queue.c: Device 'SIP/1005' changed to state '6' (Ringing) but we don't care because they're not a member of any queue. [Jan 21 15:48:54] DEBUG[28974] manager.c: Examining AMI event: Event: DeviceStateChange Privilege: call,all Device: SIP/1005 State: RINGING [Jan 21 15:48:54] DEBUG[28997][C-00000001] chan_sip.c: ** Our capability: (alaw) Video flag: False Text flag: False [Jan 21 15:48:54] DEBUG[28997][C-00000001] chan_sip.c: ** Our prefcodec: (alaw) [Jan 21 15:48:54] DEBUG[28997][C-00000001] chan_sip.c: -- Done with adding codecs to SDP [Jan 21 15:48:54] DEBUG[28997][C-00000001] chan_sip.c: Done building SDP. Settling with this capability: (alaw) [Jan 21 15:48:54] DEBUG[28997][C-00000001] chan_sip.c: Initializing initreq for method INVITE - callid 5011dd5356e21c6c2be10539376f3cfe@192.168.1.200:5060 [Jan 21 15:48:54] DEBUG[28997][C-00000001] chan_sip.c: Trying to put 'INVITE sip:' onto UDP socket destined for 192.168.1.20:5060 [Jan 21 15:48:54] DEBUG[28974] manager.c: Examining AMI event: Event: DialBegin Privilege: call,all Channel: SIP/1003-00000002 ChannelState: 6 ChannelStateDesc: Up CallerIDNum: 1003 CallerIDName: 1003 ConnectedLineNum: 1001 ConnectedLineName: 1001 AccountCode: Context: main Exten: 2005 Priority: 3 Uniqueid: 1421855327.6 DestChannel: SIP/1005-00000004 DestChannelState: 0 DestChannelStateDesc: Down DestCallerIDNum: 1003 DestCallerIDName: 1003 DestConnectedLineNum: 1003 DestConnectedLineName: 1003 DestAccountCode: DestContext: main DestExten: 2005 DestPriority: 1 DestUniqueid: 1421855334.8 DialString: 1005 [Jan 21 15:48:54] VERBOSE[28997][C-00000001] app_dial.c: Called SIP/1005 [Jan 21 15:48:54] DEBUG[28997][C-00000001] channel.c: Driver for channel 'SIP/1003-00000002' does not support indication 3, emulating it [Jan 21 15:48:54] DEBUG[28997][C-00000001] channel.c: Set channel SIP/1003-00000002 to write format slin [Jan 21 15:48:54] DEBUG[28997][C-00000001] channel.c: Scheduling timer at (50 requested / 50 actual) timer ticks per second [Jan 21 15:48:54] DEBUG[28940] chan_sip.c: = Looking for Call ID: 5011dd5356e21c6c2be10539376f3cfe@192.168.1.200:5060 (Checking To) --From tag as44ff9527 --To-tag [Jan 21 15:48:54] DEBUG[28940][C-00000001] chan_sip.c: (Provisional) Stopping retransmission (but retaining packet) on '5011dd5356e21c6c2be10539376f3cfe@192.168.1.200:5060' Request 102: Found [Jan 21 15:48:54] DEBUG[28940][C-00000001] chan_sip.c: SIP response 100 to standard invite [Jan 21 15:48:54] DEBUG[28940] chan_sip.c: = Looking for Call ID: 5011dd5356e21c6c2be10539376f3cfe@192.168.1.200:5060 (Checking To) --From tag as44ff9527 --To-tag 8d203a8e544fdb9c [Jan 21 15:48:54] DEBUG[28940][C-00000001] chan_sip.c: (Provisional) Stopping retransmission (but retaining packet) on '5011dd5356e21c6c2be10539376f3cfe@192.168.1.200:5060' Request 102: Found [Jan 21 15:48:54] DEBUG[28940][C-00000001] chan_sip.c: SIP response 180 to standard invite [Jan 21 15:48:54] DEBUG[28915] devicestate.c: No provider found, checking channel drivers for SIP - 1005 [Jan 21 15:48:54] DEBUG[28915] chan_sip.c: Checking device state for peer 1005 [Jan 21 15:48:54] DEBUG[28915] devicestate.c: Changing state for SIP/1005 - state 6 (Ringing) [Jan 21 15:48:54] DEBUG[28974] manager.c: Examining AMI event: Event: Newstate Privilege: call,all Channel: SIP/1005-00000004 ChannelState: 5 ChannelStateDesc: Ringing CallerIDNum: 1003 CallerIDName: 1003 ConnectedLineNum: 1003 ConnectedLineName: 1003 AccountCode: Context: main Exten: 2005 Priority: 1 Uniqueid: 1421855334.8 [Jan 21 15:48:54] VERBOSE[28997][C-00000001] app_dial.c: SIP/1005-00000004 is ringing [Jan 21 15:48:54] DEBUG[28997][C-00000001] channel.c: Driver for channel 'SIP/1003-00000002' does not support indication 3, emulating it [Jan 21 15:48:54] DEBUG[28997][C-00000001] channel.c: Set channel SIP/1003-00000002 to write format alaw [Jan 21 15:48:54] DEBUG[28997][C-00000001] channel.c: Set channel SIP/1003-00000002 to write format slin [Jan 21 15:48:54] DEBUG[28997][C-00000001] channel.c: Scheduling timer at (50 requested / 50 actual) timer ticks per second [Jan 21 15:48:55] DEBUG[28974] manager.c: Running action 'Ping' [Jan 21 15:48:55] DEBUG[28940] chan_sip.c: = Looking for Call ID: 8d203a8e5d4eb54e@192.168.1.20 (Checking From) --From tag 8d203a8e5d4eb54d --To-tag [Jan 21 15:48:55] DEBUG[28940] acl.c: For destination '192.168.1.20', our source address is '192.168.1.200'. [Jan 21 15:48:55] DEBUG[28940] chan_sip.c: Setting AST_TRANSPORT_UDP with address 192.168.1.200:5060 [Jan 21 15:48:55] DEBUG[28940] netsock2.c: Splitting '192.168.1.20:5060' into... [Jan 21 15:48:55] DEBUG[28940] netsock2.c: ...host '192.168.1.20' and port '5060'. [Jan 21 15:48:55] DEBUG[28940] chan_sip.c: Allocating new SIP dialog for 8d203a8e5d4eb54e@192.168.1.20 - OPTIONS (No RTP) [Jan 21 15:48:55] DEBUG[28940] chan_sip.c: **** Received OPTIONS (3) - Command in SIP OPTIONS [Jan 21 15:48:55] DEBUG[28940] netsock2.c: Splitting '192.168.1.200' into... [Jan 21 15:48:55] DEBUG[28940] netsock2.c: ...host '192.168.1.200' and port ''. [Jan 21 15:48:55] DEBUG[28940] netsock2.c: Splitting '192.168.1.200' into... [Jan 21 15:48:55] DEBUG[28940] netsock2.c: ...host '192.168.1.200' and port ''. [Jan 21 15:48:55] DEBUG[28940] chan_sip.c: Trying to put 'SIP/2.0 404' onto UDP socket destined for 192.168.1.20:5060