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> [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