Calling BCP from python throws timeout exception, then immediately completes

Question

I am running a python script that calls a subprocess. It times out, and then immediately I see the sub-process (in this case a BCP call) finish. Indeed, I can see it's complete in the database. Additionally, I can run the BCP command directly on the command line, and it works just fine.

Here's what my python script spits out to the command prompt:

C:\FaceIAPS\StudyDataFiles> py .\RUN_DATA.py
Synchronizing 80 subjects
Subject 11

Starting copy...
Traceback (most recent call last):
  File ".\RUN_DATA.py", line 261, in <module>
    bulk_import(upload_file, 'Facet_Data')
  File ".\RUN_DATA.py", line 171, in bulk_import
    subprocess.check_call("bcp BehaviorResearch.." + table_to_upload_to + " in " +     filename_to_be_uploaded + " -T -c -S
PBB-C202B-2\BEHAVIORRESEARCH -e bulk_copy_errors.log", shell=True, timeout=5)
  File "C:\Python34\lib\subprocess.py", line 554, in check_call
    retcode = call(*popenargs, **kwargs)
  File "C:\Python34\lib\subprocess.py", line 537, in call
    return p.wait(timeout=timeout)
  File "C:\Python34\lib\subprocess.py", line 1157, in wait
    raise TimeoutExpired(self.args, timeout)
subprocess.TimeoutExpired: Command 'bcp BehaviorResearch..Facet_Data in _temp_ -T -c -S     PBB-C202B-2\BEHAVIORRESEARCH -e
bulk_copy_errors.log' timed out after 5 seconds
1000 rows sent to SQL Server. Total sent: 1000
1000 rows sent to SQL Server. Total sent: 2000
PS C:\FaceIAPS\StudyDataFiles> 1000 rows sent to SQL Server. Total sent: 3000
1000 rows sent to SQL Server. Total sent: 4000
1000 rows sent to SQL Server. Total sent: 5000
1000 rows sent to SQL Server. Total sent: 6000
1000 rows sent to SQL Server. Total sent: 7000
1000 rows sent to SQL Server. Total sent: 8000
1000 rows sent to SQL Server. Total sent: 9000
1000 rows sent to SQL Server. Total sent: 10000
1000 rows sent to SQL Server. Total sent: 11000
1000 rows sent to SQL Server. Total sent: 12000
1000 rows sent to SQL Server. Total sent: 13000
1000 rows sent to SQL Server. Total sent: 14000
1000 rows sent to SQL Server. Total sent: 15000
1000 rows sent to SQL Server. Total sent: 16000

16102 rows copied.
Network packet size (bytes): 4096
Clock Time (ms.) Total     : 5164   Average : (3118.13 rows per sec.)

As you can see, the command prompt has been split up with the output of the BCP call.
What's going on, and how do I fix it?

EDIT: How I fixed it

Change the subprocess call to:

arguments = ["bcp", "BehaviorResearch.." + table_to_upload_to, "in", filename_to_be_uploaded, "-T", "-c", "-S PBB-C202B-2\BEHAVIORRESEARCH", "-e bulk_copy_errors.log"]
subprocess.call(arguments, timeout=30)

As an FYI for the uninitiated, "in" is it's own argument.

Answer 1

The docs for subprocess.check_call() say:

The timeout argument is passed to Popen.wait(). If the timeout expires, the child process will be killed and then waited for again. The TimeoutExpired exception will be re-raised after the child process has terminated.

The subprocess source code confirms it:

def call(*popenargs, timeout=None, **kwargs):
    with Popen(*popenargs, **kwargs) as p:
        try:
            return p.wait(timeout=timeout)
        except:
            p.kill() # kill on any exception including TimeoutExpired
            p.wait()
            raise

i.e., what you see is the expected behaviour: if the timeout happens then the shell (%COMSPEC% or cmd.exe) that runs the bcp process should be terminated promptly that in turn might terminate the bcp process itself.

You see the buffered output being flushed in the console after the subprocess already exited or (I'm not sure) you see the output from the alive grandchild bcp process while its parent cmd.exe already finished (the new prompt is shown).

Remove shell=True to avoid creating unnecessary intermediate cmd.exe process so that .kill() is called on the bcp process directly instead of the shell process.