From: Adam Simpkins Date: Tue, 20 Jun 2017 18:01:57 +0000 (-0700) Subject: logging: add a LogHandler::flush() call X-Git-Tag: v2017.06.26.00~38 X-Git-Url: http://demsky.eecs.uci.edu/git/?a=commitdiff_plain;h=d65439dd5a2b3325fa5bff8ff76f1515c74cf258;p=folly.git logging: add a LogHandler::flush() call Summary: Add a flush() call to the LogHandler interface. This is needed to implement `FB_LOG(FATAL)` so that we can flush all LogHandlers before aborting the program. Reviewed By: wez Differential Revision: D5189499 fbshipit-source-id: 75fa4d7e75ea26de5b7383bf7e8d073fb37e9309 --- diff --git a/folly/experimental/logging/AsyncFileWriter.h b/folly/experimental/logging/AsyncFileWriter.h index 890ae808..2fb2e454 100644 --- a/folly/experimental/logging/AsyncFileWriter.h +++ b/folly/experimental/logging/AsyncFileWriter.h @@ -63,7 +63,7 @@ class AsyncFileWriter : public LogWriter { * Block until the I/O thread has finished writing all messages that * were already enqueued when flush() was called. */ - void flush(); + void flush() override; private: /* diff --git a/folly/experimental/logging/ImmediateFileWriter.cpp b/folly/experimental/logging/ImmediateFileWriter.cpp index 4135be67..2035efd9 100644 --- a/folly/experimental/logging/ImmediateFileWriter.cpp +++ b/folly/experimental/logging/ImmediateFileWriter.cpp @@ -47,4 +47,6 @@ void ImmediateFileWriter::writeMessage( errnoStr(errnum)); } } + +void ImmediateFileWriter::flush() {} } diff --git a/folly/experimental/logging/ImmediateFileWriter.h b/folly/experimental/logging/ImmediateFileWriter.h index 9703cca2..d21c25e8 100644 --- a/folly/experimental/logging/ImmediateFileWriter.h +++ b/folly/experimental/logging/ImmediateFileWriter.h @@ -48,6 +48,7 @@ class ImmediateFileWriter : public LogWriter { using LogWriter::writeMessage; void writeMessage(folly::StringPiece buffer, uint32_t flags = 0) override; + void flush() override; private: ImmediateFileWriter(ImmediateFileWriter const&) = delete; diff --git a/folly/experimental/logging/LogHandler.h b/folly/experimental/logging/LogHandler.h index 3a77887c..60d1db65 100644 --- a/folly/experimental/logging/LogHandler.h +++ b/folly/experimental/logging/LogHandler.h @@ -65,5 +65,19 @@ class LogHandler { virtual void handleMessage( const LogMessage& message, const LogCategory* handlerCategory) = 0; + + /** + * Block until all messages that have already been sent to this LogHandler + * have been processed. + * + * For LogHandlers that perform asynchronous processing of log messages, + * this ensures that messages already sent to this handler have finished + * being processed. + * + * Other threads may still call handleMessage() while flush() is running. + * handleMessage() calls that did not complete before the flush() call + * started will not necessarily be processed by the flush call. + */ + virtual void flush() = 0; }; } diff --git a/folly/experimental/logging/LogWriter.h b/folly/experimental/logging/LogWriter.h index 6d6158c9..eba37714 100644 --- a/folly/experimental/logging/LogWriter.h +++ b/folly/experimental/logging/LogWriter.h @@ -62,5 +62,15 @@ class LogWriter { virtual void writeMessage(std::string&& buffer, uint32_t flags = 0) { writeMessage(folly::StringPiece{buffer}, flags); } + + /** + * Block until all messages that have already been sent to this LogWriter + * have been written. + * + * Other threads may still call writeMessage() while flush() is running. + * writeMessage() calls that did not complete before the flush() call started + * will not necessarily be processed by the flush call. + */ + virtual void flush() = 0; }; } diff --git a/folly/experimental/logging/StandardLogHandler.cpp b/folly/experimental/logging/StandardLogHandler.cpp index 4da5505b..51debdac 100644 --- a/folly/experimental/logging/StandardLogHandler.cpp +++ b/folly/experimental/logging/StandardLogHandler.cpp @@ -36,4 +36,8 @@ void StandardLogHandler::handleMessage( } writer_->writeMessage(formatter_->formatMessage(message, handlerCategory)); } + +void StandardLogHandler::flush() { + writer_->flush(); +} } diff --git a/folly/experimental/logging/StandardLogHandler.h b/folly/experimental/logging/StandardLogHandler.h index dfd69c50..7fd08202 100644 --- a/folly/experimental/logging/StandardLogHandler.h +++ b/folly/experimental/logging/StandardLogHandler.h @@ -67,6 +67,8 @@ class StandardLogHandler : public LogHandler { const LogMessage& message, const LogCategory* handlerCategory) override; + void flush() override; + private: std::atomic level_{LogLevel::NONE}; std::shared_ptr formatter_; diff --git a/folly/experimental/logging/test/AsyncFileWriterTest.cpp b/folly/experimental/logging/test/AsyncFileWriterTest.cpp index 1f98a421..9e4694df 100644 --- a/folly/experimental/logging/test/AsyncFileWriterTest.cpp +++ b/folly/experimental/logging/test/AsyncFileWriterTest.cpp @@ -13,6 +13,8 @@ * See the License for the specific language governing permissions and * limitations under the License. */ +#include + #include #include #include @@ -21,6 +23,8 @@ #include #include #include +#include +#include #include #include #include @@ -133,6 +137,84 @@ TEST(AsyncFileWriter, ioError) { EXPECT_GT(logErrors.size(), 0); EXPECT_LE(logErrors.size(), numMessages); } + +namespace { +size_t fillUpPipe(int fd) { + int flags = fcntl(fd, F_GETFL); + folly::checkUnixError(flags, "failed get file descriptor flags"); + auto rc = fcntl(fd, F_SETFL, flags | O_NONBLOCK); + folly::checkUnixError(rc, "failed to put pipe in non-blocking mode"); + std::vector data; + data.resize(4000); + size_t totalBytes = 0; + size_t bytesToWrite = data.size(); + while (true) { + auto bytesWritten = writeNoInt(fd, data.data(), bytesToWrite); + if (bytesWritten < 0) { + if (errno == EAGAIN || errno == EWOULDBLOCK) { + // We blocked. Keep trying smaller writes, until we get down to a + // single byte, just to make sure the logging code really won't be able + // to write anything to the pipe. + if (bytesToWrite <= 1) { + break; + } else { + bytesToWrite /= 2; + } + } else { + throwSystemError("error writing to pipe"); + } + } else { + totalBytes += bytesWritten; + } + } + fprintf(stderr, "pipe filled up after %zu bytes\n", totalBytes); + + rc = fcntl(fd, F_SETFL, flags & ~O_NONBLOCK); + folly::checkUnixError(rc, "failed to put pipe back in blocking mode"); + + return totalBytes; +} +} + +TEST(AsyncFileWriter, flush) { + // Set up a pipe(), then write data to the write endpoint until it fills up + // and starts blocking. + std::array fds; + auto rc = pipe(fds.data()); + folly::checkUnixError(rc, "failed to create pipe"); + File readPipe{fds[0], true}; + File writePipe{fds[1], true}; + + auto paddingSize = fillUpPipe(writePipe.fd()); + + // Now set up an AsyncFileWriter pointing at the write end of the pipe + AsyncFileWriter writer{std::move(writePipe)}; + + // Write a message + writer.writeMessage(std::string{"test message"}); + + // Call flush(). Use a separate thread, since this should block until we + // consume data from the pipe. + Promise promise; + auto future = promise.getFuture(); + auto flushFunction = [&] { writer.flush(); }; + std::thread flushThread{ + [&]() { promise.setTry(makeTryWith(flushFunction)); }}; + + // Sleep briefly, and make sure flush() still hasn't completed. + /* sleep override */ + std::this_thread::sleep_for(10ms); + EXPECT_FALSE(future.isReady()); + + // Now read from the pipe + std::vector buf; + buf.resize(paddingSize); + readFull(readPipe.fd(), buf.data(), buf.size()); + + // Make sure flush completes successfully now + future.get(10ms); + flushThread.join(); +} #endif /** @@ -279,7 +361,7 @@ void readThread(folly::File&& file, ReadStats* stats) { size_t bufferIdx = 0; while (true) { /* sleep override */ - usleep(stats->getSleepUS().count()); + std::this_thread::sleep_for(stats->getSleepUS()); auto readResult = folly::readNoInt( file.fd(), buffer.data() + bufferIdx, buffer.size() - bufferIdx); diff --git a/folly/experimental/logging/test/StandardLogHandlerTest.cpp b/folly/experimental/logging/test/StandardLogHandlerTest.cpp index 8ea4efee..6a1f78db 100644 --- a/folly/experimental/logging/test/StandardLogHandlerTest.cpp +++ b/folly/experimental/logging/test/StandardLogHandlerTest.cpp @@ -53,6 +53,7 @@ class TestLogWriter : public LogWriter { override { messages_.emplace_back(buffer.str()); } + void flush() override {} std::vector& getMessages() { return messages_; diff --git a/folly/experimental/logging/test/TestLogHandler.h b/folly/experimental/logging/test/TestLogHandler.h index b35c47a3..ae74313b 100644 --- a/folly/experimental/logging/test/TestLogHandler.h +++ b/folly/experimental/logging/test/TestLogHandler.h @@ -38,6 +38,8 @@ class TestLogHandler : public LogHandler { messages_.emplace_back(message, handlerCategory); } + void flush() override {} + private: std::vector> messages_; };