[Freeswitch-users] Help on reading the log better

Thu Aug 5 02:20:26 PDT 2010

The gateway must have username/password configured, but you can set register=false to tell you're not using it.

  <param name="username" value="whatever"/>
  <param name="password" value=" whatever"/>
  <param name="register" value="false"/>

/Peter

Från: freeswitch-users-bounces at lists.freeswitch.org [mailto:freeswitch-users-bounces at lists.freeswitch.org] För Nyamul Hassan
Skickat: den 5 augusti 2010 11:09
Till: FreeSWITCH Users Help
Ämne: Re: [Freeswitch-users] Help on reading the log better

Thank you for the detailed response Steven.  You were right, I was comparing my original config to the new one, and found that I did need to use it as you have said, sofia/gateway/sky189/$1

That being said, I was also unable to make a gateway without using a "username" / "password".  My providers don't need any username password, and use our IP address for authentication.  We can use the "sofia/internal/$1@<ip of provider>" format though.

Regards
HASSAN

On Thu, Aug 5, 2010 at 14:46, Steven Ayre <steveayre at gmail.com<mailto:steveayre at gmail.com>> wrote:
The call is getting 503 Service Unavailable.

2010-08-04 13:06:48.858888 [DEBUG] sofia.c:4318 Channel sofia/external/1234567890 at sky189 entering state [calling][0]
2010-08-04 13:06:48.861065 [DEBUG] sofia.c:4318 Channel sofia/external/1234567890 at sky189 entering state [terminated][503]

This either comes from the remote host, or from within the SIP stack.

An example of when I've seen Sofia generate 503 errors is when DNS lookups were failing. I'm guessing this is what is happening in your case as you're dialing "sofia/external/1234567890 at sky189".

sky189 isn't a domain name, so it won't resolve to anything for sofia to dial (unless you have a very unusual setup). My guess is what you're actually trying to do is call through a gateway named sky189. The syntax for that is different: "sofia/gateway/sky189/1234567890"

If that's not it then more debugging information should let you track down the error.
If you enable siptrace for the profile you are calling out on, then the log will include the SIP messages sent. This will let you see if the 503 is a reply from the destination.
If it isn't then it's probably within the sofia SIP stack. You can enable debugging for that stack to see why the error occurs (this would show the dns error for example). The wiki shows how to enable this debugging: http://wiki.freeswitch.org/wiki/Mod_sofia#Debugging_Sofia-SIP

-Steve

On 4 August 2010 18:52, Nyamul Hassan <mnhassan at usa.net<mailto:mnhassan at usa.net>> wrote:
Hi,

I've finished the book, and was able to send a call through to another switch that we use.  There was an initial codec mismatch (G729), but after reading the debug logs (fs_cli /log 7), it was identified and after fixing that, the call went through just fine.

Today, I was trying some more changes on the default config, and the call will not go through.  While that is not a problem as I can always go back to the default conf, what was bothering me is that I could not find out the right cause by reading the logs.  The call also did not hit the other switch.  Perhaps I am not reading something right.  Can someone please help me identify what part of the logs below are showing where the calls are failing?

The log is given below my signature.  I changed my IPs and dialed number.  Sorry for the inconvenience.

Regards
HASSAN

2010-08-04 13:06:47.459004 [DEBUG] sofia.c:6000 IP 192.168.254.10 Rejected by acl "domains". Falling back to Digest auth.
2010-08-04 13:06:48.853933 [DEBUG] sofia.c:6000 IP 192.168.254.10 Rejected by acl "domains". Falling back to Digest auth.
2010-08-04 13:06:48.855161 [NOTICE] switch_channel.c:779 New Channel sofia/internal/hassan at a.b.c.d [3b01cb99-20dd-4a9d-8084-2f2e16a5aee6]
2010-08-04 13:06:48.855161 [DEBUG] switch_core_state_machine.c:314 (sofia/internal/hassan at a.b.c.d) Running State Change CS_NEW
2010-08-04 13:06:48.855161 [DEBUG] switch_core_state_machine.c:320 (sofia/internal/hassan at a.b.c.d) State NEW
2010-08-04 13:06:48.856895 [DEBUG] sofia.c:6823 Setting NAT mode based on nat.auto
2010-08-04 13:06:48.856895 [DEBUG] sofia.c:4318 Channel sofia/internal/hassan at a.b.c.d entering state [received][100]
2010-08-04 13:06:48.856895 [DEBUG] sofia.c:4329 Remote SDP:
v=0
o=- 9 2 IN IP4 192.168.254.10
s=CounterPath Bria
c=IN IP4 192.168.254.10
t=0 0
m=audio 63242 RTP/AVP 18 101
a=rtpmap:18 G729/8000
a=fmtp:18 annexb=yes
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-15
a=alt:1 2 : wsPFY2UY ge45TD7O a1.b1.c1.d1 63242
a=alt:2 1 : mCzsWRNJ nH/GgDGG 192.168.254.10 63242
a=x-rtp-session-id:C59D45BA9189497CB4C041AC656702E2

2010-08-04 13:06:48.856895 [DEBUG] sofia_glue.c:3845 Audio Codec Compare [G729:18:8000:20]/[G729:18:8000:20]
2010-08-04 13:06:48.856895 [DEBUG] sofia_glue.c:2442 Set Codec sofia/internal/hassan at a.b.c.d G729/8000 20 ms 160 samples
2010-08-04 13:06:48.856895 [DEBUG] sofia_glue.c:3941 Set 2833 dtmf send/recv payload to 101
2010-08-04 13:06:48.856895 [DEBUG] sofia.c:4476 (sofia/internal/hassan at a.b.c.d) State Change CS_NEW -> CS_INIT
2010-08-04 13:06:48.856895 [DEBUG] switch_core_session.c:1039 Send signal sofia/internal/hassan at a.b.c.d [BREAK]
2010-08-04 13:06:48.856895 [DEBUG] switch_core_state_machine.c:314 (sofia/internal/hassan at a.b.c.d) Running State Change CS_INIT
2010-08-04 13:06:48.856895 [DEBUG] switch_core_state_machine.c:338 (sofia/internal/hassan at a.b.c.d) State INIT
2010-08-04 13:06:48.856895 [DEBUG] mod_sofia.c:83 sofia/internal/hassan at a.b.c.d SOFIA INIT
2010-08-04 13:06:48.856895 [DEBUG] mod_sofia.c:119 (sofia/internal/hassan at a.b.c.d) State Change CS_INIT -> CS_ROUTING
2010-08-04 13:06:48.856895 [DEBUG] switch_core_session.c:1039 Send signal sofia/internal/hassan at a.b.c.d [BREAK]
2010-08-04 13:06:48.856895 [DEBUG] switch_core_state_machine.c:338 (sofia/internal/hassan at a.b.c.d) State INIT going to sleep
2010-08-04 13:06:48.856895 [DEBUG] switch_core_state_machine.c:314 (sofia/internal/hassan at a.b.c.d) Running State Change CS_ROUTING
2010-08-04 13:06:48.856895 [DEBUG] switch_channel.c:1512 (sofia/internal/hassan at a.b.c.d) Callstate Change DOWN -> RINGING
2010-08-04 13:06:48.856895 [DEBUG] switch_core_state_machine.c:341 (sofia/internal/hassan at a.b.c.d) State ROUTING
2010-08-04 13:06:48.856895 [DEBUG] mod_sofia.c:142 sofia/internal/hassan at a.b.c.d SOFIA ROUTING
2010-08-04 13:06:48.856895 [DEBUG] switch_core_state_machine.c:77 sofia/internal/hassan at a.b.c.d Standard ROUTING
2010-08-04 13:06:48.856895 [INFO] mod_dialplan_xml.c:331 Processing hassan->0111234567890 in context sky189
Dialplan: sofia/internal/hassan at a.b.c.d parsing [sky189->dial_sky189] continue=false
Dialplan: sofia/internal/hassan at a.b.c.d Regex (PASS) [dial_sky189] destination_number(0111234567890) =~ /^011(\d+)$/ break=on-false
Dialplan: sofia/internal/hassan at a.b.c.d Action set(effective_caller_id_number=${outbound_caller_id_number})
Dialplan: sofia/internal/hassan at a.b.c.d Action set(effective_caller_id_name=${outbound_caller_id_name})
Dialplan: sofia/internal/hassan at a.b.c.d Action bridge(sofia/external/1234567890 at sky189)
2010-08-04 13:06:48.858888 [DEBUG] switch_core_state_machine.c:119 (sofia/internal/hassan at a.b.c.d) State Change CS_ROUTING -> CS_EXECUTE
2010-08-04 13:06:48.858888 [DEBUG] switch_core_session.c:1039 Send signal sofia/internal/hassan at a.b.c.d [BREAK]
2010-08-04 13:06:48.858888 [DEBUG] switch_core_state_machine.c:341 (sofia/internal/hassan at a.b.c.d) State ROUTING going to sleep
2010-08-04 13:06:48.858888 [DEBUG] switch_core_state_machine.c:314 (sofia/internal/hassan at a.b.c.d) Running State Change CS_EXECUTE
2010-08-04 13:06:48.858888 [DEBUG] switch_core_state_machine.c:348 (sofia/internal/hassan at a.b.c.d) State EXECUTE
2010-08-04 13:06:48.858888 [DEBUG] mod_sofia.c:235 sofia/internal/hassan at a.b.c.d SOFIA EXECUTE
2010-08-04 13:06:48.858888 [DEBUG] switch_core_state_machine.c:157 sofia/internal/hassan at a.b.c.d Standard EXECUTE
EXECUTE sofia/internal/hassan at a.b.c.d set(effective_caller_id_number=)
2010-08-04 13:06:48.858888 [DEBUG] mod_dptools.c:854 sofia/internal/hassan at a.b.c.d SET [effective_caller_id_number]=[UNDEF]
EXECUTE sofia/internal/hassan at a.b.c.d set(effective_caller_id_name=)
2010-08-04 13:06:48.858888 [DEBUG] mod_dptools.c:854 sofia/internal/hassan at a.b.c.d SET [effective_caller_id_name]=[UNDEF]
EXECUTE sofia/internal/hassan at a.b.c.d bridge(sofia/external/1234567890 at sky189)
2010-08-04 13:06:48.858888 [NOTICE] switch_channel.c:779 New Channel sofia/external/1234567890 at sky189 [cfbd2d4f-87fc-4c59-b320-2290a5a076b3]
2010-08-04 13:06:48.858888 [DEBUG] mod_sofia.c:3892 (sofia/external/1234567890 at sky189) State Change CS_NEW -> CS_INIT
2010-08-04 13:06:48.858888 [DEBUG] switch_core_session.c:1039 Send signal sofia/external/1234567890 at sky189 [BREAK]
2010-08-04 13:06:48.858888 [DEBUG] switch_core_state_machine.c:314 (sofia/external/1234567890 at sky189) Running State Change CS_INIT
2010-08-04 13:06:48.858888 [DEBUG] switch_core_state_machine.c:338 (sofia/external/1234567890 at sky189) State INIT
2010-08-04 13:06:48.858888 [DEBUG] mod_sofia.c:83 sofia/external/1234567890 at sky189 SOFIA INIT
2010-08-04 13:06:48.858888 [DEBUG] mod_sofia.c:119 (sofia/external/1234567890 at sky189) State Change CS_INIT -> CS_ROUTING
2010-08-04 13:06:48.858888 [DEBUG] switch_core_session.c:1039 Send signal sofia/external/1234567890 at sky189 [BREAK]
2010-08-04 13:06:48.858888 [DEBUG] switch_core_state_machine.c:338 (sofia/external/1234567890 at sky189) State INIT going to sleep
2010-08-04 13:06:48.858888 [DEBUG] switch_core_state_machine.c:314 (sofia/external/1234567890 at sky189) Running State Change CS_ROUTING
2010-08-04 13:06:48.858888 [DEBUG] switch_channel.c:1512 (sofia/external/1234567890 at sky189) Callstate Change DOWN -> RINGING
2010-08-04 13:06:48.858888 [DEBUG] switch_core_state_machine.c:341 (sofia/external/1234567890 at sky189) State ROUTING
2010-08-04 13:06:48.858888 [DEBUG] mod_sofia.c:142 sofia/external/1234567890 at sky189 SOFIA ROUTING
2010-08-04 13:06:48.858888 [DEBUG] switch_ivr_originate.c:66 (sofia/external/1234567890 at sky189) State Change CS_ROUTING -> CS_CONSUME_MEDIA
2010-08-04 13:06:48.858888 [DEBUG] switch_core_session.c:1039 Send signal sofia/external/1234567890 at sky189 [BREAK]
2010-08-04 13:06:48.858888 [DEBUG] switch_core_state_machine.c:341 (sofia/external/1234567890 at sky189) State ROUTING going to sleep
2010-08-04 13:06:48.858888 [DEBUG] switch_core_state_machine.c:314 (sofia/external/1234567890 at sky189) Running State Change CS_CONSUME_MEDIA
2010-08-04 13:06:48.858888 [DEBUG] switch_core_state_machine.c:360 (sofia/external/1234567890 at sky189) State CONSUME_MEDIA
2010-08-04 13:06:48.858888 [DEBUG] switch_core_state_machine.c:360 (sofia/external/1234567890 at sky189) State CONSUME_MEDIA going to sleep
2010-08-04 13:06:48.858888 [DEBUG] sofia.c:4318 Channel sofia/external/1234567890 at sky189 entering state [calling][0]
2010-08-04 13:06:48.861065 [DEBUG] sofia.c:4318 Channel sofia/external/1234567890 at sky189 entering state [terminated][503]
2010-08-04 13:06:48.861065 [DEBUG] switch_channel.c:2309 (sofia/external/1234567890 at sky189) Callstate Change RINGING -> HANGUP
2010-08-04 13:06:48.861065 [NOTICE] sofia.c:4932 Hangup sofia/external/1234567890 at sky189 [CS_CONSUME_MEDIA] [NORMAL_TEMPORARY_FAILURE]
2010-08-04 13:06:48.861065 [DEBUG] switch_channel.c:2325 Send signal sofia/external/1234567890 at sky189 [KILL]
2010-08-04 13:06:48.861065 [DEBUG] switch_core_session.c:1039 Send signal sofia/external/1234567890 at sky189 [BREAK]
2010-08-04 13:06:48.861065 [DEBUG] switch_core_state_machine.c:314 (sofia/external/1234567890 at sky189) Running State Change CS_HANGUP
2010-08-04 13:06:48.861065 [DEBUG] switch_core_state_machine.c:535 (sofia/external/1234567890 at sky189) State HANGUP
2010-08-04 13:06:48.861065 [DEBUG] mod_sofia.c:447 sofia/external/1234567890 at sky189 Overriding SIP cause 503 with 503 from the other leg
2010-08-04 13:06:48.861065 [DEBUG] mod_sofia.c:453 Channel sofia/external/1234567890 at sky189 hanging up, cause: NORMAL_TEMPORARY_FAILURE
2010-08-04 13:06:48.861065 [DEBUG] switch_core_state_machine.c:46 sofia/external/1234567890 at sky189 Standard HANGUP, cause: NORMAL_TEMPORARY_FAILURE
2010-08-04 13:06:48.861065 [DEBUG] switch_core_state_machine.c:535 (sofia/external/1234567890 at sky189) State HANGUP going to sleep
2010-08-04 13:06:48.861065 [DEBUG] switch_core_state_machine.c:333 (sofia/external/1234567890 at sky189) State Change CS_HANGUP -> CS_REPORTING
2010-08-04 13:06:48.861065 [DEBUG] switch_core_session.c:1039 Send signal sofia/external/1234567890 at sky189 [BREAK]
2010-08-04 13:06:48.861065 [DEBUG] switch_core_state_machine.c:314 (sofia/external/1234567890 at sky189) Running State Change CS_REPORTING
2010-08-04 13:06:48.861065 [DEBUG] switch_core_state_machine.c:595 (sofia/external/1234567890 at sky189) State REPORTING
2010-08-04 13:06:48.861065 [DEBUG] switch_core_state_machine.c:53 sofia/external/1234567890 at sky189 Standard REPORTING, cause: NORMAL_TEMPORARY_FAILURE
2010-08-04 13:06:48.861065 [DEBUG] switch_core_state_machine.c:595 (sofia/external/1234567890 at sky189) State REPORTING going to sleep
2010-08-04 13:06:48.861065 [DEBUG] switch_core_state_machine.c:327 (sofia/external/1234567890 at sky189) State Change CS_REPORTING -> CS_DESTROY
2010-08-04 13:06:48.861065 [DEBUG] switch_core_session.c:1039 Send signal sofia/external/1234567890 at sky189 [BREAK]
2010-08-04 13:06:48.861065 [DEBUG] switch_ivr_originate.c:3431 Originate Resulted in Error Cause: 41 [NORMAL_TEMPORARY_FAILURE]
2010-08-04 13:06:48.861065 [INFO] mod_dptools.c:2393 Originate Failed.  Cause: NORMAL_TEMPORARY_FAILURE
2010-08-04 13:06:48.861065 [DEBUG] switch_channel.c:2309 (sofia/internal/hassan at a.b.c.d) Callstate Change RINGING -> HANGUP
2010-08-04 13:06:48.861065 [NOTICE] mod_dptools.c:2456 Hangup sofia/internal/hassan at a.b.c.d [CS_EXECUTE] [NORMAL_TEMPORARY_FAILURE]
2010-08-04 13:06:48.861065 [DEBUG] switch_channel.c:2325 Send signal sofia/internal/hassan at a.b.c.d [KILL]
2010-08-04 13:06:48.861065 [DEBUG] switch_core_session.c:1039 Send signal sofia/internal/hassan at a.b.c.d [BREAK]
2010-08-04 13:06:48.861065 [DEBUG] switch_core_session.c:1905 sofia/internal/hassan at a.b.c.d skip receive message [APPLICATION_EXEC_COMPLETE] (channel is hungup already)
2010-08-04 13:06:48.861065 [DEBUG] switch_core_state_machine.c:348 (sofia/internal/hassan at a.b.c.d) State EXECUTE going to sleep
2010-08-04 13:06:48.861065 [DEBUG] switch_core_state_machine.c:314 (sofia/internal/hassan at a.b.c.d) Running State Change CS_HANGUP
2010-08-04 13:06:48.861065 [DEBUG] switch_core_state_machine.c:535 (sofia/internal/hassan at a.b.c.d) State HANGUP
2010-08-04 13:06:48.861065 [DEBUG] mod_sofia.c:447 sofia/internal/hassan at a.b.c.d Overriding SIP cause 503 with 503 from the other leg
2010-08-04 13:06:48.861065 [DEBUG] mod_sofia.c:453 Channel sofia/internal/hassan at a.b.c.d hanging up, cause: NORMAL_TEMPORARY_FAILURE
2010-08-04 13:06:48.861065 [DEBUG] switch_core_session.c:1202 Session 11 (sofia/external/1234567890 at sky189) Locked, Waiting on external entities
2010-08-04 13:06:48.861065 [NOTICE] switch_core_session.c:1220 Session 11 (sofia/external/1234567890 at sky189) Ended
2010-08-04 13:06:48.862912 [NOTICE] switch_core_session.c:1222 Close Channel sofia/external/1234567890 at sky189 [CS_DESTROY]
2010-08-04 13:06:48.862912 [DEBUG] switch_core_state_machine.c:427 (sofia/external/1234567890 at sky189) Callstate Change HANGUP -> DOWN
2010-08-04 13:06:48.862912 [DEBUG] switch_core_state_machine.c:430 (sofia/external/1234567890 at sky189) Running State Change CS_DESTROY
2010-08-04 13:06:48.862912 [DEBUG] switch_core_state_machine.c:440 (sofia/external/1234567890 at sky189) State DESTROY
2010-08-04 13:06:48.862912 [DEBUG] mod_sofia.c:358 sofia/external/1234567890 at sky189 SOFIA DESTROY
2010-08-04 13:06:48.862912 [DEBUG] switch_core_state_machine.c:60 sofia/external/1234567890 at sky189 Standard DESTROY
2010-08-04 13:06:48.862912 [DEBUG] switch_core_state_machine.c:440 (sofia/external/1234567890 at sky189) State DESTROY going to sleep
2010-08-04 13:06:48.864893 [DEBUG] mod_sofia.c:515 Responding to INVITE with: 503
2010-08-04 13:06:48.864893 [DEBUG] switch_core_state_machine.c:46 sofia/internal/hassan at a.b.c.d Standard HANGUP, cause: NORMAL_TEMPORARY_FAILURE
2010-08-04 13:06:48.864893 [DEBUG] switch_core_state_machine.c:535 (sofia/internal/hassan at a.b.c.d) State HANGUP going to sleep
2010-08-04 13:06:48.864893 [DEBUG] switch_core_state_machine.c:333 (sofia/internal/hassan at a.b.c.d) State Change CS_HANGUP -> CS_REPORTING
2010-08-04 13:06:48.864893 [DEBUG] switch_core_session.c:1039 Send signal sofia/internal/hassan at a.b.c.d [BREAK]
2010-08-04 13:06:48.864893 [DEBUG] switch_core_state_machine.c:314 (sofia/internal/hassan at a.b.c.d) Running State Change CS_REPORTING
2010-08-04 13:06:48.864893 [DEBUG] switch_core_state_machine.c:595 (sofia/internal/hassan at a.b.c.d) State REPORTING
2010-08-04 13:06:48.864893 [DEBUG] switch_core_state_machine.c:53 sofia/internal/hassan at a.b.c.d Standard REPORTING, cause: NORMAL_TEMPORARY_FAILURE
2010-08-04 13:06:48.864893 [DEBUG] switch_core_state_machine.c:595 (sofia/internal/hassan at a.b.c.d) State REPORTING going to sleep
2010-08-04 13:06:48.864893 [DEBUG] switch_core_state_machine.c:327 (sofia/internal/hassan at a.b.c.d) State Change CS_REPORTING -> CS_DESTROY
2010-08-04 13:06:48.864893 [DEBUG] switch_core_session.c:1039 Send signal sofia/internal/hassan at a.b.c.d [BREAK]
2010-08-04 13:06:48.864893 [DEBUG] switch_core_session.c:1202 Session 10 (sofia/internal/hassan at a.b.c.d) Locked, Waiting on external entities
2010-08-04 13:06:48.864893 [NOTICE] switch_core_session.c:1220 Session 10 (sofia/internal/hassan at a.b.c.d) Ended
2010-08-04 13:06:48.864893 [NOTICE] switch_core_session.c:1222 Close Channel sofia/internal/hassan at a.b.c.d [CS_DESTROY]
2010-08-04 13:06:48.864893 [DEBUG] switch_core_state_machine.c:427 (sofia/internal/hassan at a.b.c.d) Callstate Change HANGUP -> DOWN
2010-08-04 13:06:48.864893 [DEBUG] switch_core_state_machine.c:430 (sofia/internal/hassan at a.b.c.d) Running State Change CS_DESTROY
2010-08-04 13:06:48.866921 [DEBUG] switch_core_state_machine.c:440 (sofia/internal/hassan at a.b.c.d) State DESTROY
2010-08-04 13:06:48.866921 [DEBUG] mod_sofia.c:358 sofia/internal/hassan at a.b.c.d SOFIA DESTROY
2010-08-04 13:06:48.866921 [DEBUG] switch_core_state_machine.c:60 sofia/internal/hassan at a.b.c.d Standard DESTROY
2010-08-04 13:06:48.866921 [DEBUG] switch_core_state_machine.c:440 (sofia/internal/hassan at a.b.c.d) State DESTROY going to sleep

_______________________________________________
FreeSWITCH-users mailing list
FreeSWITCH-users at lists.freeswitch.org<mailto:FreeSWITCH-users at lists.freeswitch.org>
http://lists.freeswitch.org/mailman/listinfo/freeswitch-users
UNSUBSCRIBE:http://lists.freeswitch.org/mailman/options/freeswitch-users
http://www.freeswitch.org

_______________________________________________
FreeSWITCH-users mailing list
FreeSWITCH-users at lists.freeswitch.org<mailto:FreeSWITCH-users at 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:4c5a81c132932113517252!
-------------- next part --------------
An HTML attachment was scrubbed...
URL: http://lists.freeswitch.org/pipermail/freeswitch-users/attachments/20100805/f1576390/attachment-0001.html 