rendered paste bodybrian@taz [Sat Sep 02 07:29 PM] /usr/local/src/freeswitch.trunk
<25>:TPORT_LOG=1 NTA_DEBUG=9 ./freeswitch
2006-09-02 19:29:34 [CONSOLE] switch_core.c:3233 switch_core_init_and_modload() Bringing up environment.
2006-09-02 19:29:34 [CONSOLE] switch_core.c:3234 switch_core_init_and_modload() Loading Modules.
2006-09-02 19:29:34 [CONSOLE] switch_loadable_module.c:305 switch_loadable_module_load_file() Successfully Loaded [mod_console]
2006-09-02 19:29:34 [CONSOLE] switch_loadable_module.c:305 switch_loadable_module_load_file() Successfully Loaded [mod_sofia]
2006-09-02 19:29:34 [NOTICE] mod_sofia.c:1749 config_sofia() Started Profile test [sip:10.0.1.251:5060]
2006-09-02 19:29:34 [NOTICE] switch_loadable_module.c:99 switch_loadable_module_process() Adding Endpoint 'sofia'
nta_agent_create: initialized hash tables
nta_agent_create: initialized transports
nta_agent_create: initialized random identifiers
nta_agent_create: initialized timer
nta_agent_create: initialized resolver
2006-09-02 19:29:34 [CONSOLE] switch_loadable_module.c:305 switch_loadable_module_load_file() Successfully Loaded [mod_iax]
nta: master transport created
2006-09-02 19:29:34 [CONSOLE] switch_loadable_module.c:282 switch_loadable_module_load_file() Error Loading module /usr/local/freeswitch/mod/mod_portaudio.dylib
**cannot create object file image or add library**
2006-09-02 19:29:34 [NOTICE] switch_loadable_module.c:99 switch_loadable_module_process() Adding Endpoint 'iax'
2006-09-02 19:29:34 [CONSOLE] switch_loadable_module.c:305 switch_loadable_module_load_file() Successfully Loaded [mod_bridgecall]
2006-09-02 19:29:34 [INFO] mod_iax.c:921 switch_module_runtime() IAX Ready Port 4569
2006-09-02 19:29:34 [NOTICE] switch_loadable_module.c:160 switch_loadable_module_process() Adding Application 'bridge'
2006-09-02 19:29:34 [CONSOLE] switch_loadable_module.c:305 switch_loadable_module_load_file() Successfully Loaded [mod_echo]
2006-09-02 19:29:34 [NOTICE] switch_loadable_module.c:160 switch_loadable_module_process() Adding Application 'echo'
2006-09-02 19:29:34 [CONSOLE] switch_loadable_module.c:305 switch_loadable_module_load_file() Successfully Loaded [mod_dptools]
2006-09-02 19:29:34 [NOTICE] switch_loadable_module.c:160 switch_loadable_module_process() Adding Application 'sleep'
2006-09-02 19:29:34 [NOTICE] switch_loadable_module.c:160 switch_loadable_module_process() Adding Application 'strftime'
2006-09-02 19:29:34 [NOTICE] switch_loadable_module.c:160 switch_loadable_module_process() Adding Application 'answer'
2006-09-02 19:29:34 [NOTICE] switch_loadable_module.c:160 switch_loadable_module_process() Adding Application 'set'
2006-09-02 19:29:34 [NOTICE] switch_loadable_module.c:175 switch_loadable_module_process() Adding API Function 'strftime'
2006-09-02 19:29:34 [CONSOLE] switch_loadable_module.c:305 switch_loadable_module_load_file() Successfully Loaded [mod_playback]
nta: bound to (10.0.1.251:5060;transport=*)
nta: agent_init_via: SIP/2.0/udp 10.0.1.251 (sip)
2006-09-02 19:29:34 [NOTICE] switch_loadable_module.c:160 switch_loadable_module_process() Adding Application 'playback'
nta: agent_init_via: SIP/2.0/tcp 10.0.1.251 (sip)
2006-09-02 19:29:34 [NOTICE] switch_loadable_module.c:160 switch_loadable_module_process() Adding Application 'record'
2006-09-02 19:29:34 [NOTICE] switch_loadable_module.c:160 switch_loadable_module_process() Adding Application 'speak'
2006-09-02 19:29:34 [CONSOLE] switch_loadable_module.c:305 switch_loadable_module_load_file() Successfully Loaded [mod_commands]
nta: Via fields initialized
nta: Contact header created
2006-09-02 19:29:34 [NOTICE] switch_loadable_module.c:175 switch_loadable_module_process() Adding API Function 'originate'
2006-09-02 19:29:34 [NOTICE] switch_loadable_module.c:175 switch_loadable_module_process() Adding API Function 'killchan'
2006-09-02 19:29:34 [NOTICE] switch_loadable_module.c:175 switch_loadable_module_process() Adding API Function 'reloadxml'
2006-09-02 19:29:34 [NOTICE] switch_loadable_module.c:175 switch_loadable_module_process() Adding API Function 'load'
2006-09-02 19:29:34 [NOTICE] switch_loadable_module.c:175 switch_loadable_module_process() Adding API Function 'transfer'
2006-09-02 19:29:34 [NOTICE] switch_loadable_module.c:175 switch_loadable_module_process() Adding API Function 'pause'
2006-09-02 19:29:34 [NOTICE] switch_loadable_module.c:175 switch_loadable_module_process() Adding API Function 'show'
2006-09-02 19:29:34 [NOTICE] switch_loadable_module.c:175 switch_loadable_module_process() Adding API Function 'status'
2006-09-02 19:29:34 [CONSOLE] switch_loadable_module.c:305 switch_loadable_module_load_file() Successfully Loaded [mod_dialplan_xml]
2006-09-02 19:29:34 [NOTICE] switch_loadable_module.c:132 switch_loadable_module_process() Adding Dialplan 'XML'
2006-09-02 19:29:34 [CONSOLE] switch_loadable_module.c:305 switch_loadable_module_load_file() Successfully Loaded [mod_g711]
2006-09-02 19:29:34 [NOTICE] switch_loadable_module.c:110 switch_loadable_module_process() Adding Codec 'PCMU' (g711 ulaw) 8000khz 20ms
2006-09-02 19:29:34 [NOTICE] switch_loadable_module.c:110 switch_loadable_module_process() Adding Codec 'PCMA' (g711 alaw) 8000khz 20ms
2006-09-02 19:29:34 [DEBUG] mod_sofia.c:1433 event_callback() event [nua_r_set_params] status [200] [OK]
2006-09-02 19:29:34 [DEBUG] mod_sofia.c:1544 event_callback() nua_r_set_params: unknown event 23: 200 OK
2006-09-02 19:29:34 [CONSOLE] switch_loadable_module.c:305 switch_loadable_module_load_file() Successfully Loaded [mod_g729]
2006-09-02 19:29:34 [NOTICE] switch_loadable_module.c:110 switch_loadable_module_process() Adding Codec 'G729a' (g729) 8000khz 20ms
2006-09-02 19:29:34 [NOTICE] switch_loadable_module.c:110 switch_loadable_module_process() Adding Codec 'G729a' (g729) 8000khz 10ms
2006-09-02 19:29:34 [NOTICE] switch_loadable_module.c:110 switch_loadable_module_process() Adding Codec 'G729' (g729) 8000khz 20ms
2006-09-02 19:29:34 [NOTICE] switch_loadable_module.c:110 switch_loadable_module_process() Adding Codec 'G729' (g729) 8000khz 10ms
2006-09-02 19:29:34 [CONSOLE] switch_loadable_module.c:305 switch_loadable_module_load_file() Successfully Loaded [mod_g726]
2006-09-02 19:29:34 [NOTICE] switch_loadable_module.c:110 switch_loadable_module_process() Adding Codec 'AAL2-G726-40' (G.726 40k (aal2)) 8000khz 20ms
2006-09-02 19:29:34 [NOTICE] switch_loadable_module.c:110 switch_loadable_module_process() Adding Codec 'AAL2-G726-32' (G.726 32k (aal2)) 8000khz 20ms
2006-09-02 19:29:34 [NOTICE] switch_loadable_module.c:110 switch_loadable_module_process() Adding Codec 'AAL2-G726-24' (G.726 24k (aal2)) 8000khz 20ms
2006-09-02 19:29:34 [NOTICE] switch_loadable_module.c:110 switch_loadable_module_process() Adding Codec 'AAL2-G726-16' (G.726 16k (aal2)) 8000khz 20ms
2006-09-02 19:29:34 [NOTICE] switch_loadable_module.c:110 switch_loadable_module_process() Adding Codec 'G726-40' (G.726 40k) 8000khz 20ms
2006-09-02 19:29:34 [NOTICE] switch_loadable_module.c:110 switch_loadable_module_process() Adding Codec 'G726-32' (G.726 32k) 8000khz 20ms
2006-09-02 19:29:34 [NOTICE] switch_loadable_module.c:110 switch_loadable_module_process() Adding Codec 'G726-24' (G.726 24k) 8000khz 20ms
2006-09-02 19:29:34 [NOTICE] switch_loadable_module.c:110 switch_loadable_module_process() Adding Codec 'G726-16' (G.726 16k) 8000khz 20ms
2006-09-02 19:29:34 [CONSOLE] switch_loadable_module.c:305 switch_loadable_module_load_file() Successfully Loaded [mod_g723_1]
2006-09-02 19:29:34 [NOTICE] switch_loadable_module.c:110 switch_loadable_module_process() Adding Codec 'G723' (g723.1 6.3k) 8000khz 30ms
2006-09-02 19:29:34 [CONSOLE] switch_loadable_module.c:305 switch_loadable_module_load_file() Successfully Loaded [mod_gsm]
2006-09-02 19:29:34 [NOTICE] switch_loadable_module.c:110 switch_loadable_module_process() Adding Codec 'gsm' (gsm) 8000khz 20ms
2006-09-02 19:29:34 [CONSOLE] switch_loadable_module.c:305 switch_loadable_module_load_file() Successfully Loaded [mod_l16]
2006-09-02 19:29:34 [NOTICE] switch_loadable_module.c:110 switch_loadable_module_process() Adding Codec 'L16' (raw signed linear (16 bit)) 8000khz 120ms
2006-09-02 19:29:34 [NOTICE] switch_loadable_module.c:110 switch_loadable_module_process() Adding Codec 'L16' (raw signed linear (16 bit)) 8000khz 60ms
2006-09-02 19:29:34 [NOTICE] switch_loadable_module.c:110 switch_loadable_module_process() Adding Codec 'L16' (raw signed linear (16 bit)) 8000khz 30ms
2006-09-02 19:29:34 [NOTICE] switch_loadable_module.c:110 switch_loadable_module_process() Adding Codec 'L16' (raw signed linear (16 bit)) 8000khz 20ms
2006-09-02 19:29:34 [NOTICE] switch_loadable_module.c:110 switch_loadable_module_process() Adding Codec 'L16' (raw signed linear (16 bit)) 16000khz 20ms
2006-09-02 19:29:34 [NOTICE] switch_loadable_module.c:110 switch_loadable_module_process() Adding Codec 'L16' (raw signed linear (16 bit)) 22050khz 20ms
2006-09-02 19:29:34 [NOTICE] switch_loadable_module.c:110 switch_loadable_module_process() Adding Codec 'L16' (raw signed linear (16 bit)) 32000khz 20ms
2006-09-02 19:29:34 [CONSOLE] switch_loadable_module.c:305 switch_loadable_module_load_file() Successfully Loaded [mod_speex]
2006-09-02 19:29:34 [NOTICE] switch_loadable_module.c:110 switch_loadable_module_process() Adding Codec 'speex' (speex) 8000khz 20ms
2006-09-02 19:29:34 [NOTICE] switch_loadable_module.c:110 switch_loadable_module_process() Adding Codec 'speex' (speex) 16000khz 20ms
2006-09-02 19:29:34 [NOTICE] switch_loadable_module.c:110 switch_loadable_module_process() Adding Codec 'speex' (speex) 32000khz 20ms
2006-09-02 19:29:34 [CONSOLE] switch_loadable_module.c:305 switch_loadable_module_load_file() Successfully Loaded [mod_ilbc]
2006-09-02 19:29:34 [NOTICE] switch_loadable_module.c:110 switch_loadable_module_process() Adding Codec 'iLBC' (ilbc) 8000khz 20ms
2006-09-02 19:29:34 [NOTICE] switch_loadable_module.c:110 switch_loadable_module_process() Adding Codec 'iLBC' (ilbc) 8000khz 30ms
2006-09-02 19:29:34 [NOTICE] switch_loadable_module.c:110 switch_loadable_module_process() Adding Codec 'iLBC102' (ilbc) 8000khz 20ms
2006-09-02 19:29:34 [NOTICE] switch_loadable_module.c:110 switch_loadable_module_process() Adding Codec 'iLBC' (ilbc) 8000khz 30ms
2006-09-02 19:29:34 [NOTICE] switch_loadable_module.c:110 switch_loadable_module_process() Adding Codec 'iLBC20ms' (ilbc) 8000khz 20ms
2006-09-02 19:29:34 [INFO] mod_sndfile.c:282 setup_formats()
LibSndFile Version : libsndfile-1.0.16 Supported Formats
================================================================================
AIFF (Apple/SGI) (extension "aiff")
AU (Sun/NeXT) (extension "au")
AVR (Audio Visual Research) (extension "avr")
CAF (Apple Core Audio File) (extension "caf")
HTK (HMM Tool Kit) (extension "htk")
IFF (Amiga IFF/SVX8/SV16) (extension "iff")
MAT4 (GNU Octave 2.0 / Matlab 4.2) (extension "mat")
MAT5 (GNU Octave 2.1 / Matlab 5.0) (extension "mat")
PAF (Ensoniq PARIS) (extension "paf")
2006-09-02 19:29:34 [CONSOLE] switch_loadable_module.c:305 switch_loadable_module_load_file() Successfully Loaded [mod_sndfile]
PVF (Portable Voice Format) (extension "pvf")
RAW (header-less) (extension "raw")
SD2 (Sound Designer II) (extension "sd2")
SDS (Midi Sample Dump Standard) (extension "sds")
SF (Berkeley/IRCAM/CARL) (extension "sf")
VOC (Creative Labs) (extension "voc")
W64 (SoundFoundry WAVE 64) (extension "w64")
WAV (Microsoft) (extension "wav")
WAV (NIST Sphere) (extension "wav")
WAVEX (Microsoft) (extension "wav")
XI (FastTracker 2) (extension "xi")
================================================================================
2006-09-02 19:29:34 [NOTICE] switch_loadable_module.c:191 switch_loadable_module_process() Adding File Format 'aiff'
2006-09-02 19:29:34 [NOTICE] switch_loadable_module.c:191 switch_loadable_module_process() Adding File Format 'au'
2006-09-02 19:29:34 [NOTICE] switch_loadable_module.c:191 switch_loadable_module_process() Adding File Format 'avr'
2006-09-02 19:29:34 [NOTICE] switch_loadable_module.c:191 switch_loadable_module_process() Adding File Format 'caf'
2006-09-02 19:29:34 [NOTICE] switch_loadable_module.c:191 switch_loadable_module_process() Adding File Format 'htk'
2006-09-02 19:29:34 [NOTICE] switch_loadable_module.c:191 switch_loadable_module_process() Adding File Format 'iff'
2006-09-02 19:29:34 [NOTICE] switch_loadable_module.c:191 switch_loadable_module_process() Adding File Format 'mat'
2006-09-02 19:29:34 [NOTICE] switch_loadable_module.c:191 switch_loadable_module_process() Adding File Format 'paf'
2006-09-02 19:29:34 [NOTICE] switch_loadable_module.c:191 switch_loadable_module_process() Adding File Format 'pvf'
2006-09-02 19:29:34 [NOTICE] switch_loadable_module.c:191 switch_loadable_module_process() Adding File Format 'raw'
2006-09-02 19:29:34 [NOTICE] switch_loadable_module.c:191 switch_loadable_module_process() Adding File Format 'sd2'
2006-09-02 19:29:34 [NOTICE] switch_loadable_module.c:191 switch_loadable_module_process() Adding File Format 'sds'
2006-09-02 19:29:34 [NOTICE] switch_loadable_module.c:191 switch_loadable_module_process() Adding File Format 'sf'
2006-09-02 19:29:34 [NOTICE] switch_loadable_module.c:191 switch_loadable_module_process() Adding File Format 'voc'
2006-09-02 19:29:34 [NOTICE] switch_loadable_module.c:191 switch_loadable_module_process() Adding File Format 'w64'
2006-09-02 19:29:34 [NOTICE] switch_loadable_module.c:191 switch_loadable_module_process() Adding File Format 'wav'
2006-09-02 19:29:34 [NOTICE] switch_loadable_module.c:191 switch_loadable_module_process() Adding File Format 'xi'
2006-09-02 19:29:34 [NOTICE] switch_loadable_module.c:191 switch_loadable_module_process() Adding File Format 'r8'
2006-09-02 19:29:34 [NOTICE] switch_loadable_module.c:191 switch_loadable_module_process() Adding File Format 'r16'
2006-09-02 19:29:34 [NOTICE] switch_loadable_module.c:191 switch_loadable_module_process() Adding File Format 'r24'
2006-09-02 19:29:34 [NOTICE] switch_loadable_module.c:191 switch_loadable_module_process() Adding File Format 'r32'
2006-09-02 19:29:34 [NOTICE] switch_loadable_module.c:191 switch_loadable_module_process() Adding File Format 'gsm'
2006-09-02 19:29:34 [CONSOLE] switch_loadable_module.c:305 switch_loadable_module_load_file() Successfully Loaded [mod_softtimer]
2006-09-02 19:29:34 [CONSOLE] switch_loadable_module.c:514 switch_loadable_module_init() open of post_load_modules.conf failed
2006-09-02 19:29:34 [CONSOLE] switch_core.c:3250 switch_core_init_and_modload()
FreeSWITCH Version 1.0.2483 Started.
Crash Protection [DISABLED]
Max Sessions[1000]
2006-09-02 19:29:34 [NOTICE] switch_loadable_module.c:146 switch_loadable_module_process() Adding Timer 'soft'
freeswitch@taz.local>
freeswitch@taz.local> recv 747 bytes from udp/[10.0.1.2]:5060 at 00:29:39.081231:
INVITE sip:888@10.0.1.251 SIP/2.0
Via: SIP/2.0/UDP 10.0.1.2:5060;branch=z9hG4bK-a6ea2107
From: Brian West <sip:1001@10.0.1.251>;tag=45ec9c93d43efd27o0
To: <sip:888@10.0.1.251>
Call-ID: ffec3203-44cee677@10.0.1.2
CSeq: 101 INVITE
Max-Forwards: 70
Contact: Brian West <sip:1001@10.0.1.2:5060>
Expires: 240
User-Agent: Sipura/SPA3000-2.0.13(GWg)
Content-Length: 241
Allow: ACK, BYE, CANCEL, INFO, INVITE, NOTIFY, OPTIONS, PRACK, REFER
Supported: 100rel, x-sipura
Content-Type: application/sdp
v=0
o=- 26572319 26572319 IN IP4 10.0.1.2
s=-
c=IN IP4 10.0.1.2
t=0 0
m=audio 16410 RTP/AVP 124 100 101
a=rtpmap:124 AAL2-G726-16/8000
a=rtpmap:100 NSE/8000
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-15
a=ptime:20
a=sendrecv
nta: received INVITE sip:888@10.0.1.251 SIP/2.0 (CSeq 101)
nta: canonizing sip:888@10.0.1.251 with contact
nta: INVITE (101) going to a default leg
nta_leg_create(0x4124d0)
send 241 bytes to udp/[10.0.1.2]:5060 at 00:29:39.185378:
SIP/2.0 100 Trying
Via: SIP/2.0/UDP 10.0.1.2:5060;branch=z9hG4bK-a6ea2107
From: Brian West <sip:1001@10.0.1.251>;tag=45ec9c93d43efd27o0
To: <sip:888@10.0.1.251>
Call-ID: ffec3203-44cee677@10.0.1.2
CSeq: 101 INVITE
Content-Length: 0
nta: sent 100 Trying for INVITE (101)
2006-09-02 19:29:39 [DEBUG] mod_sofia.c:1433 event_callback() event [nua_i_invite] status [100] [Trying]
2006-09-02 19:29:39 [NOTICE] switch_channel.c:328 switch_channel_set_name() New Chan sofia/test/1001@10.0.1.251 [bb9dae0f-76d2-4140-b671-57523730f3be]
2006-09-02 19:29:39 [DEBUG] mod_sofia.c:1433 event_callback() event [nua_i_state] status [100] [Trying]
2006-09-02 19:29:39 [DEBUG] mod_sofia.c:1222 sip_i_state() Channel sofia/test/1001@10.0.1.251 entering state [received]
2006-09-02 19:29:39 [DEBUG] mod_sofia.c:1228 sip_i_state() Remote SDP:
v=0
o=- 26572319 26572319 IN IP4 10.0.1.2
s=-
c=IN IP4 10.0.1.2
t=0 0
m=audio 16410 RTP/AVP 124 100 101
a=rtpmap:124 AAL2-G726-16/8000
a=rtpmap:100 NSE/8000
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-15
a=ptime:20
2006-09-02 19:29:39 [INFO] mod_sofia.c:633 tech_set_codec() Set Codec sofia/test/1001@10.0.1.251 AAL2-G726-40/0 20 ms
2006-09-02 19:29:39 [DEBUG] mod_sofia.c:1293 sip_i_state() sofia/test/1001@10.0.1.251 State Change CS_NEW -> CS_INIT
2006-09-02 19:29:39 [DEBUG] switch_core.c:2291 switch_core_session_run() (sofia/test/1001@10.0.1.251) State INIT
2006-09-02 19:29:39 [DEBUG] mod_sofia.c:488 sofia_on_init() SOFIA INIT
2006-09-02 19:29:39 [DEBUG] mod_sofia.c:495 sofia_on_init() sofia/test/1001@10.0.1.251 State Change CS_INIT -> CS_RING
2006-09-02 19:29:39 [DEBUG] switch_core.c:2327 switch_core_session_run() (sofia/test/1001@10.0.1.251) State RING
2006-09-02 19:29:39 [DEBUG] mod_sofia.c:511 sofia_on_ring() SOFIA RING
2006-09-02 19:29:39 [DEBUG] switch_core.c:2019 switch_core_standard_on_ring() Standard RING sofia/test/1001@10.0.1.251
2006-09-02 19:29:39 [INFO] mod_dialplan_xml.c:274 dialplan_hunt() Processing Brian West->888!
2006-09-02 19:29:39 [DEBUG] mod_dialplan_xml.c:195 parse_exten() test conditions destination_number(888) =~ /^(18(0{2}|8{2}|7{2}|6{2})\d{7})$/
2006-09-02 19:29:39 [DEBUG] mod_dialplan_xml.c:197 parse_exten() Regex mismatch
2006-09-02 19:29:39 [DEBUG] mod_dialplan_xml.c:195 parse_exten() test conditions destination_number(888) =~ /^888$/
2006-09-02 19:29:39 [DEBUG] mod_dialplan_xml.c:314 dialplan_hunt() sofia/test/1001@10.0.1.251 State Change CS_RING -> CS_EXECUTE
2006-09-02 19:29:39 [DEBUG] switch_core.c:2363 switch_core_session_run() (sofia/test/1001@10.0.1.251) State EXECUTE
2006-09-02 19:29:39 [DEBUG] mod_sofia.c:529 sofia_on_execute() SOFIA EXECUTE
2006-09-02 19:29:39 [DEBUG] switch_core.c:2053 switch_core_standard_on_execute() Standard EXECUTE
2006-09-02 19:29:39 [NOTICE] switch_core.c:2061 switch_core_standard_on_execute() Execute answer()
2006-09-02 19:29:39 [INFO] mod_sofia.c:677 activate_rtp() RTP [sofia/test/1001@10.0.1.251] 10.0.1.251:16384->10.0.1.2:16410 codec: 124 ms: 20
2006-09-02 19:29:39 [DEBUG] mod_sofia.c:745 sofia_answer_channel() Local SDP:
v=0
o=FreeSWITCH 163841157243379188201 163841157243379188201 IN IP4 10.0.1.251
s=FreeSWITCH
c=IN IP4 10.0.1.251
t=0 0
a=sendrecv
m=audio 16384 RTP/AVP 124 101
a=rtpmap:124 AAL2-G726-16/8000
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-16
2006-09-02 19:29:39 [NOTICE] mod_dptools.c:53 answer_function() Answer sofia/test/1001@10.0.1.251!
2006-09-02 19:29:39 [NOTICE] switch_core.c:2061 switch_core_standard_on_execute() Execute playback(/usr/local/src/freeswitch.trunk/sr8k.wav)
2006-09-02 19:29:39 [INFO] mod_sndfile.c:134 sndfile_file_open() Opening File [/usr/local/src/freeswitch.trunk/sr8k.wav] 8000hz
2006-09-02 19:29:39 [DEBUG] switch_ivr.c:427 switch_ivr_play_file() OPEN FILE /usr/local/src/freeswitch.trunk/sr8k.wav 8000hz 1 channels
TITLE=
COPYRIGHT=
SOFTWARE=
ARTIST=
COMMENT=
DATE=
2006-09-02 19:29:39 [DEBUG] switch_ivr.c:455 switch_ivr_play_file() Raw Codec Activated
send 690 bytes to udp/[10.0.1.2]:5060 at 00:29:39.513993:
SIP/2.0 200 OK
Via: SIP/2.0/UDP 10.0.1.2:5060;branch=z9hG4bK-a6ea2107
From: Brian West <sip:1001@10.0.1.251>;tag=45ec9c93d43efd27o0
To: <sip:888@10.0.1.251>;tag=7v1ZSvcK9Btee
Call-ID: ffec3203-44cee677@10.0.1.2
CSeq: 101 INVITE
Contact: <sip:10.0.1.251>
User-Agent: sofia-sip/1.12.1
Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, PRACK, MESSAGE, SUBSCRIBE, NOTIFY, REFER, UPDATE
Supported: 100rel, precondition
Content-Type: application/sdp
Content-Disposition: session
Content-Length: 190
v=0
o=FreeSWITCH 6448577233919784050 3476236392233617296 IN IP4 10.0.1.251
s=FreeSWITCH
c=IN IP4 10.0.1.251
t=0 0
a=sendrecv
m=audio 16384 RTP/AVP 124
a=rtpmap:124 AAL2-G726-16/8000
nta: sent 200 OK for INVITE (101)
2006-09-02 19:29:39 [DEBUG] mod_sofia.c:1433 event_callback() event [nua_i_state] status [200] [OK]
2006-09-02 19:29:39 [DEBUG] mod_sofia.c:1222 sip_i_state() Channel sofia/test/1001@10.0.1.251 entering state [completed]
recv 747 bytes from udp/[10.0.1.2]:5060 at 00:29:39.574193:
INVITE sip:888@10.0.1.251 SIP/2.0
Via: SIP/2.0/UDP 10.0.1.2:5060;branch=z9hG4bK-a6ea2107
From: Brian West <sip:1001@10.0.1.251>;tag=45ec9c93d43efd27o0
To: <sip:888@10.0.1.251>
Call-ID: ffec3203-44cee677@10.0.1.2
CSeq: 101 INVITE
Max-Forwards: 70
Contact: Brian West <sip:1001@10.0.1.2:5060>
Expires: 240
User-Agent: Sipura/SPA3000-2.0.13(GWg)
Content-Length: 241
Allow: ACK, BYE, CANCEL, INFO, INVITE, NOTIFY, OPTIONS, PRACK, REFER
Supported: 100rel, x-sipura
Content-Type: application/sdp
v=0
o=- 26572319 26572319 IN IP4 10.0.1.2
s=-
c=IN IP4 10.0.1.2
t=0 0
m=audio 16410 RTP/AVP 124 100 101
a=rtpmap:124 AAL2-G726-16/8000
a=rtpmap:100 NSE/8000
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-15
a=ptime:20
a=sendrecv
nta: received INVITE sip:888@10.0.1.251 SIP/2.0 (CSeq 101)
nta: INVITE (101) going to existing INVITE transaction
nta: re-received INVITE request, retransmitting 200 reply
send 690 bytes to udp/[10.0.1.2]:5060 at 00:29:39.577030:
SIP/2.0 200 OK
Via: SIP/2.0/UDP 10.0.1.2:5060;branch=z9hG4bK-a6ea2107
From: Brian West <sip:1001@10.0.1.251>;tag=45ec9c93d43efd27o0
To: <sip:888@10.0.1.251>;tag=7v1ZSvcK9Btee
Call-ID: ffec3203-44cee677@10.0.1.2
CSeq: 101 INVITE
Contact: <sip:10.0.1.251>
User-Agent: sofia-sip/1.12.1
Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, PRACK, MESSAGE, SUBSCRIBE, NOTIFY, REFER, UPDATE
Supported: 100rel, precondition
Content-Type: application/sdp
Content-Disposition: session
Content-Length: 190
v=0
o=FreeSWITCH 6448577233919784050 3476236392233617296 IN IP4 10.0.1.251
s=FreeSWITCH
c=IN IP4 10.0.1.251
t=0 0
a=sendrecv
m=audio 16384 RTP/AVP 124
a=rtpmap:124 AAL2-G726-16/8000
recv 368 bytes from udp/[10.0.1.2]:5060 at 00:29:39.798420:
ACK sip:10.0.1.251 SIP/2.0
Via: SIP/2.0/UDP 10.0.1.2:5060;branch=z9hG4bK-4380238b
From: Brian West <sip:1001@10.0.1.251>;tag=45ec9c93d43efd27o0
To: <sip:888@10.0.1.251>;tag=7v1ZSvcK9Btee
Call-ID: ffec3203-44cee677@10.0.1.2
CSeq: 101 ACK
Max-Forwards: 70
Contact: Brian West <sip:1001@10.0.1.2:5060>
User-Agent: Sipura/SPA3000-2.0.13(GWg)
Content-Length: 0
nta: received ACK sip:10.0.1.251 SIP/2.0 (CSeq 101)
nta: ACK (101) is going to INVITE (101)
2006-09-02 19:29:39 [DEBUG] mod_sofia.c:1433 event_callback() event [nua_i_ack] status [200] [OK]
2006-09-02 19:29:39 [DEBUG] mod_sofia.c:1433 event_callback() event [nua_i_state] status [200] [OK]
2006-09-02 19:29:39 [DEBUG] mod_sofia.c:1222 sip_i_state() Channel sofia/test/1001@10.0.1.251 entering state [ready]
2006-09-02 19:29:39 [DEBUG] mod_sofia.c:1433 event_callback() event [nua_i_active] status [200] [Call active]
2006-09-02 19:29:39 [DEBUG] mod_sofia.c:1433 event_callback() event [nua_i_error] status [500] [Responding to a Non-Existing Request]
recv 368 bytes from udp/[10.0.1.2]:5060 at 00:29:39.813753:
ACK sip:10.0.1.251 SIP/2.0
Via: SIP/2.0/UDP 10.0.1.2:5060;branch=z9hG4bK-4380238b
From: Brian West <sip:1001@10.0.1.251>;tag=45ec9c93d43efd27o0
To: <sip:888@10.0.1.251>;tag=7v1ZSvcK9Btee
Call-ID: ffec3203-44cee677@10.0.1.2
CSeq: 101 ACK
Max-Forwards: 70
Contact: Brian West <sip:1001@10.0.1.2:5060>
User-Agent: Sipura/SPA3000-2.0.13(GWg)
Content-Length: 0
nta: received ACK sip:10.0.1.251 SIP/2.0 (CSeq 101)
nta: ACK (101) is going to INVITE (101)
nta: timer I fired, terminate 200 response
incoming_reclaim_all(0x0, 0x0, 0xb0204d8c)
nta_incoming_timer: 0/0 resent, 0/0 tout, 1/1 term, 1/1 free
2006-09-02 19:29:46 [DEBUG] switch_core.c:1568 switch_core_session_write_frame() Engaging Write Buffer at 3200 bytes to accomodate 128->320
2006-09-02 19:29:46 [DEBUG] switch_ivr.c:633 switch_ivr_play_file() done playing file
2006-09-02 19:29:46 [NOTICE] switch_core.c:2091 switch_core_standard_on_execute() Hangup sofia/test/1001@10.0.1.251 [CS_EXECUTE] [NORMAL_CLEARING]
2006-09-02 19:29:46 [INFO] switch_channel.c:866 switch_channel_perform_hangup() Kill sofia/test/1001@10.0.1.251 [1]
2006-09-02 19:29:46 [DEBUG] switch_core.c:2252 switch_core_session_run() (sofia/test/1001@10.0.1.251) State HANGUP
2006-09-02 19:29:46 [DEBUG] mod_sofia.c:563 sofia_on_hangup() SOFIA HANGUP
nta: selecting scheme sip
2006-09-02 19:29:46 [DEBUG] switch_core.c:2009 switch_core_standard_on_hangup() Standard HANGUP sofia/test/1001@10.0.1.251
2006-09-02 19:29:46 [DEBUG] switch_core.c:2287 switch_core_session_run() sofia/test/1001@10.0.1.251 State Change CS_HANGUP -> CS_DONE
2006-09-02 19:29:46 [DEBUG] switch_core.c:2647 switch_core_session_thread() Session 1 (sofia/test/1001@10.0.1.251) Locked, Waiting on external entities
2006-09-02 19:29:46 [INFO] switch_core.c:2654 switch_core_session_thread() Session 1 (sofia/test/1001@10.0.1.251) Ended
2006-09-02 19:29:46 [NOTICE] switch_core.c:2532 switch_core_session_destroy() Close Channel sofia/test/1001@10.0.1.251
send 365 bytes to udp/[10.0.1.2]:5060 at 00:29:46.868988:
BYE sip:1001@10.0.1.2:5060 SIP/2.0
Via: SIP/2.0/UDP 10.0.1.251;rport;branch=z9hG4bK708KemD125D0D
Max-Forwards: 70
From: <sip:888@10.0.1.251>;tag=7v1ZSvcK9Btee
To: Brian West <sip:1001@10.0.1.251>;tag=45ec9c93d43efd27o0
Call-ID: ffec3203-44cee677@10.0.1.2
CSeq: 72503354 BYE
User-Agent: sofia-sip/1.12.1
Supported: 100rel, precondition
Content-Length: 0
nta: sent BYE (72503354) to */10.0.1.2:5060
nta_leg_destroy(0x4124d0)
recv 294 bytes from udp/[10.0.1.2]:5060 at 00:29:46.886439:
SIP/2.0 200 OK
To: Brian West <sip:1001@10.0.1.251>;tag=45ec9c93d43efd27o0
From: <sip:888@10.0.1.251>;tag=7v1ZSvcK9Btee
Call-ID: ffec3203-44cee677@10.0.1.2
CSeq: 72503354 BYE
Via: SIP/2.0/UDP 10.0.1.251;branch=z9hG4bK708KemD125D0D
Server: Sipura/SPA3000-2.0.13(GWg)
Content-Length: 0
nta: received 200 OK for BYE (72503354)
nta: 200 OK going to a transaction
nta_outgoing: RTT is 119.729 ms
nta: timer K fired, terminate BYE (72503354)
outgoing_reclaim_all(0x0, 0x0, 0xb0204d8c)
nta_outgoing_timer: 0/0 resent, 0/0 tout, 1/1 term, 1/1 free