bugpyFormex - Bugs: bug #40566, timeout in runCommand (system) is...

 
 

bug #40566: timeout in runCommand (system) is not working

Submitted by:  gianluca de santis <gianlucadesi>
Submitted on:  Wed 13 Nov 2013 02:22:13 PM UTC  
 
Category: CoreSeverity: 4 - Important
Item Group: Functionality errorStatus: Fixed
Privacy: PublicAssigned to: Benedict Verhegghe <bverheg>
Open/Closed: Closed

Add a New Comment(Rich Markup)
   

You are not logged in

Please log in, so followups can be emailed to you.

 

(Jump to the original submission Jump to the original submission)

Fri 15 Nov 2013 09:19:00 PM UTC, comment #14:

In be61e27, the suggestion of comment 13 has been implemented.

When a command fails to execute, the Process attribute 'failed' is set True.

A new utils.command function provides the user-oriented defaults to system. runCommand use is deprecated and will be replaced with proper command calls.

Please test these new functions.

Benedict Verhegghe <bverheg>
Project AdministratorIn charge of this item.
Fri 15 Nov 2013 07:28:20 PM UTC, comment #13:

The default 'shell=False' of the system command causes an extra problem: when the command specifies a non-existing excutable, and exception is raised by the Python subprocess.Popen.__init__, while with shell=True, subprocess will spawn a shell, which will return with an error code, but no exception. The latter behavior is what we want, so we should encapsulate the Popen.__init__ in a try...except, and create a proper error status.

Benedict Verhegghe <bverheg>
Project AdministratorIn charge of this item.
Fri 15 Nov 2013 05:01:23 PM UTC, comment #12:

The extra time.sleep is implemented in 666224d.
Ready for test.

I leave the bug open until the final fix with another variable
is implemented.

Benedict Verhegghe <bverheg>
Project AdministratorIn charge of this item.
Fri 15 Nov 2013 04:51:21 PM UTC, comment #11:

I reopened the bug, because there is a remaining problem: the return code after a timeout is not correctly set.

It looks like a timing problem: the P.run() in system() can return as soon as P.terminate() or P.kill() is executed, and the timeout terminate() function may not have the time to push the correct returncode before system() already returns and runCommand already checks it.

Adding a 'time.sleep(0.3)' before the return P in system() solves the problem.

I intend however to put most of the code inside the Process class, and use another variable than the returncode to flag the timeout condition. Then we can set that condition before calling P.terminate/P.kill, and the normal returncode can be kept, while runCommand can test the new variable for a timeout condition.

Furthermore, runCommand should either disappear (and the 'verbose' argument moved into system) or just be a wrapper around system, adding the 'verbose' argument.

Benedict Verhegghe <bverheg>
Project AdministratorIn charge of this item.
Fri 15 Nov 2013 02:51:30 PM UTC, comment #10:

In commit 034adbe, this issue is fixed as proposed in comment 8.

Benedict Verhegghe <bverheg>
Project AdministratorIn charge of this item.
Fri 15 Nov 2013 02:49:24 PM UTC, comment #9:

Fully agree!

gianluca de santis <gianlucadesi>
Project Member
Fri 15 Nov 2013 02:44:44 PM UTC, comment #8:

The setting of the return code should indeed be done after the poll. In a moment of insanity I had removed the first setting, not having noticed the difference between EXITCODE and KILLCODE.

So, I think the correct way to set the codes should be like this:

So, in each case the returncode is only set at the end, and it is only set to _TIMEOUT_KILLCODE when a kill has been executed. In all other cases it will be _TIMEOUT_EXITCODE.

Benedict Verhegghe <bverheg>
Project AdministratorIn charge of this item.
Fri 15 Nov 2013 02:35:45 PM UTC, comment #7:

The custom return codes are needed to detect that the command indeed was terminated because of a timeout, and not by some other cause. There are plenty of ways to terminate or kill a process (CTRL-C, close window, some error, kill command, ...).

Benedict Verhegghe <bverheg>
Project AdministratorIn charge of this item.
Fri 15 Nov 2013 02:04:44 PM UTC, comment #6:

In utils the
_TIMEOUT_EXITCODE = -1015
_TIMEOUT_KILLCODE = -1009
are probably not needed: pyhon assigns -15 and -9 in case of terminated and kill. So why should be use different codes?

Also, in terminate(), p.kill() should kill a subprocess which was not terminated by p.terminate(). Such a case is detected using

if p.poll() is None ...

However, when assigning

p.returncode = _TIMEOUT_EXITCODE

the p.poll() is no longer None, so the p.kill will never be executed.

Therefore,
I suggest to change the terminate() as:

def terminate(p):
"""Terminate a subprocess when it times out"""
if p.poll() is None:
# Process is not terminated yet
print("Subprocess terminated due to timeout (%ss)" % timeout)
p.terminate()#this assigns a p.returncode=-15
time.sleep(0.1)
if p.poll() is None:
# Give the process 2 seconds to terminate, then kill it
time.sleep(gracetime)
if p.poll() is None:
print("Subprocess killed")
p.kill()#this assigns a p.returncode =-9

Am I wrong?

gianluca de santis <gianlucadesi>
Project Member
Thu 14 Nov 2013 06:56:05 PM UTC, comment #5:

In commit 258ac0b we changed the return value of utils.system to a Process instance, from which the required information can then
be found thus:

utils.system now also allows setting stdout and stderr to another
value than PIPE, e.g. an open file. Then no redirection is needed anymore and shell=False can be used.

See the commit message for more info.

Todo:
- add group kill for shell=True case
- expose stdout, stderr to runCommand function
- maybe also change return value of runCommand, or add the verbose functionality of runCommand into utils.system and deprecate runCommand?

Benedict Verhegghe <bverheg>
Project AdministratorIn charge of this item.
Thu 14 Nov 2013 11:35:35 AM UTC, comment #4:

Exposing the shell variable in runCommand is certainly a good idea. Then we can fix those places that currently do not work.
But we should also try to find out why they do not work.

One possible reason could be some environment variable (like PATH) being different in your current and default environments.
Such things can be fixed by addding the proper env argument to the Popen constructor.

From a look at one of the mentioned cases, the reason however seems to be the use of I/O redirection in the commands (e.g. using a '>' in the command). This redirection is indeed shell stuff, and needs a shell to execute. We can temporarily fix it with shell=True (and make shell processes interruptable with the session group technique as mentioned in comment #1).

But it could also be solved in another way, by changing the command to not need the redirection. The output of the gts command is now redirected to a file, and then read back. but we could just as well directly get the output from the command and read from that. It would save creating a temporary file (which is left cluttering /var/tmp).

In an effort to optimize the execution of external commands, I think it would be good to let the utils.system function not return a tuple sta,out,err, but just a single class instance (probably just the Popen or a subclass thereof), from which the caller can then get what he needs: return_code, stdout, stderr,
etc.

Benedict Verhegghe <bverheg>
Project AdministratorIn charge of this item.
Thu 14 Nov 2013 09:00:42 AM UTC, comment #3:

Another problem: (some) gts functions do not work if shell is False.

Try example Inside
Try example Boolean (run it as a script because there is an exit() at the end)

Should we expose shell=True/False in runCommand and set it correctly when calling an external?
But then the user cannot use gts in combination with timeout.
I pretty sure that some time ago both gts with timeout was working properly.

gianluca de santis <gianlucadesi>
Project Member
Thu 14 Nov 2013 08:47:13 AM UTC, comment #2:

It works for me but it raise an error in case of timeout.
This is because the sta after timeout is -15 and not -1015 (ie. _TIMEOUT_EXITCODE)
In commit ebaf941 the line
p.returncode = _TIMEOUT_EXITCODE
was deleted.

gianluca de santis <gianlucadesi>
Project Member
Wed 13 Nov 2013 06:27:29 PM UTC, comment #1:

This is related with using the 'shell=True' option in subprocess.Popen. When using a shell, the command is actually executed as a child of that shell, and terminating the parent does not necessarily terminate the children.
See also http://stackoverflow.com/questions/4789837/how-to-terminate-a-python-subprocess-launched-with-shell-true

In commit ebaf941 I made shell=False the default in utils.system. I had to add splitting of the command line into tokens to make it work. And with this option, timeout works properly. The script

yields as result

As you can see, in both cases the subprocess gets terminated after 3 seconds, but only in the first case (shell=False) it really returns immediately. In the second case (shell=True) we just terminate the shell that starts the sleep command, but not the sleep command itself.

This is ready for testing. Shell=False will probably work in most cases. However we should still add the solution presented in the URL refered above to terminate a whole process group. There might be cases where shell=True is needed (Python docs however warns about the security issues involved!) and even with shell=False some external commands might spawn children that do not get terminated by the parent terminating.

Benedict Verhegghe <bverheg>
Project AdministratorIn charge of this item.
Wed 13 Nov 2013 02:22:13 PM UTC, original submission:

it seems that the timeout is not doing anything (both as script and app).
If you run the attached example as a script it hangs. If you then kill the python process (external vmtk) the pyFormex GUI is re-activated and you can read that it tried to kill it.

gianluca de santis <gianlucadesi>
Project Member

 

(Note: upload size limit is set to 16384 kB, after insertion of the required escape characters.)

Attach File(s):
   
   
Comment:
   

Attached Files
file #29608:  runCmd.py added by gianlucadesi (2KiB - text/x-python)

 

Depends on the following items: None found

Items that depend on this one: None found

 

Carbon-Copy List
  • -unavailable- added by bverheg (Posted a comment)
  • -unavailable- added by gianlucadesi (Submitted the item)
  •  

    Do you think this task is very important?
    If so, you can click here to add your encouragement to it.
    This task has 0 encouragements so far.

    Only logged-in users can vote.

     

    Please enter the title of George Orwell's famous dystopian book (it's a date):

     

     

    Follow 13 latest changes.

    Date Changed By Updated Field Previous Value => Replaced By
    Thu 30 Jan 2014 10:12:54 AM UTCbverhegStatusReady For Test=>Fixed
      Open/ClosedOpen=>Closed
    Fri 15 Nov 2013 05:01:23 PM UTCbverhegStatusIn Progress=>Ready For Test
    Fri 15 Nov 2013 04:51:21 PM UTCbverhegSeverity3 - Normal=>4 - Important
      StatusFixed=>In Progress
      Open/ClosedClosed=>Open
    Fri 15 Nov 2013 02:51:30 PM UTCbverhegStatusReady For Test=>Fixed
      Open/ClosedOpen=>Closed
    Wed 13 Nov 2013 06:27:29 PM UTCbverhegCategoryNone=>Core
      Item GroupNone=>Functionality error
      StatusNone=>Ready For Test
      Assigned toNone=>bverheg
    Wed 13 Nov 2013 02:22:13 PM UTCgianlucadesiAttached File-=>Added runCmd.py, #29608

    Back to the top


    Powered by Savane 3.1-cleanup1