MacPWAs: Add app shim and browser-side logging to debug app connection

We are getting reports of the browser process rejecting connections
from app shims from the field. The failures happen after Chrome has
been open for a while (so reproducing from the console to get logs is
not an option).

Address this in two ways.
1. Add more LOG(INFO) calls in the app shim process itself. This is
   needed (and is here to stay) because, if something goes wrong
   connecting to Chrome or loading the Chrome framework, there is no
   other mechanism for getting feedback (no crash reports, etc).
2. Add four NSLog calls in the browser, for
   - Mach connection received
   - Mojo connection received first message
   - Mojo connection disposition (use or discard), so 2 calls here
   - Mojo connection closed (regardless of disposition)
   These calls are NOT here to stay -- they are for debugging problems
   we are seeing in Chrome 80. They are likely to be moved to an
   internal URL.

Disabling presubmit because this is intentionally adding LOG(INFO)s.

NOPRESUBMIT=True

Bug: 1052131
Change-Id: Ia6fd1cb21802c97d8b9fed6146db48fdc3463e93
Reviewed-on: https://chromium-review.googlesource.com/c/chromium/src/+/2055994Reviewed-by: Robert Sesek <rsesek@chromium.org>
Commit-Queue: ccameron <ccameron@chromium.org>
Cr-Commit-Position: refs/heads/master@{#741747}

chrome/app_shim/app_mode_loader_mac.mm

@@ -73,6 +73,7 @@ int LoadFrameworkAndStart(int argc, char** argv) {
     base::FilePath app_data_dir = base::mac::NSStringToFilePath([app_bundle
         objectForInfoDictionaryKey:app_mode::kCrAppModeUserDataDirKey]);
     base::FilePath user_data_dir = app_data_dir.DirName().DirName().DirName();
+    LOG(INFO) << "Using user data dir " << user_data_dir.value();
     CHECK(!user_data_dir.empty());
 
     // If the version file does not exist, |cr_version_str| will be empty and
@@ -87,8 +88,12 @@ int LoadFrameworkAndStart(int argc, char** argv) {
     if (!cr_version_str.empty()) {
       NSArray* existing_chrome = [NSRunningApplication
           runningApplicationsWithBundleIdentifier:cr_bundle_id];
-      if ([existing_chrome count] == 0)
+      if ([existing_chrome count] == 0) {
+        LOG(INFO) << "Disregarding framework version from symlink";
         cr_version_str.clear();
+      } else {
+        LOG(INFO) << "Framework version from symlink " << cr_version_str;
+      }
     }
 
     // ** 3: Read information from the Chrome bundle.
@@ -126,6 +131,7 @@ int LoadFrameworkAndStart(int argc, char** argv) {
 
     // ** 5: Open the framework.
     StartFun ChromeAppModeStart = NULL;
+    LOG(INFO) << "Loading framework " << framework_dylib_path.value();
     void* cr_dylib = dlopen(framework_dylib_path.value().c_str(), RTLD_LAZY);
     if (cr_dylib) {
       // Find the entry point.

chrome/app_shim/app_shim_controller.mm

@@ -157,13 +157,15 @@ void AppShimController::FindOrLaunchChrome() {
   }
 
   // Otherwise, launch Chrome.
+  base::FilePath chrome_bundle_path = base::mac::OuterBundlePath();
+  LOG(INFO) << "Launching " << chrome_bundle_path.value();
   base::CommandLine command_line(base::CommandLine::NO_PROGRAM);
   command_line.AppendSwitch(switches::kSilentLaunch);
   command_line.AppendSwitchPath(switches::kUserDataDir, params_.user_data_dir);
-  chrome_launched_by_app_.reset(base::mac::OpenApplicationWithPath(
-                                    base::mac::OuterBundlePath(), command_line,
-                                    NSWorkspaceLaunchNewInstance),
-                                base::scoped_policy::RETAIN);
+  chrome_launched_by_app_.reset(
+      base::mac::OpenApplicationWithPath(chrome_bundle_path, command_line,
+                                         NSWorkspaceLaunchNewInstance),
+      base::scoped_policy::RETAIN);
   if (!chrome_launched_by_app_)
     LOG(FATAL) << "Failed to launch Chrome.";
 }
@@ -179,6 +181,7 @@ AppShimController::FindChromeFromSingletonLock(
   if (!ParseProcessSingletonLock(lock_symlink_path, &hostname, &pid)) {
     // This indicates that there is no Chrome process running (or that has been
     // running long enough to get the lock).
+    LOG(INFO) << "Singleton lock not found at " << lock_symlink_path.value();
     return base::scoped_nsobject<NSRunningApplication>();
   }
 
@@ -230,8 +233,8 @@ void AppShimController::PollForChromeReady(
 
   // Poll to see if the mojo channel is ready. Of note is that we don't actually
   // verify that |endpoint| is connected to |chrome_to_connect_to_|.
-  mojo::PlatformChannelEndpoint endpoint;
   {
+    mojo::PlatformChannelEndpoint endpoint;
     NSString* browser_bundle_id =
         base::mac::ObjCCast<NSString>([[NSBundle mainBundle]
             objectForInfoDictionaryKey:app_mode::kBrowserBundleIDKey]);
@@ -241,10 +244,11 @@ void AppShimController::PollForChromeReady(
         app_mode::kAppShimBootstrapNameFragment,
         base::MD5String(params_.user_data_dir.value()).c_str());
     endpoint = ConnectToBrowser(server_name);
-  }
-  if (endpoint.is_valid()) {
-    SendBootstrapOnShimConnected(std::move(endpoint));
-    return;
+    if (endpoint.is_valid()) {
+      LOG(INFO) << "Connected to " << server_name;
+      SendBootstrapOnShimConnected(std::move(endpoint));
+      return;
+    }
   }
 
   // Otherwise, try again after a brief delay.
@@ -327,6 +331,7 @@ void AppShimController::SendBootstrapOnShimConnected(
       std::move(host_receiver_), std::move(app_shim_info),
       base::BindOnce(&AppShimController::OnShimConnectedResponse,
                      base::Unretained(this)));
+  LOG(INFO) << "Sent OnShimConnected";
 }
 
 void AppShimController::SetUpMenu() {
@@ -343,7 +348,7 @@ void AppShimController::BootstrapChannelError(uint32_t custom_reason,
   // OnShimConnected is received.
   if (init_state_ == InitState::kHasReceivedOnShimConnectedResponse)
     return;
-  LOG(ERROR) << "Channel error custom_reason:" << custom_reason
+  LOG(ERROR) << "Bootstrap Channel error custom_reason:" << custom_reason
              << " description: " << description;
   [NSApp terminate:nil];
 }
@@ -358,6 +363,7 @@ void AppShimController::ChannelError(uint32_t custom_reason,
 void AppShimController::OnShimConnectedResponse(
     chrome::mojom::AppShimLaunchResult result,
     mojo::PendingReceiver<chrome::mojom::AppShim> app_shim_receiver) {
+  LOG(INFO) << "Received OnShimConnected.";
   DCHECK_EQ(init_state_, InitState::kHasSentOnShimConnected);
   init_state_ = InitState::kHasReceivedOnShimConnectedResponse;
 

chrome/browser/apps/app_shim/app_shim_host_bootstrap_mac.cc

@@ -4,18 +4,42 @@
 
 #include "chrome/browser/apps/app_shim/app_shim_host_bootstrap_mac.h"
 
+#include <CoreFoundation/CoreFoundation.h>
 #include <memory>
 #include <utility>
 
 #include "base/bind.h"
 #include "base/feature_list.h"
+#include "base/mac/scoped_cftyperef.h"
+#include "base/strings/stringprintf.h"
+#include "base/strings/sys_string_conversions.h"
 #include "chrome/common/chrome_features.h"
 #include "mojo/public/cpp/bindings/pending_receiver.h"
 #include "mojo/public/cpp/bindings/remote.h"
 #include "mojo/public/cpp/system/message_pipe.h"
 
+// NSLog is in Foundation, which cannot be #included in this translation
+// unit without renaming it to .mm. Because the logging is temporary, just
+// forward-declare it.
+extern "C" {
+void NSLogv(CFStringRef, va_list);
+}  // extern C
+
 namespace {
 AppShimHostBootstrap::Client* g_client = nullptr;
+
+// TODO(https://crbug.com/1052131): Remove NSLog logging, and move to an
+// internal debugging URL.
+void LogToNSLog(std::string format, ...) {
+  base::ScopedCFTypeRef<CFStringRef> cf_format(
+      base::SysUTF8ToCFStringRef(format));
+
+  va_list arguments;
+  va_start(arguments, format);
+  NSLogv(cf_format.get(), arguments);
+  va_end(arguments);
+}
+
 }  // namespace
 
 // static
@@ -39,6 +63,7 @@ AppShimHostBootstrap::AppShimHostBootstrap(base::ProcessId peer_pid)
 
 AppShimHostBootstrap::~AppShimHostBootstrap() {
   DCHECK(!shim_connected_callback_);
+  LogToNSLog("AppShim: Closing pid %d", pid_);
 }
 
 void AppShimHostBootstrap::ServeChannel(
@@ -101,6 +126,7 @@ void AppShimHostBootstrap::OnShimConnected(
     mojo::PendingReceiver<chrome::mojom::AppShimHost> app_shim_host_receiver,
     chrome::mojom::AppShimInfoPtr app_shim_info,
     OnShimConnectedCallback callback) {
+  LogToNSLog("AppShim: Received OnShimConnected from pid %d", pid_);
   DCHECK_CALLED_ON_VALID_THREAD(thread_checker_);
   DCHECK(!app_shim_info_);
   // Only one app launch message per channel.
@@ -126,6 +152,7 @@ void AppShimHostBootstrap::OnShimConnected(
 
 void AppShimHostBootstrap::OnConnectedToHost(
     mojo::PendingReceiver<chrome::mojom::AppShim> app_shim_receiver) {
+  LogToNSLog("AppShim: Performing OnConnectedToHost for pid %d", pid_);
   std::move(shim_connected_callback_)
       .Run(chrome::mojom::AppShimLaunchResult::kSuccess,
            std::move(app_shim_receiver));
@@ -133,6 +160,9 @@ void AppShimHostBootstrap::OnConnectedToHost(
 
 void AppShimHostBootstrap::OnFailedToConnectToHost(
     chrome::mojom::AppShimLaunchResult result) {
+  LogToNSLog("AppShim: Performing OnFailedToConnectToHost result %d for pid %d",
+             result, pid_);
+
   // Because there will be users of the AppShim interface in failure, just
   // return a dummy receiver.
   mojo::Remote<chrome::mojom::AppShim> dummy_remote;

chrome/browser/apps/app_shim/app_shim_listener.mm

@@ -4,6 +4,7 @@
 
 #include "chrome/browser/apps/app_shim/app_shim_listener.h"
 
+#import <Foundation/Foundation.h>
 #include <unistd.h>
 
 #include "base/bind.h"
@@ -95,6 +96,9 @@ void AppShimListener::InitOnBackgroundThread() {
 
 void AppShimListener::OnClientConnected(mojo::PlatformChannelEndpoint endpoint,
                                         base::ProcessId peer_pid) {
+  // TODO(https://crbug.com/1052131): Remove NSLog logging, and move to an
+  // internal debugging URL.
+  NSLog(@"AppShim: Connection received from pid %d", peer_pid);
   base::CreateSingleThreadTaskRunner({content::BrowserThread::UI})
       ->PostTask(
           FROM_HERE,

chrome/browser/apps/app_shim/extension_app_shim_handler_mac.cc

@@ -4,6 +4,7 @@
 
 #include "chrome/browser/apps/app_shim/extension_app_shim_handler_mac.h"
 
+#include <CoreFoundation/CoreFoundation.h>
 #include <Security/Security.h>
 
 #include <algorithm>