[May 27 12:57:40] DEBUG[23176] acl.c: Found IP address for this socket
[May 27 12:57:40] DEBUG[23176] chan_sip.c: Setting NAT on RTP to On
[May 27 12:57:40] DEBUG[23176] chan_sip.c: Allocating new SIP dialog for 3c4ddbf8b56b-w9uocf9qjfsl - INVITE (With RTP)
[May 27 12:57:40] DEBUG[23176] chan_sip.c: Setting NAT on RTP to On
[May 27 12:57:40] DEBUG[23176] chan_sip.c: Trying to put 'SIP/2.0 40' onto UDP socket destined for 89.18.254.229:5060
[May 27 12:57:40] DEBUG[23176] chan_sip.c: Stopping retransmission on '3c4ddbf8b56b-w9uocf9qjfsl' of Response 1: Match Found
[May 27 12:57:40] DEBUG[23176] chan_sip.c: Setting NAT on RTP to On
[May 27 12:57:40] DEBUG[23176] chan_sip.c: We're settling with these formats: 0x10e (gsm|ulaw|alaw|g729)
[May 27 12:57:40] DEBUG[23176] chan_sip.c: Checking SIP call limits for device 1000_ilkka
[May 27 12:57:40] DEBUG[23176] chan_sip.c: Updating call counter for incoming call
[May 27 12:57:40] DEBUG[23168] chan_sip.c: Checking device state for peer 1000_ilkka
[May 27 12:57:40] DEBUG[23168] devicestate.c: Changing state for SIP/1000_ilkka - state 2 (In use)
[May 27 12:57:40] DEBUG[23168] devicestate.c: device 'SIP/1000_ilkka' state '2'
[May 27 12:57:40] DEBUG[23176] chan_sip.c: *** Our native formats are 0x4 (ulaw) 
[May 27 12:57:40] DEBUG[23176] chan_sip.c: *** Joint capabilities are 0x10e (gsm|ulaw|alaw|g729) 
[May 27 12:57:40] DEBUG[23176] chan_sip.c: *** Our capabilities are 0x50e (gsm|ulaw|alaw|g729|ilbc) 
[May 27 12:57:40] DEBUG[23195] app_queue.c: Device 'SIP/1000_ilkka' changed to state '2' (In use) but we don't care because they're not a member of any queue.
[May 27 12:57:40] DEBUG[23176] chan_sip.c: *** AST_CODEC_CHOOSE formats are 0x4 (ulaw) 
[May 27 12:57:40] DEBUG[23176] chan_sip.c: This channel will not be able to handle video.
[May 27 12:57:40] DEBUG[23176] chan_sip.c: build_route: Contact hop: <sip:1000_ilkka@89.18.254.229:5060;line=zt5gq9w3>;reg-id=1
[May 27 12:57:40] DEBUG[23176] chan_sip.c: SIP/1000_ilkka-00898448: New call is still down.... Trying... 
[May 27 12:57:40] DEBUG[23176] chan_sip.c: Trying to put 'SIP/2.0 10' onto UDP socket destined for 89.18.254.229:5060
[May 27 12:57:40] DEBUG[23168] chan_sip.c: Checking device state for peer 1000_ilkka
[May 27 12:57:40] DEBUG[23168] devicestate.c: Changing state for SIP/1000_ilkka - state 2 (In use)
[May 27 12:57:40] DEBUG[23168] devicestate.c: device 'SIP/1000_ilkka' state '2'
[May 27 12:57:40] DEBUG[23195] app_queue.c: Device 'SIP/1000_ilkka' changed to state '2' (In use) but we don't care because they're not a member of any queue.
[May 27 12:57:40] DEBUG[23242] res_config_mysql.c: MySQL RealTime: Connection okay.
[May 27 12:57:40] DEBUG[23242] res_config_mysql.c: MySQL RealTime: Retrieve SQL: SELECT * FROM sip_users WHERE name = '1000_ilkka'
[May 27 12:57:40] DEBUG[23242] pbx.c: Function result is 'id=167:name=1000_ilkka:trunk=DAHDI/g1:callerid=Ilkka Nojonen <+358942419900>:nickname=none:canreinvite=no:context=1000:client=1000:dtmfmode=rfc2833:fullcontact=sip:1000_ilkka@89.18.254.229:5060:fullcontact=line=zt5gq9w3:useragent=snom370/7.3.10a:host=dynamic:limitonpeer=yes:call-limit=999:nat=yes:port=5060:regstat=0:lastms=57:qualify=yes:allowsubscribe=yes:secret=nojonen:type=friend:username=1000_ilkka:disallow=all:allow=ulaw:allow=alaw:allow=g729:allow=ilbc:allow=gsm:regseconds=1243421616:ipaddr=89.18.254.229:regexten=358942419900:cancallforward=yes:'
[May 27 12:57:40] DEBUG[23242] pbx.c: Launching 'Set'
[May 27 12:57:40] DEBUG[23242] pbx.c: Launching 'AGI'
[May 27 12:57:40] DEBUG[23242] pbx.c: Launching 'Goto'
[May 27 12:57:40] DEBUG[23242] res_config_mysql.c: MySQL RealTime: Connection okay.
[May 27 12:57:40] DEBUG[23242] res_config_mysql.c: MySQL RealTime: Retrieve SQL: SELECT * FROM extensions WHERE exten = '358137790000' AND context = 'progress' AND priority = '1'
[May 27 12:57:40] DEBUG[23242] res_config_mysql.c: MySQL RealTime: Connection okay.
[May 27 12:57:40] DEBUG[23242] res_config_mysql.c: MySQL RealTime: Retrieve SQL: SELECT * FROM extensions WHERE exten LIKE '\\_%' AND context = 'progress' AND priority = '1' ORDER BY exten
[May 27 12:57:40] DEBUG[23242] res_config_mysql.c: MySQL RealTime: Connection okay.
[May 27 12:57:40] DEBUG[23242] res_config_mysql.c: MySQL RealTime: Retrieve SQL: SELECT * FROM extensions WHERE exten = '358137790000' AND context = 'progress' AND priority = '1'
[May 27 12:57:40] DEBUG[23242] res_config_mysql.c: MySQL RealTime: Connection okay.
[May 27 12:57:40] DEBUG[23242] res_config_mysql.c: MySQL RealTime: Retrieve SQL: SELECT * FROM extensions WHERE exten LIKE '\\_%' AND context = 'progress' AND priority = '1' ORDER BY exten
[May 27 12:57:40] DEBUG[23242] pbx.c: Launching 'Verbose'
[May 27 12:57:40] DEBUG[23242] pbx.c: Expression result is '1'
[May 27 12:57:40] DEBUG[23242] pbx.c: Launching 'GotoIf'
[May 27 12:57:40] DEBUG[23242] pbx.c: Launching 'Goto'
[May 27 12:57:40] DEBUG[23242] pbx.c: Launching 'AGI'
[May 27 12:57:40] DEBUG[23242] chan_dahdi.c: Using channel 1
[May 27 12:57:40] DEBUG[23242] dsp.c: Setup tone 1100 Hz, 500 ms, block_size=160, hits_required=21
[May 27 12:57:40] DEBUG[23242] dsp.c: Setup tone 2100 Hz, 2600 ms, block_size=160, hits_required=116
[May 27 12:57:40] DEBUG[23242] devicestate.c: device 'DAHDI/1-1' state '2'
[May 27 12:57:40] DEBUG[23195] app_queue.c: Device 'DAHDI/1-1' changed to state '2' (In use) but we don't care because they're not a member of any queue.
[May 27 12:57:40] DEBUG[23242] rtp.c: Channel 'DAHDI/1-1' has no RTP, not doing anything
[May 27 12:57:40] DEBUG[23242] channel.c: Not copying variable DIALEDTIME.
[May 27 12:57:40] DEBUG[23242] channel.c: Not copying variable ANSWEREDTIME.
[May 27 12:57:40] DEBUG[23242] channel.c: Not copying variable DIALEDPEERNAME.
[May 27 12:57:40] DEBUG[23242] channel.c: Not copying variable DIALEDPEERNUMBER.
[May 27 12:57:40] DEBUG[23242] channel.c: Not copying variable DIALSTATUS.
[May 27 12:57:40] DEBUG[23242] channel.c: Not copying variable cli_out.
[May 27 12:57:40] DEBUG[23242] channel.c: Not copying variable INVALID_EXTEN.
[May 27 12:57:40] DEBUG[23242] channel.c: Not copying variable AGISTATUS.
[May 27 12:57:40] DEBUG[23242] channel.c: Not copying variable exten_out.
[May 27 12:57:40] DEBUG[23242] channel.c: Not copying variable exten_sys.
[May 27 12:57:40] DEBUG[23242] channel.c: Not copying variable in_exten.
[May 27 12:57:40] DEBUG[23242] channel.c: Not copying variable in_clid.
[May 27 12:57:40] DEBUG[23242] channel.c: Not copying variable user_trunk.
[May 27 12:57:40] DEBUG[23242] channel.c: Not copying variable realtime.
[May 27 12:57:40] DEBUG[23242] channel.c: Not copying variable SIPCALLID.
[May 27 12:57:40] DEBUG[23242] channel.c: Not copying variable SIPDOMAIN.
[May 27 12:57:40] DEBUG[23242] channel.c: Not copying variable SIPURI.
[May 27 12:57:40] DEBUG[23168] devicestate.c: Changing state for DAHDI/1 - state 2 (In use)
[May 27 12:57:40] DEBUG[23168] devicestate.c: device 'DAHDI/1' state '2'
[May 27 12:57:40] DEBUG[23195] app_queue.c: Device 'DAHDI/1' changed to state '2' (In use) but we don't care because they're not a member of any queue.
[May 27 12:57:40] DEBUG[23242] channel.c: Set channel DAHDI/1-1 to read format ulaw
[May 27 12:57:40] DEBUG[23242] channel.c: Set channel SIP/1000_ilkka-00898448 to read format alaw
[May 27 12:57:40] DEBUG[23176] chan_sip.c: Auto destroying SIP dialog 'd348ff8f9c7e5e8f@62.78.210.176'
[May 27 12:57:40] DEBUG[23176] chan_sip.c: Destroying SIP dialog d348ff8f9c7e5e8f@62.78.210.176
[May 27 12:57:40] DEBUG[23176] chan_sip.c: Auto destroying SIP dialog '75f9b5f95b288e96@82.181.47.64'
[May 27 12:57:40] DEBUG[23176] chan_sip.c: Destroying SIP dialog 75f9b5f95b288e96@82.181.47.64
[May 27 12:57:40] DEBUG[23178] chan_dahdi.c: Enabled echo cancellation on channel 1
[May 27 12:57:40] DEBUG[23168] devicestate.c: Changing state for DAHDI/1 - state 2 (In use)
[May 27 12:57:40] DEBUG[23168] devicestate.c: device 'DAHDI/1' state '2'
[May 27 12:57:40] DEBUG[23242] chan_sip.c: SIP answering channel: SIP/1000_ilkka-00898448
[May 27 12:57:40] DEBUG[23168] chan_sip.c: Checking device state for peer 1000_ilkka
[May 27 12:57:40] DEBUG[23195] app_queue.c: Device 'DAHDI/1' changed to state '2' (In use) but we don't care because they're not a member of any queue.
[May 27 12:57:40] DEBUG[23168] devicestate.c: Changing state for SIP/1000_ilkka - state 2 (In use)
[May 27 12:57:40] DEBUG[23168] devicestate.c: device 'SIP/1000_ilkka' state '2'
[May 27 12:57:40] DEBUG[23242] chan_sip.c: Setting framing from config on incoming call
[May 27 12:57:40] DEBUG[23242] chan_sip.c: ** Our capability: 0x10e (gsm|ulaw|alaw|g729) Video flag: True Text flag: True
[May 27 12:57:40] DEBUG[23195] app_queue.c: Device 'SIP/1000_ilkka' changed to state '2' (In use) but we don't care because they're not a member of any queue.
[May 27 12:57:40] DEBUG[23242] chan_sip.c: ** Our prefcodec: 0x0 (nothing) 
[May 27 12:57:40] DEBUG[23242] chan_sip.c: -- Done with adding codecs to SDP
[May 27 12:57:40] DEBUG[23242] chan_sip.c: Done building SDP. Settling with this capability: 0x10e (gsm|ulaw|alaw|g729)
[May 27 12:57:40] DEBUG[23242] chan_sip.c: Trying to put 'SIP/2.0 20' onto UDP socket destined for 89.18.254.229:5060
[May 27 12:57:40] DEBUG[23242] chan_dahdi.c: Requested indication 20 on channel DAHDI/1-1
[May 27 12:57:40] DEBUG[23176] chan_sip.c: Stopping retransmission on '3c4ddbf8b56b-w9uocf9qjfsl' of Response 2: Match Found
[May 27 12:57:40] DEBUG[23242] rtp.c: Got RTCP report of 68 bytes
[May 27 12:57:40] DEBUG[23242] chan_dahdi.c: Dropping frame since I'm still dialing on DAHDI/1-1...
[May 27 12:57:40] DEBUG[23242] chan_dahdi.c: Dropping frame since I'm still dialing on DAHDI/1-1...
[May 27 12:57:40] DEBUG[23242] chan_dahdi.c: Dropping frame since I'm still dialing on DAHDI/1-1...
[May 27 12:57:40] DEBUG[23242] chan_dahdi.c: Dropping frame since I'm still dialing on DAHDI/1-1...
[May 27 12:57:40] DEBUG[23242] chan_dahdi.c: Dropping frame since I'm still dialing on DAHDI/1-1...
[May 27 12:57:40] DEBUG[23242] chan_dahdi.c: Dropping frame since I'm still dialing on DAHDI/1-1...
[May 27 12:57:40] DEBUG[23242] chan_dahdi.c: Dropping frame since I'm still dialing on DAHDI/1-1...
[May 27 12:57:40] DEBUG[23242] chan_dahdi.c: Dropping frame since I'm still dialing on DAHDI/1-1...
[May 27 12:57:40] DEBUG[23242] chan_dahdi.c: Dropping frame since I'm still dialing on DAHDI/1-1...
[May 27 12:57:40] DEBUG[23242] chan_dahdi.c: Dropping frame since I'm still dialing on DAHDI/1-1...
[May 27 12:57:40] DEBUG[23242] chan_dahdi.c: Dropping frame since I'm still dialing on DAHDI/1-1...
[May 27 12:57:41] DEBUG[23242] chan_dahdi.c: Dropping frame since I'm still dialing on DAHDI/1-1...
[May 27 12:57:41] DEBUG[23242] chan_dahdi.c: Dropping frame since I'm still dialing on DAHDI/1-1...
[May 27 12:57:41] DEBUG[23242] chan_dahdi.c: Dropping frame since I'm still dialing on DAHDI/1-1...
[May 27 12:57:41] DEBUG[23242] chan_dahdi.c: Dropping frame since I'm still dialing on DAHDI/1-1...
[May 27 12:57:41] DEBUG[23242] chan_dahdi.c: Dropping frame since I'm still dialing on DAHDI/1-1...
[May 27 12:57:41] DEBUG[23242] chan_dahdi.c: Dropping frame since I'm still dialing on DAHDI/1-1...
[May 27 12:57:41] DEBUG[23242] chan_dahdi.c: Dropping frame since I'm still dialing on DAHDI/1-1...
[May 27 12:57:41] DEBUG[23242] chan_dahdi.c: Dropping frame since I'm still dialing on DAHDI/1-1...
[May 27 12:57:41] DEBUG[23242] chan_dahdi.c: Dropping frame since I'm still dialing on DAHDI/1-1...
[May 27 12:57:41] DEBUG[23242] chan_dahdi.c: Dropping frame since I'm still dialing on DAHDI/1-1...
[May 27 12:57:41] DEBUG[23242] chan_dahdi.c: Dropping frame since I'm still dialing on DAHDI/1-1...
[May 27 12:57:41] DEBUG[23242] chan_dahdi.c: Dropping frame since I'm still dialing on DAHDI/1-1...
[May 27 12:57:41] DEBUG[23242] chan_dahdi.c: Dropping frame since I'm still dialing on DAHDI/1-1...
[May 27 12:57:41] DEBUG[23242] chan_dahdi.c: Dropping frame since I'm still dialing on DAHDI/1-1...
[May 27 12:57:41] DEBUG[23242] chan_dahdi.c: Dropping frame since I'm still dialing on DAHDI/1-1...
[May 27 12:57:41] DEBUG[23242] chan_dahdi.c: Dropping frame since I'm still dialing on DAHDI/1-1...
[May 27 12:57:41] DEBUG[23242] chan_dahdi.c: Dropping frame since I'm still dialing on DAHDI/1-1...
[May 27 12:57:41] DEBUG[23242] chan_dahdi.c: Dropping frame since I'm still dialing on DAHDI/1-1...
[May 27 12:57:41] DEBUG[23242] chan_dahdi.c: Dropping frame since I'm still dialing on DAHDI/1-1...
[May 27 12:57:41] DEBUG[23242] chan_dahdi.c: Dropping frame since I'm still dialing on DAHDI/1-1...