“CACHE_EVENT_OPEN_READ_FAILED” error when simultaneous requests needed revalidation?

["LIN, SHU-CHIH" <sl...@att.com>]

Hi this is Shu-Chih Lin from ATT again. We are testing ATS 5.1.2 on VM for a new use case and noticed the following “issue”.....any help/insight you can share is much appreciated.

Thanks in advance for your help.

Shu-Chih
===
Problem statement:
- When multiple requests arrived at the same time for the same object (in https and it’s > 2, in http it’s > 10) and all had to revalidate, 
   from time to time one/few request would suffered “CACHE_EVENT_OPEN_READ_FAILED” error (when debug was on, per code such error 
   meant “The cache is hosed or full or something”) which resulted in ATS issuing HTTP GET to origin for the entire object (instead of just
   sending IMS/INM as expected) 
 
We tried the following changes yet the issue persisted:
1.  Increased #VM CPU (thus increased #ATS threads under auto-config)
2. Varying object sizes (from 200KB to 300MB)
3. Requests from same vs. different client IPs
 
We were able to reproduce the problem with debug on. Sample excerpts from traffic.out when one such issue was observed:
- looked to us ATS was to revalidate yet before it opened up connection to Origin, the validation to the cached object failed to result in full GET (instead of IMS/INM)
 
. 
.
+++++++++ Proxy's Request +++++++++
-- State Machine Id: 7950
GET /html/image1 HTTP/1.1
User-Agent: curl-996019351
Host: example.com
Accept: */*
Client-ip: 135.182.135.34
X-Forwarded-For: 135.182.135.34
Via: https/1.1 server1[87B68722] (ApacheTrafficServer/5.1.2)
 
[Feb 12 15:30:39.798] Server {0x2b4f08d10700} DEBUG: <HttpTransact.cc:2275 (issue_revalidate)> (http_seq) [HttpTransact::issue_revalidate] cache action: UPDATE
+++++++++ Proxy's Request (Conditionalized) +++++++++
-- State Machine Id: 7950
GET /html/image1 HTTP/1.1
User-Agent: curl-996019351
Host: example.com
Accept: */*
Client-ip: 135.182.135.34
X-Forwarded-For: 135.182.135.34
Via: https/1.1 server1[87B68722] (ApacheTrafficServer/5.1.2)
If-Modified-Since: Tue, 10 Feb 2015 23:43:37 GMT
 
+++++++++ Proxy's Request (Conditionalized) +++++++++
-- State Machine Id: 7950
GET /html/image1 HTTP/1.1
User-Agent: curl-996019351
Host: example.com
Accept: */*
Client-ip: 135.182.135.34
X-Forwarded-For: 135.182.135.34
Via: https/1.1 server1[87B68722] (ApacheTrafficServer/5.1.2)
If-Modified-Since: Tue, 10 Feb 2015 23:43:37 GMT
If-None-Match: "42009d-13cb7350-50ec474b547a4"
.
.
[Feb 12 15:30:39.798] Server {0x2b4f08d10700} DEBUG: <HttpSM.cc:6846 (call_transact_and_set_next_state)> (http) [7950] State Transition: SM_ACTION_API_OS_DNS -> SM_ACTION_CACHE_ISSUE_WRITE
[Feb 12 15:30:39.798] Server {0x2b4f08d10700} DEBUG: <HttpSM.cc:4451 (do_cache_prepare_action)> (http_cache_write) [7950] writing to cache with URL http://example.com/html/image1
[Feb 12 15:30:39.798] Server {0x2b4f08d10700} DEBUG: <P_CacheInternal.h:563 (new_CacheVC)> (cache_new) new 0x2aace805dfa0
[Feb 12 15:30:39.798] Server {0x2b4f08d10700} DEBUG: <Cache.cc:3404 (key_to_vol)> (cache_hosting) Generic volume: 10000b78d for host: example.com
[Feb 12 15:30:39.798] Server {0x2b4f08d10700} DEBUG: <HttpCacheSM.cc:162 (state_cache_open_write)> (http_cache) [7950] [&HttpCacheSM::state_cache_open_write, CACHE_EVENT_OPEN_WRITE_FAILED]
[Feb 12 15:30:39.798] Server {0x2b4f08d10700} DEBUG: <HttpSM.cc:2526 (main_handler)> (http) [7950] [HttpSM::main_handler, CACHE_EVENT_OPEN_WRITE_FAILED]
[Feb 12 15:30:39.798] Server {0x2b4f08d10700} DEBUG: <HttpSM.cc:2378 (state_cache_open_write)> (http) [7950] [&HttpSM:state_cache_open_write, CACHE_EVENT_OPEN_WRITE_FAILED]
[Feb 12 15:30:39.798] Server {0x2b4f08d10700} DEBUG: <HttpTransact.cc:2993 (handle_cache_write_lock)> (http_trans) Next action next; __null
.
.
[Feb 12 15:30:39.799] Server {0x2b4efd51d700} DEBUG: <HttpServerSession.cc:92 (new_connection)> (http_ss) [7747] session born, netvc 0x2aacdc058ad0
+++++++++ Proxy's Request after hooks +++++++++
-- State Machine Id: 7950
GET /html/image1 HTTP/1.1
User-Agent: curl-996019351
Host: example.com
Accept: */*
Client-ip: 135.182.135.34
X-Forwarded-For: 135.182.135.34
Via: https/1.1 server1[87B68722] (ApacheTrafficServer/5.1.2)
 
[Feb 12 15:30:39.799] Server {0x2b4efd51d700} DEBUG: <HttpSM.cc:2526 (main_handler)> (http) [7950] [HttpSM::main_handler, VC_EVENT_WRITE_COMPLETE]
[Feb 12 15:30:39.799] Server {0x2b4efd51d700} DEBUG: <HttpSM.cc:1873 (state_send_server_request_header)> (http) [7950] [&HttpSM::state_send_server_request_header, VC_EVENT_WRITE_COMPLETE]
.
.