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@192.168.1.195 sip%3Alinux_ua_1@192.168.1.195>;tag=1307796831To: <sip:linux_ua_1@192.168.1.195 sip%3Alinux_ua_1@192.168.1.195>;tag=25fbdd2b0c9b93b0791296269f5ae411.38a0Call-ID: 835380265@192.168.1.195 835380265@192.168.1.195CSeq: 2 REGISTERContact: sip:linux_ua_1@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@192.168.1.195 sip%3Alinux_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=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@192.168.1.195 sip%3Alinux_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 sip%3Alinux_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=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@192.168.1.195 sip%3Alinux_ua_1@192.168.1.195>;tag=1335679035To: <sip:linux_ua_1@192.168.1.195 sip%3Alinux_ua_1@192.168.1.195>;tag=ff272440259f71af2c767e7942717037-95d5Call-ID: 1397060040@192.168.1.195 1397060040@192.168.1.195CSeq: 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@192.168.1.195 sip%3Alinux_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=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@192.168.1.195 sip%3Alinux_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 sip%3Alinux_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=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@192.168.1.195 sip%3Alinux_ua_0@192.168.1.195>;tag=604263664To: <sip:linux_ua_1@192.168.1.195 sip%3Alinux_ua_1@192.168.1.195>Call-ID: 734015646@192.168.1.195 734015646@192.168.1.195CSeq: 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@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@192.168.1.195 sip%3Alinux_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 sip%3Alinux_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 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;lrFrom: <sip:linux_ua_0@192.168.1.195 sip%3Alinux_ua_0@192.168.1.195>;tag=604263664To: <sip:linux_ua_1@192.168.1.195 sip%3Alinux_ua_1@192.168.1.195>;tag=1656432204Call-ID: 734015646@192.168.1.195 734015646@192.168.1.195CSeq: 2 INVITEContact: sip:linux_ua_1@192.168.1.195:40611;transport=TCPContent-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;lrFrom: <sip:linux_ua_0@192.168.1.195 sip%3Alinux_ua_0@192.168.1.195>;tag=604263664To: <sip:linux_ua_1@192.168.1.195 sip%3Alinux_ua_1@192.168.1.195>;tag=1656432204Call-ID: 734015646@192.168.1.195 734015646@192.168.1.195CSeq: 2 INVITEContact: sip:linux_ua_1@192.168.1.195:40611;transport=TCPContent-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@192.168.1.195:40611;transport=TCP10(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@192.168.1.195 sip%3Alinux_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 sip%3Alinux_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=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;lr13(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@192.168.1.195 sip%3Alinux_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 sip%3Alinux_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=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@192.168.1.195 sip%3Alinux_ua_0@192.168.1.195>;tag=604263664To: <sip:linux_ua_1@192.168.1.195 sip%3Alinux_ua_1@192.168.1.195>;tag=1656432204Call-ID: 734015646@192.168.1.195 734015646@192.168.1.195CSeq: 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@192.168.1.195 sip%3Alinux_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 sip%3Alinux_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 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@192.168.1.195 sip%3Alinux_ua_0@192.168.1.195>;tag=604263664To: <sip:linux_ua_1@192.168.1.195 sip%3Alinux_ua_1@192.168.1.195>;tag=1656432204Call-ID: 734015646@192.168.1.195 734015646@192.168.1.195CSeq: 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@192.168.1.195 sip%3Alinux_ua_0@192.168.1.195>;tag=604263664To: <sip:linux_ua_1@192.168.1.195 sip%3Alinux_ua_1@192.168.1.195>;tag=1656432204Call-ID: 734015646@192.168.1.195 734015646@192.168.1.195CSeq: 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@Kamal:/usr/local/etc/kamailio# *
Hello,
404 Not here is tipically sent for requests within dialog that don't have any Route header, as it should because kamailio does record routing.
If you can show the PRACK, as well as the INVITE and responses to it for such case, we can assert better what happens (e.g., send the ngrep output taken on server for such case).
Cheers, Daniel
On 24/05/15 05:48, Austin Einter wrote:
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.
-
Austin Einter -
Daniel-Constantin Mierla