Kovri: fix log levels, log appropriate asio errors

This mostly affects transports. Keeps errors to *absolutely errors* and not runtime issues that may be caused by an overloaded peer, for example. An ultimate solution is to fine-tune error handling and fix other known bugs. Note: most of these warnings could, theoretically, be moved to debug logging.
2025-10-06 00:32:51 +02:00 · 2018-07-25 01:09:32 +00:00
parent 6333929c0e
commit d2ad3bdcc7
10 changed files with 77 additions and 63 deletions
--- a/src/client/address_book/impl.cc
+++ b/src/client/address_book/impl.cc
@@ -101,8 +101,9 @@ void AddressBook::SubscriberUpdateTimer(
    const boost::system::error_code& ecode) {
  LOG(debug) << "AddressBook: begin " << __func__;
  if (ecode) {
-    LOG(error)
-      << "AddressBook: " << __func__ << " exception: " << ecode.message();
+    if (ecode != boost::asio::error::operation_aborted)
+      LOG(error) << "AddressBook: " << __func__ << ": '" << ecode.message()
+                 << "'";
    return;
  }
  // Load publishers (see below about multiple publishers)
@@ -453,6 +454,7 @@ std::unique_ptr<const kovri::core::IdentHash> AddressBook::GetLoadedAddressIdent
  return nullptr;
 }

+// TODO(unassigned): return bool
 void AddressBook::InsertAddress(
    const std::string& host,
    const kovri::core::IdentHash& address,
@@ -463,6 +465,7 @@ void AddressBook::InsertAddress(
    // Ensure address book only inserts unique entries
    if (!m_Addresses.empty())
      {
+        // TODO(unassigned): these throws should instead log warning and return bool
        auto host_search = m_Addresses.find(host);
        if (host_search != m_Addresses.end())
          throw std::runtime_error("AddressBook: host already loaded");
--- a/src/client/destination.cc
+++ b/src/client/destination.cc
@@ -399,8 +399,8 @@ void ClientDestination::HandleDatabaseSearchReplyMessage(
        }
      }
      if (!found)
-        LOG(error)
-          << "ClientDestination: suggested floodfills are not presented in NetDb";
+        LOG(warning)
+          << "ClientDestination: suggested floodfills are not found in NetDb";
    } else {
      LOG(debug)
        << "ClientDestination: " << key.ToBase64() << " was not found on "
@@ -449,8 +449,10 @@ void ClientDestination::Publish() {
  }
  auto outbound = m_Pool->GetNextOutboundTunnel();
  if (!outbound) {
-    LOG(error) << "ClientDestination: can't publish LeaseSet, no outbound tunnels";
-    return;
+      LOG(error)
+          << "ClientDestination: can't publish LeaseSet, no outbound tunnels "
+             "(router may need more time to integrate into the network)";
+      return;
  }
  std::set<kovri::core::IdentHash> excluded;
  auto floodfill =
--- a/src/client/tunnel.cc
+++ b/src/client/tunnel.cc
@@ -134,9 +134,13 @@ void I2PTunnelConnection::HandleReceived(
    const boost::system::error_code& ecode,
    std::size_t bytes_transferred) {
  if (ecode) {
-    LOG(error) << "I2PTunnelConnection: read error: " << ecode.message();
    if (ecode != boost::asio::error::operation_aborted)
-      Terminate();
+      {
+        if (ecode != boost::asio::error::eof)
+          LOG(error) << "I2PTunnelConnection: " << __func__ << ": '"
+                     << ecode.message() << "'";
+        Terminate();
+      }
  } else {
    if (m_Stream) {
      auto s = shared_from_this();
@@ -182,9 +186,12 @@ void I2PTunnelConnection::HandleStreamReceive(
    const boost::system::error_code& ecode,
    std::size_t bytes_transferred) {
  if (ecode) {
-    LOG(error) << "I2PTunnelConnection: stream read error: " << ecode.message();
    if (ecode != boost::asio::error::operation_aborted)
-      Terminate();
+      {
+        LOG(error) << "I2PTunnelConnection: " << __func__ << ": '"
+                   << ecode.message() << "'";
+        Terminate();
+      }
  } else {
    Write(m_StreamBuffer, bytes_transferred);
  }
@@ -341,7 +348,7 @@ void I2PClientTunnelHandler::HandleStreamRequestComplete(
    connection->I2PConnect();
    Done(shared_from_this());
  } else {
-    LOG(error)
+    LOG(warning)
      << "I2PClientTunnelHandler: stream not available "
      << "(router may need more time to integrate into the network)";
    Terminate();
--- a/src/core/router/net_db/requests.cc
+++ b/src/core/router/net_db/requests.cc
@@ -1,5 +1,5 @@
 /**                                                                                           //
- * Copyright (c) 2013-2017, The Kovri I2P Router Project                                      //
+ * Copyright (c) 2013-2018, The Kovri I2P Router Project                                      //
 *                                                                                            //
 * All rights reserved.                                                                       //
 *                                                                                            //
@@ -162,9 +162,11 @@ void NetDbRequests::ManageRequests() {
          } else {
            is_complete = true;
            if (!inbound)
-              LOG(warning) << "NetDbRequests: no inbound tunnels";
+              LOG(warning) << "NetDbRequests: no inbound tunnels (router may "
+                              "need more time to integrate into the network)";
            if (!outbound)
-              LOG(warning) << "NetDbRequests: no outbound tunnels";
+              LOG(warning) << "NetDbRequests: no outbound tunnels (router may "
+                              "need more time to integrate into the network)";
            if (!next_floodfill)
              LOG(warning) << "NetDbRequests: no more floodfills";
          }
--- a/src/core/router/transports/impl.cc
+++ b/src/core/router/transports/impl.cc
@@ -350,10 +350,8 @@ bool Transports::ConnectToPeer(
  ++peer.num_attempts;
  if (result)
    return true;
-  // Couldn't connect, get rid of this peer
-  LOG(error)
-    << "Transports:" << GetFormattedSessionInfo(peer.router)
-    << "no NTCP/SSU address available";
+  LOG(debug) << "Transports:" << GetFormattedSessionInfo(peer.router)
+             << __func__ << ": could not connect. Removing peer";
  peer.Done();
  m_Peers.erase(ident);
  return false;
--- a/src/core/router/transports/ntcp/server.cc
+++ b/src/core/router/transports/ntcp/server.cc
@@ -1,5 +1,5 @@
 /**                                                                                           //
- * Copyright (c) 2013-2017, The Kovri I2P Router Project                                      //
+ * Copyright (c) 2013-2018, The Kovri I2P Router Project                                      //
 *                                                                                            //
 * All rights reserved.                                                                       //
 *                                                                                            //
@@ -119,7 +119,9 @@ void NTCPServer::HandleAccept(
        << "NTCPServer: " << __func__ << " remote endpoint: " << ec.message();
    }
  } else {
-    LOG(error) << "NTCPServer: " << __func__ << ": '" << ecode.message() << "'";
+      if (ecode != boost::asio::error::operation_aborted)
+        LOG(error) << "NTCPServer: " << __func__ << ": '" << ecode.message()
+                   << "'";
  }
  if (ecode != boost::asio::error::operation_aborted) {
    conn = std::make_shared<NTCPSession>(*this);
@@ -161,7 +163,9 @@ void NTCPServer::HandleAcceptV6(
          << "NTCPServer: " << __func__ << " remote endpoint: " << ec.message();
    }
  } else {
-    LOG(error) << "NTCPServer: " << __func__ << ": '" << ecode.message() << "'";
+      if (ecode != boost::asio::error::operation_aborted)
+        LOG(error) << "NTCPServer: " << __func__ << ": '" << ecode.message()
+                   << "'";
  }
  if (ecode != boost::asio::error::operation_aborted) {
    conn = std::make_shared<NTCPSession>(*this);
@@ -198,7 +202,7 @@ void NTCPServer::HandleConnect(
    std::shared_ptr<NTCPSession> conn,
    const boost::system::error_code& ecode) {
  if (ecode) {
-    LOG(error)
+    LOG(warning)
      << "NTCPServer:"
      << " [" << conn->GetRemoteRouter()->GetIdentHashAbbreviation() << "] "
      << __func__ << ": '" << ecode.message() << "'";
--- a/src/core/router/transports/ntcp/session.cc
+++ b/src/core/router/transports/ntcp/session.cc
@@ -162,7 +162,7 @@ void NTCPSession::HandlePhase1Sent(
    const boost::system::error_code& ecode,
    std::size_t /*bytes_transferred*/) {
  if (ecode) {
-    LOG(error)
+    LOG(warning)
      << "NTCPSession:" << GetFormattedSessionInfo()
      << "!!! couldn't send Phase1 '" << ecode.message() << "'";
    if (ecode != boost::asio::error::operation_aborted)
@@ -191,13 +191,10 @@ void NTCPSession::HandlePhase2Received(
    const boost::system::error_code& ecode,
    std::size_t /*bytes_transferred*/) {
  if (ecode) {
-    LOG(error)
+    LOG(warning)
      << "NTCPSession:" << GetFormattedSessionInfo()
-      << "!!! Phase2 read error '" << ecode.message() << "'";
+      << "!!! " << __func__ << ": '" << ecode.message() << "'";
    if (ecode != boost::asio::error::operation_aborted) {
-      LOG(error)
-        << "NTCPSession:" << GetFormattedSessionInfo()
-        << "!!! Phase2 error, RI is not valid";
      LOG(trace)
        << "NTCPSession:" << GetFormattedSessionInfo()
        << GetFormattedPhaseInfo(Phase::Two);
@@ -241,9 +238,9 @@ void NTCPSession::HandlePhase2Received(
          m_Establisher->phase2.encrypted.hxy.data(),
          xy.data(),
          NTCPSize::PubKey * 2)) {
-      LOG(error)
+      LOG(warning)
        << "NTCPSession:" << GetFormattedSessionInfo()
-        << "!!! Phase2 << incorrect hash";
+        << "!!! " << __func__ << ": incorrect hash";
      LOG(trace)
        << "NTCPSession:" << GetFormattedSessionInfo()
        << "Decrypted " << GetFormattedPhaseInfo(Phase::Two);
@@ -375,7 +372,7 @@ void NTCPSession::HandlePhase3Sent(
    std::size_t /*bytes_transferred*/,
    std::uint32_t ts_A) {
  if (ecode) {
-    LOG(error)
+    LOG(warning)
      << "NTCPSession:" << GetFormattedSessionInfo()
      << "!!! couldn't send Phase3 '" << ecode.message() << "'";
    if (ecode != boost::asio::error::operation_aborted)
@@ -410,13 +407,10 @@ void NTCPSession::HandlePhase4Received(
    std::size_t bytes_transferred,
    std::uint32_t ts_A) {
  if (ecode) {
-    LOG(error)
+    LOG(warning)
      << "NTCPSession:" << GetFormattedSessionInfo()
-      << "!!! Phase4 read error '" << ecode.message() << "',  check your clock";  // TODO(anonimal): error message
+      << "!!! " << __func__ << ": '" << ecode.message() << "'";
    if (ecode != boost::asio::error::operation_aborted) {
-      LOG(error)
-        << "NTCPSession:" << GetFormattedSessionInfo()
-        << "!!! Phase4, remote router does not like us";
      kovri::core::netdb.SetUnreachable(GetRemoteIdentity().GetIdentHash(), true);
      Terminate();
    }
@@ -441,7 +435,7 @@ void NTCPSession::HandlePhase4Received(
  s.Insert(ts_A);  // Timestamp Alice
  s.Insert(m_Establisher->phase2.encrypted.timestamp);  // Timestamp Bob
  if (!s.Verify(m_RemoteIdentity, m_ReceiveBuffer)) {
-    LOG(error)
+    LOG(warning)
      << "NTCPSession:" << GetFormattedSessionInfo()
      << "!!! Phase4 signature verification failed";
    Terminate();
@@ -469,7 +463,7 @@ void NTCPSession::HandlePhase4Received(
 void NTCPSession::ServerLogin() {
  const auto& ecode = SetRemoteEndpoint();
  if (ecode) {
-    LOG(error)
+    LOG(warning)
      << "NTCPSession:" << GetFormattedSessionInfo()
      << "!!! " << __func__ << ": '" << ecode.message() << "'";
    LOG(trace)
@@ -497,9 +491,9 @@ void NTCPSession::HandlePhase1Received(
    const boost::system::error_code& ecode,
    std::size_t /*bytes_transferred*/) {
  if (ecode) {
-    LOG(error)
+    LOG(warning)
      << "NTCPSession:" << GetFormattedSessionInfo()
-      << "!!! Phase1 receive error '" << ecode.message() << "'";
+      << "!!! " << __func__ << ": '" << ecode.message() << "'";
    if (ecode != boost::asio::error::operation_aborted) {
      LOG(trace)
        << "NTCPSession:" << GetFormattedSessionInfo()
@@ -653,9 +647,9 @@ void NTCPSession::HandlePhase3Received(
    std::size_t bytes_transferred,
    std::uint32_t ts_B) {
  if (ecode) {
-    LOG(error)
+    LOG(warning)
      << "NTCPSession:" << GetFormattedSessionInfo()
-      << "!!! Phase3 read error '" << ecode.message() << "'";
+      << "!!! " << __func__ << ": '" << ecode.message() << "'";
    if (ecode != boost::asio::error::operation_aborted)
      Terminate();
    return;
@@ -675,7 +669,7 @@ void NTCPSession::HandlePhase3Received(
  std::uint16_t const size = core::InputByteStream::Read<std::uint16_t>(buf);
  m_RemoteIdentity.FromBuffer(buf + NTCPSize::Phase3AliceRI, size);
  if (m_Server.FindNTCPSession(m_RemoteIdentity.GetIdentHash())) {
-    LOG(error)
+    LOG(warning)
      << "NTCPSession:" << GetFormattedSessionInfo()
      << "!!! Phase3, session already exists";
    Terminate();
@@ -717,9 +711,9 @@ void NTCPSession::HandlePhase3ExtraReceived(
    std::uint32_t ts_B,
    std::size_t padding_len) {
  if (ecode) {
-    LOG(error)
+    LOG(warning)
      << "NTCPSession:" << GetFormattedSessionInfo()
-      << "!!! Phase3 << extra read error '" << ecode.message() << "'";
+      << "!!! " << __func__ << ": '" << ecode.message() << "'";
    if (ecode != boost::asio::error::operation_aborted)
      Terminate();
    return;
@@ -756,7 +750,7 @@ void NTCPSession::HandlePhase3(
  s.Insert(ts_A);
  s.Insert(ts_B);
  if (!s.Verify(m_RemoteIdentity, buf)) {
-    LOG(error)
+    LOG(warning)
      << "NTCPSession:" << GetFormattedSessionInfo()
      << "!!! Phase3, signature verification failed";
    Terminate();
@@ -895,7 +889,7 @@ void NTCPSession::HandleSentPayload(
  m_NumSentBytes += bytes_transferred;
  LOG(debug)
    << "NTCPSession:" << GetFormattedSessionInfo()
-    << "<-- " << bytes_transferred << " bytes transferred << "
+    << "<-- " << bytes_transferred << " bytes transferred, "
    << GetNumSentBytes() << " total bytes sent";
  kovri::core::transports.UpdateSentBytes(bytes_transferred);
  if (!m_SendQueue.empty()) {
@@ -936,7 +930,7 @@ boost::asio::const_buffers_1 NTCPSession::CreateMsgBuffer(
    if (msg) {
      // Regular I2NP
      if (msg->offset < NTCPSize::Phase3AliceRI) {
-        LOG(error)
+        LOG(warning)
          << "NTCPSession:" << GetFormattedSessionInfo()
          << "!!! malformed I2NP message";  // TODO(unassigned): Error handling
      }
@@ -1002,7 +996,7 @@ void NTCPSession::HandleReceivedPayload(
  }
  // EOF errors are expected for short messages, so ignoring them here is fine
  if (ecode && (ecode != boost::asio::error::eof)) {
-    LOG(error)
+    LOG(warning)
      << "NTCPSession:" << GetFormattedSessionInfo()
      << "!!! " << __func__ << ": '" << ecode.message() << "'";
    if (!m_NumReceivedBytes) {
@@ -1062,7 +1056,7 @@ bool NTCPSession::DecryptNextBlock(
      if (data_size) {
        // New message
        if (data_size > NTCPSize::MaxMessage) {
-          LOG(error)
+          LOG(warning)
            << "NTCPSession:" << GetFormattedSessionInfo()
            << "!!! data block size '" << data_size << "' exceeds max size";
          return false;
@@ -1159,10 +1153,10 @@ void NTCPSession::HandleTerminationTimer(
    << "NTCPSession:" << GetFormattedSessionInfo()
    << "*** handling termination timer";
  if (ecode != boost::asio::error::operation_aborted) {
-    LOG(error)
+    LOG(warning)
      << "NTCPSession:" << GetFormattedSessionInfo()
-      << "!!! no activity for '"
-      << GetType(NTCPTimeoutLength::Termination) << "' seconds";
+      << "!!! no activity for "
+      << GetType(NTCPTimeoutLength::Termination) << " seconds";
    // Terminate();
    m_Socket.close();  // invoke Terminate() from HandleReceive
  }
--- a/src/core/router/transports/ssu/data.cc
+++ b/src/core/router/transports/ssu/data.cc
@@ -323,7 +323,7 @@ void SSUData::ProcessFragments(
          m_ReceivedMessages.insert(msg_id);
          m_Handler.PutNextMessage(msg);
        } else {
-          LOG(error)
+          LOG(warning)
            << "SSUData:" << m_Session.GetFormattedSessionInfo()
            << "SSU unexpected message "
            << static_cast<int>(msg->GetTypeID());
@@ -543,7 +543,7 @@ void SSUData::HandleResendTimer(
             += it->second->num_resends * SSUDuration::ResendInterval;
          it++;
        } else {
-          LOG(error)
+          LOG(warning)
            << "SSUData:" << m_Session.GetFormattedSessionInfo()
            << "SSU message has not been ACKed after "
            << static_cast<std::size_t>(SSUDuration::MaxResends) << " attempts. Deleted";
@@ -605,10 +605,10 @@ void SSUData::HandleIncompleteMessagesCleanupTimer(
    std::uint8_t const timeout = SSUDuration::IncompleteMessagesCleanupTimeout;
    for (auto it = m_IncompleteMessages.begin(); it != m_IncompleteMessages.end();) {
      if (ts > it->second->last_fragment_insert_time + timeout) {
-        LOG(error)
+        LOG(warning)
          << "SSUData:" << m_Session.GetFormattedSessionInfo()
          << "SSU message " << it->first << " was not completed in "
-          << timeout << " seconds. Deleted";
+          << static_cast<std::uint16_t>(timeout) << " seconds. Deleted";
        it = m_IncompleteMessages.erase(it);
      } else {
        it++;
--- a/src/core/router/transports/ssu/server.cc
+++ b/src/core/router/transports/ssu/server.cc
@@ -249,7 +249,9 @@ void SSUServer::HandleReceivedFrom(
    }
  else
    {
-      LOG(error) << "SSUServer: receive error: " << ecode.message();
+      if (ecode != boost::asio::error::operation_aborted)
+        LOG(error) << "SSUServer: " << __func__ << ": '" << ecode.message()
+                   << "'";
 #if (BOOST_VERSION < 106600)
      delete packet;  // free packet, now
 #endif
@@ -313,7 +315,9 @@ void SSUServer::HandleReceivedFromV6(
    }
  else
    {
-      LOG(error) << "SSUServer: V6 receive error: " << ecode.message();
+      if (ecode != boost::asio::error::operation_aborted)
+        LOG(error) << "SSUServer: " << __func__ << ": '" << ecode.message()
+                   << "'";
 #if (BOOST_VERSION < 106600)
      delete packet;  // free packet, now
 #endif
@@ -495,7 +499,7 @@ std::shared_ptr<SSUSession> SSUServer::GetSession(
          } else {
            LOG(warning)
              << "SSUServer: can't connect to unreachable router."
-              << "No introducers presented";
+              << "No introducers available";
            std::unique_lock<std::mutex> l(m_SessionsMutex);
            m_Sessions.erase(remote_endpoint);
            session.reset();
--- a/src/core/router/transports/ssu/session.cc
+++ b/src/core/router/transports/ssu/session.cc
@@ -644,8 +644,8 @@ void SSUSession::ProcessSessionConfirmed(SSUPacket* pkt) {
  if (m_SessionConfirmData.empty())
    {
      // No session confirm data
-      LOG(error) << "SSUSession:" << GetFormattedSessionInfo()
-                 << "unsolicited SessionConfirmed";
+      LOG(warning) << "SSUSession:" << GetFormattedSessionInfo()
+                   << "unsolicited SessionConfirmed";
      return;  // TODO(anonimal): throw/warn for potential attacks
    }

@@ -1546,7 +1546,7 @@ void SSUSession::HandleConnectTimer(
    const boost::system::error_code& ecode) {
  if (!ecode) {
    // timeout expired
-    LOG(error)
+    LOG(warning)
      << "SSUSession:" << GetFormattedSessionInfo()
      << "session was not established after "
      << static_cast<std::size_t>(SSUDuration::ConnectTimeout) << " seconds";