Your call is being rejected with 488 Not Acceptable Here. That means a codec error - the client isn't offerring any of the codecs you've configured FreeSWITCH to accept. Such calls get rejected immediately, before hitting the dialplan (unless using late-negotiation).

Incidentally, don't use the sofia stack logging (sofia loglevel). Use the FreeSWITCH logging ("/log debug" in fs_cli). The sofia stack is rather verbose and unreadable, and doesn't tell you anything about what FreeSWITCH is doing at the higher level. Looking inside the stack is something to do if the FreeSWITCH log isn't showing you the error. The FreeSWITCH log'll show the SDP and the codec negotiation, so you'll see the error there.



On 29 November 2014 at 18:15, Zoltán Szabó <zoell@zoell.us> wrote:
Hi,

I have a multi tenant multi domain setup. For some reasons my FS won't try to request the dialplan configuration.

xml_curl:
<configuration name="xml_curl.conf" description="cURL XML Gateway">
  <bindings>
    <binding name="dialplan">
      <param name="gateway-url" value="http://192.168.0.15:8080/ccc-provider/GetDialplan" bindings="dialplan"/>
    </binding>
    <binding name="directory">
      <param name="gateway-url" value="http://192.168.0.15:8080/ccc-provider/GetDirectory" bindings="directory"/>
    </binding>
    <binding name="configuration">
      <param name="gateway-url" value="http://192.168.0.15:8080/ccc-provider/GetConfiguration" bindings="configuration"/>
    </binding>
  </bindings>
</configuration>



My sofia conf that I send through xml_curl upon request:
<document type="freeswitch/xml">
    <section name="configuration">
        <configuration name='sofia.conf' description='sofia endpoint'>
            <global_settings>
                <param name="log-level" value="9"/>
                <param name="debug" value="9"/>
                <param name="auto-restart" value="true"/>
                <param name="debug-presence" value="0"/>
                <param name='accept-blind-reg' value='false'/>
                <param name="sip-trace" value="no"/>
                <param name="sip-capture" value="no"/>
                <param name="auth-calls" value="false"/>
                <param name="dtmf-type" value="rfc2833"/>
            </global_settings>
            <profiles>
                    <profile name='MainCCSIP'>
                        <domains>
                                <domain name="d.1.c.domain.com" alias="false" parse="false"/>
                                <domain name="d.2.c.domain.com" alias="false" parse="false"/>
                        </domains>
                        <settings>
                            <param name="odbc-dsn" value=""/>
                            <param name="manage-presence" value="true"/>
                            <param name="dbname" value="shere_presence"/>
                            <param name="presence-hosts" value="_DISABLED_"/>
                            <param name="send-presence-on-register" value="true"/>
                            <param name="delete-subs-on-register" value="true"/>
                            <param name="caller-id-type" value="rpid"/>
                            <param name="auto-jitterbuffer-msec" value="1000"/>
                            <param name="user-agent-string" value="pbx"/>

                            <param name='dialplan' value='XML'/>
                            <param name="ext-rtp-ip" value="auto"/>
                            <param name="ext-sip-ip" value="auto"/>
                            <param name='rtp-ip' value='auto'/>
                            <param name='sip-ip' value='auto'/>
                            <param name='sip-port' value='5060'/>
                            <param name='nonce-ttl' value=''/>
                            <param name='rtp-timer-name' value='soft'/>
                            <param name='codec-prefs' value='"/>
                            <param name="rtp-timeout-sec" value="300"/>
                            <param name="rtp-hold-timeout-sec" value="1800"/>
                            <param name='rfc2833-pt' value='101'/>
                            <param name='dtmf-duration' value='100'/>
                            <param name="dtmf-type" value=""/>
                            <param name='codec-ms' value='20'/>
                            <param name='accept-blind-reg' value='false'/>
                            <param name='auth-calls' value='false'/>
                            <param name="enable-100rel" value="true"/>
                            <param name="multiple-registrations" value="contact"/>
                            <param name="minimum-session-expires" value="120"/>
                            <param name="mailer-app" value="/usr/local/freeswitch/script/emailvm.py"/>
                            <param name="mailer-app-args" value="-i -d -f voicemail@domain.org -t"/>
                            <param name='accept-blind-reg' value='false'/>
                            <param name='disable-register' value='false'/>
                            <param name='log-auth-failures' value='true'/>
                            <param name='auth-all-packets' value='false'/>
                            <param name="mailer-app" value="/usr/local/freeswitch/scripts/emailvm.py"/>
                            <param name="mailer-app-args" value="-i -d -f voicemail@domain.org -t"/>
                        </settings>
                        <gateways>
                        <gateway name='gateway-1.d.1.c.domain.com'>
                            <variables>
                                <variable name="inbound_var_name"  data="inbound_call=true"  direction="inbound"/>
                                <variable name="outbound_var_name" data="outbound_call=true" direction="outbound"/>
                                <variable name="both_var_name"     data="gw=gwname"/>
                            </variables>
                            <param name='username' value='username'/>
                            <param name='password' value='password'/>
                            <param name="realm" value="sip.voip.com"/>
                            <param name="expire-seconds" value="600"/>
                            <param name='register' value='true'/>
                            <param name="register-transport" value="udp"/>
                            <param name='retry-seconds' value='30'/>
                            <param name="ping" value="60"/>
                            <param name='register' value='true'/>
                        </gateway>
                        </gateways>
                    </profile>
            </profiles>
        </configuration>
    </section>
</document>


My user directory looks like this:

User 1000 at domain 1:
<document type="freeswitch/xml">
    <section name="directory">
        <domain name='d.1.c.domain.com'>
        
        <params>
            <param name="dial-string" value="{presence_id=${dialed_user}@${dialed_domain}}${sofia_contact(${dialed_user}@${dialed_domain})}"/>
        </params>
        
    <variables>
      <variable name="record_stereo" value="true"/>
      <variable name="transfer_fallback_extension" value="operator"/>
      <variable name="user_context" value="d.1.c.domain.com"/>
    </variables>
        
        <groups>
            <group name="d.1.c.domain.com">
                    <users>
                                <user id='1000' mailbox='1000'>
                                    <params>
                                        <param name='password' value='123456'/>
                                        <param name='vm-password' value='123456'/>
                                        <param name="vm-keep-local-after-email" value="true"/>
                                        <param name="vm-message-ext" value="mp3"/>
                                    </params>
                                    <variables>
                                        <variable name="outbound_caller_id_name" value="Unknown"/>
                                        <variable name="outbound_caller_id_number" value="0000000000"/>
                                        <variable name="internal_caller_id_name" value="Unknown"/>
                                        <variable name="user_originated" value="true"/>
                                        <variable name="toll_allow" value="domestic,international,local"/>
                                        <variable name="accountcode" value="1000"/>
                                        <variable name='sip-force-contact' value='nat-connectile-dysfunction'/>
                                        <variable name="record_stereo" value="false"/>
                                        <variable name="sip-allow-multiple-registrations" value="false"/>                                        
                                        <variable name="default_gateway" value="something"/>
                                        <variable name="presence_id" value="1000@d.1.c.domain.com"/>
                                        <variable name="transfer_fallback_extension" value="operator"/>
                                    </variables>
                                </user>
                    </users>
             </group>
          </groups>
        </domain>
    </section>
</document>


User 1000 at domain 2:
<document type="freeswitch/xml">
    <section name="directory">
        <domain name='d.2.c.domain.com'>
        
        <params>
            <param name="dial-string" value="{presence_id=${dialed_user}@${dialed_domain}}${sofia_contact(${dialed_user}@${dialed_domain})}"/>
        </params>
        
    <variables>
      <variable name="record_stereo" value="true"/>
      <variable name="transfer_fallback_extension" value="operator"/>
      <variable name="user_context" value="d.2.c.domain.com"/>
    </variables>
        
        <groups>
            <group name="d.2.c.domain.com">
                    <users>
                                <user id='1000' mailbox='1000'>
                                    <params>
                                        <param name='password' value='654321'/>
                                        <param name='vm-password' value='123456'/>
                                        <param name="vm-keep-local-after-email" value="true"/>
                                        <param name="vm-message-ext" value="mp3"/>
                                    </params>
                                    <variables>
                                        <variable name="outbound_caller_id_name" value="Unknown"/>
                                        <variable name="outbound_caller_id_number" value="0000000000"/>
                                        <variable name="internal_caller_id_name" value="Unknown"/>
                                        <variable name="user_originated" value="true"/>
                                        <variable name="toll_allow" value="domestic,international,local"/>
                                        <variable name="accountcode" value="0"/>
                                        <variable name='sip-force-contact' value='nat-connectile-dysfunction'/>
                                        <variable name="record_stereo" value="false"/>
                                        <variable name="sip-allow-multiple-registrations" value="false"/>                                        
                                        <variable name="default_gateway" value="something"/>
                                        <variable name="presence_id" value="1000@d.2.c.domain.com"/>
                                        <variable name="transfer_fallback_extension" value="operator"/>
                                    </variables>
                                </user>
                    </users>
             </group>
          </groups>
        </domain>
    </section>
</document>


So far the registration for both users in both domains are working and I can register with sip clients. But if I start to dial something, FS won't request for the dialplan. 

Here is what I can see in the cli trace:
freeswitch@dev> tport.c:2749 tport_wakeup_pri() tport_wakeup_pri(0xb92ee0): events IN
tport.c:2864 tport_recv_event() tport_recv_event(0xb92ee0)
tport.c:3205 tport_recv_iovec() tport_recv_iovec(0xb92ee0) msg 0xd47840 from (udp/192.168.0.132:5060) has 972 bytes, veclen = 1
tport.c:3023 tport_deliver() tport_deliver(0xb92ee0): msg 0xd47840 (972 bytes) from udp/192.168.0.15:5060/sip next=(nil)
nta.c:2880 agent_recv_request() nta: received INVITE sip:123456789@d.2.c.domain.com SIP/2.0 (CSeq 20)
nta.c:3085 agent_recv_request() nta: INVITE (20) going to a default leg
nta.c:1348 set_timeout() nta: timer shortened to 200 ms
nua_server.c:102 nua_stack_process_request() nua: nua_stack_process_request: entering
nua_stack.c:899 nh_create() nua: nh_create: entering
nua_common.c:108 nh_create_handle() nua: nh_create_handle: entering
nua_params.c:480 nua_stack_set_params() nua: nua_stack_set_params: entering
soa.c:280 soa_clone() soa_clone(static::0xb8f480, 0xb7cea0, 0xb85400) called
soa.c:403 soa_set_params() soa_set_params(static::0xa98310, ...) called
nta.c:4415 nta_leg_tcreate() nta_leg_tcreate(0xdcaf90)
soa.c:1302 soa_init_offer_answer() soa_init_offer_answer(static::0xa98310) called
soa.c:1171 soa_set_remote_sdp() soa_set_remote_sdp(static::0xa98310, (nil), 0xb54b3b, 433) called
nua_dialog.c:338 nua_dialog_usage_add() nua(0xb85400): adding session usage
tport.c:3257 tport_tsend() tport_tsend(0xb92ee0) tpn = UDP/192.168.0.15:5060
tport.c:4046 tport_resolve() tport_resolve addrinfo = 192.168.0.15:5060
tport.c:4680 tport_by_addrinfo() tport_by_addrinfo(0xb92ee0): not found by name UDP/192.168.0.15:5060
tport.c:3492 tport_send_msg() tport_vsend returned 307
nta.c:6789 incoming_reply() nta: sent 100 Trying for INVITE (20)
nua_session.c:4137 signal_call_state_change() nua(0xb85400): call state changed: init -> received, received offer
soa.c:1098 soa_get_remote_sdp() soa_get_remote_sdp(static::0xa98310, [0x7fe32eca6608], [0x7fe32eca6610], [(nil)]) called
nua_stack.c:359 nua_application_event() nua: nua_application_event: entering
nua.c:342 nua_handle_bind() nua: nua_handle_bind: entering
2014-11-29 18:31:52.853532 [NOTICE] switch_channel.c:1055 New Channel sofia/MainCCSIP/1000@d.2.c.domain.com [fd50511c-77f5-11e4-b25e-c755bd10628e]
nua_stack.c:359 nua_application_event() nua: nua_application_event: entering
nua.c:366 nua_handle_magic() nua: nua_handle_magic: entering
nua.c:366 nua_handle_magic() nua: nua_handle_magic: entering
nua.c:366 nua_handle_magic() nua: nua_handle_magic: entering
2014-11-29 18:31:52.853532 [NOTICE] sofia.c:6946 Hangup sofia/MainCCSIP/1000@d.2.c.domain.com [CS_NEW] [INCOMPATIBLE_DESTINATION]
nua.c:366 nua_handle_magic() nua: nua_handle_magic: entering
nua.c:879 nua_respond() nua: nua_respond: entering
nua_params.c:480 nua_stack_set_params() nua: nua_stack_set_params: entering
soa.c:403 soa_set_params() soa_set_params(static::0xa98310, ...) called
nua_session.c:2318 nua_invite_server_respond() nua: nua_invite_server_respond: entering
soa.c:1214 soa_clear_remote_sdp() soa_clear_remote_sdp(static::0xa98310) called
tport.c:3257 tport_tsend() tport_tsend(0xb92ee0) tpn = UDP/192.168.0.15:5060
tport.c:4046 tport_resolve() tport_resolve addrinfo = 192.168.0.15:5060
tport.c:4680 tport_by_addrinfo() tport_by_addrinfo(0xb92ee0): not found by name UDP/192.168.0.15:5060
tport.c:3492 tport_send_msg() tport_vsend returned 892
nta.c:6789 incoming_reply() nta: sent 488 Not Acceptable Here for INVITE (20)
nua_dialog.c:397 nua_dialog_usage_remove_at() nua(0xb85400): removing session usage
nua_session.c:4137 signal_call_state_change() nua(0xb85400): call state changed: received -> terminated
soa.c:356 soa_destroy() soa_destroy(static::0xa98310) called
nta.c:4468 nta_leg_destroy() nta_leg_destroy(0xdcaf90)
nua_stack.c:359 nua_application_event() nua: nua_application_event: entering
nua_stack.c:359 nua_application_event() nua: nua_application_event: entering
nua_stack.c:529 nua_signal() nua(0xb85400): sent signal r_respond
tport.c:2749 tport_wakeup_pri() tport_wakeup_pri(0xb92ee0): events IN
tport.c:2864 tport_recv_event() tport_recv_event(0xb92ee0)
tport.c:3205 tport_recv_iovec() tport_recv_iovec(0xb92ee0) msg 0xaa4690 from (udp/192.168.0.132:5060) has 324 bytes, veclen = 1
tport.c:3023 tport_deliver() tport_deliver(0xb92ee0): msg 0xaa4690 (324 bytes) from udp/192.168.0.15:5060/sip next=(nil)
nta.c:2880 agent_recv_request() nta: received ACK sip:123456789@d.2.c.domain.com SIP/2.0 (CSeq 20)
nta.c:3019 agent_recv_request() nta: ACK (20) is going to INVITE (20)
2014-11-29 18:31:52.853532 [NOTICE] switch_core_session.c:1633 Session 4 (sofia/MainCCSIP/1000@d.2.c.domain.com) Ended
2014-11-29 18:31:52.853532 [NOTICE] switch_core_session.c:1637 Close Channel sofia/MainCCSIP/1000@d.2.c.domain.com [CS_DESTROY]
nua.c:366 nua_handle_magic() nua: nua_handle_magic: entering
nua.c:366 nua_handle_magic() nua: nua_handle_magic: entering
nua.c:342 nua_handle_bind() nua: nua_handle_bind: entering
nua.c:366 nua_handle_magic() nua: nua_handle_magic: entering
nua.c:366 nua_handle_magic() nua: nua_handle_magic: entering
nua.c:921 nua_handle_destroy() nua: nua_handle_destroy: entering
nta.c:4468 nta_leg_destroy() nta_leg_destroy((nil))
nua_stack.c:529 nua_signal() nua(0xb85400): sent signal r_destroy
nta.c:1296 agent_timer() nta: timer set next to 1976 ms


The only request is coming from time to time is this:
hostname = [dev]
section = [directory]
tag_name = [domain]
key_name = [name]
key_value = [d.2.c.domain.com]
Event-Name = [REQUEST_PARAMS]
Core-UUID = [d1af88e4-77f4-11e4-b1f2-c755bd10628e]
FreeSWITCH-Hostname = [dev]
FreeSWITCH-Switchname = [dev]
FreeSWITCH-IPv4 = [192.168.0.132]
FreeSWITCH-IPv6 = [::1]
Event-Date-Local = [2014-11-29 18:35:05]
Event-Date-GMT = [Sat, 29 Nov 2014 18:35:05 GMT]
Event-Date-Timestamp = [1417286105312271]
Event-Calling-File = [sofia_reg.c]
Event-Calling-Function = [sofia_reg_parse_auth]
Event-Calling-Line-Number = [2739]
Event-Sequence = [898]
action = [sip_auth]
sip_profile = [MainCCSIP]
sip_user_agent = [qutecom/rev-6653cd8f2afd-trunk]
sip_auth_username = [1000]
sip_auth_realm = [d.2.c.domain.com]
sip_auth_nonce = [6ff7849c-77f6-11e4-b27c-c755bd10628e]
sip_auth_uri = [sip:d.2.c.domain.com]
sip_contact_user = [1000]
sip_contact_host = [192.168.0.15]
sip_to_user = [1000]
sip_to_host = [d.2.c.domain.com]
sip_via_protocol = [udp]
sip_from_user = [1000]
sip_from_host = [d.2.c.domain.com]
sip_call_id = [1172541516@192.168.0.15]
sip_request_host = [d.2.c.domain.com]
sip_auth_response = [6836f04faa9f464b8d78f11e88d7ee5d]
sip_auth_method = [REGISTER]
client_port = [5060]
key = [id]
user = [1000]
domain = [d.2.c.domain.com]
ip = [192.168.0.15]

Any thoughts why is the dialplan not requested?

Thanks,
Zoltan

_________________________________________________________________________
Professional FreeSWITCH Consulting Services:
consulting@freeswitch.org
http://www.freeswitchsolutions.com

Official FreeSWITCH Sites
http://www.freeswitch.org
http://confluence.freeswitch.org
http://www.cluecon.com

FreeSWITCH-users mailing list
FreeSWITCH-users@lists.freeswitch.org
http://lists.freeswitch.org/mailman/listinfo/freeswitch-users
UNSUBSCRIBE:http://lists.freeswitch.org/mailman/options/freeswitch-users
http://www.freeswitch.org