[2014-08-22 17:38:44] Asterisk 12.5.0 built by root @ sipqa on a x86_64 running Linux on 2014-08-22 21:32:56 UTC [2014-08-22 17:38:44] DEBUG[13197] config.c: Parsing /etc/asterisk/logger.conf [2014-08-22 17:38:44] VERBOSE[13197] config.c: == Parsing '/etc/asterisk/logger.conf': Found [2014-08-22 17:38:44] VERBOSE[13197] logger.c: Asterisk Queue Logger restarted [2014-08-22 17:38:51] DEBUG[13323] chan_sip.c: Auto destroying SIP dialog 'rH5G4.5Z4AFS.OXeGscU-joNtCzg4RMD' [2014-08-22 17:38:51] DEBUG[13323] chan_sip.c: Destroying SIP dialog rH5G4.5Z4AFS.OXeGscU-joNtCzg4RMD [2014-08-22 17:39:00] NOTICE[13218] phone_message.c: Pruning session for device at 'sip:192.168.5.107:5060;ob' due to inactivity. [2014-08-22 17:39:02] DEBUG[13323] chan_sip.c: Auto destroying SIP dialog 'X77u9yEm7pY4HicZ5OAmxnrAKbuzj3D0' [2014-08-22 17:39:02] DEBUG[13323] chan_sip.c: Destroying SIP dialog X77u9yEm7pY4HicZ5OAmxnrAKbuzj3D0 [2014-08-22 17:39:05] DEBUG[13323] chan_sip.c: = Looking for Call ID: MTI0NDU5ZDkxNDJmNzdlYzhmMzU3OGI0NzJlY2Q3ODE (Checking From) --From tag 87fc1f02 --To-tag [2014-08-22 17:39:05] DEBUG[13323] acl.c: For destination '192.168.5.5', our source address is '192.168.5.105'. [2014-08-22 17:39:05] DEBUG[13323] chan_sip.c: Setting AST_TRANSPORT_UDP with address 192.168.5.105:5060 [2014-08-22 17:39:05] DEBUG[13323] netsock2.c: Splitting '192.168.5.5:12948' into... [2014-08-22 17:39:05] DEBUG[13323] netsock2.c: ...host '192.168.5.5' and port '12948'. [2014-08-22 17:39:05] DEBUG[13323] chan_sip.c: Allocating new SIP dialog for MTI0NDU5ZDkxNDJmNzdlYzhmMzU3OGI0NzJlY2Q3ODE - INVITE (No RTP) [2014-08-22 17:39:05] DEBUG[13323][C-00000001] chan_sip.c: **** Received INVITE (5) - Command in SIP INVITE [2014-08-22 17:39:05] DEBUG[13323][C-00000001] sip/reqresp_parser.c: Begin: parsing SIP "Supported: replaces" [2014-08-22 17:39:05] DEBUG[13323][C-00000001] sip/reqresp_parser.c: Found SIP option: -replaces- [2014-08-22 17:39:05] DEBUG[13323][C-00000001] sip/reqresp_parser.c: Matched SIP option: replaces [2014-08-22 17:39:05] DEBUG[13323][C-00000001] netsock2.c: Splitting '192.168.5.5:12948' into... [2014-08-22 17:39:05] DEBUG[13323][C-00000001] netsock2.c: ...host '192.168.5.5' and port '12948'. [2014-08-22 17:39:05] DEBUG[13323][C-00000001] netsock2.c: Splitting 'sipqa.mmhatch.com' into... [2014-08-22 17:39:05] DEBUG[13323][C-00000001] netsock2.c: ...host 'sipqa.mmhatch.com' and port ''. [2014-08-22 17:39:05] DEBUG[13323][C-00000001] chan_sip.c: Trying to put 'SIP/2.0 401' onto UDP socket destined for 192.168.5.5:12948 [2014-08-22 17:39:05] DEBUG[13323] chan_sip.c: = Looking for Call ID: MTI0NDU5ZDkxNDJmNzdlYzhmMzU3OGI0NzJlY2Q3ODE (Checking From) --From tag 87fc1f02 --To-tag as694dd9d9 [2014-08-22 17:39:05] DEBUG[13333] manager.c: Examining AMI event: Event: ChallengeSent Privilege: security,all SystemName: sipqa EventTV: 2014-08-22T17:39:05.660-0500 Severity: Informational Service: SIP EventVersion: 1 AccountID: sip:mlcm800@sipqa.mmhatch.com SessionID: 0x7ffc34003658 LocalAddress: IPV4/UDP/192.168.5.105/5060 RemoteAddress: IPV4/UDP/192.168.5.5/12948 Challenge: 30551c1e [2014-08-22 17:39:05] DEBUG[13323][C-00000001] chan_sip.c: **** Received ACK (6) - Command in SIP ACK [2014-08-22 17:39:05] DEBUG[13323][C-00000001] chan_sip.c: Stopping retransmission on 'MTI0NDU5ZDkxNDJmNzdlYzhmMzU3OGI0NzJlY2Q3ODE' of Response 1: Match Found [2014-08-22 17:39:05] DEBUG[13323] chan_sip.c: = Looking for Call ID: MTI0NDU5ZDkxNDJmNzdlYzhmMzU3OGI0NzJlY2Q3ODE (Checking From) --From tag 87fc1f02 --To-tag [2014-08-22 17:39:05] DEBUG[13323] netsock2.c: Splitting 'sipqa.mmhatch.com' into... [2014-08-22 17:39:05] DEBUG[13323] netsock2.c: ...host 'sipqa.mmhatch.com' and port ''. [2014-08-22 17:39:05] DEBUG[13323] netsock2.c: Splitting 'sipqa.mmhatch.com' into... [2014-08-22 17:39:05] DEBUG[13323] netsock2.c: ...host 'sipqa.mmhatch.com' and port ''. [2014-08-22 17:39:05] DEBUG[13323][C-00000001] chan_sip.c: **** Received INVITE (5) - Command in SIP INVITE [2014-08-22 17:39:05] DEBUG[13323][C-00000001] netsock2.c: Splitting '192.168.5.5:12948' into... [2014-08-22 17:39:05] DEBUG[13323][C-00000001] netsock2.c: ...host '192.168.5.5' and port '12948'. [2014-08-22 17:39:05] DEBUG[13323][C-00000001] netsock2.c: Splitting 'sipqa.mmhatch.com' into... [2014-08-22 17:39:05] DEBUG[13323][C-00000001] netsock2.c: ...host 'sipqa.mmhatch.com' and port ''. [2014-08-22 17:39:05] DEBUG[13323][C-00000001] rtp_engine.c: Using engine 'asterisk' for RTP instance '0x7ffc340627b8' [2014-08-22 17:39:05] DEBUG[13323][C-00000001] res_rtp_asterisk.c: Allocated port 26866 for RTP instance '0x7ffc340627b8' [2014-08-22 17:39:05] DEBUG[13323][C-00000001] netsock2.c: Splitting '192.168.5.105' into... [2014-08-22 17:39:05] DEBUG[13323][C-00000001] netsock2.c: ...host '192.168.5.105' and port ''. [2014-08-22 17:39:05] DEBUG[13323][C-00000001] rtp_engine.c: RTP instance '0x7ffc340627b8' is setup and ready to go [2014-08-22 17:39:05] DEBUG[13323][C-00000001] res_rtp_asterisk.c: Setup RTCP on RTP instance '0x7ffc340627b8' [2014-08-22 17:39:05] VERBOSE[13323][C-00000001] netsock2.c: == Using SIP RTP CoS mark 5 [2014-08-22 17:39:05] DEBUG[13323][C-00000001] chan_sip.c: Setting NAT on RTP to Off [2014-08-22 17:39:05] DEBUG[13323][C-00000001] chan_sip.c: Processing session-level SDP v=0... UNSUPPORTED OR FAILED. [2014-08-22 17:39:05] DEBUG[13323][C-00000001] chan_sip.c: Processing session-level SDP o=- 1408747145448580 1 IN IP4 192.168.5.5... OK. [2014-08-22 17:39:05] DEBUG[13323][C-00000001] chan_sip.c: Processing session-level SDP s=Bria 3 release 3.5.5 stamp 71243... UNSUPPORTED OR FAILED. [2014-08-22 17:39:05] DEBUG[13323][C-00000001] netsock2.c: Splitting '192.168.5.5' into... [2014-08-22 17:39:05] DEBUG[13323][C-00000001] netsock2.c: ...host '192.168.5.5' and port ''. [2014-08-22 17:39:05] DEBUG[13323][C-00000001] chan_sip.c: Processing session-level SDP c=IN IP4 192.168.5.5... OK. [2014-08-22 17:39:05] DEBUG[13323][C-00000001] chan_sip.c: Processing session-level SDP t=0 0... UNSUPPORTED OR FAILED. [2014-08-22 17:39:05] DEBUG[13323][C-00000001] rtp_engine.c: Setting payload 123 based on m type on 0x7ffdd844df30 [2014-08-22 17:39:05] DEBUG[13323][C-00000001] rtp_engine.c: Setting payload 121 based on m type on 0x7ffdd844df30 [2014-08-22 17:39:05] DEBUG[13323][C-00000001] rtp_engine.c: Setting payload 9 based on m type on 0x7ffdd844df30 [2014-08-22 17:39:05] DEBUG[13323][C-00000001] rtp_engine.c: Setting payload 0 based on m type on 0x7ffdd844df30 [2014-08-22 17:39:05] DEBUG[13323][C-00000001] rtp_engine.c: Setting payload 8 based on m type on 0x7ffdd844df30 [2014-08-22 17:39:05] DEBUG[13323][C-00000001] rtp_engine.c: Setting payload 18 based on m type on 0x7ffdd844df30 [2014-08-22 17:39:05] DEBUG[13323][C-00000001] rtp_engine.c: Setting payload 101 based on m type on 0x7ffdd844df30 [2014-08-22 17:39:05] DEBUG[13323][C-00000001] chan_sip.c: Processing media-level (audio) SDP a=rtpmap:123 opus/48000/2... OK. [2014-08-22 17:39:05] DEBUG[13323][C-00000001] chan_sip.c: Processing media-level (audio) SDP a=fmtp:123 useinbandfec=1... OK. [2014-08-22 17:39:05] DEBUG[13323][C-00000001] rtp_engine.c: Unsetting payload 121 on 0x7ffdd844df30 [2014-08-22 17:39:05] DEBUG[13323][C-00000001] chan_sip.c: Processing media-level (audio) SDP a=rtpmap:121 SILK/16000... UNSUPPORTED OR FAILED. [2014-08-22 17:39:05] DEBUG[13323][C-00000001] chan_sip.c: Processing media-level (audio) SDP a=rtpmap:18 G729/8000... OK. [2014-08-22 17:39:05] DEBUG[13323][C-00000001] chan_sip.c: Processing media-level (audio) SDP a=fmtp:18 annexb=yes... OK. [2014-08-22 17:39:05] DEBUG[13323][C-00000001] chan_sip.c: Processing media-level (audio) SDP a=rtpmap:101 telephone-event/8000... OK. [2014-08-22 17:39:05] DEBUG[13323][C-00000001] chan_sip.c: Processing media-level (audio) SDP a=fmtp:101 0-15... UNSUPPORTED OR FAILED. [2014-08-22 17:39:05] DEBUG[13323][C-00000001] chan_sip.c: Processing media-level (audio) SDP a=sendrecv... OK. [2014-08-22 17:39:05] DEBUG[13323][C-00000001] res_rtp_asterisk.c: Setting RTCP address on RTP instance '0x7ffc340627b8' [2014-08-22 17:39:05] DEBUG[13323][C-00000001] rtp_engine.c: Copying payload 0 from 0x7ffdd844df30 to 0x7ffc340628f8 [2014-08-22 17:39:05] DEBUG[13323][C-00000001] rtp_engine.c: Copying payload 8 from 0x7ffdd844df30 to 0x7ffc340628f8 [2014-08-22 17:39:05] DEBUG[13323][C-00000001] rtp_engine.c: Copying payload 9 from 0x7ffdd844df30 to 0x7ffc340628f8 [2014-08-22 17:39:05] DEBUG[13323][C-00000001] rtp_engine.c: Copying payload 18 from 0x7ffdd844df30 to 0x7ffc340628f8 [2014-08-22 17:39:05] DEBUG[13323][C-00000001] rtp_engine.c: Copying payload 101 from 0x7ffdd844df30 to 0x7ffc340628f8 [2014-08-22 17:39:05] DEBUG[13323][C-00000001] rtp_engine.c: Copying payload 123 from 0x7ffdd844df30 to 0x7ffc340628f8 [2014-08-22 17:39:05] DEBUG[13323][C-00000001] res_rtp_asterisk.c: Ignoring duplicate RTCP property on RTP instance '0x7ffc340627b8' [2014-08-22 17:39:05] DEBUG[13323][C-00000001] chan_sip.c: We're settling with these formats: (ulaw|alaw) [2014-08-22 17:39:05] DEBUG[13323][C-00000001] chan_sip.c: Checking SIP call limits for device mlcm800 [2014-08-22 17:39:05] DEBUG[13323][C-00000001] chan_sip.c: Updating call counter for incoming call [2014-08-22 17:39:05] DEBUG[13323][C-00000001] netsock2.c: Splitting 'sipqa.mmhatch.com' into... [2014-08-22 17:39:05] DEBUG[13205] devicestate.c: No provider found, checking channel drivers for SIP - mlcm800 [2014-08-22 17:39:05] DEBUG[13323][C-00000001] netsock2.c: ...host 'sipqa.mmhatch.com' and port ''. [2014-08-22 17:39:05] DEBUG[13205] chan_sip.c: Checking device state for peer mlcm800 [2014-08-22 17:39:05] DEBUG[13323][C-00000001] netsock2.c: Splitting 'sipqa.mmhatch.com' into... [2014-08-22 17:39:05] DEBUG[13205] devicestate.c: Changing state for SIP/mlcm800 - state 2 (In use) [2014-08-22 17:39:05] DEBUG[13323][C-00000001] netsock2.c: ...host 'sipqa.mmhatch.com' and port ''. [2014-08-22 17:39:05] DEBUG[13330] app_queue.c: Device 'SIP/mlcm800' changed to state '2' (In use) but we don't care because they're not a member of any queue. [2014-08-22 17:39:05] DEBUG[13333] manager.c: Examining AMI event: Event: Newchannel Privilege: call,all SystemName: sipqa Channel: SIP/mlcm800-00000000 ChannelState: 0 ChannelStateDesc: Down CallerIDNum: mlcm800 CallerIDName: Mitch ConnectedLineNum: ConnectedLineName: AccountCode: Context: LocalSets Exten: 850 Priority: 1 Uniqueid: sipqa-1408747145.1 [2014-08-22 17:39:05] DEBUG[13323][C-00000001] chan_sip.c: *** Our native formats are (ulaw) [2014-08-22 17:39:05] DEBUG[13323][C-00000001] chan_sip.c: *** Joint capabilities are (ulaw|alaw) [2014-08-22 17:39:05] DEBUG[13323][C-00000001] chan_sip.c: *** Our capabilities are (ulaw|alaw) [2014-08-22 17:39:05] DEBUG[13323][C-00000001] chan_sip.c: *** AST_CODEC_CHOOSE formats are ulaw [2014-08-22 17:39:05] DEBUG[13323][C-00000001] chan_sip.c: This channel will not be able to handle video. [2014-08-22 17:39:05] DEBUG[13333] manager.c: Examining AMI event: Event: VarSet Privilege: dialplan,all SystemName: sipqa Channel: SIP/mlcm800-00000000 ChannelState: 0 ChannelStateDesc: Down CallerIDNum: mlcm800 CallerIDName: Mitch ConnectedLineNum: ConnectedLineName: AccountCode: Context: LocalSets Exten: 850 Priority: 1 Uniqueid: sipqa-1408747145.1 Variable: SIPURI Value: sip:mlcm800@192.168.5.5:12948 [2014-08-22 17:39:05] DEBUG[13333] manager.c: Examining AMI event: Event: VarSet Privilege: dialplan,all SystemName: sipqa Channel: SIP/mlcm800-00000000 ChannelState: 0 ChannelStateDesc: Down CallerIDNum: mlcm800 CallerIDName: Mitch ConnectedLineNum: ConnectedLineName: AccountCode: Context: LocalSets Exten: 850 Priority: 1 Uniqueid: sipqa-1408747145.1 Variable: SIPDOMAIN Value: sipqa.mmhatch.com [2014-08-22 17:39:05] DEBUG[13333] manager.c: Examining AMI event: Event: VarSet Privilege: dialplan,all SystemName: sipqa Channel: SIP/mlcm800-00000000 ChannelState: 0 ChannelStateDesc: Down CallerIDNum: mlcm800 CallerIDName: Mitch ConnectedLineNum: ConnectedLineName: AccountCode: Context: LocalSets Exten: 850 Priority: 1 Uniqueid: sipqa-1408747145.1 Variable: SIPCALLID Value: MTI0NDU5ZDkxNDJmNzdlYzhmMzU3OGI0NzJlY2Q3ODE [2014-08-22 17:39:05] DEBUG[13323][C-00000001] chan_sip.c: build_route: Contact hop: [2014-08-22 17:39:05] DEBUG[13323][C-00000001] chan_sip.c: SIP/mlcm800-00000000: New call is still down.... Trying... [2014-08-22 17:39:05] DEBUG[13323][C-00000001] chan_sip.c: Trying to put 'SIP/2.0 100' onto UDP socket destined for 192.168.5.5:12948 [2014-08-22 17:39:05] DEBUG[13333] manager.c: Examining AMI event: Event: Newstate Privilege: call,all SystemName: sipqa Channel: SIP/mlcm800-00000000 ChannelState: 4 ChannelStateDesc: Ring CallerIDNum: mlcm800 CallerIDName: Mitch ConnectedLineNum: ConnectedLineName: AccountCode: Context: LocalSets Exten: 850 Priority: 1 Uniqueid: sipqa-1408747145.1 [2014-08-22 17:39:05] DEBUG[13205] devicestate.c: No provider found, checking channel drivers for SIP - mlcm800 [2014-08-22 17:39:05] DEBUG[13205] chan_sip.c: Checking device state for peer mlcm800 [2014-08-22 17:39:05] DEBUG[13205] devicestate.c: Changing state for SIP/mlcm800 - state 2 (In use) [2014-08-22 17:39:05] DEBUG[13335][C-00000001] pbx.c: Launching 'NoOp' [2014-08-22 17:39:05] VERBOSE[13335][C-00000001] pbx.c: -- Executing [850@LocalSets:1] NoOp("SIP/mlcm800-00000000", "") in new stack [2014-08-22 17:39:05] DEBUG[13333] manager.c: Examining AMI event: Event: Newexten Privilege: call,all SystemName: sipqa Channel: SIP/mlcm800-00000000 ChannelState: 4 ChannelStateDesc: Ring CallerIDNum: mlcm800 CallerIDName: Mitch ConnectedLineNum: ConnectedLineName: AccountCode: Context: LocalSets Exten: 850 Priority: 1 Uniqueid: sipqa-1408747145.1 Extension: 850 Application: NoOp AppData: [2014-08-22 17:39:05] DEBUG[13335][C-00000001] pbx.c: Launching 'Playback' [2014-08-22 17:39:05] VERBOSE[13335][C-00000001] pbx.c: -- Executing [850@LocalSets:2] Playback("SIP/mlcm800-00000000", "custom/confroom") in new stack [2014-08-22 17:39:05] DEBUG[13333] manager.c: Examining AMI event: Event: Newexten Privilege: call,all SystemName: sipqa Channel: SIP/mlcm800-00000000 ChannelState: 4 ChannelStateDesc: Ring CallerIDNum: mlcm800 CallerIDName: Mitch ConnectedLineNum: ConnectedLineName: AccountCode: Context: LocalSets Exten: 850 Priority: 2 Uniqueid: sipqa-1408747145.1 Extension: 850 Application: Playback AppData: custom/confroom [2014-08-22 17:39:05] DEBUG[13333] manager.c: Examining AMI event: Event: Newstate Privilege: call,all SystemName: sipqa Channel: SIP/mlcm800-00000000 ChannelState: 6 ChannelStateDesc: Up CallerIDNum: mlcm800 CallerIDName: Mitch ConnectedLineNum: ConnectedLineName: AccountCode: Context: LocalSets Exten: 850 Priority: 2 Uniqueid: sipqa-1408747145.1 [2014-08-22 17:39:05] DEBUG[13205] devicestate.c: No provider found, checking channel drivers for SIP - mlcm800 [2014-08-22 17:39:05] DEBUG[13335][C-00000001] chan_sip.c: SIP answering channel: SIP/mlcm800-00000000 [2014-08-22 17:39:05] DEBUG[13205] chan_sip.c: Checking device state for peer mlcm800 [2014-08-22 17:39:05] DEBUG[13335][C-00000001] res_rtp_asterisk.c: Setting the marker bit due to a source update [2014-08-22 17:39:05] DEBUG[13205] devicestate.c: Changing state for SIP/mlcm800 - state 2 (In use) [2014-08-22 17:39:05] DEBUG[13335][C-00000001] chan_sip.c: Setting framing from config on incoming call [2014-08-22 17:39:05] DEBUG[13335][C-00000001] chan_sip.c: ** Our capability: (ulaw|alaw) Video flag: True Text flag: True [2014-08-22 17:39:05] DEBUG[13335][C-00000001] chan_sip.c: ** Our prefcodec: (nothing) [2014-08-22 17:39:05] DEBUG[13335][C-00000001] chan_sip.c: -- Done with adding codecs to SDP [2014-08-22 17:39:05] DEBUG[13335][C-00000001] chan_sip.c: Done building SDP. Settling with this capability: (ulaw|alaw) [2014-08-22 17:39:05] DEBUG[13335][C-00000001] chan_sip.c: Trying to put 'SIP/2.0 200' onto UDP socket destined for 192.168.5.5:12948 [2014-08-22 17:39:05] DEBUG[13323] chan_sip.c: = Looking for Call ID: MTI0NDU5ZDkxNDJmNzdlYzhmMzU3OGI0NzJlY2Q3ODE (Checking From) --From tag 87fc1f02 --To-tag as433fda8a [2014-08-22 17:39:05] DEBUG[13323][C-00000001] chan_sip.c: **** Received ACK (6) - Command in SIP ACK [2014-08-22 17:39:05] DEBUG[13323][C-00000001] chan_sip.c: Stopping retransmission on 'MTI0NDU5ZDkxNDJmNzdlYzhmMzU3OGI0NzJlY2Q3ODE' of Response 2: Match Found [2014-08-22 17:39:05] DEBUG[13335][C-00000001] res_rtp_asterisk.c: 0x7ffc34008ff0 -- Probation learning mode pass with source address 192.168.5.5:61154 [2014-08-22 17:39:05] VERBOSE[13335][C-00000001] res_rtp_asterisk.c: > 0x7ffc34008ff0 -- Probation passed - setting RTP source address to 192.168.5.5:61154 [2014-08-22 17:39:05] DEBUG[13335][C-00000001] channel.c: Set channel SIP/mlcm800-00000000 to write format slin [2014-08-22 17:39:05] DEBUG[13335][C-00000001] res_rtp_asterisk.c: Ooh, format changed from unknown to ulaw [2014-08-22 17:39:05] DEBUG[13335][C-00000001] res_rtp_asterisk.c: Created smoother: format: ulaw ms: 20 len: 160 [2014-08-22 17:39:05] DEBUG[13335][C-00000001] channel.c: Scheduling timer at (50 requested / 50 actual) timer ticks per second [2014-08-22 17:39:05] VERBOSE[13335][C-00000001] file.c: -- Playing 'custom/confroom.slin' (language 'en') [2014-08-22 17:39:05] DEBUG[13335][C-00000001] res_rtp_asterisk.c: Got RTCP report of 80 bytes [2014-08-22 17:39:05] DEBUG[13335][C-00000001] acl.c: Not an IPv4 nor IPv6 address, cannot get port. [2014-08-22 17:39:05] DEBUG[13335][C-00000001] netsock2.c: Splitting 'sipqa' into... [2014-08-22 17:39:05] DEBUG[13335][C-00000001] netsock2.c: ...host 'sipqa' and port ''. [2014-08-22 17:39:05] DEBUG[13335][C-00000001] acl.c: Multiple addresses. Using the first only [2014-08-22 17:39:05] DEBUG[13335][C-00000001] acl.c: Not an IPv4 nor IPv6 address, cannot get port. [2014-08-22 17:39:05] DEBUG[13335][C-00000001] acl.c: Attached to given IP address [2014-08-22 17:39:05] DEBUG[13333] manager.c: Examining AMI event: Event: RTCPReceived Privilege: reporting,all SystemName: sipqa Channel: SIP/mlcm800-00000000 ChannelState: 6 ChannelStateDesc: Up CallerIDNum: mlcm800 CallerIDName: Mitch ConnectedLineNum: ConnectedLineName: AccountCode: Context: LocalSets Exten: 850 Priority: 2 Uniqueid: sipqa-1408747145.1 To: 127.0.1.1:0 From: 192.168.5.5:61155 RTT: 0.0000 SSRC: 0x271ede02 PT: 200(SR) ReportCount: 1 SentNTP: 1408747145.17539853836288 SentRTP: 2397925307 SentPackets: 4 SentOctets: 640 Report0SourceSSRC: 0x5d521743 Report0FractionLost: 0 Report0CumulativeLost: 0 Report0HighestSequence: 49004 Report0SequenceNumberCycles: 0 Report0IAJitter: 0 Report0LSR: 0 Report0DLSR: 0.0000 [2014-08-22 17:39:06] DEBUG[13335][C-00000001] channel.c: Scheduling timer at (138 requested / 138 actual) timer ticks per second [2014-08-22 17:39:07] DEBUG[13335][C-00000001] channel.c: Scheduling timer at (0 requested / 0 actual) timer ticks per second [2014-08-22 17:39:07] DEBUG[13335][C-00000001] channel.c: Scheduling timer at (0 requested / 0 actual) timer ticks per second [2014-08-22 17:39:07] DEBUG[13335][C-00000001] channel.c: Scheduling timer at (0 requested / 0 actual) timer ticks per second [2014-08-22 17:39:07] DEBUG[13335][C-00000001] channel.c: Set channel SIP/mlcm800-00000000 to write format ulaw [2014-08-22 17:39:07] DEBUG[13333] manager.c: Examining AMI event: Event: VarSet Privilege: dialplan,all SystemName: sipqa Channel: SIP/mlcm800-00000000 ChannelState: 6 ChannelStateDesc: Up CallerIDNum: mlcm800 CallerIDName: Mitch ConnectedLineNum: ConnectedLineName: AccountCode: Context: LocalSets Exten: 850 Priority: 2 Uniqueid: sipqa-1408747145.1 Variable: PLAYBACKSTATUS Value: SUCCESS [2014-08-22 17:39:07] DEBUG[13335][C-00000001] pbx.c: Result of 'EXTEN' is '850' [2014-08-22 17:39:07] DEBUG[13335][C-00000001] pbx.c: Launching 'SayDigits' [2014-08-22 17:39:07] VERBOSE[13335][C-00000001] pbx.c: -- Executing [850@LocalSets:3] SayDigits("SIP/mlcm800-00000000", "850") in new stack [2014-08-22 17:39:07] DEBUG[13333] manager.c: Examining AMI event: Event: Newexten Privilege: call,all SystemName: sipqa Channel: SIP/mlcm800-00000000 ChannelState: 6 ChannelStateDesc: Up CallerIDNum: mlcm800 CallerIDName: Mitch ConnectedLineNum: ConnectedLineName: AccountCode: Context: LocalSets Exten: 850 Priority: 3 Uniqueid: sipqa-1408747145.1 Extension: 850 Application: SayDigits AppData: 850 [2014-08-22 17:39:07] DEBUG[13335][C-00000001] channel.c: Scheduling timer at (50 requested / 50 actual) timer ticks per second [2014-08-22 17:39:07] VERBOSE[13335][C-00000001] file.c: -- Playing 'digits/8.ulaw' (language 'en') [2014-08-22 17:39:07] DEBUG[13335][C-00000001] channel.c: Scheduling timer at (138 requested / 138 actual) timer ticks per second [2014-08-22 17:39:07] DEBUG[13335][C-00000001] channel.c: Scheduling timer at (0 requested / 0 actual) timer ticks per second [2014-08-22 17:39:07] DEBUG[13335][C-00000001] channel.c: Scheduling timer at (0 requested / 0 actual) timer ticks per second [2014-08-22 17:39:07] DEBUG[13335][C-00000001] channel.c: Scheduling timer at (0 requested / 0 actual) timer ticks per second [2014-08-22 17:39:07] DEBUG[13335][C-00000001] channel.c: Scheduling timer at (50 requested / 50 actual) timer ticks per second [2014-08-22 17:39:07] VERBOSE[13335][C-00000001] file.c: -- Playing 'digits/5.ulaw' (language 'en') [2014-08-22 17:39:08] DEBUG[13335][C-00000001] channel.c: Scheduling timer at (160 requested / 160 actual) timer ticks per second [2014-08-22 17:39:08] DEBUG[13335][C-00000001] channel.c: Scheduling timer at (0 requested / 0 actual) timer ticks per second [2014-08-22 17:39:08] DEBUG[13335][C-00000001] channel.c: Scheduling timer at (0 requested / 0 actual) timer ticks per second [2014-08-22 17:39:08] DEBUG[13335][C-00000001] channel.c: Scheduling timer at (0 requested / 0 actual) timer ticks per second [2014-08-22 17:39:08] DEBUG[13335][C-00000001] channel.c: Scheduling timer at (50 requested / 50 actual) timer ticks per second [2014-08-22 17:39:08] VERBOSE[13335][C-00000001] file.c: -- Playing 'digits/0.ulaw' (language 'en') [2014-08-22 17:39:09] DEBUG[13335][C-00000001] channel.c: Scheduling timer at (56 requested / 56 actual) timer ticks per second [2014-08-22 17:39:09] DEBUG[13335][C-00000001] channel.c: Scheduling timer at (0 requested / 0 actual) timer ticks per second [2014-08-22 17:39:09] DEBUG[13335][C-00000001] channel.c: Scheduling timer at (0 requested / 0 actual) timer ticks per second [2014-08-22 17:39:09] DEBUG[13335][C-00000001] channel.c: Scheduling timer at (0 requested / 0 actual) timer ticks per second [2014-08-22 17:39:09] DEBUG[13335][C-00000001] pbx.c: Result of 'EXTEN' is '850' [2014-08-22 17:39:09] DEBUG[13335][C-00000001] pbx.c: Launching 'MeetMeCount' [2014-08-22 17:39:09] VERBOSE[13335][C-00000001] pbx.c: -- Executing [850@LocalSets:4] MeetMeCount("SIP/mlcm800-00000000", "850,CONFCOUNT") in new stack [2014-08-22 17:39:09] DEBUG[13333] manager.c: Examining AMI event: Event: Newexten Privilege: call,all SystemName: sipqa Channel: SIP/mlcm800-00000000 ChannelState: 6 ChannelStateDesc: Up CallerIDNum: mlcm800 CallerIDName: Mitch ConnectedLineNum: ConnectedLineName: AccountCode: Context: LocalSets Exten: 850 Priority: 4 Uniqueid: sipqa-1408747145.1 Extension: 850 Application: MeetMeCount AppData: 850,CONFCOUNT [2014-08-22 17:39:09] DEBUG[13335][C-00000001] app_meetme.c: The requested confno is '850'? [2014-08-22 17:39:09] DEBUG[13335][C-00000001] config.c: Parsing /etc/asterisk/meetme.conf [2014-08-22 17:39:09] VERBOSE[13335][C-00000001] config.c: == Parsing '/etc/asterisk/meetme.conf': Found [2014-08-22 17:39:09] DEBUG[13335][C-00000001] app_meetme.c: Will conf 850 match 850? [2014-08-22 17:39:09] DEBUG[13333] manager.c: Examining AMI event: Event: VarSet Privilege: dialplan,all SystemName: sipqa Channel: SIP/mlcm800-00000000 ChannelState: 6 ChannelStateDesc: Up CallerIDNum: mlcm800 CallerIDName: Mitch ConnectedLineNum: ConnectedLineName: AccountCode: Context: LocalSets Exten: 850 Priority: 4 Uniqueid: sipqa-1408747145.1 Variable: CONFCOUNT Value: 0 [2014-08-22 17:39:09] DEBUG[13335][C-00000001] pbx.c: Result of 'CONFCOUNT' is '0' [2014-08-22 17:39:09] DEBUG[13335][C-00000001] pbx.c: Result of 'EXTEN' is '850' [2014-08-22 17:39:09] DEBUG[13335][C-00000001] pbx.c: Launching 'Verbose' [2014-08-22 17:39:09] VERBOSE[13335][C-00000001] pbx.c: -- Executing [850@LocalSets:5] Verbose("SIP/mlcm800-00000000", "2,0 callers in 850") in new stack [2014-08-22 17:39:09] DEBUG[13333] manager.c: Examining AMI event: Event: Newexten Privilege: call,all SystemName: sipqa Channel: SIP/mlcm800-00000000 ChannelState: 6 ChannelStateDesc: Up CallerIDNum: mlcm800 CallerIDName: Mitch ConnectedLineNum: ConnectedLineName: AccountCode: Context: LocalSets Exten: 850 Priority: 5 Uniqueid: sipqa-1408747145.1 Extension: 850 Application: Verbose AppData: 2,0 callers in 850 [2014-08-22 17:39:09] VERBOSE[13335][C-00000001] app_verbose.c: == 0 callers in 850 [2014-08-22 17:39:09] DEBUG[13335][C-00000001] pbx.c: Result of 'CONFCOUNT' is '0' [2014-08-22 17:39:09] DEBUG[13335][C-00000001] pbx.c: Expression result is '1' [2014-08-22 17:39:09] DEBUG[13335][C-00000001] pbx.c: Launching 'GotoIf' [2014-08-22 17:39:09] VERBOSE[13335][C-00000001] pbx.c: -- Executing [850@LocalSets:6] GotoIf("SIP/mlcm800-00000000", "1?join") in new stack [2014-08-22 17:39:09] DEBUG[13333] manager.c: Examining AMI event: Event: Newexten Privilege: call,all SystemName: sipqa Channel: SIP/mlcm800-00000000 ChannelState: 6 ChannelStateDesc: Up CallerIDNum: mlcm800 CallerIDName: Mitch ConnectedLineNum: ConnectedLineName: AccountCode: Context: LocalSets Exten: 850 Priority: 6 Uniqueid: sipqa-1408747145.1 Extension: 850 Application: GotoIf AppData: 1?join [2014-08-22 17:39:09] VERBOSE[13335][C-00000001] pbx.c: -- Goto (LocalSets,850,10) [2014-08-22 17:39:09] DEBUG[13335][C-00000001] pbx.c: Result of 'EXTEN' is '850' [2014-08-22 17:39:09] DEBUG[13335][C-00000001] pbx.c: Launching 'MeetMe' [2014-08-22 17:39:09] VERBOSE[13335][C-00000001] pbx.c: -- Executing [850@LocalSets:10] MeetMe("SIP/mlcm800-00000000", "850,c") in new stack [2014-08-22 17:39:09] DEBUG[13333] manager.c: Examining AMI event: Event: Newexten Privilege: call,all SystemName: sipqa Channel: SIP/mlcm800-00000000 ChannelState: 6 ChannelStateDesc: Up CallerIDNum: mlcm800 CallerIDName: Mitch ConnectedLineNum: ConnectedLineName: AccountCode: Context: LocalSets Exten: 850 Priority: 10 Uniqueid: sipqa-1408747145.1 Extension: 850 Application: MeetMe AppData: 850,c [2014-08-22 17:39:09] DEBUG[13335][C-00000001] app_meetme.c: The requested confno is '850'? [2014-08-22 17:39:09] DEBUG[13335][C-00000001] config.c: Parsing /etc/asterisk/meetme.conf [2014-08-22 17:39:09] VERBOSE[13335][C-00000001] config.c: == Parsing '/etc/asterisk/meetme.conf': Found [2014-08-22 17:39:09] DEBUG[13335][C-00000001] app_meetme.c: Will conf 850 match 850? [2014-08-22 17:39:09] DEBUG[13335][C-00000001] chan_dahdi.c: Using channel -2 [2014-08-22 17:39:09] DEBUG[13333] manager.c: Examining AMI event: Event: Newchannel Privilege: call,all SystemName: sipqa Channel: DAHDI/pseudo-1771063197 ChannelState: 1 ChannelStateDesc: Rsrvd CallerIDNum: CallerIDName: ConnectedLineNum: ConnectedLineName: AccountCode: Context: default Exten: s Priority: 1 Uniqueid: sipqa-1408747149.2 [2014-08-22 17:39:09] DEBUG[13205] devicestate.c: No provider found, checking channel drivers for DAHDI - pseudo [2014-08-22 17:39:09] DEBUG[13205] devicestate.c: Changing state for DAHDI/pseudo - state 2 (In use) [2014-08-22 17:39:09] DEBUG[13335][C-00000001] channel_internal_api.c: Channel Call ID changing from [C-00000001] to [C-00000001] [2014-08-22 17:39:09] DEBUG[13333] manager.c: Examining AMI event: Event: DAHDIChannel Privilege: call,all SystemName: sipqa Channel: DAHDI/pseudo-1771063197 ChannelState: 1 ChannelStateDesc: Rsrvd CallerIDNum: CallerIDName: ConnectedLineNum: ConnectedLineName: AccountCode: Context: default Exten: s Priority: 1 Uniqueid: sipqa-1408747149.2 DAHDISpan: 0 DAHDIChannel: pseudo [2014-08-22 17:39:09] DEBUG[13330] app_queue.c: Device 'DAHDI/pseudo' changed to state '2' (In use) but we don't care because they're not a member of any queue. [2014-08-22 17:39:09] DEBUG[13335][C-00000001] channel.c: Set channel DAHDI/pseudo-1771063197 to read format slin [2014-08-22 17:39:09] DEBUG[13335][C-00000001] channel.c: Set channel DAHDI/pseudo-1771063197 to write format slin [2014-08-22 17:39:09] VERBOSE[13335][C-00000001] app_meetme.c: -- Created MeetMe conference 1023 for conference '850' [2014-08-22 17:39:09] DEBUG[13335][C-00000001] channel.c: Scheduling timer at (50 requested / 50 actual) timer ticks per second [2014-08-22 17:39:09] VERBOSE[13335][C-00000001] file.c: -- Playing 'conf-getpin.ulaw' (language 'en') [2014-08-22 17:39:09] DEBUG[13335][C-00000001] res_rtp_asterisk.c: Creating BEGIN DTMF Frame: 52 (4), at 192.168.5.5:61154 [2014-08-22 17:39:09] DEBUG[13333] manager.c: Examining AMI event: Event: DTMFBegin Privilege: dtmf,all SystemName: sipqa Channel: SIP/mlcm800-00000000 ChannelState: 6 ChannelStateDesc: Up CallerIDNum: mlcm800 CallerIDName: Mitch ConnectedLineNum: ConnectedLineName: AccountCode: Context: LocalSets Exten: 850 Priority: 10 Uniqueid: sipqa-1408747145.1 Digit: 4 Direction: Received [2014-08-22 17:39:09] DTMF[13335][C-00000001] channel.c: DTMF begin '4' received on SIP/mlcm800-00000000 [2014-08-22 17:39:09] DTMF[13335][C-00000001] channel.c: DTMF begin ignored '4' on SIP/mlcm800-00000000 [2014-08-22 17:39:09] DEBUG[13335][C-00000001] res_rtp_asterisk.c: Creating END DTMF Frame: 52 (4), at 192.168.5.5:61154 [2014-08-22 17:39:09] DEBUG[13333] manager.c: Examining AMI event: Event: DTMFEnd Privilege: dtmf,all SystemName: sipqa Channel: SIP/mlcm800-00000000 ChannelState: 6 ChannelStateDesc: Up CallerIDNum: mlcm800 CallerIDName: Mitch ConnectedLineNum: ConnectedLineName: AccountCode: Context: LocalSets Exten: 850 Priority: 10 Uniqueid: sipqa-1408747145.1 Digit: 4 DurationMs: 100 Direction: Received [2014-08-22 17:39:09] DTMF[13335][C-00000001] channel.c: DTMF end '4' received on SIP/mlcm800-00000000, duration 100 ms [2014-08-22 17:39:09] DTMF[13335][C-00000001] channel.c: DTMF end passthrough '4' on SIP/mlcm800-00000000 [2014-08-22 17:39:09] DEBUG[13335][C-00000001] channel.c: Scheduling timer at (0 requested / 0 actual) timer ticks per second [2014-08-22 17:39:09] DEBUG[13335][C-00000001] channel.c: Scheduling timer at (0 requested / 0 actual) timer ticks per second [2014-08-22 17:39:10] DEBUG[13335][C-00000001] res_rtp_asterisk.c: Creating BEGIN DTMF Frame: 55 (7), at 192.168.5.5:61154 [2014-08-22 17:39:10] DEBUG[13333] manager.c: Examining AMI event: Event: DTMFBegin Privilege: dtmf,all SystemName: sipqa Channel: SIP/mlcm800-00000000 ChannelState: 6 ChannelStateDesc: Up CallerIDNum: mlcm800 CallerIDName: Mitch ConnectedLineNum: ConnectedLineName: AccountCode: Context: LocalSets Exten: 850 Priority: 10 Uniqueid: sipqa-1408747145.1 Digit: 7 Direction: Received [2014-08-22 17:39:10] DTMF[13335][C-00000001] channel.c: DTMF begin '7' received on SIP/mlcm800-00000000 [2014-08-22 17:39:10] DTMF[13335][C-00000001] channel.c: DTMF begin ignored '7' on SIP/mlcm800-00000000 [2014-08-22 17:39:10] DEBUG[13335][C-00000001] res_rtp_asterisk.c: Creating END DTMF Frame: 55 (7), at 192.168.5.5:61154 [2014-08-22 17:39:10] DEBUG[13333] manager.c: Examining AMI event: Event: DTMFEnd Privilege: dtmf,all SystemName: sipqa Channel: SIP/mlcm800-00000000 ChannelState: 6 ChannelStateDesc: Up CallerIDNum: mlcm800 CallerIDName: Mitch ConnectedLineNum: ConnectedLineName: AccountCode: Context: LocalSets Exten: 850 Priority: 10 Uniqueid: sipqa-1408747145.1 Digit: 7 DurationMs: 100 Direction: Received [2014-08-22 17:39:10] DTMF[13335][C-00000001] channel.c: DTMF end '7' received on SIP/mlcm800-00000000, duration 100 ms [2014-08-22 17:39:10] DTMF[13335][C-00000001] channel.c: DTMF end passthrough '7' on SIP/mlcm800-00000000 [2014-08-22 17:39:10] DEBUG[13323] acl.c: Not an IPv4 nor IPv6 address, cannot get port. [2014-08-22 17:39:10] DEBUG[13323] netsock2.c: Splitting 'sipqa' into... [2014-08-22 17:39:10] DEBUG[13323] netsock2.c: ...host 'sipqa' and port ''. [2014-08-22 17:39:10] DEBUG[13323] acl.c: Multiple addresses. Using the first only [2014-08-22 17:39:10] DEBUG[13323] acl.c: Not an IPv4 nor IPv6 address, cannot get port. [2014-08-22 17:39:10] DEBUG[13323] acl.c: Attached to given IP address [2014-08-22 17:39:10] DEBUG[13333] manager.c: Examining AMI event: Event: RTCPSent Privilege: reporting,all SystemName: sipqa Channel: SIP/mlcm800-00000000 ChannelState: 6 ChannelStateDesc: Up CallerIDNum: mlcm800 CallerIDName: Mitch ConnectedLineNum: ConnectedLineName: AccountCode: Context: LocalSets Exten: 850 Priority: 10 Uniqueid: sipqa-1408747145.1 To: 192.168.5.5:61155 From: 127.0.1.1:0 SSRC: 0x5d521743 PT: 200(SR) ReportCount: 1 SentNTP: 1408747150.2926845952 SentRTP: 32800 SentPackets: 205 SentOctets: 32800 Report0SourceSSRC: 0x271ede02 Report0FractionLost: 0 Report0CumulativeLost: 0 Report0HighestSequence: 252 Report0SequenceNumberCycles: 0 Report0IAJitter: 0 Report0LSR: 1158264872 Report0DLSR: 4.9220 [2014-08-22 17:39:10] DEBUG[13335][C-00000001] res_rtp_asterisk.c: Creating BEGIN DTMF Frame: 56 (8), at 192.168.5.5:61154 [2014-08-22 17:39:10] DEBUG[13333] manager.c: Examining AMI event: Event: DTMFBegin Privilege: dtmf,all SystemName: sipqa Channel: SIP/mlcm800-00000000 ChannelState: 6 ChannelStateDesc: Up CallerIDNum: mlcm800 CallerIDName: Mitch ConnectedLineNum: ConnectedLineName: AccountCode: Context: LocalSets Exten: 850 Priority: 10 Uniqueid: sipqa-1408747145.1 Digit: 8 Direction: Received [2014-08-22 17:39:10] DTMF[13335][C-00000001] channel.c: DTMF begin '8' received on SIP/mlcm800-00000000 [2014-08-22 17:39:10] DTMF[13335][C-00000001] channel.c: DTMF begin ignored '8' on SIP/mlcm800-00000000 [2014-08-22 17:39:10] DEBUG[13335][C-00000001] res_rtp_asterisk.c: Creating END DTMF Frame: 56 (8), at 192.168.5.5:61154 [2014-08-22 17:39:10] DEBUG[13333] manager.c: Examining AMI event: Event: DTMFEnd Privilege: dtmf,all SystemName: sipqa Channel: SIP/mlcm800-00000000 ChannelState: 6 ChannelStateDesc: Up CallerIDNum: mlcm800 CallerIDName: Mitch ConnectedLineNum: ConnectedLineName: AccountCode: Context: LocalSets Exten: 850 Priority: 10 Uniqueid: sipqa-1408747145.1 Digit: 8 DurationMs: 100 Direction: Received [2014-08-22 17:39:10] DTMF[13335][C-00000001] channel.c: DTMF end '8' received on SIP/mlcm800-00000000, duration 100 ms [2014-08-22 17:39:10] DTMF[13335][C-00000001] channel.c: DTMF end passthrough '8' on SIP/mlcm800-00000000 [2014-08-22 17:39:11] DEBUG[13335][C-00000001] res_rtp_asterisk.c: Creating BEGIN DTMF Frame: 53 (5), at 192.168.5.5:61154 [2014-08-22 17:39:11] DTMF[13335][C-00000001] channel.c: DTMF begin '5' received on SIP/mlcm800-00000000 [2014-08-22 17:39:11] DTMF[13335][C-00000001] channel.c: DTMF begin ignored '5' on SIP/mlcm800-00000000 [2014-08-22 17:39:11] DEBUG[13333] manager.c: Examining AMI event: Event: DTMFBegin Privilege: dtmf,all SystemName: sipqa Channel: SIP/mlcm800-00000000 ChannelState: 6 ChannelStateDesc: Up CallerIDNum: mlcm800 CallerIDName: Mitch ConnectedLineNum: ConnectedLineName: AccountCode: Context: LocalSets Exten: 850 Priority: 10 Uniqueid: sipqa-1408747145.1 Digit: 5 Direction: Received [2014-08-22 17:39:11] DEBUG[13335][C-00000001] res_rtp_asterisk.c: Creating END DTMF Frame: 53 (5), at 192.168.5.5:61154 [2014-08-22 17:39:11] DTMF[13335][C-00000001] channel.c: DTMF end '5' received on SIP/mlcm800-00000000, duration 100 ms [2014-08-22 17:39:11] DTMF[13335][C-00000001] channel.c: DTMF end passthrough '5' on SIP/mlcm800-00000000 [2014-08-22 17:39:11] DEBUG[13333] manager.c: Examining AMI event: Event: DTMFEnd Privilege: dtmf,all SystemName: sipqa Channel: SIP/mlcm800-00000000 ChannelState: 6 ChannelStateDesc: Up CallerIDNum: mlcm800 CallerIDName: Mitch ConnectedLineNum: ConnectedLineName: AccountCode: Context: LocalSets Exten: 850 Priority: 10 Uniqueid: sipqa-1408747145.1 Digit: 5 DurationMs: 100 Direction: Received [2014-08-22 17:39:11] DEBUG[13335][C-00000001] res_rtp_asterisk.c: Got RTCP report of 80 bytes [2014-08-22 17:39:11] DEBUG[13335][C-00000001] acl.c: Not an IPv4 nor IPv6 address, cannot get port. [2014-08-22 17:39:11] DEBUG[13335][C-00000001] netsock2.c: Splitting 'sipqa' into... [2014-08-22 17:39:11] DEBUG[13335][C-00000001] netsock2.c: ...host 'sipqa' and port ''. [2014-08-22 17:39:11] DEBUG[13335][C-00000001] acl.c: Multiple addresses. Using the first only [2014-08-22 17:39:11] DEBUG[13335][C-00000001] acl.c: Not an IPv4 nor IPv6 address, cannot get port. [2014-08-22 17:39:11] DEBUG[13335][C-00000001] acl.c: Attached to given IP address [2014-08-22 17:39:11] DEBUG[13333] manager.c: Examining AMI event: Event: RTCPReceived Privilege: reporting,all SystemName: sipqa Channel: SIP/mlcm800-00000000 ChannelState: 6 ChannelStateDesc: Up CallerIDNum: mlcm800 CallerIDName: Mitch ConnectedLineNum: ConnectedLineName: AccountCode: Context: LocalSets Exten: 850 Priority: 10 Uniqueid: sipqa-1408747145.1 To: 127.0.1.1:0 From: 192.168.5.5:61155 RTT: 0.0272 SSRC: 0x271ede02 PT: 200(SR) ReportCount: 1 SentNTP: 1408747151.17563177308160 SentRTP: 2397970824 SentPackets: 293 SentOctets: 42512 Report0SourceSSRC: 0x5d521743 Report0FractionLost: 0 Report0CumulativeLost: 0 Report0HighestSequence: 49205 Report0SequenceNumberCycles: 0 Report0IAJitter: 1 Report0LSR: 1158592237 Report0DLSR: 0.7672 [2014-08-22 17:39:11] DEBUG[13335][C-00000001] res_rtp_asterisk.c: Creating BEGIN DTMF Frame: 35 (#), at 192.168.5.5:61154 [2014-08-22 17:39:11] DEBUG[13333] manager.c: Examining AMI event: Event: DTMFBegin Privilege: dtmf,all SystemName: sipqa Channel: SIP/mlcm800-00000000 ChannelState: 6 ChannelStateDesc: Up CallerIDNum: mlcm800 CallerIDName: Mitch ConnectedLineNum: ConnectedLineName: AccountCode: Context: LocalSets Exten: 850 Priority: 10 Uniqueid: sipqa-1408747145.1 Digit: # Direction: Received [2014-08-22 17:39:11] DTMF[13335][C-00000001] channel.c: DTMF begin '#' received on SIP/mlcm800-00000000 [2014-08-22 17:39:11] DTMF[13335][C-00000001] channel.c: DTMF begin ignored '#' on SIP/mlcm800-00000000 [2014-08-22 17:39:11] DEBUG[13335][C-00000001] res_rtp_asterisk.c: Creating END DTMF Frame: 35 (#), at 192.168.5.5:61154 [2014-08-22 17:39:11] DEBUG[13333] manager.c: Examining AMI event: Event: DTMFEnd Privilege: dtmf,all SystemName: sipqa Channel: SIP/mlcm800-00000000 ChannelState: 6 ChannelStateDesc: Up CallerIDNum: mlcm800 CallerIDName: Mitch ConnectedLineNum: ConnectedLineName: AccountCode: Context: LocalSets Exten: 850 Priority: 10 Uniqueid: sipqa-1408747145.1 Digit: # DurationMs: 100 Direction: Received [2014-08-22 17:39:11] DTMF[13335][C-00000001] channel.c: DTMF end '#' received on SIP/mlcm800-00000000, duration 100 ms [2014-08-22 17:39:11] DTMF[13335][C-00000001] channel.c: DTMF end passthrough '#' on SIP/mlcm800-00000000 [2014-08-22 17:39:11] VERBOSE[13335][C-00000001] app_meetme.c: > Starting recording of MeetMe Conference 850 into file (null).(null). [2014-08-22 17:39:11] DEBUG[13330] app_queue.c: Device 'meetme:850' changed to state '2' (In use) but we don't care because they're not a member of any queue. [2014-08-22 17:39:11] DEBUG[13333] manager.c: Examining AMI event: Event: VarSet Privilege: dialplan,all SystemName: sipqa Channel: SIP/mlcm800-00000000 ChannelState: 6 ChannelStateDesc: Up CallerIDNum: mlcm800 CallerIDName: Mitch ConnectedLineNum: ConnectedLineName: AccountCode: Context: LocalSets Exten: 850 Priority: 10 Uniqueid: sipqa-1408747145.1 Variable: MEETMEUNIQUEID Value: sipqa-1408747145.1 [2014-08-22 17:39:11] DEBUG[13335][C-00000001] res_rtp_asterisk.c: Difference is 15944, ms is 2013 [2014-08-22 17:39:11] DEBUG[13335][C-00000001] channel.c: Scheduling timer at (50 requested / 50 actual) timer ticks per second [2014-08-22 17:39:11] VERBOSE[13335][C-00000001] file.c: -- Playing 'conf-onlyperson.ulaw' (language 'en') [2014-08-22 17:39:15] DEBUG[13335][C-00000001] channel.c: Scheduling timer at (107 requested / 107 actual) timer ticks per second [2014-08-22 17:39:15] DEBUG[13335][C-00000001] channel.c: Scheduling timer at (0 requested / 0 actual) timer ticks per second [2014-08-22 17:39:15] DEBUG[13335][C-00000001] channel.c: Scheduling timer at (0 requested / 0 actual) timer ticks per second [2014-08-22 17:39:15] DEBUG[13335][C-00000001] channel.c: Scheduling timer at (0 requested / 0 actual) timer ticks per second [2014-08-22 17:39:15] DEBUG[13335][C-00000001] channel.c: Set channel SIP/mlcm800-00000000 to write format slin [2014-08-22 17:39:15] DEBUG[13335][C-00000001] channel.c: Set channel SIP/mlcm800-00000000 to read format slin [2014-08-22 17:39:15] DEBUG[13335][C-00000001] app_meetme.c: Placed channel SIP/mlcm800-00000000 in DAHDI conf 1023 [2014-08-22 17:39:15] DEBUG[13333] manager.c: Examining AMI event: Event: MeetmeJoin Privilege: call,all SystemName: sipqa Meetme: 850 Channel: SIP/mlcm800-00000000 ChannelState: 6 ChannelStateDesc: Up CallerIDNum: mlcm800 CallerIDName: Mitch ConnectedLineNum: ConnectedLineName: AccountCode: Context: LocalSets Exten: 850 Priority: 10 Uniqueid: sipqa-1408747145.1 User: 1 Duration: 4 [2014-08-22 17:39:15] DEBUG[13335][C-00000001] dsp.c: Setup tone 1100 Hz, 500 ms, block_size=160, hits_required=21 [2014-08-22 17:39:15] DEBUG[13335][C-00000001] dsp.c: Setup tone 2100 Hz, 2600 ms, block_size=160, hits_required=116 [2014-08-22 17:39:15] DEBUG[13335][C-00000001] res_rtp_asterisk.c: Difference is 1112, ms is 159 [2014-08-22 17:39:15] DEBUG[13323] acl.c: Not an IPv4 nor IPv6 address, cannot get port. [2014-08-22 17:39:15] DEBUG[13323] netsock2.c: Splitting 'sipqa' into... [2014-08-22 17:39:15] DEBUG[13323] netsock2.c: ...host 'sipqa' and port ''. [2014-08-22 17:39:15] DEBUG[13323] acl.c: Multiple addresses. Using the first only [2014-08-22 17:39:15] DEBUG[13323] acl.c: Not an IPv4 nor IPv6 address, cannot get port. [2014-08-22 17:39:15] DEBUG[13323] acl.c: Attached to given IP address [2014-08-22 17:39:15] DEBUG[13333] manager.c: Examining AMI event: Event: RTCPSent Privilege: reporting,all SystemName: sipqa Channel: SIP/mlcm800-00000000 ChannelState: 6 ChannelStateDesc: Up CallerIDNum: mlcm800 CallerIDName: Mitch ConnectedLineNum: ConnectedLineName: AccountCode: Context: LocalSets Exten: 850 Priority: 10 Uniqueid: sipqa-1408747145.1 To: 192.168.5.5:61155 From: 127.0.1.1:0 SSRC: 0x5d521743 PT: 200(SR) ReportCount: 1 SentNTP: 1408747155.2929876992 SentRTP: 79616 SentPackets: 391 SentOctets: 62560 Report0SourceSSRC: 0x271ede02 Report0FractionLost: 0 Report0CumulativeLost: 0 Report0HighestSequence: 505 Report0SequenceNumberCycles: 0 Report0IAJitter: 0 Report0LSR: 1158637749 Report0DLSR: 4.2330 [2014-08-22 17:39:18] DEBUG[13335][C-00000001] res_rtp_asterisk.c: Got RTCP report of 80 bytes [2014-08-22 17:39:18] DEBUG[13335][C-00000001] acl.c: Not an IPv4 nor IPv6 address, cannot get port. [2014-08-22 17:39:18] DEBUG[13335][C-00000001] netsock2.c: Splitting 'sipqa' into... [2014-08-22 17:39:18] DEBUG[13335][C-00000001] netsock2.c: ...host 'sipqa' and port ''. [2014-08-22 17:39:18] DEBUG[13335][C-00000001] acl.c: Multiple addresses. Using the first only [2014-08-22 17:39:18] DEBUG[13335][C-00000001] acl.c: Not an IPv4 nor IPv6 address, cannot get port. [2014-08-22 17:39:18] DEBUG[13335][C-00000001] acl.c: Attached to given IP address [2014-08-22 17:39:18] DEBUG[13333] manager.c: Examining AMI event: Event: RTCPReceived Privilege: reporting,all SystemName: sipqa Channel: SIP/mlcm800-00000000 ChannelState: 6 ChannelStateDesc: Up CallerIDNum: mlcm800 CallerIDName: Mitch ConnectedLineNum: ConnectedLineName: AccountCode: Context: LocalSets Exten: 850 Priority: 10 Uniqueid: sipqa-1408747145.1 To: 127.0.1.1:0 From: 192.168.5.5:61155 RTT: 0.0237 SSRC: 0x271ede02 PT: 200(SR) ReportCount: 1 SentNTP: 1408747158.17533513306112 SentRTP: 2398030074 SentPackets: 664 SentOctets: 100780 Report0SourceSSRC: 0x5d521743 Report0FractionLost: 0 Report0CumulativeLost: 0 Report0HighestSequence: 49550 Report0SequenceNumberCycles: 0 Report0IAJitter: 0 Report0LSR: 1158919966 Report0DLSR: 3.1729 [2014-08-22 17:39:19] DEBUG[13323] chan_sip.c: = Looking for Call ID: 1aniZhX.2ngkFw4OFoBhzrkdKTh9jc9J (Checking From) --From tag liKiC6E1BuQ4dmpczdjtPyY3di6350QO --To-tag [2014-08-22 17:39:19] DEBUG[13323] acl.c: For destination '192.168.5.107', our source address is '192.168.5.105'. [2014-08-22 17:39:19] DEBUG[13323] chan_sip.c: Setting AST_TRANSPORT_UDP with address 192.168.5.105:5060 [2014-08-22 17:39:19] DEBUG[13323] netsock2.c: Splitting '192.168.5.107:5060' into... [2014-08-22 17:39:19] DEBUG[13323] netsock2.c: ...host '192.168.5.107' and port '5060'. [2014-08-22 17:39:19] DEBUG[13323] chan_sip.c: Allocating new SIP dialog for 1aniZhX.2ngkFw4OFoBhzrkdKTh9jc9J - INVITE (No RTP) [2014-08-22 17:39:19] DEBUG[13323][C-00000002] chan_sip.c: **** Received INVITE (5) - Command in SIP INVITE [2014-08-22 17:39:19] DEBUG[13323][C-00000002] sip/reqresp_parser.c: Begin: parsing SIP "Supported: replaces, 100rel, timer, norefersub" [2014-08-22 17:39:19] DEBUG[13323][C-00000002] sip/reqresp_parser.c: Found SIP option: -replaces- [2014-08-22 17:39:19] DEBUG[13323][C-00000002] sip/reqresp_parser.c: Matched SIP option: replaces [2014-08-22 17:39:19] DEBUG[13323][C-00000002] sip/reqresp_parser.c: Found SIP option: -100rel- [2014-08-22 17:39:19] DEBUG[13323][C-00000002] sip/reqresp_parser.c: Matched SIP option: 100rel [2014-08-22 17:39:19] DEBUG[13323][C-00000002] sip/reqresp_parser.c: Found SIP option: -timer- [2014-08-22 17:39:19] DEBUG[13323][C-00000002] sip/reqresp_parser.c: Matched SIP option: timer [2014-08-22 17:39:19] DEBUG[13323][C-00000002] sip/reqresp_parser.c: Found SIP option: -norefersub- [2014-08-22 17:39:19] DEBUG[13323][C-00000002] sip/reqresp_parser.c: Matched SIP option: norefersub [2014-08-22 17:39:19] DEBUG[13323][C-00000002] netsock2.c: Splitting '192.168.5.107:5060' into... [2014-08-22 17:39:19] DEBUG[13323][C-00000002] netsock2.c: ...host '192.168.5.107' and port '5060'. [2014-08-22 17:39:19] DEBUG[13323][C-00000002] netsock2.c: Splitting '192.168.5.105' into... [2014-08-22 17:39:19] DEBUG[13323][C-00000002] netsock2.c: ...host '192.168.5.105' and port ''. [2014-08-22 17:39:19] DEBUG[13323][C-00000002] chan_sip.c: Trying to put 'SIP/2.0 401' onto UDP socket destined for 192.168.5.107:5060 [2014-08-22 17:39:19] DEBUG[13333] manager.c: Examining AMI event: Event: ChallengeSent Privilege: security,all SystemName: sipqa EventTV: 2014-08-22T17:39:19.716-0500 Severity: Informational Service: SIP EventVersion: 1 AccountID: sip:mlc296@192.168.5.105 SessionID: 0x7ffc34044588 LocalAddress: IPV4/UDP/192.168.5.105/5060 RemoteAddress: IPV4/UDP/192.168.5.107/5060 Challenge: 1bab2bf8 [2014-08-22 17:39:19] DEBUG[13323] chan_sip.c: = Looking for Call ID: 1aniZhX.2ngkFw4OFoBhzrkdKTh9jc9J (Checking From) --From tag liKiC6E1BuQ4dmpczdjtPyY3di6350QO --To-tag as330fe634 [2014-08-22 17:39:19] DEBUG[13323][C-00000002] chan_sip.c: **** Received ACK (6) - Command in SIP ACK [2014-08-22 17:39:19] DEBUG[13323][C-00000002] chan_sip.c: Stopping retransmission on '1aniZhX.2ngkFw4OFoBhzrkdKTh9jc9J' of Response 19748: Match Found [2014-08-22 17:39:19] DEBUG[13323] chan_sip.c: = Looking for Call ID: 1aniZhX.2ngkFw4OFoBhzrkdKTh9jc9J (Checking From) --From tag liKiC6E1BuQ4dmpczdjtPyY3di6350QO --To-tag [2014-08-22 17:39:19] DEBUG[13323] netsock2.c: Splitting '192.168.5.105' into... [2014-08-22 17:39:19] DEBUG[13323] netsock2.c: ...host '192.168.5.105' and port ''. [2014-08-22 17:39:19] DEBUG[13323] netsock2.c: Splitting '192.168.5.105' into... [2014-08-22 17:39:19] DEBUG[13323] netsock2.c: ...host '192.168.5.105' and port ''. [2014-08-22 17:39:19] DEBUG[13323][C-00000002] chan_sip.c: **** Received INVITE (5) - Command in SIP INVITE [2014-08-22 17:39:19] DEBUG[13323][C-00000002] netsock2.c: Splitting '192.168.5.107:5060' into... [2014-08-22 17:39:19] DEBUG[13323][C-00000002] netsock2.c: ...host '192.168.5.107' and port '5060'. [2014-08-22 17:39:19] DEBUG[13323][C-00000002] netsock2.c: Splitting '192.168.5.105' into... [2014-08-22 17:39:19] DEBUG[13323][C-00000002] netsock2.c: ...host '192.168.5.105' and port ''. [2014-08-22 17:39:19] DEBUG[13323][C-00000002] rtp_engine.c: Using engine 'asterisk' for RTP instance '0x7ffc3404f968' [2014-08-22 17:39:19] DEBUG[13323][C-00000002] res_rtp_asterisk.c: Allocated port 29178 for RTP instance '0x7ffc3404f968' [2014-08-22 17:39:19] DEBUG[13323][C-00000002] netsock2.c: Splitting '192.168.5.105' into... [2014-08-22 17:39:19] DEBUG[13323][C-00000002] netsock2.c: ...host '192.168.5.105' and port ''. [2014-08-22 17:39:19] DEBUG[13323][C-00000002] rtp_engine.c: RTP instance '0x7ffc3404f968' is setup and ready to go [2014-08-22 17:39:19] DEBUG[13323][C-00000002] res_rtp_asterisk.c: Setup RTCP on RTP instance '0x7ffc3404f968' [2014-08-22 17:39:19] VERBOSE[13323][C-00000002] netsock2.c: == Using SIP RTP CoS mark 5 [2014-08-22 17:39:19] DEBUG[13323][C-00000002] chan_sip.c: Setting NAT on RTP to Off [2014-08-22 17:39:19] DEBUG[13323][C-00000002] chan_sip.c: Processing session-level SDP v=0... UNSUPPORTED OR FAILED. [2014-08-22 17:39:19] DEBUG[13323][C-00000002] chan_sip.c: Processing session-level SDP o=- 104118449 104118449 IN IP4 192.168.5.107... OK. [2014-08-22 17:39:19] DEBUG[13323][C-00000002] chan_sip.c: Processing session-level SDP s=digphn... UNSUPPORTED OR FAILED. [2014-08-22 17:39:19] DEBUG[13323][C-00000002] netsock2.c: Splitting '192.168.5.107' into... [2014-08-22 17:39:19] DEBUG[13323][C-00000002] netsock2.c: ...host '192.168.5.107' and port ''. [2014-08-22 17:39:19] DEBUG[13323][C-00000002] chan_sip.c: Processing session-level SDP c=IN IP4 192.168.5.107... OK. [2014-08-22 17:39:19] DEBUG[13323][C-00000002] chan_sip.c: Processing session-level SDP t=0 0... UNSUPPORTED OR FAILED. [2014-08-22 17:39:19] DEBUG[13323][C-00000002] chan_sip.c: Processing session-level SDP a=X-nat:0... UNSUPPORTED OR FAILED. [2014-08-22 17:39:19] DEBUG[13323][C-00000002] rtp_engine.c: Setting payload 0 based on m type on 0x7ffdd844df30 [2014-08-22 17:39:19] DEBUG[13323][C-00000002] rtp_engine.c: Setting payload 8 based on m type on 0x7ffdd844df30 [2014-08-22 17:39:19] DEBUG[13323][C-00000002] rtp_engine.c: Setting payload 9 based on m type on 0x7ffdd844df30 [2014-08-22 17:39:19] DEBUG[13323][C-00000002] rtp_engine.c: Setting payload 96 based on m type on 0x7ffdd844df30 [2014-08-22 17:39:19] DEBUG[13323][C-00000002] rtp_engine.c: Setting payload 111 based on m type on 0x7ffdd844df30 [2014-08-22 17:39:19] DEBUG[13323][C-00000002] rtp_engine.c: Setting payload 18 based on m type on 0x7ffdd844df30 [2014-08-22 17:39:19] DEBUG[13323][C-00000002] rtp_engine.c: Setting payload 58 based on m type on 0x7ffdd844df30 [2014-08-22 17:39:19] DEBUG[13323][C-00000002] rtp_engine.c: Setting payload 58 based on m type on 0x7ffdd844df30 [2014-08-22 17:39:19] DEBUG[13323][C-00000002] rtp_engine.c: Setting payload 118 based on m type on 0x7ffdd844df30 [2014-08-22 17:39:19] DEBUG[13323][C-00000002] rtp_engine.c: Setting payload 96 based on m type on 0x7ffdd844df30 [2014-08-22 17:39:19] DEBUG[13323][C-00000002] chan_sip.c: Processing media-level (audio) SDP a=rtcp:4001 IN IP4 192.168.5.107... UNSUPPORTED OR FAILED. [2014-08-22 17:39:19] DEBUG[13323][C-00000002] chan_sip.c: Processing media-level (audio) SDP a=rtpmap:0 PCMU/8000... OK. [2014-08-22 17:39:19] DEBUG[13323][C-00000002] chan_sip.c: Processing media-level (audio) SDP a=rtpmap:8 PCMA/8000... OK. [2014-08-22 17:39:19] DEBUG[13323][C-00000002] chan_sip.c: Processing media-level (audio) SDP a=rtpmap:9 G722/8000... OK. [2014-08-22 17:39:19] DEBUG[13323][C-00000002] chan_sip.c: Processing media-level (audio) SDP a=rtpmap:96 telephone-event/8000... OK. [2014-08-22 17:39:19] DEBUG[13323][C-00000002] chan_sip.c: Processing media-level (audio) SDP a=rtpmap:111 G726-32/8000... OK. [2014-08-22 17:39:19] DEBUG[13323][C-00000002] chan_sip.c: Processing media-level (audio) SDP a=rtpmap:18 G729/8000... OK. [2014-08-22 17:39:19] DEBUG[13323][C-00000002] chan_sip.c: Processing media-level (audio) SDP a=rtpmap:58 L16/16000... OK. [2014-08-22 17:39:19] DEBUG[13323][C-00000002] chan_sip.c: Processing media-level (audio) SDP a=rtpmap:58 L16-256/16000... OK. [2014-08-22 17:39:19] DEBUG[13323][C-00000002] chan_sip.c: Processing media-level (audio) SDP a=rtpmap:118 L16/8000... OK. [2014-08-22 17:39:19] DEBUG[13323][C-00000002] chan_sip.c: Processing media-level (audio) SDP a=sendrecv... OK. [2014-08-22 17:39:19] DEBUG[13323][C-00000002] chan_sip.c: Processing media-level (audio) SDP a=rtpmap:96 telephone-event/8000... OK. [2014-08-22 17:39:19] DEBUG[13323][C-00000002] chan_sip.c: Processing media-level (audio) SDP a=fmtp:96 0-15... UNSUPPORTED OR FAILED. [2014-08-22 17:39:19] DEBUG[13323][C-00000002] res_rtp_asterisk.c: Setting RTCP address on RTP instance '0x7ffc3404f968' [2014-08-22 17:39:19] DEBUG[13323][C-00000002] rtp_engine.c: Copying payload 0 from 0x7ffdd844df30 to 0x7ffc3404faa8 [2014-08-22 17:39:19] DEBUG[13323][C-00000002] rtp_engine.c: Copying payload 8 from 0x7ffdd844df30 to 0x7ffc3404faa8 [2014-08-22 17:39:19] DEBUG[13323][C-00000002] rtp_engine.c: Copying payload 9 from 0x7ffdd844df30 to 0x7ffc3404faa8 [2014-08-22 17:39:19] DEBUG[13323][C-00000002] rtp_engine.c: Copying payload 18 from 0x7ffdd844df30 to 0x7ffc3404faa8 [2014-08-22 17:39:19] DEBUG[13323][C-00000002] rtp_engine.c: Copying payload 58 from 0x7ffdd844df30 to 0x7ffc3404faa8 [2014-08-22 17:39:19] DEBUG[13323][C-00000002] rtp_engine.c: Copying payload 96 from 0x7ffdd844df30 to 0x7ffc3404faa8 [2014-08-22 17:39:19] DEBUG[13323][C-00000002] rtp_engine.c: Copying payload 111 from 0x7ffdd844df30 to 0x7ffc3404faa8 [2014-08-22 17:39:19] DEBUG[13323][C-00000002] rtp_engine.c: Copying payload 118 from 0x7ffdd844df30 to 0x7ffc3404faa8 [2014-08-22 17:39:19] DEBUG[13323][C-00000002] res_rtp_asterisk.c: Ignoring duplicate RTCP property on RTP instance '0x7ffc3404f968' [2014-08-22 17:39:19] DEBUG[13323][C-00000002] chan_sip.c: We're settling with these formats: (ulaw|alaw) [2014-08-22 17:39:19] DEBUG[13323][C-00000002] chan_sip.c: Checking SIP call limits for device mlc296 [2014-08-22 17:39:19] DEBUG[13323][C-00000002] chan_sip.c: Updating call counter for incoming call [2014-08-22 17:39:19] DEBUG[13323][C-00000002] netsock2.c: Splitting '192.168.5.105' into... [2014-08-22 17:39:19] DEBUG[13323][C-00000002] netsock2.c: ...host '192.168.5.105' and port ''. [2014-08-22 17:39:19] DEBUG[13323][C-00000002] netsock2.c: Splitting '192.168.5.105' into... [2014-08-22 17:39:19] DEBUG[13205] devicestate.c: No provider found, checking channel drivers for SIP - mlc296 [2014-08-22 17:39:19] DEBUG[13205] chan_sip.c: Checking device state for peer mlc296 [2014-08-22 17:39:19] DEBUG[13323][C-00000002] netsock2.c: ...host '192.168.5.105' and port ''. [2014-08-22 17:39:19] DEBUG[13205] devicestate.c: Changing state for SIP/mlc296 - state 2 (In use) [2014-08-22 17:39:19] DEBUG[13323][C-00000002] chan_sip.c: Incoming INVITE with 'timer' option supported [2014-08-22 17:39:19] DEBUG[13323][C-00000002] chan_sip.c: INVITE also has "Session-Expires" header. [2014-08-22 17:39:19] DEBUG[13323][C-00000002] chan_sip.c: Session-Expires: 1800 [2014-08-22 17:39:19] DEBUG[13323][C-00000002] chan_sip.c: INVITE also has "Min-SE" header. [2014-08-22 17:39:19] DEBUG[13323][C-00000002] chan_sip.c: Received Min-SE: 90 [2014-08-22 17:39:19] DEBUG[13330] app_queue.c: Device 'SIP/mlc296' changed to state '2' (In use) but we don't care because they're not a member of any queue. [2014-08-22 17:39:19] DEBUG[13333] manager.c: Examining AMI event: Event: ExtensionStatus Privilege: call,all SystemName: sipqa Exten: auto_hint_mlc296 Context: LocalSets Hint: SIP/mlc296,CustomPresence:mlc296 Status: 1 [2014-08-22 17:39:19] DEBUG[13207] app_queue.c: Extension 'auto_hint_mlc296@LocalSets' changed to state '2' (In use) but we don't care because they're not a member of any queue. [2014-08-22 17:39:19] DEBUG[13333] manager.c: Examining AMI event: Event: Newchannel Privilege: call,all SystemName: sipqa Channel: SIP/mlc296-00000001 ChannelState: 0 ChannelStateDesc: Down CallerIDNum: mlc296 CallerIDName: Mitch Digium ConnectedLineNum: ConnectedLineName: AccountCode: Context: LocalSets Exten: 850 Priority: 1 Uniqueid: sipqa-1408747159.3 [2014-08-22 17:39:19] DEBUG[13323][C-00000002] chan_sip.c: *** Our native formats are (ulaw) [2014-08-22 17:39:19] DEBUG[13323][C-00000002] chan_sip.c: *** Joint capabilities are (ulaw|alaw) [2014-08-22 17:39:19] DEBUG[13323][C-00000002] chan_sip.c: *** Our capabilities are (ulaw|alaw) [2014-08-22 17:39:19] DEBUG[13323][C-00000002] chan_sip.c: *** AST_CODEC_CHOOSE formats are ulaw [2014-08-22 17:39:19] DEBUG[13323][C-00000002] chan_sip.c: This channel will not be able to handle video. [2014-08-22 17:39:19] DEBUG[13333] manager.c: Examining AMI event: Event: VarSet Privilege: dialplan,all SystemName: sipqa Channel: SIP/mlc296-00000001 ChannelState: 0 ChannelStateDesc: Down CallerIDNum: mlc296 CallerIDName: Mitch Digium ConnectedLineNum: ConnectedLineName: AccountCode: Context: LocalSets Exten: 850 Priority: 1 Uniqueid: sipqa-1408747159.3 Variable: SIPURI Value: sip:mlc296@192.168.5.107:5060 [2014-08-22 17:39:19] DEBUG[13333] manager.c: Examining AMI event: Event: VarSet Privilege: dialplan,all SystemName: sipqa Channel: SIP/mlc296-00000001 ChannelState: 0 ChannelStateDesc: Down CallerIDNum: mlc296 CallerIDName: Mitch Digium ConnectedLineNum: ConnectedLineName: AccountCode: Context: LocalSets Exten: 850 Priority: 1 Uniqueid: sipqa-1408747159.3 Variable: SIPDOMAIN Value: 192.168.5.105 [2014-08-22 17:39:19] DEBUG[13333] manager.c: Examining AMI event: Event: VarSet Privilege: dialplan,all SystemName: sipqa Channel: SIP/mlc296-00000001 ChannelState: 0 ChannelStateDesc: Down CallerIDNum: mlc296 CallerIDName: Mitch Digium ConnectedLineNum: ConnectedLineName: AccountCode: Context: LocalSets Exten: 850 Priority: 1 Uniqueid: sipqa-1408747159.3 Variable: SIPCALLID Value: 1aniZhX.2ngkFw4OFoBhzrkdKTh9jc9J [2014-08-22 17:39:19] DEBUG[13323][C-00000002] chan_sip.c: build_route: Contact hop: "\"Mitch Digium\" 296" [2014-08-22 17:39:19] DEBUG[13323][C-00000002] chan_sip.c: SIP/mlc296-00000001: New call is still down.... Trying... [2014-08-22 17:39:19] DEBUG[13323][C-00000002] chan_sip.c: Trying to put 'SIP/2.0 100' onto UDP socket destined for 192.168.5.107:5060 [2014-08-22 17:39:19] DEBUG[13333] manager.c: Examining AMI event: Event: Newstate Privilege: call,all SystemName: sipqa Channel: SIP/mlc296-00000001 ChannelState: 4 ChannelStateDesc: Ring CallerIDNum: mlc296 CallerIDName: Mitch Digium ConnectedLineNum: ConnectedLineName: AccountCode: Context: LocalSets Exten: 850 Priority: 1 Uniqueid: sipqa-1408747159.3 [2014-08-22 17:39:19] DEBUG[13205] devicestate.c: No provider found, checking channel drivers for SIP - mlc296 [2014-08-22 17:39:19] DEBUG[13205] chan_sip.c: Checking device state for peer mlc296 [2014-08-22 17:39:19] DEBUG[13205] devicestate.c: Changing state for SIP/mlc296 - state 2 (In use) [2014-08-22 17:39:19] DEBUG[13337][C-00000002] pbx.c: Launching 'NoOp' [2014-08-22 17:39:19] VERBOSE[13337][C-00000002] pbx.c: -- Executing [850@LocalSets:1] NoOp("SIP/mlc296-00000001", "") in new stack [2014-08-22 17:39:19] DEBUG[13207] netsock2.c: Splitting '192.168.5.107:5060' into... [2014-08-22 17:39:19] DEBUG[13207] netsock2.c: ...host '192.168.5.107' and port '5060'. [2014-08-22 17:39:19] DEBUG[13207] chan_sip.c: Trying to put 'NOTIFY sip:' onto UDP socket destined for 192.168.5.107:5060 [2014-08-22 17:39:19] VERBOSE[13207] chan_sip.c: == Extension Changed auto_hint_mlc296[LocalSets] new state InUse for Notify User mlc296 [2014-08-22 17:39:19] DEBUG[13333] manager.c: Examining AMI event: Event: Newexten Privilege: call,all SystemName: sipqa Channel: SIP/mlc296-00000001 ChannelState: 4 ChannelStateDesc: Ring CallerIDNum: mlc296 CallerIDName: Mitch Digium ConnectedLineNum: ConnectedLineName: AccountCode: Context: LocalSets Exten: 850 Priority: 1 Uniqueid: sipqa-1408747159.3 Extension: 850 Application: NoOp AppData: [2014-08-22 17:39:19] DEBUG[13337][C-00000002] pbx.c: Launching 'Playback' [2014-08-22 17:39:19] VERBOSE[13337][C-00000002] pbx.c: -- Executing [850@LocalSets:2] Playback("SIP/mlc296-00000001", "custom/confroom") in new stack [2014-08-22 17:39:19] DEBUG[13333] manager.c: Examining AMI event: Event: Newexten Privilege: call,all SystemName: sipqa Channel: SIP/mlc296-00000001 ChannelState: 4 ChannelStateDesc: Ring CallerIDNum: mlc296 CallerIDName: Mitch Digium ConnectedLineNum: ConnectedLineName: AccountCode: Context: LocalSets Exten: 850 Priority: 2 Uniqueid: sipqa-1408747159.3 Extension: 850 Application: Playback AppData: custom/confroom [2014-08-22 17:39:19] DEBUG[13333] manager.c: Examining AMI event: Event: Newstate Privilege: call,all SystemName: sipqa Channel: SIP/mlc296-00000001 ChannelState: 6 ChannelStateDesc: Up CallerIDNum: mlc296 CallerIDName: Mitch Digium ConnectedLineNum: ConnectedLineName: AccountCode: Context: LocalSets Exten: 850 Priority: 2 Uniqueid: sipqa-1408747159.3 [2014-08-22 17:39:19] DEBUG[13205] devicestate.c: No provider found, checking channel drivers for SIP - mlc296 [2014-08-22 17:39:19] DEBUG[13337][C-00000002] chan_sip.c: SIP answering channel: SIP/mlc296-00000001 [2014-08-22 17:39:19] DEBUG[13205] chan_sip.c: Checking device state for peer mlc296 [2014-08-22 17:39:19] DEBUG[13337][C-00000002] res_rtp_asterisk.c: Setting the marker bit due to a source update [2014-08-22 17:39:19] DEBUG[13205] devicestate.c: Changing state for SIP/mlc296 - state 2 (In use) [2014-08-22 17:39:19] DEBUG[13337][C-00000002] chan_sip.c: Setting framing from config on incoming call [2014-08-22 17:39:19] DEBUG[13337][C-00000002] chan_sip.c: ** Our capability: (ulaw|alaw) Video flag: True Text flag: True [2014-08-22 17:39:19] DEBUG[13337][C-00000002] chan_sip.c: ** Our prefcodec: (nothing) [2014-08-22 17:39:19] DEBUG[13337][C-00000002] chan_sip.c: -- Done with adding codecs to SDP [2014-08-22 17:39:19] DEBUG[13337][C-00000002] chan_sip.c: Done building SDP. Settling with this capability: (ulaw|alaw) [2014-08-22 17:39:19] DEBUG[13337][C-00000002] chan_sip.c: Trying to put 'SIP/2.0 200' onto UDP socket destined for 192.168.5.107:5060 [2014-08-22 17:39:19] DEBUG[13337][C-00000002] chan_sip.c: Session timer started: 222 - 1aniZhX.2ngkFw4OFoBhzrkdKTh9jc9J 900000ms [2014-08-22 17:39:19] DEBUG[13323] chan_sip.c: = Looking for Call ID: lV51It2aVBUgSipQKe7AYrW.Tzt66uM. (Checking To) --From tag as30b482be --To-tag yDT0eQE5dSE0jN68kA5UTW0mSp-lM4SV [2014-08-22 17:39:19] DEBUG[13323] chan_sip.c: Acked pending invite 103 [2014-08-22 17:39:19] DEBUG[13323] chan_sip.c: Stopping retransmission on 'lV51It2aVBUgSipQKe7AYrW.Tzt66uM.' of Request 103: Match Found [2014-08-22 17:39:20] DEBUG[13323] chan_sip.c: ** SIP timers: Rescheduling retransmission 2 to 1000 ms (t1 500 ms (Retrans id #221)) [2014-08-22 17:39:20] DEBUG[13323] chan_sip.c: Trying to put 'SIP/2.0 200' onto UDP socket destined for 192.168.5.107:5060 [2014-08-22 17:39:20] DEBUG[13337][C-00000002] channel.c: Didn't receive a media frame from SIP/mlc296-00000001 within 500 ms of answering. Continuing anyway [2014-08-22 17:39:20] DEBUG[13337][C-00000002] channel.c: Set channel SIP/mlc296-00000001 to write format slin [2014-08-22 17:39:20] DEBUG[13337][C-00000002] res_rtp_asterisk.c: Ooh, format changed from unknown to ulaw [2014-08-22 17:39:20] DEBUG[13337][C-00000002] res_rtp_asterisk.c: Created smoother: format: ulaw ms: 20 len: 160 [2014-08-22 17:39:20] DEBUG[13337][C-00000002] res_rtp_asterisk.c: Starting RTCP transmission on RTP instance '0x7ffc3404f968' [2014-08-22 17:39:20] DEBUG[13337][C-00000002] channel.c: Scheduling timer at (50 requested / 50 actual) timer ticks per second [2014-08-22 17:39:20] VERBOSE[13337][C-00000002] file.c: -- Playing 'custom/confroom.slin' (language 'en') [2014-08-22 17:39:20] DEBUG[13337][C-00000002] res_rtp_asterisk.c: Got RTCP report of 20 bytes [2014-08-22 17:39:20] DEBUG[13337][C-00000002] acl.c: Not an IPv4 nor IPv6 address, cannot get port. [2014-08-22 17:39:20] DEBUG[13337][C-00000002] netsock2.c: Splitting 'sipqa' into... [2014-08-22 17:39:20] DEBUG[13337][C-00000002] netsock2.c: ...host 'sipqa' and port ''. [2014-08-22 17:39:20] DEBUG[13337][C-00000002] acl.c: Multiple addresses. Using the first only [2014-08-22 17:39:20] DEBUG[13337][C-00000002] acl.c: Not an IPv4 nor IPv6 address, cannot get port. [2014-08-22 17:39:20] DEBUG[13337][C-00000002] acl.c: Attached to given IP address [2014-08-22 17:39:20] DEBUG[13333] manager.c: Examining AMI event: Event: RTCPReceived Privilege: reporting,all SystemName: sipqa Channel: SIP/mlc296-00000001 ChannelState: 6 ChannelStateDesc: Up CallerIDNum: mlc296 CallerIDName: Mitch Digium ConnectedLineNum: ConnectedLineName: AccountCode: Context: LocalSets Exten: 850 Priority: 2 Uniqueid: sipqa-1408747159.3 To: 127.0.1.1:0 From: 192.168.5.107:4001 RTT: 0.0000 SSRC: 0x0bfb93d8 PT: 201(RR) ReportCount: 0 [2014-08-22 17:39:20] DEBUG[13337][C-00000002] res_rtp_asterisk.c: 0x7ffc34055730 -- Probation learning mode pass with source address 192.168.5.107:4000 [2014-08-22 17:39:20] VERBOSE[13337][C-00000002] res_rtp_asterisk.c: > 0x7ffc34055730 -- Probation passed - setting RTP source address to 192.168.5.107:4000 [2014-08-22 17:39:20] DEBUG[13323] chan_sip.c: = Looking for Call ID: 1aniZhX.2ngkFw4OFoBhzrkdKTh9jc9J (Checking From) --From tag liKiC6E1BuQ4dmpczdjtPyY3di6350QO --To-tag as6c74a655 [2014-08-22 17:39:20] DEBUG[13323][C-00000002] chan_sip.c: **** Received ACK (6) - Command in SIP ACK [2014-08-22 17:39:20] DEBUG[13323][C-00000002] chan_sip.c: Stopping retransmission on '1aniZhX.2ngkFw4OFoBhzrkdKTh9jc9J' of Response 19749: Match Found [2014-08-22 17:39:20] DEBUG[13323] chan_sip.c: = Looking for Call ID: 1aniZhX.2ngkFw4OFoBhzrkdKTh9jc9J (Checking From) --From tag liKiC6E1BuQ4dmpczdjtPyY3di6350QO --To-tag as6c74a655 [2014-08-22 17:39:20] DEBUG[13323][C-00000002] chan_sip.c: **** Received ACK (6) - Command in SIP ACK [2014-08-22 17:39:20] DEBUG[13323] acl.c: Not an IPv4 nor IPv6 address, cannot get port. [2014-08-22 17:39:20] DEBUG[13323] netsock2.c: Splitting 'sipqa' into... [2014-08-22 17:39:20] DEBUG[13323] netsock2.c: ...host 'sipqa' and port ''. [2014-08-22 17:39:20] DEBUG[13323] acl.c: Multiple addresses. Using the first only [2014-08-22 17:39:20] DEBUG[13323] acl.c: Not an IPv4 nor IPv6 address, cannot get port. [2014-08-22 17:39:20] DEBUG[13323] acl.c: Attached to given IP address [2014-08-22 17:39:20] DEBUG[13333] manager.c: Examining AMI event: Event: RTCPSent Privilege: reporting,all SystemName: sipqa Channel: SIP/mlcm800-00000000 ChannelState: 6 ChannelStateDesc: Up CallerIDNum: mlcm800 CallerIDName: Mitch ConnectedLineNum: ConnectedLineName: AccountCode: Context: LocalSets Exten: 850 Priority: 10 Uniqueid: sipqa-1408747145.1 To: 192.168.5.5:61155 From: 127.0.1.1:0 SSRC: 0x5d521743 PT: 200(SR) ReportCount: 1 SentNTP: 1408747160.2926002176 SentRTP: 119616 SentPackets: 641 SentOctets: 102560 Report0SourceSSRC: 0x271ede02 Report0FractionLost: 0 Report0CumulativeLost: 0 Report0HighestSequence: 754 Report0SequenceNumberCycles: 0 Report0IAJitter: 0 Report0LSR: 1159123125 Report0DLSR: 1.8250 [2014-08-22 17:39:21] DEBUG[13337][C-00000002] channel.c: Scheduling timer at (138 requested / 138 actual) timer ticks per second [2014-08-22 17:39:21] DEBUG[13337][C-00000002] channel.c: Scheduling timer at (0 requested / 0 actual) timer ticks per second [2014-08-22 17:39:21] DEBUG[13337][C-00000002] channel.c: Scheduling timer at (0 requested / 0 actual) timer ticks per second [2014-08-22 17:39:21] DEBUG[13337][C-00000002] channel.c: Scheduling timer at (0 requested / 0 actual) timer ticks per second [2014-08-22 17:39:21] DEBUG[13337][C-00000002] channel.c: Set channel SIP/mlc296-00000001 to write format ulaw [2014-08-22 17:39:21] DEBUG[13333] manager.c: Examining AMI event: Event: VarSet Privilege: dialplan,all SystemName: sipqa Channel: SIP/mlc296-00000001 ChannelState: 6 ChannelStateDesc: Up CallerIDNum: mlc296 CallerIDName: Mitch Digium ConnectedLineNum: ConnectedLineName: AccountCode: Context: LocalSets Exten: 850 Priority: 2 Uniqueid: sipqa-1408747159.3 Variable: PLAYBACKSTATUS Value: SUCCESS [2014-08-22 17:39:21] DEBUG[13337][C-00000002] pbx.c: Result of 'EXTEN' is '850' [2014-08-22 17:39:21] DEBUG[13337][C-00000002] pbx.c: Launching 'SayDigits' [2014-08-22 17:39:21] VERBOSE[13337][C-00000002] pbx.c: -- Executing [850@LocalSets:3] SayDigits("SIP/mlc296-00000001", "850") in new stack [2014-08-22 17:39:21] DEBUG[13333] manager.c: Examining AMI event: Event: Newexten Privilege: call,all SystemName: sipqa Channel: SIP/mlc296-00000001 ChannelState: 6 ChannelStateDesc: Up CallerIDNum: mlc296 CallerIDName: Mitch Digium ConnectedLineNum: ConnectedLineName: AccountCode: Context: LocalSets Exten: 850 Priority: 3 Uniqueid: sipqa-1408747159.3 Extension: 850 Application: SayDigits AppData: 850 [2014-08-22 17:39:21] DEBUG[13337][C-00000002] channel.c: Scheduling timer at (50 requested / 50 actual) timer ticks per second [2014-08-22 17:39:21] VERBOSE[13337][C-00000002] file.c: -- Playing 'digits/8.ulaw' (language 'en') [2014-08-22 17:39:22] DEBUG[13337][C-00000002] channel.c: Scheduling timer at (138 requested / 138 actual) timer ticks per second [2014-08-22 17:39:22] DEBUG[13337][C-00000002] channel.c: Scheduling timer at (0 requested / 0 actual) timer ticks per second [2014-08-22 17:39:22] DEBUG[13337][C-00000002] channel.c: Scheduling timer at (0 requested / 0 actual) timer ticks per second [2014-08-22 17:39:22] DEBUG[13337][C-00000002] channel.c: Scheduling timer at (0 requested / 0 actual) timer ticks per second [2014-08-22 17:39:22] DEBUG[13337][C-00000002] channel.c: Scheduling timer at (50 requested / 50 actual) timer ticks per second [2014-08-22 17:39:22] VERBOSE[13337][C-00000002] file.c: -- Playing 'digits/5.ulaw' (language 'en') [2014-08-22 17:39:22] DEBUG[13337][C-00000002] channel.c: Scheduling timer at (160 requested / 160 actual) timer ticks per second [2014-08-22 17:39:22] DEBUG[13337][C-00000002] channel.c: Scheduling timer at (0 requested / 0 actual) timer ticks per second [2014-08-22 17:39:22] DEBUG[13337][C-00000002] channel.c: Scheduling timer at (0 requested / 0 actual) timer ticks per second [2014-08-22 17:39:22] DEBUG[13337][C-00000002] channel.c: Scheduling timer at (0 requested / 0 actual) timer ticks per second [2014-08-22 17:39:22] DEBUG[13337][C-00000002] channel.c: Scheduling timer at (50 requested / 50 actual) timer ticks per second [2014-08-22 17:39:22] VERBOSE[13337][C-00000002] file.c: -- Playing 'digits/0.ulaw' (language 'en') [2014-08-22 17:39:23] DEBUG[13335][C-00000001] res_rtp_asterisk.c: Got RTCP report of 80 bytes [2014-08-22 17:39:23] DEBUG[13335][C-00000001] acl.c: Not an IPv4 nor IPv6 address, cannot get port. [2014-08-22 17:39:23] DEBUG[13335][C-00000001] netsock2.c: Splitting 'sipqa' into... [2014-08-22 17:39:23] DEBUG[13335][C-00000001] netsock2.c: ...host 'sipqa' and port ''. [2014-08-22 17:39:23] DEBUG[13335][C-00000001] acl.c: Multiple addresses. Using the first only [2014-08-22 17:39:23] DEBUG[13335][C-00000001] acl.c: Not an IPv4 nor IPv6 address, cannot get port. [2014-08-22 17:39:23] DEBUG[13335][C-00000001] acl.c: Attached to given IP address [2014-08-22 17:39:23] DEBUG[13333] manager.c: Examining AMI event: Event: RTCPReceived Privilege: reporting,all SystemName: sipqa Channel: SIP/mlcm800-00000000 ChannelState: 6 ChannelStateDesc: Up CallerIDNum: mlcm800 CallerIDName: Mitch ConnectedLineNum: ConnectedLineName: AccountCode: Context: LocalSets Exten: 850 Priority: 10 Uniqueid: sipqa-1408747145.1 To: 127.0.1.1:0 From: 192.168.5.5:61155 RTT: 0.0202 SSRC: 0x271ede02 PT: 200(SR) ReportCount: 1 SentNTP: 1408747163.17578868613120 SentRTP: 2398065392 SentPackets: 885 SentOctets: 136140 Report0SourceSSRC: 0x5d521743 Report0FractionLost: 0 Report0CumulativeLost: 0 Report0HighestSequence: 49771 Report0SequenceNumberCycles: 0 Report0IAJitter: 0 Report0LSR: 1159247584 Report0DLSR: 2.5887 [2014-08-22 17:39:23] DEBUG[13337][C-00000002] channel.c: Scheduling timer at (56 requested / 56 actual) timer ticks per second [2014-08-22 17:39:23] DEBUG[13337][C-00000002] channel.c: Scheduling timer at (0 requested / 0 actual) timer ticks per second [2014-08-22 17:39:23] DEBUG[13337][C-00000002] channel.c: Scheduling timer at (0 requested / 0 actual) timer ticks per second [2014-08-22 17:39:23] DEBUG[13337][C-00000002] channel.c: Scheduling timer at (0 requested / 0 actual) timer ticks per second [2014-08-22 17:39:23] DEBUG[13337][C-00000002] pbx.c: Result of 'EXTEN' is '850' [2014-08-22 17:39:23] DEBUG[13337][C-00000002] pbx.c: Launching 'MeetMeCount' [2014-08-22 17:39:23] VERBOSE[13337][C-00000002] pbx.c: -- Executing [850@LocalSets:4] MeetMeCount("SIP/mlc296-00000001", "850,CONFCOUNT") in new stack [2014-08-22 17:39:23] DEBUG[13333] manager.c: Examining AMI event: Event: Newexten Privilege: call,all SystemName: sipqa Channel: SIP/mlc296-00000001 ChannelState: 6 ChannelStateDesc: Up CallerIDNum: mlc296 CallerIDName: Mitch Digium ConnectedLineNum: ConnectedLineName: AccountCode: Context: LocalSets Exten: 850 Priority: 4 Uniqueid: sipqa-1408747159.3 Extension: 850 Application: MeetMeCount AppData: 850,CONFCOUNT [2014-08-22 17:39:23] DEBUG[13337][C-00000002] app_meetme.c: The requested confno is '850'? [2014-08-22 17:39:23] DEBUG[13337][C-00000002] app_meetme.c: Does conf 850 match 850? [2014-08-22 17:39:23] DEBUG[13333] manager.c: Examining AMI event: Event: VarSet Privilege: dialplan,all SystemName: sipqa Channel: SIP/mlc296-00000001 ChannelState: 6 ChannelStateDesc: Up CallerIDNum: mlc296 CallerIDName: Mitch Digium ConnectedLineNum: ConnectedLineName: AccountCode: Context: LocalSets Exten: 850 Priority: 4 Uniqueid: sipqa-1408747159.3 Variable: CONFCOUNT Value: 1 [2014-08-22 17:39:23] DEBUG[13337][C-00000002] pbx.c: Result of 'CONFCOUNT' is '1' [2014-08-22 17:39:23] DEBUG[13337][C-00000002] pbx.c: Result of 'EXTEN' is '850' [2014-08-22 17:39:23] DEBUG[13337][C-00000002] pbx.c: Launching 'Verbose' [2014-08-22 17:39:23] VERBOSE[13337][C-00000002] pbx.c: -- Executing [850@LocalSets:5] Verbose("SIP/mlc296-00000001", "2,1 callers in 850") in new stack [2014-08-22 17:39:23] DEBUG[13333] manager.c: Examining AMI event: Event: Newexten Privilege: call,all SystemName: sipqa Channel: SIP/mlc296-00000001 ChannelState: 6 ChannelStateDesc: Up CallerIDNum: mlc296 CallerIDName: Mitch Digium ConnectedLineNum: ConnectedLineName: AccountCode: Context: LocalSets Exten: 850 Priority: 5 Uniqueid: sipqa-1408747159.3 Extension: 850 Application: Verbose AppData: 2,1 callers in 850 [2014-08-22 17:39:23] VERBOSE[13337][C-00000002] app_verbose.c: == 1 callers in 850 [2014-08-22 17:39:23] DEBUG[13337][C-00000002] pbx.c: Result of 'CONFCOUNT' is '1' [2014-08-22 17:39:23] DEBUG[13337][C-00000002] pbx.c: Expression result is '0' [2014-08-22 17:39:23] DEBUG[13337][C-00000002] pbx.c: Launching 'GotoIf' [2014-08-22 17:39:23] VERBOSE[13337][C-00000002] pbx.c: -- Executing [850@LocalSets:6] GotoIf("SIP/mlc296-00000001", "0?join") in new stack [2014-08-22 17:39:23] DEBUG[13333] manager.c: Examining AMI event: Event: Newexten Privilege: call,all SystemName: sipqa Channel: SIP/mlc296-00000001 ChannelState: 6 ChannelStateDesc: Up CallerIDNum: mlc296 CallerIDName: Mitch Digium ConnectedLineNum: ConnectedLineName: AccountCode: Context: LocalSets Exten: 850 Priority: 6 Uniqueid: sipqa-1408747159.3 Extension: 850 Application: GotoIf AppData: 0?join [2014-08-22 17:39:23] DEBUG[13337][C-00000002] pbx.c: Not taking any branch [2014-08-22 17:39:23] DEBUG[13337][C-00000002] pbx.c: Result of 'CONFCOUNT' is '1' [2014-08-22 17:39:23] DEBUG[13337][C-00000002] pbx.c: Expression result is '1' [2014-08-22 17:39:23] DEBUG[13337][C-00000002] pbx.c: Launching 'GotoIf' [2014-08-22 17:39:23] VERBOSE[13337][C-00000002] pbx.c: -- Executing [850@LocalSets:7] GotoIf("SIP/mlc296-00000001", "1?join") in new stack [2014-08-22 17:39:23] DEBUG[13333] manager.c: Examining AMI event: Event: Newexten Privilege: call,all SystemName: sipqa Channel: SIP/mlc296-00000001 ChannelState: 6 ChannelStateDesc: Up CallerIDNum: mlc296 CallerIDName: Mitch Digium ConnectedLineNum: ConnectedLineName: AccountCode: Context: LocalSets Exten: 850 Priority: 7 Uniqueid: sipqa-1408747159.3 Extension: 850 Application: GotoIf AppData: 1?join [2014-08-22 17:39:23] VERBOSE[13337][C-00000002] pbx.c: -- Goto (LocalSets,850,10) [2014-08-22 17:39:23] DEBUG[13337][C-00000002] pbx.c: Result of 'EXTEN' is '850' [2014-08-22 17:39:23] DEBUG[13337][C-00000002] pbx.c: Launching 'MeetMe' [2014-08-22 17:39:23] VERBOSE[13337][C-00000002] pbx.c: -- Executing [850@LocalSets:10] MeetMe("SIP/mlc296-00000001", "850,c") in new stack [2014-08-22 17:39:23] DEBUG[13333] manager.c: Examining AMI event: Event: Newexten Privilege: call,all SystemName: sipqa Channel: SIP/mlc296-00000001 ChannelState: 6 ChannelStateDesc: Up CallerIDNum: mlc296 CallerIDName: Mitch Digium ConnectedLineNum: ConnectedLineName: AccountCode: Context: LocalSets Exten: 850 Priority: 10 Uniqueid: sipqa-1408747159.3 Extension: 850 Application: MeetMe AppData: 850,c [2014-08-22 17:39:23] DEBUG[13337][C-00000002] app_meetme.c: The requested confno is '850'? [2014-08-22 17:39:23] DEBUG[13337][C-00000002] app_meetme.c: Does conf 850 match 850? [2014-08-22 17:39:23] DEBUG[13337][C-00000002] channel.c: Scheduling timer at (50 requested / 50 actual) timer ticks per second [2014-08-22 17:39:23] VERBOSE[13337][C-00000002] file.c: -- Playing 'conf-getpin.ulaw' (language 'en') [2014-08-22 17:39:25] DEBUG[13337][C-00000002] res_rtp_asterisk.c: Creating BEGIN DTMF Frame: 52 (4), at 192.168.5.107:4000 [2014-08-22 17:39:25] DTMF[13337][C-00000002] channel.c: DTMF begin '4' received on SIP/mlc296-00000001 [2014-08-22 17:39:25] DEBUG[13333] manager.c: Examining AMI event: Event: DTMFBegin Privilege: dtmf,all SystemName: sipqa Channel: SIP/mlc296-00000001 ChannelState: 6 ChannelStateDesc: Up CallerIDNum: mlc296 CallerIDName: Mitch Digium ConnectedLineNum: ConnectedLineName: AccountCode: Context: LocalSets Exten: 850 Priority: 10 Uniqueid: sipqa-1408747159.3 Digit: 4 Direction: Received [2014-08-22 17:39:25] DTMF[13337][C-00000002] channel.c: DTMF begin ignored '4' on SIP/mlc296-00000001 [2014-08-22 17:39:25] DEBUG[13323] acl.c: Not an IPv4 nor IPv6 address, cannot get port. [2014-08-22 17:39:25] DEBUG[13323] netsock2.c: Splitting 'sipqa' into... [2014-08-22 17:39:25] DEBUG[13323] netsock2.c: ...host 'sipqa' and port ''. [2014-08-22 17:39:25] DEBUG[13323] acl.c: Multiple addresses. Using the first only [2014-08-22 17:39:25] DEBUG[13323] acl.c: Not an IPv4 nor IPv6 address, cannot get port. [2014-08-22 17:39:25] DEBUG[13323] acl.c: Attached to given IP address [2014-08-22 17:39:25] DEBUG[13333] manager.c: Examining AMI event: Event: RTCPSent Privilege: reporting,all SystemName: sipqa Channel: SIP/mlc296-00000001 ChannelState: 6 ChannelStateDesc: Up CallerIDNum: mlc296 CallerIDName: Mitch Digium ConnectedLineNum: ConnectedLineName: AccountCode: Context: LocalSets Exten: 850 Priority: 10 Uniqueid: sipqa-1408747159.3 To: 192.168.5.107:4001 From: 127.0.1.1:0 SSRC: 0x61f08792 PT: 200(SR) ReportCount: 1 SentNTP: 1408747165.1233670144 SentRTP: 39680 SentPackets: 248 SentOctets: 39680 Report0SourceSSRC: 0x0bfb93d8 Report0FractionLost: 0 Report0CumulativeLost: 0 Report0HighestSequence: 942 Report0SequenceNumberCycles: 0 Report0IAJitter: 0 Report0LSR: 0 Report0DLSR: 0.0000 [2014-08-22 17:39:25] DEBUG[13337][C-00000002] res_rtp_asterisk.c: Got RTCP report of 64 bytes [2014-08-22 17:39:25] DEBUG[13337][C-00000002] acl.c: Not an IPv4 nor IPv6 address, cannot get port. [2014-08-22 17:39:25] DEBUG[13337][C-00000002] netsock2.c: Splitting 'sipqa' into... [2014-08-22 17:39:25] DEBUG[13337][C-00000002] netsock2.c: ...host 'sipqa' and port ''. [2014-08-22 17:39:25] DEBUG[13337][C-00000002] acl.c: Multiple addresses. Using the first only [2014-08-22 17:39:25] DEBUG[13337][C-00000002] acl.c: Not an IPv4 nor IPv6 address, cannot get port. [2014-08-22 17:39:25] DEBUG[13337][C-00000002] acl.c: Attached to given IP address [2014-08-22 17:39:25] DEBUG[13333] manager.c: Examining AMI event: Event: RTCPReceived Privilege: reporting,all SystemName: sipqa Channel: SIP/mlc296-00000001 ChannelState: 6 ChannelStateDesc: Up CallerIDNum: mlc296 CallerIDName: Mitch Digium ConnectedLineNum: ConnectedLineName: AccountCode: Context: LocalSets Exten: 850 Priority: 10 Uniqueid: sipqa-1408747159.3 To: 127.0.1.1:0 From: 192.168.5.107:4001 RTT: 0.4000 SSRC: 0x0bfb93d8 PT: 200(SR) ReportCount: 1 SentNTP: 2128928134.17584015298560 SentRTP: 392168276 SentPackets: 250 SentOctets: 39220 Report0SourceSSRC: 0x61f08792 Report0FractionLost: 0 Report0CumulativeLost: 0 Report0HighestSequence: 21308 Report0SequenceNumberCycles: 0 Report0IAJitter: 45 Report0LSR: 1159548186 Report0DLSR: 0.0400 [2014-08-22 17:39:25] DEBUG[13337][C-00000002] res_rtp_asterisk.c: Creating END DTMF Frame: 52 (4), at 192.168.5.107:4000 [2014-08-22 17:39:25] DEBUG[13333] manager.c: Examining AMI event: Event: DTMFEnd Privilege: dtmf,all SystemName: sipqa Channel: SIP/mlc296-00000001 ChannelState: 6 ChannelStateDesc: Up CallerIDNum: mlc296 CallerIDName: Mitch Digium ConnectedLineNum: ConnectedLineName: AccountCode: Context: LocalSets Exten: 850 Priority: 10 Uniqueid: sipqa-1408747159.3 Digit: 4 DurationMs: 140 Direction: Received [2014-08-22 17:39:25] DTMF[13337][C-00000002] channel.c: DTMF end '4' received on SIP/mlc296-00000001, duration 140 ms [2014-08-22 17:39:25] DTMF[13337][C-00000002] channel.c: DTMF end passthrough '4' on SIP/mlc296-00000001 [2014-08-22 17:39:25] DEBUG[13337][C-00000002] channel.c: Scheduling timer at (0 requested / 0 actual) timer ticks per second [2014-08-22 17:39:25] DEBUG[13337][C-00000002] channel.c: Scheduling timer at (0 requested / 0 actual) timer ticks per second [2014-08-22 17:39:25] DEBUG[13337][C-00000002] res_rtp_asterisk.c: Creating BEGIN DTMF Frame: 55 (7), at 192.168.5.107:4000 [2014-08-22 17:39:25] DTMF[13337][C-00000002] channel.c: DTMF begin '7' received on SIP/mlc296-00000001 [2014-08-22 17:39:25] DEBUG[13333] manager.c: Examining AMI event: Event: DTMFBegin Privilege: dtmf,all SystemName: sipqa Channel: SIP/mlc296-00000001 ChannelState: 6 ChannelStateDesc: Up CallerIDNum: mlc296 CallerIDName: Mitch Digium ConnectedLineNum: ConnectedLineName: AccountCode: Context: LocalSets Exten: 850 Priority: 10 Uniqueid: sipqa-1408747159.3 Digit: 7 Direction: Received [2014-08-22 17:39:25] DTMF[13337][C-00000002] channel.c: DTMF begin ignored '7' on SIP/mlc296-00000001 [2014-08-22 17:39:25] DEBUG[13323] acl.c: Not an IPv4 nor IPv6 address, cannot get port. [2014-08-22 17:39:25] DEBUG[13323] netsock2.c: Splitting 'sipqa' into... [2014-08-22 17:39:25] DEBUG[13323] netsock2.c: ...host 'sipqa' and port ''. [2014-08-22 17:39:25] DEBUG[13323] acl.c: Multiple addresses. Using the first only [2014-08-22 17:39:25] DEBUG[13323] acl.c: Not an IPv4 nor IPv6 address, cannot get port. [2014-08-22 17:39:25] DEBUG[13323] acl.c: Attached to given IP address [2014-08-22 17:39:25] DEBUG[13333] manager.c: Examining AMI event: Event: RTCPSent Privilege: reporting,all SystemName: sipqa Channel: SIP/mlcm800-00000000 ChannelState: 6 ChannelStateDesc: Up CallerIDNum: mlcm800 CallerIDName: Mitch ConnectedLineNum: ConnectedLineName: AccountCode: Context: LocalSets Exten: 850 Priority: 10 Uniqueid: sipqa-1408747145.1 To: 192.168.5.5:61155 From: 127.0.1.1:0 SSRC: 0x5d521743 PT: 200(SR) ReportCount: 1 SentNTP: 1408747165.2930319360 SentRTP: 159616 SentPackets: 891 SentOctets: 142560 Report0SourceSSRC: 0x271ede02 Report0FractionLost: 0 Report0CumulativeLost: 0 Report0HighestSequence: 1005 Report0SequenceNumberCycles: 0 Report0IAJitter: 0 Report0LSR: 1159412450 Report0DLSR: 2.4120 [2014-08-22 17:39:25] DEBUG[13337][C-00000002] res_rtp_asterisk.c: Creating END DTMF Frame: 55 (7), at 192.168.5.107:4000 [2014-08-22 17:39:25] DTMF[13337][C-00000002] channel.c: DTMF end '7' received on SIP/mlc296-00000001, duration 140 ms [2014-08-22 17:39:25] DEBUG[13333] manager.c: Examining AMI event: Event: DTMFEnd Privilege: dtmf,all SystemName: sipqa Channel: SIP/mlc296-00000001 ChannelState: 6 ChannelStateDesc: Up CallerIDNum: mlc296 CallerIDName: Mitch Digium ConnectedLineNum: ConnectedLineName: AccountCode: Context: LocalSets Exten: 850 Priority: 10 Uniqueid: sipqa-1408747159.3 Digit: 7 DurationMs: 140 Direction: Received [2014-08-22 17:39:25] DTMF[13337][C-00000002] channel.c: DTMF end passthrough '7' on SIP/mlc296-00000001 [2014-08-22 17:39:25] DEBUG[13335][C-00000001] res_rtp_asterisk.c: Got RTCP report of 80 bytes [2014-08-22 17:39:25] DEBUG[13335][C-00000001] acl.c: Not an IPv4 nor IPv6 address, cannot get port. [2014-08-22 17:39:25] DEBUG[13335][C-00000001] netsock2.c: Splitting 'sipqa' into... [2014-08-22 17:39:25] DEBUG[13335][C-00000001] netsock2.c: ...host 'sipqa' and port ''. [2014-08-22 17:39:25] DEBUG[13335][C-00000001] acl.c: Multiple addresses. Using the first only [2014-08-22 17:39:25] DEBUG[13335][C-00000001] acl.c: Not an IPv4 nor IPv6 address, cannot get port. [2014-08-22 17:39:25] DEBUG[13335][C-00000001] acl.c: Attached to given IP address [2014-08-22 17:39:25] DEBUG[13333] manager.c: Examining AMI event: Event: RTCPReceived Privilege: reporting,all SystemName: sipqa Channel: SIP/mlcm800-00000000 ChannelState: 6 ChannelStateDesc: Up CallerIDNum: mlcm800 CallerIDName: Mitch ConnectedLineNum: ConnectedLineName: AccountCode: Context: LocalSets Exten: 850 Priority: 10 Uniqueid: sipqa-1408747145.1 To: 127.0.1.1:0 From: 192.168.5.5:61155 RTT: 0.0193 SSRC: 0x271ede02 PT: 200(SR) ReportCount: 1 SentNTP: 1408747165.17529607106560 SentRTP: 2398086924 SentPackets: 1019 SentOctets: 157580 Report0SourceSSRC: 0x5d521743 Report0FractionLost: 0 Report0CumulativeLost: 0 Report0HighestSequence: 49905 Report0SequenceNumberCycles: 0 Report0IAJitter: 0 Report0LSR: 1159575333 Report0DLSR: 0.2792 [2014-08-22 17:39:26] DEBUG[13337][C-00000002] res_rtp_asterisk.c: Creating BEGIN DTMF Frame: 56 (8), at 192.168.5.107:4000 [2014-08-22 17:39:26] DEBUG[13333] manager.c: Examining AMI event: Event: DTMFBegin Privilege: dtmf,all SystemName: sipqa Channel: SIP/mlc296-00000001 ChannelState: 6 ChannelStateDesc: Up CallerIDNum: mlc296 CallerIDName: Mitch Digium ConnectedLineNum: ConnectedLineName: AccountCode: Context: LocalSets Exten: 850 Priority: 10 Uniqueid: sipqa-1408747159.3 Digit: 8 Direction: Received [2014-08-22 17:39:26] DTMF[13337][C-00000002] channel.c: DTMF begin '8' received on SIP/mlc296-00000001 [2014-08-22 17:39:26] DTMF[13337][C-00000002] channel.c: DTMF begin ignored '8' on SIP/mlc296-00000001 [2014-08-22 17:39:26] DEBUG[13337][C-00000002] res_rtp_asterisk.c: Creating END DTMF Frame: 56 (8), at 192.168.5.107:4000 [2014-08-22 17:39:26] DEBUG[13333] manager.c: Examining AMI event: Event: DTMFEnd Privilege: dtmf,all SystemName: sipqa Channel: SIP/mlc296-00000001 ChannelState: 6 ChannelStateDesc: Up CallerIDNum: mlc296 CallerIDName: Mitch Digium ConnectedLineNum: ConnectedLineName: AccountCode: Context: LocalSets Exten: 850 Priority: 10 Uniqueid: sipqa-1408747159.3 Digit: 8 DurationMs: 120 Direction: Received [2014-08-22 17:39:26] DTMF[13337][C-00000002] channel.c: DTMF end '8' received on SIP/mlc296-00000001, duration 120 ms [2014-08-22 17:39:26] DTMF[13337][C-00000002] channel.c: DTMF end passthrough '8' on SIP/mlc296-00000001 [2014-08-22 17:39:26] DEBUG[13337][C-00000002] res_rtp_asterisk.c: Creating BEGIN DTMF Frame: 53 (5), at 192.168.5.107:4000 [2014-08-22 17:39:26] DEBUG[13333] manager.c: Examining AMI event: Event: DTMFBegin Privilege: dtmf,all SystemName: sipqa Channel: SIP/mlc296-00000001 ChannelState: 6 ChannelStateDesc: Up CallerIDNum: mlc296 CallerIDName: Mitch Digium ConnectedLineNum: ConnectedLineName: AccountCode: Context: LocalSets Exten: 850 Priority: 10 Uniqueid: sipqa-1408747159.3 Digit: 5 Direction: Received [2014-08-22 17:39:26] DTMF[13337][C-00000002] channel.c: DTMF begin '5' received on SIP/mlc296-00000001 [2014-08-22 17:39:26] DTMF[13337][C-00000002] channel.c: DTMF begin ignored '5' on SIP/mlc296-00000001 [2014-08-22 17:39:26] DEBUG[13337][C-00000002] res_rtp_asterisk.c: Creating END DTMF Frame: 53 (5), at 192.168.5.107:4000 [2014-08-22 17:39:26] DEBUG[13333] manager.c: Examining AMI event: Event: DTMFEnd Privilege: dtmf,all SystemName: sipqa Channel: SIP/mlc296-00000001 ChannelState: 6 ChannelStateDesc: Up CallerIDNum: mlc296 CallerIDName: Mitch Digium ConnectedLineNum: ConnectedLineName: AccountCode: Context: LocalSets Exten: 850 Priority: 10 Uniqueid: sipqa-1408747159.3 Digit: 5 DurationMs: 120 Direction: Received [2014-08-22 17:39:26] DTMF[13337][C-00000002] channel.c: DTMF end '5' received on SIP/mlc296-00000001, duration 120 ms [2014-08-22 17:39:26] DTMF[13337][C-00000002] channel.c: DTMF end passthrough '5' on SIP/mlc296-00000001 [2014-08-22 17:39:26] DEBUG[13337][C-00000002] res_rtp_asterisk.c: Creating BEGIN DTMF Frame: 35 (#), at 192.168.5.107:4000 [2014-08-22 17:39:26] DEBUG[13333] manager.c: Examining AMI event: Event: DTMFBegin Privilege: dtmf,all SystemName: sipqa Channel: SIP/mlc296-00000001 ChannelState: 6 ChannelStateDesc: Up CallerIDNum: mlc296 CallerIDName: Mitch Digium ConnectedLineNum: ConnectedLineName: AccountCode: Context: LocalSets Exten: 850 Priority: 10 Uniqueid: sipqa-1408747159.3 Digit: # Direction: Received [2014-08-22 17:39:26] DTMF[13337][C-00000002] channel.c: DTMF begin '#' received on SIP/mlc296-00000001 [2014-08-22 17:39:26] DTMF[13337][C-00000002] channel.c: DTMF begin ignored '#' on SIP/mlc296-00000001 [2014-08-22 17:39:26] DEBUG[13337][C-00000002] res_rtp_asterisk.c: Creating END DTMF Frame: 35 (#), at 192.168.5.107:4000 [2014-08-22 17:39:27] DEBUG[13333] manager.c: Examining AMI event: Event: DTMFEnd Privilege: dtmf,all SystemName: sipqa Channel: SIP/mlc296-00000001 ChannelState: 6 ChannelStateDesc: Up CallerIDNum: mlc296 CallerIDName: Mitch Digium ConnectedLineNum: ConnectedLineName: AccountCode: Context: LocalSets Exten: 850 Priority: 10 Uniqueid: sipqa-1408747159.3 Digit: # DurationMs: 130 Direction: Received [2014-08-22 17:39:27] DTMF[13337][C-00000002] channel.c: DTMF end '#' received on SIP/mlc296-00000001, duration 130 ms [2014-08-22 17:39:27] DTMF[13337][C-00000002] channel.c: DTMF end passthrough '#' on SIP/mlc296-00000001 [2014-08-22 17:39:27] VERBOSE[13337][C-00000002] app_meetme.c: > Starting recording of MeetMe Conference 850 into file (null).(null). [2014-08-22 17:39:27] DEBUG[13333] manager.c: Examining AMI event: Event: VarSet Privilege: dialplan,all SystemName: sipqa Channel: SIP/mlc296-00000001 ChannelState: 6 ChannelStateDesc: Up CallerIDNum: mlc296 CallerIDName: Mitch Digium ConnectedLineNum: ConnectedLineName: AccountCode: Context: LocalSets Exten: 850 Priority: 10 Uniqueid: sipqa-1408747159.3 Variable: MEETMEUNIQUEID Value: sipqa-1408747145.1 [2014-08-22 17:39:27] DEBUG[13337][C-00000002] res_rtp_asterisk.c: Difference is 12624, ms is 1598 [2014-08-22 17:39:27] DEBUG[13337][C-00000002] channel.c: Scheduling timer at (50 requested / 50 actual) timer ticks per second [2014-08-22 17:39:27] VERBOSE[13337][C-00000002] file.c: -- Playing 'conf-onlyone.ulaw' (language 'en') [2014-08-22 17:39:29] DEBUG[13335][C-00000001] res_rtp_asterisk.c: Got RTCP report of 80 bytes [2014-08-22 17:39:29] DEBUG[13335][C-00000001] acl.c: Not an IPv4 nor IPv6 address, cannot get port. [2014-08-22 17:39:29] DEBUG[13335][C-00000001] netsock2.c: Splitting 'sipqa' into... [2014-08-22 17:39:29] DEBUG[13335][C-00000001] netsock2.c: ...host 'sipqa' and port ''. [2014-08-22 17:39:29] DEBUG[13335][C-00000001] acl.c: Multiple addresses. Using the first only [2014-08-22 17:39:29] DEBUG[13335][C-00000001] acl.c: Not an IPv4 nor IPv6 address, cannot get port. [2014-08-22 17:39:29] DEBUG[13335][C-00000001] acl.c: Attached to given IP address [2014-08-22 17:39:29] DEBUG[13333] manager.c: Examining AMI event: Event: RTCPReceived Privilege: reporting,all SystemName: sipqa Channel: SIP/mlcm800-00000000 ChannelState: 6 ChannelStateDesc: Up CallerIDNum: mlcm800 CallerIDName: Mitch ConnectedLineNum: ConnectedLineName: AccountCode: Context: LocalSets Exten: 850 Priority: 10 Uniqueid: sipqa-1408747145.1 To: 127.0.1.1:0 From: 192.168.5.5:61155 RTT: 0.0237 SSRC: 0x271ede02 PT: 200(SR) ReportCount: 1 SentNTP: 1408747169.17533107589120 SentRTP: 2398118551 SentPackets: 1217 SentOctets: 189260 Report0SourceSSRC: 0x5d521743 Report0FractionLost: 0 Report0CumulativeLost: 0 Report0HighestSequence: 50103 Report0SequenceNumberCycles: 0 Report0IAJitter: 0 Report0LSR: 1159575333 Report0DLSR: 4.2326 [2014-08-22 17:39:30] DEBUG[13323] acl.c: Not an IPv4 nor IPv6 address, cannot get port. [2014-08-22 17:39:30] DEBUG[13323] netsock2.c: Splitting 'sipqa' into... [2014-08-22 17:39:30] DEBUG[13323] netsock2.c: ...host 'sipqa' and port ''. [2014-08-22 17:39:30] DEBUG[13323] acl.c: Multiple addresses. Using the first only [2014-08-22 17:39:30] DEBUG[13323] acl.c: Not an IPv4 nor IPv6 address, cannot get port. [2014-08-22 17:39:30] DEBUG[13323] acl.c: Attached to given IP address [2014-08-22 17:39:30] DEBUG[13333] manager.c: Examining AMI event: Event: RTCPSent Privilege: reporting,all SystemName: sipqa Channel: SIP/mlc296-00000001 ChannelState: 6 ChannelStateDesc: Up CallerIDNum: mlc296 CallerIDName: Mitch Digium ConnectedLineNum: ConnectedLineName: AccountCode: Context: LocalSets Exten: 850 Priority: 10 Uniqueid: sipqa-1408747159.3 To: 192.168.5.107:4001 From: 127.0.1.1:0 SSRC: 0x61f08792 PT: 200(SR) ReportCount: 1 SentNTP: 1408747170.1231405056 SentRTP: 79664 SentPackets: 419 SentOctets: 67040 Report0SourceSSRC: 0x0bfb93d8 Report0FractionLost: 0 Report0CumulativeLost: 0 Report0HighestSequence: 1196 Report0SequenceNumberCycles: 0 Report0IAJitter: 0 Report0LSR: 1543908229 Report0DLSR: 4.9520 [2014-08-22 17:39:30] DEBUG[13337][C-00000002] res_rtp_asterisk.c: Got RTCP report of 64 bytes [2014-08-22 17:39:30] DEBUG[13337][C-00000002] acl.c: Not an IPv4 nor IPv6 address, cannot get port. [2014-08-22 17:39:30] DEBUG[13337][C-00000002] netsock2.c: Splitting 'sipqa' into... [2014-08-22 17:39:30] DEBUG[13337][C-00000002] netsock2.c: ...host 'sipqa' and port ''. [2014-08-22 17:39:30] DEBUG[13337][C-00000002] acl.c: Multiple addresses. Using the first only [2014-08-22 17:39:30] DEBUG[13337][C-00000002] acl.c: Not an IPv4 nor IPv6 address, cannot get port. [2014-08-22 17:39:30] DEBUG[13337][C-00000002] acl.c: Attached to given IP address [2014-08-22 17:39:30] DEBUG[13333] manager.c: Examining AMI event: Event: RTCPReceived Privilege: reporting,all SystemName: sipqa Channel: SIP/mlc296-00000001 ChannelState: 6 ChannelStateDesc: Up CallerIDNum: mlc296 CallerIDName: Mitch Digium ConnectedLineNum: ConnectedLineName: AccountCode: Context: LocalSets Exten: 850 Priority: 10 Uniqueid: sipqa-1408747159.3 To: 127.0.1.1:0 From: 192.168.5.107:4001 RTT: 69813.2094 SSRC: 0x0bfb93d8 PT: 200(SR) ReportCount: 1 SentNTP: 2128928139.17581550051328 SentRTP: 2281571156 SentPackets: 504 SentOctets: 74712 Report0SourceSSRC: 0x61f08792 Report0FractionLost: 0 Report0CumulativeLost: 0 Report0HighestSequence: 21479 Report0SequenceNumberCycles: 0 Report0IAJitter: 0 Report0LSR: 1159875830 Report0DLSR: 0.0500 [2014-08-22 17:39:30] DEBUG[13337][C-00000002] channel.c: Scheduling timer at (125 requested / 125 actual) timer ticks per second [2014-08-22 17:39:30] DEBUG[13337][C-00000002] channel.c: Scheduling timer at (0 requested / 0 actual) timer ticks per second [2014-08-22 17:39:30] DEBUG[13337][C-00000002] channel.c: Scheduling timer at (0 requested / 0 actual) timer ticks per second [2014-08-22 17:39:30] DEBUG[13337][C-00000002] channel.c: Scheduling timer at (0 requested / 0 actual) timer ticks per second [2014-08-22 17:39:30] DEBUG[13337][C-00000002] channel.c: Set channel SIP/mlc296-00000001 to write format slin [2014-08-22 17:39:30] DEBUG[13337][C-00000002] channel.c: Set channel SIP/mlc296-00000001 to read format slin [2014-08-22 17:39:30] DEBUG[13337][C-00000002] app_meetme.c: Placed channel SIP/mlc296-00000001 in DAHDI conf 1023 [2014-08-22 17:39:30] DEBUG[13333] manager.c: Examining AMI event: Event: MeetmeJoin Privilege: call,all SystemName: sipqa Meetme: 850 Channel: SIP/mlc296-00000001 ChannelState: 6 ChannelStateDesc: Up CallerIDNum: mlc296 CallerIDName: Mitch Digium ConnectedLineNum: ConnectedLineName: AccountCode: Context: LocalSets Exten: 850 Priority: 10 Uniqueid: sipqa-1408747159.3 User: 2 Duration: 4 [2014-08-22 17:39:30] DEBUG[13323] acl.c: Not an IPv4 nor IPv6 address, cannot get port. [2014-08-22 17:39:30] DEBUG[13323] netsock2.c: Splitting 'sipqa' into... [2014-08-22 17:39:30] DEBUG[13323] netsock2.c: ...host 'sipqa' and port ''. [2014-08-22 17:39:30] DEBUG[13323] acl.c: Multiple addresses. Using the first only [2014-08-22 17:39:30] DEBUG[13323] acl.c: Not an IPv4 nor IPv6 address, cannot get port. [2014-08-22 17:39:30] DEBUG[13323] acl.c: Attached to given IP address [2014-08-22 17:39:30] DEBUG[13333] manager.c: Examining AMI event: Event: RTCPSent Privilege: reporting,all SystemName: sipqa Channel: SIP/mlcm800-00000000 ChannelState: 6 ChannelStateDesc: Up CallerIDNum: mlcm800 CallerIDName: Mitch ConnectedLineNum: ConnectedLineName: AccountCode: Context: LocalSets Exten: 850 Priority: 10 Uniqueid: sipqa-1408747145.1 To: 192.168.5.5:61155 From: 127.0.1.1:0 SSRC: 0x5d521743 PT: 200(SR) ReportCount: 1 SentNTP: 1408747170.2929037312 SentRTP: 199616 SentPackets: 1141 SentOctets: 182560 Report0SourceSSRC: 0x271ede02 Report0FractionLost: 0 Report0CumulativeLost: 0 Report0HighestSequence: 1254 Report0SequenceNumberCycles: 0 Report0IAJitter: 0 Report0LSR: 1159847933 Report0DLSR: 0.7660 [2014-08-22 17:39:30] DEBUG[13337][C-00000002] dsp.c: Setup tone 1100 Hz, 500 ms, block_size=160, hits_required=21 [2014-08-22 17:39:30] DEBUG[13337][C-00000002] dsp.c: Setup tone 2100 Hz, 2600 ms, block_size=160, hits_required=116 [2014-08-22 17:39:30] DEBUG[13337][C-00000002] res_rtp_asterisk.c: Difference is 1112, ms is 159 [2014-08-22 17:39:33] DEBUG[13335][C-00000001] res_rtp_asterisk.c: Got RTCP report of 80 bytes [2014-08-22 17:39:33] DEBUG[13335][C-00000001] acl.c: Not an IPv4 nor IPv6 address, cannot get port. [2014-08-22 17:39:33] DEBUG[13335][C-00000001] netsock2.c: Splitting 'sipqa' into... [2014-08-22 17:39:33] DEBUG[13335][C-00000001] netsock2.c: ...host 'sipqa' and port ''. [2014-08-22 17:39:33] DEBUG[13335][C-00000001] acl.c: Multiple addresses. Using the first only [2014-08-22 17:39:33] DEBUG[13335][C-00000001] acl.c: Not an IPv4 nor IPv6 address, cannot get port. [2014-08-22 17:39:33] DEBUG[13335][C-00000001] acl.c: Attached to given IP address [2014-08-22 17:39:33] DEBUG[13333] manager.c: Examining AMI event: Event: RTCPReceived Privilege: reporting,all SystemName: sipqa Channel: SIP/mlcm800-00000000 ChannelState: 6 ChannelStateDesc: Up CallerIDNum: mlcm800 CallerIDName: Mitch ConnectedLineNum: ConnectedLineName: AccountCode: Context: LocalSets Exten: 850 Priority: 10 Uniqueid: sipqa-1408747145.1 To: 127.0.1.1:0 From: 192.168.5.5:61155 RTT: 0.0246 SSRC: 0x271ede02 PT: 200(SR) ReportCount: 1 SentNTP: 1408747173.17539051388928 SentRTP: 2398149771 SentPackets: 1412 SentOctets: 220460 Report0SourceSSRC: 0x5d521743 Report0FractionLost: 0 Report0CumulativeLost: 0 Report0HighestSequence: 50298 Report0SequenceNumberCycles: 0 Report0IAJitter: 0 Report0LSR: 1159902992 Report0DLSR: 3.1354 [2014-08-22 17:39:34] DEBUG[13323] chan_sip.c: = Looking for Call ID: MTI0NDU5ZDkxNDJmNzdlYzhmMzU3OGI0NzJlY2Q3ODE (Checking From) --From tag 87fc1f02 --To-tag as433fda8a [2014-08-22 17:39:34] DEBUG[13323][C-00000001] chan_sip.c: **** Received BYE (8) - Command in SIP BYE [2014-08-22 17:39:34] DEBUG[13323][C-00000001] netsock2.c: Splitting '192.168.5.5:12948' into... [2014-08-22 17:39:34] DEBUG[13323][C-00000001] netsock2.c: ...host '192.168.5.5' and port '12948'. [2014-08-22 17:39:34] DEBUG[13323][C-00000001] chan_sip.c: Setting SIP_ALREADYGONE on dialog MTI0NDU5ZDkxNDJmNzdlYzhmMzU3OGI0NzJlY2Q3ODE [2014-08-22 17:39:34] DEBUG[13333] manager.c: Examining AMI event: Event: VarSet Privilege: dialplan,all SystemName: sipqa Channel: SIP/mlcm800-00000000 ChannelState: 6 ChannelStateDesc: Up CallerIDNum: mlcm800 CallerIDName: Mitch ConnectedLineNum: ConnectedLineName: AccountCode: Context: LocalSets Exten: 850 Priority: 10 Uniqueid: sipqa-1408747145.1 Variable: RTPAUDIOQOS Value: ssrc=1565660995;themssrc=656334338;lp=0;rxjitter=0.000000;rxcount=1448;txjitter=0.000036;txcount=1337;rlp=0;rtt=0.024559 [2014-08-22 17:39:34] DEBUG[13333] manager.c: Examining AMI event: Event: VarSet Privilege: dialplan,all SystemName: sipqa Channel: SIP/mlcm800-00000000 ChannelState: 6 ChannelStateDesc: Up CallerIDNum: mlcm800 CallerIDName: Mitch ConnectedLineNum: ConnectedLineName: AccountCode: Context: LocalSets Exten: 850 Priority: 10 Uniqueid: sipqa-1408747145.1 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; [2014-08-22 17:39:34] DEBUG[13333] manager.c: Examining AMI event: Event: VarSet Privilege: dialplan,all SystemName: sipqa Channel: SIP/mlcm800-00000000 ChannelState: 6 ChannelStateDesc: Up CallerIDNum: mlcm800 CallerIDName: Mitch ConnectedLineNum: ConnectedLineName: AccountCode: Context: LocalSets Exten: 850 Priority: 10 Uniqueid: sipqa-1408747145.1 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; [2014-08-22 17:39:34] DEBUG[13335][C-00000001] channel.c: Deadlock avoided for write to channel 'SIP/mlcm800-00000000' [2014-08-22 17:39:34] DEBUG[13333] manager.c: Examining AMI event: Event: VarSet Privilege: dialplan,all SystemName: sipqa Channel: SIP/mlcm800-00000000 ChannelState: 6 ChannelStateDesc: Up CallerIDNum: mlcm800 CallerIDName: Mitch ConnectedLineNum: ConnectedLineName: AccountCode: Context: LocalSets Exten: 850 Priority: 10 Uniqueid: sipqa-1408747145.1 Variable: RTPAUDIOQOSRTT Value: minrtt=0.000000;maxrtt=0.000000;avgrtt=0.000000;stdevrtt=0.000000; [2014-08-22 17:39:34] DEBUG[13323][C-00000001] res_rtp_asterisk.c: Setting RTCP address on RTP instance '0x7ffc340627b8' [2014-08-22 17:39:34] DEBUG[13333] manager.c: Examining AMI event: Event: HangupRequest Privilege: call,all SystemName: sipqa Channel: SIP/mlcm800-00000000 ChannelState: 6 ChannelStateDesc: Up CallerIDNum: mlcm800 CallerIDName: Mitch ConnectedLineNum: ConnectedLineName: AccountCode: Context: LocalSets Exten: 850 Priority: 10 Uniqueid: sipqa-1408747145.1 [2014-08-22 17:39:34] DEBUG[13323][C-00000001] chan_sip.c: Received bye, issuing owner hangup [2014-08-22 17:39:34] DEBUG[13323][C-00000001] chan_sip.c: Trying to put 'SIP/2.0 200' onto UDP socket destined for 192.168.5.5:12948 [2014-08-22 17:39:34] DEBUG[13333] manager.c: Examining AMI event: Event: MeetmeLeave Privilege: call,all SystemName: sipqa Meetme: 850 Channel: SIP/mlcm800-00000000 ChannelState: 6 ChannelStateDesc: Up CallerIDNum: mlcm800 CallerIDName: Mitch ConnectedLineNum: ConnectedLineName: AccountCode: Context: LocalSets Exten: 850 Priority: 10 Uniqueid: sipqa-1408747145.1 User: 1 Duration: 23 [2014-08-22 17:39:34] DEBUG[13333] manager.c: Examining AMI event: Event: VarSet Privilege: dialplan,all SystemName: sipqa Channel: SIP/mlcm800-00000000 ChannelState: 6 ChannelStateDesc: Up CallerIDNum: mlcm800 CallerIDName: Mitch ConnectedLineNum: ConnectedLineName: AccountCode: Context: LocalSets Exten: 850 Priority: 10 Uniqueid: sipqa-1408747145.1 Variable: MEETMESECS Value: 23 [2014-08-22 17:39:34] DEBUG[13335][C-00000001] pbx.c: Spawn extension (LocalSets,850,10) exited non-zero on 'SIP/mlcm800-00000000' [2014-08-22 17:39:34] VERBOSE[13335][C-00000001] pbx.c: == Spawn extension (LocalSets, 850, 10) exited non-zero on 'SIP/mlcm800-00000000' [2014-08-22 17:39:34] DEBUG[13335][C-00000001] channel.c: Soft-Hanging (0x10) up channel 'SIP/mlcm800-00000000' [2014-08-22 17:39:34] DEBUG[13333] manager.c: Examining AMI event: Event: SoftHangupRequest Privilege: call,all SystemName: sipqa Channel: SIP/mlcm800-00000000 ChannelState: 6 ChannelStateDesc: Up CallerIDNum: mlcm800 CallerIDName: Mitch ConnectedLineNum: ConnectedLineName: AccountCode: Context: LocalSets Exten: 850 Priority: 10 Uniqueid: sipqa-1408747145.1 Cause: 16 [2014-08-22 17:39:34] DEBUG[13335][C-00000001] channel.c: Hanging up channel 'SIP/mlcm800-00000000' [2014-08-22 17:39:34] DEBUG[13335][C-00000001] chan_sip.c: Hangup call SIP/mlcm800-00000000, SIP callid MTI0NDU5ZDkxNDJmNzdlYzhmMzU3OGI0NzJlY2Q3ODE [2014-08-22 17:39:34] DEBUG[13335][C-00000001] chan_sip.c: Updating call counter for incoming call [2014-08-22 17:39:34] DEBUG[13335][C-00000001] res_rtp_asterisk.c: Setting RTCP address on RTP instance '0x7ffc340627b8' [2014-08-22 17:39:34] DEBUG[13205] devicestate.c: No provider found, checking channel drivers for SIP - mlcm800 [2014-08-22 17:39:34] DEBUG[13205] chan_sip.c: Checking device state for peer mlcm800 [2014-08-22 17:39:34] DEBUG[13205] devicestate.c: Changing state for SIP/mlcm800 - state 1 (Not in use) [2014-08-22 17:39:34] DEBUG[13333] manager.c: Examining AMI event: Event: Hangup Privilege: call,all SystemName: sipqa Channel: SIP/mlcm800-00000000 ChannelState: 6 ChannelStateDesc: Up CallerIDNum: mlcm800 CallerIDName: Mitch ConnectedLineNum: ConnectedLineName: AccountCode: Context: LocalSets Exten: 850 Priority: 10 Uniqueid: sipqa-1408747145.1 Cause: 0 Cause-txt: Unknown [2014-08-22 17:39:34] DEBUG[13330] app_queue.c: Device 'SIP/mlcm800' changed to state '1' (Not in use) but we don't care because they're not a member of any queue. [2014-08-22 17:39:34] DEBUG[13206] cdr.c: Finalized CDR for SIP/mlcm800-00000000 - start 1408747145.670492 answer 1408747145.683941 end 1408747174.649967 dispo ANSWERED [2014-08-22 17:39:34] DEBUG[13205] devicestate.c: No provider found, checking channel drivers for SIP - mlcm800 [2014-08-22 17:39:34] DEBUG[13205] chan_sip.c: Checking device state for peer mlcm800 [2014-08-22 17:39:34] DEBUG[13205] devicestate.c: Changing state for SIP/mlcm800 - state 1 (Not in use) [2014-08-22 17:39:34] DEBUG[13206] res_odbc.c: odbc_release_obj2(0x50779c8) called (obj->txf = (nil)) [2014-08-22 17:39:35] DEBUG[13323] acl.c: Not an IPv4 nor IPv6 address, cannot get port. [2014-08-22 17:39:35] DEBUG[13323] netsock2.c: Splitting 'sipqa' into... [2014-08-22 17:39:35] DEBUG[13323] netsock2.c: ...host 'sipqa' and port ''. [2014-08-22 17:39:35] DEBUG[13323] acl.c: Multiple addresses. Using the first only [2014-08-22 17:39:35] DEBUG[13323] acl.c: Not an IPv4 nor IPv6 address, cannot get port. [2014-08-22 17:39:35] DEBUG[13323] acl.c: Attached to given IP address [2014-08-22 17:39:35] DEBUG[13333] manager.c: Examining AMI event: Event: RTCPSent Privilege: reporting,all SystemName: sipqa Channel: SIP/mlc296-00000001 ChannelState: 6 ChannelStateDesc: Up CallerIDNum: mlc296 CallerIDName: Mitch Digium ConnectedLineNum: ConnectedLineName: AccountCode: Context: LocalSets Exten: 850 Priority: 10 Uniqueid: sipqa-1408747159.3 To: 192.168.5.107:4001 From: 127.0.1.1:0 SSRC: 0x61f08792 PT: 200(SR) ReportCount: 1 SentNTP: 1408747175.1234214912 SentRTP: 119656 SentPackets: 662 SentOctets: 105920 Report0SourceSSRC: 0x0bfb93d8 Report0FractionLost: 0 Report0CumulativeLost: 0 Report0HighestSequence: 1446 Report0SequenceNumberCycles: 0 Report0IAJitter: 1 Report0LSR: 1544236564 Report0DLSR: 4.9520 [2014-08-22 17:39:35] DEBUG[13337][C-00000002] res_rtp_asterisk.c: Got RTCP report of 64 bytes [2014-08-22 17:39:35] DEBUG[13337][C-00000002] acl.c: Not an IPv4 nor IPv6 address, cannot get port. [2014-08-22 17:39:35] DEBUG[13337][C-00000002] netsock2.c: Splitting 'sipqa' into... [2014-08-22 17:39:35] DEBUG[13337][C-00000002] netsock2.c: ...host 'sipqa' and port ''. [2014-08-22 17:39:35] DEBUG[13337][C-00000002] acl.c: Multiple addresses. Using the first only [2014-08-22 17:39:35] DEBUG[13337][C-00000002] acl.c: Not an IPv4 nor IPv6 address, cannot get port. [2014-08-22 17:39:35] DEBUG[13337][C-00000002] acl.c: Attached to given IP address [2014-08-22 17:39:35] DEBUG[13333] manager.c: Examining AMI event: Event: RTCPReceived Privilege: reporting,all SystemName: sipqa Channel: SIP/mlc296-00000001 ChannelState: 6 ChannelStateDesc: Up CallerIDNum: mlc296 CallerIDName: Mitch Digium ConnectedLineNum: ConnectedLineName: AccountCode: Context: LocalSets Exten: 850 Priority: 10 Uniqueid: sipqa-1408747159.3 To: 127.0.1.1:0 From: 192.168.5.107:4001 RTT: 0.3938 SSRC: 0x0bfb93d8 PT: 200(SR) ReportCount: 1 SentNTP: 2128928144.17584015298560 SentRTP: 3348759636 SentPackets: 754 SentOctets: 114712 Report0SourceSSRC: 0x61f08792 Report0FractionLost: 0 Report0CumulativeLost: 0 Report0HighestSequence: 21722 Report0SequenceNumberCycles: 0 Report0IAJitter: 0 Report0LSR: 1160203555 Report0DLSR: 0.0400 [2014-08-22 17:39:40] DEBUG[13323] acl.c: Not an IPv4 nor IPv6 address, cannot get port. [2014-08-22 17:39:40] DEBUG[13323] netsock2.c: Splitting 'sipqa' into... [2014-08-22 17:39:40] DEBUG[13323] netsock2.c: ...host 'sipqa' and port ''. [2014-08-22 17:39:40] DEBUG[13323] acl.c: Multiple addresses. Using the first only [2014-08-22 17:39:40] DEBUG[13323] acl.c: Not an IPv4 nor IPv6 address, cannot get port. [2014-08-22 17:39:40] DEBUG[13323] acl.c: Attached to given IP address [2014-08-22 17:39:40] DEBUG[13333] manager.c: Examining AMI event: Event: RTCPSent Privilege: reporting,all SystemName: sipqa Channel: SIP/mlc296-00000001 ChannelState: 6 ChannelStateDesc: Up CallerIDNum: mlc296 CallerIDName: Mitch Digium ConnectedLineNum: ConnectedLineName: AccountCode: Context: LocalSets Exten: 850 Priority: 10 Uniqueid: sipqa-1408747159.3 To: 192.168.5.107:4001 From: 127.0.1.1:0 SSRC: 0x61f08792 PT: 200(SR) ReportCount: 1 SentNTP: 1408747180.1236828160 SentRTP: 159656 SentPackets: 912 SentOctets: 145920 Report0SourceSSRC: 0x0bfb93d8 Report0FractionLost: 0 Report0CumulativeLost: 0 Report0HighestSequence: 1696 Report0SequenceNumberCycles: 0 Report0IAJitter: 0 Report0LSR: 1544563589 Report0DLSR: 4.9530 [2014-08-22 17:39:40] DEBUG[13337][C-00000002] res_rtp_asterisk.c: Got RTCP report of 64 bytes [2014-08-22 17:39:40] DEBUG[13337][C-00000002] acl.c: Not an IPv4 nor IPv6 address, cannot get port. [2014-08-22 17:39:40] DEBUG[13337][C-00000002] netsock2.c: Splitting 'sipqa' into... [2014-08-22 17:39:40] DEBUG[13337][C-00000002] netsock2.c: ...host 'sipqa' and port ''. [2014-08-22 17:39:40] DEBUG[13337][C-00000002] acl.c: Multiple addresses. Using the first only [2014-08-22 17:39:40] DEBUG[13337][C-00000002] acl.c: Not an IPv4 nor IPv6 address, cannot get port. [2014-08-22 17:39:40] DEBUG[13337][C-00000002] acl.c: Attached to given IP address [2014-08-22 17:39:40] DEBUG[13333] manager.c: Examining AMI event: Event: RTCPReceived Privilege: reporting,all SystemName: sipqa Channel: SIP/mlc296-00000001 ChannelState: 6 ChannelStateDesc: Up CallerIDNum: mlc296 CallerIDName: Mitch Digium ConnectedLineNum: ConnectedLineName: AccountCode: Context: LocalSets Exten: 850 Priority: 10 Uniqueid: sipqa-1408747159.3 To: 127.0.1.1:0 From: 192.168.5.107:4001 RTT: 0.3614 SSRC: 0x0bfb93d8 PT: 200(SR) ReportCount: 1 SentNTP: 2128928149.17584015298560 SentRTP: 121046356 SentPackets: 1004 SentOctets: 154712 Report0SourceSSRC: 0x61f08792 Report0FractionLost: 0 Report0CumulativeLost: 0 Report0HighestSequence: 21972 Report0SequenceNumberCycles: 0 Report0IAJitter: 0 Report0LSR: 1160531277 Report0DLSR: 0.0400 [2014-08-22 17:39:42] DEBUG[13323] chan_sip.c: SIP Registry dallas.voip.ms: refcount now 3 [2014-08-22 17:39:42] DEBUG[13323] netsock2.c: Splitting 'dallas.voip.ms' into... [2014-08-22 17:39:42] DEBUG[13323] netsock2.c: ...host 'dallas.voip.ms' and port ''. [2014-08-22 17:39:42] DEBUG[13323] netsock2.c: Splitting 'dallas.voip.ms' into... [2014-08-22 17:39:42] DEBUG[13323] netsock2.c: ...host 'dallas.voip.ms' and port ''. [2014-08-22 17:39:42] DEBUG[13323] chan_sip.c: SIP Registry dallas.voip.ms: refcount now 2 [2014-08-22 17:39:42] DEBUG[13323] chan_sip.c: Allocating new SIP dialog for 19086cee0112398221b110080c1f7c40@127.0.1.1 - REGISTER (No RTP) [2014-08-22 17:39:42] DEBUG[13323] chan_sip.c: SIP Registry dallas.voip.ms: refcount now 3 [2014-08-22 17:39:42] DEBUG[13323] acl.c: For destination '74.54.54.178', our source address is '192.168.5.105'. [2014-08-22 17:39:42] DEBUG[13323] chan_sip.c: Setting AST_TRANSPORT_UDP with address 192.168.5.105:5060 [2014-08-22 17:39:42] DEBUG[13323] chan_sip.c: SIP Registry dallas.voip.ms: refcount now 4 [2014-08-22 17:39:42] DEBUG[13323] chan_sip.c: Scheduled a registration timeout for dallas.voip.ms id #225 [2014-08-22 17:39:42] DEBUG[13323] netsock2.c: Splitting 'dallas.voip.ms' into... [2014-08-22 17:39:42] DEBUG[13323] netsock2.c: ...host 'dallas.voip.ms' and port ''. [2014-08-22 17:39:42] DEBUG[13323] netsock2.c: Splitting 'dallas.voip.ms' into... [2014-08-22 17:39:42] DEBUG[13323] netsock2.c: ...host 'dallas.voip.ms' and port ''. [2014-08-22 17:39:42] DEBUG[13323] netsock2.c: Splitting 'dallas.voip.ms' into... [2014-08-22 17:39:42] DEBUG[13323] netsock2.c: ...host 'dallas.voip.ms' and port ''. [2014-08-22 17:39:42] DEBUG[13323] chan_sip.c: Initializing initreq for method REGISTER - callid 19086cee0112398221b110080c1f7c40@127.0.1.1 [2014-08-22 17:39:42] DEBUG[13323] chan_sip.c: REGISTER attempt 1 to 128581_mitchtest@dallas.voip.ms [2014-08-22 17:39:42] DEBUG[13323] chan_sip.c: Trying to put 'REGISTER si' onto UDP socket destined for 74.54.54.178:5060 [2014-08-22 17:39:42] DEBUG[13323] chan_sip.c: SIP Registry dallas.voip.ms: refcount now 3 [2014-08-22 17:39:42] DEBUG[13323] chan_sip.c: = Looking for Call ID: 19086cee0112398221b110080c1f7c40@127.0.1.1 (Checking To) --From tag as2db41ff3 --To-tag [2014-08-22 17:39:42] DEBUG[13323] chan_sip.c: = Looking for Call ID: 19086cee0112398221b110080c1f7c40@127.0.1.1 (Checking To) --From tag as2db41ff3 --To-tag as21acbbb8 [2014-08-22 17:39:42] DEBUG[13323] chan_sip.c: Stopping retransmission on '19086cee0112398221b110080c1f7c40@127.0.1.1' of Request 104: Match Found [2014-08-22 17:39:42] DEBUG[13323] chan_sip.c: SIP Registry dallas.voip.ms: refcount now 4 [2014-08-22 17:39:42] DEBUG[13323] netsock2.c: Splitting 'dallas.voip.ms' into... [2014-08-22 17:39:42] DEBUG[13323] netsock2.c: ...host 'dallas.voip.ms' and port ''. [2014-08-22 17:39:42] DEBUG[13323] netsock2.c: Splitting 'dallas.voip.ms' into... [2014-08-22 17:39:42] DEBUG[13323] netsock2.c: ...host 'dallas.voip.ms' and port ''. [2014-08-22 17:39:42] DEBUG[13323] chan_sip.c: SIP Registry dallas.voip.ms: refcount now 3 [2014-08-22 17:39:42] DEBUG[13323] netsock2.c: Splitting 'dallas.voip.ms' into... [2014-08-22 17:39:42] DEBUG[13323] netsock2.c: ...host 'dallas.voip.ms' and port ''. [2014-08-22 17:39:42] DEBUG[13323] netsock2.c: Splitting 'dallas.voip.ms' into... [2014-08-22 17:39:42] DEBUG[13323] netsock2.c: ...host 'dallas.voip.ms' and port ''. [2014-08-22 17:39:42] DEBUG[13323] netsock2.c: Splitting 'dallas.voip.ms' into... [2014-08-22 17:39:42] DEBUG[13323] netsock2.c: ...host 'dallas.voip.ms' and port ''. [2014-08-22 17:39:42] DEBUG[13323] chan_sip.c: Initializing already initialized SIP dialog 19086cee0112398221b110080c1f7c40@127.0.1.1 (presumably reinvite) [2014-08-22 17:39:42] DEBUG[13323] chan_sip.c: REGISTER attempt 2 to 128581_mitchtest@dallas.voip.ms [2014-08-22 17:39:42] DEBUG[13323] chan_sip.c: Trying to put 'REGISTER si' onto UDP socket destined for 74.54.54.178:5060 [2014-08-22 17:39:42] DEBUG[13323] chan_sip.c: = Looking for Call ID: 19086cee0112398221b110080c1f7c40@127.0.1.1 (Checking To) --From tag as2db41ff3 --To-tag [2014-08-22 17:39:42] DEBUG[13323] chan_sip.c: = Looking for Call ID: 19086cee0112398221b110080c1f7c40@127.0.1.1 (Checking To) --From tag as2db41ff3 --To-tag as21acbbb8 [2014-08-22 17:39:42] DEBUG[13323] chan_sip.c: Stopping retransmission on '19086cee0112398221b110080c1f7c40@127.0.1.1' of Request 105: Match Found [2014-08-22 17:39:42] DEBUG[13323] chan_sip.c: Registration successful [2014-08-22 17:39:42] DEBUG[13323] chan_sip.c: Cancelling timeout 225 [2014-08-22 17:39:42] DEBUG[13333] manager.c: Examining AMI event: Event: Registry Privilege: system,all SystemName: sipqa ChannelType: SIP Username: 128581_mitchtest Domain: dallas.voip.ms Status: Registered [2014-08-22 17:39:42] DEBUG[13323] chan_sip.c: SIP Registry dallas.voip.ms: refcount now 2 [2014-08-22 17:39:42] DEBUG[13323] chan_sip.c: SIP Registry dallas.voip.ms: refcount now 1 [2014-08-22 17:39:42] DEBUG[13323] chan_sip.c: SIP Registry dallas.voip.ms: refcount now 2 [2014-08-22 17:39:42] DEBUG[13323] chan_sip.c: Destroying SIP dialog 19086cee0112398221b110080c1f7c40@127.0.1.1 [2014-08-22 17:39:45] DEBUG[13323] acl.c: Not an IPv4 nor IPv6 address, cannot get port. [2014-08-22 17:39:45] DEBUG[13323] netsock2.c: Splitting 'sipqa' into... [2014-08-22 17:39:45] DEBUG[13323] netsock2.c: ...host 'sipqa' and port ''. [2014-08-22 17:39:45] DEBUG[13323] acl.c: Multiple addresses. Using the first only [2014-08-22 17:39:45] DEBUG[13323] acl.c: Not an IPv4 nor IPv6 address, cannot get port. [2014-08-22 17:39:45] DEBUG[13323] acl.c: Attached to given IP address [2014-08-22 17:39:45] DEBUG[13333] manager.c: Examining AMI event: Event: RTCPSent Privilege: reporting,all SystemName: sipqa Channel: SIP/mlc296-00000001 ChannelState: 6 ChannelStateDesc: Up CallerIDNum: mlc296 CallerIDName: Mitch Digium ConnectedLineNum: ConnectedLineName: AccountCode: Context: LocalSets Exten: 850 Priority: 10 Uniqueid: sipqa-1408747159.3 To: 192.168.5.107:4001 From: 127.0.1.1:0 SSRC: 0x61f08792 PT: 200(SR) ReportCount: 1 SentNTP: 1408747185.1232752640 SentRTP: 199656 SentPackets: 1162 SentOctets: 185920 Report0SourceSSRC: 0x0bfb93d8 Report0FractionLost: 0 Report0CumulativeLost: 0 Report0HighestSequence: 1946 Report0SequenceNumberCycles: 0 Report0IAJitter: 0 Report0LSR: 1544891269 Report0DLSR: 4.9520 [2014-08-22 17:39:45] DEBUG[13337][C-00000002] res_rtp_asterisk.c: Got RTCP report of 64 bytes [2014-08-22 17:39:45] DEBUG[13337][C-00000002] acl.c: Not an IPv4 nor IPv6 address, cannot get port. [2014-08-22 17:39:45] DEBUG[13337][C-00000002] netsock2.c: Splitting 'sipqa' into... [2014-08-22 17:39:45] DEBUG[13337][C-00000002] netsock2.c: ...host 'sipqa' and port ''. [2014-08-22 17:39:45] DEBUG[13337][C-00000002] acl.c: Multiple addresses. Using the first only [2014-08-22 17:39:45] DEBUG[13337][C-00000002] acl.c: Not an IPv4 nor IPv6 address, cannot get port. [2014-08-22 17:39:45] DEBUG[13337][C-00000002] acl.c: Attached to given IP address [2014-08-22 17:39:45] DEBUG[13333] manager.c: Examining AMI event: Event: RTCPReceived Privilege: reporting,all SystemName: sipqa Channel: SIP/mlc296-00000001 ChannelState: 6 ChannelStateDesc: Up CallerIDNum: mlc296 CallerIDName: Mitch Digium ConnectedLineNum: ConnectedLineName: AccountCode: Context: LocalSets Exten: 850 Priority: 10 Uniqueid: sipqa-1408747159.3 To: 127.0.1.1:0 From: 192.168.5.107:4001 RTT: 0.4184 SSRC: 0x0bfb93d8 PT: 200(SR) ReportCount: 1 SentNTP: 2128928154.17584015298560 SentRTP: 1205011796 SentPackets: 1254 SentOctets: 194712 Report0SourceSSRC: 0x61f08792 Report0FractionLost: 0 Report0CumulativeLost: 0 Report0HighestSequence: 22222 Report0SequenceNumberCycles: 0 Report0IAJitter: 0 Report0LSR: 1160858892 Report0DLSR: 0.0400 [2014-08-22 17:39:49] DEBUG[13337][C-00000002] res_rtp_asterisk.c: Got RTCP report of 72 bytes [2014-08-22 17:39:49] DEBUG[13337][C-00000002] acl.c: Not an IPv4 nor IPv6 address, cannot get port. [2014-08-22 17:39:49] DEBUG[13337][C-00000002] netsock2.c: Splitting 'sipqa' into... [2014-08-22 17:39:49] DEBUG[13337][C-00000002] netsock2.c: ...host 'sipqa' and port ''. [2014-08-22 17:39:49] DEBUG[13337][C-00000002] acl.c: Multiple addresses. Using the first only [2014-08-22 17:39:49] DEBUG[13337][C-00000002] acl.c: Not an IPv4 nor IPv6 address, cannot get port. [2014-08-22 17:39:49] DEBUG[13337][C-00000002] acl.c: Attached to given IP address [2014-08-22 17:39:49] DEBUG[13333] manager.c: Examining AMI event: Event: RTCPReceived Privilege: reporting,all SystemName: sipqa Channel: SIP/mlc296-00000001 ChannelState: 6 ChannelStateDesc: Up CallerIDNum: mlc296 CallerIDName: Mitch Digium ConnectedLineNum: ConnectedLineName: AccountCode: Context: LocalSets Exten: 850 Priority: 10 Uniqueid: sipqa-1408747159.3 To: 127.0.1.1:0 From: 192.168.5.107:4001 RTT: 69813.1603 SSRC: 0x0bfb93d8 PT: 200(SR) ReportCount: 1 SentNTP: 2128928158.17558144966656 SentRTP: 4149806676 SentPackets: 1469 SentOctets: 229112 Report0SourceSSRC: 0x61f08792 Report0FractionLost: 0 Report0CumulativeLost: 0 Report0HighestSequence: 22438 Report0SequenceNumberCycles: 0 Report0IAJitter: 0 Report0LSR: 1160858892 Report0DLSR: 4.3600 [2014-08-22 17:39:49] DEBUG[13323] chan_sip.c: = Looking for Call ID: 1aniZhX.2ngkFw4OFoBhzrkdKTh9jc9J (Checking From) --From tag liKiC6E1BuQ4dmpczdjtPyY3di6350QO --To-tag as6c74a655 [2014-08-22 17:39:49] DEBUG[13323][C-00000002] chan_sip.c: **** Received BYE (8) - Command in SIP BYE [2014-08-22 17:39:49] DEBUG[13323][C-00000002] netsock2.c: Splitting '192.168.5.107:5060' into... [2014-08-22 17:39:49] DEBUG[13323][C-00000002] netsock2.c: ...host '192.168.5.107' and port '5060'. [2014-08-22 17:39:49] DEBUG[13323][C-00000002] chan_sip.c: Setting SIP_ALREADYGONE on dialog 1aniZhX.2ngkFw4OFoBhzrkdKTh9jc9J [2014-08-22 17:39:49] DEBUG[13333] manager.c: Examining AMI event: Event: VarSet Privilege: dialplan,all SystemName: sipqa Channel: SIP/mlc296-00000001 ChannelState: 6 ChannelStateDesc: Up CallerIDNum: mlc296 CallerIDName: Mitch Digium ConnectedLineNum: ConnectedLineName: AccountCode: Context: LocalSets Exten: 850 Priority: 10 Uniqueid: sipqa-1408747159.3 Variable: RTPAUDIOQOS Value: ssrc=1643153298;themssrc=201036760;lp=0;rxjitter=0.000000;rxcount=1469;txjitter=0.000185;txcount=1389;rlp=0;rtt=69813.160324 [2014-08-22 17:39:49] DEBUG[13333] manager.c: Examining AMI event: Event: VarSet Privilege: dialplan,all SystemName: sipqa Channel: SIP/mlc296-00000001 ChannelState: 6 ChannelStateDesc: Up CallerIDNum: mlc296 CallerIDName: Mitch Digium ConnectedLineNum: ConnectedLineName: AccountCode: Context: LocalSets Exten: 850 Priority: 10 Uniqueid: sipqa-1408747159.3 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; [2014-08-22 17:39:49] DEBUG[13333] manager.c: Examining AMI event: Event: VarSet Privilege: dialplan,all SystemName: sipqa Channel: SIP/mlc296-00000001 ChannelState: 6 ChannelStateDesc: Up CallerIDNum: mlc296 CallerIDName: Mitch Digium ConnectedLineNum: ConnectedLineName: AccountCode: Context: LocalSets Exten: 850 Priority: 10 Uniqueid: sipqa-1408747159.3 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; [2014-08-22 17:39:49] DEBUG[13333] manager.c: Examining AMI event: Event: VarSet Privilege: dialplan,all SystemName: sipqa Channel: SIP/mlc296-00000001 ChannelState: 6 ChannelStateDesc: Up CallerIDNum: mlc296 CallerIDName: Mitch Digium ConnectedLineNum: ConnectedLineName: AccountCode: Context: LocalSets Exten: 850 Priority: 10 Uniqueid: sipqa-1408747159.3 Variable: RTPAUDIOQOSRTT Value: minrtt=0.000000;maxrtt=0.000000;avgrtt=0.000000;stdevrtt=0.000000; [2014-08-22 17:39:49] DEBUG[13323][C-00000002] res_rtp_asterisk.c: Setting RTCP address on RTP instance '0x7ffc3404f968' [2014-08-22 17:39:49] DEBUG[13323][C-00000002] chan_sip.c: Session timer stopped: 222 - 1aniZhX.2ngkFw4OFoBhzrkdKTh9jc9J [2014-08-22 17:39:49] DEBUG[13333] manager.c: Examining AMI event: Event: HangupRequest Privilege: call,all SystemName: sipqa Channel: SIP/mlc296-00000001 ChannelState: 6 ChannelStateDesc: Up CallerIDNum: mlc296 CallerIDName: Mitch Digium ConnectedLineNum: ConnectedLineName: AccountCode: Context: LocalSets Exten: 850 Priority: 10 Uniqueid: sipqa-1408747159.3 [2014-08-22 17:39:49] DEBUG[13323][C-00000002] chan_sip.c: Received bye, issuing owner hangup [2014-08-22 17:39:49] DEBUG[13323][C-00000002] chan_sip.c: Trying to put 'SIP/2.0 200' onto UDP socket destined for 192.168.5.107:5060 [2014-08-22 17:39:49] DEBUG[13333] manager.c: Examining AMI event: Event: MeetmeLeave Privilege: call,all SystemName: sipqa Meetme: 850 Channel: SIP/mlc296-00000001 ChannelState: 6 ChannelStateDesc: Up CallerIDNum: mlc296 CallerIDName: Mitch Digium ConnectedLineNum: ConnectedLineName: AccountCode: Context: LocalSets Exten: 850 Priority: 10 Uniqueid: sipqa-1408747159.3 User: 2 Duration: 23 [2014-08-22 17:39:49] DEBUG[13330] app_queue.c: Device 'meetme:850' changed to state '1' (Not in use) but we don't care because they're not a member of any queue.