cros-disks: Improve log messages
BUG=chromium:1158662
TEST=cros_workon_make cros-disks --test
Change-Id: I0e4ec7766bf974703c16a3b99329407bca47e33f
Reviewed-on: https://chromium-review.googlesource.com/c/chromiumos/platform2/+/3577766
Reviewed-by: Marcello Salomao <msalomao@google.com>
Commit-Queue: François Degros <fdegros@chromium.org>
Tested-by: François Degros <fdegros@chromium.org>
diff --git a/cros-disks/fuse_mounter.cc b/cros-disks/fuse_mounter.cc
index c0cd19b..68659a3 100644
--- a/cros-disks/fuse_mounter.cc
+++ b/cros-disks/fuse_mounter.cc
@@ -64,15 +64,15 @@
const siginfo_t& info) {
CHECK_EQ(SIGCHLD, info.si_signo);
if (info.si_code != CLD_EXITED) {
- LOG(WARNING) << "FUSE daemon for " << redact(mount_path)
- << " crashed with code " << info.si_code << " and status "
- << info.si_status;
+ LOG(ERROR) << "The 'init' process holding the FUSE daemon for "
+ << redact(mount_path) << " was killed by signal "
+ << info.si_status << ": " << strsignal(info.si_status);
} else if (info.si_status != 0) {
- LOG(WARNING) << "FUSE daemon for " << redact(mount_path)
- << " exited with status " << info.si_status;
+ LOG(ERROR) << "FUSE daemon for " << redact(mount_path)
+ << " finished with exit code " << info.si_status;
} else {
LOG(INFO) << "FUSE daemon for " << quote(mount_path)
- << " exited normally";
+ << " finished normally";
}
// If the MountPoint instance has been deleted, it was already unmounted and
@@ -344,8 +344,8 @@
return nullptr;
}
- LOG(INFO) << "Started FUSE daemon for " << quote(target_path)
- << " as PID namespace " << pid;
+ LOG(INFO) << "FUSE daemon for " << quote(target_path)
+ << " is running in PID namespace " << pid;
// At this point, the FUSE daemon has successfully started.
std::unique_ptr<FUSEMountPoint> mount_point =
@@ -380,23 +380,11 @@
mount_process->PreserveFile(fuse_file.GetPlatformFile());
std::vector<std::string> output;
- const int return_code = mount_process->Run(&output);
- *error = InterpretReturnCode(return_code);
+ const int exit_code = mount_process->Run(&output);
+ *error = InterpretReturnCode(exit_code);
- if (*error != MOUNT_ERROR_NONE) {
- const std::string& executable = mount_process->arguments()[0];
- if (!output.empty()) {
- LOG(ERROR) << "FUSE mounter " << quote(executable) << " outputted "
- << output.size() << " lines:";
- for (const std::string& line : output) {
- LOG(ERROR) << line;
- }
- }
-
- LOG(ERROR) << "FUSE mounter " << quote(executable)
- << " returned error code " << return_code;
+ if (*error != MOUNT_ERROR_NONE)
return Process::kInvalidProcessId;
- }
return mount_process->pid();
}
diff --git a/cros-disks/process.cc b/cros-disks/process.cc
index f37ddc4..ecc7d55 100644
--- a/cros-disks/process.cc
+++ b/cros-disks/process.cc
@@ -14,6 +14,7 @@
#include <base/check.h>
#include <base/check_op.h>
+#include <base/files/file_path.h>
#include <base/files/file_util.h>
#include <base/logging.h>
#include <base/posix/eintr_wrapper.h>
@@ -32,24 +33,30 @@
// Reads chunks of data from a pipe and splits the read data into lines.
class PipeReader {
public:
- PipeReader(base::ScopedFD fd, std::vector<std::string>* output)
- : fd_(std::move(fd)), output_(output) {
+ PipeReader(base::ScopedFD fd,
+ std::string program_name,
+ std::vector<std::string>* output)
+ : fd_(std::move(fd)),
+ program_name_(std::move(program_name)),
+ output_(output) {
PCHECK(base::SetNonBlocking(fd_.get()));
+ VLOG(1) << "Collecting output of program " << quote(program_name_) << "...";
}
~PipeReader() {
if (!remaining_.empty()) {
- LOG(INFO) << "Got line: " << quote(remaining_);
+ LOG(INFO) << program_name_ << ": " << remaining_;
output_->push_back(remaining_);
}
+
+ VLOG(1) << "Finished collecting output of program " << quote(program_name_);
}
void Append(std::string_view data) {
- LOG(INFO) << ">> Processing: " << quote(data);
for (std::string_view::size_type i;
(i = data.find_first_of('\n')) != std::string_view::npos;) {
remaining_ += data.substr(0, i);
- LOG(INFO) << "Got line: " << quote(remaining_);
+ LOG(INFO) << program_name_ << ": " << remaining_;
output_->push_back(remaining_);
remaining_.clear();
@@ -77,9 +84,8 @@
switch (errno) {
case EAGAIN:
case EINTR:
- // It's Ok to try again later.
- PLOG(INFO) << "Nothing to read from file descriptor " << fd
- << " for the time being";
+ // Nothing for now, but it's Ok to try again later.
+ VPLOG(2) << "Nothing to read from file descriptor " << fd;
return true;
}
@@ -90,11 +96,12 @@
if (n == 0) {
// End of stream.
- LOG(INFO) << "End of stream from file descriptor " << fd;
+ VLOG(2) << "End of stream from file descriptor " << fd;
fd_.reset();
return false;
}
+ VLOG(2) << "Got " << n << " bytes from file descriptor " << fd;
DCHECK_GT(n, 0);
DCHECK_LE(n, PIPE_BUF);
Append(std::string_view(buffer, n));
@@ -126,8 +133,7 @@
if (ret == 0) {
// Nothing to do / timeout.
- LOG(INFO) << "Nothing to do with file descriptor " << fd
- << " for the time being";
+ VLOG(2) << "Nothing to read from file descriptor " << fd;
return true;
}
@@ -135,8 +141,16 @@
}
private:
+ // Read end of the pipe.
base::ScopedFD fd_;
+
+ // Program name. Used to prefix log traces.
+ const std::string program_name_;
+
+ // Collection of strings to append to.
std::vector<std::string>* const output_;
+
+ // Last partially collected line.
std::string remaining_;
};
@@ -197,6 +211,11 @@
arguments_array_.push_back(nullptr);
}
+std::string Process::GetProgramName() const {
+ DCHECK(!arguments_.empty());
+ return base::FilePath(arguments_.front()).BaseName().value();
+}
+
void Process::AddEnvironmentVariable(const base::StringPiece name,
const base::StringPiece value) {
DCHECK(environment_array_.empty());
@@ -238,7 +257,7 @@
CHECK_EQ(kInvalidProcessId, pid_);
CHECK(!finished());
CHECK(!arguments_.empty()) << "No arguments provided";
- LOG(INFO) << "Starting program " << quote(arguments_.front())
+ LOG(INFO) << "Starting program " << quote(GetProgramName())
<< " with arguments " << quote(arguments_);
LOG_IF(INFO, !environment_.empty())
<< "and extra environment " << quote(environment_);
@@ -283,24 +302,32 @@
Communicate(output, std::move(out_fd));
- const int result = Wait();
+ const int exit_code = Wait();
- LOG(INFO) << "Process finished with return code " << result;
- if (LOG_IS_ON(INFO) && !output->empty()) {
- LOG(INFO) << "Process outputted " << output->size() << " lines:";
- for (const std::string& line : *output) {
- LOG(INFO) << line;
+ if (exit_code != 0) {
+ const std::string program_name = GetProgramName();
+
+ if (!LOG_IS_ON(INFO)) {
+ for (const std::string& s : *output) {
+ LOG(ERROR) << program_name << ": " << s;
+ }
}
+
+ LOG(ERROR) << "Program " << quote(program_name)
+ << " finished with exit code " << exit_code;
+ } else {
+ LOG(INFO) << "Program " << quote(GetProgramName())
+ << " finished successfully";
}
- return result;
+ return exit_code;
}
void Process::Communicate(std::vector<std::string>* output,
base::ScopedFD out_fd) {
DCHECK(output);
- PipeReader reader(std::move(out_fd), output);
+ PipeReader reader(std::move(out_fd), GetProgramName(), output);
// Poll process and pipe. Read from pipe when possible.
while (!IsFinished() && reader.WaitAndRead())
diff --git a/cros-disks/process.h b/cros-disks/process.h
index 83534f2..14ea31c 100644
--- a/cros-disks/process.h
+++ b/cros-disks/process.h
@@ -99,6 +99,10 @@
virtual int WaitNonBlockingImpl() = 0;
private:
+ // Gets the name of the program (from the first argument passed to
+ // AddArgument()).
+ std::string GetProgramName() const;
+
// Starts the process. The started process has its stdin, stdout and stderr
// redirected to the given file descriptors. Returns true in case of success.
bool Start(base::ScopedFD in_fd, base::ScopedFD out_fd);
diff --git a/cros-disks/sandboxed_init.cc b/cros-disks/sandboxed_init.cc
index 3805cd0..11932e7 100644
--- a/cros-disks/sandboxed_init.cc
+++ b/cros-disks/sandboxed_init.cc
@@ -99,7 +99,7 @@
if (errno == ECHILD) {
// No more child. By then, we should have closed the control pipe.
DCHECK(!ctrl_fd_.is_valid());
- VLOG(1) << "The 'init' process is finishing with exit code "
+ VLOG(2) << "The 'init' process is finishing with exit code "
<< last_failure_code;
_exit(last_failure_code);
}
@@ -111,7 +111,7 @@
// Convert wait status to exit code.
const int exit_code = WaitStatusToExitCode(wstatus);
DCHECK_GE(exit_code, 0);
- VLOG(1) << "Child process " << pid
+ VLOG(2) << "Child process " << pid
<< " of the 'init' process finished with exit code " << exit_code;
if (exit_code > 0)
@@ -161,9 +161,10 @@
DCHECK(ctrl_fd);
DCHECK(ctrl_fd->is_valid());
+ const int fd = ctrl_fd->get();
int exit_code;
const ssize_t read_bytes =
- HANDLE_EINTR(read(ctrl_fd->get(), &exit_code, sizeof(exit_code)));
+ HANDLE_EINTR(read(fd, &exit_code, sizeof(exit_code)));
// If an error occurs while reading from the pipe, consider that the init
// process was killed before it could even write to the pipe.
@@ -172,23 +173,22 @@
if (read_bytes < 0) {
// Cannot read data from pipe.
if (errno == EAGAIN) {
- VLOG(1) << "No data is available from control pipe " << ctrl_fd->get()
- << " yet";
+ VLOG(2) << "Nothing to read from control pipe " << fd;
return -1;
}
- PLOG(ERROR) << "Cannot read from control pipe";
+ PLOG(ERROR) << "Cannot read from control pipe " << fd;
exit_code = error_code;
} else if (read_bytes < sizeof(exit_code)) {
// Cannot read enough data from pipe.
DCHECK_GE(read_bytes, 0);
LOG(ERROR) << "Short read of " << read_bytes << " bytes from control pipe "
- << ctrl_fd->get();
+ << fd;
exit_code = error_code;
} else {
DCHECK_EQ(read_bytes, sizeof(exit_code));
- VLOG(1) << "Received exit code " << exit_code << " from control pipe "
- << ctrl_fd->get();
+ VLOG(2) << "Received exit code " << exit_code << " from control pipe "
+ << fd;
DCHECK_GE(exit_code, 0);
DCHECK_LE(exit_code, 255);
}
