< Debug log from console > asterisk -r Asterisk 1.2.10, Copyright (C) 1999 - 2006 Digium, Inc. and others. Created by Mark Spencer Asterisk comes with ABSOLUTELY NO WARRANTY; type 'show warranty' for details. This is free software, with components licensed under the GNU General Public License version 2 and other licenses; you are welcome to redistribute it under certain conditions. Type 'show license' for details. ========================================================================= Connected to Asterisk 1.2.10 currently running on ubuntu-test-1 (pid = 3952) Verbosity is at least 4 Core debug is at least 4 ubuntu-test-1*CLI> <-- SIP read from 10.2.6.252:5060: INVITE sip:195@10.0.90.187 SIP/2.0 Via: SIP/2.0/UDP 10.2.6.252;rport;branch=z9hG4bK0a0206fc0000003944d0d1c100006e1c00000072 Content-Length: 333 Contact: Call-ID: EC3876C9-D5F6-4AE9-B0E7-5B41CCA10C83@10.2.6.252 Content-Type: application/sdp CSeq: 1 INVITE From: "unknown";tag=79254603128430 Max-Forwards: 70 To: User-Agent: SJphone/1.60.289a (SJ Labs) v=0 o=- 3363524673 3363524673 IN IP4 10.2.6.252 s=SJphone c=IN IP4 10.2.6.252 t=0 0 a=direction:active m=audio 49158 RTP/AVP 3 97 98 8 0 101 a=rtpmap:3 GSM/8000 a=rtpmap:97 iLBC/8000 a=rtpmap:98 iLBC/8000 a=fmtp:98 mode=20 a=rtpmap:8 PCMA/8000 a=rtpmap:0 PCMU/8000 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-11,16 Aug 2 18:23:42 DEBUG[3962]: chan_sip.c:3357 parse_request: Header 0: INVITE sip:195@10.0.90.187 SIP/2.0 (34) Aug 2 18:23:42 DEBUG[3962]: chan_sip.c:3357 parse_request: Header 1: Via: SIP/2.0/UDP 10.2.6.252;rport;branch=z9hG4bK0a0206fc0000003944d0d1c100006e1c00000072 (88) Aug 2 18:23:42 DEBUG[3962]: chan_sip.c:3357 parse_request: Header 2: Content-Length: 333 (19) Aug 2 18:23:42 DEBUG[3962]: chan_sip.c:3357 parse_request: Header 3: Contact: (34) Aug 2 18:23:42 DEBUG[3962]: chan_sip.c:3357 parse_request: Header 4: Call-ID: EC3876C9-D5F6-4AE9-B0E7-5B41CCA10C83@10.2.6.252 (56) Aug 2 18:23:42 DEBUG[3962]: chan_sip.c:3357 parse_request: Header 5: Content-Type: application/sdp (29) Aug 2 18:23:42 DEBUG[3962]: chan_sip.c:3357 parse_request: Header 6: CSeq: 1 INVITE (14) Aug 2 18:23:42 DEBUG[3962]: chan_sip.c:3357 parse_request: Header 7: From: "unknown";tag=79254603128430 (55) Aug 2 18:23:42 DEBUG[3962]: chan_sip.c:3357 parse_request: Header 8: Max-Forwards: 70 (16) Aug 2 18:23:42 DEBUG[3962]: chan_sip.c:3357 parse_request: Header 9: To: (25) Aug 2 18:23:42 DEBUG[3962]: chan_sip.c:3357 parse_request: Header 10: User-Agent: SJphone/1.60.289a (SJ Labs) (39) Aug 2 18:23:42 DEBUG[3962]: chan_sip.c:3357 parse_request: Header 11: (0) Aug 2 18:23:42 DEBUG[3962]: chan_sip.c:3389 parse_request: Line: v=0 (3) Aug 2 18:23:42 DEBUG[3962]: chan_sip.c:3389 parse_request: Line: o=- 3363524673 3363524673 IN IP4 10.2.6.252 (43) Aug 2 18:23:42 DEBUG[3962]: chan_sip.c:3389 parse_request: Line: s=SJphone (9) Aug 2 18:23:42 DEBUG[3962]: chan_sip.c:3389 parse_request: Line: c=IN IP4 10.2.6.252 (19) Aug 2 18:23:42 DEBUG[3962]: chan_sip.c:3389 parse_request: Line: t=0 0 (5) Aug 2 18:23:42 DEBUG[3962]: chan_sip.c:3389 parse_request: Line: a=direction:active (18) Aug 2 18:23:42 DEBUG[3962]: chan_sip.c:3389 parse_request: Line: m=audio 49158 RTP/AVP 3 97 98 8 0 101 (37) Aug 2 18:23:42 DEBUG[3962]: chan_sip.c:3389 parse_request: Line: a=rtpmap:3 GSM/8000 (19) Aug 2 18:23:42 DEBUG[3962]: chan_sip.c:3389 parse_request: Line: a=rtpmap:97 iLBC/8000 (21) Aug 2 18:23:42 DEBUG[3962]: chan_sip.c:3389 parse_request: Line: a=rtpmap:98 iLBC/8000 (21) Aug 2 18:23:42 DEBUG[3962]: chan_sip.c:3389 parse_request: Line: a=fmtp:98 mode=20 (17) Aug 2 18:23:42 DEBUG[3962]: chan_sip.c:3389 parse_request: Line: a=rtpmap:8 PCMA/8000 (20) Aug 2 18:23:42 DEBUG[3962]: chan_sip.c:3389 parse_request: Line: a=rtpmap:0 PCMU/8000 (20) Aug 2 18:23:42 DEBUG[3962]: chan_sip.c:3389 parse_request: Line: a=rtpmap:101 telephone-event/8000 (33) Aug 2 18:23:42 DEBUG[3962]: chan_sip.c:3389 parse_request: Line: a=fmtp:101 0-11,16 (18) --- (11 headers 15 lines)--- Aug 2 18:23:42 DEBUG[3962]: chan_sip.c:3141 sip_alloc: Allocating new SIP dialog for EC3876C9-D5F6-4AE9-B0E7-5B41CCA10C83@10.2.6.252 - INVITE (With RTP) Aug 2 18:23:42 DEBUG[3962]: chan_sip.c:11139 handle_request: **** Received INVITE (5) - Command in SIP INVITE Using INVITE request as basis request - EC3876C9-D5F6-4AE9-B0E7-5B41CCA10C83@10.2.6.252 Sending to 10.2.6.252 : 5060 (NAT) Aug 2 18:23:42 DEBUG[3962]: chan_sip.c:7149 check_user_full: Setting NAT on RTP to 0 Aug 2 18:23:42 DEBUG[3962]: chan_sip.c:7153 check_user_full: Setting NAT on VRTP to 0 Reliably Transmitting (no NAT) to 10.2.6.252:5060: SIP/2.0 407 Proxy Authentication Required Via: SIP/2.0/UDP 10.2.6.252;rport;branch=z9hG4bK0a0206fc0000003944d0d1c100006e1c00000072;received=10.2.6.252 From: "unknown";tag=79254603128430 To: ;tag=as56606d2e Call-ID: EC3876C9-D5F6-4AE9-B0E7-5B41CCA10C83@10.2.6.252 CSeq: 1 INVITE User-Agent: Diptel-T50 Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY Contact: Proxy-Authenticate: Digest algorithm=MD5, realm="asterisk", nonce="769a81f0" Content-Length: 0 --- Aug 2 18:23:42 DEBUG[3962]: chan_sip.c:1293 __sip_reliable_xmit: *** SIP TIMER: Initalizing retransmit timer on packet: Id #37 Scheduling destruction of call 'EC3876C9-D5F6-4AE9-B0E7-5B41CCA10C83@10.2.6.252' in 15000 ms Found user '803' ubuntu-test-1*CLI> <-- SIP read from 10.2.6.252:5060: ACK sip:195@10.0.90.187 SIP/2.0 Via: SIP/2.0/UDP 10.2.6.252;rport;branch=z9hG4bK0a0206fc0000003944d0d1c100006e1c00000072 Content-Length: 0 Call-ID: EC3876C9-D5F6-4AE9-B0E7-5B41CCA10C83@10.2.6.252 CSeq: 1 ACK From: "unknown";tag=79254603128430 Max-Forwards: 70 To: ;tag=as56606d2e User-Agent: SJphone/1.60.289a (SJ Labs) Aug 2 18:23:42 DEBUG[3962]: chan_sip.c:3357 parse_request: Header 0: ACK sip:195@10.0.90.187 SIP/2.0 (31) Aug 2 18:23:42 DEBUG[3962]: chan_sip.c:3357 parse_request: Header 1: Via: SIP/2.0/UDP 10.2.6.252;rport;branch=z9hG4bK0a0206fc0000003944d0d1c100006e1c00000072 (88) Aug 2 18:23:42 DEBUG[3962]: chan_sip.c:3357 parse_request: Header 2: Content-Length: 0 (17) Aug 2 18:23:42 DEBUG[3962]: chan_sip.c:3357 parse_request: Header 3: Call-ID: EC3876C9-D5F6-4AE9-B0E7-5B41CCA10C83@10.2.6.252 (56) Aug 2 18:23:42 DEBUG[3962]: chan_sip.c:3357 parse_request: Header 4: CSeq: 1 ACK (11) Aug 2 18:23:42 DEBUG[3962]: chan_sip.c:3357 parse_request: Header 5: From: "unknown";tag=79254603128430 (55) Aug 2 18:23:42 DEBUG[3962]: chan_sip.c:3357 parse_request: Header 6: Max-Forwards: 70 (16) Aug 2 18:23:42 DEBUG[3962]: chan_sip.c:3357 parse_request: Header 7: To: ;tag=as56606d2e (40) Aug 2 18:23:42 DEBUG[3962]: chan_sip.c:3357 parse_request: Header 8: User-Agent: SJphone/1.60.289a (SJ Labs) (39) Aug 2 18:23:42 DEBUG[3962]: chan_sip.c:3357 parse_request: Header 9: (0) --- (9 headers 0 lines)--- Aug 2 18:23:42 DEBUG[3962]: chan_sip.c:11139 handle_request: **** Received ACK (6) - Command in SIP ACK Aug 2 18:23:42 DEBUG[3962]: chan_sip.c:1390 __sip_ack: ** SIP TIMER: Cancelling retransmit of packet (reply received) Retransid #37 Aug 2 18:23:42 DEBUG[3962]: chan_sip.c:1401 __sip_ack: Stopping retransmission on 'EC3876C9-D5F6-4AE9-B0E7-5B41CCA10C83@10.2.6.252' of Response 1: Match Found <-- SIP read from 10.2.6.252:5060: INVITE sip:195@10.0.90.187 SIP/2.0 Via: SIP/2.0/UDP 10.2.6.252;rport;branch=z9hG4bK0a0206fc0000003944d0d1c10000231000000073 Content-Length: 333 Contact: Call-ID: EC3876C9-D5F6-4AE9-B0E7-5B41CCA10C83@10.2.6.252 Content-Type: application/sdp CSeq: 2 INVITE From: "unknown";tag=79254603128430 Max-Forwards: 70 To: User-Agent: SJphone/1.60.289a (SJ Labs) Proxy-Authorization: Digest username="803",realm="asterisk",nonce="769a81f0",uri="sip:195@10.0.90.187",response="e75bf308f27948a3890ba93193c844e8",algorithm="MD5" v=0 o=- 3363524673 3363524673 IN IP4 10.2.6.252 s=SJphone c=IN IP4 10.2.6.252 t=0 0 a=direction:active m=audio 49158 RTP/AVP 3 97 98 8 0 101 a=rtpmap:3 GSM/8000 a=rtpmap:97 iLBC/8000 a=rtpmap:98 iLBC/8000 a=fmtp:98 mode=20 a=rtpmap:8 PCMA/8000 a=rtpmap:0 PCMU/8000 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-11,16 Aug 2 18:23:42 DEBUG[3962]: chan_sip.c:3357 parse_request: Header 0: INVITE sip:195@10.0.90.187 SIP/2.0 (34) Aug 2 18:23:42 DEBUG[3962]: chan_sip.c:3357 parse_request: Header 1: Via: SIP/2.0/UDP 10.2.6.252;rport;branch=z9hG4bK0a0206fc0000003944d0d1c10000231000000073 (88) Aug 2 18:23:42 DEBUG[3962]: chan_sip.c:3357 parse_request: Header 2: Content-Length: 333 (19) Aug 2 18:23:42 DEBUG[3962]: chan_sip.c:3357 parse_request: Header 3: Contact: (34) Aug 2 18:23:42 DEBUG[3962]: chan_sip.c:3357 parse_request: Header 4: Call-ID: EC3876C9-D5F6-4AE9-B0E7-5B41CCA10C83@10.2.6.252 (56) Aug 2 18:23:42 DEBUG[3962]: chan_sip.c:3357 parse_request: Header 5: Content-Type: application/sdp (29) Aug 2 18:23:42 DEBUG[3962]: chan_sip.c:3357 parse_request: Header 6: CSeq: 2 INVITE (14) Aug 2 18:23:42 DEBUG[3962]: chan_sip.c:3357 parse_request: Header 7: From: "unknown";tag=79254603128430 (55) Aug 2 18:23:42 DEBUG[3962]: chan_sip.c:3357 parse_request: Header 8: Max-Forwards: 70 (16) Aug 2 18:23:42 DEBUG[3962]: chan_sip.c:3357 parse_request: Header 9: To: (25) Aug 2 18:23:42 DEBUG[3962]: chan_sip.c:3357 parse_request: Header 10: User-Agent: SJphone/1.60.289a (SJ Labs) (39) Aug 2 18:23:42 DEBUG[3962]: chan_sip.c:3357 parse_request: Header 11: Proxy-Authorization: Digest username="803",realm="asterisk",nonce="769a81f0",uri="sip:195@10.0.90.187",response="e75bf308f27948a3890ba93193c844e8",algorithm="MD5" (162) Aug 2 18:23:42 DEBUG[3962]: chan_sip.c:3357 parse_request: Header 12: (0) Aug 2 18:23:42 DEBUG[3962]: chan_sip.c:3389 parse_request: Line: v=0 (3) Aug 2 18:23:42 DEBUG[3962]: chan_sip.c:3389 parse_request: Line: o=- 3363524673 3363524673 IN IP4 10.2.6.252 (43) Aug 2 18:23:42 DEBUG[3962]: chan_sip.c:3389 parse_request: Line: s=SJphone (9) Aug 2 18:23:42 DEBUG[3962]: chan_sip.c:3389 parse_request: Line: c=IN IP4 10.2.6.252 (19) Aug 2 18:23:42 DEBUG[3962]: chan_sip.c:3389 parse_request: Line: t=0 0 (5) Aug 2 18:23:42 DEBUG[3962]: chan_sip.c:3389 parse_request: Line: a=direction:active (18) Aug 2 18:23:42 DEBUG[3962]: chan_sip.c:3389 parse_request: Line: m=audio 49158 RTP/AVP 3 97 98 8 0 101 (37) Aug 2 18:23:42 DEBUG[3962]: chan_sip.c:3389 parse_request: Line: a=rtpmap:3 GSM/8000 (19) Aug 2 18:23:42 DEBUG[3962]: chan_sip.c:3389 parse_request: Line: a=rtpmap:97 iLBC/8000 (21) Aug 2 18:23:42 DEBUG[3962]: chan_sip.c:3389 parse_request: Line: a=rtpmap:98 iLBC/8000 (21) Aug 2 18:23:42 DEBUG[3962]: chan_sip.c:3389 parse_request: Line: a=fmtp:98 mode=20 (17) Aug 2 18:23:42 DEBUG[3962]: chan_sip.c:3389 parse_request: Line: a=rtpmap:8 PCMA/8000 (20) Aug 2 18:23:42 DEBUG[3962]: chan_sip.c:3389 parse_request: Line: a=rtpmap:0 PCMU/8000 (20) Aug 2 18:23:42 DEBUG[3962]: chan_sip.c:3389 parse_request: Line: a=rtpmap:101 telephone-event/8000 (33) Aug 2 18:23:42 DEBUG[3962]: chan_sip.c:3389 parse_request: Line: a=fmtp:101 0-11,16 (18) --- (12 headers 15 lines)--- Aug 2 18:23:42 DEBUG[3962]: chan_sip.c:11139 handle_request: **** Received INVITE (5) - Command in SIP INVITE Using INVITE request as basis request - EC3876C9-D5F6-4AE9-B0E7-5B41CCA10C83@10.2.6.252 Sending to 10.2.6.252 : 5060 (NAT) Aug 2 18:23:42 DEBUG[3962]: chan_sip.c:7149 check_user_full: Setting NAT on RTP to 0 Aug 2 18:23:42 DEBUG[3962]: chan_sip.c:7153 check_user_full: Setting NAT on VRTP to 0 Found user '803' Found RTP audio format 3 Found RTP audio format 97 Found RTP audio format 98 Found RTP audio format 8 Found RTP audio format 0 Found RTP audio format 101 Peer audio RTP is at port 10.2.6.252:49158 Aug 2 18:23:42 DEBUG[3962]: chan_sip.c:3598 process_sdp: Peer audio RTP is at port 10.2.6.252:49158 Peer video RTP is at port 10.2.6.252:65535 Aug 2 18:23:42 DEBUG[3962]: chan_sip.c:3622 process_sdp: Peer video RTP is at port 10.2.6.252:65535 Found description format GSM Found description format iLBC Found description format iLBC Found description format PCMA Found description format PCMU Found description format telephone-event Capabilities: us - 0x1c0406 (gsm|ulaw|ilbc|h261|h263|h263p), peer - audio=0x40e (gsm|ulaw|alaw|ilbc)/video=0x0 (nothing), combined - 0x406 (gsm|ulaw|ilbc) Non-codec capabilities: us - 0x1 (telephone-event), peer - 0x1 (telephone-event), combined - 0x1 (telephone-event) Aug 2 18:23:42 DEBUG[3962]: chan_sip.c:10496 handle_request_invite: Checking SIP call limits for device 803 Aug 2 18:23:42 DEBUG[3962]: chan_sip.c:2206 update_call_counter: Updating call counter for incoming call Looking for 195 in usr_11_ctx (domain 10.0.90.187) Aug 2 18:23:42 DEBUG[3962]: res_config_mysql.c:125 realtime_mysql: MySQL RealTime: Retrieve SQL: SELECT * FROM realtime_ext WHERE exten = '195' AND context = 'user' AND priority = '1' Aug 2 18:23:42 DEBUG[3962]: res_config_mysql.c:636 mysql_reconnect: MySQL RealTime: Everything is fine. Aug 2 18:23:42 DEBUG[3962]: res_config_mysql.c:237 realtime_multi_mysql: MySQL RealTime: Retrieve SQL: SELECT * FROM realtime_ext WHERE exten LIKE '\_%' AND context = 'user' AND priority = '1' ORDER BY exten Aug 2 18:23:42 DEBUG[3962]: res_config_mysql.c:636 mysql_reconnect: MySQL RealTime: Everything is fine. Aug 2 18:23:42 DEBUG[3962]: res_config_mysql.c:125 realtime_mysql: MySQL RealTime: Retrieve SQL: SELECT * FROM realtime_ext WHERE exten = '195' AND context = 'phone' AND priority = '1' Aug 2 18:23:42 DEBUG[3962]: res_config_mysql.c:636 mysql_reconnect: MySQL RealTime: Everything is fine. Aug 2 18:23:42 DEBUG[3962]: res_config_mysql.c:237 realtime_multi_mysql: MySQL RealTime: Retrieve SQL: SELECT * FROM realtime_ext WHERE exten LIKE '\_%' AND context = 'phone' AND priority = '1' ORDER BY exten Aug 2 18:23:42 DEBUG[3962]: res_config_mysql.c:636 mysql_reconnect: MySQL RealTime: Everything is fine. Aug 2 18:23:42 DEBUG[3962]: res_config_mysql.c:125 realtime_mysql: MySQL RealTime: Retrieve SQL: SELECT * FROM realtime_ext WHERE exten = '195' AND context = 'group' AND priority = '1' Aug 2 18:23:42 DEBUG[3962]: res_config_mysql.c:636 mysql_reconnect: MySQL RealTime: Everything is fine. Aug 2 18:23:42 DEBUG[3962]: res_config_mysql.c:237 realtime_multi_mysql: MySQL RealTime: Retrieve SQL: SELECT * FROM realtime_ext WHERE exten LIKE '\_%' AND context = 'group' AND priority = '1' ORDER BY exten Aug 2 18:23:42 DEBUG[3962]: res_config_mysql.c:636 mysql_reconnect: MySQL RealTime: Everything is fine. Aug 2 18:23:42 DEBUG[3962]: res_config_mysql.c:125 realtime_mysql: MySQL RealTime: Retrieve SQL: SELECT * FROM realtime_ext WHERE exten = '195' AND context = 'service' AND priority = '1' Aug 2 18:23:42 DEBUG[3962]: res_config_mysql.c:636 mysql_reconnect: MySQL RealTime: Everything is fine. Aug 2 18:23:42 DEBUG[3962]: res_config_mysql.c:237 realtime_multi_mysql: MySQL RealTime: Retrieve SQL: SELECT * FROM realtime_ext WHERE exten LIKE '\_%' AND context = 'service' AND priority = '1' ORDER BY exten Aug 2 18:23:42 DEBUG[3962]: res_config_mysql.c:636 mysql_reconnect: MySQL RealTime: Everything is fine. Aug 2 18:23:42 DEBUG[3962]: res_config_mysql.c:125 realtime_mysql: MySQL RealTime: Retrieve SQL: SELECT * FROM realtime_ext WHERE exten = '195' AND context = 'did' AND priority = '1' Aug 2 18:23:42 DEBUG[3962]: res_config_mysql.c:636 mysql_reconnect: MySQL RealTime: Everything is fine. Aug 2 18:23:42 DEBUG[3962]: res_config_mysql.c:237 realtime_multi_mysql: MySQL RealTime: Retrieve SQL: SELECT * FROM realtime_ext WHERE exten LIKE '\_%' AND context = 'did' AND priority = '1' ORDER BY exten Aug 2 18:23:42 DEBUG[3962]: res_config_mysql.c:636 mysql_reconnect: MySQL RealTime: Everything is fine. Aug 2 18:23:42 DEBUG[3962]: chan_sip.c:6131 build_route: build_route: Contact hop: list_route: hop: Transmitting (no NAT) to 10.2.6.252:5060: SIP/2.0 100 Trying Via: SIP/2.0/UDP 10.2.6.252;rport;branch=z9hG4bK0a0206fc0000003944d0d1c10000231000000073;received=10.2.6.252 From: "unknown";tag=79254603128430 To: Call-ID: EC3876C9-D5F6-4AE9-B0E7-5B41CCA10C83@10.2.6.252 CSeq: 2 INVITE User-Agent: Diptel-T50 llow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY Contact: Content-Length: 0 --- Aug 2 18:23:42 DEBUG[3956]: chan_sip.c:11670 sip_devicestate: Checking device state for peer 803 Aug 2 18:23:42 DEBUG[3956]: channel.c:777 channel_find_locked: Avoiding initial deadlock for 'SIP/803-081a7998' Aug 2 18:23:42 DEBUG[4337]: res_config_mysql.c:125 realtime_mysql: MySQL RealTime: Retrieve SQL: SELECT * FROM realtime_ext WHERE exten = '195' AND context = 'user' AND priority = '1' Aug 2 18:23:42 DEBUG[4337]: res_config_mysql.c:636 mysql_reconnect: MySQL RealTime: Everything is fine. Aug 2 18:23:42 DEBUG[4337]: res_config_mysql.c:237 realtime_multi_mysql: MySQL RealTime: Retrieve SQL: SELECT * FROM realtime_ext WHERE exten LIKE '\_%' AND context = 'user' AND priority = '1' ORDER BY exten Aug 2 18:23:42 DEBUG[4337]: res_config_mysql.c:636 mysql_reconnect: MySQL RealTime: Everything is fine. Aug 2 18:23:42 DEBUG[4337]: res_config_mysql.c:125 realtime_mysql: MySQL RealTime: Retrieve SQL: SELECT * FROM realtime_ext WHERE exten = '195' AND context = 'phone' AND priority = '1' Aug 2 18:23:42 DEBUG[4337]: res_config_mysql.c:636 mysql_reconnect: MySQL RealTime: Everything is fine. Aug 2 18:23:42 DEBUG[4337]: res_config_mysql.c:237 realtime_multi_mysql: MySQL RealTime: Retrieve SQL: SELECT * FROM realtime_ext WHERE exten LIKE '\_%' AND context = 'phone' AND priority = '1' ORDER BY exten Aug 2 18:23:42 DEBUG[4337]: res_config_mysql.c:636 mysql_reconnect: MySQL RealTime: Everything is fine. Aug 2 18:23:42 DEBUG[4337]: res_config_mysql.c:125 realtime_mysql: MySQL RealTime: Retrieve SQL: SELECT * FROM realtime_ext WHERE exten = '195' AND context = 'group' AND priority = '1' Aug 2 18:23:42 DEBUG[4337]: res_config_mysql.c:636 mysql_reconnect: MySQL RealTime: Everything is fine. Aug 2 18:23:42 DEBUG[4337]: res_config_mysql.c:237 realtime_multi_mysql: MySQL RealTime: Retrieve SQL: SELECT * FROM realtime_ext WHERE exten LIKE '\_%' AND context = 'group' AND priority = '1' ORDER BY exten Aug 2 18:23:42 DEBUG[4337]: res_config_mysql.c:636 mysql_reconnect: MySQL RealTime: Everything is fine. Aug 2 18:23:42 DEBUG[4337]: res_config_mysql.c:125 realtime_mysql: MySQL RealTime: Retrieve SQL: SELECT * FROM realtime_ext WHERE exten = '195' AND context = 'service' AND priority = '1' Aug 2 18:23:42 DEBUG[4337]: res_config_mysql.c:636 mysql_reconnect: MySQL RealTime: Everything is fine. Aug 2 18:23:42 DEBUG[4337]: res_config_mysql.c:237 realtime_multi_mysql: MySQL RealTime: Retrieve SQL: SELECT * FROM realtime_ext WHERE exten LIKE '\_%' AND context = 'service' AND priority = '1' ORDER BY exten Aug 2 18:23:42 DEBUG[3956]: devicestate.c:187 do_state_change: Changing state for SIP/803 - state 2 (In use) Aug 2 18:23:42 DEBUG[4338]: app_queue.c:490 changethread: Device 'SIP/803' changed to state '2' (In use) but we don't care because they're not a member of any queue. Aug 2 18:23:42 DEBUG[4337]: res_config_mysql.c:636 mysql_reconnect: MySQL RealTime: Everything is fine. Aug 2 18:23:42 DEBUG[4337]: res_config_mysql.c:125 realtime_mysql: MySQL RealTime: Retrieve SQL: SELECT * FROM realtime_ext WHERE exten = '195' AND context = 'did' AND priority = '1' Aug 2 18:23:42 DEBUG[4337]: res_config_mysql.c:636 mysql_reconnect: MySQL RealTime: Everything is fine. Aug 2 18:23:42 DEBUG[4337]: res_config_mysql.c:237 realtime_multi_mysql: MySQL RealTime: Retrieve SQL: SELECT * FROM realtime_ext WHERE exten LIKE '\_%' AND context = 'did' AND priority = '1' ORDER BY exten Aug 2 18:23:42 DEBUG[4337]: res_config_mysql.c:636 mysql_reconnect: MySQL RealTime: Everything is fine. Aug 2 18:23:42 DEBUG[4337]: res_config_mysql.c:125 realtime_mysql: MySQL RealTime: Retrieve SQL: SELECT * FROM realtime_ext WHERE exten = '195' AND context = 'user' AND priority = '1' Aug 2 18:23:42 DEBUG[4337]: res_config_mysql.c:636 mysql_reconnect: MySQL RealTime: Everything is fine. Aug 2 18:23:42 DEBUG[4337]: res_config_mysql.c:237 realtime_multi_mysql: MySQL RealTime: Retrieve SQL: SELECT * FROM realtime_ext WHERE exten LIKE '\_%' AND context = 'user' AND priority = '1' ORDER BY exten Aug 2 18:23:42 DEBUG[4337]: res_config_mysql.c:636 mysql_reconnect: MySQL RealTime: Everything is fine. Aug 2 18:23:42 DEBUG[4337]: res_config_mysql.c:125 realtime_mysql: MySQL RealTime: Retrieve SQL: SELECT * FROM realtime_ext WHERE exten = '195' AND context = 'phone' AND priority = '1' Aug 2 18:23:42 DEBUG[4337]: res_config_mysql.c:636 mysql_reconnect: MySQL RealTime: Everything is fine. Aug 2 18:23:42 DEBUG[4337]: res_config_mysql.c:237 realtime_multi_mysql: MySQL RealTime: Retrieve SQL: SELECT * FROM realtime_ext WHERE exten LIKE '\_%' AND context = 'phone' AND priority = '1' ORDER BY exten Aug 2 18:23:42 DEBUG[4337]: res_config_mysql.c:636 mysql_reconnect: MySQL RealTime: Everything is fine. Aug 2 18:23:42 DEBUG[4337]: res_config_mysql.c:125 realtime_mysql: MySQL RealTime: Retrieve SQL: SELECT * FROM realtime_ext WHERE exten = '195' AND context = 'group' AND priority = '1' Aug 2 18:23:42 DEBUG[4337]: res_config_mysql.c:636 mysql_reconnect: MySQL RealTime: Everything is fine. Aug 2 18:23:42 DEBUG[4337]: res_config_mysql.c:237 realtime_multi_mysql: MySQL RealTime: Retrieve SQL: SELECT * FROM realtime_ext WHERE exten LIKE '\_%' AND context = 'group' AND priority = '1' ORDER BY exten Aug 2 18:23:42 DEBUG[4337]: res_config_mysql.c:636 mysql_reconnect: MySQL RealTime: Everything is fine. Aug 2 18:23:42 DEBUG[4337]: res_config_mysql.c:125 realtime_mysql: MySQL RealTime: Retrieve SQL: SELECT * FROM realtime_ext WHERE exten = '195' AND context = 'service' AND priority = '1' Aug 2 18:23:42 DEBUG[4337]: res_config_mysql.c:636 mysql_reconnect: MySQL RealTime: Everything is fine. Aug 2 18:23:42 DEBUG[4337]: res_config_mysql.c:237 realtime_multi_mysql: MySQL RealTime: Retrieve SQL: SELECT * FROM realtime_ext WHERE exten LIKE '\_%' AND context = 'service' AND priority = '1' ORDER BY exten Aug 2 18:23:42 DEBUG[4337]: res_config_mysql.c:636 mysql_reconnect: MySQL RealTime: Everything is fine. Aug 2 18:23:42 DEBUG[4337]: res_config_mysql.c:125 realtime_mysql: MySQL RealTime: Retrieve SQL: SELECT * FROM realtime_ext WHERE exten = '195' AND context = 'did' AND priority = '1' Aug 2 18:23:42 DEBUG[4337]: res_config_mysql.c:636 mysql_reconnect: MySQL RealTime: Everything is fine. Aug 2 18:23:42 DEBUG[4337]: res_config_mysql.c:237 realtime_multi_mysql: MySQL RealTime: Retrieve SQL: SELECT * FROM realtime_ext WHERE exten LIKE '\_%' AND context = 'did' AND priority = '1' ORDER BY exten Aug 2 18:23:42 DEBUG[4337]: res_config_mysql.c:636 mysql_reconnect: MySQL RealTime: Everything is fine. Aug 2 18:23:42 DEBUG[4337]: res_config_mysql.c:125 realtime_mysql: MySQL RealTime: Retrieve SQL: SELECT * FROM realtime_ext WHERE exten = '195' AND context = 'user' AND priority = '1' Aug 2 18:23:42 DEBUG[4337]: res_config_mysql.c:636 mysql_reconnect: MySQL RealTime: Everything is fine. Aug 2 18:23:42 DEBUG[4337]: res_config_mysql.c:237 realtime_multi_mysql: MySQL RealTime: Retrieve SQL: SELECT * FROM realtime_ext WHERE exten LIKE '\_%' AND context = 'user' AND priority = '1' ORDER BY exten Aug 2 18:23:42 DEBUG[4337]: res_config_mysql.c:636 mysql_reconnect: MySQL RealTime: Everything is fine. Aug 2 18:23:42 DEBUG[4337]: res_config_mysql.c:125 realtime_mysql: MySQL RealTime: Retrieve SQL: SELECT * FROM realtime_ext WHERE exten = '195' AND context = 'phone' AND priority = '1' Aug 2 18:23:42 DEBUG[4337]: res_config_mysql.c:636 mysql_reconnect: MySQL RealTime: Everything is fine. Aug 2 18:23:42 DEBUG[4337]: res_config_mysql.c:237 realtime_multi_mysql: MySQL RealTime: Retrieve SQL: SELECT * FROM realtime_ext WHERE exten LIKE '\_%' AND context = 'phone' AND priority = '1' ORDER BY exten Aug 2 18:23:42 DEBUG[4337]: res_config_mysql.c:636 mysql_reconnect: MySQL RealTime: Everything is fine. Aug 2 18:23:42 DEBUG[4337]: res_config_mysql.c:125 realtime_mysql: MySQL RealTime: Retrieve SQL: SELECT * FROM realtime_ext WHERE exten = '195' AND context = 'group' AND priority = '1' Aug 2 18:23:42 DEBUG[4337]: res_config_mysql.c:636 mysql_reconnect: MySQL RealTime: Everything is fine. Aug 2 18:23:42 DEBUG[4337]: res_config_mysql.c:237 realtime_multi_mysql: MySQL RealTime: Retrieve SQL: SELECT * FROM realtime_ext WHERE exten LIKE '\_%' AND context = 'group' AND priority = '1' ORDER BY exten Aug 2 18:23:42 DEBUG[4337]: res_config_mysql.c:636 mysql_reconnect: MySQL RealTime: Everything is fine. Aug 2 18:23:42 DEBUG[4337]: res_config_mysql.c:125 realtime_mysql: MySQL RealTime: Retrieve SQL: SELECT * FROM realtime_ext WHERE exten = '195' AND context = 'service' AND priority = '1' Aug 2 18:23:42 DEBUG[4337]: res_config_mysql.c:636 mysql_reconnect: MySQL RealTime: Everything is fine. Aug 2 18:23:42 DEBUG[4337]: res_config_mysql.c:237 realtime_multi_mysql: MySQL RealTime: Retrieve SQL: SELECT * FROM realtime_ext WHERE exten LIKE '\_%' AND context = 'service' AND priority = '1' ORDER BY exten Aug 2 18:23:42 DEBUG[4337]: res_config_mysql.c:636 mysql_reconnect: MySQL RealTime: Everything is fine. Aug 2 18:23:42 DEBUG[4337]: res_config_mysql.c:125 realtime_mysql: MySQL RealTime: Retrieve SQL: SELECT * FROM realtime_ext WHERE exten = '195' AND context = 'did' AND priority = '1' Aug 2 18:23:42 DEBUG[4337]: res_config_mysql.c:636 mysql_reconnect: MySQL RealTime: Everything is fine. Aug 2 18:23:42 DEBUG[4337]: res_config_mysql.c:237 realtime_multi_mysql: MySQL RealTime: Retrieve SQL: SELECT * FROM realtime_ext WHERE exten LIKE '\_%' AND context = 'did' AND priority = '1' ORDER BY exten Aug 2 18:23:42 DEBUG[4337]: res_config_mysql.c:636 mysql_reconnect: MySQL RealTime: Everything is fine. Aug 2 18:23:42 DEBUG[4337]: pbx.c:1677 pbx_extension_helper: Launching 'Macro' -- Executing Macro("SIP/803-081a7998", "c_pstn|21568690|Voop50294|Voop50294|IAX2") in new stack Aug 2 18:23:42 DEBUG[4337]: pbx.c:1677 pbx_extension_helper: Launching 'Answer' -- Executing Answer("SIP/803-081a7998", "") in new stack Aug 2 18:23:42 DEBUG[3956]: chan_sip.c:11670 sip_devicestate: Checking device state for peer 803 Aug 2 18:23:42 DEBUG[3956]: channel.c:777 channel_find_locked: Avoiding initial deadlock for 'SIP/803-081a7998' Aug 2 18:23:42 DEBUG[4337]: chan_sip.c:2537 sip_answer: sip_answer(SIP/803-081a7998) We're at 10.0.90.187 port 10360 Video is at 10.0.90.187 port 14198 Adding codec 0x4 (ulaw) to SDP Adding codec 0x2 (gsm) to SDP Adding codec 0x400 (ilbc) to SDP Adding non-codec 0x1 (telephone-event) to SDP Reliably Transmitting (no NAT) to 10.2.6.252:5060: SIP/2.0 200 OK Via: SIP/2.0/UDP 10.2.6.252;rport;branch=z9hG4bK0a0206fc0000003944d0d1c10000231000000073;received=10.2.6.252 rom: "unknown";tag=79254603128430 To: ;tag=as2b87f8b9 Call-ID: EC3876C9-D5F6-4AE9-B0E7-5B41CCA10C83@10.2.6.252 CSeq: 2 INVITE User-Agent: Diptel-T50 Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY Contact: Content-Type: application/sdp Content-Length: 261 v=0 o=root 3952 3952 IN IP4 10.0.90.187 s=session c=IN IP4 10.0.90.187 t=0 0 m=audio 10360 RTP/AVP 0 3 97 101 a=rtpmap:0 PCMU/8000 a=rtpmap:3 GSM/8000 a=rtpmap:97 iLBC/8000 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-16 a=silenceSupp:off - - - - --- Aug 2 18:23:42 DEBUG[4337]: chan_sip.c:1293 __sip_reliable_xmit: *** SIP TIMER: Initalizing retransmit timer on packet: Id #39 Aug 2 18:23:42 DEBUG[4337]: pbx.c:1677 pbx_extension_helper: Launching 'NoOp' -- Executing NoOp("SIP/803-081a7998", ""Calling: 195 from 21568690 (IAX2/Voop50294@Voop50294)"") in new stack Aug 2 18:23:42 DEBUG[4337]: pbx.c:1677 pbx_extension_helper: Launching 'SetCallerID' -- Executing SetCallerID("SIP/803-081a7998", "21568690") in new stack Aug 2 18:23:42 DEBUG[4337]: pbx.c:1677 pbx_extension_helper: Launching 'Dial' -- Executing Dial("SIP/803-081a7998", "IAX2/Voop50294@Voop50294/195|120|T") in new stack Aug 2 18:23:42 DEBUG[4337]: channel.c:2856 ast_channel_inherit_variables: Not copying variable STACK-macro-c_pstn-s-4. Aug 2 18:23:42 DEBUG[4337]: channel.c:2856 ast_channel_inherit_variables: Not copying variable MACRO_DEPTH. Aug 2 18:23:42 DEBUG[4337]: channel.c:2856 ast_channel_inherit_variables: Not copying variable STACK-macro-c_pstn-s-3. Aug 2 18:23:42 DEBUG[4337]: channel.c:2856 ast_channel_inherit_variables: Not copying variable STACK-macro-c_pstn-s-2. Aug 2 18:23:42 DEBUG[4337]: channel.c:2856 ast_channel_inherit_variables: Not copying variable STACK-macro-c_pstn-s-1. Aug 2 18:23:42 DEBUG[4337]: channel.c:2856 ast_channel_inherit_variables: Not copying variable ARG4. Aug 2 18:23:42 DEBUG[4337]: channel.c:2856 ast_channel_inherit_variables: Not copying variable ARG3. Aug 2 18:23:42 DEBUG[4337]: channel.c:2856 ast_channel_inherit_variables: Not copying variable ARG2. Aug 2 18:23:42 DEBUG[4337]: channel.c:2856 ast_channel_inherit_variables: Not copying variable ARG1. Aug 2 18:23:42 DEBUG[4337]: channel.c:2856 ast_channel_inherit_variables: Not copying variable MACRO_PRIORITY. Aug 2 18:23:42 DEBUG[4337]: channel.c:2856 ast_channel_inherit_variables: Not copying variable MACRO_CONTEXT. Aug 2 18:23:42 DEBUG[4337]: channel.c:2856 ast_channel_inherit_variables: Not copying variable MACRO_EXTEN. Aug 2 18:23:42 DEBUG[4337]: channel.c:2856 ast_channel_inherit_variables: Not copying variable STACK-usr_11_ctx-195-1. Aug 2 18:23:42 DEBUG[4337]: channel.c:2856 ast_channel_inherit_variables: Not copying variable SIPCALLID. Aug 2 18:23:42 DEBUG[4337]: channel.c:2856 ast_channel_inherit_variables: Not copying variable SIPUSERAGENT. Aug 2 18:23:42 DEBUG[4337]: channel.c:2856 ast_channel_inherit_variables: Not copying variable SIPDOMAIN. Aug 2 18:23:42 DEBUG[4337]: channel.c:2856 ast_channel_inherit_variables: Not copying variable SIPURI. -- Called Voop50294@Voop50294/195 Aug 2 18:23:42 DEBUG[4337]: res_config_mysql.c:125 realtime_mysql: MySQL RealTime: Retrieve SQL: SELECT * FROM realtime_ext WHERE exten = '195' AND context = 'user' AND priority = '-1' ubuntu-test-1*CLI> <-- SIP read from 10.2.6.252:5060: ACK sip:195@10.0.90.187 SIP/2.0 Via: SIP/2.0/UDP 10.2.6.252;rport;branch=z9hG4bK0a0206fc0000003944d0d1c10000175100000076 Content-Length: 0 Call-ID: EC3876C9-D5F6-4AE9-B0E7-5B41CCA10C83@10.2.6.252 CSeq: 2 ACK From: "unknown";tag=79254603128430 Max-Forwards: 70 To: ;tag=as2b87f8b9 User-Agent: SJphone/1.60.289a (SJ Labs) Aug 2 18:23:42 DEBUG[3962]: chan_sip.c:3357 parse_request: Header 0: ACK sip:195@10.0.90.187 SIP/2.0 (31) Aug 2 18:23:42 DEBUG[3962]: chan_sip.c:3357 parse_request: Header 1: Via: SIP/2.0/UDP 10.2.6.252;rport;branch=z9hG4bK0a0206fc0000003944d0d1c10000175100000076 (88) Aug 2 18:23:42 DEBUG[3962]: chan_sip.c:3357 parse_request: Header 2: Content-Length: 0 (17) Aug 2 18:23:42 DEBUG[3962]: chan_sip.c:3357 parse_request: Header 3: Call-ID: EC3876C9-D5F6-4AE9-B0E7-5B41CCA10C83@10.2.6.252 (56) Aug 2 18:23:42 DEBUG[3962]: chan_sip.c:3357 parse_request: Header 4: CSeq: 2 ACK (11) Aug 2 18:23:42 DEBUG[3962]: chan_sip.c:3357 parse_request: Header 5: From: "unknown";tag=79254603128430 (55) Aug 2 18:23:42 DEBUG[3962]: chan_sip.c:3357 parse_request: Header 6: Max-Forwards: 70 (16) Aug 2 18:23:42 DEBUG[3962]: chan_sip.c:3357 parse_request: Header 7: To: ;tag=as2b87f8b9 (40) Aug 2 18:23:42 DEBUG[3962]: chan_sip.c:3357 parse_request: Header 8: User-Agent: SJphone/1.60.289a (SJ Labs) (39) Aug 2 18:23:42 DEBUG[3962]: chan_sip.c:3357 parse_request: Header 9: (0) --- (9 headers 0 lines)--- Aug 2 18:23:42 DEBUG[3962]: chan_sip.c:11139 handle_request: **** Received ACK (6) - Command in SIP ACK Aug 2 18:23:42 DEBUG[3962]: chan_sip.c:1390 __sip_ack: ** SIP TIMER: Cancelling retransmit of packet (reply received) Retransid #39 Aug 2 18:23:42 DEBUG[3962]: chan_sip.c:1401 __sip_ack: Stopping retransmission on 'EC3876C9-D5F6-4AE9-B0E7-5B41CCA10C83@10.2.6.252' of Response 2: Match Found Aug 2 18:23:42 DEBUG[4337]: res_config_mysql.c:636 mysql_reconnect: MySQL RealTime: Everything is fine. Aug 2 18:23:42 DEBUG[4337]: res_config_mysql.c:237 realtime_multi_mysql: MySQL RealTime: Retrieve SQL: SELECT * FROM realtime_ext WHERE exten LIKE '\_%' AND context = 'user' AND priority = '-1' ORDER BY exten Aug 2 18:23:42 DEBUG[4337]: res_config_mysql.c:636 mysql_reconnect: MySQL RealTime: Everything is fine. Aug 2 18:23:42 DEBUG[4337]: res_config_mysql.c:125 realtime_mysql: MySQL RealTime: Retrieve SQL: SELECT * FROM realtime_ext WHERE exten = '195' AND context = 'phone' AND priority = '-1' Aug 2 18:23:42 DEBUG[4337]: res_config_mysql.c:636 mysql_reconnect: MySQL RealTime: Everything is fine. Aug 2 18:23:42 DEBUG[4337]: res_config_mysql.c:237 realtime_multi_mysql: MySQL RealTime: Retrieve SQL: SELECT * FROM realtime_ext WHERE exten LIKE '\_%' AND context = 'phone' AND priority = '-1' ORDER BY exten Aug 2 18:23:42 DEBUG[4337]: res_config_mysql.c:636 mysql_reconnect: MySQL RealTime: Everything is fine. Aug 2 18:23:42 DEBUG[4337]: res_config_mysql.c:125 realtime_mysql: MySQL RealTime: Retrieve SQL: SELECT * FROM realtime_ext WHERE exten = '195' AND context = 'group' AND priority = '-1' Aug 2 18:23:42 DEBUG[4337]: res_config_mysql.c:636 mysql_reconnect: MySQL RealTime: Everything is fine. Aug 2 18:23:42 DEBUG[3956]: devicestate.c:187 do_state_change: Changing state for SIP/803 - state 2 (In use) Aug 2 18:23:42 DEBUG[4337]: res_config_mysql.c:237 realtime_multi_mysql: MySQL RealTime: Retrieve SQL: SELECT * FROM realtime_ext WHERE exten LIKE '\_%' AND context = 'group' AND priority = '-1' ORDER BY exten Aug 2 18:23:42 DEBUG[3956]: chan_iax2.c:9416 iax2_devicestate: Checking device state for device Voop50294 Aug 2 18:23:42 DEBUG[3956]: chan_iax2.c:9424 iax2_devicestate: iax2_devicestate: Found peer. What's device state of Voop50294? addr=2120478544, defaddr=0 maxms=2000, lastms=16 Aug 2 18:23:42 DEBUG[3956]: devicestate.c:187 do_state_change: Changing state for IAX2/Voop50294 - state 6 (Ringing) Aug 2 18:23:42 DEBUG[4337]: res_config_mysql.c:636 mysql_reconnect: MySQL RealTime: Everything is fine. Aug 2 18:23:42 DEBUG[4340]: app_queue.c:490 changethread: Device 'IAX2/Voop50294' changed to state '6' (Ringing) but we don't care because they're not a member of any queue. Aug 2 18:23:42 DEBUG[4339]: app_queue.c:490 changethread: Device 'SIP/803' changed to state '2' (In use) but we don't care because they're not a member of any queue. Aug 2 18:23:42 DEBUG[4337]: res_config_mysql.c:125 realtime_mysql: MySQL RealTime: Retrieve SQL: SELECT * FROM realtime_ext WHERE exten = '195' AND context = 'service' AND priority = '-1' Aug 2 18:23:42 DEBUG[4337]: res_config_mysql.c:636 mysql_reconnect: MySQL RealTime: Everything is fine. Aug 2 18:23:42 DEBUG[4337]: res_config_mysql.c:237 realtime_multi_mysql: MySQL RealTime: Retrieve SQL: SELECT * FROM realtime_ext WHERE exten LIKE '\_%' AND context = 'service' AND priority = '-1' ORDER BY exten Aug 2 18:23:42 DEBUG[4337]: res_config_mysql.c:636 mysql_reconnect: MySQL RealTime: Everything is fine. Aug 2 18:23:42 DEBUG[4337]: res_config_mysql.c:125 realtime_mysql: MySQL RealTime: Retrieve SQL: SELECT * FROM realtime_ext WHERE exten = '195' AND context = 'did' AND priority = '-1' Aug 2 18:23:42 DEBUG[4337]: res_config_mysql.c:636 mysql_reconnect: MySQL RealTime: Everything is fine. Aug 2 18:23:42 DEBUG[4337]: res_config_mysql.c:237 realtime_multi_mysql: MySQL RealTime: Retrieve SQL: SELECT * FROM realtime_ext WHERE exten LIKE '\_%' AND context = 'did' AND priority = '-1' ORDER BY exten Aug 2 18:23:42 DEBUG[4337]: res_config_mysql.c:636 mysql_reconnect: MySQL RealTime: Everything is fine. Aug 2 18:23:42 DEBUG[4337]: channel.c:2363 set_format: Set channel IAX2/Voop50294-2 to read format ulaw Aug 2 18:23:42 DEBUG[4337]: channel.c:2363 set_format: Set channel SIP/803-081a7998 to write format ulaw Aug 2 18:23:42 DEBUG[4337]: channel.c:2363 set_format: Set channel SIP/803-081a7998 to read format ulaw Aug 2 18:23:42 DEBUG[4337]: channel.c:2363 set_format: Set channel IAX2/Voop50294-2 to write format ulaw -- Call accepted by 80.239.99.126 (format ulaw) -- Format for call is ulaw Aug 2 18:23:42 DEBUG[3964]: channel.c:2363 set_format: Set channel IAX2/Voop50294-2 to write format ulaw Aug 2 18:23:42 DEBUG[3964]: channel.c:2363 set_format: Set channel IAX2/Voop50294-2 to read format ulaw -- IAX2/Voop50294-2 answered SIP/803-081a7998 Aug 2 18:23:42 DEBUG[3956]: chan_iax2.c:9416 iax2_devicestate: Checking device state for device Voop50294 Aug 2 18:23:42 DEBUG[3956]: chan_iax2.c:9424 iax2_devicestate: iax2_devicestate: Found peer. What's device state of Voop50294? addr=2120478544, defaddr=0 maxms=2000, lastms=16 Aug 2 18:23:42 DEBUG[3956]: devicestate.c:187 do_state_change: Changing state for IAX2/Voop50294 - state 2 (In use) Aug 2 18:23:42 DEBUG[4337]: channel.c:2363 set_format: Set channel SIP/803-081a7998 to read format ulaw Aug 2 18:23:42 DEBUG[4337]: channel.c:2363 set_format: Set channel IAX2/Voop50294-2 to write format ulaw Aug 2 18:23:42 DEBUG[4337]: channel.c:2363 set_format: Set channel IAX2/Voop50294-2 to read format ulaw Aug 2 18:23:42 DEBUG[4337]: channel.c:2363 set_format: Set channel SIP/803-081a7998 to write format ulaw Aug 2 18:23:42 DEBUG[4341]: app_queue.c:490 changethread: Device 'IAX2/Voop50294' changed to state '2' (In use) but we don't care because they're not a member of any queue. Aug 2 18:23:42 DEBUG[3964]: chan_iax2.c:6756 socket_read: Ooh, voice format changed to 4 Aug 2 18:23:42 DEBUG[3964]: channel.c:2363 set_format: Set channel IAX2/Voop50294-2 to read format ulaw Aug 2 18:23:42 DEBUG[4337]: rtp.c:1353 ast_rtp_write: Ooh, format changed from unknown to ulaw Aug 2 18:23:42 DEBUG[3964]: chan_iax2.c:6508 socket_read: For call=2, set last=64 Aug 2 18:23:42 DEBUG[3964]: chan_iax2.c:6508 socket_read: For call=2, set last=84 Aug 2 18:23:42 DEBUG[3964]: chan_iax2.c:6508 socket_read: For call=2, set last=104 Aug 2 18:23:42 DEBUG[3964]: chan_iax2.c:6508 socket_read: For call=2, set last=124 Aug 2 18:23:42 DEBUG[3964]: chan_iax2.c:6508 socket_read: For call=2, set last=144 Aug 2 18:23:42 DEBUG[3964]: chan_iax2.c:6508 socket_read: For call=2, set last=164 Aug 2 18:23:42 DEBUG[3964]: chan_iax2.c:6508 socket_read: For call=2, set last=184 Aug 2 18:23:42 DEBUG[3964]: chan_iax2.c:6508 socket_read: For call=2, set last=204 Aug 2 18:23:42 DEBUG[3964]: chan_iax2.c:6508 socket_read: For call=2, set last=224 Aug 2 18:23:42 DEBUG[3964]: chan_iax2.c:6508 socket_read: For call=2, set last=244 Aug 2 18:23:42 DEBUG[3964]: chan_iax2.c:6508 socket_read: For call=2, set last=264 Aug 2 18:23:42 DEBUG[3964]: chan_iax2.c:6508 socket_read: For call=2, set last=284 Aug 2 18:23:42 DEBUG[3964]: chan_iax2.c:6508 socket_read: For call=2, set last=304 Aug 2 18:23:42 DEBUG[3964]: chan_iax2.c:6508 socket_read: For call=2, set last=324 Aug 2 18:23:42 DEBUG[3964]: chan_iax2.c:6508 socket_read: For call=2, set last=344 Aug 2 18:23:42 DEBUG[3964]: chan_iax2.c:6508 socket_read: For call=2, set last=364 Aug 2 18:23:42 DEBUG[3964]: chan_iax2.c:6508 socket_read: For call=2, set last=384 Aug 2 18:23:42 DEBUG[3964]: chan_iax2.c:6508 socket_read: For call=2, set last=404 Aug 2 18:23:42 DEBUG[3964]: chan_iax2.c:6508 socket_read: For call=2, set last=424 Aug 2 18:23:42 DEBUG[3964]: chan_iax2.c:6508 socket_read: For call=2, set last=444 Aug 2 18:23:42 DEBUG[3964]: chan_iax2.c:6508 socket_read: For call=2, set last=464 Aug 2 18:23:42 DEBUG[3964]: chan_iax2.c:6508 socket_read: For call=2, set last=484 Aug 2 18:23:42 DEBUG[3964]: chan_iax2.c:6508 socket_read: For call=2, set last=504 Aug 2 18:23:42 DEBUG[3964]: chan_iax2.c:6508 socket_read: For call=2, set last=524 Aug 2 18:23:42 DEBUG[3964]: chan_iax2.c:6508 socket_read: For call=2, set last=544 Aug 2 18:23:42 DEBUG[3964]: chan_iax2.c:6508 socket_read: For call=2, set last=564 Aug 2 18:23:42 DEBUG[3964]: chan_iax2.c:6508 socket_read: For call=2, set last=584 Aug 2 18:23:42 DEBUG[3964]: chan_iax2.c:6508 socket_read: For call=2, set last=604 Aug 2 18:23:42 DEBUG[3964]: chan_iax2.c:6508 socket_read: For call=2, set last=624 Aug 2 18:23:42 DEBUG[3964]: chan_iax2.c:6508 socket_read: For call=2, set last=644 Aug 2 18:23:42 DEBUG[3964]: chan_iax2.c:6508 socket_read: For call=2, set last=664 Aug 2 18:23:42 DEBUG[3964]: chan_iax2.c:6508 socket_read: For call=2, set last=684 Aug 2 18:23:42 DEBUG[3964]: chan_iax2.c:6508 socket_read: For call=2, set last=704 Aug 2 18:23:42 DEBUG[3964]: chan_iax2.c:6508 socket_read: For call=2, set last=724 Aug 2 18:23:42 DEBUG[3964]: chan_iax2.c:6508 socket_read: For call=2, set last=744 Aug 2 18:23:42 DEBUG[3964]: chan_iax2.c:6508 socket_read: For call=2, set last=764 Aug 2 18:23:42 DEBUG[3964]: chan_iax2.c:6508 socket_read: For call=2, set last=784 Aug 2 18:23:42 DEBUG[3964]: chan_iax2.c:6508 socket_read: For call=2, set last=804 Aug 2 18:23:43 DEBUG[3964]: chan_iax2.c:6508 socket_read: For call=2, set last=824 Aug 2 18:23:43 DEBUG[3964]: chan_iax2.c:6508 socket_read: For call=2, set last=844 Aug 2 18:23:43 DEBUG[3964]: chan_iax2.c:6508 socket_read: For call=2, set last=864 Aug 2 18:23:43 DEBUG[3964]: chan_iax2.c:6508 socket_read: For call=2, set last=884 Aug 2 18:23:43 DEBUG[3964]: chan_iax2.c:6508 socket_read: For call=2, set last=904 Aug 2 18:23:43 DEBUG[3964]: chan_iax2.c:6508 socket_read: For call=2, set last=924 Aug 2 18:23:43 DEBUG[3964]: chan_iax2.c:6508 socket_read: For call=2, set last=944 Aug 2 18:23:43 DEBUG[3964]: chan_iax2.c:6508 socket_read: For call=2, set last=964 Aug 2 18:23:43 DEBUG[3964]: chan_iax2.c:6508 socket_read: For call=2, set last=984 Aug 2 18:23:43 DEBUG[3964]: chan_iax2.c:6508 socket_read: For call=2, set last=1004 Aug 2 18:23:43 DEBUG[3964]: chan_iax2.c:6508 socket_read: For call=2, set last=1024 Aug 2 18:23:43 DEBUG[3964]: chan_iax2.c:6508 socket_read: For call=2, set last=1044 Aug 2 18:23:43 DEBUG[3964]: chan_iax2.c:6508 socket_read: For call=2, set last=1064 Aug 2 18:23:43 DEBUG[3964]: chan_iax2.c:6508 socket_read: For call=2, set last=1084 Aug 2 18:23:43 DEBUG[3964]: chan_iax2.c:6508 socket_read: For call=2, set last=1104 Aug 2 18:23:43 DEBUG[3964]: chan_iax2.c:6508 socket_read: For call=2, set last=1124 Aug 2 18:23:43 DEBUG[3964]: chan_iax2.c:6508 socket_read: For call=2, set last=1144 Aug 2 18:23:43 DEBUG[3964]: chan_iax2.c:6508 socket_read: For call=2, set last=1164 Aug 2 18:23:43 DEBUG[3964]: chan_iax2.c:6508 socket_read: For call=2, set last=1184 Aug 2 18:23:43 DEBUG[3964]: chan_iax2.c:6508 socket_read: For call=2, set last=1204 Aug 2 18:23:43 DEBUG[3964]: chan_iax2.c:6508 socket_read: For call=2, set last=1224 Aug 2 18:23:43 DEBUG[3964]: chan_iax2.c:6508 socket_read: For call=2, set last=1244 Aug 2 18:23:43 DEBUG[3964]: chan_iax2.c:6508 socket_read: For call=2, set last=1264 Aug 2 18:23:43 DEBUG[3964]: chan_iax2.c:6508 socket_read: For call=2, set last=1284 Aug 2 18:23:43 DEBUG[3964]: chan_iax2.c:6508 socket_read: For call=2, set last=1304 Aug 2 18:23:43 DEBUG[3964]: chan_iax2.c:6508 socket_read: For call=2, set last=1324 Aug 2 18:23:43 DEBUG[3964]: chan_iax2.c:6508 socket_read: For call=2, set last=1344 Aug 2 18:23:43 DEBUG[3964]: chan_iax2.c:6508 socket_read: For call=2, set last=1364 Aug 2 18:23:43 DEBUG[3964]: chan_iax2.c:6508 socket_read: For call=2, set last=1384 Aug 2 18:23:43 DEBUG[3964]: chan_iax2.c:6508 socket_read: For call=2, set last=1404 Aug 2 18:23:43 DEBUG[3964]: chan_iax2.c:6508 socket_read: For call=2, set last=1424 Aug 2 18:23:43 DEBUG[3964]: chan_iax2.c:6508 socket_read: For call=2, set last=1444 Aug 2 18:23:43 DEBUG[3964]: chan_iax2.c:6508 socket_read: For call=2, set last=1464 Aug 2 18:23:43 DEBUG[3964]: chan_iax2.c:6508 socket_read: For call=2, set last=1484 Aug 2 18:23:43 DEBUG[3964]: chan_iax2.c:6508 socket_read: For call=2, set last=1504 Aug 2 18:23:43 DEBUG[3964]: chan_iax2.c:6508 socket_read: For call=2, set last=1524 Aug 2 18:23:43 DEBUG[3964]: chan_iax2.c:6508 socket_read: For call=2, set last=1544 Aug 2 18:23:43 DEBUG[3964]: chan_iax2.c:6508 socket_read: For call=2, set last=1564 Aug 2 18:23:43 DEBUG[3964]: chan_iax2.c:6508 socket_read: For call=2, set last=1584 Aug 2 18:23:43 DEBUG[3964]: chan_iax2.c:6508 socket_read: For call=2, set last=1604 Aug 2 18:23:43 DEBUG[3964]: chan_iax2.c:6508 socket_read: For call=2, set last=1624 Aug 2 18:23:43 DEBUG[3964]: chan_iax2.c:6508 socket_read: For call=2, set last=1644 Aug 2 18:23:43 DEBUG[3964]: chan_iax2.c:6508 socket_read: For call=2, set last=1664 Aug 2 18:23:43 DEBUG[3964]: chan_iax2.c:6508 socket_read: For call=2, set last=1684 Aug 2 18:23:43 DEBUG[3964]: chan_iax2.c:6508 socket_read: For call=2, set last=1704 Aug 2 18:23:43 DEBUG[3964]: chan_iax2.c:6508 socket_read: For call=2, set last=1724 Aug 2 18:23:43 DEBUG[3964]: chan_iax2.c:6508 socket_read: For call=2, set last=1744 Aug 2 18:23:43 DEBUG[3964]: chan_iax2.c:6508 socket_read: For call=2, set last=1764 Aug 2 18:23:43 DEBUG[3964]: chan_iax2.c:6508 socket_read: For call=2, set last=1784 Aug 2 18:23:44 DEBUG[3964]: chan_iax2.c:6508 socket_read: For call=2, set last=1804 Aug 2 18:23:44 DEBUG[3964]: chan_iax2.c:6508 socket_read: For call=2, set last=1824 Aug 2 18:23:44 DEBUG[3964]: chan_iax2.c:6508 socket_read: For call=2, set last=1844 Aug 2 18:23:44 DEBUG[3964]: chan_iax2.c:6508 socket_read: For call=2, set last=1864 Aug 2 18:23:44 DEBUG[3964]: chan_iax2.c:6508 socket_read: For call=2, set last=1884 Aug 2 18:23:44 DEBUG[3964]: chan_iax2.c:6508 socket_read: For call=2, set last=1904 Aug 2 18:23:44 DEBUG[3964]: chan_iax2.c:6508 socket_read: For call=2, set last=1924 Aug 2 18:23:44 DEBUG[3964]: chan_iax2.c:6508 socket_read: For call=2, set last=1944 Aug 2 18:23:44 DEBUG[3964]: chan_iax2.c:6508 socket_read: For call=2, set last=1964 Aug 2 18:23:44 DEBUG[3964]: chan_iax2.c:6508 socket_read: For call=2, set last=1984 Aug 2 18:23:44 DEBUG[3964]: chan_iax2.c:6508 socket_read: For call=2, set last=2004 Aug 2 18:23:44 DEBUG[3964]: chan_iax2.c:7232 socket_read: Peer lastms 41, historicms 41, maxms 2000 Aug 2 18:23:44 DEBUG[3964]: chan_iax2.c:6508 socket_read: For call=2, set last=2024 Aug 2 18:23:44 DEBUG[3964]: chan_iax2.c:6508 socket_read: For call=2, set last=2044 Aug 2 18:23:44 DEBUG[3964]: chan_iax2.c:6508 socket_read: For call=2, set last=2064 Aug 2 18:23:44 DEBUG[3964]: chan_iax2.c:6508 socket_read: For call=2, set last=2084 Aug 2 18:23:44 DEBUG[3964]: chan_iax2.c:6508 socket_read: For call=2, set last=2104 Aug 2 18:23:44 DEBUG[3964]: chan_iax2.c:6508 socket_read: For call=2, set last=2124 Aug 2 18:23:44 DEBUG[3964]: chan_iax2.c:6508 socket_read: For call=2, set last=2144 Aug 2 18:23:44 DEBUG[3964]: chan_iax2.c:6508 socket_read: For call=2, set last=2164 Aug 2 18:23:44 DEBUG[3964]: chan_iax2.c:6508 socket_read: For call=2, set last=2184 Aug 2 18:23:44 DEBUG[3964]: chan_iax2.c:6508 socket_read: For call=2, set last=2204 Aug 2 18:23:44 DEBUG[3964]: chan_iax2.c:6508 socket_read: For call=2, set last=2224 Aug 2 18:23:44 DEBUG[3964]: chan_iax2.c:6508 socket_read: For call=2, set last=2244 Aug 2 18:23:44 DEBUG[3964]: chan_iax2.c:6508 socket_read: For call=2, set last=2264 Aug 2 18:23:44 DEBUG[3964]: chan_iax2.c:6508 socket_read: For call=2, set last=2284 Aug 2 18:23:44 DEBUG[3964]: chan_iax2.c:6508 socket_read: For call=2, set last=2304 Aug 2 18:23:44 DEBUG[3964]: chan_iax2.c:6508 socket_read: For call=2, set last=2324 Aug 2 18:23:44 DEBUG[3964]: chan_iax2.c:6508 socket_read: For call=2, set last=2344 Aug 2 18:23:44 DEBUG[3964]: chan_iax2.c:6508 socket_read: For call=2, set last=2364 Aug 2 18:23:44 DEBUG[3964]: chan_iax2.c:6508 socket_read: For call=2, set last=2384 Aug 2 18:23:44 DEBUG[3964]: chan_iax2.c:6508 socket_read: For call=2, set last=2404 Aug 2 18:23:44 DEBUG[3964]: chan_iax2.c:6508 socket_read: For call=2, set last=2424 Aug 2 18:23:44 DEBUG[3964]: chan_iax2.c:6508 socket_read: For call=2, set last=2444 Aug 2 18:23:44 DEBUG[3964]: chan_iax2.c:6508 socket_read: For call=2, set last=2464 Aug 2 18:23:44 DEBUG[3964]: chan_iax2.c:6508 socket_read: For call=2, set last=2484 Aug 2 18:23:44 DEBUG[3964]: chan_iax2.c:6508 socket_read: For call=2, set last=2504 Aug 2 18:23:44 DEBUG[3964]: chan_iax2.c:6508 socket_read: For call=2, set last=2524 Aug 2 18:23:44 DEBUG[3964]: chan_iax2.c:6508 socket_read: For call=2, set last=2544 Aug 2 18:23:44 DEBUG[3964]: chan_iax2.c:6508 socket_read: For call=2, set last=2564 Aug 2 18:23:44 DEBUG[3964]: chan_iax2.c:6508 socket_read: For call=2, set last=2584 Aug 2 18:23:44 DEBUG[3964]: chan_iax2.c:6508 socket_read: For call=2, set last=2604 Aug 2 18:23:44 DEBUG[3964]: chan_iax2.c:6508 socket_read: For call=2, set last=2624 Aug 2 18:23:44 DEBUG[3964]: chan_iax2.c:6508 socket_read: For call=2, set last=2644 Aug 2 18:23:44 DEBUG[3964]: chan_iax2.c:6508 socket_read: For call=2, set last=2664 Aug 2 18:23:44 DEBUG[3964]: chan_iax2.c:6508 socket_read: For call=2, set last=2684 Aug 2 18:23:44 DEBUG[3964]: chan_iax2.c:6508 socket_read: For call=2, set last=2704 Aug 2 18:23:44 DEBUG[3964]: chan_iax2.c:6508 socket_read: For call=2, set last=2724 Aug 2 18:23:44 DEBUG[3964]: chan_iax2.c:6508 socket_read: For call=2, set last=2744 Aug 2 18:23:44 DEBUG[3964]: chan_iax2.c:6508 socket_read: For call=2, set last=2764 Aug 2 18:23:44 DEBUG[3964]: chan_iax2.c:6508 socket_read: For call=2, set last=2784 Aug 2 18:23:44 DEBUG[3964]: chan_iax2.c:6508 socket_read: For call=2, set last=2804 Aug 2 18:23:45 DEBUG[3964]: chan_iax2.c:6508 socket_read: For call=2, set last=2824 Aug 2 18:23:45 DEBUG[3964]: chan_iax2.c:6508 socket_read: For call=2, set last=2844 Aug 2 18:23:45 DEBUG[3964]: chan_iax2.c:6508 socket_read: For call=2, set last=2864 Aug 2 18:23:45 DEBUG[3964]: chan_iax2.c:6508 socket_read: For call=2, set last=2884 Aug 2 18:23:45 DEBUG[3964]: chan_iax2.c:6508 socket_read: For call=2, set last=2904 Aug 2 18:23:45 DEBUG[3964]: chan_iax2.c:6508 socket_read: For call=2, set last=2924 Aug 2 18:23:45 DEBUG[3964]: chan_iax2.c:6508 socket_read: For call=2, set last=2944 Aug 2 18:23:45 DEBUG[3964]: chan_iax2.c:6508 socket_read: For call=2, set last=2964 Aug 2 18:23:45 DEBUG[3964]: chan_iax2.c:6508 socket_read: For call=2, set last=2984 Aug 2 18:23:45 DEBUG[3964]: chan_iax2.c:6508 socket_read: For call=2, set last=3004 Aug 2 18:23:45 DEBUG[3964]: chan_iax2.c:6508 socket_read: For call=2, set last=3024 Aug 2 18:23:45 DEBUG[3964]: chan_iax2.c:6508 socket_read: For call=2, set last=3044 Aug 2 18:23:45 DEBUG[3964]: chan_iax2.c:6508 socket_read: For call=2, set last=3064 Aug 2 18:23:45 DEBUG[3964]: chan_iax2.c:6508 socket_read: For call=2, set last=3084 Aug 2 18:23:45 DEBUG[3964]: chan_iax2.c:6508 socket_read: For call=2, set last=3104 Aug 2 18:23:45 DEBUG[3964]: chan_iax2.c:6508 socket_read: For call=2, set last=3124 Aug 2 18:23:45 DEBUG[3964]: chan_iax2.c:6508 socket_read: For call=2, set last=3144 Aug 2 18:23:45 DEBUG[3964]: chan_iax2.c:6508 socket_read: For call=2, set last=3164 Aug 2 18:23:45 DEBUG[3964]: chan_iax2.c:6508 socket_read: For call=2, set last=3184 Aug 2 18:23:45 DEBUG[3964]: chan_iax2.c:6508 socket_read: For call=2, set last=3204 Aug 2 18:23:45 DEBUG[3964]: chan_iax2.c:6508 socket_read: For call=2, set last=3224 Aug 2 18:23:45 DEBUG[3964]: chan_iax2.c:6508 socket_read: For call=2, set last=3244 Aug 2 18:23:45 DEBUG[3964]: chan_iax2.c:6508 socket_read: For call=2, set last=3264 Aug 2 18:23:45 DEBUG[3964]: chan_iax2.c:6508 socket_read: For call=2, set last=3284 Aug 2 18:23:45 DEBUG[3964]: chan_iax2.c:6508 socket_read: For call=2, set last=3304 Aug 2 18:23:45 DEBUG[3964]: chan_iax2.c:6508 socket_read: For call=2, set last=3324 Aug 2 18:23:45 DEBUG[3964]: chan_iax2.c:6508 socket_read: For call=2, set last=3344 Aug 2 18:23:45 DEBUG[3964]: chan_iax2.c:6508 socket_read: For call=2, set last=3364 Aug 2 18:23:45 DEBUG[3964]: chan_iax2.c:6508 socket_read: For call=2, set last=3384 Aug 2 18:23:45 DEBUG[3964]: chan_iax2.c:6508 socket_read: For call=2, set last=3404 Aug 2 18:23:45 DEBUG[3964]: chan_iax2.c:6508 socket_read: For call=2, set last=3424 Aug 2 18:23:45 DEBUG[3964]: chan_iax2.c:6508 socket_read: For call=2, set last=3444 Aug 2 18:23:45 DEBUG[3964]: chan_iax2.c:6508 socket_read: For call=2, set last=3464 Aug 2 18:23:45 DEBUG[3964]: chan_iax2.c:6508 socket_read: For call=2, set last=3484 Aug 2 18:23:45 DEBUG[3964]: chan_iax2.c:6508 socket_read: For call=2, set last=3504 Aug 2 18:23:45 DEBUG[3964]: chan_iax2.c:6508 socket_read: For call=2, set last=3524 Aug 2 18:23:45 DEBUG[3964]: chan_iax2.c:6508 socket_read: For call=2, set last=3544 Aug 2 18:23:45 DEBUG[3964]: chan_iax2.c:6508 socket_read: For call=2, set last=3564 Aug 2 18:23:45 DEBUG[3964]: chan_iax2.c:6508 socket_read: For call=2, set last=3584 Aug 2 18:23:45 DEBUG[3964]: chan_iax2.c:6508 socket_read: For call=2, set last=3604 Aug 2 18:23:45 DEBUG[3964]: chan_iax2.c:6508 socket_read: For call=2, set last=3624 Aug 2 18:23:45 DEBUG[3964]: chan_iax2.c:6508 socket_read: For call=2, set last=3644 Aug 2 18:23:45 DEBUG[3964]: chan_iax2.c:6508 socket_read: For call=2, set last=3664 Aug 2 18:23:45 DEBUG[3964]: chan_iax2.c:6508 socket_read: For call=2, set last=3684 Aug 2 18:23:45 DEBUG[3964]: chan_iax2.c:6508 socket_read: For call=2, set last=3704 Aug 2 18:23:45 DEBUG[3964]: chan_iax2.c:6508 socket_read: For call=2, set last=3724 Aug 2 18:23:45 DEBUG[3964]: chan_iax2.c:6508 socket_read: For call=2, set last=3744 Aug 2 18:23:45 DEBUG[3964]: chan_iax2.c:6508 socket_read: For call=2, set last=3764 Aug 2 18:23:46 DEBUG[3964]: chan_iax2.c:6508 socket_read: For call=2, set last=3784 Aug 2 18:23:46 DEBUG[3964]: chan_iax2.c:6508 socket_read: For call=2, set last=3804 Aug 2 18:23:46 DEBUG[3964]: chan_iax2.c:6508 socket_read: For call=2, set last=3824 Aug 2 18:23:46 DEBUG[3964]: chan_iax2.c:6508 socket_read: For call=2, set last=3844 Aug 2 18:23:46 DEBUG[3964]: chan_iax2.c:6508 socket_read: For call=2, set last=3864 Aug 2 18:23:46 DEBUG[3964]: chan_iax2.c:6508 socket_read: For call=2, set last=3884 Aug 2 18:23:46 DEBUG[3964]: chan_iax2.c:6508 socket_read: For call=2, set last=3904 Aug 2 18:23:46 DEBUG[3964]: chan_iax2.c:6508 socket_read: For call=2, set last=3924 Aug 2 18:23:46 DEBUG[3964]: chan_iax2.c:6508 socket_read: For call=2, set last=3944 Aug 2 18:23:46 DEBUG[3964]: chan_iax2.c:6508 socket_read: For call=2, set last=3964 Aug 2 18:23:46 DEBUG[3964]: chan_iax2.c:6508 socket_read: For call=2, set last=3984 Aug 2 18:23:46 DEBUG[3964]: chan_iax2.c:6508 socket_read: For call=2, set last=4004 Aug 2 18:23:46 DEBUG[3964]: chan_iax2.c:6508 socket_read: For call=2, set last=4024 Aug 2 18:23:46 DEBUG[3964]: chan_iax2.c:6508 socket_read: For call=2, set last=4044 Aug 2 18:23:46 DEBUG[3964]: chan_iax2.c:6508 socket_read: For call=2, set last=4064 Aug 2 18:23:46 DEBUG[3964]: chan_iax2.c:6508 socket_read: For call=2, set last=4084 Aug 2 18:23:46 DEBUG[3964]: chan_iax2.c:6508 socket_read: For call=2, set last=4104 Aug 2 18:23:46 DEBUG[3964]: chan_iax2.c:6508 socket_read: For call=2, set last=4124 Aug 2 18:23:46 DEBUG[3964]: chan_iax2.c:6508 socket_read: For call=2, set last=4144 Aug 2 18:23:46 DEBUG[3964]: chan_iax2.c:6508 socket_read: For call=2, set last=4164 Aug 2 18:23:46 DEBUG[3964]: chan_iax2.c:6508 socket_read: For call=2, set last=4184 Aug 2 18:23:46 DEBUG[3964]: chan_iax2.c:6508 socket_read: For call=2, set last=4204 Aug 2 18:23:46 DEBUG[3964]: chan_iax2.c:6508 socket_read: For call=2, set last=4224 Aug 2 18:23:46 DEBUG[3964]: chan_iax2.c:6508 socket_read: For call=2, set last=4244 Aug 2 18:23:46 DEBUG[3964]: chan_iax2.c:6508 socket_read: For call=2, set last=4264 Aug 2 18:23:46 DEBUG[3964]: chan_iax2.c:6508 socket_read: For call=2, set last=4284 Aug 2 18:23:46 DEBUG[3964]: chan_iax2.c:6508 socket_read: For call=2, set last=4304 Aug 2 18:23:46 DEBUG[3964]: chan_iax2.c:6508 socket_read: For call=2, set last=4324 Aug 2 18:23:46 DEBUG[3964]: chan_iax2.c:6508 socket_read: For call=2, set last=4344 Aug 2 18:23:46 DEBUG[3964]: chan_iax2.c:6508 socket_read: For call=2, set last=4364 Aug 2 18:23:46 DEBUG[3964]: chan_iax2.c:6508 socket_read: For call=2, set last=4384 Aug 2 18:23:46 DEBUG[3964]: chan_iax2.c:6508 socket_read: For call=2, set last=4404 Aug 2 18:23:46 DEBUG[3964]: chan_iax2.c:6508 socket_read: For call=2, set last=4424 Aug 2 18:23:46 DEBUG[3964]: chan_iax2.c:6508 socket_read: For call=2, set last=4444 ubuntu-test-1*CLI> <-- SIP read from 10.2.6.252:5060: INVITE sip:195@10.0.90.187 SIP/2.0 Via: SIP/2.0/UDP 10.2.6.252;rport;branch=z9hG4bK0a0206fc0000003944d0d1c6000044e500000077 Content-Length: 212 Contact: Call-ID: EC3876C9-D5F6-4AE9-B0E7-5B41CCA10C83@10.2.6.252 Content-Type: application/sdp CSeq: 3 INVITE From: "unknown";tag=79254603128430 Max-Forwards: 70 To: ;tag=as2b87f8b9 User-Agent: SJphone/1.60.289a (SJ Labs) v=0 o=- 3363524673 3363524674 IN IP4 10.2.6.252 s=SJphone c=IN IP4 0.0.0.0 t=0 0 a=direction:active m=audio 49158 RTP/AVP 0 101 a=rtpmap:0 PCMU/8000 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-11,16 Aug 2 18:23:46 DEBUG[3962]: chan_sip.c:3357 parse_request: Header 0: INVITE sip:195@10.0.90.187 SIP/2.0 (34) Aug 2 18:23:46 DEBUG[3962]: chan_sip.c:3357 parse_request: Header 1: Via: SIP/2.0/UDP 10.2.6.252;rport;branch=z9hG4bK0a0206fc0000003944d0d1c6000044e500000077 (88) Aug 2 18:23:46 DEBUG[3962]: chan_sip.c:3357 parse_request: Header 2: Content-Length: 212 (19) Aug 2 18:23:46 DEBUG[3962]: chan_sip.c:3357 parse_request: Header 3: Contact: (34) Aug 2 18:23:46 DEBUG[3962]: chan_sip.c:3357 parse_request: Header 4: Call-ID: EC3876C9-D5F6-4AE9-B0E7-5B41CCA10C83@10.2.6.252 (56) Aug 2 18:23:46 DEBUG[3962]: chan_sip.c:3357 parse_request: Header 5: Content-Type: application/sdp (29) Aug 2 18:23:46 DEBUG[3962]: chan_sip.c:3357 parse_request: Header 6: CSeq: 3 INVITE (14) Aug 2 18:23:46 DEBUG[3962]: chan_sip.c:3357 parse_request: Header 7: From: "unknown";tag=79254603128430 (55) Aug 2 18:23:46 DEBUG[3962]: chan_sip.c:3357 parse_request: Header 8: Max-Forwards: 70 (16) Aug 2 18:23:46 DEBUG[3962]: chan_sip.c:3357 parse_request: Header 9: To: ;tag=as2b87f8b9 (40) Aug 2 18:23:46 DEBUG[3962]: chan_sip.c:3357 parse_request: Header 10: User-Agent: SJphone/1.60.289a (SJ Labs) (39) Aug 2 18:23:46 DEBUG[3962]: chan_sip.c:3357 parse_request: Header 11: (0) Aug 2 18:23:46 DEBUG[3962]: chan_sip.c:3389 parse_request: Line: v=0 (3) Aug 2 18:23:46 DEBUG[3962]: chan_sip.c:3389 parse_request: Line: o=- 3363524673 3363524674 IN IP4 10.2.6.252 (43) Aug 2 18:23:46 DEBUG[3962]: chan_sip.c:3389 parse_request: Line: s=SJphone (9) Aug 2 18:23:46 DEBUG[3962]: chan_sip.c:3389 parse_request: Line: c=IN IP4 0.0.0.0 (16) Aug 2 18:23:46 DEBUG[3962]: chan_sip.c:3389 parse_request: Line: t=0 0 (5) Aug 2 18:23:46 DEBUG[3962]: chan_sip.c:3389 parse_request: Line: a=direction:active (18) Aug 2 18:23:46 DEBUG[3962]: chan_sip.c:3389 parse_request: Line: m=audio 49158 RTP/AVP 0 101 (27) Aug 2 18:23:46 DEBUG[3962]: chan_sip.c:3389 parse_request: Line: a=rtpmap:0 PCMU/8000 (20) Aug 2 18:23:46 DEBUG[3962]: chan_sip.c:3389 parse_request: Line: a=rtpmap:101 telephone-event/8000 (33) Aug 2 18:23:46 DEBUG[3962]: chan_sip.c:3389 parse_request: Line: a=fmtp:101 0-11,16 (18) --- (11 headers 10 lines)--- Aug 2 18:23:46 DEBUG[3962]: chan_sip.c:11139 handle_request: **** Received INVITE (5) - Command in SIP INVITE Using INVITE request as basis request - EC3876C9-D5F6-4AE9-B0E7-5B41CCA10C83@10.2.6.252 Sending to 10.2.6.252 : 5060 (NAT) Found RTP audio format 0 Found RTP audio format 101 Peer audio RTP is at port 0.0.0.0:49158 Aug 2 18:23:46 DEBUG[3962]: chan_sip.c:3598 process_sdp: Peer audio RTP is at port 0.0.0.0:49158 Peer video RTP is at port 0.0.0.0:65535 Aug 2 18:23:46 DEBUG[3962]: chan_sip.c:3622 process_sdp: Peer video RTP is at port 0.0.0.0:65535 Found description format PCMU Found description format telephone-event Capabilities: us - 0x1c0406 (gsm|ulaw|ilbc|h261|h263|h263p), peer - audio=0x4 (ulaw)/video=0x0 (nothing), combined - 0x4 (ulaw) Non-codec capabilities: us - 0x1 (telephone-event), peer - 0x1 (telephone-event), combined - 0x1 (telephone-event) -- Started music on hold, class 'default', on IAX2/Voop50294-2 Aug 2 18:23:46 DEBUG[3962]: chan_sip.c:10550 handle_request_invite: Got a SIP re-invite for call EC3876C9-D5F6-4AE9-B0E7-5B41CCA10C83@10.2.6.252 We're at 10.0.90.187 port 10360 Video is at 10.0.90.187 port 14198 Adding codec 0x4 (ulaw) to SDP Adding non-codec 0x1 (telephone-event) to SDP Reliably Transmitting (NAT) to 10.2.6.252:5060: SIP/2.0 200 OK Via: SIP/2.0/UDP 10.2.6.252;branch=z9hG4bK0a0206fc0000003944d0d1c6000044e500000077;received=10.2.6.252;rport=5060 From: "unknown";tag=79254603128430 To: ;tag=as2b87f8b9 Call-ID: EC3876C9-D5F6-4AE9-B0E7-5B41CCA10C83@10.2.6.252 CSeq: 3 INVITE User-Agent: Diptel-T50 Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY Contact: Content-Type: application/sdp Content-Length: 212 v=0 o=root 3952 3953 IN IP4 10.0.90.187 s=session c=IN IP4 10.0.90.187 t=0 0 m=audio 10360 RTP/AVP 0 101 a=rtpmap:0 PCMU/8000 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-16 a=silenceSupp:off - - - - --- Aug 2 18:23:46 DEBUG[3962]: chan_sip.c:1293 __sip_reliable_xmit: *** SIP TIMER: Initalizing retransmit timer on packet: Id #40 ubuntu-test-1*CLI> <-- SIP read from 10.2.6.252:5060: ACK sip:195@10.0.90.187 SIP/2.0 Via: SIP/2.0/UDP 10.2.6.252;rport;branch=z9hG4bK0a0206fc0000003944d0d1c60000120f00000079 Content-Length: 0 Call-ID: EC3876C9-D5F6-4AE9-B0E7-5B41CCA10C83@10.2.6.252 CSeq: 3 ACK From: "unknown";tag=79254603128430 Max-Forwards: 70 To: ;tag=as2b87f8b9 User-Agent: SJphone/1.60.289a (SJ Labs) Aug 2 18:23:46 DEBUG[3962]: chan_sip.c:3357 parse_request: Header 0: ACK sip:195@10.0.90.187 SIP/2.0 (31) Aug 2 18:23:46 DEBUG[3962]: chan_sip.c:3357 parse_request: Header 1: Via: SIP/2.0/UDP 10.2.6.252;rport;branch=z9hG4bK0a0206fc0000003944d0d1c60000120f00000079 (88) Aug 2 18:23:46 DEBUG[3962]: chan_sip.c:3357 parse_request: Header 2: Content-Length: 0 (17) Aug 2 18:23:46 DEBUG[3962]: chan_sip.c:3357 parse_request: Header 3: Call-ID: EC3876C9-D5F6-4AE9-B0E7-5B41CCA10C83@10.2.6.252 (56) Aug 2 18:23:46 DEBUG[3962]: chan_sip.c:3357 parse_request: Header 4: CSeq: 3 ACK (11) Aug 2 18:23:46 DEBUG[3962]: chan_sip.c:3357 parse_request: Header 5: From: "unknown";tag=79254603128430 (55) Aug 2 18:23:46 DEBUG[3962]: chan_sip.c:3357 parse_request: Header 6: Max-Forwards: 70 (16) Aug 2 18:23:46 DEBUG[3962]: chan_sip.c:3357 parse_request: Header 7: To: ;tag=as2b87f8b9 (40) Aug 2 18:23:46 DEBUG[3962]: chan_sip.c:3357 parse_request: Header 8: User-Agent: SJphone/1.60.289a (SJ Labs) (39) Aug 2 18:23:46 DEBUG[3962]: chan_sip.c:3357 parse_request: Header 9: (0) --- (9 headers 0 lines)--- Aug 2 18:23:46 DEBUG[3962]: chan_sip.c:11139 handle_request: **** Received ACK (6) - Command in SIP ACK Aug 2 18:23:46 DEBUG[3962]: chan_sip.c:1390 __sip_ack: ** SIP TIMER: Cancelling retransmit of packet (reply received) Retransid #40 Aug 2 18:23:46 DEBUG[3962]: chan_sip.c:1401 __sip_ack: Stopping retransmission on 'EC3876C9-D5F6-4AE9-B0E7-5B41CCA10C83@10.2.6.252' of Response 3: Match Found <-- SIP read from 10.2.6.252:5060: REFER sip:195@10.0.90.187 SIP/2.0 Via: SIP/2.0/UDP 10.2.6.252;rport;branch=z9hG4bK0a0206fc0000003944d0d1c600000a0e0000007a Content-Length: 0 Contact: Call-ID: EC3876C9-D5F6-4AE9-B0E7-5B41CCA10C83@10.2.6.252 CSeq: 4 REFER From: "unknown";tag=79254603128430 Max-Forwards: 70 Referred-By: Refer-To: sip:700@10.0.90.187 To: ;tag=as2b87f8b9 User-Agent: SJphone/1.60.289a (SJ Labs) Aug 2 18:23:46 DEBUG[3962]: chan_sip.c:3357 parse_request: Header 0: REFER sip:195@10.0.90.187 SIP/2.0 (33) Aug 2 18:23:46 DEBUG[3962]: chan_sip.c:3357 parse_request: Header 1: Via: SIP/2.0/UDP 10.2.6.252;rport;branch=z9hG4bK0a0206fc0000003944d0d1c600000a0e0000007a (88) Aug 2 18:23:46 DEBUG[3962]: chan_sip.c:3357 parse_request: Header 2: Content-Length: 0 (17) Aug 2 18:23:46 DEBUG[3962]: chan_sip.c:3357 parse_request: Header 3: Contact: (34) Aug 2 18:23:46 DEBUG[3962]: chan_sip.c:3357 parse_request: Header 4: Call-ID: EC3876C9-D5F6-4AE9-B0E7-5B41CCA10C83@10.2.6.252 (56) Aug 2 18:23:46 DEBUG[3962]: chan_sip.c:3357 parse_request: Header 5: CSeq: 4 REFER (13) Aug 2 18:23:46 DEBUG[3962]: chan_sip.c:3357 parse_request: Header 6: From: "unknown";tag=79254603128430 (55) Aug 2 18:23:46 DEBUG[3962]: chan_sip.c:3357 parse_request: Header 7: Max-Forwards: 70 (16) Aug 2 18:23:46 DEBUG[3962]: chan_sip.c:3357 parse_request: Header 8: Referred-By: (34) Aug 2 18:23:46 DEBUG[3962]: chan_sip.c:3357 parse_request: Header 9: Refer-To: sip:700@10.0.90.187 (29) Aug 2 18:23:46 DEBUG[3962]: chan_sip.c:3357 parse_request: Header 10: To: ;tag=as2b87f8b9 (40) Aug 2 18:23:46 DEBUG[3962]: chan_sip.c:3357 parse_request: Header 11: User-Agent: SJphone/1.60.289a (SJ Labs) (39) Aug 2 18:23:46 DEBUG[3962]: chan_sip.c:3357 parse_request: Header 12: (0) --- (12 headers 0 lines)--- Aug 2 18:23:46 DEBUG[3962]: chan_sip.c:11139 handle_request: **** Received REFER (9) - Command in SIP REFER Aug 2 18:23:46 DEBUG[3962]: chan_sip.c:10662 handle_request_refer: SIP call transfer received for call EC3876C9-D5F6-4AE9-B0E7-5B41CCA10C83@10.2.6.252 (REFER)! Transfer to 700 in usr_11_ctx Transfer from 803 in usr_11_ctx Aug 2 18:23:46 DEBUG[3962]: chan_sip.c:6873 get_refer_info: Unsupervised transfer to (Refer-To): 700 Aug 2 18:23:46 DEBUG[3962]: chan_sip.c:6875 get_refer_info: Transferred by (Referred-by: ) 803 Aug 2 18:23:46 DEBUG[3962]: chan_sip.c:6876 get_refer_info: Transfer Contact Info (REFER_CONTACT) Aug 2 18:23:46 DEBUG[3962]: chan_sip.c:10682 handle_request_refer: 202 Accepted (blind) Aug 2 18:23:46 DEBUG[3962]: chan_sip.c:10687 handle_request_refer: Got SIP blind transfer, applying to 'IAX2/Voop50294-2' -- Stopped music on hold on IAX2/Voop50294-2 Aug 2 18:23:46 DEBUG[3962]: channel.c:2363 set_format: Set channel IAX2/Voop50294-2 to write format ulaw Aug 2 18:23:46 DEBUG[3962]: channel.c:2788 ast_channel_masquerade: Planning to masquerade channel IAX2/Voop50294-2 into the structure of Parking/IAX2/Voop50294-2 Aug 2 18:23:46 DEBUG[3962]: channel.c:2801 ast_channel_masquerade: Done planning to masquerade channel IAX2/Voop50294-2 into the structure of Parking/IAX2/Voop50294-2 Aug 2 18:23:46 DEBUG[3962]: channel.c:2788 ast_channel_masquerade: Planning to masquerade channel SIP/803-081a7998 into the structure of SIPPeer/SIP/803-081a7998 Aug 2 18:23:46 DEBUG[3962]: channel.c:2801 ast_channel_masquerade: Done planning to masquerade channel SIP/803-081a7998 into the structure of SIPPeer/SIP/803-081a7998 Aug 2 18:23:46 DEBUG[3962]: channel.c:2913 ast_do_masquerade: Actually Masquerading SIP/803-081a7998(6) into the structure of SIPPeer/SIP/803-081a7998(0) Aug 2 18:23:46 DEBUG[3962]: channel.c:2924 ast_do_masquerade: Got clone lock for masquerade on 'SIP/803-081a7998' at 0x81b016c Aug 2 18:23:46 DEBUG[3962]: channel.c:2363 set_format: Set channel SIP/803-081a7998 to write format ulaw Aug 2 18:23:46 DEBUG[3962]: channel.c:2363 set_format: Set channel SIP/803-081a7998 to read format ulaw Aug 2 18:23:46 DEBUG[3962]: channel.c:3085 ast_do_masquerade: Putting channel SIP/803-081a7998 in 4/4 formats Aug 2 18:23:46 DEBUG[3962]: channel.c:3120 ast_do_masquerade: Released clone lock on 'SIPPeer/SIP/803-081a7998' Aug 2 18:23:46 DEBUG[3962]: channel.c:3129 ast_do_masquerade: Done Masquerading SIP/803-081a7998 (6) Aug 2 18:23:46 DEBUG[3964]: chan_iax2.c:6508 socket_read: For call=2, set last=4464 Aug 2 18:23:46 DEBUG[4337]: channel.c:3308 ast_generic_bridge: Didn't get a frame from channel: SIPPeer/SIP/803-081a7998 Aug 2 18:23:46 DEBUG[4337]: channel.c:3584 ast_channel_bridge: Bridge stops bridging channels SIPPeer/SIP/803-081a7998 and IAX2/Voop50294-2 Aug 2 18:23:46 DEBUG[4337]: app_dial.c:1628 dial_exec_full: Exiting with DIALSTATUS=ANSWER. Aug 2 18:23:46 DEBUG[4337]: app_macro.c:231 macro_exec: Spawn extension (macro-c_pstn,s,4) exited non-zero on 'SIPPeer/SIP/803-081a7998' in macro 'c_pstn' Aug 2 18:23:46 DEBUG[4337]: pbx.c:2316 __ast_pbx_run: Spawn extension (macro-c_pstn,s,4) exited non-zero on 'SIPPeer/SIP/803-081a7998' Transmitting (NAT) to 10.2.6.252:5060: SIP/2.0 202 Accepted Via: SIP/2.0/UDP 10.2.6.252;branch=z9hG4bK0a0206fc0000003944d0d1c600000a0e0000007a;received=10.2.6.252;rport=5060 From: "unknown";tag=79254603128430 To: ;tag=as2b87f8b9 Call-ID: EC3876C9-D5F6-4AE9-B0E7-5B41CCA10C83@10.2.6.252 CSeq: 4 REFER User-Agent: Diptel-T50 Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY Contact: Content-Length: 0 --- set_destination: Parsing for address/port to send to set_destination: set destination to 10.2.6.252, port 5060 Reliably Transmitting (NAT) to 10.2.6.252:5060: NOTIFY sip:803@10.2.6.252:5060 SIP/2.0 Via: SIP/2.0/UDP 10.0.90.187:5060;branch=z9hG4bK0e09f719;rport From: ;tag=as2b87f8b9 To: "unknown";tag=79254603128430 Contact: Call-ID: EC3876C9-D5F6-4AE9-B0E7-5B41CCA10C83@10.2.6.252 CSeq: 102 NOTIFY User-Agent: Diptel-T50 Max-Forwards: 70 Event: refer;id=4 Subscription-state: terminated;reason=noresource Content-Type: message/sipfrag;version=2.0 Content-Length: 14 SIP/2.0 200 OK --- Aug 2 18:23:46 DEBUG[3962]: chan_sip.c:1293 __sip_reliable_xmit: *** SIP TIMER: Initalizing retransmit timer on packet: Id #41 Aug 2 18:23:46 DEBUG[4342]: channel.c:2913 ast_do_masquerade: Actually Masquerading IAX2/Voop50294-2(6) into the structure of Parking/IAX2/Voop50294-2(0) Aug 2 18:23:46 DEBUG[4342]: channel.c:2924 ast_do_masquerade: Got clone lock for masquerade on 'IAX2/Voop50294-2' at 0x81bf72c Aug 2 18:23:46 DEBUG[4342]: channel.c:2363 set_format: Set channel IAX2/Voop50294-2 to write format ulaw Aug 2 18:23:46 DEBUG[4342]: channel.c:2363 set_format: Set channel IAX2/Voop50294-2 to read format ulaw Aug 2 18:23:46 DEBUG[4342]: channel.c:3085 ast_do_masquerade: Putting channel IAX2/Voop50294-2 in 4/4 formats Aug 2 18:23:46 DEBUG[4342]: channel.c:3105 ast_do_masquerade: Destroying channel clone 'Parking/IAX2/Voop50294-2' Aug 2 18:23:46 DEBUG[4342]: channel.c:3129 ast_do_masquerade: Done Masquerading IAX2/Voop50294-2 (6) -- Started music on hold, class 'default', on IAX2/Voop50294-2 == Parked IAX2/Voop50294-2 on 701. Will timeout back to extension [realtime-did] s, 1 in 45 seconds Aug 2 18:23:46 DEBUG[3956]: devicestate.c:187 do_state_change: Changing state for Parking/IAX2/Voop50294 - state 4 (Invalid) Aug 2 18:23:46 DEBUG[4342]: pbx.c:4875 ast_add_extension2: Added extension '701' priority 1 to parkedcalls Aug 2 18:23:46 DEBUG[4343]: app_queue.c:490 changethread: Device 'Parking/IAX2/Voop50294' changed to state '4' (Invalid) but we don't care because they're not a member of any queue. Aug 2 18:23:46 DEBUG[4342]: channel.c:2363 set_format: Set channel SIP/803-081a7998 to write format gsm <-- SIP read from 10.2.6.252:5060: BYE sip:195@10.0.90.187 SIP/2.0 Via: SIP/2.0/UDP 10.2.6.252;rport;branch=z9hG4bK0a0206fc0000003944d0d1c60000200b0000007d Content-Length: 0 Call-ID: EC3876C9-D5F6-4AE9-B0E7-5B41CCA10C83@10.2.6.252 CSeq: 5 BYE From: "unknown";tag=79254603128430 Max-Forwards: 70 To: ;tag=as2b87f8b9 User-Agent: SJphone/1.60.289a (SJ Labs) Proxy-Authorization: Digest username="803",realm="asterisk",nonce="769a81f0",uri="sip:195@10.0.90.187",response="e75bf308f27948a3890ba93193c844e8",algorithm="MD5" Aug 2 18:23:46 DEBUG[3962]: chan_sip.c:3357 parse_request: Header 0: BYE sip:195@10.0.90.187 SIP/2.0 (31) Aug 2 18:23:46 DEBUG[3962]: chan_sip.c:3357 parse_request: Header 1: Via: SIP/2.0/UDP 10.2.6.252;rport;branch=z9hG4bK0a0206fc0000003944d0d1c60000200b0000007d (88) Aug 2 18:23:46 DEBUG[3962]: chan_sip.c:3357 parse_request: Header 2: Content-Length: 0 (17) Aug 2 18:23:46 DEBUG[3962]: chan_sip.c:3357 parse_request: Header 3: Call-ID: EC3876C9-D5F6-4AE9-B0E7-5B41CCA10C83@10.2.6.252 (56) Aug 2 18:23:46 DEBUG[3962]: chan_sip.c:3357 parse_request: Header 4: CSeq: 5 BYE (11) Aug 2 18:23:46 DEBUG[3962]: chan_sip.c:3357 parse_request: Header 5: From: "unknown";tag=79254603128430 (55) Aug 2 18:23:46 DEBUG[3962]: chan_sip.c:3357 parse_request: Header 6: Max-Forwards: 70 (16) Aug 2 18:23:46 DEBUG[3962]: chan_sip.c:3357 parse_request: Header 7: To: ;tag=as2b87f8b9 (40) Aug 2 18:23:46 DEBUG[3962]: chan_sip.c:3357 parse_request: Header 8: User-Agent: SJphone/1.60.289a (SJ Labs) (39) Aug 2 18:23:46 DEBUG[3962]: chan_sip.c:3357 parse_request: Header 9: Proxy-Authorization: Digest username="803",realm="asterisk",nonce="769a81f0",uri="sip:195@10.0.90.187",response="e75bf308f27948a3890ba93193c844e8",algorithm="MD5" (162) Aug 2 18:23:46 DEBUG[3962]: chan_sip.c:3357 parse_request: Header 10: (0) --- (10 headers 0 lines)--- Aug 2 18:23:46 DEBUG[3962]: chan_sip.c:11139 handle_request: **** Received BYE (8) - Command in SIP BYE Sending to 10.2.6.252 : 5060 (NAT) Transmitting (NAT) to 10.2.6.252:5060: SIP/2.0 200 OK Via: SIP/2.0/UDP 10.2.6.252;branch=z9hG4bK0a0206fc0000003944d0d1c60000200b0000007d;received=10.2.6.252;rport=5060 From: "unknown";tag=79254603128430 To: ;tag=as2b87f8b9 Call-ID: EC3876C9-D5F6-4AE9-B0E7-5B41CCA10C83@10.2.6.252 CSeq: 5 BYE User-Agent: Diptel-T50 Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY Contact: Content-Length: 0 --- Aug 2 18:23:46 DEBUG[3957]: channel.c:2363 set_format: Set channel IAX2/Voop50294-2 to write format slin <-- SIP read from 10.2.6.252:5060: SIP/2.0 200 OK Via: SIP/2.0/UDP 10.0.90.187:5060;rport=5060;received=10.0.90.187;branch=z9hG4bK0e09f719 Content-Length: 0 Call-ID: EC3876C9-D5F6-4AE9-B0E7-5B41CCA10C83@10.2.6.252 CSeq: 102 NOTIFY From: ;tag=as2b87f8b9 Server: SJphone/1.60.289a (SJ Labs) To: "unknown";tag=79254603128430 Aug 2 18:23:46 DEBUG[3962]: chan_sip.c:3357 parse_request: Header 0: SIP/2.0 200 OK (14) Aug 2 18:23:46 DEBUG[3962]: chan_sip.c:3357 parse_request: Header 1: Via: SIP/2.0/UDP 10.0.90.187:5060;rport=5060;received=10.0.90.187;branch=z9hG4bK0e09f719 (88) Aug 2 18:23:46 DEBUG[3962]: chan_sip.c:3357 parse_request: Header 2: Content-Length: 0 (17) Aug 2 18:23:46 DEBUG[3962]: chan_sip.c:3357 parse_request: Header 3: Call-ID: EC3876C9-D5F6-4AE9-B0E7-5B41CCA10C83@10.2.6.252 (56) Aug 2 18:23:46 DEBUG[3962]: chan_sip.c:3357 parse_request: Header 4: CSeq: 102 NOTIFY (16) Aug 2 18:23:46 DEBUG[3962]: chan_sip.c:3357 parse_request: Header 5: From: ;tag=as2b87f8b9 (42) Aug 2 18:23:46 DEBUG[3962]: chan_sip.c:3357 parse_request: Header 6: Server: SJphone/1.60.289a (SJ Labs) (35) Aug 2 18:23:46 DEBUG[3962]: chan_sip.c:3357 parse_request: Header 7: To: "unknown";tag=79254603128430 (53) Aug 2 18:23:46 DEBUG[3962]: chan_sip.c:3357 parse_request: Header 8: (0) --- (8 headers 0 lines)--- Aug 2 18:23:46 DEBUG[3962]: chan_sip.c:1390 __sip_ack: ** SIP TIMER: Cancelling retransmit of packet (reply received) Retransid #41 Aug 2 18:23:46 DEBUG[3962]: chan_sip.c:1401 __sip_ack: Stopping retransmission on 'EC3876C9-D5F6-4AE9-B0E7-5B41CCA10C83@10.2.6.252' of Request 102: Match Found Aug 2 18:23:46 DEBUG[3957]: res_musiconhold.c:233 ast_moh_files_next: IAX2/Voop50294-2 Opened file 0 '/var/lib/asterisk/mohmp3/default' Aug 2 18:23:46 WARNING[4342]: file.c:587 ast_readaudio_callback: Failed to write frame -- Playing 'digits/7' (language 'no') Aug 2 18:23:46 DEBUG[4342]: channel.c:2363 set_format: Set channel SIP/803-081a7998 to write format ulaw Aug 2 18:23:46 DEBUG[4342]: channel.c:1336 ast_hangup: Hanging up channel 'SIP/803-081a7998' Aug 2 18:23:46 DEBUG[4342]: chan_sip.c:2415 sip_hangup: Hangup call SIP/803-081a7998, SIP callid EC3876C9-D5F6-4AE9-B0E7-5B41CCA10C83@10.2.6.252) Aug 2 18:23:46 DEBUG[4342]: chan_sip.c:2423 sip_hangup: update_call_counter(803) - decrement call limit counter Aug 2 18:23:46 DEBUG[4342]: chan_sip.c:2206 update_call_counter: Updating call counter for incoming call Aug 2 18:23:46 DEBUG[4337]: cdr_addon_mysql.c:206 mysql_log: cdr_mysql: inserting a CDR record. Aug 2 18:23:46 DEBUG[4342]: chan_sip.c:10201 sip_park_thread: Parked on extension '701' Aug 2 18:23:46 DEBUG[3956]: chan_sip.c:11670 sip_devicestate: Checking device state for peer 803 Aug 2 18:23:46 DEBUG[3956]: devicestate.c:187 do_state_change: Changing state for SIP/803 - state 1 (Not in use) Aug 2 18:23:46 DEBUG[3964]: chan_iax2.c:6508 socket_read: For call=2, set last=4484 Aug 2 18:23:46 DEBUG[4337]: cdr_addon_mysql.c:222 mysql_log: cdr_mysql: SQL command as follows: INSERT INTO cdr (calldate,clid,src,dst,dcontext,channel,dstchannel,lastapp,lastdata,duration,billsec,disposition,amaflags,accountcode) VALUES ('2006-08-02 18:23:42','','','195','usr_11_ctx', 'SIP/803-081a7998','IAX2/Voop50294-2','Dial','IAX2/Voop50294@Voop50294/195|120|T',4,4,'ANSWERED',3,'11') Aug 2 18:23:46 DEBUG[4344]: app_queue.c:490 changethread: Device 'SIP/803' changed to state '1' (Not in use) but we don't care because they're not a member of any queue. Aug 2 18:23:46 DEBUG[3964]: chan_iax2.c:6508 socket_read: For call=2, set last=4504 Aug 2 18:23:46 DEBUG[3964]: chan_iax2.c:6508 socket_read: For call=2, set last=4524 Aug 2 18:23:46 DEBUG[3964]: chan_iax2.c:6508 socket_read: For call=2, set last=4544 Aug 2 18:23:46 DEBUG[4337]: pbx.c:1522 pbx_substitute_variables_helper_full: Function result is '(null)' Aug 2 18:23:46 DEBUG[4337]: pbx.c:1522 pbx_substitute_variables_helper_full: Function result is '(null)' Aug 2 18:23:46 DEBUG[4337]: pbx.c:1522 pbx_substitute_variables_helper_full: Function result is '195' Aug 2 18:23:46 DEBUG[4337]: pbx.c:1522 pbx_substitute_variables_helper_full: Function result is 'usr_11_ctx' Aug 2 18:23:46 DEBUG[4337]: pbx.c:1522 pbx_substitute_variables_helper_full: Function result is 'SIP/803-081a7998' Aug 2 18:23:46 DEBUG[4337]: pbx.c:1522 pbx_substitute_variables_helper_full: Function result is 'IAX2/Voop50294-2' Aug 2 18:23:46 DEBUG[4337]: pbx.c:1522 pbx_substitute_variables_helper_full: Function result is 'Dial' Aug 2 18:23:46 DEBUG[4337]: pbx.c:1522 pbx_substitute_variables_helper_full: Function result is 'IAX2/Voop50294@Voop50294/195|120|T' Aug 2 18:23:46 DEBUG[4337]: pbx.c:1522 pbx_substitute_variables_helper_full: Function result is '2006-08-02 18:23:42' Aug 2 18:23:46 DEBUG[4337]: pbx.c:1522 pbx_substitute_variables_helper_full: Function result is '2006-08-02 18:23:42' Aug 2 18:23:46 DEBUG[4337]: pbx.c:1522 pbx_substitute_variables_helper_full: Function result is '2006-08-02 18:23:46' Aug 2 18:23:46 DEBUG[4337]: pbx.c:1522 pbx_substitute_variables_helper_full: Function result is '4' Aug 2 18:23:46 DEBUG[4337]: pbx.c:1522 pbx_substitute_variables_helper_full: Function result is '4' Aug 2 18:23:46 DEBUG[4337]: pbx.c:1522 pbx_substitute_variables_helper_full: Function result is 'ANSWERED' Aug 2 18:23:46 DEBUG[4337]: pbx.c:1522 pbx_substitute_variables_helper_full: Function result is 'DOCUMENTATION' Aug 2 18:23:46 DEBUG[4337]: pbx.c:1522 pbx_substitute_variables_helper_full: Function result is '11' Aug 2 18:23:46 DEBUG[4337]: pbx.c:1522 pbx_substitute_variables_helper_full: Function result is '1154535822.5' Aug 2 18:23:46 DEBUG[4337]: pbx.c:1522 pbx_substitute_variables_helper_full: Function result is '(null)' Aug 2 18:23:46 DEBUG[4337]: channel.c:1341 ast_hangup: Hanging up zombie 'SIPPeer/SIP/803-081a7998' Aug 2 18:23:46 DEBUG[3956]: devicestate.c:187 do_state_change: Changing state for SIPPeer/SIP/803 - state 4 (Invalid) Aug 2 18:23:46 DEBUG[4345]: app_queue.c:490 changethread: Device 'SIPPeer/SIP/803' changed to state '4' (Invalid) but we don't care because they're not a member of any queue. Aug 2 18:23:46 DEBUG[3964]: chan_iax2.c:6508 socket_read: For call=2, set last=4564 Aug 2 18:23:46 DEBUG[3964]: chan_iax2.c:6508 socket_read: For call=2, set last=4584 Aug 2 18:23:46 DEBUG[3964]: chan_iax2.c:6508 socket_read: For call=2, set last=4604 Aug 2 18:23:46 DEBUG[3964]: chan_iax2.c:6508 socket_read: For call=2, set last=4624 Aug 2 18:23:46 DEBUG[3964]: chan_iax2.c:6508 socket_read: For call=2, set last=4644 Aug 2 18:23:46 DEBUG[3964]: chan_iax2.c:6508 socket_read: For call=2, set last=4664 Aug 2 18:23:46 DEBUG[3964]: chan_iax2.c:6508 socket_read: For call=2, set last=4684 Aug 2 18:23:46 DEBUG[3964]: chan_iax2.c:6508 socket_read: For call=2, set last=4704 Aug 2 18:23:46 DEBUG[3964]: chan_iax2.c:6508 socket_read: For call=2, set last=4724 Aug 2 18:23:46 DEBUG[3964]: chan_iax2.c:6508 socket_read: For call=2, set last=4744 Aug 2 18:23:46 DEBUG[3964]: chan_iax2.c:6508 socket_read: For call=2, set last=4764 Aug 2 18:23:47 DEBUG[3964]: chan_iax2.c:6508 socket_read: For call=2, set last=4784 Aug 2 18:23:47 DEBUG[3964]: chan_iax2.c:6508 socket_read: For call=2, set last=4804 Aug 2 18:23:47 DEBUG[3964]: chan_iax2.c:6508 socket_read: For call=2, set last=4824 Aug 2 18:23:47 DEBUG[3964]: chan_iax2.c:6508 socket_read: For call=2, set last=4844 Aug 2 18:23:47 DEBUG[3964]: chan_iax2.c:6508 socket_read: For call=2, set last=4864 Aug 2 18:23:47 DEBUG[3964]: chan_iax2.c:6508 socket_read: For call=2, set last=4884 Aug 2 18:23:47 DEBUG[3964]: chan_iax2.c:6508 socket_read: For call=2, set last=4904 Aug 2 18:23:47 DEBUG[3964]: chan_iax2.c:6508 socket_read: For call=2, set last=4924 Aug 2 18:23:47 DEBUG[3964]: chan_iax2.c:6508 socket_read: For call=2, set last=4944 Aug 2 18:23:47 DEBUG[3964]: chan_iax2.c:6508 socket_read: For call=2, set last=4964 Aug 2 18:23:47 DEBUG[3964]: chan_iax2.c:6508 socket_read: For call=2, set last=4984 Aug 2 18:23:47 DEBUG[3964]: chan_iax2.c:6508 socket_read: For call=2, set last=5004 Aug 2 18:23:47 DEBUG[3964]: chan_iax2.c:6508 socket_read: For call=2, set last=5024 Aug 2 18:23:47 DEBUG[3964]: chan_iax2.c:6508 socket_read: For call=2, set last=5044 Aug 2 18:23:47 DEBUG[3964]: chan_iax2.c:6508 socket_read: For call=2, set last=5064 Aug 2 18:23:47 DEBUG[3964]: chan_iax2.c:6508 socket_read: For call=2, set last=5084 Aug 2 18:23:47 DEBUG[3964]: chan_iax2.c:6508 socket_read: For call=2, set last=5104 Aug 2 18:23:47 DEBUG[3964]: chan_iax2.c:6508 socket_read: For call=2, set last=5124 Aug 2 18:23:47 DEBUG[3964]: chan_iax2.c:6508 socket_read: For call=2, set last=5144 Aug 2 18:23:47 DEBUG[3964]: chan_iax2.c:6508 socket_read: For call=2, set last=5164 Aug 2 18:23:47 DEBUG[3964]: chan_iax2.c:6508 socket_read: For call=2, set last=5184 Aug 2 18:23:47 DEBUG[3964]: chan_iax2.c:6508 socket_read: For call=2, set last=5204 Aug 2 18:23:47 DEBUG[3964]: chan_iax2.c:6508 socket_read: For call=2, set last=5224 Aug 2 18:23:47 DEBUG[3964]: chan_iax2.c:6508 socket_read: For call=2, set last=5244 Aug 2 18:23:47 DEBUG[3964]: chan_iax2.c:6508 socket_read: For call=2, set last=5264 Aug 2 18:23:47 DEBUG[3964]: chan_iax2.c:6508 socket_read: For call=2, set last=5284 Aug 2 18:23:47 DEBUG[3964]: chan_iax2.c:6508 socket_read: For call=2, set last=5304 Aug 2 18:23:47 DEBUG[3964]: chan_iax2.c:6508 socket_read: For call=2, set last=5324 Aug 2 18:23:47 DEBUG[3964]: chan_iax2.c:6508 socket_read: For call=2, set last=5344 Aug 2 18:23:47 DEBUG[3964]: chan_iax2.c:6508 socket_read: For call=2, set last=5364 Aug 2 18:23:47 DEBUG[3964]: chan_iax2.c:6508 socket_read: For call=2, set last=5384 Aug 2 18:23:47 DEBUG[3964]: chan_iax2.c:6508 socket_read: For call=2, set last=5404 Aug 2 18:23:47 DEBUG[3964]: chan_iax2.c:6508 socket_read: For call=2, set last=5424 Aug 2 18:23:47 DEBUG[3964]: chan_iax2.c:6508 socket_read: For call=2, set last=5444 Aug 2 18:23:47 DEBUG[3964]: chan_iax2.c:6508 socket_read: For call=2, set last=5464 Aug 2 18:23:47 DEBUG[3964]: chan_iax2.c:6508 socket_read: For call=2, set last=5484 Destroying call 'EC3876C9-D5F6-4AE9-B0E7-5B41CCA10C83@10.2.6.252' Aug 2 18:23:47 DEBUG[3964]: chan_iax2.c:6508 socket_read: For call=2, set last=5504 Aug 2 18:23:47 DEBUG[3964]: chan_iax2.c:6508 socket_read: For call=2, set last=5524 Aug 2 18:23:47 DEBUG[3964]: chan_iax2.c:6508 socket_read: For call=2, set last=5544 Aug 2 18:23:47 DEBUG[3964]: chan_iax2.c:6508 socket_read: For call=2, set last=5564 Aug 2 18:23:47 DEBUG[3964]: chan_iax2.c:6508 socket_read: For call=2, set last=5584 Aug 2 18:23:47 DEBUG[3964]: chan_iax2.c:6508 socket_read: For call=2, set last=5604 Aug 2 18:23:47 DEBUG[3964]: chan_iax2.c:6508 socket_read: For call=2, set last=5624 Aug 2 18:23:47 DEBUG[3964]: chan_iax2.c:6508 socket_read: For call=2, set last=5644 Aug 2 18:23:47 DEBUG[3964]: chan_iax2.c:6508 socket_read: For call=2, set last=5664 Aug 2 18:23:47 DEBUG[3964]: chan_iax2.c:6508 socket_read: For call=2, set last=5684 Aug 2 18:23:47 DEBUG[3964]: chan_iax2.c:6508 socket_read: For call=2, set last=5704 Aug 2 18:23:47 DEBUG[3964]: chan_iax2.c:6508 socket_read: For call=2, set last=5724 Aug 2 18:23:47 DEBUG[3964]: chan_iax2.c:6508 socket_read: For call=2, set last=5744 Aug 2 18:23:47 DEBUG[3964]: chan_iax2.c:6508 socket_read: For call=2, set last=5764 Aug 2 18:23:47 DEBUG[3964]: chan_iax2.c:6508 socket_read: For call=2, set last=5784 Aug 2 18:23:47 DEBUG[3964]: chan_iax2.c:6508 socket_read: For call=2, set last=5804 Aug 2 18:23:48 DEBUG[3964]: chan_iax2.c:6508 socket_read: For call=2, set last=5824 Aug 2 18:23:48 DEBUG[3964]: chan_iax2.c:6508 socket_read: For call=2, set last=5844 Aug 2 18:23:48 DEBUG[3964]: chan_iax2.c:6508 socket_read: For call=2, set last=5864 Aug 2 18:23:48 DEBUG[3964]: chan_iax2.c:6508 socket_read: For call=2, set last=5884 Aug 2 18:23:48 DEBUG[3964]: chan_iax2.c:6508 socket_read: For call=2, set last=5904 Aug 2 18:23:48 DEBUG[3964]: chan_iax2.c:6508 socket_read: For call=2, set last=5924 Aug 2 18:23:48 DEBUG[3964]: chan_iax2.c:6508 socket_read: For call=2, set last=5944 Aug 2 18:23:48 DEBUG[3964]: chan_iax2.c:6508 socket_read: For call=2, set last=5964 Aug 2 18:23:48 DEBUG[3964]: chan_iax2.c:6508 socket_read: For call=2, set last=5984 Aug 2 18:23:48 DEBUG[3964]: chan_iax2.c:6508 socket_read: For call=2, set last=6004 Aug 2 18:23:48 DEBUG[3964]: chan_iax2.c:6508 socket_read: For call=2, set last=6024 Aug 2 18:23:48 DEBUG[3964]: chan_iax2.c:6508 socket_read: For call=2, set last=6044 Aug 2 18:23:48 DEBUG[3964]: chan_iax2.c:6508 socket_read: For call=2, set last=6064 Aug 2 18:23:48 DEBUG[3964]: chan_iax2.c:6508 socket_read: For call=2, set last=6084 Aug 2 18:23:48 DEBUG[3964]: chan_iax2.c:6508 socket_read: For call=2, set last=6104 Aug 2 18:23:48 DEBUG[3964]: chan_iax2.c:6508 socket_read: For call=2, set last=6124 Aug 2 18:23:48 DEBUG[3964]: chan_iax2.c:6508 socket_read: For call=2, set last=6144 Aug 2 18:23:48 DEBUG[3964]: chan_iax2.c:6508 socket_read: For call=2, set last=6164 Aug 2 18:23:48 DEBUG[3964]: chan_iax2.c:6508 socket_read: For call=2, set last=6184 Aug 2 18:23:48 DEBUG[3964]: chan_iax2.c:6508 socket_read: For call=2, set last=6204 Aug 2 18:23:48 DEBUG[3964]: chan_iax2.c:6508 socket_read: For call=2, set last=6224 Aug 2 18:23:48 DEBUG[3964]: chan_iax2.c:6508 socket_read: For call=2, set last=6244 Aug 2 18:23:48 DEBUG[3964]: chan_iax2.c:6508 socket_read: For call=2, set last=6264 Aug 2 18:23:48 DEBUG[3964]: chan_iax2.c:6508 socket_read: For call=2, set last=6284 Aug 2 18:23:48 DEBUG[3964]: chan_iax2.c:6508 socket_read: For call=2, set last=6304 Aug 2 18:23:48 DEBUG[3964]: chan_iax2.c:6508 socket_read: For call=2, set last=6324 Aug 2 18:23:48 DEBUG[3964]: chan_iax2.c:6508 socket_read: For call=2, set last=6344 Aug 2 18:23:48 DEBUG[3964]: chan_iax2.c:6508 socket_read: For call=2, set last=6364 Aug 2 18:23:48 DEBUG[3964]: chan_iax2.c:6508 socket_read: For call=2, set last=6384 Aug 2 18:23:48 DEBUG[3964]: chan_iax2.c:6508 socket_read: For call=2, set last=6404 Aug 2 18:23:48 DEBUG[3964]: chan_iax2.c:6508 socket_read: For call=2, set last=6424 Aug 2 18:23:48 DEBUG[3964]: chan_iax2.c:6508 socket_read: For call=2, set last=6444 Aug 2 18:23:48 DEBUG[3964]: chan_iax2.c:6508 socket_read: For call=2, set last=6464 Aug 2 18:23:48 DEBUG[3964]: chan_iax2.c:6508 socket_read: For call=2, set last=6484 Aug 2 18:23:48 DEBUG[3964]: chan_iax2.c:6508 socket_read: For call=2, set last=6504 Aug 2 18:23:48 DEBUG[3964]: chan_iax2.c:6508 socket_read: For call=2, set last=6524 Aug 2 18:23:48 DEBUG[3964]: chan_iax2.c:6508 socket_read: For call=2, set last=6544 Aug 2 18:23:48 DEBUG[3964]: chan_iax2.c:6508 socket_read: For call=2, set last=6564 Aug 2 18:23:48 DEBUG[3964]: chan_iax2.c:6508 socket_read: For call=2, set last=6584 Aug 2 18:23:48 DEBUG[3964]: chan_iax2.c:6508 socket_read: For call=2, set last=6604 Aug 2 18:23:48 DEBUG[3964]: chan_iax2.c:6508 socket_read: For call=2, set last=6624 Aug 2 18:23:48 DEBUG[3964]: chan_iax2.c:6508 socket_read: For call=2, set last=6644 Aug 2 18:23:48 DEBUG[3964]: chan_iax2.c:6508 socket_read: For call=2, set last=6664 Aug 2 18:23:48 DEBUG[3964]: chan_iax2.c:6508 socket_read: For call=2, set last=6684 Aug 2 18:23:48 DEBUG[3964]: chan_iax2.c:6508 socket_read: For call=2, set last=6704 Aug 2 18:23:48 DEBUG[3964]: chan_iax2.c:6508 socket_read: For call=2, set last=6724 Aug 2 18:23:48 DEBUG[3964]: chan_iax2.c:6508 socket_read: For call=2, set last=6744 Aug 2 18:23:48 DEBUG[3964]: chan_iax2.c:6508 socket_read: For call=2, set last=6764 Aug 2 18:23:49 DEBUG[3964]: chan_iax2.c:6508 socket_read: For call=2, set last=6784 Aug 2 18:23:49 DEBUG[3964]: chan_iax2.c:6508 socket_read: For call=2, set last=6804 Aug 2 18:23:49 DEBUG[3964]: chan_iax2.c:6508 socket_read: For call=2, set last=6824 Aug 2 18:23:49 DEBUG[3964]: chan_iax2.c:6508 socket_read: For call=2, set last=6844 Aug 2 18:23:49 DEBUG[3964]: chan_iax2.c:6508 socket_read: For call=2, set last=6864 ubuntu-test-1*CLI> <-- SIP read from 10.2.6.252:5060: OPTIONS sip:10.0.90.187 SIP/2.0 Via: SIP/2.0/UDP 10.2.6.252;rport;branch=z9hG4bK0a0206fc0000001044d0d1c8000070280000007f Content-Length: 0 Call-ID: 104EA4CC-255F-4AC3-AF98-27175FF91164@10.2.6.252 CSeq: 22 OPTIONS From: ;tag=79255307820181 Max-Forwards: 70 To: Aug 2 18:23:49 DEBUG[3962]: chan_sip.c:3357 parse_request: Header 0: OPTIONS sip:10.0.90.187 SIP/2.0 (31) Aug 2 18:23:49 DEBUG[3962]: chan_sip.c:3357 parse_request: Header 1: Via: SIP/2.0/UDP 10.2.6.252;rport;branch=z9hG4bK0a0206fc0000001044d0d1c8000070280000007f (88) Aug 2 18:23:49 DEBUG[3962]: chan_sip.c:3357 parse_request: Header 2: Content-Length: 0 (17) Aug 2 18:23:49 DEBUG[3962]: chan_sip.c:3357 parse_request: Header 3: Call-ID: 104EA4CC-255F-4AC3-AF98-27175FF91164@10.2.6.252 (56) Aug 2 18:23:49 DEBUG[3962]: chan_sip.c:3357 parse_request: Header 4: CSeq: 22 OPTIONS (16) Aug 2 18:23:49 DEBUG[3962]: chan_sip.c:3357 parse_request: Header 5: From: ;tag=79255307820181 (46) Aug 2 18:23:49 DEBUG[3962]: chan_sip.c:3357 parse_request: Header 6: Max-Forwards: 70 (16) Aug 2 18:23:49 DEBUG[3962]: chan_sip.c:3357 parse_request: Header 7: To: (21) Aug 2 18:23:49 DEBUG[3962]: chan_sip.c:3357 parse_request: Header 8: (0) --- (8 headers 0 lines)--- Aug 2 18:23:49 DEBUG[3962]: chan_sip.c:3141 sip_alloc: Allocating new SIP dialog for 104EA4CC-255F-4AC3-AF98-27175FF91164@10.2.6.252 - OPTIONS (No RTP) Aug 2 18:23:49 DEBUG[3962]: chan_sip.c:11139 handle_request: **** Received OPTIONS (3) - Command in SIP OPTIONS Looking for s in local (domain 10.0.90.187) Aug 2 18:23:49 DEBUG[3962]: res_config_mysql.c:125 realtime_mysql: MySQL RealTime: Retrieve SQL: SELECT * FROM realtime_ext WHERE exten = 's' AND context = 'user' AND priority = '1' Aug 2 18:23:49 DEBUG[3962]: res_config_mysql.c:636 mysql_reconnect: MySQL RealTime: Everything is fine. Aug 2 18:23:49 DEBUG[3962]: res_config_mysql.c:237 realtime_multi_mysql: MySQL RealTime: Retrieve SQL: SELECT * FROM realtime_ext WHERE exten LIKE '\_%' AND context = 'user' AND priority = '1' ORDER BY exten Aug 2 18:23:49 DEBUG[3962]: res_config_mysql.c:636 mysql_reconnect: MySQL RealTime: Everything is fine. Aug 2 18:23:49 DEBUG[3962]: res_config_mysql.c:125 realtime_mysql: MySQL RealTime: Retrieve SQL: SELECT * FROM realtime_ext WHERE exten = 's' AND context = 'phone' AND priority = '1' Aug 2 18:23:49 DEBUG[3962]: res_config_mysql.c:636 mysql_reconnect: MySQL RealTime: Everything is fine. Aug 2 18:23:49 DEBUG[3962]: res_config_mysql.c:237 realtime_multi_mysql: MySQL RealTime: Retrieve SQL: SELECT * FROM realtime_ext WHERE exten LIKE '\_%' AND context = 'phone' AND priority = '1' ORDER BY exten Aug 2 18:23:49 DEBUG[3962]: res_config_mysql.c:636 mysql_reconnect: MySQL RealTime: Everything is fine. Aug 2 18:23:49 DEBUG[3962]: res_config_mysql.c:125 realtime_mysql: MySQL RealTime: Retrieve SQL: SELECT * FROM realtime_ext WHERE exten = 's' AND context = 'group' AND priority = '1' Aug 2 18:23:49 DEBUG[3962]: res_config_mysql.c:636 mysql_reconnect: MySQL RealTime: Everything is fine. Aug 2 18:23:49 DEBUG[3962]: res_config_mysql.c:237 realtime_multi_mysql: MySQL RealTime: Retrieve SQL: SELECT * FROM realtime_ext WHERE exten LIKE '\_%' AND context = 'group' AND priority = '1' ORDER BY exten Aug 2 18:23:49 DEBUG[3962]: res_config_mysql.c:636 mysql_reconnect: MySQL RealTime: Everything is fine. Aug 2 18:23:49 DEBUG[3962]: res_config_mysql.c:125 realtime_mysql: MySQL RealTime: Retrieve SQL: SELECT * FROM realtime_ext WHERE exten = 's' AND context = 'service' AND priority = '1' Aug 2 18:23:49 DEBUG[3962]: res_config_mysql.c:636 mysql_reconnect: MySQL RealTime: Everything is fine. Aug 2 18:23:49 DEBUG[3962]: res_config_mysql.c:237 realtime_multi_mysql: MySQL RealTime: Retrieve SQL: SELECT * FROM realtime_ext WHERE exten LIKE '\_%' AND context = 'service' AND priority = '1' ORDER BY exten Aug 2 18:23:49 DEBUG[3962]: res_config_mysql.c:636 mysql_reconnect: MySQL RealTime: Everything is fine. Aug 2 18:23:49 DEBUG[3962]: res_config_mysql.c:125 realtime_mysql: MySQL RealTime: Retrieve SQL: SELECT * FROM realtime_ext WHERE exten = 's' AND context = 'did' AND priority = '1' Aug 2 18:23:49 DEBUG[3962]: res_config_mysql.c:636 mysql_reconnect: MySQL RealTime: Everything is fine. Aug 2 18:23:49 DEBUG[3964]: chan_iax2.c:6508 socket_read: For call=2, set last=6884 Aug 2 18:23:49 DEBUG[3962]: res_config_mysql.c:237 realtime_multi_mysql: MySQL RealTime: Retrieve SQL: SELECT * FROM realtime_ext WHERE exten LIKE '\_%' AND context = 'did' AND priority = '1' ORDER BY exten Aug 2 18:23:49 DEBUG[3962]: res_config_mysql.c:636 mysql_reconnect: MySQL RealTime: Everything is fine. Aug 2 18:23:49 DEBUG[3962]: res_config_mysql.c:125 realtime_mysql: MySQL RealTime: Retrieve SQL: SELECT * FROM realtime_ext WHERE exten LIKE 's%' AND context = 'user' AND priority = '1' Aug 2 18:23:49 DEBUG[3962]: res_config_mysql.c:636 mysql_reconnect: MySQL RealTime: Everything is fine. Aug 2 18:23:49 DEBUG[3962]: res_config_mysql.c:237 realtime_multi_mysql: MySQL RealTime: Retrieve SQL: SELECT * FROM realtime_ext WHERE exten LIKE '\_%' AND context = 'user' AND priority = '1' ORDER BY exten Aug 2 18:23:49 DEBUG[3962]: res_config_mysql.c:636 mysql_reconnect: MySQL RealTime: Everything is fine. Aug 2 18:23:49 DEBUG[3962]: res_config_mysql.c:125 realtime_mysql: MySQL RealTime: Retrieve SQL: SELECT * FROM realtime_ext WHERE exten LIKE 's%' AND context = 'phone' AND priority = '1' Aug 2 18:23:49 DEBUG[3962]: res_config_mysql.c:636 mysql_reconnect: MySQL RealTime: Everything is fine. Aug 2 18:23:49 DEBUG[3962]: res_config_mysql.c:237 realtime_multi_mysql: MySQL RealTime: Retrieve SQL: SELECT * FROM realtime_ext WHERE exten LIKE '\_%' AND context = 'phone' AND priority = '1' ORDER BY exten Aug 2 18:23:49 DEBUG[3962]: res_config_mysql.c:636 mysql_reconnect: MySQL RealTime: Everything is fine. Aug 2 18:23:49 DEBUG[3962]: res_config_mysql.c:125 realtime_mysql: MySQL RealTime: Retrieve SQL: SELECT * FROM realtime_ext WHERE exten LIKE 's%' AND context = 'group' AND priority = '1' Aug 2 18:23:49 DEBUG[3962]: res_config_mysql.c:636 mysql_reconnect: MySQL RealTime: Everything is fine. Aug 2 18:23:49 DEBUG[3962]: res_config_mysql.c:237 realtime_multi_mysql: MySQL RealTime: Retrieve SQL: SELECT * FROM realtime_ext WHERE exten LIKE '\_%' AND context = 'group' AND priority = '1' ORDER BY exten Aug 2 18:23:49 DEBUG[3962]: res_config_mysql.c:636 mysql_reconnect: MySQL RealTime: Everything is fine. Aug 2 18:23:49 DEBUG[3962]: res_config_mysql.c:125 realtime_mysql: MySQL RealTime: Retrieve SQL: SELECT * FROM realtime_ext WHERE exten LIKE 's%' AND context = 'service' AND priority = '1' Aug 2 18:23:49 DEBUG[3962]: res_config_mysql.c:636 mysql_reconnect: MySQL RealTime: Everything is fine. Aug 2 18:23:49 DEBUG[3962]: res_config_mysql.c:237 realtime_multi_mysql: MySQL RealTime: Retrieve SQL: SELECT * FROM realtime_ext WHERE exten LIKE '\_%' AND context = 'service' AND priority = '1' ORDER BY exten Aug 2 18:23:49 DEBUG[3962]: res_config_mysql.c:636 mysql_reconnect: MySQL RealTime: Everything is fine. Aug 2 18:23:49 DEBUG[3962]: res_config_mysql.c:125 realtime_mysql: MySQL RealTime: Retrieve SQL: SELECT * FROM realtime_ext WHERE exten LIKE 's%' AND context = 'did' AND priority = '1' Aug 2 18:23:49 DEBUG[3962]: res_config_mysql.c:636 mysql_reconnect: MySQL RealTime: Everything is fine. Aug 2 18:23:49 DEBUG[3962]: res_config_mysql.c:237 realtime_multi_mysql: MySQL RealTime: Retrieve SQL: SELECT * FROM realtime_ext WHERE exten LIKE '\_%' AND context = 'did' AND priority = '1' ORDER BY exten Aug 2 18:23:49 DEBUG[3962]: res_config_mysql.c:636 mysql_reconnect: MySQL RealTime: Everything is fine. Transmitting (no NAT) to 10.2.6.252:5060: SIP/2.0 404 Not Found Via: SIP/2.0/UDP 10.2.6.252;rport;branch=z9hG4bK0a0206fc0000001044d0d1c8000070280000007f;received=10.2.6.252 From: ;tag=79255307820181 To: ;tag=as17549eab Call-ID: 104EA4CC-255F-4AC3-AF98-27175FF91164@10.2.6.252 CSeq: 22 OPTIONS User-Agent: Diptel-T50 Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY Contact: Accept: application/sdp Content-Length: 0 --- Aug 2 18:23:49 DEBUG[3962]: chan_sip.c:11340 sipsock_read: SIP message could not be handled, bad request: 104EA4CC-255F-4AC3-AF98-27175FF91164@10.2.6.252 Destroying call '104EA4CC-255F-4AC3-AF98-27175FF91164@10.2.6.252' Aug 2 18:23:49 DEBUG[3964]: chan_iax2.c:6508 socket_read: For call=2, set last=6904 Aug 2 18:23:49 DEBUG[3964]: chan_iax2.c:6508 socket_read: For call=2, set last=6924 Aug 2 18:23:49 DEBUG[3964]: chan_iax2.c:6508 socket_read: For call=2, set last=6944 Aug 2 18:23:49 DEBUG[3964]: chan_iax2.c:6508 socket_read: For call=2, set last=6964 Aug 2 18:23:49 DEBUG[3964]: chan_iax2.c:6508 socket_read: For call=2, set last=6984 Aug 2 18:23:49 DEBUG[3964]: chan_iax2.c:6508 socket_read: For call=2, set last=7004 Aug 2 18:23:49 DEBUG[3964]: chan_iax2.c:6508 socket_read: For call=2, set last=7024 Aug 2 18:23:49 DEBUG[3964]: chan_iax2.c:6508 socket_read: For call=2, set last=7044 Aug 2 18:23:49 DEBUG[3964]: chan_iax2.c:6508 socket_read: For call=2, set last=7064 Aug 2 18:23:49 DEBUG[3964]: chan_iax2.c:6508 socket_read: For call=2, set last=7084 Aug 2 18:23:49 DEBUG[3964]: chan_iax2.c:6508 socket_read: For call=2, set last=7264 Aug 2 18:23:49 DEBUG[3964]: chan_iax2.c:6508 socket_read: For call=2, set last=7284 Aug 2 18:23:49 DEBUG[3964]: chan_iax2.c:6508 socket_read: For call=2, set last=7304 Aug 2 18:23:49 DEBUG[3964]: chan_iax2.c:6508 socket_read: For call=2, set last=7324 Aug 2 18:23:49 DEBUG[3964]: chan_iax2.c:6508 socket_read: For call=2, set last=7344 Aug 2 18:23:49 DEBUG[3964]: chan_iax2.c:6508 socket_read: For call=2, set last=7364 Aug 2 18:23:49 DEBUG[3964]: chan_iax2.c:6508 socket_read: For call=2, set last=7384 Aug 2 18:23:49 DEBUG[3964]: chan_iax2.c:6508 socket_read: For call=2, set last=7404 Aug 2 18:23:49 DEBUG[3964]: chan_iax2.c:6508 socket_read: For call=2, set last=7424 Aug 2 18:23:49 DEBUG[3964]: chan_iax2.c:6508 socket_read: For call=2, set last=7444 Aug 2 18:23:49 DEBUG[3964]: chan_iax2.c:6508 socket_read: For call=2, set last=7464 Aug 2 18:23:49 DEBUG[3964]: chan_iax2.c:6508 socket_read: For call=2, set last=7484 Aug 2 18:23:49 DEBUG[3964]: chan_iax2.c:6508 socket_read: For call=2, set last=7504 Aug 2 18:23:49 DEBUG[3964]: chan_iax2.c:6508 socket_read: For call=2, set last=7524 Aug 2 18:23:49 DEBUG[3964]: chan_iax2.c:6508 socket_read: For call=2, set last=7544 Aug 2 18:23:49 DEBUG[3964]: chan_iax2.c:6508 socket_read: For call=2, set last=7564 Aug 2 18:23:49 DEBUG[3964]: chan_iax2.c:6508 socket_read: For call=2, set last=7584 Aug 2 18:23:49 DEBUG[3964]: chan_iax2.c:6508 socket_read: For call=2, set last=7604 Aug 2 18:23:49 DEBUG[3964]: chan_iax2.c:6508 socket_read: For call=2, set last=7624 Aug 2 18:23:49 DEBUG[3964]: chan_iax2.c:6508 socket_read: For call=2, set last=7644 Aug 2 18:23:49 DEBUG[3964]: chan_iax2.c:6508 socket_read: For call=2, set last=7664 < log from manager > Event: Newcallerid Privilege: call,all Channel: SIP/803-081a7998 CallerID: 803 CallerIDName: unknown Uniqueid: 1154535822.5 CID-CallingPres: 0 (Presentation Allowed, Not Screened) Event: Newchannel Privilege: call,all Channel: SIP/803-081a7998 State: Ring CallerID: 803 CallerIDName: unknown Uniqueid: 1154535822.5 Event: Newexten Privilege: call,all Channel: SIP/803-081a7998 Context: usr_11_ctx Extension: 195 Priority: 1 Application: Macro AppData: c_pstn|21568690|Voop50294|Voop50294|IAX2 Uniqueid: 1154535822.5 Event: Newexten Privilege: call,all Channel: SIP/803-081a7998 Context: macro-c_pstn Extension: s Priority: 1 Application: Answer AppData: Uniqueid: 1154535822.5 Event: Newstate Privilege: call,all Channel: SIP/803-081a7998 State: Up CallerID: 803 CallerIDName: unknown Uniqueid: 1154535822.5 Event: Newexten Privilege: call,all Channel: SIP/803-081a7998 Context: macro-c_pstn Extension: s Priority: 2 Application: NoOp AppData: "Calling: 195 from 21568690 (IAX2/Voop50294@Voop50294)" Uniqueid: 1154535822.5 Event: Newexten Privilege: call,all Channel: SIP/803-081a7998 Context: macro-c_pstn Extension: s Priority: 3 Application: SetCallerID AppData: 21568690 Uniqueid: 1154535822.5 Event: Newcallerid Privilege: call,all Channel: SIP/803-081a7998 CallerID: 21568690 CallerIDName: Uniqueid: 1154535822.5 CID-CallingPres: 0 (Presentation Allowed, Not Screened) Event: Newexten Privilege: call,all Channel: SIP/803-081a7998 Context: macro-c_pstn Extension: s Priority: 4 Application: Dial AppData: IAX2/Voop50294@Voop50294/195|120|T Uniqueid: 1154535822.5 Event: Newcallerid Privilege: call,all Channel: IAX2/Voop50294-2 CallerID: CallerIDName: Uniqueid: 1154535822.6 CID-CallingPres: 0 (Presentation Allowed, Not Screened) Event: Newchannel Privilege: call,all Channel: IAX2/Voop50294-2 State: Down CallerID: CallerIDName: Uniqueid: 1154535822.6 Event: Newchannel Privilege: call,all Channel: IAX2/Voop50294-2 State: Ringing CallerID: 21568690 CallerIDName: Uniqueid: 1154535822.6 Event: Dial Privilege: call,all Source: SIP/803-081a7998 Destination: IAX2/Voop50294-2 CallerID: 21568690 CallerIDName: SrcUniqueID: 1154535822.5 DestUniqueID: 1154535822.6 Event: Newcallerid Privilege: call,all Channel: IAX2/Voop50294-2 CallerID: 195 CallerIDName: Uniqueid: 1154535822.6 CID-CallingPres: 0 (Presentation Allowed, Not Screened) Event: Newstate Privilege: call,all Channel: IAX2/Voop50294-2 State: Up CallerID: 195 CallerIDName: Uniqueid: 1154535822.6 Event: Link Privilege: call,all Channel1: SIP/803-081a7998 Channel2: IAX2/Voop50294-2 Uniqueid1: 1154535822.5 Uniqueid2: 1154535822.6 CallerID1: 21568690 CallerID2: 195 Event: Rename Privilege: call,all Oldname: SIP/803-081a7998 Newname: SIP/803-081a7998 Uniqueid: 1154535822.5 Event: Rename Privilege: call,all Oldname: SIPPeer/SIP/803-081a7998 Newname: SIP/803-081a7998 Uniqueid: 1154535826.8 Event: Rename Privilege: call,all Oldname: SIP/803-081a7998 Newname: SIPPeer/SIP/803-081a7998 Uniqueid: 1154535822.5 Event: Unlink Privilege: call,all Channel1: SIPPeer/SIP/803-081a7998 Channel2: IAX2/Voop50294-2 Uniqueid1: 1154535822.5 Uniqueid2: 1154535822.6 CallerID1: (null) CallerID2: 195 Event: Rename Privilege: call,all Oldname: IAX2/Voop50294-2 Newname: IAX2/Voop50294-2 Uniqueid: 1154535822.6 Event: Rename Privilege: call,all Oldname: Parking/IAX2/Voop50294-2 Newname: IAX2/Voop50294-2 Uniqueid: 1154535826.7 Event: Rename Privilege: call,all Oldname: IAX2/Voop50294-2 Newname: Parking/IAX2/Voop50294-2 Uniqueid: 1154535822.6 Event: Hangup Privilege: call,all Channel: Parking/IAX2/Voop50294-2 Uniqueid: 1154535822.6 Cause: 16 Cause-txt: Normal Clearing Event: ParkedCall Privilege: call,all Exten: 701 Channel: IAX2/Voop50294-2 From: SIP/803-081a7998 Timeout: 45 CallerID: 195 CallerIDName: Event: Hangup Privilege: call,all Channel: SIP/803-081a7998 Uniqueid: 1154535826.8 Cause: 16 Cause-txt: Normal Clearing Event: Hangup Privilege: call,all Channel: SIPPeer/SIP/803-081a7998 Uniqueid: 1154535822.5 Cause: 16 Cause-txt: Normal Clearing