log elapsed

bombard/bombardier.py

@@ -6,6 +6,7 @@
 from bombard.weaver_mill import WeaverMill
 from bombard.report import Reporter
 from bombard.pretty_ns import time_ns
+from bombard.pretty_sz import pretty_sz
 from bombard.show_descr import markdown_for_terminal
 from bombard.http_request import http_request, EXCEPTION_STATUS
 from bombard import request_logging
@@ -55,6 +56,7 @@ def __init__(self, supply: dict=None, args=None, campaign_book: dict=None, ok_st
             time_units=('ms' if args.ms else None),
             time_threshold_ms=int(args.threshold)
         )
+        request_logging.pretty_ns = self.reporter.pretty_ns
 
         super().__init__()
 
@@ -125,7 +127,9 @@ def process_resp(self, ammo: dict, status: int, resp: str, elapsed: int, size: i
                         'supply': supply,
                         'ammo': AttrDict(self.campaign['ammo'])
                     }
-                    exec(request["script"], context)
+                    if 'compiled' not in request:
+                        request['compiled'] = compile(request['script'], 'script', 'exec')
+                    exec(request['compiled'], context)
                 except Exception as e:
                     log.error(f'Script fail\n{e}\n\n{request["script"]}\n\n{supply}\n', exc_info=True)
         else:
@@ -146,50 +150,53 @@ def worker(self, thread_id, ammo):
         Thread callable.
         Strike ammo from queue.
         """
-        # setup logging ASAP and as safe as possible
-        if isinstance(ammo, Mapping):
-            request = ammo.get('request', {})
-            ammo_id = ammo.get('id', '')
-            ammo_name = request.get('name', '')
-        else:
-            request = {}
-            ammo_id = None
-            ammo_name = None
-        request_logging.sending(thread_id, ammo_id, ammo_name)
-        pretty_url = ''  # we use it in `except`
         try:
-            ammo = apply_supply(ammo, dict(self.supply, **ammo['supply']))
-
-            url = request.get('url', '')
-            method = request['method'] if 'method' in request else 'GET'
-            body = json.dumps(request['body']) if 'body' in request else None
-            headers = self.get_headers(request)
-            pretty_url = self.beautify_url(url, method, body)
-
-            log.debug(f'Bomb to drop:\n{pretty_url}' + ('\n{body}' if body is not None else ''))
-            if self.args.quiet:
-                if ammo_id in self.show_request:
-                    print(f'{self.show_request[ammo_id].format(id=ammo_id):>15}\r', end='')
-            log.info(pretty_url)
-
-            start_ns = time_ns()
-            if self.args.dry:
-                status, resp = self.ok[0], json.dumps(request.get('dry'))
+            # setup logging ASAP and as safe as possible
+            if isinstance(ammo, Mapping):
+                request = ammo.get('request', {})
+                ammo_id = ammo.get('id', '')
+                ammo_name = request.get('name', '')
             else:
-                status, resp = http_request(url, method, headers, body, self.args.timeout)
-
-            request_logging.receiving()
-
-            self.process_resp(ammo, status, resp, time_ns() - start_ns, len(resp))
-
-            if self.args.quiet:
-                if ammo_id in self.show_response:
-                    print(f'{self.show_response[ammo_id].format(id=ammo_id):>15}\r', end='')
-            log.info(self.status_coloured(status) + ' ' + pretty_url
-                  + ' ' + (red(resp) if status == EXCEPTION_STATUS else '')
-            )
-        except Exception as e:
-            log.info(pretty_url + ' ' + red(str(e)), exc_info=True)
+                request = {}
+                ammo_id = None
+                ammo_name = None
+            request_logging.sending(thread_id, ammo_id, ammo_name)
+            pretty_url = ''  # we use it in `except`
+            try:
+                ammo = apply_supply(ammo, dict(self.supply, **ammo['supply']))
+
+                url = request.get('url', '')
+                method = request['method'] if 'method' in request else 'GET'
+                body = json.dumps(request['body']) if 'body' in request else None
+                headers = self.get_headers(request)
+                pretty_url = self.beautify_url(url, method, body)
+
+                log.debug(f'Bomb to drop:\n{pretty_url}' + ('\n{body}' if body is not None else ''))
+                if self.args.quiet:
+                    if ammo_id in self.show_request:
+                        print(f'{self.show_request[ammo_id].format(id=ammo_id):>15}\r', end='')
+                log.info(pretty_url)
+
+                start_ns = time_ns()
+                if self.args.dry:
+                    status, resp = self.ok[0], json.dumps(request.get('dry'))
+                else:
+                    status, resp = http_request(url, method, headers, body, self.args.timeout)
+
+                request_logging.receiving()
+
+                self.process_resp(ammo, status, resp, time_ns() - start_ns, len(resp))
+
+                if self.args.quiet:
+                    if ammo_id in self.show_response:
+                        print(f'{self.show_response[ammo_id].format(id=ammo_id):>15}\r', end='')
+                log.info(self.status_coloured(status) + f' ({pretty_sz(len(resp))}) ' + pretty_url
+                        + ' ' + (red(resp) if status == EXCEPTION_STATUS else '')
+                )
+            except Exception as e:
+                log.info(pretty_url + ' ' + red(str(e)), exc_info=True)
+        finally:
+            request_logging.main_thread()
 
     def reload(self, requests, repeat=None, **kwargs):
         """
@@ -220,5 +227,11 @@ def reload(self, requests, repeat=None, **kwargs):
     def bombard(self):
         self.start()  # lock until queue is not empty
         self.stop()  # stop all threads
-        print('\n' + '='*100)
-        print(markdown_for_terminal(self.reporter.report()) + '='*100, '\n')
+        log.warning(
+            '\n'
+            + '='*100
+            + '\n'
+            + markdown_for_terminal(self.reporter.report())
+            + '='*100
+            + '\n'
+        )

bombard/main.py

@@ -6,9 +6,7 @@
 import logging
 from bombard.args import get_args
 from typing import Optional
-
-
-log = logging.getLogger()
+from bombard.request_logging import setup_logging, log
 
 
 def guess_type(value: str):
@@ -26,14 +24,6 @@ def guess_type(value: str):
     return value
 
 
-def setup_logging(level: int, log_file_name: Optional[str] = None):
-    log.setLevel(level)
-    if log_file_name is not None:
-        log.addHandler(
-            logging.FileHandler(log_file_name)
-        )
-
-
 def get_supply_from_cli(supply: Optional[list]):
     result = {}
     if supply:
@@ -66,7 +56,7 @@ def add_names_to_requests(campaign_book):
 
 def campaign(args):
     if args.quiet:
-        level = logging.ERROR
+        level = logging.WARNING
     elif args.verbose:
         level = logging.DEBUG
     else:

bombard/request_logging.py

@@ -1,31 +1,48 @@
 """
-Use local thread storage to add to log information about request
+Logger with thread storage to add to log information about request.
+
+Use main_thread/sending/receiving to switch logger modes.
 """
 import threading
 import logging
 from bombard.terminal_colours import OFF, GRAY
+from typing import Optional
+from bombard.pretty_ns import time_ns, pretty_ns as plain_ns
 
 
+log = logging.getLogger()
 thread_data = threading.local()
+pretty_ns = plain_ns  # we can redefine that to have customized formatting
+
+
+def main_thread():
+    """
+    We are in main thread
+    """
+    thread_data.thread_id = 'Main'
+    thread_data.request_id = ''
+    thread_data.request_name = ''
+    thread_data.dir = ''
+    thread_data.start = None
+    thread_data.colour = OFF
 
 
 def sending(thread_id, request_id, request_name):
     """
     Start sending request
     """
-    global thread_data
     thread_data.thread_id = thread_id
     thread_data.request_id = request_id
     thread_data.request_name = request_name
     thread_data.dir = '>' * 3
     thread_data.colour = GRAY
+    thread_data.start = time_ns()
 
 
 def receiving():
     """
     Got response to request
     """
-    global thread_data
     thread_data.dir = '<' * 3
     thread_data.colour = OFF
 
@@ -37,15 +54,26 @@ def format(self, record):
         record.colour = thread_data.colour
         record.requestname = thread_data.request_name
         record.dir = thread_data.dir
+        record.elapsed = pretty_ns(time_ns() - thread_data.start) if thread_data.start is not None else ''
         return super().format(record)
 
 
-handler = logging.StreamHandler()
-handler.setFormatter(
-    RequestFormatter(
-        fmt=f'%(colour)s%(asctime)s %(requestid)s (thread %(threadid)s) %(requestname)s %(dir)s %(message)s{OFF}',
-        datefmt='%-d %b %H:%M:%S'
+def setup_logging(level: int, log_file_name: Optional[str] = None):
+    main_thread()
+    handler = logging.StreamHandler()
+    formatter = RequestFormatter(
+            fmt=f'%(colour)s%(asctime)s %(requestid)s %(elapsed)s (thread %(threadid)s) '
+                f'%(requestname)s %(dir)s %(message)s{OFF}',
+            datefmt='%-d %b %H:%M:%S'
     )
-)
-logging.getLogger().handlers = []
-logging.getLogger().addHandler(handler)
+    handler.setFormatter(formatter)
+    handler.setLevel(level)
+    log.handlers = []
+    log.addHandler(handler)
+    log.setLevel(logging.DEBUG)
+
+    if log_file_name is not None:
+        file_handler = logging.FileHandler(log_file_name)
+        file_handler.setFormatter(formatter)
+        file_handler.setLevel(logging.DEBUG)
+        log.addHandler(file_handler)