From cb238d299031affd40d234266415d0b6322b370a Mon Sep 17 00:00:00 2001 From: Adam Simpkins Date: Thu, 15 Jun 2017 11:03:55 -0700 Subject: [PATCH] logging: add ImmediateFileWriter 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 | 1 + folly/Makefile.am | 1 + .../logging/ImmediateFileWriter.cpp | 48 +++++++ .../logging/ImmediateFileWriter.h | 57 ++++++++ folly/experimental/logging/Makefile.am | 1 + .../logging/test/ImmediateFileWriterTest.cpp | 128 ++++++++++++++++++ 6 files changed, 236 insertions(+) create mode 100644 folly/experimental/logging/ImmediateFileWriter.cpp create mode 100644 folly/experimental/logging/ImmediateFileWriter.h create mode 100644 folly/experimental/logging/test/ImmediateFileWriterTest.cpp diff --git a/CMakeLists.txt b/CMakeLists.txt index 9aba1846..97f8e002 100755 --- a/CMakeLists.txt +++ b/CMakeLists.txt @@ -320,6 +320,7 @@ if (BUILD_TESTS) XlogHeader1.h XlogHeader2.h SOURCES + ImmediateFileWriterTest.cpp LogCategoryTest.cpp LoggerDBTest.cpp LoggerTest.cpp diff --git a/folly/Makefile.am b/folly/Makefile.am index b96b96d5..5aefef35 100644 --- a/folly/Makefile.am +++ b/folly/Makefile.am @@ -121,6 +121,7 @@ nobase_follyinclude_HEADERS = \ 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 \ diff --git a/folly/experimental/logging/ImmediateFileWriter.cpp b/folly/experimental/logging/ImmediateFileWriter.cpp new file mode 100644 index 00000000..040c5c60 --- /dev/null +++ b/folly/experimental/logging/ImmediateFileWriter.cpp @@ -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 + +#include +#include +#include + +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 index 00000000..8f49c1fc --- /dev/null +++ b/folly/experimental/logging/ImmediateFileWriter.h @@ -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 +#include +#include + +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_; +}; +} diff --git a/folly/experimental/logging/Makefile.am b/folly/experimental/logging/Makefile.am index 5cb7ba47..c3750a4d 100644 --- a/folly/experimental/logging/Makefile.am +++ b/folly/experimental/logging/Makefile.am @@ -3,6 +3,7 @@ SUBDIRS = . lib_LTLIBRARIES = libfollylogging.la libfollylogging_la_SOURCES = \ + ImmediateFileWriter.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 index 00000000..cff7525f --- /dev/null +++ b/folly/experimental/logging/test/ImmediateFileWriterTest.cpp @@ -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 +#endif + +#include +#include +#include +#include +#include +#include +#include +#include + +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("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("message ", n, "\n")); + + std::array buf; + auto sizeRead = folly::readFull(readf.fd(), buf.data(), buf.size()); + ASSERT_GT(sizeRead, 0); + EXPECT_EQ( + folly::to("message ", n, "\n"), + StringPiece(buf.data(), sizeRead)); + } +} + +#ifndef _WIN32 +namespace { +static std::vector* internalWarnings; + +void handleLoggingError( + StringPiece /* file */, + int /* lineNumber */, + std::string&& msg) { + internalWarnings->emplace_back(std::move(msg)); +} +} + +TEST(ImmediateFileWriter, ioError) { + std::array 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 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("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 -- 2.34.1