Asterisk 1.4.5, Copyright (C) 1999 - 2007 Digium, Inc. and others. Created by Mark Spencer Asterisk comes with ABSOLUTELY NO WARRANTY; type 'core show warranty' for details. This is free software, with components licensed under the GNU General Public License version 2 and other licenses; you are welcome to redistribute it under certain conditions. Type 'core show license' for details. ========================================================================= Connected to Asterisk 1.4.5 currently running on ubuntupbx (pid = 4143) ubuntupbx*CLI> Verbosity is at least 99 Core debug is at least 99 ubuntupbx*CLI> <--- SIP read from 192.168.100.126:5060 ---> INVITE sip:200@192.168.100.10;user=phone SIP/2.0 Via: SIP/2.0/UDP 192.168.100.126;branch=z9hG4bK57cbe8f6A63ECCB9 From: "100" ;tag=C09BD180-E64D3495 To: CSeq: 1 INVITE Call-ID: e6f53c04-a9e15a32-fff01997@192.168.100.126 Contact: Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, INFO, MESSAGE, SUBSCRIBE, NOTIFY, PRACK, UPDATE, REFER User-Agent: PolycomSoundPointIP-SPIP_501-UA/2.1.0.2708 Supported: 100rel,replaces Allow-Events: talk,hold,conference Max-Forwards: 70 Content-Type: application/sdp Content-Length: 255 v=0 o=- 1182877674 1182877674 IN IP4 192.168.100.126 s=Polycom IP Phone c=IN IP4 192.168.100.126 t=0 0 m=audio 2250 RTP/AVP 0 8 18 101 a=sendrecv a=rtpmap:0 PCMU/8000 a=rtpmap:8 PCMA/8000 a=rtpmap:18 G729/8000 a=rtpmap:101 telephone-event/8000 <-------------> [Jun 26 16:33:49] DEBUG[4254]: chan_sip.c:4634 parse_request: Header 0: INVITE sip:200@192.168.100.10;user=phone SIP/2.0 (48) [Jun 26 16:33:49] DEBUG[4254]: chan_sip.c:4634 parse_request: Header 1: Via: SIP/2.0/UDP 192.168.100.126;branch=z9hG4bK57cbe8f6A63ECCB9 (63) [Jun 26 16:33:49] DEBUG[4254]: chan_sip.c:4634 parse_request: Header 2: From: "100" ;tag=C09BD180-E64D3495 (58) [Jun 26 16:33:49] DEBUG[4254]: chan_sip.c:4634 parse_request: Header 3: To: (39) [Jun 26 16:33:49] DEBUG[4254]: chan_sip.c:4634 parse_request: Header 4: CSeq: 1 INVITE (14) [Jun 26 16:33:49] DEBUG[4254]: chan_sip.c:4634 parse_request: Header 5: Call-ID: e6f53c04-a9e15a32-fff01997@192.168.100.126 (51) [Jun 26 16:33:49] DEBUG[4254]: chan_sip.c:4634 parse_request: Header 6: Contact: (34) [Jun 26 16:33:49] DEBUG[4254]: chan_sip.c:4634 parse_request: Header 7: Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, INFO, MESSAGE, SUBSCRIBE, NOTIFY, PRACK, UPDATE, REFER (96) [Jun 26 16:33:49] DEBUG[4254]: chan_sip.c:4634 parse_request: Header 8: User-Agent: PolycomSoundPointIP-SPIP_501-UA/2.1.0.2708 (54) [Jun 26 16:33:49] DEBUG[4254]: chan_sip.c:4634 parse_request: Header 9: Supported: 100rel,replaces (26) [Jun 26 16:33:49] DEBUG[4254]: chan_sip.c:4634 parse_request: Header 10: Allow-Events: talk,hold,conference (34) [Jun 26 16:33:49] DEBUG[4254]: chan_sip.c:4634 parse_request: Header 11: Max-Forwards: 70 (16) [Jun 26 16:33:49] DEBUG[4254]: chan_sip.c:4634 parse_request: Header 12: Content-Type: application/sdp (29) [Jun 26 16:33:49] DEBUG[4254]: chan_sip.c:4634 parse_request: Header 13: Content-Length: 255 (19) [Jun 26 16:33:49] DEBUG[4254]: chan_sip.c:4634 parse_request: Header 14: (0) [Jun 26 16:33:49] DEBUG[4254]: chan_sip.c:4666 parse_request: Line: v=0 (3) [Jun 26 16:33:49] DEBUG[4254]: chan_sip.c:4666 parse_request: Line: o=- 1182877674 1182877674 IN IP4 192.168.100.126 (48) [Jun 26 16:33:49] DEBUG[4254]: chan_sip.c:4666 parse_request: Line: s=Polycom IP Phone (18) [Jun 26 16:33:49] DEBUG[4254]: chan_sip.c:4666 parse_request: Line: c=IN IP4 192.168.100.126 (24) [Jun 26 16:33:49] DEBUG[4254]: chan_sip.c:4666 parse_request: Line: t=0 0 (5) [Jun 26 16:33:49] DEBUG[4254]: chan_sip.c:4666 parse_request: Line: m=audio 2250 RTP/AVP 0 8 18 101 (31) [Jun 26 16:33:49] DEBUG[4254]: chan_sip.c:4666 parse_request: Line: a=sendrecv (10) [Jun 26 16:33:49] DEBUG[4254]: chan_sip.c:4666 parse_request: Line: a=rtpmap:0 PCMU/8000 (20) [Jun 26 16:33:49] DEBUG[4254]: chan_sip.c:4666 parse_request: Line: a=rtpmap:8 PCMA/8000 (20) [Jun 26 16:33:49] DEBUG[4254]: chan_sip.c:4666 parse_request: Line: a=rtpmap:18 G729/8000 (21) [Jun 26 16:33:49] DEBUG[4254]: chan_sip.c:4666 parse_request: Line: a=rtpmap:101 telephone-event/8000 (33) --- (14 headers 11 lines) --- [Jun 26 16:33:49] DEBUG[4254]: chan_sip.c:4422 find_call: = No match Their Call ID: a21612ae-a8cfba3c-459f41b1@192.168.100.126 Their Tag 3F7E4EA-DC26AF0F Our tag: as407508a4 [Jun 26 16:33:49] DEBUG[4254]: chan_sip.c:2623 do_setnat: Setting NAT on RTP to Off [Jun 26 16:33:49] DEBUG[4254]: chan_sip.c:4369 sip_alloc: Allocating new SIP dialog for e6f53c04-a9e15a32-fff01997@192.168.100.126 - INVITE (With RTP) [Jun 26 16:33:49] DEBUG[4254]: chan_sip.c:14830 handle_request: **** Received INVITE (5) - Command in SIP INVITE [Jun 26 16:33:49] DEBUG[4254]: chan_sip.c:1687 parse_sip_options: Begin: parsing SIP "Supported: 100rel,replaces" [Jun 26 16:33:49] DEBUG[4254]: chan_sip.c:1695 parse_sip_options: Found SIP option: -100rel- [Jun 26 16:33:49] DEBUG[4254]: chan_sip.c:1701 parse_sip_options: Matched SIP option: 100rel [Jun 26 16:33:49] DEBUG[4254]: chan_sip.c:1695 parse_sip_options: Found SIP option: -replaces- [Jun 26 16:33:49] DEBUG[4254]: chan_sip.c:1701 parse_sip_options: Matched SIP option: replaces Sending to 192.168.100.126 : 5060 (no NAT) Using INVITE request as basis request - e6f53c04-a9e15a32-fff01997@192.168.100.126 [Jun 26 16:33:49] DEBUG[4254]: chan_sip.c:2623 do_setnat: Setting NAT on RTP to Off <--- Reliably Transmitting (no NAT) to 192.168.100.126:5060 ---> SIP/2.0 407 Proxy Authentication Required Via: SIP/2.0/UDP 192.168.100.126;branch=z9hG4bK57cbe8f6A63ECCB9;received=192.168.100.126 From: "100" ;tag=C09BD180-E64D3495 To: ;tag=as25a27806 Call-ID: e6f53c04-a9e15a32-fff01997@192.168.100.126 CSeq: 1 INVITE User-Agent: Asterisk PBX Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY Supported: replaces Proxy-Authenticate: Digest algorithm=MD5, realm="asterisk", nonce="519c71a2" Content-Length: 0 <------------> [Jun 26 16:33:49] DEBUG[4254]: chan_sip.c:2016 __sip_reliable_xmit: *** SIP TIMER: Initalizing retransmit timer on packet: Id #312 Scheduling destruction of SIP dialog 'e6f53c04-a9e15a32-fff01997@192.168.100.126' in 32000 ms (Method: INVITE) Found user '100' ubuntupbx*CLI> <--- SIP read from 192.168.100.126:5060 ---> ACK sip:200@192.168.100.10 SIP/2.0 Via: SIP/2.0/UDP 192.168.100.126;branch=z9hG4bK57cbe8f6A63ECCB9 From: "100" ;tag=C09BD180-E64D3495 To: ;tag=as25a27806 CSeq: 1 ACK Call-ID: e6f53c04-a9e15a32-fff01997@192.168.100.126 Contact: Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, INFO, MESSAGE, SUBSCRIBE, NOTIFY, PRACK, UPDATE, REFER User-Agent: PolycomSoundPointIP-SPIP_501-UA/2.1.0.2708 Max-Forwards: 70 Content-Length: 0 <-------------> [Jun 26 16:33:49] DEBUG[4254]: chan_sip.c:4634 parse_request: Header 0: ACK sip:200@192.168.100.10 SIP/2.0 (34) [Jun 26 16:33:49] DEBUG[4254]: chan_sip.c:4634 parse_request: Header 1: Via: SIP/2.0/UDP 192.168.100.126;branch=z9hG4bK57cbe8f6A63ECCB9 (63) [Jun 26 16:33:49] DEBUG[4254]: chan_sip.c:4634 parse_request: Header 2: From: "100" ;tag=C09BD180-E64D3495 (58) [Jun 26 16:33:49] DEBUG[4254]: chan_sip.c:4634 parse_request: Header 3: To: ;tag=as25a27806 (54) [Jun 26 16:33:49] DEBUG[4254]: chan_sip.c:4634 parse_request: Header 4: CSeq: 1 ACK (11) [Jun 26 16:33:49] DEBUG[4254]: chan_sip.c:4634 parse_request: Header 5: Call-ID: e6f53c04-a9e15a32-fff01997@192.168.100.126 (51) [Jun 26 16:33:49] DEBUG[4254]: chan_sip.c:4634 parse_request: Header 6: Contact: (34) [Jun 26 16:33:49] DEBUG[4254]: chan_sip.c:4634 parse_request: Header 7: Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, INFO, MESSAGE, SUBSCRIBE, NOTIFY, PRACK, UPDATE, REFER (96) [Jun 26 16:33:49] DEBUG[4254]: chan_sip.c:4634 parse_request: Header 8: User-Agent: PolycomSoundPointIP-SPIP_501-UA/2.1.0.2708 (54) [Jun 26 16:33:49] DEBUG[4254]: chan_sip.c:4634 parse_request: Header 9: Max-Forwards: 70 (16) [Jun 26 16:33:49] DEBUG[4254]: chan_sip.c:4634 parse_request: Header 10: Content-Length: 0 (17) [Jun 26 16:33:49] DEBUG[4254]: chan_sip.c:4634 parse_request: Header 11: (0) --- (11 headers 0 lines) --- [Jun 26 16:33:49] DEBUG[4254]: chan_sip.c:4422 find_call: = Found Their Call ID: e6f53c04-a9e15a32-fff01997@192.168.100.126 Their Tag C09BD180-E64D3495 Our tag: as25a27806 [Jun 26 16:33:49] DEBUG[4254]: chan_sip.c:14830 handle_request: **** Received ACK (6) - Command in SIP ACK [Jun 26 16:33:49] DEBUG[4254]: chan_sip.c:2127 __sip_ack: ** SIP TIMER: Cancelling retransmit of packet (reply received) Retransid #312 [Jun 26 16:33:49] DEBUG[4254]: chan_sip.c:2137 __sip_ack: Stopping retransmission on 'e6f53c04-a9e15a32-fff01997@192.168.100.126' of Response 1: Match Not Found ubuntupbx*CLI> <--- SIP read from 192.168.100.126:5060 ---> INVITE sip:200@192.168.100.10;user=phone SIP/2.0 Via: SIP/2.0/UDP 192.168.100.126;branch=z9hG4bK5f877bb35B734FEE From: "100" ;tag=C09BD180-E64D3495 To: CSeq: 2 INVITE Call-ID: e6f53c04-a9e15a32-fff01997@192.168.100.126 Contact: Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, INFO, MESSAGE, SUBSCRIBE, NOTIFY, PRACK, UPDATE, REFER User-Agent: PolycomSoundPointIP-SPIP_501-UA/2.1.0.2708 Supported: 100rel,replaces Allow-Events: talk,hold,conference Proxy-Authorization: Digest username="100", realm="asterisk", nonce="519c71a2", uri="sip:200@192.168.100.10;user=phone", response="62fd1cab8d0e06044b778bfea674079d", algorithm=MD5 Max-Forwards: 70 Content-Type: application/sdp Content-Length: 255 v=0 o=- 1182877674 1182877674 IN IP4 192.168.100.126 s=Polycom IP Phone c=IN IP4 192.168.100.126 t=0 0 m=audio 2250 RTP/AVP 0 8 18 101 a=sendrecv a=rtpmap:0 PCMU/8000 a=rtpmap:8 PCMA/8000 a=rtpmap:18 G729/8000 a=rtpmap:101 telephone-event/8000 <-------------> [Jun 26 16:33:49] DEBUG[4254]: chan_sip.c:4634 parse_request: Header 0: INVITE sip:200@192.168.100.10;user=phone SIP/2.0 (48) [Jun 26 16:33:49] DEBUG[4254]: chan_sip.c:4634 parse_request: Header 1: Via: SIP/2.0/UDP 192.168.100.126;branch=z9hG4bK5f877bb35B734FEE (63) [Jun 26 16:33:49] DEBUG[4254]: chan_sip.c:4634 parse_request: Header 2: From: "100" ;tag=C09BD180-E64D3495 (58) [Jun 26 16:33:49] DEBUG[4254]: chan_sip.c:4634 parse_request: Header 3: To: (39) [Jun 26 16:33:49] DEBUG[4254]: chan_sip.c:4634 parse_request: Header 4: CSeq: 2 INVITE (14) [Jun 26 16:33:49] DEBUG[4254]: chan_sip.c:4634 parse_request: Header 5: Call-ID: e6f53c04-a9e15a32-fff01997@192.168.100.126 (51) [Jun 26 16:33:49] DEBUG[4254]: chan_sip.c:4634 parse_request: Header 6: Contact: (34) [Jun 26 16:33:49] DEBUG[4254]: chan_sip.c:4634 parse_request: Header 7: Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, INFO, MESSAGE, SUBSCRIBE, NOTIFY, PRACK, UPDATE, REFER (96) [Jun 26 16:33:49] DEBUG[4254]: chan_sip.c:4634 parse_request: Header 8: User-Agent: PolycomSoundPointIP-SPIP_501-UA/2.1.0.2708 (54) [Jun 26 16:33:49] DEBUG[4254]: chan_sip.c:4634 parse_request: Header 9: Supported: 100rel,replaces (26) [Jun 26 16:33:49] DEBUG[4254]: chan_sip.c:4634 parse_request: Header 10: Allow-Events: talk,hold,conference (34) [Jun 26 16:33:49] DEBUG[4254]: chan_sip.c:4634 parse_request: Header 11: Proxy-Authorization: Digest username="100", realm="asterisk", nonce="519c71a2", uri="sip:200@192.168.100.10;user=phone", response="62fd1cab8d0e06044b778bfea674079d", algorithm=MD5 (179) [Jun 26 16:33:49] DEBUG[4254]: chan_sip.c:4634 parse_request: Header 12: Max-Forwards: 70 (16) [Jun 26 16:33:49] DEBUG[4254]: chan_sip.c:4634 parse_request: Header 13: Content-Type: application/sdp (29) [Jun 26 16:33:49] DEBUG[4254]: chan_sip.c:4634 parse_request: Header 14: Content-Length: 255 (19) [Jun 26 16:33:49] DEBUG[4254]: chan_sip.c:4634 parse_request: Header 15: (0) [Jun 26 16:33:49] DEBUG[4254]: chan_sip.c:4666 parse_request: Line: v=0 (3) [Jun 26 16:33:49] DEBUG[4254]: chan_sip.c:4666 parse_request: Line: o=- 1182877674 1182877674 IN IP4 192.168.100.126 (48) [Jun 26 16:33:49] DEBUG[4254]: chan_sip.c:4666 parse_request: Line: s=Polycom IP Phone (18) [Jun 26 16:33:49] DEBUG[4254]: chan_sip.c:4666 parse_request: Line: c=IN IP4 192.168.100.126 (24) [Jun 26 16:33:49] DEBUG[4254]: chan_sip.c:4666 parse_request: Line: t=0 0 (5) [Jun 26 16:33:49] DEBUG[4254]: chan_sip.c:4666 parse_request: Line: m=audio 2250 RTP/AVP 0 8 18 101 (31) [Jun 26 16:33:49] DEBUG[4254]: chan_sip.c:4666 parse_request: Line: a=sendrecv (10) [Jun 26 16:33:49] DEBUG[4254]: chan_sip.c:4666 parse_request: Line: a=rtpmap:0 PCMU/8000 (20) [Jun 26 16:33:49] DEBUG[4254]: chan_sip.c:4666 parse_request: Line: a=rtpmap:8 PCMA/8000 (20) [Jun 26 16:33:49] DEBUG[4254]: chan_sip.c:4666 parse_request: Line: a=rtpmap:18 G729/8000 (21) [Jun 26 16:33:49] DEBUG[4254]: chan_sip.c:4666 parse_request: Line: a=rtpmap:101 telephone-event/8000 (33) --- (15 headers 11 lines) --- [Jun 26 16:33:49] DEBUG[4254]: chan_sip.c:4422 find_call: = Found Their Call ID: e6f53c04-a9e15a32-fff01997@192.168.100.126 Their Tag C09BD180-E64D3495 Our tag: as25a27806 [Jun 26 16:33:49] DEBUG[4254]: chan_sip.c:14830 handle_request: **** Received INVITE (5) - Command in SIP INVITE Sending to 192.168.100.126 : 5060 (no NAT) Using INVITE request as basis request - e6f53c04-a9e15a32-fff01997@192.168.100.126 [Jun 26 16:33:49] DEBUG[4254]: chan_sip.c:2623 do_setnat: Setting NAT on RTP to Off Found user '100' Found RTP audio format 0 Found RTP audio format 8 Found RTP audio format 18 Found RTP audio format 101 Peer audio RTP is at port 192.168.100.126:2250 Found description format PCMU for ID 0 Found description format PCMA for ID 8 Found description format G729 for ID 18 Found description format telephone-event for ID 101 [Jun 26 16:33:49] DEBUG[4254]: chan_sip.c:5220 process_sdp: T38 state changed to 0 on channel Capabilities: us - 0x6 (gsm|ulaw), peer - audio=0x10c (ulaw|alaw|g729)/video=0x0 (nothing), combined - 0x4 (ulaw) Non-codec capabilities (dtmf): us - 0x1 (telephone-event), peer - 0x1 (telephone-event), combined - 0x1 (telephone-event) Peer audio RTP is at port 192.168.100.126:2250 [Jun 26 16:33:49] DEBUG[4254]: chan_sip.c:5300 process_sdp: We're settling with these formats: 0x4 (ulaw) [Jun 26 16:33:49] DEBUG[4254]: chan_sip.c:13525 handle_request_invite: Checking SIP call limits for device 100 [Jun 26 16:33:49] DEBUG[4254]: chan_sip.c:3055 update_call_counter: Updating call counter for incoming call Looking for 200 in sip (domain 192.168.100.10) [Jun 26 16:33:49] DEBUG[4254]: chan_sip.c:3861 sip_new: *** Our native formats are 0x4 (ulaw) [Jun 26 16:33:49] DEBUG[4254]: chan_sip.c:3862 sip_new: *** Joint capabilities are 0x4 (ulaw) [Jun 26 16:33:49] DEBUG[4254]: chan_sip.c:3863 sip_new: *** Our capabilities are 0x6 (gsm|ulaw) [Jun 26 16:33:49] DEBUG[4254]: chan_sip.c:3864 sip_new: *** AST_CODEC_CHOOSE formats are 0x4 (ulaw) [Jun 26 16:33:49] DEBUG[4254]: chan_sip.c:3887 sip_new: This channel will not be able to handle video. [Jun 26 16:33:49] DEBUG[4254]: chan_sip.c:8058 build_route: build_route: Contact hop: list_route: hop: [Jun 26 16:33:49] DEBUG[4254]: chan_sip.c:13600 handle_request_invite: SIP/100-081db608: New call is still down.... Trying... <--- Transmitting (no NAT) to 192.168.100.126:5060 ---> SIP/2.0 100 Trying Via: SIP/2.0/UDP 192.168.100.126;branch=z9hG4bK5f877bb35B734FEE;received=192.168.100.126 From: "100" ;tag=C09BD180-E64D3495 To: Call-ID: e6f53c04-a9e15a32-fff01997@192.168.100.126 CSeq: 2 INVITE User-Agent: Asterisk PBX Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY Supported: replaces Contact: Content-Length: 0 <------------> [Jun 26 16:33:49] DEBUG[4254]: devicestate.c:304 __ast_device_state_changed_literal: Notification of state change to be queued on device/channel SIP/100-081db608 [Jun 26 16:33:49] DEBUG[4157]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for SIP - 100 [Jun 26 16:33:49] DEBUG[4157]: chan_sip.c:15450 sip_devicestate: Checking device state for peer 100 [Jun 26 16:33:49] DEBUG[4157]: devicestate.c:287 do_state_change: Changing state for SIP/100 - state 1 (Not in use) [Jun 26 16:33:49] DEBUG[5669]: pbx.c:1662 pbx_substitute_variables_helper_full: Function result is '100' [Jun 26 16:33:49] DEBUG[5669]: pbx.c:1809 pbx_extension_helper: Launching 'VoiceMailMain' -- Executing [200@sip:1] VoiceMailMain("SIP/100-081db608", "100@atlantiatech") in new stack [Jun 26 16:33:49] DEBUG[5669]: app_voicemail.c:6277 vm_execmain: Before ast_answer [Jun 26 16:33:49] DEBUG[5669]: devicestate.c:304 __ast_device_state_changed_literal: Notification of state change to be queued on device/channel SIP/100-081db608 [Jun 26 16:33:49] DEBUG[5669]: chan_sip.c:3519 sip_answer: SIP answering channel: SIP/100-081db608 [Jun 26 16:33:49] DEBUG[5669]: chan_sip.c:6490 transmit_response_with_sdp: Setting framing from config on incoming call [Jun 26 16:33:49] DEBUG[5669]: chan_sip.c:6254 add_sdp: ** Our capability: 0x4 (ulaw) Video flag: True [Jun 26 16:33:49] DEBUG[5669]: chan_sip.c:6255 add_sdp: ** Our prefcodec: 0x0 (nothing) Audio is at 192.168.100.10 port 18490 Adding codec 0x4 (ulaw) to SDP Adding non-codec 0x1 (telephone-event) to SDP [Jun 26 16:33:49] DEBUG[5669]: chan_sip.c:6386 add_sdp: -- Done with adding codecs to SDP [Jun 26 16:33:49] DEBUG[5669]: channel.c:2499 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=30) [Jun 26 16:33:49] DEBUG[5669]: chan_sip.c:6431 add_sdp: Done building SDP. Settling with this capability: 0x4 (ulaw) <--- Reliably Transmitting (no NAT) to 192.168.100.126:5060 ---> SIP/2.0 200 OK Via: SIP/2.0/UDP 192.168.100.126;branch=z9hG4bK5f877bb35B734FEE;received=192.168.100.126 From: "100" ;tag=C09BD180-E64D3495 To: ;tag=as2e352b63 Call-ID: e6f53c04-a9e15a32-fff01997@192.168.100.126 CSeq: 2 INVITE User-Agent: Asterisk PBX Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY Supported: replaces Contact: Content-Type: application/sdp Content-Length: 242 v=0 o=root 4143 4143 IN IP4 192.168.100.10 s=session c=IN IP4 192.168.100.10 t=0 0 m=audio 18490 RTP/AVP 0 101 a=rtpmap:0 PCMU/8000 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-16 a=silenceSupp:off - - - - a=ptime:20 a=sendrecv <------------> [Jun 26 16:33:49] DEBUG[5669]: chan_sip.c:2016 __sip_reliable_xmit: *** SIP TIMER: Initalizing retransmit timer on packet: Id #314 [Jun 26 16:33:49] DEBUG[5669]: app_voicemail.c:6184 vm_authenticate: Before find user for mailbox 100 [Jun 26 16:33:49] DEBUG[5669]: channel.c:2976 set_format: Set channel SIP/100-081db608 to write format gsm [Jun 26 16:33:49] DEBUG[5669]: rtp.c:2719 ast_rtp_write: Ooh, format changed from unknown to ulaw [Jun 26 16:33:49] DEBUG[5669]: rtp.c:2736 ast_rtp_write: Created smoother: format: 4 ms: 20 len: 160 [Jun 26 16:33:49] DEBUG[5669]: channel.c:2061 ast_settimeout: Scheduling timer at 160 sample intervals -- Playing 'vm-password' (language 'en') [Jun 26 16:33:49] DEBUG[5670]: app_queue.c:546 changethread: Device 'SIP/100' changed to state '1' (Not in use) but we don't care because they're not a member of any queue. [Jun 26 16:33:49] DEBUG[4157]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for SIP - 100 [Jun 26 16:33:49] DEBUG[4157]: chan_sip.c:15450 sip_devicestate: Checking device state for peer 100 [Jun 26 16:33:49] DEBUG[4157]: devicestate.c:287 do_state_change: Changing state for SIP/100 - state 1 (Not in use) [Jun 26 16:33:49] DEBUG[5671]: app_queue.c:546 changethread: Device 'SIP/100' changed to state '1' (Not in use) but we don't care because they're not a member of any queue. ubuntupbx*CLI> <--- SIP read from 192.168.100.126:5060 ---> ACK sip:200@192.168.100.10 SIP/2.0 Via: SIP/2.0/UDP 192.168.100.126;branch=z9hG4bKc377ba2a3582E5CD From: "100" ;tag=C09BD180-E64D3495 To: ;tag=as2e352b63 CSeq: 2 ACK Call-ID: e6f53c04-a9e15a32-fff01997@192.168.100.126 Contact: Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, INFO, MESSAGE, SUBSCRIBE, NOTIFY, PRACK, UPDATE, REFER User-Agent: PolycomSoundPointIP-SPIP_501-UA/2.1.0.2708 Proxy-Authorization: Digest username="100", realm="asterisk", nonce="519c71a2", uri="sip:200@192.168.100.10;user=phone", response="62fd1cab8d0e06044b778bfea674079d", algorithm=MD5 Max-Forwards: 70 Content-Length: 0 <-------------> [Jun 26 16:33:49] DEBUG[4254]: chan_sip.c:4634 parse_request: Header 0: ACK sip:200@192.168.100.10 SIP/2.0 (34) [Jun 26 16:33:49] DEBUG[4254]: chan_sip.c:4634 parse_request: Header 1: Via: SIP/2.0/UDP 192.168.100.126;branch=z9hG4bKc377ba2a3582E5CD (63) [Jun 26 16:33:49] DEBUG[4254]: chan_sip.c:4634 parse_request: Header 2: From: "100" ;tag=C09BD180-E64D3495 (58) [Jun 26 16:33:49] DEBUG[4254]: chan_sip.c:4634 parse_request: Header 3: To: ;tag=as2e352b63 (54) [Jun 26 16:33:49] DEBUG[4254]: chan_sip.c:4634 parse_request: Header 4: CSeq: 2 ACK (11) [Jun 26 16:33:49] DEBUG[4254]: chan_sip.c:4634 parse_request: Header 5: Call-ID: e6f53c04-a9e15a32-fff01997@192.168.100.126 (51) [Jun 26 16:33:49] DEBUG[4254]: chan_sip.c:4634 parse_request: Header 6: Contact: (34) [Jun 26 16:33:49] DEBUG[4254]: chan_sip.c:4634 parse_request: Header 7: Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, INFO, MESSAGE, SUBSCRIBE, NOTIFY, PRACK, UPDATE, REFER (96) [Jun 26 16:33:49] DEBUG[4254]: chan_sip.c:4634 parse_request: Header 8: User-Agent: PolycomSoundPointIP-SPIP_501-UA/2.1.0.2708 (54) [Jun 26 16:33:49] DEBUG[4254]: chan_sip.c:4634 parse_request: Header 9: Proxy-Authorization: Digest username="100", realm="asterisk", nonce="519c71a2", uri="sip:200@192.168.100.10;user=phone", response="62fd1cab8d0e06044b778bfea674079d", algorithm=MD5 (179) [Jun 26 16:33:49] DEBUG[4254]: chan_sip.c:4634 parse_request: Header 10: Max-Forwards: 70 (16) [Jun 26 16:33:49] DEBUG[4254]: chan_sip.c:4634 parse_request: Header 11: Content-Length: 0 (17) [Jun 26 16:33:49] DEBUG[4254]: chan_sip.c:4634 parse_request: Header 12: (0) --- (12 headers 0 lines) --- [Jun 26 16:33:49] DEBUG[4254]: chan_sip.c:4422 find_call: = Found Their Call ID: e6f53c04-a9e15a32-fff01997@192.168.100.126 Their Tag C09BD180-E64D3495 Our tag: as2e352b63 [Jun 26 16:33:49] DEBUG[4254]: chan_sip.c:14830 handle_request: **** Received ACK (6) - Command in SIP ACK [Jun 26 16:33:49] DEBUG[4254]: chan_sip.c:2127 __sip_ack: ** SIP TIMER: Cancelling retransmit of packet (reply received) Retransid #314 [Jun 26 16:33:49] DEBUG[4254]: chan_sip.c:2137 __sip_ack: Stopping retransmission on 'e6f53c04-a9e15a32-fff01997@192.168.100.126' of Response 2: Match Not Found ubuntupbx*CLI> [Jun 26 16:33:50] DEBUG[5669]: channel.c:2061 ast_settimeout: Scheduling timer at 0 sample intervals [Jun 26 16:33:50] DEBUG[5669]: channel.c:2061 ast_settimeout: Scheduling timer at 0 sample intervals [Jun 26 16:33:50] DEBUG[5669]: channel.c:2976 set_format: Set channel SIP/100-081db608 to write format ulaw ubuntupbx*CLI> [Jun 26 16:33:51] DEBUG[5669]: rtp.c:727 process_rfc2833: - RTP 2833 Event: 00000001 (len = 4) [Jun 26 16:33:51] DEBUG[5669]: rtp.c:626 send_dtmf: Sending dtmf: 49 (1), at 192.168.100.126 ubuntupbx*CLI> [Jun 26 16:33:51] DEBUG[5669]: rtp.c:727 process_rfc2833: - RTP 2833 Event: 00000001 (len = 4) ubuntupbx*CLI> [Jun 26 16:33:51] DEBUG[5669]: rtp.c:727 process_rfc2833: - RTP 2833 Event: 00000001 (len = 4) ubuntupbx*CLI> [Jun 26 16:33:51] DEBUG[5669]: rtp.c:727 process_rfc2833: - RTP 2833 Event: 00000001 (len = 4) [Jun 26 16:33:51] DEBUG[5669]: rtp.c:626 send_dtmf: Sending dtmf: 49 (1), at 192.168.100.126 ubuntupbx*CLI> [Jun 26 16:33:51] DEBUG[5669]: rtp.c:727 process_rfc2833: - RTP 2833 Event: 00000001 (len = 4) ubuntupbx*CLI> [Jun 26 16:33:51] DEBUG[5669]: rtp.c:727 process_rfc2833: - RTP 2833 Event: 00000001 (len = 4) ubuntupbx*CLI> [Jun 26 16:33:51] DEBUG[5669]: rtp.c:727 process_rfc2833: - RTP 2833 Event: 00000002 (len = 4) [Jun 26 16:33:51] DEBUG[5669]: rtp.c:626 send_dtmf: Sending dtmf: 50 (2), at 192.168.100.126 ubuntupbx*CLI> [Jun 26 16:33:51] DEBUG[5669]: rtp.c:727 process_rfc2833: - RTP 2833 Event: 00000002 (len = 4) ubuntupbx*CLI> [Jun 26 16:33:51] DEBUG[5669]: rtp.c:727 process_rfc2833: - RTP 2833 Event: 00000002 (len = 4) ubuntupbx*CLI> [Jun 26 16:33:51] DEBUG[5669]: rtp.c:727 process_rfc2833: - RTP 2833 Event: 00000002 (len = 4) ubuntupbx*CLI> [Jun 26 16:33:51] DEBUG[5669]: rtp.c:727 process_rfc2833: - RTP 2833 Event: 00000002 (len = 4) [Jun 26 16:33:51] DEBUG[5669]: rtp.c:626 send_dtmf: Sending dtmf: 50 (2), at 192.168.100.126 ubuntupbx*CLI> [Jun 26 16:33:51] DEBUG[5669]: rtp.c:727 process_rfc2833: - RTP 2833 Event: 00000002 (len = 4) ubuntupbx*CLI> [Jun 26 16:33:51] DEBUG[5669]: rtp.c:727 process_rfc2833: - RTP 2833 Event: 00000002 (len = 4) ubuntupbx*CLI> [Jun 26 16:33:51] DEBUG[5669]: rtp.c:727 process_rfc2833: - RTP 2833 Event: 00000003 (len = 4) [Jun 26 16:33:51] DEBUG[5669]: rtp.c:626 send_dtmf: Sending dtmf: 51 (3), at 192.168.100.126 ubuntupbx*CLI> [Jun 26 16:33:51] DEBUG[5669]: rtp.c:727 process_rfc2833: - RTP 2833 Event: 00000003 (len = 4) ubuntupbx*CLI> [Jun 26 16:33:51] DEBUG[5669]: rtp.c:727 process_rfc2833: - RTP 2833 Event: 00000003 (len = 4) ubuntupbx*CLI> [Jun 26 16:33:51] DEBUG[5669]: rtp.c:727 process_rfc2833: - RTP 2833 Event: 00000003 (len = 4) ubuntupbx*CLI> [Jun 26 16:33:51] DEBUG[5669]: rtp.c:727 process_rfc2833: - RTP 2833 Event: 00000003 (len = 4) [Jun 26 16:33:51] DEBUG[5669]: rtp.c:626 send_dtmf: Sending dtmf: 51 (3), at 192.168.100.126 ubuntupbx*CLI> [Jun 26 16:33:51] DEBUG[5669]: rtp.c:727 process_rfc2833: - RTP 2833 Event: 00000003 (len = 4) ubuntupbx*CLI> [Jun 26 16:33:51] DEBUG[5669]: rtp.c:727 process_rfc2833: - RTP 2833 Event: 00000003 (len = 4) ubuntupbx*CLI> [Jun 26 16:33:51] DEBUG[5669]: rtp.c:727 process_rfc2833: - RTP 2833 Event: 00000004 (len = 4) [Jun 26 16:33:51] DEBUG[5669]: rtp.c:626 send_dtmf: Sending dtmf: 52 (4), at 192.168.100.126 ubuntupbx*CLI> [Jun 26 16:33:52] DEBUG[5669]: rtp.c:727 process_rfc2833: - RTP 2833 Event: 00000004 (len = 4) ubuntupbx*CLI> [Jun 26 16:33:52] DEBUG[5669]: rtp.c:727 process_rfc2833: - RTP 2833 Event: 00000004 (len = 4) ubuntupbx*CLI> [Jun 26 16:33:52] DEBUG[5669]: rtp.c:727 process_rfc2833: - RTP 2833 Event: 00000004 (len = 4) ubuntupbx*CLI> [Jun 26 16:33:52] DEBUG[5669]: rtp.c:727 process_rfc2833: - RTP 2833 Event: 00000004 (len = 4) ubuntupbx*CLI> [Jun 26 16:33:52] DEBUG[5669]: rtp.c:727 process_rfc2833: - RTP 2833 Event: 00000004 (len = 4) [Jun 26 16:33:52] DEBUG[5669]: rtp.c:626 send_dtmf: Sending dtmf: 52 (4), at 192.168.100.126 ubuntupbx*CLI> [Jun 26 16:33:52] DEBUG[5669]: rtp.c:727 process_rfc2833: - RTP 2833 Event: 00000004 (len = 4) ubuntupbx*CLI> [Jun 26 16:33:52] DEBUG[5669]: rtp.c:727 process_rfc2833: - RTP 2833 Event: 00000004 (len = 4) ubuntupbx*CLI> [Jun 26 16:33:54] DEBUG[5669]: app_voicemail.c:6360 vm_execmain: After vm_authenticate [Jun 26 16:33:54] DEBUG[5669]: app_voicemail.c:6396 vm_execmain: Before open_mailbox [Jun 26 16:33:54] DEBUG[5669]: app.c:1001 ast_lock_path: Locked path '/var/spool/asterisk/voicemail/atlantiatech/100/Old' [Jun 26 16:33:54] DEBUG[5669]: app.c:1022 ast_unlock_path: Unlocked path '/var/spool/asterisk/voicemail/atlantiatech/100/Old' [Jun 26 16:33:54] DEBUG[5669]: app.c:1001 ast_lock_path: Locked path '/var/spool/asterisk/voicemail/atlantiatech/100/Old' [Jun 26 16:33:54] DEBUG[5669]: app.c:1022 ast_unlock_path: Unlocked path '/var/spool/asterisk/voicemail/atlantiatech/100/Old' [Jun 26 16:33:54] DEBUG[5669]: app_voicemail.c:6402 vm_execmain: Number of old messages: 0 [Jun 26 16:33:54] DEBUG[5669]: app.c:1001 ast_lock_path: Locked path '/var/spool/asterisk/voicemail/atlantiatech/100/INBOX' [Jun 26 16:33:54] DEBUG[5669]: app.c:1022 ast_unlock_path: Unlocked path '/var/spool/asterisk/voicemail/atlantiatech/100/INBOX' [Jun 26 16:33:54] DEBUG[5669]: app.c:1001 ast_lock_path: Locked path '/var/spool/asterisk/voicemail/atlantiatech/100/INBOX' [Jun 26 16:33:54] DEBUG[5669]: app.c:1022 ast_unlock_path: Unlocked path '/var/spool/asterisk/voicemail/atlantiatech/100/INBOX' [Jun 26 16:33:54] DEBUG[5669]: app_voicemail.c:6409 vm_execmain: Number of new messages: 0 [Jun 26 16:33:54] DEBUG[5669]: channel.c:2976 set_format: Set channel SIP/100-081db608 to write format gsm [Jun 26 16:33:54] DEBUG[5669]: rtp.c:2589 ast_rtp_raw_write: Difference is 26752, ms is 3364 [Jun 26 16:33:54] DEBUG[5669]: channel.c:2061 ast_settimeout: Scheduling timer at 160 sample intervals -- Playing 'vm-youhave' (language 'en') ubuntupbx*CLI> [Jun 26 16:33:55] DEBUG[5669]: channel.c:2061 ast_settimeout: Scheduling timer at 0 sample intervals [Jun 26 16:33:55] DEBUG[5669]: channel.c:2061 ast_settimeout: Scheduling timer at 0 sample intervals [Jun 26 16:33:55] DEBUG[5669]: channel.c:2976 set_format: Set channel SIP/100-081db608 to write format ulaw [Jun 26 16:33:55] DEBUG[5669]: channel.c:2976 set_format: Set channel SIP/100-081db608 to write format gsm [Jun 26 16:33:55] DEBUG[5669]: channel.c:2061 ast_settimeout: Scheduling timer at 160 sample intervals -- Playing 'vm-no' (language 'en') ubuntupbx*CLI> [Jun 26 16:33:56] DEBUG[5669]: channel.c:2061 ast_settimeout: Scheduling timer at 0 sample intervals [Jun 26 16:33:56] DEBUG[5669]: channel.c:2061 ast_settimeout: Scheduling timer at 0 sample intervals [Jun 26 16:33:56] DEBUG[5669]: channel.c:2976 set_format: Set channel SIP/100-081db608 to write format ulaw [Jun 26 16:33:56] DEBUG[5669]: channel.c:2976 set_format: Set channel SIP/100-081db608 to write format gsm [Jun 26 16:33:56] DEBUG[5669]: channel.c:2061 ast_settimeout: Scheduling timer at 160 sample intervals -- Playing 'vm-messages' (language 'en') ubuntupbx*CLI> [Jun 26 16:33:56] DEBUG[5669]: rtp.c:875 ast_rtcp_read: Got RTCP report of 80 bytes Internal RTCP NTP clock skew detected: lsr=4138918081, now=4139032207, dlsr=131000 (1:998ms), diff=16874 ubuntupbx*CLI> [Jun 26 16:33:57] DEBUG[5669]: channel.c:2061 ast_settimeout: Scheduling timer at 0 sample intervals [Jun 26 16:33:57] DEBUG[5669]: channel.c:2061 ast_settimeout: Scheduling timer at 0 sample intervals [Jun 26 16:33:57] DEBUG[5669]: channel.c:2976 set_format: Set channel SIP/100-081db608 to write format ulaw [Jun 26 16:33:57] DEBUG[5669]: channel.c:2976 set_format: Set channel SIP/100-081db608 to write format gsm [Jun 26 16:33:57] DEBUG[5669]: channel.c:2061 ast_settimeout: Scheduling timer at 160 sample intervals -- Playing 'vm-opts' (language 'en') ubuntupbx*CLI> [Jun 26 16:34:04] DEBUG[5669]: channel.c:2061 ast_settimeout: Scheduling timer at 0 sample intervals [Jun 26 16:34:04] DEBUG[5669]: channel.c:2061 ast_settimeout: Scheduling timer at 0 sample intervals [Jun 26 16:34:04] DEBUG[5669]: channel.c:2976 set_format: Set channel SIP/100-081db608 to write format ulaw [Jun 26 16:34:04] DEBUG[5669]: channel.c:2976 set_format: Set channel SIP/100-081db608 to write format gsm ubuntupbx*CLI> [Jun 26 16:34:04] DEBUG[5669]: channel.c:2061 ast_settimeout: Scheduling timer at 160 sample intervals -- Playing 'vm-helpexit' (language 'en') ubuntupbx*CLI> [Jun 26 16:34:06] DEBUG[5669]: rtp.c:875 ast_rtcp_read: Got RTCP report of 80 bytes Internal RTCP NTP clock skew detected: lsr=4139573547, now=4139687688, dlsr=131000 (1:998ms), diff=16859 ubuntupbx*CLI> [Jun 26 16:34:07] DEBUG[5669]: channel.c:2061 ast_settimeout: Scheduling timer at 0 sample intervals [Jun 26 16:34:07] DEBUG[5669]: channel.c:2061 ast_settimeout: Scheduling timer at 0 sample intervals [Jun 26 16:34:07] DEBUG[5669]: channel.c:2976 set_format: Set channel SIP/100-081db608 to write format ulaw ubuntupbx*CLI> [Jun 26 16:34:13] DEBUG[5669]: channel.c:2976 set_format: Set channel SIP/100-081db608 to write format gsm [Jun 26 16:34:13] DEBUG[5669]: rtp.c:2589 ast_rtp_raw_write: Difference is 49776, ms is 6242 [Jun 26 16:34:13] DEBUG[5669]: channel.c:2061 ast_settimeout: Scheduling timer at 160 sample intervals -- Playing 'vm-opts' (language 'en') ubuntupbx*CLI> [Jun 26 16:34:16] DEBUG[5669]: rtp.c:875 ast_rtcp_read: Got RTCP report of 80 bytes Internal RTCP NTP clock skew detected: lsr=4140228752, now=4140342846, dlsr=131000 (1:998ms), diff=16906 ubuntupbx*CLI> [Jun 26 16:34:20] DEBUG[5669]: channel.c:2061 ast_settimeout: Scheduling timer at 0 sample intervals [Jun 26 16:34:20] DEBUG[5669]: channel.c:2061 ast_settimeout: Scheduling timer at 0 sample intervals [Jun 26 16:34:20] DEBUG[5669]: channel.c:2976 set_format: Set channel SIP/100-081db608 to write format ulaw [Jun 26 16:34:20] DEBUG[5669]: channel.c:2976 set_format: Set channel SIP/100-081db608 to write format gsm [Jun 26 16:34:20] DEBUG[5669]: channel.c:2061 ast_settimeout: Scheduling timer at 160 sample intervals -- Playing 'vm-helpexit' (language 'en') ubuntupbx*CLI> [Jun 26 16:34:23] DEBUG[5669]: channel.c:2061 ast_settimeout: Scheduling timer at 0 sample intervals [Jun 26 16:34:23] DEBUG[5669]: channel.c:2061 ast_settimeout: Scheduling timer at 0 sample intervals [Jun 26 16:34:23] DEBUG[5669]: channel.c:2976 set_format: Set channel SIP/100-081db608 to write format ulaw ubuntupbx*CLI> [Jun 26 16:34:26] DEBUG[5669]: rtp.c:875 ast_rtcp_read: Got RTCP report of 80 bytes Internal RTCP NTP clock skew detected: lsr=4140884219, now=4140998283, dlsr=131000 (1:998ms), diff=16936 ubuntupbx*CLI> [Jun 26 16:34:29] DEBUG[5669]: channel.c:2976 set_format: Set channel SIP/100-081db608 to write format gsm [Jun 26 16:34:29] DEBUG[5669]: rtp.c:2589 ast_rtp_raw_write: Difference is 49848, ms is 6251 [Jun 26 16:34:29] DEBUG[5669]: channel.c:2061 ast_settimeout: Scheduling timer at 160 sample intervals -- Playing 'vm-opts' (language 'en') ubuntupbx*CLI> [Jun 26 16:34:36] DEBUG[5669]: rtp.c:875 ast_rtcp_read: Got RTCP report of 80 bytes Internal RTCP NTP clock skew detected: lsr=4141539423, now=4141653667, dlsr=131000 (1:998ms), diff=16756 ubuntupbx*CLI> [Jun 26 16:34:36] DEBUG[5669]: channel.c:2061 ast_settimeout: Scheduling timer at 0 sample intervals [Jun 26 16:34:36] DEBUG[5669]: channel.c:2061 ast_settimeout: Scheduling timer at 0 sample intervals [Jun 26 16:34:36] DEBUG[5669]: channel.c:2976 set_format: Set channel SIP/100-081db608 to write format ulaw [Jun 26 16:34:36] DEBUG[5669]: channel.c:2976 set_format: Set channel SIP/100-081db608 to write format gsm [Jun 26 16:34:36] DEBUG[5669]: channel.c:2061 ast_settimeout: Scheduling timer at 160 sample intervals -- Playing 'vm-helpexit' (language 'en') ubuntupbx*CLI> [Jun 26 16:34:39] DEBUG[5669]: channel.c:2061 ast_settimeout: Scheduling timer at 0 sample intervals [Jun 26 16:34:39] DEBUG[5669]: channel.c:2061 ast_settimeout: Scheduling timer at 0 sample intervals [Jun 26 16:34:39] DEBUG[5669]: channel.c:2976 set_format: Set channel SIP/100-081db608 to write format ulaw ubuntupbx*CLI> [Jun 26 16:34:46] DEBUG[5669]: channel.c:2976 set_format: Set channel SIP/100-081db608 to write format gsm ubuntupbx*CLI> [Jun 26 16:34:46] DEBUG[5669]: rtp.c:2589 ast_rtp_raw_write: Difference is 49976, ms is 6267 [Jun 26 16:34:46] DEBUG[5669]: channel.c:2061 ast_settimeout: Scheduling timer at 160 sample intervals -- Playing 'vm-goodbye' (language 'en') ubuntupbx*CLI> [Jun 26 16:34:46] DEBUG[5669]: rtp.c:875 ast_rtcp_read: Got RTCP report of 80 bytes ubuntupbx*CLI> [Jun 26 16:34:47] DEBUG[5669]: channel.c:2061 ast_settimeout: Scheduling timer at 0 sample intervals [Jun 26 16:34:47] DEBUG[5669]: channel.c:2061 ast_settimeout: Scheduling timer at 0 sample intervals [Jun 26 16:34:47] DEBUG[5669]: channel.c:2976 set_format: Set channel SIP/100-081db608 to write format ulaw == Auto fallthrough, channel 'SIP/100-081db608' status is 'UNKNOWN' [Jun 26 16:34:47] DEBUG[5669]: pbx.c:1662 pbx_substitute_variables_helper_full: Function result is '"Sandra" <100>' [Jun 26 16:34:47] DEBUG[5669]: pbx.c:1662 pbx_substitute_variables_helper_full: Function result is '100' [Jun 26 16:34:47] DEBUG[5669]: pbx.c:1662 pbx_substitute_variables_helper_full: Function result is '200' [Jun 26 16:34:47] DEBUG[5669]: pbx.c:1662 pbx_substitute_variables_helper_full: Function result is 'sip' [Jun 26 16:34:47] DEBUG[5669]: pbx.c:1662 pbx_substitute_variables_helper_full: Function result is 'SIP/100-081db608' [Jun 26 16:34:47] DEBUG[5669]: pbx.c:1662 pbx_substitute_variables_helper_full: Function result is '' [Jun 26 16:34:47] DEBUG[5669]: pbx.c:1662 pbx_substitute_variables_helper_full: Function result is 'VoiceMailMain' [Jun 26 16:34:47] DEBUG[5669]: pbx.c:1662 pbx_substitute_variables_helper_full: Function result is '100@atlantiatech' [Jun 26 16:34:47] DEBUG[5669]: pbx.c:1662 pbx_substitute_variables_helper_full: Function result is '2007-06-26 16:33:49' [Jun 26 16:34:47] DEBUG[5669]: pbx.c:1662 pbx_substitute_variables_helper_full: Function result is '2007-06-26 16:33:49' ubuntupbx*CLI> [Jun 26 16:34:47] DEBUG[5669]: pbx.c:1662 pbx_substitute_variables_helper_full: Function result is '2007-06-26 16:34:47' [Jun 26 16:34:47] DEBUG[5669]: pbx.c:1662 pbx_substitute_variables_helper_full: Function result is '58' [Jun 26 16:34:47] DEBUG[5669]: pbx.c:1662 pbx_substitute_variables_helper_full: Function result is '58' [Jun 26 16:34:47] DEBUG[5669]: pbx.c:1662 pbx_substitute_variables_helper_full: Function result is 'ANSWERED' [Jun 26 16:34:47] DEBUG[5669]: pbx.c:1662 pbx_substitute_variables_helper_full: Function result is 'DOCUMENTATION' [Jun 26 16:34:47] DEBUG[5669]: pbx.c:1662 pbx_substitute_variables_helper_full: Function result is '' [Jun 26 16:34:47] DEBUG[5669]: pbx.c:1662 pbx_substitute_variables_helper_full: Function result is '1182890029.80' [Jun 26 16:34:47] DEBUG[5669]: pbx.c:1662 pbx_substitute_variables_helper_full: Function result is '' [Jun 26 16:34:47] DEBUG[5669]: channel.c:1757 ast_hangup: Hanging up channel 'SIP/100-081db608' [Jun 26 16:34:47] DEBUG[5669]: chan_sip.c:3364 sip_hangup: Hangup call SIP/100-081db608, SIP callid e6f53c04-a9e15a32-fff01997@192.168.100.126) Scheduling destruction of SIP dialog 'e6f53c04-a9e15a32-fff01997@192.168.100.126' in 32000 ms (Method: ACK) [Jun 26 16:34:47] DEBUG[5669]: chan_sip.c:5707 reqprep: Strict routing enforced for session e6f53c04-a9e15a32-fff01997@192.168.100.126 set_destination: Parsing for address/port to send to set_destination: set destination to 192.168.100.126, port 5060 Reliably Transmitting (no NAT) to 192.168.100.126:5060: BYE sip:100@192.168.100.126 SIP/2.0 Via: SIP/2.0/UDP 192.168.100.10:5060;branch=z9hG4bK09fa70d6;rport From: ;tag=as2e352b63 To: "100" ;tag=C09BD180-E64D3495 Call-ID: e6f53c04-a9e15a32-fff01997@192.168.100.126 CSeq: 102 BYE User-Agent: Asterisk PBX Max-Forwards: 70 Content-Length: 0 --- [Jun 26 16:34:47] DEBUG[5669]: chan_sip.c:2016 __sip_reliable_xmit: *** SIP TIMER: Initalizing retransmit timer on packet: Id #317 [Jun 26 16:34:47] DEBUG[5669]: devicestate.c:304 __ast_device_state_changed_literal: Notification of state change to be queued on device/channel SIP/100-081db608 [Jun 26 16:34:47] DEBUG[4157]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for SIP - 100 [Jun 26 16:34:47] DEBUG[4157]: chan_sip.c:15450 sip_devicestate: Checking device state for peer 100 [Jun 26 16:34:47] DEBUG[4157]: devicestate.c:287 do_state_change: Changing state for SIP/100 - state 1 (Not in use) [Jun 26 16:34:47] DEBUG[5672]: app_queue.c:546 changethread: Device 'SIP/100' changed to state '1' (Not in use) but we don't care because they're not a member of any queue. ubuntupbx*CLI> <--- SIP read from 192.168.100.126:5060 ---> SIP/2.0 200 OK Via: SIP/2.0/UDP 192.168.100.10:5060;branch=z9hG4bK09fa70d6;rport From: ;tag=as2e352b63 To: "100" ;tag=C09BD180-E64D3495 CSeq: 102 BYE Call-ID: e6f53c04-a9e15a32-fff01997@192.168.100.126 Contact: User-Agent: PolycomSoundPointIP-SPIP_501-UA/2.1.0.2708 Content-Length: 0 <-------------> [Jun 26 16:34:47] DEBUG[4254]: chan_sip.c:4634 parse_request: Header 0: SIP/2.0 200 OK (14) [Jun 26 16:34:47] DEBUG[4254]: chan_sip.c:4634 parse_request: Header 1: Via: SIP/2.0/UDP 192.168.100.10:5060;branch=z9hG4bK09fa70d6;rport (65) [Jun 26 16:34:47] DEBUG[4254]: chan_sip.c:4634 parse_request: Header 2: From: ;tag=as2e352b63 (56) [Jun 26 16:34:47] DEBUG[4254]: chan_sip.c:4634 parse_request: Header 3: To: "100" ;tag=C09BD180-E64D3495 (56) [Jun 26 16:34:47] DEBUG[4254]: chan_sip.c:4634 parse_request: Header 4: CSeq: 102 BYE (13) [Jun 26 16:34:47] DEBUG[4254]: chan_sip.c:4634 parse_request: Header 5: Call-ID: e6f53c04-a9e15a32-fff01997@192.168.100.126 (51) [Jun 26 16:34:47] DEBUG[4254]: chan_sip.c:4634 parse_request: Header 6: Contact: (34) [Jun 26 16:34:47] DEBUG[4254]: chan_sip.c:4634 parse_request: Header 7: User-Agent: PolycomSoundPointIP-SPIP_501-UA/2.1.0.2708 (54) [Jun 26 16:34:47] DEBUG[4254]: chan_sip.c:4634 parse_request: Header 8: Content-Length: 0 (17) [Jun 26 16:34:47] DEBUG[4254]: chan_sip.c:4634 parse_request: Header 9: (0) --- (9 headers 0 lines) --- [Jun 26 16:34:47] DEBUG[4254]: chan_sip.c:4422 find_call: = Found Their Call ID: e6f53c04-a9e15a32-fff01997@192.168.100.126 Their Tag C09BD180-E64D3495 Our tag: as2e352b63 [Jun 26 16:34:47] DEBUG[4254]: chan_sip.c:2127 __sip_ack: ** SIP TIMER: Cancelling retransmit of packet (reply received) Retransid #317 [Jun 26 16:34:47] DEBUG[4254]: chan_sip.c:2137 __sip_ack: Stopping retransmission on 'e6f53c04-a9e15a32-fff01997@192.168.100.126' of Request 102: Match Not Found SIP Response message for INCOMING dialog BYE arrived ubuntupbx*CLI> Really destroying SIP dialog 'e6f53c04-a9e15a32-fff01997@192.168.100.126' Method: ACK ubuntupbx*CLI>