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 fd
11(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=5
11(25376) DEBUG: <core> [tcp_main.c:2551]: tcpconn_do_send(): tcp_send: buf=
SIP/2.0 200 OK
Via: SIP/2.0/TCP 192.168.1.195:40611;branch=z9hG4bK1186661565
From: <sip:linux_ua_1@192.168.1.195>;tag=1307796831
To: <sip:linux_ua_1@192.168.1.195>;tag=25fbdd2b0c9b93b0791296269f5ae411.38a0
Call-ID: 835380265@192.168.1.195
CSeq: 2 REGISTER
Contact: <sip:linux_ua_1@192.168.1.195:40611;transport=tcp>;expires=3600
Server: kamailio (4.2.3 (x86_64/linux))
Content-Length: 0

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
11(25376) DEBUG: <core> [io_wait.h:388]: io_watch_add(): DBG: io_watch_add(0xa33180, 5, 2, 0x7fe2ebd05390), fd_no=1
11(25376) DEBUG: <core> [tcp_read.c:1362]: tcp_read_req(): tcp_read_req: content-length= 0
11(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@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=16
11(25376) DEBUG: <core> [parser/parse_via.c:2672]: parse_via(): end of header reached, state=5
11(25376) DEBUG: <core> [parser/msg_parser.c:513]: parse_headers(): parse_headers: Via found, flags=2
11(25376) DEBUG: <core> [parser/msg_parser.c:515]: parse_headers(): parse_headers: this is the first via
11(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=10
11(25376) DEBUG: <core> [parser/msg_parser.c:190]: get_hdr_field(): DEBUG: get_hdr_field: <To> [28]; uri=[sip:linux_ua_1@192.168.1.195]
11(25376) DEBUG: <core> [parser/msg_parser.c:192]: get_hdr_field(): DEBUG: to body [<sip:linux_ua_1@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=0
11(25376) DEBUG: <core> [parser/msg_parser.c:106]: get_hdr_field(): found end of header
11(25376) DEBUG: <core> [parser/parse_addr_spec.c:176]: parse_to_param(): DEBUG: add_param: tag=1335679035
11(25376) DEBUG: <core> [parser/parse_addr_spec.c:898]: parse_addr_spec(): end of header reached, state=29
11(25376) DEBUG: sanity [mod_sanity.c:255]: w_sanity_check(): sanity checks result: 1
11(25376) DEBUG: siputils [checks.c:103]: has_totag(): no totag
11(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=0
11(25376) DEBUG: tm [t_lookup.c:485]: matching_3261(): DEBUG: RFC3261 transaction matching failed
11(25376) DEBUG: tm [t_lookup.c:709]: t_lookup_request(): DEBUG: t_lookup_request: no transaction found
11(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 5060
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 5060
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 4090 (advertise 0) matches port 5060
11(25376) DEBUG: registrar [lookup.c:203]: lookup_helper(): contact for [linux_ua_1] cannot handle the SIP method
11(25376) DEBUG: registrar [lookup.c:211]: lookup_helper(): 'linux_ua_1' has no valid contact in usrloc
11(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=0
11(25376) DEBUG: tm [t_lookup.c:485]: matching_3261(): DEBUG: RFC3261 transaction matching failed
11(25376) DEBUG: tm [t_lookup.c:709]: t_lookup_request(): DEBUG: t_lookup_request: no transaction found
11(25376) DEBUG: tm [t_hooks.c:380]: run_reqin_callbacks_internal(): DBG: trans=0x7fe2ebd10e68, callback type 1, id 0 entered
11(25376) DEBUG: <core> [md5utils.c:67]: MD5StringArray(): DEBUG: MD5 calculated: c17c6f2bd5d60787072aef8ffcf5bfe6
11(25376) DEBUG: tm [t_lookup.c:1072]: t_check_msg(): DEBUG: t_check_msg: msg id=2 global id=2 T start=0x7fe2ebd10e68
11(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) called
11(25376) DEBUG: tm [t_reply.c:1653]: cleanup_uac_timers(): DEBUG: cleanup_uac_timers: RETR/FR timers reset
11(25376) DEBUG: <core> [tcp_main.c:2281]: tcpconn_send_put(): tcp_send: send from reader (25376 (11)), reusing fd
11(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=5
11(25376) DEBUG: <core> [tcp_main.c:2551]: tcpconn_do_send(): tcp_send: buf=
SIP/2.0 405 Method Not Allowed
Via: SIP/2.0/TCP 192.168.1.195:40611;branch=z9hG4bK1577674881
From: <sip:linux_ua_1@192.168.1.195>;tag=1335679035
To: <sip:linux_ua_1@192.168.1.195>;tag=ff272440259f71af2c767e7942717037-95d5
Call-ID: 1397060040@192.168.1.195
CSeq: 2 SUBSCRIBE
Server: kamailio (4.2.3 (x86_64/linux))
Content-Length: 0

11(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 N
11(25376) DEBUG: tm [t_reply.c:738]: _reply_light(): DEBUG: _reply_light: finished
11(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] members
10(25375) DEBUG: <core> [tcp_read.c:1362]: tcp_read_req(): tcp_read_req: content-length= 359
10(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@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=16
10(25375) DEBUG: <core> [parser/parse_via.c:2672]: parse_via(): end of header reached, state=5
10(25375) DEBUG: <core> [parser/msg_parser.c:513]: parse_headers(): parse_headers: Via found, flags=2
10(25375) DEBUG: <core> [parser/msg_parser.c:515]: parse_headers(): parse_headers: this is the first via
10(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=10
10(25375) DEBUG: <core> [parser/msg_parser.c:190]: get_hdr_field(): DEBUG: get_hdr_field: <To> [28]; uri=[sip:linux_ua_1@192.168.1.195]
10(25375) DEBUG: <core> [parser/msg_parser.c:192]: get_hdr_field(): DEBUG: to body [<sip:linux_ua_1@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=359
10(25375) DEBUG: <core> [parser/msg_parser.c:106]: get_hdr_field(): found end of header
10(25375) DEBUG: <core> [parser/parse_addr_spec.c:176]: parse_to_param(): DEBUG: add_param: tag=604263664
10(25375) DEBUG: <core> [parser/parse_addr_spec.c:898]: parse_addr_spec(): end of header reached, state=29
10(25375) DEBUG: sanity [mod_sanity.c:255]: w_sanity_check(): sanity checks result: 1
10(25375) DEBUG: siputils [checks.c:103]: has_totag(): no totag
10(25375) DEBUG: tm [t_lookup.c:1072]: t_check_msg(): DEBUG: t_check_msg: msg id=3 global id=2 T start=0xffffffffffffffff
10(25375) DEBUG: tm [t_lookup.c:527]: t_lookup_request(): t_lookup_request: start searching: hash=12870, isACK=0
10(25375) DEBUG: tm [t_lookup.c:485]: matching_3261(): DEBUG: RFC3261 transaction matching failed
10(25375) DEBUG: tm [t_lookup.c:709]: t_lookup_request(): DEBUG: t_lookup_request: no transaction found
10(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 5060
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 5060
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 4090 (advertise 0) matches port 5060
10(25375) DEBUG: registrar [lookup.c:198]: lookup_helper(): contact for [linux_ua_1] found by address
10(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=0
10(25375) DEBUG: tm [t_lookup.c:485]: matching_3261(): DEBUG: RFC3261 transaction matching failed
10(25375) DEBUG: tm [t_lookup.c:709]: t_lookup_request(): DEBUG: t_lookup_request: no transaction found
10(25375) DEBUG: tm [t_hooks.c:380]: run_reqin_callbacks_internal(): DBG: trans=0x7fe2ebd13848, callback type 1, id 0 entered
10(25375) DEBUG: <core> [md5utils.c:67]: MD5StringArray(): DEBUG: MD5 calculated: c4c3d26baa62dea619271f186d6344fc
10(25375) DEBUG: tm [t_funcs.c:347]: t_relay_to(): SER: new INVITE
10(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) called
10(25375) DEBUG: <core> [tcp_main.c:2281]: tcpconn_send_put(): tcp_send: send from reader (25375 (10)), reusing fd
10(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=5
10(25375) DEBUG: <core> [tcp_main.c:2551]: tcpconn_do_send(): tcp_send: buf=
SIP/2.0 100 trying -- your call is important to us
Via: SIP/2.0/TCP 192.168.1.195:19009;branch=z9hG4bK1970975121
From: <sip:linux_ua_0@192.168.1.195>;tag=604263664
To: <sip:linux_ua_1@192.168.1.195>
Call-ID: 734015646@192.168.1.195
CSeq: 2 INVITE
Server: kamailio (4.2.3 (x86_64/linux))
Content-Length: 0

10(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: finished
10(25375) DEBUG: <script>: new branch [0] to sip:linux_ua_1@192.168.1.195:40611;transport=tcp
10(25375) DEBUG: <core> [msg_translator.c:2893]: create_via_hf(): create_via_hf: id added: <;i=2>, rcv proto=2
10(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 one
10(25375) DEBUG: <core> [ip_addr.c:243]: print_ip(): tcpconn_new: new tcp connection: 192.168.1.195
10(25375) DEBUG: <core> [tcp_main.c:1073]: tcpconn_new(): tcpconn_new: on port 40611, type 2
10(25375) DEBUG: <core> [tcp_main.c:1382]: tcpconn_add(): tcpconn_add: hashes: 3453:3998:0, 3
10(25375) INFO: <core> [tcp_main.c:2753]: tcpconn_1st_send(): quick connect for 0x7fe2ebd17030
10(25375) DEBUG: tm [t_funcs.c:394]: t_relay_to(): SER: new transaction fwd'ed
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: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=19
10(25375) DEBUG: <core> [receive.c:298]: receive_msg(): receive_msg: cleaning up
14(25379) DEBUG: <core> [io_wait.h:610]: io_watch_del(): DBG: io_watch_del (0x9eeee0, 28, -1, 0x0) fd_no=20 called
14(25379) DEBUG: <core> [tcp_main.c:4219]: handle_tcpconn_ev(): tcp: DBG: sending to child, events 1
14(25379) DEBUG: <core> [tcp_main.c:3902]: send2child(): selected tcp worker 2 12(25377) for activity on [tcp:192.168.1.195:4060], 0x7fe2ebd17030
12(25377) DEBUG: <core> [tcp_read.c:1554]: handle_io(): received n=8 con=0x7fe2ebd17030, fd=5
12(25377) DEBUG: <core> [tcp_read.c:1362]: tcp_read_req(): tcp_read_req: content-length= 388
12(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=6
12(25377) DEBUG: <core> [parser/parse_via.c:1284]: parse_via_param(): Found param type 236, <i> = <2>; state=16
12(25377) DEBUG: <core> [parser/parse_via.c:2672]: parse_via(): end of header reached, state=5
12(25377) DEBUG: <core> [parser/msg_parser.c:513]: parse_headers(): parse_headers: Via found, flags=2
12(25377) DEBUG: <core> [parser/msg_parser.c:515]: parse_headers(): parse_headers: this is the first via
12(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=0xffffffffffffffff
12(25377) DEBUG: <core> [parser/parse_via.c:1284]: parse_via_param(): Found param type 232, <branch> = <z9hG4bK1970975121>; state=16
12(25377) DEBUG: <core> [parser/parse_via.c:2672]: parse_via(): end of header reached, state=5
12(25377) DEBUG: <core> [parser/msg_parser.c:513]: parse_headers(): parse_headers: Via found, flags=62
12(25377) DEBUG: <core> [parser/msg_parser.c:526]: parse_headers(): parse_headers: this is the second via
12(25377) DEBUG: <core> [parser/parse_addr_spec.c:176]: parse_to_param(): DEBUG: add_param: tag=1656432204
12(25377) DEBUG: <core> [parser/parse_addr_spec.c:898]: parse_addr_spec(): end of header reached, state=29
12(25377) DEBUG: <core> [parser/msg_parser.c:190]: get_hdr_field(): DEBUG: get_hdr_field: <To> [43]; uri=[sip:linux_ua_1@192.168.1.195]
12(25377) DEBUG: <core> [parser/msg_parser.c:192]: get_hdr_field(): DEBUG: to body [<sip:linux_ua_1@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 0
12(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 entered
12(25377) DEBUG: acc [acc_logic.c:644]: tmcb_func(): acc callback called for t(0x7fe2ebd13848) event type 2, reply code 183
12(25377) DEBUG: tm [t_lookup.c:1141]: t_check_msg(): DEBUG: t_check_msg: msg id=1 global id=1 T end=0x7fe2ebd13848
12(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 reply
12(25377) DEBUG: tm [t_reply.c:1294]: t_should_relay_response(): ->>>>>>>>> T_code=100, new_code=183
12(25377) DEBUG: tm [t_reply.c:1812]: relay_reply(): DEBUG: relay_reply: branch=0, save=0, relay=0 icode=0
12(25377) DEBUG: <core> [parser/msg_parser.c:204]: get_hdr_field(): DEBUG: get_hdr_body : content_length=388
12(25377) DEBUG: <core> [parser/msg_parser.c:106]: get_hdr_field(): found end of header
12(25377) DEBUG: <core> [msg_translator.c:2278]: generate_res_buf_from_sip_res(): old size: 948, new size: 853
12(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 Progress
Via: SIP/2.0/TCP 192.168.1.195:19009;branch=z9hG4bK1970975121
Record-Route: <sip:192.168.1.195:4060;transport=tcp;lr>
From: <sip:linux_ua_0@192.168.1.195>;tag=604263664
To: <sip:linux_ua_1@192.168.1.195>;tag=1656432204
Call-ID: 734015646@192.168.1.195
CSeq: 2 INVITE
Contact: <sip:linux_ua_1@192.168.1.195:40611;transport=TCP>
Content-Type: application/sdp
User-Agent: Linux 64 US-UA 1.0.1
Require: 100rel
RSeq: 1
Content-Length:   388

v=0
o=- 0 0 IN IP4 192.168.1.195
s=IMS_Call
c=IN IP4 192.168.1.195
t=0 0
m=audio 21720 RTP/AVP 99 0 8 101
b=AS:64
a=curr:qos remote none
a=curr:qos local none
a=des:qos mandatory remote sendrecv
a=conf:qos remote sendrecv
a=des:qos mandatory local sendrecv
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-15
a=rtpmap:99 AMR/8000
a=rtpmap:0 PCMU/8000
a=rtpmap:8 PCMA/8000

12(25377) DEBUG: <core> [tcp_main.c:2297]: tcpconn_send_put(): tcp_send: tcp connection found (0x7fe2ebd096b0), acquiring fd
12(25377) DEBUG: <core> [tcp_main.c:2307]: tcpconn_send_put(): tcp_send, c= 0x7fe2ebd096b0, n=16
14(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=8
12(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=8
12(25377) DEBUG: <core> [tcp_main.c:2551]: tcpconn_do_send(): tcp_send: buf=
SIP/2.0 183 Session Progress
Via: SIP/2.0/TCP 192.168.1.195:19009;branch=z9hG4bK1970975121
Record-Route: <sip:192.168.1.195:4060;transport=tcp;lr>
From: <sip:linux_ua_0@192.168.1.195>;tag=604263664
To: <sip:linux_ua_1@192.168.1.195>;tag=1656432204
Call-ID: 734015646@192.168.1.195
CSeq: 2 INVITE
Contact: <sip:linux_ua_1@192.168.1.195:40611;transport=TCP>
Content-Type: application/sdp
User-Agent: Linux 64 US-UA 1.0.1
Require: 100rel
RSeq: 1
Content-Length:   388

v=0
o=- 0 0 IN IP4 192.168.1.195
s=IMS_Call
c=IN IP4 192.168.1.195
t=0 0
m=audio 21720 RTP/AVP 99 0 8 101
b=AS:64
a=curr:qos remote none
a=curr:qos local none
a=des:qos mandatory remote sendrecv
a=conf:qos remote sendrecv
a=des:qos mandatory local sendrecv
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-15
a=rtpmap:99 AMR/8000
a=rtpmap:0 PCMU/8000
a=rtpmap:8 PCMA/8000

12(25377) DEBUG: tm [t_hooks.c:288]: run_trans_callbacks_internal(): DBG: trans=0x7fe2ebd13848, callback type 512, id 0 entered
12(25377) DEBUG: acc [acc_logic.c:644]: tmcb_func(): acc callback called for t(0x7fe2ebd13848) event type 512, reply code 183
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> [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 up
12(25377) DEBUG: <core> [io_wait.h:388]: io_watch_add(): DBG: io_watch_add(0xa33180, 5, 2, 0x7fe2ebd17030), fd_no=1
10(25375) DEBUG: <core> [tcp_read.c:1362]: tcp_read_req(): tcp_read_req: content-length= 392
10(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@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=16
10(25375) DEBUG: <core> [parser/parse_via.c:2672]: parse_via(): end of header reached, state=5
10(25375) DEBUG: <core> [parser/msg_parser.c:513]: parse_headers(): parse_headers: Via found, flags=2
10(25375) DEBUG: <core> [parser/msg_parser.c:515]: parse_headers(): parse_headers: this is the first via
10(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=1656432204
10(25375) DEBUG: <core> [parser/parse_addr_spec.c:898]: parse_addr_spec(): end of header reached, state=29
10(25375) DEBUG: <core> [parser/msg_parser.c:190]: get_hdr_field(): DEBUG: get_hdr_field: <To> [43]; uri=[sip:linux_ua_1@192.168.1.195]
10(25375) DEBUG: <core> [parser/msg_parser.c:192]: get_hdr_field(): DEBUG: to body [<sip:linux_ua_1@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=392
10(25375) DEBUG: <core> [parser/msg_parser.c:106]: get_hdr_field(): found end of header
10(25375) DEBUG: <core> [parser/parse_addr_spec.c:176]: parse_to_param(): DEBUG: add_param: tag=604263664
10(25375) DEBUG: <core> [parser/parse_addr_spec.c:898]: parse_addr_spec(): end of header reached, state=29
10(25375) DEBUG: sanity [mod_sanity.c:255]: w_sanity_check(): sanity checks result: 1
10(25375) DEBUG: siputils [checks.c:106]: has_totag(): totag found
10(25375) DEBUG: rr [loose.c:90]: is_preloaded(): is_preloaded: No
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 40611
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 40611
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 4090 (advertise 0) matches port 40611
10(25375) DEBUG: rr [loose.c:674]: after_strict(): Next hop: 'sip:192.168.1.195:4060;transport=tcp;lr' is loose router
10(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=0xffffffffffffffff
10(25375) DEBUG: tm [t_lookup.c:527]: t_lookup_request(): t_lookup_request: start searching: hash=12871, isACK=0
10(25375) DEBUG: tm [t_lookup.c:485]: matching_3261(): DEBUG: RFC3261 transaction matching failed
10(25375) DEBUG: tm [t_lookup.c:709]: t_lookup_request(): DEBUG: t_lookup_request: no transaction found
10(25375) DEBUG: tm [t_hooks.c:380]: run_reqin_callbacks_internal(): DBG: trans=0x7fe2ebd1b780, callback type 1, id 0 entered
10(25375) DEBUG: <core> [md5utils.c:67]: MD5StringArray(): DEBUG: MD5 calculated: 0dd1edaf37f3874c5176befe76ed5b3e
10(25375) DEBUG: <core> [msg_translator.c:2893]: create_via_hf(): create_via_hf: id added: <;i=2>, rcv proto=2
10(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 one
10(25375) DEBUG: <core> [ip_addr.c:243]: print_ip(): tcpconn_new: new tcp connection: 192.168.1.195
10(25375) DEBUG: <core> [tcp_main.c:1073]: tcpconn_new(): tcpconn_new: on port 4060, type 2
10(25375) DEBUG: <core> [tcp_main.c:1382]: tcpconn_add(): tcpconn_add: hashes: 3360:0:0, 4
10(25375) INFO: <core> [tcp_main.c:2753]: tcpconn_1st_send(): quick connect for 0x7fe2ebd1e5c0
10(25375) DEBUG: tm [t_funcs.c:394]: t_relay_to(): SER: new transaction fwd'ed
14(25379) DEBUG: <core> [ip_addr.c:243]: print_ip(): tcpconn_new: new tcp connection: 192.168.1.195
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:1073]: tcpconn_new(): tcpconn_new: on port 19785, type 2
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)
14(25379) DEBUG: <core> [tcp_main.c:1382]: tcpconn_add(): tcpconn_add: hashes: 3888:3539:528, 5
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 up
14(25379) DEBUG: <core> [io_wait.h:388]: io_watch_add(): DBG: io_watch_add(0x9eeee0, 29, 2, 0x7fe2ebd228e0), fd_no=19
14(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=20
14(25379) DEBUG: <core> [io_wait.h:610]: io_watch_del(): DBG: io_watch_del (0x9eeee0, 29, -1, 0x0) fd_no=21 called
14(25379) DEBUG: <core> [tcp_main.c:4219]: handle_tcpconn_ev(): tcp: DBG: sending to child, events 1
14(25379) DEBUG: <core> [tcp_main.c:3902]: send2child(): selected tcp worker 3 13(25378) for activity on [tcp:192.168.1.195:4060], 0x7fe2ebd228e0
13(25378) DEBUG: <core> [tcp_read.c:1554]: handle_io(): received n=8 con=0x7fe2ebd228e0, fd=5
13(25378) DEBUG: <core> [tcp_read.c:1362]: tcp_read_req(): tcp_read_req: content-length= 392
13(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=6
13(25378) DEBUG: <core> [parser/parse_via.c:1284]: parse_via_param(): Found param type 236, <i> = <2>; state=16
13(25378) DEBUG: <core> [parser/parse_via.c:2672]: parse_via(): end of header reached, state=5
13(25378) DEBUG: <core> [parser/msg_parser.c:513]: parse_headers(): parse_headers: Via found, flags=2
13(25378) DEBUG: <core> [parser/msg_parser.c:515]: parse_headers(): parse_headers: this is the first via
13(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=16
13(25378) DEBUG: <core> [parser/parse_via.c:2672]: parse_via(): end of header reached, state=5
13(25378) DEBUG: <core> [parser/msg_parser.c:513]: parse_headers(): parse_headers: Via found, flags=100
13(25378) DEBUG: <core> [parser/msg_parser.c:526]: parse_headers(): parse_headers: this is the second via
13(25378) DEBUG: <core> [parser/parse_addr_spec.c:176]: parse_to_param(): DEBUG: add_param: tag=1656432204
13(25378) DEBUG: <core> [parser/parse_addr_spec.c:898]: parse_addr_spec(): end of header reached, state=29
13(25378) DEBUG: <core> [parser/msg_parser.c:190]: get_hdr_field(): DEBUG: get_hdr_field: <To> [43]; uri=[sip:linux_ua_1@192.168.1.195]
13(25378) DEBUG: <core> [parser/msg_parser.c:192]: get_hdr_field(): DEBUG: to body [<sip:linux_ua_1@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=392
13(25378) DEBUG: <core> [parser/msg_parser.c:106]: get_hdr_field(): found end of header
13(25378) DEBUG: <core> [parser/parse_addr_spec.c:176]: parse_to_param(): DEBUG: add_param: tag=604263664
13(25378) DEBUG: <core> [parser/parse_addr_spec.c:898]: parse_addr_spec(): end of header reached, state=29
13(25378) DEBUG: sanity [mod_sanity.c:255]: w_sanity_check(): sanity checks result: 1
13(25378) DEBUG: siputils [checks.c:106]: has_totag(): totag found
13(25378) DEBUG: rr [loose.c:113]: find_first_route(): No Route headers found
13(25378) DEBUG: rr [loose.c:929]: loose_route(): There is no Route HF
13(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 fd
13(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=5
14(25379) DEBUG: <core> [io_wait.h:610]: io_watch_del(): DBG: io_watch_del (0x9eeee0, 30, -1, 0x0) fd_no=20 called
13(25378) DEBUG: <core> [tcp_main.c:2551]: tcpconn_do_send(): tcp_send: buf=
SIP/2.0 404 Not here
Via: SIP/2.0/TCP 192.168.1.195:4060;branch=z9hG4bK7423.0dd1edaf37f3874c5176befe76ed5b3e.0;i=2
Via: SIP/2.0/TCP 192.168.1.195:19009;branch=z9hG4bK1576634775
From: <sip:linux_ua_0@192.168.1.195>;tag=604263664
To: <sip:linux_ua_1@192.168.1.195>;tag=1656432204
Call-ID: 734015646@192.168.1.195
CSeq: 3 PRACK
Server: kamailio (4.2.3 (x86_64/linux))
Content-Length: 0

14(25379) DEBUG: <core> [tcp_main.c:4219]: handle_tcpconn_ev(): tcp: DBG: sending to child, events 1
14(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], 0x7fe2ebd1e5c0
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:1554]: handle_io(): received n=8 con=0x7fe2ebd1e5c0, fd=10
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)
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= 0
13(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 up
10(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=6
13(25378) DEBUG: <core> [io_wait.h:388]: io_watch_add(): DBG: io_watch_add(0xa33180, 5, 2, 0x7fe2ebd228e0), fd_no=1
10(25375) DEBUG: <core> [parser/parse_via.c:1284]: parse_via_param(): Found param type 236, <i> = <2>; state=16
10(25375) DEBUG: <core> [parser/parse_via.c:2672]: parse_via(): end of header reached, state=5
10(25375) DEBUG: <core> [parser/msg_parser.c:513]: parse_headers(): parse_headers: Via found, flags=2
10(25375) DEBUG: <core> [parser/msg_parser.c:515]: parse_headers(): parse_headers: this is the first via
10(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=0xffffffffffffffff
10(25375) DEBUG: <core> [parser/parse_via.c:1284]: parse_via_param(): Found param type 232, <branch> = <z9hG4bK1576634775>; state=16
10(25375) DEBUG: <core> [parser/parse_via.c:2672]: parse_via(): end of header reached, state=5
10(25375) DEBUG: <core> [parser/msg_parser.c:513]: parse_headers(): parse_headers: Via found, flags=62
10(25375) DEBUG: <core> [parser/msg_parser.c:526]: parse_headers(): parse_headers: this is the second via
10(25375) DEBUG: <core> [parser/parse_addr_spec.c:176]: parse_to_param(): DEBUG: add_param: tag=1656432204
10(25375) DEBUG: <core> [parser/parse_addr_spec.c:898]: parse_addr_spec(): end of header reached, state=29
10(25375) DEBUG: <core> [parser/msg_parser.c:190]: get_hdr_field(): DEBUG: get_hdr_field: <To> [43]; uri=[sip:linux_ua_1@192.168.1.195]
10(25375) DEBUG: <core> [parser/msg_parser.c:192]: get_hdr_field(): DEBUG: to body [<sip:linux_ua_1@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 0
10(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=0x7fe2ebd1b780
10(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=404
10(25375) DEBUG: tm [t_reply.c:1812]: relay_reply(): DEBUG: relay_reply: branch=0, save=0, relay=0 icode=0
10(25375) DEBUG: <core> [parser/msg_parser.c:204]: get_hdr_field(): DEBUG: get_hdr_body : content_length=0
10(25375) DEBUG: <core> [parser/msg_parser.c:106]: get_hdr_field(): found end of header
10(25375) DEBUG: <core> [msg_translator.c:2278]: generate_res_buf_from_sip_res(): old size: 386, new size: 291
10(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 here
Via: SIP/2.0/TCP 192.168.1.195:19009;branch=z9hG4bK1576634775
From: <sip:linux_ua_0@192.168.1.195>;tag=604263664
To: <sip:linux_ua_1@192.168.1.195>;tag=1656432204
Call-ID: 734015646@192.168.1.195
CSeq: 3 PRACK
Server: kamailio (4.2.3 (x86_64/linux))
Content-Length: 0

10(25375) DEBUG: <core> [mem/shm_mem.c:111]: _shm_resize(): WARNING:vqm_resize: resize(0) called
10(25375) DEBUG: <core> [tcp_main.c:2281]: tcpconn_send_put(): tcp_send: send from reader (25375 (10)), reusing fd
10(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=5
10(25375) DEBUG: <core> [tcp_main.c:2551]: tcpconn_do_send(): tcp_send: buf=
SIP/2.0 404 Not here
Via: SIP/2.0/TCP 192.168.1.195:19009;branch=z9hG4bK1576634775
From: <sip:linux_ua_0@192.168.1.195>;tag=604263664
To: <sip:linux_ua_1@192.168.1.195>;tag=1656432204
Call-ID: 734015646@192.168.1.195
CSeq: 3 PRACK
Server: kamailio (4.2.3 (x86_64/linux))
Content-Length: 0

10(25375) DEBUG: tm [t_reply.c:1653]: cleanup_uac_timers(): DEBUG: cleanup_uac_timers: RETR/FR timers reset
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> [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 up
10(25375) DEBUG: <core> [io_wait.h:388]: io_watch_add(): DBG: io_watch_add(0xa33180, 10, 2, 0x7fe2ebd1e5c0), fd_no=2

14(25379) CRITICAL: <core> [pass_fd.c:293]: receive_fd(): EOF on 13
14(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 called
root@Kamal:/usr/local/etc/kamailio#