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