search

drachtio / drachtio-server

A SIP call processing server that can be controlled via nodejs applications
https://drachtio.org
MIT License
233 stars 89 forks source link

Contact header on OPTIONS #114

Open havfo opened 4 years ago

havfo commented 4 years ago

I am trying to set the contact header on a OPTIONS request initiated from drachtio.

Contact : <sips:valid-fqdn-here:5065;transport=tls>

This results in drachtio resetting my Contact header. nta.c:2655 outgoing_update_contact() outgoing_update_contact: updating contact to tls/x.x.x.x:5065

I see this has been addressed before in #65 , but I need to be able to set the contact header to different FQDN (that actually resolve to the same host).

davehorton commented 4 years ago

can you incliude the the drachtio log at debug level showing the entire sequence?

havfo commented 4 years ago 

OPTIONS sip:sip.pstnhub.microsoft.com;transport=tls SIP/2.0
Contact: <sips:valid-fqdn-here:5065;transport=tls>
Content-Length: 0

2020-02-21 14:28:08.486426 Client::processMessage - got request with 4 tokens
2020-02-21 14:28:08.486508 Client::processMessage - request id 03b53623-9c1c-492e-b797-abb9870f8cfb, request type: sip transaction id: , dialog id:
2020-02-21 14:28:08.486637 Client::processMessage - sending a request outside of a dialog
2020-02-21 14:28:08.486791 ClientController::addAppTransaction: transactionId b4c13818-3b32-4219-b7e7-d3bc10bbe250; size: 1
2020-02-21 14:28:08.486899 ClientController::addApiRequest: clientMsgId 03b53623-9c1c-492e-b797-abb9870f8cfb; size: 1
2020-02-21 14:28:08.488981 SipTransport::findAppropriateTransport: searching for a transport to reach tls/sip:sip.pstnhub.microsoft.com;transport=tls
2020-02-21 14:28:08.489093 SipTransport::findAppropriateTransport - after filtering for transport we have 6 candidates
2020-02-21 14:28:08.489212 SipTransport::findAppropriateTransport - after filtering for protocol we have 3 candidates
2020-02-21 14:28:08.494398 SipTransport::findAppropriateTransport: - returning the best match 0x559c043e5190: tls/x.x.x.x:5065
2020-02-21 14:28:08.494496 SipTransport::getContactUri - created Contact header: sips:x.x.x.x:5065;transport=tls
2020-02-21 14:28:08.494626 SipDialogController::doSendRequestOutsideDialog selected transport 0x559c043e5190tls/x.x.x.x:5065
2020-02-21 14:28:08.495101 makeTags - Adding well-known header 'Contact' with value '<sips:valid-fqdn-here:5065;transport=tls>'
2020-02-21 14:28:08.495212 SipDialogController::doSendRequestOutsideDialog - from: <sips:x.x.x.x:5065;transport=tls>
2020-02-21 14:28:08.495312 SipDialogController::doSendRequestOutsideDialog - to: sip:sip.pstnhub.microsoft.com;transport=tls
2020-02-21 14:28:08.495421 SipDialogController::doSendRequestOutsideDialog - contact: <sips:x.x.x.x:5065;transport=tls>
2020-02-21 14:28:08.495546 isLocalSipUri: checking to see if this is one of mine: sip:sip.pstnhub.microsoft.com;transport=tls
2020-02-21 14:28:08.495668 nta.c:4566 nta_leg_tcreate() nta_leg_tcreate(0x559c04452e10)
2020-02-21 14:28:08.495815 nta.c:2813 nta_tpn_by_url() nta: selecting scheme sip
2020-02-21 14:28:08.495941 sres_cache.c:272 sres_cache_get() sres_cache_get(0x559c043e3090, SRV, "_sips._tcp.sip.pstnhub.microsoft.com.") called
2020-02-21 14:28:08.496053 sres_cache.c:318 sres_cache_get() sres_cache_get(0x559c043e3090, SRV, "_sips._tcp.sip.pstnhub.microsoft.com.") returned 1 entries
2020-02-21 14:28:08.496155 nta.c:10768 outgoing_query_srv() nta: for "sip.pstnhub.microsoft.com" query "_sips._tcp.sip.pstnhub.microsoft.com" SRV (cached)
2020-02-21 14:28:08.496267 sres_cache.c:272 sres_cache_get() sres_cache_get(0x559c043e3090, AAAA, "sip.pstnhub.microsoft.com.") called
2020-02-21 14:28:08.496377 sres_cache.c:318 sres_cache_get() sres_cache_get(0x559c043e3090, AAAA, "sip.pstnhub.microsoft.com.") returned 1 entries
2020-02-21 14:28:08.496492 nta.c:10890 outgoing_query_aaaa() nta: for "sip.pstnhub.microsoft.com" query "sip.pstnhub.microsoft.com" AAAA (cached)
2020-02-21 14:28:08.496597 nta.c:11053 outgoing_query_results() nta(0x559c04433500): sip.pstnhub.microsoft.com A record still unresolved
2020-02-21 14:28:08.496697 sres_cache.c:272 sres_cache_get() sres_cache_get(0x559c043e3090, A, "sip.pstnhub.microsoft.com.") called
2020-02-21 14:28:08.496798 nta.c:10973 outgoing_query_a() nta: for "sip.pstnhub.microsoft.com" query "sip.pstnhub.microsoft.com" A
2020-02-21 14:28:08.496904 sres.c:968 sres_query() sres_query(0x559c043e2930, 0x559c04433500, A, "sip.pstnhub.microsoft.com") called
2020-02-21 14:28:08.497023 sres.c:2730 sres_send_dns_query() sres_send_dns_query(0x559c043e2930, 0x559c04443db0) called
2020-02-21 14:28:08.497239 sres.c:2819 sres_send_dns_query() sres_send_dns_query(0x559c043e2930, 0x559c04443db0) id=24628 A sip.pstnhub.microsoft.com (to [x.x.x.x]:53)
2020-02-21 14:28:08.497355 SipDialogController::addRIP adding orq 0x559c04433500
2020-02-21 14:28:08.497485 nta.c:4619 nta_leg_destroy() nta_leg_destroy(0x559c04452e10)
2020-02-21 14:28:08.497609 ClientController::removeApiRequest: clientMsgId 03b53623-9c1c-492e-b797-abb9870f8cfb; size: 0
2020-02-21 14:28:08.497862 Client::write_handler - wrote 523 bytes: system:0
2020-02-21 14:28:08.548811 sres.c:3467 sres_resolver_receive() sres_resolver_receive(0x559c043e2930, 25) called
2020-02-21 14:28:08.548967 sres.c:3781 sres_create_record() ANSWER RR received sip.pstnhub.microsoft.com. CNAME IN 265 rdlen=32
2020-02-21 14:28:08.549085 sres.c:3781 sres_create_record() ANSWER RR received sip.pstnhub.trafficmanager.net. CNAME IN 20 rdlen=42
2020-02-21 14:28:08.549249 sres.c:3781 sres_create_record() ANSWER RR received sip-du-a-euwe.westeurope.cloudapp.azure.com. A IN 10 rdlen=4
2020-02-21 14:28:08.549390 sres.c:3781 sres_create_record() AUTHORITY RR received westeurope.cloudapp.azure.com. NS IN 58 rdlen=20
2020-02-21 14:28:08.549506 sres.c:3781 sres_create_record() AUTHORITY RR received westeurope.cloudapp.azure.com. NS IN 58 rdlen=32
2020-02-21 14:28:08.549623 sres.c:3781 sres_create_record() AUTHORITY RR received westeurope.cloudapp.azure.com. NS IN 58 rdlen=31
2020-02-21 14:28:08.549737 sres.c:3781 sres_create_record() AUTHORITY RR received westeurope.cloudapp.azure.com. NS IN 58 rdlen=10
2020-02-21 14:28:08.549868 sres_cache.c:272 sres_cache_get() sres_cache_get(0x559c043e3090, A, "sip.pstnhub.trafficmanager.net.") called
2020-02-21 14:28:08.549985 sres_cache.c:318 sres_cache_get() sres_cache_get(0x559c043e3090, A, "sip.pstnhub.trafficmanager.net.") returned 1 entries
2020-02-21 14:28:08.550095 nta.c:11026 outgoing_answer_a() nta: sip-du-a-euwe.westeurope.cloudapp.azure.com. IN A 52.114.75.24
2020-02-21 14:28:08.550217 nta.c:2655 outgoing_update_contact() outgoing_update_contact: updating contact to  tls/x.x.x.x:5065
2020-02-21 14:28:08.550343 tport.c:3285 tport_tsend() tport_tsend(0x559c043e5190) tpn = tls/52.114.75.24:5061
2020-02-21 14:28:08.550464 tport.c:4085 tport_resolve() tport_resolve addrinfo = 52.114.75.24:5061
2020-02-21 14:28:08.550592 tport.c:4767 tport_by_addrinfo() tport_by_addrinfo(0x559c043e5190): found 0x559c0446be90 by name tls/52.114.75.24:5061                                                                                                                                                                                                                                                                                                                         
2020-02-21 14:28:08.550732 tport.c:880 tport_alloc_secondary() tport_alloc_secondary(0x559c043e5190): new secondary tport 0x559c04450a10
2020-02-21 14:28:08.550857 tport_type_tcp.c:203 tport_tcp_init_secondary() tport_tcp_init_secondary(0x559c04450a10): Setting TCP_KEEPIDLE to 30
2020-02-21 14:28:08.550972 tport_type_tcp.c:209 tport_tcp_init_secondary() tport_tcp_init_secondary(0x559c04450a10): Setting TCP_KEEPINTVL to 30
2020-02-21 14:28:08.551221 tport_type_tls.c:743 tport_tls_connect() tport_tls_connect(0x559c04450a10): connecting to tls/52.114.75.24:5061
2020-02-21 14:28:08.551330 tport.c:2324 tport_set_secondary_timer() tport(0x559c04450a10): reset timer
2020-02-21 14:28:08.551435 tport.c:3821 tport_queue() tport_queue(0x559c04450a10): queueing 0x559c0446b920 for tls/52.114.75.24:5061
2020-02-21 14:28:08.551555 nta.c:8470 outgoing_send() nta: sent OPTIONS (16593852) to tls/52.114.75.24:5061
2020-02-21 14:28:08.551676 tport.c:4199 tport_pend() tport_pend(0x559c04450a10): pending 0x559c0446b920 for tls/52.114.75.24:5061 (already 0)
2020-02-21 14:28:08.575622 tport_tls.c:945 tls_connect() tls_connect(0x559c04450a10): events CONNECTING
2020-02-21 14:28:08.601408 tport_tls.c:945 tls_connect() tls_connect(0x559c04450a10): events NEGOTIATING
2020-02-21 14:28:08.633302 tport_tls.c:945 tls_connect() tls_connect(0x559c04450a10): events NEGOTIATING
2020-02-21 14:28:08.633538 tport_tls.c:589 tls_post_connection_check() tls_post_connection_check(0x559c04450a10): TLS cipher chosen (name): ECDHE-RSA-AES256-GCM-SHA384
2020-02-21 14:28:08.633720 tport_tls.c:591 tls_post_connection_check() tls_post_connection_check(0x559c04450a10): TLS cipher chosen (version): TLSv1.2
2020-02-21 14:28:08.633835 tport_tls.c:594 tls_post_connection_check() tls_post_connection_check(0x559c04450a10): TLS cipher chosen (bits/alg_bits): 256/256
2020-02-21 14:28:08.633953 tport_tls.c:597 tls_post_connection_check() tls_post_connection_check(0x559c04450a10): TLS cipher chosen (description): ECDHE-RSA-AES256-GCM-SHA384 TLSv1.2 Kx=ECDH     Au=RSA  Enc=AESGCM(256) Mac=AEAD

2020-02-21 14:28:08.634112 tport.c:3962 tport_send_event() tport_send_event(0x559c04450a10) - ready to send to (tls/52.114.75.24:5061)
2020-02-21 14:28:08.634278 tport_type_tls.c:594 tport_tls_send() tport_tls_writevec: vec 0x559c04445680 0x559c04434430 396 (396)
2020-02-21 14:28:08.634481 tport.c:3531 tport_send_msg() tport_vsend returned 396
2020-02-21 14:28:08.634695 send 396 bytes to tls/[52.114.75.24]:5061 at 14:28:08.634198:
OPTIONS sip:sip.pstnhub.microsoft.com;transport=tls SIP/2.0
Via: SIP/2.0/TLS x.x.x.x:5065;branch=z9hG4bKcv8U83Fy3HX8Q
Max-Forwards: 70
From: <sips:x.x.x.x:5065;transport=tls>;tag=jm7Qr6Hr84vUN
To: <sip:sip.pstnhub.microsoft.com>;transport=tls
Call-ID: 38e0ed76-cf59-1238-a1b8-984be1679c28
CSeq: 16593852 OPTIONS
Content-Length: 0
Contact: <sips:x.x.x.x:5065;transport=tls>

2020-02-21 14:28:08.634819 tport_type_tls.c:395 tport_tls_set_events() tport_tls_set_events(0x559c04450a10): logical events IN real IN
2020-02-21 14:28:08.634934 tport.c:2324 tport_set_secondary_timer() tport(0x559c04450a10): reset timer
2020-02-21 14:28:08.663158 tport.c:2801 tport_wakeup() tport_wakeup(0x559c04450a10): events IN
2020-02-21 14:28:08.663323 tport.c:2892 tport_recv_event() tport_recv_event(0x559c04450a10)
2020-02-21 14:28:08.663442 tport_type_tls.c:491 tport_tls_recv() tport_tls_recv(0x559c04450a10): tls_read() returned 622
2020-02-21 14:28:08.663601 tport.c:3233 tport_recv_iovec() tport_recv_iovec(0x559c04450a10) msg 0x559c04430c40 from (tls/52.114.75.24:5061) has 622 bytes, veclen = 1
2020-02-21 14:28:08.664040 recv 622 bytes from tls/[52.114.75.24]:5061 at 14:28:08.663854:
SIP/2.0 403 Forbidden
FROM: <sips:x.x.x.x:5065;transport=tls>;tag=jm7Qr6Hr84vUN
TO: <sip:sip.pstnhub.microsoft.com>;transport=tls
CSEQ: 16593852 OPTIONS
CALL-ID: 38e0ed76-cf59-1238-a1b8-984be1679c28
VIA: SIP/2.0/TLS x.x.x.x:5065;branch=z9hG4bKcv8U83Fy3HX8Q
REASON: Q.850;cause=63;text="87b3a1c2-0c6c-487b-97dd-e85db24a1774;Provided Trunk FQDN 'x.x.x.x' is not allowed. Connection allows following fqdns: valid-fqdn-here, valid-fqdn-here, valid-fqdn-here."
CONTENT-LENGTH: 0
ALLOW: INVITE,ACK,OPTIONS,CANCEL,BYE,NOTIFY
SERVER: Microsoft.PSTNHub.SIPProxy v.2020.2.12.3 i.EUWE.0

2020-02-21 14:28:08.664169 tport.c:3051 tport_deliver() tport_deliver(0x559c04450a10): msg 0x559c04430c40 (622 bytes) from tls/52.114.75.24:5061 next=(nil)
2020-02-21 14:28:08.664293 nta.c:3448 agent_recv_response() nta: received 403 Forbidden for OPTIONS (16593852)
2020-02-21 14:28:08.664405 nta.c:3515 agent_recv_response() nta: 403 Forbidden is going to a transaction
2020-02-21 14:28:08.664528 nta.c:9734 outgoing_estimate_delay() nta_outgoing: RTT is 114.18 ms
2020-02-21 14:28:08.664652 tport.c:4261 tport_release() tport_release(0x559c04450a10): 0x559c0446b920 by 0x559c04433500 with 0x559c04430c40
2020-02-21 14:28:08.664770 SipDialogController::processResponseOutsideDialog
2020-02-21 14:28:08.664892 SipDialogController::findRIPByOrq orq 0x559c04433500
2020-02-21 14:28:08.665007 SipDialogController::clearRIP clearing orq 0x559c04433500
2020-02-21 14:28:08.665118 nta.c:8888 outgoing_free() nta: outgoing_free(0x559c04433500)
2020-02-21 14:28:08.665262 ClientController::removeAppTransaction: transactionId b4c13818-3b32-4219-b7e7-d3bc10bbe250; size: 0
2020-02-21 14:28:08.665374 tport.c:2324 tport_set_secondary_timer() tport(0x559c04450a10): reset timer
2020-02-21 14:28:08.665411 Client::write_handler - wrote 757 bytes: system:0
2020-02-21 14:28:10.341364 nta.c:1350 agent_timer() nta: timer not set
havfo commented 4 years ago

Sanitized, but should be correct.

davehorton commented 4 years ago

I get the need to sanitize, but in this case it may be necessary to see them. Can you send me privately the unsanitized log at daveh at drachtio dot org?

havfo commented 4 years ago

Done.

davehorton commented 4 years ago

OK got it. So, essentially, you would like the Contact rewriting function (which is necessary for servers on clouds like AWS, GCP etc that have non-bound public IPs to work) to be disabled for the case where you have explicitly provided a DNS name as the host in the Contact header.

This sounds reasonable. I will look into it. If I build a fix on a branch do you have the ability to test it?

havfo commented 4 years ago

Correct, it is needed for certificate/trunk validation at the other end of the OPTIONS, and requires it to be a valid FQDN. No problem to test a branch :+1:

davehorton commented 4 years ago

can you try building and then testing the branch local-net-enhancements? Please make sure to do a clean rebuild as the sofia-sip dependency has been updated and needs to be rebuilt.

You can verify you have the correct version of sofia-sip by checking that the 3 most recent commits in deps/sofia-sip are these:

e94fb8f8 (HEAD -> master, origin/master, origin/HEAD) travis
6cfe1f46 travis
f7029c65 outgoing_update_contact: do not update the contact if the host in the provided contact is a dns name
havfo commented 4 years ago

I can confirm that that fixes my problem :+1:

nta.c:2663 outgoing_update_contact() outgoing_update_contact: NOT updating contact because original contact is a dns name xxx

davehorton commented 4 years ago

ok, great. I will merge it into the develop branch and a tagged release shortly