[Spce-user] [EXTERNAL] Troubleshooting request

Wed Oct 9 03:47:14 EDT 2024

Hi Edo.
Can you share the full SIP INVITE message the kamailio proxy receive?
Dario

On Mon, Oct 7, 2024 at 3:36 PM Edo <edo.ekunwe at gmail.com> wrote:

> Hi Dario,
>
> I am not sure if your earlier response of malformed invite was directed at
> me so I decided to paste the sip logs from a sample call, maybe we can get
> more information that may help with troubleshooting.
>
> ****
>
> Oct  7 06:43:50.807051 spce proxy[837572]: NOTICE: DEFAULT_ROUTE
> <script>: New request on proxy - M=INVITE
> R=«sip:xxxxxxxxxxx2607244 at XXX.XXX.XXX.XXX:5060»
> F=«sip:XXCallerIDXX at XXX.XXX.86.104»
> T=«sip:xxxxxxxxxxx2607244 at XXX.XXX.XXX.XXX» IP=«XXX.XXX.188.51»:«5060»
> («127.0.0.1»:«5060») ID=«3e2e30bf-6132-478a-bdd0-292e139c39c5» UA='Asterisk
> PBX 18.24.3' DESTIP=«127.0.0.1»:«5062»
>
> Oct  7 06:43:50.807084 spce proxy[837572]: 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:xxxxxxxxxxx2607244 at XXX.XXX.XXX.XXX:5060»
> ID=«3e2e30bf-6132-478a-bdd0-292e139c39c5» UA='Asterisk PBX 18.24.3'
>
> Oct  7 06:43:50.807375 spce proxy[837572]: NOTICE:
> ROUTE_LOAD_CALLEE_DOMAIN_PREF <script>: Load domain preferences for callee
> '«XXX.XXX.XXX.XXX»' - R=«sip:xxxxxxxxxxx2607244 at XXX.XXX.XXX.XXX:5060»
> ID=«3e2e30bf-6132-478a-bdd0-292e139c39c5» UA='Asterisk PBX 18.24.3'
>
> Oct  7 06:43:50.811499 spce proxy[837572]: NOTICE: ROUTE_AUTH <script>:
> Authentication failed, no credentials -
> R=«sip:xxxxxxxxxxx2607244 at XXX.XXX.XXX.XXX:5060»
> ID=«3e2e30bf-6132-478a-bdd0-292e139c39c5» UA='Asterisk PBX 18.24.3'
> Auth=«<null>»
>
> Oct  7 06:43:50.811581 spce proxy[837572]: NOTICE: ROUTE_AUTH <script>:
> Sending reply S=407 fs='«127.0.0.1»:«5062»' du='«127.0.0.1»:«5060»' -
> ID=«3e2e30bf-6132-478a-bdd0-292e139c39c5» UA='Asterisk PBX 18.24.3'
>
> Oct  7 06:43:50.812257 spce proxy[837568]: NOTICE: sl:filtered-ack
> <script>: New request on proxy - M=ACK
> R=«sip:xxxxxxxxxxx2607244 at XXX.XXX.XXX.XXX:5060»
> F=«sip:XXCallerIDXX at XXX.XXX.86.104»
> T=«sip:xxxxxxxxxxx2607244 at XXX.XXX.XXX.XXX» IP=«<null>»:«<null>»
> («127.0.0.1»:«5060») ID=«3e2e30bf-6132-478a-bdd0-292e139c39c5» UA='<null>'
> DESTIP=«127.0.0.1»:«5062»
>
> Oct  7 06:43:50.872198 spce proxy[837565]: NOTICE: DEFAULT_ROUTE
> <script>: New request on proxy - M=INVITE
> R=«sip:xxxxxxxxxxx2607244 at XXX.XXX.XXX.XXX:5060»
> F=«sip:XXCallerIDXX at XXX.XXX.86.104»
> T=«sip:xxxxxxxxxxx2607244 at XXX.XXX.XXX.XXX» IP=«XXX.XXX.188.51»:«5060»
> («127.0.0.1»:«5060») ID=«3e2e30bf-6132-478a-bdd0-292e139c39c5» UA='Asterisk
> PBX 18.24.3' DESTIP=«127.0.0.1»:«5062»
>
> Oct  7 06:43:50.872229 spce proxy[837565]: 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:xxxxxxxxxxx2607244 at XXX.XXX.XXX.XXX:5060»
> ID=«3e2e30bf-6132-478a-bdd0-292e139c39c5» UA='Asterisk PBX 18.24.3'
>
> Oct  7 06:43:50.872504 spce proxy[837565]: NOTICE:
> ROUTE_LOAD_CALLEE_DOMAIN_PREF <script>: Load domain preferences for callee
> '«XXX.XXX.XXX.XXX»' - R=«sip:xxxxxxxxxxx2607244 at XXX.XXX.XXX.XXX:5060»
> ID=«3e2e30bf-6132-478a-bdd0-292e139c39c5» UA='Asterisk PBX 18.24.3'
>
> Oct  7 06:43:50.877414 spce proxy[837565]: NOTICE: ROUTE_FIND_CALLER
> <script>: Sending reply S=101 Connecting fs='«127.0.0.1»:«5062»'
> du='«127.0.0.1»:«5060»' - R=«sip:xxxxxxxxxxx2607244 at XXX.XXX.XXX.XXX:5060»
> ID=«3e2e30bf-6132-478a-bdd0-292e139c39c5» UA='Asterisk PBX 18.24.3'
>
> Oct  7 06:43:50.877751 spce proxy[837565]: NOTICE: ROUTE_LOAD_CALLER_PREF
> <script>: Load caller preferences for uuid
> '«86ba28d9-153f-4cee-800c-f34c1efea74a»' and domain '«XXX.XXX.86.104»' -
> R=«sip:xxxxxxxxxxx2607244 at XXX.XXX.XXX.XXX:5060»
> ID=«3e2e30bf-6132-478a-bdd0-292e139c39c5» UA='Asterisk PBX 18.24.3'
>
> Oct  7 06:43:50.883279 spce proxy[837565]: NOTICE:
> ROUTE_LOAD_CALLER_CONTRACT_PREF <script>: Load caller contract preferences
> for contract id '«2»' and ip '«XXX.XXX.188.51»' -
> R=«sip:xxxxxxxxxxx2607244 at XXX.XXX.XXX.XXX:5060»
> ID=«3e2e30bf-6132-478a-bdd0-292e139c39c5» UA='Asterisk PBX 18.24.3'
>
> Oct  7 06:43:50.883583 spce proxy[837565]: NOTICE:
> ROUTE_LOAD_CALLER_RESELLER_PREF <script>: Load caller reseller preferences
> for reseller id '«1»' - R=«sip:xxxxxxxxxxx2607244 at XXX.XXX.XXX.XXX:5060»
> ID=«3e2e30bf-6132-478a-bdd0-292e139c39c5» UA='Asterisk PBX 18.24.3'
>
> Oct  7 06:43:50.884273 spce proxy[837565]: NOTICE: ROUTE_DLG_MANAGE
> <script>: Dialog managed,
> lua_dlg_callid:[«3e2e30bf-6132-478a-bdd0-292e139c39c5»] -
> R=«sip:xxxxxxxxxxx2607244 at XXX.XXX.XXX.XXX:5060»
> ID=«3e2e30bf-6132-478a-bdd0-292e139c39c5» UA='Asterisk PBX 18.24.3'
>
> Oct  7 06:43:50.884348 spce proxy[837565]: NOTICE: ROUTE_GET_CALLER_CLI
> <script>: User-Provided CLI '«XXCallerIDXX»' taken from From-User -
> R=«sip:xxxxxxxxxxx2607244 at XXX.XXX.XXX.XXX:5060»
> ID=«3e2e30bf-6132-478a-bdd0-292e139c39c5» UA='Asterisk PBX 18.24.3'
>
> Oct  7 06:43:50.888566 spce proxy[837565]: NOTICE:
> ROUTE_APPLY_REWRITE_RULE <script>: Applying caller-in usr/domain rewrite
> rules on user-provided CLI using dpid '7' -
> R=«sip:xxxxxxxxxxx2607244 at XXX.XXX.XXX.XXX:5060»
> ID=«3e2e30bf-6132-478a-bdd0-292e139c39c5» UA='Asterisk PBX 18.24.3'
>
> Oct  7 06:43:50.888839 spce proxy[837565]: NOTICE:
> ROUTE_CHECK_CLI_ALLOWED <script>: User-provided CLI '«XXCallerIDXX»'
> accepted (matched user preference) -
> R=«sip:xxxxxxxxxxx2607244 at XXX.XXX.XXX.XXX:5060»
> ID=«3e2e30bf-6132-478a-bdd0-292e139c39c5» UA='Asterisk PBX 18.24.3'
>
> Oct  7 06:43:50.888915 spce proxy[837565]: NOTICE: ROUTE_INVITE <script>:
> Setting '«XXCallerIDXX»@«XXX.XXX.86.104»' as initiating user-provided CLI -
> R=«sip:xxxxxxxxxxx2607244 at XXX.XXX.XXX.XXX:5060»
> ID=«3e2e30bf-6132-478a-bdd0-292e139c39c5» UA='Asterisk PBX 18.24.3'
>
> Oct  7 06:43:50.888963 spce proxy[837565]: NOTICE: ROUTE_INVITE <script>:
> Setting '«XXCallerIDXX»@«XXX.XXX.86.104»' as initiating network-provided
> CLI - R=«sip:xxxxxxxxxxx2607244 at XXX.XXX.XXX.XXX:5060»
> ID=«3e2e30bf-6132-478a-bdd0-292e139c39c5» UA='Asterisk PBX 18.24.3'
>
> Oct  7 06:43:50.889037 spce proxy[837565]: NOTICE:
> ROUTE_APPLY_REWRITE_RULE <script>: Applying callee-in usr/domain rewrite
> rules on called party using dpid '8' -
> R=«sip:xxxxxxxxxxx2607244 at XXX.XXX.XXX.XXX:5060»
> ID=«3e2e30bf-6132-478a-bdd0-292e139c39c5» UA='Asterisk PBX 18.24.3'
>
> Oct  7 06:43:50.890596 spce proxy[837565]: NOTICE: ROUTE_FIND_CALLEE
> <script>: Callee is not local - R=«sip:xxxxxxxxxxx2607244 at XXX.XXX.XXX.XXX:5060»
> ID=«3e2e30bf-6132-478a-bdd0-292e139c39c5» UA='Asterisk PBX 18.24.3'
>
> Oct  7 06:43:50.890869 spce proxy[837565]: NOTICE: ROUTE_PSTN <script>:
> Call to SIP Peering - R=«sip:xxxxxxxxxxx2607244 at XXX.XXX.XXX.XXX:5060»
> ID=«3e2e30bf-6132-478a-bdd0-292e139c39c5» UA='Asterisk PBX 18.24.3'
>
> Oct  7 06:43:50.890924 spce proxy[837565]: NOTICE: ROUTE_PSTN <script>:
> Load gws matching calling part '«sip:XXCallerIDXX at XXX.XXX.86.104»' and
> called user '«xxxxxxxxxxx2607244»' and called part
> '«sip:xxxxxxxxxxx2607244 at XXX.XXX.XXX.XXX:5060»' -
> R=«sip:xxxxxxxxxxx2607244 at XXX.XXX.XXX.XXX:5060»
> ID=«3e2e30bf-6132-478a-bdd0-292e139c39c5» UA='Asterisk PBX 18.24.3'
>
> Oct  7 06:43:50.891692 spce proxy[837565]: ERROR: ROUTE_PSTN_SELECT_PEER
> pv [pv_core.c:336]: pv_get_ruri_attr(): failed to parse the R-URI
>
> Oct  7 06:43:50.891806 spce proxy[837565]: ERROR:
> ROUTE_LOAD_PEER_OUT_PREF pv [pv_core.c:261]: pv_get_ruri(): failed to parse
> the R-URI
>
> Oct  7 06:43:50.891827 spce proxy[837565]: NOTICE:
> ROUTE_LOAD_PEER_OUT_PREF <script>: Load peer preferences for peer host '1'
> - R=«<null>» ID=«3e2e30bf-6132-478a-bdd0-292e139c39c5» UA='Asterisk PBX
> 18.24.3'
>
> Oct  7 06:43:50.893690 spce proxy[837565]: ERROR: ROUTE_PSTN pv
> [pv_core.c:336]: pv_get_ruri_attr(): failed to parse the R-URI
>
> Oct  7 06:43:50.895431 spce proxy[837565]: ERROR: ROUTE_PSTN pv
> [pv_core.c:336]: pv_get_ruri_attr(): failed to parse the R-URI
>
> Oct  7 06:43:50.895538 spce proxy[837565]: ERROR: <null> pv
> [pv_core.c:336]: pv_get_ruri_attr(): failed to parse the R-URI
>
> Oct  7 06:43:50.895558 spce proxy[837565]: ERROR: <null> pv
> [pv_core.c:336]: pv_get_ruri_attr(): failed to parse the R-URI
>
> Oct  7 06:43:50.901133 spce proxy[837565]: ERROR: ROUTE_OUTBOUND pv
> [pv_core.c:336]: pv_get_ruri_attr(): failed to parse the R-URI
>
> Oct  7 06:43:50.901156 spce proxy[837565]: ERROR: ROUTE_OUTBOUND pv
> [pv_core.c:336]: pv_get_ruri_attr(): failed to parse the R-URI
>
> Oct  7 06:43:50.901829 spce proxy[837565]: ERROR:
> ROUTE_APPLY_REWRITE_RULE pv [pv_core.c:261]: pv_get_ruri(): failed to parse
> the R-URI
>
> Oct  7 06:43:50.901850 spce proxy[837565]: NOTICE:
> ROUTE_APPLY_REWRITE_RULE <script>: Applying acc caller-out peer rewrite
> rules on acc caller party using dpid '3' - R=«<null>»
> ID=«3e2e30bf-6132-478a-bdd0-292e139c39c5» UA='Asterisk PBX 18.24.3'
>
> Oct  7 06:43:50.902770 spce proxy[837565]: ERROR: ROUTE_ACC_CALLER pv
> [pv_core.c:261]: pv_get_ruri(): failed to parse the R-URI
>
> Oct  7 06:43:50.902792 spce proxy[837565]: NOTICE: ROUTE_ACC_CALLER
> <script>: Setting acc source-leg for uuid
> '«86ba28d9-153f-4cee-800c-f34c1efea74a»':
> '«{"gpp":["70770",null,null,null,null,null,null,null,null,null],"clir":0,"uuid":"86ba28d9-153f-4cee-800c-f34c1efea74a","u":"XXCallerIDXX","d":"XXX.XXX.86.104","cli":"XXCallerIDXX","s_id":"70770","c_id":"70770","a_id":2,"pau":"","par":"","s":"call","ip":"XXX.XXX.188.51","t":1728276230.902101,"lnp_p":"","cli_out":"XXCallerIDXX","lnp_t":"","pai":"","ppi":"","div":"","last_hih":"","cid":"","u2u":"","lcr":0,"cc_quota":"","cc_sub":"1","cc_cust":"1"}»'
> - R=«<null>» ID=«3e2e30bf-6132-478a-bdd0-292e139c39c5» UA='Asterisk PBX
> 18.24.3'
>
> Oct  7 06:43:50.903156 spce proxy[837565]: ERROR:
> ROUTE_APPLY_REWRITE_RULE pv [pv_core.c:261]: pv_get_ruri(): failed to parse
> the R-URI
>
> Oct  7 06:43:50.903176 spce proxy[837565]: NOTICE:
> ROUTE_APPLY_REWRITE_RULE <script>: Applying acc callee-out peer rewrite
> rules on acc called party using dpid '4' - R=«<null>»
> ID=«3e2e30bf-6132-478a-bdd0-292e139c39c5» UA='Asterisk PBX 18.24.3'
>
> Oct  7 06:43:50.903656 spce proxy[837565]: ERROR: ROUTE_ACC_CALLEE pv
> [pv_core.c:261]: pv_get_ruri(): failed to parse the R-URI
>
> Oct  7 06:43:50.903679 spce proxy[837565]: NOTICE: ROUTE_ACC_CALLEE
> <script>: Setting acc destination-leg for uuid '«0»':
> '«{"gpp":[null,null,null,null,null,null,null,null,null,null],"plu":0,"s_id":"","c_id":"","a_id":0,"dialed":"xxxxxxxxxxx2607244","uuid":"0","u":"<null>","d":"<null>","u_in":"xxxxxxxxxxx2607244","d_in":"XXX.XXX.XXX.XXX","lcr":1,"lnp_p":"","u_out":"0","lnp_t":"","fci":"","cc_quota":"","cc_sub":"1","cc_cust":""}»'
> - R=«<null>» ID=«3e2e30bf-6132-478a-bdd0-292e139c39c5» UA='Asterisk PBX
> 18.24.3'
>
> Oct  7 06:43:50.903837 spce proxy[837565]: ERROR: ROUTE_OUTBOUND tm
> [t_lookup.c:1827]: new_t(): uri invalid
>
> Oct  7 06:43:50.903858 spce proxy[837565]: ERROR: ROUTE_OUTBOUND tm
> [t_lookup.c:1979]: t_newtran(): new_t failed
>
> Oct  7 06:43:50.903913 spce proxy[837565]: ERROR: ROUTE_OUTBOUND sl
> [sl_funcs.c:428]: sl_reply_error(): stateless error reply used: I'm
> terribly sorry, server error occurred (1/SL)
>
> Oct  7 06:43:50.904591 spce proxy[837570]: NOTICE: sl:filtered-ack
> <script>: New request on proxy - M=ACK
> R=«sip:xxxxxxxxxxx2607244 at XXX.XXX.XXX.XXX:5060»
> F=«sip:XXCallerIDXX at XXX.XXX.86.104»
> T=«sip:xxxxxxxxxxx2607244 at XXX.XXX.XXX.XXX» IP=«<null>»:«<null>»
> («127.0.0.1»:«5060») ID=«3e2e30bf-6132-478a-bdd0-292e139c39c5» UA='<null>'
> DESTIP=«127.0.0.1»:«5062»
>
>
> ****
>
> Thanks
>
>
> On Mon, Oct 7, 2024 at 1:11 AM Dario Busso <dbusso at sipwise.com> wrote:
>
>> Looking at the error log, it seems that the INVITE received by SPCE is
>> malformed.
>> You need to check the peer system setup, not the SPCE.
>>
>>
>> Dario B.
>>
>>
>> Il lun 7 ott 2024, 06:50 Edo <edo.ekunwe at gmail.com> ha scritto:
>>
>>> Hi,
>>>
>>> I tried to make a call to a subscriber (SIP Trunk setup) and I got the
>>> following error message.
>>> *****
>>>
>>> Oct  7 06:43:50.891692 spce proxy[837565]: ERROR:
>>> ROUTE_PSTN_SELECT_PEER pv [pv_core.c:336]: pv_get_ruri_attr(): failed to
>>> parse the R-URI
>>>
>>> Oct  7 06:43:50.891806 spce proxy[837565]: ERROR:
>>> ROUTE_LOAD_PEER_OUT_PREF pv [pv_core.c:261]: pv_get_ruri(): failed to parse
>>> the R-URI
>>>
>>> Oct  7 06:43:50.891827 spce proxy[837565]: NOTICE:
>>> ROUTE_LOAD_PEER_OUT_PREF <script>: Load peer preferences for peer host '1'
>>> - R=«<null>» ID=«3e2e30bf-6132-478a-bdd0-292e139c39c5» UA='Asterisk PBX
>>> 18.24.3'
>>>
>>> Oct  7 06:43:50.893690 spce proxy[837565]: ERROR: ROUTE_PSTN pv
>>> [pv_core.c:336]: pv_get_ruri_attr(): failed to parse the R-URI
>>>
>>> Oct  7 06:43:50.895431 spce proxy[837565]: ERROR: ROUTE_PSTN pv
>>> [pv_core.c:336]: pv_get_ruri_attr(): failed to parse the R-URI
>>>
>>> Oct  7 06:43:50.895538 spce proxy[837565]: ERROR: <null> pv
>>> [pv_core.c:336]: pv_get_ruri_attr(): failed to parse the R-URI
>>>
>>> Oct  7 06:43:50.895558 spce proxy[837565]: ERROR: <null> pv
>>> [pv_core.c:336]: pv_get_ruri_attr(): failed to parse the R-URI
>>>
>>> Oct  7 06:43:50.901133 spce proxy[837565]: ERROR: ROUTE_OUTBOUND pv
>>> [pv_core.c:336]: pv_get_ruri_attr(): failed to parse the R-URI
>>>
>>> Oct  7 06:43:50.901156 spce proxy[837565]: ERROR: ROUTE_OUTBOUND pv
>>> [pv_core.c:336]: pv_get_ruri_attr(): failed to parse the R-URI
>>>
>>> Oct  7 06:43:50.901829 spce proxy[837565]: ERROR:
>>> ROUTE_APPLY_REWRITE_RULE pv [pv_core.c:261]: pv_get_ruri(): failed to parse
>>> the R-URI
>>> *****
>>>  I am looking for where I can set the system to a specific R-URI or
>>> check the system to use network provided R-RURI.
>>>
>>> Please help.
>>>
>>> Thanks
>>>
>>>
>>> --
>>> -----
>>> Ekunwe
>>> Tel: 601.497.3932
>>> --
>>> Spce-user mailing list
>>> Spce-user at lists.sipwise.com
>>> http://lists.sipwise.com/mailman/listinfo/spce-user_lists.sipwise.com
>>>
>>
>
> --
> -----
> Ekunwe
> Tel: 601.497.3932
>
-------------- next part --------------
An HTML attachment was scrubbed...
URL: <http://lists.sipwise.com/pipermail/spce-user_lists.sipwise.com/attachments/20241009/0866a8c1/attachment-0001.htm>