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; } } and that is debug=4 log from moment, when i killed softphone (destination of MESSAGE) without sip unregistering, but with removing tcp/tls connection: Mar 6 13:40:57 cs17792 /usr/sbin/opensips[6695]: DBG:stun:receive: Sending: from [9 x.x.x.x 3631] to [y.y.y.y 50693] Mar 6 13:40:57 cs17792 /usr/sbin/opensips[6695]: DBG:stun:receive: #012#012 Mar 6 13:40:57 cs17792 /usr/sbin/opensips[6695]: DBG:stun:freeStunMsg: freeing Mar 6 13:40:57 cs17792 /usr/sbin/opensips[6695]: DBG:stun:freeStunMsg: freeing Mar 6 13:40:57 cs17792 /usr/sbin/opensips[6695]: DBG:stun:stun_loop: READING Mar 6 13:40:57 cs17792 /usr/sbin/opensips[6713]: DBG:tm:timer_routine: timer routine:2,tl=0x7ff79cd256b0 next=(nil), timeout=12 Mar 6 13:40:57 cs17792 /usr/sbin/opensips[6713]: DBG:tm:wait_handler: removing 0x7ff79cd25630 from table Mar 6 13:40:57 cs17792 /usr/sbin/opensips[6713]: DBG:tm:delete_cell: delete transaction 0x7ff79cd25630 Mar 6 13:40:57 cs17792 /usr/sbin/opensips[6713]: DBG:tm:wait_handler: done Mar 6 13:41:02 cs17792 /usr/sbin/opensips[6698]: DBG:core:udp_rcv_loop: probing packet received len = 2 Mar 6 13:41:03 cs17792 /usr/sbin/opensips[6734]: DBG:core:handle_tcpconn_ev: data available on 0x7ff79cd2c578 53 Mar 6 13:41:03 cs17792 /usr/sbin/opensips[6734]: DBG:core:io_watch_del: io_watch_del op on index -1 53 (0x77dd80, 53, -1, 0x0,0x1) fd_no=40 called Mar 6 13:41:03 cs17792 /usr/sbin/opensips[6734]: DBG:core:send2child: to tcp child 0 0(6717), 0x7ff79cd2c578 rw 1 Mar 6 13:41:03 cs17792 /usr/sbin/opensips[6717]: DBG:core:handle_io: We have received conn 0x7ff79cd2c578 with rw 1 Mar 6 13:41:03 cs17792 /usr/sbin/opensips[6717]: DBG:core:io_watch_add: io_watch_add op on 36 (0x77dee0, 36, 2, 0x7ff79cd2c578,1), fd_no=1 Mar 6 13:41:03 cs17792 /usr/sbin/opensips[6717]: DBG:core:tcp_read_req: Using the global ( per process ) buff Mar 6 13:41:03 cs17792 /usr/sbin/opensips[6717]: DBG:core:tls_update_fd: New fd is 36 Mar 6 13:41:03 cs17792 /usr/sbin/opensips[6717]: ERROR:core:_tls_read: SYSCALL error -> (104) <Connection reset by peer> Mar 6 13:41:03 cs17792 /usr/sbin/opensips[6717]: ERROR:core:_tls_read: TLS connection to y.y.y.y:58858 read failed Mar 6 13:41:03 cs17792 /usr/sbin/opensips[6717]: ERROR:core:_tls_read: TLS read error: 5 Mar 6 13:41:03 cs17792 /usr/sbin/opensips[6717]: DBG:core:tcp_read_req: read= -1 bytes, parsed=0, state=0, error=1 Mar 6 13:41:03 cs17792 /usr/sbin/opensips[6717]: DBG:core:tcp_read_req: last char=0x00, parsed msg=#012 Mar 6 13:41:03 cs17792 /usr/sbin/opensips[6717]: ERROR:core:tcp_read_req: failed to read Mar 6 13:41:03 cs17792 /usr/sbin/opensips[6717]: DBG:core:io_watch_del: io_watch_del op on index -1 36 (0x77dee0, 36, -1, 0x10,0x3) fd_no=2 called Mar 6 13:41:03 cs17792 /usr/sbin/opensips[6717]: DBG:core:release_tcpconn: releasing con 0x7ff79cd2c578, state -2, fd=36, id=2 Mar 6 13:41:03 cs17792 /usr/sbin/opensips[6717]: DBG:core:release_tcpconn: extra_data 0x7ff79cd2c6f8 Mar 6 13:41:03 cs17792 /usr/sbin/opensips[6734]: DBG:core:handle_tcp_child: reader response= 7ff79cd2c578, -2 from 0 Mar 6 13:41:03 cs17792 /usr/sbin/opensips[6734]: DBG:core:tcpconn_destroy: destroying connection 0x7ff79cd2c578, flags 0002 Mar 6 13:41:03 cs17792 /usr/sbin/opensips[6734]: DBG:core:tls_close: closing TLS connection Mar 6 13:41:03 cs17792 /usr/sbin/opensips[6734]: DBG:core:tls_update_fd: New fd is 53 Mar 6 13:41:03 cs17792 /usr/sbin/opensips[6734]: ERROR:core:tls_shutdown: something wrong in SSL: Mar 6 13:41:03 cs17792 /usr/sbin/opensips[6734]: DBG:core:tls_tcpconn_clean: entered Mar 6 13:41:05 cs17792 /usr/sbin/opensips[6705]: DBG:msilo:m_clean_silo: cleaning stored messages - 20 Mar 6 13:41:07 cs17792 /usr/sbin/opensips[6715]: DBG:avpops:ops_dbquery_avps: query [SELECT username FROM silo GROUP BY username HAVING count(*) > 0] Mar 6 13:41:07 cs17792 /usr/sbin/opensips[6715]: DBG:db_mysql:mysql_raise_event: MySQL status has not changed: connected Mar 6 13:41:07 cs17792 /usr/sbin/opensips[6715]: DBG:core:db_new_result: allocate 48 bytes for result set at 0x7ff7a39ac9c8 Mar 6 13:41:07 cs17792 /usr/sbin/opensips[6715]: DBG:db_mysql:db_mysql_get_columns: 1 columns returned from the query Mar 6 13:41:07 cs17792 /usr/sbin/opensips[6715]: DBG:core:db_allocate_columns: allocate 28 bytes for result columns at 0x7ff7a39aca10 Mar 6 13:41:07 cs17792 /usr/sbin/opensips[6715]: DBG:db_mysql:db_mysql_get_columns: RES_NAMES(0x7ff7a39aca18)[0]=[username] Mar 6 13:41:07 cs17792 /usr/sbin/opensips[6715]: DBG:db_mysql:db_mysql_get_columns: use DB_STRING result type Mar 6 13:41:07 cs17792 /usr/sbin/opensips[6715]: DBG:db_mysql:db_mysql_convert_rows: no rows returned from the query Mar 6 13:41:07 cs17792 /usr/sbin/opensips[6715]: DBG:avpops:db_query_avp: no result after query Mar 6 13:41:07 cs17792 /usr/sbin/opensips[6715]: DBG:avpops:db_close_query: close avp query Mar 6 13:41:07 cs17792 /usr/sbin/opensips[6715]: DBG:core:db_free_columns: freeing result columns at 0x7ff7a39aca10 Mar 6 13:41:07 cs17792 /usr/sbin/opensips[6715]: DBG:core:db_free_rows: freeing 0 rows Mar 6 13:41:07 cs17792 /usr/sbin/opensips[6715]: DBG:core:db_free_result: freeing result set at 0x7ff7a39ac9c8 Mar 6 13:41:07 cs17792 /usr/sbin/opensips[6715]: DBG:core:destroy_avp_list: destroying list (nil) Mar 6 13:41:10 cs17792 /usr/sbin/opensips[6696]: DBG:core:udp_rcv_loop: probing packet received len = 2 Mar 6 13:41:14 cs17792 /usr/sbin/opensips[6734]: DBG:core:handle_tcpconn_ev: data available on 0x7ff79cd21908 52 Mar 6 13:41:14 cs17792 /usr/sbin/opensips[6734]: DBG:core:io_watch_del: io_watch_del op on index -1 52 (0x77dd80, 52, -1, 0x0,0x1) fd_no=39 called Mar 6 13:41:14 cs17792 /usr/sbin/opensips[6734]: DBG:core:send2child: to tcp child 0 0(6717), 0x7ff79cd21908 rw 1 Mar 6 13:41:14 cs17792 /usr/sbin/opensips[6717]: DBG:core:handle_io: We have received conn 0x7ff79cd21908 with rw 1 Mar 6 13:41:14 cs17792 /usr/sbin/opensips[6717]: DBG:core:io_watch_add: io_watch_add op on 36 (0x77dee0, 36, 2, 0x7ff79cd21908,1), fd_no=1 Mar 6 13:41:14 cs17792 /usr/sbin/opensips[6717]: DBG:core:tcp_read_req: Using the global ( per process ) buff Mar 6 13:41:14 cs17792 /usr/sbin/opensips[6717]: DBG:core:tcp_read_req: read= 573 bytes, parsed=573, state=4, error=1 Mar 6 13:41:14 cs17792 /usr/sbin/opensips[6717]: DBG:core:tcp_read_req: last char=0x33, parsed msg=#012MESSAGE sip:achalkov1@x.x.x.x:3631;transport=TCP SIP/2.0#015#012Via: SIP/2.0/TCP y.y.y.y:59137;branch=z9hG4bK-d8754z-b937eb7870cff11c-1---d8754z-;rport#015#012Max-Forwards: 70#015#012To: <sip:achalkov1@x.x.x.x:3631;transport=TCP>#015#012From: "achalkov"<sip:achalkov@x.x.x.x:3631;transport=TCP>;tag=64746f23#015#012Call-ID: NmRjMDQ1NGNiY2ExMjQzNzQxMDg0NDY2M2U4YmY3OGI.#015#012CSeq: 2 MESSAGE#015#012Allow: INVITE, ACK, CANCEL, BYE, NOTIFY, REFER, MESSAGE, OPTIONS, INFO, SUBSCRIBE#015#012Content-Type: text/plain#015#012User-Agent: Zoiper r21367#015#012Allow-Events: presence, kpml#015#012Content-Length: 3#015#012#015#012123 Mar 6 13:41:14 cs17792 /usr/sbin/opensips[6717]: DBG:core:tcp_read_req: content-length= 3 Mar 6 13:41:14 cs17792 /usr/sbin/opensips[6717]: DBG:core:tcp_read_req: We're releasing the connection in state 3 Mar 6 13:41:14 cs17792 /usr/sbin/opensips[6717]: DBG:core:io_watch_del: io_watch_del op on index -1 36 (0x77dee0, 36, -1, 0x10,0x1) fd_no=2 called Mar 6 13:41:14 cs17792 /usr/sbin/opensips[6717]: DBG:core:release_tcpconn: releasing con 0x7ff79cd21908, state 0, fd=36, id=1 Mar 6 13:41:14 cs17792 /usr/sbin/opensips[6717]: DBG:core:release_tcpconn: extra_data (nil) Mar 6 13:41:14 cs17792 /usr/sbin/opensips[6717]: DBG:core:parse_msg: SIP Request: Mar 6 13:41:14 cs17792 /usr/sbin/opensips[6717]: DBG:core:parse_msg: method: <MESSAGE> Mar 6 13:41:14 cs17792 /usr/sbin/opensips[6717]: DBG:core:parse_msg: uri: <sip:achalkov1@x.x.x.x:3631;transport=TCP> Mar 6 13:41:14 cs17792 /usr/sbin/opensips[6717]: DBG:core:parse_msg: version: <SIP/2.0> Mar 6 13:41:14 cs17792 /usr/sbin/opensips[6717]: DBG:core:parse_headers: flags=2 Mar 6 13:41:14 cs17792 /usr/sbin/opensips[6717]: DBG:core:parse_via_param: found param type 232, <branch> = <z9hG4bK-d8754z-b937eb7870cff11c-1---d8754z->; state=6 Mar 6 13:41:14 cs17792 /usr/sbin/opensips[6717]: DBG:core:parse_via_param: found param type 235, <rport> = <n/a>; state=17 Mar 6 13:41:14 cs17792 /usr/sbin/opensips[6717]: DBG:core:parse_via: end of header reached, state=5 Mar 6 13:41:14 cs17792 /usr/sbin/opensips[6717]: DBG:core:parse_headers: via found, flags=2 Mar 6 13:41:14 cs17792 /usr/sbin/opensips[6717]: DBG:core:parse_headers: this is the first via Mar 6 13:41:14 cs17792 /usr/sbin/opensips[6717]: DBG:core:receive_msg: After parse_msg... Mar 6 13:41:14 cs17792 /usr/sbin/opensips[6717]: DBG:core:receive_msg: preparing to run routing scripts... Mar 6 13:41:14 cs17792 /usr/sbin/opensips[6717]: DBG:core:pv_get_dsturi: no destination URI Mar 6 13:41:14 cs17792 /usr/sbin/opensips[6717]: DBG:core:parse_headers: flags=10 Mar 6 13:41:14 cs17792 /usr/sbin/opensips[6717]: DBG:core:parse_to: end of header reached, state=10 Mar 6 13:41:14 cs17792 /usr/sbin/opensips[6717]: DBG:core:parse_to: display={}, ruri={sip:achalkov1@x.x.x.x:3631;transport=TCP} Mar 6 13:41:14 cs17792 /usr/sbin/opensips[6717]: DBG:core:get_hdr_field: <To> [51]; uri=[sip:achalkov1@x.x.x.x:3631;transport=TCP] Mar 6 13:41:14 cs17792 /usr/sbin/opensips[6717]: DBG:core:get_hdr_field: to body [<sip:achalkov1@x.x.x.x:3631;transport=TCP>#015#012] Mar 6 13:41:14 cs17792 /usr/sbin/opensips[6717]: DBG:core:parse_to_param: tag=64746f23 Mar 6 13:41:14 cs17792 /usr/sbin/opensips[6717]: DBG:core:parse_to: end of header reached, state=29 Mar 6 13:41:14 cs17792 /usr/sbin/opensips[6717]: DBG:core:parse_to: display={"achalkov"}, ruri={sip:achalkov@x.x.x.x:3631;transport=TCP} Mar 6 13:41:14 cs17792 /usr/sbin/opensips[6717]: DBG:core:pv_get_dsturi_attr: no destination URI Mar 6 13:41:14 cs17792 /usr/sbin/opensips[6717]: DBG:core:parse_headers: flags=40 Mar 6 13:41:14 cs17792 /usr/sbin/opensips[6717]: DBG:core:parse_headers: flags=ffffffffffffffff Mar 6 13:41:14 cs17792 /usr/sbin/opensips[6717]: DBG:core:get_hdr_field: cseq <CSeq>: <2> <MESSAGE> Mar 6 13:41:14 cs17792 /usr/sbin/opensips[6717]: DBG:core:get_hdr_field: content_length=3 Mar 6 13:41:14 cs17792 /usr/sbin/opensips[6717]: DBG:core:get_hdr_field: found end of header Mar 6 13:41:14 cs17792 /usr/sbin/opensips[6717]: DBG:core:pv_get_contact_body: no contact header! Mar 6 13:41:14 cs17792 /usr/sbin/opensips[6717]: [MAIN] Incoming request (M=MESSAGE IP=tcp:y.y.y.y:59141 fromIP=tcp:y.y.y.y:59141 RURI=sip:achalkov1@x.x.x.x:3631;transport=TCP DURI=<null> F=sip:achalkov@x.x.x.x:3631;transport=TCP T=sip:achalkov1@x.x.x.x:3631;transport=TCP oP=TCP dP=<null> rP=TCP ID=NmRjMDQ1NGNiY2ExMjQzNzQxMDg0NDY2M2U4YmY3OGI. ct=<null> cseq=2 UA=Zoiper r21367)#012MESSAGE sip:achalkov1@x.x.x.x:3631;transport=TCP SIP/2.0#015#012Via: SIP/2.0/TCP y.y.y.y:59137;branch=z9hG4bK-d8754z-b937eb7870cff11c-1---d8754z-;rport#015#012Max-Forwards: 70#015#012To: <sip:achalkov1@x.x.x.x:3631;transport=TCP>#015#012From: "achalkov"<sip:achalkov@x.x.x.x:3631;transport=TCP>;tag=64746f23#015#012Call-ID: NmRjMDQ1NGNiY2ExMjQzNzQxMDg0NDY2M2U4YmY3OGI.#015#012CSeq: 2 MESSAGE#015#012Allow: INVITE, ACK, CANCEL, BYE, NOTIFY, REFER, MESSAGE, OPTIONS, INFO, SUBSCRIBE#015#012Content-Type: text/plain#015#012User-Agent: Zoiper r21367#015#012Allow-Events: presence, kpml#015#012Content-Length: 3#015#012#015#012123 Mar 6 13:41:14 cs17792 /usr/sbin/opensips[6717]: DBG:maxfwd:is_maxfwd_present: value = 70 Mar 6 13:41:14 cs17792 /usr/sbin/opensips[6717]: DBG:core:parse_headers: flags=ffffffffffffffff Mar 6 13:41:14 cs17792 /usr/sbin/opensips[6717]: DBG:core:parse_headers: flags=ffffffffffffffff Mar 6 13:41:14 cs17792 /usr/sbin/opensips[6717]: DBG:core:decode_mime_type: Decoding MIME type for:[text/plain] Mar 6 13:41:14 cs17792 /usr/sbin/opensips[6717]: DBG:core:parse_headers: flags=ffffffffffffffff Mar 6 13:41:14 cs17792 /usr/sbin/opensips[6717]: DBG:core:parse_methods: methods 0x173F Mar 6 13:41:14 cs17792 /usr/sbin/opensips[6717]: DBG:uri:has_totag: no totag Mar 6 13:41:14 cs17792 /usr/sbin/opensips[6717]: DBG:core:parse_headers: flags=78 Mar 6 13:41:14 cs17792 /usr/sbin/opensips[6717]: DBG:tm:t_lookup_request: start searching: hash=43604, isACK=0 Mar 6 13:41:14 cs17792 /usr/sbin/opensips[6717]: DBG:tm:matching_3261: RFC3261 transaction matching failed Mar 6 13:41:14 cs17792 /usr/sbin/opensips[6717]: DBG:tm:t_lookup_request: no transaction found Mar 6 13:41:14 cs17792 /usr/sbin/opensips[6734]: DBG:core:handle_tcp_child: reader response= 7ff79cd21908, 0 from 0 Mar 6 13:41:14 cs17792 /usr/sbin/opensips[6734]: DBG:core:io_watch_add: io_watch_add op on 52 (0x77dd80, 52, 2, 0x7ff79cd21908,1), fd_no=38 Mar 6 13:41:14 cs17792 /usr/sbin/opensips[6717]: DBG:core:parse_headers: flags=200 Mar 6 13:41:14 cs17792 /usr/sbin/opensips[6717]: DBG:rr:find_first_route: No Route headers found Mar 6 13:41:14 cs17792 /usr/sbin/opensips[6717]: DBG:rr:loose_route: There is no Route HF Mar 6 13:41:14 cs17792 /usr/sbin/opensips[6717]: DBG:core:parse_headers: flags=4000 Mar 6 13:41:14 cs17792 /usr/sbin/opensips[6717]: DBG:auth:pre_auth: credentials with given realm not found Mar 6 13:41:14 cs17792 /usr/sbin/opensips[6717]: DBG:core:pv_get_dsturi: no destination URI Mar 6 13:41:14 cs17792 /usr/sbin/opensips[6717]: DBG:core:pv_get_dsturi_attr: no destination URI Mar 6 13:41:14 cs17792 /usr/sbin/opensips[6717]: DBG:core:parse_headers: flags=ffffffffffffffff Mar 6 13:41:14 cs17792 /usr/sbin/opensips[6717]: DBG:core:pv_get_contact_body: no contact header! Mar 6 13:41:14 cs17792 /usr/sbin/opensips[6717]: [AUTH] Result: no credentials (M=MESSAGE IP=tcp:y.y.y.y:59141 fromIP=tcp:y.y.y.y:59141 RURI=sip:achalkov1@x.x.x.x:3631;transport=TCP DURI=<null> F=sip:achalkov@x.x.x.x:3631;transport=TCP T=sip:achalkov1@x.x.x.x:3631;transport=TCP oP=TCP dP=<null> rP=TCP ID=NmRjMDQ1NGNiY2ExMjQzNzQxMDg0NDY2M2U4YmY3OGI. ct=<null> cseq=2 UA=Zoiper r21367) Mar 6 13:41:14 cs17792 /usr/sbin/opensips[6717]: DBG:auth:build_auth_hf: 'WWW-Authenticate: Digest realm="x.x.x.x", nonce="54f9845e8218cc613726d1518e7e7f6b1f64cf1e", qop="auth"#015#012' Mar 6 13:41:14 cs17792 /usr/sbin/opensips[6717]: DBG:core:parse_headers: flags=ffffffffffffffff Mar 6 13:41:14 cs17792 /usr/sbin/opensips[6717]: DBG:core:tcp_send: tcp connection found (0x7ff79cd21908), acquiring fd Mar 6 13:41:14 cs17792 /usr/sbin/opensips[6717]: DBG:core:tcp_send: c= 0x7ff79cd21908, n=16 Mar 6 13:41:14 cs17792 /usr/sbin/opensips[6734]: DBG:core:handle_ser_child: read response= 7ff79cd21908, 1, fd -1 from 17 (6717) Mar 6 13:41:14 cs17792 /usr/sbin/opensips[6717]: DBG:core:tcp_send: after receive_fd: c= 0x7ff79cd21908 n=8 fd=36 Mar 6 13:41:14 cs17792 /usr/sbin/opensips[6717]: DBG:core:tcp_send: sending... Mar 6 13:41:14 cs17792 /usr/sbin/opensips[6717]: DBG:core:async_tsend_stream: Async succesful write from first try on 0x7ff79cd21908 Mar 6 13:41:14 cs17792 /usr/sbin/opensips[6717]: DBG:core:tcp_send: after write: c= 0x7ff79cd21908 n=548 fd=36 Mar 6 13:41:14 cs17792 /usr/sbin/opensips[6717]: DBG:core:tcp_send: buf=#012SIP/2.0 401 Unauthorized#015#012Via: SIP/2.0/TCP y.y.y.y:59137;received=y.y.y.y;branch=z9hG4bK-d8754z-b937eb7870cff11c-1---d8754z-;rport=59141#015#012To: <sip:achalkov1@x.x.x.x:3631;transport=TCP>;tag=d8c8651e9db6867219201727ad85910e.0fda#015#012From: "achalkov"<sip:achalkov@x.x.x.x:3631;transport=TCP>;tag=64746f23#015#012Call-ID: NmRjMDQ1NGNiY2ExMjQzNzQxMDg0NDY2M2U4YmY3OGI.#015#012CSeq: 2 MESSAGE#015#012WWW-Authenticate: Digest realm="x.x.x.x", nonce="54f9845e8218cc613726d1518e7e7f6b1f64cf1e", qop="auth"#015#012Server: Softswitch#015#012Content-Length: 0#015#012#015#012 Mar 6 13:41:14 cs17792 /usr/sbin/opensips[6717]: DBG:core:destroy_avp_list: destroying list (nil) Mar 6 13:41:14 cs17792 /usr/sbin/opensips[6717]: DBG:core:receive_msg: cleaning up Mar 6 13:41:14 cs17792 /usr/sbin/opensips[6717]: DBG:core:tcp_read_req: tcp_read_req end Mar 6 13:41:14 cs17792 /usr/sbin/opensips[6734]: DBG:core:handle_tcpconn_ev: data available on 0x7ff79cd21908 52 Mar 6 13:41:14 cs17792 /usr/sbin/opensips[6734]: DBG:core:io_watch_del: io_watch_del op on index -1 52 (0x77dd80, 52, -1, 0x0,0x1) fd_no=39 called Mar 6 13:41:14 cs17792 /usr/sbin/opensips[6734]: DBG:core:send2child: to tcp child 0 0(6717), 0x7ff79cd21908 rw 1 Mar 6 13:41:14 cs17792 /usr/sbin/opensips[6717]: DBG:core:handle_io: We have received conn 0x7ff79cd21908 with rw 1 Mar 6 13:41:14 cs17792 /usr/sbin/opensips[6717]: DBG:core:io_watch_add: io_watch_add op on 36 (0x77dee0, 36, 2, 0x7ff79cd21908,1), fd_no=1 Mar 6 13:41:14 cs17792 /usr/sbin/opensips[6717]: DBG:core:tcp_read_req: Using the global ( per process ) buff Mar 6 13:41:14 cs17792 /usr/sbin/opensips[6717]: DBG:core:tcp_read_req: read= 863 bytes, parsed=863, state=4, error=1 Mar 6 13:41:14 cs17792 /usr/sbin/opensips[6717]: DBG:core:tcp_read_req: last char=0x33, parsed msg=#012MESSAGE sip:achalkov1@x.x.x.x:3631;transport=TCP SIP/2.0#015#012Via: SIP/2.0/TCP y.y.y.y:59137;branch=z9hG4bK-d8754z-bfd5c930058a8509-1---d8754z-;rport#015#012Max-Forwards: 70#015#012To: <sip:achalkov1@x.x.x.x:3631;transport=TCP>#015#012From: "achalkov"<sip:achalkov@x.x.x.x:3631;transport=TCP>;tag=64746f23#015#012Call-ID: NmRjMDQ1NGNiY2ExMjQzNzQxMDg0NDY2M2U4YmY3OGI.#015#012CSeq: 3 MESSAGE#015#012Allow: INVITE, ACK, CANCEL, BYE, NOTIFY, REFER, MESSAGE, OPTIONS, INFO, SUBSCRIBE#015#012Content-Type: text/plain#015#012User-Agent: Zoiper r21367#015#012Authorization: Digest username="achalkov",realm="x.x.x.x",nonce="54f9845e8218cc613726d1518e7e7f6b1f64cf1e",uri="sip:achalkov1@x.x.x.x:3631;transport=TCP",response="7937faa022bb7c6b585df82ac2df0b61",cnonce="52edf7bcbdb8c892c00c506d46140e1b",nc=00000001,qop=auth,algorithm=MD5#015#012Allow-Events: presence, kpml#015#012Content-Length: 3#015#012#015#012123 Mar 6 13:41:14 cs17792 /usr/sbin/opensips[6717]: DBG:core:tcp_read_req: content-length= 3 Mar 6 13:41:14 cs17792 /usr/sbin/opensips[6717]: DBG:core:tcp_read_req: We're releasing the connection in state 3 Mar 6 13:41:14 cs17792 /usr/sbin/opensips[6717]: DBG:core:io_watch_del: io_watch_del op on index -1 36 (0x77dee0, 36, -1, 0x10,0x1) fd_no=2 called Mar 6 13:41:14 cs17792 /usr/sbin/opensips[6717]: DBG:core:release_tcpconn: releasing con 0x7ff79cd21908, state 0, fd=36, id=1 Mar 6 13:41:14 cs17792 /usr/sbin/opensips[6717]: DBG:core:release_tcpconn: extra_data (nil) Mar 6 13:41:14 cs17792 /usr/sbin/opensips[6717]: DBG:core:parse_msg: SIP Request: Mar 6 13:41:14 cs17792 /usr/sbin/opensips[6717]: DBG:core:parse_msg: method: <MESSAGE> Mar 6 13:41:14 cs17792 /usr/sbin/opensips[6717]: DBG:core:parse_msg: uri: <sip:achalkov1@x.x.x.x:3631;transport=TCP> Mar 6 13:41:14 cs17792 /usr/sbin/opensips[6717]: DBG:core:parse_msg: version: <SIP/2.0> Mar 6 13:41:14 cs17792 /usr/sbin/opensips[6717]: DBG:core:parse_headers: flags=2 Mar 6 13:41:14 cs17792 /usr/sbin/opensips[6717]: DBG:core:parse_via_param: found param type 232, <branch> = <z9hG4bK-d8754z-bfd5c930058a8509-1---d8754z->; state=6 Mar 6 13:41:14 cs17792 /usr/sbin/opensips[6717]: DBG:core:parse_via_param: found param type 235, <rport> = <n/a>; state=17 Mar 6 13:41:14 cs17792 /usr/sbin/opensips[6717]: DBG:core:parse_via: end of header reached, state=5 Mar 6 13:41:14 cs17792 /usr/sbin/opensips[6717]: DBG:core:parse_headers: via found, flags=2 Mar 6 13:41:14 cs17792 /usr/sbin/opensips[6717]: DBG:core:parse_headers: this is the first via Mar 6 13:41:14 cs17792 /usr/sbin/opensips[6717]: DBG:core:receive_msg: After parse_msg... Mar 6 13:41:14 cs17792 /usr/sbin/opensips[6717]: DBG:core:receive_msg: preparing to run routing scripts... Mar 6 13:41:14 cs17792 /usr/sbin/opensips[6717]: DBG:core:pv_get_dsturi: no destination URI Mar 6 13:41:14 cs17792 /usr/sbin/opensips[6717]: DBG:core:parse_headers: flags=10 Mar 6 13:41:14 cs17792 /usr/sbin/opensips[6717]: DBG:core:parse_to: end of header reached, state=10 Mar 6 13:41:14 cs17792 /usr/sbin/opensips[6717]: DBG:core:parse_to: display={}, ruri={sip:achalkov1@x.x.x.x:3631;transport=TCP} Mar 6 13:41:14 cs17792 /usr/sbin/opensips[6717]: DBG:core:get_hdr_field: <To> [51]; uri=[sip:achalkov1@x.x.x.x:3631;transport=TCP] Mar 6 13:41:14 cs17792 /usr/sbin/opensips[6717]: DBG:core:get_hdr_field: to body [<sip:achalkov1@x.x.x.x:3631;transport=TCP>#015#012] Mar 6 13:41:14 cs17792 /usr/sbin/opensips[6717]: DBG:core:parse_to_param: tag=64746f23 Mar 6 13:41:14 cs17792 /usr/sbin/opensips[6717]: DBG:core:parse_to: end of header reached, state=29 Mar 6 13:41:14 cs17792 /usr/sbin/opensips[6717]: DBG:core:parse_to: display={"achalkov"}, ruri={sip:achalkov@x.x.x.x:3631;transport=TCP} Mar 6 13:41:14 cs17792 /usr/sbin/opensips[6717]: DBG:core:pv_get_dsturi_attr: no destination URI Mar 6 13:41:14 cs17792 /usr/sbin/opensips[6717]: DBG:core:parse_headers: flags=40 Mar 6 13:41:14 cs17792 /usr/sbin/opensips[6717]: DBG:core:parse_headers: flags=ffffffffffffffff Mar 6 13:41:14 cs17792 /usr/sbin/opensips[6717]: DBG:core:get_hdr_field: cseq <CSeq>: <3> <MESSAGE> Mar 6 13:41:14 cs17792 /usr/sbin/opensips[6717]: DBG:core:get_hdr_field: content_length=3 Mar 6 13:41:14 cs17792 /usr/sbin/opensips[6717]: DBG:core:get_hdr_field: found end of header Mar 6 13:41:14 cs17792 /usr/sbin/opensips[6717]: DBG:core:pv_get_contact_body: no contact header! Mar 6 13:41:14 cs17792 /usr/sbin/opensips[6717]: [MAIN] Incoming request (M=MESSAGE IP=tcp:y.y.y.y:59141 fromIP=tcp:y.y.y.y:59141 RURI=sip:achalkov1@x.x.x.x:3631;transport=TCP DURI=<null> F=sip:achalkov@x.x.x.x:3631;transport=TCP T=sip:achalkov1@x.x.x.x:3631;transport=TCP oP=TCP dP=<null> rP=TCP ID=NmRjMDQ1NGNiY2ExMjQzNzQxMDg0NDY2M2U4YmY3OGI. ct=<null> cseq=3 UA=Zoiper r21367)#012MESSAGE sip:achalkov1@x.x.x.x:3631;transport=TCP SIP/2.0#015#012Via: SIP/2.0/TCP y.y.y.y:59137;branch=z9hG4bK-d8754z-bfd5c930058a8509-1---d8754z-;rport#015#012Max-Forwards: 70#015#012To: <sip:achalkov1@x.x.x.x:3631;transport=TCP>#015#012From: "achalkov"<sip:achalkov@x.x.x.x:3631;transport=TCP>;tag=64746f23#015#012Call-ID: NmRjMDQ1NGNiY2ExMjQzNzQxMDg0NDY2M2U4YmY3OGI.#015#012CSeq: 3 MESSAGE#015#012Allow: INVITE, ACK, CANCEL, BYE, NOTIFY, REFER, MESSAGE, OPTIONS, INFO, SUBSCRIBE#015#012Content-Type: text/plain#015#012User-Agent: Zoiper r21367#015#012Authorization: Digest username="achalkov",realm="x.x.x.x",nonce="54f9845e8218cc613726d1518e7e7f6b1f64cf1e",uri="sip:achalkov1@x.x.x.x:3631;transport=TCP",response="7937faa022bb7c6b585df82ac2df0b61",cnonce="52edf7bcbdb8c892c00c506d46140e1b",nc=00000001,qop=auth,algorithm=MD5#015#012Allow-Events: presence, kpml#015#012Content-Length: 3#015#012#015#012123 Mar 6 13:41:14 cs17792 /usr/sbin/opensips[6717]: DBG:maxfwd:is_maxfwd_present: value = 70 Mar 6 13:41:14 cs17792 /usr/sbin/opensips[6717]: DBG:core:parse_headers: flags=ffffffffffffffff Mar 6 13:41:14 cs17792 /usr/sbin/opensips[6717]: DBG:core:parse_headers: flags=ffffffffffffffff Mar 6 13:41:14 cs17792 /usr/sbin/opensips[6717]: DBG:core:decode_mime_type: Decoding MIME type for:[text/plain] Mar 6 13:41:14 cs17792 /usr/sbin/opensips[6717]: DBG:core:parse_headers: flags=ffffffffffffffff Mar 6 13:41:14 cs17792 /usr/sbin/opensips[6717]: DBG:core:parse_methods: methods 0x173F Mar 6 13:41:14 cs17792 /usr/sbin/opensips[6717]: DBG:uri:has_totag: no totag Mar 6 13:41:14 cs17792 /usr/sbin/opensips[6717]: DBG:core:parse_headers: flags=78 Mar 6 13:41:14 cs17792 /usr/sbin/opensips[6717]: DBG:tm:t_lookup_request: start searching: hash=43605, isACK=0 Mar 6 13:41:14 cs17792 /usr/sbin/opensips[6717]: DBG:tm:matching_3261: RFC3261 transaction matching failed Mar 6 13:41:14 cs17792 /usr/sbin/opensips[6717]: DBG:tm:t_lookup_request: no transaction found Mar 6 13:41:14 cs17792 /usr/sbin/opensips[6734]: DBG:core:handle_tcp_child: reader response= 7ff79cd21908, 0 from 0 Mar 6 13:41:14 cs17792 /usr/sbin/opensips[6734]: DBG:core:io_watch_add: io_watch_add op on 52 (0x77dd80, 52, 2, 0x7ff79cd21908,1), fd_no=38 Mar 6 13:41:14 cs17792 /usr/sbin/opensips[6717]: DBG:core:parse_headers: flags=200 Mar 6 13:41:14 cs17792 /usr/sbin/opensips[6717]: DBG:rr:find_first_route: No Route headers found Mar 6 13:41:14 cs17792 /usr/sbin/opensips[6717]: DBG:rr:loose_route: There is no Route HF Mar 6 13:41:14 cs17792 /usr/sbin/opensips[6717]: DBG:auth:check_nonce: comparing [54f9845e8218cc613726d1518e7e7f6b1f64cf1e] and [54f9845e8218cc613726d1518e7e7f6b1f64cf1e] Mar 6 13:41:14 cs17792 /usr/sbin/opensips[6717]: DBG:db_mysql:has_stmt_ctx: ctx found for subscriber Mar 6 13:41:14 cs17792 /usr/sbin/opensips[6717]: DBG:db_mysql:db_mysql_do_prepared_query: conn=0x7ff7a39ab7d0 (tail=140701578473280) MC=0x7ff7a39aafa0 Mar 6 13:41:14 cs17792 /usr/sbin/opensips[6717]: DBG:db_mysql:db_mysql_do_prepared_query: set values for the statement run Mar 6 13:41:14 cs17792 /usr/sbin/opensips[6717]: DBG:db_mysql:db_mysql_val2bind: added val (0): len=8; type=254; is_null=0 Mar 6 13:41:14 cs17792 /usr/sbin/opensips[6717]: DBG:db_mysql:db_mysql_do_prepared_query: doing BIND_PARAM in... Mar 6 13:41:14 cs17792 /usr/sbin/opensips[6717]: DBG:db_mysql:mysql_raise_event: MySQL status has not changed: connected Mar 6 13:41:14 cs17792 /usr/sbin/opensips[6717]: DBG:db_mysql:db_mysql_do_prepared_query: prepared statement has 2 columns in result Mar 6 13:41:14 cs17792 /usr/sbin/opensips[6717]: DBG:core:db_new_result: allocate 48 bytes for result set at 0x7ff7a39c4850 Mar 6 13:41:14 cs17792 /usr/sbin/opensips[6717]: DBG:db_mysql:db_mysql_get_columns: 2 columns returned from the query Mar 6 13:41:14 cs17792 /usr/sbin/opensips[6717]: DBG:core:db_allocate_columns: allocate 56 bytes for result columns at 0x7ff7a39c4898 Mar 6 13:41:14 cs17792 /usr/sbin/opensips[6717]: DBG:db_mysql:db_mysql_get_columns: RES_NAMES(0x7ff7a39c48a8)[0]=[ha1] Mar 6 13:41:14 cs17792 /usr/sbin/opensips[6717]: DBG:db_mysql:db_mysql_get_columns: use DB_STRING result type Mar 6 13:41:14 cs17792 /usr/sbin/opensips[6717]: DBG:db_mysql:db_mysql_get_columns: RES_NAMES(0x7ff7a39c48b8)[1]=[mediaproxy] Mar 6 13:41:14 cs17792 /usr/sbin/opensips[6717]: DBG:db_mysql:db_mysql_get_columns: use DB_STRING result type Mar 6 13:41:14 cs17792 /usr/sbin/opensips[6717]: DBG:core:db_allocate_rows: allocate 80 bytes for result rows and values at 0x7ff7a39d4a38 Mar 6 13:41:14 cs17792 /usr/sbin/opensips[6717]: DBG:db_mysql:db_mysql_str2val: converting STRING [659cc07a1ab8ccbbc3b5ec2172bc6473] Mar 6 13:41:14 cs17792 /usr/sbin/opensips[6717]: DBG:auth:check_response: our result = '7937faa022bb7c6b585df82ac2df0b61' Mar 6 13:41:14 cs17792 /usr/sbin/opensips[6717]: DBG:auth:check_response: authorization is OK Mar 6 13:41:14 cs17792 /usr/sbin/opensips[6717]: DBG:core:db_free_columns: freeing result columns at 0x7ff7a39c4898 Mar 6 13:41:14 cs17792 /usr/sbin/opensips[6717]: DBG:core:db_free_rows: freeing 1 rows Mar 6 13:41:14 cs17792 /usr/sbin/opensips[6717]: DBG:core:db_free_row: freeing row values at 0x7ff7a39d4a48 Mar 6 13:41:14 cs17792 /usr/sbin/opensips[6717]: DBG:core:db_free_rows: freeing rows at 0x7ff7a39d4a38 Mar 6 13:41:14 cs17792 /usr/sbin/opensips[6717]: DBG:core:db_free_result: freeing result set at 0x7ff7a39c4850 Mar 6 13:41:14 cs17792 /usr/sbin/opensips[6717]: DBG:registrar:lookup: found a complete match Mar 6 13:41:14 cs17792 /usr/sbin/opensips[6717]: DBG:registrar:lookup: setting as ruri <sip:achalkov1@192.168.1.210:58858;transport=TLS;ob> Mar 6 13:41:14 cs17792 /usr/sbin/opensips[6717]: DBG:registrar:lookup: looking for branches Mar 6 13:41:14 cs17792 /usr/sbin/opensips[6717]: DBG:registrar:lookup: found a complete match Mar 6 13:41:14 cs17792 /usr/sbin/opensips[6717]: DBG:registrar:lookup: setting as ruri <sip:achalkov1@192.168.1.210:58858;transport=TLS;ob> Mar 6 13:41:14 cs17792 /usr/sbin/opensips[6717]: DBG:registrar:lookup: looking for branches Mar 6 13:41:14 cs17792 /usr/sbin/opensips[6717]: DBG:core:comp_scriptvar: str 29 : y.y.y.y Mar 6 13:41:14 cs17792 /usr/sbin/opensips[6717]: DBG:tm:t_newtran: transaction on entrance=(nil) Mar 6 13:41:14 cs17792 /usr/sbin/opensips[6717]: DBG:core:parse_headers: flags=ffffffffffffffff Mar 6 13:41:14 cs17792 /usr/sbin/opensips[6717]: DBG:core:parse_headers: flags=78 Mar 6 13:41:14 cs17792 /usr/sbin/opensips[6717]: DBG:tm:t_lookup_request: start searching: hash=43605, isACK=0 Mar 6 13:41:14 cs17792 /usr/sbin/opensips[6717]: DBG:tm:matching_3261: RFC3261 transaction matching failed Mar 6 13:41:14 cs17792 /usr/sbin/opensips[6717]: DBG:tm:t_lookup_request: no transaction found Mar 6 13:41:14 cs17792 /usr/sbin/opensips[6717]: DBG:tm:run_reqin_callbacks: trans=0x7ff79cd25630, callback type 1, id 1 entered Mar 6 13:41:14 cs17792 /usr/sbin/opensips[6717]: DBG:tm:run_reqin_callbacks: trans=0x7ff79cd25630, callback type 1, id 0 entered Mar 6 13:41:14 cs17792 /usr/sbin/opensips[6717]: DBG:core:_shm_resize: resize(0) called Mar 6 13:41:14 cs17792 /usr/sbin/opensips[6717]: DBG:core:mk_proxy: doing DNS lookup... Mar 6 13:41:14 cs17792 /usr/sbin/opensips[6717]: DBG:core:parse_headers: flags=2000 Mar 6 13:41:14 cs17792 /usr/sbin/opensips[6717]: DBG:core:build_req_buf_from_sip_req: id added: <;i=1>, rcv proto=2 Mar 6 13:41:14 cs17792 /usr/sbin/opensips[6717]: DBG:core:tcp_send: no open tcp connection found, opening new one Mar 6 13:41:14 cs17792 /usr/sbin/opensips[6717]: DBG:core:probe_max_sock_buff: getsockopt: snd is initially 16384 Mar 6 13:41:14 cs17792 /usr/sbin/opensips[6717]: DBG:core:probe_max_sock_buff: trying : 32768 Mar 6 13:41:14 cs17792 /usr/sbin/opensips[6717]: DBG:core:probe_max_sock_buff: setting snd: set=32768,verify=65536 Mar 6 13:41:14 cs17792 /usr/sbin/opensips[6717]: DBG:core:probe_max_sock_buff: trying : 65536 Mar 6 13:41:14 cs17792 /usr/sbin/opensips[6717]: DBG:core:probe_max_sock_buff: setting snd: set=65536,verify=131072 Mar 6 13:41:14 cs17792 /usr/sbin/opensips[6717]: DBG:core:probe_max_sock_buff: trying : 131072 Mar 6 13:41:14 cs17792 /usr/sbin/opensips[6717]: DBG:core:probe_max_sock_buff: setting snd: set=131072,verify=262142 Mar 6 13:41:14 cs17792 /usr/sbin/opensips[6717]: DBG:core:probe_max_sock_buff: trying : 262144 Mar 6 13:41:14 cs17792 /usr/sbin/opensips[6717]: DBG:core:probe_max_sock_buff: setting snd: set=262144,verify=262142 Mar 6 13:41:14 cs17792 /usr/sbin/opensips[6717]: DBG:core:probe_max_sock_buff: setting buf has no effect Mar 6 13:41:14 cs17792 /usr/sbin/opensips[6717]: DBG:core:probe_max_sock_buff: trying : 133120 Mar 6 13:41:14 cs17792 /usr/sbin/opensips[6717]: DBG:core:probe_max_sock_buff: setting snd: set=133120,verify=262142 Mar 6 13:41:14 cs17792 /usr/sbin/opensips[6717]: DBG:core:probe_max_sock_buff: trying : 135168 Mar 6 13:41:14 cs17792 /usr/sbin/opensips[6717]: DBG:core:probe_max_sock_buff: setting snd: set=135168,verify=262142 Mar 6 13:41:14 cs17792 /usr/sbin/opensips[6717]: DBG:core:probe_max_sock_buff: trying : 137216 Mar 6 13:41:14 cs17792 /usr/sbin/opensips[6717]: DBG:core:probe_max_sock_buff: setting snd: set=137216,verify=262142 Mar 6 13:41:14 cs17792 /usr/sbin/opensips[6717]: DBG:core:probe_max_sock_buff: trying : 139264 Mar 6 13:41:14 cs17792 /usr/sbin/opensips[6717]: DBG:core:probe_max_sock_buff: setting snd: set=139264,verify=262142 Mar 6 13:41:14 cs17792 /usr/sbin/opensips[6717]: DBG:core:probe_max_sock_buff: trying : 141312 Mar 6 13:41:14 cs17792 /usr/sbin/opensips[6717]: DBG:core:probe_max_sock_buff: setting snd: set=141312,verify=262142 Mar 6 13:41:14 cs17792 /usr/sbin/opensips[6717]: DBG:core:probe_max_sock_buff: trying : 143360 Mar 6 13:41:14 cs17792 /usr/sbin/opensips[6717]: DBG:core:probe_max_sock_buff: setting snd: set=143360,verify=262142 Mar 6 13:41:14 cs17792 /usr/sbin/opensips[6717]: DBG:core:probe_max_sock_buff: trying : 145408 Mar 6 13:41:14 cs17792 /usr/sbin/opensips[6717]: DBG:core:probe_max_sock_buff: setting snd: set=145408,verify=262142 Mar 6 13:41:14 cs17792 /usr/sbin/opensips[6717]: DBG:core:probe_max_sock_buff: trying : 147456 Mar 6 13:41:14 cs17792 /usr/sbin/opensips[6717]: DBG:core:probe_max_sock_buff: setting snd: set=147456,verify=262142 Mar 6 13:41:14 cs17792 /usr/sbin/opensips[6717]: DBG:core:probe_max_sock_buff: trying : 149504 Mar 6 13:41:14 cs17792 /usr/sbin/opensips[6717]: DBG:core:probe_max_sock_buff: setting snd: set=149504,verify=262142 Mar 6 13:41:14 cs17792 /usr/sbin/opensips[6717]: DBG:core:probe_max_sock_buff: trying : 151552 Mar 6 13:41:14 cs17792 /usr/sbin/opensips[6717]: DBG:core:probe_max_sock_buff: setting snd: set=151552,verify=262142 Mar 6 13:41:14 cs17792 /usr/sbin/opensips[6717]: DBG:core:probe_max_sock_buff: trying : 153600 Mar 6 13:41:14 cs17792 /usr/sbin/opensips[6734]: DBG:core:handle_ser_child: read response= 7ff79cd21908, 1, fd -1 from 17 (6717) Mar 6 13:41:16 cs17792 /usr/sbin/opensips[6734]: DBG:core:handle_tcpconn_ev: data available on 0x7ff79cd21908 52 Mar 6 13:41:16 cs17792 /usr/sbin/opensips[6734]: DBG:core:io_watch_del: io_watch_del op on index -1 52 (0x77dd80, 52, -1, 0x0,0x1) fd_no=39 called Mar 6 13:41:16 cs17792 /usr/sbin/opensips[6734]: DBG:core:send2child: to tcp child 0 0(6717), 0x7ff79cd21908 rw 1 Mar 6 13:41:16 cs17792 /usr/sbin/opensips[6734]: DBG:core:handle_tcp_child: reader response= 7ff79cd21908, 0 from 0 Mar 6 13:41:16 cs17792 /usr/sbin/opensips[6734]: DBG:core:io_watch_add: io_watch_add op on 52 (0x77dd80, 52, 2, 0x7ff79cd21908,1), fd_no=38 Mar 6 13:41:16 cs17792 /usr/sbin/opensips[6734]: DBG:core:handle_ser_child: read response= 7ff79cd21908, 1, fd -1 from 17 (6717) Mar 6 13:41:16 cs17792 /usr/sbin/opensips[6734]: DBG:core:handle_tcpconn_ev: data available on 0x7ff79cd21908 52 Mar 6 13:41:16 cs17792 /usr/sbin/opensips[6734]: DBG:core:io_watch_del: io_watch_del op on index -1 52 (0x77dd80, 52, -1, 0x0,0x1) fd_no=39 called Mar 6 13:41:16 cs17792 /usr/sbin/opensips[6734]: DBG:core:send2child: to tcp child 0 0(6717), 0x7ff79cd21908 rw 1 Mar 6 13:41:16 cs17792 /usr/sbin/opensips[6734]: DBG:core:handle_tcp_child: reader response= 7ff79cd21908, 0 from 0 Mar 6 13:41:16 cs17792 /usr/sbin/opensips[6734]: DBG:core:io_watch_add: io_watch_add op on 52 (0x77dd80, 52, 2, 0x7ff79cd21908,1), fd_no=38 Mar 6 13:41:16 cs17792 /usr/sbin/opensips[6734]: DBG:core:handle_ser_child: read response= 7ff79cd21908, 1, fd -1 from 17 (6717) Mar 6 13:41:16 cs17792 /usr/sbin/opensips[6705]: DBG:msilo:m_clean_silo: cleaning stored messages - 30 Mar 6 13:41:17 cs17792 /usr/sbin/opensips[6699]: DBG:core:udp_rcv_loop: probing packet received len = 2 Mar 6 13:41:20 cs17792 /usr/sbin/opensips[6715]: DBG:avpops:ops_dbquery_avps: query [SELECT username FROM silo GROUP BY username HAVING count(*) > 0] Mar 6 13:41:20 cs17792 /usr/sbin/opensips[6715]: DBG:db_mysql:mysql_raise_event: MySQL status has not changed: connected Mar 6 13:41:20 cs17792 /usr/sbin/opensips[6715]: DBG:core:db_new_result: allocate 48 bytes for result set at 0x7ff7a39ac9c8 Mar 6 13:41:20 cs17792 /usr/sbin/opensips[6715]: DBG:db_mysql:db_mysql_get_columns: 1 columns returned from the query Mar 6 13:41:20 cs17792 /usr/sbin/opensips[6715]: DBG:core:db_allocate_columns: allocate 28 bytes for result columns at 0x7ff7a39aca10 Mar 6 13:41:20 cs17792 /usr/sbin/opensips[6715]: DBG:db_mysql:db_mysql_get_columns: RES_NAMES(0x7ff7a39aca18)[0]=[username] Mar 6 13:41:20 cs17792 /usr/sbin/opensips[6715]: DBG:db_mysql:db_mysql_get_columns: use DB_STRING result type Mar 6 13:41:20 cs17792 /usr/sbin/opensips[6715]: DBG:db_mysql:db_mysql_convert_rows: no rows returned from the query Mar 6 13:41:20 cs17792 /usr/sbin/opensips[6715]: DBG:avpops:db_query_avp: no result after query Mar 6 13:41:20 cs17792 /usr/sbin/opensips[6715]: DBG:avpops:db_close_query: close avp query Mar 6 13:41:20 cs17792 /usr/sbin/opensips[6715]: DBG:core:db_free_columns: freeing result columns at 0x7ff7a39aca10 Mar 6 13:41:20 cs17792 /usr/sbin/opensips[6715]: DBG:core:db_free_rows: freeing 0 rows Mar 6 13:41:20 cs17792 /usr/sbin/opensips[6715]: DBG:core:db_free_result: freeing result set at 0x7ff7a39ac9c8 Mar 6 13:41:20 cs17792 /usr/sbin/opensips[6715]: DBG:core:destroy_avp_list: destroying list (nil) Mar 6 13:41:20 cs17792 /usr/sbin/opensips[6713]: DBG:tm:timer_routine: timer routine:2,tl=0x7ff79cd256b0 next=(nil), timeout=33 Mar 6 13:41:20 cs17792 /usr/sbin/opensips[6713]: DBG:tm:wait_handler: removing 0x7ff79cd25630 from table Mar 6 13:41:20 cs17792 /usr/sbin/opensips[6713]: DBG:tm:delete_cell: delete transaction 0x7ff79cd25630 Mar 6 13:41:20 cs17792 /usr/sbin/opensips[6713]: DBG:tm:wait_handler: done Mar 6 13:41:25 cs17792 /usr/sbin/opensips[6697]: DBG:core:udp_rcv_loop: probing packet received len = 2 Mar 6 13:41:26 cs17792 /usr/sbin/opensips[6734]: DBG:core:handle_tcpconn_ev: data available on 0x7ff79cd21908 52 Mar 6 13:41:26 cs17792 /usr/sbin/opensips[6734]: DBG:core:io_watch_del: io_watch_del op on index -1 52 (0x77dd80, 52, -1, 0x0,0x1) fd_no=39 called Mar 6 13:41:26 cs17792 /usr/sbin/opensips[6734]: DBG:core:send2child: to tcp child 0 0(6717), 0x7ff79cd21908 rw 1 Mar 6 13:41:26 cs17792 /usr/sbin/opensips[6717]: DBG:core:handle_io: We have received conn 0x7ff79cd21908 with rw 1 Mar 6 13:41:26 cs17792 /usr/sbin/opensips[6717]: DBG:core:io_watch_add: io_watch_add op on 36 (0x77dee0, 36, 2, 0x7ff79cd21908,1), fd_no=1 Mar 6 13:41:26 cs17792 /usr/sbin/opensips[6717]: DBG:core:tcp_read_req: Using the global ( per process ) buff Mar 6 13:41:26 cs17792 /usr/sbin/opensips[6717]: DBG:core:tcp_read_req: read= 764 bytes, parsed=764, state=4, error=1 Mar 6 13:41:26 cs17792 /usr/sbin/opensips[6717]: DBG:core:tcp_read_req: last char=0x0A, parsed msg=#012SUBSCRIBE sip:achalkov@x.x.x.x:3631;transport=TCP SIP/2.0#015#012Via: SIP/2.0/TCP y.y.y.y:59137;branch=z9hG4bK-d8754z-810228177c128e2d-1---d8754z-;rport#015#012Max-Forwards: 70#015#012Contact: <sip:achalkov@y.y.y.y:43863;transport=TCP>#015#012To: "achalkov"<sip:achalkov@x.x.x.x:3631;transport=TCP>#015#012From: "achalkov"<sip:achalkov@x.x.x.x:3631;transport=TCP>;tag=7b947279#015#012Call-ID: ZDJkMGIzM2E0MWMwMjc5M2U3NTY0OGFmMjhmMWJjNTE.#015#012CSeq: 1 SUBSCRIBE#015#012Expires: 600#015#012Accept: application/watcherinfo+xml#015#012Allow: INVITE, ACK, CANCEL, BYE, NOTIFY, REFER, MESSAGE, OPTIONS, INFO, SUBSCRIBE#015#012Supported: replaces, norefersub, extended-refer, timer, X-cisco-serviceuri#015#012User-Agent: Zoiper r21367#015#012Event: presence.winfo#015#012Allow-Events: presence, kpml#015#012Content-Length: 0#015#012#015#012 Mar 6 13:41:26 cs17792 /usr/sbin/opensips[6717]: DBG:core:tcp_read_req: content-length= 0 Mar 6 13:41:26 cs17792 /usr/sbin/opensips[6717]: DBG:core:tcp_read_req: We're releasing the connection in state 3 Mar 6 13:41:26 cs17792 /usr/sbin/opensips[6717]: DBG:core:io_watch_del: io_watch_del op on index -1 36 (0x77dee0, 36, -1, 0x10,0x1) fd_no=2 called Mar 6 13:41:26 cs17792 /usr/sbin/opensips[6717]: DBG:core:release_tcpconn: releasing con 0x7ff79cd21908, state 0, fd=36, id=1 Mar 6 13:41:26 cs17792 /usr/sbin/opensips[6717]: DBG:core:release_tcpconn: extra_data (nil) Mar 6 13:41:26 cs17792 /usr/sbin/opensips[6717]: DBG:core:parse_msg: SIP Request: Mar 6 13:41:26 cs17792 /usr/sbin/opensips[6734]: DBG:core:handle_tcp_child: reader response= 7ff79cd21908, 0 from 0 Mar 6 13:41:26 cs17792 /usr/sbin/opensips[6734]: DBG:core:io_watch_add: io_watch_add op on 52 (0x77dd80, 52, 2, 0x7ff79cd21908,1), fd_no=38 Mar 6 13:41:26 cs17792 /usr/sbin/opensips[6717]: DBG:core:parse_msg: method: <SUBSCRIBE> Mar 6 13:41:26 cs17792 /usr/sbin/opensips[6717]: DBG:core:parse_msg: uri: <sip:achalkov@x.x.x.x:3631;transport=TCP> Mar 6 13:41:26 cs17792 /usr/sbin/opensips[6717]: DBG:core:parse_msg: version: <SIP/2.0> Mar 6 13:41:26 cs17792 /usr/sbin/opensips[6717]: DBG:core:parse_headers: flags=2 Mar 6 13:41:26 cs17792 /usr/sbin/opensips[6717]: DBG:core:parse_via_param: found param type 232, <branch> = <z9hG4bK-d8754z-810228177c128e2d-1---d8754z->; state=6 Mar 6 13:41:26 cs17792 /usr/sbin/opensips[6717]: DBG:core:parse_via_param: found param type 235, <rport> = <n/a>; state=17 Mar 6 13:41:26 cs17792 /usr/sbin/opensips[6717]: DBG:core:parse_via: end of header reached, state=5 Mar 6 13:41:26 cs17792 /usr/sbin/opensips[6717]: DBG:core:parse_headers: via found, flags=2 Mar 6 13:41:26 cs17792 /usr/sbin/opensips[6717]: DBG:core:parse_headers: this is the first via Mar 6 13:41:26 cs17792 /usr/sbin/opensips[6717]: DBG:core:receive_msg: After parse_msg... Mar 6 13:41:26 cs17792 /usr/sbin/opensips[6717]: DBG:core:receive_msg: preparing to run routing scripts... Mar 6 13:41:26 cs17792 /usr/sbin/opensips[6717]: DBG:core:pv_get_dsturi: no destination URI Mar 6 13:41:26 cs17792 /usr/sbin/opensips[6717]: DBG:core:parse_headers: flags=10 Mar 6 13:41:26 cs17792 /usr/sbin/opensips[6717]: DBG:core:parse_to: end of header reached, state=10 Mar 6 13:41:26 cs17792 /usr/sbin/opensips[6717]: DBG:core:parse_to: display={"achalkov"}, ruri={sip:achalkov@x.x.x.x:3631;transport=TCP} Mar 6 13:41:26 cs17792 /usr/sbin/opensips[6717]: DBG:core:get_hdr_field: <To> [60]; uri=[sip:achalkov@x.x.x.x:3631;transport=TCP] Mar 6 13:41:26 cs17792 /usr/sbin/opensips[6717]: DBG:core:get_hdr_field: to body ["achalkov"<sip:achalkov@x.x.x.x:3631;transport=TCP>#015#012] Mar 6 13:41:26 cs17792 /usr/sbin/opensips[6717]: DBG:core:parse_to_param: tag=7b947279 Mar 6 13:41:26 cs17792 /usr/sbin/opensips[6717]: DBG:core:parse_to: end of header reached, state=29 Mar 6 13:41:26 cs17792 /usr/sbin/opensips[6717]: DBG:core:parse_to: display={"achalkov"}, ruri={sip:achalkov@x.x.x.x:3631;transport=TCP} Mar 6 13:41:26 cs17792 /usr/sbin/opensips[6717]: DBG:core:pv_get_dsturi_attr: no destination URI Mar 6 13:41:26 cs17792 /usr/sbin/opensips[6717]: DBG:core:parse_headers: flags=40 Mar 6 13:41:26 cs17792 /usr/sbin/opensips[6717]: DBG:core:parse_headers: flags=20 Mar 6 13:41:26 cs17792 /usr/sbin/opensips[6717]: DBG:core:get_hdr_field: cseq <CSeq>: <1> <SUBSCRIBE> Mar 6 13:41:26 cs17792 /usr/sbin/opensips[6717]: DBG:core:parse_headers: flags=8000000 Mar 6 13:41:26 cs17792 /usr/sbin/opensips[6717]: [MAIN] Incoming request (M=SUBSCRIBE IP=tcp:y.y.y.y:59141 fromIP=tcp:y.y.y.y:59141 RURI=sip:achalkov@x.x.x.x:3631;transport=TCP DURI=<null> F=sip:achalkov@x.x.x.x:3631;transport=TCP T=sip:achalkov@x.x.x.x:3631;transport=TCP oP=TCP dP=<null> rP=TCP ID=ZDJkMGIzM2E0MWMwMjc5M2U3NTY0OGFmMjhmMWJjNTE. ct=<sip:achalkov@y.y.y.y:43863;transport=TCP> cseq=1 UA=Zoiper r21367)#012SUBSCRIBE sip:achalkov@x.x.x.x:3631;transport=TCP SIP/2.0#015#012Via: SIP/2.0/TCP y.y.y.y:59137;branch=z9hG4bK-d8754z-810228177c128e2d-1---d8754z-;rport#015#012Max-Forwards: 70#015#012Contact: <sip:achalkov@y.y.y.y:43863;transport=TCP>#015#012To: "achalkov"<sip:achalkov@x.x.x.x:3631;transport=TCP>#015#012From: "achalkov"<sip:achalkov@x.x.x.x:3631;transport=TCP>;tag=7b947279#015#012Call-ID: ZDJkMGIzM2E0MWMwMjc5M2U3NTY0OGFmMjhmMWJjNTE.#015#012CSeq: 1 SUBSCRIBE#015#012Expires: 600#015#012Accept: application/watcherinfo+xml#015#012Allow: INVITE, ACK, CANCEL, BYE, NOTIFY, REFER, MESSAGE, OPTIONS, INFO, SUBSCRIBE#015#012Supported: replaces, norefersub, extended-refer, timer, X-cisco-serviceuri#015#012User-Agent: Zoiper r21367#015#012Event: presence.winfo#015#012Allow-Events: presence, kpml#015#012Content-Length: 0#015#012#015 Mar 6 13:41:26 cs17792 /usr/sbin/opensips[6717]: DBG:maxfwd:is_maxfwd_present: value = 70 Mar 6 13:41:26 cs17792 /usr/sbin/opensips[6717]: DBG:core:parse_headers: flags=ffffffffffffffff Mar 6 13:41:26 cs17792 /usr/sbin/opensips[6717]: DBG:core:get_hdr_field: content_length=0 Mar 6 13:41:26 cs17792 /usr/sbin/opensips[6717]: DBG:core:get_hdr_field: found end of header Mar 6 13:41:26 cs17792 /usr/sbin/opensips[6717]: DBG:core:parse_headers: flags=ffffffffffffffff Mar 6 13:41:26 cs17792 /usr/sbin/opensips[6717]: DBG:core:decode_mime_type: Decoding MIME type for:[application/watcherinfo+xml] Mar 6 13:41:26 cs17792 /usr/sbin/opensips[6717]: DBG:core:parse_headers: flags=ffffffffffffffff Mar 6 13:41:26 cs17792 /usr/sbin/opensips[6717]: DBG:core:parse_methods: methods 0x173F Mar 6 13:41:26 cs17792 /usr/sbin/opensips[6717]: DBG:core:parse_headers: flags=ffffffffffffffff Mar 6 13:41:26 cs17792 /usr/sbin/opensips[6717]: DBG:core:parse_supported: parsing [Supported: replaces, norefersub, extended-refer, timer, X-cisco-serviceuri#015#012] 0x7ff7a39be888 Mar 6 13:41:26 cs17792 /usr/sbin/opensips[6717]: DBG:sipmsgops:sip_validate_hdrs: duplicate header 'Content-Length' Mar 6 13:41:26 cs17792 /usr/sbin/opensips[6717]: DBG:uri:has_totag: no totag Mar 6 13:41:26 cs17792 /usr/sbin/opensips[6717]: DBG:core:parse_headers: flags=78 Mar 6 13:41:26 cs17792 /usr/sbin/opensips[6717]: DBG:tm:t_lookup_request: start searching: hash=54316, isACK=0 Mar 6 13:41:26 cs17792 /usr/sbin/opensips[6717]: DBG:tm:matching_3261: RFC3261 transaction matching failed Mar 6 13:41:26 cs17792 /usr/sbin/opensips[6717]: DBG:tm:t_lookup_request: no transaction found Mar 6 13:41:26 cs17792 /usr/sbin/opensips[6717]: DBG:core:parse_headers: flags=200 Mar 6 13:41:26 cs17792 /usr/sbin/opensips[6717]: DBG:rr:find_first_route: No Route headers found Mar 6 13:41:26 cs17792 /usr/sbin/opensips[6717]: DBG:rr:loose_route: There is no Route HF Mar 6 13:41:26 cs17792 /usr/sbin/opensips[6717]: DBG:core:pv_get_dsturi: no destination URI Mar 6 13:41:26 cs17792 /usr/sbin/opensips[6717]: DBG:core:pv_get_dsturi_attr: no destination URI Mar 6 13:41:26 cs17792 /usr/sbin/opensips[6717]: [MAIN] Not allowed method - Sending 405 Method Not Allowed (M=SUBSCRIBE IP=tcp:y.y.y.y:59141 fromIP=tcp:y.y.y.y:59141 RURI=sip:achalkov@x.x.x.x:3631;transport=TCP DURI=<null> F=sip:achalkov@x.x.x.x:3631;transport=TCP T=sip:achalkov@x.x.x.x:3631;transport=TCP oP=TCP dP=<null> rP=TCP ID=ZDJkMGIzM2E0MWMwMjc5M2U3NTY0OGFmMjhmMWJjNTE. ct=<sip:achalkov@y.y.y.y:43863;transport=TCP> cseq=1 UA=Zoiper r21367) Mar 6 13:41:26 cs17792 /usr/sbin/opensips[6717]: DBG:core:parse_headers: flags=ffffffffffffffff Mar 6 13:41:26 cs17792 /usr/sbin/opensips[6717]: DBG:core:tcp_send: tcp connection found (0x7ff79cd21908), acquiring fd Mar 6 13:41:26 cs17792 /usr/sbin/opensips[6717]: DBG:core:tcp_send: c= 0x7ff79cd21908, n=16 Mar 6 13:41:26 cs17792 /usr/sbin/opensips[6734]: DBG:core:handle_ser_child: read response= 7ff79cd21908, 1, fd -1 from 17 (6717) Mar 6 13:41:26 cs17792 /usr/sbin/opensips[6717]: DBG:core:tcp_send: after receive_fd: c= 0x7ff79cd21908 n=8 fd=36 Mar 6 13:41:26 cs17792 /usr/sbin/opensips[6717]: DBG:core:tcp_send: sending... Mar 6 13:41:26 cs17792 /usr/sbin/opensips[6717]: DBG:core:async_tsend_stream: Async succesful write from first try on 0x7ff79cd21908 Mar 6 13:41:26 cs17792 /usr/sbin/opensips[6717]: DBG:core:tcp_send: after write: c= 0x7ff79cd21908 n=454 fd=36 Mar 6 13:41:26 cs17792 /usr/sbin/opensips[6717]: DBG:core:tcp_send: buf=#012SIP/2.0 405 Method Not Allowed#015#012Via: SIP/2.0/TCP y.y.y.y:59137;received=y.y.y.y;branch=z9hG4bK-d8754z-810228177c128e2d-1---d8754z-;rport=59141#015#012To: "achalkov"<sip:achalkov@x.x.x.x:3631;transport=TCP>;tag=d8c8651e9db6867219201727ad85910e.c770#015#012From: "achalkov"<sip:achalkov@x.x.x.x:3631;transport=TCP>;tag=7b947279#015#012Call-ID: ZDJkMGIzM2E0MWMwMjc5M2U3NTY0OGFmMjhmMWJjNTE.#015#012CSeq: 1 SUBSCRIBE#015#012Server: Softswitch#015#012Content-Length: 0#015#012#015#012 Mar 6 13:41:26 cs17792 /usr/sbin/opensips[6717]: DBG:core:destroy_avp_list: destroying list (nil) Mar 6 13:41:26 cs17792 /usr/sbin/opensips[6717]: DBG:core:receive_msg: cleaning up Mar 6 13:41:26 cs17792 /usr/sbin/opensips[6717]: DBG:core:tcp_read_req: tcp_read_req end Mar 6 13:41:27 cs17792 /usr/sbin/opensips[6705]: DBG:msilo:m_clean_silo: cleaning stored messages - 40 Mar 6 13:41:31 cs17792 /usr/sbin/opensips[6715]: DBG:avpops:ops_dbquery_avps: query [SELECT username FROM silo GROUP BY username HAVING count(*) > 0] Mar 6 13:41:31 cs17792 /usr/sbin/opensips[6715]: DBG:db_mysql:mysql_raise_event: MySQL status has not changed: connected Mar 6 13:41:31 cs17792 /usr/sbin/opensips[6715]: DBG:core:db_new_result: allocate 48 bytes for result set at 0x7ff7a39ac9c8 Mar 6 13:41:31 cs17792 /usr/sbin/opensips[6715]: DBG:db_mysql:db_mysql_get_columns: 1 columns returned from the query Mar 6 13:41:31 cs17792 /usr/sbin/opensips[6715]: DBG:core:db_allocate_columns: allocate 28 bytes for result columns at 0x7ff7a39aca10 Mar 6 13:41:31 cs17792 /usr/sbin/opensips[6715]: DBG:db_mysql:db_mysql_get_columns: RES_NAMES(0x7ff7a39aca18)[0]=[username] Mar 6 13:41:31 cs17792 /usr/sbin/opensips[6715]: DBG:db_mysql:db_mysql_get_columns: use DB_STRING result type Mar 6 13:41:31 cs17792 /usr/sbin/opensips[6715]: DBG:db_mysql:db_mysql_convert_rows: no rows returned from the query Mar 6 13:41:31 cs17792 /usr/sbin/opensips[6715]: DBG:avpops:db_query_avp: no result after query Mar 6 13:41:31 cs17792 /usr/sbin/opensips[6715]: DBG:avpops:db_close_query: close avp query Mar 6 13:41:31 cs17792 /usr/sbin/opensips[6715]: DBG:core:db_free_columns: freeing result columns at 0x7ff7a39aca10 Mar 6 13:41:31 cs17792 /usr/sbin/opensips[6715]: DBG:core:db_free_rows: freeing 0 rows Mar 6 13:41:31 cs17792 /usr/sbin/opensips[6715]: DBG:core:db_free_result: freeing result set at 0x7ff7a39ac9c8 Mar 6 13:41:31 cs17792 /usr/sbin/opensips[6715]: DBG:core:destroy_avp_list: destroying list (nil) Mar 6 13:41:32 cs17792 /usr/sbin/opensips[6698]: DBG:core:udp_rcv_loop: probing packet received len = 2 Mar 6 13:41:37 cs17792 /usr/sbin/opensips[6705]: DBG:msilo:m_clean_silo: cleaning stored messages - 50 Mar 6 13:41:40 cs17792 /usr/sbin/opensips[6696]: DBG:core:udp_rcv_loop: probing packet received len = 2 Mar 6 13:41:42 cs17792 /usr/sbin/opensips[6715]: DBG:avpops:ops_dbquery_avps: query [SELECT username FROM silo GROUP BY username HAVING count(*) > 0] Mar 6 13:41:42 cs17792 /usr/sbin/opensips[6715]: DBG:db_mysql:mysql_raise_event: MySQL status has not changed: connected Mar 6 13:41:42 cs17792 /usr/sbin/opensips[6715]: DBG:core:db_new_result: allocate 48 bytes for result set at 0x7ff7a39ac9c8 Mar 6 13:41:42 cs17792 /usr/sbin/opensips[6715]: DBG:db_mysql:db_mysql_get_columns: 1 columns returned from the query Mar 6 13:41:42 cs17792 /usr/sbin/opensips[6715]: DBG:core:db_allocate_columns: allocate 28 bytes for result columns at 0x7ff7a39aca10 Mar 6 13:41:42 cs17792 /usr/sbin/opensips[6715]: DBG:db_mysql:db_mysql_get_columns: RES_NAMES(0x7ff7a39aca18)[0]=[username] Mar 6 13:41:42 cs17792 /usr/sbin/opensips[6715]: DBG:db_mysql:db_mysql_get_columns: use DB_STRING result type Mar 6 13:41:42 cs17792 /usr/sbin/opensips[6715]: DBG:db_mysql:db_mysql_convert_rows: no rows returned from the query Mar 6 13:41:42 cs17792 /usr/sbin/opensips[6715]: DBG:avpops:db_query_avp: no result after query Mar 6 13:41:42 cs17792 /usr/sbin/opensips[6715]: DBG:avpops:db_close_query: close avp query Mar 6 13:41:42 cs17792 /usr/sbin/opensips[6715]: DBG:core:db_free_columns: freeing result columns at 0x7ff7a39aca10 Mar 6 13:41:42 cs17792 /usr/sbin/opensips[6715]: DBG:core:db_free_rows: freeing 0 rows Mar 6 13:41:42 cs17792 /usr/sbin/opensips[6715]: DBG:core:db_free_result: freeing result set at 0x7ff7a39ac9c8 Mar 6 13:41:42 cs17792 /usr/sbin/opensips[6715]: DBG:core:destroy_avp_list: destroying list (nil) 06.03.2015, 12:43, "Vlad Paiu" <vladp...@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, "Чалков Артём" <achal...@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@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@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@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@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@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@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@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" <vladp...@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@lists.opensips.org >>>>> http://lists.opensips.org/cgi-bin/mailman/listinfo/users >>>> _______________________________________________ >>>> Users mailing list >>>> Users@lists.opensips.org >>>> http://lists.opensips.org/cgi-bin/mailman/listinfo/users >>> _______________________________________________ >>> Users mailing list >>> Users@lists.opensips.org >>> http://lists.opensips.org/cgi-bin/mailman/listinfo/users >> _______________________________________________ >> Users mailing list >> Users@lists.opensips.org >> http://lists.opensips.org/cgi-bin/mailman/listinfo/users > > _______________________________________________ > Users mailing list > Users@lists.opensips.org > http://lists.opensips.org/cgi-bin/mailman/listinfo/users _______________________________________________ Users mailing list Users@lists.opensips.org http://lists.opensips.org/cgi-bin/mailman/listinfo/users