Donate to e Foundation | Murena handsets with /e/OS | Own a part of Murena! Learn more

Commit 47f7dcb3 authored by Qasim Javed's avatar Qasim Javed Committed by Chris Manton
Browse files

Wait for a string to appear in logs. 

Currently, we have to wait for arbitrary amount of time before we check
the log for a particular string. Instead of that, add functionality to
wait for a provided string to appear in the logs.

When an fd is dup?()'ed, the oldfd and the newfd share the offset.
So when the offset is changed on the oldfd using lseek, that change in
offset is applied to the newfd as well. In the context of this change,
it means that when we Rewind(), that also changes where the logs will be
written in the backing store. It can cause problems if we are
Rewind()'ing while logs are being written.

This change keeps the dup'ed fd since its needed to create a backing
store. However, it creates adds a new fd which uses the open system call
to get a new fd to the underlying backing store file. Since this is a
separate fd, an lseek on this fd will not result in a change in offset
on the newfd and oldfd provided to dup3 system call.

Bug: 246955322
Tag: #gd-refactor
Test: atest bluetooth_test_gd_unit
Ignore-AOSP-First: Cherry-pick

Merged-In: Ib2fcfeef82d3419f4c02e1815b907b0b6ac499a9
Change-Id: Ib2fcfeef82d3419f4c02e1815b907b0b6ac499a9
parent 2d1b9945

system/gd/common/testing/log_capture.cc

+30 −8
Original line number Diff line number Diff line
@@ -37,12 +37,12 @@ namespace bluetooth { 
namespace testing {



LogCapture::LogCapture() {

  fd_ = create_backing_store();

  if (fd_ == -1) {

  std::tie(dup_fd_, fd_) = create_backing_store();

  if (dup_fd_ == -1 || fd_ == -1) {

    LOG_ERROR("Unable to create backing storage : %s", strerror(errno));

    return;

  }

  if (!set_non_blocking(fd_)) {

  if (!set_non_blocking(dup_fd_)) {

    LOG_ERROR("Unable to set socket non-blocking : %s", strerror(errno));

    return;

  }
@@ -51,7 +51,7 @@ LogCapture::LogCapture() { 
    LOG_ERROR("Unable to save original fd : %s", strerror(errno));

    return;

  }

  if (dup3(fd_, kStandardErrorFd, O_CLOEXEC) == -1) {

  if (dup3(dup_fd_, kStandardErrorFd, O_CLOEXEC) == -1) {

    LOG_ERROR("Unable to duplicate stderr fd : %s", strerror(errno));

    return;

  }
@@ -101,6 +101,12 @@ void LogCapture::Reset() { 
      LOG_ERROR("Unable to truncate backing storage : %s", strerror(errno));

    }

    this->Rewind();

    // The only time we rewind the dup()'ed fd is during Reset()

    if (dup_fd_ != -1) {

      if (lseek(dup_fd_, 0, SEEK_SET) != 0) {

        LOG_ERROR("Unable to rewind log capture : %s", strerror(errno));

      }

    }

  }

}
@@ -129,14 +135,26 @@ size_t LogCapture::Size() const { 
  return size;

}



int LogCapture::create_backing_store() const {

void LogCapture::WaitUntilLogContains(std::promise<void>* promise, std::string text) {

  std::async([this, promise, text]() {

    bool found = false;

    do {

      found = this->Rewind()->Find(text);

    } while (!found);

    promise->set_value();

  });

  promise->get_future().wait();

}



std::pair<int, int> LogCapture::create_backing_store() const {

  char backing_store_filename[kTempFilenameMaxSize];

  strncpy(backing_store_filename, kTempFilename, kTempFilenameMaxSize);

  int fd = mkstemp(backing_store_filename);

  if (fd != -1) {

  int dup_fd = mkstemp(backing_store_filename);

  int fd = open(backing_store_filename, O_RDWR);

  if (dup_fd != -1) {

    unlink(backing_store_filename);

  }

  return fd;

  return std::make_pair(dup_fd, fd);

}



bool LogCapture::set_non_blocking(int fd) const {
@@ -158,6 +176,10 @@ void LogCapture::clean_up() { 
      LOG_ERROR("Unable to restore original fd : %s", strerror(errno));

    }

  }

  if (dup_fd_ != -1) {

    close(dup_fd_);

    dup_fd_ = -1;

  }

  if (fd_ != -1) {

    close(fd_);

    fd_ = -1;

system/gd/common/testing/log_capture.h

+5 −1
Original line number Diff line number Diff line
@@ -15,6 +15,7 @@ 
 */



#include <cstddef>

#include <future>

#include <string>



namespace bluetooth {
@@ -41,12 +42,15 @@ class LogCapture { 
  size_t Size() const;

  // Truncates and resets the file pointer discarding all logs up to this point

  void Reset();

  // Wait until the provided string shows up in the logs

  void WaitUntilLogContains(std::promise<void>* promise, std::string text);



 private:

  int create_backing_store() const;

  std::pair<int, int> create_backing_store() const;

  bool set_non_blocking(int fd) const;

  void clean_up();



  int dup_fd_{-1};

  int fd_{-1};

  int original_stderr_fd_{-1};

};

system/gd/common/testing/log_capture_test.cc

0 → 100644
+149 −0
Original line number Diff line number Diff line 
/*

 * Copyright 2022 The Android Open Source Project

 *

 * 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 "log_capture.h"



#include <gtest/gtest.h>



#include <cstring>

#include <memory>

#include <string>



#include "common/init_flags.h"

#include "os/log.h"



namespace {

const char* test_flags[] = {

    "INIT_logging_debug_enabled_for_all=true",

    nullptr,

};



constexpr char kEmptyLine[] = "";

constexpr char kLogError[] = "LOG_ERROR";

constexpr char kLogWarn[] = "LOG_WARN";

constexpr char kLogInfo[] = "LOG_INFO";

constexpr char kLogDebug[] = "LOG_DEBUG";

constexpr char kLogVerbose[] = "LOG_VERBOSE";



}  // namespace



namespace bluetooth {

namespace testing {



class LogCaptureTest : public ::testing::Test {

 protected:

  void SetUp() override {}



  void TearDown() override {}



  // The line number is part of the log output and must be factored out

  size_t CalibrateOneLine(const char* log_line) {

    LOG_INFO("%s", log_line);

    return strlen(log_line);

  }

};



TEST_F(LogCaptureTest, no_output) {

  std::unique_ptr<LogCapture> log_capture = std::make_unique<LogCapture>();



  ASSERT_TRUE(log_capture->Size() == 0);

}



TEST_F(LogCaptureTest, truncate) {

  std::unique_ptr<LogCapture> log_capture = std::make_unique<LogCapture>();



  CalibrateOneLine(kLogError);

  size_t size = log_capture->Size();

  ASSERT_TRUE(size > 0);



  log_capture->Reset();

  ASSERT_EQ(0UL, log_capture->Size());



  CalibrateOneLine(kLogError);

  ASSERT_EQ(size, log_capture->Size());

}



TEST_F(LogCaptureTest, log_size) {

  std::unique_ptr<LogCapture> log_capture = std::make_unique<LogCapture>();



  CalibrateOneLine(kEmptyLine);

  size_t empty_line_size = log_capture->Size();

  log_capture->Reset();



  std::vector<std::string> log_lines = {

      kLogError,

      kLogWarn,

      kLogInfo,

  };



  size_t msg_size{0};

  for (auto& log_line : log_lines) {

    msg_size += CalibrateOneLine(log_line.c_str());

  }



  ASSERT_EQ(empty_line_size * log_lines.size() + msg_size, log_capture->Size());



  ASSERT_TRUE(log_capture->Rewind()->Find(kLogError));

  ASSERT_TRUE(log_capture->Rewind()->Find(kLogWarn));

  ASSERT_TRUE(log_capture->Rewind()->Find(kLogInfo));

}



TEST_F(LogCaptureTest, typical) {

  std::unique_ptr<LogCapture> log_capture = std::make_unique<LogCapture>();



  LOG_ERROR("%s", kLogError);

  LOG_WARN("%s", kLogWarn);

  LOG_INFO("%s", kLogInfo);

  LOG_DEBUG("%s", kLogDebug);

  LOG_VERBOSE("%s", kLogVerbose);



  ASSERT_TRUE(log_capture->Rewind()->Find(kLogError));

  ASSERT_TRUE(log_capture->Rewind()->Find(kLogWarn));

  ASSERT_TRUE(log_capture->Rewind()->Find(kLogInfo));

  ASSERT_FALSE(log_capture->Rewind()->Find(kLogDebug));

  ASSERT_FALSE(log_capture->Rewind()->Find(kLogVerbose));

}



TEST_F(LogCaptureTest, with_logging_debug_enabled_for_all) {

  bluetooth::common::InitFlags::Load(test_flags);

  std::unique_ptr<LogCapture> log_capture = std::make_unique<LogCapture>();



  LOG_ERROR("%s", kLogError);

  LOG_WARN("%s", kLogWarn);

  LOG_INFO("%s", kLogInfo);

  LOG_DEBUG("%s", kLogDebug);

  LOG_VERBOSE("%s", kLogVerbose);



  ASSERT_TRUE(log_capture->Rewind()->Find(kLogError));

  ASSERT_TRUE(log_capture->Rewind()->Find(kLogWarn));

  ASSERT_TRUE(log_capture->Rewind()->Find(kLogInfo));

  ASSERT_TRUE(log_capture->Rewind()->Find(kLogDebug));

  ASSERT_TRUE(log_capture->Rewind()->Find(kLogVerbose));

  bluetooth::common::InitFlags::Load(nullptr);

}



TEST_F(LogCaptureTest, wait_until_log_contains) {

  bluetooth::common::InitFlags::Load(test_flags);

  std::unique_ptr<LogCapture> log_capture = std::make_unique<LogCapture>();



  LOG_DEBUG("%s", kLogDebug);

  std::promise<void> promise;

  log_capture->WaitUntilLogContains(&promise, kLogDebug);

  bluetooth::common::InitFlags::Load(nullptr);

}



}  // namespace testing

}  // namespace bluetooth