From bbf6c185756d3f3c3df4877a4ca5c15c81396529 Mon Sep 17 00:00:00 2001 From: Tatsuhiro Tsujikawa Date: Sun, 9 Dec 2012 19:15:14 +0900 Subject: [PATCH] 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 --- src/shrpx_client_handler.cc | 40 ++++---- src/shrpx_downstream.cc | 6 +- src/shrpx_http_downstream_connection.cc | 34 +++---- src/shrpx_https_upstream.cc | 58 +++++------ src/shrpx_listen_handler.cc | 8 +- src/shrpx_log.h | 31 ++++++ src/shrpx_spdy_downstream_connection.cc | 14 +-- src/shrpx_spdy_session.cc | 113 +++++++++++---------- src/shrpx_spdy_upstream.cc | 124 +++++++++++------------- src/shrpx_thread_event_receiver.cc | 8 +- 10 files changed, 235 insertions(+), 201 deletions(-) diff --git a/src/shrpx_client_handler.cc b/src/shrpx_client_handler.cc index a5931231..e88852bf 100644 --- a/src/shrpx_client_handler.cc +++ b/src/shrpx_client_handler.cc @@ -43,7 +43,7 @@ void upstream_readcb(bufferevent *bev, void *arg) ClientHandler *handler = reinterpret_cast(arg); int rv = handler->on_read(); if(rv != 0) { - LOG(WARNING) << " Read operation (application level) failure"; + CLOG(WARNING, handler) << "Read operation (application level) failure"; delete handler; } } @@ -65,7 +65,7 @@ void upstream_writecb(bufferevent *bev, void *arg) Upstream *upstream = handler->get_upstream(); int rv = upstream->on_write(); if(rv != 0) { - LOG(WARNING) << " Write operation (application level) failure"; + CLOG(WARNING, handler) << "Write operation (application level) failure"; delete handler; } } @@ -79,20 +79,21 @@ void upstream_eventcb(bufferevent *bev, short events, void *arg) bool finish = false; if(events & BEV_EVENT_EOF) { if(ENABLE_LOG) { - LOG(INFO) << "Upstream EOF"; + CLOG(INFO, handler) << "EOF"; } finish = true; } if(events & BEV_EVENT_ERROR) { if(ENABLE_LOG) { - LOG(INFO) << "Upstream network error: " - << evutil_socket_error_to_string(EVUTIL_SOCKET_ERROR()); + CLOG(INFO, handler) << "Network error: " + << evutil_socket_error_to_string + (EVUTIL_SOCKET_ERROR()); } finish = true; } if(events & BEV_EVENT_TIMEOUT) { if(ENABLE_LOG) { - LOG(INFO) << "Upstream time out"; + CLOG(INFO, handler) << "Time out"; } finish = true; } @@ -101,13 +102,13 @@ void upstream_eventcb(bufferevent *bev, short events, void *arg) } else { if(events & BEV_EVENT_CONNECTED) { 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->validate_next_proto(); if(ENABLE_LOG) { 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 @@ -145,7 +146,7 @@ ClientHandler::ClientHandler(bufferevent *bev, int fd, SSL *ssl, ClientHandler::~ClientHandler() { if(ENABLE_LOG) { - LOG(INFO) << "Deleting ClientHandler " << this; + CLOG(INFO, this) << "Deleting"; } if(ssl_) { SSL_shutdown(ssl_); @@ -163,7 +164,7 @@ ClientHandler::~ClientHandler() delete *i; } if(ENABLE_LOG) { - LOG(INFO) << "Deleted"; + CLOG(INFO, this) << "Deleted"; } } @@ -203,7 +204,7 @@ int ClientHandler::validate_next_proto() if(next_proto) { if(ENABLE_LOG) { 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); if(version) { @@ -213,11 +214,11 @@ int ClientHandler::validate_next_proto() } } else { if(ENABLE_LOG) { - LOG(INFO) << "No proto negotiated."; + CLOG(INFO, this) << "No proto negotiated."; } } if(ENABLE_LOG) { - LOG(INFO) << "Use HTTP/1.1"; + CLOG(INFO, this) << "Use HTTP/1.1"; } HttpsUpstream *https_upstream = new HttpsUpstream(this); upstream_ = https_upstream; @@ -252,7 +253,7 @@ void ClientHandler::set_should_close_after_write(bool f) void ClientHandler::pool_downstream_connection(DownstreamConnection *dconn) { if(ENABLE_LOG) { - LOG(INFO) << "Pooling downstream connection " << dconn; + CLOG(INFO, this) << "Pooling downstream connection DCONN:" << dconn; } dconn_pool_.insert(dconn); } @@ -260,8 +261,8 @@ void ClientHandler::pool_downstream_connection(DownstreamConnection *dconn) void ClientHandler::remove_downstream_connection(DownstreamConnection *dconn) { if(ENABLE_LOG) { - LOG(INFO) << "Removing downstream connection " << dconn - << " from pool"; + CLOG(INFO, this) << "Removing downstream connection DCONN:" << dconn + << " from pool"; } dconn_pool_.erase(dconn); } @@ -270,7 +271,8 @@ DownstreamConnection* ClientHandler::get_downstream_connection() { if(dconn_pool_.empty()) { 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) { return new SpdyDownstreamConnection(this); @@ -281,8 +283,8 @@ DownstreamConnection* ClientHandler::get_downstream_connection() DownstreamConnection *dconn = *dconn_pool_.begin(); dconn_pool_.erase(dconn); if(ENABLE_LOG) { - LOG(INFO) << "Reuse downstream connection " << dconn - << " from pool"; + CLOG(INFO, this) << "Reuse downstream connection DCONN:" << dconn + << " from pool"; } return dconn; } diff --git a/src/shrpx_downstream.cc b/src/shrpx_downstream.cc index c967dcfb..1d895794 100644 --- a/src/shrpx_downstream.cc +++ b/src/shrpx_downstream.cc @@ -64,7 +64,7 @@ Downstream::Downstream(Upstream *upstream, int stream_id, int priority) Downstream::~Downstream() { if(ENABLE_LOG) { - LOG(INFO) << "Deleting downstream " << this; + DLOG(INFO, this) << "Deleting"; } if(response_body_buf_) { // Passing NULL to evbuffer_free() causes segmentation fault. @@ -74,7 +74,7 @@ Downstream::~Downstream() delete dconn_; } 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 // buffer using push_request_headers(). if(!dconn_) { - LOG(WARNING) << "dconn_ is NULL"; + DLOG(WARNING, this) << "dconn_ is NULL"; return 0; } return dconn_->push_upload_data_chunk(data, datalen); diff --git a/src/shrpx_http_downstream_connection.cc b/src/shrpx_http_downstream_connection.cc index 116bcfe3..479b5863 100644 --- a/src/shrpx_http_downstream_connection.cc +++ b/src/shrpx_http_downstream_connection.cc @@ -67,8 +67,7 @@ HttpDownstreamConnection::~HttpDownstreamConnection() int HttpDownstreamConnection::attach_downstream(Downstream *downstream) { if(ENABLE_LOG) { - LOG(INFO) << "Attaching downstream connection " << this << " to " - << "downstream " << downstream; + DCLOG(INFO, this) << "Attaching to DOWNSTREAM:" << downstream; } Upstream *upstream = downstream->get_upstream(); if(!bev_) { @@ -87,7 +86,7 @@ int HttpDownstreamConnection::attach_downstream(Downstream *downstream) return SHRPX_ERR_NETWORK; } if(ENABLE_LOG) { - LOG(INFO) << "Connecting to downstream server " << this; + DCLOG(INFO, this) << "Connecting to downstream server"; } } downstream->set_downstream_connection(this); @@ -183,8 +182,8 @@ int HttpDownstreamConnection::push_request_headers() hdrs += "\r\n"; if(ENABLE_LOG) { - LOG(INFO) << "Downstream request headers id=" - << downstream_->get_stream_id() << "\n" << hdrs; + DCLOG(INFO, this) << "HTTP request headers. stream_id=" + << downstream_->get_stream_id() << "\n" << hdrs; } evbuffer *output = bufferevent_get_output(bev_); int rv; @@ -220,20 +219,20 @@ int HttpDownstreamConnection::push_upload_data_chunk res += rv; rv = evbuffer_add(output, chunk_size_hex, rv); if(rv == -1) { - LOG(FATAL) << "evbuffer_add() failed"; + DCLOG(FATAL, this) << "evbuffer_add() failed"; return -1; } } rv = evbuffer_add(output, data, datalen); if(rv == -1) { - LOG(FATAL) << "evbuffer_add() failed"; + DCLOG(FATAL, this) << "evbuffer_add() failed"; return -1; } res += rv; if(chunked) { rv = evbuffer_add(output, "\r\n", 2); if(rv == -1) { - LOG(FATAL) << "evbuffer_add() failed"; + DCLOG(FATAL, this) << "evbuffer_add() failed"; return -1; } res += 2; @@ -246,7 +245,7 @@ int HttpDownstreamConnection::end_upload_data() if(downstream_->get_chunked_request()) { evbuffer *output = bufferevent_get_output(bev_); if(evbuffer_add(output, "0\r\n\r\n", 5) != 0) { - LOG(FATAL) << "evbuffer_add() failed"; + DCLOG(FATAL, this) << "evbuffer_add() failed"; return -1; } } @@ -263,21 +262,21 @@ void idle_eventcb(bufferevent *bev, short events, void *arg) // Downstream was detached before connection established? // This may be safe to be left. if(ENABLE_LOG) { - LOG(INFO) << "Idle downstream connected?" << dconn; + DCLOG(INFO, dconn) << "Idle connection connected?"; } return; } if(events & BEV_EVENT_EOF) { if(ENABLE_LOG) { - LOG(INFO) << "Idle downstream connection EOF " << dconn; + DCLOG(INFO, dconn) << "Idle connection EOF"; } } else if(events & BEV_EVENT_TIMEOUT) { if(ENABLE_LOG) { - LOG(INFO) << "Idle downstream connection timeout " << dconn; + DCLOG(INFO, dconn) << "Idle connection timeout"; } } else if(events & BEV_EVENT_ERROR) { if(ENABLE_LOG) { - LOG(INFO) << "Idle downstream connection error " << dconn; + DCLOG(INFO, dconn) << "Idle connection network error"; } } 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) { if(ENABLE_LOG) { - LOG(INFO) << "Detaching downstream connection " << this << " from " - << "downstream " << downstream; + DCLOG(INFO, this) << "Detaching from DOWNSTREAM:" << downstream; } downstream->set_downstream_connection(0); downstream_ = 0; @@ -434,9 +432,9 @@ int HttpDownstreamConnection::on_read() return 0; } else { if(ENABLE_LOG) { - LOG(INFO) << "Downstream HTTP parser failure: " - << "(" << http_errno_name(htperr) << ") " - << http_errno_description(htperr); + DCLOG(INFO, this) << "HTTP parser failure: " + << "(" << http_errno_name(htperr) << ") " + << http_errno_description(htperr); } return SHRPX_ERR_HTTP_PARSE; } diff --git a/src/shrpx_https_upstream.cc b/src/shrpx_https_upstream.cc index 8c9e2192..179120c4 100644 --- a/src/shrpx_https_upstream.cc +++ b/src/shrpx_https_upstream.cc @@ -74,7 +74,7 @@ int htp_msg_begin(http_parser *htp) HttpsUpstream *upstream; upstream = reinterpret_cast(htp->data); if(ENABLE_LOG) { - LOG(INFO) << "Upstream http request start " << upstream; + ULOG(INFO, upstream) << "HTTP request started"; } upstream->reset_current_header_length(); Downstream *downstream = new Downstream(upstream, 0, 0); @@ -131,7 +131,7 @@ int htp_hdrs_completecb(http_parser *htp) HttpsUpstream *upstream; upstream = reinterpret_cast(htp->data); if(ENABLE_LOG) { - LOG(INFO) << "Upstream http request headers complete " << upstream; + ULOG(INFO, upstream) << "HTTP request headers completed"; } 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) { 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 && @@ -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"; if(bufferevent_write(upstream->get_client_handler()->get_bev(), reply_100, sizeof(reply_100)-1) != 0) { - LOG(FATAL) << "bufferevent_write() faild"; + ULOG(FATAL, upstream) << "bufferevent_write() faild"; return -1; } } @@ -218,11 +218,11 @@ namespace { int htp_msg_completecb(http_parser *htp) { int rv; - if(ENABLE_LOG) { - LOG(INFO) << "Upstream http request complete"; - } HttpsUpstream *upstream; upstream = reinterpret_cast(htp->data); + if(ENABLE_LOG) { + ULOG(INFO, upstream) << "HTTP request completed"; + } Downstream *downstream = upstream->get_downstream(); downstream->set_request_state(Downstream::MSG_COMPLETE); rv = downstream->end_upload_data(); @@ -294,8 +294,9 @@ int HttpsUpstream::on_read() if(downstream) { if(downstream->get_request_state() == Downstream::INITIAL && current_header_length_ > SHRPX_HTTPS_MAX_HEADER_LENGTH) { - LOG(WARNING) << "Request Header too long:" << current_header_length_ - << " bytes"; + ULOG(WARNING, this) << "Request Header too long:" + << current_header_length_ + << " bytes"; get_client_handler()->set_should_close_after_write(true); pause_read(SHRPX_MSG_BLOCK); if(error_reply(400) != 0) { @@ -303,16 +304,16 @@ int HttpsUpstream::on_read() } } else if(downstream->get_output_buffer_full()) { if(ENABLE_LOG) { - LOG(INFO) << "Downstream output buffer is full"; + ULOG(INFO, this) << "Downstream output buffer is full"; } pause_read(SHRPX_NO_BUFFER); } } } else { if(ENABLE_LOG) { - LOG(INFO) << "Upstream http parse failure: " - << "(" << http_errno_name(htperr) << ") " - << http_errno_description(htperr); + ULOG(INFO, this) << "HTTP parse failure: " + << "(" << http_errno_name(htperr) << ") " + << http_errno_description(htperr); } get_client_handler()->set_should_close_after_write(true); pause_read(SHRPX_MSG_BLOCK); @@ -451,18 +452,17 @@ void https_downstream_eventcb(bufferevent *bev, short events, void *ptr) upstream = static_cast(downstream->get_upstream()); if(events & BEV_EVENT_CONNECTED) { if(ENABLE_LOG) { - LOG(INFO) << "Downstream connection established. downstream " - << downstream; + DCLOG(INFO, dconn) << "Connection established"; } } else if(events & BEV_EVENT_EOF) { if(ENABLE_LOG) { - LOG(INFO) << "Downstream EOF. stream_id=" - << downstream->get_stream_id(); + DCLOG(INFO, dconn) << "EOF"; } if(downstream->get_response_state() == Downstream::HEADER_COMPLETE) { // Server may indicate the end of the request by EOF 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); downstream->set_response_state(Downstream::MSG_COMPLETE); @@ -481,7 +481,7 @@ void https_downstream_eventcb(bufferevent *bev, short events, void *ptr) } else { // error if(ENABLE_LOG) { - LOG(INFO) << "Treated as downstream error"; + DCLOG(INFO, dconn) << "Treated as error"; } if(upstream->error_reply(502) != 0) { 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)) { 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) { int status; @@ -532,7 +536,7 @@ int HttpsUpstream::error_reply(int status_code) evbuffer *output = bufferevent_get_output(handler_->get_bev()); if(evbuffer_add(output, header.c_str(), header.size()) != 0 || evbuffer_add(output, html.c_str(), html.size()) != 0) { - LOG(FATAL) << "evbuffer_add() failed"; + ULOG(FATAL, this) << "evbuffer_add() failed"; return -1; } Downstream *downstream = get_downstream(); @@ -577,7 +581,7 @@ Downstream* HttpsUpstream::get_downstream() const int HttpsUpstream::on_downstream_header_complete(Downstream *downstream) { if(ENABLE_LOG) { - LOG(INFO) << "Downstream on_downstream_header_complete"; + DLOG(INFO, downstream) << "HTTP response header completed"; } std::string via_value; char temp[16]; @@ -627,11 +631,11 @@ int HttpsUpstream::on_downstream_header_complete(Downstream *downstream) hdrs += "\r\n"; hdrs += "\r\n"; 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()); if(evbuffer_add(output, hdrs.c_str(), hdrs.size()) != 0) { - LOG(FATAL) << "evbuffer_add() failed"; + ULOG(FATAL, this) << "evbuffer_add() failed"; return -1; } 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", static_cast(len)); if(evbuffer_add(output, chunk_size_hex, rv) != 0) { - LOG(FATAL) << "evbuffer_add() failed"; + ULOG(FATAL, this) << "evbuffer_add() failed"; return -1; } } @@ -663,12 +667,12 @@ int HttpsUpstream::on_downstream_body_complete(Downstream *downstream) if(downstream->get_chunked_response()) { evbuffer *output = bufferevent_get_output(handler_->get_bev()); if(evbuffer_add(output, "0\r\n\r\n", 5) != 0) { - LOG(FATAL) << "evbuffer_add() failed"; + ULOG(FATAL, this) << "evbuffer_add() failed"; return -1; } } if(ENABLE_LOG) { - LOG(INFO) << "Downstream on_downstream_body_complete"; + DLOG(INFO, downstream) << "HTTP response completed"; } if(downstream->get_request_connection_close() || downstream->get_response_connection_close()) { diff --git a/src/shrpx_listen_handler.cc b/src/shrpx_listen_handler.cc index 3c38f874..8cbfc531 100644 --- a/src/shrpx_listen_handler.cc +++ b/src/shrpx_listen_handler.cc @@ -66,13 +66,13 @@ void ListenHandler::create_worker_thread(size_t num) WorkerInfo *info = &workers_[num_worker_]; rv = socketpair(AF_UNIX, SOCK_STREAM, 0, info->sv); if(rv == -1) { - LOG(ERROR) << "socketpair() failed: " << strerror(errno); + LLOG(ERROR, this) << "socketpair() failed: " << strerror(errno); continue; } info->ssl_ctx = ssl_ctx_; rv = pthread_create(&thread, &attr, start_threaded_worker, info); 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) { close(info->sv[j]); } @@ -82,7 +82,7 @@ void ListenHandler::create_worker_thread(size_t num) BEV_OPT_DEFER_CALLBACKS); info->bev = bev; if(ENABLE_LOG) { - LOG(INFO) << "Created thread#" << num_worker_; + LLOG(INFO, this) << "Created thread #" << num_worker_; } ++num_worker_; } @@ -92,7 +92,7 @@ int ListenHandler::accept_connection(evutil_socket_t fd, sockaddr *addr, int addrlen) { if(ENABLE_LOG) { - LOG(INFO) << " Accepted connection. fd=" << fd; + LLOG(INFO, this) << "Accepted connection. fd=" << fd; } if(num_worker_ == 0) { ClientHandler* client = diff --git a/src/shrpx_log.h b/src/shrpx_log.h index a9d29762..07d026f1 100644 --- a/src/shrpx_log.h +++ b/src/shrpx_log.h @@ -35,6 +35,37 @@ namespace shrpx { #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 { INFO, WARNING, ERROR, FATAL }; diff --git a/src/shrpx_spdy_downstream_connection.cc b/src/shrpx_spdy_downstream_connection.cc index b74e72f8..4b7f4790 100644 --- a/src/shrpx_spdy_downstream_connection.cc +++ b/src/shrpx_spdy_downstream_connection.cc @@ -90,8 +90,7 @@ int SpdyDownstreamConnection::init_request_body_buf() int SpdyDownstreamConnection::attach_downstream(Downstream *downstream) { if(ENABLE_LOG) { - LOG(INFO) << "Attaching downstream connection " << this << " to " - << "downstream " << downstream; + DCLOG(INFO, this) << "Attaching to DOWNSTREAM:" << downstream; } if(init_request_body_buf() == -1) { return -1; @@ -109,8 +108,7 @@ int SpdyDownstreamConnection::attach_downstream(Downstream *downstream) void SpdyDownstreamConnection::detach_downstream(Downstream *downstream) { if(ENABLE_LOG) { - LOG(INFO) << "Detaching spdy downstream connection " << this << " from " - << "downstream " << downstream; + DCLOG(INFO, this) << "Detaching from DOWNSTREAM:" << downstream; } downstream->set_downstream_connection(0); downstream_ = 0; @@ -298,9 +296,7 @@ int SpdyDownstreamConnection::push_request_headers() for(size_t i = 0; nv[i]; i += 2) { ss << nv[i] << ": " << nv[i+1] << "\n"; } - LOG(INFO) << "Downstream spdy request headers id=" - << downstream_->get_stream_id() << "\n" - << ss.str(); + DCLOG(INFO, this) << "HTTP request headers\n" << ss.str(); } if(downstream_->get_request_method() == "CONNECT" || @@ -315,7 +311,7 @@ int SpdyDownstreamConnection::push_request_headers() } delete [] nv; if(rv != 0) { - LOG(FATAL) << "spdylay_submit_request() failed"; + DCLOG(FATAL, this) << "spdylay_submit_request() failed"; return -1; } 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); if(rv != 0) { - LOG(FATAL) << "evbuffer_add() failed"; + DCLOG(FATAL, this) << "evbuffer_add() failed"; return -1; } if(downstream_->get_downstream_stream_id() != -1) { diff --git a/src/shrpx_spdy_session.cc b/src/shrpx_spdy_session.cc index ed67ad87..8c15cf08 100644 --- a/src/shrpx_spdy_session.cc +++ b/src/shrpx_spdy_session.cc @@ -65,7 +65,7 @@ SpdySession::~SpdySession() int SpdySession::disconnect() { if(ENABLE_LOG) { - LOG(INFO) << "Downstream spdy session disconnecting " << this; + SSLOG(INFO, this) << "Disconnecting"; } spdylay_session_del(session_); session_ = 0; @@ -121,7 +121,7 @@ void notify_readcb(bufferevent *bev, void *arg) case SpdySession::DISCONNECTED: rv = spdy->initiate_connection(); if(rv != 0) { - LOG(FATAL) << "Downstream spdy could not initiate connection " << spdy; + SSLOG(FATAL, spdy) << "Could not initiate notification connection"; DIE(); } break; @@ -138,12 +138,16 @@ void notify_readcb(bufferevent *bev, void *arg) namespace { void notify_eventcb(bufferevent *bev, short events, void *arg) { + SpdySession *spdy = reinterpret_cast(arg); // TODO should DIE()? 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) { - LOG(ERROR) << "Connection to main thread lost: network error"; + SSLOG(ERROR, spdy) << "Notification connection lost: network error"; } } } // namespace @@ -154,14 +158,14 @@ int SpdySession::init_notification() int sockpair[2]; rv = socketpair(AF_UNIX, SOCK_STREAM, 0, sockpair); if(rv == -1) { - LOG(FATAL) << "socketpair() failed: " << strerror(errno); + SSLOG(FATAL, this) << "socketpair() failed: " << strerror(errno); return -1; } wrbev_ = bufferevent_socket_new(evbase_, sockpair[0], BEV_OPT_CLOSE_ON_FREE| BEV_OPT_DEFER_CALLBACKS); if(!wrbev_) { - LOG(FATAL) << "bufferevent_socket_new() failed"; + SSLOG(FATAL, this) << "bufferevent_socket_new() failed"; for(int i = 0; i < 2; ++i) { close(sockpair[i]); } @@ -171,7 +175,7 @@ int SpdySession::init_notification() BEV_OPT_CLOSE_ON_FREE| BEV_OPT_DEFER_CALLBACKS); if(!rdbev_) { - LOG(FATAL) << "bufferevent_socket_new() failed"; + SSLOG(FATAL, this) << "bufferevent_socket_new() failed"; close(sockpair[1]); return -1; } @@ -213,7 +217,7 @@ void eventcb(bufferevent *bev, short events, void *ptr) SpdySession *spdy = reinterpret_cast(ptr); if(events & BEV_EVENT_CONNECTED) { if(ENABLE_LOG) { - LOG(INFO) << "Downstream spdy connection established. " << spdy; + SSLOG(INFO, spdy) << "Connection established"; } spdy->connected(); 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) { if(ENABLE_LOG) { - LOG(INFO) << "Downstream spdy EOF. " << spdy; + SSLOG(INFO, spdy) << "EOF"; } spdy->disconnect(); } else if(events & (BEV_EVENT_ERROR | BEV_EVENT_TIMEOUT)) { 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(); } @@ -245,13 +253,13 @@ int SpdySession::initiate_connection() int rv; assert(state_ == DISCONNECTED); if(ENABLE_LOG) { - LOG(INFO) << "Downstream spdy initiating connection " << this; + SSLOG(INFO, this) << "Connecting to downstream server"; } ssl_ = SSL_new(ssl_ctx_); if(!ssl_) { - LOG(ERROR) << "SSL_new() failed: " - << ERR_error_string(ERR_get_error(), NULL); + SSLOG(ERROR, this) << "SSL_new() failed: " + << ERR_error_string(ERR_get_error(), NULL); return -1; } @@ -275,9 +283,6 @@ int SpdySession::initiate_connection() bev_ = 0; return SHRPX_ERR_NETWORK; } - if(ENABLE_LOG) { - LOG(INFO) << "Connecting to downstream " << this; - } bufferevent_setwatermark(bev_, EV_READ, 0, SHRPX_READ_WARTER_MARK); bufferevent_enable(bev_, EV_READ); @@ -324,8 +329,8 @@ int SpdySession::submit_request(SpdyDownstreamConnection *dconn, dconn->attach_stream_data(sd); streams_.insert(sd); } else { - LOG(FATAL) << "spdylay_submit_request() failed: " - << spdylay_strerror(rv); + SSLOG(FATAL, this) << "spdylay_submit_request() failed: " + << spdylay_strerror(rv); delete sd; return -1; } @@ -338,8 +343,8 @@ int SpdySession::submit_rst_stream(SpdyDownstreamConnection *dconn, assert(state_ == CONNECTED); int rv = spdylay_submit_rst_stream(session_, stream_id, status_code); if(rv != 0) { - LOG(FATAL) << "spdylay_submit_rst_stream() failed: " - << spdylay_strerror(rv); + SSLOG(FATAL, this) << "spdylay_submit_rst_stream() failed: " + << spdylay_strerror(rv); return -1; } return 0; @@ -354,8 +359,8 @@ int SpdySession::submit_window_update(SpdyDownstreamConnection *dconn, stream_id = dconn->get_downstream()->get_downstream_stream_id(); rv = spdylay_submit_window_update(session_, stream_id, amount); if(rv < SPDYLAY_ERR_FATAL) { - LOG(FATAL) << "spdylay_submit_window_update() failed: " - << spdylay_strerror(rv); + SSLOG(FATAL, this) << "spdylay_submit_window_update() failed: " + << spdylay_strerror(rv); return -1; } return 0; @@ -382,8 +387,8 @@ int SpdySession::resume_data(SpdyDownstreamConnection *dconn) case SPDYLAY_ERR_INVALID_ARGUMENT: return 0; default: - LOG(FATAL) << "spdylay_resume_session() failed: " - << spdylay_strerror(rv); + SSLOG(FATAL, this) << "spdylay_resume_session() failed: " + << spdylay_strerror(rv); return -1; } } @@ -417,7 +422,7 @@ ssize_t send_callback(spdylay_session *session, rv = evbuffer_add(output, data, len); if(rv == -1) { - LOG(FATAL) << "evbuffer_add() failed"; + SSLOG(FATAL, spdy) << "evbuffer_add() failed"; return SPDYLAY_ERR_CALLBACK_FAILURE; } else { return len; @@ -450,10 +455,11 @@ void on_stream_close_callback void *user_data) { int rv; - if(ENABLE_LOG) { - LOG(INFO) << "Downstream spdy Stream " << stream_id << " is being closed"; - } SpdySession *spdy = reinterpret_cast(user_data); + if(ENABLE_LOG) { + SSLOG(INFO, spdy) << "Stream stream_id=" << stream_id + << " is being closed"; + } StreamData *sd; sd = reinterpret_cast (spdylay_session_get_stream_user_data(session, stream_id)); @@ -497,8 +503,8 @@ void on_ctrl_recv_callback switch(type) { case SPDYLAY_SYN_STREAM: if(ENABLE_LOG) { - LOG(INFO) << "Downstream spdy received upstream SYN_STREAM stream_id=" - << frame->syn_stream.stream_id; + SSLOG(INFO, spdy) << "Received upstream SYN_STREAM stream_id=" + << frame->syn_stream.stream_id; } // We just respond pushed stream with RST_STREAM. 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) { ss << nv[i] << ": " << nv[i+1] << "\n"; } - LOG(INFO) << "Downstream spdy response headers id=" - << frame->syn_reply.stream_id - << "\n" << ss.str(); + SSLOG(INFO, spdy) << "HTTP response headers. stream_id=" + << frame->syn_reply.stream_id + << "\n" << ss.str(); } 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); if(sd->dconn->get_recv_window_size() > spdy->get_initial_window_size()) { if(ENABLE_LOG) { - LOG(INFO) << "Flow control error: recv_window_size=" - << sd->dconn->get_recv_window_size() - << ", initial_window_size=" - << spdy->get_initial_window_size(); + SSLOG(INFO, spdy) << "Flow control error: recv_window_size=" + << sd->dconn->get_recv_window_size() + << ", initial_window_size=" + << spdy->get_initial_window_size(); } spdylay_submit_rst_stream(session, stream_id, SPDYLAY_FLOW_CONTROL_ERROR); @@ -691,13 +697,13 @@ void on_ctrl_not_send_callback(spdylay_session *session, spdylay_frame *frame, int error_code, void *user_data) { - LOG(WARNING) << "Failed to send control frame type=" << type << ", " - << "error_code=" << error_code << ":" - << spdylay_strerror(error_code); + SpdySession *spdy = reinterpret_cast(user_data); + SSLOG(WARNING, spdy) << "Failed to send control frame type=" << type << ", " + << "error_code=" << error_code << ":" + << spdylay_strerror(error_code); if(type == SPDYLAY_SYN_STREAM) { // To avoid stream hanging around, flag Downstream::MSG_RESET and // terminate the upstream and downstream connections. - SpdySession *spdy = reinterpret_cast(user_data); StreamData *sd; sd = reinterpret_cast (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, void *user_data) { + SpdySession *spdy = reinterpret_cast(user_data); if(ENABLE_LOG) { - LOG(INFO) << "Failed to parse received control frame. type=" << type - << ", error_code=" << error_code << ":" - << spdylay_strerror(error_code); + SSLOG(INFO, spdy) << "Failed to parse received control frame. type=" + << type + << ", error_code=" << error_code << ":" + << spdylay_strerror(error_code); } } } // namespace @@ -742,8 +750,9 @@ void on_unknown_ctrl_recv_callback(spdylay_session *session, const uint8_t *payload, size_t payloadlen, void *user_data) { + SpdySession *spdy = reinterpret_cast(user_data); if(ENABLE_LOG) { - LOG(INFO) << "Received unknown control frame."; + SSLOG(INFO, spdy) << "Received unknown control frame"; } } } // namespace @@ -757,7 +766,7 @@ int SpdySession::on_connect() if(ENABLE_LOG) { 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); if(!version) { @@ -827,12 +836,12 @@ int SpdySession::on_read() int rv = 0; if((rv = spdylay_session_recv(session_)) < 0) { if(rv != SPDYLAY_ERR_EOF) { - LOG(ERROR) << "spdylay_session_recv() returned error: " - << spdylay_strerror(rv); + SSLOG(ERROR, this) << "spdylay_session_recv() returned error: " + << spdylay_strerror(rv); } } else if((rv = spdylay_session_send(session_)) < 0) { - LOG(ERROR) << "spdylay_session_send() returned error: " - << spdylay_strerror(rv); + SSLOG(ERROR, this) << "spdylay_session_send() returned error: " + << spdylay_strerror(rv); } // if(rv == 0) { // if(spdylay_session_want_read(session_) == 0 && @@ -855,8 +864,8 @@ int SpdySession::send() { int rv = 0; if((rv = spdylay_session_send(session_)) < 0) { - LOG(ERROR) << "spdylay_session_send() returned error: " - << spdylay_strerror(rv); + SSLOG(ERROR, this) << "spdylay_session_send() returned error: " + << spdylay_strerror(rv); } // if(rv == 0) { // if(spdylay_session_want_read(session_) == 0 && diff --git a/src/shrpx_spdy_upstream.cc b/src/shrpx_spdy_upstream.cc index b3719032..256bed95 100644 --- a/src/shrpx_spdy_upstream.cc +++ b/src/shrpx_spdy_upstream.cc @@ -61,7 +61,7 @@ ssize_t send_callback(spdylay_session *session, rv = evbuffer_add(output, data, len); if(rv == -1) { - LOG(FATAL) << "evbuffer_add() failed"; + ULOG(FATAL, upstream) << "evbuffer_add() failed"; return SPDYLAY_ERR_CALLBACK_FAILURE; } else { return len; @@ -93,10 +93,11 @@ void on_stream_close_callback (spdylay_session *session, int32_t stream_id, spdylay_status_code status_code, void *user_data) { - if(ENABLE_LOG) { - LOG(INFO) << "Upstream spdy Stream " << stream_id << " is being closed"; - } SpdyUpstream *upstream = reinterpret_cast(user_data); + if(ENABLE_LOG) { + ULOG(INFO, upstream) << "Stream stream_id=" << stream_id + << " is being closed"; + } Downstream *downstream = upstream->find_downstream(stream_id); if(get_config()->accesslog) { upstream_spdy_stream_close(upstream->get_client_handler()->get_ipaddr(), @@ -146,8 +147,8 @@ void on_ctrl_recv_callback switch(type) { case SPDYLAY_SYN_STREAM: { if(ENABLE_LOG) { - LOG(INFO) << "Upstream spdy received upstream SYN_STREAM stream_id=" - << frame->syn_stream.stream_id; + ULOG(INFO, upstream) << "Received upstream SYN_STREAM stream_id=" + << frame->syn_stream.stream_id; } Downstream *downstream; downstream = new Downstream(upstream, @@ -199,9 +200,9 @@ void on_ctrl_recv_callback for(size_t i = 0; nv[i]; i += 2) { ss << nv[i] << ": " << nv[i+1] << "\n"; } - LOG(INFO) << "Upstream spdy request headers id=" - << downstream->get_stream_id() - << "\n" << ss.str(); + ULOG(INFO, upstream) << "HTTP request headers. stream_id=" + << downstream->get_stream_id() + << "\n" << ss.str(); } DownstreamConnection *dconn; @@ -224,11 +225,6 @@ void on_ctrl_recv_callback } downstream->set_request_state(Downstream::HEADER_COMPLETE); 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); } break; @@ -257,21 +253,16 @@ void on_data_chunk_recv_callback(spdylay_session *session, if(downstream->get_recv_window_size() > upstream->get_initial_window_size()) { if(ENABLE_LOG) { - LOG(INFO) << "Flow control error: recv_window_size=" - << downstream->get_recv_window_size() - << ", initial_window_size=" - << upstream->get_initial_window_size(); + ULOG(INFO, upstream) << "Flow control error: recv_window_size=" + << downstream->get_recv_window_size() + << ", initial_window_size=" + << upstream->get_initial_window_size(); } upstream->rst_stream(downstream, SPDYLAY_FLOW_CONTROL_ERROR); return; } } 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); } } @@ -284,12 +275,12 @@ void on_ctrl_not_send_callback(spdylay_session *session, spdylay_frame *frame, int error_code, void *user_data) { - LOG(WARNING) << "Failed to send control frame type=" << type << ", " - << "error_code=" << error_code << ":" - << spdylay_strerror(error_code); + SpdyUpstream *upstream = reinterpret_cast(user_data); + ULOG(WARNING, upstream) << "Failed to send control frame type=" << type + << ", error_code=" << error_code << ":" + << spdylay_strerror(error_code); if(type == SPDYLAY_SYN_REPLY) { // To avoid stream hanging around, issue RST_STREAM. - SpdyUpstream *upstream = reinterpret_cast(user_data); int32_t stream_id = frame->syn_reply.stream_id; Downstream *downstream = upstream->find_downstream(stream_id); if(downstream) { @@ -307,10 +298,12 @@ void on_ctrl_recv_parse_error_callback(spdylay_session *session, size_t payloadlen, int error_code, void *user_data) { + SpdyUpstream *upstream = reinterpret_cast(user_data); if(ENABLE_LOG) { - LOG(INFO) << "Failed to parse received control frame. type=" << type - << ", error_code=" << error_code << ":" - << spdylay_strerror(error_code); + ULOG(INFO, upstream) << "Failed to parse received control frame. type=" + << type + << ", error_code=" << error_code << ":" + << spdylay_strerror(error_code); } } } // namespace @@ -321,8 +314,9 @@ void on_unknown_ctrl_recv_callback(spdylay_session *session, const uint8_t *payload, size_t payloadlen, void *user_data) { + SpdyUpstream *upstream = reinterpret_cast(user_data); if(ENABLE_LOG) { - LOG(INFO) << "Received unknown control frame."; + ULOG(INFO, upstream) << "Received unknown control frame."; } } } // namespace @@ -391,18 +385,18 @@ int SpdyUpstream::on_read() int rv = 0; if((rv = spdylay_session_recv(session_)) < 0) { if(rv != SPDYLAY_ERR_EOF) { - LOG(ERROR) << "spdylay_session_recv() returned error: " - << spdylay_strerror(rv); + ULOG(ERROR, this) << "spdylay_session_recv() returned error: " + << spdylay_strerror(rv); } } else if((rv = spdylay_session_send(session_)) < 0) { - LOG(ERROR) << "spdylay_session_send() returned error: " - << spdylay_strerror(rv); + ULOG(ERROR, this) << "spdylay_session_send() returned error: " + << spdylay_strerror(rv); } if(rv == 0) { if(spdylay_session_want_read(session_) == 0 && spdylay_session_want_write(session_) == 0) { 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; } @@ -420,14 +414,14 @@ int SpdyUpstream::send() { int rv = 0; if((rv = spdylay_session_send(session_)) < 0) { - LOG(ERROR) << "spdylay_session_send() returned error: " - << spdylay_strerror(rv); + ULOG(ERROR, this) << "spdylay_session_send() returned error: " + << spdylay_strerror(rv); } if(rv == 0) { if(spdylay_session_want_read(session_) == 0 && spdylay_session_want_write(session_) == 0) { 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; } @@ -463,7 +457,7 @@ void spdy_downstream_readcb(bufferevent *bev, void *ptr) int rv = downstream->on_read(); if(rv != 0) { if(ENABLE_LOG) { - LOG(INFO) << "Downstream HTTP parser failure"; + DCLOG(INFO, dconn) << "HTTP parser failure"; } if(downstream->get_response_state() == Downstream::HEADER_COMPLETE) { upstream->rst_stream(downstream, SPDYLAY_INTERNAL_ERROR); @@ -516,13 +510,12 @@ void spdy_downstream_eventcb(bufferevent *bev, short events, void *ptr) upstream = static_cast(downstream->get_upstream()); if(events & BEV_EVENT_CONNECTED) { if(ENABLE_LOG) { - LOG(INFO) << "Downstream connection established. Downstream " - << downstream; + DCLOG(INFO, dconn) << "Connection established. stream_id=" + << downstream->get_stream_id(); } } else if(events & BEV_EVENT_EOF) { if(ENABLE_LOG) { - LOG(INFO) << "Downstream 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 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) { // Server may indicate the end of the request by EOF 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); 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)) { if(ENABLE_LOG) { if(events & BEV_EVENT_ERROR) { - LOG(INFO) << "Downstream network error: " - << evutil_socket_error_to_string(EVUTIL_SOCKET_ERROR()); + DCLOG(INFO, dconn) << "Downstream network error: " + << evutil_socket_error_to_string + (EVUTIL_SOCKET_ERROR()); } else { - LOG(INFO) << "Downstream timeout"; + DCLOG(INFO, dconn) << "Timeout"; } 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) { @@ -619,15 +613,15 @@ void spdy_downstream_eventcb(bufferevent *bev, short events, void *ptr) int SpdyUpstream::rst_stream(Downstream *downstream, int status_code) { if(ENABLE_LOG) { - LOG(INFO) << "RST_STREAM stream_id=" - << downstream->get_stream_id(); + ULOG(INFO, this) << "RST_STREAM stream_id=" + << downstream->get_stream_id(); } int rv; rv = spdylay_submit_rst_stream(session_, downstream->get_stream_id(), status_code); if(rv < SPDYLAY_ERR_FATAL) { - LOG(FATAL) << "spdylay_submit_rst_stream() failed: " - << spdylay_strerror(rv); + ULOG(FATAL, this) << "spdylay_submit_rst_stream() failed: " + << spdylay_strerror(rv); DIE(); } return 0; @@ -640,8 +634,8 @@ int SpdyUpstream::window_update(Downstream *downstream) downstream->get_recv_window_size()); downstream->set_recv_window_size(0); if(rv < SPDYLAY_ERR_FATAL) { - LOG(FATAL) << "spdylay_submit_window_update() failed: " - << spdylay_strerror(rv); + ULOG(FATAL, this) << "spdylay_submit_window_update() failed: " + << spdylay_strerror(rv); DIE(); } return 0; @@ -680,7 +674,7 @@ int SpdyUpstream::error_reply(Downstream *downstream, int status_code) evbuffer *body = downstream->get_response_body_buf(); rv = evbuffer_add(body, html.c_str(), html.size()); if(rv == -1) { - LOG(FATAL) << "evbuffer_add() failed"; + ULOG(FATAL, this) << "evbuffer_add() failed"; return -1; } 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, &data_prd); if(rv < SPDYLAY_ERR_FATAL) { - LOG(FATAL) << "spdylay_submit_response() failed: " - << spdylay_strerror(rv); + ULOG(FATAL, this) << "spdylay_submit_response() failed: " + << spdylay_strerror(rv); DIE(); } return 0; @@ -747,7 +741,7 @@ spdylay_session* SpdyUpstream::get_spdy_session() int SpdyUpstream::on_downstream_header_complete(Downstream *downstream) { 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(); // 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) { ss << nv[i] << ": " << nv[i+1] << "\n"; } - LOG(INFO) << "Upstream spdy response headers id=" - << downstream->get_stream_id() << "\n" - << ss.str(); + ULOG(INFO, this) << "HTTP response headers. stream_id=" + << downstream->get_stream_id() << "\n" + << ss.str(); } spdylay_data_provider data_prd; data_prd.source.ptr = downstream; @@ -798,7 +792,7 @@ int SpdyUpstream::on_downstream_header_complete(Downstream *downstream) &data_prd); delete [] nv; if(rv != 0) { - LOG(FATAL) << "spdylay_submit_response() failed"; + ULOG(FATAL, this) << "spdylay_submit_response() failed"; return -1; } return 0; @@ -812,7 +806,7 @@ int SpdyUpstream::on_downstream_body(Downstream *downstream, evbuffer *body = downstream->get_response_body_buf(); int rv = evbuffer_add(body, data, len); if(rv != 0) { - LOG(FATAL) << "evbuffer_add() failed"; + ULOG(FATAL, this) << "evbuffer_add() failed"; return -1; } 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) { 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()); return 0; diff --git a/src/shrpx_thread_event_receiver.cc b/src/shrpx_thread_event_receiver.cc index dbcd692f..0603e03d 100644 --- a/src/shrpx_thread_event_receiver.cc +++ b/src/shrpx_thread_event_receiver.cc @@ -48,8 +48,8 @@ void ThreadEventReceiver::on_read(bufferevent *bev) WorkerEvent wev; evbuffer_remove(input, &wev, sizeof(WorkerEvent)); if(ENABLE_LOG) { - LOG(INFO) << "WorkerEvent: client_fd=" << wev.client_fd - << ", addrlen=" << wev.client_addrlen; + TLOG(INFO, this) << "WorkerEvent: client_fd=" << wev.client_fd + << ", addrlen=" << wev.client_addrlen; } event_base *evbase = bufferevent_get_base(bev); ClientHandler *client_handler; @@ -60,11 +60,11 @@ void ThreadEventReceiver::on_read(bufferevent *bev) if(client_handler) { client_handler->set_spdy_session(spdy_); if(ENABLE_LOG) { - LOG(INFO) << "ClientHandler " << client_handler << " created"; + TLOG(INFO, this) << "CLIENT_HANDLER:" << client_handler << " created"; } } else { if(ENABLE_LOG) { - LOG(ERROR) << "ClientHandler creation failed"; + TLOG(ERROR, this) << "ClientHandler creation failed"; } close(wev.client_fd); }