Added verbose logging flag and moved most messages to verbose

Bug: 1052578: Add verbose logging to GCPW and move most messages under verbose.
Change-Id: I2bd51f2c59c0ca2487b5337abec81186784728be
Reviewed-on: https://chromium-review.googlesource.com/c/chromium/src/+/2058257Reviewed-by: Tien Mai <tienmai@chromium.org>
Reviewed-by: Yusuf Sengul <yusufsn@google.com>
Commit-Queue: Emre Kanlikilicer <emreknlk@google.com>
Cr-Commit-Position: refs/heads/master@{#742638}

chrome/credential_provider/gaiacp/associated_user_validator.cc

@@ -71,8 +71,8 @@ unsigned __stdcall CheckReauthStatus(void* param) {
     std::vector<char> response;
     hr = reauth_info->fetcher->Fetch(&response);
     if (FAILED(hr)) {
-      LOGFN(INFO) << "fetcher.Fetch sid=" << reauth_info->sid
-                  << " hr=" << putHR(hr);
+      LOGFN(ERROR) << "fetcher.Fetch sid=" << reauth_info->sid
+                   << " hr=" << putHR(hr);
       return 1;
     }
 
@@ -86,7 +86,7 @@ unsigned __stdcall CheckReauthStatus(void* param) {
 
     base::Optional<int> expires_in = properties->FindIntKey("expires_in");
     if (properties->FindKey("error") || !expires_in || expires_in.value() < 0) {
-      LOGFN(INFO) << "Needs reauth sid=" << reauth_info->sid;
+      LOGFN(VERBOSE) << "Needs reauth sid=" << reauth_info->sid;
       return 0;
     }
   }
@@ -199,8 +199,9 @@ bool AssociatedUserValidator::IsOnlineLoginStale(
       last_login_millis, &last_login_size);
 
   if (FAILED(hr)) {
-    LOGFN(INFO) << "GetUserProperty for " << kKeyLastSuccessfulOnlineLoginMillis
-                << " failed. hr=" << putHR(hr);
+    LOGFN(VERBOSE) << "GetUserProperty for "
+                   << kKeyLastSuccessfulOnlineLoginMillis
+                   << " failed. hr=" << putHR(hr);
     // Fallback to the less obstructive option to not enforce login via google
     // when fetching the registry entry fails.
     return false;
@@ -212,8 +213,8 @@ bool AssociatedUserValidator::IsOnlineLoginStale(
   hr = GetGlobalFlag(base::UTF8ToUTF16(kKeyValidityPeriodInDays),
                      &validity_period_days);
   if (FAILED(hr)) {
-    LOGFN(INFO) << "GetGlobalFlag for " << kKeyValidityPeriodInDays
-                << " failed. hr=" << putHR(hr);
+    LOGFN(VERBOSE) << "GetGlobalFlag for " << kKeyValidityPeriodInDays
+                   << " failed. hr=" << putHR(hr);
     // Fallback to the less obstructive option to not enforce login via google
     // when fetching the registry entry fails.
     return false;
@@ -304,12 +305,12 @@ bool AssociatedUserValidator::DenySigninForUsersWithInvalidTokenHandles(
   base::AutoLock locker(validator_lock_);
 
   if (block_deny_access_update_) {
-    LOGFN(INFO) << "Block the deny access update";
+    LOGFN(VERBOSE) << "Block the deny access update";
     return false;
   }
 
   if (!IsUserAccessBlockingEnforced(cpus)) {
-    LOGFN(INFO) << "User Access Blocking not enforced.";
+    LOGFN(VERBOSE) << "User Access Blocking not enforced.";
     return false;
   }
 
@@ -330,7 +331,7 @@ bool AssociatedUserValidator::DenySigninForUsersWithInvalidTokenHandles(
     // Note that logon hours cannot be changed on domain joined AD user account.
     if (GetAuthEnforceReason(sid) != EnforceAuthReason::NOT_ENFORCED &&
         !manager->IsUserDomainJoined(sid)) {
-      LOGFN(INFO) << "Revoking access for sid=" << sid;
+      LOGFN(VERBOSE) << "Revoking access for sid=" << sid;
       HRESULT hr = ModifyUserAccess(policy, sid, false);
       if (FAILED(hr)) {
         LOGFN(ERROR) << "ModifyUserAccess sid=" << sid << " hr=" << putHR(hr);
@@ -340,7 +341,7 @@ bool AssociatedUserValidator::DenySigninForUsersWithInvalidTokenHandles(
       }
     } else if (manager->IsUserDomainJoined(sid)) {
       // TODO(crbug.com/973160): Description provided in the bug.
-      LOGFN(INFO) << "Not denying signin for AD user accounts.";
+      LOGFN(VERBOSE) << "Not denying signin for AD user accounts.";
     }
   }
 
@@ -383,7 +384,7 @@ void AssociatedUserValidator::AllowSigninForAllAssociatedUsers(
 void AssociatedUserValidator::AllowSigninForUsersWithInvalidTokenHandles() {
   base::AutoLock locker(validator_lock_);
 
-  LOGFN(INFO);
+  LOGFN(VERBOSE);
   auto policy = ScopedLsaPolicy::Create(POLICY_ALL_ACCESS);
   for (auto& sid : locked_user_sids_) {
     HRESULT hr = ModifyUserAccess(policy, sid, true);
@@ -518,9 +519,9 @@ AssociatedUserValidator::GetAuthEnforceReason(const base::string16& sid) {
     base::string16 store_key = GetUserPasswordLsaStoreKey(sid);
     auto policy = ScopedLsaPolicy::Create(POLICY_ALL_ACCESS);
     if (!policy->PrivateDataExists(store_key.c_str())) {
-      LOGFN(INFO) << "Enforcing re-auth due to missing password lsa store "
-                     "data for user "
-                  << sid;
+      LOGFN(VERBOSE) << "Enforcing re-auth due to missing password lsa store "
+                        "data for user "
+                     << sid;
       return AssociatedUserValidator::EnforceAuthReason::
           MISSING_PASSWORD_RECOVERY_INFO;
     }

chrome/credential_provider/gaiacp/dllmain.cc

@@ -61,7 +61,7 @@ extern "C" BOOL WINAPI DllMain(HINSTANCE hinstance,
 // Used to determine whether the DLL can be unloaded by OLE.
 STDAPI DllCanUnloadNow(void) {
   HRESULT hr = _AtlModule.DllCanUnloadNow();
-  LOGFN(INFO) << "hr=" << putHR(hr);
+  LOGFN(VERBOSE) << "hr=" << putHR(hr);
   return hr;
 }
 
@@ -90,14 +90,14 @@ STDAPI DllGetClassObject(REFCLSID rclsid, REFIID riid, LPVOID* ppv) {
 // DllRegisterServer - Adds entries to the system registry.
 STDAPI DllRegisterServer(void) {
   HRESULT hr = credential_provider::CGaiaCredentialBase::OnDllRegisterServer();
-  LOGFN(INFO) << "CGaiaCredential::OnDllRegisterServer hr=" << putHR(hr);
+  LOGFN(VERBOSE) << "CGaiaCredential::OnDllRegisterServer hr=" << putHR(hr);
 
   if (SUCCEEDED(hr)) {
     // Registers object.  FALSE means don't register typelib.  The default
     // behaviour is assume the typelib has ID 1.  But in this case grit can't
     // be forced to use an ID of 1 when writing the rc file.
     hr = _AtlModule.DllRegisterServer(FALSE);
-    LOGFN(INFO) << "_AtlModule.DllRegisterServer hr=" << putHR(hr);
+    LOGFN(VERBOSE) << "_AtlModule.DllRegisterServer hr=" << putHR(hr);
   }
 
 #if BUILDFLAG(GOOGLE_CHROME_BRANDING)
@@ -139,11 +139,11 @@ STDAPI DllUnregisterServer(void) {
 
   HRESULT hr =
       credential_provider::CGaiaCredentialBase::OnDllUnregisterServer();
-  LOGFN(INFO) << "CGaiaCredential::OnDllUnregisterServer hr=" << putHR(hr);
+  LOGFN(VERBOSE) << "CGaiaCredential::OnDllUnregisterServer hr=" << putHR(hr);
   all_succeeded &= SUCCEEDED(hr);
 
   hr = _AtlModule.DllUnregisterServer(FALSE);
-  LOGFN(INFO) << "_AtlModule.DllUnregisterServer hr=" << putHR(hr);
+  LOGFN(VERBOSE) << "_AtlModule.DllUnregisterServer hr=" << putHR(hr);
   all_succeeded &= SUCCEEDED(hr);
 
   return all_succeeded ? S_OK : E_FAIL;
@@ -155,13 +155,13 @@ void CALLBACK PerformPostSigninActionsW(HWND /*hwnd*/,
                                         HINSTANCE /*hinst*/,
                                         wchar_t* /*pszCmdLine*/,
                                         int /*show*/) {
-  LOGFN(INFO);
+  LOGFN(VERBOSE);
 
   _AtlModule.InitializeCrashReporting();
 
   HANDLE hStdin = ::GetStdHandle(STD_INPUT_HANDLE);  // No need to close.
   if (hStdin == INVALID_HANDLE_VALUE) {
-    LOGFN(INFO) << "No stdin";
+    LOGFN(VERBOSE) << "No stdin";
     return;
   }
 
@@ -218,7 +218,7 @@ void CALLBACK PerformPostSigninActionsW(HWND /*hwnd*/,
 
   credential_provider::SecurelyClearDictionaryValue(&properties);
 
-  LOGFN(INFO) << "Done";
+  LOGFN(VERBOSE) << "Done";
 }
 
 void CALLBACK RunAsCrashpadHandlerW(HWND /*hwnd*/,

chrome/credential_provider/gaiacp/event_logs_upload_manager.cc

@@ -399,7 +399,7 @@ GURL EventLogsUploadManager::GetGcpwServiceUploadEventViewerLogsUrl() {
 
 HRESULT EventLogsUploadManager::UploadEventViewerLogs(
     const std::string& access_token) {
-  LOGFN(INFO);
+  LOGFN(VERBOSE);
 
   DWORD log_upload_level = GetGlobalFlagOrDefault(kEventLogUploadLevelRegKey,
                                                   kDefaultUploadLogLevel);
@@ -465,8 +465,8 @@ HRESULT EventLogsUploadManager::UploadEventViewerLogs(
     ++num_upload_requests_made;
   }
 
-  LOGFN(INFO) << num_event_logs_uploaded_ << " events uploaded with "
-              << num_upload_requests_made << " requests.";
+  LOGFN(VERBOSE) << num_event_logs_uploaded_ << " events uploaded with "
+                 << num_upload_requests_made << " requests.";
   upload_status_ = S_OK;
   return upload_status_;
 }

chrome/credential_provider/gaiacp/gaia_credential.cc

@@ -22,12 +22,12 @@ CGaiaCredential::CGaiaCredential() = default;
 CGaiaCredential::~CGaiaCredential() = default;
 
 HRESULT CGaiaCredential::FinalConstruct() {
-  LOGFN(INFO);
+  LOGFN(VERBOSE);
   return S_OK;
 }
 
 void CGaiaCredential::FinalRelease() {
-  LOGFN(INFO);
+  LOGFN(VERBOSE);
 }
 
 HRESULT CGaiaCredential::GetUserGlsCommandline(

chrome/credential_provider/gaiacp/gaia_credential_other_user.cc

@@ -13,12 +13,12 @@ COtherUserGaiaCredential::COtherUserGaiaCredential() = default;
 COtherUserGaiaCredential::~COtherUserGaiaCredential() = default;
 
 HRESULT COtherUserGaiaCredential::FinalConstruct() {
-  LOGFN(INFO);
+  LOGFN(VERBOSE);
   return S_OK;
 }
 
 void COtherUserGaiaCredential::FinalRelease() {
-  LOGFN(INFO);
+  LOGFN(VERBOSE);
 }
 
 }  // namespace credential_provider

chrome/credential_provider/gaiacp/gaia_credential_provider.cc

@@ -92,8 +92,8 @@ HRESULT InitializeReauthCredential(
     if (FAILED(hr))
       LOGFN(ERROR) << "reauth->SetEmailForReauth hr=" << putHR(hr);
   } else {
-    LOGFN(INFO) << "reauth for sid " << sid
-                << " doesn't contain the email association";
+    LOGFN(VERBOSE) << "reauth for sid " << sid
+                   << " doesn't contain the email association";
   }
 
   return S_OK;
@@ -176,8 +176,8 @@ unsigned __stdcall BackgroundTokenHandleUpdater::PeriodicTokenHandleUpdate(
     bool user_access_changed =
         AssociatedUserValidator::Get()->IsAuthEnforcedOnAssociatedUsers();
     if (user_access_changed) {
-      LOGFN(INFO) << "A user token handle has been invalidated. Refreshing "
-                     "credentials";
+      LOGFN(VERBOSE) << "A user token handle has been invalidated. Refreshing "
+                        "credentials";
     }
 
     event_handler->UpdateCredentialsIfNeeded(user_access_changed);
@@ -287,13 +287,13 @@ CGaiaCredentialProvider::CGaiaCredentialProvider() {}
 CGaiaCredentialProvider::~CGaiaCredentialProvider() {}
 
 HRESULT CGaiaCredentialProvider::FinalConstruct() {
-  LOGFN(INFO);
+  LOGFN(VERBOSE);
   CleanupOlderVersions();
   return S_OK;
 }
 
 void CGaiaCredentialProvider::FinalRelease() {
-  LOGFN(INFO);
+  LOGFN(VERBOSE);
   CHECK(!token_handle_updater_);
   ClearTransient();
   // Unlock all the users that had their access locked due to invalid token
@@ -302,7 +302,7 @@ void CGaiaCredentialProvider::FinalRelease() {
 }
 
 HRESULT CGaiaCredentialProvider::DestroyCredentials() {
-  LOGFN(INFO);
+  LOGFN(VERBOSE);
   for (auto it = users_.begin(); it != users_.end(); ++it)
     (*it)->Terminate();
 
@@ -311,7 +311,7 @@ HRESULT CGaiaCredentialProvider::DestroyCredentials() {
 }
 
 void CGaiaCredentialProvider::ClearTransient() {
-  LOGFN(INFO);
+  LOGFN(VERBOSE);
   CHECK(!token_handle_updater_);
   // Reset event support.
   advise_context_ = 0;
@@ -380,7 +380,7 @@ HRESULT CGaiaCredentialProvider::CreateReauthCredentials(
     return hr;
   }
 
-  LOGFN(INFO) << "count=" << count;
+  LOGFN(VERBOSE) << "count=" << count;
 
   std::vector<base::string16> reauth_cred_sids;
   for (DWORD i = 0; i < count; ++i) {
@@ -468,7 +468,7 @@ HRESULT CGaiaCredentialProvider::CreateReauthCredentials(
     // credential created.
     reauth_cred_sids.push_back(sid);
 
-    LOGFN(INFO) << "Reauth SID : " << sid;
+    LOGFN(VERBOSE) << "Reauth SID : " << sid;
   }
 
   // Deny sign in access for users that have a reauth credential added to them.
@@ -509,7 +509,7 @@ void CGaiaCredentialProvider::AddCredentialAndCheckAutoLogon(
 
 void CGaiaCredentialProvider::RecreateCredentials(
     GaiaCredentialComPtrStorage* auto_logon_credential) {
-  LOGFN(INFO);
+  LOGFN(VERBOSE);
   DCHECK(user_array_);
 
   DestroyCredentials();
@@ -570,7 +570,7 @@ HRESULT CGaiaCredentialProvider::OnUserAuthenticatedImpl(
       events_->CredentialsChanged(advise_context_);
   }
 
-  LOGFN(INFO) << "Signing in authenticated sid=" << OLE2CW(sid);
+  LOGFN(VERBOSE) << "Signing in authenticated sid=" << OLE2CW(sid);
   return S_OK;
 }
 
@@ -632,7 +632,7 @@ HRESULT CGaiaCredentialProvider::OnUserAuthenticated(
 
 HRESULT CGaiaCredentialProvider::SetUserArray(
     ICredentialProviderUserArray* users) {
-  LOGFN(INFO);
+  LOGFN(VERBOSE);
   CHECK(!token_handle_updater_);
 
   if (!IsUsageScenarioSupported(cpus_))
@@ -661,7 +661,7 @@ HRESULT CGaiaCredentialProvider::SetUsageScenario(
   cpus_ = cpus;
   cpus_flags_ = flags;
 
-  LOGFN(INFO) << " cpu=" << cpus << " flags=" << std::setbase(16) << flags;
+  LOGFN(VERBOSE) << " cpu=" << cpus << " flags=" << std::setbase(16) << flags;
   return IsUsageScenarioSupported(cpus_) ? S_OK : E_NOTIMPL;
 }
 
@@ -814,8 +814,8 @@ HRESULT CGaiaCredentialProvider::GetCredentialCount(
     *autologin_with_default = *default_index != CREDENTIAL_PROVIDER_NO_DEFAULT;
   }
 
-  LOGFN(INFO) << " count=" << *count << " default=" << *default_index
-              << " auto=" << *autologin_with_default;
+  LOGFN(VERBOSE) << " count=" << *count << " default=" << *default_index
+                 << " auto=" << *autologin_with_default;
   return S_OK;
 }
 
@@ -832,7 +832,7 @@ HRESULT CGaiaCredentialProvider::GetCredentialAt(
   hr = users_[index]->QueryInterface(IID_ICredentialProviderCredential,
                                      (void**)ppcpc);
 
-  LOGFN(INFO) << "hr=" << putHR(hr) << " index=" << index;
+  LOGFN(VERBOSE) << "hr=" << putHR(hr) << " index=" << index;
   return hr;
 }
 

chrome/credential_provider/gaiacp/gaia_credential_provider_filter.cc

@@ -33,12 +33,12 @@ CGaiaCredentialProviderFilter::CGaiaCredentialProviderFilter() = default;
 CGaiaCredentialProviderFilter::~CGaiaCredentialProviderFilter() = default;
 
 HRESULT CGaiaCredentialProviderFilter::FinalConstruct() {
-  LOGFN(INFO);
+  LOGFN(VERBOSE);
   return S_OK;
 }
 
 void CGaiaCredentialProviderFilter::FinalRelease() {
-  LOGFN(INFO);
+  LOGFN(VERBOSE);
 }
 
 HRESULT CGaiaCredentialProviderFilter::Filter(

chrome/credential_provider/gaiacp/gaia_credential_provider_module.cc

@@ -99,7 +99,7 @@ void CGaiaCredentialProviderModule::InitializeCrashReporting() {
             crash_reporter::switches::kCrashpadHandler &&
         ::InterlockedCompareExchange(&crashpad_initialized_, 1, 0) == 0) {
       ConfigureGcpCrashReporting(*cmd_line);
-      LOGFN(INFO) << "Crash reporting was initialized.";
+      LOGFN(VERBOSE) << "Crash reporting was initialized.";
     }
   }
 }
@@ -125,14 +125,21 @@ BOOL CGaiaCredentialProviderModule::DllMain(HINSTANCE /*hinstance*/,
                            true,    // Enable timestamp.
                            false);  // Enable tickcount.
       logging::SetEventSource("GCPW", GCPW_CATEGORY, MSG_LOG_MESSAGE);
+      if (GetGlobalFlagOrDefault(kRegEnableVerboseLogging, 0))
+        logging::SetMinLogLevel(logging::LOG_VERBOSE);
 
-      LOGFN(INFO) << "DllMain(DLL_PROCESS_ATTACH) Build: "
+      wchar_t process_name[MAX_PATH] = {0};
+      GetModuleFileName(nullptr, process_name, MAX_PATH);
+
+      LOGFN(INFO) << "GCPW Initialized in " << process_name
+                  << " GCPW Version: " << (CHROME_VERSION_STRING)
+                  << " Windows Build: "
                   << base::win::OSInfo::GetInstance()->Kernel32BaseVersion()
                   << " Version:" << GetWindowsVersion();
       break;
     }
     case DLL_PROCESS_DETACH:
-      LOGFN(INFO) << "DllMain(DLL_PROCESS_DETACH)";
+      LOGFN(VERBOSE) << "DllMain(DLL_PROCESS_DETACH)";
 
       // When this DLL is loaded for testing, don't reset the command line
       // since it causes tests to crash.

chrome/credential_provider/gaiacp/gcp_crash_reporting.cc

@@ -65,7 +65,7 @@ void ConfigureGcpCrashReporting(const base::CommandLine& command_line) {
   HRESULT hr = GetCommandLineForEntrypoint(
       CURRENT_MODULE(), kRunAsCrashpadHandlerEntryPoint, &dll_main_cmd_line);
   if (hr == S_FALSE) {
-    LOGFN(INFO) << "Failed to get command line to run crashpad handler";
+    LOGFN(WARNING) << "Failed to get command line to run crashpad handler";
     return;
   }
   if (FAILED(hr)) {

chrome/credential_provider/gaiacp/gcp_utils.cc

@@ -305,7 +305,7 @@ HRESULT WaitForProcess(base::win::ScopedHandle::Handle process_handle,
                        DWORD* exit_code,
                        char* output_buffer,
                        int buffer_size) {
-  LOGFN(INFO);
+  LOGFN(VERBOSE);
   DCHECK(exit_code);
   DCHECK_GT(buffer_size, 0);
 
@@ -324,24 +324,24 @@ HRESULT WaitForProcess(base::win::ScopedHandle::Handle process_handle,
     switch (ret) {
       case WAIT_OBJECT_0: {
         int index = ret - WAIT_OBJECT_0;
-        LOGFN(INFO) << "WAIT_OBJECT_" << index;
+        LOGFN(VERBOSE) << "WAIT_OBJECT_" << index;
         if (!::ReadFile(output_handle, buffer, length, &length, nullptr)) {
           hr = HRESULT_FROM_WIN32(::GetLastError());
           if (hr != HRESULT_FROM_WIN32(ERROR_BROKEN_PIPE))
             LOGFN(ERROR) << "ReadFile(" << index << ") hr=" << putHR(hr);
         } else {
-          LOGFN(INFO) << "ReadFile(" << index << ") length=" << length;
+          LOGFN(VERBOSE) << "ReadFile(" << index << ") length=" << length;
           buffer[length] = 0;
         }
         break;
       }
       case WAIT_IO_COMPLETION:
         // This is normal.  Just ignore.
-        LOGFN(INFO) << "WaitForMultipleObjectsEx WAIT_IO_COMPLETION";
+        LOGFN(VERBOSE) << "WaitForMultipleObjectsEx WAIT_IO_COMPLETION";
         break;
       case WAIT_TIMEOUT: {
         // User took too long to log in, so kill UI process.
-        LOGFN(INFO) << "WaitForMultipleObjectsEx WAIT_TIMEOUT, killing UI";
+        LOGFN(VERBOSE) << "WaitForMultipleObjectsEx WAIT_TIMEOUT, killing UI";
         ::TerminateProcess(process_handle, kUiecTimeout);
         is_done = true;
         break;
@@ -358,7 +358,7 @@ HRESULT WaitForProcess(base::win::ScopedHandle::Handle process_handle,
     // Copy the read buffer to the output buffer. If the pipe was broken,
     // we can break our loop and wait for the process to die.
     if (hr == HRESULT_FROM_WIN32(ERROR_BROKEN_PIPE)) {
-      LOGFN(INFO) << "Stop waiting for output buffer";
+      LOGFN(VERBOSE) << "Stop waiting for output buffer";
       break;
     } else {
       strcat_s(output_buffer, buffer_size, buffer);
@@ -371,13 +371,13 @@ HRESULT WaitForProcess(base::win::ScopedHandle::Handle process_handle,
   DWORD ret = ::WaitForSingleObject(process_handle, 10000);
   if (ret == 0) {
     if (::GetExitCodeProcess(process_handle, exit_code)) {
-      LOGFN(INFO) << "Process terminated with exit code " << *exit_code;
+      LOGFN(VERBOSE) << "Process terminated with exit code " << *exit_code;
     } else {
-      LOGFN(INFO) << "Process terminated without exit code";
+      LOGFN(WARNING) << "Process terminated without exit code";
       *exit_code = kUiecAbort;
     }
   } else {
-    LOGFN(INFO) << "UI did not terminiate within 10 seconds, killing now";
+    LOGFN(WARNING) << "UI did not terminiate within 10 seconds, killing now";
     ::TerminateProcess(process_handle, kUiecKilled);
     *exit_code = kUiecKilled;
   }
@@ -418,7 +418,7 @@ HRESULT CreateLogonToken(const wchar_t* domain,
 }
 
 HRESULT CreateJobForSignin(base::win::ScopedHandle* job) {
-  LOGFN(INFO);
+  LOGFN(VERBOSE);
   DCHECK(job);
 
   job->Set(::CreateJobObject(nullptr, nullptr));
@@ -498,7 +498,7 @@ HRESULT InitializeStdHandles(CommDirection direction,
                              StdHandlesToCreate to_create,
                              ScopedStartupInfo* startupinfo,
                              StdParentHandles* parent_handles) {
-  LOGFN(INFO);
+  LOGFN(VERBOSE);
   DCHECK(startupinfo);
   DCHECK(parent_handles);
 
@@ -713,8 +713,15 @@ bool VerifyStartupSentinel() {
     // Keep writing to the sentinel file until we have reached
     // |kMaxConsecutiveCrashCount| at which point it is assumed that GCPW
     // is crashing continuously and should be disabled.
-    if (!startup_sentinel.IsValid() ||
-        startup_sentinel.GetLength() >= kMaxConsecutiveCrashCount) {
+    if (!startup_sentinel.IsValid()) {
+      LOGFN(ERROR) << "Could not open the sentinel path "
+                   << startup_sentinel_path.value();
+      return false;
+    }
+
+    if (startup_sentinel.GetLength() >= kMaxConsecutiveCrashCount) {
+      LOGFN(ERROR) << "Sentinel file length indicates "
+                   << startup_sentinel.GetLength() << " possible crashes";
       return false;
     }
 

chrome/credential_provider/gaiacp/logging.h

@@ -22,10 +22,23 @@ class putHR {
   HRESULT hr_;
 };
 
+// COMPACT_GOOGLE_LOG_EX_VERBOSE is defined only for GCPW as INFO event log
+// category.
+#ifdef COMPACT_GOOGLE_LOG_EX_VERBOSE
+#undef COMPACT_GOOGLE_LOG_EX_VERBOSE
+#endif
+
+#define COMPACT_GOOGLE_LOG_EX_VERBOSE(ClassName, ...) \
+  ::logging::ClassName(__FILE__, __LINE__, ::logging::LOG_INFO, ##__VA_ARGS__)
+
+// A helper macro which checks if the message should be logged based on log
+// level.
+#define LOG_ENABLED(LEVEL) (::logging::LOG_##LEVEL >= logging::GetMinLogLevel())
+
 // A macro that puts the function name into the logging stream.  This is a
 // drop-in replacement for the LOG macro.
-
-#define LOGFN(LEVEL) SYSLOG(LEVEL) << __FUNCTION__ << ": "
+#define LOGFN(LEVEL) \
+  LAZY_STREAM((SYSLOG(LEVEL) << __FUNCTION__ << ": "), LOG_ENABLED(LEVEL))
 
 }  // namespace credential_provider
 

chrome/credential_provider/gaiacp/mdm_utils.cc

@@ -31,6 +31,7 @@
 
 namespace credential_provider {
 
+constexpr wchar_t kRegEnableVerboseLogging[] = L"enable_verbose_logging";
 constexpr wchar_t kRegInitializeCrashReporting[] = L"init_crash_reporting";
 constexpr wchar_t kRegMdmUrl[] = L"mdm";
 constexpr wchar_t kRegMdmEnableForcePasswordReset[] =
@@ -297,13 +298,13 @@ HRESULT RegisterWithGoogleDeviceManagement(const base::string16& mdm_url,
   hr = LookupLocalizedNameForWellKnownSid(WinBuiltinAdministratorsSid,
                                           &local_administrators_group_name);
   if (FAILED(hr)) {
-    LOGFN(INFO) << "Failed to fetch name for administrators group";
+    LOGFN(WARNING) << "Failed to fetch name for administrators group";
   }
 
   base::string16 builtin_administrator_name = L"";
   hr = GetLocalizedNameBuiltinAdministratorAccount(&builtin_administrator_name);
   if (FAILED(hr)) {
-    LOGFN(INFO) << "Failed to fetch name for builtin administrator account";
+    LOGFN(WARNING) << "Failed to fetch name for builtin administrator account";
   }
 
   // Build the json data needed by the server.
@@ -410,7 +411,7 @@ bool IsGemEnabled() {
 }
 
 HRESULT EnrollToGoogleMdmIfNeeded(const base::Value& properties) {
-  LOGFN(INFO);
+  LOGFN(VERBOSE);
 
   // Only enroll with MDM if configured.
   base::string16 mdm_url = GetMdmUrl();
@@ -420,7 +421,7 @@ HRESULT EnrollToGoogleMdmIfNeeded(const base::Value& properties) {
   // TODO(crbug.com/935577): Check if machine is already enrolled because
   // attempting to enroll when already enrolled causes a crash.
   if (IsEnrolledWithGoogleMdm(mdm_url)) {
-    LOGFN(INFO) << "Already enrolled to Google MDM";
+    LOGFN(VERBOSE) << "Already enrolled to Google MDM";
     return S_OK;
   }
 

chrome/credential_provider/gaiacp/mdm_utils.h

@@ -17,6 +17,9 @@ namespace credential_provider {
 
 // Mdm registry value key name.
 
+// Enables verbose logging in GCPW.
+extern const wchar_t kRegEnableVerboseLogging[];
+
 // Determines if crash reporting is initialized for credential provider DLL.
 extern const wchar_t kRegInitializeCrashReporting[];
 

chrome/credential_provider/gaiacp/os_process_manager.cc

@@ -51,7 +51,7 @@ namespace credential_provider {
 namespace {
 
 HRESULT GetTokenLogonSID(const base::win::ScopedHandle& token, PSID* sid) {
-  LOGFN(INFO);
+  LOGFN(VERBOSE);
   DCHECK(sid);
 
   // TODO: make more robust by asking for needed length first.
@@ -100,7 +100,7 @@ HRESULT AddAllowedACE(ACL* dacl,
                       DWORD access_mask,
                       PSID sid,
                       ACL** new_dacl) {
-  LOGFN(INFO);
+  LOGFN(VERBOSE);
   DCHECK(new_dacl);
 
   ACL_SIZE_INFORMATION si;
@@ -191,7 +191,7 @@ HRESULT AllowLogonSIDOnLocalBasedNamedObjects(PSID sid) {
     return hr;
   }
 
-  LOGFN(INFO) << "session=" << session_id;
+  LOGFN(VERBOSE) << "session=" << session_id;
 
   UNICODE_STRING name;
   wchar_t name_buffer[64];
@@ -259,7 +259,7 @@ HRESULT AllowLogonSIDOnLocalBasedNamedObjects(PSID sid) {
 }
 
 HRESULT AllowLogonSIDOnWinSta0(PSID sid) {
-  LOGFN(INFO);
+  LOGFN(VERBOSE);
 
   ScopedWindowStationHandle winsta0(
       ::OpenWindowStationW(L"WinSta0", FALSE, READ_CONTROL | WRITE_DAC));
@@ -320,7 +320,7 @@ HRESULT AllowLogonSIDOnWinSta0(PSID sid) {
 HDESK GetAndAllowLogonSIDOnDesktop(const wchar_t* desktop_name,
                                    PSID sid,
                                    DWORD desired_access) {
-  LOGFN(INFO);
+  LOGFN(VERBOSE);
 
   const DWORD kDesiredAccess =
       desired_access | READ_CONTROL | WRITE_DAC | DESKTOP_CREATEWINDOW;

chrome/credential_provider/gaiacp/os_user_manager.cc

@@ -288,7 +288,7 @@ HRESULT OSUserManager::AddUser(const wchar_t* username,
     wchar_t* sidstr = nullptr;
     if (::ConvertSidToStringSid(user_info->usri4_user_sid, &sidstr)) {
       *sid = SysAllocString(T2COLE(sidstr));
-      LOGFN(INFO) << "sid=" << sidstr;
+      LOGFN(VERBOSE) << "sid=" << sidstr;
       ::LocalFree(sidstr);
     } else {
       LOGFN(ERROR) << "Could not convert SID to string";

chrome/credential_provider/gaiacp/password_recovery_manager.cc

@@ -496,7 +496,7 @@ HRESULT PasswordRecoveryManager::StoreWindowsPasswordIfNeeded(
         return hr;
       }
 
-      LOGFN(INFO) << "Encrypted and stored secret for sid=" << sid;
+      LOGFN(VERBOSE) << "Encrypted and stored secret for sid=" << sid;
     } else {
       LOGFN(ERROR) << "base::JSONWriter::Write failed";
       return E_FAIL;
@@ -557,7 +557,7 @@ HRESULT PasswordRecoveryManager::RecoverWindowsPasswordIfPossible(
     *recovered_password = decrypted_password;
   SecurelyClearString(decrypted_password);
 
-  LOGFN(INFO) << "Decrypted the secret for sid=" << sid;
+  LOGFN(VERBOSE) << "Decrypted the secret for sid=" << sid;
 
   return hr;
 }

chrome/credential_provider/gaiacp/reauth_credential.cc

@@ -25,12 +25,12 @@ CReauthCredential::CReauthCredential() = default;
 CReauthCredential::~CReauthCredential() = default;
 
 HRESULT CReauthCredential::FinalConstruct() {
-  LOGFN(INFO);
+  LOGFN(VERBOSE);
   return S_OK;
 }
 
 void CReauthCredential::FinalRelease() {
-  LOGFN(INFO);
+  LOGFN(VERBOSE);
 }
 
 // CGaiaCredentialBase /////////////////////////////////////////////////////////
@@ -183,7 +183,7 @@ HRESULT CReauthCredential::GetStringValueImpl(DWORD field_id, wchar_t** value) {
 HRESULT CReauthCredential::GetUserSid(wchar_t** sid) {
   USES_CONVERSION;
   DCHECK(sid);
-  LOGFN(INFO) << "sid=" << OLE2CW(get_os_user_sid());
+  LOGFN(VERBOSE) << "sid=" << OLE2CW(get_os_user_sid());
 
   HRESULT hr = ::SHStrDupW(OLE2CW(get_os_user_sid()), sid);
   if (FAILED(hr))

chrome/credential_provider/gaiacp/scoped_user_profile.cc

@@ -339,7 +339,7 @@ HRESULT UpdateProfilePicturesForWindows8AndNewer(
     std::vector<char> response;
     HRESULT hr = fetcher->Fetch(&response);
     if (FAILED(hr)) {
-      LOGFN(INFO) << "fetcher.Fetch hr=" << putHR(hr);
+      LOGFN(ERROR) << "fetcher.Fetch hr=" << putHR(hr);
       continue;
     }
 
@@ -402,7 +402,7 @@ ScopedUserProfile::ScopedUserProfile(const base::string16& sid,
                                      const base::string16& domain,
                                      const base::string16& username,
                                      const base::string16& password) {
-  LOGFN(INFO);
+  LOGFN(VERBOSE);
   // Load the user's profile so that their regsitry hive is available.
   base::win::ScopedHandle::Handle handle;
 
@@ -467,7 +467,7 @@ HRESULT ScopedUserProfile::ExtractAssociationInformation(
   if (last_online_login_millis->empty()) {
     // This may return empty when there exists no successful login attempt.
     // Need not fail the call and instead fallback to returning S_OK.
-    LOGFN(INFO) << "LastSuccessfulOnlineLoginMillis is empty";
+    LOGFN(VERBOSE) << "LastSuccessfulOnlineLoginMillis is empty";
     *last_online_login_millis = L"0";
   }
 
@@ -513,7 +513,7 @@ HRESULT ScopedUserProfile::RegisterAssociation(
 }
 
 HRESULT ScopedUserProfile::SaveAccountInfo(const base::Value& properties) {
-  LOGFN(INFO);
+  LOGFN(VERBOSE);
 
   base::string16 sid;
   base::string16 id;
@@ -538,7 +538,7 @@ HRESULT ScopedUserProfile::SaveAccountInfo(const base::Value& properties) {
     wchar_t key_name[128];
     swprintf_s(key_name, base::size(key_name), L"%s\\%s\\%s", sid.c_str(),
                kRegHkcuAccountsPath, id.c_str());
-    LOGFN(INFO) << "HKU\\" << key_name;
+    LOGFN(VERBOSE) << "HKU\\" << key_name;
 
     base::win::RegKey key;
     LONG sts = key.Create(HKEY_USERS, key_name, KEY_READ | KEY_WRITE);
@@ -617,7 +617,7 @@ HRESULT ScopedUserProfile::SaveAccountInfo(const base::Value& properties) {
 ScopedUserProfile::ScopedUserProfile() {}
 
 bool ScopedUserProfile::WaitForProfileCreation(const base::string16& sid) {
-  LOGFN(INFO);
+  LOGFN(VERBOSE);
   wchar_t profile_dir[MAX_PATH];
   bool created = false;
 
@@ -625,17 +625,17 @@ bool ScopedUserProfile::WaitForProfileCreation(const base::string16& sid) {
     ::Sleep(1000);
     DWORD length = base::size(profile_dir);
     if (::GetUserProfileDirectoryW(token_.Get(), profile_dir, &length)) {
-      LOGFN(INFO) << "GetUserProfileDirectoryW " << i << " " << profile_dir;
+      LOGFN(VERBOSE) << "GetUserProfileDirectoryW " << i << " " << profile_dir;
       created = true;
       break;
     } else {
       HRESULT hr = HRESULT_FROM_WIN32(::GetLastError());
-      LOGFN(INFO) << "GetUserProfileDirectoryW hr=" << putHR(hr);
+      LOGFN(VERBOSE) << "GetUserProfileDirectoryW hr=" << putHR(hr);
     }
   }
 
   if (!created)
-    LOGFN(INFO) << "Profile not created yet???";
+    LOGFN(WARNING) << "Profile not created yet!";
 
   created = false;
 
@@ -646,13 +646,13 @@ bool ScopedUserProfile::WaitForProfileCreation(const base::string16& sid) {
   wchar_t key_name[128];
   swprintf_s(key_name, base::size(key_name), L"%s\\%s", sid.c_str(),
              kRegHkcuAccountsPath);
-  LOGFN(INFO) << "HKU\\" << key_name;
+  LOGFN(VERBOSE) << "HKU\\" << key_name;
 
   for (int i = 0; i < kWaitForProfileCreationRetryCount; ++i) {
     ::Sleep(1000);
     LONG sts = key.Create(HKEY_USERS, key_name, KEY_READ | KEY_WRITE);
     if (sts == ERROR_SUCCESS) {
-      LOGFN(INFO) << "Registry hive created " << i;
+      LOGFN(VERBOSE) << "Registry hive created " << i;
       created = true;
       break;
     }

chrome/credential_provider/gaiacp/win_http_url_fetcher.cc

@@ -176,7 +176,7 @@ std::unique_ptr<WinHttpUrlFetcher> WinHttpUrlFetcher::Create(const GURL& url) {
 
 WinHttpUrlFetcher::WinHttpUrlFetcher(const GURL& url)
     : url_(url), session_(nullptr), request_(nullptr) {
-  LOGFN(INFO) << "url=" << url.spec() << " (scheme and port ignored)";
+  LOGFN(VERBOSE) << "url=" << url.spec() << " (scheme and port ignored)";
 
   ScopedWinHttpHandle::Handle session = ::WinHttpOpen(
       L"GaiaCP/1.0 (Windows NT)", WINHTTP_ACCESS_TYPE_AUTOMATIC_PROXY,

chrome/credential_provider/setup/setup.cc

@@ -34,12 +34,16 @@
 #include "chrome/credential_provider/eventlog/gcp_eventlog_messages.h"
 #include "chrome/credential_provider/gaiacp/gcp_utils.h"
 #include "chrome/credential_provider/gaiacp/logging.h"
+#include "chrome/credential_provider/gaiacp/mdm_utils.h"
+#include "chrome/credential_provider/gaiacp/reg_utils.h"
 #include "chrome/credential_provider/setup/gcp_installer_crash_reporting.h"
 #include "chrome/credential_provider/setup/setup_lib.h"
 #include "components/crash/content/app/crash_switches.h"
 #include "components/crash/content/app/run_as_crashpad_handler_win.h"
 #include "content/public/common/content_switches.h"
 
+using credential_provider::GetGlobalFlagOrDefault;
+using credential_provider::kRegEnableVerboseLogging;
 using credential_provider::putHR;
 
 namespace {
@@ -91,6 +95,11 @@ int APIENTRY wWinMain(HINSTANCE hInstance,
                        true,    // Enable timestamp.
                        false);  // Enable tickcount.
 
+  logging::SetEventSource("GCPW", GCPW_CATEGORY, MSG_LOG_MESSAGE);
+
+  if (GetGlobalFlagOrDefault(kRegEnableVerboseLogging, 1))
+    logging::SetMinLogLevel(logging::LOG_VERBOSE);
+
   if (cmdline->HasSwitch(switches::kLoggingLevel)) {
     std::string log_level =
         cmdline->GetSwitchValueASCII(switches::kLoggingLevel);
@@ -103,8 +112,6 @@ int APIENTRY wWinMain(HINSTANCE hInstance,
     }
   }
 
-  logging::SetEventSource("GCPW", GCPW_CATEGORY, MSG_LOG_MESSAGE);
-
   // Make sure the process exits cleanly on unexpected errors.
   base::EnableTerminationOnHeapCorruption();
   base::EnableTerminationOnOutOfMemory();
@@ -184,8 +191,8 @@ int APIENTRY wWinMain(HINSTANCE hInstance,
           base::win::ScopedHandle parent_handle(
               base::win::Uint32ToHandle(parent_handle_value));
           DWORD ret = ::WaitForSingleObject(parent_handle.Get(), 5000);
-          LOGFN(INFO) << "Waited for parent(" << parent_handle.Get()
-                      << "): ret=" << ret;
+          LOGFN(VERBOSE) << "Waited for parent(" << parent_handle.Get()
+                         << "): ret=" << ret;
         }
       }
 

chrome/credential_provider/setup/setup_lib.cc

@@ -128,7 +128,7 @@ HRESULT RegisterDlls(const base::FilePath& dest_path,
 
     if (register_server_fn) {
       hr = static_cast<HRESULT>((*register_server_fn)());
-      LOGFN(INFO) << "Registered name=" << names[i] << " hr=" << putHR(hr);
+      LOGFN(VERBOSE) << "Registered name=" << names[i] << " hr=" << putHR(hr);
     } else {
       LOGFN(ERROR) << "Failed to register name=" << names[i];
       hr = E_NOTIMPL;
@@ -162,7 +162,7 @@ HRESULT UnregisterDlls(const base::FilePath& dest_path,
     FARPROC pfn = reinterpret_cast<FARPROC>(
         library.GetFunctionPointer("DllUnregisterServer"));
     HRESULT hr = pfn ? static_cast<HRESULT>((*pfn)()) : E_UNEXPECTED;
-    LOGFN(INFO) << "Unregistered name=" << names[i] << " hr=" << putHR(hr);
+    LOGFN(VERBOSE) << "Unregistered name=" << names[i] << " hr=" << putHR(hr);
     has_failures |= FAILED(hr);
   }
 
@@ -204,7 +204,7 @@ HRESULT DoInstall(const base::FilePath& installer_path,
     return HRESULT_FROM_WIN32(ERROR_FILE_NOT_FOUND);
 
   base::FilePath dest_path = gcp_path.Append(product_version);
-  LOGFN(INFO) << "Install to: " << dest_path;
+  LOGFN(VERBOSE) << "Install to: " << dest_path;
 
   // Make sure nothing under the destination directory is pending delete
   // after reboot, so that files installed now won't get deleted later.
@@ -310,8 +310,6 @@ HRESULT RelaunchUninstaller(const base::FilePath& installer_path) {
   }
   base::win::ScopedHandle this_process_handle(this_process_handle_handle);
 
-  LOGFN(INFO) << "This process handle: " << this_process_handle_handle;
-
   base::CommandLine cmdline(new_installer_path);
   cmdline.AppendSwitch(switches::kUninstall);
   cmdline.AppendSwitchPath(switches::kInstallPath, installer_path.DirName());
@@ -319,7 +317,7 @@ HRESULT RelaunchUninstaller(const base::FilePath& installer_path) {
                              base::NumberToString16(base::win::HandleToUint32(
                                  this_process_handle_handle)));
 
-  LOGFN(INFO) << "Cmd: " << cmdline.GetCommandLineString();
+  LOGFN(VERBOSE) << "Cmd: " << cmdline.GetCommandLineString();
 
   base::LaunchOptions options;
   options.handles_to_inherit.push_back(this_process_handle_handle);