<--- SIP read from 195.94.224.214:5060 ---> INVITE sip:02210797@195.94.224.208 SIP/2.0 Via: SIP/2.0/UDP 195.94.224.214:5060;branch=z9hG4bK-5d51b653;rport From: 1000 ;tag=161735ab18970493o0 To: Call-ID: bc01fd8b-34f7de33@195.94.224.214 CSeq: 101 INVITE Max-Forwards: 70 Contact: 1000 Expires: 240 User-Agent: Sipura/SPA1001-2.0.13(SEg) Content-Length: 430 Allow: ACK, BYE, CANCEL, INFO, INVITE, NOTIFY, OPTIONS, REFER Supported: x-sipura Content-Type: application/sdp v=0 o=- 36242371 36242371 IN IP4 195.94.224.214 s=- c=IN IP4 195.94.224.214 t=0 0 m=audio 16482 RTP/AVP 18 0 2 4 8 96 97 98 100 101 a=rtpmap:18 G729a/8000 a=rtpmap:0 PCMU/8000 a=rtpmap:2 G726-32/8000 a=rtpmap:4 G723/8000 a=rtpmap:8 PCMA/8000 a=rtpmap:96 G726-40/8000 a=rtpmap:97 G726-24/8000 a=rtpmap:98 G726-16/8000 a=rtpmap:100 NSE/8000 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-15 a=ptime:30 a=sendrecv <-------------> [Nov 14 17:25:29] DEBUG[22186]: chan_sip.c:4602 parse_request: Header 0 [ 42]: INVITE sip:02210797@195.94.224.208 SIP/2.0 [Nov 14 17:25:29] DEBUG[22186]: chan_sip.c:4602 parse_request: Header 1 [ 66]: Via: SIP/2.0/UDP 195.94.224.214:5060;branch=z9hG4bK-5d51b653;rport [Nov 14 17:25:29] DEBUG[22186]: chan_sip.c:4602 parse_request: Header 2 [ 59]: From: 1000 ;tag=161735ab18970493o0 [Nov 14 17:25:29] DEBUG[22186]: chan_sip.c:4602 parse_request: Header 3 [ 33]: To: [Nov 14 17:25:29] DEBUG[22186]: chan_sip.c:4602 parse_request: Header 4 [ 41]: Call-ID: bc01fd8b-34f7de33@195.94.224.214 [Nov 14 17:25:29] DEBUG[22186]: chan_sip.c:4602 parse_request: Header 5 [ 16]: CSeq: 101 INVITE [Nov 14 17:25:29] DEBUG[22186]: chan_sip.c:4602 parse_request: Header 6 [ 16]: Max-Forwards: 70 [Nov 14 17:25:29] DEBUG[22186]: chan_sip.c:4602 parse_request: Header 7 [ 44]: Contact: 1000 [Nov 14 17:25:29] DEBUG[22186]: chan_sip.c:4602 parse_request: Header 8 [ 12]: Expires: 240 [Nov 14 17:25:29] DEBUG[22186]: chan_sip.c:4602 parse_request: Header 9 [ 38]: User-Agent: Sipura/SPA1001-2.0.13(SEg) [Nov 14 17:25:29] DEBUG[22186]: chan_sip.c:4602 parse_request: Header 10 [ 19]: Content-Length: 430 [Nov 14 17:25:29] DEBUG[22186]: chan_sip.c:4602 parse_request: Header 11 [ 61]: Allow: ACK, BYE, CANCEL, INFO, INVITE, NOTIFY, OPTIONS, REFER [Nov 14 17:25:29] DEBUG[22186]: chan_sip.c:4602 parse_request: Header 12 [ 19]: Supported: x-sipura [Nov 14 17:25:29] DEBUG[22186]: chan_sip.c:4602 parse_request: Header 13 [ 29]: Content-Type: application/sdp [Nov 14 17:25:29] DEBUG[22186]: chan_sip.c:4602 parse_request: Header 14 [ 0]: [Nov 14 17:25:29] DEBUG[22186]: chan_sip.c:4602 parse_request: Body 0 [ 3]: v=0 [Nov 14 17:25:29] DEBUG[22186]: chan_sip.c:4602 parse_request: Body 1 [ 43]: o=- 36242371 36242371 IN IP4 195.94.224.214 [Nov 14 17:25:29] DEBUG[22186]: chan_sip.c:4602 parse_request: Body 2 [ 3]: s=- [Nov 14 17:25:29] DEBUG[22186]: chan_sip.c:4602 parse_request: Body 3 [ 23]: c=IN IP4 195.94.224.214 [Nov 14 17:25:29] DEBUG[22186]: chan_sip.c:4602 parse_request: Body 4 [ 5]: t=0 0 [Nov 14 17:25:29] DEBUG[22186]: chan_sip.c:4602 parse_request: Body 5 [ 49]: m=audio 16482 RTP/AVP 18 0 2 4 8 96 97 98 100 101 [Nov 14 17:25:29] DEBUG[22186]: chan_sip.c:4602 parse_request: Body 6 [ 22]: a=rtpmap:18 G729a/8000 [Nov 14 17:25:29] DEBUG[22186]: chan_sip.c:4602 parse_request: Body 7 [ 20]: a=rtpmap:0 PCMU/8000 [Nov 14 17:25:29] DEBUG[22186]: chan_sip.c:4602 parse_request: Body 8 [ 23]: a=rtpmap:2 G726-32/8000 [Nov 14 17:25:29] DEBUG[22186]: chan_sip.c:4602 parse_request: Body 9 [ 20]: a=rtpmap:4 G723/8000 [Nov 14 17:25:29] DEBUG[22186]: chan_sip.c:4602 parse_request: Body 10 [ 20]: a=rtpmap:8 PCMA/8000 [Nov 14 17:25:29] DEBUG[22186]: chan_sip.c:4602 parse_request: Body 11 [ 24]: a=rtpmap:96 G726-40/8000 [Nov 14 17:25:29] DEBUG[22186]: chan_sip.c:4602 parse_request: Body 12 [ 24]: a=rtpmap:97 G726-24/8000 [Nov 14 17:25:29] DEBUG[22186]: chan_sip.c:4602 parse_request: Body 13 [ 24]: a=rtpmap:98 G726-16/8000 [Nov 14 17:25:29] DEBUG[22186]: chan_sip.c:4602 parse_request: Body 14 [ 21]: a=rtpmap:100 NSE/8000 [Nov 14 17:25:29] DEBUG[22186]: chan_sip.c:4602 parse_request: Body 15 [ 33]: a=rtpmap:101 telephone-event/8000 [Nov 14 17:25:29] DEBUG[22186]: chan_sip.c:4602 parse_request: Body 16 [ 15]: a=fmtp:101 0-15 [Nov 14 17:25:29] DEBUG[22186]: chan_sip.c:4602 parse_request: Body 17 [ 10]: a=ptime:30 [Nov 14 17:25:29] DEBUG[22186]: chan_sip.c:4602 parse_request: Body 18 [ 10]: a=sendrecv --- (14 headers 19 lines) --- [Nov 14 17:25:29] DEBUG[22186]: chan_sip.c:4401 find_call: = No match Their Call ID: e7097cd816051d56@00304f4d7e30-1 Their Tag 78161 Our tag: as40911e15 [Nov 14 17:25:29] DEBUG[22186]: chan_sip.c:4401 find_call: = No match Their Call ID: 1a91c35355d773b1@192.168.200.234 Their Tag 6c141872b4972e95 Our tag: as38748131 [Nov 14 17:25:29] DEBUG[22186]: chan_sip.c:4401 find_call: = No match Their Call ID: 1a91c35355d773b1@192.168.200.247 Their Tag 6c141872b4972e95 Our tag: as17678152 [Nov 14 17:25:29] DEBUG[22186]: chan_sip.c:4401 find_call: = No match Their Call ID: bfb1420b-573d5f06@195.94.224.214 Their Tag a2fdee4712b03ffao0 Our tag: as57e699ee [Nov 14 17:25:29] DEBUG[22186]: chan_sip.c:4401 find_call: = No match Their Call ID: chxiakn3nupUijLX@192.168.1.2 Their Tag EJnxD1Oalor3SsCS Our tag: as5e66093e [Nov 14 17:25:29] DEBUG[22186]: chan_sip.c:4401 find_call: = No match Their Call ID: 81521501-c97db9cc@192.168.11.254 Their Tag 8ba4182988eb50c4o1 Our tag: as2ec1dc3e [Nov 14 17:25:29] DEBUG[22186]: chan_sip.c:4401 find_call: = No match Their Call ID: 167278e5-d7740738@192.168.11.254 Their Tag c7d24d149a16c3co0 Our tag: as5bef2479 [Nov 14 17:25:29] DEBUG[22186]: chan_sip.c:2651 do_setnat: Setting NAT on RTP to Off [Nov 14 17:25:29] DEBUG[22186]: chan_sip.c:2656 do_setnat: Setting NAT on VRTP to Off [Nov 14 17:25:29] DEBUG[22186]: chan_sip.c:4337 sip_alloc: Allocating new SIP dialog for bc01fd8b-34f7de33@195.94.224.214 - INVITE (With RTP) [Nov 14 17:25:29] DEBUG[22186]: chan_sip.c:14546 handle_request: **** Received INVITE (5) - Command in SIP INVITE [Nov 14 17:25:29] DEBUG[22186]: chan_sip.c:1689 parse_sip_options: Begin: parsing SIP "Supported: x-sipura" [Nov 14 17:25:29] DEBUG[22186]: chan_sip.c:1697 parse_sip_options: Found SIP option: -x-sipura- [Nov 14 17:25:29] DEBUG[22186]: chan_sip.c:1709 parse_sip_options: Found private SIP option, not supported: x-sipura Sending to 195.94.224.214 : 5060 (NAT) Using INVITE request as basis request - bc01fd8b-34f7de33@195.94.224.214 [Nov 14 17:25:29] DEBUG[22186]: res_config_mysql.c:809 mysql_reconnect: MySQL RealTime: Everything is fine. [Nov 14 17:25:29] DEBUG[22186]: res_config_mysql.c:139 realtime_mysql: MySQL RealTime: Retrieve SQL: SELECT * FROM sip WHERE name = '1000' Found user '1000' for '1000' [Nov 14 17:25:29] DEBUG[22186]: chan_sip.c:2651 do_setnat: Setting NAT on RTP to On [Nov 14 17:25:29] DEBUG[22186]: chan_sip.c:2656 do_setnat: Setting NAT on VRTP to On <--- Reliably Transmitting (NAT) to 195.94.224.214:5060 ---> SIP/2.0 401 Unauthorized Via: SIP/2.0/UDP 195.94.224.214:5060;branch=z9hG4bK-5d51b653;received=195.94.224.214;rport=5060 From: 1000 ;tag=161735ab18970493o0 To: ;tag=as46aa815d Call-ID: bc01fd8b-34f7de33@195.94.224.214 CSeq: 101 INVITE User-Agent: Asterisk PBX Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY Supported: replaces WWW-Authenticate: Digest algorithm=MD5, realm="asterisk", nonce="5c3e2137" Content-Length: 0 <------------> [Nov 14 17:25:29] DEBUG[22186]: chan_sip.c:1979 __sip_reliable_xmit: *** SIP TIMER: Initalizing retransmit timer on packet: Id #1463 Scheduling destruction of SIP dialog 'bc01fd8b-34f7de33@195.94.224.214' in 32000 ms (Method: INVITE) [Nov 14 17:25:29] DEBUG[22186]: chan_sip.c:2576 sip_destroy_user: Destroying user object from memory: 1000 <--- SIP read from 195.94.224.214:5060 ---> ACK sip:02210797@195.94.224.208 SIP/2.0 Via: SIP/2.0/UDP 195.94.224.214:5060;branch=z9hG4bK-5d51b653;rport From: 1000 ;tag=161735ab18970493o0 To: ;tag=as46aa815d Call-ID: bc01fd8b-34f7de33@195.94.224.214 CSeq: 101 ACK Max-Forwards: 70 Contact: 1000 User-Agent: Sipura/SPA1001-2.0.13(SEg) Content-Length: 0 <-------------> [Nov 14 17:25:29] DEBUG[22186]: chan_sip.c:4602 parse_request: Header 0 [ 39]: ACK sip:02210797@195.94.224.208 SIP/2.0 [Nov 14 17:25:29] DEBUG[22186]: chan_sip.c:4602 parse_request: Header 1 [ 66]: Via: SIP/2.0/UDP 195.94.224.214:5060;branch=z9hG4bK-5d51b653;rport [Nov 14 17:25:29] DEBUG[22186]: chan_sip.c:4602 parse_request: Header 2 [ 59]: From: 1000 ;tag=161735ab18970493o0 [Nov 14 17:25:29] DEBUG[22186]: chan_sip.c:4602 parse_request: Header 3 [ 48]: To: ;tag=as46aa815d [Nov 14 17:25:29] DEBUG[22186]: chan_sip.c:4602 parse_request: Header 4 [ 41]: Call-ID: bc01fd8b-34f7de33@195.94.224.214 [Nov 14 17:25:29] DEBUG[22186]: chan_sip.c:4602 parse_request: Header 5 [ 13]: CSeq: 101 ACK [Nov 14 17:25:29] DEBUG[22186]: chan_sip.c:4602 parse_request: Header 6 [ 16]: Max-Forwards: 70 [Nov 14 17:25:29] DEBUG[22186]: chan_sip.c:4602 parse_request: Header 7 [ 44]: Contact: 1000 [Nov 14 17:25:29] DEBUG[22186]: chan_sip.c:4602 parse_request: Header 8 [ 38]: User-Agent: Sipura/SPA1001-2.0.13(SEg) [Nov 14 17:25:29] DEBUG[22186]: chan_sip.c:4602 parse_request: Header 9 [ 17]: Content-Length: 0 [Nov 14 17:25:29] DEBUG[22186]: chan_sip.c:4602 parse_request: Header 10 [ 0]: --- (10 headers 0 lines) --- [Nov 14 17:25:29] DEBUG[22186]: chan_sip.c:4401 find_call: = Found Their Call ID: bc01fd8b-34f7de33@195.94.224.214 Their Tag 161735ab18970493o0 Our tag: as46aa815d [Nov 14 17:25:29] DEBUG[22186]: chan_sip.c:14546 handle_request: **** Received ACK (6) - Command in SIP ACK [Nov 14 17:25:29] DEBUG[22186]: chan_sip.c:2078 __sip_ack: ** SIP TIMER: Cancelling retransmit of packet (reply received) Retransid #1463 [Nov 14 17:25:29] DEBUG[22186]: chan_sip.c:2088 __sip_ack: Stopping retransmission on 'bc01fd8b-34f7de33@195.94.224.214' of Response 101: Match Found <--- SIP read from 195.94.224.214:5060 ---> INVITE sip:02210797@195.94.224.208 SIP/2.0 Via: SIP/2.0/UDP 195.94.224.214:5060;branch=z9hG4bK-d70fe19b;rport From: 1000 ;tag=161735ab18970493o0 To: Call-ID: bc01fd8b-34f7de33@195.94.224.214 CSeq: 102 INVITE Max-Forwards: 70 Authorization: Digest username="1000",realm="asterisk",nonce="5c3e2137",uri="sip:02210797@195.94.224.208",algorithm=MD5,response="cb8462833134ed53771bcb9e0e894537" Contact: 1000 Expires: 240 User-Agent: Sipura/SPA1001-2.0.13(SEg) Content-Length: 430 Allow: ACK, BYE, CANCEL, INFO, INVITE, NOTIFY, OPTIONS, REFER Supported: x-sipura Content-Type: application/sdp v=0 o=- 36242371 36242371 IN IP4 195.94.224.214 s=- c=IN IP4 195.94.224.214 t=0 0 m=audio 16482 RTP/AVP 18 0 2 4 8 96 97 98 100 101 a=rtpmap:18 G729a/8000 a=rtpmap:0 PCMU/8000 a=rtpmap:2 G726-32/8000 a=rtpmap:4 G723/8000 a=rtpmap:8 PCMA/8000 a=rtpmap:96 G726-40/8000 a=rtpmap:97 G726-24/8000 a=rtpmap:98 G726-16/8000 a=rtpmap:100 NSE/8000 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-15 a=ptime:30 a=sendrecv <-------------> [Nov 14 17:25:29] DEBUG[22186]: chan_sip.c:4602 parse_request: Header 0 [ 42]: INVITE sip:02210797@195.94.224.208 SIP/2.0 [Nov 14 17:25:29] DEBUG[22186]: chan_sip.c:4602 parse_request: Header 1 [ 66]: Via: SIP/2.0/UDP 195.94.224.214:5060;branch=z9hG4bK-d70fe19b;rport [Nov 14 17:25:29] DEBUG[22186]: chan_sip.c:4602 parse_request: Header 2 [ 59]: From: 1000 ;tag=161735ab18970493o0 [Nov 14 17:25:29] DEBUG[22186]: chan_sip.c:4602 parse_request: Header 3 [ 33]: To: [Nov 14 17:25:29] DEBUG[22186]: chan_sip.c:4602 parse_request: Header 4 [ 41]: Call-ID: bc01fd8b-34f7de33@195.94.224.214 [Nov 14 17:25:29] DEBUG[22186]: chan_sip.c:4602 parse_request: Header 5 [ 16]: CSeq: 102 INVITE [Nov 14 17:25:29] DEBUG[22186]: chan_sip.c:4602 parse_request: Header 6 [ 16]: Max-Forwards: 70 [Nov 14 17:25:29] DEBUG[22186]: chan_sip.c:4602 parse_request: Header 7 [163]: Authorization: Digest username="1000",realm="asterisk",nonce="5c3e2137",uri="sip:02210797@195.94.224.208",algorithm=MD5,response="cb8462833134ed53771bcb9e0e894537" [Nov 14 17:25:29] DEBUG[22186]: chan_sip.c:4602 parse_request: Header 8 [ 44]: Contact: 1000 [Nov 14 17:25:29] DEBUG[22186]: chan_sip.c:4602 parse_request: Header 9 [ 12]: Expires: 240 [Nov 14 17:25:29] DEBUG[22186]: chan_sip.c:4602 parse_request: Header 10 [ 38]: User-Agent: Sipura/SPA1001-2.0.13(SEg) [Nov 14 17:25:29] DEBUG[22186]: chan_sip.c:4602 parse_request: Header 11 [ 19]: Content-Length: 430 [Nov 14 17:25:29] DEBUG[22186]: chan_sip.c:4602 parse_request: Header 12 [ 61]: Allow: ACK, BYE, CANCEL, INFO, INVITE, NOTIFY, OPTIONS, REFER [Nov 14 17:25:29] DEBUG[22186]: chan_sip.c:4602 parse_request: Header 13 [ 19]: Supported: x-sipura [Nov 14 17:25:29] DEBUG[22186]: chan_sip.c:4602 parse_request: Header 14 [ 29]: Content-Type: application/sdp [Nov 14 17:25:29] DEBUG[22186]: chan_sip.c:4602 parse_request: Header 15 [ 0]: [Nov 14 17:25:29] DEBUG[22186]: chan_sip.c:4602 parse_request: Body 0 [ 3]: v=0 [Nov 14 17:25:29] DEBUG[22186]: chan_sip.c:4602 parse_request: Body 1 [ 43]: o=- 36242371 36242371 IN IP4 195.94.224.214 [Nov 14 17:25:29] DEBUG[22186]: chan_sip.c:4602 parse_request: Body 2 [ 3]: s=- [Nov 14 17:25:29] DEBUG[22186]: chan_sip.c:4602 parse_request: Body 3 [ 23]: c=IN IP4 195.94.224.214 [Nov 14 17:25:29] DEBUG[22186]: chan_sip.c:4602 parse_request: Body 4 [ 5]: t=0 0 [Nov 14 17:25:29] DEBUG[22186]: chan_sip.c:4602 parse_request: Body 5 [ 49]: m=audio 16482 RTP/AVP 18 0 2 4 8 96 97 98 100 101 [Nov 14 17:25:29] DEBUG[22186]: chan_sip.c:4602 parse_request: Body 6 [ 22]: a=rtpmap:18 G729a/8000 [Nov 14 17:25:29] DEBUG[22186]: chan_sip.c:4602 parse_request: Body 7 [ 20]: a=rtpmap:0 PCMU/8000 [Nov 14 17:25:29] DEBUG[22186]: chan_sip.c:4602 parse_request: Body 8 [ 23]: a=rtpmap:2 G726-32/8000 [Nov 14 17:25:29] DEBUG[22186]: chan_sip.c:4602 parse_request: Body 9 [ 20]: a=rtpmap:4 G723/8000 [Nov 14 17:25:29] DEBUG[22186]: chan_sip.c:4602 parse_request: Body 10 [ 20]: a=rtpmap:8 PCMA/8000 [Nov 14 17:25:29] DEBUG[22186]: chan_sip.c:4602 parse_request: Body 11 [ 24]: a=rtpmap:96 G726-40/8000 [Nov 14 17:25:29] DEBUG[22186]: chan_sip.c:4602 parse_request: Body 12 [ 24]: a=rtpmap:97 G726-24/8000 [Nov 14 17:25:29] DEBUG[22186]: chan_sip.c:4602 parse_request: Body 13 [ 24]: a=rtpmap:98 G726-16/8000 [Nov 14 17:25:29] DEBUG[22186]: chan_sip.c:4602 parse_request: Body 14 [ 21]: a=rtpmap:100 NSE/8000 [Nov 14 17:25:29] DEBUG[22186]: chan_sip.c:4602 parse_request: Body 15 [ 33]: a=rtpmap:101 telephone-event/8000 [Nov 14 17:25:29] DEBUG[22186]: chan_sip.c:4602 parse_request: Body 16 [ 15]: a=fmtp:101 0-15 [Nov 14 17:25:29] DEBUG[22186]: chan_sip.c:4602 parse_request: Body 17 [ 10]: a=ptime:30 [Nov 14 17:25:29] DEBUG[22186]: chan_sip.c:4602 parse_request: Body 18 [ 10]: a=sendrecv --- (15 headers 19 lines) --- [Nov 14 17:25:29] DEBUG[22186]: chan_sip.c:4401 find_call: = Found Their Call ID: bc01fd8b-34f7de33@195.94.224.214 Their Tag 161735ab18970493o0 Our tag: as46aa815d [Nov 14 17:25:29] DEBUG[22186]: chan_sip.c:14546 handle_request: **** Received INVITE (5) - Command in SIP INVITE [Nov 14 17:25:29] DEBUG[22186]: chan_sip.c:1689 parse_sip_options: Begin: parsing SIP "Supported: x-sipura" [Nov 14 17:25:29] DEBUG[22186]: chan_sip.c:1697 parse_sip_options: Found SIP option: -x-sipura- [Nov 14 17:25:29] DEBUG[22186]: chan_sip.c:1709 parse_sip_options: Found private SIP option, not supported: x-sipura Sending to 195.94.224.214 : 5060 (NAT) Using INVITE request as basis request - bc01fd8b-34f7de33@195.94.224.214 [Nov 14 17:25:29] DEBUG[22186]: res_config_mysql.c:809 mysql_reconnect: MySQL RealTime: Everything is fine. [Nov 14 17:25:29] DEBUG[22186]: res_config_mysql.c:139 realtime_mysql: MySQL RealTime: Retrieve SQL: SELECT * FROM sip WHERE name = '1000' Found user '1000' for '1000' [Nov 14 17:25:29] DEBUG[22186]: chan_sip.c:2651 do_setnat: Setting NAT on RTP to On [Nov 14 17:25:29] DEBUG[22186]: chan_sip.c:2656 do_setnat: Setting NAT on VRTP to On [Nov 14 17:25:29] DEBUG[22186]: chan_sip.c:2576 sip_destroy_user: Destroying user object from memory: 1000 Found RTP audio format 18 Found RTP audio format 0 Found RTP audio format 2 Found RTP audio format 4 Found RTP audio format 8 Found RTP audio format 96 Found RTP audio format 97 Found RTP audio format 98 Found RTP audio format 100 Found RTP audio format 101 Peer audio RTP is at port 195.94.224.214:16482 Found description format G729a for ID 18 Found description format PCMU for ID 0 Found description format G726-32 for ID 2 Found description format G723 for ID 4 Found description format PCMA for ID 8 Found description format G726-40 for ID 96 Found description format G726-24 for ID 97 Found description format G726-16 for ID 98 Found description format NSE for ID 100 Found description format telephone-event for ID 101 Got unsupported a:fmtp in SDP offer [Nov 14 17:25:29] DEBUG[22186]: chan_sip.c:5119 process_sdp: T38 state changed to 0 on channel Capabilities: us - 0x8000e (gsm|ulaw|alaw|h263), peer - audio=0xd0d (g723|ulaw|alaw|g726|g729|ilbc)/video=0x0 (nothing), combined - 0xc (ulaw|alaw) Non-codec capabilities (dtmf): us - 0x1 (telephone-event), peer - 0x1 (telephone-event), combined - 0x1 (telephone-event) Peer audio RTP is at port 195.94.224.214:16482 [Nov 14 17:25:29] DEBUG[22186]: chan_sip.c:5196 process_sdp: We're settling with these formats: 0xc (ulaw|alaw) [Nov 14 17:25:29] DEBUG[22186]: chan_sip.c:13345 handle_request_invite: Checking SIP call limits for device 1000 [Nov 14 17:25:29] DEBUG[22186]: chan_sip.c:3071 update_call_counter: Updating call counter for incoming call Looking for 02210797 in recording (domain 195.94.224.208) [Nov 14 17:25:29] DEBUG[22186]: res_config_mysql.c:809 mysql_reconnect: MySQL RealTime: Everything is fine. [Nov 14 17:25:29] DEBUG[22186]: res_config_mysql.c:139 realtime_mysql: MySQL RealTime: Retrieve SQL: SELECT * FROM extensions WHERE exten = '02210797' AND context = 'recording' AND priority = '1' [Nov 14 17:25:29] DEBUG[22186]: res_config_mysql.c:809 mysql_reconnect: MySQL RealTime: Everything is fine. [Nov 14 17:25:29] DEBUG[22186]: res_config_mysql.c:259 realtime_multi_mysql: MySQL RealTime: Retrieve SQL: SELECT * FROM extensions WHERE exten LIKE '\\_%' AND context = 'recording' AND priority = '1' ORDER BY exten [Nov 14 17:25:29] DEBUG[22186]: frame.c:1133 ast_codec_choose: Could not find preferred codec - Going for the best codec [Nov 14 17:25:29] DEBUG[22186]: chan_sip.c:3846 sip_new: *** Our native formats are 0x4 (ulaw) [Nov 14 17:25:29] DEBUG[22186]: chan_sip.c:3847 sip_new: *** Joint capabilities are 0xc (ulaw|alaw) [Nov 14 17:25:29] DEBUG[22186]: chan_sip.c:3848 sip_new: *** Our capabilities are 0x8000e (gsm|ulaw|alaw|h263) [Nov 14 17:25:29] DEBUG[22186]: frame.c:1133 ast_codec_choose: Could not find preferred codec - Going for the best codec [Nov 14 17:25:29] DEBUG[22186]: chan_sip.c:3849 sip_new: *** AST_CODEC_CHOOSE formats are 0x4 (ulaw) [Nov 14 17:25:29] DEBUG[22186]: chan_sip.c:3872 sip_new: This channel will not be able to handle video. [Nov 14 17:25:29] DEBUG[22186]: chan_sip.c:7909 build_route: build_route: Contact hop: 1000 list_route: hop: [Nov 14 17:25:29] DEBUG[22186]: chan_sip.c:13418 handle_request_invite: SIP/1000-081dec40: New call is still down.... Trying... <--- Transmitting (NAT) to 195.94.224.214:5060 ---> SIP/2.0 100 Trying Via: SIP/2.0/UDP 195.94.224.214:5060;branch=z9hG4bK-d70fe19b;received=195.94.224.214;rport=5060 From: 1000 ;tag=161735ab18970493o0 To: Call-ID: bc01fd8b-34f7de33@195.94.224.214 CSeq: 102 INVITE User-Agent: Asterisk PBX Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY Supported: replaces Contact: Content-Length: 0 <------------> [Nov 14 17:25:29] DEBUG[22186]: devicestate.c:303 __ast_device_state_changed_literal: Notification of state change to be queued on device/channel SIP/1000-081dec40 [Nov 14 17:25:29] DEBUG[22169]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for SIP - 1000 [Nov 14 17:25:29] DEBUG[22169]: chan_sip.c:15136 sip_devicestate: Checking device state for peer 1000 [Nov 14 17:25:29] DEBUG[22169]: res_config_mysql.c:809 mysql_reconnect: MySQL RealTime: Everything is fine. [Nov 14 17:25:29] DEBUG[22169]: res_config_mysql.c:139 realtime_mysql: MySQL RealTime: Retrieve SQL: SELECT * FROM sip WHERE name = '1000' [Nov 14 17:25:29] DEBUG[22169]: chan_sip.c:15770 build_peer: -REALTIME- peer built. Name: . Peer objects: 1 -- SIP Seeding peer from astdb: '1000' at 1000@195.94.224.214:5060 for 3600 [Nov 14 17:25:29] DEBUG[22169]: chan_sip.c:2524 realtime_peer: -REALTIME- loading peer from database to memory. Name: 1000. Peer objects: 1 [Nov 14 17:25:29] DEBUG[22169]: chan_sip.c:2428 sip_destroy_peer: Destroying SIP peer 1000 [Nov 14 17:25:29] DEBUG[22169]: chan_sip.c:2452 sip_destroy_peer: -REALTIME- peer Destroyed. Name: 1000. Realtime Peer objects: 0 [Nov 14 17:25:29] DEBUG[22169]: devicestate.c:287 do_state_change: Changing state for SIP/1000 - state 1 (Not in use) [Nov 14 17:25:29] DEBUG[22614]: res_config_mysql.c:809 mysql_reconnect: MySQL RealTime: Everything is fine. [Nov 14 17:25:29] DEBUG[22614]: res_config_mysql.c:139 realtime_mysql: MySQL RealTime: Retrieve SQL: SELECT * FROM extensions WHERE exten = '02210797' AND context = 'recording' AND priority = '1' [Nov 14 17:25:29] DEBUG[22614]: res_config_mysql.c:809 mysql_reconnect: MySQL RealTime: Everything is fine. [Nov 14 17:25:29] DEBUG[22614]: res_config_mysql.c:259 realtime_multi_mysql: MySQL RealTime: Retrieve SQL: SELECT * FROM extensions WHERE exten LIKE '\\_%' AND context = 'recording' AND priority = '1' ORDER BY exten [Nov 14 17:25:29] DEBUG[22614]: res_config_mysql.c:809 mysql_reconnect: MySQL RealTime: Everything is fine. [Nov 14 17:25:29] DEBUG[22614]: res_config_mysql.c:139 realtime_mysql: MySQL RealTime: Retrieve SQL: SELECT * FROM extensions WHERE exten = '02210797' AND context = 'recording' AND priority = '1' [Nov 14 17:25:29] DEBUG[22614]: res_config_mysql.c:809 mysql_reconnect: MySQL RealTime: Everything is fine. [Nov 14 17:25:29] DEBUG[22614]: res_config_mysql.c:259 realtime_multi_mysql: MySQL RealTime: Retrieve SQL: SELECT * FROM extensions WHERE exten LIKE '\\_%' AND context = 'recording' AND priority = '1' ORDER BY exten [Nov 14 17:25:29] DEBUG[22614]: res_config_mysql.c:809 mysql_reconnect: MySQL RealTime: Everything is fine. [Nov 14 17:25:29] DEBUG[22614]: res_config_mysql.c:139 realtime_mysql: MySQL RealTime: Retrieve SQL: SELECT * FROM extensions WHERE exten = '02210797' AND context = 'recording' AND priority = '1' [Nov 14 17:25:29] DEBUG[22614]: res_config_mysql.c:809 mysql_reconnect: MySQL RealTime: Everything is fine. [Nov 14 17:25:29] DEBUG[22614]: res_config_mysql.c:259 realtime_multi_mysql: MySQL RealTime: Retrieve SQL: SELECT * FROM extensions WHERE exten LIKE '\\_%' AND context = 'recording' AND priority = '1' ORDER BY exten [Nov 14 17:25:29] DEBUG[22614]: res_config_mysql.c:809 mysql_reconnect: MySQL RealTime: Everything is fine. [Nov 14 17:25:29] DEBUG[22614]: res_config_mysql.c:139 realtime_mysql: MySQL RealTime: Retrieve SQL: SELECT * FROM extensions WHERE exten = '02210797' AND context = 'recording' AND priority = '1' [Nov 14 17:25:29] DEBUG[22614]: res_config_mysql.c:809 mysql_reconnect: MySQL RealTime: Everything is fine. [Nov 14 17:25:29] DEBUG[22614]: res_config_mysql.c:259 realtime_multi_mysql: MySQL RealTime: Retrieve SQL: SELECT * FROM extensions WHERE exten LIKE '\\_%' AND context = 'recording' AND priority = '1' ORDER BY exten [Nov 14 17:25:29] DEBUG[22614]: pbx.c:1535 pbx_substitute_variables_helper_full: Function result is '1000' -- Executing Set("SIP/1000-081dec40", "CALLFILENAME=1000-2210797-1163514329") [Nov 14 17:25:29] DEBUG[22614]: res_config_mysql.c:809 mysql_reconnect: MySQL RealTime: Everything is fine. [Nov 14 17:25:29] DEBUG[22614]: res_config_mysql.c:139 realtime_mysql: MySQL RealTime: Retrieve SQL: SELECT * FROM extensions WHERE exten = '02210797' AND context = 'recording' AND priority = '2' [Nov 14 17:25:29] DEBUG[22614]: res_config_mysql.c:809 mysql_reconnect: MySQL RealTime: Everything is fine. [Nov 14 17:25:29] DEBUG[22614]: res_config_mysql.c:259 realtime_multi_mysql: MySQL RealTime: Retrieve SQL: SELECT * FROM extensions WHERE exten LIKE '\\_%' AND context = 'recording' AND priority = '2' ORDER BY exten [Nov 14 17:25:29] DEBUG[22614]: res_config_mysql.c:809 mysql_reconnect: MySQL RealTime: Everything is fine. [Nov 14 17:25:29] DEBUG[22614]: res_config_mysql.c:139 realtime_mysql: MySQL RealTime: Retrieve SQL: SELECT * FROM extensions WHERE exten = '02210797' AND context = 'recording' AND priority = '2' [Nov 14 17:25:29] DEBUG[22614]: res_config_mysql.c:809 mysql_reconnect: MySQL RealTime: Everything is fine. [Nov 14 17:25:29] DEBUG[22614]: res_config_mysql.c:259 realtime_multi_mysql: MySQL RealTime: Retrieve SQL: SELECT * FROM extensions WHERE exten LIKE '\\_%' AND context = 'recording' AND priority = '2' ORDER BY exten [Nov 14 17:25:29] DEBUG[22614]: res_config_mysql.c:809 mysql_reconnect: MySQL RealTime: Everything is fine. [Nov 14 17:25:29] DEBUG[22614]: res_config_mysql.c:139 realtime_mysql: MySQL RealTime: Retrieve SQL: SELECT * FROM extensions WHERE exten = '02210797' AND context = 'recording' AND priority = '2' [Nov 14 17:25:29] DEBUG[22614]: res_config_mysql.c:809 mysql_reconnect: MySQL RealTime: Everything is fine. [Nov 14 17:25:29] DEBUG[22614]: res_config_mysql.c:259 realtime_multi_mysql: MySQL RealTime: Retrieve SQL: SELECT * FROM extensions WHERE exten LIKE '\\_%' AND context = 'recording' AND priority = '2' ORDER BY exten -- Executing MixMonitor("SIP/1000-081dec40", "1000-2210797-1163514329.wav|b") [Nov 14 17:25:29] DEBUG[22615]: app_queue.c:568 changethread: Device 'SIP/1000' changed to state '1' (Not in use) but we don't care because they're not a member of any queue. *CLI> [Nov 14 17:25:29] DEBUG[22614]: channel.c:1258 ast_channel_spy_add: Spy MixMonitor added to channel SIP/1000-081dec40 [Nov 14 17:25:29] DEBUG[22614]: res_config_mysql.c:809 mysql_reconnect: MySQL RealTime: Everything is fine. [Nov 14 17:25:29] DEBUG[22614]: res_config_mysql.c:139 realtime_mysql: MySQL RealTime: Retrieve SQL: SELECT * FROM extensions WHERE exten = '02210797' AND context = 'recording' AND priority = '3' [Nov 14 17:25:29] DEBUG[22614]: res_config_mysql.c:809 mysql_reconnect: MySQL RealTime: Everything is fine. [Nov 14 17:25:29] DEBUG[22614]: res_config_mysql.c:259 realtime_multi_mysql: MySQL RealTime: Retrieve SQL: SELECT * FROM extensions WHERE exten LIKE '\\_%' AND context = 'recording' AND priority = '3' ORDER BY exten [Nov 14 17:25:29] DEBUG[22614]: res_config_mysql.c:809 mysql_reconnect: MySQL RealTime: Everything is fine. [Nov 14 17:25:29] DEBUG[22614]: res_config_mysql.c:139 realtime_mysql: MySQL RealTime: Retrieve SQL: SELECT * FROM extensions WHERE exten = '02210797' AND context = 'recording' AND priority = '3' [Nov 14 17:25:29] DEBUG[22614]: res_config_mysql.c:809 mysql_reconnect: MySQL RealTime: Everything is fine. [Nov 14 17:25:29] DEBUG[22614]: res_config_mysql.c:259 realtime_multi_mysql: MySQL RealTime: Retrieve SQL: SELECT * FROM extensions WHERE exten LIKE '\\_%' AND context = 'recording' AND priority = '3' ORDER BY exten [Nov 14 17:25:29] DEBUG[22614]: res_config_mysql.c:809 mysql_reconnect: MySQL RealTime: Everything is fine. [Nov 14 17:25:29] DEBUG[22614]: res_config_mysql.c:139 realtime_mysql: MySQL RealTime: Retrieve SQL: SELECT * FROM extensions WHERE exten = '02210797' AND context = 'recording' AND priority = '3' [Nov 14 17:25:29] DEBUG[22614]: res_config_mysql.c:809 mysql_reconnect: MySQL RealTime: Everything is fine. [Nov 14 17:25:29] DEBUG[22614]: res_config_mysql.c:259 realtime_multi_mysql: MySQL RealTime: Retrieve SQL: SELECT * FROM extensions WHERE exten LIKE '\\_%' AND context = 'recording' AND priority = '3' ORDER BY exten -- Executing GoTo("SIP/1000-081dec40", "default|02210797|1") -- Goto (default,02210797,1) [Nov 14 17:25:29] DEBUG[22614]: res_config_mysql.c:809 mysql_reconnect: MySQL RealTime: Everything is fine. [Nov 14 17:25:29] DEBUG[22614]: res_config_mysql.c:139 realtime_mysql: MySQL RealTime: Retrieve SQL: SELECT * FROM extensions WHERE exten = '02210797' AND context = 'default' AND priority = '1' [Nov 14 17:25:29] DEBUG[22614]: res_config_mysql.c:809 mysql_reconnect: MySQL RealTime: Everything is fine. [Nov 14 17:25:29] DEBUG[22614]: res_config_mysql.c:259 realtime_multi_mysql: MySQL RealTime: Retrieve SQL: SELECT * FROM extensions WHERE exten LIKE '\\_%' AND context = 'default' AND priority = '1' ORDER BY exten [Nov 14 17:25:29] DEBUG[22614]: res_config_mysql.c:809 mysql_reconnect: MySQL RealTime: Everything is fine. [Nov 14 17:25:29] DEBUG[22614]: res_config_mysql.c:139 realtime_mysql: MySQL RealTime: Retrieve SQL: SELECT * FROM extensions WHERE exten = '02210797' AND context = 'moscow' AND priority = '1' [Nov 14 17:25:29] DEBUG[22614]: res_config_mysql.c:809 mysql_reconnect: MySQL RealTime: Everything is fine. [Nov 14 17:25:29] DEBUG[22614]: res_config_mysql.c:259 realtime_multi_mysql: MySQL RealTime: Retrieve SQL: SELECT * FROM extensions WHERE exten LIKE '\\_%' AND context = 'moscow' AND priority = '1' ORDER BY exten [Nov 14 17:25:29] DEBUG[22614]: res_config_mysql.c:809 mysql_reconnect: MySQL RealTime: Everything is fine. [Nov 14 17:25:29] DEBUG[22614]: res_config_mysql.c:139 realtime_mysql: MySQL RealTime: Retrieve SQL: SELECT * FROM extensions WHERE exten = '02210797' AND context = 'default' AND priority = '1' [Nov 14 17:25:29] DEBUG[22614]: res_config_mysql.c:809 mysql_reconnect: MySQL RealTime: Everything is fine. [Nov 14 17:25:29] DEBUG[22614]: res_config_mysql.c:259 realtime_multi_mysql: MySQL RealTime: Retrieve SQL: SELECT * FROM extensions WHERE exten LIKE '\\_%' AND context = 'default' AND priority = '1' ORDER BY exten [Nov 14 17:25:29] DEBUG[22614]: res_config_mysql.c:809 mysql_reconnect: MySQL RealTime: Everything is fine. [Nov 14 17:25:29] DEBUG[22614]: res_config_mysql.c:139 realtime_mysql: MySQL RealTime: Retrieve SQL: SELECT * FROM extensions WHERE exten = '02210797' AND context = 'moscow' AND priority = '1' [Nov 14 17:25:29] DEBUG[22614]: res_config_mysql.c:809 mysql_reconnect: MySQL RealTime: Everything is fine. [Nov 14 17:25:29] DEBUG[22614]: res_config_mysql.c:259 realtime_multi_mysql: MySQL RealTime: Retrieve SQL: SELECT * FROM extensions WHERE exten LIKE '\\_%' AND context = 'moscow' AND priority = '1' ORDER BY exten [Nov 14 17:25:29] DEBUG[22614]: res_config_mysql.c:809 mysql_reconnect: MySQL RealTime: Everything is fine. [Nov 14 17:25:29] DEBUG[22614]: res_config_mysql.c:139 realtime_mysql: MySQL RealTime: Retrieve SQL: SELECT * FROM extensions WHERE exten = '02210797' AND context = 'moscow' AND priority = '1' [Nov 14 17:25:29] DEBUG[22614]: res_config_mysql.c:809 mysql_reconnect: MySQL RealTime: Everything is fine. [Nov 14 17:25:29] DEBUG[22614]: res_config_mysql.c:259 realtime_multi_mysql: MySQL RealTime: Retrieve SQL: SELECT * FROM extensions WHERE exten LIKE '\\_%' AND context = 'moscow' AND priority = '1' ORDER BY exten -- Executing DIAL("SIP/1000-081dec40", "SIP/cisco1/09774952210797") [Nov 14 17:25:29] DEBUG[22614]: chan_sip.c:15194 sip_request_call: Asked to create a SIP channel with formats: 0x4 (ulaw) [Nov 14 17:25:29] DEBUG[22614]: chan_sip.c:4337 sip_alloc: Allocating new SIP dialog for (No Call-ID) - INVITE (With RTP) [Nov 14 17:25:29] DEBUG[22614]: res_config_mysql.c:809 mysql_reconnect: MySQL RealTime: Everything is fine. [Nov 14 17:25:29] DEBUG[22614]: res_config_mysql.c:139 realtime_mysql: MySQL RealTime: Retrieve SQL: SELECT * FROM sip WHERE name = 'cisco1' [Nov 14 17:25:29] DEBUG[22614]: chan_sip.c:15770 build_peer: -REALTIME- peer built. Name: . Peer objects: 1 [Nov 14 17:25:29] DEBUG[22614]: chan_sip.c:2524 realtime_peer: -REALTIME- loading peer from database to memory. Name: cisco1. Peer objects: 1 [Nov 14 17:25:29] DEBUG[22614]: chan_sip.c:2651 do_setnat: Setting NAT on RTP to On [Nov 14 17:25:29] DEBUG[22614]: chan_sip.c:2428 sip_destroy_peer: Destroying SIP peer cisco1 [Nov 14 17:25:29] DEBUG[22614]: chan_sip.c:2452 sip_destroy_peer: -REALTIME- peer Destroyed. Name: cisco1. Realtime Peer objects: 0 [Nov 14 17:25:29] DEBUG[22614]: frame.c:1133 ast_codec_choose: Could not find preferred codec - Going for the best codec [Nov 14 17:25:29] DEBUG[22614]: chan_sip.c:3846 sip_new: *** Our native formats are 0x4 (ulaw) [Nov 14 17:25:29] DEBUG[22614]: chan_sip.c:3847 sip_new: *** Joint capabilities are 0x0 (nothing) [Nov 14 17:25:29] DEBUG[22614]: chan_sip.c:3848 sip_new: *** Our capabilities are 0x3f1fff (g723|gsm|ulaw|alaw|g726|adpcm|slin|lpc10|g729|speex|ilbc|g726aal2|g722|jpeg|png|h261|h263|h263p|h264) [Nov 14 17:25:29] DEBUG[22614]: frame.c:1133 ast_codec_choose: Could not find preferred codec - Going for the best codec [Nov 14 17:25:29] DEBUG[22614]: chan_sip.c:3849 sip_new: *** AST_CODEC_CHOOSE formats are 0x4 (ulaw) [Nov 14 17:25:29] DEBUG[22614]: chan_sip.c:3851 sip_new: *** Our preferred formats from the incoming channel are 0x4 (ulaw) [Nov 14 17:25:29] DEBUG[22614]: chan_sip.c:3872 sip_new: This channel will not be able to handle video. [Nov 14 17:25:29] DEBUG[22614]: channel.c:3191 ast_channel_inherit_variables: Not copying variable MIXMONITOR_FILENAME. [Nov 14 17:25:29] DEBUG[22614]: channel.c:3191 ast_channel_inherit_variables: Not copying variable CALLFILENAME. [Nov 14 17:25:29] DEBUG[22614]: channel.c:3191 ast_channel_inherit_variables: Not copying variable SIPCALLID. [Nov 14 17:25:29] DEBUG[22614]: channel.c:3191 ast_channel_inherit_variables: Not copying variable SIPDOMAIN. [Nov 14 17:25:29] DEBUG[22614]: channel.c:3191 ast_channel_inherit_variables: Not copying variable SIPURI. [Nov 14 17:25:29] DEBUG[22614]: chan_sip.c:2898 sip_call: Outgoing Call for 09774952210797 [Nov 14 17:25:29] DEBUG[22614]: chan_sip.c:3071 update_call_counter: Updating call counter for outgoing call [Nov 14 17:25:29] DEBUG[22614]: chan_sip.c:2915 sip_call: Our T38 capability (3840), joint T38 capability (3840) [Nov 14 17:25:29] DEBUG[22614]: chan_sip.c:6190 add_sdp: ** Our capability: 0x3f0dff (g723|gsm|ulaw|alaw|g726|adpcm|slin|lpc10|g729|ilbc|g726aal2|jpeg|png|h261|h263|h263p|h264) Video flag: False [Nov 14 17:25:29] DEBUG[22614]: chan_sip.c:6191 add_sdp: ** Our prefcodec: 0x4 (ulaw) [Nov 14 17:25:29] DEBUG[22614]: chan_sip.c:6208 add_sdp: This call needs video offers, but there's no video support enabled! Audio is at 195.94.224.208 port 12320 Adding codec 0x4 (ulaw) to SDP Adding codec 0x1 (g723) to SDP Adding codec 0x2 (gsm) to SDP Adding codec 0x8 (alaw) to SDP Adding codec 0x10 (g726aal2) to SDP Adding codec 0x20 (adpcm) to SDP Adding codec 0x40 (slin) to SDP Adding codec 0x80 (lpc10) to SDP Adding codec 0x100 (g729) to SDP Adding codec 0x400 (ilbc) to SDP Adding codec 0x800 (g726) to SDP Adding non-codec 0x1 (telephone-event) to SDP [Nov 14 17:25:29] DEBUG[22614]: chan_sip.c:6316 add_sdp: -- Done with adding codecs to SDP [Nov 14 17:25:29] DEBUG[22614]: channel.c:2275 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=-1) [Nov 14 17:25:29] DEBUG[22614]: chan_sip.c:6360 add_sdp: Done building SDP. Settling with this capability: 0x3f0dff (g723|gsm|ulaw|alaw|g726|adpcm|slin|lpc10|g729|ilbc|g726aal2|jpeg|png|h261|h263|h263p|h264) [Nov 14 17:25:29] DEBUG[22614]: chan_sip.c:1637 initialize_initreq: Initializing initreq for method INVITE - callid 2861823763f158e33fe07d5c0e37225b@195.94.224.208 [Nov 14 17:25:29] DEBUG[22614]: chan_sip.c:4602 parse_request: Header 0 [ 48]: INVITE sip:09774952210797@195.94.224.195 SIP/2.0 [Nov 14 17:25:29] DEBUG[22614]: chan_sip.c:4602 parse_request: Header 1 [ 65]: Via: SIP/2.0/UDP 195.94.224.208:5060;branch=z9hG4bK10a488dc;rport [Nov 14 17:25:29] DEBUG[22614]: chan_sip.c:4602 parse_request: Header 2 [ 16]: Max-Forwards: 70 [Nov 14 17:25:29] DEBUG[22614]: chan_sip.c:4602 parse_request: Header 3 [ 52]: From: "1000" ;tag=as7dde7e49 [Nov 14 17:25:29] DEBUG[22614]: chan_sip.c:4602 parse_request: Header 4 [ 39]: To: [Nov 14 17:25:29] DEBUG[22614]: chan_sip.c:4602 parse_request: Header 5 [ 33]: Contact: [Nov 14 17:25:29] DEBUG[22614]: chan_sip.c:4602 parse_request: Header 6 [ 56]: Call-ID: 2861823763f158e33fe07d5c0e37225b@195.94.224.208 [Nov 14 17:25:29] DEBUG[22614]: chan_sip.c:4602 parse_request: Header 7 [ 16]: CSeq: 102 INVITE [Nov 14 17:25:29] DEBUG[22614]: chan_sip.c:4602 parse_request: Header 8 [ 24]: User-Agent: Asterisk PBX [Nov 14 17:25:29] DEBUG[22614]: chan_sip.c:4602 parse_request: Header 9 [ 35]: Date: Tue, 14 Nov 2006 14:25:29 GMT [Nov 14 17:25:29] DEBUG[22614]: chan_sip.c:4602 parse_request: Header 10 [ 66]: Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY [Nov 14 17:25:29] DEBUG[22614]: chan_sip.c:4602 parse_request: Header 11 [ 19]: Supported: replaces [Nov 14 17:25:29] DEBUG[22614]: chan_sip.c:4602 parse_request: Header 12 [ 29]: Content-Type: application/sdp [Nov 14 17:25:29] DEBUG[22614]: chan_sip.c:4602 parse_request: Header 13 [ 19]: Content-Length: 546 [Nov 14 17:25:29] DEBUG[22614]: chan_sip.c:4602 parse_request: Header 14 [ 0]: [Nov 14 17:25:29] DEBUG[22614]: chan_sip.c:4602 parse_request: Body 0 [ 3]: v=0 [Nov 14 17:25:29] DEBUG[22614]: chan_sip.c:4602 parse_request: Body 1 [ 40]: o=root 22166 22166 IN IP4 195.94.224.208 [Nov 14 17:25:29] DEBUG[22614]: chan_sip.c:4602 parse_request: Body 2 [ 9]: s=session [Nov 14 17:25:29] DEBUG[22614]: chan_sip.c:4602 parse_request: Body 3 [ 23]: c=IN IP4 195.94.224.208 [Nov 14 17:25:29] DEBUG[22614]: chan_sip.c:4602 parse_request: Body 4 [ 5]: t=0 0 [Nov 14 17:25:29] DEBUG[22614]: chan_sip.c:4602 parse_request: Body 5 [ 54]: m=audio 12320 RTP/AVP 0 4 3 8 112 5 10 7 18 97 111 101 [Nov 14 17:25:29] DEBUG[22614]: chan_sip.c:4602 parse_request: Body 6 [ 20]: a=rtpmap:0 PCMU/8000 [Nov 14 17:25:29] DEBUG[22614]: chan_sip.c:4602 parse_request: Body 7 [ 20]: a=rtpmap:4 G723/8000 [Nov 14 17:25:29] DEBUG[22614]: chan_sip.c:4602 parse_request: Body 8 [ 19]: a=rtpmap:3 GSM/8000 [Nov 14 17:25:29] DEBUG[22614]: chan_sip.c:4602 parse_request: Body 9 [ 20]: a=rtpmap:8 PCMA/8000 [Nov 14 17:25:29] DEBUG[22614]: chan_sip.c:4602 parse_request: Body 10 [ 30]: a=rtpmap:112 AAL2-G726-32/8000 [Nov 14 17:25:29] DEBUG[22614]: chan_sip.c:4602 parse_request: Body 11 [ 20]: a=rtpmap:5 DVI4/8000 [Nov 14 17:25:29] DEBUG[22614]: chan_sip.c:4602 parse_request: Body 12 [ 20]: a=rtpmap:10 L16/8000 [Nov 14 17:25:29] DEBUG[22614]: chan_sip.c:4602 parse_request: Body 13 [ 19]: a=rtpmap:7 LPC/8000 [Nov 14 17:25:29] DEBUG[22614]: chan_sip.c:4602 parse_request: Body 14 [ 21]: a=rtpmap:18 G729/8000 [Nov 14 17:25:29] DEBUG[22614]: chan_sip.c:4602 parse_request: Body 15 [ 19]: a=fmtp:18 annexb=no [Nov 14 17:25:29] DEBUG[22614]: chan_sip.c:4602 parse_request: Body 16 [ 21]: a=rtpmap:97 iLBC/8000 [Nov 14 17:25:29] DEBUG[22614]: chan_sip.c:4602 parse_request: Body 17 [ 17]: a=fmtp:97 mode=30 [Nov 14 17:25:29] DEBUG[22614]: chan_sip.c:4602 parse_request: Body 18 [ 25]: a=rtpmap:111 G726-32/8000 [Nov 14 17:25:29] DEBUG[22614]: chan_sip.c:4602 parse_request: Body 19 [ 33]: a=rtpmap:101 telephone-event/8000 [Nov 14 17:25:29] DEBUG[22614]: chan_sip.c:4602 parse_request: Body 20 [ 15]: a=fmtp:101 0-16 [Nov 14 17:25:29] DEBUG[22614]: chan_sip.c:4602 parse_request: Body 21 [ 25]: a=silenceSupp:off - - - - [Nov 14 17:25:29] DEBUG[22614]: chan_sip.c:4602 parse_request: Body 22 [ 10]: a=ptime:20 [Nov 14 17:25:29] DEBUG[22614]: chan_sip.c:4602 parse_request: Body 23 [ 10]: a=sendrecv Reliably Transmitting (NAT) to 195.94.224.195:5060: INVITE sip:09774952210797@195.94.224.195 SIP/2.0 Via: SIP/2.0/UDP 195.94.224.208:5060;branch=z9hG4bK10a488dc;rport Max-Forwards: 70 From: "1000" ;tag=as7dde7e49 To: Contact: Call-ID: 2861823763f158e33fe07d5c0e37225b@195.94.224.208 CSeq: 102 INVITE User-Agent: Asterisk PBX Date: Tue, 14 Nov 2006 14:25:29 GMT Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY Supported: replaces Content-Type: application/sdp Content-Length: 546 v=0 o=root 22166 22166 IN IP4 195.94.224.208 s=session c=IN IP4 195.94.224.208 t=0 0 m=audio 12320 RTP/AVP 0 4 3 8 112 5 10 7 18 97 111 101 a=rtpmap:0 PCMU/8000 a=rtpmap:4 G723/8000 a=rtpmap:3 GSM/8000 a=rtpmap:8 PCMA/8000 a=rtpmap:112 AAL2-G726-32/8000 a=rtpmap:5 DVI4/8000 a=rtpmap:10 L16/8000 a=rtpmap:7 LPC/8000 a=rtpmap:18 G729/8000 a=fmtp:18 annexb=no a=rtpmap:97 iLBC/8000 a=fmtp:97 mode=30 a=rtpmap:111 G726-32/8000 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-16 a=silenceSupp:off - - - - a=ptime:20 a=sendrecv --- [Nov 14 17:25:29] DEBUG[22614]: chan_sip.c:1979 __sip_reliable_xmit: *** SIP TIMER: Initalizing retransmit timer on packet: Id #1466 -- Called cisco1/09774952210797 [Nov 14 17:25:29] DEBUG[22614]: res_config_mysql.c:809 mysql_reconnect: MySQL RealTime: Everything is fine. [Nov 14 17:25:29] DEBUG[22614]: res_config_mysql.c:139 realtime_mysql: MySQL RealTime: Retrieve SQL: SELECT * FROM extensions WHERE exten = '02210797' AND context = 'default' AND priority = '-1' [Nov 14 17:25:29] DEBUG[22614]: res_config_mysql.c:809 mysql_reconnect: MySQL RealTime: Everything is fine. [Nov 14 17:25:29] DEBUG[22614]: res_config_mysql.c:259 realtime_multi_mysql: MySQL RealTime: Retrieve SQL: SELECT * FROM extensions WHERE exten LIKE '\\_%' AND context = 'default' AND priority = '-1' ORDER BY exten [Nov 14 17:25:29] DEBUG[22614]: res_config_mysql.c:809 mysql_reconnect: MySQL RealTime: Everything is fine. [Nov 14 17:25:29] DEBUG[22614]: res_config_mysql.c:139 realtime_mysql: MySQL RealTime: Retrieve SQL: SELECT * FROM extensions WHERE exten = '02210797' AND context = 'moscow' AND priority = '-1' [Nov 14 17:25:29] DEBUG[22614]: res_config_mysql.c:809 mysql_reconnect: MySQL RealTime: Everything is fine. [Nov 14 17:25:29] DEBUG[22614]: res_config_mysql.c:259 realtime_multi_mysql: MySQL RealTime: Retrieve SQL: SELECT * FROM extensions WHERE exten LIKE '\\_%' AND context = 'moscow' AND priority = '-1' ORDER BY exten == Begin MixMonitor Recording SIP/1000-081dec40 <--- SIP read from 195.94.224.195:5060 ---> SIP/2.0 100 Trying Via: SIP/2.0/UDP 195.94.224.208:5060;branch=z9hG4bK10a488dc;rport From: "1000" ;tag=as7dde7e49 To: ;tag=153507B8-1F33 Date: Tue, 14 Nov 2006 13:43:34 GMT Call-ID: 2861823763f158e33fe07d5c0e37225b@195.94.224.208 Server: Cisco-SIPGateway/IOS-12.x CSeq: 102 INVITE Allow-Events: telephone-event Content-Length: 0 <-------------> [Nov 14 17:25:29] DEBUG[22186]: chan_sip.c:4602 parse_request: Header 0 [ 18]: SIP/2.0 100 Trying [Nov 14 17:25:29] DEBUG[22186]: chan_sip.c:4602 parse_request: Header 1 [ 65]: Via: SIP/2.0/UDP 195.94.224.208:5060;branch=z9hG4bK10a488dc;rport [Nov 14 17:25:29] DEBUG[22186]: chan_sip.c:4602 parse_request: Header 2 [ 52]: From: "1000" ;tag=as7dde7e49 [Nov 14 17:25:29] DEBUG[22186]: chan_sip.c:4602 parse_request: Header 3 [ 57]: To: ;tag=153507B8-1F33 [Nov 14 17:25:29] DEBUG[22186]: chan_sip.c:4602 parse_request: Header 4 [ 35]: Date: Tue, 14 Nov 2006 13:43:34 GMT [Nov 14 17:25:29] DEBUG[22186]: chan_sip.c:4602 parse_request: Header 5 [ 56]: Call-ID: 2861823763f158e33fe07d5c0e37225b@195.94.224.208 [Nov 14 17:25:29] DEBUG[22186]: chan_sip.c:4602 parse_request: Header 6 [ 33]: Server: Cisco-SIPGateway/IOS-12.x [Nov 14 17:25:29] DEBUG[22186]: chan_sip.c:4602 parse_request: Header 7 [ 16]: CSeq: 102 INVITE [Nov 14 17:25:29] DEBUG[22186]: chan_sip.c:4602 parse_request: Header 8 [ 29]: Allow-Events: telephone-event [Nov 14 17:25:29] DEBUG[22186]: chan_sip.c:4602 parse_request: Header 9 [ 17]: Content-Length: 0 [Nov 14 17:25:29] DEBUG[22186]: chan_sip.c:4602 parse_request: Header 10 [ 0]: --- (10 headers 0 lines) --- [Nov 14 17:25:29] DEBUG[22186]: chan_sip.c:4401 find_call: = Found Their Call ID: 2861823763f158e33fe07d5c0e37225b@195.94.224.208 Their Tag Our tag: as7dde7e49 [Nov 14 17:25:29] DEBUG[22186]: chan_sip.c:2122 __sip_semi_ack: *** SIP TIMER: Cancelling retransmission #1466 - INVITE (got response) [Nov 14 17:25:29] DEBUG[22186]: chan_sip.c:2131 __sip_semi_ack: (Provisional) Stopping retransmission (but retaining packet) on '2861823763f158e33fe07d5c0e37225b@195.94.224.208' Request 102: Found [Nov 14 17:25:29] DEBUG[22186]: chan_sip.c:11659 handle_response_invite: SIP response 100 to standard invite <--- SIP read from 195.94.224.195:5060 ---> SIP/2.0 183 Session Progress Via: SIP/2.0/UDP 195.94.224.208:5060;branch=z9hG4bK10a488dc;rport From: "1000" ;tag=as7dde7e49 To: ;tag=153507B8-1F33 Date: Tue, 14 Nov 2006 13:43:34 GMT Call-ID: 2861823763f158e33fe07d5c0e37225b@195.94.224.208 Server: Cisco-SIPGateway/IOS-12.x CSeq: 102 INVITE Allow-Events: telephone-event Contact: Content-Disposition: session;handling=required Content-Type: application/sdp Content-Length: 221 v=0 o=CiscoSystemsSIP-GW-UserAgent 5375 1510 IN IP4 195.94.224.195 s=SIP Call c=IN IP4 195.94.224.195 t=0 0 m=audio 18152 RTP/AVP 8 19 c=IN IP4 195.94.224.195 a=rtpmap:8 PCMA/8000 a=rtpmap:19 CN/8000 a=ptime:20 <-------------> [Nov 14 17:25:32] DEBUG[22186]: chan_sip.c:4602 parse_request: Header 0 [ 28]: SIP/2.0 183 Session Progress [Nov 14 17:25:32] DEBUG[22186]: chan_sip.c:4602 parse_request: Header 1 [ 65]: Via: SIP/2.0/UDP 195.94.224.208:5060;branch=z9hG4bK10a488dc;rport [Nov 14 17:25:32] DEBUG[22186]: chan_sip.c:4602 parse_request: Header 2 [ 52]: From: "1000" ;tag=as7dde7e49 [Nov 14 17:25:32] DEBUG[22186]: chan_sip.c:4602 parse_request: Header 3 [ 57]: To: ;tag=153507B8-1F33 [Nov 14 17:25:32] DEBUG[22186]: chan_sip.c:4602 parse_request: Header 4 [ 35]: Date: Tue, 14 Nov 2006 13:43:34 GMT [Nov 14 17:25:32] DEBUG[22186]: chan_sip.c:4602 parse_request: Header 5 [ 56]: Call-ID: 2861823763f158e33fe07d5c0e37225b@195.94.224.208 [Nov 14 17:25:32] DEBUG[22186]: chan_sip.c:4602 parse_request: Header 6 [ 33]: Server: Cisco-SIPGateway/IOS-12.x [Nov 14 17:25:32] DEBUG[22186]: chan_sip.c:4602 parse_request: Header 7 [ 16]: CSeq: 102 INVITE [Nov 14 17:25:32] DEBUG[22186]: chan_sip.c:4602 parse_request: Header 8 [ 29]: Allow-Events: telephone-event [Nov 14 17:25:32] DEBUG[22186]: chan_sip.c:4602 parse_request: Header 9 [ 49]: Contact: [Nov 14 17:25:32] DEBUG[22186]: chan_sip.c:4602 parse_request: Header 10 [ 46]: Content-Disposition: session;handling=required [Nov 14 17:25:32] DEBUG[22186]: chan_sip.c:4602 parse_request: Header 11 [ 29]: Content-Type: application/sdp [Nov 14 17:25:32] DEBUG[22186]: chan_sip.c:4602 parse_request: Header 12 [ 19]: Content-Length: 221 [Nov 14 17:25:32] DEBUG[22186]: chan_sip.c:4602 parse_request: Header 13 [ 0]: [Nov 14 17:25:32] DEBUG[22186]: chan_sip.c:4602 parse_request: Body 0 [ 3]: v=0 [Nov 14 17:25:32] DEBUG[22186]: chan_sip.c:4602 parse_request: Body 1 [ 62]: o=CiscoSystemsSIP-GW-UserAgent 5375 1510 IN IP4 195.94.224.195 [Nov 14 17:25:32] DEBUG[22186]: chan_sip.c:4602 parse_request: Body 2 [ 10]: s=SIP Call [Nov 14 17:25:32] DEBUG[22186]: chan_sip.c:4602 parse_request: Body 3 [ 23]: c=IN IP4 195.94.224.195 [Nov 14 17:25:32] DEBUG[22186]: chan_sip.c:4602 parse_request: Body 4 [ 5]: t=0 0 [Nov 14 17:25:32] DEBUG[22186]: chan_sip.c:4602 parse_request: Body 5 [ 26]: m=audio 18152 RTP/AVP 8 19 [Nov 14 17:25:32] DEBUG[22186]: chan_sip.c:4602 parse_request: Body 6 [ 23]: c=IN IP4 195.94.224.195 [Nov 14 17:25:32] DEBUG[22186]: chan_sip.c:4602 parse_request: Body 7 [ 20]: a=rtpmap:8 PCMA/8000 [Nov 14 17:25:32] DEBUG[22186]: chan_sip.c:4602 parse_request: Body 8 [ 19]: a=rtpmap:19 CN/8000 [Nov 14 17:25:32] DEBUG[22186]: chan_sip.c:4602 parse_request: Body 9 [ 10]: a=ptime:20 --- (13 headers 10 lines) --- [Nov 14 17:25:32] DEBUG[22186]: chan_sip.c:4401 find_call: = Found Their Call ID: 2861823763f158e33fe07d5c0e37225b@195.94.224.208 Their Tag 153507B8-1F33 Our tag: as7dde7e49 [Nov 14 17:25:32] DEBUG[22186]: chan_sip.c:2131 __sip_semi_ack: (Provisional) Stopping retransmission (but retaining packet) on '2861823763f158e33fe07d5c0e37225b@195.94.224.208' Request 102: Found [Nov 14 17:25:32] DEBUG[22186]: chan_sip.c:11659 handle_response_invite: SIP response 183 to standard invite Found RTP audio format 8 Found RTP audio format 19 Peer audio RTP is at port 195.94.224.195:18152 Found description format PCMA for ID 8 Found description format CN for ID 19 [Nov 14 17:25:32] DEBUG[22186]: chan_sip.c:5119 process_sdp: T38 state changed to 0 on channel SIP/cisco1-081e6230 Capabilities: us - 0x3f1fff (g723|gsm|ulaw|alaw|g726|adpcm|slin|lpc10|g729|speex|ilbc|g726aal2|g722|jpeg|png|h261|h263|h263p|h264), peer - audio=0x8 (alaw)/video=0x0 (nothing), combined - 0x8 (alaw) Non-codec capabilities (dtmf): us - 0x1 (telephone-event), peer - 0x2 (CN), combined - 0x0 (nothing) Peer audio RTP is at port 195.94.224.195:18152 [Nov 14 17:25:32] DEBUG[22186]: chan_sip.c:5196 process_sdp: We're settling with these formats: 0x8 (alaw) [Nov 14 17:25:32] DEBUG[22186]: chan_sip.c:5203 process_sdp: We have an owner, now see if we need to change this call [Nov 14 17:25:32] DEBUG[22186]: chan_sip.c:5208 process_sdp: Oooh, we need to change our audio formats since our peer supports only 0x8 (alaw) and not 0x4 (ulaw) [Nov 14 17:25:32] DEBUG[22186]: frame.c:1133 ast_codec_choose: Could not find preferred codec - Going for the best codec [Nov 14 17:25:32] DEBUG[22186]: channel.c:2735 set_format: Set channel SIP/cisco1-081e6230 to read format ulaw [Nov 14 17:25:32] DEBUG[22186]: channel.c:2735 set_format: Set channel SIP/cisco1-081e6230 to write format ulaw -- SIP/cisco1-081e6230 is making progress passing it to SIP/1000-081dec40 [Nov 14 17:25:32] DEBUG[22614]: chan_sip.c:6415 transmit_response_with_sdp: Setting framing from config on incoming call [Nov 14 17:25:32] DEBUG[22614]: chan_sip.c:6190 add_sdp: ** Our capability: 0xc (ulaw|alaw) Video flag: True [Nov 14 17:25:32] DEBUG[22614]: chan_sip.c:6191 add_sdp: ** Our prefcodec: 0x0 (nothing) Audio is at 195.94.224.208 port 17754 Adding codec 0x4 (ulaw) to SDP Adding codec 0x8 (alaw) to SDP Adding non-codec 0x1 (telephone-event) to SDP [Nov 14 17:25:32] DEBUG[22614]: chan_sip.c:6316 add_sdp: -- Done with adding codecs to SDP [Nov 14 17:25:32] DEBUG[22614]: channel.c:2275 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=-1) [Nov 14 17:25:32] DEBUG[22614]: chan_sip.c:6360 add_sdp: Done building SDP. Settling with this capability: 0xc (ulaw|alaw) <--- Transmitting (NAT) to 195.94.224.214:5060 ---> SIP/2.0 183 Session Progress Via: SIP/2.0/UDP 195.94.224.214:5060;branch=z9hG4bK-d70fe19b;received=195.94.224.214;rport=5060 From: 1000 ;tag=161735ab18970493o0 To: ;tag=as482927b4 Call-ID: bc01fd8b-34f7de33@195.94.224.214 CSeq: 102 INVITE User-Agent: Asterisk PBX Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY Supported: replaces Contact: Content-Type: application/sdp Content-Length: 268 v=0 o=root 22166 22166 IN IP4 195.94.224.208 s=session c=IN IP4 195.94.224.208 t=0 0 m=audio 17754 RTP/AVP 0 8 101 a=rtpmap:0 PCMU/8000 a=rtpmap:8 PCMA/8000 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-16 a=silenceSupp:off - - - - a=ptime:20 a=sendrecv <------------> <--- SIP read from 195.94.224.214:5060 ---> NOTIFY sip:195.94.224.208 SIP/2.0 Via: SIP/2.0/UDP 195.94.224.214:5060;branch=z9hG4bK-9b5cca9a;rport From: 1000 ;tag=55c75a49bfc3f9c1o0 To: Call-ID: b660adc9-280ebc41@195.94.224.214 CSeq: 7717 NOTIFY Max-Forwards: 70 Event: keep-alive User-Agent: Sipura/SPA1001-2.0.13(SEg) Content-Length: 0 <-------------> [Nov 14 17:25:32] DEBUG[22186]: chan_sip.c:4602 parse_request: Header 0 [ 33]: NOTIFY sip:195.94.224.208 SIP/2.0 [Nov 14 17:25:32] DEBUG[22186]: chan_sip.c:4602 parse_request: Header 1 [ 66]: Via: SIP/2.0/UDP 195.94.224.214:5060;branch=z9hG4bK-9b5cca9a;rport [Nov 14 17:25:32] DEBUG[22186]: chan_sip.c:4602 parse_request: Header 2 [ 59]: From: 1000 ;tag=55c75a49bfc3f9c1o0 [Nov 14 17:25:32] DEBUG[22186]: chan_sip.c:4602 parse_request: Header 3 [ 24]: To: [Nov 14 17:25:32] DEBUG[22186]: chan_sip.c:4602 parse_request: Header 4 [ 41]: Call-ID: b660adc9-280ebc41@195.94.224.214 [Nov 14 17:25:32] DEBUG[22186]: chan_sip.c:4602 parse_request: Header 5 [ 17]: CSeq: 7717 NOTIFY [Nov 14 17:25:32] DEBUG[22186]: chan_sip.c:4602 parse_request: Header 6 [ 16]: Max-Forwards: 70 [Nov 14 17:25:32] DEBUG[22186]: chan_sip.c:4602 parse_request: Header 7 [ 17]: Event: keep-alive [Nov 14 17:25:32] DEBUG[22186]: chan_sip.c:4602 parse_request: Header 8 [ 38]: User-Agent: Sipura/SPA1001-2.0.13(SEg) [Nov 14 17:25:32] DEBUG[22186]: chan_sip.c:4602 parse_request: Header 9 [ 17]: Content-Length: 0 [Nov 14 17:25:32] DEBUG[22186]: chan_sip.c:4602 parse_request: Header 10 [ 0]: --- (10 headers 0 lines) --- [Nov 14 17:25:32] DEBUG[22186]: chan_sip.c:4401 find_call: = No match Their Call ID: 2861823763f158e33fe07d5c0e37225b@195.94.224.208 Their Tag 153507B8-1F33 Our tag: as7dde7e49 [Nov 14 17:25:32] DEBUG[22186]: chan_sip.c:4401 find_call: = No match Their Call ID: bc01fd8b-34f7de33@195.94.224.214 Their Tag 161735ab18970493o0 Our tag: as482927b4 [Nov 14 17:25:32] DEBUG[22186]: chan_sip.c:4401 find_call: = No match Their Call ID: e7097cd816051d56@00304f4d7e30-1 Their Tag 78161 Our tag: as40911e15 [Nov 14 17:25:32] DEBUG[22186]: chan_sip.c:4401 find_call: = No match Their Call ID: 1a91c35355d773b1@192.168.200.234 Their Tag 6c141872b4972e95 Our tag: as38748131 [Nov 14 17:25:32] DEBUG[22186]: chan_sip.c:4401 find_call: = No match Their Call ID: 1a91c35355d773b1@192.168.200.247 Their Tag 6c141872b4972e95 Our tag: as17678152 [Nov 14 17:25:32] DEBUG[22186]: chan_sip.c:4401 find_call: = No match Their Call ID: bfb1420b-573d5f06@195.94.224.214 Their Tag a2fdee4712b03ffao0 Our tag: as57e699ee [Nov 14 17:25:32] DEBUG[22186]: chan_sip.c:4401 find_call: = No match Their Call ID: chxiakn3nupUijLX@192.168.1.2 Their Tag EJnxD1Oalor3SsCS Our tag: as5e66093e [Nov 14 17:25:32] DEBUG[22186]: chan_sip.c:4401 find_call: = No match Their Call ID: 81521501-c97db9cc@192.168.11.254 Their Tag 8ba4182988eb50c4o1 Our tag: as2ec1dc3e [Nov 14 17:25:32] DEBUG[22186]: chan_sip.c:4401 find_call: = No match Their Call ID: 167278e5-d7740738@192.168.11.254 Their Tag c7d24d149a16c3co0 Our tag: as5bef2479 <--- Transmitting (no NAT) to 195.94.224.214:5060 ---> SIP/2.0 489 Bad event Via: SIP/2.0/UDP 195.94.224.214:5060;branch=z9hG4bK-9b5cca9a;received=195.94.224.214;rport=5060 From: 1000 ;tag=55c75a49bfc3f9c1o0 To: ;tag=as11dbae11 Call-ID: b660adc9-280ebc41@195.94.224.214 CSeq: 7717 NOTIFY User-Agent: Asterisk PBX Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY Supported: replaces Content-Length: 0 <------------> [Nov 14 17:25:32] DEBUG[22186]: chan_sip.c:14721 sipsock_read: Invalid SIP message - rejected , no callid, len 350 [Nov 14 17:25:32] DEBUG[22614]: channel.c:1441 queue_frame_to_spies: Building translator from ulaw to SLINEAR for spies on channel SIP/1000-081dec40 [Nov 14 17:25:32] DEBUG[22614]: rtp.c:2628 ast_rtp_write: Ooh, format changed from unknown to alaw [Nov 14 17:25:32] DEBUG[22614]: rtp.c:2645 ast_rtp_write: Created smoother: format: 8 ms: 20 len: 160 [Nov 14 17:25:32] DEBUG[22614]: channel.c:1441 queue_frame_to_spies: Building translator from ulaw to SLINEAR for spies on channel SIP/1000-081dec40 [Nov 14 17:25:32] DEBUG[22614]: rtp.c:2628 ast_rtp_write: Ooh, format changed from unknown to ulaw [Nov 14 17:25:32] DEBUG[22614]: rtp.c:2645 ast_rtp_write: Created smoother: format: 4 ms: 20 len: 160 [Nov 14 17:25:33] DEBUG[22186]: chan_sip.c:2025 __sip_autodestruct: Auto destroying SIP dialog '167278e5-d7740738@192.168.11.254' [Nov 14 17:25:33] DEBUG[22186]: chan_sip.c:3172 sip_destroy: Destroying SIP dialog 167278e5-d7740738@192.168.11.254 Really destroying SIP dialog '167278e5-d7740738@192.168.11.254' Method: REGISTER [Nov 14 17:25:33] DEBUG[22186]: chan_sip.c:2025 __sip_autodestruct: Auto destroying SIP dialog '81521501-c97db9cc@192.168.11.254' [Nov 14 17:25:33] DEBUG[22186]: chan_sip.c:3172 sip_destroy: Destroying SIP dialog 81521501-c97db9cc@192.168.11.254 Really destroying SIP dialog '81521501-c97db9cc@192.168.11.254' Method: REGISTER <--- SIP read from 195.94.224.214:5060 ---> NOTIFY sip:195.94.224.208 SIP/2.0 Via: SIP/2.0/UDP 195.94.224.214:5060;branch=z9hG4bK-9b5cca9a;rport From: 1000 ;tag=55c75a49bfc3f9c1o0 To: Call-ID: b660adc9-280ebc41@195.94.224.214 CSeq: 7717 NOTIFY Max-Forwards: 70 Event: keep-alive User-Agent: Sipura/SPA1001-2.0.13(SEg) Content-Length: 0 <-------------> [Nov 14 17:25:33] DEBUG[22186]: chan_sip.c:4602 parse_request: Header 0 [ 33]: NOTIFY sip:195.94.224.208 SIP/2.0 [Nov 14 17:25:33] DEBUG[22186]: chan_sip.c:4602 parse_request: Header 1 [ 66]: Via: SIP/2.0/UDP 195.94.224.214:5060;branch=z9hG4bK-9b5cca9a;rport [Nov 14 17:25:33] DEBUG[22186]: chan_sip.c:4602 parse_request: Header 2 [ 59]: From: 1000 ;tag=55c75a49bfc3f9c1o0 [Nov 14 17:25:33] DEBUG[22186]: chan_sip.c:4602 parse_request: Header 3 [ 24]: To: [Nov 14 17:25:33] DEBUG[22186]: chan_sip.c:4602 parse_request: Header 4 [ 41]: Call-ID: b660adc9-280ebc41@195.94.224.214 [Nov 14 17:25:33] DEBUG[22186]: chan_sip.c:4602 parse_request: Header 5 [ 17]: CSeq: 7717 NOTIFY [Nov 14 17:25:33] DEBUG[22186]: chan_sip.c:4602 parse_request: Header 6 [ 16]: Max-Forwards: 70 [Nov 14 17:25:33] DEBUG[22186]: chan_sip.c:4602 parse_request: Header 7 [ 17]: Event: keep-alive [Nov 14 17:25:33] DEBUG[22186]: chan_sip.c:4602 parse_request: Header 8 [ 38]: User-Agent: Sipura/SPA1001-2.0.13(SEg) [Nov 14 17:25:33] DEBUG[22186]: chan_sip.c:4602 parse_request: Header 9 [ 17]: Content-Length: 0 [Nov 14 17:25:33] DEBUG[22186]: chan_sip.c:4602 parse_request: Header 10 [ 0]: --- (10 headers 0 lines) --- [Nov 14 17:25:33] DEBUG[22186]: chan_sip.c:4401 find_call: = No match Their Call ID: 2861823763f158e33fe07d5c0e37225b@195.94.224.208 Their Tag 153507B8-1F33 Our tag: as7dde7e49 [Nov 14 17:25:33] DEBUG[22186]: chan_sip.c:4401 find_call: = No match Their Call ID: bc01fd8b-34f7de33@195.94.224.214 Their Tag 161735ab18970493o0 Our tag: as482927b4 [Nov 14 17:25:33] DEBUG[22186]: chan_sip.c:4401 find_call: = No match Their Call ID: e7097cd816051d56@00304f4d7e30-1 Their Tag 78161 Our tag: as40911e15 [Nov 14 17:25:33] DEBUG[22186]: chan_sip.c:4401 find_call: = No match Their Call ID: 1a91c35355d773b1@192.168.200.234 Their Tag 6c141872b4972e95 Our tag: as38748131 [Nov 14 17:25:33] DEBUG[22186]: chan_sip.c:4401 find_call: = No match Their Call ID: 1a91c35355d773b1@192.168.200.247 Their Tag 6c141872b4972e95 Our tag: as17678152 [Nov 14 17:25:33] DEBUG[22186]: chan_sip.c:4401 find_call: = No match Their Call ID: bfb1420b-573d5f06@195.94.224.214 Their Tag a2fdee4712b03ffao0 Our tag: as57e699ee [Nov 14 17:25:33] DEBUG[22186]: chan_sip.c:4401 find_call: = No match Their Call ID: chxiakn3nupUijLX@192.168.1.2 Their Tag EJnxD1Oalor3SsCS Our tag: as5e66093e <--- Transmitting (no NAT) to 195.94.224.214:5060 ---> SIP/2.0 489 Bad event Via: SIP/2.0/UDP 195.94.224.214:5060;branch=z9hG4bK-9b5cca9a;received=195.94.224.214;rport=5060 From: 1000 ;tag=55c75a49bfc3f9c1o0 To: ;tag=as0855229f Call-ID: b660adc9-280ebc41@195.94.224.214 CSeq: 7717 NOTIFY User-Agent: Asterisk PBX Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY Supported: replaces Content-Length: 0 <------------> [Nov 14 17:25:33] DEBUG[22186]: chan_sip.c:14721 sipsock_read: Invalid SIP message - rejected , no callid, len 350 <--- SIP read from 195.94.224.214:5060 ---> NOTIFY sip:195.94.224.208 SIP/2.0 Via: SIP/2.0/UDP 195.94.224.214:5060;branch=z9hG4bK-9b5cca9a;rport From: 1000 ;tag=55c75a49bfc3f9c1o0 To: Call-ID: b660adc9-280ebc41@195.94.224.214 CSeq: 7717 NOTIFY Max-Forwards: 70 Event: keep-alive User-Agent: Sipura/SPA1001-2.0.13(SEg) Content-Length: 0 <-------------> [Nov 14 17:25:34] DEBUG[22186]: chan_sip.c:4602 parse_request: Header 0 [ 33]: NOTIFY sip:195.94.224.208 SIP/2.0 [Nov 14 17:25:34] DEBUG[22186]: chan_sip.c:4602 parse_request: Header 1 [ 66]: Via: SIP/2.0/UDP 195.94.224.214:5060;branch=z9hG4bK-9b5cca9a;rport [Nov 14 17:25:34] DEBUG[22186]: chan_sip.c:4602 parse_request: Header 2 [ 59]: From: 1000 ;tag=55c75a49bfc3f9c1o0 [Nov 14 17:25:34] DEBUG[22186]: chan_sip.c:4602 parse_request: Header 3 [ 24]: To: [Nov 14 17:25:34] DEBUG[22186]: chan_sip.c:4602 parse_request: Header 4 [ 41]: Call-ID: b660adc9-280ebc41@195.94.224.214 [Nov 14 17:25:34] DEBUG[22186]: chan_sip.c:4602 parse_request: Header 5 [ 17]: CSeq: 7717 NOTIFY [Nov 14 17:25:34] DEBUG[22186]: chan_sip.c:4602 parse_request: Header 6 [ 16]: Max-Forwards: 70 [Nov 14 17:25:34] DEBUG[22186]: chan_sip.c:4602 parse_request: Header 7 [ 17]: Event: keep-alive [Nov 14 17:25:34] DEBUG[22186]: chan_sip.c:4602 parse_request: Header 8 [ 38]: User-Agent: Sipura/SPA1001-2.0.13(SEg) [Nov 14 17:25:34] DEBUG[22186]: chan_sip.c:4602 parse_request: Header 9 [ 17]: Content-Length: 0 [Nov 14 17:25:34] DEBUG[22186]: chan_sip.c:4602 parse_request: Header 10 [ 0]: --- (10 headers 0 lines) --- [Nov 14 17:25:34] DEBUG[22186]: chan_sip.c:4401 find_call: = No match Their Call ID: 2861823763f158e33fe07d5c0e37225b@195.94.224.208 Their Tag 153507B8-1F33 Our tag: as7dde7e49 [Nov 14 17:25:34] DEBUG[22186]: chan_sip.c:4401 find_call: = No match Their Call ID: bc01fd8b-34f7de33@195.94.224.214 Their Tag 161735ab18970493o0 Our tag: as482927b4 [Nov 14 17:25:34] DEBUG[22186]: chan_sip.c:4401 find_call: = No match Their Call ID: e7097cd816051d56@00304f4d7e30-1 Their Tag 78161 Our tag: as40911e15 [Nov 14 17:25:34] DEBUG[22186]: chan_sip.c:4401 find_call: = No match Their Call ID: 1a91c35355d773b1@192.168.200.234 Their Tag 6c141872b4972e95 Our tag: as38748131 [Nov 14 17:25:34] DEBUG[22186]: chan_sip.c:4401 find_call: = No match Their Call ID: 1a91c35355d773b1@192.168.200.247 Their Tag 6c141872b4972e95 Our tag: as17678152 [Nov 14 17:25:34] DEBUG[22186]: chan_sip.c:4401 find_call: = No match Their Call ID: bfb1420b-573d5f06@195.94.224.214 Their Tag a2fdee4712b03ffao0 Our tag: as57e699ee [Nov 14 17:25:34] DEBUG[22186]: chan_sip.c:4401 find_call: = No match Their Call ID: chxiakn3nupUijLX@192.168.1.2 Their Tag EJnxD1Oalor3SsCS Our tag: as5e66093e <--- Transmitting (no NAT) to 195.94.224.214:5060 ---> SIP/2.0 489 Bad event Via: SIP/2.0/UDP 195.94.224.214:5060;branch=z9hG4bK-9b5cca9a;received=195.94.224.214;rport=5060 From: 1000 ;tag=55c75a49bfc3f9c1o0 To: ;tag=as4f5d77ed Call-ID: b660adc9-280ebc41@195.94.224.214 CSeq: 7717 NOTIFY User-Agent: Asterisk PBX Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY Supported: replaces Content-Length: 0 <------------> [Nov 14 17:25:34] DEBUG[22186]: chan_sip.c:14721 sipsock_read: Invalid SIP message - rejected , no callid, len 350 [Nov 14 17:25:35] DEBUG[22614]: rtp.c:858 ast_rtcp_read: Got RTCP report of 136 bytes [Nov 14 17:25:35] NOTICE[22614]: rtp.c:764 process_rfc3389: Comfort noise support incomplete in Asterisk (RFC 3389). Please turn off on client if possible. Client IP: 195.94.224.195 [Nov 14 17:25:36] DEBUG[22614]: channel.c:1496 queue_frame_to_spies: Triggering queue flush for spy 'MixMonitor' on 'SIP/1000-081dec40' <--- SIP read from 195.94.224.214:5060 ---> NOTIFY sip:195.94.224.208 SIP/2.0 Via: SIP/2.0/UDP 195.94.224.214:5060;branch=z9hG4bK-9b5cca9a;rport From: 1000 ;tag=55c75a49bfc3f9c1o0 To: Call-ID: b660adc9-280ebc41@195.94.224.214 CSeq: 7717 NOTIFY Max-Forwards: 70 Event: keep-alive User-Agent: Sipura/SPA1001-2.0.13(SEg) Content-Length: 0 <-------------> [Nov 14 17:25:36] DEBUG[22186]: chan_sip.c:4602 parse_request: Header 0 [ 33]: NOTIFY sip:195.94.224.208 SIP/2.0 [Nov 14 17:25:36] DEBUG[22186]: chan_sip.c:4602 parse_request: Header 1 [ 66]: Via: SIP/2.0/UDP 195.94.224.214:5060;branch=z9hG4bK-9b5cca9a;rport [Nov 14 17:25:36] DEBUG[22186]: chan_sip.c:4602 parse_request: Header 2 [ 59]: From: 1000 ;tag=55c75a49bfc3f9c1o0 [Nov 14 17:25:36] DEBUG[22186]: chan_sip.c:4602 parse_request: Header 3 [ 24]: To: [Nov 14 17:25:36] DEBUG[22186]: chan_sip.c:4602 parse_request: Header 4 [ 41]: Call-ID: b660adc9-280ebc41@195.94.224.214 [Nov 14 17:25:36] DEBUG[22186]: chan_sip.c:4602 parse_request: Header 5 [ 17]: CSeq: 7717 NOTIFY [Nov 14 17:25:36] DEBUG[22186]: chan_sip.c:4602 parse_request: Header 6 [ 16]: Max-Forwards: 70 [Nov 14 17:25:36] DEBUG[22186]: chan_sip.c:4602 parse_request: Header 7 [ 17]: Event: keep-alive [Nov 14 17:25:36] DEBUG[22186]: chan_sip.c:4602 parse_request: Header 8 [ 38]: User-Agent: Sipura/SPA1001-2.0.13(SEg) [Nov 14 17:25:36] DEBUG[22186]: chan_sip.c:4602 parse_request: Header 9 [ 17]: Content-Length: 0 [Nov 14 17:25:36] DEBUG[22186]: chan_sip.c:4602 parse_request: Header 10 [ 0]: --- (10 headers 0 lines) --- [Nov 14 17:25:36] DEBUG[22186]: chan_sip.c:4401 find_call: = No match Their Call ID: 2861823763f158e33fe07d5c0e37225b@195.94.224.208 Their Tag 153507B8-1F33 Our tag: as7dde7e49 [Nov 14 17:25:36] DEBUG[22186]: chan_sip.c:4401 find_call: = No match Their Call ID: bc01fd8b-34f7de33@195.94.224.214 Their Tag 161735ab18970493o0 Our tag: as482927b4 [Nov 14 17:25:36] DEBUG[22186]: chan_sip.c:4401 find_call: = No match Their Call ID: e7097cd816051d56@00304f4d7e30-1 Their Tag 78161 Our tag: as40911e15 [Nov 14 17:25:36] DEBUG[22186]: chan_sip.c:4401 find_call: = No match Their Call ID: 1a91c35355d773b1@192.168.200.234 Their Tag 6c141872b4972e95 Our tag: as38748131 [Nov 14 17:25:36] DEBUG[22186]: chan_sip.c:4401 find_call: = No match Their Call ID: 1a91c35355d773b1@192.168.200.247 Their Tag 6c141872b4972e95 Our tag: as17678152 [Nov 14 17:25:36] DEBUG[22186]: chan_sip.c:4401 find_call: = No match Their Call ID: bfb1420b-573d5f06@195.94.224.214 Their Tag a2fdee4712b03ffao0 Our tag: as57e699ee [Nov 14 17:25:36] DEBUG[22186]: chan_sip.c:4401 find_call: = No match Their Call ID: chxiakn3nupUijLX@192.168.1.2 Their Tag EJnxD1Oalor3SsCS Our tag: as5e66093e <--- Transmitting (no NAT) to 195.94.224.214:5060 ---> SIP/2.0 489 Bad event Via: SIP/2.0/UDP 195.94.224.214:5060;branch=z9hG4bK-9b5cca9a;received=195.94.224.214;rport=5060 From: 1000 ;tag=55c75a49bfc3f9c1o0 To: ;tag=as1c594c87 Call-ID: b660adc9-280ebc41@195.94.224.214 CSeq: 7717 NOTIFY User-Agent: Asterisk PBX Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY Supported: replaces Content-Length: 0 <------------> [Nov 14 17:25:36] DEBUG[22186]: chan_sip.c:14721 sipsock_read: Invalid SIP message - rejected , no callid, len 350 [Nov 14 17:25:36] DEBUG[22614]: channel.c:1496 queue_frame_to_spies: Triggering queue flush for spy 'MixMonitor' on 'SIP/1000-081dec40' <--- SIP read from 195.94.224.195:5060 ---> SIP/2.0 200 OK Via: SIP/2.0/UDP 195.94.224.208:5060;branch=z9hG4bK10a488dc;rport From: "1000" ;tag=as7dde7e49 To: ;tag=153507B8-1F33 Date: Tue, 14 Nov 2006 13:43:34 GMT Call-ID: 2861823763f158e33fe07d5c0e37225b@195.94.224.208 Server: Cisco-SIPGateway/IOS-12.x CSeq: 102 INVITE Allow: INVITE, OPTIONS, BYE, CANCEL, ACK, PRACK, COMET, REFER, SUBSCRIBE, NOTIFY, INFO Allow-Events: telephone-event Contact: Content-Type: application/sdp Content-Length: 221 v=0 o=CiscoSystemsSIP-GW-UserAgent 5375 1510 IN IP4 195.94.224.195 s=SIP Call c=IN IP4 195.94.224.195 t=0 0 m=audio 18152 RTP/AVP 8 19 c=IN IP4 195.94.224.195 a=rtpmap:8 PCMA/8000 a=rtpmap:19 CN/8000 a=ptime:20 <-------------> [Nov 14 17:25:37] DEBUG[22186]: chan_sip.c:4602 parse_request: Header 0 [ 14]: SIP/2.0 200 OK [Nov 14 17:25:37] DEBUG[22186]: chan_sip.c:4602 parse_request: Header 1 [ 65]: Via: SIP/2.0/UDP 195.94.224.208:5060;branch=z9hG4bK10a488dc;rport [Nov 14 17:25:37] DEBUG[22186]: chan_sip.c:4602 parse_request: Header 2 [ 52]: From: "1000" ;tag=as7dde7e49 [Nov 14 17:25:37] DEBUG[22186]: chan_sip.c:4602 parse_request: Header 3 [ 57]: To: ;tag=153507B8-1F33 [Nov 14 17:25:37] DEBUG[22186]: chan_sip.c:4602 parse_request: Header 4 [ 35]: Date: Tue, 14 Nov 2006 13:43:34 GMT [Nov 14 17:25:37] DEBUG[22186]: chan_sip.c:4602 parse_request: Header 5 [ 56]: Call-ID: 2861823763f158e33fe07d5c0e37225b@195.94.224.208 [Nov 14 17:25:37] DEBUG[22186]: chan_sip.c:4602 parse_request: Header 6 [ 33]: Server: Cisco-SIPGateway/IOS-12.x [Nov 14 17:25:37] DEBUG[22186]: chan_sip.c:4602 parse_request: Header 7 [ 16]: CSeq: 102 INVITE [Nov 14 17:25:37] DEBUG[22186]: chan_sip.c:4602 parse_request: Header 8 [ 86]: Allow: INVITE, OPTIONS, BYE, CANCEL, ACK, PRACK, COMET, REFER, SUBSCRIBE, NOTIFY, INFO [Nov 14 17:25:37] DEBUG[22186]: chan_sip.c:4602 parse_request: Header 9 [ 29]: Allow-Events: telephone-event [Nov 14 17:25:37] DEBUG[22186]: chan_sip.c:4602 parse_request: Header 10 [ 49]: Contact: [Nov 14 17:25:37] DEBUG[22186]: chan_sip.c:4602 parse_request: Header 11 [ 29]: Content-Type: application/sdp [Nov 14 17:25:37] DEBUG[22186]: chan_sip.c:4602 parse_request: Header 12 [ 19]: Content-Length: 221 [Nov 14 17:25:37] DEBUG[22186]: chan_sip.c:4602 parse_request: Header 13 [ 0]: [Nov 14 17:25:37] DEBUG[22186]: chan_sip.c:4602 parse_request: Body 0 [ 3]: v=0 [Nov 14 17:25:37] DEBUG[22186]: chan_sip.c:4602 parse_request: Body 1 [ 62]: o=CiscoSystemsSIP-GW-UserAgent 5375 1510 IN IP4 195.94.224.195 [Nov 14 17:25:37] DEBUG[22186]: chan_sip.c:4602 parse_request: Body 2 [ 10]: s=SIP Call [Nov 14 17:25:37] DEBUG[22186]: chan_sip.c:4602 parse_request: Body 3 [ 23]: c=IN IP4 195.94.224.195 [Nov 14 17:25:37] DEBUG[22186]: chan_sip.c:4602 parse_request: Body 4 [ 5]: t=0 0 [Nov 14 17:25:37] DEBUG[22186]: chan_sip.c:4602 parse_request: Body 5 [ 26]: m=audio 18152 RTP/AVP 8 19 [Nov 14 17:25:37] DEBUG[22186]: chan_sip.c:4602 parse_request: Body 6 [ 23]: c=IN IP4 195.94.224.195 [Nov 14 17:25:37] DEBUG[22186]: chan_sip.c:4602 parse_request: Body 7 [ 20]: a=rtpmap:8 PCMA/8000 [Nov 14 17:25:37] DEBUG[22186]: chan_sip.c:4602 parse_request: Body 8 [ 19]: a=rtpmap:19 CN/8000 [Nov 14 17:25:37] DEBUG[22186]: chan_sip.c:4602 parse_request: Body 9 [ 10]: a=ptime:20 --- (13 headers 10 lines) --- [Nov 14 17:25:37] DEBUG[22186]: chan_sip.c:4401 find_call: = Found Their Call ID: 2861823763f158e33fe07d5c0e37225b@195.94.224.208 Their Tag 153507B8-1F33 Our tag: as7dde7e49 [Nov 14 17:25:37] DEBUG[22186]: chan_sip.c:2073 __sip_ack: Acked pending invite 102 [Nov 14 17:25:37] DEBUG[22186]: chan_sip.c:2088 __sip_ack: Stopping retransmission on '2861823763f158e33fe07d5c0e37225b@195.94.224.208' of Request 102: Match Found [Nov 14 17:25:37] DEBUG[22186]: chan_sip.c:11659 handle_response_invite: SIP response 200 to standard invite Found RTP audio format 8 Found RTP audio format 19 Peer audio RTP is at port 195.94.224.195:18152 Found description format PCMA for ID 8 Found description format CN for ID 19 [Nov 14 17:25:37] DEBUG[22186]: chan_sip.c:5119 process_sdp: T38 state changed to 0 on channel SIP/cisco1-081e6230 Capabilities: us - 0x3f1fff (g723|gsm|ulaw|alaw|g726|adpcm|slin|lpc10|g729|speex|ilbc|g726aal2|g722|jpeg|png|h261|h263|h263p|h264), peer - audio=0x8 (alaw)/video=0x0 (nothing), combined - 0x8 (alaw) Non-codec capabilities (dtmf): us - 0x1 (telephone-event), peer - 0x2 (CN), combined - 0x0 (nothing) Peer audio RTP is at port 195.94.224.195:18152 [Nov 14 17:25:37] DEBUG[22186]: chan_sip.c:5196 process_sdp: We're settling with these formats: 0x8 (alaw) [Nov 14 17:25:37] DEBUG[22186]: chan_sip.c:5203 process_sdp: We have an owner, now see if we need to change this call [Nov 14 17:25:37] DEBUG[22186]: chan_sip.c:3071 update_call_counter: Updating call counter for outgoing call [Nov 14 17:25:37] DEBUG[22186]: chan_sip.c:7909 build_route: build_route: Contact hop: list_route: hop: [Nov 14 17:25:37] DEBUG[22186]: chan_sip.c:5626 reqprep: Strict routing enforced for session 2861823763f158e33fe07d5c0e37225b@195.94.224.208 set_destination: Parsing for address/port to send to set_destination: set destination to 195.94.224.195, port 5060 Transmitting (NAT) to 195.94.224.195:5060: ACK sip:09774952210797@195.94.224.195:5060 SIP/2.0 Via: SIP/2.0/UDP 195.94.224.208:5060;branch=z9hG4bK1823cdf1;rport Max-Forwards: 70 From: "1000" ;tag=as7dde7e49 To: ;tag=153507B8-1F33 Contact: Call-ID: 2861823763f158e33fe07d5c0e37225b@195.94.224.208 CSeq: 102 ACK User-Agent: Asterisk PBX Content-Length: 0 --- [Nov 14 17:25:37] DEBUG[22614]: devicestate.c:303 __ast_device_state_changed_literal: Notification of state change to be queued on device/channel SIP/cisco1-081e6230 -- SIP/cisco1-081e6230 answered SIP/1000-081dec40 [Nov 14 17:25:37] DEBUG[22614]: channel.c:2735 set_format: Set channel SIP/1000-081dec40 to read format alaw [Nov 14 17:25:37] DEBUG[22614]: channel.c:2735 set_format: Set channel SIP/cisco1-081e6230 to write format alaw [Nov 14 17:25:37] DEBUG[22614]: devicestate.c:303 __ast_device_state_changed_literal: Notification of state change to be queued on device/channel SIP/1000-081dec40 [Nov 14 17:25:37] DEBUG[22614]: chan_sip.c:3514 sip_answer: SIP answering channel: SIP/1000-081dec40 [Nov 14 17:25:37] DEBUG[22614]: chan_sip.c:6415 transmit_response_with_sdp: Setting framing from config on incoming call [Nov 14 17:25:37] DEBUG[22614]: chan_sip.c:6190 add_sdp: ** Our capability: 0xc (ulaw|alaw) Video flag: True [Nov 14 17:25:37] DEBUG[22614]: chan_sip.c:6191 add_sdp: ** Our prefcodec: 0x0 (nothing) Audio is at 195.94.224.208 port 17754 Adding codec 0x4 (ulaw) to SDP Adding codec 0x8 (alaw) to SDP Adding non-codec 0x1 (telephone-event) to SDP [Nov 14 17:25:37] DEBUG[22614]: chan_sip.c:6316 add_sdp: -- Done with adding codecs to SDP [Nov 14 17:25:37] DEBUG[22614]: channel.c:2275 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=-1) [Nov 14 17:25:37] DEBUG[22614]: chan_sip.c:6360 add_sdp: Done building SDP. Settling with this capability: 0xc (ulaw|alaw) <--- Reliably Transmitting (NAT) to 195.94.224.214:5060 ---> SIP/2.0 200 OK Via: SIP/2.0/UDP 195.94.224.214:5060;branch=z9hG4bK-d70fe19b;received=195.94.224.214;rport=5060 From: 1000 ;tag=161735ab18970493o0 To: ;tag=as482927b4 Call-ID: bc01fd8b-34f7de33@195.94.224.214 CSeq: 102 INVITE User-Agent: Asterisk PBX Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY Supported: replaces Contact: Content-Type: application/sdp Content-Length: 268 v=0 o=root 22166 22167 IN IP4 195.94.224.208 s=session c=IN IP4 195.94.224.208 t=0 0 m=audio 17754 RTP/AVP 0 8 101 a=rtpmap:0 PCMU/8000 a=rtpmap:8 PCMA/8000 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-16 a=silenceSupp:off - - - - a=ptime:20 a=sendrecv <------------> [Nov 14 17:25:37] DEBUG[22614]: chan_sip.c:1979 __sip_reliable_xmit: *** SIP TIMER: Initalizing retransmit timer on packet: Id #1470 [Nov 14 17:25:37] DEBUG[22169]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for SIP - cisco1 [Nov 14 17:25:37] DEBUG[22169]: chan_sip.c:15136 sip_devicestate: Checking device state for peer cisco1 [Nov 14 17:25:37] DEBUG[22169]: res_config_mysql.c:809 mysql_reconnect: MySQL RealTime: Everything is fine. [Nov 14 17:25:37] DEBUG[22169]: res_config_mysql.c:139 realtime_mysql: MySQL RealTime: Retrieve SQL: SELECT * FROM sip WHERE name = 'cisco1' -- fixed jitterbuffer created on channel SIP/cisco1-081e6230 -- fixed jitterbuffer created on channel SIP/1000-081dec40 [Nov 14 17:25:37] DEBUG[22169]: chan_sip.c:15770 build_peer: -REALTIME- peer built. Name: . Peer objects: 1 [Nov 14 17:25:37] DEBUG[22169]: chan_sip.c:2524 realtime_peer: -REALTIME- loading peer from database to memory. Name: cisco1. Peer objects: 1 [Nov 14 17:25:37] DEBUG[22169]: chan_sip.c:2428 sip_destroy_peer: Destroying SIP peer cisco1 [Nov 14 17:25:37] DEBUG[22169]: chan_sip.c:2452 sip_destroy_peer: -REALTIME- peer Destroyed. Name: cisco1. Realtime Peer objects: 0 [Nov 14 17:25:37] DEBUG[22169]: devicestate.c:287 do_state_change: Changing state for SIP/cisco1 - state 1 (Not in use) [Nov 14 17:25:37] DEBUG[22169]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for SIP - 1000 [Nov 14 17:25:37] DEBUG[22169]: chan_sip.c:15136 sip_devicestate: Checking device state for peer 1000 [Nov 14 17:25:37] DEBUG[22617]: app_queue.c:568 changethread: Device 'SIP/cisco1' changed to state '1' (Not in use) but we don't care because they're not a member of any queue. [Nov 14 17:25:37] DEBUG[22169]: res_config_mysql.c:809 mysql_reconnect: MySQL RealTime: Everything is fine. [Nov 14 17:25:37] DEBUG[22169]: res_config_mysql.c:139 realtime_mysql: MySQL RealTime: Retrieve SQL: SELECT * FROM sip WHERE name = '1000' [Nov 14 17:25:37] DEBUG[22169]: chan_sip.c:15770 build_peer: -REALTIME- peer built. Name: . Peer objects: 1 -- SIP Seeding peer from astdb: '1000' at 1000@195.94.224.214:5060 for 3600 [Nov 14 17:25:37] DEBUG[22169]: chan_sip.c:2524 realtime_peer: -REALTIME- loading peer from database to memory. Name: 1000. Peer objects: 1 [Nov 14 17:25:37] DEBUG[22169]: chan_sip.c:2428 sip_destroy_peer: Destroying SIP peer 1000 [Nov 14 17:25:37] DEBUG[22169]: chan_sip.c:2452 sip_destroy_peer: -REALTIME- peer Destroyed. Name: 1000. Realtime Peer objects: 0 [Nov 14 17:25:37] DEBUG[22169]: devicestate.c:287 do_state_change: Changing state for SIP/1000 - state 1 (Not in use) [Nov 14 17:25:37] DEBUG[22618]: app_queue.c:568 changethread: Device 'SIP/1000' changed to state '1' (Not in use) but we don't care because they're not a member of any queue. <--- SIP read from 195.94.224.214:5060 ---> ACK sip:02210797@195.94.224.208 SIP/2.0 Via: SIP/2.0/UDP 195.94.224.214:5060;branch=z9hG4bK-6d215f56;rport From: 1000 ;tag=161735ab18970493o0 To: ;tag=as482927b4 Call-ID: bc01fd8b-34f7de33@195.94.224.214 CSeq: 102 ACK Max-Forwards: 70 Authorization: Digest username="1000",realm="asterisk",nonce="5c3e2137",uri="sip:02210797@195.94.224.208",algorithm=MD5,response="1e1e0dc2de4fa9d61ebc5e753b74a5be" Contact: 1000 User-Agent: Sipura/SPA1001-2.0.13(SEg) Content-Length: 0 <-------------> [Nov 14 17:25:37] DEBUG[22186]: chan_sip.c:4602 parse_request: Header 0 [ 39]: ACK sip:02210797@195.94.224.208 SIP/2.0 [Nov 14 17:25:37] DEBUG[22186]: chan_sip.c:4602 parse_request: Header 1 [ 66]: Via: SIP/2.0/UDP 195.94.224.214:5060;branch=z9hG4bK-6d215f56;rport [Nov 14 17:25:37] DEBUG[22186]: chan_sip.c:4602 parse_request: Header 2 [ 59]: From: 1000 ;tag=161735ab18970493o0 [Nov 14 17:25:37] DEBUG[22186]: chan_sip.c:4602 parse_request: Header 3 [ 48]: To: ;tag=as482927b4 [Nov 14 17:25:37] DEBUG[22186]: chan_sip.c:4602 parse_request: Header 4 [ 41]: Call-ID: bc01fd8b-34f7de33@195.94.224.214 [Nov 14 17:25:37] DEBUG[22186]: chan_sip.c:4602 parse_request: Header 5 [ 13]: CSeq: 102 ACK [Nov 14 17:25:37] DEBUG[22186]: chan_sip.c:4602 parse_request: Header 6 [ 16]: Max-Forwards: 70 [Nov 14 17:25:37] DEBUG[22186]: chan_sip.c:4602 parse_request: Header 7 [163]: Authorization: Digest username="1000",realm="asterisk",nonce="5c3e2137",uri="sip:02210797@195.94.224.208",algorithm=MD5,response="1e1e0dc2de4fa9d61ebc5e753b74a5be" [Nov 14 17:25:37] DEBUG[22186]: chan_sip.c:4602 parse_request: Header 8 [ 44]: Contact: 1000 [Nov 14 17:25:37] DEBUG[22186]: chan_sip.c:4602 parse_request: Header 9 [ 38]: User-Agent: Sipura/SPA1001-2.0.13(SEg) [Nov 14 17:25:37] DEBUG[22186]: chan_sip.c:4602 parse_request: Header 10 [ 17]: Content-Length: 0 [Nov 14 17:25:37] DEBUG[22186]: chan_sip.c:4602 parse_request: Header 11 [ 0]: --- (11 headers 0 lines) --- [Nov 14 17:25:37] DEBUG[22186]: chan_sip.c:4401 find_call: = No match Their Call ID: 2861823763f158e33fe07d5c0e37225b@195.94.224.208 Their Tag 153507B8-1F33 Our tag: as7dde7e49 [Nov 14 17:25:37] DEBUG[22186]: chan_sip.c:4401 find_call: = Found Their Call ID: bc01fd8b-34f7de33@195.94.224.214 Their Tag 161735ab18970493o0 Our tag: as482927b4 [Nov 14 17:25:37] DEBUG[22186]: chan_sip.c:14546 handle_request: **** Received ACK (6) - Command in SIP ACK [Nov 14 17:25:37] DEBUG[22186]: chan_sip.c:2078 __sip_ack: ** SIP TIMER: Cancelling retransmit of packet (reply received) Retransid #1470 [Nov 14 17:25:37] DEBUG[22186]: chan_sip.c:2088 __sip_ack: Stopping retransmission on 'bc01fd8b-34f7de33@195.94.224.214' of Response 102: Match Found [Nov 14 17:25:37] DEBUG[22614]: rtp.c:2645 ast_rtp_write: Created smoother: format: 4 ms: 20 len: 160 [Nov 14 17:25:37] DEBUG[22614]: channel.c:1496 queue_frame_to_spies: Triggering queue flush for spy 'MixMonitor' on 'SIP/1000-081dec40' <--- SIP read from 81.195.98.98:5060 ---> 0 <-------------> [Nov 14 17:25:38] DEBUG[22186]: chan_sip.c:4602 parse_request: Header 0 [ 0]: --- (0 headers 0 lines) Nat keepalive --- Segmentation fault