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

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 a lower 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.