add more log for easy debug & track connection state

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;
 }
 

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<struct iovec>* 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<int>(q->front().iov_len),
  static_cast<char*>(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<int>(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);
  }

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<Connection*>::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();

src/HashkitKetama.cpp

@@ -133,7 +133,7 @@ std::vector<continuum_item_t>::iterator KetamaSelector::getServerIt(const char*
  }
  } while (--max_iter);
  if (max_iter == 0) {
- log_warn("no server is avaliable(alive) for key: \"%.*s\"", static_cast<int>(key_len), key);
+ log_warn("no server is available(alive) for key: \"%.*s\"", static_cast<int>(key_len), key);
  return m_continuum.end();
  }
  } else {

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<int>(len), key);
  struct iovec iov = {const_cast<char*>(key), len};
  m_requestKeys.push(iov);
 }