29 Oct
2020
29 Oct
'20
8:20 p.m.
Hey all,
I’m a little stuck on an implementation of a set of dispatchers via TCP. There are some
oddities about the behavior of the TCP source port of the Kamailio tcp worker/s, and maybe
this is expected, but it doesn’t seem valid. For instance, I have a dispatcher:
"RECORDS": [{
"SET": {
"ID": 1,
"TARGETS": [{
"DEST": {
"URI": “sip:2.2.2.2:5060;transport=tcp",
"FLAGS": "AP",
"PRIORITY": 5
}
}]
}
}]
But when Kamailio sends an OPTIONS keep alive, the source port for the worker is 33940,
and not 5060 (which is the TCP listen port), as received by Freeswitch:
recv 447 bytes from tcp/[1.1.1.1]:33940 at 18:58:24.958720:
------------------------------------------------------------------------
OPTIONS sip:2.2.2.2:5060;transport=tcp SIP/2.0
Via: SIP/2.0/TCP 1.1.1.1;branch=z9hG4bK1525.80a9e442000000000000000000000000.0
To: <sip:2.2.2.2:5060;transport=tcp>
From: <sip:inbound-kamailio-01>;tag=3c52ba62ee4c4621b9660728159919d3-cda8066f
CSeq: 10 OPTIONS
Call-ID: 3aa18693487268dc-2790(a)1.1.1.1
Max-Forwards: 70
Content-Length: 0
User-Agent: kamailio (5.4.2 (x86_64/linux))
------------------------------------------------------------------------
Also, I get weird debug messages when this tcp worker is spun up (specifically about
Resource temporarily unavailable):
11(2790) DEBUG: dispatcher [dispatch.c:3340]: ds_ping_result_helper(): probe all, mode
DS_PROBE_ALL
11(2790) DEBUG: dispatcher [dispatch.c:3383]: ds_ping_set(): probing set #1, URI
sip:2.2.2.2:5060;transport=tcp
11(2790) DEBUG: dispatcher [dispatch.c:3414]: ds_ping_set(): Default ping_from:
sip:inbound-kamailio-01
11(2790) DEBUG: dispatcher [dispatch.c:3424]: ds_ping_set(): Default outbound proxy:
11(2790) DEBUG: tm [uac.c:450]: t_uac_prepare():
next_hop=<sip:2.2.2.2:5060;transport=tcp>
11(2790) DEBUG: tm [uac.c:158]: dlg2hash(): hashid 21073
11(2790) DEBUG: <core> [core/tcp_main.c:1993]: tcp_send(): no open tcp connection
found, opening new one
11(2790) DEBUG: <core> [core/ip_addr.c:229]: print_ip(): tcpconn_new: new tcp
connection: 2.2.2.2
11(2790) DEBUG: <core> [core/tcp_main.c:1175]: tcpconn_new(): on port 5060, type 2,
socket -1
11(2790) DEBUG: <core> [core/tcp_main.c:1494]: tcpconn_add(): hashes: 2712:0:0, 1
11(2790) DEBUG: <core> [core/tcp_main.c:2886]: tcpconn_1st_send(): pending write on
new connection 0x7f24e64c1e18 sock 8 (-1/447 bytes written) (err: 11 - Resource
temporarily unavailable)
11(2790) DEBUG: tm [uac.c:678]: send_prepared_request_impl(): uac: 0x7f24e65285a8 branch:
0 to 2.2.2.2:5060
11(2790) DEBUG: <core> [core/onsend.c:50]: run_onsend(): required parameters are not
available - ignoring
27(2806) DEBUG: <core> [core/tcp_main.c:3792]: handle_ser_child(): read response=
7f24e64c1e18, 5, fd 46 from 11 (2790)
27(2806) DEBUG: <core> [core/io_wait.h:375]: io_watch_add(): DBG:
io_watch_add(0x56490f0f8060, 46, 2, 0x7f24e64c1e18), fd_no=37
27(2806) DEBUG: <core> [core/io_wait.h:782]: io_watch_chg(): DBG: io_watch_chg
(0x56490f0f8060, 46, 0x1, 0xffffffff) fd_no=38 called
27(2806) DEBUG: <core> [core/io_wait.h:600]: io_watch_del(): DBG: io_watch_del
(0x56490f0f8060, 46, -1, 0x0) fd_no=38 called
27(2806) DEBUG: <core> [core/tcp_main.c:4457]: handle_tcpconn_ev(): sending to
child, events 1
27(2806) DEBUG: <core> [core/tcp_main.c:4127]: send2child(): selected tcp worker
idx:0 proc:19 pid:2798 for activity on [tcp:1.1.1.1:5060], 0x7f24e64c1e18
19(2798) DEBUG: <core> [core/tcp_read.c:1749]: handle_io(): received n=8
con=0x7f24e64c1e18, fd=8
19(2798) DEBUG: <core> [core/tcp_read.c:1548]: tcp_read_req(): content-length=0
19(2798) DEBUG: <core> [core/parser/msg_parser.c:620]: parse_msg(): SIP Reply
(status):
19(2798) DEBUG: <core> [core/parser/msg_parser.c:622]: parse_msg(): version:
<SIP/2.0>
19(2798) DEBUG: <core> [core/parser/msg_parser.c:624]: parse_msg(): status:
<200>
19(2798) DEBUG: <core> [core/parser/msg_parser.c:626]: parse_msg(): reason:
<OK>
19(2798) DEBUG: <core> [core/parser/parse_via.c:1303]: parse_via_param(): Found
param type 232, <branch> = <z9hG4bK1525.80a9e442000000000000000000000000.0>;
state=6
19(2798) DEBUG: <core> [core/parser/parse_via.c:1303]: parse_via_param(): Found
param type 235, <rport> = <33940>; state=16
19(2798) DEBUG: <core> [core/parser/parse_via.c:2639]: parse_via(): end of header
reached, state=5
19(2798) DEBUG: <core> [core/parser/msg_parser.c:498]: parse_headers(): Via found,
flags=2
19(2798) DEBUG: <core> [core/parser/msg_parser.c:500]: parse_headers(): this is the
first via
19(2798) DEBUG: <core> [core/parser/parse_addr_spec.c:185]: parse_to_param(): add
param: tag=1mB9HryQ8ZBFc
19(2798) DEBUG: <core> [core/parser/parse_addr_spec.c:864]: parse_addr_spec(): end
of header reached, state=29
19(2798) DEBUG: <core> [core/parser/msg_parser.c:171]: get_hdr_field(): <To>
[59]; uri=[sip:2.2.2.2:5060;transport=tcp]
19(2798) DEBUG: <core> [core/parser/msg_parser.c:174]: get_hdr_field(): to body
(39)[<sip:2.2.2.2:5060;transport=tcp>], to tag (13)[1mB9HryQ8ZBFc]
19(2798) DEBUG: <core> [core/parser/msg_parser.c:152]: get_hdr_field(): cseq
<CSeq>: <10> <OPTIONS>
19(2798) DEBUG: <core> [core/receive.c:319]: receive_msg(): --- received sip message
- reply - call-id: [3aa18693487268dc-2790(a)1.1.1.1] - cseq: [10 OPTIONS]
19(2798) DEBUG: <core> [core/parser/msg_parser.c:185]: get_hdr_field():
content_length=0
19(2798) DEBUG: <core> [core/parser/msg_parser.c:89]: get_hdr_field(): found end of
header
Are these SIP messages expected to come from other ports than the listen port (5060 in
this case)? Also, if the worker source port is not 5060, shouldn’t the SIP message get
updated with the correct port?
In the case of OPTIONS, Freeswitch is replying correctly to the source port: 33940.
However, in the case of an in dialog BYE, Freeswitch is NOT replying to the source port of
the Kamailio messages, but only to port 5060. Here is an example (relayed from web
sockets to freeswitch over TCP) INVITE (as received from Freeswitch):
recv 1481 bytes from tcp/[1.1.1.1]:33940 at 16:56:47.920698:
------------------------------------------------------------------------
INVITE sip:991012@sip.domain <sip:991012@sip.domain>.com SIP/2.0
Record-Route: <sip:1.1.1.1;transport=tcp;r2=on;lr;nat=yes>
Record-Route: <sip:1.1.1.1:5061;transport=tls;r2=on;lr;nat=yes>
Via: SIP/2.0/TCP 1.1.1.1;branch=z9hG4bKd408.3f53e940ccb20c1033df4b3a8ebd8a34.0;i=1
Via: SIP/2.0/TLS
172.22.199.110:55304;received=5.5.5.5;rport=39518;branch=z9hG4bKPj5Css6JomCt9Cli2cCINbXi4FbPM5wewG;alias
Max-Forwards: 69
From: "Noah Mehl"
<sip:5135555555@inbound-jail>;tag=s3i3y2tiOCgnUId5TD4Vp0UChf9GyEy9
To: <sip:991012@inbound-jail>
Contact: <sip:74895612@172.22.199.110:54887;transport=tls;alias=5.5.5.5~39518~3>
Call-ID: 5aoRBMBHahxqSLzrIpFnlfRz.UcGsmfq
CSeq: 27271 INVITE
Allow: SUBSCRIBE, NOTIFY, INVITE, ACK, BYE, CANCEL, UPDATE, MESSAGE, REFER
Supported: replaces, norefersub, gruu
User-Agent: Blink Pro 4.6.0 (MacOSX)
Content-Type: application/sdp
Content-Length: 528
v=0
o=- 3812979407 3812979407 IN IP4 5.5.5.5
s=Blink Pro 4.6.0 (MacOSX)
t=0 0
m=audio 50016 RTP/SAVP 113 0 101
c=IN IP4 5.5.5.5
a=rtcp:50017
a=rtpmap:113 opus/48000/2
a=fmtp:113 useinbandfec=1
a=rtpmap:0 PCMU/8000
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-16
a=crypto:1 AES_CM_128_HMAC_SHA1_80 inline:UhHq6hth9HqALmiJ3AEeoGkixObBzkLURG60wJKT
a=crypto:2 AES_CM_128_HMAC_SHA1_32 inline:VKYaSCVwgvXCPaRvudTrgLORhWmOA7wyDJVeGjcu
a=sendrecv
a=oldmediaip:172.22.199.110
a=oldmediaip:172.22.199.110
------------------------------------------------------------------------
This doesn’t seem valid, as the top Via doesn’t have a port specified?
For reference, just rebuilt form the 5.4 branch today:
commit 62dff5b8b157236cae7defe64291a6e4a8ae27b5 (upstream/5.4)
Author: Kamailio Dev <kamailio.dev(a)kamailio.org>
Date: Wed Oct 28 20:16:28 2020 +0100
modules: readme files regenerated - modules ... [skip ci]
Thanks!
~Noah