Temporary verbose logs into certificateProvider

Add VLOG statements for the certificate, signature and PIN requests into
the chrome.certificateProvider API implementation.

These logs will help in investigating testing and customer issues for
the Chrome OS smart card login feature.

The logs will have to be removed later, once the feature gets
stabilized.

Bug: 1046860
Change-Id: Id3aaa57118f9134f15dee0e861c606ebb3e03252
Reviewed-on: https://chromium-review.googlesource.com/c/chromium/src/+/2029508Reviewed-by: Igor <igorcov@chromium.org>
Commit-Queue: Maksim Ivanov <emaxx@chromium.org>
Cr-Commit-Position: refs/heads/master@{#736780}

chrome/browser/chromeos/certificate_provider/certificate_provider_service.cc

@@ -256,6 +256,10 @@ void CertificateProviderService::ReplyToSignRequest(
     const std::vector<uint8_t>& signature) {
   DCHECK_CALLED_ON_VALID_SEQUENCE(sequence_checker_);
 
+  // TODO(crbug.com/1046860): Remove logging after stabilizing the feature.
+  VLOG(1) << "Extension " << extension_id << " replied to signature request "
+          << sign_request_id << ", size " << signature.size();
+
   scoped_refptr<net::X509Certificate> certificate;
   net::SSLPrivateKey::SignCallback callback;
   if (!sign_requests_.RemoveRequest(extension_id, sign_request_id, &certificate,
@@ -367,6 +371,11 @@ void CertificateProviderService::AbortSignatureRequestsForAuthenticatingUser(
        sign_requests_to_abort) {
     const std::string& extension_id = sign_request.first;
     const int sign_request_id = sign_request.second;
+
+    // TODO(crbug.com/1046860): Remove logging after stabilizing the feature.
+    VLOG(1) << "Aborting user login signature request from extension "
+            << extension_id << " id " << sign_request_id;
+
     pin_dialog_manager_.AbortSignRequest(extension_id, sign_request_id);
 
     scoped_refptr<net::X509Certificate> certificate;
@@ -448,10 +457,18 @@ void CertificateProviderService::RequestSignatureFromExtension(
   const int sign_request_id = sign_requests_.AddRequest(
       extension_id, certificate, authenticating_user_account_id,
       std::move(callback));
+
+  // TODO(crbug.com/1046860): Remove logging after stabilizing the feature.
+  VLOG(1) << "Starting signature request to extension " << extension_id
+          << " id " << sign_request_id;
+
   pin_dialog_manager_.AddSignRequestId(extension_id, sign_request_id,
                                        authenticating_user_account_id);
   if (!delegate_->DispatchSignRequestToExtension(
           extension_id, sign_request_id, algorithm, certificate, digest)) {
+    // TODO(crbug.com/1046860): Remove logging after stabilizing the feature.
+    VLOG(1) << "Failed to dispatch signature request to extension "
+            << extension_id << " id " << sign_request_id;
     scoped_refptr<net::X509Certificate> local_certificate;
     sign_requests_.RemoveRequest(extension_id, sign_request_id,
                                  &local_certificate, &callback);

chrome/browser/extensions/api/certificate_provider/certificate_provider_api.cc

@@ -160,6 +160,10 @@ CertificateProviderInternalReportCertificatesFunction::Run() {
       rejected_certificates.push_back(input_cert_info.certificate);
   }
 
+  // TODO(crbug.com/1046860): Remove logging after stabilizing the feature.
+  VLOG(1) << "Certificates provided by extension " << extension()->id() << ": "
+          << cert_infos.size() << ", rejected " << rejected_certificates.size();
+
   if (service->SetCertificatesProvidedByExtension(
           extension_id(), params->request_id, cert_infos)) {
     return RespondNow(ArgumentList(
@@ -248,6 +252,10 @@ CertificateProviderStopPinRequestFunction::Run() {
       api_cp::RequestPin::Params::Create(*args_));
   EXTENSION_FUNCTION_VALIDATE(params);
 
+  // TODO(crbug.com/1046860): Remove logging after stabilizing the feature.
+  VLOG(1) << "Handling PIN stop request from extension " << extension()->id()
+          << " error " << params->details.error_type;
+
   chromeos::CertificateProviderService* const service =
       chromeos::CertificateProviderServiceFactory::GetForBrowserContext(
           browser_context());
@@ -259,9 +267,14 @@ CertificateProviderStopPinRequestFunction::Run() {
     if (!dialog_closed) {
       // This might happen if the user closed the dialog while extension was
       // processing the input.
+      // TODO(crbug.com/1046860): Remove logging after stabilizing the feature.
+      VLOG(1) << "PIN stop request failed: "
+              << kCertificateProviderNoActiveDialog;
       return RespondNow(Error(kCertificateProviderNoActiveDialog));
     }
 
+    // TODO(crbug.com/1046860): Remove logging after stabilizing the feature.
+    VLOG(1) << "PIN stop request succeeded";
     return RespondNow(NoArguments());
   }
 
@@ -275,20 +288,24 @@ CertificateProviderStopPinRequestFunction::Run() {
           base::BindOnce(
               &CertificateProviderStopPinRequestFunction::OnPinRequestStopped,
               this));
+  std::string error_result;
   switch (stop_request_result) {
     case chromeos::PinDialogManager::StopPinRequestResult::kNoActiveDialog:
-      return RespondNow(Error(kCertificateProviderNoActiveDialog));
+      error_result = kCertificateProviderNoActiveDialog;
+      break;
     case chromeos::PinDialogManager::StopPinRequestResult::kNoUserInput:
-      return RespondNow(Error(kCertificateProviderNoUserInput));
+      error_result = kCertificateProviderNoUserInput;
+      break;
     case chromeos::PinDialogManager::StopPinRequestResult::kSuccess:
       return RespondLater();
   }
-
-  NOTREACHED();
-  return RespondLater();
+  // TODO(crbug.com/1046860): Remove logging after stabilizing the feature.
+  VLOG(1) << "PIN stop request failed: " << error_result;
+  return RespondNow(Error(error_result));
 }
 
 void CertificateProviderStopPinRequestFunction::OnPinRequestStopped() {
+  VLOG(1) << "PIN stop request succeeded";
   Respond(NoArguments());
 }
 
@@ -360,6 +377,12 @@ ExtensionFunction::ResponseAction CertificateProviderRequestPinFunction::Run() {
     attempts_left = *params->details.attempts_left;
   }
 
+  // TODO(crbug.com/1046860): Remove logging after stabilizing the feature.
+  VLOG(1) << "Starting PIN request from extension " << extension()->id()
+          << " signRequestId " << params->details.sign_request_id << " type "
+          << params->details.request_type << " error "
+          << params->details.error_type << " attempts " << attempts_left;
+
   const chromeos::PinDialogManager::RequestPinResult result =
       service->pin_dialog_manager()->RequestPin(
           extension()->id(), extension()->name(),
@@ -367,19 +390,23 @@ ExtensionFunction::ResponseAction CertificateProviderRequestPinFunction::Run() {
           attempts_left,
           base::BindOnce(
               &CertificateProviderRequestPinFunction::OnInputReceived, this));
+  std::string error_result;
   switch (result) {
     case chromeos::PinDialogManager::RequestPinResult::kSuccess:
       return RespondLater();
     case chromeos::PinDialogManager::RequestPinResult::kInvalidId:
-      return RespondNow(Error(kCertificateProviderInvalidId));
+      error_result = kCertificateProviderInvalidId;
+      break;
     case chromeos::PinDialogManager::RequestPinResult::kOtherFlowInProgress:
-      return RespondNow(Error(kCertificateProviderOtherFlowInProgress));
+      error_result = kCertificateProviderOtherFlowInProgress;
+      break;
     case chromeos::PinDialogManager::RequestPinResult::kDialogDisplayedAlready:
-      return RespondNow(Error(kCertificateProviderPreviousDialogActive));
+      error_result = kCertificateProviderPreviousDialogActive;
+      break;
   }
-
-  NOTREACHED();
-  return RespondNow(Error(kCertificateProviderPreviousDialogActive));
+  // TODO(crbug.com/1046860): Remove logging after stabilizing the feature.
+  VLOG(1) << "PIN request failed: " << error_result;
+  return RespondNow(Error(error_result));
 }
 
 void CertificateProviderRequestPinFunction::OnInputReceived(
@@ -390,9 +417,14 @@ void CertificateProviderRequestPinFunction::OnInputReceived(
           browser_context());
   DCHECK(service);
   if (!value.empty()) {
+    // TODO(crbug.com/1046860): Remove logging after stabilizing the feature.
+    VLOG(1) << "PIN request succeeded";
     api::certificate_provider::PinResponseDetails details;
     details.user_input = std::make_unique<std::string>(value);
     create_results->Append(details.ToValue());
+  } else {
+    // TODO(crbug.com/1046860): Remove logging after stabilizing the feature.
+    VLOG(1) << "PIN request canceled";
   }
 
   Respond(ArgumentList(std::move(create_results)));