[SR-Users] Getting 404 From Kamailio for PRACK

Sun May 24 05:48:21 CEST 2015

Hi All
I am trying ti implement a IMS client. For testing I am using Kamailio
proxy.

During call setup, I get 404 for Prack message.
Whats going wrong not able to figure out.
Here is the Kamailio log below, can somebody help me too find whats wrong
her.

*11(25376) DEBUG: sl [sl.c:296]: send_reply(): reply in stateless mode
(sl)11(25376) DEBUG: <core> [msg_translator.c:206]: check_via_address():
check_via_address(192.168.1.195, 192.168.1.195, 0)11(25376) DEBUG: <core>
[tcp_main.c:2281]: tcpconn_send_put(): tcp_send: send from reader (25376
(11)), reusing fd11(25376) DEBUG: <core> [tcp_main.c:2516]:
tcpconn_do_send(): tcp_send: sending...11(25376) DEBUG: <core>
[tcp_main.c:2550]: tcpconn_do_send(): tcp_send: after real write: c=
0x7fe2ebd05390 n=386 fd=511(25376) DEBUG: <core> [tcp_main.c:2551]:
tcpconn_do_send(): tcp_send: buf=SIP/2.0 200 OKVia: SIP/2.0/TCP
192.168.1.195:40611;branch=z9hG4bK1186661565From:
<sip:linux_ua_1 at 192.168.1.195
<sip%3Alinux_ua_1 at 192.168.1.195>>;tag=1307796831To:
<sip:linux_ua_1 at 192.168.1.195
<sip%3Alinux_ua_1 at 192.168.1.195>>;tag=25fbdd2b0c9b93b0791296269f5ae411.38a0Call-ID:
835380265 at 192.168.1.195 <835380265 at 192.168.1.195>CSeq: 2 REGISTERContact:
<sip:linux_ua_1 at 192.168.1.195:40611;transport=tcp>;expires=3600Server:
kamailio (4.2.3 (x86_64/linux))Content-Length: 011(25376) DEBUG: <core>
[usr_avp.c:643]: destroy_avp_list(): DEBUG:destroy_avp_list: destroying
list (nil)11(25376) DEBUG: <core> [usr_avp.c:643]: destroy_avp_list():
DEBUG:destroy_avp_list: destroying list (nil)11(25376) DEBUG: <core>
[usr_avp.c:643]: destroy_avp_list(): DEBUG:destroy_avp_list: destroying
list (nil)11(25376) DEBUG: <core> [usr_avp.c:643]: destroy_avp_list():
DEBUG:destroy_avp_list: destroying list (nil)11(25376) DEBUG: <core>
[usr_avp.c:643]: destroy_avp_list(): DEBUG:destroy_avp_list: destroying
list (nil)11(25376) DEBUG: <core> [usr_avp.c:643]: destroy_avp_list():
DEBUG:destroy_avp_list: destroying list (nil)11(25376) DEBUG: <core>
[xavp.c:448]: xavp_destroy_list(): destroying xavp list (nil)11(25376)
DEBUG: <core> [receive.c:298]: receive_msg(): receive_msg: cleaning
up11(25376) DEBUG: <core> [io_wait.h:388]: io_watch_add(): DBG:
io_watch_add(0xa33180, 5, 2, 0x7fe2ebd05390), fd_no=111(25376) DEBUG:
<core> [tcp_read.c:1362]: tcp_read_req(): tcp_read_req: content-length=
011(25376) DEBUG: <core> [parser/msg_parser.c:623]: parse_msg(): SIP
Request:11(25376) DEBUG: <core> [parser/msg_parser.c:625]: parse_msg():
method:  <SUBSCRIBE>11(25376) DEBUG: <core> [parser/msg_parser.c:627]:
parse_msg():  uri:     <sip:linux_ua_1 at 192.168.1.195
<sip%3Alinux_ua_1 at 192.168.1.195>>11(25376) DEBUG: <core>
[parser/msg_parser.c:629]: parse_msg():  version: <SIP/2.0>11(25376) DEBUG:
<core> [parser/parse_via.c:1284]: parse_via_param(): Found param type 232,
<branch> = <z9hG4bK1577674881>; state=1611(25376) DEBUG: <core>
[parser/parse_via.c:2672]: parse_via(): end of header reached,
state=511(25376) DEBUG: <core> [parser/msg_parser.c:513]: parse_headers():
parse_headers: Via found, flags=211(25376) DEBUG: <core>
[parser/msg_parser.c:515]: parse_headers(): parse_headers: this is the
first via11(25376) DEBUG: <core> [receive.c:154]: receive_msg(): After
parse_msg...11(25376) DEBUG: <core> [receive.c:197]: receive_msg():
preparing to run routing scripts...11(25376) DEBUG: <core>
[parser/parse_addr_spec.c:898]: parse_addr_spec(): end of header reached,
state=1011(25376) DEBUG: <core> [parser/msg_parser.c:190]: get_hdr_field():
DEBUG: get_hdr_field: <To> [28]; uri=[sip:linux_ua_1 at 192.168.1.195
<sip%3Alinux_ua_1 at 192.168.1.195>] 11(25376) DEBUG: <core>
[parser/msg_parser.c:192]: get_hdr_field(): DEBUG: to body
[<sip:linux_ua_1 at 192.168.1.195 <sip%3Alinux_ua_1 at 192.168.1.195>>]11(25376)
DEBUG: <core> [parser/msg_parser.c:170]: get_hdr_field(): get_hdr_field:
cseq <CSeq>: <2> <SUBSCRIBE>11(25376) DEBUG: maxfwd [mf_funcs.c:85]:
is_maxfwd_present(): value = 70 11(25376) DEBUG: <core>
[parser/msg_parser.c:204]: get_hdr_field(): DEBUG: get_hdr_body :
content_length=011(25376) DEBUG: <core> [parser/msg_parser.c:106]:
get_hdr_field(): found end of header11(25376) DEBUG: <core>
[parser/parse_addr_spec.c:176]: parse_to_param(): DEBUG: add_param:
tag=133567903511(25376) DEBUG: <core> [parser/parse_addr_spec.c:898]:
parse_addr_spec(): end of header reached, state=2911(25376) DEBUG: sanity
[mod_sanity.c:255]: w_sanity_check(): sanity checks result: 111(25376)
DEBUG: siputils [checks.c:103]: has_totag(): no totag11(25376) DEBUG: tm
[t_lookup.c:1072]: t_check_msg(): DEBUG: t_check_msg: msg id=2 global id=1
T start=(nil)11(25376) DEBUG: tm [t_lookup.c:527]: t_lookup_request():
t_lookup_request: start searching: hash=34123, isACK=011(25376) DEBUG: tm
[t_lookup.c:485]: matching_3261(): DEBUG: RFC3261 transaction matching
failed11(25376) DEBUG: tm [t_lookup.c:709]: t_lookup_request(): DEBUG:
t_lookup_request: no transaction found11(25376) DEBUG: tm
[t_lookup.c:1141]: t_check_msg(): DEBUG: t_check_msg: msg id=2 global id=2
T end=(nil)11(25376) DEBUG: <core> [socket_info.c:583]: grep_sock_info():
grep_sock_info - checking if host==us: 13==13 && [192.168.1.195] ==
[192.168.1.195]11(25376) DEBUG: <core> [socket_info.c:587]:
grep_sock_info(): grep_sock_info - checking if port 4060 (advertise 0)
matches port 506011(25376) DEBUG: <core> [socket_info.c:583]:
grep_sock_info(): grep_sock_info - checking if host==us: 13==13 &&
[192.168.1.195] == [192.168.1.195]11(25376) DEBUG: <core>
[socket_info.c:587]: grep_sock_info(): grep_sock_info - checking if port
4060 (advertise 0) matches port 506011(25376) DEBUG: <core>
[socket_info.c:583]: grep_sock_info(): grep_sock_info - checking if
host==us: 13==13 && [192.168.1.195] == [192.168.1.195]11(25376) DEBUG:
<core> [socket_info.c:587]: grep_sock_info(): grep_sock_info - checking if
port 4090 (advertise 0) matches port 506011(25376) DEBUG: registrar
[lookup.c:203]: lookup_helper(): contact for [linux_ua_1] cannot handle the
SIP method11(25376) DEBUG: registrar [lookup.c:211]: lookup_helper():
'linux_ua_1' has no valid contact in usrloc11(25376) DEBUG: tm
[t_lookup.c:1373]: t_newtran(): DEBUG: t_newtran: msg id=2 , global msg
id=2 , T on entrance=(nil)11(25376) DEBUG: tm [t_lookup.c:527]:
t_lookup_request(): t_lookup_request: start searching: hash=34123,
isACK=011(25376) DEBUG: tm [t_lookup.c:485]: matching_3261(): DEBUG:
RFC3261 transaction matching failed11(25376) DEBUG: tm [t_lookup.c:709]:
t_lookup_request(): DEBUG: t_lookup_request: no transaction found11(25376)
DEBUG: tm [t_hooks.c:380]: run_reqin_callbacks_internal(): DBG:
trans=0x7fe2ebd10e68, callback type 1, id 0 entered11(25376) DEBUG: <core>
[md5utils.c:67]: MD5StringArray(): DEBUG: MD5 calculated:
c17c6f2bd5d60787072aef8ffcf5bfe611(25376) DEBUG: tm [t_lookup.c:1072]:
t_check_msg(): DEBUG: t_check_msg: msg id=2 global id=2 T
start=0x7fe2ebd10e6811(25376) DEBUG: tm [t_lookup.c:1144]: t_check_msg():
DEBUG: t_check_msg: T already found!11(25376) DEBUG: <core>
[msg_translator.c:206]: check_via_address():
check_via_address(192.168.1.195, 192.168.1.195, 0)11(25376) DEBUG: <core>
[mem/shm_mem.c:111]: _shm_resize(): WARNING:vqm_resize: resize(0)
called11(25376) DEBUG: tm [t_reply.c:1653]: cleanup_uac_timers(): DEBUG:
cleanup_uac_timers: RETR/FR timers reset11(25376) DEBUG: <core>
[tcp_main.c:2281]: tcpconn_send_put(): tcp_send: send from reader (25376
(11)), reusing fd11(25376) DEBUG: <core> [tcp_main.c:2516]:
tcpconn_do_send(): tcp_send: sending...11(25376) DEBUG: <core>
[tcp_main.c:2550]: tcpconn_do_send(): tcp_send: after real write: c=
0x7fe2ebd05390 n=334 fd=511(25376) DEBUG: <core> [tcp_main.c:2551]:
tcpconn_do_send(): tcp_send: buf=SIP/2.0 405 Method Not AllowedVia:
SIP/2.0/TCP 192.168.1.195:40611;branch=z9hG4bK1577674881From:
<sip:linux_ua_1 at 192.168.1.195
<sip%3Alinux_ua_1 at 192.168.1.195>>;tag=1335679035To:
<sip:linux_ua_1 at 192.168.1.195
<sip%3Alinux_ua_1 at 192.168.1.195>>;tag=ff272440259f71af2c767e7942717037-95d5Call-ID:
1397060040 at 192.168.1.195 <1397060040 at 192.168.1.195>CSeq: 2 SUBSCRIBEServer:
kamailio (4.2.3 (x86_64/linux))Content-Length: 011(25376) DEBUG: tm
[t_reply.c:728]: _reply_light(): DEBUG: reply sent out. buf=0x7fe30fea65c0:
SIP/2.0 405 Method N..., shmem=0x7fe2ebd135a8: SIP/2.0 405 Method
N11(25376) DEBUG: tm [t_reply.c:738]: _reply_light(): DEBUG: _reply_light:
finished11(25376) DEBUG: sl [sl.c:288]: send_reply(): reply in stateful
mode (tm)11(25376) DEBUG: <core> [usr_avp.c:643]: destroy_avp_list():
DEBUG:destroy_avp_list: destroying list (nil)11(25376) DEBUG: <core>
[usr_avp.c:643]: destroy_avp_list(): DEBUG:destroy_avp_list: destroying
list (nil)11(25376) DEBUG: <core> [usr_avp.c:643]: destroy_avp_list():
DEBUG:destroy_avp_list: destroying list (nil)11(25376) DEBUG: <core>
[usr_avp.c:643]: destroy_avp_list(): DEBUG:destroy_avp_list: destroying
list (nil)11(25376) DEBUG: <core> [usr_avp.c:643]: destroy_avp_list():
DEBUG:destroy_avp_list: destroying list (nil)11(25376) DEBUG: <core>
[usr_avp.c:643]: destroy_avp_list(): DEBUG:destroy_avp_list: destroying
list (nil)11(25376) DEBUG: <core> [xavp.c:448]: xavp_destroy_list():
destroying xavp list (nil)11(25376) DEBUG: <core> [receive.c:298]:
receive_msg(): receive_msg: cleaning up 9(25374) DEBUG: websocket
[ws_conn.c:459]: wsconn_get_list(): wsconn_get_list 9(25374) DEBUG:
websocket [ws_conn.c:503]: wsconn_get_list(): wsconn_get_list returns list
[(nil)] with [0] members10(25375) DEBUG: <core> [tcp_read.c:1362]:
tcp_read_req(): tcp_read_req: content-length= 35910(25375) DEBUG: <core>
[parser/msg_parser.c:623]: parse_msg(): SIP Request:10(25375) DEBUG: <core>
[parser/msg_parser.c:625]: parse_msg():  method:  <INVITE>10(25375) DEBUG:
<core> [parser/msg_parser.c:627]: parse_msg():  uri:
<sip:linux_ua_1 at 192.168.1.195 <sip%3Alinux_ua_1 at 192.168.1.195>>10(25375)
DEBUG: <core> [parser/msg_parser.c:629]: parse_msg():  version:
<SIP/2.0>10(25375) DEBUG: <core> [parser/parse_via.c:1284]:
parse_via_param(): Found param type 232, <branch> = <z9hG4bK1970975121>;
state=1610(25375) DEBUG: <core> [parser/parse_via.c:2672]: parse_via(): end
of header reached, state=510(25375) DEBUG: <core>
[parser/msg_parser.c:513]: parse_headers(): parse_headers: Via found,
flags=210(25375) DEBUG: <core> [parser/msg_parser.c:515]: parse_headers():
parse_headers: this is the first via10(25375) DEBUG: <core>
[receive.c:154]: receive_msg(): After parse_msg...10(25375) DEBUG: <core>
[receive.c:197]: receive_msg(): preparing to run routing
scripts...10(25375) DEBUG: <core> [parser/parse_addr_spec.c:898]:
parse_addr_spec(): end of header reached, state=1010(25375) DEBUG: <core>
[parser/msg_parser.c:190]: get_hdr_field(): DEBUG: get_hdr_field: <To>
[28]; uri=[sip:linux_ua_1 at 192.168.1.195 <sip%3Alinux_ua_1 at 192.168.1.195>]
10(25375) DEBUG: <core> [parser/msg_parser.c:192]: get_hdr_field(): DEBUG:
to body [<sip:linux_ua_1 at 192.168.1.195
<sip%3Alinux_ua_1 at 192.168.1.195>>]10(25375) DEBUG: <core>
[parser/msg_parser.c:170]: get_hdr_field(): get_hdr_field: cseq <CSeq>: <2>
<INVITE>10(25375) DEBUG: maxfwd [mf_funcs.c:85]: is_maxfwd_present(): value
= 70 10(25375) DEBUG: <core> [parser/msg_parser.c:204]: get_hdr_field():
DEBUG: get_hdr_body : content_length=35910(25375) DEBUG: <core>
[parser/msg_parser.c:106]: get_hdr_field(): found end of header10(25375)
DEBUG: <core> [parser/parse_addr_spec.c:176]: parse_to_param(): DEBUG:
add_param: tag=60426366410(25375) DEBUG: <core>
[parser/parse_addr_spec.c:898]: parse_addr_spec(): end of header reached,
state=2910(25375) DEBUG: sanity [mod_sanity.c:255]: w_sanity_check():
sanity checks result: 110(25375) DEBUG: siputils [checks.c:103]:
has_totag(): no totag10(25375) DEBUG: tm [t_lookup.c:1072]: t_check_msg():
DEBUG: t_check_msg: msg id=3 global id=2 T
start=0xffffffffffffffff10(25375) DEBUG: tm [t_lookup.c:527]:
t_lookup_request(): t_lookup_request: start searching: hash=12870,
isACK=010(25375) DEBUG: tm [t_lookup.c:485]: matching_3261(): DEBUG:
RFC3261 transaction matching failed10(25375) DEBUG: tm [t_lookup.c:709]:
t_lookup_request(): DEBUG: t_lookup_request: no transaction found10(25375)
DEBUG: tm [t_lookup.c:1141]: t_check_msg(): DEBUG: t_check_msg: msg id=3
global id=3 T end=(nil)10(25375) DEBUG: <core> [socket_info.c:583]:
grep_sock_info(): grep_sock_info - checking if host==us: 13==13 &&
[192.168.1.195] == [192.168.1.195]10(25375) DEBUG: <core>
[socket_info.c:587]: grep_sock_info(): grep_sock_info - checking if port
4060 (advertise 0) matches port 506010(25375) DEBUG: <core>
[socket_info.c:583]: grep_sock_info(): grep_sock_info - checking if
host==us: 13==13 && [192.168.1.195] == [192.168.1.195]10(25375) DEBUG:
<core> [socket_info.c:587]: grep_sock_info(): grep_sock_info - checking if
port 4060 (advertise 0) matches port 506010(25375) DEBUG: <core>
[socket_info.c:583]: grep_sock_info(): grep_sock_info - checking if
host==us: 13==13 && [192.168.1.195] == [192.168.1.195]10(25375) DEBUG:
<core> [socket_info.c:587]: grep_sock_info(): grep_sock_info - checking if
port 4090 (advertise 0) matches port 506010(25375) DEBUG: registrar
[lookup.c:198]: lookup_helper(): contact for [linux_ua_1] found by
address10(25375) DEBUG: tm [t_lookup.c:1373]: t_newtran(): DEBUG:
t_newtran: msg id=3 , global msg id=3 , T on entrance=(nil)10(25375) DEBUG:
tm [t_lookup.c:527]: t_lookup_request(): t_lookup_request: start searching:
hash=12870, isACK=010(25375) DEBUG: tm [t_lookup.c:485]: matching_3261():
DEBUG: RFC3261 transaction matching failed10(25375) DEBUG: tm
[t_lookup.c:709]: t_lookup_request(): DEBUG: t_lookup_request: no
transaction found10(25375) DEBUG: tm [t_hooks.c:380]:
run_reqin_callbacks_internal(): DBG: trans=0x7fe2ebd13848, callback type 1,
id 0 entered10(25375) DEBUG: <core> [md5utils.c:67]: MD5StringArray():
DEBUG: MD5 calculated: c4c3d26baa62dea619271f186d6344fc10(25375) DEBUG: tm
[t_funcs.c:347]: t_relay_to(): SER: new INVITE10(25375) DEBUG: <core>
[msg_translator.c:206]: check_via_address():
check_via_address(192.168.1.195, 192.168.1.195, 0)10(25375) DEBUG: <core>
[mem/shm_mem.c:111]: _shm_resize(): WARNING:vqm_resize: resize(0)
called10(25375) DEBUG: <core> [tcp_main.c:2281]: tcpconn_send_put():
tcp_send: send from reader (25375 (10)), reusing fd10(25375) DEBUG: <core>
[tcp_main.c:2516]: tcpconn_do_send(): tcp_send: sending...10(25375) DEBUG:
<core> [tcp_main.c:2550]: tcpconn_do_send(): tcp_send: after real write: c=
0x7fe2ebd096b0 n=307 fd=510(25375) DEBUG: <core> [tcp_main.c:2551]:
tcpconn_do_send(): tcp_send: buf=SIP/2.0 100 trying -- your call is
important to usVia: SIP/2.0/TCP
192.168.1.195:19009;branch=z9hG4bK1970975121From:
<sip:linux_ua_0 at 192.168.1.195
<sip%3Alinux_ua_0 at 192.168.1.195>>;tag=604263664To:
<sip:linux_ua_1 at 192.168.1.195 <sip%3Alinux_ua_1 at 192.168.1.195>>Call-ID:
734015646 at 192.168.1.195 <734015646 at 192.168.1.195>CSeq: 2 INVITEServer:
kamailio (4.2.3 (x86_64/linux))Content-Length: 010(25375) DEBUG: tm
[t_reply.c:728]: _reply_light(): DEBUG: reply sent out. buf=0x7fe30fea6968:
SIP/2.0 100 trying -..., shmem=0x7fe2ebd163f0: SIP/2.0 100 trying
-10(25375) DEBUG: tm [t_reply.c:738]: _reply_light(): DEBUG: _reply_light:
finished10(25375) DEBUG: <script>: new branch [0] to
sip:linux_ua_1 at 192.168.1.195:40611;transport=tcp10(25375) DEBUG: <core>
[msg_translator.c:2893]: create_via_hf(): create_via_hf: id added: <;i=2>,
rcv proto=210(25375) DEBUG: <core> [msg_translator.c:206]:
check_via_address(): check_via_address(192.168.1.195, 192.168.1.195,
0)10(25375) DEBUG: <core> [tcp_main.c:1818]: tcp_send(): tcp_send: no open
tcp connection found, opening new one10(25375) DEBUG: <core>
[ip_addr.c:243]: print_ip(): tcpconn_new: new tcp connection:
192.168.1.19510(25375) DEBUG: <core> [tcp_main.c:1073]: tcpconn_new():
tcpconn_new: on port 40611, type 210(25375) DEBUG: <core>
[tcp_main.c:1382]: tcpconn_add(): tcpconn_add: hashes: 3453:3998:0,
310(25375) INFO: <core> [tcp_main.c:2753]: tcpconn_1st_send(): quick
connect for 0x7fe2ebd1703010(25375) DEBUG: tm [t_funcs.c:394]:
t_relay_to(): SER: new transaction fwd'ed10(25375) DEBUG: <core>
[usr_avp.c:643]: destroy_avp_list(): DEBUG:destroy_avp_list: destroying
list (nil)10(25375) DEBUG: <core> [usr_avp.c:643]: destroy_avp_list():
DEBUG:destroy_avp_list: destroying list (nil)14(25379) DEBUG: <core>
[tcp_main.c:3565]: handle_ser_child(): handle_ser_child: read response=
7fe2ebd17030, 6, fd 28 from 10 (25375)10(25375) DEBUG: <core>
[usr_avp.c:643]: destroy_avp_list(): DEBUG:destroy_avp_list: destroying
list (nil)10(25375) DEBUG: <core> [usr_avp.c:643]: destroy_avp_list():
DEBUG:destroy_avp_list: destroying list (nil)10(25375) DEBUG: <core>
[usr_avp.c:643]: destroy_avp_list(): DEBUG:destroy_avp_list: destroying
list (nil)10(25375) DEBUG: <core> [usr_avp.c:643]: destroy_avp_list():
DEBUG:destroy_avp_list: destroying list (nil)10(25375) DEBUG: <core>
[xavp.c:448]: xavp_destroy_list(): destroying xavp list (nil)14(25379)
DEBUG: <core> [io_wait.h:388]: io_watch_add(): DBG: io_watch_add(0x9eeee0,
28, 2, 0x7fe2ebd17030), fd_no=1910(25375) DEBUG: <core> [receive.c:298]:
receive_msg(): receive_msg: cleaning up14(25379) DEBUG: <core>
[io_wait.h:610]: io_watch_del(): DBG: io_watch_del (0x9eeee0, 28, -1, 0x0)
fd_no=20 called14(25379) DEBUG: <core> [tcp_main.c:4219]:
handle_tcpconn_ev(): tcp: DBG: sending to child, events 114(25379) DEBUG:
<core> [tcp_main.c:3902]: send2child(): selected tcp worker 2 12(25377) for
activity on [tcp:192.168.1.195:4060 <http://192.168.1.195:4060>],
0x7fe2ebd1703012(25377) DEBUG: <core> [tcp_read.c:1554]: handle_io():
received n=8 con=0x7fe2ebd17030, fd=512(25377) DEBUG: <core>
[tcp_read.c:1362]: tcp_read_req(): tcp_read_req: content-length=
38812(25377) DEBUG: <core> [parser/msg_parser.c:633]: parse_msg(): SIP
Reply  (status):12(25377) DEBUG: <core> [parser/msg_parser.c:635]:
parse_msg():  version: <SIP/2.0>12(25377) DEBUG: <core>
[parser/msg_parser.c:637]: parse_msg():  status:  <183>12(25377) DEBUG:
<core> [parser/msg_parser.c:639]: parse_msg():  reason:  <Session
Progress>12(25377) DEBUG: <core> [parser/parse_via.c:1284]:
parse_via_param(): Found param type 232, <branch> =
<z9hG4bK6423.c4c3d26baa62dea619271f186d6344fc.0>; state=612(25377) DEBUG:
<core> [parser/parse_via.c:1284]: parse_via_param(): Found param type 236,
<i> = <2>; state=1612(25377) DEBUG: <core> [parser/parse_via.c:2672]:
parse_via(): end of header reached, state=512(25377) DEBUG: <core>
[parser/msg_parser.c:513]: parse_headers(): parse_headers: Via found,
flags=212(25377) DEBUG: <core> [parser/msg_parser.c:515]: parse_headers():
parse_headers: this is the first via12(25377) DEBUG: <core>
[receive.c:154]: receive_msg(): After parse_msg...12(25377) DEBUG: tm
[t_lookup.c:1072]: t_check_msg(): DEBUG: t_check_msg: msg id=1 global id=0
T start=0xffffffffffffffff12(25377) DEBUG: <core>
[parser/parse_via.c:1284]: parse_via_param(): Found param type 232,
<branch> = <z9hG4bK1970975121>; state=1612(25377) DEBUG: <core>
[parser/parse_via.c:2672]: parse_via(): end of header reached,
state=512(25377) DEBUG: <core> [parser/msg_parser.c:513]: parse_headers():
parse_headers: Via found, flags=6212(25377) DEBUG: <core>
[parser/msg_parser.c:526]: parse_headers(): parse_headers: this is the
second via12(25377) DEBUG: <core> [parser/parse_addr_spec.c:176]:
parse_to_param(): DEBUG: add_param: tag=165643220412(25377) DEBUG: <core>
[parser/parse_addr_spec.c:898]: parse_addr_spec(): end of header reached,
state=2912(25377) DEBUG: <core> [parser/msg_parser.c:190]: get_hdr_field():
DEBUG: get_hdr_field: <To> [43]; uri=[sip:linux_ua_1 at 192.168.1.195
<sip%3Alinux_ua_1 at 192.168.1.195>] 12(25377) DEBUG: <core>
[parser/msg_parser.c:192]: get_hdr_field(): DEBUG: to body
[<sip:linux_ua_1 at 192.168.1.195 <sip%3Alinux_ua_1 at 192.168.1.195>>]12(25377)
DEBUG: <core> [parser/msg_parser.c:170]: get_hdr_field(): get_hdr_field:
cseq <CSeq>: <2> <INVITE>12(25377) DEBUG: tm [t_lookup.c:949]:
t_reply_matching(): DEBUG: t_reply_matching: hash 12870 label 0 branch
012(25377) DEBUG: tm [t_lookup.c:1004]: t_reply_matching(): DEBUG:
t_reply_matching: reply matched (T=0x7fe2ebd13848)!12(25377) DEBUG: tm
[t_hooks.c:288]: run_trans_callbacks_internal(): DBG: trans=0x7fe2ebd13848,
callback type 2, id 0 entered12(25377) DEBUG: acc [acc_logic.c:644]:
tmcb_func(): acc callback called for t(0x7fe2ebd13848) event type 2, reply
code 18312(25377) DEBUG: tm [t_lookup.c:1141]: t_check_msg(): DEBUG:
t_check_msg: msg id=1 global id=1 T end=0x7fe2ebd1384812(25377) DEBUG: tm
[t_reply.c:2200]: reply_received(): DEBUG: reply_received: org. status
uas=100, uac[0]=0 local=0 is_invite=1)12(25377) DEBUG: <script>: incoming
reply12(25377) DEBUG: tm [t_reply.c:1294]: t_should_relay_response():
->>>>>>>>> T_code=100, new_code=18312(25377) DEBUG: tm [t_reply.c:1812]:
relay_reply(): DEBUG: relay_reply: branch=0, save=0, relay=0
icode=012(25377) DEBUG: <core> [parser/msg_parser.c:204]: get_hdr_field():
DEBUG: get_hdr_body : content_length=38812(25377) DEBUG: <core>
[parser/msg_parser.c:106]: get_hdr_field(): found end of header12(25377)
DEBUG: <core> [msg_translator.c:2278]: generate_res_buf_from_sip_res():
old size: 948, new size: 85312(25377) DEBUG: <core>
[msg_translator.c:2296]: generate_res_buf_from_sip_res(): copied size:
orig:125, new: 30, rest: 823 msg=SIP/2.0 183 Session ProgressVia:
SIP/2.0/TCP 192.168.1.195:19009;branch=z9hG4bK1970975121Record-Route:
<sip:192.168.1.195:4060;transport=tcp;lr>From:
<sip:linux_ua_0 at 192.168.1.195
<sip%3Alinux_ua_0 at 192.168.1.195>>;tag=604263664To:
<sip:linux_ua_1 at 192.168.1.195
<sip%3Alinux_ua_1 at 192.168.1.195>>;tag=1656432204Call-ID:
734015646 at 192.168.1.195 <734015646 at 192.168.1.195>CSeq: 2 INVITEContact:
<sip:linux_ua_1 at 192.168.1.195:40611;transport=TCP>Content-Type:
application/sdpUser-Agent: Linux 64 US-UA 1.0.1Require: 100relRSeq:
1Content-Length:   388v=0o=- 0 0 IN IP4 192.168.1.195s=IMS_Callc=IN IP4
192.168.1.195t=0 0m=audio 21720 RTP/AVP 99 0 8 101 b=AS:64a=curr:qos remote
nonea=curr:qos local nonea=des:qos mandatory remote sendrecva=conf:qos
remote sendrecva=des:qos mandatory local sendrecva=rtpmap:101
telephone-event/8000a=fmtp:101 0-15a=rtpmap:99 AMR/8000a=rtpmap:0
PCMU/8000a=rtpmap:8 PCMA/800012(25377) DEBUG: <core> [tcp_main.c:2297]:
tcpconn_send_put(): tcp_send: tcp connection found (0x7fe2ebd096b0),
acquiring fd12(25377) DEBUG: <core> [tcp_main.c:2307]: tcpconn_send_put():
tcp_send, c= 0x7fe2ebd096b0, n=1614(25379) DEBUG: <core> [tcp_main.c:3565]:
handle_ser_child(): handle_ser_child: read response= 7fe2ebd096b0, 2, fd -1
from 12 (25377)12(25377) DEBUG: <core> [tcp_main.c:2337]:
tcpconn_send_put(): tcp_send: after receive_fd: c= 0x7fe2ebd096b0 n=8
fd=812(25377) DEBUG: <core> [tcp_main.c:2516]: tcpconn_do_send(): tcp_send:
sending...12(25377) DEBUG: <core> [tcp_main.c:2550]: tcpconn_do_send():
tcp_send: after real write: c= 0x7fe2ebd096b0 n=853 fd=812(25377) DEBUG:
<core> [tcp_main.c:2551]: tcpconn_do_send(): tcp_send: buf=SIP/2.0 183
Session ProgressVia: SIP/2.0/TCP
192.168.1.195:19009;branch=z9hG4bK1970975121Record-Route:
<sip:192.168.1.195:4060;transport=tcp;lr>From:
<sip:linux_ua_0 at 192.168.1.195
<sip%3Alinux_ua_0 at 192.168.1.195>>;tag=604263664To:
<sip:linux_ua_1 at 192.168.1.195
<sip%3Alinux_ua_1 at 192.168.1.195>>;tag=1656432204Call-ID:
734015646 at 192.168.1.195 <734015646 at 192.168.1.195>CSeq: 2 INVITEContact:
<sip:linux_ua_1 at 192.168.1.195:40611;transport=TCP>Content-Type:
application/sdpUser-Agent: Linux 64 US-UA 1.0.1Require: 100relRSeq:
1Content-Length:   388v=0o=- 0 0 IN IP4 192.168.1.195s=IMS_Callc=IN IP4
192.168.1.195t=0 0m=audio 21720 RTP/AVP 99 0 8 101 b=AS:64a=curr:qos remote
nonea=curr:qos local nonea=des:qos mandatory remote sendrecva=conf:qos
remote sendrecva=des:qos mandatory local sendrecva=rtpmap:101
telephone-event/8000a=fmtp:101 0-15a=rtpmap:99 AMR/8000a=rtpmap:0
PCMU/8000a=rtpmap:8 PCMA/800012(25377) DEBUG: tm [t_hooks.c:288]:
run_trans_callbacks_internal(): DBG: trans=0x7fe2ebd13848, callback type
512, id 0 entered12(25377) DEBUG: acc [acc_logic.c:644]: tmcb_func(): acc
callback called for t(0x7fe2ebd13848) event type 512, reply code
18312(25377) DEBUG: <core> [usr_avp.c:643]: destroy_avp_list():
DEBUG:destroy_avp_list: destroying list (nil)12(25377) DEBUG: <core>
[usr_avp.c:643]: destroy_avp_list(): DEBUG:destroy_avp_list: destroying
list (nil)12(25377) DEBUG: <core> [usr_avp.c:643]: destroy_avp_list():
DEBUG:destroy_avp_list: destroying list (nil)12(25377) DEBUG: <core>
[usr_avp.c:643]: destroy_avp_list(): DEBUG:destroy_avp_list: destroying
list (nil)12(25377) DEBUG: <core> [usr_avp.c:643]: destroy_avp_list():
DEBUG:destroy_avp_list: destroying list (nil)12(25377) DEBUG: <core>
[usr_avp.c:643]: destroy_avp_list(): DEBUG:destroy_avp_list: destroying
list (nil)12(25377) DEBUG: <core> [xavp.c:448]: xavp_destroy_list():
destroying xavp list (nil)12(25377) DEBUG: <core> [receive.c:298]:
receive_msg(): receive_msg: cleaning up12(25377) DEBUG: <core>
[io_wait.h:388]: io_watch_add(): DBG: io_watch_add(0xa33180, 5, 2,
0x7fe2ebd17030), fd_no=110(25375) DEBUG: <core> [tcp_read.c:1362]:
tcp_read_req(): tcp_read_req: content-length= 39210(25375) DEBUG: <core>
[parser/msg_parser.c:623]: parse_msg(): SIP Request:10(25375) DEBUG: <core>
[parser/msg_parser.c:625]: parse_msg():  method:  <PRACK>10(25375) DEBUG:
<core> [parser/msg_parser.c:627]: parse_msg():  uri:
<sip:linux_ua_1 at 192.168.1.195:40611;transport=TCP>10(25375) DEBUG: <core>
[parser/msg_parser.c:629]: parse_msg():  version: <SIP/2.0>10(25375) DEBUG:
<core> [parser/parse_via.c:1284]: parse_via_param(): Found param type 232,
<branch> = <z9hG4bK1576634775>; state=1610(25375) DEBUG: <core>
[parser/parse_via.c:2672]: parse_via(): end of header reached,
state=510(25375) DEBUG: <core> [parser/msg_parser.c:513]: parse_headers():
parse_headers: Via found, flags=210(25375) DEBUG: <core>
[parser/msg_parser.c:515]: parse_headers(): parse_headers: this is the
first via10(25375) DEBUG: <core> [receive.c:154]: receive_msg(): After
parse_msg...10(25375) DEBUG: <core> [receive.c:197]: receive_msg():
preparing to run routing scripts...10(25375) DEBUG: <core>
[parser/parse_addr_spec.c:176]: parse_to_param(): DEBUG: add_param:
tag=165643220410(25375) DEBUG: <core> [parser/parse_addr_spec.c:898]:
parse_addr_spec(): end of header reached, state=2910(25375) DEBUG: <core>
[parser/msg_parser.c:190]: get_hdr_field(): DEBUG: get_hdr_field: <To>
[43]; uri=[sip:linux_ua_1 at 192.168.1.195 <sip%3Alinux_ua_1 at 192.168.1.195>]
10(25375) DEBUG: <core> [parser/msg_parser.c:192]: get_hdr_field(): DEBUG:
to body [<sip:linux_ua_1 at 192.168.1.195
<sip%3Alinux_ua_1 at 192.168.1.195>>]10(25375) DEBUG: <core>
[parser/msg_parser.c:170]: get_hdr_field(): get_hdr_field: cseq <CSeq>: <3>
<PRACK>10(25375) DEBUG: maxfwd [mf_funcs.c:85]: is_maxfwd_present(): value
= 70 10(25375) DEBUG: <core> [parser/msg_parser.c:204]: get_hdr_field():
DEBUG: get_hdr_body : content_length=39210(25375) DEBUG: <core>
[parser/msg_parser.c:106]: get_hdr_field(): found end of header10(25375)
DEBUG: <core> [parser/parse_addr_spec.c:176]: parse_to_param(): DEBUG:
add_param: tag=60426366410(25375) DEBUG: <core>
[parser/parse_addr_spec.c:898]: parse_addr_spec(): end of header reached,
state=2910(25375) DEBUG: sanity [mod_sanity.c:255]: w_sanity_check():
sanity checks result: 110(25375) DEBUG: siputils [checks.c:106]:
has_totag(): totag found10(25375) DEBUG: rr [loose.c:90]: is_preloaded():
is_preloaded: No10(25375) DEBUG: <core> [socket_info.c:583]:
grep_sock_info(): grep_sock_info - checking if host==us: 13==13 &&
[192.168.1.195] == [192.168.1.195]10(25375) DEBUG: <core>
[socket_info.c:587]: grep_sock_info(): grep_sock_info - checking if port
4060 (advertise 0) matches port 4061110(25375) DEBUG: <core>
[socket_info.c:583]: grep_sock_info(): grep_sock_info - checking if
host==us: 13==13 && [192.168.1.195] == [192.168.1.195]10(25375) DEBUG:
<core> [socket_info.c:587]: grep_sock_info(): grep_sock_info - checking if
port 4060 (advertise 0) matches port 4061110(25375) DEBUG: <core>
[socket_info.c:583]: grep_sock_info(): grep_sock_info - checking if
host==us: 13==13 && [192.168.1.195] == [192.168.1.195]10(25375) DEBUG:
<core> [socket_info.c:587]: grep_sock_info(): grep_sock_info - checking if
port 4090 (advertise 0) matches port 4061110(25375) DEBUG: rr
[loose.c:674]: after_strict(): Next hop:
'sip:192.168.1.195:4060;transport=tcp;lr' is loose router10(25375) DEBUG:
rr [loose.c:724]: after_strict(): The last route URI:
'sip:192.168.1.195:4060;transport=tcp;lr'10(25375) DEBUG: tm
[t_lookup.c:1373]: t_newtran(): DEBUG: t_newtran: msg id=4 , global msg
id=3 , T on entrance=0xffffffffffffffff10(25375) DEBUG: tm
[t_lookup.c:527]: t_lookup_request(): t_lookup_request: start searching:
hash=12871, isACK=010(25375) DEBUG: tm [t_lookup.c:485]: matching_3261():
DEBUG: RFC3261 transaction matching failed10(25375) DEBUG: tm
[t_lookup.c:709]: t_lookup_request(): DEBUG: t_lookup_request: no
transaction found10(25375) DEBUG: tm [t_hooks.c:380]:
run_reqin_callbacks_internal(): DBG: trans=0x7fe2ebd1b780, callback type 1,
id 0 entered10(25375) DEBUG: <core> [md5utils.c:67]: MD5StringArray():
DEBUG: MD5 calculated: 0dd1edaf37f3874c5176befe76ed5b3e10(25375) DEBUG:
<core> [msg_translator.c:2893]: create_via_hf(): create_via_hf: id added:
<;i=2>, rcv proto=210(25375) DEBUG: <core> [msg_translator.c:206]:
check_via_address(): check_via_address(192.168.1.195, 192.168.1.195,
0)10(25375) DEBUG: <core> [tcp_main.c:1818]: tcp_send(): tcp_send: no open
tcp connection found, opening new one10(25375) DEBUG: <core>
[ip_addr.c:243]: print_ip(): tcpconn_new: new tcp connection:
192.168.1.19510(25375) DEBUG: <core> [tcp_main.c:1073]: tcpconn_new():
tcpconn_new: on port 4060, type 210(25375) DEBUG: <core> [tcp_main.c:1382]:
tcpconn_add(): tcpconn_add: hashes: 3360:0:0, 410(25375) INFO: <core>
[tcp_main.c:2753]: tcpconn_1st_send(): quick connect for
0x7fe2ebd1e5c010(25375) DEBUG: tm [t_funcs.c:394]: t_relay_to(): SER: new
transaction fwd'ed14(25379) DEBUG: <core> [ip_addr.c:243]: print_ip():
tcpconn_new: new tcp connection: 192.168.1.19510(25375) DEBUG: <core>
[usr_avp.c:643]: destroy_avp_list(): DEBUG:destroy_avp_list: destroying
list (nil)14(25379) DEBUG: <core> [tcp_main.c:1073]: tcpconn_new():
tcpconn_new: on port 19785, type 210(25375) DEBUG: <core> [usr_avp.c:643]:
destroy_avp_list(): DEBUG:destroy_avp_list: destroying list (nil)10(25375)
DEBUG: <core> [usr_avp.c:643]: destroy_avp_list(): DEBUG:destroy_avp_list:
destroying list (nil)10(25375) DEBUG: <core> [usr_avp.c:643]:
destroy_avp_list(): DEBUG:destroy_avp_list: destroying list (nil)14(25379)
DEBUG: <core> [tcp_main.c:1382]: tcpconn_add(): tcpconn_add: hashes:
3888:3539:528, 510(25375) DEBUG: <core> [usr_avp.c:643]:
destroy_avp_list(): DEBUG:destroy_avp_list: destroying list (nil)10(25375)
DEBUG: <core> [usr_avp.c:643]: destroy_avp_list(): DEBUG:destroy_avp_list:
destroying list (nil)10(25375) DEBUG: <core> [xavp.c:448]:
xavp_destroy_list(): destroying xavp list (nil)10(25375) DEBUG: <core>
[receive.c:298]: receive_msg(): receive_msg: cleaning up14(25379) DEBUG:
<core> [io_wait.h:388]: io_watch_add(): DBG: io_watch_add(0x9eeee0, 29, 2,
0x7fe2ebd228e0), fd_no=1914(25379) DEBUG: <core> [tcp_main.c:3565]:
handle_ser_child(): handle_ser_child: read response= 7fe2ebd1e5c0, 6, fd 30
from 10 (25375)14(25379) DEBUG: <core> [io_wait.h:388]: io_watch_add():
DBG: io_watch_add(0x9eeee0, 30, 2, 0x7fe2ebd1e5c0), fd_no=2014(25379)
DEBUG: <core> [io_wait.h:610]: io_watch_del(): DBG: io_watch_del (0x9eeee0,
29, -1, 0x0) fd_no=21 called14(25379) DEBUG: <core> [tcp_main.c:4219]:
handle_tcpconn_ev(): tcp: DBG: sending to child, events 114(25379) DEBUG:
<core> [tcp_main.c:3902]: send2child(): selected tcp worker 3 13(25378) for
activity on [tcp:192.168.1.195:4060 <http://192.168.1.195:4060>],
0x7fe2ebd228e013(25378) DEBUG: <core> [tcp_read.c:1554]: handle_io():
received n=8 con=0x7fe2ebd228e0, fd=513(25378) DEBUG: <core>
[tcp_read.c:1362]: tcp_read_req(): tcp_read_req: content-length=
39213(25378) DEBUG: <core> [parser/msg_parser.c:623]: parse_msg(): SIP
Request:13(25378) DEBUG: <core> [parser/msg_parser.c:625]: parse_msg():
method:  <PRACK>13(25378) DEBUG: <core> [parser/msg_parser.c:627]:
parse_msg():  uri:     <sip:192.168.1.195:4060;transport=tcp;lr>13(25378)
DEBUG: <core> [parser/msg_parser.c:629]: parse_msg():  version:
<SIP/2.0>13(25378) DEBUG: <core> [parser/parse_via.c:1284]:
parse_via_param(): Found param type 232, <branch> =
<z9hG4bK7423.0dd1edaf37f3874c5176befe76ed5b3e.0>; state=613(25378) DEBUG:
<core> [parser/parse_via.c:1284]: parse_via_param(): Found param type 236,
<i> = <2>; state=1613(25378) DEBUG: <core> [parser/parse_via.c:2672]:
parse_via(): end of header reached, state=513(25378) DEBUG: <core>
[parser/msg_parser.c:513]: parse_headers(): parse_headers: Via found,
flags=213(25378) DEBUG: <core> [parser/msg_parser.c:515]: parse_headers():
parse_headers: this is the first via13(25378) DEBUG: <core>
[receive.c:154]: receive_msg(): After parse_msg...13(25378) DEBUG: <core>
[receive.c:197]: receive_msg(): preparing to run routing
scripts...13(25378) DEBUG: <core> [parser/parse_via.c:1284]:
parse_via_param(): Found param type 232, <branch> = <z9hG4bK1576634775>;
state=1613(25378) DEBUG: <core> [parser/parse_via.c:2672]: parse_via(): end
of header reached, state=513(25378) DEBUG: <core>
[parser/msg_parser.c:513]: parse_headers(): parse_headers: Via found,
flags=10013(25378) DEBUG: <core> [parser/msg_parser.c:526]:
parse_headers(): parse_headers: this is the second via13(25378) DEBUG:
<core> [parser/parse_addr_spec.c:176]: parse_to_param(): DEBUG: add_param:
tag=165643220413(25378) DEBUG: <core> [parser/parse_addr_spec.c:898]:
parse_addr_spec(): end of header reached, state=2913(25378) DEBUG: <core>
[parser/msg_parser.c:190]: get_hdr_field(): DEBUG: get_hdr_field: <To>
[43]; uri=[sip:linux_ua_1 at 192.168.1.195 <sip%3Alinux_ua_1 at 192.168.1.195>]
13(25378) DEBUG: <core> [parser/msg_parser.c:192]: get_hdr_field(): DEBUG:
to body [<sip:linux_ua_1 at 192.168.1.195
<sip%3Alinux_ua_1 at 192.168.1.195>>]13(25378) DEBUG: <core>
[parser/msg_parser.c:170]: get_hdr_field(): get_hdr_field: cseq <CSeq>: <3>
<PRACK>13(25378) DEBUG: maxfwd [mf_funcs.c:85]: is_maxfwd_present(): value
= 69 13(25378) DEBUG: <core> [parser/msg_parser.c:204]: get_hdr_field():
DEBUG: get_hdr_body : content_length=39213(25378) DEBUG: <core>
[parser/msg_parser.c:106]: get_hdr_field(): found end of header13(25378)
DEBUG: <core> [parser/parse_addr_spec.c:176]: parse_to_param(): DEBUG:
add_param: tag=60426366413(25378) DEBUG: <core>
[parser/parse_addr_spec.c:898]: parse_addr_spec(): end of header reached,
state=2913(25378) DEBUG: sanity [mod_sanity.c:255]: w_sanity_check():
sanity checks result: 113(25378) DEBUG: siputils [checks.c:106]:
has_totag(): totag found13(25378) DEBUG: rr [loose.c:113]:
find_first_route(): No Route headers found13(25378) DEBUG: rr
[loose.c:929]: loose_route(): There is no Route HF13(25378) DEBUG: <core>
[msg_translator.c:206]: check_via_address():
check_via_address(192.168.1.195, 192.168.1.195, 0)13(25378) DEBUG: <core>
[tcp_main.c:2281]: tcpconn_send_put(): tcp_send: send from reader (25378
(13)), reusing fd13(25378) DEBUG: <core> [tcp_main.c:2516]:
tcpconn_do_send(): tcp_send: sending...13(25378) DEBUG: <core>
[tcp_main.c:2550]: tcpconn_do_send(): tcp_send: after real write: c=
0x7fe2ebd228e0 n=386 fd=514(25379) DEBUG: <core> [io_wait.h:610]:
io_watch_del(): DBG: io_watch_del (0x9eeee0, 30, -1, 0x0) fd_no=20
called13(25378) DEBUG: <core> [tcp_main.c:2551]: tcpconn_do_send():
tcp_send: buf=SIP/2.0 404 Not hereVia: SIP/2.0/TCP
192.168.1.195:4060;branch=z9hG4bK7423.0dd1edaf37f3874c5176befe76ed5b3e.0;i=2Via:
SIP/2.0/TCP 192.168.1.195:19009;branch=z9hG4bK1576634775From:
<sip:linux_ua_0 at 192.168.1.195
<sip%3Alinux_ua_0 at 192.168.1.195>>;tag=604263664To:
<sip:linux_ua_1 at 192.168.1.195
<sip%3Alinux_ua_1 at 192.168.1.195>>;tag=1656432204Call-ID:
734015646 at 192.168.1.195 <734015646 at 192.168.1.195>CSeq: 3 PRACKServer:
kamailio (4.2.3 (x86_64/linux))Content-Length: 014(25379) DEBUG: <core>
[tcp_main.c:4219]: handle_tcpconn_ev(): tcp: DBG: sending to child, events
114(25379) DEBUG: <core> [tcp_main.c:3898]: send2child(): WARNING:
send2child: no free tcp receiver,  connection passed to the least busy one
(1)14(25379) DEBUG: <core> [tcp_main.c:3902]: send2child(): selected tcp
worker 0 10(25375) for activity on [tcp:192.168.1.195:4060
<http://192.168.1.195:4060>], 0x7fe2ebd1e5c013(25378) DEBUG: <core>
[usr_avp.c:643]: destroy_avp_list(): DEBUG:destroy_avp_list: destroying
list (nil)13(25378) DEBUG: <core> [usr_avp.c:643]: destroy_avp_list():
DEBUG:destroy_avp_list: destroying list (nil)10(25375) DEBUG: <core>
[tcp_read.c:1554]: handle_io(): received n=8 con=0x7fe2ebd1e5c0,
fd=1013(25378) DEBUG: <core> [usr_avp.c:643]: destroy_avp_list():
DEBUG:destroy_avp_list: destroying list (nil)13(25378) DEBUG: <core>
[usr_avp.c:643]: destroy_avp_list(): DEBUG:destroy_avp_list: destroying
list (nil)13(25378) DEBUG: <core> [usr_avp.c:643]: destroy_avp_list():
DEBUG:destroy_avp_list: destroying list (nil)13(25378) DEBUG: <core>
[usr_avp.c:643]: destroy_avp_list(): DEBUG:destroy_avp_list: destroying
list (nil)10(25375) DEBUG: <core> [tcp_read.c:1362]: tcp_read_req():
tcp_read_req: content-length= 013(25378) DEBUG: <core> [xavp.c:448]:
xavp_destroy_list(): destroying xavp list (nil)10(25375) DEBUG: <core>
[parser/msg_parser.c:633]: parse_msg(): SIP Reply  (status):13(25378)
DEBUG: <core> [receive.c:298]: receive_msg(): receive_msg: cleaning
up10(25375) DEBUG: <core> [parser/msg_parser.c:635]: parse_msg():  version:
<SIP/2.0>10(25375) DEBUG: <core> [parser/msg_parser.c:637]: parse_msg():
status:  <404>10(25375) DEBUG: <core> [parser/msg_parser.c:639]:
parse_msg():  reason:  <Not here>10(25375) DEBUG: <core>
[parser/parse_via.c:1284]: parse_via_param(): Found param type 232,
<branch> = <z9hG4bK7423.0dd1edaf37f3874c5176befe76ed5b3e.0>;
state=613(25378) DEBUG: <core> [io_wait.h:388]: io_watch_add(): DBG:
io_watch_add(0xa33180, 5, 2, 0x7fe2ebd228e0), fd_no=110(25375) DEBUG:
<core> [parser/parse_via.c:1284]: parse_via_param(): Found param type 236,
<i> = <2>; state=1610(25375) DEBUG: <core> [parser/parse_via.c:2672]:
parse_via(): end of header reached, state=510(25375) DEBUG: <core>
[parser/msg_parser.c:513]: parse_headers(): parse_headers: Via found,
flags=210(25375) DEBUG: <core> [parser/msg_parser.c:515]: parse_headers():
parse_headers: this is the first via10(25375) DEBUG: <core>
[receive.c:154]: receive_msg(): After parse_msg...10(25375) DEBUG: tm
[t_lookup.c:1072]: t_check_msg(): DEBUG: t_check_msg: msg id=5 global id=4
T start=0xffffffffffffffff10(25375) DEBUG: <core>
[parser/parse_via.c:1284]: parse_via_param(): Found param type 232,
<branch> = <z9hG4bK1576634775>; state=1610(25375) DEBUG: <core>
[parser/parse_via.c:2672]: parse_via(): end of header reached,
state=510(25375) DEBUG: <core> [parser/msg_parser.c:513]: parse_headers():
parse_headers: Via found, flags=6210(25375) DEBUG: <core>
[parser/msg_parser.c:526]: parse_headers(): parse_headers: this is the
second via10(25375) DEBUG: <core> [parser/parse_addr_spec.c:176]:
parse_to_param(): DEBUG: add_param: tag=165643220410(25375) DEBUG: <core>
[parser/parse_addr_spec.c:898]: parse_addr_spec(): end of header reached,
state=2910(25375) DEBUG: <core> [parser/msg_parser.c:190]: get_hdr_field():
DEBUG: get_hdr_field: <To> [43]; uri=[sip:linux_ua_1 at 192.168.1.195
<sip%3Alinux_ua_1 at 192.168.1.195>] 10(25375) DEBUG: <core>
[parser/msg_parser.c:192]: get_hdr_field(): DEBUG: to body
[<sip:linux_ua_1 at 192.168.1.195 <sip%3Alinux_ua_1 at 192.168.1.195>>]10(25375)
DEBUG: <core> [parser/msg_parser.c:170]: get_hdr_field(): get_hdr_field:
cseq <CSeq>: <3> <PRACK>10(25375) DEBUG: tm [t_lookup.c:949]:
t_reply_matching(): DEBUG: t_reply_matching: hash 12871 label 0 branch
010(25375) DEBUG: tm [t_lookup.c:1004]: t_reply_matching(): DEBUG:
t_reply_matching: reply matched (T=0x7fe2ebd1b780)!10(25375) DEBUG: tm
[t_lookup.c:1141]: t_check_msg(): DEBUG: t_check_msg: msg id=5 global id=5
T end=0x7fe2ebd1b78010(25375) DEBUG: tm [t_reply.c:2200]: reply_received():
DEBUG: reply_received: org. status uas=0, uac[0]=0 local=0
is_invite=0)10(25375) DEBUG: tm [t_reply.c:1294]:
t_should_relay_response(): ->>>>>>>>> T_code=0, new_code=40410(25375)
DEBUG: tm [t_reply.c:1812]: relay_reply(): DEBUG: relay_reply: branch=0,
save=0, relay=0 icode=010(25375) DEBUG: <core> [parser/msg_parser.c:204]:
get_hdr_field(): DEBUG: get_hdr_body : content_length=010(25375) DEBUG:
<core> [parser/msg_parser.c:106]: get_hdr_field(): found end of
header10(25375) DEBUG: <core> [msg_translator.c:2278]:
generate_res_buf_from_sip_res():  old size: 386, new size: 29110(25375)
DEBUG: <core> [msg_translator.c:2296]: generate_res_buf_from_sip_res():
copied size: orig:117, new: 22, rest: 269 msg=SIP/2.0 404 Not hereVia:
SIP/2.0/TCP 192.168.1.195:19009;branch=z9hG4bK1576634775From:
<sip:linux_ua_0 at 192.168.1.195
<sip%3Alinux_ua_0 at 192.168.1.195>>;tag=604263664To:
<sip:linux_ua_1 at 192.168.1.195
<sip%3Alinux_ua_1 at 192.168.1.195>>;tag=1656432204Call-ID:
734015646 at 192.168.1.195 <734015646 at 192.168.1.195>CSeq: 3 PRACKServer:
kamailio (4.2.3 (x86_64/linux))Content-Length: 010(25375) DEBUG: <core>
[mem/shm_mem.c:111]: _shm_resize(): WARNING:vqm_resize: resize(0)
called10(25375) DEBUG: <core> [tcp_main.c:2281]: tcpconn_send_put():
tcp_send: send from reader (25375 (10)), reusing fd10(25375) DEBUG: <core>
[tcp_main.c:2516]: tcpconn_do_send(): tcp_send: sending...10(25375) DEBUG:
<core> [tcp_main.c:2550]: tcpconn_do_send(): tcp_send: after real write: c=
0x7fe2ebd096b0 n=291 fd=510(25375) DEBUG: <core> [tcp_main.c:2551]:
tcpconn_do_send(): tcp_send: buf=SIP/2.0 404 Not hereVia: SIP/2.0/TCP
192.168.1.195:19009;branch=z9hG4bK1576634775From:
<sip:linux_ua_0 at 192.168.1.195
<sip%3Alinux_ua_0 at 192.168.1.195>>;tag=604263664To:
<sip:linux_ua_1 at 192.168.1.195
<sip%3Alinux_ua_1 at 192.168.1.195>>;tag=1656432204Call-ID:
734015646 at 192.168.1.195 <734015646 at 192.168.1.195>CSeq: 3 PRACKServer:
kamailio (4.2.3 (x86_64/linux))Content-Length: 010(25375) DEBUG: tm
[t_reply.c:1653]: cleanup_uac_timers(): DEBUG: cleanup_uac_timers: RETR/FR
timers reset10(25375) DEBUG: <core> [usr_avp.c:643]: destroy_avp_list():
DEBUG:destroy_avp_list: destroying list (nil)10(25375) DEBUG: <core>
[usr_avp.c:643]: destroy_avp_list(): DEBUG:destroy_avp_list: destroying
list (nil)10(25375) DEBUG: <core> [usr_avp.c:643]: destroy_avp_list():
DEBUG:destroy_avp_list: destroying list (nil)10(25375) DEBUG: <core>
[usr_avp.c:643]: destroy_avp_list(): DEBUG:destroy_avp_list: destroying
list (nil)10(25375) DEBUG: <core> [usr_avp.c:643]: destroy_avp_list():
DEBUG:destroy_avp_list: destroying list (nil)10(25375) DEBUG: <core>
[usr_avp.c:643]: destroy_avp_list(): DEBUG:destroy_avp_list: destroying
list (nil)10(25375) DEBUG: <core> [xavp.c:448]: xavp_destroy_list():
destroying xavp list (nil)10(25375) DEBUG: <core> [receive.c:298]:
receive_msg(): receive_msg: cleaning up10(25375) DEBUG: <core>
[io_wait.h:388]: io_watch_add(): DBG: io_watch_add(0xa33180, 10, 2,
0x7fe2ebd1e5c0), fd_no=214(25379) CRITICAL: <core> [pass_fd.c:293]:
receive_fd(): EOF on 1314(25379) DEBUG: <core> [tcp_main.c:3537]:
handle_ser_child(): DBG: handle_ser_child: dead child 4, pid 25369
(shutting down?)14(25379) DEBUG: <core> [io_wait.h:610]: io_watch_del():
DBG: io_watch_del (0x9eeee0, 13, -1, 0x0) fd_no=19
calledroot at Kamal:/usr/local/etc/kamailio# *
-------------- next part --------------
An HTML attachment was scrubbed...
URL: <http://lists.sip-router.org/pipermail/sr-users/attachments/20150524/850eb777/attachment.html>