sofia loglevel all 9

#####################################################################

2018-06-30 22:31:43.746032 [NOTICE] sofia_reg.c:448 Registering sip-trunk.telekom.de
nua.c:622 nua_register() nua: nua_register: entering
nua_stack.c:529 nua_signal() nua(0xb4e2ec50): sent signal r_register
nua_stack.c:569 nua_stack_signal() nua(0xb4e2ec50): recv signal r_register
nua_params.c:480 nua_stack_set_params() nua: nua_stack_set_params: entering
soa.c:280 soa_clone() soa_clone(static::0xb6255520, 0x88b30b0, 0xb4e2ec50) called
soa.c:403 soa_set_params() soa_set_params(static::0xb5923410, ...) called
soa.c:403 soa_set_params() soa_set_params(static::0xb5923410, ...) called
nua_dialog.c:338 nua_dialog_usage_add() nua(0xb4e2ec50): adding register usage
nta.c:4417 nta_leg_tcreate() nta_leg_tcreate(0xb5906508)
nta.c:2665 nta_tpn_by_url() nta: selecting scheme sip
sres_cache.c:272 sres_cache_get() sres_cache_get(0x88aa8e0, SRV, "_sip._tcp.reg.sip-trunk.telekom.de.") called
sres_cache.c:318 sres_cache_get() sres_cache_get(0x88aa8e0, SRV, "_sip._tcp.reg.sip-trunk.telekom.de.") returned 3 entries
nta.c:10598 outgoing_query_srv() nta: for "reg.sip-trunk.telekom.de" query "_sip._tcp.reg.sip-trunk.telekom.de" SRV (cached)
nta.c:10694 outgoing_answer_srv() nta: _sip._tcp.reg.sip-trunk.telekom.de IN SRV 10 5  5060 d-ipr-a02.sip-trunk.telekom.de. (tcp)
nta.c:10694 outgoing_answer_srv() nta: _sip._tcp.reg.sip-trunk.telekom.de IN SRV 11 5  5060 b-ipr-a01.sip-trunk.telekom.de. (tcp)
nta.c:10694 outgoing_answer_srv() nta: _sip._tcp.reg.sip-trunk.telekom.de IN SRV 11 5  5060 b-ipr-a02.sip-trunk.telekom.de. (tcp)
sres_cache.c:272 sres_cache_get() sres_cache_get(0x88aa8e0, A, "d-ipr-a02.sip-trunk.telekom.de.") called
sres_cache.c:318 sres_cache_get() sres_cache_get(0x88aa8e0, A, "d-ipr-a02.sip-trunk.telekom.de.") returned 1 entries
nta.c:10803 outgoing_query_a() nta: for "reg.sip-trunk.telekom.de" query "d-ipr-a02.sip-trunk.telekom.de." A (cached)
nta.c:10856 outgoing_answer_a() nta: d-ipr-a02.sip-trunk.telekom.de. IN A 217.0.26.133
tport.c:4588 tport_by_name() tport(0xb625dc58): found 0x880d978 by name tcp/217.0.26.133:5060
tport.c:3257 tport_tsend() tport_tsend(0x880d978) tpn = tcp/217.0.26.133:5060
tport.c:3594 tport_vsend() tport_vsend(0x880d978): 677 bytes of 677 to tcp/217.0.26.133:5060
tport.c:3492 tport_send_msg() tport_vsend returned 677
tport.c:2296 tport_set_secondary_timer() tport(0x880d978): reset timer
nta.c:8304 outgoing_send() nta: sent REGISTER (124859287) to tcp/217.0.26.133:5060
tport.c:4160 tport_pend() tport_pend(0x880d978): pending 0xb6263a08 for tcp/217.0.26.133:5060 (already 1)
nta.c:8982 outgoing_timer_bf() nta: timer F fired, timeout REGISTER (124859241)
nta.c:9035 outgoing_timeout() nta(0xb6264318): try next after timeout
nta.c:10200 outgoing_graylist() nta: graylisting d-ipr-a02.sip-trunk.telekom.de.:5060;transport=tcp
nta.c:10227 outgoing_graylist() nta: reduced priority of 1 _sip._tcp.reg.sip-trunk.telekom.de SRV records (increase value to 11)
sres_cache.c:272 sres_cache_get() sres_cache_get(0x88aa8e0, A, "reg.sip-trunk.telekom.de.") called
nta.c:10803 outgoing_query_a() nta: for "reg.sip-trunk.telekom.de" query "reg.sip-trunk.telekom.de" A
sres.c:968 sres_query() sres_query(0xb624a8b8, 0xb6264318, A, "reg.sip-trunk.telekom.de") called
sres.c:2730 sres_send_dns_query() sres_send_dns_query(0xb624a8b8, 0x88653d0) called
sres.c:2819 sres_send_dns_query() sres_send_dns_query(0xb624a8b8, 0x88653d0) id=12982 A reg.sip-trunk.telekom.de (to [217.237.148.70]:53)
nta.c:8929 _nta_outgoing_timer() nta_outgoing_timer: 0/0 resent, 1/2 tout, 0/0 term, 0/2 free
nta.c:1296 agent_timer() nta: timer set next to 29536 ms
sres.c:3467 sres_resolver_receive() sres_resolver_receive(0xb624a8b8, 31) called
sres.c:3781 sres_create_record() AUTHORITY RR received sip-trunk.telekom.de. SOA IN 151 rdlen=64
sres.c:3572 sres_log_response() sres_resolver_receive(0xb624a8b8, 0x88653d0) id=12982 (from [217.237.148.70]:53)
sres.c:2987 sres_query_report_error() sres(q=0x88653d0): reporting error RECORD_ERR for A reg.sip-trunk.telekom.de
tport.c:4222 tport_release() tport_release(0x880d978): 0xb623b2e8 by 0xb6264318 with (nil)
nta.c:8722 outgoing_free() nta: outgoing_free(0xb6264318)
nta.c:8982 outgoing_timer_bf() nta: timer F fired, timeout REGISTER (124859287)
nta.c:9035 outgoing_timeout() nta(0xb628fb30): try next after timeout
nta.c:10200 outgoing_graylist() nta: graylisting d-ipr-a02.sip-trunk.telekom.de.:5060;transport=tcp
nta.c:10227 outgoing_graylist() nta: reduced priority of 1 _sip._tcp.reg.sip-trunk.telekom.de SRV records (increase value to 12)
sres_cache.c:272 sres_cache_get() sres_cache_get(0x88aa8e0, A, "b-ipr-a01.sip-trunk.telekom.de.") called
sres_cache.c:318 sres_cache_get() sres_cache_get(0x88aa8e0, A, "b-ipr-a01.sip-trunk.telekom.de.") returned 1 entries
nta.c:10803 outgoing_query_a() nta: for "reg.sip-trunk.telekom.de" query "b-ipr-a01.sip-trunk.telekom.de." A (cached)
nta.c:10856 outgoing_answer_a() nta: b-ipr-a01.sip-trunk.telekom.de. IN A 217.0.26.163
tport.c:4588 tport_by_name() tport(0xb625dc58): found 0x87fa8a8 by name tcp/217.0.26.163:5060
tport.c:4222 tport_release() tport_release(0x880d978): 0xb6263a08 by 0xb628fb30 with (nil)
tport.c:2296 tport_set_secondary_timer() tport(0x880d978): reset timer
tport.c:3257 tport_tsend() tport_tsend(0x87fa8a8) tpn = tcp/217.0.26.163:5060
tport.c:3594 tport_vsend() tport_vsend(0x87fa8a8): 677 bytes of 677 to tcp/217.0.26.163:5060
tport.c:3492 tport_send_msg() tport_vsend returned 677
tport.c:2296 tport_set_secondary_timer() tport(0x87fa8a8): reset timer
nta.c:8304 outgoing_send() nta: sent REGISTER (124859287) to tcp/217.0.26.163:5060
tport.c:4160 tport_pend() tport_pend(0x87fa8a8): pending 0xb6263a08 for tcp/217.0.26.163:5060 (already 0)
nta.c:8929 _nta_outgoing_timer() nta_outgoing_timer: 0/0 resent, 1/1 tout, 0/0 term, 0/1 free
nta.c:1296 agent_timer() nta: timer set next to 32000 ms
2018-06-30 22:32:44.083197 [WARNING] sofia_reg.c:484 Timeout Registering sip-trunk.telekom.de
nua.c:921 nua_handle_destroy() nua: nua_handle_destroy: entering
nua_stack.c:569 nua_stack_signal() nua(0xb4e2ec50): recv signal r_destroy
nua_dialog.c:397 nua_dialog_usage_remove_at() nua(0xb4e2ec50): removing register usage
nta.c:4470 nta_leg_destroy() nta_leg_destroy(0xb5906508)
soa.c:356 soa_destroy() soa_destroy(static::0xb5923410) called
nua_stack.c:529 nua_signal() nua(0xb4e2ec50): sent signal r_destroy
2018-06-30 22:32:45.123287 [WARNING] sofia_reg.c:505 sip-trunk.telekom.de Failed Registration [908], setting retry to 30 seconds.

#############################################################################

2018-06-30 14:18 GMT+02:00 Paul Muaddib <paul.muaddib83@gmail.com>:
Hi,

can someone please look at it and tell my what I am doing wrong?

NOTICE] sofia_reg.c:448 Registering sip-trunk.telekom.de
[WARNING] sofia_reg.c:484 Timeout Registering sip-trunk.telekom.de
[WARNING] sofia_reg.c:505 sip-trunk.telekom.de Failed Registration [908], setting retry to 30 seconds.

My setup:
########

I have a static IP address for my router. My router does not have UPnP or NAT-PMP.
Phones and Freeswitch server are on the same local network. The local network is behind NAT

PHONE -> FS -> NAT -> Public Internet
I only want to connect to the PSTN via my sip gateway provider.

According to this manual I did the following setting:
https://freeswitch.org/confluence/display/FREESWITCH/NAT+Traversal

vars.xml
######

<X-PRE-PROCESS cmd="set" data="external_rtp_ip=X.X.X.X“/>
<X-PRE-PROCESS cmd="set" data="external_sip_ip=X.X.X.X"/>

internal.xml
#########

<param name="ext-rtp-ip" value="$${external_rtp_ip}"/>

external.xml
##########

<param name="ext-sip-ip" value="$${external_sip_ip}"/>
<param name="ext-rtp-ip" value="$${external_rtp_ip}"/>

( What is a little bit strange though is that nat_map status is not working
[ERR] mod_commands.c:751 nat_map API called while NAT not initialized )

Is the reason why it does not work the port specification in the Contact field (sngrep output)?
Contact: <sip:gw+sip-trunk.telekom.de@X.X.X.X:5080;transport=tcp;gw=sip-trunk.telekom.de>

I do not want to setup port forwarding in the firewall. The connection should remain open via a keep alive signal.

sngrep output
###########

2018/06/30 13:52:37.211946 10.0.200.2:51813 -> 217.0.26.165:5060
REGISTER sip:reg.sip-trunk.telekom.de;transport=tcp SIP/2.0
Via: SIP/2.0/TCP X.X.X.X:5080;rport;branch=z2hG4bK588cZXSvrN1De
Max-Forwards: 70
From: <sip:username@reg.sip-trunk.telekom.de>;tag=9aldsj8n67a
To: <sip:username@reg.sip-trunk.telekom.de>
Call-ID:
CSeq: 111844514 REGISTER
Contact: <sip:gw+sip-trunk.telekom.de@X.X.X.X:5080;transport=tcp;gw=sip-trunk.telekom.de>
Expires: 3600
User-Agent: FreeSWITCH-mod_sofia/1.6.19+git~20170927T175834Z~38f568d343~32bit
Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, MESSAGE, INFO, UPDATE, REGISTER, REFER, NOTIFY
Supported: timer, path, replaces
Content-Length: 0

Provider settings:
#############

output proxy: reg.sip-trunk.telekom.de
registrar: sip-trunk.telekom.de

sip_profiles/external/telekom_voip.xml
##############################

<include>

 <gateway name="sip-trunk.telekom.de">
  <param name="username" value=„XXXXXX“/>
  <param name="password" value=„XXXXXX“/>

  <param name="realm" value="sip-trunk.telekom.de"/>
  <param name="proxy" value="reg.sip-trunk.telekom.de"/>
  <param name="register" value="true"/>
  <param name="register-transport" value="tcp"/>
  <param name="expire-seconds" value="3600"/>

 </gateway>
</include>

Firewall settings
#############

# block all traffic in all directions
block log

# loopback interface is not filtered
set skip on lo0

voip_tcp_client_out = "{ssh, ftp, domain, http, https, sip}"
voip_udp_client_out = "{domain, ntp, sip, 3478}"

match out on $wan_if from any nat-to ($wan_if)

pass on $voip_if inet proto tcp from any to port $voip_tcp_client_out
pass on $voip_if inet proto udp from any to port $voip_udp_client_out

pass out on $wan_if inet proto tcp from any to port $tcp_client_out
pass out on $wan_if inet proto udp from any to port $udp_client_out


Thank you for helping :)

Regards,
Paul