<--- SIP read from UDP:192.168.10.202:12136 ---> <-------------> <--- SIP read from UDP:192.168.10.202:12136 ---> INVITE sip:test@ASTERISKHOSTNAME SIP/2.0 Via: SIP/2.0/UDP 192.168.10.202:12136;branch=z9hG4bK-d8754z-6b6752080419282b-1---d8754z-;rport Max-Forwards: 70 Contact: To: "test" From: "displayname";tag=061bca55 Call-ID: MDFjY2NkZTA2YTBlYWE3ZmYxNGY2NTk0YjI3Yzc3NTU. CSeq: 1 INVITE Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, NOTIFY, MESSAGE, SUBSCRIBE, INFO Content-Type: application/sdp User-Agent: X-Lite release 1104o stamp 56125 Content-Length: 239 v=0 o=- 0 2 IN IP4 192.168.10.202 s=CounterPath X-Lite 3.0 c=IN IP4 192.168.10.202 t=0 0 m=audio 7668 RTP/AVP 0 8 101 a=alt:1 1 : aWiN+qwT LqnIZP4i 192.168.10.202 7668 a=fmtp:101 0-15 a=rtpmap:101 telephone-event/8000 a=sendrecv <-------------> --- (12 headers 10 lines) --- [May 6 13:15:45] DEBUG[8003]: acl.c:506 ast_ouraddrfor: Found IP address for this socket [May 6 13:15:45] DEBUG[8003]: chan_sip.c:3678 ast_sip_ouraddrfor: Setting SIP_TRANSPORT_UDP with address 192.168.160.20:5060 == Using SIP RTP CoS mark 5 [May 6 13:15:45] DEBUG[8003]: chan_sip.c:5001 do_setnat: Setting NAT on RTP to Off [May 6 13:15:45] DEBUG[8003]: chan_sip.c:7290 sip_alloc: Allocating new SIP dialog for MDFjY2NkZTA2YTBlYWE3ZmYxNGY2NTk0YjI3Yzc3NTU. - INVITE (With RTP) Sending to 192.168.10.202 : 12136 (no NAT) [May 6 13:15:45] DEBUG[8003]: chan_sip.c:19935 handle_request_invite: Initializing initreq for method INVITE - callid MDFjY2NkZTA2YTBlYWE3ZmYxNGY2NTk0YjI3Yzc3NTU. Using INVITE request as basis request - MDFjY2NkZTA2YTBlYWE3ZmYxNGY2NTk0YjI3Yzc3NTU. Found peer '1003' for '1003' from 192.168.10.202:12136 [May 6 13:15:45] DEBUG[8003]: chan_sip.c:5001 do_setnat: Setting NAT on RTP to Off <--- Reliably Transmitting (no NAT) to 192.168.10.202:12136 ---> SIP/2.0 401 Unauthorized Via: SIP/2.0/UDP 192.168.10.202:12136;branch=z9hG4bK-d8754z-6b6752080419282b-1---d8754z-;received=192.168.10.202;rport=12136 From: "displayname";tag=061bca55 To: "test";tag=as00575979 Call-ID: MDFjY2NkZTA2YTBlYWE3ZmYxNGY2NTk0YjI3Yzc3NTU. CSeq: 1 INVITE Server: Asterisk PBX 1.6.2.6 Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO Supported: replaces, timer WWW-Authenticate: Digest algorithm=MD5, realm="asterisk", nonce="04548088" Content-Length: 0 <------------> [May 6 13:15:45] DEBUG[8003]: chan_sip.c:3557 __sip_xmit: Trying to put 'SIP/2.0 401' onto UDP socket destined for 192.168.10.202:12136 Scheduling destruction of SIP dialog 'MDFjY2NkZTA2YTBlYWE3ZmYxNGY2NTk0YjI3Yzc3NTU.' in 11072 ms (Method: INVITE) <--- SIP read from UDP:192.168.10.202:12136 ---> ACK sip:test@ASTERISKHOSTNAME SIP/2.0 Via: SIP/2.0/UDP 192.168.10.202:12136;branch=z9hG4bK-d8754z-6b6752080419282b-1---d8754z-;rport To: "test";tag=as00575979 From: "displayname";tag=061bca55 Call-ID: MDFjY2NkZTA2YTBlYWE3ZmYxNGY2NTk0YjI3Yzc3NTU. CSeq: 1 ACK Content-Length: 0 <-------------> --- (7 headers 0 lines) --- [May 6 13:15:45] DEBUG[8003]: chan_sip.c:4093 __sip_ack: Stopping retransmission on 'MDFjY2NkZTA2YTBlYWE3ZmYxNGY2NTk0YjI3Yzc3NTU.' of Response 1: Match Found <--- SIP read from UDP:192.168.10.202:12136 ---> INVITE sip:test@ASTERISKHOSTNAME SIP/2.0 Via: SIP/2.0/UDP 192.168.10.202:12136;branch=z9hG4bK-d8754z-5f34ad2dd872e934-1---d8754z-;rport Max-Forwards: 70 Contact: To: "test" From: "displayname";tag=061bca55 Call-ID: MDFjY2NkZTA2YTBlYWE3ZmYxNGY2NTk0YjI3Yzc3NTU. CSeq: 2 INVITE Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, NOTIFY, MESSAGE, SUBSCRIBE, INFO Content-Type: application/sdp User-Agent: X-Lite release 1104o stamp 56125 Authorization: Digest username="1003",realm="asterisk",nonce="04548088",uri="sip:test@ASTERISKHOSTNAME",response="fa642ad49eb25d67118d4ccf370a1a20",algorithm=MD5 Content-Length: 239 v=0 o=- 0 2 IN IP4 192.168.10.202 s=CounterPath X-Lite 3.0 c=IN IP4 192.168.10.202 t=0 0 m=audio 7668 RTP/AVP 0 8 101 a=alt:1 1 : aWiN+qwT LqnIZP4i 192.168.10.202 7668 a=fmtp:101 0-15 a=rtpmap:101 telephone-event/8000 a=sendrecv <-------------> --- (13 headers 10 lines) --- Sending to 192.168.10.202 : 12136 (no NAT) [May 6 13:15:45] DEBUG[8003]: chan_sip.c:19935 handle_request_invite: Initializing initreq for method INVITE - callid MDFjY2NkZTA2YTBlYWE3ZmYxNGY2NTk0YjI3Yzc3NTU. Using INVITE request as basis request - MDFjY2NkZTA2YTBlYWE3ZmYxNGY2NTk0YjI3Yzc3NTU. Found peer '1003' for '1003' from 192.168.10.202:12136 [May 6 13:15:45] DEBUG[8003]: chan_sip.c:5001 do_setnat: Setting NAT on RTP to Off [May 6 13:15:45] DEBUG[8003]: chan_sip.c:8195 process_sdp: Processing session-level SDP v=0... UNSUPPORTED. [May 6 13:15:45] DEBUG[8003]: chan_sip.c:8195 process_sdp: Processing session-level SDP o=- 0 2 IN IP4 192.168.10.202... UNSUPPORTED. [May 6 13:15:45] DEBUG[8003]: chan_sip.c:8195 process_sdp: Processing session-level SDP s=CounterPath X-Lite 3.0... UNSUPPORTED. [May 6 13:15:45] DEBUG[8003]: chan_sip.c:8195 process_sdp: Processing session-level SDP c=IN IP4 192.168.10.202... OK. [May 6 13:15:45] DEBUG[8003]: chan_sip.c:8195 process_sdp: Processing session-level SDP t=0 0... UNSUPPORTED. Found RTP audio format 0 Found RTP audio format 8 Found RTP audio format 101 [May 6 13:15:45] DEBUG[8003]: chan_sip.c:8359 process_sdp: Processing media-level (audio) SDP a=alt:1 1 : aWiN+qwT LqnIZP4i 192.168.10.202 7668... UNSUPPORTED. [May 6 13:15:45] DEBUG[8003]: chan_sip.c:8359 process_sdp: Processing media-level (audio) SDP a=fmtp:101 0-15... UNSUPPORTED. Found audio description format telephone-event for ID 101 [May 6 13:15:45] DEBUG[8003]: chan_sip.c:8359 process_sdp: Processing media-level (audio) SDP a=rtpmap:101 telephone-event/8000... OK. [May 6 13:15:45] DEBUG[8003]: chan_sip.c:8359 process_sdp: Processing media-level (audio) SDP a=sendrecv... OK. Capabilities: us - 0x8010f (g723|gsm|ulaw|alaw|g729|h263), peer - audio=0xc (ulaw|alaw)/video=0x0 (nothing)/text=0x0 (nothing), combined - 0xc (ulaw|alaw) Non-codec capabilities (dtmf): us - 0x1 (telephone-event), peer - 0x1 (telephone-event), combined - 0x1 (telephone-event) Peer audio RTP is at port 192.168.10.202:7668 [May 6 13:15:45] DEBUG[8003]: chan_sip.c:8544 process_sdp: We're settling with these formats: 0xc (ulaw|alaw) [May 6 13:15:45] DEBUG[8003]: chan_sip.c:20030 handle_request_invite: Checking SIP call limits for device 1003 [May 6 13:15:45] DEBUG[8003]: chan_sip.c:5641 update_call_counter: Updating call counter for incoming call Looking for test in default (domain ASTERISKHOSTNAME) [May 6 13:15:45] DEBUG[8003]: chan_sip.c:6657 sip_new: *** Our native formats are 0x4 (ulaw) [May 6 13:15:45] DEBUG[8003]: chan_sip.c:6658 sip_new: *** Joint capabilities are 0xc (ulaw|alaw) [May 6 13:15:45] DEBUG[8003]: chan_sip.c:6659 sip_new: *** Our capabilities are 0x8010f (g723|gsm|ulaw|alaw|g729|h263) [May 6 13:15:45] DEBUG[8003]: chan_sip.c:6660 sip_new: *** AST_CODEC_CHOOSE formats are 0x4 (ulaw) [May 6 13:15:45] DEBUG[8003]: chan_sip.c:6690 sip_new: This channel will not be able to handle video. [May 6 13:15:45] DEBUG[8003]: chan_sip.c:12518 build_route: build_route: Contact hop: list_route: hop: [May 6 13:15:45] DEBUG[8003]: chan_sip.c:20289 handle_request_invite: SIP/1003-00000000: New call is still down.... Trying... <--- Transmitting (no NAT) to 192.168.10.202:12136 ---> SIP/2.0 100 Trying Via: SIP/2.0/UDP 192.168.10.202:12136;branch=z9hG4bK-d8754z-5f34ad2dd872e934-1---d8754z-;received=192.168.10.202;rport=12136 From: "displayname";tag=061bca55 To: "test" Call-ID: MDFjY2NkZTA2YTBlYWE3ZmYxNGY2NTk0YjI3Yzc3NTU. CSeq: 2 INVITE Server: Asterisk PBX 1.6.2.6 Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO Supported: replaces, timer Contact: Content-Length: 0 <------------> [May 6 13:15:45] DEBUG[8003]: chan_sip.c:3557 __sip_xmit: Trying to put 'SIP/2.0 100' onto UDP socket destined for 192.168.10.202:12136 [May 6 13:15:45] DEBUG[7983]: chan_sip.c:23000 sip_devicestate: Checking device state for peer 1003 [May 6 13:15:45] DEBUG[7983]: devicestate.c:460 do_state_change: Changing state for SIP/1003 - state 1 (Not in use) [May 6 13:15:45] DEBUG[7983]: devicestate.c:440 devstate_event: device 'SIP/1003' state '1' [May 6 13:15:45] DEBUG[7991]: app_queue.c:1084 handle_statechange: Device 'SIP/1003' changed to state '1' (Not in use) but we don't care because they're not a member of any queue. [May 6 13:15:45] DEBUG[8017]: pbx.c:3692 pbx_extension_helper: Launching 'Answer' -- Executing [test@default:1] Answer("SIP/1003-00000000", "") in new stack [May 6 13:15:45] DEBUG[8017]: chan_sip.c:6197 sip_answer: SIP answering channel: SIP/1003-00000000 [May 6 13:15:45] DEBUG[8017]: chan_sip.c:10426 transmit_response_with_sdp: Setting framing from config on incoming call [May 6 13:15:45] DEBUG[7983]: chan_sip.c:23000 sip_devicestate: Checking device state for peer 1003 [May 6 13:15:45] DEBUG[8017]: chan_sip.c:10115 add_sdp: ** Our capability: 0xc (ulaw|alaw) Video flag: True Text flag: True [May 6 13:15:45] DEBUG[8017]: chan_sip.c:10116 add_sdp: ** Our prefcodec: 0x0 (nothing) Audio is at 192.168.160.20 port 15380 Adding codec 0x4 (ulaw) to SDP Adding codec 0x8 (alaw) to SDP Adding non-codec 0x1 (telephone-event) to SDP [May 6 13:15:45] DEBUG[8017]: chan_sip.c:10227 add_sdp: -- Done with adding codecs to SDP [May 6 13:15:45] DEBUG[8017]: chan_sip.c:10363 add_sdp: Done building SDP. Settling with this capability: 0xc (ulaw|alaw) <--- Reliably Transmitting (no NAT) to 192.168.10.202:12136 ---> SIP/2.0 200 OK Via: SIP/2.0/UDP 192.168.10.202:12136;branch=z9hG4bK-d8754z-5f34ad2dd872e934-1---d8754z-;received=192.168.10.202;rport=12136 From: "displayname";tag=061bca55 To: "test";tag=as019b8931 Call-ID: MDFjY2NkZTA2YTBlYWE3ZmYxNGY2NTk0YjI3Yzc3NTU. CSeq: 2 INVITE Server: Asterisk PBX 1.6.2.6 Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO Supported: replaces, timer Contact: Content-Type: application/sdp Content-Length: 264 v=0 o=root 1203046757 1203046757 IN IP4 192.168.160.20 s=Asterisk PBX 1.6.2.6 c=IN IP4 192.168.160.20 t=0 0 m=audio 15380 RTP/AVP 0 8 101 a=rtpmap:0 PCMU/8000 a=rtpmap:8 PCMA/8000 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-16 a=ptime:20 a=sendrecv <------------> [May 6 13:15:45] DEBUG[8017]: chan_sip.c:3557 __sip_xmit: Trying to put 'SIP/2.0 200' onto UDP socket destined for 192.168.10.202:12136 [May 6 13:15:45] DEBUG[7983]: devicestate.c:460 do_state_change: Changing state for SIP/1003 - state 1 (Not in use) [May 6 13:15:45] DEBUG[7983]: devicestate.c:440 devstate_event: device 'SIP/1003' state '1' [May 6 13:15:45] DEBUG[7991]: app_queue.c:1084 handle_statechange: Device 'SIP/1003' changed to state '1' (Not in use) but we don't care because they're not a member of any queue. [May 6 13:15:45] DEBUG[8017]: rtp.c:1227 ast_rtcp_read: Got RTCP report of 132 bytes [May 6 13:15:45] DEBUG[8017]: pbx.c:3692 pbx_extension_helper: Launching 'Dial' -- Executing [test@default:2] Dial("SIP/1003-00000000", "Local/start@test1") in new stack [May 6 13:15:45] DEBUG[8017]: rtp.c:2177 ast_rtp_make_compatible: Channel 'Local/start@test1-fa87;1' has no RTP, not doing anything [May 6 13:15:45] DEBUG[8017]: channel.c:4336 ast_channel_inherit_variables: Not copying variable DIALEDTIME. [May 6 13:15:45] DEBUG[8017]: channel.c:4336 ast_channel_inherit_variables: Not copying variable ANSWEREDTIME. [May 6 13:15:45] DEBUG[8017]: channel.c:4336 ast_channel_inherit_variables: Not copying variable DIALEDPEERNAME. [May 6 13:15:45] DEBUG[8017]: channel.c:4336 ast_channel_inherit_variables: Not copying variable DIALEDPEERNUMBER. [May 6 13:15:45] DEBUG[8017]: channel.c:4336 ast_channel_inherit_variables: Not copying variable DIALSTATUS. [May 6 13:15:45] DEBUG[8017]: channel.c:4325 ast_channel_inherit_variables: Copying soft-transferable variable SRC_ADDR. [May 6 13:15:45] DEBUG[8017]: channel.c:4325 ast_channel_inherit_variables: Copying soft-transferable variable SRC_TYPE. [May 6 13:15:45] DEBUG[8017]: channel.c:4336 ast_channel_inherit_variables: Not copying variable SIPCALLID. [May 6 13:15:45] DEBUG[8017]: channel.c:4336 ast_channel_inherit_variables: Not copying variable SIPDOMAIN. [May 6 13:15:45] DEBUG[8017]: channel.c:4336 ast_channel_inherit_variables: Not copying variable SIPURI. -- Called start@test1 [May 6 13:15:45] DEBUG[8019]: pbx.c:3692 pbx_extension_helper: Launching 'Answer' -- Executing [start@test1:1] Answer("Local/start@test1-fa87;2", "") in new stack [May 6 13:15:45] DEBUG[7983]: chan_local.c:146 local_devicestate: Checking if extension start@test1 exists (devicestate) [May 6 13:15:45] DEBUG[7983]: devicestate.c:460 do_state_change: Changing state for Local/start@test1 - state 2 (In use) [May 6 13:15:45] DEBUG[7983]: devicestate.c:440 devstate_event: device 'Local/start@test1' state '2' [May 6 13:15:45] DEBUG[7991]: app_queue.c:1084 handle_statechange: Device 'Local/start@test1' changed to state '2' (In use) but we don't care because they're not a member of any queue. -- Local/start@test1-fa87;1 answered SIP/1003-00000000 [May 6 13:15:45] DEBUG[7983]: chan_local.c:146 local_devicestate: Checking if extension start@test1 exists (devicestate) [May 6 13:15:45] DEBUG[8017]: channel.c:4904 ast_generic_bridge: Got a FRAME_CONTROL (-1) frame on channel Local/start@test1-fa87;1 [May 6 13:15:45] DEBUG[7983]: devicestate.c:460 do_state_change: Changing state for Local/start@test1 - state 2 (In use) [May 6 13:15:45] DEBUG[7983]: devicestate.c:440 devstate_event: device 'Local/start@test1' state '2' [May 6 13:15:45] DEBUG[7991]: app_queue.c:1084 handle_statechange: Device 'Local/start@test1' changed to state '2' (In use) but we don't care because they're not a member of any queue. [May 6 13:15:45] DEBUG[8017]: channel.c:5301 ast_channel_bridge: Bridge stops bridging channels SIP/1003-00000000 and Local/start@test1-fa87;1 [May 6 13:15:45] DEBUG[8019]: pbx.c:3692 pbx_extension_helper: Launching 'Read' -- Executing [start@test1:2] Read("Local/start@test1-fa87;2", "code,conf-getpin") in new stack [May 6 13:15:45] DEBUG[8019]: channel.c:2426 ast_settimeout: Scheduling timer at (50 requested / 50 actual) timer ticks per second -- Playing 'conf-getpin.ulaw' (language 'en') [May 6 13:15:45] DEBUG[8017]: rtp.c:3832 ast_rtp_write: Ooh, format changed from unknown to ulaw [May 6 13:15:45] DEBUG[8017]: rtp.c:3858 ast_rtp_write: Created smoother: format: 4 ms: 20 len: 160 <--- SIP read from UDP:192.168.10.202:12136 ---> ACK sip:test@192.168.160.20 SIP/2.0 Via: SIP/2.0/UDP 192.168.10.202:12136;branch=z9hG4bK-d8754z-b83299355b5e445d-1---d8754z-;rport Max-Forwards: 70 Contact: To: "test";tag=as019b8931 From: "displayname";tag=061bca55 Call-ID: MDFjY2NkZTA2YTBlYWE3ZmYxNGY2NTk0YjI3Yzc3NTU. CSeq: 2 ACK User-Agent: X-Lite release 1104o stamp 56125 Authorization: Digest username="1003",realm="asterisk",nonce="04548088",uri="sip:test@ASTERISKHOSTNAME",response="fa642ad49eb25d67118d4ccf370a1a20",algorithm=MD5 Content-Length: 0 <-------------> --- (11 headers 0 lines) --- [May 6 13:15:46] DEBUG[8003]: chan_sip.c:4093 __sip_ack: Stopping retransmission on 'MDFjY2NkZTA2YTBlYWE3ZmYxNGY2NTk0YjI3Yzc3NTU.' of Response 2: Match Found [May 6 13:15:48] DEBUG[8019]: channel.c:2426 ast_settimeout: Scheduling timer at (76 requested / 76 actual) timer ticks per second [May 6 13:15:48] DEBUG[8019]: channel.c:2426 ast_settimeout: Scheduling timer at (0 requested / 0 actual) timer ticks per second [May 6 13:15:48] DEBUG[8019]: channel.c:2426 ast_settimeout: Scheduling timer at (0 requested / 0 actual) timer ticks per second [May 6 13:15:48] DEBUG[8019]: channel.c:2426 ast_settimeout: Scheduling timer at (0 requested / 0 actual) timer ticks per second [May 6 13:15:49] DEBUG[8017]: rtp.c:1227 ast_rtcp_read: Got RTCP report of 176 bytes [May 6 13:15:50] DEBUG[8017]: rtp.c:1032 process_rfc2833: - RTP 2833 Event: 00000003 (len = 4) [May 6 13:15:50] DEBUG[8017]: rtp.c:880 send_dtmf: Sending dtmf: 51 (3), at 192.168.10.202 [May 6 13:15:50] DEBUG[8017]: rtp.c:1032 process_rfc2833: - RTP 2833 Event: 00000003 (len = 4) [May 6 13:15:50] DEBUG[8017]: rtp.c:1032 process_rfc2833: - RTP 2833 Event: 00000003 (len = 4) [May 6 13:15:50] DEBUG[8017]: rtp.c:1032 process_rfc2833: - RTP 2833 Event: 00000003 (len = 4) [May 6 13:15:50] DEBUG[8017]: rtp.c:1032 process_rfc2833: - RTP 2833 Event: 00000003 (len = 4) [May 6 13:15:50] DEBUG[8017]: rtp.c:1032 process_rfc2833: - RTP 2833 Event: 00000003 (len = 4) [May 6 13:15:50] DEBUG[8017]: rtp.c:1032 process_rfc2833: - RTP 2833 Event: 00000003 (len = 4) [May 6 13:15:50] DEBUG[8017]: rtp.c:880 send_dtmf: Sending dtmf: 51 (3), at 192.168.10.202 [May 6 13:15:50] DEBUG[8017]: rtp.c:1032 process_rfc2833: - RTP 2833 Event: 00000003 (len = 4) [May 6 13:15:50] DEBUG[8017]: rtp.c:1032 process_rfc2833: - RTP 2833 Event: 00000003 (len = 4) [May 6 13:15:50] DEBUG[8017]: rtp.c:1032 process_rfc2833: - RTP 2833 Event: 0000000b (len = 4) [May 6 13:15:50] DEBUG[8017]: rtp.c:880 send_dtmf: Sending dtmf: 35 (#), at 192.168.10.202 [May 6 13:15:50] DEBUG[8017]: rtp.c:1032 process_rfc2833: - RTP 2833 Event: 0000000b (len = 4) [May 6 13:15:50] DEBUG[8017]: rtp.c:1032 process_rfc2833: - RTP 2833 Event: 0000000b (len = 4) [May 6 13:15:50] DEBUG[8017]: rtp.c:1032 process_rfc2833: - RTP 2833 Event: 0000000b (len = 4) [May 6 13:15:50] DEBUG[8017]: rtp.c:1032 process_rfc2833: - RTP 2833 Event: 0000000b (len = 4) [May 6 13:15:50] DEBUG[8017]: rtp.c:1032 process_rfc2833: - RTP 2833 Event: 0000000b (len = 4) [May 6 13:15:50] DEBUG[8017]: rtp.c:880 send_dtmf: Sending dtmf: 35 (#), at 192.168.10.202 [May 6 13:15:50] DEBUG[8017]: rtp.c:1032 process_rfc2833: - RTP 2833 Event: 0000000b (len = 4) [May 6 13:15:50] DEBUG[8017]: rtp.c:1032 process_rfc2833: - RTP 2833 Event: 0000000b (len = 4) -- User entered '3' [May 6 13:15:50] DEBUG[8019]: pbx.c:3692 pbx_extension_helper: Launching 'MeetMe' -- Executing [start@test1:3] MeetMe("Local/start@test1-fa87;2", "1234,F") in new stack [May 6 13:15:50] DEBUG[8019]: app_meetme.c:3561 find_conf: The requested confno is '1234'? == Parsing '/etc/asterisk/meetme.conf': [May 6 13:15:50] DEBUG[8019]: config.c:1330 config_text_file_load: Parsing /etc/asterisk/meetme.conf == FoundCLI> [May 6 13:15:50] DEBUG[8019]: app_meetme.c:3607 find_conf: Will conf 1234 match 1234? [May 6 13:15:50] DEBUG[8019]: chan_dahdi.c:10970 dahdi_request: Using channel -2 [May 6 13:15:50] DEBUG[8019]: devicestate.c:440 devstate_event: device 'DAHDI/pseudo-930413059' state '2' [May 6 13:15:50] DEBUG[7991]: app_queue.c:1084 handle_statechange: Device 'DAHDI/pseudo-930413059' changed to state '2' (In use) but we don't care because they're not a member of any queue. [May 6 13:15:50] DEBUG[8019]: channel.c:3727 set_format: Set channel DAHDI/pseudo-930413059 to read format slin [May 6 13:15:50] DEBUG[8019]: channel.c:3727 set_format: Set channel DAHDI/pseudo-930413059 to write format slin -- Created MeetMe conference 1023 for conference '1234' [May 6 13:15:50] DEBUG[8019]: res_odbc.c:988 odbc_release_obj2: odbc_release_obj2(0xb7d0b1f8) called (obj->txf = (nil)) [May 6 13:15:50] DEBUG[8019]: res_odbc.c:988 odbc_release_obj2: odbc_release_obj2(0xb7d0b1f8) called (obj->txf = (nil)) [May 6 13:15:50] DEBUG[8019]: res_config_odbc.c:73 custom_prepare: Skip: 0; SQL: UPDATE meetme SET members=? WHERE confno=? [May 6 13:15:50] DEBUG[8019]: res_config_odbc.c:88 custom_prepare: Parameter 1 ('members') = '1' [May 6 13:15:50] DEBUG[8019]: res_odbc.c:988 odbc_release_obj2: odbc_release_obj2(0xb7d0b1f8) called (obj->txf = (nil)) [May 6 13:15:50] DEBUG[8019]: devicestate.c:440 devstate_event: device 'meetme:1234' state '2' [May 6 13:15:50] DEBUG[8019]: channel.c:2426 ast_settimeout: Scheduling timer at (50 requested / 50 actual) timer ticks per second -- Playing 'conf-onlyperson.ulaw' (language 'en') [May 6 13:15:50] DEBUG[7991]: app_queue.c:1084 handle_statechange: Device 'meetme:1234' changed to state '2' (In use) but we don't care because they're not a member of any queue. [May 6 13:15:50] DEBUG[8017]: rtp.c:3640 ast_rtp_raw_write: Difference is 19760, ms is 2490 [May 6 13:15:52] DEBUG[8017]: rtp.c:1227 ast_rtcp_read: Got RTCP report of 176 bytes [May 6 13:15:53] DEBUG[8019]: channel.c:2426 ast_settimeout: Scheduling timer at (86 requested / 86 actual) timer ticks per second [May 6 13:15:53] DEBUG[8019]: channel.c:2426 ast_settimeout: Scheduling timer at (0 requested / 0 actual) timer ticks per second [May 6 13:15:53] DEBUG[8019]: channel.c:2426 ast_settimeout: Scheduling timer at (0 requested / 0 actual) timer ticks per second [May 6 13:15:53] DEBUG[8019]: channel.c:2426 ast_settimeout: Scheduling timer at (0 requested / 0 actual) timer ticks per second [May 6 13:15:53] DEBUG[8019]: channel.c:3727 set_format: Set channel Local/start@test1-fa87;2 to write format slin [May 6 13:15:53] DEBUG[8019]: channel.c:3727 set_format: Set channel Local/start@test1-fa87;2 to read format slin [May 6 13:15:53] DEBUG[8019]: app_meetme.c:2457 conf_run: Placed channel Local/start@test1-fa87;2 in DAHDI conf 1023 [May 6 13:15:53] DEBUG[8017]: channel.c:4904 ast_generic_bridge: Got a FRAME_CONTROL (-1) frame on channel Local/start@test1-fa87;1 [May 6 13:15:53] DEBUG[8017]: channel.c:5301 ast_channel_bridge: Bridge stops bridging channels SIP/1003-00000000 and Local/start@test1-fa87;1 [May 6 13:15:53] DEBUG[8019]: dsp.c:472 ast_tone_detect_init: Setup tone 1100 Hz, 500 ms, block_size=160, hits_required=21 [May 6 13:15:53] DEBUG[8019]: dsp.c:472 ast_tone_detect_init: Setup tone 2100 Hz, 2600 ms, block_size=160, hits_required=116 [May 6 13:15:53] DEBUG[8017]: rtp.c:3640 ast_rtp_raw_write: Difference is 1144, ms is 163 [May 6 13:15:56] DEBUG[8017]: rtp.c:1227 ast_rtcp_read: Got RTCP report of 180 bytes [May 6 13:15:59] DEBUG[8017]: rtp.c:1227 ast_rtcp_read: Got RTCP report of 180 bytes [May 6 13:16:00] DEBUG[8003]: acl.c:506 ast_ouraddrfor: Found IP address for this socket [May 6 13:16:00] DEBUG[8003]: chan_sip.c:3678 ast_sip_ouraddrfor: Setting SIP_TRANSPORT_UDP with address 192.168.160.20:5060 [May 6 13:16:00] DEBUG[8003]: chan_sip.c:7290 sip_alloc: Allocating new SIP dialog for N2QwNzE3MzFiY2IwZmY5ZmM0YmMxYTk3MzA2YWI2ZDk. - SUBSCRIBE (No RTP) [May 6 13:16:00] DEBUG[8003]: chan_sip.c:3557 __sip_xmit: Trying to put 'SIP/2.0 481' onto UDP socket destined for 192.168.160.145:60708 [May 6 13:16:01] NOTICE[8017]: rtp.c:1778 ast_rtp_read: Unknown RTP codec 126 received from '192.168.10.202' [May 6 13:16:03] DEBUG[8017]: rtp.c:1227 ast_rtcp_read: Got RTCP report of 200 bytes [May 6 13:16:06] DEBUG[8017]: rtp.c:1227 ast_rtcp_read: Got RTCP report of 200 bytes [May 6 13:16:10] DEBUG[8017]: rtp.c:1227 ast_rtcp_read: Got RTCP report of 200 bytes <--- SIP read from UDP:192.168.10.202:12136 ---> <-------------> [May 6 13:16:13] DEBUG[8017]: rtp.c:1227 ast_rtcp_read: Got RTCP report of 200 bytes [May 6 13:16:17] DEBUG[8017]: rtp.c:1227 ast_rtcp_read: Got RTCP report of 180 bytes [May 6 13:16:20] DEBUG[8017]: rtp.c:1227 ast_rtcp_read: Got RTCP report of 180 bytes [May 6 13:16:24] DEBUG[8017]: rtp.c:1227 ast_rtcp_read: Got RTCP report of 208 bytes <--- SIP read from UDP:192.168.10.202:12136 ---> BYE sip:test@192.168.160.20 SIP/2.0 Via: SIP/2.0/UDP 192.168.10.202:12136;branch=z9hG4bK-d8754z-217a2b009a1f4b2e-1---d8754z-;rport Max-Forwards: 70 Contact: To: "test";tag=as019b8931 From: "displayname";tag=061bca55 Call-ID: MDFjY2NkZTA2YTBlYWE3ZmYxNGY2NTk0YjI3Yzc3NTU. CSeq: 3 BYE User-Agent: X-Lite release 1104o stamp 56125 Authorization: Digest username="1003",realm="asterisk",nonce="04548088",uri="sip:test@192.168.160.20",response="28536b9e39feb0fe290c008efc167327",algorithm=MD5 Reason: SIP;description="User Hung Up" Content-Length: 0 <-------------> --- (12 headers 0 lines) --- [May 6 13:16:24] DEBUG[8003]: chan_sip.c:21041 handle_request_bye: Initializing initreq for method BYE - callid MDFjY2NkZTA2YTBlYWE3ZmYxNGY2NTk0YjI3Yzc3NTU. Sending to 192.168.10.202 : 12136 (no NAT) [May 6 13:16:24] DEBUG[8003]: chan_sip.c:3282 sip_alreadygone: Setting SIP_ALREADYGONE on dialog MDFjY2NkZTA2YTBlYWE3ZmYxNGY2NTk0YjI3Yzc3NTU. [May 6 13:16:24] DEBUG[8003]: chan_sip.c:21139 handle_request_bye: Received bye, issuing owner hangup <--- Transmitting (no NAT) to 192.168.10.202:12136 ---> SIP/2.0 200 OK Via: SIP/2.0/UDP 192.168.10.202:12136;branch=z9hG4bK-d8754z-217a2b009a1f4b2e-1---d8754z-;received=192.168.10.202;rport=12136 From: "displayname";tag=061bca55 To: "test";tag=as019b8931 Call-ID: MDFjY2NkZTA2YTBlYWE3ZmYxNGY2NTk0YjI3Yzc3NTU. CSeq: 3 BYE Server: Asterisk PBX 1.6.2.6 Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO Supported: replaces, timer Content-Length: 0 <------------> [May 6 13:16:24] DEBUG[8003]: chan_sip.c:3557 __sip_xmit: Trying to put 'SIP/2.0 200' onto UDP socket destined for 192.168.10.202:12136 [May 6 13:16:24] DEBUG[8017]: channel.c:4877 ast_generic_bridge: Didn't get a frame from channel: SIP/1003-00000000 [May 6 13:16:24] DEBUG[8017]: channel.c:5301 ast_channel_bridge: Bridge stops bridging channels SIP/1003-00000000 and Local/start@test1-fa87;1 [May 6 13:16:24] DEBUG[8019]: app_meetme.c:3176 conf_run: Got unrecognized frame on channel Local/start@test1-fa87;2, f->frametype=4,f->subclass=20 [May 6 13:16:24] DEBUG[8017]: channel.c:1760 ast_hangup: Hanging up channel 'Local/start@test1-fa87;1' [May 6 13:16:24] DEBUG[8017]: rtp.c:2103 ast_rtp_early_bridge: Channel '' has no RTP, not doing anything [May 6 13:16:24] DEBUG[7983]: chan_local.c:146 local_devicestate: Checking if extension start@test1 exists (devicestate) [May 6 13:16:24] DEBUG[8017]: app_dial.c:2315 dial_exec_full: Exiting with DIALSTATUS=ANSWER. [May 6 13:16:24] DEBUG[7983]: devicestate.c:460 do_state_change: Changing state for Local/start@test1 - state 1 (Not in use) [May 6 13:16:24] DEBUG[7983]: devicestate.c:440 devstate_event: device 'Local/start@test1' state '1' [May 6 13:16:24] DEBUG[8017]: pbx.c:4306 __ast_pbx_run: Spawn extension (default,test,2) exited non-zero on 'SIP/1003-00000000' == Spawn extension (default, test, 2) exited non-zero on 'SIP/1003-00000000' [May 6 13:16:24] DEBUG[8017]: channel.c:1655 ast_softhangup_nolock: Soft-Hanging up channel 'SIP/1003-00000000' [May 6 13:16:24] DEBUG[7991]: app_queue.c:1084 handle_statechange: Device 'Local/start@test1' changed to state '1' (Not in use) but we don't care because they're not a member of any queue. [May 6 13:16:24] DEBUG[8019]: res_odbc.c:988 odbc_release_obj2: odbc_release_obj2(0xb7d0b1f8) called (obj->txf = (nil)) [May 6 13:16:24] DEBUG[8019]: res_odbc.c:988 odbc_release_obj2: odbc_release_obj2(0xb7d0b1f8) called (obj->txf = (nil)) [May 6 13:16:24] DEBUG[8019]: res_config_odbc.c:73 custom_prepare: Skip: 0; SQL: UPDATE meetme SET members=? WHERE confno=? [May 6 13:16:24] DEBUG[8019]: res_config_odbc.c:88 custom_prepare: Parameter 1 ('members') = '0' [May 6 13:16:24] DEBUG[8019]: res_odbc.c:988 odbc_release_obj2: odbc_release_obj2(0xb7d0b1f8) called (obj->txf = (nil)) [May 6 13:16:24] DEBUG[8019]: devicestate.c:440 devstate_event: device 'meetme:1234' state '1' [May 6 13:16:24] DEBUG[8019]: channel.c:1760 ast_hangup: Hanging up channel 'DAHDI/pseudo-930413059' [May 6 13:16:24] DEBUG[8019]: chan_dahdi.c:4323 dahdi_hangup: dahdi_hangup(DAHDI/pseudo-930413059) [May 6 13:16:24] DEBUG[8019]: chan_dahdi.c:4359 dahdi_hangup: Hangup: channel: -2 index = 0, normal = 30, callwait = -1, thirdcall = -1 [May 6 13:16:24] DEBUG[8019]: chan_dahdi.c:4896 dahdi_setoption: Set option TDD MODE, value: OFF(0) on DAHDI/pseudo-930413059 [May 6 13:16:24] DEBUG[8019]: chan_dahdi.c:2656 update_conf: Updated conferencing on -2, with 0 conference users -- Hungup 'DAHDI/pseudo-930413059' [May 6 13:16:24] DEBUG[8019]: pbx.c:4306 __ast_pbx_run: Spawn extension (test1,start,3) exited non-zero on 'Local/start@test1-fa87;2' == Spawn extension (test1, start, 3) exited non-zero on 'Local/start@test1-fa87;2' [May 6 13:16:24] DEBUG[7991]: app_queue.c:1084 handle_statechange: Device 'meetme:1234' changed to state '1' (Not in use) but we don't care because they're not a member of any queue. [May 6 13:16:24] DEBUG[8019]: channel.c:1655 ast_softhangup_nolock: Soft-Hanging up channel 'Local/start@test1-fa87;2' [May 6 13:16:24] DEBUG[8019]: channel.c:1760 ast_hangup: Hanging up channel 'Local/start@test1-fa87;2' [May 6 13:16:24] DEBUG[7983]: devicestate.c:460 do_state_change: Changing state for DAHDI/pseudo - state 0 (Unknown) [May 6 13:16:24] DEBUG[7983]: devicestate.c:440 devstate_event: device 'DAHDI/pseudo' state '0' [May 6 13:16:24] DEBUG[7983]: chan_local.c:146 local_devicestate: Checking if extension start@test1 exists (devicestate) [May 6 13:16:24] DEBUG[7991]: app_queue.c:1084 handle_statechange: Device 'DAHDI/pseudo' changed to state '0' (Unknown) but we don't care because they're not a member of any queue. [May 6 13:16:24] DEBUG[7983]: devicestate.c:460 do_state_change: Changing state for Local/start@test1 - state 1 (Not in use) [May 6 13:16:24] DEBUG[7983]: devicestate.c:440 devstate_event: device 'Local/start@test1' state '1' [May 6 13:16:24] DEBUG[7991]: app_queue.c:1084 handle_statechange: Device 'Local/start@test1' changed to state '1' (Not in use) but we don't care because they're not a member of any queue. [May 6 13:16:24] DEBUG[8017]: channel.c:1760 ast_hangup: Hanging up channel 'SIP/1003-00000000' [May 6 13:16:24] DEBUG[8017]: chan_sip.c:6005 sip_hangup: Hangup call SIP/1003-00000000, SIP callid MDFjY2NkZTA2YTBlYWE3ZmYxNGY2NTk0YjI3Yzc3NTU. [May 6 13:16:24] DEBUG[7983]: chan_sip.c:23000 sip_devicestate: Checking device state for peer 1003 [May 6 13:16:24] DEBUG[7983]: devicestate.c:460 do_state_change: Changing state for SIP/1003 - state 1 (Not in use) [May 6 13:16:24] DEBUG[7983]: devicestate.c:440 devstate_event: device 'SIP/1003' state '1' [May 6 13:16:24] DEBUG[7991]: app_queue.c:1084 handle_statechange: Device 'SIP/1003' changed to state '1' (Not in use) but we don't care because they're not a member of any queue. [May 6 13:16:25] DEBUG[8003]: chan_sip.c:5788 sip_destroy: Destroying SIP dialog MDFjY2NkZTA2YTBlYWE3ZmYxNGY2NTk0YjI3Yzc3NTU. Really destroying SIP dialog 'MDFjY2NkZTA2YTBlYWE3ZmYxNGY2NTk0YjI3Yzc3NTU.' Method: BYE