Reland "[test][d8] Add d8.log.getAndStop helper"

This is a reland of 95aa697b

Original change's description:
> [test][d8] Add d8.log.getAndStop helper
>
> The new helper function allows us to write tests for log parsing
> without the need to first generating a log file. This makes it easier
> to spot errors when the log format changes.
>
> - Add d8 global variable
> - Add file_name accessor to Logger and Log classes
> - Change OS::LogFileOpenMode to w+ / wb+
> - Use separate Log::WriteLogHeader method
> - Remove unused logger_ instance variable from Log
>
> Bug: v8:10644
> Change-Id: Ifc7e35aa4e91b3f01f0847843263946e085944c3
> Reviewed-on: https://chromium-review.googlesource.com/c/v8/v8/+/2387563
> Commit-Queue: Camillo Bruni <cbruni@chromium.org>
> Reviewed-by: Michael Lippautz <mlippautz@chromium.org>
> Reviewed-by: Toon Verwaest <verwaest@chromium.org>
> Reviewed-by: Sathya Gunasekaran  <gsathya@chromium.org>
> Cr-Commit-Position: refs/heads/master@{#69715}

Bug: v8:10644

TBR=verwaest@chromium.org

Change-Id: I54741344834d88a376b74e2e3a2047e880a94624
Reviewed-on: https://chromium-review.googlesource.com/c/v8/v8/+/2396081
Commit-Queue: Camillo Bruni <cbruni@chromium.org>
Reviewed-by: Michael Lippautz <mlippautz@chromium.org>
Reviewed-by: Sathya Gunasekaran  <gsathya@chromium.org>
Cr-Commit-Position: refs/heads/master@{#69769}

src/base/platform/platform-posix.cc

@@ -679,9 +679,7 @@ FILE* OS::OpenTemporaryFile() {
   return tmpfile();
 }
 
-
-const char* const OS::LogFileOpenMode = "w";
-
+const char* const OS::LogFileOpenMode = "w+";
 
 void OS::Print(const char* format, ...) {
   va_list args;

src/base/platform/platform-win32.cc

@@ -603,8 +603,7 @@ FILE* OS::OpenTemporaryFile() {
 
 
 // Open log file in binary mode to avoid /n -> /r/n conversion.
-const char* const OS::LogFileOpenMode = "wb";
-
+const char* const OS::LogFileOpenMode = "wb+";
 
 // Print (debug) message to console.
 void OS::Print(const char* format, ...) {

src/d8/d8.h

@@ -401,6 +401,8 @@ class Shell : public i::AllStatic {
   static void RealmSharedSet(Local<String> property, Local<Value> value,
                              const PropertyCallbackInfo<void>& info);
 
+  static void LogGetAndStop(const v8::FunctionCallbackInfo<v8::Value>& args);
+
   static void AsyncHooksCreateHook(
       const v8::FunctionCallbackInfo<v8::Value>& args);
   static void AsyncHooksExecutionAsyncId(
@@ -539,7 +541,16 @@ class Shell : public i::AllStatic {
   static Local<String> Stringify(Isolate* isolate, Local<Value> value);
   static void RunShell(Isolate* isolate);
   static bool SetOptions(int argc, char* argv[]);
+
   static Local<ObjectTemplate> CreateGlobalTemplate(Isolate* isolate);
+  static Local<ObjectTemplate> CreateOSTemplate(Isolate* isolate);
+  static Local<FunctionTemplate> CreateWorkerTemplate(Isolate* isolate);
+  static Local<ObjectTemplate> CreateAsyncHookTemplate(Isolate* isolate);
+  static Local<ObjectTemplate> CreateTestRunnerTemplate(Isolate* isolate);
+  static Local<ObjectTemplate> CreatePerformanceTemplate(Isolate* isolate);
+  static Local<ObjectTemplate> CreateRealmTemplate(Isolate* isolate);
+  static Local<ObjectTemplate> CreateD8Template(Isolate* isolate);
+
   static MaybeLocal<Context> CreateRealm(
       const v8::FunctionCallbackInfo<v8::Value>& args, int index,
       v8::MaybeLocal<Value> global_object);

src/execution/isolate.cc

@@ -3077,7 +3077,8 @@ void Isolate::Deinit() {
   cancelable_task_manager()->CancelAndWait();
 
   heap_.TearDown();
-  logger_->TearDown();
+  FILE* logfile = logger_->TearDownAndGetLogFile();
+  if (logfile != nullptr) fclose(logfile);
 
   if (wasm_engine_) {
     wasm_engine_->RemoveIsolate(this);

src/logging/log-utils.cc

@@ -23,28 +23,43 @@ const char* const Log::kLogToTemporaryFile = "&";
 const char* const Log::kLogToConsole = "-";
 
 // static
-FILE* Log::CreateOutputHandle(const char* file_name) {
+FILE* Log::CreateOutputHandle(std::string file_name) {
   // If we're logging anything, we need to open the log file.
   if (!Log::InitLogAtStart()) {
     return nullptr;
-  } else if (strcmp(file_name, kLogToConsole) == 0) {
+  } else if (Log::IsLoggingToConsole(file_name)) {
     return stdout;
-  } else if (strcmp(file_name, kLogToTemporaryFile) == 0) {
+  } else if (Log::IsLoggingToTemporaryFile(file_name)) {
     return base::OS::OpenTemporaryFile();
   } else {
-    return base::OS::FOpen(file_name, base::OS::LogFileOpenMode);
+    return base::OS::FOpen(file_name.c_str(), base::OS::LogFileOpenMode);
   }
 }
 
-Log::Log(Logger* logger, const char* file_name)
-    : output_handle_(Log::CreateOutputHandle(file_name)),
+// static
+bool Log::IsLoggingToConsole(std::string file_name) {
+  return file_name.compare(Log::kLogToConsole) == 0;
+}
+
+// static
+bool Log::IsLoggingToTemporaryFile(std::string file_name) {
+  return file_name.compare(Log::kLogToTemporaryFile) == 0;
+}
+
+Log::Log(std::string file_name)
+    : file_name_(file_name),
+      output_handle_(Log::CreateOutputHandle(file_name)),
       os_(output_handle_ == nullptr ? stdout : output_handle_),
       is_enabled_(output_handle_ != nullptr),
-      format_buffer_(NewArray<char>(kMessageBufferSize)),
-      logger_(logger) {
-
+      format_buffer_(NewArray<char>(kMessageBufferSize)) {
   if (output_handle_ == nullptr) return;
-  Log::MessageBuilder msg(this);
+  WriteLogHeader();
+}
+
+void Log::WriteLogHeader() {
+  std::unique_ptr<Log::MessageBuilder> msg_ptr = NewMessageBuilder();
+  if (!msg_ptr) return;
+  Log::MessageBuilder& msg = *msg_ptr.get();
   LogSeparator kNext = LogSeparator::kSeparator;
   msg << "v8-version" << kNext << Version::GetMajor() << kNext
       << Version::GetMinor() << kNext << Version::GetBuild() << kNext
@@ -71,20 +86,17 @@ FILE* Log::Close() {
   base::MutexGuard guard(&mutex_);
   FILE* result = nullptr;
   if (output_handle_ != nullptr) {
-    if (strcmp(FLAG_logfile, kLogToTemporaryFile) != 0) {
-      fclose(output_handle_);
-    } else {
-      result = output_handle_;
-    }
+    fflush(output_handle_);
+    result = output_handle_;
   }
   output_handle_ = nullptr;
-
   format_buffer_.reset();
-
   is_enabled_.store(false, std::memory_order_relaxed);
   return result;
 }
 
+std::string Log::file_name() const { return file_name_; }
+
 Log::MessageBuilder::MessageBuilder(Log* log)
     : log_(log), lock_guard_(&log_->mutex_) {
   DCHECK_NOT_NULL(log_->format_buffer_.get());

src/logging/log-utils.h

@@ -30,22 +30,27 @@ enum class LogSeparator { kSeparator };
 // Functions and data for performing output of log messages.
 class Log {
  public:
-  Log(Logger* log, const char* log_file_name);
+  explicit Log(std::string log_file_name);
 
   static bool InitLogAtStart() {
-    return FLAG_log || FLAG_log_api || FLAG_log_code || FLAG_log_handles ||
-           FLAG_log_suspect || FLAG_ll_prof || FLAG_perf_basic_prof ||
-           FLAG_perf_prof || FLAG_log_source_code || FLAG_gdbjit ||
-           FLAG_log_internal_timer_events || FLAG_prof_cpp || FLAG_trace_ic ||
-           FLAG_log_function_events || FLAG_trace_zone_stats ||
+    return FLAG_log || FLAG_log_all || FLAG_log_api || FLAG_log_code ||
+           FLAG_log_handles || FLAG_log_suspect || FLAG_ll_prof ||
+           FLAG_perf_basic_prof || FLAG_perf_prof || FLAG_log_source_code ||
+           FLAG_gdbjit || FLAG_log_internal_timer_events || FLAG_prof_cpp ||
+           FLAG_trace_ic || FLAG_log_function_events || FLAG_trace_zone_stats ||
            FLAG_turbo_profiling_log_builtins;
   }
 
+  V8_EXPORT_PRIVATE static bool IsLoggingToConsole(std::string file_name);
+  V8_EXPORT_PRIVATE static bool IsLoggingToTemporaryFile(std::string file_name);
+
   // Frees all resources acquired in Initialize and Open... functions.
   // When a temporary file is used for the log, returns its stream descriptor,
   // leaving the file open.
   FILE* Close();
 
+  std::string file_name() const;
+
   // Returns whether logging is enabled.
   bool IsEnabled() { return is_enabled_.load(std::memory_order_relaxed); }
 
@@ -109,19 +114,15 @@ class Log {
   std::unique_ptr<Log::MessageBuilder> NewMessageBuilder();
 
  private:
-  static FILE* CreateOutputHandle(const char* file_name);
-
-  // Implementation of writing to a log file.
-  int WriteToFile(const char* msg, int length) {
-    DCHECK_NOT_NULL(output_handle_);
-    os_.write(msg, length);
-    DCHECK(!os_.bad());
-    return length;
-  }
+  static FILE* CreateOutputHandle(std::string file_name);
+
+  void WriteLogHeader();
 
+  std::string file_name_;
   // When logging is active output_handle_ is used to store a pointer to log
   // destination.  mutex_ should be acquired before using output_handle_.
   FILE* output_handle_;
+
   OFStream os_;
 
   // Stores whether logging is enabled.
@@ -134,10 +135,6 @@ class Log {
   // Buffer used for formatting log messages. This is a singleton buffer and
   // mutex_ should be acquired before using it.
   std::unique_ptr<char[]> format_buffer_;
-
-  Logger* logger_;
-
-  friend class Logger;
 };
 
 template <>

src/logging/log.cc

@@ -1974,16 +1974,13 @@ void Logger::LogAllMaps() {
   }
 }
 
-static void AddIsolateIdIfNeeded(std::ostream& os,  // NOLINT
-                                 Isolate* isolate) {
-  if (FLAG_logfile_per_isolate) {
-    os << "isolate-" << isolate << "-" << base::OS::GetCurrentProcessId()
-       << "-";
-  }
+static void AddIsolateIdIfNeeded(std::ostream& os, Isolate* isolate) {
+  if (!FLAG_logfile_per_isolate) return;
+  os << "isolate-" << isolate << "-" << base::OS::GetCurrentProcessId() << "-";
 }
 
-static void PrepareLogFileName(std::ostream& os,  // NOLINT
-                               Isolate* isolate, const char* file_name) {
+static void PrepareLogFileName(std::ostream& os, Isolate* isolate,
+                               const char* file_name) {
   int dir_separator_count = 0;
   for (const char* p = file_name; *p; p++) {
     if (base::OS::isDirectorySeparator(*p)) dir_separator_count++;
@@ -2032,9 +2029,8 @@ bool Logger::SetUp(Isolate* isolate) {
   is_initialized_ = true;
 
   std::ostringstream log_file_name;
-  std::ostringstream source_log_file_name;
   PrepareLogFileName(log_file_name, isolate, FLAG_logfile);
-  log_ = std::make_unique<Log>(this, log_file_name.str().c_str());
+  log_ = std::make_unique<Log>(log_file_name.str());
 
 #if V8_OS_LINUX
   if (FLAG_perf_basic_prof) {
@@ -2063,9 +2059,7 @@ bool Logger::SetUp(Isolate* isolate) {
 
   ticker_ = std::make_unique<Ticker>(isolate, FLAG_prof_sampling_interval);
 
-  if (Log::InitLogAtStart()) {
-    is_logging_ = true;
-  }
+  if (Log::InitLogAtStart()) is_logging_ = true;
 
   timer_.Start();
 
@@ -2075,9 +2069,7 @@ bool Logger::SetUp(Isolate* isolate) {
     profiler_->Engage();
   }
 
-  if (is_logging_) {
-    AddCodeEventListener(this);
-  }
+  if (is_logging_) AddCodeEventListener(this);
 
   return true;
 }
@@ -2104,6 +2096,7 @@ void Logger::SetCodeEventHandler(uint32_t options,
 }
 
 sampler::Sampler* Logger::sampler() { return ticker_.get(); }
+std::string Logger::file_name() const { return log_.get()->file_name(); }
 
 void Logger::StopProfilerThread() {
   if (profiler_ != nullptr) {
@@ -2112,14 +2105,16 @@ void Logger::StopProfilerThread() {
   }
 }
 
-FILE* Logger::TearDown() {
+FILE* Logger::TearDownAndGetLogFile() {
   if (!is_initialized_) return nullptr;
   is_initialized_ = false;
+  is_logging_ = false;
 
   // Stop the profiler thread before closing the file.
   StopProfilerThread();
 
   ticker_.reset();
+  timer_.Stop();
 
 #if V8_OS_LINUX
   if (perf_basic_logger_) {

src/logging/log.h

@@ -126,18 +126,19 @@ class Logger : public CodeEventListener {
   // Acquires resources for logging if the right flags are set.
   bool SetUp(Isolate* isolate);
 
+  // Frees resources acquired in SetUp.
+  // When a temporary file is used for the log, returns its stream descriptor,
+  // leaving the file open.
+  V8_EXPORT_PRIVATE FILE* TearDownAndGetLogFile();
+
   // Sets the current code event handler.
   void SetCodeEventHandler(uint32_t options, JitCodeEventHandler event_handler);
 
   sampler::Sampler* sampler();
+  V8_EXPORT_PRIVATE std::string file_name() const;
 
   V8_EXPORT_PRIVATE void StopProfilerThread();
 
-  // Frees resources acquired in SetUp.
-  // When a temporary file is used for the log, returns its stream descriptor,
-  // leaving the file open.
-  V8_EXPORT_PRIVATE FILE* TearDown();
-
   // Emits an event with a string value -> (name, value).
   V8_EXPORT_PRIVATE void StringEvent(const char* name, const char* value);
 

test/cctest/test-log.cc

@@ -83,8 +83,8 @@ class ScopedLoggerInitializer {
 
   ~ScopedLoggerInitializer() {
     env_->Exit();
-    logger_->TearDown();
-    if (temp_file_ != nullptr) fclose(temp_file_);
+    FILE* log_file = logger_->TearDownAndGetLogFile();
+    if (log_file != nullptr) fclose(log_file);
     i::FLAG_prof = saved_prof_;
     i::FLAG_log = saved_log_;
   }
@@ -203,9 +203,8 @@ class ScopedLoggerInitializer {
 
  private:
   FILE* StopLoggingGetTempFile() {
-    temp_file_ = logger_->TearDown();
+    temp_file_ = logger_->TearDownAndGetLogFile();
     CHECK(temp_file_);
-    fflush(temp_file_);
     rewind(temp_file_);
     return temp_file_;
   }

test/mjsunit/tools/log.js

+// Copyright 2020 the V8 project authors. All rights reserved.
+// Use of this source code is governed by a BSD-style license that can be
+// found in the LICENSE file.
+
+// Flags: --log-all --log --no-stress-opt
+
+function testFunctionWithFunnyName(o) {
+  return o.a;
+}
+
+(function testLoopWithFunnyName() {
+  const o = {a:1};
+  let result = 0;
+  for (let i = 0; i < 1000; i++) {
+    result += testFunctionWithFunnyName(o);
+  }
+})();
+
+const log = d8.log.getAndStop();
+
+// Check that we have a minimally working log file.
+assertTrue(log.length > 0);
+assertTrue(log.indexOf('v8-version') == 0);
+assertTrue(log.indexOf('testFunctionWithFunnyName') >= 10);
+assertTrue(log.indexOf('testLoopWithFunnyName') >= 10);