Merge lp:~ben-hutchings/ensoft-sextant/filter-search into lp:ensoft-sextant

[Ben Hutchings]

Function name search within the web frontend now supports extended syntax:
'<name matches>:<file path matches>'
where name matches and file path matches are (possibly) comma separated lists, and may include wildcards '.*'. At least one of the two must be specified.

Fixed bug with inline functions being uploaded multiple times into the database.
Fixed bug with over-zealous name stripping of function identifiers.
Fixed bug by which some functions were not uploaded.

Note: some tests do not pass - this is not because it doesn't work! Some details have changed under the hood which require the tests to be changed.

[lp:~ben-hutchings/ensoft-sextant/filter-search]

47. By Ben Hutchings on 2014-11-19

tuple instead of list

48. By Ben Hutchings on 2014-11-21

merge from autocomplete-fix

49. By Ben Hutchings on 2014-11-21

another merge from autocomplete-fix

50. By Ben Hutchings on 2014-11-21

fixed bug causing extrac characters to be removed from the start of symbol names

Unmerged revisions

=== modified file 'resources/sextant/web/interface.html'
--- resources/sextant/web/interface.html	2014-11-19 10:40:37 +0000
+++ resources/sextant/web/interface.html	2014-11-19 10:40:37 +0000
@@ -27,8 +27,8 @@
                     All functions calling specific function</option>
                 <option value="functions_called_by">
                     All functions called by a specific function</option>
-                <option value="all_call_paths">
-                    All function call paths between two functions</option>
+                <!--option value="all_call_paths"> REMOVED AS THIS IS SLOW FOR IOS
+                    All function call paths between two functions</option-->
                 <option value="shortest_call_path">
                     Shortest path between two functions</option>
                 <option value="function_names">

=== modified file 'src/sextant/__main__.py'
--- src/sextant/__main__.py	2014-10-17 15:30:14 +0000
+++ src/sextant/__main__.py	2014-11-19 10:40:37 +0000
@@ -127,16 +127,13 @@
     except TypeError:
         alternative_name = None
 
-    not_object_file = args.not_object_file
-    # the default is "yes, this is an object file" if not-object-file was
-    # unsupplied
-
     try:
         update_db.upload_program(connection, 
                                  getpass.getuser(),
                                  args.input_file,
                                  alternative_name,
-                                 not_object_file)
+                                 args.not_object_file,
+                                 args.add_file_paths)
     except requests.exceptions.ConnectionError as e:
         msg = 'Connection error to server {}: {}'
         logging.error(msg.format(_displayable_url(args), e))
@@ -221,6 +218,12 @@
                                 help='default False, if the input file is an '
                                      'object to be disassembled',
                                 action='store_true')
+    parsers['add'].add_argument('--add-file-paths',
+                                help='default False, set to True to make objdump '
+                                     'extract the file paths for each function. '
+                                     'WARNING: this is SLOW for large object files, '
+                                     '~15 hours for IOS.',
+                                action='store_true')
 
     parsers['delete'] = subparsers.add_parser('delete-program',
                                               help="delete a program from the database")

=== modified file 'src/sextant/db_api.py'
--- src/sextant/db_api.py	2014-11-19 10:40:37 +0000
+++ src/sextant/db_api.py	2014-11-19 10:40:37 +0000
@@ -159,7 +159,7 @@
         tmp_path = os.path.join(self._tmp_dir, '{}_{{}}'.format(program_name))
 
         self.func_writer = CSVWriter(tmp_path.format('funcs'), 
-                                     headers=['name', 'type'], 
+                                     headers=['name', 'type', 'file'], 
                                      max_rows=5000)
         self.call_writer = CSVWriter(tmp_path.format('calls'), 
                                      headers=['caller', 'callee'], 
@@ -171,7 +171,7 @@
                  ' WITH line, toInt(line.id) as lineid'
                  ' MATCH (n:program {{name: "{}"}})'
                  ' CREATE (n)-[:subject]->(m:func {{name: line.name,'
-                 ' id: lineid, type: line.type}})')
+                 ' id: lineid, type: line.type, file: line.file}})')
         
         self.add_call_query = (' USING PERIODIC COMMIT 250'
                  ' LOAD CSV WITH HEADERS FROM "file:{}" AS line'
@@ -203,7 +203,7 @@
         # Propagate the error if there is one.
         return False if etype is not None else True
 
-    def add_function(self, name, typ='normal'):
+    def add_function(self, name, typ='normal', source='unknown'):
         """
         Add a function.
 
@@ -219,7 +219,7 @@
                     pointer: we know only that the function exists, not its
                             name or details.
         """
-        self.func_writer.write(name, typ)
+        self.func_writer.write(name, typ, source)
 
     def add_call(self, caller, callee):
         """
@@ -257,6 +257,19 @@
             remote_paths:
                 A list of the paths of the remote fils.
         """
+
+        def try_rmdir(path):
+            # Helper function to try and remove a directory, silently
+            # fail if it contains files, otherwise raise the exception.
+            try:
+                os.rmdir(path)
+            except OSError as e:
+                if e.errno in (os.errno.ENOTEMPTY, os.errno.ENOENT):
+                    # Files in directory or directory doesn't exist.
+                    pass
+                else:
+                    raise e
+
         print('Cleaning temporary files...', end='')
         file_paths = list(itertools.chain(self.func_writer.file_iter(),
                                           self.call_writer.file_iter()))
@@ -264,16 +277,9 @@
         for path in file_paths: 
             os.remove(path)
 
-        os.rmdir(self._tmp_dir)
-
-        try:
-            # If the parent sextant temp folder is empty, remove it.
-            os.rmdir(TMP_DIR)
-        except:
-            # There is other stuff in TMP_DIR (i.e. from other users), so
-            # leave it.
-            pass
-
+        try_rmdir(self._tmp_dir)
+        try_rmdir(TMP_DIR)
+    
         self._ssh.remove_from_tmp_dir(remote_paths)
 
         print('done.')
@@ -290,6 +296,7 @@
 
         tx.append('CREATE CONSTRAINT ON (p:program) ASSERT p.name IS UNIQUE')
         tx.append('CREATE INDEX ON :func(name)')
+        tx.append('CREATE INDEX ON: func(file)')
 
         # Apply the transaction.
         tx.commit()
@@ -832,7 +839,7 @@
         result = self._db.query(q, returns=neo4jrestclient.Node)
         return bool(result)
 
-    def get_function_names(self, program_name, search, max_funcs):
+    def get_function_names(self, program_name, search=None, max_funcs=None):
         """
         Execute query to retrieve a list of all functions in the program.
         Any of the output names can be used verbatim in any SextantConnection
@@ -845,15 +852,82 @@
         if not validate_query(program_name):
             return set()
 
+        limit = "LIMIT {}".format(max_funcs) if max_funcs else ""
+
         if not search:
             q = (' MATCH (:program {{name: "{}"}})-[:subject]->(f:func)'
-                 ' RETURN f.name LIMIT {}').format(program_name, max_funcs)
+                 ' RETURN f.name {}').format(program_name, limit)
         else:
             q = (' MATCH (:program {{name: "{}"}})-[:subject]->(f:func)'
-                 ' WHERE f.name =~ ".*{}.*" RETURN f.name LIMIT {}'
-                 .format(program_name, search, max_funcs))
+                 ' WHERE f.name =~ ".*{}.*" RETURN f.name {}'
+                 .format(program_name, search, limit))
         return {func[0] for func in self._db.query(q)}
 
+    @staticmethod
+    def get_query(identifier, search):
+        """
+        Builds a filter query from a search pattern which may contain commas
+        and/or wildcards.
+
+        Return:
+            string: part of a valid cypher query.
+        Arguments:
+            identifier:
+                The identifier of the node whose properties to filter on,
+                e.g. 'f' after a 'MATCH (f:func) ...'
+            search:
+                The pattern to build the search from, of form:
+                '<name patterns>:<path patterns>'
+                where patterns are possibly empty, possibly comma separated
+                lists of strings, which will be compared to the 'name' and
+                'file' (path) attributes of 'identifier'.
+
+                These strings may contain wildcards: e.g:
+                .*substring.*
+                sub.*string
+                etc.
+                
+        """
+        if ':' in search:
+            func_subs, file_subs = search.split(':')
+        else:
+            func_subs, file_subs = search, ''
+
+        # Remove empty strings.
+        func_subs = [sub for sub in func_subs.split(',') if sub]
+        file_subs = [sub for sub in file_subs.split(',') if sub]
+
+        # Cases for search:
+        #  <specific name>:<redundant stuff>
+        #  <wildcard name>:<specific filepath>
+        #  <wildcard name>:<wildcard filepath>
+
+        query_str = ""
+
+        def get_list(subs):
+            return '[{}]'.format(','.join("'{}'".format(s) for s in subs))
+
+
+        if func_subs and not any('*' in sub for sub in func_subs):
+            # List of specific functions. Don't care about anything after ':'
+            query_str += ('USING INDEX {0}:func(name) WHERE {0}.name IN {1} '
+                          .format(identifier, get_list(func_subs)))
+        else:
+            if file_subs and not any('*' in sub for sub in file_subs):
+                # Specific file to look in.
+                query_str = ('USING INDEX {0}.func(file) WHERE {0}.file IN {1} '
+                             .format(identifier, get_list(file_subs)))
+            elif file_subs:
+                query_str = ('WHERE ANY (s_file IN {} WHERE {}.file =~ s_file) '
+                             .format(get_list(file_subs), identifier))
+
+            if func_subs:
+                query_str += 'AND ' if file_subs else 'WHERE '
+                query_str += ('ANY (s_name IN {} WHERE {}.name =~ s_name) '
+                              .format(get_list(func_subs), identifier))
+
+        return query_str
+
     def get_all_functions_called(self, program_name, function_calling):
         """
         Execute query to find all functions called by a function (indirectly).
@@ -863,14 +937,9 @@
         :param function_calling: string name of a function whose children to find
         :return: FunctionQueryResult, maximal subgraph rooted at function_calling
         """
-
-        if not self.check_function_exists(program_name, function_calling):
-            return None
-
-        q = (' MATCH (p:program {{name: "{}"}})-[:subject]->(f:func {{name: "{}"}})'
-             ' USING INDEX f:func(name)'
-             ' MATCH (f)-[:calls*]->(g) RETURN distinct f, g'
-             .format(program_name, function_calling))
+        q = (' MATCH (p:program {{name: "{}"}})-[:subject]->(f:func) {}'
+             ' MATCH (f)-[:calls]->(g:func) RETURN distinct f, g'
+             .format(program_name, SextantConnection.get_query('f', function_calling)))
 
         return self._execute_query(program_name, q)
 
@@ -884,14 +953,10 @@
         :return: FunctionQueryResult, maximal connected subgraph with leaf function_called
         """
 
-        if not self.check_function_exists(program_name, function_called):
-            return None
-
-        q = (' MATCH (p:program {{name: "{}"}})-[:subject]->(g:func {{name: "{}"}})'
-             ' USING INDEX g:func(name)'
-             ' MATCH (f)-[:calls*]->(g) WHERE f.name <> "{}"'
-             ' RETURN distinct f , g')
-        q = q.format(program_name, function_called, program_name)
+        q = (' MATCH (p:program {{name: "{}"}})-[:subject]->(g:func) {}'
+             ' MATCH (f)-[:calls]->(g)'
+             ' RETURN distinct f, g')
+        q = q.format(program_name, SextantConnection.get_query('g', function_called), program_name)
 
         return self._execute_query(program_name, q)
 
@@ -910,22 +975,17 @@
         if not self.check_program_exists(program_name):
             return None
 
-        if not self.check_function_exists(program_name, function_called):
-            return None
-
-        if not self.check_function_exists(program_name, function_calling):
-            return None
-
-        q = (' MATCH (p:program {{name: "{}"}})-[:subject]->(start:func {{name: "{}"}})'
-             ' USING INDEX start:func(name)'
-             ' MATCH (p)-[:subject]->(end:func {{name: "{}"}})'
-             ' USING INDEX end:func(name)'
+        start_q = SextantConnection.get_query('start', function_calling)
+        end_q = SextantConnection.get_query('end', function_called)
+
+        q = (' MATCH (p:program {{name: "{}"}})'
+             ' MATCH (p)-[:subject]->(start:func) {} WITH start, p'
+             ' MATCH (p)-[:subject]->(end:func) {} WITH start, end'
              ' MATCH path=(start)-[:calls*]->(end)'
              ' WITH DISTINCT nodes(path) AS result'
              ' UNWIND result AS answer'
              ' RETURN answer')
-        q = q.format(program_name, function_calling, function_called)
-
+        q = q.format(program_name, start_q, end_q)
         return self._execute_query(program_name, q)
 
     def get_whole_program(self, program_name):
@@ -942,7 +1002,7 @@
              ' RETURN (f)'.format(program_name))
         return self._execute_query(program_name, q)
 
-    def get_shortest_path_between_functions(self, program_name, func1, func2):
+    def get_shortest_path_between_functions(self, program_name, function_calling, function_called):
         """
         Execute query to get a single, shortest, path between two functions.
         :param program_name: string name of the program we wish to search under
@@ -953,17 +1013,16 @@
         if not self.check_program_exists(program_name):
             return None
 
-        if not self.check_function_exists(program_name, func1):
-            return None
-
-        if not self.check_function_exists(program_name, func2):
-            return None
-
-        q = (' MATCH (p:program {{name: "{}"}})-[:subject]->(f:func {{name: "{}"}})'
-             ' USING INDEX f:func(name)'
-             ' MATCH (p)-[:subject]->(g:func {{name: "{}"}})'
-             ' MATCH path=shortestPath((f)-[:calls*]->(g))'
-             ' UNWIND nodes(path) AS ans'
-             ' RETURN ans'.format(program_name, func1, func2))
+        start_q = SextantConnection.get_query('start', function_calling)
+        end_q = SextantConnection.get_query('end', function_called)
+
+        q = (' MATCH (p:program {{name: "{}"}})'
+             ' MATCH (p)-[:subject]->(start:func) {} WITH start, p'
+             ' MATCH (p)-[:subject]->(end:func) {} WITH start, end'
+             ' MATCH path=shortestPath((start)-[:calls*]->(end))'
+             ' UNWIND nodes(path) AS answer'
+             ' RETURN answer')
+        q = q.format(program_name, start_q, end_q)
 
         return self._execute_query(program_name, q)
+

=== modified file 'src/sextant/export.py'
--- src/sextant/export.py	2014-10-13 14:58:12 +0000
+++ src/sextant/export.py	2014-11-19 10:40:37 +0000
@@ -48,7 +48,7 @@
         for func in program.get_functions():
             if func.type == "stub":
                 output_str += ' "{}" [fillcolor=pink, style=filled]\n'.format(func.name)
-            elif func.type == "function_pointer":
+            elif func.type == "pointer":
                 output_str += ' "{}" [fillcolor=yellow, style=filled]\n'.format(func.name)
 
             # in all cases, even if we've specified that we want a filled-in

=== modified file 'src/sextant/objdump_parser.py' (properties changed: +x to -x)
--- src/sextant/objdump_parser.py	2014-10-23 11:15:48 +0000
+++ src/sextant/objdump_parser.py	2014-11-19 10:40:37 +0000
@@ -42,9 +42,12 @@
             The number of function calls that have been parsed.
         function_ptr_count:
             The number of function pointers that have been detected.
-        _known_stubs:
-            A set of the names of functions with type 'stub' that have been
-            parsed - used to avoid registering a stub multiple times.
+        _known_functions:
+            A set of the names of functions that have been
+            parsed - used to avoid registering a function multiple times.
+        _partial_functions:
+            A set of functions whose names we have seen but whose source
+            files we don't yet know.
 
     """
     def __init__(self, file_path, file_object=None, 
@@ -102,13 +105,14 @@
         self.call_count = 0
         self.function_ptr_count = 0
         
-        # Avoid adding duplicate function stubs (as these are detected from
-        # function calls so may be repeated).
-        self._known_stubs = set()
+        # Avoid adding duplicate functions.
+        self._known_functions = set()
+        # Set of partially-parsed functions.
+        self._partial_functions = set()
 
         # By default print information to stdout.
-        def print_func(name, typ):
-            print('func {:25}{}'.format(name, typ))
+        def print_func(name, typ, source='unknown'):
+            print('func {:25}{:15}{}'.format(name, typ, source))
 
         def print_call(caller, callee):
             print('call {:25}{:25}'.format(caller, callee))
@@ -116,7 +120,6 @@
         def print_started(parser):
             print('parse started: {}[{}]'.format(self.path, ', '.join(self.sections)))
 
-
         def print_finished(parser):
             print('parsed {} functions and {} calls'.format(self.function_count, self.call_count))
 
@@ -134,12 +137,32 @@
         self.function_ptr_count += 1
         return name
 
-    def _add_function_normal(self, name):
-        """
-        Add a function which we have full assembly code for.
-        """
-        self.add_function(name, 'normal')
-        self.function_count += 1
+    def _add_function(self, name, source=None):
+        """
+        Add a partially known or fully known function.
+        """
+        if source is None:
+            # Partial definition - if do not already have a full definition
+            # for this name then add it to the partials set.
+            if not name in self._known_functions:
+                self._partial_functions.add(name)
+        elif source == 'unknown':
+            # Manually adding a stub function.
+            self.add_function(name, 'stub', source)
+            self.function_count += 1
+        elif name not in self._known_functions:
+            # A full definition - either upgrade from partial function
+            # to known function, or add directly to known functions
+            # (otherwise we have already seen it)
+
+            try:
+                self._partial_functions.remove(name)
+            except KeyError:
+                pass
+
+            self._known_functions.add(name)
+            self.add_function(name, 'normal', source)
+            self.function_count += 1
 
     def _add_function_ptr(self, name):
         """
@@ -148,15 +171,6 @@
         self.add_function(name, 'pointer')
         self.function_count += 1
 
-    def _add_function_stub(self, name):
-        """
-        Add a function stub - we have its name but none of its internals.
-        """
-        if not name in self._known_stubs:
-            self._known_stubs.add(name)
-            self.add_function(name, 'stub')
-            self.function_count += 1
-
     def _add_call(self, caller, callee):
         """
         Add a function call from caller to callee.
@@ -171,10 +185,20 @@
         self.started()
 
         if self._file is not None:
-            in_section = False          # if we are in one of self.sections
-            current_function = None     # track the caller for function calls
+            in_section = False          # If we are in one of self.sections.
+            current_function = None     # Track the caller for function calls.
+            to_add = False
 
             for line in self._file:
+                if to_add:
+                    file_line = line.startswith('/')
+                    source = line.split(':')[0] if file_line else None
+                    self._add_function(current_function, source)
+                    to_add = False
+
+                    if file_line:
+                        continue
+
                 if line.startswith('Disassembly'):
                     # 'Disassembly of section <name>:\n'
                     section = line.split(' ')[-1].rstrip(':\n')
@@ -189,12 +213,19 @@
                         # <function_name>[@plt]
                         function_identifier = line.split('<')[-1].split('>')[0]
 
+                        # IOS builds add a __be_ (big endian) prefix to all functions,
+                        # get rid of it if it is there,
+                        if function_identifier.startswith('__be_'):
+                            function_identifier = function_identifier.lstrip('__be_')
+
                         if '@' in function_identifier:
+                            # Of form <function name>@<other stuff>.
                             current_function = function_identifier.split('@')[0]
-                            self._add_function_stub(current_function)
+                            self._add_function(current_function)
                         else:
                             current_function = function_identifier
-                            self._add_function_normal(current_function)
+                            # Flag function - we look for source on the next line.
+                            to_add = True
 
                     elif 'call ' in line or 'callq ' in line:
                         # WHITESPACE to prevent picking up function names 
@@ -213,9 +244,12 @@
                             # from which we extract name
                             callee_is_ptr = False
                             function_identifier = callee_info.lstrip('<').rstrip('>\n')
+                            if function_identifier.startswith('__be_'):
+                                function_identifier = function_identifier.lstrip('__be_')
+
                             if '@' in function_identifier:
                                 callee = function_identifier.split('@')[0]
-                                self._add_function_stub(callee)
+                                self._add_function(callee)
                             else:
                                 callee = function_identifier.split('-')[-1].split('+')[0]
                                 # Do not add this fn now - it is a normal func
@@ -231,6 +265,10 @@
                         # Add the call.
                         if not (self.ignore_ptrs and callee_is_ptr):
                             self._add_call(current_function, callee)
+
+            for name in self._partial_functions:
+                self._add_function(name, 'unknown')
+            
             
             self.finished()
 
@@ -261,7 +299,7 @@
         return result
 
 
-def run_objdump(input_file):
+def run_objdump(input_file, add_file_paths=False):
     """
     Run the objdump command on the file with the given path.
 
@@ -271,13 +309,24 @@
     Arguments:
         input_file:
             The path of the file to run objdump on.
+        add_file_paths:
+            Whether to call with -l option to extract line numbers and source
+            files from the binary. VERY SLOW on large binaries (~15 hours for ios).
         
     """
+    print('input file: {}'.format(input_file))
     # A single section can be specified for parsing with the -j flag,
     # but it is not obviously possible to parse multiple sections like this.
-    p = subprocess.Popen(['objdump', '-d', input_file, '--no-show-raw-insn'], 
-                         stdout=subprocess.PIPE)
-    g = subprocess.Popen(['egrep', 'Disassembly|call(q)? |>:$'], stdin=p.stdout, stdout=subprocess.PIPE)
+    args = ['objdump', '-d', input_file, '--no-show-raw-insn']
+    if add_file_paths:
+        args += ['--line-numbers']
+
+    p = subprocess.Popen(args, stdout=subprocess.PIPE)
+    # Egrep filters out the section headers (Disassembly of section...),
+    # the call lines (... [l]call[q] ...), the function declarations
+    # (... <function>:$) and the file paths (^/file_path).
+    g = subprocess.Popen(['egrep', 'Disassembly|call(q)? |>:$|^/'], 
+                         stdin=p.stdout, stdout=subprocess.PIPE)
     return input_file, g.stdout
 
 

=== modified file 'src/sextant/test_parser.py'
--- src/sextant/test_parser.py	2014-10-23 11:15:48 +0000
+++ src/sextant/test_parser.py	2014-11-19 10:40:37 +0000
@@ -23,7 +23,7 @@
         calls = defaultdict(list)
         
         # set the Parser to put output in local dictionaries
-        add_function = lambda n, t: self.add_function(functions, n, t)
+        add_function = lambda n, t, s='unknown': self.add_function(functions, n, t)
         add_call = lambda a, b: self.add_call(calls, a, b)
 
         p = parser.Parser(path, sections=sections, ignore_ptrs=ignore_ptrs, 

=== modified file 'src/sextant/test_resources/parser_test'
Binary files src/sextant/test_resources/parser_test	2014-10-13 14:10:01 +0000 and src/sextant/test_resources/parser_test	2014-11-19 10:40:37 +0000 differ
=== modified file 'src/sextant/update_db.py'
--- src/sextant/update_db.py	2014-10-17 14:20:06 +0000
+++ src/sextant/update_db.py	2014-11-19 10:40:37 +0000
@@ -20,7 +20,7 @@
 import logging
 
 def upload_program(connection, user_name, file_path, program_name=None, 
-                   not_object_file=False):
+                   not_object_file=False, add_file_paths=False):
     """
     Upload a program's functions and call graph to the database.
 
@@ -38,6 +38,9 @@
         not_object_file:
             Flag controlling whether file_path is pointing to a dump file or
             a binary file.
+        add_file_paths:
+            Flag controlling whether to call objdump with the -l option to
+            extract line numbers and source files. VERY SLOW on large binaries.
     """
     if not connection._ssh:
         raise SSHConnectionError('An SSH connection is required for '
@@ -59,9 +62,9 @@
     start = time()
 
     if not not_object_file:
-        print('Generating dump file...', end='')
+        print('Generating dump file with{} file paths...'.format(('out', '')[add_file_paths]), end='')
         sys.stdout.flush()
-        file_path, file_object = run_objdump(file_path)
+        file_path, file_object = run_objdump(file_path, add_file_paths)
         print('done.')
     else:
         file_object = None
@@ -82,15 +85,19 @@
             print('done: {} functions and {} calls.'
                   .format(parser.function_count, parser.call_count))
 
-        parser = Parser(file_path = file_path, file_object = file_object,
+        parser = Parser(file_path=file_path, file_object = file_object,
                         sections=[],
-                        add_function = program.add_function,
-                        add_call = program.add_call,
+                        add_function=program.add_function,
+                        add_call=program.add_call,
                         started=lambda parser: start_parser(program),
                         finished=lambda parser: finish_parser(parser, program))
+
         parser.parse()
-
-        program.commit()
+    
+        if parser.function_count == 0:
+            print('Nothing to upload. Did you mean to add the --not-object-file flag?')
+        else:
+            program.commit()
 
     end = time()
     print('Finished in {:.2f}s.'.format(end-start))

=== modified file 'src/sextant/web/server.py'
--- src/sextant/web/server.py	2014-11-19 10:40:37 +0000
+++ src/sextant/web/server.py	2014-11-19 10:40:37 +0000
@@ -13,6 +13,8 @@
 from twisted.internet.threads import deferToThread
 from twisted.internet import defer
 
+from neo4jrestclient.exceptions import TransactionException
+
 import logging
 import os
 import json
@@ -24,6 +26,8 @@
 import tempfile
 import subprocess
 
+from datetime import datetime
+
 from cgi import escape  # deprecated in Python 3 in favour of html.escape, but we're stuck on Python 2
 
 # global SextantConnection object which deals with the port forwarding
@@ -174,13 +178,15 @@
         # if we are okay here we have a valid query with all required arguments
         if res_code is RESPONSE_CODE_OK:
             try:
+                print('running query {}'.format(datetime.now()))
                 program = yield defer_to_thread_with_timeout(render_timeout, fn,
                                                              name, *req_args)
-            except defer.CancelledError:
+                print('\tdone {}'.format(datetime.now()))
+            except Exception as e:
                 # the timeout has fired and cancelled the request
                 res_code = RESPONSE_CODE_BAD_REQUEST
-                res_fmt = "The request timed out after {} seconds."
-                res_msg = res_fmt.format(render_timeout)
+                res_msg = "{}".format(e)
+                print('\tfailed {}'.format(datetime.now()))
             
         if res_code is RESPONSE_CODE_OK:
             # we have received a response to our request
@@ -201,10 +207,12 @@
             suppress_common = suppress_common_arg in ('null', 'true')
 
             # we have a non-empty return - render it
+            print('getting plot {}'.format(datetime.now()))
             res_msg = yield deferToThread(self.get_plot, program, 
                                           suppress_common, 
                                           remove_self_calls=False)
             request.setHeader('content-type', 'image/svg+xml')
+            print('\tdone {}'.format(datetime.now()))
 
         request.setResponseCode(res_code)
         request.write(res_msg)
@@ -229,6 +237,7 @@
         max_funcs = AUTOCOMPLETE_NAMES_LIMIT + 1
         programs = CONNECTION.programs_with_metadata()
         result = CONNECTION.get_function_names(program_name, search, max_funcs)
+        print(search, len(result))
         return result if len(result) < max_funcs else set()