Merge pull request #1900 from locustio/add-start_time-and-url-paramet…

…ers-to-request-event

Add start_time and url parameters to request event.

docs/extending-locust.rst

@@ -12,7 +12,7 @@ For example, here's how to set up an event listener that will trigger after a re
     
     @events.request.add_listener
     def my_request_handler(request_type, name, response_time, response_length, response,
-                           context, exception, **kwargs):
+                           context, exception, start_time, url, **kwargs):
         if exception:
             print(f"Request to {name} failed with exception {exception}")
         else:

examples/custom_xmlrpc_client/xmlrpc_locustfile.py

@@ -19,20 +19,21 @@ def __getattr__(self, name):
         func = ServerProxy.__getattr__(self, name)
 
         def wrapper(*args, **kwargs):
-            start_time = time.perf_counter()
             request_meta = {
                 "request_type": "xmlrpc",
                 "name": name,
+                "start_time": time.time(),
                 "response_length": 0,  # calculating this for an xmlrpc.client response would be too hard
                 "response": None,
                 "context": {},  # see HttpUser if you actually want to implement contexts
                 "exception": None,
             }
+            start_perf_counter = time.perf_counter()
             try:
                 request_meta["response"] = func(*args, **kwargs)
             except Fault as e:
                 request_meta["exception"] = e
-            request_meta["response_time"] = (time.perf_counter() - start_time) * 1000
+            request_meta["response_time"] = (time.perf_counter() - start_perf_counter) * 1000
             self._request_event.fire(**request_meta)  # This is what makes the request actually get logged in Locust
             return request_meta["response"]
 

examples/grpc/locustfile.py

@@ -31,21 +31,22 @@ def __getattr__(self, name):
         func = self._stub_class.__getattribute__(self._stub, name)
 
         def wrapper(*args, **kwargs):
-            start_time = time.perf_counter()
             request_meta = {
                 "request_type": "grpc",
                 "name": name,
+                "start_time": time.time(),
                 "response_length": 0,
                 "exception": None,
                 "context": None,
                 "response": None,
             }
+            start_perf_counter = time.perf_counter()
             try:
                 request_meta["response"] = func(*args, **kwargs)
                 request_meta["response_length"] = len(request_meta["response"].message)
             except grpc.RpcError as e:
                 request_meta["exception"] = e
-            request_meta["response_time"] = (time.perf_counter() - start_time) * 1000
+            request_meta["response_time"] = (time.perf_counter() - start_perf_counter) * 1000
             events.request.fire(**request_meta)
             return request_meta["response"]
 

locust/clients.py

@@ -123,21 +123,27 @@ def request(self, method, url, name=None, catch_response=False, context={}, **kw
 
         # prepend url with hostname unless it's already an absolute URL
         url = self._build_url(url)
-        start_time = time.perf_counter()
 
+        start_time = time.time()
+        start_perf_counter = time.perf_counter()
         response = self._send_request_safe_mode(method, url, **kwargs)
+        response_time = (time.perf_counter() - start_perf_counter) * 1000
+
+        url_after_redirect = (response.history and response.history[0] or response).request.path_url
 
         if self.user:
             context = {**self.user.context(), **context}
 
         # store meta data that is used when reporting the request to locust's statistics
         request_meta = {
             "request_type": method,
-            "response_time": (time.perf_counter() - start_time) * 1000,
-            "name": name or (response.history and response.history[0] or response).request.path_url,
+            "response_time": response_time,
+            "name": name or url_after_redirect,
             "context": context,
             "response": response,
             "exception": None,
+            "start_time": start_time,
+            "url": url_after_redirect,
         }
 
         # get the length of the content, but if the argument stream is set to True, we take

locust/contrib/fasthttp.py

@@ -161,19 +161,11 @@ def request(
         # prepend url with hostname unless it's already an absolute URL
         url = self._build_url(path)
 
-        start_time = time.perf_counter()
+        start_time = time.time()  # seconds since epoch
 
         if self.user:
             context = {**self.user.context(), **context}
 
-        # store meta data that is used when reporting the request to locust's statistics
-        request_meta = {
-            "request_type": method,
-            "name": name or path,
-            "context": context,
-            "exception": None,
-        }
-
         headers = headers or {}
         if auth:
             headers["Authorization"] = _construct_basic_auth_str(auth[0], auth[1])
@@ -193,9 +185,18 @@ def request(
             old_redirect_response_codes = self.client.redirect_resonse_codes
             self.client.redirect_resonse_codes = []
 
+        start_perf_counter = time.perf_counter()
         # send request, and catch any exceptions
         response = self._send_request_safe_mode(method, url, payload=data, headers=headers, **kwargs)
-        request_meta["response"] = response
+        request_meta = {
+            "request_type": method,
+            "name": name or path,
+            "context": context,
+            "response": response,
+            "exception": None,
+            "start_time": start_time,
+            "url": path,  # this is a small deviation from HttpSession, which gets the final (possibly redirected) URL
+        }
 
         if not allow_redirects:
             self.client.redirect_resonse_codes = old_redirect_response_codes
@@ -208,7 +209,7 @@ def request(
             try:
                 request_meta["response_length"] = len(response.content or "")
             except HTTPParseError as e:
-                request_meta["response_time"] = (time.perf_counter() - start_time) * 1000
+                request_meta["response_time"] = (time.perf_counter() - start_perf_counter) * 1000
                 request_meta["response_length"] = 0
                 request_meta["exception"] = e
                 self.environment.events.request.fire(**request_meta)
@@ -217,7 +218,7 @@ def request(
         # Record the consumed time
         # Note: This is intentionally placed after we record the content_size above, since
         # we'll then trigger fetching of the body (unless stream=True)
-        request_meta["response_time"] = int((time.perf_counter() - start_time) * 1000)
+        request_meta["response_time"] = int((time.perf_counter() - start_perf_counter) * 1000)
 
         if catch_response:
             return ResponseContextManager(response, environment=self.environment, request_meta=request_meta)

locust/test/test_fasthttp.py

@@ -1,5 +1,6 @@
 import socket
 import gevent
+import time
 from tempfile import NamedTemporaryFile
 
 from locust.user import task, TaskSet
@@ -174,6 +175,24 @@ def test_catch_response_default_fail(self):
         self.assertEqual(1, self.environment.stats.total.num_requests)
         self.assertEqual(1, self.environment.stats.total.num_failures)
 
+    def test_error_message_with_name_replacement(self):
+        s = self.get_client()
+        kwargs = {}
+
+        def on_request(**kw):
+            self.assertIsNotNone(kw["exception"])
+            kwargs.update(kw)
+
+        self.environment.events.request.add_listener(on_request)
+        before_request = time.time()
+        s.request("get", "/wrong_url/01", name="replaced_url_name", context={"foo": "bar"})
+        after_request = time.time()
+        # self.assertIn("for url: replaced_url_name", str(kwargs["exception"])) # this is actually broken for FastHttpUser right now...
+        self.assertAlmostEqual(before_request, kwargs["start_time"], delta=0.01)
+        self.assertAlmostEqual(after_request, kwargs["start_time"] + kwargs["response_time"] / 1000, delta=0.01)
+        self.assertEqual("/wrong_url/01", kwargs["url"])  # url is unaffected by name
+        self.assertDictEqual({"foo": "bar"}, kwargs["context"])
+
 
 class TestRequestStatsWithWebserver(WebserverTestCase):
     def test_request_stats_content_length(self):

locust/test/test_http.py

@@ -1,7 +1,8 @@
+import time
+
 from locust.user.users import HttpUser
 from requests.exceptions import InvalidSchema, InvalidURL, MissingSchema, RequestException
 
-
 from locust.clients import HttpSession
 from locust.exception import ResponseError
 from .testcases import WebserverTestCase
@@ -170,8 +171,13 @@ def on_request(**kw):
             kwargs.update(kw)
 
         self.environment.events.request.add_listener(on_request)
+        before_request = time.time()
         s.request("get", "/wrong_url/01", name="replaced_url_name", context={"foo": "bar"})
+        after_request = time.time()
         self.assertIn("for url: replaced_url_name", str(kwargs["exception"]))
+        self.assertAlmostEqual(before_request, kwargs["start_time"], delta=0.01)
+        self.assertAlmostEqual(after_request, kwargs["start_time"] + kwargs["response_time"] / 1000, delta=0.01)
+        self.assertEqual("/wrong_url/01", kwargs["url"])  # url is unaffected by name
         self.assertDictEqual({"foo": "bar"}, kwargs["context"])
 
     def test_get_with_params(self):

locust/test/test_main.py

@@ -297,11 +297,11 @@ def my_task(self):
             gevent.sleep(1)
             proc.send_signal(signal.SIGTERM)
             stdout, stderr = proc.communicate()
-            self.assertEqual(0, proc.returncode)
             stderr = stderr.decode("utf-8")
             self.assertIn("Starting web interface at", stderr)
             self.assertIn("Starting Locust", stderr)
             self.assertIn("Shutting down (exit code 0), bye", stderr)
+            self.assertEqual(0, proc.returncode)
 
     def test_default_headless_spawn_options(self):
         with mock_locustfile() as mocked:
@@ -318,6 +318,8 @@ def test_default_headless_spawn_options(self):
                         "--headless",
                         "--loglevel",
                         "DEBUG",
+                        "--exit-code-on-error",
+                        "0",
                     ],
                     stderr=subprocess.STDOUT,
                     timeout=2,
@@ -330,18 +332,27 @@ def test_default_headless_spawn_options(self):
     def test_headless_spawn_options_wo_run_time(self):
         with mock_locustfile() as mocked:
             proc = subprocess.Popen(
-                ["locust", "-f", mocked.file_path, "--host", "https://test.com/", "--headless"],
+                [
+                    "locust",
+                    "-f",
+                    mocked.file_path,
+                    "--host",
+                    "https://test.com/",
+                    "--headless",
+                    "--exit-code-on-error",
+                    "0",
+                ],
                 stdout=PIPE,
                 stderr=PIPE,
             )
             gevent.sleep(1)
             proc.send_signal(signal.SIGTERM)
             stdout, stderr = proc.communicate()
-            self.assertEqual(0, proc.returncode)
             stderr = stderr.decode("utf-8")
             self.assertIn("Starting Locust", stderr)
             self.assertIn("No run time limit set, use CTRL+C to interrupt", stderr)
             self.assertIn("Shutting down (exit code 0), bye", stderr)
+            self.assertEqual(0, proc.returncode)
 
     def test_default_headless_spawn_options_with_shape(self):
         content = MOCK_LOCUSTFILE_CONTENT + textwrap.dedent(
@@ -356,17 +367,36 @@ def tick(self):
             """
         )
         with mock_locustfile(content=content) as mocked:
-            output = (
-                subprocess.check_output(
-                    ["locust", "-f", mocked.file_path, "--host", "https://test.com/", "--headless"],
-                    stderr=subprocess.STDOUT,
-                    timeout=3,
-                )
-                .decode("utf-8")
-                .strip()
+            proc = subprocess.Popen(
+                [
+                    "locust",
+                    "-f",
+                    mocked.file_path,
+                    "--host",
+                    "https://test.com/",
+                    "--headless",
+                    "--exit-code-on-error",
+                    "0",
+                ],
+                stdout=PIPE,
+                stderr=PIPE,
             )
-            self.assertIn("Shape test updating to 10 users at 1.00 spawn rate", output)
-            self.assertIn("Cleaning up runner...", output)
+
+            try:
+                success = True
+                _, stderr = proc.communicate(timeout=5)
+            except subprocess.TimeoutExpired:
+                success = False
+                proc.send_signal(signal.SIGTERM)
+                _, stderr = proc.communicate()
+
+            proc.send_signal(signal.SIGTERM)
+            _, stderr = proc.communicate()
+            stderr = stderr.decode("utf-8")
+            self.assertIn("Shape test updating to 10 users at 1.00 spawn rate", stderr)
+            self.assertIn("Cleaning up runner...", stderr)
+            self.assertEqual(0, proc.returncode)
+            self.assertTrue(success, "got timeout and had to kill the process")
 
     def test_autostart_wo_run_time(self):
         port = get_free_tcp_port()
@@ -467,14 +497,23 @@ def tick(self):
             )
             gevent.sleep(1.9)
             response = requests.get(f"http://0.0.0.0:{port}/")
-            _, stderr = proc.communicate(timeout=3)
+            try:
+                success = True
+                _, stderr = proc.communicate(timeout=5)
+            except subprocess.TimeoutExpired:
+                success = False
+                proc.send_signal(signal.SIGTERM)
+                _, stderr = proc.communicate()
+
             stderr = stderr.decode("utf-8")
             self.assertIn("Starting Locust", stderr)
             self.assertIn("Shape test starting", stderr)
             self.assertIn("Shutting down ", stderr)
+            self.assertIn("autoquit time reached", stderr)
             # check response afterwards, because it really isnt as informative as stderr
             self.assertEqual(200, response.status_code)
             self.assertIn('<body class="spawning">', response.text)
+            self.assertTrue(success, "got timeout and had to kill the process")
 
     def test_web_options(self):
         port = get_free_tcp_port()
@@ -591,6 +630,8 @@ def test_html_report_option(self):
                                 "--run-time",
                                 "2s",
                                 "--headless",
+                                "--exit-code-on-error",
+                                "0",
                                 "--html",
                                 html_report_file_path,
                             ],