walkero
/
nghttp2
1
0
Fork 0
Code Issues Pull Requests Projects Releases 1 Wiki Activity

Add features to logging, client and server port, 

time_iso8601 and request_time.
This commit is contained in:
Lucas Pardue 2014-11-19 16:53:30 +00:00
parent ee65dea8af
commit 9cf1a0c77c
14 changed files with 154 additions and 53 deletions
Show Stats Download Patch File Download Diff File Expand all files Collapse all files

38
src/shrpx.cc
View File

@ -461,22 +461,7 @@ void graceful_shutdown_signal_cb(evutil_socket_t sig, short events, void *arg)
namespace {
std::unique_ptr<std::string> generate_time()
{
char buf[32];
// Format data like this:
// 03/Jul/2014:00:19:38 +0900
struct tm tms;
auto now = time(nullptr);
if(localtime_r(&now, &tms) == nullptr) {
return util::make_unique<std::string>("");
}
if(strftime(buf, sizeof(buf), "%d/%b/%Y:%T %z", &tms) == 0) {
return util::make_unique<std::string>("");
}
return util::make_unique<std::string>(buf);
return util::make_unique<std::string>(util::format_common_log(std::chrono::system_clock::now()));
}
} // namespace
@ -487,7 +472,6 @@ void refresh_cb(evutil_socket_t sig, short events, void *arg)
auto worker_stat = listener_handler->get_worker_stat();
mod_config()->cached_time = generate_time();
// In multi threaded mode (get_config()->num_worker > 1), we have to
// wait for event notification to workers to finish.
if(get_config()->num_worker == 1 &&
@ -1144,12 +1128,20 @@ Logging:
--accesslog-format=<FORMAT>
Specify format string for access log. The
default format is combined format. The following
variables are available: $remote_addr: client IP
address. $time_local: local time. $request:
HTTP request line. $status: HTTP response status
code. $body_bytes_sent: the number of bytes sent
to client as response body. $http_<VAR>: value
of HTTP request header <VAR>.
variables are available:
$remote_addr: client IP address
$time_local: local time in Common Log format
$time_iso8601: local time in ISO 8601 format
$request: HTTP request line
$status: HTTP response status code.
$body_bytes_sent: the number of bytes sent
to client as response body
$http_<VAR>: value of HTTP request header <VAR>
$remote_port: client port
$server_port: server port
$request_time: request processing time in
seconds with milliseconds
resolution.
Default: )"
<< DEFAULT_ACCESSLOG_FORMAT << R"(
--errorlog-file=<PATH>

15
src/shrpx_client_handler.cc
View File

@ -168,9 +168,11 @@ ClientHandler::ClientHandler(bufferevent *bev,
bufferevent_rate_limit_group *rate_limit_group,
int fd, SSL *ssl,
const char *ipaddr,
const char *port,
WorkerStat *worker_stat,
DownstreamConnectionPool *dconn_pool)
: ipaddr_(ipaddr),
port_(port),
dconn_pool_(dconn_pool),
bev_(bev),
http2session_(nullptr),
@ -736,10 +738,15 @@ void ClientHandler::write_accesslog(Downstream *downstream)
downstream->get_request_http2_authority().c_str() :
downstream->get_request_path().c_str(),
downstream->get_request_start_time(),
std::chrono::high_resolution_clock::now(),
downstream->get_request_major(),
downstream->get_request_minor(),
downstream->get_response_http_status(),
downstream->get_response_sent_bodylen()
downstream->get_response_sent_bodylen(),
port_.c_str(),
get_config()->port
};
upstream_accesslog(get_config()->accesslog_format, &lgsp);
@ -754,9 +761,13 @@ void ClientHandler::write_accesslog(int major, int minor,
ipaddr_.c_str(),
"-", // method
"-", // path,
std::chrono::high_resolution_clock::now(), //request_start_time TODO is there a better value?
std::chrono::high_resolution_clock::now(), //time_now
major, minor, // major, minor
status,
body_bytes_sent
body_bytes_sent,
port_.c_str(),
get_config()->port
};
upstream_accesslog(get_config()->accesslog_format, &lgsp);

4
src/shrpx_client_handler.h
View File

@ -48,7 +48,7 @@ class ClientHandler {
public:
ClientHandler(bufferevent *bev,
bufferevent_rate_limit_group *rate_limit_group,
int fd, SSL *ssl, const char *ipaddr,
int fd, SSL *ssl, const char *ipaddr, const char *port,
WorkerStat *worker_stat,
DownstreamConnectionPool *dconn_pool);
~ClientHandler();
@ -62,6 +62,7 @@ public:
const timeval *write_timeout);
int validate_next_proto();
const std::string& get_ipaddr() const;
const std::string& get_port() const;
bool get_should_close_after_write() const;
void set_should_close_after_write(bool f);
Upstream* get_upstream();
@ -117,6 +118,7 @@ public:
private:
std::unique_ptr<Upstream> upstream_;
std::string ipaddr_;
std::string port_;
DownstreamConnectionPool *dconn_pool_;
bufferevent *bev_;
// Shared HTTP2 session for each thread. NULL if backend is not

8
src/shrpx_config.cc
View File

@ -384,6 +384,8 @@ std::vector<LogFragment> parse_log_format(const char *optarg)
type = SHRPX_LOGF_REMOTE_ADDR;
} else if(util::strieq("$time_local", var_start, varlen)) {
type = SHRPX_LOGF_TIME_LOCAL;
} else if(util::strieq("$time_iso8601", var_start, varlen)) {
type = SHRPX_LOGF_TIME_ISO8601;
} else if(util::strieq("$request", var_start, varlen)) {
type = SHRPX_LOGF_REQUEST;
} else if(util::strieq("$status", var_start, varlen)) {
@ -394,6 +396,12 @@ std::vector<LogFragment> parse_log_format(const char *optarg)
type = SHRPX_LOGF_HTTP;
value = var_start + sizeof("$http_") - 1;
valuelen = varlen - (sizeof("$http_") - 1);
} else if(util::strieq("$remote_port", var_start, varlen)) {
type = SHRPX_LOGF_REMOTE_PORT;
} else if(util::strieq("$server_port", var_start, varlen)) {
type = SHRPX_LOGF_SERVER_PORT;
} else if(util::strieq("$request_time", var_start, varlen)) {
type = SHRPX_LOGF_REQUEST_TIME;
} else {
LOG(WARN) << "Unrecognized log format variable: "
<< std::string(var_start, varlen);

10
src/shrpx_downstream.cc
View File

@ -390,6 +390,16 @@ const std::string& Downstream::get_request_path() const
return request_path_;
}
void Downstream::set_request_start_time(std::chrono::high_resolution_clock::time_point time)
{
request_start_time_ = std::move(time);
}
const std::chrono::high_resolution_clock::time_point& Downstream::get_request_start_time() const
{
return request_start_time_;
}
const std::string& Downstream::get_request_http2_scheme() const
{
return request_http2_scheme_;

4
src/shrpx_downstream.h
View File

@ -32,6 +32,7 @@
#include <vector>
#include <string>
#include <memory>
#include <chrono>
#include <event.h>
#include <event2/bufferevent.h>
@ -132,6 +133,8 @@ public:
void set_request_method(std::string method);
const std::string& get_request_method() const;
void set_request_path(std::string path);
void set_request_start_time(std::chrono::high_resolution_clock::time_point time);
const std::chrono::high_resolution_clock::time_point& get_request_start_time() const;
void append_request_path(const char *data, size_t len);
// Returns request path. For HTTP/1.1, this is request-target. For
// HTTP/2, this is :path header field value.
@ -284,6 +287,7 @@ private:
std::string request_path_;
std::string request_http2_scheme_;
std::string request_http2_authority_;
std::chrono::high_resolution_clock::time_point request_start_time_;
std::string assembled_request_cookie_;
std::string http2_settings_;

1
src/shrpx_http2_upstream.cc
View File

@ -355,6 +355,7 @@ int on_request_headers(Http2Upstream *upstream,
downstream->set_request_http2_scheme(http2::value_to_str(scheme));
downstream->set_request_http2_authority(http2::value_to_str(authority));
downstream->set_request_path(http2::value_to_str(path));
downstream->set_request_start_time(std::chrono::high_resolution_clock::now());
if(!(frame->hd.flags & NGHTTP2_FLAG_END_STREAM)) {
downstream->set_request_http2_expect_body(true);

1
src/shrpx_https_upstream.cc
View File

@ -143,6 +143,7 @@ int htp_hdrs_completecb(http_parser *htp)
downstream->set_request_method(http_method_str((enum http_method)htp->method));
downstream->set_request_major(htp->http_major);
downstream->set_request_minor(htp->http_minor);
downstream->set_request_start_time(std::chrono::high_resolution_clock::now());
downstream->set_request_connection_close(!http_should_keep_alive(htp));

33
src/shrpx_log.cc
View File

@ -33,6 +33,7 @@
#include <cstring>
#include <ctime>
#include <iostream>
#include <iomanip>
#include "shrpx_config.h"
#include "shrpx_downstream.h"
@ -192,8 +193,6 @@ void upstream_accesslog(const std::vector<LogFragment>& lfv, LogSpec *lgsp)
auto p = buf;
auto avail = sizeof(buf) - 2;
auto cached_time = get_config()->cached_time;
for(auto& lf : lfv) {
switch(lf.type) {
case SHRPX_LOGF_LITERAL:
@ -203,7 +202,10 @@ void upstream_accesslog(const std::vector<LogFragment>& lfv, LogSpec *lgsp)
std::tie(p, avail) = copy(lgsp->remote_addr, avail, p);
break;
case SHRPX_LOGF_TIME_LOCAL:
std::tie(p, avail) = copy(cached_time->c_str(), avail, p);
std::tie(p, avail) = copy(util::format_common_log(lgsp->time_now).c_str(), avail, p);
break;
case SHRPX_LOGF_TIME_ISO8601:
std::tie(p, avail) = copy(util::format_iso8601(lgsp->time_now).c_str(), avail, p);
break;
case SHRPX_LOGF_REQUEST:
std::tie(p, avail) = copy(lgsp->method, avail, p);
@ -232,6 +234,31 @@ void upstream_accesslog(const std::vector<LogFragment>& lfv, LogSpec *lgsp)
std::tie(p, avail) = copy("-", avail, p);
break;
case SHRPX_LOGF_REMOTE_PORT:
std::tie(p, avail) = copy(lgsp->remote_port, avail, p);
break;
case SHRPX_LOGF_SERVER_PORT:
std::tie(p, avail) = copy(util::utos(lgsp->server_port).c_str(),
avail, p);
break;
case SHRPX_LOGF_REQUEST_TIME:
{
auto t = std::chrono::duration_cast<std::chrono::milliseconds>
(lgsp->time_now - lgsp->request_start_time).count();
auto frac = util::utos(t % 1000);
auto sec = util::utos(t / 1000);
if (frac.size() < 3) {
frac = std::string(3 - frac.size(), '0') + frac;
}
sec += ".";
sec += frac;
std::tie(p, avail) = copy( sec.c_str(), avail, p);
}
break;
case SHRPX_LOGF_NONE:
break;
default:
break;

9
src/shrpx_log.h
View File

@ -30,6 +30,7 @@
#include <sstream>
#include <memory>
#include <vector>
#include <chrono>
namespace shrpx {
@ -107,10 +108,14 @@ enum LogFragmentType {
SHRPX_LOGF_LITERAL,
SHRPX_LOGF_REMOTE_ADDR,
SHRPX_LOGF_TIME_LOCAL,
SHRPX_LOGF_TIME_ISO8601,
SHRPX_LOGF_REQUEST,
SHRPX_LOGF_STATUS,
SHRPX_LOGF_BODY_BYTES_SENT,
SHRPX_LOGF_HTTP,
SHRPX_LOGF_REMOTE_PORT,
SHRPX_LOGF_SERVER_PORT,
SHRPX_LOGF_REQUEST_TIME,
};
struct LogFragment {
@ -123,9 +128,13 @@ struct LogSpec {
const char *remote_addr;
const char *method;
const char *path;
std::chrono::high_resolution_clock::time_point request_start_time;
std::chrono::high_resolution_clock::time_point time_now;
int major, minor;
unsigned int status;
int64_t body_bytes_sent;
const char *remote_port;
uint16_t server_port;
};
void upstream_accesslog(const std::vector<LogFragment>& lf, LogSpec *lgsp);

2
src/shrpx_spdy_upstream.cc
View File

@ -214,6 +214,8 @@ void on_ctrl_recv_callback
downstream->set_request_path(path);
}
downstream->set_request_start_time(std::chrono::high_resolution_clock::now());
if(!(frame->syn_stream.hd.flags & SPDYLAY_CTRL_FLAG_FIN)) {
downstream->set_request_http2_expect_body(true);
}

9
src/shrpx_ssl.cc
View File

@ -476,9 +476,10 @@ ClientHandler* accept_connection
DownstreamConnectionPool *dconn_pool)
{
char host[NI_MAXHOST];
char service[NI_MAXSERV];
int rv;
rv = getnameinfo(addr, addrlen, host, sizeof(host), nullptr, 0,
NI_NUMERICHOST);
rv = getnameinfo(addr, addrlen, host, sizeof(host),
service, sizeof(service), NI_NUMERICHOST);
if(rv != 0) {
LOG(ERROR) << "getnameinfo() failed: " << gai_strerror(rv);
@ -522,8 +523,8 @@ ClientHandler* accept_connection
return nullptr;
}
return new ClientHandler(bev, rate_limit_group, fd, ssl, host, worker_stat,
dconn_pool);
return new ClientHandler(bev, rate_limit_group, fd, ssl, host, service,
worker_stat, dconn_pool);
}
namespace {

19
src/util.cc
View File

@ -715,25 +715,6 @@ std::vector<unsigned char> get_default_alpn()
return res;
}
std::string format_iso8601(const std::chrono::system_clock::time_point& tp)
{
auto t = std::chrono::duration_cast<std::chrono::milliseconds>
(tp.time_since_epoch());
time_t sec = t.count() / 1000;
tm tms;
if(gmtime_r(&sec, &tms) == nullptr) {
return "";
}
char buf[128];
auto nwrite = strftime(buf, sizeof(buf), "%Y-%m-%dT%H:%M:%S", &tms);
snprintf(&buf[nwrite], sizeof(buf) - nwrite, ".%03ldZ", t.count() % 1000);
return buf;
}
} // namespace util
} // namespace nghttp2

54
src/util.h
View File

@ -483,9 +483,61 @@ bool check_h2_is_selected(const unsigned char *alpn, size_t len);
// HTTP/2 protocol identifier.
std::vector<unsigned char> get_default_alpn();
// Returns given time |tp| in Common Log format (e.g.,
// 03/Jul/2014:00:19:38 +0900)
// Expected type of |tp| is std::chrono::timepoint
template <typename T>
std::string format_common_log(const T& tp)
{
auto t = std::chrono::duration_cast<std::chrono::milliseconds>
(tp.time_since_epoch());
time_t sec = t.count() / 1000;
tm tms;
if(localtime_r(&sec, &tms) == nullptr) {
return "";
}
char buf[32];
strftime(buf, sizeof(buf), "%d/%b/%Y:%T %z", &tms);
return buf;
}
// Returns given time |tp| in ISO 8601 format (e.g.,
// 2014-11-15T12:58:24.741Z)
std::string format_iso8601(const std::chrono::system_clock::time_point& tp);
// Expected type of |tp| is std::chrono::timepoint
template <typename T>
std::string format_iso8601(const T& tp)
{
auto t = std::chrono::duration_cast<std::chrono::milliseconds>
(tp.time_since_epoch());
time_t sec = t.count() / 1000;
tm tms;
if(gmtime_r(&sec, &tms) == nullptr) {
return "";
}
char buf[128];
auto nwrite = strftime(buf, sizeof(buf), "%Y-%m-%dT%H:%M:%S", &tms);
snprintf(&buf[nwrite], sizeof(buf) - nwrite, ".%03ldZ", t.count() % 1000);
return buf;
}
// Return the system precision of the template parameter |Clock| as
// a nanosecond value of type |Rep|
template <typename Clock, typename Rep>
Rep
clock_precision()
{
std::chrono::duration<Rep, std::nano> duration = typename Clock::duration(1);
return duration.count();
}
} // namespace util