Log messages regarding why app banners aren't displayed to the console

chrome/browser/banners/app_banner_data_fetcher.cc

 // Copyright 2015 The Chromium Authors. All rights reserved.
 // Use of this source code is governed by a BSD-style license that can be
 // found in the LICENSE file.
 
 #include "chrome/browser/banners/app_banner_data_fetcher.h"
 
 #include "base/bind.h"
+#include "base/command_line.h"

[benwells, 2015/05/11 08:08:40]

I don't think this include is needed now.

[dominickn (DO NOT USE), 2015/05/12 07:41:31]

Done.

 #include "base/strings/string_util.h"
 #include "base/strings/utf_string_conversions.h"
+#include "chrome/browser/banners/app_banner_debug_log.h"
 #include "chrome/browser/banners/app_banner_metrics.h"
 #include "chrome/browser/banners/app_banner_settings_helper.h"
 #include "chrome/browser/bitmap_fetcher/bitmap_fetcher.h"
 #include "chrome/browser/browser_process.h"
 #include "chrome/browser/infobars/infobar_service.h"
 #include "chrome/browser/manifest/manifest_icon_selector.h"
 #include "chrome/browser/profiles/profile.h"
+#include "chrome/common/chrome_switches.h"

[benwells, 2015/05/11 08:08:40]

This too.

[dominickn (DO NOT USE), 2015/05/12 07:41:31]

Done.

 #include "chrome/common/render_messages.h"
 #include "components/infobars/core/infobar.h"
 #include "components/rappor/rappor_utils.h"
 #include "content/public/browser/browser_context.h"
 #include "content/public/browser/browser_thread.h"
 #include "content/public/browser/navigation_details.h"
 #include "content/public/browser/render_frame_host.h"
 #include "content/public/browser/service_worker_context.h"
 #include "content/public/browser/storage_partition.h"
 #include "net/base/load_flags.h"
@@ skipping 38 matching lines @@
 }
 
 AppBannerDataFetcher::AppBannerDataFetcher(
     content::WebContents* web_contents,
     base::WeakPtr<Delegate> delegate,
     int ideal_icon_size)
     : WebContentsObserver(web_contents),
       ideal_icon_size_(ideal_icon_size),
       weak_delegate_(delegate),
       is_active_(false),
+      log_err_(false),
       event_request_id_(-1) {
 }
 
 void AppBannerDataFetcher::Start(const GURL& validated_url) {
   DCHECK_CURRENTLY_ON(content::BrowserThread::UI);
 
   content::WebContents* web_contents = GetWebContents();
   DCHECK(web_contents);
 
   is_active_ = true;
@@ skipping 48 matching lines @@
   IPC_END_MESSAGE_MAP()
 
   return handled;
 }
 
 void AppBannerDataFetcher::OnBannerPromptReply(
     content::RenderFrameHost* render_frame_host,
     int request_id,
     blink::WebAppBannerPromptReply reply) {
   content::WebContents* web_contents = GetWebContents();
-  if (!is_active_ || !web_contents || request_id != event_request_id_) {
+  if (!CheckFetcherIsStillAlive(web_contents, "user navigated") ||
+      request_id != event_request_id_) {
     Cancel();
     return;
   }
 
   // The renderer might have requested the prompt to be canceled.
   if (reply == blink::WebAppBannerPromptReply::Cancel) {
+    // TODO(mlamouri,benwells): we should probably record that to behave

[benwells, 2015/05/11 08:08:40]

This TODO has been removed, it must have come back in your rebase.

[dominickn (DO NOT USE), 2015/05/12 07:41:31]

Done.

+    // differently with regard to showing the banner.
+    SendDebugMessage(web_contents,
+        "not shown: renderer has requested the banner prompt be cancelled");
     Cancel();
     return;
   }
 
   // Definitely going to show the banner now.
   FOR_EACH_OBSERVER(Observer, observer_list_,
                     OnDecidedWhetherToShow(this, true));
 
   infobars::InfoBar* infobar = CreateBanner(app_icon_.get(), app_title_);
   if (infobar) {
@@ skipping 64 matching lines @@
       GetCurrentTime());
   rappor::SampleDomainAndRegistryFromGURL(g_browser_process->rappor_service(),
                                           event_name,
                                           web_contents->GetURL());
   banners::TrackDisplayEvent(DISPLAY_EVENT_CREATED);
 }
 
 void AppBannerDataFetcher::OnDidGetManifest(
     const content::Manifest& manifest) {
   content::WebContents* web_contents = GetWebContents();
-  if (!is_active_ || !web_contents || manifest.IsEmpty()) {
+  if (!CheckFetcherIsStillAlive(web_contents, "manifest checking") ||
+      manifest.IsEmpty()) {
+    if (manifest.IsEmpty())

[benwells, 2015/05/11 08:08:40]

This is a little convoluted. It would probably be nicer to pull the manifest
emptiness check out into a new if clause.

[dominickn (DO NOT USE), 2015/05/12 07:41:31]

Done.

+      SendDebugMessage(web_contents, "not shown: manifest is empty");
     Cancel();
     return;
   }
 
   if (manifest.prefer_related_applications &&
       manifest.related_applications.size()) {
     for (const auto& application : manifest.related_applications) {
       std::string platform = base::UTF16ToUTF8(application.platform.string());
       std::string id = base::UTF16ToUTF8(application.id.string());
       if (weak_delegate_->HandleNonWebApp(platform, application.url, id))
         return;
     }
   }
 
-  if (!IsManifestValidForWebApp(manifest)) {
+  if (!IsManifestValidForWebApp(manifest, web_contents)) {
     Cancel();
     return;
   }
 
   banners::TrackDisplayEvent(DISPLAY_EVENT_BANNER_REQUESTED);
 
   web_app_data_ = manifest;
   app_title_ = web_app_data_.name.string();
 
   // Check to see if there is a single service worker controlling this page
   // and the manifest's start url.
   Profile* profile =
       Profile::FromBrowserContext(web_contents->GetBrowserContext());
   content::StoragePartition* storage_partition =
       content::BrowserContext::GetStoragePartition(
           profile, web_contents->GetSiteInstance());
   DCHECK(storage_partition);
 
   storage_partition->GetServiceWorkerContext()->CheckHasServiceWorker(
       validated_url_, manifest.start_url,
       base::Bind(&AppBannerDataFetcher::OnDidCheckHasServiceWorker,
                  this));
 }
 
 void AppBannerDataFetcher::OnDidCheckHasServiceWorker(
     bool has_service_worker) {
   content::WebContents* web_contents = GetWebContents();
-  if (!is_active_ || !web_contents) {
+  if (!CheckFetcherIsStillAlive(web_contents, "service worker checking")) {
     Cancel();
     return;
   }
 
   if (has_service_worker) {
     // Create an infobar to promote the manifest's app.
     GURL icon_url =
         ManifestIconSelector::FindBestMatchingIcon(
             web_app_data_.icons,
             ideal_icon_size_,
             gfx::Screen::GetScreenFor(web_contents->GetNativeView()));
     if (!icon_url.is_empty()) {
       FetchIcon(icon_url);
       return;
     }
+    SendDebugMessage(web_contents,
+                     "not shown: could not find icon specified in manifest");

[benwells, 2015/05/11 08:08:40]

I don't really understand how this could happen as I haven't looked at the
FindBestMatchingIcon code, but I'm guessing it shouldn't happen based on our
manifest checks.

Despite that, in its current form it sounds more like we couldn't download the
icon, so it should be rephrased as 'could not determine the best icon to use.'
or something.

[dominickn (DO NOT USE), 2015/05/12 07:41:30]

Done.

   } else {
     TrackDisplayEvent(DISPLAY_EVENT_LACKS_SERVICE_WORKER);
+    SendDebugMessage(web_contents,
+                     "not shown: no service worker detected. You may need to "
+                     "reload the page, or check that the manifest URL matches "
+                     "the page URL");

[benwells, 2015/05/11 08:08:40]

This error is great but could still be improved. The exact rules for how the
matching needs to work are kind of confusing. The matching is coded here:
https://code.google.com/p/chromium/codesearch#chromium/src/content/browser/se...

The rule is that the service worker that is registered for the current page
needs to also control the start URL from the manifest.

I think a message that captures this would be something like: 'no matching
service worker detected. You may need to reload the page, or check that the
service worker for the current page also controls the start URL from the
manifest.'

[dominickn (DO NOT USE), 2015/05/12 07:41:31]

Done.

[dominickn (DO NOT USE), 2015/05/12 07:41:31]

Done.

   }
 
   Cancel();
 }
 
 void AppBannerDataFetcher::OnFetchComplete(const GURL& url,
                                            const SkBitmap* icon) {
   if (is_active_)
     ShowBanner(icon);
 
   Release();
 }
 
 void AppBannerDataFetcher::ShowBanner(const SkBitmap* icon) {
   content::WebContents* web_contents = GetWebContents();
-  if (!is_active_ || !web_contents || !icon) {
+  if (!CheckFetcherIsStillAlive(web_contents, "banner display") || !icon) {
+    if (!icon)
+      SendDebugMessage(web_contents, "not shown: no icon available to display");

[benwells, 2015/05/11 08:08:40]

Ditto about separating into two ifs.

[dominickn (DO NOT USE), 2015/05/12 07:41:31]

Done.

     Cancel();
     return;
   }
 
   RecordCouldShowBanner();
   if (!CheckIfShouldShowBanner()) {
+    SendDebugMessage(web_contents, "not shown: engagement checks failed");

[benwells, 2015/05/11 08:08:40]

This one is tricky. The only way a message will get printed here is if the
banner has been added to the homescreen. As that might be confusing for
developers it would be good to be more specific about it, but I'd also add a
comment as it might not be obvious that this is the only case that can cause
debug output.

[dominickn (DO NOT USE), 2015/05/12 07:41:30]

Done.

     Cancel();
     return;
   }
 
+  SendDebugMessage(web_contents, "shown");

[benwells, 2015/05/11 08:08:40]

I don't think it is necessary to output this. This means the 'not shown' bit can
move into SendDebugMessage.

[dominickn (DO NOT USE), 2015/05/12 07:41:31]

Done.

   app_icon_.reset(new SkBitmap(*icon));
   event_request_id_ = ++gCurrentRequestID;
   web_contents->GetMainFrame()->Send(
       new ChromeViewMsg_AppBannerPromptRequest(
           web_contents->GetMainFrame()->GetRoutingID(),
           event_request_id_,
           GetBannerType()));
 }
 
 void AppBannerDataFetcher::RecordCouldShowBanner() {
   content::WebContents* web_contents = GetWebContents();
   DCHECK(web_contents);
 
   AppBannerSettingsHelper::RecordBannerEvent(
       web_contents, validated_url_, GetAppIdentifier(),
       AppBannerSettingsHelper::APP_BANNER_EVENT_COULD_SHOW,
       GetCurrentTime());
 }
 
 bool AppBannerDataFetcher::CheckIfShouldShowBanner() {
   content::WebContents* web_contents = GetWebContents();
   DCHECK(web_contents);
 
   return AppBannerSettingsHelper::ShouldShowBanner(
       web_contents, validated_url_, GetAppIdentifier(), GetCurrentTime());
 }
 
+bool AppBannerDataFetcher::CheckFetcherIsStillAlive(
+    content::WebContents* web_contents,
+    const std::string& section) {
+  if (!is_active_) {
+    SendDebugMessage(web_contents,
+                     "not shown: display pipeline halted before " + section);

[benwells, 2015/05/11 08:08:40]

This message is too detailed. Please update to something like 'the user
navigated before the banner could be shown.'. Also, the section is not needed.

[dominickn (DO NOT USE), 2015/05/12 07:41:30]

Done.

+    return false;
+  }
+  if (!web_contents)
+    return false;

[benwells, 2015/05/11 08:08:40]

For completeness a message here would be good, like 'web contents closed.'

[dominickn (DO NOT USE), 2015/05/12 07:41:31]

But if the web_contents pointer doesn't exist, we can't actually log a message
to the console, because that requires a valid web_contents pointer.

+  return true;
+}
+
 // static
 bool AppBannerDataFetcher::IsManifestValidForWebApp(
-    const content::Manifest& manifest) {
-  if (manifest.IsEmpty())
+    const content::Manifest& manifest,
+    content::WebContents* web_contents) {
+  if (manifest.IsEmpty()) {
+    SendDebugMessage(web_contents, "not shown: manifest is empty");
     return false;
-  if (!manifest.start_url.is_valid())
+  }
+  if (!manifest.start_url.is_valid()) {
+    SendDebugMessage(web_contents,
+                     "not shown: start URL in manifest is not valid");
     return false;
-  if (manifest.name.is_null() && manifest.short_name.is_null())
+  }
+  if (manifest.name.is_null() && manifest.short_name.is_null()) {
+    SendDebugMessage(web_contents,
+                     "not shown: manifest name and short name are missing");

[benwells, 2015/05/11 08:08:40]

It would be good to capture in the error that only one of them needs to be
present. Something like 'one of manifest name or short name need to be
specified.'

[dominickn (DO NOT USE), 2015/05/12 07:41:31]

Done.

     return false;
-  if (!DoesManifestContainRequiredIcon(manifest))
+  }
+  if (!DoesManifestContainRequiredIcon(manifest)) {
+    SendDebugMessage(web_contents,
+                     "not shown: manifest does not contain a suitable icon");

[benwells, 2015/05/11 08:08:40]

It would be good to capture more details about what a suitable icon is.

[dominickn (DO NOT USE), 2015/05/12 07:41:31]

Done.

     return false;
+  }
   return true;
 }
 
 }  // namespace banners