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

shrpx: Log format change 

Added macros which log messages from the following components are
prefixed with their component name + object pointer address:

ListenHandler: LISTEN
ThreadEventReceiver: THREAD_RECV
Upstream: UPSTREAM
Downstream: DOWNSTREAM
DownstreamConnection: DCONN
SpdySession: DSPDY
This commit is contained in:
Tatsuhiro Tsujikawa 2012-12-09 19:15:14 +09:00
parent 4d0db62f1d
commit bbf6c18575
10 changed files with 235 additions and 201 deletions
Show Stats Download Patch File Download Diff File Expand all files Collapse all files

40
src/shrpx_client_handler.cc
View File

@ -43,7 +43,7 @@ void upstream_readcb(bufferevent *bev, void *arg)
ClientHandler *handler = reinterpret_cast<ClientHandler*>(arg); ClientHandler *handler = reinterpret_cast<ClientHandler*>(arg);
int rv = handler->on_read(); int rv = handler->on_read();
if(rv != 0) { if(rv != 0) {
LOG(WARNING) << "<upstream> Read operation (application level) failure"; CLOG(WARNING, handler) << "Read operation (application level) failure";
delete handler; delete handler;
} }
} }
@ -65,7 +65,7 @@ void upstream_writecb(bufferevent *bev, void *arg)
Upstream *upstream = handler->get_upstream(); Upstream *upstream = handler->get_upstream();
int rv = upstream->on_write(); int rv = upstream->on_write();
if(rv != 0) { if(rv != 0) {
LOG(WARNING) << "<upstream> Write operation (application level) failure"; CLOG(WARNING, handler) << "Write operation (application level) failure";
delete handler; delete handler;
} }
} }
@ -79,20 +79,21 @@ void upstream_eventcb(bufferevent *bev, short events, void *arg)
bool finish = false; bool finish = false;
if(events & BEV_EVENT_EOF) { if(events & BEV_EVENT_EOF) {
if(ENABLE_LOG) { if(ENABLE_LOG) {
LOG(INFO) << "Upstream EOF"; CLOG(INFO, handler) << "EOF";
} }
finish = true; finish = true;
} }
if(events & BEV_EVENT_ERROR) { if(events & BEV_EVENT_ERROR) {
if(ENABLE_LOG) { if(ENABLE_LOG) {
LOG(INFO) << "Upstream network error: " CLOG(INFO, handler) << "Network error: "
<< evutil_socket_error_to_string(EVUTIL_SOCKET_ERROR()); << evutil_socket_error_to_string
(EVUTIL_SOCKET_ERROR());
} }
finish = true; finish = true;
} }
if(events & BEV_EVENT_TIMEOUT) { if(events & BEV_EVENT_TIMEOUT) {
if(ENABLE_LOG) { if(ENABLE_LOG) {
LOG(INFO) << "Upstream time out"; CLOG(INFO, handler) << "Time out";
} }
finish = true; finish = true;
} }
@ -101,13 +102,13 @@ void upstream_eventcb(bufferevent *bev, short events, void *arg)
} else { } else {
if(events & BEV_EVENT_CONNECTED) { if(events & BEV_EVENT_CONNECTED) {
if(ENABLE_LOG) { if(ENABLE_LOG) {
LOG(INFO) << "Upstream connected. handler " << handler; 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(ENABLE_LOG) {
if(SSL_session_reused(handler->get_ssl())) { if(SSL_session_reused(handler->get_ssl())) {
LOG(INFO) << "SSL/TLS session reused"; CLOG(INFO, handler) << "SSL/TLS session reused";
} }
} }
// At this point, input buffer is already filled with some // At this point, input buffer is already filled with some
@ -145,7 +146,7 @@ ClientHandler::ClientHandler(bufferevent *bev, int fd, SSL *ssl,
ClientHandler::~ClientHandler() ClientHandler::~ClientHandler()
{ {
if(ENABLE_LOG) { if(ENABLE_LOG) {
LOG(INFO) << "Deleting ClientHandler " << this; CLOG(INFO, this) << "Deleting";
} }
if(ssl_) { if(ssl_) {
SSL_shutdown(ssl_); SSL_shutdown(ssl_);
@ -163,7 +164,7 @@ ClientHandler::~ClientHandler()
delete *i; delete *i;
} }
if(ENABLE_LOG) { if(ENABLE_LOG) {
LOG(INFO) << "Deleted"; CLOG(INFO, this) << "Deleted";
} }
} }
@ -203,7 +204,7 @@ int ClientHandler::validate_next_proto()
if(next_proto) { if(next_proto) {
if(ENABLE_LOG) { if(ENABLE_LOG) {
std::string proto(next_proto, next_proto+next_proto_len); std::string proto(next_proto, next_proto+next_proto_len);
LOG(INFO) << "Upstream negotiated next protocol: " << proto; CLOG(INFO, this) << "The negotiated next protocol: " << proto;
} }
uint16_t version = spdylay_npn_get_version(next_proto, next_proto_len); uint16_t version = spdylay_npn_get_version(next_proto, next_proto_len);
if(version) { if(version) {
@ -213,11 +214,11 @@ int ClientHandler::validate_next_proto()
} }
} else { } else {
if(ENABLE_LOG) { if(ENABLE_LOG) {
LOG(INFO) << "No proto negotiated."; CLOG(INFO, this) << "No proto negotiated.";
} }
} }
if(ENABLE_LOG) { if(ENABLE_LOG) {
LOG(INFO) << "Use HTTP/1.1"; CLOG(INFO, this) << "Use HTTP/1.1";
} }
HttpsUpstream *https_upstream = new HttpsUpstream(this); HttpsUpstream *https_upstream = new HttpsUpstream(this);
upstream_ = https_upstream; upstream_ = https_upstream;
@ -252,7 +253,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(ENABLE_LOG) {
LOG(INFO) << "Pooling downstream connection " << dconn; CLOG(INFO, this) << "Pooling downstream connection DCONN:" << dconn;
} }
dconn_pool_.insert(dconn); dconn_pool_.insert(dconn);
} }
@ -260,8 +261,8 @@ 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(ENABLE_LOG) {
LOG(INFO) << "Removing downstream connection " << dconn CLOG(INFO, this) << "Removing downstream connection DCONN:" << dconn
<< " from pool"; << " from pool";
} }
dconn_pool_.erase(dconn); dconn_pool_.erase(dconn);
} }
@ -270,7 +271,8 @@ DownstreamConnection* ClientHandler::get_downstream_connection()
{ {
if(dconn_pool_.empty()) { if(dconn_pool_.empty()) {
if(ENABLE_LOG) { if(ENABLE_LOG) {
LOG(INFO) << "Downstream connection pool is empty. Create new one"; CLOG(INFO, this) << "Downstream connection pool is empty."
<< " Create new one";
} }
if(get_config()->client_mode) { if(get_config()->client_mode) {
return new SpdyDownstreamConnection(this); return new SpdyDownstreamConnection(this);
@ -281,8 +283,8 @@ DownstreamConnection* ClientHandler::get_downstream_connection()
DownstreamConnection *dconn = *dconn_pool_.begin(); DownstreamConnection *dconn = *dconn_pool_.begin();
dconn_pool_.erase(dconn); dconn_pool_.erase(dconn);
if(ENABLE_LOG) { if(ENABLE_LOG) {
LOG(INFO) << "Reuse downstream connection " << dconn CLOG(INFO, this) << "Reuse downstream connection DCONN:" << dconn
<< " from pool"; << " from pool";
} }
return dconn; return dconn;
} }

6
src/shrpx_downstream.cc
View File

@ -64,7 +64,7 @@ Downstream::Downstream(Upstream *upstream, int stream_id, int priority)
Downstream::~Downstream() Downstream::~Downstream()
{ {
if(ENABLE_LOG) { if(ENABLE_LOG) {
LOG(INFO) << "Deleting downstream " << this; DLOG(INFO, this) << "Deleting";
} }
if(response_body_buf_) { if(response_body_buf_) {
// Passing NULL to evbuffer_free() causes segmentation fault. // Passing NULL to evbuffer_free() causes segmentation fault.
@ -74,7 +74,7 @@ Downstream::~Downstream()
delete dconn_; delete dconn_;
} }
if(ENABLE_LOG) { if(ENABLE_LOG) {
LOG(INFO) << "Deleted"; DLOG(INFO, this) << "Deleted";
} }
} }
@ -300,7 +300,7 @@ int Downstream::push_upload_data_chunk(const uint8_t *data, size_t datalen)
// Assumes that request headers have already been pushed to output // Assumes that request headers have already been pushed to output
// buffer using push_request_headers(). // buffer using push_request_headers().
if(!dconn_) { if(!dconn_) {
LOG(WARNING) << "dconn_ is NULL"; DLOG(WARNING, this) << "dconn_ is NULL";
return 0; return 0;
} }
return dconn_->push_upload_data_chunk(data, datalen); return dconn_->push_upload_data_chunk(data, datalen);

34
src/shrpx_http_downstream_connection.cc
View File

@ -67,8 +67,7 @@ HttpDownstreamConnection::~HttpDownstreamConnection()
int HttpDownstreamConnection::attach_downstream(Downstream *downstream) int HttpDownstreamConnection::attach_downstream(Downstream *downstream)
{ {
if(ENABLE_LOG) { if(ENABLE_LOG) {
LOG(INFO) << "Attaching downstream connection " << this << " to " DCLOG(INFO, this) << "Attaching to DOWNSTREAM:" << downstream;
<< "downstream " << downstream;
} }
Upstream *upstream = downstream->get_upstream(); Upstream *upstream = downstream->get_upstream();
if(!bev_) { if(!bev_) {
@ -87,7 +86,7 @@ int HttpDownstreamConnection::attach_downstream(Downstream *downstream)
return SHRPX_ERR_NETWORK; return SHRPX_ERR_NETWORK;
} }
if(ENABLE_LOG) { if(ENABLE_LOG) {
LOG(INFO) << "Connecting to downstream server " << this; DCLOG(INFO, this) << "Connecting to downstream server";
} }
} }
downstream->set_downstream_connection(this); downstream->set_downstream_connection(this);
@ -183,8 +182,8 @@ int HttpDownstreamConnection::push_request_headers()
hdrs += "\r\n"; hdrs += "\r\n";
if(ENABLE_LOG) { if(ENABLE_LOG) {
LOG(INFO) << "Downstream request headers id=" DCLOG(INFO, this) << "HTTP request headers. stream_id="
<< downstream_->get_stream_id() << "\n" << hdrs; << downstream_->get_stream_id() << "\n" << hdrs;
} }
evbuffer *output = bufferevent_get_output(bev_); evbuffer *output = bufferevent_get_output(bev_);
int rv; int rv;
@ -220,20 +219,20 @@ int HttpDownstreamConnection::push_upload_data_chunk
res += rv; res += rv;
rv = evbuffer_add(output, chunk_size_hex, rv); rv = evbuffer_add(output, chunk_size_hex, rv);
if(rv == -1) { if(rv == -1) {
LOG(FATAL) << "evbuffer_add() failed"; DCLOG(FATAL, this) << "evbuffer_add() failed";
return -1; return -1;
} }
} }
rv = evbuffer_add(output, data, datalen); rv = evbuffer_add(output, data, datalen);
if(rv == -1) { if(rv == -1) {
LOG(FATAL) << "evbuffer_add() failed"; DCLOG(FATAL, this) << "evbuffer_add() failed";
return -1; return -1;
} }
res += rv; res += rv;
if(chunked) { if(chunked) {
rv = evbuffer_add(output, "\r\n", 2); rv = evbuffer_add(output, "\r\n", 2);
if(rv == -1) { if(rv == -1) {
LOG(FATAL) << "evbuffer_add() failed"; DCLOG(FATAL, this) << "evbuffer_add() failed";
return -1; return -1;
} }
res += 2; res += 2;
@ -246,7 +245,7 @@ int HttpDownstreamConnection::end_upload_data()
if(downstream_->get_chunked_request()) { if(downstream_->get_chunked_request()) {
evbuffer *output = bufferevent_get_output(bev_); evbuffer *output = bufferevent_get_output(bev_);
if(evbuffer_add(output, "0\r\n\r\n", 5) != 0) { if(evbuffer_add(output, "0\r\n\r\n", 5) != 0) {
LOG(FATAL) << "evbuffer_add() failed"; DCLOG(FATAL, this) << "evbuffer_add() failed";
return -1; return -1;
} }
} }
@ -263,21 +262,21 @@ void idle_eventcb(bufferevent *bev, short events, void *arg)
// 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(ENABLE_LOG) {
LOG(INFO) << "Idle downstream connected?" << dconn; DCLOG(INFO, dconn) << "Idle connection connected?";
} }
return; return;
} }
if(events & BEV_EVENT_EOF) { if(events & BEV_EVENT_EOF) {
if(ENABLE_LOG) { if(ENABLE_LOG) {
LOG(INFO) << "Idle downstream connection EOF " << dconn; DCLOG(INFO, dconn) << "Idle connection EOF";
} }
} else if(events & BEV_EVENT_TIMEOUT) { } else if(events & BEV_EVENT_TIMEOUT) {
if(ENABLE_LOG) { if(ENABLE_LOG) {
LOG(INFO) << "Idle downstream connection timeout " << dconn; DCLOG(INFO, dconn) << "Idle connection timeout";
} }
} else if(events & BEV_EVENT_ERROR) { } else if(events & BEV_EVENT_ERROR) {
if(ENABLE_LOG) { if(ENABLE_LOG) {
LOG(INFO) << "Idle downstream connection error " << dconn; DCLOG(INFO, dconn) << "Idle connection network error";
} }
} }
ClientHandler *client_handler = dconn->get_client_handler(); ClientHandler *client_handler = dconn->get_client_handler();
@ -289,8 +288,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(ENABLE_LOG) {
LOG(INFO) << "Detaching downstream connection " << this << " from " DCLOG(INFO, this) << "Detaching from DOWNSTREAM:" << downstream;
<< "downstream " << downstream;
} }
downstream->set_downstream_connection(0); downstream->set_downstream_connection(0);
downstream_ = 0; downstream_ = 0;
@ -434,9 +432,9 @@ int HttpDownstreamConnection::on_read()
return 0; return 0;
} else { } else {
if(ENABLE_LOG) { if(ENABLE_LOG) {
LOG(INFO) << "Downstream 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);
} }
return SHRPX_ERR_HTTP_PARSE; return SHRPX_ERR_HTTP_PARSE;
} }

58
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(ENABLE_LOG) {
LOG(INFO) << "Upstream http request start " << upstream; ULOG(INFO, upstream) << "HTTP request started";
} }
upstream->reset_current_header_length(); upstream->reset_current_header_length();
Downstream *downstream = new Downstream(upstream, 0, 0); Downstream *downstream = new Downstream(upstream, 0, 0);
@ -131,7 +131,7 @@ int htp_hdrs_completecb(http_parser *htp)
HttpsUpstream *upstream; HttpsUpstream *upstream;
upstream = reinterpret_cast<HttpsUpstream*>(htp->data); upstream = reinterpret_cast<HttpsUpstream*>(htp->data);
if(ENABLE_LOG) { if(ENABLE_LOG) {
LOG(INFO) << "Upstream http request headers complete " << upstream; ULOG(INFO, upstream) << "HTTP request headers completed";
} }
Downstream *downstream = upstream->get_downstream(); Downstream *downstream = upstream->get_downstream();
@ -151,7 +151,7 @@ int htp_hdrs_completecb(http_parser *htp)
for(size_t i = 0; i < headers.size(); ++i) { for(size_t i = 0; i < headers.size(); ++i) {
ss << headers[i].first << ": " << headers[i].second << "\n"; ss << headers[i].first << ": " << headers[i].second << "\n";
} }
LOG(INFO) << "Upstream http request headers\n" << ss.str(); ULOG(INFO, upstream) << "HTTP request headers\n" << ss.str();
} }
if(get_config()->client_proxy && if(get_config()->client_proxy &&
@ -176,7 +176,7 @@ int htp_hdrs_completecb(http_parser *htp)
static const char reply_100[] = "HTTP/1.1 100 Continue\r\n\r\n"; static const char reply_100[] = "HTTP/1.1 100 Continue\r\n\r\n";
if(bufferevent_write(upstream->get_client_handler()->get_bev(), if(bufferevent_write(upstream->get_client_handler()->get_bev(),
reply_100, sizeof(reply_100)-1) != 0) { reply_100, sizeof(reply_100)-1) != 0) {
LOG(FATAL) << "bufferevent_write() faild"; ULOG(FATAL, upstream) << "bufferevent_write() faild";
return -1; return -1;
} }
} }
@ -218,11 +218,11 @@ namespace {
int htp_msg_completecb(http_parser *htp) int htp_msg_completecb(http_parser *htp)
{ {
int rv; int rv;
if(ENABLE_LOG) {
LOG(INFO) << "Upstream http request complete";
}
HttpsUpstream *upstream; HttpsUpstream *upstream;
upstream = reinterpret_cast<HttpsUpstream*>(htp->data); upstream = reinterpret_cast<HttpsUpstream*>(htp->data);
if(ENABLE_LOG) {
ULOG(INFO, upstream) << "HTTP request completed";
}
Downstream *downstream = upstream->get_downstream(); Downstream *downstream = upstream->get_downstream();
downstream->set_request_state(Downstream::MSG_COMPLETE); downstream->set_request_state(Downstream::MSG_COMPLETE);
rv = downstream->end_upload_data(); rv = downstream->end_upload_data();
@ -294,8 +294,9 @@ int HttpsUpstream::on_read()
if(downstream) { if(downstream) {
if(downstream->get_request_state() == Downstream::INITIAL && if(downstream->get_request_state() == Downstream::INITIAL &&
current_header_length_ > SHRPX_HTTPS_MAX_HEADER_LENGTH) { current_header_length_ > SHRPX_HTTPS_MAX_HEADER_LENGTH) {
LOG(WARNING) << "Request Header too long:" << current_header_length_ ULOG(WARNING, this) << "Request Header too long:"
<< " bytes"; << current_header_length_
<< " bytes";
get_client_handler()->set_should_close_after_write(true); get_client_handler()->set_should_close_after_write(true);
pause_read(SHRPX_MSG_BLOCK); pause_read(SHRPX_MSG_BLOCK);
if(error_reply(400) != 0) { if(error_reply(400) != 0) {
@ -303,16 +304,16 @@ int HttpsUpstream::on_read()
} }
} else if(downstream->get_output_buffer_full()) { } else if(downstream->get_output_buffer_full()) {
if(ENABLE_LOG) { if(ENABLE_LOG) {
LOG(INFO) << "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(ENABLE_LOG) {
LOG(INFO) << "Upstream 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);
} }
get_client_handler()->set_should_close_after_write(true); get_client_handler()->set_should_close_after_write(true);
pause_read(SHRPX_MSG_BLOCK); pause_read(SHRPX_MSG_BLOCK);
@ -451,18 +452,17 @@ void https_downstream_eventcb(bufferevent *bev, short events, void *ptr)
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(ENABLE_LOG) {
LOG(INFO) << "Downstream connection established. downstream " DCLOG(INFO, dconn) << "Connection established";
<< downstream;
} }
} else if(events & BEV_EVENT_EOF) { } else if(events & BEV_EVENT_EOF) {
if(ENABLE_LOG) { if(ENABLE_LOG) {
LOG(INFO) << "Downstream EOF. stream_id=" DCLOG(INFO, dconn) << "EOF";
<< downstream->get_stream_id();
} }
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(ENABLE_LOG) {
LOG(INFO) << "Downstream body was ended by EOF"; DCLOG(INFO, dconn) << "The end of the response body was indicated by "
<< "EOF";
} }
upstream->on_downstream_body_complete(downstream); upstream->on_downstream_body_complete(downstream);
downstream->set_response_state(Downstream::MSG_COMPLETE); downstream->set_response_state(Downstream::MSG_COMPLETE);
@ -481,7 +481,7 @@ void https_downstream_eventcb(bufferevent *bev, short events, void *ptr)
} else { } else {
// error // error
if(ENABLE_LOG) { if(ENABLE_LOG) {
LOG(INFO) << "Treated as downstream error"; DCLOG(INFO, dconn) << "Treated as error";
} }
if(upstream->error_reply(502) != 0) { if(upstream->error_reply(502) != 0) {
delete upstream->get_client_handler(); delete upstream->get_client_handler();
@ -494,7 +494,11 @@ void https_downstream_eventcb(bufferevent *bev, short events, void *ptr)
} }
} else if(events & (BEV_EVENT_ERROR | BEV_EVENT_TIMEOUT)) { } else if(events & (BEV_EVENT_ERROR | BEV_EVENT_TIMEOUT)) {
if(ENABLE_LOG) { if(ENABLE_LOG) {
LOG(INFO) << "Downstream error/timeout. " << downstream; if(events & BEV_EVENT_ERROR) {
DCLOG(INFO, dconn) << "Network error";
} else {
DCLOG(INFO, dconn) << "Timeout";
}
} }
if(downstream->get_response_state() == Downstream::INITIAL) { if(downstream->get_response_state() == Downstream::INITIAL) {
int status; int status;
@ -532,7 +536,7 @@ int HttpsUpstream::error_reply(int status_code)
evbuffer *output = bufferevent_get_output(handler_->get_bev()); evbuffer *output = bufferevent_get_output(handler_->get_bev());
if(evbuffer_add(output, header.c_str(), header.size()) != 0 || if(evbuffer_add(output, header.c_str(), header.size()) != 0 ||
evbuffer_add(output, html.c_str(), html.size()) != 0) { evbuffer_add(output, html.c_str(), html.size()) != 0) {
LOG(FATAL) << "evbuffer_add() failed"; ULOG(FATAL, this) << "evbuffer_add() failed";
return -1; return -1;
} }
Downstream *downstream = get_downstream(); Downstream *downstream = get_downstream();
@ -577,7 +581,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(ENABLE_LOG) {
LOG(INFO) << "Downstream on_downstream_header_complete"; DLOG(INFO, downstream) << "HTTP response header completed";
} }
std::string via_value; std::string via_value;
char temp[16]; char temp[16];
@ -627,11 +631,11 @@ int HttpsUpstream::on_downstream_header_complete(Downstream *downstream)
hdrs += "\r\n"; hdrs += "\r\n";
hdrs += "\r\n"; hdrs += "\r\n";
if(ENABLE_LOG) { if(ENABLE_LOG) {
LOG(INFO) << "Upstream http response headers\n" << hdrs; ULOG(INFO, this) << "HTTP response headers\n" << hdrs;
} }
evbuffer *output = bufferevent_get_output(handler_->get_bev()); evbuffer *output = bufferevent_get_output(handler_->get_bev());
if(evbuffer_add(output, hdrs.c_str(), hdrs.size()) != 0) { if(evbuffer_add(output, hdrs.c_str(), hdrs.size()) != 0) {
LOG(FATAL) << "evbuffer_add() failed"; ULOG(FATAL, this) << "evbuffer_add() failed";
return -1; return -1;
} }
return 0; return 0;
@ -647,7 +651,7 @@ int HttpsUpstream::on_downstream_body(Downstream *downstream,
rv = snprintf(chunk_size_hex, sizeof(chunk_size_hex), "%X\r\n", rv = snprintf(chunk_size_hex, sizeof(chunk_size_hex), "%X\r\n",
static_cast<unsigned int>(len)); static_cast<unsigned int>(len));
if(evbuffer_add(output, chunk_size_hex, rv) != 0) { if(evbuffer_add(output, chunk_size_hex, rv) != 0) {
LOG(FATAL) << "evbuffer_add() failed"; ULOG(FATAL, this) << "evbuffer_add() failed";
return -1; return -1;
} }
} }
@ -663,12 +667,12 @@ int HttpsUpstream::on_downstream_body_complete(Downstream *downstream)
if(downstream->get_chunked_response()) { if(downstream->get_chunked_response()) {
evbuffer *output = bufferevent_get_output(handler_->get_bev()); evbuffer *output = bufferevent_get_output(handler_->get_bev());
if(evbuffer_add(output, "0\r\n\r\n", 5) != 0) { if(evbuffer_add(output, "0\r\n\r\n", 5) != 0) {
LOG(FATAL) << "evbuffer_add() failed"; ULOG(FATAL, this) << "evbuffer_add() failed";
return -1; return -1;
} }
} }
if(ENABLE_LOG) { if(ENABLE_LOG) {
LOG(INFO) << "Downstream on_downstream_body_complete"; DLOG(INFO, downstream) << "HTTP response completed";
} }
if(downstream->get_request_connection_close() || if(downstream->get_request_connection_close() ||
downstream->get_response_connection_close()) { downstream->get_response_connection_close()) {

8
src/shrpx_listen_handler.cc
View File

@ -66,13 +66,13 @@ void ListenHandler::create_worker_thread(size_t num)
WorkerInfo *info = &workers_[num_worker_]; WorkerInfo *info = &workers_[num_worker_];
rv = socketpair(AF_UNIX, SOCK_STREAM, 0, info->sv); rv = socketpair(AF_UNIX, SOCK_STREAM, 0, info->sv);
if(rv == -1) { if(rv == -1) {
LOG(ERROR) << "socketpair() failed: " << strerror(errno); LLOG(ERROR, this) << "socketpair() failed: " << strerror(errno);
continue; continue;
} }
info->ssl_ctx = ssl_ctx_; info->ssl_ctx = ssl_ctx_;
rv = pthread_create(&thread, &attr, start_threaded_worker, info); rv = pthread_create(&thread, &attr, start_threaded_worker, info);
if(rv != 0) { if(rv != 0) {
LOG(ERROR) << "pthread_create() failed: " << strerror(rv); LLOG(ERROR, this) << "pthread_create() failed: " << strerror(rv);
for(size_t j = 0; j < 2; ++j) { for(size_t j = 0; j < 2; ++j) {
close(info->sv[j]); close(info->sv[j]);
} }
@ -82,7 +82,7 @@ void ListenHandler::create_worker_thread(size_t num)
BEV_OPT_DEFER_CALLBACKS); BEV_OPT_DEFER_CALLBACKS);
info->bev = bev; info->bev = bev;
if(ENABLE_LOG) { if(ENABLE_LOG) {
LOG(INFO) << "Created thread#" << num_worker_; LLOG(INFO, this) << "Created thread #" << num_worker_;
} }
++num_worker_; ++num_worker_;
} }
@ -92,7 +92,7 @@ int ListenHandler::accept_connection(evutil_socket_t fd,
sockaddr *addr, int addrlen) sockaddr *addr, int addrlen)
{ {
if(ENABLE_LOG) { if(ENABLE_LOG) {
LOG(INFO) << "<listener> Accepted connection. fd=" << fd; LLOG(INFO, this) << "Accepted connection. fd=" << fd;
} }
if(num_worker_ == 0) { if(num_worker_ == 0) {
ClientHandler* client = ClientHandler* client =

31
src/shrpx_log.h
View File

@ -35,6 +35,37 @@ namespace shrpx {
#define LOG(SEVERITY) Log(SEVERITY, __FILE__, __LINE__) #define LOG(SEVERITY) Log(SEVERITY, __FILE__, __LINE__)
// Listener log
#define LLOG(SEVERITY, LISTEN) \
(Log(SEVERITY, __FILE__, __LINE__) << "[LISTEN:" << LISTEN \
<< "] ")
// ThreadEventReceiver log
#define TLOG(SEVERITY, THREAD_RECV) \
(Log(SEVERITY, __FILE__, __LINE__) << "[THREAD_RECV:" << THREAD_RECV \
<< "] ")
// ClientHandler log
#define CLOG(SEVERITY, CLIENT_HANDLER) \
(Log(SEVERITY, __FILE__, __LINE__) << "[CLIENT_HANDLER:" << CLIENT_HANDLER \
<< "] ")
// Upstream log
#define ULOG(SEVERITY, UPSTREAM) \
(Log(SEVERITY, __FILE__, __LINE__) << "[UPSTREAM:" << UPSTREAM << "] ")
// Downstream log
#define DLOG(SEVERITY, DOWNSTREAM) \
(Log(SEVERITY, __FILE__, __LINE__) << "[DOWNSTREAM:" << DOWNSTREAM << "] ")
// Downstream connection log
#define DCLOG(SEVERITY, DCONN) \
(Log(SEVERITY, __FILE__, __LINE__) << "[DCONN:" << DCONN << "] ")
// Downstream SPDY session log
#define SSLOG(SEVERITY, SPDY) \
(Log(SEVERITY, __FILE__, __LINE__) << "[DSPDY:" << SPDY << "] ")
enum SeverityLevel { enum SeverityLevel {
INFO, WARNING, ERROR, FATAL INFO, WARNING, ERROR, FATAL
}; };

14
src/shrpx_spdy_downstream_connection.cc
View File

@ -90,8 +90,7 @@ int SpdyDownstreamConnection::init_request_body_buf()
int SpdyDownstreamConnection::attach_downstream(Downstream *downstream) int SpdyDownstreamConnection::attach_downstream(Downstream *downstream)
{ {
if(ENABLE_LOG) { if(ENABLE_LOG) {
LOG(INFO) << "Attaching downstream connection " << this << " to " DCLOG(INFO, this) << "Attaching to DOWNSTREAM:" << downstream;
<< "downstream " << downstream;
} }
if(init_request_body_buf() == -1) { if(init_request_body_buf() == -1) {
return -1; return -1;
@ -109,8 +108,7 @@ int SpdyDownstreamConnection::attach_downstream(Downstream *downstream)
void SpdyDownstreamConnection::detach_downstream(Downstream *downstream) void SpdyDownstreamConnection::detach_downstream(Downstream *downstream)
{ {
if(ENABLE_LOG) { if(ENABLE_LOG) {
LOG(INFO) << "Detaching spdy downstream connection " << this << " from " DCLOG(INFO, this) << "Detaching from DOWNSTREAM:" << downstream;
<< "downstream " << downstream;
} }
downstream->set_downstream_connection(0); downstream->set_downstream_connection(0);
downstream_ = 0; downstream_ = 0;
@ -298,9 +296,7 @@ int SpdyDownstreamConnection::push_request_headers()
for(size_t i = 0; nv[i]; i += 2) { for(size_t i = 0; nv[i]; i += 2) {
ss << nv[i] << ": " << nv[i+1] << "\n"; ss << nv[i] << ": " << nv[i+1] << "\n";
} }
LOG(INFO) << "Downstream spdy request headers id=" DCLOG(INFO, this) << "HTTP request headers\n" << ss.str();
<< downstream_->get_stream_id() << "\n"
<< ss.str();
} }
if(downstream_->get_request_method() == "CONNECT" || if(downstream_->get_request_method() == "CONNECT" ||
@ -315,7 +311,7 @@ int SpdyDownstreamConnection::push_request_headers()
} }
delete [] nv; delete [] nv;
if(rv != 0) { if(rv != 0) {
LOG(FATAL) << "spdylay_submit_request() failed"; DCLOG(FATAL, this) << "spdylay_submit_request() failed";
return -1; return -1;
} }
spdy_->notify(); spdy_->notify();
@ -327,7 +323,7 @@ int SpdyDownstreamConnection::push_upload_data_chunk(const uint8_t *data,
{ {
int rv = evbuffer_add(request_body_buf_, data, datalen); int rv = evbuffer_add(request_body_buf_, data, datalen);
if(rv != 0) { if(rv != 0) {
LOG(FATAL) << "evbuffer_add() failed"; DCLOG(FATAL, this) << "evbuffer_add() failed";
return -1; return -1;
} }
if(downstream_->get_downstream_stream_id() != -1) { if(downstream_->get_downstream_stream_id() != -1) {

113
src/shrpx_spdy_session.cc
View File

@ -65,7 +65,7 @@ SpdySession::~SpdySession()
int SpdySession::disconnect() int SpdySession::disconnect()
{ {
if(ENABLE_LOG) { if(ENABLE_LOG) {
LOG(INFO) << "Downstream spdy session disconnecting " << this; SSLOG(INFO, this) << "Disconnecting";
} }
spdylay_session_del(session_); spdylay_session_del(session_);
session_ = 0; session_ = 0;
@ -121,7 +121,7 @@ void notify_readcb(bufferevent *bev, void *arg)
case SpdySession::DISCONNECTED: case SpdySession::DISCONNECTED:
rv = spdy->initiate_connection(); rv = spdy->initiate_connection();
if(rv != 0) { if(rv != 0) {
LOG(FATAL) << "Downstream spdy could not initiate connection " << spdy; SSLOG(FATAL, spdy) << "Could not initiate notification connection";
DIE(); DIE();
} }
break; break;
@ -138,12 +138,16 @@ void notify_readcb(bufferevent *bev, void *arg)
namespace { namespace {
void notify_eventcb(bufferevent *bev, short events, void *arg) void notify_eventcb(bufferevent *bev, short events, void *arg)
{ {
SpdySession *spdy = reinterpret_cast<SpdySession*>(arg);
// TODO should DIE()? // TODO should DIE()?
if(events & BEV_EVENT_EOF) { if(events & BEV_EVENT_EOF) {
LOG(ERROR) << "Connection to main thread lost: eof"; SSLOG(ERROR, spdy) << "Notification connection lost: EOF";
}
if(events & BEV_EVENT_TIMEOUT) {
SSLOG(ERROR, spdy) << "Notification connection lost: timeout";
} }
if(events & BEV_EVENT_ERROR) { if(events & BEV_EVENT_ERROR) {
LOG(ERROR) << "Connection to main thread lost: network error"; SSLOG(ERROR, spdy) << "Notification connection lost: network error";
} }
} }
} // namespace } // namespace
@ -154,14 +158,14 @@ int SpdySession::init_notification()
int sockpair[2]; int sockpair[2];
rv = socketpair(AF_UNIX, SOCK_STREAM, 0, sockpair); rv = socketpair(AF_UNIX, SOCK_STREAM, 0, sockpair);
if(rv == -1) { if(rv == -1) {
LOG(FATAL) << "socketpair() failed: " << strerror(errno); SSLOG(FATAL, this) << "socketpair() failed: " << strerror(errno);
return -1; return -1;
} }
wrbev_ = bufferevent_socket_new(evbase_, sockpair[0], wrbev_ = bufferevent_socket_new(evbase_, sockpair[0],
BEV_OPT_CLOSE_ON_FREE| BEV_OPT_CLOSE_ON_FREE|
BEV_OPT_DEFER_CALLBACKS); BEV_OPT_DEFER_CALLBACKS);
if(!wrbev_) { if(!wrbev_) {
LOG(FATAL) << "bufferevent_socket_new() failed"; SSLOG(FATAL, this) << "bufferevent_socket_new() failed";
for(int i = 0; i < 2; ++i) { for(int i = 0; i < 2; ++i) {
close(sockpair[i]); close(sockpair[i]);
} }
@ -171,7 +175,7 @@ int SpdySession::init_notification()
BEV_OPT_CLOSE_ON_FREE| BEV_OPT_CLOSE_ON_FREE|
BEV_OPT_DEFER_CALLBACKS); BEV_OPT_DEFER_CALLBACKS);
if(!rdbev_) { if(!rdbev_) {
LOG(FATAL) << "bufferevent_socket_new() failed"; SSLOG(FATAL, this) << "bufferevent_socket_new() failed";
close(sockpair[1]); close(sockpair[1]);
return -1; return -1;
} }
@ -213,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(ENABLE_LOG) {
LOG(INFO) << "Downstream spdy connection established. " << spdy; SSLOG(INFO, spdy) << "Connection established";
} }
spdy->connected(); spdy->connected();
if((!get_config()->insecure && spdy->check_cert() != 0) || if((!get_config()->insecure && spdy->check_cert() != 0) ||
@ -223,12 +227,16 @@ void eventcb(bufferevent *bev, short events, void *ptr)
} }
} else if(events & BEV_EVENT_EOF) { } else if(events & BEV_EVENT_EOF) {
if(ENABLE_LOG) { if(ENABLE_LOG) {
LOG(INFO) << "Downstream spdy EOF. " << spdy; 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(ENABLE_LOG) {
LOG(INFO) << "Downstream spdy error/timeout. " << spdy; if(events & BEV_EVENT_ERROR) {
SSLOG(INFO, spdy) << "Network error";
} else {
SSLOG(INFO, spdy) << "Timeout";
}
} }
spdy->disconnect(); spdy->disconnect();
} }
@ -245,13 +253,13 @@ int SpdySession::initiate_connection()
int rv; int rv;
assert(state_ == DISCONNECTED); assert(state_ == DISCONNECTED);
if(ENABLE_LOG) { if(ENABLE_LOG) {
LOG(INFO) << "Downstream spdy initiating connection " << this; SSLOG(INFO, this) << "Connecting to downstream server";
} }
ssl_ = SSL_new(ssl_ctx_); ssl_ = SSL_new(ssl_ctx_);
if(!ssl_) { if(!ssl_) {
LOG(ERROR) << "SSL_new() failed: " SSLOG(ERROR, this) << "SSL_new() failed: "
<< ERR_error_string(ERR_get_error(), NULL); << ERR_error_string(ERR_get_error(), NULL);
return -1; return -1;
} }
@ -275,9 +283,6 @@ int SpdySession::initiate_connection()
bev_ = 0; bev_ = 0;
return SHRPX_ERR_NETWORK; return SHRPX_ERR_NETWORK;
} }
if(ENABLE_LOG) {
LOG(INFO) << "Connecting to downstream " << this;
}
bufferevent_setwatermark(bev_, EV_READ, 0, SHRPX_READ_WARTER_MARK); bufferevent_setwatermark(bev_, EV_READ, 0, SHRPX_READ_WARTER_MARK);
bufferevent_enable(bev_, EV_READ); bufferevent_enable(bev_, EV_READ);
@ -324,8 +329,8 @@ int SpdySession::submit_request(SpdyDownstreamConnection *dconn,
dconn->attach_stream_data(sd); dconn->attach_stream_data(sd);
streams_.insert(sd); streams_.insert(sd);
} else { } else {
LOG(FATAL) << "spdylay_submit_request() failed: " SSLOG(FATAL, this) << "spdylay_submit_request() failed: "
<< spdylay_strerror(rv); << spdylay_strerror(rv);
delete sd; delete sd;
return -1; return -1;
} }
@ -338,8 +343,8 @@ int SpdySession::submit_rst_stream(SpdyDownstreamConnection *dconn,
assert(state_ == CONNECTED); assert(state_ == CONNECTED);
int rv = spdylay_submit_rst_stream(session_, stream_id, status_code); int rv = spdylay_submit_rst_stream(session_, stream_id, status_code);
if(rv != 0) { if(rv != 0) {
LOG(FATAL) << "spdylay_submit_rst_stream() failed: " SSLOG(FATAL, this) << "spdylay_submit_rst_stream() failed: "
<< spdylay_strerror(rv); << spdylay_strerror(rv);
return -1; return -1;
} }
return 0; return 0;
@ -354,8 +359,8 @@ int SpdySession::submit_window_update(SpdyDownstreamConnection *dconn,
stream_id = dconn->get_downstream()->get_downstream_stream_id(); stream_id = dconn->get_downstream()->get_downstream_stream_id();
rv = spdylay_submit_window_update(session_, stream_id, amount); rv = spdylay_submit_window_update(session_, stream_id, amount);
if(rv < SPDYLAY_ERR_FATAL) { if(rv < SPDYLAY_ERR_FATAL) {
LOG(FATAL) << "spdylay_submit_window_update() failed: " SSLOG(FATAL, this) << "spdylay_submit_window_update() failed: "
<< spdylay_strerror(rv); << spdylay_strerror(rv);
return -1; return -1;
} }
return 0; return 0;
@ -382,8 +387,8 @@ int SpdySession::resume_data(SpdyDownstreamConnection *dconn)
case SPDYLAY_ERR_INVALID_ARGUMENT: case SPDYLAY_ERR_INVALID_ARGUMENT:
return 0; return 0;
default: default:
LOG(FATAL) << "spdylay_resume_session() failed: " SSLOG(FATAL, this) << "spdylay_resume_session() failed: "
<< spdylay_strerror(rv); << spdylay_strerror(rv);
return -1; return -1;
} }
} }
@ -417,7 +422,7 @@ ssize_t send_callback(spdylay_session *session,
rv = evbuffer_add(output, data, len); rv = evbuffer_add(output, data, len);
if(rv == -1) { if(rv == -1) {
LOG(FATAL) << "evbuffer_add() failed"; SSLOG(FATAL, spdy) << "evbuffer_add() failed";
return SPDYLAY_ERR_CALLBACK_FAILURE; return SPDYLAY_ERR_CALLBACK_FAILURE;
} else { } else {
return len; return len;
@ -450,10 +455,11 @@ void on_stream_close_callback
void *user_data) void *user_data)
{ {
int rv; int rv;
if(ENABLE_LOG) {
LOG(INFO) << "Downstream spdy Stream " << stream_id << " is being closed";
}
SpdySession *spdy = reinterpret_cast<SpdySession*>(user_data); SpdySession *spdy = reinterpret_cast<SpdySession*>(user_data);
if(ENABLE_LOG) {
SSLOG(INFO, spdy) << "Stream stream_id=" << stream_id
<< " is being closed";
}
StreamData *sd; StreamData *sd;
sd = reinterpret_cast<StreamData*> sd = reinterpret_cast<StreamData*>
(spdylay_session_get_stream_user_data(session, stream_id)); (spdylay_session_get_stream_user_data(session, stream_id));
@ -497,8 +503,8 @@ void on_ctrl_recv_callback
switch(type) { switch(type) {
case SPDYLAY_SYN_STREAM: case SPDYLAY_SYN_STREAM:
if(ENABLE_LOG) { if(ENABLE_LOG) {
LOG(INFO) << "Downstream 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;
} }
// We just respond pushed stream with RST_STREAM. // We just respond pushed stream with RST_STREAM.
spdylay_submit_rst_stream(session, frame->syn_stream.stream_id, spdylay_submit_rst_stream(session, frame->syn_stream.stream_id,
@ -588,9 +594,9 @@ void on_ctrl_recv_callback
for(size_t i = 0; nv[i]; i += 2) { for(size_t i = 0; nv[i]; i += 2) {
ss << nv[i] << ": " << nv[i+1] << "\n"; ss << nv[i] << ": " << nv[i+1] << "\n";
} }
LOG(INFO) << "Downstream spdy response headers id=" SSLOG(INFO, spdy) << "HTTP response headers. stream_id="
<< frame->syn_reply.stream_id << frame->syn_reply.stream_id
<< "\n" << ss.str(); << "\n" << ss.str();
} }
Upstream *upstream = downstream->get_upstream(); Upstream *upstream = downstream->get_upstream();
@ -635,10 +641,10 @@ void on_data_chunk_recv_callback(spdylay_session *session,
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(ENABLE_LOG) {
LOG(INFO) << "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="
<< spdy->get_initial_window_size(); << spdy->get_initial_window_size();
} }
spdylay_submit_rst_stream(session, stream_id, spdylay_submit_rst_stream(session, stream_id,
SPDYLAY_FLOW_CONTROL_ERROR); SPDYLAY_FLOW_CONTROL_ERROR);
@ -691,13 +697,13 @@ void on_ctrl_not_send_callback(spdylay_session *session,
spdylay_frame *frame, spdylay_frame *frame,
int error_code, void *user_data) int error_code, void *user_data)
{ {
LOG(WARNING) << "Failed to send control frame type=" << type << ", " SpdySession *spdy = reinterpret_cast<SpdySession*>(user_data);
<< "error_code=" << error_code << ":" SSLOG(WARNING, spdy) << "Failed to send control frame type=" << type << ", "
<< spdylay_strerror(error_code); << "error_code=" << error_code << ":"
<< spdylay_strerror(error_code);
if(type == SPDYLAY_SYN_STREAM) { if(type == SPDYLAY_SYN_STREAM) {
// To avoid stream hanging around, flag Downstream::MSG_RESET and // To avoid stream hanging around, flag Downstream::MSG_RESET and
// terminate the upstream and downstream connections. // terminate the upstream and downstream connections.
SpdySession *spdy = reinterpret_cast<SpdySession*>(user_data);
StreamData *sd; StreamData *sd;
sd = reinterpret_cast<StreamData*> sd = reinterpret_cast<StreamData*>
(spdylay_session_get_stream_user_data(session, (spdylay_session_get_stream_user_data(session,
@ -728,10 +734,12 @@ void on_ctrl_recv_parse_error_callback(spdylay_session *session,
size_t payloadlen, int error_code, size_t payloadlen, int error_code,
void *user_data) void *user_data)
{ {
SpdySession *spdy = reinterpret_cast<SpdySession*>(user_data);
if(ENABLE_LOG) { if(ENABLE_LOG) {
LOG(INFO) << "Failed to parse received control frame. type=" << type SSLOG(INFO, spdy) << "Failed to parse received control frame. type="
<< ", error_code=" << error_code << ":" << type
<< spdylay_strerror(error_code); << ", error_code=" << error_code << ":"
<< spdylay_strerror(error_code);
} }
} }
} // namespace } // namespace
@ -742,8 +750,9 @@ void on_unknown_ctrl_recv_callback(spdylay_session *session,
const uint8_t *payload, size_t payloadlen, const uint8_t *payload, size_t payloadlen,
void *user_data) void *user_data)
{ {
SpdySession *spdy = reinterpret_cast<SpdySession*>(user_data);
if(ENABLE_LOG) { if(ENABLE_LOG) {
LOG(INFO) << "Received unknown control frame."; SSLOG(INFO, spdy) << "Received unknown control frame";
} }
} }
} // namespace } // namespace
@ -757,7 +766,7 @@ int SpdySession::on_connect()
if(ENABLE_LOG) { if(ENABLE_LOG) {
std::string proto(next_proto, next_proto+next_proto_len); std::string proto(next_proto, next_proto+next_proto_len);
LOG(INFO) << "Downstream negotiated next protocol: " << proto; SSLOG(INFO, this) << "Negotiated next protocol: " << proto;
} }
uint16_t version = spdylay_npn_get_version(next_proto, next_proto_len); uint16_t version = spdylay_npn_get_version(next_proto, next_proto_len);
if(!version) { if(!version) {
@ -827,12 +836,12 @@ int SpdySession::on_read()
int rv = 0; int rv = 0;
if((rv = spdylay_session_recv(session_)) < 0) { if((rv = spdylay_session_recv(session_)) < 0) {
if(rv != SPDYLAY_ERR_EOF) { if(rv != SPDYLAY_ERR_EOF) {
LOG(ERROR) << "spdylay_session_recv() returned error: " SSLOG(ERROR, this) << "spdylay_session_recv() returned error: "
<< spdylay_strerror(rv); << spdylay_strerror(rv);
} }
} else if((rv = spdylay_session_send(session_)) < 0) { } else if((rv = spdylay_session_send(session_)) < 0) {
LOG(ERROR) << "spdylay_session_send() returned error: " SSLOG(ERROR, this) << "spdylay_session_send() returned error: "
<< spdylay_strerror(rv); << spdylay_strerror(rv);
} }
// if(rv == 0) { // if(rv == 0) {
// if(spdylay_session_want_read(session_) == 0 && // if(spdylay_session_want_read(session_) == 0 &&
@ -855,8 +864,8 @@ int SpdySession::send()
{ {
int rv = 0; int rv = 0;
if((rv = spdylay_session_send(session_)) < 0) { if((rv = spdylay_session_send(session_)) < 0) {
LOG(ERROR) << "spdylay_session_send() returned error: " SSLOG(ERROR, this) << "spdylay_session_send() returned error: "
<< spdylay_strerror(rv); << spdylay_strerror(rv);
} }
// if(rv == 0) { // if(rv == 0) {
// if(spdylay_session_want_read(session_) == 0 && // if(spdylay_session_want_read(session_) == 0 &&

124
src/shrpx_spdy_upstream.cc
View File

@ -61,7 +61,7 @@ ssize_t send_callback(spdylay_session *session,
rv = evbuffer_add(output, data, len); rv = evbuffer_add(output, data, len);
if(rv == -1) { if(rv == -1) {
LOG(FATAL) << "evbuffer_add() failed"; ULOG(FATAL, upstream) << "evbuffer_add() failed";
return SPDYLAY_ERR_CALLBACK_FAILURE; return SPDYLAY_ERR_CALLBACK_FAILURE;
} else { } else {
return len; return len;
@ -93,10 +93,11 @@ void on_stream_close_callback
(spdylay_session *session, int32_t stream_id, spdylay_status_code status_code, (spdylay_session *session, int32_t stream_id, spdylay_status_code status_code,
void *user_data) void *user_data)
{ {
if(ENABLE_LOG) {
LOG(INFO) << "Upstream spdy Stream " << stream_id << " is being closed";
}
SpdyUpstream *upstream = reinterpret_cast<SpdyUpstream*>(user_data); SpdyUpstream *upstream = reinterpret_cast<SpdyUpstream*>(user_data);
if(ENABLE_LOG) {
ULOG(INFO, upstream) << "Stream stream_id=" << stream_id
<< " is being closed";
}
Downstream *downstream = upstream->find_downstream(stream_id); Downstream *downstream = upstream->find_downstream(stream_id);
if(get_config()->accesslog) { if(get_config()->accesslog) {
upstream_spdy_stream_close(upstream->get_client_handler()->get_ipaddr(), upstream_spdy_stream_close(upstream->get_client_handler()->get_ipaddr(),
@ -146,8 +147,8 @@ void on_ctrl_recv_callback
switch(type) { switch(type) {
case SPDYLAY_SYN_STREAM: { case SPDYLAY_SYN_STREAM: {
if(ENABLE_LOG) { if(ENABLE_LOG) {
LOG(INFO) << "Upstream spdy 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;
} }
Downstream *downstream; Downstream *downstream;
downstream = new Downstream(upstream, downstream = new Downstream(upstream,
@ -199,9 +200,9 @@ void on_ctrl_recv_callback
for(size_t i = 0; nv[i]; i += 2) { for(size_t i = 0; nv[i]; i += 2) {
ss << nv[i] << ": " << nv[i+1] << "\n"; ss << nv[i] << ": " << nv[i+1] << "\n";
} }
LOG(INFO) << "Upstream spdy request headers id=" ULOG(INFO, upstream) << "HTTP request headers. stream_id="
<< downstream->get_stream_id() << downstream->get_stream_id()
<< "\n" << ss.str(); << "\n" << ss.str();
} }
DownstreamConnection *dconn; DownstreamConnection *dconn;
@ -224,11 +225,6 @@ void on_ctrl_recv_callback
} }
downstream->set_request_state(Downstream::HEADER_COMPLETE); downstream->set_request_state(Downstream::HEADER_COMPLETE);
if(frame->syn_stream.hd.flags & SPDYLAY_CTRL_FLAG_FIN) { if(frame->syn_stream.hd.flags & SPDYLAY_CTRL_FLAG_FIN) {
if(ENABLE_LOG) {
LOG(INFO) << "Upstream spdy "
<< "Setting Downstream::MSG_COMPLETE for Downstream "
<< downstream;
}
downstream->set_request_state(Downstream::MSG_COMPLETE); downstream->set_request_state(Downstream::MSG_COMPLETE);
} }
break; break;
@ -257,21 +253,16 @@ void on_data_chunk_recv_callback(spdylay_session *session,
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(ENABLE_LOG) {
LOG(INFO) << "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="
<< upstream->get_initial_window_size(); << upstream->get_initial_window_size();
} }
upstream->rst_stream(downstream, SPDYLAY_FLOW_CONTROL_ERROR); upstream->rst_stream(downstream, SPDYLAY_FLOW_CONTROL_ERROR);
return; return;
} }
} }
if(flags & SPDYLAY_DATA_FLAG_FIN) { if(flags & SPDYLAY_DATA_FLAG_FIN) {
if(ENABLE_LOG) {
LOG(INFO) << "Upstream spdy "
<< "setting Downstream::MSG_COMPLETE for Downstream "
<< downstream;
}
downstream->set_request_state(Downstream::MSG_COMPLETE); downstream->set_request_state(Downstream::MSG_COMPLETE);
} }
} }
@ -284,12 +275,12 @@ void on_ctrl_not_send_callback(spdylay_session *session,
spdylay_frame *frame, spdylay_frame *frame,
int error_code, void *user_data) int error_code, void *user_data)
{ {
LOG(WARNING) << "Failed to send control frame type=" << type << ", " SpdyUpstream *upstream = reinterpret_cast<SpdyUpstream*>(user_data);
<< "error_code=" << error_code << ":" ULOG(WARNING, upstream) << "Failed to send control frame type=" << type
<< spdylay_strerror(error_code); << ", error_code=" << error_code << ":"
<< spdylay_strerror(error_code);
if(type == SPDYLAY_SYN_REPLY) { if(type == SPDYLAY_SYN_REPLY) {
// To avoid stream hanging around, issue RST_STREAM. // To avoid stream hanging around, issue RST_STREAM.
SpdyUpstream *upstream = reinterpret_cast<SpdyUpstream*>(user_data);
int32_t stream_id = frame->syn_reply.stream_id; int32_t stream_id = frame->syn_reply.stream_id;
Downstream *downstream = upstream->find_downstream(stream_id); Downstream *downstream = upstream->find_downstream(stream_id);
if(downstream) { if(downstream) {
@ -307,10 +298,12 @@ void on_ctrl_recv_parse_error_callback(spdylay_session *session,
size_t payloadlen, int error_code, size_t payloadlen, int error_code,
void *user_data) void *user_data)
{ {
SpdyUpstream *upstream = reinterpret_cast<SpdyUpstream*>(user_data);
if(ENABLE_LOG) { if(ENABLE_LOG) {
LOG(INFO) << "Failed to parse received control frame. type=" << type ULOG(INFO, upstream) << "Failed to parse received control frame. type="
<< ", error_code=" << error_code << ":" << type
<< spdylay_strerror(error_code); << ", error_code=" << error_code << ":"
<< spdylay_strerror(error_code);
} }
} }
} // namespace } // namespace
@ -321,8 +314,9 @@ void on_unknown_ctrl_recv_callback(spdylay_session *session,
const uint8_t *payload, size_t payloadlen, const uint8_t *payload, size_t payloadlen,
void *user_data) void *user_data)
{ {
SpdyUpstream *upstream = reinterpret_cast<SpdyUpstream*>(user_data);
if(ENABLE_LOG) { if(ENABLE_LOG) {
LOG(INFO) << "Received unknown control frame."; ULOG(INFO, upstream) << "Received unknown control frame.";
} }
} }
} // namespace } // namespace
@ -391,18 +385,18 @@ int SpdyUpstream::on_read()
int rv = 0; int rv = 0;
if((rv = spdylay_session_recv(session_)) < 0) { if((rv = spdylay_session_recv(session_)) < 0) {
if(rv != SPDYLAY_ERR_EOF) { if(rv != SPDYLAY_ERR_EOF) {
LOG(ERROR) << "spdylay_session_recv() returned error: " ULOG(ERROR, this) << "spdylay_session_recv() returned error: "
<< spdylay_strerror(rv); << spdylay_strerror(rv);
} }
} else if((rv = spdylay_session_send(session_)) < 0) { } else if((rv = spdylay_session_send(session_)) < 0) {
LOG(ERROR) << "spdylay_session_send() returned error: " ULOG(ERROR, this) << "spdylay_session_send() returned error: "
<< spdylay_strerror(rv); << spdylay_strerror(rv);
} }
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(ENABLE_LOG) {
LOG(INFO) << "No more read/write for this SPDY session"; ULOG(INFO, this) << "No more read/write for this SPDY session";
} }
rv = -1; rv = -1;
} }
@ -420,14 +414,14 @@ int SpdyUpstream::send()
{ {
int rv = 0; int rv = 0;
if((rv = spdylay_session_send(session_)) < 0) { if((rv = spdylay_session_send(session_)) < 0) {
LOG(ERROR) << "spdylay_session_send() returned error: " ULOG(ERROR, this) << "spdylay_session_send() returned error: "
<< spdylay_strerror(rv); << spdylay_strerror(rv);
} }
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(ENABLE_LOG) {
LOG(INFO) << "No more read/write for this SPDY session"; ULOG(INFO, this) << "No more read/write for this SPDY session";
} }
rv = -1; rv = -1;
} }
@ -463,7 +457,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(ENABLE_LOG) {
LOG(INFO) << "Downstream 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) {
upstream->rst_stream(downstream, SPDYLAY_INTERNAL_ERROR); upstream->rst_stream(downstream, SPDYLAY_INTERNAL_ERROR);
@ -516,13 +510,12 @@ void spdy_downstream_eventcb(bufferevent *bev, short events, void *ptr)
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(ENABLE_LOG) {
LOG(INFO) << "Downstream connection established. Downstream " DCLOG(INFO, dconn) << "Connection established. stream_id="
<< downstream; << downstream->get_stream_id();
} }
} else if(events & BEV_EVENT_EOF) { } else if(events & BEV_EVENT_EOF) {
if(ENABLE_LOG) { if(ENABLE_LOG) {
LOG(INFO) << "Downstream EOF stream_id=" DCLOG(INFO, dconn) << "EOF. stream_id=" << downstream->get_stream_id();
<< downstream->get_stream_id();
} }
if(downstream->get_request_state() == Downstream::STREAM_CLOSED) { if(downstream->get_request_state() == Downstream::STREAM_CLOSED) {
// If stream was closed already, we don't need to send reply at // If stream was closed already, we don't need to send reply at
@ -539,7 +532,7 @@ void spdy_downstream_eventcb(bufferevent *bev, short events, void *ptr)
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(ENABLE_LOG) {
LOG(INFO) << "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);
if(downstream->tunnel_established()) { if(downstream->tunnel_established()) {
@ -568,13 +561,14 @@ void spdy_downstream_eventcb(bufferevent *bev, short events, void *ptr)
} else if(events & (BEV_EVENT_ERROR | BEV_EVENT_TIMEOUT)) { } else if(events & (BEV_EVENT_ERROR | BEV_EVENT_TIMEOUT)) {
if(ENABLE_LOG) { if(ENABLE_LOG) {
if(events & BEV_EVENT_ERROR) { if(events & BEV_EVENT_ERROR) {
LOG(INFO) << "Downstream network error: " DCLOG(INFO, dconn) << "Downstream network error: "
<< evutil_socket_error_to_string(EVUTIL_SOCKET_ERROR()); << evutil_socket_error_to_string
(EVUTIL_SOCKET_ERROR());
} else { } else {
LOG(INFO) << "Downstream timeout"; DCLOG(INFO, dconn) << "Timeout";
} }
if(downstream->tunnel_established()) { if(downstream->tunnel_established()) {
LOG(INFO) << "Note: this is tunnel connection"; DCLOG(INFO, dconn) << "Note: this is tunnel connection";
} }
} }
if(downstream->get_request_state() == Downstream::STREAM_CLOSED) { if(downstream->get_request_state() == Downstream::STREAM_CLOSED) {
@ -619,15 +613,15 @@ 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(ENABLE_LOG) {
LOG(INFO) << "RST_STREAM stream_id=" ULOG(INFO, this) << "RST_STREAM stream_id="
<< downstream->get_stream_id(); << downstream->get_stream_id();
} }
int rv; int rv;
rv = spdylay_submit_rst_stream(session_, downstream->get_stream_id(), rv = spdylay_submit_rst_stream(session_, downstream->get_stream_id(),
status_code); status_code);
if(rv < SPDYLAY_ERR_FATAL) { if(rv < SPDYLAY_ERR_FATAL) {
LOG(FATAL) << "spdylay_submit_rst_stream() failed: " ULOG(FATAL, this) << "spdylay_submit_rst_stream() failed: "
<< spdylay_strerror(rv); << spdylay_strerror(rv);
DIE(); DIE();
} }
return 0; return 0;
@ -640,8 +634,8 @@ int SpdyUpstream::window_update(Downstream *downstream)
downstream->get_recv_window_size()); downstream->get_recv_window_size());
downstream->set_recv_window_size(0); downstream->set_recv_window_size(0);
if(rv < SPDYLAY_ERR_FATAL) { if(rv < SPDYLAY_ERR_FATAL) {
LOG(FATAL) << "spdylay_submit_window_update() failed: " ULOG(FATAL, this) << "spdylay_submit_window_update() failed: "
<< spdylay_strerror(rv); << spdylay_strerror(rv);
DIE(); DIE();
} }
return 0; return 0;
@ -680,7 +674,7 @@ int SpdyUpstream::error_reply(Downstream *downstream, int status_code)
evbuffer *body = downstream->get_response_body_buf(); evbuffer *body = downstream->get_response_body_buf();
rv = evbuffer_add(body, html.c_str(), html.size()); rv = evbuffer_add(body, html.c_str(), html.size());
if(rv == -1) { if(rv == -1) {
LOG(FATAL) << "evbuffer_add() failed"; ULOG(FATAL, this) << "evbuffer_add() failed";
return -1; return -1;
} }
downstream->set_response_state(Downstream::MSG_COMPLETE); downstream->set_response_state(Downstream::MSG_COMPLETE);
@ -700,8 +694,8 @@ int SpdyUpstream::error_reply(Downstream *downstream, int status_code)
rv = spdylay_submit_response(session_, downstream->get_stream_id(), nv, rv = spdylay_submit_response(session_, downstream->get_stream_id(), nv,
&data_prd); &data_prd);
if(rv < SPDYLAY_ERR_FATAL) { if(rv < SPDYLAY_ERR_FATAL) {
LOG(FATAL) << "spdylay_submit_response() failed: " ULOG(FATAL, this) << "spdylay_submit_response() failed: "
<< spdylay_strerror(rv); << spdylay_strerror(rv);
DIE(); DIE();
} }
return 0; return 0;
@ -747,7 +741,7 @@ spdylay_session* SpdyUpstream::get_spdy_session()
int SpdyUpstream::on_downstream_header_complete(Downstream *downstream) int SpdyUpstream::on_downstream_header_complete(Downstream *downstream)
{ {
if(ENABLE_LOG) { if(ENABLE_LOG) {
LOG(INFO) << "Downstream on_downstream_header_complete"; DLOG(INFO, downstream) << "HTTP response header completed";
} }
size_t nheader = downstream->get_response_headers().size(); size_t nheader = downstream->get_response_headers().size();
// 6 means :status, :version and possible via header field. // 6 means :status, :version and possible via header field.
@ -785,9 +779,9 @@ int SpdyUpstream::on_downstream_header_complete(Downstream *downstream)
for(size_t i = 0; nv[i]; i += 2) { for(size_t i = 0; nv[i]; i += 2) {
ss << nv[i] << ": " << nv[i+1] << "\n"; ss << nv[i] << ": " << nv[i+1] << "\n";
} }
LOG(INFO) << "Upstream spdy response headers id=" ULOG(INFO, this) << "HTTP response headers. stream_id="
<< downstream->get_stream_id() << "\n" << downstream->get_stream_id() << "\n"
<< ss.str(); << ss.str();
} }
spdylay_data_provider data_prd; spdylay_data_provider data_prd;
data_prd.source.ptr = downstream; data_prd.source.ptr = downstream;
@ -798,7 +792,7 @@ int SpdyUpstream::on_downstream_header_complete(Downstream *downstream)
&data_prd); &data_prd);
delete [] nv; delete [] nv;
if(rv != 0) { if(rv != 0) {
LOG(FATAL) << "spdylay_submit_response() failed"; ULOG(FATAL, this) << "spdylay_submit_response() failed";
return -1; return -1;
} }
return 0; return 0;
@ -812,7 +806,7 @@ int SpdyUpstream::on_downstream_body(Downstream *downstream,
evbuffer *body = downstream->get_response_body_buf(); evbuffer *body = downstream->get_response_body_buf();
int rv = evbuffer_add(body, data, len); int rv = evbuffer_add(body, data, len);
if(rv != 0) { if(rv != 0) {
LOG(FATAL) << "evbuffer_add() failed"; ULOG(FATAL, this) << "evbuffer_add() failed";
return -1; return -1;
} }
spdylay_session_resume_data(session_, downstream->get_stream_id()); spdylay_session_resume_data(session_, downstream->get_stream_id());
@ -830,7 +824,7 @@ int SpdyUpstream::on_downstream_body(Downstream *downstream,
int SpdyUpstream::on_downstream_body_complete(Downstream *downstream) int SpdyUpstream::on_downstream_body_complete(Downstream *downstream)
{ {
if(ENABLE_LOG) { if(ENABLE_LOG) {
LOG(INFO) << "Downstream on_downstream_body_complete"; DLOG(INFO, downstream) << "HTTP response completed";
} }
spdylay_session_resume_data(session_, downstream->get_stream_id()); spdylay_session_resume_data(session_, downstream->get_stream_id());
return 0; return 0;

8
src/shrpx_thread_event_receiver.cc
View File

@ -48,8 +48,8 @@ void ThreadEventReceiver::on_read(bufferevent *bev)
WorkerEvent wev; WorkerEvent wev;
evbuffer_remove(input, &wev, sizeof(WorkerEvent)); evbuffer_remove(input, &wev, sizeof(WorkerEvent));
if(ENABLE_LOG) { if(ENABLE_LOG) {
LOG(INFO) << "WorkerEvent: client_fd=" << wev.client_fd TLOG(INFO, this) << "WorkerEvent: client_fd=" << wev.client_fd
<< ", addrlen=" << wev.client_addrlen; << ", addrlen=" << wev.client_addrlen;
} }
event_base *evbase = bufferevent_get_base(bev); event_base *evbase = bufferevent_get_base(bev);
ClientHandler *client_handler; ClientHandler *client_handler;
@ -60,11 +60,11 @@ void ThreadEventReceiver::on_read(bufferevent *bev)
if(client_handler) { if(client_handler) {
client_handler->set_spdy_session(spdy_); client_handler->set_spdy_session(spdy_);
if(ENABLE_LOG) { if(ENABLE_LOG) {
LOG(INFO) << "ClientHandler " << client_handler << " created"; TLOG(INFO, this) << "CLIENT_HANDLER:" << client_handler << " created";
} }
} else { } else {
if(ENABLE_LOG) { if(ENABLE_LOG) {
LOG(ERROR) << "ClientHandler creation failed"; TLOG(ERROR, this) << "ClientHandler creation failed";
} }
close(wev.client_fd); close(wev.client_fd);
} }