Uploaded image for project: 'Core Server'
  1. Core Server
  2. SERVER-42823

Output between print() function and ProgramOutputMultiplexer::appendLine() can be interleaved, leading to a deadlock on Windows DEBUG

    XMLWordPrintable

    Details

    • Type: Bug
    • Status: Blocked
    • Priority: Major - P3
    • Resolution: Unresolved
    • Affects Version/s: None
    • Fix Version/s: None
    • Component/s: Shell
    • Labels:
      None
    • Operating System:
      ALL
    • Steps To Reproduce:
      Hide

      python buildscripts/resmoke.py --suite=no_server repro_interleaved_output.js | sed 's/x\+/xxx/g'
      

      repro_interleaved_output.js

      (function() {
          'use strict';
       
          // _INTERNAL_BUFSIZ=4096 is the default buffer size for streams on Windows.
          TestData.largeStr = 'x'.repeat(4096);
       
          const awaitShell = startParallelShell(function() {
              while (true) {
                  print(`inside parallel shell: ${TestData.largeStr}`);
              }
          }, undefined, true);
       
          while (true) {
              print(`main shell: ${TestData.largeStr}`);
          }
      })();
      

      Show
      python buildscripts/resmoke.py --suite=no_server repro_interleaved_output.js | sed 's/x\+/xxx/g' repro_interleaved_output.js ( function () { 'use strict' ;   // _INTERNAL_BUFSIZ=4096 is the default buffer size for streams on Windows. TestData.largeStr = 'x' .repeat(4096);   const awaitShell = startParallelShell( function () { while ( true ) { print(`inside parallel shell: ${TestData.largeStr}`); } }, undefined, true );   while ( true ) { print(`main shell: ${TestData.largeStr}`); } })();
    • Sprint:
      Dev Tools 2019-08-26, Dev Tools 2019-09-09, Dev Tools 2020-02-10
    • Linked BF Score:
      14

      Description

      The print() function acquires the ShellConsoleAppender::mx mutex when writing to std::cout as part of the LogstreamBuilder going out of scope. The ProgramOutputMultiplexer::appendLine() function is holding the mongoProgramOutputMutex mutex when writing directly to std::cout. This allows the main thread in the mongo shell to be writing text to std::cout in the print() function while a ProgramRunner reader thread is writing subprocess output to std::cout.

      Interleaving the writes to std::cout from these two different threads corrupts the underlying output stream. It causes the following assertion to fire on --dbg=on builds on Windows.

      // Write blocks of data from the buffer until there is no more data left:
      size_t remaining_bytes = total_bytes;
      while (remaining_bytes != 0)
      {
          // If the buffer is big and is not full, copy data into the buffer:
          if (stream.has_big_buffer() && stream->_cnt != 0)
          {
              if (stream->_cnt < 0)
              {
                  _ASSERTE(("Inconsistent Stream Count. Flush between consecutive read and write", stream->_cnt >= 0));
                  stream.set_flags(_IOERROR);
                  return (total_bytes - remaining_bytes) / element_size;
              }
      

      Since the crtDebugCallback() function also calls log(), we actually end up hanging because the main thread calling print() is holding the ShellConsoleAppender::mx mutex and waiting for the critical section on std::cout, but the ProgramRunner read thread which triggered the callback is holding the critical section on std::cout and is blocked trying to acquire the ShellConsoleAppender::mx mutex.


      [js_test:repro_interleaved_output] 2019-08-14T20:56:14.922+0100 main shell: xxx
      [js_test:repro_interleaved_output] 2019-08-14T20:56:14.922+0100 sh2676| inside parallel shell: xxxmain shell: xxx
      [js_test:repro_interleaved_output] 2019-08-14T20:56:14.923+0100 xxx
      [js_test:repro_interleaved_output] 2019-08-14T20:56:14.923+0100 main shell: xxx
      [js_test:repro_interleaved_output] 2019-08-14T20:56:14.923+0100 main shell: xxx
      

        Attachments

          Issue Links

            Activity

              People

              • Votes:
                1 Vote for this issue
                Watchers:
                9 Start watching this issue

                Dates

                • Created:
                  Updated: