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(-)
Signed-off-by: Jan Tluka jtluka@redhat.com --- 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:
Signed-off-by: Jan Tluka jtluka@redhat.com --- 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
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@redhat.com --- 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()
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@redhat.com --- 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
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@redhat.com --- 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)
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@redhat.com --- 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):
On Fri, Apr 22, 2016 at 03:07:57PM +0200, Jan Tluka wrote:
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@redhat.com
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()
AH! I remember this one!... I've spent 3 weeks looking for this deadlock bug. Take a look at this commit: e2dcc4d126b8dee82df9a6f21e66b75905f224c4
This needs to be checked before applying this patch... The commit message mentions large amounts of data being sent over the communication PIPE, I'm not exactly sure how much this is at the moment but something tells me it could be connected to the memory page size of the system. Also I think we saw this bug when using tcpdump, probably from the PacketAssert module.
-Ondrej
self._control_cmd = cmd def kill(self, cmd):-- 2.4.11 _______________________________________________ LNST-developers mailing list lnst-developers@lists.fedorahosted.org https://lists.fedorahosted.org/admin/lists/lnst-developers@lists.fedorahoste...
Mon, Apr 25, 2016 at 03:28:40PM CEST, olichtne@redhat.com wrote:
On Fri, Apr 22, 2016 at 03:07:57PM +0200, Jan Tluka wrote:
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@redhat.com
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()AH! I remember this one!... I've spent 3 weeks looking for this deadlock bug. Take a look at this commit: e2dcc4d126b8dee82df9a6f21e66b75905f224c4
This needs to be checked before applying this patch... The commit message mentions large amounts of data being sent over the communication PIPE, I'm not exactly sure how much this is at the moment but something tells me it could be connected to the memory page size of the system. Also I think we saw this bug when using tcpdump, probably from the PacketAssert module.
-Ondrej
Yes, the deadlock is there. Scratch this patch set until we find better solution.
Thanks for catching this, Ondrej!
-Jan
self._control_cmd = cmd def kill(self, cmd):-- 2.4.11 _______________________________________________ LNST-developers mailing list lnst-developers@lists.fedorahosted.org https://lists.fedorahosted.org/admin/lists/lnst-developers@lists.fedorahoste...
Signed-off-by: Jan Tluka jtluka@redhat.com --- 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
lnst-developers@lists.fedorahosted.org
-
Jan Tluka -
Ondrej Lichtner