[Freeswitch-users] Help on reading the log better

Thu Aug 5 01:46:14 PDT 2010

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> 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.dbridge(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
> http://lists.freeswitch.org/mailman/listinfo/freeswitch-users
> UNSUBSCRIBE:http://lists.freeswitch.org/mailman/options/freeswitch-users
> http://www.freeswitch.org
>
>
-------------- next part --------------
An HTML attachment was scrubbed...
URL: http://lists.freeswitch.org/pipermail/freeswitch-users/attachments/20100805/ee024eee/attachment-0001.html 