Re: [Freeswitch-users] setting up forward incoming calls to external gateway
I spent a few more hours and I figured a few more things. It looks like there was a lot of excessive configuration for the purpose. I think what should work (although it still does not) is as follows. No need for any java scripts in this new version. I set the public.xml extension: <extension name="extname"> <condition field="caller_id_number" expression="^(9051212121)$"> <action application="set" data="domain_name=$${domain}"/> <action application="transfer" data="3472 XML default"/> </condition> </extension> And the default.xml goes like this: <extension name="extname"> <condition field="destination_number" expression="3472"> <action application="set" data="ringback=$${us-ring}"/> <action application="set" data="transfer_ringback=$${us-ring}"/> <action application="set" data="hangup_after_bridge=true"/> <action application="bridge" data="sofia/gateway/mysipprovider/15191212121"/> </condition> </extension> So this is way simpler, although the result is the same - the channel is opened (2011-05-15 5:33:45.687500 [NOTICE] switch_channel.c:812 New Channel sofia/external/15191212121 [430cf1e6-0876-4cc7-ba87-9c962619b341]), but I still get paused for 10 seconds. After which I get short busy signals. What I noticed, and that seems to be a clue, if I do not hang up on calling side and continue with the busy signal, the connection gets through to the destination number and it shows the caller ID and rings shortly. The way I see it it is a break through! I never got any rings before on the destination side. Anyway, so the question I have now, why the heck it seems not calling on destination right away as soon as the channel is opened but pauses until disconnected? And then actually still calls, but only a short ring, enough to display a caller ID. If anyone had similar problem solved, please, let me know. I would really appreciate it. Regards, Kamen -- View this message in context: http://freeswitch-users.2379917.n2.nabble.com/setting-up-forward-incoming-ca... Sent from the freeswitch-users mailing list archive at Nabble.com.
Time to get a full debug log with sip trace and put on pastebin. Be sure to use "FreeSWITCH Log" as the syntax highlighting. -MC On Sun, May 15, 2011 at 12:43 PM, Kamen <sireeps@gmail.com> wrote:
I spent a few more hours and I figured a few more things. It looks like there was a lot of excessive configuration for the purpose. I think what should work (although it still does not) is as follows. No need for any java scripts in this new version.
I set the public.xml extension:
<extension name="extname"> <condition field="caller_id_number" expression="^(9051212121)$"> <action application="set" data="domain_name=$${domain}"/> <action application="transfer" data="3472 XML default"/> </condition> </extension>
And the default.xml goes like this:
<extension name="extname"> <condition field="destination_number" expression="3472"> <action application="set" data="ringback=$${us-ring}"/> <action application="set" data="transfer_ringback=$${us-ring}"/> <action application="set" data="hangup_after_bridge=true"/> <action application="bridge" data="sofia/gateway/mysipprovider/15191212121"/> </condition> </extension>
So this is way simpler, although the result is the same - the channel is opened (2011-05-15 5:33:45.687500 [NOTICE] switch_channel.c:812 New Channel sofia/external/15191212121 [430cf1e6-0876-4cc7-ba87-9c962619b341]), but I still get paused for 10 seconds. After which I get short busy signals.
What I noticed, and that seems to be a clue, if I do not hang up on calling side and continue with the busy signal, the connection gets through to the destination number and it shows the caller ID and rings shortly. The way I see it it is a break through! I never got any rings before on the destination side.
Anyway, so the question I have now, why the heck it seems not calling on destination right away as soon as the channel is opened but pauses until disconnected? And then actually still calls, but only a short ring, enough to display a caller ID.
If anyone had similar problem solved, please, let me know. I would really appreciate it.
Regards,
Kamen
-- View this message in context: http://freeswitch-users.2379917.n2.nabble.com/setting-up-forward-incoming-ca... Sent from the freeswitch-users mailing list archive at Nabble.com.
_______________________________________________ FreeSWITCH-users mailing list FreeSWITCH-users@lists.freeswitch.org http://lists.freeswitch.org/mailman/listinfo/freeswitch-users UNSUBSCRIBE:http://lists.freeswitch.org/mailman/options/freeswitch-users http://www.freeswitch.org
Hi Michael, Frankly I am not sure what exactly you referring to. I am completely new to freeswitch. If you are talking about running command (I found it in online doc): TPORT_LOG=1 /usr/local/freeswitch/bin/freeswitch then there is a problem, Like I said I am running it in Windows. Running FreeSWITCH\FreeSwitchConsole.exe. Besides I have no idea what pastebin is. Only can guess it preserves the colors of debug printouts. I have instead prepared below a debug printout I manage to get in the console. Also added my comment. Please, could anyone have a look at it. Briefly, I want a simple functionality. If call comes in to my SIP provider I want it to be forwarded to another fixed external number. That is it! Seems like a straight forward task for freeswitch. The call seems to be forwarded (according to the log), but something stops it and it gets paused for 10 seconds, until busy signal and call is disconnected afterwards. Thanks in advance. Sergei Kamen ============================================================== public.xml has extension: <extension name="Forward All"> <condition field="caller_id_number" expression="^(\d+)$"> <action application="transfer" data="3472 XML default"/> </condition> </extension> and default.xml has: <extension name="Forward All"> <condition field="destination_number" expression="3472"> <action application="bridge" data="sofia/gateway/freephoneline/15191212121"/> </condition> </extension> The following printout in my console is as follows from the beginning: ------------------------------ nta: bind([::1]:5070;transport=*): No such file or directory nua: initializing SIP stack failed [SK:] could it be the error above? 2011-05-21 17:59:38.187500 [ERR] sofia.c:1533 Error Creating SIP UA for profile: internal-ipv6 2011-05-21 17:59:40.875000 [DEBUG] switch_nat.c:502 mapped public port 5080 protocol TCP to localport 5080 2011-05-21 17:59:40.875000 [DEBUG] sofia.c:1487 Created TCP nat mapping for external port 5080 2011-05-21 17:59:40.875000 [DEBUG] switch_nat.c:502 mapped public port 5070 protocol TCP to localport 5070 2011-05-21 17:59:40.875000 [DEBUG] sofia.c:1487 Created TCP nat mapping for internal port 5070 2011-05-21 17:59:40.906250 [DEBUG] sofia.c:1539 Created agent for external 2011-05-21 17:59:40.906250 [DEBUG] sofia.c:1576 Set params for external 2011-05-21 17:59:40.906250 [DEBUG] sofia.c:1599 Activated db for external 2011-05-21 17:59:40.906250 [DEBUG] sofia.c:1626 Starting thread for external 2011-05-21 17:59:40.921875 [DEBUG] sofia.c:1539 Created agent for internal 2011-05-21 17:59:40.921875 [DEBUG] sofia.c:1576 Set params for internal 2011-05-21 17:59:40.921875 [DEBUG] sofia.c:1599 Activated db for internal 2011-05-21 17:59:40.921875 [DEBUG] sofia.c:1626 Starting thread for internal 2011-05-21 17:59:41.921875 [NOTICE] sofia_reg.c:367 Registering mysipprovider 2011-05-21 17:59:44.062500 [DEBUG] sofia_reg.c:1922 Authenticating '16472222222' with 'Digest:"voip.mysipprovider.ca":16472222222:mypassword'. 2011-05-21 17:59:44.921875 [DEBUG] sofia_reg.c:331 Registered mysipprovider 2011-05-21 18:00:00.984375 [WARNING] sofia.c:4065 Ping succeeded mysipprovider with code 501 - count -1/1/1, state UP [SK:]I am calling here to my SIP provider number (16472222222) from another phone (9051212121). I expect it to forward to a third number (15191212121) with updated Caller ID of my provider. 2011-05-21 18:00:34.609375 [NOTICE] switch_channel.c:812 New Channel sofia/external/9051212121@218.165.240.142 [bc74d840-a951-458e-9eec-c70941fdd05a] 2011-05-21 18:00:34.609375 [DEBUG] sofia.c:4744 Channel sofia/external/9051212121@218.165.240.142 entering state [received][100] 2011-05-21 18:00:34.609375 [DEBUG] sofia.c:4755 Remote SDP: v=0 o=Sippy 383374256 0 IN IP4 218.165.240.142 s=- t=0 0 m=audio 35774 RTP/AVP 0 c=IN IP4 208.72.120.90 2011-05-21 18:00:34.609375 [DEBUG] sofia_glue.c:4637 Audio Codec Compare [PCMU:0:8000:20:64000]/[G7221:115:32000:20:48000] 2011-05-21 18:00:34.609375 [DEBUG] sofia_glue.c:4637 Audio Codec Compare [PCMU:0:8000:20:64000]/[G7221:107:16000:20:32000] 2011-05-21 18:00:34.609375 [DEBUG] sofia_glue.c:4637 Audio Codec Compare [PCMU:0:8000:20:64000]/[G722:9:8000:20:64000] 2011-05-21 18:00:34.609375 [DEBUG] switch_core_state_machine.c:320 (sofia/external/9051212121@218.165.240.142) Running State Change CS_NEW 2011-05-21 18:00:34.609375 [DEBUG] switch_core_state_machine.c:338 (sofia/external/9051212121@218.165.240.142) State NEW 2011-05-21 18:00:34.609375 [DEBUG] sofia_glue.c:4637 Audio Codec Compare [PCMU:0:8000:20:64000]/[PCMU:0:8000:20:64000] 2011-05-21 18:00:34.609375 [DEBUG] sofia_glue.c:2760 Set Codec sofia/external/9051212121@218.165.240.142 PCMU/8000 20 ms 160 samples 64000 bits 2011-05-21 18:00:34.609375 [DEBUG] sofia.c:4922 (sofia/external/9051212121@218.165.240.142) State Change CS_NEW -> CS_INIT 2011-05-21 18:00:34.609375 [DEBUG] switch_core_session.c:1116 Send signal sofia/external/9051212121@218.165.240.142 [BREAK] 2011-05-21 18:00:34.609375 [DEBUG] switch_core_state_machine.c:320 (sofia/external/9051212121@218.165.240.142) Running State Change CS_INIT 2011-05-21 18:00:34.609375 [DEBUG] switch_core_state_machine.c:356 (sofia/external/9051212121@218.165.240.142) State INIT 2011-05-21 18:00:34.609375 [DEBUG] mod_sofia.c:84 sofia/external/9051212121@218.165.240.142 SOFIA INIT 2011-05-21 18:00:34.609375 [DEBUG] mod_sofia.c:124 (sofia/external/9051212121@218.165.240.142) State Change CS_INIT -> CS_ROUTING 2011-05-21 18:00:34.609375 [DEBUG] switch_core_session.c:1116 Send signal sofia/external/9051212121@218.165.240.142 [BREAK] 2011-05-21 18:00:34.609375 [DEBUG] switch_core_state_machine.c:356 (sofia/external/9051212121@218.165.240.142) State INIT going to sleep 2011-05-21 18:00:34.609375 [DEBUG] switch_core_state_machine.c:320 (sofia/external/9051212121@218.165.240.142) Running State Change CS_ROUTING 2011-05-21 18:00:34.609375 [DEBUG] switch_channel.c:1668 (sofia/external/9051212121@218.165.240.142) Callstate Change DOWN -> RINGING 2011-05-21 18:00:34.609375 [DEBUG] switch_core_state_machine.c:359 (sofia/external/9051212121@218.165.240.142) State ROUTING 2011-05-21 18:00:34.609375 [DEBUG] mod_sofia.c:147 sofia/external/9051212121@218.165.240.142 SOFIA ROUTING 2011-05-21 18:00:34.609375 [DEBUG] switch_core_state_machine.c:77 sofia/external/9051212121@218.165.240.142 Standard ROUTING 2011-05-21 18:00:34.609375 [INFO] mod_dialplan_xml.c:331 Processing MICHAEL S <9051212121>->3472 in context public Dialplan: sofia/external/9051212121@218.165.240.142 parsing [public->Forward All] continue=false Dialplan: sofia/external/9051212121@218.165.240.142 Regex (PASS) [Forward All] caller_id_number(9051212121) =~ /^(\d+)$/ break=on-false Dialplan: sofia/external/9051212121@218.165.240.142 Action transfer(3472 XML default) 2011-05-21 18:00:34.609375 [DEBUG] switch_core_state_machine.c:119 (sofia/external/9051212121@218.165.240.142) State Change CS_ROUTING -> CS_EXECUTE 2011-05-21 18:00:34.609375 [DEBUG] switch_core_session.c:1116 Send signal sofia/external/9051212121@218.165.240.142 [BREAK] 2011-05-21 18:00:34.609375 [DEBUG] switch_core_state_machine.c:359 (sofia/external/9051212121@218.165.240.142) State ROUTING going to sleep 2011-05-21 18:00:34.609375 [DEBUG] switch_core_state_machine.c:320 (sofia/external/9051212121@218.165.240.142) Running State Change CS_EXECUTE 2011-05-21 18:00:34.609375 [DEBUG] switch_core_state_machine.c:366 (sofia/external/9051212121@218.165.240.142) State EXECUTE 2011-05-21 18:00:34.609375 [DEBUG] mod_sofia.c:240 sofia/external/9051212121@218.165.240.142 SOFIA EXECUTE 2011-05-21 18:00:34.609375 [DEBUG] switch_core_state_machine.c:157 sofia/external/9051212121@218.165.240.142 Standard EXECUTE EXECUTE sofia/external/9051212121@218.165.240.142 transfer(3472 XML default) 2011-05-21 18:00:34.609375 [DEBUG] switch_ivr.c:1600 (sofia/external/9051212121@218.165.240.142) State Change CS_EXECUTE -> CS_ROUTING 2011-05-21 18:00:34.609375 [DEBUG] switch_core_session.c:1116 Send signal sofia/external/9051212121@218.165.240.142 [BREAK] 2011-05-21 18:00:34.609375 [DEBUG] switch_core_session.c:709 Send signal sofia/external/9051212121@218.165.240.142 [BREAK] 2011-05-21 18:00:34.609375 [NOTICE] switch_ivr.c:1606 Transfer sofia/external/9051212121@218.165.240.142 to XML[3472@default] 2011-05-21 18:00:34.609375 [DEBUG] switch_core_state_machine.c:366 (sofia/external/9051212121@218.165.240.142) State EXECUTE going to sleep 2011-05-21 18:00:34.609375 [DEBUG] switch_core_state_machine.c:320 (sofia/external/9051212121@218.165.240.142) Running State Change CS_ROUTING 2011-05-21 18:00:34.609375 [DEBUG] switch_core_state_machine.c:359 (sofia/external/9051212121@218.165.240.142) State ROUTING 2011-05-21 18:00:34.609375 [DEBUG] mod_sofia.c:147 sofia/external/9051212121@218.165.240.142 SOFIA ROUTING 2011-05-21 18:00:34.609375 [DEBUG] switch_core_state_machine.c:77 sofia/external/9051212121@218.165.240.142 Standard ROUTING 2011-05-21 18:00:34.609375 [INFO] mod_dialplan_xml.c:331 Processing SIDOROV S <9051212121>->3472 in context default Dialplan: sofia/external/9051212121@218.165.240.142 parsing [default->Forward All] continue=false Dialplan: sofia/external/9051212121@218.165.240.142 Regex (PASS) [Forward All] destination_number(3472) =~ /3472/ break=on-false Dialplan: sofia/external/9051212121@218.165.240.142 Action log(INFO dialing destination number) Dialplan: sofia/external/9051212121@218.165.240.142 Action bridge(sofia/gateway/mysipprovider/15191212121) 2011-05-21 18:00:34.609375 [DEBUG] switch_core_state_machine.c:119 (sofia/external/9051212121@218.165.240.142) State Change CS_ROUTING -> CS_EXECUTE 2011-05-21 18:00:34.609375 [DEBUG] switch_core_session.c:1116 Send signal sofia/external/9051212121@218.165.240.142 [BREAK] 2011-05-21 18:00:34.609375 [DEBUG] switch_core_state_machine.c:359 (sofia/external/9051212121@218.165.240.142) State ROUTING going to sleep 2011-05-21 18:00:34.609375 [DEBUG] switch_core_state_machine.c:320 (sofia/external/9051212121@218.165.240.142) Running State Change CS_EXECUTE 2011-05-21 18:00:34.609375 [DEBUG] switch_core_state_machine.c:366 (sofia/external/9051212121@218.165.240.142) State EXECUTE 2011-05-21 18:00:34.609375 [DEBUG] mod_sofia.c:240 sofia/external/9051212121@218.165.240.142 SOFIA EXECUTE 2011-05-21 18:00:34.609375 [DEBUG] switch_core_state_machine.c:157 sofia/external/9051212121@218.165.240.142 Standard EXECUTE EXECUTE sofia/external/9051212121@218.165.240.142 log(INFO dialing destination number) 2011-05-21 18:00:34.609375 [INFO] mod_dptools.c:1183 dialing destination number EXECUTE sofia/external/9051212121@218.165.240.142 bridge(sofia/gateway/mysipprovider/15191212121) 2011-05-21 18:00:34.625000 [NOTICE] switch_channel.c:812 New Channel sofia/external/15191212121 [5a8e5141-6d37-4db3-b5d4-5c3d1f952bbe] 2011-05-21 18:00:34.625000 [DEBUG] mod_sofia.c:4286 (sofia/external/15191212121) State Change CS_NEW -> CS_INIT 2011-05-21 18:00:34.625000 [DEBUG] switch_core_session.c:1116 Send signal sofia/external/15191212121 [BREAK] 2011-05-21 18:00:34.625000 [DEBUG] switch_core_state_machine.c:320 (sofia/external/15191212121) Running State Change CS_INIT 2011-05-21 18:00:34.625000 [DEBUG] switch_core_state_machine.c:356 (sofia/external/15191212121) State INIT 2011-05-21 18:00:34.625000 [DEBUG] mod_sofia.c:84 sofia/external/15191212121 SOFIA INIT [SK:]Pause starts here 2011-05-21 18:00:39.625000 [DEBUG] switch_nat.c:502 mapped public port 17090 protocol UDP to localport 17090 [SK:]I get short "busy" signal here, and hang up. The rest is "hanging up" process messages. 2011-05-21 18:00:44.421875 [DEBUG] sofia.c:4744 Channel sofia/external/9051212121@218.165.240.142 entering state [terminated][487] 2011-05-21 18:00:44.421875 [DEBUG] switch_channel.c:2563 (sofia/external/9051212121@218.165.240.142) Callstate Change RINGING -> HANGUP 2011-05-21 18:00:44.421875 [NOTICE] sofia.c:5384 Hangup sofia/external/9051212121@218.165.240.142 [CS_EXECUTE] [ORIGINATOR_CANCEL] 2011-05-21 18:00:44.421875 [DEBUG] switch_channel.c:2579 Send signal sofia/external/9051212121@218.165.240.142 [KILL] 2011-05-21 18:00:44.421875 [DEBUG] switch_core_session.c:1116 Send signal sofia/external/9051212121@218.165.240.142 [BREAK] 2011-05-21 18:00:44.437500 [DEBUG] switch_channel.c:2563 (sofia/external/15191212121) Callstate Change DOWN -> HANGUP 2011-05-21 18:00:44.437500 [NOTICE] switch_ivr_originate.c:3343 Hangup sofia/external/15191212121 [CS_INIT] [ORIGINATOR_CANCEL] 2011-05-21 18:00:44.437500 [DEBUG] switch_channel.c:2579 Send signal sofia/external/15191212121 [KILL] 2011-05-21 18:00:44.437500 [DEBUG] switch_core_session.c:1116 Send signal sofia/external/15191212121 [BREAK] 2011-05-21 18:00:44.437500 [DEBUG] switch_ivr_originate.c:3500 Originate Cancelled by originator termination Cause: 487 [ORIGINATOR_CANCEL] 2011-05-21 18:00:44.437500 [INFO] mod_dptools.c:2623 Originate Failed. Cause: ORIGINATOR_CANCEL 2011-05-21 18:00:44.437500 [DEBUG] switch_core_session.c:2060 sofia/external/9051212121@218.165.240.142 skip receive message [APPLICATION_EXEC_COMPLETE] (channel is hungup already) 2011-05-21 18:00:44.437500 [DEBUG] switch_core_state_machine.c:366 (sofia/external/9051212121@218.165.240.142) State EXECUTE going to sleep 2011-05-21 18:00:44.437500 [DEBUG] switch_core_state_machine.c:320 (sofia/external/9051212121@218.165.240.142) Running State Change CS_HANGUP 2011-05-21 18:00:44.437500 [DEBUG] switch_core_state_machine.c:560 (sofia/external/9051212121@218.165.240.142) State HANGUP 2011-05-21 18:00:44.437500 [DEBUG] mod_sofia.c:451 sofia/external/9051212121@218.165.240.142 Overriding SIP cause 487 with 487 from the other leg 2011-05-21 18:00:44.437500 [DEBUG] mod_sofia.c:457 Channel sofia/external/9051212121@218.165.240.142 hanging up, cause: ORIGINATOR_CANCEL 2011-05-21 18:00:44.437500 [DEBUG] switch_core_state_machine.c:46 sofia/external/9051212121@218.165.240.142 Standard HANGUP, cause: ORIGINATOR_CANCEL 2011-05-21 18:00:44.437500 [DEBUG] switch_core_state_machine.c:560 (sofia/external/9051212121@218.165.240.142) State HANGUP going to sleep 2011-05-21 18:00:44.437500 [DEBUG] switch_core_state_machine.c:351 (sofia/external/9051212121@218.165.240.142) State Change CS_HANGUP -> CS_REPORTING 2011-05-21 18:00:44.437500 [DEBUG] switch_core_session.c:1116 Send signal sofia/external/9051212121@218.165.240.142 [BREAK] 2011-05-21 18:00:44.437500 [DEBUG] switch_core_state_machine.c:320 (sofia/external/9051212121@218.165.240.142) Running State Change CS_REPORTING 2011-05-21 18:00:44.437500 [DEBUG] switch_core_state_machine.c:620 (sofia/external/9051212121@218.165.240.142) State REPORTING 2011-05-21 18:00:44.453125 [DEBUG] switch_core_state_machine.c:53 sofia/external/9051212121@218.165.240.142 Standard REPORTING, cause: ORIGINATOR_CANCEL 2011-05-21 18:00:44.453125 [DEBUG] switch_core_state_machine.c:620 (sofia/external/9051212121@218.165.240.142) State REPORTING going to sleep 2011-05-21 18:00:44.453125 [DEBUG] switch_core_state_machine.c:345 (sofia/external/9051212121@218.165.240.142) State Change CS_REPORTING -> CS_DESTROY 2011-05-21 18:00:44.453125 [DEBUG] switch_core_session.c:1116 Send signal sofia/external/9051212121@218.165.240.142 [BREAK] 2011-05-21 18:00:44.453125 [DEBUG] switch_core_session.c:1288 Session 1 (sofia/external/9051212121@218.165.240.142) Locked, Waiting on external entities 2011-05-21 18:00:44.453125 [NOTICE] switch_core_session.c:1306 Session 1 (sofia/external/9051212121@218.165.240.142) Ended 2011-05-21 18:00:44.453125 [NOTICE] switch_core_session.c:1308 Close Channel sofia/external/9051212121@218.165.240.142 [CS_DESTROY] 2011-05-21 18:00:44.453125 [DEBUG] switch_core_state_machine.c:449 (sofia/external/9051212121@218.165.240.142) Callstate Change HANGUP -> DOWN 2011-05-21 18:00:44.453125 [DEBUG] switch_core_state_machine.c:452 (sofia/external/9051212121@218.165.240.142) Running State Change CS_DESTROY 2011-05-21 18:00:44.453125 [DEBUG] switch_core_state_machine.c:462 (sofia/external/9051212121@218.165.240.142) State DESTROY 2011-05-21 18:00:44.453125 [DEBUG] mod_sofia.c:362 sofia/external/9051212121@218.165.240.142 SOFIA DESTROY 2011-05-21 18:00:44.453125 [DEBUG] switch_core_state_machine.c:60 sofia/external/9051212121@218.165.240.142 Standard DESTROY 2011-05-21 18:00:44.453125 [DEBUG] switch_core_state_machine.c:462 (sofia/external/9051212121@218.165.240.142) State DESTROY going to sleep 2011-05-21 18:00:44.625000 [DEBUG] switch_nat.c:502 mapped public port 17091 protocol UDP to localport 17091 2011-05-21 18:00:44.625000 [DEBUG] switch_core_state_machine.c:356 (sofia/external/15191212121) State INIT going to 2011-05-21 18:00:44.625000 [DEBUG] switch_core_state_machine.c:320 (sofia/external/15191212121) Running State Change CS_HANGUP 2011-05-21 18:00:44.625000 [DEBUG] switch_core_state_machine.c:560 (sofia/external/15191212121) State HANGUP 2011-05-21 18:00:44.625000 [DEBUG] mod_sofia.c:451 sofia/external/15191212121 Overriding SIP cause 487 with 487 from the other leg 2011-05-21 18:00:44.625000 [DEBUG] mod_sofia.c:457 Channel sofia/external/15191212121 hanging up, cause: ORIGINATOR_CANCEL 2011-05-21 18:00:44.625000 [DEBUG] mod_sofia.c:510 Sending CANCEL to sofia/external/15191212121 2011-05-21 18:00:44.625000 [DEBUG] switch_core_state_machine.c:46 sofia/external/15191212121 Standard HANGUP, cause: ORIGINATOR_CANCEL 2011-05-21 18:00:44.625000 [DEBUG] switch_core_state_machine.c:560 (sofia/external/15191212121) State HANGUP going to sleep 2011-05-21 18:00:44.625000 [DEBUG] switch_core_state_machine.c:351 (sofia/external/15191212121) State Change CS_HANGUP -> CS_REPORTING 2011-05-21 18:00:44.625000 [DEBUG] switch_core_session.c:1116 Send signal sofia/external/15191212121 [BREAK] 2011-05-21 18:00:44.625000 [DEBUG] switch_core_state_machine.c:320 (sofia/external/15191212121) Running State Change CS_REPORTING 2011-05-21 18:00:44.625000 [DEBUG] switch_core_state_machine.c:620 (sofia/external/15191212121) State REPORTING 2011-05-21 18:00:44.625000 [DEBUG] switch_core_state_machine.c:53 sofia/external/15191212121 Standard REPORTING, cause: ORIGINATOR_CANCEL 2011-05-21 18:00:44.625000 [DEBUG] switch_core_state_machine.c:620 (sofia/external/15191212121) State REPORTING going to sleep 2011-05-21 18:00:44.625000 [DEBUG] switch_core_state_machine.c:345 (sofia/external/15191212121) State Change CS_REPORTING -> CS_DESTROY 2011-05-21 18:00:44.625000 [DEBUG] switch_core_session.c:1116 Send signal sofia/external/15191212121 [BREAK] 2011-05-21 18:00:44.625000 [DEBUG] switch_core_session.c:1288 Session 2 (sofia/external/15191212121) Locked, Waiting on external entities 2011-05-21 18:00:44.625000 [NOTICE] switch_core_session.c:1306 Session 2 (sofia/external/15191212121) Ended 2011-05-21 18:00:44.625000 [NOTICE] switch_core_session.c:1308 Close Channel sofia/external/15191212121 [CS_DESTROY] 2011-05-21 18:00:44.640625 [DEBUG] switch_core_state_machine.c:449 (sofia/external/15191212121) Callstate Change HANGUP -> DOWN 2011-05-21 18:00:44.640625 [DEBUG] switch_core_state_machine.c:452 (sofia/external/15191212121) Running State Change CS_DESTROY 2011-05-21 18:00:44.640625 [DEBUG] switch_core_state_machine.c:462 (sofia/external/15191212121) State DESTROY 2011-05-21 18:00:44.640625 [DEBUG] mod_sofia.c:362 sofia/external/15191212121 SOFIA DESTROY 2011-05-21 18:00:49.640625 [DEBUG] switch_nat.c:562 unmapped public port 17090 protocol UDP to localport 17090 2011-05-21 18:00:54.640625 [DEBUG] switch_nat.c:562 unmapped public port 17091 protocol UDP to localport 17091 2011-05-21 18:00:54.640625 [DEBUG] switch_core_state_machine.c:60 sofia/external/15191212121 Standard DESTROY 2011-05-21 18:00:54.640625 [DEBUG] switch_core_state_machine.c:462 (sofia/external/15191212121) State DESTROY going to sleep Thanks, Sergei Kamen -- View this message in context: http://freeswitch-users.2379917.n2.nabble.com/setting-up-forward-incoming-ca... Sent from the freeswitch-users mailing list archive at Nabble.com.
You will need to enable siptrace also - "sofia global siptrace on". My guess is this a NAT issue. /Peter ________________________________________ Från: freeswitch-users-bounces@lists.freeswitch.org [freeswitch-users-bounces@lists.freeswitch.org] för Kamen [sireeps@gmail.com] Skickat: den 22 maj 2011 01:16 Till: freeswitch-users@lists.freeswitch.org Ämne: Re: [Freeswitch-users] setting up forward incoming calls to external gateway Hi Michael, Frankly I am not sure what exactly you referring to. I am completely new to freeswitch. If you are talking about running command (I found it in online doc): TPORT_LOG=1 /usr/local/freeswitch/bin/freeswitch then there is a problem, Like I said I am running it in Windows. Running FreeSWITCH\FreeSwitchConsole.exe. Besides I have no idea what pastebin is. Only can guess it preserves the colors of debug printouts. I have instead prepared below a debug printout I manage to get in the console. Also added my comment. Please, could anyone have a look at it. Briefly, I want a simple functionality. If call comes in to my SIP provider I want it to be forwarded to another fixed external number. That is it! Seems like a straight forward task for freeswitch. The call seems to be forwarded (according to the log), but something stops it and it gets paused for 10 seconds, until busy signal and call is disconnected afterwards. Thanks in advance. Sergei Kamen ============================================================== public.xml has extension: <extension name="Forward All"> <condition field="caller_id_number" expression="^(\d+)$"> <action application="transfer" data="3472 XML default"/> </condition> </extension> and default.xml has: <extension name="Forward All"> <condition field="destination_number" expression="3472"> <action application="bridge" data="sofia/gateway/freephoneline/15191212121"/> </condition> </extension> The following printout in my console is as follows from the beginning: ------------------------------ nta: bind([::1]:5070;transport=*): No such file or directory nua: initializing SIP stack failed [SK:] could it be the error above? 2011-05-21 17:59:38.187500 [ERR] sofia.c:1533 Error Creating SIP UA for profile: internal-ipv6 2011-05-21 17:59:40.875000 [DEBUG] switch_nat.c:502 mapped public port 5080 protocol TCP to localport 5080 2011-05-21 17:59:40.875000 [DEBUG] sofia.c:1487 Created TCP nat mapping for external port 5080 2011-05-21 17:59:40.875000 [DEBUG] switch_nat.c:502 mapped public port 5070 protocol TCP to localport 5070 2011-05-21 17:59:40.875000 [DEBUG] sofia.c:1487 Created TCP nat mapping for internal port 5070 2011-05-21 17:59:40.906250 [DEBUG] sofia.c:1539 Created agent for external 2011-05-21 17:59:40.906250 [DEBUG] sofia.c:1576 Set params for external 2011-05-21 17:59:40.906250 [DEBUG] sofia.c:1599 Activated db for external 2011-05-21 17:59:40.906250 [DEBUG] sofia.c:1626 Starting thread for external 2011-05-21 17:59:40.921875 [DEBUG] sofia.c:1539 Created agent for internal 2011-05-21 17:59:40.921875 [DEBUG] sofia.c:1576 Set params for internal 2011-05-21 17:59:40.921875 [DEBUG] sofia.c:1599 Activated db for internal 2011-05-21 17:59:40.921875 [DEBUG] sofia.c:1626 Starting thread for internal 2011-05-21 17:59:41.921875 [NOTICE] sofia_reg.c:367 Registering mysipprovider 2011-05-21 17:59:44.062500 [DEBUG] sofia_reg.c:1922 Authenticating '16472222222' with 'Digest:"voip.mysipprovider.ca":16472222222:mypassword'. 2011-05-21 17:59:44.921875 [DEBUG] sofia_reg.c:331 Registered mysipprovider 2011-05-21 18:00:00.984375 [WARNING] sofia.c:4065 Ping succeeded mysipprovider with code 501 - count -1/1/1, state UP [SK:]I am calling here to my SIP provider number (16472222222) from another phone (9051212121). I expect it to forward to a third number (15191212121) with updated Caller ID of my provider. 2011-05-21 18:00:34.609375 [NOTICE] switch_channel.c:812 New Channel sofia/external/9051212121@218.165.240.142 [bc74d840-a951-458e-9eec-c70941fdd05a] 2011-05-21 18:00:34.609375 [DEBUG] sofia.c:4744 Channel sofia/external/9051212121@218.165.240.142 entering state [received][100] 2011-05-21 18:00:34.609375 [DEBUG] sofia.c:4755 Remote SDP: v=0 o=Sippy 383374256 0 IN IP4 218.165.240.142 s=- t=0 0 m=audio 35774 RTP/AVP 0 c=IN IP4 208.72.120.90 2011-05-21 18:00:34.609375 [DEBUG] sofia_glue.c:4637 Audio Codec Compare [PCMU:0:8000:20:64000]/[G7221:115:32000:20:48000] 2011-05-21 18:00:34.609375 [DEBUG] sofia_glue.c:4637 Audio Codec Compare [PCMU:0:8000:20:64000]/[G7221:107:16000:20:32000] 2011-05-21 18:00:34.609375 [DEBUG] sofia_glue.c:4637 Audio Codec Compare [PCMU:0:8000:20:64000]/[G722:9:8000:20:64000] 2011-05-21 18:00:34.609375 [DEBUG] switch_core_state_machine.c:320 (sofia/external/9051212121@218.165.240.142) Running State Change CS_NEW 2011-05-21 18:00:34.609375 [DEBUG] switch_core_state_machine.c:338 (sofia/external/9051212121@218.165.240.142) State NEW 2011-05-21 18:00:34.609375 [DEBUG] sofia_glue.c:4637 Audio Codec Compare [PCMU:0:8000:20:64000]/[PCMU:0:8000:20:64000] 2011-05-21 18:00:34.609375 [DEBUG] sofia_glue.c:2760 Set Codec sofia/external/9051212121@218.165.240.142 PCMU/8000 20 ms 160 samples 64000 bits 2011-05-21 18:00:34.609375 [DEBUG] sofia.c:4922 (sofia/external/9051212121@218.165.240.142) State Change CS_NEW -> CS_INIT 2011-05-21 18:00:34.609375 [DEBUG] switch_core_session.c:1116 Send signal sofia/external/9051212121@218.165.240.142 [BREAK] 2011-05-21 18:00:34.609375 [DEBUG] switch_core_state_machine.c:320 (sofia/external/9051212121@218.165.240.142) Running State Change CS_INIT 2011-05-21 18:00:34.609375 [DEBUG] switch_core_state_machine.c:356 (sofia/external/9051212121@218.165.240.142) State INIT 2011-05-21 18:00:34.609375 [DEBUG] mod_sofia.c:84 sofia/external/9051212121@218.165.240.142 SOFIA INIT 2011-05-21 18:00:34.609375 [DEBUG] mod_sofia.c:124 (sofia/external/9051212121@218.165.240.142) State Change CS_INIT -> CS_ROUTING 2011-05-21 18:00:34.609375 [DEBUG] switch_core_session.c:1116 Send signal sofia/external/9051212121@218.165.240.142 [BREAK] 2011-05-21 18:00:34.609375 [DEBUG] switch_core_state_machine.c:356 (sofia/external/9051212121@218.165.240.142) State INIT going to sleep 2011-05-21 18:00:34.609375 [DEBUG] switch_core_state_machine.c:320 (sofia/external/9051212121@218.165.240.142) Running State Change CS_ROUTING 2011-05-21 18:00:34.609375 [DEBUG] switch_channel.c:1668 (sofia/external/9051212121@218.165.240.142) Callstate Change DOWN -> RINGING 2011-05-21 18:00:34.609375 [DEBUG] switch_core_state_machine.c:359 (sofia/external/9051212121@218.165.240.142) State ROUTING 2011-05-21 18:00:34.609375 [DEBUG] mod_sofia.c:147 sofia/external/9051212121@218.165.240.142 SOFIA ROUTING 2011-05-21 18:00:34.609375 [DEBUG] switch_core_state_machine.c:77 sofia/external/9051212121@218.165.240.142 Standard ROUTING 2011-05-21 18:00:34.609375 [INFO] mod_dialplan_xml.c:331 Processing MICHAEL S <9051212121>->3472 in context public Dialplan: sofia/external/9051212121@218.165.240.142 parsing [public->Forward All] continue=false Dialplan: sofia/external/9051212121@218.165.240.142 Regex (PASS) [Forward All] caller_id_number(9051212121) =~ /^(\d+)$/ break=on-false Dialplan: sofia/external/9051212121@218.165.240.142 Action transfer(3472 XML default) 2011-05-21 18:00:34.609375 [DEBUG] switch_core_state_machine.c:119 (sofia/external/9051212121@218.165.240.142) State Change CS_ROUTING -> CS_EXECUTE 2011-05-21 18:00:34.609375 [DEBUG] switch_core_session.c:1116 Send signal sofia/external/9051212121@218.165.240.142 [BREAK] 2011-05-21 18:00:34.609375 [DEBUG] switch_core_state_machine.c:359 (sofia/external/9051212121@218.165.240.142) State ROUTING going to sleep 2011-05-21 18:00:34.609375 [DEBUG] switch_core_state_machine.c:320 (sofia/external/9051212121@218.165.240.142) Running State Change CS_EXECUTE 2011-05-21 18:00:34.609375 [DEBUG] switch_core_state_machine.c:366 (sofia/external/9051212121@218.165.240.142) State EXECUTE 2011-05-21 18:00:34.609375 [DEBUG] mod_sofia.c:240 sofia/external/9051212121@218.165.240.142 SOFIA EXECUTE 2011-05-21 18:00:34.609375 [DEBUG] switch_core_state_machine.c:157 sofia/external/9051212121@218.165.240.142 Standard EXECUTE EXECUTE sofia/external/9051212121@218.165.240.142 transfer(3472 XML default) 2011-05-21 18:00:34.609375 [DEBUG] switch_ivr.c:1600 (sofia/external/9051212121@218.165.240.142) State Change CS_EXECUTE -> CS_ROUTING 2011-05-21 18:00:34.609375 [DEBUG] switch_core_session.c:1116 Send signal sofia/external/9051212121@218.165.240.142 [BREAK] 2011-05-21 18:00:34.609375 [DEBUG] switch_core_session.c:709 Send signal sofia/external/9051212121@218.165.240.142 [BREAK] 2011-05-21 18:00:34.609375 [NOTICE] switch_ivr.c:1606 Transfer sofia/external/9051212121@218.165.240.142 to XML[3472@default] 2011-05-21 18:00:34.609375 [DEBUG] switch_core_state_machine.c:366 (sofia/external/9051212121@218.165.240.142) State EXECUTE going to sleep 2011-05-21 18:00:34.609375 [DEBUG] switch_core_state_machine.c:320 (sofia/external/9051212121@218.165.240.142) Running State Change CS_ROUTING 2011-05-21 18:00:34.609375 [DEBUG] switch_core_state_machine.c:359 (sofia/external/9051212121@218.165.240.142) State ROUTING 2011-05-21 18:00:34.609375 [DEBUG] mod_sofia.c:147 sofia/external/9051212121@218.165.240.142 SOFIA ROUTING 2011-05-21 18:00:34.609375 [DEBUG] switch_core_state_machine.c:77 sofia/external/9051212121@218.165.240.142 Standard ROUTING 2011-05-21 18:00:34.609375 [INFO] mod_dialplan_xml.c:331 Processing SIDOROV S <9051212121>->3472 in context default Dialplan: sofia/external/9051212121@218.165.240.142 parsing [default->Forward All] continue=false Dialplan: sofia/external/9051212121@218.165.240.142 Regex (PASS) [Forward All] destination_number(3472) =~ /3472/ break=on-false Dialplan: sofia/external/9051212121@218.165.240.142 Action log(INFO dialing destination number) Dialplan: sofia/external/9051212121@218.165.240.142 Action bridge(sofia/gateway/mysipprovider/15191212121) 2011-05-21 18:00:34.609375 [DEBUG] switch_core_state_machine.c:119 (sofia/external/9051212121@218.165.240.142) State Change CS_ROUTING -> CS_EXECUTE 2011-05-21 18:00:34.609375 [DEBUG] switch_core_session.c:1116 Send signal sofia/external/9051212121@218.165.240.142 [BREAK] 2011-05-21 18:00:34.609375 [DEBUG] switch_core_state_machine.c:359 (sofia/external/9051212121@218.165.240.142) State ROUTING going to sleep 2011-05-21 18:00:34.609375 [DEBUG] switch_core_state_machine.c:320 (sofia/external/9051212121@218.165.240.142) Running State Change CS_EXECUTE 2011-05-21 18:00:34.609375 [DEBUG] switch_core_state_machine.c:366 (sofia/external/9051212121@218.165.240.142) State EXECUTE 2011-05-21 18:00:34.609375 [DEBUG] mod_sofia.c:240 sofia/external/9051212121@218.165.240.142 SOFIA EXECUTE 2011-05-21 18:00:34.609375 [DEBUG] switch_core_state_machine.c:157 sofia/external/9051212121@218.165.240.142 Standard EXECUTE EXECUTE sofia/external/9051212121@218.165.240.142 log(INFO dialing destination number) 2011-05-21 18:00:34.609375 [INFO] mod_dptools.c:1183 dialing destination number EXECUTE sofia/external/9051212121@218.165.240.142 bridge(sofia/gateway/mysipprovider/15191212121) 2011-05-21 18:00:34.625000 [NOTICE] switch_channel.c:812 New Channel sofia/external/15191212121 [5a8e5141-6d37-4db3-b5d4-5c3d1f952bbe] 2011-05-21 18:00:34.625000 [DEBUG] mod_sofia.c:4286 (sofia/external/15191212121) State Change CS_NEW -> CS_INIT 2011-05-21 18:00:34.625000 [DEBUG] switch_core_session.c:1116 Send signal sofia/external/15191212121 [BREAK] 2011-05-21 18:00:34.625000 [DEBUG] switch_core_state_machine.c:320 (sofia/external/15191212121) Running State Change CS_INIT 2011-05-21 18:00:34.625000 [DEBUG] switch_core_state_machine.c:356 (sofia/external/15191212121) State INIT 2011-05-21 18:00:34.625000 [DEBUG] mod_sofia.c:84 sofia/external/15191212121 SOFIA INIT [SK:]Pause starts here 2011-05-21 18:00:39.625000 [DEBUG] switch_nat.c:502 mapped public port 17090 protocol UDP to localport 17090 [SK:]I get short "busy" signal here, and hang up. The rest is "hanging up" process messages. 2011-05-21 18:00:44.421875 [DEBUG] sofia.c:4744 Channel sofia/external/9051212121@218.165.240.142 entering state [terminated][487] 2011-05-21 18:00:44.421875 [DEBUG] switch_channel.c:2563 (sofia/external/9051212121@218.165.240.142) Callstate Change RINGING -> HANGUP 2011-05-21 18:00:44.421875 [NOTICE] sofia.c:5384 Hangup sofia/external/9051212121@218.165.240.142 [CS_EXECUTE] [ORIGINATOR_CANCEL] 2011-05-21 18:00:44.421875 [DEBUG] switch_channel.c:2579 Send signal sofia/external/9051212121@218.165.240.142 [KILL] 2011-05-21 18:00:44.421875 [DEBUG] switch_core_session.c:1116 Send signal sofia/external/9051212121@218.165.240.142 [BREAK] 2011-05-21 18:00:44.437500 [DEBUG] switch_channel.c:2563 (sofia/external/15191212121) Callstate Change DOWN -> HANGUP 2011-05-21 18:00:44.437500 [NOTICE] switch_ivr_originate.c:3343 Hangup sofia/external/15191212121 [CS_INIT] [ORIGINATOR_CANCEL] 2011-05-21 18:00:44.437500 [DEBUG] switch_channel.c:2579 Send signal sofia/external/15191212121 [KILL] 2011-05-21 18:00:44.437500 [DEBUG] switch_core_session.c:1116 Send signal sofia/external/15191212121 [BREAK] 2011-05-21 18:00:44.437500 [DEBUG] switch_ivr_originate.c:3500 Originate Cancelled by originator termination Cause: 487 [ORIGINATOR_CANCEL] 2011-05-21 18:00:44.437500 [INFO] mod_dptools.c:2623 Originate Failed. Cause: ORIGINATOR_CANCEL 2011-05-21 18:00:44.437500 [DEBUG] switch_core_session.c:2060 sofia/external/9051212121@218.165.240.142 skip receive message [APPLICATION_EXEC_COMPLETE] (channel is hungup already) 2011-05-21 18:00:44.437500 [DEBUG] switch_core_state_machine.c:366 (sofia/external/9051212121@218.165.240.142) State EXECUTE going to sleep 2011-05-21 18:00:44.437500 [DEBUG] switch_core_state_machine.c:320 (sofia/external/9051212121@218.165.240.142) Running State Change CS_HANGUP 2011-05-21 18:00:44.437500 [DEBUG] switch_core_state_machine.c:560 (sofia/external/9051212121@218.165.240.142) State HANGUP 2011-05-21 18:00:44.437500 [DEBUG] mod_sofia.c:451 sofia/external/9051212121@218.165.240.142 Overriding SIP cause 487 with 487 from the other leg 2011-05-21 18:00:44.437500 [DEBUG] mod_sofia.c:457 Channel sofia/external/9051212121@218.165.240.142 hanging up, cause: ORIGINATOR_CANCEL 2011-05-21 18:00:44.437500 [DEBUG] switch_core_state_machine.c:46 sofia/external/9051212121@218.165.240.142 Standard HANGUP, cause: ORIGINATOR_CANCEL 2011-05-21 18:00:44.437500 [DEBUG] switch_core_state_machine.c:560 (sofia/external/9051212121@218.165.240.142) State HANGUP going to sleep 2011-05-21 18:00:44.437500 [DEBUG] switch_core_state_machine.c:351 (sofia/external/9051212121@218.165.240.142) State Change CS_HANGUP -> CS_REPORTING 2011-05-21 18:00:44.437500 [DEBUG] switch_core_session.c:1116 Send signal sofia/external/9051212121@218.165.240.142 [BREAK] 2011-05-21 18:00:44.437500 [DEBUG] switch_core_state_machine.c:320 (sofia/external/9051212121@218.165.240.142) Running State Change CS_REPORTING 2011-05-21 18:00:44.437500 [DEBUG] switch_core_state_machine.c:620 (sofia/external/9051212121@218.165.240.142) State REPORTING 2011-05-21 18:00:44.453125 [DEBUG] switch_core_state_machine.c:53 sofia/external/9051212121@218.165.240.142 Standard REPORTING, cause: ORIGINATOR_CANCEL 2011-05-21 18:00:44.453125 [DEBUG] switch_core_state_machine.c:620 (sofia/external/9051212121@218.165.240.142) State REPORTING going to sleep 2011-05-21 18:00:44.453125 [DEBUG] switch_core_state_machine.c:345 (sofia/external/9051212121@218.165.240.142) State Change CS_REPORTING -> CS_DESTROY 2011-05-21 18:00:44.453125 [DEBUG] switch_core_session.c:1116 Send signal sofia/external/9051212121@218.165.240.142 [BREAK] 2011-05-21 18:00:44.453125 [DEBUG] switch_core_session.c:1288 Session 1 (sofia/external/9051212121@218.165.240.142) Locked, Waiting on external entities 2011-05-21 18:00:44.453125 [NOTICE] switch_core_session.c:1306 Session 1 (sofia/external/9051212121@218.165.240.142) Ended 2011-05-21 18:00:44.453125 [NOTICE] switch_core_session.c:1308 Close Channel sofia/external/9051212121@218.165.240.142 [CS_DESTROY] 2011-05-21 18:00:44.453125 [DEBUG] switch_core_state_machine.c:449 (sofia/external/9051212121@218.165.240.142) Callstate Change HANGUP -> DOWN 2011-05-21 18:00:44.453125 [DEBUG] switch_core_state_machine.c:452 (sofia/external/9051212121@218.165.240.142) Running State Change CS_DESTROY 2011-05-21 18:00:44.453125 [DEBUG] switch_core_state_machine.c:462 (sofia/external/9051212121@218.165.240.142) State DESTROY 2011-05-21 18:00:44.453125 [DEBUG] mod_sofia.c:362 sofia/external/9051212121@218.165.240.142 SOFIA DESTROY 2011-05-21 18:00:44.453125 [DEBUG] switch_core_state_machine.c:60 sofia/external/9051212121@218.165.240.142 Standard DESTROY 2011-05-21 18:00:44.453125 [DEBUG] switch_core_state_machine.c:462 (sofia/external/9051212121@218.165.240.142) State DESTROY going to sleep 2011-05-21 18:00:44.625000 [DEBUG] switch_nat.c:502 mapped public port 17091 protocol UDP to localport 17091 2011-05-21 18:00:44.625000 [DEBUG] switch_core_state_machine.c:356 (sofia/external/15191212121) State INIT going to 2011-05-21 18:00:44.625000 [DEBUG] switch_core_state_machine.c:320 (sofia/external/15191212121) Running State Change CS_HANGUP 2011-05-21 18:00:44.625000 [DEBUG] switch_core_state_machine.c:560 (sofia/external/15191212121) State HANGUP 2011-05-21 18:00:44.625000 [DEBUG] mod_sofia.c:451 sofia/external/15191212121 Overriding SIP cause 487 with 487 from the other leg 2011-05-21 18:00:44.625000 [DEBUG] mod_sofia.c:457 Channel sofia/external/15191212121 hanging up, cause: ORIGINATOR_CANCEL 2011-05-21 18:00:44.625000 [DEBUG] mod_sofia.c:510 Sending CANCEL to sofia/external/15191212121 2011-05-21 18:00:44.625000 [DEBUG] switch_core_state_machine.c:46 sofia/external/15191212121 Standard HANGUP, cause: ORIGINATOR_CANCEL 2011-05-21 18:00:44.625000 [DEBUG] switch_core_state_machine.c:560 (sofia/external/15191212121) State HANGUP going to sleep 2011-05-21 18:00:44.625000 [DEBUG] switch_core_state_machine.c:351 (sofia/external/15191212121) State Change CS_HANGUP -> CS_REPORTING 2011-05-21 18:00:44.625000 [DEBUG] switch_core_session.c:1116 Send signal sofia/external/15191212121 [BREAK] 2011-05-21 18:00:44.625000 [DEBUG] switch_core_state_machine.c:320 (sofia/external/15191212121) Running State Change CS_REPORTING 2011-05-21 18:00:44.625000 [DEBUG] switch_core_state_machine.c:620 (sofia/external/15191212121) State REPORTING 2011-05-21 18:00:44.625000 [DEBUG] switch_core_state_machine.c:53 sofia/external/15191212121 Standard REPORTING, cause: ORIGINATOR_CANCEL 2011-05-21 18:00:44.625000 [DEBUG] switch_core_state_machine.c:620 (sofia/external/15191212121) State REPORTING going to sleep 2011-05-21 18:00:44.625000 [DEBUG] switch_core_state_machine.c:345 (sofia/external/15191212121) State Change CS_REPORTING -> CS_DESTROY 2011-05-21 18:00:44.625000 [DEBUG] switch_core_session.c:1116 Send signal sofia/external/15191212121 [BREAK] 2011-05-21 18:00:44.625000 [DEBUG] switch_core_session.c:1288 Session 2 (sofia/external/15191212121) Locked, Waiting on external entities 2011-05-21 18:00:44.625000 [NOTICE] switch_core_session.c:1306 Session 2 (sofia/external/15191212121) Ended 2011-05-21 18:00:44.625000 [NOTICE] switch_core_session.c:1308 Close Channel sofia/external/15191212121 [CS_DESTROY] 2011-05-21 18:00:44.640625 [DEBUG] switch_core_state_machine.c:449 (sofia/external/15191212121) Callstate Change HANGUP -> DOWN 2011-05-21 18:00:44.640625 [DEBUG] switch_core_state_machine.c:452 (sofia/external/15191212121) Running State Change CS_DESTROY 2011-05-21 18:00:44.640625 [DEBUG] switch_core_state_machine.c:462 (sofia/external/15191212121) State DESTROY 2011-05-21 18:00:44.640625 [DEBUG] mod_sofia.c:362 sofia/external/15191212121 SOFIA DESTROY 2011-05-21 18:00:49.640625 [DEBUG] switch_nat.c:562 unmapped public port 17090 protocol UDP to localport 17090 2011-05-21 18:00:54.640625 [DEBUG] switch_nat.c:562 unmapped public port 17091 protocol UDP to localport 17091 2011-05-21 18:00:54.640625 [DEBUG] switch_core_state_machine.c:60 sofia/external/15191212121 Standard DESTROY 2011-05-21 18:00:54.640625 [DEBUG] switch_core_state_machine.c:462 (sofia/external/15191212121) State DESTROY going to sleep Thanks, Sergei Kamen -- View this message in context: http://freeswitch-users.2379917.n2.nabble.com/setting-up-forward-incoming-ca... Sent from the freeswitch-users mailing list archive at Nabble.com. _______________________________________________ FreeSWITCH-users mailing list FreeSWITCH-users@lists.freeswitch.org http://lists.freeswitch.org/mailman/listinfo/freeswitch-users UNSUBSCRIBE:http://lists.freeswitch.org/mailman/options/freeswitch-users http://www.freeswitch.org !DSPAM:4dd8496432761158895848!
Hi Peter, Michael Thanks for your suggestion. I enabled the sip trace and got the following traces while calling inbound: ===================================== freeswitch@mars> sofia global siptrace on +OK Global siptrace on freeswitch@mars> recv 869 bytes from udp/[218.165.240.142]:5060 at 16:23:07.562500: ------------------------------------------------------------------------ INVITE sip:gw+mysipprovider@192.168.123.100:5080;transport=udp;gw=mysipprovider SIP/2.0 Via: SIP/2.0/UDP 218.165.240.142:5060;branch=z9hG4bK-d8754z-03f1d4147d39e75a-1---d8754z-;rport Via: SIP/2.0/UDP 218.165.240.142:5061;branch=z9hG4bK-6yit3js32dookuqy;rport=5061 Max-Forwards: 69 Record-Route: <sip:218.165.240.142;lr> Contact: "Anonymous"<sip:218.165.240.142:5061> To: <sip:16472222222@218.165.240.142> From: "MICHAEL S"<sip:9051212121@218.165.240.142>;tag=uvgya25q6jekqd53.o Call-ID: 80741E4A@208.72.120.66~o CSeq: 120 INVITE Expires: 300 Content-Disposition: session Content-Type: application/sdp User-Agent: Sippy cisco-GUID: 51683594-2224034272-2239627291-559912524 h323-conf-id: 51683594-2224034272-2239627291-559912524 Content-Length: 109 v=0 o=Sippy 450031128 0 IN IP4 218.165.240.142 s=- t=0 0 m=audio 34260 RTP/AVP 0 c=IN IP4 208.72.120.90 ------------------------------------------------------------------------ send 506 bytes to udp/[218.165.240.142]:5060 at 16:23:07.562500: ------------------------------------------------------------------------ SIP/2.0 100 Trying Via: SIP/2.0/UDP 218.165.240.142:5060;branch=z9hG4bK-d8754z-03f1d4147d39e75a-1---d8754z-;rport=5060 Via: SIP/2.0/UDP 218.165.240.142:5061;branch=z9hG4bK-6yit3js32dookuqy;rport=5061 Record-Route: <sip:218.165.240.142;lr> From: "MICHAEL S"<sip:9051212121@218.165.240.142>;tag=uvgya25q6jekqd53.o To: <sip:16472222222@218.165.240.142> Call-ID: 80741E4A@208.72.120.66~o CSeq: 120 INVITE User-Agent: FreeSWITCH-mod_sofia/1.0.head-git-57b6255 2011-03-22 15-15-09 -0500 Content-Length: 0 ------------------------------------------------------------------------ 2011-05-22 12:23:07.562500 [NOTICE] switch_channel.c:812 New Channel sofia/external/9051212121@218.165.240.142 [2b6b8394-faab-4704-a3be-158396d08477] 2011-05-22 12:23:07.562500 [DEBUG] sofia.c:4744 Channel sofia/external/9051212121@218.165.240.142 entering state [received][100] 2011-05-22 12:23:07.562500 [DEBUG] sofia.c:4755 Remote SDP: v=0 o=Sippy 450031128 0 IN IP4 218.165.240.142 s=- t=0 0 m=audio 34260 RTP/AVP 0 c=IN IP4 208.72.120.90 ============================================================ I am not sure how to interpret above, but I hope this will give you some clue. I also have the printout file, but I do not see how I can attach it here. Do not think putting over 2000 lines into this message would be polite :) After you suggestion that it could be a NAT issue, I checked the log more closely and found the following at the very startup: ============================================================ 2011-05-22 12:21:40.312500 [INFO] switch_event.c:615 Activate Eventing Engine. 2011-05-22 12:21:40.343750 [DEBUG] switch_event.c:594 Create event dispatch thread 0 2011-05-22 12:21:41.328125 [INFO] switch_nat.c:411 Scanning for NAT 2011-05-22 12:21:41.343750 [DEBUG] switch_nat.c:168 Checking for PMP 1/5 2011-05-22 12:21:41.343750 [ERR] switch_nat.c:199 Error checking for PMP [general error] 2011-05-22 12:21:41.343750 [DEBUG] switch_nat.c:416 Checking for UPnP 2011-05-22 12:21:47.046875 [INFO] switch_nat.c:425 NAT detected type: upnp, ExtIP: '173.248.202.119' 2011-05-22 12:21:47.046875 [ERR] switch_nat.c:251 Bind Error 2011-05-22 12:21:47.046875 [ERR] switch_nat.c:358 Unable to initialize NAT thread ================================================================== Those are the very first lines of the traces. The last line of this quote kind of points to the NAT problem. What do you think, could it be related? Although I did an experiment and connected my PC over DMZ on my router. The result was exactly the same. What bugs me is that I can see communication in the trace. The call for sure gets to FS, where it being processed and kind of forwarded to the defined number. Where it gets stalled. If there was a problem with SIP, would it even get to FS from outside? Anyway, thanks for looking into it. Appreciate it. It helps me to look at the problem from other angles. Hope to hear more of your suggestions. Meanwhile I will keep banging my head against it "from different angles". :) Regards, Sergei Kamen -- View this message in context: http://freeswitch-users.2379917.n2.nabble.com/setting-up-forward-incoming-ca... Sent from the freeswitch-users mailing list archive at Nabble.com.
"Do not think putting over 2000 lines into this message would be polite :) " You can always paste it into http://pastebin.freeswitch.org and then put the URL in the email :) Steve on iPhone On 22 May 2011, at 19:08, Kamen <sireeps@gmail.com> wrote:
Do not think putting over 2000 lines into this message would be polite :)
Steven Ayre wrote:
You can always paste it into http://pastebin.freeswitch.org and then put the URL in the email :)
Oh, great! Thanks Steven! I was wondering what that pastebin means. I am confused, though. While trying to get into pastebin, I was asked for a login. Do I need to sign up to use it? I tried to login with my credentials for this forum/mailing list and got rejected. Please help me out here. Thanks, Sergei Kamen -- View this message in context: http://freeswitch-users.2379917.n2.nabble.com/setting-up-forward-incoming-ca... Sent from the freeswitch-users mailing list archive at Nabble.com.
I am confused, though. While trying to get into pastebin, I was asked for a login. Do I need to sign up to use it? I tried to login with my credentials for this forum/mailing list and got rejected. Please help me out here.
Are you sure you were asked for a login, because you _read_ what it asked you:) Try again, but have a quick read of the prompt...
On Sun, May 22, 2011 at 4:58 PM, Joseph L. Casale <jcasale@activenetwerx.com> wrote:
Are you sure you were asked for a login, because you _read_ what it asked you:) Try again, but have a quick read of the prompt...
This is true, but if you've seen it in Chrome, it's not very clear what's expected. I hate to include attachments to the list, but this isn't the first time it's come up. Anyway, see the attached dialogs if you're interested in seeing the difference yourselves. Is there a better way of letting users know how to get in? Is this even an issue? Best, Gabe
Yuck, you're right that is a little confusing. :) On 23 May 2011 07:24, Gabriel Gunderson <gabe@gundy.org> wrote:
On Sun, May 22, 2011 at 4:58 PM, Joseph L. Casale <jcasale@activenetwerx.com> wrote:
Are you sure you were asked for a login, because you _read_ what it asked you:) Try again, but have a quick read of the prompt...
This is true, but if you've seen it in Chrome, it's not very clear what's expected. I hate to include attachments to the list, but this isn't the first time it's come up. Anyway, see the attached dialogs if you're interested in seeing the difference yourselves.
Is there a better way of letting users know how to get in? Is this even an issue?
Best, Gabe
_______________________________________________ FreeSWITCH-users mailing list FreeSWITCH-users@lists.freeswitch.org http://lists.freeswitch.org/mailman/listinfo/freeswitch-users UNSUBSCRIBE:http://lists.freeswitch.org/mailman/options/freeswitch-users http://www.freeswitch.org
Gabriel! I really appreciate your clarification post. I am using Chrome as my default browser and the message confused me. Following you suggestion I opened it in Firefox and finally got what was needed. Yeah, may be I am not that quick thinking chap, but hay, thats why I am here looking for your advise. Cheers Sergei Kamen -- View this message in context: http://freeswitch-users.2379917.n2.nabble.com/setting-up-forward-incoming-ca... Sent from the freeswitch-users mailing list archive at Nabble.com.
Hello, I have posted the trace with sip trace on at pastebin. Thanks everyone for helping me out with that. The only thing is that I do not know how to get the trace with freeswitch highlights on. So for now it is plain text (I will appreciate any hints on how to get the highlights, though). I added some comments in there. http://pastebin.freeswitch.org/16358 http://pastebin.freeswitch.org/16358 Could anyone please have a look and let me know what I have wrong in my setup. I'd like to repeat that this is really a simple case of forwarding incoming external call to outgoing external. Thanks a lot! Sergei Kamen -- View this message in context: http://freeswitch-users.2379917.n2.nabble.com/setting-up-forward-incoming-ca... Sent from the freeswitch-users mailing list archive at Nabble.com.
When you do the pastebin there is a drop-down box for "Syntax Highlighting" - choose "FreeSWITCH Log" and it will do the colorizing for you. -MC On Mon, May 23, 2011 at 8:25 AM, Kamen <sireeps@gmail.com> wrote:
Hello,
I have posted the trace with sip trace on at pastebin. Thanks everyone for helping me out with that. The only thing is that I do not know how to get the trace with freeswitch highlights on. So for now it is plain text (I will appreciate any hints on how to get the highlights, though). I added some comments in there.
http://pastebin.freeswitch.org/16358 http://pastebin.freeswitch.org/16358
Could anyone please have a look and let me know what I have wrong in my setup. I'd like to repeat that this is really a simple case of forwarding incoming external call to outgoing external.
Thanks a lot!
Sergei Kamen
-- View this message in context: http://freeswitch-users.2379917.n2.nabble.com/setting-up-forward-incoming-ca... Sent from the freeswitch-users mailing list archive at Nabble.com.
_______________________________________________ FreeSWITCH-users mailing list FreeSWITCH-users@lists.freeswitch.org http://lists.freeswitch.org/mailman/listinfo/freeswitch-users UNSUBSCRIBE:http://lists.freeswitch.org/mailman/options/freeswitch-users http://www.freeswitch.org
Yeah, it does! Thanks, MC! Here is the colored trace: http://pastebin.freeswitch.org/16360 http://pastebin.freeswitch.org/16360 Please have a look. Could it be really NAT? Seems like everything else is working fine over my router. Besides I was trying to test it directly over DMZ connection with the same results. Thanks in advance! Regards, Sergei Kamen -- View this message in context: http://freeswitch-users.2379917.n2.nabble.com/setting-up-forward-incoming-ca... Sent from the freeswitch-users mailing list archive at Nabble.com.
Okay, let me make a suggestion: only include the actual call. You have all of the startup and shutdown stuff in there and it's confusing. Capture only the part where you make the call and include it from start to finish, including the siptrace. -MC On Mon, May 23, 2011 at 2:36 PM, Kamen <sireeps@gmail.com> wrote:
Yeah, it does! Thanks, MC!
Here is the colored trace:
http://pastebin.freeswitch.org/16360 http://pastebin.freeswitch.org/16360
Please have a look. Could it be really NAT? Seems like everything else is working fine over my router. Besides I was trying to test it directly over DMZ connection with the same results. Thanks in advance!
Regards,
Sergei Kamen
-- View this message in context: http://freeswitch-users.2379917.n2.nabble.com/setting-up-forward-incoming-ca... Sent from the freeswitch-users mailing list archive at Nabble.com.
_______________________________________________ FreeSWITCH-users mailing list FreeSWITCH-users@lists.freeswitch.org http://lists.freeswitch.org/mailman/listinfo/freeswitch-users UNSUBSCRIBE:http://lists.freeswitch.org/mailman/options/freeswitch-users http://www.freeswitch.org
Sure, no problem! Sorry about that. I am not sure what is important and what is not, that's why. The trimmed down trace is here: http://pastebin.freeswitch.org/16362 http://pastebin.freeswitch.org/16362 Cheers, Sergei Kamen -- View this message in context: http://freeswitch-users.2379917.n2.nabble.com/setting-up-forward-incoming-ca... Sent from the freeswitch-users mailing list archive at Nabble.com.
Alright folks! I have figured the problem. The solution was kind of simple. My SIP provider does not ring back while caller is trying to connect to the number. After 10 seconds of silence the line is disconnected on caller side. I do not know why it takes longer than 10 seconds to connect, but that is another issue. In any case after I added <action application="ring_ready"/> to my default extension the caller can hear rings and the system does not hangup. Eventually the call gets through. Thanks anyone who tried to help me, anyway. Regards, Sergei Kamen -- View this message in context: http://freeswitch-users.2379917.n2.nabble.com/setting-up-forward-incoming-ca... Sent from the freeswitch-users mailing list archive at Nabble.com.
participants (6)
-
Gabriel Gunderson
-
Joseph L. Casale
-
Kamen
-
Michael Collins
-
Peter Olsson
-
Steven Ayre