[PATCH v2 0/7] Graceful kill for timouted processes

[Jan Tluka]

This patch set enhances handling of command timeouts. We've noticed that
for example netperf ran from Netperf test module might not be able to make
connection to netperf server. Linux default is to try send 6 SYN packets
before giving up TCP connection. This can take up to 2 minutes before netperf
terminates.

When the timeout for Netperf module happens the current approach is simply to
send SIG_KILL to the process. It works fine but this also make all of command
outputs to be lost so the user can't tell what happened to netperf besides
that it was killed.

To overcome this limitation I've added graceful kill when timeout occurs.
First the slave tries to send SIG_INT to the process and checks if the process
ended for 5 seconds. If the process does not end it is SIG_KILLed.

I tried to test this as much as possible and I also ran the regression tests.
Two of the tests had to be modified due to new reporting of graceful kill.
Besides that all is working fine and even better.

Jan Tluka (7):
  NetTestCommand: add pid_exists method to NetTestCommand
  NetTestCommand: log interrupt of foreground and background command
    separately
  NetTestCommand: added graceful kill flag
  NetTestSlave: add graceful termination to kill_command
  Machine: use graceful kill_command on process timeout
  NetTestCommand: add missing join on interrupt
  regression-tests: update tests to match graceful termination on
    timeout

 lnst/Common/NetTestCommand.py    | 26 +++++++++++++++++++++++---
 lnst/Controller/Machine.py       |  9 +++++++--
 lnst/Slave/NetTestSlave.py       | 22 ++++++++++++++++++++--
 regression-tests/tests/24/run.sh |  2 +-
 regression-tests/tests/27/run.sh |  4 ++--
 5 files changed, 53 insertions(+), 10 deletions(-)

-- 
2.4.11

[PATCH v2 1/7] NetTestCommand: add pid_exists method to NetTestCommand

[Jan Tluka]

Signed-off-by: Jan Tluka <jtluka(a)redhat.com&gt;
---
 lnst/Common/NetTestCommand.py | 7 +++++--
 1 file changed, 5 insertions(+), 2 deletions(-)

diff --git a/lnst/Common/NetTestCommand.py b/lnst/Common/NetTestCommand.py
index 774c26e..b64186d 100644
--- a/lnst/Common/NetTestCommand.py
+++ b/lnst/Common/NetTestCommand.py
@@ -188,15 +188,18 @@ class NetTestCommand:
         self._finished = True
         self._control_cmd = cmd
 
+    def pid_exists(self):
+        return os.path.exists("/proc/%d" % self._pid)
+
     def interrupt(self, cmd):
         self._finished = True
-        if os.path.exists("/proc/%d" % self._pid):
+        if self.pid_exists():
             logging.debug("Interrupting background command with id \"%s\",
pid \"%d\"" % (self._id, self._pid))
             os.killpg(os.getpgid(self._pid), signal.SIGINT)
         self._control_cmd = cmd
 
     def kill(self, cmd):
-        if os.path.exists("/proc/%d" % self._pid):
+        if self.pid_exists():
             if self._id:
                 logging.debug("Killing background command with id \"%s\",
pid \"%d\"" % (self._id, self._pid))
             else:
-- 
2.4.11

[PATCH v2 2/7] NetTestCommand: log interrupt of foreground and background command separately

[Jan Tluka]

Signed-off-by: Jan Tluka <jtluka(a)redhat.com&gt;

# Conflicts:
#	lnst/Common/NetTestCommand.py

Signed-off-by: Jan Tluka <jtluka(a)redhat.com&gt;
---
 lnst/Common/NetTestCommand.py | 5 ++++-
 1 file changed, 4 insertions(+), 1 deletion(-)

diff --git a/lnst/Common/NetTestCommand.py b/lnst/Common/NetTestCommand.py
index b64186d..3f11f92 100644
--- a/lnst/Common/NetTestCommand.py
+++ b/lnst/Common/NetTestCommand.py
@@ -194,7 +194,10 @@ class NetTestCommand:
     def interrupt(self, cmd):
         self._finished = True
         if self.pid_exists():
-            logging.debug("Interrupting background command with id \"%s\",
pid \"%d\"" % (self._id, self._pid))
+            if self._id:
+                logging.debug("Interrupting background command with id
\"%s\", pid \"%d\"" % (self._id, self._pid))
+            else:
+                logging.debug("Interrupting command with id \"%s\", pid
\"%d\"" % (self._id, self._pid))
             os.killpg(os.getpgid(self._pid), signal.SIGINT)
         self._control_cmd = cmd
 
-- 
2.4.11

[PATCH v2 2/7] NetTestCommand: log interrupt of foreground and background command separately

[Jan Tluka]

Fri, Apr 22, 2016 at 02:45:57PM CEST, jtluka(a)redhat.com wrote:
> Signed-off-by: Jan Tluka <jtluka(a)redhat.com&gt;
>
> # Conflicts:
> #	lnst/Common/NetTestCommand.py
>  
OMG, is it Friday? I'm going to check this, I mean the patch not Friday.

Sorry for noise.

[PATCH v2 2/7] NetTestCommand: log interrupt of foreground and background command separately

[Jan Tluka]

Fri, Apr 22, 2016 at 02:50:35PM CEST, jtluka(a)redhat.com wrote:
> Fri, Apr 22, 2016 at 02:45:57PM CEST, jtluka(a)redhat.com wrote:
> >Signed-off-by: Jan Tluka <jtluka(a)redhat.com&gt;
> >
> ># Conflicts:
> >#	lnst/Common/NetTestCommand.py
> >
>
> OMG, is it Friday? I'm going to check this, I mean the patch not Friday.
>
> Sorry for noise. 
Ok, so it is a relict of conflict that has been resolved.

Anyway I'm sending v3.

-Jan

[PATCH v2 3/7] NetTestCommand: added graceful kill flag

[Jan Tluka]

This flag indicates whether it was possible to kill the command
gracefully. Since we're using forked processes the value must be shared
between parent and child. I used multiprocessing.Value for this purpose.

The flag is used to mark the result to be sent to controller with the
indication of this kind of interruption.

Signed-off-by: Jan Tluka <jtluka(a)redhat.com&gt;
---
 lnst/Common/NetTestCommand.py | 13 +++++++++++++
 1 file changed, 13 insertions(+)

diff --git a/lnst/Common/NetTestCommand.py b/lnst/Common/NetTestCommand.py
index 3f11f92..f09e402 100644
--- a/lnst/Common/NetTestCommand.py
+++ b/lnst/Common/NetTestCommand.py
@@ -100,6 +100,7 @@ class NetTestCommand:
         self._log_ctl = log_ctl
         self._start_time = None
         self._result_sent = False
+        self._gracefully_killed = multiprocessing.Value('i', 0)
 
         if "bg_id" not in self._command:
             self._id = None
@@ -177,9 +178,21 @@ class NetTestCommand:
             result["cmd_id"] = self._id
             result["result"] = res_data
 
+        if self.get_gracefully_killed() == 1:
+            result["result"]["gracefully_killed"] = True
+
         send_data(self._write_pipe, result)
         self._write_pipe.close()
 
+    def set_gracefully_killed(self, value=True):
+        if value:
+            self._gracefully_killed.value = 1
+        else:
+            self._gracefully_killed.value = 0
+
+    def get_gracefully_killed(self):
+        return self._gracefully_killed.value
+
     def join(self):
         self._process.join()
 
-- 
2.4.11

[PATCH v2 4/7] NetTestSlave: add graceful termination to kill_command

[Jan Tluka]

I added graceful parameter to kill_command. When it is set to True
the slave first tries to interrupt the command using SIG_INT. Then it
waits 5 seconds and checks if the process is still alive using pid_exists().
When the command does not terminate after this period it is killed by
SIG_KILL.

This is basically needed if we want to keep the output of a command
that timeouts. When killed (not interrupted) the command's output is
lost and never logged.

V2: place reset of the graceful flag in graceful branch

Signed-off-by: Jan Tluka <jtluka(a)redhat.com&gt;
---
 lnst/Slave/NetTestSlave.py | 22 ++++++++++++++++++++--
 1 file changed, 20 insertions(+), 2 deletions(-)

diff --git a/lnst/Slave/NetTestSlave.py b/lnst/Slave/NetTestSlave.py
index 3b8bf79..d8ad158 100644
--- a/lnst/Slave/NetTestSlave.py
+++ b/lnst/Slave/NetTestSlave.py
@@ -439,11 +439,29 @@ class SlaveMethods:
 
         return res
 
-    def kill_command(self, id):
+    def kill_command(self, id, graceful=False):
         cmd = self._command_context.get_cmd(id)
         if cmd is not None:
             if not cmd.get_result_sent():
-                cmd.kill(None)
+                if graceful:
+                    check=0
+                    cmd.set_gracefully_killed()
+                    cmd.interrupt(None)
+                    while check < 5:
+                        sleep(1)
+                        if not cmd.pid_exists():
+                            break
+                        check += 1
+
+                    if cmd.pid_exists():
+                        cmd.set_gracefully_killed(False)
+                        logging.debug("Graceful termination timeout, killing")
+                        cmd.kill(None)
+                    else:
+                        return None
+                else:
+                    cmd.kill(None)
+
                 result = cmd.get_result()
                 cmd.set_result_sent()
                 return result
-- 
2.4.11

[PATCH v2 5/7] Machine: use graceful kill_command on process timeout

[Jan Tluka]

The controller now uses graceful killing of a command that timeouts. This is
needed if we want to keep the output of the command.

Also we need to set fail flag on the result in that case. The reason is that
for example IcmpPing module would report that it has passed based on
processing data of interrupted ping command within the module.

Signed-off-by: Jan Tluka <jtluka(a)redhat.com&gt;
---
 lnst/Controller/Machine.py | 9 +++++++--
 1 file changed, 7 insertions(+), 2 deletions(-)

diff --git a/lnst/Controller/Machine.py b/lnst/Controller/Machine.py
index 5d8db7d..da63197 100644
--- a/lnst/Controller/Machine.py
+++ b/lnst/Controller/Machine.py
@@ -330,15 +330,20 @@ class Machine(object):
         except MachineError as exc:
             if "proc_id" in command:
                 cmd_res = self._rpc_call_x(netns, "kill_command",
-                                           command["proc_id"])
+                                           command["proc_id"], True)
             else:
                 cmd_res = self._rpc_call_x(netns, "kill_command",
-                                           None)
+                                           None, True)
 
             if "killed" in cmd_res and cmd_res["killed"]:
                 cmd_res["passed"] = False
                 cmd_res["msg"] = str(exc)
 
+            if "gracefully_killed" in cmd_res and \
+               cmd_res["gracefully_killed"]:
+                cmd_res["passed"] = False
+                cmd_res["msg"] = "Command gracefully killed on
timeout"
+
         signal.alarm(0)
         signal.signal(signal.SIGALRM, prev_handler)
 
-- 
2.4.11

[PATCH v2 6/7] NetTestCommand: add missing join on interrupt

[Jan Tluka]

While working on graceful kill I noticed that when we call interrupt on
a command then the forked child is left orphaned and the pid_exists() check
always return true and graceful kill timeouts.

Adding join() call after sending the interrupt solves this problem.

Signed-off-by: Jan Tluka <jtluka(a)redhat.com&gt;
---
 lnst/Common/NetTestCommand.py | 1 +
 1 file changed, 1 insertion(+)

diff --git a/lnst/Common/NetTestCommand.py b/lnst/Common/NetTestCommand.py
index f09e402..6573ffd 100644
--- a/lnst/Common/NetTestCommand.py
+++ b/lnst/Common/NetTestCommand.py
@@ -212,6 +212,7 @@ class NetTestCommand:
             else:
                 logging.debug("Interrupting command with id \"%s\", pid
\"%d\"" % (self._id, self._pid))
             os.killpg(os.getpgid(self._pid), signal.SIGINT)
+            self._process.join()
         self._control_cmd = cmd
 
     def kill(self, cmd):
-- 
2.4.11

[PATCH v2 7/7] regression-tests: update tests to match graceful termination on timeout

[Jan Tluka]

Signed-off-by: Jan Tluka <jtluka(a)redhat.com&gt;
---
 regression-tests/tests/24/run.sh | 2 +-
 regression-tests/tests/27/run.sh | 4 ++--
 2 files changed, 3 insertions(+), 3 deletions(-)

diff --git a/regression-tests/tests/24/run.sh b/regression-tests/tests/24/run.sh
index 1aff4a3..0ec860d 100755
--- a/regression-tests/tests/24/run.sh
+++ b/regression-tests/tests/24/run.sh
@@ -14,7 +14,7 @@ log2=`cat test.log`
 
 print_separator
 assert_status "fail" "$rv1"
-assert_log "INFO" "RPC connection to machine \w* timed out"
"$log1"
+assert_log "INFO" "Command gracefully killed on timeout"
"$log1"
 assert_status "pass" "$rv2"
 
 rm -f test.log
diff --git a/regression-tests/tests/27/run.sh b/regression-tests/tests/27/run.sh
index e61da3f..e5acfeb 100755
--- a/regression-tests/tests/27/run.sh
+++ b/regression-tests/tests/27/run.sh
@@ -36,12 +36,12 @@ print_separator
 assert_status "pass" "$rv1"
 assert_status "pass" "$rv2"
 assert_status "fail" "$rv3"
-assert_log "INFO" "RPC connection to machine testmachine1 timed out"
"$log3"
+assert_log "INFO" "Command gracefully killed on timeout"
"$log3"
 assert_status "pass" "$rv4"
 assert_status "pass" "$rv5"
 assert_status "pass" "$rv6"
 assert_status "fail" "$rv7"
-assert_log "INFO" "RPC connection to machine testmachine1 timed out"
"$log7"
+assert_log "INFO" "Command gracefully killed on timeout"
"$log7"
 
 rm -f test.log
 
-- 
2.4.11