Jan 13 14:57:46 Yakhchali-SBC [410624]: DBG:proto_tls:tls_read_req: Using the global ( per process ) buff Jan 13 14:57:46 Yakhchali-SBC [410624]: DBG:tls_openssl:openssl_tls_update_fd: New fd is 196 Jan 13 14:57:46 Yakhchali-SBC [410624]: DBG:tls_openssl:openssl_read: 1026 bytes read Jan 13 14:57:46 Yakhchali-SBC [410624]: DBG:proto_tls:tcp_handle_req: content-length= 316 Jan 13 14:57:46 Yakhchali-SBC [410624]: DBG:proto_tls:tcp_handle_req: Nothing more to read on TCP conn 0x7f3fdfd15df8, currently in state 0 Jan 13 14:57:46 Yakhchali-SBC [410624]: DBG:core:parse_msg: SIP Request: Jan 13 14:57:46 Yakhchali-SBC [410624]: DBG:core:parse_msg: method: Jan 13 14:57:46 Yakhchali-SBC [410624]: DBG:core:parse_msg: uri: Jan 13 14:57:46 Yakhchali-SBC [410624]: DBG:core:parse_msg: version: Jan 13 14:57:46 Yakhchali-SBC [410624]: DBG:core:parse_headers_aux: flags=ffffffffffffffff Jan 13 14:57:46 Yakhchali-SBC [410624]: DBG:core:parse_via_param: found param type 235, = ; state=6 Jan 13 14:57:46 Yakhchali-SBC [410624]: DBG:core:parse_via_param: found param type 232, = ; state=6 Jan 13 14:57:46 Yakhchali-SBC [410624]: DBG:core:parse_via_param: found param type 237, = ; state=16 Jan 13 14:57:46 Yakhchali-SBC [410624]: DBG:core:parse_via: end of header reached, state=5 Jan 13 14:57:46 Yakhchali-SBC [410624]: DBG:core:parse_headers_aux: via found, flags=ffffffffffffffff Jan 13 14:57:46 Yakhchali-SBC [410624]: DBG:core:parse_headers_aux: this is the first via Jan 13 14:57:46 Yakhchali-SBC [410624]: DBG:core:_parse_to: end of header reached, state=10 Jan 13 14:57:46 Yakhchali-SBC [410624]: DBG:core:_parse_to: display={}, ruri={sip:98212010@172.25.17.70} Jan 13 14:57:46 Yakhchali-SBC [410624]: DBG:core:get_hdr_field_aux: [29]; uri=[sip:98212010@172.25.17.70] Jan 13 14:57:46 Yakhchali-SBC [410624]: DBG:core:get_hdr_field_aux: to body [#015#012] Jan 13 14:57:46 Yakhchali-SBC [410624]: DBG:core:get_hdr_field_aux: cseq : <6323> Jan 13 14:57:46 Yakhchali-SBC [410624]: DBG:core:get_hdr_field_aux: content_length=316 Jan 13 14:57:46 Yakhchali-SBC [410624]: DBG:core:get_hdr_field_aux: found end of header Jan 13 14:57:46 Yakhchali-SBC [410624]: DBG:core:receive_msg: After parse_msg... Jan 13 14:57:46 Yakhchali-SBC [410624]: DBG:core:tcpconn_add_alias: refusing to add alias (alias_mode: 0, via 'alias': 1) Jan 13 14:57:46 Yakhchali-SBC [410624]: DBG:core:receive_msg: preparing to run routing scripts... Jan 13 14:57:46 Yakhchali-SBC [410624]: DBG:core:parse_headers_aux: flags=ffffffffffffffff Jan 13 14:57:46 Yakhchali-SBC [410624]: DBG:b2b_entities:b2b_prescript_f: start - method = INVITE Jan 13 14:57:46 Yakhchali-SBC [410624]: DBG:b2b_entities:b2b_prescript_f: Found route headers Jan 13 14:57:46 Yakhchali-SBC [410624]: DBG:core:grep_sock_info_ext: checking if host==us: 12==12 && [172.25.17.70] == [172.25.17.70] Jan 13 14:57:46 Yakhchali-SBC [410624]: DBG:core:grep_sock_info_ext: checking if port 8090 matches port 5060 Jan 13 14:57:46 Yakhchali-SBC [410624]: DBG:core:grep_sock_info_ext: checking if host==us: 12==13 && [172.25.17.70] == [172.25.19.192] Jan 13 14:57:46 Yakhchali-SBC [410624]: DBG:core:grep_sock_info_ext: checking if port 5061 matches port 5060 Jan 13 14:57:46 Yakhchali-SBC [410624]: DBG:core:grep_sock_info_ext: checking if host==us: 12==12 && [172.25.17.70] == [172.25.17.70] Jan 13 14:57:46 Yakhchali-SBC [410624]: DBG:core:grep_sock_info_ext: checking if port 5061 matches port 5060 Jan 13 14:57:46 Yakhchali-SBC [410624]: DBG:core:check_self: host != me Jan 13 14:57:46 Yakhchali-SBC [410624]: DBG:b2b_entities:b2b_prescript_f: First Route uri is not mine Jan 13 14:57:46 Yakhchali-SBC [410624]: DBG:core:parse_headers_aux: flags=ffffffffffffffff Jan 13 14:57:46 Yakhchali-SBC [410624]: DBG:core:comp_scriptvar: str 20: tls Jan 13 14:57:46 Yakhchali-SBC [410624]: DBG:core:comp_scriptvar: str 20: tls Jan 13 14:57:46 Yakhchali-SBC [410624]: DBG:core:cachedb_fetch: from script [redis] - with grp [local] Jan 13 14:57:46 Yakhchali-SBC [410624]: DBG:cachedb_redis:get_redis_connection: Single redis connection, returning 0x7f4020c98488 Jan 13 14:57:46 Yakhchali-SBC [410624]: DBG:cachedb_redis:redis_get: GET UA - /^(test1|test2|test3)$/ Jan 13 14:57:46 Yakhchali-SBC [410624]: DBG:core:parse_headers_aux: flags=ffffffffffffffff Jan 13 14:57:46 Yakhchali-SBC [410624]: DBG:core:parse_headers_aux: flags=ffffffffffffffff Jan 13 14:57:46 Yakhchali-SBC [410624]: NOTICE:[1c41cdc79d3a4b2ea7c841ef49518a00(INVITE)] --------------------------------------------------------------------------- Jan 13 14:57:46 Yakhchali-SBC [410624]: DBG:core:parse_to_param: tag=44432d591fe247278a2b558198fcd166 Jan 13 14:57:46 Yakhchali-SBC [410624]: DBG:core:parse_to_param: end of header reached, state=11 Jan 13 14:57:46 Yakhchali-SBC [410624]: DBG:core:_parse_to: end of header reached, state=29 Jan 13 14:57:46 Yakhchali-SBC [410624]: DBG:core:_parse_to: display={}, ruri={sip:98212009@172.25.17.70} Jan 13 14:57:46 Yakhchali-SBC [410624]: NOTICE:[1c41cdc79d3a4b2ea7c841ef49518a00(INVITE)] [main] INVITE ci:1c41cdc79d3a4b2ea7c841ef49518a00 ru:sip:98212010@172.25.17.70;transport=tls from:sip:98212009@172.25.17.70 to:sip:98212010@172.25.17.70 si:172.25.5.253 avp(is_h323):0 proto:tls Jan 13 14:57:46 Yakhchali-SBC [410624]: DBG:core:comp_scriptvar: str 20: TLS Jan 13 14:57:46 Yakhchali-SBC [410624]: DBG:core:tcp_conn_get: con found in state 0 Jan 13 14:57:46 Yakhchali-SBC [410624]: DBG:core:tcp_conn_get: con found in state 0 Jan 13 14:57:46 Yakhchali-SBC [410624]: DBG:tls_openssl:openssl_tls_var_comp: ind = 406 Jan 13 14:57:46 Yakhchali-SBC [410624]: ERROR:tls_openssl:get_cert: failed to get certificate from SSL structure Jan 13 14:57:46 Yakhchali-SBC [410624]: DBG:core:tcp_conn_get: con found in state 0 Jan 13 14:57:46 Yakhchali-SBC [410624]: DBG:tls_openssl:openssl_tls_var_comp: ind = 405 Jan 13 14:57:46 Yakhchali-SBC [410624]: DBG:core:tcp_conn_get: con found in state 0 Jan 13 14:57:46 Yakhchali-SBC [410624]: DBG:core:tcp_conn_get: con found in state 0 Jan 13 14:57:46 Yakhchali-SBC [410624]: DBG:tls_openssl:openssl_tls_var_comp: ind = a Jan 13 14:57:46 Yakhchali-SBC [410624]: ERROR:tls_openssl:get_cert: failed to get certificate from SSL structure Jan 13 14:57:46 Yakhchali-SBC [410624]: DBG:core:tcp_conn_get: con found in state 0 Jan 13 14:57:46 Yakhchali-SBC [410624]: DBG:tls_openssl:openssl_tls_var_comp: ind = 9 Jan 13 14:57:46 Yakhchali-SBC [410624]: NOTICE:[1c41cdc79d3a4b2ea7c841ef49518a00(INVITE)] [main] [tls] version:TLSv1.2 peer_cn: my_cn:172.25.17.70 peer_verified:0 '' '/C=IR/ST=TTT/L=TTT/O=chakavak/OU=SBC/CN=172.25.17.70/emailAddress=info@chakavak.io' Jan 13 14:57:46 Yakhchali-SBC [410624]: DBG:core:tcp_conn_get: con found in state 0 Jan 13 14:57:46 Yakhchali-SBC [410624]: DBG:tls_openssl:openssl_tls_var_comp: ind = 405 Jan 13 14:57:46 Yakhchali-SBC [410624]: DBG:core:cachedb_fetch: from script [redis] - with grp [local] Jan 13 14:57:46 Yakhchali-SBC [410624]: DBG:cachedb_redis:get_redis_connection: Single redis connection, returning 0x7f4020c98488 Jan 13 14:57:46 Yakhchali-SBC [410624]: DBG:cachedb_redis:redis_get: no such key - tls:172.25.17.70 Jan 13 14:57:46 Yakhchali-SBC [410624]: DBG:core:tcp_conn_get: con found in state 0 Jan 13 14:57:46 Yakhchali-SBC [410624]: DBG:tls_openssl:openssl_tls_var_comp: ind = 405 Jan 13 14:57:46 Yakhchali-SBC [410624]: ERROR:[1c41cdc79d3a4b2ea7c841ef49518a00(INVITE)] [check_tls] no tls config found for domain:172.25.17.70 Jan 13 14:57:46 Yakhchali-SBC [410624]: DBG:maxfwd:is_maxfwd_present: value = 70 Jan 13 14:57:46 Yakhchali-SBC [410624]: DBG:core:cachedb_fetch: from script [redis] - with grp [local] Jan 13 14:57:46 Yakhchali-SBC [410624]: DBG:cachedb_redis:get_redis_connection: Single redis connection, returning 0x7f4020c98488 Jan 13 14:57:46 Yakhchali-SBC [410624]: DBG:cachedb_redis:redis_get: no such key - blacklist_from:98212009 Jan 13 14:57:46 Yakhchali-SBC [410624]: DBG:core:cachedb_fetch: from script [redis] - with grp [local] Jan 13 14:57:46 Yakhchali-SBC [410624]: DBG:cachedb_redis:get_redis_connection: Single redis connection, returning 0x7f4020c98488 Jan 13 14:57:46 Yakhchali-SBC [410624]: DBG:cachedb_redis:redis_get: no such key - blacklist_from:98212009@172.25.5.253 Jan 13 14:57:46 Yakhchali-SBC [410624]: DBG:core:parse_headers_aux: flags=78 Jan 13 14:57:46 Yakhchali-SBC [410624]: DBG:tm:t_lookup_request: start searching: hash=58939, isACK=0 Jan 13 14:57:46 Yakhchali-SBC [410624]: DBG:tm:matching_3261: RFC3261 transaction matching failed Jan 13 14:57:46 Yakhchali-SBC [410624]: DBG:tm:t_lookup_request: no transaction found Jan 13 14:57:46 Yakhchali-SBC [410624]: DBG:sipmsgops:has_totag: no totag Jan 13 14:57:46 Yakhchali-SBC [410624]: DBG:core:parse_headers_aux: flags=200 Jan 13 14:57:46 Yakhchali-SBC [410624]: DBG:rr:is_preloaded: Yes Jan 13 14:57:46 Yakhchali-SBC [410624]: DBG:core:grep_sock_info_ext: checking if host==us: 12==12 && [172.25.17.70] == [172.25.17.70] Jan 13 14:57:46 Yakhchali-SBC [410624]: DBG:core:grep_sock_info_ext: checking if port 8090 matches port 5061 Jan 13 14:57:46 Yakhchali-SBC [410624]: DBG:core:grep_sock_info_ext: checking if host==us: 12==13 && [172.25.17.70] == [172.25.19.192] Jan 13 14:57:46 Yakhchali-SBC [410624]: DBG:core:grep_sock_info_ext: checking if port 5061 matches port 5061 Jan 13 14:57:46 Yakhchali-SBC [410624]: DBG:core:grep_sock_info_ext: checking if host==us: 12==12 && [172.25.17.70] == [172.25.17.70] Jan 13 14:57:46 Yakhchali-SBC [410624]: DBG:core:grep_sock_info_ext: checking if port 5061 matches port 5061 Jan 13 14:57:46 Yakhchali-SBC [410624]: DBG:rr:after_loose: Topmost route URI: 'sip:172.25.17.70;transport=tls;lr' is me Jan 13 14:57:46 Yakhchali-SBC [410624]: DBG:core:parse_headers_aux: flags=200 Jan 13 14:57:46 Yakhchali-SBC [410624]: DBG:core:get_hdr_field_aux: found end of header Jan 13 14:57:46 Yakhchali-SBC [410624]: DBG:rr:find_next_route: No next Route HF found Jan 13 14:57:46 Yakhchali-SBC [410624]: DBG:rr:after_loose: No next URI found! Jan 13 14:57:46 Yakhchali-SBC [410624]: DBG:rr:run_rr_callbacks: callback id 1 entered with Jan 13 14:57:46 Yakhchali-SBC [410624]: DBG:rr:run_rr_callbacks: callback id 2 entered with Jan 13 14:57:46 Yakhchali-SBC [410624]: DBG:uac:restore_uri: getting 'vsf' Route param Jan 13 14:57:46 Yakhchali-SBC [410624]: DBG:uac:restore_uri: route param 'vsf' not found Jan 13 14:57:46 Yakhchali-SBC [410624]: DBG:uac:restore_uri: getting 'vst' Route param Jan 13 14:57:46 Yakhchali-SBC [410624]: DBG:uac:restore_uri: route param 'vst' not found Jan 13 14:57:46 Yakhchali-SBC [410624]: DBG:[1c41cdc79d3a4b2ea7c841ef49518a00(INVITE)] [initialrequest] start Jan 13 14:57:46 Yakhchali-SBC [410624]: DBG:[1c41cdc79d3a4b2ea7c841ef49518a00(INVITE)] [Run_DialPlan] start Jan 13 14:57:46 Yakhchali-SBC [410624]: DBG:core:comp_scriptvar: str 29: 98212009 Jan 13 14:57:46 Yakhchali-SBC [410624]: DBG:dialplan:dp_translate_f: dpid is 1 partition is default Jan 13 14:57:46 Yakhchali-SBC [410624]: DBG:dialplan:dp_translate_f: input is 98212009 Jan 13 14:57:46 Yakhchali-SBC [410624]: DBG:dialplan:dp_translate_f: no information available for dpid 1 Jan 13 14:57:46 Yakhchali-SBC [410624]: DBG:dialplan:dp_translate_f: dpid is 2 partition is default Jan 13 14:57:46 Yakhchali-SBC [410624]: DBG:dialplan:dp_translate_f: input is 98212010 Jan 13 14:57:46 Yakhchali-SBC [410624]: DBG:dialplan:dp_translate_f: no information available for dpid 2 Jan 13 14:57:46 Yakhchali-SBC [410624]: DBG:permissions:get_source_group: Looking for <172.25.5.253, 54700> in address table Jan 13 14:57:46 Yakhchali-SBC [410624]: DBG:permissions:get_source_group: Looking for in subnet table Jan 13 14:57:46 Yakhchali-SBC [410624]: DBG:permissions:get_source_group: IP <172.25.5.253:54700> not found in any group Jan 13 14:57:46 Yakhchali-SBC [410624]: DBG:core:parse_headers_aux: flags=ffffffffffffffff Jan 13 14:57:46 Yakhchali-SBC [410624]: DBG:core:parse_headers_aux: flags=ffffffffffffffff Jan 13 14:57:46 Yakhchali-SBC [410624]: DBG:core:parse_headers_aux: flags=ffffffffffffffff Jan 13 14:57:46 Yakhchali-SBC [410624]: DBG:core:parse_headers_aux: flags=ffffffffffffffff Jan 13 14:57:46 Yakhchali-SBC [410624]: INFO:[1c41cdc79d3a4b2ea7c841ef49518a00(INVITE)] [load_routing_info] cache_key routing_requests:172.25.17.70:TLS:172.25.17.70:5061 Jan 13 14:57:46 Yakhchali-SBC [410624]: DBG:core:cachedb_fetch: from script [redis] - with grp [local] Jan 13 14:57:46 Yakhchali-SBC [410624]: DBG:cachedb_redis:get_redis_connection: Single redis connection, returning 0x7f4020c98488 Jan 13 14:57:46 Yakhchali-SBC [410624]: DBG:cachedb_redis:redis_get: GET routing_requests:172.25.17.70:TLS:172.25.17.70:5061 - [{"ifacesalida":"","Outgoingfromvalue":"","net":"0.0.0.0\/0.0.0.0","idrtpin":"external","routebymatchingrule_from":"none","routebymatchingrule_to":"none","ratelimit":"0","isWhitelist":"0","handleRtp":"1","nextHop":"0","srtp_mode":"transient","allowedNet":"0.0.0.0\/0.0.0.0","nextHopTransport":"","idrtpout":"external","codecs":"pcmu,pcma,gsm,speex,opus,g718,g719,g721,g723,g726,g728,g729,ilbc","rtpparam":null,"setid":"2","b2b":"1","metrica":"1","prefix_remove_add":"[]","route_id":57,"dispatcher_algo":"","sip_hdr_to_add":"","sip_hdr_prefix_to_remove":"","normal_compact_sip_hdr":"no","check_sip_from_hdr":"no","h323_gw_id":"0","allowed_methods":"NOTIFY|OPTIONS|INFO|SUBSCRIBE|PUBLISH","outbound_proxy":null,"nat_handling":"disable","fraud_pro_id":"","fraud_action":"","fraud_excluded_username":"","add_chk_hdrs":"false","match_type_from":"match","match_type_to":"match"}] Jan 13 14:57:46 Yakhchali-SBC [410624]: DBG:[1c41cdc79d3a4b2ea7c841ef49518a00(INVITE)] [load_routing_info] routes:[ { "ifacesalida": "", "Outgoingfromvalue": "", "net": "0.0.0.0\/0.0.0.0", "idrtpin": "external", "routebymatchingrule_from": "none", "routebymatchingrule_to": "none", "ratelimit": "0", "isWhitelist": "0", "handleRtp": "1", "nextHop": "0", "srtp_mode": "transient", "allowedNet": "0.0.0.0\/0.0.0.0", "nextHopTransport": "", "idrtpout": "external", "codecs": "pcmu,pcma,gsm,speex,opus,g718,g719,g721,g723,g726,g728,g729,ilbc", "rtpparam": null, "setid": "2", "b2b": "1", "metrica": "1", "prefix_remove_add": "[]", "route_id": 57, "dispatcher_algo": "", "sip_hdr_to_add": "", "sip_hdr_prefix_to_remove": "", "normal_compact_sip_hdr": "no", "check_sip_from_hdr": "no", "h323_gw_id": "0", "allowed_methods": "NOTIFY|OPTIONS|INFO|SUBSCRIBE|PUBLISH", "outbound_proxy": null, "nat_handling": "disable", "fraud_pro_id": "", "fraud_action": "", "fraud_excluded_username": "", "add_chk_hdrs": "false", "match_type_from": "match", "match_type_to": "match" } ] Jan 13 14:57:46 Yakhchali-SBC [410624]: DBG:core:comp_scriptvar: str 29: none Jan 13 14:57:46 Yakhchali-SBC [410624]: DBG:core:comp_scriptvar: str 29: none Jan 13 14:57:46 Yakhchali-SBC [410624]: DBG:core:comp_scriptvar: str 29: none Jan 13 14:57:46 Yakhchali-SBC [410624]: DBG:core:comp_scriptvar: str 29: none Jan 13 14:57:46 Yakhchali-SBC [410624]: DBG:core:comp_scriptvar: str 20: 0.0.0.0/0.0.0.0 Jan 13 14:57:46 Yakhchali-SBC [410624]: DBG:core:comp_scriptvar: str 20: Jan 13 14:57:46 Yakhchali-SBC [410624]: INFO:[1c41cdc79d3a4b2ea7c841ef49518a00(INVITE)] [checksourceip] ip:172.25.5.253 matches 0.0.0.0/0.0.0.0 Jan 13 14:57:46 Yakhchali-SBC [410624]: DBG:core:comp_scriptvar: str 20: false Jan 13 14:57:46 Yakhchali-SBC [410624]: DBG:core:destroy_index_avp: AVP with the specified index not found Jan 13 14:57:46 Yakhchali-SBC [410624]: DBG:core:destroy_index_avp: AVP with the specified index not found Jan 13 14:57:46 Yakhchali-SBC [410624]: DBG:core:destroy_index_avp: AVP with the specified index not found Jan 13 14:57:46 Yakhchali-SBC [410624]: DBG:core:destroy_index_avp: AVP with the specified index not found Jan 13 14:57:46 Yakhchali-SBC [410624]: INFO:[1c41cdc79d3a4b2ea7c841ef49518a00(INVITE)] [load_routing_info] route found:{ "ifacesalida": "", "Outgoingfromvalue": "", "net": "0.0.0.0\/0.0.0.0", "idrtpin": "external", "routebymatchingrule_from": "none", "routebymatchingrule_to": "none", "ratelimit": "0", "isWhitelist": "0", "handleRtp": "1", "nextHop": "0", "srtp_mode": "transient", "allowedNet": "0.0.0.0\/0.0.0.0", "nextHopTransport": "", "idrtpout": "external", "codecs": "pcmu,pcma,gsm,speex,opus,g718,g719,g721,g723,g726,g728,g729,ilbc", "rtpparam": null, "setid": "2", "b2b": "1", "metrica": "1", "prefix_remove_add": "[]", "route_id": 57, "dispatcher_algo": "", "sip_hdr_to_add": "", "sip_hdr_prefix_to_remove": "", "normal_compact_sip_hdr": "no", "check_sip_from_hdr": "no", "h323_gw_id": "0", "allowed_methods": "NOTIFY|OPTIONS|INFO|SUBSCRIBE|PUBLISH", "outbound_proxy": null, "nat_handling": "disable", "fraud_pro_id": "", "fraud_action": "", "fraud_excluded_username": "", "add_chk_hdrs": "false", "match_type_from": "match", "match_type_to": "match" } Jan 13 14:57:46 Yakhchali-SBC [410624]: DBG:core:comp_scriptvar: int 25: 0 / 0 Jan 13 14:57:46 Yakhchali-SBC [410624]: DBG:[1c41cdc79d3a4b2ea7c841ef49518a00(INVITE)] [apply_route_dialplan] rules:[ ] Jan 13 14:57:46 Yakhchali-SBC [410624]: INFO:[1c41cdc79d3a4b2ea7c841ef49518a00(INVITE)] [check_method] INVITE: NOTIFY|OPTIONS|INFO|SUBSCRIBE|PUBLISH Jan 13 14:57:46 Yakhchali-SBC [410624]: DBG:core:comp_scriptvar: str 20: no Jan 13 14:57:46 Yakhchali-SBC [410624]: INFO:[1c41cdc79d3a4b2ea7c841ef49518a00(INVITE)] [initialrequest] route b2b:1 Jan 13 14:57:46 Yakhchali-SBC [410624]: DBG:core:comp_scriptvar: str 20: 1 Jan 13 14:57:46 Yakhchali-SBC [410624]: DBG:core:parse_headers_aux: flags=ffffffffffffffff Jan 13 14:57:46 Yakhchali-SBC [410624]: DBG:core:comp_scriptvar: str 29: b2b Jan 13 14:57:46 Yakhchali-SBC [410624]: DBG:core:parse_headers_aux: flags=ffffffffffffffff Jan 13 14:57:46 Yakhchali-SBC [410624]: DBG:core:decode_mime_type: Decoding MIME type for:[application/sdp] Jan 13 14:57:46 Yakhchali-SBC [410624]: DBG:[1c41cdc79d3a4b2ea7c841ef49518a00(INVITE)] [Check_Codecs] avp(codecs):pcmu,pcma,gsm,speex,opus,g718,g719,g721,g723,g726,g728,g729,ilbc avp(rtpparam): Jan 13 14:57:46 Yakhchali-SBC [410624]: DBG:core:comp_scriptvar: str 20: pcmu,pcma,gsm,speex,opus,g718,g719,g721,g723,g726,g728,g729,ilbc Jan 13 14:57:46 Yakhchali-SBC [410624]: DBG:core:comp_scriptvar: str 20: pcmu,pcma,gsm,speex,opus,g718,g719,g721,g723,g726,g728,g729,ilbc Jan 13 14:57:46 Yakhchali-SBC [410624]: DBG:core:comp_scriptvar: str 20: pcmu,pcma,gsm,speex,opus,g718,g719,g721,g723,g726,g728,g729,ilbc Jan 13 14:57:46 Yakhchali-SBC [410624]: DBG:core:tr_eval_re: Trying to apply regexp [/,/|/g] on : [pcmu,pcma,gsm,speex,opus,g718,g719,g721,g723,g726,g728,g729,ilbc] Jan 13 14:57:46 Yakhchali-SBC [410624]: DBG:core:tr_eval_re: yay, we can use the pre-compile regexp Jan 13 14:57:46 Yakhchali-SBC [410624]: DBG:core:subst_run: running. r=0 Jan 13 14:57:46 Yakhchali-SBC [410624]: DBG:core:subst_run: matched (4, 1): [,] Jan 13 14:57:46 Yakhchali-SBC [410624]: DBG:core:subst_run: running. r=0 Jan 13 14:57:46 Yakhchali-SBC [410624]: DBG:core:subst_run: matched (9, 1): [,] Jan 13 14:57:46 Yakhchali-SBC [410624]: DBG:core:subst_run: running. r=0 Jan 13 14:57:46 Yakhchali-SBC [410624]: DBG:core:subst_run: matched (13, 1): [,] Jan 13 14:57:46 Yakhchali-SBC [410624]: DBG:core:subst_run: running. r=0 Jan 13 14:57:46 Yakhchali-SBC [410624]: DBG:core:subst_run: matched (19, 1): [,] Jan 13 14:57:46 Yakhchali-SBC [410624]: DBG:core:subst_run: running. r=0 Jan 13 14:57:46 Yakhchali-SBC [410624]: DBG:core:subst_run: matched (24, 1): [,] Jan 13 14:57:46 Yakhchali-SBC [410624]: DBG:core:subst_run: running. r=0 Jan 13 14:57:46 Yakhchali-SBC [410624]: DBG:core:subst_run: matched (29, 1): [,] Jan 13 14:57:46 Yakhchali-SBC [410624]: DBG:core:subst_run: running. r=0 Jan 13 14:57:46 Yakhchali-SBC [410624]: DBG:core:subst_run: matched (34, 1): [,] Jan 13 14:57:46 Yakhchali-SBC [410624]: DBG:core:subst_run: running. r=0 Jan 13 14:57:46 Yakhchali-SBC [410624]: DBG:core:subst_run: matched (39, 1): [,] Jan 13 14:57:46 Yakhchali-SBC [410624]: DBG:core:subst_run: running. r=0 Jan 13 14:57:46 Yakhchali-SBC [410624]: DBG:core:subst_run: matched (44, 1): [,] Jan 13 14:57:46 Yakhchali-SBC [410624]: DBG:core:subst_run: running. r=0 Jan 13 14:57:46 Yakhchali-SBC [410624]: DBG:core:subst_run: matched (49, 1): [,] Jan 13 14:57:46 Yakhchali-SBC [410624]: DBG:core:subst_run: running. r=0 Jan 13 14:57:46 Yakhchali-SBC [410624]: DBG:core:subst_run: matched (54, 1): [,] Jan 13 14:57:46 Yakhchali-SBC [410624]: DBG:core:subst_run: running. r=0 Jan 13 14:57:46 Yakhchali-SBC [410624]: DBG:core:subst_run: matched (59, 1): [,] Jan 13 14:57:46 Yakhchali-SBC [410624]: DBG:core:subst_run: running. r=1 Jan 13 14:57:46 Yakhchali-SBC [410624]: DBG:[1c41cdc79d3a4b2ea7c841ef49518a00(INVITE)] [Check_Codecs] regex to search is: pcmu|pcma|gsm|speex|opus|g718|g719|g721|g723|g726|g728|g729|ilbc Jan 13 14:57:46 Yakhchali-SBC [410624]: DBG:core:tr_eval_re: Trying to apply regexp [/,/|/g] on : [pcmu,pcma,gsm,speex,opus,g718,g719,g721,g723,g726,g728,g729,ilbc] Jan 13 14:57:46 Yakhchali-SBC [410624]: DBG:core:tr_eval_re: yay, we can use the pre-compile regexp Jan 13 14:57:46 Yakhchali-SBC [410624]: DBG:core:subst_run: running. r=0 Jan 13 14:57:46 Yakhchali-SBC [410624]: DBG:core:subst_run: matched (4, 1): [,] Jan 13 14:57:46 Yakhchali-SBC [410624]: DBG:core:subst_run: running. r=0 Jan 13 14:57:46 Yakhchali-SBC [410624]: DBG:core:subst_run: matched (9, 1): [,] Jan 13 14:57:46 Yakhchali-SBC [410624]: DBG:core:subst_run: running. r=0 Jan 13 14:57:46 Yakhchali-SBC [410624]: DBG:core:subst_run: matched (13, 1): [,] Jan 13 14:57:46 Yakhchali-SBC [410624]: DBG:core:subst_run: running. r=0 Jan 13 14:57:46 Yakhchali-SBC [410624]: DBG:core:subst_run: matched (19, 1): [,] Jan 13 14:57:46 Yakhchali-SBC [410624]: DBG:core:subst_run: running. r=0 Jan 13 14:57:46 Yakhchali-SBC [410624]: DBG:core:subst_run: matched (24, 1): [,] Jan 13 14:57:46 Yakhchali-SBC [410624]: DBG:core:subst_run: running. r=0 Jan 13 14:57:46 Yakhchali-SBC [410624]: DBG:core:subst_run: matched (29, 1): [,] Jan 13 14:57:46 Yakhchali-SBC [410624]: DBG:core:subst_run: running. r=0 Jan 13 14:57:46 Yakhchali-SBC [410624]: DBG:core:subst_run: matched (34, 1): [,] Jan 13 14:57:46 Yakhchali-SBC [410624]: DBG:core:subst_run: running. r=0 Jan 13 14:57:46 Yakhchali-SBC [410624]: DBG:core:subst_run: matched (39, 1): [,] Jan 13 14:57:46 Yakhchali-SBC [410624]: DBG:core:subst_run: running. r=0 Jan 13 14:57:46 Yakhchali-SBC [410624]: DBG:core:subst_run: matched (44, 1): [,] Jan 13 14:57:46 Yakhchali-SBC [410624]: DBG:core:subst_run: running. r=0 Jan 13 14:57:46 Yakhchali-SBC [410624]: DBG:core:subst_run: matched (49, 1): [,] Jan 13 14:57:46 Yakhchali-SBC [410624]: DBG:core:subst_run: running. r=0 Jan 13 14:57:46 Yakhchali-SBC [410624]: DBG:core:subst_run: matched (54, 1): [,] Jan 13 14:57:46 Yakhchali-SBC [410624]: DBG:core:subst_run: running. r=0 Jan 13 14:57:46 Yakhchali-SBC [410624]: DBG:core:subst_run: matched (59, 1): [,] Jan 13 14:57:46 Yakhchali-SBC [410624]: DBG:core:subst_run: running. r=1 Jan 13 14:57:46 Yakhchali-SBC [410624]: DBG:core:parse_sdp_session: Found FMTP [0-16] for payload [101] Jan 13 14:57:46 Yakhchali-SBC [410624]: DBG:core:try_set_fmtp_payload_link: We need to link [0-16] to [101] Jan 13 14:57:46 Yakhchali-SBC [410624]: DBG:core:parse_sdp_session: extracted attr [cname:66217ff13dc73666] for payload [1216100939] Jan 13 14:57:46 Yakhchali-SBC [410624]: DBG:core:set_sdp_payload_custom_attr: No payload_attr Jan 13 14:57:46 Yakhchali-SBC [410624]: DBG:sipmsgops:create_codec_lumps: creating 1 streams Jan 13 14:57:46 Yakhchali-SBC [410624]: DBG:sipmsgops:get_associated_lump: Have 1 lumps Jan 13 14:57:46 Yakhchali-SBC [410624]: DBG:sipmsgops:get_associated_lump: have lump at 820 want at 820 Jan 13 14:57:46 Yakhchali-SBC [410624]: DBG:core:comp_scriptvar: str 20: transient Jan 13 14:57:46 Yakhchali-SBC [410624]: DBG:core:cachedb_fetch: from script [redis] - with grp [local] Jan 13 14:57:46 Yakhchali-SBC [410624]: DBG:cachedb_redis:get_redis_connection: Single redis connection, returning 0x7f4020c98488 Jan 13 14:57:46 Yakhchali-SBC [410624]: DBG:cachedb_redis:redis_get: no such key - Tagged_Numbers Jan 13 14:57:46 Yakhchali-SBC [410624]: DBG:core:comp_scriptvar: int 26: 4 / 13 Jan 13 14:57:46 Yakhchali-SBC [410624]: DBG:core:comp_scriptvar: str 20: false Jan 13 14:57:46 Yakhchali-SBC [410624]: DBG:core:tr_eval_string: i=0 j=4 Jan 13 14:57:46 Yakhchali-SBC [410624]: DBG:core:tr_eval_string: i=0 j=4 Jan 13 14:57:46 Yakhchali-SBC [410624]: DBG:core:comp_scriptvar: int 26: 5 / 13 Jan 13 14:57:46 Yakhchali-SBC [410624]: DBG:core:comp_scriptvar: str 20: false Jan 13 14:57:46 Yakhchali-SBC [410624]: DBG:core:tr_eval_string: i=0 j=5 Jan 13 14:57:46 Yakhchali-SBC [410624]: DBG:core:tr_eval_string: i=0 j=5 Jan 13 14:57:46 Yakhchali-SBC [410624]: DBG:core:comp_scriptvar: int 26: 6 / 13 Jan 13 14:57:46 Yakhchali-SBC [410624]: DBG:core:comp_scriptvar: str 20: false Jan 13 14:57:46 Yakhchali-SBC [410624]: DBG:core:tr_eval_string: i=0 j=6 Jan 13 14:57:46 Yakhchali-SBC [410624]: DBG:core:tr_eval_string: i=0 j=6 Jan 13 14:57:46 Yakhchali-SBC [410624]: DBG:core:comp_scriptvar: int 26: 7 / 13 Jan 13 14:57:46 Yakhchali-SBC [410624]: DBG:core:comp_scriptvar: str 20: false Jan 13 14:57:46 Yakhchali-SBC [410624]: DBG:core:tr_eval_string: i=0 j=7 Jan 13 14:57:46 Yakhchali-SBC [410624]: DBG:core:tr_eval_string: i=0 j=7 Jan 13 14:57:46 Yakhchali-SBC [410624]: DBG:core:comp_scriptvar: int 26: 8 / 13 Jan 13 14:57:46 Yakhchali-SBC [410624]: DBG:core:comp_scriptvar: str 20: false Jan 13 14:57:46 Yakhchali-SBC [410624]: DBG:core:tr_eval_string: i=0 j=8 Jan 13 14:57:46 Yakhchali-SBC [410624]: DBG:core:tr_eval_string: i=0 j=8 Jan 13 14:57:46 Yakhchali-SBC [410624]: DBG:core:comp_scriptvar: int 26: 9 / 13 Jan 13 14:57:46 Yakhchali-SBC [410624]: DBG:core:comp_scriptvar: str 20: false Jan 13 14:57:46 Yakhchali-SBC [410624]: DBG:core:tr_eval_string: i=0 j=9 Jan 13 14:57:46 Yakhchali-SBC [410624]: DBG:core:tr_eval_string: i=0 j=9 Jan 13 14:57:46 Yakhchali-SBC [410624]: DBG:core:comp_scriptvar: int 26: 10 / 13 Jan 13 14:57:46 Yakhchali-SBC [410624]: DBG:core:comp_scriptvar: str 20: false Jan 13 14:57:46 Yakhchali-SBC [410624]: DBG:core:tr_eval_string: i=0 j=10 Jan 13 14:57:46 Yakhchali-SBC [410624]: DBG:core:tr_eval_string: i=0 j=10 Jan 13 14:57:46 Yakhchali-SBC [410624]: DBG:core:comp_scriptvar: int 26: 11 / 13 Jan 13 14:57:46 Yakhchali-SBC [410624]: DBG:core:comp_scriptvar: str 20: false Jan 13 14:57:46 Yakhchali-SBC [410624]: DBG:core:tr_eval_string: i=0 j=11 Jan 13 14:57:46 Yakhchali-SBC [410624]: DBG:core:tr_eval_string: i=0 j=11 Jan 13 14:57:46 Yakhchali-SBC [410624]: DBG:core:comp_scriptvar: int 26: 12 / 13 Jan 13 14:57:46 Yakhchali-SBC [410624]: DBG:core:comp_scriptvar: str 20: false Jan 13 14:57:46 Yakhchali-SBC [410624]: DBG:core:tr_eval_string: i=0 j=12 Jan 13 14:57:46 Yakhchali-SBC [410624]: DBG:core:tr_eval_string: i=0 j=12 Jan 13 14:57:46 Yakhchali-SBC [410624]: DBG:core:comp_scriptvar: int 26: 13 / 13 Jan 13 14:57:46 Yakhchali-SBC [410624]: DBG:core:cachedb_fetch: from script [redis] - with grp [local] Jan 13 14:57:46 Yakhchali-SBC [410624]: DBG:cachedb_redis:get_redis_connection: Single redis connection, returning 0x7f4020c98488 Jan 13 14:57:46 Yakhchali-SBC [410624]: DBG:cachedb_redis:redis_get: no such key - ValueAddedServices:98212010 Jan 13 14:57:46 Yakhchali-SBC [410624]: NOTICE:[1c41cdc79d3a4b2ea7c841ef49518a00(INVITE)] [initialrequest] next ho:0 Jan 13 14:57:46 Yakhchali-SBC [410624]: DBG:core:comp_scriptvar: int 20: 0 / 0 Jan 13 14:57:46 Yakhchali-SBC [410624]: INFO:[1c41cdc79d3a4b2ea7c841ef49518a00(INVITE)] [initialrequest] avp(nextHop):0 destino:lookup Jan 13 14:57:46 Yakhchali-SBC [410624]: DBG:core:comp_scriptvar: str 29: b2b Jan 13 14:57:46 Yakhchali-SBC [410624]: DBG:core:parse_headers_aux: flags=ffffffffffffffff Jan 13 14:57:46 Yakhchali-SBC [410624]: DBG:sipmsgops:is_present_hf: header ''(10) not found Jan 13 14:57:46 Yakhchali-SBC [410624]: DBG:core:comp_scriptvar: str 20: disable Jan 13 14:57:46 Yakhchali-SBC [410624]: DBG:core:comp_scriptvar: str 20: tls Jan 13 14:57:46 Yakhchali-SBC [410624]: DBG:core:comp_scriptvar: str 20: tls Jan 13 14:57:46 Yakhchali-SBC [410624]: DBG:core:comp_scriptvar: str 29: b2b Jan 13 14:57:46 Yakhchali-SBC [410624]: DBG:core:parse_headers_aux: flags=ffffffffffffffff Jan 13 14:57:46 Yakhchali-SBC [410624]: DBG:core:parse_headers_aux: flags=ffffffffffffffff Jan 13 14:57:46 Yakhchali-SBC [410624]: DBG:core:parse_headers_aux: flags=ffffffffffffffff Jan 13 14:57:46 Yakhchali-SBC [410624]: INFO:[1c41cdc79d3a4b2ea7c841ef49518a00(INVITE)] [checkresults] Outgoing Interface: destination:lookup net:0.0.0.0/0.0.0.0 Jan 13 14:57:46 Yakhchali-SBC [410624]: INFO:[1c41cdc79d3a4b2ea7c841ef49518a00(INVITE)] [initialrequest] destination after applying protocol:lookup Jan 13 14:57:46 Yakhchali-SBC [410624]: DBG:core:tr_eval_string: i=0 j=6 Jan 13 14:57:46 Yakhchali-SBC [410624]: DBG:core:comp_scriptvar: str 20: lookup Jan 13 14:57:46 Yakhchali-SBC [410624]: DBG:core:parse_headers_aux: flags=ffffffffffffffff Jan 13 14:57:46 Yakhchali-SBC [410624]: INFO:[1c41cdc79d3a4b2ea7c841ef49518a00(INVITE)] [initialrequest] looking up X-chakavak_orginal_did: Jan 13 14:57:46 Yakhchali-SBC [410624]: DBG:core:select_contacts: ct: sip:98212010@172.25.5.253:7070;ob Jan 13 14:57:46 Yakhchali-SBC [410624]: DBG:core:push_branch: setting msg R-URI Jan 13 14:57:46 Yakhchali-SBC [410624]: INFO:[1c41cdc79d3a4b2ea7c841ef49518a00(INVITE)] [initialrequest] lookup ru:sip:98212010@172.25.5.253:7070;ob Jan 13 14:57:46 Yakhchali-SBC [410624]: DBG:[1c41cdc79d3a4b2ea7c841ef49518a00(INVITE)] [initialrequest] contact_attributes: Jan 13 14:57:46 Yakhchali-SBC [410624]: DBG:core:parse_headers_aux: flags=ffffffffffffffff Jan 13 14:57:46 Yakhchali-SBC [410624]: DBG:[1c41cdc79d3a4b2ea7c841ef49518a00(INVITE)] [filter_headers] sip_hdr_prefix_to_remove: param(1):lookup direction:from_ss Jan 13 14:57:46 Yakhchali-SBC [410624]: DBG:core:comp_scriptvar: str 20: lookup Jan 13 14:57:46 Yakhchali-SBC [410624]: DBG:core:comp_scriptvar: str 20: lookup Jan 13 14:57:46 Yakhchali-SBC [410624]: DBG:core:comp_scriptvar: str 20: lookup Jan 13 14:57:46 Yakhchali-SBC [410624]: DBG:core:parse_headers_aux: flags=ffffffffffffffff Jan 13 14:57:46 Yakhchali-SBC [410624]: DBG:core:parse_headers_aux: flags=ffffffffffffffff Jan 13 14:57:46 Yakhchali-SBC [410624]: DBG:[1c41cdc79d3a4b2ea7c841ef49518a00(INVITE)] [relay] du:sip:172.25.5.253:7070 ru:sip:98212010@172.25.5.253:7070;ob Jan 13 14:57:46 Yakhchali-SBC [410624]: DBG:[1c41cdc79d3a4b2ea7c841ef49518a00(INVITE)] [filter_headers] sip_hdr_prefix_to_remove: param(1):invite direction:from_ss Jan 13 14:57:46 Yakhchali-SBC [410624]: DBG:core:comp_scriptvar: str 20: invite Jan 13 14:57:46 Yakhchali-SBC [410624]: DBG:core:comp_scriptvar: str 20: invite Jan 13 14:57:46 Yakhchali-SBC [410624]: DBG:core:comp_scriptvar: str 20: invite Jan 13 14:57:46 Yakhchali-SBC [410624]: DBG:core:comp_scriptvar: str 20: invite Jan 13 14:57:46 Yakhchali-SBC [410624]: DBG:sipmsgops:has_totag: no totag Jan 13 14:57:46 Yakhchali-SBC [410624]: INFO:[1c41cdc79d3a4b2ea7c841ef49518a00(INVITE)] [apply_manipulations] var(out_from_ip): var(out_to_ip):172.25.5.253 var(dpFrom): var(out_to_ip):172.25.5.253 var(dpRu): dd:172.25.5.253 dp:7070 Jan 13 14:57:46 Yakhchali-SBC [410624]: DBG:core:pv_get_xto_attr: no Display name Jan 13 14:57:46 Yakhchali-SBC [410624]: DBG:core:comp_scriptvar: str 29: no Jan 13 14:57:46 Yakhchali-SBC [410624]: INFO:[1c41cdc79d3a4b2ea7c841ef49518a00(INVITE)] [apply_manipulations] replace to:sip:98212010@172.25.17.70 => sip:98212010@172.25.5.253 Jan 13 14:57:46 Yakhchali-SBC [410624]: DBG:uac:replace_uri: uri to replace [], replacement is [] Jan 13 14:57:46 Yakhchali-SBC [410624]: DBG:uac:replace_uri: encode is= len=36 Jan 13 14:57:46 Yakhchali-SBC [410624]: DBG:rr:add_rr_param: adding (;vst=ImNGOWZieGZ3XXFgAwJxYXFlWGh6YXJgcWxO) Jan 13 14:57:46 Yakhchali-SBC [410624]: DBG:core:tr_eval_string: i=0 j=6 Jan 13 14:57:46 Yakhchali-SBC [410624]: DBG:core:comp_scriptvar: str 29: lookup Jan 13 14:57:46 Yakhchali-SBC [410624]: DBG:b2b_logic:get_ctx_vals: tuple not created yet Jan 13 14:57:46 Yakhchali-SBC [410624]: DBG:b2b_logic:fetch_ctx_value: looking for context value [route_data] Jan 13 14:57:46 Yakhchali-SBC [410624]: DBG:b2b_logic:fetch_ctx_value: context value not found! Jan 13 14:57:46 Yakhchali-SBC [410624]: DBG:core:route_param_get: route without parameters Jan 13 14:57:46 Yakhchali-SBC [410624]: DBG:core:route_param_get: route without parameters Jan 13 14:57:46 Yakhchali-SBC [410624]: DBG:core:comp_scriptvar: str 20: b2b Jan 13 14:57:46 Yakhchali-SBC [410624]: DBG:core:comp_scriptvar: str 20: b2b Jan 13 14:57:46 Yakhchali-SBC [410624]: DBG:[1c41cdc79d3a4b2ea7c841ef49518a00(INVITE)] [save_session_data] using b2bctx Jan 13 14:57:46 Yakhchali-SBC [410624]: DBG:b2b_logic:get_ctx_vals: tuple not created yet Jan 13 14:57:46 Yakhchali-SBC [410624]: DBG:b2b_logic:store_ctx_value: inserting [route_data]=[{ "ifacesalida": "", "Outgoingfromvalue": "", "net": "0.0.0.0\/0.0.0.0", "idrtpin": "external", "routebymatchingrule_from": "none", "routebymatchingrule_to": "none", "ratelimit": "0", "isWhitelist": "0", "handleRtp": "1", "nextHop": "0", "srtp_mode": "transient", "allowedNet": "0.0.0.0\/0.0.0.0", "nextHopTransport": "", "idrtpout": "external", "codecs": "pcmu,pcma,gsm,speex,opus,g718,g719,g721,g723,g726,g728,g729,ilbc", "rtpparam": null, "setid": "2", "b2b": "1", "metrica": "1", "prefix_remove_add": "[]", "route_id": 57, "dispatcher_algo": "", "sip_hdr_to_add": "", "sip_hdr_prefix_to_remove": "", "normal_compact_sip_hdr": "no", "check_sip_from_hdr": "no", "h323_gw_id": "0", "allowed_methods": "NOTIFY|OPTIONS|INFO|SUBSCRIBE|PUBLISH", "outbound_proxy": null, "nat_handling": "disable", "fraud_pro_id": "", "fraud_action": "", "fraud_excluded_username": "", "add_chk_hdrs": "false", "match_type_from": "match", "match_type_to": "match", "call_sourceip": "172.25.5.253", "is_dst_ws": -1, "is_src_ws": -1, "socket_out": "udp:172.25.17.70:5060", "rtp_cid": "1c41cdc79d3a4b2ea7c841ef49518a00", "rtp_from_tag": "44432d591fe247278a2b558198fcd166" }] Jan 13 14:57:46 Yakhchali-SBC [410624]: DBG:core:comp_scriptvar: str 29: b2b Jan 13 14:57:46 Yakhchali-SBC [410624]: DBG:core:comp_scriptvar: str 20: b2b Jan 13 14:57:46 Yakhchali-SBC [410624]: DBG:[1c41cdc79d3a4b2ea7c841ef49518a00(INVITE)] [relay] engaging b2b refer, DLG_status: Jan 13 14:57:46 Yakhchali-SBC [410624]: DBG:b2b_logic:b2bl_entity_new: First new entity [caller] saved in context Jan 13 14:57:46 Yakhchali-SBC [410624]: DBG:b2b_logic:b2bl_entity_new: Second new entity [callee] saved in context Jan 13 14:57:46 Yakhchali-SBC [410624]: DBG:b2b_logic:get_ctx_vals: tuple not created yet Jan 13 14:57:46 Yakhchali-SBC [410624]: DBG:b2b_logic:store_ctx_value: inserting [aleg_cid]=[1c41cdc79d3a4b2ea7c841ef49518a00] Jan 13 14:57:46 Yakhchali-SBC [410624]: DBG:core:prep_reassemble_body_parts: only one part to be added Jan 13 14:57:46 Yakhchali-SBC [410624]: DBG:core:prep_reassemble_body_parts: handing part with flags 0, mime application/sdp, dump function (nil) Jan 13 14:57:46 Yakhchali-SBC [410624]: DBG:core:prep_reassemble_body_parts: lumps found in the part, applying... Jan 13 14:57:46 Yakhchali-SBC [410624]: DBG:core:prep_reassemble_body_parts: resulting body len is 316 Jan 13 14:57:46 Yakhchali-SBC [410624]: DBG:core:parse_headers_aux: flags=2000 Jan 13 14:57:46 Yakhchali-SBC [410624]: DBG:core:parse_headers_aux: flags=ffffffffffffffff Jan 13 14:57:46 Yakhchali-SBC [410624]: DBG:core:reassemble_body_parts: only one part to be added Jan 13 14:57:46 Yakhchali-SBC [410624]: DBG:core:reassemble_body_parts: handing part with flags 0, mime application/sdp, dump function (nil) Jan 13 14:57:46 Yakhchali-SBC [410624]: DBG:core:reassemble_body_parts: lumps found in the part, applying... Jan 13 14:57:46 Yakhchali-SBC [410624]: DBG:core:free_sdp_content: sdp = 0x7f4020c9b6d0 Jan 13 14:57:46 Yakhchali-SBC [410624]: DBG:core:free_sdp_content: sdp = 0x7f4020c9b6d0 Jan 13 14:57:46 Yakhchali-SBC [410624]: DBG:core:free_sdp_content: session = 0x7f4020c9aec8 Jan 13 14:57:46 Yakhchali-SBC [410624]: DBG:core:parse_msg: SIP Request: Jan 13 14:57:46 Yakhchali-SBC [410624]: DBG:core:parse_msg: method: Jan 13 14:57:46 Yakhchali-SBC [410624]: DBG:core:parse_msg: uri: Jan 13 14:57:46 Yakhchali-SBC [410624]: DBG:core:parse_msg: version: Jan 13 14:57:46 Yakhchali-SBC [410624]: DBG:core:parse_headers_aux: flags=ffffffffffffffff Jan 13 14:57:46 Yakhchali-SBC [410624]: DBG:core:parse_via_param: found param type 235, = ; state=6 Jan 13 14:57:46 Yakhchali-SBC [410624]: DBG:core:parse_via_param: found param type 232, = ; state=6 Jan 13 14:57:46 Yakhchali-SBC [410624]: DBG:core:parse_via_param: found param type 237, = ; state=16 Jan 13 14:57:46 Yakhchali-SBC [410624]: DBG:core:parse_via: end of header reached, state=5 Jan 13 14:57:46 Yakhchali-SBC [410624]: DBG:core:parse_headers_aux: via found, flags=ffffffffffffffff Jan 13 14:57:46 Yakhchali-SBC [410624]: DBG:core:parse_headers_aux: this is the first via Jan 13 14:57:46 Yakhchali-SBC [410624]: DBG:core:_parse_to: end of header reached, state=10 Jan 13 14:57:46 Yakhchali-SBC [410624]: DBG:core:_parse_to: display={}, ruri={sip:98212010@172.25.5.253} Jan 13 14:57:46 Yakhchali-SBC [410624]: DBG:core:get_hdr_field_aux: [29]; uri=[sip:98212010@172.25.5.253] Jan 13 14:57:46 Yakhchali-SBC [410624]: DBG:core:get_hdr_field_aux: to body [#015#012] Jan 13 14:57:46 Yakhchali-SBC [410624]: DBG:core:get_hdr_field_aux: cseq : <6323> Jan 13 14:57:46 Yakhchali-SBC [410624]: DBG:core:get_hdr_field_aux: content_length=316 Jan 13 14:57:46 Yakhchali-SBC [410624]: DBG:core:get_hdr_field_aux: found end of header Jan 13 14:57:46 Yakhchali-SBC [410624]: DBG:core:parse_headers_aux: flags=ffffffffffffffff Jan 13 14:57:46 Yakhchali-SBC [410624]: DBG:core:decode_mime_type: Decoding MIME type for:[application/sdp] Jan 13 14:57:46 Yakhchali-SBC [410624]: DBG:core:parse_sdp_session: Found FMTP [0-16] for payload [101] Jan 13 14:57:46 Yakhchali-SBC [410624]: DBG:core:try_set_fmtp_payload_link: We need to link [0-16] to [101] Jan 13 14:57:46 Yakhchali-SBC [410624]: DBG:core:parse_sdp_session: extracted attr [cname:66217ff13dc73666] for payload [1216100939] Jan 13 14:57:46 Yakhchali-SBC [410624]: DBG:core:set_sdp_payload_custom_attr: No payload_attr Jan 13 14:57:46 Yakhchali-SBC [410624]: DBG:core:parse_headers_aux: flags=ffffffffffffffff Jan 13 14:57:46 Yakhchali-SBC [410624]: DBG:core:parse_to_param: tag=44432d591fe247278a2b558198fcd166 Jan 13 14:57:46 Yakhchali-SBC [410624]: DBG:core:parse_to_param: end of header reached, state=11 Jan 13 14:57:46 Yakhchali-SBC [410624]: DBG:core:_parse_to: end of header reached, state=29 Jan 13 14:57:46 Yakhchali-SBC [410624]: DBG:core:_parse_to: display={}, ruri={sip:98212009@172.25.17.70} Jan 13 14:57:46 Yakhchali-SBC [410624]: DBG:core:parse_headers_aux: flags=ffffffffffffffff Jan 13 14:57:46 Yakhchali-SBC [410624]: DBG:b2b_logic:b2bl_insert_new: hash index [250]: Jan 13 14:57:46 Yakhchali-SBC [410624]: DBG:b2b_logic:b2bl_insert_new: id [0] Jan 13 14:57:46 Yakhchali-SBC [410624]: DBG:core:dup_ref_script_route_in_shm: dupping 0x7f401f737f78 [b2b_request], idx 42, ver/cnt 1, to new 0x7f3fdfd2c880 [b2b_request], idx 42, ver/cnt 1 Jan 13 14:57:46 Yakhchali-SBC [410624]: DBG:core:dup_ref_script_route_in_shm: dupping 0x7f401f73c618 [b2b_reply], idx 46, ver/cnt 1, to new 0x7f3fdfd16c70 [b2b_reply], idx 46, ver/cnt 1 Jan 13 14:57:46 Yakhchali-SBC [410624]: DBG:b2b_logic:b2bl_insert_new: new tuple [0x7f3fdfd2c730]->[250.0] Jan 13 14:57:46 Yakhchali-SBC [410624]: DBG:core:parse_headers_aux: flags=ffffffffffffffff Jan 13 14:57:46 Yakhchali-SBC [410624]: DBG:tm:t_newtran: transaction on entrance=(nil) Jan 13 14:57:46 Yakhchali-SBC [410624]: DBG:core:parse_headers_aux: flags=ffffffffffffffff Jan 13 14:57:46 Yakhchali-SBC [410624]: DBG:core:parse_headers_aux: flags=78 Jan 13 14:57:46 Yakhchali-SBC [410624]: DBG:tm:t_lookup_request: start searching: hash=58939, isACK=0 Jan 13 14:57:46 Yakhchali-SBC [410624]: DBG:tm:matching_3261: RFC3261 transaction matching failed Jan 13 14:57:46 Yakhchali-SBC [410624]: DBG:tm:t_lookup_request: no transaction found Jan 13 14:57:46 Yakhchali-SBC [410624]: DBG:tm:run_any_trans_callbacks: trans=0x7f3fdfd1a998, callback type 1, id 0 entered Jan 13 14:57:46 Yakhchali-SBC [410624]: DBG:core:parse_headers_aux: flags=ffffffffffffffff Jan 13 14:57:46 Yakhchali-SBC [410624]: DBG:core:tcp_conn_get: con found in state 0 Jan 13 14:57:46 Yakhchali-SBC [410624]: DBG:core:tcp_conn_get: tcp connection found (0x7f3fdfd15df8) already in this process ( 16 ) , fd = 196 Jan 13 14:57:46 Yakhchali-SBC [410624]: DBG:proto_tls:proto_tls_send: sending via fd 196... Jan 13 14:57:46 Yakhchali-SBC [410624]: DBG:tls_openssl:openssl_tls_update_fd: New fd is 196 Jan 13 14:57:46 Yakhchali-SBC [410624]: DBG:tls_openssl:openssl_tls_write: write was successful (343 bytes) Jan 13 14:57:46 Yakhchali-SBC [410624]: DBG:proto_tls:proto_tls_send: after write: c=0x7f3fdfd15df8 n=343 fd=196 Jan 13 14:57:46 Yakhchali-SBC [410624]: DBG:proto_tls:proto_tls_send: buf=#012SIP/2.0 100 Giving it a try#015#012Via: SIP/2.0/TLS 172.25.5.253:54700;received=172.25.5.253;rport=54700;branch=z9hG4bKPjc2c3b7e324214127a1036a887ab785e5;alias#015#012To: #015#012From: ;tag=44432d591fe247278a2b558198fcd166#015#012Call-ID: 1c41cdc79d3a4b2ea7c841ef49518a00#015#012CSeq: 6323 INVITE#015#012Content-Length: 0#015#012#015#012 Jan 13 14:57:46 Yakhchali-SBC [410624]: DBG:tm:_reply_light: reply sent out. buf=0x7f4020c9c2d0: SIP/2.0 1..., shmem=0x7f3fdfd1c420: SIP/2.0 1 Jan 13 14:57:46 Yakhchali-SBC [410624]: DBG:tm:_reply_light: finished Jan 13 14:57:46 Yakhchali-SBC [410624]: DBG:tm:t_ref_cell: REF_UNSAFE:[0x7f3fdfd1a998] after is 2 Jan 13 14:57:46 Yakhchali-SBC [410624]: DBG:b2b_entities:_server_new: new server entity[0x7f3fdfd37338]: callid=[1c41cdc79d3a4b2ea7c841ef49518a00] tag=[44432d591fe247278a2b558198fcd166] param=[250.0] dlg->uas_tran=[0x7f3fdfd1a998] Jan 13 14:57:46 Yakhchali-SBC [410624]: DBG:b2b_logic:b2bl_create_new_entity: new entity type [0] [0x7f3fdfd02810]->[B2B.412.51.1736767665.742304390] Jan 13 14:57:46 Yakhchali-SBC [410624]: DBG:core:MD5StringArray: MD5 calculated: 5d9d0a4cf3fa4717380f13d8f920816f Jan 13 14:57:46 Yakhchali-SBC [410624]: DBG:b2b_entities:generate_tag: from_tag = 5d9d0a4cf3fa4717380f13d8f920816f-a699 Jan 13 14:57:46 Yakhchali-SBC [410624]: DBG:core:parse_headers_aux: flags=ffffffffffffffff Jan 13 14:57:46 Yakhchali-SBC [410624]: DBG:tm:t_uac: next_hop= Jan 13 14:57:46 Yakhchali-SBC [410624]: DBG:core:mk_proxy: doing DNS lookup... Jan 13 14:57:46 Yakhchali-SBC [410624]: DBG:tm:t_uac: sending socket is 172.25.17.70 Jan 13 14:57:46 Yakhchali-SBC [410624]: DBG:tm:print_request_uri: sip:98212010@172.25.5.253:7070;ob Jan 13 14:57:46 Yakhchali-SBC [410624]: DBG:tm:run_local_route: building sip_msg from buffer Jan 13 14:57:46 Yakhchali-SBC [410624]: DBG:core:parse_msg: SIP Request: Jan 13 14:57:46 Yakhchali-SBC [410624]: DBG:core:parse_msg: method: Jan 13 14:57:46 Yakhchali-SBC [410624]: DBG:core:parse_msg: uri: Jan 13 14:57:46 Yakhchali-SBC [410624]: DBG:core:parse_msg: version: Jan 13 14:57:46 Yakhchali-SBC [410624]: DBG:core:parse_headers_aux: flags=ffffffffffffffff Jan 13 14:57:46 Yakhchali-SBC [410624]: DBG:core:parse_via_param: found param type 232, = ; state=16 Jan 13 14:57:46 Yakhchali-SBC [410624]: DBG:core:parse_via: end of header reached, state=5 Jan 13 14:57:46 Yakhchali-SBC [410624]: DBG:core:parse_headers_aux: via found, flags=ffffffffffffffff Jan 13 14:57:46 Yakhchali-SBC [410624]: DBG:core:parse_headers_aux: this is the first via Jan 13 14:57:46 Yakhchali-SBC [410624]: DBG:core:_parse_to: end of header reached, state=10 Jan 13 14:57:46 Yakhchali-SBC [410624]: DBG:core:_parse_to: display={}, ruri={sip:98212010@172.25.5.253:7070;ob} Jan 13 14:57:46 Yakhchali-SBC [410624]: DBG:core:get_hdr_field_aux: [37]; uri=[sip:98212010@172.25.5.253:7070;ob] Jan 13 14:57:46 Yakhchali-SBC [410624]: DBG:core:get_hdr_field_aux: to body [#015#012] Jan 13 14:57:46 Yakhchali-SBC [410624]: DBG:core:get_hdr_field_aux: cseq : <6324> Jan 13 14:57:46 Yakhchali-SBC [410624]: DBG:core:get_hdr_field_aux: content_length=316 Jan 13 14:57:46 Yakhchali-SBC [410624]: DBG:core:get_hdr_field_aux: found end of header Jan 13 14:57:46 Yakhchali-SBC [410624]: DBG:core:parse_headers_aux: flags=ffffffffffffffff Jan 13 14:57:46 Yakhchali-SBC [410624]: DBG:core:parse_headers_aux: flags=78 Jan 13 14:57:46 Yakhchali-SBC [410624]: NOTICE:[B2B.493.5675184.1736767665.1245583625] --------------------------------------------------------------------------- Jan 13 14:57:46 Yakhchali-SBC [410624]: DBG:core:parse_to_param: tag=5d9d0a4cf3fa4717380f13d8f920816f-a699 Jan 13 14:57:46 Yakhchali-SBC [410624]: DBG:core:parse_to_param: end of header reached, state=11 Jan 13 14:57:46 Yakhchali-SBC [410624]: DBG:core:_parse_to: end of header reached, state=29 Jan 13 14:57:46 Yakhchali-SBC [410624]: DBG:core:_parse_to: display={}, ruri={sip:98212009@172.25.17.70} Jan 13 14:57:46 Yakhchali-SBC [410624]: DBG:[B2B.493.5675184.1736767665.1245583625] [b2b_local_route] rm:INVITE si:172.25.17.70 rd:172.25.5.253 avp(net):0.0.0.0/0.0.0.0 fu:sip:98212009@172.25.17.70 tu:sip:98212010@172.25.5.253:7070;ob ci:B2B.493.5675184.1736767665.1245583625 socket:udp:172.25.17.70:5060 Jan 13 14:57:46 Yakhchali-SBC [410624]: DBG:core:comp_scriptvar: str 20: b2b Jan 13 14:57:46 Yakhchali-SBC [410624]: DBG:b2b_logic:fetch_ctx_value: looking for context value [route_data] Jan 13 14:57:46 Yakhchali-SBC [410624]: DBG:b2b_logic:fetch_ctx_value: looking for context value [route_data] Jan 13 14:57:46 Yakhchali-SBC [410624]: DBG:b2b_logic:fetch_ctx_value: looking for context value [route_data] Jan 13 14:57:46 Yakhchali-SBC [410624]: DBG:[B2B.493.5675184.1736767665.1245583625] [load_session_data] using b2bctx:{ "ifacesalida": "", "Outgoingfromvalue": "", "net": "0.0.0.0\/0.0.0.0", "idrtpin": "external", "routebymatchingrule_from": "none", "routebymatchingrule_to": "none", "ratelimit": "0", "isWhitelist": "0", "handleRtp": "1", "nextHop": "0", "srtp_mode": "transient", "allowedNet": "0.0.0.0\/0.0.0.0", "nextHopTransport": "", "idrtpout": "external", "codecs": "pcmu,pcma,gsm,speex,opus,g718,g719,g721,g723,g726,g728,g729,ilbc", "rtpparam": null, "setid": "2", "b2b": "1", "metrica": "1", "prefix_remove_add": "[]", "route_id": 57, "dispatcher_algo": "", "sip_hdr_to_add": "", "sip_hdr_prefix_to_remove": "", "normal_compact_sip_hdr": "no", "check_sip_from_hdr": "no", "h323_gw_id": "0", "allowed_methods": "NOTIFY|OPTIONS|INFO|SUBSCRIBE|PUBLISH", "outbound_proxy": null, "nat_handling": "disable", "fraud_pro_id": "", "fraud_action": "", "fraud_excluded_username": "", "add_chk_hdrs": "false", "match_type_from": "match", "match_type_to": "match", "call_sourceip": "172.25.5.253", "is_dst_ws": -1, "is_src_ws": -1, "socket_out": "udp:172.25.17.70:5060", "rtp_cid": "1c41cdc79d3a4b2ea7c841ef49518a00", "rtp_from_tag": "44432d591fe247278a2b558198fcd166" } Jan 13 14:57:46 Yakhchali-SBC [410624]: DBG:core:destroy_index_avp: AVP with the specified index not found Jan 13 14:57:46 Yakhchali-SBC [410624]: DBG:core:destroy_index_avp: AVP with the specified index not found Jan 13 14:57:46 Yakhchali-SBC [410624]: DBG:core:destroy_index_avp: AVP with the specified index not found Jan 13 14:57:46 Yakhchali-SBC [410624]: DBG:core:parse_headers_aux: flags=ffffffffffffffff Jan 13 14:57:46 Yakhchali-SBC [410624]: DBG:core:decode_mime_type: Decoding MIME type for:[application/sdp] Jan 13 14:57:46 Yakhchali-SBC [410624]: DBG:core:parse_sdp_session: Found FMTP [0-16] for payload [101] Jan 13 14:57:46 Yakhchali-SBC [410624]: DBG:core:try_set_fmtp_payload_link: We need to link [0-16] to [101] Jan 13 14:57:46 Yakhchali-SBC [410624]: DBG:core:parse_sdp_session: extracted attr [cname:66217ff13dc73666] for payload [1216100939] Jan 13 14:57:46 Yakhchali-SBC [410624]: DBG:core:set_sdp_payload_custom_attr: No payload_attr Jan 13 14:57:46 Yakhchali-SBC [410624]: DBG:core:comp_scriptvar: str 20: INVITE Jan 13 14:57:46 Yakhchali-SBC [410624]: DBG:[B2B.493.5675184.1736767665.1245583625] [b2b_local_route] non hold invite, setting socket:udp:172.25.17.70:5060 Jan 13 14:57:46 Yakhchali-SBC [410624]: DBG:core:grep_sock_info_ext: checking if host==us: 12==13 && [172.25.17.70] == [172.25.19.192] Jan 13 14:57:46 Yakhchali-SBC [410624]: DBG:core:grep_sock_info_ext: checking if port 5080 matches port 5060 Jan 13 14:57:46 Yakhchali-SBC [410624]: DBG:core:grep_sock_info_ext: checking if host==us: 12==12 && [172.25.17.70] == [172.25.17.70] Jan 13 14:57:46 Yakhchali-SBC [410624]: DBG:core:grep_sock_info_ext: checking if port 5060 matches port 5060 Jan 13 14:57:46 Yakhchali-SBC [410624]: DBG:core:comp_scriptvar: str 29: offer Jan 13 14:57:46 Yakhchali-SBC [410624]: DBG:[B2B.493.5675184.1736767665.1245583625] [load_session_data] already loaded Jan 13 14:57:46 Yakhchali-SBC [410624]: DBG:[B2B.493.5675184.1736767665.1245583625] [rtp_logic] mode:b2b req_type:offer DLG_dir: is_src_ws:-1 is_dst_ws:-1 Jan 13 14:57:46 Yakhchali-SBC [410624]: DBG:core:comp_scriptvar: str 20: offer Jan 13 14:57:46 Yakhchali-SBC [410624]: INFO:[B2B.493.5675184.1736767665.1245583625] [rtp_logic] set_id:2 req_type:offer req_dir:ab si:172.25.17.70 call_sourceip:172.25.5.253 srtp_mode:transient Jan 13 14:57:46 Yakhchali-SBC [410624]: DBG:core:comp_scriptvar: str 20: offer Jan 13 14:57:46 Yakhchali-SBC [410624]: DBG:core:parse_headers_aux: flags=ffffffffffffffff Jan 13 14:57:46 Yakhchali-SBC [410624]: DBG:core:comp_scriptvar: str 20: ab Jan 13 14:57:46 Yakhchali-SBC [410624]: DBG:core:comp_scriptvar: str 20: ab Jan 13 14:57:46 Yakhchali-SBC [410624]: DBG:core:comp_scriptvar: int 20: -1 / 1 Jan 13 14:57:46 Yakhchali-SBC [410624]: DBG:core:comp_scriptvar: int 20: -1 / 1 Jan 13 14:57:46 Yakhchali-SBC [410624]: DBG:core:comp_scriptvar: int 20: -1 / -1 Jan 13 14:57:46 Yakhchali-SBC [410624]: DBG:core:comp_scriptvar: int 20: -1 / 1 Jan 13 14:57:46 Yakhchali-SBC [410624]: DBG:core:comp_scriptvar: int 20: -1 / -1 Jan 13 14:57:46 Yakhchali-SBC [410624]: DBG:core:comp_scriptvar: int 20: -1 / -1 Jan 13 14:57:46 Yakhchali-SBC [410624]: DBG:core:parse_headers_aux: flags=ffffffffffffffff Jan 13 14:57:46 Yakhchali-SBC [410624]: DBG:core:comp_scriptvar: str 20: offer Jan 13 14:57:46 Yakhchali-SBC [410624]: DBG:[B2B.493.5675184.1736767665.1245583625] [rtp_logic] req_type:offer rtp_req_srtp:none rtp_resp_srtp: Jan 13 14:57:46 Yakhchali-SBC [410624]: DBG:core:comp_scriptvar: str 20: transient Jan 13 14:57:46 Yakhchali-SBC [410624]: DBG:core:comp_scriptvar: str 20: transient Jan 13 14:57:46 Yakhchali-SBC [410624]: DBG:core:comp_scriptvar: str 20: offer Jan 13 14:57:46 Yakhchali-SBC [410624]: DBG:[B2B.493.5675184.1736767665.1245583625] [rtp_logic] req_type:offer rtp_opts: in-iface=external out-iface=external replace-origin-full port-latching ICE=remove call-id=1c41cdc79d3a4b2ea7c841ef49518a00 from-tag=44432d591fe247278a2b558198fcd166 Jan 13 14:57:46 Yakhchali-SBC [410624]: DBG:core:comp_scriptvar: str 20: offer Jan 13 14:57:46 Yakhchali-SBC [410624]: DBG:rtpengine:rtpe_function_call: proxy reply: d3:sdp298:v=0#015#012o=- 3945769098 3945769098 IN IP4 172.25.17.70#015#012s=pjmedia#015#012b=AS:84#015#012t=0 0#015#012a=X-nat:0#015#012m=audio 14310 RTP/AVP 0 101#015#012c=IN IP4 172.25.17.70#015#012b=TIAS:64000#015#012a=rtpmap:0 PCMU/8000#015#012a=rtpmap:101 telephone-event/8000#015#012a=fmtp:101 0-16#015#012a=ssrc:1216100939 cname:66217ff13dc73666#015#012a=sendrecv#015#012a=rtcp:14311#015#0126:result2:oke Jan 13 14:57:46 Yakhchali-SBC [410624]: DBG:tm:run_local_route: Change in local route -> rebuilding buffer Jan 13 14:57:46 Yakhchali-SBC [410624]: DBG:core:prep_reassemble_body_parts: only one part to be added Jan 13 14:57:46 Yakhchali-SBC [410624]: DBG:core:prep_reassemble_body_parts: handing part with flags 0, mime application/sdp, dump function (nil) Jan 13 14:57:46 Yakhchali-SBC [410624]: DBG:core:prep_reassemble_body_parts: lumps found in the part, applying... Jan 13 14:57:46 Yakhchali-SBC [410624]: DBG:core:prep_reassemble_body_parts: resulting body len is 298 Jan 13 14:57:46 Yakhchali-SBC [410624]: DBG:core:parse_headers_aux: flags=2000 Jan 13 14:57:46 Yakhchali-SBC [410624]: DBG:core:parse_headers_aux: flags=ffffffffffffffff Jan 13 14:57:46 Yakhchali-SBC [410624]: DBG:core:clen_builder: content-length: 298 (298) Jan 13 14:57:46 Yakhchali-SBC [410624]: DBG:core:parse_headers_aux: flags=ffffffffffffffff Jan 13 14:57:46 Yakhchali-SBC [410624]: DBG:core:reassemble_body_parts: only one part to be added Jan 13 14:57:46 Yakhchali-SBC [410624]: DBG:core:reassemble_body_parts: handing part with flags 0, mime application/sdp, dump function (nil) Jan 13 14:57:46 Yakhchali-SBC [410624]: DBG:core:reassemble_body_parts: lumps found in the part, applying... Jan 13 14:57:46 Yakhchali-SBC [410624]: DBG:core:extract_ftc_hdrs: flags = 15 Jan 13 14:57:46 Yakhchali-SBC [410624]: DBG:core:extract_ftc_hdrs: hdr 2 extracted as #015#012> Jan 13 14:57:46 Yakhchali-SBC [410624]: DBG:core:extract_ftc_hdrs: hdr 1 extracted as ;tag=5d9d0a4cf3fa4717380f13d8f920816f-a699#015#012> Jan 13 14:57:46 Yakhchali-SBC [410624]: DBG:core:extract_ftc_hdrs: hdr 8 extracted as Jan 13 14:57:46 Yakhchali-SBC [410624]: DBG:tm:t_uac: REF_UNSAFE:[0x7f3fdfd28150] after is 1 Jan 13 14:57:46 Yakhchali-SBC [410624]: DBG:tm:set_timer: relative timeout is 500000 Jan 13 14:57:46 Yakhchali-SBC [410624]: DBG:tm:insert_timer_unsafe: [4]: 0x7f3fdfd28370 (714200000) Jan 13 14:57:46 Yakhchali-SBC [410624]: DBG:tm:insert_timer_unsafe: [0]: 0x7f3fdfd283a0 (718) Jan 13 14:57:46 Yakhchali-SBC [410624]: DBG:core:free_sdp_content: sdp = 0x7f4020ca1f30 Jan 13 14:57:46 Yakhchali-SBC [410624]: DBG:core:free_sdp_content: sdp = 0x7f4020ca1f30 Jan 13 14:57:46 Yakhchali-SBC [410624]: DBG:core:free_sdp_content: session = 0x7f4020ca1f78 Jan 13 14:57:46 Yakhchali-SBC [410624]: DBG:b2b_entities:_client_new: new client entity [0x7f3fdfd2ae68] callid=[B2B.493.5675184.1736767665.1245583625] tag=[5d9d0a4cf3fa4717380f13d8f920816f-a699] param=[250.0] last method=[1] dlg->uac_tran=[0x7f3fdfd28150] Jan 13 14:57:46 Yakhchali-SBC [410624]: DBG:b2b_logic:b2bl_create_new_entity: new entity type [1] [0x7f3fdfd2b120]->[B2B.493.5675184.1736767665.1245583625] Jan 13 14:57:46 Yakhchali-SBC [410624]: INFO:b2b_logic:b2bl_add_client: adding entity [0x7f3fdfd2b120]->[B2B.493.5675184.1736767665.1245583625] to tuple [0x7f3fdfd2c730]->[250.0] Jan 13 14:57:46 Yakhchali-SBC [410624]: DBG:[0x7f3fdfd2c730]->[250.0] to_del=[0] lifetime=[773] bridge_entities[0x7f3fdfd02810][(nil)][(nil)] Jan 13 14:57:46 Yakhchali-SBC [410624]: DBG:.type=[0] index=[0] [0x7f3fdfd02810]->[B2B.412.51.1736767665.742304390] state=0 no=0 dlginfo=[0x7f3fdfd1c6c0] peer=[(nil)] prev:next=[(nil)][(nil)] Jan 13 14:57:46 Yakhchali-SBC [410624]: DBG:..........dlginfo=[0x7f3fdfd1c6c0]->[1c41cdc79d3a4b2ea7c841ef49518a00][44432d591fe247278a2b558198fcd166][B2B.412.51.1736767665.742304390] Jan 13 14:57:46 Yakhchali-SBC [410624]: DBG:.type=[1] index=[0] [0x7f3fdfd2b120]->[B2B.493.5675184.1736767665.1245583625] state=0 no=0 dlginfo=[(nil)] peer=[(nil)] prev:next=[(nil)][(nil)] Jan 13 14:57:46 Yakhchali-SBC [410624]: DBG:.type=[0] index=[0] [0x7f3fdfd02810] peer=[(nil)] prev:next=[(nil)][(nil)] Jan 13 14:57:46 Yakhchali-SBC [410624]: DBG:tm:update_cloned_msg_from_msg: dst_uri must be copied old=0, new=21 Jan 13 14:57:46 Yakhchali-SBC [410624]: DBG:tm:t_unref: UNREF_UNSAFE: [0x7f3fdfd1a998] after is 1 Jan 13 14:57:46 Yakhchali-SBC [410624]: DBG:core:destroy_avp_list: destroying list (nil) Jan 13 14:57:46 Yakhchali-SBC [410624]: DBG:core:receive_msg: cleaning up Jan 13 14:57:46 Yakhchali-SBC [410624]: DBG:core:free_sdp_content: sdp = 0x7f4020c9b6d0 Jan 13 14:57:46 Yakhchali-SBC [410624]: DBG:core:free_sdp_content: sdp = 0x7f4020c9b6d0 Jan 13 14:57:46 Yakhchali-SBC [410624]: DBG:core:free_sdp_content: session = 0x7f4020ca0640 Jan 13 14:57:46 Yakhchali-SBC [410624]: DBG:proto_tls:tls_read_req: tls_read_req end Jan 13 14:57:46 Yakhchali-SBC [410614]: DBG:core:parse_msg: SIP Reply (status): Jan 13 14:57:46 Yakhchali-SBC [410614]: DBG:core:parse_msg: version: Jan 13 14:57:46 Yakhchali-SBC [410614]: DBG:core:parse_msg: status: <100> Jan 13 14:57:46 Yakhchali-SBC [410614]: DBG:core:parse_msg: reason: Jan 13 14:57:46 Yakhchali-SBC [410614]: DBG:core:parse_headers_aux: flags=ffffffffffffffff Jan 13 14:57:46 Yakhchali-SBC [410614]: DBG:core:parse_via_param: found param type 234, = <172.25.17.70>; state=6 Jan 13 14:57:46 Yakhchali-SBC [410614]: DBG:core:parse_via_param: found param type 232, = ; state=16 Jan 13 14:57:46 Yakhchali-SBC [410614]: DBG:core:parse_via: end of header reached, state=5 Jan 13 14:57:46 Yakhchali-SBC [410614]: DBG:core:parse_headers_aux: via found, flags=ffffffffffffffff Jan 13 14:57:46 Yakhchali-SBC [410614]: DBG:core:parse_headers_aux: this is the first via Jan 13 14:57:46 Yakhchali-SBC [410614]: DBG:core:_parse_to: end of header reached, state=10 Jan 13 14:57:46 Yakhchali-SBC [410614]: DBG:core:_parse_to: display={}, ruri={sip:98212010@172.25.5.253;ob} Jan 13 14:57:46 Yakhchali-SBC [410614]: DBG:core:get_hdr_field_aux: [32]; uri=[sip:98212010@172.25.5.253;ob] Jan 13 14:57:46 Yakhchali-SBC [410614]: DBG:core:get_hdr_field_aux: to body [#015#012] Jan 13 14:57:46 Yakhchali-SBC [410614]: DBG:core:get_hdr_field_aux: cseq : <6324> Jan 13 14:57:46 Yakhchali-SBC [410614]: DBG:core:get_hdr_field_aux: content_length=0 Jan 13 14:57:46 Yakhchali-SBC [410614]: DBG:core:get_hdr_field_aux: found end of header Jan 13 14:57:46 Yakhchali-SBC [410614]: DBG:core:receive_msg: After parse_msg... Jan 13 14:57:46 Yakhchali-SBC [410614]: DBG:core:forward_reply: found module tm, passing reply to it Jan 13 14:57:46 Yakhchali-SBC [410614]: DBG:tm:t_check: start=0xffffffffffffffff Jan 13 14:57:46 Yakhchali-SBC [410614]: DBG:core:parse_headers_aux: flags=22 Jan 13 14:57:46 Yakhchali-SBC [410614]: DBG:core:parse_headers_aux: flags=8 Jan 13 14:57:46 Yakhchali-SBC [410614]: DBG:tm:t_reply_matching: hash 60976 label 1449028844 branch 0 Jan 13 14:57:46 Yakhchali-SBC [410614]: DBG:tm:t_reply_matching: REF_UNSAFE:[0x7f3fdfd28150] after is 2 Jan 13 14:57:46 Yakhchali-SBC [410614]: DBG:tm:t_reply_matching: reply matched (T=0x7f3fdfd28150)! Jan 13 14:57:46 Yakhchali-SBC [410614]: DBG:tm:t_check: end=0x7f3fdfd28150 Jan 13 14:57:46 Yakhchali-SBC [410614]: DBG:tm:reply_received: org. status uas=0, uac[0]=0 local=2 is_invite=1) Jan 13 14:57:46 Yakhchali-SBC [410614]: DBG:tm:t_should_relay_response: T_code=0, new_code=100 Jan 13 14:57:46 Yakhchali-SBC [410614]: DBG:tm:local_reply: branch=0, save=0, winner=-1 Jan 13 14:57:46 Yakhchali-SBC [410614]: DBG:tm:reply_received: FR_INV_TIMER = 59 Jan 13 14:57:46 Yakhchali-SBC [410614]: DBG:tm:set_timer: relative timeout is 59 Jan 13 14:57:46 Yakhchali-SBC [410614]: DBG:tm:insert_timer_unsafe: [1]: 0x7f3fdfd283a0 (772) Jan 13 14:57:46 Yakhchali-SBC [410614]: DBG:tm:t_unref: UNREF_UNSAFE: [0x7f3fdfd28150] after is 1 Jan 13 14:57:46 Yakhchali-SBC [410614]: DBG:core:destroy_avp_list: destroying list (nil) Jan 13 14:57:46 Yakhchali-SBC [410614]: DBG:core:receive_msg: cleaning up Jan 13 14:57:46 Yakhchali-SBC [410614]: DBG:core:parse_msg: SIP Reply (status): Jan 13 14:57:46 Yakhchali-SBC [410614]: DBG:core:parse_msg: version: Jan 13 14:57:46 Yakhchali-SBC [410614]: DBG:core:parse_msg: status: <180> Jan 13 14:57:46 Yakhchali-SBC [410614]: DBG:core:parse_msg: reason: Jan 13 14:57:46 Yakhchali-SBC [410614]: DBG:core:parse_headers_aux: flags=ffffffffffffffff Jan 13 14:57:46 Yakhchali-SBC [410614]: DBG:core:parse_via_param: found param type 234, = <172.25.17.70>; state=6 Jan 13 14:57:46 Yakhchali-SBC [410614]: DBG:core:parse_via_param: found param type 232, = ; state=16 Jan 13 14:57:46 Yakhchali-SBC [410614]: DBG:core:parse_via: end of header reached, state=5 Jan 13 14:57:46 Yakhchali-SBC [410614]: DBG:core:parse_headers_aux: via found, flags=ffffffffffffffff Jan 13 14:57:46 Yakhchali-SBC [410614]: DBG:core:parse_headers_aux: this is the first via Jan 13 14:57:46 Yakhchali-SBC [410614]: DBG:core:parse_to_param: tag=c23830c9308940e0b4ea520bc8705e10 Jan 13 14:57:46 Yakhchali-SBC [410614]: DBG:core:parse_to_param: end of header reached, state=13 Jan 13 14:57:46 Yakhchali-SBC [410614]: DBG:core:_parse_to: end of header reached, state=29 Jan 13 14:57:46 Yakhchali-SBC [410614]: DBG:core:_parse_to: display={}, ruri={sip:98212010@172.25.5.253;ob} Jan 13 14:57:46 Yakhchali-SBC [410614]: DBG:core:get_hdr_field_aux: [69]; uri=[sip:98212010@172.25.5.253;ob] Jan 13 14:57:46 Yakhchali-SBC [410614]: DBG:core:get_hdr_field_aux: to body [] Jan 13 14:57:46 Yakhchali-SBC [410614]: DBG:core:get_hdr_field_aux: cseq : <6324> Jan 13 14:57:46 Yakhchali-SBC [410614]: DBG:core:get_hdr_field_aux: content_length=0 Jan 13 14:57:46 Yakhchali-SBC [410614]: DBG:core:get_hdr_field_aux: found end of header Jan 13 14:57:46 Yakhchali-SBC [410614]: DBG:core:receive_msg: After parse_msg... Jan 13 14:57:46 Yakhchali-SBC [410614]: DBG:core:forward_reply: found module tm, passing reply to it Jan 13 14:57:46 Yakhchali-SBC [410614]: DBG:tm:t_check: start=0xffffffffffffffff Jan 13 14:57:46 Yakhchali-SBC [410614]: DBG:core:parse_headers_aux: flags=22 Jan 13 14:57:46 Yakhchali-SBC [410614]: DBG:core:parse_headers_aux: flags=8 Jan 13 14:57:46 Yakhchali-SBC [410614]: DBG:tm:t_reply_matching: hash 60976 label 1449028844 branch 0 Jan 13 14:57:46 Yakhchali-SBC [410614]: DBG:tm:t_reply_matching: REF_UNSAFE:[0x7f3fdfd28150] after is 2 Jan 13 14:57:46 Yakhchali-SBC [410614]: DBG:tm:t_reply_matching: reply matched (T=0x7f3fdfd28150)! Jan 13 14:57:46 Yakhchali-SBC [410614]: DBG:tm:t_check: end=0x7f3fdfd28150 Jan 13 14:57:46 Yakhchali-SBC [410614]: DBG:tm:reply_received: org. status uas=0, uac[0]=100 local=2 is_invite=1) Jan 13 14:57:46 Yakhchali-SBC [410614]: DBG:tm:t_should_relay_response: T_code=0, new_code=180 Jan 13 14:57:46 Yakhchali-SBC [410614]: DBG:tm:local_reply: branch=0, save=0, winner=0 Jan 13 14:57:46 Yakhchali-SBC [410614]: DBG:tm:local_reply: Passing provisional reply 180 to FIFO application Jan 13 14:57:46 Yakhchali-SBC [410614]: DBG:tm:run_any_trans_callbacks: trans=0x7f3fdfd28150, callback type 512, id 0 entered Jan 13 14:57:46 Yakhchali-SBC [410614]: DBG:b2b_entities:b2b_tm_cback: tm [0x7f3fdfd28150] notification cb for [180] reply Jan 13 14:57:46 Yakhchali-SBC [410614]: DBG:b2b_entities:b2b_parse_key: hash_index = [493] - local_index= [5675184] Jan 13 14:57:46 Yakhchali-SBC [410614]: DBG:core:parse_headers_aux: flags=ffffffffffffffff Jan 13 14:57:46 Yakhchali-SBC [410614]: DBG:core:parse_to_param: tag=5d9d0a4cf3fa4717380f13d8f920816f-a699 Jan 13 14:57:46 Yakhchali-SBC [410614]: DBG:core:parse_to_param: end of header reached, state=11 Jan 13 14:57:46 Yakhchali-SBC [410614]: DBG:core:_parse_to: end of header reached, state=29 Jan 13 14:57:46 Yakhchali-SBC [410614]: DBG:core:_parse_to: display={}, ruri={sip:98212009@172.25.17.70} Jan 13 14:57:46 Yakhchali-SBC [410614]: DBG:b2b_entities:b2b_search_htable_next_dlg: entering with start=(nil), table=0x7f3fdfc708d0, hash=493, label=5675184 Jan 13 14:57:46 Yakhchali-SBC [410614]: DBG:b2b_entities:b2b_search_htable_next_dlg: searching callid 37[B2B.493.5675184.1736767665.1245583625] Jan 13 14:57:46 Yakhchali-SBC [410614]: DBG:b2b_entities:b2b_search_htable_next_dlg: searching totag 37[5d9d0a4cf3fa4717380f13d8f920816f-a699] Jan 13 14:57:46 Yakhchali-SBC [410614]: DBG:b2b_entities:b2b_search_htable_next_dlg: searching fromtag 32[c23830c9308940e0b4ea520bc8705e10] Jan 13 14:57:46 Yakhchali-SBC [410614]: DBG:b2b_entities:b2b_search_htable_next_dlg: Match for client dlg [0x7f3fdfd2ae68] last_method=1 dlg->uac_tran=[0x7f3fdfd28150] Jan 13 14:57:46 Yakhchali-SBC [410614]: DBG:b2b_entities:b2b_tm_cback: Received reply [180] for dialog [0x7f3fdfd2ae68], method [INVITE] Jan 13 14:57:46 Yakhchali-SBC [410614]: DBG:core:parse_headers_aux: flags=ffffffffffffffff Jan 13 14:57:46 Yakhchali-SBC [410614]: DBG:b2b_entities:b2b_new_dlg: Not an initial request Jan 13 14:57:46 Yakhchali-SBC [410614]: DBG:b2b_entities:b2b_tm_cback: Created new dialog structure 0x7f3fdfd0ad18 Jan 13 14:57:46 Yakhchali-SBC [410614]: NOTICE:[B2B.493.5675184.1736767665.1245583625] --------------------------------------------------------------------------- Jan 13 14:57:46 Yakhchali-SBC [410614]: DBG:b2b_logic:b2bl_parse_key: hash_index = [250] - local_index= [0] Jan 13 14:57:46 Yakhchali-SBC [410614]: DBG:core:parse_headers_aux: flags=40 Jan 13 14:57:46 Yakhchali-SBC [410614]: DBG:b2b_logic:pv_get_entity: Unable to identify current entity in tuple: [250.0] Jan 13 14:57:46 Yakhchali-SBC [410614]: DBG:[B2B.493.5675184.1736767665.1245583625] [b2b_reply_en] fu:sip:98212009@172.25.17.70 tu:sip:98212010@172.25.5.253;ob ci:B2B.493.5675184.1736767665.1245583625 rm:INVITE rs:180 rr:Ringing avp(invite_direction):from_ss si:172.25.5.253 b2b_id: Jan 13 14:57:46 Yakhchali-SBC [410614]: DBG:core:comp_scriptvar: str 20: INVITE Jan 13 14:57:46 Yakhchali-SBC [410614]: DBG:core:comp_scriptvar: int 27: 180 / 400 Jan 13 14:57:46 Yakhchali-SBC [410614]: DBG:core:comp_scriptvar: str 20: INVITE Jan 13 14:57:46 Yakhchali-SBC [410614]: DBG:core:comp_scriptvar: str 20: INVITE Jan 13 14:57:46 Yakhchali-SBC [410614]: DBG:core:parse_headers_aux: flags=ffffffffffffffff Jan 13 14:57:46 Yakhchali-SBC [410614]: DBG:sipmsgops:has_body_f: no body found Jan 13 14:57:46 Yakhchali-SBC [410614]: DBG:core:parse_headers_aux: flags=ffffffffffffffff Jan 13 14:57:46 Yakhchali-SBC [410614]: DBG:core:parse_sdp: message body has length zero Jan 13 14:57:46 Yakhchali-SBC [410614]: DBG:core:comp_scriptvar: str 29: answer Jan 13 14:57:46 Yakhchali-SBC [410614]: DBG:core:parse_headers_aux: flags=ffffffffffffffff Jan 13 14:57:46 Yakhchali-SBC [410614]: DBG:sipmsgops:has_body_f: no body found Jan 13 14:57:46 Yakhchali-SBC [410614]: DBG:[B2B.493.5675184.1736767665.1245583625] [rtp_logic] req_type:answer no sdp present Jan 13 14:57:46 Yakhchali-SBC [410614]: DBG:b2b_logic:b2bl_parse_key: hash_index = [250] - local_index= [0] Jan 13 14:57:46 Yakhchali-SBC [410614]: DBG:core:parse_headers_aux: flags=ffffffffffffffff Jan 13 14:57:46 Yakhchali-SBC [410614]: DBG:core:parse_headers_aux: flags=ffffffffffffffff Jan 13 14:57:46 Yakhchali-SBC [410614]: DBG:b2b_logic:b2b_logic_notify: b2b_entities notification cb for [250.0] with entity [B2B.493.5675184.1736767665.1245583625] Jan 13 14:57:46 Yakhchali-SBC [410614]: DBG:core:parse_headers_aux: flags=ffffffffffffffff Jan 13 14:57:46 Yakhchali-SBC [410614]: DBG:b2b_logic:b2bl_search_entity: Key [B2B.493.5675184.1736767665.1245583625] Jan 13 14:57:46 Yakhchali-SBC [410614]: DBG:b2b_logic:b2b_logic_notify_reply: b2b_entity key = B2B.493.5675184.1736767665.1245583625 Jan 13 14:57:46 Yakhchali-SBC [410614]: NOTICE:[B2B.493.5675184.1736767665.1245583625] --------------------------------------------------------------------------- Jan 13 14:57:46 Yakhchali-SBC [410614]: DBG:[B2B.493.5675184.1736767665.1245583625] [b2b_reply] fu:sip:98212009@172.25.17.70 tu:sip:98212010@172.25.5.253;ob ci:B2B.493.5675184.1736767665.1245583625 rm:INVITE rs:180 rr:Ringing avp(invite_direction):from_ss si:172.25.5.253 callee Jan 13 14:57:46 Yakhchali-SBC [410614]: DBG:core:comp_scriptvar: int 27: 180 / 200 Jan 13 14:57:46 Yakhchali-SBC [410614]: DBG:core:comp_scriptvar: int 27: 180 / 400 Jan 13 14:57:46 Yakhchali-SBC [410614]: DBG:core:comp_scriptvar: int 27: 180 / 500 Jan 13 14:57:46 Yakhchali-SBC [410614]: DBG:core:comp_scriptvar: int 27: 180 / 600 Jan 13 14:57:46 Yakhchali-SBC [410614]: DBG:core:comp_scriptvar: int 27: 180 / 400 Jan 13 14:57:46 Yakhchali-SBC [410614]: DBG:core:comp_scriptvar: str 20: callee Jan 13 14:57:46 Yakhchali-SBC [410614]: DBG:b2b_logic:b2bl_search_entity: Key [B2B.493.5675184.1736767665.1245583625] Jan 13 14:57:46 Yakhchali-SBC [410614]: DBG:b2b_logic:_b2b_handle_reply: b2b_entity key = B2B.493.5675184.1736767665.1245583625 Jan 13 14:57:46 Yakhchali-SBC [410614]: DBG:b2b_entities:_b2b_send_reply: For server entity Jan 13 14:57:46 Yakhchali-SBC [410614]: DBG:b2b_entities:b2b_parse_key: hash_index = [412] - local_index= [51] Jan 13 14:57:46 Yakhchali-SBC [410614]: DBG:b2b_entities:b2b_search_htable_next_dlg: entering with start=(nil), table=0x7f3fdfc6d898, hash=412, label=51 Jan 13 14:57:46 Yakhchali-SBC [410614]: DBG:b2b_entities:b2b_search_htable_next_dlg: searching callid 32[1c41cdc79d3a4b2ea7c841ef49518a00] Jan 13 14:57:46 Yakhchali-SBC [410614]: DBG:b2b_entities:b2b_search_htable_next_dlg: searching totag 31[B2B.412.51.1736767665.742304390] Jan 13 14:57:46 Yakhchali-SBC [410614]: DBG:b2b_entities:b2b_search_htable_next_dlg: searching fromtag 32[44432d591fe247278a2b558198fcd166] Jan 13 14:57:46 Yakhchali-SBC [410614]: DBG:b2b_entities:b2b_search_htable_next_dlg: Match for server dlg [0x7f3fdfd37338] dlg->uas_tran=[0x7f3fdfd1a998] Jan 13 14:57:46 Yakhchali-SBC [410614]: DBG:b2b_entities:_b2b_send_reply: Send reply 180 INVITE, for dlg [0x7f3fdfd37338]->[B2B.412.51.1736767665.742304390] Jan 13 14:57:46 Yakhchali-SBC [410614]: DBG:core:parse_headers_aux: flags=ffffffffffffffff Jan 13 14:57:46 Yakhchali-SBC [410614]: DBG:core:parse_headers_aux: flags=ffffffffffffffff Jan 13 14:57:46 Yakhchali-SBC [410614]: DBG:core:tcp_conn_get: con found in state 0 Jan 13 14:57:46 Yakhchali-SBC [410614]: DBG:core:tcp_conn_get: tcp connection found (0x7f3fdfd15df8), acquiring fd Jan 13 14:57:46 Yakhchali-SBC [410614]: DBG:core:tcp_conn_get: c= 0x7f3fdfd15df8, n=16, Usock=127 Jan 13 14:57:46 Yakhchali-SBC [410641]: DBG:core:handle_worker: read response= 7f3fdfd15df8, 1, fd -1 from 6 (410614) Jan 13 14:57:46 Yakhchali-SBC [410614]: DBG:core:tcp_conn_get: after receive_fd: c= 0x7f3fdfd15df8 n=8 fd=5 Jan 13 14:57:46 Yakhchali-SBC [410614]: DBG:proto_tls:proto_tls_send: sending via fd 5... Jan 13 14:57:46 Yakhchali-SBC [410614]: DBG:tls_openssl:openssl_tls_update_fd: New fd is 5 Jan 13 14:57:46 Yakhchali-SBC [410614]: DBG:tls_openssl:openssl_tls_write: write was successful (512 bytes) Jan 13 14:57:46 Yakhchali-SBC [410614]: DBG:proto_tls:proto_tls_send: after write: c=0x7f3fdfd15df8 n=512 fd=5 Jan 13 14:57:46 Yakhchali-SBC [410614]: DBG:proto_tls:proto_tls_send: buf=#012SIP/2.0 180 Ringing#015#012Via: SIP/2.0/TLS 172.25.5.253:54700;received=172.25.5.253;rport=54700;branch=z9hG4bKPjc2c3b7e324214127a1036a887ab785e5;alias#015#012To: ;tag=B2B.412.51.1736767665.742304390#015#012From: ;tag=44432d591fe247278a2b558198fcd166#015#012Call-ID: 1c41cdc79d3a4b2ea7c841ef49518a00#015#012CSeq: 6323 INVITE#015#012Allow: PRACK, INVITE, ACK, BYE, CANCEL, UPDATE, INFO, SUBSCRIBE, NOTIFY, REFER, MESSAGE, OPTIONS#015#012Contact: #015#012Content-Length: 0#015#012#015#012 Jan 13 14:57:46 Yakhchali-SBC [410614]: DBG:tm:_reply_light: reply sent out. buf=0x7f4020c9cea0: SIP/2.0 1..., shmem=0x7f3fdfd2ae68: SIP/2.0 1 Jan 13 14:57:46 Yakhchali-SBC [410614]: DBG:tm:_reply_light: finished Jan 13 14:57:46 Yakhchali-SBC [410614]: DBG:b2b_entities:_b2b_send_reply: code not >= 200 Jan 13 14:57:46 Yakhchali-SBC [410614]: DBG:tm:reply_received: FR_INV_TIMER = 59 Jan 13 14:57:46 Yakhchali-SBC [410614]: DBG:tm:set_timer: relative timeout is 59 Jan 13 14:57:46 Yakhchali-SBC [410614]: DBG:tm:insert_timer_unsafe: [1]: 0x7f3fdfd283a0 (772) Jan 13 14:57:46 Yakhchali-SBC [410614]: DBG:tm:t_unref: UNREF_UNSAFE: [0x7f3fdfd28150] after is 1 Jan 13 14:57:46 Yakhchali-SBC [410614]: DBG:core:destroy_avp_list: destroying list (nil) Jan 13 14:57:46 Yakhchali-SBC [410614]: DBG:core:receive_msg: cleaning up Jan 13 14:57:47 Yakhchali-SBC [410639]: DBG:tm:utimer_routine: timer routine:4,tl=0x7f3fdfd28370 next=(nil), timeout=714200000 Jan 13 14:57:49 Yakhchali-SBC [410614]: DBG:core:parse_msg: SIP Reply (status): Jan 13 14:57:49 Yakhchali-SBC [410614]: DBG:core:parse_msg: version: Jan 13 14:57:49 Yakhchali-SBC [410614]: DBG:core:parse_msg: status: <200> Jan 13 14:57:49 Yakhchali-SBC [410614]: DBG:core:parse_msg: reason: Jan 13 14:57:49 Yakhchali-SBC [410614]: DBG:core:parse_headers_aux: flags=ffffffffffffffff Jan 13 14:57:49 Yakhchali-SBC [410614]: DBG:core:parse_via_param: found param type 234, = <172.25.17.70>; state=6 Jan 13 14:57:49 Yakhchali-SBC [410614]: DBG:core:parse_via_param: found param type 232, = ; state=16 Jan 13 14:57:49 Yakhchali-SBC [410614]: DBG:core:parse_via: end of header reached, state=5 Jan 13 14:57:49 Yakhchali-SBC [410614]: DBG:core:parse_headers_aux: via found, flags=ffffffffffffffff Jan 13 14:57:49 Yakhchali-SBC [410614]: DBG:core:parse_headers_aux: this is the first via Jan 13 14:57:49 Yakhchali-SBC [410614]: DBG:core:parse_to_param: tag=c23830c9308940e0b4ea520bc8705e10 Jan 13 14:57:49 Yakhchali-SBC [410614]: DBG:core:parse_to_param: end of header reached, state=13 Jan 13 14:57:49 Yakhchali-SBC [410614]: DBG:core:_parse_to: end of header reached, state=29 Jan 13 14:57:49 Yakhchali-SBC [410614]: DBG:core:_parse_to: display={}, ruri={sip:98212010@172.25.5.253;ob} Jan 13 14:57:49 Yakhchali-SBC [410614]: DBG:core:get_hdr_field_aux: [69]; uri=[sip:98212010@172.25.5.253;ob] Jan 13 14:57:49 Yakhchali-SBC [410614]: DBG:core:get_hdr_field_aux: to body [] Jan 13 14:57:49 Yakhchali-SBC [410614]: DBG:core:get_hdr_field_aux: cseq : <6324> Jan 13 14:57:49 Yakhchali-SBC [410614]: DBG:core:get_hdr_field_aux: content_length=316 Jan 13 14:57:49 Yakhchali-SBC [410614]: DBG:core:get_hdr_field_aux: found end of header Jan 13 14:57:49 Yakhchali-SBC [410614]: DBG:core:receive_msg: After parse_msg... Jan 13 14:57:49 Yakhchali-SBC [410614]: DBG:core:forward_reply: found module tm, passing reply to it Jan 13 14:57:49 Yakhchali-SBC [410614]: DBG:tm:t_check: start=0xffffffffffffffff Jan 13 14:57:49 Yakhchali-SBC [410614]: DBG:core:parse_headers_aux: flags=22 Jan 13 14:57:49 Yakhchali-SBC [410614]: DBG:core:parse_headers_aux: flags=8 Jan 13 14:57:49 Yakhchali-SBC [410614]: DBG:tm:t_reply_matching: hash 60976 label 1449028844 branch 0 Jan 13 14:57:49 Yakhchali-SBC [410614]: DBG:tm:t_reply_matching: REF_UNSAFE:[0x7f3fdfd28150] after is 2 Jan 13 14:57:49 Yakhchali-SBC [410614]: DBG:tm:t_reply_matching: reply matched (T=0x7f3fdfd28150)! Jan 13 14:57:49 Yakhchali-SBC [410614]: DBG:core:parse_headers_aux: flags=8 Jan 13 14:57:49 Yakhchali-SBC [410614]: DBG:tm:t_check: end=0x7f3fdfd28150 Jan 13 14:57:49 Yakhchali-SBC [410614]: DBG:tm:reply_received: org. status uas=180, uac[0]=180 local=2 is_invite=1) Jan 13 14:57:49 Yakhchali-SBC [410614]: DBG:tm:t_should_relay_response: T_code=180, new_code=200 Jan 13 14:57:49 Yakhchali-SBC [410614]: DBG:tm:local_reply: branch=0, save=0, winner=0 Jan 13 14:57:49 Yakhchali-SBC [410614]: DBG:tm:local_reply: local transaction completed Jan 13 14:57:49 Yakhchali-SBC [410614]: DBG:tm:run_any_trans_callbacks: trans=0x7f3fdfd28150, callback type 256, id 0 entered Jan 13 14:57:49 Yakhchali-SBC [410614]: DBG:b2b_entities:b2b_tm_cback: tm [0x7f3fdfd28150] notification cb for [200] reply Jan 13 14:57:49 Yakhchali-SBC [410614]: DBG:b2b_entities:b2b_parse_key: hash_index = [493] - local_index= [5675184] Jan 13 14:57:49 Yakhchali-SBC [410614]: DBG:core:parse_headers_aux: flags=ffffffffffffffff Jan 13 14:57:49 Yakhchali-SBC [410614]: DBG:core:parse_to_param: tag=5d9d0a4cf3fa4717380f13d8f920816f-a699 Jan 13 14:57:49 Yakhchali-SBC [410614]: DBG:core:parse_to_param: end of header reached, state=11 Jan 13 14:57:49 Yakhchali-SBC [410614]: DBG:core:_parse_to: end of header reached, state=29 Jan 13 14:57:49 Yakhchali-SBC [410614]: DBG:core:_parse_to: display={}, ruri={sip:98212009@172.25.17.70} Jan 13 14:57:49 Yakhchali-SBC [410614]: DBG:b2b_entities:b2b_search_htable_next_dlg: entering with start=(nil), table=0x7f3fdfc708d0, hash=493, label=5675184 Jan 13 14:57:49 Yakhchali-SBC [410614]: DBG:b2b_entities:b2b_search_htable_next_dlg: searching callid 37[B2B.493.5675184.1736767665.1245583625] Jan 13 14:57:49 Yakhchali-SBC [410614]: DBG:b2b_entities:b2b_search_htable_next_dlg: searching totag 37[5d9d0a4cf3fa4717380f13d8f920816f-a699] Jan 13 14:57:49 Yakhchali-SBC [410614]: DBG:b2b_entities:b2b_search_htable_next_dlg: searching fromtag 32[c23830c9308940e0b4ea520bc8705e10] Jan 13 14:57:49 Yakhchali-SBC [410614]: DBG:b2b_entities:b2b_tm_cback: Received reply [200] for dialog [0x7f3fdfd0ad18], method [INVITE] Jan 13 14:57:49 Yakhchali-SBC [410614]: DBG:tm:t_unref_cell: UNREF_UNSAFE: [0x7f3fdfd28150] after is 1 Jan 13 14:57:49 Yakhchali-SBC [410614]: DBG:b2b_entities:b2b_tm_cback: dlg=[0x7f3fdfd0ad18], uac_tran=NULL Jan 13 14:57:49 Yakhchali-SBC [410614]: DBG:b2b_entities:b2b_tm_cback: A final response Jan 13 14:57:49 Yakhchali-SBC [410614]: DBG:b2b_logic:b2bl_parse_key: hash_index = [250] - local_index= [0] Jan 13 14:57:49 Yakhchali-SBC [410614]: DBG:b2b_logic:b2bl_search_entity: Key [B2B.493.5675184.1736767665.1245583625] Jan 13 14:57:49 Yakhchali-SBC [410614]: INFO:b2b_logic:b2b_add_dlginfo: Dialog pair: [1c41cdc79d3a4b2ea7c841ef49518a00] - [B2B.493.5675184.1736767665.1245583625] Jan 13 14:57:49 Yakhchali-SBC [410614]: NOTICE:[B2B.493.5675184.1736767665.1245583625] --------------------------------------------------------------------------- Jan 13 14:57:49 Yakhchali-SBC [410614]: DBG:b2b_logic:b2bl_parse_key: hash_index = [250] - local_index= [0] Jan 13 14:57:49 Yakhchali-SBC [410614]: DBG:core:parse_headers_aux: flags=40 Jan 13 14:57:49 Yakhchali-SBC [410614]: DBG:[B2B.493.5675184.1736767665.1245583625] [b2b_reply_en] fu:sip:98212009@172.25.17.70 tu:sip:98212010@172.25.5.253;ob ci:B2B.493.5675184.1736767665.1245583625 rm:INVITE rs:200 rr:OK avp(invite_direction):from_ss si:172.25.5.253 b2b_id:callee Jan 13 14:57:49 Yakhchali-SBC [410614]: DBG:core:comp_scriptvar: str 20: INVITE Jan 13 14:57:49 Yakhchali-SBC [410614]: DBG:core:comp_scriptvar: int 27: 200 / 400 Jan 13 14:57:49 Yakhchali-SBC [410614]: DBG:core:comp_scriptvar: str 20: INVITE Jan 13 14:57:49 Yakhchali-SBC [410614]: DBG:core:comp_scriptvar: str 20: INVITE Jan 13 14:57:49 Yakhchali-SBC [410614]: DBG:core:parse_headers_aux: flags=ffffffffffffffff Jan 13 14:57:49 Yakhchali-SBC [410614]: DBG:core:decode_mime_type: Decoding MIME type for:[application/sdp] Jan 13 14:57:49 Yakhchali-SBC [410614]: DBG:b2b_logic:fetch_ctx_value: looking for context value [route_data] Jan 13 14:57:49 Yakhchali-SBC [410614]: DBG:[B2B.493.5675184.1736767665.1245583625] [save_session_data] already saved session data! Jan 13 14:57:49 Yakhchali-SBC [410614]: DBG:core:comp_scriptvar: str 29: update Jan 13 14:57:49 Yakhchali-SBC [410614]: DBG:core:comp_scriptvar: str 20: update Jan 13 14:57:49 Yakhchali-SBC [410614]: DBG:b2b_logic:fetch_ctx_value: looking for context value [route_data] Jan 13 14:57:49 Yakhchali-SBC [410614]: DBG:core:comp_scriptvar: str 20: update Jan 13 14:57:49 Yakhchali-SBC [410614]: DBG:core:comp_scriptvar: str 20: b2b Jan 13 14:57:49 Yakhchali-SBC [410614]: DBG:b2b_logic:fetch_ctx_value: looking for context value [route_data] Jan 13 14:57:49 Yakhchali-SBC [410614]: DBG:b2b_logic:fetch_ctx_value: looking for context value [route_data] Jan 13 14:57:49 Yakhchali-SBC [410614]: DBG:b2b_logic:fetch_ctx_value: looking for context value [route_data] Jan 13 14:57:49 Yakhchali-SBC [410614]: DBG:[B2B.493.5675184.1736767665.1245583625] [load_session_data] using b2bctx:{ "ifacesalida": "", "Outgoingfromvalue": "", "net": "0.0.0.0\/0.0.0.0", "idrtpin": "external", "routebymatchingrule_from": "none", "routebymatchingrule_to": "none", "ratelimit": "0", "isWhitelist": "0", "handleRtp": "1", "nextHop": "0", "srtp_mode": "transient", "allowedNet": "0.0.0.0\/0.0.0.0", "nextHopTransport": "", "idrtpout": "external", "codecs": "pcmu,pcma,gsm,speex,opus,g718,g719,g721,g723,g726,g728,g729,ilbc", "rtpparam": null, "setid": "2", "b2b": "1", "metrica": "1", "prefix_remove_add": "[]", "route_id": 57, "dispatcher_algo": "", "sip_hdr_to_add": "", "sip_hdr_prefix_to_remove": "", "normal_compact_sip_hdr": "no", "check_sip_from_hdr": "no", "h323_gw_id": "0", "allowed_methods": "NOTIFY|OPTIONS|INFO|SUBSCRIBE|PUBLISH", "outbound_proxy": null, "nat_handling": "disable", "fraud_pro_id": "", "fraud_action": "", "fraud_excluded_username": "", "add_chk_hdrs": "false", "match_type_from": "match", "match_type_to": "match", "call_sourceip": "172.25.5.253", "is_dst_ws": -1, "is_src_ws": -1, "socket_out": "udp:172.25.17.70:5060", "rtp_cid": "1c41cdc79d3a4b2ea7c841ef49518a00", "rtp_from_tag": "44432d591fe247278a2b558198fcd166" } Jan 13 14:57:49 Yakhchali-SBC [410614]: DBG:core:destroy_index_avp: AVP with the specified index not found Jan 13 14:57:49 Yakhchali-SBC [410614]: DBG:core:destroy_index_avp: AVP with the specified index not found Jan 13 14:57:49 Yakhchali-SBC [410614]: DBG:core:destroy_index_avp: AVP with the specified index not found Jan 13 14:57:49 Yakhchali-SBC [410614]: DBG:core:comp_scriptvar: str 20: to-tag Jan 13 14:57:49 Yakhchali-SBC [410614]: DBG:[B2B.493.5675184.1736767665.1245583625] [save_session_data] updating to-tag:c23830c9308940e0b4ea520bc8705e10 Jan 13 14:57:49 Yakhchali-SBC [410614]: DBG:core:comp_scriptvar: str 20: b2b Jan 13 14:57:49 Yakhchali-SBC [410614]: DBG:[B2B.493.5675184.1736767665.1245583625] [save_session_data] using b2bctx Jan 13 14:57:49 Yakhchali-SBC [410614]: DBG:b2b_logic:store_ctx_value: inserting [route_data]=[{ "ifacesalida": "", "Outgoingfromvalue": "", "net": "0.0.0.0\/0.0.0.0", "idrtpin": "external", "routebymatchingrule_from": "none", "routebymatchingrule_to": "none", "ratelimit": "0", "isWhitelist": "0", "handleRtp": "1", "nextHop": "0", "srtp_mode": "transient", "allowedNet": "0.0.0.0\/0.0.0.0", "nextHopTransport": "", "idrtpout": "external", "codecs": "pcmu,pcma,gsm,speex,opus,g718,g719,g721,g723,g726,g728,g729,ilbc", "rtpparam": null, "setid": "2", "b2b": "1", "metrica": "1", "prefix_remove_add": "[]", "route_id": 57, "dispatcher_algo": "", "sip_hdr_to_add": "", "sip_hdr_prefix_to_remove": "", "normal_compact_sip_hdr": "no", "check_sip_from_hdr": "no", "h323_gw_id": "0", "allowed_methods": "NOTIFY|OPTIONS|INFO|SUBSCRIBE|PUBLISH", "outbound_proxy": null, "nat_handling": "disable", "fraud_pro_id": "", "fraud_action": "", "fraud_excluded_username": "", "add_chk_hdrs": "false", "match_type_from": "match", "match_type_to": "match", "call_sourceip": "172.25.5.253", "is_dst_ws": -1, "is_src_ws": -1, "socket_out": "udp:172.25.17.70:5060", "rtp_cid": "1c41cdc79d3a4b2ea7c841ef49518a00", "rtp_from_tag": "44432d591fe247278a2b558198fcd166", "rtp_to_tag": "c23830c9308940e0b4ea520bc8705e10" }] Jan 13 14:57:49 Yakhchali-SBC [410614]: DBG:b2b_logic:store_ctx_value: context value found-> [{ "ifacesalida": "", "Outgoingfromvalue": "", "net": "0.0.0.0\/0.0.0.0", "idrtpin": "external", "routebymatchingrule_from": "none", "routebymatchingrule_to": "none", "ratelimit": "0", "isWhitelist": "0", "handleRtp": "1", "nextHop": "0", "srtp_mode": "transient", "allowedNet": "0.0.0.0\/0.0.0.0", "nextHopTransport": "", "idrtpout": "external", "codecs": "pcmu,pcma,gsm,speex,opus,g718,g719,g721,g723,g726,g728,g729,ilbc", "rtpparam": null, "setid": "2", "b2b": "1", "metrica": "1", "prefix_remove_add": "[]", "route_id": 57, "dispatcher_algo": "", "sip_hdr_to_add": "", "sip_hdr_prefix_to_remove": "", "normal_compact_sip_hdr": "no", "check_sip_from_hdr": "no", "h323_gw_id": "0", "allowed_methods": "NOTIFY|OPTIONS|INFO|SUBSCRIBE|PUBLISH", "outbound_proxy": null, "nat_handling": "disable", "fraud_pro_id": "", "fraud_action": "", "fraud_excluded_username": "", "add_chk_hdrs": "false", "match_type_from": "match", "match_type_to": "match", "call_sourceip": "172.25.5.253", "is_dst_ws": -1, "is_src_ws": -1, "socket_out": "udp:172.25.17.70:5060", "rtp_cid": "1c41cdc79d3a4b2ea7c841ef49518a00", "rtp_from_tag": "44432d591fe247278a2b558198fcd166" }]! Jan 13 14:57:49 Yakhchali-SBC [410614]: DBG:core:parse_sdp_session: Found FMTP [0-16] for payload [101] Jan 13 14:57:49 Yakhchali-SBC [410614]: DBG:core:try_set_fmtp_payload_link: We need to link [0-16] to [101] Jan 13 14:57:49 Yakhchali-SBC [410614]: DBG:core:parse_sdp_session: extracted attr [cname:46261cdf27da0e29] for payload [1856064614] Jan 13 14:57:49 Yakhchali-SBC [410614]: DBG:core:set_sdp_payload_custom_attr: No payload_attr Jan 13 14:57:49 Yakhchali-SBC [410614]: DBG:core:comp_scriptvar: str 29: answer Jan 13 14:57:49 Yakhchali-SBC [410614]: DBG:[B2B.493.5675184.1736767665.1245583625] [load_session_data] already loaded Jan 13 14:57:49 Yakhchali-SBC [410614]: DBG:[B2B.493.5675184.1736767665.1245583625] [rtp_logic] mode:b2b req_type:answer DLG_dir: is_src_ws:-1 is_dst_ws:-1 Jan 13 14:57:49 Yakhchali-SBC [410614]: DBG:core:comp_scriptvar: str 20: answer Jan 13 14:57:49 Yakhchali-SBC [410614]: DBG:core:route_param_get: no such parameter index 2 Jan 13 14:57:49 Yakhchali-SBC [410614]: DBG:core:comp_scriptvar: str 20: b2b Jan 13 14:57:49 Yakhchali-SBC [410614]: DBG:core:parse_headers_aux: flags=40 Jan 13 14:57:49 Yakhchali-SBC [410614]: DBG:core:comp_scriptvar: str 20: callee Jan 13 14:57:49 Yakhchali-SBC [410614]: INFO:[B2B.493.5675184.1736767665.1245583625] [rtp_logic] set_id:2 req_type:answer req_dir:ba si:172.25.5.253 call_sourceip:172.25.5.253 srtp_mode:transient Jan 13 14:57:49 Yakhchali-SBC [410614]: DBG:core:comp_scriptvar: str 20: answer Jan 13 14:57:49 Yakhchali-SBC [410614]: DBG:core:parse_headers_aux: flags=ffffffffffffffff Jan 13 14:57:49 Yakhchali-SBC [410614]: DBG:core:comp_scriptvar: str 20: ba Jan 13 14:57:49 Yakhchali-SBC [410614]: DBG:core:comp_scriptvar: str 20: ba Jan 13 14:57:49 Yakhchali-SBC [410614]: DBG:core:comp_scriptvar: int 20: -1 / 1 Jan 13 14:57:49 Yakhchali-SBC [410614]: DBG:core:comp_scriptvar: int 20: -1 / 1 Jan 13 14:57:49 Yakhchali-SBC [410614]: DBG:core:comp_scriptvar: int 20: -1 / -1 Jan 13 14:57:49 Yakhchali-SBC [410614]: DBG:core:comp_scriptvar: int 20: -1 / 1 Jan 13 14:57:49 Yakhchali-SBC [410614]: DBG:core:comp_scriptvar: int 20: -1 / -1 Jan 13 14:57:49 Yakhchali-SBC [410614]: DBG:core:comp_scriptvar: int 20: -1 / -1 Jan 13 14:57:49 Yakhchali-SBC [410614]: DBG:core:parse_headers_aux: flags=ffffffffffffffff Jan 13 14:57:49 Yakhchali-SBC [410614]: DBG:core:comp_scriptvar: str 20: answer Jan 13 14:57:49 Yakhchali-SBC [410614]: DBG:[B2B.493.5675184.1736767665.1245583625] [rtp_logic] req_type:answer rtp_req_srtp:none rtp_resp_srtp:none Jan 13 14:57:49 Yakhchali-SBC [410614]: DBG:core:comp_scriptvar: str 20: transient Jan 13 14:57:49 Yakhchali-SBC [410614]: DBG:core:comp_scriptvar: str 20: transient Jan 13 14:57:49 Yakhchali-SBC [410614]: DBG:core:comp_scriptvar: str 20: answer Jan 13 14:57:49 Yakhchali-SBC [410614]: DBG:[B2B.493.5675184.1736767665.1245583625] [rtp_logic] req_type:answer rtp_opts: in-iface=external out-iface=external replace-origin-full port-latching ICE=remove call-id=1c41cdc79d3a4b2ea7c841ef49518a00 from-tag=44432d591fe247278a2b558198fcd166 Jan 13 14:57:49 Yakhchali-SBC [410614]: DBG:core:comp_scriptvar: str 20: answer Jan 13 14:57:49 Yakhchali-SBC [410614]: DBG:rtpengine:rtpe_function_call: proxy reply: d3:sdp298:v=0#015#012o=- 3945769098 3945769099 IN IP4 172.25.17.70#015#012s=pjmedia#015#012b=AS:84#015#012t=0 0#015#012a=X-nat:0#015#012m=audio 17190 RTP/AVP 0 101#015#012c=IN IP4 172.25.17.70#015#012b=TIAS:64000#015#012a=rtpmap:0 PCMU/8000#015#012a=rtpmap:101 telephone-event/8000#015#012a=fmtp:101 0-16#015#012a=ssrc:1856064614 cname:46261cdf27da0e29#015#012a=sendrecv#015#012a=rtcp:17191#015#0126:result2:oke Jan 13 14:57:49 Yakhchali-SBC [410614]: DBG:core:prep_reassemble_body_parts: only one part to be added Jan 13 14:57:49 Yakhchali-SBC [410614]: DBG:core:prep_reassemble_body_parts: handing part with flags 0, mime application/sdp, dump function (nil) Jan 13 14:57:49 Yakhchali-SBC [410614]: DBG:core:prep_reassemble_body_parts: lumps found in the part, applying... Jan 13 14:57:49 Yakhchali-SBC [410614]: DBG:core:prep_reassemble_body_parts: resulting body len is 298 Jan 13 14:57:49 Yakhchali-SBC [410614]: DBG:core:parse_headers_aux: flags=2000 Jan 13 14:57:49 Yakhchali-SBC [410614]: DBG:core:parse_headers_aux: flags=ffffffffffffffff Jan 13 14:57:49 Yakhchali-SBC [410614]: DBG:core:clen_builder: content-length: 298 (298) Jan 13 14:57:49 Yakhchali-SBC [410614]: DBG:core:parse_headers_aux: flags=ffffffffffffffff Jan 13 14:57:49 Yakhchali-SBC [410614]: DBG:core:build_res_buf_from_sip_res: old size: 938, new size: 830 Jan 13 14:57:49 Yakhchali-SBC [410614]: DBG:core:reassemble_body_parts: only one part to be added Jan 13 14:57:49 Yakhchali-SBC [410614]: DBG:core:reassemble_body_parts: handing part with flags 0, mime application/sdp, dump function (nil) Jan 13 14:57:49 Yakhchali-SBC [410614]: DBG:core:reassemble_body_parts: lumps found in the part, applying... Jan 13 14:57:49 Yakhchali-SBC [410614]: DBG:core:build_res_buf_from_sip_res: copied size: orig:938, new: 830, rest: 0 msg=|#012SIP/2.0 200 OK#015#012Call-ID: B2B.493.5675184.1736767665.1245583625#015#012From: ;tag=5d9d0a4cf3fa4717380f13d8f920816f-a699#015#012To: ;tag=c23830c9308940e0b4ea520bc8705e10#015#012CSeq: 6324 INVITE#015#012Allow: PRACK, INVITE, ACK, BYE, CANCEL, UPDATE, INFO, SUBSCRIBE, NOTIFY, REFER, MESSAGE, OPTIONS#015#012Contact: #015#012Supported: replaces, 100rel, timer, norefersub#015#012Session-Expires: 1800;refresher=uac#015#012Require: timer#015#012Content-Type: application/sdp#015#012Content-Length: 298#015#012#015#012v=0#015#012o=- 3945769098 3945769099 IN IP4 172.25.17.70#015#012s=pjmedia#015#012b=AS:84#015#012t=0 0#015#012a=X-nat:0#015#012m=audio 17190 RTP/AVP 0 101#015#012c=IN IP4 172.25.17.70#015#012b=TIAS:64000#015#012a=rtpmap:0 PCMU/8000#015#012a=rtpmap:101 telephone-event/8000#015#012a=fmtp:101 0-16#015#012a=ssrc:1856064614 cname:46261cdf27da0e29#015#012a=sendrecv#015#012a=rtcp:17191#015#012| Jan 13 14:57:49 Yakhchali-SBC [410614]: DBG:core:free_sdp_content: sdp = 0x7f4020c9aa88 Jan 13 14:57:49 Yakhchali-SBC [410614]: DBG:core:free_sdp_content: sdp = 0x7f4020c9aa88 Jan 13 14:57:49 Yakhchali-SBC [410614]: DBG:core:free_sdp_content: session = 0x7f4020c9aad0 Jan 13 14:57:49 Yakhchali-SBC [410614]: DBG:core:parse_msg: SIP Reply (status): Jan 13 14:57:49 Yakhchali-SBC [410614]: DBG:core:parse_msg: version: Jan 13 14:57:49 Yakhchali-SBC [410614]: DBG:core:parse_msg: status: <200> Jan 13 14:57:49 Yakhchali-SBC [410614]: DBG:core:parse_msg: reason: Jan 13 14:57:49 Yakhchali-SBC [410614]: DBG:core:parse_headers_aux: flags=ffffffffffffffff Jan 13 14:57:49 Yakhchali-SBC [410614]: DBG:core:parse_to_param: tag=c23830c9308940e0b4ea520bc8705e10 Jan 13 14:57:49 Yakhchali-SBC [410614]: DBG:core:parse_to_param: end of header reached, state=13 Jan 13 14:57:49 Yakhchali-SBC [410614]: DBG:core:_parse_to: end of header reached, state=29 Jan 13 14:57:49 Yakhchali-SBC [410614]: DBG:core:_parse_to: display={}, ruri={sip:98212010@172.25.5.253;ob} Jan 13 14:57:49 Yakhchali-SBC [410614]: DBG:core:get_hdr_field_aux: [69]; uri=[sip:98212010@172.25.5.253;ob] Jan 13 14:57:49 Yakhchali-SBC [410614]: DBG:core:get_hdr_field_aux: to body [] Jan 13 14:57:49 Yakhchali-SBC [410614]: DBG:core:get_hdr_field_aux: cseq : <6324> Jan 13 14:57:49 Yakhchali-SBC [410614]: DBG:core:get_hdr_field_aux: content_length=298 Jan 13 14:57:49 Yakhchali-SBC [410614]: DBG:core:get_hdr_field_aux: found end of header Jan 13 14:57:49 Yakhchali-SBC [410614]: DBG:core:parse_headers_aux: flags=ffffffffffffffff Jan 13 14:57:49 Yakhchali-SBC [410614]: DBG:core:decode_mime_type: Decoding MIME type for:[application/sdp] Jan 13 14:57:49 Yakhchali-SBC [410614]: DBG:core:parse_sdp_session: Found FMTP [0-16] for payload [101] Jan 13 14:57:49 Yakhchali-SBC [410614]: DBG:core:try_set_fmtp_payload_link: We need to link [0-16] to [101] Jan 13 14:57:49 Yakhchali-SBC [410614]: DBG:core:parse_sdp_session: extracted attr [cname:46261cdf27da0e29] for payload [1856064614] Jan 13 14:57:49 Yakhchali-SBC [410614]: DBG:core:set_sdp_payload_custom_attr: No payload_attr Jan 13 14:57:49 Yakhchali-SBC [410614]: DBG:b2b_logic:b2bl_parse_key: hash_index = [250] - local_index= [0] Jan 13 14:57:49 Yakhchali-SBC [410614]: DBG:core:parse_headers_aux: flags=ffffffffffffffff Jan 13 14:57:49 Yakhchali-SBC [410614]: DBG:core:parse_headers_aux: flags=ffffffffffffffff Jan 13 14:57:49 Yakhchali-SBC [410614]: DBG:b2b_logic:b2b_logic_notify: b2b_entities notification cb for [250.0] with entity [B2B.493.5675184.1736767665.1245583625] Jan 13 14:57:49 Yakhchali-SBC [410614]: DBG:core:parse_headers_aux: flags=ffffffffffffffff Jan 13 14:57:49 Yakhchali-SBC [410614]: DBG:b2b_logic:b2bl_search_entity: Key [B2B.493.5675184.1736767665.1245583625] Jan 13 14:57:49 Yakhchali-SBC [410614]: DBG:b2b_logic:b2b_logic_notify_reply: b2b_entity key = B2B.493.5675184.1736767665.1245583625 Jan 13 14:57:49 Yakhchali-SBC [410614]: NOTICE:[B2B.493.5675184.1736767665.1245583625] --------------------------------------------------------------------------- Jan 13 14:57:49 Yakhchali-SBC [410614]: DBG:core:parse_to_param: tag=5d9d0a4cf3fa4717380f13d8f920816f-a699 Jan 13 14:57:49 Yakhchali-SBC [410614]: DBG:core:parse_to_param: end of header reached, state=11 Jan 13 14:57:49 Yakhchali-SBC [410614]: DBG:core:_parse_to: end of header reached, state=29 Jan 13 14:57:49 Yakhchali-SBC [410614]: DBG:core:_parse_to: display={}, ruri={sip:98212009@172.25.17.70} Jan 13 14:57:49 Yakhchali-SBC [410614]: DBG:[B2B.493.5675184.1736767665.1245583625] [b2b_reply] fu:sip:98212009@172.25.17.70 tu:sip:98212010@172.25.5.253;ob ci:B2B.493.5675184.1736767665.1245583625 rm:INVITE rs:200 rr:OK avp(invite_direction):from_ss si:172.25.5.253 callee Jan 13 14:57:49 Yakhchali-SBC [410614]: DBG:core:comp_scriptvar: int 27: 200 / 200 Jan 13 14:57:49 Yakhchali-SBC [410614]: DBG:core:comp_scriptvar: int 26: 200 / 400 Jan 13 14:57:49 Yakhchali-SBC [410614]: DBG:core:route_param_get: no such parameter index 3 Jan 13 14:57:49 Yakhchali-SBC [410614]: DBG:core:route_param_get: no such parameter index 4 Jan 13 14:57:49 Yakhchali-SBC [410614]: DBG:core:route_param_get: no such parameter index 5 Jan 13 14:57:49 Yakhchali-SBC [410614]: NOTICE:[B2B.493.5675184.1736767665.1245583625] [update_stats] reply 200 route_id:57 Jan 13 14:57:49 Yakhchali-SBC [410614]: DBG:core:comp_scriptvar: str 20: reply Jan 13 14:57:49 Yakhchali-SBC [410614]: DBG:core:comp_scriptvar: str 20: reply Jan 13 14:57:49 Yakhchali-SBC [410614]: DBG:core:comp_scriptvar: str 20: reply Jan 13 14:57:49 Yakhchali-SBC [410614]: DBG:core:comp_scriptvar: int 27: 200 / 400 Jan 13 14:57:49 Yakhchali-SBC [410614]: DBG:core:comp_scriptvar: str 20: callee Jan 13 14:57:49 Yakhchali-SBC [410614]: DBG:b2b_logic:b2bl_search_entity: Key [B2B.493.5675184.1736767665.1245583625] Jan 13 14:57:49 Yakhchali-SBC [410614]: DBG:b2b_logic:_b2b_handle_reply: b2b_entity key = B2B.493.5675184.1736767665.1245583625 Jan 13 14:57:49 Yakhchali-SBC [410614]: DBG:[0x7f3fdfd2c730]->[250.0] to_del=[0] lifetime=[43916] bridge_entities[0x7f3fdfd02810][0x7f3fdfd2b120][(nil)] Jan 13 14:57:49 Yakhchali-SBC [410614]: DBG:.type=[0] index=[0] [0x7f3fdfd02810]->[B2B.412.51.1736767665.742304390] state=0 no=0 dlginfo=[0x7f3fdfd1c6c0] peer=[0x7f3fdfd2b120] prev:next=[(nil)][(nil)] Jan 13 14:57:49 Yakhchali-SBC [410614]: DBG:..........dlginfo=[0x7f3fdfd1c6c0]->[1c41cdc79d3a4b2ea7c841ef49518a00][44432d591fe247278a2b558198fcd166][B2B.412.51.1736767665.742304390] Jan 13 14:57:49 Yakhchali-SBC [410614]: DBG:.type=[1] index=[0] [0x7f3fdfd2b120]->[B2B.493.5675184.1736767665.1245583625] state=0 no=1 dlginfo=[0x7f3fdfd1c4d0] peer=[0x7f3fdfd02810] prev:next=[(nil)][(nil)] Jan 13 14:57:49 Yakhchali-SBC [410614]: DBG:..........dlginfo=[0x7f3fdfd1c4d0]->[B2B.493.5675184.1736767665.1245583625][c23830c9308940e0b4ea520bc8705e10][5d9d0a4cf3fa4717380f13d8f920816f-a699] Jan 13 14:57:49 Yakhchali-SBC [410614]: DBG:.type=[0] index=[0] [0x7f3fdfd02810] peer=[0x7f3fdfd2b120] prev:next=[(nil)][(nil)] Jan 13 14:57:49 Yakhchali-SBC [410614]: DBG:.type=[1] index=[1] [0x7f3fdfd2b120] peer=[0x7f3fdfd02810] prev:next=[(nil)][(nil)] Jan 13 14:57:49 Yakhchali-SBC [410614]: DBG:b2b_entities:_b2b_send_reply: For server entity Jan 13 14:57:49 Yakhchali-SBC [410614]: DBG:b2b_entities:b2b_parse_key: hash_index = [412] - local_index= [51] Jan 13 14:57:49 Yakhchali-SBC [410614]: DBG:b2b_entities:b2b_search_htable_next_dlg: entering with start=(nil), table=0x7f3fdfc6d898, hash=412, label=51 Jan 13 14:57:49 Yakhchali-SBC [410614]: DBG:b2b_entities:b2b_search_htable_next_dlg: searching callid 32[1c41cdc79d3a4b2ea7c841ef49518a00] Jan 13 14:57:49 Yakhchali-SBC [410614]: DBG:b2b_entities:b2b_search_htable_next_dlg: searching totag 31[B2B.412.51.1736767665.742304390] Jan 13 14:57:49 Yakhchali-SBC [410614]: DBG:b2b_entities:b2b_search_htable_next_dlg: searching fromtag 32[44432d591fe247278a2b558198fcd166] Jan 13 14:57:49 Yakhchali-SBC [410614]: DBG:b2b_entities:b2b_search_htable_next_dlg: Match for server dlg [0x7f3fdfd37338] dlg->uas_tran=[0x7f3fdfd1a998] Jan 13 14:57:49 Yakhchali-SBC [410614]: DBG:b2b_entities:_b2b_send_reply: Send reply 200 INVITE, for dlg [0x7f3fdfd37338]->[B2B.412.51.1736767665.742304390] Jan 13 14:57:49 Yakhchali-SBC [410614]: DBG:core:parse_headers_aux: flags=ffffffffffffffff Jan 13 14:57:49 Yakhchali-SBC [410614]: DBG:core:parse_headers_aux: flags=ffffffffffffffff Jan 13 14:57:49 Yakhchali-SBC [410614]: DBG:tm:cleanup_uac_timers: RETR/FR timers reset Jan 13 14:57:49 Yakhchali-SBC [410614]: DBG:tm:set_timer: relative timeout is 500000 Jan 13 14:57:49 Yakhchali-SBC [410614]: DBG:tm:insert_timer_unsafe: [4]: 0x7f3fdfd1aae0 (716800000) Jan 13 14:57:49 Yakhchali-SBC [410614]: DBG:tm:insert_timer_unsafe: [0]: 0x7f3fdfd1ab10 (721) Jan 13 14:57:49 Yakhchali-SBC [410614]: DBG:core:tcp_conn_get: con found in state 0 Jan 13 14:57:49 Yakhchali-SBC [410614]: DBG:core:tcp_conn_get: tcp connection found (0x7f3fdfd15df8), acquiring fd Jan 13 14:57:49 Yakhchali-SBC [410614]: DBG:core:tcp_conn_get: c= 0x7f3fdfd15df8, n=16, Usock=127 Jan 13 14:57:49 Yakhchali-SBC [410641]: DBG:core:handle_worker: read response= 7f3fdfd15df8, 1, fd -1 from 6 (410614) Jan 13 14:57:49 Yakhchali-SBC [410614]: DBG:core:tcp_conn_get: after receive_fd: c= 0x7f3fdfd15df8 n=8 fd=5 Jan 13 14:57:49 Yakhchali-SBC [410614]: DBG:proto_tls:proto_tls_send: sending via fd 5... Jan 13 14:57:49 Yakhchali-SBC [410614]: DBG:tls_openssl:openssl_tls_update_fd: New fd is 5 Jan 13 14:57:49 Yakhchali-SBC [410614]: DBG:tls_openssl:openssl_tls_write: write was successful (939 bytes) Jan 13 14:57:49 Yakhchali-SBC [410614]: DBG:proto_tls:proto_tls_send: after write: c=0x7f3fdfd15df8 n=939 fd=5 Jan 13 14:57:49 Yakhchali-SBC [410614]: DBG:proto_tls:proto_tls_send: buf=#012SIP/2.0 200 OK#015#012Via: SIP/2.0/TLS 172.25.5.253:54700;received=172.25.5.253;rport=54700;branch=z9hG4bKPjc2c3b7e324214127a1036a887ab785e5;alias#015#012To: ;tag=B2B.412.51.1736767665.742304390#015#012From: ;tag=44432d591fe247278a2b558198fcd166#015#012Call-ID: 1c41cdc79d3a4b2ea7c841ef49518a00#015#012CSeq: 6323 INVITE#015#012Content-Type: application/sdp#015#012Supported: replaces, 100rel, timer, norefersub#015#012Allow: PRACK, INVITE, ACK, BYE, CANCEL, UPDATE, INFO, SUBSCRIBE, NOTIFY, REFER, MESSAGE, OPTIONS#015#012Session-Expires: 1800;refresher=uac#015#012Require: timer#015#012Contact: #015#012Content-Length: 298#015#012#015#012v=0#015#012o=- 3945769098 3945769099 IN IP4 172.25.17.70#015#012s=pjmedia#015#012b=AS:84#015#012t=0 0#015#012a=X-nat:0#015#012m=audio 17190 RTP/AVP 0 101#015#012c=IN IP4 172.25.17.70#015#012b=TIAS:64000#015#012a=rtpmap:0 PCMU/8000#015#012a=rtpmap:101 telephone-event/8000#015#012a=fmtp:101 0-16#015#012a=ssrc:1856064614 cname:46261cdf27da0e29#015#012a=sendrecv#015#012a=rtcp:17191#015#012 Jan 13 14:57:49 Yakhchali-SBC [410614]: DBG:tm:_reply_light: reply sent out. buf=0x7f4020c9daa0: SIP/2.0 2..., shmem=0x7f3fdfd2d558: SIP/2.0 2 Jan 13 14:57:49 Yakhchali-SBC [410614]: DBG:tm:_reply_light: finished Jan 13 14:57:49 Yakhchali-SBC [410614]: DBG:b2b_entities:_b2b_send_reply: Sent reply [200] without unreffing the cell 0x7f3fdfd1a998 Jan 13 14:57:49 Yakhchali-SBC [410614]: DBG:[0x7f3fdfd2c730]->[250.0] to_del=[0] lifetime=[43916] bridge_entities[0x7f3fdfd02810][0x7f3fdfd2b120][(nil)] Jan 13 14:57:49 Yakhchali-SBC [410614]: DBG:.type=[0] index=[0] [0x7f3fdfd02810]->[B2B.412.51.1736767665.742304390] state=1 no=0 dlginfo=[0x7f3fdfd1c6c0] peer=[0x7f3fdfd2b120] prev:next=[(nil)][(nil)] Jan 13 14:57:49 Yakhchali-SBC [410614]: DBG:..........dlginfo=[0x7f3fdfd1c6c0]->[1c41cdc79d3a4b2ea7c841ef49518a00][44432d591fe247278a2b558198fcd166][B2B.412.51.1736767665.742304390] Jan 13 14:57:49 Yakhchali-SBC [410614]: DBG:.type=[1] index=[0] [0x7f3fdfd2b120]->[B2B.493.5675184.1736767665.1245583625] state=1 no=1 dlginfo=[0x7f3fdfd1c4d0] peer=[0x7f3fdfd02810] prev:next=[(nil)][(nil)] Jan 13 14:57:49 Yakhchali-SBC [410614]: DBG:..........dlginfo=[0x7f3fdfd1c4d0]->[B2B.493.5675184.1736767665.1245583625][c23830c9308940e0b4ea520bc8705e10][5d9d0a4cf3fa4717380f13d8f920816f-a699] Jan 13 14:57:49 Yakhchali-SBC [410614]: DBG:.type=[0] index=[0] [0x7f3fdfd02810] peer=[0x7f3fdfd2b120] prev:next=[(nil)][(nil)] Jan 13 14:57:49 Yakhchali-SBC [410614]: DBG:.type=[1] index=[1] [0x7f3fdfd2b120] peer=[0x7f3fdfd02810] prev:next=[(nil)][(nil)] Jan 13 14:57:49 Yakhchali-SBC [410614]: DBG:b2b_logic:entity_event_trigger: Triggerd event [0] for entity [B2B.493.5675184.1736767665.1245583625] Jan 13 14:57:49 Yakhchali-SBC [410614]: DBG:b2b_logic:b2bl_parse_key: hash_index = [250] - local_index= [0] Jan 13 14:57:49 Yakhchali-SBC [410614]: DBG:tm:cleanup_uac_timers: RETR/FR timers reset Jan 13 14:57:49 Yakhchali-SBC [410614]: DBG:tm:insert_timer_unsafe: [2]: 0x7f3fdfd281d0 (721) Jan 13 14:57:49 Yakhchali-SBC [410614]: DBG:tm:t_unref: UNREF_UNSAFE: [0x7f3fdfd28150] after is 0 Jan 13 14:57:49 Yakhchali-SBC [410614]: DBG:core:destroy_avp_list: destroying list (nil) Jan 13 14:57:49 Yakhchali-SBC [410614]: DBG:core:receive_msg: cleaning up Jan 13 14:57:49 Yakhchali-SBC [410614]: DBG:core:free_sdp_content: sdp = 0x7f4020c9a6a0 Jan 13 14:57:49 Yakhchali-SBC [410614]: DBG:core:free_sdp_content: sdp = 0x7f4020c9a6a0 Jan 13 14:57:49 Yakhchali-SBC [410614]: DBG:core:free_sdp_content: session = 0x7f4020c9a6e8 Jan 13 14:57:49 Yakhchali-SBC [410624]: DBG:proto_tls:tls_read_req: Using the global ( per process ) buff Jan 13 14:57:49 Yakhchali-SBC [410624]: DBG:tls_openssl:openssl_tls_update_fd: New fd is 196 Jan 13 14:57:49 Yakhchali-SBC [410624]: DBG:tls_openssl:openssl_read: 382 bytes read Jan 13 14:57:49 Yakhchali-SBC [410624]: DBG:proto_tls:tcp_handle_req: content-length= 0 Jan 13 14:57:49 Yakhchali-SBC [410624]: DBG:proto_tls:tcp_handle_req: Nothing more to read on TCP conn 0x7f3fdfd15df8, currently in state 0 Jan 13 14:57:49 Yakhchali-SBC [410624]: DBG:core:parse_msg: SIP Request: Jan 13 14:57:49 Yakhchali-SBC [410624]: DBG:core:parse_msg: method: Jan 13 14:57:49 Yakhchali-SBC [410624]: DBG:core:parse_msg: uri: Jan 13 14:57:49 Yakhchali-SBC [410624]: DBG:core:parse_msg: version: Jan 13 14:57:49 Yakhchali-SBC [410624]: DBG:core:parse_headers_aux: flags=ffffffffffffffff Jan 13 14:57:49 Yakhchali-SBC [410624]: DBG:core:parse_via_param: found param type 235, = ; state=6 Jan 13 14:57:49 Yakhchali-SBC [410624]: DBG:core:parse_via_param: found param type 232, = ; state=6 Jan 13 14:57:49 Yakhchali-SBC [410624]: DBG:core:parse_via_param: found param type 237, = ; state=16 Jan 13 14:57:49 Yakhchali-SBC [410624]: DBG:core:parse_via: end of header reached, state=5 Jan 13 14:57:49 Yakhchali-SBC [410624]: DBG:core:parse_headers_aux: via found, flags=ffffffffffffffff Jan 13 14:57:49 Yakhchali-SBC [410624]: DBG:core:parse_headers_aux: this is the first via Jan 13 14:57:49 Yakhchali-SBC [410624]: DBG:core:parse_to_param: tag=B2B.412.51.1736767665.742304390 Jan 13 14:57:49 Yakhchali-SBC [410624]: DBG:core:parse_to_param: end of header reached, state=13 Jan 13 14:57:49 Yakhchali-SBC [410624]: DBG:core:_parse_to: end of header reached, state=29 Jan 13 14:57:49 Yakhchali-SBC [410624]: DBG:core:_parse_to: display={}, ruri={sip:98212010@172.25.17.70} Jan 13 14:57:49 Yakhchali-SBC [410624]: DBG:core:get_hdr_field_aux: [65]; uri=[sip:98212010@172.25.17.70] Jan 13 14:57:49 Yakhchali-SBC [410624]: DBG:core:get_hdr_field_aux: to body [] Jan 13 14:57:49 Yakhchali-SBC [410624]: DBG:core:get_hdr_field_aux: cseq : <6323> Jan 13 14:57:49 Yakhchali-SBC [410624]: DBG:core:get_hdr_field_aux: content_length=0 Jan 13 14:57:49 Yakhchali-SBC [410624]: DBG:core:get_hdr_field_aux: found end of header Jan 13 14:57:49 Yakhchali-SBC [410624]: DBG:core:receive_msg: After parse_msg... Jan 13 14:57:49 Yakhchali-SBC [410624]: DBG:core:tcpconn_add_alias: refusing to add alias (alias_mode: 0, via 'alias': 1) Jan 13 14:57:49 Yakhchali-SBC [410624]: DBG:core:receive_msg: preparing to run routing scripts... Jan 13 14:57:49 Yakhchali-SBC [410624]: DBG:sl:sl_filter_ACK: too late to be a local ACK! Jan 13 14:57:49 Yakhchali-SBC [410624]: DBG:core:parse_headers_aux: flags=ffffffffffffffff Jan 13 14:57:49 Yakhchali-SBC [410624]: DBG:b2b_entities:b2b_prescript_f: start - method = ACK Jan 13 14:57:49 Yakhchali-SBC [410624]: DBG:core:parse_to_param: tag=44432d591fe247278a2b558198fcd166 Jan 13 14:57:49 Yakhchali-SBC [410624]: DBG:core:parse_to_param: end of header reached, state=11 Jan 13 14:57:49 Yakhchali-SBC [410624]: DBG:core:_parse_to: end of header reached, state=29 Jan 13 14:57:49 Yakhchali-SBC [410624]: DBG:core:_parse_to: display={}, ruri={sip:98212009@172.25.17.70} Jan 13 14:57:49 Yakhchali-SBC [410624]: DBG:b2b_entities:b2b_parse_key: hash_index = [412] - local_index= [51] Jan 13 14:57:49 Yakhchali-SBC [410624]: DBG:b2b_entities:b2b_prescript_f: Received a b2b server request [ACK] Jan 13 14:57:49 Yakhchali-SBC [410624]: DBG:b2b_entities:b2b_search_htable_next_dlg: entering with start=(nil), table=0x7f3fdfc6d898, hash=412, label=51 Jan 13 14:57:49 Yakhchali-SBC [410624]: DBG:b2b_entities:b2b_search_htable_next_dlg: searching callid 32[1c41cdc79d3a4b2ea7c841ef49518a00] Jan 13 14:57:49 Yakhchali-SBC [410624]: DBG:b2b_entities:b2b_search_htable_next_dlg: searching totag 31[B2B.412.51.1736767665.742304390] Jan 13 14:57:49 Yakhchali-SBC [410624]: DBG:b2b_entities:b2b_search_htable_next_dlg: searching fromtag 32[44432d591fe247278a2b558198fcd166] Jan 13 14:57:49 Yakhchali-SBC [410624]: DBG:b2b_entities:b2b_search_htable_next_dlg: Match for server dlg [0x7f3fdfd37338] dlg->uas_tran=[0x7f3fdfd1a998] Jan 13 14:57:49 Yakhchali-SBC [410624]: DBG:b2b_entities:b2b_prescript_f: Received request method[ACK] for dialog[0x7f3fdfd37338] Jan 13 14:57:49 Yakhchali-SBC [410624]: NOTICE:[1c41cdc79d3a4b2ea7c841ef49518a00] --------------------------------------------------------------------------- Jan 13 14:57:49 Yakhchali-SBC [410624]: DBG:core:parse_headers_aux: flags=100000000 Jan 13 14:57:49 Yakhchali-SBC [410624]: DBG:core:pv_get_refer_to: no Refer-To header Jan 13 14:57:49 Yakhchali-SBC [410624]: DBG:b2b_logic:b2bl_parse_key: hash_index = [250] - local_index= [0] Jan 13 14:57:49 Yakhchali-SBC [410624]: DBG:core:parse_headers_aux: flags=40 Jan 13 14:57:49 Yakhchali-SBC [410624]: NOTICE:[1c41cdc79d3a4b2ea7c841ef49518a00] [b2b_request_en] fu:sip:98212009@172.25.17.70 tu:sip:98212010@172.25.17.70 ci:1c41cdc79d3a4b2ea7c841ef49518a00 rm:ACK rt: si:172.25.5.253 b2b_key:caller Jan 13 14:57:49 Yakhchali-SBC [410624]: DBG:core:parse_headers_aux: flags=78 Jan 13 14:57:49 Yakhchali-SBC [410624]: DBG:tm:t_lookup_request: start searching: hash=58939, isACK=1 Jan 13 14:57:49 Yakhchali-SBC [410624]: DBG:core:parse_headers_aux: flags=38 Jan 13 14:57:49 Yakhchali-SBC [410624]: DBG:tm:t_lookup_request: REF_UNSAFE:[0x7f3fdfd1a998] after is 2 Jan 13 14:57:49 Yakhchali-SBC [410624]: DBG:tm:t_lookup_request: e2e proxy ACK found Jan 13 14:57:49 Yakhchali-SBC [410624]: DBG:tm:cleanup_uac_timers: RETR/FR timers reset Jan 13 14:57:49 Yakhchali-SBC [410624]: DBG:tm:insert_timer_unsafe: [2]: 0x7f3fdfd1aa18 (721) Jan 13 14:57:49 Yakhchali-SBC [410624]: DBG:tm:t_unref_cell: UNREF_UNSAFE: [0x7f3fdfd1a998] after is 1 Jan 13 14:57:49 Yakhchali-SBC [410624]: DBG:tm:t_newtran: transaction on entrance=(nil) Jan 13 14:57:49 Yakhchali-SBC [410624]: DBG:core:parse_headers_aux: flags=ffffffffffffffff Jan 13 14:57:49 Yakhchali-SBC [410624]: DBG:tm:cleanup_uac_timers: RETR/FR timers reset Jan 13 14:57:49 Yakhchali-SBC [410624]: DBG:tm:t_unref_cell: UNREF_UNSAFE: [0x7f3fdfd1a998] after is 0 Jan 13 14:57:49 Yakhchali-SBC [410624]: DBG:b2b_logic:b2bl_parse_key: hash_index = [250] - local_index= [0] Jan 13 14:57:49 Yakhchali-SBC [410624]: DBG:core:parse_headers_aux: flags=ffffffffffffffff Jan 13 14:57:49 Yakhchali-SBC [410624]: DBG:core:parse_headers_aux: flags=ffffffffffffffff Jan 13 14:57:49 Yakhchali-SBC [410624]: DBG:b2b_logic:b2b_logic_notify: b2b_entities notification cb for [250.0] with entity [B2B.412.51.1736767665.742304390] Jan 13 14:57:49 Yakhchali-SBC [410624]: DBG:b2b_logic:b2bl_search_entity: Key [B2B.412.51.1736767665.742304390] Jan 13 14:57:49 Yakhchali-SBC [410624]: DBG:b2b_logic:b2b_logic_notify_request: b2b_entity key = B2B.412.51.1736767665.742304390 Jan 13 14:57:49 Yakhchali-SBC [410624]: DBG:b2b_logic:b2b_logic_notify_request: request received for tuple[0x7f3fdfd2c730]->[250.0] Jan 13 14:57:49 Yakhchali-SBC [410624]: NOTICE:[1c41cdc79d3a4b2ea7c841ef49518a00] --------------------------------------------------------------------------- Jan 13 14:57:49 Yakhchali-SBC [410624]: DBG:core:parse_headers_aux: flags=100000000 Jan 13 14:57:49 Yakhchali-SBC [410624]: DBG:core:pv_get_refer_to: no Refer-To header Jan 13 14:57:49 Yakhchali-SBC [410624]: NOTICE:[1c41cdc79d3a4b2ea7c841ef49518a00] [b2b_request] fu:sip:98212009@172.25.17.70 tu:sip:98212010@172.25.17.70 ci:1c41cdc79d3a4b2ea7c841ef49518a00 rm:ACK rt: si:172.25.5.253 b2b_key:caller Jan 13 14:57:49 Yakhchali-SBC [410624]: DBG:core:comp_scriptvar: str 29: ACK Jan 13 14:57:49 Yakhchali-SBC [410624]: DBG:b2b_logic:b2bl_search_entity: Key [B2B.412.51.1736767665.742304390] Jan 13 14:57:49 Yakhchali-SBC [410624]: DBG:b2b_logic:_b2b_pass_request: Send request [ACK] to peer [B2B.493.5675184.1736767665.1245583625] Jan 13 14:57:49 Yakhchali-SBC [410624]: DBG:b2b_entities:b2b_parse_key: hash_index = [493] - local_index= [5675184] Jan 13 14:57:49 Yakhchali-SBC [410624]: DBG:b2b_entities:b2b_search_htable_next_dlg: entering with start=(nil), table=0x7f3fdfc708d0, hash=493, label=5675184 Jan 13 14:57:49 Yakhchali-SBC [410624]: DBG:b2b_entities:b2b_search_htable_next_dlg: searching callid 37[B2B.493.5675184.1736767665.1245583625] Jan 13 14:57:49 Yakhchali-SBC [410624]: DBG:b2b_entities:b2b_search_htable_next_dlg: searching totag 37[5d9d0a4cf3fa4717380f13d8f920816f-a699] Jan 13 14:57:49 Yakhchali-SBC [410624]: DBG:b2b_entities:b2b_search_htable_next_dlg: searching fromtag 32[c23830c9308940e0b4ea520bc8705e10] Jan 13 14:57:49 Yakhchali-SBC [410624]: DBG:b2b_entities:_b2b_send_request: Send request [ACK] for entity type [1] for dlg[0x7f3fdfd0ad18]->[B2B.493.5675184.1736767665.1245583625] Jan 13 14:57:49 Yakhchali-SBC [410624]: DBG:b2b_entities:b2b_client_build_dlg: Rem_target = sip:98212010@172.25.5.253:7070;ob Jan 13 14:57:49 Yakhchali-SBC [410624]: DBG:b2b_entities:b2b_client_build_dlg: send sock= 172.25.17.70 Jan 13 14:57:49 Yakhchali-SBC [410624]: DBG:tm:t_uac: next_hop= Jan 13 14:57:49 Yakhchali-SBC [410624]: DBG:core:mk_proxy: doing DNS lookup... Jan 13 14:57:49 Yakhchali-SBC [410624]: DBG:tm:t_uac: sending socket is 172.25.17.70 Jan 13 14:57:49 Yakhchali-SBC [410624]: DBG:tm:print_request_uri: sip:98212010@172.25.5.253:7070;ob Jan 13 14:57:49 Yakhchali-SBC [410624]: DBG:tm:run_local_route: building sip_msg from buffer Jan 13 14:57:49 Yakhchali-SBC [410624]: DBG:core:parse_msg: SIP Request: Jan 13 14:57:49 Yakhchali-SBC [410624]: DBG:core:parse_msg: method: Jan 13 14:57:49 Yakhchali-SBC [410624]: DBG:core:parse_msg: uri: Jan 13 14:57:49 Yakhchali-SBC [410624]: DBG:core:parse_msg: version: Jan 13 14:57:49 Yakhchali-SBC [410624]: DBG:core:parse_headers_aux: flags=ffffffffffffffff Jan 13 14:57:49 Yakhchali-SBC [410624]: DBG:core:parse_via_param: found param type 232, = ; state=16 Jan 13 14:57:49 Yakhchali-SBC [410624]: DBG:core:parse_via: end of header reached, state=5 Jan 13 14:57:49 Yakhchali-SBC [410624]: DBG:core:parse_headers_aux: via found, flags=ffffffffffffffff Jan 13 14:57:49 Yakhchali-SBC [410624]: DBG:core:parse_headers_aux: this is the first via Jan 13 14:57:49 Yakhchali-SBC [410624]: DBG:core:parse_to_param: tag=c23830c9308940e0b4ea520bc8705e10 Jan 13 14:57:49 Yakhchali-SBC [410624]: DBG:core:parse_to_param: end of header reached, state=13 Jan 13 14:57:49 Yakhchali-SBC [410624]: DBG:core:_parse_to: end of header reached, state=29 Jan 13 14:57:49 Yakhchali-SBC [410624]: DBG:core:_parse_to: display={}, ruri={sip:98212010@172.25.5.253:7070;ob} Jan 13 14:57:49 Yakhchali-SBC [410624]: DBG:core:get_hdr_field_aux: [74]; uri=[sip:98212010@172.25.5.253:7070;ob] Jan 13 14:57:49 Yakhchali-SBC [410624]: DBG:core:get_hdr_field_aux: to body [] Jan 13 14:57:49 Yakhchali-SBC [410624]: DBG:core:get_hdr_field_aux: cseq : <6324> Jan 13 14:57:49 Yakhchali-SBC [410624]: DBG:core:get_hdr_field_aux: content_length=0 Jan 13 14:57:49 Yakhchali-SBC [410624]: DBG:core:get_hdr_field_aux: found end of header Jan 13 14:57:49 Yakhchali-SBC [410624]: DBG:core:parse_headers_aux: flags=ffffffffffffffff Jan 13 14:57:49 Yakhchali-SBC [410624]: DBG:core:parse_headers_aux: flags=78 Jan 13 14:57:49 Yakhchali-SBC [410624]: NOTICE:[B2B.493.5675184.1736767665.1245583625] --------------------------------------------------------------------------- Jan 13 14:57:49 Yakhchali-SBC [410624]: DBG:core:parse_to_param: tag=5d9d0a4cf3fa4717380f13d8f920816f-a699 Jan 13 14:57:49 Yakhchali-SBC [410624]: DBG:core:parse_to_param: end of header reached, state=11 Jan 13 14:57:49 Yakhchali-SBC [410624]: DBG:core:_parse_to: end of header reached, state=29 Jan 13 14:57:49 Yakhchali-SBC [410624]: DBG:core:_parse_to: display={}, ruri={sip:98212009@172.25.17.70} Jan 13 14:57:49 Yakhchali-SBC [410624]: DBG:[B2B.493.5675184.1736767665.1245583625] [b2b_local_route] rm:ACK si:172.25.17.70 rd:172.25.5.253 avp(net): fu:sip:98212009@172.25.17.70 tu:sip:98212010@172.25.5.253:7070;ob ci:B2B.493.5675184.1736767665.1245583625 socket:udp:172.25.17.70:5060 Jan 13 14:57:49 Yakhchali-SBC [410624]: DBG:core:comp_scriptvar: str 20: b2b Jan 13 14:57:49 Yakhchali-SBC [410624]: DBG:b2b_logic:fetch_ctx_value: looking for context value [route_data] Jan 13 14:57:49 Yakhchali-SBC [410624]: DBG:b2b_logic:fetch_ctx_value: looking for context value [route_data] Jan 13 14:57:49 Yakhchali-SBC [410624]: DBG:b2b_logic:fetch_ctx_value: looking for context value [route_data] Jan 13 14:57:49 Yakhchali-SBC [410624]: DBG:[B2B.493.5675184.1736767665.1245583625] [load_session_data] using b2bctx:{ "ifacesalida": "", "Outgoingfromvalue": "", "net": "0.0.0.0\/0.0.0.0", "idrtpin": "external", "routebymatchingrule_from": "none", "routebymatchingrule_to": "none", "ratelimit": "0", "isWhitelist": "0", "handleRtp": "1", "nextHop": "0", "srtp_mode": "transient", "allowedNet": "0.0.0.0\/0.0.0.0", "nextHopTransport": "", "idrtpout": "external", "codecs": "pcmu,pcma,gsm,speex,opus,g718,g719,g721,g723,g726,g728,g729,ilbc", "rtpparam": null, "setid": "2", "b2b": "1", "metrica": "1", "prefix_remove_add": "[]", "route_id": 57, "dispatcher_algo": "", "sip_hdr_to_add": "", "sip_hdr_prefix_to_remove": "", "normal_compact_sip_hdr": "no", "check_sip_from_hdr": "no", "h323_gw_id": "0", "allowed_methods": "NOTIFY|OPTIONS|INFO|SUBSCRIBE|PUBLISH", "outbound_proxy": null, "nat_handling": "disable", "fraud_pro_id": "", "fraud_action": "", "fraud_excluded_username": "", "add_chk_hdrs": "false", "match_type_from": "match", "match_type_to": "match", "call_sourceip": "172.25.5.253", "is_dst_ws": -1, "is_src_ws": -1, "socket_out": "udp:172.25.17.70:5060", "rtp_cid": "1c41cdc79d3a4b2ea7c841ef49518a00", "rtp_from_tag": "44432d591fe247278a2b558198fcd166", "rtp_to_tag": "c23830c9308940e0b4ea520bc8705e10" } Jan 13 14:57:49 Yakhchali-SBC [410624]: DBG:core:destroy_index_avp: AVP with the specified index not found Jan 13 14:57:49 Yakhchali-SBC [410624]: DBG:core:destroy_index_avp: AVP with the specified index not found Jan 13 14:57:49 Yakhchali-SBC [410624]: DBG:tm:cleanup_uac_timers: RETR/FR timers reset Jan 13 14:57:49 Yakhchali-SBC [410624]: DBG:tm:insert_timer_unsafe: [2]: 0x7f3fdfd1c858 (721) Jan 13 14:57:49 Yakhchali-SBC [410624]: DBG:b2b_logic:entity_event_trigger: Triggerd event [1] for entity [B2B.493.5675184.1736767665.1245583625] Jan 13 14:57:49 Yakhchali-SBC [410624]: DBG:b2b_logic:b2bl_parse_key: hash_index = [250] - local_index= [0] Jan 13 14:57:49 Yakhchali-SBC [410624]: DBG:b2b_logic:entity_event_trigger: Triggerd event [1] for entity [B2B.412.51.1736767665.742304390] Jan 13 14:57:49 Yakhchali-SBC [410624]: DBG:b2b_logic:b2bl_parse_key: hash_index = [250] - local_index= [0] Jan 13 14:57:49 Yakhchali-SBC [410624]: DBG:core:destroy_avp_list: destroying list 0x7f3fdfd2aec8 Jan 13 14:57:49 Yakhchali-SBC [410624]: DBG:core:receive_msg: cleaning up Jan 13 14:57:49 Yakhchali-SBC [410624]: DBG:proto_tls:tls_read_req: tls_read_req end Jan 13 14:57:49 Yakhchali-SBC [410639]: DBG:tm:utimer_routine: timer routine:4,tl=0x7f3fdfd1aae0 next=(nil), timeout=716800000 Jan 13 14:57:50 Yakhchali-SBC [410624]: DBG:proto_tls:tls_read_req: Using the global ( per process ) buff Jan 13 14:57:50 Yakhchali-SBC [410624]: DBG:tls_openssl:openssl_tls_update_fd: New fd is 196 Jan 13 14:57:50 Yakhchali-SBC [410624]: DBG:tls_openssl:openssl_read: 411 bytes read Jan 13 14:57:50 Yakhchali-SBC [410624]: DBG:proto_tls:tcp_handle_req: content-length= 0 Jan 13 14:57:50 Yakhchali-SBC [410624]: DBG:proto_tls:tcp_handle_req: Nothing more to read on TCP conn 0x7f3fdfd15df8, currently in state 0 Jan 13 14:57:50 Yakhchali-SBC [410624]: DBG:core:parse_msg: SIP Request: Jan 13 14:57:50 Yakhchali-SBC [410624]: DBG:core:parse_msg: method: Jan 13 14:57:50 Yakhchali-SBC [410624]: DBG:core:parse_msg: uri: Jan 13 14:57:50 Yakhchali-SBC [410624]: DBG:core:parse_msg: version: Jan 13 14:57:50 Yakhchali-SBC [410624]: DBG:core:parse_headers_aux: flags=ffffffffffffffff Jan 13 14:57:50 Yakhchali-SBC [410624]: DBG:core:parse_via_param: found param type 235, = ; state=6 Jan 13 14:57:50 Yakhchali-SBC [410624]: DBG:core:parse_via_param: found param type 232, = ; state=6 Jan 13 14:57:50 Yakhchali-SBC [410624]: DBG:core:parse_via_param: found param type 237, = ; state=16 Jan 13 14:57:50 Yakhchali-SBC [410624]: DBG:core:parse_via: end of header reached, state=5 Jan 13 14:57:50 Yakhchali-SBC [410624]: DBG:core:parse_headers_aux: via found, flags=ffffffffffffffff Jan 13 14:57:50 Yakhchali-SBC [410624]: DBG:core:parse_headers_aux: this is the first via Jan 13 14:57:50 Yakhchali-SBC [410624]: DBG:core:parse_to_param: tag=B2B.412.51.1736767665.742304390 Jan 13 14:57:50 Yakhchali-SBC [410624]: DBG:core:parse_to_param: end of header reached, state=13 Jan 13 14:57:50 Yakhchali-SBC [410624]: DBG:core:_parse_to: end of header reached, state=29 Jan 13 14:57:50 Yakhchali-SBC [410624]: DBG:core:_parse_to: display={}, ruri={sip:98212010@172.25.17.70} Jan 13 14:57:50 Yakhchali-SBC [410624]: DBG:core:get_hdr_field_aux: [65]; uri=[sip:98212010@172.25.17.70] Jan 13 14:57:50 Yakhchali-SBC [410624]: DBG:core:get_hdr_field_aux: to body [] Jan 13 14:57:50 Yakhchali-SBC [410624]: DBG:core:get_hdr_field_aux: cseq : <6324> Jan 13 14:57:50 Yakhchali-SBC [410624]: DBG:core:get_hdr_field_aux: content_length=0 Jan 13 14:57:50 Yakhchali-SBC [410624]: DBG:core:get_hdr_field_aux: found end of header Jan 13 14:57:50 Yakhchali-SBC [410624]: DBG:core:receive_msg: After parse_msg... Jan 13 14:57:50 Yakhchali-SBC [410624]: DBG:core:tcpconn_add_alias: refusing to add alias (alias_mode: 0, via 'alias': 1) Jan 13 14:57:50 Yakhchali-SBC [410624]: DBG:core:receive_msg: preparing to run routing scripts... Jan 13 14:57:50 Yakhchali-SBC [410624]: DBG:core:parse_headers_aux: flags=ffffffffffffffff Jan 13 14:57:50 Yakhchali-SBC [410624]: DBG:b2b_entities:b2b_prescript_f: start - method = BYE Jan 13 14:57:50 Yakhchali-SBC [410624]: DBG:b2b_entities:b2b_prescript_f: host:port [172.25.17.70][0] Jan 13 14:57:50 Yakhchali-SBC [410624]: DBG:core:grep_sock_info_ext: checking if host==us: 12==12 && [172.25.17.70] == [172.25.17.70] Jan 13 14:57:50 Yakhchali-SBC [410624]: DBG:core:grep_sock_info_ext: checking if port 8090 matches port 5060 Jan 13 14:57:50 Yakhchali-SBC [410624]: DBG:core:grep_sock_info_ext: checking if host==us: 12==13 && [172.25.17.70] == [172.25.19.192] Jan 13 14:57:50 Yakhchali-SBC [410624]: DBG:core:grep_sock_info_ext: checking if port 5061 matches port 5060 Jan 13 14:57:50 Yakhchali-SBC [410624]: DBG:core:grep_sock_info_ext: checking if host==us: 12==12 && [172.25.17.70] == [172.25.17.70] Jan 13 14:57:50 Yakhchali-SBC [410624]: DBG:core:grep_sock_info_ext: checking if port 5061 matches port 5060 Jan 13 14:57:50 Yakhchali-SBC [410624]: DBG:core:check_self: host != me Jan 13 14:57:50 Yakhchali-SBC [410624]: DBG:b2b_entities:b2b_prescript_f: RURI does not point to me Jan 13 14:57:50 Yakhchali-SBC [410624]: DBG:core:parse_headers_aux: flags=ffffffffffffffff Jan 13 14:57:50 Yakhchali-SBC [410624]: DBG:core:comp_scriptvar: str 20: tls Jan 13 14:57:50 Yakhchali-SBC [410624]: DBG:core:comp_scriptvar: str 20: tls Jan 13 14:57:50 Yakhchali-SBC [410624]: DBG:core:cachedb_fetch: from script [redis] - with grp [local] Jan 13 14:57:50 Yakhchali-SBC [410624]: DBG:cachedb_redis:get_redis_connection: Single redis connection, returning 0x7f4020c98488 Jan 13 14:57:50 Yakhchali-SBC [410624]: DBG:cachedb_redis:redis_get: GET UA - /^(test1|test2|test3)$/ Jan 13 14:57:50 Yakhchali-SBC [410624]: DBG:core:parse_headers_aux: flags=ffffffffffffffff Jan 13 14:57:50 Yakhchali-SBC [410624]: DBG:core:parse_headers_aux: flags=ffffffffffffffff Jan 13 14:57:50 Yakhchali-SBC [410624]: NOTICE:[1c41cdc79d3a4b2ea7c841ef49518a00(BYE)] --------------------------------------------------------------------------- Jan 13 14:57:50 Yakhchali-SBC [410624]: DBG:core:parse_to_param: tag=44432d591fe247278a2b558198fcd166 Jan 13 14:57:50 Yakhchali-SBC [410624]: DBG:core:parse_to_param: end of header reached, state=11 Jan 13 14:57:50 Yakhchali-SBC [410624]: DBG:core:_parse_to: end of header reached, state=29 Jan 13 14:57:50 Yakhchali-SBC [410624]: DBG:core:_parse_to: display={}, ruri={sip:98212009@172.25.17.70} Jan 13 14:57:50 Yakhchali-SBC [410624]: NOTICE:[1c41cdc79d3a4b2ea7c841ef49518a00(BYE)] [main] BYE ci:1c41cdc79d3a4b2ea7c841ef49518a00 ru:sip:172.25.17.70;transport=tls from:sip:98212009@172.25.17.70 to:sip:98212010@172.25.17.70 si:172.25.5.253 avp(is_h323):0 proto:tls Jan 13 14:57:50 Yakhchali-SBC [410624]: DBG:core:comp_scriptvar: str 20: TLS Jan 13 14:57:50 Yakhchali-SBC [410624]: DBG:core:tcp_conn_get: con found in state 0 Jan 13 14:57:50 Yakhchali-SBC [410624]: DBG:core:tcp_conn_get: con found in state 0 Jan 13 14:57:50 Yakhchali-SBC [410624]: DBG:tls_openssl:openssl_tls_var_comp: ind = 406 Jan 13 14:57:50 Yakhchali-SBC [410624]: ERROR:tls_openssl:get_cert: failed to get certificate from SSL structure Jan 13 14:57:50 Yakhchali-SBC [410624]: DBG:core:tcp_conn_get: con found in state 0 Jan 13 14:57:50 Yakhchali-SBC [410624]: DBG:tls_openssl:openssl_tls_var_comp: ind = 405 Jan 13 14:57:50 Yakhchali-SBC [410624]: DBG:core:tcp_conn_get: con found in state 0 Jan 13 14:57:50 Yakhchali-SBC [410624]: DBG:core:tcp_conn_get: con found in state 0 Jan 13 14:57:50 Yakhchali-SBC [410624]: DBG:tls_openssl:openssl_tls_var_comp: ind = a Jan 13 14:57:50 Yakhchali-SBC [410624]: ERROR:tls_openssl:get_cert: failed to get certificate from SSL structure Jan 13 14:57:50 Yakhchali-SBC [410624]: DBG:core:tcp_conn_get: con found in state 0 Jan 13 14:57:50 Yakhchali-SBC [410624]: DBG:tls_openssl:openssl_tls_var_comp: ind = 9 Jan 13 14:57:50 Yakhchali-SBC [410624]: NOTICE:[1c41cdc79d3a4b2ea7c841ef49518a00(BYE)] [main] [tls] version:TLSv1.2 peer_cn: my_cn:172.25.17.70 peer_verified:0 '' '/C=IR/ST=TTT/L=TTT/O=chakavak/OU=SBC/CN=172.25.17.70/emailAddress=info@chakavak.io' Jan 13 14:57:50 Yakhchali-SBC [410624]: DBG:core:tcp_conn_get: con found in state 0 Jan 13 14:57:50 Yakhchali-SBC [410624]: DBG:tls_openssl:openssl_tls_var_comp: ind = 405 Jan 13 14:57:50 Yakhchali-SBC [410624]: DBG:core:cachedb_fetch: from script [redis] - with grp [local] Jan 13 14:57:50 Yakhchali-SBC [410624]: DBG:cachedb_redis:get_redis_connection: Single redis connection, returning 0x7f4020c98488 Jan 13 14:57:50 Yakhchali-SBC [410624]: DBG:cachedb_redis:redis_get: no such key - tls:172.25.17.70 Jan 13 14:57:50 Yakhchali-SBC [410624]: DBG:core:tcp_conn_get: con found in state 0 Jan 13 14:57:50 Yakhchali-SBC [410624]: DBG:tls_openssl:openssl_tls_var_comp: ind = 405 Jan 13 14:57:50 Yakhchali-SBC [410624]: ERROR:[1c41cdc79d3a4b2ea7c841ef49518a00(BYE)] [check_tls] no tls config found for domain:172.25.17.70 Jan 13 14:57:50 Yakhchali-SBC [410624]: DBG:maxfwd:is_maxfwd_present: value = 70 Jan 13 14:57:50 Yakhchali-SBC [410624]: DBG:core:cachedb_fetch: from script [redis] - with grp [local] Jan 13 14:57:50 Yakhchali-SBC [410624]: DBG:cachedb_redis:get_redis_connection: Single redis connection, returning 0x7f4020c98488 Jan 13 14:57:50 Yakhchali-SBC [410624]: DBG:cachedb_redis:redis_get: no such key - blacklist_from:98212009 Jan 13 14:57:50 Yakhchali-SBC [410624]: DBG:core:cachedb_fetch: from script [redis] - with grp [local] Jan 13 14:57:50 Yakhchali-SBC [410624]: DBG:cachedb_redis:get_redis_connection: Single redis connection, returning 0x7f4020c98488 Jan 13 14:57:50 Yakhchali-SBC [410624]: DBG:cachedb_redis:redis_get: no such key - blacklist_from:98212009@172.25.5.253 Jan 13 14:57:50 Yakhchali-SBC [410624]: DBG:core:parse_headers_aux: flags=78 Jan 13 14:57:50 Yakhchali-SBC [410624]: DBG:tm:t_lookup_request: start searching: hash=58936, isACK=0 Jan 13 14:57:50 Yakhchali-SBC [410624]: DBG:tm:matching_3261: RFC3261 transaction matching failed Jan 13 14:57:50 Yakhchali-SBC [410624]: DBG:tm:t_lookup_request: no transaction found Jan 13 14:57:50 Yakhchali-SBC [410624]: DBG:sipmsgops:has_totag: totag found Jan 13 14:57:50 Yakhchali-SBC [410624]: DBG:core:comp_scriptvar: str 20: BYE Jan 13 14:57:50 Yakhchali-SBC [410624]: DBG:core:parse_headers_aux: flags=200 Jan 13 14:57:50 Yakhchali-SBC [410624]: DBG:core:grep_sock_info_ext: checking if host==us: 12==13 && [172.25.17.70] == [172.25.19.192] Jan 13 14:57:50 Yakhchali-SBC [410624]: DBG:core:grep_sock_info_ext: checking if port 5080 matches port 5060 Jan 13 14:57:50 Yakhchali-SBC [410624]: DBG:core:grep_sock_info_ext: checking if host==us: 12==12 && [172.25.17.70] == [172.25.17.70] Jan 13 14:57:50 Yakhchali-SBC [410624]: DBG:core:grep_sock_info_ext: checking if port 5060 matches port 5060 Jan 13 14:57:50 Yakhchali-SBC [410624]: DBG:dialog:dlg_onroute: Route param 'did' not found Jan 13 14:57:50 Yakhchali-SBC [410624]: DBG:core:parse_headers_aux: flags=58 Jan 13 14:57:50 Yakhchali-SBC [410624]: DBG:dialog:get_dlg: input ci=<1c41cdc79d3a4b2ea7c841ef49518a00>(32), tt=<44432d591fe247278a2b558198fcd166>(32), ft=(31) Jan 13 14:57:50 Yakhchali-SBC [410624]: DBG:dialog:get_dlg: no dialog callid='1c41cdc79d3a4b2ea7c841ef49518a00' found Jan 13 14:57:50 Yakhchali-SBC [410624]: DBG:dialog:dlg_onroute: Callid '1c41cdc79d3a4b2ea7c841ef49518a00' not found Jan 13 14:57:50 Yakhchali-SBC [410624]: DBG:core:parse_headers_aux: flags=200 Jan 13 14:57:50 Yakhchali-SBC [410624]: DBG:core:grep_sock_info_ext: checking if host==us: 12==13 && [172.25.17.70] == [172.25.19.192] Jan 13 14:57:50 Yakhchali-SBC [410624]: DBG:core:grep_sock_info_ext: checking if port 5080 matches port 5060 Jan 13 14:57:50 Yakhchali-SBC [410624]: DBG:core:grep_sock_info_ext: checking if host==us: 12==12 && [172.25.17.70] == [172.25.17.70] Jan 13 14:57:50 Yakhchali-SBC [410624]: DBG:core:grep_sock_info_ext: checking if port 5060 matches port 5060 Jan 13 14:57:50 Yakhchali-SBC [410624]: INFO:[1c41cdc79d3a4b2ea7c841ef49518a00(BYE)] [indialogrouting] topology hiding not matched Jan 13 14:57:50 Yakhchali-SBC [410624]: DBG:core:parse_headers_aux: flags=ffffffffffffffff Jan 13 14:57:50 Yakhchali-SBC [410624]: DBG:sipmsgops:is_present_hf: header ''(10) not found Jan 13 14:57:50 Yakhchali-SBC [410624]: DBG:core:parse_headers_aux: flags=200 Jan 13 14:57:50 Yakhchali-SBC [410624]: DBG:rr:find_first_route: No Route headers found Jan 13 14:57:50 Yakhchali-SBC [410624]: DBG:rr:loose_route: There is no Route HF Jan 13 14:57:50 Yakhchali-SBC [410624]: ERROR:[1c41cdc79d3a4b2ea7c841ef49518a00(BYE)] [indialogrouting] Loose-routing not possible for BYE in-dialog request, 404 Jan 13 14:57:50 Yakhchali-SBC [410624]: DBG:core:parse_headers_aux: flags=ffffffffffffffff Jan 13 14:57:50 Yakhchali-SBC [410624]: DBG:core:tcp_conn_get: con found in state 0 Jan 13 14:57:50 Yakhchali-SBC [410624]: DBG:core:tcp_conn_get: tcp connection found (0x7f3fdfd15df8) already in this process ( 16 ) , fd = 196 Jan 13 14:57:50 Yakhchali-SBC [410624]: DBG:proto_tls:proto_tls_send: sending via fd 196... Jan 13 14:57:50 Yakhchali-SBC [410624]: DBG:tls_openssl:openssl_tls_update_fd: New fd is 196 Jan 13 14:57:50 Yakhchali-SBC [410624]: DBG:tls_openssl:openssl_tls_write: write was successful (369 bytes) Jan 13 14:57:50 Yakhchali-SBC [410624]: DBG:proto_tls:proto_tls_send: after write: c=0x7f3fdfd15df8 n=369 fd=196 Jan 13 14:57:50 Yakhchali-SBC [410624]: DBG:proto_tls:proto_tls_send: buf=#012SIP/2.0 404 Not here#015#012Via: SIP/2.0/TLS 172.25.5.253:54700;received=172.25.5.253;rport=54700;branch=z9hG4bKPjd61bc292c2034ee283616db38d78188d;alias#015#012To: ;tag=B2B.412.51.1736767665.742304390#015#012From: ;tag=44432d591fe247278a2b558198fcd166#015#012Call-ID: 1c41cdc79d3a4b2ea7c841ef49518a00#015#012CSeq: 6324 BYE#015#012Content-Length: 0#015#012#015#012 Jan 13 14:57:50 Yakhchali-SBC [410624]: DBG:core:destroy_avp_list: destroying list 0x7f3fdfd063d0 Jan 13 14:57:50 Yakhchali-SBC [410624]: DBG:core:receive_msg: cleaning up Jan 13 14:57:50 Yakhchali-SBC [410624]: DBG:proto_tls:tls_read_req: tls_read_req end Jan 13 14:57:50 Yakhchali-SBC [410614]: DBG:core:udp_read_req: probing packet received len = 2