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