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 <[email protected]
<mailto:[email protected]>> 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 <[email protected]
<mailto:[email protected]>> 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:[email protected]:5061;transport=TLS"
headers="From:
sip:[email protected]:5061;transport=tls\r\nTo:
sip:[email protected]:5061;transport=TLS\r\nContact:
sip:[email protected]: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:[email protected]: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:[email protected]:5061
<http://sip:[email protected]:5061>}
Sep 26 07:21:13 opensips[3477]: DBG:core:get_hdr_field: <To>
[37]; uri=[sip:[email protected]:5061
<http://sip:[email protected]:5061>]
Sep 26 07:21:13 opensips[3477]: DBG:core:get_hdr_field: to
body [sip:[email protected]:5061#015#012
<http://sip:[email protected]: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:[email protected]: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:[email protected]: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:[email protected]:5061
<http://sip:[email protected]:5061>}
Sep 26 07:32:00 ip-172-31-14-229 /usr/sbin/opensips[11569]:
DBG:core:get_hdr_field: <To> [38];
uri=[sip:[email protected]:5061
<http://sip:[email protected]:5061>]
Sep 26 07:32:00 ip-172-31-14-229 /usr/sbin/opensips[11569]:
DBG:core:get_hdr_field: to body
[sip:[email protected]:5061#015#012
<http://sip:[email protected]: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:[email protected]:5061;transport=TLS
SIP/2.0#015#012Via: SIP/2.0/TLS
sip.domain.com:5061;branch=z9hG4bK08a6.250aa504.0#015#012To:
sip:[email protected]:5061#015#012From
<http://sip:[email protected]:5061#015%23012From>:
<sip:[email protected]:5061
<http://sip:[email protected]:5061>>;tag=fb020df94c5e77218c43e857503e9580-89dd#015#012CSeq:
10 MESSAGE#015#012Call-ID:
[email protected]#015#012Max-Forwards
<http://[email protected]#015%23012Max-Forwards>:
70#015#012Content-Length: 28#015#012User-Agent: OpenSIPS
(3.1.11 (x86_64/linux))#015#012Contact:
sip:[email protected]: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
[email protected]
http://lists.opensips.org/cgi-bin/mailman/listinfo/users
_______________________________________________
Users mailing list
[email protected]
http://lists.opensips.org/cgi-bin/mailman/listinfo/users
