logging: add ImmediateFileWriter
authorAdam Simpkins <simpkins@fb.com>
Thu, 15 Jun 2017 18:03:55 +0000 (11:03 -0700)
committerFacebook Github Bot <facebook-github-bot@users.noreply.github.com>
Thu, 15 Jun 2017 18:06:06 +0000 (11:06 -0700)
Summary:
Add an ImmediateFileWriter class that implements the LogWriter interface by
immediately writing data it receives to a file descriptor.

This LogWriter implementation can be used by users that want to ensure log
messages are immediately flushed to a file as soon as they are written, at the
expense of possibly having logging I/O block their normal process threads.

Reviewed By: wez

Differential Revision: D5083105

fbshipit-source-id: 15cd071834e1784fe50e1d6d6ce403b9bc907047

CMakeLists.txt
folly/Makefile.am
folly/experimental/logging/ImmediateFileWriter.cpp [new file with mode: 0644]
folly/experimental/logging/ImmediateFileWriter.h [new file with mode: 0644]
folly/experimental/logging/Makefile.am
folly/experimental/logging/test/ImmediateFileWriterTest.cpp [new file with mode: 0644]

index 9aba1846d97b1f83ad38d63078151f426b66acfd..97f8e0027f2ea52de4f29ddc295ea09c2fd7377d 100755 (executable)
@@ -320,6 +320,7 @@ if (BUILD_TESTS)
           XlogHeader1.h
           XlogHeader2.h
         SOURCES
           XlogHeader1.h
           XlogHeader2.h
         SOURCES
+          ImmediateFileWriterTest.cpp
           LogCategoryTest.cpp
           LoggerDBTest.cpp
           LoggerTest.cpp
           LogCategoryTest.cpp
           LoggerDBTest.cpp
           LoggerTest.cpp
index b96b96d55cde93dc417aeb993da3801e08479c6c..5aefef35fbc82fa05b5bd44f16ad49a9468b0bfd 100644 (file)
@@ -121,6 +121,7 @@ nobase_follyinclude_HEADERS = \
        experimental/JemallocNodumpAllocator.h \
        experimental/JSONSchema.h \
        experimental/LockFreeRingBuffer.h \
        experimental/JemallocNodumpAllocator.h \
        experimental/JSONSchema.h \
        experimental/LockFreeRingBuffer.h \
+       experimental/logging/ImmediateFileWriter.h \
        experimental/logging/LogCategory.h \
        experimental/logging/LogFormatter.h \
        experimental/logging/Logger.h \
        experimental/logging/LogCategory.h \
        experimental/logging/LogFormatter.h \
        experimental/logging/Logger.h \
diff --git a/folly/experimental/logging/ImmediateFileWriter.cpp b/folly/experimental/logging/ImmediateFileWriter.cpp
new file mode 100644 (file)
index 0000000..040c5c6
--- /dev/null
@@ -0,0 +1,48 @@
+/*
+ * Copyright 2004-present Facebook, Inc.
+ *
+ * Licensed under the Apache License, Version 2.0 (the "License");
+ * you may not use this file except in compliance with the License.
+ * You may obtain a copy of the License at
+ *
+ *   http://www.apache.org/licenses/LICENSE-2.0
+ *
+ * Unless required by applicable law or agreed to in writing, software
+ * distributed under the License is distributed on an "AS IS" BASIS,
+ * WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied.
+ * See the License for the specific language governing permissions and
+ * limitations under the License.
+ */
+#include <folly/experimental/logging/ImmediateFileWriter.h>
+
+#include <folly/FileUtil.h>
+#include <folly/String.h>
+#include <folly/experimental/logging/LoggerDB.h>
+
+using folly::StringPiece;
+
+namespace folly {
+
+ImmediateFileWriter::ImmediateFileWriter(StringPiece path)
+    : file_{path.str(), O_WRONLY | O_APPEND | O_CREAT} {}
+
+ImmediateFileWriter::ImmediateFileWriter(folly::File&& file)
+    : file_{std::move(file)} {}
+
+void ImmediateFileWriter::writeMessage(StringPiece buffer) {
+  // 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.
+  auto ret = folly::writeFull(file_.fd(), buffer.data(), buffer.size());
+  if (ret < 0) {
+    int errnum = errno;
+    LoggerDB::internalWarning(
+        __FILE__,
+        __LINE__,
+        "error writing to log file ",
+        file_.fd(),
+        ": ",
+        errnoStr(errnum));
+  }
+}
+}
diff --git a/folly/experimental/logging/ImmediateFileWriter.h b/folly/experimental/logging/ImmediateFileWriter.h
new file mode 100644 (file)
index 0000000..8f49c1f
--- /dev/null
@@ -0,0 +1,57 @@
+/*
+ * Copyright 2004-present Facebook, Inc.
+ *
+ * Licensed under the Apache License, Version 2.0 (the "License");
+ * you may not use this file except in compliance with the License.
+ * You may obtain a copy of the License at
+ *
+ *   http://www.apache.org/licenses/LICENSE-2.0
+ *
+ * Unless required by applicable law or agreed to in writing, software
+ * distributed under the License is distributed on an "AS IS" BASIS,
+ * WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied.
+ * See the License for the specific language governing permissions and
+ * limitations under the License.
+ */
+#pragma once
+
+#include <folly/File.h>
+#include <folly/Range.h>
+#include <folly/experimental/logging/LogWriter.h>
+
+namespace folly {
+
+/**
+ * A LogWriter implementation that immediately writes to a file descriptor when
+ * it is invoked.
+ *
+ * The downside of this class is that logging I/O occurs directly in your
+ * normal program threads, so that logging I/O may block or slow down normal
+ * processing.
+ *
+ * However, one benefit of this class is that log messages are written out
+ * immediately, so if your program crashes, all log messages generated before
+ * the crash will have already been written, and no messages will be lost.
+ */
+class ImmediateFileWriter : public LogWriter {
+ public:
+  /**
+   * Construct an ImmediateFileWriter that appends to the file at the specified
+   * path.
+   */
+  explicit ImmediateFileWriter(folly::StringPiece path);
+
+  /**
+   * Construct an ImmediateFileWriter that writes to the specified File object.
+   */
+  explicit ImmediateFileWriter(folly::File&& file);
+
+  void writeMessage(folly::StringPiece buffer) override;
+
+ private:
+  ImmediateFileWriter(ImmediateFileWriter const&) = delete;
+  ImmediateFileWriter& operator=(ImmediateFileWriter const&) = delete;
+
+  folly::File file_;
+};
+}
index 5cb7ba47fb5fa29bb0f6b9930e68e4500591d1f9..c3750a4d2e6c6d44b5ffa99925a6c85e9253ad53 100644 (file)
@@ -3,6 +3,7 @@ SUBDIRS = .
 lib_LTLIBRARIES = libfollylogging.la
 
 libfollylogging_la_SOURCES = \
 lib_LTLIBRARIES = libfollylogging.la
 
 libfollylogging_la_SOURCES = \
+       ImmediateFileWriter.cpp \
        LogCategory.cpp \
        Logger.cpp \
        LoggerDB.cpp \
        LogCategory.cpp \
        Logger.cpp \
        LoggerDB.cpp \
diff --git a/folly/experimental/logging/test/ImmediateFileWriterTest.cpp b/folly/experimental/logging/test/ImmediateFileWriterTest.cpp
new file mode 100644 (file)
index 0000000..cff7525
--- /dev/null
@@ -0,0 +1,128 @@
+/*
+ * Copyright 2004-present Facebook, Inc.
+ *
+ * Licensed under the Apache License, Version 2.0 (the "License");
+ * you may not use this file except in compliance with the License.
+ * You may obtain a copy of the License at
+ *
+ *   http://www.apache.org/licenses/LICENSE-2.0
+ *
+ * Unless required by applicable law or agreed to in writing, software
+ * distributed under the License is distributed on an "AS IS" BASIS,
+ * WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied.
+ * See the License for the specific language governing permissions and
+ * limitations under the License.
+ */
+#ifndef _WIN32
+#include <unistd.h>
+#endif
+
+#include <folly/Conv.h>
+#include <folly/Exception.h>
+#include <folly/FileUtil.h>
+#include <folly/experimental/TestUtil.h>
+#include <folly/experimental/logging/ImmediateFileWriter.h>
+#include <folly/experimental/logging/LoggerDB.h>
+#include <folly/portability/GMock.h>
+#include <folly/portability/GTest.h>
+
+using namespace folly;
+using folly::test::TemporaryFile;
+
+TEST(ImmediateFileWriter, readBatch) {
+  TemporaryFile tmpFile{"logging_test"};
+  ImmediateFileWriter writer{folly::File{tmpFile.fd(), false}};
+
+  // Write several messages
+  for (int n = 0; n < 10; ++n) {
+    writer.writeMessage(folly::to<std::string>("message ", n, "\n"));
+  }
+
+  // Read the log file and confirm it contains all of the expected messages
+  std::string data;
+  auto ret = folly::readFile(tmpFile.path().native().c_str(), data);
+  ASSERT_TRUE(ret);
+
+  std::string expected =
+      "message 0\n"
+      "message 1\n"
+      "message 2\n"
+      "message 3\n"
+      "message 4\n"
+      "message 5\n"
+      "message 6\n"
+      "message 7\n"
+      "message 8\n"
+      "message 9\n";
+  EXPECT_EQ(expected, data);
+}
+
+TEST(ImmediateFileWriter, immediateRead) {
+  TemporaryFile tmpFile{"logging_test"};
+  ImmediateFileWriter writer{tmpFile.path().native()};
+
+  // Write several messages, and read each one back immediately
+  // after we write it.
+  folly::File readf{tmpFile.path().native()};
+  for (int n = 0; n < 10; ++n) {
+    writer.writeMessage(folly::to<std::string>("message ", n, "\n"));
+
+    std::array<char, 1024> buf;
+    auto sizeRead = folly::readFull(readf.fd(), buf.data(), buf.size());
+    ASSERT_GT(sizeRead, 0);
+    EXPECT_EQ(
+        folly::to<std::string>("message ", n, "\n"),
+        StringPiece(buf.data(), sizeRead));
+  }
+}
+
+#ifndef _WIN32
+namespace {
+static std::vector<std::string>* internalWarnings;
+
+void handleLoggingError(
+    StringPiece /* file */,
+    int /* lineNumber */,
+    std::string&& msg) {
+  internalWarnings->emplace_back(std::move(msg));
+}
+}
+
+TEST(ImmediateFileWriter, ioError) {
+  std::array<int, 2> fds;
+  auto rc = pipe(fds.data());
+  folly::checkUnixError(rc, "failed to create pipe");
+  signal(SIGPIPE, SIG_IGN);
+
+  // Set the LoggerDB internal warning handler so we can record the messages
+  std::vector<std::string> logErrors;
+  internalWarnings = &logErrors;
+  LoggerDB::setInternalWarningHandler(handleLoggingError);
+
+  // Create an ImmediateFileWriter that refers to a pipe whose read end is
+  // closed, then log a bunch of messages to it.
+  ::close(fds[0]);
+
+  size_t numMessages = 100;
+  {
+    ImmediateFileWriter writer{folly::File{fds[1], true}};
+    for (size_t n = 0; n < numMessages; ++n) {
+      writer.writeMessage(folly::to<std::string>("message ", n, "\n"));
+      sched_yield();
+    }
+  }
+
+  LoggerDB::setInternalWarningHandler(nullptr);
+
+  // ImmediateFileWriter should have generated one warning
+  // for each attempt to log a message.
+  //
+  // (The default internalWarning() handler would have rate limited these
+  // messages, but our test handler does not perform rate limiting.)
+  for (const auto& msg : logErrors) {
+    EXPECT_THAT(msg, testing::HasSubstr("error writing to log file"));
+    EXPECT_THAT(msg, testing::HasSubstr("Broken pipe"));
+  }
+  EXPECT_EQ(numMessages, logErrors.size());
+}
+#endif