Call-ID	isbcmq49mmdt5qba6tozy4q9ocamc55zoz43@10.18.5.64


23:04:56 [24016]: DEBUG: <core> [core/udp_server.c:491]: udp_rcv_loop(): received on udp socket: (106/100/1268) [[INVITE sip:444444656646820@2.2.2.2;user=phone SIP/2.0 0D  0A Via: SIP/2.0/UDP 1.1.1.1:5060;b]]
23:04:56 [24016]: DEBUG: <core> [core/receive.c:138]: sip_check_fline(): first line indicates a SIP request
23:04:56 [24016]: DEBUG: siptrace [siptrace_hep.c:498]: pipport2su(): the port string is 5060
23:04:56 [24016]: DEBUG: siptrace [siptrace_hep.c:498]: pipport2su(): the port string is 5060
23:04:56 [24016]: DEBUG: <core> [core/proxy.c:264]: mk_proxy(): doing DNS lookup...
23:04:56 [24016]: DEBUG: siptrace [siptrace_hep.c:183]: trace_send_hep3_duplicate(): setting up the socket_info
23:04:56 [24016]: DEBUG: <core> [core/parser/msg_parser.c:610]: parse_msg(): SIP Request:
23:04:56 [24016]: DEBUG: <core> [core/parser/msg_parser.c:612]: parse_msg():  method:  <INVITE>
23:04:56 [24016]: DEBUG: <core> [core/parser/msg_parser.c:614]: parse_msg():  uri:     <sip:444444656646820@2.2.2.2;user=phone>
23:04:56 [24016]: DEBUG: <core> [core/parser/msg_parser.c:616]: parse_msg():  version: <SIP/2.0>
23:04:56 [24016]: DEBUG: <core> [core/parser/parse_via.c:1303]: parse_via_param(): Found param type 232, <branch> = <z9hG4bKete1rhqujwelu1nonl1toinrp>; state=6
23:04:56 [24016]: DEBUG: <core> [core/parser/parse_via.c:1303]: parse_via_param(): Found param type 253, <Role> = <3>; state=6
23:04:56 [24016]: DEBUG: <core> [core/parser/parse_via.c:1303]: parse_via_param(): Found param type 253, <Hpt> = <9038_16>; state=16
23:04:56 [24016]: DEBUG: <core> [core/parser/parse_via.c:2639]: parse_via(): end of header reached, state=5
23:04:56 [24016]: DEBUG: <core> [core/parser/msg_parser.c:498]: parse_headers(): Via found, flags=2
23:04:56 [24016]: DEBUG: <core> [core/parser/msg_parser.c:500]: parse_headers(): this is the first via
23:04:56 [24016]: DEBUG: <core> [core/parser/parse_addr_spec.c:864]: parse_addr_spec(): end of header reached, state=10
23:04:56 [24016]: DEBUG: <core> [core/parser/msg_parser.c:171]: get_hdr_field(): <To> [80]; uri=[sip:444444656646820@2.2.2.2;transport=udp;user=phone]
23:04:56 [24016]: DEBUG: <core> [core/parser/msg_parser.c:174]: get_hdr_field(): to body ["444444656646820"<sip:444444656646820@2.2.2.2;transport=udp;user=phone>#015#012], to tag []
23:04:56 [24016]: DEBUG: <core> [core/parser/msg_parser.c:152]: get_hdr_field(): cseq <CSeq>: <1> <INVITE>
23:04:56 [24016]: DEBUG: <core> [core/parser/msg_parser.c:185]: get_hdr_field(): content_length=270
23:04:56 [24016]: DEBUG: <core> [core/parser/msg_parser.c:89]: get_hdr_field(): found end of header
23:04:56 [24016]: DEBUG: <core> [core/parser/parse_addr_spec.c:185]: parse_to_param(): add param: tag=456mb993-CC-1020-OFC-1324
23:04:56 [24016]: DEBUG: <core> [core/parser/parse_addr_spec.c:864]: parse_addr_spec(): end of header reached, state=29
23:04:56 [24016]: DEBUG: <core> [core/parser/msg_parser.c:610]: parse_msg(): SIP Request:
23:04:56 [24016]: DEBUG: <core> [core/parser/msg_parser.c:612]: parse_msg():  method:  <INVITE>
23:04:56 [24016]: DEBUG: <core> [core/parser/msg_parser.c:614]: parse_msg():  uri:     <sip:444444656646820@2.2.2.2;user=phone>
23:04:56 [24016]: DEBUG: <core> [core/parser/msg_parser.c:616]: parse_msg():  version: <SIP/2.0>
23:04:56 [24016]: DEBUG: <core> [core/parser/parse_via.c:1303]: parse_via_param(): Found param type 232, <branch> = <z9hG4bKete1rhqujwelu1nonl1toinrp>; state=6
23:04:56 [24016]: DEBUG: <core> [core/parser/parse_via.c:1303]: parse_via_param(): Found param type 253, <Role> = <3>; state=6
23:04:56 [24016]: DEBUG: <core> [core/parser/parse_via.c:1303]: parse_via_param(): Found param type 253, <Hpt> = <9038_16>; state=16
23:04:56 [24016]: DEBUG: <core> [core/parser/parse_via.c:2639]: parse_via(): end of header reached, state=5
23:04:56 [24016]: DEBUG: <core> [core/parser/msg_parser.c:498]: parse_headers(): Via found, flags=2
23:04:56 [24016]: DEBUG: <core> [core/parser/msg_parser.c:500]: parse_headers(): this is the first via
23:04:56 [24016]: DEBUG: <core> [core/parser/parse_addr_spec.c:864]: parse_addr_spec(): end of header reached, state=10
23:04:56 [24016]: DEBUG: <core> [core/parser/msg_parser.c:171]: get_hdr_field(): <To> [80]; uri=[sip:444444656646820@2.2.2.2;transport=udp;user=phone]
23:04:56 [24016]: DEBUG: <core> [core/parser/msg_parser.c:174]: get_hdr_field(): to body ["444444656646820"<sip:444444656646820@2.2.2.2;transport=udp;user=phone>#015#012], to tag []
23:04:56 [24016]: DEBUG: <core> [core/parser/msg_parser.c:152]: get_hdr_field(): cseq <CSeq>: <1> <INVITE>
23:04:56 [24016]: DEBUG: <core> [core/receive.c:241]: receive_msg(): --- received sip message - request - call-id: [isbcmq49mmdt5qba6tozy4q9ocamc55zoz43@10.18.5.64] - cseq: [1 INVITE]
23:04:56 [24016]: DEBUG: <core> [core/receive.c:296]: receive_msg(): preparing to run routing scripts...
23:04:56 [24016]: DEBUG: <core> [core/parser/parse_addr_spec.c:185]: parse_to_param(): add param: tag=456mb993-CC-1020-OFC-1324
23:04:56 [24016]: DEBUG: <core> [core/parser/parse_addr_spec.c:864]: parse_addr_spec(): end of header reached, state=29
23:04:56 [24016]: INFO: <script>: [MAIN] New request - M=INVITE RURI=sip:444444656646820@2.2.2.2;user=phone F=sip:+33825462354@1.1.1.1;transport=udp;user=phone T=sip:444444656646820@2.2.2.2;transport=udp;user=phone IP=1.1.1.1 ID=isbcmq49mmdt5qba6tozy4q9ocamc55zoz43@10.18.5.64
23:04:56 [24016]: INFO: <script>: [SANITY_CHECK] - ID=isbcmq49mmdt5qba6tozy4q9ocamc55zoz43@10.18.5.64
23:04:56 [24016]: DEBUG: <script>: [SANITY_CHECK] - M=INVITE RURI=sip:444444656646820@2.2.2.2;user=phone F=sip:+33825462354@1.1.1.1;transport=udp;user=phone T=sip:444444656646820@2.2.2.2;transport=udp;user=phone IP=1.1.1.1 ID=isbcmq49mmdt5qba6tozy4q9ocamc55zoz43@10.18.5.64
23:04:56 [24016]: DEBUG: maxfwd [mf_funcs.c:74]: is_maxfwd_present(): value = 65
23:04:56 [24016]: DEBUG: sanity [sanity.c:247]: check_ruri_sip_version(): check_ruri_sip_version entered
23:04:56 [24016]: DEBUG: sanity [sanity.c:270]: check_ruri_sip_version(): check_ruri_sip_version passed
23:04:56 [24016]: DEBUG: sanity [sanity.c:277]: check_ruri_scheme(): check_ruri_scheme entered
23:04:56 [24016]: DEBUG: sanity [sanity.c:297]: check_ruri_scheme(): check_ruri_scheme passed
23:04:56 [24016]: DEBUG: sanity [sanity.c:305]: check_required_headers(): check_required_headers entered
23:04:56 [24016]: DEBUG: sanity [sanity.c:313]: check_required_headers(): check_required_headers passed
23:04:56 [24016]: DEBUG: sanity [sanity.c:479]: check_cseq_method(): check_cseq_method entered
23:04:56 [24016]: DEBUG: sanity [sanity.c:512]: check_cseq_method(): check_cseq_method passed
23:04:56 [24016]: DEBUG: sanity [sanity.c:521]: check_cseq_value(): check_cseq_value entered
23:04:56 [24016]: DEBUG: sanity [sanity.c:549]: check_cseq_value(): check_cseq_value passed
23:04:56 [24016]: DEBUG: sanity [sanity.c:558]: check_cl(): check_cl entered
23:04:56 [24016]: DEBUG: <core> [core/parser/msg_parser.c:185]: get_hdr_field(): content_length=270
23:04:56 [24016]: DEBUG: <core> [core/parser/msg_parser.c:89]: get_hdr_field(): found end of header
23:04:56 [24016]: DEBUG: sanity [sanity.c:583]: check_cl(): check_cl passed
23:04:56 [24016]: DEBUG: sanity [sanity.c:595]: check_expires_value(): check_expires_value entered
23:04:56 [24016]: DEBUG: sanity [sanity.c:632]: check_expires_value(): no expires header found
23:04:56 [24016]: DEBUG: sanity [sanity.c:644]: check_proxy_require(): checking proxy require
23:04:56 [24016]: DEBUG: sanity [sanity.c:716]: check_proxy_require(): no proxy-require header found
23:04:56 [24016]: DEBUG: sanity [sanity.c:894]: check_digest_only(): Nothing to check
23:04:56 [24016]: DEBUG: sanity [sanity_mod.c:254]: w_sanity_check(): sanity checks result: 1
23:04:56 [24016]: DEBUG: pv [pv_core.c:1031]: pv_get_useragent(): no User-Agent header
23:04:56 [24016]: DEBUG: pv [pv_core.c:1031]: pv_get_useragent(): no User-Agent header
23:04:56 [24016]: DEBUG: pv [pv_core.c:1031]: pv_get_useragent(): no User-Agent header
23:04:56 [24016]: INFO: <script>: [CHECK_SOURCE_IP] - ID=isbcmq49mmdt5qba6tozy4q9ocamc55zoz43@10.18.5.64
23:04:56 [24016]: DEBUG: <script>: [CHECK_SOURCE_IP] - M=INVITE RURI=sip:444444656646820@2.2.2.2;user=phone F=sip:+33825462354@1.1.1.1;transport=udp;user=phone T=sip:444444656646820@2.2.2.2;transport=udp;user=phone IP=1.1.1.1 ID=isbcmq49mmdt5qba6tozy4q9ocamc55zoz43@10.18.5.64
23:04:56 [24016]: INFO: <script>: [CHECK_SOURCE_IP] FROM_PEER - ID=isbcmq49mmdt5qba6tozy4q9ocamc55zoz43@10.18.5.64
23:04:56 [24016]: DEBUG: <script>: [CHECK_SOURCE_IP] FROM_PEER - M=INVITE RURI=sip:444444656646820@2.2.2.2;user=phone F=sip:+33825462354@1.1.1.1;transport=udp;user=phone T=sip:444444656646820@2.2.2.2;transport=udp;user=phone IP=1.1.1.1 ID=isbcmq49mmdt5qba6tozy4q9ocamc55zoz43@10.18.5.64
23:04:56 [24016]: DEBUG: siputils [checks.c:120]: has_totag(): no totag
23:04:56 [24016]: DEBUG: outbound [outbound_mod.c:489]: use_outbound(): Analysing INVITE for outbound markers
23:04:56 [24016]: DEBUG: outbound [outbound_mod.c:409]: use_outbound_non_reg(): outbound is not supported and thus not used
23:04:56 [24016]: DEBUG: rr [loose.c:1226]: is_direction(): param ftag not found
23:04:56 [24016]: DEBUG: <script>: [MAIN] INVITE or REFER add RR - M=INVITE RURI=sip:444444656646820@2.2.2.2;user=phone F=sip:+33825462354@1.1.1.1;transport=udp;user=phone T=sip:444444656646820@2.2.2.2;transport=udp;user=phone IP=1.1.1.1 ID=isbcmq49mmdt5qba6tozy4q9ocamc55zoz43@10.18.5.64
23:04:56 [24016]: INFO: <script>: [MAIN] INVITE or REFER add RR - ID=isbcmq49mmdt5qba6tozy4q9ocamc55zoz43@10.18.5.64
23:04:56 [24016]: DEBUG: tm [t_lookup.c:1041]: t_check_msg(): msg (0x7fe49d15d2d0) id=23/24016 global id=22/24016 T start=0xffffffffffffffff
23:04:56 [24016]: DEBUG: tm [t_lookup.c:499]: t_lookup_request(): start searching: hash=39920, isACK=0
23:04:56 [24016]: DEBUG: tm [t_lookup.c:457]: matching_3261(): RFC3261 transaction matching failed - via branch [z9hG4bKete1rhqujwelu1nonl1toinrp]
23:04:56 [24016]: DEBUG: tm [t_lookup.c:682]: t_lookup_request(): no transaction found
23:04:56 [24016]: DEBUG: tm [t_lookup.c:1111]: t_check_msg(): msg (0x7fe49d15d2d0) id=23/24016 global id=23/24016 T end=(nil)
23:04:56 [24016]: INFO: <script>: [DISPATCH] - ID=isbcmq49mmdt5qba6tozy4q9ocamc55zoz43@10.18.5.64
23:04:56 [24016]: DEBUG: <script>: [DISPATCH] - M=INVITE RURI=sip:444444656646820@2.2.2.2;user=phone F=sip:+33825462354@1.1.1.1;transport=udp;user=phone T=sip:444444656646820@2.2.2.2;transport=udp;user=phone IP=1.1.1.1 ID=isbcmq49mmdt5qba6tozy4q9ocamc55zoz43@10.18.5.64
23:04:56 [24016]: DEBUG: dispatcher [dispatch.c:2054]: ds_manage_routes(): set [1]
23:04:56 [24016]: DEBUG: dispatcher [dispatch.c:2158]: ds_manage_routes(): using alg [4] hash [3]
23:04:56 [24016]: DEBUG: dispatcher [dispatch.c:2197]: ds_manage_routes(): selected [4-1-0/3] <sip:3.3.3.3:5060>
23:04:56 [24016]: DEBUG: dispatcher [dispatch.c:2218]: ds_manage_routes(): using first entry [1/3]
23:04:56 [24016]: DEBUG: dispatcher [dispatch.c:2259]: ds_manage_routes(): using entry [1/0]
23:04:56 [24016]: DEBUG: dispatcher [dispatch.c:2259]: ds_manage_routes(): using entry [1/1]
23:04:56 [24016]: DEBUG: dispatcher [dispatch.c:2259]: ds_manage_routes(): using entry [1/2]
23:04:56 [24016]: DEBUG: dispatcher [dispatch.c:2016]: ds_select_dst_limit(): selected target destinations: 4
23:04:56 [24016]: INFO: <script>: [DISPATCH] going to <sip:444444656646820@2.2.2.2;user=phone> via <sip:3.3.3.3:5060> - ID=isbcmq49mmdt5qba6tozy4q9ocamc55zoz43@10.18.5.64
23:04:56 [24016]: DEBUG: <script>: [DISPATCH] going to <sip:444444656646820@2.2.2.2;user=phone> via <sip:3.3.3.3:5060> - M=INVITE RURI=sip:444444656646820@2.2.2.2;user=phone F=sip:+33825462354@1.1.1.1;transport=udp;user=phone T=sip:444444656646820@2.2.2.2;transport=udp;user=phone IP=1.1.1.1 ID=isbcmq49mmdt5qba6tozy4q9ocamc55zoz43@10.18.5.64
23:04:56 [24016]: INFO: <script>: [IP_2_ACC_ID] - ID=isbcmq49mmdt5qba6tozy4q9ocamc55zoz43@10.18.5.64
23:04:56 [24016]: DEBUG: <script>: [IP_2_ACC_ID] - M=INVITE RURI=sip:444444656646820@2.2.2.2;user=phone F=sip:+33825462354@1.1.1.1;transport=udp;user=phone T=sip:444444656646820@2.2.2.2;transport=udp;user=phone IP=1.1.1.1 ID=isbcmq49mmdt5qba6tozy4q9ocamc55zoz43@10.18.5.64
23:04:56 [24016]: INFO: <script>: [IP_2_ACC_ID] 444444656646820 +33825462354 - ID=isbcmq49mmdt5qba6tozy4q9ocamc55zoz43@10.18.5.64
23:04:56 [24016]: DEBUG: <core> [core/parser/parse_addr_spec.c:864]: parse_addr_spec(): end of header reached, state=10
23:04:56 [24016]: DEBUG: <core> [core/parser/msg_parser.c:89]: get_hdr_field(): found end of header
23:04:56 [24016]: DEBUG: <core> [core/md5utils.c:67]: MD5StringArray(): MD5 calculated: 8cb4c7f17c1fcfc06e7098af82a59c0b
23:04:56 [24016]: DEBUG: exec [exec_hf.c:293]: print_hf_var(): SIP_HF_CONTENT_TYPE=application/sdp
23:04:56 [24016]: DEBUG: exec [exec_hf.c:293]: print_hf_var(): SIP_HF_CONTENT_LENGTH=270
23:04:56 [24016]: DEBUG: exec [exec_hf.c:293]: print_hf_var(): SIP_HF_P_EARLY_MEDIA=supported
23:04:56 [24016]: DEBUG: exec [exec_hf.c:293]: print_hf_var(): SIP_HF_P_ASSERTED_IDENTITY=<sip:+33825462354@1.1.1.1;transport=udp;user=phone>
23:04:56 [24016]: DEBUG: exec [exec_hf.c:293]: print_hf_var(): SIP_HF_MIN_SE=90
23:04:56 [24016]: DEBUG: exec [exec_hf.c:293]: print_hf_var(): SIP_HF_SESSION_EXPIRES=1800;refresher=uac
23:04:56 [24016]: DEBUG: exec [exec_hf.c:293]: print_hf_var(): SIP_HF_SUPPORTED=100rel,timer,histinfo
23:04:56 [24016]: DEBUG: exec [exec_hf.c:293]: print_hf_var(): SIP_HF_MAX_FORWARDS=64
23:04:56 [24016]: DEBUG: exec [exec_hf.c:293]: print_hf_var(): SIP_HF_CONTACT=<sip:+33825462354@1.1.1.1:5060;transport=udp;user=phone;Hpt=9038_16;CxtId=4;TRC=ffffffff-ffffffff>
23:04:56 [24016]: DEBUG: exec [exec_hf.c:293]: print_hf_var(): SIP_HF_ALLOW=INVITE,ACK,OPTIONS,BYE,CANCEL,INFO,PRACK,NOTIFY,MESSAGE,UPDATE
23:04:56 [24016]: DEBUG: exec [exec_hf.c:293]: print_hf_var(): SIP_HF_CSEQ=1 INVITE
23:04:56 [24016]: DEBUG: exec [exec_hf.c:293]: print_hf_var(): SIP_HF_TO="444444656646820"<sip:444444656646820@2.2.2.2;transport=udp;user=phone>
23:04:56 [24016]: DEBUG: exec [exec_hf.c:293]: print_hf_var(): SIP_HF_FROM="+33825462354"<sip:+33825462354@1.1.1.1;transport=udp;user=phone>;tag=456mb993-CC-1020-OFC-1324
23:04:56 [24016]: DEBUG: exec [exec_hf.c:293]: print_hf_var(): SIP_HF_CALLID=isbcmq49mmdt5qba6tozy4q9ocamc55zoz43@10.18.5.64
23:04:56 [24016]: DEBUG: exec [exec_hf.c:293]: print_hf_var(): SIP_HF_RECORD_ROUTE=<sip:1.1.1.1:5060;transport=udp;lr;Hpt=9038_16;CxtId=4;TRC=ffffffff-ffffffff;X-HwB2bUaCookie=10981>
23:04:56 [24016]: DEBUG: exec [exec_hf.c:293]: print_hf_var(): SIP_HF_VIA=SIP/2.0/UDP 1.1.1.1:5060;branch=z9hG4bKete1rhqujwelu1nonl1toinrp;Role=3;Hpt=9038_16
23:04:56 [24016]: DEBUG: exec [exec_mod.c:213]: w_exec_avp_helper(): executing [php /opt/acq/kamailio/IP2AccId.php 1.1.1.1:5060 444444656646820 +33825462354 +33825462354]
23:04:56 [24016]: DEBUG: <core> [main.c:883]: sig_usr(): SIGCHLD received: we do not worry about grand-children
23:04:56 [24016]: INFO: <script>: [IP_2_ACC_ID] loading Checking Account ID for IP address  = ' 1.1.1.1' - ID=isbcmq49mmdt5qba6tozy4q9ocamc55zoz43@10.18.5.64
23:04:56 [24016]: DEBUG: <script>: [IP_2_ACC_ID] loading Checking Account ID for IP address  = ' 1.1.1.1' - M=INVITE RURI=sip:444444656646820@2.2.2.2;user=phone F=sip:+33825462354@1.1.1.1;transport=udp;user=phone T=sip:444444656646820@2.2.2.2;transport=udp;user=phone IP=1.1.1.1 ID=isbcmq49mmdt5qba6tozy4q9ocamc55zoz43@10.18.5.64
23:04:56 [24016]: INFO: <script>: [IP_2_ACC_ID] loading TPFL = '4' - ID=isbcmq49mmdt5qba6tozy4q9ocamc55zoz43@10.18.5.64
23:04:56 [24016]: DEBUG: <script>: [IP_2_ACC_ID] loading TPFL = '4' - M=INVITE RURI=sip:444444656646820@2.2.2.2;user=phone F=sip:+33825462354@1.1.1.1;transport=udp;user=phone T=sip:444444656646820@2.2.2.2;transport=udp;user=phone IP=1.1.1.1 ID=isbcmq49mmdt5qba6tozy4q9ocamc55zoz43@10.18.5.64
23:04:56 [24016]: INFO: <script>: [IP_2_ACC_ID] loading TPF = '4444' - ID=isbcmq49mmdt5qba6tozy4q9ocamc55zoz43@10.18.5.64
23:04:56 [24016]: DEBUG: <script>: [IP_2_ACC_ID] loading TPF = '4444' - M=INVITE RURI=sip:444444656646820@2.2.2.2;user=phone F=sip:+33825462354@1.1.1.1;transport=udp;user=phone T=sip:444444656646820@2.2.2.2;transport=udp;user=phone IP=1.1.1.1 ID=isbcmq49mmdt5qba6tozy4q9ocamc55zoz43@10.18.5.64
23:04:56 [24016]: INFO: <script>: [IP_2_ACC_ID] loading AccId = '14884' - ID=isbcmq49mmdt5qba6tozy4q9ocamc55zoz43@10.18.5.64
23:04:56 [24016]: DEBUG: <script>: [IP_2_ACC_ID] loading AccId = '14884' - M=INVITE RURI=sip:444444656646820@2.2.2.2;user=phone F=sip:+33825462354@1.1.1.1;transport=udp;user=phone T=sip:444444656646820@2.2.2.2;transport=udp;user=phone IP=1.1.1.1 ID=isbcmq49mmdt5qba6tozy4q9ocamc55zoz43@10.18.5.64
23:04:56 [24016]: INFO: <script>: [IP_2_ACC_ID] loading Peer Operator = 'Deutsche Telekom EUR Premium' - ID=isbcmq49mmdt5qba6tozy4q9ocamc55zoz43@10.18.5.64
23:04:56 [24016]: DEBUG: <script>: [IP_2_ACC_ID] loading Peer Operator = 'Deutsche Telekom EUR Premium' - M=INVITE RURI=sip:444444656646820@2.2.2.2;user=phone F=sip:+33825462354@1.1.1.1;transport=udp;user=phone T=sip:444444656646820@2.2.2.2;transport=udp;user=phone IP=1.1.1.1 ID=isbcmq49mmdt5qba6tozy4q9ocamc55zoz43@10.18.5.64
23:04:56 [24016]: INFO: <script>: [IP_2_ACC_ID] loading SSWPeer = 'lb_AandB' - ID=isbcmq49mmdt5qba6tozy4q9ocamc55zoz43@10.18.5.64
23:04:56 [24016]: DEBUG: <script>: [IP_2_ACC_ID] loading SSWPeer = 'lb_AandB' - M=INVITE RURI=sip:444444656646820@2.2.2.2;user=phone F=sip:+33825462354@1.1.1.1;transport=udp;user=phone T=sip:444444656646820@2.2.2.2;transport=udp;user=phone IP=1.1.1.1 ID=isbcmq49mmdt5qba6tozy4q9ocamc55zoz43@10.18.5.64
23:04:56 [24016]: INFO: <script>: [IP_2_ACC_ID] loading Pattern = '/[^0-9a-zA-Z]/' - ID=isbcmq49mmdt5qba6tozy4q9ocamc55zoz43@10.18.5.64
23:04:56 [24016]: DEBUG: <script>: [IP_2_ACC_ID] loading Pattern = '/[^0-9a-zA-Z]/' - M=INVITE RURI=sip:444444656646820@2.2.2.2;user=phone F=sip:+33825462354@1.1.1.1;transport=udp;user=phone T=sip:444444656646820@2.2.2.2;transport=udp;user=phone IP=1.1.1.1 ID=isbcmq49mmdt5qba6tozy4q9ocamc55zoz43@10.18.5.64
23:04:56 [24016]: INFO: <script>: [IP_2_ACC_ID] loading Replacement = '' - ID=isbcmq49mmdt5qba6tozy4q9ocamc55zoz43@10.18.5.64
23:04:56 [24016]: DEBUG: <script>: [IP_2_ACC_ID] loading Replacement = '' - M=INVITE RURI=sip:444444656646820@2.2.2.2;user=phone F=sip:+33825462354@1.1.1.1;transport=udp;user=phone T=sip:444444656646820@2.2.2.2;transport=udp;user=phone IP=1.1.1.1 ID=isbcmq49mmdt5qba6tozy4q9ocamc55zoz43@10.18.5.64
23:04:56 [24016]: INFO: <script>: [IP_2_ACC_ID] loading Bnum = '44656646820' - ID=isbcmq49mmdt5qba6tozy4q9ocamc55zoz43@10.18.5.64
23:04:56 [24016]: DEBUG: <script>: [IP_2_ACC_ID] loading Bnum = '44656646820' - M=INVITE RURI=sip:444444656646820@2.2.2.2;user=phone F=sip:+33825462354@1.1.1.1;transport=udp;user=phone T=sip:444444656646820@2.2.2.2;transport=udp;user=phone IP=1.1.1.1 ID=isbcmq49mmdt5qba6tozy4q9ocamc55zoz43@10.18.5.64
23:04:56 [24016]: INFO: <script>: [IP_2_ACC_ID] loading FCN = '44656646820' - ID=isbcmq49mmdt5qba6tozy4q9ocamc55zoz43@10.18.5.64
23:04:56 [24016]: DEBUG: <script>: [IP_2_ACC_ID] loading FCN = '44656646820' - M=INVITE RURI=sip:444444656646820@2.2.2.2;user=phone F=sip:+33825462354@1.1.1.1;transport=udp;user=phone T=sip:444444656646820@2.2.2.2;transport=udp;user=phone IP=1.1.1.1 ID=isbcmq49mmdt5qba6tozy4q9ocamc55zoz43@10.18.5.64
23:04:56 [24016]: INFO: <script>: [IP_2_ACC_ID] loading PatternA = '/[^0-9a-zA-Z]/' - ID=isbcmq49mmdt5qba6tozy4q9ocamc55zoz43@10.18.5.64
23:04:56 [24016]: DEBUG: <script>: [IP_2_ACC_ID] loading PatternA = '/[^0-9a-zA-Z]/' - M=INVITE RURI=sip:444444656646820@2.2.2.2;user=phone F=sip:+33825462354@1.1.1.1;transport=udp;user=phone T=sip:444444656646820@2.2.2.2;transport=udp;user=phone IP=1.1.1.1 ID=isbcmq49mmdt5qba6tozy4q9ocamc55zoz43@10.18.5.64
23:04:56 [24016]: INFO: <script>: [IP_2_ACC_ID] loading ReplacementA = '' - ID=isbcmq49mmdt5qba6tozy4q9ocamc55zoz43@10.18.5.64
23:04:56 [24016]: DEBUG: <script>: [IP_2_ACC_ID] loading ReplacementA = '' - M=INVITE RURI=sip:444444656646820@2.2.2.2;user=phone F=sip:+33825462354@1.1.1.1;transport=udp;user=phone T=sip:444444656646820@2.2.2.2;transport=udp;user=phone IP=1.1.1.1 ID=isbcmq49mmdt5qba6tozy4q9ocamc55zoz43@10.18.5.64
23:04:56 [24016]: INFO: <script>: [IP_2_ACC_ID] loading FCID = '33825462354' - ID=isbcmq49mmdt5qba6tozy4q9ocamc55zoz43@10.18.5.64
23:04:56 [24016]: DEBUG: <script>: [IP_2_ACC_ID] loading FCID = '33825462354' - M=INVITE RURI=sip:444444656646820@2.2.2.2;user=phone F=sip:+33825462354@1.1.1.1;transport=udp;user=phone T=sip:444444656646820@2.2.2.2;transport=udp;user=phone IP=1.1.1.1 ID=isbcmq49mmdt5qba6tozy4q9ocamc55zoz43@10.18.5.64
23:04:56 [24016]: INFO: <script>: [IP_2_ACC_ID] Add header X-ACQ-FromGw: 2.2.2.2 - ID=isbcmq49mmdt5qba6tozy4q9ocamc55zoz43@10.18.5.64
23:04:56 [24016]: INFO: <script>: [IP_2_ACC_ID] Add header X-ACQ-FromSIP: 1.1.1.1:5060 - ID=isbcmq49mmdt5qba6tozy4q9ocamc55zoz43@10.18.5.64
23:04:56 [24016]: INFO: <script>: [IP_2_ACC_ID] Add header X-ACQ-FromAccId: 14884 - ID=isbcmq49mmdt5qba6tozy4q9ocamc55zoz43@10.18.5.64
23:04:56 [24016]: DEBUG: <script>: [IP_2_ACC_ID] Add header X-ACQ-FromGw: 2.2.2.2 - M=INVITE RURI=sip:444444656646820@2.2.2.2;user=phone F=sip:+33825462354@1.1.1.1;transport=udp;user=phone T=sip:444444656646820@2.2.2.2;transport=udp;user=phone IP=1.1.1.1 ID=isbcmq49mmdt5qba6tozy4q9ocamc55zoz43@10.18.5.64
23:04:56 [24016]: DEBUG: <script>: [IP_2_ACC_ID] Add header X-ACQ-FromSIP: 1.1.1.1:5060 - M=INVITE RURI=sip:444444656646820@2.2.2.2;user=phone F=sip:+33825462354@1.1.1.1;transport=udp;user=phone T=sip:444444656646820@2.2.2.2;transport=udp;user=phone IP=1.1.1.1 ID=isbcmq49mmdt5qba6tozy4q9ocamc55zoz43@10.18.5.64
23:04:56 [24016]: DEBUG: <script>: [IP_2_ACC_ID] Add header X-ACQ-FromAccId: 14884 - M=INVITE RURI=sip:444444656646820@2.2.2.2;user=phone F=sip:+33825462354@1.1.1.1;transport=udp;user=phone T=sip:444444656646820@2.2.2.2;transport=udp;user=phone IP=1.1.1.1 ID=isbcmq49mmdt5qba6tozy4q9ocamc55zoz43@10.18.5.64
23:04:56 [24016]: INFO: <script>: [IP_2_ACC_ID] Rewrite URI with domain 3.3.3.3 and port 5060 - ID=isbcmq49mmdt5qba6tozy4q9ocamc55zoz43@10.18.5.64
23:04:56 [24016]: DEBUG: <script>: [IP_2_ACC_ID] Rewrite URI with domain 3.3.3.3 and port 5060 - M=INVITE RURI=sip:44656646820@3.3.3.3:5060;user=phone F=sip:+33825462354@1.1.1.1;transport=udp;user=phone T=sip:444444656646820@2.2.2.2;transport=udp;user=phone IP=1.1.1.1 ID=isbcmq49mmdt5qba6tozy4q9ocamc55zoz43@10.18.5.64
23:04:56 [24016]: DEBUG: uac [uac.c:524]: ki_replace_to(): dsp=(nil) (len=0) , uri=0x7ffc18ea3160 (len=35)
23:04:56 [24016]: DEBUG: uac [replace.c:361]: replace_uri(): uri to replace [sip:444444656646820@2.2.2.2;transport=udp;user=phone]
23:04:56 [24016]: DEBUG: uac [replace.c:362]: replace_uri(): replacement uri is [sip:44656646820@3.3.3.3:5060]
23:04:56 [24016]: INFO: <script>: [IP_2_ACC_ID] Rewrite header To with <sip:44656646820@3.3.3.3:5060> - ID=isbcmq49mmdt5qba6tozy4q9ocamc55zoz43@10.18.5.64
23:04:56 [24016]: DEBUG: <script>: [IP_2_ACC_ID] Rewrite header To with <sip:44656646820@3.3.3.3:5060> - M=INVITE RURI=sip:44656646820@3.3.3.3:5060;user=phone F=sip:+33825462354@1.1.1.1;transport=udp;user=phone T=sip:444444656646820@2.2.2.2;transport=udp;user=phone IP=1.1.1.1 ID=isbcmq49mmdt5qba6tozy4q9ocamc55zoz43@10.18.5.64
23:04:56 [24016]: DEBUG: <core> [core/re.c:436]: subst_run(): running. r=0
23:04:56 [24016]: DEBUG: <core> [core/re.c:455]: subst_run(): matched (277, 109): [From: "+33825462354"<sip:+33825462354@1.1.1.1;transport=udp;user=phone>;tag=456mb993-CC-1020-OFC-1324#015]
23:04:56 [24016]: DEBUG: <core> [core/re.c:436]: subst_run(): running. r=1
23:04:56 [24016]: DEBUG: textops [textops.c:1169]: subst_helper_f(): textops: replacing at offset 339 [From: "+33825462354"<sip:+33825462354@1.1.1.1;transport=udp;user=phone>;tag=456mb993-CC-1020-OFC-1324#015] with [From: "+33825462354"<sip:33825462354@2.2.2.2;transport=udp;user=phone>;tag=456mb993-CC-1020-OFC-1324#015]
23:04:56 [24016]: DEBUG: textops [textops.c:1188]: subst_helper_f(): lst was 0x7fe49d15dee8
23:04:56 [24016]: INFO: <script>: [IP_2_ACC_ID] FCID Rewrite header From with 33825462354@2.2.2.2 - ID=isbcmq49mmdt5qba6tozy4q9ocamc55zoz43@10.18.5.64
23:04:56 [24016]: DEBUG: <script>: [IP_2_ACC_ID] FCID Rewrite header From with 33825462354@2.2.2.2 - M=INVITE RURI=sip:44656646820@3.3.3.3:5060;user=phone F=sip:+33825462354@1.1.1.1;transport=udp;user=phone T=sip:444444656646820@2.2.2.2;transport=udp;user=phone IP=1.1.1.1 ID=isbcmq49mmdt5qba6tozy4q9ocamc55zoz43@10.18.5.64
23:04:56 [24016]: DEBUG: <core> [core/re.c:436]: subst_run(): running. r=0
23:04:56 [24016]: DEBUG: <core> [core/re.c:455]: subst_run(): matched (558, 115): [Contact: <sip:+33825462354@1.1.1.1:5060;transport=udp;user=phone;Hpt=9038_16;CxtId=4;TRC=ffffffff-ffffffff>#015]
23:04:56 [24016]: DEBUG: <core> [core/re.c:436]: subst_run(): running. r=1
23:04:56 [24016]: DEBUG: textops [textops.c:1169]: subst_helper_f(): textops: replacing at offset 620 [Contact: <sip:+33825462354@1.1.1.1:5060;transport=udp;user=phone;Hpt=9038_16;CxtId=4;TRC=ffffffff-ffffffff>#015] with [Contact: <sip:33825462354@1.1.1.1:5060;transport=udp;user=phone;Hpt=9038_16;CxtId=4;TRC=ffffffff-ffffffff>#015]
23:04:56 [24016]: DEBUG: textops [textops.c:1188]: subst_helper_f(): lst was 0x7fe49d15cb90
23:04:56 [24016]: INFO: <script>: [IP_2_ACC_ID] FCID Rewrite header Contact with 33825462354 - ID=isbcmq49mmdt5qba6tozy4q9ocamc55zoz43@10.18.5.64
23:04:56 [24016]: DEBUG: <script>: [IP_2_ACC_ID] FCID Rewrite header Contact with 33825462354 - M=INVITE RURI=sip:44656646820@3.3.3.3:5060;user=phone F=sip:+33825462354@1.1.1.1;transport=udp;user=phone T=sip:444444656646820@2.2.2.2;transport=udp;user=phone IP=1.1.1.1 ID=isbcmq49mmdt5qba6tozy4q9ocamc55zoz43@10.18.5.64
23:04:56 [24016]: INFO: <script>: [RELAY] - M=INVITE IP=1.1.1.1 ID=isbcmq49mmdt5qba6tozy4q9ocamc55zoz43@10.18.5.64
23:04:56 [24016]: DEBUG: <script>: [RELAY] - M=INVITE RURI=sip:44656646820@3.3.3.3:5060;user=phone F=sip:+33825462354@1.1.1.1;transport=udp;user=phone T=sip:444444656646820@2.2.2.2;transport=udp;user=phone IP=1.1.1.1 ID=isbcmq49mmdt5qba6tozy4q9ocamc55zoz43@10.18.5.64
23:04:56 [24016]: DEBUG: tm [t_lookup.c:1344]: t_newtran(): msg (0x7fe49d15d2d0) id=23/24016 global id=23/24016 T start=(nil)
23:04:56 [24016]: DEBUG: tm [t_lookup.c:499]: t_lookup_request(): start searching: hash=39920, isACK=0
23:04:56 [24016]: DEBUG: tm [t_lookup.c:457]: matching_3261(): RFC3261 transaction matching failed - via branch [z9hG4bKete1rhqujwelu1nonl1toinrp]
23:04:56 [24016]: DEBUG: tm [t_lookup.c:682]: t_lookup_request(): no transaction found
23:04:56 [24016]: DEBUG: tm [t_hooks.c:348]: run_reqin_callbacks_internal(): trans=0x7fe477a75c68, callback type 1, id 0 entered
23:04:56 [24016]: DEBUG: siptrace [siptrace.c:982]: trace_onreq_in(): trace off...
23:04:56 [24016]: DEBUG: <core> [core/md5utils.c:67]: MD5StringArray(): MD5 calculated: 8cb4c7f17c1fcfc06e7098af82a59c0b
23:04:56 [24016]: DEBUG: tm [t_funcs.c:327]: t_relay_to(): new INVITE
23:04:56 [24016]: DEBUG: <core> [core/msg_translator.c:162]: check_via_address(): (1.1.1.1, 1.1.1.1, 0)
23:04:56 [24016]: DEBUG: <core> [core/parser/msg_parser.c:620]: parse_msg(): SIP Reply  (status):
23:04:56 [24016]: DEBUG: <core> [core/parser/msg_parser.c:622]: parse_msg():  version: <SIP/2.0>
23:04:56 [24016]: DEBUG: <core> [core/parser/msg_parser.c:624]: parse_msg():  status:  <100>
23:04:56 [24016]: DEBUG: <core> [core/parser/msg_parser.c:626]: parse_msg():  reason:  <trying -- your call is important to us>
23:04:56 [24016]: DEBUG: <core> [core/parser/parse_via.c:1303]: parse_via_param(): Found param type 232, <branch> = <z9hG4bKete1rhqujwelu1nonl1toinrp>; state=6
23:04:56 [24016]: DEBUG: <core> [core/parser/parse_via.c:1303]: parse_via_param(): Found param type 253, <Role> = <3>; state=6
23:04:56 [24016]: DEBUG: <core> [core/parser/parse_via.c:1303]: parse_via_param(): Found param type 253, <Hpt> = <9038_16>; state=16
23:04:56 [24016]: DEBUG: <core> [core/parser/parse_via.c:2639]: parse_via(): end of header reached, state=5
23:04:56 [24016]: DEBUG: <core> [core/parser/msg_parser.c:498]: parse_headers(): Via found, flags=2
23:04:56 [24016]: DEBUG: <core> [core/parser/msg_parser.c:500]: parse_headers(): this is the first via
23:04:56 [24016]: DEBUG: <core> [core/parser/parse_addr_spec.c:864]: parse_addr_spec(): end of header reached, state=10
23:04:56 [24016]: DEBUG: <core> [core/parser/msg_parser.c:171]: get_hdr_field(): <To> [80]; uri=[sip:444444656646820@2.2.2.2;transport=udp;user=phone]
23:04:56 [24016]: DEBUG: <core> [core/parser/msg_parser.c:174]: get_hdr_field(): to body ["444444656646820"<sip:444444656646820@2.2.2.2;transport=udp;user=phone>#015#012], to tag []
23:04:56 [24016]: DEBUG: <core> [core/parser/msg_parser.c:152]: get_hdr_field(): cseq <CSeq>: <1> <INVITE>
23:04:56 [24016]: DEBUG: <core> [core/parser/msg_parser.c:185]: get_hdr_field(): content_length=0
23:04:56 [24016]: DEBUG: <core> [core/parser/msg_parser.c:89]: get_hdr_field(): found end of header
23:04:56 [24016]: DEBUG: <core> [core/parser/parse_addr_spec.c:185]: parse_to_param(): add param: tag=456mb993-CC-1020-OFC-1324
23:04:56 [24016]: DEBUG: <core> [core/parser/parse_addr_spec.c:864]: parse_addr_spec(): end of header reached, state=29
23:04:56 [24016]: DEBUG: siptrace [siptrace_hep.c:498]: pipport2su(): the port string is 5060
23:04:56 [24016]: DEBUG: siptrace [siptrace_hep.c:498]: pipport2su(): the port string is 5060
23:04:56 [24016]: DEBUG: <core> [core/proxy.c:264]: mk_proxy(): doing DNS lookup...
23:04:56 [24016]: DEBUG: siptrace [siptrace_hep.c:183]: trace_send_hep3_duplicate(): setting up the socket_info
23:04:56 [24016]: DEBUG: tm [t_reply.c:596]: _reply_light(): reply sent out. buf=0x7fe49d160268: SIP/2.0 100 trying -..., shmem=0x7fe477a7b368: SIP/2.0 100 trying -
23:04:56 [24016]: DEBUG: tm [t_reply.c:607]: _reply_light(): finished
23:04:56 [24016]: DEBUG: <core> [core/msg_translator.c:162]: check_via_address(): (1.1.1.1, 1.1.1.1, 0)
23:04:56 [24016]: INFO: <script>: [onsend_route] Sending INVITE ID=isbcmq49mmdt5qba6tozy4q9ocamc55zoz43@10.18.5.64
23:04:56 [24016]: DEBUG: <script>: [onsend_route] Sending INVITE to RURI=sip:44656646820@3.3.3.3:5060;user=phone DURI=sip:3.3.3.3:5060 ID=isbcmq49mmdt5qba6tozy4q9ocamc55zoz43@10.18.5.64
23:04:56 [24016]: DEBUG: <core> [core/parser/msg_parser.c:610]: parse_msg(): SIP Request:
23:04:56 [24016]: DEBUG: <core> [core/parser/msg_parser.c:612]: parse_msg():  method:  <INVITE>
23:04:56 [24016]: DEBUG: <core> [core/parser/msg_parser.c:614]: parse_msg():  uri:     <sip:44656646820@3.3.3.3:5060;user=phone>
23:04:56 [24016]: DEBUG: <core> [core/parser/msg_parser.c:616]: parse_msg():  version: <SIP/2.0>
23:04:56 [24016]: DEBUG: <core> [core/parser/parse_via.c:1303]: parse_via_param(): Found param type 232, <branch> = <z9hG4bK0fb9.8cb4c7f17c1fcfc06e7098af82a59c0b.0>; state=16
23:04:56 [24016]: DEBUG: <core> [core/parser/parse_via.c:2639]: parse_via(): end of header reached, state=5
23:04:56 [24016]: DEBUG: <core> [core/parser/msg_parser.c:498]: parse_headers(): Via found, flags=2
23:04:56 [24016]: DEBUG: <core> [core/parser/msg_parser.c:500]: parse_headers(): this is the first via
23:04:56 [24016]: DEBUG: <core> [core/parser/parse_via.c:1303]: parse_via_param(): Found param type 232, <branch> = <z9hG4bKete1rhqujwelu1nonl1toinrp>; state=6
23:04:56 [24016]: DEBUG: <core> [core/parser/parse_via.c:1303]: parse_via_param(): Found param type 253, <Role> = <3>; state=6
23:04:56 [24016]: DEBUG: <core> [core/parser/parse_via.c:1303]: parse_via_param(): Found param type 253, <Hpt> = <9038_16>; state=16
23:04:56 [24016]: DEBUG: <core> [core/parser/parse_via.c:2639]: parse_via(): end of header reached, state=5
23:04:56 [24016]: DEBUG: <core> [core/parser/msg_parser.c:498]: parse_headers(): Via found, flags=4
23:04:56 [24016]: DEBUG: <core> [core/parser/msg_parser.c:511]: parse_headers(): this is the second via
23:04:56 [24016]: DEBUG: <core> [core/parser/parse_addr_spec.c:864]: parse_addr_spec(): end of header reached, state=10
23:04:56 [24016]: DEBUG: <core> [core/parser/msg_parser.c:171]: get_hdr_field(): <To> [56]; uri=[sip:44656646820@3.3.3.3:5060]
23:04:56 [24016]: DEBUG: <core> [core/parser/msg_parser.c:174]: get_hdr_field(): to body ["444444656646820"<sip:44656646820@3.3.3.3:5060>#015#012], to tag []
23:04:56 [24016]: DEBUG: <core> [core/parser/msg_parser.c:152]: get_hdr_field(): cseq <CSeq>: <1> <INVITE>
23:04:56 [24016]: DEBUG: <core> [core/parser/msg_parser.c:185]: get_hdr_field(): content_length=270
23:04:56 [24016]: DEBUG: <core> [core/parser/msg_parser.c:89]: get_hdr_field(): found end of header
23:04:56 [24016]: DEBUG: <core> [core/parser/parse_addr_spec.c:185]: parse_to_param(): add param: tag=456mb993-CC-1020-OFC-1324
23:04:56 [24016]: DEBUG: <core> [core/parser/parse_addr_spec.c:864]: parse_addr_spec(): end of header reached, state=29
23:04:56 [24016]: DEBUG: topos [tps_msg.c:934]: tps_request_sent(): handling outgoing request (0, 0)
23:04:56 [24016]: DEBUG: topos [tps_msg.c:376]: tps_pack_message(): compacted headers - x_via1: [SIP/2.0/UDP 2.2.2.2;branch=z9hG4bK0fb9.8cb4c7f17c1fcfc06e7098af82a59c0b.0](80) - x_via2: [SIP/2.0/UDP 1.1.1.1:5060;branch=z9hG4bKete1rhqujwelu1nonl1toinrp;Role=3;Hpt=9038_16](90) - x_vbranch1: [z9hG4bK0fb9.8cb4c7f17c1fcfc06e7098af82a59c0b.0](46)
23:04:56 [24016]: DEBUG: topos [tps_msg.c:435]: tps_pack_message(): single record routing by proxy
23:04:56 [24016]: DEBUG: topos [tps_msg.c:485]: tps_pack_message(): compacted headers - a_rr: [<sip:1.1.1.1:5060;transport=udp;lr;Hpt=9038_16;CxtId=4;TRC=ffffffff-ffffffff;X-HwB2bUaCookie=10981>](106) - b_rr: [](0) - s_rr: [<sip:2.2.2.2;lr=on;ftag=456mb993-CC-1020-OFC-1324>](57)
23:04:56 [24016]: DEBUG: topos [tps_msg.c:490]: tps_pack_message(): compacted headers - as_contact: [sip:2.2.2.2;lr=on;ftag=456mb993-CC-1020-OFC-1324](55) - bs_contact: [sip:2.2.2.2;lr=on;ftag=456mb993-CC-1020-OFC-1324](55)
23:04:56 [24016]: DEBUG: topos [tps_storage.c:126]: tps_storage_lock_get(): tps lock get: 441
23:04:56 [24016]: DEBUG: ndb_redis [redis_client.c:391]: redisc_get_server(): Hash 2100282977 (srv8)
23:04:56 [24016]: DEBUG: ndb_redis [redis_client.c:395]: redisc_get_server(): Entry 2100282977 (srv8)
23:04:56 [24016]: DEBUG: topos_redis [topos_redis_storage.c:764]: tps_redis_load_branch(): loading branch record for [b:x:z9hG4bK0fb9.8cb4c7f17c1fcfc06e7098af82a59c0b.0]
23:04:56 [24016]: DEBUG: ndb_redis [redis_client.c:1043]: redisc_exec_argv(): rsrv->ctxRedis = 0x5580680a0cd0
23:04:56 [24016]: DEBUG: topos_redis [topos_redis_storage.c:782]: tps_redis_load_branch(): hmap with key [b:x:z9hG4bK0fb9.8cb4c7f17c1fcfc06e7098af82a59c0b.0] not found
23:04:56 [24016]: DEBUG: <core> [sruid.c:182]: sruid_next(): new sruid is [tpsh-5e87a4a2-5dd0-2] (2 / 20)
23:04:56 [24016]: DEBUG: topos [tps_storage.c:391]: tps_storage_link_msg(): downstream: yes - acontact: [sip:33825462354@1.1.1.1:5060;transport=udp;user=phone;Hpt=9038_16;CxtId=4;TRC=ffffffff-ffffffff] - bcontact: []
23:04:56 [24016]: DEBUG: ndb_redis [redis_client.c:391]: redisc_get_server(): Hash 2100282977 (srv8)
23:04:56 [24016]: DEBUG: ndb_redis [redis_client.c:395]: redisc_get_server(): Entry 2100282977 (srv8)
23:04:56 [24016]: DEBUG: ndb_redis [redis_client.c:1043]: redisc_exec_argv(): rsrv->ctxRedis = 0x5580680a0cd0
23:04:56 [24016]: DEBUG: topos_redis [topos_redis_storage.c:253]: tps_redis_insert_dialog(): inserted dialog record for [d:z:atpsh-5e87a4a2-5dd0-2] with argc 28
23:04:56 [24016]: DEBUG: ndb_redis [redis_client.c:1043]: redisc_exec_argv(): rsrv->ctxRedis = 0x5580680a0cd0
23:04:56 [24016]: DEBUG: topos_redis [topos_redis_storage.c:282]: tps_redis_insert_dialog(): expire 10800 set on dialog record for [d:z:atpsh-5e87a4a2-5dd0-2] with argc 3
23:04:56 [24016]: DEBUG: ndb_redis [redis_client.c:391]: redisc_get_server(): Hash 2100282977 (srv8)
23:04:56 [24016]: DEBUG: ndb_redis [redis_client.c:395]: redisc_get_server(): Entry 2100282977 (srv8)
23:04:56 [24016]: DEBUG: ndb_redis [redis_client.c:1043]: redisc_exec_argv(): rsrv->ctxRedis = 0x5580680a0cd0
23:04:56 [24016]: DEBUG: topos_redis [topos_redis_storage.c:491]: tps_redis_insert_branch(): inserting branch record for [b:x:z9hG4bK0fb9.8cb4c7f17c1fcfc06e7098af82a59c0b.0] with argc 34
23:04:56 [24016]: DEBUG: ndb_redis [redis_client.c:1043]: redisc_exec_argv(): rsrv->ctxRedis = 0x5580680a0cd0
23:04:56 [24016]: DEBUG: topos_redis [topos_redis_storage.c:521]: tps_redis_insert_branch(): expire 180 set on branch record for [b:x:z9hG4bK0fb9.8cb4c7f17c1fcfc06e7098af82a59c0b.0] with argc 3
23:04:56 [24016]: DEBUG: topos [tps_msg.c:182]: tps_add_headers(): adding to headers(1) - [Via: SIP/2.0/UDP 2.2.2.2;branch=z9hG4bK0fb9.8cb4c7f17c1fcfc06e7098af82a59c0b.0#015#012]
23:04:56 [24016]: DEBUG: topos [tps_msg.c:182]: tps_add_headers(): adding to headers(0) - [Contact: <sip:btpsh-5e87a4a2-5dd0-2@2.2.2.2>#015#012]
23:04:56 [24016]: DEBUG: topos [tps_storage.c:138]: tps_storage_lock_release(): tps lock release: 441
23:04:56 [24016]: DEBUG: siptrace [siptrace_hep.c:498]: pipport2su(): the port string is 5060
23:04:56 [24016]: DEBUG: siptrace [siptrace_hep.c:498]: pipport2su(): the port string is 5060
23:04:56 [24016]: DEBUG: <core> [core/proxy.c:264]: mk_proxy(): doing DNS lookup...
23:04:56 [24016]: DEBUG: siptrace [siptrace_hep.c:183]: trace_send_hep3_duplicate(): setting up the socket_info
23:04:56 [24016]: DEBUG: tm [t_funcs.c:375]: t_relay_to(): new transaction forwarded
23:04:56 [24016]: DEBUG: <core> [core/receive.c:354]: receive_msg(): request-route executed in: 35982 usec
23:04:56 [24016]: DEBUG: <core> [core/usr_avp.c:636]: destroy_avp_list(): destroying list (nil)
23:04:56 [24016]: DEBUG: <core> [core/usr_avp.c:636]: destroy_avp_list(): destroying list (nil)
23:04:56 [24016]: DEBUG: <core> [core/usr_avp.c:636]: destroy_avp_list(): destroying list (nil)
23:04:56 [24016]: DEBUG: <core> [core/usr_avp.c:636]: destroy_avp_list(): destroying list (nil)
23:04:56 [24016]: DEBUG: <core> [core/usr_avp.c:636]: destroy_avp_list(): destroying list (nil)
23:04:56 [24016]: DEBUG: <core> [core/usr_avp.c:636]: destroy_avp_list(): destroying list (nil)
23:04:56 [24016]: DEBUG: <core> [core/xavp.c:495]: xavp_destroy_list(): destroying xavp list (nil)
23:04:56 [24016]: DEBUG: <core> [core/receive.c:458]: receive_msg(): cleaning up
23:04:56 [24015]: DEBUG: <core> [core/udp_server.c:491]: udp_rcv_loop(): received on udp socket: (106/100/444) [[SIP/2.0 100 trying -- your call is important to us 0D  0A Via: SIP/2.0/UDP 2.2.2.2;branch=z9hG4bK0f]]
23:04:56 [24015]: DEBUG: <core> [core/receive.c:128]: sip_check_fline(): first line indicates a SIP reply
23:04:56 [24015]: DEBUG: siptrace [siptrace_hep.c:498]: pipport2su(): the port string is 5060
23:04:56 [24015]: DEBUG: siptrace [siptrace_hep.c:498]: pipport2su(): the port string is 5060
23:04:56 [24015]: DEBUG: <core> [core/proxy.c:264]: mk_proxy(): doing DNS lookup...
23:04:56 [24015]: DEBUG: siptrace [siptrace_hep.c:183]: trace_send_hep3_duplicate(): setting up the socket_info
23:04:56 [24015]: DEBUG: <core> [core/parser/msg_parser.c:620]: parse_msg(): SIP Reply  (status):
23:04:56 [24015]: DEBUG: <core> [core/parser/msg_parser.c:622]: parse_msg():  version: <SIP/2.0>
23:04:56 [24015]: DEBUG: <core> [core/parser/msg_parser.c:624]: parse_msg():  status:  <100>
23:04:56 [24015]: DEBUG: <core> [core/parser/msg_parser.c:626]: parse_msg():  reason:  <trying -- your call is important to us>
23:04:56 [24015]: DEBUG: <core> [core/parser/parse_via.c:1303]: parse_via_param(): Found param type 232, <branch> = <z9hG4bK0fb9.8cb4c7f17c1fcfc06e7098af82a59c0b.0>; state=16
23:04:56 [24015]: DEBUG: <core> [core/parser/parse_via.c:2639]: parse_via(): end of header reached, state=5
23:04:56 [24015]: DEBUG: <core> [core/parser/msg_parser.c:498]: parse_headers(): Via found, flags=2
23:04:56 [24015]: DEBUG: <core> [core/parser/msg_parser.c:500]: parse_headers(): this is the first via
23:04:56 [24015]: DEBUG: <core> [core/parser/parse_addr_spec.c:864]: parse_addr_spec(): end of header reached, state=10
23:04:56 [24015]: DEBUG: <core> [core/parser/msg_parser.c:171]: get_hdr_field(): <To> [56]; uri=[sip:44656646820@3.3.3.3:5060]
23:04:56 [24015]: DEBUG: <core> [core/parser/msg_parser.c:174]: get_hdr_field(): to body ["444444656646820"<sip:44656646820@3.3.3.3:5060>#015#012], to tag []
23:04:56 [24015]: DEBUG: <core> [core/parser/msg_parser.c:152]: get_hdr_field(): cseq <CSeq>: <1> <INVITE>
23:04:56 [24015]: DEBUG: <core> [core/parser/msg_parser.c:185]: get_hdr_field(): content_length=0
23:04:56 [24015]: DEBUG: <core> [core/parser/msg_parser.c:89]: get_hdr_field(): found end of header
23:04:56 [24015]: DEBUG: <core> [core/parser/parse_addr_spec.c:185]: parse_to_param(): add param: tag=456mb993-CC-1020-OFC-1324
23:04:56 [24015]: DEBUG: <core> [core/parser/parse_addr_spec.c:864]: parse_addr_spec(): end of header reached, state=29
23:04:56 [24015]: DEBUG: <core> [core/parser/msg_parser.c:620]: parse_msg(): SIP Reply  (status):
23:04:56 [24015]: DEBUG: <core> [core/parser/msg_parser.c:622]: parse_msg():  version: <SIP/2.0>
23:04:56 [24015]: DEBUG: <core> [core/parser/msg_parser.c:624]: parse_msg():  status:  <100>
23:04:56 [24015]: DEBUG: <core> [core/parser/msg_parser.c:626]: parse_msg():  reason:  <trying -- your call is important to us>
23:04:56 [24015]: DEBUG: <core> [core/parser/parse_via.c:1303]: parse_via_param(): Found param type 232, <branch> = <z9hG4bK0fb9.8cb4c7f17c1fcfc06e7098af82a59c0b.0>; state=16
23:04:56 [24015]: DEBUG: <core> [core/parser/parse_via.c:2639]: parse_via(): end of header reached, state=5
23:04:56 [24015]: DEBUG: <core> [core/parser/msg_parser.c:498]: parse_headers(): Via found, flags=2
23:04:56 [24015]: DEBUG: <core> [core/parser/msg_parser.c:500]: parse_headers(): this is the first via
23:04:56 [24015]: DEBUG: <core> [core/parser/parse_addr_spec.c:864]: parse_addr_spec(): end of header reached, state=10
23:04:56 [24015]: DEBUG: <core> [core/parser/msg_parser.c:171]: get_hdr_field(): <To> [56]; uri=[sip:44656646820@3.3.3.3:5060]
23:04:56 [24015]: DEBUG: <core> [core/parser/msg_parser.c:174]: get_hdr_field(): to body ["444444656646820"<sip:44656646820@3.3.3.3:5060>#015#012], to tag []
23:04:56 [24015]: DEBUG: <core> [core/parser/msg_parser.c:152]: get_hdr_field(): cseq <CSeq>: <1> <INVITE>
23:04:56 [24015]: DEBUG: <core> [core/receive.c:241]: receive_msg(): --- received sip message - reply - call-id: [isbcmq49mmdt5qba6tozy4q9ocamc55zoz43@10.18.5.64] - cseq: [1 INVITE]
23:04:56 [24015]: INFO: <script>: [reply_route] - rs=100 trying -- your call is important to us IP=3.3.3.3 ID=isbcmq49mmdt5qba6tozy4q9ocamc55zoz43@10.18.5.64
23:04:56 [24015]: DEBUG: <core> [core/parser/parse_addr_spec.c:185]: parse_to_param(): add param: tag=456mb993-CC-1020-OFC-1324
23:04:56 [24015]: DEBUG: <core> [core/parser/parse_addr_spec.c:864]: parse_addr_spec(): end of header reached, state=29
23:04:56 [24015]: DEBUG: <script>: [reply_route] - rs=100 trying -- your call is important to us M=INVITE RURI=<null> F=sip:33825462354@2.2.2.2;transport=udp;user=phone T=sip:44656646820@3.3.3.3:5060 IP=3.3.3.3 ID=isbcmq49mmdt5qba6tozy4q9ocamc55zoz43@10.18.5.64
23:04:56 [24015]: DEBUG: tm [t_lookup.c:1041]: t_check_msg(): msg (0x7fe49d15ecb8) id=23/24015 global id=22/24015 T start=0xffffffffffffffff
23:04:56 [24015]: DEBUG: tm [t_lookup.c:919]: t_reply_matching(): t_reply_matching: hash 39920 label 0 branch 0
23:04:56 [24015]: DEBUG: tm [t_lookup.c:974]: t_reply_matching(): reply (0x7fe49d15ecb8) matched an active transaction (T=0x7fe477a75c68)!
23:04:56 [24015]: DEBUG: tm [t_lookup.c:1111]: t_check_msg(): msg (0x7fe49d15ecb8) id=23/24015 global id=23/24015 T end=0x7fe477a75c68
23:04:56 [24015]: DEBUG: tm [t_reply.c:2243]: reply_received(): transaction found - T:0x7fe477a75c68 branch:0
23:04:56 [24015]: DEBUG: tm [t_reply.c:2256]: reply_received(): org. status uas=100, uac[0]=0 local=0 is_invite=1)
23:04:56 [24015]: INFO: <script>: [onreply_route_3] Initial request from PEER to SSW - rs=100 trying -- your call is important to us ID=isbcmq49mmdt5qba6tozy4q9ocamc55zoz43@10.18.5.64
23:04:56 [24015]: DEBUG: <script>: [onreply_route_3] Initial request from PEER to SSW - rs=100 trying -- your call is important to us M=INVITE RURI=<null> F=sip:33825462354@2.2.2.2;transport=udp;user=phone T=sip:44656646820@3.3.3.3:5060 IP=3.3.3.3 ID=isbcmq49mmdt5qba6tozy4q9ocamc55zoz43@10.18.5.64
23:04:56 [24015]: DEBUG: tm [t_reply.c:1266]: t_should_relay_response(): ->>>>>>>>> T_code=100, new_code=100
23:04:56 [24015]: DEBUG: tm [t_reply.c:1521]: t_should_relay_response(): rps provisional - uas status: 100
23:04:56 [24015]: DEBUG: tm [t_reply.c:1823]: relay_reply(): reply status=5 branch=0, save=0, relay=-1 icode=0 msg status=100
23:04:56 [24015]: DEBUG: <core> [core/receive.c:442]: receive_msg(): reply-route executed in: 169 usec
23:04:56 [24015]: DEBUG: <core> [core/usr_avp.c:636]: destroy_avp_list(): destroying list (nil)
23:04:56 [24015]: DEBUG: <core> [core/usr_avp.c:636]: destroy_avp_list(): destroying list (nil)
23:04:56 [24015]: DEBUG: <core> [core/usr_avp.c:636]: destroy_avp_list(): destroying list (nil)
23:04:56 [24015]: DEBUG: <core> [core/usr_avp.c:636]: destroy_avp_list(): destroying list (nil)
23:04:56 [24015]: DEBUG: <core> [core/usr_avp.c:636]: destroy_avp_list(): destroying list (nil)
23:04:56 [24015]: DEBUG: <core> [core/usr_avp.c:636]: destroy_avp_list(): destroying list (nil)
23:04:56 [24015]: DEBUG: <core> [core/xavp.c:495]: xavp_destroy_list(): destroying xavp list (nil)
23:04:56 [24015]: DEBUG: <core> [core/receive.c:458]: receive_msg(): cleaning up
23:04:58 [24013]: DEBUG: <core> [core/udp_server.c:491]: udp_rcv_loop(): received on udp socket: (106/100/1253) [[SIP/2.0 183 Session Progress 0D  0A Via: SIP/2.0/UDP 2.2.2.2;branch=z9hG4bK0fb9.8cb4c7f17c1fcfc06e7]]
23:04:58 [24013]: DEBUG: <core> [core/receive.c:128]: sip_check_fline(): first line indicates a SIP reply
23:04:58 [24013]: DEBUG: siptrace [siptrace_hep.c:498]: pipport2su(): the port string is 5060
23:04:58 [24013]: DEBUG: siptrace [siptrace_hep.c:498]: pipport2su(): the port string is 5060
23:04:58 [24013]: DEBUG: <core> [core/proxy.c:264]: mk_proxy(): doing DNS lookup...
23:04:58 [24013]: DEBUG: siptrace [siptrace_hep.c:183]: trace_send_hep3_duplicate(): setting up the socket_info
23:04:58 [24013]: DEBUG: <core> [core/parser/msg_parser.c:620]: parse_msg(): SIP Reply  (status):
23:04:58 [24013]: DEBUG: <core> [core/parser/msg_parser.c:622]: parse_msg():  version: <SIP/2.0>
23:04:58 [24013]: DEBUG: <core> [core/parser/msg_parser.c:624]: parse_msg():  status:  <183>
23:04:58 [24013]: DEBUG: <core> [core/parser/msg_parser.c:626]: parse_msg():  reason:  <Session Progress>
23:04:58 [24013]: DEBUG: <core> [core/parser/parse_via.c:1303]: parse_via_param(): Found param type 232, <branch> = <z9hG4bK0fb9.8cb4c7f17c1fcfc06e7098af82a59c0b.0>; state=16
23:04:58 [24013]: DEBUG: <core> [core/parser/parse_via.c:2639]: parse_via(): end of header reached, state=5
23:04:58 [24013]: DEBUG: <core> [core/parser/msg_parser.c:498]: parse_headers(): Via found, flags=2
23:04:58 [24013]: DEBUG: <core> [core/parser/msg_parser.c:500]: parse_headers(): this is the first via
23:04:58 [24013]: DEBUG: <core> [core/parser/parse_addr_spec.c:185]: parse_to_param(): add param: tag=U53bzzlYd_-57621-3575-7-50
23:04:58 [24013]: DEBUG: <core> [core/parser/parse_addr_spec.c:864]: parse_addr_spec(): end of header reached, state=29
23:04:58 [24013]: DEBUG: <core> [core/parser/msg_parser.c:171]: get_hdr_field(): <To> [74]; uri=[sip:+386980051856093@7.7.7.7:5261]
23:04:58 [24013]: DEBUG: <core> [core/parser/msg_parser.c:174]: get_hdr_field(): to body [<sip:+386980051856093@7.7.7.7:5261>], to tag [U53bzzlYd_-57621-3575-7-50]
23:04:58 [24013]: DEBUG: <core> [core/parser/msg_parser.c:152]: get_hdr_field(): cseq <CSeq>: <1> <INVITE>
23:04:58 [24013]: DEBUG: <core> [core/parser/msg_parser.c:185]: get_hdr_field(): content_length=242
23:04:58 [24013]: DEBUG: <core> [core/parser/msg_parser.c:89]: get_hdr_field(): found end of header
23:04:58 [24013]: DEBUG: <core> [core/parser/parse_addr_spec.c:185]: parse_to_param(): add param: tag=456mb993-CC-1020-OFC-1324
23:04:58 [24013]: DEBUG: <core> [core/parser/parse_addr_spec.c:864]: parse_addr_spec(): end of header reached, state=29
23:04:58 [24013]: DEBUG: topos [tps_msg.c:868]: tps_response_received(): handling incoming response
23:04:58 [24013]: DEBUG: topos [tps_msg.c:376]: tps_pack_message(): compacted headers - x_via1: [SIP/2.0/UDP 2.2.2.2;branch=z9hG4bK0fb9.8cb4c7f17c1fcfc06e7098af82a59c0b.0](80) - x_via2: [](0) - x_vbranch1: [z9hG4bK0fb9.8cb4c7f17c1fcfc06e7098af82a59c0b.0](46)
23:04:58 [24013]: DEBUG: topos [tps_msg.c:485]: tps_pack_message(): compacted headers - a_rr: [](0) - b_rr: [<sip:DIAG_22_0_161cd3fa@7.7.7.7:5261;lr>,<sip:6.6.6.6;lr;r2=on;ftag=456mb993-CC-1020-OFC-1324>,<sip:5.5.5.5;lr;r2=on;ftag=456mb993-CC-1020-OFC-1324>,<sip:4.4.4.4;lr;ftag=456mb993-CC-1020-OFC-1324>,<sip:3.3.3.3;lr>](247) - s_rr: [](0)
23:04:58 [24013]: DEBUG: topos [tps_msg.c:490]: tps_pack_message(): compacted headers - as_contact: [](0) - bs_contact: [](0)
23:04:58 [24013]: DEBUG: topos [tps_storage.c:126]: tps_storage_lock_get(): tps lock get: 441
23:04:58 [24013]: DEBUG: ndb_redis [redis_client.c:391]: redisc_get_server(): Hash 2100282977 (srv8)
23:04:58 [24013]: DEBUG: ndb_redis [redis_client.c:395]: redisc_get_server(): Entry 2100282977 (srv8)
23:04:58 [24013]: DEBUG: topos_redis [topos_redis_storage.c:764]: tps_redis_load_branch(): loading branch record for [b:x:z9hG4bK0fb9.8cb4c7f17c1fcfc06e7098af82a59c0b.0]
23:04:58 [24013]: DEBUG: ndb_redis [redis_client.c:1043]: redisc_exec_argv(): rsrv->ctxRedis = 0x5580680a0cd0
23:04:58 [24013]: DEBUG: topos_redis [topos_redis_storage.c:810]: tps_redis_load_branch(): r[1]: s[1]
23:04:58 [24013]: DEBUG: topos_redis [topos_redis_storage.c:810]: tps_redis_load_branch(): r[3]: s[456mb993-CC-1020-OFC-1324]
23:04:58 [24013]: DEBUG: topos_redis [topos_redis_storage.c:810]: tps_redis_load_branch(): r[5]: s[<sip:1.1.1.1:5060;transport=udp;lr;Hpt=9038_16;CxtId=4;TRC=ffffffff-ffffffff;X-HwB2bUaCookie=10981>]
23:04:58 [24013]: DEBUG: topos_redis [topos_redis_storage.c:810]: tps_redis_load_branch(): r[7]: s[<sip:btpsh-5e87a4a2-5dd0-2@2.2.2.2>]
23:04:58 [24013]: DEBUG: topos_redis [topos_redis_storage.c:810]: tps_redis_load_branch(): r[9]: s[456mb993-CC-1020-OFC-1324]
23:04:58 [24013]: DEBUG: topos_redis [topos_redis_storage.c:810]: tps_redis_load_branch(): r[11]: s[<sip:2.2.2.2;lr=on;ftag=456mb993-CC-1020-OFC-1324>]
23:04:58 [24013]: DEBUG: topos_redis [topos_redis_storage.c:810]: tps_redis_load_branch(): r[13]: s[<sip:atpsh-5e87a4a2-5dd0-2@2.2.2.2>]
23:04:58 [24013]: DEBUG: topos_redis [topos_redis_storage.c:810]: tps_redis_load_branch(): r[15]: s[sip:33825462354@1.1.1.1:5060;transport=udp;user=phone;Hpt=9038_16;CxtId=4;TRC=ffffffff-ffffffff]
23:04:58 [24013]: DEBUG: topos_redis [topos_redis_storage.c:810]: tps_redis_load_branch(): r[17]: s[0]
23:04:58 [24013]: DEBUG: topos_redis [topos_redis_storage.c:810]: tps_redis_load_branch(): r[19]: s[z9hG4bK0fb9.8cb4c7f17c1fcfc06e7098af82a59c0b.0]
23:04:58 [24013]: DEBUG: topos_redis [topos_redis_storage.c:810]: tps_redis_load_branch(): r[21]: s[1585947896]
23:04:58 [24013]: DEBUG: topos_redis [topos_redis_storage.c:810]: tps_redis_load_branch(): r[23]: s[atpsh-5e87a4a2-5dd0-2]
23:04:58 [24013]: DEBUG: topos_redis [topos_redis_storage.c:810]: tps_redis_load_branch(): r[25]: s[INVITE]
23:04:58 [24013]: DEBUG: topos_redis [topos_redis_storage.c:810]: tps_redis_load_branch(): r[27]: s[btpsh-5e87a4a2-5dd0-2]
23:04:58 [24013]: DEBUG: topos_redis [topos_redis_storage.c:810]: tps_redis_load_branch(): r[29]: s[isbcmq49mmdt5qba6tozy4q9ocamc55zoz43@10.18.5.64]
23:04:58 [24013]: DEBUG: topos_redis [topos_redis_storage.c:810]: tps_redis_load_branch(): r[31]: s[SIP/2.0/UDP 1.1.1.1:5060;branch=z9hG4bKete1rhqujwelu1nonl1toinrp;Role=3;Hpt=9038_16]
23:04:58 [24013]: DEBUG: topos [tps_msg.c:889]: tps_response_received(): loaded dialog a_uuid [atpsh-5e87a4a2-5dd0-2]
23:04:58 [24013]: DEBUG: ndb_redis [redis_client.c:391]: redisc_get_server(): Hash 2100282977 (srv8)
23:04:58 [24013]: DEBUG: ndb_redis [redis_client.c:395]: redisc_get_server(): Entry 2100282977 (srv8)
23:04:58 [24013]: DEBUG: topos_redis [topos_redis_storage.c:967]: tps_redis_load_dialog(): loading dialog record for [d:z:atpsh-5e87a4a2-5dd0-2]
23:04:58 [24013]: DEBUG: ndb_redis [redis_client.c:1043]: redisc_exec_argv(): rsrv->ctxRedis = 0x5580680a0cd0
23:04:58 [24013]: DEBUG: topos_redis [topos_redis_storage.c:1013]: tps_redis_load_dialog(): r[1]: s[isbcmq49mmdt5qba6tozy4q9ocamc55zoz43@10.18.5.64]
23:04:58 [24013]: DEBUG: topos_redis [topos_redis_storage.c:1013]: tps_redis_load_dialog(): r[3]: s[btpsh-5e87a4a2-5dd0-2]
23:04:58 [24013]: DEBUG: topos_redis [topos_redis_storage.c:1013]: tps_redis_load_dialog(): r[5]: s[1]
23:04:58 [24013]: DEBUG: topos_redis [topos_redis_storage.c:1013]: tps_redis_load_dialog(): r[7]: s[<sip:btpsh-5e87a4a2-5dd0-2@2.2.2.2>]
23:04:58 [24013]: DEBUG: topos_redis [topos_redis_storage.c:1013]: tps_redis_load_dialog(): r[9]: s[456mb993-CC-1020-OFC-1324]
23:04:58 [24013]: DEBUG: topos_redis [topos_redis_storage.c:1013]: tps_redis_load_dialog(): r[11]: s[<sip:2.2.2.2;lr=on;ftag=456mb993-CC-1020-OFC-1324>]
23:04:58 [24013]: DEBUG: topos_redis [topos_redis_storage.c:1013]: tps_redis_load_dialog(): r[13]: s[sip:33825462354@1.1.1.1:5060;transport=udp;user=phone;Hpt=9038_16;CxtId=4;TRC=ffffffff-ffffffff]
23:04:58 [24013]: DEBUG: topos_redis [topos_redis_storage.c:1013]: tps_redis_load_dialog(): r[15]: s[<sip:atpsh-5e87a4a2-5dd0-2@2.2.2.2>]
23:04:58 [24013]: DEBUG: topos_redis [topos_redis_storage.c:1013]: tps_redis_load_dialog(): r[17]: s[<sip:1.1.1.1:5060;transport=udp;lr;Hpt=9038_16;CxtId=4;TRC=ffffffff-ffffffff;X-HwB2bUaCookie=10981>]
23:04:58 [24013]: DEBUG: topos_redis [topos_redis_storage.c:1013]: tps_redis_load_dialog(): r[19]: s[1585947896]
23:04:58 [24013]: DEBUG: topos_redis [topos_redis_storage.c:1013]: tps_redis_load_dialog(): r[21]: s[atpsh-5e87a4a2-5dd0-2]
23:04:58 [24013]: DEBUG: topos_redis [topos_redis_storage.c:1013]: tps_redis_load_dialog(): r[23]: s[0]
23:04:58 [24013]: DEBUG: topos_redis [topos_redis_storage.c:1013]: tps_redis_load_dialog(): r[25]: s[INVITE]
23:04:58 [24013]: DEBUG: topos [tps_storage.c:391]: tps_storage_link_msg(): downstream: yes - acontact: [] - bcontact: [sip:7.7.7.7:5261]
23:04:58 [24013]: DEBUG: ndb_redis [redis_client.c:391]: redisc_get_server(): Hash 2100282977 (srv8)
23:04:58 [24013]: DEBUG: ndb_redis [redis_client.c:395]: redisc_get_server(): Entry 2100282977 (srv8)
23:04:58 [24013]: DEBUG: ndb_redis [redis_client.c:1043]: redisc_exec_argv(): rsrv->ctxRedis = 0x5580680a0cd0
23:04:58 [24013]: DEBUG: topos_redis [topos_redis_storage.c:363]: tps_redis_insert_invite_branch(): inserting branch record for [b:x:INVITE:isbcmq49mmdt5qba6tozy4q9ocamc55zoz43@10.18.5.64:U53bzzlYd_-57621-3575-7-50] with argc 6
23:04:58 [24013]: DEBUG: ndb_redis [redis_client.c:1043]: redisc_exec_argv(): rsrv->ctxRedis = 0x5580680a0cd0
23:04:58 [24013]: DEBUG: topos_redis [topos_redis_storage.c:393]: tps_redis_insert_invite_branch(): expire 180 set on branch record for [b:x:INVITE:isbcmq49mmdt5qba6tozy4q9ocamc55zoz43@10.18.5.64:U53bzzlYd_-57621-3575-7-50] with argc 3
23:04:58 [24013]: DEBUG: ndb_redis [redis_client.c:391]: redisc_get_server(): Hash 2100282977 (srv8)
23:04:58 [24013]: DEBUG: ndb_redis [redis_client.c:395]: redisc_get_server(): Entry 2100282977 (srv8)
23:04:58 [24013]: DEBUG: ndb_redis [redis_client.c:1043]: redisc_exec_argv(): rsrv->ctxRedis = 0x5580680a0cd0
23:04:58 [24013]: DEBUG: topos_redis [topos_redis_storage.c:1189]: tps_redis_update_branch(): updated branch record for [b:x:z9hG4bK0fb9.8cb4c7f17c1fcfc06e7098af82a59c0b.0] with argc 10
23:04:58 [24013]: DEBUG: topos [tps_storage.c:138]: tps_storage_lock_release(): tps lock release: 441
23:04:58 [24013]: DEBUG: topos [tps_msg.c:182]: tps_add_headers(): adding to headers(0) - [Via: SIP/2.0/UDP 1.1.1.1:5060;branch=z9hG4bKete1rhqujwelu1nonl1toinrp;Role=3;Hpt=9038_16#015#012]
23:04:58 [24013]: DEBUG: topos [tps_msg.c:182]: tps_add_headers(): adding to headers(0) - [Record-Route: <sip:2.2.2.2;lr=on;ftag=456mb993-CC-1020-OFC-1324>#015#012]
23:04:58 [24013]: DEBUG: topos [tps_msg.c:182]: tps_add_headers(): adding to headers(0) - [Record-Route: <sip:1.1.1.1:5060;transport=udp;lr;Hpt=9038_16;CxtId=4;TRC=ffffffff-ffffffff;X-HwB2bUaCookie=10981>#015#012]
23:04:58 [24013]: DEBUG: topos [tps_msg.c:182]: tps_add_headers(): adding to headers(0) - [P-SR-XBranch: z9hG4bK0fb9.8cb4c7f17c1fcfc06e7098af82a59c0b.0#015#012]
23:04:58 [24013]: DEBUG: <core> [core/parser/msg_parser.c:620]: parse_msg(): SIP Reply  (status):
23:04:58 [24013]: DEBUG: <core> [core/parser/msg_parser.c:622]: parse_msg():  version: <SIP/2.0>
23:04:58 [24013]: DEBUG: <core> [core/parser/msg_parser.c:624]: parse_msg():  status:  <183>
23:04:58 [24013]: DEBUG: <core> [core/parser/msg_parser.c:626]: parse_msg():  reason:  <Session Progress>
23:04:58 [24013]: DEBUG: <core> [core/parser/parse_via.c:1303]: parse_via_param(): Found param type 232, <branch> = <z9hG4bK0fb9.8cb4c7f17c1fcfc06e7098af82a59c0b.0>; state=16
23:04:58 [24013]: DEBUG: <core> [core/parser/parse_via.c:2639]: parse_via(): end of header reached, state=5
23:04:58 [24013]: DEBUG: <core> [core/parser/msg_parser.c:498]: parse_headers(): Via found, flags=2
23:04:58 [24013]: DEBUG: <core> [core/parser/msg_parser.c:500]: parse_headers(): this is the first via
23:04:58 [24013]: DEBUG: <core> [core/parser/parse_addr_spec.c:185]: parse_to_param(): add param: tag=U53bzzlYd_-57621-3575-7-50
23:04:58 [24013]: DEBUG: <core> [core/parser/parse_addr_spec.c:864]: parse_addr_spec(): end of header reached, state=29
23:04:58 [24013]: DEBUG: <core> [core/parser/msg_parser.c:171]: get_hdr_field(): <To> [74]; uri=[sip:+386980051856093@7.7.7.7:5261]
23:04:58 [24013]: DEBUG: <core> [core/parser/msg_parser.c:174]: get_hdr_field(): to body [<sip:+386980051856093@7.7.7.7:5261>], to tag [U53bzzlYd_-57621-3575-7-50]
23:04:58 [24013]: DEBUG: <core> [core/parser/msg_parser.c:152]: get_hdr_field(): cseq <CSeq>: <1> <INVITE>
23:04:58 [24013]: DEBUG: <core> [core/receive.c:241]: receive_msg(): --- received sip message - reply - call-id: [isbcmq49mmdt5qba6tozy4q9ocamc55zoz43@10.18.5.64] - cseq: [1 INVITE]
23:04:58 [24013]: INFO: <script>: [reply_route] - rs=183 Session Progress IP=3.3.3.3 ID=isbcmq49mmdt5qba6tozy4q9ocamc55zoz43@10.18.5.64
23:04:58 [24013]: DEBUG: <core> [core/parser/parse_addr_spec.c:185]: parse_to_param(): add param: tag=456mb993-CC-1020-OFC-1324
23:04:58 [24013]: DEBUG: <core> [core/parser/parse_addr_spec.c:864]: parse_addr_spec(): end of header reached, state=29
23:04:58 [24013]: DEBUG: <script>: [reply_route] - rs=183 Session Progress M=INVITE RURI=<null> F=sip:33825462354@6.6.6.6;transport=udp;user=phone T=sip:+386980051856093@7.7.7.7:5261 IP=3.3.3.3 ID=isbcmq49mmdt5qba6tozy4q9ocamc55zoz43@10.18.5.64
23:04:58 [24013]: DEBUG: tm [t_lookup.c:1041]: t_check_msg(): msg (0x7fe49d15ecb8) id=24/24013 global id=23/24013 T start=0xffffffffffffffff
23:04:58 [24013]: DEBUG: tm [t_lookup.c:919]: t_reply_matching(): t_reply_matching: hash 39920 label 0 branch 0
23:04:58 [24013]: DEBUG: tm [t_lookup.c:974]: t_reply_matching(): reply (0x7fe49d15ecb8) matched an active transaction (T=0x7fe477a75c68)!
23:04:58 [24013]: DEBUG: tm [t_lookup.c:1111]: t_check_msg(): msg (0x7fe49d15ecb8) id=24/24013 global id=24/24013 T end=0x7fe477a75c68
23:04:58 [24013]: DEBUG: tm [t_reply.c:2243]: reply_received(): transaction found - T:0x7fe477a75c68 branch:0
23:04:58 [24013]: DEBUG: tm [t_reply.c:2256]: reply_received(): org. status uas=100, uac[0]=100 local=0 is_invite=1)
23:04:58 [24013]: INFO: <script>: [onreply_route_3] Initial request from PEER to SSW - rs=183 Session Progress ID=isbcmq49mmdt5qba6tozy4q9ocamc55zoz43@10.18.5.64
23:04:58 [24013]: DEBUG: <script>: [onreply_route_3] Initial request from PEER to SSW - rs=183 Session Progress M=INVITE RURI=<null> F=sip:33825462354@6.6.6.6;transport=udp;user=phone T=sip:+386980051856093@7.7.7.7:5261 IP=3.3.3.3 ID=isbcmq49mmdt5qba6tozy4q9ocamc55zoz43@10.18.5.64
23:04:58 [24013]: DEBUG: tm [t_reply.c:1266]: t_should_relay_response(): ->>>>>>>>> T_code=100, new_code=183
23:04:58 [24013]: DEBUG: tm [t_reply.c:1521]: t_should_relay_response(): rps provisional - uas status: 100
23:04:58 [24013]: DEBUG: tm [t_reply.c:1823]: relay_reply(): reply status=5 branch=0, save=0, relay=0 icode=0 msg status=183
23:04:58 [24013]: DEBUG: <core> [core/msg_translator.c:2288]: generate_res_buf_from_sip_res(): old size: 1607, new size: 1520
23:04:58 [24013]: DEBUG: <core> [core/msg_translator.c:2305]: generate_res_buf_from_sip_res(): copied size: orig:117, new: 30, rest: 1490 msg=#012SIP/2.0 183 Session Progress#015#012To: <sip:+386980051856093@7.7.7.7:5261>;tag=U53bzzlYd_-57621-3575-7-50#015#012From: "+33825462354"<sip:33825462354@6.6.6.6;transport=udp;user=phone>;tag=456mb993-CC-1020-OFC-1324#015#012Call-ID: isbcmq49mmdt5qba6tozy4q9ocamc55zoz43@10.18.5.64#015#012CSeq: 1 INVITE#015#012Contact: <sip:7.7.7.7:5261>#015#012RSeq: 1#015#012Record-Route: <sip:DIAG_22_0_161cd3fa@7.7.7.7:5261;lr>#015#012Record-Route: <sip:6.6.6.6;lr;r2=on;ftag=456mb993-CC-1020-OFC-1324>#015#012Record-Route: <sip:5.5.5.5;lr;r2=on;ftag=456mb993-CC-1020-OFC-1324>#015#012Record-Route: <sip:4.4.4.4;lr;ftag=456mb993-CC-1020-OFC-1324>#015#012Record-Route: <sip:3.3.3.3;lr>#015#012Require: 100rel#015#012P-Charging-Vector: icid-value=HNVIapaO9I-01cf01bf-16-00004f81-001;transit-ioi="void"#015#012Allow: INVITE,PRACK,ACK,UPDATE,CANCEL,BYE,OPTIONS,INFO,SUBSCRIBE,REFER,NOTIFY#015#012Content-Type: application/sdp#015#012Content-Disposition: session#015#012Content-Length: 242#015#012Via: SIP/2.0/UDP 1.1.1.1:5060;branch=z9hG4bKete1rhqujwelu1nonl1toinrp;Role=3;Hpt=9038_16#015#012Record-Route: <sip:2.2.2.2;lr=on;ftag=456mb993-CC-1020-OFC-1324>#015#012Record-Route: <sip:1.1.1.1:5060;transport=udp;lr;Hpt=9038_16;CxtId=4;TRC=ffffffff-ffffffff;X-HwB2bUaCookie=10981>#015#012P-SR-XBranch: z9hG4bK0fb9.8cb4c7f17c1fcfc06e7098af82a59c0b.0#015#012#015#012v=0#015#012o=- 639270298 639270298 IN IP4 3.3.3.4#015#012s=-#015#012c=IN IP4 3.3.3.4#015#012t=0 0#015#012m=audio 52948 RTP/AVP 8 101#015#012c=IN IP4 3.3.3.4#015#012a=rtpmap:8 PCMA/8000/1#015#012a=rtpmap:101 telephone-event/8000/1#015#012a=fmtp:101 0-15#015#012a=ptime:20#015#012a=sendrecv
23:04:58 [24013]: DEBUG: <core> [core/parser/msg_parser.c:620]: parse_msg(): SIP Reply  (status):
23:04:58 [24013]: DEBUG: <core> [core/parser/msg_parser.c:622]: parse_msg():  version: <SIP/2.0>
23:04:58 [24013]: DEBUG: <core> [core/parser/msg_parser.c:624]: parse_msg():  status:  <183>
23:04:58 [24013]: DEBUG: <core> [core/parser/msg_parser.c:626]: parse_msg():  reason:  <Session Progress>
23:04:58 [24013]: DEBUG: <core> [core/parser/parse_addr_spec.c:185]: parse_to_param(): add param: tag=U53bzzlYd_-57621-3575-7-50
23:04:58 [24013]: DEBUG: <core> [core/parser/parse_addr_spec.c:864]: parse_addr_spec(): end of header reached, state=29
23:04:58 [24013]: DEBUG: <core> [core/parser/msg_parser.c:171]: get_hdr_field(): <To> [74]; uri=[sip:+386980051856093@7.7.7.7:5261]
23:04:58 [24013]: DEBUG: <core> [core/parser/msg_parser.c:174]: get_hdr_field(): to body [<sip:+386980051856093@7.7.7.7:5261>], to tag [U53bzzlYd_-57621-3575-7-50]
23:04:58 [24013]: DEBUG: <core> [core/parser/msg_parser.c:152]: get_hdr_field(): cseq <CSeq>: <1> <INVITE>
23:04:58 [24013]: DEBUG: <core> [core/parser/msg_parser.c:185]: get_hdr_field(): content_length=242
23:04:58 [24013]: DEBUG: <core> [core/parser/parse_via.c:1303]: parse_via_param(): Found param type 232, <branch> = <z9hG4bKete1rhqujwelu1nonl1toinrp>; state=6
23:04:58 [24013]: DEBUG: <core> [core/parser/parse_via.c:1303]: parse_via_param(): Found param type 253, <Role> = <3>; state=6
23:04:58 [24013]: DEBUG: <core> [core/parser/parse_via.c:1303]: parse_via_param(): Found param type 253, <Hpt> = <9038_16>; state=16
23:04:58 [24013]: DEBUG: <core> [core/parser/parse_via.c:2639]: parse_via(): end of header reached, state=5
23:04:58 [24013]: DEBUG: <core> [core/parser/msg_parser.c:498]: parse_headers(): Via found, flags=2
23:04:58 [24013]: DEBUG: <core> [core/parser/msg_parser.c:500]: parse_headers(): this is the first via
23:04:58 [24013]: DEBUG: <core> [core/parser/msg_parser.c:89]: get_hdr_field(): found end of header
23:04:58 [24013]: DEBUG: <core> [core/parser/parse_addr_spec.c:185]: parse_to_param(): add param: tag=456mb993-CC-1020-OFC-1324
23:04:58 [24013]: DEBUG: <core> [core/parser/parse_addr_spec.c:864]: parse_addr_spec(): end of header reached, state=29
23:04:58 [24013]: DEBUG: topos [tps_msg.c:1034]: tps_response_sent(): handling outgoing response
23:04:58 [24013]: DEBUG: topos [tps_msg.c:376]: tps_pack_message(): compacted headers - x_via1: [SIP/2.0/UDP 1.1.1.1:5060;branch=z9hG4bKete1rhqujwelu1nonl1toinrp;Role=3;Hpt=9038_16](90) - x_via2: [](0) - x_vbranch1: [z9hG4bKete1rhqujwelu1nonl1toinrp](32)
23:04:58 [24013]: DEBUG: topos [tps_msg.c:485]: tps_pack_message(): compacted headers - a_rr: [](0) - b_rr: [<sip:DIAG_22_0_161cd3fa@7.7.7.7:5261;lr>,<sip:6.6.6.6;lr;r2=on;ftag=456mb993-CC-1020-OFC-1324>,<sip:5.5.5.5;lr;r2=on;ftag=456mb993-CC-1020-OFC-1324>,<sip:4.4.4.4;lr;ftag=456mb993-CC-1020-OFC-1324>,<sip:3.3.3.3;lr>,<sip:2.2.2.2;lr=on;ftag=456mb993-CC-1020-OFC-1324>,<sip:1.1.1.1:5060;transport=udp;lr;Hpt=9038_16;CxtId=4;TRC=ffffffff-ffffffff;X-HwB2bUaCookie=10981>](412) - s_rr: [](0)
23:04:58 [24013]: DEBUG: topos [tps_msg.c:490]: tps_pack_message(): compacted headers - as_contact: [](0) - bs_contact: [](0)
23:04:58 [24013]: DEBUG: topos [tps_storage.c:126]: tps_storage_lock_get(): tps lock get: 441
23:04:58 [24013]: DEBUG: ndb_redis [redis_client.c:391]: redisc_get_server(): Hash 2100282977 (srv8)
23:04:58 [24013]: DEBUG: ndb_redis [redis_client.c:395]: redisc_get_server(): Entry 2100282977 (srv8)
23:04:58 [24013]: DEBUG: topos_redis [topos_redis_storage.c:764]: tps_redis_load_branch(): loading branch record for [b:x:z9hG4bK0fb9.8cb4c7f17c1fcfc06e7098af82a59c0b.0]
23:04:58 [24013]: DEBUG: ndb_redis [redis_client.c:1043]: redisc_exec_argv(): rsrv->ctxRedis = 0x5580680a0cd0
23:04:58 [24013]: DEBUG: topos_redis [topos_redis_storage.c:810]: tps_redis_load_branch(): r[1]: s[<sip:atpsh-5e87a4a2-5dd0-2@2.2.2.2>]
23:04:58 [24013]: DEBUG: topos_redis [topos_redis_storage.c:810]: tps_redis_load_branch(): r[3]: s[sip:33825462354@1.1.1.1:5060;transport=udp;user=phone;Hpt=9038_16;CxtId=4;TRC=ffffffff-ffffffff]
23:04:58 [24013]: DEBUG: topos_redis [topos_redis_storage.c:810]: tps_redis_load_branch(): r[5]: s[0]
23:04:58 [24013]: DEBUG: topos_redis [topos_redis_storage.c:810]: tps_redis_load_branch(): r[7]: s[z9hG4bK0fb9.8cb4c7f17c1fcfc06e7098af82a59c0b.0]
23:04:58 [24013]: DEBUG: topos_redis [topos_redis_storage.c:810]: tps_redis_load_branch(): r[9]: s[1585947896]
23:04:58 [24013]: DEBUG: topos_redis [topos_redis_storage.c:810]: tps_redis_load_branch(): r[11]: s[atpsh-5e87a4a2-5dd0-2]
23:04:58 [24013]: DEBUG: topos_redis [topos_redis_storage.c:810]: tps_redis_load_branch(): r[13]: s[INVITE]
23:04:58 [24013]: DEBUG: topos_redis [topos_redis_storage.c:810]: tps_redis_load_branch(): r[15]: s[btpsh-5e87a4a2-5dd0-2]
23:04:58 [24013]: DEBUG: topos_redis [topos_redis_storage.c:810]: tps_redis_load_branch(): r[17]: s[isbcmq49mmdt5qba6tozy4q9ocamc55zoz43@10.18.5.64]
23:04:58 [24013]: DEBUG: topos_redis [topos_redis_storage.c:810]: tps_redis_load_branch(): r[19]: s[SIP/2.0/UDP 1.1.1.1:5060;branch=z9hG4bKete1rhqujwelu1nonl1toinrp;Role=3;Hpt=9038_16]
23:04:58 [24013]: DEBUG: topos_redis [topos_redis_storage.c:810]: tps_redis_load_branch(): r[21]: s[<sip:DIAG_22_0_161cd3fa@7.7.7.7:5261;lr>,<sip:6.6.6.6;lr;r2=on;ftag=456mb993-CC-1020-OFC-1324>,<sip:5.5.5.5;lr;r2=on;ftag=456mb993-CC-1020-OFC-1324>,<sip:4.4.4.4;lr;ftag=456mb993-CC-1020-OFC-1324>,<sip:3.3.3.3;lr>]
23:04:58 [24013]: DEBUG: topos_redis [topos_redis_storage.c:810]: tps_redis_load_branch(): r[23]: s[456mb993-CC-1020-OFC-1324]
23:04:58 [24013]: DEBUG: topos_redis [topos_redis_storage.c:810]: tps_redis_load_branch(): r[25]: s[<sip:btpsh-5e87a4a2-5dd0-2@2.2.2.2>]
23:04:58 [24013]: DEBUG: topos_redis [topos_redis_storage.c:810]: tps_redis_load_branch(): r[27]: s[U53bzzlYd_-57621-3575-7-50]
23:04:58 [24013]: DEBUG: topos_redis [topos_redis_storage.c:810]: tps_redis_load_branch(): r[29]: s[<sip:1.1.1.1:5060;transport=udp;lr;Hpt=9038_16;CxtId=4;TRC=ffffffff-ffffffff;X-HwB2bUaCookie=10981>]
23:04:58 [24013]: DEBUG: topos_redis [topos_redis_storage.c:810]: tps_redis_load_branch(): r[31]: s[1]
23:04:58 [24013]: DEBUG: topos_redis [topos_redis_storage.c:810]: tps_redis_load_branch(): r[33]: s[456mb993-CC-1020-OFC-1324]
23:04:58 [24013]: DEBUG: topos_redis [topos_redis_storage.c:810]: tps_redis_load_branch(): r[35]: s[<sip:2.2.2.2;lr=on;ftag=456mb993-CC-1020-OFC-1324>]
23:04:58 [24013]: DEBUG: topos_redis [topos_redis_storage.c:810]: tps_redis_load_branch(): r[37]: s[sip:7.7.7.7:5261]
23:04:58 [24013]: DEBUG: topos [tps_msg.c:1064]: tps_response_sent(): loaded branch a_uuid [atpsh-5e87a4a2-5dd0-2]
23:04:58 [24013]: DEBUG: ndb_redis [redis_client.c:391]: redisc_get_server(): Hash 2100282977 (srv8)
23:04:58 [24013]: DEBUG: ndb_redis [redis_client.c:395]: redisc_get_server(): Entry 2100282977 (srv8)
23:04:58 [24013]: DEBUG: topos_redis [topos_redis_storage.c:967]: tps_redis_load_dialog(): loading dialog record for [d:z:atpsh-5e87a4a2-5dd0-2]
23:04:58 [24013]: DEBUG: ndb_redis [redis_client.c:1043]: redisc_exec_argv(): rsrv->ctxRedis = 0x5580680a0cd0
23:04:58 [24013]: DEBUG: topos_redis [topos_redis_storage.c:1013]: tps_redis_load_dialog(): r[1]: s[isbcmq49mmdt5qba6tozy4q9ocamc55zoz43@10.18.5.64]
23:04:58 [24013]: DEBUG: topos_redis [topos_redis_storage.c:1013]: tps_redis_load_dialog(): r[3]: s[btpsh-5e87a4a2-5dd0-2]
23:04:58 [24013]: DEBUG: topos_redis [topos_redis_storage.c:1013]: tps_redis_load_dialog(): r[5]: s[1]
23:04:58 [24013]: DEBUG: topos_redis [topos_redis_storage.c:1013]: tps_redis_load_dialog(): r[7]: s[<sip:btpsh-5e87a4a2-5dd0-2@2.2.2.2>]
23:04:58 [24013]: DEBUG: topos_redis [topos_redis_storage.c:1013]: tps_redis_load_dialog(): r[9]: s[456mb993-CC-1020-OFC-1324]
23:04:58 [24013]: DEBUG: topos_redis [topos_redis_storage.c:1013]: tps_redis_load_dialog(): r[11]: s[<sip:2.2.2.2;lr=on;ftag=456mb993-CC-1020-OFC-1324>]
23:04:58 [24013]: DEBUG: topos_redis [topos_redis_storage.c:1013]: tps_redis_load_dialog(): r[13]: s[sip:33825462354@1.1.1.1:5060;transport=udp;user=phone;Hpt=9038_16;CxtId=4;TRC=ffffffff-ffffffff]
23:04:58 [24013]: DEBUG: topos_redis [topos_redis_storage.c:1013]: tps_redis_load_dialog(): r[15]: s[<sip:atpsh-5e87a4a2-5dd0-2@2.2.2.2>]
23:04:58 [24013]: DEBUG: topos_redis [topos_redis_storage.c:1013]: tps_redis_load_dialog(): r[17]: s[<sip:1.1.1.1:5060;transport=udp;lr;Hpt=9038_16;CxtId=4;TRC=ffffffff-ffffffff;X-HwB2bUaCookie=10981>]
23:04:58 [24013]: DEBUG: topos_redis [topos_redis_storage.c:1013]: tps_redis_load_dialog(): r[19]: s[1585947896]
23:04:58 [24013]: DEBUG: topos_redis [topos_redis_storage.c:1013]: tps_redis_load_dialog(): r[21]: s[atpsh-5e87a4a2-5dd0-2]
23:04:58 [24013]: DEBUG: topos_redis [topos_redis_storage.c:1013]: tps_redis_load_dialog(): r[23]: s[0]
23:04:58 [24013]: DEBUG: topos_redis [topos_redis_storage.c:1013]: tps_redis_load_dialog(): r[25]: s[INVITE]
23:04:58 [24013]: DEBUG: topos [tps_storage.c:138]: tps_storage_lock_release(): tps lock release: 441
23:04:58 [24013]: DEBUG: topos [tps_msg.c:182]: tps_add_headers(): adding to headers(0) - [Contact: <sip:atpsh-5e87a4a2-5dd0-2@2.2.2.2>#015#012]
23:04:58 [24013]: DEBUG: topos [tps_msg.c:182]: tps_add_headers(): adding to headers(0) - [Record-Route: <sip:1.1.1.1:5060;transport=udp;lr;Hpt=9038_16;CxtId=4;TRC=ffffffff-ffffffff;X-HwB2bUaCookie=10981>#015#012]
23:04:58 [24013]: DEBUG: topos [tps_storage.c:391]: tps_storage_link_msg(): downstream: yes - acontact: [] - bcontact: [sip:7.7.7.7:5261]
23:04:58 [24013]: DEBUG: ndb_redis [redis_client.c:391]: redisc_get_server(): Hash 2100282977 (srv8)
23:04:58 [24013]: DEBUG: ndb_redis [redis_client.c:395]: redisc_get_server(): Entry 2100282977 (srv8)
23:04:58 [24013]: DEBUG: ndb_redis [redis_client.c:1043]: redisc_exec_argv(): rsrv->ctxRedis = 0x5580680a0cd0
23:04:58 [24013]: DEBUG: topos_redis [topos_redis_storage.c:363]: tps_redis_insert_invite_branch(): inserting branch record for [b:x:INVITE:isbcmq49mmdt5qba6tozy4q9ocamc55zoz43@10.18.5.64:U53bzzlYd_-57621-3575-7-50] with argc 6
23:04:58 [24013]: DEBUG: ndb_redis [redis_client.c:1043]: redisc_exec_argv(): rsrv->ctxRedis = 0x5580680a0cd0
23:04:58 [24013]: DEBUG: topos_redis [topos_redis_storage.c:393]: tps_redis_insert_invite_branch(): expire 180 set on branch record for [b:x:INVITE:isbcmq49mmdt5qba6tozy4q9ocamc55zoz43@10.18.5.64:U53bzzlYd_-57621-3575-7-50] with argc 3
23:04:58 [24013]: DEBUG: ndb_redis [redis_client.c:391]: redisc_get_server(): Hash 2100282977 (srv8)
23:04:58 [24013]: DEBUG: ndb_redis [redis_client.c:395]: redisc_get_server(): Entry 2100282977 (srv8)
23:04:58 [24013]: DEBUG: ndb_redis [redis_client.c:1043]: redisc_exec_argv(): rsrv->ctxRedis = 0x5580680a0cd0
23:04:58 [24013]: DEBUG: topos_redis [topos_redis_storage.c:1189]: tps_redis_update_branch(): updated branch record for [b:x:z9hG4bK0fb9.8cb4c7f17c1fcfc06e7098af82a59c0b.0] with argc 6
23:04:58 [24013]: DEBUG: siptrace [siptrace_hep.c:498]: pipport2su(): the port string is 5060
23:04:58 [24013]: DEBUG: siptrace [siptrace_hep.c:498]: pipport2su(): the port string is 5060
23:04:58 [24013]: DEBUG: <core> [core/proxy.c:264]: mk_proxy(): doing DNS lookup...
23:04:58 [24013]: DEBUG: siptrace [siptrace_hep.c:183]: trace_send_hep3_duplicate(): setting up the socket_info
23:04:58 [24013]: DEBUG: tm [t_reply.c:2016]: relay_reply(): reply buffer sent out
23:04:58 [24013]: DEBUG: <core> [core/receive.c:442]: receive_msg(): reply-route executed in: 6323 usec
23:04:58 [24013]: DEBUG: <core> [core/usr_avp.c:636]: destroy_avp_list(): destroying list (nil)
23:04:58 [24013]: DEBUG: <core> [core/usr_avp.c:636]: destroy_avp_list(): destroying list (nil)
23:04:58 [24013]: DEBUG: <core> [core/usr_avp.c:636]: destroy_avp_list(): destroying list (nil)
23:04:58 [24013]: DEBUG: <core> [core/usr_avp.c:636]: destroy_avp_list(): destroying list (nil)
23:04:58 [24013]: DEBUG: <core> [core/usr_avp.c:636]: destroy_avp_list(): destroying list (nil)
23:04:58 [24013]: DEBUG: <core> [core/usr_avp.c:636]: destroy_avp_list(): destroying list (nil)
23:04:58 [24013]: DEBUG: <core> [core/xavp.c:495]: xavp_destroy_list(): destroying xavp list (nil)
23:04:58 [24013]: DEBUG: <core> [core/receive.c:458]: receive_msg(): cleaning up
23:04:58 [24014]: DEBUG: <core> [core/udp_server.c:491]: udp_rcv_loop(): received on udp socket: (106/100/508) [[PRACK sip:atpsh-5e87a4a2-5dd0-2@2.2.2.2 SIP/2.0 0D  0A Via: SIP/2.0/UDP 1.1.1.1:5060;branch=]]
23:04:58 [24014]: DEBUG: <core> [core/receive.c:138]: sip_check_fline(): first line indicates a SIP request
23:04:58 [24014]: DEBUG: siptrace [siptrace_hep.c:498]: pipport2su(): the port string is 5060
23:04:58 [24014]: DEBUG: siptrace [siptrace_hep.c:498]: pipport2su(): the port string is 5060
23:04:58 [24014]: DEBUG: <core> [core/proxy.c:264]: mk_proxy(): doing DNS lookup...
23:04:58 [24014]: DEBUG: siptrace [siptrace_hep.c:183]: trace_send_hep3_duplicate(): setting up the socket_info
23:04:58 [24014]: DEBUG: <core> [core/parser/msg_parser.c:610]: parse_msg(): SIP Request:
23:04:58 [24014]: DEBUG: <core> [core/parser/msg_parser.c:612]: parse_msg():  method:  <PRACK>
23:04:58 [24014]: DEBUG: <core> [core/parser/msg_parser.c:614]: parse_msg():  uri:     <sip:atpsh-5e87a4a2-5dd0-2@2.2.2.2>
23:04:58 [24014]: DEBUG: <core> [core/parser/msg_parser.c:616]: parse_msg():  version: <SIP/2.0>
23:04:58 [24014]: DEBUG: <core> [core/parser/parse_via.c:1303]: parse_via_param(): Found param type 232, <branch> = <z9hG4bKutqiephe9suiniut1rth1qji1>; state=6
23:04:58 [24014]: DEBUG: <core> [core/parser/parse_via.c:1303]: parse_via_param(): Found param type 253, <Role> = <3>; state=6
23:04:58 [24014]: DEBUG: <core> [core/parser/parse_via.c:1303]: parse_via_param(): Found param type 253, <Hpt> = <9038_16>; state=16
23:04:58 [24014]: DEBUG: <core> [core/parser/parse_via.c:2639]: parse_via(): end of header reached, state=5
23:04:58 [24014]: DEBUG: <core> [core/parser/msg_parser.c:498]: parse_headers(): Via found, flags=2
23:04:58 [24014]: DEBUG: <core> [core/parser/msg_parser.c:500]: parse_headers(): this is the first via
23:04:58 [24014]: DEBUG: <core> [core/parser/parse_addr_spec.c:185]: parse_to_param(): add param: tag=U53bzzlYd_-57621-3575-7-50
23:04:58 [24014]: DEBUG: <core> [core/parser/parse_addr_spec.c:864]: parse_addr_spec(): end of header reached, state=29
23:04:58 [24014]: DEBUG: <core> [core/parser/msg_parser.c:171]: get_hdr_field(): <To> [111]; uri=[sip:444444656646820@2.2.2.2;transport=udp;user=phone]
23:04:58 [24014]: DEBUG: <core> [core/parser/msg_parser.c:174]: get_hdr_field(): to body ["444444656646820"<sip:444444656646820@2.2.2.2;transport=udp;user=phone>], to tag [U53bzzlYd_-57621-3575-7-50]
23:04:58 [24014]: DEBUG: <core> [core/parser/msg_parser.c:152]: get_hdr_field(): cseq <CSeq>: <2> <PRACK>
23:04:58 [24014]: DEBUG: <core> [core/parser/msg_parser.c:185]: get_hdr_field(): content_length=0
23:04:58 [24014]: DEBUG: <core> [core/parser/msg_parser.c:89]: get_hdr_field(): found end of header
23:04:58 [24014]: DEBUG: <core> [core/parser/parse_addr_spec.c:185]: parse_to_param(): add param: tag=456mb993-CC-1020-OFC-1324
23:04:58 [24014]: DEBUG: <core> [core/parser/parse_addr_spec.c:864]: parse_addr_spec(): end of header reached, state=29
23:04:58 [24014]: DEBUG: topos [tps_msg.c:742]: tps_request_received(): handling incoming request
23:04:58 [24014]: DEBUG: topos [tps_msg.c:376]: tps_pack_message(): compacted headers - x_via1: [SIP/2.0/UDP 1.1.1.1:5060;branch=z9hG4bKutqiephe9suiniut1rth1qji1;Role=3;Hpt=9038_16](90) - x_via2: [](0) - x_vbranch1: [z9hG4bKutqiephe9suiniut1rth1qji1](32)
23:04:58 [24014]: DEBUG: topos [tps_msg.c:485]: tps_pack_message(): compacted headers - a_rr: [](0) - b_rr: [](0) - s_rr: [](0)
23:04:58 [24014]: DEBUG: topos [tps_msg.c:490]: tps_pack_message(): compacted headers - as_contact: [](0) - bs_contact: [](0)
23:04:58 [24014]: DEBUG: topos [tps_storage.c:126]: tps_storage_lock_get(): tps lock get: 441
23:04:58 [24014]: DEBUG: ndb_redis [redis_client.c:391]: redisc_get_server(): Hash 2100282977 (srv8)
23:04:58 [24014]: DEBUG: ndb_redis [redis_client.c:395]: redisc_get_server(): Entry 2100282977 (srv8)
23:04:58 [24014]: DEBUG: ndb_redis [redis_client.c:391]: redisc_get_server(): Hash 2100282977 (srv8)
23:04:58 [24014]: DEBUG: ndb_redis [redis_client.c:395]: redisc_get_server(): Entry 2100282977 (srv8)
23:04:58 [24014]: DEBUG: topos_redis [topos_redis_storage.c:610]: tps_redis_load_invite_branch(): loading branch record for [b:x:INVITE:isbcmq49mmdt5qba6tozy4q9ocamc55zoz43@10.18.5.64:U53bzzlYd_-57621-3575-7-50]
23:04:58 [24014]: DEBUG: ndb_redis [redis_client.c:1043]: redisc_exec_argv(): rsrv->ctxRedis = 0x5580680a0cd0
23:04:58 [24014]: DEBUG: topos_redis [topos_redis_storage.c:657]: tps_redis_load_invite_branch(): r[1]: s[1585947898]
23:04:58 [24014]: DEBUG: topos_redis [topos_redis_storage.c:657]: tps_redis_load_invite_branch(): r[3]: s[z9hG4bK0fb9.8cb4c7f17c1fcfc06e7098af82a59c0b.0]
23:04:58 [24014]: DEBUG: topos_redis [topos_redis_storage.c:744]: tps_redis_load_branch(): branch value not found (mode: 1)
23:04:58 [24014]: DEBUG: topos [tps_storage.c:138]: tps_storage_lock_release(): tps lock release: 441
23:04:58 [24014]: DEBUG: <core> [core/parser/msg_parser.c:610]: parse_msg(): SIP Request:
23:04:58 [24014]: DEBUG: <core> [core/parser/msg_parser.c:612]: parse_msg():  method:  <PRACK>
23:04:58 [24014]: DEBUG: <core> [core/parser/msg_parser.c:614]: parse_msg():  uri:     <sip:atpsh-5e87a4a2-5dd0-2@2.2.2.2>
23:04:58 [24014]: DEBUG: <core> [core/parser/msg_parser.c:616]: parse_msg():  version: <SIP/2.0>
23:04:58 [24014]: DEBUG: <core> [core/parser/parse_via.c:1303]: parse_via_param(): Found param type 232, <branch> = <z9hG4bKutqiephe9suiniut1rth1qji1>; state=6
23:04:58 [24014]: DEBUG: <core> [core/parser/parse_via.c:1303]: parse_via_param(): Found param type 253, <Role> = <3>; state=6
23:04:58 [24014]: DEBUG: <core> [core/parser/parse_via.c:1303]: parse_via_param(): Found param type 253, <Hpt> = <9038_16>; state=16
23:04:58 [24014]: DEBUG: <core> [core/parser/parse_via.c:2639]: parse_via(): end of header reached, state=5
23:04:58 [24014]: DEBUG: <core> [core/parser/msg_parser.c:498]: parse_headers(): Via found, flags=2
23:04:58 [24014]: DEBUG: <core> [core/parser/msg_parser.c:500]: parse_headers(): this is the first via
23:04:58 [24014]: DEBUG: <core> [core/parser/parse_addr_spec.c:185]: parse_to_param(): add param: tag=U53bzzlYd_-57621-3575-7-50
23:04:58 [24014]: DEBUG: <core> [core/parser/parse_addr_spec.c:864]: parse_addr_spec(): end of header reached, state=29
23:04:58 [24014]: DEBUG: <core> [core/parser/msg_parser.c:171]: get_hdr_field(): <To> [111]; uri=[sip:444444656646820@2.2.2.2;transport=udp;user=phone]
23:04:58 [24014]: DEBUG: <core> [core/parser/msg_parser.c:174]: get_hdr_field(): to body ["444444656646820"<sip:444444656646820@2.2.2.2;transport=udp;user=phone>], to tag [U53bzzlYd_-57621-3575-7-50]
23:04:58 [24014]: DEBUG: <core> [core/parser/msg_parser.c:152]: get_hdr_field(): cseq <CSeq>: <2> <PRACK>
23:04:58 [24014]: DEBUG: <core> [core/receive.c:241]: receive_msg(): --- received sip message - request - call-id: [isbcmq49mmdt5qba6tozy4q9ocamc55zoz43@10.18.5.64] - cseq: [2 PRACK]
23:04:58 [24014]: DEBUG: <core> [core/receive.c:296]: receive_msg(): preparing to run routing scripts...
23:04:58 [24014]: DEBUG: <core> [core/parser/parse_addr_spec.c:185]: parse_to_param(): add param: tag=456mb993-CC-1020-OFC-1324
23:04:58 [24014]: DEBUG: <core> [core/parser/parse_addr_spec.c:864]: parse_addr_spec(): end of header reached, state=29
23:04:58 [24014]: INFO: <script>: [MAIN] New request - M=PRACK RURI=sip:atpsh-5e87a4a2-5dd0-2@2.2.2.2 F=sip:+33825462354@1.1.1.1;transport=udp;user=phone T=sip:444444656646820@2.2.2.2;transport=udp;user=phone IP=1.1.1.1 ID=isbcmq49mmdt5qba6tozy4q9ocamc55zoz43@10.18.5.64
23:04:58 [24014]: INFO: <script>: [SANITY_CHECK] - ID=isbcmq49mmdt5qba6tozy4q9ocamc55zoz43@10.18.5.64
23:04:58 [24014]: DEBUG: <script>: [SANITY_CHECK] - M=PRACK RURI=sip:atpsh-5e87a4a2-5dd0-2@2.2.2.2 F=sip:+33825462354@1.1.1.1;transport=udp;user=phone T=sip:444444656646820@2.2.2.2;transport=udp;user=phone IP=1.1.1.1 ID=isbcmq49mmdt5qba6tozy4q9ocamc55zoz43@10.18.5.64
23:04:58 [24014]: DEBUG: maxfwd [mf_funcs.c:74]: is_maxfwd_present(): value = 69
23:04:58 [24014]: DEBUG: sanity [sanity.c:247]: check_ruri_sip_version(): check_ruri_sip_version entered
23:04:58 [24014]: DEBUG: sanity [sanity.c:270]: check_ruri_sip_version(): check_ruri_sip_version passed
23:04:58 [24014]: DEBUG: sanity [sanity.c:277]: check_ruri_scheme(): check_ruri_scheme entered
23:04:58 [24014]: DEBUG: sanity [sanity.c:297]: check_ruri_scheme(): check_ruri_scheme passed
23:04:58 [24014]: DEBUG: sanity [sanity.c:305]: check_required_headers(): check_required_headers entered
23:04:58 [24014]: DEBUG: sanity [sanity.c:313]: check_required_headers(): check_required_headers passed
23:04:58 [24014]: DEBUG: sanity [sanity.c:479]: check_cseq_method(): check_cseq_method entered
23:04:58 [24014]: DEBUG: sanity [sanity.c:512]: check_cseq_method(): check_cseq_method passed
23:04:58 [24014]: DEBUG: sanity [sanity.c:521]: check_cseq_value(): check_cseq_value entered
23:04:58 [24014]: DEBUG: sanity [sanity.c:549]: check_cseq_value(): check_cseq_value passed
23:04:58 [24014]: DEBUG: sanity [sanity.c:558]: check_cl(): check_cl entered
23:04:58 [24014]: DEBUG: <core> [core/parser/msg_parser.c:185]: get_hdr_field(): content_length=0
23:04:58 [24014]: DEBUG: <core> [core/parser/msg_parser.c:89]: get_hdr_field(): found end of header
23:04:58 [24014]: DEBUG: sanity [sanity.c:583]: check_cl(): check_cl passed
23:04:58 [24014]: DEBUG: sanity [sanity.c:595]: check_expires_value(): check_expires_value entered
23:04:58 [24014]: DEBUG: sanity [sanity.c:632]: check_expires_value(): no expires header found
23:04:58 [24014]: DEBUG: sanity [sanity.c:644]: check_proxy_require(): checking proxy require
23:04:58 [24014]: DEBUG: sanity [sanity.c:716]: check_proxy_require(): no proxy-require header found
23:04:58 [24014]: DEBUG: sanity [sanity.c:894]: check_digest_only(): Nothing to check
23:04:58 [24014]: DEBUG: sanity [sanity_mod.c:254]: w_sanity_check(): sanity checks result: 1
23:04:58 [24014]: DEBUG: pv [pv_core.c:1031]: pv_get_useragent(): no User-Agent header
23:04:58 [24014]: DEBUG: pv [pv_core.c:1031]: pv_get_useragent(): no User-Agent header
23:04:58 [24014]: DEBUG: pv [pv_core.c:1031]: pv_get_useragent(): no User-Agent header
23:04:58 [24014]: INFO: <script>: [CHECK_SOURCE_IP] - ID=isbcmq49mmdt5qba6tozy4q9ocamc55zoz43@10.18.5.64
23:04:58 [24014]: DEBUG: <script>: [CHECK_SOURCE_IP] - M=PRACK RURI=sip:atpsh-5e87a4a2-5dd0-2@2.2.2.2 F=sip:+33825462354@1.1.1.1;transport=udp;user=phone T=sip:444444656646820@2.2.2.2;transport=udp;user=phone IP=1.1.1.1 ID=isbcmq49mmdt5qba6tozy4q9ocamc55zoz43@10.18.5.64
23:04:58 [24014]: DEBUG: siputils [checks.c:123]: has_totag(): totag found
23:04:58 [24014]: INFO: <script>: [WITHINDLG] - ID=isbcmq49mmdt5qba6tozy4q9ocamc55zoz43@10.18.5.64
23:04:58 [24014]: DEBUG: <script>: [WITHINDLG] - M=PRACK RURI=sip:atpsh-5e87a4a2-5dd0-2@2.2.2.2 F=sip:+33825462354@1.1.1.1;transport=udp;user=phone T=sip:444444656646820@2.2.2.2;transport=udp;user=phone IP=1.1.1.1 ID=isbcmq49mmdt5qba6tozy4q9ocamc55zoz43@10.18.5.64
23:04:58 [24014]: DEBUG: rr [loose.c:114]: find_first_route(): No Route headers found
23:04:58 [24014]: DEBUG: rr [loose.c:961]: loose_route(): There is no Route HF
23:04:58 [24014]: INFO: <script>: [WITHINDLG] Not loose-route send 404 Not Here - ID=isbcmq49mmdt5qba6tozy4q9ocamc55zoz43@10.18.5.64
23:04:58 [24014]: DEBUG: <script>: [WITHINDLG] Not loose-route send 404 Not Here - M=PRACK RURI=sip:atpsh-5e87a4a2-5dd0-2@2.2.2.2 F=sip:+33825462354@1.1.1.1;transport=udp;user=phone T=sip:444444656646820@2.2.2.2;transport=udp;user=phone IP=1.1.1.1 ID=isbcmq49mmdt5qba6tozy4q9ocamc55zoz43@10.18.5.64
23:04:58 [24014]: DEBUG: <core> [core/msg_translator.c:162]: check_via_address(): (1.1.1.1, 1.1.1.1, 0)
23:04:58 [24014]: DEBUG: sl [sl_funcs.c:500]: sl_run_callbacks(): execute callback for event type 1
23:04:58 [24014]: DEBUG: siptrace [siptrace.c:1369]: trace_sl_onreply_out(): trace off...
23:04:58 [24014]: DEBUG: <core> [core/parser/msg_parser.c:620]: parse_msg(): SIP Reply  (status):
23:04:58 [24014]: DEBUG: <core> [core/parser/msg_parser.c:622]: parse_msg():  version: <SIP/2.0>
23:04:58 [24014]: DEBUG: <core> [core/parser/msg_parser.c:624]: parse_msg():  status:  <404>
23:04:58 [24014]: DEBUG: <core> [core/parser/msg_parser.c:626]: parse_msg():  reason:  <Not here>
23:04:58 [24014]: DEBUG: <core> [core/parser/parse_via.c:1303]: parse_via_param(): Found param type 232, <branch> = <z9hG4bKutqiephe9suiniut1rth1qji1>; state=6
23:04:58 [24014]: DEBUG: <core> [core/parser/parse_via.c:1303]: parse_via_param(): Found param type 253, <Role> = <3>; state=6
23:04:58 [24014]: DEBUG: <core> [core/parser/parse_via.c:1303]: parse_via_param(): Found param type 253, <Hpt> = <9038_16>; state=16
23:04:58 [24014]: DEBUG: <core> [core/parser/parse_via.c:2639]: parse_via(): end of header reached, state=5
23:04:58 [24014]: DEBUG: <core> [core/parser/msg_parser.c:498]: parse_headers(): Via found, flags=2
23:04:58 [24014]: DEBUG: <core> [core/parser/msg_parser.c:500]: parse_headers(): this is the first via
23:04:58 [24014]: DEBUG: <core> [core/parser/parse_addr_spec.c:185]: parse_to_param(): add param: tag=U53bzzlYd_-57621-3575-7-50
23:04:58 [24014]: DEBUG: <core> [core/parser/parse_addr_spec.c:864]: parse_addr_spec(): end of header reached, state=29
23:04:58 [24014]: DEBUG: <core> [core/parser/msg_parser.c:171]: get_hdr_field(): <To> [111]; uri=[sip:444444656646820@2.2.2.2;transport=udp;user=phone]
23:04:58 [24014]: DEBUG: <core> [core/parser/msg_parser.c:174]: get_hdr_field(): to body ["444444656646820"<sip:444444656646820@2.2.2.2;transport=udp;user=phone>], to tag [U53bzzlYd_-57621-3575-7-50]
23:04:58 [24014]: DEBUG: <core> [core/parser/msg_parser.c:152]: get_hdr_field(): cseq <CSeq>: <2> <PRACK>
23:04:58 [24014]: DEBUG: <core> [core/parser/msg_parser.c:185]: get_hdr_field(): content_length=0
23:04:58 [24014]: DEBUG: <core> [core/parser/msg_parser.c:89]: get_hdr_field(): found end of header
23:04:58 [24014]: DEBUG: <core> [core/parser/parse_addr_spec.c:185]: parse_to_param(): add param: tag=456mb993-CC-1020-OFC-1324
23:04:58 [24014]: DEBUG: <core> [core/parser/parse_addr_spec.c:864]: parse_addr_spec(): end of header reached, state=29
23:04:58 [24014]: DEBUG: topos [tps_msg.c:1034]: tps_response_sent(): handling outgoing response
23:04:58 [24014]: DEBUG: topos [tps_msg.c:1041]: tps_response_sent(): no x-branch header - nothing to do
23:04:58 [24014]: DEBUG: siptrace [siptrace_hep.c:498]: pipport2su(): the port string is 5060
23:04:58 [24014]: DEBUG: siptrace [siptrace_hep.c:498]: pipport2su(): the port string is 5060
23:04:58 [24014]: DEBUG: <core> [core/proxy.c:264]: mk_proxy(): doing DNS lookup...
23:04:58 [24014]: DEBUG: siptrace [siptrace_hep.c:183]: trace_send_hep3_duplicate(): setting up the socket_info
23:04:58 [24014]: DEBUG: <core> [core/receive.c:354]: receive_msg(): request-route executed in: 5924 usec
23:04:58 [24014]: DEBUG: <core> [core/usr_avp.c:636]: destroy_avp_list(): destroying list (nil)
23:04:58 [24014]: DEBUG: <core> [core/usr_avp.c:636]: destroy_avp_list(): destroying list (nil)
23:04:58 [24014]: DEBUG: <core> [core/usr_avp.c:636]: destroy_avp_list(): destroying list (nil)
23:04:58 [24014]: DEBUG: <core> [core/usr_avp.c:636]: destroy_avp_list(): destroying list (nil)
23:04:58 [24014]: DEBUG: <core> [core/usr_avp.c:636]: destroy_avp_list(): destroying list (nil)
23:04:58 [24014]: DEBUG: <core> [core/usr_avp.c:636]: destroy_avp_list(): destroying list (nil)
23:04:58 [24014]: DEBUG: <core> [core/xavp.c:495]: xavp_destroy_list(): destroying xavp list (nil)