shill: portal: improve logging
This patch improves captive portal dection logging by changing some SLOG
statements in device.cc into normal LOG statements such that feedback
reports contain more information.
This patch also fixes a logging error in portal_detector.cc. The attempt
number is now correctly printed inside http_request.cc.
BUG=b:197362052
TEST=unit tests. Flashed trogdor, forced captive portal to fail by
blocking DNS replies, observed retried logs in /var/log/net.log.
Change-Id: Ia95315f12f790b9de048d190148b0e8bd5360160
Reviewed-on: https://chromium-review.googlesource.com/c/chromiumos/platform2/+/3145034
Tested-by: Hugo Benichi <hugobenichi@google.com>
Commit-Queue: Hugo Benichi <hugobenichi@google.com>
Reviewed-by: Matthew Wang <matthewmwang@chromium.org>
Reviewed-by: Steven Bennetts <stevenjb@chromium.org>
diff --git a/shill/device.cc b/shill/device.cc
index e52b15c..9d6e33f 100644
--- a/shill/device.cc
+++ b/shill/device.cc
@@ -1256,25 +1256,20 @@
bool Device::RequestPortalDetection() {
if (!selected_service_) {
- SLOG(this, 2) << link_name()
- << ": No selected service, so no need for portal check.";
+ LOG(INFO) << link_name() << ": Skipping portal detection: no Service";
return false;
}
if (!connection_) {
- SLOG(this, 2) << link_name()
- << ": No connection, so no need for portal check.";
+ LOG(INFO) << link_name() << ": Skipping portal detection: no Connection";
return false;
}
- SLOG(this, 1) << __func__ << " for: " << selected_service_->log_name();
-
// Do not run portal detection unless in a connected state (i.e. connected,
// online, or portalled).
if (!selected_service_->IsConnected()) {
- SLOG(this, 3)
- << link_name()
- << ": Service is not in a connected state. No need to start check.";
+ LOG(INFO) << link_name()
+ << ": Skipping portal detection: Service is not connected";
return false;
}
@@ -1285,10 +1280,12 @@
}
if (portal_detector_.get() && portal_detector_->IsInProgress()) {
- SLOG(this, 2) << link_name() << ": Portal detection is already running.";
+ LOG(INFO) << link_name() << ": Portal detection is already running.";
return true;
}
+ SLOG(this, 1) << __func__ << " for: " << selected_service_->log_name();
+
return StartPortalDetection();
}
@@ -1300,21 +1297,20 @@
bool Device::StartPortalDetection() {
DCHECK(selected_service_);
SLOG(this, 1) << __func__ << " for: " << selected_service_->log_name();
+
if (selected_service_->IsPortalDetectionDisabled()) {
- SLOG(this, 2) << "Service " << selected_service_->log_name()
- << ": Portal detection is disabled; "
- << "marking service online.";
+ LOG(INFO) << link_name() << ": Portal detection is disabled for service "
+ << selected_service_->log_name();
SetServiceConnectedState(Service::kStateOnline);
return false;
}
+ // If portal detection is disabled for this technology, immediately set
+ // the service state to "Online".
if (selected_service_->IsPortalDetectionAuto() &&
!manager_->IsPortalDetectionEnabled(technology())) {
- // If portal detection is disabled for this technology, immediately set
- // the service state to "Online".
- SLOG(this, 2) << "Device " << link_name()
- << ": Portal detection is disabled; "
- << "marking service online.";
+ LOG(INFO) << link_name()
+ << ": Portal detection is disabled for this technology";
SetServiceConnectedState(Service::kStateOnline);
return false;
}
@@ -1326,20 +1322,18 @@
if (!portal_detector_->Start(props, connection_->interface_name(),
connection_->local(),
connection_->dns_servers())) {
- LOG(ERROR) << "Device " << link_name()
- << ": Portal detection failed to start: likely bad URL: "
- << props.http_url_string << " or " << props.https_url_string;
+ LOG(ERROR) << link_name() << ": Portal detection failed to start";
SetServiceConnectedState(Service::kStateOnline);
return false;
}
- SLOG(this, 2) << "Device " << link_name()
- << ": Portal detection has started.";
+ SLOG(this, 2) << link_name() << ": Portal detection has started.";
+
return true;
}
void Device::StopPortalDetection() {
- SLOG(this, 2) << "Device " << link_name() << ": Portal detection stopping.";
+ SLOG(this, 2) << link_name() << ": Portal detection stopping.";
portal_detector_.reset();
}
@@ -1352,26 +1346,22 @@
base::Bind(&Device::ConnectionDiagnosticsCallback, AsWeakPtr())));
if (!connection_diagnostics_->StartAfterPortalDetection(
manager_->GetPortalCheckHttpUrl(), result)) {
- LOG(ERROR) << "Device " << link_name()
- << ": Connection diagnostics failed to start: likely bad URL: "
- << manager_->GetPortalCheckHttpUrl();
+ LOG(ERROR) << link_name() << ": Connection diagnostics failed to start.";
connection_diagnostics_.reset();
return false;
}
- SLOG(this, 2) << "Device " << link_name()
- << ": Connection diagnostics has started.";
+ SLOG(this, 2) << link_name() << ": Connection diagnostics has started.";
return true;
}
void Device::StopConnectionDiagnostics() {
- SLOG(this, 2) << "Device " << link_name()
- << ": Connection diagnostics stopping.";
+ SLOG(this, 2) << link_name() << ": Connection diagnostics stopping.";
connection_diagnostics_.reset();
}
bool Device::StartConnectivityTest() {
- LOG(INFO) << "Device " << link_name() << " starting connectivity test.";
+ LOG(INFO) << link_name() << " starting connectivity test.";
connection_tester_.reset(new PortalDetector(
dispatcher(), metrics(),
@@ -1383,7 +1373,7 @@
}
void Device::StopConnectivityTest() {
- SLOG(this, 2) << "Device " << link_name() << ": Connectivity test stopping.";
+ SLOG(this, 2) << link_name() << ": Connectivity test stopping.";
connection_tester_.reset();
}
@@ -1412,22 +1402,24 @@
DCHECK(selected_service_.get());
if (!selected_service_) {
- LOG(ERROR) << link_name() << ": "
- << "Portal detection completed but no selected service exists!";
+ // A race can happen if the Service has disconnected in the meantime.
+ LOG(WARNING)
+ << link_name() << ": "
+ << "Portal detection completed but no selected service exists.";
return;
}
if (!selected_service_->IsConnected()) {
- LOG(ERROR) << link_name() << ": "
- << "Portal detection completed but selected service "
- << selected_service_->log_name()
- << " is in non-connected state.";
+ // A race can happen if the Service is currently disconnecting.
+ LOG(WARNING) << link_name() << ": "
+ << "Portal detection completed but selected service "
+ << selected_service_->log_name()
+ << " is in non-connected state.";
return;
}
- SLOG(this, 2) << __func__ << " Service: "
- << GetSelectedServiceRpcIdentifier(nullptr).value()
- << " State: " << static_cast<int>(state);
+ SLOG(this, 2) << __func__ << " Service: " << selected_service_->log_name()
+ << " State: " << Service::ConnectStateToString(state);
if (Service::IsPortalledState(state) && connection_->IsDefault()) {
CHECK(portal_detector_.get());
@@ -1436,17 +1428,14 @@
if (!portal_detector_->Start(props, connection_->interface_name(),
connection_->local(),
connection_->dns_servers(), next_delay)) {
- LOG(ERROR) << "Device " << link_name()
- << ": Portal detection failed to restart: likely bad URL: "
- << props.http_url_string << " or " << props.https_url_string;
+ LOG(ERROR) << link_name() << ": Portal detection failed to restart";
SetServiceState(Service::kStateOnline);
StopPortalDetection();
return;
}
- LOG(INFO) << "Device " << link_name() << ": Portal detection retrying in "
- << next_delay;
+ LOG(INFO) << link_name() << ": Portal detection retrying in " << next_delay;
} else {
- SLOG(this, 2) << "Device " << link_name() << ": Portal will not retry.";
+ LOG(INFO) << link_name() << ": Portal detection finished";
StopPortalDetection();
}
diff --git a/shill/http_request.cc b/shill/http_request.cc
index b2d3e69..290b185 100644
--- a/shill/http_request.cc
+++ b/shill/http_request.cc
@@ -42,13 +42,11 @@
const int HttpRequest::kRequestTimeoutSeconds = 10;
HttpRequest::HttpRequest(EventDispatcher* dispatcher,
- const std::string& logging_tag,
const std::string& interface_name,
const IPAddress& src_address,
const std::vector<std::string>& dns_list,
bool allow_non_google_https)
- : logging_tag_(logging_tag),
- interface_name_(interface_name),
+ : interface_name_(interface_name),
ip_family_(src_address.family()),
dns_list_(dns_list),
weak_ptr_factory_(this),
@@ -82,6 +80,7 @@
}
HttpRequest::Result HttpRequest::Start(
+ const std::string& logging_tag,
const std::string& url_string,
const brillo::http::HeaderList& headers,
const base::Callback<void(std::shared_ptr<brillo::http::Response>)>&
@@ -91,6 +90,7 @@
DCHECK(!is_running_);
+ logging_tag_ = logging_tag;
HttpUrl url;
if (!url.ParseFromString(url_string)) {
LOG(ERROR) << logging_tag_
diff --git a/shill/http_request.h b/shill/http_request.h
index 05d7983..fa7f9a5 100644
--- a/shill/http_request.h
+++ b/shill/http_request.h
@@ -47,7 +47,6 @@
// communication with a non-Google server is allowed. Note that this
// will not change any behavior for HTTP communication.
HttpRequest(EventDispatcher* dispatcher,
- const std::string& logging_tag,
const std::string& interface_name,
const IPAddress& src_address,
const std::vector<std::string>& dns_list,
@@ -65,6 +64,7 @@
// initialize the DNS client, or kResultInProgress if the request
// has started successfully and is now in progress.
virtual Result Start(
+ const std::string& logging_tag,
const std::string& url_string,
const brillo::http::HeaderList& headers,
const base::Callback<void(std::shared_ptr<brillo::http::Response>)>&
diff --git a/shill/http_request_test.cc b/shill/http_request_test.cc
index 6c26808..f63d4b9 100644
--- a/shill/http_request_test.cc
+++ b/shill/http_request_test.cc
@@ -117,7 +117,7 @@
};
void SetUp() override {
- request_.reset(new HttpRequest(&dispatcher_, kLoggingTag, interface_name_,
+ request_.reset(new HttpRequest(&dispatcher_, interface_name_,
IPAddress(IPAddress::kFamilyIPv4),
{kDNSServer0, kDNSServer1}, true));
// Passes ownership.
@@ -187,7 +187,8 @@
request_->GetDNSResult(error, address);
}
HttpRequest::Result StartRequest(const std::string& url) {
- return request_->Start(url, {}, target_.request_success_callback(),
+ return request_->Start(kLoggingTag, url, {},
+ target_.request_success_callback(),
target_.request_error_callback());
}
void ExpectCreateConnection(const std::string& url) {
diff --git a/shill/portal_detector.cc b/shill/portal_detector.cc
index a50404e..3d3b6a0 100644
--- a/shill/portal_detector.cc
+++ b/shill/portal_detector.cc
@@ -110,15 +110,13 @@
if (http_request_ || https_request_) {
CleanupTrial();
} else {
- http_request_ =
- std::make_unique<HttpRequest>(dispatcher_, LoggingTag() + " HTTP probe",
- ifname, src_address, dns_list);
+ http_request_ = std::make_unique<HttpRequest>(dispatcher_, ifname,
+ src_address, dns_list);
// For non-default URLs, allow for secure communication with both Google and
// non-Google servers.
bool allow_non_google_https = (https_url_string_ != kDefaultHttpsUrl);
https_request_ = std::make_unique<HttpRequest>(
- dispatcher_, LoggingTag() + " HTTPS probe", ifname, src_address,
- dns_list, allow_non_google_https);
+ dispatcher_, ifname, src_address, dns_list, allow_non_google_https);
}
trial_.Reset(base::Bind(&PortalDetector::StartTrialTask,
weak_ptr_factory_.GetWeakPtr()));
@@ -142,8 +140,8 @@
base::Bind(&PortalDetector::HttpRequestErrorCallback,
weak_ptr_factory_.GetWeakPtr()));
HttpRequest::Result http_result = http_request_->Start(
- http_url_string_, kHeaders, http_request_success_callback,
- http_request_error_callback);
+ LoggingTag() + " HTTP probe", http_url_string_, kHeaders,
+ http_request_success_callback, http_request_error_callback);
if (http_result != HttpRequest::kResultInProgress) {
// If the http probe fails to start, complete the trial with a failure
// Result for https.
@@ -168,8 +166,8 @@
base::Bind(&PortalDetector::HttpsRequestErrorCallback,
weak_ptr_factory_.GetWeakPtr()));
HttpRequest::Result https_result = https_request_->Start(
- https_url_string_, kHeaders, https_request_success_callback,
- https_request_error_callback);
+ LoggingTag() + " HTTPS probe", https_url_string_, kHeaders,
+ https_request_success_callback, https_request_error_callback);
if (https_result != HttpRequest::kResultInProgress) {
result_->https_phase = GetPortalPhaseForRequestResult(https_result);
result_->https_status = GetPortalStatusForRequestResult(https_result);
diff --git a/shill/portal_detector_test.cc b/shill/portal_detector_test.cc
index 934ad25..cb04e5a 100644
--- a/shill/portal_detector_test.cc
+++ b/shill/portal_detector_test.cc
@@ -31,7 +31,6 @@
namespace {
const char kBadURL[] = "badurl";
-const char kLoggingTag[] = "int0 IPv4 attempt=1 HTTP probe";
const char kInterfaceName[] = "int0";
const char kHttpUrl[] = "http://www.chromium.org";
const char kHttpsUrl[] = "https://www.google.com";
@@ -48,11 +47,10 @@
public:
MockHttpRequest()
: HttpRequest(nullptr,
- kLoggingTag,
kInterfaceName,
IPAddress(IPAddress::kFamilyIPv4),
{kDNSServer0, kDNSServer1},
- true){};
+ true) {}
MockHttpRequest(const MockHttpRequest&) = delete;
MockHttpRequest& operator=(const MockHttpRequest&) = delete;
~MockHttpRequest() = default;
@@ -61,6 +59,7 @@
HttpRequest::Result,
Start,
(const std::string&,
+ const std::string&,
const brillo::http::HeaderList&,
const base::Callback<void(std::shared_ptr<brillo::http::Response>)>&,
const base::Callback<void(Result)>&),
@@ -147,9 +146,9 @@
}
void StartTrialTask() {
- EXPECT_CALL(*http_request(), Start(_, _, _, _))
+ EXPECT_CALL(*http_request(), Start(_, _, _, _, _))
.WillOnce(Return(HttpRequest::kResultInProgress));
- EXPECT_CALL(*https_request(), Start(_, _, _, _))
+ EXPECT_CALL(*https_request(), Start(_, _, _, _, _))
.WillOnce(Return(HttpRequest::kResultInProgress));
portal_detector()->StartTrialTask();
}
@@ -255,7 +254,7 @@
EXPECT_TRUE(StartPortalRequest(props));
// Expect that the request will be started -- return failure.
- EXPECT_CALL(*http_request(), Start(_, _, _, _))
+ EXPECT_CALL(*http_request(), Start(_, _, _, _, _))
.WillOnce(Return(HttpRequest::kResultDNSFailure));
EXPECT_CALL(dispatcher(), PostDelayedTask(_, _, 0)).Times(0);
