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.
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:
A destination requires TLS (e.g. sips:10.0.0.1:5061)
The destination has flags 8 (i.e. in normal conditions we want AP,
Active Probing) and dispatcher uses ds_probing_mode 1 (always probe)
- 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@lists.sip-router.org http://lists.sip-router.org/cgi-bin/mailman/listinfo/sr-users
Thanks Daniel,
I’ve changed the destination format and I’m seeing the same behaviour, but I made tests in various scenarios and my feeling is that Kamailio is doing the right thing.
I don’t want to waste the readers’ time for what doesn’t appear to be an issue with Kamailio, so be warned if you keep reading.
I moved to TCP (e.g. sip:10.0.0.1;transport=tcp) to have a better idea whether the problem was related to TLS only or not. The behaviour was basically the same, but it was easier to debug.
Initially Kamailio sends the 2 OPTIONS requests within the same packet, e.g.:
T 2014/04/28 16:04:15.715917 MYIP:44191 -> 10.0.0.1:5060 [AP] OPTIONS sip:10.0.0.1:5060;transport=tcp SIP/2.0. Via: SIP/2.0/TCP 192.168.142.170;branch=z9hG4bKe47.39ae71f3000000000000000000000000.0. To: sip:10.0.0.1:5060;transport=tcp. From: sip:dispatcher@localhost;tag=533cb9e91f4b999cf76861cbb9ed54ed-2a2c. CSeq: 10 OPTIONS. Call-ID: 75918ba6133d8b07-15565@127.0.0.1. Max-Forwards: 70. Content-Length: 0. User-Agent: kamailio (4.1.3 (x86_64/linux)). . OPTIONS sip:10.0.0.1:5060;transport=tcp SIP/2.0. Via: SIP/2.0/TCP 192.168.142.170;branch=z9hG4bKc57.0786b917000000000000000000000000.0. To: sip:10.0.0.1:5060;transport=tcp. From: sip:dispatcher@localhost;tag=533cb9e91f4b999cf76861cbb9ed54ed-7f23. CSeq: 10 OPTIONS. Call-ID: 75918ba6133d8b08-15565@127.0.0.1. Max-Forwards: 70. Content-Length: 0. User-Agent: kamailio (4.1.3 (x86_64/linux)). .
and Asterisk replies to both:
T 2014/04/28 16:04:15.717998 10,0.0.1:5060 -> MYIP:44191 [AP] SIP/2.0 404 Not Found. Via: SIP/2.0/TCP 192.168.142.170;branch=z9hG4bKe47.39ae71f3000000000000000000000000.0;received=MYIP;rport=44191. From: sip:dispatcher@localhost;tag=533cb9e91f4b999cf76861cbb9ed54ed-2a2c. To: sip:10.0.0.1:5060;transport=tcp;tag=as7421c5d4. Call-ID: 75918ba6133d8b07-15565@127.0.0.1. CSeq: 10 OPTIONS. Server: Truphone TAMS Server. Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO, PUBLISH. Supported: replaces, timer. Accept: application/sdp. Content-Length: 0. .
T 2014/04/28 16:04:15.802983 10,0.0.1:5060 -> MYIP:44191 [AP] SIP/2.0 404 Not Found. Via: SIP/2.0/TCP 192.168.142.170;branch=z9hG4bKc57.0786b917000000000000000000000000.0;received=MYIP;rport=44191. From: sip:dispatcher@localhost;tag=533cb9e91f4b999cf76861cbb9ed54ed-7f23. To: sip:10.0.0.1:5060;transport=tcp;tag=as595d9838. Call-ID: 75918ba6133d8b08-15565@127.0.0.1. CSeq: 10 OPTIONS. Server: Truphone TAMS Server. Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO, PUBLISH. Supported: replaces, timer. Accept: application/sdp. Content-Length: 0. .
but also Asterisk (1.8) marks the dialog for destruction:
“Scheduling destruction of SIP dialog '75918ba6133d8b08-15565@127.0.0.1' in 32000 ms (Method: OPTIONS)”
When Kamailio sends the following probe (after 30” from the first), Asterisk does not respond, and resets the TCP socket instead:
T 2014/04/28 16:04:45.620346 MYIP:44191 -> 10.0.0.1:5060 [AP] OPTIONS sip:10.0.0.1:5060;transport=tcp SIP/2.0. Via: SIP/2.0/TCP 192.168.142.170;branch=z9hG4bKb57.25e82864000000000000000000000000.0. To: sip:10.0.0.1:5060;transport=tcp. From: sip:dispatcher@localhost;tag=533cb9e91f4b999cf76861cbb9ed54ed-8f22. CSeq: 10 OPTIONS. Call-ID: 75918ba6133d8b09-15565@127.0.0.1. Max-Forwards: 70. Content-Length: 0. User-Agent: kamailio (4.1.3 (x86_64/linux)). .
T 2014/04/28 16:04:45.622140 MYIP:44191 -> 10.0.0.1:5060 [AP] OPTIONS sip:10.0.0.1:5060;transport=tcp SIP/2.0. Via: SIP/2.0/TCP 192.168.142.170;branch=z9hG4bKa87.61f85cf3000000000000000000000000.0. To: sip:10.0.0.1:5060;transport=tcp. From: sip:dispatcher@localhost;tag=533cb9e91f4b999cf76861cbb9ed54ed-5e98. CSeq: 10 OPTIONS. Call-ID: 75918ba6133d8b0a-15565@127.0.0.1. Max-Forwards: 70. Content-Length: 0. User-Agent: kamailio (4.1.3 (x86_64/linux)). .
<<NO REPLY>>
With tcpdump:
16:04:45.620352 IP (tos 0x0, ttl 241, id 28746, offset 0, flags [none], proto TCP (6), length 448) MYIP.44191 > 10.0.0.1.5060: Flags [P.], cksum 0x95b7 (correct), seq 817:1225, ack 1057, win 63184, length 408 16:04:45.620516 IP (tos 0x0, ttl 64, id 45429, offset 0, flags [DF], proto TCP (6), length 40) 10.0.0.1.5060 > MYIP.44191: Flags [R.], cksum 0xf813 (incorrect -> 0x1802), seq 1057, ack 1225, win 17136, length 0 16:04:45.622143 IP (tos 0x0, ttl 241, id 25284, offset 0, flags [none], proto TCP (6), length 448) MYIP.44191 > 10.0.0.1.5060: Flags [P.], cksum 0x57ca (correct), seq 1225:1633, ack 1057, win 63184, length 408 16:04:45.622164 IP (tos 0x0, ttl 64, id 0, offset 0, flags [DF], proto TCP (6), length 40) 10.0.0.1.5060 > MYIP.44191: Flags [R], cksum 0xb792 (correct), seq 2351215564, win 0, length 0
This second group of OPTIONS times out, and Kamailio will open a new socket for the following probe. Changing the dispatcher’s probing interval from 30” to 10” confirms that OPTIONS requests within about 30” from the initial ones are correctly handled, but once Asterisk has destroyed the dialog, Kamailio times out and needs to create a new socket (so every about 30” kamailio logs a 408). I haven’t managed to replicate the problem with FS, so at the moment it seems only an issue with how Asterisk manages the TCP sockets created by Kamailio for probing.
If you’ve read so far and have any hint or reference on why Asterisk behaves in this way, or examples of TCP/TLS destinations involving Asterisk for Kamailio dispatcher, I’d be grateful.
Kind Regards, Giacomo
From: sr-users-bounces@lists.sip-router.org [mailto:sr-users-bounces@lists.sip-router.org] On Behalf Of Daniel-Constantin Mierla Sent: 28 April 2014 09:07 To: Kamailio (SER) - Users Mailing List Subject: Re: [SR-Users] Dispatcher marks TLS destinations as Inactive when present in more than one set
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 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.
_______________________________________________
SIP Express Router (SER) and Kamailio (OpenSER) - sr-users mailing list
sr-users@lists.sip-router.orgmailto:sr-users@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
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.
-
Daniel-Constantin Mierla -
Giacomo Vacca