Thanks Robert,
I got the issue with your suggestion. The authorized format should be
privateid@domain.
Regards,
Tam Vo
On Wednesday, June 24, 2015 11:51 PM, Robert Day
<[email protected]> wrote:
#yiv0061778429 #yiv0061778429 -- _filtered #yiv0061778429
{font-family:Helvetica;panose-1:2 11 6 4 2 2 2 2 2 4;} _filtered #yiv0061778429
{font-family:Helvetica;panose-1:2 11 6 4 2 2 2 2 2 4;} _filtered #yiv0061778429
{font-family:Calibri;panose-1:2 15 5 2 2 2 4 3 2 4;}#yiv0061778429
#yiv0061778429 p.yiv0061778429MsoNormal, #yiv0061778429
li.yiv0061778429MsoNormal, #yiv0061778429 div.yiv0061778429MsoNormal
{margin:0cm;margin-bottom:.0001pt;font-size:12.0pt;}#yiv0061778429 a:link,
#yiv0061778429 span.yiv0061778429MsoHyperlink
{color:#0563C1;text-decoration:underline;}#yiv0061778429 a:visited,
#yiv0061778429 span.yiv0061778429MsoHyperlinkFollowed
{color:#954F72;text-decoration:underline;}#yiv0061778429
span.yiv0061778429EmailStyle17 {color:#1F497D;}#yiv0061778429
.yiv0061778429MsoChpDefault {font-size:10.0pt;} _filtered #yiv0061778429
{margin:72.0pt 72.0pt 72.0pt 72.0pt;}#yiv0061778429
div.yiv0061778429WordSection1 {}#yiv0061778429 Hi Tam Vo, The Authorization
header that X-Lite is sending in is: Authorization: Digest
username="7107204018", realm="example.com", nonce="7ddf3cfa67ba46bb",
uri="sip:example.com", response="612f62e73abddbeec9d82ad5ff7120c7",
algorithm=MD5, cnonce="1f0876e3a01bf152f5d20335a797800b",
opaque="1d5cd17028c1f33b", qop=auth,
nc=00000001,integrity-protected=ip-assoc-pending
Note that the “username” field is just “7107204018”, whereas I’d
[email protected] (matching the private identity shown in Ellis) –
because this is wrong, Homestead can’t find the subscriber and returns 404,
which is why HTTP errors are reported. The fix is to set your ‘Authorization
name’ in X-Lite [email protected]. Best, Rob -- Rob Day Software
Engineer, Project Clearwater From:
[email protected]
[mailto:[email protected]]On Behalf Of atva angel
Sent: 24 June 2015 16:35
To: Clearwater Mail
Subject: [Clearwater] S-CSCF returns 403 Forbidden due to cURL failure with
cURL error code 0 Hi community, I have clearwater imscore installed
manually done with 6 machines. When I register the IMS user from X-lite, S-CSCF
returns 403 Forbidden due to cURL failure with cURL error code 0. Could you
please help to take a look and share your advice? Thanks. #On the machine
runs sprout root@ubun3:~# cat /etc/clearwater/config
# Deployment definitions
home_domain=example.com
bono_hostname=137.116.157.173
sprout_hostname=137.116.157.174
#chronos_hostname=:7253
hs_hostname=137.116.157.176:8888
hs_provisioning_hostname=137.116.157.176:8889
ralf_hostname=137.116.157.177:10888
xdms_hostname=137.116.157.175:7888
# Local IP configuration
local_ip=137.116.157.174
public_ip=137.116.157.174
public_hostname=137.116.157.174
# Email server configuration
smtp_smarthost=127.0.0.1
smtp_username=username
smtp_password=password
email_recovery_sender=clearwater@xxxxxxxxxxx
# Keys
signup_key=secret
turn_workaround=secret
ellis_api_key=secret
ellis_cookie_key=secret
# I-CSCF/S-CSCF configuration
#icscf=5052
#scscf=5054 #sprout log
root@ubun3:/etc/clearwater#
root@ubun3:/etc/clearwater# tail -f /var/log/sprout/sprout_current.txt
24-06-2015 12:28:20.936 UTC Debug thread_dispatcher.cpp:176: Worker thread
completed processing message 0x7f8db406b688
24-06-2015 12:28:20.936 UTC Debug thread_dispatcher.cpp:182: Request latency =
371us
24-06-2015 12:28:20.936 UTC Debug statistic.cpp:103: Send new value for
statistic latency_us, size 5
24-06-2015 12:28:20.936 UTC Debug zmq_lvc.cpp:172: Update to latency_us
statistic
24-06-2015 12:28:20.936 UTC Debug zmq_lvc.cpp:256: Clearing message cache for
0x7f8de8012ff0
24-06-2015 12:28:20.942 UTC Verbose httpstack.cpp:281: Process request for URL
/ping, args (null)
24-06-2015 12:28:20.942 UTC Verbose httpstack.cpp:69: Sending response 200 to
request for URL /ping, args (null)
24-06-2015 12:28:21.939 UTC Verbose pjsip: tcps0x7f8db417 TCP connection closed
24-06-2015 12:28:21.939 UTC Debug connection_tracker.cpp:91: Connection
0x7f8db4172e38 has been destroyed
24-06-2015 12:28:21.939 UTC Verbose pjsip: tcps0x7f8db417 TCP transport
destroyed with reason 70016: End of file (PJ_EEOF)
24-06-2015 12:28:30.960 UTC Verbose pjsip: tcplis:5054 TCP listener
137.116.157.174:5054: got incoming TCP connection from 137.116.157.174:35144,
sock=374
24-06-2015 12:28:30.960 UTC Verbose pjsip: tcps0x7f8db417 TCP server transport
created
24-06-2015 12:28:30.961 UTC Debug pjsip: sip_endpoint.c Processing incoming
message: Request msg OPTIONS/cseq=3190 (rdata0x7f8db4173170)
24-06-2015 12:28:30.961 UTC Verbose common_sip_processing.cpp:120: RX 358 bytes
Request msg OPTIONS/cseq=3190 (rdata0x7f8db4173170) from TCP
137.116.157.174:35144:
--start msg--
OPTIONS sip:[email protected]:5054 SIP/2.0
Via: SIP/2.0/TCP 137.116.157.174;rport;branch=z9hG4bK-3190
Max-Forwards: 2
To: <sip:[email protected]:5054>
From: poll-sip <sip:[email protected]>;tag=3190
Call-ID: poll-sip-3190
CSeq: 3190 OPTIONS
Contact: <sip:137.116.157.174>
Accept: application/sdp
Content-Length: 0
User-Agent: poll-sip
--end msg--
24-06-2015 12:28:30.961 UTC Debug statistic.cpp:103: Send new value for
statistic incoming_requests, size 1
24-06-2015 12:28:30.961 UTC Debug zmq_lvc.cpp:172: Update to incoming_requests
statistic
24-06-2015 12:28:30.961 UTC Debug zmq_lvc.cpp:256: Clearing message cache for
0x7f8de802a270
24-06-2015 12:28:30.961 UTC Debug thread_dispatcher.cpp:236: Queuing cloned
received message 0x7f8db406b688 for worker threads
24-06-2015 12:28:30.961 UTC Debug statistic.cpp:103: Send new value for
statistic queue_size, size 5
24-06-2015 12:28:30.961 UTC Debug zmq_lvc.cpp:172: Update to queue_size
statistic
24-06-2015 12:28:30.961 UTC Debug zmq_lvc.cpp:256: Clearing message cache for
0x7f8de80335b0
24-06-2015 12:28:30.961 UTC Debug thread_dispatcher.cpp:149: Worker thread
dequeue message 0x7f8db406b688
24-06-2015 12:28:30.961 UTC Debug pjsip: sip_endpoint.c Distributing rdata to
modules: Request msg OPTIONS/cseq=3190 (rdata0x7f8db406b688)
24-06-2015 12:28:30.961 UTC Debug pjsip: endpoint Response msg
200/OPTIONS/cseq=3190 (tdta0x7f8db403eaa0) created
24-06-2015 12:28:30.961 UTC Verbose common_sip_processing.cpp:136: TX 284 bytes
Response msg 200/OPTIONS/cseq=3190 (tdta0x7f8db403eaa0) to TCP
137.116.157.174:35144:
--start msg--
SIP/2.0 200 OK
Via: SIP/2.0/TCP
137.116.157.174;rport=35144;received=137.116.157.174;branch=z9hG4bK-3190
Call-ID: poll-sip-3190
From: "poll-sip" <sip:[email protected]>;tag=3190
To: <sip:[email protected]>;tag=z9hG4bK-3190
CSeq: 3190 OPTIONS
Content-Length: 0
--end msg--
24-06-2015 12:28:30.961 UTC Debug pjsip: tdta0x7f8db403 Destroying txdata
Response msg 200/OPTIONS/cseq=3190 (tdta0x7f8db403eaa0)
24-06-2015 12:28:30.961 UTC Debug thread_dispatcher.cpp:176: Worker thread
completed processing message 0x7f8db406b688
24-06-2015 12:28:30.961 UTC Debug thread_dispatcher.cpp:182: Request latency =
296us
24-06-2015 12:28:30.961 UTC Debug statistic.cpp:103: Send new value for
statistic latency_us, size 5
24-06-2015 12:28:30.961 UTC Debug zmq_lvc.cpp:172: Update to latency_us
statistic
24-06-2015 12:28:30.961 UTC Debug zmq_lvc.cpp:256: Clearing message cache for
0x7f8de8012ff0
24-06-2015 12:28:30.964 UTC Verbose httpstack.cpp:281: Process request for URL
/ping, args (null)
24-06-2015 12:28:30.964 UTC Verbose httpstack.cpp:69: Sending response 200 to
request for URL /ping, args (null)
24-06-2015 12:28:31.965 UTC Verbose pjsip: tcps0x7f8db417 TCP connection closed
24-06-2015 12:28:31.966 UTC Debug connection_tracker.cpp:91: Connection
0x7f8db4172e38 has been destroyed
24-06-2015 12:28:31.966 UTC Verbose pjsip: tcps0x7f8db417 TCP transport
destroyed with reason 70016: End of file (PJ_EEOF)
24-06-2015 12:28:38.286 UTC Debug pjsip: sip_endpoint.c Processing incoming
message: Request msg REGISTER/cseq=1 (rdata0x7f8db40536b0)
24-06-2015 12:28:38.286 UTC Verbose common_sip_processing.cpp:120: RX 875 bytes
Request msg REGISTER/cseq=1 (rdata0x7f8db40536b0) from TCP
137.116.157.173:41219:
--start msg--
REGISTER sip:example.com SIP/2.0
Via: SIP/2.0/TCP
137.116.157.173:41219;rport;branch=z9hG4bKPji-nevKQYcoUiCAkw4-aDvXPa3DWTNc9j
Path: <sip:[email protected]:5058;transport=TCP;lr;ob>
Via: SIP/2.0/UDP
137.116.157.232:3214;rport=3214;received=137.116.157.232;branch=z9hG4bK-d8754z-886a6262b8691d67-1---d8754z-
Max-Forwards: 70
Contact: <sip:[email protected]:3214;rinstance=298bd1a969f6f2b8>
To: "7107204018" <sip:[email protected]>
From: "7107204018" <sip:[email protected]>;tag=3f31ad3b
Call-ID: ZGRjYmZlZjdiZTNiMzBmODMyYzA2ODdmZWNkZmI2ZDM.
CSeq: 1 REGISTER
Expires: 3600
Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, NOTIFY, MESSAGE, SUBSCRIBE,
INFO
User-Agent: X-Lite release 1104o stamp 56125
P-Visited-Network-ID: example.com
Session-Expires: 600
Route: <sip:137.116.157.174:5054;transport=TCP;lr;orig>
Content-Length: 0
--end msg--
24-06-2015 12:28:38.286 UTC Debug statistic.cpp:103: Send new value for
statistic incoming_requests, size 1
24-06-2015 12:28:38.287 UTC Debug zmq_lvc.cpp:172: Update to incoming_requests
statistic
24-06-2015 12:28:38.287 UTC Debug zmq_lvc.cpp:256: Clearing message cache for
0x7f8de802a270
24-06-2015 12:28:38.287 UTC Debug thread_dispatcher.cpp:236: Queuing cloned
received message 0x7f8db406a678 for worker threads
24-06-2015 12:28:38.287 UTC Debug statistic.cpp:103: Send new value for
statistic queue_size, size 5
24-06-2015 12:28:38.287 UTC Debug zmq_lvc.cpp:172: Update to queue_size
statistic
24-06-2015 12:28:38.287 UTC Debug zmq_lvc.cpp:256: Clearing message cache for
0x7f8de80335b0
24-06-2015 12:28:38.287 UTC Debug thread_dispatcher.cpp:149: Worker thread
dequeue message 0x7f8db406a678
24-06-2015 12:28:38.288 UTC Debug pjsip: sip_endpoint.c Distributing rdata to
modules: Request msg REGISTER/cseq=1 (rdata0x7f8db406a678)
24-06-2015 12:28:38.288 UTC Debug acr.cpp:1743: Create RalfACR for node type
S-CSCF with role Originating
24-06-2015 12:28:38.288 UTC Debug acr.cpp:49: Created ACR (0x7f8db00cd7d0)
24-06-2015 12:28:38.288 UTC Debug acr.cpp:171: Created S-CSCF Ralf ACR
24-06-2015 12:28:38.288 UTC Debug acr.cpp:210: Set record type for P/S-CSCF
24-06-2015 12:28:38.288 UTC Debug acr.cpp:218: Non-dialog message =>
EVENT_RECORD
24-06-2015 12:28:38.288 UTC Debug acr.cpp:1471: Stored 0 subscription
identifiers
24-06-2015 12:28:38.288 UTC Debug authentication.cpp:730: No authentication
information in request or stale nonce, so reject with challenge
24-06-2015 12:28:38.288 UTC Debug pjsip: endpoint Response msg
401/REGISTER/cseq=1 (tdta0x7f8db00af940) created
24-06-2015 12:28:38.288 UTC Debug pjutils.cpp:470: Private identity defaulted
from public identity [email protected]
24-06-2015 12:28:38.289 UTC Debug httpconnection.cpp:191: Allocated CURL handle
0x7f8db0156680
24-06-2015 12:28:38.289 UTC Debug httpresolver.cpp:71: HttpResolver::resolve
for host 137.116.157.176, port 8888, family 2
24-06-2015 12:28:38.289 UTC Debug baseresolver.cpp:503: Attempt to parse
137.116.157.176 as IP address
24-06-2015 12:28:38.289 UTC Debug httpresolver.cpp:79: Target is an IP address
24-06-2015 12:28:38.289 UTC Debug httpconnection.cpp:614: Sending HTTP request
:
http://137.116.157.176:8888/impi/7107204018%40example.com/av?impu=sip%3A7107204018%40example.com
(trying 137.116.157.176) on new connection
24-06-2015 12:28:38.299 UTC Debug httpconnection.cpp:629: Received HTTP
response: status=200,
doc={"digest":{"ha1":"dfa242abefea9c2259824c64f7003c31","realm":"example.com","qop":"auth"}}
24-06-2015 12:28:38.299 UTC Debug statistic.cpp:103: Send new value for
statistic connected_homesteads, size 2
24-06-2015 12:28:38.300 UTC Debug zmq_lvc.cpp:172: Update to
connected_homesteads statistic
24-06-2015 12:28:38.300 UTC Debug zmq_lvc.cpp:256: Clearing message cache for
0x7f8de8009cb0
24-06-2015 12:28:38.300 UTC Debug statistic.cpp:103: Send new value for
statistic hss_latency_us, size 5
24-06-2015 12:28:38.300 UTC Debug zmq_lvc.cpp:172: Update to hss_latency_us
statistic
24-06-2015 12:28:38.300 UTC Debug zmq_lvc.cpp:256: Clearing message cache for
0x7f8de8017980
24-06-2015 12:28:38.300 UTC Debug statistic.cpp:103: Send new value for
statistic hss_digest_latency_us, size 5
24-06-2015 12:28:38.300 UTC Debug zmq_lvc.cpp:172: Update to
hss_digest_latency_us statistic
24-06-2015 12:28:38.300 UTC Debug zmq_lvc.cpp:256: Clearing message cache for
0x7f8de801c320
24-06-2015 12:28:38.301 UTC Debug authentication.cpp:124: Verifying AV:
{"digest":{"ha1":"dfa242abefea9c2259824c64f7003c31","realm":"example.com","qop":"auth"}}
24-06-2015 12:28:38.301 UTC Debug authentication.cpp:151: Digest specified
24-06-2015 12:28:38.301 UTC Debug authentication.cpp:334: Valid AV - generate
challenge
24-06-2015 12:28:38.301 UTC Debug authentication.cpp:340: Create
WWW-Authenticate header
24-06-2015 12:28:38.301 UTC Debug authentication.cpp:402: Add Digest information
24-06-2015 12:28:38.301 UTC Debug authentication.cpp:444: Write AV to store
24-06-2015 12:28:38.301 UTC Debug avstore.cpp:72: Set AV for
[email protected]\7ddf3cfa67ba46bb
{"digest":{"ha1":"dfa242abefea9c2259824c64f7003c31","realm":"example.com","qop":"auth"},"branch":"z9hG4bKPji-nevKQYcoUiCAkw4-aDvXPa3DWTNc9j"}
24-06-2015 12:28:38.301 UTC Debug memcachedstore.cpp:542: Writing 141 bytes to
table av [email protected]\7ddf3cfa67ba46bb, CAS = 0, expiry = 40
24-06-2015 12:28:38.301 UTC Debug memcachedstore.cpp:195: Key
av\\[email protected]\7ddf3cfa67ba46bb hashes to vbucket 126 via hash
0x3dff5efe
24-06-2015 12:28:38.301 UTC Debug memcachedstore.cpp:236: Set up new view 1 for
thread
24-06-2015 12:28:38.301 UTC Debug memcachedstore.cpp:243: Setting up server 0
for connection 0x7f8db00a7cc0 (--CONNECT-TIMEOUT=10 --SUPPORT-CAS
--POLL-TIMEOUT=250 --BINARY-PROTOCOL)
24-06-2015 12:28:38.301 UTC Debug memcachedstore.cpp:245: Set up connection
0x7f8db00a7d30 to server 137.116.157.174:11211
24-06-2015 12:28:38.301 UTC Debug memcachedstore.cpp:256: Setting server to IP
address 137.116.157.174 port 11211
24-06-2015 12:28:38.301 UTC Debug memcachedstore.cpp:562: 1 write replicas for
key av\\[email protected]\7ddf3cfa67ba46bb
24-06-2015 12:28:38.301 UTC Debug memcachedstore.cpp:616: Attempt conditional
write to vbucket 126 on replica 0 (connection 0x7f8db00a7d30), CAS = 0, expiry
= 40
24-06-2015 12:28:38.302 UTC Debug memcachedstore.cpp:816: Attempting to add
data for key av\\[email protected]\7ddf3cfa67ba46bb
24-06-2015 12:28:38.302 UTC Debug memcachedstore.cpp:826: Attempting memcached
ADD command
24-06-2015 12:28:38.302 UTC Debug memcachedstore.cpp:916: ADD/CAS returned rc =
0 (SUCCESS)
SUCCESS
24-06-2015 12:28:38.302 UTC Debug memcachedstore.cpp:657: Conditional write
succeeded to replica 0
24-06-2015 12:28:38.302 UTC Debug authentication.cpp:454: Sending {"impi":
"[email protected]", "impu": "sip:[email protected]", "nonce":
"7ddf3cfa67ba46bb"} to Chronos to set AV timer
24-06-2015 12:28:38.302 UTC Debug httpconnection.cpp:191: Allocated CURL handle
0x7f8db01a0800
24-06-2015 12:28:38.303 UTC Debug httpresolver.cpp:71: HttpResolver::resolve
for host 127.0.0.1, port 7253, family 2
24-06-2015 12:28:38.303 UTC Debug baseresolver.cpp:503: Attempt to parse
127.0.0.1 as IP address
24-06-2015 12:28:38.303 UTC Debug httpresolver.cpp:79: Target is an IP address
24-06-2015 12:28:38.303 UTC Debug httpconnection.cpp:614: Sending HTTP request
: http://127.0.0.1:7253/timers (trying 127.0.0.1) on new connection
24-06-2015 12:28:38.304 UTC Debug httpconnection.cpp:914: Received header
http/1.1200ok with value
24-06-2015 12:28:38.304 UTC Debug httpconnection.cpp:914: Received header
location with value /timers/ffffffffc00000040040001000104104
24-06-2015 12:28:38.304 UTC Debug httpconnection.cpp:914: Received header
content-length with value 0
24-06-2015 12:28:38.304 UTC Debug httpconnection.cpp:914: Received header with
value
24-06-2015 12:28:38.304 UTC Debug httpconnection.cpp:629: Received HTTP
response: status=200, doc=
24-06-2015 12:28:38.304 UTC Verbose common_sip_processing.cpp:136: TX 651 bytes
Response msg 401/REGISTER/cseq=1 (tdta0x7f8db00af940) to TCP
137.116.157.173:41219:
--start msg--
SIP/2.0 401 Unauthorized
Via: SIP/2.0/TCP
137.116.157.173:41219;rport=41219;received=137.116.157.173;branch=z9hG4bKPji-nevKQYcoUiCAkw4-aDvXPa3DWTNc9j
Via: SIP/2.0/UDP
137.116.157.232:3214;rport=3214;received=137.116.157.232;branch=z9hG4bK-d8754z-886a6262b8691d67-1---d8754z-
Call-ID: ZGRjYmZlZjdiZTNiMzBmODMyYzA2ODdmZWNkZmI2ZDM.
From: "7107204018" <sip:[email protected]>;tag=3f31ad3b
To: "7107204018"
<sip:[email protected]>;tag=z9hG4bKPji-nevKQYcoUiCAkw4-aDvXPa3DWTNc9j
CSeq: 1 REGISTER
WWW-Authenticate: Digest
realm="example.com",nonce="7ddf3cfa67ba46bb",opaque="1d5cd17028c1f33b",algorithm=MD5,qop="auth"
Content-Length: 0
--end msg--
24-06-2015 12:28:38.304 UTC Debug pjsip: tdta0x7f8db00a Destroying txdata
Response msg 401/REGISTER/cseq=1 (tdta0x7f8db00af940)
24-06-2015 12:28:38.304 UTC Info acr.cpp:648: No CCF or ECF to send ACR for
session ZGRjYmZlZjdiZTNiMzBmODMyYzA2ODdmZWNkZmI2ZDM. to - dropping!
24-06-2015 12:28:38.305 UTC Debug acr.cpp:54: Destroyed ACR (0x7f8db00cd7d0)
24-06-2015 12:28:38.305 UTC Debug thread_dispatcher.cpp:176: Worker thread
completed processing message 0x7f8db406a678
24-06-2015 12:28:38.305 UTC Debug thread_dispatcher.cpp:182: Request latency =
17777us
24-06-2015 12:28:38.305 UTC Debug statistic.cpp:103: Send new value for
statistic latency_us, size 5
24-06-2015 12:28:38.305 UTC Debug zmq_lvc.cpp:172: Update to latency_us
statistic
24-06-2015 12:28:38.305 UTC Debug zmq_lvc.cpp:256: Clearing message cache for
0x7f8de8012ff0
24-06-2015 12:28:38.550 UTC Debug pjsip: sip_endpoint.c Processing incoming
message: Request msg REGISTER/cseq=2 (rdata0x7f8db400aab0)
24-06-2015 12:28:38.550 UTC Verbose common_sip_processing.cpp:120: RX 1180
bytes Request msg REGISTER/cseq=2 (rdata0x7f8db400aab0) from TCP
137.116.157.173:51538:
--start msg--
REGISTER sip:example.com SIP/2.0
Via: SIP/2.0/TCP
137.116.157.173:51538;rport;branch=z9hG4bKPjZp.BQJwh-2TUjg.Ynx-Z0vtONh3SnXbX
Path: <sip:[email protected]:5058;transport=TCP;lr;ob>
Via: SIP/2.0/UDP
137.116.157.232:3214;rport=3214;received=137.116.157.232;branch=z9hG4bK-d8754z-f5095d7a4d239b01-1---d8754z-
Max-Forwards: 70
Contact: <sip:[email protected]:3214;rinstance=298bd1a969f6f2b8>
To: "7107204018" <sip:[email protected]>
From: "7107204018" <sip:[email protected]>;tag=3f31ad3b
Call-ID: ZGRjYmZlZjdiZTNiMzBmODMyYzA2ODdmZWNkZmI2ZDM.
CSeq: 2 REGISTER
Expires: 3600
Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, NOTIFY, MESSAGE, SUBSCRIBE,
INFO
User-Agent: X-Lite release 1104o stamp 56125
Authorization: Digest username="7107204018", realm="example.com",
nonce="7ddf3cfa67ba46bb", uri="sip:example.com",
response="612f62e73abddbeec9d82ad5ff7120c7", algorithm=MD5,
cnonce="1f0876e3a01bf152f5d20335a797800b", opaque="1d5cd17028c1f33b", qop=auth,
nc=00000001,integrity-protected=ip-assoc-pending
P-Visited-Network-ID: example.com
Session-Expires: 600
Route: <sip:137.116.157.174:5054;transport=TCP;lr;orig>
Content-Length: 0
--end msg--
24-06-2015 12:28:38.550 UTC Debug thread_dispatcher.cpp:236: Queuing cloned
received message 0x7f8db406a678 for worker threads
24-06-2015 12:28:38.550 UTC Debug thread_dispatcher.cpp:149: Worker thread
dequeue message 0x7f8db406a678
24-06-2015 12:28:38.550 UTC Debug pjsip: sip_endpoint.c Distributing rdata to
modules: Request msg REGISTER/cseq=2 (rdata0x7f8db406a678)
24-06-2015 12:28:38.550 UTC Debug authentication.cpp:544: Authorization header
in request
24-06-2015 12:28:38.551 UTC Debug memcachedstore.cpp:195: Key
av\\7107204018\7ddf3cfa67ba46bb hashes to vbucket 115 via hash 0xfd57b173
24-06-2015 12:28:38.551 UTC Debug memcachedstore.cpp:236: Set up new view 1 for
thread
24-06-2015 12:28:38.551 UTC Debug memcachedstore.cpp:243: Setting up server 0
for connection 0x7f8db80b9150 (--CONNECT-TIMEOUT=10 --SUPPORT-CAS
--POLL-TIMEOUT=250 --BINARY-PROTOCOL)
24-06-2015 12:28:38.551 UTC Debug memcachedstore.cpp:245: Set up connection
0x7f8db8007310 to server 137.116.157.174:11211
24-06-2015 12:28:38.551 UTC Debug memcachedstore.cpp:256: Setting server to IP
address 137.116.157.174 port 11211
24-06-2015 12:28:38.551 UTC Debug memcachedstore.cpp:367: 1 read replicas for
key av\\7107204018\7ddf3cfa67ba46bb
24-06-2015 12:28:38.551 UTC Debug memcachedstore.cpp:402: Attempt to read from
replica 0 (connection 0x7f8db8007310)
24-06-2015 12:28:38.551 UTC Debug memcachedstore.cpp:780: Fetch result
24-06-2015 12:28:38.552 UTC Debug memcachedstore.cpp:418: Read for
av\\7107204018\7ddf3cfa67ba46bb on replica 0 returned NOTFOUND
24-06-2015 12:28:38.552 UTC Debug memcachedstore.cpp:492: At least one replica
returned not found, so return NOT_FOUND
24-06-2015 12:28:38.552 UTC Debug authentication.cpp:597: Verify authentication
information in request
24-06-2015 12:28:38.552 UTC Warning authentication.cpp:209: Received an
authentication request for 7107204018 with nonce 7ddf3cfa67ba46bb, but no
matching AV found
24-06-2015 12:28:38.552 UTC Debug acr.cpp:1743: Create RalfACR for node type
S-CSCF with role Originating
24-06-2015 12:28:38.552 UTC Debug acr.cpp:49: Created ACR (0x7f8db8196350)
24-06-2015 12:28:38.552 UTC Debug acr.cpp:171: Created S-CSCF Ralf ACR
24-06-2015 12:28:38.552 UTC Debug acr.cpp:210: Set record type for P/S-CSCF
24-06-2015 12:28:38.552 UTC Debug acr.cpp:218: Non-dialog message =>
EVENT_RECORD
24-06-2015 12:28:38.552 UTC Debug acr.cpp:1471: Stored 0 subscription
identifiers
24-06-2015 12:28:38.552 UTC Debug authentication.cpp:730: No authentication
information in request or stale nonce, so reject with challenge
24-06-2015 12:28:38.552 UTC Debug pjsip: endpoint Response msg
401/REGISTER/cseq=2 (tdta0x7f8db81966b0) created
24-06-2015 12:28:38.552 UTC Debug pjutils.cpp:463: Private identity from
authorization header = 7107204018
24-06-2015 12:28:38.553 UTC Debug httpconnection.cpp:191: Allocated CURL handle
0x7f8db81dc3d0
24-06-2015 12:28:38.554 UTC Debug httpresolver.cpp:71: HttpResolver::resolve
for host 137.116.157.176, port 8888, family 2
24-06-2015 12:28:38.554 UTC Debug baseresolver.cpp:503: Attempt to parse
137.116.157.176 as IP address
24-06-2015 12:28:38.554 UTC Debug httpresolver.cpp:79: Target is an IP address
24-06-2015 12:28:38.554 UTC Debug httpconnection.cpp:614: Sending HTTP request
:
http://137.116.157.176:8888/impi/7107204018/av?impu=sip%3A7107204018%40example.com
(trying 137.116.157.176) on new connection
24-06-2015 12:28:38.558 UTC Debug httpconnection.cpp:629: Received HTTP
response: status=404, doc=
24-06-2015 12:28:38.558 UTC Debug statistic.cpp:103: Send new value for
statistic connected_homesteads, size 2
24-06-2015 12:28:38.558 UTC Debug zmq_lvc.cpp:172: Update to
connected_homesteads statistic
24-06-2015 12:28:38.558 UTC Debug zmq_lvc.cpp:256: Clearing message cache for
0x7f8de8009cb0
24-06-2015 12:28:38.558 UTC Error httpconnection.cpp:748: cURL failure with
cURL error code 0 (see man 3 libcurl-errors) and HTTP error code 404
24-06-2015 12:28:38.558 UTC Error hssconnection.cpp:143: Failed to get
Authentication Vector for 7107204018
24-06-2015 12:28:38.559 UTC Debug authentication.cpp:474: Failed to get
Authentication vector
24-06-2015 12:28:38.559 UTC Verbose common_sip_processing.cpp:136: TX 525 bytes
Response msg 403/REGISTER/cseq=2 (tdta0x7f8db81966b0) to TCP
137.116.157.173:51538:
--start msg--
SIP/2.0 403 Forbidden
Via: SIP/2.0/TCP
137.116.157.173:51538;rport=51538;received=137.116.157.173;branch=z9hG4bKPjZp.BQJwh-2TUjg.Ynx-Z0vtONh3SnXbX
Via: SIP/2.0/UDP
137.116.157.232:3214;rport=3214;received=137.116.157.232;branch=z9hG4bK-d8754z-f5095d7a4d239b01-1---d8754z-
Call-ID: ZGRjYmZlZjdiZTNiMzBmODMyYzA2ODdmZWNkZmI2ZDM.
From: "7107204018" <sip:[email protected]>;tag=3f31ad3b
To: "7107204018"
<sip:[email protected]>;tag=z9hG4bKPjZp.BQJwh-2TUjg.Ynx-Z0vtONh3SnXbX
CSeq: 2 REGISTER
Content-Length: 0
--end msg--
24-06-2015 12:28:38.559 UTC Debug pjsip: tdta0x7f8db819 Destroying txdata
Response msg 403/REGISTER/cseq=2 (tdta0x7f8db81966b0)
24-06-2015 12:28:38.559 UTC Info acr.cpp:648: No CCF or ECF to send ACR for
session ZGRjYmZlZjdiZTNiMzBmODMyYzA2ODdmZWNkZmI2ZDM. to - dropping!
24-06-2015 12:28:38.559 UTC Debug acr.cpp:54: Destroyed ACR (0x7f8db8196350)
24-06-2015 12:28:38.559 UTC Debug thread_dispatcher.cpp:176: Worker thread
completed processing message 0x7f8db406a678
24-06-2015 12:28:38.559 UTC Debug thread_dispatcher.cpp:182: Request latency =
9248us
24-06-2015 12:28:38.559 UTC Info load_monitor.cpp:194: Accepted 100.000000% of
requests, latency error = -0.966900, overload responses = 0
24-06-2015 12:28:38.560 UTC Status load_monitor.cpp:221: Maximum incoming
request rate/second increased to 168.563904 (based on a smoothed mean latency
of 3310 and 0 upstream overload responses)
24-06-2015 12:28:40.984 UTC Verbose pjsip: tcplis:5054 TCP listener
137.116.157.174:5054: got incoming TCP connection from 137.116.157.174:35221,
sock=437
24-06-2015 12:28:40.985 UTC Verbose pjsip: tcps0x7f8db417 TCP server transport
created
24-06-2015 12:28:40.985 UTC Debug pjsip: sip_endpoint.c Processing incoming
message: Request msg OPTIONS/cseq=3200 (rdata0x7f8db4173170)
24-06-2015 12:28:40.985 UTC Verbose common_sip_processing.cpp:120: RX 358 bytes
Request msg OPTIONS/cseq=3200 (rdata0x7f8db4173170) from TCP
137.116.157.174:35221:
--start msg--
OPTIONS sip:[email protected]:5054 SIP/2.0
Via: SIP/2.0/TCP 137.116.157.174;rport;branch=z9hG4bK-3200
Max-Forwards: 2
To: <sip:[email protected]:5054>
From: poll-sip <sip:[email protected]>;tag=3200
Call-ID: poll-sip-3200
CSeq: 3200 OPTIONS
Contact: <sip:137.116.157.174>
Accept: application/sdp
Content-Length: 0
User-Agent: poll-sip
--end msg--
24-06-2015 12:28:40.985 UTC Debug thread_dispatcher.cpp:236: Queuing cloned
received message 0x7f8db406b688 for worker threads
24-06-2015 12:28:40.985 UTC Debug thread_dispatcher.cpp:149: Worker thread
dequeue message 0x7f8db406b688
24-06-2015 12:28:40.985 UTC Debug pjsip: sip_endpoint.c Distributing rdata to
modules: Request msg OPTIONS/cseq=3200 (rdata0x7f8db406b688)
24-06-2015 12:28:40.985 UTC Debug pjsip: endpoint Response msg
200/OPTIONS/cseq=3200 (tdta0x7f8dd80de600) created
24-06-2015 12:28:40.985 UTC Verbose common_sip_processing.cpp:136: TX 284 bytes
Response msg 200/OPTIONS/cseq=3200 (tdta0x7f8dd80de600) to TCP
137.116.157.174:35221:
--start msg--
SIP/2.0 200 OK
Via: SIP/2.0/TCP
137.116.157.174;rport=35221;received=137.116.157.174;branch=z9hG4bK-3200
Call-ID: poll-sip-3200
From: "poll-sip" <sip:[email protected]>;tag=3200
To: <sip:[email protected]>;tag=z9hG4bK-3200
CSeq: 3200 OPTIONS
Content-Length: 0
--end msg--
24-06-2015 12:28:40.985 UTC Debug pjsip: tdta0x7f8dd80d Destroying txdata
Response msg 200/OPTIONS/cseq=3200 (tdta0x7f8dd80de600)
24-06-2015 12:28:40.985 UTC Debug thread_dispatcher.cpp:176: Worker thread
completed processing message 0x7f8db406b688
24-06-2015 12:28:40.985 UTC Debug thread_dispatcher.cpp:182: Request latency =
173us
24-06-2015 12:28:40.991 UTC Verbose httpstack.cpp:281: Process request for URL
/ping, args (null)
24-06-2015 12:28:40.991 UTC Verbose httpstack.cpp:69: Sending response 200 to
request for URL /ping, args (null)
24-06-2015 12:28:41.988 UTC Verbose pjsip: tcps0x7f8db417 TCP connection closed
24-06-2015 12:28:41.988 UTC Debug connection_tracker.cpp:91: Connection
0x7f8db4172e38 has been destroyed
24-06-2015 12:28:41.988 UTC Verbose pjsip: tcps0x7f8db417 TCP transport
destroyed with reason 70016: End of file (PJ_EEOF)
^Z
[7]+ Stopped tail -f /var/log/sprout/sprout_current.txt
root@ubun3:~# tail -f /var/log/syslog
Jun 24 19:20:01 ubun3 CRON[11106]: (root) CMD (/usr/lib/sysstat/sadc 1 1
/var/log/sysstat/clearwater-sa`date +%d` > /dev/null 2>&1)
Jun 24 19:21:01 ubun3 CRON[11296]: (root) CMD (/usr/lib/sysstat/sadc 1 1
/var/log/sysstat/clearwater-sa`date +%d` > /dev/null 2>&1)
Jun 24 19:22:01 ubun3 CRON[11486]: (root) CMD (/usr/lib/sysstat/sadc 1 1
/var/log/sysstat/clearwater-sa`date +%d` > /dev/null 2>&1)
Jun 24 19:23:01 ubun3 CRON[11675]: (root) CMD (/usr/lib/sysstat/sadc 1 1
/var/log/sysstat/clearwater-sa`date +%d` > /dev/null 2>&1)
Jun 24 19:24:01 ubun3 CRON[11865]: (root) CMD (/usr/lib/sysstat/sadc 1 1
/var/log/sysstat/clearwater-sa`date +%d` > /dev/null 2>&1)
Jun 24 19:25:01 ubun3 CRON[12056]: (root) CMD (command -v debian-sa1 >
/dev/null && debian-sa1 1 1)
Jun 24 19:25:01 ubun3 CRON[12057]: (root) CMD (/usr/lib/sysstat/sadc 1 1
/var/log/sysstat/clearwater-sa`date +%d` > /dev/null 2>&1)
Jun 24 19:26:01 ubun3 CRON[12248]: (root) CMD (/usr/lib/sysstat/sadc 1 1
/var/log/sysstat/clearwater-sa`date +%d` > /dev/null 2>&1)
Jun 24 19:27:01 ubun3 CRON[12438]: (root) CMD (/usr/lib/sysstat/sadc 1 1
/var/log/sysstat/clearwater-sa`date +%d` > /dev/null 2>&1)
Jun 24 19:28:01 ubun3 CRON[12628]: (root) CMD (/usr/lib/sysstat/sadc 1 1
/var/log/sysstat/clearwater-sa`date +%d` > /dev/null 2>&1)
Jun 24 19:28:38 ubun3 sprout[8367]: 1005 - Description:
http://137.116.157.176:8888/impi/7107204018/av?impu=sip%3A7107204018%40example.com
failed to communicate with HTTP server 137.116.157.176 with curl error No
error code 0. @@Cause: An HTTP connection attempt failed to the specified
server with the specified error code. @@Effect: This condition impacts the
ability to register, subscribe, or make a call. @@Action: (1). Check to see if
the specified host has failed. (2). Check to see if there is TCP connectivity
to the host by using ping and/or Wireshark.
^Z
[1]+ Stopped tail -f /var/log/syslog
root@ubun3:/etc/clearwater# Thanks, Tam Vo
_______________________________________________
Clearwater mailing list
[email protected]
http://lists.projectclearwater.org/listinfo/clearwater
