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:[email protected]: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:[email protected]:3631;transport=TCP>#015#012From:
"achalkov"<sip:[email protected]: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:[email protected]: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:[email protected]:3631;transport=TCP}
Mar 6 13:41:14 cs17792 /usr/sbin/opensips[6717]: DBG:core:get_hdr_field: <To>
[51]; uri=[sip:[email protected]:3631;transport=TCP]
Mar 6 13:41:14 cs17792 /usr/sbin/opensips[6717]: DBG:core:get_hdr_field: to
body [<sip:[email protected]: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:[email protected]: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:[email protected]:3631;transport=TCP DURI=<null>
F=sip:[email protected]:3631;transport=TCP
T=sip:[email protected]:3631;transport=TCP oP=TCP dP=<null> rP=TCP
ID=NmRjMDQ1NGNiY2ExMjQzNzQxMDg0NDY2M2U4YmY3OGI. ct=<null> cseq=2 UA=Zoiper
r21367)#012MESSAGE sip:[email protected]: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:[email protected]:3631;transport=TCP>#015#012From:
"achalkov"<sip:[email protected]: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:[email protected]:3631;transport=TCP DURI=<null>
F=sip:[email protected]:3631;transport=TCP
T=sip:[email protected]: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:[email protected]:3631;transport=TCP>;tag=d8c8651e9db6867219201727ad85910e.0fda#015#012From:
"achalkov"<sip:[email protected]: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:[email protected]: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:[email protected]:3631;transport=TCP>#015#012From:
"achalkov"<sip:[email protected]: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:[email protected]: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:[email protected]: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:[email protected]:3631;transport=TCP}
Mar 6 13:41:14 cs17792 /usr/sbin/opensips[6717]: DBG:core:get_hdr_field: <To>
[51]; uri=[sip:[email protected]:3631;transport=TCP]
Mar 6 13:41:14 cs17792 /usr/sbin/opensips[6717]: DBG:core:get_hdr_field: to
body [<sip:[email protected]: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:[email protected]: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:[email protected]:3631;transport=TCP DURI=<null>
F=sip:[email protected]:3631;transport=TCP
T=sip:[email protected]:3631;transport=TCP oP=TCP dP=<null> rP=TCP
ID=NmRjMDQ1NGNiY2ExMjQzNzQxMDg0NDY2M2U4YmY3OGI. ct=<null> cseq=3 UA=Zoiper
r21367)#012MESSAGE sip:[email protected]: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:[email protected]:3631;transport=TCP>#015#012From:
"achalkov"<sip:[email protected]: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:[email protected]: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:[email protected]: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:[email protected]: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:[email protected]: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:[email protected]:43863;transport=TCP>#015#012To:
"achalkov"<sip:[email protected]:3631;transport=TCP>#015#012From:
"achalkov"<sip:[email protected]: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:[email protected]: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:[email protected]:3631;transport=TCP}
Mar 6 13:41:26 cs17792 /usr/sbin/opensips[6717]: DBG:core:get_hdr_field: <To>
[60]; uri=[sip:[email protected]:3631;transport=TCP]
Mar 6 13:41:26 cs17792 /usr/sbin/opensips[6717]: DBG:core:get_hdr_field: to
body ["achalkov"<sip:[email protected]: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:[email protected]: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:[email protected]:3631;transport=TCP DURI=<null>
F=sip:[email protected]:3631;transport=TCP
T=sip:[email protected]:3631;transport=TCP oP=TCP dP=<null> rP=TCP
ID=ZDJkMGIzM2E0MWMwMjc5M2U3NTY0OGFmMjhmMWJjNTE.
ct=<sip:[email protected]:43863;transport=TCP> cseq=1 UA=Zoiper
r21367)#012SUBSCRIBE sip:[email protected]: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:[email protected]:43863;transport=TCP>#015#012To:
"achalkov"<sip:[email protected]:3631;transport=TCP>#015#012From:
"achalkov"<sip:[email protected]: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:[email protected]:3631;transport=TCP
DURI=<null> F=sip:[email protected]:3631;transport=TCP
T=sip:[email protected]:3631;transport=TCP oP=TCP dP=<null> rP=TCP
ID=ZDJkMGIzM2E0MWMwMjc5M2U3NTY0OGFmMjhmMWJjNTE.
ct=<sip:[email protected]: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:[email protected]:3631;transport=TCP>;tag=d8c8651e9db6867219201727ad85910e.c770#015#012From:
"achalkov"<sip:[email protected]: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" <[email protected]>:
> 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, "Чалков Артём" <[email protected]>:
>>> 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:[email protected]: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:[email protected]:3631;transport=TCP}
>>> Mar 5 16:07:46 cs17792 /usr/sbin/opensips[19012]: DBG:core:get_hdr_field:
>>> <To> [51]; uri=[sip:[email protected]:3631;transport=TCP]
>>> Mar 5 16:07:46 cs17792 /usr/sbin/opensips[19012]: DBG:core:get_hdr_field:
>>> to body [<sip:[email protected]: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:[email protected]: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:[email protected]: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:[email protected]: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" <[email protected]>:
>>>> 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
>>>>> [email protected]
>>>>> http://lists.opensips.org/cgi-bin/mailman/listinfo/users
>>>> _______________________________________________
>>>> Users mailing list
>>>> [email protected]
>>>> http://lists.opensips.org/cgi-bin/mailman/listinfo/users
>>> _______________________________________________
>>> Users mailing list
>>> [email protected]
>>> http://lists.opensips.org/cgi-bin/mailman/listinfo/users
>> _______________________________________________
>> Users mailing list
>> [email protected]
>> http://lists.opensips.org/cgi-bin/mailman/listinfo/users
>
> _______________________________________________
> Users mailing list
> [email protected]
> http://lists.opensips.org/cgi-bin/mailman/listinfo/users
_______________________________________________
Users mailing list
[email protected]
http://lists.opensips.org/cgi-bin/mailman/listinfo/users
