[Jan 10 19:27:42] -- Executing [s@macro-dial:10] Dial("IAX2/704-1", "SIP/705||tr") in new stack [Jan 10 19:27:42] DEBUG[27665]: chan_sip.c:15162 sip_request_call: Asked to create a SIP channel with formats: 0x2 (gsm) [Jan 10 19:27:42] DEBUG[27665]: chan_sip.c:4256 sip_alloc: Allocating new SIP dialog for (No Call-ID) - INVITE (With RTP) [Jan 10 19:27:42] DEBUG[27665]: chan_sip.c:2551 do_setnat: Setting NAT on RTP to Off [Jan 10 19:27:42] DEBUG[27665]: chan_sip.c:3758 sip_new: *** Our native formats are 0x4 (ulaw) [Jan 10 19:27:42] DEBUG[27665]: chan_sip.c:3759 sip_new: *** Joint capabilities are 0x0 (nothing) [Jan 10 19:27:42] DEBUG[27665]: chan_sip.c:3760 sip_new: *** Our capabilities are 0xc (ulaw|alaw) [Jan 10 19:27:42] DEBUG[27665]: chan_sip.c:3761 sip_new: *** AST_CODEC_CHOOSE formats are 0x4 (ulaw) [Jan 10 19:27:42] DEBUG[27665]: chan_sip.c:3763 sip_new: *** Our preferred formats from the incoming channel are 0x2 (gsm) [Jan 10 19:27:42] DEBUG[27665]: chan_sip.c:3784 sip_new: This channel will not be able to handle video. [Jan 10 19:27:42] DEBUG[27665]: rtp.c:1539 ast_rtp_make_compatible: Channel 'IAX2/704-1' has no RTP, not doing anything [Jan 10 19:27:42] DEBUG[27665]: channel.c:3185 ast_channel_inherit_variables: Not copying variable STACK-macro-dial-s-10. [Jan 10 19:27:42] DEBUG[27665]: channel.c:3185 ast_channel_inherit_variables: Not copying variable MACRO_DEPTH. [Jan 10 19:27:42] DEBUG[27665]: channel.c:3185 ast_channel_inherit_variables: Not copying variable AGISTATUS. [Jan 10 19:27:42] DEBUG[27665]: channel.c:3185 ast_channel_inherit_variables: Not copying variable ds. [Jan 10 19:27:42] DEBUG[27665]: channel.c:3185 ast_channel_inherit_variables: Not copying variable STACK-macro-dial-s-2. [Jan 10 19:27:42] DEBUG[27665]: channel.c:3185 ast_channel_inherit_variables: Not copying variable DYNAMIC_FEATURES. [Jan 10 19:27:42] DEBUG[27665]: channel.c:3185 ast_channel_inherit_variables: Not copying variable STACK-macro-dial-s-1. [Jan 10 19:27:42] DEBUG[27665]: channel.c:3185 ast_channel_inherit_variables: Not copying variable ARG3. [Jan 10 19:27:42] DEBUG[27665]: channel.c:3185 ast_channel_inherit_variables: Not copying variable ARG2. [Jan 10 19:27:42] DEBUG[27665]: channel.c:3185 ast_channel_inherit_variables: Not copying variable ARG1. [Jan 10 19:27:42] DEBUG[27665]: channel.c:3185 ast_channel_inherit_variables: Not copying variable MACRO_PRIORITY. [Jan 10 19:27:42] DEBUG[27665]: channel.c:3185 ast_channel_inherit_variables: Not copying variable MACRO_CONTEXT. [Jan 10 19:27:42] DEBUG[27665]: channel.c:3185 ast_channel_inherit_variables: Not copying variable MACRO_EXTEN. [Jan 10 19:27:42] DEBUG[27665]: channel.c:3185 ast_channel_inherit_variables: Not copying variable STACK-macro-exten-vm-s-9. [Jan 10 19:27:42] DEBUG[27665]: channel.c:3185 ast_channel_inherit_variables: Not copying variable STACK-macro-exten-vm-s-8. [Jan 10 19:27:42] DEBUG[27665]: channel.c:3185 ast_channel_inherit_variables: Not copying variable STACK-macro-record-enable-s-5. [Jan 10 19:27:42] DEBUG[27665]: channel.c:3185 ast_channel_inherit_variables: Not copying variable STACK-macro-record-enable-s-4. [Jan 10 19:27:42] DEBUG[27665]: channel.c:3185 ast_channel_inherit_variables: Not copying variable STACK-macro-record-enable-s-1. [Jan 10 19:27:42] DEBUG[27665]: channel.c:3185 ast_channel_inherit_variables: Not copying variable STACK-macro-exten-vm-s-7. [Jan 10 19:27:42] DEBUG[27665]: channel.c:3185 ast_channel_inherit_variables: Not copying variable RT. [Jan 10 19:27:42] DEBUG[27665]: channel.c:3185 ast_channel_inherit_variables: Not copying variable STACK-macro-exten-vm-s-6. [Jan 10 19:27:42] DEBUG[27665]: channel.c:3185 ast_channel_inherit_variables: Not copying variable CFUEXT. [Jan 10 19:27:42] DEBUG[27665]: channel.c:3185 ast_channel_inherit_variables: Not copying variable STACK-macro-exten-vm-s-5. [Jan 10 19:27:42] DEBUG[27665]: channel.c:3185 ast_channel_inherit_variables: Not copying variable EXTTOCALL. [Jan 10 19:27:42] DEBUG[27665]: channel.c:3185 ast_channel_inherit_variables: Not copying variable STACK-macro-exten-vm-s-4. [Jan 10 19:27:42] DEBUG[27665]: channel.c:3185 ast_channel_inherit_variables: Not copying variable VMBOX. [Jan 10 19:27:42] DEBUG[27665]: channel.c:3185 ast_channel_inherit_variables: Not copying variable STACK-macro-exten-vm-s-3. [Jan 10 19:27:42] DEBUG[27665]: channel.c:3185 ast_channel_inherit_variables: Not copying variable FROMCONTEXT. [Jan 10 19:27:42] DEBUG[27665]: channel.c:3185 ast_channel_inherit_variables: Not copying variable STACK-macro-exten-vm-s-2. [Jan 10 19:27:42] DEBUG[27665]: channel.c:3185 ast_channel_inherit_variables: Not copying variable STACK-macro-user-callerid-s-9. [Jan 10 19:27:42] DEBUG[27665]: channel.c:3185 ast_channel_inherit_variables: Not copying variable STACK-macro-user-callerid-s-8. [Jan 10 19:27:42] DEBUG[27665]: channel.c:3185 ast_channel_inherit_variables: Not copying variable STACK-macro-user-callerid-s-7. [Jan 10 19:27:42] DEBUG[27665]: channel.c:3185 ast_channel_inherit_variables: Not copying variable AMPUSERCIDNAME. [Jan 10 19:27:42] DEBUG[27665]: channel.c:3185 ast_channel_inherit_variables: Not copying variable STACK-macro-user-callerid-s-6. [Jan 10 19:27:42] DEBUG[27665]: channel.c:3185 ast_channel_inherit_variables: Not copying variable DB_RESULT. [Jan 10 19:27:42] DEBUG[27665]: channel.c:3185 ast_channel_inherit_variables: Not copying variable AMPUSER. [Jan 10 19:27:42] DEBUG[27665]: channel.c:3185 ast_channel_inherit_variables: Not copying variable STACK-macro-user-callerid-s-5. [Jan 10 19:27:42] DEBUG[27665]: channel.c:3185 ast_channel_inherit_variables: Not copying variable STACK-macro-user-callerid-s-4. [Jan 10 19:27:42] DEBUG[27665]: channel.c:3185 ast_channel_inherit_variables: Not copying variable REALCALLERIDNUM. [Jan 10 19:27:42] DEBUG[27665]: channel.c:3185 ast_channel_inherit_variables: Not copying variable STACK-macro-user-callerid-s-3. [Jan 10 19:27:42] DEBUG[27665]: channel.c:3185 ast_channel_inherit_variables: Not copying variable STACK-macro-user-callerid-s-2. [Jan 10 19:27:42] DEBUG[27665]: channel.c:3185 ast_channel_inherit_variables: Not copying variable STACK-macro-user-callerid-s-1. [Jan 10 19:27:42] DEBUG[27665]: channel.c:3185 ast_channel_inherit_variables: Not copying variable STACK-macro-exten-vm-s-1. [Jan 10 19:27:42] DEBUG[27665]: channel.c:3185 ast_channel_inherit_variables: Not copying variable STACK-from-internal-705-1. [Jan 10 19:27:42] DEBUG[27665]: chan_sip.c:2804 sip_call: Outgoing Call for 705 [Jan 10 19:27:42] DEBUG[27665]: chan_sip.c:2970 update_call_counter: Updating call counter for outgoing call [Jan 10 19:27:42] DEBUG[27665]: chan_sip.c:2818 sip_call: Our T38 capability (0), joint T38 capability (0) [Jan 10 19:27:42] DEBUG[27665]: chan_sip.c:6121 add_sdp: ** Our capability: 0xc (ulaw|alaw) Video flag: False [Jan 10 19:27:42] DEBUG[27665]: chan_sip.c:6122 add_sdp: ** Our prefcodec: 0x2 (gsm) [Jan 10 19:27:42] Audio is at 192.168.1.114 port 15812 [Jan 10 19:27:42] Adding codec 0x4 (ulaw) to SDP [Jan 10 19:27:42] Adding codec 0x8 (alaw) to SDP [Jan 10 19:27:42] Adding non-codec 0x1 (telephone-event) to SDP [Jan 10 19:27:42] DEBUG[27665]: chan_sip.c:6253 add_sdp: -- Done with adding codecs to SDP [Jan 10 19:27:42] DEBUG[27665]: chan_sip.c:6298 add_sdp: Done building SDP. Settling with this capability: 0xc (ulaw|alaw) [Jan 10 19:27:42] DEBUG[27665]: chan_sip.c:4519 parse_request: Header 0: INVITE sip:705@192.168.1.115:5060 SIP/2.0 (41) [Jan 10 19:27:42] DEBUG[27665]: chan_sip.c:4519 parse_request: Header 1: Via: SIP/2.0/UDP 192.168.1.114:5060;branch=z9hG4bK6be0e3b4 (58) [Jan 10 19:27:42] DEBUG[27665]: chan_sip.c:4519 parse_request: Header 2: From: "IAX softphone" ;tag=as5425b937 (60) [Jan 10 19:27:42] DEBUG[27665]: chan_sip.c:4519 parse_request: Header 3: To: (32) [Jan 10 19:27:42] DEBUG[27665]: chan_sip.c:4519 parse_request: Header 4: Contact: (32) [Jan 10 19:27:42] DEBUG[27665]: chan_sip.c:4519 parse_request: Header 5: Call-ID: 1743acc97a735b134ba9f04e40cf16b2@192.168.1.114 (55) [Jan 10 19:27:42] DEBUG[27665]: chan_sip.c:4519 parse_request: Header 6: CSeq: 102 INVITE (16) [Jan 10 19:27:42] DEBUG[27665]: chan_sip.c:4519 parse_request: Header 7: User-Agent: Asterisk PBX (24) [Jan 10 19:27:42] DEBUG[27665]: chan_sip.c:4519 parse_request: Header 8: Max-Forwards: 70 (16) [Jan 10 19:27:42] DEBUG[27665]: chan_sip.c:4519 parse_request: Header 9: Date: Thu, 11 Jan 2007 02:27:42 GMT (35) [Jan 10 19:27:42] DEBUG[27665]: chan_sip.c:4519 parse_request: Header 10: Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY (66) [Jan 10 19:27:42] DEBUG[27665]: chan_sip.c:4519 parse_request: Header 11: Supported: replaces (19) [Jan 10 19:27:42] DEBUG[27665]: chan_sip.c:4519 parse_request: Header 12: Content-Type: application/sdp (29) [Jan 10 19:27:42] DEBUG[27665]: chan_sip.c:4519 parse_request: Header 13: Content-Length: 266 (19) [Jan 10 19:27:42] DEBUG[27665]: chan_sip.c:4519 parse_request: Header 14: (0) [Jan 10 19:27:42] DEBUG[27665]: chan_sip.c:4551 parse_request: Line: v=0 (3) [Jan 10 19:27:42] DEBUG[27665]: chan_sip.c:4551 parse_request: Line: o=root 27547 27547 IN IP4 192.168.1.114 (39) [Jan 10 19:27:42] DEBUG[27665]: chan_sip.c:4551 parse_request: Line: s=session (9) [Jan 10 19:27:42] DEBUG[27665]: chan_sip.c:4551 parse_request: Line: c=IN IP4 192.168.1.114 (22) [Jan 10 19:27:42] DEBUG[27665]: chan_sip.c:4551 parse_request: Line: t=0 0 (5) [Jan 10 19:27:42] DEBUG[27665]: chan_sip.c:4551 parse_request: Line: m=audio 15812 RTP/AVP 0 8 101 (29) [Jan 10 19:27:42] DEBUG[27665]: chan_sip.c:4551 parse_request: Line: a=rtpmap:0 PCMU/8000 (20) [Jan 10 19:27:42] DEBUG[27665]: chan_sip.c:4551 parse_request: Line: a=rtpmap:8 PCMA/8000 (20) [Jan 10 19:27:42] DEBUG[27665]: chan_sip.c:4551 parse_request: Line: a=rtpmap:101 telephone-event/8000 (33) [Jan 10 19:27:42] DEBUG[27665]: chan_sip.c:4551 parse_request: Line: a=fmtp:101 0-16 (15) [Jan 10 19:27:42] DEBUG[27665]: chan_sip.c:4551 parse_request: Line: a=silenceSupp:off - - - - (25) [Jan 10 19:27:42] DEBUG[27665]: chan_sip.c:4551 parse_request: Line: a=ptime:20 (10) [Jan 10 19:27:42] DEBUG[27665]: chan_sip.c:4551 parse_request: Line: a=sendrecv (10) [Jan 10 19:27:42] Reliably Transmitting (no NAT) to 192.168.1.115:5060: INVITE sip:705@192.168.1.115:5060 SIP/2.0 Via: SIP/2.0/UDP 192.168.1.114:5060;branch=z9hG4bK6be0e3b4 From: "IAX softphone" ;tag=as5425b937 To: Contact: Call-ID: 1743acc97a735b134ba9f04e40cf16b2@192.168.1.114 CSeq: 102 INVITE User-Agent: Asterisk PBX Max-Forwards: 70 Date: Thu, 11 Jan 2007 02:27:42 GMT Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY Supported: replaces Content-Type: application/sdp Content-Length: 266 v=0 o=root 27547 27547 IN IP4 192.168.1.114 s=session c=IN IP4 192.168.1.114 t=0 0 m=audio 15812 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=silenceSupp:off - - - - a=ptime:20 a=sendrecv --- [Jan 10 19:27:42] DEBUG[27665]: chan_sip.c:1951 __sip_reliable_xmit: *** SIP TIMER: Initalizing retransmit timer on packet: Id #54 [Jan 10 19:27:42] -- Called 705 [Jan 10 19:27:42] DEBUG[27559]: chan_iax2.c:6635 socket_process: Ooh, voice format changed to 2 [Jan 10 19:27:42] DEBUG[27559]: channel.c:2731 set_format: Set channel IAX2/704-1 to read format gsm [Jan 10 19:27:42] <--- SIP read from 192.168.1.115:5060 ---> SIP/2.0 100 Trying To: From: "IAX softphone" ;tag=as5425b937 Call-ID: 1743acc97a735b134ba9f04e40cf16b2@192.168.1.114 CSeq: 102 INVITE Via: SIP/2.0/UDP 192.168.1.114:5060;branch=z9hG4bK6be0e3b4 Server: Linksys/SPA941-4.1.15 Content-Length: 0 <-------------> [Jan 10 19:27:42] DEBUG[27568]: chan_sip.c:4519 parse_request: Header 0: SIP/2.0 100 Trying (18) [Jan 10 19:27:42] DEBUG[27568]: chan_sip.c:4519 parse_request: Header 1: To: (32) [Jan 10 19:27:42] DEBUG[27568]: chan_sip.c:4519 parse_request: Header 2: From: "IAX softphone" ;tag=as5425b937 (60) [Jan 10 19:27:42] DEBUG[27568]: chan_sip.c:4519 parse_request: Header 3: Call-ID: 1743acc97a735b134ba9f04e40cf16b2@192.168.1.114 (55) [Jan 10 19:27:42] DEBUG[27568]: chan_sip.c:4519 parse_request: Header 4: CSeq: 102 INVITE (16) [Jan 10 19:27:42] DEBUG[27568]: chan_sip.c:4519 parse_request: Header 5: Via: SIP/2.0/UDP 192.168.1.114:5060;branch=z9hG4bK6be0e3b4 (58) [Jan 10 19:27:42] DEBUG[27568]: chan_sip.c:4519 parse_request: Header 6: Server: Linksys/SPA941-4.1.15 (29) [Jan 10 19:27:42] DEBUG[27568]: chan_sip.c:4519 parse_request: Header 7: Content-Length: 0 (17) [Jan 10 19:27:42] DEBUG[27568]: chan_sip.c:4519 parse_request: Header 8: (0) [Jan 10 19:27:42] --- (8 headers 0 lines) --- [Jan 10 19:27:42] DEBUG[27568]: chan_sip.c:2098 __sip_semi_ack: *** SIP TIMER: Cancelling retransmission #54 - INVITE (got response) [Jan 10 19:27:42] DEBUG[27568]: chan_sip.c:2107 __sip_semi_ack: (Provisional) Stopping retransmission (but retaining packet) on '1743acc97a735b134ba9f04e40cf16b2@192.168.1.114' Request 102: Found [Jan 10 19:27:42] DEBUG[27568]: chan_sip.c:11539 handle_response_invite: SIP response 100 to standard invite [Jan 10 19:27:42] <--- SIP read from 192.168.1.115:5060 ---> SIP/2.0 180 Ringing To: ;tag=9ee8c7545a2fad6bi0 From: "IAX softphone" ;tag=as5425b937 Call-ID: 1743acc97a735b134ba9f04e40cf16b2@192.168.1.114 CSeq: 102 INVITE Via: SIP/2.0/UDP 192.168.1.114:5060;branch=z9hG4bK6be0e3b4 Server: Linksys/SPA941-4.1.15 Content-Length: 0 <-------------> [Jan 10 19:27:42] DEBUG[27568]: chan_sip.c:4519 parse_request: Header 0: SIP/2.0 180 Ringing (19) [Jan 10 19:27:42] DEBUG[27568]: chan_sip.c:4519 parse_request: Header 1: To: ;tag=9ee8c7545a2fad6bi0 (55) [Jan 10 19:27:42] DEBUG[27568]: chan_sip.c:4519 parse_request: Header 2: From: "IAX softphone" ;tag=as5425b937 (60) [Jan 10 19:27:42] DEBUG[27568]: chan_sip.c:4519 parse_request: Header 3: Call-ID: 1743acc97a735b134ba9f04e40cf16b2@192.168.1.114 (55) [Jan 10 19:27:42] DEBUG[27568]: chan_sip.c:4519 parse_request: Header 4: CSeq: 102 INVITE (16) [Jan 10 19:27:42] DEBUG[27568]: chan_sip.c:4519 parse_request: Header 5: Via: SIP/2.0/UDP 192.168.1.114:5060;branch=z9hG4bK6be0e3b4 (58) [Jan 10 19:27:42] DEBUG[27568]: chan_sip.c:4519 parse_request: Header 6: Server: Linksys/SPA941-4.1.15 (29) [Jan 10 19:27:42] DEBUG[27568]: chan_sip.c:4519 parse_request: Header 7: Content-Length: 0 (17) [Jan 10 19:27:42] DEBUG[27568]: chan_sip.c:4519 parse_request: Header 8: (0) [Jan 10 19:27:42] --- (8 headers 0 lines) --- [Jan 10 19:27:42] DEBUG[27568]: chan_sip.c:2107 __sip_semi_ack: (Provisional) Stopping retransmission (but retaining packet) on '1743acc97a735b134ba9f04e40cf16b2@192.168.1.114' Request 102: Found [Jan 10 19:27:42] DEBUG[27568]: chan_sip.c:11539 handle_response_invite: SIP response 180 to standard invite [Jan 10 19:27:42] DEBUG[27568]: devicestate.c:303 __ast_device_state_changed_literal: Notification of state change to be queued on device/channel SIP/705-081ea8f8 [Jan 10 19:27:42] DEBUG[27552]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for SIP - 705 [Jan 10 19:27:42] DEBUG[27552]: chan_sip.c:15104 sip_devicestate: Checking device state for peer 705 [Jan 10 19:27:42] DEBUG[27552]: devicestate.c:287 do_state_change: Changing state for SIP/705 - state 1 (Not in use) [Jan 10 19:27:42] DEBUG[27552]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for SIP - 705 [Jan 10 19:27:42] DEBUG[27552]: chan_sip.c:15104 sip_devicestate: Checking device state for peer 705 [Jan 10 19:27:42] DEBUG[27669]: app_queue.c:546 changethread: Device 'SIP/705' changed to state '1' (Not in use) but we don't care because they're not a member of any queue. [Jan 10 19:27:42] -- SIP/705-081ea8f8 is ringing [Jan 10 19:27:44] <--- SIP read from 192.168.1.115:5060 ---> SIP/2.0 200 OK To: ;tag=9ee8c7545a2fad6bi0 From: "IAX softphone" ;tag=as5425b937 Call-ID: 1743acc97a735b134ba9f04e40cf16b2@192.168.1.114 CSeq: 102 INVITE Via: SIP/2.0/UDP 192.168.1.114:5060;branch=z9hG4bK6be0e3b4 Contact: "705" Server: Linksys/SPA941-4.1.15 Content-Length: 212 Allow: ACK, BYE, CANCEL, INFO, INVITE, NOTIFY, OPTIONS, REFER Content-Type: application/sdp v=0 o=- 17218096 17218096 IN IP4 192.168.1.115 s=- c=IN IP4 192.168.1.115 t=0 0 m=audio 16416 RTP/AVP 0 101 a=rtpmap:0 PCMU/8000 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-15 a=ptime:30 a=sendrecv <-------------> [Jan 10 19:27:44] DEBUG[27568]: chan_sip.c:4519 parse_request: Header 0: SIP/2.0 200 OK (14) [Jan 10 19:27:44] DEBUG[27568]: chan_sip.c:4519 parse_request: Header 1: To: ;tag=9ee8c7545a2fad6bi0 (55) [Jan 10 19:27:44] DEBUG[27568]: chan_sip.c:4519 parse_request: Header 2: From: "IAX softphone" ;tag=as5425b937 (60) [Jan 10 19:27:44] DEBUG[27568]: chan_sip.c:4519 parse_request: Header 3: Call-ID: 1743acc97a735b134ba9f04e40cf16b2@192.168.1.114 (55) [Jan 10 19:27:44] DEBUG[27568]: chan_sip.c:4519 parse_request: Header 4: CSeq: 102 INVITE (16) [Jan 10 19:27:44] DEBUG[27568]: chan_sip.c:4519 parse_request: Header 5: Via: SIP/2.0/UDP 192.168.1.114:5060;branch=z9hG4bK6be0e3b4 (58) [Jan 10 19:27:44] DEBUG[27568]: chan_sip.c:4519 parse_request: Header 6: Contact: "705" (43) [Jan 10 19:27:44] DEBUG[27568]: chan_sip.c:4519 parse_request: Header 7: Server: Linksys/SPA941-4.1.15 (29) [Jan 10 19:27:44] DEBUG[27568]: chan_sip.c:4519 parse_request: Header 8: Content-Length: 212 (19) [Jan 10 19:27:44] DEBUG[27568]: chan_sip.c:4519 parse_request: Header 9: Allow: ACK, BYE, CANCEL, INFO, INVITE, NOTIFY, OPTIONS, REFER (61) [Jan 10 19:27:44] DEBUG[27568]: chan_sip.c:4519 parse_request: Header 10: Content-Type: application/sdp (29) [Jan 10 19:27:44] DEBUG[27568]: chan_sip.c:4519 parse_request: Header 11: (0) [Jan 10 19:27:44] DEBUG[27568]: chan_sip.c:4551 parse_request: Line: v=0 (3) [Jan 10 19:27:44] DEBUG[27568]: chan_sip.c:4551 parse_request: Line: o=- 17218096 17218096 IN IP4 192.168.1.115 (42) [Jan 10 19:27:44] DEBUG[27568]: chan_sip.c:4551 parse_request: Line: s=- (3) [Jan 10 19:27:44] DEBUG[27568]: chan_sip.c:4551 parse_request: Line: c=IN IP4 192.168.1.115 (22) [Jan 10 19:27:44] DEBUG[27568]: chan_sip.c:4551 parse_request: Line: t=0 0 (5) [Jan 10 19:27:44] DEBUG[27568]: chan_sip.c:4551 parse_request: Line: m=audio 16416 RTP/AVP 0 101 (27) [Jan 10 19:27:44] DEBUG[27568]: chan_sip.c:4551 parse_request: Line: a=rtpmap:0 PCMU/8000 (20) [Jan 10 19:27:44] DEBUG[27568]: chan_sip.c:4551 parse_request: Line: a=rtpmap:101 telephone-event/8000 (33) [Jan 10 19:27:44] DEBUG[27568]: chan_sip.c:4551 parse_request: Line: a=fmtp:101 0-15 (15) [Jan 10 19:27:44] DEBUG[27568]: chan_sip.c:4551 parse_request: Line: a=ptime:30 (10) [Jan 10 19:27:44] DEBUG[27568]: chan_sip.c:4551 parse_request: Line: a=sendrecv (10) [Jan 10 19:27:44] --- (11 headers 11 lines) --- [Jan 10 19:27:44] DEBUG[27568]: chan_sip.c:2047 __sip_ack: Acked pending invite 102 [Jan 10 19:27:44] DEBUG[27568]: chan_sip.c:2065 __sip_ack: Stopping retransmission on '1743acc97a735b134ba9f04e40cf16b2@192.168.1.114' of Request 102: Match Not Found [Jan 10 19:27:44] DEBUG[27568]: chan_sip.c:11539 handle_response_invite: SIP response 200 to standard invite [Jan 10 19:27:44] Found RTP audio format 0 [Jan 10 19:27:44] Found RTP audio format 101 [Jan 10 19:27:44] Peer audio RTP is at port 192.168.1.115:16416 [Jan 10 19:27:44] Found description format PCMU for ID 0 [Jan 10 19:27:44] Found description format telephone-event for ID 101 [Jan 10 19:27:44] Got unsupported a:fmtp in SDP offer [Jan 10 19:27:44] DEBUG[27568]: chan_sip.c:5062 process_sdp: T38 state changed to 0 on channel SIP/705-081ea8f8 [Jan 10 19:27:44] Capabilities: us - 0xc (ulaw|alaw), peer - audio=0x4 (ulaw)/video=0x0 (nothing), combined - 0x4 (ulaw) [Jan 10 19:27:44] Non-codec capabilities (dtmf): us - 0x1 (telephone-event), peer - 0x1 (telephone-event), combined - 0x1 (telephone-event) [Jan 10 19:27:44] Peer audio RTP is at port 192.168.1.115:16416 [Jan 10 19:27:44] DEBUG[27568]: chan_sip.c:5139 process_sdp: We're settling with these formats: 0x4 (ulaw) [Jan 10 19:27:44] DEBUG[27568]: chan_sip.c:5146 process_sdp: We have an owner, now see if we need to change this call [Jan 10 19:27:44] DEBUG[27568]: chan_sip.c:2970 update_call_counter: Updating call counter for outgoing call [Jan 10 19:27:44] DEBUG[27568]: chan_sip.c:7894 build_route: build_route: Contact hop: "705" [Jan 10 19:27:44] list_route: hop: [Jan 10 19:27:44] DEBUG[27568]: chan_sip.c:5576 reqprep: Strict routing enforced for session 1743acc97a735b134ba9f04e40cf16b2@192.168.1.114 [Jan 10 19:27:44] set_destination: Parsing for address/port to send to [Jan 10 19:27:44] set_destination: set destination to 192.168.1.115, port 5060 [Jan 10 19:27:44] Transmitting (no NAT) to 192.168.1.115:5060: ACK sip:705@192.168.1.115:5060 SIP/2.0 Via: SIP/2.0/UDP 192.168.1.114:5060;branch=z9hG4bK0083d08f From: "IAX softphone" ;tag=as5425b937 To: ;tag=9ee8c7545a2fad6bi0 Contact: Call-ID: 1743acc97a735b134ba9f04e40cf16b2@192.168.1.114 CSeq: 102 ACK User-Agent: Asterisk PBX Max-Forwards: 70 Content-Length: 0 --- [Jan 10 19:27:44] DEBUG[27665]: devicestate.c:303 __ast_device_state_changed_literal: Notification of state change to be queued on device/channel SIP/705-081ea8f8 [Jan 10 19:27:44] -- SIP/705-081ea8f8 answered IAX2/704-1 [Jan 10 19:27:44] DEBUG[27665]: rtp.c:1460 ast_rtp_early_bridge: Channel 'IAX2/704-1' has no RTP, not doing anything [Jan 10 19:27:44] DEBUG[27665]: channel.c:2731 set_format: Set channel IAX2/704-1 to read format slin [Jan 10 19:27:44] DEBUG[27665]: channel.c:2731 set_format: Set channel SIP/705-081ea8f8 to write format slin [Jan 10 19:27:44] DEBUG[27665]: channel.c:2731 set_format: Set channel SIP/705-081ea8f8 to read format slin [Jan 10 19:27:44] DEBUG[27665]: channel.c:2731 set_format: Set channel IAX2/704-1 to write format slin [Jan 10 19:27:44] DEBUG[27665]: chan_iax2.c:3179 iax2_answer: Answering IAX2 call [Jan 10 19:27:44] DEBUG[27665]: devicestate.c:303 __ast_device_state_changed_literal: Notification of state change to be queued on device/channel IAX2/704-1 [Jan 10 19:27:44] DEBUG[27552]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for SIP - 705 [Jan 10 19:27:44] DEBUG[27552]: chan_sip.c:15104 sip_devicestate: Checking device state for peer 705 [Jan 10 19:27:44] DEBUG[27552]: devicestate.c:287 do_state_change: Changing state for SIP/705 - state 1 (Not in use) [Jan 10 19:27:44] DEBUG[27552]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for SIP - 705 [Jan 10 19:27:44] DEBUG[27552]: chan_sip.c:15104 sip_devicestate: Checking device state for peer 705 [Jan 10 19:27:44] DEBUG[27552]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for IAX2 - 704 [Jan 10 19:27:44] DEBUG[27552]: chan_iax2.c:9611 iax2_devicestate: Checking device state for device 704 [Jan 10 19:27:44] DEBUG[27552]: chan_iax2.c:9619 iax2_devicestate: iax2_devicestate: Found peer. What's device state of 704? addr=1845602496, defaddr=0 maxms=0, lastms=0 [Jan 10 19:27:44] DEBUG[27552]: devicestate.c:287 do_state_change: Changing state for IAX2/704 - state 2 (In use) [Jan 10 19:27:44] DEBUG[27552]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for IAX2 - 704 [Jan 10 19:27:44] DEBUG[27552]: chan_iax2.c:9611 iax2_devicestate: Checking device state for device 704 [Jan 10 19:27:44] DEBUG[27552]: chan_iax2.c:9619 iax2_devicestate: iax2_devicestate: Found peer. What's device state of 704? addr=1845602496, defaddr=0 maxms=0, lastms=0 [Jan 10 19:27:44] DEBUG[27670]: app_queue.c:546 changethread: Device 'SIP/705' changed to state '1' (Not in use) but we don't care because they're not a member of any queue. [Jan 10 19:27:44] DEBUG[27671]: app_queue.c:546 changethread: Device 'IAX2/704' changed to state '2' (In use) but we don't care because they're not a member of any queue. [Jan 10 19:27:44] DEBUG[27665]: rtp.c:2662 ast_rtp_write: Ooh, format changed from unknown to ulaw [Jan 10 19:27:44] DEBUG[27665]: rtp.c:2679 ast_rtp_write: Created smoother: format: 4 ms: 20 len: 160 [Jan 10 19:27:46] <--- SIP read from 192.168.1.115:5060 ---> INVITE sip:704@192.168.1.114 SIP/2.0 Via: SIP/2.0/UDP 192.168.1.115:5060;branch=z9hG4bK-de3cbdbd From: ;tag=9ee8c7545a2fad6bi0 To: "IAX softphone" ;tag=as5425b937 Call-ID: 1743acc97a735b134ba9f04e40cf16b2@192.168.1.114 CSeq: 101 INVITE Max-Forwards: 70 Contact: "705" Expires: 30 User-Agent: Linksys/SPA941-4.1.15 Content-Length: 230 Content-Type: application/sdp v=0 o=- 17218522 17218522 IN IP4 192.168.1.115 s=- c=IN IP4 0.0.0.0 t=0 0 m=audio 16416 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-15 a=ptime:30 a=sendonly <-------------> [Jan 10 19:27:46] DEBUG[27568]: chan_sip.c:4519 parse_request: Header 0: INVITE sip:704@192.168.1.114 SIP/2.0 (36) [Jan 10 19:27:46] DEBUG[27568]: chan_sip.c:4519 parse_request: Header 1: Via: SIP/2.0/UDP 192.168.1.115:5060;branch=z9hG4bK-de3cbdbd (59) [Jan 10 19:27:46] DEBUG[27568]: chan_sip.c:4519 parse_request: Header 2: From: ;tag=9ee8c7545a2fad6bi0 (57) [Jan 10 19:27:46] DEBUG[27568]: chan_sip.c:4519 parse_request: Header 3: To: "IAX softphone" ;tag=as5425b937 (58) [Jan 10 19:27:46] DEBUG[27568]: chan_sip.c:4519 parse_request: Header 4: Call-ID: 1743acc97a735b134ba9f04e40cf16b2@192.168.1.114 (55) [Jan 10 19:27:46] DEBUG[27568]: chan_sip.c:4519 parse_request: Header 5: CSeq: 101 INVITE (16) [Jan 10 19:27:46] DEBUG[27568]: chan_sip.c:4519 parse_request: Header 6: Max-Forwards: 70 (16) [Jan 10 19:27:46] DEBUG[27568]: chan_sip.c:4519 parse_request: Header 7: Contact: "705" (43) [Jan 10 19:27:46] DEBUG[27568]: chan_sip.c:4519 parse_request: Header 8: Expires: 30 (11) [Jan 10 19:27:46] DEBUG[27568]: chan_sip.c:4519 parse_request: Header 9: User-Agent: Linksys/SPA941-4.1.15 (33) [Jan 10 19:27:46] DEBUG[27568]: chan_sip.c:4519 parse_request: Header 10: Content-Length: 230 (19) [Jan 10 19:27:46] DEBUG[27568]: chan_sip.c:4519 parse_request: Header 11: Content-Type: application/sdp (29) [Jan 10 19:27:46] DEBUG[27568]: chan_sip.c:4519 parse_request: Header 12: (0) [Jan 10 19:27:46] DEBUG[27568]: chan_sip.c:4551 parse_request: Line: v=0 (3) [Jan 10 19:27:46] DEBUG[27568]: chan_sip.c:4551 parse_request: Line: o=- 17218522 17218522 IN IP4 192.168.1.115 (42) [Jan 10 19:27:46] DEBUG[27568]: chan_sip.c:4551 parse_request: Line: s=- (3) [Jan 10 19:27:46] DEBUG[27568]: chan_sip.c:4551 parse_request: Line: c=IN IP4 0.0.0.0 (16) [Jan 10 19:27:46] DEBUG[27568]: chan_sip.c:4551 parse_request: Line: t=0 0 (5) [Jan 10 19:27:46] DEBUG[27568]: chan_sip.c:4551 parse_request: Line: m=audio 16416 RTP/AVP 0 8 101 (29) [Jan 10 19:27:46] DEBUG[27568]: chan_sip.c:4551 parse_request: Line: a=rtpmap:0 PCMU/8000 (20) [Jan 10 19:27:46] DEBUG[27568]: chan_sip.c:4551 parse_request: Line: a=rtpmap:8 PCMA/8000 (20) [Jan 10 19:27:46] DEBUG[27568]: chan_sip.c:4551 parse_request: Line: a=rtpmap:101 telephone-event/8000 (33) [Jan 10 19:27:46] DEBUG[27568]: chan_sip.c:4551 parse_request: Line: a=fmtp:101 0-15 (15) [Jan 10 19:27:46] DEBUG[27568]: chan_sip.c:4551 parse_request: Line: a=ptime:30 (10) [Jan 10 19:27:46] DEBUG[27568]: chan_sip.c:4551 parse_request: Line: a=sendonly (10) [Jan 10 19:27:46] --- (12 headers 12 lines) --- [Jan 10 19:27:46] DEBUG[27568]: chan_sip.c:14509 handle_request: **** Received INVITE (5) - Command in SIP INVITE [Jan 10 19:27:46] Sending to 192.168.1.115 : 5060 (no NAT) [Jan 10 19:27:46] Found RTP audio format 0 [Jan 10 19:27:46] Found RTP audio format 8 [Jan 10 19:27:46] Found RTP audio format 101 [Jan 10 19:27:46] Peer audio RTP is at port 0.0.0.0:16416 [Jan 10 19:27:46] Found description format PCMU for ID 0 [Jan 10 19:27:46] Found description format PCMA for ID 8 [Jan 10 19:27:46] Found description format telephone-event for ID 101 [Jan 10 19:27:46] Got unsupported a:fmtp in SDP offer [Jan 10 19:27:46] DEBUG[27568]: chan_sip.c:5062 process_sdp: T38 state changed to 0 on channel SIP/705-081ea8f8 [Jan 10 19:27:46] Capabilities: us - 0xc (ulaw|alaw), peer - audio=0xc (ulaw|alaw)/video=0x0 (nothing), combined - 0xc (ulaw|alaw) [Jan 10 19:27:46] Non-codec capabilities (dtmf): us - 0x1 (telephone-event), peer - 0x1 (telephone-event), combined - 0x1 (telephone-event) [Jan 10 19:27:46] Peer audio RTP is at port 0.0.0.0:16416 [Jan 10 19:27:46] DEBUG[27568]: chan_sip.c:5139 process_sdp: We're settling with these formats: 0xc (ulaw|alaw) [Jan 10 19:27:46] DEBUG[27568]: chan_sip.c:5146 process_sdp: We have an owner, now see if we need to change this call [Jan 10 19:27:46] DEBUG[27568]: chan_sip.c:13343 handle_request_invite: Got a SIP re-invite for call 1743acc97a735b134ba9f04e40cf16b2@192.168.1.114 [Jan 10 19:27:46] DEBUG[27568]: chan_sip.c:13438 handle_request_invite: SIP/705-081ea8f8: This call is UP.... [Jan 10 19:27:46] DEBUG[27568]: chan_sip.c:6353 transmit_response_with_sdp: Setting framing from config on incoming call [Jan 10 19:27:46] DEBUG[27568]: chan_sip.c:6121 add_sdp: ** Our capability: 0xc (ulaw|alaw) Video flag: True [Jan 10 19:27:46] DEBUG[27568]: chan_sip.c:6122 add_sdp: ** Our prefcodec: 0x2 (gsm) [Jan 10 19:27:46] Audio is at 192.168.1.114 port 15812 [Jan 10 19:27:46] Adding codec 0x4 (ulaw) to SDP [Jan 10 19:27:46] Adding codec 0x8 (alaw) to SDP [Jan 10 19:27:46] Adding non-codec 0x1 (telephone-event) to SDP [Jan 10 19:27:46] DEBUG[27568]: chan_sip.c:6253 add_sdp: -- Done with adding codecs to SDP [Jan 10 19:27:46] DEBUG[27568]: chan_sip.c:6298 add_sdp: Done building SDP. Settling with this capability: 0xc (ulaw|alaw) [Jan 10 19:27:46] <--- Reliably Transmitting (no NAT) to 192.168.1.115:5060 ---> SIP/2.0 200 OK Via: SIP/2.0/UDP 192.168.1.115:5060;branch=z9hG4bK-de3cbdbd;received=192.168.1.115 From: ;tag=9ee8c7545a2fad6bi0 To: "IAX softphone" ;tag=as5425b937 Call-ID: 1743acc97a735b134ba9f04e40cf16b2@192.168.1.114 CSeq: 101 INVITE User-Agent: Asterisk PBX Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY Supported: replaces Contact: Content-Type: application/sdp Content-Length: 266 v=0 o=root 27547 27548 IN IP4 192.168.1.114 s=session c=IN IP4 192.168.1.114 t=0 0 m=audio 15812 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=silenceSupp:off - - - - a=ptime:20 a=recvonly <------------> [Jan 10 19:27:46] DEBUG[27568]: chan_sip.c:1951 __sip_reliable_xmit: *** SIP TIMER: Initalizing retransmit timer on packet: Id #57 [Jan 10 19:27:46] -- Started music on hold, class 'default', on IAX2/704-1 [Jan 10 19:27:46] <--- SIP read from 192.168.1.115:5060 ---> ACK sip:704@192.168.1.114 SIP/2.0 Via: SIP/2.0/UDP 192.168.1.115:5060;branch=z9hG4bK-505d83c2 From: ;tag=9ee8c7545a2fad6bi0 To: "IAX softphone" ;tag=as5425b937 Call-ID: 1743acc97a735b134ba9f04e40cf16b2@192.168.1.114 CSeq: 101 ACK Max-Forwards: 70 Contact: "705" User-Agent: Linksys/SPA941-4.1.15 Content-Length: 0 <-------------> [Jan 10 19:27:46] DEBUG[27568]: chan_sip.c:4519 parse_request: Header 0: ACK sip:704@192.168.1.114 SIP/2.0 (33) [Jan 10 19:27:46] DEBUG[27568]: chan_sip.c:4519 parse_request: Header 1: Via: SIP/2.0/UDP 192.168.1.115:5060;branch=z9hG4bK-505d83c2 (59) [Jan 10 19:27:46] DEBUG[27568]: chan_sip.c:4519 parse_request: Header 2: From: ;tag=9ee8c7545a2fad6bi0 (57) [Jan 10 19:27:46] DEBUG[27568]: chan_sip.c:4519 parse_request: Header 3: To: "IAX softphone" ;tag=as5425b937 (58) [Jan 10 19:27:46] DEBUG[27568]: chan_sip.c:4519 parse_request: Header 4: Call-ID: 1743acc97a735b134ba9f04e40cf16b2@192.168.1.114 (55) [Jan 10 19:27:46] DEBUG[27568]: chan_sip.c:4519 parse_request: Header 5: CSeq: 101 ACK (13) [Jan 10 19:27:46] DEBUG[27568]: chan_sip.c:4519 parse_request: Header 6: Max-Forwards: 70 (16) [Jan 10 19:27:46] DEBUG[27568]: chan_sip.c:4519 parse_request: Header 7: Contact: "705" (43) [Jan 10 19:27:46] DEBUG[27568]: chan_sip.c:4519 parse_request: Header 8: User-Agent: Linksys/SPA941-4.1.15 (33) [Jan 10 19:27:46] DEBUG[27568]: chan_sip.c:4519 parse_request: Header 9: Content-Length: 0 (17) [Jan 10 19:27:46] DEBUG[27568]: chan_sip.c:4519 parse_request: Header 10: (0) [Jan 10 19:27:46] --- (10 headers 0 lines) --- [Jan 10 19:27:46] DEBUG[27568]: chan_sip.c:14509 handle_request: **** Received ACK (6) - Command in SIP ACK [Jan 10 19:27:46] DEBUG[27568]: chan_sip.c:2055 __sip_ack: ** SIP TIMER: Cancelling retransmit of packet (reply received) Retransid #57 [Jan 10 19:27:46] DEBUG[27568]: chan_sip.c:2065 __sip_ack: Stopping retransmission on '1743acc97a735b134ba9f04e40cf16b2@192.168.1.114' of Response 101: Match Not Found [Jan 10 19:27:46] WARNING[27665]: file.c:553 ast_openstream_full: File /var/lib/asterisk/mohmp3/Amurvel does not exist in any format [Jan 10 19:27:46] WARNING[27665]: res_musiconhold.c:243 ast_moh_files_next: Unable to open file '/var/lib/asterisk/mohmp3/Amurvel': No such file or directory [Jan 10 19:27:46] DEBUG[27665]: channel.c:2234 __ast_read: Auto-deactivating generator [Jan 10 19:27:46] -- Stopped music on hold on IAX2/704-1 [Jan 10 19:27:49] <--- SIP read from 192.168.1.115:5060 ---> INVITE sip:70@192.168.1.114 SIP/2.0 Via: SIP/2.0/UDP 192.168.1.115:5060;branch=z9hG4bK-72958607 From: "705" ;tag=4ed98004c62ecf56o0 To: Call-ID: d734381c-f6e9b61e@192.168.1.115 CSeq: 101 INVITE Max-Forwards: 70 Contact: "705" Expires: 240 User-Agent: Linksys/SPA941-4.1.15 Content-Length: 401 Allow: ACK, BYE, CANCEL, INFO, INVITE, NOTIFY, OPTIONS, REFER Content-Type: application/sdp v=0 o=- 17218827 17218827 IN IP4 192.168.1.115 s=- c=IN IP4 192.168.1.115 t=0 0 m=audio 16418 RTP/AVP 0 2 4 8 18 96 97 98 101 a=rtpmap:0 PCMU/8000 a=rtpmap:2 G726-32/8000 a=rtpmap:4 G723/8000 a=rtpmap:8 PCMA/8000 a=rtpmap:18 G729a/8000 a=rtpmap:96 G726-40/8000 a=rtpmap:97 G726-24/8000 a=rtpmap:98 G726-16/8000 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-15 a=ptime:30 a=sendrecv <-------------> [Jan 10 19:27:49] DEBUG[27568]: chan_sip.c:4519 parse_request: Header 0: INVITE sip:70@192.168.1.114 SIP/2.0 (35) [Jan 10 19:27:49] DEBUG[27568]: chan_sip.c:4519 parse_request: Header 1: Via: SIP/2.0/UDP 192.168.1.115:5060;branch=z9hG4bK-72958607 (59) [Jan 10 19:27:49] DEBUG[27568]: chan_sip.c:4519 parse_request: Header 2: From: "705" ;tag=4ed98004c62ecf56o0 (58) [Jan 10 19:27:49] DEBUG[27568]: chan_sip.c:4519 parse_request: Header 3: To: (26) [Jan 10 19:27:49] DEBUG[27568]: chan_sip.c:4519 parse_request: Header 4: Call-ID: d734381c-f6e9b61e@192.168.1.115 (40) [Jan 10 19:27:49] DEBUG[27568]: chan_sip.c:4519 parse_request: Header 5: CSeq: 101 INVITE (16) [Jan 10 19:27:49] DEBUG[27568]: chan_sip.c:4519 parse_request: Header 6: Max-Forwards: 70 (16) [Jan 10 19:27:49] DEBUG[27568]: chan_sip.c:4519 parse_request: Header 7: Contact: "705" (43) [Jan 10 19:27:49] DEBUG[27568]: chan_sip.c:4519 parse_request: Header 8: Expires: 240 (12) [Jan 10 19:27:49] DEBUG[27568]: chan_sip.c:4519 parse_request: Header 9: User-Agent: Linksys/SPA941-4.1.15 (33) [Jan 10 19:27:49] DEBUG[27568]: chan_sip.c:4519 parse_request: Header 10: Content-Length: 401 (19) [Jan 10 19:27:49] DEBUG[27568]: chan_sip.c:4519 parse_request: Header 11: Allow: ACK, BYE, CANCEL, INFO, INVITE, NOTIFY, OPTIONS, REFER (61) [Jan 10 19:27:49] DEBUG[27568]: chan_sip.c:4519 parse_request: Header 12: Content-Type: application/sdp (29) [Jan 10 19:27:49] DEBUG[27568]: chan_sip.c:4519 parse_request: Header 13: (0) [Jan 10 19:27:49] DEBUG[27568]: chan_sip.c:4551 parse_request: Line: v=0 (3) [Jan 10 19:27:49] DEBUG[27568]: chan_sip.c:4551 parse_request: Line: o=- 17218827 17218827 IN IP4 192.168.1.115 (42) [Jan 10 19:27:49] DEBUG[27568]: chan_sip.c:4551 parse_request: Line: s=- (3) [Jan 10 19:27:49] DEBUG[27568]: chan_sip.c:4551 parse_request: Line: c=IN IP4 192.168.1.115 (22) [Jan 10 19:27:49] DEBUG[27568]: chan_sip.c:4551 parse_request: Line: t=0 0 (5) [Jan 10 19:27:49] DEBUG[27568]: chan_sip.c:4551 parse_request: Line: m=audio 16418 RTP/AVP 0 2 4 8 18 96 97 98 101 (45) [Jan 10 19:27:49] DEBUG[27568]: chan_sip.c:4551 parse_request: Line: a=rtpmap:0 PCMU/8000 (20) [Jan 10 19:27:49] DEBUG[27568]: chan_sip.c:4551 parse_request: Line: a=rtpmap:2 G726-32/8000 (23) [Jan 10 19:27:49] DEBUG[27568]: chan_sip.c:4551 parse_request: Line: a=rtpmap:4 G723/8000 (20) [Jan 10 19:27:49] DEBUG[27568]: chan_sip.c:4551 parse_request: Line: a=rtpmap:8 PCMA/8000 (20) [Jan 10 19:27:49] DEBUG[27568]: chan_sip.c:4551 parse_request: Line: a=rtpmap:18 G729a/8000 (22) [Jan 10 19:27:49] DEBUG[27568]: chan_sip.c:4551 parse_request: Line: a=rtpmap:96 G726-40/8000 (24) [Jan 10 19:27:49] DEBUG[27568]: chan_sip.c:4551 parse_request: Line: a=rtpmap:97 G726-24/8000 (24) [Jan 10 19:27:49] DEBUG[27568]: chan_sip.c:4551 parse_request: Line: a=rtpmap:98 G726-16/8000 (24) [Jan 10 19:27:49] DEBUG[27568]: chan_sip.c:4551 parse_request: Line: a=rtpmap:101 telephone-event/8000 (33) [Jan 10 19:27:49] DEBUG[27568]: chan_sip.c:4551 parse_request: Line: a=fmtp:101 0-15 (15) [Jan 10 19:27:49] DEBUG[27568]: chan_sip.c:4551 parse_request: Line: a=ptime:30 (10) [Jan 10 19:27:49] DEBUG[27568]: chan_sip.c:4551 parse_request: Line: a=sendrecv (10) [Jan 10 19:27:49] --- (13 headers 18 lines) --- [Jan 10 19:27:49] DEBUG[27568]: chan_sip.c:2551 do_setnat: Setting NAT on RTP to Off [Jan 10 19:27:49] DEBUG[27568]: chan_sip.c:4256 sip_alloc: Allocating new SIP dialog for d734381c-f6e9b61e@192.168.1.115 - INVITE (With RTP) [Jan 10 19:27:49] DEBUG[27568]: chan_sip.c:14509 handle_request: **** Received INVITE (5) - Command in SIP INVITE [Jan 10 19:27:49] Sending to 192.168.1.115 : 5060 (no NAT) [Jan 10 19:27:49] Using INVITE request as basis request - d734381c-f6e9b61e@192.168.1.115 [Jan 10 19:27:49] DEBUG[27568]: chan_sip.c:2551 do_setnat: Setting NAT on RTP to Off [Jan 10 19:27:49] <--- Reliably Transmitting (no NAT) to 192.168.1.115:5060 ---> SIP/2.0 407 Proxy Authentication Required Via: SIP/2.0/UDP 192.168.1.115:5060;branch=z9hG4bK-72958607;received=192.168.1.115 From: "705" ;tag=4ed98004c62ecf56o0 To: ;tag=as32796f39 Call-ID: d734381c-f6e9b61e@192.168.1.115 CSeq: 101 INVITE User-Agent: Asterisk PBX Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY Supported: replaces Proxy-Authenticate: Digest algorithm=MD5, realm="asterisk", nonce="45085383" Content-Length: 0 <------------> [Jan 10 19:27:49] DEBUG[27568]: chan_sip.c:1951 __sip_reliable_xmit: *** SIP TIMER: Initalizing retransmit timer on packet: Id #58 [Jan 10 19:27:49] Scheduling destruction of SIP dialog 'd734381c-f6e9b61e@192.168.1.115' in 32000 ms (Method: INVITE) [Jan 10 19:27:49] Found user '705' [Jan 10 19:27:49] <--- SIP read from 192.168.1.115:5060 ---> ACK sip:70@192.168.1.114 SIP/2.0 Via: SIP/2.0/UDP 192.168.1.115:5060;branch=z9hG4bK-72958607 From: "705" ;tag=4ed98004c62ecf56o0 To: ;tag=as32796f39 Call-ID: d734381c-f6e9b61e@192.168.1.115 CSeq: 101 ACK Max-Forwards: 70 Contact: "705" User-Agent: Linksys/SPA941-4.1.15 Content-Length: 0 <-------------> [Jan 10 19:27:49] DEBUG[27568]: chan_sip.c:4519 parse_request: Header 0: ACK sip:70@192.168.1.114 SIP/2.0 (32) [Jan 10 19:27:49] DEBUG[27568]: chan_sip.c:4519 parse_request: Header 1: Via: SIP/2.0/UDP 192.168.1.115:5060;branch=z9hG4bK-72958607 (59) [Jan 10 19:27:49] DEBUG[27568]: chan_sip.c:4519 parse_request: Header 2: From: "705" ;tag=4ed98004c62ecf56o0 (58) [Jan 10 19:27:49] DEBUG[27568]: chan_sip.c:4519 parse_request: Header 3: To: ;tag=as32796f39 (41) [Jan 10 19:27:49] DEBUG[27568]: chan_sip.c:4519 parse_request: Header 4: Call-ID: d734381c-f6e9b61e@192.168.1.115 (40) [Jan 10 19:27:49] DEBUG[27568]: chan_sip.c:4519 parse_request: Header 5: CSeq: 101 ACK (13) [Jan 10 19:27:49] DEBUG[27568]: chan_sip.c:4519 parse_request: Header 6: Max-Forwards: 70 (16) [Jan 10 19:27:49] DEBUG[27568]: chan_sip.c:4519 parse_request: Header 7: Contact: "705" (43) [Jan 10 19:27:49] DEBUG[27568]: chan_sip.c:4519 parse_request: Header 8: User-Agent: Linksys/SPA941-4.1.15 (33) [Jan 10 19:27:49] DEBUG[27568]: chan_sip.c:4519 parse_request: Header 9: Content-Length: 0 (17) [Jan 10 19:27:49] DEBUG[27568]: chan_sip.c:4519 parse_request: Header 10: (0) [Jan 10 19:27:49] --- (10 headers 0 lines) --- [Jan 10 19:27:49] DEBUG[27568]: chan_sip.c:14509 handle_request: **** Received ACK (6) - Command in SIP ACK [Jan 10 19:27:49] DEBUG[27568]: chan_sip.c:2055 __sip_ack: ** SIP TIMER: Cancelling retransmit of packet (reply received) Retransid #58 [Jan 10 19:27:49] DEBUG[27568]: chan_sip.c:2065 __sip_ack: Stopping retransmission on 'd734381c-f6e9b61e@192.168.1.115' of Response 101: Match Not Found [Jan 10 19:27:49] <--- SIP read from 192.168.1.115:5060 ---> INVITE sip:70@192.168.1.114 SIP/2.0 Via: SIP/2.0/UDP 192.168.1.115:5060;branch=z9hG4bK-41b2e803 From: "705" ;tag=4ed98004c62ecf56o0 To: Call-ID: d734381c-f6e9b61e@192.168.1.115 CSeq: 102 INVITE Max-Forwards: 70 Proxy-Authorization: Digest username="705",realm="asterisk",nonce="45085383",uri="sip:70@192.168.1.114",algorithm=MD5,response="f8749c7ad5706a1e32b2fd1341a7a7e8" Contact: "705" Expires: 240 User-Agent: Linksys/SPA941-4.1.15 Content-Length: 401 Allow: ACK, BYE, CANCEL, INFO, INVITE, NOTIFY, OPTIONS, REFER Content-Type: application/sdp v=0 o=- 17218827 17218827 IN IP4 192.168.1.115 s=- c=IN IP4 192.168.1.115 t=0 0 m=audio 16418 RTP/AVP 0 2 4 8 18 96 97 98 101 a=rtpmap:0 PCMU/8000 a=rtpmap:2 G726-32/8000 a=rtpmap:4 G723/8000 a=rtpmap:8 PCMA/8000 a=rtpmap:18 G729a/8000 a=rtpmap:96 G726-40/8000 a=rtpmap:97 G726-24/8000 a=rtpmap:98 G726-16/8000 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-15 a=ptime:30 a=sendrecv <-------------> [Jan 10 19:27:49] DEBUG[27568]: chan_sip.c:4519 parse_request: Header 0: INVITE sip:70@192.168.1.114 SIP/2.0 (35) [Jan 10 19:27:49] DEBUG[27568]: chan_sip.c:4519 parse_request: Header 1: Via: SIP/2.0/UDP 192.168.1.115:5060;branch=z9hG4bK-41b2e803 (59) [Jan 10 19:27:49] DEBUG[27568]: chan_sip.c:4519 parse_request: Header 2: From: "705" ;tag=4ed98004c62ecf56o0 (58) [Jan 10 19:27:49] DEBUG[27568]: chan_sip.c:4519 parse_request: Header 3: To: (26) [Jan 10 19:27:49] DEBUG[27568]: chan_sip.c:4519 parse_request: Header 4: Call-ID: d734381c-f6e9b61e@192.168.1.115 (40) [Jan 10 19:27:49] DEBUG[27568]: chan_sip.c:4519 parse_request: Header 5: CSeq: 102 INVITE (16) [Jan 10 19:27:49] DEBUG[27568]: chan_sip.c:4519 parse_request: Header 6: Max-Forwards: 70 (16) [Jan 10 19:27:49] DEBUG[27568]: chan_sip.c:4519 parse_request: Header 7: Proxy-Authorization: Digest username="705",realm="asterisk",nonce="45085383",uri="sip:70@192.168.1.114",algorithm=MD5,response="f8749c7ad5706a1e32b2fd1341a7a7e8" (161) [Jan 10 19:27:49] DEBUG[27568]: chan_sip.c:4519 parse_request: Header 8: Contact: "705" (43) [Jan 10 19:27:49] DEBUG[27568]: chan_sip.c:4519 parse_request: Header 9: Expires: 240 (12) [Jan 10 19:27:49] DEBUG[27568]: chan_sip.c:4519 parse_request: Header 10: User-Agent: Linksys/SPA941-4.1.15 (33) [Jan 10 19:27:49] DEBUG[27568]: chan_sip.c:4519 parse_request: Header 11: Content-Length: 401 (19) [Jan 10 19:27:49] DEBUG[27568]: chan_sip.c:4519 parse_request: Header 12: Allow: ACK, BYE, CANCEL, INFO, INVITE, NOTIFY, OPTIONS, REFER (61) [Jan 10 19:27:49] DEBUG[27568]: chan_sip.c:4519 parse_request: Header 13: Content-Type: application/sdp (29) [Jan 10 19:27:49] DEBUG[27568]: chan_sip.c:4519 parse_request: Header 14: (0) [Jan 10 19:27:49] DEBUG[27568]: chan_sip.c:4551 parse_request: Line: v=0 (3) [Jan 10 19:27:49] DEBUG[27568]: chan_sip.c:4551 parse_request: Line: o=- 17218827 17218827 IN IP4 192.168.1.115 (42) [Jan 10 19:27:49] DEBUG[27568]: chan_sip.c:4551 parse_request: Line: s=- (3) [Jan 10 19:27:49] DEBUG[27568]: chan_sip.c:4551 parse_request: Line: c=IN IP4 192.168.1.115 (22) [Jan 10 19:27:49] DEBUG[27568]: chan_sip.c:4551 parse_request: Line: t=0 0 (5) [Jan 10 19:27:49] DEBUG[27568]: chan_sip.c:4551 parse_request: Line: m=audio 16418 RTP/AVP 0 2 4 8 18 96 97 98 101 (45) [Jan 10 19:27:49] DEBUG[27568]: chan_sip.c:4551 parse_request: Line: a=rtpmap:0 PCMU/8000 (20) [Jan 10 19:27:49] DEBUG[27568]: chan_sip.c:4551 parse_request: Line: a=rtpmap:2 G726-32/8000 (23) [Jan 10 19:27:49] DEBUG[27568]: chan_sip.c:4551 parse_request: Line: a=rtpmap:4 G723/8000 (20) [Jan 10 19:27:49] DEBUG[27568]: chan_sip.c:4551 parse_request: Line: a=rtpmap:8 PCMA/8000 (20) [Jan 10 19:27:49] DEBUG[27568]: chan_sip.c:4551 parse_request: Line: a=rtpmap:18 G729a/8000 (22) [Jan 10 19:27:49] DEBUG[27568]: chan_sip.c:4551 parse_request: Line: a=rtpmap:96 G726-40/8000 (24) [Jan 10 19:27:49] DEBUG[27568]: chan_sip.c:4551 parse_request: Line: a=rtpmap:97 G726-24/8000 (24) [Jan 10 19:27:49] DEBUG[27568]: chan_sip.c:4551 parse_request: Line: a=rtpmap:98 G726-16/8000 (24) [Jan 10 19:27:49] DEBUG[27568]: chan_sip.c:4551 parse_request: Line: a=rtpmap:101 telephone-event/8000 (33) [Jan 10 19:27:49] DEBUG[27568]: chan_sip.c:4551 parse_request: Line: a=fmtp:101 0-15 (15) [Jan 10 19:27:49] DEBUG[27568]: chan_sip.c:4551 parse_request: Line: a=ptime:30 (10) [Jan 10 19:27:49] DEBUG[27568]: chan_sip.c:4551 parse_request: Line: a=sendrecv (10) [Jan 10 19:27:49] --- (14 headers 18 lines) --- [Jan 10 19:27:49] DEBUG[27568]: chan_sip.c:14509 handle_request: **** Received INVITE (5) - Command in SIP INVITE [Jan 10 19:27:49] Sending to 192.168.1.115 : 5060 (no NAT) [Jan 10 19:27:49] Using INVITE request as basis request - d734381c-f6e9b61e@192.168.1.115 [Jan 10 19:27:49] DEBUG[27568]: chan_sip.c:2551 do_setnat: Setting NAT on RTP to Off [Jan 10 19:27:49] Found user '705' [Jan 10 19:27:49] Found RTP audio format 0 [Jan 10 19:27:49] Found RTP audio format 2 [Jan 10 19:27:49] Found RTP audio format 4 [Jan 10 19:27:49] Found RTP audio format 8 [Jan 10 19:27:49] Found RTP audio format 18 [Jan 10 19:27:49] Found RTP audio format 96 [Jan 10 19:27:49] Found RTP audio format 97 [Jan 10 19:27:49] Found RTP audio format 98 [Jan 10 19:27:49] Found RTP audio format 101 [Jan 10 19:27:49] Peer audio RTP is at port 192.168.1.115:16418 [Jan 10 19:27:49] Found description format PCMU for ID 0 [Jan 10 19:27:49] Found description format G726-32 for ID 2 [Jan 10 19:27:49] Found description format G723 for ID 4 [Jan 10 19:27:49] Found description format PCMA for ID 8 [Jan 10 19:27:49] Found description format G729a for ID 18 [Jan 10 19:27:49] Found description format G726-40 for ID 96 [Jan 10 19:27:49] Found description format G726-24 for ID 97 [Jan 10 19:27:49] Found description format G726-16 for ID 98 [Jan 10 19:27:49] Found description format telephone-event for ID 101 [Jan 10 19:27:49] Got unsupported a:fmtp in SDP offer [Jan 10 19:27:49] DEBUG[27568]: chan_sip.c:5062 process_sdp: T38 state changed to 0 on channel [Jan 10 19:27:49] Capabilities: us - 0xc (ulaw|alaw), peer - audio=0xd0d (g723|ulaw|alaw|g726|g729|ilbc)/video=0x0 (nothing), combined - 0xc (ulaw|alaw) [Jan 10 19:27:49] Non-codec capabilities (dtmf): us - 0x1 (telephone-event), peer - 0x1 (telephone-event), combined - 0x1 (telephone-event) [Jan 10 19:27:49] Peer audio RTP is at port 192.168.1.115:16418 [Jan 10 19:27:49] DEBUG[27568]: chan_sip.c:5139 process_sdp: We're settling with these formats: 0xc (ulaw|alaw) [Jan 10 19:27:49] DEBUG[27568]: chan_sip.c:13290 handle_request_invite: Checking SIP call limits for device 705 [Jan 10 19:27:49] DEBUG[27568]: chan_sip.c:2970 update_call_counter: Updating call counter for incoming call [Jan 10 19:27:49] Looking for 70 in from-internal (domain 192.168.1.114) [Jan 10 19:27:49] DEBUG[27568]: chan_sip.c:3758 sip_new: *** Our native formats are 0x4 (ulaw) [Jan 10 19:27:49] DEBUG[27568]: chan_sip.c:3759 sip_new: *** Joint capabilities are 0xc (ulaw|alaw) [Jan 10 19:27:49] DEBUG[27568]: chan_sip.c:3760 sip_new: *** Our capabilities are 0xc (ulaw|alaw) [Jan 10 19:27:49] DEBUG[27568]: chan_sip.c:3761 sip_new: *** AST_CODEC_CHOOSE formats are 0x4 (ulaw) [Jan 10 19:27:49] DEBUG[27568]: chan_sip.c:3784 sip_new: This channel will not be able to handle video. [Jan 10 19:27:49] DEBUG[27568]: chan_sip.c:7894 build_route: build_route: Contact hop: "705" [Jan 10 19:27:49] list_route: hop: [Jan 10 19:27:49] DEBUG[27568]: chan_sip.c:13365 handle_request_invite: SIP/705-08203868: New call is still down.... Trying... [Jan 10 19:27:49] <--- Transmitting (no NAT) to 192.168.1.115:5060 ---> SIP/2.0 100 Trying Via: SIP/2.0/UDP 192.168.1.115:5060;branch=z9hG4bK-41b2e803;received=192.168.1.115 From: "705" ;tag=4ed98004c62ecf56o0 To: Call-ID: d734381c-f6e9b61e@192.168.1.115 CSeq: 102 INVITE User-Agent: Asterisk PBX Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY Supported: replaces Contact: Content-Length: 0 <------------> [Jan 10 19:27:49] DEBUG[27568]: devicestate.c:303 __ast_device_state_changed_literal: Notification of state change to be queued on device/channel SIP/705-08203868 [Jan 10 19:27:49] DEBUG[27552]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for SIP - 705 [Jan 10 19:27:49] DEBUG[27552]: chan_sip.c:15104 sip_devicestate: Checking device state for peer 705 [Jan 10 19:27:49] DEBUG[27552]: devicestate.c:287 do_state_change: Changing state for SIP/705 - state 1 (Not in use) [Jan 10 19:27:49] DEBUG[27552]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for SIP - 705 [Jan 10 19:27:49] DEBUG[27552]: chan_sip.c:15104 sip_devicestate: Checking device state for peer 705 [Jan 10 19:27:49] DEBUG[27673]: app_queue.c:546 changethread: Device 'SIP/705' changed to state '1' (Not in use) but we don't care because they're not a member of any queue. [Jan 10 19:27:49] DEBUG[27672]: pbx.c:1767 pbx_extension_helper: Launching 'Park' [Jan 10 19:27:49] -- Executing [70@from-internal:1] Park("SIP/705-08203868", "") in new stack [Jan 10 19:27:49] DEBUG[27672]: devicestate.c:303 __ast_device_state_changed_literal: Notification of state change to be queued on device/channel SIP/705-08203868 [Jan 10 19:27:49] DEBUG[27552]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for SIP - 705 [Jan 10 19:27:49] DEBUG[27552]: chan_sip.c:15104 sip_devicestate: Checking device state for peer 705 [Jan 10 19:27:49] DEBUG[27552]: devicestate.c:287 do_state_change: Changing state for SIP/705 - state 1 (Not in use) [Jan 10 19:27:49] DEBUG[27552]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for SIP - 705 [Jan 10 19:27:49] DEBUG[27552]: chan_sip.c:15104 sip_devicestate: Checking device state for peer 705 [Jan 10 19:27:49] DEBUG[27674]: app_queue.c:546 changethread: Device 'SIP/705' changed to state '1' (Not in use) but we don't care because they're not a member of any queue. [Jan 10 19:27:49] DEBUG[27672]: chan_sip.c:3420 sip_answer: SIP answering channel: SIP/705-08203868 [Jan 10 19:27:49] DEBUG[27672]: chan_sip.c:6353 transmit_response_with_sdp: Setting framing from config on incoming call [Jan 10 19:27:49] DEBUG[27672]: chan_sip.c:6121 add_sdp: ** Our capability: 0xc (ulaw|alaw) Video flag: True [Jan 10 19:27:49] DEBUG[27672]: chan_sip.c:6122 add_sdp: ** Our prefcodec: 0x0 (nothing) [Jan 10 19:27:49] Audio is at 192.168.1.114 port 19818 [Jan 10 19:27:49] Adding codec 0x4 (ulaw) to SDP [Jan 10 19:27:49] Adding codec 0x8 (alaw) to SDP [Jan 10 19:27:49] Adding non-codec 0x1 (telephone-event) to SDP [Jan 10 19:27:49] DEBUG[27672]: chan_sip.c:6253 add_sdp: -- Done with adding codecs to SDP [Jan 10 19:27:49] DEBUG[27672]: chan_sip.c:6298 add_sdp: Done building SDP. Settling with this capability: 0xc (ulaw|alaw) [Jan 10 19:27:49] <--- Reliably Transmitting (no NAT) to 192.168.1.115:5060 ---> SIP/2.0 200 OK Via: SIP/2.0/UDP 192.168.1.115:5060;branch=z9hG4bK-41b2e803;received=192.168.1.115 From: "705" ;tag=4ed98004c62ecf56o0 To: ;tag=as1ca65f07 Call-ID: d734381c-f6e9b61e@192.168.1.115 CSeq: 102 INVITE User-Agent: Asterisk PBX Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY Supported: replaces Contact: Content-Type: application/sdp Content-Length: 266 v=0 o=root 27547 27547 IN IP4 192.168.1.114 s=session c=IN IP4 192.168.1.114 t=0 0 m=audio 19818 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=silenceSupp:off - - - - a=ptime:20 a=sendrecv <------------> [Jan 10 19:27:49] DEBUG[27672]: chan_sip.c:1951 __sip_reliable_xmit: *** SIP TIMER: Initalizing retransmit timer on packet: Id #60 [Jan 10 19:27:49] <--- SIP read from 192.168.1.115:5060 ---> ACK sip:70@192.168.1.114 SIP/2.0 Via: SIP/2.0/UDP 192.168.1.115:5060;branch=z9hG4bK-7b38ef6a From: "705" ;tag=4ed98004c62ecf56o0 To: ;tag=as1ca65f07 Call-ID: d734381c-f6e9b61e@192.168.1.115 CSeq: 102 ACK Max-Forwards: 70 Proxy-Authorization: Digest username="705",realm="asterisk",nonce="45085383",uri="sip:70@192.168.1.114",algorithm=MD5,response="cac08e4ec2570f4314a3b8f3173cfad8" Contact: "705" User-Agent: Linksys/SPA941-4.1.15 Content-Length: 0 <-------------> [Jan 10 19:27:49] DEBUG[27568]: chan_sip.c:4519 parse_request: Header 0: ACK sip:70@192.168.1.114 SIP/2.0 (32) [Jan 10 19:27:49] DEBUG[27568]: chan_sip.c:4519 parse_request: Header 1: Via: SIP/2.0/UDP 192.168.1.115:5060;branch=z9hG4bK-7b38ef6a (59) [Jan 10 19:27:49] DEBUG[27568]: chan_sip.c:4519 parse_request: Header 2: From: "705" ;tag=4ed98004c62ecf56o0 (58) [Jan 10 19:27:49] DEBUG[27568]: chan_sip.c:4519 parse_request: Header 3: To: ;tag=as1ca65f07 (41) [Jan 10 19:27:49] DEBUG[27568]: chan_sip.c:4519 parse_request: Header 4: Call-ID: d734381c-f6e9b61e@192.168.1.115 (40) [Jan 10 19:27:49] DEBUG[27568]: chan_sip.c:4519 parse_request: Header 5: CSeq: 102 ACK (13) [Jan 10 19:27:49] DEBUG[27568]: chan_sip.c:4519 parse_request: Header 6: Max-Forwards: 70 (16) [Jan 10 19:27:49] DEBUG[27568]: chan_sip.c:4519 parse_request: Header 7: Proxy-Authorization: Digest username="705",realm="asterisk",nonce="45085383",uri="sip:70@192.168.1.114",algorithm=MD5,response="cac08e4ec2570f4314a3b8f3173cfad8" (161) [Jan 10 19:27:49] DEBUG[27568]: chan_sip.c:4519 parse_request: Header 8: Contact: "705" (43) [Jan 10 19:27:49] DEBUG[27568]: chan_sip.c:4519 parse_request: Header 9: User-Agent: Linksys/SPA941-4.1.15 (33) [Jan 10 19:27:49] DEBUG[27568]: chan_sip.c:4519 parse_request: Header 10: Content-Length: 0 (17) [Jan 10 19:27:49] DEBUG[27568]: chan_sip.c:4519 parse_request: Header 11: (0) [Jan 10 19:27:49] --- (11 headers 0 lines) --- [Jan 10 19:27:49] DEBUG[27568]: chan_sip.c:14509 handle_request: **** Received ACK (6) - Command in SIP ACK [Jan 10 19:27:49] DEBUG[27568]: chan_sip.c:2055 __sip_ack: ** SIP TIMER: Cancelling retransmit of packet (reply received) Retransid #60 [Jan 10 19:27:49] DEBUG[27568]: chan_sip.c:2065 __sip_ack: Stopping retransmission on 'd734381c-f6e9b61e@192.168.1.115' of Response 102: Match Not Found [Jan 10 19:27:50] == Parked SIP/705-08203868 on 71@parkedcalls. Will timeout back to extension [from-internal] s, 1 in 45 seconds [Jan 10 19:27:50] DEBUG[27672]: pbx.c:4790 ast_add_extension2: Added extension '71' priority 1 to parkedcalls [Jan 10 19:27:50] -- Added extension '71' priority 1 to parkedcalls [Jan 10 19:27:50] DEBUG[27672]: res_features.c:277 notify_metermaids: Notification of state change to metermaids 71@parkedcalls [Jan 10 19:27:50] DEBUG[27672]: devicestate.c:303 __ast_device_state_changed_literal: Notification of state change to be queued on device/channel park:71@parkedcalls [Jan 10 19:27:50] DEBUG[27672]: channel.c:2731 set_format: Set channel SIP/705-08203868 to write format gsm [Jan 10 19:27:50] DEBUG[27672]: rtp.c:2662 ast_rtp_write: Ooh, format changed from unknown to ulaw [Jan 10 19:27:50] DEBUG[27672]: rtp.c:2679 ast_rtp_write: Created smoother: format: 4 ms: 20 len: 160 [Jan 10 19:27:50] -- Playing 'digits/7' (language 'en') [Jan 10 19:27:50] DEBUG[27552]: devicestate.c:157 ast_device_state: Checking if I can find provider for "park" - number: 71@parkedcalls [Jan 10 19:27:50] DEBUG[27552]: res_features.c:296 metermaidstate: Checking state of exten 71 in context parkedcalls [Jan 10 19:27:50] DEBUG[27552]: devicestate.c:287 do_state_change: Changing state for park:71@parkedcalls - state 2 (In use) [Jan 10 19:27:51] DEBUG[27561]: devicestate.c:303 __ast_device_state_changed_literal: Notification of state change to be queued on device/channel IAX2/704 [Jan 10 19:27:51] DEBUG[27552]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for IAX2 - 704 [Jan 10 19:27:51] DEBUG[27552]: chan_iax2.c:9611 iax2_devicestate: Checking device state for device 704 [Jan 10 19:27:51] DEBUG[27552]: chan_iax2.c:9619 iax2_devicestate: iax2_devicestate: Found peer. What's device state of 704? addr=1845602496, defaddr=0 maxms=0, lastms=0 [Jan 10 19:27:51] DEBUG[27552]: devicestate.c:287 do_state_change: Changing state for IAX2/704 - state 2 (In use) [Jan 10 19:27:51] DEBUG[27552]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for IAX2 - 704 [Jan 10 19:27:51] DEBUG[27552]: chan_iax2.c:9611 iax2_devicestate: Checking device state for device 704 [Jan 10 19:27:51] DEBUG[27552]: chan_iax2.c:9619 iax2_devicestate: iax2_devicestate: Found peer. What's device state of 704? addr=1845602496, defaddr=0 maxms=0, lastms=0 [Jan 10 19:27:51] DEBUG[27676]: app_queue.c:546 changethread: Device 'IAX2/704' changed to state '2' (In use) but we don't care because they're not a member of any queue. [Jan 10 19:27:51] DEBUG[27672]: channel.c:2731 set_format: Set channel SIP/705-08203868 to write format ulaw [Jan 10 19:27:51] DEBUG[27672]: channel.c:2731 set_format: Set channel SIP/705-08203868 to write format gsm [Jan 10 19:27:51] -- Playing 'digits/1' (language 'en') [Jan 10 19:27:52] DEBUG[27672]: channel.c:2731 set_format: Set channel SIP/705-08203868 to write format ulaw [Jan 10 19:27:52] -- Started music on hold, class 'default', on SIP/705-08203868 [Jan 10 19:27:52] DEBUG[27672]: pbx.c:2356 __ast_pbx_run: Spawn extension (from-internal,s,1) exited KEEPALIVE on 'SIP/705-08203868' [Jan 10 19:27:52] == Spawn extension (from-internal, s, 1) exited KEEPALIVE on 'SIP/705-08203868' [Jan 10 19:27:52] WARNING[27553]: file.c:553 ast_openstream_full: File /var/lib/asterisk/mohmp3/Amurvel does not exist in any format [Jan 10 19:27:52] WARNING[27553]: res_musiconhold.c:243 ast_moh_files_next: Unable to open file '/var/lib/asterisk/mohmp3/Amurvel': No such file or directory [Jan 10 19:27:52] DEBUG[27553]: channel.c:2234 __ast_read: Auto-deactivating generator [Jan 10 19:27:52] -- Stopped music on hold on SIP/705-08203868 [Jan 10 19:27:52] DEBUG[27553]: res_features.c:1650 do_parking_thread: MOH on parked call stopped by outside source. Restarting. [Jan 10 19:27:52] -- Started music on hold, class 'default', on SIP/705-08203868 [Jan 10 19:27:52] WARNING[27553]: file.c:553 ast_openstream_full: File /var/lib/asterisk/mohmp3/Amurvel does not exist in any format [Jan 10 19:27:52] WARNING[27553]: res_musiconhold.c:243 ast_moh_files_next: Unable to open file '/var/lib/asterisk/mohmp3/Amurvel': No such file or directory [Jan 10 19:27:52] DEBUG[27553]: channel.c:2234 __ast_read: Auto-deactivating generator [Jan 10 19:27:52] -- Stopped music on hold on SIP/705-08203868 [Jan 10 19:27:52] DEBUG[27553]: res_features.c:1650 do_parking_thread: MOH on parked call stopped by outside source. Restarting. [Jan 10 19:27:52] -- Started music on hold, class 'default', on SIP/705-08203868 [Jan 10 19:27:52] WARNING[27553]: file.c:553 ast_openstream_full: File /var/lib/asterisk/mohmp3/Amurvel does not exist in any format [Jan 10 19:27:52] WARNING[27553]: res_musiconhold.c:243 ast_moh_files_next: Unable to open file '/var/lib/asterisk/mohmp3/Amurvel': No such file or directory [Jan 10 19:27:52] DEBUG[27553]: channel.c:2234 __ast_read: Auto-deactivating generator [Jan 10 19:27:52] -- Stopped music on hold on SIP/705-08203868 [Jan 10 19:27:52] DEBUG[27553]: res_features.c:1650 do_parking_thread: MOH on parked call stopped by outside source. Restarting. [Jan 10 19:27:52] -- Started music on hold, class 'default', on SIP/705-08203868 [Jan 10 19:27:52] WARNING[27553]: file.c:553 ast_openstream_full: File /var/lib/asterisk/mohmp3/Amurvel does not exist in any format [Jan 10 19:27:52] WARNING[27553]: res_musiconhold.c:243 ast_moh_files_next: Unable to open file '/var/lib/asterisk/mohmp3/Amurvel': No such file or directory [Jan 10 19:27:52] DEBUG[27553]: channel.c:2234 __ast_read: Auto-deactivating generator [Jan 10 19:27:52] -- Stopped music on hold on SIP/705-08203868 [Jan 10 19:27:53] <--- SIP read from 192.168.1.115:5060 ---> REFER sip:704@192.168.1.114 SIP/2.0 Via: SIP/2.0/UDP 192.168.1.115:5060;branch=z9hG4bK-ca9cb8b6 From: ;tag=9ee8c7545a2fad6bi0 To: "IAX softphone" ;tag=as5425b937 Referred-By: "705" Call-ID: 1743acc97a735b134ba9f04e40cf16b2@192.168.1.114 CSeq: 102 REFER Max-Forwards: 70 Contact: "705" Refer-To: User-Agent: Linksys/SPA941-4.1.15 Content-Length: 0 <-------------> [Jan 10 19:27:53] DEBUG[27568]: chan_sip.c:4519 parse_request: Header 0: REFER sip:704@192.168.1.114 SIP/2.0 (35) [Jan 10 19:27:53] DEBUG[27568]: chan_sip.c:4519 parse_request: Header 1: Via: SIP/2.0/UDP 192.168.1.115:5060;branch=z9hG4bK-ca9cb8b6 (59) [Jan 10 19:27:53] DEBUG[27568]: chan_sip.c:4519 parse_request: Header 2: From: ;tag=9ee8c7545a2fad6bi0 (57) [Jan 10 19:27:53] DEBUG[27568]: chan_sip.c:4519 parse_request: Header 3: To: "IAX softphone" ;tag=as5425b937 (58) [Jan 10 19:27:53] DEBUG[27568]: chan_sip.c:4519 parse_request: Header 4: Referred-By: "705" (42) [Jan 10 19:27:53] DEBUG[27568]: chan_sip.c:4519 parse_request: Header 5: Call-ID: 1743acc97a735b134ba9f04e40cf16b2@192.168.1.114 (55) [Jan 10 19:27:53] DEBUG[27568]: chan_sip.c:4519 parse_request: Header 6: CSeq: 102 REFER (15) [Jan 10 19:27:53] DEBUG[27568]: chan_sip.c:4519 parse_request: Header 7: Max-Forwards: 70 (16) [Jan 10 19:27:53] DEBUG[27568]: chan_sip.c:4519 parse_request: Header 8: Contact: "705" (43) [Jan 10 19:27:53] DEBUG[27568]: chan_sip.c:4519 parse_request: Header 9: Refer-To: (137) [Jan 10 19:27:53] DEBUG[27568]: chan_sip.c:4519 parse_request: Header 10: User-Agent: Linksys/SPA941-4.1.15 (33) [Jan 10 19:27:53] DEBUG[27568]: chan_sip.c:4519 parse_request: Header 11: Content-Length: 0 (17) [Jan 10 19:27:53] DEBUG[27568]: chan_sip.c:4519 parse_request: Header 12: (0) [Jan 10 19:27:53] --- (12 headers 0 lines) --- [Jan 10 19:27:53] DEBUG[27568]: chan_sip.c:14509 handle_request: **** Received REFER (9) - Command in SIP REFER [Jan 10 19:27:53] Call 1743acc97a735b134ba9f04e40cf16b2@192.168.1.114 got a SIP call transfer from caller: (REFER)! [Jan 10 19:27:53] DEBUG[27568]: chan_sip.c:8626 get_refer_info: Attended transfer: Will use Replace-Call-ID : d734381c-f6e9b61e@192.168.1.115 (No check of from/to tags) [Jan 10 19:27:53] SIP transfer to extension 70@from-internal by 705@192.168.1.114 [Jan 10 19:27:53] DEBUG[27568]: chan_sip.c:13850 handle_request_refer: SIP attended transfer: Transferer channel SIP/705-081ea8f8, transferee channel IAX2/704-1 [Jan 10 19:27:53] DEBUG[27568]: chan_sip.c:13866 handle_request_refer: Got SIP transfer, applying to bridged peer 'IAX2/704-1' [Jan 10 19:27:53] DEBUG[27568]: chan_sip.c:8480 get_sip_pvt_byid_locked: Looking for callid d734381c-f6e9b61e@192.168.1.115 (fromtag 4ed98004c62ecf56o0 totag as1ca65f07) [Jan 10 19:27:53] DEBUG[27568]: chan_sip.c:8504 get_sip_pvt_byid_locked: Matched INCOMING call - their tag is 4ed98004c62ecf56o0 Our tag is as1ca65f07 [Jan 10 19:27:53] <--- Transmitting (no NAT) to 192.168.1.115:5060 ---> SIP/2.0 202 Accepted Via: SIP/2.0/UDP 192.168.1.115:5060;branch=z9hG4bK-ca9cb8b6;received=192.168.1.115 From: ;tag=9ee8c7545a2fad6bi0 To: "IAX softphone" ;tag=as5425b937 Call-ID: 1743acc97a735b134ba9f04e40cf16b2@192.168.1.114 CSeq: 102 REFER User-Agent: Asterisk PBX Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY Supported: replaces Contact: Content-Length: 0 <------------> [Jan 10 19:27:53] DEBUG[27568]: chan_sip.c:13599 local_attended_transfer: SIP attended transfer: Error: No target channel [Jan 10 19:27:53] DEBUG[27568]: chan_sip.c:5576 reqprep: Strict routing enforced for session 1743acc97a735b134ba9f04e40cf16b2@192.168.1.114 [Jan 10 19:27:53] set_destination: Parsing for address/port to send to [Jan 10 19:27:53] set_destination: set destination to 192.168.1.115, port 5060 [Jan 10 19:27:53] Reliably Transmitting (no NAT) to 192.168.1.115:5060: NOTIFY sip:705@192.168.1.115:5060 SIP/2.0 Via: SIP/2.0/UDP 192.168.1.114:5060;branch=z9hG4bK12b9115c From: "IAX softphone" ;tag=as5425b937 To: ;tag=9ee8c7545a2fad6bi0 Contact: Call-ID: 1743acc97a735b134ba9f04e40cf16b2@192.168.1.114 CSeq: 103 NOTIFY User-Agent: Asterisk PBX Max-Forwards: 70 Event: refer;id=102 Subscription-state: terminated;reason=noresource Content-Type: message/sipfrag;version=2.0 Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY Supported: replaces Content-Length: 33 SIP/2.0 503 Service Unavailable --- [Jan 10 19:27:53] DEBUG[27568]: chan_sip.c:1951 __sip_reliable_xmit: *** SIP TIMER: Initalizing retransmit timer on packet: Id #62 [Jan 10 19:27:53] DEBUG[27568]: chan_sip.c:14720 sipsock_read: SIP message could not be handled, bad request: 1743acc97a735b134ba9f04e40cf16b2@192.168.1.114 [Jan 10 19:27:53] <--- SIP read from 192.168.1.115:5060 ---> SIP/2.0 200 OK To: ;tag=9ee8c7545a2fad6bi0 From: "IAX softphone" ;tag=as5425b937 Call-ID: 1743acc97a735b134ba9f04e40cf16b2@192.168.1.114 CSeq: 103 NOTIFY Via: SIP/2.0/UDP 192.168.1.114:5060;branch=z9hG4bK12b9115c Server: Linksys/SPA941-4.1.15 Content-Length: 0 <-------------> [Jan 10 19:27:53] DEBUG[27568]: chan_sip.c:4519 parse_request: Header 0: SIP/2.0 200 OK (14) [Jan 10 19:27:53] DEBUG[27568]: chan_sip.c:4519 parse_request: Header 1: To: ;tag=9ee8c7545a2fad6bi0 (55) [Jan 10 19:27:53] DEBUG[27568]: chan_sip.c:4519 parse_request: Header 2: From: "IAX softphone" ;tag=as5425b937 (60) [Jan 10 19:27:53] DEBUG[27568]: chan_sip.c:4519 parse_request: Header 3: Call-ID: 1743acc97a735b134ba9f04e40cf16b2@192.168.1.114 (55) [Jan 10 19:27:53] DEBUG[27568]: chan_sip.c:4519 parse_request: Header 4: CSeq: 103 NOTIFY (16) [Jan 10 19:27:53] DEBUG[27568]: chan_sip.c:4519 parse_request: Header 5: Via: SIP/2.0/UDP 192.168.1.114:5060;branch=z9hG4bK12b9115c (58) [Jan 10 19:27:53] DEBUG[27568]: chan_sip.c:4519 parse_request: Header 6: Server: Linksys/SPA941-4.1.15 (29) [Jan 10 19:27:53] DEBUG[27568]: chan_sip.c:4519 parse_request: Header 7: Content-Length: 0 (17) [Jan 10 19:27:53] DEBUG[27568]: chan_sip.c:4519 parse_request: Header 8: (0) [Jan 10 19:27:53] --- (8 headers 0 lines) --- [Jan 10 19:27:53] DEBUG[27568]: chan_sip.c:2055 __sip_ack: ** SIP TIMER: Cancelling retransmit of packet (reply received) Retransid #62 [Jan 10 19:27:53] DEBUG[27568]: chan_sip.c:2065 __sip_ack: Stopping retransmission on '1743acc97a735b134ba9f04e40cf16b2@192.168.1.114' of Request 103: Match Not Found [Jan 10 19:27:53] SIP Response message for INCOMING dialog NOTIFY arrived [Jan 10 19:27:53] WARNING[27568]: chan_sip.c:12350 handle_response: Notify answer on an owned channel? [Jan 10 19:27:57] <--- SIP read from 192.168.1.115:5060 ---> BYE sip:704@192.168.1.114 SIP/2.0 Via: SIP/2.0/UDP 192.168.1.115:5060;branch=z9hG4bK-5bd4a16c From: ;tag=9ee8c7545a2fad6bi0 To: "IAX softphone" ;tag=as5425b937 Call-ID: 1743acc97a735b134ba9f04e40cf16b2@192.168.1.114 CSeq: 103 BYE Max-Forwards: 70 User-Agent: Linksys/SPA941-4.1.15 Content-Length: 0 <-------------> [Jan 10 19:27:57] DEBUG[27568]: chan_sip.c:4519 parse_request: Header 0: BYE sip:704@192.168.1.114 SIP/2.0 (33) [Jan 10 19:27:57] DEBUG[27568]: chan_sip.c:4519 parse_request: Header 1: Via: SIP/2.0/UDP 192.168.1.115:5060;branch=z9hG4bK-5bd4a16c (59) [Jan 10 19:27:57] DEBUG[27568]: chan_sip.c:4519 parse_request: Header 2: From: ;tag=9ee8c7545a2fad6bi0 (57) [Jan 10 19:27:57] DEBUG[27568]: chan_sip.c:4519 parse_request: Header 3: To: "IAX softphone" ;tag=as5425b937 (58) [Jan 10 19:27:57] DEBUG[27568]: chan_sip.c:4519 parse_request: Header 4: Call-ID: 1743acc97a735b134ba9f04e40cf16b2@192.168.1.114 (55) [Jan 10 19:27:57] DEBUG[27568]: chan_sip.c:4519 parse_request: Header 5: CSeq: 103 BYE (13) [Jan 10 19:27:57] DEBUG[27568]: chan_sip.c:4519 parse_request: Header 6: Max-Forwards: 70 (16) [Jan 10 19:27:57] DEBUG[27568]: chan_sip.c:4519 parse_request: Header 7: User-Agent: Linksys/SPA941-4.1.15 (33) [Jan 10 19:27:57] DEBUG[27568]: chan_sip.c:4519 parse_request: Header 8: Content-Length: 0 (17) [Jan 10 19:27:57] DEBUG[27568]: chan_sip.c:4519 parse_request: Header 9: (0) [Jan 10 19:27:57] --- (9 headers 0 lines) --- [Jan 10 19:27:57] DEBUG[27568]: chan_sip.c:14509 handle_request: **** Received BYE (8) - Command in SIP BYE [Jan 10 19:27:57] Sending to 192.168.1.115 : 5060 (no NAT) [Jan 10 19:27:57] DEBUG[27568]: chan_sip.c:1609 sip_alreadygone: Setting SIP_ALREADYGONE on dialog 1743acc97a735b134ba9f04e40cf16b2@192.168.1.114 [Jan 10 19:27:57] DEBUG[27568]: chan_sip.c:14086 handle_request_bye: Received bye, issuing owner hangup [Jan 10 19:27:57] <--- Transmitting (no NAT) to 192.168.1.115:5060 ---> SIP/2.0 200 OK Via: SIP/2.0/UDP 192.168.1.115:5060;branch=z9hG4bK-5bd4a16c;received=192.168.1.115 From: ;tag=9ee8c7545a2fad6bi0 To: "IAX softphone" ;tag=as5425b937 Call-ID: 1743acc97a735b134ba9f04e40cf16b2@192.168.1.114 CSeq: 103 BYE User-Agent: Asterisk PBX Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY Supported: replaces Contact: Content-Length: 0 <------------> [Jan 10 19:27:57] DEBUG[27665]: channel.c:3682 ast_generic_bridge: Didn't get a frame from channel: SIP/705-081ea8f8 [Jan 10 19:27:57] DEBUG[27665]: channel.c:3986 ast_channel_bridge: Bridge stops bridging channels IAX2/704-1 and SIP/705-081ea8f8 [Jan 10 19:27:57] DEBUG[27665]: channel.c:1606 ast_hangup: Hanging up channel 'SIP/705-081ea8f8' [Jan 10 19:27:57] DEBUG[27665]: chan_sip.c:3270 sip_hangup: Hangup call SIP/705-081ea8f8, SIP callid 1743acc97a735b134ba9f04e40cf16b2@192.168.1.114) [Jan 10 19:27:57] DEBUG[27665]: chan_sip.c:3278 sip_hangup: update_call_counter(705) - decrement call limit counter on hangup [Jan 10 19:27:57] DEBUG[27665]: chan_sip.c:2970 update_call_counter: Updating call counter for incoming call [Jan 10 19:27:57] DEBUG[27665]: devicestate.c:303 __ast_device_state_changed_literal: Notification of state change to be queued on device/channel SIP/705-081ea8f8 [Jan 10 19:27:57] DEBUG[27665]: rtp.c:1460 ast_rtp_early_bridge: Channel 'IAX2/704-1' has no RTP, not doing anything [Jan 10 19:27:57] DEBUG[27665]: app_dial.c:1643 dial_exec_full: Exiting with DIALSTATUS=ANSWER. [Jan 10 19:27:57] DEBUG[27665]: app_macro.c:253 _macro_exec: Spawn extension (macro-dial,s,10) exited non-zero on 'IAX2/704-1' in macro 'dial' [Jan 10 19:27:57] DEBUG[27665]: app_macro.c:253 _macro_exec: Spawn extension (macro-dial,s,10) exited non-zero on 'IAX2/704-1' in macro 'exten-vm' [Jan 10 19:27:57] DEBUG[27665]: pbx.c:2363 __ast_pbx_run: Spawn extension (macro-dial,s,10) exited non-zero on 'IAX2/704-1' [Jan 10 19:27:57] == Spawn extension (macro-dial, s, 10) exited non-zero on 'IAX2/704-1' [Jan 10 19:27:57] DEBUG[27665]: pbx.c:1621 pbx_substitute_variables_helper_full: Function result is '"IAX softphone" <704>' [Jan 10 19:27:57] DEBUG[27665]: pbx.c:1621 pbx_substitute_variables_helper_full: Function result is '704' [Jan 10 19:27:57] DEBUG[27665]: pbx.c:1621 pbx_substitute_variables_helper_full: Function result is '705' [Jan 10 19:27:57] DEBUG[27665]: pbx.c:1621 pbx_substitute_variables_helper_full: Function result is 'from-internal' [Jan 10 19:27:57] DEBUG[27665]: pbx.c:1621 pbx_substitute_variables_helper_full: Function result is 'IAX2/704-1' [Jan 10 19:27:57] DEBUG[27665]: pbx.c:1621 pbx_substitute_variables_helper_full: Function result is 'SIP/705-081ea8f8' [Jan 10 19:27:57] DEBUG[27665]: pbx.c:1621 pbx_substitute_variables_helper_full: Function result is 'Dial' [Jan 10 19:27:57] DEBUG[27665]: pbx.c:1621 pbx_substitute_variables_helper_full: Function result is 'SIP/705||tr' [Jan 10 19:27:57] DEBUG[27665]: pbx.c:1621 pbx_substitute_variables_helper_full: Function result is '2007-01-10 19:27:42' [Jan 10 19:27:57] DEBUG[27665]: pbx.c:1621 pbx_substitute_variables_helper_full: Function result is '2007-01-10 19:27:44' [Jan 10 19:27:57] DEBUG[27665]: pbx.c:1621 pbx_substitute_variables_helper_full: Function result is '2007-01-10 19:27:57' [Jan 10 19:27:57] DEBUG[27665]: pbx.c:1621 pbx_substitute_variables_helper_full: Function result is '15' [Jan 10 19:27:57] DEBUG[27665]: pbx.c:1621 pbx_substitute_variables_helper_full: Function result is '13' [Jan 10 19:27:57] DEBUG[27665]: pbx.c:1621 pbx_substitute_variables_helper_full: Function result is 'ANSWERED' [Jan 10 19:27:57] DEBUG[27665]: pbx.c:1621 pbx_substitute_variables_helper_full: Function result is 'DOCUMENTATION' [Jan 10 19:27:57] DEBUG[27665]: pbx.c:1621 pbx_substitute_variables_helper_full: Function result is '' [Jan 10 19:27:57] DEBUG[27665]: pbx.c:1621 pbx_substitute_variables_helper_full: Function result is '1168482462.0' [Jan 10 19:27:57] DEBUG[27665]: pbx.c:1621 pbx_substitute_variables_helper_full: Function result is '' [Jan 10 19:27:57] DEBUG[27665]: channel.c:1606 ast_hangup: Hanging up channel 'IAX2/704-1' [Jan 10 19:27:57] DEBUG[27665]: chan_iax2.c:2936 iax2_hangup: We're hanging up IAX2/704-1 now... [Jan 10 19:27:57] -- Hungup 'IAX2/704-1' [Jan 10 19:27:57] DEBUG[27665]: devicestate.c:303 __ast_device_state_changed_literal: Notification of state change to be queued on device/channel IAX2/704-1 [Jan 10 19:27:57] DEBUG[27552]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for SIP - 705 [Jan 10 19:27:57] DEBUG[27552]: chan_sip.c:15104 sip_devicestate: Checking device state for peer 705 [Jan 10 19:27:57] DEBUG[27552]: devicestate.c:287 do_state_change: Changing state for SIP/705 - state 1 (Not in use) [Jan 10 19:27:57] DEBUG[27552]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for SIP - 705 [Jan 10 19:27:57] DEBUG[27552]: chan_sip.c:15104 sip_devicestate: Checking device state for peer 705 [Jan 10 19:27:57] DEBUG[27552]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for IAX2 - 704 [Jan 10 19:27:57] DEBUG[27552]: chan_iax2.c:9611 iax2_devicestate: Checking device state for device 704 [Jan 10 19:27:57] DEBUG[27552]: chan_iax2.c:9619 iax2_devicestate: iax2_devicestate: Found peer. What's device state of 704? addr=1845602496, defaddr=0 maxms=0, lastms=0 [Jan 10 19:27:57] DEBUG[27552]: devicestate.c:287 do_state_change: Changing state for IAX2/704 - state 1 (Not in use) [Jan 10 19:27:57] DEBUG[27552]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for IAX2 - 704 [Jan 10 19:27:57] DEBUG[27552]: chan_iax2.c:9611 iax2_devicestate: Checking device state for device 704 [Jan 10 19:27:57] DEBUG[27552]: chan_iax2.c:9619 iax2_devicestate: iax2_devicestate: Found peer. What's device state of 704? addr=1845602496, defaddr=0 maxms=0, lastms=0 [Jan 10 19:27:57] DEBUG[27677]: app_queue.c:546 changethread: Device 'SIP/705' changed to state '1' (Not in use) but we don't care because they're not a member of any queue. [Jan 10 19:27:57] DEBUG[27678]: app_queue.c:546 changethread: Device 'IAX2/704' changed to state '1' (Not in use) but we don't care because they're not a member of any queue. [Jan 10 19:27:57] <--- SIP read from 192.168.1.115:5060 ---> BYE sip:70@192.168.1.114 SIP/2.0 Via: SIP/2.0/UDP 192.168.1.115:5060;branch=z9hG4bK-c1bbe02e From: "705" ;tag=4ed98004c62ecf56o0 To: ;tag=as1ca65f07 Call-ID: d734381c-f6e9b61e@192.168.1.115 CSeq: 103 BYE Max-Forwards: 70 Proxy-Authorization: Digest username="705",realm="asterisk",nonce="45085383",uri="sip:70@192.168.1.114",algorithm=MD5,response="ca4c53d9cdb1525b6499d85a62e4a0a8" User-Agent: Linksys/SPA941-4.1.15 Content-Length: 0 <-------------> [Jan 10 19:27:57] DEBUG[27568]: chan_sip.c:4519 parse_request: Header 0: BYE sip:70@192.168.1.114 SIP/2.0 (32) [Jan 10 19:27:57] DEBUG[27568]: chan_sip.c:4519 parse_request: Header 1: Via: SIP/2.0/UDP 192.168.1.115:5060;branch=z9hG4bK-c1bbe02e (59) [Jan 10 19:27:57] DEBUG[27568]: chan_sip.c:4519 parse_request: Header 2: From: "705" ;tag=4ed98004c62ecf56o0 (58) [Jan 10 19:27:57] DEBUG[27568]: chan_sip.c:4519 parse_request: Header 3: To: ;tag=as1ca65f07 (41) [Jan 10 19:27:57] DEBUG[27568]: chan_sip.c:4519 parse_request: Header 4: Call-ID: d734381c-f6e9b61e@192.168.1.115 (40) [Jan 10 19:27:57] DEBUG[27568]: chan_sip.c:4519 parse_request: Header 5: CSeq: 103 BYE (13) [Jan 10 19:27:57] DEBUG[27568]: chan_sip.c:4519 parse_request: Header 6: Max-Forwards: 70 (16) [Jan 10 19:27:57] DEBUG[27568]: chan_sip.c:4519 parse_request: Header 7: Proxy-Authorization: Digest username="705",realm="asterisk",nonce="45085383",uri="sip:70@192.168.1.114",algorithm=MD5,response="ca4c53d9cdb1525b6499d85a62e4a0a8" (161) [Jan 10 19:27:57] DEBUG[27568]: chan_sip.c:4519 parse_request: Header 8: User-Agent: Linksys/SPA941-4.1.15 (33) [Jan 10 19:27:57] DEBUG[27568]: chan_sip.c:4519 parse_request: Header 9: Content-Length: 0 (17) [Jan 10 19:27:57] DEBUG[27568]: chan_sip.c:4519 parse_request: Header 10: (0) [Jan 10 19:27:57] --- (10 headers 0 lines) --- [Jan 10 19:27:57] DEBUG[27568]: chan_sip.c:14509 handle_request: **** Received BYE (8) - Command in SIP BYE [Jan 10 19:27:57] Sending to 192.168.1.115 : 5060 (no NAT) [Jan 10 19:27:57] DEBUG[27568]: chan_sip.c:1609 sip_alreadygone: Setting SIP_ALREADYGONE on dialog d734381c-f6e9b61e@192.168.1.115 [Jan 10 19:27:57] DEBUG[27568]: chan_sip.c:14086 handle_request_bye: Received bye, issuing owner hangup [Jan 10 19:27:57] <--- Transmitting (no NAT) to 192.168.1.115:5060 ---> SIP/2.0 200 OK Via: SIP/2.0/UDP 192.168.1.115:5060;branch=z9hG4bK-c1bbe02e;received=192.168.1.115 From: "705" ;tag=4ed98004c62ecf56o0 To: ;tag=as1ca65f07 Call-ID: d734381c-f6e9b61e@192.168.1.115 CSeq: 103 BYE User-Agent: Asterisk PBX Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY Supported: replaces Contact: Content-Length: 0 <------------> [Jan 10 19:27:57] Really destroying SIP dialog '1743acc97a735b134ba9f04e40cf16b2@192.168.1.114' Method: BYE [Jan 10 19:27:57] == SIP/705-08203868 got tired of being parked