diff --git a/src/dht_proxy_client.cpp b/src/dht_proxy_client.cpp index 25c3b919985a0954483d928c2276006b127f454f..ddef5634edb307c49e67a8f5936fec899e068348 100644 --- a/src/dht_proxy_client.cpp +++ b/src/dht_proxy_client.cpp @@ -93,12 +93,12 @@ DhtProxyClient::DhtProxyClient( httpClientThread_ = std::thread([this](){ try { if (logger_) - logger_->d("[proxy:client] starting io context"); + logger_->d("[proxy:client] starting io_context"); // Ensures the httpContext_ won't run out of work auto work = asio::make_work_guard(httpContext_); httpContext_.run(); if (logger_) - logger_->d("[proxy:client] http client io context stopped"); + logger_->d("[proxy:client] http client io_context stopped"); } catch(const std::exception& ex){ if (logger_) @@ -116,7 +116,7 @@ DhtProxyClient::startProxy() return; if (logger_) - logger_->d("[proxy:client] staring proxy with %s", serverHostService_.first.c_str()); + logger_->d("[proxy:client] start proxy with %s", serverHostService_.first.c_str()); nextProxyConfirmationTimer_ = std::make_shared<asio::steady_timer>(httpContext_, std::chrono::steady_clock::now()); nextProxyConfirmationTimer_->async_wait(std::bind(&DhtProxyClient::handleProxyConfirm, this, std::placeholders::_1)); @@ -190,7 +190,7 @@ DhtProxyClient::cancelAllListeners() { std::lock_guard<std::mutex> lock(searchLock_); if (logger_) - logger_->d("[proxy:client] [listeners:cancel:all] [%zu searches]", searches_.size()); + logger_->d("[proxy:client] [listeners] [%zu searches] cancel all", searches_.size()); for (auto& s: searches_) { s.second.ops.cancelAll([&](size_t token){ auto l = s.second.listeners.find(token); @@ -535,7 +535,7 @@ DhtProxyClient::cancelPut(const InfoHash& key, const Value::Id& id) if (search == searches_.end()) return false; if (logger_) - logger_->d("[proxy:client] [put:cancel] [search %s]", key.to_c_str()); + logger_->d("[proxy:client] [put] [search %s] cancel", key.to_c_str()); return search->second.puts.erase(id) > 0; } @@ -617,7 +617,7 @@ DhtProxyClient::queryProxyInfo(std::shared_ptr<InfoState> infoState, const sa_fa std::vector<asio::ip::tcp::endpoint>&& endpoints) { if (logger_) - logger_->d("[proxy:client] [status:ipv%i] query info", family == AF_INET ? 4 : 6); + logger_->d("[proxy:client] [status] query ipv%i info", family == AF_INET ? 4 : 6); auto request = std::make_shared<http::Request>(httpContext_, std::move(endpoints), logger_); auto reqid = request->id(); try { @@ -632,7 +632,7 @@ DhtProxyClient::queryProxyInfo(std::shared_ptr<InfoState> infoState, const sa_fa request->add_on_status_callback([this, ok, family](unsigned int status_code){ if (status_code != 200){ if (logger_) - logger_->e("[proxy:client] [status:ipv%i] status code error: %i", family, status_code); + logger_->e("[proxy:client] [status] ipv%i status code error: %i", family, status_code); ok->store(false); } }); @@ -662,7 +662,7 @@ DhtProxyClient::queryProxyInfo(std::shared_ptr<InfoState> infoState, const sa_fa if (state == http::Request::State::DONE){ if (response.status_code != 200) if (logger_) - logger_->e("[proxy:client] [status:ipv%i] failed with code=%i", + logger_->e("[proxy:client] [status] ipv%i failed with code=%i", family == AF_INET ? 4 : 6, response.status_code); if (infoState->cancel.load()){ // pass along the failures @@ -1010,7 +1010,7 @@ DhtProxyClient::sendListen(const restinio::http_request_header_t header, request->add_on_status_callback([this, reqid, opstate](unsigned int status_code){ if (status_code != 200){ if (logger_) - logger_->e("[proxy:client] [listen:send] %i status error: %i", reqid, status_code); + logger_->e("[proxy:client] [listen] send request #%i status error: %i", reqid, status_code); opstate->ok.store(false); } }); @@ -1049,7 +1049,7 @@ DhtProxyClient::sendListen(const restinio::http_request_header_t header, } } catch(const std::exception& e) { if (logger_) - logger_->e("[proxy:client] [listen:send] %i error in parsing: %s", reqid, e.what()); + logger_->e("[proxy:client] [listen] request #%i error in parsing: %s", reqid, e.what()); opstate->ok.store(false); } }); @@ -1058,7 +1058,7 @@ DhtProxyClient::sendListen(const restinio::http_request_header_t header, if (state == http::Request::State::DONE){ if (response.status_code != 200) if (logger_) - logger_->e("[proxy:client] [listen:send] %i failed with code=%i", + logger_->e("[proxy:client] [listen] send request #%i failed with code=%i", reqid, response.status_code); requests_.erase(reqid); } @@ -1070,7 +1070,7 @@ DhtProxyClient::sendListen(const restinio::http_request_header_t header, } catch (const std::exception &e){ if (logger_) - logger_->e("[proxy:client] [listen:send] %i failed: %s", reqid, e.what()); + logger_->e("[proxy:client] [listen] request #%i failed: %s", reqid, e.what()); requests_.erase(reqid); } } @@ -1104,7 +1104,7 @@ DhtProxyClient::restartListeners() if (isDestroying_) return; if (logger_) - logger_->d("[proxy:client] [listeners:restart] refresh permanent puts"); + logger_->d("[proxy:client] [listeners] refresh permanent puts"); std::lock_guard<std::mutex> lock(searchLock_); for (auto& search : searches_) { @@ -1127,7 +1127,7 @@ DhtProxyClient::restartListeners() } if (not deviceKey_.empty()) { if (logger_) - logger_->d("[proxy:client] [listeners:restart] resubscribe due to a connectivity change"); + logger_->d("[proxy:client] [listeners] resubscribe due to a connectivity change"); // Connectivity changed, refresh all subscribe for (auto& search : searches_) for (auto& listener : search.second.listeners) @@ -1136,7 +1136,7 @@ DhtProxyClient::restartListeners() return; } if (logger_) - logger_->d("[proxy:client] [listeners:restart] restarting listeners"); + logger_->d("[proxy:client] [listeners] restarting listeners"); for (auto& search: searches_) { for (auto& l: search.second.listeners) { auto& listener = l.second; @@ -1206,7 +1206,7 @@ DhtProxyClient::pushNotificationReceived(const std::map<std::string, std::string if (list.second.opstate->stop) continue; if (logger_) - logger_->d("[proxy:client] [push:received] [search %s] handling", key.to_c_str()); + logger_->d("[proxy:client] [push] [search %s] received", key.to_c_str()); auto expired = notification.find("exp"); auto token = list.first; auto opstate = list.second.opstate; @@ -1250,7 +1250,7 @@ DhtProxyClient::pushNotificationReceived(const std::map<std::string, std::string } } catch (const std::exception& e) { if (logger_) - logger_->e("[proxy:client] [push:received] error handling: %s", e.what()); + logger_->e("[proxy:client] [push] receive error: %s", e.what()); } #else (void) notification; @@ -1264,7 +1264,7 @@ DhtProxyClient::resubscribe(const InfoHash& key, const size_t token, Listener& l if (deviceKey_.empty()) return; if (logger_) - logger_->d("[proxy:client] [resubscribe] [search %s] resubscribe push listener", key.to_c_str()); + logger_->d("[proxy:client] [resubscribe] [search %s]", key.to_c_str()); auto opstate = listener.opstate; opstate->stop = true; diff --git a/src/http.cpp b/src/http.cpp index 7ed02a62587e7fee9f5bdd3dcaaeabb980871a67..b0e44401fd9ea4c044b63b5bc047762bfb67649e 100644 --- a/src/http.cpp +++ b/src/http.cpp @@ -43,12 +43,12 @@ Connection::Connection(asio::io_context& ctx, const bool ssl, std::shared_ptr<dh ssl_ctx_->set_verify_mode(asio::ssl::verify_none); ssl_socket_ = std::make_unique<ssl_socket_t>(ctx_, ssl_ctx_); if (logger_) - logger_->d("[http:client] [connection:%i] [ssl] https init", id_); + logger_->d("[http:client] [connection:%i] start https session", id_); } else { socket_ = std::make_unique<socket_t>(ctx); if (logger_) - logger_->d("[http:client] [connection:%i] http init", id_); + logger_->d("[http:client] [connection:%i] start http session", id_); } } @@ -67,12 +67,10 @@ Connection::Connection(asio::io_context& ctx, std::shared_ptr<dht::crypto::Certi if (ec) throw std::runtime_error("Error setting certificate: " + ec.message()); else if (logger_) - logger_->d("[http:client] [connection:%i] [ssl] using %s certificate", id_, certificate->getUID().c_str()); + logger_->d("[http:client] [connection:%i] start https session with %s", id_, certificate->getUID().c_str()); ssl_ctx_->set_verify_mode(asio::ssl::verify_peer | asio::ssl::verify_fail_if_no_peer_cert); ssl_socket_ = std::make_unique<ssl_socket_t>(ctx_, ssl_ctx_); - if (logger_) - logger_->d("[http:client] [connection:%i] [ssl] https init", id_); } Connection::~Connection() @@ -136,7 +134,7 @@ Connection::set_endpoint(const asio::ip::tcp::endpoint& endpoint, const asio::ss X509* cert = X509_STORE_CTX_get_current_cert(ctx.native_handle()); X509_NAME_oneline(X509_get_subject_name(cert), subject_name, 256); if (logger_) - logger_->d("[http:client] [connection:%i] [ssl] verifying %s", id_, subject_name); + logger_->d("[http:client] [connection:%i] verify certificate: %s", id_, subject_name); // run the verification auto verifier = asio::ssl::rfc2818_verification(hostname); bool verified = verifier(preverified, ctx); @@ -148,7 +146,7 @@ Connection::set_endpoint(const asio::ip::tcp::endpoint& endpoint, const asio::ss } ); if (logger_) - logger_->d("[http:client] [connection:%i] [ssl] verifying %s compliance to RFC 2818", id_, hostname.c_str()); + logger_->d("[http:client] [connection:%i] verify %s compliance to RFC 2818", id_, hostname.c_str()); } } @@ -199,9 +197,9 @@ Connection::async_handshake(HandlerCb cb) { auto verify_ec = SSL_get_verify_result(ssl_socket_->asio_ssl_stream().native_handle()); if (verify_ec == X509_V_ERR_SELF_SIGNED_CERT_IN_CHAIN /*19*/ and logger_) - logger_->d("[http:client] [connection:%i] [handshake:ssl] allowing self-signed certificate", id_); + logger_->d("[http:client] [connection:%i] allow self-signed certificate in handshake", id_); else if (verify_ec != X509_V_OK and logger_) - logger_->e("[http:client] [connection:%i] [handshake:ssl] verify error: %i", id_, verify_ec); + logger_->e("[http:client] [connection:%i] verify handshake error: %i", id_, verify_ec); if (cb) cb(ec); }); @@ -381,9 +379,9 @@ Resolver::resolve(const std::string host, const std::string service) else { for (auto it = endpoints.begin(); it != endpoints.end(); ++it){ asio::ip::tcp::endpoint endpoint = *it; - logger_->d("[http:client] [resolver] resolved %s:%s: address=%s ipv%i", - host.c_str(), service.c_str(), endpoint.address().to_string().c_str(), - endpoint.address().is_v6() ? 6 : 4); + logger_->d("[http:client] [resolver] %s:%s endpoint (ipv%i): %s", + host.c_str(), service.c_str(), endpoint.address().is_v6() ? 6 : 4, + endpoint.address().to_string().c_str()); } } } @@ -668,7 +666,7 @@ Request::connect(std::vector<asio::ip::tcp::endpoint>&& endpoints, HandlerCb cb) { if (endpoints.empty()){ if (logger_) - logger_->e("[http:client] [request:%i] [connect] no endpoints provided", id_); + logger_->e("[http:client] [request:%i] connect: no endpoints provided", id_); if (cb) cb(asio::error::connection_aborted); return; @@ -677,7 +675,7 @@ Request::connect(std::vector<asio::ip::tcp::endpoint>&& endpoints, HandlerCb cb) std::string eps = ""; for (auto& endpoint : endpoints) eps.append(endpoint.address().to_string() + " "); - logger_->d("[http:client] [request:%i] [connect] begin endpoints { %s}", id_, eps.c_str()); + logger_->d("[http:client] [request:%i] connect begin: %s", id_, eps.c_str()); } if (certificate_) conn_ = std::make_shared<Connection>(ctx_, certificate_, logger_); @@ -692,10 +690,10 @@ Request::connect(std::vector<asio::ip::tcp::endpoint>&& endpoints, HandlerCb cb) if (ec == asio::error::operation_aborted) return; else if (ec and logger_) - logger_->e("[http:client] [request:%i] [connect] failed with all endpoints", id_); + logger_->e("[http:client] [request:%i] connect: failed with all endpoints", id_); else { if (logger_) - logger_->d("[http:client] [request:%i] [connect] success", id_); + logger_->d("[http:client] [request:%i] connect success", id_); if (!certificate_) conn_->set_endpoint(endpoint, asio::ssl::verify_none); @@ -705,9 +703,9 @@ Request::connect(std::vector<asio::ip::tcp::endpoint>&& endpoints, HandlerCb cb) if (conn_->is_ssl()){ conn_->async_handshake([this, cb](const asio::error_code& ec){ if (ec and logger_) - logger_->e("[http:client] [request:%i] [ssl:handshake] error: %s", id_, ec.message().c_str()); + logger_->e("[http:client] [request:%i] handshake error: %s", id_, ec.message().c_str()); else if (logger_) - logger_->d("[http:client] [request:%i] [ssl:handshake] secure channel established", id_); + logger_->d("[http:client] [request:%i] handshake success", id_); if (cb) cb(ec); }); @@ -728,7 +726,7 @@ Request::send() std::vector<asio::ip::tcp::endpoint> endpoints){ if (ec){ if (logger_) - logger_->e("[http:client] [request:%i] [send] resolve error: %s", id_, ec.message().c_str()); + logger_->e("[http:client] [request:%i] resolve error: %s", id_, ec.message().c_str()); terminate(asio::error::connection_aborted); } else if (!conn_ or !conn_->is_open()){ @@ -750,17 +748,16 @@ void Request::post() { if (!conn_ or !conn_->is_open()){ - if (logger_) - logger_->e("[http:client] [request:%i] [post] closed connection", id_); terminate(asio::error::not_connected); return; } build(); init_parser(); - if (logger_) - logger_->d("[http:client] [request:%i] [post]\n%s", id_, request_.c_str()); - + if (logger_){ + std::string header; std::getline(std::istringstream(request_), header); + logger_->d("[http:client] [request:%i] send: %s", id_, header.c_str()); + } // write the request to buffer std::ostream request_stream(&conn_->input()); request_stream << request_; @@ -776,9 +773,8 @@ Request::terminate(const asio::error_code& ec) if (finishing_.load()) return; - if (ec != asio::error::eof and ec != asio::error::operation_aborted) - if (logger_) - logger_->e("[http:client] [request:%i] end with error: %s", id_, ec.message().c_str()); + if (ec != asio::error::eof and ec != asio::error::operation_aborted and logger_) + logger_->e("[http:client] [request:%i] end with error: %s", id_, ec.message().c_str()); finishing_.store(true); @@ -796,7 +792,6 @@ Request::terminate(const asio::error_code& ec) if (logger_) logger_->d("[http:client] [request:%i] done", id_); - notify_state_change(State::DONE); } @@ -806,20 +801,15 @@ Request::handle_request(const asio::error_code& ec) if (ec == asio::error::operation_aborted) return; else if (ec and ec != asio::error::eof){ - if (logger_) - logger_->e("[http:client] [request:%i] [write] error: %s", id_, ec.message().c_str()); terminate(ec); return; } if (!conn_->is_open()){ - if (logger_) - logger_->e("[http:client] [request:%i] [write] closed connection", id_); terminate(asio::error::not_connected); return; } if (logger_) - logger_->d("[http:client] [request:%i] [write] success", id_); - + logger_->d("[http:client] [request:%i] send success", id_); // read response notify_state_change(State::RECEIVING); conn_->async_read_until(HTTP_HEADER_DELIM, std::bind(&Request::handle_response_header, @@ -832,8 +822,6 @@ Request::handle_response_header(const asio::error_code& ec) if (ec == asio::error::operation_aborted) return; else if ((ec == asio::error::eof) or (ec == asio::error::connection_reset)){ - if (logger_) - logger_->e("[http:client] [request:%i] [read:header] error: %s", id_, ec.message().c_str()); terminate(ec); return; } @@ -842,11 +830,11 @@ Request::handle_response_header(const asio::error_code& ec) return; } if (!conn_->is_open()){ - if (logger_) - logger_->e("[http:client] [request:%i] [read:header] closed connection", id_); terminate(asio::error::not_connected); return; } + if (logger_) + logger_->d("[http:client] [request:%i] response headers received", id_); // read the header std::string header; std::string headers; @@ -855,9 +843,6 @@ Request::handle_response_header(const asio::error_code& ec) headers.append(header + "\n"); } headers.append("\n"); - if (logger_) - logger_->d("[http:client] [request:%i] [read:header]\n%s", id_, headers.c_str()); - // parse the headers parse_request(headers); @@ -899,17 +884,16 @@ Request::handle_response_body(const asio::error_code& ec, const size_t bytes) return; } else if (ec && ec != asio::error::eof){ - if (logger_) - logger_->e("[http:client] [request:%i] [read:body] error: %s", id_, ec.message().c_str()); terminate(ec); return; } if (!conn_->is_open()){ - if (logger_) - logger_->e("[http:client] [request] [read:body] closed connection"); terminate(asio::error::not_connected); return; } + if (logger_) + logger_->d("[http:client] [request:%i] response body: %i bytes received", id_, bytes); + unsigned int content_length; auto content_length_it = response_.headers.find(HTTP_HEADER_CONTENT_LENGTH); @@ -928,8 +912,6 @@ Request::handle_response_body(const asio::error_code& ec, const size_t bytes) response_.body = body; parse_request(body); } - if (logger_) - logger_->d("[http:client] [request:%i] [read:body] success:\n%s", id_, response_.body.c_str()); // should be executed after each parse_request who can trigger http_parser on_message_complete if (message_complete_.load()){