[Apr 13 13:59:30] Asterisk 1.4.19-rc2, Copyright (C) 1999 - 2008 Digium, Inc. and others. [Apr 13 14:00:07] <--- SIP read from 10.50.10.183:5060 ---> INVITE sip:station3_line1@10.50.10.171:5060 SIP/2.0 Via: SIP/2.0/UDP 10.50.10.183:5060;branch=z9hG4bK9dc8dcc01b5c48f2a Max-Forwards: 70 From: "PowerPBX 23" ;tag=4798cebe7e To: "station3_line1" Call-ID: 071ad47524e1b4e8 CSeq: 12811 INVITE Allow: INVITE, ACK, CANCEL, BYE, NOTIFY, REFER, OPTIONS, UPDATE, PRACK, SUBSCRIBE, INFO Allow-Events: talk, hold, conference Contact: PowerPBX 23 Supported: timer, 100rel, replaces User-Agent: Aastra 55i/2.2.0.166 Content-Type: application/sdp Content-Length: 282 v=0 o=MxSIP 0 0 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 18 101 a=rtpmap:0 PCMU/8000 a=rtpmap:8 PCMA/8000 a=rtpmap:18 G729/8000 a=rtpmap:101 telephone-event/8000 a=silenceSupp:on - - - - a=fmtp:101 0-15 a=ptime:30 a=sendrecv <-------------> [Apr 13 14:00:07] DEBUG[4330]: chan_sip.c:4794 parse_request: Header 0: INVITE sip:station3_line1@10.50.10.171:5060 SIP/2.0 (51) [Apr 13 14:00:07] DEBUG[4330]: chan_sip.c:4794 parse_request: Header 1: Via: SIP/2.0/UDP 10.50.10.183:5060;branch=z9hG4bK9dc8dcc01b5c48f2a (66) [Apr 13 14:00:07] DEBUG[4330]: chan_sip.c:4794 parse_request: Header 2: Max-Forwards: 70 (16) [Apr 13 14:00:07] DEBUG[4330]: chan_sip.c:4794 parse_request: Header 3: From: "PowerPBX 23" ;tag=4798cebe7e (67) [Apr 13 14:00:07] DEBUG[4330]: chan_sip.c:4794 parse_request: Header 4: To: "station3_line1" (59) [Apr 13 14:00:07] DEBUG[4330]: chan_sip.c:4794 parse_request: Header 5: Call-ID: 071ad47524e1b4e8 (25) [Apr 13 14:00:07] DEBUG[4330]: chan_sip.c:4794 parse_request: Header 6: CSeq: 12811 INVITE (18) [Apr 13 14:00:07] DEBUG[4330]: chan_sip.c:4794 parse_request: Header 7: Allow: INVITE, ACK, CANCEL, BYE, NOTIFY, REFER, OPTIONS, UPDATE, PRACK, SUBSCRIBE, INFO (87) [Apr 13 14:00:07] DEBUG[4330]: chan_sip.c:4794 parse_request: Header 8: Allow-Events: talk, hold, conference (36) [Apr 13 14:00:07] DEBUG[4330]: chan_sip.c:4794 parse_request: Header 9: Contact: PowerPBX 23 (67) [Apr 13 14:00:07] DEBUG[4330]: chan_sip.c:4794 parse_request: Header 10: Supported: timer, 100rel, replaces (34) [Apr 13 14:00:07] DEBUG[4330]: chan_sip.c:4794 parse_request: Header 11: User-Agent: Aastra 55i/2.2.0.166 (32) [Apr 13 14:00:07] DEBUG[4330]: chan_sip.c:4794 parse_request: Header 12: Content-Type: application/sdp (29) [Apr 13 14:00:07] DEBUG[4330]: chan_sip.c:4794 parse_request: Header 13: Content-Length: 282 (19) [Apr 13 14:00:07] DEBUG[4330]: chan_sip.c:4794 parse_request: Header 14: (0) [Apr 13 14:00:07] DEBUG[4330]: chan_sip.c:4826 parse_request: Line: v=0 (3) [Apr 13 14:00:07] DEBUG[4330]: chan_sip.c:4826 parse_request: Line: o=MxSIP 0 0 IN IP4 10.50.10.183 (31) [Apr 13 14:00:07] DEBUG[4330]: chan_sip.c:4826 parse_request: Line: s=SIP Call (10) [Apr 13 14:00:07] DEBUG[4330]: chan_sip.c:4826 parse_request: Line: c=IN IP4 10.50.10.183 (21) [Apr 13 14:00:07] DEBUG[4330]: chan_sip.c:4826 parse_request: Line: t=0 0 (5) [Apr 13 14:00:07] DEBUG[4330]: chan_sip.c:4826 parse_request: Line: m=audio 3000 RTP/AVP 0 8 18 101 (31) [Apr 13 14:00:07] DEBUG[4330]: chan_sip.c:4826 parse_request: Line: a=rtpmap:0 PCMU/8000 (20) [Apr 13 14:00:07] DEBUG[4330]: chan_sip.c:4826 parse_request: Line: a=rtpmap:8 PCMA/8000 (20) [Apr 13 14:00:07] DEBUG[4330]: chan_sip.c:4826 parse_request: Line: a=rtpmap:18 G729/8000 (21) [Apr 13 14:00:07] DEBUG[4330]: chan_sip.c:4826 parse_request: Line: a=rtpmap:101 telephone-event/8000 (33) [Apr 13 14:00:07] DEBUG[4330]: chan_sip.c:4826 parse_request: Line: a=silenceSupp:on - - - - (24) [Apr 13 14:00:07] DEBUG[4330]: chan_sip.c:4826 parse_request: Line: a=fmtp:101 0-15 (15) [Apr 13 14:00:07] DEBUG[4330]: chan_sip.c:4826 parse_request: Line: a=ptime:30 (10) [Apr 13 14:00:07] --- (14 headers 14 lines) --- [Apr 13 14:00:07] DEBUG[4330]: chan_sip.c:4566 find_call: = Looking for Call ID: 071ad47524e1b4e8 (Checking From) --From tag 4798cebe7e --To-tag [Apr 13 14:00:07] DEBUG[4330]: chan_sip.c:4582 find_call: = No match Their Call ID: CEDB0C22@metaswitch Their Tag metaswitch+1+0+bf1272c3 Our tag: as11e9e6a5 [Apr 13 14:00:07] DEBUG[4330]: chan_sip.c:2741 do_setnat: Setting NAT on RTP to Off [Apr 13 14:00:07] DEBUG[4330]: chan_sip.c:4529 sip_alloc: Allocating new SIP dialog for 071ad47524e1b4e8 - INVITE (With RTP) [Apr 13 14:00:07] DEBUG[4330]: chan_sip.c:15219 handle_request: **** Received INVITE (5) - Command in SIP INVITE [Apr 13 14:00:07] DEBUG[4330]: chan_sip.c:1702 parse_sip_options: Begin: parsing SIP "Supported: timer, 100rel, replaces" [Apr 13 14:00:07] DEBUG[4330]: chan_sip.c:1710 parse_sip_options: Found SIP option: -timer- [Apr 13 14:00:07] DEBUG[4330]: chan_sip.c:1716 parse_sip_options: Matched SIP option: timer [Apr 13 14:00:07] DEBUG[4330]: chan_sip.c:1710 parse_sip_options: Found SIP option: -100rel- [Apr 13 14:00:07] DEBUG[4330]: chan_sip.c:1716 parse_sip_options: Matched SIP option: 100rel [Apr 13 14:00:07] DEBUG[4330]: chan_sip.c:1710 parse_sip_options: Found SIP option: -replaces- [Apr 13 14:00:07] DEBUG[4330]: chan_sip.c:1716 parse_sip_options: Matched SIP option: replaces [Apr 13 14:00:07] Sending to 10.50.10.183 : 5060 (no NAT) [Apr 13 14:00:07] Using INVITE request as basis request - 071ad47524e1b4e8 [Apr 13 14:00:07] DEBUG[4330]: chan_sip.c:2741 do_setnat: Setting NAT on RTP to Off [Apr 13 14:00:07] <--- Reliably Transmitting (no NAT) to 10.50.10.183:5060 ---> SIP/2.0 407 Proxy Authentication Required Via: SIP/2.0/UDP 10.50.10.183:5060;branch=z9hG4bK9dc8dcc01b5c48f2a;received=10.50.10.183 From: "PowerPBX 23" ;tag=4798cebe7e To: "station3_line1" ;tag=as338b9eef Call-ID: 071ad47524e1b4e8 CSeq: 12811 INVITE User-Agent: Asterisk PBX Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY Supported: replaces Proxy-Authenticate: Digest algorithm=MD5, realm="asterisk", nonce="7388fa45" Content-Length: 0 <------------> [Apr 13 14:00:07] DEBUG[4330]: chan_sip.c:2043 __sip_reliable_xmit: *** SIP TIMER: Initializing retransmit timer on packet: Id #-1 [Apr 13 14:00:07] Scheduling destruction of SIP dialog '071ad47524e1b4e8' in 32000 ms (Method: INVITE) [Apr 13 14:00:07] Found user 'station3' [Apr 13 14:00:07] <--- SIP read from 10.50.10.183:5060 ---> ACK sip:station3_line1@10.50.10.171:5060 SIP/2.0 Via: SIP/2.0/UDP 10.50.10.183:5060;branch=z9hG4bK9dc8dcc01b5c48f2a Max-Forwards: 70 From: "PowerPBX 23" ;tag=4798cebe7e To: "station3_line1" ;tag=as338b9eef Call-ID: 071ad47524e1b4e8 CSeq: 12811 ACK User-Agent: Aastra 55i/2.2.0.166 Content-Length: 0 <-------------> [Apr 13 14:00:07] DEBUG[4330]: chan_sip.c:4794 parse_request: Header 0: ACK sip:station3_line1@10.50.10.171:5060 SIP/2.0 (48) [Apr 13 14:00:07] DEBUG[4330]: chan_sip.c:4794 parse_request: Header 1: Via: SIP/2.0/UDP 10.50.10.183:5060;branch=z9hG4bK9dc8dcc01b5c48f2a (66) [Apr 13 14:00:07] DEBUG[4330]: chan_sip.c:4794 parse_request: Header 2: Max-Forwards: 70 (16) [Apr 13 14:00:07] DEBUG[4330]: chan_sip.c:4794 parse_request: Header 3: From: "PowerPBX 23" ;tag=4798cebe7e (67) [Apr 13 14:00:07] DEBUG[4330]: chan_sip.c:4794 parse_request: Header 4: To: "station3_line1" ;tag=as338b9eef (74) [Apr 13 14:00:07] DEBUG[4330]: chan_sip.c:4794 parse_request: Header 5: Call-ID: 071ad47524e1b4e8 (25) [Apr 13 14:00:07] DEBUG[4330]: chan_sip.c:4794 parse_request: Header 6: CSeq: 12811 ACK (15) [Apr 13 14:00:07] DEBUG[4330]: chan_sip.c:4794 parse_request: Header 7: User-Agent: Aastra 55i/2.2.0.166 (32) [Apr 13 14:00:07] DEBUG[4330]: chan_sip.c:4794 parse_request: Header 8: Content-Length: 0 (17) [Apr 13 14:00:07] --- (9 headers 0 lines) --- [Apr 13 14:00:07] DEBUG[4330]: chan_sip.c:4566 find_call: = Looking for Call ID: 071ad47524e1b4e8 (Checking From) --From tag 4798cebe7e --To-tag as338b9eef [Apr 13 14:00:07] DEBUG[4330]: chan_sip.c:4582 find_call: = Found Their Call ID: 071ad47524e1b4e8 Their Tag 4798cebe7e Our tag: as338b9eef [Apr 13 14:00:07] DEBUG[4330]: chan_sip.c:15219 handle_request: **** Received ACK (6) - Command in SIP ACK [Apr 13 14:00:07] DEBUG[4330]: chan_sip.c:2166 __sip_ack: ** SIP TIMER: Cancelling retransmit of packet (reply received) Retransid #37 [Apr 13 14:00:07] DEBUG[4330]: chan_sip.c:2175 __sip_ack: Stopping retransmission on '071ad47524e1b4e8' of Response 12811: Match Found [Apr 13 14:00:07] <--- SIP read from 10.50.10.183:5060 ---> INVITE sip:station3_line1@10.50.10.171:5060 SIP/2.0 Via: SIP/2.0/UDP 10.50.10.183:5060;branch=z9hG4bK80271598d63ab70b3 Proxy-Authorization: Digest username="station3",realm="asterisk",nonce="7388fa45",uri="sip:station3_line1@10.50.10.171:5060",response="e8cbade8d4b48faa89530c06e6e61c58",algorithm=MD5 Max-Forwards: 70 From: "PowerPBX 23" ;tag=4798cebe7e To: "station3_line1" Call-ID: 071ad47524e1b4e8 CSeq: 12812 INVITE Allow: INVITE, ACK, CANCEL, BYE, NOTIFY, REFER, OPTIONS, UPDATE, PRACK, SUBSCRIBE, INFO Allow-Events: talk, hold, conference Contact: PowerPBX 23 Supported: timer, 100rel, replaces User-Agent: Aastra 55i/2.2.0.166 Content-Type: application/sdp Content-Length: 282 v=0 o=MxSIP 0 0 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 18 101 a=rtpmap:0 PCMU/8000 a=rtpmap:8 PCMA/8000 a=rtpmap:18 G729/8000 a=rtpmap:101 telephone-event/8000 a=silenceSupp:on - - - - a=fmtp:101 0-15 a=ptime:30 a=sendrecv <-------------> [Apr 13 14:00:07] DEBUG[4330]: chan_sip.c:4794 parse_request: Header 0: INVITE sip:station3_line1@10.50.10.171:5060 SIP/2.0 (51) [Apr 13 14:00:07] DEBUG[4330]: chan_sip.c:4794 parse_request: Header 1: Via: SIP/2.0/UDP 10.50.10.183:5060;branch=z9hG4bK80271598d63ab70b3 (66) [Apr 13 14:00:07] DEBUG[4330]: chan_sip.c:4794 parse_request: Header 2: Proxy-Authorization: Digest username="station3",realm="asterisk",nonce="7388fa45",uri="sip:station3_line1@10.50.10.171:5060",response="e8cbade8d4b48faa89530c06e6e61c58",algorithm=MD5 (182) [Apr 13 14:00:07] DEBUG[4330]: chan_sip.c:4794 parse_request: Header 3: Max-Forwards: 70 (16) [Apr 13 14:00:07] DEBUG[4330]: chan_sip.c:4794 parse_request: Header 4: From: "PowerPBX 23" ;tag=4798cebe7e (67) [Apr 13 14:00:07] DEBUG[4330]: chan_sip.c:4794 parse_request: Header 5: To: "station3_line1" (59) [Apr 13 14:00:07] DEBUG[4330]: chan_sip.c:4794 parse_request: Header 6: Call-ID: 071ad47524e1b4e8 (25) [Apr 13 14:00:07] DEBUG[4330]: chan_sip.c:4794 parse_request: Header 7: CSeq: 12812 INVITE (18) [Apr 13 14:00:07] DEBUG[4330]: chan_sip.c:4794 parse_request: Header 8: Allow: INVITE, ACK, CANCEL, BYE, NOTIFY, REFER, OPTIONS, UPDATE, PRACK, SUBSCRIBE, INFO (87) [Apr 13 14:00:07] DEBUG[4330]: chan_sip.c:4794 parse_request: Header 9: Allow-Events: talk, hold, conference (36) [Apr 13 14:00:07] DEBUG[4330]: chan_sip.c:4794 parse_request: Header 10: Contact: PowerPBX 23 (67) [Apr 13 14:00:07] DEBUG[4330]: chan_sip.c:4794 parse_request: Header 11: Supported: timer, 100rel, replaces (34) [Apr 13 14:00:07] DEBUG[4330]: chan_sip.c:4794 parse_request: Header 12: User-Agent: Aastra 55i/2.2.0.166 (32) [Apr 13 14:00:07] DEBUG[4330]: chan_sip.c:4794 parse_request: Header 13: Content-Type: application/sdp (29) [Apr 13 14:00:07] DEBUG[4330]: chan_sip.c:4794 parse_request: Header 14: Content-Length: 282 (19) [Apr 13 14:00:07] DEBUG[4330]: chan_sip.c:4794 parse_request: Header 15: (0) [Apr 13 14:00:07] DEBUG[4330]: chan_sip.c:4826 parse_request: Line: v=0 (3) [Apr 13 14:00:07] DEBUG[4330]: chan_sip.c:4826 parse_request: Line: o=MxSIP 0 0 IN IP4 10.50.10.183 (31) [Apr 13 14:00:07] DEBUG[4330]: chan_sip.c:4826 parse_request: Line: s=SIP Call (10) [Apr 13 14:00:07] DEBUG[4330]: chan_sip.c:4826 parse_request: Line: c=IN IP4 10.50.10.183 (21) [Apr 13 14:00:07] DEBUG[4330]: chan_sip.c:4826 parse_request: Line: t=0 0 (5) [Apr 13 14:00:07] DEBUG[4330]: chan_sip.c:4826 parse_request: Line: m=audio 3000 RTP/AVP 0 8 18 101 (31) [Apr 13 14:00:07] DEBUG[4330]: chan_sip.c:4826 parse_request: Line: a=rtpmap:0 PCMU/8000 (20) [Apr 13 14:00:07] DEBUG[4330]: chan_sip.c:4826 parse_request: Line: a=rtpmap:8 PCMA/8000 (20) [Apr 13 14:00:07] DEBUG[4330]: chan_sip.c:4826 parse_request: Line: a=rtpmap:18 G729/8000 (21) [Apr 13 14:00:07] DEBUG[4330]: chan_sip.c:4826 parse_request: Line: a=rtpmap:101 telephone-event/8000 (33) [Apr 13 14:00:07] DEBUG[4330]: chan_sip.c:4826 parse_request: Line: a=silenceSupp:on - - - - (24) [Apr 13 14:00:07] DEBUG[4330]: chan_sip.c:4826 parse_request: Line: a=fmtp:101 0-15 (15) [Apr 13 14:00:07] DEBUG[4330]: chan_sip.c:4826 parse_request: Line: a=ptime:30 (10) [Apr 13 14:00:07] --- (15 headers 14 lines) --- [Apr 13 14:00:07] DEBUG[4330]: chan_sip.c:4566 find_call: = Looking for Call ID: 071ad47524e1b4e8 (Checking From) --From tag 4798cebe7e --To-tag [Apr 13 14:00:07] DEBUG[4330]: chan_sip.c:4582 find_call: = Found Their Call ID: 071ad47524e1b4e8 Their Tag 4798cebe7e Our tag: as338b9eef [Apr 13 14:00:07] DEBUG[4330]: chan_sip.c:15219 handle_request: **** Received INVITE (5) - Command in SIP INVITE [Apr 13 14:00:07] Sending to 10.50.10.183 : 5060 (no NAT) [Apr 13 14:00:07] Using INVITE request as basis request - 071ad47524e1b4e8 [Apr 13 14:00:07] DEBUG[4330]: chan_sip.c:2741 do_setnat: Setting NAT on RTP to Off [Apr 13 14:00:07] Found user 'station3' [Apr 13 14:00:07] Found RTP audio format 0 [Apr 13 14:00:07] Found RTP audio format 8 [Apr 13 14:00:07] Found RTP audio format 18 [Apr 13 14:00:07] Found RTP audio format 101 [Apr 13 14:00:07] Peer audio RTP is at port 10.50.10.183:3000 [Apr 13 14:00:07] Found audio description format PCMU for ID 0 [Apr 13 14:00:07] Found audio description format PCMA for ID 8 [Apr 13 14:00:07] Found audio description format G729 for ID 18 [Apr 13 14:00:07] Found audio description format telephone-event for ID 101 [Apr 13 14:00:07] Got unsupported a:fmtp in SDP offer [Apr 13 14:00:07] DEBUG[4330]: chan_sip.c:5411 process_sdp: T38 state changed to 0 on channel [Apr 13 14:00:07] Capabilities: us - 0xe (gsm|ulaw|alaw), peer - audio=0x10c (ulaw|alaw|g729)/video=0x0 (nothing), combined - 0xc (ulaw|alaw) [Apr 13 14:00:07] Non-codec capabilities (dtmf): us - 0x1 (telephone-event), peer - 0x1 (telephone-event), combined - 0x1 (telephone-event) [Apr 13 14:00:07] Peer audio RTP is at port 10.50.10.183:3000 [Apr 13 14:00:07] DEBUG[4330]: chan_sip.c:5491 process_sdp: We're settling with these formats: 0xc (ulaw|alaw) [Apr 13 14:00:07] DEBUG[4330]: chan_sip.c:13887 handle_request_invite: Checking SIP call limits for device station3 [Apr 13 14:00:07] DEBUG[4330]: chan_sip.c:3186 update_call_counter: Updating call counter for incoming call [Apr 13 14:00:07] Looking for station3_line1 in sla_stations (domain 10.50.10.171) [Apr 13 14:00:07] DEBUG[4330]: chan_sip.c:4013 sip_new: *** Our native formats are 0x4 (ulaw) [Apr 13 14:00:07] DEBUG[4330]: chan_sip.c:4014 sip_new: *** Joint capabilities are 0xc (ulaw|alaw) [Apr 13 14:00:07] DEBUG[4330]: chan_sip.c:4015 sip_new: *** Our capabilities are 0xe (gsm|ulaw|alaw) [Apr 13 14:00:07] DEBUG[4330]: chan_sip.c:4016 sip_new: *** AST_CODEC_CHOOSE formats are 0x4 (ulaw) [Apr 13 14:00:07] DEBUG[4330]: chan_sip.c:4039 sip_new: This channel will not be able to handle video. [Apr 13 14:00:07] DEBUG[4330]: chan_sip.c:8263 build_route: build_route: Contact hop: PowerPBX 23 [Apr 13 14:00:07] list_route: hop: [Apr 13 14:00:07] DEBUG[4330]: chan_sip.c:13966 handle_request_invite: SIP/station3-09717830: New call is still down.... Trying... [Apr 13 14:00:07] <--- Transmitting (no NAT) to 10.50.10.183:5060 ---> SIP/2.0 100 Trying Via: SIP/2.0/UDP 10.50.10.183:5060;branch=z9hG4bK80271598d63ab70b3;received=10.50.10.183 From: "PowerPBX 23" ;tag=4798cebe7e To: "station3_line1" Call-ID: 071ad47524e1b4e8 CSeq: 12812 INVITE User-Agent: Asterisk PBX Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY Supported: replaces Contact: Content-Length: 0 <------------> [Apr 13 14:00:07] DEBUG[4330]: devicestate.c:304 __ast_device_state_changed_literal: Notification of state change to be queued on device/channel SIP/station3-09717830 [Apr 13 14:00:07] DEBUG[4330]: devicestate.c:304 __ast_device_state_changed_literal: Notification of state change to be queued on device/channel SIP/station3 [Apr 13 14:00:07] DEBUG[4308]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for SIP - station3-09717830 [Apr 13 14:00:07] DEBUG[4308]: chan_sip.c:15855 sip_devicestate: Checking device state for peer station3-09717830 [Apr 13 14:00:07] DEBUG[4308]: devicestate.c:287 do_state_change: Changing state for SIP/station3-09717830 - state 4 (Invalid) [Apr 13 14:00:07] DEBUG[4308]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for SIP - station3 [Apr 13 14:00:07] DEBUG[4308]: chan_sip.c:15855 sip_devicestate: Checking device state for peer station3 [Apr 13 14:00:07] DEBUG[4308]: devicestate.c:287 do_state_change: Changing state for SIP/station3 - state 1 (Not in use) [Apr 13 14:00:07] DEBUG[4333]: app_queue.c:609 handle_statechange: Device 'SIP/station3-09717830' changed to state '4' (Invalid) but we don't care because they're not a member of any queue. [Apr 13 14:00:07] DEBUG[4333]: app_queue.c:609 handle_statechange: Device 'SIP/station3' changed to state '1' (Not in use) but we don't care because they're not a member of any queue. [Apr 13 14:00:07] DEBUG[4338]: pbx.c:1839 pbx_extension_helper: Launching 'SLAStation' [Apr 13 14:00:07] -- Executing [station3_line1@sla_stations:1] SLAStation("SIP/station3-09717830", "station3_line1") in new stack [Apr 13 14:00:07] DEBUG[4338]: devicestate.c:304 __ast_device_state_changed_literal: Notification of state change to be queued on device/channel SLA:station1_line1 [Apr 13 14:00:07] DEBUG[4308]: devicestate.c:157 ast_device_state: Checking if I can find provider for "SLA" - number: station1_line1 [Apr 13 14:00:07] DEBUG[4308]: devicestate.c:230 getproviderstate: Checking provider SLA with SLA [Apr 13 14:00:07] DEBUG[4308]: devicestate.c:287 do_state_change: Changing state for SLA:station1_line1 - state 2 (In use) [Apr 13 14:00:07] DEBUG[4308]: devicestate.c:157 ast_device_state: Checking if I can find provider for "SLA" - number: station1_line1 [Apr 13 14:00:07] DEBUG[4308]: devicestate.c:230 getproviderstate: Checking provider SLA with SLA [Apr 13 14:00:07] DEBUG[4338]: devicestate.c:304 __ast_device_state_changed_literal: Notification of state change to be queued on device/channel SLA:station2_line1 [Apr 13 14:00:07] DEBUG[4308]: devicestate.c:157 ast_device_state: Checking if I can find provider for "SLA" - number: station2_line1 [Apr 13 14:00:07] DEBUG[4308]: devicestate.c:230 getproviderstate: Checking provider SLA with SLA [Apr 13 14:00:07] DEBUG[4308]: devicestate.c:287 do_state_change: Changing state for SLA:station2_line1 - state 2 (In use) [Apr 13 14:00:07] DEBUG[4308]: devicestate.c:157 ast_device_state: Checking if I can find provider for "SLA" - number: station2_line1 [Apr 13 14:00:07] DEBUG[4308]: devicestate.c:230 getproviderstate: Checking provider SLA with SLA [Apr 13 14:00:07] DEBUG[4338]: devicestate.c:304 __ast_device_state_changed_literal: Notification of state change to be queued on device/channel SLA:station3_line1 [Apr 13 14:00:07] DEBUG[4308]: devicestate.c:157 ast_device_state: Checking if I can find provider for "SLA" - number: station3_line1 [Apr 13 14:00:07] DEBUG[4308]: devicestate.c:230 getproviderstate: Checking provider SLA with SLA [Apr 13 14:00:07] DEBUG[4308]: devicestate.c:287 do_state_change: Changing state for SLA:station3_line1 - state 2 (In use) [Apr 13 14:00:07] DEBUG[4308]: devicestate.c:157 ast_device_state: Checking if I can find provider for "SLA" - number: station3_line1 [Apr 13 14:00:07] DEBUG[4308]: devicestate.c:230 getproviderstate: Checking provider SLA with SLA [Apr 13 14:00:07] DEBUG[4340]: channel.c:3293 ast_channel_inherit_variables: Not copying variable SIPCALLID. [Apr 13 14:00:07] DEBUG[4340]: channel.c:3293 ast_channel_inherit_variables: Not copying variable SIPUSERAGENT. [Apr 13 14:00:07] DEBUG[4340]: channel.c:3293 ast_channel_inherit_variables: Not copying variable SIPDOMAIN. [Apr 13 14:00:07] DEBUG[4340]: channel.c:3293 ast_channel_inherit_variables: Not copying variable SIPURI. [Apr 13 14:00:07] -- Called disa@line1_outbound [Apr 13 14:00:07] DEBUG[4341]: pbx.c:1839 pbx_extension_helper: Launching 'DISA' [Apr 13 14:00:07] -- Executing [disa@line1_outbound:1] DISA("Local/disa@line1_outbound-00fe,2", "no-password|line1_outbound") in new stack [Apr 13 14:00:07] DEBUG[4341]: app_disa.c:157 disa_exec: Digittimeout: 5000 [Apr 13 14:00:07] DEBUG[4341]: app_disa.c:158 disa_exec: Responsetimeout: 10000 [Apr 13 14:00:07] DEBUG[4341]: app_disa.c:169 disa_exec: Mailbox: [Apr 13 14:00:07] DEBUG[4341]: devicestate.c:304 __ast_device_state_changed_literal: Notification of state change to be queued on device/channel Local/disa@line1_outbound-00fe,2 [Apr 13 14:00:07] DEBUG[4308]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for Local - disa@line1_outbound-00fe,2 [Apr 13 14:00:07] DEBUG[4308]: chan_local.c:145 local_devicestate: Checking if extension disa@line1_outbound-00fe,2 exists (devicestate) [Apr 13 14:00:07] DEBUG[4308]: devicestate.c:287 do_state_change: Changing state for Local/disa@line1_outbound-00fe,2 - state 4 (Invalid) [Apr 13 14:00:07] DEBUG[4333]: app_queue.c:609 handle_statechange: Device 'Local/disa@line1_outbound-00fe,2' changed to state '4' (Invalid) but we don't care because they're not a member of any queue. [Apr 13 14:00:07] DEBUG[4341]: devicestate.c:304 __ast_device_state_changed_literal: Notification of state change to be queued on device/channel Local/disa@line1_outbound [Apr 13 14:00:07] DEBUG[4308]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for Local - disa@line1_outbound [Apr 13 14:00:07] DEBUG[4308]: chan_local.c:145 local_devicestate: Checking if extension disa@line1_outbound exists (devicestate) [Apr 13 14:00:07] DEBUG[4308]: channel.c:1068 channel_find_locked: Avoiding initial deadlock for channel '0x9712b30' [Apr 13 14:00:07] DEBUG[4308]: channel.c:1068 channel_find_locked: Avoiding initial deadlock for channel '0x9712b30' [Apr 13 14:00:07] DEBUG[4341]: app_disa.c:186 disa_exec: Context: line1_outbound [Apr 13 14:00:07] DEBUG[4341]: app_disa.c:190 disa_exec: DISA no-password login success [Apr 13 14:00:07] DEBUG[4308]: devicestate.c:287 do_state_change: Changing state for Local/disa@line1_outbound - state 2 (In use) [Apr 13 14:00:07] DEBUG[4333]: app_queue.c:609 handle_statechange: Device 'Local/disa@line1_outbound' changed to state '2' (In use) but we don't care because they're not a member of any queue. [Apr 13 14:00:07] DEBUG[4341]: channel.c:2778 set_format: Set channel Local/disa@line1_outbound-00fe,2 to write format slin [Apr 13 14:00:07] DEBUG[4341]: channel.c:1798 ast_settimeout: Scheduling timer at 160 sample intervals [Apr 13 14:00:07] DEBUG[4342]: devicestate.c:304 __ast_device_state_changed_literal: Notification of state change to be queued on device/channel Local/disa@line1_outbound-00fe,1 [Apr 13 14:00:07] DEBUG[4308]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for Local - disa@line1_outbound-00fe,1 [Apr 13 14:00:07] DEBUG[4308]: chan_local.c:145 local_devicestate: Checking if extension disa@line1_outbound-00fe,1 exists (devicestate) [Apr 13 14:00:07] DEBUG[4308]: devicestate.c:287 do_state_change: Changing state for Local/disa@line1_outbound-00fe,1 - state 4 (Invalid) [Apr 13 14:00:07] DEBUG[4333]: app_queue.c:609 handle_statechange: Device 'Local/disa@line1_outbound-00fe,1' changed to state '4' (Invalid) but we don't care because they're not a member of any queue. [Apr 13 14:00:07] DEBUG[4342]: devicestate.c:304 __ast_device_state_changed_literal: Notification of state change to be queued on device/channel Local/disa@line1_outbound [Apr 13 14:00:07] DEBUG[4308]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for Local - disa@line1_outbound [Apr 13 14:00:07] DEBUG[4308]: chan_local.c:145 local_devicestate: Checking if extension disa@line1_outbound exists (devicestate) [Apr 13 14:00:07] DEBUG[4308]: devicestate.c:287 do_state_change: Changing state for Local/disa@line1_outbound - state 2 (In use) [Apr 13 14:00:07] DEBUG[4333]: app_queue.c:609 handle_statechange: Device 'Local/disa@line1_outbound' changed to state '2' (In use) but we don't care because they're not a member of any queue. [Apr 13 14:00:07] -- Local/disa@line1_outbound-00fe,1 answered [Apr 13 14:00:07] DEBUG[4340]: chan_zap.c:7901 zt_request: Using channel -2 [Apr 13 14:00:07] DEBUG[4340]: channel.c:2778 set_format: Set channel Zap/pseudo-1660513430 to read format slin [Apr 13 14:00:07] DEBUG[4340]: channel.c:2778 set_format: Set channel Zap/pseudo-1660513430 to write format slin [Apr 13 14:00:07] -- Created MeetMe conference 1023 for conference 'SLA_line1' [Apr 13 14:00:07] DEBUG[4340]: devicestate.c:304 __ast_device_state_changed_literal: Notification of state change to be queued on device/channel meetme:SLA_line1 [Apr 13 14:00:07] DEBUG[4308]: devicestate.c:157 ast_device_state: Checking if I can find provider for "meetme" - number: SLA_line1 [Apr 13 14:00:07] DEBUG[4308]: devicestate.c:230 getproviderstate: Checking provider SLA with meetme [Apr 13 14:00:07] DEBUG[4308]: devicestate.c:230 getproviderstate: Checking provider Meetme with meetme [Apr 13 14:00:07] DEBUG[4308]: devicestate.c:287 do_state_change: Changing state for meetme:SLA_line1 - state 2 (In use) [Apr 13 14:00:07] DEBUG[4340]: channel.c:2778 set_format: Set channel Local/disa@line1_outbound-00fe,1 to write format slin [Apr 13 14:00:07] DEBUG[4340]: channel.c:2778 set_format: Set channel Local/disa@line1_outbound-00fe,1 to read format slin [Apr 13 14:00:07] DEBUG[4340]: app_meetme.c:1676 conf_run: Placed channel Local/disa@line1_outbound-00fe,1 in ZAP conf 1023 [Apr 13 14:00:07] DEBUG[4338]: devicestate.c:304 __ast_device_state_changed_literal: Notification of state change to be queued on device/channel SIP/station3-09717830 [Apr 13 14:00:07] DEBUG[4338]: devicestate.c:304 __ast_device_state_changed_literal: Notification of state change to be queued on device/channel SIP/station3 [Apr 13 14:00:07] DEBUG[4338]: chan_sip.c:3659 sip_answer: SIP answering channel: SIP/station3-09717830 [Apr 13 14:00:07] DEBUG[4338]: chan_sip.c:6686 transmit_response_with_sdp: Setting framing from config on incoming call [Apr 13 14:00:07] DEBUG[4338]: chan_sip.c:6450 add_sdp: ** Our capability: 0xc (ulaw|alaw) Video flag: True [Apr 13 14:00:07] DEBUG[4338]: chan_sip.c:6451 add_sdp: ** Our prefcodec: 0x0 (nothing) [Apr 13 14:00:07] Audio is at 10.50.10.171 port 12450 [Apr 13 14:00:07] Adding codec 0x4 (ulaw) to SDP [Apr 13 14:00:07] Adding codec 0x8 (alaw) to SDP [Apr 13 14:00:07] Adding non-codec 0x1 (telephone-event) to SDP [Apr 13 14:00:07] DEBUG[4338]: chan_sip.c:6582 add_sdp: -- Done with adding codecs to SDP [Apr 13 14:00:07] DEBUG[4338]: channel.c:2312 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=24) [Apr 13 14:00:07] DEBUG[4338]: chan_sip.c:6627 add_sdp: Done building SDP. Settling with this capability: 0xc (ulaw|alaw) [Apr 13 14:00:07] <--- Reliably Transmitting (no NAT) to 10.50.10.183:5060 ---> SIP/2.0 200 OK Via: SIP/2.0/UDP 10.50.10.183:5060;branch=z9hG4bK80271598d63ab70b3;received=10.50.10.183 From: "PowerPBX 23" ;tag=4798cebe7e To: "station3_line1" ;tag=as7d6173b9 Call-ID: 071ad47524e1b4e8 CSeq: 12812 INVITE User-Agent: Asterisk PBX Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY Supported: replaces Contact: Content-Type: application/sdp Content-Length: 262 v=0 o=root 4304 4304 IN IP4 10.50.10.171 s=session c=IN IP4 10.50.10.171 t=0 0 m=audio 12450 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 <------------> [Apr 13 14:00:07] DEBUG[4338]: chan_sip.c:2043 __sip_reliable_xmit: *** SIP TIMER: Initializing retransmit timer on packet: Id #-1 [Apr 13 14:00:07] DEBUG[4308]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for SIP - station3-09717830 [Apr 13 14:00:07] DEBUG[4308]: chan_sip.c:15855 sip_devicestate: Checking device state for peer station3-09717830 [Apr 13 14:00:07] DEBUG[4338]: channel.c:2778 set_format: Set channel SIP/station3-09717830 to write format slin [Apr 13 14:00:07] DEBUG[4338]: channel.c:2778 set_format: Set channel SIP/station3-09717830 to read format slin [Apr 13 14:00:07] DEBUG[4338]: app_meetme.c:1676 conf_run: Placed channel SIP/station3-09717830 in ZAP conf 1023 [Apr 13 14:00:07] DEBUG[4308]: devicestate.c:287 do_state_change: Changing state for SIP/station3-09717830 - state 4 (Invalid) [Apr 13 14:00:07] DEBUG[4308]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for SIP - station3 [Apr 13 14:00:07] DEBUG[4308]: chan_sip.c:15855 sip_devicestate: Checking device state for peer station3 [Apr 13 14:00:07] DEBUG[4308]: devicestate.c:287 do_state_change: Changing state for SIP/station3 - state 1 (Not in use) [Apr 13 14:00:07] DEBUG[4333]: app_queue.c:609 handle_statechange: Device 'SIP/station3-09717830' changed to state '4' (Invalid) but we don't care because they're not a member of any queue. [Apr 13 14:00:07] DEBUG[4333]: app_queue.c:609 handle_statechange: Device 'SIP/station3' changed to state '1' (Not in use) but we don't care because they're not a member of any queue. [Apr 13 14:00:07] DEBUG[4338]: rtp.c:2769 ast_rtp_write: Ooh, format changed from unknown to ulaw [Apr 13 14:00:07] DEBUG[4338]: rtp.c:2786 ast_rtp_write: Created smoother: format: 4 ms: 20 len: 160 [Apr 13 14:00:07] DEBUG[4341]: channel.c:2312 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=26) [Apr 13 14:00:07] DEBUG[4341]: channel.c:1888 ast_read_generator_actions: Generator got voice, switching to phase locked mode [Apr 13 14:00:07] DEBUG[4341]: channel.c:1798 ast_settimeout: Scheduling timer at 0 sample intervals [Apr 13 14:00:07] DEBUG[4341]: channel.c:2312 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=26) [Apr 13 14:00:07] DEBUG[4341]: channel.c:2312 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=26) [Apr 13 14:00:07] DEBUG[4341]: channel.c:2312 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=26) [Apr 13 14:00:07] DEBUG[4341]: channel.c:2312 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=26) [Apr 13 14:00:07] DEBUG[4341]: channel.c:2312 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=26) [Apr 13 14:00:07] DEBUG[4341]: channel.c:2312 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=26) [Apr 13 14:00:07] DEBUG[4341]: channel.c:2312 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=26) [Apr 13 14:00:07] DEBUG[4341]: channel.c:2312 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=26) [Apr 13 14:00:07] DEBUG[4341]: channel.c:2312 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=26) [Apr 13 14:00:07] DEBUG[4341]: channel.c:2312 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=26) [Apr 13 14:00:07] <--- SIP read from 10.50.10.183:5060 ---> ACK sip:station3_line1@10.50.10.171 SIP/2.0 Via: SIP/2.0/UDP 10.50.10.183:5060;branch=z9hG4bKe94d75ea8da8fc7f6 Proxy-Authorization: Digest username="station3",realm="asterisk",nonce="7388fa45",uri="sip:station3_line1@10.50.10.171",response="0607d66a86eeb5218f499db52e63ce47",algorithm=MD5 Max-Forwards: 70 From: "PowerPBX 23" ;tag=4798cebe7e To: "station3_line1" ;tag=as7d6173b9 Call-ID: 071ad47524e1b4e8 CSeq: 12812 ACK User-Agent: Aastra 55i/2.2.0.166 Content-Length: 0 <-------------> [Apr 13 14:00:07] DEBUG[4330]: chan_sip.c:4794 parse_request: Header 0: ACK sip:station3_line1@10.50.10.171 SIP/2.0 (43) [Apr 13 14:00:07] DEBUG[4330]: chan_sip.c:4794 parse_request: Header 1: Via: SIP/2.0/UDP 10.50.10.183:5060;branch=z9hG4bKe94d75ea8da8fc7f6 (66) [Apr 13 14:00:07] DEBUG[4330]: chan_sip.c:4794 parse_request: Header 2: Proxy-Authorization: Digest username="station3",realm="asterisk",nonce="7388fa45",uri="sip:station3_line1@10.50.10.171",response="0607d66a86eeb5218f499db52e63ce47",algorithm=MD5 (177) [Apr 13 14:00:07] DEBUG[4330]: chan_sip.c:4794 parse_request: Header 3: Max-Forwards: 70 (16) [Apr 13 14:00:07] DEBUG[4330]: chan_sip.c:4794 parse_request: Header 4: From: "PowerPBX 23" ;tag=4798cebe7e (67) [Apr 13 14:00:07] DEBUG[4330]: chan_sip.c:4794 parse_request: Header 5: To: "station3_line1" ;tag=as7d6173b9 (74) [Apr 13 14:00:07] DEBUG[4330]: chan_sip.c:4794 parse_request: Header 6: Call-ID: 071ad47524e1b4e8 (25) [Apr 13 14:00:07] DEBUG[4330]: chan_sip.c:4794 parse_request: Header 7: CSeq: 12812 ACK (15) [Apr 13 14:00:07] DEBUG[4330]: chan_sip.c:4794 parse_request: Header 8: User-Agent: Aastra 55i/2.2.0.166 (32) [Apr 13 14:00:07] DEBUG[4330]: chan_sip.c:4794 parse_request: Header 9: Content-Length: 0 (17) [Apr 13 14:00:07] --- (10 headers 0 lines) --- [Apr 13 14:00:07] DEBUG[4330]: chan_sip.c:4566 find_call: = Looking for Call ID: 071ad47524e1b4e8 (Checking From) --From tag 4798cebe7e --To-tag as7d6173b9 [Apr 13 14:00:07] DEBUG[4330]: chan_sip.c:4582 find_call: = Found Their Call ID: 071ad47524e1b4e8 Their Tag 4798cebe7e Our tag: as7d6173b9 [Apr 13 14:00:07] DEBUG[4330]: chan_sip.c:15219 handle_request: **** Received ACK (6) - Command in SIP ACK [Apr 13 14:00:07] DEBUG[4330]: chan_sip.c:2166 __sip_ack: ** SIP TIMER: Cancelling retransmit of packet (reply received) Retransid #39 [Apr 13 14:00:07] DEBUG[4330]: chan_sip.c:2175 __sip_ack: Stopping retransmission on '071ad47524e1b4e8' of Response 12812: Match Found [Apr 13 14:00:07] DEBUG[4341]: channel.c:2312 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=26) [Apr 13 14:00:07] DEBUG[4341]: channel.c:2312 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=26) [Apr 13 14:00:07] DEBUG[4341]: channel.c:2312 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=26) [Apr 13 14:00:07] DEBUG[4341]: channel.c:2312 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=26) [Apr 13 14:00:07] DEBUG[4341]: channel.c:2312 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=26) [Apr 13 14:00:07] DEBUG[4341]: channel.c:2312 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=26) [Apr 13 14:00:07] DEBUG[4341]: channel.c:2312 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=26) [Apr 13 14:00:07] DEBUG[4341]: channel.c:2312 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=26) [Apr 13 14:00:07] DEBUG[4341]: channel.c:2312 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=26) [Apr 13 14:00:07] DEBUG[4341]: channel.c:2312 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=26) [Apr 13 14:00:07] DEBUG[4341]: channel.c:2312 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=26) [Apr 13 14:00:07] DEBUG[4341]: channel.c:2312 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=26) [Apr 13 14:00:07] DEBUG[4341]: channel.c:2312 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=26) [Apr 13 14:00:07] DEBUG[4341]: channel.c:2312 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=26) [Apr 13 14:00:08] DEBUG[4341]: channel.c:2312 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=26) [Apr 13 14:00:08] DEBUG[4341]: channel.c:2312 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=26) [Apr 13 14:00:08] DEBUG[4341]: channel.c:2312 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=26) [Apr 13 14:00:08] DEBUG[4341]: channel.c:2312 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=26) [Apr 13 14:00:08] DEBUG[4341]: channel.c:2312 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=26) [Apr 13 14:00:08] DEBUG[4341]: channel.c:2312 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=26) [Apr 13 14:00:08] DEBUG[4341]: channel.c:2312 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=26) [Apr 13 14:00:08] DEBUG[4341]: channel.c:2312 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=26) [Apr 13 14:00:08] DEBUG[4341]: channel.c:2312 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=26) [Apr 13 14:00:08] DEBUG[4341]: channel.c:2312 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=26) [Apr 13 14:00:08] DEBUG[4341]: channel.c:2312 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=26) [Apr 13 14:00:08] DEBUG[4341]: channel.c:2312 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=26) [Apr 13 14:00:08] DEBUG[4341]: channel.c:2312 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=26) [Apr 13 14:00:08] DEBUG[4341]: channel.c:2312 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=26) [Apr 13 14:00:08] DEBUG[4341]: channel.c:2312 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=26) [Apr 13 14:00:08] DEBUG[4341]: channel.c:2312 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=26) [Apr 13 14:00:08] DEBUG[4341]: channel.c:2312 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=26) [Apr 13 14:00:08] DEBUG[4341]: channel.c:2312 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=26) [Apr 13 14:00:08] DEBUG[4341]: channel.c:2312 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=26) [Apr 13 14:00:08] DEBUG[4341]: channel.c:2312 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=26) [Apr 13 14:00:08] DEBUG[4341]: channel.c:2312 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=26) [Apr 13 14:00:08] DEBUG[4341]: channel.c:2312 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=26) [Apr 13 14:00:08] DEBUG[4341]: channel.c:2312 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=26) [Apr 13 14:00:08] DEBUG[4341]: channel.c:2312 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=26) [Apr 13 14:00:08] DEBUG[4341]: channel.c:2312 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=26) [Apr 13 14:00:08] DEBUG[4341]: channel.c:2312 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=26) [Apr 13 14:00:08] DEBUG[4341]: channel.c:2312 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=26) [Apr 13 14:00:08] DEBUG[4341]: channel.c:2312 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=26) [Apr 13 14:00:08] DEBUG[4341]: channel.c:2312 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=26) [Apr 13 14:00:08] DEBUG[4341]: channel.c:2312 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=26) [Apr 13 14:00:08] DEBUG[4341]: channel.c:2312 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=26) [Apr 13 14:00:08] DEBUG[4341]: channel.c:2312 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=26) [Apr 13 14:00:08] DEBUG[4341]: channel.c:2312 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=26) [Apr 13 14:00:08] DEBUG[4341]: channel.c:2312 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=26) [Apr 13 14:00:08] DEBUG[4341]: channel.c:2312 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=26) [Apr 13 14:00:08] DEBUG[4341]: channel.c:2312 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=26) [Apr 13 14:00:08] DEBUG[4341]: channel.c:2312 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=26) [Apr 13 14:00:08] DEBUG[4341]: channel.c:2312 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=26) [Apr 13 14:00:08] DEBUG[4341]: channel.c:2312 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=26) [Apr 13 14:00:08] DEBUG[4341]: channel.c:2312 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=26) [Apr 13 14:00:08] DEBUG[4341]: channel.c:2312 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=26) [Apr 13 14:00:08] DEBUG[4341]: channel.c:2312 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=26) [Apr 13 14:00:08] DEBUG[4341]: channel.c:2312 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=26) [Apr 13 14:00:08] DEBUG[4341]: channel.c:2312 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=26) [Apr 13 14:00:08] DEBUG[4341]: channel.c:2312 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=26) [Apr 13 14:00:08] DEBUG[4341]: channel.c:2312 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=26) [Apr 13 14:00:08] DEBUG[4341]: channel.c:2312 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=26) [Apr 13 14:00:08] DEBUG[4341]: channel.c:2312 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=26) [Apr 13 14:00:08] DEBUG[4341]: channel.c:2312 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=26) [Apr 13 14:00:08] DEBUG[4341]: channel.c:2312 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=26) [Apr 13 14:00:09] DEBUG[4341]: channel.c:2312 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=26) [Apr 13 14:00:09] DEBUG[4341]: channel.c:2312 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=26) [Apr 13 14:00:09] DEBUG[4338]: rtp.c:728 process_rfc2833: - RTP 2833 Event: 00000007 (len = 4) [Apr 13 14:00:09] DEBUG[4338]: rtp.c:627 send_dtmf: Sending dtmf: 55 (7), at 10.50.10.183 [Apr 13 14:00:09] DEBUG[4338]: channel.c:2597 ast_write: Thread -1215247440 Blocking 'Local/disa@line1_outbound-00fe,1', already blocked by thread -1215738960 in procedure ast_waitfor_nandfds [Apr 13 14:00:09] DEBUG[4338]: rtp.c:728 process_rfc2833: - RTP 2833 Event: 00000007 (len = 4) [Apr 13 14:00:09] DEBUG[4338]: rtp.c:728 process_rfc2833: - RTP 2833 Event: 00000007 (len = 4) [Apr 13 14:00:09] DEBUG[4338]: rtp.c:728 process_rfc2833: - RTP 2833 Event: 00000007 (len = 4) [Apr 13 14:00:09] DEBUG[4338]: rtp.c:728 process_rfc2833: - RTP 2833 Event: 00000007 (len = 4) [Apr 13 14:00:09] DEBUG[4338]: rtp.c:728 process_rfc2833: - RTP 2833 Event: 00000007 (len = 4) [Apr 13 14:00:09] DEBUG[4338]: rtp.c:728 process_rfc2833: - RTP 2833 Event: 00000007 (len = 4) [Apr 13 14:00:09] DEBUG[4338]: rtp.c:627 send_dtmf: Sending dtmf: 55 (7), at 10.50.10.183 [Apr 13 14:00:09] DEBUG[4338]: channel.c:2597 ast_write: Thread -1215247440 Blocking 'Local/disa@line1_outbound-00fe,1', already blocked by thread -1215738960 in procedure ast_waitfor_nandfds [Apr 13 14:00:09] DEBUG[4341]: channel.c:2778 set_format: Set channel Local/disa@line1_outbound-00fe,2 to write format ulaw [Apr 13 14:00:09] DEBUG[4341]: channel.c:1798 ast_settimeout: Scheduling timer at 0 sample intervals [Apr 13 14:00:09] DEBUG[4338]: rtp.c:728 process_rfc2833: - RTP 2833 Event: 00000007 (len = 4) [Apr 13 14:00:09] DEBUG[4338]: rtp.c:728 process_rfc2833: - RTP 2833 Event: 00000007 (len = 4) [Apr 13 14:00:09] DEBUG[4338]: rtp.c:728 process_rfc2833: - RTP 2833 Event: 00000006 (len = 4) [Apr 13 14:00:09] DEBUG[4338]: rtp.c:627 send_dtmf: Sending dtmf: 54 (6), at 10.50.10.183 [Apr 13 14:00:09] DEBUG[4338]: channel.c:2597 ast_write: Thread -1215247440 Blocking 'Local/disa@line1_outbound-00fe,1', already blocked by thread -1215738960 in procedure ast_waitfor_nandfds [Apr 13 14:00:09] DEBUG[4338]: rtp.c:728 process_rfc2833: - RTP 2833 Event: 00000006 (len = 4) [Apr 13 14:00:09] DEBUG[4338]: rtp.c:728 process_rfc2833: - RTP 2833 Event: 00000006 (len = 4) [Apr 13 14:00:09] DEBUG[4338]: rtp.c:728 process_rfc2833: - RTP 2833 Event: 00000006 (len = 4) [Apr 13 14:00:09] DEBUG[4338]: rtp.c:728 process_rfc2833: - RTP 2833 Event: 00000006 (len = 4) [Apr 13 14:00:09] DEBUG[4338]: rtp.c:728 process_rfc2833: - RTP 2833 Event: 00000006 (len = 4) [Apr 13 14:00:09] DEBUG[4338]: rtp.c:728 process_rfc2833: - RTP 2833 Event: 00000006 (len = 4) [Apr 13 14:00:09] DEBUG[4338]: rtp.c:728 process_rfc2833: - RTP 2833 Event: 00000006 (len = 4) [Apr 13 14:00:09] DEBUG[4338]: rtp.c:627 send_dtmf: Sending dtmf: 54 (6), at 10.50.10.183 [Apr 13 14:00:09] DEBUG[4338]: channel.c:2597 ast_write: Thread -1215247440 Blocking 'Local/disa@line1_outbound-00fe,1', already blocked by thread -1215738960 in procedure ast_waitfor_nandfds [Apr 13 14:00:09] DEBUG[4338]: rtp.c:728 process_rfc2833: - RTP 2833 Event: 00000006 (len = 4) [Apr 13 14:00:09] DEBUG[4338]: rtp.c:728 process_rfc2833: - RTP 2833 Event: 00000006 (len = 4) [Apr 13 14:00:10] DEBUG[4338]: rtp.c:728 process_rfc2833: - RTP 2833 Event: 00000007 (len = 4) [Apr 13 14:00:10] DEBUG[4338]: rtp.c:627 send_dtmf: Sending dtmf: 55 (7), at 10.50.10.183 [Apr 13 14:00:10] DEBUG[4338]: channel.c:2597 ast_write: Thread -1215247440 Blocking 'Local/disa@line1_outbound-00fe,1', already blocked by thread -1215738960 in procedure ast_waitfor_nandfds [Apr 13 14:00:10] DEBUG[4338]: rtp.c:728 process_rfc2833: - RTP 2833 Event: 00000007 (len = 4) [Apr 13 14:00:10] DEBUG[4338]: rtp.c:728 process_rfc2833: - RTP 2833 Event: 00000007 (len = 4) [Apr 13 14:00:10] DEBUG[4338]: rtp.c:728 process_rfc2833: - RTP 2833 Event: 00000007 (len = 4) [Apr 13 14:00:10] DEBUG[4338]: rtp.c:728 process_rfc2833: - RTP 2833 Event: 00000007 (len = 4) [Apr 13 14:00:10] DEBUG[4338]: rtp.c:728 process_rfc2833: - RTP 2833 Event: 00000007 (len = 4) [Apr 13 14:00:10] DEBUG[4338]: rtp.c:728 process_rfc2833: - RTP 2833 Event: 00000007 (len = 4) [Apr 13 14:00:10] DEBUG[4338]: rtp.c:728 process_rfc2833: - RTP 2833 Event: 00000007 (len = 4) [Apr 13 14:00:10] DEBUG[4338]: rtp.c:728 process_rfc2833: - RTP 2833 Event: 00000007 (len = 4) [Apr 13 14:00:10] DEBUG[4338]: rtp.c:627 send_dtmf: Sending dtmf: 55 (7), at 10.50.10.183 [Apr 13 14:00:10] DEBUG[4338]: channel.c:2597 ast_write: Thread -1215247440 Blocking 'Local/disa@line1_outbound-00fe,1', already blocked by thread -1215738960 in procedure ast_waitfor_nandfds [Apr 13 14:00:10] DEBUG[4338]: rtp.c:728 process_rfc2833: - RTP 2833 Event: 00000007 (len = 4) [Apr 13 14:00:10] DEBUG[4338]: rtp.c:728 process_rfc2833: - RTP 2833 Event: 00000007 (len = 4) [Apr 13 14:00:10] DEBUG[4338]: rtp.c:728 process_rfc2833: - RTP 2833 Event: 00000008 (len = 4) [Apr 13 14:00:10] DEBUG[4338]: rtp.c:627 send_dtmf: Sending dtmf: 56 (8), at 10.50.10.183 [Apr 13 14:00:10] DEBUG[4338]: channel.c:2597 ast_write: Thread -1215247440 Blocking 'Local/disa@line1_outbound-00fe,1', already blocked by thread -1215738960 in procedure ast_waitfor_nandfds [Apr 13 14:00:10] DEBUG[4338]: rtp.c:728 process_rfc2833: - RTP 2833 Event: 00000008 (len = 4) [Apr 13 14:00:10] DEBUG[4338]: rtp.c:728 process_rfc2833: - RTP 2833 Event: 00000008 (len = 4) [Apr 13 14:00:10] DEBUG[4338]: rtp.c:728 process_rfc2833: - RTP 2833 Event: 00000008 (len = 4) [Apr 13 14:00:10] DEBUG[4338]: rtp.c:728 process_rfc2833: - RTP 2833 Event: 00000008 (len = 4) [Apr 13 14:00:10] DEBUG[4338]: rtp.c:728 process_rfc2833: - RTP 2833 Event: 00000008 (len = 4) [Apr 13 14:00:10] DEBUG[4338]: rtp.c:728 process_rfc2833: - RTP 2833 Event: 00000008 (len = 4) [Apr 13 14:00:10] DEBUG[4338]: rtp.c:728 process_rfc2833: - RTP 2833 Event: 00000008 (len = 4) [Apr 13 14:00:10] DEBUG[4338]: rtp.c:728 process_rfc2833: - RTP 2833 Event: 00000008 (len = 4) [Apr 13 14:00:10] DEBUG[4338]: rtp.c:728 process_rfc2833: - RTP 2833 Event: 00000008 (len = 4) [Apr 13 14:00:10] DEBUG[4338]: rtp.c:627 send_dtmf: Sending dtmf: 56 (8), at 10.50.10.183 [Apr 13 14:00:10] DEBUG[4338]: channel.c:2597 ast_write: Thread -1215247440 Blocking 'Local/disa@line1_outbound-00fe,1', already blocked by thread -1215738960 in procedure ast_waitfor_nandfds [Apr 13 14:00:10] DEBUG[4338]: rtp.c:728 process_rfc2833: - RTP 2833 Event: 00000008 (len = 4) [Apr 13 14:00:10] DEBUG[4338]: rtp.c:728 process_rfc2833: - RTP 2833 Event: 00000008 (len = 4) [Apr 13 14:00:10] DEBUG[4338]: rtp.c:728 process_rfc2833: - RTP 2833 Event: 00000009 (len = 4) [Apr 13 14:00:10] DEBUG[4338]: rtp.c:627 send_dtmf: Sending dtmf: 57 (9), at 10.50.10.183 [Apr 13 14:00:10] DEBUG[4338]: channel.c:2597 ast_write: Thread -1215247440 Blocking 'Local/disa@line1_outbound-00fe,1', already blocked by thread -1215738960 in procedure ast_waitfor_nandfds [Apr 13 14:00:10] DEBUG[4338]: rtp.c:728 process_rfc2833: - RTP 2833 Event: 00000009 (len = 4) [Apr 13 14:00:10] DEBUG[4338]: rtp.c:728 process_rfc2833: - RTP 2833 Event: 00000009 (len = 4) [Apr 13 14:00:10] DEBUG[4338]: rtp.c:728 process_rfc2833: - RTP 2833 Event: 00000009 (len = 4) [Apr 13 14:00:10] DEBUG[4338]: rtp.c:728 process_rfc2833: - RTP 2833 Event: 00000009 (len = 4) [Apr 13 14:00:10] DEBUG[4338]: rtp.c:728 process_rfc2833: - RTP 2833 Event: 00000009 (len = 4) [Apr 13 14:00:10] DEBUG[4338]: rtp.c:728 process_rfc2833: - RTP 2833 Event: 00000009 (len = 4) [Apr 13 14:00:10] DEBUG[4338]: rtp.c:728 process_rfc2833: - RTP 2833 Event: 00000009 (len = 4) [Apr 13 14:00:10] DEBUG[4338]: rtp.c:728 process_rfc2833: - RTP 2833 Event: 00000009 (len = 4) [Apr 13 14:00:10] DEBUG[4338]: rtp.c:728 process_rfc2833: - RTP 2833 Event: 00000009 (len = 4) [Apr 13 14:00:10] DEBUG[4338]: rtp.c:627 send_dtmf: Sending dtmf: 57 (9), at 10.50.10.183 [Apr 13 14:00:10] DEBUG[4338]: channel.c:2597 ast_write: Thread -1215247440 Blocking 'Local/disa@line1_outbound-00fe,1', already blocked by thread -1215738960 in procedure ast_waitfor_nandfds [Apr 13 14:00:10] DEBUG[4338]: rtp.c:728 process_rfc2833: - RTP 2833 Event: 00000009 (len = 4) [Apr 13 14:00:11] DEBUG[4338]: rtp.c:728 process_rfc2833: - RTP 2833 Event: 00000009 (len = 4) [Apr 13 14:00:11] DEBUG[4338]: rtp.c:728 process_rfc2833: - RTP 2833 Event: 00000000 (len = 4) [Apr 13 14:00:11] DEBUG[4338]: rtp.c:627 send_dtmf: Sending dtmf: 48 (0), at 10.50.10.183 [Apr 13 14:00:11] DEBUG[4338]: channel.c:2597 ast_write: Thread -1215247440 Blocking 'Local/disa@line1_outbound-00fe,1', already blocked by thread -1215738960 in procedure ast_waitfor_nandfds [Apr 13 14:00:11] DEBUG[4338]: rtp.c:728 process_rfc2833: - RTP 2833 Event: 00000000 (len = 4) [Apr 13 14:00:11] DEBUG[4338]: rtp.c:728 process_rfc2833: - RTP 2833 Event: 00000000 (len = 4) [Apr 13 14:00:11] DEBUG[4338]: rtp.c:728 process_rfc2833: - RTP 2833 Event: 00000000 (len = 4) [Apr 13 14:00:11] DEBUG[4338]: rtp.c:728 process_rfc2833: - RTP 2833 Event: 00000000 (len = 4) [Apr 13 14:00:11] DEBUG[4338]: rtp.c:728 process_rfc2833: - RTP 2833 Event: 00000000 (len = 4) [Apr 13 14:00:11] DEBUG[4338]: rtp.c:728 process_rfc2833: - RTP 2833 Event: 00000000 (len = 4) [Apr 13 14:00:11] DEBUG[4338]: rtp.c:728 process_rfc2833: - RTP 2833 Event: 00000000 (len = 4) [Apr 13 14:00:11] DEBUG[4338]: rtp.c:627 send_dtmf: Sending dtmf: 48 (0), at 10.50.10.183 [Apr 13 14:00:11] DEBUG[4338]: channel.c:2597 ast_write: Thread -1215247440 Blocking 'Local/disa@line1_outbound-00fe,1', already blocked by thread -1215738960 in procedure ast_waitfor_nandfds [Apr 13 14:00:11] DEBUG[4338]: rtp.c:728 process_rfc2833: - RTP 2833 Event: 00000000 (len = 4) [Apr 13 14:00:11] DEBUG[4338]: rtp.c:728 process_rfc2833: - RTP 2833 Event: 00000000 (len = 4) [Apr 13 14:00:11] DEBUG[4338]: rtp.c:728 process_rfc2833: - RTP 2833 Event: 00000000 (len = 4) [Apr 13 14:00:11] DEBUG[4338]: rtp.c:627 send_dtmf: Sending dtmf: 48 (0), at 10.50.10.183 [Apr 13 14:00:11] DEBUG[4338]: channel.c:2597 ast_write: Thread -1215247440 Blocking 'Local/disa@line1_outbound-00fe,1', already blocked by thread -1215738960 in procedure ast_waitfor_nandfds [Apr 13 14:00:11] DEBUG[4338]: rtp.c:728 process_rfc2833: - RTP 2833 Event: 00000000 (len = 4) [Apr 13 14:00:11] DEBUG[4338]: rtp.c:728 process_rfc2833: - RTP 2833 Event: 00000000 (len = 4) [Apr 13 14:00:11] DEBUG[4338]: rtp.c:728 process_rfc2833: - RTP 2833 Event: 00000000 (len = 4) [Apr 13 14:00:11] DEBUG[4338]: rtp.c:728 process_rfc2833: - RTP 2833 Event: 00000000 (len = 4) [Apr 13 14:00:11] DEBUG[4338]: rtp.c:728 process_rfc2833: - RTP 2833 Event: 00000000 (len = 4) [Apr 13 14:00:11] DEBUG[4338]: rtp.c:728 process_rfc2833: - RTP 2833 Event: 00000000 (len = 4) [Apr 13 14:00:11] DEBUG[4338]: rtp.c:728 process_rfc2833: - RTP 2833 Event: 00000000 (len = 4) [Apr 13 14:00:11] DEBUG[4338]: rtp.c:728 process_rfc2833: - RTP 2833 Event: 00000000 (len = 4) [Apr 13 14:00:11] DEBUG[4338]: rtp.c:728 process_rfc2833: - RTP 2833 Event: 00000000 (len = 4) [Apr 13 14:00:11] DEBUG[4338]: rtp.c:627 send_dtmf: Sending dtmf: 48 (0), at 10.50.10.183 [Apr 13 14:00:11] DEBUG[4338]: channel.c:2597 ast_write: Thread -1215247440 Blocking 'Local/disa@line1_outbound-00fe,1', already blocked by thread -1215738960 in procedure ast_waitfor_nandfds [Apr 13 14:00:11] DEBUG[4341]: pbx.c:1688 pbx_substitute_variables_helper_full: Function result is '' [Apr 13 14:00:11] DEBUG[4341]: pbx.c:1688 pbx_substitute_variables_helper_full: Function result is '' [Apr 13 14:00:11] DEBUG[4341]: pbx.c:1688 pbx_substitute_variables_helper_full: Function result is 'disa' [Apr 13 14:00:11] DEBUG[4341]: pbx.c:1688 pbx_substitute_variables_helper_full: Function result is 'line1_outbound' [Apr 13 14:00:11] DEBUG[4341]: pbx.c:1688 pbx_substitute_variables_helper_full: Function result is 'Local/disa@line1_outbound-00fe,2' [Apr 13 14:00:11] DEBUG[4341]: pbx.c:1688 pbx_substitute_variables_helper_full: Function result is '' [Apr 13 14:00:11] DEBUG[4341]: pbx.c:1688 pbx_substitute_variables_helper_full: Function result is 'DISA' [Apr 13 14:00:11] DEBUG[4341]: pbx.c:1688 pbx_substitute_variables_helper_full: Function result is 'no-password|line1_outbound' [Apr 13 14:00:11] DEBUG[4341]: pbx.c:1688 pbx_substitute_variables_helper_full: Function result is '2008-04-13 14:00:07' [Apr 13 14:00:11] DEBUG[4341]: pbx.c:1688 pbx_substitute_variables_helper_full: Function result is '2008-04-13 14:00:07' [Apr 13 14:00:11] DEBUG[4341]: pbx.c:1688 pbx_substitute_variables_helper_full: Function result is '2008-04-13 14:00:11' [Apr 13 14:00:11] DEBUG[4341]: pbx.c:1688 pbx_substitute_variables_helper_full: Function result is '4' [Apr 13 14:00:11] DEBUG[4341]: pbx.c:1688 pbx_substitute_variables_helper_full: Function result is '4' [Apr 13 14:00:11] DEBUG[4341]: pbx.c:1688 pbx_substitute_variables_helper_full: Function result is 'ANSWERED' [Apr 13 14:00:11] DEBUG[4341]: pbx.c:1688 pbx_substitute_variables_helper_full: Function result is 'DOCUMENTATION' [Apr 13 14:00:11] DEBUG[4341]: pbx.c:1688 pbx_substitute_variables_helper_full: Function result is '' [Apr 13 14:00:11] DEBUG[4341]: pbx.c:1688 pbx_substitute_variables_helper_full: Function result is '1208120407.2' [Apr 13 14:00:11] DEBUG[4341]: pbx.c:1688 pbx_substitute_variables_helper_full: Function result is '' [Apr 13 14:00:11] DEBUG[4341]: pbx.c:1839 pbx_extension_helper: Launching 'Dial' [Apr 13 14:00:11] -- Executing [7678900@line1_outbound:1] Dial("Local/disa@line1_outbound-00fe,2", "SIP/7678900@metaswitch0001|60") in new stack [Apr 13 14:00:11] DEBUG[4341]: chan_sip.c:15924 sip_request_call: Asked to create a SIP channel with formats: 0x4 (ulaw) [Apr 13 14:00:11] DEBUG[4341]: chan_sip.c:4529 sip_alloc: Allocating new SIP dialog for (No Call-ID) - INVITE (With RTP) [Apr 13 14:00:11] DEBUG[4341]: chan_sip.c:2741 do_setnat: Setting NAT on RTP to Off [Apr 13 14:00:11] DEBUG[4341]: chan_sip.c:4013 sip_new: *** Our native formats are 0x80004 (ulaw|h263) [Apr 13 14:00:11] DEBUG[4341]: chan_sip.c:4014 sip_new: *** Joint capabilities are 0x0 (nothing) [Apr 13 14:00:11] DEBUG[4341]: chan_sip.c:4015 sip_new: *** Our capabilities are 0x8000e (gsm|ulaw|alaw|h263) [Apr 13 14:00:11] DEBUG[4341]: chan_sip.c:4016 sip_new: *** AST_CODEC_CHOOSE formats are 0x4 (ulaw) [Apr 13 14:00:11] DEBUG[4341]: chan_sip.c:4018 sip_new: *** Our preferred formats from the incoming channel are 0x4 (ulaw) [Apr 13 14:00:11] DEBUG[4341]: chan_sip.c:4039 sip_new: This channel will not be able to handle video. [Apr 13 14:00:11] DEBUG[4341]: rtp.c:1593 ast_rtp_make_compatible: Channel 'Local/disa@line1_outbound-00fe,2' has no RTP, not doing anything [Apr 13 14:00:11] DEBUG[4341]: chan_sip.c:2999 sip_call: Outgoing Call for 7678900 [Apr 13 14:00:11] DEBUG[4341]: chan_sip.c:3186 update_call_counter: Updating call counter for outgoing call [Apr 13 14:00:11] DEBUG[4341]: chan_sip.c:3014 sip_call: Our T38 capability (0), joint T38 capability (0) [Apr 13 14:00:11] DEBUG[4341]: chan_sip.c:6450 add_sdp: ** Our capability: 0x8000e (gsm|ulaw|alaw|h263) Video flag: False [Apr 13 14:00:11] DEBUG[4341]: chan_sip.c:6451 add_sdp: ** Our prefcodec: 0x4 (ulaw) [Apr 13 14:00:11] DEBUG[4341]: chan_sip.c:6468 add_sdp: This call needs video offers, but there's no video support enabled! [Apr 13 14:00:11] Audio is at 10.50.10.171 port 10802 [Apr 13 14:00:11] Adding codec 0x4 (ulaw) to SDP [Apr 13 14:00:11] Adding codec 0x2 (gsm) to SDP [Apr 13 14:00:11] Adding codec 0x8 (alaw) to SDP [Apr 13 14:00:11] Adding non-codec 0x1 (telephone-event) to SDP [Apr 13 14:00:11] DEBUG[4341]: chan_sip.c:6582 add_sdp: -- Done with adding codecs to SDP [Apr 13 14:00:11] DEBUG[4341]: channel.c:2312 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=34) [Apr 13 14:00:11] DEBUG[4341]: chan_sip.c:6627 add_sdp: Done building SDP. Settling with this capability: 0x8000e (gsm|ulaw|alaw|h263) [Apr 13 14:00:11] DEBUG[4341]: chan_sip.c:4794 parse_request: Header 0: INVITE sip:7678900@10.50.10.2 SIP/2.0 (37) [Apr 13 14:00:11] DEBUG[4341]: chan_sip.c:4794 parse_request: Header 1: Via: SIP/2.0/UDP 10.50.10.171:5060;branch=z9hG4bK561faea1;rport (63) [Apr 13 14:00:11] DEBUG[4341]: chan_sip.c:4794 parse_request: Header 2: From: "IC" ;tag=as4344012e (55) [Apr 13 14:00:11] DEBUG[4341]: chan_sip.c:4794 parse_request: Header 3: To: (28) [Apr 13 14:00:11] DEBUG[4341]: chan_sip.c:4794 parse_request: Header 4: Contact: (38) [Apr 13 14:00:11] DEBUG[4341]: chan_sip.c:4794 parse_request: Header 5: Call-ID: 21249f7b23d1ae654bf45424212e7e7e@10.50.10.171 (54) [Apr 13 14:00:11] DEBUG[4341]: chan_sip.c:4794 parse_request: Header 6: CSeq: 102 INVITE (16) [Apr 13 14:00:11] DEBUG[4341]: chan_sip.c:4794 parse_request: Header 7: User-Agent: Asterisk PBX (24) [Apr 13 14:00:11] DEBUG[4341]: chan_sip.c:4794 parse_request: Header 8: Max-Forwards: 70 (16) [Apr 13 14:00:11] DEBUG[4341]: chan_sip.c:4794 parse_request: Header 9: Date: Sun, 13 Apr 2008 21:00:11 GMT (35) [Apr 13 14:00:11] DEBUG[4341]: chan_sip.c:4794 parse_request: Header 10: Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY (66) [Apr 13 14:00:11] DEBUG[4341]: chan_sip.c:4794 parse_request: Header 11: Supported: replaces (19) [Apr 13 14:00:11] DEBUG[4341]: chan_sip.c:4794 parse_request: Header 12: Content-Type: application/sdp (29) [Apr 13 14:00:11] DEBUG[4341]: chan_sip.c:4794 parse_request: Header 13: Content-Length: 285 (19) [Apr 13 14:00:11] DEBUG[4341]: chan_sip.c:4794 parse_request: Header 14: (0) [Apr 13 14:00:11] DEBUG[4341]: chan_sip.c:4826 parse_request: Line: v=0 (3) [Apr 13 14:00:11] DEBUG[4341]: chan_sip.c:4826 parse_request: Line: o=root 4304 4304 IN IP4 10.50.10.171 (36) [Apr 13 14:00:11] DEBUG[4341]: chan_sip.c:4826 parse_request: Line: s=session (9) [Apr 13 14:00:11] DEBUG[4341]: chan_sip.c:4826 parse_request: Line: c=IN IP4 10.50.10.171 (21) [Apr 13 14:00:11] DEBUG[4341]: chan_sip.c:4826 parse_request: Line: t=0 0 (5) [Apr 13 14:00:11] DEBUG[4341]: chan_sip.c:4826 parse_request: Line: m=audio 10802 RTP/AVP 0 3 8 101 (31) [Apr 13 14:00:11] DEBUG[4341]: chan_sip.c:4826 parse_request: Line: a=rtpmap:0 PCMU/8000 (20) [Apr 13 14:00:11] DEBUG[4341]: chan_sip.c:4826 parse_request: Line: a=rtpmap:3 GSM/8000 (19) [Apr 13 14:00:11] DEBUG[4341]: chan_sip.c:4826 parse_request: Line: a=rtpmap:8 PCMA/8000 (20) [Apr 13 14:00:11] DEBUG[4341]: chan_sip.c:4826 parse_request: Line: a=rtpmap:101 telephone-event/8000 (33) [Apr 13 14:00:11] DEBUG[4341]: chan_sip.c:4826 parse_request: Line: a=fmtp:101 0-16 (15) [Apr 13 14:00:11] DEBUG[4341]: chan_sip.c:4826 parse_request: Line: a=silenceSupp:off - - - - (25) [Apr 13 14:00:11] DEBUG[4341]: chan_sip.c:4826 parse_request: Line: a=ptime:20 (10) [Apr 13 14:00:11] DEBUG[4341]: chan_sip.c:4826 parse_request: Line: a=sendrecv (10) [Apr 13 14:00:11] Reliably Transmitting (no NAT) to 10.50.10.2:5060: INVITE sip:7678900@10.50.10.2 SIP/2.0 Via: SIP/2.0/UDP 10.50.10.171:5060;branch=z9hG4bK561faea1;rport From: "IC" ;tag=as4344012e To: Contact: Call-ID: 21249f7b23d1ae654bf45424212e7e7e@10.50.10.171 CSeq: 102 INVITE User-Agent: Asterisk PBX Max-Forwards: 70 Date: Sun, 13 Apr 2008 21:00:11 GMT Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY Supported: replaces Content-Type: application/sdp Content-Length: 285 v=0 o=root 4304 4304 IN IP4 10.50.10.171 s=session c=IN IP4 10.50.10.171 t=0 0 m=audio 10802 RTP/AVP 0 3 8 101 a=rtpmap:0 PCMU/8000 a=rtpmap:3 GSM/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 --- [Apr 13 14:00:11] DEBUG[4341]: chan_sip.c:2043 __sip_reliable_xmit: *** SIP TIMER: Initializing retransmit timer on packet: Id #-1 [Apr 13 14:00:11] -- Called 7678900@metaswitch0001 [Apr 13 14:00:11] DEBUG[4338]: rtp.c:728 process_rfc2833: - RTP 2833 Event: 00000000 (len = 4) [Apr 13 14:00:11] <--- SIP read from 10.50.10.2:5060 ---> SIP/2.0 100 Trying Call-ID: 21249f7b23d1ae654bf45424212e7e7e@10.50.10.171 CSeq: 102 INVITE From: "IC" ;tag=as4344012e To: ;tag=metaswitch+1+14ee4b+6094bc39 Via: SIP/2.0/UDP 10.50.10.171:5060;rport=5060;branch=z9hG4bK561faea1 Server: DC-SIP/2.0 Organization: Supported: 100rel Contact: Content-Length: 0 <-------------> [Apr 13 14:00:11] DEBUG[4330]: chan_sip.c:4794 parse_request: Header 0: SIP/2.0 100 Trying (18) [Apr 13 14:00:11] DEBUG[4330]: chan_sip.c:4794 parse_request: Header 1: Call-ID: 21249f7b23d1ae654bf45424212e7e7e@10.50.10.171 (54) [Apr 13 14:00:11] DEBUG[4330]: chan_sip.c:4794 parse_request: Header 2: CSeq: 102 INVITE (16) [Apr 13 14:00:11] DEBUG[4330]: chan_sip.c:4794 parse_request: Header 3: From: "IC" ;tag=as4344012e (55) [Apr 13 14:00:11] DEBUG[4330]: chan_sip.c:4794 parse_request: Header 4: To: ;tag=metaswitch+1+14ee4b+6094bc39 (61) [Apr 13 14:00:11] DEBUG[4330]: chan_sip.c:4794 parse_request: Header 5: Via: SIP/2.0/UDP 10.50.10.171:5060;rport=5060;branch=z9hG4bK561faea1 (68) [Apr 13 14:00:11] DEBUG[4330]: chan_sip.c:4794 parse_request: Header 6: Server: DC-SIP/2.0 (18) [Apr 13 14:00:11] DEBUG[4330]: chan_sip.c:4794 parse_request: Header 7: Organization: (14) [Apr 13 14:00:11] DEBUG[4330]: chan_sip.c:4794 parse_request: Header 8: Supported: 100rel (17) [Apr 13 14:00:11] DEBUG[4330]: chan_sip.c:4794 parse_request: Header 9: Contact: (33) [Apr 13 14:00:11] DEBUG[4330]: chan_sip.c:4794 parse_request: Header 10: Content-Length: 0 (17) [Apr 13 14:00:11] --- (11 headers 0 lines) --- [Apr 13 14:00:11] DEBUG[4330]: chan_sip.c:4566 find_call: = Looking for Call ID: 21249f7b23d1ae654bf45424212e7e7e@10.50.10.171 (Checking To) --From tag as4344012e --To-tag metaswitch+1+14ee4b+6094bc39 [Apr 13 14:00:11] DEBUG[4330]: chan_sip.c:4582 find_call: = Found Their Call ID: 21249f7b23d1ae654bf45424212e7e7e@10.50.10.171 Their Tag Our tag: as4344012e [Apr 13 14:00:11] DEBUG[4330]: chan_sip.c:2208 __sip_semi_ack: *** SIP TIMER: Cancelling retransmission #41 - INVITE (got response) [Apr 13 14:00:11] DEBUG[4330]: chan_sip.c:2216 __sip_semi_ack: (Provisional) Stopping retransmission (but retaining packet) on '21249f7b23d1ae654bf45424212e7e7e@10.50.10.171' Request 102: Found [Apr 13 14:00:11] DEBUG[4330]: chan_sip.c:12022 handle_response_invite: SIP response 100 to standard invite [Apr 13 14:00:11] DEBUG[4338]: rtp.c:728 process_rfc2833: - RTP 2833 Event: 00000000 (len = 4) [Apr 13 14:00:12] <--- SIP read from 10.50.10.2:5060 ---> SIP/2.0 183 Session Progress Call-ID: 21249f7b23d1ae654bf45424212e7e7e@10.50.10.171 CSeq: 102 INVITE From: "IC" ;tag=as4344012e To: ;tag=metaswitch+1+14ee4b+6094bc39 Via: SIP/2.0/UDP 10.50.10.171:5060;rport=5060;branch=z9hG4bK561faea1 Server: DC-SIP/2.0 Organization: Supported: 100rel Contact: Content-Length: 161 Content-Type: application/sdp v=0 o=- 1234618226 1234618226 IN IP4 10.50.10.13 s=- c=IN IP4 10.50.10.13 t=0 0 m=audio 32860 RTP/AVP 0 101 a=rtpmap:101 telephone-event/8000 a=ptime:20 <-------------> [Apr 13 14:00:12] DEBUG[4330]: chan_sip.c:4794 parse_request: Header 0: SIP/2.0 183 Session Progress (28) [Apr 13 14:00:12] DEBUG[4330]: chan_sip.c:4794 parse_request: Header 1: Call-ID: 21249f7b23d1ae654bf45424212e7e7e@10.50.10.171 (54) [Apr 13 14:00:12] DEBUG[4330]: chan_sip.c:4794 parse_request: Header 2: CSeq: 102 INVITE (16) [Apr 13 14:00:12] DEBUG[4330]: chan_sip.c:4794 parse_request: Header 3: From: "IC" ;tag=as4344012e (55) [Apr 13 14:00:12] DEBUG[4330]: chan_sip.c:4794 parse_request: Header 4: To: ;tag=metaswitch+1+14ee4b+6094bc39 (61) [Apr 13 14:00:12] DEBUG[4330]: chan_sip.c:4794 parse_request: Header 5: Via: SIP/2.0/UDP 10.50.10.171:5060;rport=5060;branch=z9hG4bK561faea1 (68) [Apr 13 14:00:12] DEBUG[4330]: chan_sip.c:4794 parse_request: Header 6: Server: DC-SIP/2.0 (18) [Apr 13 14:00:12] DEBUG[4330]: chan_sip.c:4794 parse_request: Header 7: Organization: (14) [Apr 13 14:00:12] DEBUG[4330]: chan_sip.c:4794 parse_request: Header 8: Supported: 100rel (17) [Apr 13 14:00:12] DEBUG[4330]: chan_sip.c:4794 parse_request: Header 9: Contact: (33) [Apr 13 14:00:12] DEBUG[4330]: chan_sip.c:4794 parse_request: Header 10: Content-Length: 161 (19) [Apr 13 14:00:12] DEBUG[4330]: chan_sip.c:4794 parse_request: Header 11: Content-Type: application/sdp (29) [Apr 13 14:00:12] DEBUG[4330]: chan_sip.c:4794 parse_request: Header 12: (0) [Apr 13 14:00:12] DEBUG[4330]: chan_sip.c:4826 parse_request: Line: v=0 (3) [Apr 13 14:00:12] DEBUG[4330]: chan_sip.c:4826 parse_request: Line: o=- 1234618226 1234618226 IN IP4 10.50.10.13 (44) [Apr 13 14:00:12] DEBUG[4330]: chan_sip.c:4826 parse_request: Line: s=- (3) [Apr 13 14:00:12] DEBUG[4330]: chan_sip.c:4826 parse_request: Line: c=IN IP4 10.50.10.13 (20) [Apr 13 14:00:12] DEBUG[4330]: chan_sip.c:4826 parse_request: Line: t=0 0 (5) [Apr 13 14:00:12] DEBUG[4330]: chan_sip.c:4826 parse_request: Line: m=audio 32860 RTP/AVP 0 101 (27) [Apr 13 14:00:12] DEBUG[4330]: chan_sip.c:4826 parse_request: Line: a=rtpmap:101 telephone-event/8000 (33) [Apr 13 14:00:12] --- (12 headers 8 lines) --- [Apr 13 14:00:12] DEBUG[4330]: chan_sip.c:4566 find_call: = Looking for Call ID: 21249f7b23d1ae654bf45424212e7e7e@10.50.10.171 (Checking To) --From tag as4344012e --To-tag metaswitch+1+14ee4b+6094bc39 [Apr 13 14:00:12] DEBUG[4330]: chan_sip.c:4582 find_call: = Found Their Call ID: 21249f7b23d1ae654bf45424212e7e7e@10.50.10.171 Their Tag metaswitch+1+14ee4b+6094bc39 Our tag: as4344012e [Apr 13 14:00:12] DEBUG[4330]: chan_sip.c:2216 __sip_semi_ack: (Provisional) Stopping retransmission (but retaining packet) on '21249f7b23d1ae654bf45424212e7e7e@10.50.10.171' Request 102: Found [Apr 13 14:00:12] DEBUG[4330]: chan_sip.c:12022 handle_response_invite: SIP response 183 to standard invite [Apr 13 14:00:12] Found RTP audio format 0 [Apr 13 14:00:12] Found RTP audio format 101 [Apr 13 14:00:12] Peer audio RTP is at port 10.50.10.13:32860 [Apr 13 14:00:12] Found audio description format telephone-event for ID 101 [Apr 13 14:00:12] DEBUG[4330]: chan_sip.c:5411 process_sdp: T38 state changed to 0 on channel SIP/metaswitch0001-0971fb58 [Apr 13 14:00:12] Capabilities: us - 0x8000e (gsm|ulaw|alaw|h263), peer - audio=0x4 (ulaw)/video=0x0 (nothing), combined - 0x4 (ulaw) [Apr 13 14:00:12] Non-codec capabilities (dtmf): us - 0x1 (telephone-event), peer - 0x1 (telephone-event), combined - 0x1 (telephone-event) [Apr 13 14:00:12] Peer audio RTP is at port 10.50.10.13:32860 [Apr 13 14:00:12] DEBUG[4330]: chan_sip.c:5491 process_sdp: We're settling with these formats: 0x4 (ulaw) [Apr 13 14:00:12] DEBUG[4330]: chan_sip.c:5498 process_sdp: We have an owner, now see if we need to change this call [Apr 13 14:00:12] -- SIP/metaswitch0001-0971fb58 is making progress passing it to Local/disa@line1_outbound-00fe,2 [Apr 13 14:00:12] DEBUG[4341]: rtp.c:1503 ast_rtp_early_bridge: Channel 'Local/disa@line1_outbound-00fe,2' has no RTP, not doing anything [Apr 13 14:00:12] DEBUG[4340]: app_meetme.c:2160 conf_run: Got unrecognized frame on channel Local/disa@line1_outbound-00fe,1, f->frametype=4,f->subclass=14 [Apr 13 14:00:12] DEBUG[4341]: rtp.c:2769 ast_rtp_write: Ooh, format changed from unknown to ulaw [Apr 13 14:00:12] DEBUG[4341]: rtp.c:2786 ast_rtp_write: Created smoother: format: 4 ms: 20 len: 160 [Apr 13 14:00:12] DEBUG[4338]: rtp.c:880 ast_rtcp_read: Got RTCP report of 64 bytes [Apr 13 14:00:13] <--- SIP read from 10.50.10.183:5060 ---> BYE sip:station3_line1@10.50.10.171 SIP/2.0 Via: SIP/2.0/UDP 10.50.10.183:5060;branch=z9hG4bKde7f94e4b6110c431 Proxy-Authorization: Digest username="station3",realm="asterisk",nonce="7388fa45",uri="sip:station3_line1@10.50.10.171",response="d26832f8efc3a17831e821fb05395829",algorithm=MD5 Max-Forwards: 70 From: "PowerPBX 23" ;tag=4798cebe7e To: "station3_line1" ;tag=as7d6173b9 Call-ID: 071ad47524e1b4e8 CSeq: 12813 BYE Allow: INVITE, ACK, CANCEL, BYE, NOTIFY, REFER, OPTIONS, UPDATE, PRACK, SUBSCRIBE, INFO Allow-Events: talk, hold, conference Supported: timer User-Agent: Aastra 55i/2.2.0.166 Content-Length: 0 <-------------> [Apr 13 14:00:13] DEBUG[4330]: chan_sip.c:4794 parse_request: Header 0: BYE sip:station3_line1@10.50.10.171 SIP/2.0 (43) [Apr 13 14:00:13] DEBUG[4330]: chan_sip.c:4794 parse_request: Header 1: Via: SIP/2.0/UDP 10.50.10.183:5060;branch=z9hG4bKde7f94e4b6110c431 (66) [Apr 13 14:00:13] DEBUG[4330]: chan_sip.c:4794 parse_request: Header 2: Proxy-Authorization: Digest username="station3",realm="asterisk",nonce="7388fa45",uri="sip:station3_line1@10.50.10.171",response="d26832f8efc3a17831e821fb05395829",algorithm=MD5 (177) [Apr 13 14:00:13] DEBUG[4330]: chan_sip.c:4794 parse_request: Header 3: Max-Forwards: 70 (16) [Apr 13 14:00:13] DEBUG[4330]: chan_sip.c:4794 parse_request: Header 4: From: "PowerPBX 23" ;tag=4798cebe7e (67) [Apr 13 14:00:13] DEBUG[4330]: chan_sip.c:4794 parse_request: Header 5: To: "station3_line1" ;tag=as7d6173b9 (74) [Apr 13 14:00:13] DEBUG[4330]: chan_sip.c:4794 parse_request: Header 6: Call-ID: 071ad47524e1b4e8 (25) [Apr 13 14:00:13] DEBUG[4330]: chan_sip.c:4794 parse_request: Header 7: CSeq: 12813 BYE (15) [Apr 13 14:00:13] DEBUG[4330]: chan_sip.c:4794 parse_request: Header 8: Allow: INVITE, ACK, CANCEL, BYE, NOTIFY, REFER, OPTIONS, UPDATE, PRACK, SUBSCRIBE, INFO (87) [Apr 13 14:00:13] DEBUG[4330]: chan_sip.c:4794 parse_request: Header 9: Allow-Events: talk, hold, conference (36) [Apr 13 14:00:13] DEBUG[4330]: chan_sip.c:4794 parse_request: Header 10: Supported: timer (16) [Apr 13 14:00:13] DEBUG[4330]: chan_sip.c:4794 parse_request: Header 11: User-Agent: Aastra 55i/2.2.0.166 (32) [Apr 13 14:00:13] DEBUG[4330]: chan_sip.c:4794 parse_request: Header 12: Content-Length: 0 (17) [Apr 13 14:00:13] --- (13 headers 0 lines) --- [Apr 13 14:00:13] DEBUG[4330]: chan_sip.c:4566 find_call: = Looking for Call ID: 071ad47524e1b4e8 (Checking From) --From tag 4798cebe7e --To-tag as7d6173b9 [Apr 13 14:00:13] DEBUG[4330]: chan_sip.c:4582 find_call: = No match Their Call ID: 21249f7b23d1ae654bf45424212e7e7e@10.50.10.171 Their Tag metaswitch+1+14ee4b+6094bc39 Our tag: as4344012e [Apr 13 14:00:13] DEBUG[4330]: chan_sip.c:4582 find_call: = Found Their Call ID: 071ad47524e1b4e8 Their Tag 4798cebe7e Our tag: as7d6173b9 [Apr 13 14:00:13] DEBUG[4330]: chan_sip.c:15219 handle_request: **** Received BYE (8) - Command in SIP BYE [Apr 13 14:00:13] Sending to 10.50.10.183 : 5060 (no NAT) [Apr 13 14:00:13] DEBUG[4330]: chan_sip.c:1655 sip_alreadygone: Setting SIP_ALREADYGONE on dialog 071ad47524e1b4e8 [Apr 13 14:00:13] DEBUG[4330]: chan_sip.c:14759 handle_request_bye: Received bye, issuing owner hangup [Apr 13 14:00:13] <--- Transmitting (no NAT) to 10.50.10.183:5060 ---> SIP/2.0 200 OK Via: SIP/2.0/UDP 10.50.10.183:5060;branch=z9hG4bKde7f94e4b6110c431;received=10.50.10.183 From: "PowerPBX 23" ;tag=4798cebe7e To: "station3_line1" ;tag=as7d6173b9 Call-ID: 071ad47524e1b4e8 CSeq: 12813 BYE User-Agent: Asterisk PBX Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY Supported: replaces Contact: Content-Length: 0 <------------> [Apr 13 14:00:13] DEBUG[4338]: devicestate.c:304 __ast_device_state_changed_literal: Notification of state change to be queued on device/channel SLA:station1_line1 [Apr 13 14:00:13] DEBUG[4338]: devicestate.c:304 __ast_device_state_changed_literal: Notification of state change to be queued on device/channel SLA:station2_line1 [Apr 13 14:00:13] DEBUG[4338]: devicestate.c:304 __ast_device_state_changed_literal: Notification of state change to be queued on device/channel SLA:station3_line1 [Apr 13 14:00:13] DEBUG[4338]: pbx.c:2456 __ast_pbx_run: Extension station3_line1, priority 1 returned normally even though call was hung up [Apr 13 14:00:13] DEBUG[4338]: channel.c:1378 ast_softhangup_nolock: Soft-Hanging up channel 'SIP/station3-09717830' [Apr 13 14:00:13] DEBUG[4338]: channel.c:1477 ast_hangup: Hanging up channel 'SIP/station3-09717830' [Apr 13 14:00:13] DEBUG[4338]: chan_sip.c:3498 sip_hangup: Hangup call SIP/station3-09717830, SIP callid 071ad47524e1b4e8) [Apr 13 14:00:13] DEBUG[4338]: devicestate.c:304 __ast_device_state_changed_literal: Notification of state change to be queued on device/channel SIP/station3-09717830 [Apr 13 14:00:13] DEBUG[4338]: devicestate.c:304 __ast_device_state_changed_literal: Notification of state change to be queued on device/channel SIP/station3 [Apr 13 14:00:13] DEBUG[4338]: pbx.c:1688 pbx_substitute_variables_helper_full: Function result is '"IC" <8055480003>' [Apr 13 14:00:13] DEBUG[4338]: pbx.c:1688 pbx_substitute_variables_helper_full: Function result is '8055480003' [Apr 13 14:00:13] DEBUG[4338]: pbx.c:1688 pbx_substitute_variables_helper_full: Function result is 'station3_line1' [Apr 13 14:00:13] DEBUG[4338]: pbx.c:1688 pbx_substitute_variables_helper_full: Function result is 'sla_stations' [Apr 13 14:00:13] DEBUG[4338]: pbx.c:1688 pbx_substitute_variables_helper_full: Function result is 'SIP/station3-09717830' [Apr 13 14:00:13] DEBUG[4338]: pbx.c:1688 pbx_substitute_variables_helper_full: Function result is '' [Apr 13 14:00:13] DEBUG[4338]: pbx.c:1688 pbx_substitute_variables_helper_full: Function result is 'SLAStation' [Apr 13 14:00:13] DEBUG[4338]: pbx.c:1688 pbx_substitute_variables_helper_full: Function result is 'station3_line1' [Apr 13 14:00:13] DEBUG[4338]: pbx.c:1688 pbx_substitute_variables_helper_full: Function result is '2008-04-13 14:00:07' [Apr 13 14:00:13] DEBUG[4338]: pbx.c:1688 pbx_substitute_variables_helper_full: Function result is '2008-04-13 14:00:07' [Apr 13 14:00:13] DEBUG[4338]: pbx.c:1688 pbx_substitute_variables_helper_full: Function result is '2008-04-13 14:00:13' [Apr 13 14:00:13] DEBUG[4338]: pbx.c:1688 pbx_substitute_variables_helper_full: Function result is '6' [Apr 13 14:00:13] DEBUG[4338]: pbx.c:1688 pbx_substitute_variables_helper_full: Function result is '6' [Apr 13 14:00:13] DEBUG[4338]: pbx.c:1688 pbx_substitute_variables_helper_full: Function result is 'ANSWERED' [Apr 13 14:00:13] DEBUG[4338]: pbx.c:1688 pbx_substitute_variables_helper_full: Function result is 'DOCUMENTATION' [Apr 13 14:00:13] DEBUG[4338]: pbx.c:1688 pbx_substitute_variables_helper_full: Function result is '' [Apr 13 14:00:13] DEBUG[4338]: pbx.c:1688 pbx_substitute_variables_helper_full: Function result is '1208120407.0' [Apr 13 14:00:13] DEBUG[4338]: pbx.c:1688 pbx_substitute_variables_helper_full: Function result is '' [Apr 13 14:00:13] DEBUG[4308]: devicestate.c:157 ast_device_state: Checking if I can find provider for "SLA" - number: station1_line1 [Apr 13 14:00:13] DEBUG[4308]: devicestate.c:230 getproviderstate: Checking provider SLA with SLA [Apr 13 14:00:13] DEBUG[4308]: devicestate.c:287 do_state_change: Changing state for SLA:station1_line1 - state 1 (Not in use) [Apr 13 14:00:13] DEBUG[4308]: devicestate.c:157 ast_device_state: Checking if I can find provider for "SLA" - number: station1_line1 [Apr 13 14:00:13] DEBUG[4308]: devicestate.c:230 getproviderstate: Checking provider SLA with SLA [Apr 13 14:00:13] DEBUG[4308]: devicestate.c:157 ast_device_state: Checking if I can find provider for "SLA" - number: station2_line1 [Apr 13 14:00:13] DEBUG[4308]: devicestate.c:230 getproviderstate: Checking provider SLA with SLA [Apr 13 14:00:13] DEBUG[4308]: devicestate.c:287 do_state_change: Changing state for SLA:station2_line1 - state 1 (Not in use) [Apr 13 14:00:13] DEBUG[4308]: devicestate.c:157 ast_device_state: Checking if I can find provider for "SLA" - number: station2_line1 [Apr 13 14:00:13] DEBUG[4308]: devicestate.c:230 getproviderstate: Checking provider SLA with SLA [Apr 13 14:00:13] DEBUG[4308]: devicestate.c:157 ast_device_state: Checking if I can find provider for "SLA" - number: station3_line1 [Apr 13 14:00:13] DEBUG[4308]: devicestate.c:230 getproviderstate: Checking provider SLA with SLA [Apr 13 14:00:13] DEBUG[4308]: devicestate.c:287 do_state_change: Changing state for SLA:station3_line1 - state 1 (Not in use) [Apr 13 14:00:13] DEBUG[4308]: devicestate.c:157 ast_device_state: Checking if I can find provider for "SLA" - number: station3_line1 [Apr 13 14:00:13] DEBUG[4308]: devicestate.c:230 getproviderstate: Checking provider SLA with SLA [Apr 13 14:00:13] DEBUG[4308]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for SIP - station3-09717830 [Apr 13 14:00:13] DEBUG[4308]: chan_sip.c:15855 sip_devicestate: Checking device state for peer station3-09717830 [Apr 13 14:00:13] DEBUG[4340]: devicestate.c:304 __ast_device_state_changed_literal: Notification of state change to be queued on device/channel meetme:SLA_line1 [Apr 13 14:00:13] DEBUG[4340]: channel.c:1477 ast_hangup: Hanging up channel 'Zap/pseudo-1660513430' [Apr 13 14:00:13] DEBUG[4340]: chan_zap.c:2424 zt_hangup: zt_hangup(Zap/pseudo-1660513430) [Apr 13 14:00:13] DEBUG[4340]: chan_zap.c:2458 zt_hangup: Hangup: channel: -2 index = 0, normal = 28, callwait = -1, thirdcall = -1 [Apr 13 14:00:13] DEBUG[4340]: chan_zap.c:2888 zt_setoption: Set option TDD MODE, value: OFF(0) on Zap/pseudo-1660513430 [Apr 13 14:00:13] DEBUG[4340]: chan_zap.c:1410 update_conf: Updated conferencing on -2, with 0 conference users [Apr 13 14:00:13] -- Hungup 'Zap/pseudo-1660513430' [Apr 13 14:00:13] DEBUG[4340]: devicestate.c:304 __ast_device_state_changed_literal: Notification of state change to be queued on device/channel Zap/pseudo-1660513430 [Apr 13 14:00:13] DEBUG[4340]: devicestate.c:304 __ast_device_state_changed_literal: Notification of state change to be queued on device/channel Zap/pseudo [Apr 13 14:00:13] DEBUG[4340]: devicestate.c:304 __ast_device_state_changed_literal: Notification of state change to be queued on device/channel SLA:station1_line1 [Apr 13 14:00:13] DEBUG[4340]: devicestate.c:304 __ast_device_state_changed_literal: Notification of state change to be queued on device/channel SLA:station2_line1 [Apr 13 14:00:13] DEBUG[4340]: devicestate.c:304 __ast_device_state_changed_literal: Notification of state change to be queued on device/channel SLA:station3_line1 [Apr 13 14:00:13] DEBUG[4340]: channel.c:1477 ast_hangup: Hanging up channel 'Local/disa@line1_outbound-00fe,1' [Apr 13 14:00:13] DEBUG[4340]: devicestate.c:304 __ast_device_state_changed_literal: Notification of state change to be queued on device/channel Local/disa@line1_outbound-00fe,1 [Apr 13 14:00:13] DEBUG[4340]: devicestate.c:304 __ast_device_state_changed_literal: Notification of state change to be queued on device/channel Local/disa@line1_outbound [Apr 13 14:00:13] DEBUG[4340]: pbx.c:1688 pbx_substitute_variables_helper_full: Function result is '' [Apr 13 14:00:13] DEBUG[4340]: pbx.c:1688 pbx_substitute_variables_helper_full: Function result is '' [Apr 13 14:00:13] DEBUG[4340]: pbx.c:1688 pbx_substitute_variables_helper_full: Function result is 'disa' [Apr 13 14:00:13] DEBUG[4340]: pbx.c:1688 pbx_substitute_variables_helper_full: Function result is 'line1_outbound' [Apr 13 14:00:13] DEBUG[4340]: pbx.c:1688 pbx_substitute_variables_helper_full: Function result is 'Local/disa@line1_outbound-00fe,1' [Apr 13 14:00:13] DEBUG[4340]: pbx.c:1688 pbx_substitute_variables_helper_full: Function result is '' [Apr 13 14:00:13] DEBUG[4340]: pbx.c:1688 pbx_substitute_variables_helper_full: Function result is '' [Apr 13 14:00:13] DEBUG[4340]: pbx.c:1688 pbx_substitute_variables_helper_full: Function result is '' [Apr 13 14:00:13] DEBUG[4340]: pbx.c:1688 pbx_substitute_variables_helper_full: Function result is '2008-04-13 14:00:07' [Apr 13 14:00:13] DEBUG[4340]: pbx.c:1688 pbx_substitute_variables_helper_full: Function result is '2008-04-13 14:00:07' [Apr 13 14:00:13] DEBUG[4340]: pbx.c:1688 pbx_substitute_variables_helper_full: Function result is '2008-04-13 14:00:13' [Apr 13 14:00:13] DEBUG[4340]: pbx.c:1688 pbx_substitute_variables_helper_full: Function result is '6' [Apr 13 14:00:13] DEBUG[4340]: pbx.c:1688 pbx_substitute_variables_helper_full: Function result is '6' [Apr 13 14:00:13] DEBUG[4340]: pbx.c:1688 pbx_substitute_variables_helper_full: Function result is 'ANSWERED' [Apr 13 14:00:13] DEBUG[4340]: pbx.c:1688 pbx_substitute_variables_helper_full: Function result is 'DOCUMENTATION' [Apr 13 14:00:13] DEBUG[4340]: pbx.c:1688 pbx_substitute_variables_helper_full: Function result is '' [Apr 13 14:00:13] DEBUG[4340]: pbx.c:1688 pbx_substitute_variables_helper_full: Function result is '1208120407.1' [Apr 13 14:00:13] DEBUG[4340]: pbx.c:1688 pbx_substitute_variables_helper_full: Function result is '' [Apr 13 14:00:13] DEBUG[4308]: devicestate.c:287 do_state_change: Changing state for SIP/station3-09717830 - state 4 (Invalid) [Apr 13 14:00:13] DEBUG[4308]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for SIP - station3 [Apr 13 14:00:13] DEBUG[4308]: chan_sip.c:15855 sip_devicestate: Checking device state for peer station3 [Apr 13 14:00:13] DEBUG[4308]: devicestate.c:287 do_state_change: Changing state for SIP/station3 - state 1 (Not in use) [Apr 13 14:00:13] DEBUG[4308]: devicestate.c:157 ast_device_state: Checking if I can find provider for "meetme" - number: SLA_line1 [Apr 13 14:00:13] DEBUG[4308]: devicestate.c:230 getproviderstate: Checking provider SLA with meetme [Apr 13 14:00:13] DEBUG[4308]: devicestate.c:230 getproviderstate: Checking provider Meetme with meetme [Apr 13 14:00:13] DEBUG[4308]: devicestate.c:287 do_state_change: Changing state for meetme:SLA_line1 - state 4 (Invalid) [Apr 13 14:00:13] DEBUG[4308]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for Zap - pseudo-1660513430 [Apr 13 14:00:13] DEBUG[4308]: devicestate.c:287 do_state_change: Changing state for Zap/pseudo-1660513430 - state 0 (Unknown) [Apr 13 14:00:13] DEBUG[4308]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for Zap - pseudo [Apr 13 14:00:13] DEBUG[4308]: devicestate.c:287 do_state_change: Changing state for Zap/pseudo - state 0 (Unknown) [Apr 13 14:00:13] DEBUG[4308]: devicestate.c:157 ast_device_state: Checking if I can find provider for "SLA" - number: station1_line1 [Apr 13 14:00:13] Really destroying SIP dialog '071ad47524e1b4e8' Method: BYE [Apr 13 14:00:13] DEBUG[4308]: devicestate.c:230 getproviderstate: Checking provider SLA with SLA [Apr 13 14:00:13] DEBUG[4308]: devicestate.c:287 do_state_change: Changing state for SLA:station1_line1 - state 1 (Not in use) [Apr 13 14:00:13] DEBUG[4308]: devicestate.c:157 ast_device_state: Checking if I can find provider for "SLA" - number: station1_line1 [Apr 13 14:00:13] DEBUG[4308]: devicestate.c:230 getproviderstate: Checking provider SLA with SLA [Apr 13 14:00:13] DEBUG[4308]: devicestate.c:157 ast_device_state: Checking if I can find provider for "SLA" - number: station2_line1 [Apr 13 14:00:13] DEBUG[4308]: devicestate.c:230 getproviderstate: Checking provider SLA with SLA [Apr 13 14:00:13] DEBUG[4308]: devicestate.c:287 do_state_change: Changing state for SLA:station2_line1 - state 1 (Not in use) [Apr 13 14:00:13] DEBUG[4308]: devicestate.c:157 ast_device_state: Checking if I can find provider for "SLA" - number: station2_line1 [Apr 13 14:00:13] DEBUG[4308]: devicestate.c:230 getproviderstate: Checking provider SLA with SLA [Apr 13 14:00:13] DEBUG[4308]: devicestate.c:157 ast_device_state: Checking if I can find provider for "SLA" - number: station3_line1 [Apr 13 14:00:13] DEBUG[4308]: devicestate.c:230 getproviderstate: Checking provider SLA with SLA [Apr 13 14:00:13] DEBUG[4308]: devicestate.c:287 do_state_change: Changing state for SLA:station3_line1 - state 1 (Not in use) [Apr 13 14:00:13] DEBUG[4308]: devicestate.c:157 ast_device_state: Checking if I can find provider for "SLA" - number: station3_line1 [Apr 13 14:00:13] DEBUG[4308]: devicestate.c:230 getproviderstate: Checking provider SLA with SLA [Apr 13 14:00:13] DEBUG[4308]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for Local - disa@line1_outbound-00fe,1 [Apr 13 14:00:13] DEBUG[4308]: chan_local.c:145 local_devicestate: Checking if extension disa@line1_outbound-00fe,1 exists (devicestate) [Apr 13 14:00:13] DEBUG[4308]: devicestate.c:287 do_state_change: Changing state for Local/disa@line1_outbound-00fe,1 - state 4 (Invalid) [Apr 13 14:00:13] DEBUG[4308]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for Local - disa@line1_outbound [Apr 13 14:00:13] DEBUG[4308]: chan_local.c:145 local_devicestate: Checking if extension disa@line1_outbound exists (devicestate) [Apr 13 14:00:13] DEBUG[4308]: channel.c:1068 channel_find_locked: Avoiding initial deadlock for channel '0x9712b30' [Apr 13 14:00:13] DEBUG[4333]: app_queue.c:609 handle_statechange: Device 'SIP/station3-09717830' changed to state '4' (Invalid) but we don't care because they're not a member of any queue. [Apr 13 14:00:13] DEBUG[4333]: app_queue.c:609 handle_statechange: Device 'SIP/station3' changed to state '1' (Not in use) but we don't care because they're not a member of any queue. [Apr 13 14:00:13] DEBUG[4333]: app_queue.c:609 handle_statechange: Device 'Zap/pseudo-1660513430' changed to state '0' (Unknown) but we don't care because they're not a member of any queue. [Apr 13 14:00:13] DEBUG[4333]: app_queue.c:609 handle_statechange: Device 'Zap/pseudo' changed to state '0' (Unknown) but we don't care because they're not a member of any queue. [Apr 13 14:00:13] DEBUG[4333]: app_queue.c:609 handle_statechange: Device 'Local/disa@line1_outbound-00fe,1' changed to state '4' (Invalid) but we don't care because they're not a member of any queue. [Apr 13 14:00:13] DEBUG[4341]: rtp.c:1503 ast_rtp_early_bridge: Channel 'Local/disa@line1_outbound-00fe,2' has no RTP, not doing anything [Apr 13 14:00:13] DEBUG[4341]: channel.c:1477 ast_hangup: Hanging up channel 'SIP/metaswitch0001-0971fb58' [Apr 13 14:00:13] DEBUG[4341]: chan_sip.c:3498 sip_hangup: Hangup call SIP/metaswitch0001-0971fb58, SIP callid 21249f7b23d1ae654bf45424212e7e7e@10.50.10.171) [Apr 13 14:00:13] DEBUG[4341]: chan_sip.c:3521 sip_hangup: Hanging up channel in state Down (not UP) [Apr 13 14:00:13] Scheduling destruction of SIP dialog '21249f7b23d1ae654bf45424212e7e7e@10.50.10.171' in 6400 ms (Method: INVITE) [Apr 13 14:00:13] DEBUG[4341]: chan_sip.c:2158 __sip_ack: Acked pending invite 102 [Apr 13 14:00:13] DEBUG[4341]: chan_sip.c:2175 __sip_ack: Stopping retransmission on '21249f7b23d1ae654bf45424212e7e7e@10.50.10.171' of Request 102: Match Found [Apr 13 14:00:13] Reliably Transmitting (no NAT) to 10.50.10.2:5060: CANCEL sip:7678900@10.50.10.2 SIP/2.0 Via: SIP/2.0/UDP 10.50.10.171:5060;branch=z9hG4bK561faea1;rport From: "IC" ;tag=as4344012e To: Call-ID: 21249f7b23d1ae654bf45424212e7e7e@10.50.10.171 CSeq: 102 CANCEL User-Agent: Asterisk PBX Max-Forwards: 70 Content-Length: 0 --- [Apr 13 14:00:13] DEBUG[4341]: chan_sip.c:2043 __sip_reliable_xmit: *** SIP TIMER: Initializing retransmit timer on packet: Id #-1 [Apr 13 14:00:13] Scheduling destruction of SIP dialog '21249f7b23d1ae654bf45424212e7e7e@10.50.10.171' in 6400 ms (Method: INVITE) [Apr 13 14:00:13] DEBUG[4341]: devicestate.c:304 __ast_device_state_changed_literal: Notification of state change to be queued on device/channel SIP/metaswitch0001-0971fb58 [Apr 13 14:00:13] DEBUG[4341]: devicestate.c:304 __ast_device_state_changed_literal: Notification of state change to be queued on device/channel SIP/metaswitch0001 [Apr 13 14:00:13] DEBUG[4341]: app_dial.c:1728 dial_exec_full: Exiting with DIALSTATUS=CANCEL. [Apr 13 14:00:13] DEBUG[4341]: pbx.c:2435 __ast_pbx_run: Spawn extension (line1_outbound,7678900,1) exited non-zero on 'Local/disa@line1_outbound-00fe,2' [Apr 13 14:00:13] == Spawn extension (line1_outbound, 7678900, 1) exited non-zero on 'Local/disa@line1_outbound-00fe,2' [Apr 13 14:00:13] DEBUG[4341]: channel.c:1378 ast_softhangup_nolock: Soft-Hanging up channel 'Local/disa@line1_outbound-00fe,2' [Apr 13 14:00:13] DEBUG[4341]: channel.c:1477 ast_hangup: Hanging up channel 'Local/disa@line1_outbound-00fe,2' [Apr 13 14:00:13] DEBUG[4341]: devicestate.c:304 __ast_device_state_changed_literal: Notification of state change to be queued on device/channel Local/disa@line1_outbound-00fe,2 [Apr 13 14:00:13] DEBUG[4341]: devicestate.c:304 __ast_device_state_changed_literal: Notification of state change to be queued on device/channel Local/disa@line1_outbound [Apr 13 14:00:13] DEBUG[4341]: pbx.c:1688 pbx_substitute_variables_helper_full: Function result is '"IC" <8055480003>' [Apr 13 14:00:13] DEBUG[4341]: pbx.c:1688 pbx_substitute_variables_helper_full: Function result is '8055480003' [Apr 13 14:00:13] DEBUG[4341]: pbx.c:1688 pbx_substitute_variables_helper_full: [Apr 13 14:00:13] <--- SIP read from 10.50.10.2:5060 ---> SIP/2.0 200 OK Call-ID: 21249f7b23d1ae654bf45424212e7e7e@10.50.10.171 CSeq: 102 CANCEL From: "IC" ;tag=as4344012e To: ;tag=metaswitch+1+14ee4b+6094bc39 Via: SIP/2.0/UDP 10.50.10.171:5060;rport=5060;branch=z9hG4bK561faea1 Server: DC-SIP/2.0 Organization: Supported: 100rel Content-Length: 0 <-------------> Function result is '7678900' [Apr 13 14:00:13] DEBUG[4341]: pbx.c:1688 pbx_substitute_variables_helper_full: Function result is 'line1_outbound' [Apr 13 14:00:13] DEBUG[4341]: pbx.c:1688 pbx_substitute_variables_helper_full: Function result is 'Local/disa@line1_outbound-00fe,2' [Apr 13 14:00:13] DEBUG[4341]: pbx.c:1688 pbx_substitute_variables_helper_full: Function result is 'SIP/metaswitch0001-0971fb58' [Apr 13 14:00:13] DEBUG[4341]: pbx.c:1688 pbx_substitute_variables_helper_full: Function result is 'Dial' [Apr 13 14:00:13] DEBUG[4341]: pbx.c:1688 pbx_substitute_variables_helper_full: Function result is 'SIP/7678900@metaswitch0001|60' [Apr 13 14:00:13] DEBUG[4341]: pbx.c:1688 pbx_substitute_variables_helper_full: Function result is '2008-04-13 14:00:11' [Apr 13 14:00:13] DEBUG[4341]: pbx.c:1688 pbx_substitute_variables_helper_full: Function result is '' [Apr 13 14:00:13] DEBUG[4341]: pbx.c:1688 pbx_substitute_variables_helper_full: Function result is '2008-04-13 14:00:13' [Apr 13 14:00:13] DEBUG[4341]: pbx.c:1688 pbx_substitute_variables_helper_full: Function result is '2' [Apr 13 14:00:13] DEBUG[4341]: pbx.c:1688 pbx_substitute_variables_helper_full: Function result is '0' [Apr 13 14:00:13] DEBUG[4341]: pbx.c:1688 pbx_substitute_variables_helper_full: Function result is 'NO ANSWER' [Apr 13 14:00:13] DEBUG[4341]: pbx.c:1688 pbx_substitute_variables_helper_full: Function result is 'DOCUMENTATION' [Apr 13 14:00:13] DEBUG[4341]: pbx.c:1688 pbx_substitute_variables_helper_full: Function result is '' [Apr 13 14:00:13] DEBUG[4341]: pbx.c:1688 pbx_substitute_variables_helper_full: Function result is '1208120407.2' [Apr 13 14:00:13] DEBUG[4341]: pbx.c:1688 pbx_substitute_variables_helper_full: Function result is '' [Apr 13 14:00:13] DEBUG[4308]: devicestate.c:287 do_state_change: Changing state for Local/disa@line1_outbound - state 1 (Not in use) [Apr 13 14:00:13] DEBUG[4330]: chan_sip.c:4794 parse_request: Header 0: SIP/2.0 200 OK (14) [Apr 13 14:00:13] DEBUG[4330]: chan_sip.c:4794 parse_request: Header 1: Call-ID: 21249f7b23d1ae654bf45424212e7e7e@10.50.10.171 (54) [Apr 13 14:00:13] DEBUG[4330]: chan_sip.c:4794 parse_request: Header 2: CSeq: 102 CANCEL (16) [Apr 13 14:00:13] DEBUG[4330]: chan_sip.c:4794 parse_request: Header 3: From: "IC" ;tag=as4344012e (55) [Apr 13 14:00:13] DEBUG[4330]: chan_sip.c:4794 parse_request: Header 4: To: ;tag=metaswitch+1+14ee4b+6094bc39 (61) [Apr 13 14:00:13] DEBUG[4330]: chan_sip.c:4794 parse_request: Header 5: Via: SIP/2.0/UDP 10.50.10.171:5060;rport=5060;branch=z9hG4bK561faea1 (68) [Apr 13 14:00:13] DEBUG[4330]: chan_sip.c:4794 parse_request: Header 6: Server: DC-SIP/2.0 (18) [Apr 13 14:00:13] DEBUG[4330]: chan_sip.c:4794 parse_request: Header 7: Organization: (14) [Apr 13 14:00:13] DEBUG[4330]: chan_sip.c:4794 parse_request: Header 8: Supported: 100rel (17) [Apr 13 14:00:13] DEBUG[4330]: chan_sip.c:4794 parse_request: Header 9: Content-Length: 0 (17) [Apr 13 14:00:13] --- (10 headers 0 lines) --- [Apr 13 14:00:13] DEBUG[4330]: chan_sip.c:4566 find_call: = Looking for Call ID: 21249f7b23d1ae654bf45424212e7e7e@10.50.10.171 (Checking To) --From tag as4344012e --To-tag metaswitch+1+14ee4b+6094bc39 [Apr 13 14:00:13] DEBUG[4330]: chan_sip.c:4582 find_call: = Found Their Call ID: 21249f7b23d1ae654bf45424212e7e7e@10.50.10.171 Their Tag metaswitch+1+14ee4b+6094bc39 Our tag: as4344012e [Apr 13 14:00:13] DEBUG[4330]: chan_sip.c:2166 __sip_ack: ** SIP TIMER: Cancelling retransmit of packet (reply received) Retransid #45 [Apr 13 14:00:13] DEBUG[4330]: chan_sip.c:2175 __sip_ack: Stopping retransmission on '21249f7b23d1ae654bf45424212e7e7e@10.50.10.171' of Request 102: Match Found [Apr 13 14:00:13] <--- SIP read from 10.50.10.2:5060 ---> SIP/2.0 487 Request Terminated Call-ID: 21249f7b23d1ae654bf45424212e7e7e@10.50.10.171 CSeq: 102 INVITE From: "IC" ;tag=as4344012e To: ;tag=metaswitch+1+14ee4b+6094bc39 Via: SIP/2.0/UDP 10.50.10.171:5060;rport=5060;branch=z9hG4bK561faea1 Server: DC-SIP/2.0 Organization: Supported: 100rel Contact: Content-Length: 0 <-------------> [Apr 13 14:00:13] DEBUG[4330]: chan_sip.c:4794 parse_request: Header 0: SIP/2.0 487 Request Terminated (30) [Apr 13 14:00:13] DEBUG[4330]: chan_sip.c:4794 parse_request: Header 1: Call-ID: 21249f7b23d1ae654bf45424212e7e7e@10.50.10.171 (54) [Apr 13 14:00:13] DEBUG[4330]: chan_sip.c:4794 parse_request: Header 2: CSeq: 102 INVITE (16) [Apr 13 14:00:13] DEBUG[4330]: chan_sip.c:4794 parse_request: Header 3: From: "IC" ;tag=as4344012e (55) [Apr 13 14:00:13] DEBUG[4330]: chan_sip.c:4794 parse_request: Header 4: To: ;tag=metaswitch+1+14ee4b+6094bc39 (61) [Apr 13 14:00:13] DEBUG[4330]: chan_sip.c:4794 parse_request: Header 5: Via: SIP/2.0/UDP 10.50.10.171:5060;rport=5060;branch=z9hG4bK561faea1 (68) [Apr 13 14:00:13] DEBUG[4330]: chan_sip.c:4794 parse_request: Header 6: Server: DC-SIP/2.0 (18) [Apr 13 14:00:13] DEBUG[4330]: chan_sip.c:4794 parse_request: Header 7: Organization: (14) [Apr 13 14:00:13] DEBUG[4330]: chan_sip.c:4794 parse_request: Header 8: Supported: 100rel (17) [Apr 13 14:00:13] DEBUG[4330]: chan_sip.c:4794 parse_request: Header 9: Contact: (33) [Apr 13 14:00:13] DEBUG[4330]: chan_sip.c:4794 parse_request: Header 10: Content-Length: 0 (17) [Apr 13 14:00:13] --- (11 headers 0 lines) --- [Apr 13 14:00:13] DEBUG[4330]: chan_sip.c:4566 find_call: = Looking for Call ID: 21249f7b23d1ae654bf45424212e7e7e@10.50.10.171 (Checking To) --From tag as4344012e --To-tag metaswitch+1+14ee4b+6094bc39 [Apr 13 14:00:13] DEBUG[4330]: chan_sip.c:4582 find_call: = Found Their Call ID: 21249f7b23d1ae654bf45424212e7e7e@10.50.10.171 Their Tag metaswitch+1+14ee4b+6094bc39 Our tag: as4344012e [Apr 13 14:00:13] DEBUG[4330]: chan_sip.c:2175 __sip_ack: Stopping retransmission on '21249f7b23d1ae654bf45424212e7e7e@10.50.10.171' of Request 102: Match Not Found [Apr 13 14:00:13] DEBUG[4330]: chan_sip.c:12022 handle_response_invite: SIP response 487 to standard invite [Apr 13 14:00:13] Transmitting (no NAT) to 10.50.10.2:5060: ACK sip:7678900@10.50.10.2 SIP/2.0 Via: SIP/2.0/UDP 10.50.10.171:5060;branch=z9hG4bK561faea1;rport From: "IC" ;tag=as4344012e To: ;tag=metaswitch+1+14ee4b+6094bc39 Contact: Call-ID: 21249f7b23d1ae654bf45424212e7e7e@10.50.10.171 CSeq: 102 ACK User-Agent: Asterisk PBX Max-Forwards: 70 Content-Length: 0 --- [Apr 13 14:00:13] DEBUG[4330]: chan_sip.c:3186 update_call_counter: Updating call counter for outgoing call [Apr 13 14:00:13] DEBUG[4330]: chan_sip.c:1655 sip_alreadygone: Setting SIP_ALREADYGONE on dialog 21249f7b23d1ae654bf45424212e7e7e@10.50.10.171 [Apr 13 14:00:13] DEBUG[4308]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for SIP - metaswitch0001-0971fb58 [Apr 13 14:00:13] DEBUG[4308]: chan_sip.c:15855 sip_devicestate: Checking device state for peer metaswitch0001-0971fb58 [Apr 13 14:00:13] DEBUG[4333]: app_queue.c:609 handle_statechange: Device 'Local/disa@line1_outbound' changed to state '1' (Not in use) but we don't care because they're not a member of any queue. [Apr 13 14:00:13] Really destroying SIP dialog '21249f7b23d1ae654bf45424212e7e7e@10.50.10.171' Method: INVITE [Apr 13 14:00:13] DEBUG[4308]: devicestate.c:287 do_state_change: Changing state for SIP/metaswitch0001-0971fb58 - state 4 (Invalid) [Apr 13 14:00:13] DEBUG[4308]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for SIP - metaswitch0001 [Apr 13 14:00:13] DEBUG[4308]: chan_sip.c:15855 sip_devicestate: Checking device state for peer metaswitch0001 [Apr 13 14:00:13] DEBUG[4308]: devicestate.c:287 do_state_change: Changing state for SIP/metaswitch0001 - state 1 (Not in use) [Apr 13 14:00:13] DEBUG[4308]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for Local - disa@line1_outbound-00fe,2 [Apr 13 14:00:13] DEBUG[4308]: chan_local.c:145 local_devicestate: Checking if extension disa@line1_outbound-00fe,2 exists (devicestate) [Apr 13 14:00:13] DEBUG[4308]: devicestate.c:287 do_state_change: Changing state for Local/disa@line1_outbound-00fe,2 - state 4 (Invalid) [Apr 13 14:00:13] DEBUG[4308]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for Local - disa@line1_outbound [Apr 13 14:00:13] DEBUG[4308]: chan_local.c:145 local_devicestate: Checking if extension disa@line1_outbound exists (devicestate) [Apr 13 14:00:13] DEBUG[4308]: devicestate.c:287 do_state_change: Changing state for Local/disa@line1_outbound - state 1 (Not in use) [Apr 13 14:00:13] DEBUG[4333]: app_queue.c:609 handle_statechange: Device 'SIP/metaswitch0001-0971fb58' changed to state '4' (Invalid) but we don't care because they're not a member of any queue. [Apr 13 14:00:13] DEBUG[4333]: app_queue.c:609 handle_statechange: Device 'SIP/metaswitch0001' changed to state '1' (Not in use) but we don't care because they're not a member of any queue. [Apr 13 14:00:13] DEBUG[4333]: app_queue.c:609 handle_statechange: Device 'Local/disa@line1_outbound-00fe,2' changed to state '4' (Invalid) but we don't care because they're not a member of any queue. [Apr 13 14:00:13] DEBUG[4333]: app_queue.c:609 handle_statechange: Device 'Local/disa@line1_outbound' changed to state '1' (Not in use) but we don't care because they're not a member of any queue. [Apr 13 14:00:22] <--- 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-902b3db0063a5efe310f7b47bf30caf2-metaswitch-1 Allow-Events: message-summary Allow-Events: refer Allow-Events: dialog Allow-Events: line-seize Max-Forwards: 70 Call-ID: 787823BD@metaswitch From: ;tag=metaswitch+1+0+d6a5cb4d CSeq: 424523867 OPTIONS Organization: Supported: 100rel Content-Length: 0 Contact: To: <-------------> [Apr 13 14:00:22] DEBUG[4330]: chan_sip.c:4794 parse_request: Header 0: OPTIONS sip:metaswitch@10.50.10.171:5060;transport=udp SIP/2.0 (62) [Apr 13 14:00:22] DEBUG[4330]: chan_sip.c:4794 parse_request: Header 1: Via: SIP/2.0/UDP 10.50.10.2:5060;rport;branch=z9hG4bK-902b3db0063a5efe310f7b47bf30caf2-metaswitch-1 (99) [Apr 13 14:00:22] DEBUG[4330]: chan_sip.c:4794 parse_request: Header 2: Allow-Events: message-summary (29) [Apr 13 14:00:22] DEBUG[4330]: chan_sip.c:4794 parse_request: Header 3: Allow-Events: refer (19) [Apr 13 14:00:22] DEBUG[4330]: chan_sip.c:4794 parse_request: Header 4: Allow-Events: dialog (20) [Apr 13 14:00:22] DEBUG[4330]: chan_sip.c:4794 parse_request: Header 5: Allow-Events: line-seize (24) [Apr 13 14:00:22] DEBUG[4330]: chan_sip.c:4794 parse_request: Header 6: Max-Forwards: 70 (16) [Apr 13 14:00:22] DEBUG[4330]: chan_sip.c:4794 parse_request: Header 7: Call-ID: 787823BD@metaswitch (28) [Apr 13 14:00:22] DEBUG[4330]: chan_sip.c:4794 parse_request: Header 8: From: ;tag=metaswitch+1+0+d6a5cb4d (66) [Apr 13 14:00:22] DEBUG[4330]: chan_sip.c:4794 parse_request: Header 9: CSeq: 424523867 OPTIONS (23) [Apr 13 14:00:22] DEBUG[4330]: chan_sip.c:4794 parse_request: Header 10: Organization: (14) [Apr 13 14:00:22] DEBUG[4330]: chan_sip.c:4794 parse_request: Header 11: Supported: 100rel (17) [Apr 13 14:00:22] DEBUG[4330]: chan_sip.c:4794 parse_request: Header 12: Content-Length: 0 (17) [Apr 13 14:00:22] DEBUG[4330]: chan_sip.c:4794 parse_request: Header 13: Contact: (41) [Apr 13 14:00:22] DEBUG[4330]: chan_sip.c:4794 parse_request: Header 14: To: (33) [Apr 13 14:00:22] --- (15 headers 0 lines) --- [Apr 13 14:00:22] DEBUG[4330]: chan_sip.c:4566 find_call: = Looking for Call ID: 787823BD@metaswitch (Checking From) --From tag metaswitch+1+0+d6a5cb4d --To-tag [Apr 13 14:00:22] DEBUG[4330]: chan_sip.c:4582 find_call: = No match Their Call ID: CEDB0C22@metaswitch Their Tag metaswitch+1+0+bf1272c3 Our tag: as11e9e6a5 [Apr 13 14:00:22] DEBUG[4330]: chan_sip.c:4529 sip_alloc: Allocating new SIP dialog for 787823BD@metaswitch - OPTIONS (No RTP) [Apr 13 14:00:22] DEBUG[4330]: chan_sip.c:15219 handle_request: **** Received OPTIONS (3) - Command in SIP OPTIONS [Apr 13 14:00:22] Looking for metaswitch in default (domain 10.50.10.171) [Apr 13 14:00:22] <--- 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-902b3db0063a5efe310f7b47bf30caf2-metaswitch-1;received=10.50.10.2 From: ;tag=metaswitch+1+0+d6a5cb4d To: ;tag=as51adb1d6 Call-ID: 787823BD@metaswitch CSeq: 424523867 OPTIONS User-Agent: Asterisk PBX Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY Supported: replaces Accept: application/sdp Content-Length: 0 <------------>