logging: add a NEVER_DISCARD flag to LogWriter
authorAdam Simpkins <simpkins@fb.com>
Tue, 20 Jun 2017 18:01:55 +0000 (11:01 -0700)
committerFacebook Github Bot <facebook-github-bot@users.noreply.github.com>
Tue, 20 Jun 2017 18:06:44 +0000 (11:06 -0700)
Summary:
Add a flag to the LogWriter so we can ensure that particular messages are never
discarded, even when the LogWriter is throttling messages.

This functionality will be necessary to implement `FB_LOG(FATAL)` to that we
can avoid discarding the reason for crashing.

Reviewed By: wez

Differential Revision: D5189498

fbshipit-source-id: dc4322ea5ba449a341cdbdc32afb0ed466019801

folly/experimental/logging/AsyncFileWriter.cpp
folly/experimental/logging/AsyncFileWriter.h
folly/experimental/logging/ImmediateFileWriter.cpp
folly/experimental/logging/ImmediateFileWriter.h
folly/experimental/logging/LogWriter.h
folly/experimental/logging/test/AsyncFileWriterTest.cpp
folly/experimental/logging/test/StandardLogHandlerTest.cpp

index 3aab81ad06e4ce95cde145b024b130011b2eb7cc..61c379fe8cf08369a2ac9efb61e15602c0329a1b 100644 (file)
@@ -36,13 +36,14 @@ AsyncFileWriter::~AsyncFileWriter() {
   ioThread_.join();
 }
 
-void AsyncFileWriter::writeMessage(StringPiece buffer) {
-  return writeMessage(buffer.str());
+void AsyncFileWriter::writeMessage(StringPiece buffer, uint32_t flags) {
+  return writeMessage(buffer.str(), flags);
 }
 
-void AsyncFileWriter::writeMessage(std::string&& buffer) {
+void AsyncFileWriter::writeMessage(std::string&& buffer, uint32_t flags) {
   auto data = data_.lock();
-  if (data->currentBufferSize >= data->maxBufferBytes) {
+  if ((data->currentBufferSize >= data->maxBufferBytes) &&
+      !(flags & NEVER_DISCARD)) {
     ++data->numDiscarded;
     return;
   }
index 0d05ccd39c7839835fff4f57335ebea789da0c73..890ae808fb88a7186fd46dcba07f1d94ff66a724 100644 (file)
@@ -56,8 +56,8 @@ class AsyncFileWriter : public LogWriter {
 
   ~AsyncFileWriter();
 
-  void writeMessage(folly::StringPiece buffer) override;
-  void writeMessage(std::string&& buffer) override;
+  void writeMessage(folly::StringPiece buffer, uint32_t flags = 0) override;
+  void writeMessage(std::string&& buffer, uint32_t flags = 0) override;
 
   /**
    * Block until the I/O thread has finished writing all messages that
index 040c5c608fd3a434372aaf26ce2101ab5ec83e69..4135be677cbf87692e8534779eed05a1214bf588 100644 (file)
@@ -29,7 +29,9 @@ ImmediateFileWriter::ImmediateFileWriter(StringPiece path)
 ImmediateFileWriter::ImmediateFileWriter(folly::File&& file)
     : file_{std::move(file)} {}
 
-void ImmediateFileWriter::writeMessage(StringPiece buffer) {
+void ImmediateFileWriter::writeMessage(
+    StringPiece buffer,
+    uint32_t /* flags */) {
   // Write the data.
   // We are doing direct file descriptor writes here, so there is no buffering
   // of log message data.  Each message is immediately written to the output.
index a029e73ff4bf660e3c3c1bbd7c2817e9a605b782..9703cca21de33bfbe5a6b3dc82c1d9b03cc3e61b 100644 (file)
@@ -47,7 +47,7 @@ class ImmediateFileWriter : public LogWriter {
   explicit ImmediateFileWriter(folly::File&& file);
 
   using LogWriter::writeMessage;
-  void writeMessage(folly::StringPiece buffer) override;
+  void writeMessage(folly::StringPiece buffer, uint32_t flags = 0) override;
 
  private:
   ImmediateFileWriter(ImmediateFileWriter const&) = delete;
index e5b2ffe5904910f232ad1404d935996539c3b172..6d6158c9a7353f38ee9c9895a16bcb4bff37d247 100644 (file)
@@ -24,12 +24,32 @@ namespace folly {
  */
 class LogWriter {
  public:
+  /**
+   * Bit flag values for use with writeMessage()
+   */
+  enum Flags : uint32_t {
+    NO_FLAGS = 0x00,
+    /**
+     * Ensure that this log message never gets discarded.
+     *
+     * Some LogWriter implementations may discard messages when messages are
+     * being received faster than they can be written.  This flag ensures that
+     * this message will never be discarded.
+     *
+     * This flag is used to ensure that LOG(FATAL) messages never get
+     * discarded, so we always report the reason for a crash.
+     */
+    NEVER_DISCARD = 0x01,
+  };
+
   virtual ~LogWriter() {}
 
   /**
    * Write a serialized log message.
+   *
+   * The flags parameter is a bitwise-ORed set of Flag values defined above.
    */
-  virtual void writeMessage(folly::StringPiece buffer) = 0;
+  virtual void writeMessage(folly::StringPiece buffer, uint32_t flags = 0) = 0;
 
   /**
    * Write a serialized message.
@@ -39,8 +59,8 @@ class LogWriter {
    * writeMessage(), but subclasses may override this implementation if
    * desired.
    */
-  virtual void writeMessage(std::string&& buffer) {
-    writeMessage(folly::StringPiece{buffer});
+  virtual void writeMessage(std::string&& buffer, uint32_t flags = 0) {
+    writeMessage(folly::StringPiece{buffer}, flags);
   }
 };
 }
index d1541dc52ca9d5b432f3032ae4ba5a6b3a7ae5e9..1f98a4219db73298eb4eb37bbde31edd5ab5b4d0 100644 (file)
@@ -43,6 +43,7 @@ DEFINE_int64(
     "the AsyncFileWriter.discard test");
 
 using namespace folly;
+using namespace std::literals::chrono_literals;
 using folly::test::TemporaryFile;
 
 TEST(AsyncFileWriter, noMessages) {
@@ -137,15 +138,30 @@ TEST(AsyncFileWriter, ioError) {
 /**
  * writeThread() writes a series of messages to the AsyncFileWriter
  */
-void writeThread(AsyncFileWriter* writer, size_t id, size_t numMessages) {
+void writeThread(
+    AsyncFileWriter* writer,
+    size_t id,
+    size_t numMessages,
+    uint32_t flags) {
   for (size_t n = 0; n < numMessages; ++n) {
     writer->writeMessage(
-        folly::to<std::string>("thread ", id, " message ", n + 1, '\n'));
+        folly::to<std::string>("thread ", id, " message ", n + 1, '\n'), flags);
   }
 }
 
 class ReadStats {
  public:
+  ReadStats()
+      : readSleepUS_{static_cast<uint64_t>(
+            std::min(0L, FLAGS_async_discard_read_sleep_usec))} {}
+
+  void clearSleepDuration() {
+    readSleepUS_.store(0);
+  }
+  std::chrono::microseconds getSleepUS() const {
+    return std::chrono::microseconds{readSleepUS_.load()};
+  }
+
   void check(size_t numThreads, size_t messagesPerThread) {
     EXPECT_EQ("", trailingData_);
     EXPECT_EQ(numThreads, writers_.size());
@@ -162,6 +178,14 @@ class ReadStats {
         numThreads * messagesPerThread, totalMessagesReceived + numDiscarded_);
   }
 
+  /**
+   * Check that no messages were dropped from the specified thread.
+   */
+  void checkNoDrops(size_t threadIndex, size_t messagesPerThread) {
+    EXPECT_EQ(writers_[threadIndex].numMessages, messagesPerThread);
+    EXPECT_EQ(writers_[threadIndex].lastId, messagesPerThread);
+  }
+
   void messageReceived(StringPiece msg) {
     if (msg.endsWith(" log messages discarded: "
                      "logging faster than we can write")) {
@@ -240,6 +264,8 @@ class ReadStats {
   size_t numUnableToParse_{0};
   size_t numOutOfOrder_{0};
   size_t numDiscarded_{0};
+
+  std::atomic<uint64_t> readSleepUS_;
 };
 
 /**
@@ -253,7 +279,7 @@ void readThread(folly::File&& file, ReadStats* stats) {
   size_t bufferIdx = 0;
   while (true) {
     /* sleep override */
-    usleep(FLAGS_async_discard_read_sleep_usec);
+    usleep(stats->getSleepUS().count());
 
     auto readResult = folly::readNoInt(
         file.fd(), buffer.data() + bufferIdx, buffer.size() - bufferIdx);
@@ -306,6 +332,11 @@ TEST(AsyncFileWriter, discard) {
   folly::File readPipe{fds[0], true};
   folly::File writePipe{fds[1], true};
 
+  // This test should always be run with at least 2 writer threads.
+  // The last one will use the NEVER_DISCARD flag, and we want at least
+  // one that does discard messages.
+  ASSERT_GT(FLAGS_async_discard_num_writer_threads, 2);
+
   ReadStats readStats;
   std::thread reader(readThread, std::move(readPipe), &readStats);
   {
@@ -313,8 +344,18 @@ TEST(AsyncFileWriter, discard) {
 
     std::vector<std::thread> writeThreads;
     for (int n = 0; n < FLAGS_async_discard_num_writer_threads; ++n) {
+      uint32_t flags = 0;
+      // Configure the last writer thread to never drop messages
+      if (n == (FLAGS_async_discard_num_writer_threads - 1)) {
+        flags = LogWriter::NEVER_DISCARD;
+      }
+
       writeThreads.emplace_back(
-          writeThread, &writer, n, FLAGS_async_discard_messages_per_writer);
+          writeThread,
+          &writer,
+          n,
+          FLAGS_async_discard_messages_per_writer,
+          flags);
     }
 
     for (auto& t : writeThreads) {
@@ -322,8 +363,15 @@ TEST(AsyncFileWriter, discard) {
     }
     fprintf(stderr, "writers done\n");
   }
+  // Clear the read sleep duration so the reader will finish quickly now
+  readStats.clearSleepDuration();
   reader.join();
   readStats.check(
       FLAGS_async_discard_num_writer_threads,
       FLAGS_async_discard_messages_per_writer);
+  // Check that no messages were dropped from the thread using the
+  // NEVER_DISCARD flag.
+  readStats.checkNoDrops(
+      FLAGS_async_discard_num_writer_threads - 1,
+      FLAGS_async_discard_messages_per_writer);
 }
index c34366d7094e8d7916ebc450960b53266d062321..8ea4efeef8679be2d631cd794e93e4e98536bba0 100644 (file)
@@ -49,7 +49,8 @@ class TestLogFormatter : public LogFormatter {
 
 class TestLogWriter : public LogWriter {
  public:
-  void writeMessage(folly::StringPiece buffer) override {
+  void writeMessage(folly::StringPiece buffer, uint32_t /* flags */ = 0)
+      override {
     messages_.emplace_back(buffer.str());
   }