*CLI> [May 17 15:48:10] DEBUG[8310]: chan_sip.c:4312 sip_alloc: Allocating new SIP dialog for (No Call-ID) - OPTIONS (No RTP) [May 17 15:48:10] DEBUG[8310]: chan_sip.c:4577 parse_request: Header 0: OPTIONS sip:10.50.10.2 SIP/2.0 (30) [May 17 15:48:10] DEBUG[8310]: chan_sip.c:4577 parse_request: Header 1: Via: SIP/2.0/UDP 10.50.10.171:5060;branch=z9hG4bK16121b22;rport (63) [May 17 15:48:10] DEBUG[8310]: chan_sip.c:4577 parse_request: Header 2: From: "asterisk" ;tag=as5b11be10 (59) [May 17 15:48:10] DEBUG[8310]: chan_sip.c:4577 parse_request: Header 3: To: (20) [May 17 15:48:10] DEBUG[8310]: chan_sip.c:4577 parse_request: Header 4: Contact: (36) [May 17 15:48:10] DEBUG[8310]: chan_sip.c:4577 parse_request: Header 5: Call-ID: 6ced76972f8f6ac350766c2161dd4d47@10.50.10.171 (54) [May 17 15:48:10] DEBUG[8310]: chan_sip.c:4577 parse_request: Header 6: CSeq: 102 OPTIONS (17) [May 17 15:48:10] DEBUG[8310]: chan_sip.c:4577 parse_request: Header 7: User-Agent: Asterisk PBX (24) [May 17 15:48:10] DEBUG[8310]: chan_sip.c:4577 parse_request: Header 8: Max-Forwards: 70 (16) [May 17 15:48:10] DEBUG[8310]: chan_sip.c:4577 parse_request: Header 9: Date: Thu, 17 May 2007 22:48:10 GMT (35) [May 17 15:48:10] DEBUG[8310]: chan_sip.c:4577 parse_request: Header 10: Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY (66) [May 17 15:48:10] DEBUG[8310]: chan_sip.c:4577 parse_request: Header 11: Supported: replaces (19) [May 17 15:48:10] DEBUG[8310]: chan_sip.c:4577 parse_request: Header 12: Content-Length: 0 (17) Reliably Transmitting (no NAT) to 10.50.10.2:5060: OPTIONS sip:10.50.10.2 SIP/2.0 Via: SIP/2.0/UDP 10.50.10.171:5060;branch=z9hG4bK16121b22;rport From: "asterisk" ;tag=as5b11be10 To: Contact: Call-ID: 6ced76972f8f6ac350766c2161dd4d47@10.50.10.171 CSeq: 102 OPTIONS User-Agent: Asterisk PBX Max-Forwards: 70 Date: Thu, 17 May 2007 22:48:10 GMT Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY Supported: replaces Content-Length: 0 --- [May 17 15:48:10] DEBUG[8310]: chan_sip.c:1976 __sip_reliable_xmit: *** SIP TIMER: Initalizing retransmit timer on packet: Id #38 <--- SIP read from 10.50.10.2:5060 ---> SIP/2.0 403 From: URI not recognized From: "asterisk" ;tag=as5b11be10 To: ;tag=metaswitch+1+0+ddd76f09 Via: SIP/2.0/UDP 10.50.10.171:5060;rport=5060;branch=z9hG4bK16121b22 Server: DC-SIP/2.0 Organization: Content-Length: 0 Call-ID: 6ced76972f8f6ac350766c2161dd4d47@10.50.10.171 CSeq: 102 OPTIONS <-------------> [May 17 15:48:10] DEBUG[8310]: chan_sip.c:4577 parse_request: Header 0: SIP/2.0 403 From: URI not recognized (36) [May 17 15:48:10] DEBUG[8310]: chan_sip.c:4577 parse_request: Header 1: From: "asterisk" ;tag=as5b11be10 (59) [May 17 15:48:10] DEBUG[8310]: chan_sip.c:4577 parse_request: Header 2: To: ;tag=metaswitch+1+0+ddd76f09 (48) [May 17 15:48:10] DEBUG[8310]: chan_sip.c:4577 parse_request: Header 3: Via: SIP/2.0/UDP 10.50.10.171:5060;rport=5060;branch=z9hG4bK16121b22 (68) [May 17 15:48:10] DEBUG[8310]: chan_sip.c:4577 parse_request: Header 4: Server: DC-SIP/2.0 (18) [May 17 15:48:10] DEBUG[8310]: chan_sip.c:4577 parse_request: Header 5: Organization: (14) [May 17 15:48:10] DEBUG[8310]: chan_sip.c:4577 parse_request: Header 6: Content-Length: 0 (17) [May 17 15:48:10] DEBUG[8310]: chan_sip.c:4577 parse_request: Header 7: Call-ID: 6ced76972f8f6ac350766c2161dd4d47@10.50.10.171 (54) [May 17 15:48:10] DEBUG[8310]: chan_sip.c:4577 parse_request: Header 8: CSeq: 102 OPTIONS (17) [May 17 15:48:10] DEBUG[8310]: chan_sip.c:4577 parse_request: Header 9: (0) --- (9 headers 0 lines) --- [May 17 15:48:10] DEBUG[8310]: chan_sip.c:2080 __sip_ack: ** SIP TIMER: Cancelling retransmit of packet (reply received) Retransid #38 [May 17 15:48:10] DEBUG[8310]: chan_sip.c:2090 __sip_ack: Stopping retransmission on '6ced76972f8f6ac350766c2161dd4d47@10.50.10.171' of Request 102: Match Not Found Really destroying SIP dialog '6ced76972f8f6ac350766c2161dd4d47@10.50.10.171' Method: OPTIONS <--- SIP read from 10.50.10.2:5060 ---> OPTIONS sip:metaswitch@10.50.10.171:5060;transport=udp SIP/2.0 Via: SIP/2.0/UDP 10.50.10.2:5060;rport;branch=z9hG4bK-73a0c31e51d9021f240926b8feff5599-metaswitch-1 Allow-Events: message-summary Allow-Events: refer Allow-Events: dialog Allow-Events: line-seize Max-Forwards: 70 Call-ID: 0A4F3CB2@metaswitch From: ;tag=metaswitch+1+0+f48edc89 CSeq: 441477885 OPTIONS Organization: Supported: 100rel Content-Length: 0 Contact: To: <-------------> [May 17 15:48:11] DEBUG[8310]: chan_sip.c:4577 parse_request: Header 0: OPTIONS sip:metaswitch@10.50.10.171:5060;transport=udp SIP/2.0 (62) [May 17 15:48:11] DEBUG[8310]: chan_sip.c:4577 parse_request: Header 1: Via: SIP/2.0/UDP 10.50.10.2:5060;rport;branch=z9hG4bK-73a0c31e51d9021f240926b8feff5599-metaswitch-1 (99) [May 17 15:48:11] DEBUG[8310]: chan_sip.c:4577 parse_request: Header 2: Allow-Events: message-summary (29) [May 17 15:48:11] DEBUG[8310]: chan_sip.c:4577 parse_request: Header 3: Allow-Events: refer (19) [May 17 15:48:11] DEBUG[8310]: chan_sip.c:4577 parse_request: Header 4: Allow-Events: dialog (20) [May 17 15:48:11] DEBUG[8310]: chan_sip.c:4577 parse_request: Header 5: Allow-Events: line-seize (24) [May 17 15:48:11] DEBUG[8310]: chan_sip.c:4577 parse_request: Header 6: Max-Forwards: 70 (16) [May 17 15:48:11] DEBUG[8310]: chan_sip.c:4577 parse_request: Header 7: Call-ID: 0A4F3CB2@metaswitch (28) [May 17 15:48:11] DEBUG[8310]: chan_sip.c:4577 parse_request: Header 8: From: ;tag=metaswitch+1+0+f48edc89 (66) [May 17 15:48:11] DEBUG[8310]: chan_sip.c:4577 parse_request: Header 9: CSeq: 441477885 OPTIONS (23) [May 17 15:48:11] DEBUG[8310]: chan_sip.c:4577 parse_request: Header 10: Organization: (14) [May 17 15:48:11] DEBUG[8310]: chan_sip.c:4577 parse_request: Header 11: Supported: 100rel (17) [May 17 15:48:11] DEBUG[8310]: chan_sip.c:4577 parse_request: Header 12: Content-Length: 0 (17) [May 17 15:48:11] DEBUG[8310]: chan_sip.c:4577 parse_request: Header 13: Contact: (41) [May 17 15:48:11] DEBUG[8310]: chan_sip.c:4577 parse_request: Header 14: To: (33) [May 17 15:48:11] DEBUG[8310]: chan_sip.c:4577 parse_request: Header 15: (0) --- (15 headers 0 lines) --- [May 17 15:48:11] DEBUG[8310]: chan_sip.c:4312 sip_alloc: Allocating new SIP dialog for 0A4F3CB2@metaswitch - OPTIONS (No RTP) [May 17 15:48:11] DEBUG[8310]: chan_sip.c:14709 handle_request: **** Received OPTIONS (3) - Command in SIP OPTIONS Looking for metaswitch in default (domain 10.50.10.171) <--- Transmitting (no NAT) to 10.50.10.2:5060 ---> SIP/2.0 404 Not Found Via: SIP/2.0/UDP 10.50.10.2:5060;rport;branch=z9hG4bK-73a0c31e51d9021f240926b8feff5599-metaswitch-1;received=10.50.10.2 From: ;tag=metaswitch+1+0+f48edc89 To: ;tag=as46ad0cff Call-ID: 0A4F3CB2@metaswitch CSeq: 441477885 OPTIONS User-Agent: Asterisk PBX Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY Supported: replaces Accept: application/sdp Content-Length: 0 <------------> Scheduling destruction of SIP dialog '0A4F3CB2@metaswitch' in 32000 ms (Method: OPTIONS) [May 17 15:48:11] DEBUG[8310]: chan_sip.c:14927 sipsock_read: SIP message could not be handled, bad request: 0A4F3CB2@metaswitch <--- SIP read from 10.50.10.2:5060 ---> INVITE sip:8055480617@10.50.10.171:5060;transport=udp SIP/2.0 Via: SIP/2.0/UDP 10.50.10.2:5060;rport;branch=z9hG4bK-228962e788d5c7cd9bb692e8201c716f-metaswitch-1 Allow-Events: message-summary Allow-Events: refer Allow-Events: dialog Allow-Events: line-seize Max-Forwards: 70 Call-ID: 6A14A302@metaswitch From: WIRELESS CALLER ;tag=metaswitch+1+2dcf1f+5b991871;isup-oli=62 To: CSeq: 362195609 INVITE Expires: 180 Organization: Supported: 100rel Content-Length: 122 Content-Type: application/sdp Contact: WIRELESS CALLER ;isup-oli=62 v=0 o=- 2621156084 2621156084 IN IP4 10.50.10.13 s=- c=IN IP4 10.50.10.13 t=0 0 m=audio 33768 RTP/AVP 0 a=ptime:20 <-------------> [May 17 15:48:12] DEBUG[8310]: chan_sip.c:4577 parse_request: Header 0: INVITE sip:8055480617@10.50.10.171:5060;transport=udp SIP/2.0 (61) [May 17 15:48:12] DEBUG[8310]: chan_sip.c:4577 parse_request: Header 1: Via: SIP/2.0/UDP 10.50.10.2:5060;rport;branch=z9hG4bK-228962e788d5c7cd9bb692e8201c716f-metaswitch-1 (99) [May 17 15:48:12] DEBUG[8310]: chan_sip.c:4577 parse_request: Header 2: Allow-Events: message-summary (29) [May 17 15:48:12] DEBUG[8310]: chan_sip.c:4577 parse_request: Header 3: Allow-Events: refer (19) [May 17 15:48:12] DEBUG[8310]: chan_sip.c:4577 parse_request: Header 4: Allow-Events: dialog (20) [May 17 15:48:12] DEBUG[8310]: chan_sip.c:4577 parse_request: Header 5: Allow-Events: line-seize (24) [May 17 15:48:12] DEBUG[8310]: chan_sip.c:4577 parse_request: Header 6: Max-Forwards: 70 (16) [May 17 15:48:12] DEBUG[8310]: chan_sip.c:4577 parse_request: Header 7: Call-ID: 6A14A302@metaswitch (28) [May 17 15:48:12] DEBUG[8310]: chan_sip.c:4577 parse_request: Header 8: From: WIRELESS CALLER ;tag=metaswitch+1+2dcf1f+5b991871;isup-oli=62 (99) [May 17 15:48:12] DEBUG[8310]: chan_sip.c:4577 parse_request: Header 9: To: (33) [May 17 15:48:12] DEBUG[8310]: chan_sip.c:4577 parse_request: Header 10: CSeq: 362195609 INVITE (22) [May 17 15:48:12] DEBUG[8310]: chan_sip.c:4577 parse_request: Header 11: Expires: 180 (12) [May 17 15:48:12] DEBUG[8310]: chan_sip.c:4577 parse_request: Header 12: Organization: (14) [May 17 15:48:12] DEBUG[8310]: chan_sip.c:4577 parse_request: Header 13: Supported: 100rel (17) [May 17 15:48:12] DEBUG[8310]: chan_sip.c:4577 parse_request: Header 14: Content-Length: 122 (19) [May 17 15:48:12] DEBUG[8310]: chan_sip.c:4577 parse_request: Header 15: Content-Type: application/sdp (29) [May 17 15:48:12] DEBUG[8310]: chan_sip.c:4577 parse_request: Header 16: Contact: WIRELESS CALLER ;isup-oli=62 (69) [May 17 15:48:12] DEBUG[8310]: chan_sip.c:4577 parse_request: Header 17: (0) [May 17 15:48:12] DEBUG[8310]: chan_sip.c:4609 parse_request: Line: v=0 (3) [May 17 15:48:12] DEBUG[8310]: chan_sip.c:4609 parse_request: Line: o=- 2621156084 2621156084 IN IP4 10.50.10.13 (44) [May 17 15:48:12] DEBUG[8310]: chan_sip.c:4609 parse_request: Line: s=- (3) [May 17 15:48:12] DEBUG[8310]: chan_sip.c:4609 parse_request: Line: c=IN IP4 10.50.10.13 (20) [May 17 15:48:12] DEBUG[8310]: chan_sip.c:4609 parse_request: Line: t=0 0 (5) [May 17 15:48:12] DEBUG[8310]: chan_sip.c:4609 parse_request: Line: m=audio 33768 RTP/AVP 0 (23) [May 17 15:48:12] DEBUG[8310]: chan_sip.c:4609 parse_request: Line: a=ptime:20 (10) --- (17 headers 7 lines) --- [May 17 15:48:12] DEBUG[8310]: chan_sip.c:2576 do_setnat: Setting NAT on RTP to Off [May 17 15:48:12] DEBUG[8310]: chan_sip.c:4312 sip_alloc: Allocating new SIP dialog for 6A14A302@metaswitch - INVITE (With RTP) [May 17 15:48:12] DEBUG[8310]: chan_sip.c:14709 handle_request: **** Received INVITE (5) - Command in SIP INVITE [May 17 15:48:12] DEBUG[8310]: chan_sip.c:1681 parse_sip_options: Begin: parsing SIP "Supported: 100rel" [May 17 15:48:12] DEBUG[8310]: chan_sip.c:1689 parse_sip_options: Found SIP option: -100rel- [May 17 15:48:12] DEBUG[8310]: chan_sip.c:1695 parse_sip_options: Matched SIP option: 100rel Sending to 10.50.10.2 : 5060 (NAT) Using INVITE request as basis request - 6A14A302@metaswitch Found peer '8055488091' [May 17 15:48:12] DEBUG[8310]: chan_sip.c:2576 do_setnat: Setting NAT on RTP to Off Found RTP audio format 0 Peer audio RTP is at port 10.50.10.13:33768 [May 17 15:48:12] DEBUG[8310]: chan_sip.c:5136 process_sdp: T38 state changed to 0 on channel Capabilities: us - 0x8000e (gsm|ulaw|alaw|h263), peer - audio=0x4 (ulaw)/video=0x0 (nothing), combined - 0x4 (ulaw) Non-codec capabilities (dtmf): us - 0x1 (telephone-event), peer - 0x0 (nothing), combined - 0x0 (nothing) Peer audio RTP is at port 10.50.10.13:33768 [May 17 15:48:12] DEBUG[8310]: chan_sip.c:5216 process_sdp: We're settling with these formats: 0x4 (ulaw) [May 17 15:48:12] DEBUG[8310]: chan_sip.c:13418 handle_request_invite: Checking SIP call limits for device 8055488091 [May 17 15:48:12] DEBUG[8310]: chan_sip.c:3004 update_call_counter: Updating call counter for incoming call Looking for 8055480617 in sip (domain 10.50.10.171) [May 17 15:48:12] DEBUG[8310]: frame.c:1267 ast_codec_choose: Could not find preferred codec - Going for the best codec [May 17 15:48:12] DEBUG[8310]: chan_sip.c:3806 sip_new: *** Our native formats are 0x4 (ulaw) [May 17 15:48:12] DEBUG[8310]: chan_sip.c:3807 sip_new: *** Joint capabilities are 0x4 (ulaw) [May 17 15:48:12] DEBUG[8310]: chan_sip.c:3808 sip_new: *** Our capabilities are 0x8000e (gsm|ulaw|alaw|h263) [May 17 15:48:12] DEBUG[8310]: frame.c:1267 ast_codec_choose: Could not find preferred codec - Going for the best codec [May 17 15:48:12] DEBUG[8310]: chan_sip.c:3809 sip_new: *** AST_CODEC_CHOOSE formats are 0x4 (ulaw) [May 17 15:48:12] DEBUG[8310]: chan_sip.c:3832 sip_new: This channel will not be able to handle video. [May 17 15:48:12] DEBUG[8310]: chan_sip.c:7994 build_route: build_route: Contact hop: WIRELESS CALLER ;isup-oli=62 list_route: hop: [May 17 15:48:12] DEBUG[8310]: chan_sip.c:13492 handle_request_invite: SIP/8055488091-09f4a6f0: New call is still down.... Trying... <--- Transmitting (no NAT) to 10.50.10.2:5060 ---> SIP/2.0 100 Trying Via: SIP/2.0/UDP 10.50.10.2:5060;rport;branch=z9hG4bK-228962e788d5c7cd9bb692e8201c716f-metaswitch-1;received=10.50.10.2 From: WIRELESS CALLER ;tag=metaswitch+1+2dcf1f+5b991871;isup-oli=62 To: Call-ID: 6A14A302@metaswitch CSeq: 362195609 INVITE User-Agent: Asterisk PBX Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY Supported: replaces Contact: Content-Length: 0 <------------> [May 17 15:48:12] DEBUG[8310]: devicestate.c:303 __ast_device_state_changed_literal: Notification of state change to be queued on device/channel SIP/8055488091-09f4a6f0 [May 17 15:48:12] DEBUG[8288]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for SIP - 8055488091 [May 17 15:48:12] DEBUG[8288]: chan_sip.c:15321 sip_devicestate: Checking device state for peer 8055488091 [May 17 15:48:12] DEBUG[8288]: devicestate.c:287 do_state_change: Changing state for SIP/8055488091 - state 1 (Not in use) [May 17 15:48:12] DEBUG[8316]: pbx.c:1809 pbx_extension_helper: Launching 'Goto' -- Executing [8055480617@sip:1] Goto("SIP/8055488091-09f4a6f0", "line2|8055488092|1") in new stack -- Goto (line2,8055488092,1) [May 17 15:48:12] DEBUG[8316]: pbx.c:1809 pbx_extension_helper: Launching 'SLATrunk' -- Executing [8055488092@line2:1] SLATrunk("SIP/8055488091-09f4a6f0", "line2") in new stack [May 17 15:48:12] DEBUG[8316]: devicestate.c:303 __ast_device_state_changed_literal: Notification of state change to be queued on device/channel SLA:station1_line2 [May 17 15:48:12] DEBUG[8288]: devicestate.c:157 ast_device_state: Checking if I can find provider for "SLA" - number: station1_line2 [May 17 15:48:12] DEBUG[8288]: devicestate.c:287 do_state_change: Changing state for SLA:station1_line2 - state 6 (Ringing) [May 17 15:48:12] DEBUG[8288]: devicestate.c:157 ast_device_state: Checking if I can find provider for "SLA" - number: station1_line2 [May 17 15:48:12] DEBUG[8316]: devicestate.c:303 __ast_device_state_changed_literal: Notification of state change to be queued on device/channel SLA:station2_line2 [May 17 15:48:12] DEBUG[8288]: devicestate.c:157 ast_device_state: Checking if I can find provider for "SLA" - number: station2_line2 [May 17 15:48:12] DEBUG[8288]: devicestate.c:287 do_state_change: Changing state for SLA:station2_line2 - state 6 (Ringing) [May 17 15:48:12] DEBUG[8288]: devicestate.c:157 ast_device_state: Checking if I can find provider for "SLA" - number: station2_line2 [May 17 15:48:12] DEBUG[8304]: chan_sip.c:15387 sip_request_call: Asked to create a SIP channel with formats: 0x4 (ulaw) [May 17 15:48:12] DEBUG[8304]: chan_sip.c:4312 sip_alloc: Allocating new SIP dialog for (No Call-ID) - INVITE (With RTP) [May 17 15:48:12] DEBUG[8304]: chan_sip.c:2576 do_setnat: Setting NAT on RTP to Off [May 17 15:48:12] DEBUG[8304]: chan_sip.c:3806 sip_new: *** Our native formats are 0x4 (ulaw) [May 17 15:48:12] DEBUG[8304]: chan_sip.c:3807 sip_new: *** Joint capabilities are 0x0 (nothing) [May 17 15:48:12] DEBUG[8304]: chan_sip.c:3808 sip_new: *** Our capabilities are 0xe (gsm|ulaw|alaw) [May 17 15:48:12] DEBUG[8304]: chan_sip.c:3809 sip_new: *** AST_CODEC_CHOOSE formats are 0x4 (ulaw) [May 17 15:48:12] DEBUG[8304]: chan_sip.c:3811 sip_new: *** Our preferred formats from the incoming channel are 0x4 (ulaw) [May 17 15:48:12] DEBUG[8304]: chan_sip.c:3832 sip_new: This channel will not be able to handle video. [May 17 15:48:12] DEBUG[8304]: channel.c:3376 ast_channel_inherit_variables: Not copying variable STACK-line2-8055488092-1. [May 17 15:48:12] DEBUG[8304]: channel.c:3376 ast_channel_inherit_variables: Not copying variable STACK-sip-8055480617-1. [May 17 15:48:12] DEBUG[8304]: channel.c:3376 ast_channel_inherit_variables: Not copying variable SIPCALLID. [May 17 15:48:12] DEBUG[8304]: channel.c:3376 ast_channel_inherit_variables: Not copying variable SIPDOMAIN. [May 17 15:48:12] DEBUG[8304]: channel.c:3376 ast_channel_inherit_variables: Not copying variable SIPURI. [May 17 15:48:12] DEBUG[8304]: chan_sip.c:2831 sip_call: Outgoing Call for station1 [May 17 15:48:12] DEBUG[8304]: chan_sip.c:3004 update_call_counter: Updating call counter for outgoing call [May 17 15:48:12] DEBUG[8304]: chan_sip.c:2846 sip_call: Our T38 capability (0), joint T38 capability (0) [May 17 15:48:12] DEBUG[8304]: chan_sip.c:6198 add_sdp: ** Our capability: 0xe (gsm|ulaw|alaw) Video flag: False [May 17 15:48:12] DEBUG[8304]: chan_sip.c:6199 add_sdp: ** Our prefcodec: 0x4 (ulaw) Audio is at 10.50.10.171 port 12170 Adding codec 0x4 (ulaw) to SDP Adding codec 0x8 (alaw) to SDP Adding codec 0x2 (gsm) to SDP Adding non-codec 0x1 (telephone-event) to SDP [May 17 15:48:12] DEBUG[8304]: chan_sip.c:6330 add_sdp: -- Done with adding codecs to SDP [May 17 15:48:12] DEBUG[8304]: chan_sip.c:6375 add_sdp: Done building SDP. Settling with this capability: 0xe (gsm|ulaw|alaw) [May 17 15:48:12] DEBUG[8304]: chan_sip.c:4577 parse_request: Header 0: INVITE sip:station1@10.50.10.177 SIP/2.0 (40) [May 17 15:48:12] DEBUG[8304]: chan_sip.c:4577 parse_request: Header 1: Via: SIP/2.0/UDP 10.50.10.171:5060;branch=z9hG4bK11611bf4;rport (63) [May 17 15:48:12] DEBUG[8304]: chan_sip.c:4577 parse_request: Header 2: From: "WIRELESS CALLER" ;tag=as7fe55b67 (68) [May 17 15:48:12] DEBUG[8304]: chan_sip.c:4577 parse_request: Header 3: To: (31) [May 17 15:48:12] DEBUG[8304]: chan_sip.c:4577 parse_request: Header 4: Contact: (38) [May 17 15:48:12] DEBUG[8304]: chan_sip.c:4577 parse_request: Header 5: Call-ID: 460e7cf631d31e697f9f7b97421b6e3a@10.50.10.171 (54) [May 17 15:48:12] DEBUG[8304]: chan_sip.c:4577 parse_request: Header 6: CSeq: 102 INVITE (16) [May 17 15:48:12] DEBUG[8304]: chan_sip.c:4577 parse_request: Header 7: User-Agent: Asterisk PBX (24) [May 17 15:48:12] DEBUG[8304]: chan_sip.c:4577 parse_request: Header 8: Max-Forwards: 70 (16) [May 17 15:48:12] DEBUG[8304]: chan_sip.c:4577 parse_request: Header 9: Date: Thu, 17 May 2007 22:48:12 GMT (35) [May 17 15:48:12] DEBUG[8304]: chan_sip.c:4577 parse_request: Header 10: Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY (66) [May 17 15:48:12] DEBUG[8304]: chan_sip.c:4577 parse_request: Header 11: Supported: replaces (19) [May 17 15:48:12] DEBUG[8304]: chan_sip.c:4577 parse_request: Header 12: Content-Type: application/sdp (29) [May 17 15:48:12] DEBUG[8304]: chan_sip.c:4577 parse_request: Header 13: Content-Length: 285 (19) [May 17 15:48:12] DEBUG[8304]: chan_sip.c:4577 parse_request: Header 14: (0) [May 17 15:48:12] DEBUG[8304]: chan_sip.c:4609 parse_request: Line: v=0 (3) [May 17 15:48:12] DEBUG[8304]: chan_sip.c:4609 parse_request: Line: o=root 8284 8284 IN IP4 10.50.10.171 (36) [May 17 15:48:12] DEBUG[8304]: chan_sip.c:4609 parse_request: Line: s=session (9) [May 17 15:48:12] DEBUG[8304]: chan_sip.c:4609 parse_request: Line: c=IN IP4 10.50.10.171 (21) [May 17 15:48:12] DEBUG[8304]: chan_sip.c:4609 parse_request: Line: t=0 0 (5) [May 17 15:48:12] DEBUG[8304]: chan_sip.c:4609 parse_request: Line: m=audio 12170 RTP/AVP 0 8 3 101 (31) [May 17 15:48:12] DEBUG[8304]: chan_sip.c:4609 parse_request: Line: a=rtpmap:0 PCMU/8000 (20) [May 17 15:48:12] DEBUG[8304]: chan_sip.c:4609 parse_request: Line: a=rtpmap:8 PCMA/8000 (20) [May 17 15:48:12] DEBUG[8304]: chan_sip.c:4609 parse_request: Line: a=rtpmap:3 GSM/8000 (19) [May 17 15:48:12] DEBUG[8304]: chan_sip.c:4609 parse_request: Line: a=rtpmap:101 telephone-event/8000 (33) [May 17 15:48:12] DEBUG[8304]: chan_sip.c:4609 parse_request: Line: a=fmtp:101 0-16 (15) [May 17 15:48:12] DEBUG[8304]: chan_sip.c:4609 parse_request: Line: a=silenceSupp:off - - - - (25) [May 17 15:48:12] DEBUG[8304]: chan_sip.c:4609 parse_request: Line: a=ptime:20 (10) [May 17 15:48:12] DEBUG[8304]: chan_sip.c:4609 parse_request: Line: a=sendrecv (10) Reliably Transmitting (no NAT) to 10.50.10.177:5060: INVITE sip:station1@10.50.10.177 SIP/2.0 Via: SIP/2.0/UDP 10.50.10.171:5060;branch=z9hG4bK11611bf4;rport From: "WIRELESS CALLER" ;tag=as7fe55b67 To: Contact: Call-ID: 460e7cf631d31e697f9f7b97421b6e3a@10.50.10.171 CSeq: 102 INVITE User-Agent: Asterisk PBX Max-Forwards: 70 Date: Thu, 17 May 2007 22:48:12 GMT Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY Supported: replaces Content-Type: application/sdp Content-Length: 285 v=0 o=root 8284 8284 IN IP4 10.50.10.171 s=session c=IN IP4 10.50.10.171 t=0 0 m=audio 12170 RTP/AVP 0 8 3 101 a=rtpmap:0 PCMU/8000 a=rtpmap:8 PCMA/8000 a=rtpmap:3 GSM/8000 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-16 a=silenceSupp:off - - - - a=ptime:20 a=sendrecv --- [May 17 15:48:12] DEBUG[8304]: chan_sip.c:1976 __sip_reliable_xmit: *** SIP TIMER: Initalizing retransmit timer on packet: Id #42 -- Called station1 [May 17 15:48:12] DEBUG[8304]: chan_sip.c:15387 sip_request_call: Asked to create a SIP channel with formats: 0x4 (ulaw) [May 17 15:48:12] DEBUG[8304]: chan_sip.c:4312 sip_alloc: Allocating new SIP dialog for (No Call-ID) - INVITE (With RTP) [May 17 15:48:12] DEBUG[8304]: chan_sip.c:2576 do_setnat: Setting NAT on RTP to Off [May 17 15:48:12] DEBUG[8304]: chan_sip.c:3806 sip_new: *** Our native formats are 0x4 (ulaw) [May 17 15:48:12] DEBUG[8304]: chan_sip.c:3807 sip_new: *** Joint capabilities are 0x0 (nothing) [May 17 15:48:12] DEBUG[8304]: chan_sip.c:3808 sip_new: *** Our capabilities are 0xe (gsm|ulaw|alaw) [May 17 15:48:12] DEBUG[8304]: chan_sip.c:3809 sip_new: *** AST_CODEC_CHOOSE formats are 0x4 (ulaw) [May 17 15:48:12] DEBUG[8304]: chan_sip.c:3811 sip_new: *** Our preferred formats from the incoming channel are 0x4 (ulaw) [May 17 15:48:12] DEBUG[8304]: chan_sip.c:3832 sip_new: This channel will not be able to handle video. [May 17 15:48:12] DEBUG[8304]: channel.c:3376 ast_channel_inherit_variables: Not copying variable STACK-line2-8055488092-1. [May 17 15:48:12] DEBUG[8304]: channel.c:3376 ast_channel_inherit_variables: Not copying variable STACK-sip-8055480617-1. [May 17 15:48:12] DEBUG[8304]: channel.c:3376 ast_channel_inherit_variables: Not copying variable SIPCALLID. [May 17 15:48:12] DEBUG[8304]: channel.c:3376 ast_channel_inherit_variables: Not copying variable SIPDOMAIN. [May 17 15:48:12] DEBUG[8304]: channel.c:3376 ast_channel_inherit_variables: Not copying variable SIPURI. [May 17 15:48:12] DEBUG[8304]: chan_sip.c:2831 sip_call: Outgoing Call for station2 [May 17 15:48:12] DEBUG[8304]: chan_sip.c:3004 update_call_counter: Updating call counter for outgoing call [May 17 15:48:12] DEBUG[8304]: chan_sip.c:2846 sip_call: Our T38 capability (0), joint T38 capability (0) [May 17 15:48:12] DEBUG[8304]: chan_sip.c:6198 add_sdp: ** Our capability: 0xe (gsm|ulaw|alaw) Video flag: False [May 17 15:48:12] DEBUG[8304]: chan_sip.c:6199 add_sdp: ** Our prefcodec: 0x4 (ulaw) Audio is at 10.50.10.171 port 19402 Adding codec 0x4 (ulaw) to SDP Adding codec 0x8 (alaw) to SDP Adding codec 0x2 (gsm) to SDP Adding non-codec 0x1 (telephone-event) to SDP [May 17 15:48:12] DEBUG[8304]: chan_sip.c:6330 add_sdp: -- Done with adding codecs to SDP [May 17 15:48:12] DEBUG[8304]: chan_sip.c:6375 add_sdp: Done building SDP. Settling with this capability: 0xe (gsm|ulaw|alaw) [May 17 15:48:12] DEBUG[8304]: chan_sip.c:4577 parse_request: Header 0: INVITE sip:station2@10.50.10.183 SIP/2.0 (40) [May 17 15:48:12] DEBUG[8304]: chan_sip.c:4577 parse_request: Header 1: Via: SIP/2.0/UDP 10.50.10.171:5060;branch=z9hG4bK2d204008;rport (63) [May 17 15:48:12] DEBUG[8304]: chan_sip.c:4577 parse_request: Header 2: From: "WIRELESS CALLER" ;tag=as5c54499d (68) [May 17 15:48:12] DEBUG[8304]: chan_sip.c:4577 parse_request: Header 3: To: (31) [May 17 15:48:12] DEBUG[8304]: chan_sip.c:4577 parse_request: Header 4: Contact: (38) [May 17 15:48:12] DEBUG[8304]: chan_sip.c:4577 parse_request: Header 5: Call-ID: 6b2fa96c1e9bd58d0cecf5a34c0b73a8@10.50.10.171 (54) [May 17 15:48:12] DEBUG[8304]: chan_sip.c:4577 parse_request: Header 6: CSeq: 102 INVITE (16) [May 17 15:48:12] DEBUG[8304]: chan_sip.c:4577 parse_request: Header 7: User-Agent: Asterisk PBX (24) [May 17 15:48:12] DEBUG[8304]: chan_sip.c:4577 parse_request: Header 8: Max-Forwards: 70 (16) [May 17 15:48:12] DEBUG[8304]: chan_sip.c:4577 parse_request: Header 9: Date: Thu, 17 May 2007 22:48:12 GMT (35) [May 17 15:48:12] DEBUG[8304]: chan_sip.c:4577 parse_request: Header 10: Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY (66) [May 17 15:48:12] DEBUG[8304]: chan_sip.c:4577 parse_request: Header 11: Supported: replaces (19) [May 17 15:48:12] DEBUG[8304]: chan_sip.c:4577 parse_request: Header 12: Content-Type: application/sdp (29) [May 17 15:48:12] DEBUG[8304]: chan_sip.c:4577 parse_request: Header 13: Content-Length: 285 (19) [May 17 15:48:12] DEBUG[8304]: chan_sip.c:4577 parse_request: Header 14: (0) [May 17 15:48:12] DEBUG[8304]: chan_sip.c:4609 parse_request: Line: v=0 (3) [May 17 15:48:12] DEBUG[8304]: chan_sip.c:4609 parse_request: Line: o=root 8284 8284 IN IP4 10.50.10.171 (36) [May 17 15:48:12] DEBUG[8304]: chan_sip.c:4609 parse_request: Line: s=session (9) [May 17 15:48:12] DEBUG[8304]: chan_sip.c:4609 parse_request: Line: c=IN IP4 10.50.10.171 (21) [May 17 15:48:12] DEBUG[8304]: chan_sip.c:4609 parse_request: Line: t=0 0 (5) [May 17 15:48:12] DEBUG[8304]: chan_sip.c:4609 parse_request: Line: m=audio 19402 RTP/AVP 0 8 3 101 (31) [May 17 15:48:12] DEBUG[8304]: chan_sip.c:4609 parse_request: Line: a=rtpmap:0 PCMU/8000 (20) [May 17 15:48:12] DEBUG[8304]: chan_sip.c:4609 parse_request: Line: a=rtpmap:8 PCMA/8000 (20) [May 17 15:48:12] DEBUG[8304]: chan_sip.c:4609 parse_request: Line: a=rtpmap:3 GSM/8000 (19) [May 17 15:48:12] DEBUG[8304]: chan_sip.c:4609 parse_request: Line: a=rtpmap:101 telephone-event/8000 (33) [May 17 15:48:12] DEBUG[8304]: chan_sip.c:4609 parse_request: Line: a=fmtp:101 0-16 (15) [May 17 15:48:12] DEBUG[8304]: chan_sip.c:4609 parse_request: Line: a=silenceSupp:off - - - - (25) [May 17 15:48:12] DEBUG[8304]: chan_sip.c:4609 parse_request: Line: a=ptime:20 (10) [May 17 15:48:12] DEBUG[8304]: chan_sip.c:4609 parse_request: Line: a=sendrecv (10) Reliably Transmitting (no NAT) to 10.50.10.183:5060: INVITE sip:station2@10.50.10.183 SIP/2.0 Via: SIP/2.0/UDP 10.50.10.171:5060;branch=z9hG4bK2d204008;rport From: "WIRELESS CALLER" ;tag=as5c54499d To: Contact: Call-ID: 6b2fa96c1e9bd58d0cecf5a34c0b73a8@10.50.10.171 CSeq: 102 INVITE User-Agent: Asterisk PBX Max-Forwards: 70 Date: Thu, 17 May 2007 22:48:12 GMT Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY Supported: replaces Content-Type: application/sdp Content-Length: 285 v=0 o=root 8284 8284 IN IP4 10.50.10.171 s=session c=IN IP4 10.50.10.171 t=0 0 m=audio 19402 RTP/AVP 0 8 3 101 a=rtpmap:0 PCMU/8000 a=rtpmap:8 PCMA/8000 a=rtpmap:3 GSM/8000 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-16 a=silenceSupp:off - - - - a=ptime:20 a=sendrecv --- [May 17 15:48:12] DEBUG[8304]: chan_sip.c:1976 __sip_reliable_xmit: *** SIP TIMER: Initalizing retransmit timer on packet: Id #44 -- Called station2 [May 17 15:48:12] DEBUG[8317]: app_queue.c:546 changethread: Device 'SIP/8055488091' changed to state '1' (Not in use) but we don't care because they're not a member of any queue. [May 17 15:48:12] DEBUG[8316]: chan_zap.c:7817 zt_request: Using channel -2 [May 17 15:48:12] DEBUG[8316]: channel.c:2911 set_format: Set channel Zap/pseudo-377676547 to read format slin [May 17 15:48:12] DEBUG[8316]: channel.c:2911 set_format: Set channel Zap/pseudo-377676547 to write format slin -- Created MeetMe conference 1023 for conference 'SLA_line2' <--- Transmitting (no NAT) to 10.50.10.2:5060 ---> SIP/2.0 180 Ringing Via: SIP/2.0/UDP 10.50.10.2:5060;rport;branch=z9hG4bK-228962e788d5c7cd9bb692e8201c716f-metaswitch-1;received=10.50.10.2 From: WIRELESS CALLER ;tag=metaswitch+1+2dcf1f+5b991871;isup-oli=62 To: ;tag=as1f43dbfa Call-ID: 6A14A302@metaswitch CSeq: 362195609 INVITE User-Agent: Asterisk PBX Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY Supported: replaces Contact: Content-Length: 0 <------------> [May 17 15:48:12] DEBUG[8316]: devicestate.c:303 __ast_device_state_changed_literal: Notification of state change to be queued on device/channel meetme:SLA_line2 [May 17 15:48:12] DEBUG[8288]: devicestate.c:157 ast_device_state: Checking if I can find provider for "meetme" - number: SLA_line2 [May 17 15:48:12] DEBUG[8288]: devicestate.c:287 do_state_change: Changing state for meetme:SLA_line2 - state 2 (In use) [May 17 15:48:12] DEBUG[8316]: channel.c:2911 set_format: Set channel SIP/8055488091-09f4a6f0 to write format slin [May 17 15:48:12] DEBUG[8316]: channel.c:2911 set_format: Set channel SIP/8055488091-09f4a6f0 to read format slin [May 17 15:48:12] DEBUG[8316]: app_meetme.c:1641 conf_run: Placed channel SIP/8055488091-09f4a6f0 in ZAP conf 1023 [May 17 15:48:12] DEBUG[8316]: chan_sip.c:6432 transmit_response_with_sdp: Setting framing from config on incoming call [May 17 15:48:12] DEBUG[8316]: chan_sip.c:6198 add_sdp: ** Our capability: 0x4 (ulaw) Video flag: True [May 17 15:48:12] DEBUG[8316]: chan_sip.c:6199 add_sdp: ** Our prefcodec: 0x0 (nothing) Audio is at 10.50.10.171 port 11916 Adding codec 0x4 (ulaw) to SDP [May 17 15:48:12] DEBUG[8316]: chan_sip.c:6330 add_sdp: -- Done with adding codecs to SDP [May 17 15:48:12] DEBUG[8316]: chan_sip.c:6375 add_sdp: Done building SDP. Settling with this capability: 0x4 (ulaw) <--- Transmitting (no NAT) to 10.50.10.2:5060 ---> SIP/2.0 183 Session Progress Via: SIP/2.0/UDP 10.50.10.2:5060;rport;branch=z9hG4bK-228962e788d5c7cd9bb692e8201c716f-metaswitch-1;received=10.50.10.2 From: WIRELESS CALLER ;tag=metaswitch+1+2dcf1f+5b991871;isup-oli=62 To: ;tag=as1f43dbfa Call-ID: 6A14A302@metaswitch CSeq: 362195609 INVITE User-Agent: Asterisk PBX Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY Supported: replaces Contact: Content-Type: application/sdp Content-Length: 182 v=0 o=root 8284 8284 IN IP4 10.50.10.171 s=session c=IN IP4 10.50.10.171 t=0 0 m=audio 11916 RTP/AVP 0 a=rtpmap:0 PCMU/8000 a=silenceSupp:off - - - - a=ptime:20 a=sendrecv <------------> [May 17 15:48:12] DEBUG[8316]: rtp.c:2701 ast_rtp_write: Ooh, format changed from unknown to ulaw [May 17 15:48:12] DEBUG[8316]: rtp.c:2718 ast_rtp_write: Created smoother: format: 4 ms: 20 len: 160 <--- SIP read from 10.50.10.177:5060 ---> SIP/2.0 100 Trying Call-ID: 460e7cf631d31e697f9f7b97421b6e3a@10.50.10.171 CSeq: 102 INVITE From: "WIRELESS CALLER" ;tag=as7fe55b67 To: ;tag=5413f0b70eba4ba Via: SIP/2.0/UDP 10.50.10.171:5060;branch=z9hG4bK11611bf4;rport Content-Length: 0 User-Agent: Aastra 480i/1.4.1.2000 Brcm Callctrl/1.5.1.0 MxSF/v3.2.6.26 <-------------> [May 17 15:48:12] DEBUG[8310]: chan_sip.c:4577 parse_request: Header 0: SIP/2.0 100 Trying (18) [May 17 15:48:12] DEBUG[8310]: chan_sip.c:4577 parse_request: Header 1: Call-ID: 460e7cf631d31e697f9f7b97421b6e3a@10.50.10.171 (54) [May 17 15:48:12] DEBUG[8310]: chan_sip.c:4577 parse_request: Header 2: CSeq: 102 INVITE (16) [May 17 15:48:12] DEBUG[8310]: chan_sip.c:4577 parse_request: Header 3: From: "WIRELESS CALLER" ;tag=as7fe55b67 (68) [May 17 15:48:12] DEBUG[8310]: chan_sip.c:4577 parse_request: Header 4: To: ;tag=5413f0b70eba4ba (51) [May 17 15:48:12] DEBUG[8310]: chan_sip.c:4577 parse_request: Header 5: Via: SIP/2.0/UDP 10.50.10.171:5060;branch=z9hG4bK11611bf4;rport (63) [May 17 15:48:12] DEBUG[8310]: chan_sip.c:4577 parse_request: Header 6: Content-Length: 0 (17) [May 17 15:48:12] DEBUG[8310]: chan_sip.c:4577 parse_request: Header 7: User-Agent: Aastra 480i/1.4.1.2000 Brcm Callctrl/1.5.1.0 MxSF/v3.2.6.26 (71) [May 17 15:48:12] DEBUG[8310]: chan_sip.c:4577 parse_request: Header 8: (0) --- (8 headers 0 lines) --- [May 17 15:48:12] DEBUG[8310]: chan_sip.c:2123 __sip_semi_ack: *** SIP TIMER: Cancelling retransmission #42 - INVITE (got response) [May 17 15:48:12] DEBUG[8310]: chan_sip.c:2132 __sip_semi_ack: (Provisional) Stopping retransmission (but retaining packet) on '460e7cf631d31e697f9f7b97421b6e3a@10.50.10.171' Request 102: Found [May 17 15:48:12] DEBUG[8310]: chan_sip.c:11658 handle_response_invite: SIP response 100 to standard invite <--- SIP read from 10.50.10.177:5060 ---> SIP/2.0 180 Ringing Call-ID: 460e7cf631d31e697f9f7b97421b6e3a@10.50.10.171 CSeq: 102 INVITE From: "WIRELESS CALLER" ;tag=as7fe55b67 To: ;tag=5413f0b70eba4ba Via: SIP/2.0/UDP 10.50.10.171:5060;branch=z9hG4bK11611bf4;rport Content-Length: 0 Allow-Events: talk, hold, conference Contact: User-Agent: Aastra 480i/1.4.1.2000 Brcm Callctrl/1.5.1.0 MxSF/v3.2.6.26 <-------------> [May 17 15:48:12] DEBUG[8310]: chan_sip.c:4577 parse_request: Header 0: SIP/2.0 180 Ringing (19) [May 17 15:48:12] DEBUG[8310]: chan_sip.c:4577 parse_request: Header 1: Call-ID: 460e7cf631d31e697f9f7b97421b6e3a@10.50.10.171 (54) [May 17 15:48:12] DEBUG[8310]: chan_sip.c:4577 parse_request: Header 2: CSeq: 102 INVITE (16) [May 17 15:48:12] DEBUG[8310]: chan_sip.c:4577 parse_request: Header 3: From: "WIRELESS CALLER" ;tag=as7fe55b67 (68) [May 17 15:48:12] DEBUG[8310]: chan_sip.c:4577 parse_request: Header 4: To: ;tag=5413f0b70eba4ba (51) [May 17 15:48:12] DEBUG[8310]: chan_sip.c:4577 parse_request: Header 5: Via: SIP/2.0/UDP 10.50.10.171:5060;branch=z9hG4bK11611bf4;rport (63) [May 17 15:48:12] DEBUG[8310]: chan_sip.c:4577 parse_request: Header 6: Content-Length: 0 (17) [May 17 15:48:12] DEBUG[8310]: chan_sip.c:4577 parse_request: Header 7: Allow-Events: talk, hold, conference (36) [May 17 15:48:12] DEBUG[8310]: chan_sip.c:4577 parse_request: Header 8: Contact: (36) [May 17 15:48:12] DEBUG[8310]: chan_sip.c:4577 parse_request: Header 9: User-Agent: Aastra 480i/1.4.1.2000 Brcm Callctrl/1.5.1.0 MxSF/v3.2.6.26 (71) [May 17 15:48:12] DEBUG[8310]: chan_sip.c:4577 parse_request: Header 10: (0) --- (10 headers 0 lines) --- [May 17 15:48:12] DEBUG[8310]: chan_sip.c:2132 __sip_semi_ack: (Provisional) Stopping retransmission (but retaining packet) on '460e7cf631d31e697f9f7b97421b6e3a@10.50.10.171' Request 102: Found [May 17 15:48:12] DEBUG[8310]: chan_sip.c:11658 handle_response_invite: SIP response 180 to standard invite [May 17 15:48:12] DEBUG[8310]: devicestate.c:303 __ast_device_state_changed_literal: Notification of state change to be queued on device/channel SIP/station1-09f4bc70 -- SIP/station1-09f4bc70 is ringing [May 17 15:48:12] DEBUG[8288]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for SIP - station1 [May 17 15:48:12] DEBUG[8288]: chan_sip.c:15321 sip_devicestate: Checking device state for peer station1 [May 17 15:48:12] DEBUG[8288]: devicestate.c:287 do_state_change: Changing state for SIP/station1 - state 1 (Not in use) [May 17 15:48:12] DEBUG[8323]: app_queue.c:546 changethread: Device 'SIP/station1' changed to state '1' (Not in use) but we don't care because they're not a member of any queue. <--- SIP read from 10.50.10.183:5060 ---> SIP/2.0 180 Ringing Call-ID: 6b2fa96c1e9bd58d0cecf5a34c0b73a8@10.50.10.171 CSeq: 102 INVITE From: "WIRELESS CALLER" ;tag=as5c54499d To: ;tag=8239a373ed95e9b Via: SIP/2.0/UDP 10.50.10.171:5060;branch=z9hG4bK2d204008;rport Content-Length: 0 Call-Info: ;appearance-index=1 Allow-Events: talk, hold, conference Contact: User-Agent: Aastra 55i/2.0.1.2000 Brcm-Callctrl/v1.7.2.2 MxSF/v3.6.2.5 <-------------> [May 17 15:48:12] DEBUG[8310]: chan_sip.c:4577 parse_request: Header 0: SIP/2.0 180 Ringing (19) [May 17 15:48:12] DEBUG[8310]: chan_sip.c:4577 parse_request: Header 1: Call-ID: 6b2fa96c1e9bd58d0cecf5a34c0b73a8@10.50.10.171 (54) [May 17 15:48:12] DEBUG[8310]: chan_sip.c:4577 parse_request: Header 2: CSeq: 102 INVITE (16) [May 17 15:48:12] DEBUG[8310]: chan_sip.c:4577 parse_request: Header 3: From: "WIRELESS CALLER" ;tag=as5c54499d (68) [May 17 15:48:12] DEBUG[8310]: chan_sip.c:4577 parse_request: Header 4: To: ;tag=8239a373ed95e9b (51) [May 17 15:48:12] DEBUG[8310]: chan_sip.c:4577 parse_request: Header 5: Via: SIP/2.0/UDP 10.50.10.171:5060;branch=z9hG4bK2d204008;rport (63) [May 17 15:48:12] DEBUG[8310]: chan_sip.c:4577 parse_request: Header 6: Content-Length: 0 (17) [May 17 15:48:12] DEBUG[8310]: chan_sip.c:4577 parse_request: Header 7: Call-Info: ;appearance-index=1 (48) [May 17 15:48:12] DEBUG[8310]: chan_sip.c:4577 parse_request: Header 8: Allow-Events: talk, hold, conference (36) [May 17 15:48:12] DEBUG[8310]: chan_sip.c:4577 parse_request: Header 9: Contact: (36) [May 17 15:48:12] DEBUG[8310]: chan_sip.c:4577 parse_request: Header 10: User-Agent: Aastra 55i/2.0.1.2000 Brcm-Callctrl/v1.7.2.2 MxSF/v3.6.2.5 (70) [May 17 15:48:12] DEBUG[8310]: chan_sip.c:4577 parse_request: Header 11: (0) --- (11 headers 0 lines) --- [May 17 15:48:12] DEBUG[8310]: chan_sip.c:2123 __sip_semi_ack: *** SIP TIMER: Cancelling retransmission #44 - INVITE (got response) [May 17 15:48:12] DEBUG[8310]: chan_sip.c:2132 __sip_semi_ack: (Provisional) Stopping retransmission (but retaining packet) on '6b2fa96c1e9bd58d0cecf5a34c0b73a8@10.50.10.171' Request 102: Found [May 17 15:48:12] DEBUG[8310]: chan_sip.c:11658 handle_response_invite: SIP response 180 to standard invite [May 17 15:48:12] DEBUG[8310]: devicestate.c:303 __ast_device_state_changed_literal: Notification of state change to be queued on device/channel SIP/station2-09f569b8 -- SIP/station2-09f569b8 is ringing [May 17 15:48:12] DEBUG[8288]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for SIP - station2 [May 17 15:48:12] DEBUG[8288]: chan_sip.c:15321 sip_devicestate: Checking device state for peer station2 [May 17 15:48:12] DEBUG[8288]: devicestate.c:287 do_state_change: Changing state for SIP/station2 - state 1 (Not in use) [May 17 15:48:12] DEBUG[8324]: app_queue.c:546 changethread: Device 'SIP/station2' changed to state '1' (Not in use) but we don't care because they're not a member of any queue. [May 17 15:48:13] DEBUG[8310]: chan_sip.c:2011 __sip_autodestruct: Auto destroying SIP dialog '46212CA3@metaswitch' [May 17 15:48:13] DEBUG[8310]: chan_sip.c:3110 sip_destroy: Destroying SIP dialog 46212CA3@metaswitch Really destroying SIP dialog '46212CA3@metaswitch' Method: OPTIONS [May 17 15:48:16] DEBUG[8310]: chan_sip.c:2011 __sip_autodestruct: Auto destroying SIP dialog 'F15AF21D@metaswitch' [May 17 15:48:16] DEBUG[8310]: chan_sip.c:3110 sip_destroy: Destroying SIP dialog F15AF21D@metaswitch Really destroying SIP dialog 'F15AF21D@metaswitch' Method: OPTIONS <--- SIP read from 10.50.10.183:5060 ---> SIP/2.0 200 OK Call-ID: 6b2fa96c1e9bd58d0cecf5a34c0b73a8@10.50.10.171 CSeq: 102 INVITE From: "WIRELESS CALLER" ;tag=as5c54499d To: ;tag=8239a373ed95e9b Via: SIP/2.0/UDP 10.50.10.171:5060;branch=z9hG4bK2d204008;rport Content-Length: 265 Call-Info: ;appearance-index=1 Allow-Events: talk,hold,conference Allow:NOTIFY,REFER,OPTIONS,INVITE,ACK,CANCEL,BYE,INFO Content-Type: application/sdp Supported: replaces Contact: User-Agent: Aastra 55i/2.0.1.2000 Brcm-Callctrl/v1.7.2.2 MxSF/v3.6.2.5 v=0 o=MxSIP 0 128974779 IN IP4 10.50.10.183 s=SIP Call c=IN IP4 10.50.10.183 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=sendrecv a=silenceSupp:off - - - - <-------------> [May 17 15:48:22] DEBUG[8310]: chan_sip.c:4577 parse_request: Header 0: SIP/2.0 200 OK (14) [May 17 15:48:22] DEBUG[8310]: chan_sip.c:4577 parse_request: Header 1: Call-ID: 6b2fa96c1e9bd58d0cecf5a34c0b73a8@10.50.10.171 (54) [May 17 15:48:22] DEBUG[8310]: chan_sip.c:4577 parse_request: Header 2: CSeq: 102 INVITE (16) [May 17 15:48:22] DEBUG[8310]: chan_sip.c:4577 parse_request: Header 3: From: "WIRELESS CALLER" ;tag=as5c54499d (68) [May 17 15:48:22] DEBUG[8310]: chan_sip.c:4577 parse_request: Header 4: To: ;tag=8239a373ed95e9b (51) [May 17 15:48:22] DEBUG[8310]: chan_sip.c:4577 parse_request: Header 5: Via: SIP/2.0/UDP 10.50.10.171:5060;branch=z9hG4bK2d204008;rport (63) [May 17 15:48:22] DEBUG[8310]: chan_sip.c:4577 parse_request: Header 6: Content-Length: 265 (19) [May 17 15:48:22] DEBUG[8310]: chan_sip.c:4577 parse_request: Header 7: Call-Info: ;appearance-index=1 (48) [May 17 15:48:22] DEBUG[8310]: chan_sip.c:4577 parse_request: Header 8: Allow-Events: talk,hold,conference (34) [May 17 15:48:22] DEBUG[8310]: chan_sip.c:4577 parse_request: Header 9: Allow:NOTIFY,REFER,OPTIONS,INVITE,ACK,CANCEL,BYE,INFO (53) [May 17 15:48:22] DEBUG[8310]: chan_sip.c:4577 parse_request: Header 10: Content-Type: application/sdp (29) [May 17 15:48:22] DEBUG[8310]: chan_sip.c:4577 parse_request: Header 11: Supported: replaces (19) [May 17 15:48:22] DEBUG[8310]: chan_sip.c:4577 parse_request: Header 12: Contact: (36) [May 17 15:48:22] DEBUG[8310]: chan_sip.c:4577 parse_request: Header 13: User-Agent: Aastra 55i/2.0.1.2000 Brcm-Callctrl/v1.7.2.2 MxSF/v3.6.2.5 (70) [May 17 15:48:22] DEBUG[8310]: chan_sip.c:4577 parse_request: Header 14: (0) [May 17 15:48:22] DEBUG[8310]: chan_sip.c:4609 parse_request: Line: v=0 (3) [May 17 15:48:22] DEBUG[8310]: chan_sip.c:4609 parse_request: Line: o=MxSIP 0 128974779 IN IP4 10.50.10.183 (39) [May 17 15:48:22] DEBUG[8310]: chan_sip.c:4609 parse_request: Line: s=SIP Call (10) [May 17 15:48:22] DEBUG[8310]: chan_sip.c:4609 parse_request: Line: c=IN IP4 10.50.10.183 (21) [May 17 15:48:22] DEBUG[8310]: chan_sip.c:4609 parse_request: Line: t=0 0 (5) [May 17 15:48:22] DEBUG[8310]: chan_sip.c:4609 parse_request: Line: m=audio 3000 RTP/AVP 0 8 101 (28) [May 17 15:48:22] DEBUG[8310]: chan_sip.c:4609 parse_request: Line: a=rtpmap:0 PCMU/8000 (20) [May 17 15:48:22] DEBUG[8310]: chan_sip.c:4609 parse_request: Line: a=rtpmap:8 PCMA/8000 (20) [May 17 15:48:22] DEBUG[8310]: chan_sip.c:4609 parse_request: Line: a=rtpmap:101 telephone-event/8000 (33) [May 17 15:48:22] DEBUG[8310]: chan_sip.c:4609 parse_request: Line: a=fmtp:101 0-15 (15) [May 17 15:48:22] DEBUG[8310]: chan_sip.c:4609 parse_request: Line: a=ptime:20 (10) [May 17 15:48:22] DEBUG[8310]: chan_sip.c:4609 parse_request: Line: a=sendrecv (10) [May 17 15:48:22] DEBUG[8310]: chan_sip.c:4609 parse_request: Line: a=silenceSupp:off - - - - (25) --- (14 headers 13 lines) --- [May 17 15:48:22] DEBUG[8310]: chan_sip.c:2072 __sip_ack: Acked pending invite 102 [May 17 15:48:22] DEBUG[8310]: chan_sip.c:2090 __sip_ack: Stopping retransmission on '6b2fa96c1e9bd58d0cecf5a34c0b73a8@10.50.10.171' of Request 102: Match Not Found [May 17 15:48:22] DEBUG[8310]: chan_sip.c:11658 handle_response_invite: SIP response 200 to standard invite Found RTP audio format 0 Found RTP audio format 8 Found RTP audio format 101 Peer audio RTP is at port 10.50.10.183:3000 Found description format PCMU for ID 0 Found description format PCMA for ID 8 Found description format telephone-event for ID 101 Got unsupported a:fmtp in SDP offer [May 17 15:48:22] DEBUG[8310]: chan_sip.c:5136 process_sdp: T38 state changed to 0 on channel SIP/station2-09f569b8 Capabilities: us - 0xe (gsm|ulaw|alaw), peer - audio=0xc (ulaw|alaw)/video=0x0 (nothing), combined - 0xc (ulaw|alaw) Non-codec capabilities (dtmf): us - 0x1 (telephone-event), peer - 0x1 (telephone-event), combined - 0x1 (telephone-event) Peer audio RTP is at port 10.50.10.183:3000 [May 17 15:48:22] DEBUG[8310]: chan_sip.c:5216 process_sdp: We're settling with these formats: 0xc (ulaw|alaw) [May 17 15:48:22] DEBUG[8310]: chan_sip.c:5223 process_sdp: We have an owner, now see if we need to change this call [May 17 15:48:22] DEBUG[8310]: chan_sip.c:3004 update_call_counter: Updating call counter for outgoing call [May 17 15:48:22] DEBUG[8310]: chan_sip.c:7994 build_route: build_route: Contact hop: list_route: hop: [May 17 15:48:22] DEBUG[8310]: chan_sip.c:5651 reqprep: Strict routing enforced for session 6b2fa96c1e9bd58d0cecf5a34c0b73a8@10.50.10.171 set_destination: Parsing for address/port to send to set_destination: set destination to 10.50.10.183, port 5060 Transmitting (no NAT) to 10.50.10.183:5060: ACK sip:station2@10.50.10.183 SIP/2.0 Via: SIP/2.0/UDP 10.50.10.171:5060;branch=z9hG4bK0f561192;rport From: "WIRELESS CALLER" ;tag=as5c54499d To: ;tag=8239a373ed95e9b Contact: Call-ID: 6b2fa96c1e9bd58d0cecf5a34c0b73a8@10.50.10.171 CSeq: 102 ACK User-Agent: Asterisk PBX Max-Forwards: 70 Content-Length: 0 --- [May 17 15:48:22] DEBUG[8321]: devicestate.c:303 __ast_device_state_changed_literal: Notification of state change to be queued on device/channel SIP/station2-09f569b8 -- SIP/station2-09f569b8 answered [May 17 15:48:22] DEBUG[8288]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for SIP - station2 [May 17 15:48:22] DEBUG[8288]: chan_sip.c:15321 sip_devicestate: Checking device state for peer station2 [May 17 15:48:22] DEBUG[8288]: devicestate.c:287 do_state_change: Changing state for SIP/station2 - state 1 (Not in use) [May 17 15:48:22] DEBUG[8304]: devicestate.c:303 __ast_device_state_changed_literal: Notification of state change to be queued on device/channel SIP/8055488091-09f4a6f0 [May 17 15:48:22] DEBUG[8304]: chan_sip.c:3464 sip_answer: SIP answering channel: SIP/8055488091-09f4a6f0 [May 17 15:48:22] DEBUG[8304]: chan_sip.c:6432 transmit_response_with_sdp: Setting framing from config on incoming call [May 17 15:48:22] DEBUG[8304]: chan_sip.c:6198 add_sdp: ** Our capability: 0x4 (ulaw) Video flag: True [May 17 15:48:22] DEBUG[8304]: chan_sip.c:6199 add_sdp: ** Our prefcodec: 0x0 (nothing) Audio is at 10.50.10.171 port 11916 Adding codec 0x4 (ulaw) to SDP [May 17 15:48:22] DEBUG[8304]: chan_sip.c:6330 add_sdp: -- Done with adding codecs to SDP [May 17 15:48:22] DEBUG[8304]: chan_sip.c:6375 add_sdp: Done building SDP. Settling with this capability: 0x4 (ulaw) <--- Reliably Transmitting (no NAT) to 10.50.10.2:5060 ---> SIP/2.0 200 OK Via: SIP/2.0/UDP 10.50.10.2:5060;rport;branch=z9hG4bK-228962e788d5c7cd9bb692e8201c716f-metaswitch-1;received=10.50.10.2 From: WIRELESS CALLER ;tag=metaswitch+1+2dcf1f+5b991871;isup-oli=62 To: ;tag=as1f43dbfa Call-ID: 6A14A302@metaswitch CSeq: 362195609 INVITE User-Agent: Asterisk PBX Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY Supported: replaces Contact: Content-Type: application/sdp Content-Length: 182 v=0 o=root 8284 8285 IN IP4 10.50.10.171 s=session c=IN IP4 10.50.10.171 t=0 0 m=audio 11916 RTP/AVP 0 a=rtpmap:0 PCMU/8000 a=silenceSupp:off - - - - a=ptime:20 a=sendrecv <------------> [May 17 15:48:22] DEBUG[8304]: chan_sip.c:1976 __sip_reliable_xmit: *** SIP TIMER: Initalizing retransmit timer on packet: Id #47 <--- SIP read from 10.50.10.2:5060 ---> ACK sip:8055480617@10.50.10.171 SIP/2.0 Via: SIP/2.0/UDP 10.50.10.2:5060;branch=z9hG4bK-a89ad76233f313ed0e62cdec614666c3-metaswitch-1 Allow-Events: message-summary Allow-Events: refer Allow-Events: dialog Allow-Events: line-seize Max-Forwards: 70 Call-ID: 6A14A302@metaswitch From: WIRELESS CALLER ;tag=metaswitch+1+2dcf1f+5b991871;isup-oli=62 To: ;tag=as1f43dbfa CSeq: 362195609 ACK Contact: WIRELESS CALLER ;isup-oli=62 Organization: Content-Length: 0 <-------------> [May 17 15:48:22] DEBUG[8310]: chan_sip.c:4577 parse_request: Header 0: ACK sip:8055480617@10.50.10.171 SIP/2.0 (39) [May 17 15:48:22] DEBUG[8310]: chan_sip.c:4577 parse_request: Header 1: Via: SIP/2.0/UDP 10.50.10.2:5060;branch=z9hG4bK-a89ad76233f313ed0e62cdec614666c3-metaswitch-1 (93) [May 17 15:48:22] DEBUG[8310]: chan_sip.c:4577 parse_request: Header 2: Allow-Events: message-summary (29) [May 17 15:48:22] DEBUG[8310]: chan_sip.c:4577 parse_request: Header 3: Allow-Events: refer (19) [May 17 15:48:22] DEBUG[8310]: chan_sip.c:4577 parse_request: Header 4: Allow-Events: dialog (20) [May 17 15:48:22] DEBUG[8310]: chan_sip.c:4577 parse_request: Header 5: Allow-Events: line-seize (24) [May 17 15:48:22] DEBUG[8310]: chan_sip.c:4577 parse_request: Header 6: Max-Forwards: 70 (16) [May 17 15:48:22] DEBUG[8310]: chan_sip.c:4577 parse_request: Header 7: Call-ID: 6A14A302@metaswitch (28) [May 17 15:48:22] DEBUG[8310]: chan_sip.c:4577 parse_request: Header 8: From: WIRELESS CALLER ;tag=metaswitch+1+2dcf1f+5b991871;isup-oli=62 (99) [May 17 15:48:22] DEBUG[8310]: chan_sip.c:4577 parse_request: Header 9: To: ;tag=as1f43dbfa (48) [May 17 15:48:22] DEBUG[8310]: chan_sip.c:4577 parse_request: Header 10: CSeq: 362195609 ACK (19) [May 17 15:48:22] DEBUG[8310]: chan_sip.c:4577 parse_request: Header 11: Contact: WIRELESS CALLER ;isup-oli=62 (69) [May 17 15:48:22] DEBUG[8310]: chan_sip.c:4577 parse_request: Header 12: Organization: (14) [May 17 15:48:22] DEBUG[8310]: chan_sip.c:4577 parse_request: Header 13: Content-Length: 0 (17) [May 17 15:48:22] DEBUG[8310]: chan_sip.c:4577 parse_request: Header 14: (0) --- (14 headers 0 lines) --- [May 17 15:48:22] DEBUG[8310]: chan_sip.c:14709 handle_request: **** Received ACK (6) - Command in SIP ACK [May 17 15:48:22] DEBUG[8310]: chan_sip.c:2080 __sip_ack: ** SIP TIMER: Cancelling retransmit of packet (reply received) Retransid #47 [May 17 15:48:22] DEBUG[8310]: chan_sip.c:2090 __sip_ack: Stopping retransmission on '6A14A302@metaswitch' of Response 362195609: Match Not Found [May 17 15:48:22] DEBUG[8288]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for SIP - 8055488091 [May 17 15:48:22] DEBUG[8288]: chan_sip.c:15321 sip_devicestate: Checking device state for peer 8055488091 [May 17 15:48:22] DEBUG[8288]: devicestate.c:287 do_state_change: Changing state for SIP/8055488091 - state 1 (Not in use) [May 17 15:48:22] DEBUG[8304]: devicestate.c:303 __ast_device_state_changed_literal: Notification of state change to be queued on device/channel SLA:station1_line2 [May 17 15:48:22] DEBUG[8304]: devicestate.c:303 __ast_device_state_changed_literal: Notification of state change to be queued on device/channel SLA:station2_line2 [May 17 15:48:22] DEBUG[8288]: devicestate.c:157 ast_device_state: Checking if I can find provider for "SLA" - number: station1_line2 [May 17 15:48:22] DEBUG[8288]: devicestate.c:287 do_state_change: Changing state for SLA:station1_line2 - state 2 (In use) [May 17 15:48:22] DEBUG[8288]: devicestate.c:157 ast_device_state: Checking if I can find provider for "SLA" - number: station1_line2 [May 17 15:48:22] DEBUG[8288]: devicestate.c:157 ast_device_state: Checking if I can find provider for "SLA" - number: station2_line2 [May 17 15:48:22] DEBUG[8288]: devicestate.c:287 do_state_change: Changing state for SLA:station2_line2 - state 2 (In use) [May 17 15:48:22] DEBUG[8288]: devicestate.c:157 ast_device_state: Checking if I can find provider for "SLA" - number: station2_line2 [May 17 15:48:22] DEBUG[8325]: app_queue.c:546 changethread: Device 'SIP/station2' changed to state '1' (Not in use) but we don't care because they're not a member of any queue. [May 17 15:48:22] DEBUG[8326]: app_queue.c:546 changethread: Device 'SIP/8055488091' changed to state '1' (Not in use) but we don't care because they're not a member of any queue. [May 17 15:48:22] DEBUG[8304]: pbx.c:1662 pbx_substitute_variables_helper_full: Function result is '' [May 17 15:48:22] DEBUG[8304]: pbx.c:1662 pbx_substitute_variables_helper_full: Function result is '' [May 17 15:48:22] DEBUG[8304]: pbx.c:1662 pbx_substitute_variables_helper_full: Function result is 's' [May 17 15:48:22] DEBUG[8304]: pbx.c:1662 pbx_substitute_variables_helper_full: Function result is 'sla_stations' [May 17 15:48:22] DEBUG[8304]: pbx.c:1662 pbx_substitute_variables_helper_full: Function result is 'SIP/station1-09f4bc70' [May 17 15:48:22] DEBUG[8304]: pbx.c:1662 pbx_substitute_variables_helper_full: Function result is '' [May 17 15:48:22] DEBUG[8304]: pbx.c:1662 pbx_substitute_variables_helper_full: Function result is '' [May 17 15:48:22] DEBUG[8304]: pbx.c:1662 pbx_substitute_variables_helper_full: Function result is '' [May 17 15:48:22] DEBUG[8304]: pbx.c:1662 pbx_substitute_variables_helper_full: Function result is '2007-05-17 15:48:12' [May 17 15:48:22] DEBUG[8304]: pbx.c:1662 pbx_substitute_variables_helper_full: Function result is '' [May 17 15:48:22] DEBUG[8304]: pbx.c:1662 pbx_substitute_variables_helper_full: Function result is '2007-05-17 15:48:22' [May 17 15:48:22] DEBUG[8304]: pbx.c:1662 pbx_substitute_variables_helper_full: Function result is '10' [May 17 15:48:22] DEBUG[8304]: pbx.c:1662 pbx_substitute_variables_helper_full: Function result is '0' [May 17 15:48:22] DEBUG[8304]: pbx.c:1662 pbx_substitute_variables_helper_full: Function result is 'NO ANSWER' [May 17 15:48:22] DEBUG[8304]: pbx.c:1662 pbx_substitute_variables_helper_full: Function result is 'DOCUMENTATION' [May 17 15:48:22] DEBUG[8304]: pbx.c:1662 pbx_substitute_variables_helper_full: Function result is '' [May 17 15:48:22] DEBUG[8304]: pbx.c:1662 pbx_substitute_variables_helper_full: Function result is '1179442092.1' [May 17 15:48:22] DEBUG[8304]: pbx.c:1662 pbx_substitute_variables_helper_full: Function result is '' [May 17 15:48:22] DEBUG[8304]: channel.c:1726 ast_hangup: Hanging up channel 'SIP/station1-09f4bc70' [May 17 15:48:22] DEBUG[8304]: chan_sip.c:3313 sip_hangup: Hangup call SIP/station1-09f4bc70, SIP callid 460e7cf631d31e697f9f7b97421b6e3a@10.50.10.171) [May 17 15:48:22] DEBUG[8304]: chan_sip.c:3336 sip_hangup: Hanging up channel in state Ringing (not UP) Scheduling destruction of SIP dialog '460e7cf631d31e697f9f7b97421b6e3a@10.50.10.171' in 32000 ms (Method: INVITE) [May 17 15:48:22] DEBUG[8304]: chan_sip.c:2072 __sip_ack: Acked pending invite 102 [May 17 15:48:22] DEBUG[8304]: chan_sip.c:2090 __sip_ack: Stopping retransmission on '460e7cf631d31e697f9f7b97421b6e3a@10.50.10.171' of Request 102: Match Not Found Reliably Transmitting (no NAT) to 10.50.10.177:5060: CANCEL sip:station1@10.50.10.177 SIP/2.0 Via: SIP/2.0/UDP 10.50.10.171:5060;branch=z9hG4bK11611bf4;rport From: "WIRELESS CALLER" ;tag=as7fe55b67 To: Call-ID: 460e7cf631d31e697f9f7b97421b6e3a@10.50.10.171 CSeq: 102 CANCEL User-Agent: Asterisk PBX Max-Forwards: 70 Content-Length: 0 --- [May 17 15:48:22] DEBUG[8304]: chan_sip.c:1976 __sip_reliable_xmit: *** SIP TIMER: Initalizing retransmit timer on packet: Id #49 Scheduling destruction of SIP dialog '460e7cf631d31e697f9f7b97421b6e3a@10.50.10.171' in 32000 ms (Method: INVITE) [May 17 15:48:22] DEBUG[8304]: devicestate.c:303 __ast_device_state_changed_literal: Notification of state change to be queued on device/channel SIP/station1-09f4bc70 [May 17 15:48:22] DEBUG[8288]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for SIP - station1 [May 17 15:48:22] DEBUG[8288]: chan_sip.c:15321 sip_devicestate: Checking device state for peer station1 [May 17 15:48:22] DEBUG[8288]: devicestate.c:287 do_state_change: Changing state for SIP/station1 - state 1 (Not in use) [May 17 15:48:22] DEBUG[8327]: channel.c:2911 set_format: Set channel SIP/station2-09f569b8 to write format slin [May 17 15:48:22] DEBUG[8327]: channel.c:2911 set_format: Set channel SIP/station2-09f569b8 to read format slin [May 17 15:48:22] DEBUG[8327]: app_meetme.c:1641 conf_run: Placed channel SIP/station2-09f569b8 in ZAP conf 1023 [May 17 15:48:22] DEBUG[8330]: app_queue.c:546 changethread: Device 'SIP/station1' changed to state '1' (Not in use) but we don't care because they're not a member of any queue. [May 17 15:48:22] DEBUG[8316]: rtp.c:2718 ast_rtp_write: Created smoother: format: 4 ms: 20 len: 160 [May 17 15:48:22] DEBUG[8327]: rtp.c:2701 ast_rtp_write: Ooh, format changed from unknown to ulaw [May 17 15:48:22] DEBUG[8327]: rtp.c:2718 ast_rtp_write: Created smoother: format: 4 ms: 20 len: 160 <--- SIP read from 10.50.10.177:5060 ---> SIP/2.0 200 OK Call-ID: 460e7cf631d31e697f9f7b97421b6e3a@10.50.10.171 CSeq: 102 CANCEL From: "WIRELESS CALLER" ;tag=as7fe55b67 To: ;tag=5413f0b70eba4ba Via: SIP/2.0/UDP 10.50.10.171:5060;branch=z9hG4bK11611bf4;rport Content-Length: 0 Contact: Supported: replaces User-Agent: Aastra 480i/1.4.1.2000 Brcm Callctrl/1.5.1.0 MxSF/v3.2.6.26 <-------------> [May 17 15:48:22] DEBUG[8310]: chan_sip.c:4577 parse_request: Header 0: SIP/2.0 200 OK (14) [May 17 15:48:22] DEBUG[8310]: chan_sip.c:4577 parse_request: Header 1: Call-ID: 460e7cf631d31e697f9f7b97421b6e3a@10.50.10.171 (54) [May 17 15:48:22] DEBUG[8310]: chan_sip.c:4577 parse_request: Header 2: CSeq: 102 CANCEL (16) [May 17 15:48:22] DEBUG[8310]: chan_sip.c:4577 parse_request: Header 3: From: "WIRELESS CALLER" ;tag=as7fe55b67 (68) [May 17 15:48:22] DEBUG[8310]: chan_sip.c:4577 parse_request: Header 4: To: ;tag=5413f0b70eba4ba (51) [May 17 15:48:22] DEBUG[8310]: chan_sip.c:4577 parse_request: Header 5: Via: SIP/2.0/UDP 10.50.10.171:5060;branch=z9hG4bK11611bf4;rport (63) [May 17 15:48:22] DEBUG[8310]: chan_sip.c:4577 parse_request: Header 6: Content-Length: 0 (17) [May 17 15:48:22] DEBUG[8310]: chan_sip.c:4577 parse_request: Header 7: Contact: (36) [May 17 15:48:22] DEBUG[8310]: chan_sip.c:4577 parse_request: Header 8: Supported: replaces (19) [May 17 15:48:22] DEBUG[8310]: chan_sip.c:4577 parse_request: Header 9: User-Agent: Aastra 480i/1.4.1.2000 Brcm Callctrl/1.5.1.0 MxSF/v3.2.6.26 (71) [May 17 15:48:22] DEBUG[8310]: chan_sip.c:4577 parse_request: Header 10: (0) --- (10 headers 0 lines) --- [May 17 15:48:22] DEBUG[8310]: chan_sip.c:2080 __sip_ack: ** SIP TIMER: Cancelling retransmit of packet (reply received) Retransid #49 [May 17 15:48:22] DEBUG[8310]: chan_sip.c:2090 __sip_ack: Stopping retransmission on '460e7cf631d31e697f9f7b97421b6e3a@10.50.10.171' of Request 102: Match Not Found <--- SIP read from 10.50.10.177:5060 ---> SIP/2.0 487 Request Terminated Call-ID: 460e7cf631d31e697f9f7b97421b6e3a@10.50.10.171 CSeq: 102 INVITE From: "WIRELESS CALLER" ;tag=as7fe55b67 To: ;tag=5413f0b70eba4ba Via: SIP/2.0/UDP 10.50.10.171:5060;branch=z9hG4bK11611bf4;rport Content-Length: 0 User-Agent: Aastra 480i/1.4.1.2000 Brcm Callctrl/1.5.1.0 MxSF/v3.2.6.26 <-------------> [May 17 15:48:22] DEBUG[8310]: chan_sip.c:4577 parse_request: Header 0: SIP/2.0 487 Request Terminated (30) [May 17 15:48:22] DEBUG[8310]: chan_sip.c:4577 parse_request: Header 1: Call-ID: 460e7cf631d31e697f9f7b97421b6e3a@10.50.10.171 (54) [May 17 15:48:22] DEBUG[8310]: chan_sip.c:4577 parse_request: Header 2: CSeq: 102 INVITE (16) [May 17 15:48:22] DEBUG[8310]: chan_sip.c:4577 parse_request: Header 3: From: "WIRELESS CALLER" ;tag=as7fe55b67 (68) [May 17 15:48:22] DEBUG[8310]: chan_sip.c:4577 parse_request: Header 4: To: ;tag=5413f0b70eba4ba (51) [May 17 15:48:22] DEBUG[8310]: chan_sip.c:4577 parse_request: Header 5: Via: SIP/2.0/UDP 10.50.10.171:5060;branch=z9hG4bK11611bf4;rport (63) [May 17 15:48:22] DEBUG[8310]: chan_sip.c:4577 parse_request: Header 6: Content-Length: 0 (17) [May 17 15:48:22] DEBUG[8310]: chan_sip.c:4577 parse_request: Header 7: User-Agent: Aastra 480i/1.4.1.2000 Brcm Callctrl/1.5.1.0 MxSF/v3.2.6.26 (71) [May 17 15:48:22] DEBUG[8310]: chan_sip.c:4577 parse_request: Header 8: (0) --- (8 headers 0 lines) --- [May 17 15:48:22] DEBUG[8310]: chan_sip.c:2090 __sip_ack: Stopping retransmission on '460e7cf631d31e697f9f7b97421b6e3a@10.50.10.171' of Request 102: Match Found [May 17 15:48:22] DEBUG[8310]: chan_sip.c:11658 handle_response_invite: SIP response 487 to standard invite Transmitting (no NAT) to 10.50.10.177:5060: ACK sip:station1@10.50.10.177 SIP/2.0 Via: SIP/2.0/UDP 10.50.10.171:5060;branch=z9hG4bK11611bf4;rport From: "WIRELESS CALLER" ;tag=as7fe55b67 To: ;tag=5413f0b70eba4ba Contact: Call-ID: 460e7cf631d31e697f9f7b97421b6e3a@10.50.10.171 CSeq: 102 ACK User-Agent: Asterisk PBX Max-Forwards: 70 Content-Length: 0 --- [May 17 15:48:22] DEBUG[8310]: chan_sip.c:3004 update_call_counter: Updating call counter for outgoing call [May 17 15:48:26] DEBUG[8327]: rtp.c:875 ast_rtcp_read: Got RTCP report of 64 bytes [May 17 15:48:26] DEBUG[8327]: app_meetme.c:2119 conf_run: Got unrecognized frame on channel SIP/station2-09f569b8, f->frametype=5,f->subclass=0 <--- SIP read from 10.50.10.183:5060 ---> BYE sip:8054584444@10.50.10.171 SIP/2.0 Max-Forwards: 70 Content-Length: 0 Via: SIP/2.0/UDP 10.50.10.183;branch=z9hG4bK6692f2862 Call-ID: 6b2fa96c1e9bd58d0cecf5a34c0b73a8@10.50.10.171 From: ;tag=8239a373ed95e9b To: "WIRELESS CALLER" ;tag=as5c54499d CSeq: 1523437192 BYE Supported: timer Call-Info: ;appearance-index=1 Allow-Events: talk,hold,conference Allow:NOTIFY,REFER,OPTIONS,INVITE,ACK,CANCEL,BYE,INFO Supported: replaces User-Agent: Aastra 55i/2.0.1.2000 Brcm-Callctrl/v1.7.2.2 MxSF/v3.6.2.5 <-------------> [May 17 15:48:28] DEBUG[8310]: chan_sip.c:4577 parse_request: Header 0: BYE sip:8054584444@10.50.10.171 SIP/2.0 (39) [May 17 15:48:28] DEBUG[8310]: chan_sip.c:4577 parse_request: Header 1: Max-Forwards: 70 (16) [May 17 15:48:28] DEBUG[8310]: chan_sip.c:4577 parse_request: Header 2: Content-Length: 0 (17) [May 17 15:48:28] DEBUG[8310]: chan_sip.c:4577 parse_request: Header 3: Via: SIP/2.0/UDP 10.50.10.183;branch=z9hG4bK6692f2862 (53) [May 17 15:48:28] DEBUG[8310]: chan_sip.c:4577 parse_request: Header 4: Call-ID: 6b2fa96c1e9bd58d0cecf5a34c0b73a8@10.50.10.171 (54) [May 17 15:48:28] DEBUG[8310]: chan_sip.c:4577 parse_request: Header 5: From: ;tag=8239a373ed95e9b (53) [May 17 15:48:28] DEBUG[8310]: chan_sip.c:4577 parse_request: Header 6: To: "WIRELESS CALLER" ;tag=as5c54499d (66) [May 17 15:48:28] DEBUG[8310]: chan_sip.c:4577 parse_request: Header 7: CSeq: 1523437192 BYE (20) [May 17 15:48:28] DEBUG[8310]: chan_sip.c:4577 parse_request: Header 8: Supported: timer (16) [May 17 15:48:28] DEBUG[8310]: chan_sip.c:4577 parse_request: Header 9: Call-Info: ;appearance-index=1 (48) [May 17 15:48:28] DEBUG[8310]: chan_sip.c:4577 parse_request: Header 10: Allow-Events: talk,hold,conference (34) [May 17 15:48:28] DEBUG[8310]: chan_sip.c:4577 parse_request: Header 11: Allow:NOTIFY,REFER,OPTIONS,INVITE,ACK,CANCEL,BYE,INFO (53) [May 17 15:48:28] DEBUG[8310]: chan_sip.c:4577 parse_request: Header 12: Supported: replaces (19) [May 17 15:48:28] DEBUG[8310]: chan_sip.c:4577 parse_request: Header 13: User-Agent: Aastra 55i/2.0.1.2000 Brcm-Callctrl/v1.7.2.2 MxSF/v3.6.2.5 (70) [May 17 15:48:28] DEBUG[8310]: chan_sip.c:4577 parse_request: Header 14: (0) --- (14 headers 0 lines) --- [May 17 15:48:28] DEBUG[8310]: chan_sip.c:14709 handle_request: **** Received BYE (8) - Command in SIP BYE Sending to 10.50.10.183 : 5060 (no NAT) [May 17 15:48:28] DEBUG[8310]: chan_sip.c:1634 sip_alreadygone: Setting SIP_ALREADYGONE on dialog 6b2fa96c1e9bd58d0cecf5a34c0b73a8@10.50.10.171 [May 17 15:48:28] DEBUG[8310]: chan_sip.c:14263 handle_request_bye: Received bye, issuing owner hangup <--- Transmitting (no NAT) to 10.50.10.183:5060 ---> SIP/2.0 200 OK Via: SIP/2.0/UDP 10.50.10.183;branch=z9hG4bK6692f2862;received=10.50.10.183 From: ;tag=8239a373ed95e9b To: "WIRELESS CALLER" ;tag=as5c54499d Call-ID: 6b2fa96c1e9bd58d0cecf5a34c0b73a8@10.50.10.171 CSeq: 1523437192 BYE User-Agent: Asterisk PBX Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY Supported: replaces Contact: Content-Length: 0 <------------> [May 17 15:48:28] DEBUG[8327]: devicestate.c:303 __ast_device_state_changed_literal: Notification of state change to be queued on device/channel SLA:station1_line2 [May 17 15:48:28] DEBUG[8327]: devicestate.c:303 __ast_device_state_changed_literal: Notification of state change to be queued on device/channel SLA:station2_line2 [May 17 15:48:28] DEBUG[8327]: pbx.c:1662 pbx_substitute_variables_helper_full: Function result is '' [May 17 15:48:28] DEBUG[8327]: pbx.c:1662 pbx_substitute_variables_helper_full: Function result is '' [May 17 15:48:28] DEBUG[8327]: pbx.c:1662 pbx_substitute_variables_helper_full: Function result is 's' [May 17 15:48:28] DEBUG[8327]: pbx.c:1662 pbx_substitute_variables_helper_full: Function result is 'sla_stations' [May 17 15:48:28] DEBUG[8327]: pbx.c:1662 pbx_substitute_variables_helper_full: Function result is 'SIP/station2-09f569b8' [May 17 15:48:28] DEBUG[8327]: pbx.c:1662 pbx_substitute_variables_helper_full: Function result is '' [May 17 15:48:28] DEBUG[8327]: pbx.c:1662 pbx_substitute_variables_helper_full: Function result is '' [May 17 15:48:28] DEBUG[8327]: pbx.c:1662 pbx_substitute_variables_helper_full: Function result is '' [May 17 15:48:28] DEBUG[8327]: pbx.c:1662 pbx_substitute_variables_helper_full: Function result is '2007-05-17 15:48:12' [May 17 15:48:28] DEBUG[8327]: pbx.c:1662 pbx_substitute_variables_helper_full: Function result is '2007-05-17 15:48:22' [May 17 15:48:28] DEBUG[8327]: pbx.c:1662 pbx_substitute_variables_helper_full: Function result is '2007-05-17 15:48:28' [May 17 15:48:28] DEBUG[8327]: pbx.c:1662 pbx_substitute_variables_helper_full: Function result is '16' [May 17 15:48:28] DEBUG[8327]: pbx.c:1662 pbx_substitute_variables_helper_full: Function result is '6' [May 17 15:48:28] DEBUG[8327]: pbx.c:1662 pbx_substitute_variables_helper_full: Function result is 'ANSWERED' [May 17 15:48:28] DEBUG[8327]: pbx.c:1662 pbx_substitute_variables_helper_full: Function result is 'DOCUMENTATION' [May 17 15:48:28] DEBUG[8327]: pbx.c:1662 pbx_substitute_variables_helper_full: Function result is '' [May 17 15:48:28] DEBUG[8327]: pbx.c:1662 pbx_substitute_variables_helper_full: Function result is '1179442092.2' [May 17 15:48:28] DEBUG[8327]: pbx.c:1662 pbx_substitute_variables_helper_full: Function result is '' [May 17 15:48:28] DEBUG[8327]: channel.c:1726 ast_hangup: Hanging up channel 'SIP/station2-09f569b8' [May 17 15:48:28] DEBUG[8327]: chan_sip.c:3313 sip_hangup: Hangup call SIP/station2-09f569b8, SIP callid 6b2fa96c1e9bd58d0cecf5a34c0b73a8@10.50.10.171) [May 17 15:48:28] DEBUG[8327]: devicestate.c:303 __ast_device_state_changed_literal: Notification of state change to be queued on device/channel SIP/station2-09f569b8 [May 17 15:48:28] DEBUG[8316]: devicestate.c:303 __ast_device_state_changed_literal: Notification of state change to be queued on device/channel meetme:SLA_line2 [May 17 15:48:28] DEBUG[8316]: pbx.c:1662 pbx_substitute_variables_helper_full: Function result is '' [May 17 15:48:28] DEBUG[8316]: pbx.c:1662 pbx_substitute_variables_helper_full: Function result is '' [May 17 15:48:28] DEBUG[8316]: pbx.c:1662 pbx_substitute_variables_helper_full: Function result is 's' [May 17 15:48:28] DEBUG[8316]: pbx.c:1662 pbx_substitute_variables_helper_full: Function result is 'default' [May 17 15:48:28] DEBUG[8316]: pbx.c:1662 pbx_substitute_variables_helper_full: Function result is 'Zap/pseudo-377676547' [May 17 15:48:28] DEBUG[8316]: pbx.c:1662 pbx_substitute_variables_helper_full: Function result is '' [May 17 15:48:28] DEBUG[8316]: pbx.c:1662 pbx_substitute_variables_helper_full: Function result is '' [May 17 15:48:28] DEBUG[8316]: pbx.c:1662 pbx_substitute_variables_helper_full: Function result is '' [May 17 15:48:28] DEBUG[8316]: pbx.c:1662 pbx_substitute_variables_helper_full: Function result is '2007-05-17 15:48:12' [May 17 15:48:28] DEBUG[8316]: pbx.c:1662 pbx_substitute_variables_helper_full: Function result is '' [May 17 15:48:28] DEBUG[8316]: pbx.c:1662 pbx_substitute_variables_helper_full: Function result is '2007-05-17 15:48:28' [May 17 15:48:28] DEBUG[8316]: pbx.c:1662 pbx_substitute_variables_helper_full: Function result is '16' [May 17 15:48:28] DEBUG[8316]: pbx.c:1662 pbx_substitute_variables_helper_full: Function result is '0' [May 17 15:48:28] DEBUG[8316]: pbx.c:1662 pbx_substitute_variables_helper_full: Function result is 'NO ANSWER' [May 17 15:48:28] DEBUG[8316]: pbx.c:1662 pbx_substitute_variables_helper_full: Function result is 'DOCUMENTATION' [May 17 15:48:28] DEBUG[8316]: pbx.c:1662 pbx_substitute_variables_helper_full: Function result is '' [May 17 15:48:28] DEBUG[8316]: pbx.c:1662 pbx_substitute_variables_helper_full: Function result is '1179442092.3' [May 17 15:48:28] DEBUG[8316]: pbx.c:1662 pbx_substitute_variables_helper_full: Function result is '' [May 17 15:48:28] DEBUG[8316]: channel.c:1726 ast_hangup: Hanging up channel 'Zap/pseudo-377676547' [May 17 15:48:28] DEBUG[8316]: chan_zap.c:2412 zt_hangup: zt_hangup(Zap/pseudo-377676547) [May 17 15:48:28] DEBUG[8316]: chan_zap.c:2446 zt_hangup: Hangup: channel: -2 index = 0, normal = 30, callwait = -1, thirdcall = -1 [May 17 15:48:28] DEBUG[8316]: chan_zap.c:2874 zt_setoption: Set option TDD MODE, value: OFF(0) on Zap/pseudo-377676547 [May 17 15:48:28] DEBUG[8316]: chan_zap.c:1403 update_conf: Updated conferencing on -2, with 0 conference users -- Hungup 'Zap/pseudo-377676547' [May 17 15:48:28] DEBUG[8316]: devicestate.c:303 __ast_device_state_changed_literal: Notification of state change to be queued on device/channel Zap/pseudo-377676547 [May 17 15:48:28] DEBUG[8316]: pbx.c:1809 pbx_extension_helper: Launching 'VoiceMail' -- Executing [8055488092@line2:2] VoiceMail("SIP/8055488091-09f4a6f0", "5480617|u") in new stack [May 17 15:48:28] DEBUG[8316]: app_voicemail.c:2852 leave_voicemail: Before find_user [May 17 15:48:28] DEBUG[8288]: devicestate.c:157 ast_device_state: Checking if I can find provider for "SLA" - number: station1_line2 [May 17 15:48:28] DEBUG[8288]: devicestate.c:287 do_state_change: Changing state for SLA:station1_line2 - state 1 (Not in use) [May 17 15:48:28] DEBUG[8288]: devicestate.c:157 ast_device_state: Checking if I can find provider for "SLA" - number: station1_line2 [May 17 15:48:28] DEBUG[8288]: devicestate.c:157 ast_device_state: Checking if I can find provider for "SLA" - number: station2_line2 [May 17 15:48:28] DEBUG[8288]: devicestate.c:287 do_state_change: Changing state for SLA:station2_line2 - state 1 (Not in use) [May 17 15:48:28] DEBUG[8288]: devicestate.c:157 ast_device_state: Checking if I can find provider for "SLA" - number: station2_line2 [May 17 15:48:28] DEBUG[8288]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for SIP - station2 [May 17 15:48:28] DEBUG[8288]: chan_sip.c:15321 sip_devicestate: Checking device state for peer station2 [May 17 15:48:28] DEBUG[8288]: devicestate.c:287 do_state_change: Changing state for SIP/station2 - state 1 (Not in use) [May 17 15:48:28] DEBUG[8288]: devicestate.c:157 ast_device_state: Checking if I can find provider for "meetme" - number: SLA_line2 [May 17 15:48:28] DEBUG[8288]: devicestate.c:287 do_state_change: Changing state for meetme:SLA_line2 - state 4 (Invalid) [May 17 15:48:28] DEBUG[8288]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for Zap - pseudo [May 17 15:48:28] DEBUG[8288]: devicestate.c:287 do_state_change: Changing state for Zap/pseudo - state 0 (Unknown) [May 17 15:48:28] DEBUG[8333]: app_queue.c:546 changethread: Device 'SIP/station2' changed to state '1' (Not in use) but we don't care because they're not a member of any queue. [May 17 15:48:28] DEBUG[8335]: app_queue.c:546 changethread: Device 'Zap/pseudo' changed to state '0' (Unknown) but we don't care because they're not a member of any queue. [May 17 15:48:28] DEBUG[8316]: channel.c:2030 ast_settimeout: Scheduling timer at 160 sample intervals -- Playing '/var/spool/asterisk/voicemail/default/5480617/unavail' (language 'en') Really destroying SIP dialog '6b2fa96c1e9bd58d0cecf5a34c0b73a8@10.50.10.171' Method: BYE