Repository: pytorch
Issue: ProcessGroupGlooTest and other distributed tests don't capture stdout/stderr in test UI view
Labels: oncall: distributed

Here is a distributed test failure in CI https://app.circleci.com/pipelines/github/pytorch/pytorch/301716/workflows/cb3d7c0f-6dc1-40b6-9ae7-5294e24206c8/jobs/12415307/tests

![image](https://user-images.githubusercontent.com/13564/114808762-e7777700-9d76-11eb-8f0a-39da51f3b927.png)

If you believed the test UI view, you'd think this was the only information about the test available. But this is not true. In logs:

<details>

```
Apr 14 22:48:38   test_dist_optim_exception (__main__.ProcessGroupDistOptimizerTestWithSpawn) ... /Users/distiller/workspace/miniconda3/lib/python3.7/site-packages/torch/distributed/rpc/__init__.py:158: UserWarning: RPC was initialized with the PROCESS_GROUP backend which is deprecated and slated to be removed and superseded by the TENSORPIPE backend. It is recommended to migrate to the TENSORPIPE backend. PyTorch v1.9 will be the last release that carries PROCESS_GROUP RPC backend. If you have concerns or suggestions please comment in https://github.com/pytorch/pytorch/issues/55615
Apr 14 22:48:38   "RPC was initialized with the PROCESS_GROUP backend which is "
Apr 14 22:48:38 /Users/distiller/workspace/miniconda3/lib/python3.7/site-packages/torch/distributed/rpc/__init__.py:158: UserWarning: RPC was initialized with the PROCESS_GROUP backend which is deprecated and slated to be removed and superseded by the TENSORPIPE backend. It is recommended to migrate to the TENSORPIPE backend. PyTorch v1.9 will be the last release that carries PROCESS_GROUP RPC backend. If you have concerns or suggestions please comment in https://github.com/pytorch/pytorch/issues/55615
Apr 14 22:48:38   "RPC was initialized with the PROCESS_GROUP backend which is "
Apr 14 22:48:38 /Users/distiller/workspace/miniconda3/lib/python3.7/site-packages/torch/distributed/rpc/__init__.py:158: UserWarning: RPC was initialized with the PROCESS_GROUP backend which is deprecated and slated to be removed and superseded by the TENSORPIPE backend. It is recommended to migrate to the TENSORPIPE backend. PyTorch v1.9 will be the last release that carries PROCESS_GROUP RPC backend. If you have concerns or suggestions please comment in https://github.com/pytorch/pytorch/issues/55615
Apr 14 22:48:38   "RPC was initialized with the PROCESS_GROUP backend which is "
Apr 14 22:48:38 /Users/distiller/workspace/miniconda3/lib/python3.7/site-packages/torch/distributed/rpc/__init__.py:158: UserWarning: RPC was initialized with the PROCESS_GROUP backend which is deprecated and slated to be removed and superseded by the TENSORPIPE backend. It is recommended to migrate to the TENSORPIPE backend. PyTorch v1.9 will be the last release that carries PROCESS_GROUP RPC backend. If you have concerns or suggestions please comment in https://github.com/pytorch/pytorch/issues/55615
Apr 14 22:48:38   "RPC was initialized with the PROCESS_GROUP backend which is "
Apr 14 22:48:38 Creating the optimizer <class 'torch.testing._internal.distributed.rpc.dist_optimizer_test.FailingOptimizer'> without TorchScript support, this might result in slow computation time in multithreading environment(i.e. Distributed Model Parallel training on CPU) due to the Python's Global Interpreter Lock (GIL). Please file an issue if you need this optimizer in TorchScript. 
Apr 14 22:48:38 Creating the optimizer <class 'torch.testing._internal.distributed.rpc.dist_optimizer_test.FailingOptimizer'> without TorchScript support, this might result in slow computation time in multithreading environment(i.e. Distributed Model Parallel training on CPU) due to the Python's Global Interpreter Lock (GIL). Please file an issue if you need this optimizer in TorchScript. 
Apr 14 22:48:38 Creating the optimizer <class 'torch.testing._internal.distributed.rpc.dist_optimizer_test.FailingOptimizer'> without TorchScript support, this might result in slow computation time in multithreading environment(i.e. Distributed Model Parallel training on CPU) due to the Python's Global Interpreter Lock (GIL). Please file an issue if you need this optimizer in TorchScript. 
Apr 14 22:48:38 Creating the optimizer <class 'torch.testing._internal.distributed.rpc.dist_optimizer_test.FailingOptimizer'> without TorchScript support, this might result in slow computation time in multithreading environment(i.e. Distributed Model Parallel training on CPU) due to the Python's Global Interpreter Lock (GIL). Please file an issue if you need this optimizer in TorchScript. 
Apr 14 22:48:38 On WorkerInfo(id=3, name=worker3):
Apr 14 22:48:38 ValueError('Error running optimizer.')
Apr 14 22:48:38 Traceback (most recent call last):
Apr 14 22:48:38   File "/Users/distiller/workspace/miniconda3/lib/python3.7/site-packages/torch/distributed/rpc/internal.py", line 193, in _run_function
Apr 14 22:48:38     result = python_udf.func(*python_udf.args, **python_udf.kwargs)
Apr 14 22:48:38   File "/Users/distiller/workspace/miniconda3/lib/python3.7/site-packages/torch/distributed/optim/optimizer.py", line 100, in _local_optimizer_step
Apr 14 22:48:38     local_optim.step(autograd_ctx_id)
Apr 14 22:48:38   File "/Users/distiller/workspace/miniconda3/lib/python3.7/site-packages/torch/distributed/optim/optimizer.py", line 90, in step
Apr 14 22:48:38     self.optim.step()
Apr 14 22:48:38   File "/Users/distiller/workspace/miniconda3/lib/python3.7/site-packages/torch/optim/optimizer.py", line 88, in wrapper
Apr 14 22:48:38     return func(*args, **kwargs)
Apr 14 22:48:38   File "/Users/distiller/workspace/miniconda3/lib/python3.7/site-packages/torch/testing/_internal/distributed/rpc/dist_optimizer_test.py", line 39, in step
Apr 14 22:48:38     raise ValueError("Error running optimizer.")
Apr 14 22:48:38 ValueError: Error running optimizer.
Apr 14 22:48:38 
Apr 14 22:48:38 On WorkerInfo(id=2, name=worker2):
Apr 14 22:48:38 ValueError('Error running optimizer.')
Apr 14 22:48:38 Traceback (most recent call last):
Apr 14 22:48:38   File "/Users/distiller/workspace/miniconda3/lib/python3.7/site-packages/torch/distributed/rpc/internal.py", line 193, in _run_function
Apr 14 22:48:38     result = python_udf.func(*python_udf.args, **python_udf.kwargs)
Apr 14 22:48:38   File "/Users/distiller/workspace/miniconda3/lib/python3.7/site-packages/torch/distributed/optim/optimizer.py", line 100, in _local_optimizer_step
Apr 14 22:48:38     local_optim.step(autograd_ctx_id)
Apr 14 22:48:38   File "/Users/distiller/workspace/miniconda3/lib/python3.7/site-packages/torch/distributed/optim/optimizer.py", line 90, in step
Apr 14 22:48:38     self.optim.step()
Apr 14 22:48:38   File "/Users/distiller/workspace/miniconda3/lib/python3.7/site-packages/torch/optim/optimizer.py", line 88, in wrapper
Apr 14 22:48:38     return func(*args, **kwargs)
Apr 14 22:48:38   File "/Users/distiller/workspace/miniconda3/lib/python3.7/site-packages/torch/testing/_internal/distributed/rpc/dist_optimizer_test.py", line 39, in step
Apr 14 22:48:38     raise ValueError("Error running optimizer.")
Apr 14 22:48:38 ValueError: Error running optimizer.
Apr 14 22:48:38 
Apr 14 22:48:38 On WorkerInfo(id=3, name=worker3):
Apr 14 22:48:38 ValueError('Error running optimizer.')
Apr 14 22:48:38 Traceback (most recent call last):
Apr 14 22:48:38   File "/Users/distiller/workspace/miniconda3/lib/python3.7/site-packages/torch/distributed/rpc/internal.py", line 193, in _run_function
Apr 14 22:48:38     result = python_udf.func(*python_udf.args, **python_udf.kwargs)
Apr 14 22:48:38   File "/Users/distiller/workspace/miniconda3/lib/python3.7/site-packages/torch/distributed/optim/optimizer.py", line 100, in _local_optimizer_step
Apr 14 22:48:38     local_optim.step(autograd_ctx_id)
Apr 14 22:48:38   File "/Users/distiller/workspace/miniconda3/lib/python3.7/site-packages/torch/distributed/optim/optimizer.py", line 90, in step
Apr 14 22:48:38     self.optim.step()
Apr 14 22:48:38   File "/Users/distiller/workspace/miniconda3/lib/python3.7/site-packages/torch/optim/optimizer.py", line 88, in wrapper
Apr 14 22:48:38     return func(*args, **kwargs)
Apr 14 22:48:38   File "/Users/distiller/workspace/miniconda3/lib/python3.7/site-packages/torch/testing/_internal/distributed/rpc/dist_optimizer_test.py", line 39, in step
Apr 14 22:48:38     raise ValueError("Error running optimizer.")
Apr 14 22:48:38 ValueError: Error running optimizer.
Apr 14 22:48:38 
Apr 14 22:48:38 On WorkerInfo(id=0, name=worker0):
Apr 14 22:48:38 ValueError('Error running optimizer.')
Apr 14 22:48:38 Traceback (most recent call last):
Apr 14 22:48:38   File "/Users/distiller/workspace/miniconda3/lib/python3.7/site-packages/torch/distributed/rpc/internal.py", line 193, in _run_function
Apr 14 22:48:38     result = python_udf.func(*python_udf.args, **python_udf.kwargs)
Apr 14 22:48:38   File "/Users/distiller/workspace/miniconda3/lib/python3.7/site-packages/torch/distributed/optim/optimizer.py", line 100, in _local_optimizer_step
Apr 14 22:48:38     local_optim.step(autograd_ctx_id)
Apr 14 22:48:38   File "/Users/distiller/workspace/miniconda3/lib/python3.7/site-packages/torch/distributed/optim/optimizer.py", line 90, in step
Apr 14 22:48:38     self.optim.step()
Apr 14 22:48:38   File "/Users/distiller/workspace/miniconda3/lib/python3.7/site-packages/torch/optim/optimizer.py", line 88, in wrapper
Apr 14 22:48:38     return func(*args, **kwargs)
Apr 14 22:48:38   File "/Users/distiller/workspace/miniconda3/lib/python3.7/site-packages/torch/testing/_internal/distributed/rpc/dist_optimizer_test.py", line 39, in step
Apr 14 22:48:38     raise ValueError("Error running optimizer.")
Apr 14 22:48:38 ValueError: Error running optimizer.
Apr 14 22:48:38 
Apr 14 22:48:38 On WorkerInfo(id=0, name=worker0):
Apr 14 22:48:38 ValueError('Error running optimizer.')
Apr 14 22:48:38 Traceback (most recent call last):
Apr 14 22:48:38   File "/Users/distiller/workspace/miniconda3/lib/python3.7/site-packages/torch/distributed/rpc/internal.py", line 193, in _run_function
Apr 14 22:48:38     result = python_udf.func(*python_udf.args, **python_udf.kwargs)
Apr 14 22:48:38   File "/Users/distiller/workspace/miniconda3/lib/python3.7/site-packages/torch/distributed/optim/optimizer.py", line 100, in _local_optimizer_step
Apr 14 22:48:38     local_optim.step(autograd_ctx_id)
Apr 14 22:48:38   File "/Users/distiller/workspace/miniconda3/lib/python3.7/site-packages/torch/distributed/optim/optimizer.py", line 90, in step
Apr 14 22:48:38     self.optim.step()
Apr 14 22:48:38   File "/Users/distiller/workspace/miniconda3/lib/python3.7/site-packages/torch/optim/optimizer.py", line 88, in wrapper
Apr 14 22:48:38     return func(*args, **kwargs)
Apr 14 22:48:38   File "/Users/distiller/workspace/miniconda3/lib/python3.7/site-packages/torch/testing/_internal/distributed/rpc/dist_optimizer_test.py", line 39, in step
Apr 14 22:48:38     raise ValueError("Error running optimizer.")
Apr 14 22:48:38 ValueError: Error running optimizer.
Apr 14 22:48:38 
Apr 14 22:48:38 On WorkerInfo(id=1, name=worker1):
Apr 14 22:48:38 ValueError('Error running optimizer.')
Apr 14 22:48:38 Traceback (most recent call last):
Apr 14 22:48:38   File "/Users/distiller/workspace/miniconda3/lib/python3.7/site-packages/torch/distributed/rpc/internal.py", line 193, in _run_function
Apr 14 22:48:38     result = python_udf.func(*python_udf.args, **python_udf.kwargs)
Apr 14 22:48:38   File "/Users/distiller/workspace/miniconda3/lib/python3.7/site-packages/torch/distributed/optim/optimizer.py", line 100, in _local_optimizer_step
Apr 14 22:48:38     local_optim.step(autograd_ctx_id)
Apr 14 22:48:38   File "/Users/distiller/workspace/miniconda3/lib/python3.7/site-packages/torch/distributed/optim/optimizer.py", line 90, in step
Apr 14 22:48:38     self.optim.step()
Apr 14 22:48:38   File "/Users/distiller/workspace/miniconda3/lib/python3.7/site-packages/torch/optim/optimizer.py", line 88, in wrapper
Apr 14 22:48:38     return func(*args, **kwargs)
Apr 14 22:48:38   File "/Users/distiller/workspace/miniconda3/lib/python3.7/site-packages/torch/testing/_internal/distributed/rpc/dist_optimizer_test.py", line 39, in step
Apr 14 22:48:38     raise ValueError("Error running optimizer.")
Apr 14 22:48:38 ValueError: Error running optimizer.
Apr 14 22:48:38 
Apr 14 22:49:38 Caught exception: 
Apr 14 22:49:38 Traceback (most recent call last):
Apr 14 22:49:38   File "/Users/distiller/workspace/miniconda3/lib/python3.7/site-packages/torch/testing/_internal/common_distributed.py", line 441, in run_test
Apr 14 22:49:38     getattr(self, test_name)()
Apr 14 22:49:38   File "/Users/distiller/workspace/miniconda3/lib/python3.7/site-packages/torch/testing/_internal/common_distributed.py", line 324, in wrapper
Apr 14 22:49:38     fn()
Apr 14 22:49:38   File "/Users/distiller/workspace/miniconda3/lib/python3.7/site-packages/torch/testing/_internal/dist_utils.py", line 91, in new_test_method
Apr 14 22:49:38     return_value = old_test_method(self, *arg, **kwargs)
Apr 14 22:49:38   File "/Users/distiller/workspace/miniconda3/lib/python3.7/site-packages/torch/testing/_internal/distributed/rpc/dist_optimizer_test.py", line 120, in test_dist_optim_exception
Apr 14 22:49:38     dist_autograd.backward(context_id, [loss])
Apr 14 22:49:38 RuntimeError: Error on Node 0: RPCErr:1:RPC ran for more than set timeout (60000 ms) and will now be marked with an error
Apr 14 22:49:38  exiting process with exit code: {MultiProcessTestCase.TEST_ERROR_EXIT_CODE}
Apr 14 22:49:39 Process 0 terminated with exit code 10, terminating remaining processes.
Apr 14 22:49:39 ERROR (61.983s)
```

</details>

There's a decent about of stderr/stdout spam that could be used to diagnose problems. But it's not reflected in the CircleCI UI! This should be fixed.

cc @pietern @mrshenli @pritamdamania87 @zhaojuanmao @satgera @rohan-varma @gqchen @aazzolini @osalpekar @jiayisuse @agolynski @SciPioneer @H-Huang @mrzzd @cbalioglu @malfet