[SR-Users] Dispatcher marks TLS destinations as Inactive when present in more than one set

Daniel-Constantin Mierla miconda at gmail.com
Mon Apr 28 10:07:00 CEST 2014 

Hello,

seems like an issue if the second OPTIONS is not sent out -- I will look 
over it.

However, SIPS doesn't enforce tls, it means a secure connection which 
can be also VPN or a private wire.

Can you give it a try with uris like:

sip: _IP_ADDR_:5061;transport=tls

?

Cheers,
Daniel

On 25/04/14 16:56, Giacomo Vacca wrote:
>
> Hi all,
>
> I’m seeing a strange behaviour with dispatcher in these conditions:
>
> 1. A destination requires TLS (e.g. sips:10.0.0.1:5061)
>
> 2. The destination has flags 8 (i.e. in normal conditions we want AP, 
> Active Probing) and dispatcher uses ds_probing_mode 1 (always probe)
>
> 3. The destination is present in more than one set
>
> The behaviour is that the destination is marked as IP (Inactive 
> Probing) in the set with alower set number.
>
> In other words at startup (or dispatcher reload):
>
> SET_NO:: 2
>
> SET:: 2
>
>         URI:: sips:10.0.0.1:5061 flags=AP priority=0 attrs=
>
> SET:: 1
>
>         URI:: sips:10.0.0.1:5061 flags=AP priority=0 attrs=
>
> After some time (about 30”, see below):
>
> SET_NO:: 2
>
> SET:: 2
>
>         URI:: sips:10.0.0.1:5061 flags=AP priority=0 attrs=
>
> SET:: 1
>
>         URI:: sips:10.0.0.1:5061 flags=IP priority=0 attrs=
>
> So the same destination is marked as AP and IP at the same time.
>
> I’ve reproduced this with a brand new installation (4.1.3 on debian 
> wheezy), but seen with 3.2.3 and 4.0.4 as well.
>
> debian wheezy VM (Linux debian7 3.2.0-4-amd64 #1 SMP Debian 3.2.54-2 
> x86_64 GNU/Linux)
>
> I can see (with either ssldump or asterisk’s ‘sip set debug on’) the 
> first OPTIONS/404 (related to set #2), but not the second (related to 
> set #1).
>
> I haven’t seen (with tcpdump) the attempt to create a second 
> connection to the destination (which makes me think that it either 
> fails or kamailio attempts to re-use the existing one).
>
> Probing for set #1 appears to time out (i.e. after 30” the response is 
> considered a 408).
>
> It happens with either Asterisk or FreeSWITCH as servers.
>
> Extract from tls.cfg:
>
> [client:default]
>
> verify_certificate = no
>
> require_certificate = no
>
> Dispatcher configuration:
>
> loadmodule "dispatcher.so"
>
> [...]
>
> # ----- dispatcher params -----
>
> modparam("dispatcher", "list_file", "/etc/kamailio/dispatcher.cfg")
>
> modparam("dispatcher", "ds_ping_reply_codes", "class=2;code=404")
>
> modparam("dispatcher", "ds_probing_mode", 1)
>
> modparam("dispatcher", "ds_ping_interval", 30)
>
> /etc/kamailio/dispatcher.cfg:
>
> 1 sips:10.0.0.1:5061 8 0
>
> 2 sips:10.0.0.1:5061 8 0
>
> (I'm using 10.0.0.1 here for simplification only; the real IP address 
> has been omitted).
>
> Server (Asterisk or FreeSWITCH) certs are self-signed.
>
> Relevant logs (level 4):
>
> Apr 24 15:54:19 debian7 /usr/sbin/kamailio[11169]: DEBUG: dispatcher 
> [dispatch.c:2453]: ds_check_timer(): probing set #2, URI 
> sips:10.0.0.1:5061
>
> Apr 24 15:54:19 debian7 /usr/sbin/kamailio[11169]: DEBUG: tm 
> [uac.c:243]: t_uac_prepare(): DEBUG:tm:t_uac: 
> next_hop=<sips:10.0.0.1:5061>
>
> Apr 24 15:54:19 debian7 /usr/sbin/kamailio[11169]: DEBUG: tm 
> [uac.c:182]: dlg2hash(): DEBUG: dlg2hash: 49688
>
> Apr 24 15:54:19 debian7 /usr/sbin/kamailio[11169]: DEBUG: <core> 
> [tcp_main.c:1849]: tcp_send(): tcp_send: no open tcp connection found, 
> opening new one
>
> Apr 24 15:54:19 debian7 /usr/sbin/kamailio[11169]: DEBUG: <core> 
> [ip_addr.c:243]: print_ip(): tcpconn_new: new tcp connection: 10.0.0.1
>
> Apr 24 15:54:19 debian7 /usr/sbin/kamailio[11169]: DEBUG: <core> 
> [tcp_main.c:1096]: tcpconn_new(): tcpconn_new: on port 5061, type 3
>
> Apr 24 15:54:19 debian7 /usr/sbin/kamailio[11169]: DEBUG: <core> 
> [tcp_main.c:1408]: tcpconn_add(): tcpconn_add: hashes: 1217:0:0, 1
>
> Apr 24 15:54:19 debian7 /usr/sbin/kamailio[11169]: DEBUG: tls 
> [tls_server.c:178]: tls_complete_init(): Using TLS domain TLSc<default>
>
> Apr 24 15:54:19 debian7 /usr/sbin/kamailio[11169]: DEBUG: tls 
> [tls_domain.c:700]: sr_ssl_ctx_info_callback(): SSL handshake started
>
> Apr 24 15:54:19 debian7 /usr/sbin/kamailio[11169]: DEBUG: <core> 
> [tcp_main.c:2737]: tcpconn_1st_send(): pending write on new connection 
> 0x7fd4813cdb70  (-1/225 bytes written)
>
> Apr 24 15:54:19 debian7 /usr/sbin/kamailio[11177]: DEBUG: <core> 
> [tcp_main.c:3624]: handle_ser_child(): handle_ser_child: read 
> response= 7fd4813cdb70, 5, fd 32 from 9 (11169)
>
> Apr 24 15:54:19 debian7 /usr/sbin/kamailio[11177]: DEBUG: <core> 
> [io_wait.h:390]: io_watch_add(): DBG: io_watch_add(0x89dc40, 32, 2, 
> 0x7fd4813cdb70), fd_no=24
>
> Apr 24 15:54:19 debian7 /usr/sbin/kamailio[11169]: DEBUG: dispatcher 
> [dispatch.c:2453]: ds_check_timer(): probing set #1, URI 
> sips:10.0.0.1:5061
>
> Apr 24 15:54:19 debian7 /usr/sbin/kamailio[11169]: DEBUG: tm 
> [uac.c:243]: t_uac_prepare(): DEBUG:tm:t_uac: 
> next_hop=<sips:10.0.0.1:5061>
>
> Apr 24 15:54:19 debian7 /usr/sbin/kamailio[11169]: DEBUG: tm 
> [uac.c:182]: dlg2hash(): DEBUG: dlg2hash: 49689
>
> Apr 24 15:54:20 debian7 /usr/sbin/kamailio[11177]: DEBUG: <core> 
> [io_wait.h:796]: io_watch_chg(): DBG: io_watch_chg (0x89dc40, 32, 0x1, 
> 0xffffffff) fd_no=25 called
>
> Apr 24 15:54:20 debian7 /usr/sbin/kamailio[11177]: DEBUG: <core> 
> [io_wait.h:617]: io_watch_del(): DBG: io_watch_del (0x89dc40, 32, -1, 
> 0x0) fd_no=25 called
>
> Apr 24 15:54:20 debian7 /usr/sbin/kamailio[11177]: DEBUG: <core> 
> [tcp_main.c:4302]: handle_tcpconn_ev(): tcp: DBG: sending to child, 
> events 1
>
> Apr 24 15:54:20 debian7 /usr/sbin/kamailio[11177]: DEBUG: <core> 
> [tcp_main.c:3973]: send2child(): selected tcp worker 0 13(11173) for 
> activity on [tls:192.168.142.170:5061], 0x7fd4813cdb70
>
> Apr 24 15:54:20 debian7 /usr/sbin/kamailio[11173]: DEBUG: <core> 
> [tcp_read.c:1510]: handle_io(): received n=8 con=0x7fd4813cdb70, fd=7
>
> Apr 24 15:54:20 debian7 /usr/sbin/kamailio[11173]: DEBUG: <core> 
> [io_wait.h:390]: io_watch_add(): DBG: io_watch_add(0x8e2040, 7, 2, 
> 0x7fd4813cdb70), fd_no=1
>
> Apr 24 15:54:20 debian7 /usr/sbin/kamailio[11173]: DEBUG: <core> 
> [tcp_main.c:2556]: tcpconn_do_send(): tcp_send: sending...
>
> Apr 24 15:54:20 debian7 /usr/sbin/kamailio[11173]: DEBUG: <core> 
> [tcp_main.c:2590]: tcpconn_do_send(): tcp_send: after real write: c= 
> 0x7fd4813cdb70 n=198 fd=7
>
> Apr 24 15:54:20 debian7 /usr/sbin/kamailio[11173]: DEBUG: <core> 
> [tcp_main.c:2591]: tcpconn_do_send(): tcp_send: buf=#012#026#003#001
>
> Apr 24 15:54:20 debian7 /usr/sbin/kamailio[11173]: DEBUG: tls 
> [tls_domain.c:712]: sr_ssl_ctx_info_callback(): SSL handshake done
>
> Apr 24 15:54:20 debian7 /usr/sbin/kamailio[11173]: DEBUG: tls 
> [tls_domain.c:715]: sr_ssl_ctx_info_callback(): SSL disable renegotiation
>
> Apr 24 15:54:20 debian7 /usr/sbin/kamailio[11173]: DEBUG: tls 
> [tls_server.c:413]: tls_connect(): TLS connect successful
>
> Apr 24 15:54:20 debian7 /usr/sbin/kamailio[11173]: DEBUG: tls 
> [tls_server.c:420]: tls_connect(): tls_connect: new connection to 
> 10.0.0.1:5061 using TLSv1/SSLv3 AES256-SHA 256
>
> Apr 24 15:54:20 debian7 /usr/sbin/kamailio[11173]: DEBUG: tls 
> [tls_server.c:423]: tls_connect(): tls_connect: sending socket: 
> 192.168.142.170:43914
>
> Apr 24 15:54:20 debian7 /usr/sbin/kamailio[11173]: DEBUG: tls 
> [tls_server.c:305]: tls_dump_cert_info(): tls_connect: server 
> certificate subject:/CN=REMOVED/O=REMOVED
>
> Apr 24 15:54:20 debian7 /usr/sbin/kamailio[11173]: DEBUG: tls 
> [tls_server.c:309]: tls_dump_cert_info(): tls_connect: server 
> certificate issuer:/CN=REMOVED/O=REMOVED
>
> Apr 24 15:54:20 debian7 /usr/sbin/kamailio[11173]: DEBUG: tls 
> [tls_server.c:429]: tls_connect(): WARNING: tls_connect: server 
> certificate verification failed!!!
>
> Apr 24 15:54:20 debian7 /usr/sbin/kamailio[11173]: DEBUG: tls 
> [tls_dump_vf.c:105]: tls_dump_verification_failure(): verification 
> failure: self signed certificate in certificate chain
>
> Apr 24 15:54:20 debian7 /usr/sbin/kamailio[11173]: DEBUG: <core> 
> [tcp_main.c:2556]: tcpconn_do_send(): tcp_send: sending...
>
> Apr 24 15:54:20 debian7 /usr/sbin/kamailio[11173]: DEBUG: <core> 
> [tcp_main.c:2590]: tcpconn_do_send(): tcp_send: after real write: c= 
> 0x7fd4813cdb70 n=805 fd=7
>
> Apr 24 15:54:20 debian7 /usr/sbin/kamailio[11173]: DEBUG: <core> 
> [tcp_main.c:2591]: tcpconn_do_send(): tcp_send: buf=[...REMOVED...]
>
> Apr 24 15:54:20 debian7 /usr/sbin/kamailio[11173]: DEBUG: <core> 
> [tcp_read.c:1317]: tcp_read_req(): tcp_read_req: content-length= 0
>
> Apr 24 15:54:20 debian7 /usr/sbin/kamailio[11173]: DEBUG: <core> 
> [parser/msg_parser.c:633]: parse_msg(): SIP Reply  (status):
>
> Apr 24 15:54:20 debian7 /usr/sbin/kamailio[11173]: DEBUG: <core> 
> [parser/msg_parser.c:635]: parse_msg():  version: <SIP/2.0>
>
> Apr 24 15:54:20 debian7 /usr/sbin/kamailio[11173]: DEBUG: <core> 
> [parser/msg_parser.c:637]: parse_msg():  status:  <404>
>
> Apr 24 15:54:20 debian7 /usr/sbin/kamailio[11173]: DEBUG: <core> 
> [parser/msg_parser.c:639]: parse_msg():  reason:  <Not Found>
>
> Apr 24 15:54:20 debian7 /usr/sbin/kamailio[11173]: DEBUG: <core> 
> [parser/parse_via.c:1284]: parse_via_param(): Found param type 232, 
> <branch> = <z9hG4bK812c.b064d3e3000000000000000000000000.0>; state=6
>
> Apr 24 15:54:20 debian7 /usr/sbin/kamailio[11173]: DEBUG: <core> 
> [parser/parse_via.c:1284]: parse_via_param(): Found param type 234, 
> <received> = <REMOVED>; state=6
>
> Apr 24 15:54:20 debian7 /usr/sbin/kamailio[11173]: DEBUG: <core> 
> [parser/parse_via.c:1284]: parse_via_param(): Found param type 235, 
> <rport> = <59525>; state=16
>
> Apr 24 15:54:20 debian7 /usr/sbin/kamailio[11173]: DEBUG: <core> 
> [parser/parse_via.c:2672]: parse_via(): end of header reached, state=5
>
> Apr 24 15:54:20 debian7 /usr/sbin/kamailio[11173]: DEBUG: <core> 
> [parser/msg_parser.c:513]: parse_headers(): parse_headers: Via found, 
> flags=2
>
> Apr 24 15:54:20 debian7 /usr/sbin/kamailio[11173]: DEBUG: <core> 
> [parser/msg_parser.c:515]: parse_headers(): parse_headers: this is the 
> first via
>
> Apr 24 15:54:20 debian7 /usr/sbin/kamailio[11173]: DEBUG: <core> 
> [receive.c:152]: receive_msg(): After parse_msg...
>
> Apr 24 15:54:20 debian7 /usr/sbin/kamailio[11173]: DEBUG: tm 
> [t_lookup.c:1072]: t_check_msg(): DEBUG: t_check_msg: msg id=1 global 
> id=0 T start=0xffffffffffffffff
>
> Apr 24 15:54:20 debian7 /usr/sbin/kamailio[11173]: DEBUG: <core> 
> [parser/parse_addr_spec.c:176]: parse_to_param(): DEBUG: add_param: 
> tag=as232959d2
>
> Apr 24 15:54:20 debian7 /usr/sbin/kamailio[11173]: DEBUG: <core> 
> [parser/parse_addr_spec.c:893]: parse_addr_spec(): end of header 
> reached, state=29
>
> Apr 24 15:54:20 debian7 /usr/sbin/kamailio[11173]: DEBUG: <core> 
> [parser/msg_parser.c:190]: get_hdr_field(): DEBUG: get_hdr_field: <To> 
> [43]; uri=[sips:10.0.0.1:5061]
>
> Apr 24 15:54:20 debian7 /usr/sbin/kamailio[11173]: DEBUG: <core> 
> [parser/msg_parser.c:192]: get_hdr_field(): DEBUG: to body 
> [<sips:10.0.0.1:5061>]
>
> Apr 24 15:54:20 debian7 /usr/sbin/kamailio[11173]: DEBUG: <core> 
> [parser/msg_parser.c:170]: get_hdr_field(): get_hdr_field: cseq 
> <CSeq>: <10> <OPTIONS>
>
> Apr 24 15:54:20 debian7 /usr/sbin/kamailio[11173]: DEBUG: tm 
> [t_lookup.c:949]: t_reply_matching(): DEBUG: t_reply_matching: hash 
> 49688 label 0 branch 0
>
> Apr 24 15:54:20 debian7 /usr/sbin/kamailio[11173]: DEBUG: tm 
> [t_lookup.c:1004]: t_reply_matching(): DEBUG: t_reply_matching: reply 
> matched (T=0x7fd4813cc530)!
>
> Apr 24 15:54:20 debian7 /usr/sbin/kamailio[11173]: DEBUG: tm 
> [t_lookup.c:1141]: t_check_msg(): DEBUG: t_check_msg: msg id=1 global 
> id=1 T end=0x7fd4813cc530
>
> Apr 24 15:54:20 debian7 /usr/sbin/kamailio[11173]: DEBUG: tm 
> [t_reply.c:2206]: reply_received(): DEBUG: reply_received: org. status 
> uas=0, uac[0]=0 local=2 is_invite=0)
>
> Apr 24 15:54:20 debian7 /usr/sbin/kamailio[11173]: DEBUG: tm 
> [t_reply.c:1304]: t_should_relay_response(): ->>>>>>>>> T_code=0, 
> new_code=404
>
> Apr 24 15:54:20 debian7 /usr/sbin/kamailio[11173]: DEBUG: tm 
> [t_reply.c:2086]: local_reply(): DEBUG: local_reply: branch=0, save=0, 
> winner=0
>
> Apr 24 15:54:20 debian7 /usr/sbin/kamailio[11173]: DEBUG: tm 
> [t_reply.c:2123]: local_reply(): DEBUG: local transaction completed
>
> Apr 24 15:54:20 debian7 /usr/sbin/kamailio[11173]: DEBUG: tm 
> [t_hooks.c:288]: run_trans_callbacks_internal(): DBG: 
> trans=0x7fd4813cc530, callback type 1024, id 0 entered
>
> Apr 24 15:54:20 debian7 /usr/sbin/kamailio[11173]: DEBUG: dispatcher 
> [dispatch.c:2392]: ds_options_callback(): OPTIONS-Request was finished 
> with code 404 (to sips:10.0.0.1:5061, group 2)
>
> Apr 24 15:54:20 debian7 /usr/sbin/kamailio[11173]: DEBUG: tm 
> [t_reply.c:1663]: cleanup_uac_timers(): DEBUG: cleanup_uac_timers: 
> RETR/FR timers reset
>
> Apr 24 15:54:20 debian7 /usr/sbin/kamailio[11173]: DEBUG: <core> 
> [usr_avp.c:644]: destroy_avp_list(): DEBUG:destroy_avp_list: 
> destroying list (nil)
>
> Apr 24 15:54:20 debian7 /usr/sbin/kamailio[11173]: DEBUG: <core> 
> [usr_avp.c:644]: destroy_avp_list(): DEBUG:destroy_avp_list: 
> destroying list (nil)
>
> Apr 24 15:54:20 debian7 /usr/sbin/kamailio[11173]: DEBUG: <core> 
> [usr_avp.c:644]: destroy_avp_list(): DEBUG:destroy_avp_list: 
> destroying list (nil)
>
> Apr 24 15:54:20 debian7 /usr/sbin/kamailio[11173]: DEBUG: <core> 
> [usr_avp.c:644]: destroy_avp_list(): DEBUG:destroy_avp_list: 
> destroying list (nil)
>
> Apr 24 15:54:20 debian7 /usr/sbin/kamailio[11173]: DEBUG: <core> 
> [usr_avp.c:644]: destroy_avp_list(): DEBUG:destroy_avp_list: 
> destroying list (nil)
>
> Apr 24 15:54:20 debian7 /usr/sbin/kamailio[11173]: DEBUG: <core> 
> [usr_avp.c:644]: destroy_avp_list(): DEBUG:destroy_avp_list: 
> destroying list (nil)
>
> Apr 24 15:54:20 debian7 /usr/sbin/kamailio[11173]: DEBUG: <core> 
> [xavp.c:448]: xavp_destroy_list(): destroying xavp list (nil)
>
> Apr 24 15:54:20 debian7 /usr/sbin/kamailio[11173]: DEBUG: <core> 
> [receive.c:296]: receive_msg(): receive_msg: cleaning up
>
> Apr 24 15:54:26 debian7 /usr/sbin/kamailio[11173]: DEBUG: <core> 
> [io_wait.h:617]: io_watch_del(): DBG: io_watch_del (0x8e2040, 7, -1, 
> 0x10) fd_no=2 called
>
> Apr 24 15:54:26 debian7 /usr/sbin/kamailio[11173]: DEBUG: <core> 
> [tcp_read.c:1437]: release_tcpconn(): releasing con 0x7fd4813cdb70, 
> state 1, fd=7, id=1
>
> Apr 24 15:54:26 debian7 /usr/sbin/kamailio[11173]: DEBUG: <core> 
> [tcp_read.c:1438]: release_tcpconn():  extra_data 0x7fd4813b51f0
>
> Apr 24 15:54:26 debian7 /usr/sbin/kamailio[11177]: DEBUG: <core> 
> [tcp_main.c:3385]: handle_tcp_child(): handle_tcp_child: reader 
> response= 7fd4813cdb70, 1 from 0
>
> Apr 24 15:54:26 debian7 /usr/sbin/kamailio[11177]: DEBUG: <core> 
> [io_wait.h:390]: io_watch_add(): DBG: io_watch_add(0x89dc40, 32, 2, 
> 0x7fd4813cdb70), fd_no=24
>
> Apr 24 15:54:26 debian7 /usr/sbin/kamailio[11177]: DEBUG: <core> 
> [tcp_main.c:3515]: handle_tcp_child(): handle_tcp_child: CONN_RELEASE  
> 0x7fd4813cdb70 refcnt= 1
>
> Apr 24 15:54:49 debian7 /usr/sbin/kamailio[11169]: DEBUG: tm 
> [t_reply.c:1304]: t_should_relay_response(): ->>>>>>>>> T_code=0, 
> new_code=408
>
> Apr 24 15:54:49 debian7 /usr/sbin/kamailio[11169]: DEBUG: tm 
> [t_reply.c:2086]: local_reply(): DEBUG: local_reply: branch=0, save=0, 
> winner=0
>
> Apr 24 15:54:49 debian7 /usr/sbin/kamailio[11169]: DEBUG: tm 
> [t_reply.c:2123]: local_reply(): DEBUG: local transaction completed
>
> Apr 24 15:54:49 debian7 /usr/sbin/kamailio[11169]: DEBUG: tm 
> [t_hooks.c:288]: run_trans_callbacks_internal(): DBG: 
> trans=0x7fd4813e5890, callback type 1024, id 0 entered
>
> Apr 24 15:54:49 debian7 /usr/sbin/kamailio[11169]: DEBUG: dispatcher 
> [dispatch.c:2392]: ds_options_callback(): OPTIONS-Request was finished 
> with code 408 (to sips:10.0.0.1:5061, group 1)
>
> Probing set #2 goes OK.
>
> Probing set #1: starts probing at 15:54:19, and times out 30" later at 
> 15:54:49.
>
> Is this a bug, a misconfiguration, or perhaps a wrong way to manage 
> dispatcher sets using TLS?
>
> Additional question: Is it not expected that a persistent TLS 
> connection is established with a 'sips' dispatcher destination?
>
> Thanks in advance for the time to read through all this!
>
> Giacomo
>
> Truphone Limited, registered in England and Wales (registered company 
> number: 04187081). Registered office: CityPoint, One Ropemaker Street, 
> London EC2Y 9SS. VAT No. GB 851 5278 19
>
> This e-mail, and any attachment(s), may contain information which is 
> confidential and/or privileged, and is intended for the addressee 
> only. If you are not the intended recipient, you may not use, 
> disclose, copy or distribute this information in any manner 
> whatsoever. If you have received this e-mail in error, please contact 
> the sender immediately and delete it.
>
>
> _______________________________________________
> SIP Express Router (SER) and Kamailio (OpenSER) - sr-users mailing list
> sr-users at lists.sip-router.org
> http://lists.sip-router.org/cgi-bin/mailman/listinfo/sr-users

-- 
Daniel-Constantin Mierla - http://www.asipto.com
http://twitter.com/#!/miconda - http://www.linkedin.com/in/miconda

-------------- next part --------------
An HTML attachment was scrubbed...
URL: <http://lists.sip-router.org/pipermail/sr-users/attachments/20140428/a326e356/attachment.html>

More information about the sr-users mailing list