Add logging for sending and receiving STUN binding requests and TURN requests and responses.

BUG=
R=guoweis@webrtc.org

Review URL: https://webrtc-codereview.appspot.com/46189004

Cr-Commit-Position: refs/heads/master@{#9195}

webrtc/base/stringencode.cc

@@ -466,6 +466,10 @@ size_t hex_encode_with_delimiter(char* buffer, size_t buflen,
   return bufpos;
 }
 
+std::string hex_encode(const std::string& str) {
+  return hex_encode(str.c_str(), str.size());
+}
+
 std::string hex_encode(const char* source, size_t srclen) {
   return hex_encode_with_delimiter(source, srclen, 0);
 }

webrtc/base/stringencode.h

@@ -11,8 +11,8 @@
 #ifndef WEBRTC_BASE_STRINGENCODE_H_
 #define WEBRTC_BASE_STRINGENCODE_H_
 
-#include <string>
 #include <sstream>
+#include <string>
 #include <vector>
 
 #include "webrtc/base/checks.h"
@@ -95,6 +95,7 @@ size_t hex_encode_with_delimiter(char* buffer, size_t buflen,
                                  char delimiter);
 
 // Helper functions for hex_encode.
+std::string hex_encode(const std::string& str);
 std::string hex_encode(const char* source, size_t srclen);
 std::string hex_encode_with_delimiter(const char* source, size_t srclen,
                                       char delimiter);

webrtc/p2p/base/port.cc

@@ -29,7 +29,7 @@ namespace {
 // Determines whether we have seen at least the given maximum number of
 // pings fail to have a response.
 inline bool TooManyFailures(
-    const std::vector<uint32>& pings_since_last_response,
+    const std::vector<cricket::Connection::SentPing>& pings_since_last_response,
     uint32 maximum_failures,
     uint32 rtt_estimate,
     uint32 now) {
@@ -40,19 +40,22 @@ inline bool TooManyFailures(
 
   // Check if the window in which we would expect a response to the ping has
   // already elapsed.
-  return pings_since_last_response[maximum_failures - 1] + rtt_estimate < now;
+  uint32 expected_response_time =
+      pings_since_last_response[maximum_failures - 1].sent_time + rtt_estimate;
+  return now > expected_response_time;
 }
 
 // Determines whether we have gone too long without seeing any response.
 inline bool TooLongWithoutResponse(
-    const std::vector<uint32>& pings_since_last_response,
+    const std::vector<cricket::Connection::SentPing>& pings_since_last_response,
     uint32 maximum_time,
     uint32 now) {
 
   if (pings_since_last_response.size() == 0)
     return false;
 
-  return pings_since_last_response[0] + maximum_time < now;
+  auto first = pings_since_last_response[0];
+  return now > (first.sent_time + maximum_time);
 }
 
 // GICE(ICEPROTO_GOOGLE) requires different username for RTP and RTCP.
@@ -304,6 +307,10 @@ void Port::OnReadPacket(
   } else if (!msg) {
     // STUN message handled already
   } else if (msg->type() == STUN_BINDING_REQUEST) {
+    LOG(LS_INFO) << "Received STUN ping "
+                 << " id=" << rtc::hex_encode(msg->transaction_id())
+                 << " from unknown address " << addr.ToSensitiveString();
+
     // Check for role conflicts.
     if (IsStandardIce() &&
         !MaybeIceRoleConflict(addr, msg.get(), remote_username)) {
@@ -634,18 +641,32 @@ void Port::SendBindingResponse(StunMessage* request,
         STUN_ATTR_USERNAME, username_attr->GetString()));
   }
 
+  // The fact that we received a successful request means that this connection
+  // (if one exists) should now be readable.
+  Connection* conn = GetConnection(addr);
+
   // Send the response message.
   rtc::ByteBuffer buf;
   response.Write(&buf);
   rtc::PacketOptions options(DefaultDscpValue());
-  if (SendTo(buf.Data(), buf.Length(), addr, options, false) < 0) {
+  auto err = SendTo(buf.Data(), buf.Length(), addr, options, false);
-    LOG_J(LS_ERROR, this) << "Failed to send STUN ping response to "
+  if (err < 0) {
-                          << addr.ToSensitiveString();
+    LOG_J(LS_ERROR, this)
+        << "Failed to send STUN ping response"
+        << ", to=" << addr.ToSensitiveString()
+        << ", err=" << err
+        << ", id=" << rtc::hex_encode(response.transaction_id());
+  } else {
+    // Log at LS_INFO if we send a stun ping response on an unwritable
+    // connection.
+    rtc::LoggingSeverity sev = (conn && !conn->writable()) ?
+        rtc::LS_INFO : rtc::LS_VERBOSE;
+    LOG_JV(sev, this)
+        << "Sent STUN ping response"
+        << ", to=" << addr.ToSensitiveString()
+        << ", id=" << rtc::hex_encode(response.transaction_id());
   }
 
-  // The fact that we received a successful request means that this connection
-  // (if one exists) should now be readable.
-  Connection* conn = GetConnection(addr);
   ASSERT(conn != NULL);
   if (conn)
     conn->ReceivedPing();
@@ -767,7 +788,7 @@ class ConnectionRequest : public StunRequest {
   virtual ~ConnectionRequest() {
   }
 
-  virtual void Prepare(StunMessage* request) {
+  void Prepare(StunMessage* request) override {
     request->SetType(STUN_BINDING_REQUEST);
     std::string username;
     connection_->port()->CreateStunUsername(
@@ -823,22 +844,26 @@ class ConnectionRequest : public StunRequest {
     }
   }
 
-  virtual void OnResponse(StunMessage* response) {
+  void OnResponse(StunMessage* response) override {
     connection_->OnConnectionRequestResponse(this, response);
   }
 
-  virtual void OnErrorResponse(StunMessage* response) {
+  void OnErrorResponse(StunMessage* response) override {
     connection_->OnConnectionRequestErrorResponse(this, response);
   }
 
-  virtual void OnTimeout() {
+  void OnTimeout() override {
     connection_->OnConnectionRequestTimeout(this);
   }
 
-  virtual int GetNextDelay() {
+  void OnSent() override {
+    connection_->OnConnectionRequestSent(this);
     // Each request is sent only once.  After a single delay , the request will
     // time out.
     timeout_ = true;
+  }
+
+  int resend_delay() override {
     return CONNECTION_RESPONSE_TIMEOUT;
   }
 
@@ -957,9 +982,12 @@ void Connection::set_use_candidate_attr(bool enable) {
 void Connection::OnSendStunPacket(const void* data, size_t size,
                                   StunRequest* req) {
   rtc::PacketOptions options(port_->DefaultDscpValue());
-  if (port_->SendTo(data, size, remote_candidate_.address(),
+  auto err = port_->SendTo(
-                    options, false) < 0) {
+      data, size, remote_candidate_.address(), options, false);
-    LOG_J(LS_WARNING, this) << "Failed to send STUN ping " << req->id();
+  if (err < 0) {
+    LOG_J(LS_WARNING, this) << "Failed to send STUN ping "
+                            << " err=" << err
+                            << " id=" << rtc::hex_encode(req->id());
   }
 }
 
@@ -1000,8 +1028,13 @@ void Connection::OnReadPacket(
     // Perform our own checks to ensure this packet is valid.
     // If this is a STUN request, then update the readable bit and respond.
     // If this is a STUN response, then update the writable bit.
+    // Log at LS_INFO if we receive a ping on an unwritable connection.
+    rtc::LoggingSeverity sev = (!writable() ? rtc::LS_INFO : rtc::LS_VERBOSE);
     switch (msg->type()) {
       case STUN_BINDING_REQUEST:
+        LOG_JV(sev, this) << "Received STUN ping"
+                          << ", id=" << rtc::hex_encode(msg->transaction_id());
+
         if (remote_ufrag == remote_candidate_.username()) {
           // Check for role conflicts.
           if (port_->IsStandardIce() &&
@@ -1093,20 +1126,37 @@ void Connection::Destroy() {
   set_write_state(STATE_WRITE_TIMEOUT);
 }
 
+void Connection::PrintPingsSinceLastResponse(std::string* s, size_t max) {
+  std::ostringstream oss;
+  oss << std::boolalpha;
+  if (pings_since_last_response_.size() > max) {
+    for (size_t i = 0; i < max; i++) {
+      const SentPing& ping = pings_since_last_response_[i];
+      oss << rtc::hex_encode(ping.id) << " ";
+    }
+    oss << "... " << (pings_since_last_response_.size() - max) << " more";
+  } else {
+    for (const SentPing& ping : pings_since_last_response_) {
+      oss << rtc::hex_encode(ping.id) << " ";
+    }
+  }
+  *s = oss.str();
+}
+
 void Connection::UpdateState(uint32 now) {
   uint32 rtt = ConservativeRTTEstimate(rtt_);
 
-  std::string pings;
+  if (rtc::LogCheckLevel(rtc::LS_VERBOSE)) {
-  for (size_t i = 0; i < pings_since_last_response_.size(); ++i) {
+    std::string pings;
-    char buf[32];
+    PrintPingsSinceLastResponse(&pings, 5);
-    rtc::sprintfn(buf, sizeof(buf), "%u",
+    LOG_J(LS_VERBOSE, this) << "UpdateState()"
-        pings_since_last_response_[i]);
+                            << ", ms since last received response="
-    pings.append(buf).append(" ");
+                            << now - last_ping_response_received_
+                            << ", ms since last received data="
+                            << now - last_data_received_
+                            << ", rtt=" << rtt
+                            << ", pings_since_last_response=" << pings;
   }
-  LOG_J(LS_VERBOSE, this) << "UpdateState(): pings_since_last_response_="
-                          << pings << ", rtt=" << rtt << ", now=" << now
-                          << ", last ping received: " << last_ping_received_
-                          << ", last data_received: " << last_data_received_;
 
   // Check the readable state.
   //
@@ -1122,8 +1172,7 @@ void Connection::UpdateState(uint32 now) {
   if (port_->IsGoogleIce() && (read_state_ == STATE_READABLE) &&
       (last_ping_received_ + CONNECTION_READ_TIMEOUT <= now) &&
       (last_data_received_ + CONNECTION_READ_TIMEOUT <= now)) {
-    LOG_J(LS_INFO, this) << "Unreadable after "
+    LOG_J(LS_INFO, this) << "Unreadable after " << now - last_ping_received_
-                         << now - last_ping_received_
                          << " ms without a ping,"
                          << " ms since last received response="
                          << now - last_ping_response_received_
@@ -1153,7 +1202,7 @@ void Connection::UpdateState(uint32 now) {
     uint32 max_pings = CONNECTION_WRITE_CONNECT_FAILURES;
     LOG_J(LS_INFO, this) << "Unwritable after " << max_pings
                          << " ping failures and "
-                         << now - pings_since_last_response_[0]
+                         << now - pings_since_last_response_[0].sent_time
                          << " ms without a response,"
                          << " ms since last received ping="
                          << now - last_ping_received_
@@ -1169,17 +1218,19 @@ void Connection::UpdateState(uint32 now) {
                              CONNECTION_WRITE_TIMEOUT,
                              now)) {
     LOG_J(LS_INFO, this) << "Timed out after "
-                         << now - pings_since_last_response_[0]
+                         << now - pings_since_last_response_[0].sent_time
-                         << " ms without a response, rtt=" << rtt;
+                         << " ms without a response"
+                         << ", rtt=" << rtt;
     set_write_state(STATE_WRITE_TIMEOUT);
   }
 }
 
 void Connection::Ping(uint32 now) {
   last_ping_sent_ = now;
-  pings_since_last_response_.push_back(now);
   ConnectionRequest *req = new ConnectionRequest(this);
-  LOG_J(LS_VERBOSE, this) << "Sending STUN ping " << req->id() << " at " << now;
+  pings_since_last_response_.push_back(SentPing(req->id(), now));
+  LOG_J(LS_VERBOSE, this) << "Sending STUN ping "
+                          << ", id=" << rtc::hex_encode(req->id());
   requests_.Send(req);
   state_ = STATE_INPROGRESS;
 }
@@ -1249,6 +1300,10 @@ std::string Connection::ToSensitiveString() const {
 
 void Connection::OnConnectionRequestResponse(ConnectionRequest* request,
                                              StunMessage* response) {
+  // Log at LS_INFO if we receive a ping response on an unwritable
+  // connection.
+  rtc::LoggingSeverity sev = !writable() ? rtc::LS_INFO : rtc::LS_VERBOSE;
+
   // We've already validated that this is a STUN binding response with
   // the correct local and remote username for this connection.
   // So if we're not already, become writable. We may be bringing a pruned
@@ -1264,22 +1319,16 @@ void Connection::OnConnectionRequestResponse(ConnectionRequest* request,
     ReceivedPing();
   }
 
-  std::string pings;
+  if (rtc::LogCheckLevel(sev)) {
-  for (size_t i = 0; i < pings_since_last_response_.size(); ++i) {
+    std::string pings;
-    char buf[32];
+    PrintPingsSinceLastResponse(&pings, 5);
-    rtc::sprintfn(buf, sizeof(buf), "%u",
+    LOG_JV(sev, this) << "Received STUN ping response"
-        pings_since_last_response_[i]);
+                        << ", id=" << rtc::hex_encode(request->id())
-    pings.append(buf).append(" ");
+                        << ", code=0"  // Makes logging easier to parse.
+                        << ", rtt=" << rtt
+                        << ", pings_since_last_response=" << pings;
   }
 
-  rtc::LoggingSeverity level =
-      (pings_since_last_response_.size() > CONNECTION_WRITE_CONNECT_FAILURES) ?
-          rtc::LS_INFO : rtc::LS_VERBOSE;
-
-  LOG_JV(level, this) << "Received STUN ping response " << request->id()
-                      << ", pings_since_last_response_=" << pings
-                      << ", rtt=" << rtt;
-
   pings_since_last_response_.clear();
   last_ping_response_received_ = rtc::Time();
   rtt_ = (RTT_RATIO * rtt_ + rtt) / (RTT_RATIO + 1);
@@ -1304,6 +1353,11 @@ void Connection::OnConnectionRequestErrorResponse(ConnectionRequest* request,
     }
   }
 
+  LOG_J(LS_INFO, this) << "Received STUN error response"
+                       << " id=" << rtc::hex_encode(request->id())
+                       << " code=" << error_code
+                       << " rtt=" << request->Elapsed();
+
   if (error_code == STUN_ERROR_UNKNOWN_ATTRIBUTE ||
       error_code == STUN_ERROR_SERVER_ERROR ||
       error_code == STUN_ERROR_UNAUTHORIZED) {
@@ -1323,12 +1377,19 @@ void Connection::OnConnectionRequestErrorResponse(ConnectionRequest* request,
 
 void Connection::OnConnectionRequestTimeout(ConnectionRequest* request) {
   // Log at LS_INFO if we miss a ping on a writable connection.
-  rtc::LoggingSeverity sev = (write_state_ == STATE_WRITABLE) ?
+  rtc::LoggingSeverity sev = writable() ? rtc::LS_INFO : rtc::LS_VERBOSE;
-      rtc::LS_INFO : rtc::LS_VERBOSE;
+  LOG_JV(sev, this) << "Timing-out STUN ping "
-  LOG_JV(sev, this) << "Timing-out STUN ping " << request->id()
+                    << rtc::hex_encode(request->id())
                     << " after " << request->Elapsed() << " ms";
 }
 
+void Connection::OnConnectionRequestSent(ConnectionRequest* request) {
+  // Log at LS_INFO if we send a ping on an unwritable connection.
+  rtc::LoggingSeverity sev = !writable() ? rtc::LS_INFO : rtc::LS_VERBOSE;
+  LOG_JV(sev, this) << "Sent STUN ping"
+                    << ", id=" << rtc::hex_encode(request->id());
+}
+
 void Connection::CheckTimeout() {
   // If both read and write have timed out or read has never initialized, then
   // this connection can contribute no more to p2p socket unless at some later

webrtc/p2p/base/port.h

@@ -402,6 +402,15 @@ class Port : public PortInterface, public rtc::MessageHandler,
 class Connection : public rtc::MessageHandler,
     public sigslot::has_slots<> {
  public:
+  struct SentPing {
+    SentPing(const std::string id, uint32 sent_time)
+        : id(id),
+          sent_time(sent_time) {}
+
+    std::string id;
+    uint32 sent_time;
+  };
+
   // States are from RFC 5245. http://tools.ietf.org/html/rfc5245#section-5.7.4
   enum State {
     STATE_WAITING = 0,  // Check has not been performed, Waiting pair on CL.
@@ -520,6 +529,8 @@ class Connection : public rtc::MessageHandler,
   std::string ToDebugId() const;
   std::string ToString() const;
   std::string ToSensitiveString() const;
+  // Prints pings_since_last_response_ into a string.
+  void PrintPingsSinceLastResponse(std::string* pings, size_t max);
 
   bool reported() const { return reported_; }
   void set_reported(bool reported) { reported_ = reported;}
@@ -560,6 +571,7 @@ class Connection : public rtc::MessageHandler,
   void OnConnectionRequestErrorResponse(ConnectionRequest* req,
                                         StunMessage* response);
   void OnConnectionRequestTimeout(ConnectionRequest* req);
+  void OnConnectionRequestSent(ConnectionRequest* req);
 
   // Changes the state and signals if necessary.
   void set_read_state(ReadState value);
@@ -592,7 +604,7 @@ class Connection : public rtc::MessageHandler,
                                // side
   uint32 last_data_received_;
   uint32 last_ping_response_received_;
-  std::vector<uint32> pings_since_last_response_;
+  std::vector<SentPing> pings_since_last_response_;
 
   rtc::RateTracker recv_rate_tracker_;
   rtc::RateTracker send_rate_tracker_;

webrtc/p2p/base/relayport.cc

@@ -159,13 +159,14 @@ class AllocateRequest : public StunRequest {
   AllocateRequest(RelayEntry* entry, RelayConnection* connection);
   virtual ~AllocateRequest() {}
 
-  virtual void Prepare(StunMessage* request);
+  void Prepare(StunMessage* request) override;
 
-  virtual int GetNextDelay();
+  void OnSent() override;
+  int resend_delay() override;
 
-  virtual void OnResponse(StunMessage* response);
+  void OnResponse(StunMessage* response) override;
-  virtual void OnErrorResponse(StunMessage* response);
+  void OnErrorResponse(StunMessage* response) override;
-  virtual void OnTimeout();
+  void OnTimeout() override;
 
  private:
   RelayEntry* entry_;
@@ -775,14 +776,20 @@ void AllocateRequest::Prepare(StunMessage* request) {
   VERIFY(request->AddAttribute(username_attr));
 }
 
-int AllocateRequest::GetNextDelay() {
+void AllocateRequest::OnSent() {
-  int delay = 100 * std::max(1 << count_, 2);
   count_ += 1;
   if (count_ == 5)
     timeout_ = true;
-  return delay;
 }
 
+int AllocateRequest::resend_delay() {
+  if (count_ == 0) {
+    return 0;
+  }
+  return 100 * std::max(1 << (count_-1), 2);
+}
+
+
 void AllocateRequest::OnResponse(StunMessage* response) {
   const StunAddressAttribute* addr_attr =
       response->GetAddress(STUN_ATTR_MAPPED_ADDRESS);

webrtc/p2p/base/stunport.cc

@@ -39,11 +39,11 @@ class StunBindingRequest : public StunRequest {
 
   const rtc::SocketAddress& server_addr() const { return server_addr_; }
 
-  virtual void Prepare(StunMessage* request) {
+  virtual void Prepare(StunMessage* request) override {
     request->SetType(STUN_BINDING_REQUEST);
   }
 
-  virtual void OnResponse(StunMessage* response) {
+  virtual void OnResponse(StunMessage* response) override {
     const StunAddressAttribute* addr_attr =
         response->GetAddress(STUN_ATTR_MAPPED_ADDRESS);
     if (!addr_attr) {
@@ -65,7 +65,7 @@ class StunBindingRequest : public StunRequest {
     }
   }
 
-  virtual void OnErrorResponse(StunMessage* response) {
+  virtual void OnErrorResponse(StunMessage* response) override {
     const StunErrorCodeAttribute* attr = response->GetErrorCode();
     if (!attr) {
       LOG(LS_ERROR) << "Bad allocate response error code";
@@ -86,7 +86,7 @@ class StunBindingRequest : public StunRequest {
     }
   }
 
-  virtual void OnTimeout() {
+  virtual void OnTimeout() override {
     LOG(LS_ERROR) << "Binding request timed out from "
       << port_->GetLocalAddress().ToSensitiveString()
       << " (" << port_->Network()->name() << ")";

webrtc/p2p/base/stunrequest.cc

@@ -14,6 +14,7 @@
 #include "webrtc/base/common.h"
 #include "webrtc/base/helpers.h"
 #include "webrtc/base/logging.h"
+#include "webrtc/base/stringencode.h"
 
 namespace cricket {
 
@@ -76,8 +77,11 @@ void StunRequestManager::Clear() {
 
 bool StunRequestManager::CheckResponse(StunMessage* msg) {
   RequestMap::iterator iter = requests_.find(msg->transaction_id());
-  if (iter == requests_.end())
+  if (iter == requests_.end()) {
+    LOG(LS_WARNING) << "Ignoring STUN response for unknown request "
+                    << rtc::hex_encode(msg->transaction_id());
     return false;
+  }
 
   StunRequest* request = iter->second;
   if (msg->type() == GetStunSuccessResponseType(request->type())) {
@@ -106,15 +110,20 @@ bool StunRequestManager::CheckResponse(const char* data, size_t size) {
   id.append(data + kStunTransactionIdOffset, kStunTransactionIdLength);
 
   RequestMap::iterator iter = requests_.find(id);
-  if (iter == requests_.end())
+  if (iter == requests_.end()) {
+    LOG(LS_WARNING) << "Ignoring STUN response for unknown request "
+                    << rtc::hex_encode(id);
     return false;
+  }
 
   // Parse the STUN message and continue processing as usual.
 
   rtc::ByteBuffer buf(data, size);
   rtc::scoped_ptr<StunMessage> response(iter->second->msg_->CreateNew());
-  if (!response->Read(&buf))
+  if (!response->Read(&buf)) {
+    LOG(LS_WARNING) << "Failed to read STUN response " << rtc::hex_encode(id);
     return false;
+  }
 
   return CheckResponse(response.get());
 }
@@ -188,16 +197,21 @@ void StunRequest::OnMessage(rtc::Message* pmsg) {
   msg_->Write(&buf);
   manager_->SignalSendPacket(buf.Data(), buf.Length(), this);
 
-  int delay = GetNextDelay();
+  OnSent();
-  manager_->thread_->PostDelayed(delay, this, MSG_STUN_SEND, NULL);
+  manager_->thread_->PostDelayed(resend_delay(), this, MSG_STUN_SEND, NULL);
 }
 
-int StunRequest::GetNextDelay() {
+void StunRequest::OnSent() {
-  int delay = DELAY_UNIT * std::min(1 << count_, DELAY_MAX_FACTOR);
   count_ += 1;
   if (count_ == MAX_SENDS)
     timeout_ = true;
-  return delay;
+}
+
+int StunRequest::resend_delay() {
+  if (count_ == 0) {
+    return 0;
+  }
+  return DELAY_UNIT * std::min(1 << (count_-1), DELAY_MAX_FACTOR);
 }
 
 }  // namespace cricket

webrtc/p2p/base/stunrequest.h

@@ -105,7 +105,10 @@ class StunRequest : public rtc::MessageHandler {
   virtual void OnResponse(StunMessage* response) {}
   virtual void OnErrorResponse(StunMessage* response) {}
   virtual void OnTimeout() {}
-  virtual int GetNextDelay();
+  // Called when the message is sent.
+  virtual void OnSent();
+  // Returns the next delay for resends.
+  virtual int resend_delay();
 
  private:
   void set_manager(StunRequestManager* manager);

webrtc/p2p/base/turnport.cc

@@ -57,10 +57,11 @@ static int GetRelayPreference(cricket::ProtocolType proto, bool secure) {
 class TurnAllocateRequest : public StunRequest {
  public:
   explicit TurnAllocateRequest(TurnPort* port);
-  virtual void Prepare(StunMessage* request);
+  void Prepare(StunMessage* request) override;
-  virtual void OnResponse(StunMessage* response);
+  void OnSent() override;
-  virtual void OnErrorResponse(StunMessage* response);
+  void OnResponse(StunMessage* response) override;
-  virtual void OnTimeout();
+  void OnErrorResponse(StunMessage* response) override;
+  void OnTimeout() override;
 
  private:
   // Handles authentication challenge from the server.
@@ -74,10 +75,11 @@ class TurnAllocateRequest : public StunRequest {
 class TurnRefreshRequest : public StunRequest {
  public:
   explicit TurnRefreshRequest(TurnPort* port);
-  virtual void Prepare(StunMessage* request);
+  void Prepare(StunMessage* request) override;
-  virtual void OnResponse(StunMessage* response);
+  void OnSent() override;
-  virtual void OnErrorResponse(StunMessage* response);
+  void OnResponse(StunMessage* response) override;
-  virtual void OnTimeout();
+  void OnErrorResponse(StunMessage* response) override;
+  void OnTimeout() override;
   void set_lifetime(int lifetime) { lifetime_ = lifetime; }
 
  private:
@@ -90,10 +92,11 @@ class TurnCreatePermissionRequest : public StunRequest,
  public:
   TurnCreatePermissionRequest(TurnPort* port, TurnEntry* entry,
                               const rtc::SocketAddress& ext_addr);
-  virtual void Prepare(StunMessage* request);
+  void Prepare(StunMessage* request) override;
-  virtual void OnResponse(StunMessage* response);
+  void OnSent() override;
-  virtual void OnErrorResponse(StunMessage* response);
+  void OnResponse(StunMessage* response) override;
-  virtual void OnTimeout();
+  void OnErrorResponse(StunMessage* response) override;
+  void OnTimeout() override;
 
  private:
   void OnEntryDestroyed(TurnEntry* entry);
@@ -108,10 +111,11 @@ class TurnChannelBindRequest : public StunRequest,
  public:
   TurnChannelBindRequest(TurnPort* port, TurnEntry* entry, int channel_id,
                          const rtc::SocketAddress& ext_addr);
-  virtual void Prepare(StunMessage* request);
+  void Prepare(StunMessage* request) override;
-  virtual void OnResponse(StunMessage* response);
+  void OnSent() override;
-  virtual void OnErrorResponse(StunMessage* response);
+  void OnResponse(StunMessage* response) override;
-  virtual void OnTimeout();
+  void OnErrorResponse(StunMessage* response) override;
+  void OnTimeout() override;
 
  private:
   void OnEntryDestroyed(TurnEntry* entry);
@@ -897,7 +901,18 @@ void TurnAllocateRequest::Prepare(StunMessage* request) {
   }
 }
 
+void TurnAllocateRequest::OnSent() {
+  LOG_J(LS_INFO, port_) << "TURN allocate request sent"
+                        << ", id=" << rtc::hex_encode(id());
+  StunRequest::OnSent();
+}
+
 void TurnAllocateRequest::OnResponse(StunMessage* response) {
+  LOG_J(LS_INFO, port_) << "TURN allocate requested successfully"
+                        << ", id=" << rtc::hex_encode(id())
+                        << ", code=0"  // Makes logging easier to parse.
+                        << ", rtt=" << Elapsed();
+
   // Check mandatory attributes as indicated in RFC5766, Section 6.3.
   const StunAddressAttribute* mapped_attr =
       response->GetAddress(STUN_ATTR_XOR_MAPPED_ADDRESS);
@@ -933,6 +948,12 @@ void TurnAllocateRequest::OnResponse(StunMessage* response) {
 void TurnAllocateRequest::OnErrorResponse(StunMessage* response) {
   // Process error response according to RFC5766, Section 6.4.
   const StunErrorCodeAttribute* error_code = response->GetErrorCode();
+
+  LOG_J(LS_INFO, port_) << "Received TURN allocate error response"
+                        << ", id=" << rtc::hex_encode(id())
+                        << ", code=" << error_code->code()
+                        << ", rtt=" << Elapsed();
+
   switch (error_code->code()) {
     case STUN_ERROR_UNAUTHORIZED:       // Unauthrorized.
       OnAuthChallenge(response, error_code->code());
@@ -946,14 +967,17 @@ void TurnAllocateRequest::OnErrorResponse(StunMessage* response) {
       port_->thread()->Post(port_, TurnPort::MSG_ALLOCATE_MISMATCH);
       break;
     default:
-      LOG_J(LS_WARNING, port_) << "Allocate response error, code="
+      LOG_J(LS_WARNING, port_) << "Received TURN allocate error response"
-                               << error_code->code();
+                               << ", id=" << rtc::hex_encode(id())
+                               << ", code=" << error_code->code()
+                               << ", rtt=" << Elapsed();
       port_->OnAllocateError();
   }
 }
 
 void TurnAllocateRequest::OnTimeout() {
-  LOG_J(LS_WARNING, port_) << "Allocate request timeout";
+  LOG_J(LS_WARNING, port_) << "TURN allocate request "
+                           << rtc::hex_encode(id()) << " timout";
   port_->OnAllocateRequestTimeout();
 }
 
@@ -1050,8 +1074,17 @@ void TurnRefreshRequest::Prepare(StunMessage* request) {
   port_->AddRequestAuthInfo(request);
 }
 
+void TurnRefreshRequest::OnSent() {
+  LOG_J(LS_INFO, port_) << "TURN refresh request sent"
+                        << ", id=" << rtc::hex_encode(id());
+  StunRequest::OnSent();
+}
+
 void TurnRefreshRequest::OnResponse(StunMessage* response) {
-  LOG_J(LS_INFO, port_) << "Refresh requested successfully.";
+  LOG_J(LS_INFO, port_) << "TURN refresh requested successfully"
+                        << ", id=" << rtc::hex_encode(id())
+                        << ", code=0"  // Makes logging easier to parse.
+                        << ", rtt=" << Elapsed();
 
   // Check mandatory attributes as indicated in RFC5766, Section 7.3.
   const StunUInt32Attribute* lifetime_attr =
@@ -1068,19 +1101,27 @@ void TurnRefreshRequest::OnResponse(StunMessage* response) {
 
 void TurnRefreshRequest::OnErrorResponse(StunMessage* response) {
   const StunErrorCodeAttribute* error_code = response->GetErrorCode();
-  LOG_J(LS_WARNING, port_) << "Refresh response error, code="
+
-                           << error_code->code();
+  LOG_J(LS_INFO, port_) << "Received TURN refresh error response"
+                        << ", id=" << rtc::hex_encode(id())
+                        << ", code=" << error_code->code()
+                        << ", rtt=" << Elapsed();
 
   if (error_code->code() == STUN_ERROR_STALE_NONCE) {
     if (port_->UpdateNonce(response)) {
       // Send RefreshRequest immediately.
       port_->SendRequest(new TurnRefreshRequest(port_), 0);
     }
+  } else {
+    LOG_J(LS_WARNING, port_) << "Received TURN refresh error response"
+                             << ", id=" << rtc::hex_encode(id())
+                             << ", code=" << error_code->code()
+                             << ", rtt=" << Elapsed();
   }
 }
 
 void TurnRefreshRequest::OnTimeout() {
-  LOG_J(LS_WARNING, port_) << "Refresh request timeout";
+  LOG_J(LS_WARNING, port_) << "TURN refresh timeout " << rtc::hex_encode(id());
 }
 
 TurnCreatePermissionRequest::TurnCreatePermissionRequest(
@@ -1102,7 +1143,18 @@ void TurnCreatePermissionRequest::Prepare(StunMessage* request) {
   port_->AddRequestAuthInfo(request);
 }
 
+void TurnCreatePermissionRequest::OnSent() {
+  LOG_J(LS_INFO, port_) << "TURN create permission request sent"
+                        << ", id=" << rtc::hex_encode(id());
+  StunRequest::OnSent();
+}
+
 void TurnCreatePermissionRequest::OnResponse(StunMessage* response) {
+  LOG_J(LS_INFO, port_) << "TURN permission requested successfully"
+                        << ", id=" << rtc::hex_encode(id())
+                        << ", code=0"  // Makes logging easier to parse.
+                        << ", rtt=" << Elapsed();
+
   if (entry_) {
     entry_->OnCreatePermissionSuccess();
   }
@@ -1110,15 +1162,18 @@ void TurnCreatePermissionRequest::OnResponse(StunMessage* response) {
 
 void TurnCreatePermissionRequest::OnErrorResponse(StunMessage* response) {
   const StunErrorCodeAttribute* error_code = response->GetErrorCode();
-  LOG_J(LS_WARNING, port_) << "Allocate response error, code="
+  LOG_J(LS_WARNING, port_) << "Received TURN create permission error response"
-                           << error_code->code();
+                           << ", id=" << rtc::hex_encode(id())
+                           << ", code=" << error_code->code()
+                           << ", rtt=" << Elapsed();
   if (entry_) {
     entry_->OnCreatePermissionError(response, error_code->code());
   }
 }
 
 void TurnCreatePermissionRequest::OnTimeout() {
-  LOG_J(LS_WARNING, port_) << "Create permission timeout";
+  LOG_J(LS_WARNING, port_) << "TURN create permission timeout "
+                           << rtc::hex_encode(id());
 }
 
 void TurnCreatePermissionRequest::OnEntryDestroyed(TurnEntry* entry) {
@@ -1148,7 +1203,18 @@ void TurnChannelBindRequest::Prepare(StunMessage* request) {
   port_->AddRequestAuthInfo(request);
 }
 
+void TurnChannelBindRequest::OnSent() {
+  LOG_J(LS_INFO, port_) << "TURN channel bind request sent"
+                        << ", id=" << rtc::hex_encode(id());
+  StunRequest::OnSent();
+}
+
 void TurnChannelBindRequest::OnResponse(StunMessage* response) {
+  LOG_J(LS_INFO, port_) << "TURN channel bind requested successfully"
+                        << ", id=" << rtc::hex_encode(id())
+                        << ", code=0"  // Makes logging easier to parse.
+                        << ", rtt=" << Elapsed();
+
   if (entry_) {
     entry_->OnChannelBindSuccess();
     // Refresh the channel binding just under the permission timeout
@@ -1162,14 +1228,19 @@ void TurnChannelBindRequest::OnResponse(StunMessage* response) {
 }
 
 void TurnChannelBindRequest::OnErrorResponse(StunMessage* response) {
+  const StunErrorCodeAttribute* error_code = response->GetErrorCode();
+  LOG_J(LS_WARNING, port_) << "Received TURN channel bind error response"
+                           << ", id=" << rtc::hex_encode(id())
+                           << ", code=" << error_code->code()
+                           << ", rtt=" << Elapsed();
   if (entry_) {
-    const StunErrorCodeAttribute* error_code = response->GetErrorCode();
     entry_->OnChannelBindError(response, error_code->code());
   }
 }
 
 void TurnChannelBindRequest::OnTimeout() {
-  LOG_J(LS_WARNING, port_) << "Channel bind timeout";
+  LOG_J(LS_WARNING, port_) << "TURN channel bind timeout "
+                           << rtc::hex_encode(id());
 }
 
 void TurnChannelBindRequest::OnEntryDestroyed(TurnEntry* entry) {
@@ -1235,9 +1306,6 @@ void TurnEntry::OnCreatePermissionSuccess() {
 }
 
 void TurnEntry::OnCreatePermissionError(StunMessage* response, int code) {
-  LOG_J(LS_WARNING, port_) << "Create permission for "
-                           << ext_addr_.ToSensitiveString()
-                           << " failed, code=" << code;
   if (code == STUN_ERROR_STALE_NONCE) {
     if (port_->UpdateNonce(response)) {
       SendCreatePermissionRequest();
@@ -1258,9 +1326,6 @@ void TurnEntry::OnChannelBindSuccess() {
 void TurnEntry::OnChannelBindError(StunMessage* response, int code) {
   // TODO(mallinath) - Implement handling of error response for channel
   // bind request as per http://tools.ietf.org/html/rfc5766#section-11.3
-  LOG_J(LS_WARNING, port_) << "Channel bind for "
-                           << ext_addr_.ToSensitiveString()
-                           << " failed, code=" << code;
   if (code == STUN_ERROR_STALE_NONCE) {
     if (port_->UpdateNonce(response)) {
       // Send channel bind request with fresh nonce.