<--- SIP read from 216.221.84.171:5060 ---> INVITE sip:9055920255@sipproxy2.easyofficephone.com SIP/2.0 Via: SIP/2.0/UDP 192.168.2.189:5060;branch=z9hG4bK-72c5f62b From: Dan Moschuk ;tag=ddd53689f170907bo0 To: Remote-Party-ID: Dan Moschuk ;screen=yes;party=calling Call-ID: 463a221-329f59c3@192.168.2.189 CSeq: 101 INVITE Max-Forwards: 70 Contact: Dan Moschuk Expires: 240 User-Agent: Linksys/SPA2102-3.3.5(a) Content-Length: 261 Allow: ACK, BYE, CANCEL, INFO, INVITE, NOTIFY, OPTIONS, REFER Supported: x-sipura Content-Type: application/sdp v=0 o=- 14338801 14338801 IN IP4 216.221.84.171 s=- c=IN IP4 216.221.84.171 t=0 0 m=audio 16414 RTP/AVP 0 100 101 a=rtpmap:0 PCMU/8000 a=rtpmap:100 NSE/8000 a=fmtp:100 192-193 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-15 a=ptime:30 a=sendrecv <-------------> [Jan 12 13:49:01] DEBUG[15234]: chan_sip.c:4519 parse_request: Header 0: INVITE sip:9055920255@sipproxy2.easyofficephone.com SIP/2.0 (59) [Jan 12 13:49:01] DEBUG[15234]: chan_sip.c:4519 parse_request: Header 1: Via: SIP/2.0/UDP 192.168.2.189:5060;branch=z9hG4bK-72c5f62b (59) [Jan 12 13:49:01] DEBUG[15234]: chan_sip.c:4519 parse_request: Header 2: From: Dan Moschuk ;tag=ddd53689f170907bo0 (89) [Jan 12 13:49:01] DEBUG[15234]: chan_sip.c:4519 parse_request: Header 3: To: (50) [Jan 12 13:49:01] DEBUG[15234]: chan_sip.c:4519 parse_request: Header 4: Remote-Party-ID: Dan Moschuk ;screen=yes;party=calling (102) [Jan 12 13:49:01] DEBUG[15234]: chan_sip.c:4519 parse_request: Header 5: Call-ID: 463a221-329f59c3@192.168.2.189 (39) [Jan 12 13:49:01] DEBUG[15234]: chan_sip.c:4519 parse_request: Header 6: CSeq: 101 INVITE (16) [Jan 12 13:49:01] DEBUG[15234]: chan_sip.c:4519 parse_request: Header 7: Max-Forwards: 70 (16) [Jan 12 13:49:01] DEBUG[15234]: chan_sip.c:4519 parse_request: Header 8: Contact: Dan Moschuk (59) [Jan 12 13:49:01] DEBUG[15234]: chan_sip.c:4519 parse_request: Header 9: Expires: 240 (12) [Jan 12 13:49:01] DEBUG[15234]: chan_sip.c:4519 parse_request: Header 10: User-Agent: Linksys/SPA2102-3.3.5(a) (36) [Jan 12 13:49:01] DEBUG[15234]: chan_sip.c:4519 parse_request: Header 11: Content-Length: 261 (19) [Jan 12 13:49:01] DEBUG[15234]: chan_sip.c:4519 parse_request: Header 12: Allow: ACK, BYE, CANCEL, INFO, INVITE, NOTIFY, OPTIONS, REFER (61) [Jan 12 13:49:01] DEBUG[15234]: chan_sip.c:4519 parse_request: Header 13: Supported: x-sipura (19) [Jan 12 13:49:01] DEBUG[15234]: chan_sip.c:4519 parse_request: Header 14: Content-Type: application/sdp (29) [Jan 12 13:49:01] DEBUG[15234]: chan_sip.c:4519 parse_request: Header 15: (0) [Jan 12 13:49:01] DEBUG[15234]: chan_sip.c:4551 parse_request: Line: v=0 (3) [Jan 12 13:49:01] DEBUG[15234]: chan_sip.c:4551 parse_request: Line: o=- 14338801 14338801 IN IP4 216.221.84.171 (43) [Jan 12 13:49:01] DEBUG[15234]: chan_sip.c:4551 parse_request: Line: s=- (3) [Jan 12 13:49:01] DEBUG[15234]: chan_sip.c:4551 parse_request: Line: c=IN IP4 216.221.84.171 (23) [Jan 12 13:49:01] DEBUG[15234]: chan_sip.c:4551 parse_request: Line: t=0 0 (5) [Jan 12 13:49:01] DEBUG[15234]: chan_sip.c:4551 parse_request: Line: m=audio 16414 RTP/AVP 0 100 101 (31) [Jan 12 13:49:01] DEBUG[15234]: chan_sip.c:4551 parse_request: Line: a=rtpmap:0 PCMU/8000 (20) [Jan 12 13:49:01] DEBUG[15234]: chan_sip.c:4551 parse_request: Line: a=rtpmap:100 NSE/8000 (21) [Jan 12 13:49:01] DEBUG[15234]: chan_sip.c:4551 parse_request: Line: a=fmtp:100 192-193 (18) [Jan 12 13:49:01] DEBUG[15234]: chan_sip.c:4551 parse_request: Line: a=rtpmap:101 telephone-event/8000 (33) [Jan 12 13:49:01] DEBUG[15234]: chan_sip.c:4551 parse_request: Line: a=fmtp:101 0-15 (15) [Jan 12 13:49:01] DEBUG[15234]: chan_sip.c:4551 parse_request: Line: a=ptime:30 (10) [Jan 12 13:49:01] DEBUG[15234]: chan_sip.c:4551 parse_request: Line: a=sendrecv (10) [Jan 12 13:49:01] --- (15 headers 13 lines) --- [Jan 12 13:49:01] DEBUG[15234]: chan_sip.c:2551 do_setnat: Setting NAT on RTP to Off [Jan 12 13:49:01] DEBUG[15234]: chan_sip.c:4256 sip_alloc: Allocating new SIP dialog for 463a221-329f59c3@192.168.2.189 - INVITE (With RTP) [Jan 12 13:49:01] DEBUG[15234]: chan_sip.c:14502 handle_request: **** Received INVITE (5) - Command in SIP INVITE [Jan 12 13:49:01] DEBUG[15234]: chan_sip.c:1656 parse_sip_options: Begin: parsing SIP "Supported: x-sipura" [Jan 12 13:49:01] DEBUG[15234]: chan_sip.c:1664 parse_sip_options: Found SIP option: -x-sipura- [Jan 12 13:49:01] DEBUG[15234]: chan_sip.c:1676 parse_sip_options: Found private SIP option, not supported: x-sipura [Jan 12 13:49:01] Sending to 192.168.2.189 : 5060 (no NAT) [Jan 12 13:49:01] Using INVITE request as basis request - 463a221-329f59c3@192.168.2.189 [Jan 12 13:49:01] DEBUG[15234]: chan_sip.c:2551 do_setnat: Setting NAT on RTP to On [Jan 12 13:49:01] <--- Reliably Transmitting (NAT) to 216.221.84.171:5060 ---> SIP/2.0 407 Proxy Authentication Required Via: SIP/2.0/UDP 192.168.2.189:5060;branch=z9hG4bK-72c5f62b;received=216.221.84.171 From: Dan Moschuk ;tag=ddd53689f170907bo0 To: ;tag=as750d373b Call-ID: 463a221-329f59c3@192.168.2.189 CSeq: 101 INVITE User-Agent: Easy Office Phone Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY Supported: replaces Proxy-Authenticate: Digest algorithm=MD5, realm="asterisk", nonce="2297c390" Content-Length: 0 <------------> [Jan 12 13:49:01] DEBUG[15234]: chan_sip.c:1951 __sip_reliable_xmit: *** SIP TIMER: Initalizing retransmit timer on packet: Id #133 [Jan 12 13:49:01] Scheduling destruction of SIP dialog '463a221-329f59c3@192.168.2.189' in 32000 ms (Method: INVITE) [Jan 12 13:49:01] Found user 'danmoschuk-1' [Jan 12 13:49:01] <--- SIP read from 216.221.84.171:5060 ---> ACK sip:9055920255@sipproxy2.easyofficephone.com SIP/2.0 Via: SIP/2.0/UDP 192.168.2.189:5060;branch=z9hG4bK-72c5f62b From: Dan Moschuk ;tag=ddd53689f170907bo0 To: ;tag=as750d373b Call-ID: 463a221-329f59c3@192.168.2.189 CSeq: 101 ACK Max-Forwards: 70 Contact: Dan Moschuk User-Agent: Linksys/SPA2102-3.3.5(a) Content-Length: 0 <-------------> [Jan 12 13:49:01] DEBUG[15234]: chan_sip.c:4519 parse_request: Header 0: ACK sip:9055920255@sipproxy2.easyofficephone.com SIP/2.0 (56) [Jan 12 13:49:01] DEBUG[15234]: chan_sip.c:4519 parse_request: Header 1: Via: SIP/2.0/UDP 192.168.2.189:5060;branch=z9hG4bK-72c5f62b (59) [Jan 12 13:49:01] DEBUG[15234]: chan_sip.c:4519 parse_request: Header 2: From: Dan Moschuk ;tag=ddd53689f170907bo0 (89) [Jan 12 13:49:01] DEBUG[15234]: chan_sip.c:4519 parse_request: Header 3: To: ;tag=as750d373b (65) [Jan 12 13:49:01] DEBUG[15234]: chan_sip.c:4519 parse_request: Header 4: Call-ID: 463a221-329f59c3@192.168.2.189 (39) [Jan 12 13:49:01] DEBUG[15234]: chan_sip.c:4519 parse_request: Header 5: CSeq: 101 ACK (13) [Jan 12 13:49:01] DEBUG[15234]: chan_sip.c:4519 parse_request: Header 6: Max-Forwards: 70 (16) [Jan 12 13:49:01] DEBUG[15234]: chan_sip.c:4519 parse_request: Header 7: Contact: Dan Moschuk (59) [Jan 12 13:49:01] DEBUG[15234]: chan_sip.c:4519 parse_request: Header 8: User-Agent: Linksys/SPA2102-3.3.5(a) (36) [Jan 12 13:49:01] DEBUG[15234]: chan_sip.c:4519 parse_request: Header 9: Content-Length: 0 (17) [Jan 12 13:49:01] DEBUG[15234]: chan_sip.c:4519 parse_request: Header 10: (0) [Jan 12 13:49:01] --- (10 headers 0 lines) --- [Jan 12 13:49:01] DEBUG[15234]: chan_sip.c:14502 handle_request: **** Received ACK (6) - Command in SIP ACK [Jan 12 13:49:01] DEBUG[15234]: chan_sip.c:2055 __sip_ack: ** SIP TIMER: Cancelling retransmit of packet (reply received) Retransid #133 [Jan 12 13:49:01] DEBUG[15234]: chan_sip.c:2065 __sip_ack: Stopping retransmission on '463a221-329f59c3@192.168.2.189' of Response 101: Match Not Found [Jan 12 13:49:01] <--- SIP read from 216.221.84.171:5060 ---> INVITE sip:9055920255@sipproxy2.easyofficephone.com SIP/2.0 Via: SIP/2.0/UDP 192.168.2.189:5060;branch=z9hG4bK-f9e978cf From: Dan Moschuk ;tag=ddd53689f170907bo0 To: Remote-Party-ID: Dan Moschuk ;screen=yes;party=calling Call-ID: 463a221-329f59c3@192.168.2.189 CSeq: 102 INVITE Max-Forwards: 70 Proxy-Authorization: Digest username="danmoschuk-1",realm="asterisk",nonce="2297c390",uri="sip:9055920255@sipproxy2.easyofficephone.com",algorithm=MD5,response="f81e41ae4a5abc36d7c5a27a22c9f0db" Contact: Dan Moschuk Expires: 240 User-Agent: Linksys/SPA2102-3.3.5(a) Content-Length: 261 Allow: ACK, BYE, CANCEL, INFO, INVITE, NOTIFY, OPTIONS, REFER Supported: x-sipura Content-Type: application/sdp v=0 o=- 14338801 14338801 IN IP4 216.221.84.171 s=- c=IN IP4 216.221.84.171 t=0 0 m=audio 16414 RTP/AVP 0 100 101 a=rtpmap:0 PCMU/8000 a=rtpmap:100 NSE/8000 a=fmtp:100 192-193 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-15 a=ptime:30 a=sendrecv <-------------> [Jan 12 13:49:01] DEBUG[15234]: chan_sip.c:4519 parse_request: Header 0: INVITE sip:9055920255@sipproxy2.easyofficephone.com SIP/2.0 (59) [Jan 12 13:49:01] DEBUG[15234]: chan_sip.c:4519 parse_request: Header 1: Via: SIP/2.0/UDP 192.168.2.189:5060;branch=z9hG4bK-f9e978cf (59) [Jan 12 13:49:01] DEBUG[15234]: chan_sip.c:4519 parse_request: Header 2: From: Dan Moschuk ;tag=ddd53689f170907bo0 (89) [Jan 12 13:49:01] DEBUG[15234]: chan_sip.c:4519 parse_request: Header 3: To: (50) [Jan 12 13:49:01] DEBUG[15234]: chan_sip.c:4519 parse_request: Header 4: Remote-Party-ID: Dan Moschuk ;screen=yes;party=calling (102) [Jan 12 13:49:01] DEBUG[15234]: chan_sip.c:4519 parse_request: Header 5: Call-ID: 463a221-329f59c3@192.168.2.189 (39) [Jan 12 13:49:01] DEBUG[15234]: chan_sip.c:4519 parse_request: Header 6: CSeq: 102 INVITE (16) [Jan 12 13:49:01] DEBUG[15234]: chan_sip.c:4519 parse_request: Header 7: Max-Forwards: 70 (16) [Jan 12 13:49:01] DEBUG[15234]: chan_sip.c:4519 parse_request: Header 8: Proxy-Authorization: Digest username="danmoschuk-1",realm="asterisk",nonce="2297c390",uri="sip:9055920255@sipproxy2.easyofficephone.com",algorithm=MD5,response="f81e41ae4a5abc36d7c5a27a22c9f0db" (194) [Jan 12 13:49:01] DEBUG[15234]: chan_sip.c:4519 parse_request: Header 9: Contact: Dan Moschuk (59) [Jan 12 13:49:01] DEBUG[15234]: chan_sip.c:4519 parse_request: Header 10: Expires: 240 (12) [Jan 12 13:49:01] DEBUG[15234]: chan_sip.c:4519 parse_request: Header 11: User-Agent: Linksys/SPA2102-3.3.5(a) (36) [Jan 12 13:49:01] DEBUG[15234]: chan_sip.c:4519 parse_request: Header 12: Content-Length: 261 (19) [Jan 12 13:49:01] DEBUG[15234]: chan_sip.c:4519 parse_request: Header 13: Allow: ACK, BYE, CANCEL, INFO, INVITE, NOTIFY, OPTIONS, REFER (61) [Jan 12 13:49:01] DEBUG[15234]: chan_sip.c:4519 parse_request: Header 14: Supported: x-sipura (19) [Jan 12 13:49:01] DEBUG[15234]: chan_sip.c:4519 parse_request: Header 15: Content-Type: application/sdp (29) [Jan 12 13:49:01] DEBUG[15234]: chan_sip.c:4519 parse_request: Header 16: (0) [Jan 12 13:49:01] DEBUG[15234]: chan_sip.c:4551 parse_request: Line: v=0 (3) [Jan 12 13:49:01] DEBUG[15234]: chan_sip.c:4551 parse_request: Line: o=- 14338801 14338801 IN IP4 216.221.84.171 (43) [Jan 12 13:49:01] DEBUG[15234]: chan_sip.c:4551 parse_request: Line: s=- (3) [Jan 12 13:49:01] DEBUG[15234]: chan_sip.c:4551 parse_request: Line: c=IN IP4 216.221.84.171 (23) [Jan 12 13:49:01] DEBUG[15234]: chan_sip.c:4551 parse_request: Line: t=0 0 (5) [Jan 12 13:49:01] DEBUG[15234]: chan_sip.c:4551 parse_request: Line: m=audio 16414 RTP/AVP 0 100 101 (31) [Jan 12 13:49:01] DEBUG[15234]: chan_sip.c:4551 parse_request: Line: a=rtpmap:0 PCMU/8000 (20) [Jan 12 13:49:01] DEBUG[15234]: chan_sip.c:4551 parse_request: Line: a=rtpmap:100 NSE/8000 (21) [Jan 12 13:49:01] DEBUG[15234]: chan_sip.c:4551 parse_request: Line: a=fmtp:100 192-193 (18) [Jan 12 13:49:01] DEBUG[15234]: chan_sip.c:4551 parse_request: Line: a=rtpmap:101 telephone-event/8000 (33) [Jan 12 13:49:01] DEBUG[15234]: chan_sip.c:4551 parse_request: Line: a=fmtp:101 0-15 (15) [Jan 12 13:49:01] DEBUG[15234]: chan_sip.c:4551 parse_request: Line: a=ptime:30 (10) [Jan 12 13:49:01] DEBUG[15234]: chan_sip.c:4551 parse_request: Line: a=sendrecv (10) [Jan 12 13:49:01] --- (16 headers 13 lines) --- [Jan 12 13:49:01] DEBUG[15234]: chan_sip.c:14502 handle_request: **** Received INVITE (5) - Command in SIP INVITE [Jan 12 13:49:01] DEBUG[15234]: chan_sip.c:1656 parse_sip_options: Begin: parsing SIP "Supported: x-sipura" [Jan 12 13:49:01] DEBUG[15234]: chan_sip.c:1664 parse_sip_options: Found SIP option: -x-sipura- [Jan 12 13:49:01] DEBUG[15234]: chan_sip.c:1676 parse_sip_options: Found private SIP option, not supported: x-sipura [Jan 12 13:49:01] Sending to 216.221.84.171 : 5060 (NAT) [Jan 12 13:49:01] Using INVITE request as basis request - 463a221-329f59c3@192.168.2.189 [Jan 12 13:49:01] DEBUG[15234]: chan_sip.c:2551 do_setnat: Setting NAT on RTP to On [Jan 12 13:49:01] Found user 'danmoschuk-1' [Jan 12 13:49:01] Found RTP audio format 0 [Jan 12 13:49:01] Found RTP audio format 100 [Jan 12 13:49:01] Found RTP audio format 101 [Jan 12 13:49:01] Peer audio RTP is at port 216.221.84.171:16414 [Jan 12 13:49:01] Found description format PCMU for ID 0 [Jan 12 13:49:01] Found description format NSE for ID 100 [Jan 12 13:49:01] Got unsupported a:fmtp in SDP offer [Jan 12 13:49:01] Found description format telephone-event for ID 101 [Jan 12 13:49:01] Got unsupported a:fmtp in SDP offer [Jan 12 13:49:01] DEBUG[15234]: chan_sip.c:5062 process_sdp: T38 state changed to 0 on channel [Jan 12 13:49:01] Capabilities: us - 0xc (ulaw|alaw), peer - audio=0x4 (ulaw)/video=0x0 (nothing), combined - 0x4 (ulaw) [Jan 12 13:49:01] Non-codec capabilities (dtmf): us - 0x1 (telephone-event), peer - 0x1 (telephone-event), combined - 0x1 (telephone-event) [Jan 12 13:49:01] Peer audio RTP is at port 216.221.84.171:16414 [Jan 12 13:49:01] DEBUG[15234]: chan_sip.c:5139 process_sdp: We're settling with these formats: 0x4 (ulaw) [Jan 12 13:49:01] DEBUG[15234]: chan_sip.c:13290 handle_request_invite: Checking SIP call limits for device danmoschuk-1 [Jan 12 13:49:01] DEBUG[15234]: chan_sip.c:2970 update_call_counter: Updating call counter for incoming call [Jan 12 13:49:01] Looking for 9055920255 in danmoschuk-ext1-out (domain sipproxy2.easyofficephone.com) [Jan 12 13:49:01] DEBUG[15234]: chan_sip.c:3758 sip_new: *** Our native formats are 0x4 (ulaw) [Jan 12 13:49:01] DEBUG[15234]: chan_sip.c:3759 sip_new: *** Joint capabilities are 0x4 (ulaw) [Jan 12 13:49:01] DEBUG[15234]: chan_sip.c:3760 sip_new: *** Our capabilities are 0xc (ulaw|alaw) [Jan 12 13:49:01] DEBUG[15234]: chan_sip.c:3761 sip_new: *** AST_CODEC_CHOOSE formats are 0x4 (ulaw) [Jan 12 13:49:01] DEBUG[15234]: chan_sip.c:3784 sip_new: This channel will not be able to handle video. [Jan 12 13:49:01] DEBUG[15234]: chan_sip.c:7894 build_route: build_route: Contact hop: Dan Moschuk [Jan 12 13:49:01] list_route: hop: [Jan 12 13:49:01] DEBUG[15234]: chan_sip.c:13365 handle_request_invite: SIP/danmoschuk-1-08466a88: New call is still down.... Trying... [Jan 12 13:49:01] <--- Transmitting (NAT) to 216.221.84.171:5060 ---> SIP/2.0 100 Trying Via: SIP/2.0/UDP 192.168.2.189:5060;branch=z9hG4bK-f9e978cf;received=216.221.84.171 From: Dan Moschuk ;tag=ddd53689f170907bo0 To: Call-ID: 463a221-329f59c3@192.168.2.189 CSeq: 102 INVITE User-Agent: Easy Office Phone Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY Supported: replaces Contact: Content-Length: 0 <------------> [Jan 12 13:49:01] DEBUG[15234]: devicestate.c:303 __ast_device_state_changed_literal: Notification of state change to be queued on device/channel SIP/danmoschuk-1-08466a88 [Jan 12 13:49:01] DEBUG[15214]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for SIP - danmoschuk-1 [Jan 12 13:49:01] DEBUG[15214]: chan_sip.c:15097 sip_devicestate: Checking device state for peer danmoschuk-1 [Jan 12 13:49:01] DEBUG[15214]: devicestate.c:287 do_state_change: Changing state for SIP/danmoschuk-1 - state 1 (Not in use) [Jan 12 13:49:01] DEBUG[15214]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for SIP - danmoschuk-1 [Jan 12 13:49:01] DEBUG[15214]: chan_sip.c:15097 sip_devicestate: Checking device state for peer danmoschuk-1 [Jan 12 13:49:01] DEBUG[15249]: pbx.c:1768 pbx_extension_helper: Launching 'Macro' [Jan 12 13:49:01] -- Executing [9055920255@danmoschuk-ext1-out:1] Macro("SIP/danmoschuk-1-08466a88", "danmoschuk_outbound_init") in new stack [Jan 12 13:49:01] DEBUG[15249]: pbx.c:1768 pbx_extension_helper: Launching 'Macro' [Jan 12 13:49:01] -- Executing [s@macro-danmoschuk_outbound_init:1] Macro("SIP/danmoschuk-1-08466a88", "danmoschuk_global_init") in new stack [Jan 12 13:49:01] DEBUG[15249]: pbx.c:1768 pbx_extension_helper: Launching 'Set' [Jan 12 13:49:01] -- Executing [s@macro-danmoschuk_global_init:1] Set("SIP/danmoschuk-1-08466a88", "CDR(accountcode)=15") in new stack [Jan 12 13:49:01] DEBUG[15249]: pbx.c:1768 pbx_extension_helper: Launching 'Set' [Jan 12 13:49:01] -- Executing [s@macro-danmoschuk_global_init:2] Set("SIP/danmoschuk-1-08466a88", "CHANNEL(musicclass)=classicrock") in new stack [Jan 12 13:49:01] DEBUG[15249]: pbx.c:1768 pbx_extension_helper: Launching 'Set' [Jan 12 13:49:01] -- Executing [s@macro-danmoschuk_outbound_init:2] Set("SIP/danmoschuk-1-08466a88", "CALLERID(all)=DAN MOSCHUK <9053196467>") in new stack [Jan 12 13:49:01] DEBUG[15249]: pbx.c:1768 pbx_extension_helper: Launching 'Goto' [Jan 12 13:49:01] -- Executing [9055920255@danmoschuk-ext1-out:2] Goto("SIP/danmoschuk-1-08466a88", "outgoing|9055920255|1") in new stack [Jan 12 13:49:01] -- Goto (outgoing,9055920255,1) [Jan 12 13:49:01] DEBUG[15249]: pbx.c:1768 pbx_extension_helper: Launching 'Goto' [Jan 12 13:49:01] -- Executing [9055920255@outgoing:1] Goto("SIP/danmoschuk-1-08466a88", "easyofficephone-incoming|9055920255|1") in new stack [Jan 12 13:49:01] -- Goto (easyofficephone-incoming,9055920255,1) [Jan 12 13:49:01] DEBUG[15249]: pbx.c:1768 pbx_extension_helper: Launching 'Macro' [Jan 12 13:49:01] -- Executing [9055920255@easyofficephone-incoming:1] Macro("SIP/danmoschuk-1-08466a88", "easyofficephone_inbound_init|9055920255") in new stack [Jan 12 13:49:01] DEBUG[15249]: pbx.c:1768 pbx_extension_helper: Launching 'Set' [Jan 12 13:49:01] -- Executing [s@macro-easyofficephone_inbound_init:1] Set("SIP/danmoschuk-1-08466a88", "dstdid=9055920255") in new stack [Jan 12 13:49:01] DEBUG[15249]: pbx.c:1768 pbx_extension_helper: Launching 'Macro' [Jan 12 13:49:01] -- Executing [s@macro-easyofficephone_inbound_init:2] Macro("SIP/danmoschuk-1-08466a88", "easyofficephone_global_init") in new stack [Jan 12 13:49:01] DEBUG[15249]: pbx.c:1768 pbx_extension_helper: Launching 'Set' [Jan 12 13:49:01] -- Executing [s@macro-easyofficephone_global_init:1] Set("SIP/danmoschuk-1-08466a88", "CDR(accountcode)=1") in new stack [Jan 12 13:49:01] DEBUG[15249]: pbx.c:1768 pbx_extension_helper: Launching 'Set' [Jan 12 13:49:01] -- Executing [s@macro-easyofficephone_global_init:2] Set("SIP/danmoschuk-1-08466a88", "CHANNEL(musicclass)=easyofficephone") in new stack [Jan 12 13:49:01] DEBUG[15249]: pbx.c:1768 pbx_extension_helper: Launching 'Set' [Jan 12 13:49:01] -- Executing [s@macro-easyofficephone_inbound_init:3] Set("SIP/danmoschuk-1-08466a88", "CDR(userfield)=9055920255") in new stack [Jan 12 13:49:01] DEBUG[15249]: pbx.c:1768 pbx_extension_helper: Launching 'Answer' [Jan 12 13:49:01] -- Executing [s@macro-easyofficephone_inbound_init:4] Answer("SIP/danmoschuk-1-08466a88", "") in new stack [Jan 12 13:49:01] DEBUG[15249]: devicestate.c:303 __ast_device_state_changed_literal: Notification of state change to be queued on device/channel SIP/danmoschuk-1-08466a88 [Jan 12 13:49:01] DEBUG[15214]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for SIP - danmoschuk-1 [Jan 12 13:49:01] DEBUG[15214]: chan_sip.c:15097 sip_devicestate: Checking device state for peer danmoschuk-1 [Jan 12 13:49:01] DEBUG[15214]: devicestate.c:287 do_state_change: Changing state for SIP/danmoschuk-1 - state 1 (Not in use) [Jan 12 13:49:01] DEBUG[15214]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for SIP - danmoschuk-1 [Jan 12 13:49:01] DEBUG[15214]: chan_sip.c:15097 sip_devicestate: Checking device state for peer danmoschuk-1 [Jan 12 13:49:01] DEBUG[15249]: chan_sip.c:3420 sip_answer: SIP answering channel: SIP/danmoschuk-1-08466a88 [Jan 12 13:49:01] DEBUG[15249]: chan_sip.c:6353 transmit_response_with_sdp: Setting framing from config on incoming call [Jan 12 13:49:01] DEBUG[15249]: chan_sip.c:6121 add_sdp: ** Our capability: 0x4 (ulaw) Video flag: True [Jan 12 13:49:01] DEBUG[15249]: chan_sip.c:6122 add_sdp: ** Our prefcodec: 0x0 (nothing) [Jan 12 13:49:01] Audio is at 208.68.92.122 port 15520 [Jan 12 13:49:01] Adding codec 0x4 (ulaw) to SDP [Jan 12 13:49:01] Adding non-codec 0x1 (telephone-event) to SDP [Jan 12 13:49:01] DEBUG[15249]: chan_sip.c:6253 add_sdp: -- Done with adding codecs to SDP [Jan 12 13:49:01] DEBUG[15249]: chan_sip.c:6298 add_sdp: Done building SDP. Settling with this capability: 0x4 (ulaw) [Jan 12 13:49:01] <--- Reliably Transmitting (NAT) to 216.221.84.171:5060 ---> SIP/2.0 200 OK Via: SIP/2.0/UDP 192.168.2.189:5060;branch=z9hG4bK-f9e978cf;received=216.221.84.171 From: Dan Moschuk ;tag=ddd53689f170907bo0 To: ;tag=as1b24eed5 Call-ID: 463a221-329f59c3@192.168.2.189 CSeq: 102 INVITE User-Agent: Easy Office Phone Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY Supported: replaces Contact: Content-Type: application/sdp Content-Length: 242 v=0 o=root 15249 15249 IN IP4 208.68.92.122 s=session c=IN IP4 208.68.92.122 t=0 0 m=audio 15520 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 <------------> [Jan 12 13:49:01] DEBUG[15249]: chan_sip.c:1951 __sip_reliable_xmit: *** SIP TIMER: Initalizing retransmit timer on packet: Id #135 [Jan 12 13:49:01] DEBUG[15249]: pbx.c:1768 pbx_extension_helper: Launching 'Macro' [Jan 12 13:49:01] -- Executing [s@macro-easyofficephone_inbound_init:5] Macro("SIP/danmoschuk-1-08466a88", "debug") in new stack [Jan 12 13:49:01] DEBUG[15249]: pbx.c:1622 pbx_substitute_variables_helper_full: Function result is '"DAN MOSCHUK" <9053196467>' [Jan 12 13:49:01] DEBUG[15249]: pbx.c:1768 pbx_extension_helper: Launching 'NoOp' [Jan 12 13:49:01] -- Executing [s@macro-debug:1] NoOp("SIP/danmoschuk-1-08466a88", "Call from: "DAN MOSCHUK" <9053196467>") in new stack [Jan 12 13:49:01] DEBUG[15249]: pbx.c:1768 pbx_extension_helper: Launching 'Goto' [Jan 12 13:49:01] -- Executing [9055920255@easyofficephone-incoming:2] Goto("SIP/danmoschuk-1-08466a88", "easyofficephone-mainmenu|s|1") in new stack [Jan 12 13:49:01] -- Goto (easyofficephone-mainmenu,s,1) [Jan 12 13:49:01] DEBUG[15249]: pbx.c:1768 pbx_extension_helper: Launching 'BackGround' [Jan 12 13:49:01] -- Executing [s@easyofficephone-mainmenu:1] BackGround("SIP/danmoschuk-1-08466a88", "easyofficephone/mainmenu") in new stack [Jan 12 13:49:01] DEBUG[15249]: rtp.c:2667 ast_rtp_write: Ooh, format changed from unknown to ulaw [Jan 12 13:49:01] DEBUG[15249]: rtp.c:2684 ast_rtp_write: Created smoother: format: 4 ms: 20 len: 160 [Jan 12 13:49:01] -- Playing 'easyofficephone/mainmenu' (language 'en') [Jan 12 13:49:01] DEBUG[15250]: app_queue.c:546 changethread: Device 'SIP/danmoschuk-1' changed to state '1' (Not in use) but we don't care because they're not a member of any queue. [Jan 12 13:49:01] DEBUG[15251]: app_queue.c:546 changethread: Device 'SIP/danmoschuk-1' changed to state '1' (Not in use) but we don't care because they're not a member of any queue. [Jan 12 13:49:01] <--- SIP read from 216.221.84.171:5060 ---> ACK sip:9055920255@208.68.92.122 SIP/2.0 Via: SIP/2.0/UDP 192.168.2.189:5060;branch=z9hG4bK-a284c2fe From: Dan Moschuk ;tag=ddd53689f170907bo0 To: ;tag=as1b24eed5 Call-ID: 463a221-329f59c3@192.168.2.189 CSeq: 102 ACK Max-Forwards: 70 Proxy-Authorization: Digest username="danmoschuk-1",realm="asterisk",nonce="2297c390",uri="sip:9055920255@208.68.92.122",algorithm=MD5,response="258a67319ab788e786a9027c225d725f" Contact: Dan Moschuk User-Agent: Linksys/SPA2102-3.3.5(a) Content-Length: 0 <-------------> [Jan 12 13:49:01] DEBUG[15234]: chan_sip.c:4519 parse_request: Header 0: ACK sip:9055920255@208.68.92.122 SIP/2.0 (40) [Jan 12 13:49:01] DEBUG[15234]: chan_sip.c:4519 parse_request: Header 1: Via: SIP/2.0/UDP 192.168.2.189:5060;branch=z9hG4bK-a284c2fe (59) [Jan 12 13:49:01] DEBUG[15234]: chan_sip.c:4519 parse_request: Header 2: From: Dan Moschuk ;tag=ddd53689f170907bo0 (89) [Jan 12 13:49:01] DEBUG[15234]: chan_sip.c:4519 parse_request: Header 3: To: ;tag=as1b24eed5 (65) [Jan 12 13:49:01] DEBUG[15234]: chan_sip.c:4519 parse_request: Header 4: Call-ID: 463a221-329f59c3@192.168.2.189 (39) [Jan 12 13:49:01] DEBUG[15234]: chan_sip.c:4519 parse_request: Header 5: CSeq: 102 ACK (13) [Jan 12 13:49:01] DEBUG[15234]: chan_sip.c:4519 parse_request: Header 6: Max-Forwards: 70 (16) [Jan 12 13:49:01] DEBUG[15234]: chan_sip.c:4519 parse_request: Header 7: Proxy-Authorization: Digest username="danmoschuk-1",realm="asterisk",nonce="2297c390",uri="sip:9055920255@208.68.92.122",algorithm=MD5,response="258a67319ab788e786a9027c225d725f" (178) [Jan 12 13:49:01] DEBUG[15234]: chan_sip.c:4519 parse_request: Header 8: Contact: Dan Moschuk (59) [Jan 12 13:49:01] DEBUG[15234]: chan_sip.c:4519 parse_request: Header 9: User-Agent: Linksys/SPA2102-3.3.5(a) (36) [Jan 12 13:49:01] DEBUG[15234]: chan_sip.c:4519 parse_request: Header 10: Content-Length: 0 (17) [Jan 12 13:49:01] DEBUG[15234]: chan_sip.c:4519 parse_request: Header 11: (0) [Jan 12 13:49:01] --- (11 headers 0 lines) --- [Jan 12 13:49:01] DEBUG[15234]: chan_sip.c:14502 handle_request: **** Received ACK (6) - Command in SIP ACK [Jan 12 13:49:01] DEBUG[15234]: chan_sip.c:2055 __sip_ack: ** SIP TIMER: Cancelling retransmit of packet (reply received) Retransid #135 [Jan 12 13:49:01] DEBUG[15234]: chan_sip.c:2065 __sip_ack: Stopping retransmission on '463a221-329f59c3@192.168.2.189' of Response 102: Match Not Found [Jan 12 13:49:05] DEBUG[15234]: chan_sip.c:1986 __sip_autodestruct: Auto destroying SIP dialog 'aa6dbb54-b0488f95@24.141.120.117' [Jan 12 13:49:05] DEBUG[15234]: chan_sip.c:3072 sip_destroy: Destroying SIP dialog aa6dbb54-b0488f95@24.141.120.117 [Jan 12 13:49:05] Really destroying SIP dialog 'aa6dbb54-b0488f95@24.141.120.117' Method: REGISTER [Jan 12 13:49:06] DEBUG[15234]: chan_sip.c:1986 __sip_autodestruct: Auto destroying SIP dialog '6dfe66fc-491397f7@192.168.15.101' [Jan 12 13:49:06] DEBUG[15234]: chan_sip.c:3072 sip_destroy: Destroying SIP dialog 6dfe66fc-491397f7@192.168.15.101 [Jan 12 13:49:06] Really destroying SIP dialog '6dfe66fc-491397f7@192.168.15.101' Method: REGISTER [Jan 12 13:49:07] DEBUG[15249]: rtp.c:726 process_rfc2833: - RTP 2833 Event: 00000002 (len = 4) [Jan 12 13:49:07] DEBUG[15249]: rtp.c:625 send_dtmf: Sending dtmf: 50 (2), at 216.221.84.171 [Jan 12 13:49:07] DEBUG[15249]: rtp.c:726 process_rfc2833: - RTP 2833 Event: 00000002 (len = 4) [Jan 12 13:49:07] DEBUG[15249]: rtp.c:726 process_rfc2833: - RTP 2833 Event: 00000002 (len = 4) [Jan 12 13:49:07] DEBUG[15249]: rtp.c:726 process_rfc2833: - RTP 2833 Event: 00000002 (len = 4) [Jan 12 13:49:07] DEBUG[15249]: rtp.c:726 process_rfc2833: - RTP 2833 Event: 00000002 (len = 4) [Jan 12 13:49:07] DEBUG[15249]: rtp.c:625 send_dtmf: Sending dtmf: 50 (2), at 216.221.84.171 [Jan 12 13:49:07] DEBUG[15249]: pbx.c:2349 __ast_pbx_run: Oooh, got something to jump out with ('2')! [Jan 12 13:49:07] DEBUG[15249]: rtp.c:726 process_rfc2833: - RTP 2833 Event: 00000002 (len = 4) [Jan 12 13:49:07] DEBUG[15249]: rtp.c:726 process_rfc2833: - RTP 2833 Event: 00000002 (len = 4) [Jan 12 13:49:07] DEBUG[15234]: chan_sip.c:1986 __sip_autodestruct: Auto destroying SIP dialog '5424c1b8-2e949c93@24.36.121.59' [Jan 12 13:49:07] DEBUG[15234]: chan_sip.c:3072 sip_destroy: Destroying SIP dialog 5424c1b8-2e949c93@24.36.121.59 [Jan 12 13:49:07] Really destroying SIP dialog '5424c1b8-2e949c93@24.36.121.59' Method: REGISTER [Jan 12 13:49:08] DEBUG[15249]: rtp.c:726 process_rfc2833: - RTP 2833 Event: 00000008 (len = 4) [Jan 12 13:49:08] DEBUG[15249]: rtp.c:625 send_dtmf: Sending dtmf: 56 (8), at 216.221.84.171 [Jan 12 13:49:08] DEBUG[15249]: rtp.c:726 process_rfc2833: - RTP 2833 Event: 00000008 (len = 4) [Jan 12 13:49:08] DEBUG[15249]: rtp.c:726 process_rfc2833: - RTP 2833 Event: 00000008 (len = 4) [Jan 12 13:49:08] DEBUG[15249]: rtp.c:726 process_rfc2833: - RTP 2833 Event: 00000008 (len = 4) [Jan 12 13:49:08] DEBUG[15249]: rtp.c:726 process_rfc2833: - RTP 2833 Event: 00000008 (len = 4) [Jan 12 13:49:08] DEBUG[15249]: rtp.c:726 process_rfc2833: - RTP 2833 Event: 00000008 (len = 4) [Jan 12 13:49:08] DEBUG[15249]: rtp.c:625 send_dtmf: Sending dtmf: 56 (8), at 216.221.84.171 [Jan 12 13:49:08] DEBUG[15249]: rtp.c:726 process_rfc2833: - RTP 2833 Event: 00000008 (len = 4) [Jan 12 13:49:08] DEBUG[15249]: rtp.c:726 process_rfc2833: - RTP 2833 Event: 00000008 (len = 4) [Jan 12 13:49:08] DEBUG[15249]: rtp.c:726 process_rfc2833: - RTP 2833 Event: 00000009 (len = 4) [Jan 12 13:49:08] DEBUG[15249]: rtp.c:625 send_dtmf: Sending dtmf: 57 (9), at 216.221.84.171 [Jan 12 13:49:08] DEBUG[15249]: rtp.c:726 process_rfc2833: - RTP 2833 Event: 00000009 (len = 4) [Jan 12 13:49:08] DEBUG[15249]: rtp.c:726 process_rfc2833: - RTP 2833 Event: 00000009 (len = 4) [Jan 12 13:49:08] DEBUG[15249]: rtp.c:726 process_rfc2833: - RTP 2833 Event: 00000009 (len = 4) [Jan 12 13:49:08] DEBUG[15249]: rtp.c:726 process_rfc2833: - RTP 2833 Event: 00000009 (len = 4) [Jan 12 13:49:08] DEBUG[15249]: rtp.c:726 process_rfc2833: - RTP 2833 Event: 00000009 (len = 4) [Jan 12 13:49:08] DEBUG[15249]: rtp.c:625 send_dtmf: Sending dtmf: 57 (9), at 216.221.84.171 [Jan 12 13:49:08] == CDR updated on SIP/danmoschuk-1-08466a88 [Jan 12 13:49:08] DEBUG[15249]: pbx.c:1768 pbx_extension_helper: Launching 'Playback' [Jan 12 13:49:08] -- Executing [289@easyofficephone-mainmenu:1] Playback("SIP/danmoschuk-1-08466a88", "pls-hold-while-try") in new stack [Jan 12 13:49:08] DEBUG[15249]: rtp.c:2537 ast_rtp_raw_write: Difference is 6320, ms is 810 [Jan 12 13:49:08] -- Playing 'pls-hold-while-try' (language 'en') [Jan 12 13:49:08] DEBUG[15249]: rtp.c:726 process_rfc2833: - RTP 2833 Event: 00000009 (len = 4) [Jan 12 13:49:08] DEBUG[15249]: rtp.c:726 process_rfc2833: - RTP 2833 Event: 00000009 (len = 4) [Jan 12 13:49:10] <--- SIP read from 69.157.33.248:60348 ---> REGISTER sip:sipproxy2.easyofficephone.com:5060 SIP/2.0 Via: SIP/2.0/UDP 192.168.2.11;branch=z9hG4bKc3b65a396 Max-Forwards: 70 Content-Length: 0 To: Adam Simpson From: Adam Simpson ;tag=6c624e40ddab302 Call-ID: b5baf5533ee8decc0695bf1312e78e43@192.168.2.11 CSeq: 1088648859 REGISTER Contact: Adam Simpson ;expires=60 Allow-Events: talk,hold,conference Allow:NOTIFY,REFER,OPTIONS,INVITE,ACK,CANCEL,BYE,INFO Authorization:Digest response="9dae5d91546f09272fa9660c091fe57a",username="easyofficephone-289",realm="asterisk",nonce="0c2a77d5",algorithm=MD5,uri="sip:sipproxy2.easyofficephone.com:5060" User-Agent: Aastra 480i Cordless/1.4.1.1077 Brcm Callctrl/1.5 MxSF/v3.2.6.26 <-------------> [Jan 12 13:49:10] DEBUG[15234]: chan_sip.c:4519 parse_request: Header 0: REGISTER sip:sipproxy2.easyofficephone.com:5060 SIP/2.0 (55) [Jan 12 13:49:10] DEBUG[15234]: chan_sip.c:4519 parse_request: Header 1: Via: SIP/2.0/UDP 192.168.2.11;branch=z9hG4bKc3b65a396 (53) [Jan 12 13:49:10] DEBUG[15234]: chan_sip.c:4519 parse_request: Header 2: Max-Forwards: 70 (16) [Jan 12 13:49:10] DEBUG[15234]: chan_sip.c:4519 parse_request: Header 3: Content-Length: 0 (17) [Jan 12 13:49:10] DEBUG[15234]: chan_sip.c:4519 parse_request: Header 4: To: Adam Simpson (77) [Jan 12 13:49:10] DEBUG[15234]: chan_sip.c:4519 parse_request: Header 5: From: Adam Simpson ;tag=6c624e40ddab302 (99) [Jan 12 13:49:10] DEBUG[15234]: chan_sip.c:4519 parse_request: Header 6: Call-ID: b5baf5533ee8decc0695bf1312e78e43@192.168.2.11 (54) [Jan 12 13:49:10] DEBUG[15234]: chan_sip.c:4519 parse_request: Header 7: CSeq: 1088648859 REGISTER (25) [Jan 12 13:49:10] DEBUG[15234]: chan_sip.c:4519 parse_request: Header 8: Contact: Adam Simpson ;expires=60 (71) [Jan 12 13:49:10] DEBUG[15234]: chan_sip.c:4519 parse_request: Header 9: Allow-Events: talk,hold,conference (34) [Jan 12 13:49:10] DEBUG[15234]: chan_sip.c:4519 parse_request: Header 10: Allow:NOTIFY,REFER,OPTIONS,INVITE,ACK,CANCEL,BYE,INFO (53) [Jan 12 13:49:10] DEBUG[15234]: chan_sip.c:4519 parse_request: Header 11: Authorization:Digest response="9dae5d91546f09272fa9660c091fe57a",username="easyofficephone-289",realm="asterisk",nonce="0c2a77d5",algorithm=MD5,uri="sip:sipproxy2.easyofficephone.com:5060" (188) [Jan 12 13:49:10] DEBUG[15234]: chan_sip.c:4519 parse_request: Header 12: User-Agent: Aastra 480i Cordless/1.4.1.1077 Brcm Callctrl/1.5 MxSF/v3.2.6.26 (76) [Jan 12 13:49:10] DEBUG[15234]: chan_sip.c:4519 parse_request: Header 13: (0) [Jan 12 13:49:10] --- (13 headers 0 lines) --- [Jan 12 13:49:10] DEBUG[15234]: chan_sip.c:4256 sip_alloc: Allocating new SIP dialog for b5baf5533ee8decc0695bf1312e78e43@192.168.2.11 - REGISTER (No RTP) [Jan 12 13:49:10] DEBUG[15234]: chan_sip.c:14502 handle_request: **** Received REGISTER (2) - Command in SIP REGISTER [Jan 12 13:49:10] Using latest REGISTER request as basis request [Jan 12 13:49:10] Sending to 192.168.2.11 : 5060 (no NAT) [Jan 12 13:49:10] <--- Transmitting (NAT) to 69.157.33.248:60348 ---> SIP/2.0 100 Trying Via: SIP/2.0/UDP 192.168.2.11;branch=z9hG4bKc3b65a396;received=69.157.33.248 From: Adam Simpson ;tag=6c624e40ddab302 To: Adam Simpson Call-ID: b5baf5533ee8decc0695bf1312e78e43@192.168.2.11 CSeq: 1088648859 REGISTER User-Agent: Easy Office Phone Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY Supported: replaces Contact: Content-Length: 0 <------------> [Jan 12 13:49:10] <--- Transmitting (NAT) to 69.157.33.248:60348 ---> SIP/2.0 401 Unauthorized Via: SIP/2.0/UDP 192.168.2.11;branch=z9hG4bKc3b65a396;received=69.157.33.248 From: Adam Simpson ;tag=6c624e40ddab302 To: Adam Simpson ;tag=as2eef4777 Call-ID: b5baf5533ee8decc0695bf1312e78e43@192.168.2.11 CSeq: 1088648859 REGISTER User-Agent: Easy Office Phone Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY Supported: replaces WWW-Authenticate: Digest algorithm=MD5, realm="asterisk", nonce="5fed1443" Content-Length: 0 <------------> [Jan 12 13:49:10] Scheduling destruction of SIP dialog 'b5baf5533ee8decc0695bf1312e78e43@192.168.2.11' in 32000 ms (Method: REGISTER) [Jan 12 13:49:10] <--- SIP read from 216.221.84.171:5060 ---> NOTIFY sip:sipproxy2.easyofficephone.com SIP/2.0 Via: SIP/2.0/UDP 192.168.2.189:5060;branch=z9hG4bK-e112ea4d From: Dan Moschuk ;tag=5b8238bf642eba9ao0 To: Call-ID: f9e16f13-27b6d856@192.168.2.189 CSeq: 9498 NOTIFY Max-Forwards: 70 Event: keep-alive User-Agent: Linksys/SPA2102-3.3.5(a) Content-Length: 0 <-------------> [Jan 12 13:49:10] DEBUG[15234]: chan_sip.c:4519 parse_request: Header 0: NOTIFY sip:sipproxy2.easyofficephone.com SIP/2.0 (48) [Jan 12 13:49:10] DEBUG[15234]: chan_sip.c:4519 parse_request: Header 1: Via: SIP/2.0/UDP 192.168.2.189:5060;branch=z9hG4bK-e112ea4d (59) [Jan 12 13:49:10] DEBUG[15234]: chan_sip.c:4519 parse_request: Header 2: From: Dan Moschuk ;tag=5b8238bf642eba9ao0 (89) [Jan 12 13:49:10] DEBUG[15234]: chan_sip.c:4519 parse_request: Header 3: To: (39) [Jan 12 13:49:10] DEBUG[15234]: chan_sip.c:4519 parse_request: Header 4: Call-ID: f9e16f13-27b6d856@192.168.2.189 (40) [Jan 12 13:49:10] DEBUG[15234]: chan_sip.c:4519 parse_request: Header 5: CSeq: 9498 NOTIFY (17) [Jan 12 13:49:10] DEBUG[15234]: chan_sip.c:4519 parse_request: Header 6: Max-Forwards: 70 (16) [Jan 12 13:49:10] DEBUG[15234]: chan_sip.c:4519 parse_request: Header 7: Event: keep-alive (17) [Jan 12 13:49:10] DEBUG[15234]: chan_sip.c:4519 parse_request: Header 8: User-Agent: Linksys/SPA2102-3.3.5(a) (36) [Jan 12 13:49:10] DEBUG[15234]: chan_sip.c:4519 parse_request: Header 9: Content-Length: 0 (17) [Jan 12 13:49:10] DEBUG[15234]: chan_sip.c:4519 parse_request: Header 10: (0) [Jan 12 13:49:10] --- (10 headers 0 lines) --- [Jan 12 13:49:10] <--- Transmitting (no NAT) to 216.221.84.171:5060 ---> SIP/2.0 489 Bad event Via: SIP/2.0/UDP 192.168.2.189:5060;branch=z9hG4bK-e112ea4d;received=216.221.84.171 From: Dan Moschuk ;tag=5b8238bf642eba9ao0 To: ;tag=as10d7c179 Call-ID: f9e16f13-27b6d856@192.168.2.189 CSeq: 9498 NOTIFY User-Agent: Easy Office Phone Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY Supported: replaces Content-Length: 0 <------------> [Jan 12 13:49:10] DEBUG[15234]: chan_sip.c:14680 sipsock_read: Invalid SIP message - rejected , no callid, len 400 [Jan 12 13:49:10] DEBUG[15249]: pbx.c:1768 pbx_extension_helper: Launching 'Dial' [Jan 12 13:49:10] -- Executing [289@easyofficephone-mainmenu:2] Dial("SIP/danmoschuk-1-08466a88", "SIP/easyofficephone-289|24|m") in new stack [Jan 12 13:49:10] DEBUG[15249]: chan_sip.c:15155 sip_request_call: Asked to create a SIP channel with formats: 0x4 (ulaw) [Jan 12 13:49:10] DEBUG[15249]: chan_sip.c:4256 sip_alloc: Allocating new SIP dialog for (No Call-ID) - INVITE (With RTP) [Jan 12 13:49:10] DEBUG[15249]: chan_sip.c:2551 do_setnat: Setting NAT on RTP to On [Jan 12 13:49:10] DEBUG[15249]: chan_sip.c:3758 sip_new: *** Our native formats are 0x4 (ulaw) [Jan 12 13:49:10] DEBUG[15249]: chan_sip.c:3759 sip_new: *** Joint capabilities are 0x0 (nothing) [Jan 12 13:49:10] DEBUG[15249]: chan_sip.c:3760 sip_new: *** Our capabilities are 0xc (ulaw|alaw) [Jan 12 13:49:10] DEBUG[15249]: chan_sip.c:3761 sip_new: *** AST_CODEC_CHOOSE formats are 0x4 (ulaw) [Jan 12 13:49:10] DEBUG[15249]: chan_sip.c:3763 sip_new: *** Our preferred formats from the incoming channel are 0x4 (ulaw) [Jan 12 13:49:10] DEBUG[15249]: chan_sip.c:3784 sip_new: This channel will not be able to handle video. [Jan 12 13:49:10] DEBUG[15249]: channel.c:3185 ast_channel_inherit_variables: Not copying variable STACK-easyofficephone-mainmenu-289-2. [Jan 12 13:49:10] DEBUG[15249]: channel.c:3185 ast_channel_inherit_variables: Not copying variable PLAYBACKSTATUS. [Jan 12 13:49:10] DEBUG[15249]: channel.c:3185 ast_channel_inherit_variables: Not copying variable STACK-easyofficephone-mainmenu-289-1. [Jan 12 13:49:10] DEBUG[15249]: channel.c:3185 ast_channel_inherit_variables: Not copying variable STACK-easyofficephone-mainmenu-s-1. [Jan 12 13:49:10] DEBUG[15249]: channel.c:3185 ast_channel_inherit_variables: Not copying variable STACK-easyofficephone-incoming-9055920255-2. [Jan 12 13:49:10] DEBUG[15249]: channel.c:3185 ast_channel_inherit_variables: Not copying variable MACRO_DEPTH. [Jan 12 13:49:10] DEBUG[15249]: channel.c:3185 ast_channel_inherit_variables: Not copying variable STACK-macro-debug-s-1. [Jan 12 13:49:10] DEBUG[15249]: channel.c:3185 ast_channel_inherit_variables: Not copying variable STACK-macro-easyofficephone_inbound_init-s-5. [Jan 12 13:49:10] DEBUG[15249]: channel.c:3185 ast_channel_inherit_variables: Not copying variable STACK-macro-easyofficephone_inbound_init-s-4. [Jan 12 13:49:10] DEBUG[15249]: channel.c:3185 ast_channel_inherit_variables: Not copying variable STACK-macro-easyofficephone_inbound_init-s-3. [Jan 12 13:49:10] DEBUG[15249]: channel.c:3185 ast_channel_inherit_variables: Not copying variable STACK-macro-easyofficephone_global_init-s-2. [Jan 12 13:49:10] DEBUG[15249]: channel.c:3185 ast_channel_inherit_variables: Not copying variable STACK-macro-easyofficephone_global_init-s-1. [Jan 12 13:49:10] DEBUG[15249]: channel.c:3185 ast_channel_inherit_variables: Not copying variable STACK-macro-easyofficephone_inbound_init-s-2. [Jan 12 13:49:10] DEBUG[15249]: channel.c:3185 ast_channel_inherit_variables: Not copying variable dstdid. [Jan 12 13:49:10] DEBUG[15249]: channel.c:3185 ast_channel_inherit_variables: Not copying variable STACK-macro-easyofficephone_inbound_init-s-1. [Jan 12 13:49:10] DEBUG[15249]: channel.c:3185 ast_channel_inherit_variables: Not copying variable STACK-easyofficephone-incoming-9055920255-1. [Jan 12 13:49:10] DEBUG[15249]: channel.c:3185 ast_channel_inherit_variables: Not copying variable STACK-outgoing-9055920255-1. [Jan 12 13:49:10] DEBUG[15249]: channel.c:3185 ast_channel_inherit_variables: Not copying variable STACK-danmoschuk-ext1-out-9055920255-2. [Jan 12 13:49:10] DEBUG[15249]: channel.c:3185 ast_channel_inherit_variables: Not copying variable STACK-macro-danmoschuk_outbound_init-s-2. [Jan 12 13:49:10] DEBUG[15249]: channel.c:3185 ast_channel_inherit_variables: Not copying variable STACK-macro-danmoschuk_global_init-s-2. [Jan 12 13:49:10] DEBUG[15249]: channel.c:3185 ast_channel_inherit_variables: Not copying variable STACK-macro-danmoschuk_global_init-s-1. [Jan 12 13:49:10] DEBUG[15249]: channel.c:3185 ast_channel_inherit_variables: Not copying variable STACK-macro-danmoschuk_outbound_init-s-1. [Jan 12 13:49:10] DEBUG[15249]: channel.c:3185 ast_channel_inherit_variables: Not copying variable STACK-danmoschuk-ext1-out-9055920255-1. [Jan 12 13:49:10] DEBUG[15249]: channel.c:3185 ast_channel_inherit_variables: Not copying variable SIPCALLID. [Jan 12 13:49:10] DEBUG[15249]: channel.c:3185 ast_channel_inherit_variables: Not copying variable SIPUSERAGENT. [Jan 12 13:49:10] DEBUG[15249]: channel.c:3185 ast_channel_inherit_variables: Not copying variable SIPDOMAIN. [Jan 12 13:49:10] DEBUG[15249]: channel.c:3185 ast_channel_inherit_variables: Not copying variable SIPURI. [Jan 12 13:49:10] DEBUG[15249]: chan_sip.c:2804 sip_call: Outgoing Call for easyofficephone-289 [Jan 12 13:49:10] DEBUG[15249]: chan_sip.c:2970 update_call_counter: Updating call counter for outgoing call [Jan 12 13:49:10] DEBUG[15249]: chan_sip.c:2818 sip_call: Our T38 capability (0), joint T38 capability (0) [Jan 12 13:49:10] DEBUG[15249]: chan_sip.c:6121 add_sdp: ** Our capability: 0xc (ulaw|alaw) Video flag: False [Jan 12 13:49:10] DEBUG[15249]: chan_sip.c:6122 add_sdp: ** Our prefcodec: 0x4 (ulaw) [Jan 12 13:49:10] Audio is at 208.68.92.122 port 16794 [Jan 12 13:49:10] Adding codec 0x4 (ulaw) to SDP [Jan 12 13:49:10] Adding codec 0x8 (alaw) to SDP [Jan 12 13:49:10] Adding non-codec 0x1 (telephone-event) to SDP [Jan 12 13:49:10] DEBUG[15249]: chan_sip.c:6253 add_sdp: -- Done with adding codecs to SDP [Jan 12 13:49:10] DEBUG[15249]: chan_sip.c:6298 add_sdp: Done building SDP. Settling with this capability: 0xc (ulaw|alaw) [Jan 12 13:49:10] DEBUG[15249]: chan_sip.c:4519 parse_request: Header 0: INVITE sip:easyofficephone-289@192.168.2.11 SIP/2.0 (51) [Jan 12 13:49:10] DEBUG[15249]: chan_sip.c:4519 parse_request: Header 1: Via: SIP/2.0/UDP 208.68.92.122:5060;branch=z9hG4bK0eaf2539;rport (64) [Jan 12 13:49:10] DEBUG[15249]: chan_sip.c:4519 parse_request: Header 2: From: "DAN MOSCHUK" ;tag=as5f542e73 (65) [Jan 12 13:49:10] DEBUG[15249]: chan_sip.c:4519 parse_request: Header 3: To: (42) [Jan 12 13:49:10] DEBUG[15249]: chan_sip.c:4519 parse_request: Header 4: Contact: (39) [Jan 12 13:49:10] DEBUG[15249]: chan_sip.c:4519 parse_request: Header 5: Call-ID: 33554d704c2ef1490f5962b104aca81b@208.68.92.122 (55) [Jan 12 13:49:10] DEBUG[15249]: chan_sip.c:4519 parse_request: Header 6: CSeq: 102 INVITE (16) [Jan 12 13:49:10] DEBUG[15249]: chan_sip.c:4519 parse_request: Header 7: User-Agent: Easy Office Phone (29) [Jan 12 13:49:10] DEBUG[15249]: chan_sip.c:4519 parse_request: Header 8: Max-Forwards: 70 (16) [Jan 12 13:49:10] DEBUG[15249]: chan_sip.c:4519 parse_request: Header 9: Date: Fri, 12 Jan 2007 18:49:10 GMT (35) [Jan 12 13:49:10] DEBUG[15249]: chan_sip.c:4519 parse_request: Header 10: Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY (66) [Jan 12 13:49:10] DEBUG[15249]: chan_sip.c:4519 parse_request: Header 11: Supported: replaces (19) [Jan 12 13:49:10] DEBUG[15249]: chan_sip.c:4519 parse_request: Header 12: Content-Type: application/sdp (29) [Jan 12 13:49:10] DEBUG[15249]: chan_sip.c:4519 parse_request: Header 13: Content-Length: 266 (19) [Jan 12 13:49:10] DEBUG[15249]: chan_sip.c:4519 parse_request: Header 14: (0) [Jan 12 13:49:10] DEBUG[15249]: chan_sip.c:4551 parse_request: Line: v=0 (3) [Jan 12 13:49:10] DEBUG[15249]: chan_sip.c:4551 parse_request: Line: o=root 15249 15249 IN IP4 208.68.92.122 (39) [Jan 12 13:49:10] DEBUG[15249]: chan_sip.c:4551 parse_request: Line: s=session (9) [Jan 12 13:49:10] DEBUG[15249]: chan_sip.c:4551 parse_request: Line: c=IN IP4 208.68.92.122 (22) [Jan 12 13:49:10] DEBUG[15249]: chan_sip.c:4551 parse_request: Line: t=0 0 (5) [Jan 12 13:49:10] DEBUG[15249]: chan_sip.c:4551 parse_request: Line: m=audio 16794 RTP/AVP 0 8 101 (29) [Jan 12 13:49:10] DEBUG[15249]: chan_sip.c:4551 parse_request: Line: a=rtpmap:0 PCMU/8000 (20) [Jan 12 13:49:10] DEBUG[15249]: chan_sip.c:4551 parse_request: Line: a=rtpmap:8 PCMA/8000 (20) [Jan 12 13:49:10] DEBUG[15249]: chan_sip.c:4551 parse_request: Line: a=rtpmap:101 telephone-event/8000 (33) [Jan 12 13:49:10] DEBUG[15249]: chan_sip.c:4551 parse_request: Line: a=fmtp:101 0-16 (15) [Jan 12 13:49:10] DEBUG[15249]: chan_sip.c:4551 parse_request: Line: a=silenceSupp:off - - - - (25) [Jan 12 13:49:10] DEBUG[15249]: chan_sip.c:4551 parse_request: Line: a=ptime:20 (10) [Jan 12 13:49:10] DEBUG[15249]: chan_sip.c:4551 parse_request: Line: a=sendrecv (10) [Jan 12 13:49:10] Reliably Transmitting (NAT) to 69.157.33.248:60348: INVITE sip:easyofficephone-289@192.168.2.11 SIP/2.0 Via: SIP/2.0/UDP 208.68.92.122:5060;branch=z9hG4bK0eaf2539;rport From: "DAN MOSCHUK" ;tag=as5f542e73 To: Contact: Call-ID: 33554d704c2ef1490f5962b104aca81b@208.68.92.122 CSeq: 102 INVITE User-Agent: Easy Office Phone Max-Forwards: 70 Date: Fri, 12 Jan 2007 18:49:10 GMT Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY Supported: replaces Content-Type: application/sdp Content-Length: 266 v=0 o=root 15249 15249 IN IP4 208.68.92.122 s=session c=IN IP4 208.68.92.122 t=0 0 m=audio 16794 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 12 13:49:10] DEBUG[15249]: chan_sip.c:1951 __sip_reliable_xmit: *** SIP TIMER: Initalizing retransmit timer on packet: Id #138 [Jan 12 13:49:10] -- Called easyofficephone-289 [Jan 12 13:49:10] DEBUG[15249]: channel.c:2731 set_format: Set channel SIP/danmoschuk-1-08466a88 to write format slin [Jan 12 13:49:10] -- Started music on hold, class 'easyofficephone', on channel 'SIP/danmoschuk-1-08466a88' [Jan 12 13:49:10] <--- SIP read from 69.157.33.248:60348 ---> REGISTER sip:sipproxy2.easyofficephone.com:5060 SIP/2.0 Via: SIP/2.0/UDP 192.168.2.11;branch=z9hG4bKd4524f264 Max-Forwards: 70 Content-Length: 0 To: Adam Simpson From: Adam Simpson ;tag=6c624e40ddab302 Call-ID: b5baf5533ee8decc0695bf1312e78e43@192.168.2.11 CSeq: 1088648860 REGISTER Contact: Adam Simpson ;expires=60 Allow-Events: talk,hold,conference Allow:NOTIFY,REFER,OPTIONS,INVITE,ACK,CANCEL,BYE,INFO Authorization:Digest response="5c3efadf464d46a7fb0146af9046cf14",username="easyofficephone-289",realm="asterisk",nonce="5fed1443",algorithm=MD5,uri="sip:sipproxy2.easyofficephone.com:5060" User-Agent: Aastra 480i Cordless/1.4.1.1077 Brcm Callctrl/1.5 MxSF/v3.2.6.26 <-------------> [Jan 12 13:49:10] DEBUG[15234]: chan_sip.c:4519 parse_request: Header 0: REGISTER sip:sipproxy2.easyofficephone.com:5060 SIP/2.0 (55) [Jan 12 13:49:10] DEBUG[15234]: chan_sip.c:4519 parse_request: Header 1: Via: SIP/2.0/UDP 192.168.2.11;branch=z9hG4bKd4524f264 (53) [Jan 12 13:49:10] DEBUG[15234]: chan_sip.c:4519 parse_request: Header 2: Max-Forwards: 70 (16) [Jan 12 13:49:10] DEBUG[15234]: chan_sip.c:4519 parse_request: Header 3: Content-Length: 0 (17) [Jan 12 13:49:10] DEBUG[15234]: chan_sip.c:4519 parse_request: Header 4: To: Adam Simpson (77) [Jan 12 13:49:10] DEBUG[15234]: chan_sip.c:4519 parse_request: Header 5: From: Adam Simpson ;tag=6c624e40ddab302 (99) [Jan 12 13:49:10] DEBUG[15234]: chan_sip.c:4519 parse_request: Header 6: Call-ID: b5baf5533ee8decc0695bf1312e78e43@192.168.2.11 (54) [Jan 12 13:49:10] DEBUG[15234]: chan_sip.c:4519 parse_request: Header 7: CSeq: 1088648860 REGISTER (25) [Jan 12 13:49:10] DEBUG[15234]: chan_sip.c:4519 parse_request: Header 8: Contact: Adam Simpson ;expires=60 (71) [Jan 12 13:49:10] DEBUG[15234]: chan_sip.c:4519 parse_request: Header 9: Allow-Events: talk,hold,conference (34) [Jan 12 13:49:10] DEBUG[15234]: chan_sip.c:4519 parse_request: Header 10: Allow:NOTIFY,REFER,OPTIONS,INVITE,ACK,CANCEL,BYE,INFO (53) [Jan 12 13:49:10] DEBUG[15234]: chan_sip.c:4519 parse_request: Header 11: Authorization:Digest response="5c3efadf464d46a7fb0146af9046cf14",username="easyofficephone-289",realm="asterisk",nonce="5fed1443",algorithm=MD5,uri="sip:sipproxy2.easyofficephone.com:5060" (188) [Jan 12 13:49:10] DEBUG[15234]: chan_sip.c:4519 parse_request: Header 12: User-Agent: Aastra 480i Cordless/1.4.1.1077 Brcm Callctrl/1.5 MxSF/v3.2.6.26 (76) [Jan 12 13:49:10] DEBUG[15234]: chan_sip.c:4519 parse_request: Header 13: (0) [Jan 12 13:49:10] --- (13 headers 0 lines) --- [Jan 12 13:49:10] DEBUG[15234]: chan_sip.c:14502 handle_request: **** Received REGISTER (2) - Command in SIP REGISTER [Jan 12 13:49:10] Using latest REGISTER request as basis request [Jan 12 13:49:10] Sending to 69.157.33.248 : 60348 (NAT) [Jan 12 13:49:10] <--- Transmitting (NAT) to 69.157.33.248:60348 ---> SIP/2.0 100 Trying Via: SIP/2.0/UDP 192.168.2.11;branch=z9hG4bKd4524f264;received=69.157.33.248 From: Adam Simpson ;tag=6c624e40ddab302 To: Adam Simpson Call-ID: b5baf5533ee8decc0695bf1312e78e43@192.168.2.11 CSeq: 1088648860 REGISTER User-Agent: Easy Office Phone Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY Supported: replaces Contact: Content-Length: 0 <------------> [Jan 12 13:49:10] <--- Transmitting (NAT) to 69.157.33.248:60348 ---> SIP/2.0 200 OK Via: SIP/2.0/UDP 192.168.2.11;branch=z9hG4bKd4524f264;received=69.157.33.248 From: Adam Simpson ;tag=6c624e40ddab302 To: Adam Simpson ;tag=as2eef4777 Call-ID: b5baf5533ee8decc0695bf1312e78e43@192.168.2.11 CSeq: 1088648860 REGISTER User-Agent: Easy Office Phone Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY Supported: replaces Expires: 60 Contact: ;expires=60 Date: Fri, 12 Jan 2007 18:49:10 GMT Content-Length: 0 <------------> [Jan 12 13:49:10] DEBUG[15234]: devicestate.c:303 __ast_device_state_changed_literal: Notification of state change to be queued on device/channel SIP/easyofficephone-289 [Jan 12 13:49:10] Scheduling destruction of SIP dialog 'b5baf5533ee8decc0695bf1312e78e43@192.168.2.11' in 32000 ms (Method: REGISTER) [Jan 12 13:49:10] DEBUG[15214]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for SIP - easyofficephone [Jan 12 13:49:10] DEBUG[15214]: chan_sip.c:15097 sip_devicestate: Checking device state for peer easyofficephone [Jan 12 13:49:10] DEBUG[15214]: devicestate.c:287 do_state_change: Changing state for SIP/easyofficephone - state 4 (Invalid) [Jan 12 13:49:10] DEBUG[15252]: app_queue.c:546 changethread: Device 'SIP/easyofficephone' changed to state '4' (Invalid) but we don't care because they're not a member of any queue. [Jan 12 13:49:10] DEBUG[15249]: rtp.c:2537 ast_rtp_raw_write: Difference is 1240, ms is 175 [Jan 12 13:49:10] <--- SIP read from 69.157.33.248:60348 ---> SIP/2.0 100 Trying Call-ID: 33554d704c2ef1490f5962b104aca81b@208.68.92.122 CSeq: 102 INVITE From: "DAN MOSCHUK" ;tag=as5f542e73 To: ;tag=229e7ae9e0bb111 Via: SIP/2.0/UDP 208.68.92.122:5060;branch=z9hG4bK0eaf2539;rport Content-Length: 0 User-Agent: Aastra 480i Cordless/1.4.1.1077 Brcm Callctrl/1.5 MxSF/v3.2.6.26 <-------------> [Jan 12 13:49:10] DEBUG[15234]: chan_sip.c:4519 parse_request: Header 0: SIP/2.0 100 Trying (18) [Jan 12 13:49:10] DEBUG[15234]: chan_sip.c:4519 parse_request: Header 1: Call-ID: 33554d704c2ef1490f5962b104aca81b@208.68.92.122 (55) [Jan 12 13:49:10] DEBUG[15234]: chan_sip.c:4519 parse_request: Header 2: CSeq: 102 INVITE (16) [Jan 12 13:49:10] DEBUG[15234]: chan_sip.c:4519 parse_request: Header 3: From: "DAN MOSCHUK" ;tag=as5f542e73 (65) [Jan 12 13:49:10] DEBUG[15234]: chan_sip.c:4519 parse_request: Header 4: To: ;tag=229e7ae9e0bb111 (62) [Jan 12 13:49:10] DEBUG[15234]: chan_sip.c:4519 parse_request: Header 5: Via: SIP/2.0/UDP 208.68.92.122:5060;branch=z9hG4bK0eaf2539;rport (64) [Jan 12 13:49:10] DEBUG[15234]: chan_sip.c:4519 parse_request: Header 6: Content-Length: 0 (17) [Jan 12 13:49:10] DEBUG[15234]: chan_sip.c:4519 parse_request: Header 7: User-Agent: Aastra 480i Cordless/1.4.1.1077 Brcm Callctrl/1.5 MxSF/v3.2.6.26 (76) [Jan 12 13:49:10] DEBUG[15234]: chan_sip.c:4519 parse_request: Header 8: (0) [Jan 12 13:49:10] --- (8 headers 0 lines) --- [Jan 12 13:49:10] DEBUG[15234]: chan_sip.c:2098 __sip_semi_ack: *** SIP TIMER: Cancelling retransmission #138 - INVITE (got response) [Jan 12 13:49:10] DEBUG[15234]: chan_sip.c:2107 __sip_semi_ack: (Provisional) Stopping retransmission (but retaining packet) on '33554d704c2ef1490f5962b104aca81b@208.68.92.122' Request 102: Found [Jan 12 13:49:10] DEBUG[15234]: chan_sip.c:11539 handle_response_invite: SIP response 100 to standard invite [Jan 12 13:49:11] DEBUG[15249]: rtp.c:2537 ast_rtp_raw_write: Difference is 888, ms is 131 [Jan 12 13:49:11] <--- SIP read from 69.157.33.248:60348 ---> SIP/2.0 180 Ringing Call-ID: 33554d704c2ef1490f5962b104aca81b@208.68.92.122 CSeq: 102 INVITE From: "DAN MOSCHUK" ;tag=as5f542e73 To: ;tag=229e7ae9e0bb111 Via: SIP/2.0/UDP 208.68.92.122:5060;branch=z9hG4bK0eaf2539;rport Content-Length: 0 Allow-Events: talk, hold, conference Contact: User-Agent: Aastra 480i Cordless/1.4.1.1077 Brcm Callctrl/1.5 MxSF/v3.2.6.26 <-------------> [Jan 12 13:49:11] DEBUG[15234]: chan_sip.c:4519 parse_request: Header 0: SIP/2.0 180 Ringing (19) [Jan 12 13:49:11] DEBUG[15234]: chan_sip.c:4519 parse_request: Header 1: Call-ID: 33554d704c2ef1490f5962b104aca81b@208.68.92.122 (55) [Jan 12 13:49:11] DEBUG[15234]: chan_sip.c:4519 parse_request: Header 2: CSeq: 102 INVITE (16) [Jan 12 13:49:11] DEBUG[15234]: chan_sip.c:4519 parse_request: Header 3: From: "DAN MOSCHUK" ;tag=as5f542e73 (65) [Jan 12 13:49:11] DEBUG[15234]: chan_sip.c:4519 parse_request: Header 4: To: ;tag=229e7ae9e0bb111 (62) [Jan 12 13:49:11] DEBUG[15234]: chan_sip.c:4519 parse_request: Header 5: Via: SIP/2.0/UDP 208.68.92.122:5060;branch=z9hG4bK0eaf2539;rport (64) [Jan 12 13:49:11] DEBUG[15234]: chan_sip.c:4519 parse_request: Header 6: Content-Length: 0 (17) [Jan 12 13:49:11] DEBUG[15234]: chan_sip.c:4519 parse_request: Header 7: Allow-Events: talk, hold, conference (36) [Jan 12 13:49:11] DEBUG[15234]: chan_sip.c:4519 parse_request: Header 8: Contact: (47) [Jan 12 13:49:11] DEBUG[15234]: chan_sip.c:4519 parse_request: Header 9: User-Agent: Aastra 480i Cordless/1.4.1.1077 Brcm Callctrl/1.5 MxSF/v3.2.6.26 (76) [Jan 12 13:49:11] DEBUG[15234]: chan_sip.c:4519 parse_request: Header 10: (0) [Jan 12 13:49:11] --- (10 headers 0 lines) --- [Jan 12 13:49:11] DEBUG[15234]: chan_sip.c:2107 __sip_semi_ack: (Provisional) Stopping retransmission (but retaining packet) on '33554d704c2ef1490f5962b104aca81b@208.68.92.122' Request 102: Found [Jan 12 13:49:11] DEBUG[15234]: chan_sip.c:11539 handle_response_invite: SIP response 180 to standard invite [Jan 12 13:49:11] DEBUG[15234]: devicestate.c:303 __ast_device_state_changed_literal: Notification of state change to be queued on device/channel SIP/easyofficephone-289-083eb088 [Jan 12 13:49:11] -- SIP/easyofficephone-289-083eb088 is ringing [Jan 12 13:49:11] DEBUG[15214]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for SIP - easyofficephone-289 [Jan 12 13:49:11] DEBUG[15214]: chan_sip.c:15097 sip_devicestate: Checking device state for peer easyofficephone-289 [Jan 12 13:49:11] DEBUG[15214]: devicestate.c:287 do_state_change: Changing state for SIP/easyofficephone-289 - state 1 (Not in use) [Jan 12 13:49:11] DEBUG[15214]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for SIP - easyofficephone-289 [Jan 12 13:49:11] DEBUG[15214]: chan_sip.c:15097 sip_devicestate: Checking device state for peer easyofficephone-289 [Jan 12 13:49:11] DEBUG[15253]: app_queue.c:546 changethread: Device 'SIP/easyofficephone-289' changed to state '1' (Not in use) but we don't care because they're not a member of any queue. [Jan 12 13:49:11] DEBUG[15249]: rtp.c:2537 ast_rtp_raw_write: Difference is 1288, ms is 181 [Jan 12 13:49:11] DEBUG[15249]: rtp.c:2537 ast_rtp_raw_write: Difference is 1448, ms is 201 [Jan 12 13:49:12] DEBUG[15249]: rtp.c:2537 ast_rtp_raw_write: Difference is 1152, ms is 164 [Jan 12 13:49:12] DEBUG[15249]: rtp.c:2537 ast_rtp_raw_write: Difference is 1176, ms is 167 [Jan 12 13:49:12] DEBUG[15249]: rtp.c:2537 ast_rtp_raw_write: Difference is 640, ms is 100 [Jan 12 13:49:12] DEBUG[15249]: rtp.c:2537 ast_rtp_raw_write: Difference is 736, ms is 112 [Jan 12 13:49:12] <--- SIP read from 64.15.136.207:5060 ---> OPTIONS sip:star69.clearphase.net SIP/2.0 Via: SIP/2.0/UDP 64.15.136.207:5060;branch=z9hG4bK32b28ac9;rport From: "asterisk" ;tag=as7a13fe47 To: Contact: Call-ID: 438023bb35eca9db75c918a009c7f34c@64.15.136.207 CSeq: 102 OPTIONS User-Agent: Easy Office Phone Max-Forwards: 70 Date: Fri, 12 Jan 2007 18:49:12 GMT Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY Content-Length: 0 <-------------> [Jan 12 13:49:12] DEBUG[15234]: chan_sip.c:4519 parse_request: Header 0: OPTIONS sip:star69.clearphase.net SIP/2.0 (41) [Jan 12 13:49:12] DEBUG[15234]: chan_sip.c:4519 parse_request: Header 1: Via: SIP/2.0/UDP 64.15.136.207:5060;branch=z9hG4bK32b28ac9;rport (64) [Jan 12 13:49:12] DEBUG[15234]: chan_sip.c:4519 parse_request: Header 2: From: "asterisk" ;tag=as7a13fe47 (60) [Jan 12 13:49:12] DEBUG[15234]: chan_sip.c:4519 parse_request: Header 3: To: (31) [Jan 12 13:49:12] DEBUG[15234]: chan_sip.c:4519 parse_request: Header 4: Contact: (37) [Jan 12 13:49:12] DEBUG[15234]: chan_sip.c:4519 parse_request: Header 5: Call-ID: 438023bb35eca9db75c918a009c7f34c@64.15.136.207 (55) [Jan 12 13:49:12] DEBUG[15234]: chan_sip.c:4519 parse_request: Header 6: CSeq: 102 OPTIONS (17) [Jan 12 13:49:12] DEBUG[15234]: chan_sip.c:4519 parse_request: Header 7: User-Agent: Easy Office Phone (29) [Jan 12 13:49:12] DEBUG[15234]: chan_sip.c:4519 parse_request: Header 8: Max-Forwards: 70 (16) [Jan 12 13:49:12] DEBUG[15234]: chan_sip.c:4519 parse_request: Header 9: Date: Fri, 12 Jan 2007 18:49:12 GMT (35) [Jan 12 13:49:12] DEBUG[15234]: chan_sip.c:4519 parse_request: Header 10: Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY (66) [Jan 12 13:49:12] DEBUG[15234]: chan_sip.c:4519 parse_request: Header 11: Content-Length: 0 (17) [Jan 12 13:49:12] DEBUG[15234]: chan_sip.c:4519 parse_request: Header 12: (0) [Jan 12 13:49:12] --- (12 headers 0 lines) --- [Jan 12 13:49:12] DEBUG[15234]: chan_sip.c:4256 sip_alloc: Allocating new SIP dialog for 438023bb35eca9db75c918a009c7f34c@64.15.136.207 - OPTIONS (No RTP) [Jan 12 13:49:12] DEBUG[15234]: chan_sip.c:14502 handle_request: **** Received OPTIONS (3) - Command in SIP OPTIONS [Jan 12 13:49:12] Looking for s in default (domain star69.clearphase.net) [Jan 12 13:49:12] <--- Transmitting (no NAT) to 64.15.136.207:5060 ---> SIP/2.0 200 OK Via: SIP/2.0/UDP 64.15.136.207:5060;branch=z9hG4bK32b28ac9;received=64.15.136.207;rport=5060 From: "asterisk" ;tag=as7a13fe47 To: ;tag=as45eacfe8 Call-ID: 438023bb35eca9db75c918a009c7f34c@64.15.136.207 CSeq: 102 OPTIONS User-Agent: Easy Office Phone Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY Supported: replaces Contact: Accept: application/sdp Content-Length: 0 <------------> [Jan 12 13:49:12] Scheduling destruction of SIP dialog '438023bb35eca9db75c918a009c7f34c@64.15.136.207' in 32000 ms (Method: OPTIONS) [Jan 12 13:49:12] <--- SIP read from 69.157.33.248:60348 ---> SIP/2.0 200 OK Call-ID: 33554d704c2ef1490f5962b104aca81b@208.68.92.122 CSeq: 102 INVITE From: "DAN MOSCHUK" ;tag=as5f542e73 To: ;tag=229e7ae9e0bb111 Via: SIP/2.0/UDP 208.68.92.122:5060;branch=z9hG4bK0eaf2539;rport Content-Length: 253 Allow-Events: talk,hold,conference Allow:NOTIFY,REFER,OPTIONS,INVITE,ACK,CANCEL,BYE,INFO Content-Type: application/sdp Supported: replaces Contact: User-Agent: Aastra 480i Cordless/1.4.1.1077 Brcm Callctrl/1.5 MxSF/v3.2.6.26 v=0 o=MxSIP 0 765617140 IN IP4 192.168.2.11 s=SIP Call c=IN IP4 192.168.2.11 t=0 0 m=audio 3000 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:20 a=silenceSupp:off - - - - <-------------> [Jan 12 13:49:12] DEBUG[15234]: chan_sip.c:4519 parse_request: Header 0: SIP/2.0 200 OK (14) [Jan 12 13:49:12] DEBUG[15234]: chan_sip.c:4519 parse_request: Header 1: Call-ID: 33554d704c2ef1490f5962b104aca81b@208.68.92.122 (55) [Jan 12 13:49:12] DEBUG[15234]: chan_sip.c:4519 parse_request: Header 2: CSeq: 102 INVITE (16) [Jan 12 13:49:12] DEBUG[15234]: chan_sip.c:4519 parse_request: Header 3: From: "DAN MOSCHUK" ;tag=as5f542e73 (65) [Jan 12 13:49:12] DEBUG[15234]: chan_sip.c:4519 parse_request: Header 4: To: ;tag=229e7ae9e0bb111 (62) [Jan 12 13:49:12] DEBUG[15234]: chan_sip.c:4519 parse_request: Header 5: Via: SIP/2.0/UDP 208.68.92.122:5060;branch=z9hG4bK0eaf2539;rport (64) [Jan 12 13:49:12] DEBUG[15234]: chan_sip.c:4519 parse_request: Header 6: Content-Length: 253 (19) [Jan 12 13:49:12] DEBUG[15234]: chan_sip.c:4519 parse_request: Header 7: Allow-Events: talk,hold,conference (34) [Jan 12 13:49:12] DEBUG[15234]: chan_sip.c:4519 parse_request: Header 8: Allow:NOTIFY,REFER,OPTIONS,INVITE,ACK,CANCEL,BYE,INFO (53) [Jan 12 13:49:12] DEBUG[15234]: chan_sip.c:4519 parse_request: Header 9: Content-Type: application/sdp (29) [Jan 12 13:49:12] DEBUG[15234]: chan_sip.c:4519 parse_request: Header 10: Supported: replaces (19) [Jan 12 13:49:12] DEBUG[15234]: chan_sip.c:4519 parse_request: Header 11: Contact: (47) [Jan 12 13:49:12] DEBUG[15234]: chan_sip.c:4519 parse_request: Header 12: User-Agent: Aastra 480i Cordless/1.4.1.1077 Brcm Callctrl/1.5 MxSF/v3.2.6.26 (76) [Jan 12 13:49:12] DEBUG[15234]: chan_sip.c:4519 parse_request: Header 13: (0) [Jan 12 13:49:12] DEBUG[15234]: chan_sip.c:4551 parse_request: Line: v=0 (3) [Jan 12 13:49:12] DEBUG[15234]: chan_sip.c:4551 parse_request: Line: o=MxSIP 0 765617140 IN IP4 192.168.2.11 (39) [Jan 12 13:49:12] DEBUG[15234]: chan_sip.c:4551 parse_request: Line: s=SIP Call (10) [Jan 12 13:49:12] DEBUG[15234]: chan_sip.c:4551 parse_request: Line: c=IN IP4 192.168.2.11 (21) [Jan 12 13:49:12] DEBUG[15234]: chan_sip.c:4551 parse_request: Line: t=0 0 (5) [Jan 12 13:49:12] DEBUG[15234]: chan_sip.c:4551 parse_request: Line: m=audio 3000 RTP/AVP 0 8 101 (28) [Jan 12 13:49:12] DEBUG[15234]: chan_sip.c:4551 parse_request: Line: a=rtpmap:0 PCMU/8000 (20) [Jan 12 13:49:12] DEBUG[15234]: chan_sip.c:4551 parse_request: Line: a=rtpmap:8 PCMA/8000 (20) [Jan 12 13:49:12] DEBUG[15234]: chan_sip.c:4551 parse_request: Line: a=rtpmap:101 telephone-event/8000 (33) [Jan 12 13:49:12] DEBUG[15234]: chan_sip.c:4551 parse_request: Line: a=fmtp:101 0-15 (15) [Jan 12 13:49:12] DEBUG[15234]: chan_sip.c:4551 parse_request: Line: a=ptime:20 (10) [Jan 12 13:49:12] DEBUG[15234]: chan_sip.c:4551 parse_request: Line: a=silenceSupp:off - - - - (25) [Jan 12 13:49:12] --- (13 headers 12 lines) --- [Jan 12 13:49:12] DEBUG[15234]: chan_sip.c:2047 __sip_ack: Acked pending invite 102 [Jan 12 13:49:12] DEBUG[15234]: chan_sip.c:2065 __sip_ack: Stopping retransmission on '33554d704c2ef1490f5962b104aca81b@208.68.92.122' of Request 102: Match Not Found [Jan 12 13:49:12] DEBUG[15234]: chan_sip.c:11539 handle_response_invite: SIP response 200 to standard invite [Jan 12 13:49:12] Found RTP audio format 0 [Jan 12 13:49:12] Found RTP audio format 8 [Jan 12 13:49:12] Found RTP audio format 101 [Jan 12 13:49:12] Peer audio RTP is at port 192.168.2.11:3000 [Jan 12 13:49:12] Found description format PCMU for ID 0 [Jan 12 13:49:12] Found description format PCMA for ID 8 [Jan 12 13:49:12] Found description format telephone-event for ID 101 [Jan 12 13:49:12] Got unsupported a:fmtp in SDP offer [Jan 12 13:49:12] DEBUG[15234]: chan_sip.c:5062 process_sdp: T38 state changed to 0 on channel SIP/easyofficephone-289-083eb088 [Jan 12 13:49:12] Capabilities: us - 0xc (ulaw|alaw), peer - audio=0xc (ulaw|alaw)/video=0x0 (nothing), combined - 0xc (ulaw|alaw) [Jan 12 13:49:12] Non-codec capabilities (dtmf): us - 0x1 (telephone-event), peer - 0x1 (telephone-event), combined - 0x1 (telephone-event) [Jan 12 13:49:12] Peer audio RTP is at port 192.168.2.11:3000 [Jan 12 13:49:12] DEBUG[15234]: chan_sip.c:5139 process_sdp: We're settling with these formats: 0xc (ulaw|alaw) [Jan 12 13:49:12] DEBUG[15234]: chan_sip.c:5146 process_sdp: We have an owner, now see if we need to change this call [Jan 12 13:49:12] DEBUG[15234]: chan_sip.c:2970 update_call_counter: Updating call counter for outgoing call [Jan 12 13:49:12] DEBUG[15234]: chan_sip.c:7894 build_route: build_route: Contact hop: [Jan 12 13:49:12] list_route: hop: [Jan 12 13:49:12] DEBUG[15234]: chan_sip.c:5576 reqprep: Strict routing enforced for session 33554d704c2ef1490f5962b104aca81b@208.68.92.122 [Jan 12 13:49:12] set_destination: Parsing for address/port to send to [Jan 12 13:49:12] set_destination: set destination to 192.168.2.11, port 5060 [Jan 12 13:49:12] Transmitting (NAT) to 69.157.33.248:60348: ACK sip:easyofficephone-289@192.168.2.11 SIP/2.0 Via: SIP/2.0/UDP 208.68.92.122:5060;branch=z9hG4bK45ba8eda;rport From: "DAN MOSCHUK" ;tag=as5f542e73 To: ;tag=229e7ae9e0bb111 Contact: Call-ID: 33554d704c2ef1490f5962b104aca81b@208.68.92.122 CSeq: 102 ACK User-Agent: Easy Office Phone Max-Forwards: 70 Content-Length: 0 --- [Jan 12 13:49:12] DEBUG[15249]: devicestate.c:303 __ast_device_state_changed_literal: Notification of state change to be queued on device/channel SIP/easyofficephone-289-083eb088 [Jan 12 13:49:12] -- SIP/easyofficephone-289-083eb088 answered SIP/danmoschuk-1-08466a88 [Jan 12 13:49:12] DEBUG[15214]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for SIP - easyofficephone-289 [Jan 12 13:49:12] DEBUG[15214]: chan_sip.c:15097 sip_devicestate: Checking device state for peer easyofficephone-289 [Jan 12 13:49:12] DEBUG[15249]: channel.c:2731 set_format: Set channel SIP/danmoschuk-1-08466a88 to write format ulaw [Jan 12 13:49:12] -- Stopped music on hold on SIP/danmoschuk-1-08466a88 [Jan 12 13:49:12] DEBUG[15214]: devicestate.c:287 do_state_change: Changing state for SIP/easyofficephone-289 - state 1 (Not in use) [Jan 12 13:49:12] -- Packet2Packet bridging SIP/danmoschuk-1-08466a88 and SIP/easyofficephone-289-083eb088 [Jan 12 13:49:12] DEBUG[15214]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for SIP - easyofficephone-289 [Jan 12 13:49:12] DEBUG[15214]: chan_sip.c:15097 sip_devicestate: Checking device state for peer easyofficephone-289 [Jan 12 13:49:12] DEBUG[15254]: app_queue.c:546 changethread: Device 'SIP/easyofficephone-289' changed to state '1' (Not in use) but we don't care because they're not a member of any queue. [Jan 12 13:49:12] DEBUG[15249]: rtp.c:2667 ast_rtp_write: Ooh, format changed from unknown to ulaw [Jan 12 13:49:12] DEBUG[15249]: rtp.c:2684 ast_rtp_write: Created smoother: format: 4 ms: 20 len: 160 [Jan 12 13:49:12] DEBUG[15249]: rtp.c:1148 ast_rtp_read: RTP NAT: Got audio from other end. Now sending to address 69.157.33.248:60007 [Jan 12 13:49:13] Scheduling destruction of SIP dialog 'fc677395-226bcce2@10.0.0.3' in 32000 ms (Method: REGISTER) [Jan 12 13:49:18] DEBUG[15234]: chan_sip.c:1951 __sip_reliable_xmit: *** SIP TIMER: Initalizing retransmit timer on packet: Id #148 [Jan 12 13:49:18] DEBUG[15234]: chan_sip.c:4256 sip_alloc: Allocating new SIP dialog for (No Call-ID) - NOTIFY (No RTP) [Jan 12 13:49:18] Scheduling destruction of SIP dialog '4d28bd582571370f21c89afe54f558f8@208.68.92.122' in 18048 ms (Method: NOTIFY) [Jan 12 13:49:18] DEBUG[15234]: chan_sip.c:4519 parse_request: Header 0: NOTIFY sip:easyofficephone-289@192.168.2.11 SIP/2.0 (51) [Jan 12 13:49:18] DEBUG[15234]: chan_sip.c:4519 parse_request: Header 1: Via: SIP/2.0/UDP 208.68.92.122:5060;branch=z9hG4bK22e88d38;rport (64) [Jan 12 13:49:18] DEBUG[15234]: chan_sip.c:4519 parse_request: Header 2: From: "asterisk" ;tag=as2e97fbeb (60) [Jan 12 13:49:18] DEBUG[15234]: chan_sip.c:4519 parse_request: Header 3: To: (42) [Jan 12 13:49:18] DEBUG[15234]: chan_sip.c:4519 parse_request: Header 4: Contact: (37) [Jan 12 13:49:18] DEBUG[15234]: chan_sip.c:4519 parse_request: Header 5: Call-ID: 4d28bd582571370f21c89afe54f558f8@208.68.92.122 (55) [Jan 12 13:49:18] DEBUG[15234]: chan_sip.c:4519 parse_request: Header 6: CSeq: 102 NOTIFY (16) [Jan 12 13:49:18] DEBUG[15234]: chan_sip.c:4519 parse_request: Header 7: User-Agent: Easy Office Phone (29) [Jan 12 13:49:18] DEBUG[15234]: chan_sip.c:4519 parse_request: Header 8: Max-Forwards: 70 (16) [Jan 12 13:49:18] DEBUG[15234]: chan_sip.c:4519 parse_request: Header 9: Event: message-summary (22) [Jan 12 13:49:18] DEBUG[15234]: chan_sip.c:4519 parse_request: Header 10: Content-Type: application/simple-message-summary (48) [Jan 12 13:49:18] DEBUG[15234]: chan_sip.c:4519 parse_request: Header 11: Content-Length: 94 (18) [Jan 12 13:49:18] DEBUG[15234]: chan_sip.c:4519 parse_request: Header 12: (0) [Jan 12 13:49:18] DEBUG[15234]: chan_sip.c:4551 parse_request: Line: Messages-Waiting: no (20) [Jan 12 13:49:18] DEBUG[15234]: chan_sip.c:4551 parse_request: Line: Message-Account: sip:asterisk@208.68.92.122 (43) [Jan 12 13:49:18] DEBUG[15234]: chan_sip.c:4551 parse_request: Line: Voice-Message: 0/17 (0/0) (25) [Jan 12 13:49:18] Reliably Transmitting (NAT) to 69.157.33.248:60348: NOTIFY sip:easyofficephone-289@192.168.2.11 SIP/2.0 Via: SIP/2.0/UDP 208.68.92.122:5060;branch=z9hG4bK22e88d38;rport From: "asterisk" ;tag=as2e97fbeb To: Contact: Call-ID: 4d28bd582571370f21c89afe54f558f8@208.68.92.122 CSeq: 102 NOTIFY User-Agent: Easy Office Phone Max-Forwards: 70 Event: message-summary Content-Type: application/simple-message-summary Content-Length: 94 Messages-Waiting: no Message-Account: sip:asterisk@208.68.92.122 Voice-Message: 0/17 (0/0) --- [Jan 12 13:49:18] DEBUG[15234]: chan_sip.c:1951 __sip_reliable_xmit: *** SIP TIMER: Initalizing retransmit timer on packet: Id #150 [Jan 12 13:49:18] <--- SIP read from 24.36.39.16:5060 ---> SIP/2.0 200 OK To: ;tag=54bf710a10986699i0 From: "asterisk" ;tag=as243cedef Call-ID: 7190851d0b1c6cb5635d90041b6372a0@208.68.92.122 CSeq: 102 NOTIFY Via: SIP/2.0/UDP 208.68.92.122:5060;branch=z9hG4bK374a07ba Server: Linksys/SPA2100-3.3.6 Content-Length: 0 <-------------> [Jan 12 13:49:18] DEBUG[15234]: chan_sip.c:4519 parse_request: Header 0: SIP/2.0 200 OK (14) [Jan 12 13:49:18] DEBUG[15234]: chan_sip.c:4519 parse_request: Header 1: To: ;tag=54bf710a10986699i0 (62) [Jan 12 13:49:18] DEBUG[15234]: chan_sip.c:4519 parse_request: Header 2: From: "asterisk" ;tag=as243cedef (60) [Jan 12 13:49:18] DEBUG[15234]: chan_sip.c:4519 parse_request: Header 3: Call-ID: 7190851d0b1c6cb5635d90041b6372a0@208.68.92.122 (55) [Jan 12 13:49:18] DEBUG[15234]: chan_sip.c:4519 parse_request: Header 4: CSeq: 102 NOTIFY (16) [Jan 12 13:49:18] DEBUG[15234]: chan_sip.c:4519 parse_request: Header 5: Via: SIP/2.0/UDP 208.68.92.122:5060;branch=z9hG4bK374a07ba (58) [Jan 12 13:49:18] DEBUG[15234]: chan_sip.c:4519 parse_request: Header 6: Server: Linksys/SPA2100-3.3.6 (29) [Jan 12 13:49:18] DEBUG[15234]: chan_sip.c:4519 parse_request: Header 7: Content-Length: 0 (17) [Jan 12 13:49:18] DEBUG[15234]: chan_sip.c:4519 parse_request: Header 8: (0) [Jan 12 13:49:18] --- (8 headers 0 lines) --- [Jan 12 13:49:18] DEBUG[15234]: chan_sip.c:2055 __sip_ack: ** SIP TIMER: Cancelling retransmit of packet (reply received) Retransid #148 [Jan 12 13:49:18] DEBUG[15234]: chan_sip.c:2065 __sip_ack: Stopping retransmission on '7190851d0b1c6cb5635d90041b6372a0@208.68.92.122' of Request 102: Match Not Found [Jan 12 13:49:18] Really destroying SIP dialog '7190851d0b1c6cb5635d90041b6372a0@208.68.92.122' Method: NOTIFY [Jan 12 13:49:19] DEBUG[15249]: rtp.c:870 ast_rtcp_read: Got RTCP report of 84 bytes [Jan 12 13:49:19] <--- SIP read from 69.157.33.248:60348 ---> SIP/2.0 200 OK Call-ID: 4d28bd582571370f21c89afe54f558f8@208.68.92.122 CSeq: 102 NOTIFY From: "asterisk" ;tag=as2e97fbeb To: ;tag=ccc6f9dac74935f Via: SIP/2.0/UDP 208.68.92.122:5060;branch=z9hG4bK22e88d38;rport Content-Length: 0 Contact: Supported: replaces User-Agent: Aastra 480i Cordless/1.4.1.1077 Brcm Callctrl/1.5 MxSF/v3.2.6.26 <-------------> [Jan 12 13:49:19] DEBUG[15234]: chan_sip.c:4519 parse_request: Header 0: SIP/2.0 200 OK (14) [Jan 12 13:49:19] DEBUG[15234]: chan_sip.c:4519 parse_request: Header 1: Call-ID: 4d28bd582571370f21c89afe54f558f8@208.68.92.122 (55) [Jan 12 13:49:19] DEBUG[15234]: chan_sip.c:4519 parse_request: Header 2: CSeq: 102 NOTIFY (16) [Jan 12 13:49:19] DEBUG[15234]: chan_sip.c:4519 parse_request: Header 3: From: "asterisk" ;tag=as2e97fbeb (60) [Jan 12 13:49:19] DEBUG[15234]: chan_sip.c:4519 parse_request: Header 4: To: ;tag=ccc6f9dac74935f (62) [Jan 12 13:49:19] DEBUG[15234]: chan_sip.c:4519 parse_request: Header 5: Via: SIP/2.0/UDP 208.68.92.122:5060;branch=z9hG4bK22e88d38;rport (64) [Jan 12 13:49:19] DEBUG[15234]: chan_sip.c:4519 parse_request: Header 6: Content-Length: 0 (17) [Jan 12 13:49:19] DEBUG[15234]: chan_sip.c:4519 parse_request: Header 7: Contact: (47) [Jan 12 13:49:19] DEBUG[15234]: chan_sip.c:4519 parse_request: Header 8: Supported: replaces (19) [Jan 12 13:49:19] DEBUG[15234]: chan_sip.c:4519 parse_request: Header 9: User-Agent: Aastra 480i Cordless/1.4.1.1077 Brcm Callctrl/1.5 MxSF/v3.2.6.26 (76) [Jan 12 13:49:19] DEBUG[15234]: chan_sip.c:4519 parse_request: Header 10: (0) [Jan 12 13:49:19] --- (10 headers 0 lines) --- BYE sip:9055920255@208.68.92.122 SIP/2.0 Via: SIP/2.0/UDP 192.168.2.189:5060;branch=z9hG4bK-e32b150 From: Dan Moschuk ;tag=ddd53689f170907bo0 To: ;tag=as1b24eed5 Call-ID: 463a221-329f59c3@192.168.2.189 CSeq: 103 BYE Max-Forwards: 70 Proxy-Authorization: Digest username="danmoschuk-1",realm="asterisk",nonce="2297c390",uri="sip:9055920255@208.68.92.122",algorithm=MD5,response="85c3ca207c966750c0fd428c04994143" User-Agent: Linksys/SPA2102-3.3.5(a) Content-Length: 0 <-------------> [Jan 12 13:49:30] DEBUG[15234]: chan_sip.c:4519 parse_request: Header 0: BYE sip:9055920255@208.68.92.122 SIP/2.0 (40) [Jan 12 13:49:30] DEBUG[15234]: chan_sip.c:4519 parse_request: Header 1: Via: SIP/2.0/UDP 192.168.2.189:5060;branch=z9hG4bK-e32b150 (58) [Jan 12 13:49:30] DEBUG[15234]: chan_sip.c:4519 parse_request: Header 2: From: Dan Moschuk ;tag=ddd53689f170907bo0 (89) [Jan 12 13:49:30] DEBUG[15234]: chan_sip.c:4519 parse_request: Header 3: To: ;tag=as1b24eed5 (65) [Jan 12 13:49:30] DEBUG[15234]: chan_sip.c:4519 parse_request: Header 4: Call-ID: 463a221-329f59c3@192.168.2.189 (39) [Jan 12 13:49:30] DEBUG[15234]: chan_sip.c:4519 parse_request: Header 5: CSeq: 103 BYE (13) [Jan 12 13:49:30] DEBUG[15234]: chan_sip.c:4519 parse_request: Header 6: Max-Forwards: 70 (16) [Jan 12 13:49:30] DEBUG[15234]: chan_sip.c:4519 parse_request: Header 7: Proxy-Authorization: Digest username="danmoschuk-1",realm="asterisk",nonce="2297c390",uri="sip:9055920255@208.68.92.122",algorithm=MD5,response="85c3ca207c966750c0fd428c04994143" (178) [Jan 12 13:49:30] DEBUG[15234]: chan_sip.c:4519 parse_request: Header 8: User-Agent: Linksys/SPA2102-3.3.5(a) (36) [Jan 12 13:49:30] DEBUG[15234]: chan_sip.c:4519 parse_request: Header 9: Content-Length: 0 (17) [Jan 12 13:49:30] DEBUG[15234]: chan_sip.c:4519 parse_request: Header 10: (0) [Jan 12 13:49:30] --- (10 headers 0 lines) --- [Jan 12 13:49:30] DEBUG[15234]: chan_sip.c:14502 handle_request: **** Received BYE (8) - Command in SIP BYE [Jan 12 13:49:30] Sending to 216.221.84.171 : 5060 (NAT) [Jan 12 13:49:30] DEBUG[15234]: chan_sip.c:1609 sip_alreadygone: Setting SIP_ALREADYGONE on dialog 463a221-329f59c3@192.168.2.189 [Jan 12 13:49:30] DEBUG[15234]: chan_sip.c:14079 handle_request_bye: Received bye, issuing owner hangup [Jan 12 13:49:30] <--- Transmitting (NAT) to 216.221.84.171:5060 ---> SIP/2.0 200 OK Via: SIP/2.0/UDP 192.168.2.189:5060;branch=z9hG4bK-e32b150;received=216.221.84.171 From: Dan Moschuk ;tag=ddd53689f170907bo0 To: ;tag=as1b24eed5 Call-ID: 463a221-329f59c3@192.168.2.189 CSeq: 103 BYE User-Agent: Easy Office Phone Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY Supported: replaces Contact: Content-Length: 0 <------------> [Jan 12 13:49:30] DEBUG[15249]: rtp.c:3048 bridge_p2p_loop: Oooh, got a hangup [Jan 12 13:49:30] DEBUG[15249]: channel.c:3920 ast_channel_bridge: Returning from native bridge, channels: SIP/danmoschuk-1-08466a88, SIP/easyofficephone-289-083eb088 [Jan 12 13:49:30] DEBUG[15249]: channel.c:1606 ast_hangup: Hanging up channel 'SIP/easyofficephone-289-083eb088' [Jan 12 13:49:30] DEBUG[15249]: chan_sip.c:3270 sip_hangup: Hangup call SIP/easyofficephone-289-083eb088, SIP callid 33554d704c2ef1490f5962b104aca81b@208.68.92.122) [Jan 12 13:49:30] DEBUG[15249]: chan_sip.c:3278 sip_hangup: update_call_counter(easyofficephone-289) - decrement call limit counter on hangup [Jan 12 13:49:30] DEBUG[15249]: chan_sip.c:2970 update_call_counter: Updating call counter for outgoing call [Jan 12 13:49:30] Scheduling destruction of SIP dialog '33554d704c2ef1490f5962b104aca81b@208.68.92.122' in 18048 ms (Method: INVITE) [Jan 12 13:49:30] DEBUG[15249]: chan_sip.c:5576 reqprep: Strict routing enforced for session 33554d704c2ef1490f5962b104aca81b@208.68.92.122 [Jan 12 13:49:30] set_destination: Parsing for address/port to send to [Jan 12 13:49:30] set_destination: set destination to 192.168.2.11, port 5060 [Jan 12 13:49:30] Reliably Transmitting (NAT) to 69.157.33.248:60348: BYE sip:easyofficephone-289@192.168.2.11 SIP/2.0 Via: SIP/2.0/UDP 208.68.92.122:5060;branch=z9hG4bK12eccd14;rport From: "DAN MOSCHUK" ;tag=as5f542e73 To: ;tag=229e7ae9e0bb111 Call-ID: 33554d704c2ef1490f5962b104aca81b@208.68.92.122 CSeq: 103 BYE User-Agent: Easy Office Phone Max-Forwards: 70 Content-Length: 0 --- [Jan 12 13:49:30] DEBUG[15249]: chan_sip.c:1951 __sip_reliable_xmit: *** SIP TIMER: Initalizing retransmit timer on packet: Id #181 [Jan 12 13:49:30] DEBUG[15249]: devicestate.c:303 __ast_device_state_changed_literal: Notification of state change to be queued on device/channel SIP/easyofficephone-289-083eb088 [Jan 12 13:49:30] DEBUG[15249]: rtp.c:1473 ast_rtp_early_bridge: Channel '' has no RTP, not doing anything [Jan 12 13:49:30] DEBUG[15214]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for SIP - easyofficephone-289 [Jan 12 13:49:30] DEBUG[15214]: chan_sip.c:15097 sip_devicestate: Checking device state for peer easyofficephone-289 [Jan 12 13:49:30] DEBUG[15249]: app_dial.c:1643 dial_exec_full: Exiting with DIALSTATUS=ANSWER.