Fix issues with inferior stdout coming out of order

[labath]

Summary

We've had a bug where two pieces of code, executing on two threads were
attempting to write inferior output simultaneously. The first one was in
Debugger::HandleProcessEvent, which handled the cases where stdout was
coming while the process was running. The second was in
CommandInterpreter::IOHandlerInputComplete, which was ensuring that any
output is printed before the command which caused process to run
terminates.

Both of these things make sense, but the fact they were implemented as
two independent functions without any synchronization meant that race
conditions could occur (e.g. both threads call process->GetSTDOUT, get
two chunks of data, but then end up calling stream->Write in opposite
order). This was most apparent in situations where a process quickly
writes a bunch of output and then exits (as all our register tests do).

This patch adds a mutex to ensure that stdout forwarding happens
atomically. It also refactors a code somewhat in order to reduce code
duplication.

[labath]

Remove sleep, left over from testing.

[clayborg]

include/lldb/Core/Debugger.h

350

What about making this function:

void Debugger::FlushProcessOutput(Process &process, bool flush_stdout, bool flush_stderr);

Then we don't need to call this twice everywhere.

source/Core/Debugger.cpp

1418–1422

If we change FlushProcessOutput as mentioned above this would be:

FlushProcessOutput(Process &process, got_stdout || got_state_changed, got_stderr || got_state_changed);

source/Interpreter/CommandInterpreter.cpp

2712–2713

m_debugger.FlushProcessOutput(*process_sp, true, true);

[jingham]

I agree with Greg, having one function that can do any of the combinations of stdout & stderr seems more convenient.

Other than that, this is fine.

[labath]

Thanks for the feedback. Updating the patch to avoid calling the flush function twice.

include/lldb/Core/Debugger.h

protected:
   void DefaultEventHandler();
 
   void HandleBreakpointEvent(const lldb::EventSP &event_sp);
 
   void HandleProcessEvent(const lldb::EventSP &event_sp);
 
   void HandleThreadEvent(const lldb::EventSP &event_sp);
 
-  size_t GetProcessSTDOUT(Process *process, Stream *stream);
-
-  size_t GetProcessSTDERR(Process *process, Stream *stream);
+  // Ensures two threads don't attempt to flush process output in parallel.
+  std::mutex m_output_flush_mutex;
+  void FlushProcessOutput(Process &process, bool flush_stdout,
+                          bool flush_stderr);
 
   SourceManager::SourceFileCache &GetSourceFileCache() {
     return m_source_file_cache;
   }
 
   void InstanceInitialize();
 
   lldb::StreamFileSP m_input_file_sp;

include/lldb/Interpreter/CommandInterpreter.h

protected:
   ConstString IOHandlerGetControlSequence(char ch) override {
     if (ch == 'd')
       return ConstString("quit\n");
     return ConstString();
   }
 
   bool IOHandlerInterrupt(IOHandler &io_handler) override;
 
-  size_t GetProcessOutput();
+  void GetProcessOutput();
 
   void SetSynchronous(bool value);
 
   lldb::CommandObjectSP GetCommandSP(llvm::StringRef cmd,
                                      bool include_aliases = true,
                                      bool exact = true,
                                      StringList *matches = nullptr,
                                      StringList *descriptions = nullptr) const;

source/Core/Debugger.cpp

void Debugger::HandleBreakpointEvent(const EventSP &event_sp) {
   //    }
   //    else if (event_type & eBreakpointEventTypeLocationsResolved)
   //    {
   //        // This might be an interesting thing to note, but I'm going to
   //        leave it quiet for now, it just looked noisy.
   //    }
 }
 
-size_t Debugger::GetProcessSTDOUT(Process *process, Stream *stream) {
-  size_t total_bytes = 0;
-  if (stream == nullptr)
-    stream = GetOutputFile().get();
-
-  if (stream) {
-    //  The process has stuff waiting for stdout; get it and write it out to the
-    //  appropriate place.
-    if (process == nullptr) {
-      TargetSP target_sp = GetTargetList().GetSelectedTarget();
-      if (target_sp)
-        process = target_sp->GetProcessSP().get();
-    }
-    if (process) {
-      Status error;
-      size_t len;
-      char stdio_buffer[1024];
-      while ((len = process->GetSTDOUT(stdio_buffer, sizeof(stdio_buffer),
-                                       error)) > 0) {
-        stream->Write(stdio_buffer, len);
-        total_bytes += len;
-      }
-    }
-    stream->Flush();
-  }
-  return total_bytes;
-}
-
-size_t Debugger::GetProcessSTDERR(Process *process, Stream *stream) {
-  size_t total_bytes = 0;
-  if (stream == nullptr)
-    stream = GetOutputFile().get();
+void Debugger::FlushProcessOutput(Process &process, bool flush_stdout,
+                                  bool flush_stderr) {
+  const auto &flush = [&](Stream &stream,
+                          size_t (Process::*get)(char *, size_t, Status &)) {
+    char buffer[1024];
+    while ((len = (process.*get)(buffer, sizeof(buffer), error)) > 0)
+      stream.Write(buffer, len);
+    stream.Flush();
+  };
 
-  if (stream) {
-    //  The process has stuff waiting for stderr; get it and write it out to the
-    //  appropriate place.
-    if (process == nullptr) {
-      TargetSP target_sp = GetTargetList().GetSelectedTarget();
-      if (target_sp)
-        process = target_sp->GetProcessSP().get();
-    }
-    if (process) {
-      Status error;
-      size_t len;
-      char stdio_buffer[1024];
-      while ((len = process->GetSTDERR(stdio_buffer, sizeof(stdio_buffer),
-                                       error)) > 0) {
-        stream->Write(stdio_buffer, len);
-        total_bytes += len;
-      }
-    }
-    stream->Flush();
-  }
-  return total_bytes;
+  std::lock_guard<std::mutex> guard(m_output_flush_mutex);
+  if (flush_stdout)
+    flush(*GetAsyncOutputStream(), &Process::GetSTDOUT);
+  if (flush_stderr)
+    flush(*GetAsyncErrorStream(), &Process::GetSTDERR);
 }
 
 // This function handles events that were broadcast by the process.
 void Debugger::HandleProcessEvent(const EventSP &event_sp) {
   using namespace lldb;
   const uint32_t event_type = event_sp->GetType();
   ProcessSP process_sp =
       (event_type == Process::eBroadcastBitStructuredData)
if (got_state_changed) {
       state_is_stopped = StateIsStoppedState(event_state, false);
     }
 
     // Display running state changes first before any STDIO
     if (got_state_changed && !state_is_stopped) {
       Process::HandleProcessStateChangedEvent(event_sp, output_stream_sp.get(),
                                               pop_process_io_handler);
     }
 
-    // Now display and STDOUT
-    if (got_stdout || got_state_changed) {
-      GetProcessSTDOUT(process_sp.get(), output_stream_sp.get());
-    }
-
-    // Now display and STDERR
-    if (got_stderr || got_state_changed) {
-      GetProcessSTDERR(process_sp.get(), error_stream_sp.get());
-    }
+    // Now display STDOUT and STDERR
+    FlushProcessOutput(*process_sp, got_stdout || got_state_changed,
+                       got_stderr || got_state_changed);
 
     // Give structured data events an opportunity to display.
     if (got_structured_data) {
       StructuredDataPluginSP plugin_sp =
           EventDataStructuredData::GetPluginFromEvent(event_sp.get());
       if (plugin_sp) {
         auto structured_data_sp =
             EventDataStructuredData::GetObjectFromEvent(event_sp.get());
         if (output_stream_sp) {

source/Interpreter/CommandInterpreter.cpp

if (override_context != nullptr) {
     m_exe_ctx_ref = *override_context;
   } else {
     const bool adopt_selected = true;
     m_exe_ctx_ref.SetTargetPtr(m_debugger.GetSelectedTarget().get(),
                                adopt_selected);
   }
 }
 
-size_t CommandInterpreter::GetProcessOutput() {
-  //  The process has stuff waiting for stderr; get it and write it out to the
-  //  appropriate place.
-  char stdio_buffer[1024];
-  size_t len;
-  size_t total_bytes = 0;
-  Status error;
+void CommandInterpreter::GetProcessOutput() {
   TargetSP target_sp(m_debugger.GetTargetList().GetSelectedTarget());
-  if (target_sp) {
-    ProcessSP process_sp(target_sp->GetProcessSP());
-    if (process_sp) {
-      while ((len = process_sp->GetSTDOUT(stdio_buffer, sizeof(stdio_buffer),
-                                          error)) > 0) {
-        size_t bytes_written = len;
-        m_debugger.GetOutputFile()->Write(stdio_buffer, bytes_written);
-        total_bytes += len;
-      }
-      while ((len = process_sp->GetSTDERR(stdio_buffer, sizeof(stdio_buffer),
-                                          error)) > 0) {
-        size_t bytes_written = len;
-        m_debugger.GetErrorFile()->Write(stdio_buffer, bytes_written);
-        total_bytes += len;
-      }
-    }
-  }
-  return total_bytes;
+  if (!target_sp)
+    return;
+
+  if (ProcessSP process_sp = target_sp->GetProcessSP())
+    m_debugger.FlushProcessOutput(*process_sp, /*flush_stdout*/ true,
+                                  /*flush_stderr*/ true);
 }
 
 void CommandInterpreter::StartHandlingCommand() {
   auto idle_state = CommandHandlingState::eIdle;
   if (m_command_state.compare_exchange_strong(
           idle_state, CommandHandlingState::eInProgress))
     lldbassert(m_iohandler_nesting_level == 0);
   else
     lldbassert(m_iohandler_nesting_level > 0);
   ++m_iohandler_nesting_level;