<p>Friendly Automation <strong>submitted</strong> this change.</p><p><a href="https://gerrit.asterisk.org/c/testsuite/+/19130">View Change</a></p><pre style="font-family: monospace,monospace; white-space: pre-wrap;"><span></span><br></pre><div style="white-space:pre-wrap">Approvals:
  Friendly Automation: Looks good to me, approved; Approved for Submit

</div><pre style="font-family: monospace,monospace; white-space: pre-wrap;">testsuite: avoid hang on waitfullybooted<br><br>change to call waitfullybooted as blocking with<br>a fixed number of tries (3).  The delay is set<br>to one second per asterisk instance.<br><br>ASTERISK-30208<br><br>Change-Id: I444f714834081e73f584bd08e21b3ec4c047ae8e<br>(cherry picked from commit b7fcb6de8961ed5b47ca526e21c50be106cd72f1)<br>---<br>M lib/python/asterisk/asterisk.py<br>M lib/python/asterisk/test_case.py<br>2 files changed, 78 insertions(+), 31 deletions(-)<br><br></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 6ca964e..66c1124 100644</span><br><span>--- a/lib/python/asterisk/asterisk.py</span><br><span>+++ b/lib/python/asterisk/asterisk.py</span><br><span>@@ -10,6 +10,7 @@</span><br><span> the GNU General Public License Version 2.</span><br><span> """</span><br><span> </span><br><span style="color: hsl(120, 100%, 40%);">+import subprocess</span><br><span> import sys</span><br><span> import os</span><br><span> import time</span><br><span>@@ -337,7 +338,7 @@</span><br><span>         default_etc_directory = "/etc/asterisk"</span><br><span> </span><br><span>     def __init__(self, base=None, ast_conf_options=None, host="127.0.0.1",</span><br><span style="color: hsl(0, 100%, 40%);">-                 remote_config=None, test_config=None):</span><br><span style="color: hsl(120, 100%, 40%);">+                 remote_config=None, test_config=None, bootdelay=1):</span><br><span>         """Construct an Asterisk instance.</span><br><span> </span><br><span>         Keyword Arguments:</span><br><span>@@ -368,6 +369,8 @@</span><br><span>         self.remote_config = remote_config</span><br><span>         self.memcheck_delay_stop = 0</span><br><span>         self.instance_id = 0</span><br><span style="color: hsl(120, 100%, 40%);">+        self.wfbdelay = bootdelay</span><br><span style="color: hsl(120, 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>@@ -464,47 +467,30 @@</span><br><span>             self.process = reactor.spawnProcess(self.protocol,</span><br><span>                                                 cmd[0],</span><br><span>                                                 cmd, env=os.environ)</span><br><span style="color: hsl(0, 100%, 40%);">-            # This was a one second delay, now two.  This is to allow</span><br><span style="color: hsl(120, 100%, 40%);">+            # This was a one second delay, now is passed in.  This is to allow</span><br><span>             # asterisk sufficient time to actually start and create the ctl</span><br><span>             # file. If we try to send the fully booted command before this</span><br><span>             # happens we wait and try again, but this results in an unhandled</span><br><span>             # error in twisted after the command succeeds.</span><br><span style="color: hsl(0, 100%, 40%);">-            reactor.callLater(2, __execute_wait_fully_booted)</span><br><span style="color: hsl(120, 100%, 40%);">+            reactor.callLater(self.wfbdelay, __execute_wait_fully_booted)</span><br><span> </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%);">-            cli_deferred = self.cli_exec("core waitfullybooted")</span><br><span style="color: hsl(0, 100%, 40%);">-            cli_deferred.addCallbacks(__wait_fully_booted_callback,</span><br><span style="color: hsl(0, 100%, 40%);">-                                      __wait_fully_booted_error)</span><br><span style="color: hsl(0, 100%, 40%);">-</span><br><span style="color: hsl(0, 100%, 40%);">-        def __wait_fully_booted_callback(cli_command):</span><br><span style="color: hsl(0, 100%, 40%);">-            """Callback for CLI command waitfullybooted"""</span><br><span style="color: hsl(0, 100%, 40%);">-</span><br><span style="color: hsl(0, 100%, 40%);">-            if "Asterisk has fully booted" in cli_command.output:</span><br><span style="color: hsl(120, 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%);">+            CLIRetVal = self.cli_exec_blocking("core waitfullybooted", "Asterisk has fully booted")</span><br><span style="color: hsl(120, 100%, 40%);">+            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(120, 100%, 40%);">+            elif self.wfbfailures < 2:</span><br><span style="color: hsl(120, 100%, 40%);">+                self.wfbfailures +=1</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%);">+                reactor.callLater(self.wfbdelay, __execute_wait_fully_booted)</span><br><span>             else:</span><br><span style="color: hsl(0, 100%, 40%);">-                LOGGER.debug("Asterisk core waitfullybooted failed " +</span><br><span style="color: hsl(0, 100%, 40%);">-                             "with output '%s', attempting again..." %</span><br><span style="color: hsl(0, 100%, 40%);">-                             cli_command.output)</span><br><span style="color: hsl(0, 100%, 40%);">-                reactor.callLater(1, __execute_wait_fully_booted)</span><br><span style="color: hsl(0, 100%, 40%);">-            return cli_command</span><br><span style="color: hsl(0, 100%, 40%);">-</span><br><span style="color: hsl(0, 100%, 40%);">-        def __wait_fully_booted_error(cli_command):</span><br><span style="color: hsl(0, 100%, 40%);">-            """Errback for CLI command waitfullybooted"""</span><br><span style="color: hsl(0, 100%, 40%);">-</span><br><span style="color: hsl(0, 100%, 40%);">-            timeout = 90 if self.valgrind_enabled else 45</span><br><span style="color: hsl(0, 100%, 40%);">-            if time.time() - self.__start_asterisk_time > timeout:</span><br><span style="color: hsl(0, 100%, 40%);">-                msg = "Asterisk core waitfullybooted for %s failed" % self.host</span><br><span style="color: hsl(120, 100%, 40%);">+                msg = "Asterisk core waitfullybooted for %s failed too many times, exiting" % self.host</span><br><span>                 LOGGER.error(msg)</span><br><span>                 self._start_deferred.errback(Exception(msg))</span><br><span style="color: hsl(0, 100%, 40%);">-            else:</span><br><span style="color: hsl(0, 100%, 40%);">-                LOGGER.debug("Asterisk core waitfullybooted failed " +</span><br><span style="color: hsl(0, 100%, 40%);">-                             "with output '%s', attempting again..." %</span><br><span style="color: hsl(0, 100%, 40%);">-                             cli_command.value.err.decode('utf-8'))</span><br><span style="color: hsl(0, 100%, 40%);">-                reactor.callLater(1, __execute_wait_fully_booted)</span><br><span style="color: hsl(0, 100%, 40%);">-            return cli_command</span><br><span> </span><br><span>         self.install_configs(os.getcwd() + "/configs", deps)</span><br><span>         self._setup_configs()</span><br><span>@@ -947,6 +933,47 @@</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(120, 100%, 40%);">+    def cli_exec_blocking(self, cli_cmd, responsekey=""):</span><br><span style="color: hsl(120, 100%, 40%);">+        """Execute a CLI command on this instance of Asterisk.</span><br><span style="color: hsl(120, 100%, 40%);">+</span><br><span style="color: hsl(120, 100%, 40%);">+        Keyword Arguments:</span><br><span style="color: hsl(120, 100%, 40%);">+        cli_cmd The command to execute.</span><br><span style="color: hsl(120, 100%, 40%);">+</span><br><span style="color: hsl(120, 100%, 40%);">+        Returns:</span><br><span style="color: hsl(120, 100%, 40%);">+        A integer indicating success/failure, looking for the</span><br><span style="color: hsl(120, 100%, 40%);">+        response key in stdout</span><br><span style="color: hsl(120, 100%, 40%);">+</span><br><span style="color: hsl(120, 100%, 40%);">+        Example Usage:</span><br><span style="color: hsl(120, 100%, 40%);">+        asterisk.cli_exec_immediate("core set verbose 10")</span><br><span style="color: hsl(120, 100%, 40%);">+        """</span><br><span style="color: hsl(120, 100%, 40%);">+        CLIRetVal = 0</span><br><span style="color: hsl(120, 100%, 40%);">+        # If this is going to a remote system, make sure we enclose</span><br><span style="color: hsl(120, 100%, 40%);">+        # the command in quotes</span><br><span style="color: hsl(120, 100%, 40%);">+        if self.remote_config:</span><br><span style="color: hsl(120, 100%, 40%);">+            cli_cmd = '"{0}"'.format(cli_cmd)</span><br><span style="color: hsl(120, 100%, 40%);">+</span><br><span style="color: hsl(120, 100%, 40%);">+        cmd = [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%);">+        ]</span><br><span style="color: hsl(120, 100%, 40%);">+        cmd = " ".join(cmd)</span><br><span style="color: hsl(120, 100%, 40%);">+        LOGGER.debug("Executing \"%s\"", cmd)</span><br><span style="color: hsl(120, 100%, 40%);">+</span><br><span style="color: hsl(120, 100%, 40%);">+        if not self.remote_config:</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%);">+                capture_output=True, encoding='utf-8')</span><br><span style="color: hsl(120, 100%, 40%);">+</span><br><span style="color: hsl(120, 100%, 40%);">+            if responsekey not in completed.stdout:</span><br><span style="color: hsl(120, 100%, 40%);">+                CLIRetVal = 2</span><br><span style="color: hsl(120, 100%, 40%);">+            else:</span><br><span style="color: hsl(120, 100%, 40%);">+                CLIRetVal = completed.returncode</span><br><span style="color: hsl(120, 100%, 40%);">+        else:</span><br><span style="color: hsl(120, 100%, 40%);">+            LOGGER.debug("remote not quite supported")</span><br><span style="color: hsl(120, 100%, 40%);">+            CLIRetVal = 1</span><br><span style="color: hsl(120, 100%, 40%);">+        return CLIRetVal</span><br><span style="color: hsl(120, 100%, 40%);">+</span><br><span>     def _make_directory_structure(self):</span><br><span>         """ Mirror system directory structure """</span><br><span> </span><br><span>diff --git a/lib/python/asterisk/test_case.py b/lib/python/asterisk/test_case.py</span><br><span>index 56bf37c..67ef93d 100644</span><br><span>--- a/lib/python/asterisk/test_case.py</span><br><span>+++ b/lib/python/asterisk/test_case.py</span><br><span>@@ -267,6 +267,8 @@</span><br><span>                           configuration can be overwritten by individual tests,</span><br><span>                           however.</span><br><span>         """</span><br><span style="color: hsl(120, 100%, 40%);">+        # delay first cli call for waitfullybooted by 1 second per asterisk instance</span><br><span style="color: hsl(120, 100%, 40%);">+        wfbootdelay = count</span><br><span>         for i, ast_config in enumerate(self.get_asterisk_hosts(count)):</span><br><span>             local_num = ast_config.get('num')</span><br><span>             host = ast_config.get('host')</span><br><span>@@ -279,12 +281,14 @@</span><br><span>                 LOGGER.info("Creating Asterisk instance %d" % local_num)</span><br><span>                 ast_instance = Asterisk(base=self.testlogdir, host=host,</span><br><span>                                         ast_conf_options=self.ast_conf_options,</span><br><span style="color: hsl(0, 100%, 40%);">-                                        test_config=test_config)</span><br><span style="color: hsl(120, 100%, 40%);">+                                        test_config=test_config,</span><br><span style="color: hsl(120, 100%, 40%);">+                                        bootdelay=wfbootdelay)</span><br><span>             else:</span><br><span>                 LOGGER.info("Managing Asterisk instance at %s" % host)</span><br><span>                 ast_instance = Asterisk(base=self.testlogdir, host=host,</span><br><span>                                         remote_config=ast_config,</span><br><span style="color: hsl(0, 100%, 40%);">-                                        test_config=test_config)</span><br><span style="color: hsl(120, 100%, 40%);">+                                        test_config=test_config,</span><br><span style="color: hsl(120, 100%, 40%);">+                                        bootdelay=wfbootdelay)</span><br><span>             self.ast.append(ast_instance)</span><br><span>             self.condition_controller.register_asterisk_instance(self.ast[i])</span><br><span> </span><br><span></span><br></pre><p>To view, visit <a href="https://gerrit.asterisk.org/c/testsuite/+/19130">change 19130</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/+/19130"/><meta itemprop="name" content="View Change"/></div></div>

<div style="display:none"> Gerrit-Project: testsuite </div>
<div style="display:none"> Gerrit-Branch: master </div>
<div style="display:none"> Gerrit-Change-Id: I444f714834081e73f584bd08e21b3ec4c047ae8e </div>
<div style="display:none"> Gerrit-Change-Number: 19130 </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-Reviewer: Friendly Automation </div>
<div style="display:none"> Gerrit-CC: Michael Bradeen <mbradeen@sangoma.com> </div>
<div style="display:none"> Gerrit-MessageType: merged </div>