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@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@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@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@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@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@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@a.b.c.d [BREAK] 2010-08-04 13:06:48.856895 [DEBUG] switch_core_state_machine.c:314 (sofia/internal/hassan@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@a.b.c.d) State INIT 2010-08-04 13:06:48.856895 [DEBUG] mod_sofia.c:83 sofia/internal/hassan@a.b.c.d SOFIA INIT 2010-08-04 13:06:48.856895 [DEBUG] mod_sofia.c:119 (sofia/internal/hassan@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@a.b.c.d [BREAK] 2010-08-04 13:06:48.856895 [DEBUG] switch_core_state_machine.c:338 (sofia/internal/hassan@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@a.b.c.d) Running State Change CS_ROUTING 2010-08-04 13:06:48.856895 [DEBUG] switch_channel.c:1512 (sofia/internal/hassan@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@a.b.c.d) State ROUTING 2010-08-04 13:06:48.856895 [DEBUG] mod_sofia.c:142 sofia/internal/hassan@a.b.c.d SOFIA ROUTING 2010-08-04 13:06:48.856895 [DEBUG] switch_core_state_machine.c:77 sofia/internal/hassan@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@a.b.c.d parsing [sky189->dial_sky189] continue=false Dialplan: sofia/internal/hassan@a.b.c.d Regex (PASS) [dial_sky189] destination_number(0111234567890) =~ /^011(\d+)$/ break=on-false Dialplan: sofia/internal/hassan@a.b.c.d Action set(effective_caller_id_number=${outbound_caller_id_number}) Dialplan: sofia/internal/hassan@a.b.c.d Action set(effective_caller_id_name=${outbound_caller_id_name}) Dialplan: sofia/internal/hassan@a.b.c.d Action bridge(sofia/external/1234567890@sky189) 2010-08-04 13:06:48.858888 [DEBUG] switch_core_state_machine.c:119 (sofia/internal/hassan@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@a.b.c.d [BREAK] 2010-08-04 13:06:48.858888 [DEBUG] switch_core_state_machine.c:341 (sofia/internal/hassan@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@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@a.b.c.d) State EXECUTE 2010-08-04 13:06:48.858888 [DEBUG] mod_sofia.c:235 sofia/internal/hassan@a.b.c.d SOFIA EXECUTE 2010-08-04 13:06:48.858888 [DEBUG] switch_core_state_machine.c:157 sofia/internal/hassan@a.b.c.d Standard EXECUTE EXECUTE sofia/internal/hassan@a.b.c.d set(effective_caller_id_number=) 2010-08-04 13:06:48.858888 [DEBUG] mod_dptools.c:854 sofia/internal/hassan@a.b.c.d SET [effective_caller_id_number]=[UNDEF] EXECUTE sofia/internal/hassan@a.b.c.d set(effective_caller_id_name=) 2010-08-04 13:06:48.858888 [DEBUG] mod_dptools.c:854 sofia/internal/hassan@a.b.c.d SET [effective_caller_id_name]=[UNDEF] EXECUTE sofia/internal/hassan@a.b.c.dbridge(sofia/external/1234567890@sky189 ) 2010-08-04 13:06:48.858888 [NOTICE] switch_channel.c:779 New Channel sofia/external/1234567890@sky189 [cfbd2d4f-87fc-4c59-b320-2290a5a076b3] 2010-08-04 13:06:48.858888 [DEBUG] mod_sofia.c:3892 (sofia/external/1234567890@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@sky189 [BREAK] 2010-08-04 13:06:48.858888 [DEBUG] switch_core_state_machine.c:314 (sofia/external/1234567890@sky189) Running State Change CS_INIT 2010-08-04 13:06:48.858888 [DEBUG] switch_core_state_machine.c:338 (sofia/external/1234567890@sky189) State INIT 2010-08-04 13:06:48.858888 [DEBUG] mod_sofia.c:83 sofia/external/1234567890@sky189 SOFIA INIT 2010-08-04 13:06:48.858888 [DEBUG] mod_sofia.c:119 (sofia/external/1234567890@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@sky189 [BREAK] 2010-08-04 13:06:48.858888 [DEBUG] switch_core_state_machine.c:338 (sofia/external/1234567890@sky189) State INIT going to sleep 2010-08-04 13:06:48.858888 [DEBUG] switch_core_state_machine.c:314 (sofia/external/1234567890@sky189) Running State Change CS_ROUTING 2010-08-04 13:06:48.858888 [DEBUG] switch_channel.c:1512 (sofia/external/1234567890@sky189) Callstate Change DOWN -> RINGING 2010-08-04 13:06:48.858888 [DEBUG] switch_core_state_machine.c:341 (sofia/external/1234567890@sky189) State ROUTING 2010-08-04 13:06:48.858888 [DEBUG] mod_sofia.c:142 sofia/external/1234567890@sky189 SOFIA ROUTING 2010-08-04 13:06:48.858888 [DEBUG] switch_ivr_originate.c:66 (sofia/external/1234567890@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@sky189 [BREAK] 2010-08-04 13:06:48.858888 [DEBUG] switch_core_state_machine.c:341 (sofia/external/1234567890@sky189) State ROUTING going to sleep 2010-08-04 13:06:48.858888 [DEBUG] switch_core_state_machine.c:314 (sofia/external/1234567890@sky189) Running State Change CS_CONSUME_MEDIA 2010-08-04 13:06:48.858888 [DEBUG] switch_core_state_machine.c:360 (sofia/external/1234567890@sky189) State CONSUME_MEDIA 2010-08-04 13:06:48.858888 [DEBUG] switch_core_state_machine.c:360 (sofia/external/1234567890@sky189) State CONSUME_MEDIA going to sleep 2010-08-04 13:06:48.858888 [DEBUG] sofia.c:4318 Channel sofia/external/1234567890@sky189 entering state [calling][0] 2010-08-04 13:06:48.861065 [DEBUG] sofia.c:4318 Channel sofia/external/1234567890@sky189 entering state [terminated][503] 2010-08-04 13:06:48.861065 [DEBUG] switch_channel.c:2309 (sofia/external/1234567890@sky189) Callstate Change RINGING -> HANGUP 2010-08-04 13:06:48.861065 [NOTICE] sofia.c:4932 Hangup sofia/external/1234567890@sky189 [CS_CONSUME_MEDIA] [NORMAL_TEMPORARY_FAILURE] 2010-08-04 13:06:48.861065 [DEBUG] switch_channel.c:2325 Send signal sofia/external/1234567890@sky189 [KILL] 2010-08-04 13:06:48.861065 [DEBUG] switch_core_session.c:1039 Send signal sofia/external/1234567890@sky189 [BREAK] 2010-08-04 13:06:48.861065 [DEBUG] switch_core_state_machine.c:314 (sofia/external/1234567890@sky189) Running State Change CS_HANGUP 2010-08-04 13:06:48.861065 [DEBUG] switch_core_state_machine.c:535 (sofia/external/1234567890@sky189) State HANGUP 2010-08-04 13:06:48.861065 [DEBUG] mod_sofia.c:447 sofia/external/1234567890@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@sky189 hanging up, cause: NORMAL_TEMPORARY_FAILURE 2010-08-04 13:06:48.861065 [DEBUG] switch_core_state_machine.c:46 sofia/external/1234567890@sky189 Standard HANGUP, cause: NORMAL_TEMPORARY_FAILURE 2010-08-04 13:06:48.861065 [DEBUG] switch_core_state_machine.c:535 (sofia/external/1234567890@sky189) State HANGUP going to sleep 2010-08-04 13:06:48.861065 [DEBUG] switch_core_state_machine.c:333 (sofia/external/1234567890@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@sky189 [BREAK] 2010-08-04 13:06:48.861065 [DEBUG] switch_core_state_machine.c:314 (sofia/external/1234567890@sky189) Running State Change CS_REPORTING 2010-08-04 13:06:48.861065 [DEBUG] switch_core_state_machine.c:595 (sofia/external/1234567890@sky189) State REPORTING 2010-08-04 13:06:48.861065 [DEBUG] switch_core_state_machine.c:53 sofia/external/1234567890@sky189 Standard REPORTING, cause: NORMAL_TEMPORARY_FAILURE 2010-08-04 13:06:48.861065 [DEBUG] switch_core_state_machine.c:595 (sofia/external/1234567890@sky189) State REPORTING going to sleep 2010-08-04 13:06:48.861065 [DEBUG] switch_core_state_machine.c:327 (sofia/external/1234567890@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@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@a.b.c.d) Callstate Change RINGING -> HANGUP 2010-08-04 13:06:48.861065 [NOTICE] mod_dptools.c:2456 Hangup sofia/internal/hassan@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@a.b.c.d [KILL] 2010-08-04 13:06:48.861065 [DEBUG] switch_core_session.c:1039 Send signal sofia/internal/hassan@a.b.c.d [BREAK] 2010-08-04 13:06:48.861065 [DEBUG] switch_core_session.c:1905 sofia/internal/hassan@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@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@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@a.b.c.d) State HANGUP 2010-08-04 13:06:48.861065 [DEBUG] mod_sofia.c:447 sofia/internal/hassan@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@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@sky189) Locked, Waiting on external entities 2010-08-04 13:06:48.861065 [NOTICE] switch_core_session.c:1220 Session 11 (sofia/external/1234567890@sky189) Ended 2010-08-04 13:06:48.862912 [NOTICE] switch_core_session.c:1222 Close Channel sofia/external/1234567890@sky189 [CS_DESTROY] 2010-08-04 13:06:48.862912 [DEBUG] switch_core_state_machine.c:427 (sofia/external/1234567890@sky189) Callstate Change HANGUP -> DOWN 2010-08-04 13:06:48.862912 [DEBUG] switch_core_state_machine.c:430 (sofia/external/1234567890@sky189) Running State Change CS_DESTROY 2010-08-04 13:06:48.862912 [DEBUG] switch_core_state_machine.c:440 (sofia/external/1234567890@sky189) State DESTROY 2010-08-04 13:06:48.862912 [DEBUG] mod_sofia.c:358 sofia/external/1234567890@sky189 SOFIA DESTROY 2010-08-04 13:06:48.862912 [DEBUG] switch_core_state_machine.c:60 sofia/external/1234567890@sky189 Standard DESTROY 2010-08-04 13:06:48.862912 [DEBUG] switch_core_state_machine.c:440 (sofia/external/1234567890@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@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@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@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@a.b.c.d [BREAK] 2010-08-04 13:06:48.864893 [DEBUG] switch_core_state_machine.c:314 (sofia/internal/hassan@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@a.b.c.d) State REPORTING 2010-08-04 13:06:48.864893 [DEBUG] switch_core_state_machine.c:53 sofia/internal/hassan@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@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@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@a.b.c.d [BREAK] 2010-08-04 13:06:48.864893 [DEBUG] switch_core_session.c:1202 Session 10 (sofia/internal/hassan@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@a.b.c.d) Ended 2010-08-04 13:06:48.864893 [NOTICE] switch_core_session.c:1222 Close Channel sofia/internal/hassan@a.b.c.d [CS_DESTROY] 2010-08-04 13:06:48.864893 [DEBUG] switch_core_state_machine.c:427 (sofia/internal/hassan@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@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@a.b.c.d) State DESTROY 2010-08-04 13:06:48.866921 [DEBUG] mod_sofia.c:358 sofia/internal/hassan@a.b.c.d SOFIA DESTROY 2010-08-04 13:06:48.866921 [DEBUG] switch_core_state_machine.c:60 sofia/internal/hassan@a.b.c.d Standard DESTROY 2010-08-04 13:06:48.866921 [DEBUG] switch_core_state_machine.c:440 (sofia/internal/hassan@a.b.c.d) State DESTROY going to sleep
The call is getting 503 Service Unavailable. 2010-08-04 13:06:48.858888 [DEBUG] sofia.c:4318 Channel sofia/external/1234567890@sky189 entering state [calling][0] 2010-08-04 13:06:48.861065 [DEBUG] sofia.c:4318 Channel sofia/external/1234567890@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@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@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@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@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@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@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@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@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@a.b.c.d [BREAK] 2010-08-04 13:06:48.856895 [DEBUG] switch_core_state_machine.c:314 (sofia/internal/hassan@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@a.b.c.d) State INIT 2010-08-04 13:06:48.856895 [DEBUG] mod_sofia.c:83 sofia/internal/hassan@a.b.c.d SOFIA INIT 2010-08-04 13:06:48.856895 [DEBUG] mod_sofia.c:119 (sofia/internal/hassan@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@a.b.c.d [BREAK] 2010-08-04 13:06:48.856895 [DEBUG] switch_core_state_machine.c:338 (sofia/internal/hassan@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@a.b.c.d) Running State Change CS_ROUTING 2010-08-04 13:06:48.856895 [DEBUG] switch_channel.c:1512 (sofia/internal/hassan@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@a.b.c.d) State ROUTING 2010-08-04 13:06:48.856895 [DEBUG] mod_sofia.c:142 sofia/internal/hassan@a.b.c.d SOFIA ROUTING 2010-08-04 13:06:48.856895 [DEBUG] switch_core_state_machine.c:77 sofia/internal/hassan@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@a.b.c.d parsing [sky189->dial_sky189] continue=false Dialplan: sofia/internal/hassan@a.b.c.d Regex (PASS) [dial_sky189] destination_number(0111234567890) =~ /^011(\d+)$/ break=on-false Dialplan: sofia/internal/hassan@a.b.c.d Action set(effective_caller_id_number=${outbound_caller_id_number}) Dialplan: sofia/internal/hassan@a.b.c.d Action set(effective_caller_id_name=${outbound_caller_id_name}) Dialplan: sofia/internal/hassan@a.b.c.d Action bridge(sofia/external/1234567890@sky189) 2010-08-04 13:06:48.858888 [DEBUG] switch_core_state_machine.c:119 (sofia/internal/hassan@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@a.b.c.d [BREAK] 2010-08-04 13:06:48.858888 [DEBUG] switch_core_state_machine.c:341 (sofia/internal/hassan@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@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@a.b.c.d) State EXECUTE 2010-08-04 13:06:48.858888 [DEBUG] mod_sofia.c:235 sofia/internal/hassan@a.b.c.d SOFIA EXECUTE 2010-08-04 13:06:48.858888 [DEBUG] switch_core_state_machine.c:157 sofia/internal/hassan@a.b.c.d Standard EXECUTE EXECUTE sofia/internal/hassan@a.b.c.d set(effective_caller_id_number=) 2010-08-04 13:06:48.858888 [DEBUG] mod_dptools.c:854 sofia/internal/hassan@a.b.c.d SET [effective_caller_id_number]=[UNDEF] EXECUTE sofia/internal/hassan@a.b.c.d set(effective_caller_id_name=) 2010-08-04 13:06:48.858888 [DEBUG] mod_dptools.c:854 sofia/internal/hassan@a.b.c.d SET [effective_caller_id_name]=[UNDEF] EXECUTE sofia/internal/hassan@a.b.c.dbridge(sofia/external/1234567890@sky189 ) 2010-08-04 13:06:48.858888 [NOTICE] switch_channel.c:779 New Channel sofia/external/1234567890@sky189 [cfbd2d4f-87fc-4c59-b320-2290a5a076b3] 2010-08-04 13:06:48.858888 [DEBUG] mod_sofia.c:3892 (sofia/external/1234567890@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@sky189 [BREAK] 2010-08-04 13:06:48.858888 [DEBUG] switch_core_state_machine.c:314 (sofia/external/1234567890@sky189) Running State Change CS_INIT 2010-08-04 13:06:48.858888 [DEBUG] switch_core_state_machine.c:338 (sofia/external/1234567890@sky189) State INIT 2010-08-04 13:06:48.858888 [DEBUG] mod_sofia.c:83 sofia/external/1234567890@sky189 SOFIA INIT 2010-08-04 13:06:48.858888 [DEBUG] mod_sofia.c:119 (sofia/external/1234567890@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@sky189 [BREAK] 2010-08-04 13:06:48.858888 [DEBUG] switch_core_state_machine.c:338 (sofia/external/1234567890@sky189) State INIT going to sleep 2010-08-04 13:06:48.858888 [DEBUG] switch_core_state_machine.c:314 (sofia/external/1234567890@sky189) Running State Change CS_ROUTING 2010-08-04 13:06:48.858888 [DEBUG] switch_channel.c:1512 (sofia/external/1234567890@sky189) Callstate Change DOWN -> RINGING 2010-08-04 13:06:48.858888 [DEBUG] switch_core_state_machine.c:341 (sofia/external/1234567890@sky189) State ROUTING 2010-08-04 13:06:48.858888 [DEBUG] mod_sofia.c:142 sofia/external/1234567890@sky189 SOFIA ROUTING 2010-08-04 13:06:48.858888 [DEBUG] switch_ivr_originate.c:66 (sofia/external/1234567890@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@sky189 [BREAK] 2010-08-04 13:06:48.858888 [DEBUG] switch_core_state_machine.c:341 (sofia/external/1234567890@sky189) State ROUTING going to sleep 2010-08-04 13:06:48.858888 [DEBUG] switch_core_state_machine.c:314 (sofia/external/1234567890@sky189) Running State Change CS_CONSUME_MEDIA 2010-08-04 13:06:48.858888 [DEBUG] switch_core_state_machine.c:360 (sofia/external/1234567890@sky189) State CONSUME_MEDIA 2010-08-04 13:06:48.858888 [DEBUG] switch_core_state_machine.c:360 (sofia/external/1234567890@sky189) State CONSUME_MEDIA going to sleep 2010-08-04 13:06:48.858888 [DEBUG] sofia.c:4318 Channel sofia/external/1234567890@sky189 entering state [calling][0] 2010-08-04 13:06:48.861065 [DEBUG] sofia.c:4318 Channel sofia/external/1234567890@sky189 entering state [terminated][503] 2010-08-04 13:06:48.861065 [DEBUG] switch_channel.c:2309 (sofia/external/1234567890@sky189) Callstate Change RINGING -> HANGUP 2010-08-04 13:06:48.861065 [NOTICE] sofia.c:4932 Hangup sofia/external/1234567890@sky189 [CS_CONSUME_MEDIA] [NORMAL_TEMPORARY_FAILURE] 2010-08-04 13:06:48.861065 [DEBUG] switch_channel.c:2325 Send signal sofia/external/1234567890@sky189 [KILL] 2010-08-04 13:06:48.861065 [DEBUG] switch_core_session.c:1039 Send signal sofia/external/1234567890@sky189 [BREAK] 2010-08-04 13:06:48.861065 [DEBUG] switch_core_state_machine.c:314 (sofia/external/1234567890@sky189) Running State Change CS_HANGUP 2010-08-04 13:06:48.861065 [DEBUG] switch_core_state_machine.c:535 (sofia/external/1234567890@sky189) State HANGUP 2010-08-04 13:06:48.861065 [DEBUG] mod_sofia.c:447 sofia/external/1234567890@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@sky189 hanging up, cause: NORMAL_TEMPORARY_FAILURE 2010-08-04 13:06:48.861065 [DEBUG] switch_core_state_machine.c:46 sofia/external/1234567890@sky189 Standard HANGUP, cause: NORMAL_TEMPORARY_FAILURE 2010-08-04 13:06:48.861065 [DEBUG] switch_core_state_machine.c:535 (sofia/external/1234567890@sky189) State HANGUP going to sleep 2010-08-04 13:06:48.861065 [DEBUG] switch_core_state_machine.c:333 (sofia/external/1234567890@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@sky189 [BREAK] 2010-08-04 13:06:48.861065 [DEBUG] switch_core_state_machine.c:314 (sofia/external/1234567890@sky189) Running State Change CS_REPORTING 2010-08-04 13:06:48.861065 [DEBUG] switch_core_state_machine.c:595 (sofia/external/1234567890@sky189) State REPORTING 2010-08-04 13:06:48.861065 [DEBUG] switch_core_state_machine.c:53 sofia/external/1234567890@sky189 Standard REPORTING, cause: NORMAL_TEMPORARY_FAILURE 2010-08-04 13:06:48.861065 [DEBUG] switch_core_state_machine.c:595 (sofia/external/1234567890@sky189) State REPORTING going to sleep 2010-08-04 13:06:48.861065 [DEBUG] switch_core_state_machine.c:327 (sofia/external/1234567890@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@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@a.b.c.d) Callstate Change RINGING -> HANGUP 2010-08-04 13:06:48.861065 [NOTICE] mod_dptools.c:2456 Hangup sofia/internal/hassan@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@a.b.c.d [KILL] 2010-08-04 13:06:48.861065 [DEBUG] switch_core_session.c:1039 Send signal sofia/internal/hassan@a.b.c.d [BREAK] 2010-08-04 13:06:48.861065 [DEBUG] switch_core_session.c:1905 sofia/internal/hassan@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@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@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@a.b.c.d) State HANGUP 2010-08-04 13:06:48.861065 [DEBUG] mod_sofia.c:447 sofia/internal/hassan@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@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@sky189) Locked, Waiting on external entities 2010-08-04 13:06:48.861065 [NOTICE] switch_core_session.c:1220 Session 11 (sofia/external/1234567890@sky189) Ended 2010-08-04 13:06:48.862912 [NOTICE] switch_core_session.c:1222 Close Channel sofia/external/1234567890@sky189 [CS_DESTROY] 2010-08-04 13:06:48.862912 [DEBUG] switch_core_state_machine.c:427 (sofia/external/1234567890@sky189) Callstate Change HANGUP -> DOWN 2010-08-04 13:06:48.862912 [DEBUG] switch_core_state_machine.c:430 (sofia/external/1234567890@sky189) Running State Change CS_DESTROY 2010-08-04 13:06:48.862912 [DEBUG] switch_core_state_machine.c:440 (sofia/external/1234567890@sky189) State DESTROY 2010-08-04 13:06:48.862912 [DEBUG] mod_sofia.c:358 sofia/external/1234567890@sky189 SOFIA DESTROY 2010-08-04 13:06:48.862912 [DEBUG] switch_core_state_machine.c:60 sofia/external/1234567890@sky189 Standard DESTROY 2010-08-04 13:06:48.862912 [DEBUG] switch_core_state_machine.c:440 (sofia/external/1234567890@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@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@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@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@a.b.c.d [BREAK] 2010-08-04 13:06:48.864893 [DEBUG] switch_core_state_machine.c:314 (sofia/internal/hassan@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@a.b.c.d) State REPORTING 2010-08-04 13:06:48.864893 [DEBUG] switch_core_state_machine.c:53 sofia/internal/hassan@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@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@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@a.b.c.d [BREAK] 2010-08-04 13:06:48.864893 [DEBUG] switch_core_session.c:1202 Session 10 (sofia/internal/hassan@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@a.b.c.d) Ended 2010-08-04 13:06:48.864893 [NOTICE] switch_core_session.c:1222 Close Channel sofia/internal/hassan@a.b.c.d [CS_DESTROY] 2010-08-04 13:06:48.864893 [DEBUG] switch_core_state_machine.c:427 (sofia/internal/hassan@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@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@a.b.c.d) State DESTROY 2010-08-04 13:06:48.866921 [DEBUG] mod_sofia.c:358 sofia/internal/hassan@a.b.c.d SOFIA DESTROY 2010-08-04 13:06:48.866921 [DEBUG] switch_core_state_machine.c:60 sofia/internal/hassan@a.b.c.d Standard DESTROY 2010-08-04 13:06:48.866921 [DEBUG] switch_core_state_machine.c:440 (sofia/internal/hassan@a.b.c.d) State DESTROY going to sleep
_______________________________________________ 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
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@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@sky189 entering state [calling][0] 2010-08-04 13:06:48.861065 [DEBUG] sofia.c:4318 Channel sofia/external/1234567890@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@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@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@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@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@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@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@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@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@a.b.c.d [BREAK] 2010-08-04 13:06:48.856895 [DEBUG] switch_core_state_machine.c:314 (sofia/internal/hassan@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@a.b.c.d) State INIT 2010-08-04 13:06:48.856895 [DEBUG] mod_sofia.c:83 sofia/internal/hassan@a.b.c.d SOFIA INIT 2010-08-04 13:06:48.856895 [DEBUG] mod_sofia.c:119 (sofia/internal/hassan@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@a.b.c.d [BREAK] 2010-08-04 13:06:48.856895 [DEBUG] switch_core_state_machine.c:338 (sofia/internal/hassan@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@a.b.c.d) Running State Change CS_ROUTING 2010-08-04 13:06:48.856895 [DEBUG] switch_channel.c:1512 (sofia/internal/hassan@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@a.b.c.d) State ROUTING 2010-08-04 13:06:48.856895 [DEBUG] mod_sofia.c:142 sofia/internal/hassan@a.b.c.d SOFIA ROUTING 2010-08-04 13:06:48.856895 [DEBUG] switch_core_state_machine.c:77 sofia/internal/hassan@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@a.b.c.d parsing [sky189->dial_sky189] continue=false Dialplan: sofia/internal/hassan@a.b.c.d Regex (PASS) [dial_sky189] destination_number(0111234567890) =~ /^011(\d+)$/ break=on-false Dialplan: sofia/internal/hassan@a.b.c.d Action set(effective_caller_id_number=${outbound_caller_id_number}) Dialplan: sofia/internal/hassan@a.b.c.d Action set(effective_caller_id_name=${outbound_caller_id_name}) Dialplan: sofia/internal/hassan@a.b.c.d Action bridge(sofia/external/1234567890@sky189) 2010-08-04 13:06:48.858888 [DEBUG] switch_core_state_machine.c:119 (sofia/internal/hassan@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@a.b.c.d [BREAK] 2010-08-04 13:06:48.858888 [DEBUG] switch_core_state_machine.c:341 (sofia/internal/hassan@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@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@a.b.c.d) State EXECUTE 2010-08-04 13:06:48.858888 [DEBUG] mod_sofia.c:235 sofia/internal/hassan@a.b.c.d SOFIA EXECUTE 2010-08-04 13:06:48.858888 [DEBUG] switch_core_state_machine.c:157 sofia/internal/hassan@a.b.c.d Standard EXECUTE EXECUTE sofia/internal/hassan@a.b.c.d set(effective_caller_id_number=) 2010-08-04 13:06:48.858888 [DEBUG] mod_dptools.c:854 sofia/internal/hassan@a.b.c.d SET [effective_caller_id_number]=[UNDEF] EXECUTE sofia/internal/hassan@a.b.c.d set(effective_caller_id_name=) 2010-08-04 13:06:48.858888 [DEBUG] mod_dptools.c:854 sofia/internal/hassan@a.b.c.d SET [effective_caller_id_name]=[UNDEF] EXECUTE sofia/internal/hassan@a.b.c.dbridge(sofia/external/1234567890@sky189 ) 2010-08-04 13:06:48.858888 [NOTICE] switch_channel.c:779 New Channel sofia/external/1234567890@sky189 [cfbd2d4f-87fc-4c59-b320-2290a5a076b3] 2010-08-04 13:06:48.858888 [DEBUG] mod_sofia.c:3892 (sofia/external/1234567890@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@sky189 [BREAK] 2010-08-04 13:06:48.858888 [DEBUG] switch_core_state_machine.c:314 (sofia/external/1234567890@sky189) Running State Change CS_INIT 2010-08-04 13:06:48.858888 [DEBUG] switch_core_state_machine.c:338 (sofia/external/1234567890@sky189) State INIT 2010-08-04 13:06:48.858888 [DEBUG] mod_sofia.c:83 sofia/external/1234567890@sky189 SOFIA INIT 2010-08-04 13:06:48.858888 [DEBUG] mod_sofia.c:119 (sofia/external/1234567890@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@sky189 [BREAK] 2010-08-04 13:06:48.858888 [DEBUG] switch_core_state_machine.c:338 (sofia/external/1234567890@sky189) State INIT going to sleep 2010-08-04 13:06:48.858888 [DEBUG] switch_core_state_machine.c:314 (sofia/external/1234567890@sky189) Running State Change CS_ROUTING 2010-08-04 13:06:48.858888 [DEBUG] switch_channel.c:1512 (sofia/external/1234567890@sky189) Callstate Change DOWN -> RINGING 2010-08-04 13:06:48.858888 [DEBUG] switch_core_state_machine.c:341 (sofia/external/1234567890@sky189) State ROUTING 2010-08-04 13:06:48.858888 [DEBUG] mod_sofia.c:142 sofia/external/1234567890@sky189 SOFIA ROUTING 2010-08-04 13:06:48.858888 [DEBUG] switch_ivr_originate.c:66 (sofia/external/1234567890@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@sky189 [BREAK] 2010-08-04 13:06:48.858888 [DEBUG] switch_core_state_machine.c:341 (sofia/external/1234567890@sky189) State ROUTING going to sleep 2010-08-04 13:06:48.858888 [DEBUG] switch_core_state_machine.c:314 (sofia/external/1234567890@sky189) Running State Change CS_CONSUME_MEDIA 2010-08-04 13:06:48.858888 [DEBUG] switch_core_state_machine.c:360 (sofia/external/1234567890@sky189) State CONSUME_MEDIA 2010-08-04 13:06:48.858888 [DEBUG] switch_core_state_machine.c:360 (sofia/external/1234567890@sky189) State CONSUME_MEDIA going to sleep 2010-08-04 13:06:48.858888 [DEBUG] sofia.c:4318 Channel sofia/external/1234567890@sky189 entering state [calling][0] 2010-08-04 13:06:48.861065 [DEBUG] sofia.c:4318 Channel sofia/external/1234567890@sky189 entering state [terminated][503] 2010-08-04 13:06:48.861065 [DEBUG] switch_channel.c:2309 (sofia/external/1234567890@sky189) Callstate Change RINGING -> HANGUP 2010-08-04 13:06:48.861065 [NOTICE] sofia.c:4932 Hangup sofia/external/1234567890@sky189 [CS_CONSUME_MEDIA] [NORMAL_TEMPORARY_FAILURE] 2010-08-04 13:06:48.861065 [DEBUG] switch_channel.c:2325 Send signal sofia/external/1234567890@sky189 [KILL] 2010-08-04 13:06:48.861065 [DEBUG] switch_core_session.c:1039 Send signal sofia/external/1234567890@sky189 [BREAK] 2010-08-04 13:06:48.861065 [DEBUG] switch_core_state_machine.c:314 (sofia/external/1234567890@sky189) Running State Change CS_HANGUP 2010-08-04 13:06:48.861065 [DEBUG] switch_core_state_machine.c:535 (sofia/external/1234567890@sky189) State HANGUP 2010-08-04 13:06:48.861065 [DEBUG] mod_sofia.c:447 sofia/external/1234567890@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@sky189 hanging up, cause: NORMAL_TEMPORARY_FAILURE 2010-08-04 13:06:48.861065 [DEBUG] switch_core_state_machine.c:46 sofia/external/1234567890@sky189 Standard HANGUP, cause: NORMAL_TEMPORARY_FAILURE 2010-08-04 13:06:48.861065 [DEBUG] switch_core_state_machine.c:535 (sofia/external/1234567890@sky189) State HANGUP going to sleep 2010-08-04 13:06:48.861065 [DEBUG] switch_core_state_machine.c:333 (sofia/external/1234567890@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@sky189 [BREAK] 2010-08-04 13:06:48.861065 [DEBUG] switch_core_state_machine.c:314 (sofia/external/1234567890@sky189) Running State Change CS_REPORTING 2010-08-04 13:06:48.861065 [DEBUG] switch_core_state_machine.c:595 (sofia/external/1234567890@sky189) State REPORTING 2010-08-04 13:06:48.861065 [DEBUG] switch_core_state_machine.c:53 sofia/external/1234567890@sky189 Standard REPORTING, cause: NORMAL_TEMPORARY_FAILURE 2010-08-04 13:06:48.861065 [DEBUG] switch_core_state_machine.c:595 (sofia/external/1234567890@sky189) State REPORTING going to sleep 2010-08-04 13:06:48.861065 [DEBUG] switch_core_state_machine.c:327 (sofia/external/1234567890@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@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@a.b.c.d) Callstate Change RINGING -> HANGUP 2010-08-04 13:06:48.861065 [NOTICE] mod_dptools.c:2456 Hangup sofia/internal/hassan@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@a.b.c.d [KILL] 2010-08-04 13:06:48.861065 [DEBUG] switch_core_session.c:1039 Send signal sofia/internal/hassan@a.b.c.d [BREAK] 2010-08-04 13:06:48.861065 [DEBUG] switch_core_session.c:1905 sofia/internal/hassan@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@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@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@a.b.c.d) State HANGUP 2010-08-04 13:06:48.861065 [DEBUG] mod_sofia.c:447 sofia/internal/hassan@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@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@sky189) Locked, Waiting on external entities 2010-08-04 13:06:48.861065 [NOTICE] switch_core_session.c:1220 Session 11 (sofia/external/1234567890@sky189) Ended 2010-08-04 13:06:48.862912 [NOTICE] switch_core_session.c:1222 Close Channel sofia/external/1234567890@sky189 [CS_DESTROY] 2010-08-04 13:06:48.862912 [DEBUG] switch_core_state_machine.c:427 (sofia/external/1234567890@sky189) Callstate Change HANGUP -> DOWN 2010-08-04 13:06:48.862912 [DEBUG] switch_core_state_machine.c:430 (sofia/external/1234567890@sky189) Running State Change CS_DESTROY 2010-08-04 13:06:48.862912 [DEBUG] switch_core_state_machine.c:440 (sofia/external/1234567890@sky189) State DESTROY 2010-08-04 13:06:48.862912 [DEBUG] mod_sofia.c:358 sofia/external/1234567890@sky189 SOFIA DESTROY 2010-08-04 13:06:48.862912 [DEBUG] switch_core_state_machine.c:60 sofia/external/1234567890@sky189 Standard DESTROY 2010-08-04 13:06:48.862912 [DEBUG] switch_core_state_machine.c:440 (sofia/external/1234567890@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@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@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@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@a.b.c.d [BREAK] 2010-08-04 13:06:48.864893 [DEBUG] switch_core_state_machine.c:314 (sofia/internal/hassan@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@a.b.c.d) State REPORTING 2010-08-04 13:06:48.864893 [DEBUG] switch_core_state_machine.c:53 sofia/internal/hassan@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@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@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@a.b.c.d [BREAK] 2010-08-04 13:06:48.864893 [DEBUG] switch_core_session.c:1202 Session 10 (sofia/internal/hassan@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@a.b.c.d) Ended 2010-08-04 13:06:48.864893 [NOTICE] switch_core_session.c:1222 Close Channel sofia/internal/hassan@a.b.c.d [CS_DESTROY] 2010-08-04 13:06:48.864893 [DEBUG] switch_core_state_machine.c:427 (sofia/internal/hassan@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@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@a.b.c.d) State DESTROY 2010-08-04 13:06:48.866921 [DEBUG] mod_sofia.c:358 sofia/internal/hassan@a.b.c.d SOFIA DESTROY 2010-08-04 13:06:48.866921 [DEBUG] switch_core_state_machine.c:60 sofia/internal/hassan@a.b.c.d Standard DESTROY 2010-08-04 13:06:48.866921 [DEBUG] switch_core_state_machine.c:440 (sofia/internal/hassan@a.b.c.d) State DESTROY going to sleep
_______________________________________________ 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
_______________________________________________ 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
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@lists.freeswitch.org [mailto:freeswitch-users-bounces@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@gmail.com<mailto:steveayre@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@sky189 entering state [calling][0] 2010-08-04 13:06:48.861065 [DEBUG] sofia.c:4318 Channel sofia/external/1234567890@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@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@usa.net<mailto:mnhassan@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@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@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@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@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@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@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@a.b.c.d [BREAK] 2010-08-04 13:06:48.856895 [DEBUG] switch_core_state_machine.c:314 (sofia/internal/hassan@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@a.b.c.d) State INIT 2010-08-04 13:06:48.856895 [DEBUG] mod_sofia.c:83 sofia/internal/hassan@a.b.c.d SOFIA INIT 2010-08-04 13:06:48.856895 [DEBUG] mod_sofia.c:119 (sofia/internal/hassan@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@a.b.c.d [BREAK] 2010-08-04 13:06:48.856895 [DEBUG] switch_core_state_machine.c:338 (sofia/internal/hassan@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@a.b.c.d) Running State Change CS_ROUTING 2010-08-04 13:06:48.856895 [DEBUG] switch_channel.c:1512 (sofia/internal/hassan@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@a.b.c.d) State ROUTING 2010-08-04 13:06:48.856895 [DEBUG] mod_sofia.c:142 sofia/internal/hassan@a.b.c.d SOFIA ROUTING 2010-08-04 13:06:48.856895 [DEBUG] switch_core_state_machine.c:77 sofia/internal/hassan@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@a.b.c.d parsing [sky189->dial_sky189] continue=false Dialplan: sofia/internal/hassan@a.b.c.d Regex (PASS) [dial_sky189] destination_number(0111234567890) =~ /^011(\d+)$/ break=on-false Dialplan: sofia/internal/hassan@a.b.c.d Action set(effective_caller_id_number=${outbound_caller_id_number}) Dialplan: sofia/internal/hassan@a.b.c.d Action set(effective_caller_id_name=${outbound_caller_id_name}) Dialplan: sofia/internal/hassan@a.b.c.d Action bridge(sofia/external/1234567890@sky189) 2010-08-04 13:06:48.858888 [DEBUG] switch_core_state_machine.c:119 (sofia/internal/hassan@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@a.b.c.d [BREAK] 2010-08-04 13:06:48.858888 [DEBUG] switch_core_state_machine.c:341 (sofia/internal/hassan@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@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@a.b.c.d) State EXECUTE 2010-08-04 13:06:48.858888 [DEBUG] mod_sofia.c:235 sofia/internal/hassan@a.b.c.d SOFIA EXECUTE 2010-08-04 13:06:48.858888 [DEBUG] switch_core_state_machine.c:157 sofia/internal/hassan@a.b.c.d Standard EXECUTE EXECUTE sofia/internal/hassan@a.b.c.d set(effective_caller_id_number=) 2010-08-04 13:06:48.858888 [DEBUG] mod_dptools.c:854 sofia/internal/hassan@a.b.c.d SET [effective_caller_id_number]=[UNDEF] EXECUTE sofia/internal/hassan@a.b.c.d set(effective_caller_id_name=) 2010-08-04 13:06:48.858888 [DEBUG] mod_dptools.c:854 sofia/internal/hassan@a.b.c.d SET [effective_caller_id_name]=[UNDEF] EXECUTE sofia/internal/hassan@a.b.c.d bridge(sofia/external/1234567890@sky189) 2010-08-04 13:06:48.858888 [NOTICE] switch_channel.c:779 New Channel sofia/external/1234567890@sky189 [cfbd2d4f-87fc-4c59-b320-2290a5a076b3] 2010-08-04 13:06:48.858888 [DEBUG] mod_sofia.c:3892 (sofia/external/1234567890@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@sky189 [BREAK] 2010-08-04 13:06:48.858888 [DEBUG] switch_core_state_machine.c:314 (sofia/external/1234567890@sky189) Running State Change CS_INIT 2010-08-04 13:06:48.858888 [DEBUG] switch_core_state_machine.c:338 (sofia/external/1234567890@sky189) State INIT 2010-08-04 13:06:48.858888 [DEBUG] mod_sofia.c:83 sofia/external/1234567890@sky189 SOFIA INIT 2010-08-04 13:06:48.858888 [DEBUG] mod_sofia.c:119 (sofia/external/1234567890@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@sky189 [BREAK] 2010-08-04 13:06:48.858888 [DEBUG] switch_core_state_machine.c:338 (sofia/external/1234567890@sky189) State INIT going to sleep 2010-08-04 13:06:48.858888 [DEBUG] switch_core_state_machine.c:314 (sofia/external/1234567890@sky189) Running State Change CS_ROUTING 2010-08-04 13:06:48.858888 [DEBUG] switch_channel.c:1512 (sofia/external/1234567890@sky189) Callstate Change DOWN -> RINGING 2010-08-04 13:06:48.858888 [DEBUG] switch_core_state_machine.c:341 (sofia/external/1234567890@sky189) State ROUTING 2010-08-04 13:06:48.858888 [DEBUG] mod_sofia.c:142 sofia/external/1234567890@sky189 SOFIA ROUTING 2010-08-04 13:06:48.858888 [DEBUG] switch_ivr_originate.c:66 (sofia/external/1234567890@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@sky189 [BREAK] 2010-08-04 13:06:48.858888 [DEBUG] switch_core_state_machine.c:341 (sofia/external/1234567890@sky189) State ROUTING going to sleep 2010-08-04 13:06:48.858888 [DEBUG] switch_core_state_machine.c:314 (sofia/external/1234567890@sky189) Running State Change CS_CONSUME_MEDIA 2010-08-04 13:06:48.858888 [DEBUG] switch_core_state_machine.c:360 (sofia/external/1234567890@sky189) State CONSUME_MEDIA 2010-08-04 13:06:48.858888 [DEBUG] switch_core_state_machine.c:360 (sofia/external/1234567890@sky189) State CONSUME_MEDIA going to sleep 2010-08-04 13:06:48.858888 [DEBUG] sofia.c:4318 Channel sofia/external/1234567890@sky189 entering state [calling][0] 2010-08-04 13:06:48.861065 [DEBUG] sofia.c:4318 Channel sofia/external/1234567890@sky189 entering state [terminated][503] 2010-08-04 13:06:48.861065 [DEBUG] switch_channel.c:2309 (sofia/external/1234567890@sky189) Callstate Change RINGING -> HANGUP 2010-08-04 13:06:48.861065 [NOTICE] sofia.c:4932 Hangup sofia/external/1234567890@sky189 [CS_CONSUME_MEDIA] [NORMAL_TEMPORARY_FAILURE] 2010-08-04 13:06:48.861065 [DEBUG] switch_channel.c:2325 Send signal sofia/external/1234567890@sky189 [KILL] 2010-08-04 13:06:48.861065 [DEBUG] switch_core_session.c:1039 Send signal sofia/external/1234567890@sky189 [BREAK] 2010-08-04 13:06:48.861065 [DEBUG] switch_core_state_machine.c:314 (sofia/external/1234567890@sky189) Running State Change CS_HANGUP 2010-08-04 13:06:48.861065 [DEBUG] switch_core_state_machine.c:535 (sofia/external/1234567890@sky189) State HANGUP 2010-08-04 13:06:48.861065 [DEBUG] mod_sofia.c:447 sofia/external/1234567890@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@sky189 hanging up, cause: NORMAL_TEMPORARY_FAILURE 2010-08-04 13:06:48.861065 [DEBUG] switch_core_state_machine.c:46 sofia/external/1234567890@sky189 Standard HANGUP, cause: NORMAL_TEMPORARY_FAILURE 2010-08-04 13:06:48.861065 [DEBUG] switch_core_state_machine.c:535 (sofia/external/1234567890@sky189) State HANGUP going to sleep 2010-08-04 13:06:48.861065 [DEBUG] switch_core_state_machine.c:333 (sofia/external/1234567890@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@sky189 [BREAK] 2010-08-04 13:06:48.861065 [DEBUG] switch_core_state_machine.c:314 (sofia/external/1234567890@sky189) Running State Change CS_REPORTING 2010-08-04 13:06:48.861065 [DEBUG] switch_core_state_machine.c:595 (sofia/external/1234567890@sky189) State REPORTING 2010-08-04 13:06:48.861065 [DEBUG] switch_core_state_machine.c:53 sofia/external/1234567890@sky189 Standard REPORTING, cause: NORMAL_TEMPORARY_FAILURE 2010-08-04 13:06:48.861065 [DEBUG] switch_core_state_machine.c:595 (sofia/external/1234567890@sky189) State REPORTING going to sleep 2010-08-04 13:06:48.861065 [DEBUG] switch_core_state_machine.c:327 (sofia/external/1234567890@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@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@a.b.c.d) Callstate Change RINGING -> HANGUP 2010-08-04 13:06:48.861065 [NOTICE] mod_dptools.c:2456 Hangup sofia/internal/hassan@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@a.b.c.d [KILL] 2010-08-04 13:06:48.861065 [DEBUG] switch_core_session.c:1039 Send signal sofia/internal/hassan@a.b.c.d [BREAK] 2010-08-04 13:06:48.861065 [DEBUG] switch_core_session.c:1905 sofia/internal/hassan@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@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@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@a.b.c.d) State HANGUP 2010-08-04 13:06:48.861065 [DEBUG] mod_sofia.c:447 sofia/internal/hassan@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@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@sky189) Locked, Waiting on external entities 2010-08-04 13:06:48.861065 [NOTICE] switch_core_session.c:1220 Session 11 (sofia/external/1234567890@sky189) Ended 2010-08-04 13:06:48.862912 [NOTICE] switch_core_session.c:1222 Close Channel sofia/external/1234567890@sky189 [CS_DESTROY] 2010-08-04 13:06:48.862912 [DEBUG] switch_core_state_machine.c:427 (sofia/external/1234567890@sky189) Callstate Change HANGUP -> DOWN 2010-08-04 13:06:48.862912 [DEBUG] switch_core_state_machine.c:430 (sofia/external/1234567890@sky189) Running State Change CS_DESTROY 2010-08-04 13:06:48.862912 [DEBUG] switch_core_state_machine.c:440 (sofia/external/1234567890@sky189) State DESTROY 2010-08-04 13:06:48.862912 [DEBUG] mod_sofia.c:358 sofia/external/1234567890@sky189 SOFIA DESTROY 2010-08-04 13:06:48.862912 [DEBUG] switch_core_state_machine.c:60 sofia/external/1234567890@sky189 Standard DESTROY 2010-08-04 13:06:48.862912 [DEBUG] switch_core_state_machine.c:440 (sofia/external/1234567890@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@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@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@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@a.b.c.d [BREAK] 2010-08-04 13:06:48.864893 [DEBUG] switch_core_state_machine.c:314 (sofia/internal/hassan@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@a.b.c.d) State REPORTING 2010-08-04 13:06:48.864893 [DEBUG] switch_core_state_machine.c:53 sofia/internal/hassan@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@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@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@a.b.c.d [BREAK] 2010-08-04 13:06:48.864893 [DEBUG] switch_core_session.c:1202 Session 10 (sofia/internal/hassan@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@a.b.c.d) Ended 2010-08-04 13:06:48.864893 [NOTICE] switch_core_session.c:1222 Close Channel sofia/internal/hassan@a.b.c.d [CS_DESTROY] 2010-08-04 13:06:48.864893 [DEBUG] switch_core_state_machine.c:427 (sofia/internal/hassan@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@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@a.b.c.d) State DESTROY 2010-08-04 13:06:48.866921 [DEBUG] mod_sofia.c:358 sofia/internal/hassan@a.b.c.d SOFIA DESTROY 2010-08-04 13:06:48.866921 [DEBUG] switch_core_state_machine.c:60 sofia/internal/hassan@a.b.c.d Standard DESTROY 2010-08-04 13:06:48.866921 [DEBUG] switch_core_state_machine.c:440 (sofia/internal/hassan@a.b.c.d) State DESTROY going to sleep _______________________________________________ FreeSWITCH-users mailing list FreeSWITCH-users@lists.freeswitch.org<mailto: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 _______________________________________________ FreeSWITCH-users mailing list FreeSWITCH-users@lists.freeswitch.org<mailto: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:4c5a81c132932113517252!
The format you uses is the correct one in your case. Gateways are only the ones you authenticate with. If you don't need to authenticate, you don't need gateway. Is in the book, IIRC -giovanni On 8/5/10, Nyamul Hassan <mnhassan@usa.net> wrote:
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@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@sky189 entering state [calling][0] 2010-08-04 13:06:48.861065 [DEBUG] sofia.c:4318 Channel sofia/external/1234567890@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@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@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@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@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@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@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@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@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@a.b.c.d [BREAK] 2010-08-04 13:06:48.856895 [DEBUG] switch_core_state_machine.c:314 (sofia/internal/hassan@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@a.b.c.d) State INIT 2010-08-04 13:06:48.856895 [DEBUG] mod_sofia.c:83 sofia/internal/hassan@a.b.c.d SOFIA INIT 2010-08-04 13:06:48.856895 [DEBUG] mod_sofia.c:119 (sofia/internal/hassan@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@a.b.c.d [BREAK] 2010-08-04 13:06:48.856895 [DEBUG] switch_core_state_machine.c:338 (sofia/internal/hassan@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@a.b.c.d) Running State Change CS_ROUTING 2010-08-04 13:06:48.856895 [DEBUG] switch_channel.c:1512 (sofia/internal/hassan@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@a.b.c.d) State ROUTING 2010-08-04 13:06:48.856895 [DEBUG] mod_sofia.c:142 sofia/internal/hassan@a.b.c.d SOFIA ROUTING 2010-08-04 13:06:48.856895 [DEBUG] switch_core_state_machine.c:77 sofia/internal/hassan@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@a.b.c.d parsing [sky189->dial_sky189] continue=false Dialplan: sofia/internal/hassan@a.b.c.d Regex (PASS) [dial_sky189] destination_number(0111234567890) =~ /^011(\d+)$/ break=on-false Dialplan: sofia/internal/hassan@a.b.c.d Action set(effective_caller_id_number=${outbound_caller_id_number}) Dialplan: sofia/internal/hassan@a.b.c.d Action set(effective_caller_id_name=${outbound_caller_id_name}) Dialplan: sofia/internal/hassan@a.b.c.d Action bridge(sofia/external/1234567890@sky189) 2010-08-04 13:06:48.858888 [DEBUG] switch_core_state_machine.c:119 (sofia/internal/hassan@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@a.b.c.d [BREAK] 2010-08-04 13:06:48.858888 [DEBUG] switch_core_state_machine.c:341 (sofia/internal/hassan@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@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@a.b.c.d) State EXECUTE 2010-08-04 13:06:48.858888 [DEBUG] mod_sofia.c:235 sofia/internal/hassan@a.b.c.d SOFIA EXECUTE 2010-08-04 13:06:48.858888 [DEBUG] switch_core_state_machine.c:157 sofia/internal/hassan@a.b.c.d Standard EXECUTE EXECUTE sofia/internal/hassan@a.b.c.d set(effective_caller_id_number=) 2010-08-04 13:06:48.858888 [DEBUG] mod_dptools.c:854 sofia/internal/hassan@a.b.c.d SET [effective_caller_id_number]=[UNDEF] EXECUTE sofia/internal/hassan@a.b.c.d set(effective_caller_id_name=) 2010-08-04 13:06:48.858888 [DEBUG] mod_dptools.c:854 sofia/internal/hassan@a.b.c.d SET [effective_caller_id_name]=[UNDEF] EXECUTE sofia/internal/hassan@a.b.c.dbridge(sofia/external/1234567890@sky189 ) 2010-08-04 13:06:48.858888 [NOTICE] switch_channel.c:779 New Channel sofia/external/1234567890@sky189 [cfbd2d4f-87fc-4c59-b320-2290a5a076b3] 2010-08-04 13:06:48.858888 [DEBUG] mod_sofia.c:3892 (sofia/external/1234567890@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@sky189 [BREAK] 2010-08-04 13:06:48.858888 [DEBUG] switch_core_state_machine.c:314 (sofia/external/1234567890@sky189) Running State Change CS_INIT 2010-08-04 13:06:48.858888 [DEBUG] switch_core_state_machine.c:338 (sofia/external/1234567890@sky189) State INIT 2010-08-04 13:06:48.858888 [DEBUG] mod_sofia.c:83 sofia/external/1234567890@sky189 SOFIA INIT 2010-08-04 13:06:48.858888 [DEBUG] mod_sofia.c:119 (sofia/external/1234567890@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@sky189 [BREAK] 2010-08-04 13:06:48.858888 [DEBUG] switch_core_state_machine.c:338 (sofia/external/1234567890@sky189) State INIT going to sleep 2010-08-04 13:06:48.858888 [DEBUG] switch_core_state_machine.c:314 (sofia/external/1234567890@sky189) Running State Change CS_ROUTING 2010-08-04 13:06:48.858888 [DEBUG] switch_channel.c:1512 (sofia/external/1234567890@sky189) Callstate Change DOWN -> RINGING 2010-08-04 13:06:48.858888 [DEBUG] switch_core_state_machine.c:341 (sofia/external/1234567890@sky189) State ROUTING 2010-08-04 13:06:48.858888 [DEBUG] mod_sofia.c:142 sofia/external/1234567890@sky189 SOFIA ROUTING 2010-08-04 13:06:48.858888 [DEBUG] switch_ivr_originate.c:66 (sofia/external/1234567890@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@sky189 [BREAK] 2010-08-04 13:06:48.858888 [DEBUG] switch_core_state_machine.c:341 (sofia/external/1234567890@sky189) State ROUTING going to sleep 2010-08-04 13:06:48.858888 [DEBUG] switch_core_state_machine.c:314 (sofia/external/1234567890@sky189) Running State Change CS_CONSUME_MEDIA 2010-08-04 13:06:48.858888 [DEBUG] switch_core_state_machine.c:360 (sofia/external/1234567890@sky189) State CONSUME_MEDIA 2010-08-04 13:06:48.858888 [DEBUG] switch_core_state_machine.c:360 (sofia/external/1234567890@sky189) State CONSUME_MEDIA going to sleep 2010-08-04 13:06:48.858888 [DEBUG] sofia.c:4318 Channel sofia/external/1234567890@sky189 entering state [calling][0] 2010-08-04 13:06:48.861065 [DEBUG] sofia.c:4318 Channel sofia/external/1234567890@sky189 entering state [terminated][503] 2010-08-04 13:06:48.861065 [DEBUG] switch_channel.c:2309 (sofia/external/1234567890@sky189) Callstate Change RINGING -> HANGUP 2010-08-04 13:06:48.861065 [NOTICE] sofia.c:4932 Hangup sofia/external/1234567890@sky189 [CS_CONSUME_MEDIA] [NORMAL_TEMPORARY_FAILURE] 2010-08-04 13:06:48.861065 [DEBUG] switch_channel.c:2325 Send signal sofia/external/1234567890@sky189 [KILL] 2010-08-04 13:06:48.861065 [DEBUG] switch_core_session.c:1039 Send signal sofia/external/1234567890@sky189 [BREAK] 2010-08-04 13:06:48.861065 [DEBUG] switch_core_state_machine.c:314 (sofia/external/1234567890@sky189) Running State Change CS_HANGUP 2010-08-04 13:06:48.861065 [DEBUG] switch_core_state_machine.c:535 (sofia/external/1234567890@sky189) State HANGUP 2010-08-04 13:06:48.861065 [DEBUG] mod_sofia.c:447 sofia/external/1234567890@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@sky189 hanging up, cause: NORMAL_TEMPORARY_FAILURE 2010-08-04 13:06:48.861065 [DEBUG] switch_core_state_machine.c:46 sofia/external/1234567890@sky189 Standard HANGUP, cause: NORMAL_TEMPORARY_FAILURE 2010-08-04 13:06:48.861065 [DEBUG] switch_core_state_machine.c:535 (sofia/external/1234567890@sky189) State HANGUP going to sleep 2010-08-04 13:06:48.861065 [DEBUG] switch_core_state_machine.c:333 (sofia/external/1234567890@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@sky189 [BREAK] 2010-08-04 13:06:48.861065 [DEBUG] switch_core_state_machine.c:314 (sofia/external/1234567890@sky189) Running State Change CS_REPORTING 2010-08-04 13:06:48.861065 [DEBUG] switch_core_state_machine.c:595 (sofia/external/1234567890@sky189) State REPORTING 2010-08-04 13:06:48.861065 [DEBUG] switch_core_state_machine.c:53 sofia/external/1234567890@sky189 Standard REPORTING, cause: NORMAL_TEMPORARY_FAILURE 2010-08-04 13:06:48.861065 [DEBUG] switch_core_state_machine.c:595 (sofia/external/1234567890@sky189) State REPORTING going to sleep 2010-08-04 13:06:48.861065 [DEBUG] switch_core_state_machine.c:327 (sofia/external/1234567890@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@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@a.b.c.d) Callstate Change RINGING -> HANGUP 2010-08-04 13:06:48.861065 [NOTICE] mod_dptools.c:2456 Hangup sofia/internal/hassan@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@a.b.c.d [KILL] 2010-08-04 13:06:48.861065 [DEBUG] switch_core_session.c:1039 Send signal sofia/internal/hassan@a.b.c.d [BREAK] 2010-08-04 13:06:48.861065 [DEBUG] switch_core_session.c:1905 sofia/internal/hassan@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@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@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@a.b.c.d) State HANGUP 2010-08-04 13:06:48.861065 [DEBUG] mod_sofia.c:447 sofia/internal/hassan@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@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@sky189) Locked, Waiting on external entities 2010-08-04 13:06:48.861065 [NOTICE] switch_core_session.c:1220 Session 11 (sofia/external/1234567890@sky189) Ended 2010-08-04 13:06:48.862912 [NOTICE] switch_core_session.c:1222 Close Channel sofia/external/1234567890@sky189 [CS_DESTROY] 2010-08-04 13:06:48.862912 [DEBUG] switch_core_state_machine.c:427 (sofia/external/1234567890@sky189) Callstate Change HANGUP -> DOWN 2010-08-04 13:06:48.862912 [DEBUG] switch_core_state_machine.c:430 (sofia/external/1234567890@sky189) Running State Change CS_DESTROY 2010-08-04 13:06:48.862912 [DEBUG] switch_core_state_machine.c:440 (sofia/external/1234567890@sky189) State DESTROY 2010-08-04 13:06:48.862912 [DEBUG] mod_sofia.c:358 sofia/external/1234567890@sky189 SOFIA DESTROY 2010-08-04 13:06:48.862912 [DEBUG] switch_core_state_machine.c:60 sofia/external/1234567890@sky189 Standard DESTROY 2010-08-04 13:06:48.862912 [DEBUG] switch_core_state_machine.c:440 (sofia/external/1234567890@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@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@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@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@a.b.c.d [BREAK] 2010-08-04 13:06:48.864893 [DEBUG] switch_core_state_machine.c:314 (sofia/internal/hassan@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@a.b.c.d) State REPORTING 2010-08-04 13:06:48.864893 [DEBUG] switch_core_state_machine.c:53 sofia/internal/hassan@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@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@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@a.b.c.d [BREAK] 2010-08-04 13:06:48.864893 [DEBUG] switch_core_session.c:1202 Session 10 (sofia/internal/hassan@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@a.b.c.d) Ended 2010-08-04 13:06:48.864893 [NOTICE] switch_core_session.c:1222 Close Channel sofia/internal/hassan@a.b.c.d [CS_DESTROY] 2010-08-04 13:06:48.864893 [DEBUG] switch_core_state_machine.c:427 (sofia/internal/hassan@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@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@a.b.c.d) State DESTROY 2010-08-04 13:06:48.866921 [DEBUG] mod_sofia.c:358 sofia/internal/hassan@a.b.c.d SOFIA DESTROY 2010-08-04 13:06:48.866921 [DEBUG] switch_core_state_machine.c:60 sofia/internal/hassan@a.b.c.d Standard DESTROY 2010-08-04 13:06:48.866921 [DEBUG] switch_core_state_machine.c:440 (sofia/internal/hassan@a.b.c.d) State DESTROY going to sleep
_______________________________________________ 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
_______________________________________________ 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
-- Sent from my mobile device Sincerely, Giovanni Maruzzelli Cell : +39-347-2665618
As already mentioned, one is required. But it's only used if the gateway gives a 401 Not Authorized response. If you don't need authentication, just make one up. -Steve On 5 August 2010 10:09, Nyamul Hassan <mnhassan@usa.net> wrote:
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@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@sky189 entering state [calling][0] 2010-08-04 13:06:48.861065 [DEBUG] sofia.c:4318 Channel sofia/external/1234567890@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@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@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@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@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@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@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@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@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@a.b.c.d [BREAK] 2010-08-04 13:06:48.856895 [DEBUG] switch_core_state_machine.c:314 (sofia/internal/hassan@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@a.b.c.d) State INIT 2010-08-04 13:06:48.856895 [DEBUG] mod_sofia.c:83 sofia/internal/hassan@a.b.c.d SOFIA INIT 2010-08-04 13:06:48.856895 [DEBUG] mod_sofia.c:119 (sofia/internal/hassan@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@a.b.c.d [BREAK] 2010-08-04 13:06:48.856895 [DEBUG] switch_core_state_machine.c:338 (sofia/internal/hassan@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@a.b.c.d) Running State Change CS_ROUTING 2010-08-04 13:06:48.856895 [DEBUG] switch_channel.c:1512 (sofia/internal/hassan@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@a.b.c.d) State ROUTING 2010-08-04 13:06:48.856895 [DEBUG] mod_sofia.c:142 sofia/internal/hassan@a.b.c.d SOFIA ROUTING 2010-08-04 13:06:48.856895 [DEBUG] switch_core_state_machine.c:77 sofia/internal/hassan@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@a.b.c.d parsing [sky189->dial_sky189] continue=false Dialplan: sofia/internal/hassan@a.b.c.d Regex (PASS) [dial_sky189] destination_number(0111234567890) =~ /^011(\d+)$/ break=on-false Dialplan: sofia/internal/hassan@a.b.c.d Action set(effective_caller_id_number=${outbound_caller_id_number}) Dialplan: sofia/internal/hassan@a.b.c.d Action set(effective_caller_id_name=${outbound_caller_id_name}) Dialplan: sofia/internal/hassan@a.b.c.d Action bridge(sofia/external/1234567890@sky189) 2010-08-04 13:06:48.858888 [DEBUG] switch_core_state_machine.c:119 (sofia/internal/hassan@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@a.b.c.d [BREAK] 2010-08-04 13:06:48.858888 [DEBUG] switch_core_state_machine.c:341 (sofia/internal/hassan@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@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@a.b.c.d) State EXECUTE 2010-08-04 13:06:48.858888 [DEBUG] mod_sofia.c:235 sofia/internal/hassan@a.b.c.d SOFIA EXECUTE 2010-08-04 13:06:48.858888 [DEBUG] switch_core_state_machine.c:157 sofia/internal/hassan@a.b.c.d Standard EXECUTE EXECUTE sofia/internal/hassan@a.b.c.d set(effective_caller_id_number=) 2010-08-04 13:06:48.858888 [DEBUG] mod_dptools.c:854 sofia/internal/hassan@a.b.c.d SET [effective_caller_id_number]=[UNDEF] EXECUTE sofia/internal/hassan@a.b.c.d set(effective_caller_id_name=) 2010-08-04 13:06:48.858888 [DEBUG] mod_dptools.c:854 sofia/internal/hassan@a.b.c.d SET [effective_caller_id_name]=[UNDEF] EXECUTE sofia/internal/hassan@a.b.c.dbridge(sofia/external/1234567890@sky189 ) 2010-08-04 13:06:48.858888 [NOTICE] switch_channel.c:779 New Channel sofia/external/1234567890@sky189 [cfbd2d4f-87fc-4c59-b320-2290a5a076b3] 2010-08-04 13:06:48.858888 [DEBUG] mod_sofia.c:3892 (sofia/external/1234567890@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@sky189 [BREAK] 2010-08-04 13:06:48.858888 [DEBUG] switch_core_state_machine.c:314 (sofia/external/1234567890@sky189) Running State Change CS_INIT 2010-08-04 13:06:48.858888 [DEBUG] switch_core_state_machine.c:338 (sofia/external/1234567890@sky189) State INIT 2010-08-04 13:06:48.858888 [DEBUG] mod_sofia.c:83 sofia/external/1234567890@sky189 SOFIA INIT 2010-08-04 13:06:48.858888 [DEBUG] mod_sofia.c:119 (sofia/external/1234567890@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@sky189 [BREAK] 2010-08-04 13:06:48.858888 [DEBUG] switch_core_state_machine.c:338 (sofia/external/1234567890@sky189) State INIT going to sleep 2010-08-04 13:06:48.858888 [DEBUG] switch_core_state_machine.c:314 (sofia/external/1234567890@sky189) Running State Change CS_ROUTING 2010-08-04 13:06:48.858888 [DEBUG] switch_channel.c:1512 (sofia/external/1234567890@sky189) Callstate Change DOWN -> RINGING 2010-08-04 13:06:48.858888 [DEBUG] switch_core_state_machine.c:341 (sofia/external/1234567890@sky189) State ROUTING 2010-08-04 13:06:48.858888 [DEBUG] mod_sofia.c:142 sofia/external/1234567890@sky189 SOFIA ROUTING 2010-08-04 13:06:48.858888 [DEBUG] switch_ivr_originate.c:66 (sofia/external/1234567890@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@sky189 [BREAK] 2010-08-04 13:06:48.858888 [DEBUG] switch_core_state_machine.c:341 (sofia/external/1234567890@sky189) State ROUTING going to sleep 2010-08-04 13:06:48.858888 [DEBUG] switch_core_state_machine.c:314 (sofia/external/1234567890@sky189) Running State Change CS_CONSUME_MEDIA 2010-08-04 13:06:48.858888 [DEBUG] switch_core_state_machine.c:360 (sofia/external/1234567890@sky189) State CONSUME_MEDIA 2010-08-04 13:06:48.858888 [DEBUG] switch_core_state_machine.c:360 (sofia/external/1234567890@sky189) State CONSUME_MEDIA going to sleep 2010-08-04 13:06:48.858888 [DEBUG] sofia.c:4318 Channel sofia/external/1234567890@sky189 entering state [calling][0] 2010-08-04 13:06:48.861065 [DEBUG] sofia.c:4318 Channel sofia/external/1234567890@sky189 entering state [terminated][503] 2010-08-04 13:06:48.861065 [DEBUG] switch_channel.c:2309 (sofia/external/1234567890@sky189) Callstate Change RINGING -> HANGUP 2010-08-04 13:06:48.861065 [NOTICE] sofia.c:4932 Hangup sofia/external/1234567890@sky189 [CS_CONSUME_MEDIA] [NORMAL_TEMPORARY_FAILURE] 2010-08-04 13:06:48.861065 [DEBUG] switch_channel.c:2325 Send signal sofia/external/1234567890@sky189 [KILL] 2010-08-04 13:06:48.861065 [DEBUG] switch_core_session.c:1039 Send signal sofia/external/1234567890@sky189 [BREAK] 2010-08-04 13:06:48.861065 [DEBUG] switch_core_state_machine.c:314 (sofia/external/1234567890@sky189) Running State Change CS_HANGUP 2010-08-04 13:06:48.861065 [DEBUG] switch_core_state_machine.c:535 (sofia/external/1234567890@sky189) State HANGUP 2010-08-04 13:06:48.861065 [DEBUG] mod_sofia.c:447 sofia/external/1234567890@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@sky189 hanging up, cause: NORMAL_TEMPORARY_FAILURE 2010-08-04 13:06:48.861065 [DEBUG] switch_core_state_machine.c:46 sofia/external/1234567890@sky189 Standard HANGUP, cause: NORMAL_TEMPORARY_FAILURE 2010-08-04 13:06:48.861065 [DEBUG] switch_core_state_machine.c:535 (sofia/external/1234567890@sky189) State HANGUP going to sleep 2010-08-04 13:06:48.861065 [DEBUG] switch_core_state_machine.c:333 (sofia/external/1234567890@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@sky189 [BREAK] 2010-08-04 13:06:48.861065 [DEBUG] switch_core_state_machine.c:314 (sofia/external/1234567890@sky189) Running State Change CS_REPORTING 2010-08-04 13:06:48.861065 [DEBUG] switch_core_state_machine.c:595 (sofia/external/1234567890@sky189) State REPORTING 2010-08-04 13:06:48.861065 [DEBUG] switch_core_state_machine.c:53 sofia/external/1234567890@sky189 Standard REPORTING, cause: NORMAL_TEMPORARY_FAILURE 2010-08-04 13:06:48.861065 [DEBUG] switch_core_state_machine.c:595 (sofia/external/1234567890@sky189) State REPORTING going to sleep 2010-08-04 13:06:48.861065 [DEBUG] switch_core_state_machine.c:327 (sofia/external/1234567890@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@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@a.b.c.d) Callstate Change RINGING -> HANGUP 2010-08-04 13:06:48.861065 [NOTICE] mod_dptools.c:2456 Hangup sofia/internal/hassan@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@a.b.c.d [KILL] 2010-08-04 13:06:48.861065 [DEBUG] switch_core_session.c:1039 Send signal sofia/internal/hassan@a.b.c.d [BREAK] 2010-08-04 13:06:48.861065 [DEBUG] switch_core_session.c:1905 sofia/internal/hassan@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@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@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@a.b.c.d) State HANGUP 2010-08-04 13:06:48.861065 [DEBUG] mod_sofia.c:447 sofia/internal/hassan@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@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@sky189) Locked, Waiting on external entities 2010-08-04 13:06:48.861065 [NOTICE] switch_core_session.c:1220 Session 11 (sofia/external/1234567890@sky189) Ended 2010-08-04 13:06:48.862912 [NOTICE] switch_core_session.c:1222 Close Channel sofia/external/1234567890@sky189 [CS_DESTROY] 2010-08-04 13:06:48.862912 [DEBUG] switch_core_state_machine.c:427 (sofia/external/1234567890@sky189) Callstate Change HANGUP -> DOWN 2010-08-04 13:06:48.862912 [DEBUG] switch_core_state_machine.c:430 (sofia/external/1234567890@sky189) Running State Change CS_DESTROY 2010-08-04 13:06:48.862912 [DEBUG] switch_core_state_machine.c:440 (sofia/external/1234567890@sky189) State DESTROY 2010-08-04 13:06:48.862912 [DEBUG] mod_sofia.c:358 sofia/external/1234567890@sky189 SOFIA DESTROY 2010-08-04 13:06:48.862912 [DEBUG] switch_core_state_machine.c:60 sofia/external/1234567890@sky189 Standard DESTROY 2010-08-04 13:06:48.862912 [DEBUG] switch_core_state_machine.c:440 (sofia/external/1234567890@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@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@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@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@a.b.c.d [BREAK] 2010-08-04 13:06:48.864893 [DEBUG] switch_core_state_machine.c:314 (sofia/internal/hassan@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@a.b.c.d) State REPORTING 2010-08-04 13:06:48.864893 [DEBUG] switch_core_state_machine.c:53 sofia/internal/hassan@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@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@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@a.b.c.d [BREAK] 2010-08-04 13:06:48.864893 [DEBUG] switch_core_session.c:1202 Session 10 (sofia/internal/hassan@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@a.b.c.d) Ended 2010-08-04 13:06:48.864893 [NOTICE] switch_core_session.c:1222 Close Channel sofia/internal/hassan@a.b.c.d [CS_DESTROY] 2010-08-04 13:06:48.864893 [DEBUG] switch_core_state_machine.c:427 (sofia/internal/hassan@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@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@a.b.c.d) State DESTROY 2010-08-04 13:06:48.866921 [DEBUG] mod_sofia.c:358 sofia/internal/hassan@a.b.c.d SOFIA DESTROY 2010-08-04 13:06:48.866921 [DEBUG] switch_core_state_machine.c:60 sofia/internal/hassan@a.b.c.d Standard DESTROY 2010-08-04 13:06:48.866921 [DEBUG] switch_core_state_machine.c:440 (sofia/internal/hassan@a.b.c.d) State DESTROY going to sleep
_______________________________________________ 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
_______________________________________________ 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
_______________________________________________ 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
I've set the "registration" to false, but whenever FS attempts to call the gateway, it tries to send the call using the user/pass given. For some switches, that also messes up the CallerID. I'm using the "non-gateway" format for now, and it works. Thanks to everyone for their help. Regards HASSAN On Thu, Aug 5, 2010 at 16:16, Steven Ayre <steveayre@gmail.com> wrote:
As already mentioned, one is required.
But it's only used if the gateway gives a 401 Not Authorized response. If you don't need authentication, just make one up.
-Steve
On 5 August 2010 10:09, Nyamul Hassan <mnhassan@usa.net> wrote:
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@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@sky189 entering state [calling][0] 2010-08-04 13:06:48.861065 [DEBUG] sofia.c:4318 Channel sofia/external/1234567890@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@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@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@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@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@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@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@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@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@a.b.c.d [BREAK] 2010-08-04 13:06:48.856895 [DEBUG] switch_core_state_machine.c:314 (sofia/internal/hassan@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@a.b.c.d) State INIT 2010-08-04 13:06:48.856895 [DEBUG] mod_sofia.c:83 sofia/internal/hassan@a.b.c.d SOFIA INIT 2010-08-04 13:06:48.856895 [DEBUG] mod_sofia.c:119 (sofia/internal/hassan@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@a.b.c.d [BREAK] 2010-08-04 13:06:48.856895 [DEBUG] switch_core_state_machine.c:338 (sofia/internal/hassan@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@a.b.c.d) Running State Change CS_ROUTING 2010-08-04 13:06:48.856895 [DEBUG] switch_channel.c:1512 (sofia/internal/hassan@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@a.b.c.d) State ROUTING 2010-08-04 13:06:48.856895 [DEBUG] mod_sofia.c:142 sofia/internal/hassan@a.b.c.d SOFIA ROUTING 2010-08-04 13:06:48.856895 [DEBUG] switch_core_state_machine.c:77 sofia/internal/hassan@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@a.b.c.d parsing [sky189->dial_sky189] continue=false Dialplan: sofia/internal/hassan@a.b.c.d Regex (PASS) [dial_sky189] destination_number(0111234567890) =~ /^011(\d+)$/ break=on-false Dialplan: sofia/internal/hassan@a.b.c.d Action set(effective_caller_id_number=${outbound_caller_id_number}) Dialplan: sofia/internal/hassan@a.b.c.d Action set(effective_caller_id_name=${outbound_caller_id_name}) Dialplan: sofia/internal/hassan@a.b.c.d Action bridge(sofia/external/1234567890@sky189) 2010-08-04 13:06:48.858888 [DEBUG] switch_core_state_machine.c:119 (sofia/internal/hassan@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@a.b.c.d [BREAK] 2010-08-04 13:06:48.858888 [DEBUG] switch_core_state_machine.c:341 (sofia/internal/hassan@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@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@a.b.c.d) State EXECUTE 2010-08-04 13:06:48.858888 [DEBUG] mod_sofia.c:235 sofia/internal/hassan@a.b.c.d SOFIA EXECUTE 2010-08-04 13:06:48.858888 [DEBUG] switch_core_state_machine.c:157 sofia/internal/hassan@a.b.c.d Standard EXECUTE EXECUTE sofia/internal/hassan@a.b.c.d set(effective_caller_id_number=) 2010-08-04 13:06:48.858888 [DEBUG] mod_dptools.c:854 sofia/internal/hassan@a.b.c.d SET [effective_caller_id_number]=[UNDEF] EXECUTE sofia/internal/hassan@a.b.c.d set(effective_caller_id_name=) 2010-08-04 13:06:48.858888 [DEBUG] mod_dptools.c:854 sofia/internal/hassan@a.b.c.d SET [effective_caller_id_name]=[UNDEF] EXECUTE sofia/internal/hassan@a.b.c.dbridge(sofia/external/1234567890@sky189 ) 2010-08-04 13:06:48.858888 [NOTICE] switch_channel.c:779 New Channel sofia/external/1234567890@sky189 [cfbd2d4f-87fc-4c59-b320-2290a5a076b3] 2010-08-04 13:06:48.858888 [DEBUG] mod_sofia.c:3892 (sofia/external/1234567890@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@sky189 [BREAK] 2010-08-04 13:06:48.858888 [DEBUG] switch_core_state_machine.c:314 (sofia/external/1234567890@sky189) Running State Change CS_INIT 2010-08-04 13:06:48.858888 [DEBUG] switch_core_state_machine.c:338 (sofia/external/1234567890@sky189) State INIT 2010-08-04 13:06:48.858888 [DEBUG] mod_sofia.c:83 sofia/external/1234567890@sky189 SOFIA INIT 2010-08-04 13:06:48.858888 [DEBUG] mod_sofia.c:119 (sofia/external/1234567890@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@sky189 [BREAK] 2010-08-04 13:06:48.858888 [DEBUG] switch_core_state_machine.c:338 (sofia/external/1234567890@sky189) State INIT going to sleep 2010-08-04 13:06:48.858888 [DEBUG] switch_core_state_machine.c:314 (sofia/external/1234567890@sky189) Running State Change CS_ROUTING 2010-08-04 13:06:48.858888 [DEBUG] switch_channel.c:1512 (sofia/external/1234567890@sky189) Callstate Change DOWN -> RINGING 2010-08-04 13:06:48.858888 [DEBUG] switch_core_state_machine.c:341 (sofia/external/1234567890@sky189) State ROUTING 2010-08-04 13:06:48.858888 [DEBUG] mod_sofia.c:142 sofia/external/1234567890@sky189 SOFIA ROUTING 2010-08-04 13:06:48.858888 [DEBUG] switch_ivr_originate.c:66 (sofia/external/1234567890@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@sky189 [BREAK] 2010-08-04 13:06:48.858888 [DEBUG] switch_core_state_machine.c:341 (sofia/external/1234567890@sky189) State ROUTING going to sleep 2010-08-04 13:06:48.858888 [DEBUG] switch_core_state_machine.c:314 (sofia/external/1234567890@sky189) Running State Change CS_CONSUME_MEDIA 2010-08-04 13:06:48.858888 [DEBUG] switch_core_state_machine.c:360 (sofia/external/1234567890@sky189) State CONSUME_MEDIA 2010-08-04 13:06:48.858888 [DEBUG] switch_core_state_machine.c:360 (sofia/external/1234567890@sky189) State CONSUME_MEDIA going to sleep 2010-08-04 13:06:48.858888 [DEBUG] sofia.c:4318 Channel sofia/external/1234567890@sky189 entering state [calling][0] 2010-08-04 13:06:48.861065 [DEBUG] sofia.c:4318 Channel sofia/external/1234567890@sky189 entering state [terminated][503] 2010-08-04 13:06:48.861065 [DEBUG] switch_channel.c:2309 (sofia/external/1234567890@sky189) Callstate Change RINGING -> HANGUP 2010-08-04 13:06:48.861065 [NOTICE] sofia.c:4932 Hangup sofia/external/1234567890@sky189 [CS_CONSUME_MEDIA] [NORMAL_TEMPORARY_FAILURE] 2010-08-04 13:06:48.861065 [DEBUG] switch_channel.c:2325 Send signal sofia/external/1234567890@sky189 [KILL] 2010-08-04 13:06:48.861065 [DEBUG] switch_core_session.c:1039 Send signal sofia/external/1234567890@sky189 [BREAK] 2010-08-04 13:06:48.861065 [DEBUG] switch_core_state_machine.c:314 (sofia/external/1234567890@sky189) Running State Change CS_HANGUP 2010-08-04 13:06:48.861065 [DEBUG] switch_core_state_machine.c:535 (sofia/external/1234567890@sky189) State HANGUP 2010-08-04 13:06:48.861065 [DEBUG] mod_sofia.c:447 sofia/external/1234567890@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@sky189 hanging up, cause: NORMAL_TEMPORARY_FAILURE 2010-08-04 13:06:48.861065 [DEBUG] switch_core_state_machine.c:46 sofia/external/1234567890@sky189 Standard HANGUP, cause: NORMAL_TEMPORARY_FAILURE 2010-08-04 13:06:48.861065 [DEBUG] switch_core_state_machine.c:535 (sofia/external/1234567890@sky189) State HANGUP going to sleep 2010-08-04 13:06:48.861065 [DEBUG] switch_core_state_machine.c:333 (sofia/external/1234567890@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@sky189 [BREAK] 2010-08-04 13:06:48.861065 [DEBUG] switch_core_state_machine.c:314 (sofia/external/1234567890@sky189) Running State Change CS_REPORTING 2010-08-04 13:06:48.861065 [DEBUG] switch_core_state_machine.c:595 (sofia/external/1234567890@sky189) State REPORTING 2010-08-04 13:06:48.861065 [DEBUG] switch_core_state_machine.c:53 sofia/external/1234567890@sky189 Standard REPORTING, cause: NORMAL_TEMPORARY_FAILURE 2010-08-04 13:06:48.861065 [DEBUG] switch_core_state_machine.c:595 (sofia/external/1234567890@sky189) State REPORTING going to sleep 2010-08-04 13:06:48.861065 [DEBUG] switch_core_state_machine.c:327 (sofia/external/1234567890@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@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@a.b.c.d) Callstate Change RINGING -> HANGUP 2010-08-04 13:06:48.861065 [NOTICE] mod_dptools.c:2456 Hangup sofia/internal/hassan@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@a.b.c.d [KILL] 2010-08-04 13:06:48.861065 [DEBUG] switch_core_session.c:1039 Send signal sofia/internal/hassan@a.b.c.d [BREAK] 2010-08-04 13:06:48.861065 [DEBUG] switch_core_session.c:1905 sofia/internal/hassan@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@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@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@a.b.c.d) State HANGUP 2010-08-04 13:06:48.861065 [DEBUG] mod_sofia.c:447 sofia/internal/hassan@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@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@sky189) Locked, Waiting on external entities 2010-08-04 13:06:48.861065 [NOTICE] switch_core_session.c:1220 Session 11 (sofia/external/1234567890@sky189) Ended 2010-08-04 13:06:48.862912 [NOTICE] switch_core_session.c:1222 Close Channel sofia/external/1234567890@sky189 [CS_DESTROY] 2010-08-04 13:06:48.862912 [DEBUG] switch_core_state_machine.c:427 (sofia/external/1234567890@sky189) Callstate Change HANGUP -> DOWN 2010-08-04 13:06:48.862912 [DEBUG] switch_core_state_machine.c:430 (sofia/external/1234567890@sky189) Running State Change CS_DESTROY 2010-08-04 13:06:48.862912 [DEBUG] switch_core_state_machine.c:440 (sofia/external/1234567890@sky189) State DESTROY 2010-08-04 13:06:48.862912 [DEBUG] mod_sofia.c:358 sofia/external/1234567890@sky189 SOFIA DESTROY 2010-08-04 13:06:48.862912 [DEBUG] switch_core_state_machine.c:60 sofia/external/1234567890@sky189 Standard DESTROY 2010-08-04 13:06:48.862912 [DEBUG] switch_core_state_machine.c:440 (sofia/external/1234567890@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@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@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@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@a.b.c.d [BREAK] 2010-08-04 13:06:48.864893 [DEBUG] switch_core_state_machine.c:314 (sofia/internal/hassan@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@a.b.c.d) State REPORTING 2010-08-04 13:06:48.864893 [DEBUG] switch_core_state_machine.c:53 sofia/internal/hassan@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@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@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@a.b.c.d [BREAK] 2010-08-04 13:06:48.864893 [DEBUG] switch_core_session.c:1202 Session 10 (sofia/internal/hassan@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@a.b.c.d) Ended 2010-08-04 13:06:48.864893 [NOTICE] switch_core_session.c:1222 Close Channel sofia/internal/hassan@a.b.c.d [CS_DESTROY] 2010-08-04 13:06:48.864893 [DEBUG] switch_core_state_machine.c:427 (sofia/internal/hassan@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@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@a.b.c.d) State DESTROY 2010-08-04 13:06:48.866921 [DEBUG] mod_sofia.c:358 sofia/internal/hassan@a.b.c.d SOFIA DESTROY 2010-08-04 13:06:48.866921 [DEBUG] switch_core_state_machine.c:60 sofia/internal/hassan@a.b.c.d Standard DESTROY 2010-08-04 13:06:48.866921 [DEBUG] switch_core_state_machine.c:440 (sofia/internal/hassan@a.b.c.d) State DESTROY going to sleep
_______________________________________________ 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
_______________________________________________ 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
_______________________________________________ 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
_______________________________________________ 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
Have you reloaded the sip profile? I'm using this syntax for lots of gateways, and they never tries to register. /Peter ________________________________________ Från: freeswitch-users-bounces@lists.freeswitch.org [freeswitch-users-bounces@lists.freeswitch.org] för Nyamul Hassan [mnhassan@usa.net] Skickat: den 5 augusti 2010 15:47 Till: FreeSWITCH Users Help Ämne: Re: [Freeswitch-users] Help on reading the log better I've set the "registration" to false, but whenever FS attempts to call the gateway, it tries to send the call using the user/pass given. For some switches, that also messes up the CallerID. I'm using the "non-gateway" format for now, and it works. Thanks to everyone for their help. Regards HASSAN On Thu, Aug 5, 2010 at 16:16, Steven Ayre <steveayre@gmail.com<mailto:steveayre@gmail.com>> wrote: As already mentioned, one is required. But it's only used if the gateway gives a 401 Not Authorized response. If you don't need authentication, just make one up. -Steve On 5 August 2010 10:09, Nyamul Hassan <mnhassan@usa.net<mailto:mnhassan@usa.net>> wrote: 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@gmail.com<mailto:steveayre@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@sky189 entering state [calling][0] 2010-08-04 13:06:48.861065 [DEBUG] sofia.c:4318 Channel sofia/external/1234567890@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@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@usa.net<mailto:mnhassan@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@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@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@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@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@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@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@a.b.c.d [BREAK] 2010-08-04 13:06:48.856895 [DEBUG] switch_core_state_machine.c:314 (sofia/internal/hassan@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@a.b.c.d) State INIT 2010-08-04 13:06:48.856895 [DEBUG] mod_sofia.c:83 sofia/internal/hassan@a.b.c.d SOFIA INIT 2010-08-04 13:06:48.856895 [DEBUG] mod_sofia.c:119 (sofia/internal/hassan@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@a.b.c.d [BREAK] 2010-08-04 13:06:48.856895 [DEBUG] switch_core_state_machine.c:338 (sofia/internal/hassan@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@a.b.c.d) Running State Change CS_ROUTING 2010-08-04 13:06:48.856895 [DEBUG] switch_channel.c:1512 (sofia/internal/hassan@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@a.b.c.d) State ROUTING 2010-08-04 13:06:48.856895 [DEBUG] mod_sofia.c:142 sofia/internal/hassan@a.b.c.d SOFIA ROUTING 2010-08-04 13:06:48.856895 [DEBUG] switch_core_state_machine.c:77 sofia/internal/hassan@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@a.b.c.d parsing [sky189->dial_sky189] continue=false Dialplan: sofia/internal/hassan@a.b.c.d Regex (PASS) [dial_sky189] destination_number(0111234567890) =~ /^011(\d+)$/ break=on-false Dialplan: sofia/internal/hassan@a.b.c.d Action set(effective_caller_id_number=${outbound_caller_id_number}) Dialplan: sofia/internal/hassan@a.b.c.d Action set(effective_caller_id_name=${outbound_caller_id_name}) Dialplan: sofia/internal/hassan@a.b.c.d Action bridge(sofia/external/1234567890@sky189) 2010-08-04 13:06:48.858888 [DEBUG] switch_core_state_machine.c:119 (sofia/internal/hassan@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@a.b.c.d [BREAK] 2010-08-04 13:06:48.858888 [DEBUG] switch_core_state_machine.c:341 (sofia/internal/hassan@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@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@a.b.c.d) State EXECUTE 2010-08-04 13:06:48.858888 [DEBUG] mod_sofia.c:235 sofia/internal/hassan@a.b.c.d SOFIA EXECUTE 2010-08-04 13:06:48.858888 [DEBUG] switch_core_state_machine.c:157 sofia/internal/hassan@a.b.c.d Standard EXECUTE EXECUTE sofia/internal/hassan@a.b.c.d set(effective_caller_id_number=) 2010-08-04 13:06:48.858888 [DEBUG] mod_dptools.c:854 sofia/internal/hassan@a.b.c.d SET [effective_caller_id_number]=[UNDEF] EXECUTE sofia/internal/hassan@a.b.c.d set(effective_caller_id_name=) 2010-08-04 13:06:48.858888 [DEBUG] mod_dptools.c:854 sofia/internal/hassan@a.b.c.d SET [effective_caller_id_name]=[UNDEF] EXECUTE sofia/internal/hassan@a.b.c.d bridge(sofia/external/1234567890@sky189) 2010-08-04 13:06:48.858888 [NOTICE] switch_channel.c:779 New Channel sofia/external/1234567890@sky189 [cfbd2d4f-87fc-4c59-b320-2290a5a076b3] 2010-08-04 13:06:48.858888 [DEBUG] mod_sofia.c:3892 (sofia/external/1234567890@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@sky189 [BREAK] 2010-08-04 13:06:48.858888 [DEBUG] switch_core_state_machine.c:314 (sofia/external/1234567890@sky189) Running State Change CS_INIT 2010-08-04 13:06:48.858888 [DEBUG] switch_core_state_machine.c:338 (sofia/external/1234567890@sky189) State INIT 2010-08-04 13:06:48.858888 [DEBUG] mod_sofia.c:83 sofia/external/1234567890@sky189 SOFIA INIT 2010-08-04 13:06:48.858888 [DEBUG] mod_sofia.c:119 (sofia/external/1234567890@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@sky189 [BREAK] 2010-08-04 13:06:48.858888 [DEBUG] switch_core_state_machine.c:338 (sofia/external/1234567890@sky189) State INIT going to sleep 2010-08-04 13:06:48.858888 [DEBUG] switch_core_state_machine.c:314 (sofia/external/1234567890@sky189) Running State Change CS_ROUTING 2010-08-04 13:06:48.858888 [DEBUG] switch_channel.c:1512 (sofia/external/1234567890@sky189) Callstate Change DOWN -> RINGING 2010-08-04 13:06:48.858888 [DEBUG] switch_core_state_machine.c:341 (sofia/external/1234567890@sky189) State ROUTING 2010-08-04 13:06:48.858888 [DEBUG] mod_sofia.c:142 sofia/external/1234567890@sky189 SOFIA ROUTING 2010-08-04 13:06:48.858888 [DEBUG] switch_ivr_originate.c:66 (sofia/external/1234567890@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@sky189 [BREAK] 2010-08-04 13:06:48.858888 [DEBUG] switch_core_state_machine.c:341 (sofia/external/1234567890@sky189) State ROUTING going to sleep 2010-08-04 13:06:48.858888 [DEBUG] switch_core_state_machine.c:314 (sofia/external/1234567890@sky189) Running State Change CS_CONSUME_MEDIA 2010-08-04 13:06:48.858888 [DEBUG] switch_core_state_machine.c:360 (sofia/external/1234567890@sky189) State CONSUME_MEDIA 2010-08-04 13:06:48.858888 [DEBUG] switch_core_state_machine.c:360 (sofia/external/1234567890@sky189) State CONSUME_MEDIA going to sleep 2010-08-04 13:06:48.858888 [DEBUG] sofia.c:4318 Channel sofia/external/1234567890@sky189 entering state [calling][0] 2010-08-04 13:06:48.861065 [DEBUG] sofia.c:4318 Channel sofia/external/1234567890@sky189 entering state [terminated][503] 2010-08-04 13:06:48.861065 [DEBUG] switch_channel.c:2309 (sofia/external/1234567890@sky189) Callstate Change RINGING -> HANGUP 2010-08-04 13:06:48.861065 [NOTICE] sofia.c:4932 Hangup sofia/external/1234567890@sky189 [CS_CONSUME_MEDIA] [NORMAL_TEMPORARY_FAILURE] 2010-08-04 13:06:48.861065 [DEBUG] switch_channel.c:2325 Send signal sofia/external/1234567890@sky189 [KILL] 2010-08-04 13:06:48.861065 [DEBUG] switch_core_session.c:1039 Send signal sofia/external/1234567890@sky189 [BREAK] 2010-08-04 13:06:48.861065 [DEBUG] switch_core_state_machine.c:314 (sofia/external/1234567890@sky189) Running State Change CS_HANGUP 2010-08-04 13:06:48.861065 [DEBUG] switch_core_state_machine.c:535 (sofia/external/1234567890@sky189) State HANGUP 2010-08-04 13:06:48.861065 [DEBUG] mod_sofia.c:447 sofia/external/1234567890@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@sky189 hanging up, cause: NORMAL_TEMPORARY_FAILURE 2010-08-04 13:06:48.861065 [DEBUG] switch_core_state_machine.c:46 sofia/external/1234567890@sky189 Standard HANGUP, cause: NORMAL_TEMPORARY_FAILURE 2010-08-04 13:06:48.861065 [DEBUG] switch_core_state_machine.c:535 (sofia/external/1234567890@sky189) State HANGUP going to sleep 2010-08-04 13:06:48.861065 [DEBUG] switch_core_state_machine.c:333 (sofia/external/1234567890@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@sky189 [BREAK] 2010-08-04 13:06:48.861065 [DEBUG] switch_core_state_machine.c:314 (sofia/external/1234567890@sky189) Running State Change CS_REPORTING 2010-08-04 13:06:48.861065 [DEBUG] switch_core_state_machine.c:595 (sofia/external/1234567890@sky189) State REPORTING 2010-08-04 13:06:48.861065 [DEBUG] switch_core_state_machine.c:53 sofia/external/1234567890@sky189 Standard REPORTING, cause: NORMAL_TEMPORARY_FAILURE 2010-08-04 13:06:48.861065 [DEBUG] switch_core_state_machine.c:595 (sofia/external/1234567890@sky189) State REPORTING going to sleep 2010-08-04 13:06:48.861065 [DEBUG] switch_core_state_machine.c:327 (sofia/external/1234567890@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@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@a.b.c.d) Callstate Change RINGING -> HANGUP 2010-08-04 13:06:48.861065 [NOTICE] mod_dptools.c:2456 Hangup sofia/internal/hassan@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@a.b.c.d [KILL] 2010-08-04 13:06:48.861065 [DEBUG] switch_core_session.c:1039 Send signal sofia/internal/hassan@a.b.c.d [BREAK] 2010-08-04 13:06:48.861065 [DEBUG] switch_core_session.c:1905 sofia/internal/hassan@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@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@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@a.b.c.d) State HANGUP 2010-08-04 13:06:48.861065 [DEBUG] mod_sofia.c:447 sofia/internal/hassan@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@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@sky189) Locked, Waiting on external entities 2010-08-04 13:06:48.861065 [NOTICE] switch_core_session.c:1220 Session 11 (sofia/external/1234567890@sky189) Ended 2010-08-04 13:06:48.862912 [NOTICE] switch_core_session.c:1222 Close Channel sofia/external/1234567890@sky189 [CS_DESTROY] 2010-08-04 13:06:48.862912 [DEBUG] switch_core_state_machine.c:427 (sofia/external/1234567890@sky189) Callstate Change HANGUP -> DOWN 2010-08-04 13:06:48.862912 [DEBUG] switch_core_state_machine.c:430 (sofia/external/1234567890@sky189) Running State Change CS_DESTROY 2010-08-04 13:06:48.862912 [DEBUG] switch_core_state_machine.c:440 (sofia/external/1234567890@sky189) State DESTROY 2010-08-04 13:06:48.862912 [DEBUG] mod_sofia.c:358 sofia/external/1234567890@sky189 SOFIA DESTROY 2010-08-04 13:06:48.862912 [DEBUG] switch_core_state_machine.c:60 sofia/external/1234567890@sky189 Standard DESTROY 2010-08-04 13:06:48.862912 [DEBUG] switch_core_state_machine.c:440 (sofia/external/1234567890@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@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@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@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@a.b.c.d [BREAK] 2010-08-04 13:06:48.864893 [DEBUG] switch_core_state_machine.c:314 (sofia/internal/hassan@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@a.b.c.d) State REPORTING 2010-08-04 13:06:48.864893 [DEBUG] switch_core_state_machine.c:53 sofia/internal/hassan@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@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@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@a.b.c.d [BREAK] 2010-08-04 13:06:48.864893 [DEBUG] switch_core_session.c:1202 Session 10 (sofia/internal/hassan@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@a.b.c.d) Ended 2010-08-04 13:06:48.864893 [NOTICE] switch_core_session.c:1222 Close Channel sofia/internal/hassan@a.b.c.d [CS_DESTROY] 2010-08-04 13:06:48.864893 [DEBUG] switch_core_state_machine.c:427 (sofia/internal/hassan@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@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@a.b.c.d) State DESTROY 2010-08-04 13:06:48.866921 [DEBUG] mod_sofia.c:358 sofia/internal/hassan@a.b.c.d SOFIA DESTROY 2010-08-04 13:06:48.866921 [DEBUG] switch_core_state_machine.c:60 sofia/internal/hassan@a.b.c.d Standard DESTROY 2010-08-04 13:06:48.866921 [DEBUG] switch_core_state_machine.c:440 (sofia/internal/hassan@a.b.c.d) State DESTROY going to sleep _______________________________________________ FreeSWITCH-users mailing list FreeSWITCH-users@lists.freeswitch.org<mailto: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 _______________________________________________ FreeSWITCH-users mailing list FreeSWITCH-users@lists.freeswitch.org<mailto: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 _______________________________________________ FreeSWITCH-users mailing list FreeSWITCH-users@lists.freeswitch.org<mailto: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 _______________________________________________ FreeSWITCH-users mailing list FreeSWITCH-users@lists.freeswitch.org<mailto: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:4c5ac2e032932114784393!
I have certainly reloaded the profile. Did a full FS restart too. The problem is not about registration. Coz, FS does not register at all when "registration" is set to "false". But, when FS tries to send the call, it appends the user/pass in the call setup message. For example, we have an asterisk box doing SS7 to a telco. We just added the FS as a "peer" and it shows up in the "sip show peers" output. But, when sending calls from FS, Asterisk says cannot authenticate "user/pass@<FS IP>". Regards HASSAN On Thu, Aug 5, 2010 at 20:06, Peter Olsson <peter.olsson@visionutveckling.se
wrote:
Have you reloaded the sip profile? I'm using this syntax for lots of gateways, and they never tries to register.
/Peter ________________________________________ Från: freeswitch-users-bounces@lists.freeswitch.org [ freeswitch-users-bounces@lists.freeswitch.org] för Nyamul Hassan [ mnhassan@usa.net] Skickat: den 5 augusti 2010 15:47 Till: FreeSWITCH Users Help Ämne: Re: [Freeswitch-users] Help on reading the log better
I've set the "registration" to false, but whenever FS attempts to call the gateway, it tries to send the call using the user/pass given. For some switches, that also messes up the CallerID.
I'm using the "non-gateway" format for now, and it works.
Thanks to everyone for their help.
Regards HASSAN
On Thu, Aug 5, 2010 at 16:16, Steven Ayre <steveayre@gmail.com<mailto: steveayre@gmail.com>> wrote: As already mentioned, one is required.
But it's only used if the gateway gives a 401 Not Authorized response. If you don't need authentication, just make one up.
-Steve
On 5 August 2010 10:09, Nyamul Hassan <mnhassan@usa.net<mailto: mnhassan@usa.net>> wrote: 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@gmail.com<mailto: steveayre@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@sky189 entering state [calling][0] 2010-08-04 13:06:48.861065 [DEBUG] sofia.c:4318 Channel sofia/external/1234567890@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@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@usa.net<mailto: mnhassan@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@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@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@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@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@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@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@a.b.c.d [BREAK] 2010-08-04 13:06:48.856895 [DEBUG] switch_core_state_machine.c:314 (sofia/internal/hassan@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@a.b.c.d) State INIT 2010-08-04 13:06:48.856895 [DEBUG] mod_sofia.c:83 sofia/internal/hassan@a.b.c.d SOFIA INIT 2010-08-04 13:06:48.856895 [DEBUG] mod_sofia.c:119 (sofia/internal/hassan@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@a.b.c.d [BREAK] 2010-08-04 13:06:48.856895 [DEBUG] switch_core_state_machine.c:338 (sofia/internal/hassan@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@a.b.c.d) Running State Change CS_ROUTING 2010-08-04 13:06:48.856895 [DEBUG] switch_channel.c:1512 (sofia/internal/hassan@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@a.b.c.d) State ROUTING 2010-08-04 13:06:48.856895 [DEBUG] mod_sofia.c:142 sofia/internal/hassan@a.b.c.d SOFIA ROUTING 2010-08-04 13:06:48.856895 [DEBUG] switch_core_state_machine.c:77 sofia/internal/hassan@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@a.b.c.d parsing [sky189->dial_sky189] continue=false Dialplan: sofia/internal/hassan@a.b.c.d Regex (PASS) [dial_sky189] destination_number(0111234567890) =~ /^011(\d+)$/ break=on-false Dialplan: sofia/internal/hassan@a.b.c.d Action set(effective_caller_id_number=${outbound_caller_id_number}) Dialplan: sofia/internal/hassan@a.b.c.d Action set(effective_caller_id_name=${outbound_caller_id_name}) Dialplan: sofia/internal/hassan@a.b.c.d Action bridge(sofia/external/1234567890@sky189) 2010-08-04 13:06:48.858888 [DEBUG] switch_core_state_machine.c:119 (sofia/internal/hassan@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@a.b.c.d [BREAK] 2010-08-04 13:06:48.858888 [DEBUG] switch_core_state_machine.c:341 (sofia/internal/hassan@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@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@a.b.c.d) State EXECUTE 2010-08-04 13:06:48.858888 [DEBUG] mod_sofia.c:235 sofia/internal/hassan@a.b.c.d SOFIA EXECUTE 2010-08-04 13:06:48.858888 [DEBUG] switch_core_state_machine.c:157 sofia/internal/hassan@a.b.c.d Standard EXECUTE EXECUTE sofia/internal/hassan@a.b.c.d set(effective_caller_id_number=) 2010-08-04 13:06:48.858888 [DEBUG] mod_dptools.c:854 sofia/internal/hassan@a.b.c.d SET [effective_caller_id_number]=[UNDEF] EXECUTE sofia/internal/hassan@a.b.c.d set(effective_caller_id_name=) 2010-08-04 13:06:48.858888 [DEBUG] mod_dptools.c:854 sofia/internal/hassan@a.b.c.d SET [effective_caller_id_name]=[UNDEF] EXECUTE sofia/internal/hassan@a.b.c.dbridge(sofia/external/1234567890@sky189 ) 2010-08-04 13:06:48.858888 [NOTICE] switch_channel.c:779 New Channel sofia/external/1234567890@sky189 [cfbd2d4f-87fc-4c59-b320-2290a5a076b3] 2010-08-04 13:06:48.858888 [DEBUG] mod_sofia.c:3892 (sofia/external/1234567890@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@sky189 [BREAK] 2010-08-04 13:06:48.858888 [DEBUG] switch_core_state_machine.c:314 (sofia/external/1234567890@sky189) Running State Change CS_INIT 2010-08-04 13:06:48.858888 [DEBUG] switch_core_state_machine.c:338 (sofia/external/1234567890@sky189) State INIT 2010-08-04 13:06:48.858888 [DEBUG] mod_sofia.c:83 sofia/external/1234567890@sky189 SOFIA INIT 2010-08-04 13:06:48.858888 [DEBUG] mod_sofia.c:119 (sofia/external/1234567890@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@sky189 [BREAK] 2010-08-04 13:06:48.858888 [DEBUG] switch_core_state_machine.c:338 (sofia/external/1234567890@sky189) State INIT going to sleep 2010-08-04 13:06:48.858888 [DEBUG] switch_core_state_machine.c:314 (sofia/external/1234567890@sky189) Running State Change CS_ROUTING 2010-08-04 13:06:48.858888 [DEBUG] switch_channel.c:1512 (sofia/external/1234567890@sky189) Callstate Change DOWN -> RINGING 2010-08-04 13:06:48.858888 [DEBUG] switch_core_state_machine.c:341 (sofia/external/1234567890@sky189) State ROUTING 2010-08-04 13:06:48.858888 [DEBUG] mod_sofia.c:142 sofia/external/1234567890@sky189 SOFIA ROUTING 2010-08-04 13:06:48.858888 [DEBUG] switch_ivr_originate.c:66 (sofia/external/1234567890@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@sky189 [BREAK] 2010-08-04 13:06:48.858888 [DEBUG] switch_core_state_machine.c:341 (sofia/external/1234567890@sky189) State ROUTING going to sleep 2010-08-04 13:06:48.858888 [DEBUG] switch_core_state_machine.c:314 (sofia/external/1234567890@sky189) Running State Change CS_CONSUME_MEDIA 2010-08-04 13:06:48.858888 [DEBUG] switch_core_state_machine.c:360 (sofia/external/1234567890@sky189) State CONSUME_MEDIA 2010-08-04 13:06:48.858888 [DEBUG] switch_core_state_machine.c:360 (sofia/external/1234567890@sky189) State CONSUME_MEDIA going to sleep 2010-08-04 13:06:48.858888 [DEBUG] sofia.c:4318 Channel sofia/external/1234567890@sky189 entering state [calling][0] 2010-08-04 13:06:48.861065 [DEBUG] sofia.c:4318 Channel sofia/external/1234567890@sky189 entering state [terminated][503] 2010-08-04 13:06:48.861065 [DEBUG] switch_channel.c:2309 (sofia/external/1234567890@sky189) Callstate Change RINGING -> HANGUP 2010-08-04 13:06:48.861065 [NOTICE] sofia.c:4932 Hangup sofia/external/1234567890@sky189 [CS_CONSUME_MEDIA] [NORMAL_TEMPORARY_FAILURE] 2010-08-04 13:06:48.861065 [DEBUG] switch_channel.c:2325 Send signal sofia/external/1234567890@sky189 [KILL] 2010-08-04 13:06:48.861065 [DEBUG] switch_core_session.c:1039 Send signal sofia/external/1234567890@sky189 [BREAK] 2010-08-04 13:06:48.861065 [DEBUG] switch_core_state_machine.c:314 (sofia/external/1234567890@sky189) Running State Change CS_HANGUP 2010-08-04 13:06:48.861065 [DEBUG] switch_core_state_machine.c:535 (sofia/external/1234567890@sky189) State HANGUP 2010-08-04 13:06:48.861065 [DEBUG] mod_sofia.c:447 sofia/external/1234567890@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@sky189 hanging up, cause: NORMAL_TEMPORARY_FAILURE 2010-08-04 13:06:48.861065 [DEBUG] switch_core_state_machine.c:46 sofia/external/1234567890@sky189 Standard HANGUP, cause: NORMAL_TEMPORARY_FAILURE 2010-08-04 13:06:48.861065 [DEBUG] switch_core_state_machine.c:535 (sofia/external/1234567890@sky189) State HANGUP going to sleep 2010-08-04 13:06:48.861065 [DEBUG] switch_core_state_machine.c:333 (sofia/external/1234567890@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@sky189 [BREAK] 2010-08-04 13:06:48.861065 [DEBUG] switch_core_state_machine.c:314 (sofia/external/1234567890@sky189) Running State Change CS_REPORTING 2010-08-04 13:06:48.861065 [DEBUG] switch_core_state_machine.c:595 (sofia/external/1234567890@sky189) State REPORTING 2010-08-04 13:06:48.861065 [DEBUG] switch_core_state_machine.c:53 sofia/external/1234567890@sky189 Standard REPORTING, cause: NORMAL_TEMPORARY_FAILURE 2010-08-04 13:06:48.861065 [DEBUG] switch_core_state_machine.c:595 (sofia/external/1234567890@sky189) State REPORTING going to sleep 2010-08-04 13:06:48.861065 [DEBUG] switch_core_state_machine.c:327 (sofia/external/1234567890@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@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@a.b.c.d) Callstate Change RINGING -> HANGUP 2010-08-04 13:06:48.861065 [NOTICE] mod_dptools.c:2456 Hangup sofia/internal/hassan@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@a.b.c.d [KILL] 2010-08-04 13:06:48.861065 [DEBUG] switch_core_session.c:1039 Send signal sofia/internal/hassan@a.b.c.d [BREAK] 2010-08-04 13:06:48.861065 [DEBUG] switch_core_session.c:1905 sofia/internal/hassan@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@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@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@a.b.c.d) State HANGUP 2010-08-04 13:06:48.861065 [DEBUG] mod_sofia.c:447 sofia/internal/hassan@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@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@sky189) Locked, Waiting on external entities 2010-08-04 13:06:48.861065 [NOTICE] switch_core_session.c:1220 Session 11 (sofia/external/1234567890@sky189) Ended 2010-08-04 13:06:48.862912 [NOTICE] switch_core_session.c:1222 Close Channel sofia/external/1234567890@sky189 [CS_DESTROY] 2010-08-04 13:06:48.862912 [DEBUG] switch_core_state_machine.c:427 (sofia/external/1234567890@sky189) Callstate Change HANGUP -> DOWN 2010-08-04 13:06:48.862912 [DEBUG] switch_core_state_machine.c:430 (sofia/external/1234567890@sky189) Running State Change CS_DESTROY 2010-08-04 13:06:48.862912 [DEBUG] switch_core_state_machine.c:440 (sofia/external/1234567890@sky189) State DESTROY 2010-08-04 13:06:48.862912 [DEBUG] mod_sofia.c:358 sofia/external/1234567890@sky189 SOFIA DESTROY 2010-08-04 13:06:48.862912 [DEBUG] switch_core_state_machine.c:60 sofia/external/1234567890@sky189 Standard DESTROY 2010-08-04 13:06:48.862912 [DEBUG] switch_core_state_machine.c:440 (sofia/external/1234567890@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@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@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@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@a.b.c.d [BREAK] 2010-08-04 13:06:48.864893 [DEBUG] switch_core_state_machine.c:314 (sofia/internal/hassan@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@a.b.c.d) State REPORTING 2010-08-04 13:06:48.864893 [DEBUG] switch_core_state_machine.c:53 sofia/internal/hassan@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@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@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@a.b.c.d [BREAK] 2010-08-04 13:06:48.864893 [DEBUG] switch_core_session.c:1202 Session 10 (sofia/internal/hassan@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@a.b.c.d) Ended 2010-08-04 13:06:48.864893 [NOTICE] switch_core_session.c:1222 Close Channel sofia/internal/hassan@a.b.c.d [CS_DESTROY] 2010-08-04 13:06:48.864893 [DEBUG] switch_core_state_machine.c:427 (sofia/internal/hassan@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@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@a.b.c.d) State DESTROY 2010-08-04 13:06:48.866921 [DEBUG] mod_sofia.c:358 sofia/internal/hassan@a.b.c.d SOFIA DESTROY 2010-08-04 13:06:48.866921 [DEBUG] switch_core_state_machine.c:60 sofia/internal/hassan@a.b.c.d Standard DESTROY 2010-08-04 13:06:48.866921 [DEBUG] switch_core_state_machine.c:440 (sofia/internal/hassan@a.b.c.d) State DESTROY going to sleep
_______________________________________________ FreeSWITCH-users mailing list FreeSWITCH-users@lists.freeswitch.org<mailto: 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
_______________________________________________ FreeSWITCH-users mailing list FreeSWITCH-users@lists.freeswitch.org<mailto: 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
_______________________________________________ FreeSWITCH-users mailing list FreeSWITCH-users@lists.freeswitch.org<mailto: 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
_______________________________________________ FreeSWITCH-users mailing list FreeSWITCH-users@lists.freeswitch.org<mailto: 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:4c5ac2e032932114784393!
_______________________________________________ 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
On Thu, Aug 5, 2010 at 9:55 AM, Nyamul Hassan <mnhassan@usa.net> wrote:
I have certainly reloaded the profile. Did a full FS restart too. The problem is not about registration. Coz, FS does not register at all when "registration" is set to "false".
But, when FS tries to send the call, it appends the user/pass in the call setup message. For example, we have an asterisk box doing SS7 to a telco. We just added the FS as a "peer" and it shows up in the "sip show peers" output. But, when sending calls from FS, Asterisk says cannot authenticate "user/pass@<FS IP>".
Sounds like you found the problem: Authentication. It looks like Ast is trying to auth the call and the gateway is responding with whatever you put in for the username and password. Were you not expecting Asterisk to challenge the calls? (Don't forget: there is a difference between registration and authentication. Buy the FreeSWITCH book and read chapter four. :P ) -MC
Try configuring your gateway like this: <gateway name="gw01"> <param name="realm" value="a.b.c.d"/> <param name="username" value="fakeuser"/> <param name="password" value="fakepass"/> <param name="register" value="false"/> <param name="caller-id-in-from" value="true"/> </gateway> The gateway has benefits over sending direct to a IP - FS monitors the gateway and stops sending traffic if the gateway is offline, resulting in your calls failing quickly (and possibly trying another route) rather than calls starting to the offline gateway but then timing out. -Steve On 5 August 2010 15:55, Nyamul Hassan <mnhassan@usa.net> wrote:
I have certainly reloaded the profile. Did a full FS restart too. The problem is not about registration. Coz, FS does not register at all when "registration" is set to "false".
But, when FS tries to send the call, it appends the user/pass in the call setup message. For example, we have an asterisk box doing SS7 to a telco. We just added the FS as a "peer" and it shows up in the "sip show peers" output. But, when sending calls from FS, Asterisk says cannot authenticate "user/pass@<FS IP>".
Regards HASSAN
On Thu, Aug 5, 2010 at 20:06, Peter Olsson < peter.olsson@visionutveckling.se> wrote:
Have you reloaded the sip profile? I'm using this syntax for lots of gateways, and they never tries to register.
/Peter ________________________________________ Från: freeswitch-users-bounces@lists.freeswitch.org [ freeswitch-users-bounces@lists.freeswitch.org] för Nyamul Hassan [ mnhassan@usa.net] Skickat: den 5 augusti 2010 15:47 Till: FreeSWITCH Users Help Ämne: Re: [Freeswitch-users] Help on reading the log better
I've set the "registration" to false, but whenever FS attempts to call the gateway, it tries to send the call using the user/pass given. For some switches, that also messes up the CallerID.
I'm using the "non-gateway" format for now, and it works.
Thanks to everyone for their help.
Regards HASSAN
On Thu, Aug 5, 2010 at 16:16, Steven Ayre <steveayre@gmail.com<mailto: steveayre@gmail.com>> wrote: As already mentioned, one is required.
But it's only used if the gateway gives a 401 Not Authorized response. If you don't need authentication, just make one up.
-Steve
On 5 August 2010 10:09, Nyamul Hassan <mnhassan@usa.net<mailto: mnhassan@usa.net>> wrote: 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@gmail.com<mailto: steveayre@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@sky189 entering state [calling][0] 2010-08-04 13:06:48.861065 [DEBUG] sofia.c:4318 Channel sofia/external/1234567890@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@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@usa.net<mailto: mnhassan@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@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@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@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@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@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@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@a.b.c.d [BREAK] 2010-08-04 13:06:48.856895 [DEBUG] switch_core_state_machine.c:314 (sofia/internal/hassan@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@a.b.c.d) State INIT 2010-08-04 13:06:48.856895 [DEBUG] mod_sofia.c:83 sofia/internal/hassan@a.b.c.d SOFIA INIT 2010-08-04 13:06:48.856895 [DEBUG] mod_sofia.c:119 (sofia/internal/hassan@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@a.b.c.d [BREAK] 2010-08-04 13:06:48.856895 [DEBUG] switch_core_state_machine.c:338 (sofia/internal/hassan@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@a.b.c.d) Running State Change CS_ROUTING 2010-08-04 13:06:48.856895 [DEBUG] switch_channel.c:1512 (sofia/internal/hassan@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@a.b.c.d) State ROUTING 2010-08-04 13:06:48.856895 [DEBUG] mod_sofia.c:142 sofia/internal/hassan@a.b.c.d SOFIA ROUTING 2010-08-04 13:06:48.856895 [DEBUG] switch_core_state_machine.c:77 sofia/internal/hassan@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@a.b.c.d parsing [sky189->dial_sky189] continue=false Dialplan: sofia/internal/hassan@a.b.c.d Regex (PASS) [dial_sky189] destination_number(0111234567890) =~ /^011(\d+)$/ break=on-false Dialplan: sofia/internal/hassan@a.b.c.d Action set(effective_caller_id_number=${outbound_caller_id_number}) Dialplan: sofia/internal/hassan@a.b.c.d Action set(effective_caller_id_name=${outbound_caller_id_name}) Dialplan: sofia/internal/hassan@a.b.c.d Action bridge(sofia/external/1234567890@sky189) 2010-08-04 13:06:48.858888 [DEBUG] switch_core_state_machine.c:119 (sofia/internal/hassan@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@a.b.c.d [BREAK] 2010-08-04 13:06:48.858888 [DEBUG] switch_core_state_machine.c:341 (sofia/internal/hassan@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@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@a.b.c.d) State EXECUTE 2010-08-04 13:06:48.858888 [DEBUG] mod_sofia.c:235 sofia/internal/hassan@a.b.c.d SOFIA EXECUTE 2010-08-04 13:06:48.858888 [DEBUG] switch_core_state_machine.c:157 sofia/internal/hassan@a.b.c.d Standard EXECUTE EXECUTE sofia/internal/hassan@a.b.c.d set(effective_caller_id_number=) 2010-08-04 13:06:48.858888 [DEBUG] mod_dptools.c:854 sofia/internal/hassan@a.b.c.d SET [effective_caller_id_number]=[UNDEF] EXECUTE sofia/internal/hassan@a.b.c.d set(effective_caller_id_name=) 2010-08-04 13:06:48.858888 [DEBUG] mod_dptools.c:854 sofia/internal/hassan@a.b.c.d SET [effective_caller_id_name]=[UNDEF] EXECUTE sofia/internal/hassan@a.b.c.dbridge(sofia/external/1234567890@sky189 ) 2010-08-04 13:06:48.858888 [NOTICE] switch_channel.c:779 New Channel sofia/external/1234567890@sky189 [cfbd2d4f-87fc-4c59-b320-2290a5a076b3] 2010-08-04 13:06:48.858888 [DEBUG] mod_sofia.c:3892 (sofia/external/1234567890@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@sky189 [BREAK] 2010-08-04 13:06:48.858888 [DEBUG] switch_core_state_machine.c:314 (sofia/external/1234567890@sky189) Running State Change CS_INIT 2010-08-04 13:06:48.858888 [DEBUG] switch_core_state_machine.c:338 (sofia/external/1234567890@sky189) State INIT 2010-08-04 13:06:48.858888 [DEBUG] mod_sofia.c:83 sofia/external/1234567890@sky189 SOFIA INIT 2010-08-04 13:06:48.858888 [DEBUG] mod_sofia.c:119 (sofia/external/1234567890@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@sky189 [BREAK] 2010-08-04 13:06:48.858888 [DEBUG] switch_core_state_machine.c:338 (sofia/external/1234567890@sky189) State INIT going to sleep 2010-08-04 13:06:48.858888 [DEBUG] switch_core_state_machine.c:314 (sofia/external/1234567890@sky189) Running State Change CS_ROUTING 2010-08-04 13:06:48.858888 [DEBUG] switch_channel.c:1512 (sofia/external/1234567890@sky189) Callstate Change DOWN -> RINGING 2010-08-04 13:06:48.858888 [DEBUG] switch_core_state_machine.c:341 (sofia/external/1234567890@sky189) State ROUTING 2010-08-04 13:06:48.858888 [DEBUG] mod_sofia.c:142 sofia/external/1234567890@sky189 SOFIA ROUTING 2010-08-04 13:06:48.858888 [DEBUG] switch_ivr_originate.c:66 (sofia/external/1234567890@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@sky189 [BREAK] 2010-08-04 13:06:48.858888 [DEBUG] switch_core_state_machine.c:341 (sofia/external/1234567890@sky189) State ROUTING going to sleep 2010-08-04 13:06:48.858888 [DEBUG] switch_core_state_machine.c:314 (sofia/external/1234567890@sky189) Running State Change CS_CONSUME_MEDIA 2010-08-04 13:06:48.858888 [DEBUG] switch_core_state_machine.c:360 (sofia/external/1234567890@sky189) State CONSUME_MEDIA 2010-08-04 13:06:48.858888 [DEBUG] switch_core_state_machine.c:360 (sofia/external/1234567890@sky189) State CONSUME_MEDIA going to sleep 2010-08-04 13:06:48.858888 [DEBUG] sofia.c:4318 Channel sofia/external/1234567890@sky189 entering state [calling][0] 2010-08-04 13:06:48.861065 [DEBUG] sofia.c:4318 Channel sofia/external/1234567890@sky189 entering state [terminated][503] 2010-08-04 13:06:48.861065 [DEBUG] switch_channel.c:2309 (sofia/external/1234567890@sky189) Callstate Change RINGING -> HANGUP 2010-08-04 13:06:48.861065 [NOTICE] sofia.c:4932 Hangup sofia/external/1234567890@sky189 [CS_CONSUME_MEDIA] [NORMAL_TEMPORARY_FAILURE] 2010-08-04 13:06:48.861065 [DEBUG] switch_channel.c:2325 Send signal sofia/external/1234567890@sky189 [KILL] 2010-08-04 13:06:48.861065 [DEBUG] switch_core_session.c:1039 Send signal sofia/external/1234567890@sky189 [BREAK] 2010-08-04 13:06:48.861065 [DEBUG] switch_core_state_machine.c:314 (sofia/external/1234567890@sky189) Running State Change CS_HANGUP 2010-08-04 13:06:48.861065 [DEBUG] switch_core_state_machine.c:535 (sofia/external/1234567890@sky189) State HANGUP 2010-08-04 13:06:48.861065 [DEBUG] mod_sofia.c:447 sofia/external/1234567890@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@sky189 hanging up, cause: NORMAL_TEMPORARY_FAILURE 2010-08-04 13:06:48.861065 [DEBUG] switch_core_state_machine.c:46 sofia/external/1234567890@sky189 Standard HANGUP, cause: NORMAL_TEMPORARY_FAILURE 2010-08-04 13:06:48.861065 [DEBUG] switch_core_state_machine.c:535 (sofia/external/1234567890@sky189) State HANGUP going to sleep 2010-08-04 13:06:48.861065 [DEBUG] switch_core_state_machine.c:333 (sofia/external/1234567890@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@sky189 [BREAK] 2010-08-04 13:06:48.861065 [DEBUG] switch_core_state_machine.c:314 (sofia/external/1234567890@sky189) Running State Change CS_REPORTING 2010-08-04 13:06:48.861065 [DEBUG] switch_core_state_machine.c:595 (sofia/external/1234567890@sky189) State REPORTING 2010-08-04 13:06:48.861065 [DEBUG] switch_core_state_machine.c:53 sofia/external/1234567890@sky189 Standard REPORTING, cause: NORMAL_TEMPORARY_FAILURE 2010-08-04 13:06:48.861065 [DEBUG] switch_core_state_machine.c:595 (sofia/external/1234567890@sky189) State REPORTING going to sleep 2010-08-04 13:06:48.861065 [DEBUG] switch_core_state_machine.c:327 (sofia/external/1234567890@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@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@a.b.c.d) Callstate Change RINGING -> HANGUP 2010-08-04 13:06:48.861065 [NOTICE] mod_dptools.c:2456 Hangup sofia/internal/hassan@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@a.b.c.d [KILL] 2010-08-04 13:06:48.861065 [DEBUG] switch_core_session.c:1039 Send signal sofia/internal/hassan@a.b.c.d [BREAK] 2010-08-04 13:06:48.861065 [DEBUG] switch_core_session.c:1905 sofia/internal/hassan@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@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@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@a.b.c.d) State HANGUP 2010-08-04 13:06:48.861065 [DEBUG] mod_sofia.c:447 sofia/internal/hassan@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@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@sky189) Locked, Waiting on external entities 2010-08-04 13:06:48.861065 [NOTICE] switch_core_session.c:1220 Session 11 (sofia/external/1234567890@sky189) Ended 2010-08-04 13:06:48.862912 [NOTICE] switch_core_session.c:1222 Close Channel sofia/external/1234567890@sky189 [CS_DESTROY] 2010-08-04 13:06:48.862912 [DEBUG] switch_core_state_machine.c:427 (sofia/external/1234567890@sky189) Callstate Change HANGUP -> DOWN 2010-08-04 13:06:48.862912 [DEBUG] switch_core_state_machine.c:430 (sofia/external/1234567890@sky189) Running State Change CS_DESTROY 2010-08-04 13:06:48.862912 [DEBUG] switch_core_state_machine.c:440 (sofia/external/1234567890@sky189) State DESTROY 2010-08-04 13:06:48.862912 [DEBUG] mod_sofia.c:358 sofia/external/1234567890@sky189 SOFIA DESTROY 2010-08-04 13:06:48.862912 [DEBUG] switch_core_state_machine.c:60 sofia/external/1234567890@sky189 Standard DESTROY 2010-08-04 13:06:48.862912 [DEBUG] switch_core_state_machine.c:440 (sofia/external/1234567890@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@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@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@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@a.b.c.d [BREAK] 2010-08-04 13:06:48.864893 [DEBUG] switch_core_state_machine.c:314 (sofia/internal/hassan@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@a.b.c.d) State REPORTING 2010-08-04 13:06:48.864893 [DEBUG] switch_core_state_machine.c:53 sofia/internal/hassan@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@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@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@a.b.c.d [BREAK] 2010-08-04 13:06:48.864893 [DEBUG] switch_core_session.c:1202 Session 10 (sofia/internal/hassan@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@a.b.c.d) Ended 2010-08-04 13:06:48.864893 [NOTICE] switch_core_session.c:1222 Close Channel sofia/internal/hassan@a.b.c.d [CS_DESTROY] 2010-08-04 13:06:48.864893 [DEBUG] switch_core_state_machine.c:427 (sofia/internal/hassan@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@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@a.b.c.d) State DESTROY 2010-08-04 13:06:48.866921 [DEBUG] mod_sofia.c:358 sofia/internal/hassan@a.b.c.d SOFIA DESTROY 2010-08-04 13:06:48.866921 [DEBUG] switch_core_state_machine.c:60 sofia/internal/hassan@a.b.c.d Standard DESTROY 2010-08-04 13:06:48.866921 [DEBUG] switch_core_state_machine.c:440 (sofia/internal/hassan@a.b.c.d) State DESTROY going to sleep
_______________________________________________ FreeSWITCH-users mailing list FreeSWITCH-users@lists.freeswitch.org<mailto: 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
_______________________________________________ FreeSWITCH-users mailing list FreeSWITCH-users@lists.freeswitch.org<mailto: 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
_______________________________________________ FreeSWITCH-users mailing list FreeSWITCH-users@lists.freeswitch.org<mailto: 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
_______________________________________________ FreeSWITCH-users mailing list FreeSWITCH-users@lists.freeswitch.org<mailto: 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:4c5ac2e032932114784393!
_______________________________________________ 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
_______________________________________________ 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
participants (5)
-
Giovanni Maruzzelli
-
Michael Collins
-
Nyamul Hassan
-
Peter Olsson
-
Steven Ayre