From 5e83afa85b9832cb17b1a6eb8d07c82f597d06d2 Mon Sep 17 00:00:00 2001 From: MOON_CLJ Date: Sat, 26 Jan 2019 13:04:07 +0800 Subject: [PATCH] add more log for easy debug & track connection state --- src/Client.cpp | 10 ++++++++++ src/Connection.cpp | 21 +++++++++++---------- src/ConnectionPool.cpp | 8 ++++++-- src/HashkitKetama.cpp | 2 +- src/Parser.cpp | 1 - 5 files changed, 28 insertions(+), 14 deletions(-) diff --git a/src/Client.cpp b/src/Client.cpp index 1265344d..93992e32 100644 --- a/src/Client.cpp +++ b/src/Client.cpp @@ -41,6 +41,7 @@ err_code_t Client::get(const char* const* keys, const size_t* keyLens, size_t nK dispatchRetrieval(GET_OP, keys, keyLens, nKeys); err_code_t rv = waitPoll(); collectRetrievalResult(results, nResults); + log_info_if(rv != RET_OK, "[I: %p], err code %s", this, errCodeToString(rv)); return rv; } @@ -50,6 +51,7 @@ err_code_t Client::gets(const char* const* keys, const size_t* keyLens, size_t n dispatchRetrieval(GETS_OP, keys, keyLens, nKeys); err_code_t rv = waitPoll(); collectRetrievalResult(results, nResults); + log_info_if(rv != RET_OK, "[I: %p], err code %s", this, errCodeToString(rv)); return rv; } @@ -101,6 +103,7 @@ err_code_t Client::M(const char* const* keys, const size_t* keyLens, \ valLens, nItems); \ err_code_t rv = waitPoll(); \ collectMessageResult(results, nResults); \ + log_info_if(rv != RET_OK, "[I: %p], err code %s", this, errCodeToString(rv)); \ return rv;\ } @@ -118,6 +121,7 @@ err_code_t Client::_delete(const char* const* keys, const size_t* keyLens, dispatchDeletion(keys, keyLens, noreply, nItems); err_code_t rv = waitPoll(); collectMessageResult(results, nResults); + log_info_if(rv != RET_OK, "[I: %p], err code %s", this, errCodeToString(rv)); return rv; } @@ -144,6 +148,7 @@ err_code_t Client::version(broadcast_result_t** results, size_t* nHosts) { broadcastCommand(keywords::kVERSION, 7); err_code_t rv = waitPoll(); collectBroadcastResult(results, nHosts); + log_info_if(rv != RET_OK, "[I: %p], err code %s", this, errCodeToString(rv)); return rv; } @@ -152,6 +157,7 @@ err_code_t Client::quit() { broadcastCommand(keywords::kQUIT, 4, true); err_code_t rv = waitPoll(); markDeadAll(NULL, keywords::kCONN_QUIT); + log_info_if(rv != RET_OK, "[I: %p], err code %s", this, errCodeToString(rv)); return rv; } @@ -160,6 +166,7 @@ err_code_t Client::stats(broadcast_result_t** results, size_t* nHosts) { broadcastCommand(keywords::kSTATS, 5); err_code_t rv = waitPoll(); collectBroadcastResult(results, nHosts); + log_info_if(rv != RET_OK, "[I: %p], err code %s", this, errCodeToString(rv)); return rv; } @@ -170,6 +177,7 @@ err_code_t Client::touch(const char* const* keys, const size_t* keyLens, dispatchTouch(keys, keyLens, exptime, noreply, nItems); err_code_t rv = waitPoll(); collectMessageResult(results, nResults); + log_info_if(rv != RET_OK, "[I: %p], err code %s", this, errCodeToString(rv)); return rv; } @@ -193,6 +201,7 @@ err_code_t Client::incr(const char* key, const size_t keyLen, const uint64_t del dispatchIncrDecr(INCR_OP, key, keyLen, delta, noreply); err_code_t rv = waitPoll(); collectUnsignedResult(results, nResults); + log_info_if(rv != RET_OK, "[I: %p], err code %s", this, errCodeToString(rv)); return rv; } @@ -203,6 +212,7 @@ err_code_t Client::decr(const char* key, const size_t keyLen, const uint64_t del dispatchIncrDecr(DECR_OP, key, keyLen, delta, noreply); err_code_t rv = waitPoll(); collectUnsignedResult(results, nResults); + log_info_if(rv != RET_OK, "[I: %p], err code %s", this, errCodeToString(rv)); return rv; } diff --git a/src/Connection.cpp b/src/Connection.cpp index 70837dcf..2a1dce07 100644 --- a/src/Connection.cpp +++ b/src/Connection.cpp @@ -164,18 +164,15 @@ void Connection::close() { bool Connection::tryReconnect() { if (!m_alive) { - time_t now; - time(&now); + time_t now = time(NULL); if (now >= m_deadUntil) { int rv = this->connect(); if (rv == 0) { - if (m_deadUntil > 0) { - log_info("Connection %s is back to live at %lu", m_name, now); - } + log_info_if(m_deadUntil > 0, "[I: %p] %s is back to live at %lu", this, m_name, now); m_deadUntil = 0; } else { m_deadUntil = now + m_retryTimeout; - // log_info("%s is still dead", m_name); + log_info("[I: %p] %s is still dead", this, m_name); } } } @@ -188,14 +185,16 @@ void Connection::markDead(const char* reason, int delay) { m_deadUntil += delay; // check after `delay` seconds, default 0 this->close(); if (strcmp(reason, keywords::kCONN_QUIT) != 0) { - log_warn("Connection %s is dead(reason: %s, delay: %d), next check at %lu", - m_name, reason, delay, m_deadUntil); + log_warn("[I: %p] %s is dead(reason: %s, delay: %d), next check at %lu", + this, m_name, reason, delay, m_deadUntil); +#ifndef NDEBUG std::queue* q = m_parser.getRequestKeys(); if (!q->empty()) { - log_warn("%s: first request key: %.*s", m_name, + log_debug("[I: %p] %s first request key: %.*s", this, m_name, static_cast(q->front().iov_len), static_cast(q->front().iov_base)); } +#endif } } } @@ -209,6 +208,7 @@ void Connection::takeBuffer(const char* const buf, size_t buf_len) { } void Connection::addRequestKey(const char* const key, const size_t len) { + log_debug("[I: %p] %s add request key: %.*s", this, m_name, static_cast(len), key); m_parser.addRequestKey(key, len); } @@ -261,7 +261,8 @@ ssize_t Connection::recv() { size_t bufferSizeAvailable = m_buffer_reader->prepareWriteBlock(bufferSize); char* writePtr = m_buffer_reader->getWritePtr(); ssize_t bufferSizeActual = ::recv(m_socketFd, writePtr, bufferSizeAvailable, 0); - // log_info("%p recv(%lu) %.*s", this, bufferSizeActual, (int)bufferSizeActual, writePtr); + log_debug("[I: %p] %s recv(%lu)", this, m_name, bufferSizeActual); + // log_debug("[I: %p] %.*s", (int)bufferSizeActual, writePtr); if (bufferSizeActual > 0) { m_buffer_reader->commitWrite(bufferSizeActual); } diff --git a/src/ConnectionPool.cpp b/src/ConnectionPool.cpp index 07110b43..730f1c81 100644 --- a/src/ConnectionPool.cpp +++ b/src/ConnectionPool.cpp @@ -204,6 +204,7 @@ void ConnectionPool::dispatchStorage(op_code_t op, conn->getMessageResults()->reserve(conn->m_counter); } } + log_debug("[I: %p] after dispatchStorage, m_nActiveConn: %d", this, m_nActiveConn); } @@ -248,7 +249,7 @@ void ConnectionPool::dispatchRetrieval(op_code_t op, const char* const* keys, conn->getRetrievalResults()->reserve(conn->m_counter); } } - // log_debug("after dispatchRetrieval: m_nActiveConn: %d", this->m_nActiveConn); + log_debug("[I: %p] after dispatchRetrieval, m_nActiveConn: %d", this, m_nActiveConn); } @@ -404,7 +405,7 @@ err_code_t ConnectionPool::waitPoll() { if (m_nInvalidKey > 0) { return RET_INVALID_KEY_ERR; } else { - // hard server error + log_debug("[I: %p] hard server error", this); return RET_MC_SERVER_ERR; } } @@ -480,6 +481,7 @@ err_code_t ConnectionPool::waitPoll() { // POLLIN recv ssize_t nRecv = conn->recv(); if (nRecv == -1 || nRecv == 0) { + log_warn("[I: %p] recv_error, Connection(%p): %s, nRecv: %zd", this, conn, conn->name(), nRecv); markDeadConn(conn, keywords::kRECV_ERROR, pollfd_ptr); ret_code = RET_RECV_ERR; --m_nActiveConn; @@ -625,6 +627,7 @@ void ConnectionPool::setRetryTimeout(int timeout) { void ConnectionPool::markDeadAll(pollfd_t* pollfds, const char* reason) { + log_warn("[I: %p] markDeadAll(reason: %s), m_nActiveConn: %d", this, reason, m_nActiveConn); nfds_t fd_idx = 0; for (std::vector::iterator it = m_activeConns.begin(); it != m_activeConns.end(); @@ -643,6 +646,7 @@ void ConnectionPool::markDeadAll(pollfd_t* pollfds, const char* reason) { void ConnectionPool::markDeadConn(Connection* conn, const char* reason, pollfd_t* fd_ptr) { + log_warn("[I: %p] markDeadConn(reason: %s), Connection(%p): %s", this, reason, conn, conn->name()); conn->markDead(reason); fd_ptr->events &= ~POLLOUT & ~POLLIN; fd_ptr->fd = conn->socketFd(); diff --git a/src/HashkitKetama.cpp b/src/HashkitKetama.cpp index 1bc45c46..707daf3c 100644 --- a/src/HashkitKetama.cpp +++ b/src/HashkitKetama.cpp @@ -133,7 +133,7 @@ std::vector::iterator KetamaSelector::getServerIt(const char* } } while (--max_iter); if (max_iter == 0) { - log_warn("no server is avaliable(alive) for key: \"%.*s\"", static_cast(key_len), key); + log_warn("no server is available(alive) for key: \"%.*s\"", static_cast(key_len), key); return m_continuum.end(); } } else { diff --git a/src/Parser.cpp b/src/Parser.cpp index 7004d8df..d5635ede 100644 --- a/src/Parser.cpp +++ b/src/Parser.cpp @@ -63,7 +63,6 @@ void PacketParser::setBufferReader(BufferReader* reader) { void PacketParser::addRequestKey(const char* const key, const size_t len) { - // log_info("add request key: %.*s", static_cast(len), key); struct iovec iov = {const_cast(key), len}; m_requestKeys.push(iov); }