fix flake in LogOutputStreamTest

LogOutputStreamTest.{WriteAbort,FlushAbort} are flaky because the logcat
is sometimes overloaded earlier than expected causing FlushAbort to fail
during Write() or either test to fail to write the abort message.

This change updates LogOutputStream to detect logcat overloads (EAGAIN)
and make one attempt at writing the abort message, even if the output
cap hasn't been reached.

This change also updates LogOutputStream's interface to defer log writes
to a Delegate. In tests, the Delegate implements a mock log and in
production, writes to Android's logcat.

I've removed VerifyGuards because LogOutputStream no longer writes
guards if Write() has never been called and the guards are tested in
other tests.

Change-Id: Icad83524aaf573c3e082469f1de095b6ca2c4839
Reviewed-on: https://chromium-review.googlesource.com/c/crashpad/crashpad/+/2439641
Reviewed-by: Mark Mentovai <mark@chromium.org>

handler/linux/crash_report_exception_handler.cc

@@ -18,6 +18,7 @@
 #include <utility>
 
 #include "base/logging.h"
+#include "build/build_config.h"
 #include "client/settings.h"
 #include "handler/linux/capture_snapshot.h"
 #include "minidump/minidump_file_writer.h"
@@ -35,15 +36,53 @@
 #include "util/stream/log_output_stream.h"
 #include "util/stream/zlib_output_stream.h"
 
-namespace crashpad {
+#if defined(OS_ANDROID)
+#include <android/log.h>
+#endif
 
+namespace crashpad {
 namespace {
 
+class Logger : public LogOutputStream::Delegate {
+ public:
+  Logger() = default;
+  ~Logger() = default;
+
+#if defined(OS_ANDROID)
+  int Log(const char* buf) override {
+    return __android_log_buf_write(
+        LOG_ID_CRASH, ANDROID_LOG_FATAL, "crashpad", buf);
+  }
+
+  size_t OutputCap() override {
+    // Most minidumps are expected to be compressed and encoded into less than
+    // 128k.
+    return 128 * 1024;
+  }
+
+  size_t LineWidth() override {
+    // From Android NDK r20 <android/log.h>, log message text may be truncated
+    // to less than an implementation-specific limit (1023 bytes), for sake of
+    // safe and being easy to read in logcat, choose 512.
+    return 512;
+  }
+#else
+  // TODO(jperaza): Log to an appropriate location on Linux.
+  int Log(const char* buf) override { return -ENOTCONN; }
+  size_t OutputCap() override { return 0; }
+  size_t LineWidth() override { return 0; }
+#endif
+
+ private:
+  DISALLOW_COPY_AND_ASSIGN(Logger);
+};
+
 bool WriteMinidumpLogFromFile(FileReaderInterface* file_reader) {
-  ZlibOutputStream stream(ZlibOutputStream::Mode::kCompress,
-                          std::make_unique<Base94OutputStream>(
-                              Base94OutputStream::Mode::kEncode,
-                              std::make_unique<LogOutputStream>()));
+  ZlibOutputStream stream(
+      ZlibOutputStream::Mode::kCompress,
+      std::make_unique<Base94OutputStream>(
+          Base94OutputStream::Mode::kEncode,
+          std::make_unique<LogOutputStream>(std::make_unique<Logger>())));
   FileOperationResult read_result;
   do {
     uint8_t buffer[4096];
@@ -259,7 +298,7 @@ bool CrashReportExceptionHandler::WriteMinidumpToLog(
       ZlibOutputStream::Mode::kCompress,
       std::make_unique<Base94OutputStream>(
           Base94OutputStream::Mode::kEncode,
-          std::make_unique<LogOutputStream>())));
+          std::make_unique<LogOutputStream>(std::make_unique<Logger>()))));
   if (!minidump.WriteMinidump(&writer, false /* allow_seek */)) {
     LOG(ERROR) << "WriteMinidump failed";
     return false;

util/stream/log_output_stream.cc

@@ -21,27 +21,14 @@
 #include "base/check.h"
 #include "base/logging.h"
 
-#if defined(OS_ANDROID)
-#include <android/log.h>
-#endif
-
 namespace crashpad {
 
-namespace {
-
-// Most minidumps are expected to be compressed and encoded into less than 128k.
-constexpr size_t kOutputCap = 128 * 1024;
-
-// From Android NDK r20 <android/log.h>, log message text may be truncated to
-// less than an implementation-specific limit (1023 bytes), for sake of safe
-// and being easy to read in logcat, choose 512.
-constexpr size_t kLineBufferSize = 512;
-
-}  // namespace
-
-LogOutputStream::LogOutputStream()
-    : output_count_(0), flush_needed_(false), flushed_(false) {
-  buffer_.reserve(kLineBufferSize);
+LogOutputStream::LogOutputStream(std::unique_ptr<Delegate> delegate)
+    : delegate_(std::move(delegate)),
+      output_count_(0),
+      flush_needed_(false),
+      flushed_(false) {
+  buffer_.reserve(delegate_->LineWidth());
 }
 
 LogOutputStream::~LogOutputStream() {
@@ -50,17 +37,19 @@ LogOutputStream::~LogOutputStream() {
 
 bool LogOutputStream::Write(const uint8_t* data, size_t size) {
   DCHECK(!flushed_);
+
+  static constexpr char kBeginMessage[] = "-----BEGIN CRASHPAD MINIDUMP-----";
+  if (output_count_ == 0 && WriteToLog(kBeginMessage) < 0) {
+    return false;
+  }
+
   flush_needed_ = true;
   while (size > 0) {
-    size_t m = std::min(kLineBufferSize - buffer_.size(), size);
+    size_t m = std::min(delegate_->LineWidth() - buffer_.size(), size);
     buffer_.append(reinterpret_cast<const char*>(data), m);
     data += m;
     size -= m;
-    if (buffer_.size() == kLineBufferSize && !WriteBuffer()) {
-      flush_needed_ = false;
-      LOG(ERROR) << "Write: exceeds cap.";
-      if (output_stream_for_testing_)
-        output_stream_for_testing_->Flush();
+    if (buffer_.size() == delegate_->LineWidth() && !WriteBuffer()) {
       return false;
     }
   }
@@ -68,66 +57,47 @@ bool LogOutputStream::Write(const uint8_t* data, size_t size) {
 }
 
 bool LogOutputStream::WriteBuffer() {
-  if (output_count_ == 0) {
-    if (!WriteToLog("-----BEGIN CRASHPAD MINIDUMP-----"))
-      return false;
-  }
-
   if (buffer_.empty())
     return true;
 
+  static constexpr char kAbortMessage[] = "-----ABORT CRASHPAD MINIDUMP-----";
+
   output_count_ += buffer_.size();
-  if (output_count_ > kOutputCap) {
-    WriteToLog("-----ABORT CRASHPAD MINIDUMP-----");
+  if (output_count_ > delegate_->OutputCap()) {
+    WriteToLog(kAbortMessage);
+    flush_needed_ = false;
+    return false;
+  }
+
+  int result = WriteToLog(buffer_.c_str());
+  if (result < 0) {
+    if (result == -EAGAIN) {
+      WriteToLog(kAbortMessage);
+    }
+    flush_needed_ = false;
     return false;
   }
 
-  bool result = WriteToLog(buffer_.c_str());
   buffer_.clear();
-  return result;
-}
-
-bool LogOutputStream::WriteToLog(const char* buf) {
-#if defined(OS_ANDROID)
-  int ret =
-      __android_log_buf_write(LOG_ID_CRASH, ANDROID_LOG_FATAL, "crashpad", buf);
-  if (ret < 0) {
-    errno = -ret;
-    PLOG(ERROR) << "__android_log_buf_write";
-    return false;
-  }
-#endif
-  // For testing.
-  if (output_stream_for_testing_) {
-    return output_stream_for_testing_->Write(
-        reinterpret_cast<const uint8_t*>(buf), strlen(buf));
-  }
   return true;
 }
 
+int LogOutputStream::WriteToLog(const char* buf) {
+  return delegate_->Log(buf);
+}
+
 bool LogOutputStream::Flush() {
-  flush_needed_ = false;
-  flushed_ = true;
-
   bool result = true;
-  if (WriteBuffer()) {
-    result = WriteToLog("-----END CRASHPAD MINIDUMP-----");
-  } else {
-    LOG(ERROR) << "Flush: exceeds cap.";
-    result = false;
+  if (flush_needed_) {
+    flush_needed_ = false;
+    flushed_ = true;
+
+    static constexpr char kEndMessage[] = "-----END CRASHPAD MINIDUMP-----";
+    if (!WriteBuffer() || WriteToLog(kEndMessage) < 0) {
+      result = false;
+    }
   }
-
-  // Since output_stream_for_testing_'s Write() method has been called, its
-  // Flush() shall always be invoked.
-  if (output_stream_for_testing_)
-    output_stream_for_testing_->Flush();
-
   return result;
 }
 
-void LogOutputStream::SetOutputStreamForTesting(
-    std::unique_ptr<OutputStreamInterface> stream) {
-  output_stream_for_testing_ = std::move(stream);
-}
-
 }  // namespace crashpad

util/stream/log_output_stream.h

@@ -26,32 +26,48 @@
 
 namespace crashpad {
 
-//! \brief This class output the received data to Android log, NOP in other
-//! platform.
-//!
-//! To avoid overflowing Android log, total 128k log data is allowed, after
-//! that cap, the output is aborted.
+//! \brief This class outputs a stream of data as a series of log messages.
 class LogOutputStream : public OutputStreamInterface {
  public:
-  LogOutputStream();
+  //! \brief An interface to a log output sink.
+  class Delegate {
+   public:
+    Delegate() = default;
+    virtual ~Delegate() = default;
+
+    //! \brief Logs |buf| to the output sink.
+    //!
+    //! \param buf the buffer to write to the log. More bytes than are in |buf|
+    //!     may be written, e.g. to convey metadata.
+    //! \return the number of bytes written, or a negative error code.
+    virtual int Log(const char* buf) = 0;
+
+    //! \brief Returns the maximum number of bytes to allow writing to this log.
+    virtual size_t OutputCap() = 0;
+
+    //! \brief Returns the maximum length of buffers allowed to be passed to
+    //!     Log().
+    virtual size_t LineWidth() = 0;
+  };
+
+  LogOutputStream(std::unique_ptr<Delegate> delegate);
   ~LogOutputStream() override;
 
   // OutputStreamInterface:
   bool Write(const uint8_t* data, size_t size) override;
   bool Flush() override;
 
-  void SetOutputStreamForTesting(std::unique_ptr<OutputStreamInterface> stream);
-
  private:
-  // Flush the |buffer_|, return false if kOutputCap meet.
+  // Flushes buffer_, returning false on failure.
   bool WriteBuffer();
-  bool WriteToLog(const char* buf);
+
+  int WriteToLog(const char* buf);
 
   std::string buffer_;
+  std::unique_ptr<Delegate> delegate_;
   size_t output_count_;
   bool flush_needed_;
   bool flushed_;
-  std::unique_ptr<OutputStreamInterface> output_stream_for_testing_;
 
   DISALLOW_COPY_AND_ASSIGN(LogOutputStream);
 };

util/stream/log_output_stream_test.cc

@@ -20,7 +20,6 @@
 
 #include "base/macros.h"
 #include "gtest/gtest.h"
-#include "util/stream/test_output_stream.h"
 
 namespace crashpad {
 namespace test {
@@ -32,21 +31,34 @@ const char* kBeginGuard = "-----BEGIN CRASHPAD MINIDUMP-----";
 const char* kEndGuard = "-----END CRASHPAD MINIDUMP-----";
 const char* kAbortGuard = "-----ABORT CRASHPAD MINIDUMP-----";
 
-std::string ConvertToString(const std::vector<uint8_t>& src) {
-  return std::string(reinterpret_cast<const char*>(src.data()), src.size());
-}
+class LogOutputStreamTestDelegate : public LogOutputStream::Delegate {
+ public:
+  LogOutputStreamTestDelegate(std::string* logging_destination)
+      : logging_destination_(logging_destination) {}
+  ~LogOutputStreamTestDelegate() = default;
+
+  int Log(const char* buf) override {
+    size_t len = strnlen(buf, kLineBufferSize + 1);
+    EXPECT_LE(len, kLineBufferSize);
+    logging_destination_->append(buf, len);
+    return static_cast<int>(len);
+  }
+
+  size_t OutputCap() override { return kOutputCap; }
+  size_t LineWidth() override { return kLineBufferSize; }
+
+ private:
+  std::string* logging_destination_;
+};
 
 class LogOutputStreamTest : public testing::Test {
  public:
-  LogOutputStreamTest() : test_output_stream_(nullptr) {}
+  LogOutputStreamTest() : test_log_output_() {}
 
  protected:
   void SetUp() override {
-    std::unique_ptr<TestOutputStream> output_stream =
-        std::make_unique<TestOutputStream>();
-    test_output_stream_ = output_stream.get();
-    log_stream_ = std::make_unique<LogOutputStream>();
-    log_stream_->SetOutputStreamForTesting(std::move(output_stream));
+    log_stream_ = std::make_unique<LogOutputStream>(
+        std::make_unique<LogOutputStreamTestDelegate>(&test_log_output_));
   }
 
   const uint8_t* BuildDeterministicInput(size_t size) {
@@ -57,37 +69,25 @@ class LogOutputStreamTest : public testing::Test {
     return deterministic_input_base;
   }
 
-  TestOutputStream* test_output_stream() const { return test_output_stream_; }
+  const std::string& test_log_output() const { return test_log_output_; }
 
   LogOutputStream* log_stream() const { return log_stream_.get(); }
 
  private:
   std::unique_ptr<LogOutputStream> log_stream_;
-  TestOutputStream* test_output_stream_;
+  std::string test_log_output_;
   std::unique_ptr<uint8_t[]> deterministic_input_;
 
   DISALLOW_COPY_AND_ASSIGN(LogOutputStreamTest);
 };
 
-TEST_F(LogOutputStreamTest, VerifyGuards) {
-  log_stream()->Flush();
-  // Verify OutputStream wrote 2 guards.
-  EXPECT_EQ(test_output_stream()->write_count(), 2u);
-  EXPECT_EQ(test_output_stream()->flush_count(), 1u);
-  EXPECT_FALSE(test_output_stream()->all_data().empty());
-  EXPECT_EQ(ConvertToString(test_output_stream()->all_data()),
-            std::string(kBeginGuard).append(kEndGuard));
-}
-
 TEST_F(LogOutputStreamTest, WriteShortLog) {
   const uint8_t* input = BuildDeterministicInput(2);
   EXPECT_TRUE(log_stream()->Write(input, 2));
   EXPECT_TRUE(log_stream()->Flush());
   // Verify OutputStream wrote 2 guards and data.
-  EXPECT_EQ(test_output_stream()->write_count(), 3u);
-  EXPECT_EQ(test_output_stream()->flush_count(), 1u);
-  EXPECT_FALSE(test_output_stream()->all_data().empty());
-  EXPECT_EQ(ConvertToString(test_output_stream()->all_data()),
+  EXPECT_FALSE(test_log_output().empty());
+  EXPECT_EQ(test_log_output(),
             std::string(kBeginGuard).append("aa").append(kEndGuard));
 }
 
@@ -97,10 +97,7 @@ TEST_F(LogOutputStreamTest, WriteLongLog) {
   // Verify OutputStream wrote 2 guards and data.
   EXPECT_TRUE(log_stream()->Write(input, input_length));
   EXPECT_TRUE(log_stream()->Flush());
-  EXPECT_EQ(test_output_stream()->write_count(),
-            2 + input_length / kLineBufferSize + 1);
-  EXPECT_EQ(test_output_stream()->flush_count(), 1u);
-  EXPECT_EQ(test_output_stream()->all_data().size(),
+  EXPECT_EQ(test_log_output().size(),
             strlen(kBeginGuard) + strlen(kEndGuard) + input_length);
 }
 
@@ -108,17 +105,19 @@ TEST_F(LogOutputStreamTest, WriteAbort) {
   size_t input_length = kOutputCap + kLineBufferSize;
   const uint8_t* input = BuildDeterministicInput(input_length);
   EXPECT_FALSE(log_stream()->Write(input, input_length));
-  std::string data(ConvertToString(test_output_stream()->all_data()));
-  EXPECT_EQ(data.substr(data.size() - strlen(kAbortGuard)), kAbortGuard);
+  EXPECT_EQ(
+      test_log_output().substr(test_log_output().size() - strlen(kAbortGuard)),
+      kAbortGuard);
 }
 
 TEST_F(LogOutputStreamTest, FlushAbort) {
-  size_t input_length = kOutputCap + kLineBufferSize / 2;
+  size_t input_length = kOutputCap - strlen(kBeginGuard) + kLineBufferSize / 2;
   const uint8_t* input = BuildDeterministicInput(input_length);
   EXPECT_TRUE(log_stream()->Write(input, input_length));
   EXPECT_FALSE(log_stream()->Flush());
-  std::string data(ConvertToString(test_output_stream()->all_data()));
-  EXPECT_EQ(data.substr(data.size() - strlen(kAbortGuard)), kAbortGuard);
+  EXPECT_EQ(
+      test_log_output().substr(test_log_output().size() - strlen(kAbortGuard)),
+      kAbortGuard);
 }
 
 }  // namespace