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}
diff --git a/webrtc/base/stringencode.cc b/webrtc/base/stringencode.cc
index 5662040..880538d 100644
--- a/webrtc/base/stringencode.cc
+++ b/webrtc/base/stringencode.cc
@@ -466,6 +466,10 @@
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 79af285..df163dd 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 <string>
#include <sstream>
+#include <string>
#include <vector>
#include "webrtc/base/checks.h"
@@ -95,6 +95,7 @@
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 bf7d75f..9a7463c 100644
--- a/webrtc/p2p/base/port.cc
+++ b/webrtc/p2p/base/port.cc
@@ -29,7 +29,7 @@
// 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 @@
// 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 @@
} 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 @@
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 @@
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 @@
}
}
- 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::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 @@
// 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 @@
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 @@
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 @@
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 @@
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 @@
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 @@
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 @@
}
}
+ 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::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 a9d4c00..a6a54e8 100644
--- a/webrtc/p2p/base/port.h
+++ b/webrtc/p2p/base/port.h
@@ -402,6 +402,15 @@
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 @@
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 @@
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 @@
// 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_;
diff --git a/webrtc/p2p/base/relayport.cc b/webrtc/p2p/base/relayport.cc
index 8e74ee3..e593f52 100644
--- a/webrtc/p2p/base/relayport.cc
+++ b/webrtc/p2p/base/relayport.cc
@@ -159,13 +159,14 @@
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 @@
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 fe125ec..953e585 100644
--- a/webrtc/p2p/base/stunport.cc
+++ b/webrtc/p2p/base/stunport.cc
@@ -39,11 +39,11 @@
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 @@
}
}
- 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 @@
}
}
- 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 1f124ee..e3f21df 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 @@
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 @@
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 @@
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 6a4bdc0..e6b9e7d 100644
--- a/webrtc/p2p/base/stunrequest.h
+++ b/webrtc/p2p/base/stunrequest.h
@@ -105,7 +105,10 @@
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 e839187..58fb01a 100644
--- a/webrtc/p2p/base/turnport.cc
+++ b/webrtc/p2p/base/turnport.cc
@@ -57,10 +57,11 @@
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 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 @@
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 @@
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::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::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 @@
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 @@
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::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 @@
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::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 @@
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::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::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::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.