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

shrpx: Don't run expensive INFO log code 

INFO log and its surrounding code are now guarded by
LOG_ENABLED(SEVERITY) macro so that they don't run if log level
threshold is higher. This increases performance because log formatting
is somewhat expensive.
This commit is contained in:
Tatsuhiro Tsujikawa 2013-01-21 22:42:49 +09:00
parent 5adfd07e7c
commit 29bec93eb9
12 changed files with 102 additions and 89 deletions
Show Stats Download Patch File Download Diff File Expand all files Collapse all files

13
src/shrpx.cc
View File

@ -105,10 +105,12 @@ int cache_downstream_host_address()
rv = getnameinfo(res->ai_addr, res->ai_addrlen, host, sizeof(host), rv = getnameinfo(res->ai_addr, res->ai_addrlen, host, sizeof(host),
0, 0, NI_NUMERICHOST); 0, 0, NI_NUMERICHOST);
if(rv == 0) { if(rv == 0) {
if(LOG_ENABLED(INFO)) {
LOG(INFO) << "Using first returned address for downstream " LOG(INFO) << "Using first returned address for downstream "
<< host << host
<< ", port " << ", port "
<< get_config()->downstream_port; << get_config()->downstream_port;
}
} else { } else {
LOG(FATAL) << gai_strerror(rv); LOG(FATAL) << gai_strerror(rv);
DIE(); DIE();
@ -147,9 +149,11 @@ evconnlistener* create_evlistener(ListenHandler *handler, int family)
addrinfo *res, *rp; addrinfo *res, *rp;
r = getaddrinfo(get_config()->host, service, &hints, &res); r = getaddrinfo(get_config()->host, service, &hints, &res);
if(r != 0) { if(r != 0) {
if(LOG_ENABLED(INFO)) {
LOG(INFO) << "Unable to get IPv" << (family == AF_INET ? "4" : "6") LOG(INFO) << "Unable to get IPv" << (family == AF_INET ? "4" : "6")
<< " address for " << get_config()->host << ": " << " address for " << get_config()->host << ": "
<< gai_strerror(r); << gai_strerror(r);
}
return NULL; return NULL;
} }
for(rp = res; rp; rp = rp->ai_next) { for(rp = res; rp; rp = rp->ai_next) {
@ -183,7 +187,10 @@ evconnlistener* create_evlistener(ListenHandler *handler, int family)
r = getnameinfo(rp->ai_addr, rp->ai_addrlen, host, sizeof(host), r = getnameinfo(rp->ai_addr, rp->ai_addrlen, host, sizeof(host),
0, 0, NI_NUMERICHOST); 0, 0, NI_NUMERICHOST);
if(r == 0) { if(r == 0) {
LOG(INFO) << "Listening on " << host << ", port " << get_config()->port; if(LOG_ENABLED(INFO)) {
LOG(INFO) << "Listening on " << host << ", port "
<< get_config()->port;
}
} else { } else {
LOG(FATAL) << gai_strerror(r); LOG(FATAL) << gai_strerror(r);
DIE(); DIE();
@ -191,7 +198,7 @@ evconnlistener* create_evlistener(ListenHandler *handler, int family)
} }
freeaddrinfo(res); freeaddrinfo(res);
if(rp == 0) { if(rp == 0) {
if(ENABLE_LOG) { if(LOG_ENABLED(INFO)) {
LOG(INFO) << "Listening " << (family == AF_INET ? "IPv4" : "IPv6") LOG(INFO) << "Listening " << (family == AF_INET ? "IPv4" : "IPv6")
<< " socket failed"; << " socket failed";
} }
@ -263,7 +270,7 @@ int event_loop()
listener_handler->create_spdy_session(); listener_handler->create_spdy_session();
} }
if(ENABLE_LOG) { if(LOG_ENABLED(INFO)) {
LOG(INFO) << "Entering event loop"; LOG(INFO) << "Entering event loop";
} }
event_base_loop(evbase, 0); event_base_loop(evbase, 0);

28
src/shrpx_client_handler.cc
View File

@ -76,13 +76,13 @@ void upstream_eventcb(bufferevent *bev, short events, void *arg)
ClientHandler *handler = reinterpret_cast<ClientHandler*>(arg); ClientHandler *handler = reinterpret_cast<ClientHandler*>(arg);
bool finish = false; bool finish = false;
if(events & BEV_EVENT_EOF) { if(events & BEV_EVENT_EOF) {
if(ENABLE_LOG) { if(LOG_ENABLED(INFO)) {
CLOG(INFO, handler) << "EOF"; CLOG(INFO, handler) << "EOF";
} }
finish = true; finish = true;
} }
if(events & BEV_EVENT_ERROR) { if(events & BEV_EVENT_ERROR) {
if(ENABLE_LOG) { if(LOG_ENABLED(INFO)) {
CLOG(INFO, handler) << "Network error: " CLOG(INFO, handler) << "Network error: "
<< evutil_socket_error_to_string << evutil_socket_error_to_string
(EVUTIL_SOCKET_ERROR()); (EVUTIL_SOCKET_ERROR());
@ -90,7 +90,7 @@ void upstream_eventcb(bufferevent *bev, short events, void *arg)
finish = true; finish = true;
} }
if(events & BEV_EVENT_TIMEOUT) { if(events & BEV_EVENT_TIMEOUT) {
if(ENABLE_LOG) { if(LOG_ENABLED(INFO)) {
CLOG(INFO, handler) << "Time out"; CLOG(INFO, handler) << "Time out";
} }
finish = true; finish = true;
@ -99,12 +99,12 @@ void upstream_eventcb(bufferevent *bev, short events, void *arg)
delete handler; delete handler;
} else { } else {
if(events & BEV_EVENT_CONNECTED) { if(events & BEV_EVENT_CONNECTED) {
if(ENABLE_LOG) { if(LOG_ENABLED(INFO)) {
CLOG(INFO, handler) << "SSL/TLS handleshake completed"; CLOG(INFO, handler) << "SSL/TLS handleshake completed";
} }
handler->set_bev_cb(upstream_readcb, upstream_writecb, upstream_eventcb); handler->set_bev_cb(upstream_readcb, upstream_writecb, upstream_eventcb);
handler->validate_next_proto(); handler->validate_next_proto();
if(ENABLE_LOG) { if(LOG_ENABLED(INFO)) {
if(SSL_session_reused(handler->get_ssl())) { if(SSL_session_reused(handler->get_ssl())) {
CLOG(INFO, handler) << "SSL/TLS session reused"; CLOG(INFO, handler) << "SSL/TLS session reused";
} }
@ -143,7 +143,7 @@ ClientHandler::ClientHandler(bufferevent *bev, int fd, SSL *ssl,
ClientHandler::~ClientHandler() ClientHandler::~ClientHandler()
{ {
if(ENABLE_LOG) { if(LOG_ENABLED(INFO)) {
CLOG(INFO, this) << "Deleting"; CLOG(INFO, this) << "Deleting";
} }
if(ssl_) { if(ssl_) {
@ -161,7 +161,7 @@ ClientHandler::~ClientHandler()
i != dconn_pool_.end(); ++i) { i != dconn_pool_.end(); ++i) {
delete *i; delete *i;
} }
if(ENABLE_LOG) { if(LOG_ENABLED(INFO)) {
CLOG(INFO, this) << "Deleted"; CLOG(INFO, this) << "Deleted";
} }
} }
@ -200,7 +200,7 @@ int ClientHandler::validate_next_proto()
unsigned int next_proto_len; unsigned int next_proto_len;
SSL_get0_next_proto_negotiated(ssl_, &next_proto, &next_proto_len); SSL_get0_next_proto_negotiated(ssl_, &next_proto, &next_proto_len);
if(next_proto) { if(next_proto) {
if(ENABLE_LOG) { if(LOG_ENABLED(INFO)) {
std::string proto(next_proto, next_proto+next_proto_len); std::string proto(next_proto, next_proto+next_proto_len);
CLOG(INFO, this) << "The negotiated next protocol: " << proto; CLOG(INFO, this) << "The negotiated next protocol: " << proto;
} }
@ -211,11 +211,11 @@ int ClientHandler::validate_next_proto()
return 0; return 0;
} }
} else { } else {
if(ENABLE_LOG) { if(LOG_ENABLED(INFO)) {
CLOG(INFO, this) << "No proto negotiated."; CLOG(INFO, this) << "No proto negotiated.";
} }
} }
if(ENABLE_LOG) { if(LOG_ENABLED(INFO)) {
CLOG(INFO, this) << "Use HTTP/1.1"; CLOG(INFO, this) << "Use HTTP/1.1";
} }
HttpsUpstream *https_upstream = new HttpsUpstream(this); HttpsUpstream *https_upstream = new HttpsUpstream(this);
@ -250,7 +250,7 @@ void ClientHandler::set_should_close_after_write(bool f)
void ClientHandler::pool_downstream_connection(DownstreamConnection *dconn) void ClientHandler::pool_downstream_connection(DownstreamConnection *dconn)
{ {
if(ENABLE_LOG) { if(LOG_ENABLED(INFO)) {
CLOG(INFO, this) << "Pooling downstream connection DCONN:" << dconn; CLOG(INFO, this) << "Pooling downstream connection DCONN:" << dconn;
} }
dconn_pool_.insert(dconn); dconn_pool_.insert(dconn);
@ -258,7 +258,7 @@ void ClientHandler::pool_downstream_connection(DownstreamConnection *dconn)
void ClientHandler::remove_downstream_connection(DownstreamConnection *dconn) void ClientHandler::remove_downstream_connection(DownstreamConnection *dconn)
{ {
if(ENABLE_LOG) { if(LOG_ENABLED(INFO)) {
CLOG(INFO, this) << "Removing downstream connection DCONN:" << dconn CLOG(INFO, this) << "Removing downstream connection DCONN:" << dconn
<< " from pool"; << " from pool";
} }
@ -268,7 +268,7 @@ void ClientHandler::remove_downstream_connection(DownstreamConnection *dconn)
DownstreamConnection* ClientHandler::get_downstream_connection() DownstreamConnection* ClientHandler::get_downstream_connection()
{ {
if(dconn_pool_.empty()) { if(dconn_pool_.empty()) {
if(ENABLE_LOG) { if(LOG_ENABLED(INFO)) {
CLOG(INFO, this) << "Downstream connection pool is empty." CLOG(INFO, this) << "Downstream connection pool is empty."
<< " Create new one"; << " Create new one";
} }
@ -280,7 +280,7 @@ DownstreamConnection* ClientHandler::get_downstream_connection()
} else { } else {
DownstreamConnection *dconn = *dconn_pool_.begin(); DownstreamConnection *dconn = *dconn_pool_.begin();
dconn_pool_.erase(dconn); dconn_pool_.erase(dconn);
if(ENABLE_LOG) { if(LOG_ENABLED(INFO)) {
CLOG(INFO, this) << "Reuse downstream connection DCONN:" << dconn CLOG(INFO, this) << "Reuse downstream connection DCONN:" << dconn
<< " from pool"; << " from pool";
} }

4
src/shrpx_downstream.cc
View File

@ -63,7 +63,7 @@ Downstream::Downstream(Upstream *upstream, int stream_id, int priority)
Downstream::~Downstream() Downstream::~Downstream()
{ {
if(ENABLE_LOG) { if(LOG_ENABLED(INFO)) {
DLOG(INFO, this) << "Deleting"; DLOG(INFO, this) << "Deleting";
} }
if(response_body_buf_) { if(response_body_buf_) {
@ -73,7 +73,7 @@ Downstream::~Downstream()
if(dconn_) { if(dconn_) {
delete dconn_; delete dconn_;
} }
if(ENABLE_LOG) { if(LOG_ENABLED(INFO)) {
DLOG(INFO, this) << "Deleted"; DLOG(INFO, this) << "Deleted";
} }
} }

18
src/shrpx_http_downstream_connection.cc
View File

@ -66,7 +66,7 @@ HttpDownstreamConnection::~HttpDownstreamConnection()
int HttpDownstreamConnection::attach_downstream(Downstream *downstream) int HttpDownstreamConnection::attach_downstream(Downstream *downstream)
{ {
if(ENABLE_LOG) { if(LOG_ENABLED(INFO)) {
DCLOG(INFO, this) << "Attaching to DOWNSTREAM:" << downstream; DCLOG(INFO, this) << "Attaching to DOWNSTREAM:" << downstream;
} }
Upstream *upstream = downstream->get_upstream(); Upstream *upstream = downstream->get_upstream();
@ -85,7 +85,7 @@ int HttpDownstreamConnection::attach_downstream(Downstream *downstream)
bev_ = 0; bev_ = 0;
return SHRPX_ERR_NETWORK; return SHRPX_ERR_NETWORK;
} }
if(ENABLE_LOG) { if(LOG_ENABLED(INFO)) {
DCLOG(INFO, this) << "Connecting to downstream server"; DCLOG(INFO, this) << "Connecting to downstream server";
} }
} }
@ -184,7 +184,7 @@ int HttpDownstreamConnection::push_request_headers()
} }
hdrs += "\r\n"; hdrs += "\r\n";
if(ENABLE_LOG) { if(LOG_ENABLED(INFO)) {
const char *hdrp; const char *hdrp;
std::string nhdrs; std::string nhdrs;
if(get_config()->tty) { if(get_config()->tty) {
@ -272,21 +272,21 @@ void idle_eventcb(bufferevent *bev, short events, void *arg)
if(events & BEV_EVENT_CONNECTED) { if(events & BEV_EVENT_CONNECTED) {
// Downstream was detached before connection established? // Downstream was detached before connection established?
// This may be safe to be left. // This may be safe to be left.
if(ENABLE_LOG) { if(LOG_ENABLED(INFO)) {
DCLOG(INFO, dconn) << "Idle connection connected?"; DCLOG(INFO, dconn) << "Idle connection connected?";
} }
return; return;
} }
if(events & BEV_EVENT_EOF) { if(events & BEV_EVENT_EOF) {
if(ENABLE_LOG) { if(LOG_ENABLED(INFO)) {
DCLOG(INFO, dconn) << "Idle connection EOF"; DCLOG(INFO, dconn) << "Idle connection EOF";
} }
} else if(events & BEV_EVENT_TIMEOUT) { } else if(events & BEV_EVENT_TIMEOUT) {
if(ENABLE_LOG) { if(LOG_ENABLED(INFO)) {
DCLOG(INFO, dconn) << "Idle connection timeout"; DCLOG(INFO, dconn) << "Idle connection timeout";
} }
} else if(events & BEV_EVENT_ERROR) { } else if(events & BEV_EVENT_ERROR) {
if(ENABLE_LOG) { if(LOG_ENABLED(INFO)) {
DCLOG(INFO, dconn) << "Idle connection network error"; DCLOG(INFO, dconn) << "Idle connection network error";
} }
} }
@ -298,7 +298,7 @@ void idle_eventcb(bufferevent *bev, short events, void *arg)
void HttpDownstreamConnection::detach_downstream(Downstream *downstream) void HttpDownstreamConnection::detach_downstream(Downstream *downstream)
{ {
if(ENABLE_LOG) { if(LOG_ENABLED(INFO)) {
DCLOG(INFO, this) << "Detaching from DOWNSTREAM:" << downstream; DCLOG(INFO, this) << "Detaching from DOWNSTREAM:" << downstream;
} }
downstream->set_downstream_connection(0); downstream->set_downstream_connection(0);
@ -443,7 +443,7 @@ int HttpDownstreamConnection::on_read()
if(htperr == HPE_OK) { if(htperr == HPE_OK) {
return 0; return 0;
} else { } else {
if(ENABLE_LOG) { if(LOG_ENABLED(INFO)) {
DCLOG(INFO, this) << "HTTP parser failure: " DCLOG(INFO, this) << "HTTP parser failure: "
<< "(" << http_errno_name(htperr) << ") " << "(" << http_errno_name(htperr) << ") "
<< http_errno_description(htperr); << http_errno_description(htperr);

28
src/shrpx_https_upstream.cc
View File

@ -74,7 +74,7 @@ int htp_msg_begin(http_parser *htp)
{ {
HttpsUpstream *upstream; HttpsUpstream *upstream;
upstream = reinterpret_cast<HttpsUpstream*>(htp->data); upstream = reinterpret_cast<HttpsUpstream*>(htp->data);
if(ENABLE_LOG) { if(LOG_ENABLED(INFO)) {
ULOG(INFO, upstream) << "HTTP request started"; ULOG(INFO, upstream) << "HTTP request started";
} }
upstream->reset_current_header_length(); upstream->reset_current_header_length();
@ -131,7 +131,7 @@ int htp_hdrs_completecb(http_parser *htp)
int rv; int rv;
HttpsUpstream *upstream; HttpsUpstream *upstream;
upstream = reinterpret_cast<HttpsUpstream*>(htp->data); upstream = reinterpret_cast<HttpsUpstream*>(htp->data);
if(ENABLE_LOG) { if(LOG_ENABLED(INFO)) {
ULOG(INFO, upstream) << "HTTP request headers completed"; ULOG(INFO, upstream) << "HTTP request headers completed";
} }
Downstream *downstream = upstream->get_downstream(); Downstream *downstream = upstream->get_downstream();
@ -142,7 +142,7 @@ int htp_hdrs_completecb(http_parser *htp)
downstream->set_request_connection_close(!http_should_keep_alive(htp)); downstream->set_request_connection_close(!http_should_keep_alive(htp));
if(ENABLE_LOG) { if(LOG_ENABLED(INFO)) {
std::stringstream ss; std::stringstream ss;
ss << downstream->get_request_method() << " " ss << downstream->get_request_method() << " "
<< downstream->get_request_path() << " " << downstream->get_request_path() << " "
@ -222,7 +222,7 @@ int htp_msg_completecb(http_parser *htp)
int rv; int rv;
HttpsUpstream *upstream; HttpsUpstream *upstream;
upstream = reinterpret_cast<HttpsUpstream*>(htp->data); upstream = reinterpret_cast<HttpsUpstream*>(htp->data);
if(ENABLE_LOG) { if(LOG_ENABLED(INFO)) {
ULOG(INFO, upstream) << "HTTP request completed"; ULOG(INFO, upstream) << "HTTP request completed";
} }
Downstream *downstream = upstream->get_downstream(); Downstream *downstream = upstream->get_downstream();
@ -306,14 +306,14 @@ int HttpsUpstream::on_read()
return -1; return -1;
} }
} else if(downstream->get_output_buffer_full()) { } else if(downstream->get_output_buffer_full()) {
if(ENABLE_LOG) { if(LOG_ENABLED(INFO)) {
ULOG(INFO, this) << "Downstream output buffer is full"; ULOG(INFO, this) << "Downstream output buffer is full";
} }
pause_read(SHRPX_NO_BUFFER); pause_read(SHRPX_NO_BUFFER);
} }
} }
} else { } else {
if(ENABLE_LOG) { if(LOG_ENABLED(INFO)) {
ULOG(INFO, this) << "HTTP parse failure: " ULOG(INFO, this) << "HTTP parse failure: "
<< "(" << http_errno_name(htperr) << ") " << "(" << http_errno_name(htperr) << ") "
<< http_errno_description(htperr); << http_errno_description(htperr);
@ -454,16 +454,16 @@ void https_downstream_eventcb(bufferevent *bev, short events, void *ptr)
HttpsUpstream *upstream; HttpsUpstream *upstream;
upstream = static_cast<HttpsUpstream*>(downstream->get_upstream()); upstream = static_cast<HttpsUpstream*>(downstream->get_upstream());
if(events & BEV_EVENT_CONNECTED) { if(events & BEV_EVENT_CONNECTED) {
if(ENABLE_LOG) { if(LOG_ENABLED(INFO)) {
DCLOG(INFO, dconn) << "Connection established"; DCLOG(INFO, dconn) << "Connection established";
} }
} else if(events & BEV_EVENT_EOF) { } else if(events & BEV_EVENT_EOF) {
if(ENABLE_LOG) { if(LOG_ENABLED(INFO)) {
DCLOG(INFO, dconn) << "EOF"; DCLOG(INFO, dconn) << "EOF";
} }
if(downstream->get_response_state() == Downstream::HEADER_COMPLETE) { if(downstream->get_response_state() == Downstream::HEADER_COMPLETE) {
// Server may indicate the end of the request by EOF // Server may indicate the end of the request by EOF
if(ENABLE_LOG) { if(LOG_ENABLED(INFO)) {
DCLOG(INFO, dconn) << "The end of the response body was indicated by " DCLOG(INFO, dconn) << "The end of the response body was indicated by "
<< "EOF"; << "EOF";
} }
@ -483,7 +483,7 @@ void https_downstream_eventcb(bufferevent *bev, short events, void *ptr)
// Nothing to do // Nothing to do
} else { } else {
// error // error
if(ENABLE_LOG) { if(LOG_ENABLED(INFO)) {
DCLOG(INFO, dconn) << "Treated as error"; DCLOG(INFO, dconn) << "Treated as error";
} }
if(upstream->error_reply(502) != 0) { if(upstream->error_reply(502) != 0) {
@ -496,7 +496,7 @@ void https_downstream_eventcb(bufferevent *bev, short events, void *ptr)
upstream->resume_read(SHRPX_MSG_BLOCK); upstream->resume_read(SHRPX_MSG_BLOCK);
} }
} else if(events & (BEV_EVENT_ERROR | BEV_EVENT_TIMEOUT)) { } else if(events & (BEV_EVENT_ERROR | BEV_EVENT_TIMEOUT)) {
if(ENABLE_LOG) { if(LOG_ENABLED(INFO)) {
if(events & BEV_EVENT_ERROR) { if(events & BEV_EVENT_ERROR) {
DCLOG(INFO, dconn) << "Network error"; DCLOG(INFO, dconn) << "Network error";
} else { } else {
@ -590,7 +590,7 @@ Downstream* HttpsUpstream::get_downstream() const
int HttpsUpstream::on_downstream_header_complete(Downstream *downstream) int HttpsUpstream::on_downstream_header_complete(Downstream *downstream)
{ {
if(ENABLE_LOG) { if(LOG_ENABLED(INFO)) {
DLOG(INFO, downstream) << "HTTP response header completed"; DLOG(INFO, downstream) << "HTTP response header completed";
} }
std::string via_value; std::string via_value;
@ -643,7 +643,7 @@ int HttpsUpstream::on_downstream_header_complete(Downstream *downstream)
} }
hdrs += "\r\n"; hdrs += "\r\n";
if(ENABLE_LOG) { if(LOG_ENABLED(INFO)) {
const char *hdrp; const char *hdrp;
std::string nhdrs; std::string nhdrs;
if(get_config()->tty) { if(get_config()->tty) {
@ -696,7 +696,7 @@ int HttpsUpstream::on_downstream_body_complete(Downstream *downstream)
return -1; return -1;
} }
} }
if(ENABLE_LOG) { if(LOG_ENABLED(INFO)) {
DLOG(INFO, downstream) << "HTTP response completed"; DLOG(INFO, downstream) << "HTTP response completed";
} }
if(downstream->get_request_connection_close() || if(downstream->get_request_connection_close() ||

4
src/shrpx_listen_handler.cc
View File

@ -81,7 +81,7 @@ void ListenHandler::create_worker_thread(size_t num)
bufferevent *bev = bufferevent_socket_new(evbase_, info->sv[0], bufferevent *bev = bufferevent_socket_new(evbase_, info->sv[0],
BEV_OPT_DEFER_CALLBACKS); BEV_OPT_DEFER_CALLBACKS);
info->bev = bev; info->bev = bev;
if(ENABLE_LOG) { if(LOG_ENABLED(INFO)) {
LLOG(INFO, this) << "Created thread #" << num_worker_; LLOG(INFO, this) << "Created thread #" << num_worker_;
} }
++num_worker_; ++num_worker_;
@ -91,7 +91,7 @@ void ListenHandler::create_worker_thread(size_t num)
int ListenHandler::accept_connection(evutil_socket_t fd, int ListenHandler::accept_connection(evutil_socket_t fd,
sockaddr *addr, int addrlen) sockaddr *addr, int addrlen)
{ {
if(ENABLE_LOG) { if(LOG_ENABLED(INFO)) {
LLOG(INFO, this) << "Accepted connection. fd=" << fd; LLOG(INFO, this) << "Accepted connection. fd=" << fd;
} }
if(num_worker_ == 0) { if(num_worker_ == 0) {

2
src/shrpx_log.cc
View File

@ -90,7 +90,7 @@ Log::Log(int severity, const char *filename, int linenum)
Log::~Log() Log::~Log()
{ {
if(severity_ >= severity_thres_) { if(log_enabled(severity_)) {
fprintf(stderr, "[%s%s%s] %s\n %s(%s:%d)%s\n", fprintf(stderr, "[%s%s%s] %s\n %s(%s:%d)%s\n",
get_config()->tty ? SEVERITY_COLOR[severity_] : "", get_config()->tty ? SEVERITY_COLOR[severity_] : "",
SEVERITY_STR[severity_], SEVERITY_STR[severity_],

6
src/shrpx_log.h
View File

@ -33,6 +33,8 @@ namespace shrpx {
#define ENABLE_LOG 1 #define ENABLE_LOG 1
#define LOG_ENABLED(SEVERITY) (ENABLE_LOG && Log::log_enabled(SEVERITY))
#define LOG(SEVERITY) Log(SEVERITY, __FILE__, __LINE__) #define LOG(SEVERITY) Log(SEVERITY, __FILE__, __LINE__)
// Listener log // Listener log
@ -81,6 +83,10 @@ public:
} }
static void set_severity_level(int severity); static void set_severity_level(int severity);
static int set_severity_level_by_name(const char *name); static int set_severity_level_by_name(const char *name);
static bool log_enabled(int severity)
{
return severity >= severity_thres_;
}
private: private:
int severity_; int severity_;
const char *filename_; const char *filename_;

6
src/shrpx_spdy_downstream_connection.cc
View File

@ -89,7 +89,7 @@ int SpdyDownstreamConnection::init_request_body_buf()
int SpdyDownstreamConnection::attach_downstream(Downstream *downstream) int SpdyDownstreamConnection::attach_downstream(Downstream *downstream)
{ {
if(ENABLE_LOG) { if(LOG_ENABLED(INFO)) {
DCLOG(INFO, this) << "Attaching to DOWNSTREAM:" << downstream; DCLOG(INFO, this) << "Attaching to DOWNSTREAM:" << downstream;
} }
if(init_request_body_buf() == -1) { if(init_request_body_buf() == -1) {
@ -107,7 +107,7 @@ int SpdyDownstreamConnection::attach_downstream(Downstream *downstream)
void SpdyDownstreamConnection::detach_downstream(Downstream *downstream) void SpdyDownstreamConnection::detach_downstream(Downstream *downstream)
{ {
if(ENABLE_LOG) { if(LOG_ENABLED(INFO)) {
DCLOG(INFO, this) << "Detaching from DOWNSTREAM:" << downstream; DCLOG(INFO, this) << "Detaching from DOWNSTREAM:" << downstream;
} }
downstream->set_downstream_connection(0); downstream->set_downstream_connection(0);
@ -293,7 +293,7 @@ int SpdyDownstreamConnection::push_request_headers()
nv[hdidx++] = via_value.c_str(); nv[hdidx++] = via_value.c_str();
} }
nv[hdidx++] = 0; nv[hdidx++] = 0;
if(ENABLE_LOG) { if(LOG_ENABLED(INFO)) {
std::stringstream ss; std::stringstream ss;
for(size_t i = 0; nv[i]; i += 2) { for(size_t i = 0; nv[i]; i += 2) {
ss << TTY_HTTP_HD << nv[i] << TTY_RST << ": " << nv[i+1] << "\n"; ss << TTY_HTTP_HD << nv[i] << TTY_RST << ": " << nv[i+1] << "\n";

28
src/shrpx_spdy_session.cc
View File

@ -65,7 +65,7 @@ SpdySession::~SpdySession()
int SpdySession::disconnect() int SpdySession::disconnect()
{ {
if(ENABLE_LOG) { if(LOG_ENABLED(INFO)) {
SSLOG(INFO, this) << "Disconnecting"; SSLOG(INFO, this) << "Disconnecting";
} }
spdylay_session_del(session_); spdylay_session_del(session_);
@ -217,7 +217,7 @@ void eventcb(bufferevent *bev, short events, void *ptr)
{ {
SpdySession *spdy = reinterpret_cast<SpdySession*>(ptr); SpdySession *spdy = reinterpret_cast<SpdySession*>(ptr);
if(events & BEV_EVENT_CONNECTED) { if(events & BEV_EVENT_CONNECTED) {
if(ENABLE_LOG) { if(LOG_ENABLED(INFO)) {
SSLOG(INFO, spdy) << "Connection established"; SSLOG(INFO, spdy) << "Connection established";
} }
spdy->connected(); spdy->connected();
@ -231,12 +231,12 @@ void eventcb(bufferevent *bev, short events, void *ptr)
setsockopt(fd, IPPROTO_TCP, TCP_NODELAY, setsockopt(fd, IPPROTO_TCP, TCP_NODELAY,
reinterpret_cast<char *>(&val), sizeof(val)); reinterpret_cast<char *>(&val), sizeof(val));
} else if(events & BEV_EVENT_EOF) { } else if(events & BEV_EVENT_EOF) {
if(ENABLE_LOG) { if(LOG_ENABLED(INFO)) {
SSLOG(INFO, spdy) << "EOF"; SSLOG(INFO, spdy) << "EOF";
} }
spdy->disconnect(); spdy->disconnect();
} else if(events & (BEV_EVENT_ERROR | BEV_EVENT_TIMEOUT)) { } else if(events & (BEV_EVENT_ERROR | BEV_EVENT_TIMEOUT)) {
if(ENABLE_LOG) { if(LOG_ENABLED(INFO)) {
if(events & BEV_EVENT_ERROR) { if(events & BEV_EVENT_ERROR) {
SSLOG(INFO, spdy) << "Network error"; SSLOG(INFO, spdy) << "Network error";
} else { } else {
@ -257,7 +257,7 @@ int SpdySession::initiate_connection()
{ {
int rv; int rv;
assert(state_ == DISCONNECTED); assert(state_ == DISCONNECTED);
if(ENABLE_LOG) { if(LOG_ENABLED(INFO)) {
SSLOG(INFO, this) << "Connecting to downstream server"; SSLOG(INFO, this) << "Connecting to downstream server";
} }
@ -461,7 +461,7 @@ void on_stream_close_callback
{ {
int rv; int rv;
SpdySession *spdy = reinterpret_cast<SpdySession*>(user_data); SpdySession *spdy = reinterpret_cast<SpdySession*>(user_data);
if(ENABLE_LOG) { if(LOG_ENABLED(INFO)) {
SSLOG(INFO, spdy) << "Stream stream_id=" << stream_id SSLOG(INFO, spdy) << "Stream stream_id=" << stream_id
<< " is being closed"; << " is being closed";
} }
@ -507,7 +507,7 @@ void on_ctrl_recv_callback
Downstream *downstream; Downstream *downstream;
switch(type) { switch(type) {
case SPDYLAY_SYN_STREAM: case SPDYLAY_SYN_STREAM:
if(ENABLE_LOG) { if(LOG_ENABLED(INFO)) {
SSLOG(INFO, spdy) << "Received upstream SYN_STREAM stream_id=" SSLOG(INFO, spdy) << "Received upstream SYN_STREAM stream_id="
<< frame->syn_stream.stream_id; << frame->syn_stream.stream_id;
} }
@ -594,7 +594,7 @@ void on_ctrl_recv_callback
} }
} }
if(ENABLE_LOG) { if(LOG_ENABLED(INFO)) {
std::stringstream ss; std::stringstream ss;
for(size_t i = 0; nv[i]; i += 2) { for(size_t i = 0; nv[i]; i += 2) {
ss << TTY_HTTP_HD << nv[i] << TTY_RST << ": " << nv[i+1] << "\n"; ss << TTY_HTTP_HD << nv[i] << TTY_RST << ": " << nv[i+1] << "\n";
@ -645,7 +645,7 @@ void on_data_chunk_recv_callback(spdylay_session *session,
if(spdy->get_flow_control()) { if(spdy->get_flow_control()) {
sd->dconn->inc_recv_window_size(len); sd->dconn->inc_recv_window_size(len);
if(sd->dconn->get_recv_window_size() > spdy->get_initial_window_size()) { if(sd->dconn->get_recv_window_size() > spdy->get_initial_window_size()) {
if(ENABLE_LOG) { if(LOG_ENABLED(INFO)) {
SSLOG(INFO, spdy) << "Flow control error: recv_window_size=" SSLOG(INFO, spdy) << "Flow control error: recv_window_size="
<< sd->dconn->get_recv_window_size() << sd->dconn->get_recv_window_size()
<< ", initial_window_size=" << ", initial_window_size="
@ -740,7 +740,7 @@ void on_ctrl_recv_parse_error_callback(spdylay_session *session,
void *user_data) void *user_data)
{ {
SpdySession *spdy = reinterpret_cast<SpdySession*>(user_data); SpdySession *spdy = reinterpret_cast<SpdySession*>(user_data);
if(ENABLE_LOG) { if(LOG_ENABLED(INFO)) {
SSLOG(INFO, spdy) << "Failed to parse received control frame. type=" SSLOG(INFO, spdy) << "Failed to parse received control frame. type="
<< type << type
<< ", error_code=" << error_code << ":" << ", error_code=" << error_code << ":"
@ -756,7 +756,7 @@ void on_unknown_ctrl_recv_callback(spdylay_session *session,
void *user_data) void *user_data)
{ {
SpdySession *spdy = reinterpret_cast<SpdySession*>(user_data); SpdySession *spdy = reinterpret_cast<SpdySession*>(user_data);
if(ENABLE_LOG) { if(LOG_ENABLED(INFO)) {
SSLOG(INFO, spdy) << "Received unknown control frame"; SSLOG(INFO, spdy) << "Received unknown control frame";
} }
} }
@ -769,7 +769,7 @@ int SpdySession::on_connect()
unsigned int next_proto_len; unsigned int next_proto_len;
SSL_get0_next_proto_negotiated(ssl_, &next_proto, &next_proto_len); SSL_get0_next_proto_negotiated(ssl_, &next_proto, &next_proto_len);
if(ENABLE_LOG) { if(LOG_ENABLED(INFO)) {
std::string proto(next_proto, next_proto+next_proto_len); std::string proto(next_proto, next_proto+next_proto_len);
SSLOG(INFO, this) << "Negotiated next protocol: " << proto; SSLOG(INFO, this) << "Negotiated next protocol: " << proto;
} }
@ -851,7 +851,7 @@ int SpdySession::on_read()
if(rv == 0) { if(rv == 0) {
if(spdylay_session_want_read(session_) == 0 && if(spdylay_session_want_read(session_) == 0 &&
spdylay_session_want_write(session_) == 0) { spdylay_session_want_write(session_) == 0) {
if(ENABLE_LOG) { if(LOG_ENABLED(INFO)) {
SSLOG(INFO, this) << "No more read/write for this session"; SSLOG(INFO, this) << "No more read/write for this session";
} }
rv = -1; rv = -1;
@ -875,7 +875,7 @@ int SpdySession::send()
if(rv == 0) { if(rv == 0) {
if(spdylay_session_want_read(session_) == 0 && if(spdylay_session_want_read(session_) == 0 &&
spdylay_session_want_write(session_) == 0) { spdylay_session_want_write(session_) == 0) {
if(ENABLE_LOG) { if(LOG_ENABLED(INFO)) {
SSLOG(INFO, this) << "No more read/write for this session"; SSLOG(INFO, this) << "No more read/write for this session";
} }
rv = -1; rv = -1;

34
src/shrpx_spdy_upstream.cc
View File

@ -95,7 +95,7 @@ void on_stream_close_callback
void *user_data) void *user_data)
{ {
SpdyUpstream *upstream = reinterpret_cast<SpdyUpstream*>(user_data); SpdyUpstream *upstream = reinterpret_cast<SpdyUpstream*>(user_data);
if(ENABLE_LOG) { if(LOG_ENABLED(INFO)) {
ULOG(INFO, upstream) << "Stream stream_id=" << stream_id ULOG(INFO, upstream) << "Stream stream_id=" << stream_id
<< " is being closed"; << " is being closed";
} }
@ -143,7 +143,7 @@ void on_ctrl_recv_callback
SpdyUpstream *upstream = reinterpret_cast<SpdyUpstream*>(user_data); SpdyUpstream *upstream = reinterpret_cast<SpdyUpstream*>(user_data);
switch(type) { switch(type) {
case SPDYLAY_SYN_STREAM: { case SPDYLAY_SYN_STREAM: {
if(ENABLE_LOG) { if(LOG_ENABLED(INFO)) {
ULOG(INFO, upstream) << "Received upstream SYN_STREAM stream_id=" ULOG(INFO, upstream) << "Received upstream SYN_STREAM stream_id="
<< frame->syn_stream.stream_id; << frame->syn_stream.stream_id;
} }
@ -192,7 +192,7 @@ void on_ctrl_recv_callback
downstream->add_request_header("X-Forwarded-Spdy", "true"); downstream->add_request_header("X-Forwarded-Spdy", "true");
} }
if(ENABLE_LOG) { if(LOG_ENABLED(INFO)) {
std::stringstream ss; std::stringstream ss;
for(size_t i = 0; nv[i]; i += 2) { for(size_t i = 0; nv[i]; i += 2) {
ss << TTY_HTTP_HD << nv[i] << TTY_RST << ": " << nv[i+1] << "\n"; ss << TTY_HTTP_HD << nv[i] << TTY_RST << ": " << nv[i+1] << "\n";
@ -245,7 +245,7 @@ void on_data_chunk_recv_callback(spdylay_session *session,
downstream->inc_recv_window_size(len); downstream->inc_recv_window_size(len);
if(downstream->get_recv_window_size() > if(downstream->get_recv_window_size() >
upstream->get_initial_window_size()) { upstream->get_initial_window_size()) {
if(ENABLE_LOG) { if(LOG_ENABLED(INFO)) {
ULOG(INFO, upstream) << "Flow control error: recv_window_size=" ULOG(INFO, upstream) << "Flow control error: recv_window_size="
<< downstream->get_recv_window_size() << downstream->get_recv_window_size()
<< ", initial_window_size=" << ", initial_window_size="
@ -292,7 +292,7 @@ void on_ctrl_recv_parse_error_callback(spdylay_session *session,
void *user_data) void *user_data)
{ {
SpdyUpstream *upstream = reinterpret_cast<SpdyUpstream*>(user_data); SpdyUpstream *upstream = reinterpret_cast<SpdyUpstream*>(user_data);
if(ENABLE_LOG) { if(LOG_ENABLED(INFO)) {
ULOG(INFO, upstream) << "Failed to parse received control frame. type=" ULOG(INFO, upstream) << "Failed to parse received control frame. type="
<< type << type
<< ", error_code=" << error_code << ":" << ", error_code=" << error_code << ":"
@ -308,7 +308,7 @@ void on_unknown_ctrl_recv_callback(spdylay_session *session,
void *user_data) void *user_data)
{ {
SpdyUpstream *upstream = reinterpret_cast<SpdyUpstream*>(user_data); SpdyUpstream *upstream = reinterpret_cast<SpdyUpstream*>(user_data);
if(ENABLE_LOG) { if(LOG_ENABLED(INFO)) {
ULOG(INFO, upstream) << "Received unknown control frame."; ULOG(INFO, upstream) << "Received unknown control frame.";
} }
} }
@ -388,7 +388,7 @@ int SpdyUpstream::on_read()
if(rv == 0) { if(rv == 0) {
if(spdylay_session_want_read(session_) == 0 && if(spdylay_session_want_read(session_) == 0 &&
spdylay_session_want_write(session_) == 0) { spdylay_session_want_write(session_) == 0) {
if(ENABLE_LOG) { if(LOG_ENABLED(INFO)) {
ULOG(INFO, this) << "No more read/write for this SPDY session"; ULOG(INFO, this) << "No more read/write for this SPDY session";
} }
rv = -1; rv = -1;
@ -413,7 +413,7 @@ int SpdyUpstream::send()
if(rv == 0) { if(rv == 0) {
if(spdylay_session_want_read(session_) == 0 && if(spdylay_session_want_read(session_) == 0 &&
spdylay_session_want_write(session_) == 0) { spdylay_session_want_write(session_) == 0) {
if(ENABLE_LOG) { if(LOG_ENABLED(INFO)) {
ULOG(INFO, this) << "No more read/write for this SPDY session"; ULOG(INFO, this) << "No more read/write for this SPDY session";
} }
rv = -1; rv = -1;
@ -449,7 +449,7 @@ void spdy_downstream_readcb(bufferevent *bev, void *ptr)
} }
int rv = downstream->on_read(); int rv = downstream->on_read();
if(rv != 0) { if(rv != 0) {
if(ENABLE_LOG) { if(LOG_ENABLED(INFO)) {
DCLOG(INFO, dconn) << "HTTP parser failure"; DCLOG(INFO, dconn) << "HTTP parser failure";
} }
if(downstream->get_response_state() == Downstream::HEADER_COMPLETE) { if(downstream->get_response_state() == Downstream::HEADER_COMPLETE) {
@ -502,7 +502,7 @@ void spdy_downstream_eventcb(bufferevent *bev, short events, void *ptr)
SpdyUpstream *upstream; SpdyUpstream *upstream;
upstream = static_cast<SpdyUpstream*>(downstream->get_upstream()); upstream = static_cast<SpdyUpstream*>(downstream->get_upstream());
if(events & BEV_EVENT_CONNECTED) { if(events & BEV_EVENT_CONNECTED) {
if(ENABLE_LOG) { if(LOG_ENABLED(INFO)) {
DCLOG(INFO, dconn) << "Connection established. stream_id=" DCLOG(INFO, dconn) << "Connection established. stream_id="
<< downstream->get_stream_id(); << downstream->get_stream_id();
} }
@ -511,7 +511,7 @@ void spdy_downstream_eventcb(bufferevent *bev, short events, void *ptr)
setsockopt(fd, IPPROTO_TCP, TCP_NODELAY, setsockopt(fd, IPPROTO_TCP, TCP_NODELAY,
reinterpret_cast<char *>(&val), sizeof(val)); reinterpret_cast<char *>(&val), sizeof(val));
} else if(events & BEV_EVENT_EOF) { } else if(events & BEV_EVENT_EOF) {
if(ENABLE_LOG) { if(LOG_ENABLED(INFO)) {
DCLOG(INFO, dconn) << "EOF. stream_id=" << downstream->get_stream_id(); DCLOG(INFO, dconn) << "EOF. stream_id=" << downstream->get_stream_id();
} }
if(downstream->get_request_state() == Downstream::STREAM_CLOSED) { if(downstream->get_request_state() == Downstream::STREAM_CLOSED) {
@ -528,7 +528,7 @@ void spdy_downstream_eventcb(bufferevent *bev, short events, void *ptr)
// downstream wil be deleted in on_stream_close_callback. // downstream wil be deleted in on_stream_close_callback.
if(downstream->get_response_state() == Downstream::HEADER_COMPLETE) { if(downstream->get_response_state() == Downstream::HEADER_COMPLETE) {
// Server may indicate the end of the request by EOF // Server may indicate the end of the request by EOF
if(ENABLE_LOG) { if(LOG_ENABLED(INFO)) {
ULOG(INFO, upstream) << "Downstream body was ended by EOF"; ULOG(INFO, upstream) << "Downstream body was ended by EOF";
} }
downstream->set_response_state(Downstream::MSG_COMPLETE); downstream->set_response_state(Downstream::MSG_COMPLETE);
@ -556,7 +556,7 @@ void spdy_downstream_eventcb(bufferevent *bev, short events, void *ptr)
// At this point, downstream may be deleted. // At this point, downstream may be deleted.
} }
} else if(events & (BEV_EVENT_ERROR | BEV_EVENT_TIMEOUT)) { } else if(events & (BEV_EVENT_ERROR | BEV_EVENT_TIMEOUT)) {
if(ENABLE_LOG) { if(LOG_ENABLED(INFO)) {
if(events & BEV_EVENT_ERROR) { if(events & BEV_EVENT_ERROR) {
DCLOG(INFO, dconn) << "Downstream network error: " DCLOG(INFO, dconn) << "Downstream network error: "
<< evutil_socket_error_to_string << evutil_socket_error_to_string
@ -609,7 +609,7 @@ void spdy_downstream_eventcb(bufferevent *bev, short events, void *ptr)
int SpdyUpstream::rst_stream(Downstream *downstream, int status_code) int SpdyUpstream::rst_stream(Downstream *downstream, int status_code)
{ {
if(ENABLE_LOG) { if(LOG_ENABLED(INFO)) {
ULOG(INFO, this) << "RST_STREAM stream_id=" ULOG(INFO, this) << "RST_STREAM stream_id="
<< downstream->get_stream_id(); << downstream->get_stream_id();
} }
@ -744,7 +744,7 @@ spdylay_session* SpdyUpstream::get_spdy_session()
// spdylay_session_recv. These calls may delete downstream. // spdylay_session_recv. These calls may delete downstream.
int SpdyUpstream::on_downstream_header_complete(Downstream *downstream) int SpdyUpstream::on_downstream_header_complete(Downstream *downstream)
{ {
if(ENABLE_LOG) { if(LOG_ENABLED(INFO)) {
DLOG(INFO, downstream) << "HTTP response header completed"; DLOG(INFO, downstream) << "HTTP response header completed";
} }
size_t nheader = downstream->get_response_headers().size(); size_t nheader = downstream->get_response_headers().size();
@ -781,7 +781,7 @@ int SpdyUpstream::on_downstream_header_complete(Downstream *downstream)
nv[hdidx++] = via_value.c_str(); nv[hdidx++] = via_value.c_str();
} }
nv[hdidx++] = 0; nv[hdidx++] = 0;
if(ENABLE_LOG) { if(LOG_ENABLED(INFO)) {
std::stringstream ss; std::stringstream ss;
for(size_t i = 0; nv[i]; i += 2) { for(size_t i = 0; nv[i]; i += 2) {
ss << TTY_HTTP_HD << nv[i] << TTY_RST << ": " << nv[i+1] << "\n"; ss << TTY_HTTP_HD << nv[i] << TTY_RST << ": " << nv[i+1] << "\n";
@ -835,7 +835,7 @@ int SpdyUpstream::on_downstream_body(Downstream *downstream,
// spdylay_session_recv. These calls may delete downstream. // spdylay_session_recv. These calls may delete downstream.
int SpdyUpstream::on_downstream_body_complete(Downstream *downstream) int SpdyUpstream::on_downstream_body_complete(Downstream *downstream)
{ {
if(ENABLE_LOG) { if(LOG_ENABLED(INFO)) {
DLOG(INFO, downstream) << "HTTP response completed"; DLOG(INFO, downstream) << "HTTP response completed";
} }
spdylay_session_resume_data(session_, downstream->get_stream_id()); spdylay_session_resume_data(session_, downstream->get_stream_id());

6
src/shrpx_thread_event_receiver.cc
View File

@ -47,7 +47,7 @@ void ThreadEventReceiver::on_read(bufferevent *bev)
while(evbuffer_get_length(input) >= sizeof(WorkerEvent)) { while(evbuffer_get_length(input) >= sizeof(WorkerEvent)) {
WorkerEvent wev; WorkerEvent wev;
evbuffer_remove(input, &wev, sizeof(WorkerEvent)); evbuffer_remove(input, &wev, sizeof(WorkerEvent));
if(ENABLE_LOG) { if(LOG_ENABLED(INFO)) {
TLOG(INFO, this) << "WorkerEvent: client_fd=" << wev.client_fd TLOG(INFO, this) << "WorkerEvent: client_fd=" << wev.client_fd
<< ", addrlen=" << wev.client_addrlen; << ", addrlen=" << wev.client_addrlen;
} }
@ -59,11 +59,11 @@ void ThreadEventReceiver::on_read(bufferevent *bev)
wev.client_addrlen); wev.client_addrlen);
if(client_handler) { if(client_handler) {
client_handler->set_spdy_session(spdy_); client_handler->set_spdy_session(spdy_);
if(ENABLE_LOG) { if(LOG_ENABLED(INFO)) {
TLOG(INFO, this) << "CLIENT_HANDLER:" << client_handler << " created"; TLOG(INFO, this) << "CLIENT_HANDLER:" << client_handler << " created";
} }
} else { } else {
if(ENABLE_LOG) { if(LOG_ENABLED(INFO)) {
TLOG(ERROR, this) << "ClientHandler creation failed"; TLOG(ERROR, this) << "ClientHandler creation failed";
} }
close(wev.client_fd); close(wev.client_fd);