[OpenSIPS-Users] Opensips 3.2.8 does not send message with opensips-cli command
Bogdan-Andrei Iancu
bogdan at opensips.org
Mon Oct 10 12:44:24 UTC 2022
Hi,
On 3.2, are you sure you actually have the ongoing connection? Try
running the list_tcp_conns MI cmd just before trying to push the MESSAGE
out. Be sure that the remote point (proto:ip:port) of the connection
matches the destination of your MESSAGE (so the connection gets re-used).
https://www.opensips.org/Documentation/Interface-CoreMI-3-2#toc4
Regards,
Bogdan-Andrei Iancu
OpenSIPS Founder and Developer
https://www.opensips-solutions.com
OpenSIPS Summit 27-30 Sept 2022, Athens
https://www.opensips.org/events/Summit-2022Athens/
On 9/29/22 5:09 PM, jacky z wrote:
> Also tried version 3.2.2. The same issue. The existing TCP connection
> can't be found when there is a Message request, either from msilo dump
> or opensips-cli command. A message sent directly is normal when the
> receiver side registers with a living TCP socket. Guess this would
> also affect other behavior where an existing TCP connection needs to
> be found. From the log, the connection ID is zero. Very strange
> behavior. I would like to debug, but not familiar with the source code
> structure. For example how a TCP connection is looked for and which
> file handles this. Guess it is not difficult to fix, hope the Opensips
> team can help. Thank you!
>
> On Tue, Sep 27, 2022 at 10:56 PM jacky z <zjack0992 at gmail.com
> <mailto:zjack0992 at gmail.com>> wrote:
>
> Who can help on this? It is difficult to understand why the live
> tcp connection can't be found with opensips 3.2. It works well
> with opensips 3.1. Thanks!
>
> On Mon, Sep 26, 2022 at 3:54 PM jacky z <zjack0992 at gmail.com
> <mailto:zjack0992 at gmail.com>> wrote:
>
> 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
> <http://sip:6989229721@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
> <http://sip:6989229721@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
> <http://sip:6989229721@sip.domain.com:5061#015%23012>]
> 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 <http://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
> <http://sip:3293543374@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
> <http://sip:3293543374@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
> <http://sip:3293543374@sip.domain.com:5061#015%23012>]
> 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
> <http://sip:3293543374@sip.domain.com:5061#015%23012From>:
> <sip:3293543374 at sip.domain.com:5061
> <http://sip:3293543374@sip.domain.com:5061>>;tag=fb020df94c5e77218c43e857503e9580-89dd#015#012CSeq:
> 10 MESSAGE#015#012Call-ID:
> 70bcd9894ae296f3-11558 at 172.31.14.229#015#012Max-Forwards
> <http://70bcd9894ae296f3-11558@172.31.14.229#015%23012Max-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
>
>
> _______________________________________________
> Users mailing list
> Users at lists.opensips.org
> http://lists.opensips.org/cgi-bin/mailman/listinfo/users
-------------- next part --------------
An HTML attachment was scrubbed...
URL: <http://lists.opensips.org/pipermail/users/attachments/20221010/de76be65/attachment-0001.html>
More information about the Users
mailing list