diff --git a/docs/extending-locust.rst b/docs/extending-locust.rst index 8feff45a5b..d2c4097d0c 100644 --- a/docs/extending-locust.rst +++ b/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: diff --git a/examples/custom_xmlrpc_client/xmlrpc_locustfile.py b/examples/custom_xmlrpc_client/xmlrpc_locustfile.py index f878ff0a4d..75a48fd737 100644 --- a/examples/custom_xmlrpc_client/xmlrpc_locustfile.py +++ b/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"] diff --git a/examples/grpc/locustfile.py b/examples/grpc/locustfile.py index bfb1bda6b4..1a405ebf7b 100644 --- a/examples/grpc/locustfile.py +++ b/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"] diff --git a/locust/clients.py b/locust/clients.py index fa7fe57913..d01a9b1b84 100644 --- a/locust/clients.py +++ b/locust/clients.py @@ -123,9 +123,13 @@ 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} @@ -133,11 +137,13 @@ def request(self, method, url, name=None, catch_response=False, context={}, **kw # 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 diff --git a/locust/contrib/fasthttp.py b/locust/contrib/fasthttp.py index b11ddffafe..6b38ca2ead 100644 --- a/locust/contrib/fasthttp.py +++ b/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) diff --git a/locust/test/test_fasthttp.py b/locust/test/test_fasthttp.py index 62d22e30d6..f712bfc145 100644 --- a/locust/test/test_fasthttp.py +++ b/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): diff --git a/locust/test/test_http.py b/locust/test/test_http.py index 2932393ece..fb14fc5259 100644 --- a/locust/test/test_http.py +++ b/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): diff --git a/locust/test/test_main.py b/locust/test/test_main.py index 1f4f2dd27a..5fbcd16991 100644 --- a/locust/test/test_main.py +++ b/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('', 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, ],