[Jan 31 02:03:18] DEBUG[10183]: chan_sip.c:2694 do_setnat: Setting NAT on RTP to Off
[Jan 31 02:03:18] DEBUG[10183]: chan_sip.c:4399 sip_alloc: Allocating new SIP dialog for 1a6f6681-34af-db11-8019-000fcbb01957@eoyslebo-laptop - INVITE (With RTP)
[Jan 31 02:03:18] DEBUG[10183]: chan_sip.c:5196 process_sdp: T38 state changed to 0 on channel <none>
[Jan 31 02:03:18] DEBUG[10183]: chan_sip.c:5273 process_sdp: We're settling with these formats: 0xe (gsm|ulaw|alaw)
[Jan 31 02:03:18] DEBUG[10183]: chan_sip.c:13535 handle_request_invite: Checking SIP call limits for device 
[Jan 31 02:03:18] DEBUG[10183]: chan_sip.c:3119 update_call_counter: Updating call counter for incoming call
[Jan 31 02:03:18] DEBUG[10183]: chan_sip.c:3903 sip_new: *** Our native formats are 0x4 (ulaw) 
[Jan 31 02:03:18] DEBUG[10183]: chan_sip.c:3904 sip_new: *** Joint capabilities are 0xe (gsm|ulaw|alaw) 
[Jan 31 02:03:18] DEBUG[10183]: chan_sip.c:3905 sip_new: *** Our capabilities are 0x8000e (gsm|ulaw|alaw|h263) 
[Jan 31 02:03:18] DEBUG[10183]: chan_sip.c:3906 sip_new: *** AST_CODEC_CHOOSE formats are 0x4 (ulaw) 
[Jan 31 02:03:18] DEBUG[10183]: chan_sip.c:3929 sip_new: This channel will not be able to handle video.
[Jan 31 02:03:18] DEBUG[10183]: chan_sip.c:8005 build_route: build_route: Contact hop: <sip:6000@10.10.10.108:5096;transport=udp>
[Jan 31 02:03:18] DEBUG[10183]: chan_sip.c:13610 handle_request_invite: SIP/localhost-081c55c0: New call is still down.... Trying... 
[Jan 31 02:03:18] DEBUG[10183]: devicestate.c:387 __ast_device_state_changed_literal: Notification of state change to be queued on device/channel SIP/localhost-081c55c0
[Jan 31 02:03:18] DEBUG[10183]: chan_sip.c:15359 sip_devicestate: Checking device state for peer localhost
[Jan 31 02:03:18] DEBUG[10183]: devicestate.c:371 do_state_change: Changing state for SIP/localhost - state 2 (In use)
[Jan 31 02:03:18] DEBUG[10183]: pbx.c:1693 pbx_extension_helper: Launching 'Dial'
[Jan 31 02:03:18] DEBUG[10183]: rtp.c:1601 ast_rtp_make_compatible: Channel 'CELL/Espen-3f3a' has no RTP, not doing anything
[Jan 31 02:03:18] DEBUG[10183]: channel.c:3203 ast_channel_inherit_variables: Not copying variable STACK-default-9999-1.
[Jan 31 02:03:18] DEBUG[10183]: channel.c:3203 ast_channel_inherit_variables: Not copying variable SIPCALLID.
[Jan 31 02:03:18] DEBUG[10183]: channel.c:3203 ast_channel_inherit_variables: Not copying variable SIPDOMAIN.
[Jan 31 02:03:18] DEBUG[10183]: channel.c:3203 ast_channel_inherit_variables: Not copying variable SIPURI.
[Jan 31 02:03:18] DEBUG[10183]: chan_cellphone.c:370 cel_call: Calling Espen/22334455 on CELL/Espen-3f3a
[Jan 31 02:03:18] DEBUG[10183]: channel.c:2753 set_format: Set channel CELL/Espen-3f3a to read format ulaw
[Jan 31 02:03:18] DEBUG[10183]: channel.c:2753 set_format: Set channel SIP/localhost-081c55c0 to read format slin
]Jan 31 02:03:18] DEBUG[10183]: chan_cellphone.c:631 rfcomm_write: rfcomm_write() (20) [ATD22334455;
[Jan 31 02:03:18] DEBUG[10183]: app_queue.c:568 changethread: Device 'SIP/localhost' changed to state '2' (In use) but we don't care because they're not a member of any queue.
]Jan 31 02:03:18] DEBUG[10183]: chan_cellphone.c:800 do_monitor: rfcomm_read() (20) [
]Jan 31 02:03:18] DEBUG[10183]: chan_cellphone.c:800 do_monitor: rfcomm_read() (20) [ERROR
[Jan 31 02:03:26] ERROR[10183]: chan_cellphone.c:961 do_monitor: Dial failed on CELL/Espen-3f3a
[Jan 31 02:03:26] DEBUG[10183]: channel.c:1589 ast_hangup: Hanging up channel 'CELL/Espen-3f3a'
[Jan 31 02:03:26] DEBUG[10183]: chan_cellphone.c:391 cel_hangup: Hanging up device Espen.
[Jan 31 02:03:26] DEBUG[10183]: devicestate.c:387 __ast_device_state_changed_literal: Notification of state change to be queued on device/channel CELL/Espen-3f3a
[Jan 31 02:03:26] DEBUG[10183]: rtp.c:1538 ast_rtp_early_bridge: Channel '<unspecified>' has no RTP, not doing anything
[Jan 31 02:03:26] DEBUG[10183]: app_dial.c:1682 dial_exec_full: Exiting with DIALSTATUS=CONGESTION.
[Jan 31 02:03:26] DEBUG[10183]: chan_cellphone.c:575 cel_devicestate: Checking device state for device Espen
[Jan 31 02:03:26] DEBUG[10183]: devicestate.c:371 do_state_change: Changing state for CELL/Espen - state 1 (Not in use)
[Jan 31 02:03:26] DEBUG[10183]: app_queue.c:568 changethread: Device 'CELL/Espen' changed to state '1' (Not in use) but we don't care because they're not a member of any queue.
[Jan 31 02:03:36] DEBUG[10183]: pbx.c:1693 pbx_extension_helper: Launching 'Goto'
[Jan 31 02:03:36] DEBUG[10183]: pbx.c:1693 pbx_extension_helper: Launching 'Playback'
[Jan 31 02:03:36] DEBUG[10183]: devicestate.c:387 __ast_device_state_changed_literal: Notification of state change to be queued on device/channel SIP/localhost-081c55c0
[Jan 31 02:03:36] DEBUG[10183]: chan_sip.c:3565 sip_answer: SIP answering channel: SIP/localhost-081c55c0
[Jan 31 02:03:36] DEBUG[10183]: chan_sip.c:6501 transmit_response_with_sdp: Setting framing from config on incoming call
[Jan 31 02:03:36] DEBUG[10183]: chan_sip.c:6276 add_sdp: ** Our capability: 0xe (gsm|ulaw|alaw) Video flag: False
[Jan 31 02:03:36] DEBUG[10183]: chan_sip.c:6277 add_sdp: ** Our prefcodec: 0x0 (nothing) 
[Jan 31 02:03:36] DEBUG[10183]: chan_sip.c:6402 add_sdp: -- Done with adding codecs to SDP
[Jan 31 02:03:36] DEBUG[10183]: chan_sip.c:6446 add_sdp: Done building SDP. Settling with this capability: 0xe (gsm|ulaw|alaw)
[Jan 31 02:03:36] DEBUG[10183]: chan_sip.c:15359 sip_devicestate: Checking device state for peer localhost
[Jan 31 02:03:36] DEBUG[10183]: devicestate.c:371 do_state_change: Changing state for SIP/localhost - state 2 (In use)
[Jan 31 02:03:36] DEBUG[10183]: app_queue.c:568 changethread: Device 'SIP/localhost' changed to state '2' (In use) but we don't care because they're not a member of any queue.
[Jan 31 02:03:36] DEBUG[10183]: chan_sip.c:2130 __sip_ack: Stopping retransmission on '1a6f6681-34af-db11-8019-000fcbb01957@eoyslebo-laptop' of Response 1: Match Found
[Jan 31 02:03:36] DEBUG[10183]: channel.c:2753 set_format: Set channel SIP/localhost-081c55c0 to write format gsm
[Jan 31 02:03:36] DEBUG[10183]: rtp.c:2737 ast_rtp_write: Ooh, format changed from unknown to ulaw
[Jan 31 02:03:36] DEBUG[10183]: rtp.c:2754 ast_rtp_write: Created smoother: format: 4 ms: 20 len: 160
[Jan 31 02:03:38] DEBUG[10183]: rtp.c:921 ast_rtcp_read: Got RTCP report of 80 bytes
[Jan 31 02:03:38] DEBUG[10183]: chan_sip.c:4181 sip_rtp_read: Oooh, format changed to 2
[Jan 31 02:03:38] DEBUG[10183]: channel.c:2753 set_format: Set channel SIP/localhost-081c55c0 to read format slin
[Jan 31 02:03:38] DEBUG[10183]: channel.c:2753 set_format: Set channel SIP/localhost-081c55c0 to write format gsm
[Jan 31 02:03:38] DEBUG[10183]: rtp.c:2737 ast_rtp_write: Ooh, format changed from ulaw to gsm
[Jan 31 02:03:38] DEBUG[10183]: rtp.c:2754 ast_rtp_write: Created smoother: format: 2 ms: 20 len: 33
[Jan 31 02:03:41] DEBUG[10183]: channel.c:2753 set_format: Set channel SIP/localhost-081c55c0 to write format ulaw
[Jan 31 02:03:41] DEBUG[10183]: pbx.c:1693 pbx_extension_helper: Launching 'Hangup'
[Jan 31 02:03:41] DEBUG[10183]: pbx.c:2289 __ast_pbx_run: Spawn extension (default,#,2) exited non-zero on 'SIP/localhost-081c55c0'
[Jan 31 02:03:41] DEBUG[10183]: pbx.c:1543 pbx_substitute_variables_helper_full: Function result is '"Espen Oyslebo" <6000>'
[Jan 31 02:03:41] DEBUG[10183]: pbx.c:1543 pbx_substitute_variables_helper_full: Function result is '6000'
[Jan 31 02:03:41] DEBUG[10183]: pbx.c:1543 pbx_substitute_variables_helper_full: Function result is '#'
[Jan 31 02:03:41] DEBUG[10183]: pbx.c:1543 pbx_substitute_variables_helper_full: Function result is 'default'
[Jan 31 02:03:41] DEBUG[10183]: pbx.c:1543 pbx_substitute_variables_helper_full: Function result is 'SIP/localhost-081c55c0'
[Jan 31 02:03:41] DEBUG[10183]: pbx.c:1543 pbx_substitute_variables_helper_full: Function result is 'CELL/Espen-3f3a'
[Jan 31 02:03:41] DEBUG[10183]: pbx.c:1543 pbx_substitute_variables_helper_full: Function result is 'Hangup'
[Jan 31 02:03:41] DEBUG[10183]: pbx.c:1543 pbx_substitute_variables_helper_full: Function result is ''
[Jan 31 02:03:41] DEBUG[10183]: pbx.c:1543 pbx_substitute_variables_helper_full: Function result is '2007-01-31 02:03:18'
[Jan 31 02:03:41] DEBUG[10183]: pbx.c:1543 pbx_substitute_variables_helper_full: Function result is '2007-01-31 02:03:36'
[Jan 31 02:03:41] DEBUG[10183]: pbx.c:1543 pbx_substitute_variables_helper_full: Function result is '2007-01-31 02:03:41'
[Jan 31 02:03:41] DEBUG[10183]: pbx.c:1543 pbx_substitute_variables_helper_full: Function result is '23'
[Jan 31 02:03:41] DEBUG[10183]: pbx.c:1543 pbx_substitute_variables_helper_full: Function result is '5'
[Jan 31 02:03:41] DEBUG[10183]: pbx.c:1543 pbx_substitute_variables_helper_full: Function result is 'ANSWERED'
[Jan 31 02:03:41] DEBUG[10183]: pbx.c:1543 pbx_substitute_variables_helper_full: Function result is 'DOCUMENTATION'
[Jan 31 02:03:41] DEBUG[10183]: pbx.c:1543 pbx_substitute_variables_helper_full: Function result is ''
[Jan 31 02:03:41] DEBUG[10183]: pbx.c:1543 pbx_substitute_variables_helper_full: Function result is '1170205398.2'
[Jan 31 02:03:41] DEBUG[10183]: pbx.c:1543 pbx_substitute_variables_helper_full: Function result is ''
[Jan 31 02:03:41] DEBUG[10183]: channel.c:1589 ast_hangup: Hanging up channel 'SIP/localhost-081c55c0'
[Jan 31 02:03:41] DEBUG[10183]: chan_sip.c:3417 sip_hangup: Hangup call SIP/localhost-081c55c0, SIP callid 1a6f6681-34af-db11-8019-000fcbb01957@eoyslebo-laptop)
[Jan 31 02:03:41] DEBUG[10183]: chan_sip.c:3119 update_call_counter: Updating call counter for incoming call
[Jan 31 02:03:41] DEBUG[10183]: devicestate.c:387 __ast_device_state_changed_literal: Notification of state change to be queued on device/channel SIP/localhost-081c55c0
[Jan 31 02:03:41] DEBUG[10183]: chan_sip.c:15359 sip_devicestate: Checking device state for peer localhost
[Jan 31 02:03:41] DEBUG[10183]: devicestate.c:371 do_state_change: Changing state for SIP/localhost - state 1 (Not in use)
[Jan 31 02:03:41] DEBUG[10183]: chan_sip.c:2130 __sip_ack: Stopping retransmission on '1a6f6681-34af-db11-8019-000fcbb01957@eoyslebo-laptop' of Request 102: Match Found
Really destroying SIP dialog '1a6f6681-34af-db11-8019-000fcbb01957@eoyslebo-laptop' Method: ACK
[Jan 31 02:03:41] DEBUG[10183]: app_queue.c:568 changethread: Device 'SIP/localhost' changed to state '1' (Not in use) but we don't care because they're not a member of any queue.