lolzzzz
till now i just tried Registration with TLS, today after this mail i
started testing INVITE and i also came across the same problem
let me explain my case. I have got two grandstream gvx3140 connected to
kamailio via TLS. via UDP i have successfully tested calls between each
other.
Now when i try to call 1000 from 1001, it gives me 404 error message.
Kamailio fails to send Invite message to user 1000. Is it possible that
kamailio is trying to forward INVITE packet to Contact Address rather then
the TCP connected which is already established between kamailio and
grandstream device.
I am attaching the log file.
few things are like:
Mar 23 10:33:43 [2335] DBG:core:tcp_send: after write: c= 0x7f35bdfad988
n=-1 fd=9
Mar 23 10:33:43 [2341] DBG:core:io_watch_del: io_watch_del (0x74efe0, 19,
-1, 0x10) fd_no=2 called
Mar 23 10:33:43 [2335] DBG:core:tcp_send: buf=
INVITE sip:1...@172.16.17.81:15099;transport=tls;user=phone SIP/2.0
Record-Route: <sip:172.16.16.218:5091;transport=tls;r2=on;lr=on>
Record-Route: <sip:172.16.16.218:5090;r2=on;lr=on>
Via: SIP/2.0/TLS 172.16.16.218:5091;branch=z9hG4bK00843d58
Via: SIP/2.0/UDP
172.16.16.218:5070;received=172.16.16.218;branch=z9hG4bK00843d58;rport=5070
From: "1001" <sip:1...@172.16.16.218:5070>;tag=as60af855f
To: <sip:1...@172.16.16.218:5090>
Contact: <sip:1...@172.16.16.218:5070>
Call-ID: 15b634d06c6e5d2d63b71fe123c3c...@172.16.16.218
CSeq: 102 INVITE
User-Agent: PANTHER-SC
Max-Forwards: 69
Date: Tue, 23 Mar 2010 05:03:43 GMT
Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY
Supported: replaces
Content-Type: application/sdp
Content-Length: 580
v=0
o=root 2126 2126 IN IP4 172.16.16.218
s=session
c=IN IP4 172.16.16.218
t=0 0
m=audio 11262 RTP/SAVP 0 18 8 101
a=rtpmap:0 PCMU/8000
a=rtpmap:18 G729/8000
a=fmtp:18 annexb=no
a=rtpmap:8 PCMA/8000
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-16
a=silenceSupp:off - - - -
a=ptime:20
a=crypto:1 AES_CM_128_HMAC_SHA1_80
inline:2FXsAoBFaNzqIwXcyo8EwI81slJDnNpoA6+PkJFY
a=sendrecv
m=video 17638 RTP/SAVP 99
a=rtpmap:99 H264/90000
a=fmtp:99 profile-level-id=42800d
a=crypto:1 AES_CM_128_HMAC_SHA1_80
inline:WNjW7f5hxaItleUZMNPv/Ni1ZNQ7A9i4AUhHBBxI
a=sendrecv
Mar 23 10:33:43 [2341] DBG:core:release_tcpconn: releasing con
0x7f35bdfad988, state -2, fd=19, id=41
Mar 23 10:33:43 [2335] ERROR:core:tcp_send: failed to send
Mar 23 10:33:43 [2341] DBG:core:release_tcpconn: extra_data 0x7f35bdf5d490
Mar 23 10:33:43 [2335] ERROR:core:msg_send: tcp_send failed
Mar 23 10:33:43 [2344] DBG:core:handle_ser_child: read response=
7f35bdfad988, -2, fd -1 from 2 (2335)
Mar 23 10:33:43 [2344] DBG:core:tcpconn_destroy: delaying (0x7f35bdfad988,
flags 0002) ...
Mar 23 10:33:43 [2335] DBG:sl:sl_reply_error: error text is Send failed
(477/SL)
Mar 23 10:33:43 [2344] DBG:core:handle_tcp_child: reader response=
7f35bdfad988, -2 from 1
Mar 23 10:33:43 [2344] DBG:core:tcpconn_destroy: destroying connection
0x7f35bdfad988, flags 0002
Mar 23 10:33:43 [2344] DBG:core:tls_close: closing SSL connection
Mar 23 10:33:43 [2335] DBG:core:parse_headers: flags=ffffffffffffffff
Mar 23 10:33:43 [2335] DBG:core:get_hdr_field: found end of header
Mar 23 10:33:43 [2344] DBG:core:tls_update_fd: New fd is 24
Mar 23 10:33:43 [2344] DBG:core:tls_shutdown: shutdown successful
Mar 23 10:33:43 [2335] DBG:core:check_via_address: params 172.
check where it says tcp_send failed.
i have configure tls section in my kamailio like below:
disable_tls = no
listen = tls:172.16.16.218:5091
tls_verify_server = 1
tls_verify_client = 0
tls_require_client_certificate = 0
tls_method = TLSv1
tls_certificate =
"/data/hemanshu/install/kama/etc/kamailio/tls/user/user-cert.pem"
tls_private_key =
"/data/hemanshu/install/kama/etc/kamailio/tls/user/user-privkey.pem"
tls_ca_list =
"/data/hemanshu/install/kama/etc/kamailio/tls/user/user-calist.pem"
Please let me know if i am making any mistake in configuration or anything
else?
--
Regards,
Hemanshu Patel
M: 09601295238
> Hi,
>
> I am using
>
> kamailio 3.0.1 (x86_64/linux) 0822a9
> flags: STATS: Off, USE_IPV6, USE_TCP, USE_TLS, TLS_HOOKS, DISABLE_NAGLE,
> USE_MCAST, DNS_IP_HACK, SHM_MEM, SHM_MMAP, PKG_MALLOC, F_MALLOC,
> USE_FUTEX, FAST_LOCK-ADAPTIVE_WAIT, USE_DNS_CACHE, USE_DNS_FAILOVER,
> USE_NAPTR, USE_DST_BLACKLIST, HAVE_RESOLV_RES
> ADAPTIVE_WAIT_LOOPS=1024, MAX_RECV_BUFFER_SIZE 262144, MAX_LISTEN 16,
> MAX_URI_SIZE 1024, BUF_SIZE 65535
> poll method support: poll, epoll_lt, epoll_et, sigio_rt, select.
>
> and I am using the client "PhonerLite" (http://www.phonerlite.de).
>
> The phone is registered on my server with TLS.
>
> If I call someone or myself I get an error message. What is wrong with my
> server? (TLS calls with PhonerLite with the provider antisip.com are
> possible without problems!)
>
> With UDP calling myself I get "486:Busy Here" on the phone, this is OK and
> normal.
> With TLS I get "477:Unfortunately error on sending to next hop
> occurred(477/SL)" on the phone and some ERROR messages like the following
> on the kamailio.log (you can see the rest of the log in the attached zip):
>
> Mar 21 20:24:00 vs208140 /usr/local/sbin/kamailio[20013]: DEBUG: <core>
> [msg_translator.c:200]: check_via_address(95.90.205.74, 95.90.205.74, 0)
> Mar 21 20:24:00 vs208140 /usr/local/sbin/kamailio[20013]: DEBUG: <core>
> [tcp_main.c:1786]: tcp_send: no open tcp connection found, opening new one
> Mar 21 20:24:10 vs208140 /usr/local/sbin/kamailio[20013]: ERROR: <core>
> [tcp_main.c:618]: connect 95.90.205.74:5061 failed (timeout)
> Mar 21 20:24:10 vs208140 /usr/local/sbin/kamailio[20013]: ERROR: <core>
> [tcp_main.c:621]: ERROR: tcp_blocking_connect 95.90.205.74:5061: timeout
> 10 s elapsed from 10 s
> Mar 21 20:24:10 vs208140 /usr/local/sbin/kamailio[20013]: ERROR: <core>
> [tcp_main.c:1168]: ERROR: tcp_do_connect: tcp_blocking_connect
> 95.90.205.74:5061 failed
> Mar 21 20:24:10 vs208140 /usr/local/sbin/kamailio[20013]: ERROR: <core>
> [tcp_main.c:1237]: ERROR: tcp_do_connect 95.90.205.74:5061: failed (115)
> Operation now in progress
> Mar 21 20:24:10 vs208140 /usr/local/sbin/kamailio[20013]: ERROR: <core>
> [tcp_main.c:1955]: ERROR: tcp_send 95.90.205.74:5061: connect failed
> Mar 21 20:24:10 vs208140 /usr/local/sbin/kamailio[20013]: ERROR: tm
> [../../forward.h:191]: msg_send: ERROR: tcp_send failed
>
> The kamailio.cfg file is also in the zip attached.
> The PC is connected with the router (I opened the TCP ports 5060-5062)
> that is connected to the Internet. The problem also happens if I disable
> the firewall of the server and of the PC.
>
> Can someone give me help?
>
> Thanks in advance!
>
> Regards
>
> Detlef Pilzecker_______________________________________________
> Kamailio (OpenSER) - Users mailing list
> Users@lists.kamailio.org
> http://lists.kamailio.org/cgi-bin/mailman/listinfo/users
> http://lists.openser-project.org/cgi-bin/mailman/listinfo/users
Mar 23 10:33:43 [2344] DBG:core:handle_tcpconn_ev: data available on
0x7f35bdf9d7f0 23
Mar 23 10:33:43 [2344] DBG:core:io_watch_del: io_watch_del (0x74ee80, 23, -1,
0x0) fd_no=17 called
Mar 23 10:33:43 [2344] DBG:core:send2child: to tcp child 0 0(2340),
0x7f35bdf9d7f0
Mar 23 10:33:43 [2340] DBG:core:handle_io: received n=8 con=0x7f35bdf9d7f0,
fd=17
Mar 23 10:33:43 [2340] DBG:core:io_watch_add: io_watch_add(0x74efe0, 17, 2,
0x7f35bdf9d7f0), fd_no=1
Mar 23 10:33:43 [2340] DBG:core:tls_update_fd: New fd is 17
Mar 23 10:33:43 [2340] DBG:core:_tls_read: 1557 bytes read
Mar 23 10:33:43 [2340] DBG:core:tcp_read_req: content-length= 815
Mar 23 10:33:43 [2340] DBG:core:parse_msg: SIP Request:
Mar 23 10:33:43 [2340] DBG:core:parse_msg: method: <INVITE>
Mar 23 10:33:43 [2340] DBG:core:parse_msg: uri:
<sip:1...@172.16.16.218:5091;user=phone>
Mar 23 10:33:43 [2340] DBG:core:parse_msg: version: <SIP/2.0>
Mar 23 10:33:43 [2340] DBG:core:parse_headers: flags=2
Mar 23 10:33:43 [2340] DBG:core:parse_via_param: found param type 232, <branch>
= <z9hG4bK1337273695>; state=6
Mar 23 10:33:43 [2340] DBG:core:parse_via_param: found param type 235, <rport>
= <n/a>; state=6
Mar 23 10:33:43 [2340] DBG:core:parse_via_param: found param type 237, <alias>
= <n/a>; state=16
Mar 23 10:33:43 [2340] DBG:core:parse_via: end of header reached, state=5
Mar 23 10:33:43 [2340] DBG:core:parse_headers: via found, flags=2
Mar 23 10:33:43 [2340] DBG:core:parse_headers: this is the first via
Mar 23 10:33:43 [2340] DBG:core:receive_msg: After parse_msg...
Mar 23 10:33:43 [2340] DBG:core:receive_msg: preparing to run routing scripts...
Mar 23 10:33:43 [2340] DBG:core:parse_headers: flags=100
Mar 23 10:33:43 [2340] DBG:core:parse_to: end of header reached, state=10
Mar 23 10:33:43 [2340] DBG:core:parse_to: display={},
ruri={sip:1...@172.16.16.218:5091;user=phone}
Mar 23 10:33:43 [2340] DBG:core:get_hdr_field: <To> [42];
uri=[sip:1...@172.16.16.218:5091;user=phone]
Mar 23 10:33:43 [2340] DBG:core:get_hdr_field: to body
[<sip:1...@172.16.16.218:5091;user=phone>
]
Mar 23 10:33:43 [2340] DBG:core:get_hdr_field: cseq <CSeq>: <60> <INVITE>
Mar 23 10:33:43 [2340] DBG:maxfwd:is_maxfwd_present: value = 70
Mar 23 10:33:43 [2340] DBG:siputils:has_totag: no totag
Mar 23 10:33:43 [2340] DBG:core:parse_headers: flags=78
Mar 23 10:33:43 [2340] DBG:tm:t_lookup_request: start searching: hash=43957,
isACK=0
Mar 23 10:33:43 [2340] DBG:tm:matching_3261: RFC3261 transaction matching failed
Mar 23 10:33:43 [2340] DBG:tm:t_lookup_request: no transaction found
Mar 23 10:33:43 [2340] DBG:core:parse_to_param: tag=272384034
Mar 23 10:33:43 [2340] DBG:core:parse_to: end of header reached, state=29
Mar 23 10:33:43 [2340] DBG:core:parse_to: display={"1001"},
ruri={sip:1...@172.16.16.218:5091;user=phone}
Mar 23 10:33:43 [2340] DBG:core:grep_sock_info: checking if host==us: 13==13 &&
[172.16.16.218] == [172.16.16.218]
Mar 23 10:33:43 [2340] DBG:core:grep_sock_info: checking if port 5090 matches
port 5091
Mar 23 10:33:43 [2340] DBG:core:grep_sock_info: checking if host==us: 13==13 &&
[172.16.16.218] == [172.16.16.218]
Mar 23 10:33:43 [2340] DBG:core:grep_sock_info: checking if port 5091 matches
port 5091
Mar 23 10:33:43 [2340] DBG:core:grep_sock_info: match found for:
[172.16.16.218:5091]
Mar 23 10:33:43 [2340] DBG:core:check_self: host == me
Mar 23 10:33:43 [2340] DBG:core:parse_headers: flags=10000
Mar 23 10:33:43 [2340] DBG:core:get_hdr_field: content_length=815
Mar 23 10:33:43 [2340] DBG:core:get_hdr_field: found end of header
Mar 23 10:33:43 [2340] DBG:auth:pre_auth: credentials with given realm not found
Mar 23 10:33:43 [2340] DBG:auth:reserve_nonce_index: second= 30, sec_monit= 37,
index= 40
Mar 23 10:33:43 [2340] DBG:auth:build_auth_hf: nonce index= 40
Mar 23 10:33:43 [2340] DBG:auth:build_auth_hf: 'Proxy-Authenticate: Digest
realm="172.16.16.218", nonce="4ba84bcd000000289547d96a6775a0ed93350e7b16af1340"
'
Mar 23 10:33:43 [2340] DBG:sl:send_reply: reply in stateless mode (sl)
Mar 23 10:33:43 [2340] DBG:core:parse_headers: flags=ffffffffffffffff
Mar 23 10:33:43 [2340] DBG:core:check_via_address: params 172.16.16.206,
172.16.16.206, 0
Mar 23 10:33:43 [2340] DBG:core:tcp_send: tcp connection found
(0x7f35bdf9d7f0), acquiring fd
Mar 23 10:33:43 [2340] DBG:core:tcp_send: c= 0x7f35bdf9d7f0, n=16
Mar 23 10:33:43 [2344] DBG:core:handle_ser_child: read response= 7f35bdf9d7f0,
1, fd -1 from 7 (2340)
Mar 23 10:33:43 [2340] DBG:core:tcp_send: after receive_fd: c= 0x7f35bdf9d7f0
n=8 fd=18
Mar 23 10:33:43 [2340] DBG:core:tcp_send: sending...
Mar 23 10:33:43 [2340] DBG:core:tls_update_fd: New fd is 18
Mar 23 10:33:43 [2340] DBG:core:tls_write: write was successful (511 bytes)
Mar 23 10:33:43 [2340] DBG:core:tcp_send: after write: c= 0x7f35bdf9d7f0 n=511
fd=18
Mar 23 10:33:43 [2340] DBG:core:tcp_send: buf=
SIP/2.0 407 Proxy Authentication Required
Via: SIP/2.0/TLS 172.16.16.206:5060;branch=z9hG4bK1337273695;rport=4972;alias
From: "1001" <sip:1...@172.16.16.218:5091;user=phone>;tag=272384034
To:
<sip:1...@172.16.16.218:5091;user=phone>;tag=2cf7f9a22b6374f465182a893bba7dec.a34e
Call-ID: 875232337-506...@bhc.bg.bg.cag
CSeq: 60 INVITE
Proxy-Authenticate: Digest realm="172.16.16.218",
nonce="4ba84bcd000000289547d96a6775a0ed93350e7b16af1340"
Server: Kamailio (1.5.4-tls (x86_64/linux))
Content-Length: 0
Mar 23 10:33:43 [2340] DBG:core:destroy_avp_list: destroying list (nil)
Mar 23 10:33:43 [2340] DBG:core:receive_msg: cleaning up
Mar 23 10:33:43 [2340] DBG:core:tls_update_fd: New fd is 17
Mar 23 10:33:43 [2340] DBG:core:_tls_read: 359 bytes read
Mar 23 10:33:43 [2340] DBG:core:tcp_read_req: content-length= 0
Mar 23 10:33:43 [2340] DBG:core:parse_msg: SIP Request:
Mar 23 10:33:43 [2340] DBG:core:parse_msg: method: <ACK>
Mar 23 10:33:43 [2340] DBG:core:parse_msg: uri:
<sip:1...@172.16.16.218:5091;user=phone>
Mar 23 10:33:43 [2340] DBG:core:parse_msg: version: <SIP/2.0>
Mar 23 10:33:43 [2340] DBG:core:parse_headers: flags=2
Mar 23 10:33:43 [2340] DBG:core:parse_via_param: found param type 232, <branch>
= <z9hG4bK1337273695>; state=6
Mar 23 10:33:43 [2340] DBG:core:parse_via_param: found param type 235, <rport>
= <n/a>; state=6
Mar 23 10:33:43 [2340] DBG:core:parse_via_param: found param type 237, <alias>
= <n/a>; state=16
Mar 23 10:33:43 [2340] DBG:core:parse_via: end of header reached, state=5
Mar 23 10:33:43 [2340] DBG:core:parse_headers: via found, flags=2
Mar 23 10:33:43 [2340] DBG:core:parse_headers: this is the first via
Mar 23 10:33:43 [2340] DBG:core:receive_msg: After parse_msg...
Mar 23 10:33:43 [2340] DBG:core:receive_msg: preparing to run routing scripts...
Mar 23 10:33:43 [2340] DBG:core:parse_headers: flags=8
Mar 23 10:33:43 [2340] DBG:core:parse_to_param:
tag=2cf7f9a22b6374f465182a893bba7dec.a34e
Mar 23 10:33:43 [2340] DBG:core:parse_to: end of header reached, state=29
Mar 23 10:33:43 [2340] DBG:core:parse_to: display={},
ruri={sip:1...@172.16.16.218:5091;user=phone}
Mar 23 10:33:43 [2340] DBG:core:get_hdr_field: <To> [84];
uri=[sip:1...@172.16.16.218:5091;user=phone]
Mar 23 10:33:43 [2340] DBG:core:get_hdr_field: to body
[<sip:1...@172.16.16.218:5091;user=phone>]
Mar 23 10:33:43 [2340] DBG:sl:sl_filter_ACK: local ACK found -> dropping it!
Mar 23 10:33:43 [2340] DBG:core:destroy_avp_list: destroying list (nil)
Mar 23 10:33:43 [2340] DBG:core:receive_msg: cleaning up
Mar 23 10:33:43 [2340] DBG:core:tls_update_fd: New fd is 17
Mar 23 10:33:43 [2340] DBG:core:tls_update_fd: New fd is 17
Mar 23 10:33:43 [2340] DBG:core:_tls_read: 1788 bytes read
Mar 23 10:33:43 [2340] DBG:core:tcp_read_req: content-length= 815
Mar 23 10:33:43 [2340] DBG:core:parse_msg: SIP Request:
Mar 23 10:33:43 [2340] DBG:core:parse_msg: method: <INVITE>
Mar 23 10:33:43 [2340] DBG:core:parse_msg: uri:
<sip:1...@172.16.16.218:5091;user=phone>
Mar 23 10:33:43 [2340] DBG:core:parse_msg: version: <SIP/2.0>
Mar 23 10:33:43 [2340] DBG:core:parse_headers: flags=2
Mar 23 10:33:43 [2340] DBG:core:parse_via_param: found param type 232, <branch>
= <z9hG4bK687870189>; state=6
Mar 23 10:33:43 [2340] DBG:core:parse_via_param: found param type 235, <rport>
= <n/a>; state=6
Mar 23 10:33:43 [2340] DBG:core:parse_via_param: found param type 237, <alias>
= <n/a>; state=16
Mar 23 10:33:43 [2340] DBG:core:parse_via: end of header reached, state=5
Mar 23 10:33:43 [2340] DBG:core:parse_headers: via found, flags=2
Mar 23 10:33:43 [2340] DBG:core:parse_headers: this is the first via
Mar 23 10:33:43 [2340] DBG:core:receive_msg: After parse_msg...
Mar 23 10:33:43 [2340] DBG:core:receive_msg: preparing to run routing scripts...
Mar 23 10:33:43 [2340] DBG:core:parse_headers: flags=100
Mar 23 10:33:43 [2340] DBG:core:parse_to: end of header reached, state=10
Mar 23 10:33:43 [2340] DBG:core:parse_to: display={},
ruri={sip:1...@172.16.16.218:5091;user=phone}
Mar 23 10:33:43 [2340] DBG:core:get_hdr_field: <To> [42];
uri=[sip:1...@172.16.16.218:5091;user=phone]
Mar 23 10:33:43 [2340] DBG:core:get_hdr_field: to body
[<sip:1...@172.16.16.218:5091;user=phone>
]
Mar 23 10:33:43 [2340] DBG:core:get_hdr_field: cseq <CSeq>: <61> <INVITE>
Mar 23 10:33:43 [2340] DBG:maxfwd:is_maxfwd_present: value = 70
Mar 23 10:33:43 [2340] DBG:siputils:has_totag: no totag
Mar 23 10:33:43 [2340] DBG:core:parse_headers: flags=78
Mar 23 10:33:43 [2340] DBG:tm:t_lookup_request: start searching: hash=43958,
isACK=0
Mar 23 10:33:43 [2340] DBG:tm:matching_3261: RFC3261 transaction matching failed
Mar 23 10:33:43 [2340] DBG:tm:t_lookup_request: no transaction found
Mar 23 10:33:43 [2340] DBG:core:parse_to_param: tag=272384034
Mar 23 10:33:43 [2340] DBG:core:parse_to: end of header reached, state=29
Mar 23 10:33:43 [2340] DBG:core:parse_to: display={"1001"},
ruri={sip:1...@172.16.16.218:5091;user=phone}
Mar 23 10:33:43 [2340] DBG:core:grep_sock_info: checking if host==us: 13==13 &&
[172.16.16.218] == [172.16.16.218]
Mar 23 10:33:43 [2340] DBG:core:grep_sock_info: checking if port 5090 matches
port 5091
Mar 23 10:33:43 [2340] DBG:core:grep_sock_info: checking if host==us: 13==13 &&
[172.16.16.218] == [172.16.16.218]
Mar 23 10:33:43 [2340] DBG:core:grep_sock_info: checking if port 5091 matches
port 5091
Mar 23 10:33:43 [2340] DBG:core:grep_sock_info: match found for:
[172.16.16.218:5091]
Mar 23 10:33:43 [2340] DBG:core:check_self: host == me
Mar 23 10:33:43 [2340] DBG:auth:check_nonce: comparing
[4ba84bcd000000289547d96a6775a0ed93350e7b16af1340] and
[4ba84bcd000000289547d96a6775a0ed93350e7b16af1340]
Mar 23 10:33:43 [2340] DBG:core:db_new_result: allocate 48 bytes for result set
at 0x78d560
Mar 23 10:33:43 [2340] DBG:db_mysql:db_mysql_get_columns: 1 columns returned
from the query
Mar 23 10:33:43 [2340] DBG:core:db_allocate_columns: allocate 8 bytes for
result names at 0x78a918
Mar 23 10:33:43 [2340] DBG:core:db_allocate_columns: allocate 4 bytes for
result types at 0x78ce58
Mar 23 10:33:43 [2340] DBG:db_mysql:db_mysql_get_columns: allocate 16 bytes for
RES_NAMES[0] at 0x78d210
Mar 23 10:33:43 [2340] DBG:db_mysql:db_mysql_get_columns:
RES_NAMES(0x78d210)[0]=[password]
Mar 23 10:33:43 [2340] DBG:db_mysql:db_mysql_get_columns: use DB_STRING result
type
Mar 23 10:33:43 [2340] DBG:core:db_allocate_rows: allocate 16 bytes for rows at
0x79ebe0
Mar 23 10:33:43 [2340] DBG:core:db_allocate_row: allocate 32 bytes for row
values at 0x78d230
Mar 23 10:33:43 [2340] DBG:core:db_str2val: converting STRING [1234]
Mar 23 10:33:43 [2340] DBG:auth_db:get_ha1: HA1 string calculated:
6e66d4925dd533f54199f801c85894f5
Mar 23 10:33:43 [2340] DBG:auth:check_response: our result =
'24b0cb91322b8e3c3ec3576ad62fbce8'
Mar 23 10:33:43 [2340] DBG:auth:check_response: authorization is OK
Mar 23 10:33:43 [2340] DBG:auth:post_auth: nonce index= 40
Mar 23 10:33:43 [2340] DBG:core:db_free_columns: freeing 1 columns
Mar 23 10:33:43 [2340] DBG:core:db_free_columns: freeing RES_NAMES[0] at
0x78d210
Mar 23 10:33:43 [2340] DBG:core:db_free_columns: freeing result names at
0x78a918
Mar 23 10:33:43 [2340] DBG:core:db_free_columns: freeing result types at
0x78ce58
Mar 23 10:33:43 [2340] DBG:core:db_free_rows: freeing 1 rows
Mar 23 10:33:43 [2340] DBG:core:db_free_row: freeing row values at 0x78d230
Mar 23 10:33:43 [2340] DBG:core:db_free_rows: freeing rows at 0x79ebe0
Mar 23 10:33:43 [2340] DBG:core:db_free_result: freeing result set at 0x78d560
Mar 23 10:33:43 [2340] DBG:core:parse_headers: flags=14000
Mar 23 10:33:43 [2340] DBG:core:get_hdr_field: content_length=815
Mar 23 10:33:43 [2340] DBG:core:get_hdr_field: found end of header
Mar 23 10:33:43 [2340] DBG:core:comp_scriptvar: str 29 : 1001
---- Invite ----
Mar 23 10:33:43 [2340] DBG:core:comp_scriptvar: str 29 : 1001
Mar 23 10:33:43 [2340] ERROR:rr:w_record_route: Double attempt to record-route
Mar 23 10:33:43 [2340] DBG:dispatcher:ds_select_dst: set [1]
Mar 23 10:33:43 [2340] DBG:dispatcher:ds_select_dst: alg hash [2504030904]
Mar 23 10:33:43 [2340] DBG:dispatcher:ds_select_dst: selected [0-1/0]
<sip:172.16.16.218:5070>
Mar 23 10:33:43 [2340] DBG:tm:t_newtran: transaction on entrance=(nil)
Mar 23 10:33:43 [2340] DBG:core:parse_headers: flags=ffffffffffffffff
Mar 23 10:33:43 [2340] DBG:core:parse_headers: flags=78
Mar 23 10:33:43 [2340] DBG:tm:t_lookup_request: start searching: hash=43958,
isACK=0
Mar 23 10:33:43 [2340] DBG:tm:matching_3261: RFC3261 transaction matching failed
Mar 23 10:33:43 [2340] DBG:tm:t_lookup_request: no transaction found
Mar 23 10:33:43 [2340] DBG:tm:run_reqin_callbacks: trans=0x7f35bdf67498,
callback type 1, id 0 entered
Mar 23 10:33:43 [2340] DBG:core:parse_headers: flags=ffffffffffffffff
Mar 23 10:33:43 [2340] DBG:core:check_via_address: params 172.16.16.206,
172.16.16.206, 0
Mar 23 10:33:43 [2340] DBG:core:_shm_resize: resize(0) called
Mar 23 10:33:43 [2340] DBG:core:tcp_send: tcp connection found
(0x7f35bdf9d7f0), acquiring fd
Mar 23 10:33:43 [2340] DBG:core:tcp_send: c= 0x7f35bdf9d7f0, n=16
Mar 23 10:33:43 [2344] DBG:core:handle_ser_child: read response= 7f35bdf9d7f0,
1, fd -1 from 7 (2340)
Mar 23 10:33:43 [2340] DBG:core:tcp_send: after receive_fd: c= 0x7f35bdf9d7f0
n=8 fd=18
Mar 23 10:33:43 [2340] DBG:core:tcp_send: sending...
Mar 23 10:33:43 [2340] DBG:core:tls_update_fd: New fd is 18
Mar 23 10:33:43 [2340] DBG:core:tls_write: write was successful (343 bytes)
Mar 23 10:33:43 [2340] DBG:core:tcp_send: after write: c= 0x7f35bdf9d7f0 n=343
fd=18
Mar 23 10:33:43 [2340] DBG:core:tcp_send: buf=
SIP/2.0 100 Giving a try
Via: SIP/2.0/TLS 172.16.16.206:5060;branch=z9hG4bK687870189;rport=4972;alias
From: "1001" <sip:1...@172.16.16.218:5091;user=phone>;tag=272384034
To: <sip:1...@172.16.16.218:5091;user=phone>
Call-ID: 875232337-506...@bhc.bg.bg.cag
CSeq: 61 INVITE
Server: Kamailio (1.5.4-tls (x86_64/linux))
Content-Length: 0
Mar 23 10:33:43 [2340] DBG:tm:_reply_light: reply sent out. buf=0x79f4a0:
SIP/2.0 1..., shmem=0x7f35bdf56b10: SIP/2.0 1
Mar 23 10:33:43 [2340] DBG:tm:_reply_light: finished
Mar 23 10:33:43 [2340] DBG:core:mk_proxy: doing DNS lookup...
Mar 23 10:33:43 [2340] DBG:core:build_req_buf_from_sip_req: id added: <;i=82>,
rcv proto=3
Mar 23 10:33:43 [2340] DBG:tm:set_timer: relative timeout is 500000
Mar 23 10:33:43 [2340] DBG:tm:insert_timer_unsafe: [4]: 0x7f35bdf676b8
(2883200000)
Mar 23 10:33:43 [2340] DBG:tm:set_timer: relative timeout is 30
Mar 23 10:33:43 [2340] DBG:tm:insert_timer_unsafe: [0]: 0x7f35bdf676e8 (2912)
Mar 23 10:33:43 [2340] DBG:tm:t_relay_to: new transaction fwd'ed
Mar 23 10:33:43 [2340] DBG:tm:t_unref: UNREF_UNSAFE: after is 0
Mar 23 10:33:43 [2340] DBG:core:destroy_avp_list: destroying list (nil)
Mar 23 10:33:43 [2340] DBG:core:receive_msg: cleaning up
Mar 23 10:33:43 [2337] DBG:core:parse_msg: SIP Reply (status):
Mar 23 10:33:43 [2337] DBG:core:parse_msg: version: <SIP/2.0>
Mar 23 10:33:43 [2337] DBG:core:parse_msg: status: <100>
Mar 23 10:33:43 [2337] DBG:core:parse_msg: reason: <Trying>
Mar 23 10:33:43 [2337] DBG:core:parse_headers: flags=2
Mar 23 10:33:43 [2337] DBG:core:parse_via_param: found param type 232, <branch>
= <z9hG4bK6bba.793f1952.0>; state=6
Mar 23 10:33:43 [2337] DBG:core:parse_via_param: found param type 236, <i> =
<82>; state=6
Mar 23 10:33:43 [2337] DBG:core:parse_via_param: found param type 234,
<received> = <172.16.16.218>; state=16
Mar 23 10:33:43 [2337] DBG:core:parse_via: end of header reached, state=5
Mar 23 10:33:43 [2337] DBG:core:parse_headers: via found, flags=2
Mar 23 10:33:43 [2337] DBG:core:parse_headers: this is the first via
Mar 23 10:33:43 [2337] DBG:core:receive_msg: After parse_msg...
Mar 23 10:33:43 [2337] DBG:core:forward_reply: found module tm, passing reply
to it
Mar 23 10:33:43 [2337] DBG:tm:t_check: start=0xffffffffffffffff
Mar 23 10:33:43 [2337] DBG:core:parse_headers: flags=22
Mar 23 10:33:43 [2337] DBG:core:parse_via_param: found param type 234,
<received> = <172.16.16.206>; state=6
Mar 23 10:33:43 [2337] DBG:core:parse_via_param: found param type 232, <branch>
= <z9hG4bK687870189>; state=6
Mar 23 10:33:43 [2337] DBG:core:parse_via_param: found param type 235, <rport>
= <4972>; state=6
Mar 23 10:33:43 [2337] DBG:core:parse_via_param: found param type 237, <alias>
= <n/a>; state=16
Mar 23 10:33:43 [2337] DBG:core:parse_via: end of header reached, state=5
Mar 23 10:33:43 [2337] DBG:core:parse_headers: via found, flags=22
Mar 23 10:33:43 [2337] DBG:core:parse_headers: parse_headers: this is the
second via
Mar 23 10:33:43 [2337] DBG:core:parse_to: end of header reached, state=10
Mar 23 10:33:43 [2337] DBG:core:parse_to: display={},
ruri={sip:1...@172.16.16.218:5091;user=phone}
Mar 23 10:33:43 [2337] DBG:core:get_hdr_field: <To> [42];
uri=[sip:1...@172.16.16.218:5091;user=phone]
Mar 23 10:33:43 [2337] DBG:core:get_hdr_field: to body
[<sip:1...@172.16.16.218:5091;user=phone>
]
Mar 23 10:33:43 [2337] DBG:core:get_hdr_field: cseq <CSeq>: <61> <INVITE>
Mar 23 10:33:43 [2337] DBG:core:parse_headers: flags=8
Mar 23 10:33:43 [2337] DBG:tm:t_reply_matching: hash 43958 label 630322071
branch 0
Mar 23 10:33:43 [2337] DBG:tm:t_reply_matching: REF_UNSAFE: after is 1
Mar 23 10:33:43 [2337] DBG:tm:t_reply_matching: reply matched
(T=0x7f35bdf67498)!
Mar 23 10:33:43 [2337] DBG:tm:t_check: end=0x7f35bdf67498
Mar 23 10:33:43 [2337] DBG:tm:reply_received: org. status uas=100, uac[0]=0
local=0 is_invite=1)
Mar 23 10:33:43 [2337] DBG:tm:t_should_relay_response: T_code=100, new_code=100
Mar 23 10:33:43 [2337] DBG:tm:relay_reply: branch=0, save=0, relay=-1
Mar 23 10:33:43 [2337] DBG:tm:set_timer: relative timeout is 120
Mar 23 10:33:43 [2337] DBG:tm:insert_timer_unsafe: [1]: 0x7f35bdf676e8 (3003)
Mar 23 10:33:43 [2337] DBG:tm:t_unref: UNREF_UNSAFE: after is 0
Mar 23 10:33:43 [2337] DBG:core:destroy_avp_list: destroying list (nil)
Mar 23 10:33:43 [2337] DBG:core:receive_msg: cleaning up
Mar 23 10:33:43 [2335] DBG:core:parse_msg: SIP Request:
Mar 23 10:33:43 [2335] DBG:core:parse_msg: method: <INVITE>
Mar 23 10:33:43 [2335] DBG:core:parse_msg: uri:
<sip:1...@172.16.16.218:5090>
Mar 23 10:33:43 [2335] DBG:core:parse_msg: version: <SIP/2.0>
Mar 23 10:33:43 [2335] DBG:core:parse_headers: flags=2
Mar 23 10:33:43 [2335] DBG:core:parse_via_param: found param type 232, <branch>
= <z9hG4bK00843d58>; state=6
Mar 23 10:33:43 [2335] DBG:core:parse_via_param: found param type 235, <rport>
= <n/a>; state=17
Mar 23 10:33:43 [2335] DBG:core:parse_via: end of header reached, state=5
Mar 23 10:33:43 [2335] DBG:core:parse_headers: via found, flags=2
Mar 23 10:33:43 [2335] DBG:core:parse_headers: this is the first via
Mar 23 10:33:43 [2335] DBG:core:receive_msg: After parse_msg...
Mar 23 10:33:43 [2335] DBG:core:receive_msg: preparing to run routing scripts...
Mar 23 10:33:43 [2335] DBG:core:parse_headers: flags=100
Mar 23 10:33:43 [2335] DBG:core:parse_to: end of header reached, state=10
Mar 23 10:33:43 [2335] DBG:core:parse_to: display={},
ruri={sip:1...@172.16.16.218:5090}
Mar 23 10:33:43 [2335] DBG:core:get_hdr_field: <To> [31];
uri=[sip:1...@172.16.16.218:5090]
Mar 23 10:33:43 [2335] DBG:core:get_hdr_field: to body
[<sip:1...@172.16.16.218:5090>
]
Mar 23 10:33:43 [2335] DBG:core:get_hdr_field: cseq <CSeq>: <102> <INVITE>
Mar 23 10:33:43 [2335] DBG:maxfwd:is_maxfwd_present: value = 70
---- From SC/MS/IC ----
Mar 23 10:33:43 [2335] DBG:core:rewrite_uri: rewriting Request-URI with
'sip:1...@172.16.17.81:15099;transport=tls;user=phone'
Mar 23 10:33:43 [2335] DBG:core:mk_proxy: doing DNS lookup...
Mar 23 10:33:43 [2335] DBG:core:parse_headers: flags=2000
Mar 23 10:33:43 [2335] DBG:core:get_hdr_field: content_length=580
Mar 23 10:33:43 [2335] DBG:core:forward_request: sending:
INVITE sip:1...@172.16.17.81:15099;transport=tls;user=phone SIP/2.0
Record-Route: <sip:172.16.16.218:5091;transport=tls;r2=on;lr=on>
Record-Route: <sip:172.16.16.218:5090;r2=on;lr=on>
Via: SIP/2.0/TLS 172.16.16.218:5091;branch=z9hG4bK00843d58
Via: SIP/2.0/UDP
172.16.16.218:5070;received=172.16.16.218;branch=z9hG4bK00843d58;rport=5070
From: "1001" <sip:1...@172.16.16.218:5070>;tag=as60af855f
To: <sip:1...@172.16.16.218:5090>
Contact: <sip:1...@172.16.16.218:5070>
Call-ID: 15b634d06c6e5d2d63b71fe123c3c...@172.16.16.218
CSeq: 102 INVITE
User-Agent: PANTHER-SC
Max-Forwards: 69
Date: Tue, 23 Mar 2010 05:03:43 GMT
Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY
Supported: replaces
Content-Type: application/sdp
Content-Length: 580
v=0
o=root 2126 2126 IN IP4 172.16.16.218
s=session
c=IN IP4 172.16.16.218
t=0 0
m=audio 11262 RTP/SAVP 0 18 8 101
a=rtpmap:0 PCMU/8000
a=rtpmap:18 G729/8000
a=fmtp:18 annexb=no
a=rtpmap:8 PCMA/8000
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-16
a=silenceSupp:off - - - -
a=ptime:20
a=crypto:1 AES_CM_128_HMAC_SHA1_80
inline:2FXsAoBFaNzqIwXcyo8EwI81slJDnNpoA6+PkJFY
a=sendrecv
m=video 17638 RTP/SAVP 99
a=rtpmap:99 H264/90000
a=fmtp:99 profile-level-id=42800d
a=crypto:1 AES_CM_128_HMAC_SHA1_80
inline:WNjW7f5hxaItleUZMNPv/Ni1ZNQ7A9i4AUhHBBxI
a=sendrecv
.
Mar 23 10:33:43 [2335] DBG:core:forward_request: orig. len=1121, new_len=1352,
proto=3
Mar 23 10:33:43 [2335] DBG:core:tcp_send: no open tcp connection found, opening
new one
Mar 23 10:33:43 [2335] DBG:core:print_ip: tcpconn_new: new tcp connection to:
172.16.17.81
Mar 23 10:33:43 [2335] DBG:core:tcpconn_new: on port 15099, type 3
Mar 23 10:33:43 [2335] DBG:core:tls_tcpconn_init: entered: Creating a whole new
ssl connection
Mar 23 10:33:43 [2335] DBG:core:tls_tcpconn_init: name based TLS client domains
are disabled
Mar 23 10:33:43 [2335] DBG:core:tls_tcpconn_init: no TLS client domain AVP set,
looking for socket based TLS client domain
Mar 23 10:33:43 [2335] DBG:core:tls_find_client_domain: virtual TLS client
domain not found, Using default TLS client domain settings
Mar 23 10:33:43 [2335] DBG:core:tls_tcpconn_init: found socket based TLS client
domain [0.0.0.0:0]
Mar 23 10:33:43 [2335] DBG:core:tls_tcpconn_init: Setting in CONNECT mode
(client)
Mar 23 10:33:43 [2335] DBG:core:tls_tcpconn_init: TLS server extension is not
activated
Mar 23 10:33:43 [2335] DBG:core:tls_tcpconn_init: TLS server name is not set,
sending ClientHello without server_name
Mar 23 10:33:43 [2335] DBG:core:tcp_send: sending...
Mar 23 10:33:43 [2344] DBG:core:handle_ser_child: read response= 7f35bdfad988,
2, fd 24 from 2 (2335)
Mar 23 10:33:43 [2344] DBG:core:tcpconn_add: hashes: 599, 41
Mar 23 10:33:43 [2335] DBG:core:tls_update_fd: New fd is 9
Mar 23 10:33:43 [2344] DBG:core:io_watch_add: io_watch_add(0x74ee80, 24, 2,
0x7f35bdfad988), fd_no=16
Mar 23 10:33:43 [2344] DBG:core:handle_tcpconn_ev: data available on
0x7f35bdfad988 24
Mar 23 10:33:43 [2344] DBG:core:io_watch_del: io_watch_del (0x74ee80, 24, -1,
0x0) fd_no=17 called
Mar 23 10:33:43 [2344] DBG:core:send2child: to tcp child 1 0(2341),
0x7f35bdfad988
Mar 23 10:33:43 [2341] DBG:core:handle_io: received n=8 con=0x7f35bdfad988,
fd=19
Mar 23 10:33:43 [2341] DBG:core:io_watch_add: io_watch_add(0x74efe0, 19, 2,
0x7f35bdfad988), fd_no=1
Mar 23 10:33:43 [2335] NOTICE:core:verify_callback: depth = 0
Mar 23 10:33:43 [2335] NOTICE:core:verify_callback: subject =
/C=US/ST=California/L=Los Angeles/O=Grandstream Networks, Inc./CN=HT500 ATA
Mar 23 10:33:43 [2335] NOTICE:core:verify_callback: verify error:num=20:unable
to get local issuer certificate
Mar 23 10:33:43 [2335] NOTICE:core:verify_callback: error code is 20
Mar 23 10:33:43 [2335] NOTICE:core:verify_callback: something wrong with the
cert ... error code is 20 (check x509_vfy.h)
Mar 23 10:33:43 [2335] NOTICE:core:verify_callback: verify return:0
Mar 23 10:33:43 [2335] ERROR:core:tls_connect: something wrong in SSL: 1
(ret=-1) err=Success(0)
Mar 23 10:33:43 [2335] ERROR:core:tls_print_errstack: error:14090086:SSL
routines:SSL3_GET_SERVER_CERTIFICATE:certificate verify failed
Mar 23 10:33:43 [2335] DBG:core:tcp_send: after write: c= 0x7f35bdfad988 n=-1
fd=9
Mar 23 10:33:43 [2341] DBG:core:io_watch_del: io_watch_del (0x74efe0, 19, -1,
0x10) fd_no=2 called
Mar 23 10:33:43 [2335] DBG:core:tcp_send: buf=
INVITE sip:1...@172.16.17.81:15099;transport=tls;user=phone SIP/2.0
Record-Route: <sip:172.16.16.218:5091;transport=tls;r2=on;lr=on>
Record-Route: <sip:172.16.16.218:5090;r2=on;lr=on>
Via: SIP/2.0/TLS 172.16.16.218:5091;branch=z9hG4bK00843d58
Via: SIP/2.0/UDP
172.16.16.218:5070;received=172.16.16.218;branch=z9hG4bK00843d58;rport=5070
From: "1001" <sip:1...@172.16.16.218:5070>;tag=as60af855f
To: <sip:1...@172.16.16.218:5090>
Contact: <sip:1...@172.16.16.218:5070>
Call-ID: 15b634d06c6e5d2d63b71fe123c3c...@172.16.16.218
CSeq: 102 INVITE
User-Agent: PANTHER-SC
Max-Forwards: 69
Date: Tue, 23 Mar 2010 05:03:43 GMT
Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY
Supported: replaces
Content-Type: application/sdp
Content-Length: 580
v=0
o=root 2126 2126 IN IP4 172.16.16.218
s=session
c=IN IP4 172.16.16.218
t=0 0
m=audio 11262 RTP/SAVP 0 18 8 101
a=rtpmap:0 PCMU/8000
a=rtpmap:18 G729/8000
a=fmtp:18 annexb=no
a=rtpmap:8 PCMA/8000
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-16
a=silenceSupp:off - - - -
a=ptime:20
a=crypto:1 AES_CM_128_HMAC_SHA1_80
inline:2FXsAoBFaNzqIwXcyo8EwI81slJDnNpoA6+PkJFY
a=sendrecv
m=video 17638 RTP/SAVP 99
a=rtpmap:99 H264/90000
a=fmtp:99 profile-level-id=42800d
a=crypto:1 AES_CM_128_HMAC_SHA1_80
inline:WNjW7f5hxaItleUZMNPv/Ni1ZNQ7A9i4AUhHBBxI
a=sendrecv
Mar 23 10:33:43 [2341] DBG:core:release_tcpconn: releasing con 0x7f35bdfad988,
state -2, fd=19, id=41
Mar 23 10:33:43 [2335] ERROR:core:tcp_send: failed to send
Mar 23 10:33:43 [2341] DBG:core:release_tcpconn: extra_data 0x7f35bdf5d490
Mar 23 10:33:43 [2335] ERROR:core:msg_send: tcp_send failed
Mar 23 10:33:43 [2344] DBG:core:handle_ser_child: read response= 7f35bdfad988,
-2, fd -1 from 2 (2335)
Mar 23 10:33:43 [2344] DBG:core:tcpconn_destroy: delaying (0x7f35bdfad988,
flags 0002) ...
Mar 23 10:33:43 [2335] DBG:sl:sl_reply_error: error text is Send failed (477/SL)
Mar 23 10:33:43 [2344] DBG:core:handle_tcp_child: reader response=
7f35bdfad988, -2 from 1
Mar 23 10:33:43 [2344] DBG:core:tcpconn_destroy: destroying connection
0x7f35bdfad988, flags 0002
Mar 23 10:33:43 [2344] DBG:core:tls_close: closing SSL connection
Mar 23 10:33:43 [2335] DBG:core:parse_headers: flags=ffffffffffffffff
Mar 23 10:33:43 [2335] DBG:core:get_hdr_field: found end of header
Mar 23 10:33:43 [2344] DBG:core:tls_update_fd: New fd is 24
Mar 23 10:33:43 [2344] DBG:core:tls_shutdown: shutdown successful
Mar 23 10:33:43 [2335] DBG:core:check_via_address: params 172.16.16.218,
172.16.16.218, 0
Mar 23 10:33:43 [2344] DBG:core:tls_tcpconn_clean: Cleanup function entered
Mar 23 10:33:43 [2335] DBG:core:destroy_avp_list: destroying list (nil)
Mar 23 10:33:43 [2335] DBG:core:receive_msg: cleaning up
Mar 23 10:33:43 [2336] DBG:core:parse_msg: SIP Request:
Mar 23 10:33:43 [2336] DBG:core:parse_msg: method: <ACK>
Mar 23 10:33:43 [2336] DBG:core:parse_msg: uri:
<sip:1...@172.16.16.218:5090>
Mar 23 10:33:43 [2336] DBG:core:parse_msg: version: <SIP/2.0>
Mar 23 10:33:43 [2336] DBG:core:parse_headers: flags=2
Mar 23 10:33:43 [2336] DBG:core:parse_via_param: found param type 232, <branch>
= <z9hG4bK00843d58>; state=6
Mar 23 10:33:43 [2336] DBG:core:parse_via_param: found param type 235, <rport>
= <n/a>; state=17
Mar 23 10:33:43 [2336] DBG:core:parse_via: end of header reached, state=5
Mar 23 10:33:43 [2336] DBG:core:parse_headers: via found, flags=2
Mar 23 10:33:43 [2336] DBG:core:parse_headers: this is the first via
Mar 23 10:33:43 [2336] DBG:core:receive_msg: After parse_msg...
Mar 23 10:33:43 [2336] DBG:core:receive_msg: preparing to run routing scripts...
Mar 23 10:33:43 [2336] DBG:core:parse_headers: flags=8
Mar 23 10:33:43 [2336] DBG:core:parse_to_param:
tag=2cf7f9a22b6374f465182a893bba7dec.3da6
Mar 23 10:33:43 [2336] DBG:core:parse_to: end of header reached, state=29
Mar 23 10:33:43 [2336] DBG:core:parse_to: display={},
ruri={sip:1...@172.16.16.218:5090}
Mar 23 10:33:43 [2336] DBG:core:get_hdr_field: <To> [73];
uri=[sip:1...@172.16.16.218:5090]
Mar 23 10:33:43 [2336] DBG:core:get_hdr_field: to body
[<sip:1...@172.16.16.218:5090>]
Mar 23 10:33:43 [2336] DBG:sl:sl_filter_ACK: local ACK found -> dropping it!
Mar 23 10:33:43 [2336] DBG:core:destroy_avp_list: destroying list (nil)
Mar 23 10:33:43 [2336] DBG:core:receive_msg: cleaning up
Mar 23 10:33:43 [2338] DBG:tm:utimer_routine: timer routine:4,tl=0x7f35bdf676b8
next=(nil), timeout=2883200000
Mar 23 10:33:43 [2334] DBG:core:parse_msg: SIP Reply (status):
Mar 23 10:33:43 [2334] DBG:core:parse_msg: version: <SIP/2.0>
Mar 23 10:33:43 [2334] DBG:core:parse_msg: status: <404>
Mar 23 10:33:43 [2334] DBG:core:parse_msg: reason: <Not Found>
Mar 23 10:33:43 [2334] DBG:core:parse_headers: flags=2
Mar 23 10:33:43 [2334] DBG:core:parse_via_param: found param type 232, <branch>
= <z9hG4bK6bba.793f1952.0>; state=6
Mar 23 10:33:43 [2334] DBG:core:parse_via_param: found param type 236, <i> =
<82>; state=6
Mar 23 10:33:43 [2334] DBG:core:parse_via_param: found param type 234,
<received> = <172.16.16.218>; state=16
Mar 23 10:33:43 [2334] DBG:core:parse_via: end of header reached, state=5
Mar 23 10:33:43 [2334] DBG:core:parse_headers: via found, flags=2
Mar 23 10:33:43 [2334] DBG:core:parse_headers: this is the first via
Mar 23 10:33:43 [2334] DBG:core:receive_msg: After parse_msg...
Mar 23 10:33:43 [2334] DBG:core:forward_reply: found module tm, passing reply
to it
Mar 23 10:33:43 [2334] DBG:tm:t_check: start=0xffffffffffffffff
Mar 23 10:33:43 [2334] DBG:core:parse_headers: flags=22
Mar 23 10:33:43 [2334] DBG:core:parse_via_param: found param type 234,
<received> = <172.16.16.206>; state=6
Mar 23 10:33:43 [2334] DBG:core:parse_via_param: found param type 232, <branch>
= <z9hG4bK687870189>; state=6
Mar 23 10:33:43 [2334] DBG:core:parse_via_param: found param type 235, <rport>
= <4972>; state=6
Mar 23 10:33:43 [2334] DBG:core:parse_via_param: found param type 237, <alias>
= <n/a>; state=16
Mar 23 10:33:43 [2334] DBG:core:parse_via: end of header reached, state=5
Mar 23 10:33:43 [2334] DBG:core:parse_headers: via found, flags=22
Mar 23 10:33:43 [2334] DBG:core:parse_headers: parse_headers: this is the
second via
Mar 23 10:33:43 [2334] DBG:core:parse_to_param: tag=as4b33da29
Mar 23 10:33:43 [2334] DBG:core:parse_to: end of header reached, state=29
Mar 23 10:33:43 [2334] DBG:core:parse_to: display={},
ruri={sip:1...@172.16.16.218:5091;user=phone}
Mar 23 10:33:43 [2334] DBG:core:get_hdr_field: <To> [57];
uri=[sip:1...@172.16.16.218:5091;user=phone]
Mar 23 10:33:43 [2334] DBG:core:get_hdr_field: to body
[<sip:1...@172.16.16.218:5091;user=phone>]
Mar 23 10:33:43 [2334] DBG:core:get_hdr_field: cseq <CSeq>: <61> <INVITE>
Mar 23 10:33:43 [2334] DBG:core:parse_headers: flags=8
Mar 23 10:33:43 [2334] DBG:tm:t_reply_matching: hash 43958 label 630322071
branch 0
Mar 23 10:33:43 [2334] DBG:tm:t_reply_matching: REF_UNSAFE: after is 1
Mar 23 10:33:43 [2334] DBG:tm:t_reply_matching: reply matched
(T=0x7f35bdf67498)!
Mar 23 10:33:43 [2334] DBG:tm:t_check: end=0x7f35bdf67498
Mar 23 10:33:43 [2334] DBG:tm:reply_received: org. status uas=100, uac[0]=100
local=0 is_invite=1)
Mar 23 10:33:43 [2334] DBG:core:parse_headers: flags=8
Mar 23 10:33:43 [2334] DBG:tm:build_local: using FROM=<From: "1001"
<sip:1...@172.16.16.218:5091;user=phone>;tag=272384034
>, TO=<To: <sip:1...@172.16.16.218:5091;user=phone>;tag=as4b33da29
>, CSEQ_N=<CSeq: 61>
Mar 23 10:33:43 [2334] DBG:tm:extract_parsed_hdrs: ----parsing the buf req -
first line
Mar 23 10:33:43 [2334] DBG:core:parse_headers: flags=ffffffffffffffff
Mar 23 10:33:43 [2334] DBG:core:parse_via_param: found param type 232, <branch>
= <z9hG4bK6bba.793f1952.0>; state=6
Mar 23 10:33:43 [2334] DBG:core:parse_via_param: found param type 236, <i> =
<82>; state=16
Mar 23 10:33:43 [2334] DBG:core:parse_via: end of header reached, state=5
Mar 23 10:33:43 [2334] DBG:core:parse_headers: via found, flags=ffffffffffffffff
Mar 23 10:33:43 [2334] DBG:core:parse_headers: this is the first via
Mar 23 10:33:43 [2334] DBG:core:parse_via_param: found param type 234,
<received> = <172.16.16.206>; state=6
Mar 23 10:33:43 [2334] DBG:core:parse_via_param: found param type 232, <branch>
= <z9hG4bK687870189>; state=6
Mar 23 10:33:43 [2334] DBG:core:parse_via_param: found param type 235, <rport>
= <4972>; state=6
Mar 23 10:33:43 [2334] DBG:core:parse_via_param: found param type 237, <alias>
= <n/a>; state=16
Mar 23 10:33:43 [2334] DBG:core:parse_via: end of header reached, state=5
Mar 23 10:33:43 [2334] DBG:core:parse_headers: via found, flags=ffffffffffffffff
Mar 23 10:33:43 [2334] DBG:core:parse_headers: parse_headers: this is the
second via
Mar 23 10:33:43 [2334] DBG:core:parse_to: end of header reached, state=10
Mar 23 10:33:43 [2334] DBG:core:parse_to: display={},
ruri={sip:1...@172.16.16.218:5091;user=phone}
Mar 23 10:33:43 [2334] DBG:core:get_hdr_field: <To> [42];
uri=[sip:1...@172.16.16.218:5091;user=phone]
Mar 23 10:33:43 [2334] DBG:core:get_hdr_field: to body
[<sip:1...@172.16.16.218:5091;user=phone>
]
Mar 23 10:33:43 [2334] DBG:core:get_hdr_field: cseq <CSeq>: <61> <INVITE>
Mar 23 10:33:43 [2334] DBG:core:get_hdr_field: content_length=815
Mar 23 10:33:43 [2334] DBG:core:get_hdr_field: found end of header
Mar 23 10:33:43 [2334] DBG:tm:t_should_relay_response: T_code=100, new_code=404
Mar 23 10:33:43 [2334] DBG:tm:t_pick_branch: picked branch 0, code 404
Mar 23 10:33:43 [2334] DBG:tm:is_3263_failure: dns-failover test: branch=0,
last_recv=404, flags=2
Mar 23 10:33:43 [2334] WARNING:core:run_actions: null action list (rec_level=1)
Mar 23 10:33:43 [2334] DBG:tm:relay_reply: branch=0, save=0, relay=0
Mar 23 10:33:43 [2334] DBG:core:parse_headers: flags=2000
Mar 23 10:33:43 [2334] DBG:core:get_hdr_field: content_length=0
Mar 23 10:33:43 [2334] DBG:core:build_res_buf_from_sip_res: old size: 541, new
size: 446
Mar 23 10:33:43 [2334] DBG:core:build_res_buf_from_sip_res: copied size:
orig:118, new: 23, rest: 423 msg=
SIP/2.0 404 Not Found
Via: SIP/2.0/TLS
172.16.16.206:5060;received=172.16.16.206;branch=z9hG4bK687870189;rport=4972;alias
From: "1001" <sip:1...@172.16.16.218:5091;user=phone>;tag=272384034
To: <sip:1...@172.16.16.218:5091;user=phone>;tag=as4b33da29
Call-ID: 875232337-506...@bhc.bg.bg.cag
CSeq: 61 INVITE
User-Agent: PANTHER-SC
Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY
Supported: replaces
Content-Length: 0
Mar 23 10:33:43 [2334] DBG:tm:set_timer: relative timeout is 30
Mar 23 10:33:43 [2334] DBG:tm:insert_timer_unsafe: [0]: 0x7f35bdf67610 (2913)
Mar 23 10:33:43 [2334] DBG:core:tcp_send: tcp connection found
(0x7f35bdf9d7f0), acquiring fd
Mar 23 10:33:43 [2334] DBG:core:tcp_send: c= 0x7f35bdf9d7f0, n=16
Mar 23 10:33:43 [2344] DBG:core:handle_ser_child: read response= 7f35bdf9d7f0,
1, fd -1 from 1 (2334)
Mar 23 10:33:43 [2334] DBG:core:tcp_send: after receive_fd: c= 0x7f35bdf9d7f0
n=8 fd=8
Mar 23 10:33:43 [2334] DBG:core:tcp_send: sending...
Mar 23 10:33:43 [2334] DBG:core:tls_update_fd: New fd is 8
Mar 23 10:33:43 [2334] DBG:core:tls_write: write was successful (446 bytes)
Mar 23 10:33:43 [2334] DBG:core:tcp_send: after write: c= 0x7f35bdf9d7f0 n=446
fd=8
Mar 23 10:33:43 [2334] DBG:core:tcp_send: buf=
SIP/2.0 404 Not Found
Via: SIP/2.0/TLS
172.16.16.206:5060;received=172.16.16.206;branch=z9hG4bK687870189;rport=4972;alias
From: "1001" <sip:1...@172.16.16.218:5091;user=phone>;tag=272384034
To: <sip:1...@172.16.16.218:5091;user=phone>;tag=as4b33da29
Call-ID: 875232337-506...@bhc.bg.bg.cag
CSeq: 61 INVITE
User-Agent: PANTHER-SC
Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY
Supported: replaces
Content-Length: 0
Mar 23 10:33:43 [2334] DBG:tm:relay_reply: sent buf=0x7915a8: SIP/2.0 4...,
shmem=0x7f35bdf5dbb0: SIP/2.0 4
Mar 23 10:33:43 [2334] DBG:tm:cleanup_uac_timers: RETR/FR timers reset
Mar 23 10:33:43 [2334] DBG:tm:t_unref: UNREF_UNSAFE: after is 0
Mar 23 10:33:43 [2334] DBG:core:destroy_avp_list: destroying list (nil)
Mar 23 10:33:43 [2334] DBG:core:receive_msg: cleaning up
Mar 23 10:33:43 [2340] DBG:core:tls_update_fd: New fd is 17
Mar 23 10:33:43 [2340] DBG:core:_tls_read: 331 bytes read
Mar 23 10:33:43 [2340] DBG:core:tcp_read_req: content-length= 0
Mar 23 10:33:43 [2340] DBG:core:parse_msg: SIP Request:
Mar 23 10:33:43 [2340] DBG:core:parse_msg: method: <ACK>
Mar 23 10:33:43 [2340] DBG:core:parse_msg: uri:
<sip:1...@172.16.16.218:5091;user=phone>
Mar 23 10:33:43 [2340] DBG:core:parse_msg: version: <SIP/2.0>
Mar 23 10:33:43 [2340] DBG:core:parse_headers: flags=2
Mar 23 10:33:43 [2340] DBG:core:parse_via_param: found param type 232, <branch>
= <z9hG4bK687870189>; state=6
Mar 23 10:33:43 [2340] DBG:core:parse_via_param: found param type 235, <rport>
= <n/a>; state=6
Mar 23 10:33:43 [2340] DBG:core:parse_via_param: found param type 237, <alias>
= <n/a>; state=16
Mar 23 10:33:43 [2340] DBG:core:parse_via: end of header reached, state=5
Mar 23 10:33:43 [2340] DBG:core:parse_headers: via found, flags=2
Mar 23 10:33:43 [2340] DBG:core:parse_headers: this is the first via
Mar 23 10:33:43 [2340] DBG:core:receive_msg: After parse_msg...
Mar 23 10:33:43 [2340] DBG:core:receive_msg: preparing to run routing scripts...
Mar 23 10:33:43 [2340] DBG:core:parse_headers: flags=8
Mar 23 10:33:43 [2340] DBG:core:parse_to_param: tag=as4b33da29
Mar 23 10:33:43 [2340] DBG:core:parse_to: end of header reached, state=29
Mar 23 10:33:43 [2340] DBG:core:parse_to: display={},
ruri={sip:1...@172.16.16.218:5091;user=phone}
Mar 23 10:33:43 [2340] DBG:core:get_hdr_field: <To> [57];
uri=[sip:1...@172.16.16.218:5091;user=phone]
Mar 23 10:33:43 [2340] DBG:core:get_hdr_field: to body
[<sip:1...@172.16.16.218:5091;user=phone>]
Mar 23 10:33:43 [2340] DBG:core:parse_headers: flags=100
Mar 23 10:33:43 [2340] DBG:core:get_hdr_field: cseq <CSeq>: <61> <ACK>
Mar 23 10:33:43 [2340] DBG:core:get_hdr_field: content_length=0
Mar 23 10:33:43 [2340] DBG:core:get_hdr_field: found end of header
Mar 23 10:33:43 [2340] DBG:maxfwd:is_maxfwd_present: max_forwards header not
found!
Mar 23 10:33:43 [2340] DBG:siputils:has_totag: totag found
Mar 23 10:33:43 [2340] DBG:core:parse_headers: flags=200
Mar 23 10:33:43 [2340] DBG:rr:find_first_route: No Route headers found
Mar 23 10:33:43 [2340] DBG:rr:loose_route: There is no Route HF
Mar 23 10:33:43 [2340] DBG:core:parse_headers: flags=78
Mar 23 10:33:43 [2340] DBG:tm:t_lookup_request: start searching: hash=43958,
isACK=1
Mar 23 10:33:43 [2340] DBG:tm:matching_3261: RFC3261 transaction matched,
tid=687870189
Mar 23 10:33:43 [2340] DBG:tm:t_lookup_request: REF_UNSAFE: after is 1
Mar 23 10:33:43 [2340] DBG:tm:t_lookup_request: transaction found
(T=0x7f35bdf67498)
Mar 23 10:33:43 [2340] DBG:tm:cleanup_uac_timers: RETR/FR timers reset
Mar 23 10:33:43 [2340] DBG:tm:insert_timer_unsafe: [2]: 0x7f35bdf67518 (2888)
Mar 23 10:33:43 [2340] DBG:tm:t_unref: UNREF_UNSAFE: after is 0
Mar 23 10:33:43 [2340] DBG:core:destroy_avp_list: destroying list (nil)
Mar 23 10:33:43 [2340] DBG:core:receive_msg: cleaning up
Mar 23 10:33:48 [2338] DBG:tm:timer_routine: timer routine:2,tl=0x7f35bdf67518
next=(nil), timeout=2888
Mar 23 10:33:48 [2338] DBG:tm:wait_handler: removing 0x7f35bdf67498 from table
Mar 23 10:33:48 [2338] DBG:tm:delete_cell: delete transaction 0x7f35bdf67498
Mar 23 10:33:48 [2338] DBG:tm:wait_handler: done
Mar 23 10:33:49 [2340] DBG:core:tcp_receive_timeout: 0x7f35bdf9d7f0 expired
(2888, 2889) lt=0
Mar 23 10:33:49 [2340] DBG:core:io_watch_del: io_watch_del (0x74efe0, 17, -1,
0x10) fd_no=2 called
Mar 23 10:33:49 [2340] DBG:core:release_tcpconn: releasing con 0x7f35bdf9d7f0,
state 0, fd=17, id=40
Mar 23 10:33:49 [2340] DBG:core:release_tcpconn: extra_data 0x7f35bdf59cc0
Mar 23 10:33:49 [2344] DBG:core:handle_tcp_child: reader response=
7f35bdf9d7f0, 0 from 0
Mar 23 10:33:49 [2344] DBG:core:io_watch_add: io_watch_add(0x74ee80, 23, 2,
0x7f35bdf9d7f0), fd_no=16
Mar 23 10:33:49 [2344] DBG:core:handle_tcp_child: cmd CONN_RELEASE
0x7f35bdf9d7f0 refcnt= 0
_______________________________________________
Kamailio (OpenSER) - Users mailing list
Users@lists.kamailio.org
http://lists.kamailio.org/cgi-bin/mailman/listinfo/users
http://lists.openser-project.org/cgi-bin/mailman/listinfo/users
