Reland "Implement wait-for-logs functionality in user_session binary"

This is a reland of 26c8b12c

BUG=751309

Original change's description:
> Implement wait-for-logs functionality in user_session binary
> 
> This ports the wait_for_logs method from the Python script, and forwards
> the pipe write fd to the Python script.
> 
> Change-Id: Ief54da136894cd13e0761b9755aa3c7d51fe17f8
> Reviewed-on: https://chromium-review.googlesource.com/594807
> Reviewed-by: Lambros Lambrou <lambroslambrou@chromium.org>
> Reviewed-by: Jamie Walch <jamiewalch@chromium.org>
> Commit-Queue: Erik Jensen <rkjnsn@chromium.org>
> Cr-Commit-Position: refs/heads/master@{#491058}

Change-Id: I9daf4957636a99b5179975cf1db33ba101bc179d
Reviewed-on: https://chromium-review.googlesource.com/597087
Commit-Queue: Erik Jensen <rkjnsn@chromium.org>
Reviewed-by: Lambros Lambrou <lambroslambrou@chromium.org>
Reviewed-by: Jamie Walch <jamiewalch@chromium.org>
Cr-Commit-Position: refs/heads/master@{#491179}

remoting/host/linux/linux_me2me_host.py

@@ -130,6 +130,11 @@ MAX_LAUNCH_FAILURES = SHORT_BACKOFF_THRESHOLD + 10
 # Number of seconds to save session output to the log.
 SESSION_OUTPUT_TIME_LIMIT_SECONDS = 30
 
+# This is the file descriptor used to pass messages to the user_session binary
+# during startup. It must be kept in sync with kMessageFd in
+# remoting_user_session.cc.
+USER_SESSION_MESSAGE_FD = 202
+
 # Globals needed by the atexit cleanup() handler.
 g_desktop = None
 g_host_hash = hashlib.md5(socket.gethostname()).hexdigest()
@@ -885,23 +890,46 @@ class ParentProcessLogger(object):
   daemon removes the log-handler and closes the pipe, causing the the parent
   process to reach end-of-file while reading the pipe and exit.
 
-  The (singleton) logger should be instantiated before forking. The parent
-  process should call wait_for_logs() before exiting. The (grand-)child process
-  should call start_logging() when it starts, and then use logging.* to issue
-  log statements, as usual. When the child has either succesfully started the
-  host or terminated, it must call release_parent() to allow the parent to exit.
+  When daemonizing, the (singleton) logger should be instantiated before
+  forking. The parent process should call wait_for_logs() before exiting. When
+  running via user-session, the file descriptor for the pipe to the parent
+  process should be passed to the constructor. In the latter case, wait_for_logs
+  may not be used.
+
+  In either case, the (grand-)child process should call start_logging() when it
+  starts, and then use logging.* to issue log statements, as usual. When the
+  child has either succesfully started the host or terminated, it must call
+  release_parent() to allow the parent to exit.
   """
 
   __instance = None
 
-  def __init__(self):
-    """Constructor. Must be called before forking."""
-    read_pipe, write_pipe = os.pipe()
+  def __init__(self, write_fd=None):
+    """Constructor. When daemonizing, must be called before forking.
+
+    Constructs the singleton instance of ParentProcessLogger. This should be
+    called at most once.
+
+    write_fd: If specified, the logger will use the file descriptor provided
+              for sending log messages instead of creating a new pipe. It is
+              assumed that this is the write end of a pipe created by an
+              already-existing parent process, such as user-session. If
+              write_fd is not a valid file descriptor, the constructor will
+              throw either IOError or OSError.
+    """
+    if write_fd is None:
+      read_pipe, write_pipe = os.pipe()
+    else:
+      read_pipe = None
+      write_pipe = write_fd
     # Ensure write_pipe is closed on exec, otherwise it will be kept open by
     # child processes (X, host), preventing the read pipe from EOF'ing.
     old_flags = fcntl.fcntl(write_pipe, fcntl.F_GETFD)
     fcntl.fcntl(write_pipe, fcntl.F_SETFD, old_flags | fcntl.FD_CLOEXEC)
-    self._read_file = os.fdopen(read_pipe, 'r')
+    if read_pipe is not None:
+      self._read_file = os.fdopen(read_pipe, 'r')
+    else:
+      self._read_file = None
     self._write_file = os.fdopen(write_pipe, 'w')
     self._logging_handler = None
     ParentProcessLogger.__instance = self
@@ -913,7 +941,8 @@ class ParentProcessLogger(object):
 
     Must be called by the child process.
     """
-    self._read_file.close()
+    if self._read_file is not None:
+      self._read_file.close()
     self._logging_handler = logging.StreamHandler(self._write_file)
     self._logging_handler.setFormatter(logging.Formatter(fmt='MSG:%(message)s'))
     logging.getLogger().addHandler(self._logging_handler)
@@ -1490,6 +1519,16 @@ Web Store: https://chrome.google.com/remotedesktop"""
   # requested to run in the foreground.
   if not options.foreground:
     daemonize()
+  else:
+    # Log to existing messaging pipe if it exists.
+    try:
+      ParentProcessLogger(USER_SESSION_MESSAGE_FD).start_logging()
+    except (IOError, OSError):
+      # One of these will be thrown if the file descriptor is invalid, such as
+      # if the script is not being run under the wrapper or the fd got closed by
+      # the login shell. In either case, just continue without sending log
+      # messages.
+      pass
 
   if host.host_id:
     logging.info("Using host_id: " + host.host_id)

remoting/host/linux/remoting_user_session.cc

@@ -20,8 +20,11 @@
 #include <grp.h>
 #include <limits.h>
 #include <pwd.h>
+#include <signal.h>
 #include <unistd.h>
 
+#include <security/pam_appl.h>
+
 #include <cerrno>
 #include <cstdio>
 #include <cstdlib>
@@ -35,8 +38,6 @@
 #include <utility>
 #include <vector>
 
-#include <security/pam_appl.h>
-
 #include "base/environment.h"
 #include "base/files/file_path.h"
 #include "base/files/file_util.h"
@@ -45,9 +46,16 @@
 #include "base/optional.h"
 #include "base/process/launch.h"
 #include "base/strings/string_piece.h"
+#include "base/strings/string_util.h"
 
 namespace {
 
+// This is the file descriptor used for the Python session script to pass us
+// messages during startup. It must be kept in sync with USER_SESSION_MESSAGE_FD
+// in linux_me2me_host.py. It should be high enough that login scripts are
+// unlikely to interfere with it, but is otherwise arbitrary.
+const int kMessageFd = 202;
+
 const char kPamName[] = "chrome-remote-desktop";
 const char kScriptName[] = "chrome-remote-desktop";
 const char kStartCommand[] = "start";
@@ -359,6 +367,8 @@ void ExecuteSession(std::string user,
     CHECK(pam_environment) << "Failed to get environment from PAM";
     ExecMe2MeScript(std::move(*pam_environment), pwinfo);  // Never returns
   } else {
+    // Close pipe write fd if it is open
+    close(kMessageFd);
     // waitpid will return if the child is ptraced, so loop until the process
     // actually exits.
     int status;
@@ -388,22 +398,29 @@ void ExecuteSession(std::string user,
   }
 }
 
+struct LogFile {
+  int fd;
+  std::string path;
+};
+
 // Opens a temp file for logging. Exits the program on failure.
-int OpenLogFile() {
+// Returns open file descriptor and path to log file.
+LogFile OpenLogFile() {
   char logfile[265];
   std::time_t time = std::time(nullptr);
   CHECK_NE(time, (std::time_t)(-1));
   // Safe because we're single threaded
   std::tm* localtime = std::localtime(&time);
   CHECK_NE(std::strftime(logfile, sizeof(logfile), kLogFileTemplate, localtime),
-           (std::size_t) 0);
+           static_cast<std::size_t>(0))
+      << "Failed to format log file name";
 
   mode_t mode = umask(0177);
   int fd = mkstemp(logfile);
-  PCHECK(fd != -1);
+  PCHECK(fd != -1) << "Failed to open log file";
   umask(mode);
 
-  return fd;
+  return {fd, logfile};
 }
 
 // Find the username for the current user. If either USER or LOGNAME is set to
@@ -433,56 +450,171 @@ std::string FindCurrentUsername() {
   return pwinfo->pw_name;
 }
 
-// Daemonizes the process. Output is redirected to a file. Exits the program on
-// failure.
+// Handle SIGINT and SIGTERM by printing a message and reraising the signal.
+// This handler expects to be registered with the SA_RESETHAND and SA_NODEFER
+// options to sigaction. (Don't register using signal.)
+void HandleInterrupt(int signal) {
+  static const char kInterruptedMessage[] =
+      "Interrupted. The daemon is still running in the background.\n";
+  // Use write since fputs isn't async-signal-handler safe.
+  ignore_result(write(STDERR_FILENO, kInterruptedMessage,
+                      arraysize(kInterruptedMessage) - 1));
+  raise(signal);
+}
+
+// Handle SIGALRM timeout
+void HandleAlarm(int) {
+  static const char kTimeoutMessage[] =
+      "Timeout waiting for session to start. It may have crashed, or may still "
+      "be running in the background.\n";
+  // Use write since fputs isn't async-signal-handler safe.
+  ignore_result(write(STDERR_FILENO, kTimeoutMessage,
+                      arraysize(kTimeoutMessage) - 1));
+  std::_Exit(EXIT_FAILURE);
+}
+
+// Relay messages from the host session and then exit.
+void WaitForMessagesAndExit(int read_fd, const std::string& log_name) {
+  // Use initializer-list syntax to avoid trailing null
+  static const base::StringPiece kMessagePrefix = "MSG:";
+  static const base::StringPiece kReady = "READY\n";
+
+  struct sigaction action = {};
+  sigemptyset(&action.sa_mask);
+  action.sa_flags = SA_RESETHAND | SA_NODEFER;
+
+  // If Ctrl-C is pressed or TERM is received, inform the user that the daemon
+  // is still running before exiting.
+  action.sa_handler = HandleInterrupt;
+  sigaction(SIGINT, &action, nullptr);
+  sigaction(SIGTERM, &action, nullptr);
+
+  // Install a fallback timeout to end the parent process, in case the daemon
+  // never responds (e.g. host crash-looping, daemon killed).
+  //
+  // The value of 120s is chosen to match the heartbeat retry timeout in
+  // hearbeat_sender.cc.
+  action.sa_handler = HandleAlarm;
+  sigaction(SIGALRM, &action, nullptr);
+  alarm(120);
+
+  std::FILE* stream = fdopen(read_fd, "r");
+  char* buffer = nullptr;
+  std::size_t buffer_size = 0;
+  ssize_t line_size;
+  bool message_received = false;
+  bool host_ready = false;
+  while ((line_size = getline(&buffer, &buffer_size, stream)) >= 0) {
+    message_received = true;
+    base::StringPiece line(buffer, line_size);
+    if (base::StartsWith(line, kMessagePrefix, base::CompareCase::SENSITIVE)) {
+      line.remove_prefix(kMessagePrefix.size());
+      std::fwrite(line.data(), sizeof(char), line.size(), stderr);
+    } else if (line == kReady) {
+      host_ready = true;
+    } else {
+      std::fputs("Unrecognized command: ", stderr);
+      std::fwrite(line.data(), sizeof(char), line.size(), stderr);
+    }
+  }
+
+  // If we're not at EOF, it means a read error occured and we don't know if the
+  // host is still running or not. Similarly, if we received an EOF before any
+  // messages were received, it probably means the user's log-in shell closed
+  // the pipe before execing the python script, so again we don't know the state
+  // of the host. This latter behavior has only been observed in csh and tcsh.
+  // All other shells tested allowed the python script to inherit the pipe file
+  // descriptor without trouble.
+  if (!std::feof(stream) || !message_received) {
+    LOG(WARNING) << "Failed to read from message pipe. Please check log to "
+                    "determine host status.\n";
+    // Assume host started so native messaging host allows flow to complete.
+    host_ready = true;
+  }
+
+  std::fprintf(stderr, "Log file: %s\n", log_name.c_str());
+
+  std::exit(host_ready ? EXIT_SUCCESS : EXIT_FAILURE);
+}
+
+// Daemonizes the process. Output is redirected to a log file. Exits the program
+// on failure. Only returns in the child process.
 //
-// This logic is mostly the same as daemonize() in linux_me2me_host.py. Log-
-// file redirection especially should be kept in sync. Note that this does
-// not currently wait for the host to start successfully before exiting the
-// parent process like the Python script does, as that functionality is
-// probably not useful at boot, where the wrapper is expected to be used. If
-// it turns out to be desired, it can be implemented by setting up a pipe and
-// passing a file descriptor to the Python script.
+// When executed by root (almost certainly via the init script), or if a pipe
+// cannot be created, the parent will immediately exit. When executed by a
+// user, the parent process will drop privileges and wait for the host to
+// start, relaying any start-up messages to stdout.
 void Daemonize() {
-  int log_fd = OpenLogFile();
+  LogFile log_file = OpenLogFile();
   int devnull_fd = open("/dev/null", O_RDONLY);
-  PCHECK(devnull_fd != -1);
+  PCHECK(devnull_fd != -1) << "Failed to open /dev/null";
 
-  PCHECK(dup2(devnull_fd, STDIN_FILENO) != -1);
-  PCHECK(dup2(log_fd, STDOUT_FILENO) != -1);
-  PCHECK(dup2(log_fd, STDERR_FILENO) != -1);
+  uid_t real_uid = getuid();
 
-  // Close all file descriptors except stdio, including any we may have
-  // inherited.
-  base::CloseSuperfluousFds(base::InjectiveMultimap());
+  // Set up message pipe
+  bool pipe_created = false;
+  int read_fd;
+  if (real_uid != 0) {
+    int pipe_fd[2];
+    int pipe_result = ::pipe(pipe_fd);
+    if (pipe_result != 0 || dup2(pipe_fd[1], kMessageFd) != kMessageFd) {
+      PLOG(WARNING) << "Failed to create message pipe. Please check log to "
+                       "determine host status.\n";
+    } else {
+      pipe_created = true;
+      read_fd = pipe_fd[0];
+      close(pipe_fd[1]);
+    }
+  }
 
   // Allow parent to exit, and ensure we're not a session leader so setsid can
   // succeed
   pid_t pid = fork();
-  PCHECK(pid != -1);
+  PCHECK(pid != -1) << "fork failed";
 
   if (pid != 0) {
-    std::exit(EXIT_SUCCESS);
+    if (!pipe_created) {
+      std::exit(EXIT_SUCCESS);
+    } else {
+      PCHECK(setuid(real_uid) == 0) << "setuid failed";
+      close(kMessageFd);
+      WaitForMessagesAndExit(read_fd, log_file.path);
+      CHECK(false);
+    }
   }
 
   // Start a new process group and session with no controlling terminal.
-  PCHECK(setsid() != -1);
+  PCHECK(setsid() != -1) << "setsid failed";
 
   // Fork again so we're no longer a session leader and can't get a controlling
   // terminal.
   pid = fork();
-  PCHECK(pid != -1);
+  PCHECK(pid != -1) << "fork failed";
 
   if (pid != 0) {
     std::exit(EXIT_SUCCESS);
   }
 
+  LOG(INFO) << "Daemon process started in the background, logging to '"
+            << log_file.path << "'";
+
   // We don't want to change to the target user's home directory until we've
   // dropped privileges, so change to / to make sure we're not keeping any other
   // directory in use.
-  PCHECK(chdir("/") == 0);
+  PCHECK(chdir("/") == 0) << "chdir / failed";
 
-  // Done!
+  PCHECK(dup2(devnull_fd, STDIN_FILENO) != -1) << "dup2 failed";
+  PCHECK(dup2(log_file.fd, STDOUT_FILENO) != -1) << "dup2 failed";
+  PCHECK(dup2(log_file.fd, STDERR_FILENO) != -1) << "dup2 failed";
+
+  // Close all file descriptors except stdio and kMessageFd, including any we
+  // may have inherited.
+  if (pipe_created) {
+    base::CloseSuperfluousFds(
+        {base::InjectionArc(kMessageFd, kMessageFd, false)});
+  } else {
+    base::CloseSuperfluousFds(base::InjectiveMultimap());
+  }
 }
 
 }  // namespace