Add Start/Stop/Reset to CapturedStdFd.

Move the fd() function to be private since it should not have been
exposed in the first place.

Fix the way logging_test uses CapturedXXX.

Adding this because the new isolated testing doesn't print errors to
stderr so the ASSERT_ EXPECT_ messages can get swallowed. Also, it's easier
to reuse a CapturedXXX object in a test with these functions.

Test: New unit tests pass.
Change-Id: I38b113fc184146ce434802f80a9b7997fa83e78a
This commit is contained in:
Christopher Ferris 2018-08-30 13:31:45 -07:00
parent 640ceee567
commit eea85c9aab
4 changed files with 161 additions and 101 deletions

View file

@ -62,16 +62,18 @@ class CapturedStdFd {
CapturedStdFd(int std_fd);
~CapturedStdFd();
int fd() const;
std::string str();
private:
void Init();
void Start();
void Stop();
void Reset();
private:
int fd() const;
TemporaryFile temp_file_;
int std_fd_;
int old_fd_;
int old_fd_ = -1;
DISALLOW_COPY_AND_ASSIGN(CapturedStdFd);
};

View file

@ -206,10 +206,8 @@ static std::string make_log_pattern(android::base::LogSeverity severity,
}
#endif
static void CheckMessage(CapturedStderr& cap, android::base::LogSeverity severity,
static void CheckMessage(const std::string& output, android::base::LogSeverity severity,
const char* expected, const char* expected_tag = nullptr) {
std::string output = cap.str();
// We can't usefully check the output of any of these on Windows because we
// don't have std::regex, but we can at least make sure we printed at least as
// many characters are in the log message.
@ -231,20 +229,28 @@ static void CheckMessage(CapturedStderr& cap, android::base::LogSeverity severit
#endif
}
static void CheckMessage(CapturedStderr& cap, android::base::LogSeverity severity,
const char* expected, const char* expected_tag = nullptr) {
cap.Stop();
std::string output = cap.str();
return CheckMessage(output, severity, expected, expected_tag);
}
#define CHECK_LOG_STREAM_DISABLED(severity) \
{ \
#define CHECK_LOG_STREAM_DISABLED(severity) \
{ \
android::base::ScopedLogSeverity sls1(android::base::FATAL); \
CapturedStderr cap1; \
LOG_STREAM(severity) << "foo bar"; \
ASSERT_EQ(0, lseek(cap1.fd(), 0, SEEK_CUR)); \
} \
{ \
CapturedStderr cap1; \
LOG_STREAM(severity) << "foo bar"; \
cap1.Stop(); \
ASSERT_EQ("", cap1.str()); \
} \
{ \
android::base::ScopedLogSeverity sls1(android::base::FATAL); \
CapturedStderr cap1; \
LOG_STREAM(::android::base::severity) << "foo bar"; \
ASSERT_EQ(0, lseek(cap1.fd(), 0, SEEK_CUR)); \
} \
CapturedStderr cap1; \
LOG_STREAM(::android::base::severity) << "foo bar"; \
cap1.Stop(); \
ASSERT_EQ("", cap1.str()); \
}
#define CHECK_LOG_STREAM_ENABLED(severity) \
{ \
@ -265,7 +271,7 @@ TEST(logging, LOG_STREAM_FATAL_WITHOUT_ABORT_disabled) {
}
TEST(logging, LOG_STREAM_FATAL_WITHOUT_ABORT_enabled) {
CHECK_LOG_STREAM_ENABLED(FATAL_WITHOUT_ABORT);
ASSERT_NO_FATAL_FAILURE(CHECK_LOG_STREAM_ENABLED(FATAL_WITHOUT_ABORT));
}
TEST(logging, LOG_STREAM_ERROR_disabled) {
@ -273,7 +279,7 @@ TEST(logging, LOG_STREAM_ERROR_disabled) {
}
TEST(logging, LOG_STREAM_ERROR_enabled) {
CHECK_LOG_STREAM_ENABLED(ERROR);
ASSERT_NO_FATAL_FAILURE(CHECK_LOG_STREAM_ENABLED(ERROR));
}
TEST(logging, LOG_STREAM_WARNING_disabled) {
@ -281,7 +287,7 @@ TEST(logging, LOG_STREAM_WARNING_disabled) {
}
TEST(logging, LOG_STREAM_WARNING_enabled) {
CHECK_LOG_STREAM_ENABLED(WARNING);
ASSERT_NO_FATAL_FAILURE(CHECK_LOG_STREAM_ENABLED(WARNING));
}
TEST(logging, LOG_STREAM_INFO_disabled) {
@ -289,7 +295,7 @@ TEST(logging, LOG_STREAM_INFO_disabled) {
}
TEST(logging, LOG_STREAM_INFO_enabled) {
CHECK_LOG_STREAM_ENABLED(INFO);
ASSERT_NO_FATAL_FAILURE(CHECK_LOG_STREAM_ENABLED(INFO));
}
TEST(logging, LOG_STREAM_DEBUG_disabled) {
@ -297,7 +303,7 @@ TEST(logging, LOG_STREAM_DEBUG_disabled) {
}
TEST(logging, LOG_STREAM_DEBUG_enabled) {
CHECK_LOG_STREAM_ENABLED(DEBUG);
ASSERT_NO_FATAL_FAILURE(CHECK_LOG_STREAM_ENABLED(DEBUG));
}
TEST(logging, LOG_STREAM_VERBOSE_disabled) {
@ -305,26 +311,27 @@ TEST(logging, LOG_STREAM_VERBOSE_disabled) {
}
TEST(logging, LOG_STREAM_VERBOSE_enabled) {
CHECK_LOG_STREAM_ENABLED(VERBOSE);
ASSERT_NO_FATAL_FAILURE(CHECK_LOG_STREAM_ENABLED(VERBOSE));
}
#undef CHECK_LOG_STREAM_DISABLED
#undef CHECK_LOG_STREAM_ENABLED
#define CHECK_LOG_DISABLED(severity) \
{ \
#define CHECK_LOG_DISABLED(severity) \
{ \
android::base::ScopedLogSeverity sls1(android::base::FATAL); \
CapturedStderr cap1; \
LOG(severity) << "foo bar"; \
ASSERT_EQ(0, lseek(cap1.fd(), 0, SEEK_CUR)); \
} \
{ \
CapturedStderr cap1; \
LOG(severity) << "foo bar"; \
cap1.Stop(); \
ASSERT_EQ("", cap1.str()); \
} \
{ \
android::base::ScopedLogSeverity sls1(android::base::FATAL); \
CapturedStderr cap1; \
LOG(::android::base::severity) << "foo bar"; \
ASSERT_EQ(0, lseek(cap1.fd(), 0, SEEK_CUR)); \
} \
CapturedStderr cap1; \
LOG(::android::base::severity) << "foo bar"; \
cap1.Stop(); \
ASSERT_EQ("", cap1.str()); \
}
#define CHECK_LOG_ENABLED(severity) \
{ \
@ -350,7 +357,7 @@ TEST(logging, LOG_FATAL_WITHOUT_ABORT_disabled) {
}
TEST(logging, LOG_FATAL_WITHOUT_ABORT_enabled) {
CHECK_LOG_ENABLED(FATAL_WITHOUT_ABORT);
ASSERT_NO_FATAL_FAILURE(CHECK_LOG_ENABLED(FATAL_WITHOUT_ABORT));
}
TEST(logging, LOG_ERROR_disabled) {
@ -358,7 +365,7 @@ TEST(logging, LOG_ERROR_disabled) {
}
TEST(logging, LOG_ERROR_enabled) {
CHECK_LOG_ENABLED(ERROR);
ASSERT_NO_FATAL_FAILURE(CHECK_LOG_ENABLED(ERROR));
}
TEST(logging, LOG_WARNING_disabled) {
@ -366,7 +373,7 @@ TEST(logging, LOG_WARNING_disabled) {
}
TEST(logging, LOG_WARNING_enabled) {
CHECK_LOG_ENABLED(WARNING);
ASSERT_NO_FATAL_FAILURE(CHECK_LOG_ENABLED(WARNING));
}
TEST(logging, LOG_INFO_disabled) {
@ -374,7 +381,7 @@ TEST(logging, LOG_INFO_disabled) {
}
TEST(logging, LOG_INFO_enabled) {
CHECK_LOG_ENABLED(INFO);
ASSERT_NO_FATAL_FAILURE(CHECK_LOG_ENABLED(INFO));
}
TEST(logging, LOG_DEBUG_disabled) {
@ -382,7 +389,7 @@ TEST(logging, LOG_DEBUG_disabled) {
}
TEST(logging, LOG_DEBUG_enabled) {
CHECK_LOG_ENABLED(DEBUG);
ASSERT_NO_FATAL_FAILURE(CHECK_LOG_ENABLED(DEBUG));
}
TEST(logging, LOG_VERBOSE_disabled) {
@ -390,28 +397,28 @@ TEST(logging, LOG_VERBOSE_disabled) {
}
TEST(logging, LOG_VERBOSE_enabled) {
CHECK_LOG_ENABLED(VERBOSE);
ASSERT_NO_FATAL_FAILURE(CHECK_LOG_ENABLED(VERBOSE));
}
#undef CHECK_LOG_DISABLED
#undef CHECK_LOG_ENABLED
TEST(logging, LOG_complex_param) {
#define CHECK_LOG_COMBINATION(use_scoped_log_severity_info, use_logging_severity_info) \
{ \
android::base::ScopedLogSeverity sls( \
(use_scoped_log_severity_info) ? ::android::base::INFO : ::android::base::WARNING); \
CapturedStderr cap; \
LOG((use_logging_severity_info) ? ::android::base::INFO : ::android::base::WARNING) \
<< "foobar"; \
if ((use_scoped_log_severity_info) || !(use_logging_severity_info)) { \
CheckMessage(cap, \
(use_logging_severity_info) ? ::android::base::INFO : ::android::base::WARNING, \
"foobar"); \
} else { \
ASSERT_EQ(0, lseek(cap.fd(), 0, SEEK_CUR)); \
} \
#define CHECK_LOG_COMBINATION(use_scoped_log_severity_info, use_logging_severity_info) \
{ \
android::base::ScopedLogSeverity sls( \
(use_scoped_log_severity_info) ? ::android::base::INFO : ::android::base::WARNING); \
CapturedStderr cap; \
LOG((use_logging_severity_info) ? ::android::base::INFO : ::android::base::WARNING) \
<< "foobar"; \
if ((use_scoped_log_severity_info) || !(use_logging_severity_info)) { \
ASSERT_NO_FATAL_FAILURE(CheckMessage( \
cap, (use_logging_severity_info) ? ::android::base::INFO : ::android::base::WARNING, \
"foobar")); \
} else { \
cap.Stop(); \
ASSERT_EQ("", cap.str()); \
} \
}
CHECK_LOG_COMBINATION(false,false);
@ -429,7 +436,7 @@ TEST(logging, LOG_does_not_clobber_errno) {
LOG(INFO) << (errno = 67890);
EXPECT_EQ(12345, errno) << "errno was not restored";
CheckMessage(cap, android::base::INFO, "67890");
ASSERT_NO_FATAL_FAILURE(CheckMessage(cap, android::base::INFO, "67890"));
}
TEST(logging, PLOG_does_not_clobber_errno) {
@ -438,7 +445,7 @@ TEST(logging, PLOG_does_not_clobber_errno) {
PLOG(INFO) << (errno = 67890);
EXPECT_EQ(12345, errno) << "errno was not restored";
CheckMessage(cap, android::base::INFO, "67890");
ASSERT_NO_FATAL_FAILURE(CheckMessage(cap, android::base::INFO, "67890"));
}
TEST(logging, LOG_does_not_have_dangling_if) {
@ -464,19 +471,21 @@ TEST(logging, LOG_does_not_have_dangling_if) {
EXPECT_FALSE(flag) << "LOG macro probably has a dangling if with no else";
}
#define CHECK_PLOG_DISABLED(severity) \
{ \
#define CHECK_PLOG_DISABLED(severity) \
{ \
android::base::ScopedLogSeverity sls1(android::base::FATAL); \
CapturedStderr cap1; \
PLOG(severity) << "foo bar"; \
ASSERT_EQ(0, lseek(cap1.fd(), 0, SEEK_CUR)); \
} \
{ \
CapturedStderr cap1; \
PLOG(severity) << "foo bar"; \
cap1.Stop(); \
ASSERT_EQ("", cap1.str()); \
} \
{ \
android::base::ScopedLogSeverity sls1(android::base::FATAL); \
CapturedStderr cap1; \
PLOG(severity) << "foo bar"; \
ASSERT_EQ(0, lseek(cap1.fd(), 0, SEEK_CUR)); \
} \
CapturedStderr cap1; \
PLOG(severity) << "foo bar"; \
cap1.Stop(); \
ASSERT_EQ("", cap1.str()); \
}
#define CHECK_PLOG_ENABLED(severity) \
{ \
@ -504,7 +513,7 @@ TEST(logging, PLOG_FATAL_WITHOUT_ABORT_disabled) {
}
TEST(logging, PLOG_FATAL_WITHOUT_ABORT_enabled) {
CHECK_PLOG_ENABLED(FATAL_WITHOUT_ABORT);
ASSERT_NO_FATAL_FAILURE(CHECK_PLOG_ENABLED(FATAL_WITHOUT_ABORT));
}
TEST(logging, PLOG_ERROR_disabled) {
@ -512,7 +521,7 @@ TEST(logging, PLOG_ERROR_disabled) {
}
TEST(logging, PLOG_ERROR_enabled) {
CHECK_PLOG_ENABLED(ERROR);
ASSERT_NO_FATAL_FAILURE(CHECK_PLOG_ENABLED(ERROR));
}
TEST(logging, PLOG_WARNING_disabled) {
@ -520,7 +529,7 @@ TEST(logging, PLOG_WARNING_disabled) {
}
TEST(logging, PLOG_WARNING_enabled) {
CHECK_PLOG_ENABLED(WARNING);
ASSERT_NO_FATAL_FAILURE(CHECK_PLOG_ENABLED(WARNING));
}
TEST(logging, PLOG_INFO_disabled) {
@ -528,7 +537,7 @@ TEST(logging, PLOG_INFO_disabled) {
}
TEST(logging, PLOG_INFO_enabled) {
CHECK_PLOG_ENABLED(INFO);
ASSERT_NO_FATAL_FAILURE(CHECK_PLOG_ENABLED(INFO));
}
TEST(logging, PLOG_DEBUG_disabled) {
@ -536,7 +545,7 @@ TEST(logging, PLOG_DEBUG_disabled) {
}
TEST(logging, PLOG_DEBUG_enabled) {
CHECK_PLOG_ENABLED(DEBUG);
ASSERT_NO_FATAL_FAILURE(CHECK_PLOG_ENABLED(DEBUG));
}
TEST(logging, PLOG_VERBOSE_disabled) {
@ -544,7 +553,7 @@ TEST(logging, PLOG_VERBOSE_disabled) {
}
TEST(logging, PLOG_VERBOSE_enabled) {
CHECK_PLOG_ENABLED(VERBOSE);
ASSERT_NO_FATAL_FAILURE(CHECK_PLOG_ENABLED(VERBOSE));
}
#undef CHECK_PLOG_DISABLED
@ -557,7 +566,7 @@ TEST(logging, UNIMPLEMENTED) {
CapturedStderr cap;
errno = ENOENT;
UNIMPLEMENTED(ERROR);
CheckMessage(cap, android::base::ERROR, expected.c_str());
ASSERT_NO_FATAL_FAILURE(CheckMessage(cap, android::base::ERROR, expected.c_str()));
}
static void NoopAborter(const char* msg ATTRIBUTE_UNUSED) {
@ -565,17 +574,19 @@ static void NoopAborter(const char* msg ATTRIBUTE_UNUSED) {
}
TEST(logging, LOG_FATAL_NOOP_ABORTER) {
CapturedStderr cap;
{
android::base::SetAborter(NoopAborter);
android::base::ScopedLogSeverity sls(android::base::ERROR);
CapturedStderr cap;
LOG(FATAL) << "foobar";
CheckMessage(cap, android::base::FATAL, "foobar");
CheckMessage(cap, android::base::ERROR, "called noop");
cap.Stop();
android::base::SetAborter(android::base::DefaultAborter);
}
std::string output = cap.str();
ASSERT_NO_FATAL_FAILURE(CheckMessage(output, android::base::FATAL, "foobar"));
ASSERT_NO_FATAL_FAILURE(CheckMessage(output, android::base::ERROR, "called noop"));
ASSERT_DEATH({SuppressAbortUI(); LOG(FATAL) << "foobar";}, "foobar");
}
@ -619,25 +630,21 @@ TEST(logging, SetDefaultTag) {
LOG(INFO) << expected_msg;
android::base::SetDefaultTag(old_default_tag);
}
CheckMessage(cap, android::base::LogSeverity::INFO, expected_msg, expected_tag);
ASSERT_NO_FATAL_FAILURE(
CheckMessage(cap, android::base::LogSeverity::INFO, expected_msg, expected_tag));
}
TEST(logging, StdioLogger) {
std::string err_str;
std::string out_str;
{
CapturedStderr cap_err;
CapturedStdout cap_out;
android::base::SetLogger(android::base::StdioLogger);
LOG(INFO) << "out";
LOG(ERROR) << "err";
err_str = cap_err.str();
out_str = cap_out.str();
}
CapturedStderr cap_err;
CapturedStdout cap_out;
android::base::SetLogger(android::base::StdioLogger);
LOG(INFO) << "out";
LOG(ERROR) << "err";
cap_err.Stop();
cap_out.Stop();
// For INFO we expect just the literal "out\n".
ASSERT_EQ("out\n", out_str) << out_str;
ASSERT_EQ("out\n", cap_out.str());
// Whereas ERROR logging includes the program name.
ASSERT_EQ(android::base::Basename(android::base::GetExecutablePath()) + ": err\n", err_str)
<< err_str;
ASSERT_EQ(android::base::Basename(android::base::GetExecutablePath()) + ": err\n", cap_err.str());
}

View file

@ -126,11 +126,13 @@ bool TemporaryDir::init(const std::string& tmp_dir) {
}
CapturedStdFd::CapturedStdFd(int std_fd) : std_fd_(std_fd), old_fd_(-1) {
Init();
Start();
}
CapturedStdFd::~CapturedStdFd() {
Reset();
if (old_fd_ != -1) {
Stop();
}
}
int CapturedStdFd::fd() const {
@ -144,19 +146,28 @@ std::string CapturedStdFd::str() {
return result;
}
void CapturedStdFd::Init() {
void CapturedStdFd::Reset() {
// Do not reset while capturing.
CHECK_EQ(-1, old_fd_);
CHECK_EQ(0, TEMP_FAILURE_RETRY(lseek(fd(), 0, SEEK_SET)));
CHECK_EQ(0, ftruncate(fd(), 0));
}
void CapturedStdFd::Start() {
#if defined(_WIN32)
// On Windows, stderr is often buffered, so make sure it is unbuffered so
// that we can immediately read back what was written to stderr.
if (std_fd_ == STDERR_FILENO) CHECK_EQ(0, setvbuf(stderr, NULL, _IONBF, 0));
if (std_fd_ == STDERR_FILENO) CHECK_EQ(0, setvbuf(stderr, nullptr, _IONBF, 0));
#endif
old_fd_ = dup(std_fd_);
CHECK_NE(-1, old_fd_);
CHECK_NE(-1, dup2(fd(), std_fd_));
}
void CapturedStdFd::Reset() {
void CapturedStdFd::Stop() {
CHECK_NE(-1, old_fd_);
CHECK_NE(-1, dup2(old_fd_, std_fd_));
CHECK_EQ(0, close(old_fd_));
close(old_fd_);
old_fd_ = -1;
// Note: cannot restore prior setvbuf() setting.
}

View file

@ -14,6 +14,8 @@
* limitations under the License.
*/
#include <stdio.h>
#include "android-base/test_utils.h"
#include <gtest/gtest-spi.h>
@ -42,5 +44,43 @@ TEST(TestUtilsTest, ExpectNotMatch) {
EXPECT_NONFATAL_FAILURE(EXPECT_NOT_MATCH("foobar", R"(foobar)"), "regex mismatch");
}
TEST(TestUtilsTest, CaptureStdout_smoke) {
CapturedStdout cap;
printf("This should be captured.\n");
cap.Stop();
printf("This will not be captured.\n");
ASSERT_EQ("This should be captured.\n", cap.str());
cap.Start();
printf("And this text should be captured too.\n");
cap.Stop();
ASSERT_EQ("This should be captured.\nAnd this text should be captured too.\n", cap.str());
printf("Still not going to be captured.\n");
cap.Reset();
cap.Start();
printf("Only this will be captured.\n");
ASSERT_EQ("Only this will be captured.\n", cap.str());
}
TEST(TestUtilsTest, CaptureStderr_smoke) {
CapturedStderr cap;
fprintf(stderr, "This should be captured.\n");
cap.Stop();
fprintf(stderr, "This will not be captured.\n");
ASSERT_EQ("This should be captured.\n", cap.str());
cap.Start();
fprintf(stderr, "And this text should be captured too.\n");
cap.Stop();
ASSERT_EQ("This should be captured.\nAnd this text should be captured too.\n", cap.str());
fprintf(stderr, "Still not going to be captured.\n");
cap.Reset();
cap.Start();
fprintf(stderr, "Only this will be captured.\n");
ASSERT_EQ("Only this will be captured.\n", cap.str());
}
} // namespace base
} // namespace android