[Apr 28 12:20:43] DEBUG[18162] rtp.c: Got RTCP report of 52 bytes
[Apr 28 12:20:43] DEBUG[18162] rtp.c: Got RTCP report of 52 bytes
[Apr 28 12:20:48] DEBUG[18162] rtp.c: Got RTCP report of 52 bytes
[Apr 28 12:20:48] DEBUG[18162] rtp.c: Got RTCP report of 52 bytes
[Apr 28 12:20:53] DEBUG[18162] rtp.c: Got RTCP report of 52 bytes
[Apr 28 12:20:53] DEBUG[18162] rtp.c: Got RTCP report of 60 bytes
[Apr 28 12:20:53] DEBUG[8169] chan_sip.c: Setting SIP_ALREADYGONE on dialog 62b15b1701c9a2141b24358a5cde62ea@192.168.121.2
[Apr 28 12:20:53] DEBUG[8169] chan_sip.c: Received bye, issuing owner hangup
[Apr 28 12:20:53] DEBUG[8169] chan_sip.c: Trying to put 'SIP/2.0 20' onto UDP socket destined for 192.168.121.4:5060
[Apr 28 12:20:53] DEBUG[18162] channel.c: Didn't get a frame from channel: SIP/TRUNK_DLINK-b7a42348
[Apr 28 12:20:53] DEBUG[18162] channel.c: Bridge stops bridging channels SIP/01201-b7a3e8f0 and SIP/TRUNK_DLINK-b7a42348
[Apr 28 12:20:53] DEBUG[18162] channel.c: Hanging up channel 'SIP/TRUNK_DLINK-b7a42348'
[Apr 28 12:20:53] DEBUG[18162] chan_sip.c: Hangup call SIP/TRUNK_DLINK-b7a42348, SIP callid 62b15b1701c9a2141b24358a5cde62ea@192.168.121.2
[Apr 28 12:20:53] DEBUG[18162] rtp.c: Channel '<unspecified>' has no RTP, not doing anything
[Apr 28 12:20:53] DEBUG[8152] chan_sip.c: Checking device state for peer TRUNK_DLINK
[Apr 28 12:20:53] DEBUG[18162] app_dial.c: Exiting with DIALSTATUS=ANSWER.
[Apr 28 12:20:53] DEBUG[8152] devicestate.c: Changing state for SIP/TRUNK_DLINK - state 1 (Not in use)
[Apr 28 12:20:53] DEBUG[8152] devicestate.c: device 'SIP/TRUNK_DLINK' state '1'
[Apr 28 12:20:53] DEBUG[18162] app_macro.c: Spawn extension (macro-Moutdial,s,2) exited non-zero on 'SIP/01201-b7a3e8f0' in macro 'Moutdial'
[Apr 28 12:20:53] DEBUG[8176] app_queue.c: Device 'SIP/TRUNK_DLINK' changed to state '1' (Not in use) but we don't care because they're not a member of any queue.
[Apr 28 12:20:53] DEBUG[18162] pbx.c: Spawn extension (officeSU,89242830732,2) exited non-zero on 'SIP/01201-b7a3e8f0'
[Apr 28 12:20:53] DEBUG[18162] channel.c: Soft-Hanging up channel 'SIP/01201-b7a3e8f0'
[Apr 28 12:20:53] DEBUG[18162] channel.c: Hanging up channel 'SIP/01201-b7a3e8f0'
[Apr 28 12:20:53] DEBUG[18162] chan_sip.c: Hangup call SIP/01201-b7a3e8f0, SIP callid D1B9-8A15-4668534586B7D59E6023-012@SipHost
[Apr 28 12:20:53] DEBUG[18162] chan_sip.c: Trying to put 'BYE sip:01' onto UDP socket destined for 192.168.121.4:5060
[Apr 28 12:20:53] DEBUG[8152] chan_sip.c: Checking device state for peer 01201
[Apr 28 12:20:53] DEBUG[8152] devicestate.c: Changing state for SIP/01201 - state 1 (Not in use)
[Apr 28 12:20:53] DEBUG[8152] devicestate.c: device 'SIP/01201' state '1'
[Apr 28 12:20:53] DEBUG[8176] app_queue.c: Device 'SIP/01201' changed to state '1' (Not in use) but we don't care because they're not a member of any queue.
[Apr 28 12:20:54] DEBUG[8169] chan_sip.c: Stopping retransmission on 'D1B9-8A15-4668534586B7D59E6023-012@SipHost' of Request 102: Match Found
[Apr 28 12:20:54] DEBUG[8169] chan_sip.c: Destroying SIP dialog 62b15b1701c9a2141b24358a5cde62ea@192.168.121.2
[Apr 28 12:20:54] DEBUG[8169] chan_sip.c: Destroying SIP dialog D1B9-8A15-4668534586B7D59E6023-012@SipHost
[Apr 28 12:21:04] DEBUG[8169] acl.c: Found IP address for this socket
[Apr 28 12:21:04] DEBUG[8169] chan_sip.c: Setting NAT on RTP to Off
[Apr 28 12:21:04] DEBUG[8169] chan_sip.c: Allocating new SIP dialog for D1B9-8A15-46685387C88F38D48A8C-013@SipHost - INVITE (With RTP)
[Apr 28 12:21:04] DEBUG[8169] chan_sip.c: Setting NAT on RTP to Off
[Apr 28 12:21:04] DEBUG[8169] chan_sip.c: Trying to put 'SIP/2.0 40' onto UDP socket destined for 192.168.121.4:5060
[Apr 28 12:21:04] DEBUG[8169] chan_sip.c: Stopping retransmission on 'D1B9-8A15-46685387C88F38D48A8C-013@SipHost' of Response 14: Match Found
[Apr 28 12:21:04] DEBUG[8169] chan_sip.c: Setting NAT on RTP to Off
[Apr 28 12:21:04] DEBUG[8169] chan_sip.c: We're settling with these formats: 0x8 (alaw)
[Apr 28 12:21:04] DEBUG[8169] chan_sip.c: Checking SIP call limits for device 01201
[Apr 28 12:21:04] DEBUG[8169] chan_sip.c: Updating call counter for incoming call
[Apr 28 12:21:04] DEBUG[8169] chan_sip.c: *** Our native formats are 0x8 (alaw)
[Apr 28 12:21:04] DEBUG[8169] chan_sip.c: *** Joint capabilities are 0x8 (alaw)
[Apr 28 12:21:04] DEBUG[8169] chan_sip.c: *** Our capabilities are 0x8 (alaw)
[Apr 28 12:21:04] DEBUG[8169] chan_sip.c: *** AST_CODEC_CHOOSE formats are 0x8 (alaw)
[Apr 28 12:21:04] DEBUG[8169] chan_sip.c: This channel will not be able to handle video.
[Apr 28 12:21:04] DEBUG[8169] chan_sip.c: build_route: Contact hop: <sip:01201@192.168.121.4:5060>
[Apr 28 12:21:04] DEBUG[8169] chan_sip.c: SIP/01201-b7a3e8f0: New call is still down.... Trying...
[Apr 28 12:21:04] DEBUG[8169] chan_sip.c: Trying to put 'SIP/2.0 10' onto UDP socket destined for 192.168.121.4:5060
[Apr 28 12:21:04] DEBUG[8152] chan_sip.c: Checking device state for peer 01201
[Apr 28 12:21:04] DEBUG[8152] devicestate.c: Changing state for SIP/01201 - state 1 (Not in use)
[Apr 28 12:21:04] DEBUG[8152] devicestate.c: device 'SIP/01201' state '1'
[Apr 28 12:21:04] DEBUG[8176] app_queue.c: Device 'SIP/01201' changed to state '1' (Not in use) but we don't care because they're not a member of any queue.
[Apr 28 12:21:04] DEBUG[19474] pbx.c: Function result is '01201'
[Apr 28 12:21:04] DEBUG[19474] pbx.c: Launching 'Set'
[Apr 28 12:21:04] DEBUG[19474] pbx.c: Launching 'Macro'
[Apr 28 12:21:04] DEBUG[19474] pbx.c: Launching 'NoOp'
[Apr 28 12:21:04] DEBUG[19474] app_macro.c: Executed application: NoOp
[Apr 28 12:21:04] DEBUG[19474] pbx.c: Launching 'Dial'
[Apr 28 12:21:04] DEBUG[19474] chan_sip.c: Asked to create a SIP channel with formats: 0x8 (alaw)
[Apr 28 12:21:04] DEBUG[19474] chan_sip.c: Allocating new SIP dialog for 7f1111524be303291e6b02f07830f872@89.188.251.130 - INVITE (With RTP)
[Apr 28 12:21:04] DEBUG[19474] chan_sip.c: Setting NAT on RTP to Off
[Apr 28 12:21:04] DEBUG[19474] chan_sip.c: Setting NAT on UDPTL to Off
[Apr 28 12:21:04] DEBUG[19474] acl.c: Found IP address for this socket
[Apr 28 12:21:04] DEBUG[19474] chan_sip.c: *** Our native formats are 0x8 (alaw)
[Apr 28 12:21:04] DEBUG[19474] chan_sip.c: *** Joint capabilities are 0x8 (alaw)
[Apr 28 12:21:04] DEBUG[19474] chan_sip.c: *** Our capabilities are 0x8 (alaw)
[Apr 28 12:21:04] DEBUG[19474] chan_sip.c: *** AST_CODEC_CHOOSE formats are 0x8 (alaw)
[Apr 28 12:21:04] DEBUG[19474] chan_sip.c: *** Our preferred formats from the incoming channel are 0x8 (alaw)
[Apr 28 12:21:04] DEBUG[19474] chan_sip.c: This channel will not be able to handle video.
[Apr 28 12:21:04] DEBUG[19474] channel.c: Not copying variable DIALEDTIME.
[Apr 28 12:21:04] DEBUG[19474] channel.c: Not copying variable ANSWEREDTIME.
[Apr 28 12:21:04] DEBUG[19474] channel.c: Not copying variable DIALEDPEERNAME.
[Apr 28 12:21:04] DEBUG[19474] channel.c: Not copying variable DIALEDPEERNUMBER.
[Apr 28 12:21:04] DEBUG[19474] channel.c: Not copying variable DIALSTATUS.
[Apr 28 12:21:04] DEBUG[19474] channel.c: Not copying variable MACRO_DEPTH.
[Apr 28 12:21:04] DEBUG[19474] channel.c: Not copying variable ARG1.
[Apr 28 12:21:04] DEBUG[19474] channel.c: Not copying variable MACRO_PRIORITY.
[Apr 28 12:21:04] DEBUG[19474] channel.c: Not copying variable MACRO_CONTEXT.
[Apr 28 12:21:04] DEBUG[19474] channel.c: Not copying variable MACRO_EXTEN.
[Apr 28 12:21:04] DEBUG[19474] channel.c: Not copying variable SAVE_ID.
[Apr 28 12:21:04] DEBUG[19474] channel.c: Not copying variable SIPCALLID.
[Apr 28 12:21:04] DEBUG[19474] channel.c: Not copying variable SIPDOMAIN.
[Apr 28 12:21:04] DEBUG[19474] channel.c: Not copying variable SIPURI.
[Apr 28 12:21:04] DEBUG[19474] chan_sip.c: Outgoing Call for 4242464654
[Apr 28 12:21:04] DEBUG[19474] chan_sip.c: Updating call counter for outgoing call
[Apr 28 12:21:04] DEBUG[19474] chan_sip.c: Our T38 capability (16160), joint T38 capability (16160)
[Apr 28 12:21:04] DEBUG[19474] chan_sip.c: ** Our capability: 0x8 (alaw) Video flag: False Text flag: False
[Apr 28 12:21:04] DEBUG[19474] chan_sip.c: ** Our prefcodec: 0x8 (alaw)
[Apr 28 12:21:04] DEBUG[19474] chan_sip.c: -- Done with adding codecs to SDP
[Apr 28 12:21:04] DEBUG[19474] chan_sip.c: Done building SDP. Settling with this capability: 0x8 (alaw)
[Apr 28 12:21:04] DEBUG[19474] chan_sip.c: Initializing initreq for method INVITE - callid 6a342f455993c0c27eeb82632054e400@192.168.121.2
[Apr 28 12:21:04] DEBUG[19474] chan_sip.c: Trying to put 'INVITE sip' onto UDP socket destined for 192.168.121.4:5060
[Apr 28 12:21:04] DEBUG[19474] channel.c: Prodding channel 'SIP/01201-b7a3e8f0'
[Apr 28 12:21:04] DEBUG[19474] chan_sip.c: Setting framing from config on incoming call
[Apr 28 12:21:04] DEBUG[19474] chan_sip.c: ** Our capability: 0x8 (alaw) Video flag: True Text flag: True
[Apr 28 12:21:04] DEBUG[19474] chan_sip.c: ** Our prefcodec: 0x0 (nothing)
[Apr 28 12:21:04] DEBUG[19474] chan_sip.c: -- Done with adding codecs to SDP
[Apr 28 12:21:04] DEBUG[19474] chan_sip.c: Done building SDP. Settling with this capability: 0x8 (alaw)
[Apr 28 12:21:04] DEBUG[19474] chan_sip.c: Trying to put 'SIP/2.0 18' onto UDP socket destined for 192.168.121.4:5060
[Apr 28 12:21:04] DEBUG[19474] channel.c: Scheduling timer at (50 requested / 50 actual) timer ticks per second
[Apr 28 12:21:04] DEBUG[19474] channel.c: Set channel SIP/01201-b7a3e8f0 to write format slin
[Apr 28 12:21:04] DEBUG[19474] res_musiconhold.c: SIP/01201-b7a3e8f0 Opened file 1 '/var/lib/asterisk/moh/macroform-robot_dity'
[Apr 28 12:21:04] DEBUG[19474] rtp.c: Ooh, format changed from unknown to alaw
[Apr 28 12:21:04] DEBUG[19474] rtp.c: Created smoother: format: 8 ms: 20 len: 160
[Apr 28 12:21:04] DEBUG[8169] chan_sip.c: (Provisional) Stopping retransmission (but retaining packet) on '6a342f455993c0c27eeb82632054e400@192.168.121.2' Request 102: Found
[Apr 28 12:21:05] DEBUG[19474] channel.c: Generator got voice, switching to phase locked mode
[Apr 28 12:21:05] DEBUG[19474] channel.c: Scheduling timer at (0 requested / 0 actual) timer ticks per second
[Apr 28 12:21:05] DEBUG[8169] chan_sip.c: Acked pending invite 102
[Apr 28 12:21:05] DEBUG[8169] chan_sip.c: Stopping retransmission on '6a342f455993c0c27eeb82632054e400@192.168.121.2' of Request 102: Match Found
[Apr 28 12:21:05] DEBUG[8169] chan_sip.c: We're settling with these formats: 0x8 (alaw)
[Apr 28 12:21:05] DEBUG[8169] chan_sip.c: Updating call counter for outgoing call
[Apr 28 12:21:05] DEBUG[8169] chan_sip.c: build_route: Contact hop: <sip:4242464654@192.168.121.4:5060>
[Apr 28 12:21:05] DEBUG[8169] chan_sip.c: Trying to put 'ACK sip:42' onto UDP socket destined for 192.168.121.4:5060
[Apr 28 12:21:05] DEBUG[8152] chan_sip.c: Checking device state for peer TRUNK_DLINK
[Apr 28 12:21:05] DEBUG[19474] pbx.c: Launching 'Wait'
[Apr 28 12:21:05] DEBUG[8152] devicestate.c: Changing state for SIP/TRUNK_DLINK - state 1 (Not in use)
[Apr 28 12:21:05] DEBUG[8152] devicestate.c: device 'SIP/TRUNK_DLINK' state '1'
[Apr 28 12:21:05] DEBUG[8176] app_queue.c: Device 'SIP/TRUNK_DLINK' changed to state '1' (Not in use) but we don't care because they're not a member of any queue.
[Apr 28 12:21:07] DEBUG[19474] app_macro.c: Executed application: Wait
[Apr 28 12:21:07] DEBUG[19474] pbx.c: Launching 'SIPDtmfMode'
[Apr 28 12:21:07] DEBUG[19474] dsp.c: Setup tone 1100 Hz, 500 ms, block_size=160, hits_required=21
[Apr 28 12:21:07] DEBUG[19474] dsp.c: Setup tone 2100 Hz, 2600 ms, block_size=160, hits_required=116
[Apr 28 12:21:07] DEBUG[19474] app_macro.c: Executed application: SIPDtmfMode
[Apr 28 12:21:07] DEBUG[19474] pbx.c: Launching 'SendDTMF'
[Apr 28 12:21:07] DEBUG[19474] channel.c: Set channel SIP/TRUNK_DLINK-08219288 to write format slin
[Apr 28 12:21:07] DEBUG[19474] channel.c: Scheduling timer at (50 requested / 50 actual) timer ticks per second
[Apr 28 12:21:07] DEBUG[19474] channel.c: Generator got voice, switching to phase locked mode
[Apr 28 12:21:07] DEBUG[19474] channel.c: Scheduling timer at (0 requested / 0 actual) timer ticks per second
[Apr 28 12:21:07] DEBUG[19474] rtp.c: Ooh, format changed from unknown to alaw
[Apr 28 12:21:07] DEBUG[19474] rtp.c: Created smoother: format: 8 ms: 20 len: 160
[Apr 28 12:21:07] DEBUG[19474] channel.c: Set channel SIP/TRUNK_DLINK-08219288 to write format alaw
[Apr 28 12:21:07] DEBUG[19474] channel.c: Scheduling timer at (0 requested / 0 actual) timer ticks per second
[Apr 28 12:21:07] DEBUG[19474] channel.c: Set channel SIP/TRUNK_DLINK-08219288 to write format slin
[Apr 28 12:21:07] DEBUG[19474] channel.c: Scheduling timer at (50 requested / 50 actual) timer ticks per second
[Apr 28 12:21:07] DEBUG[19474] channel.c: Generator got voice, switching to phase locked mode
[Apr 28 12:21:07] DEBUG[19474] channel.c: Scheduling timer at (0 requested / 0 actual) timer ticks per second
[Apr 28 12:21:07] DEBUG[19474] rtp.c: Difference is 1592, ms is 219
[Apr 28 12:21:07] DEBUG[19474] channel.c: Set channel SIP/TRUNK_DLINK-08219288 to write format alaw
[Apr 28 12:21:07] DEBUG[19474] channel.c: Scheduling timer at (0 requested / 0 actual) timer ticks per second
[Apr 28 12:21:07] DEBUG[19474] channel.c: Set channel SIP/TRUNK_DLINK-08219288 to write format slin
[Apr 28 12:21:07] DEBUG[19474] channel.c: Scheduling timer at (50 requested / 50 actual) timer ticks per second
[Apr 28 12:21:08] DEBUG[19474] channel.c: Generator got voice, switching to phase locked mode
[Apr 28 12:21:08] DEBUG[19474] channel.c: Scheduling timer at (0 requested / 0 actual) timer ticks per second
[Apr 28 12:21:08] DEBUG[19474] rtp.c: Difference is 1752, ms is 239
[Apr 28 12:21:08] DEBUG[19474] rtp.c: - RTP 2833 Event: 00000002 (len = 4)
[Apr 28 12:21:08] DEBUG[19474] rtp.c: Sending dtmf: 50 (2), at 192.168.121.4
[Apr 28 12:21:08] DEBUG[19474] rtp.c: - RTP 2833 Event: 00000002 (len = 4)
[Apr 28 12:21:08] DEBUG[19474] rtp.c: - RTP 2833 Event: 00000002 (len = 4)
[Apr 28 12:21:08] DEBUG[19474] rtp.c: - RTP 2833 Event: 00000002 (len = 4)
[Apr 28 12:21:08] DEBUG[19474] channel.c: Set channel SIP/TRUNK_DLINK-08219288 to write format alaw
[Apr 28 12:21:08] DEBUG[19474] channel.c: Scheduling timer at (0 requested / 0 actual) timer ticks per second
[Apr 28 12:21:08] DEBUG[19474] rtp.c: - RTP 2833 Event: 00000002 (len = 4)
[Apr 28 12:21:08] DEBUG[19474] rtp.c: - RTP 2833 Event: 00000002 (len = 4)
[Apr 28 12:21:08] DEBUG[19474] rtp.c: - RTP 2833 Event: 00000002 (len = 4)
[Apr 28 12:21:08] DEBUG[19474] rtp.c: - RTP 2833 Event: 00000002 (len = 4)
[Apr 28 12:21:08] DEBUG[19474] rtp.c: - RTP 2833 Event: 00000002 (len = 4)
[Apr 28 12:21:08] DEBUG[19474] rtp.c: Sending dtmf: 50 (2), at 192.168.121.4
[Apr 28 12:21:08] DEBUG[19474] rtp.c: - RTP 2833 Event: 00000002 (len = 4)
[Apr 28 12:21:08] DEBUG[19474] rtp.c: - RTP 2833 Event: 00000002 (len = 4)
[Apr 28 12:21:08] DEBUG[19474] channel.c: Set channel SIP/TRUNK_DLINK-08219288 to write format slin
[Apr 28 12:21:08] DEBUG[19474] channel.c: Scheduling timer at (50 requested / 50 actual) timer ticks per second
[Apr 28 12:21:08] DEBUG[19474] rtp.c: Difference is 2016, ms is 272
[Apr 28 12:21:08] DEBUG[19474] channel.c: Set channel SIP/TRUNK_DLINK-08219288 to write format alaw
[Apr 28 12:21:08] DEBUG[19474] channel.c: Scheduling timer at (0 requested / 0 actual) timer ticks per second
[Apr 28 12:21:08] DEBUG[19474] channel.c: Set channel SIP/TRUNK_DLINK-08219288 to write format slin
[Apr 28 12:21:08] DEBUG[19474] channel.c: Scheduling timer at (50 requested / 50 actual) timer ticks per second
[Apr 28 12:21:08] DEBUG[19474] rtp.c: Difference is 1760, ms is 240
[Apr 28 12:21:08] DEBUG[19474] channel.c: Set channel SIP/TRUNK_DLINK-08219288 to write format alaw
[Apr 28 12:21:08] DEBUG[19474] channel.c: Scheduling timer at (0 requested / 0 actual) timer ticks per second
[Apr 28 12:21:08] DEBUG[19474] channel.c: Set channel SIP/TRUNK_DLINK-08219288 to write format slin
[Apr 28 12:21:08] DEBUG[19474] channel.c: Scheduling timer at (50 requested / 50 actual) timer ticks per second
[Apr 28 12:21:08] DEBUG[19474] rtp.c: Difference is 1824, ms is 248
[Apr 28 12:21:09] DEBUG[19474] channel.c: Set channel SIP/TRUNK_DLINK-08219288 to write format alaw
[Apr 28 12:21:09] DEBUG[19474] channel.c: Scheduling timer at (0 requested / 0 actual) timer ticks per second
[Apr 28 12:21:09] DEBUG[19474] channel.c: Set channel SIP/TRUNK_DLINK-08219288 to write format slin
[Apr 28 12:21:09] DEBUG[19474] channel.c: Scheduling timer at (50 requested / 50 actual) timer ticks per second
[Apr 28 12:21:09] DEBUG[19474] rtp.c: Difference is 1760, ms is 240
[Apr 28 12:21:09] DEBUG[19474] channel.c: Set channel SIP/TRUNK_DLINK-08219288 to write format alaw
[Apr 28 12:21:09] DEBUG[19474] channel.c: Scheduling timer at (0 requested / 0 actual) timer ticks per second
[Apr 28 12:21:09] DEBUG[19474] channel.c: Set channel SIP/TRUNK_DLINK-08219288 to write format slin
[Apr 28 12:21:09] DEBUG[19474] channel.c: Scheduling timer at (50 requested / 50 actual) timer ticks per second
[Apr 28 12:21:09] DEBUG[19474] rtp.c: Difference is 1760, ms is 240
[Apr 28 12:21:09] DEBUG[19474] channel.c: Set channel SIP/TRUNK_DLINK-08219288 to write format alaw
[Apr 28 12:21:09] DEBUG[19474] channel.c: Scheduling timer at (0 requested / 0 actual) timer ticks per second
[Apr 28 12:21:09] DEBUG[19474] channel.c: Set channel SIP/TRUNK_DLINK-08219288 to write format slin
[Apr 28 12:21:09] DEBUG[19474] channel.c: Scheduling timer at (50 requested / 50 actual) timer ticks per second
[Apr 28 12:21:09] DEBUG[19474] rtp.c: Difference is 1760, ms is 240
[Apr 28 12:21:09] DEBUG[19474] channel.c: Set channel SIP/TRUNK_DLINK-08219288 to write format alaw
[Apr 28 12:21:09] DEBUG[19474] channel.c: Scheduling timer at (0 requested / 0 actual) timer ticks per second
[Apr 28 12:21:10] DEBUG[19474] channel.c: Set channel SIP/TRUNK_DLINK-08219288 to write format slin
[Apr 28 12:21:10] DEBUG[19474] channel.c: Scheduling timer at (50 requested / 50 actual) timer ticks per second
[Apr 28 12:21:10] DEBUG[19474] rtp.c: Difference is 1912, ms is 259
[Apr 28 12:21:10] DEBUG[9531] rtp.c: Got RTCP report of 52 bytes
[Apr 28 12:21:10] DEBUG[19474] channel.c: Set channel SIP/TRUNK_DLINK-08219288 to write format alaw
[Apr 28 12:21:10] DEBUG[19474] channel.c: Scheduling timer at (0 requested / 0 actual) timer ticks per second
[Apr 28 12:21:10] DEBUG[19474] rtp.c: Got RTCP report of 52 bytes
[Apr 28 12:21:10] DEBUG[19474] channel.c: Set channel SIP/TRUNK_DLINK-08219288 to write format slin
[Apr 28 12:21:10] DEBUG[19474] channel.c: Scheduling timer at (50 requested / 50 actual) timer ticks per second
[Apr 28 12:21:10] DEBUG[19474] rtp.c: Difference is 1824, ms is 248
[Apr 28 12:21:10] DEBUG[19474] channel.c: Set channel SIP/TRUNK_DLINK-08219288 to write format alaw
[Apr 28 12:21:10] DEBUG[19474] channel.c: Scheduling timer at (0 requested / 0 actual) timer ticks per second
[Apr 28 12:21:10] DEBUG[19474] app_macro.c: Executed application: SendDTMF
[Apr 28 12:21:10] DEBUG[19474] app_dial.c: Macro exited with status 0
[Apr 28 12:21:10] DEBUG[19474] channel.c: Set channel SIP/01201-b7a3e8f0 to write format alaw
[Apr 28 12:21:10] DEBUG[19474] channel.c: Scheduling timer at (0 requested / 0 actual) timer ticks per second
[Apr 28 12:21:10] DEBUG[19474] chan_sip.c: SIP answering channel: SIP/01201-b7a3e8f0
[Apr 28 12:21:10] DEBUG[8152] chan_sip.c: Checking device state for peer 01201
[Apr 28 12:21:10] DEBUG[8152] devicestate.c: Changing state for SIP/01201 - state 1 (Not in use)
[Apr 28 12:21:10] DEBUG[8152] devicestate.c: device 'SIP/01201' state '1'
[Apr 28 12:21:10] DEBUG[8176] app_queue.c: Device 'SIP/01201' changed to state '1' (Not in use) but we don't care because they're not a member of any queue.
[Apr 28 12:21:10] DEBUG[19474] chan_sip.c: Setting framing from config on incoming call
[Apr 28 12:21:10] DEBUG[19474] chan_sip.c: ** Our capability: 0x8 (alaw) Video flag: True Text flag: True
[Apr 28 12:21:10] DEBUG[19474] chan_sip.c: ** Our prefcodec: 0x0 (nothing)
[Apr 28 12:21:10] DEBUG[19474] chan_sip.c: -- Done with adding codecs to SDP
[Apr 28 12:21:10] DEBUG[19474] chan_sip.c: Done building SDP. Settling with this capability: 0x8 (alaw)
[Apr 28 12:21:10] DEBUG[19474] chan_sip.c: Trying to put 'SIP/2.0 20' onto UDP socket destined for 192.168.121.4:5060
[Apr 28 12:21:10] DEBUG[8169] chan_sip.c: Stopping retransmission on 'D1B9-8A15-46685387C88F38D48A8C-013@SipHost' of Response 15: Match Found
[Apr 28 12:21:15] DEBUG[19474] rtp.c: Got RTCP report of 52 bytes
[Apr 28 12:21:16] DEBUG[19474] rtp.c: Got RTCP report of 52 bytes
[Apr 28 12:21:20] DEBUG[19474] rtp.c: Got RTCP report of 52 bytes
[Apr 28 12:21:21] DEBUG[19474] rtp.c: Got RTCP report of 52 bytes
[Apr 28 12:21:24] DEBUG[8169] acl.c: Found IP address for this socket
[Apr 28 12:21:24] DEBUG[8169] chan_sip.c: Allocating new SIP dialog for D1B9-8A15-466848163DC28BEF8DEF-002@SipHost - REGISTER (No RTP)
[Apr 28 12:21:24] DEBUG[8169] chan_sip.c: Trying to put 'SIP/2.0 40' onto UDP socket destined for 192.168.121.4:5060
[Apr 28 12:21:24] DEBUG[8169] acl.c: Found IP address for this socket
[Apr 28 12:21:24] DEBUG[8169] chan_sip.c: Allocating new SIP dialog for D1B9-8A15-466848163E324B5A719E-003@SipHost - REGISTER (No RTP)
[Apr 28 12:21:24] DEBUG[8169] chan_sip.c: Trying to put 'SIP/2.0 40' onto UDP socket destined for 192.168.121.4:5060
[Apr 28 12:21:24] DEBUG[8169] acl.c: Found IP address for this socket
[Apr 28 12:21:24] DEBUG[8169] chan_sip.c: Allocating new SIP dialog for D1B9-8A15-4668481637F986968B86-004@SipHost - REGISTER (No RTP)
[Apr 28 12:21:24] DEBUG[8169] chan_sip.c: Trying to put 'SIP/2.0 40' onto UDP socket destined for 192.168.121.4:5060
[Apr 28 12:21:25] DEBUG[8169] chan_sip.c: Trying to put 'SIP/2.0 20' onto UDP socket destined for 192.168.121.4:5060
[Apr 28 12:21:25] DEBUG[8152] chan_sip.c: Checking device state for peer 01202
[Apr 28 12:21:25] DEBUG[8152] devicestate.c: Changing state for SIP/01202 - state 1 (Not in use)
[Apr 28 12:21:25] DEBUG[8152] devicestate.c: device 'SIP/01202' state '1'
[Apr 28 12:21:25] DEBUG[8176] app_queue.c: Device 'SIP/01202' changed to state '1' (Not in use) but we don't care because they're not a member of any queue.
[Apr 28 12:21:25] DEBUG[8169] chan_sip.c: Trying to put 'SIP/2.0 20' onto UDP socket destined for 192.168.121.4:5060
[Apr 28 12:21:25] DEBUG[8152] chan_sip.c: Checking device state for peer 01203
[Apr 28 12:21:25] DEBUG[8152] devicestate.c: Changing state for SIP/01203 - state 1 (Not in use)
[Apr 28 12:21:25] DEBUG[8152] devicestate.c: device 'SIP/01203' state '1'
[Apr 28 12:21:25] DEBUG[8176] app_queue.c: Device 'SIP/01203' changed to state '1' (Not in use) but we don't care because they're not a member of any queue.
[Apr 28 12:21:25] DEBUG[8169] acl.c: Found IP address for this socket
[Apr 28 12:21:25] DEBUG[8169] chan_sip.c: Allocating new SIP dialog for D1B9-8A15-4668481699F9AE82A2B2-005@SipHost - REGISTER (No RTP)
[Apr 28 12:21:25] DEBUG[8169] chan_sip.c: Trying to put 'SIP/2.0 40' onto UDP socket destined for 192.168.121.4:5060
[Apr 28 12:21:25] DEBUG[8169] acl.c: Found IP address for this socket
[Apr 28 12:21:25] DEBUG[8169] chan_sip.c: Allocating new SIP dialog for D1B9-8A15-4668481658F41493E5D9-006@SipHost - REGISTER (No RTP)
[Apr 28 12:21:25] DEBUG[8169] chan_sip.c: Trying to put 'SIP/2.0 40' onto UDP socket destined for 192.168.121.4:5060
[Apr 28 12:21:25] DEBUG[8169] acl.c: Found IP address for this socket
[Apr 28 12:21:25] DEBUG[8169] chan_sip.c: Allocating new SIP dialog for D1B9-8A15-466848169422F8DF9D67-007@SipHost - REGISTER (No RTP)
[Apr 28 12:21:25] DEBUG[8169] chan_sip.c: Trying to put 'SIP/2.0 40' onto UDP socket destined for 192.168.121.4:5060
[Apr 28 12:21:25] DEBUG[8169] chan_sip.c: Trying to put 'SIP/2.0 20' onto UDP socket destined for 192.168.121.4:5060
[Apr 28 12:21:25] DEBUG[8152] chan_sip.c: Checking device state for peer 01204
[Apr 28 12:21:25] DEBUG[8152] devicestate.c: Changing state for SIP/01204 - state 1 (Not in use)
[Apr 28 12:21:25] DEBUG[8152] devicestate.c: device 'SIP/01204' state '1'
[Apr 28 12:21:25] DEBUG[8176] app_queue.c: Device 'SIP/01204' changed to state '1' (Not in use) but we don't care because they're not a member of any queue.
[Apr 28 12:21:25] DEBUG[19474] rtp.c: Got RTCP report of 52 bytes
[Apr 28 12:21:25] DEBUG[8169] chan_sip.c: Trying to put 'SIP/2.0 20' onto UDP socket destined for 192.168.121.4:5060
[Apr 28 12:21:25] DEBUG[8152] chan_sip.c: Checking device state for peer 01205
[Apr 28 12:21:25] DEBUG[8152] devicestate.c: Changing state for SIP/01205 - state 1 (Not in use)
[Apr 28 12:21:25] DEBUG[8152] devicestate.c: device 'SIP/01205' state '1'
[Apr 28 12:21:25] DEBUG[8176] app_queue.c: Device 'SIP/01205' changed to state '1' (Not in use) but we don't care because they're not a member of any queue.
[Apr 28 12:21:25] DEBUG[8169] chan_sip.c: Trying to put 'SIP/2.0 20' onto UDP socket destined for 192.168.121.4:5060
[Apr 28 12:21:25] DEBUG[8152] chan_sip.c: Checking device state for peer 01206
[Apr 28 12:21:25] DEBUG[8152] devicestate.c: Changing state for SIP/01206 - state 1 (Not in use)
[Apr 28 12:21:25] DEBUG[8152] devicestate.c: device 'SIP/01206' state '1'
[Apr 28 12:21:25] DEBUG[8176] app_queue.c: Device 'SIP/01206' changed to state '1' (Not in use) but we don't care because they're not a member of any queue.
[Apr 28 12:21:25] DEBUG[8169] chan_sip.c: Trying to put 'SIP/2.0 20' onto UDP socket destined for 192.168.121.4:5060
[Apr 28 12:21:25] DEBUG[8152] chan_sip.c: Checking device state for peer TRUNK_DLINK
[Apr 28 12:21:25] DEBUG[8152] devicestate.c: Changing state for SIP/TRUNK_DLINK - state 1 (Not in use)
[Apr 28 12:21:25] DEBUG[8152] devicestate.c: device 'SIP/TRUNK_DLINK' state '1'
[Apr 28 12:21:25] DEBUG[8176] app_queue.c: Device 'SIP/TRUNK_DLINK' changed to state '1' (Not in use) but we don't care because they're not a member of any queue.

[Apr 28 12:21:26] DEBUG[19474] rtp.c: Got RTCP report of 52 bytes
[Apr 28 12:21:30] DEBUG[19474] rtp.c: Got RTCP report of 52 bytes
[Apr 28 12:21:31] DEBUG[19474] rtp.c: Got RTCP report of 52 bytes
[Apr 28 12:21:31] DEBUG[19474] rtp.c: Got RTCP report of 60 bytes
[Apr 28 12:21:31] DEBUG[8169] chan_sip.c: Setting SIP_ALREADYGONE on dialog D1B9-8A15-46685387C88F38D48A8C-013@SipHost
[Apr 28 12:21:31] DEBUG[8169] chan_sip.c: Received bye, issuing owner hangup
[Apr 28 12:21:31] DEBUG[8169] chan_sip.c: Trying to put 'SIP/2.0 20' onto UDP socket destined for 192.168.121.4:5060
[Apr 28 12:21:31] DEBUG[19474] channel.c: Didn't get a frame from channel: SIP/01201-b7a3e8f0
[Apr 28 12:21:31] DEBUG[19474] channel.c: Bridge stops bridging channels SIP/01201-b7a3e8f0 and SIP/TRUNK_DLINK-08219288
[Apr 28 12:21:31] DEBUG[19474] channel.c: Hanging up channel 'SIP/TRUNK_DLINK-08219288'
[Apr 28 12:21:31] DEBUG[19474] chan_sip.c: Hangup call SIP/TRUNK_DLINK-08219288, SIP callid 6a342f455993c0c27eeb82632054e400@192.168.121.2
[Apr 28 12:21:31] DEBUG[19474] chan_sip.c: Trying to put 'BYE sip:42' onto UDP socket destined for 192.168.121.4:5060
[Apr 28 12:21:31] DEBUG[19474] rtp.c: Channel '<unspecified>' has no RTP, not doing anything
[Apr 28 12:21:31] DEBUG[19474] app_dial.c: Exiting with DIALSTATUS=ANSWER.
[Apr 28 12:21:31] DEBUG[8152] chan_sip.c: Checking device state for peer TRUNK_DLINK
[Apr 28 12:21:31] DEBUG[19474] app_macro.c: Spawn extension (macro-Moutdial,s,2) exited non-zero on 'SIP/01201-b7a3e8f0' in macro 'Moutdial'
[Apr 28 12:21:31] DEBUG[8152] devicestate.c: Changing state for SIP/TRUNK_DLINK - state 1 (Not in use)
[Apr 28 12:21:31] DEBUG[8152] devicestate.c: device 'SIP/TRUNK_DLINK' state '1'
[Apr 28 12:21:31] DEBUG[19474] pbx.c: Spawn extension (officeSU,89242830732,2) exited non-zero on 'SIP/01201-b7a3e8f0'
[Apr 28 12:21:31] DEBUG[19474] channel.c: Soft-Hanging up channel 'SIP/01201-b7a3e8f0'
[Apr 28 12:21:31] DEBUG[8176] app_queue.c: Device 'SIP/TRUNK_DLINK' changed to state '1' (Not in use) but we don't care because they're not a member of any queue.
[Apr 28 12:21:31] DEBUG[19474] channel.c: Hanging up channel 'SIP/01201-b7a3e8f0'
[Apr 28 12:21:31] DEBUG[19474] chan_sip.c: Hangup call SIP/01201-b7a3e8f0, SIP callid D1B9-8A15-46685387C88F38D48A8C-013@SipHost
[Apr 28 12:21:31] DEBUG[8152] chan_sip.c: Checking device state for peer 01201
[Apr 28 12:21:31] DEBUG[8152] devicestate.c: Changing state for SIP/01201 - state 1 (Not in use)
[Apr 28 12:21:31] DEBUG[8152] devicestate.c: device 'SIP/01201' state '1'
[Apr 28 12:21:31] DEBUG[8176] app_queue.c: Device 'SIP/01201' changed to state '1' (Not in use) but we don't care because they're not a member of any queue.
[Apr 28 12:21:31] DEBUG[8169] chan_sip.c: Stopping retransmission on '6a342f455993c0c27eeb82632054e400@192.168.121.2' of Request 103: Match Found
[Apr 28 12:21:31] DEBUG[8169] chan_sip.c: Destroying SIP dialog 6a342f455993c0c27eeb82632054e400@192.168.121.2
[Apr 28 12:21:31] DEBUG[8169] chan_sip.c: Destroying SIP dialog D1B9-8A15-46685387C88F38D48A8C-013@SipHost
[Apr 28 12:21:37] DEBUG[8169] acl.c: Found IP address for this socket
[Apr 28 12:21:37] DEBUG[8169] chan_sip.c: Setting NAT on RTP to Off
[Apr 28 12:21:37] DEBUG[8169] chan_sip.c: Allocating new SIP dialog for D1B9-8A15-466854209ED18290E6BF-014@SipHost - INVITE (With RTP)
[Apr 28 12:21:37] DEBUG[8169] chan_sip.c: Setting NAT on RTP to Off
[Apr 28 12:21:37] DEBUG[8169] chan_sip.c: Trying to put 'SIP/2.0 40' onto UDP socket destined for 192.168.121.4:5060
[Apr 28 12:21:37] DEBUG[8169] chan_sip.c: Stopping retransmission on 'D1B9-8A15-466854209ED18290E6BF-014@SipHost' of Response 7: Match Found
[Apr 28 12:21:37] DEBUG[8169] chan_sip.c: Setting NAT on RTP to Off
[Apr 28 12:21:37] DEBUG[8169] chan_sip.c: We're settling with these formats: 0x8 (alaw)
[Apr 28 12:21:37] DEBUG[8169] chan_sip.c: Checking SIP call limits for device TRUNK_DLINK
[Apr 28 12:21:37] DEBUG[8169] chan_sip.c: Updating call counter for incoming call
[Apr 28 12:21:37] DEBUG[8169] chan_sip.c: *** Our native formats are 0x8 (alaw)
[Apr 28 12:21:37] DEBUG[8169] chan_sip.c: *** Joint capabilities are 0x8 (alaw)
[Apr 28 12:21:37] DEBUG[8169] chan_sip.c: *** Our capabilities are 0x8 (alaw)
[Apr 28 12:21:37] DEBUG[8169] chan_sip.c: *** AST_CODEC_CHOOSE formats are 0x8 (alaw)
[Apr 28 12:21:37] DEBUG[8169] chan_sip.c: This channel will not be able to handle video.
[Apr 28 12:21:37] DEBUG[8169] chan_sip.c: build_route: Contact hop: <sip:TRUNK_DLINK@192.168.121.4:5060>
[Apr 28 12:21:37] DEBUG[8169] chan_sip.c: SIP/TRUNK_DLINK-b7a46978: New call is still down.... Trying...
[Apr 28 12:21:37] DEBUG[8169] chan_sip.c: Trying to put 'SIP/2.0 10' onto UDP socket destined for 192.168.121.4:5060
[Apr 28 12:21:37] DEBUG[8152] chan_sip.c: Checking device state for peer TRUNK_DLINK
[Apr 28 12:21:37] DEBUG[19509] pbx.c: Launching 'Goto'
[Apr 28 12:21:37] DEBUG[8152] devicestate.c: Changing state for SIP/TRUNK_DLINK - state 1 (Not in use)
[Apr 28 12:21:37] DEBUG[19509] pbx.c: Launching 'Answer'
[Apr 28 12:21:37] DEBUG[8152] devicestate.c: device 'SIP/TRUNK_DLINK' state '1'
[Apr 28 12:21:37] DEBUG[19509] chan_sip.c: SIP answering channel: SIP/TRUNK_DLINK-b7a46978
[Apr 28 12:21:37] DEBUG[8152] chan_sip.c: Checking device state for peer TRUNK_DLINK
[Apr 28 12:21:37] DEBUG[8152] devicestate.c: Changing state for SIP/TRUNK_DLINK - state 1 (Not in use)
[Apr 28 12:21:37] DEBUG[19509] chan_sip.c: Setting framing from config on incoming call
[Apr 28 12:21:37] DEBUG[8152] devicestate.c: device 'SIP/TRUNK_DLINK' state '1'
[Apr 28 12:21:37] DEBUG[19509] chan_sip.c: ** Our capability: 0x8 (alaw) Video flag: True Text flag: True
[Apr 28 12:21:37] DEBUG[19509] chan_sip.c: ** Our prefcodec: 0x0 (nothing)
[Apr 28 12:21:37] DEBUG[19509] chan_sip.c: -- Done with adding codecs to SDP
[Apr 28 12:21:37] DEBUG[19509] chan_sip.c: Done building SDP. Settling with this capability: 0x8 (alaw)
[Apr 28 12:21:37] DEBUG[19509] chan_sip.c: Trying to put 'SIP/2.0 20' onto UDP socket destined for 192.168.121.4:5060
[Apr 28 12:21:37] DEBUG[8176] app_queue.c: Device 'SIP/TRUNK_DLINK' changed to state '1' (Not in use) but we don't care because they're not a member of any queue.
[Apr 28 12:21:37] DEBUG[8176] app_queue.c: Device 'SIP/TRUNK_DLINK' changed to state '1' (Not in use) but we don't care because they're not a member of any queue.
[Apr 28 12:21:37] DEBUG[8169] chan_sip.c: Stopping retransmission on 'D1B9-8A15-466854209ED18290E6BF-014@SipHost' of Response 8: Match Found
[Apr 28 12:21:37] DEBUG[19509] pbx.c: Launching 'Wait'
[Apr 28 12:21:38] DEBUG[19509] pbx.c: Launching 'BackGround'
[Apr 28 12:21:38] DEBUG[19509] channel.c: Set channel SIP/TRUNK_DLINK-b7a46978 to write format gsm
[Apr 28 12:21:38] DEBUG[19509] rtp.c: Ooh, format changed from unknown to alaw
[Apr 28 12:21:38] DEBUG[19509] rtp.c: Created smoother: format: 8 ms: 20 len: 160
[Apr 28 12:21:38] DEBUG[19509] channel.c: Scheduling timer at (50 requested / 50 actual) timer ticks per second
[Apr 28 12:21:42] DEBUG[19509] rtp.c: Got RTCP report of 52 bytes
[Apr 28 12:21:45] DEBUG[8169] acl.c: Found IP address for this socket
[Apr 28 12:21:45] DEBUG[8169] chan_sip.c: Allocating new SIP dialog for D1B9-8A15-46684816AF3C2431EF6C-001@SipHost - REGISTER (No RTP)
[Apr 28 12:21:45] DEBUG[8169] chan_sip.c: Trying to put 'SIP/2.0 40' onto UDP socket destined for 192.168.121.4:5060
[Apr 28 12:21:45] DEBUG[8169] chan_sip.c: Trying to put 'SIP/2.0 20' onto UDP socket destined for 192.168.121.4:5060
[Apr 28 12:21:45] DEBUG[8152] chan_sip.c: Checking device state for peer 01201
[Apr 28 12:21:45] DEBUG[8152] devicestate.c: Changing state for SIP/01201 - state 1 (Not in use)
[Apr 28 12:21:45] DEBUG[8152] devicestate.c: device 'SIP/01201' state '1'
[Apr 28 12:21:45] DEBUG[8176] app_queue.c: Device 'SIP/01201' changed to state '1' (Not in use) but we don't care because they're not a member of any queue.
[Apr 28 12:21:47] DEBUG[19509] rtp.c: Got RTCP report of 52 bytes
[Apr 28 12:21:49] DEBUG[19509] channel.c: Scheduling timer at (0 requested / 0 actual) timer ticks per second
[Apr 28 12:21:49] DEBUG[19509] channel.c: Scheduling timer at (0 requested / 0 actual) timer ticks per second



[Apr 28 12:21:49] DEBUG[19509] channel.c: Set channel SIP/TRUNK_DLINK-b7a46978 to write format alaw
[Apr 28 12:21:49] DEBUG[19509] pbx.c: Launching 'WaitExten'
[Apr 28 12:21:51] DEBUG[19509] pbx.c: Launching 'Dial'
[Apr 28 12:21:51] DEBUG[19509] chan_sip.c: Asked to create a SIP channel with formats: 0x8 (alaw)
[Apr 28 12:21:51] DEBUG[19509] chan_sip.c: Allocating new SIP dialog for 78a7e902093a8daf495f12b8489cbcec@89.188.251.130 - INVITE (With RTP)
[Apr 28 12:21:51] DEBUG[19509] chan_sip.c: Setting NAT on RTP to Off
[Apr 28 12:21:51] DEBUG[19509] chan_sip.c: Setting NAT on UDPTL to Off
[Apr 28 12:21:51] DEBUG[19509] acl.c: Found IP address for this socket
[Apr 28 12:21:51] DEBUG[19509] chan_sip.c: *** Our native formats are 0x8 (alaw)
[Apr 28 12:21:51] DEBUG[19509] chan_sip.c: *** Joint capabilities are 0x8 (alaw)
[Apr 28 12:21:51] DEBUG[19509] chan_sip.c: *** Our capabilities are 0x8 (alaw)
[Apr 28 12:21:51] DEBUG[19509] chan_sip.c: *** AST_CODEC_CHOOSE formats are 0x8 (alaw)
[Apr 28 12:21:51] DEBUG[19509] chan_sip.c: *** Our preferred formats from the incoming channel are 0x8 (alaw)
[Apr 28 12:21:51] DEBUG[19509] chan_sip.c: This channel will not be able to handle video.
[Apr 28 12:21:51] DEBUG[19509] channel.c: Not copying variable DIALEDTIME.
[Apr 28 12:21:51] DEBUG[19509] channel.c: Not copying variable ANSWEREDTIME.
[Apr 28 12:21:51] DEBUG[19509] channel.c: Not copying variable DIALEDPEERNAME.
[Apr 28 12:21:51] DEBUG[19509] channel.c: Not copying variable DIALEDPEERNUMBER.
[Apr 28 12:21:51] DEBUG[19509] channel.c: Not copying variable DIALSTATUS.
[Apr 28 12:21:51] DEBUG[19509] channel.c: Not copying variable BACKGROUNDSTATUS.
[Apr 28 12:21:51] DEBUG[19509] channel.c: Not copying variable SIPCALLID.
[Apr 28 12:21:51] DEBUG[19509] channel.c: Not copying variable SIPDOMAIN.
[Apr 28 12:21:51] DEBUG[19509] channel.c: Not copying variable SIPURI.
[Apr 28 12:21:51] DEBUG[19509] chan_sip.c: Outgoing Call for 01201
[Apr 28 12:21:51] DEBUG[19509] chan_sip.c: Updating call counter for outgoing call
[Apr 28 12:21:51] DEBUG[19509] chan_sip.c: Our T38 capability (16160), joint T38 capability (16160)
[Apr 28 12:21:51] DEBUG[19509] chan_sip.c: ** Our capability: 0x8 (alaw) Video flag: False Text flag: False
[Apr 28 12:21:51] DEBUG[19509] chan_sip.c: ** Our prefcodec: 0x8 (alaw)
[Apr 28 12:21:51] DEBUG[19509] chan_sip.c: -- Done with adding codecs to SDP
[Apr 28 12:21:51] DEBUG[19509] chan_sip.c: Done building SDP. Settling with this capability: 0x8 (alaw)
[Apr 28 12:21:51] DEBUG[19509] chan_sip.c: Initializing initreq for method INVITE - callid 37214ac663b9985b010ee0703d01a247@192.168.121.2
[Apr 28 12:21:51] DEBUG[19509] chan_sip.c: Trying to put 'INVITE sip' onto UDP socket destined for 192.168.121.4:5060
[Apr 28 12:21:51] DEBUG[19509] chan_sip.c: Asked to create a SIP channel with formats: 0x8 (alaw)
[Apr 28 12:21:51] DEBUG[19509] chan_sip.c: Allocating new SIP dialog for 47c5dd753fc02238574d1cc64dfd6eeb@89.188.251.130 - INVITE (With RTP)
[Apr 28 12:21:51] DEBUG[19509] chan_sip.c: Setting NAT on RTP to Off
[Apr 28 12:21:51] DEBUG[19509] chan_sip.c: Setting NAT on UDPTL to Off
[Apr 28 12:21:51] DEBUG[19509] acl.c: Found IP address for this socket
[Apr 28 12:21:51] DEBUG[19509] chan_sip.c: *** Our native formats are 0x8 (alaw)
[Apr 28 12:21:51] DEBUG[19509] chan_sip.c: *** Joint capabilities are 0x8 (alaw)
[Apr 28 12:21:51] DEBUG[19509] chan_sip.c: *** Our capabilities are 0x8 (alaw)
[Apr 28 12:21:51] DEBUG[19509] chan_sip.c: *** AST_CODEC_CHOOSE formats are 0x8 (alaw)
[Apr 28 12:21:51] DEBUG[19509] chan_sip.c: *** Our preferred formats from the incoming channel are 0x8 (alaw)
[Apr 28 12:21:51] DEBUG[19509] chan_sip.c: This channel will not be able to handle video.
[Apr 28 12:21:51] DEBUG[19509] channel.c: Not copying variable DIALEDTIME.
[Apr 28 12:21:51] DEBUG[19509] channel.c: Not copying variable ANSWEREDTIME.
[Apr 28 12:21:51] DEBUG[19509] channel.c: Not copying variable DIALEDPEERNAME.
[Apr 28 12:21:51] DEBUG[19509] channel.c: Not copying variable DIALEDPEERNUMBER.
[Apr 28 12:21:51] DEBUG[19509] channel.c: Not copying variable DIALSTATUS.
[Apr 28 12:21:51] DEBUG[19509] channel.c: Not copying variable BACKGROUNDSTATUS.
[Apr 28 12:21:51] DEBUG[19509] channel.c: Not copying variable SIPCALLID.
[Apr 28 12:21:51] DEBUG[19509] channel.c: Not copying variable SIPDOMAIN.
[Apr 28 12:21:51] DEBUG[19509] channel.c: Not copying variable SIPURI.
[Apr 28 12:21:51] DEBUG[19509] chan_sip.c: Outgoing Call for 01202
[Apr 28 12:21:51] DEBUG[19509] chan_sip.c: Updating call counter for outgoing call
[Apr 28 12:21:51] DEBUG[19509] chan_sip.c: Our T38 capability (16160), joint T38 capability (16160)
[Apr 28 12:21:51] DEBUG[19509] chan_sip.c: ** Our capability: 0x8 (alaw) Video flag: False Text flag: False
[Apr 28 12:21:51] DEBUG[19509] chan_sip.c: ** Our prefcodec: 0x8 (alaw)
[Apr 28 12:21:51] DEBUG[19509] chan_sip.c: -- Done with adding codecs to SDP
[Apr 28 12:21:51] DEBUG[19509] chan_sip.c: Done building SDP. Settling with this capability: 0x8 (alaw)
[Apr 28 12:21:51] DEBUG[19509] chan_sip.c: Initializing initreq for method INVITE - callid 3719422b395f9a6d67aac23d2d978f68@192.168.121.2
[Apr 28 12:21:51] DEBUG[19509] chan_sip.c: Trying to put 'INVITE sip' onto UDP socket destined for 192.168.121.4:5060
[Apr 28 12:21:51] DEBUG[19509] chan_sip.c: Asked to create a SIP channel with formats: 0x8 (alaw)
[Apr 28 12:21:51] DEBUG[19509] chan_sip.c: Allocating new SIP dialog for 410611511eba989e4cf96c4044fb71e7@89.188.251.130 - INVITE (With RTP)
[Apr 28 12:21:51] DEBUG[19509] chan_sip.c: Setting NAT on RTP to Off
[Apr 28 12:21:51] DEBUG[19509] chan_sip.c: Setting NAT on UDPTL to Off
[Apr 28 12:21:51] DEBUG[19509] acl.c: Found IP address for this socket
[Apr 28 12:21:51] DEBUG[19509] chan_sip.c: *** Our native formats are 0x8 (alaw)
[Apr 28 12:21:51] DEBUG[19509] chan_sip.c: *** Joint capabilities are 0x8 (alaw)
[Apr 28 12:21:51] DEBUG[19509] chan_sip.c: *** Our capabilities are 0x8 (alaw)
[Apr 28 12:21:51] DEBUG[19509] chan_sip.c: *** AST_CODEC_CHOOSE formats are 0x8 (alaw)
[Apr 28 12:21:51] DEBUG[19509] chan_sip.c: *** Our preferred formats from the incoming channel are 0x8 (alaw)
[Apr 28 12:21:51] DEBUG[19509] chan_sip.c: This channel will not be able to handle video.
[Apr 28 12:21:51] DEBUG[19509] channel.c: Not copying variable DIALEDTIME.
[Apr 28 12:21:51] DEBUG[19509] channel.c: Not copying variable ANSWEREDTIME.
[Apr 28 12:21:51] DEBUG[19509] channel.c: Not copying variable DIALEDPEERNAME.
[Apr 28 12:21:51] DEBUG[19509] channel.c: Not copying variable DIALEDPEERNUMBER.
[Apr 28 12:21:51] DEBUG[19509] channel.c: Not copying variable DIALSTATUS.
[Apr 28 12:21:51] DEBUG[19509] channel.c: Not copying variable BACKGROUNDSTATUS.
[Apr 28 12:21:51] DEBUG[19509] channel.c: Not copying variable SIPCALLID.
[Apr 28 12:21:51] DEBUG[19509] channel.c: Not copying variable SIPDOMAIN.
[Apr 28 12:21:51] DEBUG[19509] channel.c: Not copying variable SIPURI.
[Apr 28 12:21:51] DEBUG[19509] chan_sip.c: Outgoing Call for 01203
[Apr 28 12:21:51] DEBUG[19509] chan_sip.c: Updating call counter for outgoing call
[Apr 28 12:21:51] DEBUG[19509] chan_sip.c: Our T38 capability (16160), joint T38 capability (16160)
[Apr 28 12:21:51] DEBUG[19509] chan_sip.c: ** Our capability: 0x8 (alaw) Video flag: False Text flag: False
[Apr 28 12:21:51] DEBUG[19509] chan_sip.c: ** Our prefcodec: 0x8 (alaw)
[Apr 28 12:21:51] DEBUG[19509] chan_sip.c: -- Done with adding codecs to SDP
[Apr 28 12:21:51] DEBUG[19509] chan_sip.c: Done building SDP. Settling with this capability: 0x8 (alaw)
[Apr 28 12:21:51] DEBUG[19509] chan_sip.c: Initializing initreq for method INVITE - callid 5c6330a448948551573fe65a20e3f784@192.168.121.2
[Apr 28 12:21:51] DEBUG[19509] chan_sip.c: Trying to put 'INVITE sip' onto UDP socket destined for 192.168.121.4:5060
[Apr 28 12:21:51] DEBUG[19509] chan_sip.c: Asked to create a SIP channel with formats: 0x8 (alaw)
[Apr 28 12:21:51] DEBUG[19509] chan_sip.c: Allocating new SIP dialog for 2a07e3b57bde7e053b6baaf5268d7942@89.188.251.130 - INVITE (With RTP)
[Apr 28 12:21:51] DEBUG[19509] chan_sip.c: Setting NAT on RTP to Off
[Apr 28 12:21:51] DEBUG[19509] chan_sip.c: Setting NAT on UDPTL to Off
[Apr 28 12:21:51] DEBUG[19509] acl.c: Found IP address for this socket
[Apr 28 12:21:51] DEBUG[19509] chan_sip.c: *** Our native formats are 0x8 (alaw)
[Apr 28 12:21:51] DEBUG[19509] chan_sip.c: *** Joint capabilities are 0x8 (alaw)
[Apr 28 12:21:51] DEBUG[19509] chan_sip.c: *** Our capabilities are 0x8 (alaw)
[Apr 28 12:21:51] DEBUG[19509] chan_sip.c: *** AST_CODEC_CHOOSE formats are 0x8 (alaw)
[Apr 28 12:21:51] DEBUG[19509] chan_sip.c: *** Our preferred formats from the incoming channel are 0x8 (alaw)
[Apr 28 12:21:51] DEBUG[19509] chan_sip.c: This channel will not be able to handle video.
[Apr 28 12:21:51] DEBUG[19509] channel.c: Not copying variable DIALEDTIME.
[Apr 28 12:21:51] DEBUG[19509] channel.c: Not copying variable ANSWEREDTIME.
[Apr 28 12:21:51] DEBUG[19509] channel.c: Not copying variable DIALEDPEERNAME.
[Apr 28 12:21:51] DEBUG[19509] channel.c: Not copying variable DIALEDPEERNUMBER.
[Apr 28 12:21:51] DEBUG[19509] channel.c: Not copying variable DIALSTATUS.
[Apr 28 12:21:51] DEBUG[19509] channel.c: Not copying variable BACKGROUNDSTATUS.
[Apr 28 12:21:51] DEBUG[19509] channel.c: Not copying variable SIPCALLID.
[Apr 28 12:21:51] DEBUG[19509] channel.c: Not copying variable SIPDOMAIN.
[Apr 28 12:21:51] DEBUG[19509] channel.c: Not copying variable SIPURI.
[Apr 28 12:21:51] DEBUG[19509] chan_sip.c: Outgoing Call for 01204
[Apr 28 12:21:51] DEBUG[19509] chan_sip.c: Updating call counter for outgoing call
[Apr 28 12:21:51] DEBUG[19509] chan_sip.c: Our T38 capability (16160), joint T38 capability (16160)
[Apr 28 12:21:51] DEBUG[19509] chan_sip.c: ** Our capability: 0x8 (alaw) Video flag: False Text flag: False
[Apr 28 12:21:51] DEBUG[19509] chan_sip.c: ** Our prefcodec: 0x8 (alaw)
[Apr 28 12:21:51] DEBUG[19509] chan_sip.c: -- Done with adding codecs to SDP
[Apr 28 12:21:51] DEBUG[19509] chan_sip.c: Done building SDP. Settling with this capability: 0x8 (alaw)
[Apr 28 12:21:51] DEBUG[19509] chan_sip.c: Initializing initreq for method INVITE - callid 2b7fb75400e3d5926e374f8521bc6344@192.168.121.2
[Apr 28 12:21:51] DEBUG[19509] chan_sip.c: Trying to put 'INVITE sip' onto UDP socket destined for 192.168.121.4:5060
[Apr 28 12:21:51] DEBUG[19509] chan_sip.c: Asked to create a SIP channel with formats: 0x8 (alaw)
[Apr 28 12:21:51] DEBUG[19509] chan_sip.c: Allocating new SIP dialog for 32aa985625dc6f4629373fd84dc0c4e5@89.188.251.130 - INVITE (With RTP)
[Apr 28 12:21:51] DEBUG[19509] chan_sip.c: Setting NAT on RTP to Off
[Apr 28 12:21:51] DEBUG[19509] chan_sip.c: Setting NAT on UDPTL to Off
[Apr 28 12:21:51] DEBUG[19509] acl.c: Found IP address for this socket
[Apr 28 12:21:51] DEBUG[19509] chan_sip.c: *** Our native formats are 0x8 (alaw)
[Apr 28 12:21:51] DEBUG[19509] chan_sip.c: *** Joint capabilities are 0x8 (alaw)
[Apr 28 12:21:51] DEBUG[19509] chan_sip.c: *** Our capabilities are 0x8 (alaw)
[Apr 28 12:21:51] DEBUG[19509] chan_sip.c: *** AST_CODEC_CHOOSE formats are 0x8 (alaw)
[Apr 28 12:21:51] DEBUG[19509] chan_sip.c: *** Our preferred formats from the incoming channel are 0x8 (alaw)
[Apr 28 12:21:51] DEBUG[19509] chan_sip.c: This channel will not be able to handle video.
[Apr 28 12:21:51] DEBUG[19509] channel.c: Not copying variable DIALEDTIME.
[Apr 28 12:21:51] DEBUG[19509] channel.c: Not copying variable ANSWEREDTIME.
[Apr 28 12:21:51] DEBUG[19509] channel.c: Not copying variable DIALEDPEERNAME.
[Apr 28 12:21:51] DEBUG[19509] channel.c: Not copying variable DIALEDPEERNUMBER.
[Apr 28 12:21:51] DEBUG[19509] channel.c: Not copying variable DIALSTATUS.
[Apr 28 12:21:51] DEBUG[19509] channel.c: Not copying variable BACKGROUNDSTATUS.
[Apr 28 12:21:51] DEBUG[19509] channel.c: Not copying variable SIPCALLID.
[Apr 28 12:21:51] DEBUG[19509] channel.c: Not copying variable SIPDOMAIN.
[Apr 28 12:21:51] DEBUG[19509] channel.c: Not copying variable SIPURI.
[Apr 28 12:21:51] DEBUG[19509] chan_sip.c: Outgoing Call for 01205
[Apr 28 12:21:51] DEBUG[19509] chan_sip.c: Updating call counter for outgoing call
[Apr 28 12:21:51] DEBUG[19509] chan_sip.c: Our T38 capability (16160), joint T38 capability (16160)
[Apr 28 12:21:51] DEBUG[19509] chan_sip.c: ** Our capability: 0x8 (alaw) Video flag: False Text flag: False
[Apr 28 12:21:51] DEBUG[19509] chan_sip.c: ** Our prefcodec: 0x8 (alaw)
[Apr 28 12:21:51] DEBUG[19509] chan_sip.c: -- Done with adding codecs to SDP
[Apr 28 12:21:51] DEBUG[19509] chan_sip.c: Done building SDP. Settling with this capability: 0x8 (alaw)
[Apr 28 12:21:51] DEBUG[19509] chan_sip.c: Initializing initreq for method INVITE - callid 56352e5f0921f14d467061c32a2b137f@192.168.121.2
[Apr 28 12:21:51] DEBUG[19509] chan_sip.c: Trying to put 'INVITE sip' onto UDP socket destined for 192.168.121.4:5060
[Apr 28 12:21:51] DEBUG[19509] chan_sip.c: Asked to create a SIP channel with formats: 0x8 (alaw)
[Apr 28 12:21:51] DEBUG[19509] chan_sip.c: Allocating new SIP dialog for 32598cf02f84240d4689151a05820848@89.188.251.130 - INVITE (With RTP)
[Apr 28 12:21:51] DEBUG[19509] chan_sip.c: Setting NAT on RTP to Off
[Apr 28 12:21:51] DEBUG[19509] chan_sip.c: Setting NAT on UDPTL to Off
[Apr 28 12:21:51] DEBUG[19509] acl.c: Found IP address for this socket
[Apr 28 12:21:51] DEBUG[19509] chan_sip.c: *** Our native formats are 0x8 (alaw)
[Apr 28 12:21:51] DEBUG[19509] chan_sip.c: *** Joint capabilities are 0x8 (alaw)
[Apr 28 12:21:51] DEBUG[19509] chan_sip.c: *** Our capabilities are 0x8 (alaw)
[Apr 28 12:21:51] DEBUG[19509] chan_sip.c: *** AST_CODEC_CHOOSE formats are 0x8 (alaw)
[Apr 28 12:21:51] DEBUG[19509] chan_sip.c: *** Our preferred formats from the incoming channel are 0x8 (alaw)
[Apr 28 12:21:51] DEBUG[19509] chan_sip.c: This channel will not be able to handle video.
[Apr 28 12:21:51] DEBUG[19509] channel.c: Not copying variable DIALEDTIME.
[Apr 28 12:21:51] DEBUG[19509] channel.c: Not copying variable ANSWEREDTIME.
[Apr 28 12:21:51] DEBUG[19509] channel.c: Not copying variable DIALEDPEERNAME.
[Apr 28 12:21:51] DEBUG[19509] channel.c: Not copying variable DIALEDPEERNUMBER.
[Apr 28 12:21:51] DEBUG[19509] channel.c: Not copying variable DIALSTATUS.
[Apr 28 12:21:51] DEBUG[19509] channel.c: Not copying variable BACKGROUNDSTATUS.
[Apr 28 12:21:51] DEBUG[19509] channel.c: Not copying variable SIPCALLID.
[Apr 28 12:21:51] DEBUG[19509] channel.c: Not copying variable SIPDOMAIN.
[Apr 28 12:21:51] DEBUG[19509] channel.c: Not copying variable SIPURI.
[Apr 28 12:21:51] DEBUG[19509] chan_sip.c: Outgoing Call for 01206
[Apr 28 12:21:51] DEBUG[19509] chan_sip.c: Updating call counter for outgoing call
[Apr 28 12:21:51] DEBUG[19509] chan_sip.c: Our T38 capability (16160), joint T38 capability (16160)
[Apr 28 12:21:51] DEBUG[19509] chan_sip.c: ** Our capability: 0x8 (alaw) Video flag: False Text flag: False
[Apr 28 12:21:51] DEBUG[19509] chan_sip.c: ** Our prefcodec: 0x8 (alaw)
[Apr 28 12:21:51] DEBUG[19509] chan_sip.c: -- Done with adding codecs to SDP
[Apr 28 12:21:51] DEBUG[19509] chan_sip.c: Done building SDP. Settling with this capability: 0x8 (alaw)
[Apr 28 12:21:51] DEBUG[19509] chan_sip.c: Initializing initreq for method INVITE - callid 220c670e468ff38639530d5a7ce0db6d@192.168.121.2
[Apr 28 12:21:51] DEBUG[19509] chan_sip.c: Trying to put 'INVITE sip' onto UDP socket destined for 192.168.121.4:5060
[Apr 28 12:21:51] DEBUG[19509] channel.c: Scheduling timer at (50 requested / 50 actual) timer ticks per second
[Apr 28 12:21:51] DEBUG[19509] channel.c: Generator got voice, switching to phase locked mode
[Apr 28 12:21:51] DEBUG[19509] channel.c: Scheduling timer at (0 requested / 0 actual) timer ticks per second
[Apr 28 12:21:51] DEBUG[19509] channel.c: Set channel SIP/TRUNK_DLINK-b7a46978 to write format slin
[Apr 28 12:21:51] DEBUG[19509] res_musiconhold.c: SIP/TRUNK_DLINK-b7a46978 Opened file 1 '/var/lib/asterisk/moh/macroform-robot_dity'
[Apr 28 12:21:51] DEBUG[19509] rtp.c: Difference is 16696, ms is 2107
[Apr 28 12:21:51] DEBUG[8169] chan_sip.c: (Provisional) Stopping retransmission (but retaining packet) on '37214ac663b9985b010ee0703d01a247@192.168.121.2' Request 102: Found
[Apr 28 12:21:51] DEBUG[8169] chan_sip.c: (Provisional) Stopping retransmission (but retaining packet) on '37214ac663b9985b010ee0703d01a247@192.168.121.2' Request 102: Found
[Apr 28 12:21:51] DEBUG[8152] chan_sip.c: Checking device state for peer 01201
[Apr 28 12:21:51] DEBUG[8152] devicestate.c: Changing state for SIP/01201 - state 1 (Not in use)
[Apr 28 12:21:51] DEBUG[8152] devicestate.c: device 'SIP/01201' state '1'
[Apr 28 12:21:51] DEBUG[8176] app_queue.c: Device 'SIP/01201' changed to state '1' (Not in use) but we don't care because they're not a member of any queue.
[Apr 28 12:21:51] DEBUG[8169] chan_sip.c: (Provisional) Stopping retransmission (but retaining packet) on '3719422b395f9a6d67aac23d2d978f68@192.168.121.2' Request 102: Found
[Apr 28 12:21:51] DEBUG[8169] chan_sip.c: (Provisional) Stopping retransmission (but retaining packet) on '3719422b395f9a6d67aac23d2d978f68@192.168.121.2' Request 102: Found
[Apr 28 12:21:51] DEBUG[8152] chan_sip.c: Checking device state for peer 01202
[Apr 28 12:21:51] DEBUG[8152] devicestate.c: Changing state for SIP/01202 - state 1 (Not in use)
[Apr 28 12:21:51] DEBUG[8152] devicestate.c: device 'SIP/01202' state '1'
[Apr 28 12:21:51] DEBUG[8176] app_queue.c: Device 'SIP/01202' changed to state '1' (Not in use) but we don't care because they're not a member of any queue.
[Apr 28 12:21:51] DEBUG[8169] chan_sip.c: (Provisional) Stopping retransmission (but retaining packet) on '5c6330a448948551573fe65a20e3f784@192.168.121.2' Request 102: Found
[Apr 28 12:21:51] DEBUG[8169] chan_sip.c: (Provisional) Stopping retransmission (but retaining packet) on '5c6330a448948551573fe65a20e3f784@192.168.121.2' Request 102: Found
[Apr 28 12:21:51] DEBUG[8152] chan_sip.c: Checking device state for peer 01203
[Apr 28 12:21:51] DEBUG[8152] devicestate.c: Changing state for SIP/01203 - state 1 (Not in use)
[Apr 28 12:21:51] DEBUG[8152] devicestate.c: device 'SIP/01203' state '1'
[Apr 28 12:21:51] DEBUG[8176] app_queue.c: Device 'SIP/01203' changed to state '1' (Not in use) but we don't care because they're not a member of any queue.
[Apr 28 12:21:51] DEBUG[8169] chan_sip.c: (Provisional) Stopping retransmission (but retaining packet) on '2b7fb75400e3d5926e374f8521bc6344@192.168.121.2' Request 102: Found
[Apr 28 12:21:51] DEBUG[8169] chan_sip.c: (Provisional) Stopping retransmission (but retaining packet) on '2b7fb75400e3d5926e374f8521bc6344@192.168.121.2' Request 102: Found
[Apr 28 12:21:51] DEBUG[8152] chan_sip.c: Checking device state for peer 01204
[Apr 28 12:21:51] DEBUG[8152] devicestate.c: Changing state for SIP/01204 - state 1 (Not in use)
[Apr 28 12:21:51] DEBUG[8152] devicestate.c: device 'SIP/01204' state '1'
[Apr 28 12:21:51] DEBUG[8176] app_queue.c: Device 'SIP/01204' changed to state '1' (Not in use) but we don't care because they're not a member of any queue.
[Apr 28 12:21:51] DEBUG[8169] chan_sip.c: (Provisional) Stopping retransmission (but retaining packet) on '56352e5f0921f14d467061c32a2b137f@192.168.121.2' Request 102: Found
[Apr 28 12:21:51] DEBUG[8169] chan_sip.c: (Provisional) Stopping retransmission (but retaining packet) on '56352e5f0921f14d467061c32a2b137f@192.168.121.2' Request 102: Found
[Apr 28 12:21:51] DEBUG[8152] chan_sip.c: Checking device state for peer 01205
[Apr 28 12:21:51] DEBUG[8152] devicestate.c: Changing state for SIP/01205 - state 1 (Not in use)
[Apr 28 12:21:51] DEBUG[8152] devicestate.c: device 'SIP/01205' state '1'
[Apr 28 12:21:51] DEBUG[8176] app_queue.c: Device 'SIP/01205' changed to state '1' (Not in use) but we don't care because they're not a member of any queue.
[Apr 28 12:21:52] DEBUG[8169] chan_sip.c: (Provisional) Stopping retransmission (but retaining packet) on '220c670e468ff38639530d5a7ce0db6d@192.168.121.2' Request 102: Found
[Apr 28 12:21:52] DEBUG[8169] chan_sip.c: (Provisional) Stopping retransmission (but retaining packet) on '220c670e468ff38639530d5a7ce0db6d@192.168.121.2' Request 102: Found
[Apr 28 12:21:52] DEBUG[8152] chan_sip.c: Checking device state for peer 01206
[Apr 28 12:21:52] DEBUG[8152] devicestate.c: Changing state for SIP/01206 - state 1 (Not in use)
[Apr 28 12:21:52] DEBUG[8152] devicestate.c: device 'SIP/01206' state '1'
[Apr 28 12:21:52] DEBUG[8176] app_queue.c: Device 'SIP/01206' changed to state '1' (Not in use) but we don't care because they're not a member of any queue.
[Apr 28 12:21:52] DEBUG[19509] rtp.c: Got RTCP report of 52 bytes
[Apr 28 12:21:56] DEBUG[8169] chan_sip.c: Acked pending invite 102
[Apr 28 12:21:56] DEBUG[8169] chan_sip.c: Stopping retransmission on '220c670e468ff38639530d5a7ce0db6d@192.168.121.2' of Request 102: Match Found
[Apr 28 12:21:56] DEBUG[8169] chan_sip.c: We're settling with these formats: 0x8 (alaw)
[Apr 28 12:21:56] DEBUG[8169] chan_sip.c: Updating call counter for outgoing call
[Apr 28 12:21:56] DEBUG[8169] chan_sip.c: build_route: Contact hop: <sip:01206@192.168.121.4:5060>
[Apr 28 12:21:56] DEBUG[8169] chan_sip.c: Trying to put 'ACK sip:01' onto UDP socket destined for 192.168.121.4:5060
[Apr 28 12:21:56] DEBUG[19509] channel.c: Hanging up channel 'SIP/01205-b690a718'
[Apr 28 12:21:56] DEBUG[8152] chan_sip.c: Checking device state for peer 01206
[Apr 28 12:21:56] DEBUG[19509] chan_sip.c: This call was answered elsewhere[Apr 28 12:21:56] DEBUG[19509] chan_sip.c: Hangup call SIP/01205-b690a718, SIP callid 56352e5f0921f14d467061c32a2b137f@192.168.121.2
[Apr 28 12:21:56] DEBUG[8152] devicestate.c: Changing state for SIP/01206 - state 1 (Not in use)
[Apr 28 12:21:56] DEBUG[8152] devicestate.c: device 'SIP/01206' state '1'
[Apr 28 12:21:56] DEBUG[19509] chan_sip.c: Acked pending invite 102
[Apr 28 12:21:56] DEBUG[19509] chan_sip.c: Stopping retransmission on '56352e5f0921f14d467061c32a2b137f@192.168.121.2' of Request 102: Match Found
[Apr 28 12:21:56] DEBUG[8176] app_queue.c: Device 'SIP/01206' changed to state '1' (Not in use) but we don't care because they're not a member of any queue.
[Apr 28 12:21:56] DEBUG[19509] chan_sip.c: Trying to put 'CANCEL sip' onto UDP socket destined for 192.168.121.4:5060
[Apr 28 12:21:56] DEBUG[19509] channel.c: Hanging up channel 'SIP/01204-b6906720'
[Apr 28 12:21:56] DEBUG[8152] chan_sip.c: Checking device state for peer 01205
[Apr 28 12:21:56] DEBUG[19509] chan_sip.c: This call was answered elsewhere[Apr 28 12:21:56] DEBUG[8152] devicestate.c: Changing state for SIP/01205 - state 1 (Not in use)
[Apr 28 12:21:56] DEBUG[8152] devicestate.c: device 'SIP/01205' state '1'
[Apr 28 12:21:56] DEBUG[19509] chan_sip.c: Hangup call SIP/01204-b6906720, SIP callid 2b7fb75400e3d5926e374f8521bc6344@192.168.121.2
[Apr 28 12:21:56] DEBUG[19509] chan_sip.c: Acked pending invite 102
[Apr 28 12:21:56] DEBUG[8176] app_queue.c: Device 'SIP/01205' changed to state '1' (Not in use) but we don't care because they're not a member of any queue.
[Apr 28 12:21:56] DEBUG[19509] chan_sip.c: Stopping retransmission on '2b7fb75400e3d5926e374f8521bc6344@192.168.121.2' of Request 102: Match Found
[Apr 28 12:21:56] DEBUG[19509] chan_sip.c: Trying to put 'CANCEL sip' onto UDP socket destined for 192.168.121.4:5060
[Apr 28 12:21:56] DEBUG[8152] chan_sip.c: Checking device state for peer 01204
[Apr 28 12:21:56] DEBUG[19509] channel.c: Hanging up channel 'SIP/01203-b6901408'
[Apr 28 12:21:56] DEBUG[8152] devicestate.c: Changing state for SIP/01204 - state 1 (Not in use)
[Apr 28 12:21:56] DEBUG[8152] devicestate.c: device 'SIP/01204' state '1'
[Apr 28 12:21:56] DEBUG[19509] chan_sip.c: This call was answered elsewhere[Apr 28 12:21:56] DEBUG[19509] chan_sip.c: Hangup call SIP/01203-b6901408, SIP callid 5c6330a448948551573fe65a20e3f784@192.168.121.2
[Apr 28 12:21:56] DEBUG[19509] chan_sip.c: Acked pending invite 102
[Apr 28 12:21:56] DEBUG[8176] app_queue.c: Device 'SIP/01204' changed to state '1' (Not in use) but we don't care because they're not a member of any queue.
[Apr 28 12:21:56] DEBUG[19509] chan_sip.c: Stopping retransmission on '5c6330a448948551573fe65a20e3f784@192.168.121.2' of Request 102: Match Found
[Apr 28 12:21:56] DEBUG[19509] chan_sip.c: Trying to put 'CANCEL sip' onto UDP socket destined for 192.168.121.4:5060
[Apr 28 12:21:56] DEBUG[8152] chan_sip.c: Checking device state for peer 01203
[Apr 28 12:21:56] DEBUG[19509] channel.c: Hanging up channel 'SIP/01202-0821a348'
[Apr 28 12:21:56] DEBUG[19509] chan_sip.c: This call was answered elsewhere[Apr 28 12:21:56] DEBUG[8152] devicestate.c: Changing state for SIP/01203 - state 1 (Not in use)
[Apr 28 12:21:56] DEBUG[19509] chan_sip.c: Hangup call SIP/01202-0821a348, SIP callid 3719422b395f9a6d67aac23d2d978f68@192.168.121.2
[Apr 28 12:21:56] DEBUG[8152] devicestate.c: device 'SIP/01203' state '1'
[Apr 28 12:21:56] DEBUG[19509] chan_sip.c: Acked pending invite 102
[Apr 28 12:21:56] DEBUG[19509] chan_sip.c: Stopping retransmission on '3719422b395f9a6d67aac23d2d978f68@192.168.121.2' of Request 102: Match Found
[Apr 28 12:21:56] DEBUG[8176] app_queue.c: Device 'SIP/01203' changed to state '1' (Not in use) but we don't care because they're not a member of any queue.
[Apr 28 12:21:56] DEBUG[19509] chan_sip.c: Trying to put 'CANCEL sip' onto UDP socket destined for 192.168.121.4:5060
[Apr 28 12:21:56] DEBUG[8152] chan_sip.c: Checking device state for peer 01202
[Apr 28 12:21:56] DEBUG[19509] channel.c: Hanging up channel 'SIP/01201-b7a476e8'
[Apr 28 12:21:56] DEBUG[8152] devicestate.c: Changing state for SIP/01202 - state 1 (Not in use)
[Apr 28 12:21:56] DEBUG[19509] chan_sip.c: This call was answered elsewhere[Apr 28 12:21:56] DEBUG[8152] devicestate.c: device 'SIP/01202' state '1'
[Apr 28 12:21:56] DEBUG[19509] chan_sip.c: Hangup call SIP/01201-b7a476e8, SIP callid 37214ac663b9985b010ee0703d01a247@192.168.121.2
[Apr 28 12:21:56] DEBUG[19509] chan_sip.c: Acked pending invite 102
[Apr 28 12:21:56] DEBUG[8176] app_queue.c: Device 'SIP/01202' changed to state '1' (Not in use) but we don't care because they're not a member of any queue.
[Apr 28 12:21:56] DEBUG[19509] chan_sip.c: Stopping retransmission on '37214ac663b9985b010ee0703d01a247@192.168.121.2' of Request 102: Match Found
[Apr 28 12:21:56] DEBUG[19509] chan_sip.c: Trying to put 'CANCEL sip' onto UDP socket destined for 192.168.121.4:5060
[Apr 28 12:21:56] DEBUG[8152] chan_sip.c: Checking device state for peer 01201
[Apr 28 12:21:56] DEBUG[19509] channel.c: Set channel SIP/TRUNK_DLINK-b7a46978 to write format alaw
[Apr 28 12:21:56] DEBUG[8152] devicestate.c: Changing state for SIP/01201 - state 1 (Not in use)
[Apr 28 12:21:56] DEBUG[19509] channel.c: Scheduling timer at (0 requested / 0 actual) timer ticks per second
[Apr 28 12:21:56] DEBUG[8152] devicestate.c: device 'SIP/01201' state '1'
[Apr 28 12:21:56] DEBUG[8176] app_queue.c: Device 'SIP/01201' changed to state '1' (Not in use) but we don't care because they're not a member of any queue.
[Apr 28 12:21:56] DEBUG[19509] rtp.c: Ooh, format changed from unknown to alaw
[Apr 28 12:21:56] DEBUG[19509] rtp.c: Created smoother: format: 8 ms: 20 len: 160
[Apr 28 12:21:56] DEBUG[8169] chan_sip.c: Stopping retransmission on '56352e5f0921f14d467061c32a2b137f@192.168.121.2' of Request 102: Match Not Found
[Apr 28 12:21:56] DEBUG[8169] chan_sip.c: Trying to put 'ACK sip:01' onto UDP socket destined for 192.168.121.4:5060
[Apr 28 12:21:56] DEBUG[8169] chan_sip.c: Updating call counter for outgoing call
[Apr 28 12:21:56] DEBUG[8169] chan_sip.c: Setting SIP_ALREADYGONE on dialog 56352e5f0921f14d467061c32a2b137f@192.168.121.2
[Apr 28 12:21:56] DEBUG[8169] chan_sip.c: Stopping retransmission on '56352e5f0921f14d467061c32a2b137f@192.168.121.2' of Request 102: Match Found
[Apr 28 12:21:56] DEBUG[8169] chan_sip.c: Destroying SIP dialog 56352e5f0921f14d467061c32a2b137f@192.168.121.2
[Apr 28 12:21:56] DEBUG[8169] chan_sip.c: Stopping retransmission on '2b7fb75400e3d5926e374f8521bc6344@192.168.121.2' of Request 102: Match Not Found
[Apr 28 12:21:56] DEBUG[8169] chan_sip.c: Trying to put 'ACK sip:01' onto UDP socket destined for 192.168.121.4:5060
[Apr 28 12:21:56] DEBUG[8169] chan_sip.c: Updating call counter for outgoing call
[Apr 28 12:21:56] DEBUG[8169] chan_sip.c: Setting SIP_ALREADYGONE on dialog 2b7fb75400e3d5926e374f8521bc6344@192.168.121.2
[Apr 28 12:21:56] DEBUG[8169] chan_sip.c: Stopping retransmission on '2b7fb75400e3d5926e374f8521bc6344@192.168.121.2' of Request 102: Match Found
[Apr 28 12:21:56] DEBUG[8169] chan_sip.c: Destroying SIP dialog 2b7fb75400e3d5926e374f8521bc6344@192.168.121.2
[Apr 28 12:21:56] DEBUG[8169] chan_sip.c: Stopping retransmission on '5c6330a448948551573fe65a20e3f784@192.168.121.2' of Request 102: Match Not Found
[Apr 28 12:21:56] DEBUG[8169] chan_sip.c: Trying to put 'ACK sip:01' onto UDP socket destined for 192.168.121.4:5060
[Apr 28 12:21:56] DEBUG[8169] chan_sip.c: Updating call counter for outgoing call
[Apr 28 12:21:56] DEBUG[8169] chan_sip.c: Setting SIP_ALREADYGONE on dialog 5c6330a448948551573fe65a20e3f784@192.168.121.2
[Apr 28 12:21:56] DEBUG[8169] chan_sip.c: Stopping retransmission on '5c6330a448948551573fe65a20e3f784@192.168.121.2' of Request 102: Match Found
[Apr 28 12:21:56] DEBUG[8169] chan_sip.c: Destroying SIP dialog 5c6330a448948551573fe65a20e3f784@192.168.121.2
[Apr 28 12:21:56] DEBUG[8169] chan_sip.c: Stopping retransmission on '3719422b395f9a6d67aac23d2d978f68@192.168.121.2' of Request 102: Match Not Found
[Apr 28 12:21:56] DEBUG[8169] chan_sip.c: Trying to put 'ACK sip:01' onto UDP socket destined for 192.168.121.4:5060
[Apr 28 12:21:56] DEBUG[8169] chan_sip.c: Updating call counter for outgoing call
[Apr 28 12:21:56] DEBUG[8169] chan_sip.c: Setting SIP_ALREADYGONE on dialog 3719422b395f9a6d67aac23d2d978f68@192.168.121.2
[Apr 28 12:21:56] DEBUG[8169] chan_sip.c: Stopping retransmission on '3719422b395f9a6d67aac23d2d978f68@192.168.121.2' of Request 102: Match Found
[Apr 28 12:21:56] DEBUG[8169] chan_sip.c: Destroying SIP dialog 3719422b395f9a6d67aac23d2d978f68@192.168.121.2
[Apr 28 12:21:56] DEBUG[8169] chan_sip.c: Stopping retransmission on '37214ac663b9985b010ee0703d01a247@192.168.121.2' of Request 102: Match Not Found
[Apr 28 12:21:56] DEBUG[8169] chan_sip.c: Trying to put 'ACK sip:01' onto UDP socket destined for 192.168.121.4:5060
[Apr 28 12:21:56] DEBUG[8169] chan_sip.c: Updating call counter for outgoing call
[Apr 28 12:21:56] DEBUG[8169] chan_sip.c: Setting SIP_ALREADYGONE on dialog 37214ac663b9985b010ee0703d01a247@192.168.121.2
[Apr 28 12:21:56] DEBUG[8169] chan_sip.c: Stopping retransmission on '37214ac663b9985b010ee0703d01a247@192.168.121.2' of Request 102: Match Found
[Apr 28 12:21:56] DEBUG[8169] chan_sip.c: Destroying SIP dialog 37214ac663b9985b010ee0703d01a247@192.168.121.2
[Apr 28 12:21:57] DEBUG[8169] chan_sip.c: Auto destroying SIP dialog 'D1B9-8A15-466848163DC28BEF8DEF-002@SipHost'
[Apr 28 12:21:57] DEBUG[8169] chan_sip.c: Destroying SIP dialog D1B9-8A15-466848163DC28BEF8DEF-002@SipHost
[Apr 28 12:21:57] DEBUG[8169] chan_sip.c: Auto destroying SIP dialog 'D1B9-8A15-466848163E324B5A719E-003@SipHost'
[Apr 28 12:21:57] DEBUG[8169] chan_sip.c: Destroying SIP dialog D1B9-8A15-466848163E324B5A719E-003@SipHost
[Apr 28 12:21:57] DEBUG[8169] chan_sip.c: Auto destroying SIP dialog 'D1B9-8A15-4668481637F986968B86-004@SipHost'
[Apr 28 12:21:57] DEBUG[8169] chan_sip.c: Destroying SIP dialog D1B9-8A15-4668481637F986968B86-004@SipHost
[Apr 28 12:21:57] DEBUG[8169] chan_sip.c: Auto destroying SIP dialog 'D1B9-8A15-4668481699F9AE82A2B2-005@SipHost'
[Apr 28 12:21:57] DEBUG[8169] chan_sip.c: Destroying SIP dialog D1B9-8A15-4668481699F9AE82A2B2-005@SipHost
[Apr 28 12:21:57] DEBUG[8169] chan_sip.c: Auto destroying SIP dialog 'D1B9-8A15-4668481658F41493E5D9-006@SipHost'
[Apr 28 12:21:57] DEBUG[8169] chan_sip.c: Destroying SIP dialog D1B9-8A15-4668481658F41493E5D9-006@SipHost
[Apr 28 12:21:57] DEBUG[8169] chan_sip.c: Auto destroying SIP dialog 'D1B9-8A15-466848169422F8DF9D67-007@SipHost'
[Apr 28 12:21:57] DEBUG[8169] chan_sip.c: Destroying SIP dialog D1B9-8A15-466848169422F8DF9D67-007@SipHost
[Apr 28 12:21:57] DEBUG[19509] rtp.c: Got RTCP report of 52 bytes
[Apr 28 12:22:01] DEBUG[19509] rtp.c: Got RTCP report of 52 bytes
[Apr 28 12:22:02] DEBUG[19509] rtp.c: Got RTCP report of 52 bytes

89.188.251.130
Кто такой?

Эта строчка есть только у второго звонка. 89.188.251.130 там, по-моему, быть не должно.
По видимому так астер пытается обойти несуществующий НАТ. Можно попробовать в настройках пира указать nat=never. И еще можно настроить определение астером своего айпишнега. Как — не помню.