Hello,
After downloading clearwater latest release on ubuntu server 14.04 i
cannot register using zoiper i keep receiving Internal Server Error 500
and it seems that a problem in sprout which appears in sprout logs
i Attached the logs to the mail so you can help me. However, this
problem didnot appear in the latest version of clearwater 1.0-170307.151028
Thanks in advance
03-04-2017 12:16:18.052 UTC Verbose sproutletproxy.cpp:538: Sproutlet Proxy
transaction (0x7f983400b310) destroyed
03-04-2017 12:16:18.052 UTC Debug basicproxy.cpp:494: BasicProxy::UASTsx
destructor (0x7f983400b310)
03-04-2017 12:16:18.052 UTC Debug basicproxy.cpp:511: Disconnect UAC
transactions from UAS transaction
03-04-2017 12:16:18.052 UTC Debug basicproxy.cpp:525: Free original request
03-04-2017 12:16:18.052 UTC Debug pjsip: tdta0x7f983406 Destroying txdata
Request msg REGISTER/cseq=1 (tdta0x7f98340608c0)
03-04-2017 12:16:18.052 UTC Debug basicproxy.cpp:534: Free un-used best response
03-04-2017 12:16:18.052 UTC Debug pjsip: tdta0x7f983403 Destroying txdata
Response msg 408/REGISTER/cseq=1 (tdta0x7f9834030140)
03-04-2017 12:16:18.052 UTC Debug basicproxy.cpp:555: BasicProxy::UASTsx
destructor completed
03-04-2017 12:16:18.052 UTC Debug pjsip: tdta0x7f983407 Destroying txdata
Response msg 500/REGISTER/cseq=1 (tdta0x7f9834070e90)
03-04-2017 12:16:18.052 UTC Debug pjsip: tsx0x7f983400e Transaction destroyed!
03-04-2017 12:16:18.970 UTC Debug pjsip: sip_endpoint.c Processing incoming
message: Request msg REGISTER/cseq=1 (rdata0x7f98640f3180)
03-04-2017 12:16:18.970 UTC Verbose common_sip_processing.cpp:120: RX 781 bytes
Request msg REGISTER/cseq=1 (rdata0x7f98640f3180) from TCP 192.168.0.210:34676:
--start msg--
REGISTER sip:ims.cw.4gtss.com:5060;transport=TCP SIP/2.0
Via: SIP/2.0/TCP
192.168.0.210:5058;rport;branch=z9hG4bKPj7OjKdLfzTihQz6Rf6JLTREZbtt3I978D
Path: <sip:[email protected]:5058;transport=TCP;lr;ob>
Via: SIP/2.0/TCP
192.168.0.207:44446;received=192.168.0.207;branch=z9hG4bK-524287-1---b4bccf7baf143257
Max-Forwards: 70
Contact:
<sip:[email protected]:44446;transport=tcp;rinstance=e5dd172bc47340ed>
To: <sip:[email protected]>
From: <sip:[email protected]>;tag=9542d61f
Call-ID: gKQzo8Y5VOUJVN__WEpSBA..
CSeq: 1 REGISTER
Expires: 600
User-Agent: Zoiper rv2.8.30
Allow-Events: presence, kpml, talk
P-Visited-Network-ID: ims.cw.4gtss.com
Route: <sip:icscf.sprout.ims.cw.4gtss.com:5052;transport=TCP;lr;orig>
Content-Length: 0
--end msg--
03-04-2017 12:16:18.970 UTC Debug pjutils.cpp:1714: Logging SAS Call-ID marker,
Call-ID gKQzo8Y5VOUJVN__WEpSBA..
03-04-2017 12:16:18.970 UTC Debug thread_dispatcher.cpp:264: Queuing cloned
received message 0x7f98640b0ae8 for worker threads
03-04-2017 12:16:18.970 UTC Debug thread_dispatcher.cpp:150: Worker thread
dequeue message 0x7f98640b0ae8
03-04-2017 12:16:18.970 UTC Debug pjsip: sip_endpoint.c Distributing rdata to
modules: Request msg REGISTER/cseq=1 (rdata0x7f98640b0ae8)
03-04-2017 12:16:18.970 UTC Debug uri_classifier.cpp:174: home domain: true,
local_to_node: false, is_gruu: false, enforce_user_phone: false, prefer_sip:
true, treat_number_as_phone: false
03-04-2017 12:16:18.970 UTC Debug uri_classifier.cpp:204: Classified URI as 4
03-04-2017 12:16:18.970 UTC Debug basicproxy.cpp:92: Process REGISTER request
03-04-2017 12:16:18.970 UTC Verbose sproutletproxy.cpp:507: Sproutlet Proxy
transaction (0x7f985c01c2d0) created
03-04-2017 12:16:18.970 UTC Debug basicproxy.cpp:1298: Report SAS start marker
- trail (190)
03-04-2017 12:16:18.970 UTC Debug pjutils.cpp:724: Cloned Request msg
REGISTER/cseq=1 (rdata0x7f98640b0ae8) to tdta0x7f985c00d0f0
03-04-2017 12:16:18.971 UTC Debug pjsip: tsx0x7f985c010 Transaction created for
Request msg REGISTER/cseq=1 (rdata0x7f98640b0ae8)
03-04-2017 12:16:18.971 UTC Debug pjsip: tsx0x7f985c010 Incoming Request msg
REGISTER/cseq=1 (rdata0x7f98640b0ae8) in state Null
03-04-2017 12:16:18.971 UTC Debug pjsip: tsx0x7f985c010 State changed from Null
to Trying, event=RX_MSG
03-04-2017 12:16:18.971 UTC Debug basicproxy.cpp:213: tsx0x7f985c010708 -
tu_on_tsx_state UAS, TSX_STATE RX_MSG state=Trying
03-04-2017 12:16:18.971 UTC Debug pjsip: endpoint Response msg
408/REGISTER/cseq=1 (tdta0x7f985c059940) created
03-04-2017 12:16:18.971 UTC Debug sproutletproxy.cpp:119: Find target Sproutlet
for request
03-04-2017 12:16:18.971 UTC Debug sproutletproxy.cpp:154: Found next routable
URI: sip:icscf.sprout.ims.cw.4gtss.com:5052;transport=TCP;lr;orig
03-04-2017 12:16:18.971 UTC Debug sproutletproxy.cpp:289: Possible service name
icscf will be used if sprout.ims.cw.4gtss.com is a local hostname
03-04-2017 12:16:18.971 UTC Debug sproutletproxy.cpp:293: Adding possible
service name icscf based on domain
03-04-2017 12:16:18.971 UTC Debug sproutletproxy.cpp:289: Possible service name
icscf will be used if sprout.ims.cw.4gtss.com is a local hostname
03-04-2017 12:16:18.971 UTC Debug sproutletproxy.cpp:293: Adding possible
service name icscf based on domain
03-04-2017 12:16:18.971 UTC Debug sproutletproxy.cpp:289: Possible service name
icscf will be used if sprout.ims.cw.4gtss.com is a local hostname
03-04-2017 12:16:18.971 UTC Debug sproutletproxy.cpp:293: Adding possible
service name icscf based on domain
03-04-2017 12:16:18.971 UTC Debug sproutletproxy.cpp:289: Possible service name
icscf will be used if sprout.ims.cw.4gtss.com is a local hostname
03-04-2017 12:16:18.971 UTC Debug sproutletproxy.cpp:293: Adding possible
service name icscf based on domain
03-04-2017 12:16:18.971 UTC Debug sproutletproxy.cpp:289: Possible service name
icscf will be used if sprout.ims.cw.4gtss.com is a local hostname
03-04-2017 12:16:18.971 UTC Debug sproutletproxy.cpp:293: Adding possible
service name icscf based on domain
03-04-2017 12:16:18.971 UTC Debug sproutletproxy.cpp:289: Possible service name
icscf will be used if sprout.ims.cw.4gtss.com is a local hostname
03-04-2017 12:16:18.971 UTC Debug sproutletproxy.cpp:293: Adding possible
service name icscf based on domain
03-04-2017 12:16:18.971 UTC Debug sproutletproxy.cpp:289: Possible service name
icscf will be used if sprout.ims.cw.4gtss.com is a local hostname
03-04-2017 12:16:18.971 UTC Debug sproutletproxy.cpp:293: Adding possible
service name icscf based on domain
03-04-2017 12:16:18.971 UTC Verbose sproutletproxy.cpp:1163: Created Sproutlet
icscf-0x7f985c0008e0 for Request msg REGISTER/cseq=1 (tdta0x7f985c00d0f0)
03-04-2017 12:16:18.971 UTC Verbose sproutletproxy.cpp:2095: Routing Request
msg REGISTER/cseq=1 (tdta0x7f985c00d0f0) (810 bytes) to downstream sproutlet
icscf:
--start msg--
REGISTER sip:ims.cw.4gtss.com:5060;transport=TCP SIP/2.0
Via: SIP/2.0/TCP
192.168.0.210:5058;rport=34676;received=192.168.0.210;branch=z9hG4bKPj7OjKdLfzTihQz6Rf6JLTREZbtt3I978D
Path: <sip:[email protected]:5058;transport=TCP;lr;ob>
Via: SIP/2.0/TCP
192.168.0.207:44446;received=192.168.0.207;branch=z9hG4bK-524287-1---b4bccf7baf143257
Max-Forwards: 70
Contact:
<sip:[email protected]:44446;transport=tcp;rinstance=e5dd172bc47340ed>
To: <sip:[email protected]>
From: <sip:[email protected]>;tag=9542d61f
Call-ID: gKQzo8Y5VOUJVN__WEpSBA..
CSeq: 1 REGISTER
Expires: 600
User-Agent: Zoiper rv2.8.30
Allow-Events: presence, kpml, talk
P-Visited-Network-ID: ims.cw.4gtss.com
Route: <sip:icscf.sprout.ims.cw.4gtss.com:5052;transport=TCP;lr;orig>
Content-Length: 0
--end msg--
03-04-2017 12:16:18.971 UTC Debug pjutils.cpp:741: Cloned tdta0x7f985c00d0f0 to
tdta0x7f985c05a950
03-04-2017 12:16:18.971 UTC Debug sproutletproxy.cpp:1224: Remove top Route
header Route: <sip:icscf.sprout.ims.cw.4gtss.com:5052;transport=TCP;lr;orig>
03-04-2017 12:16:18.971 UTC Debug sproutletproxy.cpp:1768: Adding message
0x7f985c05af60 => txdata 0x7f985c05a9f8 mapping
03-04-2017 12:16:18.971 UTC Verbose sproutletproxy.cpp:1613:
icscf-0x7f985c0008e0 pass initial request Request msg REGISTER/cseq=1
(tdta0x7f985c05a950) to Sproutlet
03-04-2017 12:16:18.971 UTC Debug acr.cpp:1812: Create RalfACR for node type
I-CSCF with role Terminating
03-04-2017 12:16:18.971 UTC Debug acr.cpp:49: Created ACR (0x7f985c04d290)
03-04-2017 12:16:18.971 UTC Debug acr.cpp:189: Created I-CSCF Ralf ACR
03-04-2017 12:16:18.971 UTC Debug acr.cpp:269: Set record type for I-CSCF,
BGCF, IBCF, AS to EVENT_RECORD
03-04-2017 12:16:18.971 UTC Debug icscfsproutlet.cpp:194: I-CSCF initialize
transaction for REGISTER request
03-04-2017 12:16:18.971 UTC Debug icscfrouter.cpp:362: Perform UAR - impi
[email protected], impu sip:[email protected], vn
ims.cw.4gtss.com, auth_type REG
03-04-2017 12:16:18.971 UTC Debug a_record_resolver.cpp:80:
ARecordResolver::resolve_iter for host hs.ims.cw.4gtss.com, port 8888, family 2
03-04-2017 12:16:18.971 UTC Debug baseresolver.cpp:425: Attempt to parse
hs.ims.cw.4gtss.com as IP address
03-04-2017 12:16:18.971 UTC Verbose dnscachedresolver.cpp:486: Check cache for
hs.ims.cw.4gtss.com type 1
03-04-2017 12:16:18.971 UTC Debug dnscachedresolver.cpp:588: Pulling 1 records
from cache for hs.ims.cw.4gtss.com A
03-04-2017 12:16:18.971 UTC Debug baseresolver.cpp:366: Found 1 A/AAAA records,
creating iterator
03-04-2017 12:16:18.971 UTC Debug baseresolver.cpp:425: Attempt to parse
hs.ims.cw.4gtss.com as IP address
03-04-2017 12:16:18.971 UTC Debug baseresolver.cpp:819: 192.168.0.212:8888
transport 6 has state: WHITE
03-04-2017 12:16:18.971 UTC Debug baseresolver.cpp:819: 192.168.0.212:8888
transport 6 has state: WHITE
03-04-2017 12:16:18.971 UTC Debug baseresolver.cpp:1004: Added a whitelisted
server, now have 1 of 1
03-04-2017 12:16:18.971 UTC Debug connection_pool.h:231: Request for connection
to IP: 192.168.0.212, port: 8888
03-04-2017 12:16:18.971 UTC Debug connection_pool.h:244: Found existing
connection 0x7f986c0216d0 in pool
03-04-2017 12:16:18.971 UTC Debug httpclient.cpp:478: Set CURLOPT_RESOLVE:
hs.ims.cw.4gtss.com:8888:192.168.0.212
03-04-2017 12:16:18.971 UTC Debug httpclient.cpp:505: Sending HTTP request :
http://hs.ims.cw.4gtss.com:8888/impi/6505550392%40ims.cw.4gtss.com/registration-status?impu=sip%3A6505550392%40ims.cw.4gtss.com&visited-network=ims.cw.4gtss.com&auth-type=REG
(trying 192.168.0.212)
03-04-2017 12:16:18.971 UTC Debug httpclient.cpp:832: Received header
http/1.1200ok with value
03-04-2017 12:16:18.971 UTC Debug httpclient.cpp:833: Header pointer:
0x7f98547ef340
03-04-2017 12:16:18.971 UTC Debug httpclient.cpp:832: Received header
content-length with value 83
03-04-2017 12:16:18.971 UTC Debug httpclient.cpp:833: Header pointer:
0x7f98547ef340
03-04-2017 12:16:18.971 UTC Debug httpclient.cpp:832: Received header
content-type with value text/plain
03-04-2017 12:16:18.971 UTC Debug httpclient.cpp:833: Header pointer:
0x7f98547ef340
03-04-2017 12:16:18.971 UTC Debug httpclient.cpp:832: Received header with
value
03-04-2017 12:16:18.971 UTC Debug httpclient.cpp:833: Header pointer:
0x7f98547ef340
03-04-2017 12:16:18.971 UTC Debug httpclient.cpp:538: Received HTTP response:
status=200,
doc={"result-code":2001,"scscf":"sip:scscf.sprout.ims.cw.4gtss.com:5054;transport=TCP"}
03-04-2017 12:16:18.971 UTC Debug baseresolver.cpp:830: Successful response
from 192.168.0.212:8888 transport 6
03-04-2017 12:16:18.971 UTC Debug connection_pool.h:267: Release connection to
IP: 192.168.0.212, port: 8888 to pool
03-04-2017 12:16:18.971 UTC Debug icscfrouter.cpp:245: HSS returned S-CSCF
sip:scscf.sprout.ims.cw.4gtss.com:5054;transport=TCP as target
03-04-2017 12:16:18.971 UTC Debug acr.cpp:653: Storing Server-Capabilities
03-04-2017 12:16:18.971 UTC Debug icscfrouter.cpp:120: SCSCF specified by HSS:
sip:scscf.sprout.ims.cw.4gtss.com:5054;transport=TCP
03-04-2017 12:16:18.971 UTC Debug uri_classifier.cpp:174: home domain: false,
local_to_node: true, is_gruu: false, enforce_user_phone: false, prefer_sip:
true, treat_number_as_phone: false
03-04-2017 12:16:18.971 UTC Debug uri_classifier.cpp:204: Classified URI as 3
03-04-2017 12:16:18.971 UTC Debug icscfsproutlet.cpp:283: Found SCSCF for
REGISTER
03-04-2017 12:16:18.971 UTC Debug sproutletproxy.cpp:1364: Sproutlet
send_request 0x7f985c05af60
03-04-2017 12:16:18.971 UTC Verbose sproutletproxy.cpp:1400:
icscf-0x7f985c0008e0 sending Request msg REGISTER/cseq=1 (tdta0x7f985c05a950)
on fork 0
03-04-2017 12:16:18.971 UTC Debug sproutletproxy.cpp:1783: Processing actions
from sproutlet - 0 responses, 1 requests, 0 timers
03-04-2017 12:16:18.971 UTC Debug sproutletproxy.cpp:1823: Processing request
0x7f985c05a9f8, fork = 0
03-04-2017 12:16:18.971 UTC Debug sproutletproxy.cpp:1947: icscf-0x7f985c0008e0
transmitting request on fork 0
03-04-2017 12:16:18.971 UTC Debug sproutletproxy.cpp:1961: icscf-0x7f985c0008e0
store reference to non-ACK request Request msg REGISTER/cseq=1
(tdta0x7f985c05a950) on fork 0
03-04-2017 12:16:18.971 UTC Debug sproutletproxy.cpp:1775: Removing message
0x7f985c05af60 => txdata 0x7f985c05a9f8 mapping
03-04-2017 12:16:18.971 UTC Debug sproutletproxy.cpp:119: Find target Sproutlet
for request
03-04-2017 12:16:18.971 UTC Debug sproutletproxy.cpp:154: Found next routable
URI: sip:scscf.sprout.ims.cw.4gtss.com:5054;transport=TCP
03-04-2017 12:16:18.971 UTC Debug sproutletproxy.cpp:289: Possible service name
scscf will be used if sprout.ims.cw.4gtss.com is a local hostname
03-04-2017 12:16:18.972 UTC Debug sproutletproxy.cpp:293: Adding possible
service name scscf based on domain
03-04-2017 12:16:18.972 UTC Verbose sproutletproxy.cpp:1163: Created Sproutlet
authentication-0x7f985c03da90 for Request msg REGISTER/cseq=1
(tdta0x7f985c05a950)
03-04-2017 12:16:18.972 UTC Verbose sproutletproxy.cpp:2095: Routing Request
msg REGISTER/cseq=1 (tdta0x7f985c05a950) (752 bytes) to downstream sproutlet
authentication:
--start msg--
REGISTER sip:scscf.sprout.ims.cw.4gtss.com:5054;transport=TCP SIP/2.0
Via: SIP/2.0/TCP
192.168.0.210:5058;rport=34676;received=192.168.0.210;branch=z9hG4bKPj7OjKdLfzTihQz6Rf6JLTREZbtt3I978D
Path: <sip:[email protected]:5058;transport=TCP;lr;ob>
Via: SIP/2.0/TCP
192.168.0.207:44446;received=192.168.0.207;branch=z9hG4bK-524287-1---b4bccf7baf143257
Max-Forwards: 69
Contact:
<sip:[email protected]:44446;transport=tcp;rinstance=e5dd172bc47340ed>
To: <sip:[email protected]>
From: <sip:[email protected]>;tag=9542d61f
Call-ID: gKQzo8Y5VOUJVN__WEpSBA..
CSeq: 1 REGISTER
Expires: 600
User-Agent: Zoiper rv2.8.30
Allow-Events: presence, kpml, talk
P-Visited-Network-ID: ims.cw.4gtss.com
Content-Length: 0
--end msg--
03-04-2017 12:16:18.972 UTC Debug pjutils.cpp:741: Cloned tdta0x7f985c05a950 to
tdta0x7f985c068d10
03-04-2017 12:16:18.972 UTC Debug sproutletproxy.cpp:1768: Adding message
0x7f985c069320 => txdata 0x7f985c068db8 mapping
03-04-2017 12:16:18.972 UTC Verbose sproutletproxy.cpp:1613:
authentication-0x7f985c03da90 pass initial request Request msg REGISTER/cseq=1
(tdta0x7f985c068d10) to Sproutlet
03-04-2017 12:16:18.972 UTC Debug authenticationsproutlet.cpp:829:
Authentication module invoked
03-04-2017 12:16:18.972 UTC Debug authenticationsproutlet.cpp:841: Request
needs authentication
03-04-2017 12:16:18.972 UTC Debug acr.cpp:1812: Create RalfACR for node type
S-CSCF with role Originating
03-04-2017 12:16:18.972 UTC Debug acr.cpp:49: Created ACR (0x7f985c0110a0)
03-04-2017 12:16:18.972 UTC Debug acr.cpp:189: Created S-CSCF Ralf ACR
03-04-2017 12:16:18.972 UTC Debug acr.cpp:229: Set record type for P/S-CSCF
03-04-2017 12:16:18.972 UTC Debug acr.cpp:237: Non-dialog message =>
EVENT_RECORD
03-04-2017 12:16:18.972 UTC Debug acr.cpp:1540: Stored 0 subscription
identifiers
03-04-2017 12:16:18.972 UTC Debug authenticationsproutlet.cpp:1150: No
authentication information in request or stale nonce, so reject with challenge
03-04-2017 12:16:18.972 UTC Debug sproutletproxy.cpp:1768: Adding message
0x7f985c06b2e0 => txdata 0x7f985c06ad78 mapping
03-04-2017 12:16:18.972 UTC Debug pjutils.cpp:448: Private identity defaulted
from public identity = [email protected]
03-04-2017 12:16:18.972 UTC Debug a_record_resolver.cpp:80:
ARecordResolver::resolve_iter for host hs.ims.cw.4gtss.com, port 8888, family 2
03-04-2017 12:16:18.972 UTC Debug baseresolver.cpp:425: Attempt to parse
hs.ims.cw.4gtss.com as IP address
03-04-2017 12:16:18.972 UTC Verbose dnscachedresolver.cpp:486: Check cache for
hs.ims.cw.4gtss.com type 1
03-04-2017 12:16:18.972 UTC Debug dnscachedresolver.cpp:588: Pulling 1 records
from cache for hs.ims.cw.4gtss.com A
03-04-2017 12:16:18.972 UTC Debug baseresolver.cpp:366: Found 1 A/AAAA records,
creating iterator
03-04-2017 12:16:18.972 UTC Debug baseresolver.cpp:425: Attempt to parse
hs.ims.cw.4gtss.com as IP address
03-04-2017 12:16:18.972 UTC Debug baseresolver.cpp:819: 192.168.0.212:8888
transport 6 has state: WHITE
03-04-2017 12:16:18.972 UTC Debug baseresolver.cpp:819: 192.168.0.212:8888
transport 6 has state: WHITE
03-04-2017 12:16:18.972 UTC Debug baseresolver.cpp:1004: Added a whitelisted
server, now have 1 of 1
03-04-2017 12:16:18.972 UTC Debug connection_pool.h:231: Request for connection
to IP: 192.168.0.212, port: 8888
03-04-2017 12:16:18.972 UTC Debug connection_pool.h:244: Found existing
connection 0x7f986c0216d0 in pool
03-04-2017 12:16:18.972 UTC Debug httpclient.cpp:478: Set CURLOPT_RESOLVE:
hs.ims.cw.4gtss.com:8888:192.168.0.212
03-04-2017 12:16:18.972 UTC Debug httpclient.cpp:505: Sending HTTP request :
http://hs.ims.cw.4gtss.com:8888/impi/6505550392%40ims.cw.4gtss.com/av?impu=sip%3A6505550392%40ims.cw.4gtss.com
(trying 192.168.0.212)
03-04-2017 12:16:18.982 UTC Debug httpclient.cpp:832: Received header
http/1.1200ok with value
03-04-2017 12:16:18.982 UTC Debug httpclient.cpp:833: Header pointer:
0x7f98547ef060
03-04-2017 12:16:18.982 UTC Debug httpclient.cpp:832: Received header
content-length with value 93
03-04-2017 12:16:18.982 UTC Debug httpclient.cpp:833: Header pointer:
0x7f98547ef060
03-04-2017 12:16:18.982 UTC Debug httpclient.cpp:832: Received header
content-type with value text/plain
03-04-2017 12:16:18.982 UTC Debug httpclient.cpp:833: Header pointer:
0x7f98547ef060
03-04-2017 12:16:18.982 UTC Debug httpclient.cpp:832: Received header with
value
03-04-2017 12:16:18.982 UTC Debug httpclient.cpp:833: Header pointer:
0x7f98547ef060
03-04-2017 12:16:18.982 UTC Debug httpclient.cpp:538: Received HTTP response:
status=200,
doc={"digest":{"ha1":"f18910d1d4f10d6e232b49add87a697e","realm":"ims.cw.4gtss.com","qop":"auth"}}
03-04-2017 12:16:18.982 UTC Debug baseresolver.cpp:830: Successful response
from 192.168.0.212:8888 transport 6
03-04-2017 12:16:18.982 UTC Debug connection_pool.h:267: Release connection to
IP: 192.168.0.212, port: 8888 to pool
03-04-2017 12:16:18.982 UTC Debug authenticationsproutlet.cpp:219: Verifying
AV:
{"digest":{"ha1":"f18910d1d4f10d6e232b49add87a697e","realm":"ims.cw.4gtss.com","qop":"auth"}}
03-04-2017 12:16:18.982 UTC Debug authenticationsproutlet.cpp:246: Digest
specified
03-04-2017 12:16:18.982 UTC Debug authenticationsproutlet.cpp:411: Valid AV -
generate challenge
03-04-2017 12:16:18.982 UTC Debug authenticationsproutlet.cpp:420: Create
WWW-Authenticate header
03-04-2017 12:16:18.982 UTC Debug authenticationsproutlet.cpp:536: Add Digest
information
03-04-2017 12:16:18.982 UTC Debug authenticationsproutlet.cpp:591: Write
authentication challenge to IMPI store
03-04-2017 12:16:18.982 UTC Debug memcachedstore.cpp:1128: Start GET from table
impi for key [email protected]
03-04-2017 12:16:18.982 UTC Debug astaire_resolver.cpp:72:
AstaireResolver::resolve for host sprout.ims.cw.4gtss.com, family 2
03-04-2017 12:16:18.982 UTC Debug utils.cpp:353: Malformed host/port
sprout.ims.cw.4gtss.com
03-04-2017 12:16:18.982 UTC Debug baseresolver.cpp:425: Attempt to parse
sprout.ims.cw.4gtss.com as IP address
03-04-2017 12:16:18.982 UTC Verbose dnscachedresolver.cpp:486: Check cache for
sprout.ims.cw.4gtss.com type 1
03-04-2017 12:16:18.982 UTC Debug dnscachedresolver.cpp:588: Pulling 1 records
from cache for sprout.ims.cw.4gtss.com A
03-04-2017 12:16:18.982 UTC Debug baseresolver.cpp:366: Found 1 A/AAAA records,
creating iterator
03-04-2017 12:16:18.982 UTC Debug baseresolver.cpp:819: 192.168.0.212:11311
transport 6 has state: BLACK
03-04-2017 12:16:18.982 UTC Debug baseresolver.cpp:819: 192.168.0.212:11311
transport 6 has state: BLACK
03-04-2017 12:16:18.982 UTC Debug baseresolver.cpp:1032: Added an unhealthy
server, now have 1 of 2
03-04-2017 12:16:18.982 UTC Debug memcachedstore.cpp:1469: Found 1 targets for
sprout.ims.cw.4gtss.com
03-04-2017 12:16:18.982 UTC Debug memcachedstore.cpp:1494: Duplicate target
IP=192.168.0.212, port= 11311 as it is the only target
03-04-2017 12:16:18.982 UTC Debug memcachedstore.cpp:1082: Try server IP
192.168.0.212, port 11311
03-04-2017 12:16:18.982 UTC Debug connection_pool.h:231: Request for connection
to IP: 192.168.0.212, port: 11311
03-04-2017 12:16:18.982 UTC Debug connection_pool.h:244: Found existing
connection 0x7f986c059740 in pool
03-04-2017 12:16:18.983 UTC Debug memcachedstore.cpp:107: Fetch result
03-04-2017 12:16:18.983 UTC Debug memcachedstore.cpp:1093: libmemcached
returned 16
03-04-2017 12:16:18.983 UTC Debug memcachedstore.cpp:1103: Return code means
the request should not be retried
03-04-2017 12:16:18.983 UTC Debug connection_pool.h:267: Release connection to
IP: 192.168.0.212, port: 11311 to pool
03-04-2017 12:16:18.983 UTC Debug memcachedstore.cpp:1200: Key not found
03-04-2017 12:16:18.983 UTC Debug communicationmonitor.cpp:82: Checking
communication changes - successful attempts 4, failures 4
03-04-2017 12:16:18.983 UTC Debug impistore.cpp:648: Storing IMPI for
[email protected]
{"authChallenges":[{"type":"digest","nonce":"4884896d5d032f4b","nc":1,"expires":1491221818,"correlator":"z9hG4bKPj7OjKdLfzTihQz6Rf6JLTREZbtt3I978D","realm":"ims.cw.4gtss.com","qop":"auth","ha1":"f18910d1d4f10d6e232b49add87a697e"}]}
03-04-2017 12:16:18.983 UTC Debug memcachedstore.cpp:1251: Writing 231 bytes to
table impi key [email protected], CAS = 0, expiry = 40
03-04-2017 12:16:18.983 UTC Debug astaire_resolver.cpp:72:
AstaireResolver::resolve for host sprout.ims.cw.4gtss.com, family 2
03-04-2017 12:16:18.983 UTC Debug utils.cpp:353: Malformed host/port
sprout.ims.cw.4gtss.com
03-04-2017 12:16:18.983 UTC Debug baseresolver.cpp:425: Attempt to parse
sprout.ims.cw.4gtss.com as IP address
03-04-2017 12:16:18.983 UTC Verbose dnscachedresolver.cpp:486: Check cache for
sprout.ims.cw.4gtss.com type 1
03-04-2017 12:16:18.983 UTC Debug dnscachedresolver.cpp:588: Pulling 1 records
from cache for sprout.ims.cw.4gtss.com A
03-04-2017 12:16:18.983 UTC Debug baseresolver.cpp:366: Found 1 A/AAAA records,
creating iterator
03-04-2017 12:16:18.983 UTC Debug baseresolver.cpp:819: 192.168.0.212:11311
transport 6 has state: BLACK
03-04-2017 12:16:18.983 UTC Debug baseresolver.cpp:819: 192.168.0.212:11311
transport 6 has state: BLACK
03-04-2017 12:16:18.983 UTC Debug baseresolver.cpp:1032: Added an unhealthy
server, now have 1 of 2
03-04-2017 12:16:18.983 UTC Debug memcachedstore.cpp:1469: Found 1 targets for
sprout.ims.cw.4gtss.com
03-04-2017 12:16:18.983 UTC Debug memcachedstore.cpp:1494: Duplicate target
IP=192.168.0.212, port= 11311 as it is the only target
03-04-2017 12:16:18.983 UTC Debug memcachedstore.cpp:1082: Try server IP
192.168.0.212, port 11311
03-04-2017 12:16:18.983 UTC Debug connection_pool.h:231: Request for connection
to IP: 192.168.0.212, port: 11311
03-04-2017 12:16:18.983 UTC Debug connection_pool.h:244: Found existing
connection 0x7f986c059740 in pool
03-04-2017 12:16:18.983 UTC Debug memcachedstore.cpp:144: Attempting to add
data for key impi\\[email protected]
03-04-2017 12:16:18.983 UTC Debug memcachedstore.cpp:154: Attempting memcached
ADD command
03-04-2017 12:16:18.984 UTC Debug memcachedstore.cpp:244: ADD/CAS returned rc =
7 (UNKNOWN READ FAILURE)
(140292624120432) UNKNOWN READ FAILURE, host: 192.168.0.212:11311 ->
libmemcached/response.cc:782
03-04-2017 12:16:18.984 UTC Debug memcachedstore.cpp:1093: libmemcached
returned 7
03-04-2017 12:16:18.984 UTC Debug memcachedstore.cpp:1110: Blacklisting target
03-04-2017 12:16:18.984 UTC Debug baseresolver.cpp:400: Add 192.168.0.212:11311
transport 6 to blacklist for 30 seconds, graylist for 0 seconds
03-04-2017 12:16:18.984 UTC Debug connection_pool.h:267: Release connection to
IP: 192.168.0.212, port: 11311 to pool
03-04-2017 12:16:18.984 UTC Debug memcachedstore.cpp:1082: Try server IP
192.168.0.212, port 11311
03-04-2017 12:16:18.984 UTC Debug connection_pool.h:231: Request for connection
to IP: 192.168.0.212, port: 11311
03-04-2017 12:16:18.984 UTC Debug connection_pool.h:244: Found existing
connection 0x7f986c059740 in pool
03-04-2017 12:16:18.984 UTC Debug memcachedstore.cpp:144: Attempting to add
data for key impi\\[email protected]
03-04-2017 12:16:18.984 UTC Debug memcachedstore.cpp:154: Attempting memcached
ADD command
03-04-2017 12:16:18.985 UTC Debug memcachedstore.cpp:244: ADD/CAS returned rc =
7 (UNKNOWN READ FAILURE)
(140292624120432) UNKNOWN READ FAILURE, host: 192.168.0.212:11311 ->
libmemcached/response.cc:782
03-04-2017 12:16:18.985 UTC Debug memcachedstore.cpp:1093: libmemcached
returned 7
03-04-2017 12:16:18.985 UTC Debug memcachedstore.cpp:1110: Blacklisting target
03-04-2017 12:16:18.985 UTC Debug baseresolver.cpp:400: Add 192.168.0.212:11311
transport 6 to blacklist for 30 seconds, graylist for 0 seconds
03-04-2017 12:16:18.985 UTC Debug connection_pool.h:267: Release connection to
IP: 192.168.0.212, port: 11311 to pool
03-04-2017 12:16:18.985 UTC Debug memcachedstore.cpp:1366: Failed to write data
for impi\\[email protected] to store with error UNKNOWN READ FAILURE
03-04-2017 12:16:18.985 UTC Error impistore.cpp:664: Failed to write IMPI for
private_id [email protected]
03-04-2017 12:16:18.985 UTC Debug authenticationsproutlet.cpp:675: Failed to
store nonce in memcached
03-04-2017 12:16:18.985 UTC Info acr.cpp:690: No CCF or ECF to send ACR for
session gKQzo8Y5VOUJVN__WEpSBA.. to - dropping!
03-04-2017 12:16:18.985 UTC Verbose sproutletproxy.cpp:1427:
authentication-0x7f985c03da90 sending Response msg 500/REGISTER/cseq=1
(tdta0x7f985c06acd0)
03-04-2017 12:16:18.985 UTC Debug sproutletproxy.cpp:1775: Removing message
0x7f985c069320 => txdata 0x7f985c068db8 mapping
03-04-2017 12:16:18.985 UTC Debug sproutletproxy.cpp:1504: Free message
tdta0x7f985c068d10
03-04-2017 12:16:18.985 UTC Debug pjsip: tdta0x7f985c06 Destroying txdata
Request msg REGISTER/cseq=1 (tdta0x7f985c068d10)
03-04-2017 12:16:18.985 UTC Debug acr.cpp:54: Destroyed ACR (0x7f985c0110a0)
03-04-2017 12:16:18.985 UTC Debug sproutletproxy.cpp:1783: Processing actions
from sproutlet - 1 responses, 0 requests, 0 timers
03-04-2017 12:16:18.985 UTC Debug sproutletproxy.cpp:1869: Aggregating response
with status code 500
03-04-2017 12:16:18.985 UTC Debug sproutletproxy.cpp:1919: 3xx/4xx/5xx/6xx
response
03-04-2017 12:16:18.985 UTC Debug sproutletproxy.cpp:1923: Best 3xx/4xx/5xx/6xx
response so far
03-04-2017 12:16:18.985 UTC Debug sproutletproxy.cpp:1810: All UAC responded
03-04-2017 12:16:18.985 UTC Debug sproutletproxy.cpp:1775: Removing message
0x7f985c06b2e0 => txdata 0x7f985c06ad78 mapping
03-04-2017 12:16:18.985 UTC Verbose sproutletproxy.cpp:2095: Routing Response
msg 500/REGISTER/cseq=1 (tdta0x7f985c06acd0) (602 bytes) to upstream sproutlet
icscf:
--start msg--
SIP/2.0 500 Internal Server Error
Via: SIP/2.0/TCP
192.168.0.210:5058;rport=34676;received=192.168.0.210;branch=z9hG4bKPj7OjKdLfzTihQz6Rf6JLTREZbtt3I978D
Via: SIP/2.0/TCP
192.168.0.207:44446;received=192.168.0.207;branch=z9hG4bK-524287-1---b4bccf7baf143257
Call-ID: gKQzo8Y5VOUJVN__WEpSBA..
From: <sip:[email protected]>;tag=9542d61f
To:
<sip:[email protected]>;tag=z9hG4bKPj7OjKdLfzTihQz6Rf6JLTREZbtt3I978D
CSeq: 1 REGISTER
WWW-Authenticate: Digest
realm="ims.cw.4gtss.com",nonce="4884896d5d032f4b",opaque="6748a04c7f558e19",algorithm=MD5,qop="auth"
Content-Length: 0
--end msg--
03-04-2017 12:16:18.985 UTC Debug sproutletproxy.cpp:1768: Adding message
0x7f985c06b2e0 => txdata 0x7f985c06ad78 mapping
03-04-2017 12:16:18.985 UTC Verbose sproutletproxy.cpp:1666:
icscf-0x7f985c0008e0 received final response Response msg 500/REGISTER/cseq=1
(tdta0x7f985c06acd0) on fork 0, state = Terminated
03-04-2017 12:16:18.985 UTC Debug acr.cpp:1540: Stored 1 subscription
identifiers
03-04-2017 12:16:18.985 UTC Debug icscfsproutlet.cpp:333: Check retry
conditions for REGISTER, status = 500, S-CSCF responsive
03-04-2017 12:16:18.985 UTC Verbose sproutletproxy.cpp:1427:
icscf-0x7f985c0008e0 sending Response msg 500/REGISTER/cseq=1
(tdta0x7f985c06acd0)
03-04-2017 12:16:18.985 UTC Debug sproutletproxy.cpp:1783: Processing actions
from sproutlet - 1 responses, 0 requests, 0 timers
03-04-2017 12:16:18.985 UTC Debug sproutletproxy.cpp:1869: Aggregating response
with status code 500
03-04-2017 12:16:18.985 UTC Debug sproutletproxy.cpp:1919: 3xx/4xx/5xx/6xx
response
03-04-2017 12:16:18.985 UTC Debug sproutletproxy.cpp:1923: Best 3xx/4xx/5xx/6xx
response so far
03-04-2017 12:16:18.985 UTC Debug sproutletproxy.cpp:1810: All UAC responded
03-04-2017 12:16:18.985 UTC Debug sproutletproxy.cpp:1775: Removing message
0x7f985c06b2e0 => txdata 0x7f985c06ad78 mapping
03-04-2017 12:16:18.985 UTC Debug pjsip: tsx0x7f985c010 Sending Response msg
500/REGISTER/cseq=1 (tdta0x7f985c06acd0) in state Trying
03-04-2017 12:16:18.985 UTC Verbose common_sip_processing.cpp:136: TX 602 bytes
Response msg 500/REGISTER/cseq=1 (tdta0x7f985c06acd0) to TCP
192.168.0.210:34676:
--start msg--
SIP/2.0 500 Internal Server Error
Via: SIP/2.0/TCP
192.168.0.210:5058;rport=34676;received=192.168.0.210;branch=z9hG4bKPj7OjKdLfzTihQz6Rf6JLTREZbtt3I978D
Via: SIP/2.0/TCP
192.168.0.207:44446;received=192.168.0.207;branch=z9hG4bK-524287-1---b4bccf7baf143257
Call-ID: gKQzo8Y5VOUJVN__WEpSBA..
From: <sip:[email protected]>;tag=9542d61f
To:
<sip:[email protected]>;tag=z9hG4bKPj7OjKdLfzTihQz6Rf6JLTREZbtt3I978D
CSeq: 1 REGISTER
WWW-Authenticate: Digest
realm="ims.cw.4gtss.com",nonce="4884896d5d032f4b",opaque="6748a04c7f558e19",algorithm=MD5,qop="auth"
Content-Length: 0
--end msg--
03-04-2017 12:16:18.985 UTC Debug pjsip: tsx0x7f985c010 State changed from
Trying to Completed, event=TX_MSG
03-04-2017 12:16:18.985 UTC Debug basicproxy.cpp:213: tsx0x7f985c010708 -
tu_on_tsx_state UAS, TSX_STATE TX_MSG state=Completed
03-04-2017 12:16:18.985 UTC Verbose sproutletproxy.cpp:1861:
icscf-0x7f985c0008e0 suiciding
03-04-2017 12:16:18.985 UTC Debug sproutletproxy.cpp:1169: Destroying
SproutletWrapper 0x7f985c00cbf0
03-04-2017 12:16:18.985 UTC Info acr.cpp:690: No CCF or ECF to send ACR for
session gKQzo8Y5VOUJVN__WEpSBA.. to - dropping!
03-04-2017 12:16:18.985 UTC Debug acr.cpp:54: Destroyed ACR (0x7f985c04d290)
03-04-2017 12:16:18.985 UTC Debug sproutletproxy.cpp:1178: Free original
request Request msg REGISTER/cseq=1 (tdta0x7f985c00d0f0) (tdta0x7f985c00d0f0)
03-04-2017 12:16:18.985 UTC Verbose sproutletproxy.cpp:1861:
authentication-0x7f985c03da90 suiciding
03-04-2017 12:16:18.985 UTC Debug sproutletproxy.cpp:1169: Destroying
SproutletWrapper 0x7f985c03db00
03-04-2017 12:16:18.985 UTC Debug sproutletproxy.cpp:1178: Free original
request Request msg REGISTER/cseq=1 (tdta0x7f985c05a950) (tdta0x7f985c05a950)
03-04-2017 12:16:18.985 UTC Debug pjsip: tdta0x7f985c05 Destroying txdata
Request msg REGISTER/cseq=1 (tdta0x7f985c05a950)
03-04-2017 12:16:18.985 UTC Debug thread_dispatcher.cpp:200: Worker thread
completed processing message 0x7f98640b0ae8
03-04-2017 12:16:18.985 UTC Debug thread_dispatcher.cpp:206: Request latency =
14704us
03-04-2017 12:16:18.985 UTC Info load_monitor.cpp:232: Accepted 100.000000% of
requests, latency error = -0.915970, overload responses = 0
03-04-2017 12:16:18.985 UTC Status load_monitor.cpp:285: Maximum incoming
request rate/second unchanged - only handled 25 requests in last 203671ms,
minimum threshold for a change is 25458.876953
03-04-2017 12:16:18.985 UTC Debug
snmp_continuous_accumulator_by_scope_table.cpp:111: Accumulating sample 250ui
into continuous accumulator statistic
03-04-2017 12:16:18.985 UTC Debug
snmp_continuous_accumulator_by_scope_table.cpp:111: Accumulating sample 250ui
into continuous accumulator statistic
03-04-2017 12:16:18.989 UTC Debug pjsip: tsx0x7f985c010 Timeout timer event
03-04-2017 12:16:18.989 UTC Debug pjsip: tsx0x7f985c010 State changed from
Completed to Terminated, event=TIMER
03-04-2017 12:16:18.989 UTC Debug basicproxy.cpp:213: tsx0x7f985c010708 -
tu_on_tsx_state UAS, TSX_STATE TIMER state=Terminated
03-04-2017 12:16:18.989 UTC Debug basicproxy.cpp:1308: Report SAS end marker -
trail (190)
03-04-2017 12:16:18.989 UTC Debug pjsip: tsx0x7f985c010 Timeout timer event
03-04-2017 12:16:18.989 UTC Debug pjsip: tsx0x7f985c010 State changed from
Terminated to Destroyed, event=TIMER
03-04-2017 12:16:18.989 UTC Debug basicproxy.cpp:213: tsx0x7f985c010708 -
tu_on_tsx_state UAS, TSX_STATE TIMER state=Destroyed
03-04-2017 12:16:18.989 UTC Debug sproutletproxy.cpp:750: tsx0x7f985c010708 -
UAS tsx destroyed
03-04-2017 12:16:18.989 UTC Debug sproutletproxy.cpp:1090: Safe for UASTsx to
suicide
03-04-2017 12:16:18.989 UTC Debug basicproxy.cpp:1483: Transaction ((nil))
suiciding
03-04-2017 12:16:18.989 UTC Verbose sproutletproxy.cpp:538: Sproutlet Proxy
transaction (0x7f985c01c2d0) destroyed
03-04-2017 12:16:18.989 UTC Debug basicproxy.cpp:494: BasicProxy::UASTsx
destructor (0x7f985c01c2d0)
03-04-2017 12:16:18.989 UTC Debug basicproxy.cpp:511: Disconnect UAC
transactions from UAS transaction
03-04-2017 12:16:18.989 UTC Debug basicproxy.cpp:525: Free original request
03-04-2017 12:16:18.989 UTC Debug pjsip: tdta0x7f985c00 Destroying txdata
Request msg REGISTER/cseq=1 (tdta0x7f985c00d0f0)
03-04-2017 12:16:18.989 UTC Debug basicproxy.cpp:534: Free un-used best response
03-04-2017 12:16:18.989 UTC Debug pjsip: tdta0x7f985c05 Destroying txdata
Response msg 408/REGISTER/cseq=1 (tdta0x7f985c059940)
03-04-2017 12:16:18.989 UTC Debug basicproxy.cpp:555: BasicProxy::UASTsx
destructor completed
03-04-2017 12:16:18.989 UTC Debug pjsip: tdta0x7f985c06 Destroying txdata
Response msg 500/REGISTER/cseq=1 (tdta0x7f985c06acd0)
03-04-2017 12:16:18.989 UTC Debug pjsip: tsx0x7f985c010 Transaction destroyed!
_______________________________________________
Clearwater mailing list
[email protected]
http://lists.projectclearwater.org/mailman/listinfo/clearwater_lists.projectclearwater.org
