From 8e56b1df7d0090fb86c3c5701fb4c4ba8482caed Mon Sep 17 00:00:00 2001 From: Jan Christoph Uhde Date: Fri, 26 Aug 2016 16:22:49 +0200 Subject: [PATCH] improve logging --- arangod/GeneralServer/VppCommTask.cpp | 75 +++++++++++++++++++++------ arangod/V8Server/v8-actions.cpp | 38 +++++++------- 2 files changed, 76 insertions(+), 37 deletions(-) diff --git a/arangod/GeneralServer/VppCommTask.cpp b/arangod/GeneralServer/VppCommTask.cpp index 917f23b5ae..f7ce044547 100644 --- a/arangod/GeneralServer/VppCommTask.cpp +++ b/arangod/GeneralServer/VppCommTask.cpp @@ -167,6 +167,7 @@ VppCommTask::VppCommTask(GeneralServer* server, TRI_socket_t sock, // loose information during a resize // connectionStatisticsAgentSetVpp(); _agents.emplace(std::make_pair(0UL, RequestStatisticsAgent(true))); + getAgent(0UL)->acquire(); } void VppCommTask::addResponse(VppResponse* response) { @@ -183,7 +184,8 @@ void VppCommTask::addResponse(VppResponse* response) { slices.push_back(builder.slice()); } - LOG_TOPIC(DEBUG, Logger::COMMUNICATION) << "got response:"; + LOG_TOPIC(DEBUG, Logger::COMMUNICATION) << "VppCommTask: " + << "created response:"; for (auto const& slice : slices) { try { LOG_TOPIC(DEBUG, Logger::COMMUNICATION) << slice.toJson(); @@ -202,11 +204,22 @@ void VppCommTask::addResponse(VppResponse* response) { // used with _writeBuffers auto buffer = createChunkForNetworkSingle(slices, id); + double const totalTime = getAgent(id)->elapsedSinceReadStart(); + addWriteBuffer(std::move(buffer), getAgent(id)); - _agents.erase(id); - if (!id) { - _agents.emplace(std::make_pair(0UL, RequestStatisticsAgent(true))); + // and give some request information + LOG_TOPIC(INFO, Logger::REQUESTS) + << "\"vpp-request-end\",\"" << (void*)this << "\",\"" + << _connectionInfo.clientAddress << "\",\"" + << VppRequest::translateVersion(_protocolVersion) << "\"," + << static_cast(response->responseCode()) << "," + << "\"," << Logger::FIXED(totalTime, 6); + + if (id) { + _agents.erase(id); + } else { + getAgent(0UL)->acquire(); } } @@ -286,8 +299,13 @@ bool VppCommTask::processRead() { if (chunkHeader._isFirst && chunkHeader._chunk == 1) { _agents.emplace( std::make_pair(chunkHeader._messageID, RequestStatisticsAgent(true))); - getAgent(chunkHeader._messageID)->requestStatisticsAgentSetReadStart(); - LOG_TOPIC(DEBUG, Logger::COMMUNICATION) << "chunk contains single message"; + + auto agent = getAgent(chunkHeader._messageID); + agent->acquire(); + agent->requestStatisticsAgentSetReadStart(); + + LOG_TOPIC(DEBUG, Logger::COMMUNICATION) << "VppCommTask: " + << "chunk contains single message"; std::size_t payloads = 0; try { @@ -296,13 +314,15 @@ bool VppCommTask::processRead() { handleSimpleError(rest::ResponseCode::BAD, TRI_ERROR_ARANGO_DATABASE_NOT_FOUND, e.what(), chunkHeader._messageID); - LOG_TOPIC(DEBUG, Logger::COMMUNICATION) << "VPack Validation failed!" + LOG_TOPIC(DEBUG, Logger::COMMUNICATION) << "VppCommTask: " + << "VPack Validation failed!" << e.what(); closeTask(rest::ResponseCode::BAD); return false; } catch (...) { handleSimpleError(rest::ResponseCode::BAD, chunkHeader._messageID); - LOG_TOPIC(DEBUG, Logger::COMMUNICATION) << "VPack Validation failed!"; + LOG_TOPIC(DEBUG, Logger::COMMUNICATION) << "VppCommTask: " + << "VPack Validation failed!"; closeTask(rest::ResponseCode::BAD); return false; } @@ -326,10 +346,16 @@ bool VppCommTask::processRead() { if (chunkHeader._isFirst) { // first chunk of multi chunk message _agents.emplace( std::make_pair(chunkHeader._messageID, RequestStatisticsAgent(true))); - getAgent(chunkHeader._messageID)->requestStatisticsAgentSetReadStart(); - LOG_TOPIC(DEBUG, Logger::COMMUNICATION) << "chunk starts a new message"; + + auto agent = getAgent(chunkHeader._messageID); + agent->acquire(); + agent->requestStatisticsAgentSetReadStart(); + + LOG_TOPIC(DEBUG, Logger::COMMUNICATION) << "VppCommTask: " + << "chunk starts a new message"; if (incompleteMessageItr != _incompleteMessages.end()) { LOG_TOPIC(DEBUG, Logger::COMMUNICATION) + << "VppCommTask: " << "Message should be first but is already in the Map of incomplete " "messages"; closeTask(rest::ResponseCode::BAD); @@ -344,16 +370,19 @@ bool VppCommTask::processRead() { auto insertPair = _incompleteMessages.emplace( std::make_pair(chunkHeader._messageID, std::move(message))); if (!insertPair.second) { - LOG_TOPIC(DEBUG, Logger::COMMUNICATION) << "insert failed"; + LOG_TOPIC(DEBUG, Logger::COMMUNICATION) << "VppCommTask: " + << "insert failed"; closeTask(rest::ResponseCode::BAD); return false; } // CASE 2b: chunk continues a message } else { // followup chunk of some mesage - LOG_TOPIC(DEBUG, Logger::COMMUNICATION) << "chunk continues a message"; + LOG_TOPIC(DEBUG, Logger::COMMUNICATION) << "VppCommTask: " + << "chunk continues a message"; if (incompleteMessageItr == _incompleteMessages.end()) { LOG_TOPIC(DEBUG, Logger::COMMUNICATION) + << "VppCommTask: " << "found message without previous part"; closeTask(rest::ResponseCode::BAD); return false; @@ -366,7 +395,8 @@ bool VppCommTask::processRead() { // MESSAGE COMPLETE if (im._currentChunk == im._numberOfChunks - 1 /* zero based counting */) { - LOG_TOPIC(DEBUG, Logger::COMMUNICATION) << "chunk completes a message"; + LOG_TOPIC(DEBUG, Logger::COMMUNICATION) << "VppCommTask: " + << "chunk completes a message"; std::size_t payloads = 0; try { @@ -379,13 +409,15 @@ bool VppCommTask::processRead() { handleSimpleError(rest::ResponseCode::BAD, TRI_ERROR_ARANGO_DATABASE_NOT_FOUND, e.what(), chunkHeader._messageID); - LOG_TOPIC(DEBUG, Logger::COMMUNICATION) << "VPack Validation failed!" + LOG_TOPIC(DEBUG, Logger::COMMUNICATION) << "VppCommTask: " + << "VPack Validation failed!" << e.what(); closeTask(rest::ResponseCode::BAD); return false; } catch (...) { handleSimpleError(rest::ResponseCode::BAD, chunkHeader._messageID); - LOG_TOPIC(DEBUG, Logger::COMMUNICATION) << "VPack Validation failed!"; + LOG_TOPIC(DEBUG, Logger::COMMUNICATION) << "VppCommTask: " + << "VPack Validation failed!"; closeTask(rest::ResponseCode::BAD); return false; } @@ -398,6 +430,7 @@ bool VppCommTask::processRead() { getAgent(chunkHeader._messageID)->requestStatisticsAgentSetReadEnd(); } LOG_TOPIC(DEBUG, Logger::COMMUNICATION) + << "VppCommTask: " << "chunk does not complete a message"; } @@ -416,14 +449,22 @@ bool VppCommTask::processRead() { if (doExecute) { VPackSlice header = message.header(); - LOG_TOPIC(DEBUG, Logger::COMMUNICATION) << "got request:" - << header.toJson(); + + LOG_TOPIC(DEBUG, Logger::REQUESTS) << "\"vpp-request-header\",\"" + << "\"," << message.header().toJson() + << "\""; + + LOG_TOPIC(DEBUG, Logger::REQUESTS) << "\"vpp-request-payload\",\"" + << "\"," << message.payload().toJson() + << "\""; + int type = meta::underlyingValue(rest::RequestType::ILLEGAL); try { type = header.at(1).getInt(); } catch (std::exception const& e) { handleSimpleError(rest::ResponseCode::BAD, chunkHeader._messageID); LOG_TOPIC(DEBUG, Logger::COMMUNICATION) + << "VppCommTask: " << std::string("VPack Validation failed!") + e.what(); closeTask(rest::ResponseCode::BAD); return false; diff --git a/arangod/V8Server/v8-actions.cpp b/arangod/V8Server/v8-actions.cpp index 94ac7bc44e..9efab022ab 100644 --- a/arangod/V8Server/v8-actions.cpp +++ b/arangod/V8Server/v8-actions.cpp @@ -24,6 +24,10 @@ #include "v8-actions.h" #include "V8/v8-vpack.h" +#include +#include +#include +#include #include "Actions/ActionFeature.h" #include "Actions/actions.h" #include "Basics/MutexLocker.h" @@ -49,10 +53,6 @@ #include "V8Server/v8-vocbase.h" #include "VocBase/ticks.h" #include "VocBase/vocbase.h" -#include -#include -#include -#include #include @@ -424,8 +424,8 @@ static v8::Handle RequestCppToV8(v8::Isolate* isolate, // auto result = TRI_VPackToV8(isolate, slice); std::string jsonString = slice.toJson(); - LOG_TOPIC(DEBUG, Logger::COMMUNICATION) - << "json handed into v8 request:\n" << jsonString; + LOG_TOPIC(DEBUG, Logger::REQUESTS) << "json handed into v8 request:\n" + << jsonString; // V8Buffer* buffer = // V8Buffer::New(isolate, slice.startAs(), @@ -715,7 +715,8 @@ static void ResponseV8ToCpp(v8::Isolate* isolate, TRI_v8_global_t const* v8g, // json could not be converted // there was no json - change content type? LOG_TOPIC(DEBUG, Logger::COMMUNICATION) - << "failed to parse json:\n" << out; + << "failed to parse json:\n" + << out; } } @@ -728,11 +729,9 @@ static void ResponseV8ToCpp(v8::Isolate* isolate, TRI_v8_global_t const* v8g, response->setContentType(rest::ContentType::VPACK); response->setPayload(builder.slice(), true); break; - } - - default: { - throw std::logic_error("unknown transport type"); } + + default: { throw std::logic_error("unknown transport type"); } } bodySet = true; } @@ -757,8 +756,7 @@ static void ResponseV8ToCpp(v8::Isolate* isolate, TRI_v8_global_t const* v8g, "': " + TRI_last_error(); httpResponse->body().appendText(msg.c_str(), msg.size()); - response->setResponseCode( - rest::ResponseCode::SERVER_ERROR); + response->setResponseCode(rest::ResponseCode::SERVER_ERROR); } } break; @@ -936,8 +934,9 @@ static TRI_action_result_t ExecuteActionVocbase( // TODO how to generalize this? if (response->transportType() == Endpoint::TransportType::HTTP) { // FIXME - ((HttpResponse*)response)->body().appendText( - TRI_StringifyV8Exception(isolate, &tryCatch)); + ((HttpResponse*)response) + ->body() + .appendText(TRI_StringifyV8Exception(isolate, &tryCatch)); } } else { v8g->_canceled = true; @@ -1368,8 +1367,7 @@ void TRI_InitV8Actions(v8::Isolate* isolate, v8::Handle context) { static bool clusterSendToAllServers( std::string const& dbname, std::string const& path, // Note: Has to be properly encoded! - arangodb::rest::RequestType const& method, - std::string const& body) { + arangodb::rest::RequestType const& method, std::string const& body) { ClusterInfo* ci = ClusterInfo::instance(); ClusterComm* cc = ClusterComm::instance(); std::string url = "/_db/" + StringUtils::urlEncode(dbname) + "/" + path; @@ -1552,9 +1550,9 @@ static void JS_DebugClearFailAt( } std::string dbname(v8g->_vocbase->name()); - int res = clusterSendToAllServers( - dbname, "_admin/debug/failat", - arangodb::rest::RequestType::DELETE_REQ, ""); + int res = + clusterSendToAllServers(dbname, "_admin/debug/failat", + arangodb::rest::RequestType::DELETE_REQ, ""); if (res != TRI_ERROR_NO_ERROR) { TRI_V8_THROW_EXCEPTION(res); }