I try to do an stress test on a manually installed version. However users
are successfully registered but the call is aborted with the following
error.

sipp: The following events occured:
2018-07-16      12:48:02.879689 1531729082.879689: Aborting call on
unexpected message for Call-Id '1-29085@127.0.1.1': while expecting '183'
(index 2), received 'SIP/2.0 503 Service Unavailable

Via: SIP/2.0/TCP 127.0.1.1:17027
;received=192.168.122.251;branch=z9hG4bK-29085-1-0
Record-Route:
<sip:scscf.sprout.example.amir;transport=TCP;lr;billing-role=charge-term>
Record-Route:
<sip:scscf.sprout.example.amir;transport=TCP;lr;billing-role=charge-orig>
Call-ID: 1-29085@127.0.1.1
From: <sip:2010000...@example.amir>;tag=29085SIPpTag001
To: <sip:2010000...@example.amir
>;tag=z9hG4bKPjkqlLv4G9J3y5Ay7UJ-yjI1FVg2jNqOe6
CSeq: 1 INVITE
P-Charging-Vector:
icid-value="29085SIPpTag001";orig-ioi=example.amir;term-ioi=example.amir
P-Charging-Function-Addresses: ccf=0.0.0.0
Content-Length:  0

I set the log level to 4 in sprout and a part of this is included.
looks like pjsip finds a connection problem.

16-07-2018 08:18:03.618 UTC [7f9af379e700] Verbose sproutletproxy.cpp:2284:
scscf-proxy-0x7f9b24172ba0 pass initial request Request msg INVITE/cseq=1
(tdta0x7f9b24174170) to Sproutlet
16-07-2018 08:18:03.618 UTC [7f9af379e700] Info scscfsproutlet.cpp:442:
S-CSCF received initial request
16-07-2018 08:18:03.618 UTC [7f9af379e700] Info scscfsproutlet.cpp:973:
Original dialog for odi_b31nIgVSUL found: AsChain-term[0x7f9b2415da20]:2/1
16-07-2018 08:18:03.618 UTC [7f9af379e700] Verbose
static_dns_cache.cpp:327: No matching CNAME record found in static cache
16-07-2018 08:18:03.618 UTC [7f9af379e700] Verbose
dnscachedresolver.cpp:314: Check cache for hs.example.amir type 1
16-07-2018 08:18:03.619 UTC [7f9af379e700] Info scscfsproutlet.cpp:606:
Found served user, so apply services
16-07-2018 08:18:03.619 UTC [7f9af379e700] Info scscfsproutlet.cpp:1550:
Completed applying terminating services
16-07-2018 08:18:03.619 UTC [7f9af379e700] Info scscfsproutlet.cpp:1776:
Route request to registered UE bindings
16-07-2018 08:18:03.619 UTC [7f9af379e700] Info scscfsproutlet.cpp:244:
Look up bindings for sip:2010000...@example.amir in subscriber manager
16-07-2018 08:18:03.619 UTC [7f9af379e700] Verbose
static_dns_cache.cpp:327: No matching CNAME record found in static cache
16-07-2018 08:18:03.619 UTC [7f9af379e700] Verbose
dnscachedresolver.cpp:314: Check cache for vellum.example.amir type 1
16-07-2018 08:18:03.620 UTC [7f9af379e700] Verbose sproutletproxy.cpp:1995:
scscf-proxy-0x7f9b24172ba0 sending Request msg INVITE/cseq=1
(tdta0x7f9b24174170) on fork 0
16-07-2018 08:18:03.620 UTC [7f9af379e700] Info pjutils.cpp:1001: Resolved
destination URI sip:127.0.1.1:5082;transport=tcp;lr
16-07-2018 08:18:03.620 UTC [7f9af379e700] Verbose pjsip: tcpc0x7f9b2418
tcp->base.local_name: 192.168.122.59
16-07-2018 08:18:03.620 UTC [7f9af379e700] Verbose pjsip: tcpc0x7f9b2418
TCP client transport created
16-07-2018 08:18:03.620 UTC [7f9af379e700] Verbose pjsip: tcpc0x7f9b2418
TCP transport 192.168.122.59:5052 is connecting to 127.0.1.1:5082...
16-07-2018 08:18:03.620 UTC [7f9af379e700] Verbose
common_sip_processing.cpp:103: TX 3166 bytes Request msg INVITE/cseq=1
(tdta0x7f9b24174170) to TCP 127.0.1.1:5082:
--start msg--

INVITE sip:2010000041@127.0.1.1:26268 SIP/2.0
Record-Route:
<sip:scscf.sprout.example.amir;transport=TCP;lr;billing-role=charge-term>
Record-Route:
<sip:scscf.sprout.example.amir;transport=TCP;lr;billing-role=charge-orig>
Via: SIP/2.0/TCP
192.168.122.59:5052;rport;branch=z9hG4bKPjAPniom2E9LBwFkQV5tQmnAjbbNSEYjFq

Via: SIP/2.0/TCP
mmtel.sprout.example.amir;branch=z9hG4bKPjkqlLv4G9J3y5Ay7UJ-yjI1FVg2jNqOe6
Via: SIP/2.0/TCP
scscf.sprout.example.amir;branch=z9hG4bKPjA3-iG2tALLWhnc7.DVbVgxGicTIAmADn
Via: SIP/2.0/TCP
icscf.sprout.example.amir;branch=z9hG4bKPjhA8NyujPVgl2qMEADF4S7T87NEY-YWPL
Via: SIP/2.0/TCP
scscf.sprout.example.amir;branch=z9hG4bKPjdHHGQkTLRkC0a3IhU2xcw6THXK6b3VjE
Via: SIP/2.0/TCP
mmtel.sprout.example.amir;branch=z9hG4bKPj4GDzedM6HbxvCs4LztENsDY3gJ0XbBxx
Via: SIP/2.0/TCP
scscf.sprout.example.amir;branch=z9hG4bKPjYSOuqmNTNkKa3oOf25TBkxrKnSUgUqvw
Via: SIP/2.0/TCP
127.0.1.1:17027;received=192.168.122.251;branch=z9hG4bK-29085-1-0

From: <sip:2010000...@example.amir>;tag=29085SIPpTag001
To: <sip:2010000...@example.amir>
CSeq: 1 INVITE
Expires: 180
Call-Info: 
<sip:127.0.1.1:17027>;method="NOTIFY;Event=telephone-event;Duration=2000"

P-Charging-Function-Addresses: ccf=0.0.0.0
Supported: timer, precondition, sec-agree, histinfo, 100rel
P-Charging-Vector:
icid-value="29085SIPpTag001";orig-ioi=example.amir;term-ioi=example.amir
Contact: 
<sip:2010000088@127.0.1.1:17027>;+g.3gpp.icsi-ref="urn%3Aurn-7%3A3gpp-service.ims.icsi.mmtel";video;+sip.instance="<urn:gsma:imei:35283606-360704-0>"

P-Early-Media: supported
Allow: INVITE, ACK, OPTIONS, CANCEL, BYE, UPDATE, INFO, REFER, NOTIFY,
MESSAGE, PRACK
P-Asserted-Identity: <sip:2010000...@example.amir>
Security-Verify:
ipsec-3gpp;q=0.1;alg=hmac-md5-96;mod=trans;ealg=aes-cbc;spi-c=265324728;spi-s=83307704;port-c=16381;port-s=5061

User-Agent: AAAAA IMS 4.0.0
Accept-Contact:
*;+g.3gpp.icsi-ref="urn%3Aurn-7%3A3gpp-service.ims.icsi.mmtel"
Session-Expires: 600;refresher=uac
Call-ID: 1-29085@127.0.1.1
Max-Forwards: 62
P-Visited-Network-ID: example.amir
X-Dummy-Header: abcd
Accept: application/sdp, application/dtmf-relay
P-Served-User: <sip:2010000...@example.amir>;sescase=term;regstate=reg
P-Called-Party-ID: <sip:2010000...@example.amir>
Route: <sip:127.0.1.1:5082;transport=tcp;lr>
Content-Type: application/sdp
Content-Length:   823

v=0
o=AAAAAA-IMS-UE 18567144687033 18567144687033 IN IP4 127.0.1.1
s=-
c=IN IP4 127.0.1.1
t=0 0
m=audio 16404 RTP/AVP 116 107 118 96 0 8 111 110
b=AS:38
b=RS:375
b=RR:1125
a=inactive
a=rtpmap:116 AMR-WB/16000/1
a=rtpmap:107 AMR-WB/16000/1
a=rtpmap:118 AMR/8000/1
a=rtpmap:96 AMR/8000/1
a=rtpmap:111 telephone-event/16000
a=rtpmap:110 telephone-event/8000
a=rtpmap:0 PCMU/8000
a=rtpmap:8 PCMA/8000
a=fmtp:116 mode-change-capability=2; max-red=220
a=fmtp:107 octet-align=1;mode-change-capability=2; max-red=220
a=fmtp:118 mode-change-capability=2; max-red=220
a=fmtp:96 octet-align=1;mode-change-capability=2; max-red=220
a=fmtp:111 0-15
a=fmtp:110 0-15
a=curr:qos local none
a=curr:qos remote none
a=des:qos mandatory local sendrecv
a=des:qos optional remote sendrecv
a=maxptime:240
a=ptime:20

--end msg--
16-07-2018 08:18:03.630 UTC [7f9aa8708700] Info pjsip: tcpc0x7f9b2418 TCP
connect() error: Connection refused [code=120111]
16-07-2018 08:18:03.630 UTC [7f9aa8708700] Info pjsip: tcpc0x7f9b2418
Unable to connect to 127.0.1.1:5082
16-07-2018 08:18:03.630 UTC [7f9aa8708700] Info pjsip: tsx0x7f9b2418d
Failed to send Request msg INVITE/cseq=1 (tdta0x7f9b24174170)! err=120111
(Connection refused)
16-07-2018 08:18:03.630 UTC [7f9aa8708700] Verbose pjsip: tcpc0x7f9b2418
TCP transport destroyed with reason 120111: Connection refused
16-07-2018 08:18:03.630 UTC [7f9aecf91700] Verbose sproutletproxy.cpp:1007:
Notifying upstream sproutlet scscf-proxy of client failure: TRANSPORT_ERROR
16-07-2018 08:18:03.630 UTC [7f9aecf91700] Verbose sproutletproxy.cpp:2392:
scscf-proxy-0x7f9b24172ba0 received error TRANSPORT_ERROR on fork 0, state
= Calling
16-07-2018 08:18:03.630 UTC [7f9aecf91700] Info pjutils.cpp:1809: Cloning
header! 140304302170008
16-07-2018 08:18:03.630 UTC [7f9aecf91700] Info pjutils.cpp:1809: Cloning
header! 140304302169072
16-07-2018 08:18:03.630 UTC [7f9aecf91700] Info scscfsproutlet.cpp:699:
S-CSCF received response
16-07-2018 08:18:03.630 UTC [7f9aecf91700] Verbose sproutletproxy.cpp:2031:
scscf-proxy-0x7f9b24172ba0 sending Response msg 503/INVITE/cseq=1
(tdta0x7f9b3c0250b0)
16-07-2018 08:18:03.630 UTC [7f9aecf91700] Verbose sproutletproxy.cpp:2825:
Routing Response msg 503/INVITE/cseq=1 (tdta0x7f9b3c0250b0) (1101 bytes) to
upstream sproutlet mmtel:
--start msg--

SIP/2.0 503 Service Unavailable
Via: SIP/2.0/TCP
scscf.sprout.example.amir;branch=z9hG4bKPjA3-iG2tALLWhnc7.DVbVgxGicTIAmADn
Via: SIP/2.0/TCP
icscf.sprout.example.amir;branch=z9hG4bKPjhA8NyujPVgl2qMEADF4S7T87NEY-YWPL
Via: SIP/2.0/TCP
scscf.sprout.example.amir;branch=z9hG4bKPjdHHGQkTLRkC0a3IhU2xcw6THXK6b3VjE
Via: SIP/2.0/TCP
mmtel.sprout.example.amir;branch=z9hG4bKPj4GDzedM6HbxvCs4LztENsDY3gJ0XbBxx
Via: SIP/2.0/TCP
scscf.sprout.example.amir;branch=z9hG4bKPjYSOuqmNTNkKa3oOf25TBkxrKnSUgUqvw
Via: SIP/2.0/TCP
127.0.1.1:17027;received=192.168.122.251;branch=z9hG4bK-29085-1-0

Record-Route:
<sip:scscf.sprout.example.amir;transport=TCP;lr;billing-role=charge-term>
Record-Route:
<sip:scscf.sprout.example.amir;transport=TCP;lr;billing-role=charge-orig>
Call-ID: 1-29085@127.0.1.1
From: <sip:2010000...@example.amir>;tag=29085SIPpTag001
To: <sip:2010000...@example.amir>;tag=z9hG4bKPjkqlLv4G9J3y5Ay7UJ-yjI1FVg2jNqOe6

CSeq: 1 INVITE
P-Charging-Vector:
icid-value="29085SIPpTag001";orig-ioi=example.amir;term-ioi=example.amir
P-Charging-Function-Addresses: ccf=0.0.0.0
Content-Length:  0


--end msg--
16-07-2018 08:18:03.630 UTC [7f9aecf91700] Verbose sproutletproxy.cpp:2341:
mmtel-0x7f9b2415d900 received final response Response msg 503/INVITE/cseq=1
(tdta0x7f9b3c0250b0) on fork 0, state = Terminated
16-07-2018 08:18:03.630 UTC [7f9aecf91700] Verbose sproutletproxy.cpp:2031:
mmtel-0x7f9b2415d900 sending Response msg 503/INVITE/cseq=1
(tdta0x7f9b3c0250b0)
16-07-2018 08:18:03.630 UTC [7f9aecf91700] Verbose sproutletproxy.cpp:2825:
Routing Response msg 503/INVITE/cseq=1 (tdta0x7f9b3c0250b0) (1008 bytes) to
upstream sproutlet scscf-proxy:
--start msg--

SIP/2.0 503 Service Unavailable
Via: SIP/2.0/TCP
icscf.sprout.example.amir;branch=z9hG4bKPjhA8NyujPVgl2qMEADF4S7T87NEY-YWPL
Via: SIP/2.0/TCP
scscf.sprout.example.amir;branch=z9hG4bKPjdHHGQkTLRkC0a3IhU2xcw6THXK6b3VjE
Via: SIP/2.0/TCP
mmtel.sprout.example.amir;branch=z9hG4bKPj4GDzedM6HbxvCs4LztENsDY3gJ0XbBxx
Via: SIP/2.0/TCP
scscf.sprout.example.amir;branch=z9hG4bKPjYSOuqmNTNkKa3oOf25TBkxrKnSUgUqvw
Via: SIP/2.0/TCP
127.0.1.1:17027;received=192.168.122.251;branch=z9hG4bK-29085-1-0

Record-Route:
<sip:scscf.sprout.example.amir;transport=TCP;lr;billing-role=charge-term>
Record-Route:
<sip:scscf.sprout.example.amir;transport=TCP;lr;billing-role=charge-orig>
Call-ID: 1-29085@127.0.1.1
From: <sip:2010000...@example.amir>;tag=29085SIPpTag001
To: <sip:2010000...@example.amir>;tag=z9hG4bKPjkqlLv4G9J3y5Ay7UJ-yjI1FVg2jNqOe6

CSeq: 1 INVITE
P-Charging-Vector:
icid-value="29085SIPpTag001";orig-ioi=example.amir;term-ioi=example.amir
P-Charging-Function-Addresses: ccf=0.0.0.0
Content-Length:  0


--end msg--
_______________________________________________
Clearwater mailing list
Clearwater@lists.projectclearwater.org
http://lists.projectclearwater.org/mailman/listinfo/clearwater_lists.projectclearwater.org

Reply via email to