<p>George Joseph has uploaded this change for <strong>review</strong>.</p><p><a href="https://gerrit.asterisk.org/c/testsuite/+/19138">View Change</a></p><pre style="font-family: monospace,monospace; white-space: pre-wrap;">testsuite: avoid hang on waitfullybooted<br><br>Modify asterisk connection to timeout instead of<br>hitting a retry counter. Add exception handling for<br>command timeout and adding exponential back-off on<br>retries.<br><br>ASTERISK-30208<br><br>Change-Id: I863c6119b1c71e0e682a49f4187f1c079fc14ff2<br>(cherry picked from commit 0c886bc716393630e747984165f69e46786a04c0)<br>---<br>M lib/python/asterisk/asterisk.py<br>1 file changed, 53 insertions(+), 18 deletions(-)<br><br></pre><pre style="font-family: monospace,monospace; white-space: pre-wrap;">git pull ssh://gerrit.asterisk.org:29418/testsuite refs/changes/38/19138/1</pre><pre style="font-family: monospace,monospace; white-space: pre-wrap;"><span>diff --git a/lib/python/asterisk/asterisk.py b/lib/python/asterisk/asterisk.py</span><br><span>index 1c0edfd..d88cfb5 100644</span><br><span>--- a/lib/python/asterisk/asterisk.py</span><br><span>+++ b/lib/python/asterisk/asterisk.py</span><br><span>@@ -23,7 +23,7 @@</span><br><span> </span><br><span> from .config import ConfigFile</span><br><span> </span><br><span style="color: hsl(0, 100%, 40%);">-from subprocess import PIPE</span><br><span style="color: hsl(120, 100%, 40%);">+from subprocess import PIPE, TimeoutExpired</span><br><span> </span><br><span> from twisted.internet import reactor, protocol, defer, utils, error</span><br><span> from twisted.python.failure import Failure</span><br><span>@@ -372,7 +372,6 @@</span><br><span> self.memcheck_delay_stop = 0</span><br><span> self.instance_id = 0</span><br><span> self.wfbdelay = bootdelay</span><br><span style="color: hsl(0, 100%, 40%);">- self.wfbfailures = 0</span><br><span> if test_config is not None and 'memcheck-delay-stop' in test_config:</span><br><span> self.memcheck_delay_stop = test_config['memcheck-delay-stop'] or 0</span><br><span> </span><br><span>@@ -479,20 +478,25 @@</span><br><span> def __execute_wait_fully_booted():</span><br><span> """Send the CLI command waitfullybooted"""</span><br><span> </span><br><span style="color: hsl(0, 100%, 40%);">- # try to send the command three times, then assume asterisk won't start and error out</span><br><span style="color: hsl(120, 100%, 40%);">+ # try to send the command until we timeout,</span><br><span style="color: hsl(120, 100%, 40%);">+ # then assume asterisk won't start and error out</span><br><span style="color: hsl(120, 100%, 40%);">+ timeout = 90 if self.valgrind_enabled else 45</span><br><span> CLIRetVal = self.cli_exec_blocking("core waitfullybooted", "Asterisk has fully booted")</span><br><span> if CLIRetVal == 0:</span><br><span> msg = "Successfully started Asterisk %s" % self.host</span><br><span> self._start_deferred.callback(msg)</span><br><span style="color: hsl(0, 100%, 40%);">- elif self.wfbfailures < 2:</span><br><span style="color: hsl(0, 100%, 40%);">- self.wfbfailures +=1</span><br><span style="color: hsl(0, 100%, 40%);">- msg = "Asterisk core waitfullybooted for %s failed, retrying" % self.host</span><br><span style="color: hsl(0, 100%, 40%);">- LOGGER.warning(msg)</span><br><span style="color: hsl(0, 100%, 40%);">- reactor.callLater(self.wfbdelay, __execute_wait_fully_booted)</span><br><span style="color: hsl(0, 100%, 40%);">- else:</span><br><span style="color: hsl(0, 100%, 40%);">- msg = "Asterisk core waitfullybooted for %s failed too many times, exiting" % self.host</span><br><span style="color: hsl(120, 100%, 40%);">+ elif time.time() - self.__start_asterisk_time > timeout:</span><br><span style="color: hsl(120, 100%, 40%);">+ msg = "Asterisk core waitfullybooted for %s failed" % self.host</span><br><span> LOGGER.error(msg)</span><br><span> self._start_deferred.errback(Exception(msg))</span><br><span style="color: hsl(120, 100%, 40%);">+ else:</span><br><span style="color: hsl(120, 100%, 40%);">+ msg = "Asterisk core waitfullybooted for %s failed, retrying" % self.host</span><br><span style="color: hsl(120, 100%, 40%);">+ LOGGER.warning(msg)</span><br><span style="color: hsl(120, 100%, 40%);">+ # wait twice as long as last time up until half timeout</span><br><span style="color: hsl(120, 100%, 40%);">+ self.wfbdelay = self.wfbdelay*2</span><br><span style="color: hsl(120, 100%, 40%);">+ if self.wfbdelay > (timeout/2):</span><br><span style="color: hsl(120, 100%, 40%);">+ self.wfbdelay = (timeout/2)</span><br><span style="color: hsl(120, 100%, 40%);">+ reactor.callLater(self.wfbdelay, __execute_wait_fully_booted)</span><br><span> </span><br><span> self.install_configs(os.getcwd() + "/configs", deps)</span><br><span> self._setup_configs()</span><br><span>@@ -935,18 +939,24 @@</span><br><span> cli_protocol = AsteriskRemoteCliCommand(self.remote_config, cmd)</span><br><span> return cli_protocol.execute()</span><br><span> </span><br><span style="color: hsl(0, 100%, 40%);">- def cli_exec_blocking(self, cli_cmd, responsekey=""):</span><br><span style="color: hsl(120, 100%, 40%);">+ def cli_exec_blocking(self, cli_cmd, responsekey="", timeout=10):</span><br><span> """Execute a CLI command on this instance of Asterisk.</span><br><span> </span><br><span> Keyword Arguments:</span><br><span> cli_cmd The command to execute.</span><br><span style="color: hsl(120, 100%, 40%);">+ responsekey Optional string to look for in the stdout of the comand</span><br><span style="color: hsl(120, 100%, 40%);">+ timeout How long to let the run before timeout, default 10s</span><br><span> </span><br><span> Returns:</span><br><span> A integer indicating success/failure, looking for the</span><br><span style="color: hsl(0, 100%, 40%);">- response key in stdout</span><br><span style="color: hsl(120, 100%, 40%);">+ optional response key in stdout.</span><br><span style="color: hsl(120, 100%, 40%);">+ 0 = success</span><br><span style="color: hsl(120, 100%, 40%);">+ 1 = command failed</span><br><span style="color: hsl(120, 100%, 40%);">+ 2 = command missing key</span><br><span style="color: hsl(120, 100%, 40%);">+ 3 = command timed out</span><br><span> </span><br><span> Example Usage:</span><br><span style="color: hsl(0, 100%, 40%);">- asterisk.cli_exec_immediate("core set verbose 10")</span><br><span style="color: hsl(120, 100%, 40%);">+ asterisk.cli_exec_blocking("core waitfullybooted", "Asterisk has fully booted")</span><br><span> """</span><br><span> CLIRetVal = 0</span><br><span> # If this is going to a remote system, make sure we enclose</span><br><span>@@ -962,12 +972,20 @@</span><br><span> LOGGER.debug("Executing \"%s\"", cmd)</span><br><span> </span><br><span> if not self.remote_config:</span><br><span style="color: hsl(0, 100%, 40%);">- completed = subprocess.run([self.ast_binary,</span><br><span style="color: hsl(0, 100%, 40%);">- "-C", "%s" % os.path.join(self.astetcdir, "asterisk.conf"),</span><br><span style="color: hsl(0, 100%, 40%);">- "-rx", "%s" % cli_cmd],</span><br><span style="color: hsl(0, 100%, 40%);">- stdout=PIPE, stderr=PIPE, encoding='utf-8')</span><br><span style="color: hsl(120, 100%, 40%);">+ try:</span><br><span style="color: hsl(120, 100%, 40%);">+ # allow 10 seconds for the command itself to run or timeout, just</span><br><span style="color: hsl(120, 100%, 40%);">+ # so we don't sit forever.</span><br><span style="color: hsl(120, 100%, 40%);">+ completed = subprocess.run([self.ast_binary,</span><br><span style="color: hsl(120, 100%, 40%);">+ "-C", "%s" % os.path.join(self.astetcdir, "asterisk.conf"),</span><br><span style="color: hsl(120, 100%, 40%);">+ "-rx", "%s" % cli_cmd],</span><br><span style="color: hsl(120, 100%, 40%);">+ timeout=timeout,</span><br><span style="color: hsl(120, 100%, 40%);">+ stdout=PIPE, stderr=PIPE, encoding='utf-8')</span><br><span style="color: hsl(120, 100%, 40%);">+ except TimeoutExpired:</span><br><span style="color: hsl(120, 100%, 40%);">+ # Catch the timeout and return</span><br><span style="color: hsl(120, 100%, 40%);">+ CLIRetVal = 3</span><br><span style="color: hsl(120, 100%, 40%);">+ return CLIRetVal</span><br><span> </span><br><span style="color: hsl(0, 100%, 40%);">- if responsekey not in completed.stdout:</span><br><span style="color: hsl(120, 100%, 40%);">+ if responsekey and responsekey not in completed.stdout:</span><br><span> CLIRetVal = 2</span><br><span> else:</span><br><span> CLIRetVal = completed.returncode</span><br><span></span><br></pre><p>To view, visit <a href="https://gerrit.asterisk.org/c/testsuite/+/19138">change 19138</a>. To unsubscribe, or for help writing mail filters, visit <a href="https://gerrit.asterisk.org/settings">settings</a>.</p><div itemscope itemtype="http://schema.org/EmailMessage"><div itemscope itemprop="action" itemtype="http://schema.org/ViewAction"><link itemprop="url" href="https://gerrit.asterisk.org/c/testsuite/+/19138"/><meta itemprop="name" content="View Change"/></div></div>
<div style="display:none"> Gerrit-Project: testsuite </div>
<div style="display:none"> Gerrit-Branch: certified/18.9 </div>
<div style="display:none"> Gerrit-Change-Id: I863c6119b1c71e0e682a49f4187f1c079fc14ff2 </div>
<div style="display:none"> Gerrit-Change-Number: 19138 </div>
<div style="display:none"> Gerrit-PatchSet: 1 </div>
<div style="display:none"> Gerrit-Owner: George Joseph <gjoseph@digium.com> </div>
<div style="display:none"> Gerrit-CC: Michael Bradeen <mbradeen@sangoma.com> </div>
<div style="display:none"> Gerrit-MessageType: newchange </div>