Why are two exceptions thrown when using subprocess.run()?

Question

I am using python subprocess.run() to process some command. I want to capture output/error/return code, and want to have timeout if the command is blocked. The code is simple:

cmd = "ping 1.1.1.1 -n 5"
subprocess.run(cmd, shell=True, timeout=2)

But the result confuses me, why are two exception thrown?

Python 3.6.8 (default, Jan 14 2019, 11:02:34) 
[GCC 8.0.1 20180414 (experimental) [trunk revision 259383]] on linux
Type "help", "copyright", "credits" or "license" for more information.
>>> import subprocess
>>> cmd = "ping 1.1.1.1 -n 5"
>>> subprocess.run(cmd, shell=True, timeout=2)
PING 5 (0.0.0.5) 56(124) bytes of data.
Traceback (most recent call last):
  File "/usr/lib/python3.6/subprocess.py", line 425, in run
    stdout, stderr = process.communicate(input, timeout=timeout)
  File "/usr/lib/python3.6/subprocess.py", line 863, in communicate
    stdout, stderr = self._communicate(input, endtime, timeout)
  File "/usr/lib/python3.6/subprocess.py", line 1560, in _communicate
    self.wait(timeout=self._remaining_time(endtime))
  File "/usr/lib/python3.6/subprocess.py", line 1469, in wait
    raise TimeoutExpired(self.args, timeout)
subprocess.TimeoutExpired: Command 'ping 1.1.1.1 -n 5' timed out after 1.999514610040933 seconds

During handling of the above exception, another exception occurred:

Traceback (most recent call last):
  File "<stdin>", line 1, in <module>
  File "/usr/lib/python3.6/subprocess.py", line 430, in run
    stderr=stderr)
subprocess.TimeoutExpired: Command 'ping 1.1.1.1 -n 5' timed out after 2 seconds
>>> 

Answer 1

You're not handling the exception of subprocess.run(). The Python documentation for subprocess contains a similar example, and it also shows a traceback:

>>> subprocess.run("exit 1", shell=True, check=True)
Traceback (most recent call last):
  ...
subprocess.CalledProcessError: Command 'exit 1' returned non-zero exit status 1

Because you're not handling the exception, python is giving you tracebacks as it fails out. Since you're intentionally looking for exceptions (TimeoutExpired), you'll need to handle it. Here's an example for your command:

import sys
import subprocess

f = open('output.txt', 'w') # store stdout
g = open('error.txt', 'w') # store stderr

cmd = "ping 8.8.8.8 -n -c 5"

try:
    subprocess.run(cmd, shell=True, check=False, stdout=f, stderr=g timeout=2)
except subprocess.TimeoutExpired as t:
    print("Timeout expired!")
    print(t.timeout)

The output from this is:

Timeout expired!
2

The 2 is the timeout threshold -- subprocess.TimeoutExpired has other attributes you could print::

cmd
    Command that was used to spawn the child process.
timeout
    Timeout in seconds.
output
    Output of the child process if it was captured by run() or check_output(). Otherwise, None.
stdout
    Alias for output, for symmetry with stderr.
stderr
    Stderr output of the child process if it was captured by run(). Otherwise, None.

I created output.txt and error.txt in my local directory to catch stdout and stderr, which answers the other part of your ask, how to record the command's output and error as well as the timeout.

Answer 2

if you want a certain number of pings, then the option is 'c'. if you want a timeout to the ping command, the option is 'w'.

>>> subprocess.run("ping -w 3 127.0.0.1".split())
PING 127.0.0.1 (127.0.0.1) 56(84) bytes of data.
64 bytes from 127.0.0.1: icmp_seq=1 ttl=64 time=0.100 ms
64 bytes from 127.0.0.1: icmp_seq=2 ttl=64 time=0.125 ms
64 bytes from 127.0.0.1: icmp_seq=3 ttl=64 time=0.052 ms

--- 127.0.0.1 ping statistics ---
3 packets transmitted, 3 received, 0% packet loss, time 2000ms
rtt min/avg/max/mdev = 0.052/0.092/0.125/0.031 ms
CompletedProcess(args=['ping', '-w', '3', '127.0.0.1'], returncode=0)

wrapping in a try/except means that it doesn't matter if there are multiple exceptions:

>>> try:
...   subprocess.run("ping 127.0.0.1".split(), timeout=2)
... except subprocess.TimeoutExpired:
...   print('handle')
... 
PING 127.0.0.1 (127.0.0.1) 56(84) bytes of data.
64 bytes from 127.0.0.1: icmp_seq=1 ttl=64 time=0.094 ms
64 bytes from 127.0.0.1: icmp_seq=2 ttl=64 time=0.163 ms
handle

Answer 3

I've had similar problem. But I've caused it myself - on behalf of good IDE advice :-D. I've handled TimeoutExpired properly, but at the end of except block I've risen another exception and used from. It has risen TimeoutExpired too which was not handled again.

try:
    check_output(...)
except subprocess.TimeoutExpired as problem:
    # some logging stuff
    raise ConnectionError("Some useful info") from problem