|
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.
|
fwrite.cpp
|
// 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
|
|