diff --git a/webrtc/base/stringencode.cc b/webrtc/base/stringencode.cc index 5662040c62..880538d4e9 100644 --- a/webrtc/base/stringencode.cc +++ b/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); } diff --git a/webrtc/base/stringencode.h b/webrtc/base/stringencode.h index 79af28509f..df163dd34e 100644 --- a/webrtc/base/stringencode.h +++ b/webrtc/base/stringencode.h @@ -11,8 +11,8 @@ #ifndef WEBRTC_BASE_STRINGENCODE_H_ #define WEBRTC_BASE_STRINGENCODE_H_ -#include #include +#include #include #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); diff --git a/webrtc/p2p/base/port.cc b/webrtc/p2p/base/port.cc index bf7d75fbad..9a7463cb37 100644 --- a/webrtc/p2p/base/port.cc +++ b/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& pings_since_last_response, + const std::vector& 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& pings_since_last_response, + const std::vector& 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) { - LOG_J(LS_ERROR, this) << "Failed to send STUN ping response to " - << addr.ToSensitiveString(); + auto err = SendTo(buf.Data(), buf.Length(), addr, options, false); + if (err < 0) { + 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(), - options, false) < 0) { - LOG_J(LS_WARNING, this) << "Failed to send STUN ping " << req->id(); + auto err = port_->SendTo( + data, size, remote_candidate_.address(), options, false); + 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; - for (size_t i = 0; i < pings_since_last_response_.size(); ++i) { - char buf[32]; - rtc::sprintfn(buf, sizeof(buf), "%u", - pings_since_last_response_[i]); - pings.append(buf).append(" "); + if (rtc::LogCheckLevel(rtc::LS_VERBOSE)) { + std::string pings; + PrintPingsSinceLastResponse(&pings, 5); + LOG_J(LS_VERBOSE, this) << "UpdateState()" + << ", ms since last received response=" + << 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 " - << now - last_ping_received_ + LOG_J(LS_INFO, this) << "Unreadable after " << 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] - << " ms without a response, rtt=" << rtt; + << now - pings_since_last_response_[0].sent_time + << " 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; - for (size_t i = 0; i < pings_since_last_response_.size(); ++i) { - char buf[32]; - rtc::sprintfn(buf, sizeof(buf), "%u", - pings_since_last_response_[i]); - pings.append(buf).append(" "); + if (rtc::LogCheckLevel(sev)) { + std::string pings; + PrintPingsSinceLastResponse(&pings, 5); + LOG_JV(sev, this) << "Received STUN ping response" + << ", id=" << rtc::hex_encode(request->id()) + << ", 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::LS_INFO : rtc::LS_VERBOSE; - LOG_JV(sev, this) << "Timing-out STUN ping " << request->id() + rtc::LoggingSeverity sev = writable() ? rtc::LS_INFO : rtc::LS_VERBOSE; + LOG_JV(sev, this) << "Timing-out STUN ping " + << 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 diff --git a/webrtc/p2p/base/port.h b/webrtc/p2p/base/port.h index a9d4c00aad..a6a54e8d26 100644 --- a/webrtc/p2p/base/port.h +++ b/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 pings_since_last_response_; + std::vector pings_since_last_response_; rtc::RateTracker recv_rate_tracker_; rtc::RateTracker send_rate_tracker_; diff --git a/webrtc/p2p/base/relayport.cc b/webrtc/p2p/base/relayport.cc index 8e74ee3682..e593f52ecf 100644 --- a/webrtc/p2p/base/relayport.cc +++ b/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); - virtual void OnErrorResponse(StunMessage* response); - virtual void OnTimeout(); + void OnResponse(StunMessage* response) override; + void OnErrorResponse(StunMessage* response) override; + void OnTimeout() override; private: RelayEntry* entry_; @@ -775,14 +776,20 @@ void AllocateRequest::Prepare(StunMessage* request) { VERIFY(request->AddAttribute(username_attr)); } -int AllocateRequest::GetNextDelay() { - int delay = 100 * std::max(1 << count_, 2); +void AllocateRequest::OnSent() { 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); diff --git a/webrtc/p2p/base/stunport.cc b/webrtc/p2p/base/stunport.cc index fe125ec2bf..953e585444 100644 --- a/webrtc/p2p/base/stunport.cc +++ b/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() << ")"; diff --git a/webrtc/p2p/base/stunrequest.cc b/webrtc/p2p/base/stunrequest.cc index 1f124ee917..e3f21df7b4 100644 --- a/webrtc/p2p/base/stunrequest.cc +++ b/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 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(); - manager_->thread_->PostDelayed(delay, this, MSG_STUN_SEND, NULL); + OnSent(); + manager_->thread_->PostDelayed(resend_delay(), this, MSG_STUN_SEND, NULL); } -int StunRequest::GetNextDelay() { - int delay = DELAY_UNIT * std::min(1 << count_, DELAY_MAX_FACTOR); +void StunRequest::OnSent() { 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 diff --git a/webrtc/p2p/base/stunrequest.h b/webrtc/p2p/base/stunrequest.h index 6a4bdc0971..e6b9e7dcfd 100644 --- a/webrtc/p2p/base/stunrequest.h +++ b/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); diff --git a/webrtc/p2p/base/turnport.cc b/webrtc/p2p/base/turnport.cc index e839187ee2..58fb01a4e8 100644 --- a/webrtc/p2p/base/turnport.cc +++ b/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); - virtual void OnResponse(StunMessage* response); - virtual void OnErrorResponse(StunMessage* response); - virtual void OnTimeout(); + void Prepare(StunMessage* request) override; + void OnSent() override; + void OnResponse(StunMessage* response) override; + 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); - virtual void OnResponse(StunMessage* response); - virtual void OnErrorResponse(StunMessage* response); - virtual void OnTimeout(); + void Prepare(StunMessage* request) override; + void OnSent() override; + void OnResponse(StunMessage* response) override; + 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); - virtual void OnResponse(StunMessage* response); - virtual void OnErrorResponse(StunMessage* response); - virtual void OnTimeout(); + void Prepare(StunMessage* request) override; + void OnSent() override; + void OnResponse(StunMessage* response) override; + 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); - virtual void OnResponse(StunMessage* response); - virtual void OnErrorResponse(StunMessage* response); - virtual void OnTimeout(); + void Prepare(StunMessage* request) override; + void OnSent() override; + void OnResponse(StunMessage* response) override; + 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=" - << error_code->code(); + LOG_J(LS_WARNING, port_) << "Received TURN allocate error response" + << ", 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=" - << error_code->code(); + LOG_J(LS_WARNING, port_) << "Received TURN create permission error response" + << ", 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.