Hi Schahzad, What version of Ralf are you running?
Also, what level of requests are you generating? You're getting back a 503 from Ralf, which suggests that Ralf itself is overloaded and is rejecting requests. On Ralf, if you go from a cold start to a high load, Ralf will take a short time to adjust to the new load level, and will reject some requests while doing so. If this is the case, can you try ramping up the load more slowly, or give Ralf a short while to adjust to the new load level? If this isn't the case, then I'd like to see more diagnostics. Can you please run "/usr/share/clearwater/bin/gather_diags" on your Sprout and Ralf nodes and send me the resulting files (called "<datestamp>.gather_diags.tar.gz") in "/var/clearwater-diags-monitor/dumps/"? Thanks, Ellie -----Original Message----- From: [email protected] [mailto:[email protected]] On Behalf Of Schahzad Zafar Sent: 28 May 2014 15:00 To: [email protected] Subject: [Clearwater] Sprout http fails to Ralf Dear Team, i am getting Ralf huges logs like a loop and upon investigation i found Sprout tries to send HTTP calls to Ralf which work one or two time and then later on Sprout send HTTP request to ralf and get some error, on the other hand its seems Ralf keep sending response to sprout doesnt show any special error or atleast it looks like to me, it would be nice if some one can guide me urgently as i am in middle of testing to our billing team 28-05-2014 13:44:53.855 Debug pjutils.cpp:489: Next hop node is encoded in top route header 28-05-2014 13:44:53.855 Debug sipresolver.cpp:85: SIPResolver::resolve for name sprout.ef.net, port 5052, transport -1, family 2 28-05-2014 13:44:53.855 Debug baseresolver.cpp:480: Attempt to parse sprout.ef.net as IP address 28-05-2014 13:44:53.855 Debug sipresolver.cpp:127: Port is specified 28-05-2014 13:44:53.855 Debug sipresolver.cpp:295: Perform A/AAAA record lookup only, name = sprout.ef.net 28-05-2014 13:44:53.855 Debug dnscachedresolver.cpp:551: Removing record for sprout.ef.net (type 1, expiry time 1401284692) from the expiry list 28-05-2014 13:44:53.855 Debug dnscachedresolver.cpp:562: Expiring record for sprout.ef.net (type 1) from the DNS cache 28-05-2014 13:44:53.856 Debug dnscachedresolver.cpp:136: Create cache entry pending query 28-05-2014 13:44:53.852 Debug pjutils.cpp:489: Next hop node is encoded in top route header 28-05-2014 13:44:53.856 Debug sipresolver.cpp:85: SIPResolver::resolve for name sprout.ef.net, port 5052, transport -1, family 2 28-05-2014 13:44:53.857 Debug baseresolver.cpp:480: Attempt to parse sprout.ef.net as IP address 28-05-2014 13:44:53.857 Debug sipresolver.cpp:127: Port is specified 28-05-2014 13:44:53.857 Debug sipresolver.cpp:295: Perform A/AAAA record lookup only, name = sprout.ef.net 28-05-2014 13:44:53.858 Debug dnscachedresolver.cpp:148: Create and execute DNS query transaction 28-05-2014 13:44:53.859 Debug dnscachedresolver.cpp:154: Wait for query responses 28-05-2014 13:44:53.859 Debug httpconnection.cpp:482: Received HTTP error response : http://ralf.ef.net:10888/call-id/ZmRlNTEwNjg3YTkwMmQ2YmMzMDYzNTFlMTg3ZTdkNjk. : HTTP response code said error 28-05-2014 13:44:53.859 Error httpconnection.cpp:523: http://ralf.ef.net:10888/call-id/ZmRlNTEwNjg3YTkwMmQ2YmMzMDYzNTFlMTg3ZTdkNjk. failed at server 192.168.20.114 : HTTP response code said error (22 503) : retrying 28-05-2014 13:44:53.859 Debug httpconnection.cpp:456: Sending HTTP request : http://ralf.ef.net:10888/call-id/ZmRlNTEwNjg3YTkwMmQ2YmMzMDYzNTFlMTg3ZTdkNjk. (try 1) on new connection .... 28-05-2014 13:44:53.873 Debug httpconnection.cpp:482: Received HTTP error response : http://ralf.ef.net:10888/call-id/ZmRlNTEwNjg3YTkwMmQ2YmMzMDYzNTFlMTg3ZTdkNjk. : HTTP response code said error 28-05-2014 13:44:53.874 Error httpconnection.cpp:536: http://ralf.ef.net:10888/call-id/ZmRlNTEwNjg3YTkwMmQ2YmMzMDYzNTFlMTg3ZTdkNjk. failed at server 192.168.20.114 : HTTP response code said error (22 503) : fatal 28-05-2014 13:44:53.874 Error httpconnection.cpp:574: cURL failure with cURL error code 22 (see man 3 libcurl-errors) and HTTP error code 503 28-05-2014 13:44:53.874 Warning acr.cpp:612: Failed to send Ralf ACR message (0x7f7edc037ec0), rc = 503 28-05-2014 13:44:53.874 Debug acr.cpp:53: Destroyed ACR (0x7f7edc037ec0) 28-05-2014 13:44:53.874 Debug basicproxy.cpp:427: BasicProxy::UASTsx destructor (0x7f7edc387e80) 28-05-2014 13:44:53.874 Debug basicproxy.cpp:442: Disconnect UAC transactions from UAS transaction 28-05-2014 13:44:53.875 Debug basicproxy.cpp:456: Free original request 28-05-2014 13:44:53.875 Debug pjsip: tdta0x7f7edc58 Destroying txdata Request msg INVITE/cseq=1 (tdta0x7f7edc58e5b0) 28-05-2014 13:44:53.875 Debug basicproxy.cpp:486: BasicProxy::UASTsx destructor completed 28-05-2014 13:44:53.875 Debug pjsip: tdta0x2296740 Destroying txdata Response msg 200/INVITE/cseq=1 (tdta0x2296740) 28-05-2014 13:44:53.875 Debug pjsip: tsx0x7f7edc5e4 Timeout timer event 28-05-2014 13:44:53.875 Debug pjsip: tsx0x7f7edc5e4 State changed from Terminated to Destroyed, event=TIMER 28-05-2014 13:44:53.876 Debug basicproxy.cpp:212: tsx0x7f7edc5e4998 - tu_on_tsx_state UAC, TSX_STATE TIMER state=Destroyed 28-05-2014 13:44:53.876 Debug basicproxy.cpp:1710: tsx0x7f7edc5e4998 - uac_tsx = 0x7f7edc625f00, uas_tsx = (nil) 28-05-2014 13:44:53.876 Debug basicproxy.cpp:1777: tsx0x7f7edc5e4998 - UAC tsx destroyed 28-05-2014 13:44:53.876 Debug basicproxy.cpp:1445: BasicProxy::UACTsx destructor (0x7f7edc625f00) 28-05-2014 13:44:53.876 Debug pjsip: tdta0x7f7edc5e Destroying txdata Request msg INVITE/cseq=1 (tdta0x7f7edc5e0450) ... ... ... SIP/2.0 200 OK^M Via: SIP/2.0/TCP 192.168.9.97:43927 ;rport=43927;received=192.168.9.97;branch=z9hG4bKPjluGlETs04-RwsZL7lpSILLZrqy92v78R^M Via: SIP/2.0/TCP 192.168.9.96:44653 ;rport=44653;received=192.168.9.96;branch=z9hG4bKPjNC7s5bW3YEgrVhnoSOD9vBrI6uLSI5d4^M Via: SIP/2.0/UDP 192.168.18.102:57561 ;rport=57561;received=192.168.18.102;branch=z9hG4bK-d8754z-854d3b1467ddfad7-1---d8754z-^M Record-Route: <sip:[email protected]:5060;transport=UDP;lr>^M Record-Route: <sip:192.168.9.96:5058;transport=TCP;lr>^M Record-Route: <sip:sprout.ef.net:5054;transport=TCP;lr>^M Record-Route: <sip:192.168.9.96:5058;transport=TCP;lr>^M Record-Route: <sip:[email protected]:5060;transport=UDP;lr>^M Require: timer^M Contact: <sip:[email protected]:62706 ;transport=UDP;rinstance=9a4514681c6d1a06>^M To: <sip:[email protected]>;tag=1778425d^M From: <sip:[email protected]>;tag=cb958a5f^M Call-ID: ZmRlNTEwNjg3YTkwMmQ2YmMzMDYzNTFlMTg3ZTdkNjk.^M CSeq: 1 INVITE^M Session-Expires: 600;refresher=uac^M Min-SE: 90^M Allow: INVITE, ACK, CANCEL, BYE, NOTIFY, REFER, MESSAGE, OPTIONS, INFO, SUBSCRIBE^M .... .... .... 28-05-2014 13:44:53.905 Debug acr.cpp:986: Adding Route-Header-Received AVP 28-05-2014 13:44:53.905 Debug acr.cpp:991: Adding Route-Header-Transmitted AVP 28-05-2014 13:44:53.906 Debug httpconnection.cpp:456: Sending HTTP request : http://ralf.ef.net:10888/call-id/ZmRlNTEwNjg3YTkwMmQ2YmMzMDYzNTFlMTg3ZTdkNjk. (try 0) 28-05-2014 13:44:53.918 Debug httpconnection.cpp:482: Received HTTP error response : http://ralf.ef.net:10888/call-id/NjUwNjFkYzc0ZjkzZmJjNDU1MjY4OTZkMTNlOWQ4M2M. : HTTP response code said error 28-05-2014 13:44:53.918 Error httpconnection.cpp:536: http://ralf.ef.net:10888/call-id/NjUwNjFkYzc0ZjkzZmJjNDU1MjY4OTZkMTNlOWQ4M2M. failed at server 192.168.20.114 : HTTP response code said error (22 503) : fatal 28-05-2014 13:44:53.918 Debug statistic.cpp:103: Send new value for statistic connected_ralfs, size 2 28-05-2014 13:44:53.918 Debug zmq_lvc.cpp:167: Update to connected_ralfs statistic 28-05-2014 13:44:53.918 Debug zmq_lvc.cpp:250: Clearing message cache for 0x7f7f18041210 28-05-2014 13:44:53.918 Error httpconnection.cpp:574: cURL failure with cURL error code 22 (see man 3 libcurl-errors) and HTTP error code 503 28-05-2014 13:44:53.918 Warning acr.cpp:612: Failed to send Ralf ACR message (0x7f7f100be500), rc = 503 28-05-2014 13:44:53.919 Debug icscfproxy.cpp:340: Route Non-REGISTER to S-CSCF sip:192.168.9.97:5054 28-05-2014 13:44:53.919 Debug basicproxy.cpp:870: Allocating transaction and data for target 0 28-05-2014 13:44:53.919 Debug pjsip: tsx0x7f7f10296 Transaction created for Request msg SUBSCRIBE/cseq=1 (tdta0x7f7f1028cd50) 28-05-2014 13:44:53.919 Debug basicproxy.cpp:1506: Added trail identifier 252 to UAC transaction 28-05-2014 13:44:53.919 Debug basicproxy.cpp:1517: Set target for UAC transaction 28-05-2014 13:44:53.919 Debug basicproxy.cpp:1539: Adding a Route header to sip:192.168.9.97 On the other hand in Ralf keep running into 28-05-2014 13:45:02.321 Verbose httpstack.cpp:238: Handling request for URL /call-id/ZmRlNTEwNjg3YTkwMmQ2YmMzMDYzNTFlMTg3ZTdkNjk., args timer-interim=true 28-05-2014 13:45:02.321 Debug freeDiameter: Peer timeout reset to 30 seconds (+/- 2) 28-05-2014 13:45:02.321 Debug handlers.cpp:120: Handling request, body: { "event": { "Service-Information": { "IMS-Information": { "Role-Of-Node": 1, "Node-Functionality": 1 } }, "Accounting-Record-Type": 3 } } 28-05-2014 13:45:02.321 Verbose httpstack.cpp:66: Sending response 200 to request for URL /call-id/ZmRlNTEwNjg3YTkwMmQ2YmMzMDYzNTFlMTg3ZTdkNjk., args timer-interim=true 28-05-2014 13:45:02.321 Debug freeDiameter: '192.168.20.115' in state 'STATE_OPEN' waiting for next event. 28-05-2014 13:45:02.321 Debug sessionstore.cpp:58: Retrieving session data for ZmRlNTEwNjg3YTkwMmQ2YmMzMDYzNTFlMTg3ZTdkNjk.11 28-05-2014 13:45:02.321 Debug memcachedstore.cpp:260: Key session\\ZmRlNTEwNjg3YTkwMmQ2YmMzMDYzNTFlMTg3ZTdkNjk.11 hashes to vbucket 64 via hash 0x569ed840 28-05-2014 13:45:02.321 Debug memcachedstore.cpp:304: 1 read replicas for key session\\ZmRlNTEwNjg3YTkwMmQ2YmMzMDYzNTFlMTg3ZTdkNjk.11 28-05-2014 13:45:02.321 Debug memcachedstore.cpp:337: Attempt to read from replica 0 (connection 0x7fb48801ea00) 28-05-2014 13:45:02.321 Debug memcachedstore.cpp:343: Fetch result 28-05-2014 13:45:02.322 Debug memcachedstore.cpp:351: Found record on replica 0 28-05-2014 13:45:02.322 Debug memcachedstore.cpp:400: Read 86 bytes from table session key ZmRlNTEwNjg3YTkwMmQ2YmMzMDYzNTFlMTg3ZTdkNjk.11, CAS = 3668534 28-05-2014 13:45:02.322 Debug sessionstore.cpp:69: Retrieved record, CAS = 3668534 28-05-2014 13:45:02.322 Debug sessionstore.cpp:82: Saving session data for ZmRlNTEwNjg3YTkwMmQ2YmMzMDYzNTFlMTg3ZTdkNjk.11, CAS = 3668534 28-05-2014 13:45:02.322 Debug memcachedstore.cpp:449: Writing 86 bytes to table session key ZmRlNTEwNjg3YTkwMmQ2YmMzMDYzNTFlMTg3ZTdkNjk.11, CAS = 3668534, expiry = 600 28-05-2014 13:45:02.322 Debug memcachedstore.cpp:260: Key session\\ZmRlNTEwNjg3YTkwMmQ2YmMzMDYzNTFlMTg3ZTdkNjk.11 hashes to vbucket 64 via hash 0x569ed840 28-05-2014 13:45:02.322 Debug memcachedstore.cpp:468: 1 write replicas for key session\\ZmRlNTEwNjg3YTkwMmQ2YmMzMDYzNTFlMTg3ZTdkNjk.11 28-05-2014 13:45:02.322 Debug memcachedstore.cpp:506: Attempt conditional write to replica 0 (connection 0x7fb48801ea00), CAS = 3668534 28-05-2014 13:45:02.322 Debug memcachedstore.cpp:537: Conditional write succeeded to replica 0 28-05-2014 13:45:02.322 Debug sessionstore.cpp:92: Store returned 1 28-05-2014 13:45:02.322 Debug peer_message_sender.cpp:84: Sending message to hss.ef.net (number 0) 28-05-2014 13:45:02.322 Debug rf.cpp:62: Building an Accounting-Request 28-05-2014 13:45:02.322 Verbose diameterstack.cpp:989: Sending Diameter message of type 271 on transaction 0x7fb48800f490 28-05-2014 13:45:02.322 Debug freeDiameter: Sending 208b data on connection {----} TCP,#619->192.168.20.115(3868) 28-05-2014 13:45:02.322 Debug freeDiameter: 'STATE_OPEN' <-- 'FDEVP_CNX_MSG_RECV' (0x7fb49801e860,128) '192.168.20.115' 28-05-2014 13:45:02.322 Debug freeDiameter: Peer timeout reset to 30 seconds (+/- 2) 28-05-2014 13:45:02.322 Debug freeDiameter: '192.168.20.115' in state 'STATE_OPEN' waiting for next event. 28-05-2014 13:45:02.322 Debug freeDiameter: Iterating on rules of COMMAND: 'Accounting-Answer'. 28-05-2014 13:45:02.322 Debug freeDiameter: Calling callback registered when query was sent (0x424430, 0x7fb48800f1c0) 28-05-2014 13:45:02.322 Verbose diameterstack.cpp:721: Got Diameter response of type 271 - calling callback on transaction 0x7fb48800f1c0 28-05-2014 13:45:02.322 Verbose httpstack.cpp:238: Handling request for URL /call-id/ZmRlNTEwNjg3YTkwMmQ2YmMzMDYzNTFlMTg3ZTdkNjk., args timer-interim=true 28-05-2014 13:45:02.322 Debug handlers.cpp:120: Handling request, body: { "event": { "Service-Information": { "IMS-Information": { "Role-Of-Node": 1, "Node-Functionality": 0 } }, "Accounting-Record-Type": 3 } } 28-05-2014 13:45:02.322 Verbose httpstack.cpp:66: Sending response 200 to request for URL /call-id/ZmRlNTEwNjg3YTkwMmQ2YmMzMDYzNTFlMTg3ZTdkNjk., args timer-interim=true 28-05-2014 13:45:02.322 Debug sessionstore.cpp:58: Retrieving session data for ZmRlNTEwNjg3YTkwMmQ2YmMzMDYzNTFlMTg3ZTdkNjk.10 28-05-2014 13:45:02.322 Debug memcachedstore.cpp:260: Key session\\ZmRlNTEwNjg3YTkwMmQ2YmMzMDYzNTFlMTg3ZTdkNjk.10 hashes to vbucket 11 via hash 0xf5b9e88b 28-05-2014 13:45:02.322 Debug memcachedstore.cpp:304: 1 read replicas for key session\\ZmRlNTEwNjg3YTkwMmQ2YmMzMDYzNTFlMTg3ZTdkNjk.10 28-05-2014 13:45:02.322 Debug memcachedstore.cpp:337: Attempt to read from replica 0 (connection 0x7fb48801ea00) 28-05-2014 13:45:02.322 Debug memcachedstore.cpp:343: Fetch result 28-05-2014 13:45:02.322 Debug memcachedstore.cpp:351: Found record on replica 0 28-05-2014 13:45:02.322 Debug memcachedstore.cpp:400: Read 86 bytes from table session key ZmRlNTEwNjg3YTkwMmQ2YmMzMDYzNTFlMTg3ZTdkNjk.10, CAS = 3668535 28-05-2014 13:45:02.322 Debug sessionstore.cpp:69: Retrieved record, CAS = 3668535 28-05-2014 13:45:02.322 Debug sessionstore.cpp:82: Saving session data for ZmRlNTEwNjg3YTkwMmQ2YmMzMDYzNTFlMTg3ZTdkNjk.10, CAS = 3668535 28-05-2014 13:45:02.322 Debug memcachedstore.cpp:449: Writing 86 bytes to table session key ZmRlNTEwNjg3YTkwMmQ2YmMzMDYzNTFlMTg3ZTdkNjk.10, CAS = 3668535, expiry = 600 28-05-2014 13:45:02.322 Debug memcachedstore.cpp:260: Key session\\ZmRlNTEwNjg3YTkwMmQ2YmMzMDYzNTFlMTg3ZTdkNjk.10 hashes to vbucket 11 via hash 0xf5b9e88b 28-05-2014 13:45:02.322 Debug memcachedstore.cpp:468: 1 write replicas for key session\\ZmRlNTEwNjg3YTkwMmQ2YmMzMDYzNTFlMTg3ZTdkNjk.10 28-05-2014 13:45:02.322 Debug memcachedstore.cpp:506: Attempt conditional write to replica 0 (connection 0x7fb48801ea00), CAS = 3668535 28-05-2014 13:45:02.323 Debug memcachedstore.cpp:537: Conditional write succeeded to replica 0 28-05-2014 13:45:02.323 Debug sessionstore.cpp:92: Store returned 1 28-05-2014 13:45:02.323 Debug peer_message_sender.cpp:84: Sending message to hss.ef.net (number 0) 28-05-2014 13:45:02.323 Debug rf.cpp:62: Building an Accounting-Request 28-05-2014 13:45:02.323 Verbose diameterstack.cpp:989: Sending Diameter message of type 271 on transaction 0x7fb48801e790 28-05-2014 13:45:02.323 Debug freeDiameter: Sending 208b data on connection {----} TCP,#619->192.168.20.115(3868) 28-05-2014 13:45:02.323 Debug freeDiameter: 'STATE_OPEN' <-- 'FDEVP_CNX_MSG_RECV' (0x7fb49801e860,128) '192.168.20.115' 28-05-2014 13:45:02.323 Debug freeDiameter: Peer timeout reset to 30 seconds (+/- 2) 28-05-2014 13:45:02.323 Debug freeDiameter: '192.168.20.115' in state 'STATE_OPEN' waiting for next event. 28-05-2014 13:45:02.323 Debug freeDiameter: Iterating on rules of COMMAND: 'Accounting-Answer'. 28-05-2014 13:45:02.323 Debug freeDiameter: Calling callback registered when query was sent (0x424430, 0x7fb48800f490) 28-05-2014 13:45:02.323 Verbose diameterstack.cpp:721: Got Diameter response of type 271 - calling callback on transaction 0x7fb48800f490 28-05-2014 13:45:02.323 Verbose httpstack.cpp:238: Handling request for URL /call-id/ZmRlNTEwNjg3YTkwMmQ2YmMzMDYzNTFlMTg3ZTdkNjk., args timer-interim=true 28-05-2014 13:45:02.323 Debug handlers.cpp:120: Handling request, body: { "event": { "Service-Information": { "IMS-Information": { "Role-Of-Node": 1, "Node-Functionality": 1 } }, "Accounting-Record-Type": 3 } } 28-05-2014 13:45:02.323 Verbose httpstack.cpp:66: Sending response 200 to request for URL /call-id/ZmRlNTEwNjg3YTkwMmQ2YmMzMDYzNTFlMTg3ZTdkNjk., args timer-interim=true 28-05-2014 13:45:02.323 Debug sessionstore.cpp:58: Retrieving session data for ZmRlNTEwNjg3YTkwMmQ2YmMzMDYzNTFlMTg3ZTdkNjk.11 28-05-2014 13:45:02.323 Debug memcachedstore.cpp:260: Key session\\ZmRlNTEwNjg3YTkwMmQ2YmMzMDYzNTFlMTg3ZTdkNjk.11 hashes to vbucket 64 via hash 0x569ed840 -- Best Regards Schahzad Z. Choudhry 0092 - 321 -9001131 _______________________________________________ Clearwater mailing list [email protected] http://lists.projectclearwater.org/listinfo/clearwater _______________________________________________ Clearwater mailing list [email protected] http://lists.projectclearwater.org/listinfo/clearwater
