Repository: locustio/locust

Issue:
Samples with response_time None crashes stats.py
Certain async protocols/clients (like websockets, MQ etc) dont really have a response time. They should be able to report a None response time. Using zero is not good enough, because a test may contain a mix of synchronous requests (like HTTP) and async, and we dont want to "taint" the average response time with zeroes.

```
from locust import HttpLocust, task, TaskSet
from locust.events import request_success

class UserBehavior(TaskSet):
    @task
    def my_task(self):
        request_success.fire(request_type="foo", name="bar", response_time=None, response_length=0)


class MyHttpLocust(HttpLocust):
    task_set = UserBehavior
```

Result:
```
[2019-09-22 09:57:13,877] lafp-mac-JG5J.int.svenskaspel.se/ERROR/stderr: Traceback (most recent call last):
  File "/Users/lafp/git/locust/locust/core.py", line 361, in run
    self.execute_next_task()
  File "/Users/lafp/git/locust/locust/core.py", line 387, in execute_next_task
    self.execute_task(task["callable"], *task["args"], **task["kwargs"])
  File "/Users/lafp/git/locust/locust/core.py", line 399, in execute_task
    task(self, *args, **kwargs)
  File "/Users/lafp/git/locust-plugins/examples/foo.py", line 10, in my_task
    request_success.fire(request_type="foo", name="bar", response_time=None, response_length=0)
  File "/Users/lafp/git/locust/locust/events.py", line 34, in fire
    handler(**kwargs)
  File "/Users/lafp/git/locust/locust/stats.py", line 559, in on_request_success
    global_stats.log_request(request_type, name, response_time, response_length)
  File "/Users/lafp/git/locust/locust/stats.py", line 93, in log_request
    self.total.log(response_time, content_length)
  File "/Users/lafp/git/locust/locust/stats.py", line 239, in log
    self._log_response_time(response_time)
  File "/Users/lafp/git/locust/locust/stats.py", line 250, in _log_response_time
    self.total_response_time += response_time
TypeError: unsupported operand type(s) for +=: 'int' and 'NoneType'
```

Discussion:
codecov[bot]: # [Codecov](https://codecov.io/gh/locustio/locust/pull/1088?src=pr&el=h1) Report
> Merging [#1088](https://codecov.io/gh/locustio/locust/pull/1088?src=pr&el=desc) into [master](https://codecov.io/gh/locustio/locust/commit/644496f5548ceb5a9ff4220aa808ec25a4c9a143?src=pr&el=desc) will **decrease** coverage by `0.12%`.
> The diff coverage is `0%`.

[![Impacted file tree graph](https://codecov.io/gh/locustio/locust/pull/1088/graphs/tree.svg?width=650&token=RyxsllhZ27&height=150&src=pr)](https://codecov.io/gh/locustio/locust/pull/1088?src=pr&el=tree)

```diff
@@            Coverage Diff             @@
##           master    #1088      +/-   ##
==========================================
- Coverage   72.29%   72.16%   -0.13%     
==========================================
  Files          17       17              
  Lines        1700     1703       +3     
  Branches      253      254       +1     
==========================================
  Hits         1229     1229              
- Misses        408      410       +2     
- Partials       63       64       +1
```


| [Impacted Files](https://codecov.io/gh/locustio/locust/pull/1088?src=pr&el=tree) | Coverage Δ | |
|---|---|---|
| [locust/stats.py](https://codecov.io/gh/locustio/locust/pull/1088/diff?src=pr&el=tree#diff-bG9jdXN0L3N0YXRzLnB5) | `79.89% <0%> (-0.65%)` | :arrow_down: |

------

[Continue to review full report at Codecov](https://codecov.io/gh/locustio/locust/pull/1088?src=pr&el=continue).
> **Legend** - [Click here to learn more](https://docs.codecov.io/docs/codecov-delta)
> `Δ = absolute <relative> (impact)`, `ø = not affected`, `? = missing data`
> Powered by [Codecov](https://codecov.io/gh/locustio/locust/pull/1088?src=pr&el=footer). Last update [644496f...6b13bea](https://codecov.io/gh/locustio/locust/pull/1088?src=pr&el=lastupdated). Read the [comment docs](https://docs.codecov.io/docs/pull-request-comments).


Patch:
diff --git a/locust/stats.py b/locust/stats.py
index b49beaf3..e27076c3 100644
--- a/locust/stats.py
+++ b/locust/stats.py
@@ -52,6 +52,8 @@ def calculate_response_time_percentile(response_times, num_requests, percent):
         processed_count += response_times[response_time]
         if(num_requests - processed_count <= num_of_request):
             return response_time
+    # if all response times were None
+    return 0
 
 
 def diff_response_time_dicts(latest, old):
@@ -81,6 +83,10 @@ class RequestStats(object):
     def num_requests(self):
         return self.total.num_requests
     
+    @property
+    def num_none_requests(self):
+        return self.total.num_none_requests
+
     @property
     def num_failures(self):
         return self.total.num_failures
@@ -155,6 +161,9 @@ class StatsEntry(object):
     num_requests = None
     """ The number of requests made """
     
+    num_none_requests = None
+    """ The number of requests made with a None response time (typically async requests) """
+
     num_failures = None
     """ Number of failed request """
     
@@ -214,6 +223,7 @@ class StatsEntry(object):
     def reset(self):
         self.start_time = time.time()
         self.num_requests = 0
+        self.num_none_requests = 0
         self.num_failures = 0
         self.total_response_time = 0
         self.response_times = {}
@@ -246,6 +256,9 @@ class StatsEntry(object):
         self.last_request_timestamp = t
 
     def _log_response_time(self, response_time):
+        if response_time is None:
+            self.num_none_requests += 1
+            return
 
         self.total_response_time += response_time
 
@@ -287,7 +300,7 @@ class StatsEntry(object):
     @property
     def avg_response_time(self):
         try:
-            return float(self.total_response_time) / self.num_requests
+            return float(self.total_response_time) / (self.num_requests - self.num_none_requests)
         except ZeroDivisionError:
             return 0
 
@@ -295,7 +308,7 @@ class StatsEntry(object):
     def median_response_time(self):
         if not self.response_times:
             return 0
-        median = median_from_dict(self.num_requests, self.response_times)
+        median = median_from_dict(self.num_requests - self.num_none_requests, self.response_times) or 0
 
         # Since we only use two digits of precision when calculating the median response time 
         # while still using the exact values for min and max response times, the following checks 
@@ -340,6 +353,7 @@ class StatsEntry(object):
         self.start_time = min(self.start_time, other.start_time)
 
         self.num_requests = self.num_requests + other.num_requests
+        self.num_none_requests = self.num_none_requests + other.num_none_requests
         self.num_failures = self.num_failures + other.num_failures
         self.total_response_time = self.total_response_time + other.total_response_time
         self.max_response_time = max(self.max_response_time, other.max_response_time)
@@ -362,6 +376,7 @@ class StatsEntry(object):
             "last_request_timestamp": self.last_request_timestamp,
             "start_time": self.start_time,
             "num_requests": self.num_requests,
+            "num_none_requests": self.num_none_requests,
             "num_failures": self.num_failures,
             "total_response_time": self.total_response_time,
             "max_response_time": self.max_response_time,
@@ -378,6 +393,7 @@ class StatsEntry(object):
             "last_request_timestamp",
             "start_time",
             "num_requests",
+            "num_none_requests",
             "num_failures",
             "total_response_time",
             "max_response_time",


Test patch:
diff --git a/locust/test/test_runners.py b/locust/test/test_runners.py
index 14ad50f9..ef70f726 100644
--- a/locust/test/test_runners.py
+++ b/locust/test/test_runners.py
@@ -159,6 +159,35 @@ class TestMasterRunner(LocustTestCase):
             s = master.stats.get("/", "GET")
             self.assertEqual(700, s.median_response_time)
 
+    def test_slave_stats_report_with_none_response_times(self):
+        class MyTestLocust(Locust):
+            pass
+        
+        with mock.patch("locust.rpc.rpc.Server", mocked_rpc_server()) as server:
+            master = MasterLocustRunner(MyTestLocust, self.options)
+            server.mocked_send(Message("client_ready", None, "fake_client"))
+            
+            master.stats.get("/mixed", "GET").log(0, 23455)
+            master.stats.get("/mixed", "GET").log(800, 23455)
+            master.stats.get("/mixed", "GET").log(700, 23455)
+            master.stats.get("/mixed", "GET").log(None, 23455)
+            master.stats.get("/mixed", "GET").log(None, 23455)
+            master.stats.get("/mixed", "GET").log(None, 23455)
+            master.stats.get("/mixed", "GET").log(None, 23455)
+            master.stats.get("/onlyNone", "GET").log(None, 23455)
+            
+            data = {"user_count":1}
+            events.report_to_master.fire(client_id="fake_client", data=data)
+            master.stats.clear_all()
+            
+            server.mocked_send(Message("stats", data, "fake_client"))
+            s1 = master.stats.get("/mixed", "GET")
+            self.assertEqual(700, s1.median_response_time)
+            self.assertEqual(500, s1.avg_response_time)            
+            s2 = master.stats.get("/onlyNone", "GET")
+            self.assertEqual(0, s2.median_response_time)
+            self.assertEqual(0, s2.avg_response_time)
+
     def test_master_marks_downed_slaves_as_missing(self):
         class MyTestLocust(Locust):
             pass
@@ -195,7 +224,43 @@ class TestMasterRunner(LocustTestCase):
                 "user_count": 2,
             }, "fake_client"))
             self.assertEqual(700, master.stats.total.median_response_time)
-    
+
+    def test_master_total_stats_with_none_response_times(self):
+        class MyTestLocust(Locust):
+            pass
+        
+        with mock.patch("locust.rpc.rpc.Server", mocked_rpc_server()) as server:
+            master = MasterLocustRunner(MyTestLocust, self.options)
+            server.mocked_send(Message("client_ready", None, "fake_client"))
+            stats = RequestStats()
+            stats.log_request("GET", "/1", 100, 3546)
+            stats.log_request("GET", "/1", 800, 56743)
+            stats.log_request("GET", "/1", None, 56743)
+            stats2 = RequestStats()
+            stats2.log_request("GET", "/2", 700, 2201)
+            stats2.log_request("GET", "/2", None, 2201)
+            stats3 = RequestStats()
+            stats3.log_request("GET", "/3", None, 2201)
+            server.mocked_send(Message("stats", {
+                "stats":stats.serialize_stats(), 
+                "stats_total": stats.total.serialize(),
+                "errors":stats.serialize_errors(),
+                "user_count": 1,
+            }, "fake_client"))
+            server.mocked_send(Message("stats", {
+                "stats":stats2.serialize_stats(), 
+                "stats_total": stats2.total.serialize(),
+                "errors":stats2.serialize_errors(),
+                "user_count": 2,
+            }, "fake_client"))
+            server.mocked_send(Message("stats", {
+                "stats":stats3.serialize_stats(), 
+                "stats_total": stats3.total.serialize(),
+                "errors":stats3.serialize_errors(),
+                "user_count": 2,
+            }, "fake_client"))
+            self.assertEqual(700, master.stats.total.median_response_time)
+        
     def test_master_current_response_times(self):
         class MyTestLocust(Locust):
             pass
diff --git a/locust/test/test_stats.py b/locust/test/test_stats.py
index 0250231e..444426c7 100644
--- a/locust/test/test_stats.py
+++ b/locust/test/test_stats.py
@@ -19,12 +19,14 @@ class TestRequestStats(unittest.TestCase):
         self.s.log(45, 0)
         self.s.log(135, 0)
         self.s.log(44, 0)
+        self.s.log(None, 0)        
         self.s.log_error(Exception("dummy fail"))
         self.s.log_error(Exception("dummy fail"))
         self.s.log(375, 0)
         self.s.log(601, 0)
         self.s.log(35, 0)
         self.s.log(79, 0)
+        self.s.log(None, 0)        
         self.s.log_error(Exception("dummy fail"))
 
     def test_percentile(self):
@@ -48,17 +50,17 @@ class TestRequestStats(unittest.TestCase):
         self.assertEqual(s.median_response_time, 6099)
 
     def test_total_rps(self):
-        self.assertEqual(self.s.total_rps, 7)
+        self.assertEqual(self.s.total_rps, 9)
 
     def test_current_rps(self):
         self.stats.total.last_request_timestamp = int(time.time()) + 4
-        self.assertEqual(self.s.current_rps, 3.5)
+        self.assertEqual(self.s.current_rps, 4.5)
 
         self.stats.total.last_request_timestamp = int(time.time()) + 25
         self.assertEqual(self.s.current_rps, 0)
 
     def test_num_reqs_fails(self):
-        self.assertEqual(self.s.num_requests, 7)
+        self.assertEqual(self.s.num_requests, 9)
         self.assertEqual(self.s.num_failures, 3)
 
     def test_avg(self):
@@ -76,6 +78,13 @@ class TestRequestStats(unittest.TestCase):
         self.assertEqual(self.s.avg_response_time, 420.5)
         self.assertEqual(self.s.median_response_time, 85)
     
+    def test_avg_only_none(self):
+        self.s.reset()
+        self.s.log(None, 123)
+        self.assertEqual(self.s.avg_response_time, 0)
+        self.assertEqual(self.s.median_response_time, 0)
+        self.assertEqual(self.s.get_response_time_percentile(0.5), 0)
+
     def test_reset_min_response_time(self):
         self.s.reset()
         self.s.log(756, 0)