Skip to content

Slice Plugin: add options for disabling or pacing detailed block stitch error logging. #5301

New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Merged
ezelkow1 merged 1 commit into from
Apr 26, 2019
Merged

Slice Plugin: add options for disabling or pacing detailed block stitch error logging. #5301

Show file tree
Hide file tree
Changes from all commits
Commits
Show all changes
1 commit
Select commit
File filter

Filter by extension

Filter by extension
Conversations
Failed to load comments.
Loading
Jump to
Jump to file
Failed to load files.
Loading
Diff view
Diff view
91 changes: 69 additions & 22 deletions doc/admin-guide/plugins/slice.en.rst
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -61,39 +61,87 @@ In this case, the plugin will use the default behaviour:
Plugin Options
--------------

Slice block sizes can specified using the blockbytes parameter::
The slice plugin supports the following options::

@plugin=slice.so @pparam=blockbytes:1000000 @cache_range_requests.so
--blockbytes=<bytes> (optional)
Default is 1m or 1048576 bytes
-b <bytes> for short.
Suffix k,m,g supported
Limited to 32k and 32m inclusive.

In adition to bytes, 'k', 'm' and 'g' suffixes may be used for
kilobytes, megabytes and gigabytes::
--test-blockbytes=<bytes> (optional)
Suffix k,m,g supported
-t <bytes> for short.
Limited to any positive number.
Ignored if --blockbytes provided.

@plugin=slice.so @pparam=blockbytes:5m @cache_range_requests.so
@plugin=slice.so @pparam=blockbytes:512k @cache_range_requests.so
@plugin=slice.so @pparam=blockbytes:32m @cache_range_requests.so
--pace-errorlog=<seconds> (optional)
Limit stitching error logs to every 'n' second(s)

paramater ``blockbytes`` is checked to be between 32kb and 32mb
inclusive.
--disable-errorlog (optional)
Disable writing block stitch errors to the error log.

For testing and extreme purposes the parameter ``bytesover`` may
Examples::

@plugin=slice.so @pparam=--blockbytes=1000000 @plugin=cache_range_requests.so

Or alternatively::

@plugin=slice.so @pparam=-b @pparam=1000000 @plugin=cache_range_requests.so

Byte suffix examples::

slice.so --blockbytes=5m
slice.so -b 512k
slice.so --blockbytes=32m

For testing and extreme purposes the parameter ``test-blockbytes`` may
be used instead which is unchecked::

@plugin=slice.so @pparam=bytesover:1G @cache_range_requests.so
@plugin=slice.so @pparam=bytesover:13 @cache_range_requests.so
slice.so --test-blockbytes=1G
slice.so -t 13

Because the slice plugin is susceptible to errors during block stitching
extra logs related to stitching are written to ``diags.log``. Worst case
an error log entry could be generated for every transaction. The
following options are provided to help with log overrun::

slice.so --pace-errorlog=5
slice.so -p 1
slice.so --disable-errorlog

After modifying :file:`remap.config`, restart or reload traffic server
(sudo traffic_ctl config reload) or (sudo traffic_ctl server restart)
to activate the new configuration values.

Debug Options
-------------

While the current slice plugin is able to detect block consistency
errors during the block stitching process, it can only abort the
client connection. A CDN can only "fix" these by issuing an appropriate
content revalidation.

Under normal logging these slice block errors tend to show up as::

pscl value 0
crc value ERR_READ_ERROR

By default more detailed stitching errors are written to ``diags.log``.
An example is as follows::

[Apr 19 20:26:13.639] [ET_NET 17] ERROR: [slice] 1555705573.639 reason="Non 206 internal block response" uri="http://localhost:18080/%7Ep.tex/%7Es.50M/%7Eui.20000/" uas="curl/7.29.0" req_range="bytes=1000000-" norm_range="bytes 1000000-52428799/52428800" etag_exp="%221603934496%22" lm_exp="Fri, 19 Apr 2019 18:53:20 GMT" blk_range="21000000-21999999" status_got="400" cr_got="" etag_got="" lm_got="" cc="no-store" via=""

Whether or how often these detailed log entries are written are
configurable plugin options.

Implementation Notes
====================

This slice plugin is by no means a best solution for adding
blocking support to ATS.

The slice plugin as is designed to provide a basic capability to block
requests for arbitrary range requests and for blocking large assets for
ease of caching.
This slice plugin is a stop gap plugin for handling special cases
involving very large assets that may be range requested. Hopefully
the slice plugin is deprecated in the future when partial object
caching is finally implemented.

Slice *ONLY* handles slicing up requests into blocks, it delegates
actual caching and fetching to the cache_range_requests.so plugin.
Expand Down Expand Up @@ -133,7 +181,7 @@ the block fetch to ensure the block is cached.
Important Notes
===============

This plugin also assumes that the content requested is cacheable.
This plugin assumes that the content requested is cacheable.

Any first block server response that is not a 206 is passed directly
down to the client. If that response is a '200' only the first
Expand All @@ -145,7 +193,7 @@ remove these headers.

The only 416 response that this plugin handles itself is if the
requested range is inside the last slice block but past the end of
the asset contents. Other 416 responses are handled by the parents.
the asset contents. Other 416 responses are handled by the parent.

If a client aborts mid transaction the current slice block continues to
be read from the server until it is complete to ensure that the block
Expand All @@ -166,5 +214,4 @@ check for the existence of any headers they may have created the
first time they have were visited.

Since the Slice plugin is written as an intercept handler it loses the
ability to use state machine hooks and transaction states.

ability to use normal state machine hooks and transaction states.
188 changes: 114 additions & 74 deletions plugins/experimental/slice/Config.cc
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -18,22 +18,23 @@

#include "Config.h"

#include <algorithm>
#include <cctype>
#include <cinttypes>
#include <map>
#include <string>
#include <cstdlib>
#include <getopt.h>
#include <string_view>

#include "ts/experimental.h"

int64_t
Config::bytesFrom(std::string const &valstr)
Config::bytesFrom(char const *const valstr)
{
char const *const nptr = valstr.c_str();
char *endptr = nullptr;
int64_t blockbytes = strtoll(nptr, &endptr, 10);
char *endptr = nullptr;
int64_t blockbytes = strtoll(valstr, &endptr, 10);

if (nullptr != endptr && nptr < endptr) {
size_t const dist = endptr - nptr;
if (dist < valstr.size() && 0 <= blockbytes) {
if (nullptr != endptr && valstr < endptr) {
size_t const dist = endptr - valstr;
if (dist < strlen(valstr) && 0 <= blockbytes) {
switch (tolower(*endptr)) {
case 'g':
blockbytes *= ((int64_t)1024 * (int64_t)1024 * (int64_t)1024);
Expand All @@ -58,96 +59,135 @@ Config::bytesFrom(std::string const &valstr)
}

bool
Config::fromArgs(int const argc, char const *const argv[], char *const errbuf, int const errbuf_size)
Config::fromArgs(int const argc, char const *const argv[])
{
#if !defined(SLICE_UNIT_TEST)
DEBUG_LOG("Number of arguments: %d", argc);
for (int index = 0; index < argc; ++index) {
DEBUG_LOG("args[%d] = %s", index, argv[index]);
}
#endif

std::map<std::string, std::string> keyvals;
// current "best" blockbytes from configuration
int64_t blockbytes = 0;

static std::string const bbstr(blockbytesstr);
static std::string const bostr(bytesoverstr);

// collect all args
// backwards compat: look for blockbytes
for (int index = 0; index < argc; ++index) {
std::string const argstr = argv[index];
std::string_view const argstr = argv[index];

std::size_t const spos = argstr.find_first_of(':');
if (spos != std::string::npos) {
std::string key = argstr.substr(0, spos);
std::string val = argstr.substr(spos + 1);

if (!key.empty()) {
std::for_each(key.begin(), key.end(), [](char &ch) { ch = tolower(ch); });

// blockbytes and bytesover collide
if (bbstr == key) {
keyvals.erase(bostr);
} else if (bostr == key) {
keyvals.erase(bbstr);
}
if (spos != std::string_view::npos) {
std::string_view const key = argstr.substr(0, spos);
std::string_view const val = argstr.substr(spos + 1);

keyvals[std::move(key)] = std::move(val);
if (!key.empty() && !val.empty()) {
char const *const valstr = val.data(); // inherits argv's null
int64_t const bytesread = bytesFrom(valstr);

if (blockbytesmin <= bytesread && bytesread <= blockbytesmax) {
DEBUG_LOG("Found deprecated blockbytes %" PRId64, bytesread);
blockbytes = bytesread;
}
}
}
}

std::map<std::string, std::string>::const_iterator itfind;
// standard parsing
constexpr const struct option longopts[] = {
{const_cast<char *>("blockbytes"), required_argument, nullptr, 'b'},
{const_cast<char *>("test-blockbytes"), required_argument, nullptr, 't'},
{const_cast<char *>("pace-errorlog"), required_argument, nullptr, 'p'},
{const_cast<char *>("disable-errorlog"), no_argument, nullptr, 'd'},
{nullptr, 0, nullptr, 0},
};

// getopt assumes args start at '1' so this hack is needed
char *const *argvp = ((char *const *)argv - 1);

for (;;) {
int const opt = getopt_long(argc + 1, argvp, "b:t:p:d", longopts, nullptr);
if (-1 == opt) {
break;
}

// blockbytes checked range string
itfind = keyvals.find(bbstr);
if (keyvals.end() != itfind) {
std::string val = itfind->second;
if (!val.empty()) {
int64_t const blockbytes = bytesFrom(val);
DEBUG_LOG("processing '%c' %s", (char)opt, argvp[optind - 1]);

if (blockbytes < blockbytesmin || blockbytesmax < blockbytes) {
#if !defined(SLICE_UNIT_TEST)
DEBUG_LOG("Block Bytes %" PRId64 " outside checked limits %" PRId64 "-%" PRId64, blockbytes, blockbytesmin, blockbytesmax);
DEBUG_LOG("Block Bytes kept at %" PRId64, m_blockbytes);
#endif
switch (opt) {
case 'b': {
int64_t const bytesread = bytesFrom(optarg);
if (blockbytesmin <= bytesread && bytesread <= blockbytesmax) {
DEBUG_LOG("Using blockbytes %" PRId64, bytesread);
blockbytes = bytesread;
} else {
#if !defined(SLICE_UNIT_TEST)
DEBUG_LOG("Block Bytes set to %" PRId64, blockbytes);
#endif
m_blockbytes = blockbytes;
ERROR_LOG("Invalid blockbytes: %s", optarg);
}
} break;
case 't':
if (0 == blockbytes) {
int64_t const bytesread = bytesFrom(optarg);
if (0 < bytesread) {
DEBUG_LOG("Using blockbytestest %" PRId64, bytesread);
blockbytes = bytesread;
} else {
ERROR_LOG("Invalid blockbytestest: %s", optarg);
}
} else {
DEBUG_LOG("Skipping blockbytestest in favor of blockbytes");
}
break;
case 'p': {
int const secsread = atoi(optarg);
if (0 < secsread) {
m_paceerrsecs = std::min(secsread, 60);
} else {
DEBUG_LOG("Ignoring pace-errlog argument");
}
} break;
case 'd':
m_paceerrsecs = -1;
break;
default:
break;
}
}

keyvals.erase(itfind);
if (0 < blockbytes) {
DEBUG_LOG("Using configured blockbytes %" PRId64, blockbytes);
m_blockbytes = blockbytes;
} else {
DEBUG_LOG("Using default blockbytes %" PRId64, m_blockbytes);
}

// bytesover unchecked range string
itfind = keyvals.find(bostr);
if (keyvals.end() != itfind) {
std::string val = itfind->second;
if (!val.empty()) {
int64_t const bytesover = bytesFrom(val);

if (bytesover <= 0) {
#if !defined(SLICE_UNIT_TEST)
DEBUG_LOG("Bytes Over %" PRId64 " <= 0", bytesover);
DEBUG_LOG("Block Bytes kept at %" PRId64, m_blockbytes);
#endif
} else {
#if !defined(SLICE_UNIT_TEST)
DEBUG_LOG("Block Bytes set to %" PRId64, bytesover);
#endif
m_blockbytes = bytesover;
}
}
keyvals.erase(itfind);
if (m_paceerrsecs < 0) {
DEBUG_LOG("Block stitching error logs disabled");
} else if (0 == m_paceerrsecs) {
DEBUG_LOG("Block stitching error logs enabled");
} else {
DEBUG_LOG("Block stitching error logs at most every %d sec(s)", m_paceerrsecs);
}

for (std::map<std::string, std::string>::const_iterator itkv(keyvals.cbegin()); keyvals.cend() != itkv; ++itkv) {
#if !defined(SLICE_UNIT_TEST)
ERROR_LOG("Unhandled pparam %s", itkv->first.c_str());
#endif
return true;
}

bool
Config::canLogError()
{
std::lock_guard<std::mutex> const guard(m_mutex);

if (m_paceerrsecs < 0) {
return false;
} else if (0 == m_paceerrsecs) {
return true;
}

#if !defined(UNITTEST)
TSHRTime const timenow = TShrtime();
if (timenow < m_nextlogtime) {
return false;
}

m_nextlogtime = timenow + TS_HRTIME_SECONDS(m_paceerrsecs);
#else
m_nextlogtime = 0; // thanks clang
#endif

return true;
}
Loading