[OpenSIPS-Users] MSILO can't send message

Wed Oct 20 12:27:47 EST 2021

Hi Bogdan_Andrei,

You are right. The actual content is not attached. Attached is the log.

Hi,
>
> So the actual content of the message is not attached to the MSG? Could you
> send me (maybe off list) the opensips logs (level 4) for a m_dump() ?
>
> Best regards,
>
> Bogdan-Andrei Iancu
>
> OpenSIPS Founder and Developer
>   https://www.opensips-solutions.com
> OpenSIPS eBootcamp 2021
>   https://opensips.org/training/OpenSIPS_eBootcamp_2021/
>
> On 10/15/21 11:02 AM, jacky z wrote:
>
> Hi Bogdan-Andrei,
>
> Did you also noticed the msilo module still can't send the dumped message,
> but send "[Offline message - Thu Jan  1 00:00:00 1970" no matter what the
> message is? or just the setting I used?
>
>
> :+1:
>>
>> Regards,
>>
>> Bogdan-Andrei Iancu
>>
>> OpenSIPS Founder and Developer
>>   https://www.opensips-solutions.com
>> OpenSIPS eBootcamp 2021
>>   https://opensips.org/training/OpenSIPS_eBootcamp_2021/
>>
>> On 10/14/21 5:03 AM, jacky z wrote:
>>
>> Hi Bogdan-Andrei,
>>
>> Finally made it send offline message by setting
>>
>> modparam("msilo", "outbound_proxy",
>> "sip:name.domain.com:5061;transport=tls")
>> modparam("tls_mgm", "match_sip_domain", "[dom]*")
>>
>> It seems the port number needs to be included and the match_sip_domain
>> needs to *. If the domain name is included, the error happens. Hope this
>> info is helpful for others who may be interested.
>>
>> However, it still can't send the dumped message, but send "[Offline
>> message - Thu Jan  1 08:00:00 1970" no matter what the message is. It seems
>> the message was truncated. Based on the source code of the msilo module,
>> the message should be something like  "[Offline message - Thu Jan  1
>> 08:00:00 1970] message here".
>>
>> In the log, I can see the correct message was read out from the silo
>> table. Here is the log that shows the correct offline message that should
>> be sent:
>>
>> DBG:db_mysql:db_mysql_str2val: converting BLOB [{"type":"1","cont":"the
>> right message"}]
>>
>> Thanks!
>>
>>
>> Hi Jacky,
>>>
>>> The m_dump() sends the MESSAGE to the AOR of the user, so, ideally, you
>>> should do take care of the "lookup(location)" in order to the get it
>>> properly routed.
>>>
>>> For the TLS part, do you use it between the end-point and opensips? if
>>> so, I guess the MESSAGE sent by m_dump() and looping back to opensips (for
>>> doing the lookup(location)) is via UDP ?
>>>
>>> I'm asking as from the TLS perspective the most important think to know
>>> is where (in the  routing logic) the TLS connection gets used/opened, as
>>> you need to be sure and correlate the destination IP (at the moment) with
>>> the IPs/mask you have in the TLS client domain.
>>>
>>> Best regards,
>>>
>>> Bogdan-Andrei Iancu
>>>
>>> OpenSIPS Founder and Developer
>>>   https://www.opensips-solutions.com
>>> OpenSIPS eBootcamp 2021
>>>   https://opensips.org/training/OpenSIPS_eBootcamp_2021/
>>>
>>> On 9/28/21 3:03 AM, jacky z wrote:
>>>
>>> Hi Team,
>>>
>>> I want to use MSILO to forward offline messages. I use TLS connections
>>> and have set up both server domain and client domains. If we don't
>>> use outbound_proxy, the logs show no error, but the message just was not
>>> sent. I searched online and it was said that the outbound proxy needs to be
>>> used. However, if we use outbound_proxy, there will be errors- no TLS
>>> client domain found. Actually, I have set up the client domain. It
>>> seems the MSILO module can't recognize the client domain. I have checked
>>> the messages were all in the database table silo. Have you ever encountered
>>> such issues? Any clue to debug? Thanks!
>>>
>>> Here are the scripts and logs
>>>
>>> When m_dump() is called in "REGISTER":
>>>
>>>         	if (m_dump()) {
>>>             	xlog("MSILO: offline messages dumped - if they were");
>>>         	}else{
>>>             	xlog("MSILO: no offline messages dumped");
>>>         	};
>>>
>>> It can dump the message from the database but can't send the message.
>>> Here is the log:
>>>
>>> Sep 18 17:29:55 sipserver /usr/sbin/opensips[9794]: DBG:core:parse_msg:
>>> method:
>>> Sep 18 17:29:55 sipserver /usr/sbin/opensips[9794]: DBG:core:parse_msg:
>>> uri: sip:10000 at xxx.com:5061;transport=tls
>>> Sep 18 17:29:55 sipserver /usr/sbin/opensips[9794]: DBG:core:parse_msg:
>>> version: <SIP/2.0>
>>> Sep 18 17:29:55 sipserver /usr/sbin/opensips[9794]:
>>> DBG:core:parse_headers: flags=ffffffffffffffff
>>> Sep 18 17:29:55 sipserver /usr/sbin/opensips[9794]:
>>> DBG:core:parse_via_param: found param type 232, = <z9hG4bKe0c6.787dad54.0>;
>>> state=16
>>> Sep 18 17:29:55 sipserver /usr/sbin/opensips[9794]: DBG:core:parse_via:
>>> end of header reached, state=5
>>> Sep 18 17:29:55 sipserver /usr/sbin/opensips[9794]:
>>> DBG:core:parse_headers: via found, flags=ffffffffffffffff
>>> Sep 18 17:29:55 sipserver /usr/sbin/opensips[9794]:
>>> DBG:core:parse_headers: this is the first via
>>> Sep 18 17:29:55 sipserver /usr/sbin/opensips[9794]:
>>> DBG:core:parse_to_param: transport=tls
>>> Sep 18 17:29:55 sipserver /usr/sbin/opensips[9794]: DBG:core:_parse_to:
>>> end of header reached, state=29
>>> Sep 18 17:29:55 sipserver /usr/sbin/opensips[9794]: DBG:core:_parse_to:
>>> display={}, ruri={sip:10000 at xxx.com:5061}
>>> Sep 18 17:29:55 sipserver /usr/sbin/opensips[9794]:
>>> DBG:core:get_hdr_field: [50]; uri=[sip:10000 at xxx.com:5061]
>>> Sep 18 17:29:55 sipserver /usr/sbin/opensips[9794]:
>>> DBG:core:get_hdr_field: to body [sip:10000 at xxx.com:5061]
>>> Sep 18 17:29:55 sipserver /usr/sbin/opensips[9794]:
>>> DBG:core:get_hdr_field: cseq : <10>
>>> Sep 18 17:29:55 sipserver /usr/sbin/opensips[9794]:
>>> DBG:core:get_hdr_field: content_length=78
>>> Sep 18 17:29:55 sipserver /usr/sbin/opensips[9794]:
>>> DBG:core:get_hdr_field: found end of header
>>> Sep 18 17:29:55 sipserver /usr/sbin/opensips[9794]:
>>> DBG:core:parse_headers: flags=ffffffffffffffff
>>> Sep 18 17:29:55 sipserver /usr/sbin/opensips[9794]:
>>> DBG:core:parse_headers: flags=78
>>> Sep 18 17:29:55 sipserver /usr/sbin/opensips[9794]:
>>> DBG:proto_tls:proto_tls_send: no open tcp connection found, opening new one
>>> Sep 18 17:29:55 sipserver /usr/sbin/opensips[9794]:
>>> DBG:core:probe_max_sock_buff: getsockopt: snd is initially 16384
>>> Sep 18 17:29:55 sipserver /usr/sbin/opensips[9794]:
>>> DBG:core:probe_max_sock_buff: using snd buffer of 416 kb
>>> Sep 18 17:29:55 sipserver /usr/sbin/opensips[9794]:
>>> DBG:core:init_sock_keepalive: TCP keepalive enabled on socket 119
>>> Sep 18 17:29:55 sipserver /usr/sbin/opensips[9794]: DBG:core:print_ip:
>>> tcpconn_new: new tcp connection to: 142.107.16.203
>>> <http://142.107.16.203:5061/>
>>> Sep 18 17:29:55 sipserver /usr/sbin/opensips[9794]:
>>> DBG:core:tcpconn_new: on port 5061, proto 3
>>> Sep 18 17:29:55 sipserver /usr/sbin/opensips[9794]:
>>> DBG:proto_tls:tls_conn_init: Creating a whole new ssl connection
>>> Sep 18 17:29:55 sipserver /usr/sbin/opensips[9794]:
>>> ERROR:proto_tls:tls_conn_init: no TLS client domain found
>>> Sep 18 17:29:55 sipserver /usr/sbin/opensips[9794]:
>>> ERROR:core:tcp_conn_new: failed to do proto 3 specific init for conn
>>> 0x7f0559e116b8
>>> Sep 18 17:29:55 sipserver /usr/sbin/opensips[9794]:
>>> DBG:core:tcpconn_destroy: destroying connection 0x7f0559e116b8, flags 0018
>>> Sep 18 17:29:55 sipserver /usr/sbin/opensips[9794]:
>>> ERROR:proto_tls:tls_sync_connect: tcp_conn_create failed, closing the socket
>>> Sep 18 17:29:55 sipserver /usr/sbin/opensips[9794]:
>>> ERROR:proto_tls:proto_tls_send: connect failed
>>> Sep 18 17:29:55 sipserver /usr/sbin/opensips[9794]: ERROR™️msg_send:
>>> send() to 142.107.16.203:5061 for proto tls/3 failed
>>> Sep 18 17:29:55 sipserver /usr/sbin/opensips[9794]: ERROR™️t_uac:
>>> attempt to send to 'sip:10000 at xxx.com:5061;transport=tls' failed
>>>
>>> _______________________________________________
>>> Users mailing listUsers at lists.opensips.orghttp://lists.opensips.org/cgi-bin/mailman/listinfo/users
>>>
>>>
>>>
>>
>
-------------- next part --------------
An HTML attachment was scrubbed...
URL: <http://lists.opensips.org/pipermail/users/attachments/20211020/f5025410/attachment-0001.html>
-------------- next part --------------
Oct 18 17:25:19 sipserver /usr/sbin/opensips[18616]: DBG:msilo:m_dump: user <1234 at sip.domain.com> online - expires=300
Oct 18 17:25:19 sipserver /usr/sbin/opensips[18616]: DBG:core:parse_headers: flags=ffffffffffffffff
Oct 18 17:25:19 sipserver /usr/sbin/opensips[18616]: DBG:msilo:check_message_support: Allow message: 256
Oct 18 17:25:19 sipserver /usr/sbin/opensips[18616]: DBG:msilo:check_message_support: MESSAGE found in Allow Header
Oct 18 17:25:19 sipserver /usr/sbin/opensips[18616]: DBG:db_mysql:mysql_raise_event: MySQL status has not changed: connected
Oct 18 17:25:19 sipserver /usr/sbin/opensips[18616]: DBG:core:db_new_result: allocate 48 bytes for result set at 0x7f0fc515e718
Oct 18 17:25:19 sipserver /usr/sbin/opensips[18616]: DBG:db_mysql:db_mysql_get_columns: 6 columns returned from the query
Oct 18 17:25:19 sipserver /usr/sbin/opensips[18616]: DBG:core:db_allocate_columns: allocate 168 bytes for result columns at 0x7f0fc5149760
Oct 18 17:25:19 sipserver /usr/sbin/opensips[18616]: DBG:db_mysql:db_mysql_get_columns: RES_NAMES(0x7f0fc5149790)[0]=[id]
Oct 18 17:25:19 sipserver /usr/sbin/opensips[18616]: DBG:db_mysql:db_mysql_get_columns: use DB_INT result type
Oct 18 17:25:19 sipserver /usr/sbin/opensips[18616]: DBG:db_mysql:db_mysql_get_columns: RES_NAMES(0x7f0fc51497a0)[1]=[src_addr]
Oct 18 17:25:19 sipserver /usr/sbin/opensips[18616]: DBG:db_mysql:db_mysql_get_columns: use DB_STRING result type
Oct 18 17:25:19 sipserver /usr/sbin/opensips[18616]: DBG:db_mysql:db_mysql_get_columns: RES_NAMES(0x7f0fc51497b0)[2]=[dst_addr]
Oct 18 17:25:19 sipserver /usr/sbin/opensips[18616]: DBG:db_mysql:db_mysql_get_columns: use DB_STRING result type
Oct 18 17:25:19 sipserver /usr/sbin/opensips[18616]: DBG:db_mysql:db_mysql_get_columns: RES_NAMES(0x7f0fc51497c0)[3]=[body]
Oct 18 17:25:19 sipserver /usr/sbin/opensips[18616]: DBG:db_mysql:db_mysql_get_columns: use DB_BLOB result type
Oct 18 17:25:19 sipserver /usr/sbin/opensips[18616]: DBG:db_mysql:db_mysql_get_columns: RES_NAMES(0x7f0fc51497d0)[4]=[ctype]
Oct 18 17:25:19 sipserver /usr/sbin/opensips[18616]: DBG:db_mysql:db_mysql_get_columns: use DB_STRING result type
Oct 18 17:25:19 sipserver /usr/sbin/opensips[18616]: DBG:db_mysql:db_mysql_get_columns: RES_NAMES(0x7f0fc51497e0)[5]=[inc_time]
Oct 18 17:25:19 sipserver /usr/sbin/opensips[18616]: DBG:db_mysql:db_mysql_get_columns: use DB_INT result type
Oct 18 17:25:19 sipserver /usr/sbin/opensips[18616]: DBG:core:db_allocate_rows: allocate 416 bytes for result rows and values at 0x7f0fc5148600
Oct 18 17:25:19 sipserver /usr/sbin/opensips[18616]: DBG:db_mysql:db_mysql_str2val: converting INT [73]
Oct 18 17:25:19 sipserver /usr/sbin/opensips[18616]: DBG:db_mysql:db_mysql_str2val: converting STRING [sip:5678 at sip.domain.com]
Oct 18 17:25:19 sipserver /usr/sbin/opensips[18616]: DBG:db_mysql:db_mysql_str2val: converting STRING [sip:1234 at sip.domain.com]
Oct 18 17:25:19 sipserver /usr/sbin/opensips[18616]: DBG:db_mysql:db_mysql_str2val: converting BLOB [this is a message]
Oct 18 17:25:19 sipserver /usr/sbin/opensips[18616]: DBG:db_mysql:db_mysql_str2val: converting STRING [text/plain]
Oct 18 17:25:19 sipserver /usr/sbin/opensips[18616]: DBG:db_mysql:db_mysql_str2val: converting INT [1634193408]
Oct 18 17:25:19 sipserver /usr/sbin/opensips[18616]: DBG:db_mysql:db_mysql_str2val: converting INT [74]
Oct 18 17:25:19 sipserver /usr/sbin/opensips[18616]: DBG:db_mysql:db_mysql_str2val: converting STRING [sip:5678 at sip.domain.com]
Oct 18 17:25:19 sipserver /usr/sbin/opensips[18616]: DBG:db_mysql:db_mysql_str2val: converting STRING [sip:1234 at sip.domain.com]
Oct 18 17:25:19 sipserver /usr/sbin/opensips[18616]: DBG:db_mysql:db_mysql_str2val: converting BLOB [this is another message]
Oct 18 17:25:19 sipserver /usr/sbin/opensips[18616]: DBG:db_mysql:db_mysql_str2val: converting STRING [text/plain]
Oct 18 17:25:19 sipserver /usr/sbin/opensips[18616]: DBG:db_mysql:db_mysql_str2val: converting INT [1634193408]
Oct 18 17:25:19 sipserver /usr/sbin/opensips[18616]: DBG:msilo:m_dump: dumping [2] messages for <1234 at sip.domain.com>!!!
Oct 18 17:25:19 sipserver /usr/sbin/opensips[18616]: DBG:msilo:msg_list_check_msg: checking msgid=73
Oct 18 17:25:19 sipserver /usr/sbin/opensips[18616]: DBG:msilo:msg_list_check_msg: msg already in sent list.
Oct 18 17:25:19 sipserver /usr/sbin/opensips[18616]: DBG:msilo:m_dump: message[0] mid=73 already sent.
Oct 18 17:25:19 sipserver /usr/sbin/opensips[18616]: DBG:msilo:msg_list_check_msg: checking msgid=74
Oct 18 17:25:19 sipserver /usr/sbin/opensips[18616]: DBG:msilo:msg_list_check_msg: msg already in sent list.
Oct 18 17:25:19 sipserver /usr/sbin/opensips[18616]: DBG:msilo:m_dump: message[1] mid=74 already sent.
Oct 18 17:25:19 sipserver /usr/sbin/opensips[18616]: DBG:core:db_free_columns: freeing result columns at 0x7f0fc5149760
Oct 18 17:25:19 sipserver /usr/sbin/opensips[18616]: DBG:core:db_free_rows: freeing 2 rows
Oct 18 17:25:19 sipserver /usr/sbin/opensips[18616]: DBG:core:db_free_row: freeing row values at 0x7f0fc5148620
Oct 18 17:25:19 sipserver /usr/sbin/opensips[18616]: DBG:core:db_free_row: freeing row values at 0x7f0fc51486e0
Oct 18 17:25:19 sipserver /usr/sbin/opensips[18616]: DBG:core:db_free_rows: freeing rows at 0x7f0fc5148600
Oct 18 17:25:19 sipserver /usr/sbin/opensips[18616]: DBG:core:db_free_result: freeing result set at 0x7f0fc515e718
Oct 18 17:25:19 sipserver /usr/sbin/opensips[18616]: MSILO: offline messages dumped - if they were
Oct 18 17:25:19 sipserver /usr/sbin/opensips[18616]: DBG:core:parse_headers: flags=ffffffffffffffff
Oct 18 17:25:19 sipserver /usr/sbin/opensips[18616]: DBG:core:parse_params: Parsing params for:[reg-id=1;+sip.instance="<urn:uuid:00000000-0000-0000-0000-00007e5b9907>"]
Oct 18 17:25:19 sipserver /usr/sbin/opensips[18616]: DBG:core:parse_headers: flags=ffffffffffffffff
Oct 18 17:25:19 sipserver /usr/sbin/opensips[18616]: DBG:core:parse_headers: flags=ffffffffffffffff
Oct 18 17:25:19 sipserver /usr/sbin/opensips[18616]: DBG:core:parse_headers: flags=ffffffffffffffff
Oct 18 17:25:19 sipserver /usr/sbin/opensips[18616]: INFO:avpops:ops_print_avp: ----------- All AVPs in this context --------
Oct 18 17:25:19 sipserver /usr/sbin/opensips[18617]: ERROR:core:tcp_connect_blocking_timeout: poll error: flags 28 - 4 8 16 32 
Oct 18 17:25:19 sipserver /usr/sbin/opensips[18617]: ERROR:core:tcp_connect_blocking_timeout: failed to retrieve SO_ERROR [server=1.2.3.4:38351] (111) Connection refused
Oct 18 17:25:19 sipserver /usr/sbin/opensips[18617]: ERROR:proto_tls:tls_sync_connect: tcp_blocking_connect failed
Oct 18 17:25:19 sipserver /usr/sbin/opensips[18617]: ERROR:proto_tls:proto_tls_send: connect failed
Oct 18 17:25:19 sipserver /usr/sbin/opensips[18617]: ERROR:tm:msg_send: send() to 1.2.3.4:38351 for proto tls/3 failed
Oct 18 17:25:19 sipserver /usr/sbin/opensips[18617]: ERROR:tm:t_forward_nonack: sending request failed
Oct 18 17:25:19 sipserver /usr/sbin/opensips[18617]: DBG:core:tcp_conn_get: con found in state 0
Oct 18 17:25:19 sipserver /usr/sbin/opensips[18617]: DBG:core:tcp_conn_get: tcp connection found (0x7f0fc18f7040), acquiring fd
Oct 18 17:25:19 sipserver /usr/sbin/opensips[18617]: DBG:core:tcp_conn_get: c= 0x7f0fc18f7040, n=16, Usock=87
Oct 18 17:25:19 sipserver /usr/sbin/opensips[18624]: DBG:core:handle_worker: read response= 7f0fc18f7040, 1, fd -1 from 8 (18617)
Oct 18 17:25:19 sipserver /usr/sbin/opensips[18617]: DBG:core:tcp_conn_get: after receive_fd: c= 0x7f0fc18f7040 n=8 fd=119
Oct 18 17:25:19 sipserver /usr/sbin/opensips[18617]: DBG:proto_tls:proto_tls_send: sending via fd 119...
Oct 18 17:25:19 sipserver /usr/sbin/opensips[18617]: DBG:proto_tls:tls_update_fd: New fd is 119
Oct 18 17:25:19 sipserver /usr/sbin/opensips[18617]: DBG:proto_tls:tls_write: write was successful (768 bytes)
Oct 18 17:25:19 sipserver /usr/sbin/opensips[18617]: DBG:proto_tls:proto_tls_send: after write: c= 0x7f0fc18f7040 n=768 fd=119
Oct 18 17:25:19 sipserver /usr/sbin/opensips[18617]: DBG:proto_tls:proto_tls_send: buf=#012MESSAGE sip:1234 at 1.2.3.4:38250;transport=TLS;ob;push-type=apple;push-app=com.domain.anapp;push-tok=d26762bc904e92c7c7257b16d01c0306743842283890fbf3fc283f888a151dd1 SIP/2.0#015#012Via: SIP/2.0/TLS 5.6.7.8:5061;branch=z9hG4bKa4f6.a67d16b5.1;i=d08d52a7#015#012Via: SIP/2.0/TLS 5.6.7.8:5061;branch=z9hG4bKa4f6.967d16b5.0#015#012To: sip:1234 at sip.domain.com#015#012From: <sip:5678 at sip.domain.com>;tag=9afce3b8fbcf13cb78dc600ec9e7e602-19db#015#012CSeq: 10 MESSAGE#015#012Call-ID: 6143c1e65061294e-18616 at 172.29.118.78#015#012Max-Forwards: 69#015#012Content-Length: 51#015#012User-Agent: OpenSIPS (3.1.2 (x86_64/linux))#015#012Date: Thu, 14 Oct 2021 06:36:48 GMT#015#012Content-Type: text/plain#015#012Contact: <sip:5678 at sip.domain.com>;msilo=yes#015#012#015#012[Offline message - Thu Jan  1 08:00:00 1970#012