[May 20 15:46:09] DEBUG[10263] chan_sip.c: = Looking for Call ID: OTZjZjQwN2Q3ZmM4NzYwODlkNGY3YmNiN2IyM2ZlMmE. (Checking From) --From tag 3503644a --To-tag [May 20 15:46:09] DEBUG[10263] acl.c: For destination '555.555.9.134', our source address is '555.555.35.6'. [May 20 15:46:09] DEBUG[10263] chan_sip.c: Setting SIP_TRANSPORT_UDP with address 555.555.35.6:5060 [May 20 15:46:09] DEBUG[10263] netsock2.c: Splitting '444.444.2.47:33518' into... [May 20 15:46:09] DEBUG[10263] netsock2.c: ...host '444.444.2.47' and port '33518'. [May 20 15:46:09] DEBUG[10263] chan_sip.c: NAT detected for 444.444.2.47 / 555.555.9.134 [May 20 15:46:09] DEBUG[10263] chan_sip.c: Allocating new SIP dialog for OTZjZjQwN2Q3ZmM4NzYwODlkNGY3YmNiN2IyM2ZlMmE. - INVITE (No RTP) [May 20 15:46:09] DEBUG[10263][C-00000010] chan_sip.c: **** Received INVITE (5) - Command in SIP INVITE [May 20 15:46:09] DEBUG[10263][C-00000010] netsock2.c: Splitting '444.444.2.47:33518' into... [May 20 15:46:09] DEBUG[10263][C-00000010] netsock2.c: ...host '444.444.2.47' and port '33518'. [May 20 15:46:09] DEBUG[10263][C-00000010] chan_sip.c: NAT detected for 444.444.2.47 / 555.555.9.134 [May 20 15:46:09] DEBUG[10263][C-00000010] netsock2.c: Splitting 'mypbx.mydomain.net' into... [May 20 15:46:09] DEBUG[10263][C-00000010] netsock2.c: ...host 'mypbx.mydomain.net' and port ''. [May 20 15:46:09] DEBUG[10263][C-00000010] chan_sip.c: Trying to put 'SIP/2.0 401' onto UDP socket destined for 555.555.9.134:56018 [May 20 15:46:09] DEBUG[10263] chan_sip.c: = Looking for Call ID: OTZjZjQwN2Q3ZmM4NzYwODlkNGY3YmNiN2IyM2ZlMmE. (Checking From) --From tag 3503644a --To-tag as3795c042 [May 20 15:46:09] DEBUG[10263][C-00000010] chan_sip.c: **** Received ACK (6) - Command in SIP ACK [May 20 15:46:09] DEBUG[10263][C-00000010] chan_sip.c: Stopping retransmission on 'OTZjZjQwN2Q3ZmM4NzYwODlkNGY3YmNiN2IyM2ZlMmE.' of Response 1: Match Found [May 20 15:46:09] DEBUG[10263] chan_sip.c: = Looking for Call ID: OTZjZjQwN2Q3ZmM4NzYwODlkNGY3YmNiN2IyM2ZlMmE. (Checking From) --From tag 3503644a --To-tag [May 20 15:46:09] DEBUG[10263] netsock2.c: Splitting 'mypbx.mydomain.net' into... [May 20 15:46:09] DEBUG[10263] netsock2.c: ...host 'mypbx.mydomain.net' and port ''. [May 20 15:46:09] DEBUG[10263] netsock2.c: Splitting 'mypbx.mydomain.net' into... [May 20 15:46:09] DEBUG[10263] netsock2.c: ...host 'mypbx.mydomain.net' and port ''. [May 20 15:46:09] DEBUG[10263][C-00000010] chan_sip.c: **** Received INVITE (5) - Command in SIP INVITE [May 20 15:46:09] DEBUG[10263][C-00000010] netsock2.c: Splitting '444.444.2.47:33518' into... [May 20 15:46:09] DEBUG[10263][C-00000010] netsock2.c: ...host '444.444.2.47' and port '33518'. [May 20 15:46:09] DEBUG[10263][C-00000010] chan_sip.c: NAT detected for 444.444.2.47 / 555.555.9.134 [May 20 15:46:09] DEBUG[10263][C-00000010] netsock2.c: Splitting 'mypbx.mydomain.net' into... [May 20 15:46:09] DEBUG[10263][C-00000010] netsock2.c: ...host 'mypbx.mydomain.net' and port ''. [May 20 15:46:09] DEBUG[10263][C-00000010] rtp_engine.c: Using engine 'asterisk' for RTP instance '0xb730056c' [May 20 15:46:09] DEBUG[10263][C-00000010] res_rtp_asterisk.c: Allocated port 11258 for RTP instance '0xb730056c' [May 20 15:46:09] DEBUG[10263][C-00000010] netsock2.c: Splitting '333.333.33.242' into... [May 20 15:46:09] DEBUG[10263][C-00000010] netsock2.c: ...host '333.333.33.242' and port ''. [May 20 15:46:09] DEBUG[10263][C-00000010] netsock2.c: Splitting '555.555.35.6' into... [May 20 15:46:09] DEBUG[10263][C-00000010] netsock2.c: ...host '555.555.35.6' and port ''. [May 20 15:46:09] DEBUG[10263][C-00000010] netsock2.c: Splitting '555.555.35.6' into... [May 20 15:46:09] DEBUG[10263][C-00000010] netsock2.c: ...host '555.555.35.6' and port ''. [May 20 15:46:09] DEBUG[10263][C-00000010] netsock2.c: Splitting '333.333.33.242' into... [May 20 15:46:09] DEBUG[10263][C-00000010] netsock2.c: ...host '333.333.33.242' and port ''. [May 20 15:46:09] DEBUG[10263][C-00000010] rtp_engine.c: RTP instance '0xb730056c' is setup and ready to go [May 20 15:46:09] DEBUG[10263][C-00000010] rtp_engine.c: Using engine 'asterisk' for RTP instance '0xb73cc48c' [May 20 15:46:09] DEBUG[10263][C-00000010] res_rtp_asterisk.c: Allocated port 15258 for RTP instance '0xb73cc48c' [May 20 15:46:09] DEBUG[10263][C-00000010] netsock2.c: Splitting '333.333.33.242' into... [May 20 15:46:09] DEBUG[10263][C-00000010] netsock2.c: ...host '333.333.33.242' and port ''. [May 20 15:46:09] DEBUG[10263][C-00000010] netsock2.c: Splitting '555.555.35.6' into... [May 20 15:46:09] DEBUG[10263][C-00000010] netsock2.c: ...host '555.555.35.6' and port ''. [May 20 15:46:09] DEBUG[10263][C-00000010] netsock2.c: Splitting '555.555.35.6' into... [May 20 15:46:09] DEBUG[10263][C-00000010] netsock2.c: ...host '555.555.35.6' and port ''. [May 20 15:46:09] DEBUG[10263][C-00000010] netsock2.c: Splitting '333.333.33.242' into... [May 20 15:46:09] DEBUG[10263][C-00000010] netsock2.c: ...host '333.333.33.242' and port ''. [May 20 15:46:09] DEBUG[10263][C-00000010] rtp_engine.c: RTP instance '0xb73cc48c' is setup and ready to go [May 20 15:46:09] DEBUG[10263][C-00000010] res_rtp_asterisk.c: Setup RTCP on RTP instance '0xb73cc48c' [May 20 15:46:09] DEBUG[10263][C-00000010] res_rtp_asterisk.c: Setup RTCP on RTP instance '0xb730056c' [May 20 15:46:09] DEBUG[10263][C-00000010] chan_sip.c: Setting NAT on RTP to On [May 20 15:46:09] DEBUG[10263][C-00000010] chan_sip.c: Setting NAT on VRTP to On [May 20 15:46:09] DEBUG[10263][C-00000010] chan_sip.c: Processing session-level SDP v=0... UNSUPPORTED OR FAILED. [May 20 15:46:09] DEBUG[10263][C-00000010] chan_sip.c: Processing session-level SDP o=- 1 2 IN IP4 444.444.2.47... OK. [May 20 15:46:09] DEBUG[10263][C-00000010] chan_sip.c: Processing session-level SDP s=CounterPath eyeBeam 1.5... UNSUPPORTED OR FAILED. [May 20 15:46:09] DEBUG[10263][C-00000010] netsock2.c: Splitting '444.444.2.47' into... [May 20 15:46:09] DEBUG[10263][C-00000010] netsock2.c: ...host '444.444.2.47' and port ''. [May 20 15:46:09] DEBUG[10263][C-00000010] chan_sip.c: Processing session-level SDP c=IN IP4 444.444.2.47... OK. [May 20 15:46:09] DEBUG[10263][C-00000010] chan_sip.c: Processing session-level SDP t=0 0... UNSUPPORTED OR FAILED. [May 20 15:46:09] DEBUG[10263][C-00000010] rtp_engine.c: Setting payload 0 based on m type on 0xb6518d80 [May 20 15:46:09] DEBUG[10263][C-00000010] rtp_engine.c: Setting payload 101 based on m type on 0xb6518d80 [May 20 15:46:09] DEBUG[10263][C-00000010] chan_sip.c: Processing media-level (audio) SDP a=alt:1 2 : ep6zQLOH 2IXymzQt 192.168.0.2 39586... UNSUPPORTED OR FAILED. [May 20 15:46:09] DEBUG[10263][C-00000010] chan_sip.c: Processing media-level (audio) SDP a=alt:2 1 : vPooViqx S/yhoeWI 444.444.2.47 39586... UNSUPPORTED OR FAILED. [May 20 15:46:09] DEBUG[10263][C-00000010] chan_sip.c: Processing media-level (audio) SDP a=fmtp:101 0-15... UNSUPPORTED OR FAILED. [May 20 15:46:09] DEBUG[10263][C-00000010] chan_sip.c: Processing media-level (audio) SDP a=rtpmap:101 telephone-event/8000... OK. [May 20 15:46:09] DEBUG[10263][C-00000010] chan_sip.c: Processing media-level (audio) SDP a=sendrecv... OK. [May 20 15:46:09] DEBUG[10263][C-00000010] rtp_engine.c: Setting payload 123 based on m type on 0xb6514a3c [May 20 15:46:09] DEBUG[10263][C-00000010] rtp_engine.c: Setting payload 124 based on m type on 0xb6514a3c [May 20 15:46:09] DEBUG[10263][C-00000010] chan_sip.c: Processing media-level (video) SDP a=alt:1 2 : 9jCXUmgq f9Z9SNfy 192.168.0.2 55864... UNSUPPORTED OR FAILED. [May 20 15:46:09] DEBUG[10263][C-00000010] chan_sip.c: Processing media-level (video) SDP a=alt:2 1 : t+DUslc9 lZDYmJga 444.444.2.47 55864... UNSUPPORTED OR FAILED. [May 20 15:46:09] DEBUG[10263][C-00000010] chan_sip.c: Processing media-level (video) SDP a=fmtp:123 profile-level-id=42801e; packetization-mode=0; max-mbps=48600... UNSUPPORTED OR FAILED. [May 20 15:46:09] DEBUG[10263][C-00000010] chan_sip.c: Processing media-level (video) SDP a=fmtp:124 profile-level-id=42801e; packetization-mode=1; max-mbps=48600... UNSUPPORTED OR FAILED. [May 20 15:46:09] DEBUG[10263][C-00000010] chan_sip.c: Processing media-level (video) SDP a=rtpmap:123 H264/90000... OK. [May 20 15:46:09] DEBUG[10263][C-00000010] chan_sip.c: Processing media-level (video) SDP a=rtpmap:124 H264/90000... OK. [May 20 15:46:09] DEBUG[10263][C-00000010] chan_sip.c: Processing media-level (video) SDP a=sendrecv... UNSUPPORTED OR FAILED. [May 20 15:46:09] DEBUG[10263][C-00000010] res_rtp_asterisk.c: Setting RTCP address on RTP instance '0xb730056c' [May 20 15:46:09] DEBUG[10263][C-00000010] rtp_engine.c: Copying payload 0 from 0xb6518d80 to 0xb7300718 [May 20 15:46:09] DEBUG[10263][C-00000010] rtp_engine.c: Copying payload 101 from 0xb6518d80 to 0xb7300718 [May 20 15:46:09] DEBUG[10263][C-00000010] res_rtp_asterisk.c: Ignoring duplicate RTCP property on RTP instance '0xb730056c' [May 20 15:46:09] DEBUG[10263][C-00000010] res_rtp_asterisk.c: Setting RTCP address on RTP instance '0xb73cc48c' [May 20 15:46:09] DEBUG[10263][C-00000010] rtp_engine.c: Copying payload 123 from 0xb6514a3c to 0xb73cc638 [May 20 15:46:09] DEBUG[10263][C-00000010] rtp_engine.c: Copying payload 124 from 0xb6514a3c to 0xb73cc638 [May 20 15:46:09] DEBUG[10263][C-00000010] chan_sip.c: We're settling with these formats: (ulaw|h264) [May 20 15:46:09] DEBUG[10263][C-00000010] chan_sip.c: Checking SIP call limits for device 556 [May 20 15:46:09] DEBUG[10263][C-00000010] chan_sip.c: Updating call counter for incoming call [May 20 15:46:09] DEBUG[10253] devicestate.c: No provider found, checking channel drivers for SIP - 556 [May 20 15:46:09] DEBUG[10263][C-00000010] netsock2.c: Splitting 'mypbx.mydomain.net' into... [May 20 15:46:09] DEBUG[10263][C-00000010] netsock2.c: ...host 'mypbx.mydomain.net' and port ''. [May 20 15:46:09] DEBUG[10253] chan_sip.c: Checking device state for peer 556 [May 20 15:46:09] DEBUG[10263][C-00000010] netsock2.c: Splitting 'mypbx.mydomain.net' into... [May 20 15:46:09] DEBUG[10253] devicestate.c: Changing state for SIP/556 - state 2 (In use) [May 20 15:46:09] DEBUG[10263][C-00000010] netsock2.c: ...host 'mypbx.mydomain.net' and port ''. [May 20 15:46:09] DEBUG[10253] devicestate.c: device 'SIP/556' state '2' [May 20 15:46:09] DEBUG[10255] devicestate.c: No provider found, checking channel drivers for SIP - wsp_556 [May 20 15:46:09] DEBUG[10255] chan_sip.c: Checking device state for peer wsp_556 [May 20 15:46:09] DEBUG[10255] devicestate.c: Checking if I can find provider for "Custom" - number: DND_556 [May 20 15:46:09] DEBUG[10255] devicestate.c: Checking provider Custom with Custom [May 20 15:46:09] DEBUG[10255] db.c: Unable to find key 'DND_556' in family 'CustomDevstate' [May 20 15:46:09] DEBUG[10294] devicestate.c: device 'Queue:camp_556_avail' state '2' [May 20 15:46:09] DEBUG[10294] app_queue.c: Device 'SIP/556' changed to state '2' (In use) [May 20 15:46:09] DEBUG[10347] manager.c: Examining event: Event: QueueMemberStatus Privilege: agent,all Queue: camp_556 Location: SIP/556 MemberName: SIP/556 StateInterface: SIP/556 Membership: static Penalty: 0 CallsTaken: 0 LastCall: 0 Status: 2 Paused: 0 [May 20 15:46:09] DEBUG[10347] manager.c: Examining event: Event: ExtensionStatus Privilege: call,all Exten: 556 Context: localusers Hint: SIP/556&SIP/wsp_556&Custom:DND_556 Status: 1 [May 20 15:46:09] DEBUG[10255] app_queue.c: Extension '556@localusers' changed to state '2' (In use) but we don't care because they're not a member of any queue. [May 20 15:46:09] DEBUG[10294] app_queue.c: Device 'Queue:camp_556_avail' changed to state '2' (In use) but we don't care because they're not a member of any queue. [May 20 15:46:09] DEBUG[10263][C-00000010] chan_sip.c: *** Our native formats are (ulaw|h264) [May 20 15:46:09] DEBUG[10263][C-00000010] chan_sip.c: *** Joint capabilities are (ulaw|h264) [May 20 15:46:09] DEBUG[10263][C-00000010] chan_sip.c: *** Our capabilities are (ulaw|g729|g722|h264) [May 20 15:46:09] DEBUG[10263][C-00000010] chan_sip.c: *** AST_CODEC_CHOOSE formats are ulaw [May 20 15:46:09] DEBUG[10263][C-00000010] chan_sip.c: This channel can handle video! HOLLYWOOD next! [May 20 15:46:09] DEBUG[10347] manager.c: Examining event: Event: Newchannel Privilege: call,all Channel: SIP/556-00000004 ChannelState: 0 ChannelStateDesc: Down CallerIDNum: 556 CallerIDName: test 2 AccountCode: Exten: 855 Context: outbounduser556 Uniqueid: 1432154769.4 [May 20 15:46:09] DEBUG[10263][C-00000010] chan_sip.c: build_route: Contact hop: [May 20 15:46:09] DEBUG[10263][C-00000010] chan_sip.c: SIP/556-00000004: New call is still down.... Trying... [May 20 15:46:09] DEBUG[10263][C-00000010] chan_sip.c: Trying to put 'SIP/2.0 100' onto UDP socket destined for 555.555.9.134:56018 [May 20 15:46:09] DEBUG[10253] devicestate.c: No provider found, checking channel drivers for SIP - 556 [May 20 15:46:09] DEBUG[10253] chan_sip.c: Checking device state for peer 556 [May 20 15:46:09] DEBUG[10253] devicestate.c: Changing state for SIP/556 - state 2 (In use) [May 20 15:46:09] DEBUG[10253] devicestate.c: device 'SIP/556' state '2' [May 20 15:46:09] DEBUG[10347] manager.c: Examining event: Event: Newstate Privilege: call,all Channel: SIP/556-00000004 ChannelState: 4 ChannelStateDesc: Ring CallerIDNum: 556 CallerIDName: test 2 ConnectedLineNum: ConnectedLineName: Uniqueid: 1432154769.4 [May 20 15:46:09] DEBUG[4929][C-00000010] pbx.c: Launching 'Playback' [May 20 15:46:09] DEBUG[10253] devicestate.c: No provider found, checking channel drivers for SIP - 556 [May 20 15:46:09] DEBUG[10253] chan_sip.c: Checking device state for peer 556 [May 20 15:46:09] DEBUG[10253] devicestate.c: Changing state for SIP/556 - state 2 (In use) [May 20 15:46:09] DEBUG[10253] devicestate.c: device 'SIP/556' state '2' [May 20 15:46:09] DEBUG[10347] manager.c: Examining event: Event: Newstate Privilege: call,all Channel: SIP/556-00000004 ChannelState: 6 ChannelStateDesc: Up CallerIDNum: 556 CallerIDName: test 2 ConnectedLineNum: ConnectedLineName: Uniqueid: 1432154769.4 [May 20 15:46:09] DEBUG[4929][C-00000010] chan_sip.c: SIP answering channel: SIP/556-00000004 [May 20 15:46:09] DEBUG[4929][C-00000010] res_rtp_asterisk.c: Setting the marker bit due to a source update [May 20 15:46:09] DEBUG[4929][C-00000010] chan_sip.c: Setting framing from config on incoming call [May 20 15:46:09] DEBUG[4929][C-00000010] chan_sip.c: This call needs video offers! [May 20 15:46:09] DEBUG[4929][C-00000010] chan_sip.c: ** Our capability: (ulaw|h264) Video flag: False Text flag: True [May 20 15:46:09] DEBUG[4929][C-00000010] chan_sip.c: ** Our prefcodec: (nothing) [May 20 15:46:09] DEBUG[4929][C-00000010] chan_sip.c: -- Done with adding codecs to SDP [May 20 15:46:09] DEBUG[4929][C-00000010] chan_sip.c: Done building SDP. Settling with this capability: (ulaw|h264) [May 20 15:46:09] DEBUG[4929][C-00000010] chan_sip.c: Trying to put 'SIP/2.0 200' onto UDP socket destined for 555.555.9.134:56018 [May 20 15:46:09] DEBUG[10245] res_odbc.c: odbc_release_obj2(0xa44762c) called (obj->txf = (nil)) [May 20 15:46:09] DEBUG[10255] devicestate.c: No provider found, checking channel drivers for SIP - wsp_556 [May 20 15:46:09] DEBUG[10255] chan_sip.c: Checking device state for peer wsp_556 [May 20 15:46:09] DEBUG[10255] devicestate.c: Checking if I can find provider for "Custom" - number: DND_556 [May 20 15:46:09] DEBUG[10255] devicestate.c: Checking provider Custom with Custom [May 20 15:46:09] DEBUG[10255] db.c: Unable to find key 'DND_556' in family 'CustomDevstate' [May 20 15:46:09] DEBUG[10294] devicestate.c: device 'Queue:camp_556_avail' state '2' [May 20 15:46:09] DEBUG[10255] devicestate.c: No provider found, checking channel drivers for SIP - wsp_556 [May 20 15:46:09] DEBUG[10255] chan_sip.c: Checking device state for peer wsp_556 [May 20 15:46:09] DEBUG[10255] devicestate.c: Checking if I can find provider for "Custom" - number: DND_556 [May 20 15:46:09] DEBUG[10255] devicestate.c: Checking provider Custom with Custom [May 20 15:46:09] DEBUG[10294] app_queue.c: Device 'SIP/556' changed to state '2' (In use) [May 20 15:46:09] DEBUG[10255] db.c: Unable to find key 'DND_556' in family 'CustomDevstate' [May 20 15:46:09] DEBUG[10347] manager.c: Examining event: Event: QueueMemberStatus Privilege: agent,all Queue: camp_556 Location: SIP/556 MemberName: SIP/556 StateInterface: SIP/556 Membership: static Penalty: 0 CallsTaken: 0 LastCall: 0 Status: 2 Paused: 0 [May 20 15:46:09] DEBUG[10347] manager.c: Examining event: Event: QueueMemberStatus Privilege: agent,all Queue: camp_556 Location: SIP/556 MemberName: SIP/556 StateInterface: SIP/556 Membership: static Penalty: 0 CallsTaken: 0 LastCall: 0 Status: 2 Paused: 0 [May 20 15:46:09] DEBUG[10294] devicestate.c: device 'Queue:camp_556_avail' state '2' [May 20 15:46:09] DEBUG[10294] app_queue.c: Device 'SIP/556' changed to state '2' (In use) [May 20 15:46:09] DEBUG[4929][C-00000010] res_rtp_asterisk.c: Got RTCP report of 132 bytes [May 20 15:46:09] DEBUG[4929][C-00000010] res_rtp_asterisk.c: Got RTCP report of 132 bytes [May 20 15:46:09] DEBUG[10245] res_odbc.c: odbc_release_obj2(0xa44762c) called (obj->txf = (nil)) [May 20 15:46:09] DEBUG[10294] app_queue.c: Device 'Queue:camp_556_avail' changed to state '2' (In use) but we don't care because they're not a member of any queue. [May 20 15:46:09] DEBUG[10294] app_queue.c: Device 'Queue:camp_556_avail' changed to state '2' (In use) but we don't care because they're not a member of any queue. [May 20 15:46:09] DEBUG[4929][C-00000010] res_rtp_asterisk.c: 0xb732c7a0 -- Probation learning mode pass with source address 555.555.9.134:3107 [May 20 15:46:09] DEBUG[4929][C-00000010] res_rtp_asterisk.c: Setting RTCP address on RTP instance '0xb730056c' [May 20 15:46:09] DEBUG[4929][C-00000010] channel.c: Set channel SIP/556-00000004 to write format h264 [May 20 15:46:09] WARNING[4929][C-00000010] file.c: Unable to open /var/tmp/8 (format (ulaw|h264)): No such file or directory [May 20 15:46:09] WARNING[4929][C-00000010] app_playback.c: ast_streamfile failed on SIP/556-00000004 for /var/tmp/8 [May 20 15:46:09] DEBUG[4929][C-00000010] channel.c: Soft-Hanging up channel 'SIP/556-00000004' [May 20 15:46:09] DEBUG[10347] manager.c: Examining event: Event: SoftHangupRequest Privilege: call,all Channel: SIP/556-00000004 Uniqueid: 1432154769.4 Cause: 16 [May 20 15:46:09] DEBUG[4929][C-00000010] channel.c: Hanging up channel 'SIP/556-00000004' [May 20 15:46:09] DEBUG[4929][C-00000010] chan_sip.c: Hangup call SIP/556-00000004, SIP callid OTZjZjQwN2Q3ZmM4NzYwODlkNGY3YmNiN2IyM2ZlMmE. [May 20 15:46:09] DEBUG[4929][C-00000010] chan_sip.c: Updating call counter for incoming call [May 20 15:46:09] DEBUG[10253] devicestate.c: No provider found, checking channel drivers for SIP - 556 [May 20 15:46:09] DEBUG[10253] chan_sip.c: Checking device state for peer 556 [May 20 15:46:09] DEBUG[10253] devicestate.c: Changing state for SIP/556 - state 1 (Not in use) [May 20 15:46:09] DEBUG[10253] devicestate.c: device 'SIP/556' state '1' [May 20 15:46:09] DEBUG[4929][C-00000010] res_rtp_asterisk.c: Setting RTCP address on RTP instance '0xb730056c' [May 20 15:46:09] DEBUG[4929][C-00000010] res_rtp_asterisk.c: Setting RTCP address on RTP instance '0xb73cc48c' [May 20 15:46:09] DEBUG[10347] manager.c: Examining event: Event: Hangup Privilege: call,all Channel: SIP/556-00000004 Uniqueid: 1432154769.4 CallerIDNum: 556 CallerIDName: test 2 ConnectedLineNum: ConnectedLineName: AccountCode: Cause: 0 Cause-txt: Unknown [May 20 15:46:09] DEBUG[10245] res_odbc.c: odbc_release_obj2(0xa44762c) called (obj->txf = (nil)) [May 20 15:46:09] DEBUG[10255] devicestate.c: No provider found, checking channel drivers for SIP - wsp_556 [May 20 15:46:09] DEBUG[10255] chan_sip.c: Checking device state for peer wsp_556 [May 20 15:46:09] DEBUG[10255] devicestate.c: Checking if I can find provider for "Custom" - number: DND_556 [May 20 15:46:09] DEBUG[10255] devicestate.c: Checking provider Custom with Custom [May 20 15:46:09] DEBUG[10255] db.c: Unable to find key 'DND_556' in family 'CustomDevstate' [May 20 15:46:09] DEBUG[10294] devicestate.c: device 'Queue:camp_556_avail' state '1' [May 20 15:46:09] DEBUG[10294] app_queue.c: Device 'SIP/556' changed to state '1' (Not in use) [May 20 15:46:09] DEBUG[10255] app_queue.c: Extension '556@localusers' changed to state '1' (Not in use) but we don't care because they're not a member of any queue. [May 20 15:46:09] DEBUG[10347] manager.c: Examining event: Event: QueueMemberStatus Privilege: agent,all Queue: camp_556 Location: SIP/556 MemberName: SIP/556 StateInterface: SIP/556 Membership: static Penalty: 0 CallsTaken: 0 LastCall: 0 Status: 1 Paused: 0 [May 20 15:46:09] DEBUG[10347] manager.c: Examining event: Event: ExtensionStatus Privilege: call,all Exten: 556 Context: localusers Hint: SIP/556&SIP/wsp_556&Custom:DND_556 Status: 0 [May 20 15:46:09] DEBUG[10294] app_queue.c: Device 'Queue:camp_556_avail' changed to state '1' (Not in use) but we don't care because they're not a member of any queue. [May 20 15:46:09] DEBUG[4929][C-00000010] res_odbc.c: odbc_release_obj2(0xa44762c) called (obj->txf = (nil)) [May 20 15:46:09] DEBUG[10253] devicestate.c: No provider found, checking channel drivers for SIP - 556 [May 20 15:46:09] DEBUG[10253] chan_sip.c: Checking device state for peer 556 [May 20 15:46:09] DEBUG[10253] devicestate.c: Changing state for SIP/556 - state 1 (Not in use) [May 20 15:46:09] DEBUG[10253] devicestate.c: device 'SIP/556' state '1' [May 20 15:46:09] DEBUG[10263] chan_sip.c: = Looking for Call ID: OTZjZjQwN2Q3ZmM4NzYwODlkNGY3YmNiN2IyM2ZlMmE. (Checking From) --From tag 3503644a --To-tag as009dea1c [May 20 15:46:09] DEBUG[10263][C-00000010] chan_sip.c: **** Received ACK (6) - Command in SIP ACK [May 20 15:46:09] DEBUG[10263][C-00000010] chan_sip.c: Stopping retransmission on 'OTZjZjQwN2Q3ZmM4NzYwODlkNGY3YmNiN2IyM2ZlMmE.' of Response 2: Match Found [May 20 15:46:09] DEBUG[10263][C-00000010] netsock2.c: Splitting '555.555.9.134:56018' into... [May 20 15:46:09] DEBUG[10263][C-00000010] netsock2.c: ...host '555.555.9.134' and port '56018'. [May 20 15:46:09] DEBUG[10263][C-00000010] chan_sip.c: Trying to put 'BYE sip:556' onto UDP socket destined for 555.555.9.134:56018 [May 20 15:46:09] DEBUG[10245] res_odbc.c: odbc_release_obj2(0xa44762c) called (obj->txf = (nil)) [May 20 15:46:09] DEBUG[10245] res_odbc.c: odbc_release_obj2(0xa44762c) called (obj->txf = (nil)) [May 20 15:46:09] DEBUG[10255] devicestate.c: No provider found, checking channel drivers for SIP - wsp_556 [May 20 15:46:09] DEBUG[10255] chan_sip.c: Checking device state for peer wsp_556 [May 20 15:46:09] DEBUG[10255] devicestate.c: Checking if I can find provider for "Custom" - number: DND_556 [May 20 15:46:09] DEBUG[10255] devicestate.c: Checking provider Custom with Custom [May 20 15:46:09] DEBUG[10255] db.c: Unable to find key 'DND_556' in family 'CustomDevstate' [May 20 15:46:09] DEBUG[10294] devicestate.c: device 'Queue:camp_556_avail' state '1' [May 20 15:46:09] DEBUG[10347] manager.c: Examining event: Event: QueueMemberStatus Privilege: agent,all Queue: camp_556 Location: SIP/556 MemberName: SIP/556 StateInterface: SIP/556 Membership: static Penalty: 0 CallsTaken: 0 LastCall: 0 Status: 1 Paused: 0 [May 20 15:46:09] DEBUG[10294] app_queue.c: Device 'SIP/556' changed to state '1' (Not in use) [May 20 15:46:09] DEBUG[10294] app_queue.c: Device 'Queue:camp_556_avail' changed to state '1' (Not in use) but we don't care because they're not a member of any queue. [May 20 15:46:09] DEBUG[10263] chan_sip.c: = Looking for Call ID: OTZjZjQwN2Q3ZmM4NzYwODlkNGY3YmNiN2IyM2ZlMmE. (Checking To) --From tag as009dea1c --To-tag 3503644a [May 20 15:46:09] DEBUG[10263][C-00000010] chan_sip.c: Stopping retransmission on 'OTZjZjQwN2Q3ZmM4NzYwODlkNGY3YmNiN2IyM2ZlMmE.' of Request 102: Match Found [May 20 15:46:09] DEBUG[10263] chan_sip.c: Destroying SIP dialog OTZjZjQwN2Q3ZmM4NzYwODlkNGY3YmNiN2IyM2ZlMmE. [May 20 15:46:09] DEBUG[10263] rtp_engine.c: Destroyed RTP instance '0xb730056c' [May 20 15:46:09] DEBUG[10263] rtp_engine.c: Destroyed RTP instance '0xb73cc48c' [May 20 15:46:17] DEBUG[10263] chan_sip.c: Destroying SIP dialog 11b54ecf5e1ed42e30084eab7b43bd84@555.555.17.166:5060