[Spce-user] Call hangs at about 15 seconds

Leopoldo Iglesia liglesia at por-aire.es
Fri Aug 1 07:50:50 EDT 2014 

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

-------------- next part --------------
A non-text attachment was scrubbed...
Name: telefoniae5.cap
Type: application/octet-stream
Size: 635978 bytes
Desc: not available
URL: <http://lists.sipwise.com/mailman/private/spce-user_lists.sipwise.com/attachments/20140801/45ae5595/attachment.cap>

More information about the Spce-user mailing list