brian@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 ;tag=45ec9c93d43efd27o0 To: Call-ID: ffec3203-44cee677@10.0.1.2 CSeq: 101 INVITE Max-Forwards: 70 Contact: Brian West 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 ;tag=45ec9c93d43efd27o0 To: 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 ;tag=45ec9c93d43efd27o0 To: ;tag=7v1ZSvcK9Btee Call-ID: ffec3203-44cee677@10.0.1.2 CSeq: 101 INVITE Contact: 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 ;tag=45ec9c93d43efd27o0 To: Call-ID: ffec3203-44cee677@10.0.1.2 CSeq: 101 INVITE Max-Forwards: 70 Contact: Brian West 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 ;tag=45ec9c93d43efd27o0 To: ;tag=7v1ZSvcK9Btee Call-ID: ffec3203-44cee677@10.0.1.2 CSeq: 101 INVITE Contact: 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 ;tag=45ec9c93d43efd27o0 To: ;tag=7v1ZSvcK9Btee Call-ID: ffec3203-44cee677@10.0.1.2 CSeq: 101 ACK Max-Forwards: 70 Contact: Brian West 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 ;tag=45ec9c93d43efd27o0 To: ;tag=7v1ZSvcK9Btee Call-ID: ffec3203-44cee677@10.0.1.2 CSeq: 101 ACK Max-Forwards: 70 Contact: Brian West 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: ;tag=7v1ZSvcK9Btee To: Brian West ;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 ;tag=45ec9c93d43efd27o0 From: ;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