0(18097) DEBUG: [core/udp_server.c:493]: udp_rcv_loop(): received on udp socket: (106/100/1204) [[INVITE sip:102@192.168.0.15 SIP/2.0 0D 0A Via: SIP/2.0/UDP 192.168.0.28:50045;branch=z9hG4bK.7B8TuSp2h;rp]] 0(18097) DEBUG: [core/parser/msg_parser.c:610]: parse_msg(): SIP Request: 0(18097) DEBUG: [core/parser/msg_parser.c:612]: parse_msg(): method: 0(18097) DEBUG: [core/parser/msg_parser.c:614]: parse_msg(): uri: 0(18097) DEBUG: [core/parser/msg_parser.c:616]: parse_msg(): version: 0(18097) DEBUG: [core/parser/parse_via.c:1303]: parse_via_param(): Found param type 232, = ; state=6 0(18097) DEBUG: [core/parser/parse_via.c:1303]: parse_via_param(): Found param type 235, = ; state=17 0(18097) DEBUG: [core/parser/parse_via.c:2639]: parse_via(): end of header reached, state=5 0(18097) DEBUG: [core/parser/msg_parser.c:498]: parse_headers(): Via found, flags=2 0(18097) DEBUG: [core/parser/msg_parser.c:500]: parse_headers(): this is the first via 0(18097) DEBUG: [core/parser/parse_addr_spec.c:864]: parse_addr_spec(): end of header reached, state=10 0(18097) DEBUG: [core/parser/msg_parser.c:171]: get_hdr_field(): [30]; uri=[sip:102@192.168.0.15] 0(18097) DEBUG: [core/parser/msg_parser.c:174]: get_hdr_field(): to body (30)["102" ], to tag (0)[] 0(18097) DEBUG: [core/parser/msg_parser.c:152]: get_hdr_field(): cseq : <20> 0(18097) DEBUG: [core/receive.c:319]: receive_msg(): --- received sip message - request - call-id: [FdUwYxGLEF] - cseq: [20 INVITE] 0(18097) DEBUG: [core/parser/msg_parser.c:185]: get_hdr_field(): content_length=517 0(18097) DEBUG: [core/parser/msg_parser.c:89]: get_hdr_field(): found end of header 0(18097) DEBUG: {1 20 INVITE FdUwYxGLEF} [core/receive.c:379]: receive_msg(): preparing to run routing scripts... 0(18097) DEBUG: {1 20 INVITE FdUwYxGLEF} app_python3 [apy_kemi.c:234]: sr_apy_kemi_exec_func_ex(): execution of method: .is_method_in 0(18097) DEBUG: {1 20 INVITE FdUwYxGLEF} app_python3 [apy_kemi.c:266]: sr_apy_kemi_exec_func_ex(): param[1] for: is_method_in is str: RS 0(18097) DEBUG: {1 20 INVITE FdUwYxGLEF} app_python3 [apy_kemi.c:232]: sr_apy_kemi_exec_func_ex(): execution of method: process_maxfwd 0(18097) DEBUG: {1 20 INVITE FdUwYxGLEF} app_python3 [apy_kemi.c:258]: sr_apy_kemi_exec_func_ex(): param[1] for: process_maxfwd is int: 10 0(18097) DEBUG: {1 20 INVITE FdUwYxGLEF} maxfwd [mf_funcs.c:74]: is_maxfwd_present(): value = 70 0(18097) DEBUG: {1 20 INVITE FdUwYxGLEF} app_python3 [apy_kemi.c:234]: sr_apy_kemi_exec_func_ex(): execution of method: .is_OPTIONS 0(18097) DEBUG: {1 20 INVITE FdUwYxGLEF} app_python3 [apy_kemi.c:232]: sr_apy_kemi_exec_func_ex(): execution of method: sanity_check 0(18097) DEBUG: {1 20 INVITE FdUwYxGLEF} app_python3 [apy_kemi.c:279]: sr_apy_kemi_exec_func_ex(): params[2] for: sanity_check are int-int: [1511] [7] 0(18097) DEBUG: {1 20 INVITE FdUwYxGLEF} sanity [sanity.c:247]: check_ruri_sip_version(): check_ruri_sip_version entered 0(18097) DEBUG: {1 20 INVITE FdUwYxGLEF} sanity [sanity.c:270]: check_ruri_sip_version(): check_ruri_sip_version passed 0(18097) DEBUG: {1 20 INVITE FdUwYxGLEF} sanity [sanity.c:277]: check_ruri_scheme(): check_ruri_scheme entered 0(18097) DEBUG: {1 20 INVITE FdUwYxGLEF} sanity [sanity.c:297]: check_ruri_scheme(): check_ruri_scheme passed 0(18097) DEBUG: {1 20 INVITE FdUwYxGLEF} sanity [sanity.c:318]: check_required_headers(): check_required_headers entered 0(18097) DEBUG: {1 20 INVITE FdUwYxGLEF} sanity [sanity.c:340]: check_required_headers(): check_required_headers passed 0(18097) DEBUG: {1 20 INVITE FdUwYxGLEF} sanity [sanity.c:506]: check_cseq_method(): check_cseq_method entered 0(18097) DEBUG: {1 20 INVITE FdUwYxGLEF} sanity [sanity.c:539]: check_cseq_method(): check_cseq_method passed 0(18097) DEBUG: {1 20 INVITE FdUwYxGLEF} sanity [sanity.c:548]: check_cseq_value(): check_cseq_value entered 0(18097) DEBUG: {1 20 INVITE FdUwYxGLEF} sanity [sanity.c:576]: check_cseq_value(): check_cseq_value passed 0(18097) DEBUG: {1 20 INVITE FdUwYxGLEF} sanity [sanity.c:585]: check_cl(): check_cl entered 0(18097) DEBUG: {1 20 INVITE FdUwYxGLEF} sanity [sanity.c:610]: check_cl(): check_cl passed 0(18097) DEBUG: {1 20 INVITE FdUwYxGLEF} sanity [sanity.c:622]: check_expires_value(): check_expires_value entered 0(18097) DEBUG: {1 20 INVITE FdUwYxGLEF} sanity [sanity.c:659]: check_expires_value(): no expires header found 0(18097) DEBUG: {1 20 INVITE FdUwYxGLEF} sanity [sanity.c:759]: check_parse_uris(): check_parse_uris entered 0(18097) DEBUG: {1 20 INVITE FdUwYxGLEF} sanity [sanity.c:763]: check_parse_uris(): parsing ruri 0(18097) DEBUG: {1 20 INVITE FdUwYxGLEF} sanity [sanity.c:777]: check_parse_uris(): looking up From header 0(18097) DEBUG: {1 20 INVITE FdUwYxGLEF} sanity [sanity.c:791]: check_parse_uris(): parsing From header 0(18097) DEBUG: {1 20 INVITE FdUwYxGLEF} [core/parser/parse_addr_spec.c:185]: parse_to_param(): add param: tag=ILonsDQko 0(18097) DEBUG: {1 20 INVITE FdUwYxGLEF} [core/parser/parse_addr_spec.c:864]: parse_addr_spec(): end of header reached, state=29 0(18097) DEBUG: {1 20 INVITE FdUwYxGLEF} sanity [sanity.c:817]: check_parse_uris(): parsing From URI 0(18097) DEBUG: {1 20 INVITE FdUwYxGLEF} sanity [sanity.c:835]: check_parse_uris(): looking up To header 0(18097) DEBUG: {1 20 INVITE FdUwYxGLEF} sanity [sanity.c:857]: check_parse_uris(): check_parse_uris(): parsing To URI 0(18097) DEBUG: {1 20 INVITE FdUwYxGLEF} sanity [sanity.c:902]: check_parse_uris(): check_parse_uris passed 0(18097) DEBUG: {1 20 INVITE FdUwYxGLEF} app_python3 [apy_kemi.c:234]: sr_apy_kemi_exec_func_ex(): execution of method: .is_CANCEL 0(18097) DEBUG: {1 20 INVITE FdUwYxGLEF} app_python3 [apy_kemi.c:232]: sr_apy_kemi_exec_func_ex(): execution of method: has_totag 0(18097) DEBUG: {1 20 INVITE FdUwYxGLEF} siputils [checks.c:120]: has_totag(): no totag 0(18097) DEBUG: {1 20 INVITE FdUwYxGLEF} app_python3 [apy_kemi.c:232]: sr_apy_kemi_exec_func_ex(): execution of method: t_precheck_trans 0(18097) DEBUG: {1 20 INVITE FdUwYxGLEF} app_python3 [apy_kemi.c:232]: sr_apy_kemi_exec_func_ex(): execution of method: t_check_trans 0(18097) DEBUG: {1 20 INVITE FdUwYxGLEF} tm [t_lookup.c:1034]: t_check_msg(): msg (0x7f051ac799a0) id=5/18097 global id=0/0 T start=0xffffffffffffffff 0(18097) DEBUG: {1 20 INVITE FdUwYxGLEF} tm [t_lookup.c:497]: t_lookup_request(): start searching: hash=56127, isACK=0 0(18097) DEBUG: {1 20 INVITE FdUwYxGLEF} tm [t_lookup.c:455]: matching_3261(): RFC3261 transaction matching failed - via branch [z9hG4bK.7B8TuSp2h] 0(18097) DEBUG: {1 20 INVITE FdUwYxGLEF} tm [t_lookup.c:675]: t_lookup_request(): no transaction found 0(18097) DEBUG: {1 20 INVITE FdUwYxGLEF} tm [t_lookup.c:1104]: t_check_msg(): msg (0x7f051ac799a0) id=5/18097 global id=5/18097 T end=(nil) 0(18097) DEBUG: {1 20 INVITE FdUwYxGLEF} app_python3 [apy_kemi.c:232]: sr_apy_kemi_exec_func_ex(): execution of method: remove 0(18097) DEBUG: {1 20 INVITE FdUwYxGLEF} app_python3 [apy_kemi.c:266]: sr_apy_kemi_exec_func_ex(): param[1] for: remove is str: Route 0(18097) DEBUG: {1 20 INVITE FdUwYxGLEF} [core/kemi.c:2062]: sr_kemi_hdr_remove(): remove hf: Route 0(18097) DEBUG: {1 20 INVITE FdUwYxGLEF} app_python3 [apy_kemi.c:234]: sr_apy_kemi_exec_func_ex(): execution of method: .is_method_in 0(18097) DEBUG: {1 20 INVITE FdUwYxGLEF} app_python3 [apy_kemi.c:266]: sr_apy_kemi_exec_func_ex(): param[1] for: is_method_in is str: IS 0(18097) DEBUG: {1 20 INVITE FdUwYxGLEF} app_python3 [apy_kemi.c:232]: sr_apy_kemi_exec_func_ex(): execution of method: record_route 0(18097) DEBUG: {1 20 INVITE FdUwYxGLEF} rr [record.c:479]: record_route(): inserted record route (r2: 1 - plen: 0) 0(18097) DEBUG: {1 20 INVITE FdUwYxGLEF} app_python3 [apy_kemi.c:234]: sr_apy_kemi_exec_func_ex(): execution of method: .is_method_in 0(18097) DEBUG: {1 20 INVITE FdUwYxGLEF} app_python3 [apy_kemi.c:266]: sr_apy_kemi_exec_func_ex(): param[1] for: is_method_in is str: ISU 0(18097) DEBUG: {1 20 INVITE FdUwYxGLEF} app_python3 [apy_kemi.c:232]: sr_apy_kemi_exec_func_ex(): execution of method: t_is_set 0(18097) DEBUG: {1 20 INVITE FdUwYxGLEF} app_python3 [apy_kemi.c:266]: sr_apy_kemi_exec_func_ex(): param[1] for: t_is_set is str: onreply_route 0(18097) DEBUG: {1 20 INVITE FdUwYxGLEF} app_python3 [apy_kemi.c:232]: sr_apy_kemi_exec_func_ex(): execution of method: t_on_reply 0(18097) DEBUG: {1 20 INVITE FdUwYxGLEF} app_python3 [apy_kemi.c:266]: sr_apy_kemi_exec_func_ex(): param[1] for: t_on_reply is str: ksr_onreply_manage 0(18097) DEBUG: {1 20 INVITE FdUwYxGLEF} app_python3 [apy_kemi.c:234]: sr_apy_kemi_exec_func_ex(): execution of method: .is_INVITE 0(18097) DEBUG: {1 20 INVITE FdUwYxGLEF} app_python3 [apy_kemi.c:232]: sr_apy_kemi_exec_func_ex(): execution of method: t_is_set 0(18097) DEBUG: {1 20 INVITE FdUwYxGLEF} app_python3 [apy_kemi.c:266]: sr_apy_kemi_exec_func_ex(): param[1] for: t_is_set is str: failure_route 0(18097) DEBUG: {1 20 INVITE FdUwYxGLEF} app_python3 [apy_kemi.c:232]: sr_apy_kemi_exec_func_ex(): execution of method: t_on_failure 0(18097) DEBUG: {1 20 INVITE FdUwYxGLEF} app_python3 [apy_kemi.c:266]: sr_apy_kemi_exec_func_ex(): param[1] for: t_on_failure is str: ksr_failure_manage 0(18097) DEBUG: {1 20 INVITE FdUwYxGLEF} app_python3 [apy_kemi.c:232]: sr_apy_kemi_exec_func_ex(): execution of method: has_body 0(18097) DEBUG: {1 20 INVITE FdUwYxGLEF} app_python3 [apy_kemi.c:232]: sr_apy_kemi_exec_func_ex(): execution of method: rtpengine_manage 0(18097) DEBUG: {1 20 INVITE FdUwYxGLEF} app_python3 [apy_kemi.c:266]: sr_apy_kemi_exec_func_ex(): param[1] for: rtpengine_manage is str: asymmetric 0(18097) DEBUG: {1 20 INVITE FdUwYxGLEF} [core/parser/sdp/sdp_helpr_funcs.c:619]: extract_sess_version(): oline(37): >o=1971 526 1906 IN IP4 192.168.0.28 < 0(18097) DEBUG: {1 20 INVITE FdUwYxGLEF} [core/parser/sdp/sdp_helpr_funcs.c:648]: extract_sess_version(): end 4: >1906< 0(18097) DEBUG: {1 20 INVITE FdUwYxGLEF} [core/parser/sdp/sdp_helpr_funcs.c:503]: extract_mediaip(): located IP address [192.168.0.28] in `o=' field 0(18097) DEBUG: {1 20 INVITE FdUwYxGLEF} [core/parser/sdp/sdp_helpr_funcs.c:503]: extract_mediaip(): located IP address [192.168.0.28] in `c=' field 0(18097) DEBUG: {1 20 INVITE FdUwYxGLEF} [core/parser/sdp/sdp.c:587]: parse_sdp_session(): ignoring unknown type in a= line: `a=rtcp-fb:* trr-int 1000 a=rtcp-fb:* ccm tmmbr ' 0(18097) DEBUG: {1 20 INVITE FdUwYxGLEF} [core/parser/sdp/sdp.c:587]: parse_sdp_session(): ignoring unknown type in a= line: `a=rtcp-fb:* ccm tmmbr ' 0(18097) DEBUG: {1 20 INVITE FdUwYxGLEF} rtpengine [rtpengine_funcs.c:144]: check_content_type(): type found valid 0(18097) DEBUG: {1 20 INVITE FdUwYxGLEF} rtpengine [rtpengine.c:3102]: select_rtpp_node_old(): rtpengine hash table lookup failed to find node for calllen=10 callid=FdUwYxGLEF viabranch= 0(18097) DEBUG: {1 20 INVITE FdUwYxGLEF} rtpengine [rtpengine.c:2579]: rtpp_function_call(): proxy reply: d3:sdp612:v=0 o=1971 526 1906 IN IP4 192.168.0.28 s=Talk c=IN IP4 192.168.0.101 t=0 0 a=rtcp-xr:rcvr-rtt=all:10000 stat-summary=loss,dup,jitt,TTL voip-metrics m=audio 32380 RTP/AVP 96 97 98 0 8 18 101 99 100 a=rtcp-fb:* trr-int 1000 a=rtcp-fb:* ccm tmmbr a=rtpmap:96 opus/48000/2 a=fmtp:96 useinbandfec=1 a=rtpmap:97 speex/16000 a=fmtp:97 vbr=on a=rtpmap:98 speex/8000 a=fmtp:98 vbr=on a=rtpmap:0 PCMU/8000 a=rtpmap:8 PCMA/8000 a=rtpmap:18 G729/8000 a=fmtp:18 annexb=yes a=rtpmap:101 telephone-event/48000 a=rtpmap:99 telephone-event/16000 a=rtpmap:100 telephone-event/8000 a=sendrecv a=rtcp:32381 6:result2:oke 0(18097) DEBUG: {1 20 INVITE FdUwYxGLEF} rtpengine [rtpengine.c:2665]: rtpp_function_call(): rtpengine hash table insert node=udp:127.0.0.1:2223 for calllen=10 callid=FdUwYxGLEF viabranch= 0(18097) DEBUG: {1 20 INVITE FdUwYxGLEF} app_python3 [apy_kemi.c:232]: sr_apy_kemi_exec_func_ex(): execution of method: t_relay 0(18097) DEBUG: {1 20 INVITE FdUwYxGLEF} tm [t_lookup.c:1328]: t_newtran(): msg (0x7f051ac799a0) id=5/18097 global id=5/18097 T start=(nil) 0(18097) DEBUG: {1 20 INVITE FdUwYxGLEF} tm [t_lookup.c:497]: t_lookup_request(): start searching: hash=56127, isACK=0 0(18097) DEBUG: {1 20 INVITE FdUwYxGLEF} tm [t_lookup.c:455]: matching_3261(): RFC3261 transaction matching failed - via branch [z9hG4bK.7B8TuSp2h] 0(18097) DEBUG: {1 20 INVITE FdUwYxGLEF} tm [t_lookup.c:675]: t_lookup_request(): no transaction found 0(18097) DEBUG: {1 20 INVITE FdUwYxGLEF} [core/crypto/md5utils.c:67]: MD5StringArray(): MD5 calculated: 9bcaf3821cbb9d948d6b89bd9849307a 0(18097) DEBUG: {1 20 INVITE FdUwYxGLEF} tm [t_funcs.c:328]: t_relay_to(): new INVITE 0(18097) DEBUG: {1 20 INVITE FdUwYxGLEF} tm [t_reply.c:633]: _reply_light(): reply sent out - buf=0x7f051ac7ce60: SIP/2.0 100 trying -... shmem=0x7f05161efbb8: SIP/2.0 100 trying - 0(18097) DEBUG: {1 20 INVITE FdUwYxGLEF} tm [t_reply.c:644]: _reply_light(): finished 0(18097) DEBUG: {1 20 INVITE FdUwYxGLEF} [core/msg_translator.c:1796]: check_boundaries(): no multi-part body 0(18097) DEBUG: {1 20 INVITE FdUwYxGLEF} [core/msg_translator.c:431]: clen_builder(): content-length: 612 (612) 0(18097) DEBUG: {1 20 INVITE FdUwYxGLEF} app_python3 [python_exec.c:93]: apy_exec(): ksr_onsend_route not found or is not callable 0(18097) DEBUG: {1 20 INVITE FdUwYxGLEF} tm [t_funcs.c:376]: t_relay_to(): new transaction forwarded 0(18097) ERROR: {1 20 INVITE FdUwYxGLEF} app_python3 [python_support.c:156]: python_handle_exception(): apy_exec: ksr_request_route((null)): Unhandled exception in the Python code: AttributeError: 'kamailio' object has no attribute 'ksr_onsend_route' The above exception was the direct cause of the following exception: Traceback (most recent call last): File "/root/kam.py", line 76, in ksr_request_route self.ksr_route_relay(msg) File "/root/kam.py", line 110, in ksr_route_relay if KSR.tm.t_relay()<0 : SystemError: returned a result with an error set 0(18097) DEBUG: {1 20 INVITE FdUwYxGLEF} app_python3 [apy_kemi.c:112]: sr_kemi_config_engine_python(): execution of route type 1 with no name returned -1 0(18097) DEBUG: {1 20 INVITE FdUwYxGLEF} [core/receive.c:437]: receive_msg(): request-route executed in: 20245 usec 0(18097) DEBUG: {1 20 INVITE FdUwYxGLEF} [core/usr_avp.c:636]: destroy_avp_list(): destroying list (nil) 0(18097) DEBUG: {1 20 INVITE FdUwYxGLEF} [core/usr_avp.c:636]: destroy_avp_list(): destroying list (nil) 0(18097) DEBUG: {1 20 INVITE FdUwYxGLEF} [core/usr_avp.c:636]: destroy_avp_list(): destroying list (nil) 0(18097) DEBUG: {1 20 INVITE FdUwYxGLEF} [core/usr_avp.c:636]: destroy_avp_list(): destroying list (nil) 0(18097) DEBUG: {1 20 INVITE FdUwYxGLEF} [core/usr_avp.c:636]: destroy_avp_list(): destroying list (nil) 0(18097) DEBUG: {1 20 INVITE FdUwYxGLEF} [core/usr_avp.c:636]: destroy_avp_list(): destroying list (nil) 0(18097) DEBUG: {1 20 INVITE FdUwYxGLEF} [core/xavp.c:539]: xavp_destroy_list(): destroying xavp list (nil) 0(18097) DEBUG: {1 20 INVITE FdUwYxGLEF} [core/xavp.c:539]: xavp_destroy_list(): destroying xavp list (nil) 0(18097) DEBUG: {1 20 INVITE FdUwYxGLEF} [core/xavp.c:539]: xavp_destroy_list(): destroying xavp list (nil) 0(18097) DEBUG: {1 20 INVITE FdUwYxGLEF} [core/receive.c:528]: receive_msg(): cleaning up 0(18097) DEBUG: {1 20 INVITE FdUwYxGLEF} [core/parser/sdp/sdp.c:806]: free_sdp(): _sdp = 0x7f051ac79b88 0(18097) DEBUG: {1 20 INVITE FdUwYxGLEF} [core/parser/sdp/sdp.c:808]: free_sdp(): sdp = 0x7f051ac7c238 0(18097) DEBUG: {1 20 INVITE FdUwYxGLEF} [core/parser/sdp/sdp.c:810]: free_sdp(): session = 0x7f051ac7c2e0 0(18097) DEBUG: [core/udp_server.c:493]: udp_rcv_loop(): received on udp socket: (106/100/718) [[SIP/2.0 180 Ringing 0D 0A Via: SIP/2.0/UDP 192.168.0.101;branch=z9hG4bKf3bd.9bcaf3821cbb9d948d6b89bd98493]] 0(18097) DEBUG: [core/parser/msg_parser.c:620]: parse_msg(): SIP Reply (status): 0(18097) DEBUG: [core/parser/msg_parser.c:622]: parse_msg(): version: 0(18097) DEBUG: [core/parser/msg_parser.c:624]: parse_msg(): status: <180> 0(18097) DEBUG: [core/parser/msg_parser.c:626]: parse_msg(): reason: 0(18097) DEBUG: [core/parser/parse_via.c:1303]: parse_via_param(): Found param type 232, = ; state=16 0(18097) DEBUG: [core/parser/parse_via.c:2639]: parse_via(): end of header reached, state=5 0(18097) DEBUG: [core/parser/msg_parser.c:498]: parse_headers(): Via found, flags=2 0(18097) DEBUG: [core/parser/msg_parser.c:500]: parse_headers(): this is the first via 0(18097) DEBUG: [core/parser/parse_via.c:1303]: parse_via_param(): Found param type 234, = <192.168.0.28>; state=6 0(18097) DEBUG: [core/parser/parse_via.c:1303]: parse_via_param(): Found param type 232, = ; state=6 0(18097) DEBUG: [core/parser/parse_via.c:1303]: parse_via_param(): Found param type 235, = <50045>; state=16 0(18097) DEBUG: [core/parser/parse_via.c:2639]: parse_via(): end of header reached, state=5 0(18097) DEBUG: [core/parser/msg_parser.c:498]: parse_headers(): Via found, flags=78 0(18097) DEBUG: [core/parser/msg_parser.c:511]: parse_headers(): this is the second via 0(18097) DEBUG: [core/parser/parse_addr_spec.c:185]: parse_to_param(): add param: tag=605898205 0(18097) DEBUG: [core/parser/parse_addr_spec.c:864]: parse_addr_spec(): end of header reached, state=29 0(18097) DEBUG: [core/parser/msg_parser.c:171]: get_hdr_field(): [44]; uri=[sip:102@192.168.0.15] 0(18097) DEBUG: [core/parser/msg_parser.c:174]: get_hdr_field(): to body (28)["102" ], to tag (9)[605898205] 0(18097) DEBUG: [core/parser/msg_parser.c:152]: get_hdr_field(): cseq : <20> 0(18097) DEBUG: [core/receive.c:319]: receive_msg(): --- received sip message - reply - call-id: [FdUwYxGLEF] - cseq: [20 INVITE] 0(18097) DEBUG: [core/parser/msg_parser.c:185]: get_hdr_field(): content_length=0 0(18097) DEBUG: [core/parser/msg_parser.c:89]: get_hdr_field(): found end of header 0(18097) DEBUG: {2 20 INVITE FdUwYxGLEF} app_python3 [apy_kemi.c:234]: sr_apy_kemi_exec_func_ex(): execution of method: .info 0(18097) DEBUG: {2 20 INVITE FdUwYxGLEF} app_python3 [apy_kemi.c:266]: sr_apy_kemi_exec_func_ex(): param[1] for: info is str: ===== response - from kamailio python script 0(18097) INFO: {2 20 INVITE FdUwYxGLEF} [core/kemi.c:104]: sr_kemi_core_info(): ===== response - from kamailio python script 0(18097) DEBUG: {2 20 INVITE FdUwYxGLEF} app_python3 [apy_kemi.c:112]: sr_kemi_config_engine_python(): execution of route type 128 with no name returned 1 0(18097) DEBUG: {2 20 INVITE FdUwYxGLEF} tm [t_lookup.c:1034]: t_check_msg(): msg (0x7f051ac799a0) id=6/18097 global id=5/18097 T start=0xffffffffffffffff 0(18097) DEBUG: {2 20 INVITE FdUwYxGLEF} tm [t_lookup.c:912]: t_reply_matching(): t_reply_matching: hash 56127 label 0 branch 0 0(18097) DEBUG: {2 20 INVITE FdUwYxGLEF} tm [t_lookup.c:967]: t_reply_matching(): reply (0x7f051ac799a0) matched an active transaction (T=0x7f05161ec510)! 0(18097) DEBUG: {2 20 INVITE FdUwYxGLEF} tm [t_lookup.c:1104]: t_check_msg(): msg (0x7f051ac799a0) id=6/18097 global id=6/18097 T end=0x7f05161ec510 0(18097) DEBUG: {2 20 INVITE FdUwYxGLEF} tm [t_reply.c:2352]: reply_received(): transaction found - T:0x7f05161ec510 branch:0 0(18097) DEBUG: {2 20 INVITE FdUwYxGLEF} tm [t_reply.c:2365]: reply_received(): original status uas=100, uac[0]=0 local=0 is_invite=1) 0(18097) DEBUG: {2 20 INVITE FdUwYxGLEF} app_python3 [apy_kemi.c:234]: sr_apy_kemi_exec_func_ex(): execution of method: .dbg 0(18097) DEBUG: {2 20 INVITE FdUwYxGLEF} app_python3 [apy_kemi.c:266]: sr_apy_kemi_exec_func_ex(): param[1] for: dbg is str: incoming reply 0(18097) DEBUG: {2 20 INVITE FdUwYxGLEF} [core/kemi.c:84]: sr_kemi_core_dbg(): incoming reply 0(18097) DEBUG: {2 20 INVITE FdUwYxGLEF} app_python3 [apy_kemi.c:232]: sr_apy_kemi_exec_func_ex(): execution of method: has_body 0(18097) DEBUG: {2 20 INVITE FdUwYxGLEF} textops [textops.c:3807]: has_body_helper(): content length is zero 0(18097) DEBUG: {2 20 INVITE FdUwYxGLEF} app_python3 [apy_kemi.c:232]: sr_apy_kemi_exec_func_ex(): execution of method: rtpengine_manage 0(18097) DEBUG: {2 20 INVITE FdUwYxGLEF} app_python3 [apy_kemi.c:266]: sr_apy_kemi_exec_func_ex(): param[1] for: rtpengine_manage is str: asymmetric 0(18097) DEBUG: {2 20 INVITE FdUwYxGLEF} [core/parser/sdp/sdp.c:725]: parse_sdp(): message body has length zero 0(18097) DEBUG: {2 20 INVITE FdUwYxGLEF} app_python3 [apy_kemi.c:109]: sr_kemi_config_engine_python(): execution of route type 4 with name [ksr_onreply_manage] returned 1 0(18097) DEBUG: {2 20 INVITE FdUwYxGLEF} tm [t_reply.c:1359]: t_should_relay_response(): ->>>>>>>>> T_code=100, new_code=180 0(18097) DEBUG: {2 20 INVITE FdUwYxGLEF} tm [t_reply.c:1609]: t_should_relay_response(): rps provisional - uas status: 100 0(18097) DEBUG: {2 20 INVITE FdUwYxGLEF} tm [t_reply.c:1922]: relay_reply(): reply status=5 branch=0, save=0, relay=0 icode=0 msg status=180 0(18097) DEBUG: {2 20 INVITE FdUwYxGLEF} [core/msg_translator.c:2325]: generate_res_buf_from_sip_res(): old size: 718, new size: 632 0(18097) DEBUG: {2 20 INVITE FdUwYxGLEF} [core/msg_translator.c:2342]: generate_res_buf_from_sip_res(): copied size: orig:107, new: 21, rest: 611 msg= SIP/2.0 180 Ringing Via: SIP/2.0/UDP 192.168.0.28:50045;received=192.168.0.28;branch=z9hG4bK.7B8TuSp2h;rport=50045 Record-Route: From: "myali" ;tag=ILonsDQko To: "102" ;tag=605898205 Call-ID: FdUwYxGLEF CSeq: 20 INVITE Allow: INVITE, ACK, CANCEL, BYE, NOTIFY, REFER, OPTIONS, UPDATE, PRACK, SUBSCRIBE, INFO Allow-Events: talk, hold, conference, LocalModeStatus Contact: "102" ;+sip.instance="" Server: Aastra 57iCT/3.2.2.2104 Supported: path Content-Length: 0 0(18097) DEBUG: {2 20 INVITE FdUwYxGLEF} tm [t_reply.c:2119]: relay_reply(): reply buffer sent out 0(18097) DEBUG: {2 20 INVITE FdUwYxGLEF} [core/receive.c:518]: receive_msg(): reply-route executed in: 477 usec 0(18097) DEBUG: {2 20 INVITE FdUwYxGLEF} [core/usr_avp.c:636]: destroy_avp_list(): destroying list (nil) 0(18097) DEBUG: {2 20 INVITE FdUwYxGLEF} [core/usr_avp.c:636]: destroy_avp_list(): destroying list (nil) 0(18097) DEBUG: {2 20 INVITE FdUwYxGLEF} [core/usr_avp.c:636]: destroy_avp_list(): destroying list (nil) 0(18097) DEBUG: {2 20 INVITE FdUwYxGLEF} [core/usr_avp.c:636]: destroy_avp_list(): destroying list (nil) 0(18097) DEBUG: {2 20 INVITE FdUwYxGLEF} [core/usr_avp.c:636]: destroy_avp_list(): destroying list (nil) 0(18097) DEBUG: {2 20 INVITE FdUwYxGLEF} [core/usr_avp.c:636]: destroy_avp_list(): destroying list (nil) 0(18097) DEBUG: {2 20 INVITE FdUwYxGLEF} [core/xavp.c:539]: xavp_destroy_list(): destroying xavp list (nil) 0(18097) DEBUG: {2 20 INVITE FdUwYxGLEF} [core/xavp.c:539]: xavp_destroy_list(): destroying xavp list (nil) 0(18097) DEBUG: {2 20 INVITE FdUwYxGLEF} [core/xavp.c:539]: xavp_destroy_list(): destroying xavp list (nil) 0(18097) DEBUG: {2 20 INVITE FdUwYxGLEF} [core/receive.c:528]: receive_msg(): cleaning up 0(18097) DEBUG: [core/udp_server.c:493]: udp_rcv_loop(): received on udp socket: (106/100/979) [[SIP/2.0 200 OK 0D 0A Via: SIP/2.0/UDP 192.168.0.101;branch=z9hG4bKf3bd.9bcaf3821cbb9d948d6b89bd9849307a.0]] 0(18097) DEBUG: [core/parser/msg_parser.c:620]: parse_msg(): SIP Reply (status): 0(18097) DEBUG: [core/parser/msg_parser.c:622]: parse_msg(): version: 0(18097) DEBUG: [core/parser/msg_parser.c:624]: parse_msg(): status: <200> 0(18097) DEBUG: [core/parser/msg_parser.c:626]: parse_msg(): reason: 0(18097) DEBUG: [core/parser/parse_via.c:1303]: parse_via_param(): Found param type 232, = ; state=16 0(18097) DEBUG: [core/parser/parse_via.c:2639]: parse_via(): end of header reached, state=5 0(18097) DEBUG: [core/parser/msg_parser.c:498]: parse_headers(): Via found, flags=2 0(18097) DEBUG: [core/parser/msg_parser.c:500]: parse_headers(): this is the first via 0(18097) DEBUG: [core/parser/parse_via.c:1303]: parse_via_param(): Found param type 234, = <192.168.0.28>; state=6 0(18097) DEBUG: [core/parser/parse_via.c:1303]: parse_via_param(): Found param type 232, = ; state=6 0(18097) DEBUG: [core/parser/parse_via.c:1303]: parse_via_param(): Found param type 235, = <50045>; state=16 0(18097) DEBUG: [core/parser/parse_via.c:2639]: parse_via(): end of header reached, state=5 0(18097) DEBUG: [core/parser/msg_parser.c:498]: parse_headers(): Via found, flags=78 0(18097) DEBUG: [core/parser/msg_parser.c:511]: parse_headers(): this is the second via 0(18097) DEBUG: [core/parser/parse_addr_spec.c:185]: parse_to_param(): add param: tag=605898205 0(18097) DEBUG: [core/parser/parse_addr_spec.c:864]: parse_addr_spec(): end of header reached, state=29 0(18097) DEBUG: [core/parser/msg_parser.c:171]: get_hdr_field(): [44]; uri=[sip:102@192.168.0.15] 0(18097) DEBUG: [core/parser/msg_parser.c:174]: get_hdr_field(): to body (28)["102" ], to tag (9)[605898205] 0(18097) DEBUG: [core/parser/msg_parser.c:152]: get_hdr_field(): cseq : <20> 0(18097) DEBUG: [core/receive.c:319]: receive_msg(): --- received sip message - reply - call-id: [FdUwYxGLEF] - cseq: [20 INVITE] 0(18097) DEBUG: [core/parser/msg_parser.c:185]: get_hdr_field(): content_length=223 0(18097) DEBUG: [core/parser/msg_parser.c:89]: get_hdr_field(): found end of header 0(18097) DEBUG: {2 20 INVITE FdUwYxGLEF} app_python3 [apy_kemi.c:234]: sr_apy_kemi_exec_func_ex(): execution of method: .info 0(18097) DEBUG: {2 20 INVITE FdUwYxGLEF} app_python3 [apy_kemi.c:266]: sr_apy_kemi_exec_func_ex(): param[1] for: info is str: ===== response - from kamailio python script 0(18097) INFO: {2 20 INVITE FdUwYxGLEF} [core/kemi.c:104]: sr_kemi_core_info(): ===== response - from kamailio python script 0(18097) DEBUG: {2 20 INVITE FdUwYxGLEF} app_python3 [apy_kemi.c:112]: sr_kemi_config_engine_python(): execution of route type 128 with no name returned 1 0(18097) DEBUG: {2 20 INVITE FdUwYxGLEF} tm [t_lookup.c:1034]: t_check_msg(): msg (0x7f051ac799a0) id=7/18097 global id=6/18097 T start=0xffffffffffffffff 0(18097) DEBUG: {2 20 INVITE FdUwYxGLEF} tm [t_lookup.c:912]: t_reply_matching(): t_reply_matching: hash 56127 label 0 branch 0 0(18097) DEBUG: {2 20 INVITE FdUwYxGLEF} tm [t_lookup.c:967]: t_reply_matching(): reply (0x7f051ac799a0) matched an active transaction (T=0x7f05161ec510)! 0(18097) DEBUG: {2 20 INVITE FdUwYxGLEF} tm [t_lookup.c:1104]: t_check_msg(): msg (0x7f051ac799a0) id=7/18097 global id=7/18097 T end=0x7f05161ec510 0(18097) DEBUG: {2 20 INVITE FdUwYxGLEF} tm [t_reply.c:2352]: reply_received(): transaction found - T:0x7f05161ec510 branch:0 0(18097) DEBUG: {2 20 INVITE FdUwYxGLEF} tm [t_reply.c:2365]: reply_received(): original status uas=180, uac[0]=180 local=0 is_invite=1) 0(18097) DEBUG: {2 20 INVITE FdUwYxGLEF} app_python3 [apy_kemi.c:234]: sr_apy_kemi_exec_func_ex(): execution of method: .dbg 0(18097) DEBUG: {2 20 INVITE FdUwYxGLEF} app_python3 [apy_kemi.c:266]: sr_apy_kemi_exec_func_ex(): param[1] for: dbg is str: incoming reply 0(18097) DEBUG: {2 20 INVITE FdUwYxGLEF} [core/kemi.c:84]: sr_kemi_core_dbg(): incoming reply 0(18097) DEBUG: {2 20 INVITE FdUwYxGLEF} app_python3 [apy_kemi.c:232]: sr_apy_kemi_exec_func_ex(): execution of method: has_body 0(18097) DEBUG: {2 20 INVITE FdUwYxGLEF} app_python3 [apy_kemi.c:232]: sr_apy_kemi_exec_func_ex(): execution of method: rtpengine_manage 0(18097) DEBUG: {2 20 INVITE FdUwYxGLEF} app_python3 [apy_kemi.c:266]: sr_apy_kemi_exec_func_ex(): param[1] for: rtpengine_manage is str: asymmetric 0(18097) DEBUG: {2 20 INVITE FdUwYxGLEF} [core/parser/sdp/sdp_helpr_funcs.c:619]: extract_sess_version(): oline(33): >o=MxSIP 0 1 IN IP4 192.168.0.15 < 0(18097) DEBUG: {2 20 INVITE FdUwYxGLEF} [core/parser/sdp/sdp_helpr_funcs.c:648]: extract_sess_version(): end 1: >1< 0(18097) DEBUG: {2 20 INVITE FdUwYxGLEF} [core/parser/sdp/sdp_helpr_funcs.c:503]: extract_mediaip(): located IP address [192.168.0.15] in `o=' field 0(18097) DEBUG: {2 20 INVITE FdUwYxGLEF} [core/parser/sdp/sdp_helpr_funcs.c:503]: extract_mediaip(): located IP address [192.168.0.15] in `c=' field 0(18097) DEBUG: {2 20 INVITE FdUwYxGLEF} [core/parser/sdp/sdp.c:587]: parse_sdp_session(): ignoring unknown type in a= line: `a=silenceSupp:off - - - - a=fmtp:100 0-15 a=sendrecv ' 0(18097) DEBUG: {2 20 INVITE FdUwYxGLEF} [core/parser/parse_addr_spec.c:185]: parse_to_param(): add param: tag=ILonsDQko 0(18097) DEBUG: {2 20 INVITE FdUwYxGLEF} [core/parser/parse_addr_spec.c:864]: parse_addr_spec(): end of header reached, state=29 0(18097) DEBUG: {2 20 INVITE FdUwYxGLEF} rtpengine [rtpengine_funcs.c:144]: check_content_type(): type found valid 0(18097) DEBUG: {2 20 INVITE FdUwYxGLEF} rtpengine [rtpengine.c:3106]: select_rtpp_node_old(): rtpengine hash table lookup find node=udp:127.0.0.1:2223 for calllen=10 callid=FdUwYxGLEF viabranch= 0(18097) DEBUG: {2 20 INVITE FdUwYxGLEF} rtpengine [rtpengine.c:2579]: rtpp_function_call(): proxy reply: d3:sdp239:v=0 o=MxSIP 0 1 IN IP4 192.168.0.15 s=SIP Call c=IN IP4 192.168.0.101 t=0 0 m=audio 32402 RTP/AVP 18 100 a=silenceSupp:off - - - - a=rtpmap:18 G729/8000 a=rtpmap:100 telephone-event/8000 a=fmtp:100 0-15 a=sendrecv a=rtcp:32403 6:result2:oke 0(18097) DEBUG: {2 20 INVITE FdUwYxGLEF} app_python3 [apy_kemi.c:109]: sr_kemi_config_engine_python(): execution of route type 4 with name [ksr_onreply_manage] returned 1 0(18097) DEBUG: {2 20 INVITE FdUwYxGLEF} tm [t_reply.c:1359]: t_should_relay_response(): ->>>>>>>>> T_code=180, new_code=200 0(18097) DEBUG: {2 20 INVITE FdUwYxGLEF} tm [t_reply.c:1606]: t_should_relay_response(): rps completed - uas status: 180 0(18097) DEBUG: {2 20 INVITE FdUwYxGLEF} tm [t_reply.c:1922]: relay_reply(): reply status=4 branch=0, save=0, relay=0 icode=0 msg status=200 0(18097) DEBUG: {2 20 INVITE FdUwYxGLEF} [core/msg_translator.c:431]: clen_builder(): content-length: 239 (239) 0(18097) DEBUG: {2 20 INVITE FdUwYxGLEF} [core/msg_translator.c:2325]: generate_res_buf_from_sip_res(): old size: 979, new size: 909 0(18097) DEBUG: {2 20 INVITE FdUwYxGLEF} [core/msg_translator.c:2342]: generate_res_buf_from_sip_res(): copied size: orig:979, new: 909, rest: 0 msg= SIP/2.0 200 OK Via: SIP/2.0/UDP 192.168.0.28:50045;received=192.168.0.28;branch=z9hG4bK.7B8TuSp2h;rport=50045 Record-Route: From: "myali" ;tag=ILonsDQko To: "102" ;tag=605898205 Call-ID: FdUwYxGLEF CSeq: 20 INVITE Allow: INVITE, ACK, CANCEL, BYE, NOTIFY, REFER, OPTIONS, UPDATE, PRACK, SUBSCRIBE, INFO Allow-Events: talk, hold, conference, LocalModeStatus Contact: "102" ;+sip.instance="" Server: Aastra 57iCT/3.2.2.2104 Supported: path, replaces Content-Type: application/sdp Content-Length: 239 v=0 o=MxSIP 0 1 IN IP4 192.168.0.15 s=SIP Call c=IN IP4 192.168.0.101 t=0 0 m=audio 32402 RTP/AVP 18 100 a=silenceSupp:off - - - - a=rtpmap:18 G729/8000 a=rtpmap:100 telephone-event/8000 a=fmtp:100 0-15 a=sendrecv a=rtcp:32403 0(18097) DEBUG: {2 20 INVITE FdUwYxGLEF} tm [t_reply.c:2119]: relay_reply(): reply buffer sent out 0(18097) DEBUG: {2 20 INVITE FdUwYxGLEF} tm [t_reply.c:1761]: cleanup_uac_timers(): RETR/FR timers reset 0(18097) DEBUG: {2 20 INVITE FdUwYxGLEF} [core/receive.c:518]: receive_msg(): reply-route executed in: 5414 usec 0(18097) DEBUG: {2 20 INVITE FdUwYxGLEF} [core/usr_avp.c:636]: destroy_avp_list(): destroying list (nil) 0(18097) DEBUG: {2 20 INVITE FdUwYxGLEF} [core/usr_avp.c:636]: destroy_avp_list(): destroying list (nil) 0(18097) DEBUG: {2 20 INVITE FdUwYxGLEF} [core/usr_avp.c:636]: destroy_avp_list(): destroying list (nil) 0(18097) DEBUG: {2 20 INVITE FdUwYxGLEF} [core/usr_avp.c:636]: destroy_avp_list(): destroying list (nil) 0(18097) DEBUG: {2 20 INVITE FdUwYxGLEF} [core/usr_avp.c:636]: destroy_avp_list(): destroying list (nil) 0(18097) DEBUG: {2 20 INVITE FdUwYxGLEF} [core/usr_avp.c:636]: destroy_avp_list(): destroying list (nil) 0(18097) DEBUG: {2 20 INVITE FdUwYxGLEF} [core/xavp.c:539]: xavp_destroy_list(): destroying xavp list (nil) 0(18097) DEBUG: {2 20 INVITE FdUwYxGLEF} [core/xavp.c:539]: xavp_destroy_list(): destroying xavp list (nil) 0(18097) DEBUG: {2 20 INVITE FdUwYxGLEF} [core/xavp.c:539]: xavp_destroy_list(): destroying xavp list (nil) 0(18097) DEBUG: {2 20 INVITE FdUwYxGLEF} [core/receive.c:528]: receive_msg(): cleaning up 0(18097) DEBUG: {2 20 INVITE FdUwYxGLEF} [core/parser/sdp/sdp.c:806]: free_sdp(): _sdp = 0x7f051ac79b88 0(18097) DEBUG: {2 20 INVITE FdUwYxGLEF} [core/parser/sdp/sdp.c:808]: free_sdp(): sdp = 0x7f051ac7b3c0 0(18097) DEBUG: {2 20 INVITE FdUwYxGLEF} [core/parser/sdp/sdp.c:810]: free_sdp(): session = 0x7f051ac7b468 0(18097) DEBUG: [core/udp_server.c:493]: udp_rcv_loop(): received on udp socket: (106/100/367) [[ACK sip:102@192.168.0.15:5060;transport=udp SIP/2.0 0D 0A Via: SIP/2.0/UDP 192.168.0.28:50045;rport;branc]] 0(18097) DEBUG: [core/parser/msg_parser.c:610]: parse_msg(): SIP Request: 0(18097) DEBUG: [core/parser/msg_parser.c:612]: parse_msg(): method: 0(18097) DEBUG: [core/parser/msg_parser.c:614]: parse_msg(): uri: 0(18097) DEBUG: [core/parser/msg_parser.c:616]: parse_msg(): version: 0(18097) DEBUG: [core/parser/parse_via.c:1303]: parse_via_param(): Found param type 235, = ; state=6 0(18097) DEBUG: [core/parser/parse_via.c:1303]: parse_via_param(): Found param type 232, = ; state=16 0(18097) DEBUG: [core/parser/parse_via.c:2639]: parse_via(): end of header reached, state=5 0(18097) DEBUG: [core/parser/msg_parser.c:498]: parse_headers(): Via found, flags=2 0(18097) DEBUG: [core/parser/msg_parser.c:500]: parse_headers(): this is the first via 0(18097) DEBUG: [core/parser/parse_addr_spec.c:185]: parse_to_param(): add param: tag=605898205 0(18097) DEBUG: [core/parser/parse_addr_spec.c:864]: parse_addr_spec(): end of header reached, state=29 0(18097) DEBUG: [core/parser/msg_parser.c:171]: get_hdr_field(): [44]; uri=[sip:102@192.168.0.15] 0(18097) DEBUG: [core/parser/msg_parser.c:174]: get_hdr_field(): to body (28)["102" ], to tag (9)[605898205] 0(18097) DEBUG: [core/parser/msg_parser.c:152]: get_hdr_field(): cseq : <20> 0(18097) DEBUG: [core/receive.c:319]: receive_msg(): --- received sip message - request - call-id: [FdUwYxGLEF] - cseq: [20 ACK] 0(18097) DEBUG: [core/parser/msg_parser.c:89]: get_hdr_field(): found end of header 0(18097) DEBUG: {1 20 ACK FdUwYxGLEF} [core/receive.c:379]: receive_msg(): preparing to run routing scripts... 0(18097) DEBUG: {1 20 ACK FdUwYxGLEF} sl [sl_funcs.c:443]: sl_filter_ACK(): too late to be a local ACK! 0(18097) DEBUG: {1 20 ACK FdUwYxGLEF} app_python3 [apy_kemi.c:234]: sr_apy_kemi_exec_func_ex(): execution of method: .is_method_in 0(18097) DEBUG: {1 20 ACK FdUwYxGLEF} app_python3 [apy_kemi.c:266]: sr_apy_kemi_exec_func_ex(): param[1] for: is_method_in is str: RS 0(18097) DEBUG: {1 20 ACK FdUwYxGLEF} app_python3 [apy_kemi.c:232]: sr_apy_kemi_exec_func_ex(): execution of method: process_maxfwd 0(18097) DEBUG: {1 20 ACK FdUwYxGLEF} app_python3 [apy_kemi.c:258]: sr_apy_kemi_exec_func_ex(): param[1] for: process_maxfwd is int: 10 0(18097) DEBUG: {1 20 ACK FdUwYxGLEF} maxfwd [mf_funcs.c:74]: is_maxfwd_present(): value = 70 0(18097) DEBUG: {1 20 ACK FdUwYxGLEF} app_python3 [apy_kemi.c:234]: sr_apy_kemi_exec_func_ex(): execution of method: .is_OPTIONS 0(18097) DEBUG: {1 20 ACK FdUwYxGLEF} app_python3 [apy_kemi.c:232]: sr_apy_kemi_exec_func_ex(): execution of method: sanity_check 0(18097) DEBUG: {1 20 ACK FdUwYxGLEF} app_python3 [apy_kemi.c:279]: sr_apy_kemi_exec_func_ex(): params[2] for: sanity_check are int-int: [1511] [7] 0(18097) DEBUG: {1 20 ACK FdUwYxGLEF} sanity [sanity.c:247]: check_ruri_sip_version(): check_ruri_sip_version entered 0(18097) DEBUG: {1 20 ACK FdUwYxGLEF} sanity [sanity.c:270]: check_ruri_sip_version(): check_ruri_sip_version passed 0(18097) DEBUG: {1 20 ACK FdUwYxGLEF} sanity [sanity.c:277]: check_ruri_scheme(): check_ruri_scheme entered 0(18097) DEBUG: {1 20 ACK FdUwYxGLEF} sanity [sanity.c:297]: check_ruri_scheme(): check_ruri_scheme passed 0(18097) DEBUG: {1 20 ACK FdUwYxGLEF} sanity [sanity.c:318]: check_required_headers(): check_required_headers entered 0(18097) DEBUG: {1 20 ACK FdUwYxGLEF} sanity [sanity.c:340]: check_required_headers(): check_required_headers passed 0(18097) DEBUG: {1 20 ACK FdUwYxGLEF} sanity [sanity.c:506]: check_cseq_method(): check_cseq_method entered 0(18097) DEBUG: {1 20 ACK FdUwYxGLEF} sanity [sanity.c:539]: check_cseq_method(): check_cseq_method passed 0(18097) DEBUG: {1 20 ACK FdUwYxGLEF} sanity [sanity.c:548]: check_cseq_value(): check_cseq_value entered 0(18097) DEBUG: {1 20 ACK FdUwYxGLEF} sanity [sanity.c:576]: check_cseq_value(): check_cseq_value passed 0(18097) DEBUG: {1 20 ACK FdUwYxGLEF} sanity [sanity.c:585]: check_cl(): check_cl entered 0(18097) WARNING: {1 20 ACK FdUwYxGLEF} sanity [sanity.c:612]: check_cl(): content length header missing in request 0(18097) DEBUG: {1 20 ACK FdUwYxGLEF} sanity [sanity.c:622]: check_expires_value(): check_expires_value entered 0(18097) DEBUG: {1 20 ACK FdUwYxGLEF} sanity [sanity.c:659]: check_expires_value(): no expires header found 0(18097) DEBUG: {1 20 ACK FdUwYxGLEF} sanity [sanity.c:759]: check_parse_uris(): check_parse_uris entered 0(18097) DEBUG: {1 20 ACK FdUwYxGLEF} sanity [sanity.c:763]: check_parse_uris(): parsing ruri 0(18097) DEBUG: {1 20 ACK FdUwYxGLEF} sanity [sanity.c:777]: check_parse_uris(): looking up From header 0(18097) DEBUG: {1 20 ACK FdUwYxGLEF} sanity [sanity.c:791]: check_parse_uris(): parsing From header 0(18097) DEBUG: {1 20 ACK FdUwYxGLEF} [core/parser/parse_addr_spec.c:185]: parse_to_param(): add param: tag=ILonsDQko 0(18097) DEBUG: {1 20 ACK FdUwYxGLEF} [core/parser/parse_addr_spec.c:864]: parse_addr_spec(): end of header reached, state=29 0(18097) DEBUG: {1 20 ACK FdUwYxGLEF} sanity [sanity.c:817]: check_parse_uris(): parsing From URI 0(18097) DEBUG: {1 20 ACK FdUwYxGLEF} sanity [sanity.c:835]: check_parse_uris(): looking up To header 0(18097) DEBUG: {1 20 ACK FdUwYxGLEF} sanity [sanity.c:857]: check_parse_uris(): check_parse_uris(): parsing To URI 0(18097) DEBUG: {1 20 ACK FdUwYxGLEF} sanity [sanity.c:902]: check_parse_uris(): check_parse_uris passed 0(18097) DEBUG: {1 20 ACK FdUwYxGLEF} app_python3 [apy_kemi.c:234]: sr_apy_kemi_exec_func_ex(): execution of method: .is_CANCEL 0(18097) DEBUG: {1 20 ACK FdUwYxGLEF} app_python3 [apy_kemi.c:232]: sr_apy_kemi_exec_func_ex(): execution of method: has_totag 0(18097) DEBUG: {1 20 ACK FdUwYxGLEF} siputils [checks.c:123]: has_totag(): totag found 0(18097) DEBUG: {1 20 ACK FdUwYxGLEF} app_python3 [apy_kemi.c:232]: sr_apy_kemi_exec_func_ex(): execution of method: loose_route 0(18097) DEBUG: {1 20 ACK FdUwYxGLEF} rr [loose.c:85]: is_preloaded(): is_preloaded: No 0(18097) DEBUG: {1 20 ACK FdUwYxGLEF} [core/socket_info.c:641]: grep_sock_info(): checking if host==us: 12==13 && [192.168.0.15] == [192.168.0.101] 0(18097) DEBUG: {1 20 ACK FdUwYxGLEF} [core/socket_info.c:648]: grep_sock_info(): checking if port 5060 (advertise 0) matches port 5060 0(18097) DEBUG: {1 20 ACK FdUwYxGLEF} [core/socket_info.c:641]: grep_sock_info(): checking if host==us: 12==13 && [192.168.0.15] == [192.168.0.201] 0(18097) DEBUG: {1 20 ACK FdUwYxGLEF} [core/socket_info.c:648]: grep_sock_info(): checking if port 5060 (advertise 0) matches port 5060 0(18097) DEBUG: {1 20 ACK FdUwYxGLEF} [core/forward.c:424]: check_self(): host (0:192.168.0.15:5060) != me 0(18097) DEBUG: {1 20 ACK FdUwYxGLEF} [core/socket_info.c:641]: grep_sock_info(): checking if host==us: 13==13 && [192.168.0.101] == [192.168.0.101] 0(18097) DEBUG: {1 20 ACK FdUwYxGLEF} [core/socket_info.c:648]: grep_sock_info(): checking if port 5060 (advertise 0) matches port 5060 0(18097) DEBUG: {1 20 ACK FdUwYxGLEF} [core/forward.c:422]: check_self(): host (0:192.168.0.101:5060) == me 0(18097) DEBUG: {1 20 ACK FdUwYxGLEF} rr [loose.c:850]: after_loose(): Topmost route URI: 'sip:192.168.0.101;lr' is me 0(18097) DEBUG: {1 20 ACK FdUwYxGLEF} [core/parser/msg_parser.c:89]: get_hdr_field(): found end of header 0(18097) DEBUG: {1 20 ACK FdUwYxGLEF} rr [loose.c:176]: find_next_route(): No next Route HF found 0(18097) DEBUG: {1 20 ACK FdUwYxGLEF} rr [loose.c:881]: after_loose(): No next URI found 0(18097) DEBUG: {1 20 ACK FdUwYxGLEF} app_python3 [apy_kemi.c:234]: sr_apy_kemi_exec_func_ex(): execution of method: .is_NOTIFY 0(18097) DEBUG: {1 20 ACK FdUwYxGLEF} app_python3 [apy_kemi.c:234]: sr_apy_kemi_exec_func_ex(): execution of method: .is_method_in 0(18097) DEBUG: {1 20 ACK FdUwYxGLEF} app_python3 [apy_kemi.c:266]: sr_apy_kemi_exec_func_ex(): param[1] for: is_method_in is str: ISU 0(18097) DEBUG: {1 20 ACK FdUwYxGLEF} app_python3 [apy_kemi.c:234]: sr_apy_kemi_exec_func_ex(): execution of method: .is_INVITE 0(18097) DEBUG: {1 20 ACK FdUwYxGLEF} app_python3 [apy_kemi.c:232]: sr_apy_kemi_exec_func_ex(): execution of method: has_body 0(18097) DEBUG: {1 20 ACK FdUwYxGLEF} app_python3 [apy_kemi.c:232]: sr_apy_kemi_exec_func_ex(): execution of method: rtpengine_manage 0(18097) DEBUG: {1 20 ACK FdUwYxGLEF} app_python3 [apy_kemi.c:266]: sr_apy_kemi_exec_func_ex(): param[1] for: rtpengine_manage is str: asymmetric 0(18097) DEBUG: {1 20 ACK FdUwYxGLEF} [core/parser/sdp/sdp.c:725]: parse_sdp(): message body has length zero 0(18097) DEBUG: {1 20 ACK FdUwYxGLEF} app_python3 [apy_kemi.c:232]: sr_apy_kemi_exec_func_ex(): execution of method: t_relay 0(18097) DEBUG: {1 20 ACK FdUwYxGLEF} tm [t_lookup.c:1328]: t_newtran(): msg (0x7f051ac799a0) id=8/18097 global id=7/18097 T start=0xffffffffffffffff 0(18097) DEBUG: {1 20 ACK FdUwYxGLEF} tm [t_lookup.c:497]: t_lookup_request(): start searching: hash=56127, isACK=1 0(18097) DEBUG: {1 20 ACK FdUwYxGLEF} tm [t_lookup.c:455]: matching_3261(): RFC3261 transaction matching failed - via branch [z9hG4bK.VeeAew9Rk] 0(18097) DEBUG: {1 20 ACK FdUwYxGLEF} tm [t_lookup.c:675]: t_lookup_request(): no transaction found 0(18097) DEBUG: {1 20 ACK FdUwYxGLEF} tm [t_funcs.c:286]: t_relay_to(): forwarding ACK statelessly 0(18097) DEBUG: {1 20 ACK FdUwYxGLEF} [core/crypto/md5utils.c:67]: MD5StringArray(): MD5 calculated: 10404fb0207ef93ee75468bb7de379d2 0(18097) DEBUG: {1 20 ACK FdUwYxGLEF} [core/msg_translator.c:1796]: check_boundaries(): no multi-part body 0(18097) DEBUG: {1 20 ACK FdUwYxGLEF} [core/forward.c:570]: forward_request(): Sending: ACK sip:102@192.168.0.15:5060;transport=udp SIP/2.0 Via: SIP/2.0/UDP 192.168.0.101;branch=z9hG4bKf3bd.10404fb0207ef93ee75468bb7de379d2.0 Via: SIP/2.0/UDP 192.168.0.28:50045;received=192.168.0.28;rport=50045;branch=z9hG4bK.VeeAew9Rk From: "myali" ;tag=ILonsDQko To: "102" ;tag=605898205 CSeq: 20 ACK Call-ID: FdUwYxGLEF Max-Forwards: 69 User-Agent: LinphoneiOS/4.3.2 (iPhone) LinphoneSDK/4.4.2 . 0(18097) DEBUG: {1 20 ACK FdUwYxGLEF} [core/forward.c:571]: forward_request(): orig. len=367, new_len=450, proto=1 0(18097) DEBUG: {1 20 ACK FdUwYxGLEF} app_python3 [python_exec.c:93]: apy_exec(): ksr_onsend_route not found or is not callable 0(18097) ERROR: {1 20 ACK FdUwYxGLEF} app_python3 [python_support.c:156]: python_handle_exception(): apy_exec: ksr_request_route((null)): Unhandled exception in the Python code: AttributeError: 'kamailio' object has no attribute 'ksr_onsend_route' The above exception was the direct cause of the following exception: Traceback (most recent call last): File "/root/kam.py", line 57, in ksr_request_route if self.ksr_route_withindlg(msg)==-255 : File "/root/kam.py", line 131, in ksr_route_withindlg self.ksr_route_relay(msg) File "/root/kam.py", line 110, in ksr_route_relay if KSR.tm.t_relay()<0 : SystemError: returned a result with an error set 0(18097) DEBUG: {1 20 ACK FdUwYxGLEF} app_python3 [apy_kemi.c:112]: sr_kemi_config_engine_python(): execution of route type 1 with no name returned -1 0(18097) DEBUG: {1 20 ACK FdUwYxGLEF} [core/receive.c:437]: receive_msg(): request-route executed in: 634 usec 0(18097) DEBUG: {1 20 ACK FdUwYxGLEF} [core/usr_avp.c:636]: destroy_avp_list(): destroying list (nil) 0(18097) DEBUG: {1 20 ACK FdUwYxGLEF} [core/usr_avp.c:636]: destroy_avp_list(): destroying list (nil) 0(18097) DEBUG: {1 20 ACK FdUwYxGLEF} [core/usr_avp.c:636]: destroy_avp_list(): destroying list (nil) 0(18097) DEBUG: {1 20 ACK FdUwYxGLEF} [core/usr_avp.c:636]: destroy_avp_list(): destroying list (nil) 0(18097) DEBUG: {1 20 ACK FdUwYxGLEF} [core/usr_avp.c:636]: destroy_avp_list(): destroying list (nil) 0(18097) DEBUG: {1 20 ACK FdUwYxGLEF} [core/usr_avp.c:636]: destroy_avp_list(): destroying list (nil) 0(18097) DEBUG: {1 20 ACK FdUwYxGLEF} [core/xavp.c:539]: xavp_destroy_list(): destroying xavp list (nil) 0(18097) DEBUG: {1 20 ACK FdUwYxGLEF} [core/xavp.c:539]: xavp_destroy_list(): destroying xavp list (nil) 0(18097) DEBUG: {1 20 ACK FdUwYxGLEF} [core/xavp.c:539]: xavp_destroy_list(): destroying xavp list (nil) 0(18097) DEBUG: {1 20 ACK FdUwYxGLEF} [core/receive.c:528]: receive_msg(): cleaning up 2(18100) DEBUG: [core/timer.c:422]: adjust_ticks(): adjusting timer ticks (465097845) with 437 ms (7 ticks) 2(18100) DEBUG: tm [timer.c:634]: wait_handler(): finished transaction: 0x7f05161ec510 (p:0x7f051618ded0/n:0x7f051618ded0) 2(18100) DEBUG: tm [h_table.c:132]: free_cell_helper(): freeing transaction 0x7f05161ec510 from timer.c:643 0(18097) DEBUG: [core/udp_server.c:493]: udp_rcv_loop(): received on udp socket: (106/100/367) [[BYE sip:102@192.168.0.15:5060;transport=udp SIP/2.0 0D 0A Via: SIP/2.0/UDP 192.168.0.28:50045;branch=z9hG]] 0(18097) DEBUG: [core/parser/msg_parser.c:610]: parse_msg(): SIP Request: 0(18097) DEBUG: [core/parser/msg_parser.c:612]: parse_msg(): method: 0(18097) DEBUG: [core/parser/msg_parser.c:614]: parse_msg(): uri: 0(18097) DEBUG: [core/parser/msg_parser.c:616]: parse_msg(): version: 0(18097) DEBUG: [core/parser/parse_via.c:1303]: parse_via_param(): Found param type 232, = ; state=6 0(18097) DEBUG: [core/parser/parse_via.c:1303]: parse_via_param(): Found param type 235, = ; state=17 0(18097) DEBUG: [core/parser/parse_via.c:2639]: parse_via(): end of header reached, state=5 0(18097) DEBUG: [core/parser/msg_parser.c:498]: parse_headers(): Via found, flags=2 0(18097) DEBUG: [core/parser/msg_parser.c:500]: parse_headers(): this is the first via 0(18097) DEBUG: [core/parser/parse_addr_spec.c:185]: parse_to_param(): add param: tag=605898205 0(18097) DEBUG: [core/parser/parse_addr_spec.c:864]: parse_addr_spec(): end of header reached, state=29 0(18097) DEBUG: [core/parser/msg_parser.c:171]: get_hdr_field(): [44]; uri=[sip:102@192.168.0.15] 0(18097) DEBUG: [core/parser/msg_parser.c:174]: get_hdr_field(): to body (28)["102" ], to tag (9)[605898205] 0(18097) DEBUG: [core/parser/msg_parser.c:152]: get_hdr_field(): cseq : <21> 0(18097) DEBUG: [core/receive.c:319]: receive_msg(): --- received sip message - request - call-id: [FdUwYxGLEF] - cseq: [21 BYE] 0(18097) DEBUG: [core/parser/msg_parser.c:89]: get_hdr_field(): found end of header 0(18097) DEBUG: {1 21 BYE FdUwYxGLEF} [core/receive.c:379]: receive_msg(): preparing to run routing scripts... 0(18097) DEBUG: {1 21 BYE FdUwYxGLEF} app_python3 [apy_kemi.c:234]: sr_apy_kemi_exec_func_ex(): execution of method: .is_method_in 0(18097) DEBUG: {1 21 BYE FdUwYxGLEF} app_python3 [apy_kemi.c:266]: sr_apy_kemi_exec_func_ex(): param[1] for: is_method_in is str: RS 0(18097) DEBUG: {1 21 BYE FdUwYxGLEF} app_python3 [apy_kemi.c:232]: sr_apy_kemi_exec_func_ex(): execution of method: process_maxfwd 0(18097) DEBUG: {1 21 BYE FdUwYxGLEF} app_python3 [apy_kemi.c:258]: sr_apy_kemi_exec_func_ex(): param[1] for: process_maxfwd is int: 10 0(18097) DEBUG: {1 21 BYE FdUwYxGLEF} maxfwd [mf_funcs.c:74]: is_maxfwd_present(): value = 70 0(18097) DEBUG: {1 21 BYE FdUwYxGLEF} app_python3 [apy_kemi.c:234]: sr_apy_kemi_exec_func_ex(): execution of method: .is_OPTIONS 0(18097) DEBUG: {1 21 BYE FdUwYxGLEF} app_python3 [apy_kemi.c:232]: sr_apy_kemi_exec_func_ex(): execution of method: sanity_check 0(18097) DEBUG: {1 21 BYE FdUwYxGLEF} app_python3 [apy_kemi.c:279]: sr_apy_kemi_exec_func_ex(): params[2] for: sanity_check are int-int: [1511] [7] 0(18097) DEBUG: {1 21 BYE FdUwYxGLEF} sanity [sanity.c:247]: check_ruri_sip_version(): check_ruri_sip_version entered 0(18097) DEBUG: {1 21 BYE FdUwYxGLEF} sanity [sanity.c:270]: check_ruri_sip_version(): check_ruri_sip_version passed 0(18097) DEBUG: {1 21 BYE FdUwYxGLEF} sanity [sanity.c:277]: check_ruri_scheme(): check_ruri_scheme entered 0(18097) DEBUG: {1 21 BYE FdUwYxGLEF} sanity [sanity.c:297]: check_ruri_scheme(): check_ruri_scheme passed 0(18097) DEBUG: {1 21 BYE FdUwYxGLEF} sanity [sanity.c:318]: check_required_headers(): check_required_headers entered 0(18097) DEBUG: {1 21 BYE FdUwYxGLEF} sanity [sanity.c:340]: check_required_headers(): check_required_headers passed 0(18097) DEBUG: {1 21 BYE FdUwYxGLEF} sanity [sanity.c:506]: check_cseq_method(): check_cseq_method entered 0(18097) DEBUG: {1 21 BYE FdUwYxGLEF} sanity [sanity.c:539]: check_cseq_method(): check_cseq_method passed 0(18097) DEBUG: {1 21 BYE FdUwYxGLEF} sanity [sanity.c:548]: check_cseq_value(): check_cseq_value entered 0(18097) DEBUG: {1 21 BYE FdUwYxGLEF} sanity [sanity.c:576]: check_cseq_value(): check_cseq_value passed 0(18097) DEBUG: {1 21 BYE FdUwYxGLEF} sanity [sanity.c:585]: check_cl(): check_cl entered 0(18097) WARNING: {1 21 BYE FdUwYxGLEF} sanity [sanity.c:612]: check_cl(): content length header missing in request 0(18097) DEBUG: {1 21 BYE FdUwYxGLEF} sanity [sanity.c:622]: check_expires_value(): check_expires_value entered 0(18097) DEBUG: {1 21 BYE FdUwYxGLEF} sanity [sanity.c:659]: check_expires_value(): no expires header found 0(18097) DEBUG: {1 21 BYE FdUwYxGLEF} sanity [sanity.c:759]: check_parse_uris(): check_parse_uris entered 0(18097) DEBUG: {1 21 BYE FdUwYxGLEF} sanity [sanity.c:763]: check_parse_uris(): parsing ruri 0(18097) DEBUG: {1 21 BYE FdUwYxGLEF} sanity [sanity.c:777]: check_parse_uris(): looking up From header 0(18097) DEBUG: {1 21 BYE FdUwYxGLEF} sanity [sanity.c:791]: check_parse_uris(): parsing From header 0(18097) DEBUG: {1 21 BYE FdUwYxGLEF} [core/parser/parse_addr_spec.c:185]: parse_to_param(): add param: tag=ILonsDQko 0(18097) DEBUG: {1 21 BYE FdUwYxGLEF} [core/parser/parse_addr_spec.c:864]: parse_addr_spec(): end of header reached, state=29 0(18097) DEBUG: {1 21 BYE FdUwYxGLEF} sanity [sanity.c:817]: check_parse_uris(): parsing From URI 0(18097) DEBUG: {1 21 BYE FdUwYxGLEF} sanity [sanity.c:835]: check_parse_uris(): looking up To header 0(18097) DEBUG: {1 21 BYE FdUwYxGLEF} sanity [sanity.c:857]: check_parse_uris(): check_parse_uris(): parsing To URI 0(18097) DEBUG: {1 21 BYE FdUwYxGLEF} sanity [sanity.c:902]: check_parse_uris(): check_parse_uris passed 0(18097) DEBUG: {1 21 BYE FdUwYxGLEF} app_python3 [apy_kemi.c:234]: sr_apy_kemi_exec_func_ex(): execution of method: .is_CANCEL 0(18097) DEBUG: {1 21 BYE FdUwYxGLEF} app_python3 [apy_kemi.c:232]: sr_apy_kemi_exec_func_ex(): execution of method: has_totag 0(18097) DEBUG: {1 21 BYE FdUwYxGLEF} siputils [checks.c:123]: has_totag(): totag found 0(18097) DEBUG: {1 21 BYE FdUwYxGLEF} app_python3 [apy_kemi.c:232]: sr_apy_kemi_exec_func_ex(): execution of method: loose_route 0(18097) DEBUG: {1 21 BYE FdUwYxGLEF} rr [loose.c:85]: is_preloaded(): is_preloaded: No 0(18097) DEBUG: {1 21 BYE FdUwYxGLEF} [core/socket_info.c:641]: grep_sock_info(): checking if host==us: 12==13 && [192.168.0.15] == [192.168.0.101] 0(18097) DEBUG: {1 21 BYE FdUwYxGLEF} [core/socket_info.c:648]: grep_sock_info(): checking if port 5060 (advertise 0) matches port 5060 0(18097) DEBUG: {1 21 BYE FdUwYxGLEF} [core/socket_info.c:641]: grep_sock_info(): checking if host==us: 12==13 && [192.168.0.15] == [192.168.0.201] 0(18097) DEBUG: {1 21 BYE FdUwYxGLEF} [core/socket_info.c:648]: grep_sock_info(): checking if port 5060 (advertise 0) matches port 5060 0(18097) DEBUG: {1 21 BYE FdUwYxGLEF} [core/forward.c:424]: check_self(): host (0:192.168.0.15:5060) != me 0(18097) DEBUG: {1 21 BYE FdUwYxGLEF} [core/socket_info.c:641]: grep_sock_info(): checking if host==us: 13==13 && [192.168.0.101] == [192.168.0.101] 0(18097) DEBUG: {1 21 BYE FdUwYxGLEF} [core/socket_info.c:648]: grep_sock_info(): checking if port 5060 (advertise 0) matches port 5060 0(18097) DEBUG: {1 21 BYE FdUwYxGLEF} [core/forward.c:422]: check_self(): host (0:192.168.0.101:5060) == me 0(18097) DEBUG: {1 21 BYE FdUwYxGLEF} rr [loose.c:850]: after_loose(): Topmost route URI: 'sip:192.168.0.101;lr' is me 0(18097) DEBUG: {1 21 BYE FdUwYxGLEF} [core/parser/msg_parser.c:89]: get_hdr_field(): found end of header 0(18097) DEBUG: {1 21 BYE FdUwYxGLEF} rr [loose.c:176]: find_next_route(): No next Route HF found 0(18097) DEBUG: {1 21 BYE FdUwYxGLEF} rr [loose.c:881]: after_loose(): No next URI found 0(18097) DEBUG: {1 21 BYE FdUwYxGLEF} app_python3 [apy_kemi.c:234]: sr_apy_kemi_exec_func_ex(): execution of method: .is_NOTIFY 0(18097) DEBUG: {1 21 BYE FdUwYxGLEF} app_python3 [apy_kemi.c:234]: sr_apy_kemi_exec_func_ex(): execution of method: .is_method_in 0(18097) DEBUG: {1 21 BYE FdUwYxGLEF} app_python3 [apy_kemi.c:266]: sr_apy_kemi_exec_func_ex(): param[1] for: is_method_in is str: ISU 0(18097) DEBUG: {1 21 BYE FdUwYxGLEF} app_python3 [apy_kemi.c:234]: sr_apy_kemi_exec_func_ex(): execution of method: .is_INVITE 0(18097) DEBUG: {1 21 BYE FdUwYxGLEF} app_python3 [apy_kemi.c:232]: sr_apy_kemi_exec_func_ex(): execution of method: has_body 0(18097) DEBUG: {1 21 BYE FdUwYxGLEF} app_python3 [apy_kemi.c:232]: sr_apy_kemi_exec_func_ex(): execution of method: rtpengine_manage 0(18097) DEBUG: {1 21 BYE FdUwYxGLEF} app_python3 [apy_kemi.c:266]: sr_apy_kemi_exec_func_ex(): param[1] for: rtpengine_manage is str: asymmetric 0(18097) DEBUG: {1 21 BYE FdUwYxGLEF} rtpengine [rtpengine.c:3106]: select_rtpp_node_old(): rtpengine hash table lookup find node=udp:127.0.0.1:2223 for calllen=10 callid=FdUwYxGLEF viabranch= 0(18097) DEBUG: {1 21 BYE FdUwYxGLEF} rtpengine [rtpengine.c:2579]: rtpp_function_call(): proxy reply: d7:createdi1615432895e10:created_usi330946e11:last signali1615432897e4:SSRCd9:454512312de9:394329524d11:average MOSd3:MOSi43e15:round-trip timei67930e19:round-trip time legi59888e6:jitteri17e11:packet lossi0e7:samplesi1ee10:lowest MOSd3:MOSi43e15:round-trip timei67930e19:round-trip time legi59888e6:jitteri17e11:packet lossi0e11:reported ati1615432902ee11:highest MOSd3:MOSi43e15:round-trip timei67930e19:round-trip time legi59888e6:jitteri17e11:packet lossi0e11:reported ati1615432902ee15:MOS progressiond8:intervali0e7:entriesld3:MOSi43e15:round-trip timei67930e19:round-trip time legi59888e6:jitteri17e11:packet lossi0e11:reported ati1615432902eeeeee4:tagsd9:ILonsDQkod3:tag9:ILonsDQko7:createdi1615432895e16:in dialogue with9:6058982056:mediasld5:indexi1e4:type5:audio8:protocol7:RTP/AVP7:streamsld10:local porti32402e13:local address13:192.168.0.1016:family4:IPv48:endpointd6:family4:IPv47:address12:192.168.0.284:porti7286ee19:advertised endpointd6:family4:IPv47:address12:192.168.0.284:porti7286ee11:last packeti1615432903e5:flagsl3:RTP6:filled9:confirmed10:kernelizede5:statsd7:packetsi259e5:bytesi8264e6:errorsi0eeed10:local porti32403e13:local address13:192.168.0.1016:family4:IPv48:endpointd6:family4:IPv47:address12:192.168.0.284:porti7287ee19:advertised endpointd6:family4:IPv47:address12:192.168.0.284:porti7287ee11:last packeti1615432902e5:flagsl4:RTCP6:filled9:confirmed10:kernelized17:no kernel supporte4:SSRCi394329524e5:statsd7:packetsi12e5:bytesi464e6:errorsi0eeee5:flagsl11:initialized10:asymmetric4:send4:recveeee9:605898205d3:tag9:6058982057:createdi1615432895e16:in dialogue with9:ILonsDQko6:mediasld5:indexi1e4:type5:audio8:protocol7:RTP/AVP7:streamsld10:local porti32380e13:local address13:192.168.0.1016:family4:IPv48:endpointd6:family4:IPv47:address12:192.168.0.154:porti3000ee19:advertised endpointd6:family4:IPv47:address12:192.168.0.154:porti3000ee11:last packeti1615432903e5:flagsl3:RTP6:filled9:confirmed10:kernelizede4:SSRCi454512312e5:statsd7:packetsi248e5:bytesi7936e6:errorsi0eeed10:local porti32381e13:local address13:192.168.0.1016:family4:IPv48:endpointd6:family4:IPv47:address12:192.168.0.154:porti3001ee19:advertised endpointd6:family4:IPv47:address12:192.168.0.154:porti3001ee11:last packeti1615432902e5:flagsl4:RTCP6:filled9:confirmed10:kernelized17:no kernel supporte4:SSRCi454512312e5:statsd7:packetsi1e5:bytesi80e6:errorsi0eeee5:flagsl11:initialized10:asymmetric4:send4:recv15:ICE controllingeeeee6:totalsd3:RTPd7:packetsi507e5:bytesi16200e6:errorsi0ee4:RTCPd7:packetsi13e5:bytesi544e6:errorsi0eee6:result2:oke 0(18097) DEBUG: {1 21 BYE FdUwYxGLEF} rtpengine [rtpengine.c:2682]: rtpp_function_call(): rtpengine hash table remove entry for callen=10 callid=FdUwYxGLEF viabranch= 0(18097) DEBUG: {1 21 BYE FdUwYxGLEF} app_python3 [apy_kemi.c:232]: sr_apy_kemi_exec_func_ex(): execution of method: t_relay 0(18097) DEBUG: {1 21 BYE FdUwYxGLEF} tm [t_lookup.c:1328]: t_newtran(): msg (0x7f051ac799a0) id=9/18097 global id=8/18097 T start=(nil) 0(18097) DEBUG: {1 21 BYE FdUwYxGLEF} tm [t_lookup.c:497]: t_lookup_request(): start searching: hash=56128, isACK=0 0(18097) DEBUG: {1 21 BYE FdUwYxGLEF} tm [t_lookup.c:455]: matching_3261(): RFC3261 transaction matching failed - via branch [z9hG4bK.gEkDQkxKl] 0(18097) DEBUG: {1 21 BYE FdUwYxGLEF} tm [t_lookup.c:675]: t_lookup_request(): no transaction found 0(18097) DEBUG: {1 21 BYE FdUwYxGLEF} [core/crypto/md5utils.c:67]: MD5StringArray(): MD5 calculated: 2e400daff3dd2156a549dc9cdbbeee3a 0(18097) DEBUG: {1 21 BYE FdUwYxGLEF} [core/msg_translator.c:1796]: check_boundaries(): no multi-part body 0(18097) DEBUG: {1 21 BYE FdUwYxGLEF} app_python3 [python_exec.c:93]: apy_exec(): ksr_onsend_route not found or is not callable 0(18097) DEBUG: {1 21 BYE FdUwYxGLEF} tm [t_funcs.c:376]: t_relay_to(): new transaction forwarded 0(18097) ERROR: {1 21 BYE FdUwYxGLEF} app_python3 [python_support.c:156]: python_handle_exception(): apy_exec: ksr_request_route((null)): Unhandled exception in the Python code: AttributeError: 'kamailio' object has no attribute 'ksr_onsend_route' The above exception was the direct cause of the following exception: Traceback (most recent call last): File "/root/kam.py", line 57, in ksr_request_route if self.ksr_route_withindlg(msg)==-255 : File "/root/kam.py", line 131, in ksr_route_withindlg self.ksr_route_relay(msg) File "/root/kam.py", line 110, in ksr_route_relay if KSR.tm.t_relay()<0 : SystemError: returned a result with an error set 0(18097) DEBUG: {1 21 BYE FdUwYxGLEF} app_python3 [apy_kemi.c:112]: sr_kemi_config_engine_python(): execution of route type 1 with no name returned -1 0(18097) DEBUG: {1 21 BYE FdUwYxGLEF} [core/receive.c:437]: receive_msg(): request-route executed in: 46390 usec 0(18097) DEBUG: {1 21 BYE FdUwYxGLEF} [core/usr_avp.c:636]: destroy_avp_list(): destroying list (nil) 0(18097) DEBUG: {1 21 BYE FdUwYxGLEF} [core/usr_avp.c:636]: destroy_avp_list(): destroying list (nil) 0(18097) DEBUG: {1 21 BYE FdUwYxGLEF} [core/usr_avp.c:636]: destroy_avp_list(): destroying list (nil) 0(18097) DEBUG: {1 21 BYE FdUwYxGLEF} [core/usr_avp.c:636]: destroy_avp_list(): destroying list (nil) 0(18097) DEBUG: {1 21 BYE FdUwYxGLEF} [core/usr_avp.c:636]: destroy_avp_list(): destroying list (nil) 0(18097) DEBUG: {1 21 BYE FdUwYxGLEF} [core/usr_avp.c:636]: destroy_avp_list(): destroying list (nil) 0(18097) DEBUG: {1 21 BYE FdUwYxGLEF} [core/xavp.c:539]: xavp_destroy_list(): destroying xavp list (nil) 0(18097) DEBUG: {1 21 BYE FdUwYxGLEF} [core/xavp.c:539]: xavp_destroy_list(): destroying xavp list (nil) 0(18097) DEBUG: {1 21 BYE FdUwYxGLEF} [core/xavp.c:539]: xavp_destroy_list(): destroying xavp list (nil) 0(18097) DEBUG: {1 21 BYE FdUwYxGLEF} [core/receive.c:528]: receive_msg(): cleaning up 0(18097) DEBUG: [core/udp_server.c:493]: udp_rcv_loop(): received on udp socket: (106/100/550) [[SIP/2.0 200 OK 0D 0A Via: SIP/2.0/UDP 192.168.0.101;branch=z9hG4bK04bd.2e400daff3dd2156a549dc9cdbbeee3a.0]] 0(18097) DEBUG: [core/parser/msg_parser.c:620]: parse_msg(): SIP Reply (status): 0(18097) DEBUG: [core/parser/msg_parser.c:622]: parse_msg(): version: 0(18097) DEBUG: [core/parser/msg_parser.c:624]: parse_msg(): status: <200> 0(18097) DEBUG: [core/parser/msg_parser.c:626]: parse_msg(): reason: 0(18097) DEBUG: [core/parser/parse_via.c:1303]: parse_via_param(): Found param type 232, = ; state=16 0(18097) DEBUG: [core/parser/parse_via.c:2639]: parse_via(): end of header reached, state=5 0(18097) DEBUG: [core/parser/msg_parser.c:498]: parse_headers(): Via found, flags=2 0(18097) DEBUG: [core/parser/msg_parser.c:500]: parse_headers(): this is the first via 0(18097) DEBUG: [core/parser/parse_via.c:1303]: parse_via_param(): Found param type 234, = <192.168.0.28>; state=6 0(18097) DEBUG: [core/parser/parse_via.c:1303]: parse_via_param(): Found param type 232, = ; state=6 0(18097) DEBUG: [core/parser/parse_via.c:1303]: parse_via_param(): Found param type 235, = <50045>; state=16 0(18097) DEBUG: [core/parser/parse_via.c:2639]: parse_via(): end of header reached, state=5 0(18097) DEBUG: [core/parser/msg_parser.c:498]: parse_headers(): Via found, flags=78 0(18097) DEBUG: [core/parser/msg_parser.c:511]: parse_headers(): this is the second via 0(18097) DEBUG: [core/parser/parse_addr_spec.c:185]: parse_to_param(): add param: tag=605898205 0(18097) DEBUG: [core/parser/parse_addr_spec.c:864]: parse_addr_spec(): end of header reached, state=29 0(18097) DEBUG: [core/parser/msg_parser.c:171]: get_hdr_field(): [44]; uri=[sip:102@192.168.0.15] 0(18097) DEBUG: [core/parser/msg_parser.c:174]: get_hdr_field(): to body (28)["102" ], to tag (9)[605898205] 0(18097) DEBUG: [core/parser/msg_parser.c:152]: get_hdr_field(): cseq : <21> 0(18097) DEBUG: [core/receive.c:319]: receive_msg(): --- received sip message - reply - call-id: [FdUwYxGLEF] - cseq: [21 BYE] 0(18097) DEBUG: [core/parser/msg_parser.c:185]: get_hdr_field(): content_length=0 0(18097) DEBUG: [core/parser/msg_parser.c:89]: get_hdr_field(): found end of header 0(18097) DEBUG: {2 21 BYE FdUwYxGLEF} app_python3 [apy_kemi.c:234]: sr_apy_kemi_exec_func_ex(): execution of method: .info 0(18097) DEBUG: {2 21 BYE FdUwYxGLEF} app_python3 [apy_kemi.c:266]: sr_apy_kemi_exec_func_ex(): param[1] for: info is str: ===== response - from kamailio python script 0(18097) INFO: {2 21 BYE FdUwYxGLEF} [core/kemi.c:104]: sr_kemi_core_info(): ===== response - from kamailio python script 0(18097) DEBUG: {2 21 BYE FdUwYxGLEF} app_python3 [apy_kemi.c:112]: sr_kemi_config_engine_python(): execution of route type 128 with no name returned 1 0(18097) DEBUG: {2 21 BYE FdUwYxGLEF} tm [t_lookup.c:1034]: t_check_msg(): msg (0x7f051ac799a0) id=10/18097 global id=9/18097 T start=0xffffffffffffffff 0(18097) DEBUG: {2 21 BYE FdUwYxGLEF} tm [t_lookup.c:912]: t_reply_matching(): t_reply_matching: hash 56128 label 0 branch 0 0(18097) DEBUG: {2 21 BYE FdUwYxGLEF} tm [t_lookup.c:967]: t_reply_matching(): reply (0x7f051ac799a0) matched an active transaction (T=0x7f05161ec3f8)! 0(18097) DEBUG: {2 21 BYE FdUwYxGLEF} tm [t_lookup.c:1104]: t_check_msg(): msg (0x7f051ac799a0) id=10/18097 global id=10/18097 T end=0x7f05161ec3f8 0(18097) DEBUG: {2 21 BYE FdUwYxGLEF} tm [t_reply.c:2352]: reply_received(): transaction found - T:0x7f05161ec3f8 branch:0 0(18097) DEBUG: {2 21 BYE FdUwYxGLEF} tm [t_reply.c:2365]: reply_received(): original status uas=0, uac[0]=0 local=0 is_invite=0) 0(18097) DEBUG: {2 21 BYE FdUwYxGLEF} tm [t_reply.c:1359]: t_should_relay_response(): ->>>>>>>>> T_code=0, new_code=200 0(18097) DEBUG: {2 21 BYE FdUwYxGLEF} tm [t_reply.c:1606]: t_should_relay_response(): rps completed - uas status: 0 0(18097) DEBUG: {2 21 BYE FdUwYxGLEF} tm [t_reply.c:1922]: relay_reply(): reply status=4 branch=0, save=0, relay=0 icode=0 msg status=200 0(18097) DEBUG: {2 21 BYE FdUwYxGLEF} [core/msg_translator.c:2325]: generate_res_buf_from_sip_res(): old size: 550, new size: 464 0(18097) DEBUG: {2 21 BYE FdUwYxGLEF} [core/msg_translator.c:2342]: generate_res_buf_from_sip_res(): copied size: orig:102, new: 16, rest: 448 msg= SIP/2.0 200 OK Via: SIP/2.0/UDP 192.168.0.28:50045;received=192.168.0.28;branch=z9hG4bK.gEkDQkxKl;rport=50045 From: "myali" ;tag=ILonsDQko To: "102" ;tag=605898205 Call-ID: FdUwYxGLEF CSeq: 21 BYE Allow: INVITE, ACK, CANCEL, BYE, NOTIFY, REFER, OPTIONS, UPDATE, PRACK, SUBSCRIBE, INFO Allow-Events: talk, hold, conference, LocalModeStatus Server: Aastra 57iCT/3.2.2.2104 Supported: path Content-Length: 0 0(18097) DEBUG: {2 21 BYE FdUwYxGLEF} tm [t_reply.c:2119]: relay_reply(): reply buffer sent out 0(18097) DEBUG: {2 21 BYE FdUwYxGLEF} tm [t_reply.c:1761]: cleanup_uac_timers(): RETR/FR timers reset 0(18097) DEBUG: {2 21 BYE FdUwYxGLEF} [core/receive.c:518]: receive_msg(): reply-route executed in: 379 usec 0(18097) DEBUG: {2 21 BYE FdUwYxGLEF} [core/usr_avp.c:636]: destroy_avp_list(): destroying list (nil) 0(18097) DEBUG: {2 21 BYE FdUwYxGLEF} [core/usr_avp.c:636]: destroy_avp_list(): destroying list (nil) 0(18097) DEBUG: {2 21 BYE FdUwYxGLEF} [core/usr_avp.c:636]: destroy_avp_list(): destroying list (nil) 0(18097) DEBUG: {2 21 BYE FdUwYxGLEF} [core/usr_avp.c:636]: destroy_avp_list(): destroying list (nil) 0(18097) DEBUG: {2 21 BYE FdUwYxGLEF} [core/usr_avp.c:636]: destroy_avp_list(): destroying list (nil) 0(18097) DEBUG: {2 21 BYE FdUwYxGLEF} [core/usr_avp.c:636]: destroy_avp_list(): destroying list (nil) 0(18097) DEBUG: {2 21 BYE FdUwYxGLEF} [core/xavp.c:539]: xavp_destroy_list(): destroying xavp list (nil) 0(18097) DEBUG: {2 21 BYE FdUwYxGLEF} [core/xavp.c:539]: xavp_destroy_list(): destroying xavp list (nil) 0(18097) DEBUG: {2 21 BYE FdUwYxGLEF} [core/xavp.c:539]: xavp_destroy_list(): destroying xavp list (nil) 0(18097) DEBUG: {2 21 BYE FdUwYxGLEF} [core/receive.c:528]: receive_msg(): cleaning up 0(18097) DEBUG: [core/udp_server.c:493]: udp_rcv_loop(): received on udp socket: (106/100/607) [[REGISTER sip:192.168.0.101 SIP/2.0 0D 0A Via: SIP/2.0/UDP 192.168.0.28:50045;branch=z9hG4bK.NAxT~SJot;rpo]] 0(18097) DEBUG: [core/parser/msg_parser.c:610]: parse_msg(): SIP Request: 0(18097) DEBUG: [core/parser/msg_parser.c:612]: parse_msg(): method: 0(18097) DEBUG: [core/parser/msg_parser.c:614]: parse_msg(): uri: 0(18097) DEBUG: [core/parser/msg_parser.c:616]: parse_msg(): version: 0(18097) DEBUG: [core/parser/parse_via.c:1303]: parse_via_param(): Found param type 232, = ; state=6 0(18097) DEBUG: [core/parser/parse_via.c:1303]: parse_via_param(): Found param type 235, = ; state=17 0(18097) DEBUG: [core/parser/parse_via.c:2639]: parse_via(): end of header reached, state=5 0(18097) DEBUG: [core/parser/msg_parser.c:498]: parse_headers(): Via found, flags=2 0(18097) DEBUG: [core/parser/msg_parser.c:500]: parse_headers(): this is the first via 0(18097) DEBUG: [core/parser/parse_addr_spec.c:864]: parse_addr_spec(): end of header reached, state=10 0(18097) DEBUG: [core/parser/msg_parser.c:171]: get_hdr_field(): [34]; uri=[sip:1971@192.168.0.101] 0(18097) DEBUG: [core/parser/msg_parser.c:174]: get_hdr_field(): to body (34)["myali" ], to tag (0)[] 0(18097) DEBUG: [core/parser/msg_parser.c:152]: get_hdr_field(): cseq : <21> 0(18097) DEBUG: [core/receive.c:319]: receive_msg(): --- received sip message - request - call-id: [UwWa1yG-Xd] - cseq: [21 REGISTER] 0(18097) DEBUG: [core/parser/msg_parser.c:89]: get_hdr_field(): found end of header 0(18097) DEBUG: {1 21 REGISTER UwWa1yG-Xd} [core/receive.c:379]: receive_msg(): preparing to run routing scripts... 0(18097) DEBUG: {1 21 REGISTER UwWa1yG-Xd} app_python3 [apy_kemi.c:234]: sr_apy_kemi_exec_func_ex(): execution of method: .is_method_in 0(18097) DEBUG: {1 21 REGISTER UwWa1yG-Xd} app_python3 [apy_kemi.c:266]: sr_apy_kemi_exec_func_ex(): param[1] for: is_method_in is str: RS 0(18097) DEBUG: {1 21 REGISTER UwWa1yG-Xd} app_python3 [apy_kemi.c:232]: sr_apy_kemi_exec_func_ex(): execution of method: sl_send_reply 0(18097) DEBUG: {1 21 REGISTER UwWa1yG-Xd} app_python3 [apy_kemi.c:287]: sr_apy_kemi_exec_func_ex(): params[2] for: sl_send_reply are int-str: [200] [OK] 0(18097) DEBUG: {1 21 REGISTER UwWa1yG-Xd} [core/parser/msg_parser.c:620]: parse_msg(): SIP Reply (status): 0(18097) DEBUG: {1 21 REGISTER UwWa1yG-Xd} [core/parser/msg_parser.c:622]: parse_msg(): version: 0(18097) DEBUG: {1 21 REGISTER UwWa1yG-Xd} [core/parser/msg_parser.c:624]: parse_msg(): status: <200> 0(18097) DEBUG: {1 21 REGISTER UwWa1yG-Xd} [core/parser/msg_parser.c:626]: parse_msg(): reason: 0(18097) DEBUG: {1 21 REGISTER UwWa1yG-Xd} [core/parser/parse_via.c:1303]: parse_via_param(): Found param type 232, = ; state=6 0(18097) DEBUG: {1 21 REGISTER UwWa1yG-Xd} [core/parser/parse_via.c:1303]: parse_via_param(): Found param type 235, = <50045>; state=6 0(18097) DEBUG: {1 21 REGISTER UwWa1yG-Xd} [core/parser/parse_via.c:1303]: parse_via_param(): Found param type 234, = <192.168.0.28>; state=16 0(18097) DEBUG: {1 21 REGISTER UwWa1yG-Xd} [core/parser/parse_via.c:2639]: parse_via(): end of header reached, state=5 0(18097) DEBUG: {1 21 REGISTER UwWa1yG-Xd} [core/parser/msg_parser.c:498]: parse_headers(): Via found, flags=2 0(18097) DEBUG: {1 21 REGISTER UwWa1yG-Xd} [core/parser/msg_parser.c:500]: parse_headers(): this is the first via 0(18097) DEBUG: {1 21 REGISTER UwWa1yG-Xd} app_python3 [apy_kemi.c:109]: sr_kemi_config_engine_python(): execution of route type 513 with name [] returned -1 0(18097) DEBUG: {1 21 REGISTER UwWa1yG-Xd} app_python3 [apy_kemi.c:112]: sr_kemi_config_engine_python(): execution of route type 1 with no name returned 1 0(18097) DEBUG: {1 21 REGISTER UwWa1yG-Xd} [core/receive.c:437]: receive_msg(): request-route executed in: 191 usec 0(18097) DEBUG: {1 21 REGISTER UwWa1yG-Xd} [core/usr_avp.c:636]: destroy_avp_list(): destroying list (nil) 0(18097) DEBUG: {1 21 REGISTER UwWa1yG-Xd} [core/usr_avp.c:636]: destroy_avp_list(): destroying list (nil) 0(18097) DEBUG: {1 21 REGISTER UwWa1yG-Xd} [core/usr_avp.c:636]: destroy_avp_list(): destroying list (nil) 0(18097) DEBUG: {1 21 REGISTER UwWa1yG-Xd} [core/usr_avp.c:636]: destroy_avp_list(): destroying list (nil) 0(18097) DEBUG: {1 21 REGISTER UwWa1yG-Xd} [core/usr_avp.c:636]: destroy_avp_list(): destroying list (nil) 0(18097) DEBUG: {1 21 REGISTER UwWa1yG-Xd} [core/usr_avp.c:636]: destroy_avp_list(): destroying list (nil) 0(18097) DEBUG: {1 21 REGISTER UwWa1yG-Xd} [core/xavp.c:539]: xavp_destroy_list(): destroying xavp list (nil) 0(18097) DEBUG: {1 21 REGISTER UwWa1yG-Xd} [core/xavp.c:539]: xavp_destroy_list(): destroying xavp list (nil) 0(18097) DEBUG: {1 21 REGISTER UwWa1yG-Xd} [core/xavp.c:539]: xavp_destroy_list(): destroying xavp list (nil) 0(18097) DEBUG: {1 21 REGISTER UwWa1yG-Xd} [core/receive.c:528]: receive_msg(): cleaning up 2(18100) DEBUG: tm [timer.c:634]: wait_handler(): finished transaction: 0x7f05161ec3f8 (p:0x7f051618def0/n:0x7f051618def0) 2(18100) DEBUG: tm [h_table.c:132]: free_cell_helper(): freeing transaction 0x7f05161ec3f8 from timer.c:643 ^C 1(18099) INFO: