Mailing-List: contact users-help@trafficserver.apache.org; run by ezmlm
Precedence: bulk
Reply-To: users@trafficserver.apache.org
Received-SPF: pass (nike.apache.org: local policy)
From: "LIN, SHU-CHIH" <sl3241@att.com>
To: "'users@trafficserver.apache.org'" <users@trafficserver.apache.org>
Subject: 
 =?Windows-1252?Q?=93CACHE=5FEVENT=5FOPEN=5FREAD=5FFAILED=94_error_when_si?=
 =?Windows-1252?Q?multaneous_requests_needed_revalidation=3F?=
Thread-Topic: 
 =?Windows-1252?Q?=93CACHE=5FEVENT=5FOPEN=5FREAD=5FFAILED=94_error_when_si?=
 =?Windows-1252?Q?multaneous_requests_needed_revalidation=3F?=
Thread-Index: AdBH5dsdL78SKUQ+QICXKmS4XDX6Lw==
Date: Fri, 13 Feb 2015 23:34:14 +0000
Message-ID: 
 <30778D2546DCBC44875BF75DC7C72778153F5B42@MISOUT7MSGUSRCF.ITServices.sbc.com>
Accept-Language: en-US
Content-Language: en-US
Content-Type: text/plain; charset="Windows-1252"
Content-Transfer-Encoding: quoted-printable
MIME-Version: 1.0

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 =93issue=94.....any help/insight y=
ou can share is much appreciated.

Thanks in advance for your help.

Shu-Chih
=3D=3D=3D
Problem statement:
- When multiple requests arrived at the same time for the same object (in h=
ttps and it=92s > 2, in http it=92s > 10) and all had to revalidate,=20
=A0=A0=A0from time to time one/few request would suffered =93CACHE_EVENT_OP=
EN_READ_FAILED=94 error (when debug was on, per code such error=20
=A0=A0=A0meant =93The cache is hosed or full or something=94) which resulte=
d in ATS issuing HTTP GET to origin for the entire object (instead of just
=A0=A0=A0sending IMS/INM as expected)=20
=A0
We tried the following changes yet the issue persisted:
1. =A0Increased #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
=A0
We were able to reproduce the problem with debug on. Sample excerpts from t=
raffic.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 (i=
nstead of IMS/INM)
=A0
.=20
.
+++++++++ 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)
=A0
[Feb 12 15:30:39.798] Server {0x2b4f08d10700} DEBUG: <HttpTransact.cc:2275 =
(issue_revalidate)> (http_seq) [HttpTransact::issue_revalidate] cache actio=
n: 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
=A0
+++++++++ 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_ca=
che_prepare_action)> (http_cache_write) [7950] writing to cache with URL ht=
tp://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 (s=
tate_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_FAILE=
D]
[Feb 12 15:30:39.798] Server {0x2b4f08d10700} DEBUG: <HttpSM.cc:2378 (state=
_cache_open_write)> (http) [7950] [&HttpSM:state_cache_open_write, CACHE_EV=
ENT_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)
=A0
[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_req=
uest_header, VC_EVENT_WRITE_COMPLETE]
.
.