Hi,
I have written a plugin that scans data using transformations. It all works
fine until caching is enabled. I have found two problems and I have supplied
modified bnull_transform code to demonstrate them. The only changes I have
made to the code are: basic logging, adding hooks for READ_CACHE_HDR_HOOK
and reading the cache headers instead of the server headers
where appropriate.
The problems are:
1. It seems that when data is transformed from the cache that another
duplicate copy of it is written to the cache. To re-create this I use an
Apache server with the expires module enabled and then:
a. stop Traffic Server
b. clear the cache - traffic_server --Cclear
c. restart Traffic Server - running the modified bnull plugin
d. wget a 1MB file through the proxy - bnull logging shows that this comes
from the server
e. wait a while then use 'traffic_line -r proxy.process.cache_bytes_used' to
see that 1081344 bytes have been stored in the cache
f. perform exactly the same wget again - bnull logging shows that this comes
from the cache
g. use 'traffic_line -r proxy.process.cache_bytes_used' to see that 2162688
bytes have been stored in the cache - exactly double
h. keep using wget and 1081344 bytes keeps on being added to the cache
I have got around this in my own plugin by not writing to the OutputVConn
connection when the headers have come from the cache. I do not know whether
this is the best solution though.
2. This problem is a bit more complicated. It seems that sometimes if a
client sends a request with a 'if-modified-since' header to Traffic Server
with caching enabled but the response does not come from the cache then the
created transformation is not called so I cannot scan the data. The modified
bnull plugin shows this - in this case the cache header code path is never
used because the headers always come from the server. I have done some
network traces which I have attached which show the problem. To test this I
use a Eurogamer site URL where the response has been cached in the browser
causing it to add a 'if-modified-since' header to subsequent requests. The
URL I use is: http://www.eurogamer.net/styles/Autocomplete.css?v10.20-21670.
Normally this occurs (the 200sentback.cap shows this):
a. Go to the URL so that the response is stored in the browser cache.
b. Restart the browser.
c. Enter the URL again - browser sends request with 'if-modified-since'
header - this is shown in the capture.
d. The capture shows the request being sent to the server with
the 'if-modified-since' header stripped.
e. The server returns 200.
f. The proxy returns 200 and the transformation fires as normal - the
logging shows this:
20110909.17h38m12s transform_plugin - from server
20110909.17h38m12s transformable 1
20110909.17h38m12s bnull_transform 1
20110909.17h38m12s handle_transform
20110909.17h38m12s bnull_transform 1
20110909.17h38m12s handle_transform
20110909.17h38m12s bnull_transform 103
20110909.17h38m12s bnull_transform 1
When the problem occurs (the 304sentback.cap shows this):
a. Go to the URL so that the response is stored in the browser cache.
b. Restart the browser.
c. Enter the URL again - browser sends request with 'if-modified-since'
header - this is shown in the capture.
d. The capture shows the request being sent to the server with
the 'if-modified-since' header stripped.
e. The server returns 200.
f. The proxy returns 304 and closes the connection to the server. When this
occurs the transaction is closed down and the transformation is never
called. The logging shows this:
20110909.17h39m28s transform_plugin - from server
20110909.17h39m28s transformable 1
20110909.17h39m28s bnull_transform 1
As the logging shows 'handle_transform' is never called.
Note that it can take a number of attempts to re-create the problem. I used
Firefox and opened a new tab for each attempt.
Its odd that for 90% of the requests Traffic Server returns a 200 response
but for the rest (which are identical) it returns a 304. I guess that the
304 is causing the transformation not to fire because it thinks there is no
data. I cannot think of a workaround to get past this issue.
Can anyone shine any light on this?
Cheers,
Chris Reynolds.
/** @file
A brief file description
@section license License
Licensed to the Apache Software Foundation (ASF) under one
or more contributor license agreements. See the NOTICE file
distributed with this work for additional information
regarding copyright ownership. The ASF licenses this file
to you under the Apache License, Version 2.0 (the
"License"); you may not use this file except in compliance
with the License. You may obtain a copy of the License at
http://www.apache.org/licenses/LICENSE-2.0
Unless required by applicable law or agreed to in writing, software
distributed under the License is distributed on an "AS IS" BASIS,
WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied.
See the License for the specific language governing permissions and
limitations under the License.
*/
/* bnull-transform.c: an example program that illustrates a buffered
* null transform.
*
*
*
* Usage:
* (NT): BNullTransform.dll
* (Solaris): bnull-transform.so
*
*
*/
/* set tab stops to four. */
#include <stdio.h>
#include <ts/ts.h>
#include <stdarg.h>
#define TS_NULL_MUTEX NULL
#define STATE_BUFFER_DATA 0
#define STATE_OUTPUT_DATA 1
typedef struct
{
int state;
TSVIO output_vio;
TSIOBuffer output_buffer;
TSIOBufferReader output_reader;
} MyData;
int mPerformLogging = 1;
TSTextLogObject gLog_p;
#define LOG_LINE_MAX_SIZE 1024
//-------------------------------------------------------------------[log]-
/** Logs to the log file
*
* @param formatString_p IN Format string
* @param ... IN Format parameters
**/
//-------------------------------------------------------------------------
void dolog (const char* formatString_p, ...)
{
if (mPerformLogging)
{
va_list args;
char buf_p[LOG_LINE_MAX_SIZE];
va_start (args, formatString_p);
vsnprintf (buf_p, LOG_LINE_MAX_SIZE, formatString_p, args);
va_end (args);
TSTextLogObjectWrite (gLog_p, buf_p);
TSTextLogObjectFlush (gLog_p);
}
}
static MyData *
my_data_alloc()
{
MyData *data;
data = (MyData *) TSmalloc(sizeof(MyData));
data->state = STATE_BUFFER_DATA;
data->output_vio = NULL;
data->output_buffer = NULL;
data->output_reader = NULL;
return data;
}
static void
my_data_destroy(MyData * data)
{
if (data) {
if (data->output_buffer) {
TSIOBufferDestroy(data->output_buffer);
}
TSfree(data);
}
}
static int
handle_buffering(TSCont contp, MyData * data)
{
TSVIO write_vio;
int towrite;
int avail;
/* Get the write VIO for the write operation that was performed on
ourself. This VIO contains the buffer that we are to read from
as well as the continuation we are to call when the buffer is
empty. */
write_vio = TSVConnWriteVIOGet(contp);
/* Create the output buffer and its associated reader */
if (!data->output_buffer) {
data->output_buffer = TSIOBufferCreate();
TSAssert(data->output_buffer);
data->output_reader = TSIOBufferReaderAlloc(data->output_buffer);
TSAssert(data->output_reader);
}
/* We also check to see if the write VIO's buffer is non-NULL. A
NULL buffer indicates that the write operation has been
shutdown and that the continuation does not want us to send any
more WRITE_READY or WRITE_COMPLETE events. For this buffered
transformation that means we're done buffering data. */
if (!TSVIOBufferGet(write_vio)) {
data->state = STATE_OUTPUT_DATA;
return 0;
}
/* Determine how much data we have left to read. For this bnull
transform plugin this is also the amount of data we have left
to write to the output connection. */
towrite = TSVIONTodoGet(write_vio);
if (towrite > 0) {
/* The amount of data left to read needs to be truncated by
the amount of data actually in the read buffer. */
avail = TSIOBufferReaderAvail(TSVIOReaderGet(write_vio));
if (towrite > avail) {
towrite = avail;
}
if (towrite > 0) {
/* Copy the data from the read buffer to the input buffer. */
TSIOBufferCopy(data->output_buffer, TSVIOReaderGet(write_vio), towrite, 0);
/* Tell the read buffer that we have read the data and are no
longer interested in it. */
TSIOBufferReaderConsume(TSVIOReaderGet(write_vio), towrite);
/* Modify the write VIO to reflect how much data we've
completed. */
TSVIONDoneSet(write_vio, TSVIONDoneGet(write_vio) + towrite);
}
}
/* Now we check the write VIO to see if there is data left to read. */
if (TSVIONTodoGet(write_vio) > 0) {
if (towrite > 0) {
/* Call back the write VIO continuation to let it know that we
are ready for more data. */
TSContCall(TSVIOContGet(write_vio), TS_EVENT_VCONN_WRITE_READY, write_vio);
}
} else {
data->state = STATE_OUTPUT_DATA;
/* Call back the write VIO continuation to let it know that we
have completed the write operation. */
TSContCall(TSVIOContGet(write_vio), TS_EVENT_VCONN_WRITE_COMPLETE, write_vio);
}
return 1;
/* If we are in this code path then something is seriously wrong. */
TSError("[bnull-transform] Fatal error in plugin");
TSReleaseAssert(!"[bnull-transform] Fatal error in plugin\n");
return 0;
}
static int
handle_output(TSCont contp, MyData * data)
{
/* Check to see if we need to initiate the output operation. */
if (!data->output_vio) {
TSVConn output_conn;
/* Get the output connection where we'll write data to. */
output_conn = TSTransformOutputVConnGet(contp);
data->output_vio =
TSVConnWrite(output_conn, contp, data->output_reader, TSIOBufferReaderAvail(data->output_reader));
TSAssert(data->output_vio);
}
return 1;
}
static void
handle_transform(TSCont contp)
{
dolog ("handle_transform");
MyData *data;
int done;
/* Get our data structure for this operation. The private data
structure contains the output VIO and output buffer. If the
private data structure pointer is NULL, then we'll create it
and initialize its internals. */
data = TSContDataGet(contp);
if (!data) {
data = my_data_alloc();
TSContDataSet(contp, data);
}
do {
switch (data->state) {
case STATE_BUFFER_DATA:
done = handle_buffering(contp, data);
break;
case STATE_OUTPUT_DATA:
done = handle_output(contp, data);
break;
default:
done = 1;
break;
}
} while (!done);
}
static int
bnull_transform(TSCont contp, TSEvent event, void *edata)
{
dolog ("bnull_transform %d", event);
/* Check to see if the transformation has been closed by a
call to TSVConnClose. */
if (TSVConnClosedGet(contp)) {
my_data_destroy(TSContDataGet(contp));
TSContDestroy(contp);
} else {
switch (event) {
case TS_EVENT_ERROR:{
TSVIO write_vio;
/* Get the write VIO for the write operation that was
performed on ourself. This VIO contains the continuation of
our parent transformation. */
write_vio = TSVConnWriteVIOGet(contp);
/* Call back the write VIO continuation to let it know that we
have completed the write operation. */
TSContCall(TSVIOContGet(write_vio), TS_EVENT_ERROR, write_vio);
break;
}
case TS_EVENT_VCONN_WRITE_COMPLETE:
/* When our output connection says that it has finished
reading all the data we've written to it then we should
shutdown the write portion of its connection to
indicate that we don't want to hear about it anymore. */
TSVConnShutdown(TSTransformOutputVConnGet(contp), 0, 1);
break;
case TS_EVENT_VCONN_WRITE_READY:
default:
/* If we get a WRITE_READY event or any other type of event
(sent, perhaps, because we were reenabled) then we'll attempt
to transform more data. */
handle_transform(contp);
break;
}
}
return 0;
}
static int
transformable(TSHttpTxn txnp, int fromCache)
{
TSMBuffer bufp;
TSMLoc hdr_loc;
TSHttpStatus resp_status;
int retv;
if (fromCache)
{
TSHttpTxnCachedRespGet (txnp, &bufp, &hdr_loc);
}
else
{
TSHttpTxnServerRespGet (txnp, &bufp, &hdr_loc);
}
/* We are only interested in transforming "200 OK" responses. */
//TSHttpTxnServerRespGet(txnp, &bufp, &hdr_loc);
resp_status = TSHttpHdrStatusGet(bufp, hdr_loc);
retv = (resp_status == TS_HTTP_STATUS_OK);
if (TSHandleMLocRelease(bufp, TS_NULL_MLOC, hdr_loc) == TS_ERROR) {
TSError("[bnull-transform] Error releasing MLOC while checking " "header status\n");
}
dolog ("transformable %d", retv);
return retv;
}
static void
transform_add(TSHttpTxn txnp)
{
TSVConn connp;
connp = TSTransformCreate(bnull_transform, txnp);
TSHttpTxnHookAdd(txnp, TS_HTTP_RESPONSE_TRANSFORM_HOOK, connp);
return;
}
static int
transform_plugin(TSCont contp, TSEvent event, void *edata)
{
TSHttpTxn txnp = (TSHttpTxn) edata;
switch (event) {
case TS_EVENT_HTTP_READ_RESPONSE_HDR:
dolog ("transform_plugin - from server", event);
if (transformable(txnp, 0)) {
transform_add(txnp);
}
TSHttpTxnReenable(txnp, TS_EVENT_HTTP_CONTINUE);
return 0;
case TS_EVENT_HTTP_READ_CACHE_HDR:
dolog ("transform_plugin - from cache", event);
if (transformable(txnp, 1)) {
transform_add(txnp);
}
TSHttpTxnReenable(txnp, TS_EVENT_HTTP_CONTINUE);
return 0;
default:
break;
}
return 0;
}
int
check_ts_version()
{
const char *ts_version = TSTrafficServerVersionGet();
int result = 0;
if (ts_version) {
int major_ts_version = 0;
int minor_ts_version = 0;
int patch_ts_version = 0;
if (sscanf(ts_version, "%d.%d.%d", &major_ts_version, &minor_ts_version, &patch_ts_version) != 3) {
return 0;
}
/* Need at least TS 2.0 */
if (major_ts_version >= 2) {
result = 1;
}
}
return result;
}
void
TSPluginInit(int argc, const char *argv[])
{
TSPluginRegistrationInfo info;
TSMutex mutex = TS_NULL_MUTEX;
info.plugin_name = "buffered-null-transform";
info.vendor_name = "MyCompany";
info.support_email = "ts-api-supp...@mycompany.com";
if (TSPluginRegister(TS_SDK_VERSION_3_0, &info) != TS_SUCCESS) {
TSError("[bnull-transform] Plugin registration failed.\n");
goto Lerror;
}
if (!check_ts_version()) {
TSError("[bnull-transform] Plugin requires Traffic Server 3.0" " or later\n");
goto Lerror;
}
TSTextLogObjectCreate ("bnull.log", TS_LOG_MODE_ADD_TIMESTAMP, &gLog_p);
dolog ("Starting...");
/* This is call we could use if we need to protect global data */
/* TSReleaseAssert ((mutex = TSMutexCreate()) != TS_NULL_MUTEX); */
TSHttpHookAdd(TS_HTTP_READ_RESPONSE_HDR_HOOK, TSContCreate(transform_plugin, mutex));
TSHttpHookAdd(TS_HTTP_READ_CACHE_HDR_HOOK, TSContCreate(transform_plugin, mutex));
return;
Lerror:
TSError("[bnull-transform] Plugin disabled\n");
}
