Asterisk 1.2.9.1, 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.9.1 currently running on phone2 (pid = 22425) phone2*CLI> set verbose 4 phone2*CLI> Verbosity was 0 and is now 4 sip debug phone2*CLI> SIP Debugging enabled set debug 4 phone2*CLI> Core debug was 0 and is now 4 -- Accepting call from '9166104314' to '7729720' on channel 0/1, span 2 Jun 21 05:11:16 DEBUG[22429]: devicestate.c:187 do_state_change: Changing state for Zap/32 - state 2 (In use) Jun 21 05:11:16 DEBUG[22438]: chan_zap.c:1408 zt_enable_ec: No echo cancellation requested Jun 21 05:11:16 DEBUG[22444]: pbx.c:1677 pbx_extension_helper: Launching 'Answer' -- Executing Answer("Zap/32-1", "") in new stack Jun 21 05:11:16 DEBUG[22445]: app_queue.c:523 changethread: Device 'Zap/32' changed to state '2' (In use) but we don't care because they're not a member of any queue. Jun 21 05:11:16 DEBUG[22429]: channel.c:777 channel_find_locked: Avoiding initial deadlock for 'Zap/32-1' Jun 21 05:11:16 DEBUG[22444]: pbx.c:1522 pbx_substitute_variables_helper_full: Function result is '20060621-051116' Jun 21 05:11:16 DEBUG[22444]: pbx.c:1677 pbx_extension_helper: Launching 'Monitor' -- Executing Monitor("Zap/32-1", "|in-20060621-051116-9166104314|mb") in new stack Jun 21 05:11:16 DEBUG[22444]: pbx.c:1677 pbx_extension_helper: Launching 'Wait' -- Executing Wait("Zap/32-1", "0.5") in new stack Jun 21 05:11:16 DEBUG[22429]: devicestate.c:187 do_state_change: Changing state for Zap/32 - state 2 (In use) Jun 21 05:11:16 DEBUG[22446]: app_queue.c:523 changethread: Device 'Zap/32' changed to state '2' (In use) but we don't care because they're not a member of any queue. Jun 21 05:11:17 DEBUG[22444]: pbx.c:1677 pbx_extension_helper: Launching 'Queue' -- Executing Queue("Zap/32-1", "callcenterq|tw") in new stack Jun 21 05:11:17 DEBUG[22444]: app_queue.c:3049 queue_exec: NO QUEUE_PRIO variable found. Using default. Jun 21 05:11:17 DEBUG[22444]: app_queue.c:3057 queue_exec: queue: callcenterq, options: tw, url: (null), announce: (null), expires: 0, priority: 0 Jun 21 05:11:17 DEBUG[22444]: app_queue.c:1156 join_queue: Queue 'callcenterq' Join, Channel 'Zap/32-1', Position '1' -- Started music on hold, class 'default', on Zap/32-1 Jun 21 05:11:17 DEBUG[22444]: channel.c:1711 ast_settimeout: Scheduling timer at 160 sample intervals Jun 21 05:11:17 DEBUG[22444]: app_queue.c:2000 is_our_turn: It's our turn (Zap/32-1). Jun 21 05:11:17 DEBUG[22444]: app_queue.c:2196 try_calling: Zap/32-1 is trying to call a queue member. Jun 21 05:11:17 DEBUG[22444]: app_queue.c:2220 try_calling: Simple queue (no URL) Jun 21 05:11:17 DEBUG[22444]: app_queue.c:1613 ring_one: (Parallel) Trying 'Local/1211@toagent' with metric 0 Jun 21 05:11:17 DEBUG[22429]: devicestate.c:187 do_state_change: Changing state for Local/1211@toagent - state 2 (In use) Jun 21 05:11:17 DEBUG[22444]: channel.c:2823 ast_channel_inherit_variables: Not copying variable STACK-fromoutside-7729720-4. Jun 21 05:11:17 DEBUG[22444]: channel.c:2823 ast_channel_inherit_variables: Not copying variable STACK-fromoutside-7729720-3. Jun 21 05:11:17 DEBUG[22444]: channel.c:2823 ast_channel_inherit_variables: Not copying variable AUTO_MONITOR. Jun 21 05:11:17 DEBUG[22444]: channel.c:2823 ast_channel_inherit_variables: Not copying variable STACK-fromoutside-7729720-2. Jun 21 05:11:17 DEBUG[22444]: channel.c:2823 ast_channel_inherit_variables: Not copying variable STACK-fromoutside-7729720-1. Jun 21 05:11:17 DEBUG[22444]: channel.c:2823 ast_channel_inherit_variables: Not copying variable CALLEDTON. Jun 21 05:11:17 DEBUG[22444]: channel.c:2823 ast_channel_inherit_variables: Not copying variable ANI2. Jun 21 05:11:17 DEBUG[22444]: channel.c:2823 ast_channel_inherit_variables: Not copying variable TRANSFERCAPABILITY. Jun 21 05:11:17 DEBUG[22447]: app_queue.c:492 changethread: -- Called Local/1211@toagent Device 'Local/1211@toagent' changed to state '2' (In use) Jun 21 05:11:17 DEBUG[22448]: pbx.c:1522 pbx_substitute_variables_helper_full: Function result is 'SIP/1211' Jun 21 05:11:17 DEBUG[22448]: pbx.c:1677 pbx_extension_helper: Launching 'Set' -- Executing Set("Local/1211@toagent-0b79,2", "chan=SIP/1211") in new stack Jun 21 05:11:17 DEBUG[22448]: pbx.c:1677 pbx_extension_helper: Launching 'ChanIsAvail' -- Executing ChanIsAvail("Local/1211@toagent-0b79,2", "SIP/1211|s") in new stack Jun 21 05:11:17 DEBUG[22448]: chan_sip.c:11668 sip_devicestate: Checking device state for peer 1211 Jun 21 05:11:17 DEBUG[22448]: chan_sip.c:3147 sip_alloc: Allocating new SIP dialog for (No Call-ID) - INVITE (With RTP) Jun 21 05:11:17 DEBUG[22448]: chan_sip.c:1874 create_addr_from_peer: Setting NAT on RTP to 524288 Jun 21 05:11:17 DEBUG[22448]: chan_sip.c:1878 create_addr_from_peer: Setting NAT on VRTP to 524288 Jun 21 05:11:17 DEBUG[22448]: channel.c:1323 ast_hangup: Hanging up channel 'SIP/1211-0fb2' Jun 21 05:11:17 DEBUG[22448]: chan_sip.c:2418 sip_hangup: Hangup call SIP/1211-0fb2, SIP callid 66ed24f964f5a9f31b18115d66a78459@masterhost.ru) Jun 21 05:11:17 DEBUG[22448]: chan_sip.c:2426 sip_hangup: update_call_counter(1211) - decrement call limit counter Jun 21 05:11:17 DEBUG[22448]: chan_sip.c:2209 update_call_counter: Updating call counter for incoming call Jun 21 05:11:17 DEBUG[22429]: chan_sip.c:11668 sip_devicestate: Checking device state for peer 1211 Jun 21 05:11:17 DEBUG[22448]: pbx.c:1677 pbx_extension_helper: Launching 'NoOp' -- Executing NoOp("Local/1211@toagent-0b79,2", "0") in new stack Jun 21 05:11:17 DEBUG[22429]: devicestate.c:187 do_state_change: Changing state for SIP/1211 - state 1 (Not in use) Jun 21 05:11:17 DEBUG[22449]: app_queue.c:523 changethread: Device 'SIP/1211' changed to state '1' (Not in use) but we don't care because they're not a member of any queue. Jun 21 05:11:17 DEBUG[22448]: pbx.c:1589 pbx_substitute_variables_helper_full: Expression result is '0' Jun 21 05:11:17 DEBUG[22448]: pbx.c:1677 pbx_extension_helper: Launching 'GotoIf' -- Executing GotoIf("Local/1211@toagent-0b79,2", "0?unavail") in new stack Jun 21 05:11:17 DEBUG[22448]: pbx.c:6175 pbx_builtin_gotoif: Not taking any branch Jun 21 05:11:17 DEBUG[22448]: pbx.c:1589 pbx_substitute_variables_helper_full: Expression result is '0' Jun 21 05:11:17 DEBUG[22448]: pbx.c:1677 pbx_extension_helper: Launching 'GotoIf' -- Executing GotoIf("Local/1211@toagent-0b79,2", "0?busy") in new stack Jun 21 05:11:17 DEBUG[22448]: pbx.c:6175 pbx_builtin_gotoif: Not taking any branch Jun 21 05:11:17 DEBUG[22448]: pbx.c:1677 pbx_extension_helper: Launching 'Dial' -- Executing Dial("Local/1211@toagent-0b79,2", "SIP/1211|30|tw") in new stack Jun 21 05:11:17 DEBUG[22448]: chan_sip.c:3147 sip_alloc: Allocating new SIP dialog for (No Call-ID) - INVITE (With RTP) Jun 21 05:11:17 DEBUG[22448]: chan_sip.c:1874 create_addr_from_peer: Setting NAT on RTP to 524288 Jun 21 05:11:17 DEBUG[22448]: chan_sip.c:1878 create_addr_from_peer: Setting NAT on VRTP to 524288 Jun 21 05:11:17 DEBUG[22448]: channel.c:2823 ast_channel_inherit_variables: Not copying variable STACK-toagent-1211-6. Destroying call '66ed24f964f5a9f31b18115d66a78459@masterhost.ru' Jun 21 05:11:17 DEBUG[22448]: channel.c:2823 ast_channel_inherit_variables: Not copying variable STACK-toagent-1211-5. Jun 21 05:11:17 DEBUG[22448]: channel.c:2823 ast_channel_inherit_variables: Not copying variable STACK-toagent-1211-4. Jun 21 05:11:17 DEBUG[22448]: channel.c:2823 ast_channel_inherit_variables: Not copying variable STACK-toagent-1211-3. Jun 21 05:11:17 DEBUG[22448]: channel.c:2823 ast_channel_inherit_variables: Not copying variable AVAILSTATUS. Jun 21 05:11:17 DEBUG[22448]: channel.c:2823 ast_channel_inherit_variables: Not copying variable AVAILORIGCHAN. Jun 21 05:11:17 DEBUG[22448]: channel.c:2823 ast_channel_inherit_variables: Not copying variable AVAILCHAN. Jun 21 05:11:17 DEBUG[22448]: channel.c:2823 ast_channel_inherit_variables: Not copying variable STACK-toagent-1211-2. Jun 21 05:11:17 DEBUG[22448]: channel.c:2823 ast_channel_inherit_variables: Not copying variable chan. Jun 21 05:11:17 DEBUG[22448]: channel.c:2823 ast_channel_inherit_variables: Not copying variable STACK-toagent-1211-1. Jun 21 05:11:17 DEBUG[22448]: channel.c:2823 ast_channel_inherit_variables: Not copying variable DB_RESULT. Jun 21 05:11:17 DEBUG[22448]: chan_sip.c:2068 sip_call: Outgoing Call for 1211 Jun 21 05:11:17 DEBUG[22448]: chan_sip.c:2209 update_call_counter: Updating call counter for outgoing call We're at 83.222.22.242 port 18868 Video is at 83.222.22.242 port 14398 Adding codec 0x4 (ulaw) to SDP Adding codec 0x8 (alaw) to SDP Adding codec 0x2 (gsm) to SDP Adding codec 0x80000 (h263) to SDP Adding non-codec 0x1 (telephone-event) to SDP Jun 21 05:11:17 DEBUG[22448]: chan_sip.c:3363 parse_request: Header 0: INVITE sip:1211@10.10.10.7:5060 SIP/2.0 (39) Jun 21 05:11:17 DEBUG[22448]: chan_sip.c:3363 parse_request: Header 1: Via: SIP/2.0/UDP 83.222.22.242:5060;branch=z9hG4bK3ad01157;rport (64) Jun 21 05:11:17 DEBUG[22448]: chan_sip.c:3363 parse_request: Header 2: From: "9166104314" ;tag=as78c50bc3 (64) Jun 21 05:11:17 DEBUG[22448]: chan_sip.c:3363 parse_request: Header 3: To: (30) Jun 21 05:11:17 DEBUG[22448]: chan_sip.c:3363 parse_request: Header 4: Contact: (39) Jun 21 05:11:17 DEBUG[22448]: chan_sip.c:3363 parse_request: Header 5: Call-ID: 25cc17a101808ece7e127e501478ea9c@masterhost.ru (55) Jun 21 05:11:17 DEBUG[22448]: chan_sip.c:3363 parse_request: Header 6: CSeq: 102 INVITE (16) Jun 21 05:11:17 DEBUG[22448]: chan_sip.c:3363 parse_request: Header 7: User-Agent: Asterisk PBX (24) Jun 21 05:11:17 DEBUG[22448]: chan_sip.c:3363 parse_request: Header 8: Max-Forwards: 70 (16) Jun 21 05:11:17 DEBUG[22448]: chan_sip.c:3363 parse_request: Header 9: Date: Wed, 21 Jun 2006 01:11:17 GMT (35) Jun 21 05:11:17 DEBUG[22448]: chan_sip.c:3363 parse_request: Header 10: Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY (66) Jun 21 05:11:17 DEBUG[22448]: chan_sip.c:3363 parse_request: Header 11: Content-Type: application/sdp (29) Jun 21 05:11:17 DEBUG[22448]: chan_sip.c:3363 parse_request: Header 12: Content-Length: 315 (19) Jun 21 05:11:17 DEBUG[22448]: chan_sip.c:3363 parse_request: Header 13: (0) Jun 21 05:11:17 DEBUG[22448]: chan_sip.c:3395 parse_request: Line: v=0 (3) Jun 21 05:11:17 DEBUG[22448]: chan_sip.c:3395 parse_request: Line: o=root 22425 22425 IN IP4 83.222.22.242 (39) Jun 21 05:11:17 DEBUG[22448]: chan_sip.c:3395 parse_request: Line: s=session (9) Jun 21 05:11:17 DEBUG[22448]: chan_sip.c:3395 parse_request: Line: c=IN IP4 83.222.22.242 (22) Jun 21 05:11:17 DEBUG[22448]: chan_sip.c:3395 parse_request: Line: t=0 0 (5) Jun 21 05:11:17 DEBUG[22448]: chan_sip.c:3395 parse_request: Line: m=audio 18868 RTP/AVP 0 8 3 101 (31) Jun 21 05:11:17 DEBUG[22448]: chan_sip.c:3395 parse_request: Line: a=rtpmap:0 PCMU/8000 (20) Jun 21 05:11:17 DEBUG[22448]: chan_sip.c:3395 parse_request: Line: a=rtpmap:8 PCMA/8000 (20) Jun 21 05:11:17 DEBUG[22448]: chan_sip.c:3395 parse_request: Line: a=rtpmap:3 GSM/8000 (19) Jun 21 05:11:17 DEBUG[22448]: chan_sip.c:3395 parse_request: Line: a=rtpmap:101 telephone-event/8000 (33) Jun 21 05:11:17 DEBUG[22448]: chan_sip.c:3395 parse_request: Line: a=fmtp:101 0-16 (15) Jun 21 05:11:17 DEBUG[22448]: chan_sip.c:3395 parse_request: Line: a=silenceSupp:off - - - - (25) Jun 21 05:11:17 DEBUG[22448]: chan_sip.c:3395 parse_request: Line: m=video 14398 RTP/AVP 34 (24) Jun 21 05:11:17 DEBUG[22448]: chan_sip.c:3395 parse_request: Line: a=rtpmap:34 H263/90000 (22) 13 headers, 14 lines Reliably Transmitting (NAT) to 83.237.98.254:62291: INVITE sip:1211@10.10.10.7:5060 SIP/2.0 Via: SIP/2.0/UDP 83.222.22.242:5060;branch=z9hG4bK3ad01157;rport From: "9166104314" ;tag=as78c50bc3 To: Contact: Call-ID: 25cc17a101808ece7e127e501478ea9c@masterhost.ru CSeq: 102 INVITE User-Agent: Asterisk PBX Max-Forwards: 70 Date: Wed, 21 Jun 2006 01:11:17 GMT Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY Content-Type: application/sdp Content-Length: 315 v=0 o=root 22425 22425 IN IP4 83.222.22.242 s=session c=IN IP4 83.222.22.242 t=0 0 m=audio 18868 RTP/AVP 0 8 3 101 a=rtpmap:0 PCMU/8000 a=rtpmap:8 PCMA/8000 a=rtpmap:3 GSM/8000 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-16 a=silenceSupp:off - - - - m=video 14398 RTP/AVP 34 a=rtpmap:34 H263/90000 --- Jun 21 05:11:17 DEBUG[22448]: chan_sip.c:1293 __sip_reliable_xmit: *** SIP TIMER: Initalizing retransmit timer on packet: Id #183 -- Called 1211 Jun 21 05:11:17 DEBUG[22448]: channel.c:2350 set_format: Set channel SIP/1211-97f9 to read format slin Jun 21 05:11:17 DEBUG[22448]: channel.c:2350 set_format: Set channel Local/1211@toagent-0b79,2 to write format slin Jun 21 05:11:17 DEBUG[22448]: channel.c:2350 set_format: Set channel Local/1211@toagent-0b79,2 to read format slin Jun 21 05:11:17 DEBUG[22448]: channel.c:2350 set_format: Set channel SIP/1211-97f9 to write format slin Jun 21 05:11:17 DEBUG[22444]: channel.c:1975 ast_read: Generator got voice, switching to phase locked mode Jun 21 05:11:17 DEBUG[22444]: channel.c:1711 ast_settimeout: Scheduling timer at 0 sample intervals Jun 21 05:11:17 DEBUG[22444]: channel.c:2350 set_format: Set channel Zap/32-1 to write format ulaw Jun 21 05:11:17 DEBUG[22444]: res_musiconhold.c:233 ast_moh_files_next: Zap/32-1 Opened file 2 '/var/lib/asterisk/mohmp3/misc/Heaven_For_Everyone_Queen' <-- SIP read from 83.237.98.254:62291: SIP/2.0 100 Trying Via: SIP/2.0/UDP 83.222.22.242:5060;rport=5060;received=83.222.22.242;branch=z9hG4bK3ad01157 Content-Length: 0 Call-ID: 25cc17a101808ece7e127e501478ea9c@masterhost.ru CSeq: 102 INVITE From: "9166104314";tag=as78c50bc3 Server: SJphone/1.60.289a (SJ Labs) To: "operator name";tag=11595025729485 Jun 21 05:11:17 DEBUG[22434]: chan_sip.c:3363 parse_request: Header 0: SIP/2.0 100 Trying (18) Jun 21 05:11:17 DEBUG[22434]: chan_sip.c:3363 parse_request: Header 1: Via: SIP/2.0/UDP 83.222.22.242:5060;rport=5060;received=83.222.22.242;branch=z9hG4bK3ad01157 (92) Jun 21 05:11:17 DEBUG[22434]: chan_sip.c:3363 parse_request: Header 2: Content-Length: 0 (17) Jun 21 05:11:17 DEBUG[22434]: chan_sip.c:3363 parse_request: Header 3: Call-ID: 25cc17a101808ece7e127e501478ea9c@masterhost.ru (55) Jun 21 05:11:17 DEBUG[22434]: chan_sip.c:3363 parse_request: Header 4: CSeq: 102 INVITE (16) Jun 21 05:11:17 DEBUG[22434]: chan_sip.c:3363 parse_request: Header 5: From: "9166104314";tag=as78c50bc3 (63) Jun 21 05:11:17 DEBUG[22434]: chan_sip.c:3363 parse_request: Header 6: Server: SJphone/1.60.289a (SJ Labs) (35) Jun 21 05:11:17 DEBUG[22434]: chan_sip.c:3363 parse_request: Header 7: To: "operator name";tag=11595025729485 (66) Jun 21 05:11:17 DEBUG[22434]: chan_sip.c:3363 parse_request: Header 8: (0) --- (8 headers 0 lines)--- Jun 21 05:11:17 DEBUG[22434]: chan_sip.c:1445 __sip_semi_ack: *** SIP TIMER: Cancelling retransmission #183 - INVITE (got response) Jun 21 05:11:17 DEBUG[22434]: chan_sip.c:1454 __sip_semi_ack: (Provisional) Stopping retransmission (but retaining packet) on '25cc17a101808ece7e127e501478ea9c@masterhost.ru' Request 102: Found Jun 21 05:11:17 DEBUG[22434]: chan_sip.c:9584 handle_response_invite: SIP response 100 to standard invite <-- SIP read from 83.237.98.254:62291: SIP/2.0 200 OK Via: SIP/2.0/UDP 83.222.22.242:5060;rport=5060;received=83.222.22.242;branch=z9hG4bK3ad01157 Content-Length: 214 Contact: Call-ID: 25cc17a101808ece7e127e501478ea9c@masterhost.ru Content-Type: application/sdp CSeq: 102 INVITE From: "9166104314";tag=as78c50bc3 Server: SJphone/1.60.289a (SJ Labs) To: "operator name";tag=11595025729485 v=0 o=- 3359841080 3359841080 IN IP4 10.10.10.7 s=SJphone c=IN IP4 10.10.10.7 t=0 0 a=direction:active m=audio 49218 RTP/AVP 3 101 a=rtpmap:3 GSM/8000 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-11,16 Jun 21 05:11:18 DEBUG[22434]: chan_sip.c:3363 parse_request: Header 0: SIP/2.0 200 OK (14) Jun 21 05:11:18 DEBUG[22434]: chan_sip.c:3363 parse_request: Header 1: Via: SIP/2.0/UDP 83.222.22.242:5060;rport=5060;received=83.222.22.242;branch=z9hG4bK3ad01157 (92) Jun 21 05:11:18 DEBUG[22434]: chan_sip.c:3363 parse_request: Header 2: Content-Length: 214 (19) Jun 21 05:11:18 DEBUG[22434]: chan_sip.c:3363 parse_request: Header 3: Contact: (35) Jun 21 05:11:18 DEBUG[22434]: chan_sip.c:3363 parse_request: Header 4: Call-ID: 25cc17a101808ece7e127e501478ea9c@masterhost.ru (55) Jun 21 05:11:18 DEBUG[22434]: chan_sip.c:3363 parse_request: Header 5: Content-Type: application/sdp (29) Jun 21 05:11:18 DEBUG[22434]: chan_sip.c:3363 parse_request: Header 6: CSeq: 102 INVITE (16) Jun 21 05:11:18 DEBUG[22434]: chan_sip.c:3363 parse_request: Header 7: From: "9166104314";tag=as78c50bc3 (63) Jun 21 05:11:18 DEBUG[22434]: chan_sip.c:3363 parse_request: Header 8: Server: SJphone/1.60.289a (SJ Labs) (35) Jun 21 05:11:18 DEBUG[22434]: chan_sip.c:3363 parse_request: Header 9: To: "operator name";tag=11595025729485 (66) Jun 21 05:11:18 DEBUG[22434]: chan_sip.c:3363 parse_request: Header 10: (0) Jun 21 05:11:18 DEBUG[22434]: chan_sip.c:3395 parse_request: Line: v=0 (3) Jun 21 05:11:18 DEBUG[22434]: chan_sip.c:3395 parse_request: Line: o=- 3359841080 3359841080 IN IP4 10.10.10.7 (43) Jun 21 05:11:18 DEBUG[22434]: chan_sip.c:3395 parse_request: Line: s=SJphone (9) Jun 21 05:11:18 DEBUG[22434]: chan_sip.c:3395 parse_request: Line: c=IN IP4 10.10.10.7 (19) Jun 21 05:11:18 DEBUG[22434]: chan_sip.c:3395 parse_request: Line: t=0 0 (5) Jun 21 05:11:18 DEBUG[22434]: chan_sip.c:3395 parse_request: Line: a=direction:active (18) Jun 21 05:11:18 DEBUG[22434]: chan_sip.c:3395 parse_request: Line: m=audio 49218 RTP/AVP 3 101 (27) Jun 21 05:11:18 DEBUG[22434]: chan_sip.c:3395 parse_request: Line: a=rtpmap:3 GSM/8000 (19) Jun 21 05:11:18 DEBUG[22434]: chan_sip.c:3395 parse_request: Line: a=rtpmap:101 telephone-event/8000 (33) Jun 21 05:11:18 DEBUG[22434]: chan_sip.c:3395 parse_request: Line: a=fmtp:101 0-11,16 (18) --- (10 headers 10 lines)--- Jun 21 05:11:18 DEBUG[22434]: chan_sip.c:1379 __sip_ack: Acked pending invite 102 Jun 21 05:11:18 DEBUG[22434]: chan_sip.c:1401 __sip_ack: Stopping retransmission on '25cc17a101808ece7e127e501478ea9c@masterhost.ru' of Request 102: Match Found Jun 21 05:11:18 DEBUG[22434]: chan_sip.c:9584 handle_response_invite: SIP response 200 to standard invite Found RTP audio format 3 Found RTP audio format 101 Peer audio RTP is at port 10.10.10.7:49218 Jun 21 05:11:18 DEBUG[22434]: chan_sip.c:3604 process_sdp: Peer audio RTP is at port 10.10.10.7:49218 Peer video RTP is at port 10.10.10.7:65535 Jun 21 05:11:18 DEBUG[22434]: chan_sip.c:3628 process_sdp: Peer video RTP is at port 10.10.10.7:65535 Found description format GSM Found description format telephone-event Capabilities: us - 0x8000e (gsm|ulaw|alaw|h263), peer - audio=0x2 (gsm)/video=0x0 (nothing), combined - 0x2 (gsm) Non-codec capabilities: us - 0x1 (telephone-event), peer - 0x1 (telephone-event), combined - 0x1 (telephone-event) Jun 21 05:11:18 DEBUG[22434]: chan_sip.c:3701 process_sdp: Oooh, we need to change our formats since our peer supports only 0x2 (gsm) and not 0x4 (ulaw) Jun 21 05:11:18 DEBUG[22434]: channel.c:2350 set_format: Set channel SIP/1211-97f9 to read format slin Jun 21 05:11:18 DEBUG[22434]: channel.c:2350 set_format: Set channel SIP/1211-97f9 to write format slin Jun 21 05:11:18 DEBUG[22434]: chan_sip.c:6137 build_route: build_route: Contact hop: list_route: hop: set_destination: Parsing for address/port to send to set_destination: set destination to 10.10.10.7, port 5060 Transmitting (NAT) to 83.237.98.254:62291: ACK sip:1211@10.10.10.7:5060 SIP/2.0 Via: SIP/2.0/UDP 83.222.22.242:5060;branch=z9hG4bK29550bc3;rport From: "9166104314" ;tag=as78c50bc3 To: ;tag=11595025729485 Contact: Call-ID: 25cc17a101808ece7e127e501478ea9c@masterhost.ru CSeq: 102 ACK User-Agent: Asterisk PBX Max-Forwards: 70 Content-Length: 0 --- -- SIP/1211-97f9 answered Local/1211@toagent-0b79,2 Jun 21 05:11:18 DEBUG[22429]: chan_sip.c:11668 sip_devicestate: Checking device state for peer 1211 Jun 21 05:11:18 DEBUG[22448]: channel.c:2350 set_format: Set channel Local/1211@toagent-0b79,2 to read format slin Jun 21 05:11:18 DEBUG[22429]: devicestate.c:187 do_state_change: Changing state for SIP/1211 - state 2 (In use) Jun 21 05:11:18 DEBUG[22448]: channel.c:2350 set_format: Set channel SIP/1211-97f9 to write format slin Jun 21 05:11:18 DEBUG[22448]: channel.c:2350 set_format: Set channel SIP/1211-97f9 to read format slin Jun 21 05:11:18 DEBUG[22448]: channel.c:2350 set_format: Set channel Local/1211@toagent-0b79,2 to write format slin Jun 21 05:11:18 DEBUG[22450]: app_queue.c:523 changethread: Device 'SIP/1211' changed to state '2' (In use) but we don't care because they're not a member of any queue. Jun 21 05:11:18 DEBUG[22429]: channel.c:777 channel_find_locked: -- Local/1211@toagent-0b79,1 answered Zap/32-1 Avoiding initial deadlock for 'Local/1211@toagent-0b79,2' Jun 21 05:11:18 DEBUG[22444]: chan_zap.c:2766 zt_setoption: Set option TONE VERIFY, mode: MUTECONF(1) on Zap/32-1 -- Stopped music on hold on Zap/32-1 Jun 21 05:11:18 DEBUG[22444]: channel.c:2350 set_format: Set channel Zap/32-1 to write format alaw Jun 21 05:11:18 DEBUG[22444]: channel.c:1711 ast_settimeout: Scheduling timer at 0 sample intervals Jun 21 05:11:18 DEBUG[22444]: channel.c:2350 set_format: Set channel Zap/32-1 to read format slin Jun 21 05:11:18 DEBUG[22444]: channel.c:2350 set_format: Set channel Local/1211@toagent-0b79,1 to write format slin Jun 21 05:11:18 DEBUG[22444]: channel.c:2350 set_format: Set channel Local/1211@toagent-0b79,1 to read format slin Jun 21 05:11:18 DEBUG[22444]: channel.c:2350 set_format: Set channel Zap/32-1 to write format slin Jun 21 05:11:18 DEBUG[22429]: devicestate.c:187 do_state_change: Changing state for Local/1211@toagent - state 2 (In use) Jun 21 05:11:18 DEBUG[22429]: devicestate.c:187 do_state_change: Changing state for Local/1211@toagent - state 2 (In use) Jun 21 05:11:18 DEBUG[22452]: app_queue.c:492 changethread: Device 'Local/1211@toagent' changed to state '2' (In use) Jun 21 05:11:18 DEBUG[22451]: app_queue.c:492 changethread: Device 'Local/1211@toagent' changed to state '2' (In use) Jun 21 05:11:18 DEBUG[22448]: rtp.c:479 ast_rtp_read: RTP NAT: Got audio from other end. Now sending to address 83.237.98.254:62400 Jun 21 05:11:18 DEBUG[22448]: channel.c:2757 ast_channel_masquerade: Planning to masquerade channel SIP/1211-97f9 into the structure of Local/1211@toagent-0b79,1 Jun 21 05:11:18 DEBUG[22448]: channel.c:2770 ast_channel_masquerade: Done planning to masquerade channel SIP/1211-97f9 into the structure of Local/1211@toagent-0b79,1 Jun 21 05:11:18 DEBUG[22448]: chan_local.c:244 local_write: Not posting to queue since already masked on 'Local/1211@toagent-0b79,2' Jun 21 05:11:18 DEBUG[22444]: channel.c:2880 ast_do_masquerade: Actually Masquerading SIP/1211-97f9(6) into the structure of Local/1211@toagent-0b79,1(6) Jun 21 05:11:18 DEBUG[22444]: channel.c:2891 ast_do_masquerade: Got clone lock for masquerade on 'SIP/1211-97f9' at 0x8233694 Jun 21 05:11:18 DEBUG[22444]: channel.c:2350 set_format: Set channel SIP/1211-97f9 to write format slin Jun 21 05:11:18 DEBUG[22448]: channel.c:3275 ast_generic_bridge: Didn't get a frame from channel: Local/1211@toagent-0b79,2 Jun 21 05:11:18 DEBUG[22448]: channel.c:3550 ast_channel_bridge: Bridge stops bridging channels Local/1211@toagent-0b79,2 and Local/1211@toagent-0b79,1 Jun 21 05:11:18 DEBUG[22444]: channel.c:2350 set_format: Set channel SIP/1211-97f9 to read format slin Jun 21 05:11:18 DEBUG[22444]: channel.c:3052 ast_do_masquerade: Putting channel SIP/1211-97f9 in 64/64 formats Jun 21 05:11:18 DEBUG[22444]: channel.c:3087 ast_do_masquerade: Released clone lock on 'Local/1211@toagent-0b79,1' Jun 21 05:11:18 DEBUG[22444]: channel.c:3096 ast_do_masquerade: Done Masquerading SIP/1211-97f9 (6) Jun 21 05:11:18 DEBUG[22448]: channel.c:1328 ast_hangup: Hanging up zombie 'Local/1211@toagent-0b79,1' Jun 21 05:11:18 DEBUG[22444]: channel.c:2350 set_format: Set channel Zap/32-1 to read format slin Jun 21 05:11:18 DEBUG[22448]: app_dial.c:1619 dial_exec_full: Exiting with DIALSTATUS=ANSWER. Jun 21 05:11:18 DEBUG[22448]: pbx.c:2316 __ast_pbx_run: Spawn extension (toagent,1211,6) exited non-zero on 'Local/1211@toagent-0b79,2' Jun 21 05:11:18 DEBUG[22448]: pbx.c:1522 pbx_substitute_variables_helper_full: Function result is '9166104314' Jun 21 05:11:18 DEBUG[22448]: pbx.c:1522 pbx_substitute_variables_helper_full: Function result is '9166104314' Jun 21 05:11:18 DEBUG[22448]: pbx.c:1522 pbx_substitute_variables_helper_full: Function result is '1211' Jun 21 05:11:18 DEBUG[22448]: pbx.c:1522 pbx_substitute_variables_helper_full: Function result is 'toagent' Jun 21 05:11:18 DEBUG[22448]: pbx.c:1522 pbx_substitute_variables_helper_full: Function result is 'Local/1211@toagent-0b79,2' Jun 21 05:11:18 DEBUG[22448]: pbx.c:1522 pbx_substitute_variables_helper_full: Function result is 'SIP/1211-97f9' Jun 21 05:11:18 DEBUG[22448]: pbx.c:1522 pbx_substitute_variables_helper_full: Function result is 'Dial' Jun 21 05:11:18 DEBUG[22448]: pbx.c:1522 pbx_substitute_variables_helper_full: Function result is 'SIP/1211|30|tw' Jun 21 05:11:18 DEBUG[22448]: pbx.c:1522 pbx_substitute_variables_helper_full: Function result is '2006-06-21 05:11:17' Jun 21 05:11:18 DEBUG[22448]: pbx.c:1522 pbx_substitute_variables_helper_full: Function result is '2006-06-21 05:11:18' Jun 21 05:11:18 DEBUG[22448]: pbx.c:1522 pbx_substitute_variables_helper_full: Function result is '2006-06-21 05:11:18' Jun 21 05:11:18 DEBUG[22448]: pbx.c:1522 pbx_substitute_variables_helper_full: Function result is '1' Jun 21 05:11:18 DEBUG[22448]: pbx.c:1522 pbx_substitute_variables_helper_full: Function result is '0' Jun 21 05:11:18 DEBUG[22448]: pbx.c:1522 pbx_substitute_variables_helper_full: Function result is 'ANSWERED' Jun 21 05:11:18 DEBUG[22448]: pbx.c:1522 pbx_substitute_variables_helper_full: Function result is 'DOCUMENTATION' Jun 21 05:11:18 DEBUG[22448]: pbx.c:1522 pbx_substitute_variables_helper_full: Function result is '(null)' Jun 21 05:11:18 DEBUG[22448]: pbx.c:1522 pbx_substitute_variables_helper_full: Function result is '1150852277.2' Jun 21 05:11:18 DEBUG[22448]: pbx.c:1522 pbx_substitute_variables_helper_full: Function result is '(null)' Jun 21 05:11:18 DEBUG[22448]: channel.c:1323 ast_hangup: Hanging up channel 'Local/1211@toagent-0b79,2' Jun 21 05:11:18 DEBUG[22429]: devicestate.c:187 do_state_change: Changing state for Local/1211@toagent - state 2 (In use) Jun 21 05:11:18 DEBUG[22444]: channel.c:2350 set_format: Set channel SIP/1211-97f9 to write format slin Jun 21 05:11:18 DEBUG[22429]: devicestate.c:187 do_state_change: Changing state for Local/1211@toagent - state 0 (Unknown) Jun 21 05:11:18 DEBUG[22444]: channel.c:2350 set_format: Set channel SIP/1211-97f9 to read format slin Jun 21 05:11:18 DEBUG[22444]: channel.c:2350 set_format: Set channel Zap/32-1 to write format slin Jun 21 05:11:18 DEBUG[22454]: app_queue.c:492 changethread: Device 'Local/1211@toagent' changed to state '0' (Unknown) Jun 21 05:11:18 DEBUG[22453]: app_queue.c:492 changethread: Device 'Local/1211@toagent' changed to state '2' (In use) Jun 21 05:11:18 DEBUG[22444]: rtp.c:1352 ast_rtp_write: Ooh, format changed from unknown to gsm <-- SIP read from 83.237.98.254:62291: OPTIONS sip:phone2.masterhost.ru SIP/2.0 Via: SIP/2.0/UDP 10.10.10.7;rport;branch=z9hG4bK0a0a0a070000001044989cba00004114000010fd Content-Length: 0 Call-ID: FDD64600-96E1-48B8-8C70-15829AEAE40A@10.10.10.7 CSeq: 1861 OPTIONS From: ;tag=1159517992529 Max-Forwards: 70 To: Jun 21 05:11:18 DEBUG[22434]: chan_sip.c:3363 parse_request: Header 0: OPTIONS sip:phone2.masterhost.ru SIP/2.0 (40) Jun 21 05:11:18 DEBUG[22434]: chan_sip.c:3363 parse_request: Header 1: Via: SIP/2.0/UDP 10.10.10.7;rport;branch=z9hG4bK0a0a0a070000001044989cba00004114000010fd (88) Jun 21 05:11:18 DEBUG[22434]: chan_sip.c:3363 parse_request: Header 2: Content-Length: 0 (17) Jun 21 05:11:18 DEBUG[22434]: chan_sip.c:3363 parse_request: Header 3: Call-ID: FDD64600-96E1-48B8-8C70-15829AEAE40A@10.10.10.7 (56) Jun 21 05:11:18 DEBUG[22434]: chan_sip.c:3363 parse_request: Header 4: CSeq: 1861 OPTIONS (18) Jun 21 05:11:18 DEBUG[22434]: chan_sip.c:3363 parse_request: Header 5: From: ;tag=1159517992529 (55) Jun 21 05:11:18 DEBUG[22434]: chan_sip.c:3363 parse_request: Header 6: Max-Forwards: 70 (16) Jun 21 05:11:18 DEBUG[22434]: chan_sip.c:3363 parse_request: Header 7: To: (30) Jun 21 05:11:18 DEBUG[22434]: chan_sip.c:3363 parse_request: Header 8: (0) --- (8 headers 0 lines)--- Jun 21 05:11:18 DEBUG[22434]: chan_sip.c:3147 sip_alloc: Allocating new SIP dialog for FDD64600-96E1-48B8-8C70-15829AEAE40A@10.10.10.7 - OPTIONS (No RTP) Jun 21 05:11:18 DEBUG[22434]: chan_sip.c:11137 handle_request: **** Received OPTIONS (3) - Command in SIP OPTIONS Looking for s in fromoutside (domain phone2.masterhost.ru) Transmitting (NAT) to 83.237.98.254:62291: SIP/2.0 404 Not Found Via: SIP/2.0/UDP 10.10.10.7;branch=z9hG4bK0a0a0a070000001044989cba00004114000010fd;received=83.237.98.254;rport=62291 From: ;tag=1159517992529 To: ;tag=as60e5861a Call-ID: FDD64600-96E1-48B8-8C70-15829AEAE40A@10.10.10.7 CSeq: 1861 OPTIONS User-Agent: Asterisk PBX Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY Contact: Accept: application/sdp Content-Length: 0 --- Jun 21 05:11:18 DEBUG[22434]: chan_sip.c:11338 sipsock_read: SIP message could not be handled, bad request: FDD64600-96E1-48B8-8C70-15829AEAE40A@10.10.10.7 Destroying call 'FDD64600-96E1-48B8-8C70-15829AEAE40A@10.10.10.7' <-- SIP read from 83.237.98.254:62291: INVITE sip:9166104314@83.222.22.242 SIP/2.0 Via: SIP/2.0/UDP 10.10.10.7;rport;branch=z9hG4bK0a0a0a07000001c144989cbb000026f8000010ff Content-Length: 211 Contact: Call-ID: 25cc17a101808ece7e127e501478ea9c@masterhost.ru Content-Type: application/sdp CSeq: 1 INVITE From: "operator name";tag=11595025729485 Max-Forwards: 70 To: ;tag=as78c50bc3 User-Agent: SJphone/1.60.289a (SJ Labs) v=0 o=- 3359841080 3359841081 IN IP4 10.10.10.7 s=SJphone c=IN IP4 0.0.0.0 t=0 0 a=direction:active m=audio 49218 RTP/AVP 3 101 a=rtpmap:3 GSM/8000 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-11,16 Jun 21 05:11:20 DEBUG[22434]: chan_sip.c:3363 parse_request: Header 0: INVITE sip:9166104314@83.222.22.242 SIP/2.0 (43) Jun 21 05:11:20 DEBUG[22434]: chan_sip.c:3363 parse_request: Header 1: Via: SIP/2.0/UDP 10.10.10.7;rport;branch=z9hG4bK0a0a0a07000001c144989cbb000026f8000010ff (88) Jun 21 05:11:20 DEBUG[22434]: chan_sip.c:3363 parse_request: Header 2: Content-Length: 211 (19) Jun 21 05:11:20 DEBUG[22434]: chan_sip.c:3363 parse_request: Header 3: Contact: (35) Jun 21 05:11:20 DEBUG[22434]: chan_sip.c:3363 parse_request: Header 4: Call-ID: 25cc17a101808ece7e127e501478ea9c@masterhost.ru (55) Jun 21 05:11:20 DEBUG[22434]: chan_sip.c:3363 parse_request: Header 5: Content-Type: application/sdp (29) Jun 21 05:11:20 DEBUG[22434]: chan_sip.c:3363 parse_request: Header 6: CSeq: 1 INVITE (14) Jun 21 05:11:20 DEBUG[22434]: chan_sip.c:3363 parse_request: Header 7: From: "operator name";tag=11595025729485 (68) Jun 21 05:11:20 DEBUG[22434]: chan_sip.c:3363 parse_request: Header 8: Max-Forwards: 70 (16) Jun 21 05:11:20 DEBUG[22434]: chan_sip.c:3363 parse_request: Header 9: To: ;tag=as78c50bc3 (49) Jun 21 05:11:20 DEBUG[22434]: chan_sip.c:3363 parse_request: Header 10: User-Agent: SJphone/1.60.289a (SJ Labs) (39) Jun 21 05:11:20 DEBUG[22434]: chan_sip.c:3363 parse_request: Header 11: (0) Jun 21 05:11:20 DEBUG[22434]: chan_sip.c:3395 parse_request: Line: v=0 (3) Jun 21 05:11:20 DEBUG[22434]: chan_sip.c:3395 parse_request: Line: o=- 3359841080 3359841081 IN IP4 10.10.10.7 (43) Jun 21 05:11:20 DEBUG[22434]: chan_sip.c:3395 parse_request: Line: s=SJphone (9) Jun 21 05:11:20 DEBUG[22434]: chan_sip.c:3395 parse_request: Line: c=IN IP4 0.0.0.0 (16) Jun 21 05:11:20 DEBUG[22434]: chan_sip.c:3395 parse_request: Line: t=0 0 (5) Jun 21 05:11:20 DEBUG[22434]: chan_sip.c:3395 parse_request: Line: a=direction:active (18) Jun 21 05:11:20 DEBUG[22434]: chan_sip.c:3395 parse_request: Line: m=audio 49218 RTP/AVP 3 101 (27) Jun 21 05:11:20 DEBUG[22434]: chan_sip.c:3395 parse_request: Line: a=rtpmap:3 GSM/8000 (19) Jun 21 05:11:20 DEBUG[22434]: chan_sip.c:3395 parse_request: Line: a=rtpmap:101 telephone-event/8000 (33) Jun 21 05:11:20 DEBUG[22434]: chan_sip.c:3395 parse_request: Line: a=fmtp:101 0-11,16 (18) --- (11 headers 10 lines)--- Jun 21 05:11:20 DEBUG[22434]: chan_sip.c:11137 handle_request: **** Received INVITE (5) - Command in SIP INVITE Using INVITE request as basis request - 25cc17a101808ece7e127e501478ea9c@masterhost.ru Sending to 10.10.10.7 : 5060 (NAT) Found RTP audio format 3 Found RTP audio format 101 Peer audio RTP is at port 0.0.0.0:49218 Jun 21 05:11:20 DEBUG[22434]: chan_sip.c:3604 process_sdp: Peer audio RTP is at port 0.0.0.0:49218 Peer video RTP is at port 0.0.0.0:65535 Jun 21 05:11:20 DEBUG[22434]: chan_sip.c:3628 process_sdp: Peer video RTP is at port 0.0.0.0:65535 Found description format GSM Found description format telephone-event Capabilities: us - 0x8000e (gsm|ulaw|alaw|h263), peer - audio=0x2 (gsm)/video=0x0 (nothing), combined - 0x2 (gsm) Non-codec capabilities: us - 0x1 (telephone-event), peer - 0x1 (telephone-event), combined - 0x1 (telephone-event) -- Started music on hold, class 'default', on Zap/32-1 Jun 21 05:11:20 DEBUG[22434]: channel.c:1711 ast_settimeout: Scheduling timer at 160 sample intervals Jun 21 05:11:20 DEBUG[22434]: chan_sip.c:10551 handle_request_invite: Got a SIP re-invite for call 25cc17a101808ece7e127e501478ea9c@masterhost.ru We're at 83.222.22.242 port 18868 Video is at 83.222.22.242 port 14398 Adding codec 0x2 (gsm) to SDP Adding non-codec 0x1 (telephone-event) to SDP Reliably Transmitting (NAT) to 83.237.98.254:62291: SIP/2.0 200 OK Via: SIP/2.0/UDP 10.10.10.7;branch=z9hG4bK0a0a0a07000001c144989cbb000026f8000010ff;received=83.237.98.254;rport=62291 From: "operator name";tag=11595025729485 To: ;tag=as78c50bc3 Call-ID: 25cc17a101808ece7e127e501478ea9c@masterhost.ru CSeq: 1 INVITE User-Agent: Asterisk PBX Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY Contact: Content-Type: application/sdp Content-Length: 217 v=0 o=root 22425 22426 IN IP4 83.222.22.242 s=session c=IN IP4 83.222.22.242 t=0 0 m=audio 18868 RTP/AVP 3 101 a=rtpmap:3 GSM/8000 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-16 a=silenceSupp:off - - - - --- Jun 21 05:11:20 DEBUG[22434]: chan_sip.c:1293 __sip_reliable_xmit: *** SIP TIMER: Initalizing retransmit timer on packet: Id #184 Jun 21 05:11:20 DEBUG[22444]: channel.c:1975 ast_read: Generator got voice, switching to phase locked mode Jun 21 05:11:20 DEBUG[22444]: channel.c:1711 ast_settimeout: Scheduling timer at 0 sample intervals Jun 21 05:11:20 DEBUG[22444]: channel.c:2350 set_format: Set channel Zap/32-1 to write format ulaw Jun 21 05:11:20 DEBUG[22444]: res_musiconhold.c:233 ast_moh_files_next: Zap/32-1 Opened file 2 '/var/lib/asterisk/mohmp3/misc/Heaven_For_Everyone_Queen' <-- SIP read from 83.237.98.254:62291: ACK sip:9166104314@83.222.22.242 SIP/2.0 Via: SIP/2.0/UDP 10.10.10.7;rport;branch=z9hG4bK0a0a0a07000001c144989cbb00005fc000001101 Content-Length: 0 Call-ID: 25cc17a101808ece7e127e501478ea9c@masterhost.ru CSeq: 1 ACK From: "operator name";tag=11595025729485 Max-Forwards: 70 To: ;tag=as78c50bc3 User-Agent: SJphone/1.60.289a (SJ Labs) Jun 21 05:11:20 DEBUG[22434]: chan_sip.c:3363 parse_request: Header 0: ACK sip:9166104314@83.222.22.242 SIP/2.0 (40) Jun 21 05:11:20 DEBUG[22434]: chan_sip.c:3363 parse_request: Header 1: Via: SIP/2.0/UDP 10.10.10.7;rport;branch=z9hG4bK0a0a0a07000001c144989cbb00005fc000001101 (88) Jun 21 05:11:20 DEBUG[22434]: chan_sip.c:3363 parse_request: Header 2: Content-Length: 0 (17) Jun 21 05:11:20 DEBUG[22434]: chan_sip.c:3363 parse_request: Header 3: Call-ID: 25cc17a101808ece7e127e501478ea9c@masterhost.ru (55) Jun 21 05:11:20 DEBUG[22434]: chan_sip.c:3363 parse_request: Header 4: CSeq: 1 ACK (11) Jun 21 05:11:20 DEBUG[22434]: chan_sip.c:3363 parse_request: Header 5: From: "operator name";tag=11595025729485 (68) Jun 21 05:11:20 DEBUG[22434]: chan_sip.c:3363 parse_request: Header 6: Max-Forwards: 70 (16) Jun 21 05:11:20 DEBUG[22434]: chan_sip.c:3363 parse_request: Header 7: To: ;tag=as78c50bc3 (49) Jun 21 05:11:20 DEBUG[22434]: chan_sip.c:3363 parse_request: Header 8: User-Agent: SJphone/1.60.289a (SJ Labs) (39) Jun 21 05:11:20 DEBUG[22434]: chan_sip.c:3363 parse_request: Header 9: (0) --- (9 headers 0 lines)--- Jun 21 05:11:20 DEBUG[22434]: chan_sip.c:11137 handle_request: **** Received ACK (6) - Command in SIP ACK Jun 21 05:11:20 DEBUG[22434]: chan_sip.c:1390 __sip_ack: ** SIP TIMER: Cancelling retransmit of packet (reply received) Retransid #184 Jun 21 05:11:20 DEBUG[22434]: chan_sip.c:1401 __sip_ack: Stopping retransmission on '25cc17a101808ece7e127e501478ea9c@masterhost.ru' of Response 1: Match Found <-- SIP read from 83.237.98.254:62291: INVITE sip:7677@phone2.masterhost.ru SIP/2.0 Via: SIP/2.0/UDP 10.10.10.7;rport;branch=z9hG4bK0a0a0a07000001c344989cbe0000078f00001102 Content-Length: 285 Contact: Call-ID: B0F3B39B-580F-41C9-BD45-39BBA87062BB@10.10.10.7 Content-Type: application/sdp CSeq: 1 INVITE From: "operator name";tag=11595580529332 Max-Forwards: 70 To: User-Agent: SJphone/1.60.289a (SJ Labs) v=0 o=- 3359841086 3359841086 IN IP4 10.10.10.7 s=SJphone c=IN IP4 10.10.10.7 t=0 0 a=direction:active m=audio 49220 RTP/AVP 3 97 98 101 a=rtpmap:3 GSM/8000 a=rtpmap:97 iLBC/8000 a=rtpmap:98 iLBC/8000 a=fmtp:98 mode=20 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-11,16 Jun 21 05:11:22 DEBUG[22434]: chan_sip.c:3363 parse_request: Header 0: INVITE sip:7677@phone2.masterhost.ru SIP/2.0 (44) Jun 21 05:11:22 DEBUG[22434]: chan_sip.c:3363 parse_request: Header 1: Via: SIP/2.0/UDP 10.10.10.7;rport;branch=z9hG4bK0a0a0a07000001c344989cbe0000078f00001102 (88) Jun 21 05:11:22 DEBUG[22434]: chan_sip.c:3363 parse_request: Header 2: Content-Length: 285 (19) Jun 21 05:11:22 DEBUG[22434]: chan_sip.c:3363 parse_request: Header 3: Contact: (35) Jun 21 05:11:22 DEBUG[22434]: chan_sip.c:3363 parse_request: Header 4: Call-ID: B0F3B39B-580F-41C9-BD45-39BBA87062BB@10.10.10.7 (56) Jun 21 05:11:22 DEBUG[22434]: chan_sip.c:3363 parse_request: Header 5: Content-Type: application/sdp (29) Jun 21 05:11:22 DEBUG[22434]: chan_sip.c:3363 parse_request: Header 6: CSeq: 1 INVITE (14) Jun 21 05:11:22 DEBUG[22434]: chan_sip.c:3363 parse_request: Header 7: From: "operator name";tag=11595580529332 (73) Jun 21 05:11:22 DEBUG[22434]: chan_sip.c:3363 parse_request: Header 8: Max-Forwards: 70 (16) Jun 21 05:11:22 DEBUG[22434]: chan_sip.c:3363 parse_request: Header 9: To: (35) Jun 21 05:11:22 DEBUG[22434]: chan_sip.c:3363 parse_request: Header 10: User-Agent: SJphone/1.60.289a (SJ Labs) (39) Jun 21 05:11:22 DEBUG[22434]: chan_sip.c:3363 parse_request: Header 11: (0) Jun 21 05:11:22 DEBUG[22434]: chan_sip.c:3395 parse_request: Line: v=0 (3) Jun 21 05:11:22 DEBUG[22434]: chan_sip.c:3395 parse_request: Line: o=- 3359841086 3359841086 IN IP4 10.10.10.7 (43) Jun 21 05:11:22 DEBUG[22434]: chan_sip.c:3395 parse_request: Line: s=SJphone (9) Jun 21 05:11:22 DEBUG[22434]: chan_sip.c:3395 parse_request: Line: c=IN IP4 10.10.10.7 (19) Jun 21 05:11:22 DEBUG[22434]: chan_sip.c:3395 parse_request: Line: t=0 0 (5) Jun 21 05:11:22 DEBUG[22434]: chan_sip.c:3395 parse_request: Line: a=direction:active (18) Jun 21 05:11:22 DEBUG[22434]: chan_sip.c:3395 parse_request: Line: m=audio 49220 RTP/AVP 3 97 98 101 (33) Jun 21 05:11:22 DEBUG[22434]: chan_sip.c:3395 parse_request: Line: a=rtpmap:3 GSM/8000 (19) Jun 21 05:11:22 DEBUG[22434]: chan_sip.c:3395 parse_request: Line: a=rtpmap:97 iLBC/8000 (21) Jun 21 05:11:22 DEBUG[22434]: chan_sip.c:3395 parse_request: Line: a=rtpmap:98 iLBC/8000 (21) Jun 21 05:11:22 DEBUG[22434]: chan_sip.c:3395 parse_request: Line: a=fmtp:98 mode=20 (17) Jun 21 05:11:22 DEBUG[22434]: chan_sip.c:3395 parse_request: Line: a=rtpmap:101 telephone-event/8000 (33) Jun 21 05:11:22 DEBUG[22434]: chan_sip.c:3395 parse_request: Line: a=fmtp:101 0-11,16 (18) --- (11 headers 13 lines)--- Jun 21 05:11:22 DEBUG[22434]: chan_sip.c:3147 sip_alloc: Allocating new SIP dialog for B0F3B39B-580F-41C9-BD45-39BBA87062BB@10.10.10.7 - INVITE (With RTP) Jun 21 05:11:22 DEBUG[22434]: chan_sip.c:11137 handle_request: **** Received INVITE (5) - Command in SIP INVITE Using INVITE request as basis request - B0F3B39B-580F-41C9-BD45-39BBA87062BB@10.10.10.7 Sending to 10.10.10.7 : 5060 (NAT) Jun 21 05:11:22 DEBUG[22434]: chan_sip.c:7155 check_user_full: Setting NAT on RTP to 524288 Jun 21 05:11:22 DEBUG[22434]: chan_sip.c:7159 check_user_full: Setting NAT on VRTP to 524288 Reliably Transmitting (NAT) to 83.237.98.254:62291: SIP/2.0 407 Proxy Authentication Required Via: SIP/2.0/UDP 10.10.10.7;branch=z9hG4bK0a0a0a07000001c344989cbe0000078f00001102;received=83.237.98.254;rport=62291 From: "operator name";tag=11595580529332 To: ;tag=as0716e536 Call-ID: B0F3B39B-580F-41C9-BD45-39BBA87062BB@10.10.10.7 CSeq: 1 INVITE User-Agent: Asterisk PBX Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY Contact: Proxy-Authenticate: Digest realm="phone1.masterhost.ru", nonce="4fbd69e4" Content-Length: 0 --- Jun 21 05:11:22 DEBUG[22434]: chan_sip.c:1293 __sip_reliable_xmit: *** SIP TIMER: Initalizing retransmit timer on packet: Id #185 Scheduling destruction of call 'B0F3B39B-580F-41C9-BD45-39BBA87062BB@10.10.10.7' in 15000 ms Found user '1211' <-- SIP read from 83.237.98.254:62291: ACK sip:7677@phone2.masterhost.ru SIP/2.0 Via: SIP/2.0/UDP 10.10.10.7;rport;branch=z9hG4bK0a0a0a07000001c344989cbe0000078f00001102 Content-Length: 0 Call-ID: B0F3B39B-580F-41C9-BD45-39BBA87062BB@10.10.10.7 CSeq: 1 ACK From: "operator name";tag=11595580529332 Max-Forwards: 70 To: ;tag=as0716e536 User-Agent: SJphone/1.60.289a (SJ Labs) Jun 21 05:11:22 DEBUG[22434]: chan_sip.c:3363 parse_request: Header 0: ACK sip:7677@phone2.masterhost.ru SIP/2.0 (41) Jun 21 05:11:22 DEBUG[22434]: chan_sip.c:3363 parse_request: Header 1: Via: SIP/2.0/UDP 10.10.10.7;rport;branch=z9hG4bK0a0a0a07000001c344989cbe0000078f00001102 (88) Jun 21 05:11:22 DEBUG[22434]: chan_sip.c:3363 parse_request: Header 2: Content-Length: 0 (17) Jun 21 05:11:22 DEBUG[22434]: chan_sip.c:3363 parse_request: Header 3: Call-ID: B0F3B39B-580F-41C9-BD45-39BBA87062BB@10.10.10.7 (56) Jun 21 05:11:22 DEBUG[22434]: chan_sip.c:3363 parse_request: Header 4: CSeq: 1 ACK (11) Jun 21 05:11:22 DEBUG[22434]: chan_sip.c:3363 parse_request: Header 5: From: "operator name";tag=11595580529332 (73) Jun 21 05:11:22 DEBUG[22434]: chan_sip.c:3363 parse_request: Header 6: Max-Forwards: 70 (16) Jun 21 05:11:22 DEBUG[22434]: chan_sip.c:3363 parse_request: Header 7: To: ;tag=as0716e536 (50) Jun 21 05:11:22 DEBUG[22434]: chan_sip.c:3363 parse_request: Header 8: User-Agent: SJphone/1.60.289a (SJ Labs) (39) Jun 21 05:11:22 DEBUG[22434]: chan_sip.c:3363 parse_request: Header 9: (0) --- (9 headers 0 lines)--- Jun 21 05:11:22 DEBUG[22434]: chan_sip.c:11137 handle_request: **** Received ACK (6) - Command in SIP ACK Jun 21 05:11:22 DEBUG[22434]: chan_sip.c:1390 __sip_ack: ** SIP TIMER: Cancelling retransmit of packet (reply received) Retransid #185 Jun 21 05:11:22 DEBUG[22434]: chan_sip.c:1401 __sip_ack: Stopping retransmission on 'B0F3B39B-580F-41C9-BD45-39BBA87062BB@10.10.10.7' of Response 1: Match Found <-- SIP read from 83.237.98.254:62291: INVITE sip:7677@phone2.masterhost.ru SIP/2.0 Via: SIP/2.0/UDP 10.10.10.7;rport;branch=z9hG4bK0a0a0a07000001c344989cbe00000a6700001103 Content-Length: 285 Contact: Call-ID: B0F3B39B-580F-41C9-BD45-39BBA87062BB@10.10.10.7 Content-Type: application/sdp CSeq: 2 INVITE From: "operator name";tag=11595580529332 Max-Forwards: 70 To: User-Agent: SJphone/1.60.289a (SJ Labs) Proxy-Authorization: Digest username="1211",realm="phone1.masterhost.ru",nonce="4fbd69e4",uri="sip:7677@phone2.masterhost.ru",response="***" v=0 o=- 3359841086 3359841086 IN IP4 10.10.10.7 s=SJphone c=IN IP4 10.10.10.7 t=0 0 a=direction:active m=audio 49220 RTP/AVP 3 97 98 101 a=rtpmap:3 GSM/8000 a=rtpmap:97 iLBC/8000 a=rtpmap:98 iLBC/8000 a=fmtp:98 mode=20 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-11,16 Jun 21 05:11:22 DEBUG[22434]: chan_sip.c:3363 parse_request: Header 0: INVITE sip:7677@phone2.masterhost.ru SIP/2.0 (44) Jun 21 05:11:22 DEBUG[22434]: chan_sip.c:3363 parse_request: Header 1: Via: SIP/2.0/UDP 10.10.10.7;rport;branch=z9hG4bK0a0a0a07000001c344989cbe00000a6700001103 (88) Jun 21 05:11:22 DEBUG[22434]: chan_sip.c:3363 parse_request: Header 2: Content-Length: 285 (19) Jun 21 05:11:22 DEBUG[22434]: chan_sip.c:3363 parse_request: Header 3: Contact: (35) Jun 21 05:11:22 DEBUG[22434]: chan_sip.c:3363 parse_request: Header 4: Call-ID: B0F3B39B-580F-41C9-BD45-39BBA87062BB@10.10.10.7 (56) Jun 21 05:11:22 DEBUG[22434]: chan_sip.c:3363 parse_request: Header 5: Content-Type: application/sdp (29) Jun 21 05:11:22 DEBUG[22434]: chan_sip.c:3363 parse_request: Header 6: CSeq: 2 INVITE (14) Jun 21 05:11:22 DEBUG[22434]: chan_sip.c:3363 parse_request: Header 7: From: "operator name";tag=11595580529332 (73) Jun 21 05:11:22 DEBUG[22434]: chan_sip.c:3363 parse_request: Header 8: Max-Forwards: 70 (16) Jun 21 05:11:22 DEBUG[22434]: chan_sip.c:3363 parse_request: Header 9: To: (35) Jun 21 05:11:22 DEBUG[22434]: chan_sip.c:3363 parse_request: Header 10: User-Agent: SJphone/1.60.289a (SJ Labs) (39) Jun 21 05:11:22 DEBUG[22434]: chan_sip.c:3363 parse_request: Header 11: Proxy-Authorization: Digest username="1211",realm="phone1.masterhost.ru",nonce="4fbd69e4",uri="sip:7677@phone2.masterhost.ru",response="***" (169) Jun 21 05:11:22 DEBUG[22434]: chan_sip.c:3363 parse_request: Header 12: (0) Jun 21 05:11:22 DEBUG[22434]: chan_sip.c:3395 parse_request: Line: v=0 (3) Jun 21 05:11:22 DEBUG[22434]: chan_sip.c:3395 parse_request: Line: o=- 3359841086 3359841086 IN IP4 10.10.10.7 (43) Jun 21 05:11:22 DEBUG[22434]: chan_sip.c:3395 parse_request: Line: s=SJphone (9) Jun 21 05:11:22 DEBUG[22434]: chan_sip.c:3395 parse_request: Line: c=IN IP4 10.10.10.7 (19) Jun 21 05:11:22 DEBUG[22434]: chan_sip.c:3395 parse_request: Line: t=0 0 (5) Jun 21 05:11:22 DEBUG[22434]: chan_sip.c:3395 parse_request: Line: a=direction:active (18) Jun 21 05:11:22 DEBUG[22434]: chan_sip.c:3395 parse_request: Line: m=audio 49220 RTP/AVP 3 97 98 101 (33) Jun 21 05:11:22 DEBUG[22434]: chan_sip.c:3395 parse_request: Line: a=rtpmap:3 GSM/8000 (19) Jun 21 05:11:22 DEBUG[22434]: chan_sip.c:3395 parse_request: Line: a=rtpmap:97 iLBC/8000 (21) Jun 21 05:11:22 DEBUG[22434]: chan_sip.c:3395 parse_request: Line: a=rtpmap:98 iLBC/8000 (21) Jun 21 05:11:22 DEBUG[22434]: chan_sip.c:3395 parse_request: Line: a=fmtp:98 mode=20 (17) Jun 21 05:11:22 DEBUG[22434]: chan_sip.c:3395 parse_request: Line: a=rtpmap:101 telephone-event/8000 (33) Jun 21 05:11:22 DEBUG[22434]: chan_sip.c:3395 parse_request: Line: a=fmtp:101 0-11,16 (18) --- (12 headers 13 lines)--- Jun 21 05:11:22 DEBUG[22434]: chan_sip.c:11137 handle_request: **** Received INVITE (5) - Command in SIP INVITE Using INVITE request as basis request - B0F3B39B-580F-41C9-BD45-39BBA87062BB@10.10.10.7 Sending to 10.10.10.7 : 5060 (NAT) Jun 21 05:11:22 DEBUG[22434]: chan_sip.c:7155 check_user_full: Setting NAT on RTP to 524288 Jun 21 05:11:22 DEBUG[22434]: chan_sip.c:7159 check_user_full: Setting NAT on VRTP to 524288 Found user '1211' Found RTP audio format 3 Found RTP audio format 97 Found RTP audio format 98 Found RTP audio format 101 Peer audio RTP is at port 10.10.10.7:49220 Jun 21 05:11:22 DEBUG[22434]: chan_sip.c:3604 process_sdp: Peer audio RTP is at port 10.10.10.7:49220 Peer video RTP is at port 10.10.10.7:65535 Jun 21 05:11:22 DEBUG[22434]: chan_sip.c:3628 process_sdp: Peer video RTP is at port 10.10.10.7:65535 Found description format GSM Found description format iLBC Found description format iLBC Found description format telephone-event Capabilities: us - 0x8000e (gsm|ulaw|alaw|h263), peer - audio=0x402 (gsm|ilbc)/video=0x0 (nothing), combined - 0x2 (gsm) Non-codec capabilities: us - 0x1 (telephone-event), peer - 0x1 (telephone-event), combined - 0x1 (telephone-event) Jun 21 05:11:22 DEBUG[22434]: chan_sip.c:10497 handle_request_invite: Checking SIP call limits for device 1211 Jun 21 05:11:22 DEBUG[22434]: chan_sip.c:2209 update_call_counter: Updating call counter for incoming call Looking for 7677 in fromoffice (domain phone2.masterhost.ru) Jun 21 05:11:22 DEBUG[22434]: chan_sip.c:6137 build_route: build_route: Contact hop: list_route: hop: Transmitting (NAT) to 83.237.98.254:62291: SIP/2.0 100 Trying Via: SIP/2.0/UDP 10.10.10.7;branch=z9hG4bK0a0a0a07000001c344989cbe00000a6700001103;received=83.237.98.254;rport=62291 From: "operator name";tag=11595580529332 To: Call-ID: B0F3B39B-580F-41C9-BD45-39BBA87062BB@10.10.10.7 CSeq: 2 INVITE User-Agent: Asterisk PBX Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY Contact: Content-Length: 0 --- Jun 21 05:11:22 DEBUG[22429]: chan_sip.c:11668 sip_devicestate: Checking device state for peer 1211 Jun 21 05:11:22 DEBUG[22429]: devicestate.c:187 do_state_change: Changing state for SIP/1211 - state 2 (In use) Jun 21 05:11:22 DEBUG[22458]: app_queue.c:523 changethread: Device 'SIP/1211' changed to state '2' (In use) but we don't care because they're not a member of any queue. Jun 21 05:11:22 DEBUG[22457]: pbx.c:1589 pbx_substitute_variables_helper_full: Expression result is '0' Jun 21 05:11:22 DEBUG[22457]: pbx.c:1677 pbx_extension_helper: Launching 'GotoIf' -- Executing GotoIf("SIP/1211-c549", "0?dial") in new stack Jun 21 05:11:22 DEBUG[22457]: pbx.c:6175 pbx_builtin_gotoif: Not taking any branch Jun 21 05:11:22 DEBUG[22457]: pbx.c:1677 pbx_extension_helper: Launching 'Set' -- Executing Set("SIP/1211-c549", "DIALOPT=TW") in new stack Jun 21 05:11:22 DEBUG[22457]: pbx.c:1677 pbx_extension_helper: Launching 'Dial' -- Executing Dial("SIP/1211-c549", "SIP/677@gatewayTDO|60|twTW") in new stack Jun 21 05:11:22 DEBUG[22457]: chan_sip.c:3147 sip_alloc: Allocating new SIP dialog for (No Call-ID) - INVITE (With RTP) Jun 21 05:11:22 DEBUG[22457]: chan_sip.c:1874 create_addr_from_peer: Setting NAT on RTP to 524288 Jun 21 05:11:22 DEBUG[22457]: chan_sip.c:1878 create_addr_from_peer: Setting NAT on VRTP to 524288 Jun 21 05:11:22 DEBUG[22457]: channel.c:2823 ast_channel_inherit_variables: Not copying variable STACK-fromoffice-7677-3. Jun 21 05:11:22 DEBUG[22457]: channel.c:2823 ast_channel_inherit_variables: Not copying variable DIALOPT. Jun 21 05:11:22 DEBUG[22457]: channel.c:2823 ast_channel_inherit_variables: Not copying variable STACK-fromoffice-7677-2. Jun 21 05:11:22 DEBUG[22457]: channel.c:2823 ast_channel_inherit_variables: Not copying variable STACK-fromoffice-7677-1. Jun 21 05:11:22 DEBUG[22457]: channel.c:2823 ast_channel_inherit_variables: Not copying variable SIPCALLID. Jun 21 05:11:22 DEBUG[22457]: channel.c:2823 ast_channel_inherit_variables: Not copying variable SIPUSERAGENT. Jun 21 05:11:22 DEBUG[22457]: channel.c:2823 ast_channel_inherit_variables: Not copying variable SIPDOMAIN. Jun 21 05:11:22 DEBUG[22457]: channel.c:2823 ast_channel_inherit_variables: Not copying variable SIPURI. Jun 21 05:11:22 DEBUG[22457]: chan_sip.c:2068 sip_call: Outgoing Call for 677 Jun 21 05:11:22 DEBUG[22457]: chan_sip.c:2209 update_call_counter: Updating call counter for outgoing call We're at 10.10.10.61 port 19102 Video is at 10.10.10.61 port 17112 Adding codec 0x2 (gsm) to SDP Adding codec 0x4 (ulaw) to SDP Adding codec 0x8 (alaw) to SDP Adding codec 0x80000 (h263) to SDP Adding non-codec 0x1 (telephone-event) to SDP Jun 21 05:11:22 DEBUG[22457]: chan_sip.c:3363 parse_request: Header 0: INVITE sip:677@10.10.10.37 SIP/2.0 (34) Jun 21 05:11:22 DEBUG[22457]: chan_sip.c:3363 parse_request: Header 1: Via: SIP/2.0/UDP 10.10.10.61:5060;branch=z9hG4bK7f77a113;rport (62) Jun 21 05:11:22 DEBUG[22457]: chan_sip.c:3363 parse_request: Header 2: From: "test sjphone" ;tag=as6e9300de (58) Jun 21 05:11:22 DEBUG[22457]: chan_sip.c:3363 parse_request: Header 3: To: (25) Jun 21 05:11:22 DEBUG[22457]: chan_sip.c:3363 parse_request: Header 4: Contact: (31) Jun 21 05:11:22 DEBUG[22457]: chan_sip.c:3363 parse_request: Header 5: Call-ID: 411381e0766f42282c15b58c423325ad@10.10.10.61 (53) Jun 21 05:11:22 DEBUG[22457]: chan_sip.c:3363 parse_request: Header 6: CSeq: 102 INVITE (16) Jun 21 05:11:22 DEBUG[22457]: chan_sip.c:3363 parse_request: Header 7: User-Agent: Asterisk PBX (24) Jun 21 05:11:22 DEBUG[22457]: chan_sip.c:3363 parse_request: Header 8: Max-Forwards: 70 (16) Jun 21 05:11:22 DEBUG[22457]: chan_sip.c:3363 parse_request: Header 9: Date: Wed, 21 Jun 2006 01:11:22 GMT (35) Jun 21 05:11:22 DEBUG[22457]: chan_sip.c:3363 parse_request: Header 10: Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY (66) Jun 21 05:11:22 DEBUG[22457]: chan_sip.c:3363 parse_request: Header 11: Content-Type: application/sdp (29) Jun 21 05:11:22 DEBUG[22457]: chan_sip.c:3363 parse_request: Header 12: Content-Length: 311 (19) Jun 21 05:11:22 DEBUG[22457]: chan_sip.c:3363 parse_request: Header 13: (0) Jun 21 05:11:22 DEBUG[22457]: chan_sip.c:3395 parse_request: Line: v=0 (3) Jun 21 05:11:22 DEBUG[22457]: chan_sip.c:3395 parse_request: Line: o=root 22425 22425 IN IP4 10.10.10.61 (37) Jun 21 05:11:22 DEBUG[22457]: chan_sip.c:3395 parse_request: Line: s=session (9) Jun 21 05:11:22 DEBUG[22457]: chan_sip.c:3395 parse_request: Line: c=IN IP4 10.10.10.61 (20) Jun 21 05:11:22 DEBUG[22457]: chan_sip.c:3395 parse_request: Line: t=0 0 (5) Jun 21 05:11:22 DEBUG[22457]: chan_sip.c:3395 parse_request: Line: m=audio 19102 RTP/AVP 3 0 8 101 (31) Jun 21 05:11:22 DEBUG[22457]: chan_sip.c:3395 parse_request: Line: a=rtpmap:3 GSM/8000 (19) Jun 21 05:11:22 DEBUG[22457]: chan_sip.c:3395 parse_request: Line: a=rtpmap:0 PCMU/8000 (20) Jun 21 05:11:22 DEBUG[22457]: chan_sip.c:3395 parse_request: Line: a=rtpmap:8 PCMA/8000 (20) Jun 21 05:11:22 DEBUG[22457]: chan_sip.c:3395 parse_request: Line: a=rtpmap:101 telephone-event/8000 (33) Jun 21 05:11:22 DEBUG[22457]: chan_sip.c:3395 parse_request: Line: a=fmtp:101 0-16 (15) Jun 21 05:11:22 DEBUG[22457]: chan_sip.c:3395 parse_request: Line: a=silenceSupp:off - - - - (25) Jun 21 05:11:22 DEBUG[22457]: chan_sip.c:3395 parse_request: Line: m=video 17112 RTP/AVP 34 (24) Jun 21 05:11:22 DEBUG[22457]: chan_sip.c:3395 parse_request: Line: a=rtpmap:34 H263/90000 (22) 13 headers, 14 lines Reliably Transmitting (NAT) to 10.10.10.37:5060: INVITE sip:677@10.10.10.37 SIP/2.0 Via: SIP/2.0/UDP 10.10.10.61:5060;branch=z9hG4bK7f77a113;rport From: "test sjphone" ;tag=as6e9300de To: Contact: Call-ID: 411381e0766f42282c15b58c423325ad@10.10.10.61 CSeq: 102 INVITE User-Agent: Asterisk PBX Max-Forwards: 70 Date: Wed, 21 Jun 2006 01:11:22 GMT Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY Content-Type: application/sdp Content-Length: 311 v=0 o=root 22425 22425 IN IP4 10.10.10.61 s=session c=IN IP4 10.10.10.61 t=0 0 m=audio 19102 RTP/AVP 3 0 8 101 a=rtpmap:3 GSM/8000 a=rtpmap:0 PCMU/8000 a=rtpmap:8 PCMA/8000 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-16 a=silenceSupp:off - - - - m=video 17112 RTP/AVP 34 a=rtpmap:34 H263/90000 --- Jun 21 05:11:22 DEBUG[22457]: chan_sip.c:1293 __sip_reliable_xmit: *** SIP TIMER: Initalizing retransmit timer on packet: Id #187 -- Called 677@gatewayTDO Jun 21 05:11:22 DEBUG[22457]: channel.c:2350 set_format: Set channel SIP/gatewayTDO-9640 to read format slin Jun 21 05:11:22 DEBUG[22457]: channel.c:2350 set_format: Set channel SIP/1211-c549 to write format slin Jun 21 05:11:22 DEBUG[22457]: channel.c:2350 set_format: Set channel SIP/1211-c549 to read format slin Jun 21 05:11:22 DEBUG[22457]: channel.c:2350 set_format: Set channel SIP/gatewayTDO-9640 to write format slin <-- SIP read from 10.10.10.37:5060: SIP/2.0 100 Trying Via: SIP/2.0/UDP 10.10.10.61:5060;branch=z9hG4bK7f77a113;rport From: "test sjphone" ;tag=as6e9300de To: ;tag=1c2045987290 Call-ID: 411381e0766f42282c15b58c423325ad@10.10.10.61 CSeq: 102 INVITE Supported: em,timer,replaces,path Allow: REGISTER,OPTIONS,INVITE,ACK,CANCEL,BYE,NOTIFY,PRACK,REFER,INFO,SUBSCRIBE,UPDATE Server: Audiocodes-Sip-Gateway-MP-104 FXO/v.4.40.215.400 Content-Length: 0 Jun 21 05:11:23 DEBUG[22434]: chan_sip.c:3363 parse_request: Header 0: SIP/2.0 100 Trying (18) Jun 21 05:11:23 DEBUG[22434]: chan_sip.c:3363 parse_request: Header 1: Via: SIP/2.0/UDP 10.10.10.61:5060;branch=z9hG4bK7f77a113;rport (62) Jun 21 05:11:23 DEBUG[22434]: chan_sip.c:3363 parse_request: Header 2: From: "test sjphone" ;tag=as6e9300de (58) Jun 21 05:11:23 DEBUG[22434]: chan_sip.c:3363 parse_request: Header 3: To: ;tag=1c2045987290 (42) Jun 21 05:11:23 DEBUG[22434]: chan_sip.c:3363 parse_request: Header 4: Call-ID: 411381e0766f42282c15b58c423325ad@10.10.10.61 (53) Jun 21 05:11:23 DEBUG[22434]: chan_sip.c:3363 parse_request: Header 5: CSeq: 102 INVITE (16) Jun 21 05:11:23 DEBUG[22434]: chan_sip.c:3363 parse_request: Header 6: Supported: em,timer,replaces,path (33) Jun 21 05:11:23 DEBUG[22434]: chan_sip.c:3363 parse_request: Header 7: Allow: REGISTER,OPTIONS,INVITE,ACK,CANCEL,BYE,NOTIFY,PRACK,REFER,INFO,SUBSCRIBE,UPDATE (86) Jun 21 05:11:23 DEBUG[22434]: chan_sip.c:3363 parse_request: Header 8: Server: Audiocodes-Sip-Gateway-MP-104 FXO/v.4.40.215.400 (56) Jun 21 05:11:23 DEBUG[22434]: chan_sip.c:3363 parse_request: Header 9: Content-Length: 0 (17) Jun 21 05:11:23 DEBUG[22434]: chan_sip.c:3363 parse_request: Header 10: (0) --- (10 headers 0 lines)--- Jun 21 05:11:23 DEBUG[22434]: chan_sip.c:1445 __sip_semi_ack: *** SIP TIMER: Cancelling retransmission #187 - INVITE (got response) Jun 21 05:11:23 DEBUG[22434]: chan_sip.c:1454 __sip_semi_ack: (Provisional) Stopping retransmission (but retaining packet) on '411381e0766f42282c15b58c423325ad@10.10.10.61' Request 102: Found Jun 21 05:11:23 DEBUG[22434]: chan_sip.c:9584 handle_response_invite: SIP response 100 to standard invite <-- SIP read from 10.10.10.37:5060: SIP/2.0 180 Ringing Via: SIP/2.0/UDP 10.10.10.61:5060;branch=z9hG4bK7f77a113;rport From: "test sjphone" ;tag=as6e9300de To: ;tag=1c2045987290 Call-ID: 411381e0766f42282c15b58c423325ad@10.10.10.61 CSeq: 102 INVITE Contact: Supported: em,timer,replaces,path Allow: REGISTER,OPTIONS,INVITE,ACK,CANCEL,BYE,NOTIFY,PRACK,REFER,INFO,SUBSCRIBE,UPDATE Server: Audiocodes-Sip-Gateway-MP-104 FXO/v.4.40.215.400 Content-Length: 0 Jun 21 05:11:23 DEBUG[22434]: chan_sip.c:3363 parse_request: Header 0: SIP/2.0 180 Ringing (19) Jun 21 05:11:23 DEBUG[22434]: chan_sip.c:3363 parse_request: Header 1: Via: SIP/2.0/UDP 10.10.10.61:5060;branch=z9hG4bK7f77a113;rport (62) Jun 21 05:11:23 DEBUG[22434]: chan_sip.c:3363 parse_request: Header 2: From: "test sjphone" ;tag=as6e9300de (58) Jun 21 05:11:23 DEBUG[22434]: chan_sip.c:3363 parse_request: Header 3: To: ;tag=1c2045987290 (42) Jun 21 05:11:23 DEBUG[22434]: chan_sip.c:3363 parse_request: Header 4: Call-ID: 411381e0766f42282c15b58c423325ad@10.10.10.61 (53) Jun 21 05:11:23 DEBUG[22434]: chan_sip.c:3363 parse_request: Header 5: CSeq: 102 INVITE (16) Jun 21 05:11:23 DEBUG[22434]: chan_sip.c:3363 parse_request: Header 6: Contact: (30) Jun 21 05:11:23 DEBUG[22434]: chan_sip.c:3363 parse_request: Header 7: Supported: em,timer,replaces,path (33) Jun 21 05:11:23 DEBUG[22434]: chan_sip.c:3363 parse_request: Header 8: Allow: REGISTER,OPTIONS,INVITE,ACK,CANCEL,BYE,NOTIFY,PRACK,REFER,INFO,SUBSCRIBE,UPDATE (86) Jun 21 05:11:23 DEBUG[22434]: chan_sip.c:3363 parse_request: Header 9: Server: Audiocodes-Sip-Gateway-MP-104 FXO/v.4.40.215.400 (56) Jun 21 05:11:23 DEBUG[22434]: chan_sip.c:3363 parse_request: Header 10: Content-Length: 0 (17) Jun 21 05:11:23 DEBUG[22434]: chan_sip.c:3363 parse_request: Header 11: (0) --- (11 headers 0 lines)--- Jun 21 05:11:23 DEBUG[22434]: chan_sip.c:1454 __sip_semi_ack: (Provisional) Stopping retransmission (but retaining packet) on '411381e0766f42282c15b58c423325ad@10.10.10.61' Request 102: Found Jun 21 05:11:23 DEBUG[22434]: chan_sip.c:9584 handle_response_invite: SIP response 180 to standard invite -- SIP/gatewayTDO-9640 is ringing Jun 21 05:11:23 DEBUG[22429]: chan_sip.c:11668 sip_devicestate: Checking device state for peer gatewayTDO Transmitting (NAT) to 83.237.98.254:62291: SIP/2.0 180 Ringing Via: SIP/2.0/UDP 10.10.10.7;branch=z9hG4bK0a0a0a07000001c344989cbe00000a6700001103;received=83.237.98.254;rport=62291 From: "operator name";tag=11595580529332 To: ;tag=as1158c6d6 Call-ID: B0F3B39B-580F-41C9-BD45-39BBA87062BB@10.10.10.7 CSeq: 2 INVITE User-Agent: Asterisk PBX Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY Contact: Content-Length: 0 --- Jun 21 05:11:23 DEBUG[22429]: devicestate.c:187 do_state_change: Changing state for SIP/gatewayTDO - state 6 (Ringing) Jun 21 05:11:23 DEBUG[22459]: app_queue.c:523 changethread: Device 'SIP/gatewayTDO' changed to state '6' (Ringing) but we don't care because they're not a member of any queue. <-- SIP read from 195.14.53.142:5060: OPTIONS sip:phone2.masterhost.ru SIP/2.0 Via: SIP/2.0/UDP 192.168.200.218;rport;branch=z9hG4bKc0a8c8da0000000b44989c94000054a80000246e Content-Length: 0 Call-ID: 9E638111-4C41-455C-BD6E-E0832EC4BDE3@192.168.200.218 CSeq: 4653 OPTIONS From: ;tag=10668218715315 Max-Forwards: 70 To: Jun 21 05:11:23 DEBUG[22434]: chan_sip.c:3363 parse_request: Header 0: OPTIONS sip:phone2.masterhost.ru SIP/2.0 (40) Jun 21 05:11:23 DEBUG[22434]: chan_sip.c:3363 parse_request: Header 1: Via: SIP/2.0/UDP 192.168.200.218;rport;branch=z9hG4bKc0a8c8da0000000b44989c94000054a80000246e (93) Jun 21 05:11:23 DEBUG[22434]: chan_sip.c:3363 parse_request: Header 2: Content-Length: 0 (17) Jun 21 05:11:23 DEBUG[22434]: chan_sip.c:3363 parse_request: Header 3: Call-ID: 9E638111-4C41-455C-BD6E-E0832EC4BDE3@192.168.200.218 (61) Jun 21 05:11:23 DEBUG[22434]: chan_sip.c:3363 parse_request: Header 4: CSeq: 4653 OPTIONS (18) Jun 21 05:11:23 DEBUG[22434]: chan_sip.c:3363 parse_request: Header 5: From: ;tag=10668218715315 (56) Jun 21 05:11:23 DEBUG[22434]: chan_sip.c:3363 parse_request: Header 6: Max-Forwards: 70 (16) Jun 21 05:11:23 DEBUG[22434]: chan_sip.c:3363 parse_request: Header 7: To: (30) Jun 21 05:11:23 DEBUG[22434]: chan_sip.c:3363 parse_request: Header 8: (0) --- (8 headers 0 lines)--- Jun 21 05:11:23 DEBUG[22434]: chan_sip.c:3147 sip_alloc: Allocating new SIP dialog for 9E638111-4C41-455C-BD6E-E0832EC4BDE3@192.168.200.218 - OPTIONS (No RTP) Jun 21 05:11:23 DEBUG[22434]: chan_sip.c:11137 handle_request: **** Received OPTIONS (3) - Command in SIP OPTIONS Looking for s in fromoutside (domain phone2.masterhost.ru) Transmitting (NAT) to 195.14.53.142:5060: SIP/2.0 404 Not Found Via: SIP/2.0/UDP 192.168.200.218;branch=z9hG4bKc0a8c8da0000000b44989c94000054a80000246e;received=195.14.53.142;rport=5060 From: ;tag=10668218715315 To: ;tag=as52d0634e Call-ID: 9E638111-4C41-455C-BD6E-E0832EC4BDE3@192.168.200.218 CSeq: 4653 OPTIONS User-Agent: Asterisk PBX Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY Contact: Accept: application/sdp Content-Length: 0 --- Jun 21 05:11:23 DEBUG[22434]: chan_sip.c:11338 sipsock_read: SIP message could not be handled, bad request: 9E638111-4C41-455C-BD6E-E0832EC4BDE3@192.168.200.218 Destroying call '9E638111-4C41-455C-BD6E-E0832EC4BDE3@192.168.200.218' <-- SIP read from 10.10.10.37:5060: SIP/2.0 200 OK Via: SIP/2.0/UDP 10.10.10.61:5060;branch=z9hG4bK7f77a113;rport From: "test sjphone" ;tag=as6e9300de To: ;tag=1c2045987290 Call-ID: 411381e0766f42282c15b58c423325ad@10.10.10.61 CSeq: 102 INVITE Contact: Supported: em,timer,replaces,path Allow: REGISTER,OPTIONS,INVITE,ACK,CANCEL,BYE,NOTIFY,PRACK,REFER,INFO,SUBSCRIBE,UPDATE Server: Audiocodes-Sip-Gateway-MP-104 FXO/v.4.40.215.400 Content-Type: application/sdp Content-Length: 253 v=0 o=AudiocodesGW 2045994933 2045994867 IN IP4 10.10.10.37 s=Phone-Call c=IN IP4 10.10.10.37 t=0 0 m=audio 4030 RTP/AVP 0 101 a=rtpmap:0 pcmu/8000 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-15 a=ptime:20 a=sendrecv m=video 0 RTP/AVP Jun 21 05:11:24 DEBUG[22434]: chan_sip.c:3363 parse_request: Header 0: SIP/2.0 200 OK (14) Jun 21 05:11:24 DEBUG[22434]: chan_sip.c:3363 parse_request: Header 1: Via: SIP/2.0/UDP 10.10.10.61:5060;branch=z9hG4bK7f77a113;rport (62) Jun 21 05:11:24 DEBUG[22434]: chan_sip.c:3363 parse_request: Header 2: From: "test sjphone" ;tag=as6e9300de (58) Jun 21 05:11:24 DEBUG[22434]: chan_sip.c:3363 parse_request: Header 3: To: ;tag=1c2045987290 (42) Jun 21 05:11:24 DEBUG[22434]: chan_sip.c:3363 parse_request: Header 4: Call-ID: 411381e0766f42282c15b58c423325ad@10.10.10.61 (53) Jun 21 05:11:24 DEBUG[22434]: chan_sip.c:3363 parse_request: Header 5: CSeq: 102 INVITE (16) Jun 21 05:11:24 DEBUG[22434]: chan_sip.c:3363 parse_request: Header 6: Contact: (30) Jun 21 05:11:24 DEBUG[22434]: chan_sip.c:3363 parse_request: Header 7: Supported: em,timer,replaces,path (33) Jun 21 05:11:24 DEBUG[22434]: chan_sip.c:3363 parse_request: Header 8: Allow: REGISTER,OPTIONS,INVITE,ACK,CANCEL,BYE,NOTIFY,PRACK,REFER,INFO,SUBSCRIBE,UPDATE (86) Jun 21 05:11:24 DEBUG[22434]: chan_sip.c:3363 parse_request: Header 9: Server: Audiocodes-Sip-Gateway-MP-104 FXO/v.4.40.215.400 (56) Jun 21 05:11:24 DEBUG[22434]: chan_sip.c:3363 parse_request: Header 10: Content-Type: application/sdp (29) Jun 21 05:11:24 DEBUG[22434]: chan_sip.c:3363 parse_request: Header 11: Content-Length: 253 (19) Jun 21 05:11:24 DEBUG[22434]: chan_sip.c:3363 parse_request: Header 12: (0) Jun 21 05:11:24 DEBUG[22434]: chan_sip.c:3395 parse_request: Line: v=0 (3) Jun 21 05:11:24 DEBUG[22434]: chan_sip.c:3395 parse_request: Line: o=AudiocodesGW 2045994933 2045994867 IN IP4 10.10.10.37 (55) Jun 21 05:11:24 DEBUG[22434]: chan_sip.c:3395 parse_request: Line: s=Phone-Call (12) Jun 21 05:11:24 DEBUG[22434]: chan_sip.c:3395 parse_request: Line: c=IN IP4 10.10.10.37 (20) Jun 21 05:11:24 DEBUG[22434]: chan_sip.c:3395 parse_request: Line: t=0 0 (5) Jun 21 05:11:24 DEBUG[22434]: chan_sip.c:3395 parse_request: Line: m=audio 4030 RTP/AVP 0 101 (26) Jun 21 05:11:24 DEBUG[22434]: chan_sip.c:3395 parse_request: Line: a=rtpmap:0 pcmu/8000 (20) Jun 21 05:11:24 DEBUG[22434]: chan_sip.c:3395 parse_request: Line: a=rtpmap:101 telephone-event/8000 (33) Jun 21 05:11:24 DEBUG[22434]: chan_sip.c:3395 parse_request: Line: a=fmtp:101 0-15 (15) Jun 21 05:11:24 DEBUG[22434]: chan_sip.c:3395 parse_request: Line: a=ptime:20 (10) Jun 21 05:11:24 DEBUG[22434]: chan_sip.c:3395 parse_request: Line: a=sendrecv (10) Jun 21 05:11:24 DEBUG[22434]: chan_sip.c:3395 parse_request: Line: m=video 0 RTP/AVP (18) Jun 21 05:11:24 DEBUG[22434]: chan_sip.c:3395 parse_request: Line: (0) --- (12 headers 13 lines)--- Jun 21 05:11:24 DEBUG[22434]: chan_sip.c:1379 __sip_ack: Acked pending invite 102 Jun 21 05:11:24 DEBUG[22434]: chan_sip.c:1401 __sip_ack: Stopping retransmission on '411381e0766f42282c15b58c423325ad@10.10.10.61' of Request 102: Match Found Jun 21 05:11:24 DEBUG[22434]: chan_sip.c:9584 handle_response_invite: SIP response 200 to standard invite Found RTP audio format 0 Found RTP audio format 101 Peer audio RTP is at port 10.10.10.37:4030 Jun 21 05:11:24 DEBUG[22434]: chan_sip.c:3604 process_sdp: Peer audio RTP is at port 10.10.10.37:4030 Found description format pcmu Found description format telephone-event Capabilities: us - 0x8000e (gsm|ulaw|alaw|h263), 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) Jun 21 05:11:24 DEBUG[22434]: chan_sip.c:6137 build_route: build_route: Contact hop: list_route: hop: set_destination: Parsing for address/port to send to set_destination: set destination to 10.10.10.37, port 5060 Transmitting (NAT) to 10.10.10.37:5060: ACK sip:491@10.10.10.37 SIP/2.0 Via: SIP/2.0/UDP 10.10.10.61:5060;branch=z9hG4bK645ccd3c;rport From: "test sjphone" ;tag=as6e9300de To: ;tag=1c2045987290 Contact: Call-ID: 411381e0766f42282c15b58c423325ad@10.10.10.61 CSeq: 102 ACK User-Agent: Asterisk PBX Max-Forwards: 70 Content-Length: 0 --- -- SIP/gatewayTDO-9640 answered SIP/1211-c549 Jun 21 05:11:24 DEBUG[22429]: chan_sip.c:11668 sip_devicestate: Checking device state for peer gatewayTDO Jun 21 05:11:24 DEBUG[22457]: channel.c:2350 set_format: Set channel SIP/1211-c549 to read format slin Jun 21 05:11:24 DEBUG[22429]: devicestate.c:187 do_state_change: Changing state for SIP/gatewayTDO - state 2 (In use) Jun 21 05:11:24 DEBUG[22457]: channel.c:2350 set_format: Set channel SIP/gatewayTDO-9640 to write format slin Jun 21 05:11:24 DEBUG[22460]: app_queue.c:523 changethread: Device 'SIP/gatewayTDO' changed to state '2' (In use) but we don't care because they're not a member of any queue. Jun 21 05:11:24 DEBUG[22457]: channel.c:2350 set_format: Set channel SIP/gatewayTDO-9640 to read format slin Jun 21 05:11:24 DEBUG[22457]: channel.c:2350 set_format: Set channel SIP/1211-c549 to write format slin Jun 21 05:11:24 DEBUG[22457]: chan_sip.c:2540 sip_answer: sip_answer(SIP/1211-c549) Jun 21 05:11:24 DEBUG[22429]: chan_sip.c:11668 sip_devicestate: We're at 83.222.22.242 port 11928 Checking device state for peer 1211 Video is at 83.222.22.242 port 15518 Adding codec 0x2 (gsm) to SDP Adding non-codec 0x1 (telephone-event) to SDP Jun 21 05:11:24 DEBUG[22429]: channel.c:777 channel_find_locked: Avoiding initial deadlock for 'SIP/1211-c549' Reliably Transmitting (NAT) to 83.237.98.254:62291: SIP/2.0 200 OK Via: SIP/2.0/UDP 10.10.10.7;branch=z9hG4bK0a0a0a07000001c344989cbe00000a6700001103;received=83.237.98.254;rport=62291 From: "operator name";tag=11595580529332 To: ;tag=as1158c6d6 Call-ID: B0F3B39B-580F-41C9-BD45-39BBA87062BB@10.10.10.7 CSeq: 2 INVITE User-Agent: Asterisk PBX Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY Contact: Content-Type: application/sdp Content-Length: 217 v=0 o=root 22425 22425 IN IP4 83.222.22.242 s=session c=IN IP4 83.222.22.242 t=0 0 m=audio 11928 RTP/AVP 3 101 a=rtpmap:3 GSM/8000 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-16 a=silenceSupp:off - - - - --- Jun 21 05:11:24 DEBUG[22457]: chan_sip.c:1293 __sip_reliable_xmit: *** SIP TIMER: Initalizing retransmit timer on packet: Id #188 -- Attempting native bridge of SIP/1211-c549 and SIP/gatewayTDO-9640 Jun 21 05:11:24 DEBUG[22429]: devicestate.c:187 do_state_change: Changing state for SIP/1211 - state 2 (In use) Jun 21 05:11:24 DEBUG[22461]: app_queue.c:523 changethread: Device 'SIP/1211' changed to state '2' (In use) but we don't care because they're not a member of any queue. Jun 21 05:11:24 DEBUG[22457]: rtp.c:1352 ast_rtp_write: Ooh, format changed from unknown to gsm Jun 21 05:11:24 DEBUG[22457]: rtp.c:411 ast_rtcp_read: Got RTCP report of 44 bytes Jun 21 05:11:24 DEBUG[22457]: rtp.c:479 ast_rtp_read: RTP NAT: Got audio from other end. Now sending to address 83.237.98.254:62404 Jun 21 05:11:24 DEBUG[22457]: rtp.c:1352 ast_rtp_write: Ooh, format changed from unknown to ulaw <-- SIP read from 83.237.98.254:62291: ACK sip:7677@83.222.22.242 SIP/2.0 Via: SIP/2.0/UDP 10.10.10.7;rport;branch=z9hG4bK0a0a0a07000001c344989cc0000066f800001107 Content-Length: 0 Call-ID: B0F3B39B-580F-41C9-BD45-39BBA87062BB@10.10.10.7 CSeq: 2 ACK From: "operator name";tag=11595580529332 Max-Forwards: 70 To: ;tag=as1158c6d6 User-Agent: SJphone/1.60.289a (SJ Labs) Jun 21 05:11:24 DEBUG[22434]: chan_sip.c:3363 parse_request: Header 0: ACK sip:7677@83.222.22.242 SIP/2.0 (34) Jun 21 05:11:24 DEBUG[22434]: chan_sip.c:3363 parse_request: Header 1: Via: SIP/2.0/UDP 10.10.10.7;rport;branch=z9hG4bK0a0a0a07000001c344989cc0000066f800001107 (88) Jun 21 05:11:24 DEBUG[22434]: chan_sip.c:3363 parse_request: Header 2: Content-Length: 0 (17) Jun 21 05:11:24 DEBUG[22434]: chan_sip.c:3363 parse_request: Header 3: Call-ID: B0F3B39B-580F-41C9-BD45-39BBA87062BB@10.10.10.7 (56) Jun 21 05:11:24 DEBUG[22434]: chan_sip.c:3363 parse_request: Header 4: CSeq: 2 ACK (11) Jun 21 05:11:24 DEBUG[22434]: chan_sip.c:3363 parse_request: Header 5: From: "operator name";tag=11595580529332 (73) Jun 21 05:11:24 DEBUG[22434]: chan_sip.c:3363 parse_request: Header 6: Max-Forwards: 70 (16) Jun 21 05:11:24 DEBUG[22434]: chan_sip.c:3363 parse_request: Header 7: To: ;tag=as1158c6d6 (50) Jun 21 05:11:24 DEBUG[22434]: chan_sip.c:3363 parse_request: Header 8: User-Agent: SJphone/1.60.289a (SJ Labs) (39) Jun 21 05:11:24 DEBUG[22434]: chan_sip.c:3363 parse_request: Header 9: (0) --- (9 headers 0 lines)--- Jun 21 05:11:24 DEBUG[22434]: chan_sip.c:11137 handle_request: **** Received ACK (6) - Command in SIP ACK Jun 21 05:11:24 DEBUG[22434]: chan_sip.c:1390 __sip_ack: ** SIP TIMER: Cancelling retransmit of packet (reply received) Retransid #188 Jun 21 05:11:24 DEBUG[22434]: chan_sip.c:1401 __sip_ack: Stopping retransmission on 'B0F3B39B-580F-41C9-BD45-39BBA87062BB@10.10.10.7' of Response 2: Match Found <-- SIP read from 10.10.10.37:5060: BYE sip:1211@10.10.10.61 SIP/2.0 Via: SIP/2.0/UDP 10.10.10.37;branch=z9hG4bKac2048848741 Max-Forwards: 70 From: ;tag=1c2045987290 To: "test sjphone" ;tag=as6e9300de Call-ID: 411381e0766f42282c15b58c423325ad@10.10.10.61 CSeq: 1 BYE Contact: Supported: em,timer,replaces,path Allow: REGISTER,OPTIONS,INVITE,ACK,CANCEL,BYE,NOTIFY,PRACK,REFER,INFO,SUBSCRIBE,UPDATE User-Agent: Audiocodes-Sip-Gateway-MP-104 FXO/v.4.40.215.400 Content-Length: 0 Jun 21 05:11:25 DEBUG[22434]: chan_sip.c:3363 parse_request: Header 0: BYE sip:1211@10.10.10.61 SIP/2.0 (32) Jun 21 05:11:25 DEBUG[22434]: chan_sip.c:3363 parse_request: Header 1: Via: SIP/2.0/UDP 10.10.10.37;branch=z9hG4bKac2048848741 (55) Jun 21 05:11:25 DEBUG[22434]: chan_sip.c:3363 parse_request: Header 2: Max-Forwards: 70 (16) Jun 21 05:11:25 DEBUG[22434]: chan_sip.c:3363 parse_request: Header 3: From: ;tag=1c2045987290 (44) Jun 21 05:11:25 DEBUG[22434]: chan_sip.c:3363 parse_request: Header 4: To: "test sjphone" ;tag=as6e9300de (56) Jun 21 05:11:25 DEBUG[22434]: chan_sip.c:3363 parse_request: Header 5: Call-ID: 411381e0766f42282c15b58c423325ad@10.10.10.61 (53) Jun 21 05:11:25 DEBUG[22434]: chan_sip.c:3363 parse_request: Header 6: CSeq: 1 BYE (11) Jun 21 05:11:25 DEBUG[22434]: chan_sip.c:3363 parse_request: Header 7: Contact: (30) Jun 21 05:11:25 DEBUG[22434]: chan_sip.c:3363 parse_request: Header 8: Supported: em,timer,replaces,path (33) Jun 21 05:11:25 DEBUG[22434]: chan_sip.c:3363 parse_request: Header 9: Allow: REGISTER,OPTIONS,INVITE,ACK,CANCEL,BYE,NOTIFY,PRACK,REFER,INFO,SUBSCRIBE,UPDATE (86) Jun 21 05:11:25 DEBUG[22434]: chan_sip.c:3363 parse_request: Header 10: User-Agent: Audiocodes-Sip-Gateway-MP-104 FXO/v.4.40.215.400 (60) Jun 21 05:11:25 DEBUG[22434]: chan_sip.c:3363 parse_request: Header 11: Content-Length: 0 (17) Jun 21 05:11:25 DEBUG[22434]: chan_sip.c:3363 parse_request: Header 12: (0) --- (12 headers 0 lines)--- Jun 21 05:11:25 DEBUG[22434]: chan_sip.c:11137 handle_request: **** Received BYE (8) - Command in SIP BYE Sending to 10.10.10.37 : 5060 (NAT) Transmitting (NAT) to 10.10.10.37:5060: SIP/2.0 200 OK Via: SIP/2.0/UDP 10.10.10.37;branch=z9hG4bKac2048848741;received=10.10.10.37 From: ;tag=1c2045987290 To: "test sjphone" ;tag=as6e9300de Call-ID: 411381e0766f42282c15b58c423325ad@10.10.10.61 CSeq: 1 BYE User-Agent: Asterisk PBX Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY Contact: Content-Length: 0 X-Asterisk-HangupCause: Normal Clearing --- Jun 21 05:11:25 DEBUG[22457]: channel.c:3275 ast_generic_bridge: Didn't get a frame from channel: SIP/gatewayTDO-9640 Jun 21 05:11:25 DEBUG[22457]: channel.c:3550 ast_channel_bridge: Bridge stops bridging channels SIP/1211-c549 and SIP/gatewayTDO-9640 Jun 21 05:11:25 DEBUG[22457]: channel.c:1323 ast_hangup: Hanging up channel 'SIP/gatewayTDO-9640' Jun 21 05:11:25 DEBUG[22457]: chan_sip.c:2418 sip_hangup: Hangup call SIP/gatewayTDO-9640, SIP callid 411381e0766f42282c15b58c423325ad@10.10.10.61) Jun 21 05:11:25 DEBUG[22457]: chan_sip.c:2426 sip_hangup: update_call_counter(677) - decrement call limit counter Jun 21 05:11:25 DEBUG[22457]: chan_sip.c:2209 update_call_counter: Updating call counter for outgoing call Jun 21 05:11:25 DEBUG[22457]: app_dial.c:1619 dial_exec_full: Exiting with DIALSTATUS=ANSWER. Jun 21 05:11:25 DEBUG[22429]: chan_sip.c:11668 sip_devicestate: Checking device state for peer gatewayTDO Jun 21 05:11:25 DEBUG[22457]: pbx.c:2316 __ast_pbx_run: Spawn extension (fromoffice,7677,3) exited non-zero on 'SIP/1211-c549' Jun 21 05:11:25 DEBUG[22429]: devicestate.c:187 do_state_change: Changing state for SIP/gatewayTDO - state 1 (Not in use) Jun 21 05:11:25 DEBUG[22462]: app_queue.c:523 changethread: Device 'SIP/gatewayTDO' changed to state '1' (Not in use) but we don't care because they're not a member of any queue. Jun 21 05:11:25 DEBUG[22457]: pbx.c:1522 pbx_substitute_variables_helper_full: Function result is '"test sjphone" <1211>' Jun 21 05:11:25 DEBUG[22457]: pbx.c:1522 pbx_substitute_variables_helper_full: Function result is '1211' Jun 21 05:11:25 DEBUG[22457]: pbx.c:1522 pbx_substitute_variables_helper_full: Function result is '7677' Jun 21 05:11:25 DEBUG[22457]: pbx.c:1522 pbx_substitute_variables_helper_full: Function result is 'fromoffice' Jun 21 05:11:25 DEBUG[22457]: pbx.c:1522 pbx_substitute_variables_helper_full: Function result is 'SIP/1211-c549' Jun 21 05:11:25 DEBUG[22457]: pbx.c:1522 pbx_substitute_variables_helper_full: Function result is 'SIP/gatewayTDO-9640' Jun 21 05:11:25 DEBUG[22457]: pbx.c:1522 pbx_substitute_variables_helper_full: Function result is 'Dial' Jun 21 05:11:25 DEBUG[22457]: pbx.c:1522 pbx_substitute_variables_helper_full: Function result is 'SIP/677@gatewayTDO|60|twTW' Jun 21 05:11:25 DEBUG[22457]: pbx.c:1522 pbx_substitute_variables_helper_full: Function result is '2006-06-21 05:11:22' Jun 21 05:11:25 DEBUG[22457]: pbx.c:1522 pbx_substitute_variables_helper_full: Function result is '2006-06-21 05:11:24' Jun 21 05:11:25 DEBUG[22457]: pbx.c:1522 pbx_substitute_variables_helper_full: Function result is '2006-06-21 05:11:25' Jun 21 05:11:25 DEBUG[22457]: pbx.c:1522 pbx_substitute_variables_helper_full: Function result is '3' Jun 21 05:11:25 DEBUG[22457]: pbx.c:1522 pbx_substitute_variables_helper_full: Function result is '1' Jun 21 05:11:25 DEBUG[22457]: pbx.c:1522 pbx_substitute_variables_helper_full: Function result is 'ANSWERED' Jun 21 05:11:25 DEBUG[22457]: pbx.c:1522 pbx_substitute_variables_helper_full: Function result is 'DOCUMENTATION' Jun 21 05:11:25 DEBUG[22457]: pbx.c:1522 pbx_substitute_variables_helper_full: Function result is '(null)' Jun 21 05:11:25 DEBUG[22457]: pbx.c:1522 pbx_substitute_variables_helper_full: Function result is '1150852282.5' Jun 21 05:11:25 DEBUG[22457]: pbx.c:1522 pbx_substitute_variables_helper_full: Function result is '(null)' Jun 21 05:11:25 DEBUG[22457]: channel.c:1323 ast_hangup: Hanging up channel 'SIP/1211-c549' Jun 21 05:11:25 DEBUG[22457]: chan_sip.c:2418 sip_hangup: Hangup call SIP/1211-c549, SIP callid B0F3B39B-580F-41C9-BD45-39BBA87062BB@10.10.10.7) Jun 21 05:11:25 DEBUG[22457]: chan_sip.c:2426 sip_hangup: update_call_counter(1211) - decrement call limit counter Jun 21 05:11:25 DEBUG[22457]: chan_sip.c:2209 update_call_counter: Updating call counter for incoming call set_destination: Parsing for address/port to send to set_destination: set destination to 10.10.10.7, port 5060 Reliably Transmitting (NAT) to 83.237.98.254:62291: BYE sip:1211@10.10.10.7:5060 SIP/2.0 Via: SIP/2.0/UDP 83.222.22.242:5060;branch=z9hG4bK581642da;rport From: ;tag=as1158c6d6 To: "operator name";tag=11595580529332 Contact: Call-ID: B0F3B39B-580F-41C9-BD45-39BBA87062BB@10.10.10.7 CSeq: 102 BYE User-Agent: Asterisk PBX Max-Forwards: 70 Content-Length: 0 --- Jun 21 05:11:25 DEBUG[22457]: chan_sip.c:1293 __sip_reliable_xmit: *** SIP TIMER: Initalizing retransmit timer on packet: Id #189 Jun 21 05:11:25 DEBUG[22429]: chan_sip.c:11668 sip_devicestate: Checking device state for peer 1211 Jun 21 05:11:25 DEBUG[22429]: devicestate.c:187 do_state_change: Changing state for SIP/1211 - state 2 (In use) Jun 21 05:11:25 DEBUG[22463]: app_queue.c:523 changethread: Device 'SIP/1211' changed to state '2' (In use) but we don't care because they're not a member of any queue. <-- SIP read from 83.237.98.254:62291: SIP/2.0 200 OK Via: SIP/2.0/UDP 83.222.22.242:5060;rport=5060;received=83.222.22.242;branch=z9hG4bK581642da Content-Length: 0 Call-ID: B0F3B39B-580F-41C9-BD45-39BBA87062BB@10.10.10.7 CSeq: 102 BYE From: ;tag=as1158c6d6 Server: SJphone/1.60.289a (SJ Labs) To: "operator name";tag=11595580529332 Jun 21 05:11:26 DEBUG[22434]: chan_sip.c:3363 parse_request: Header 0: SIP/2.0 200 OK (14) Jun 21 05:11:26 DEBUG[22434]: chan_sip.c:3363 parse_request: Header 1: Via: SIP/2.0/UDP 83.222.22.242:5060;rport=5060;received=83.222.22.242;branch=z9hG4bK581642da (92) Jun 21 05:11:26 DEBUG[22434]: chan_sip.c:3363 parse_request: Header 2: Content-Length: 0 (17) Jun 21 05:11:26 DEBUG[22434]: chan_sip.c:3363 parse_request: Header 3: Call-ID: B0F3B39B-580F-41C9-BD45-39BBA87062BB@10.10.10.7 (56) Jun 21 05:11:26 DEBUG[22434]: chan_sip.c:3363 parse_request: Header 4: CSeq: 102 BYE (13) Jun 21 05:11:26 DEBUG[22434]: chan_sip.c:3363 parse_request: Header 5: From: ;tag=as1158c6d6 (52) Jun 21 05:11:26 DEBUG[22434]: chan_sip.c:3363 parse_request: Header 6: Server: SJphone/1.60.289a (SJ Labs) (35) Jun 21 05:11:26 DEBUG[22434]: chan_sip.c:3363 parse_request: Header 7: To: "operator name";tag=11595580529332 (71) Jun 21 05:11:26 DEBUG[22434]: chan_sip.c:3363 parse_request: Header 8: (0) --- (8 headers 0 lines)--- Jun 21 05:11:26 DEBUG[22434]: chan_sip.c:1390 __sip_ack: ** SIP TIMER: Cancelling retransmit of packet (reply received) Retransid #189 Jun 21 05:11:26 DEBUG[22434]: chan_sip.c:1401 __sip_ack: Stopping retransmission on 'B0F3B39B-580F-41C9-BD45-39BBA87062BB@10.10.10.7' of Request 102: Match Found Destroying call '411381e0766f42282c15b58c423325ad@10.10.10.61' Destroying call 'B0F3B39B-580F-41C9-BD45-39BBA87062BB@10.10.10.7' <-- SIP read from 83.237.98.254:62291: INVITE sip:9166104314@83.222.22.242 SIP/2.0 Via: SIP/2.0/UDP 10.10.10.7;rport;branch=z9hG4bK0a0a0a07000001c144989cc1000062ab00001109 Content-Length: 214 Contact: Call-ID: 25cc17a101808ece7e127e501478ea9c@masterhost.ru Content-Type: application/sdp CSeq: 2 INVITE From: "operator name";tag=11595025729485 Max-Forwards: 70 To: ;tag=as78c50bc3 User-Agent: SJphone/1.60.289a (SJ Labs) v=0 o=- 3359841080 3359841082 IN IP4 10.10.10.7 s=SJphone c=IN IP4 10.10.10.7 t=0 0 a=direction:active m=audio 49218 RTP/AVP 3 101 a=rtpmap:3 GSM/8000 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-11,16 Jun 21 05:11:26 DEBUG[22434]: chan_sip.c:3363 parse_request: Header 0: INVITE sip:9166104314@83.222.22.242 SIP/2.0 (43) Jun 21 05:11:26 DEBUG[22434]: chan_sip.c:3363 parse_request: Header 1: Via: SIP/2.0/UDP 10.10.10.7;rport;branch=z9hG4bK0a0a0a07000001c144989cc1000062ab00001109 (88) Jun 21 05:11:26 DEBUG[22434]: chan_sip.c:3363 parse_request: Header 2: Content-Length: 214 (19) Jun 21 05:11:26 DEBUG[22434]: chan_sip.c:3363 parse_request: Header 3: Contact: (35) Jun 21 05:11:26 DEBUG[22434]: chan_sip.c:3363 parse_request: Header 4: Call-ID: 25cc17a101808ece7e127e501478ea9c@masterhost.ru (55) Jun 21 05:11:26 DEBUG[22434]: chan_sip.c:3363 parse_request: Header 5: Content-Type: application/sdp (29) Jun 21 05:11:26 DEBUG[22434]: chan_sip.c:3363 parse_request: Header 6: CSeq: 2 INVITE (14) Jun 21 05:11:26 DEBUG[22434]: chan_sip.c:3363 parse_request: Header 7: From: "operator name";tag=11595025729485 (68) Jun 21 05:11:26 DEBUG[22434]: chan_sip.c:3363 parse_request: Header 8: Max-Forwards: 70 (16) Jun 21 05:11:26 DEBUG[22434]: chan_sip.c:3363 parse_request: Header 9: To: ;tag=as78c50bc3 (49) Jun 21 05:11:26 DEBUG[22434]: chan_sip.c:3363 parse_request: Header 10: User-Agent: SJphone/1.60.289a (SJ Labs) (39) Jun 21 05:11:26 DEBUG[22434]: chan_sip.c:3363 parse_request: Header 11: (0) Jun 21 05:11:26 DEBUG[22434]: chan_sip.c:3395 parse_request: Line: v=0 (3) Jun 21 05:11:26 DEBUG[22434]: chan_sip.c:3395 parse_request: Line: o=- 3359841080 3359841082 IN IP4 10.10.10.7 (43) Jun 21 05:11:26 DEBUG[22434]: chan_sip.c:3395 parse_request: Line: s=SJphone (9) Jun 21 05:11:26 DEBUG[22434]: chan_sip.c:3395 parse_request: Line: c=IN IP4 10.10.10.7 (19) Jun 21 05:11:26 DEBUG[22434]: chan_sip.c:3395 parse_request: Line: t=0 0 (5) Jun 21 05:11:26 DEBUG[22434]: chan_sip.c:3395 parse_request: Line: a=direction:active (18) Jun 21 05:11:26 DEBUG[22434]: chan_sip.c:3395 parse_request: Line: m=audio 49218 RTP/AVP 3 101 (27) Jun 21 05:11:26 DEBUG[22434]: chan_sip.c:3395 parse_request: Line: a=rtpmap:3 GSM/8000 (19) Jun 21 05:11:26 DEBUG[22434]: chan_sip.c:3395 parse_request: Line: a=rtpmap:101 telephone-event/8000 (33) Jun 21 05:11:26 DEBUG[22434]: chan_sip.c:3395 parse_request: Line: a=fmtp:101 0-11,16 (18) --- (11 headers 10 lines)--- Jun 21 05:11:26 DEBUG[22434]: chan_sip.c:11137 handle_request: **** Received INVITE (5) - Command in SIP INVITE Using INVITE request as basis request - 25cc17a101808ece7e127e501478ea9c@masterhost.ru Sending to 10.10.10.7 : 5060 (NAT) Found RTP audio format 3 Found RTP audio format 101 Peer audio RTP is at port 10.10.10.7:49218 Jun 21 05:11:26 DEBUG[22434]: chan_sip.c:3604 process_sdp: Peer audio RTP is at port 10.10.10.7:49218 Peer video RTP is at port 10.10.10.7:65535 Jun 21 05:11:26 DEBUG[22434]: chan_sip.c:3628 process_sdp: Peer video RTP is at port 10.10.10.7:65535 Found description format GSM Found description format telephone-event Capabilities: us - 0x8000e (gsm|ulaw|alaw|h263), peer - audio=0x2 (gsm)/video=0x0 (nothing), combined - 0x2 (gsm) Non-codec capabilities: us - 0x1 (telephone-event), peer - 0x1 (telephone-event), combined - 0x1 (telephone-event) -- Stopped music on hold on Zap/32-1 Jun 21 05:11:26 DEBUG[22434]: channel.c:2350 set_format: Set channel Zap/32-1 to write format slin Jun 21 05:11:26 DEBUG[22434]: channel.c:1711 ast_settimeout: Scheduling timer at 0 sample intervals Jun 21 05:11:26 DEBUG[22434]: chan_sip.c:10551 handle_request_invite: Got a SIP re-invite for call 25cc17a101808ece7e127e501478ea9c@masterhost.ru We're at 83.222.22.242 port 18868 Video is at 83.222.22.242 port 14398 Adding codec 0x2 (gsm) to SDP Adding non-codec 0x1 (telephone-event) to SDP Reliably Transmitting (NAT) to 83.237.98.254:62291: SIP/2.0 200 OK Via: SIP/2.0/UDP 10.10.10.7;branch=z9hG4bK0a0a0a07000001c144989cc1000062ab00001109;received=83.237.98.254;rport=62291 From: "operator name";tag=11595025729485 To: ;tag=as78c50bc3 Call-ID: 25cc17a101808ece7e127e501478ea9c@masterhost.ru CSeq: 2 INVITE User-Agent: Asterisk PBX Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY Contact: Content-Type: application/sdp Content-Length: 217 v=0 o=root 22425 22427 IN IP4 83.222.22.242 s=session c=IN IP4 83.222.22.242 t=0 0 m=audio 18868 RTP/AVP 3 101 a=rtpmap:3 GSM/8000 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-16 a=silenceSupp:off - - - - --- Jun 21 05:11:26 DEBUG[22434]: chan_sip.c:1293 __sip_reliable_xmit: *** SIP TIMER: Initalizing retransmit timer on packet: Id #190 Jun 21 05:11:26 DEBUG[22444]: rtp.c:1260 ast_rtp_raw_write: Difference is 45600, ms is 5720 Jun 21 05:11:26 DEBUG[22444]: rtp.c:479 ast_rtp_read: RTP NAT: Got audio from other end. Now sending to address 83.237.98.254:62400 <-- SIP read from 83.237.98.254:62291: ACK sip:9166104314@83.222.22.242 SIP/2.0 Via: SIP/2.0/UDP 10.10.10.7;rport;branch=z9hG4bK0a0a0a07000001c144989cc10000394e0000110b Content-Length: 0 Call-ID: 25cc17a101808ece7e127e501478ea9c@masterhost.ru CSeq: 2 ACK From: "operator name";tag=11595025729485 Max-Forwards: 70 To: ;tag=as78c50bc3 User-Agent: SJphone/1.60.289a (SJ Labs) Jun 21 05:11:26 DEBUG[22434]: chan_sip.c:3363 parse_request: Header 0: ACK sip:9166104314@83.222.22.242 SIP/2.0 (40) Jun 21 05:11:26 DEBUG[22434]: chan_sip.c:3363 parse_request: Header 1: Via: SIP/2.0/UDP 10.10.10.7;rport;branch=z9hG4bK0a0a0a07000001c144989cc10000394e0000110b (88) Jun 21 05:11:26 DEBUG[22434]: chan_sip.c:3363 parse_request: Header 2: Content-Length: 0 (17) Jun 21 05:11:26 DEBUG[22434]: chan_sip.c:3363 parse_request: Header 3: Call-ID: 25cc17a101808ece7e127e501478ea9c@masterhost.ru (55) Jun 21 05:11:26 DEBUG[22434]: chan_sip.c:3363 parse_request: Header 4: CSeq: 2 ACK (11) Jun 21 05:11:26 DEBUG[22434]: chan_sip.c:3363 parse_request: Header 5: From: "operator name";tag=11595025729485 (68) Jun 21 05:11:26 DEBUG[22434]: chan_sip.c:3363 parse_request: Header 6: Max-Forwards: 70 (16) Jun 21 05:11:26 DEBUG[22434]: chan_sip.c:3363 parse_request: Header 7: To: ;tag=as78c50bc3 (49) Jun 21 05:11:26 DEBUG[22434]: chan_sip.c:3363 parse_request: Header 8: User-Agent: SJphone/1.60.289a (SJ Labs) (39) Jun 21 05:11:26 DEBUG[22434]: chan_sip.c:3363 parse_request: Header 9: (0) --- (9 headers 0 lines)--- Jun 21 05:11:26 DEBUG[22434]: chan_sip.c:11137 handle_request: **** Received ACK (6) - Command in SIP ACK Jun 21 05:11:26 DEBUG[22434]: chan_sip.c:1390 __sip_ack: ** SIP TIMER: Cancelling retransmit of packet (reply received) Retransid #190 Jun 21 05:11:26 DEBUG[22434]: chan_sip.c:1401 __sip_ack: Stopping retransmission on '25cc17a101808ece7e127e501478ea9c@masterhost.ru' of Response 2: Match Found <-- SIP read from 83.237.98.254:62291: INVITE sip:9166104314@83.222.22.242 SIP/2.0 Via: SIP/2.0/UDP 10.10.10.7;rport;branch=z9hG4bK0a0a0a07000001c144989cc300001e600000110c Content-Length: 211 Contact: Call-ID: 25cc17a101808ece7e127e501478ea9c@masterhost.ru Content-Type: application/sdp CSeq: 3 INVITE From: "operator name";tag=11595025729485 Max-Forwards: 70 To: ;tag=as78c50bc3 User-Agent: SJphone/1.60.289a (SJ Labs) v=0 o=- 3359841080 3359841083 IN IP4 10.10.10.7 s=SJphone c=IN IP4 0.0.0.0 t=0 0 a=direction:active m=audio 49218 RTP/AVP 3 101 a=rtpmap:3 GSM/8000 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-11,16 Jun 21 05:11:28 DEBUG[22434]: chan_sip.c:3363 parse_request: Header 0: INVITE sip:9166104314@83.222.22.242 SIP/2.0 (43) Jun 21 05:11:28 DEBUG[22434]: chan_sip.c:3363 parse_request: Header 1: Via: SIP/2.0/UDP 10.10.10.7;rport;branch=z9hG4bK0a0a0a07000001c144989cc300001e600000110c (88) Jun 21 05:11:28 DEBUG[22434]: chan_sip.c:3363 parse_request: Header 2: Content-Length: 211 (19) Jun 21 05:11:28 DEBUG[22434]: chan_sip.c:3363 parse_request: Header 3: Contact: (35) Jun 21 05:11:28 DEBUG[22434]: chan_sip.c:3363 parse_request: Header 4: Call-ID: 25cc17a101808ece7e127e501478ea9c@masterhost.ru (55) Jun 21 05:11:28 DEBUG[22434]: chan_sip.c:3363 parse_request: Header 5: Content-Type: application/sdp (29) Jun 21 05:11:28 DEBUG[22434]: chan_sip.c:3363 parse_request: Header 6: CSeq: 3 INVITE (14) Jun 21 05:11:28 DEBUG[22434]: chan_sip.c:3363 parse_request: Header 7: From: "operator name";tag=11595025729485 (68) Jun 21 05:11:28 DEBUG[22434]: chan_sip.c:3363 parse_request: Header 8: Max-Forwards: 70 (16) Jun 21 05:11:28 DEBUG[22434]: chan_sip.c:3363 parse_request: Header 9: To: ;tag=as78c50bc3 (49) Jun 21 05:11:28 DEBUG[22434]: chan_sip.c:3363 parse_request: Header 10: User-Agent: SJphone/1.60.289a (SJ Labs) (39) Jun 21 05:11:28 DEBUG[22434]: chan_sip.c:3363 parse_request: Header 11: (0) Jun 21 05:11:28 DEBUG[22434]: chan_sip.c:3395 parse_request: Line: v=0 (3) Jun 21 05:11:28 DEBUG[22434]: chan_sip.c:3395 parse_request: Line: o=- 3359841080 3359841083 IN IP4 10.10.10.7 (43) Jun 21 05:11:28 DEBUG[22434]: chan_sip.c:3395 parse_request: Line: s=SJphone (9) Jun 21 05:11:28 DEBUG[22434]: chan_sip.c:3395 parse_request: Line: c=IN IP4 0.0.0.0 (16) Jun 21 05:11:28 DEBUG[22434]: chan_sip.c:3395 parse_request: Line: t=0 0 (5) Jun 21 05:11:28 DEBUG[22434]: chan_sip.c:3395 parse_request: Line: a=direction:active (18) Jun 21 05:11:28 DEBUG[22434]: chan_sip.c:3395 parse_request: Line: m=audio 49218 RTP/AVP 3 101 (27) Jun 21 05:11:28 DEBUG[22434]: chan_sip.c:3395 parse_request: Line: a=rtpmap:3 GSM/8000 (19) Jun 21 05:11:28 DEBUG[22434]: chan_sip.c:3395 parse_request: Line: a=rtpmap:101 telephone-event/8000 (33) Jun 21 05:11:28 DEBUG[22434]: chan_sip.c:3395 parse_request: Line: a=fmtp:101 0-11,16 (18) --- (11 headers 10 lines)--- Jun 21 05:11:28 DEBUG[22434]: chan_sip.c:11137 handle_request: **** Received INVITE (5) - Command in SIP INVITE Using INVITE request as basis request - 25cc17a101808ece7e127e501478ea9c@masterhost.ru Sending to 10.10.10.7 : 5060 (NAT) Found RTP audio format 3 Found RTP audio format 101 Peer audio RTP is at port 0.0.0.0:49218 Jun 21 05:11:28 DEBUG[22434]: chan_sip.c:3604 process_sdp: Peer audio RTP is at port 0.0.0.0:49218 Peer video RTP is at port 0.0.0.0:65535 Jun 21 05:11:28 DEBUG[22434]: chan_sip.c:3628 process_sdp: Peer video RTP is at port 0.0.0.0:65535 Found description format GSM Found description format telephone-event Capabilities: us - 0x8000e (gsm|ulaw|alaw|h263), peer - audio=0x2 (gsm)/video=0x0 (nothing), combined - 0x2 (gsm) Non-codec capabilities: us - 0x1 (telephone-event), peer - 0x1 (telephone-event), combined - 0x1 (telephone-event) -- Started music on hold, class 'default', on Zap/32-1 Jun 21 05:11:28 DEBUG[22434]: channel.c:1711 ast_settimeout: Scheduling timer at 160 sample intervals Jun 21 05:11:28 DEBUG[22434]: chan_sip.c:10551 handle_request_invite: Got a SIP re-invite for call 25cc17a101808ece7e127e501478ea9c@masterhost.ru We're at 83.222.22.242 port 18868 Video is at 83.222.22.242 port 14398 Adding codec 0x2 (gsm) to SDP Adding non-codec 0x1 (telephone-event) to SDP Reliably Transmitting (NAT) to 83.237.98.254:62291: SIP/2.0 200 OK Via: SIP/2.0/UDP 10.10.10.7;branch=z9hG4bK0a0a0a07000001c144989cc300001e600000110c;received=83.237.98.254;rport=62291 From: "operator name";tag=11595025729485 To: ;tag=as78c50bc3 Call-ID: 25cc17a101808ece7e127e501478ea9c@masterhost.ru CSeq: 3 INVITE User-Agent: Asterisk PBX Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY Contact: Content-Type: application/sdp Content-Length: 217 v=0 o=root 22425 22428 IN IP4 83.222.22.242 s=session c=IN IP4 83.222.22.242 t=0 0 m=audio 18868 RTP/AVP 3 101 a=rtpmap:3 GSM/8000 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-16 a=silenceSupp:off - - - - --- Jun 21 05:11:28 DEBUG[22434]: chan_sip.c:1293 __sip_reliable_xmit: *** SIP TIMER: Initalizing retransmit timer on packet: Id #191 Jun 21 05:11:28 DEBUG[22444]: channel.c:1975 ast_read: Generator got voice, switching to phase locked mode Jun 21 05:11:28 DEBUG[22444]: channel.c:1711 ast_settimeout: Scheduling timer at 0 sample intervals Jun 21 05:11:28 DEBUG[22444]: channel.c:2350 set_format: Set channel Zap/32-1 to write format ulaw Jun 21 05:11:28 DEBUG[22444]: res_musiconhold.c:233 ast_moh_files_next: Zap/32-1 Opened file 2 '/var/lib/asterisk/mohmp3/misc/Heaven_For_Everyone_Queen' <-- SIP read from 83.237.98.254:62291: ACK sip:9166104314@83.222.22.242 SIP/2.0 Via: SIP/2.0/UDP 10.10.10.7;rport;branch=z9hG4bK0a0a0a07000001c144989cc3000021a40000110e Content-Length: 0 Call-ID: 25cc17a101808ece7e127e501478ea9c@masterhost.ru CSeq: 3 ACK From: "operator name";tag=11595025729485 Max-Forwards: 70 To: ;tag=as78c50bc3 User-Agent: SJphone/1.60.289a (SJ Labs) Jun 21 05:11:28 DEBUG[22434]: chan_sip.c:3363 parse_request: Header 0: ACK sip:9166104314@83.222.22.242 SIP/2.0 (40) Jun 21 05:11:28 DEBUG[22434]: chan_sip.c:3363 parse_request: Header 1: Via: SIP/2.0/UDP 10.10.10.7;rport;branch=z9hG4bK0a0a0a07000001c144989cc3000021a40000110e (88) Jun 21 05:11:28 DEBUG[22434]: chan_sip.c:3363 parse_request: Header 2: Content-Length: 0 (17) Jun 21 05:11:28 DEBUG[22434]: chan_sip.c:3363 parse_request: Header 3: Call-ID: 25cc17a101808ece7e127e501478ea9c@masterhost.ru (55) Jun 21 05:11:28 DEBUG[22434]: chan_sip.c:3363 parse_request: Header 4: CSeq: 3 ACK (11) Jun 21 05:11:28 DEBUG[22434]: chan_sip.c:3363 parse_request: Header 5: From: "operator name";tag=11595025729485 (68) Jun 21 05:11:28 DEBUG[22434]: chan_sip.c:3363 parse_request: Header 6: Max-Forwards: 70 (16) Jun 21 05:11:28 DEBUG[22434]: chan_sip.c:3363 parse_request: Header 7: To: ;tag=as78c50bc3 (49) Jun 21 05:11:28 DEBUG[22434]: chan_sip.c:3363 parse_request: Header 8: User-Agent: SJphone/1.60.289a (SJ Labs) (39) Jun 21 05:11:28 DEBUG[22434]: chan_sip.c:3363 parse_request: Header 9: (0) --- (9 headers 0 lines)--- Jun 21 05:11:28 DEBUG[22434]: chan_sip.c:11137 handle_request: **** Received ACK (6) - Command in SIP ACK Jun 21 05:11:28 DEBUG[22434]: chan_sip.c:1390 __sip_ack: ** SIP TIMER: Cancelling retransmit of packet (reply received) Retransid #191 Jun 21 05:11:28 DEBUG[22434]: chan_sip.c:1401 __sip_ack: Stopping retransmission on '25cc17a101808ece7e127e501478ea9c@masterhost.ru' of Response 3: Match Found <-- SIP read from 83.237.98.254:62291: REFER sip:9166104314@83.222.22.242 SIP/2.0 Via: SIP/2.0/UDP 10.10.10.7;rport;branch=z9hG4bK0a0a0a07000001c144989cc30000781a0000110f Content-Length: 0 Contact: Call-ID: 25cc17a101808ece7e127e501478ea9c@masterhost.ru CSeq: 4 REFER From: "operator name";tag=11595025729485 Max-Forwards: 70 Referred-By: Refer-To: To: ;tag=as78c50bc3 User-Agent: SJphone/1.60.289a (SJ Labs) Jun 21 05:11:28 DEBUG[22434]: chan_sip.c:3363 parse_request: Header 0: REFER sip:9166104314@83.222.22.242 SIP/2.0 (42) Jun 21 05:11:28 DEBUG[22434]: chan_sip.c:3363 parse_request: Header 1: Via: SIP/2.0/UDP 10.10.10.7;rport;branch=z9hG4bK0a0a0a07000001c144989cc30000781a0000110f (88) Jun 21 05:11:28 DEBUG[22434]: chan_sip.c:3363 parse_request: Header 2: Content-Length: 0 (17) Jun 21 05:11:28 DEBUG[22434]: chan_sip.c:3363 parse_request: Header 3: Contact: (35) Jun 21 05:11:28 DEBUG[22434]: chan_sip.c:3363 parse_request: Header 4: Call-ID: 25cc17a101808ece7e127e501478ea9c@masterhost.ru (55) Jun 21 05:11:28 DEBUG[22434]: chan_sip.c:3363 parse_request: Header 5: CSeq: 4 REFER (13) Jun 21 05:11:28 DEBUG[22434]: chan_sip.c:3363 parse_request: Header 6: From: "operator name";tag=11595025729485 (68) Jun 21 05:11:28 DEBUG[22434]: chan_sip.c:3363 parse_request: Header 7: Max-Forwards: 70 (16) Jun 21 05:11:28 DEBUG[22434]: chan_sip.c:3363 parse_request: Header 8: Referred-By: (39) Jun 21 05:11:28 DEBUG[22434]: chan_sip.c:3363 parse_request: Header 9: Refer-To: (148) Jun 21 05:11:28 DEBUG[22434]: chan_sip.c:3363 parse_request: Header 10: To: ;tag=as78c50bc3 (49) Jun 21 05:11:28 DEBUG[22434]: chan_sip.c:3363 parse_request: Header 11: User-Agent: SJphone/1.60.289a (SJ Labs) (39) Jun 21 05:11:28 DEBUG[22434]: chan_sip.c:3363 parse_request: Header 12: (0) --- (12 headers 0 lines)--- Jun 21 05:11:28 DEBUG[22434]: chan_sip.c:11137 handle_request: **** Received REFER (9) - Command in SIP REFER Jun 21 05:11:28 DEBUG[22434]: chan_sip.c:10663 handle_request_refer: SIP call transfer received for call 25cc17a101808ece7e127e501478ea9c@masterhost.ru (REFER)! Transfer to 9166104314 in fromoffice Transfer from 1211 in fromoffice Jun 21 05:11:28 DEBUG[22434]: chan_sip.c:6857 get_refer_info: Assigning Replace-Call-ID Info 25cc17a101808ece7e127e501478ea9c@masterhost.ru to REPLACE_CALL_ID Jun 21 05:11:28 NOTICE[22434]: chan_sip.c:6866 get_refer_info: Supervised transfer attempted to transfer into same call id (25cc17a101808ece7e127e501478ea9c@masterhost.ru == 25cc17a101808ece7e127e501478ea9c@masterhost.ru)! Reliably Transmitting (NAT) to 83.237.98.254:62291: SIP/2.0 404 Not Found Via: SIP/2.0/UDP 10.10.10.7;branch=z9hG4bK0a0a0a07000001c144989cc30000781a0000110f;received=83.237.98.254;rport=62291 From: "operator name";tag=11595025729485 To: ;tag=as78c50bc3 Call-ID: 25cc17a101808ece7e127e501478ea9c@masterhost.ru CSeq: 4 REFER User-Agent: Asterisk PBX Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY Contact: Accept: application/sdp Content-Length: 0 --- Jun 21 05:11:28 DEBUG[22434]: chan_sip.c:1293 __sip_reliable_xmit: *** SIP TIMER: Initalizing retransmit timer on packet: Id #192 Jun 21 05:11:28 DEBUG[22434]: chan_sip.c:11338 sipsock_read: SIP message could not be handled, bad request: 25cc17a101808ece7e127e501478ea9c@masterhost.ru Jun 21 05:11:29 DEBUG[22434]: chan_sip.c:1184 retrans_pkt: SIP TIMER: Rescheduling retransmission #192 (1) SIP/2.0 - 1 Jun 21 05:11:29 DEBUG[22434]: chan_sip.c:1198 retrans_pkt: ** SIP timers: Rescheduling retransmission 2 to 1000 ms (t1 500 ms (Retrans id #192)) Retransmitting #1 (NAT) to 83.237.98.254:62291: SIP/2.0 404 Not Found Via: SIP/2.0/UDP 10.10.10.7;branch=z9hG4bK0a0a0a07000001c144989cc30000781a0000110f;received=83.237.98.254;rport=62291 From: "operator name";tag=11595025729485 To: ;tag=as78c50bc3 Call-ID: 25cc17a101808ece7e127e501478ea9c@masterhost.ru CSeq: 4 REFER User-Agent: Asterisk PBX Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY Contact: Accept: application/sdp Content-Length: 0 --- Jun 21 05:11:30 DEBUG[22434]: chan_sip.c:1184 retrans_pkt: SIP TIMER: Rescheduling retransmission #192 (2) SIP/2.0 - 1 Jun 21 05:11:30 DEBUG[22434]: chan_sip.c:1198 retrans_pkt: ** SIP timers: Rescheduling retransmission 3 to 2000 ms (t1 500 ms (Retrans id #192)) Retransmitting #2 (NAT) to 83.237.98.254:62291: SIP/2.0 404 Not Found Via: SIP/2.0/UDP 10.10.10.7;branch=z9hG4bK0a0a0a07000001c144989cc30000781a0000110f;received=83.237.98.254;rport=62291 From: "operator name";tag=11595025729485 To: ;tag=as78c50bc3 Call-ID: 25cc17a101808ece7e127e501478ea9c@masterhost.ru CSeq: 4 REFER User-Agent: Asterisk PBX Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY Contact: Accept: application/sdp Content-Length: 0 --- Jun 21 05:11:32 DEBUG[22434]: chan_sip.c:1184 retrans_pkt: SIP TIMER: Rescheduling retransmission #192 (3) SIP/2.0 - 1 Jun 21 05:11:32 DEBUG[22434]: chan_sip.c:1198 retrans_pkt: ** SIP timers: Rescheduling retransmission 4 to 4000 ms (t1 500 ms (Retrans id #192)) Retransmitting #3 (NAT) to 83.237.98.254:62291: SIP/2.0 404 Not Found Via: SIP/2.0/UDP 10.10.10.7;branch=z9hG4bK0a0a0a07000001c144989cc30000781a0000110f;received=83.237.98.254;rport=62291 From: "operator name";tag=11595025729485 To: ;tag=as78c50bc3 Call-ID: 25cc17a101808ece7e127e501478ea9c@masterhost.ru CSeq: 4 REFER User-Agent: Asterisk PBX Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY Contact: Accept: application/sdp Content-Length: 0 --- Jun 21 05:11:36 DEBUG[22434]: chan_sip.c:1184 retrans_pkt: SIP TIMER: Rescheduling retransmission #192 (4) SIP/2.0 - 1 Jun 21 05:11:36 DEBUG[22434]: chan_sip.c:1198 retrans_pkt: ** SIP timers: Rescheduling retransmission 5 to 4000 ms (t1 500 ms (Retrans id #192)) Retransmitting #4 (NAT) to 83.237.98.254:62291: SIP/2.0 404 Not Found Via: SIP/2.0/UDP 10.10.10.7;branch=z9hG4bK0a0a0a07000001c144989cc30000781a0000110f;received=83.237.98.254;rport=62291 From: "operator name";tag=11595025729485 To: ;tag=as78c50bc3 Call-ID: 25cc17a101808ece7e127e501478ea9c@masterhost.ru CSeq: 4 REFER User-Agent: Asterisk PBX Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY Contact: Accept: application/sdp Content-Length: 0 --- <-- SIP read from 83.237.98.254:62291: BYE sip:9166104314@83.222.22.242 SIP/2.0 Via: SIP/2.0/UDP 10.10.10.7;rport;branch=z9hG4bK0a0a0a07000001c144989ccc00002ce400001115 Content-Length: 0 Call-ID: 25cc17a101808ece7e127e501478ea9c@masterhost.ru CSeq: 5 BYE From: "operator name";tag=11595025729485 Max-Forwards: 70 To: ;tag=as78c50bc3 User-Agent: SJphone/1.60.289a (SJ Labs) Jun 21 05:11:37 DEBUG[22434]: chan_sip.c:3363 parse_request: Header 0: BYE sip:9166104314@83.222.22.242 SIP/2.0 (40) Jun 21 05:11:37 DEBUG[22434]: chan_sip.c:3363 parse_request: Header 1: Via: SIP/2.0/UDP 10.10.10.7;rport;branch=z9hG4bK0a0a0a07000001c144989ccc00002ce400001115 (88) Jun 21 05:11:37 DEBUG[22434]: chan_sip.c:3363 parse_request: Header 2: Content-Length: 0 (17) Jun 21 05:11:37 DEBUG[22434]: chan_sip.c:3363 parse_request: Header 3: Call-ID: 25cc17a101808ece7e127e501478ea9c@masterhost.ru (55) Jun 21 05:11:37 DEBUG[22434]: chan_sip.c:3363 parse_request: Header 4: CSeq: 5 BYE (11) Jun 21 05:11:37 DEBUG[22434]: chan_sip.c:3363 parse_request: Header 5: From: "operator name";tag=11595025729485 (68) Jun 21 05:11:37 DEBUG[22434]: chan_sip.c:3363 parse_request: Header 6: Max-Forwards: 70 (16) Jun 21 05:11:37 DEBUG[22434]: chan_sip.c:3363 parse_request: Header 7: To: ;tag=as78c50bc3 (49) Jun 21 05:11:37 DEBUG[22434]: chan_sip.c:3363 parse_request: Header 8: User-Agent: SJphone/1.60.289a (SJ Labs) (39) Jun 21 05:11:37 DEBUG[22434]: chan_sip.c:3363 parse_request: Header 9: (0) --- (9 headers 0 lines)--- Jun 21 05:11:37 DEBUG[22434]: chan_sip.c:11137 handle_request: **** Received BYE (8) - Command in SIP BYE Sending to 10.10.10.7 : 5060 (NAT) Transmitting (NAT) to 83.237.98.254:62291: SIP/2.0 200 OK Via: SIP/2.0/UDP 10.10.10.7;branch=z9hG4bK0a0a0a07000001c144989ccc00002ce400001115;received=83.237.98.254;rport=62291 From: "operator name";tag=11595025729485 To: ;tag=as78c50bc3 Call-ID: 25cc17a101808ece7e127e501478ea9c@masterhost.ru CSeq: 5 BYE User-Agent: Asterisk PBX Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY Contact: Content-Length: 0 --- <-- SIP read from 83.237.98.254:62291: OPTIONS sip:phone2.masterhost.ru SIP/2.0 Via: SIP/2.0/UDP 10.10.10.7;rport;branch=z9hG4bK0a0a0a070000001044989cce00004aa800001117 Content-Length: 0 Call-ID: FDD64600-96E1-48B8-8C70-15829AEAE40A@10.10.10.7 CSeq: 1862 OPTIONS From: ;tag=1159718086965 Max-Forwards: 70 To: Jun 21 05:11:38 DEBUG[22434]: chan_sip.c:3363 parse_request: Header 0: OPTIONS sip:phone2.masterhost.ru SIP/2.0 (40) Jun 21 05:11:38 DEBUG[22434]: chan_sip.c:3363 parse_request: Header 1: Via: SIP/2.0/UDP 10.10.10.7;rport;branch=z9hG4bK0a0a0a070000001044989cce00004aa800001117 (88) Jun 21 05:11:38 DEBUG[22434]: chan_sip.c:3363 parse_request: Header 2: Content-Length: 0 (17) Jun 21 05:11:38 DEBUG[22434]: chan_sip.c:3363 parse_request: Header 3: Call-ID: FDD64600-96E1-48B8-8C70-15829AEAE40A@10.10.10.7 (56) Jun 21 05:11:38 DEBUG[22434]: chan_sip.c:3363 parse_request: Header 4: CSeq: 1862 OPTIONS (18) Jun 21 05:11:38 DEBUG[22434]: chan_sip.c:3363 parse_request: Header 5: From: ;tag=1159718086965 (55) Jun 21 05:11:38 DEBUG[22434]: chan_sip.c:3363 parse_request: Header 6: Max-Forwards: 70 (16) Jun 21 05:11:38 DEBUG[22434]: chan_sip.c:3363 parse_request: Header 7: To: (30) Jun 21 05:11:38 DEBUG[22434]: chan_sip.c:3363 parse_request: Header 8: (0) --- (8 headers 0 lines)--- Jun 21 05:11:38 DEBUG[22434]: chan_sip.c:3147 sip_alloc: Allocating new SIP dialog for FDD64600-96E1-48B8-8C70-15829AEAE40A@10.10.10.7 - OPTIONS (No RTP) Jun 21 05:11:38 DEBUG[22434]: chan_sip.c:11137 handle_request: **** Received OPTIONS (3) - Command in SIP OPTIONS Looking for s in fromoutside (domain phone2.masterhost.ru) Transmitting (NAT) to 83.237.98.254:62291: SIP/2.0 404 Not Found Via: SIP/2.0/UDP 10.10.10.7;branch=z9hG4bK0a0a0a070000001044989cce00004aa800001117;received=83.237.98.254;rport=62291 From: ;tag=1159718086965 To: ;tag=as72db3c8b Call-ID: FDD64600-96E1-48B8-8C70-15829AEAE40A@10.10.10.7 CSeq: 1862 OPTIONS User-Agent: Asterisk PBX Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY Contact: Accept: application/sdp Content-Length: 0 --- Jun 21 05:11:38 DEBUG[22434]: chan_sip.c:11338 sipsock_read: SIP message could not be handled, bad request: FDD64600-96E1-48B8-8C70-15829AEAE40A@10.10.10.7 Destroying call 'FDD64600-96E1-48B8-8C70-15829AEAE40A@10.10.10.7' Jun 21 05:11:40 DEBUG[22434]: chan_sip.c:1184 retrans_pkt: SIP TIMER: Rescheduling retransmission #192 (5) SIP/2.0 - 1 Jun 21 05:11:40 DEBUG[22434]: chan_sip.c:1198 retrans_pkt: ** SIP timers: Rescheduling retransmission 6 to 4000 ms (t1 500 ms (Retrans id #192)) Retransmitting #5 (NAT) to 83.237.98.254:62291: SIP/2.0 404 Not Found Via: SIP/2.0/UDP 10.10.10.7;branch=z9hG4bK0a0a0a07000001c144989cc30000781a0000110f;received=83.237.98.254;rport=62291 From: "operator name";tag=11595025729485 To: ;tag=as78c50bc3 Call-ID: 25cc17a101808ece7e127e501478ea9c@masterhost.ru CSeq: 4 REFER User-Agent: Asterisk PBX Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY Contact: Accept: application/sdp Content-Length: 0 --- <-- SIP read from 195.14.53.142:5060: OPTIONS sip:phone2.masterhost.ru SIP/2.0 Via: SIP/2.0/UDP 192.168.200.218;rport;branch=z9hG4bKc0a8c8da0000000b44989ca8000034aa00002470 Content-Length: 0 Call-ID: 9E638111-4C41-455C-BD6E-E0832EC4BDE3@192.168.200.218 CSeq: 4654 OPTIONS From: ;tag=1067021871497 Max-Forwards: 70 To: Jun 21 05:11:43 DEBUG[22434]: chan_sip.c:3363 parse_request: Header 0: OPTIONS sip:phone2.masterhost.ru SIP/2.0 (40) Jun 21 05:11:43 DEBUG[22434]: chan_sip.c:3363 parse_request: Header 1: Via: SIP/2.0/UDP 192.168.200.218;rport;branch=z9hG4bKc0a8c8da0000000b44989ca8000034aa00002470 (93) Jun 21 05:11:43 DEBUG[22434]: chan_sip.c:3363 parse_request: Header 2: Content-Length: 0 (17) Jun 21 05:11:43 DEBUG[22434]: chan_sip.c:3363 parse_request: Header 3: Call-ID: 9E638111-4C41-455C-BD6E-E0832EC4BDE3@192.168.200.218 (61) Jun 21 05:11:43 DEBUG[22434]: chan_sip.c:3363 parse_request: Header 4: CSeq: 4654 OPTIONS (18) Jun 21 05:11:43 DEBUG[22434]: chan_sip.c:3363 parse_request: Header 5: From: ;tag=1067021871497 (55) Jun 21 05:11:43 DEBUG[22434]: chan_sip.c:3363 parse_request: Header 6: Max-Forwards: 70 (16) Jun 21 05:11:43 DEBUG[22434]: chan_sip.c:3363 parse_request: Header 7: To: (30) Jun 21 05:11:43 DEBUG[22434]: chan_sip.c:3363 parse_request: Header 8: (0) --- (8 headers 0 lines)--- Jun 21 05:11:43 DEBUG[22434]: chan_sip.c:3147 sip_alloc: Allocating new SIP dialog for 9E638111-4C41-455C-BD6E-E0832EC4BDE3@192.168.200.218 - OPTIONS (No RTP) Jun 21 05:11:43 DEBUG[22434]: chan_sip.c:11137 handle_request: **** Received OPTIONS (3) - Command in SIP OPTIONS Looking for s in fromoutside (domain phone2.masterhost.ru) Transmitting (NAT) to 195.14.53.142:5060: SIP/2.0 404 Not Found Via: SIP/2.0/UDP 192.168.200.218;branch=z9hG4bKc0a8c8da0000000b44989ca8000034aa00002470;received=195.14.53.142;rport=5060 From: ;tag=1067021871497 To: ;tag=as675b6236 Call-ID: 9E638111-4C41-455C-BD6E-E0832EC4BDE3@192.168.200.218 CSeq: 4654 OPTIONS User-Agent: Asterisk PBX Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY Contact: Accept: application/sdp Content-Length: 0 --- Jun 21 05:11:43 DEBUG[22434]: chan_sip.c:11338 sipsock_read: SIP message could not be handled, bad request: 9E638111-4C41-455C-BD6E-E0832EC4BDE3@192.168.200.218 Destroying call '9E638111-4C41-455C-BD6E-E0832EC4BDE3@192.168.200.218' Jun 21 05:11:44 DEBUG[22434]: chan_sip.c:1184 retrans_pkt: SIP TIMER: Rescheduling retransmission #192 (6) SIP/2.0 - 1 Jun 21 05:11:44 DEBUG[22434]: chan_sip.c:1198 retrans_pkt: ** SIP timers: Rescheduling retransmission 7 to 4000 ms (t1 500 ms (Retrans id #192)) Retransmitting #6 (NAT) to 83.237.98.254:62291: SIP/2.0 404 Not Found Via: SIP/2.0/UDP 10.10.10.7;branch=z9hG4bK0a0a0a07000001c144989cc30000781a0000110f;received=83.237.98.254;rport=62291 From: "operator name";tag=11595025729485 To: ;tag=as78c50bc3 Call-ID: 25cc17a101808ece7e127e501478ea9c@masterhost.ru CSeq: 4 REFER User-Agent: Asterisk PBX Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY Contact: Accept: application/sdp Content-Length: 0 --- Jun 21 05:11:48 WARNING[22434]: chan_sip.c:1217 retrans_pkt: Maximum retries exceeded on transmission 25cc17a101808ece7e127e501478ea9c@masterhost.ru for seqno 0 (Non-critical Response) Jun 21 05:11:49 DEBUG[22429]: chan_iax2.c:9354 iax2_devicestate: Checking device state for device iaxmodem01 Jun 21 05:11:49 DEBUG[22429]: chan_iax2.c:9362 iax2_devicestate: iax2_devicestate(iaxmodem01): Found peer. What's device state of iaxmodem01? addr=0, defaddr=0 maxms=0, lastms=0 Jun 21 05:11:49 DEBUG[22429]: devicestate.c:187 do_state_change: Changing state for IAX2/iaxmodem01 - state 5 (Unavailable) Jun 21 05:11:49 DEBUG[22472]: app_queue.c:523 changethread: Device 'IAX2/iaxmodem01' changed to state '5' (Unavailable) but we don't care because they're not a member of any queue. Jun 21 05:11:49 DEBUG[22429]: chan_iax2.c:9354 iax2_devicestate: Checking device state for device iaxmodem01 Jun 21 05:11:49 DEBUG[22429]: chan_iax2.c:9362 iax2_devicestate: iax2_devicestate(iaxmodem01): Found peer. What's device state of iaxmodem01? addr=16777343, defaddr=0 maxms=0, lastms=0 Jun 21 05:11:49 DEBUG[22429]: devicestate.c:187 do_state_change: Changing state for IAX2/iaxmodem01 - state 1 (Not in use) Jun 21 05:11:49 DEBUG[22473]: app_queue.c:523 changethread: Device 'IAX2/iaxmodem01' changed to state '1' (Not in use) but we don't care because they're not a member of any queue. -- Registered IAX2 'iaxmodem01' (AUTHENTICATED) at 127.0.0.1:4571 Jun 21 05:11:49 DEBUG[22429]: chan_iax2.c:9354 iax2_devicestate: Checking device state for device iaxmodem01 Jun 21 05:11:49 DEBUG[22429]: chan_iax2.c:9362 iax2_devicestate: iax2_devicestate(iaxmodem01): Found peer. What's device state of iaxmodem01? addr=16777343, defaddr=0 maxms=0, lastms=0 Jun 21 05:11:49 DEBUG[22429]: devicestate.c:187 do_state_change: Changing state for IAX2/iaxmodem01 - state 1 (Not in use) Jun 21 05:11:49 DEBUG[22474]: app_queue.c:523 changethread: Device 'IAX2/iaxmodem01' changed to state '1' (Not in use) but we don't care because they're not a member of any queue. Jun 21 05:11:52 DEBUG[22429]: chan_iax2.c:9354 iax2_devicestate: Checking device state for device iaxmodem02 Jun 21 05:11:52 DEBUG[22429]: chan_iax2.c:9362 iax2_devicestate: iax2_devicestate(iaxmodem02): Found peer. What's device state of iaxmodem02? addr=0, defaddr=0 maxms=0, lastms=0 Jun 21 05:11:52 DEBUG[22429]: devicestate.c:187 do_state_change: Changing state for IAX2/iaxmodem02 - state 5 (Unavailable) Jun 21 05:11:52 DEBUG[22475]: app_queue.c:523 changethread: Device 'IAX2/iaxmodem02' changed to state '5' (Unavailable) but we don't care because they're not a member of any queue. Jun 21 05:11:52 DEBUG[22429]: chan_iax2.c:9354 iax2_devicestate: Checking device state for device iaxmodem02 Jun 21 05:11:52 DEBUG[22429]: chan_iax2.c:9362 iax2_devicestate: iax2_devicestate(iaxmodem02): Found peer. What's device state of iaxmodem02? addr=16777343, defaddr=0 maxms=0, lastms=0 Jun 21 05:11:52 DEBUG[22429]: devicestate.c:187 do_state_change: Changing state for IAX2/iaxmodem02 - state 1 (Not in use) Jun 21 05:11:52 DEBUG[22476]: app_queue.c:523 changethread: Device 'IAX2/iaxmodem02' changed to state '1' (Not in use) but we don't care because they're not a member of any queue. -- Registered IAX2 'iaxmodem02' (AUTHENTICATED) at 127.0.0.1:4572 Jun 21 05:11:52 DEBUG[22429]: chan_iax2.c:9354 iax2_devicestate: Checking device state for device iaxmodem02 Jun 21 05:11:52 DEBUG[22429]: chan_iax2.c:9362 iax2_devicestate: iax2_devicestate(iaxmodem02): Found peer. What's device state of iaxmodem02? addr=16777343, defaddr=0 maxms=0, lastms=0 Jun 21 05:11:52 DEBUG[22429]: devicestate.c:187 do_state_change: Changing state for IAX2/iaxmodem02 - state 1 (Not in use) Jun 21 05:11:52 DEBUG[22477]: app_queue.c:523 changethread: Device 'IAX2/iaxmodem02' changed to state '1' (Not in use) but we don't care because they're not a member of any queue. <-- SIP read from 83.237.98.254:62291: OPTIONS sip:phone2.masterhost.ru SIP/2.0 Via: SIP/2.0/UDP 10.10.10.7;rport;branch=z9hG4bK0a0a0a070000001044989ce200005def0000111b Content-Length: 0 Call-ID: FDD64600-96E1-48B8-8C70-15829AEAE40A@10.10.10.7 CSeq: 1863 OPTIONS From: ;tag=11599181711208 Max-Forwards: 70 To: Jun 21 05:12:51 DEBUG[22434]: chan_sip.c:3363 parse_request: Header 0: OPTIONS sip:phone2.masterhost.ru SIP/2.0 (40) Jun 21 05:12:51 DEBUG[22434]: chan_sip.c:3363 parse_request: Header 1: Via: SIP/2.0/UDP 10.10.10.7;rport;branch=z9hG4bK0a0a0a070000001044989ce200005def0000111b (88) Jun 21 05:12:51 DEBUG[22434]: chan_sip.c:3363 parse_request: Header 2: Content-Length: 0 (17) Jun 21 05:12:51 DEBUG[22434]: chan_sip.c:3363 parse_request: Header 3: Call-ID: FDD64600-96E1-48B8-8C70-15829AEAE40A@10.10.10.7 (56) Jun 21 05:12:51 DEBUG[22434]: chan_sip.c:3363 parse_request: Header 4: CSeq: 1863 OPTIONS (18) Jun 21 05:12:51 DEBUG[22434]: chan_sip.c:3363 parse_request: Header 5: From: ;tag=11599181711208 (56) Jun 21 05:12:51 DEBUG[22434]: chan_sip.c:3363 parse_request: Header 6: Max-Forwards: 70 (16) Jun 21 05:12:51 DEBUG[22434]: chan_sip.c:3363 parse_request: Header 7: To: (30) Jun 21 05:12:51 DEBUG[22434]: chan_sip.c:3363 parse_request: Header 8: (0) --- (8 headers 0 lines)--- Jun 21 05:12:51 DEBUG[22434]: chan_sip.c:3147 sip_alloc: Allocating new SIP dialog for FDD64600-96E1-48B8-8C70-15829AEAE40A@10.10.10.7 - OPTIONS (No RTP) Jun 21 05:12:51 DEBUG[22434]: chan_sip.c:11137 handle_request: **** Received OPTIONS (3) - Command in SIP OPTIONS Looking for s in fromoutside (domain phone2.masterhost.ru) Transmitting (NAT) to 83.237.98.254:62291: SIP/2.0 404 Not Found Via: SIP/2.0/UDP 10.10.10.7;branch=z9hG4bK0a0a0a070000001044989ce200005def0000111b;received=83.237.98.254;rport=62291 From: ;tag=11599181711208 To: ;tag=as56e41862 Call-ID: FDD64600-96E1-48B8-8C70-15829AEAE40A@10.10.10.7 CSeq: 1863 OPTIONS User-Agent: Asterisk PBX Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY Contact: Accept: application/sdp Content-Length: 0 --- Jun 21 05:12:51 DEBUG[22434]: chan_sip.c:11338 sipsock_read: SIP message could not be handled, bad request: FDD64600-96E1-48B8-8C70-15829AEAE40A@10.10.10.7 Destroying call 'FDD64600-96E1-48B8-8C70-15829AEAE40A@10.10.10.7' <-- SIP read from 195.14.53.142:5060: OPTIONS sip:phone2.masterhost.ru SIP/2.0 Via: SIP/2.0/UDP 192.168.200.218;rport;branch=z9hG4bKc0a8c8da0000000b44989cbc000073ee00002472 Content-Length: 0 Call-ID: 9E638111-4C41-455C-BD6E-E0832EC4BDE3@192.168.200.218 CSeq: 4655 OPTIONS From: ;tag=106722187187 Max-Forwards: 70 To: Jun 21 05:12:51 DEBUG[22434]: chan_sip.c:3363 parse_request: Header 0: OPTIONS sip:phone2.masterhost.ru SIP/2.0 (40) Jun 21 05:12:51 DEBUG[22434]: chan_sip.c:3363 parse_request: Header 1: Via: SIP/2.0/UDP 192.168.200.218;rport;branch=z9hG4bKc0a8c8da0000000b44989cbc000073ee00002472 (93) Jun 21 05:12:51 DEBUG[22434]: chan_sip.c:3363 parse_request: Header 2: Content-Length: 0 (17) Jun 21 05:12:51 DEBUG[22434]: chan_sip.c:3363 parse_request: Header 3: Call-ID: 9E638111-4C41-455C-BD6E-E0832EC4BDE3@192.168.200.218 (61) Jun 21 05:12:51 DEBUG[22434]: chan_sip.c:3363 parse_request: Header 4: CSeq: 4655 OPTIONS (18) Jun 21 05:12:51 DEBUG[22434]: chan_sip.c:3363 parse_request: Header 5: From: ;tag=106722187187 (54) Jun 21 05:12:51 DEBUG[22434]: chan_sip.c:3363 parse_request: Header 6: Max-Forwards: 70 (16) Jun 21 05:12:51 DEBUG[22434]: chan_sip.c:3363 parse_request: Header 7: To: (30) Jun 21 05:12:51 DEBUG[22434]: chan_sip.c:3363 parse_request: Header 8: (0) --- (8 headers 0 lines)--- Jun 21 05:12:51 DEBUG[22434]: chan_sip.c:3147 sip_alloc: Allocating new SIP dialog for 9E638111-4C41-455C-BD6E-E0832EC4BDE3@192.168.200.218 - OPTIONS (No RTP) Jun 21 05:12:51 DEBUG[22434]: chan_sip.c:11137 handle_request: **** Received OPTIONS (3) - Command in SIP OPTIONS Looking for s in fromoutside (domain phone2.masterhost.ru) Transmitting (NAT) to 195.14.53.142:5060: SIP/2.0 404 Not Found Via: SIP/2.0/UDP 192.168.200.218;branch=z9hG4bKc0a8c8da0000000b44989cbc000073ee00002472;received=195.14.53.142;rport=5060 From: ;tag=106722187187 To: ;tag=as10375a5b Call-ID: 9E638111-4C41-455C-BD6E-E0832EC4BDE3@192.168.200.218 CSeq: 4655 OPTIONS User-Agent: Asterisk PBX Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY Contact: Accept: application/sdp Content-Length: 0 --- Jun 21 05:12:51 DEBUG[22434]: chan_sip.c:11338 sipsock_read: SIP message could not be handled, bad request: 9E638111-4C41-455C-BD6E-E0832EC4BDE3@192.168.200.218 Destroying call '9E638111-4C41-455C-BD6E-E0832EC4BDE3@192.168.200.218' <-- SIP read from 83.237.98.254:62291: OPTIONS sip:phone2.masterhost.ru SIP/2.0 Via: SIP/2.0/UDP 10.10.10.7;rport;branch=z9hG4bK0a0a0a070000001044989cf600002c430000111c Content-Length: 0 Call-ID: FDD64600-96E1-48B8-8C70-15829AEAE40A@10.10.10.7 CSeq: 1864 OPTIONS From: ;tag=1160118366933 Max-Forwards: 70 To: Jun 21 05:12:51 DEBUG[22434]: chan_sip.c:3363 parse_request: Header 0: OPTIONS sip:phone2.masterhost.ru SIP/2.0 (40) Jun 21 05:12:51 DEBUG[22434]: chan_sip.c:3363 parse_request: Header 1: Via: SIP/2.0/UDP 10.10.10.7;rport;branch=z9hG4bK0a0a0a070000001044989cf600002c430000111c (88) Jun 21 05:12:51 DEBUG[22434]: chan_sip.c:3363 parse_request: Header 2: Content-Length: 0 (17) Jun 21 05:12:51 DEBUG[22434]: chan_sip.c:3363 parse_request: Header 3: Call-ID: FDD64600-96E1-48B8-8C70-15829AEAE40A@10.10.10.7 (56) Jun 21 05:12:51 DEBUG[22434]: chan_sip.c:3363 parse_request: Header 4: CSeq: 1864 OPTIONS (18) Jun 21 05:12:51 DEBUG[22434]: chan_sip.c:3363 parse_request: Header 5: From: ;tag=1160118366933 (55) Jun 21 05:12:51 DEBUG[22434]: chan_sip.c:3363 parse_request: Header 6: Max-Forwards: 70 (16) Jun 21 05:12:51 DEBUG[22434]: chan_sip.c:3363 parse_request: Header 7: To: (30) Jun 21 05:12:51 DEBUG[22434]: chan_sip.c:3363 parse_request: Header 8: (0) --- (8 headers 0 lines)--- Jun 21 05:12:51 DEBUG[22434]: chan_sip.c:3147 sip_alloc: Allocating new SIP dialog for FDD64600-96E1-48B8-8C70-15829AEAE40A@10.10.10.7 - OPTIONS (No RTP) Jun 21 05:12:51 DEBUG[22434]: chan_sip.c:11137 handle_request: **** Received OPTIONS (3) - Command in SIP OPTIONS Looking for s in fromoutside (domain phone2.masterhost.ru) Transmitting (NAT) to 83.237.98.254:62291: SIP/2.0 404 Not Found Via: SIP/2.0/UDP 10.10.10.7;branch=z9hG4bK0a0a0a070000001044989cf600002c430000111c;received=83.237.98.254;rport=62291 From: ;tag=1160118366933 To: ;tag=as56173ff2 Call-ID: FDD64600-96E1-48B8-8C70-15829AEAE40A@10.10.10.7 CSeq: 1864 OPTIONS User-Agent: Asterisk PBX Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY Contact: Accept: application/sdp Content-Length: 0 --- Jun 21 05:12:51 DEBUG[22434]: chan_sip.c:11338 sipsock_read: SIP message could not be handled, bad request: FDD64600-96E1-48B8-8C70-15829AEAE40A@10.10.10.7 Destroying call 'FDD64600-96E1-48B8-8C70-15829AEAE40A@10.10.10.7' <-- SIP read from 195.14.53.142:5060: OPTIONS sip:phone2.masterhost.ru SIP/2.0 Via: SIP/2.0/UDP 192.168.200.218;rport;branch=z9hG4bKc0a8c8da0000000b44989cd000001c9700002473 Content-Length: 0 Call-ID: 9E638111-4C41-455C-BD6E-E0832EC4BDE3@192.168.200.218 CSeq: 4656 OPTIONS From: ;tag=10674218712627 Max-Forwards: 70 To: Jun 21 05:12:51 DEBUG[22434]: chan_sip.c:3363 parse_request: Header 0: OPTIONS sip:phone2.masterhost.ru SIP/2.0 (40) Jun 21 05:12:51 DEBUG[22434]: chan_sip.c:3363 parse_request: Header 1: Via: SIP/2.0/UDP 192.168.200.218;rport;branch=z9hG4bKc0a8c8da0000000b44989cd000001c9700002473 (93) Jun 21 05:12:51 DEBUG[22434]: chan_sip.c:3363 parse_request: Header 2: Content-Length: 0 (17) Jun 21 05:12:51 DEBUG[22434]: chan_sip.c:3363 parse_request: Header 3: Call-ID: 9E638111-4C41-455C-BD6E-E0832EC4BDE3@192.168.200.218 (61) Jun 21 05:12:51 DEBUG[22434]: chan_sip.c:3363 parse_request: Header 4: CSeq: 4656 OPTIONS (18) Jun 21 05:12:51 DEBUG[22434]: chan_sip.c:3363 parse_request: Header 5: From: ;tag=10674218712627 (56) Jun 21 05:12:51 DEBUG[22434]: chan_sip.c:3363 parse_request: Header 6: Max-Forwards: 70 (16) Jun 21 05:12:51 DEBUG[22434]: chan_sip.c:3363 parse_request: Header 7: To: (30) Jun 21 05:12:51 DEBUG[22434]: chan_sip.c:3363 parse_request: Header 8: (0) --- (8 headers 0 lines)--- Jun 21 05:12:51 DEBUG[22434]: chan_sip.c:3147 sip_alloc: Allocating new SIP dialog for 9E638111-4C41-455C-BD6E-E0832EC4BDE3@192.168.200.218 - OPTIONS (No RTP) Jun 21 05:12:51 DEBUG[22434]: chan_sip.c:11137 handle_request: **** Received OPTIONS (3) - Command in SIP OPTIONS Looking for s in fromoutside (domain phone2.masterhost.ru) Transmitting (NAT) to 195.14.53.142:5060: SIP/2.0 404 Not Found Via: SIP/2.0/UDP 192.168.200.218;branch=z9hG4bKc0a8c8da0000000b44989cd000001c9700002473;received=195.14.53.142;rport=5060 From: ;tag=10674218712627 To: ;tag=as3a97b65e Call-ID: 9E638111-4C41-455C-BD6E-E0832EC4BDE3@192.168.200.218 CSeq: 4656 OPTIONS User-Agent: Asterisk PBX Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY Contact: Accept: application/sdp Content-Length: 0 --- == Primary D-Channel on span 2 up == Primary D-Channel on span 2 up == Primary D-Channel on span 2 up Jun 21 05:12:51 NOTICE[22438]: chan_zap.c:8207 pri_dchannel: PRI got event: HDLC Abort (6) on Primary D-channel of span 2 Jun 21 05:12:51 DEBUG[22438]: chan_zap.c:8218 pri_dchannel: Got event HDLC Abort (6) on D-channel for span 2 == Primary D-Channel on span 2 up == Primary D-Channel on span 2 up == Primary D-Channel on span 2 up == Primary D-Channel on span 2 up == Primary D-Channel on span 2 up == Primary D-Channel on span 2 up == Primary D-Channel on span 2 up == Primary D-Channel on span 2 up == Primary D-Channel on span 2 up == Primary D-Channel on span 2 up == Primary D-Channel on span 2 up == Primary D-Channel on span 2 up == Primary D-Channel on span 2 up == Primary D-Channel on span 2 up == Primary D-Channel on span 2 up == Primary D-Channel on span 2 up == Primary D-Channel on span 2 up == Primary D-Channel on span 2 down Jun 21 05:12:54 WARNING[22438]: chan_zap.c:2289 pri_find_dchan: No D-channels available! Using Primary channel 47 as D-channel anyway! == Primary D-Channel on span 2 up ACK received for '1' outside of window of '0' to '0', restarting == Primary D-Channel on span 2 down Jun 21 05:12:54 WARNING[22438]: chan_zap.c:2289 pri_find_dchan: No D-channels available! Using Primary channel 47 as D-channel anyway! !! Got I-frame while link state 2 !! Got S-frame while link down == Primary D-Channel on span 2 up sip no debug phone2*CLI> SIP Debugging Disabled Jun 21 05:12:58 DEBUG[22434]: chan_sip.c:3147 sip_alloc: Allocating new SIP dialog for FDD64600-96E1-48B8-8C70-15829AEAE40A@10.10.10.7 - OPTIONS (No RTP) Jun 21 05:12:58 DEBUG[22434]: chan_sip.c:11137 handle_request: **** Received OPTIONS (3) - Command in SIP OPTIONS Jun 21 05:12:58 DEBUG[22434]: chan_sip.c:11338 sipsock_read: SIP message could not be handled, bad request: FDD64600-96E1-48B8-8C70-15829AEAE40A@10.10.10.7 seJun 21 05:13:00 DEBUG[22434]: chan_sip.c:3147 sip_alloc: Allocating new SIP dialog for 8626FC19-C40F-4D27-A73A-EED6B7F91A52@10.10.11.134 - OPTIONS (No RTP) seJun 21 05:13:00 DEBUG[22434]: chan_sip.c:11137 handle_request: **** Received OPTIONS (3) - Command in SIP OPTIONS seJun 21 05:13:00 DEBUG[22434]: chan_sip.c:11338 sipsock_read: SIP message could not be handled, bad request: 8626FC19-C40F-4D27-A73A-EED6B7F91A52@10.10.11.134 set debug 0 phone2*CLI> Core debug is now OFF setJun 21 05:13:03 DEBUG[22434]: chan_sip.c:11338 sipsock_read: SIP message could not be handled, bad request: 9E638111-4C41-455C-BD6E-E0832EC4BDE3@192.168.200.218 set verbose -- Saved useragent "Cisco-CP7912/8.0.0-060111A" for peer 1642 set verbose 0 phone2*CLI> Verbosity is now OFF show channels phone2*CLI> Channel Location State Application(Data) 0 active channels 1 active call Jun 21 05:13:11 WARNING[22443]: channel.c:787 channel_find_locked: Avoided initial deadlock for '0x8222528', 10 retries! show queues phone2*CLI> operatorq has 0 calls (max unlimited) in 'ringall' strategy (0s holdtime), W:0, C:0, A:0, SL:0.0% within 0s No Members No Callers callcenterq has 0 calls (max unlimited) in 'ringall' strategy (0s holdtime), W:0, C:0, A:0, SL:0.0% within 0s Members: Local/1211@toagent (dynamic) (In use) has taken no calls yet No Callers phone2*CLI> stop now phone2*CLI> quit