<div dir="ltr">Dear mailing list members,<br>I was trying to deploy a new installation of sipwise CE 13.5.1 and I get this error when testing calls.<br><br><i>ERROR: ROUTE_BRANCH_ACC_RTP dialog [dialog.c:1868]: ki_dlg_get_var_helper(): invalid Call-ID parameter<br></i><br>Currently, I am in the phase of testing the basic network configuration before enabling peering and advanced settings. I have configured the network interfaces as follows:<br><br>neth1: type=sip_ext and rtp_ext (To connect to a peering in the future)<br>Subnet: <a href="http://172.100.100.0/29">172.100.100.0/29</a> <br>neth2: type=sip_ext_incoming<br>Subnet: <a href="http://172.16.0.0/16">172.16.0.0/16</a> <br>neth3: type=sip_ext_incoming Public IP<br><br>The tests I am conducting involve making calls between devices connected to these different interfaces. Additionally, I am actively monitoring SIP transactions during these calls to validate signaling behavior.<br><br>The specific problem manifests in calls going from the neth2 interface to the neth3 interface. This scenario fails, and upon reviewing SIP transactions, we observe an  &quot;<i>Reply LEG_B - S=408 - Request Timeout</i>&quot; response. However, calls in the opposite direction (from neth3 to neth2) function correctly, with SIP transactions completing as expected.<br><br>It is important to note that this same test scenario works flawlessly on an older version, mr8.5.2, with the exact same network configuration and interfaces.<br><br>I have temporarily disabled the firewall to ensure it is not the cause of the problem.<br><br>- Has anyone experienced similar behavior with mr13.5.1 LTS, particularly concerning SIP signaling in  flows between interfaces configured in this manner? <br>- Could the following error be related to the problem?<br>  <i> # iptables -L <br>   target     prot opt source               destination<br>   Error: target extension not found<br>   # iptables v1.8.11 (nf_tables): Parsing nftables rule failed<br>   Perhaps iptables or your kernel needs to be upgraded.</i><br><br>I would appreciate any suggestions on potential points of failure in version mr13.5.1, or further diagnostic steps that might help identify the root cause in the SIP transactions.<br>I&#39;m adding a few lines of log data.<br><br>Thank you in advance for your time and help.<br><br>Best regards,<br><br>Dario T<br><br>I am also adding notes that may be useful for analysis.<br><i># uname -a<br>Linux spce 6.12.48+deb13-amd64 #1 SMP PREEMPT_DYNAMIC Debian 6.12.48-1 (2025-09-20) x86_64 GNU/Linux<br><br>#lsmod | grep -i rtp<br>xt_RTPENGINE           81920  3<br>x_tables               53248  3 nft_compat,xt_RTPENGINE,ip_tables<br><br># lsmod | grep -i nft<br>nft_compat             20480  1<br>nf_tables             380928  6 nft_compat<br>nfnetlink              20480  3 nft_compat,nf_tables<br>x_tables               53248  3 nft_compat,xt_RTPENGINE,ip_tables<br></i><br>kamailio-proxy.log<br>```log<br><i>Oct 29 15:11:29.635257 spce proxy[6044]: NOTICE: DEFAULT_ROUTE &lt;script&gt;: New request on proxy - M=INVITE R=«sip:51187654321@ss.example.org:5060» F=«<a href="mailto:sip%3Aalice@ss.example.org">sip:alice@ss.example.org</a>» T=«<a href="mailto:sip%3A51187654321@ss.example.org">sip:51187654321@ss.example.org</a>» IP=«172.16.100.209»:«5060» («127.0.0.1»:«5060») ID=«FiLArRmpsyS5gpLCFSHR7jzDRpQiYPSE» UA=&#39;uagv1&#39; DESTIP=«127.0.0.1»:«5062»<br>Oct 29 15:11:29.635305 spce proxy[6044]: NOTICE: DEFAULT_ROUTE &lt;script&gt;: Sending reply S=100 Trying M=INVITE fs=&#39;«127.0.0.1»:«5062»&#39; du=&#39;«127.0.0.1»:«5060»&#39; - R=«sip:51187654321@ss.example.org:5060» ID=«FiLArRmpsyS5gpLCFSHR7jzDRpQiYPSE» UA=&#39;uagv1&#39;<br>Oct 29 15:11:29.635316 spce proxy[6044]: INFO: DEFAULT_ROUTE &lt;script&gt;: processing INVITE - R=«sip:51187654321@ss.example.org:5060» ID=«FiLArRmpsyS5gpLCFSHR7jzDRpQiYPSE» UA=&#39;uagv1&#39;<br>Oct 29 15:11:29.635326 spce proxy[6044]: DEBUG: ROUTE_CHECK_TEL_URI &lt;script&gt;: x_hdr(From):«&lt;<a href="mailto:sip%3Aalice@ss.example.org">sip:alice@ss.example.org</a>&gt;;tag=VxUyKI6TlvPyt7OGWLD-tWDU3S5Yq9p-» - R=«sip:51187654321@ss.example.org:5060» ID=«FiLArRmpsyS5gpLCFSHR7jzDRpQiYPSE» UA=&#39;uagv1&#39;<br>Oct 29 15:11:29.635336 spce proxy[6044]: DEBUG: DEFAULT_ROUTE &lt;script&gt;: pua_dialoginfo: Disable PUBLISH messages to caller setting FLB_PRESENCE_CALLER flag - R=«sip:51187654321@ss.example.org:5060» ID=«FiLArRmpsyS5gpLCFSHR7jzDRpQiYPSE» UA=&#39;uagv1&#39;<br>Oct 29 15:11:29.635345 spce proxy[6044]: DEBUG: DEFAULT_ROUTE &lt;script&gt;: pua_dialoginfo: Disable PUBLISH messages to callee setting FLB_PRESENCE_CALLEE flag - R=«sip:51187654321@ss.example.org:5060» ID=«FiLArRmpsyS5gpLCFSHR7jzDRpQiYPSE» UA=&#39;uagv1&#39;<br>Oct 29 15:11:29.635521 spce proxy[6044]: DEBUG: ROUTE_INVITE &lt;script&gt;: pua_dialoginfo: Set flag presence to activate the publish messages - R=«sip:51187654321@ss.example.org:5060» ID=«FiLArRmpsyS5gpLCFSHR7jzDRpQiYPSE» UA=&#39;uagv1&#39;<br>Oct 29 15:11:29.635538 spce proxy[6044]: NOTICE: ROUTE_LOAD_CALLEE_DOMAIN_PREF &lt;script&gt;: Load domain preferences for callee &#39;«<a href="http://ss.example.org">ss.example.org</a>»&#39; - R=«sip:51187654321@ss.example.org:5060» ID=«FiLArRmpsyS5gpLCFSHR7jzDRpQiYPSE» UA=&#39;uagv1&#39;<br>Oct 29 15:11:29.639320 spce proxy[6044]: INFO: ROUTE_CLEAR_CALLEE_DOMAIN_PREF &lt;script&gt;: Clean domain preferences for callee - R=«sip:51187654321@ss.example.org:5060» ID=«FiLArRmpsyS5gpLCFSHR7jzDRpQiYPSE» UA=&#39;uagv1&#39;<br>Oct 29 15:11:29.639630 spce proxy[6044]: INFO: ROUTE_FIND_CALLER &lt;script&gt;: +++++++++++++++ find caller - R=«sip:51187654321@ss.example.org:5060» ID=«FiLArRmpsyS5gpLCFSHR7jzDRpQiYPSE» UA=&#39;uagv1&#39;<br>Oct 29 15:11:29.639876 spce proxy[6044]: DEBUG: ROUTE_FIND_CALLER &lt;script&gt;: pua_dialoginfo: Set by default puburis_caller to a fake (random) value and disable PUBLISH messages to caller setting FLB_PRESENCE_CALLER flag - R=«sip:51187654321@ss.example.org:5060» ID=«FiLArRmpsyS5gpLCFSHR7jzDRpQiYPSE» UA=&#39;uagv1&#39;<br>Oct 29 15:11:29.640250 spce proxy[6044]: NOTICE: ROUTE_AUTH &lt;script&gt;: Authentication failed, no credentials - R=«sip:51187654321@ss.example.org:5060» ID=«FiLArRmpsyS5gpLCFSHR7jzDRpQiYPSE» UA=&#39;uagv1&#39; Auth=«&lt;null&gt;»<br>Oct 29 15:11:29.640491 spce proxy[6044]: NOTICE: ROUTE_AUTH &lt;script&gt;: Sending reply S=407 fs=&#39;«127.0.0.1»:«5062»&#39; du=&#39;«127.0.0.1»:«5060»&#39; - ID=«FiLArRmpsyS5gpLCFSHR7jzDRpQiYPSE» UA=&#39;uagv1&#39;<br>Oct 29 15:11:29.641366 spce proxy[6043]: NOTICE: sl:filtered-ack &lt;script&gt;: New request on proxy - M=ACK R=«sip:51187654321@ss.example.org:5060» F=«<a href="mailto:sip%3Aalice@ss.example.org">sip:alice@ss.example.org</a>» T=«<a href="mailto:sip%3A51187654321@ss.example.org">sip:51187654321@ss.example.org</a>» IP=«&lt;null&gt;»:«&lt;null&gt;» («127.0.0.1»:«5060») ID=«FiLArRmpsyS5gpLCFSHR7jzDRpQiYPSE» UA=&#39;&lt;null&gt;&#39; DESTIP=«127.0.0.1»:«5062»<br>Oct 29 15:11:29.641381 spce proxy[6044]: INFO: ROUTE_EXIT &lt;script&gt;: INVITE processed - ID=«FiLArRmpsyS5gpLCFSHR7jzDRpQiYPSE»<br>Oct 29 15:11:29.641390 spce proxy[6044]: INFO: ROUTE_EXIT &lt;script&gt;: Runtime for request M=INVITE was 6053 usec - ID=«FiLArRmpsyS5gpLCFSHR7jzDRpQiYPSE»<br>Oct 29 15:11:29.645694 spce proxy[6041]: NOTICE: DEFAULT_ROUTE &lt;script&gt;: New request on proxy - M=INVITE R=«sip:51187654321@ss.example.org:5060» F=«<a href="mailto:sip%3Aalice@ss.example.org">sip:alice@ss.example.org</a>» T=«<a href="mailto:sip%3A51187654321@ss.example.org">sip:51187654321@ss.example.org</a>» IP=«172.16.100.209»:«5060» («127.0.0.1»:«5060») ID=«FiLArRmpsyS5gpLCFSHR7jzDRpQiYPSE» UA=&#39;uagv1&#39; DESTIP=«127.0.0.1»:«5062»<br>Oct 29 15:11:29.645727 spce proxy[6041]: NOTICE: DEFAULT_ROUTE &lt;script&gt;: Sending reply S=100 Trying M=INVITE fs=&#39;«127.0.0.1»:«5062»&#39; du=&#39;«127.0.0.1»:«5060»&#39; - R=«sip:51187654321@ss.example.org:5060» ID=«FiLArRmpsyS5gpLCFSHR7jzDRpQiYPSE» UA=&#39;uagv1&#39;<br>Oct 29 15:11:29.645741 spce proxy[6041]: INFO: DEFAULT_ROUTE &lt;script&gt;: processing INVITE - R=«sip:51187654321@ss.example.org:5060» ID=«FiLArRmpsyS5gpLCFSHR7jzDRpQiYPSE» UA=&#39;uagv1&#39;<br>Oct 29 15:11:29.645751 spce proxy[6041]: DEBUG: ROUTE_CHECK_TEL_URI &lt;script&gt;: x_hdr(From):«&lt;<a href="mailto:sip%3Aalice@ss.example.org">sip:alice@ss.example.org</a>&gt;;tag=VxUyKI6TlvPyt7OGWLD-tWDU3S5Yq9p-» - R=«sip:51187654321@ss.example.org:5060» ID=«FiLArRmpsyS5gpLCFSHR7jzDRpQiYPSE» UA=&#39;uagv1&#39;<br>Oct 29 15:11:29.645761 spce proxy[6041]: DEBUG: DEFAULT_ROUTE &lt;script&gt;: pua_dialoginfo: Disable PUBLISH messages to caller setting FLB_PRESENCE_CALLER flag - R=«sip:51187654321@ss.example.org:5060» ID=«FiLArRmpsyS5gpLCFSHR7jzDRpQiYPSE» UA=&#39;uagv1&#39;<br>Oct 29 15:11:29.645770 spce proxy[6041]: DEBUG: DEFAULT_ROUTE &lt;script&gt;: pua_dialoginfo: Disable PUBLISH messages to callee setting FLB_PRESENCE_CALLEE flag - R=«sip:51187654321@ss.example.org:5060» ID=«FiLArRmpsyS5gpLCFSHR7jzDRpQiYPSE» UA=&#39;uagv1&#39;<br>Oct 29 15:11:29.645779 spce proxy[6041]: DEBUG: ROUTE_INVITE &lt;script&gt;: pua_dialoginfo: Set flag presence to activate the publish messages - R=«sip:51187654321@ss.example.org:5060» ID=«FiLArRmpsyS5gpLCFSHR7jzDRpQiYPSE» UA=&#39;uagv1&#39;<br>Oct 29 15:11:29.645788 spce proxy[6041]: NOTICE: ROUTE_LOAD_CALLEE_DOMAIN_PREF &lt;script&gt;: Load domain preferences for callee &#39;«<a href="http://ss.example.org">ss.example.org</a>»&#39; - R=«sip:51187654321@ss.example.org:5060» ID=«FiLArRmpsyS5gpLCFSHR7jzDRpQiYPSE» UA=&#39;uagv1&#39;<br>Oct 29 15:11:29.648482 spce proxy[6041]: INFO: ROUTE_CLEAR_CALLEE_DOMAIN_PREF &lt;script&gt;: Clean domain preferences for callee - R=«sip:51187654321@ss.example.org:5060» ID=«FiLArRmpsyS5gpLCFSHR7jzDRpQiYPSE» UA=&#39;uagv1&#39;<br>Oct 29 15:11:29.648876 spce proxy[6041]: INFO: ROUTE_FIND_CALLER &lt;script&gt;: +++++++++++++++ find caller - R=«sip:51187654321@ss.example.org:5060» ID=«FiLArRmpsyS5gpLCFSHR7jzDRpQiYPSE» UA=&#39;uagv1&#39;<br>Oct 29 15:11:29.648898 spce proxy[6041]: DEBUG: ROUTE_FIND_CALLER &lt;script&gt;: pua_dialoginfo: Set by default puburis_caller to a fake (random) value and disable PUBLISH messages to caller setting FLB_PRESENCE_CALLER flag - R=«sip:51187654321@ss.example.org:5060» ID=«FiLArRmpsyS5gpLCFSHR7jzDRpQiYPSE» UA=&#39;uagv1&#39;<br>Oct 29 15:11:29.649526 spce proxy[6041]: INFO: ROUTE_ADD_CALLINFO_REPLY &lt;script&gt;: Adding reply P-NGCP-Caller-Info &#39;&lt;sip:«alice»@«<a href="http://ss.example.org">ss.example.org</a>»&gt;;ip=«172.16.100.209»;port=«5060»«;primary=51123456789»«»&#39; - ID=«FiLArRmpsyS5gpLCFSHR7jzDRpQiYPSE» UA=&#39;uagv1&#39;<br>Oct 29 15:11:29.649682 spce proxy[6041]: NOTICE: ROUTE_FIND_CALLER &lt;script&gt;: Sending reply S=101 Connecting fs=&#39;«127.0.0.1»:«5062»&#39; du=&#39;«127.0.0.1»:«5060»&#39; - R=«sip:51187654321@ss.example.org:5060» ID=«FiLArRmpsyS5gpLCFSHR7jzDRpQiYPSE» UA=&#39;uagv1&#39;<br>Oct 29 15:11:29.650929 spce proxy[6041]: INFO: ROUTE_INVITE &lt;script&gt;: IMS marker, s:ims_role=&#39;&lt;null&gt;&#39;, s:caller_uuid=&#39;«03fd71a7-df7a-4f89-8eb6-7283013550dc»&#39;, s:callee_uuid=&#39;«&lt;null&gt;»&#39;, s:acc_caller_user=&#39;«alice»&#39;, s:acc_caller_domain=&#39;«<a href="http://ss.example.org">ss.example.org</a>»&#39;  - R=«sip:51187654321@ss.example.org:5060» ID=«FiLArRmpsyS5gpLCFSHR7jzDRpQiYPSE» UA=&#39;uagv1&#39;<br>Oct 29 15:11:29.650941 spce proxy[6041]: INFO: ROUTE_CLEAR_CALLER_PREF &lt;script&gt;: Clear caller preferences - R=«sip:51187654321@ss.example.org:5060» ID=«FiLArRmpsyS5gpLCFSHR7jzDRpQiYPSE» UA=&#39;uagv1&#39;<br>Oct 29 15:11:29.650952 spce proxy[6041]: NOTICE: ROUTE_LOAD_CALLER_PREF &lt;script&gt;: Load caller preferences for uuid &#39;«03fd71a7-df7a-4f89-8eb6-7283013550dc»&#39; and domain &#39;«<a href="http://ss.example.org">ss.example.org</a>»&#39; - R=«sip:51187654321@ss.example.org:5060» ID=«FiLArRmpsyS5gpLCFSHR7jzDRpQiYPSE» UA=&#39;uagv1&#39;<br>Oct 29 15:11:29.654422 spce proxy[6041]: INFO: ROUTE_CHECK_UA &lt;script&gt;: Checking User-Agent filters - R=«sip:51187654321@ss.example.org:5060» ID=«FiLArRmpsyS5gpLCFSHR7jzDRpQiYPSE» UA=&#39;uagv1&#39;<br>Oct 29 15:11:29.654519 spce proxy[6041]: INFO: ROUTE_CHECK_UA &lt;script&gt;: User-Agent header found, check filter list - R=«sip:51187654321@ss.example.org:5060» ID=«FiLArRmpsyS5gpLCFSHR7jzDRpQiYPSE» UA=&#39;uagv1&#39;<br>Oct 29 15:11:29.654637 spce proxy[6041]: INFO: ROUTE_CHECK_UA &lt;script&gt;: UA filter mode is &#39;blacklist&#39; - R=«sip:51187654321@ss.example.org:5060» ID=«FiLArRmpsyS5gpLCFSHR7jzDRpQiYPSE» UA=&#39;uagv1&#39;<br>Oct 29 15:11:29.654717 spce proxy[6041]: INFO: ROUTE_CHECK_UA &lt;script&gt;: UA filter checks passed - R=«sip:51187654321@ss.example.org:5060» ID=«FiLArRmpsyS5gpLCFSHR7jzDRpQiYPSE» UA=&#39;uagv1&#39;<br>Oct 29 15:11:29.654903 spce proxy[6041]: NOTICE: ROUTE_LOAD_CALLER_CONTRACT_PREF &lt;script&gt;: Load caller contract preferences for contract id &#39;«2»&#39; and ip &#39;«172.16.100.209»&#39; - R=«sip:51187654321@ss.example.org:5060» ID=«FiLArRmpsyS5gpLCFSHR7jzDRpQiYPSE» UA=&#39;uagv1&#39;<br>Oct 29 15:11:29.655447 spce proxy[6041]: INFO: ROUTE_LOAD_CALLER_CONTRACT_PREF &lt;script&gt;: Loaded caller contract preferences for location id &#39;&lt;null&gt;&#39; - R=«sip:51187654321@ss.example.org:5060» ID=«FiLArRmpsyS5gpLCFSHR7jzDRpQiYPSE» UA=&#39;uagv1&#39;<br>Oct 29 15:11:29.655532 spce proxy[6041]: NOTICE: ROUTE_LOAD_CALLER_RESELLER_PREF &lt;script&gt;: Load caller reseller preferences for reseller id &#39;«1»&#39; - R=«sip:51187654321@ss.example.org:5060» ID=«FiLArRmpsyS5gpLCFSHR7jzDRpQiYPSE» UA=&#39;uagv1&#39;<br>Oct 29 15:11:29.656712 spce proxy[6041]: INFO: ROUTE_LOAD_CALLER_PREF &lt;script&gt;: Setting network-provided domain &#39;«<a href="http://ss.example.org">ss.example.org</a>»&#39; as acc_caller_domain - R=«sip:51187654321@ss.example.org:5060» ID=«FiLArRmpsyS5gpLCFSHR7jzDRpQiYPSE» UA=&#39;uagv1&#39;<br>Oct 29 15:11:29.656826 spce proxy[6041]: INFO: ROUTE_LOAD_CALLER_PREF &lt;script&gt;: Use lb/rtp set id &#39;«50»&#39; for local caller - R=«sip:51187654321@ss.example.org:5060» ID=«FiLArRmpsyS5gpLCFSHR7jzDRpQiYPSE» UA=&#39;uagv1&#39;<br>Oct 29 15:11:29.656910 spce proxy[6041]: INFO: ROUTE_LOAD_CALLER_PREF &lt;script&gt;: Fetched dialplan IDs caller_in=&#39;&lt;null&gt;&#39;, callee_in=&#39;&lt;null&gt;&#39; - R=«sip:51187654321@ss.example.org:5060» ID=«FiLArRmpsyS5gpLCFSHR7jzDRpQiYPSE» UA=&#39;uagv1&#39;<br>Oct 29 15:11:29.656976 spce proxy[6041]: INFO: ROUTE_LOAD_CALLER_PREF &lt;script&gt;: CDR IP header &#39;P-NGCP-Src-Ip&#39; not found, use &#39;P-NGCP-Src-Ip&#39; - R=«sip:51187654321@ss.example.org:5060» ID=«FiLArRmpsyS5gpLCFSHR7jzDRpQiYPSE» UA=&#39;uagv1&#39;<br>Oct 29 15:11:29.657339 spce proxy[6041]: NOTICE: ROUTE_DLG_MANAGE &lt;script&gt;: Dialog managed, lua_dlg_callid:[«FiLArRmpsyS5gpLCFSHR7jzDRpQiYPSE»] - R=«sip:51187654321@ss.example.org:5060» ID=«FiLArRmpsyS5gpLCFSHR7jzDRpQiYPSE» UA=&#39;uagv1&#39;<br>Oct 29 15:11:29.657795 spce proxy[6041]: INFO: ROUTE_INVITE &lt;script&gt;: ccli_selector for inbound_upn has been set to &#39;from_user&#39; - R=«sip:51187654321@ss.example.org:5060» ID=«FiLArRmpsyS5gpLCFSHR7jzDRpQiYPSE» UA=&#39;uagv1&#39;<br>Oct 29 15:11:29.657812 spce proxy[6041]: NOTICE: ROUTE_GET_CALLER_CLI &lt;script&gt;: User-Provided CLI &#39;«alice»&#39; taken from From-User - R=«sip:51187654321@ss.example.org:5060» ID=«FiLArRmpsyS5gpLCFSHR7jzDRpQiYPSE» UA=&#39;uagv1&#39;<br>Oct 29 15:11:29.657823 spce proxy[6041]: INFO: ROUTE_INVITE &lt;script&gt;: ccli_selector for inbound_uprn has been set to &#39;npn&#39; - R=«sip:51187654321@ss.example.org:5060» ID=«FiLArRmpsyS5gpLCFSHR7jzDRpQiYPSE» UA=&#39;uagv1&#39;<br>Oct 29 15:11:29.657833 spce proxy[6041]: INFO: ROUTE_INVITE &lt;script&gt;: IP authorization for caller not provisioned, allow call - R=«sip:51187654321@ss.example.org:5060» ID=«FiLArRmpsyS5gpLCFSHR7jzDRpQiYPSE» UA=&#39;uagv1&#39;<br>Oct 29 15:11:29.657842 spce proxy[6041]: INFO: ROUTE_CALLER_BLOCK_CLI &lt;script&gt;: Checking UPN &#39;«alice»&#39; and NPN &#39;«51123456789»&#39; against blocked cli lists - R=«sip:51187654321@ss.example.org:5060» ID=«FiLArRmpsyS5gpLCFSHR7jzDRpQiYPSE» UA=&#39;uagv1&#39;<br>Oct 29 15:11:29.657852 spce proxy[6041]: INFO: ROUTE_CALLER_BLOCK_CLI &lt;script&gt;: Caller UPN block mode is &#39;blacklist&#39; - R=«sip:51187654321@ss.example.org:5060» ID=«FiLArRmpsyS5gpLCFSHR7jzDRpQiYPSE» UA=&#39;uagv1&#39;<br>Oct 29 15:11:29.658683 spce proxy[6041]: INFO: ROUTE_CHECK_CLI_ALLOWED &lt;script&gt;: Checking User-provided CLI against allowed CLIs - R=«sip:51187654321@ss.example.org:5060» ID=«FiLArRmpsyS5gpLCFSHR7jzDRpQiYPSE» UA=&#39;uagv1&#39;<br>Oct 29 15:11:29.658741 spce proxy[6041]: NOTICE: ROUTE_CHECK_CLI_ALLOWED &lt;script&gt;: User-provided CLI &#39;«alice»&#39; rejected, using network-provided CLI &#39;«51123456789»&#39; - R=«sip:51187654321@ss.example.org:5060» ID=«FiLArRmpsyS5gpLCFSHR7jzDRpQiYPSE» UA=&#39;uagv1&#39;<br>Oct 29 15:11:29.658755 spce proxy[6041]: NOTICE: ROUTE_INVITE &lt;script&gt;: Setting &#39;«51123456789»@«<a href="http://ss.example.org">ss.example.org</a>»&#39; as initiating user-provided CLI - R=«sip:51187654321@ss.example.org:5060» ID=«FiLArRmpsyS5gpLCFSHR7jzDRpQiYPSE» UA=&#39;uagv1&#39;<br>Oct 29 15:11:29.658779 spce proxy[6041]: NOTICE: ROUTE_INVITE &lt;script&gt;: Setting &#39;«51123456789»@«<a href="http://ss.example.org">ss.example.org</a>»&#39; as initiating network-provided CLI - R=«sip:51187654321@ss.example.org:5060» ID=«FiLArRmpsyS5gpLCFSHR7jzDRpQiYPSE» UA=&#39;uagv1&#39;<br>Oct 29 15:11:29.658789 spce proxy[6041]: INFO: ROUTE_FIND_CALLEE &lt;script&gt;: Searching for callee - R=«sip:51187654321@ss.example.org:5060» ID=«FiLArRmpsyS5gpLCFSHR7jzDRpQiYPSE» UA=&#39;uagv1&#39;<br>Oct 29 15:11:29.659866 spce proxy[6041]: INFO: ROUTE_FIND_CALLEE &lt;core&gt; [core/kemi.c:109]: sr_kemi_core_info(): central:hset[out_03fd71a7-df7a-4f89-8eb6-7283013550dc]=&gt;[true] callee: 51187654321 expire: 86400<br>Oct 29 15:11:29.660240 spce proxy[6041]: INFO: ROUTE_FIND_CALLEE &lt;script&gt;: Saved outgoing recent call for uuid «03fd71a7-df7a-4f89-8eb6-7283013550dc» with key «out_03fd71a7-df7a-4f89-8eb6-7283013550dc» - R=«sip:51187654321@ss.example.org:5060» ID=«FiLArRmpsyS5gpLCFSHR7jzDRpQiYPSE» UA=&#39;uagv1&#39;<br>Oct 29 15:11:29.661699 spce proxy[6041]: NOTICE: ROUTE_FIND_CALLEE &lt;script&gt;: Callee was aliased with base &#39;«51187654321»&#39; - R=«sip:bob@ss.example.org:5060» ID=«FiLArRmpsyS5gpLCFSHR7jzDRpQiYPSE» UA=&#39;uagv1&#39;<br>Oct 29 15:11:29.661847 spce proxy[6041]: INFO: ROUTE_CLEAR_CALLEE_PREF &lt;script&gt;: Clear callee preferences - R=«sip:bob@ss.example.org:5060» ID=«FiLArRmpsyS5gpLCFSHR7jzDRpQiYPSE» UA=&#39;uagv1&#39;<br>Oct 29 15:11:29.662224 spce proxy[6041]: NOTICE: ROUTE_FIND_CALLEE &lt;script&gt;: Callee is local, uuid=&#39;«99d31b34-96d5-4dbb-b89a-14847096007c»&#39; - R=«sip:bob@ss.example.org:5060» ID=«FiLArRmpsyS5gpLCFSHR7jzDRpQiYPSE» UA=&#39;uagv1&#39;<br>Oct 29 15:11:29.662515 spce proxy[6041]: NOTICE: ROUTE_LOAD_CALLEE_PREF &lt;script&gt;: Load callee preferences for uuid &#39;«99d31b34-96d5-4dbb-b89a-14847096007c»&#39; domain: &#39;«<a href="http://ss.example.org">ss.example.org</a>»&#39;- R=«sip:bob@ss.example.org:5060» ID=«FiLArRmpsyS5gpLCFSHR7jzDRpQiYPSE» UA=&#39;uagv1&#39;<br>Oct 29 15:11:29.665512 spce proxy[6041]: DEBUG: ROUTE_LOAD_CALLEE_PREF &lt;script&gt;: pua_dialoginfo: Set local_identity to &#39;<a href="mailto:sip%3Abob@ss.example.org">sip:bob@ss.example.org</a>&#39; - R=«sip:bob@ss.example.org:5060» ID=«FiLArRmpsyS5gpLCFSHR7jzDRpQiYPSE» UA=&#39;uagv1&#39;<br>Oct 29 15:11:29.665666 spce proxy[6041]: NOTICE: ROUTE_LOAD_CALLEE_CONTRACT_PREF &lt;script&gt;: Load callee contract preferences for contract id &#39;«2» and ip &#39;«&lt;null&gt;»&#39; - R=«sip:bob@ss.example.org:5060» ID=«FiLArRmpsyS5gpLCFSHR7jzDRpQiYPSE» UA=&#39;uagv1&#39;<br>Oct 29 15:11:29.666166 spce proxy[6041]: INFO: ROUTE_LOAD_CALLEE_CONTRACT_PREF &lt;script&gt;: Loaded callee contract preferences for location id &#39;«&lt;null&gt;»&#39; - R=«sip:bob@ss.example.org:5060» ID=«FiLArRmpsyS5gpLCFSHR7jzDRpQiYPSE» UA=&#39;uagv1&#39;<br>Oct 29 15:11:29.666244 spce proxy[6041]: NOTICE: ROUTE_LOAD_CALLEE_RESELLER_PREF &lt;script&gt;: Load callee reseller preferences for reseller id &#39;«1» - R=«sip:bob@ss.example.org:5060» ID=«FiLArRmpsyS5gpLCFSHR7jzDRpQiYPSE» UA=&#39;uagv1&#39;<br>Oct 29 15:11:29.666702 spce proxy[6041]: INFO: ROUTE_LOAD_CALLEE_PREF &lt;script&gt;: Use lb/rtp set id &#39;«50»&#39; for local callee - R=«sip:bob@ss.example.org:5060» ID=«FiLArRmpsyS5gpLCFSHR7jzDRpQiYPSE» UA=&#39;uagv1&#39;<br>Oct 29 15:11:29.667163 spce proxy[6041]: INFO: ROUTE_LOAD_CALLEE_PREF &lt;script&gt;: Fetched dialplan IDs caller_out=&#39;&lt;null&gt;&#39;, callee_out=&#39;&lt;null&gt;&#39; - R=«sip:bob@ss.example.org:5060» ID=«FiLArRmpsyS5gpLCFSHR7jzDRpQiYPSE» UA=&#39;uagv1&#39;<br>Oct 29 15:11:29.668145 spce proxy[6041]: INFO: ROUTE_SET_CALLEE_DIALOG_BASE &lt;script&gt;: Set callee dialogs: user, account to &#39;«99d31b34-96d5-4dbb-b89a-14847096007c»/2&#39; - R=«sip:bob@ss.example.org:5060» ID=«FiLArRmpsyS5gpLCFSHR7jzDRpQiYPSE» UA=&#39;uagv1&#39;<br>Oct 29 15:11:29.670181 spce proxy[6041]: INFO: ROUTE_SET_CALLEE_DIALOG_TOTAL &lt;script&gt;: Set callee dialogs: totaluser, totalaccount,totalreseller to &#39;«99d31b34-96d5-4dbb-b89a-14847096007c»/2/1&#39; - R=«sip:bob@ss.example.org:5060» ID=«FiLArRmpsyS5gpLCFSHR7jzDRpQiYPSE» UA=&#39;uagv1&#39;<br>Oct 29 15:11:29.670200 spce proxy[6041]: INFO: ROUTE_BLOCK_IN &lt;script&gt;: Checking UPN &#39;«51123456789»&#39;, NPN &#39;«51123456789»&#39;, First UPN &#39;«51123456789»&#39; and First NPN &#39;«51123456789»&#39; against block in lists - R=«sip:bob@ss.example.org:5060» ID=«FiLArRmpsyS5gpLCFSHR7jzDRpQiYPSE» UA=&#39;uagv1&#39;<br>Oct 29 15:11:29.670211 spce proxy[6041]: INFO: ROUTE_BLOCK_IN &lt;script&gt;: Admin Contract callee block mode is &#39;blacklist&#39; - R=«sip:bob@ss.example.org:5060» ID=«FiLArRmpsyS5gpLCFSHR7jzDRpQiYPSE» UA=&#39;uagv1&#39;<br>Oct 29 15:11:29.670221 spce proxy[6041]: INFO: ROUTE_BLOCK_IN &lt;script&gt;: Admin callee block mode is &#39;blacklist&#39; - R=«sip:bob@ss.example.org:5060» ID=«FiLArRmpsyS5gpLCFSHR7jzDRpQiYPSE» UA=&#39;uagv1&#39;<br>Oct 29 15:11:29.670231 spce proxy[6041]: INFO: ROUTE_BLOCK_IN &lt;script&gt;: Contract callee block mode is &#39;blacklist&#39; - R=«sip:bob@ss.example.org:5060» ID=«FiLArRmpsyS5gpLCFSHR7jzDRpQiYPSE» UA=&#39;uagv1&#39;<br>Oct 29 15:11:29.670240 spce proxy[6041]: INFO: ROUTE_BLOCK_IN &lt;script&gt;: Callee block mode is &#39;blacklist&#39; - R=«sip:bob@ss.example.org:5060» ID=«FiLArRmpsyS5gpLCFSHR7jzDRpQiYPSE» UA=&#39;uagv1&#39;<br>Oct 29 15:11:29.670249 spce proxy[6041]: INFO: ROUTE_NCOS_CHECK &lt;script&gt;: Check Administrative Contract NCOS level - R=«sip:bob@ss.example.org:5060» ID=«FiLArRmpsyS5gpLCFSHR7jzDRpQiYPSE» UA=&#39;uagv1&#39;<br>Oct 29 15:11:29.670259 spce proxy[6041]: INFO: ROUTE_NCOS_CHECK &lt;script&gt;: Check Administrative Contract NCOS Set - R=«sip:bob@ss.example.org:5060» ID=«FiLArRmpsyS5gpLCFSHR7jzDRpQiYPSE» UA=&#39;uagv1&#39;<br>Oct 29 15:11:29.670268 spce proxy[6041]: INFO: ROUTE_NCOS_CHECK &lt;script&gt;: Check Administrative NCOS level - R=«sip:bob@ss.example.org:5060» ID=«FiLArRmpsyS5gpLCFSHR7jzDRpQiYPSE» UA=&#39;uagv1&#39;<br>Oct 29 15:11:29.670278 spce proxy[6041]: INFO: ROUTE_NCOS_CHECK &lt;script&gt;: Check Administrative NCOS Set - R=«sip:bob@ss.example.org:5060» ID=«FiLArRmpsyS5gpLCFSHR7jzDRpQiYPSE» UA=&#39;uagv1&#39;<br>Oct 29 15:11:29.670287 spce proxy[6041]: INFO: ROUTE_NCOS_CHECK &lt;script&gt;: Check Contract NCOS level - R=«sip:bob@ss.example.org:5060» ID=«FiLArRmpsyS5gpLCFSHR7jzDRpQiYPSE» UA=&#39;uagv1&#39;<br>Oct 29 15:11:29.670297 spce proxy[6041]: INFO: ROUTE_NCOS_CHECK &lt;script&gt;: Check Contract NCOS Set - R=«sip:bob@ss.example.org:5060» ID=«FiLArRmpsyS5gpLCFSHR7jzDRpQiYPSE» UA=&#39;uagv1&#39;<br>Oct 29 15:11:29.670306 spce proxy[6041]: INFO: ROUTE_NCOS_CHECK &lt;script&gt;: Check User NCOS level - R=«sip:bob@ss.example.org:5060» ID=«FiLArRmpsyS5gpLCFSHR7jzDRpQiYPSE» UA=&#39;uagv1&#39;<br>Oct 29 15:11:29.670315 spce proxy[6041]: INFO: ROUTE_NCOS_CHECK &lt;script&gt;: Check User NCOS Set - R=«sip:bob@ss.example.org:5060» ID=«FiLArRmpsyS5gpLCFSHR7jzDRpQiYPSE» UA=&#39;uagv1&#39;<br>Oct 29 15:11:29.670325 spce proxy[6041]: INFO: ROUTE_BLOCK_OUT &lt;script&gt;: Checking URI &#39;«<a href="mailto:sip%3Abob@ss.example.org">sip:bob@ss.example.org</a>»&#39; and CLI &#39;«51187654321»&#39; against admin contract block out lists - R=«sip:bob@ss.example.org:5060» ID=«FiLArRmpsyS5gpLCFSHR7jzDRpQiYPSE» UA=&#39;uagv1&#39;<br>Oct 29 15:11:29.670334 spce proxy[6041]: INFO: ROUTE_BLOCK_OUT &lt;script&gt;: Admin Contract caller block mode is &#39;blacklist&#39; - R=«sip:bob@ss.example.org:5060» ID=«FiLArRmpsyS5gpLCFSHR7jzDRpQiYPSE» UA=&#39;uagv1&#39;<br>Oct 29 15:11:29.670343 spce proxy[6041]: INFO: ROUTE_BLOCK_OUT &lt;script&gt;: Checking URI &#39;«<a href="mailto:sip%3Abob@ss.example.org">sip:bob@ss.example.org</a>»&#39; and CLI &#39;«51187654321»&#39; against block out lists - R=«sip:bob@ss.example.org:5060» ID=«FiLArRmpsyS5gpLCFSHR7jzDRpQiYPSE» UA=&#39;uagv1&#39;<br>Oct 29 15:11:29.670352 spce proxy[6041]: INFO: ROUTE_BLOCK_OUT &lt;script&gt;: Admin caller block mode is &#39;blacklist&#39; - R=«sip:bob@ss.example.org:5060» ID=«FiLArRmpsyS5gpLCFSHR7jzDRpQiYPSE» UA=&#39;uagv1&#39;<br>Oct 29 15:11:29.670361 spce proxy[6041]: INFO: ROUTE_BLOCK_OUT &lt;script&gt;: Checking URI &#39;«<a href="mailto:sip%3Abob@ss.example.org">sip:bob@ss.example.org</a>»&#39; and CLI &#39;«51187654321»&#39; against contract block out lists - R=«sip:bob@ss.example.org:5060» ID=«FiLArRmpsyS5gpLCFSHR7jzDRpQiYPSE» UA=&#39;uagv1&#39;<br>Oct 29 15:11:29.670370 spce proxy[6041]: INFO: ROUTE_BLOCK_OUT &lt;script&gt;: Contract caller block mode is &#39;blacklist&#39; - R=«sip:bob@ss.example.org:5060» ID=«FiLArRmpsyS5gpLCFSHR7jzDRpQiYPSE» UA=&#39;uagv1&#39;<br>Oct 29 15:11:29.670379 spce proxy[6041]: INFO: ROUTE_BLOCK_OUT &lt;script&gt;: Caller block mode is &#39;blacklist&#39; - R=«sip:bob@ss.example.org:5060» ID=«FiLArRmpsyS5gpLCFSHR7jzDRpQiYPSE» UA=&#39;uagv1&#39;<br>Oct 29 15:11:29.671206 spce proxy[6041]: INFO: ROUTE_INVITE_TO_INT &lt;script&gt;: Dialog set mark type to local - R=«sip:bob@ss.example.org:5060» ID=«FiLArRmpsyS5gpLCFSHR7jzDRpQiYPSE» UA=&#39;uagv1&#39;<br>Oct 29 15:11:29.673744 spce proxy[6041]: INFO: ROUTE_SET_CALLER_DIALOG_TOTAL &lt;script&gt;: Dialog set total - R=«sip:bob-c6NONwRkf6N5JRP@192.168.1.103:43779» ID=«FiLArRmpsyS5gpLCFSHR7jzDRpQiYPSE» UA=&#39;uagv1&#39;<br>Oct 29 15:11:29.673825 spce proxy[6041]: INFO: ROUTE_SET_CALLER_DIALOG_TOTAL &lt;script&gt;: Set caller dialogs: totaluser, totaluserout, totalaccount, totalaccountout to &#39;«03fd71a7-df7a-4f89-8eb6-7283013550dc»/«2»&#39; - R=«sip:bob-c6NONwRkf6N5JRP@192.168.1.103:43779» ID=«FiLArRmpsyS5gpLCFSHR7jzDRpQiYPSE» UA=&#39;uagv1&#39;<br>Oct 29 15:11:29.675648 spce proxy[6041]: INFO: ROUTE_SET_CALLER_DIALOG_BASE &lt;script&gt;: Set caller dialogs: user, userout, account, accountout to &#39;«03fd71a7-df7a-4f89-8eb6-7283013550dc»/«2»&#39; - R=«sip:bob-c6NONwRkf6N5JRP@192.168.1.103:43779» ID=«FiLArRmpsyS5gpLCFSHR7jzDRpQiYPSE» UA=&#39;uagv1&#39;<br>Oct 29 15:11:29.676489 spce proxy[6041]: NOTICE: ROUTE_ACC_CALLER &lt;script&gt;: Setting acc source-leg for uuid &#39;«03fd71a7-df7a-4f89-8eb6-7283013550dc»&#39;: &#39;«{&quot;gpp&quot;:[null,null,null,null,null,null,null,null,null,null],&quot;clir&quot;:0,&quot;uuid&quot;:&quot;03fd71a7-df7a-4f89-8eb6-7283013550dc&quot;,&quot;u&quot;:&quot;alice&quot;,&quot;d&quot;:&quot;<a href="http://ss.example.org">ss.example.org</a>&quot;,&quot;cli&quot;:&quot;51123456789&quot;,&quot;s_id&quot;:&quot;&quot;,&quot;c_id&quot;:&quot;&quot;,&quot;a_id&quot;:2,&quot;pau&quot;:&quot;&quot;,&quot;par&quot;:&quot;&quot;,&quot;s&quot;:&quot;call&quot;,&quot;ip&quot;:&quot;172.16.100.209&quot;,&quot;t&quot;:1761761489.6761539,&quot;lnp_p&quot;:&quot;&quot;,&quot;cli_out&quot;:&quot;51123456789&quot;,&quot;lnp_t&quot;:&quot;&quot;,&quot;pai&quot;:&quot;&quot;,&quot;ppi&quot;:&quot;&quot;,&quot;div&quot;:&quot;&quot;,&quot;last_hih&quot;:&quot;&quot;,&quot;cid&quot;:&quot;&quot;,&quot;u2u&quot;:&quot;&quot;,&quot;lcr&quot;:0,&quot;cc_quota&quot;:&quot;&quot;,&quot;cc_sub&quot;:&quot;1&quot;,&quot;cc_cust&quot;:&quot;2&quot;}»&#39; - R=«sip:bob-c6NONwRkf6N5JRP@192.168.1.103:43779» ID=«FiLArRmpsyS5gpLCFSHR7jzDRpQiYPSE» UA=&#39;uagv1&#39;<br>Oct 29 15:11:29.677193 spce proxy[6041]: NOTICE: ROUTE_ACC_CALLEE &lt;script&gt;: Setting acc destination-leg for uuid &#39;«99d31b34-96d5-4dbb-b89a-14847096007c»&#39;: &#39;«{&quot;gpp&quot;:[null,null,null,null,null,null,null,null,null,null],&quot;plu&quot;:0,&quot;s_id&quot;:&quot;&quot;,&quot;c_id&quot;:&quot;&quot;,&quot;a_id&quot;:2,&quot;dialed&quot;:&quot;51187654321&quot;,&quot;uuid&quot;:&quot;99d31b34-96d5-4dbb-b89a-14847096007c&quot;,&quot;u&quot;:&quot;bob&quot;,&quot;d&quot;:&quot;<a href="http://ss.example.org">ss.example.org</a>&quot;,&quot;u_in&quot;:&quot;51187654321&quot;,&quot;d_in&quot;:&quot;<a href="http://ss.example.org">ss.example.org</a>&quot;,&quot;lcr&quot;:0,&quot;lnp_p&quot;:&quot;&quot;,&quot;u_out&quot;:&quot;bob&quot;,&quot;lnp_t&quot;:&quot;&quot;,&quot;fci&quot;:&quot;&quot;,&quot;cc_quota&quot;:&quot;&quot;,&quot;cc_sub&quot;:&quot;1&quot;,&quot;cc_cust&quot;:&quot;2&quot;}»&#39; - R=«sip:bob-c6NONwRkf6N5JRP@192.168.1.103:43779» ID=«FiLArRmpsyS5gpLCFSHR7jzDRpQiYPSE» UA=&#39;uagv1&#39;<br>Oct 29 15:11:29.677244 spce proxy[6041]: INFO: ROUTE_OUTBOUND &lt;script&gt;: Relaying request, du=&#39;«<a href="mailto:sip%3Alb@127.0.0.1">sip:lb@127.0.0.1</a>;lr;received=sip:160.1.100.100:43779;socket=sip:131.3.1.1:5060»&#39; - R=«sip:bob-c6NONwRkf6N5JRP@192.168.1.103:43779» ID=«FiLArRmpsyS5gpLCFSHR7jzDRpQiYPSE» UA=&#39;uagv1&#39;<br>Oct 29 15:11:29.677506 spce proxy[6041]: INFO: BRANCH_ROUTE_SBC &lt;script&gt;: +++ Entering branch route BRANCH_ROUTE_SBC with dest uri «<a href="mailto:sip%3Alb@127.0.0.1">sip:lb@127.0.0.1</a>;lr;received=sip:160.1.100.100:43779;socket=sip:131.3.1.1:5060» - R=«sip:bob-c6NONwRkf6N5JRP@192.168.1.103:43779» ID=«FiLArRmpsyS5gpLCFSHR7jzDRpQiYPSE» UA=&#39;uagv1&#39;<br>Oct 29 15:11:29.677750 spce proxy[6041]: NOTICE: ROUTE_LOAD_CALLEE_CONTRACT_PREF &lt;script&gt;: Load callee contract preferences for contract id &#39;«2» and ip &#39;«160.1.100.100»&#39; - R=«sip:bob-c6NONwRkf6N5JRP@192.168.1.103:43779» ID=«FiLArRmpsyS5gpLCFSHR7jzDRpQiYPSE» UA=&#39;uagv1&#39;<br>Oct 29 15:11:29.678082 spce proxy[6041]: INFO: ROUTE_LOAD_CALLEE_CONTRACT_PREF &lt;script&gt;: Loaded callee contract preferences for location id &#39;«&lt;null&gt;»&#39; - R=«sip:bob-c6NONwRkf6N5JRP@192.168.1.103:43779» ID=«FiLArRmpsyS5gpLCFSHR7jzDRpQiYPSE» UA=&#39;uagv1&#39;<br>Oct 29 15:11:29.678099 spce proxy[6041]: NOTICE: ROUTE_LOAD_CALLEE_RESELLER_PREF &lt;script&gt;: Load callee reseller preferences for reseller id &#39;«1» - R=«sip:bob-c6NONwRkf6N5JRP@192.168.1.103:43779» ID=«FiLArRmpsyS5gpLCFSHR7jzDRpQiYPSE» UA=&#39;uagv1&#39;<br>Oct 29 15:11:29.678297 spce proxy[6041]: INFO: ROUTE_SET_CALLEE_DIALOG_BASE &lt;script&gt;: Set callee dialogs: user, account to &#39;«99d31b34-96d5-4dbb-b89a-14847096007c»/2&#39; - R=«sip:bob-c6NONwRkf6N5JRP@192.168.1.103:43779» ID=«FiLArRmpsyS5gpLCFSHR7jzDRpQiYPSE» UA=&#39;uagv1&#39;<br>Oct 29 15:11:29.678314 spce proxy[6041]: INFO: ROUTE_SET_CALLEE_DIALOG_TOTAL &lt;script&gt;: Set callee dialogs: totaluser, totalaccount,totalreseller to &#39;«99d31b34-96d5-4dbb-b89a-14847096007c»/2/1&#39; - R=«sip:bob-c6NONwRkf6N5JRP@192.168.1.103:43779» ID=«FiLArRmpsyS5gpLCFSHR7jzDRpQiYPSE» UA=&#39;uagv1&#39;<br>Oct 29 15:11:29.678354 spce proxy[6041]: INFO: ROUTE_SET_BRANCH_HDRS &lt;script&gt;: Setting P-Caller-UUID to &#39;«03fd71a7-df7a-4f89-8eb6-7283013550dc»&#39; - R=«sip:bob-c6NONwRkf6N5JRP@192.168.1.103:43779» ID=«FiLArRmpsyS5gpLCFSHR7jzDRpQiYPSE» UA=&#39;uagv1&#39;<br>Oct 29 15:11:29.678420 spce proxy[6041]: INFO: ROUTE_SET_BRANCH_HDRS &lt;script&gt;: Setting P-Callee-UUID to &#39;«99d31b34-96d5-4dbb-b89a-14847096007c»&#39; - R=«sip:bob-c6NONwRkf6N5JRP@192.168.1.103:43779» ID=«FiLArRmpsyS5gpLCFSHR7jzDRpQiYPSE» UA=&#39;uagv1&#39;<br>Oct 29 15:11:29.678497 spce proxy[6041]: INFO: ROUTE_PREPARE_UA &lt;script&gt;: User Agent header removed - R=«sip:bob-c6NONwRkf6N5JRP@192.168.1.103:43779» ID=«FiLArRmpsyS5gpLCFSHR7jzDRpQiYPSE» UA=&#39;uagv1&#39;<br>Oct 29 15:11:29.678588 spce proxy[6041]: INFO: ROUTE_SET_RUSER &lt;script&gt;: Local user online, using registered contact as user - R=«sip:bob-c6NONwRkf6N5JRP@192.168.1.103:43779» ID=«FiLArRmpsyS5gpLCFSHR7jzDRpQiYPSE» UA=&#39;uagv1&#39;<br>Oct 29 15:11:29.678689 spce proxy[6041]: NOTICE: ROUTE_BRANCH_ACC_RTP &lt;script&gt;: Not Forcing RTP/AVP towards b2b because local service or caller/callee are not pbx users - R=«sip:bob-c6NONwRkf6N5JRP@192.168.1.103:43779» ID=«FiLArRmpsyS5gpLCFSHR7jzDRpQiYPSE» UA=&#39;uagv1&#39;<br>Oct 29 15:11:29.678706 spce proxy[6041]: ERROR: ROUTE_BRANCH_ACC_RTP dialog [dialog.c:1868]: ki_dlg_get_var_helper(): invalid Call-ID parameter<br>Oct 29 15:11:29.678811 spce proxy[6041]: INFO: ROUTE_BRANCH_ACC_RTP &lt;script&gt;: Use rtpengine for forward direction for IPv4/IPv4 - R=«sip:bob-c6NONwRkf6N5JRP@192.168.1.103:43779» ID=«FiLArRmpsyS5gpLCFSHR7jzDRpQiYPSE» UA=&#39;uagv1&#39;<br>Oct 29 15:11:29.679856 spce proxy[6041]: INFO: ROUTE_BRANCH_ACC_RTP &lt;script&gt;: Remove existing ICE candidates (if any) for call to local service - R=«sip:bob-c6NONwRkf6N5JRP@192.168.1.103:43779» ID=«FiLArRmpsyS5gpLCFSHR7jzDRpQiYPSE» UA=&#39;uagv1&#39;<br>Oct 29 15:11:29.679874 spce proxy[6041]: INFO: ROUTE_BRANCH_ACC_RTP &lt;script&gt;: Try protocol &#39;transparent&#39; for callee - R=«sip:bob-c6NONwRkf6N5JRP@192.168.1.103:43779» ID=«FiLArRmpsyS5gpLCFSHR7jzDRpQiYPSE» UA=&#39;uagv1&#39;<br>Oct 29 15:11:29.679884 spce proxy[6041]: INFO: ROUTE_BRANCH_ACC_RTP &lt;script&gt;: Use rtcp-mux=[demux] for callee - R=«sip:bob-c6NONwRkf6N5JRP@192.168.1.103:43779» ID=«FiLArRmpsyS5gpLCFSHR7jzDRpQiYPSE» UA=&#39;uagv1&#39;<br>Oct 29 15:11:29.679896 spce proxy[6041]: INFO: ROUTE_BRANCH_ACC_RTP &lt;script&gt;: Engaging rtpengine in request for caller did &#39;«50»&#39; and callee did &#39;«50»&#39; - R=«sip:bob-c6NONwRkf6N5JRP@192.168.1.103:43779» ID=«FiLArRmpsyS5gpLCFSHR7jzDRpQiYPSE» UA=&#39;uagv1&#39;<br>Oct 29 15:11:29.679907 spce proxy[6041]: INFO: ROUTE_BRANCH_ACC_RTP &lt;script&gt;: Setting last transport protocol to «transparent» - R=«sip:bob-c6NONwRkf6N5JRP@192.168.1.103:43779» ID=«FiLArRmpsyS5gpLCFSHR7jzDRpQiYPSE» UA=&#39;uagv1&#39;<br>Oct 29 15:11:29.680001 spce proxy[6041]: DEBUG: ROUTE_BRANCH_ACC_RTP &lt;script&gt;: RTPENGINE OFFER: rtpp_flags:[address-family=IP4 debug transport-protocol=transparent rtcp-mux=[demux] ICE=remove ]- R=«sip:bob-c6NONwRkf6N5JRP@192.168.1.103:43779» ID=«FiLArRmpsyS5gpLCFSHR7jzDRpQiYPSE» UA=&#39;uagv1&#39;<br>Oct 29 15:11:29.682632 spce proxy[6041]: INFO: ROUTE_PREPARE_SST &lt;script&gt;: Sessions Timers enabled, check configuration of caller and callee  - ID=«FiLArRmpsyS5gpLCFSHR7jzDRpQiYPSE» UA=&#39;uagv1&#39;<br>Oct 29 15:11:29.682933 spce proxy[6041]: INFO: ROUTE_PREPARE_SST &lt;script&gt;: Sessions Timers disabled for caller - R=«sip:bob-c6NONwRkf6N5JRP@192.168.1.103:43779» ID=«FiLArRmpsyS5gpLCFSHR7jzDRpQiYPSE» UA=&#39;uagv1&#39;<br>Oct 29 15:11:29.683216 spce proxy[6041]: INFO: ROUTE_PREPARE_SST &lt;script&gt;: Sessions Timers disabled for callee - R=«sip:bob-c6NONwRkf6N5JRP@192.168.1.103:43779» ID=«FiLArRmpsyS5gpLCFSHR7jzDRpQiYPSE» UA=&#39;uagv1&#39;<br>Oct 29 15:11:29.683226 spce proxy[6041]: INFO: ROUTE_REMOVE_TIMER_SUPP_REQ &lt;script&gt;: Timer successfully removed from Supported - ID=«FiLArRmpsyS5gpLCFSHR7jzDRpQiYPSE» UA=&#39;uagv1&#39;<br>Oct 29 15:11:29.683235 spce proxy[6041]: INFO: ROUTE_REMOVE_TIMER_SUPP_REQ &lt;script&gt;: Timer successfully removed from Require - ID=«FiLArRmpsyS5gpLCFSHR7jzDRpQiYPSE» UA=&#39;uagv1&#39;<br>Oct 29 15:11:29.683244 spce proxy[6041]: INFO: ROUTE_REMOVE_TIMER_SUPP_REQ &lt;script&gt;: Session-Expires successfully removed - R=«sip:bob-c6NONwRkf6N5JRP@192.168.1.103:43779» ID=«FiLArRmpsyS5gpLCFSHR7jzDRpQiYPSE» UA=&#39;uagv1&#39;<br>Oct 29 15:11:29.683254 spce proxy[6041]: INFO: ROUTE_SET_CALLER_CLI &lt;script&gt;: Setting userprovided caller domain - R=«sip:bob-c6NONwRkf6N5JRP@192.168.1.103:43779» ID=«FiLArRmpsyS5gpLCFSHR7jzDRpQiYPSE» UA=&#39;uagv1&#39;<br>Oct 29 15:11:29.683263 spce proxy[6041]: INFO: ROUTE_SET_CALLER_CLI &lt;script&gt;: Use first userprov caller domain &#39;«<a href="http://ss.example.org">ss.example.org</a>»&#39; - R=«sip:bob-c6NONwRkf6N5JRP@192.168.1.103:43779» ID=«FiLArRmpsyS5gpLCFSHR7jzDRpQiYPSE» UA=&#39;uagv1&#39;<br>Oct 29 15:11:29.683272 spce proxy[6041]: INFO: ROUTE_SET_CALLER_CLI &lt;script&gt;: Prepare >From display-name setting - R=«sip:bob-c6NONwRkf6N5JRP@192.168.1.103:43779» ID=«FiLArRmpsyS5gpLCFSHR7jzDRpQiYPSE» UA=&#39;uagv1&#39;<br>Oct 29 15:11:29.683282 spce proxy[6041]: INFO: ROUTE_PREPARE_CALLER_CLI &lt;script&gt;: No selector set, not setting CLI - R=«sip:bob-c6NONwRkf6N5JRP@192.168.1.103:43779» ID=«FiLArRmpsyS5gpLCFSHR7jzDRpQiYPSE» UA=&#39;uagv1&#39;<br>Oct 29 15:11:29.683291 spce proxy[6041]: INFO: ROUTE_SET_CALLER_CLI &lt;script&gt;: Prepare From username setting - R=«sip:bob-c6NONwRkf6N5JRP@192.168.1.103:43779» ID=«FiLArRmpsyS5gpLCFSHR7jzDRpQiYPSE» UA=&#39;uagv1&#39;<br>Oct 29 15:11:29.683300 spce proxy[6041]: NOTICE: ROUTE_PREPARE_CALLER_CLI &lt;script&gt;: Setting caller_cli_userprov/caller_domain_userprov &#39;«51123456789»@«<a href="http://ss.example.org">ss.example.org</a>»&#39; for upn - R=«sip:bob-c6NONwRkf6N5JRP@192.168.1.103:43779» ID=«FiLArRmpsyS5gpLCFSHR7jzDRpQiYPSE» UA=&#39;uagv1&#39;<br>Oct 29 15:11:29.683309 spce proxy[6041]: NOTICE: ROUTE_SET_CALLER_CLI &lt;script&gt;: Setting From to &#39;&lt;«<a href="mailto:sip%3A51123456789@ss.example.org">sip:51123456789@ss.example.org</a>»&gt;&#39; - R=«sip:bob-c6NONwRkf6N5JRP@192.168.1.103:43779» ID=«FiLArRmpsyS5gpLCFSHR7jzDRpQiYPSE» UA=&#39;uagv1&#39;<br>Oct 29 15:11:29.683317 spce proxy[6041]: INFO: ROUTE_SET_CALLER_CLI &lt;script&gt;: Prepare PAI display-name setting - R=«sip:bob-c6NONwRkf6N5JRP@192.168.1.103:43779» ID=«FiLArRmpsyS5gpLCFSHR7jzDRpQiYPSE» UA=&#39;uagv1&#39;<br>Oct 29 15:11:29.683327 spce proxy[6041]: INFO: ROUTE_PREPARE_CALLER_CLI &lt;script&gt;: No selector set, not setting CLI - R=«sip:bob-c6NONwRkf6N5JRP@192.168.1.103:43779» ID=«FiLArRmpsyS5gpLCFSHR7jzDRpQiYPSE» UA=&#39;uagv1&#39;<br>Oct 29 15:11:29.683336 spce proxy[6041]: INFO: ROUTE_SET_CALLER_CLI &lt;script&gt;: Prepare PAI username setting - R=«sip:bob-c6NONwRkf6N5JRP@192.168.1.103:43779» ID=«FiLArRmpsyS5gpLCFSHR7jzDRpQiYPSE» UA=&#39;uagv1&#39;<br>Oct 29 15:11:29.683345 spce proxy[6041]: NOTICE: ROUTE_PREPARE_CALLER_CLI &lt;script&gt;: Setting caller_cli_netprov/caller_domain_netprov &#39;«51123456789»@«<a href="http://ss.example.org">ss.example.org</a>»&#39; for npn - R=«sip:bob-c6NONwRkf6N5JRP@192.168.1.103:43779» ID=«FiLArRmpsyS5gpLCFSHR7jzDRpQiYPSE» UA=&#39;uagv1&#39;<br>Oct 29 15:11:29.683354 spce proxy[6041]: NOTICE: ROUTE_SET_CALLER_CLI &lt;script&gt;: Setting PAI to &#39;&lt;«<a href="mailto:sip%3A51123456789@ss.example.org">sip:51123456789@ss.example.org</a>»&gt;&#39; - R=«sip:bob-c6NONwRkf6N5JRP@192.168.1.103:43779» ID=«FiLArRmpsyS5gpLCFSHR7jzDRpQiYPSE» UA=&#39;uagv1&#39;<br>Oct 29 15:11:29.683363 spce proxy[6041]: INFO: ROUTE_SET_CALLER_CLI &lt;script&gt;: Prepare PPI username setting - R=«sip:bob-c6NONwRkf6N5JRP@192.168.1.103:43779» ID=«FiLArRmpsyS5gpLCFSHR7jzDRpQiYPSE» UA=&#39;uagv1&#39;<br>Oct 29 15:11:29.683372 spce proxy[6041]: INFO: ROUTE_PREPARE_CALLER_CLI &lt;script&gt;: No selector set, not setting CLI - R=«sip:bob-c6NONwRkf6N5JRP@192.168.1.103:43779» ID=«FiLArRmpsyS5gpLCFSHR7jzDRpQiYPSE» UA=&#39;uagv1&#39;<br>Oct 29 15:11:29.683381 spce proxy[6041]: INFO: ROUTE_PREPARE_CALLER_CLI &lt;script&gt;: No selector set, not setting CLI - R=«sip:bob-c6NONwRkf6N5JRP@192.168.1.103:43779» ID=«FiLArRmpsyS5gpLCFSHR7jzDRpQiYPSE» UA=&#39;uagv1&#39;<br>Oct 29 15:11:29.683390 spce proxy[6041]: INFO: BRANCH_ROUTE_SBC &lt;script&gt;: Prepare P-Called-Party-ID setting using selector &#39;callee&#39; - R=«sip:bob-c6NONwRkf6N5JRP@192.168.1.103:43779» ID=«FiLArRmpsyS5gpLCFSHR7jzDRpQiYPSE» UA=&#39;uagv1&#39;<br>Oct 29 15:11:29.683399 spce proxy[6041]: NOTICE: BRANCH_ROUTE_SBC &lt;script&gt;: Setting P-Called-Party-ID &#39;&lt;sip:«bob-c6NONwRkf6N5JRP»@«<a href="http://ss.example.org">ss.example.org</a>»&gt;&#39; - R=«sip:bob-c6NONwRkf6N5JRP@192.168.1.103:43779» ID=«FiLArRmpsyS5gpLCFSHR7jzDRpQiYPSE» UA=&#39;uagv1&#39;<br>Oct 29 15:11:29.683408 spce proxy[6041]: INFO: BRANCH_ROUTE_SBC &lt;script&gt;: Leg A info set on header P-NGCP-Leg-A-Info with encoded value of «FiLArRmpsyS5gpLCFSHR7jzDRpQiYPSE» «VxUyKI6TlvPyt7OGWLD-tWDU3S5Yq9p-» - R=«sip:bob-c6NONwRkf6N5JRP@192.168.1.103:43779» ID=«FiLArRmpsyS5gpLCFSHR7jzDRpQiYPSE» UA=&#39;uagv1&#39;<br>Oct 29 15:11:29.683418 spce proxy[6041]: NOTICE: BRANCH_ROUTE_SBC &lt;script&gt;: Writing sbc parameters «;calltimer=21600;aleg_sst_enable=no;sst_enable=no;hold_alter_b2b_bleg=no;hold_alter_b2b_aleg=no;a_park_domain=2;b_park_domain=2» - R=«sip:bob-c6NONwRkf6N5JRP@192.168.1.103:43779» ID=«FiLArRmpsyS5gpLCFSHR7jzDRpQiYPSE» UA=&#39;uagv1&#39;<br>Oct 29 15:11:29.683435 spce proxy[6041]: INFO: ROUTE_ADD_CALLINFO &lt;script&gt;: Adding P-NGCP-Caller-Info &#39;&lt;sip:«alice»@«<a href="http://ss.example.org">ss.example.org</a>»&gt;;ip=«172.16.100.209»;port=«5060»«;primary=51123456789»«»&#39; - R=«sip:bob-c6NONwRkf6N5JRP@192.168.1.103:43779» ID=«FiLArRmpsyS5gpLCFSHR7jzDRpQiYPSE» UA=&#39;uagv1&#39;<br>Oct 29 15:11:29.683446 spce proxy[6041]: INFO: ROUTE_ADD_CALLINFO &lt;script&gt;: Adding P-NGCP-Callee-Info &#39;&lt;sip:«51187654321»@«<a href="http://ss.example.org">ss.example.org</a>»&gt;;ip=«160.1.100.100»;port=«43779»«;primary=51187654321»«»&#39; - R=«sip:bob-c6NONwRkf6N5JRP@192.168.1.103:43779» ID=«FiLArRmpsyS5gpLCFSHR7jzDRpQiYPSE» UA=&#39;uagv1&#39;<br>Oct 29 15:11:29.683457 spce proxy[6041]: NOTICE: BRANCH_ROUTE_SBC &lt;script&gt;: Appending P-D-URI &#39;«<a href="mailto:sip%3Alb@127.0.0.1">sip:lb@127.0.0.1</a>;lr;received=sip:160.1.100.100:43779;socket=sip:131.3.1.1:5060»&#39; - R=«sip:bob-c6NONwRkf6N5JRP@192.168.1.103:43779» ID=«FiLArRmpsyS5gpLCFSHR7jzDRpQiYPSE» UA=&#39;uagv1&#39;<br>Oct 29 15:11:29.683467 spce proxy[6041]: NOTICE: BRANCH_ROUTE_SBC &lt;script&gt;: Forcing request via B2BUA &#39;«sip:127.0.0.1:5080»&#39; - R=«sip:bob-c6NONwRkf6N5JRP@192.168.1.103:43779» ID=«FiLArRmpsyS5gpLCFSHR7jzDRpQiYPSE» UA=&#39;uagv1&#39;<br>Oct 29 15:11:29.685494 spce proxy[6041]: NOTICE: DEFAULT_SEND &lt;script&gt;: Request leaving server, M=INVITE fs=&#39;«127.0.0.1»:«5062»&#39; du=&#39;«127.0.0.1»:«5080»&#39; - R=«sip:bob-c6NONwRkf6N5JRP@192.168.1.103:43779» ID=«FiLArRmpsyS5gpLCFSHR7jzDRpQiYPSE» UA=&#39;uagv1&#39;<br>Oct 29 15:11:29.686675 spce proxy[6041]: INFO: ROUTE_EXIT &lt;script&gt;: INVITE processed - ID=«FiLArRmpsyS5gpLCFSHR7jzDRpQiYPSE»<br>Oct 29 15:11:29.686686 spce proxy[6041]: INFO: ROUTE_EXIT &lt;script&gt;: Runtime for request M=INVITE was 38954 usec - ID=«FiLArRmpsyS5gpLCFSHR7jzDRpQiYPSE»<br>Oct 29 15:11:29.697061 spce proxy[6047]: NOTICE: DEFAULT_ONREPLY &lt;script&gt;: New reply on proxy - M=INVITE ID=«FiLArRmpsyS5gpLCFSHR7jzDRpQiYPSE» UA=&#39;&lt;null&gt;&#39;<br>Oct 29 15:11:29.697316 spce proxy[6047]: NOTICE: REPLY_ROUTE_NAT &lt;script&gt;: NAT-Reply - S=100 - Connecting M=INVITE IP=«172.16.100.209»:«5060» («127.0.0.1»:«5080») ID=«FiLArRmpsyS5gpLCFSHR7jzDRpQiYPSE» UA=&#39;&lt;null&gt;&#39; DESTIP=«127.0.0.1»:«5062»<br>Oct 29 15:11:29.697341 spce proxy[6047]: INFO: ROUTE_EXIT &lt;script&gt;: INVITE processed - ID=«FiLArRmpsyS5gpLCFSHR7jzDRpQiYPSE»<br>Oct 29 15:11:29.697361 spce proxy[6047]: INFO: ROUTE_EXIT &lt;script&gt;: Runtime for response M=INVITE 100 was 421 usec - ID=«FiLArRmpsyS5gpLCFSHR7jzDRpQiYPSE»<br>Oct 29 15:11:29.698517 spce proxy[6042]: NOTICE: DEFAULT_ROUTE &lt;script&gt;: New request on proxy for the B LEG of the call - M=INVITE R=«sip:bob-c6NONwRkf6N5JRP@192.168.1.103:43779» F=«<a href="mailto:sip%3A51123456789@ss.example.org">sip:51123456789@ss.example.org</a>» T=«<a href="mailto:sip%3Abob-c6NONwRkf6N5JRP@ss.example.org">sip:bob-c6NONwRkf6N5JRP@ss.example.org</a>» IP=«&lt;null&gt;»:«&lt;null&gt;» («127.0.0.1»:«5080») ID=«FiLArRmpsyS5gpLCFSHR7jzDRpQiYPSE_b2b-1» UA=&#39;&lt;null&gt;&#39; DESTIP=«127.0.0.1»:«5062»<br>Oct 29 15:11:29.698541 spce proxy[6042]: INFO: ROUTE_LEG_B &lt;script&gt;: Original P-D-Uri saved with value &#39;«<a href="mailto:sip%3Alb@127.0.0.1">sip:lb@127.0.0.1</a>;lr;received=sip:160.1.100.100:43779;socket=sip:131.3.1.1:5060»&#39; - R=«sip:bob-c6NONwRkf6N5JRP@192.168.1.103:43779» ID=«FiLArRmpsyS5gpLCFSHR7jzDRpQiYPSE_b2b-1» UA=&#39;&lt;null&gt;&#39;<br>Oct 29 15:11:29.698553 spce proxy[6042]: NOTICE: ROUTE_LEG_B &lt;script&gt;: Sending request to LB - R=«sip:bob-c6NONwRkf6N5JRP@192.168.1.103:43779» ID=«FiLArRmpsyS5gpLCFSHR7jzDRpQiYPSE_b2b-1» UA=&#39;&lt;null&gt;&#39;<br>Oct 29 15:11:29.698856 spce proxy[6042]: NOTICE: DEFAULT_SEND &lt;script&gt;: Request leaving server, M=INVITE fs=&#39;«127.0.0.1»:«5062»&#39; du=&#39;«127.0.0.1»:«5060»&#39; - R=«sip:bob-c6NONwRkf6N5JRP@192.168.1.103:43779» ID=«FiLArRmpsyS5gpLCFSHR7jzDRpQiYPSE_b2b-1» UA=&#39;&lt;null&gt;&#39;<br>Oct 29 15:11:29.698865 spce proxy[6042]: INFO: ROUTE_EXIT &lt;script&gt;: INVITE processed - ID=«FiLArRmpsyS5gpLCFSHR7jzDRpQiYPSE_b2b-1»<br>Oct 29 15:11:29.698874 spce proxy[6042]: INFO: ROUTE_EXIT &lt;script&gt;: Runtime for request M=INVITE was 776 usec - ID=«FiLArRmpsyS5gpLCFSHR7jzDRpQiYPSE_b2b-1»<br>Oct 29 15:11:29.701219 spce proxy[6046]: NOTICE: DEFAULT_ONREPLY &lt;script&gt;: New reply on proxy - M=INVITE ID=«FiLArRmpsyS5gpLCFSHR7jzDRpQiYPSE_b2b-1» UA=&#39;&lt;null&gt;&#39;<br>Oct 29 15:11:29.701237 spce proxy[6046]: NOTICE: REPLY_ROUTE_LEG_B &lt;script&gt;: *** Reply LEG_B - S=100 - Trying M=INVITE IP=«&lt;null&gt;»:«&lt;null&gt;» («127.0.0.1»:«5060») ID=«FiLArRmpsyS5gpLCFSHR7jzDRpQiYPSE_b2b-1» UA=&#39;&lt;null&gt;&#39; DESTIP=«127.0.0.1»:«5062»<br>Oct 29 15:11:29.701247 spce proxy[6046]: INFO: ROUTE_EXIT &lt;script&gt;: INVITE processed - ID=«FiLArRmpsyS5gpLCFSHR7jzDRpQiYPSE_b2b-1»<br>Oct 29 15:11:29.701256 spce proxy[6046]: INFO: ROUTE_EXIT &lt;script&gt;: Runtime for response M=INVITE 100 was 44 usec - ID=«FiLArRmpsyS5gpLCFSHR7jzDRpQiYPSE_b2b-1»<br>Oct 29 15:11:32.985838 spce proxy[6048]: WARNING: &lt;null&gt; db_redis [redis_dbase.c:1652]: db_redis_perform_query(): performing full table scan on table &#39;location&#39; while doing the query<br>Oct 29 15:11:32.985871 spce proxy[6048]: WARNING: &lt;null&gt; db_redis [redis_dbase.c:1656]: db_redis_perform_query():   scan key 0 is &#39;expires&#39;<br>Oct 29 15:11:32.985881 spce proxy[6048]: WARNING: &lt;null&gt; db_redis [redis_dbase.c:1656]: db_redis_perform_query():   scan key 1 is &#39;expires&#39;<br>Oct 29 15:11:38.569259 spce proxy[6063]: INFO: &lt;script&gt;: New XMLRPC request - M=POST IP=«127.0.0.1»:«45000»<br>Oct 29 15:11:38.576817 spce proxy[6064]: INFO: &lt;script&gt;: New XMLRPC request - M=POST IP=«127.0.0.1»:«45002»<br>Oct 29 15:11:38.582023 spce proxy[6065]: INFO: &lt;script&gt;: New XMLRPC request - M=POST IP=«127.0.0.1»:«45010»<br>Oct 29 15:11:38.587812 spce proxy[6066]: INFO: &lt;script&gt;: New XMLRPC request - M=POST IP=«127.0.0.1»:«45016»<br>Oct 29 15:11:38.616270 spce proxy[6063]: INFO: &lt;script&gt;: New XMLRPC request - M=POST IP=«127.0.0.1»:«45018»<br>Oct 29 15:11:48.563611 spce proxy[6064]: INFO: &lt;script&gt;: New XMLRPC request - M=POST IP=«127.0.0.1»:«48974»<br>Oct 29 15:11:48.572026 spce proxy[6065]: INFO: &lt;script&gt;: New XMLRPC request - M=POST IP=«127.0.0.1»:«48978»<br>Oct 29 15:11:48.578170 spce proxy[6066]: INFO: &lt;script&gt;: New XMLRPC request - M=POST IP=«127.0.0.1»:«48992»<br>Oct 29 15:11:48.580108 spce proxy[6063]: INFO: &lt;script&gt;: New XMLRPC request - M=POST IP=«127.0.0.1»:«49006»<br>Oct 29 15:11:48.609483 spce proxy[6064]: INFO: &lt;script&gt;: New XMLRPC request - M=POST IP=«127.0.0.1»:«49010»<br>Oct 29 15:11:58.568874 spce proxy[6065]: INFO: &lt;script&gt;: New XMLRPC request - M=POST IP=«127.0.0.1»:«59702»<br>Oct 29 15:11:58.576701 spce proxy[6066]: INFO: &lt;script&gt;: New XMLRPC request - M=POST IP=«127.0.0.1»:«59718»<br>Oct 29 15:11:58.581017 spce proxy[6063]: INFO: &lt;script&gt;: New XMLRPC request - M=POST IP=«127.0.0.1»:«59722»<br>Oct 29 15:11:58.584099 spce proxy[6064]: INFO: &lt;script&gt;: New XMLRPC request - M=POST IP=«127.0.0.1»:«59734»<br>Oct 29 15:11:58.612863 spce proxy[6065]: INFO: &lt;script&gt;: New XMLRPC request - M=POST IP=«127.0.0.1»:«59736»<br>Oct 29 15:11:59.643786 spce proxy[6044]: NOTICE: DEFAULT_ONREPLY &lt;script&gt;: New reply on proxy - M=INVITE ID=«FiLArRmpsyS5gpLCFSHR7jzDRpQiYPSE_b2b-1» UA=&#39;&lt;null&gt;&#39;<br>Oct 29 15:11:59.643950 spce proxy[6044]: NOTICE: REPLY_ROUTE_LEG_B &lt;script&gt;: *** Reply LEG_B - S=408 - Request Timeout M=INVITE IP=«&lt;null&gt;»:«&lt;null&gt;» («127.0.0.1»:«5060») ID=«FiLArRmpsyS5gpLCFSHR7jzDRpQiYPSE_b2b-1» UA=&#39;&lt;null&gt;&#39; DESTIP=«127.0.0.1»:«5062»<br>Oct 29 15:11:59.645015 spce proxy[6044]: NOTICE: REPLY_ROUTE_LEG_B &lt;script&gt;: Sending reply S=408 M=INVITE fs=&#39;«127.0.0.1»:«5062»&#39; du=&#39;«127.0.0.1»:«5080»&#39; - ID=«FiLArRmpsyS5gpLCFSHR7jzDRpQiYPSE_b2b-1» UA=&#39;&lt;null&gt;&#39;<br>Oct 29 15:11:59.645035 spce proxy[6044]: INFO: ROUTE_EXIT &lt;script&gt;: INVITE processed - ID=«FiLArRmpsyS5gpLCFSHR7jzDRpQiYPSE_b2b-1»<br>Oct 29 15:11:59.645046 spce proxy[6044]: INFO: ROUTE_EXIT &lt;script&gt;: Runtime for response M=INVITE 408 was 96 usec - ID=«FiLArRmpsyS5gpLCFSHR7jzDRpQiYPSE_b2b-1»<br>Oct 29 15:11:59.645076 spce proxy[6044]: NOTICE: FAILURE_ROUTE_LEG_B &lt;script&gt;: *** Failure route for leg-b call, code=&#39;408&#39; - R=«sip:bob-c6NONwRkf6N5JRP@192.168.1.103:43779» ID=«FiLArRmpsyS5gpLCFSHR7jzDRpQiYPSE_b2b-1» UA=&#39;&lt;null&gt;&#39;<br>Oct 29 15:11:59.645092 spce proxy[6044]: INFO: ROUTE_EXIT &lt;script&gt;: INVITE processed - ID=«FiLArRmpsyS5gpLCFSHR7jzDRpQiYPSE_b2b-1»<br>Oct 29 15:11:59.645103 spce proxy[6044]: INFO: ROUTE_EXIT &lt;script&gt;: Runtime for request M=INVITE was 33 usec - ID=«FiLArRmpsyS5gpLCFSHR7jzDRpQiYPSE_b2b-1»<br>Oct 29 15:11:59.646131 spce proxy[6041]: NOTICE: DEFAULT_ROUTE &lt;script&gt;: New request on proxy - M=ACK R=«sip:bob-c6NONwRkf6N5JRP@192.168.1.103:43779» F=«<a href="mailto:sip%3A51123456789@ss.example.org">sip:51123456789@ss.example.org</a>» T=«<a href="mailto:sip%3Abob-c6NONwRkf6N5JRP@ss.example.org">sip:bob-c6NONwRkf6N5JRP@ss.example.org</a>» IP=«127.0.0.1»:«5080» («127.0.0.1»:«5080») ID=«FiLArRmpsyS5gpLCFSHR7jzDRpQiYPSE_b2b-1» UA=&#39;&lt;null&gt;&#39; DESTIP=«127.0.0.1»:«5062»<br>Oct 29 15:11:59.646179 spce proxy[6041]: DEBUG: ROUTE_CHECK_TEL_URI &lt;script&gt;: x_hdr(From):«&lt;<a href="mailto:sip%3A51123456789@ss.example.org">sip:51123456789@ss.example.org</a>&gt;;tag=1E82B336-690258D1000A9ACA-8F48E6C0» - R=«sip:bob-c6NONwRkf6N5JRP@192.168.1.103:43779» ID=«FiLArRmpsyS5gpLCFSHR7jzDRpQiYPSE_b2b-1» UA=&#39;&lt;null&gt;&#39;<br>Oct 29 15:11:59.646268 spce proxy[6041]: DEBUG: DEFAULT_ROUTE &lt;script&gt;: pua_dialoginfo: Disable PUBLISH messages to caller setting FLB_PRESENCE_CALLER flag - R=«sip:bob-c6NONwRkf6N5JRP@192.168.1.103:43779» ID=«FiLArRmpsyS5gpLCFSHR7jzDRpQiYPSE_b2b-1» UA=&#39;&lt;null&gt;&#39;<br>Oct 29 15:11:59.646277 spce proxy[6041]: DEBUG: DEFAULT_ROUTE &lt;script&gt;: pua_dialoginfo: Disable PUBLISH messages to callee setting FLB_PRESENCE_CALLEE flag - R=«sip:bob-c6NONwRkf6N5JRP@192.168.1.103:43779» ID=«FiLArRmpsyS5gpLCFSHR7jzDRpQiYPSE_b2b-1» UA=&#39;&lt;null&gt;&#39;<br>Oct 29 15:11:59.649091 spce proxy[6047]: NOTICE: DEFAULT_ONREPLY &lt;script&gt;: New reply on proxy - M=INVITE ID=«FiLArRmpsyS5gpLCFSHR7jzDRpQiYPSE» UA=&#39;&lt;null&gt;&#39;<br>Oct 29 15:11:59.649107 spce proxy[6047]: NOTICE: REPLY_ROUTE_NAT &lt;script&gt;: NAT-Reply - S=408 - Request Timeout M=INVITE IP=«172.16.100.209»:«5060» («127.0.0.1»:«5080») ID=«FiLArRmpsyS5gpLCFSHR7jzDRpQiYPSE» UA=&#39;&lt;null&gt;&#39; DESTIP=«127.0.0.1»:«5062»<br>Oct 29 15:11:59.649118 spce proxy[6047]: DEBUG: REPLY_ROUTE_NAT &lt;script&gt;: pua_dialoginfo: Set flag REFRESH presence to activate the publish messages - ID=«FiLArRmpsyS5gpLCFSHR7jzDRpQiYPSE» UA=&#39;&lt;null&gt;&#39;<br>Oct 29 15:11:59.649127 spce proxy[6047]: NOTICE: REPLY_ROUTE_NAT_CONTINUE &lt;script&gt;: Sending reply S=408 M=INVITE fs=&#39;«127.0.0.1»:«5062»&#39; du=&#39;«127.0.0.1»:«&lt;null&gt;»&#39; - ID=«FiLArRmpsyS5gpLCFSHR7jzDRpQiYPSE» UA=&#39;&lt;null&gt;&#39;<br>Oct 29 15:11:59.649137 spce proxy[6047]: INFO: ROUTE_EXIT &lt;script&gt;: INVITE processed - ID=«FiLArRmpsyS5gpLCFSHR7jzDRpQiYPSE»<br>Oct 29 15:11:59.649145 spce proxy[6047]: INFO: ROUTE_EXIT &lt;script&gt;: Runtime for response M=INVITE 408 was 289 usec - ID=«FiLArRmpsyS5gpLCFSHR7jzDRpQiYPSE»<br>Oct 29 15:11:59.649154 spce proxy[6047]: NOTICE: FAILURE_ROUTE_LOCAL &lt;script&gt;: Failure route for local call, code=&#39;408&#39; - R=«sip:bob-c6NONwRkf6N5JRP@192.168.1.103:43779» ID=«FiLArRmpsyS5gpLCFSHR7jzDRpQiYPSE» UA=&#39;uagv1&#39;<br>Oct 29 15:11:59.649164 spce proxy[6047]: DEBUG: FAILURE_ROUTE_LOCAL &lt;script&gt;: pua_dialoginfo: Set puburis_callee to a fake (random) value and disable PUBLISH messages to callee setting FLB_PRESENCE_CALLEE flag - R=«sip:bob-c6NONwRkf6N5JRP@192.168.1.103:43779» ID=«FiLArRmpsyS5gpLCFSHR7jzDRpQiYPSE» UA=&#39;uagv1&#39;<br>Oct 29 15:11:59.649173 spce proxy[6047]: INFO: ROUTE_STOP_RTPPROXY_BRANCH &lt;script&gt;: Stop rtpengine for current branch using first Via, caller did is &#39;«50»&#39; and callee did is &#39;«50»&#39; - R=«sip:bob-c6NONwRkf6N5JRP@192.168.1.103:43779» ID=«FiLArRmpsyS5gpLCFSHR7jzDRpQiYPSE» UA=&#39;uagv1&#39;<br>Oct 29 15:11:59.649341 spce proxy[6041]: INFO: FILTER_CODECS &lt;script&gt;: Restoring xavp callee codecs filter from callee dlg_var for the downstream in-dialog &#39;ACK&#39; request with values &lt;null&gt; &lt;null&gt; - R=«sip:bob-c6NONwRkf6N5JRP@192.168.1.103:43779» ID=«FiLArRmpsyS5gpLCFSHR7jzDRpQiYPSE_b2b-1» UA=&#39;&lt;null&gt;&#39;<br>Oct 29 15:11:59.649350 spce proxy[6041]: INFO: FILTER_CODECS &lt;script&gt;: Processing codecs filters - R=«sip:bob-c6NONwRkf6N5JRP@192.168.1.103:43779» ID=«FiLArRmpsyS5gpLCFSHR7jzDRpQiYPSE_b2b-1» UA=&#39;&lt;null&gt;&#39;<br>Oct 29 15:11:59.649359 spce proxy[6041]: INFO: ROUTE_OUTBOUND &lt;script&gt;: Relaying request, du=&#39;«&lt;null&gt;»&#39; - R=«sip:bob-c6NONwRkf6N5JRP@192.168.1.103:43779» ID=«FiLArRmpsyS5gpLCFSHR7jzDRpQiYPSE_b2b-1» UA=&#39;&lt;null&gt;&#39;<br>Oct 29 15:11:59.649368 spce proxy[6041]: INFO: ROUTE_EXIT &lt;script&gt;: Runtime for request M=ACK was 3319 usec - ID=«FiLArRmpsyS5gpLCFSHR7jzDRpQiYPSE_b2b-1»<br>Oct 29 15:11:59.649671 spce proxy[6047]: INFO: ROUTE_EARLY_REJECT &lt;script&gt;: Cannot call the media server to play an announcement - R=«sip:bob-c6NONwRkf6N5JRP@192.168.1.103:43779» ID=«FiLArRmpsyS5gpLCFSHR7jzDRpQiYPSE» UA=&#39;uagv1&#39;<br>Oct 29 15:11:59.650688 spce proxy[6047]: INFO: ROUTE_ADD_CALLINFO_REPLY &lt;script&gt;: Adding reply P-NGCP-Caller-Info &#39;&lt;sip:«alice»@«<a href="http://ss.example.org">ss.example.org</a>»&gt;;ip=«172.16.100.209»;port=«5060»«;primary=51123456789»«»&#39; - ID=«FiLArRmpsyS5gpLCFSHR7jzDRpQiYPSE» UA=&#39;uagv1&#39;<br>Oct 29 15:11:59.651741 spce proxy[6047]: INFO: ROUTE_ADD_CALLINFO_REPLY &lt;script&gt;: Adding reply P-NGCP-Callee-Info &#39;&lt;sip:«51187654321»@«<a href="http://ss.example.org">ss.example.org</a>»&gt;;ip=«192.168.1.103»;port=«43779»«;primary=51187654321»«»&#39; - ID=«FiLArRmpsyS5gpLCFSHR7jzDRpQiYPSE» UA=&#39;uagv1&#39;<br>Oct 29 15:11:59.651866 spce proxy[6047]: NOTICE: ROUTE_LOCAL_REPLY &lt;script&gt;: Sending reply S=408 Request Timeout fs=&#39;«127.0.0.1»:«5062»&#39; du=&#39;«127.0.0.1»:«5060»&#39; - ID=«FiLArRmpsyS5gpLCFSHR7jzDRpQiYPSE» UA=&#39;uagv1&#39;<br>Oct 29 15:11:59.653735 spce proxy[6047]: INFO: dialog:failed &lt;core&gt; [core/kemi.c:109]: sr_kemi_core_info(): connected to redis server[16] <a href="http://127.0.0.1:6379">127.0.0.1:6379</a> at 4<br>Oct 29 15:11:59.654868 spce proxy[6047]: INFO: dialog:failed &lt;core&gt; [core/kemi.c:109]: sr_kemi_core_info(): connected to redis server[17] <a href="http://127.0.0.1:6379">127.0.0.1:6379</a> at 3<br>Oct 29 15:11:59.659105 spce proxy[6047]: NOTICE: dialog:failed &lt;script&gt;: [dialog:failed] decreased redis counters lua_dlg_callid:[«FiLArRmpsyS5gpLCFSHR7jzDRpQiYPSE»] - R=«<a href="mailto:sip%3Ayou@kamailio.org">sip:you@kamailio.org</a>» ID=«123» UA=&#39;&lt;null&gt;&#39;<br>Oct 29 15:11:59.660075 spce proxy[6042]: NOTICE: DEFAULT_ROUTE &lt;script&gt;: New request on proxy - M=ACK R=«sip:51187654321@ss.example.org:5060» F=«<a href="mailto:sip%3Aalice@ss.example.org">sip:alice@ss.example.org</a>» T=«<a href="mailto:sip%3A51187654321@ss.example.org">sip:51187654321@ss.example.org</a>» IP=«127.0.0.1»:«5060» («127.0.0.1»:«5060») ID=«FiLArRmpsyS5gpLCFSHR7jzDRpQiYPSE» UA=&#39;&lt;null&gt;&#39; DESTIP=«127.0.0.1»:«5062»<br>Oct 29 15:11:59.660092 spce proxy[6042]: DEBUG: ROUTE_CHECK_TEL_URI &lt;script&gt;: x_hdr(From):«&lt;<a href="mailto:sip%3Aalice@ss.example.org">sip:alice@ss.example.org</a>&gt;;tag=VxUyKI6TlvPyt7OGWLD-tWDU3S5Yq9p-» - R=«sip:51187654321@ss.example.org:5060» ID=«FiLArRmpsyS5gpLCFSHR7jzDRpQiYPSE» UA=&#39;&lt;null&gt;&#39;<br>Oct 29 15:11:59.660104 spce proxy[6042]: DEBUG: DEFAULT_ROUTE &lt;script&gt;: pua_dialoginfo: Disable PUBLISH messages to caller setting FLB_PRESENCE_CALLER flag - R=«sip:51187654321@ss.example.org:5060» ID=«FiLArRmpsyS5gpLCFSHR7jzDRpQiYPSE» UA=&#39;&lt;null&gt;&#39;<br>Oct 29 15:11:59.660114 spce proxy[6042]: DEBUG: DEFAULT_ROUTE &lt;script&gt;: pua_dialoginfo: Disable PUBLISH messages to callee setting FLB_PRESENCE_CALLEE flag - R=«sip:51187654321@ss.example.org:5060» ID=«FiLArRmpsyS5gpLCFSHR7jzDRpQiYPSE» UA=&#39;&lt;null&gt;&#39;<br>Oct 29 15:11:59.661339 spce proxy[6047]: INFO: ROUTE_EXIT &lt;script&gt;: INVITE processed - ID=«FiLArRmpsyS5gpLCFSHR7jzDRpQiYPSE»<br>Oct 29 15:11:59.661633 spce proxy[6047]: INFO: ROUTE_EXIT &lt;script&gt;: Runtime for request M=INVITE was 14969 usec - ID=«FiLArRmpsyS5gpLCFSHR7jzDRpQiYPSE»</i><br>```</div>