[Apr 13 14:45:44] Asterisk 1.6.0-beta7.1, Copyright (C) 1999 - 2008 Digium, Inc. and others. SIP Debugging enabled *CLI> [Apr 13 14:45:58] <--- SIP read from UDP://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=z9hG4bK2ebc463f61f63c71d Max-Forwards: 70 From: "PowerPBX 23" ;tag=4d6ff13510 To: "station3_line1" Call-ID: a3a868736ab469d3 CSeq: 21099 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:45:58] DEBUG[3291]: chan_sip.c:6121 parse_request: Header 0 [ 51]: INVITE sip:station3_line1@10.50.10.171:5060 SIP/2.0 [Apr 13 14:45:58] DEBUG[3291]: chan_sip.c:6121 parse_request: Header 1 [ 66]: Via: SIP/2.0/UDP 10.50.10.183:5060;branch=z9hG4bK2ebc463f61f63c71d [Apr 13 14:45:58] DEBUG[3291]: chan_sip.c:6121 parse_request: Header 2 [ 16]: Max-Forwards: 70 [Apr 13 14:45:58] DEBUG[3291]: chan_sip.c:6121 parse_request: Header 3 [ 67]: From: "PowerPBX 23" ;tag=4d6ff13510 [Apr 13 14:45:58] DEBUG[3291]: chan_sip.c:6121 parse_request: Header 4 [ 59]: To: "station3_line1" [Apr 13 14:45:58] DEBUG[3291]: chan_sip.c:6121 parse_request: Header 5 [ 25]: Call-ID: a3a868736ab469d3 [Apr 13 14:45:58] DEBUG[3291]: chan_sip.c:6121 parse_request: Header 6 [ 18]: CSeq: 21099 INVITE [Apr 13 14:45:58] DEBUG[3291]: chan_sip.c:6121 parse_request: Header 7 [ 87]: Allow: INVITE, ACK, CANCEL, BYE, NOTIFY, REFER, OPTIONS, UPDATE, PRACK, SUBSCRIBE, INFO [Apr 13 14:45:58] DEBUG[3291]: chan_sip.c:6121 parse_request: Header 8 [ 36]: Allow-Events: talk, hold, conference [Apr 13 14:45:58] DEBUG[3291]: chan_sip.c:6121 parse_request: Header 9 [ 67]: Contact: PowerPBX 23 [Apr 13 14:45:58] DEBUG[3291]: chan_sip.c:6121 parse_request: Header 10 [ 34]: Supported: timer, 100rel, replaces [Apr 13 14:45:58] DEBUG[3291]: chan_sip.c:6121 parse_request: Header 11 [ 32]: User-Agent: Aastra 55i/2.2.0.166 [Apr 13 14:45:58] DEBUG[3291]: chan_sip.c:6121 parse_request: Header 12 [ 29]: Content-Type: application/sdp [Apr 13 14:45:58] DEBUG[3291]: chan_sip.c:6121 parse_request: Header 13 [ 19]: Content-Length: 282 [Apr 13 14:45:58] DEBUG[3291]: chan_sip.c:6121 parse_request: Header 14 [ 0]: [Apr 13 14:45:58] DEBUG[3291]: chan_sip.c:6121 parse_request: Body 0 [ 3]: v=0 [Apr 13 14:45:58] DEBUG[3291]: chan_sip.c:6121 parse_request: Body 1 [ 31]: o=MxSIP 0 0 IN IP4 10.50.10.183 [Apr 13 14:45:58] DEBUG[3291]: chan_sip.c:6121 parse_request: Body 2 [ 10]: s=SIP Call [Apr 13 14:45:58] DEBUG[3291]: chan_sip.c:6121 parse_request: Body 3 [ 21]: c=IN IP4 10.50.10.183 [Apr 13 14:45:58] DEBUG[3291]: chan_sip.c:6121 parse_request: Body 4 [ 5]: t=0 0 [Apr 13 14:45:58] DEBUG[3291]: chan_sip.c:6121 parse_request: Body 5 [ 31]: m=audio 3000 RTP/AVP 0 8 18 101 [Apr 13 14:45:58] DEBUG[3291]: chan_sip.c:6121 parse_request: Body 6 [ 20]: a=rtpmap:0 PCMU/8000 [Apr 13 14:45:58] DEBUG[3291]: chan_sip.c:6121 parse_request: Body 7 [ 20]: a=rtpmap:8 PCMA/8000 [Apr 13 14:45:58] DEBUG[3291]: chan_sip.c:6121 parse_request: Body 8 [ 21]: a=rtpmap:18 G729/8000 [Apr 13 14:45:58] DEBUG[3291]: chan_sip.c:6121 parse_request: Body 9 [ 33]: a=rtpmap:101 telephone-event/8000 [Apr 13 14:45:58] DEBUG[3291]: chan_sip.c:6121 parse_request: Body 10 [ 24]: a=silenceSupp:on - - - - [Apr 13 14:45:58] DEBUG[3291]: chan_sip.c:6121 parse_request: Body 11 [ 15]: a=fmtp:101 0-15 [Apr 13 14:45:58] DEBUG[3291]: chan_sip.c:6121 parse_request: Body 12 [ 10]: a=ptime:30 [Apr 13 14:45:58] DEBUG[3291]: chan_sip.c:6141 parse_request: Body 13 [ 10]: a=sendrecv [Apr 13 14:45:58] --- (14 headers 14 lines) --- [Apr 13 14:45:58] DEBUG[3291]: chan_sip.c:5849 find_call: = Looking for Call ID: a3a868736ab469d3 (Checking From) --From tag 4d6ff13510 --To-tag [Apr 13 14:45:58] DEBUG[3291]: chan_sip.c:5876 find_call: = No match Their Call ID: 58836ef0798742bf4002370e5877c808@127.0.0.1 Their Tag metaswitch+1+0+cda6eac1 Our tag: as6c690e8a [Apr 13 14:45:58] DEBUG[3291]: chan_sip.c:5876 find_call: = No match Their Call ID: 59bec6a116d82a3955a4f74c1cee14a6@127.0.0.1 Their Tag metaswitch+1+0+6e97b884 Our tag: as1fd94a8c [Apr 13 14:45:58] DEBUG[3291]: chan_sip.c:5876 find_call: = No match Their Call ID: 48ef4f2a7baf832d1192b297083293d7@127.0.0.1 Their Tag metaswitch+1+0+a5680d76 Our tag: as5da77ddc [Apr 13 14:45:58] DEBUG[3291]: chan_sip.c:5876 find_call: = No match Their Call ID: 615078E5@metaswitch Their Tag metaswitch+1+0+8b861ff2 Our tag: as4b149aa5 [Apr 13 14:45:58] DEBUG[3291]: acl.c:490 ast_ouraddrfor: Found IP address for this socket [Apr 13 14:45:58] == Using SIP RTP CoS mark 5 [Apr 13 14:45:58] DEBUG[3291]: chan_sip.c:3837 do_setnat: Setting NAT on RTP to Off [Apr 13 14:45:58] DEBUG[3291]: chan_sip.c:5810 sip_alloc: Allocating new SIP dialog for a3a868736ab469d3 - INVITE (With RTP) [Apr 13 14:45:58] DEBUG[3291]: chan_sip.c:17847 handle_incoming: **** Received INVITE (5) - Command in SIP INVITE [Apr 13 14:45:58] DEBUG[3291]: chan_sip.c:2420 parse_sip_options: Begin: parsing SIP "Supported: timer, 100rel, replaces" [Apr 13 14:45:58] DEBUG[3291]: chan_sip.c:2428 parse_sip_options: Found SIP option: -timer- [Apr 13 14:45:58] DEBUG[3291]: chan_sip.c:2434 parse_sip_options: Matched SIP option: timer [Apr 13 14:45:58] DEBUG[3291]: chan_sip.c:2428 parse_sip_options: Found SIP option: -100rel- [Apr 13 14:45:58] DEBUG[3291]: chan_sip.c:2434 parse_sip_options: Matched SIP option: 100rel [Apr 13 14:45:58] DEBUG[3291]: chan_sip.c:2428 parse_sip_options: Found SIP option: -replaces- [Apr 13 14:45:58] DEBUG[3291]: chan_sip.c:2434 parse_sip_options: Matched SIP option: replaces [Apr 13 14:45:58] Sending to 10.50.10.183 : 5060 (no NAT) [Apr 13 14:45:58] DEBUG[3291]: chan_sip.c:16265 handle_request_invite: Initializing initreq for method INVITE - callid a3a868736ab469d3 [Apr 13 14:45:58] Using INVITE request as basis request - a3a868736ab469d3 [Apr 13 14:45:58] Found user 'station3' for 'station3' [Apr 13 14:45:58] DEBUG[3291]: chan_sip.c:3837 do_setnat: Setting NAT on RTP to Off [Apr 13 14:45:58] <--- Reliably Transmitting (no NAT) to 10.50.10.183:5060 ---> SIP/2.0 401 Unauthorized Via: SIP/2.0/UDP 10.50.10.183:5060;branch=z9hG4bK2ebc463f61f63c71d;received=10.50.10.183 From: "PowerPBX 23" ;tag=4d6ff13510 To: "station3_line1" ;tag=as6bc152de Call-ID: a3a868736ab469d3 CSeq: 21099 INVITE User-Agent: Asterisk PBX 1.6.0-beta7.1 Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY Supported: replaces, timer WWW-Authenticate: Digest algorithm=MD5, realm="asterisk", nonce="5f2becac" Content-Length: 0 <------------> [Apr 13 14:45:58] DEBUG[3291]: chan_sip.c:2837 __sip_reliable_xmit: *** SIP TIMER: Initializing retransmit timer on packet: Id #35 [Apr 13 14:45:58] DEBUG[3291]: chan_sip.c:2520 __sip_xmit: Trying to put 'SIP/2.0 40' onto UDP socket... [Apr 13 14:45:58] Scheduling destruction of SIP dialog 'a3a868736ab469d3' in 32000 ms (Method: INVITE) [Apr 13 14:45:58] <--- SIP read from UDP://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=z9hG4bK2ebc463f61f63c71d Max-Forwards: 70 From: "PowerPBX 23" ;tag=4d6ff13510 To: "station3_line1" ;tag=as6bc152de Call-ID: a3a868736ab469d3 CSeq: 21099 ACK User-Agent: Aastra 55i/2.2.0.166 Content-Length: 0 <-------------> [Apr 13 14:45:58] DEBUG[3291]: chan_sip.c:6121 parse_request: Header 0 [ 48]: ACK sip:station3_line1@10.50.10.171:5060 SIP/2.0 [Apr 13 14:45:58] DEBUG[3291]: chan_sip.c:6121 parse_request: Header 1 [ 66]: Via: SIP/2.0/UDP 10.50.10.183:5060;branch=z9hG4bK2ebc463f61f63c71d [Apr 13 14:45:58] DEBUG[3291]: chan_sip.c:6121 parse_request: Header 2 [ 16]: Max-Forwards: 70 [Apr 13 14:45:58] DEBUG[3291]: chan_sip.c:6121 parse_request: Header 3 [ 67]: From: "PowerPBX 23" ;tag=4d6ff13510 [Apr 13 14:45:58] DEBUG[3291]: chan_sip.c:6121 parse_request: Header 4 [ 74]: To: "station3_line1" ;tag=as6bc152de [Apr 13 14:45:58] DEBUG[3291]: chan_sip.c:6121 parse_request: Header 5 [ 25]: Call-ID: a3a868736ab469d3 [Apr 13 14:45:58] DEBUG[3291]: chan_sip.c:6121 parse_request: Header 6 [ 15]: CSeq: 21099 ACK [Apr 13 14:45:58] DEBUG[3291]: chan_sip.c:6121 parse_request: Header 7 [ 32]: User-Agent: Aastra 55i/2.2.0.166 [Apr 13 14:45:58] DEBUG[3291]: chan_sip.c:6121 parse_request: Header 8 [ 17]: Content-Length: 0 [Apr 13 14:45:58] --- (9 headers 0 lines) --- [Apr 13 14:45:58] DEBUG[3291]: chan_sip.c:5849 find_call: = Looking for Call ID: a3a868736ab469d3 (Checking From) --From tag 4d6ff13510 --To-tag as6bc152de [Apr 13 14:45:58] DEBUG[3291]: chan_sip.c:5876 find_call: = Found Their Call ID: a3a868736ab469d3 Their Tag 4d6ff13510 Our tag: as6bc152de [Apr 13 14:45:58] DEBUG[3291]: chan_sip.c:17847 handle_incoming: **** Received ACK (6) - Command in SIP ACK [Apr 13 14:45:58] DEBUG[3291]: chan_sip.c:2966 __sip_ack: ** SIP TIMER: Cancelling retransmit of packet (reply received) Retransid #35 [Apr 13 14:45:58] DEBUG[3291]: chan_sip.c:2996 __sip_ack: Stopping retransmission on 'a3a868736ab469d3' of Response 21099: Match Found [Apr 13 14:45:58] <--- SIP read from UDP://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=z9hG4bKab56d32f697831f2c Max-Forwards: 70 From: "PowerPBX 23" ;tag=4d6ff13510 To: "station3_line1" Call-ID: a3a868736ab469d3 CSeq: 21100 INVITE Allow: INVITE, ACK, CANCEL, BYE, NOTIFY, REFER, OPTIONS, UPDATE, PRACK, SUBSCRIBE, INFO Allow-Events: talk, hold, conference Authorization: Digest username="station3",realm="asterisk",nonce="5f2becac",uri="sip:station3_line1@10.50.10.171:5060",response="be6b39cfbfd7ea59219679aba72bdd2c",algorithm=MD5 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:45:58] DEBUG[3291]: chan_sip.c:6121 parse_request: Header 0 [ 51]: INVITE sip:station3_line1@10.50.10.171:5060 SIP/2.0 [Apr 13 14:45:58] DEBUG[3291]: chan_sip.c:6121 parse_request: Header 1 [ 66]: Via: SIP/2.0/UDP 10.50.10.183:5060;branch=z9hG4bKab56d32f697831f2c [Apr 13 14:45:58] DEBUG[3291]: chan_sip.c:6121 parse_request: Header 2 [ 16]: Max-Forwards: 70 [Apr 13 14:45:58] DEBUG[3291]: chan_sip.c:6121 parse_request: Header 3 [ 67]: From: "PowerPBX 23" ;tag=4d6ff13510 [Apr 13 14:45:58] DEBUG[3291]: chan_sip.c:6121 parse_request: Header 4 [ 59]: To: "station3_line1" [Apr 13 14:45:58] DEBUG[3291]: chan_sip.c:6121 parse_request: Header 5 [ 25]: Call-ID: a3a868736ab469d3 [Apr 13 14:45:58] DEBUG[3291]: chan_sip.c:6121 parse_request: Header 6 [ 18]: CSeq: 21100 INVITE [Apr 13 14:45:58] DEBUG[3291]: chan_sip.c:6121 parse_request: Header 7 [ 87]: Allow: INVITE, ACK, CANCEL, BYE, NOTIFY, REFER, OPTIONS, UPDATE, PRACK, SUBSCRIBE, INFO [Apr 13 14:45:58] DEBUG[3291]: chan_sip.c:6121 parse_request: Header 8 [ 36]: Allow-Events: talk, hold, conference [Apr 13 14:45:58] DEBUG[3291]: chan_sip.c:6121 parse_request: Header 9 [176]: Authorization: Digest username="station3",realm="asterisk",nonce="5f2becac",uri="sip:station3_line1@10.50.10.171:5060",response="be6b39cfbfd7ea59219679aba72bdd2c",algorithm=MD5 [Apr 13 14:45:58] DEBUG[3291]: chan_sip.c:6121 parse_request: Header 10 [ 67]: Contact: PowerPBX 23 [Apr 13 14:45:58] DEBUG[3291]: chan_sip.c:6121 parse_request: Header 11 [ 34]: Supported: timer, 100rel, replaces [Apr 13 14:45:58] DEBUG[3291]: chan_sip.c:6121 parse_request: Header 12 [ 32]: User-Agent: Aastra 55i/2.2.0.166 [Apr 13 14:45:58] DEBUG[3291]: chan_sip.c:6121 parse_request: Header 13 [ 29]: Content-Type: application/sdp [Apr 13 14:45:58] DEBUG[3291]: chan_sip.c:6121 parse_request: Header 14 [ 19]: Content-Length: 282 [Apr 13 14:45:58] DEBUG[3291]: chan_sip.c:6121 parse_request: Header 15 [ 0]: [Apr 13 14:45:58] DEBUG[3291]: chan_sip.c:6121 parse_request: Body 0 [ 3]: v=0 [Apr 13 14:45:58] DEBUG[3291]: chan_sip.c:6121 parse_request: Body 1 [ 31]: o=MxSIP 0 0 IN IP4 10.50.10.183 [Apr 13 14:45:58] DEBUG[3291]: chan_sip.c:6121 parse_request: Body 2 [ 10]: s=SIP Call [Apr 13 14:45:58] DEBUG[3291]: chan_sip.c:6121 parse_request: Body 3 [ 21]: c=IN IP4 10.50.10.183 [Apr 13 14:45:58] DEBUG[3291]: chan_sip.c:6121 parse_request: Body 4 [ 5]: t=0 0 [Apr 13 14:45:58] DEBUG[3291]: chan_sip.c:6121 parse_request: Body 5 [ 31]: m=audio 3000 RTP/AVP 0 8 18 101 [Apr 13 14:45:58] DEBUG[3291]: chan_sip.c:6121 parse_request: Body 6 [ 20]: a=rtpmap:0 PCMU/8000 [Apr 13 14:45:58] DEBUG[3291]: chan_sip.c:6121 parse_request: Body 7 [ 20]: a=rtpmap:8 PCMA/8000 [Apr 13 14:45:58] DEBUG[3291]: chan_sip.c:6121 parse_request: Body 8 [ 21]: a=rtpmap:18 G729/8000 [Apr 13 14:45:58] DEBUG[3291]: chan_sip.c:6121 parse_request: Body 9 [ 33]: a=rtpmap:101 telephone-event/8000 [Apr 13 14:45:58] DEBUG[3291]: chan_sip.c:6121 parse_request: Body 10 [ 24]: a=silenceSupp:on - - - - [Apr 13 14:45:58] DEBUG[3291]: chan_sip.c:6121 parse_request: Body 11 [ 15]: a=fmtp:101 0-15 [Apr 13 14:45:58] DEBUG[3291]: chan_sip.c:6121 parse_request: Body 12 [ 10]: a=ptime:30 [Apr 13 14:45:58] DEBUG[3291]: chan_sip.c:6141 parse_request: Body 13 [ 10]: a=sendrecv [Apr 13 14:45:58] --- (15 headers 14 lines) --- [Apr 13 14:45:58] DEBUG[3291]: chan_sip.c:5849 find_call: = Looking for Call ID: a3a868736ab469d3 (Checking From) --From tag 4d6ff13510 --To-tag [Apr 13 14:45:58] DEBUG[3291]: chan_sip.c:5876 find_call: = Found Their Call ID: a3a868736ab469d3 Their Tag 4d6ff13510 Our tag: as6bc152de [Apr 13 14:45:58] DEBUG[3291]: chan_sip.c:17847 handle_incoming: **** Received INVITE (5) - Command in SIP INVITE [Apr 13 14:45:58] Sending to 10.50.10.183 : 5060 (no NAT) [Apr 13 14:45:58] DEBUG[3291]: chan_sip.c:16265 handle_request_invite: Initializing initreq for method INVITE - callid a3a868736ab469d3 [Apr 13 14:45:58] Using INVITE request as basis request - a3a868736ab469d3 [Apr 13 14:45:58] Found user 'station3' for 'station3' [Apr 13 14:45:58] DEBUG[3291]: chan_sip.c:3837 do_setnat: Setting NAT on RTP to Off [Apr 13 14:45:58] Found RTP audio format 0 [Apr 13 14:45:58] Found RTP audio format 8 [Apr 13 14:45:58] Found RTP audio format 18 [Apr 13 14:45:58] Found RTP audio format 101 [Apr 13 14:45:58] Peer audio RTP is at port 10.50.10.183:3000 [Apr 13 14:45:58] Found audio description format PCMU for ID 0 [Apr 13 14:45:58] Found audio description format PCMA for ID 8 [Apr 13 14:45:58] Found audio description format G729 for ID 18 [Apr 13 14:45:58] Found audio description format telephone-event for ID 101 [Apr 13 14:45:58] Got unsupported a:fmtp in SDP offer [Apr 13 14:45:58] Capabilities: us - 0xe (gsm|ulaw|alaw), peer - audio=0x10c (ulaw|alaw|g729)/video=0x0 (nothing)/text=0x0 (nothing), combined - 0xc (ulaw|alaw) [Apr 13 14:45:58] Non-codec capabilities (dtmf): us - 0x1 (telephone-event), peer - 0x1 (telephone-event), combined - 0x1 (telephone-event) [Apr 13 14:45:58] Peer audio RTP is at port 10.50.10.183:3000 [Apr 13 14:45:58] DEBUG[3291]: chan_sip.c:6894 process_sdp: We're settling with these formats: 0xc (ulaw|alaw) [Apr 13 14:45:58] DEBUG[3291]: chan_sip.c:16342 handle_request_invite: Checking SIP call limits for device station3 [Apr 13 14:45:58] DEBUG[3291]: chan_sip.c:4381 update_call_counter: Updating call counter for incoming call [Apr 13 14:45:58] Looking for station3_line1 in sla_stations (domain 10.50.10.171) [Apr 13 14:45:58] DEBUG[3291]: chan_sip.c:5241 sip_new: *** Our native formats are 0x4 (ulaw) [Apr 13 14:45:58] DEBUG[3291]: chan_sip.c:5242 sip_new: *** Joint capabilities are 0xc (ulaw|alaw) [Apr 13 14:45:58] DEBUG[3291]: chan_sip.c:5243 sip_new: *** Our capabilities are 0xe (gsm|ulaw|alaw) [Apr 13 14:45:58] DEBUG[3291]: chan_sip.c:5244 sip_new: *** AST_CODEC_CHOOSE formats are 0x4 (ulaw) [Apr 13 14:45:58] DEBUG[3291]: chan_sip.c:5272 sip_new: This channel will not be able to handle video. [Apr 13 14:45:58] DEBUG[3291]: chan_sip.c:9937 build_route: build_route: Contact hop: PowerPBX 23 [Apr 13 14:45:58] list_route: hop: [Apr 13 14:45:58] DEBUG[3291]: chan_sip.c:16552 handle_request_invite: SIP/station3-0a051308: New call is still down.... Trying... [Apr 13 14:45:58] <--- 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=z9hG4bKab56d32f697831f2c;received=10.50.10.183 From: "PowerPBX 23" ;tag=4d6ff13510 To: "station3_line1" Call-ID: a3a868736ab469d3 CSeq: 21100 INVITE User-Agent: Asterisk PBX 1.6.0-beta7.1 Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY Supported: replaces, timer Contact: Content-Length: 0 <------------> [Apr 13 14:45:58] DEBUG[3291]: chan_sip.c:2520 __sip_xmit: Trying to put 'SIP/2.0 10' onto UDP socket... [Apr 13 14:45:58] DEBUG[3291]: devicestate.c:441 __ast_devstate_changed_literal: Notification of state change to be queued on device/channel SIP/station3-0a051308 [Apr 13 14:45:58] DEBUG[3291]: devicestate.c:441 __ast_devstate_changed_literal: Notification of state change to be queued on device/channel SIP/station3 [Apr 13 14:45:58] DEBUG[3291]: pbx.c:2693 pbx_extension_helper: Launching 'SLAStation' [Apr 13 14:45:58] -- Executing [station3_line1@sla_stations:1] SLAStation("SIP/station3-0a051308", "station3_line1") in new stack [Apr 13 14:45:58] DEBUG[3291]: devicestate.c:441 __ast_devstate_changed_literal: Notification of state change to be queued on device/channel SLA:station1_line1 [Apr 13 14:45:58] DEBUG[3291]: devicestate.c:441 __ast_devstate_changed_literal: Notification of state change to be queued on device/channel SLA:station2_line1 [Apr 13 14:45:58] DEBUG[3291]: devicestate.c:441 __ast_devstate_changed_literal: Notification of state change to be queued on device/channel SLA:station3_line1 [Apr 13 14:45:58] DEBUG[3291]: devicestate.c:320 ast_device_state: No provider found, checking channel drivers for SIP - station3-0a051308 [Apr 13 14:45:58] DEBUG[3291]: chan_sip.c:18907 sip_devicestate: Checking device state for peer station3-0a051308 [Apr 13 14:45:58] DEBUG[3291]: devicestate.c:430 do_state_change: Changing state for SIP/station3-0a051308 - state 1 (Not in use) [Apr 13 14:45:58] DEBUG[3291]: devicestate.c:320 ast_device_state: No provider found, checking channel drivers for SIP - station3 [Apr 13 14:45:58] DEBUG[3291]: chan_sip.c:18907 sip_devicestate: Checking device state for peer station3 [Apr 13 14:45:58] DEBUG[3291]: devicestate.c:430 do_state_change: Changing state for SIP/station3 - state 1 (Not in use) [Apr 13 14:45:58] DEBUG[3291]: channel.c:3690 ast_channel_inherit_variables: Not copying variable SIPCALLID. [Apr 13 14:45:58] DEBUG[3291]: channel.c:3690 ast_channel_inherit_variables: Not copying variable SIPDOMAIN. [Apr 13 14:45:58] DEBUG[3291]: channel.c:3690 ast_channel_inherit_variables: Not copying variable SIPURI. [Apr 13 14:45:58] DEBUG[3291]: app_queue.c:761 handle_statechange: Device 'SIP/station3-0a051308' changed to state '1' (Not in use) but we don't care because they're not a member of any queue. [Apr 13 14:45:58] DEBUG[3291]: app_queue.c:761 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:45:58] DEBUG[3291]: pbx.c:2693 pbx_extension_helper: Launching 'DISA' [Apr 13 14:45:58] -- Executing [disa@line1_outbound:1] DISA("Local/disa@line1_outbound-9d53;2", "no-password,line1_outbound") in new stack [Apr 13 14:45:58] DEBUG[3291]: app_disa.c:142 disa_exec: Digittimeout: 5000 [Apr 13 14:45:58] DEBUG[3291]: app_disa.c:143 disa_exec: Responsetimeout: 10000 [Apr 13 14:45:58] DEBUG[3291]: app_disa.c:156 disa_exec: Mailbox: [Apr 13 14:45:58] -- Called disa@line1_outbound [Apr 13 14:45:59] DEBUG[3291]: devicestate.c:441 __ast_devstate_changed_literal: Notification of state change to be queued on device/channel Local/disa@line1_outbound-9d53;2 [Apr 13 14:45:59] DEBUG[3291]: devicestate.c:320 ast_device_state: No provider found, checking channel drivers for Local - disa@line1_outbound-9d53;2 [Apr 13 14:45:59] DEBUG[3291]: chan_local.c:141 local_devicestate: Checking if extension disa@line1_outbound-9d53;2 exists (devicestate) [Apr 13 14:45:59] DEBUG[3291]: devicestate.c:430 do_state_change: Changing state for Local/disa@line1_outbound-9d53;2 - state 4 (Invalid) [Apr 13 14:45:59] DEBUG[3291]: app_queue.c:761 handle_statechange: Device 'Local/disa@line1_outbound-9d53;2' changed to state '4' (Invalid) but we don't care because they're not a member of any queue. [Apr 13 14:45:59] DEBUG[3291]: devicestate.c:441 __ast_devstate_changed_literal: Notification of state change to be queued on device/channel Local/disa@line1_outbound [Apr 13 14:45:59] DEBUG[3291]: devicestate.c:320 ast_device_state: No provider found, checking channel drivers for Local - disa@line1_outbound [Apr 13 14:45:59] DEBUG[3291]: chan_local.c:141 local_devicestate: Checking if extension disa@line1_outbound exists (devicestate) [Apr 13 14:45:59] DEBUG[3291]: devicestate.c:430 do_state_change: Changing state for Local/disa@line1_outbound - state 2 (In use) [Apr 13 14:45:59] DEBUG[3291]: app_queue.c:761 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:45:59] DEBUG[3291]: devicestate.c:441 __ast_devstate_changed_literal: Notification of state change to be queued on device/channel Local/disa@line1_outbound-9d53;1 [Apr 13 14:45:59] DEBUG[3291]: devicestate.c:320 ast_device_state: No provider found, checking channel drivers for Local - disa@line1_outbound-9d53;1 [Apr 13 14:45:59] DEBUG[3291]: chan_local.c:141 local_devicestate: Checking if extension disa@line1_outbound-9d53;1 exists (devicestate) [Apr 13 14:45:59] DEBUG[3291]: devicestate.c:430 do_state_change: Changing state for Local/disa@line1_outbound-9d53;1 - state 4 (Invalid) [Apr 13 14:45:59] DEBUG[3291]: app_queue.c:761 handle_statechange: Device 'Local/disa@line1_outbound-9d53;1' changed to state '4' (Invalid) but we don't care because they're not a member of any queue. [Apr 13 14:45:59] DEBUG[3291]: devicestate.c:441 __ast_devstate_changed_literal: Notification of state change to be queued on device/channel Local/disa@line1_outbound [Apr 13 14:45:59] DEBUG[3291]: devicestate.c:320 ast_device_state: No provider found, checking channel drivers for Local - disa@line1_outbound [Apr 13 14:45:59] DEBUG[3291]: chan_local.c:141 local_devicestate: Checking if extension disa@line1_outbound exists (devicestate) [Apr 13 14:45:59] DEBUG[3291]: devicestate.c:430 do_state_change: Changing state for Local/disa@line1_outbound - state 2 (In use) [Apr 13 14:45:59] DEBUG[3291]: app_queue.c:761 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:45:59] -- Local/disa@line1_outbound-9d53;1 answered [Apr 13 14:45:59] DEBUG[3291]: chan_zap.c:8896 zt_request: Using channel -2 [Apr 13 14:45:59] DEBUG[3291]: devicestate.c:441 __ast_devstate_changed_literal: Notification of state change to be queued on device/channel Zap/pseudo-611129770 [Apr 13 14:45:59] DEBUG[3291]: devicestate.c:320 ast_device_state: No provider found, checking channel drivers for Zap - pseudo-611129770 [Apr 13 14:45:59] DEBUG[3291]: devicestate.c:430 do_state_change: Changing state for Zap/pseudo-611129770 - state 0 (Unknown) [Apr 13 14:45:59] DEBUG[3291]: app_queue.c:761 handle_statechange: Device 'Zap/pseudo-611129770' changed to state '0' (Unknown) but we don't care because they're not a member of any queue. [Apr 13 14:45:59] DEBUG[3291]: devicestate.c:441 __ast_devstate_changed_literal: Notification of state change to be queued on device/channel Zap/pseudo [Apr 13 14:45:59] DEBUG[3291]: devicestate.c:320 ast_device_state: No provider found, checking channel drivers for Zap - pseudo [Apr 13 14:45:59] DEBUG[3291]: devicestate.c:430 do_state_change: Changing state for Zap/pseudo - state 2 (In use) [Apr 13 14:45:59] DEBUG[3291]: app_queue.c:761 handle_statechange: Device 'Zap/pseudo' changed to state '2' (In use) but we don't care because they're not a member of any queue. [Apr 13 14:45:59] DEBUG[3291]: channel.c:3174 set_format: Set channel Zap/pseudo-611129770 to read format slin [Apr 13 14:45:59] DEBUG[3291]: channel.c:3174 set_format: Set channel Zap/pseudo-611129770 to write format slin [Apr 13 14:45:59] -- Created MeetMe conference 1023 for conference 'SLA_line1' [Apr 13 14:45:59] DEBUG[3291]: devicestate.c:441 __ast_devstate_changed_literal: Notification of state change to be queued on device/channel meetme:SLA_line1 [Apr 13 14:45:59] DEBUG[3291]: channel.c:3174 set_format: Set channel Local/disa@line1_outbound-9d53;1 to write format slin [Apr 13 14:45:59] DEBUG[3291]: channel.c:3174 set_format: Set channel Local/disa@line1_outbound-9d53;1 to read format slin [Apr 13 14:45:59] DEBUG[3291]: app_meetme.c:1894 conf_run: Placed channel Local/disa@line1_outbound-9d53;1 in ZAP conf 1023 [Apr 13 14:45:59] DEBUG[3291]: dsp.c:408 ast_tone_detect_init: Setup tone 1100 Hz, 500 ms, block_size=160, hits_required=21 [Apr 13 14:45:59] DEBUG[3291]: dsp.c:408 ast_tone_detect_init: Setup tone 2100 Hz, 2600 ms, block_size=160, hits_required=116 [Apr 13 14:45:59] DEBUG[3291]: devicestate.c:441 __ast_devstate_changed_literal: Notification of state change to be queued on device/channel SIP/station3-0a051308 [Apr 13 14:45:59] DEBUG[3291]: devicestate.c:441 __ast_devstate_changed_literal: Notification of state change to be queued on device/channel SIP/station3 [Apr 13 14:45:59] DEBUG[3291]: chan_sip.c:4851 sip_answer: SIP answering channel: SIP/station3-0a051308 [Apr 13 14:45:59] DEBUG[3291]: chan_sip.c:8294 transmit_response_with_sdp: Setting framing from config on incoming call [Apr 13 14:45:59] DEBUG[3291]: chan_sip.c:8018 add_sdp: ** Our capability: 0xc (ulaw|alaw) Video flag: True Text flag: True [Apr 13 14:45:59] DEBUG[3291]: chan_sip.c:8019 add_sdp: ** Our prefcodec: 0x0 (nothing) [Apr 13 14:45:59] Audio is at 10.50.10.171 port 10898 [Apr 13 14:45:59] Adding codec 0x4 (ulaw) to SDP [Apr 13 14:45:59] Adding codec 0x8 (alaw) to SDP [Apr 13 14:45:59] Adding non-codec 0x1 (telephone-event) to SDP [Apr 13 14:45:59] DEBUG[3291]: chan_sip.c:8172 add_sdp: -- Done with adding codecs to SDP [Apr 13 14:45:59] DEBUG[3291]: channel.c:2701 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Apr 13 14:45:59] DEBUG[3291]: chan_sip.c:8237 add_sdp: Done building SDP. Settling with this capability: 0xc (ulaw|alaw) [Apr 13 14:45:59] <--- 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=z9hG4bKab56d32f697831f2c;received=10.50.10.183 From: "PowerPBX 23" ;tag=4d6ff13510 To: "station3_line1" ;tag=as09d7ceab Call-ID: a3a868736ab469d3 CSeq: 21100 INVITE User-Agent: Asterisk PBX 1.6.0-beta7.1 Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY Supported: replaces, timer Contact: Content-Type: application/sdp Content-Length: 291 v=0 o=root 130290504 130290504 IN IP4 10.50.10.171 s=Asterisk PBX 1.6.0-beta7.1 c=IN IP4 10.50.10.171 t=0 0 m=audio 10898 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:45:59] DEBUG[3291]: chan_sip.c:2837 __sip_reliable_xmit: *** SIP TIMER: Initializing retransmit timer on packet: Id #37 [Apr 13 14:45:59] DEBUG[3291]: chan_sip.c:2520 __sip_xmit: Trying to put 'SIP/2.0 20' onto UDP socket... [Apr 13 14:45:59] DEBUG[3291]: devicestate.c:320 ast_device_state: No provider found, checking channel drivers for SIP - station3-0a051308 [Apr 13 14:45:59] DEBUG[3291]: chan_sip.c:18907 sip_devicestate: Checking device state for peer station3-0a051308 [Apr 13 14:45:59] DEBUG[3291]: devicestate.c:430 do_state_change: Changing state for SIP/station3-0a051308 - state 1 (Not in use) [Apr 13 14:45:59] DEBUG[3291]: devicestate.c:320 ast_device_state: No provider found, checking channel drivers for SIP - station3 [Apr 13 14:45:59] DEBUG[3291]: chan_sip.c:18907 sip_devicestate: Checking device state for peer station3 [Apr 13 14:45:59] DEBUG[3291]: devicestate.c:430 do_state_change: Changing state for SIP/station3 - state 1 (Not in use) [Apr 13 14:45:59] DEBUG[3291]: app_queue.c:761 handle_statechange: Device 'SIP/station3-0a051308' changed to state '1' (Not in use) but we don't care because they're not a member of any queue. [Apr 13 14:45:59] DEBUG[3291]: app_queue.c:761 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:45:59] <--- SIP read from UDP://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=z9hG4bK5f34dd98149636861 Max-Forwards: 70 From: "PowerPBX 23" ;tag=4d6ff13510 To: "station3_line1" ;tag=as09d7ceab Call-ID: a3a868736ab469d3 CSeq: 21100 ACK Authorization: Digest username="station3",realm="asterisk",nonce="5f2becac",uri="sip:station3_line1@10.50.10.171",response="623f13d1b77577078128c33dcafac78d",algorithm=MD5 User-Agent: Aastra 55i/2.2.0.166 Content-Length: 0 <-------------> [Apr 13 14:45:59] DEBUG[3291]: chan_sip.c:6121 parse_request: Header 0 [ 43]: ACK sip:station3_line1@10.50.10.171 SIP/2.0 [Apr 13 14:45:59] DEBUG[3291]: chan_sip.c:6121 parse_request: Header 1 [ 66]: Via: SIP/2.0/UDP 10.50.10.183:5060;branch=z9hG4bK5f34dd98149636861 [Apr 13 14:45:59] DEBUG[3291]: chan_sip.c:6121 parse_request: Header 2 [ 16]: Max-Forwards: 70 [Apr 13 14:45:59] DEBUG[3291]: chan_sip.c:6121 parse_request: Header 3 [ 67]: From: "PowerPBX 23" ;tag=4d6ff13510 [Apr 13 14:45:59] DEBUG[3291]: chan_sip.c:6121 parse_request: Header 4 [ 74]: To: "station3_line1" ;tag=as09d7ceab [Apr 13 14:45:59] DEBUG[3291]: chan_sip.c:6121 parse_request: Header 5 [ 25]: Call-ID: a3a868736ab469d3 [Apr 13 14:45:59] DEBUG[3291]: chan_sip.c:6121 parse_request: Header 6 [ 15]: CSeq: 21100 ACK [Apr 13 14:45:59] DEBUG[3291]: chan_sip.c:6121 parse_request: Header 7 [171]: Authorization: Digest username="station3",realm="asterisk",nonce="5f2becac",uri="sip:station3_line1@10.50.10.171",response="623f13d1b77577078128c33dcafac78d",algorithm=MD5 [Apr 13 14:45:59] DEBUG[3291]: chan_sip.c:6121 parse_request: Header 8 [ 32]: User-Agent: Aastra 55i/2.2.0.166 [Apr 13 14:45:59] DEBUG[3291]: chan_sip.c:6121 parse_request: Header 9 [ 17]: Content-Length: 0 [Apr 13 14:45:59] --- (10 headers 0 lines) --- [Apr 13 14:45:59] DEBUG[3291]: chan_sip.c:5849 find_call: = Looking for Call ID: a3a868736ab469d3 (Checking From) --From tag 4d6ff13510 --To-tag as09d7ceab [Apr 13 14:45:59] DEBUG[3291]: chan_sip.c:5876 find_call: = Found Their Call ID: a3a868736ab469d3 Their Tag 4d6ff13510 Our tag: as09d7ceab [Apr 13 14:45:59] DEBUG[3291]: chan_sip.c:17847 handle_incoming: **** Received ACK (6) - Command in SIP ACK [Apr 13 14:45:59] DEBUG[3291]: chan_sip.c:2966 __sip_ack: ** SIP TIMER: Cancelling retransmit of packet (reply received) Retransid #37 [Apr 13 14:45:59] DEBUG[3291]: chan_sip.c:2996 __sip_ack: Stopping retransmission on 'a3a868736ab469d3' of Response 21100: Match Found [Apr 13 14:45:59] DEBUG[3291]: channel.c:3174 set_format: Set channel SIP/station3-0a051308 to write format slin [Apr 13 14:45:59] DEBUG[3291]: channel.c:3174 set_format: Set channel SIP/station3-0a051308 to read format slin [Apr 13 14:45:59] DEBUG[3291]: app_meetme.c:1894 conf_run: Placed channel SIP/station3-0a051308 in ZAP conf 1023 [Apr 13 14:45:59] DEBUG[3291]: app_disa.c:166 disa_exec: Context: line1_outbound [Apr 13 14:45:59] DEBUG[3291]: app_disa.c:170 disa_exec: DISA no-password login success [Apr 13 14:45:59] DEBUG[3291]: channel.c:3174 set_format: Set channel Local/disa@line1_outbound-9d53;2 to write format slin [Apr 13 14:45:59] DEBUG[3291]: channel.c:2156 ast_settimeout: Scheduling timer at 160 sample intervals [Apr 13 14:45:59] DEBUG[3291]: dsp.c:408 ast_tone_detect_init: Setup tone 1100 Hz, 500 ms, block_size=160, hits_required=21 [Apr 13 14:45:59] DEBUG[3291]: dsp.c:408 ast_tone_detect_init: Setup tone 2100 Hz, 2600 ms, block_size=160, hits_required=116 [Apr 13 14:45:59] DEBUG[3291]: channel.c:2701 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=27) [Apr 13 14:45:59] DEBUG[3291]: channel.c:2263 ast_read_generator_actions: Generator got voice, switching to phase locked mode [Apr 13 14:45:59] DEBUG[3291]: channel.c:2156 ast_settimeout: Scheduling timer at 0 sample intervals [Apr 13 14:45:59] DEBUG[3291]: rtp.c:3167 ast_rtp_write: Ooh, format changed from unknown to ulaw [Apr 13 14:45:59] DEBUG[3291]: rtp.c:3183 ast_rtp_write: Created smoother: format: 4 ms: 20 len: 160 [Apr 13 14:45:59] DEBUG[3291]: channel.c:2701 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=27) [Apr 13 14:45:59] DEBUG[3291]: channel.c:2701 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=27) [Apr 13 14:45:59] DEBUG[3291]: channel.c:2701 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=27) [Apr 13 14:45:59] DEBUG[3291]: channel.c:2701 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=27) [Apr 13 14:45:59] DEBUG[3291]: channel.c:2701 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=27) [Apr 13 14:45:59] DEBUG[3291]: channel.c:2701 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=27) [Apr 13 14:45:59] DEBUG[3291]: channel.c:2701 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=27) [Apr 13 14:45:59] DEBUG[3291]: channel.c:2701 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=27) [Apr 13 14:45:59] DEBUG[3291]: channel.c:2701 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=27) [Apr 13 14:45:59] DEBUG[3291]: channel.c:2701 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=27) [Apr 13 14:45:59] DEBUG[3291]: channel.c:2701 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=27) [Apr 13 14:45:59] DEBUG[3291]: channel.c:2701 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=27) [Apr 13 14:45:59] DEBUG[3291]: channel.c:2701 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=27) [Apr 13 14:45:59] DEBUG[3291]: channel.c:2701 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=27) [Apr 13 14:45:59] DEBUG[3291]: channel.c:2701 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=27) [Apr 13 14:45:59] DEBUG[3291]: channel.c:2701 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=27) [Apr 13 14:45:59] DEBUG[3291]: channel.c:2701 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=27) [Apr 13 14:45:59] DEBUG[3291]: channel.c:2701 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=27) [Apr 13 14:45:59] DEBUG[3291]: channel.c:2701 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=27) [Apr 13 14:45:59] DEBUG[3291]: channel.c:2701 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=27) [Apr 13 14:45:59] DEBUG[3291]: channel.c:2701 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=27) [Apr 13 14:46:00] DEBUG[3291]: channel.c:2701 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=27) [Apr 13 14:46:00] DEBUG[3291]: channel.c:2701 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=27) [Apr 13 14:46:00] DEBUG[3291]: channel.c:2701 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=27) [Apr 13 14:46:00] DEBUG[3291]: channel.c:2701 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=27) [Apr 13 14:46:00] DEBUG[3291]: channel.c:2701 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=27) [Apr 13 14:46:00] DEBUG[3291]: channel.c:2701 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=27) [Apr 13 14:46:00] DEBUG[3291]: channel.c:2701 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=27) [Apr 13 14:46:00] DEBUG[3291]: channel.c:2701 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=27) [Apr 13 14:46:00] DEBUG[3291]: channel.c:2701 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=27) [Apr 13 14:46:00] DEBUG[3291]: channel.c:2701 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=27) [Apr 13 14:46:00] DEBUG[3291]: channel.c:2701 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=27) [Apr 13 14:46:00] DEBUG[3291]: channel.c:2701 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=27) [Apr 13 14:46:00] DEBUG[3291]: channel.c:2701 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=27) [Apr 13 14:46:00] DEBUG[3291]: channel.c:2701 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=27) [Apr 13 14:46:00] DEBUG[3291]: channel.c:2701 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=27) [Apr 13 14:46:00] DEBUG[3291]: channel.c:2701 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=27) [Apr 13 14:46:00] DEBUG[3291]: channel.c:2701 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=27) [Apr 13 14:46:00] DEBUG[3291]: channel.c:2701 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=27) [Apr 13 14:46:00] DEBUG[3291]: channel.c:2701 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=27) [Apr 13 14:46:00] DEBUG[3291]: channel.c:2701 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=27) [Apr 13 14:46:00] DEBUG[3291]: channel.c:2701 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=27) [Apr 13 14:46:00] DEBUG[3291]: channel.c:2701 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=27) [Apr 13 14:46:00] DEBUG[3291]: channel.c:2701 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=27) [Apr 13 14:46:00] DEBUG[3291]: channel.c:2701 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=27) [Apr 13 14:46:00] DEBUG[3291]: channel.c:2701 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=27) [Apr 13 14:46:00] DEBUG[3291]: channel.c:2701 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=27) [Apr 13 14:46:00] DEBUG[3291]: channel.c:2701 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=27) [Apr 13 14:46:00] DEBUG[3291]: channel.c:2701 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=27) [Apr 13 14:46:00] DEBUG[3291]: channel.c:2701 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=27) [Apr 13 14:46:00] DEBUG[3291]: channel.c:2701 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=27) [Apr 13 14:46:00] DEBUG[3291]: channel.c:2701 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=27) [Apr 13 14:46:00] DEBUG[3291]: channel.c:2701 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=27) [Apr 13 14:46:00] DEBUG[3291]: channel.c:2701 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=27) [Apr 13 14:46:00] DEBUG[3291]: channel.c:2701 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=27) [Apr 13 14:46:00] DEBUG[3291]: channel.c:2701 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=27) [Apr 13 14:46:00] DEBUG[3291]: channel.c:2701 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=27) [Apr 13 14:46:00] DEBUG[3291]: channel.c:2701 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=27) [Apr 13 14:46:00] DEBUG[3291]: channel.c:2701 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=27) [Apr 13 14:46:00] DEBUG[3291]: channel.c:2701 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=27) [Apr 13 14:46:00] DEBUG[3291]: channel.c:2701 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=27) [Apr 13 14:46:00] DEBUG[3291]: channel.c:2701 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=27) [Apr 13 14:46:00] DEBUG[3291]: channel.c:2701 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=27) [Apr 13 14:46:00] DEBUG[3291]: channel.c:2701 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=27) [Apr 13 14:46:00] DEBUG[3291]: channel.c:2701 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=27) [Apr 13 14:46:00] DEBUG[3291]: channel.c:2701 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=27) [Apr 13 14:46:00] DEBUG[3291]: channel.c:2701 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=27) [Apr 13 14:46:00] DEBUG[3291]: channel.c:2701 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=27) [Apr 13 14:46:00] DEBUG[3291]: channel.c:2701 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=27) [Apr 13 14:46:00] DEBUG[3291]: channel.c:2701 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=27) [Apr 13 14:46:00] DEBUG[3291]: channel.c:2701 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=27) [Apr 13 14:46:01] DEBUG[3291]: channel.c:2701 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=27) [Apr 13 14:46:01] DEBUG[3291]: channel.c:2701 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=27) [Apr 13 14:46:01] DEBUG[3291]: channel.c:2701 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=27) [Apr 13 14:46:01] DEBUG[3291]: channel.c:2701 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=27) [Apr 13 14:46:01] DEBUG[3291]: channel.c:2701 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=27) [Apr 13 14:46:01] DEBUG[3291]: channel.c:2701 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=27) [Apr 13 14:46:01] DEBUG[3291]: channel.c:2701 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=27) [Apr 13 14:46:01] DEBUG[3291]: channel.c:2701 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=27) [Apr 13 14:46:01] DEBUG[3291]: channel.c:2701 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=27) [Apr 13 14:46:01] DEBUG[3291]: channel.c:2701 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=27) [Apr 13 14:46:01] DEBUG[3291]: channel.c:2701 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=27) [Apr 13 14:46:01] DEBUG[3291]: channel.c:2701 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=27) [Apr 13 14:46:01] DEBUG[3291]: channel.c:2701 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=27) [Apr 13 14:46:01] DEBUG[3291]: channel.c:2701 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=27) [Apr 13 14:46:01] DEBUG[3291]: channel.c:2701 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=27) [Apr 13 14:46:01] DEBUG[3291]: channel.c:2701 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=27) [Apr 13 14:46:01] DEBUG[3291]: channel.c:2701 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=27) [Apr 13 14:46:01] DEBUG[3291]: channel.c:2701 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=27) [Apr 13 14:46:01] DEBUG[3291]: channel.c:2701 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=27) [Apr 13 14:46:01] DEBUG[3291]: channel.c:2701 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=27) [Apr 13 14:46:01] DEBUG[3291]: channel.c:2701 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=27) [Apr 13 14:46:01] DEBUG[3291]: channel.c:2701 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=27) [Apr 13 14:46:01] DEBUG[3291]: channel.c:2701 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=27) [Apr 13 14:46:01] DEBUG[3291]: channel.c:2701 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=27) [Apr 13 14:46:01] DEBUG[3291]: channel.c:2701 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=27) [Apr 13 14:46:01] DEBUG[3291]: channel.c:2701 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=27) [Apr 13 14:46:01] DEBUG[3291]: channel.c:2701 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=27) [Apr 13 14:46:01] DEBUG[3291]: channel.c:2701 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=27) [Apr 13 14:46:01] DEBUG[3291]: channel.c:2701 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=27) [Apr 13 14:46:01] DEBUG[3291]: channel.c:2701 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=27) [Apr 13 14:46:01] DEBUG[3291]: channel.c:2701 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=27) [Apr 13 14:46:01] DEBUG[3291]: channel.c:2701 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=27) [Apr 13 14:46:01] DEBUG[3291]: channel.c:2701 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=27) [Apr 13 14:46:01] DEBUG[3291]: channel.c:2701 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=27) [Apr 13 14:46:01] DEBUG[3291]: channel.c:2701 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=27) [Apr 13 14:46:01] DEBUG[3291]: channel.c:2701 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=27) [Apr 13 14:46:01] DEBUG[3291]: channel.c:2701 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=27) [Apr 13 14:46:01] DEBUG[3291]: channel.c:2701 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=27) [Apr 13 14:46:01] DEBUG[3291]: channel.c:2701 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=27) [Apr 13 14:46:01] DEBUG[3291]: channel.c:2701 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=27) [Apr 13 14:46:01] DEBUG[3291]: channel.c:2701 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=27) [Apr 13 14:46:01] DEBUG[3291]: channel.c:2701 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=27) [Apr 13 14:46:01] DEBUG[3291]: channel.c:2701 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=27) [Apr 13 14:46:01] DEBUG[3291]: channel.c:2701 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=27) [Apr 13 14:46:01] DEBUG[3291]: channel.c:2701 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=27) [Apr 13 14:46:01] DEBUG[3291]: channel.c:2701 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=27) [Apr 13 14:46:01] DEBUG[3291]: channel.c:2701 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=27) [Apr 13 14:46:01] DEBUG[3291]: channel.c:2701 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=27) [Apr 13 14:46:01] DEBUG[3291]: channel.c:2701 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=27) [Apr 13 14:46:01] DEBUG[3291]: channel.c:2701 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=27) [Apr 13 14:46:02] DEBUG[3291]: channel.c:2701 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=27) [Apr 13 14:46:02] DEBUG[3291]: channel.c:2701 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=27) [Apr 13 14:46:02] DEBUG[3291]: channel.c:2701 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=27) [Apr 13 14:46:02] DEBUG[3291]: channel.c:2701 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=27) [Apr 13 14:46:02] DEBUG[3291]: channel.c:2701 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=27) [Apr 13 14:46:02] DEBUG[3291]: channel.c:2701 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=27) [Apr 13 14:46:02] DEBUG[3291]: channel.c:2701 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=27) [Apr 13 14:46:02] DEBUG[3291]: channel.c:2701 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=27) [Apr 13 14:46:02] DEBUG[3291]: channel.c:2701 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=27) [Apr 13 14:46:02] DEBUG[3291]: channel.c:2701 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=27) [Apr 13 14:46:02] DEBUG[3291]: channel.c:2701 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=27) [Apr 13 14:46:02] DEBUG[3291]: channel.c:2701 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=27) [Apr 13 14:46:02] DEBUG[3291]: channel.c:2701 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=27) [Apr 13 14:46:02] DEBUG[3291]: channel.c:2701 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=27) [Apr 13 14:46:02] DEBUG[3291]: channel.c:2701 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=27) [Apr 13 14:46:02] DEBUG[3291]: channel.c:2701 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=27) [Apr 13 14:46:02] DEBUG[3291]: channel.c:2701 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=27) [Apr 13 14:46:02] DEBUG[3291]: channel.c:2701 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=27) [Apr 13 14:46:02] DEBUG[3291]: channel.c:2701 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=27) [Apr 13 14:46:02] DEBUG[3291]: channel.c:2701 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=27) [Apr 13 14:46:02] DEBUG[3291]: channel.c:2701 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=27) [Apr 13 14:46:02] DEBUG[3291]: channel.c:2701 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=27) [Apr 13 14:46:02] DEBUG[3291]: channel.c:2701 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=27) [Apr 13 14:46:02] DEBUG[3291]: channel.c:2701 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=27) [Apr 13 14:46:02] DEBUG[3291]: channel.c:2701 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=27) [Apr 13 14:46:02] DEBUG[3291]: channel.c:2701 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=27) [Apr 13 14:46:02] DEBUG[3291]: channel.c:2701 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=27) [Apr 13 14:46:02] DEBUG[3291]: channel.c:2701 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=27) [Apr 13 14:46:02] DEBUG[3291]: channel.c:2701 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=27) [Apr 13 14:46:02] DEBUG[3291]: channel.c:2701 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=27) [Apr 13 14:46:02] DEBUG[3291]: channel.c:2701 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=27) [Apr 13 14:46:02] DEBUG[3291]: channel.c:2701 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=27) [Apr 13 14:46:02] DEBUG[3291]: channel.c:2701 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=27) [Apr 13 14:46:02] DEBUG[3291]: channel.c:2701 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=27) [Apr 13 14:46:02] DEBUG[3291]: channel.c:2701 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=27) [Apr 13 14:46:02] DEBUG[3291]: channel.c:2701 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=27) [Apr 13 14:46:02] DEBUG[3291]: channel.c:2701 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=27) [Apr 13 14:46:02] DEBUG[3291]: channel.c:2701 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=27) [Apr 13 14:46:02] DEBUG[3291]: channel.c:2701 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=27) [Apr 13 14:46:02] DEBUG[3291]: channel.c:2701 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=27) [Apr 13 14:46:02] DEBUG[3291]: channel.c:2701 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=27) [Apr 13 14:46:02] DEBUG[3291]: channel.c:2701 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=27) [Apr 13 14:46:02] DEBUG[3291]: channel.c:2701 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=27) [Apr 13 14:46:02] DEBUG[3291]: channel.c:2701 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=27) [Apr 13 14:46:02] DEBUG[3291]: channel.c:2701 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=27) [Apr 13 14:46:02] DEBUG[3291]: channel.c:2701 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=27) [Apr 13 14:46:02] DEBUG[3291]: channel.c:2701 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=27) [Apr 13 14:46:02] DEBUG[3291]: channel.c:2701 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=27) [Apr 13 14:46:02] DEBUG[3291]: channel.c:2701 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=27) [Apr 13 14:46:02] DEBUG[3291]: channel.c:2701 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=27) [Apr 13 14:46:03] DEBUG[3291]: channel.c:2701 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=27) [Apr 13 14:46:03] DEBUG[3291]: channel.c:2701 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=27) [Apr 13 14:46:03] DEBUG[3291]: channel.c:2701 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=27) [Apr 13 14:46:03] DEBUG[3291]: channel.c:2701 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=27) [Apr 13 14:46:03] DEBUG[3291]: channel.c:2701 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=27) [Apr 13 14:46:03] DEBUG[3291]: channel.c:2701 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=27) [Apr 13 14:46:03] DEBUG[3291]: channel.c:2701 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=27) [Apr 13 14:46:03] DEBUG[3291]: channel.c:2701 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=27) [Apr 13 14:46:03] DEBUG[3291]: channel.c:2701 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=27) [Apr 13 14:46:03] DEBUG[3291]: channel.c:2701 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=27) [Apr 13 14:46:03] DEBUG[3291]: channel.c:2701 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=27) [Apr 13 14:46:03] DEBUG[3291]: channel.c:2701 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=27) [Apr 13 14:46:03] DEBUG[3291]: channel.c:2701 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=27) [Apr 13 14:46:03] DEBUG[3291]: channel.c:2701 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=27) [Apr 13 14:46:03] DEBUG[3291]: channel.c:2701 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=27) [Apr 13 14:46:03] DEBUG[3291]: channel.c:2701 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=27) [Apr 13 14:46:03] DEBUG[3291]: channel.c:2701 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=27) [Apr 13 14:46:03] DEBUG[3291]: channel.c:2701 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=27) [Apr 13 14:46:03] DEBUG[3291]: channel.c:2701 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=27) [Apr 13 14:46:03] DEBUG[3291]: channel.c:2701 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=27) [Apr 13 14:46:03] DEBUG[3291]: channel.c:2701 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=27) [Apr 13 14:46:03] DEBUG[3291]: channel.c:2701 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=27) [Apr 13 14:46:03] DEBUG[3291]: channel.c:2701 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=27) [Apr 13 14:46:03] DEBUG[3291]: channel.c:2701 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=27) [Apr 13 14:46:03] DEBUG[3291]: channel.c:2701 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=27) [Apr 13 14:46:03] DEBUG[3291]: channel.c:2701 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=27) [Apr 13 14:46:03] DEBUG[3291]: channel.c:2701 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=27) [Apr 13 14:46:03] DEBUG[3291]: channel.c:2701 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=27) [Apr 13 14:46:03] DEBUG[3291]: channel.c:2701 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=27) [Apr 13 14:46:03] DEBUG[3291]: channel.c:2701 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=27) [Apr 13 14:46:03] DEBUG[3291]: channel.c:2701 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=27) [Apr 13 14:46:03] DEBUG[3291]: channel.c:2701 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=27) [Apr 13 14:46:03] DEBUG[3291]: channel.c:2701 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=27) [Apr 13 14:46:03] DEBUG[3291]: channel.c:2701 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=27) [Apr 13 14:46:03] DEBUG[3291]: channel.c:2701 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=27) [Apr 13 14:46:03] DEBUG[3291]: channel.c:2701 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=27) [Apr 13 14:46:03] DEBUG[3291]: channel.c:2701 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=27) [Apr 13 14:46:03] DEBUG[3291]: channel.c:2701 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=27) [Apr 13 14:46:03] DEBUG[3291]: channel.c:2701 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=27) [Apr 13 14:46:03] DEBUG[3291]: channel.c:2701 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=27) [Apr 13 14:46:03] DEBUG[3291]: channel.c:2701 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=27) [Apr 13 14:46:03] DEBUG[3291]: channel.c:2701 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=27) [Apr 13 14:46:03] DEBUG[3291]: channel.c:2701 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=27) [Apr 13 14:46:03] DEBUG[3291]: channel.c:2701 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=27) [Apr 13 14:46:03] DEBUG[3291]: channel.c:2701 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=27) [Apr 13 14:46:03] DEBUG[3291]: channel.c:2701 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=27) [Apr 13 14:46:03] DEBUG[3291]: channel.c:2701 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=27) [Apr 13 14:46:03] DEBUG[3291]: channel.c:2701 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=27) [Apr 13 14:46:03] DEBUG[3291]: channel.c:2701 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=27) [Apr 13 14:46:04] DEBUG[3291]: channel.c:2701 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=27) [Apr 13 14:46:04] DEBUG[3291]: channel.c:2701 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=27) [Apr 13 14:46:04] DEBUG[3291]: channel.c:2701 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=27) [Apr 13 14:46:04] DEBUG[3291]: channel.c:2701 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=27) [Apr 13 14:46:04] DEBUG[3291]: channel.c:2701 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=27) [Apr 13 14:46:04] DEBUG[3291]: channel.c:2701 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=27) [Apr 13 14:46:04] DEBUG[3291]: rtp.c:1101 ast_rtcp_read: Got RTCP report of 64 bytes [Apr 13 14:46:04] DEBUG[3291]: channel.c:2701 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=27) [Apr 13 14:46:04] DEBUG[3291]: channel.c:2701 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=27) [Apr 13 14:46:04] DEBUG[3291]: channel.c:2701 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=27) [Apr 13 14:46:04] DEBUG[3291]: channel.c:2701 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=27) [Apr 13 14:46:04] DEBUG[3291]: channel.c:2701 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=27) [Apr 13 14:46:04] DEBUG[3291]: channel.c:2701 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=27) [Apr 13 14:46:04] DEBUG[3291]: channel.c:2701 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=27) [Apr 13 14:46:04] DEBUG[3291]: channel.c:2701 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=27) [Apr 13 14:46:04] DEBUG[3291]: channel.c:2701 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=27) [Apr 13 14:46:04] DEBUG[3291]: channel.c:2701 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=27) [Apr 13 14:46:04] DEBUG[3291]: channel.c:2701 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=27) [Apr 13 14:46:04] DEBUG[3291]: channel.c:2701 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=27) [Apr 13 14:46:04] DEBUG[3291]: channel.c:2701 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=27) [Apr 13 14:46:04] DEBUG[3291]: channel.c:2701 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=27) [Apr 13 14:46:04] DEBUG[3291]: channel.c:2701 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=27) [Apr 13 14:46:04] DEBUG[3291]: channel.c:2701 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=27) [Apr 13 14:46:04] DEBUG[3291]: channel.c:2701 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=27) [Apr 13 14:46:04] DEBUG[3291]: channel.c:2701 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=27) [Apr 13 14:46:04] DEBUG[3291]: channel.c:2701 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=27) [Apr 13 14:46:04] DEBUG[3291]: channel.c:2701 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=27) [Apr 13 14:46:04] DEBUG[3291]: channel.c:2701 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=27) [Apr 13 14:46:04] DEBUG[3291]: channel.c:2701 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=27) [Apr 13 14:46:04] DEBUG[3291]: channel.c:2701 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=27) [Apr 13 14:46:04] DEBUG[3291]: channel.c:2701 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=27) [Apr 13 14:46:04] DEBUG[3291]: channel.c:2701 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=27) [Apr 13 14:46:04] DEBUG[3291]: channel.c:2701 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=27) [Apr 13 14:46:04] DEBUG[3291]: channel.c:2701 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=27) [Apr 13 14:46:04] DEBUG[3291]: channel.c:2701 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=27) [Apr 13 14:46:04] DEBUG[3291]: channel.c:2701 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=27) [Apr 13 14:46:04] DEBUG[3291]: channel.c:2701 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=27) [Apr 13 14:46:04] DEBUG[3291]: channel.c:2701 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=27) [Apr 13 14:46:04] DEBUG[3291]: channel.c:2701 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=27) [Apr 13 14:46:04] DEBUG[3291]: channel.c:2701 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=27) [Apr 13 14:46:04] DEBUG[3291]: channel.c:2701 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=27) [Apr 13 14:46:04] DEBUG[3291]: channel.c:2701 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=27) [Apr 13 14:46:04] DEBUG[3291]: channel.c:2701 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=27) [Apr 13 14:46:04] DEBUG[3291]: channel.c:2701 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=27) [Apr 13 14:46:04] DEBUG[3291]: channel.c:2701 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=27) [Apr 13 14:46:04] DEBUG[3291]: channel.c:2701 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=27) [Apr 13 14:46:04] DEBUG[3291]: channel.c:2701 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=27) [Apr 13 14:46:04] DEBUG[3291]: channel.c:2701 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=27) [Apr 13 14:46:04] DEBUG[3291]: channel.c:2701 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=27) [Apr 13 14:46:04] DEBUG[3291]: channel.c:2701 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=27) [Apr 13 14:46:04] DEBUG[3291]: channel.c:2701 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=27) [Apr 13 14:46:04] DEBUG[3291]: channel.c:2701 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=27) [Apr 13 14:46:05] DEBUG[3291]: channel.c:2701 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=27) [Apr 13 14:46:05] DEBUG[3291]: channel.c:2701 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=27) [Apr 13 14:46:05] DEBUG[3291]: channel.c:2701 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=27) [Apr 13 14:46:05] DEBUG[3291]: channel.c:2701 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=27) [Apr 13 14:46:05] DEBUG[3291]: channel.c:2701 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=27) [Apr 13 14:46:05] DEBUG[3291]: channel.c:2701 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=27) [Apr 13 14:46:05] DEBUG[3291]: channel.c:2701 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=27) [Apr 13 14:46:05] DEBUG[3291]: channel.c:2701 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=27) [Apr 13 14:46:05] DEBUG[3291]: channel.c:2701 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=27) [Apr 13 14:46:05] DEBUG[3291]: channel.c:2701 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=27) [Apr 13 14:46:05] DEBUG[3291]: channel.c:2701 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=27) [Apr 13 14:46:05] DEBUG[3291]: channel.c:2701 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=27) [Apr 13 14:46:05] DEBUG[3291]: channel.c:2701 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=27) [Apr 13 14:46:05] DEBUG[3291]: channel.c:2701 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=27) [Apr 13 14:46:05] DEBUG[3291]: channel.c:2701 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=27) [Apr 13 14:46:05] DEBUG[3291]: channel.c:2701 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=27) [Apr 13 14:46:05] DEBUG[3291]: channel.c:2701 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=27) [Apr 13 14:46:05] DEBUG[3291]: channel.c:2701 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=27) [Apr 13 14:46:05] DEBUG[3291]: channel.c:2701 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=27) [Apr 13 14:46:05] DEBUG[3291]: channel.c:2701 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=27) [Apr 13 14:46:05] DEBUG[3291]: channel.c:2701 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=27) [Apr 13 14:46:05] DEBUG[3291]: channel.c:2701 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=27) [Apr 13 14:46:05] DEBUG[3291]: channel.c:2701 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=27) [Apr 13 14:46:05] DEBUG[3291]: channel.c:2701 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=27) [Apr 13 14:46:05] DEBUG[3291]: channel.c:2701 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=27) [Apr 13 14:46:05] DEBUG[3291]: channel.c:2701 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=27) [Apr 13 14:46:05] DEBUG[3291]: channel.c:2701 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=27) [Apr 13 14:46:05] DEBUG[3291]: channel.c:2701 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=27) [Apr 13 14:46:05] DEBUG[3291]: channel.c:2701 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=27) [Apr 13 14:46:05] DEBUG[3291]: channel.c:2701 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=27) [Apr 13 14:46:05] DEBUG[3291]: channel.c:2701 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=27) [Apr 13 14:46:05] DEBUG[3291]: channel.c:2701 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=27) [Apr 13 14:46:05] DEBUG[3291]: channel.c:2701 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=27) [Apr 13 14:46:05] DEBUG[3291]: rtp.c:950 process_rfc2833: - RTP 2833 Event: 00000007 (len = 4) [Apr 13 14:46:05] DEBUG[3291]: rtp.c:798 send_dtmf: Sending dtmf: 55 (7), at 10.50.10.183 [Apr 13 14:46:05] DEBUG[3291]: channel.c:2982 ast_write: Thread -1216930928 Blocking 'Local/disa@line1_outbound-9d53;1', already blocked by thread -1217422448 in procedure ast_waitfor_nandfds [Apr 13 14:46:05] DEBUG[3291]: channel.c:2701 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=27) [Apr 13 14:46:05] DEBUG[3291]: rtp.c:950 process_rfc2833: - RTP 2833 Event: 00000007 (len = 4) [Apr 13 14:46:05] DEBUG[3291]: channel.c:2701 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=27) [Apr 13 14:46:05] DEBUG[3291]: rtp.c:950 process_rfc2833: - RTP 2833 Event: 00000007 (len = 4) [Apr 13 14:46:05] DEBUG[3291]: channel.c:2701 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=27) [Apr 13 14:46:05] DEBUG[3291]: rtp.c:950 process_rfc2833: - RTP 2833 Event: 00000007 (len = 4) [Apr 13 14:46:05] DEBUG[3291]: rtp.c:798 send_dtmf: Sending dtmf: 55 (7), at 10.50.10.183 [Apr 13 14:46:05] DEBUG[3291]: channel.c:2701 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=27) [Apr 13 14:46:05] DEBUG[3291]: rtp.c:950 process_rfc2833: - RTP 2833 Event: 00000007 (len = 4) [Apr 13 14:46:05] DEBUG[3291]: channel.c:2982 ast_write: Thread -1216930928 Blocking 'Local/disa@line1_outbound-9d53;1', already blocked by thread -1217422448 in procedure ast_waitfor_nandfds [Apr 13 14:46:05] DEBUG[3291]: channel.c:3174 set_format: Set channel Local/disa@line1_outbound-9d53;2 to write format ulaw [Apr 13 14:46:05] DEBUG[3291]: channel.c:2156 ast_settimeout: Scheduling timer at 0 sample intervals [Apr 13 14:46:05] DEBUG[3291]: rtp.c:950 process_rfc2833: - RTP 2833 Event: 00000007 (len = 4) [Apr 13 14:46:06] DEBUG[3291]: rtp.c:950 process_rfc2833: - RTP 2833 Event: 00000005 (len = 4) [Apr 13 14:46:06] DEBUG[3291]: rtp.c:798 send_dtmf: Sending dtmf: 53 (5), at 10.50.10.183 [Apr 13 14:46:06] DEBUG[3291]: channel.c:2982 ast_write: Thread -1216930928 Blocking 'Local/disa@line1_outbound-9d53;1', already blocked by thread -1217422448 in procedure ast_waitfor_nandfds [Apr 13 14:46:06] DEBUG[3291]: rtp.c:950 process_rfc2833: - RTP 2833 Event: 00000005 (len = 4) [Apr 13 14:46:06] DEBUG[3291]: rtp.c:950 process_rfc2833: - RTP 2833 Event: 00000005 (len = 4) [Apr 13 14:46:06] DEBUG[3291]: rtp.c:950 process_rfc2833: - RTP 2833 Event: 00000005 (len = 4) [Apr 13 14:46:06] DEBUG[3291]: rtp.c:950 process_rfc2833: - RTP 2833 Event: 00000005 (len = 4) [Apr 13 14:46:06] DEBUG[3291]: rtp.c:798 send_dtmf: Sending dtmf: 53 (5), at 10.50.10.183 [Apr 13 14:46:06] DEBUG[3291]: channel.c:2982 ast_write: Thread -1216930928 Blocking 'Local/disa@line1_outbound-9d53;1', already blocked by thread -1217422448 in procedure ast_waitfor_nandfds [Apr 13 14:46:06] DEBUG[3291]: rtp.c:950 process_rfc2833: - RTP 2833 Event: 00000005 (len = 4) [Apr 13 14:46:06] DEBUG[3291]: rtp.c:950 process_rfc2833: - RTP 2833 Event: 00000005 (len = 4) [Apr 13 14:46:06] DEBUG[3291]: rtp.c:950 process_rfc2833: - RTP 2833 Event: 00000006 (len = 4) [Apr 13 14:46:06] DEBUG[3291]: rtp.c:798 send_dtmf: Sending dtmf: 54 (6), at 10.50.10.183 [Apr 13 14:46:06] DEBUG[3291]: channel.c:2982 ast_write: Thread -1216930928 Blocking 'Local/disa@line1_outbound-9d53;1', already blocked by thread -1217422448 in procedure ast_waitfor_nandfds [Apr 13 14:46:06] DEBUG[3291]: rtp.c:950 process_rfc2833: - RTP 2833 Event: 00000006 (len = 4) [Apr 13 14:46:06] DEBUG[3291]: rtp.c:950 process_rfc2833: - RTP 2833 Event: 00000006 (len = 4) [Apr 13 14:46:06] DEBUG[3291]: rtp.c:950 process_rfc2833: - RTP 2833 Event: 00000006 (len = 4) [Apr 13 14:46:06] DEBUG[3291]: rtp.c:950 process_rfc2833: - RTP 2833 Event: 00000006 (len = 4) [Apr 13 14:46:06] DEBUG[3291]: rtp.c:950 process_rfc2833: - RTP 2833 Event: 00000006 (len = 4) [Apr 13 14:46:06] DEBUG[3291]: rtp.c:798 send_dtmf: Sending dtmf: 54 (6), at 10.50.10.183 [Apr 13 14:46:06] DEBUG[3291]: channel.c:2982 ast_write: Thread -1216930928 Blocking 'Local/disa@line1_outbound-9d53;1', already blocked by thread -1217422448 in procedure ast_waitfor_nandfds [Apr 13 14:46:06] DEBUG[3291]: rtp.c:950 process_rfc2833: - RTP 2833 Event: 00000006 (len = 4) [Apr 13 14:46:06] DEBUG[3291]: rtp.c:950 process_rfc2833: - RTP 2833 Event: 00000006 (len = 4) [Apr 13 14:46:08] <--- SIP read from UDP://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=z9hG4bK9347381f26bb95e94 Max-Forwards: 70 From: "PowerPBX 23" ;tag=4d6ff13510 To: "station3_line1" ;tag=as09d7ceab Call-ID: a3a868736ab469d3 CSeq: 21101 BYE Allow: INVITE, ACK, CANCEL, BYE, NOTIFY, REFER, OPTIONS, UPDATE, PRACK, SUBSCRIBE, INFO Allow-Events: talk, hold, conference Authorization: Digest username="station3",realm="asterisk",nonce="5f2becac",uri="sip:station3_line1@10.50.10.171",response="c4fae666edabda00eaf4b81574d12620",algorithm=MD5 Supported: timer User-Agent: Aastra 55i/2.2.0.166 Content-Length: 0 <-------------> [Apr 13 14:46:08] DEBUG[3291]: chan_sip.c:6121 parse_request: Header 0 [ 43]: BYE sip:station3_line1@10.50.10.171 SIP/2.0 [Apr 13 14:46:08] DEBUG[3291]: chan_sip.c:6121 parse_request: Header 1 [ 66]: Via: SIP/2.0/UDP 10.50.10.183:5060;branch=z9hG4bK9347381f26bb95e94 [Apr 13 14:46:08] DEBUG[3291]: chan_sip.c:6121 parse_request: Header 2 [ 16]: Max-Forwards: 70 [Apr 13 14:46:08] DEBUG[3291]: chan_sip.c:6121 parse_request: Header 3 [ 67]: From: "PowerPBX 23" ;tag=4d6ff13510 [Apr 13 14:46:08] DEBUG[3291]: chan_sip.c:6121 parse_request: Header 4 [ 74]: To: "station3_line1" ;tag=as09d7ceab [Apr 13 14:46:08] DEBUG[3291]: chan_sip.c:6121 parse_request: Header 5 [ 25]: Call-ID: a3a868736ab469d3 [Apr 13 14:46:08] DEBUG[3291]: chan_sip.c:6121 parse_request: Header 6 [ 15]: CSeq: 21101 BYE [Apr 13 14:46:08] DEBUG[3291]: chan_sip.c:6121 parse_request: Header 7 [ 87]: Allow: INVITE, ACK, CANCEL, BYE, NOTIFY, REFER, OPTIONS, UPDATE, PRACK, SUBSCRIBE, INFO [Apr 13 14:46:08] DEBUG[3291]: chan_sip.c:6121 parse_request: Header 8 [ 36]: Allow-Events: talk, hold, conference [Apr 13 14:46:08] DEBUG[3291]: chan_sip.c:6121 parse_request: Header 9 [171]: Authorization: Digest username="station3",realm="asterisk",nonce="5f2becac",uri="sip:station3_line1@10.50.10.171",response="c4fae666edabda00eaf4b81574d12620",algorithm=MD5 [Apr 13 14:46:08] DEBUG[3291]: chan_sip.c:6121 parse_request: Header 10 [ 16]: Supported: timer [Apr 13 14:46:08] DEBUG[3291]: chan_sip.c:6121 parse_request: Header 11 [ 32]: User-Agent: Aastra 55i/2.2.0.166 [Apr 13 14:46:08] DEBUG[3291]: chan_sip.c:6121 parse_request: Header 12 [ 17]: Content-Length: 0 [Apr 13 14:46:08] --- (13 headers 0 lines) --- [Apr 13 14:46:08] DEBUG[3291]: chan_sip.c:5849 find_call: = Looking for Call ID: a3a868736ab469d3 (Checking From) --From tag 4d6ff13510 --To-tag as09d7ceab [Apr 13 14:46:08] DEBUG[3291]: chan_sip.c:5876 find_call: = Found Their Call ID: a3a868736ab469d3 Their Tag 4d6ff13510 Our tag: as09d7ceab [Apr 13 14:46:08] DEBUG[3291]: chan_sip.c:17847 handle_incoming: **** Received BYE (8) - Command in SIP BYE [Apr 13 14:46:08] DEBUG[3291]: chan_sip.c:17317 handle_request_bye: Initializing initreq for method BYE - callid a3a868736ab469d3 [Apr 13 14:46:08] Sending to 10.50.10.183 : 5060 (no NAT) [Apr 13 14:46:08] DEBUG[3291]: chan_sip.c:2323 sip_alreadygone: Setting SIP_ALREADYGONE on dialog a3a868736ab469d3 [Apr 13 14:46:08] DEBUG[3291]: chan_sip.c:17374 handle_request_bye: Received bye, issuing owner hangup [Apr 13 14:46:08] <--- 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=z9hG4bK9347381f26bb95e94;received=10.50.10.183 From: "PowerPBX 23" ;tag=4d6ff13510 To: "station3_line1" ;tag=as09d7ceab Call-ID: a3a868736ab469d3 CSeq: 21101 BYE User-Agent: Asterisk PBX 1.6.0-beta7.1 Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY Supported: replaces, timer Contact: Content-Length: 0 <------------> [Apr 13 14:46:08] DEBUG[3291]: chan_sip.c:2520 __sip_xmit: Trying to put 'SIP/2.0 20' onto UDP socket... [Apr 13 14:46:08] DEBUG[3291]: devicestate.c:441 __ast_devstate_changed_literal: Notification of state change to be queued on device/channel SLA:station1_line1 [Apr 13 14:46:08] DEBUG[3291]: devicestate.c:441 __ast_devstate_changed_literal: Notification of state change to be queued on device/channel SLA:station2_line1 [Apr 13 14:46:08] DEBUG[3291]: devicestate.c:441 __ast_devstate_changed_literal: Notification of state change to be queued on device/channel SLA:station3_line1 [Apr 13 14:46:08] DEBUG[3291]: pbx.c:3318 __ast_pbx_run: Extension station3_line1, priority 1 returned normally even though call was hung up [Apr 13 14:46:08] DEBUG[3291]: channel.c:1518 ast_softhangup_nolock: Soft-Hanging up channel 'SIP/station3-0a051308' [Apr 13 14:46:08] DEBUG[3291]: channel.c:1617 ast_hangup: Hanging up channel 'SIP/station3-0a051308' [Apr 13 14:46:08] DEBUG[3291]: chan_sip.c:4689 sip_hangup: Hangup call SIP/station3-0a051308, SIP callid a3a868736ab469d3 [Apr 13 14:46:08] DEBUG[3291]: devicestate.c:441 __ast_devstate_changed_literal: Notification of state change to be queued on device/channel SIP/station3-0a051308 [Apr 13 14:46:08] DEBUG[3291]: devicestate.c:441 __ast_devstate_changed_literal: Notification of state change to be queued on device/channel SIP/station3 [Apr 13 14:46:08] DEBUG[3291]: pbx.c:2527 pbx_substitute_variables_helper_full: Function result is '2008-04-13 14:45:58' [Apr 13 14:46:08] DEBUG[3291]: pbx.c:2527 pbx_substitute_variables_helper_full: Function result is '"IC" <8055480003>' [Apr 13 14:46:08] DEBUG[3291]: pbx.c:2527 pbx_substitute_variables_helper_full: Function result is 'sla_stations' [Apr 13 14:46:08] DEBUG[3291]: pbx.c:2527 pbx_substitute_variables_helper_full: Function result is 'SIP/station3-0a051308' [Apr 13 14:46:08] DEBUG[3291]: pbx.c:2527 pbx_substitute_variables_helper_full: Function result is '' [Apr 13 14:46:08] DEBUG[3291]: pbx.c:2527 pbx_substitute_variables_helper_full: Function result is 'SLAStation' [Apr 13 14:46:08] DEBUG[3291]: pbx.c:2527 pbx_substitute_variables_helper_full: Function result is 'station3_line1' [Apr 13 14:46:08] DEBUG[3291]: pbx.c:2527 pbx_substitute_variables_helper_full: Function result is '10' [Apr 13 14:46:08] DEBUG[3291]: pbx.c:2527 pbx_substitute_variables_helper_full: Function result is '9' [Apr 13 14:46:08] DEBUG[3291]: pbx.c:2527 pbx_substitute_variables_helper_full: Function result is 'ANSWERED' [Apr 13 14:46:08] DEBUG[3291]: pbx.c:2527 pbx_substitute_variables_helper_full: Function result is 'DOCUMENTATION' [Apr 13 14:46:08] DEBUG[3291]: pbx.c:2527 pbx_substitute_variables_helper_full: Function result is '' [Apr 13 14:46:08] DEBUG[3291]: pbx.c:2527 pbx_substitute_variables_helper_full: Function result is '1208123158.0' [Apr 13 14:46:08] DEBUG[3291]: pbx.c:2527 pbx_substitute_variables_helper_full: Function result is '' [Apr 13 14:46:08] DEBUG[3291]: pbx.c:2527 pbx_substitute_variables_helper_full: Function result is '' [Apr 13 14:46:08] DEBUG[3291]: cdr_sqlite3_custom.c:266 sqlite3_log: About to log: INSERT INTO cdr (calldate,clid,dcontext,channel,dstchannel,lastapp,lastdata,duration,billsec,disposition,amaflags,accountcode,uniqueid,userfield,test) VALUES ('2008-04-13 14:45:58','"IC" <8055480003>','sla_stations','SIP/station3-0a051308','','SLAStation','station3_line1','10','9','ANSWERED','DOCUMENTATION','','1208123158.0','','') [Apr 13 14:46:08] DEBUG[3291]: devicestate.c:320 ast_device_state: No provider found, checking channel drivers for SIP - station3-0a051308 [Apr 13 14:46:08] DEBUG[3291]: chan_sip.c:18907 sip_devicestate: Checking device state for peer station3-0a051308 [Apr 13 14:46:08] DEBUG[3291]: devicestate.c:430 do_state_change: Changing state for SIP/station3-0a051308 - state 1 (Not in use) [Apr 13 14:46:08] DEBUG[3291]: devicestate.c:320 ast_device_state: No provider found, checking channel drivers for SIP - station3 [Apr 13 14:46:08] DEBUG[3291]: chan_sip.c:18907 sip_devicestate: Checking device state for peer station3 [Apr 13 14:46:08] DEBUG[3291]: devicestate.c:430 do_state_change: Changing state for SIP/station3 - state 1 (Not in use) [Apr 13 14:46:08] DEBUG[3291]: devicestate.c:441 __ast_devstate_changed_literal: Notification of state change to be queued on device/channel meetme:SLA_line1 [Apr 13 14:46:08] DEBUG[3291]: channel.c:1617 ast_hangup: Hanging up channel 'Zap/pseudo-611129770' [Apr 13 14:46:08] DEBUG[3291]: chan_zap.c:2974 zt_hangup: zt_hangup(Zap/pseudo-611129770) [Apr 13 14:46:08] DEBUG[3291]: chan_zap.c:3008 zt_hangup: Hangup: channel: -2 index = 0, normal = 29, callwait = -1, thirdcall = -1 [Apr 13 14:46:08] DEBUG[3291]: chan_zap.c:3472 zt_setoption: Set option TDD MODE, value: OFF(0) on Zap/pseudo-611129770 [Apr 13 14:46:08] DEBUG[3291]: chan_zap.c:1631 update_conf: Updated conferencing on -2, with 0 conference users [Apr 13 14:46:08] -- Hungup 'Zap/pseudo-611129770' [Apr 13 14:46:08] DEBUG[3291]: devicestate.c:441 __ast_devstate_changed_literal: Notification of state change to be queued on device/channel Zap/pseudo-611129770 [Apr 13 14:46:08] DEBUG[3291]: devicestate.c:441 __ast_devstate_changed_literal: Notification of state change to be queued on device/channel Zap/pseudo [Apr 13 14:46:08] DEBUG[3291]: devicestate.c:441 __ast_devstate_changed_literal: Notification of state change to be queued on device/channel SLA:station1_line1 [Apr 13 14:46:08] DEBUG[3291]: devicestate.c:441 __ast_devstate_changed_literal: Notification of state change to be queued on device/channel SLA:station2_line1 [Apr 13 14:46:08] DEBUG[3291]: devicestate.c:441 __ast_devstate_changed_literal: Notification of state change to be queued on device/channel SLA:station3_line1 [Apr 13 14:46:08] DEBUG[3291]: channel.c:1617 ast_hangup: Hanging up channel 'Local/disa@line1_outbound-9d53;1' [Apr 13 14:46:08] DEBUG[3291]: devicestate.c:441 __ast_devstate_changed_literal: Notification of state change to be queued on device/channel Local/disa@line1_outbound-9d53;1 [Apr 13 14:46:08] DEBUG[3291]: devicestate.c:441 __ast_devstate_changed_literal: Notification of state change to be queued on device/channel Local/disa@line1_outbound [Apr 13 14:46:08] DEBUG[3291]: pbx.c:2527 pbx_substitute_variables_helper_full: Function result is '2008-04-13 14:45:58' [Apr 13 14:46:08] DEBUG[3291]: pbx.c:2527 pbx_substitute_variables_helper_full: Function result is '' [Apr 13 14:46:08] DEBUG[3291]: pbx.c:2527 pbx_substitute_variables_helper_full: Function result is 'line1_outbound' [Apr 13 14:46:08] DEBUG[3291]: pbx.c:2527 pbx_substitute_variables_helper_full: Function result is 'Local/disa@line1_outbound-9d53;1' [Apr 13 14:46:08] DEBUG[3291]: pbx.c:2527 pbx_substitute_variables_helper_full: Function result is '' [Apr 13 14:46:08] DEBUG[3291]: pbx.c:2527 pbx_substitute_variables_helper_full: Function result is '' [Apr 13 14:46:08] DEBUG[3291]: pbx.c:2527 pbx_substitute_variables_helper_full: Function result is '' [Apr 13 14:46:08] DEBUG[3291]: pbx.c:2527 pbx_substitute_variables_helper_full: Function result is '10' [Apr 13 14:46:08] DEBUG[3291]: pbx.c:2527 pbx_substitute_variables_helper_full: Function result is '9' [Apr 13 14:46:08] DEBUG[3291]: pbx.c:2527 pbx_substitute_variables_helper_full: Function result is 'ANSWERED' [Apr 13 14:46:08] DEBUG[3291]: pbx.c:2527 pbx_substitute_variables_helper_full: Function result is 'DOCUMENTATION' [Apr 13 14:46:08] DEBUG[3291]: pbx.c:2527 pbx_substitute_variables_helper_full: Function result is '' [Apr 13 14:46:08] DEBUG[3291]: pbx.c:2527 pbx_substitute_variables_helper_full: Function result is '1208123158.1' [Apr 13 14:46:08] DEBUG[3291]: pbx.c:2527 pbx_substitute_variables_helper_full: Function result is '' [Apr 13 14:46:08] DEBUG[3291]: pbx.c:2527 pbx_substitute_variables_helper_full: Function result is '' [Apr 13 14:46:08] DEBUG[3291]: cdr_sqlite3_custom.c:266 sqlite3_log: About to log: INSERT INTO cdr (calldate,clid,dcontext,channel,dstchannel,lastapp,lastdata,duration,billsec,disposition,amaflags,accountcode,uniqueid,userfield,test) VALUES ('2008-04-13 14:45:58','','line1_outbound','Local/disa@line1_outbound-9d53;1','','','','10','9','ANSWERED','DOCUMENTATION','','1208123158.1','','') [Apr 13 14:46:08] DEBUG[3291]: devicestate.c:320 ast_device_state: No provider found, checking channel drivers for Zap - pseudo-611129770 [Apr 13 14:46:08] DEBUG[3291]: devicestate.c:430 do_state_change: Changing state for Zap/pseudo-611129770 - state 0 (Unknown) [Apr 13 14:46:08] DEBUG[3291]: devicestate.c:320 ast_device_state: No provider found, checking channel drivers for Zap - pseudo [Apr 13 14:46:08] DEBUG[3291]: devicestate.c:430 do_state_change: Changing state for Zap/pseudo - state 0 (Unknown) [Apr 13 14:46:08] DEBUG[3291]: devicestate.c:320 ast_device_state: No provider found, checking channel drivers for Local - disa@line1_outbound-9d53;1 [Apr 13 14:46:08] DEBUG[3291]: chan_local.c:141 local_devicestate: Checking if extension disa@line1_outbound-9d53;1 exists (devicestate) [Apr 13 14:46:08] DEBUG[3291]: devicestate.c:430 do_state_change: Changing state for Local/disa@line1_outbound-9d53;1 - state 4 (Invalid) [Apr 13 14:46:08] DEBUG[3291]: devicestate.c:320 ast_device_state: No provider found, checking channel drivers for Local - disa@line1_outbound [Apr 13 14:46:08] DEBUG[3291]: chan_local.c:141 local_devicestate: Checking if extension disa@line1_outbound exists (devicestate) [Apr 13 14:46:08] DEBUG[3291]: devicestate.c:430 do_state_change: Changing state for Local/disa@line1_outbound - state 1 (Not in use) [Apr 13 14:46:08] DEBUG[3291]: pbx.c:3336 __ast_pbx_run: Spawn extension (line1_outbound,disa,1) exited non-zero on 'Local/disa@line1_outbound-9d53;2' [Apr 13 14:46:08] == Spawn extension (line1_outbound, disa, 1) exited non-zero on 'Local/disa@line1_outbound-9d53;2' [Apr 13 14:46:08] DEBUG[3291]: channel.c:1518 ast_softhangup_nolock: Soft-Hanging up channel 'Local/disa@line1_outbound-9d53;2' [Apr 13 14:46:08] DEBUG[3291]: channel.c:1617 ast_hangup: Hanging up channel 'Local/disa@line1_outbound-9d53;2' [Apr 13 14:46:08] DEBUG[3291]: devicestate.c:441 __ast_devstate_changed_literal: Notification of state change to be queued on device/channel Local/disa@line1_outbound-9d53;2 [Apr 13 14:46:08] DEBUG[3291]: devicestate.c:441 __ast_devstate_changed_literal: Notification of state change to be queued on device/channel Local/disa@line1_outbound [Apr 13 14:46:08] DEBUG[3291]: pbx.c:2527 pbx_substitute_variables_helper_full: Function result is '2008-04-13 14:45:58' [Apr 13 14:46:08] DEBUG[3291]: pbx.c:2527 pbx_substitute_variables_helper_full: Function result is '"IC" <8055480003>' [Apr 13 14:46:08] DEBUG[3291]: pbx.c:2527 pbx_substitute_variables_helper_full: Function result is 'line1_outbound' [Apr 13 14:46:08] DEBUG[3291]: pbx.c:2527 pbx_substitute_variables_helper_full: Function result is 'Local/disa@line1_outbound-9d53;2' [Apr 13 14:46:08] DEBUG[3291]: pbx.c:2527 pbx_substitute_variables_helper_full: Function result is '' [Apr 13 14:46:08] DEBUG[3291]: pbx.c:2527 pbx_substitute_variables_helper_full: Function result is 'DISA' [Apr 13 14:46:08] DEBUG[3291]: pbx.c:2527 pbx_substitute_variables_helper_full: Function result is 'no-password,line1_outbound' [Apr 13 14:46:08] DEBUG[3291]: pbx.c:2527 pbx_substitute_variables_helper_full: Function result is '10' [Apr 13 14:46:08] DEBUG[3291]: pbx.c:2527 pbx_substitute_variables_helper_full: Function result is '9' [Apr 13 14:46:08] DEBUG[3291]: pbx.c:2527 pbx_substitute_variables_helper_full: Function result is 'ANSWERED' [Apr 13 14:46:08] DEBUG[3291]: pbx.c:2527 pbx_substitute_variables_helper_full: Function result is 'DOCUMENTATION' [Apr 13 14:46:08] DEBUG[3291]: pbx.c:2527 pbx_substitute_variables_helper_full: Function result is '' [Apr 13 14:46:08] DEBUG[3291]: pbx.c:2527 pbx_substitute_variables_helper_full: Function result is '1208123158.2' [Apr 13 14:46:08] DEBUG[3291]: pbx.c:2527 pbx_substitute_variables_helper_full: Function result is '' [Apr 13 14:46:08] DEBUG[3291]: pbx.c:2527 pbx_substitute_variables_helper_full: Function result is '' [Apr 13 14:46:08] DEBUG[3291]: cdr_sqlite3_custom.c:266 sqlite3_log: About to log: INSERT INTO cdr (calldate,clid,dcontext,channel,dstchannel,lastapp,lastdata,duration,billsec,disposition,amaflags,accountcode,uniqueid,userfield,test) VALUES ('2008-04-13 14:45:58','"IC" <8055480003>','line1_outbound','Local/disa@line1_outbound-9d53;2','','DISA','no-password,line1_outbound','10','9','ANSWERED','DOCUMENTATION','','1208123158.2','','') [Apr 13 14:46:08] DEBUG[3291]: app_queue.c:761 handle_statechange: Device 'SIP/station3-0a051308' changed to state '1' (Not in use) but we don't care because they're not a member of any queue. [Apr 13 14:46:08] DEBUG[3291]: app_queue.c:761 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:46:08] DEBUG[3291]: devicestate.c:320 ast_device_state: No provider found, checking channel drivers for Local - disa@line1_outbound-9d53;2 [Apr 13 14:46:08] DEBUG[3291]: chan_local.c:141 local_devicestate: Checking if extension disa@line1_outbound-9d53;2 exists (devicestate) [Apr 13 14:46:08] DEBUG[3291]: devicestate.c:430 do_state_change: Changing state for Local/disa@line1_outbound-9d53;2 - state 4 (Invalid) [Apr 13 14:46:08] DEBUG[3291]: devicestate.c:320 ast_device_state: No provider found, checking channel drivers for Local - disa@line1_outbound [Apr 13 14:46:08] DEBUG[3291]: chan_local.c:141 local_devicestate: Checking if extension disa@line1_outbound exists (devicestate) [Apr 13 14:46:08] DEBUG[3291]: devicestate.c:430 do_state_change: Changing state for Local/disa@line1_outbound - state 1 (Not in use) [Apr 13 14:46:08] DEBUG[3291]: app_queue.c:761 handle_statechange: Device 'Zap/pseudo-611129770' changed to state '0' (Unknown) but we don't care because they're not a member of any queue. [Apr 13 14:46:08] DEBUG[3291]: app_queue.c:761 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:46:08] DEBUG[3291]: app_queue.c:761 handle_statechange: Device 'Local/disa@line1_outbound-9d53;1' changed to state '4' (Invalid) but we don't care because they're not a member of any queue. [Apr 13 14:46:08] DEBUG[3291]: app_queue.c:761 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:46:08] DEBUG[3291]: app_queue.c:761 handle_statechange: Device 'Local/disa@line1_outbound-9d53;2' changed to state '4' (Invalid) but we don't care because they're not a member of any queue. [Apr 13 14:46:08] DEBUG[3291]: app_queue.c:761 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:46:09] Really destroying SIP dialog 'a3a868736ab469d3' Method: BYE [Apr 13 14:46:16] <--- SIP read from UDP://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-045e2aeac8bd85330bab5e4d2939c64a-metaswitch-1 Allow-Events: message-summary Allow-Events: refer Allow-Events: dialog Allow-Events: line-seize Max-Forwards: 70 Call-ID: 06166B94@metaswitch From: ;tag=metaswitch+1+0+981f1307 CSeq: 841984229 OPTIONS Organization: Supported: 100rel Content-Length: 0 Contact: To: <-------------> [Apr 13 14:46:16] DEBUG[3291]: chan_sip.c:6121 parse_request: Header 0 [ 62]: OPTIONS sip:metaswitch@10.50.10.171:5060;transport=udp SIP/2.0 [Apr 13 14:46:16] DEBUG[3291]: chan_sip.c:6121 parse_request: Header 1 [ 99]: Via: SIP/2.0/UDP 10.50.10.2:5060;rport;branch=z9hG4bK-045e2aeac8bd85330bab5e4d2939c64a-metaswitch-1 [Apr 13 14:46:16] DEBUG[3291]: chan_sip.c:6121 parse_request: Header 2 [ 29]: Allow-Events: message-summary [Apr 13 14:46:16] DEBUG[3291]: chan_sip.c:6121 parse_request: Header 3 [ 19]: Allow-Events: refer [Apr 13 14:46:16] DEBUG[3291]: chan_sip.c:6121 parse_request: Header 4 [ 20]: Allow-Events: dialog [Apr 13 14:46:16] DEBUG[3291]: chan_sip.c:6121 parse_request: Header 5 [ 24]: Allow-Events: line-seize [Apr 13 14:46:16] DEBUG[3291]: chan_sip.c:6121 parse_request: Header 6 [ 16]: Max-Forwards: 70 [Apr 13 14:46:16] DEBUG[3291]: chan_sip.c:6121 parse_request: Header 7 [ 28]: Call-ID: 06166B94@metaswitch [Apr 13 14:46:16] DEBUG[3291]: chan_sip.c:6121 parse_request: Header 8 [ 66]: From: ;tag=metaswitch+1+0+981f1307 [Apr 13 14:46:16] DEBUG[3291]: chan_sip.c:6121 parse_request: Header 9 [ 23]: CSeq: 841984229 OPTIONS [Apr 13 14:46:16] DEBUG[3291]: chan_sip.c:6121 parse_request: Header 10 [ 14]: Organization: [Apr 13 14:46:16] DEBUG[3291]: chan_sip.c:6121 parse_request: Header 11 [ 17]: Supported: 100rel [Apr 13 14:46:16] DEBUG[3291]: chan_sip.c:6121 parse_request: Header 12 [ 17]: Content-Length: 0 [Apr 13 14:46:16] DEBUG[3291]: chan_sip.c:6121 parse_request: Header 13 [ 41]: Contact: [Apr 13 14:46:16] DEBUG[3291]: chan_sip.c:6121 parse_request: Header 14 [ 33]: To: [Apr 13 14:46:16] --- (15 headers 0 lines) --- [Apr 13 14:46:16] DEBUG[3291]: chan_sip.c:5849 find_call: = Looking for Call ID: 06166B94@metaswitch (Checking From) --From tag metaswitch+1+0+981f1307 --To-tag [Apr 13 14:46:16] DEBUG[3291]: chan_sip.c:5876 find_call: = No match Their Call ID: 58836ef0798742bf4002370e5877c808@127.0.0.1 Their Tag metaswitch+1+0+cda6eac1 Our tag: as6c690e8a [Apr 13 14:46:16] DEBUG[3291]: chan_sip.c:5876 find_call: = No match Their Call ID: 59bec6a116d82a3955a4f74c1cee14a6@127.0.0.1 Their Tag metaswitch+1+0+6e97b884 Our tag: as1fd94a8c [Apr 13 14:46:16] DEBUG[3291]: chan_sip.c:5876 find_call: = No match Their Call ID: 48ef4f2a7baf832d1192b297083293d7@127.0.0.1 Their Tag metaswitch+1+0+a5680d76 Our tag: as5da77ddc [Apr 13 14:46:16] DEBUG[3291]: chan_sip.c:5876 find_call: = No match Their Call ID: 615078E5@metaswitch Their Tag metaswitch+1+0+8b861ff2 Our tag: as4b149aa5 [Apr 13 14:46:16] DEBUG[3291]: acl.c:490 ast_ouraddrfor: Found IP address for this socket [Apr 13 14:46:16] DEBUG[3291]: chan_sip.c:5810 sip_alloc: Allocating new SIP dialog for 06166B94@metaswitch - OPTIONS (No RTP) [Apr 13 14:46:16] DEBUG[3291]: chan_sip.c:17847 handle_incoming: **** Received OPTIONS (3) - Command in SIP OPTIONS [Apr 13 14:46:16] Looking for metaswitch in default (domain 10.50.10.171) [Apr 13 14:46:16] <--- 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-045e2aeac8bd85330bab5e4d2939c64a-metaswitch-1;received=10.50.10.2 From: ;tag=metaswitch+1+0+981f1307 To: ;tag=as56847aee Call-ID: 06166B94@metaswitch CSeq: 841984229 OPTIONS User-Agent: Asterisk PBX 1.6.0-beta7.1 Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY Supported: replaces, timer Accept: application/sdp Content-Length: 0 <------------> [