[Spce-user] Call hangs at about 15 seconds

Daniel Grotti dgrotti at sipwise.com
Fri Aug 1 08:18:15 EDT 2014 

Hi,
there is no such call (ID=16888 at 154.58.3.158) in the trace attached.

Also you have a lot of ERROR:

ERROR: rtpengine [rtpengine.c:1491]: rtpp_function_call(): proxy replied
with error: Failed to parse SDP

But the reason why the call is drop is because the ACK is wrong and it
is not delivered:

NOTICE: <script>: New request - M=ACK R=sip:127.0.0.1:5080
F=sip:x1009 at 154.58.3.135 T=sip:606105877 at 154.58.3.135 IP=127.0.0.1:5060
(127.0.0.1:5060) ID=16888 at 154.58.3.158
NOTICE: <script>: Dropping mis-routed request - R=sip:127.0.0.1:5080
ID=16888 at 154.58.3.158


Can't check the ACK inside cause there is no trace for that callid
16888 at 154.58.3.158.


Daniel



On 08/01/2014 01:50 PM, Leopoldo Iglesia wrote:
> If i call, from a suscriber to a foreign number,  via peering, or to
> other suscriber it hangs at about 15 secs.
>
> I send a wireshark capture and proxy log.
>
>
> Aug  1 13:13:37 sipwise proxy[4400]: NOTICE: <script>: Authentication
> failed, no credentials - R=sip:606105877 at 154.58.3.135
> ID=16888 at 154.58.3.158
> Aug  1 13:13:37 sipwise proxy[4402]: NOTICE: <script>: New request -
> M=INVITE R=sip:606105877 at 154.58.3.135 F=sip:x1009 at 154.58.3.135
> T=sip:606105877 at 154.58.3.135 IP=154.58.3.158:5060 (127.0.0.1:5060)
> ID=16888 at 154.58.3.158
> Aug  1 13:13:37 sipwise proxy[4402]: NOTICE: <script>: User-Provided
> CLI 'x1009' taken from From-User as fallback, should be from
> 'rpid_user' - R=sip:606105877 at 154.58.3.135 ID=16888 at 154.58.3.158
> Aug  1 13:13:37 sipwise proxy[4402]: NOTICE: <script>: User-provided
> CLI 'x1009' rejected, using network-provided CLI '34984099519' -
> R=sip:606105877 at 154.58.3.135 ID=16888 at 154.58.3.158
> Aug  1 13:13:37 sipwise proxy[4402]: NOTICE: <script>: Setting
> '34984099519 at 154.58.3.135' as initiating user-provided CLI -
> R=sip:606105877 at 154.58.3.135 ID=16888 at 154.58.3.158
> Aug  1 13:13:37 sipwise proxy[4402]: NOTICE: <script>: Setting
> '34984099519 at 154.58.3.135' as initiating network-provided CLI -
> R=sip:606105877 at 154.58.3.135 ID=16888 at 154.58.3.158
> Aug  1 13:13:37 sipwise proxy[4402]: NOTICE: <script>: Rewriting
> called party '606105877' to '34606105877' -
> R=sip:606105877 at 154.58.3.135 ID=16888 at 154.58.3.158
> Aug  1 13:13:37 sipwise proxy[4402]: NOTICE: <script>: Callee is not
> local - R=sip:34606105877 at 154.58.3.135 ID=16888 at 154.58.3.158
> Aug  1 13:13:37 sipwise proxy[4402]: NOTICE: <script>: Call to SIP
> Peering - R=sip:34606105877 at 154.58.3.135 ID=16888 at 154.58.3.158
> Aug  1 13:13:37 sipwise proxy[4402]: NOTICE: <script>: Load gws
> matching calling part 'sip:34984099519 at 154.58.3.135' and called user
> '34606105877' and called part 'sip:34606105877 at 154.58.3.135' -
> R=sip:34606105877 at 154.58.3.135 ID=16888 at 154.58.3.158
> Aug  1 13:13:37 sipwise proxy[4402]: NOTICE: <script>: Setting acc
> source-leg for uuid 'c2731ab4-e7f5-4440-a821-d95c5d94eeac':
> 'c2731ab4-e7f5-4440-a821-d95c5d94eeac|x1009|154.58.3.135|34984099519|||2|||0|call|154.58.3.158|1406891617.480275'
> - R=sip:34606105877 at 212.231.4.206:5060;transport=udp
> ID=16888 at 154.58.3.158
> Aug  1 13:13:37 sipwise proxy[4402]: NOTICE: <script>: Setting acc
> destination-leg for uuid '0':
> '0|||0|606105877|0|34606105877|212.231.4.206|34606105877|154.58.3.135'
> - R=sip:34606105877 at 212.231.4.206:5060;transport=udp
> ID=16888 at 154.58.3.158
> Aug  1 13:13:37 sipwise proxy[4402]: ERROR: rtpengine
> [rtpengine.c:1491]: rtpp_function_call(): proxy replied with error:
> Failed to parse SDP
> Aug  1 13:13:37 sipwise proxy[4402]: NOTICE: <script>: Rewriting first
> user-provided CLI '34984099519' to '984099519' -
> R=sip:34606105877 at 212.231.4.206:5060;transport=udp ID=16888 at 154.58.3.158
> Aug  1 13:13:37 sipwise proxy[4402]: NOTICE: <script>: Rewriting first
> network-provided CLI '34984099519' to '984099519' -
> R=sip:34606105877 at 212.231.4.206:5060;transport=udp ID=16888 at 154.58.3.158
> Aug  1 13:13:37 sipwise proxy[4402]: NOTICE: <script>: Setting
> caller_cli_netprov/caller_domain_netprov '984099519 at 154.58.3.135' for
> npn - R=sip:34606105877 at 212.231.4.206:5060;transport=udp
> ID=16888 at 154.58.3.158
> Aug  1 13:13:37 sipwise proxy[4402]: NOTICE: <script>: Setting
> caller_cli_netprov/caller_domain_netprov '984099519 at 154.58.3.135' for
> npn - R=sip:34606105877 at 212.231.4.206:5060;transport=udp
> ID=16888 at 154.58.3.158
> Aug  1 13:13:37 sipwise proxy[4402]: NOTICE: <script>: Setting From to
> '984099519 <sip:984099519 at 154.58.3.135>' -
> R=sip:34606105877 at 212.231.4.206:5060;transport=udp ID=16888 at 154.58.3.158
> Aug  1 13:13:37 sipwise proxy[4402]: NOTICE: <script>: Setting
> caller_cli_netprov/caller_domain_netprov '984099519 at 154.58.3.135' for
> npn - R=sip:34606105877 at 212.231.4.206:5060;transport=udp
> ID=16888 at 154.58.3.158
> Aug  1 13:13:37 sipwise proxy[4402]: NOTICE: <script>: Setting PAI to
> '<sip:984099519 at 154.58.3.135>' -
> R=sip:34606105877 at 212.231.4.206:5060;transport=udp ID=16888 at 154.58.3.158
> Aug  1 13:13:37 sipwise proxy[4402]: NOTICE: <script>: Setting
> P-Called-Party-ID '<sip:34606105877 at 212.231.4.206>' -
> R=sip:34606105877 at 212.231.4.206:5060;transport=udp ID=16888 at 154.58.3.158
> Aug  1 13:13:37 sipwise proxy[4402]: NOTICE: <script>: Setting
> 'sip:212.231.4.206:5060' taken from R-URI as next hop after lb for
> PSTN call - R=sip:34606105877 at 212.231.4.206:5060;transport=udp
> ID=16888 at 154.58.3.158
> Aug  1 13:13:37 sipwise proxy[4402]: NOTICE: <script>: Appending
> P-D-URI
> 'sip:127.0.0.1:5060;received='sip:212.231.4.206:5060;lr;transport=udp'' -
> R=sip:34606105877 at 212.231.4.206:5060;transport=udp ID=16888 at 154.58.3.158
> Aug  1 13:13:37 sipwise proxy[4402]: NOTICE: <script>: Forcing request
> via B2BUA 'sip:127.0.0.1:5080' -
> R=sip:34606105877 at 212.231.4.206:5060;transport=udp ID=16888 at 154.58.3.158
> Aug  1 13:13:37 sipwise proxy[4402]: NOTICE: <script>: Request leaving
> server, D-URI='sip:127.0.0.1:5080' -
> R=sip:34606105877 at 212.231.4.206:5060;transport=udp ID=16888 at 154.58.3.158
> Aug  1 13:13:37 sipwise proxy[4404]: NOTICE: <script>: NAT-Reply -
> S=100 - Connecting M=INVITE IP=154.58.3.158:5060 (127.0.0.1:5080)
> ID=16888 at 154.58.3.158
> Aug  1 13:13:38 sipwise proxy[4408]: NOTICE: <script>: NAT-Reply -
> S=183 - Session Progress M=INVITE IP=154.58.3.158:5060
> (127.0.0.1:5080) ID=16888 at 154.58.3.158
> Aug  1 13:13:38 sipwise proxy[4408]: ERROR: rtpengine
> [rtpengine.c:1491]: rtpp_function_call(): proxy replied with error:
> Unknown call-id
> Aug  1 13:13:48 sipwise proxy[4400]: NOTICE: <script>: NAT-Reply -
> S=200 - OK M=INVITE IP=154.58.3.158:5060 (127.0.0.1:5080)
> ID=16888 at 154.58.3.158
> Aug  1 13:13:48 sipwise proxy[4400]: ERROR: rtpengine
> [rtpengine.c:1491]: rtpp_function_call(): proxy replied with error:
> Unknown call-id
> Aug  1 13:13:48 sipwise proxy[4398]: NOTICE: <script>: New request -
> M=ACK R=sip:127.0.0.1:5080 F=sip:x1009 at 154.58.3.135
> T=sip:606105877 at 154.58.3.135 IP=127.0.0.1:5060 (127.0.0.1:5060)
> ID=16888 at 154.58.3.158
> Aug  1 13:13:48 sipwise proxy[4398]: NOTICE: <script>: Dropping
> mis-routed request - R=sip:127.0.0.1:5080 ID=16888 at 154.58.3.158
> Aug  1 13:13:48 sipwise proxy[4412]: ERROR: db_mysql [km_dbase.c:122]:
> db_mysql_submit_query(): driver error on query: Duplicate entry
> 'uloc-53db7100-112e-1' for key 'ruid_idx'
> Aug  1 13:13:48 sipwise proxy[4412]: ERROR: <core> [db_query.c:235]:
> db_do_insert_cmd(): error while submitting query
> Aug  1 13:13:48 sipwise proxy[4412]: ERROR: usrloc [ucontact.c:627]:
> db_insert_ucontact(): inserting contact in db failed
> Aug  1 13:13:48 sipwise proxy[4412]: ERROR: usrloc [urecord.c:386]:
> wb_timer(): inserting contact into database failed (aor:
> x984099517 at 154.58.3.135)
> Aug  1 13:13:48 sipwise proxy[4402]: NOTICE: <script>: NAT-Reply -
> S=200 - OK M=INVITE IP=154.58.3.158:5060 (127.0.0.1:5080)
> ID=16888 at 154.58.3.158
> Aug  1 13:13:48 sipwise proxy[4402]: ERROR: rtpengine
> [rtpengine.c:1491]: rtpp_function_call(): proxy replied with error:
> Unknown call-id
> Aug  1 13:13:48 sipwise proxy[4404]: NOTICE: <script>: New request -
> M=ACK R=sip:127.0.0.1:5080 F=sip:x1009 at 154.58.3.135
> T=sip:606105877 at 154.58.3.135 IP=127.0.0.1:5060 (127.0.0.1:5060)
> ID=16888 at 154.58.3.158
> Aug  1 13:13:49 sipwise proxy[4404]: NOTICE: <script>: Dropping
> mis-routed request - R=sip:127.0.0.1:5080 ID=16888 at 154.58.3.158
> Aug  1 13:13:49 sipwise proxy[4408]: NOTICE: <script>: New request -
> M=REGISTER R=sip:154.58.3.135 F=sip:x1010 at 154.58.3.135
> T=sip:x1010 at 154.58.3.135 IP=154.58.3.149:5060 (127.0.0.1:5060)
> ID=cx0.Aa34erSB8FN6X7KRy.pHLfN3V9Y-
> Aug  1 13:13:49 sipwise proxy[4408]: NOTICE: <script>: Authentication
> failed, no credentials - R=sip:154.58.3.135
> ID=cx0.Aa34erSB8FN6X7KRy.pHLfN3V9Y-
> Aug  1 13:13:49 sipwise proxy[4410]: NOTICE: <script>: NAT-Reply -
> S=200 - OK M=INVITE IP=154.58.3.158:5060 (127.0.0.1:5080)
> ID=16888 at 154.58.3.158
> Aug  1 13:13:49 sipwise proxy[4410]: ERROR: rtpengine
> [rtpengine.c:1491]: rtpp_function_call(): proxy replied with error:
> Unknown call-id
> Aug  1 13:13:50 sipwise proxy[4397]: NOTICE: <script>: New request -
> M=ACK R=sip:127.0.0.1:5080 F=sip:x1009 at 154.58.3.135
> T=sip:606105877 at 154.58.3.135 IP=127.0.0.1:5060 (127.0.0.1:5060)
> ID=16888 at 154.58.3.158
> Aug  1 13:13:50 sipwise proxy[4397]: NOTICE: <script>: Dropping
> mis-routed request - R=sip:127.0.0.1:5080 ID=16888 at 154.58.3.158
> Aug  1 13:13:53 sipwise proxy[4400]: NOTICE: <script>: New request -
> M=ACK R=sip:127.0.0.1:5080 F=sip:x1009 at 154.58.3.135
> T=sip:606105877 at 154.58.3.135 IP=127.0.0.1:5060 (127.0.0.1:5060)
> ID=16888 at 154.58.3.158
> Aug  1 13:13:53 sipwise proxy[4400]: NOTICE: <script>: Dropping
> mis-routed request - R=sip:127.0.0.1:5080 ID=16888 at 154.58.3.158
> Aug  1 13:13:57 sipwise proxy[4404]: NOTICE: <script>: New request -
> M=ACK R=sip:127.0.0.1:5080 F=sip:x1009 at 154.58.3.135
> T=sip:606105877 at 154.58.3.135 IP=127.0.0.1:5060 (127.0.0.1:5060)
> ID=16888 at 154.58.3.158
> Aug  1 13:13:57 sipwise proxy[4404]: NOTICE: <script>: Dropping
> mis-routed request - R=sip:127.0.0.1:5080 ID=16888 at 154.58.3.158
> Aug  1 13:14:01 sipwise proxy[4410]: NOTICE: <script>: New request -
> M=ACK R=sip:127.0.0.1:5080 F=sip:x1009 at 154.58.3.135
> T=sip:606105877 at 154.58.3.135 IP=127.0.0.1:5060 (127.0.0.1:5060)
> ID=16888 at 154.58.3.158
> Aug  1 13:14:01 sipwise proxy[4410]: NOTICE: <script>: Dropping
> mis-routed request - R=sip:127.0.0.1:5080 ID=16888 at 154.58.3.158
> Aug  1 13:14:03 sipwise proxy[4406]: NOTICE: <script>: New request -
> M=BYE R=sip:x1009 at 154.58.3.158:5060 F=sip:606105877 at 154.58.3.135
> T=sip:984099519 at 154.58.3.135 IP=127.0.0.1:5080 (127.0.0.1:5080)
> ID=16888 at 154.58.3.158
> Aug  1 13:14:03 sipwise proxy[4398]: NOTICE: <script>: NAT-Reply -
> S=200 - OK M=BYE IP=127.0.0.1:5080 (127.0.0.1:5060) ID=16888 at 154.58.3.158
> Aug  1 13:14:05 sipwise proxy[4402]: NOTICE: <script>: New request -
> M=ACK R=sip:127.0.0.1:5080 F=sip:984099519 at 154.58.3.135
> T=sip:606105877 at 154.58.3.135 IP=127.0.0.1:5060 (127.0.0.1:5060)
> ID=16888 at 154.58.3.158
> Aug  1 13:14:05 sipwise proxy[4402]: NOTICE: <script>: Dropping
> mis-routed request - R=sip:127.0.0.1:5080 ID=16888 at 154.58.3.158
> root at sipwise:/var/log/ngcp# tail -n 1000 kamailio-proxy.log
>
>
>
> _______________________________________________
> Spce-user mailing list
> Spce-user at lists.sipwise.com
> https://lists.sipwise.com/listinfo/spce-user

-------------- next part --------------
An HTML attachment was scrubbed...
URL: <http://lists.sipwise.com/pipermail/spce-user_lists.sipwise.com/attachments/20140801/40946250/attachment-0001.html>

More information about the Spce-user mailing list