Merge branch 'feature/stopit' into develop

circle.yml

@@ -16,10 +16,12 @@ dependencies:
     - "pico-wavsep"
     - "sqlmap-testenv"
     - "php-moth"
+
   pre:
     - sudo apt-get update; sudo apt-get install python-gtksourceview2 python-gtk2 gir1.2-notify-0.7 python-pyatspi2 python-dbus python-pygame python-opencv python-scipy python-numpy stunnel4 libffi-dev
 
     # Install the core/console dependencies
+    - pip install --upgrade pip
     - w3af/core/controllers/ci/install_scripts/install_core_dependencies.sh
 
     # Install GUI dependencies
@@ -54,6 +56,10 @@ dependencies:
     # Wait for the daemon to be available to run the tests
     - w3af/core/controllers/ci/wait_for_moth.py
 
+  post:
+    - pip --version
+    - pip freeze
+
 machine:
   python:
     version: 2.7.3

w3af/core/controllers/ci/install_scripts/install_test_dependencies.sh

@@ -3,15 +3,16 @@
 #
 # Install all libs required to run our tests (which are available at pypi)
 #
-pip install pylint==0.28.0 mock==1.0.1 httpretty==0.7.0 psutil==1.2.1
+pip install pylint==0.28.0 mock==1.0.1 psutil==1.2.1
 pip install logilab-astng==0.24.3 SOAPpy==0.12.5 Pillow==1.7.8 SimpleCV==1.3
 pip install termcolor==1.1.0 yanc==0.2.4 futures==2.1.5 fabric==1.8.0
 pip install xunitparser==1.2.0
 
 # Install requirements for coveralls
 pip install coverage==3.6 nose-cov==1.6 coveralls==0.2
 
-pip install --upgrade -e 'git+https://github.com/andresriancho/nose.git#egg=nose'
+pip install --upgrade 'git+https://github.com/andresriancho/nose.git#egg=nose'
+pip install --upgrade 'git+https://github.com/andresriancho/HTTPretty.git'
 
 #
 # Install xpresser

w3af/core/controllers/ci/nosetests_wrapper/main.py

@@ -26,7 +26,8 @@
 from w3af.core.controllers.ci.nosetests_wrapper.utils.output import (print_info_console,
                                                                      print_status,
                                                                      print_will_fail,
-                                                                     print_summary)
+                                                                     print_summary,
+                                                                     get_run_id)
 
 
 def summarize_exit_codes(exit_codes):
@@ -61,35 +62,51 @@ def nose_strategy():
     exit_codes = []
     future_list = []
     done_list = []
-
+    queued_run_ids = []
+
     configure_logging(LOG_FILE)
 
     with futures.ThreadPoolExecutor(max_workers=MAX_WORKERS) as executor:
         for nose_cmd, first, last in nose_strategy():
             args = run_nosetests, nose_cmd, first, last
-            future_list.append(executor.submit(*args))
+
+            run_id = get_run_id(first, last)
+            queued_run_ids.append(run_id)
+
+            future = executor.submit(*args)
+            future.run_id = run_id
+            future_list.append(future)
 
         total_tests = len(future_list)
-        print_status(done_list, total_tests)
+        print_status(done_list, total_tests, queued_run_ids, executor)
 
         while future_list:
             try:
                 for future in futures.as_completed(future_list, timeout=120):
-                    cmd, stdout, stderr, exit_code, output_fname = future.result()
-                    exit_codes.append(exit_code)
-                    done_list.append(future)
-
-                    print_status(done_list, total_tests)
-
-                    if exit_code != 0:
-                        print_info_console(cmd, stdout, stderr,
-                                           exit_code, output_fname)
-                        print_will_fail(exit_code)
+                    try:
+                        cmd, stdout, stderr, exit_code, output_fname = future.result()
+                    except Exception as e:
+                        msg = 'Run id %s raised exception: "%s"'
+                        logging.error(msg % (future.run_id, e))
+                        print_will_fail(1)
+                        raise
+                    else:
+                        exit_codes.append(exit_code)
+                        done_list.append(future)
+                        queued_run_ids.remove(future.run_id)
+
+                        print_status(done_list, total_tests,
+                                     queued_run_ids, executor)
+
+                        if exit_code != 0:
+                            print_info_console(cmd, stdout, stderr,
+                                               exit_code, output_fname)
+                            print_will_fail(exit_code)
 
             except futures.TimeoutError:
                 logging.debug('Hit futures.as_completed timeout.')
                 logging.warning('Waiting...')
-                print_status(done_list, total_tests)
+                print_status(done_list, total_tests, queued_run_ids, executor)
 
             # Filter future_list to avoid issues with tasks which are already
             # finished/done

w3af/core/controllers/ci/nosetests_wrapper/utils/nosetests.py

@@ -1,30 +1,17 @@
 import os
+import signal
 import logging
 import select
 import subprocess
 import shlex
 
-from w3af.core.controllers.ci.nosetests_wrapper.constants import (NOISE,
-                                                                  ARTIFACT_DIR,
+from w3af.core.controllers.ci.nosetests_wrapper.utils.output import get_run_id
+from w3af.core.controllers.ci.nosetests_wrapper.constants import (ARTIFACT_DIR,
                                                                   NOSE_TIMEOUT,
                                                                   NOSE_OUTPUT_PREFIX,
                                                                   NOSE_XUNIT_EXT)
 
 
-def clean_noise(output_string):
-    """
-    Removes useless noise from the output
-    
-    :param output_string: The output string, stdout.
-    :return: A sanitized output string
-    """
-    for noise in NOISE:
-        output_string = output_string.replace(noise + '\n', '')
-        output_string = output_string.replace(noise, '')
-
-    return output_string
-
-
 def open_nosetests_output(suffix, first, last):
     name = '%s_%s-%s.%s' % (NOSE_OUTPUT_PREFIX, first, last, suffix)
     path_name = os.path.join(ARTIFACT_DIR, name)
@@ -35,32 +22,50 @@ def open_nosetests_output(suffix, first, last):
     return fhandler
 
 
+def add_message(message, output_file, stdout):
+    output_file.write('%s\n' % message)
+    output_file.flush()
+
+    logging.debug(message)
+
+    stdout += '%s\n' % message
+    return stdout
+
+
 def run_nosetests(nose_cmd, first, last):
     """
     Run nosetests and return the output
     
     :param nose_cmd: The nosetests command, with all parameters.
     :return: (stdout, stderr, exit code) 
     """
-    # Init the outputs
-    console = stdout = stderr = ''
-    output_file = open_nosetests_output('log', first, last)
-    xunit_output = open_nosetests_output(NOSE_XUNIT_EXT, first, last)
-
-    # Configure the xunit output before running the command
-    nose_cmd = nose_cmd % xunit_output.name
-
+    logging.debug('Called run_nosetests for %s' % get_run_id(first, last))
+
+    try:
+        # Init the outputs
+        console = stdout = stderr = ''
+        output_file = open_nosetests_output('log', first, last)
+        xunit_output = open_nosetests_output(NOSE_XUNIT_EXT, first, last)
+
+        # Configure the xunit output before running the command
+        nose_cmd %= xunit_output.name
+    except Exception as e:
+        logging.warning('Failed to initialize run_nosetests: "%s"' % e)
+        return
+
+    logging.debug('Starting (%s): "%s"' % (get_run_id(first, last), nose_cmd))
+
+    # Start the nosetests process
     cmd_args = shlex.split(nose_cmd)
-
-    logging.debug('Starting: "%s"' % nose_cmd)
-
+
     p = subprocess.Popen(
         cmd_args,
         stdin=subprocess.PIPE,
         stdout=subprocess.PIPE,
         stderr=subprocess.PIPE,
         shell=False,
-        universal_newlines=True
+        universal_newlines=True,
+        preexec_fn=os.setsid
     )
 
     # Read output while the process is alive
@@ -88,26 +93,40 @@ def run_nosetests(nose_cmd, first, last):
                 # There is a special case which happens with the first call to
                 # nose where the tests finish successfully (OK shown) but the
                 # nosetests process doesn't end. Handle that case here:
-                if console.strip().endswith('OK') and 'Ran ' in console:
-                    p.kill()
+                if console.strip().split('\n')[-1].startswith('OK') and 'Ran ' in console:
+                    msg = 'TIMEOUT after success at wrapper (%s)'
+                    stdout = add_message(msg % get_run_id(first, last),
+                                         output_file,
+                                         stdout)
+
+                    # Send the signal to all the process groups
+                    os.killpg(p.pid, signal.SIGTERM)
                     p.returncode = 0
-                    break
 
-                # Debugging my workaround
-                output_file.write("stdout.strip().endswith('OK') == %s\n" % console.strip().endswith('OK'))
-                output_file.write("'Ran ' in stdout == %s\n" % ('Ran ' in console))
+                    logging.debug('Process %s killed' % get_run_id(first, last))
 
+                    break
 
                 # Log everywhere I can:
-                output_file.write('TIMEOUT @ nosetests wrapper\n')
-                stdout += 'TIMEOUT @ nosetests wrapper\n'
-                logging.warning('"%s" timeout waiting for output.' % nose_cmd)
+                msg = 'TIMEOUT after error at wrapper (%s)'
+                stdout = add_message(msg % get_run_id(first, last),
+                                     output_file,
+                                     stdout)
+
+                args = (nose_cmd, get_run_id(first, last))
+                logging.warning('"%s" (%s) timeout waiting for output.' % args)
 
                 # Kill the nosetests command
-                p.kill()
+                # Send the signal to all the process groups
+                os.killpg(p.pid, signal.SIGTERM)
                 p.returncode = -1
+
+                logging.debug('Process %s killed' % get_run_id(first, last))
+
                 break
-
+
+    logging.debug('Cleanup for %s' % get_run_id(first, last))
+
     # Make sure all the output is read, there were cases when the process ended
     # and there were still bytes in stdout/stderr.
     c_stdout, c_stderr = p.communicate()
@@ -120,6 +139,8 @@ def run_nosetests(nose_cmd, first, last):
     # Close the output   
     output_file.close()
 
-    logging.debug('Finished: "%s" with code "%s"' % (nose_cmd, p.returncode))
+    logging.debug('Finished (%s): "%s" with code "%s"' % (get_run_id(first, last),
+                                                          nose_cmd,
+                                                          p.returncode))
 
     return nose_cmd, stdout, stderr, p.returncode, output_file.name

w3af/core/controllers/ci/nosetests_wrapper/utils/output.py

@@ -1,11 +1,12 @@
 from __future__ import print_function
 
 import logging
+import hashlib
 
 from itertools import ifilterfalse
 
-from w3af.core.controllers.ci.nosetests_wrapper.utils.nosetests import clean_noise
-from w3af.core.controllers.ci.nosetests_wrapper.constants import NOSE_IGNORE_SELECTOR
+from w3af.core.controllers.ci.nosetests_wrapper.constants import (NOISE,
+                                                                  NOSE_IGNORE_SELECTOR)
 
 
 def unique_everseen(iterable, key=None):
@@ -45,10 +46,26 @@ def print_info_console(cmd, stdout, stderr, exit_code, output_fname):
     logging.debug(stderr)
 
 
-def print_status(done_list, total_tests):
+def get_run_id(first, last):
+    _first = str(first).zfill(4)
+    _last = str(last).zfill(4)
+    _hash = hashlib.md5('%s%s' % (first, last)).hexdigest()[:7]
+    return '%s-%s-%s' % (_first, _last, _hash)
+
+
+def print_status(done_list, total_tests, queued_run_ids, executor):
     msg = 'Status: (%s/%s) ' % (len(done_list), total_tests)
     logging.warning(msg)
-
+
+    if len(queued_run_ids) <= 3 and queued_run_ids:
+        logging.warning('The pending run ids are:')
+        for qri in queued_run_ids:
+            logging.warning('    - %s' % qri)
+
+        msg = 'Running in %s threads, task queue size is %s'
+        logging.warning(msg % (len(executor._threads),
+                               executor._work_queue.qsize()))
+
     if len(done_list) > total_tests:
         raise RuntimeError('Done list has more items than total_tests!')
 
@@ -72,3 +89,17 @@ def print_summary(all_tests, run_tests, ignored_tests):
     msg = 'The following %s tests were NOT run due to selector "%s":\n%s'
     logging.debug(msg % (len(ignored_tests._tests), NOSE_IGNORE_SELECTOR,
                          missing_str))
+
+
+def clean_noise(output_string):
+    """
+    Removes useless noise from the output
+
+    :param output_string: The output string, stdout.
+    :return: A sanitized output string
+    """
+    for noise in NOISE:
+        output_string = output_string.replace(noise + '\n', '')
+        output_string = output_string.replace(noise, '')
+
+    return output_string

w3af/core/controllers/core_helpers/consumers/base_consumer.py

@@ -63,6 +63,7 @@ def _wrapper(self, *args, **kwds):
     return _wrapper
 
 
+# pylint: disable=E1120
 class BaseConsumer(Process):
     """
     Consumer thread that takes fuzzable requests from a Queue that's populated
@@ -121,14 +122,13 @@ def run(self):
                 # pylint: disable=E1120
                 self._consume_wrapper(work_unit)
                 self.in_queue.task_done()
-                # pylint: enable=E1120
 
     def _teardown(self):
         raise NotImplementedError
 
     def _consume(self, work_unit):
         raise NotImplementedError
-    
+
     @task_decorator
     def _consume_wrapper(self, function_id, work_unit):
         """