[OpenSIPS-Users] Opensips 3.2.8 does not send message with opensips-cli command

Mon Sep 26 07:54:25 UTC 2022

Hi Team,

We use MI command to send messages to a user successfully with opensips
3.1, but after we upgraded to 3.2.8, the message can't be sent with
opensips-cli command.

We compared the logs and found that when the command was run on 3.2.8, the
tcp connection couldn't be found though we can confirm there was a tcp
connection. Another strange behavior is that it did not lookup the location
table for the ruri and it seems the message route was not called. On 3.2.8,
if we specify the ruri in the command with the actual ip address and port
we manually found in the location table, the message can be sent. We also
found the msilo module can't send messages on 3.2.8 but it works well on
3.1.

Here is the command we used:

opensips-cli -x mi t_uac_dlg method=MESSAGE
ruri="sip:12345 at sip.domain.com:5061;transport=TLS" headers="From:
sip:6789 at sip.domain.com:5061;transport=tls\r\nTo:
sip:12345 at sip.domain.com:5061;transport=TLS\r\nContact:
sip:6789 at sip.domain.com:5061;transport=tls\r\nContent-Type: text/plain\r\n"
body="this is a message"

Here are the logs on 3.1 and 3.2.8 respectively,

Logs for OPENSIPS 3.2

Sep 26 07:21:13 opensips[3477]: DBG:core:parse_msg: SIP Request:
Sep 26 07:21:13 opensips[3477]: DBG:core:parse_msg:  method:  <MESSAGE>
Sep 26 07:21:13 opensips[3477]: DBG:core:parse_msg:  uri:
 <sip:6989229721 at sip.domain.com:5061;transport=TLS>
Sep 26 07:21:13 opensips[3477]: DBG:core:parse_msg:  version: <SIP/2.0>
Sep 26 07:21:13 opensips[3477]: DBG:core:parse_headers:
flags=ffffffffffffffff
Sep 26 07:21:13 opensips[3477]: DBG:core:parse_via_param: found param type
232, <branch> = <z9hG4bKaaa.9835bef.0>; state=16
Sep 26 07:21:13 opensips[3477]: DBG:core:parse_via: end of header reached,
state=5
Sep 26 07:21:13 opensips[3477]: DBG:core:parse_headers: via found,
flags=ffffffffffffffff
Sep 26 07:21:13 opensips[3477]: DBG:core:parse_headers: this is the first
via
Sep 26 07:21:13 opensips[3477]: DBG:core:_parse_to: end of header reached,
state=9
Sep 26 07:21:13 opensips[3477]: DBG:core:_parse_to: display={}, ruri={
sip:6989229721 at sip.domain.com:5061}
Sep 26 07:21:13 opensips[3477]: DBG:core:get_hdr_field: <To> [37]; uri=[
sip:6989229721 at sip.domain.com:5061]
Sep 26 07:21:13 opensips[3477]: DBG:core:get_hdr_field: to body [
sip:6989229721 at sip.domain.com:5061#015#012]
Sep 26 07:21:13 opensips[3477]: DBG:core:get_hdr_field: cseq <CSeq>: <10>
<MESSAGE>
Sep 26 07:21:13 opensips[3477]: DBG:core:get_hdr_field: content_length=28
Sep 26 07:21:13 opensips[3477]: DBG:core:get_hdr_field: found end of header
Sep 26 07:21:13 opensips[3477]: DBG:core:parse_headers:
flags=ffffffffffffffff
Sep 26 07:21:13 opensips[3477]: DBG:core:parse_headers: flags=78
Sep 26 07:21:13 opensips[3477]: DBG:proto_tls:proto_tls_send: no open tcp
connection found, opening new one, async = 0
Sep 26 07:21:13 opensips[3477]: DBG:core:probe_max_sock_buff: getsockopt:
snd is initially 16384
Sep 26 07:21:13 opensips[3477]: DBG:core:probe_max_sock_buff: using snd
buffer of 416 kb
Sep 26 07:21:13 opensips[3477]: DBG:core:init_sock_keepalive: TCP keepalive
enabled on socket 103
Sep 26 07:21:14 opensips[3477]: ERROR:core:tcp_connect_blocking_timeout:
connect timed out, 1000079 us elapsed out of 1000000 us
Sep 26 07:21:14 opensips[3477]: ERROR:core:tcp_sync_connect_fd:
tcp_blocking_connect failed
Sep 26 07:21:14 opensips[3477]: ERROR:proto_tls:proto_tls_send: connect
failed
Sep 26 07:21:14 opensips[3477]: ERROR:tm:msg_send: send() to
12.34.56.78:5061 for proto tls/3 failed
Sep 26 07:21:14 opensips[3477]: ERROR:tm:t_uac: attempt to send to
'sip:6989229721 at sip.domain.com:5061;transport=TLS' failed

Logs for OPENSIPS 3.1

Sep 26 07:32:00 ip-172-31-14-229 /usr/sbin/opensips[11569]:
DBG:core:parse_msg: SIP Request:
Sep 26 07:32:00 ip-172-31-14-229 /usr/sbin/opensips[11569]:
DBG:core:parse_msg:  method:  <MESSAGE>
Sep 26 07:32:00 ip-172-31-14-229 /usr/sbin/opensips[11569]:
DBG:core:parse_msg:  uri:     <sip:3293543374 at sip.domain.com:5061
;transport=TLS>
Sep 26 07:32:00 ip-172-31-14-229 /usr/sbin/opensips[11569]:
DBG:core:parse_msg:  version: <SIP/2.0>
Sep 26 07:32:00 ip-172-31-14-229 /usr/sbin/opensips[11569]:
DBG:core:parse_headers: flags=ffffffffffffffff
Sep 26 07:32:00 ip-172-31-14-229 /usr/sbin/opensips[11569]:
DBG:core:parse_via_param: found param type 232, <branch> =
<z9hG4bK08a6.250aa504.0>; state=16
Sep 26 07:32:00 ip-172-31-14-229 /usr/sbin/opensips[11569]:
DBG:core:parse_via: end of header reached, state=5
Sep 26 07:32:00 ip-172-31-14-229 /usr/sbin/opensips[11569]:
DBG:core:parse_headers: via found, flags=ffffffffffffffff
Sep 26 07:32:00 ip-172-31-14-229 /usr/sbin/opensips[11569]:
DBG:core:parse_headers: this is the first via
Sep 26 07:32:00 ip-172-31-14-229 /usr/sbin/opensips[11569]:
DBG:core:_parse_to: end of header reached, state=9
Sep 26 07:32:00 ip-172-31-14-229 /usr/sbin/opensips[11569]:
DBG:core:_parse_to: display={}, ruri={sip:3293543374 at sip.domain.com:5061}
Sep 26 07:32:00 ip-172-31-14-229 /usr/sbin/opensips[11569]:
DBG:core:get_hdr_field: <To> [38]; uri=[sip:3293543374 at sip.domain.com:5061]
Sep 26 07:32:00 ip-172-31-14-229 /usr/sbin/opensips[11569]:
DBG:core:get_hdr_field: to body [sip:3293543374 at sip.domain.com:5061#015#012]
Sep 26 07:32:00 ip-172-31-14-229 /usr/sbin/opensips[11569]:
DBG:core:get_hdr_field: cseq <CSeq>: <10> <MESSAGE>
Sep 26 07:32:00 ip-172-31-14-229 /usr/sbin/opensips[11569]:
DBG:core:get_hdr_field: content_length=28
Sep 26 07:32:00 ip-172-31-14-229 /usr/sbin/opensips[11569]:
DBG:core:get_hdr_field: found end of header
Sep 26 07:32:00 ip-172-31-14-229 /usr/sbin/opensips[11569]:
DBG:core:parse_headers: flags=ffffffffffffffff
Sep 26 07:32:00 ip-172-31-14-229 /usr/sbin/opensips[11569]:
DBG:core:parse_headers: flags=78
Sep 26 07:32:00 ip-172-31-14-229 /usr/sbin/opensips[11558]:
DBG:core:tcp_conn_get: con found in state 0
Sep 26 07:32:00 ip-172-31-14-229 /usr/sbin/opensips[11558]:
DBG:core:tcp_conn_get: tcp connection found (0x7fd4544ee2f0), acquiring fd
Sep 26 07:32:00 ip-172-31-14-229 /usr/sbin/opensips[11558]:
DBG:core:tcp_conn_get: c= 0x7fd4544ee2f0, n=16, Usock=75
Sep 26 07:32:00 ip-172-31-14-229 /usr/sbin/opensips[11571]:
DBG:core:handle_worker: read response= 7fd4544ee2f0, 1, fd -1 from 2 (11558)
Sep 26 07:32:00 ip-172-31-14-229 /usr/sbin/opensips[11558]:
DBG:core:tcp_conn_get: after receive_fd: c= 0x7fd4544ee2f0 n=8 fd=102
Sep 26 07:32:00 ip-172-31-14-229 /usr/sbin/opensips[11558]:
DBG:proto_tls:proto_tls_send: sending via fd 102...
Sep 26 07:32:00 ip-172-31-14-229 /usr/sbin/opensips[11558]:
DBG:proto_tls:tls_update_fd: New fd is 102
Sep 26 07:32:00 ip-172-31-14-229 /usr/sbin/opensips[11558]:
DBG:proto_tls:tls_write: write was successful (534 bytes)
Sep 26 07:32:00 ip-172-31-14-229 /usr/sbin/opensips[11558]:
DBG:proto_tls:proto_tls_send: after write: c= 0x7fd4544ee2f0 n=534 fd=102
Sep 26 07:32:00 ip-172-31-14-229 /usr/sbin/opensips[11558]:
DBG:proto_tls:proto_tls_send: buf=#012MESSAGE
sip:3293543374 at sip.domain.com:5061;transport=TLS SIP/2.0#015#012Via:
SIP/2.0/TLS sip.domain.com:5061;branch=z9hG4bK08a6.250aa504.0#015#012To:
sip:3293543374 at sip.domain.com:5061#015#012From: <
sip:3293543374 at sip.domain.com:5061>;tag=fb020df94c5e77218c43e857503e9580-89dd#015#012CSeq:
10 MESSAGE#015#012Call-ID:
70bcd9894ae296f3-11558 at 172.31.14.229#015#012Max-Forwards:
70#015#012Content-Length: 28#015#012User-Agent: OpenSIPS (3.1.11
(x86_64/linux))#015#012Contact:
sip:3293543374 at sip.domain.com:5061;transport=tls#015#012Content-Type:
text/plain#015#012#015#012{"type":"11", "cont":"test"}
Sep 26 07:32:00 ip-172-31-14-229 /usr/sbin/opensips[11558]:
DBG:tm:insert_timer_unsafe: [0]: 0x7fd4545590c0 (42)
Sep 26 07:32:00 ip-172-31-14-229 /usr/sbin/opensips[11558]:
DBG:mi_fifo:mi_fifo_server: got mi response = [0xffffffffffffffff]

Thanks!

jacky
-------------- next part --------------
An HTML attachment was scrubbed...
URL: <http://lists.opensips.org/pipermail/users/attachments/20220926/bbfdcc55/attachment.html>