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