[OpenSIPS-Users] TLS handling

Чалков Артём achalkov at ya.ru
Fri Mar 6 12:12:59 CET 2015


Yes, i sure. I have only 1 branch because i have only one instance to receive sent MESSAGE and i dont add branches manually. Actually, that is all MESSAGE routing:

...
 if (is_method("MESSAGE")) route(MESSAGE);
...
route[MESSAGE] {
...
        if (!lookup("location")) {
  ...
   } else {
                t_on_reply("ON_REPLY");
                if ($si != "127.0.0.1") t_on_failure("ON_FAIL_MESSAGE");
                t_relay("0x01");
                $var(retcode) = $retcode;
                xlog("L_INFO", "[!!!MESSAGE_DEBUG!!!] t_relay returns $var(retcode) LOGHDR");
                ifdef(`LOGS', `xlog("L_INFO", "[MESSAGE] Request is leaving server LOGHDR");')
                exit;
   }
}

I have sent to your e-mail (vladpaiu at opensips.org) debug=4 log from moment, when i killed softphone (destination of MESSAGE) without sip unregistering, but with removing tcp/tls connection.

06.03.2015, 12:43, "Vlad Paiu" <vladpaiu at opensips.org>:
> Hello,
>
> OpenSIPS complains that there is an error when connecting via TCP to
> that endpoint.
> Now, are you sure you do not have multple branches when relaying that
> SIP MESSAGE,out of which only one fails ? In t_relay(), if you have
> multiple branches and at least one succceeds, you will get a 1 return code.
>
> Please post the complete debug=4 logs for the processing. In the
> previous email, you've truncated the logs to the moment OpenSIPS gets
> blocked in trying to connect to the endpoint - what happens afterwards (
> after connet timeout ) would also be helpfull.
>
> Best Regards,
>
> Vlad Paiu
> OpenSIPS Developer
> http://www.opensips-solutions.com
>
> On 06.03.2015 11:06, Чалков Артём wrote:
>>  do anyone have any idea about how to handle that?
>>
>>  05.03.2015, 16:22, "Чалков Артём" <achalkov at ya.ru>:
>>>  debug=4
>>>
>>>  Mar  5 16:07:46 cs17792 /usr/sbin/opensips[19012]: DBG:core:tcp_read_req: We're releasing the connection in state 3
>>>  Mar  5 16:07:46 cs17792 /usr/sbin/opensips[19012]: DBG:core:io_watch_del: io_watch_del op on index -1 36 (0x77dee0, 36, -1, 0x10,0x1) fd_no=2 called
>>>  Mar  5 16:07:46 cs17792 /usr/sbin/opensips[19012]: DBG:core:release_tcpconn:  releasing con 0x7f2be91663a8, state 0, fd=36, id=1
>>>  Mar  5 16:07:46 cs17792 /usr/sbin/opensips[19012]: DBG:core:release_tcpconn:  extra_data (nil)
>>>  Mar  5 16:07:46 cs17792 /usr/sbin/opensips[19012]: DBG:core:parse_msg: SIP Request:
>>>  Mar  5 16:07:46 cs17792 /usr/sbin/opensips[19012]: DBG:core:parse_msg:  method:  <MESSAGE>
>>>  Mar  5 16:07:46 cs17792 /usr/sbin/opensips[19028]: DBG:core:handle_tcp_child: reader response= 7f2be91663a8, 0 from 0
>>>  Mar  5 16:07:46 cs17792 /usr/sbin/opensips[19012]: DBG:core:parse_msg:  uri:     <sip:achalkov1 at x.x.x.x:3631;transport=TCP>
>>>  Mar  5 16:07:46 cs17792 /usr/sbin/opensips[19028]: DBG:core:io_watch_add: io_watch_add op on 52 (0x77dd80, 52, 2, 0x7f2be91663a8,1), fd_no=38
>>>  Mar  5 16:07:46 cs17792 /usr/sbin/opensips[19012]: DBG:core:parse_msg:  version: <SIP/2.0>
>>>  Mar  5 16:07:46 cs17792 /usr/sbin/opensips[19012]: DBG:core:parse_headers: flags=2
>>>  Mar  5 16:07:46 cs17792 /usr/sbin/opensips[19012]: DBG:core:parse_via_param: found param type 232, <branch> = <z9hG4bK-d8754z-668ef50b1a4c0a31-1---d8754z->; state=6
>>>  Mar  5 16:07:46 cs17792 /usr/sbin/opensips[19012]: DBG:core:parse_via_param: found param type 235, <rport> = <n/a>; state=17
>>>  Mar  5 16:07:46 cs17792 /usr/sbin/opensips[19012]: DBG:core:parse_via: end of header reached, state=5
>>>  Mar  5 16:07:46 cs17792 /usr/sbin/opensips[19012]: DBG:core:parse_headers: via found, flags=2
>>>  Mar  5 16:07:46 cs17792 /usr/sbin/opensips[19012]: DBG:core:parse_headers: this is the first via
>>>  Mar  5 16:07:46 cs17792 /usr/sbin/opensips[19012]: DBG:core:receive_msg: After parse_msg...
>>>  Mar  5 16:07:46 cs17792 /usr/sbin/opensips[19012]: DBG:core:receive_msg: preparing to run routing scripts...
>>>  Mar  5 16:07:46 cs17792 /usr/sbin/opensips[19012]: DBG:core:parse_headers: flags=8000000
>>>  Mar  5 16:07:46 cs17792 /usr/sbin/opensips[19012]: DBG:core:parse_to: end of header reached, state=10
>>>  Mar  5 16:07:46 cs17792 /usr/sbin/opensips[19012]: DBG:core:parse_to: display={}, ruri={sip:achalkov1 at x.x.x.x:3631;transport=TCP}
>>>  Mar  5 16:07:46 cs17792 /usr/sbin/opensips[19012]: DBG:core:get_hdr_field: <To> [51]; uri=[sip:achalkov1 at x.x.x.x:3631;transport=TCP]
>>>  Mar  5 16:07:46 cs17792 /usr/sbin/opensips[19012]: DBG:core:get_hdr_field: to body [<sip:achalkov1 at x.x.x.x:3631;transport=TCP>#015#012]
>>>  Mar  5 16:07:46 cs17792 /usr/sbin/opensips[19012]: DBG:core:get_hdr_field: cseq <CSeq>: <3> <MESSAGE>
>>>  Mar  5 16:07:46 cs17792 /usr/sbin/opensips[19012]: DBG:maxfwd:is_maxfwd_present: value = 70
>>>  Mar  5 16:07:46 cs17792 /usr/sbin/opensips[19012]: DBG:core:parse_headers: flags=ffffffffffffffff
>>>  Mar  5 16:07:46 cs17792 /usr/sbin/opensips[19012]: DBG:core:get_hdr_field: content_length=3
>>>  Mar  5 16:07:46 cs17792 /usr/sbin/opensips[19012]: DBG:core:get_hdr_field: found end of header
>>>  Mar  5 16:07:46 cs17792 /usr/sbin/opensips[19012]: DBG:core:parse_headers: flags=ffffffffffffffff
>>>  Mar  5 16:07:46 cs17792 /usr/sbin/opensips[19012]: DBG:core:decode_mime_type: Decoding MIME type for:[text/plain]
>>>  Mar  5 16:07:46 cs17792 /usr/sbin/opensips[19012]: DBG:core:parse_to_param: tag=b2b91161
>>>  Mar  5 16:07:46 cs17792 /usr/sbin/opensips[19012]: DBG:core:parse_to: end of header reached, state=29
>>>  Mar  5 16:07:46 cs17792 /usr/sbin/opensips[19012]: DBG:core:parse_to: display={"achalkov"}, ruri={sip:achalkov at x.x.x.x:3631;transport=TCP}
>>>  Mar  5 16:07:46 cs17792 /usr/sbin/opensips[19012]: DBG:core:parse_headers: flags=ffffffffffffffff
>>>  Mar  5 16:07:46 cs17792 /usr/sbin/opensips[19012]: DBG:core:parse_methods: methods 0x173F
>>>  Mar  5 16:07:46 cs17792 /usr/sbin/opensips[19012]: DBG:uri:has_totag: no totag
>>>  Mar  5 16:07:46 cs17792 /usr/sbin/opensips[19012]: DBG:core:parse_headers: flags=78
>>>  Mar  5 16:07:46 cs17792 /usr/sbin/opensips[19012]: DBG:tm:t_lookup_request: start searching: hash=32018, isACK=0
>>>  Mar  5 16:07:46 cs17792 /usr/sbin/opensips[19012]: DBG:tm:matching_3261: RFC3261 transaction matching failed
>>>  Mar  5 16:07:46 cs17792 /usr/sbin/opensips[19012]: DBG:tm:t_lookup_request: no transaction found
>>>  Mar  5 16:07:46 cs17792 /usr/sbin/opensips[19012]: DBG:core:parse_headers: flags=200
>>>  Mar  5 16:07:46 cs17792 /usr/sbin/opensips[19012]: DBG:rr:find_first_route: No Route headers found
>>>  Mar  5 16:07:46 cs17792 /usr/sbin/opensips[19012]: DBG:rr:loose_route: There is no Route HF
>>>  Mar  5 16:07:46 cs17792 /usr/sbin/opensips[19012]: DBG:auth:check_nonce: comparing [54f85536be0ae02858c2001d58774c222d958f86] and [54f85536be0ae02858c2001d58774c222d958f86]
>>>  Mar  5 16:07:46 cs17792 /usr/sbin/opensips[19012]: DBG:db_mysql:has_stmt_ctx: ctx found for subscriber
>>>  Mar  5 16:07:46 cs17792 /usr/sbin/opensips[19012]: DBG:db_mysql:db_mysql_do_prepared_query: conn=0x7f2bef4e28b0 (tail=139826675195936) MC=0x7f2bef4e2080
>>>  Mar  5 16:07:46 cs17792 /usr/sbin/opensips[19012]: DBG:db_mysql:db_mysql_do_prepared_query: set values for the statement run
>>>  Mar  5 16:07:46 cs17792 /usr/sbin/opensips[19012]: DBG:db_mysql:db_mysql_val2bind: added val (0): len=8; type=254; is_null=0
>>>  Mar  5 16:07:46 cs17792 /usr/sbin/opensips[19012]: DBG:db_mysql:db_mysql_do_prepared_query: doing BIND_PARAM in...
>>>  Mar  5 16:07:46 cs17792 /usr/sbin/opensips[19012]: DBG:db_mysql:mysql_raise_event: MySQL status has not changed: connected
>>>  Mar  5 16:07:46 cs17792 /usr/sbin/opensips[19012]: DBG:db_mysql:db_mysql_do_prepared_query: prepared statement has 2 columns in result
>>>  Mar  5 16:07:46 cs17792 /usr/sbin/opensips[19012]: DBG:core:db_new_result: allocate 48 bytes for result set at 0x7f2bef4f5968
>>>  Mar  5 16:07:46 cs17792 /usr/sbin/opensips[19012]: DBG:db_mysql:db_mysql_get_columns: 2 columns returned from the query
>>>  Mar  5 16:07:46 cs17792 /usr/sbin/opensips[19012]: DBG:core:db_allocate_columns: allocate 56 bytes for result columns at 0x7f2bef4f6368
>>>  Mar  5 16:07:46 cs17792 /usr/sbin/opensips[19012]: DBG:db_mysql:db_mysql_get_columns: RES_NAMES(0x7f2bef4f6378)[0]=[ha1]
>>>  Mar  5 16:07:46 cs17792 /usr/sbin/opensips[19012]: DBG:db_mysql:db_mysql_get_columns: use DB_STRING result type
>>>  Mar  5 16:07:46 cs17792 /usr/sbin/opensips[19012]: DBG:db_mysql:db_mysql_get_columns: RES_NAMES(0x7f2bef4f6388)[1]=[mediaproxy]
>>>  Mar  5 16:07:46 cs17792 /usr/sbin/opensips[19012]: DBG:db_mysql:db_mysql_get_columns: use DB_STRING result type
>>>  Mar  5 16:07:46 cs17792 /usr/sbin/opensips[19012]: DBG:core:db_allocate_rows: allocate 80 bytes for result rows and values at 0x7f2bef4f6a48
>>>  Mar  5 16:07:46 cs17792 /usr/sbin/opensips[19012]: DBG:db_mysql:db_mysql_str2val: converting STRING [659cc07a1ab8ccbbc3b5ec2172bc6473]
>>>  Mar  5 16:07:46 cs17792 /usr/sbin/opensips[19012]: DBG:auth:check_response: our result = '06223b730875bf2c01ad98448dd08438'
>>>  Mar  5 16:07:46 cs17792 /usr/sbin/opensips[19012]: DBG:auth:check_response: authorization is OK
>>>  Mar  5 16:07:46 cs17792 /usr/sbin/opensips[19012]: DBG:core:db_free_columns: freeing result columns at 0x7f2bef4f6368
>>>  Mar  5 16:07:46 cs17792 /usr/sbin/opensips[19012]: DBG:core:db_free_rows: freeing 1 rows
>>>  Mar  5 16:07:46 cs17792 /usr/sbin/opensips[19012]: DBG:core:db_free_row: freeing row values at 0x7f2bef4f6a58
>>>  Mar  5 16:07:46 cs17792 /usr/sbin/opensips[19012]: DBG:core:db_free_rows: freeing rows at 0x7f2bef4f6a48
>>>  Mar  5 16:07:46 cs17792 /usr/sbin/opensips[19012]: DBG:core:db_free_result: freeing result set at 0x7f2bef4f5968
>>>  Mar  5 16:07:46 cs17792 /usr/sbin/opensips[19012]: DBG:registrar:lookup: found a complete match
>>>  Mar  5 16:07:46 cs17792 /usr/sbin/opensips[19012]: DBG:registrar:lookup: setting as ruri <sip:achalkov1 at 192.168.1.210:65062;transport=TLS;ob>
>>>  Mar  5 16:07:46 cs17792 /usr/sbin/opensips[19012]: DBG:registrar:lookup: looking for branches
>>>  Mar  5 16:07:46 cs17792 /usr/sbin/opensips[19012]: DBG:registrar:lookup: found a complete match
>>>  Mar  5 16:07:46 cs17792 /usr/sbin/opensips[19012]: DBG:registrar:lookup: setting as ruri <sip:achalkov1 at 192.168.1.210:65062;transport=TLS;ob>
>>>  Mar  5 16:07:46 cs17792 /usr/sbin/opensips[19012]: DBG:registrar:lookup: looking for branches
>>>  Mar  5 16:07:46 cs17792 /usr/sbin/opensips[19012]: DBG:core:comp_scriptvar: str 29 : 83.149.9.184
>>>  Mar  5 16:07:46 cs17792 /usr/sbin/opensips[19012]: DBG:tm:t_newtran: transaction on entrance=(nil)
>>>  Mar  5 16:07:46 cs17792 /usr/sbin/opensips[19012]: DBG:core:parse_headers: flags=ffffffffffffffff
>>>  Mar  5 16:07:46 cs17792 /usr/sbin/opensips[19012]: DBG:core:parse_headers: flags=78
>>>  Mar  5 16:07:46 cs17792 /usr/sbin/opensips[19012]: DBG:tm:t_lookup_request: start searching: hash=32018, isACK=0
>>>  Mar  5 16:07:46 cs17792 /usr/sbin/opensips[19012]: DBG:tm:matching_3261: RFC3261 transaction matching failed
>>>  Mar  5 16:07:46 cs17792 /usr/sbin/opensips[19012]: DBG:tm:t_lookup_request: no transaction found
>>>  Mar  5 16:07:46 cs17792 /usr/sbin/opensips[19012]: DBG:tm:run_reqin_callbacks: trans=0x7f2be91669a0, callback type 1, id 1 entered
>>>  Mar  5 16:07:46 cs17792 /usr/sbin/opensips[19012]: DBG:tm:run_reqin_callbacks: trans=0x7f2be91669a0, callback type 1, id 0 entered
>>>  Mar  5 16:07:46 cs17792 /usr/sbin/opensips[19012]: DBG:core:_shm_resize: resize(0) called
>>>  Mar  5 16:07:46 cs17792 /usr/sbin/opensips[19012]: DBG:core:mk_proxy: doing DNS lookup...
>>>  Mar  5 16:07:46 cs17792 /usr/sbin/opensips[19012]: DBG:core:parse_headers: flags=2000
>>>  Mar  5 16:07:46 cs17792 /usr/sbin/opensips[19012]: DBG:core:build_req_buf_from_sip_req: id added: <;i=1>, rcv proto=2
>>>  Mar  5 16:07:46 cs17792 /usr/sbin/opensips[19012]: DBG:core:tcp_send: no open tcp connection found, opening new one
>>>  Mar  5 16:07:46 cs17792 /usr/sbin/opensips[19012]: DBG:core:probe_max_sock_buff: getsockopt: snd is initially 16384
>>>  Mar  5 16:07:46 cs17792 /usr/sbin/opensips[19012]: DBG:core:probe_max_sock_buff: trying : 32768
>>>  Mar  5 16:07:46 cs17792 /usr/sbin/opensips[19012]: DBG:core:probe_max_sock_buff: setting snd: set=32768,verify=65536
>>>  Mar  5 16:07:46 cs17792 /usr/sbin/opensips[19012]: DBG:core:probe_max_sock_buff: trying : 65536
>>>  Mar  5 16:07:46 cs17792 /usr/sbin/opensips[19012]: DBG:core:probe_max_sock_buff: setting snd: set=65536,verify=131072
>>>  Mar  5 16:07:46 cs17792 /usr/sbin/opensips[19012]: DBG:core:probe_max_sock_buff: trying : 131072
>>>  Mar  5 16:07:46 cs17792 /usr/sbin/opensips[19012]: DBG:core:probe_max_sock_buff: setting snd: set=131072,verify=262142
>>>  Mar  5 16:07:46 cs17792 /usr/sbin/opensips[19012]: DBG:core:probe_max_sock_buff: trying : 262144
>>>  Mar  5 16:07:46 cs17792 /usr/sbin/opensips[19012]: DBG:core:probe_max_sock_buff: setting snd: set=262144,verify=262142
>>>  Mar  5 16:07:46 cs17792 /usr/sbin/opensips[19012]: DBG:core:probe_max_sock_buff: setting buf has no effect
>>>  Mar  5 16:07:46 cs17792 /usr/sbin/opensips[19012]: DBG:core:probe_max_sock_buff: trying : 133120
>>>  Mar  5 16:07:46 cs17792 /usr/sbin/opensips[19012]: DBG:core:probe_max_sock_buff: setting snd: set=133120,verify=262142
>>>  Mar  5 16:07:46 cs17792 /usr/sbin/opensips[19012]: DBG:core:probe_max_sock_buff: trying : 135168
>>>  Mar  5 16:07:46 cs17792 /usr/sbin/opensips[19012]: DBG:core:probe_max_sock_buff: setting snd: set=135168,verify=262142
>>>  Mar  5 16:07:46 cs17792 /usr/sbin/opensips[19012]: DBG:core:probe_max_sock_buff: trying : 137216
>>>  Mar  5 16:07:46 cs17792 /usr/sbin/opensips[19012]: DBG:core:probe_max_sock_buff: setting snd: set=137216,verify=262142
>>>  Mar  5 16:07:46 cs17792 /usr/sbin/opensips[19012]: DBG:core:probe_max_sock_buff: trying : 139264
>>>  Mar  5 16:07:46 cs17792 /usr/sbin/opensips[19012]: DBG:core:probe_max_sock_buff: setting snd: set=139264,verify=262142
>>>  Mar  5 16:07:46 cs17792 /usr/sbin/opensips[19012]: DBG:core:probe_max_sock_buff: trying : 141312
>>>  Mar  5 16:07:46 cs17792 /usr/sbin/opensips[19012]: DBG:core:probe_max_sock_buff: setting snd: set=141312,verify=262142
>>>  Mar  5 16:07:46 cs17792 /usr/sbin/opensips[19012]: DBG:core:probe_max_sock_buff: trying : 143360
>>>  Mar  5 16:07:46 cs17792 /usr/sbin/opensips[19012]: DBG:core:probe_max_sock_buff: setting snd: set=143360,verify=262142
>>>  Mar  5 16:07:46 cs17792 /usr/sbin/opensips[19012]: DBG:core:probe_max_sock_buff: trying : 145408
>>>  Mar  5 16:07:46 cs17792 /usr/sbin/opensips[19012]: DBG:core:probe_max_sock_buff: setting snd: set=145408,verify=262142
>>>  Mar  5 16:07:46 cs17792 /usr/sbin/opensips[19012]: DBG:core:probe_max_sock_buff: trying : 147456
>>>  Mar  5 16:07:46 cs17792 /usr/sbin/opensips[19012]: DBG:core:probe_max_sock_buff: setting snd: set=147456,verify=262142
>>>  Mar  5 16:07:46 cs17792 /usr/sbin/opensips[19012]: DBG:core:probe_max_sock_buff: trying : 149504
>>>  Mar  5 16:07:46 cs17792 /usr/sbin/opensips[19012]: DBG:core:probe_max_sock_buff: setting snd: set=149504,verify=262142
>>>  Mar  5 16:07:46 cs17792 /usr/sbin/opensips[19012]: DBG:core:probe_max_sock_buff: trying : 151552
>>>  Mar  5 16:07:46 cs17792 /usr/sbin/opensips[19012]: DBG:core:probe_max_sock_buff: setting snd: set=151552,verify=262142
>>>  Mar  5 16:07:46 cs17792 /usr/sbin/opensips[19012]: DBG:core:probe_max_sock_buff: trying : 153600
>>>  Mar  5 16:07:46 cs17792 /usr/sbin/opensips[19012]: DBG:core:probe_max_sock_buff: setting snd: set=153600,verify=262142
>>>  Mar  5 16:07:46 cs17792 /usr/sbin/opensips[19012]: DBG:core:probe_max_sock_buff: trying : 155648
>>>  Mar  5 16:07:46 cs17792 /usr/sbin/opensips[19012]: DBG:core:probe_max_sock_buff: setting snd: set=155648,verify=262142
>>>  Mar  5 16:07:46 cs17792 /usr/sbin/opensips[19012]: DBG:core:probe_max_sock_buff: trying : 157696
>>>  Mar  5 16:07:46 cs17792 /usr/sbin/opensips[19012]: DBG:core:probe_max_sock_buff: setting snd: set=157696,verify=262142
>>>  Mar  5 16:07:46 cs17792 /usr/sbin/opensips[19012]: DBG:core:probe_max_sock_buff: trying : 159744
>>>  Mar  5 16:07:46 cs17792 /usr/sbin/opensips[19012]: DBG:core:probe_max_sock_buff: setting snd: set=159744,verify=262142
>>>  Mar  5 16:07:46 cs17792 /usr/sbin/opensips[19012]: DBG:core:probe_max_sock_buff: trying : 161792
>>>  Mar  5 16:07:46 cs17792 /usr/sbin/opensips[19012]: DBG:core:probe_max_sock_buff: setting snd: set=161792,verify=262142
>>>  Mar  5 16:07:46 cs17792 /usr/sbin/opensips[19012]: DBG:core:probe_max_sock_buff: trying : 163840
>>>  Mar  5 16:07:46 cs17792 /usr/sbin/opensips[19012]: DBG:core:probe_max_sock_buff: setting snd: set=163840,verify=262142
>>>  Mar  5 16:07:46 cs17792 /usr/sbin/opensips[19012]: DBG:core:probe_max_sock_buff: trying : 165888
>>>  Mar  5 16:07:46 cs17792 /usr/sbin/opensips[19012]: DBG:core:probe_max_sock_buff: setting snd: set=165888,verify=262142
>>>  Mar  5 16:07:46 cs17792 /usr/sbin/opensips[19012]: DBG:core:probe_max_sock_buff: trying : 167936
>>>  Mar  5 16:07:46 cs17792 /usr/sbin/opensips[19012]: DBG:core:probe_max_sock_buff: setting snd: set=167936,verify=262142
>>>  Mar  5 16:07:46 cs17792 /usr/sbin/opensips[19012]: DBG:core:probe_max_sock_buff: trying : 169984
>>>  Mar  5 16:07:46 cs17792 /usr/sbin/opensips[19012]: DBG:core:probe_max_sock_buff: setting snd: set=169984,verify=262142
>>>  Mar  5 16:07:46 cs17792 /usr/sbin/opensips[19028]: DBG:core:handle_ser_child: read response= 7f2be91663a8, 1, fd -1 from 17 (19012)
>>>  Mar  5 16:07:49 cs17792 /usr/sbin/opensips[19010]: DBG:avpops:ops_dbquery_avps: query [SELECT username FROM silo GROUP BY username HAVING count(*) > 0]
>>>  Mar  5 16:07:49 cs17792 /usr/sbin/opensips[19010]: DBG:db_mysql:mysql_raise_event: MySQL status has not changed: connected
>>>  Mar  5 16:07:49 cs17792 /usr/sbin/opensips[19010]: DBG:core:db_new_result: allocate 48 bytes for result set at 0x7f2bef4e3aa8
>>>  Mar  5 16:07:49 cs17792 /usr/sbin/opensips[19010]: DBG:db_mysql:db_mysql_get_columns: 1 columns returned from the query
>>>  Mar  5 16:07:49 cs17792 /usr/sbin/opensips[19010]: DBG:core:db_allocate_columns: allocate 28 bytes for result columns at 0x7f2bef4e3af0
>>>  Mar  5 16:07:49 cs17792 /usr/sbin/opensips[19010]: DBG:db_mysql:db_mysql_get_columns: RES_NAMES(0x7f2bef4e3af8)[0]=[username]
>>>  Mar  5 16:07:49 cs17792 /usr/sbin/opensips[19010]: DBG:db_mysql:db_mysql_get_columns: use DB_STRING result type
>>>  Mar  5 16:07:49 cs17792 /usr/sbin/opensips[19010]: DBG:db_mysql:db_mysql_convert_rows: no rows returned from the query
>>>  Mar  5 16:07:49 cs17792 /usr/sbin/opensips[19010]: DBG:avpops:db_query_avp: no result after query
>>>  Mar  5 16:07:49 cs17792 /usr/sbin/opensips[19010]: DBG:avpops:db_close_query: close avp query
>>>  Mar  5 16:07:49 cs17792 /usr/sbin/opensips[19010]: DBG:core:db_free_columns: freeing result columns at 0x7f2bef4e3af0
>>>  Mar  5 16:07:49 cs17792 /usr/sbin/opensips[19010]: DBG:core:db_free_rows: freeing 0 rows
>>>  Mar  5 16:07:49 cs17792 /usr/sbin/opensips[19010]: DBG:core:db_free_result: freeing result set at 0x7f2bef4e3aa8
>>>  Mar  5 16:07:49 cs17792 /usr/sbin/opensips[19010]: DBG:core:destroy_avp_list: destroying list (nil)
>>>  Mar  5 16:07:52 cs17792 /usr/sbin/opensips[19009]: DBG:tm:timer_routine: timer routine:2,tl=0x7f2be9166a20 next=(nil), timeout=36
>>>  Mar  5 16:07:52 cs17792 /usr/sbin/opensips[19009]: DBG:tm:wait_handler: removing 0x7f2be91669a0 from table
>>>  Mar  5 16:07:52 cs17792 /usr/sbin/opensips[19009]: DBG:tm:delete_cell: delete transaction 0x7f2be91669a0
>>>  Mar  5 16:07:52 cs17792 /usr/sbin/opensips[19009]: DBG:tm:wait_handler: done
>>>
>>>  debug=3 with check
>>>
>>>                   if ($si != "127.0.0.1") t_on_failure("ON_FAIL_MESSAGE");
>>>                   t_relay("0x01");
>>>                   $var(retcode) = $retcode;
>>>                   xlog("L_INFO", "[!!!MESSAGE_DEBUG!!!] t_relay returns $var(retcode)");
>>>
>>>  Mar  5 16:15:01 cs17792 /usr/sbin/opensips[19205]: [MAIN] Incoming request (MESSAGE)
>>>  Mar  5 16:15:01 cs17792 /usr/sbin/opensips[19205]: INFO:core:probe_max_sock_buff: using snd buffer of 255 kb
>>>  Mar  5 16:15:01 cs17792 /usr/sbin/opensips[19205]: INFO:core:init_sock_keepalive: -- TCP keepalive enabled on socket
>>>  Mar  5 16:15:01 cs17792 /usr/sbin/opensips[19205]: ERROR:core:tcp_blocking_connect: poll error: flags 24 - 4 8 16 32
>>>  Mar  5 16:15:01 cs17792 /usr/sbin/opensips[19205]: ERROR:core:tcp_blocking_connect: failed to retrieve SO_ERROR [server=x.x.x.x:65106] (111) Connection refused
>>>  Mar  5 16:15:01 cs17792 /usr/sbin/opensips[19205]: ERROR:core:tcpconn_connect: tcp_blocking_connect failed
>>>  Mar  5 16:15:01 cs17792 /usr/sbin/opensips[19205]: ERROR:core:tcp_send: connect failed
>>>  Mar  5 16:15:01 cs17792 /usr/sbin/opensips[19205]: ERROR:tm:msg_send: tcp_send failed
>>>  Mar  5 16:15:01 cs17792 /usr/sbin/opensips[19205]: ERROR:tm:t_forward_nonack: sending request failed
>>>  Mar  5 16:15:01 cs17792 /usr/sbin/opensips[19205]: [!!!MESSAGE_DEBUG!!!] t_relay returns 1
>>>
>>>  05.03.2015, 15:39, "Vlad Paiu" <vladpaiu at opensips.org>:
>>>>    Hello,
>>>>
>>>>    Since TLS doesn't support async in 1.11, you should get an error
>>>>    straight out of t_relay()
>>>>    Can you please post the full debug logs here ?
>>>>
>>>>    Best Regards,
>>>>
>>>>    Vlad Paiu
>>>>    OpenSIPS Developer
>>>>    http://www.opensips-solutions.com
>>>>
>>>>    On 05.03.2015 13:44, Чалков Артём wrote:
>>>>>     Hi all!
>>>>>
>>>>>     Can someone help us?. I cannot understand how TLS in opensips 1.11 works.
>>>>>     The problem is when we use TLS, i cannot handle connection problems.
>>>>>
>>>>>     When i use TCP in async mode, i have 408 in failure route when outgoing TCP connection fails, when i use TCP in sync mode, i have negative status after t_relay(), however, after TLS, i cannot catch neither 408, or negative t_relay() status. So, how to handle TLS connection error?
>>>>>
>>>>>     _______________________________________________
>>>>>     Users mailing list
>>>>>     Users at lists.opensips.org
>>>>>     http://lists.opensips.org/cgi-bin/mailman/listinfo/users
>>>>    _______________________________________________
>>>>    Users mailing list
>>>>    Users at lists.opensips.org
>>>>    http://lists.opensips.org/cgi-bin/mailman/listinfo/users
>>>  _______________________________________________
>>>  Users mailing list
>>>  Users at lists.opensips.org
>>>  http://lists.opensips.org/cgi-bin/mailman/listinfo/users
>>  _______________________________________________
>>  Users mailing list
>>  Users at lists.opensips.org
>>  http://lists.opensips.org/cgi-bin/mailman/listinfo/users
>
> _______________________________________________
> Users mailing list
> Users at lists.opensips.org
> http://lists.opensips.org/cgi-bin/mailman/listinfo/users



More information about the Users mailing list