Locust: Unhandled exception: stream ended at an unexpected time

Created on 30 Jun 2020 · 18Comments · Source: locustio/locust

Describe the bug

I running a test pulling large files (some > 250mb) using the fast client, when connection gets dropped ("stream ended at an unexpected time") on some files it throws an unhandled exception and does not log a failure.

Exception:
Traceback (most recent call last):
File "/home/mkarlovich/.pyenv/versions/3.8.2/lib/python3.8/site-packages/geventhttpclient/useragent.py", line 184, in content
return self._cached_content
AttributeError: _cached_content

During handling of the above exception, another exception occurred:

Traceback (most recent call last):
File "/home/mkarlovich/.pyenv/versions/3.8.2/lib/python3.8/site-packages/locust/user/task.py", line 284, in run
self.execute_next_task()
File "/home/mkarlovich/.pyenv/versions/3.8.2/lib/python3.8/site-packages/locust/user/task.py", line 309, in execute_next_task
self.execute_task(self._task_queue.pop(0))
File "/home/mkarlovich/.pyenv/versions/3.8.2/lib/python3.8/site-packages/locust/user/task.py", line 416, in execute_task
task(self.user)
File "/home/mkarlovich/source/locust-plugins/examples/fast_csvreader_ex.py", line 17, in index
self.client.get(url, headers=headers)
File "/home/mkarlovich/.pyenv/versions/3.8.2/lib/python3.8/site-packages/locust/contrib/fasthttp.py", line 272, in get
return self.request("GET", path, **kwargs)
File "/home/mkarlovich/.pyenv/versions/3.8.2/lib/python3.8/site-packages/locust/contrib/fasthttp.py", line 237, in request
request_meta["content_size"] = len(response.content or "")
File "/home/mkarlovich/.pyenv/versions/3.8.2/lib/python3.8/site-packages/geventhttpclient/useragent.py", line 186, in content
self._cached_content = self._content()
File "/home/mkarlovich/.pyenv/versions/3.8.2/lib/python3.8/site-packages/locust/contrib/fasthttp.py", line 340, in _content
return super(FastResponse, self)._content()
File "/home/mkarlovich/.pyenv/versions/3.8.2/lib/python3.8/site-packages/geventhttpclient/useragent.py", line 201, in _content
ret = self._response.read()
File "/home/mkarlovich/.pyenv/versions/3.8.2/lib/python3.8/site-packages/geventhttpclient/response.py", line 260, in read
self.feed(data)
_parser.HTTPParseError: ('stream ended at an unexpected time', 11)

Expected behavior

It should handle this exception and report it as a failure.

Actual behavior

Workers throw exception but no failure is recorded

Steps to reproduce

I can't reproduce it except under load, code is using script below which constructs file download urls from csv file.

Environment

OS: Ubuntu 16.04 master and workers
Python version: 3.8.2
Locust version: 1.0.3
Locust command line that you ran:

locust -f fast_csvreader_ex.py --master --expect-workers 10 --headless -u 100 -r 1 -t 60m --csv=test100u60m10w
locust -f fast_csvreader_ex.py --worker --master-host=10.66.11.21 & # run 5 per worker machine

Locust file contents (anonymized if necessary):
```
from locust_plugins.csvreader import CSVReader
from locust import task
from locust.contrib.fasthttp import FastHttpUser
import traceback, logging, sys
import locust.stats
locust.stats.CSV_STATS_INTERVAL_SEC = 5

id_reader = CSVReader("ids.csv")

class MyUser(FastHttpUser):
@task
def index(self):
headers = { "Authorization": "apikey", "Accept": "application/json" }
feed_id, file_id = next(id_reader)
url = f'/feeds/{feed_id}/files/{file_id}'
self.client.get(url, headers=headers)

host = 'https://my-test-sever.com'
connection_timeout = 6000.0
network_timeout = 6000.0

bug

Source

mkarlovich

Most helpful comment

That works for me and marks wrong packets as a failure
https://github.com/locustio/locust/pull/1464

magupov on 4 Jul 2020

👍2

All 18 comments

Interesting! Do you think you could have a look at fixing it yourself?

cyberw on 30 Jun 2020

I am a python newbie, I could use some help on this one! I get these errors in Jmeter as well, but they are handled. Unfortunately Jmeter is not memory efficient enough for me to run these tests with resources I have. I believe this is the equivalent:
```
Thread Name:Thread Group 1-28
Sample Start:2020-06-10 11:35:48 PDT
Load time:121478
Connect Time:48
Latency:144
Size in bytes:1327
Sent bytes:0
Headers size in bytes:0
Body size in bytes:0
Sample Count:1
Error Count:1
Data type ("text"|"bin"|""):text
Response code:Non HTTP response code: org.apache.http.ConnectionClosedException
Response message:Non HTTP response message: Premature end of Content-Length delimited message body (expected: 254,887,721; received: 177,220,663)

mkarlovich on 30 Jun 2020

I had the same issue recently, the interesting part is that the tested server sent status 200 with such responses. And that issue happened when the server sent not the full payload

magupov on 30 Jun 2020

Does it work with the standard HttpUser?

cyberw on 30 Jun 2020

Yes... only for me the CPU usage becomes a bottleneck for higher load with standard HttpUser. Error from standard HttpUser is recorded in the failure csv thus:

"GET","/feeds//157/files/<file_id>","ChunkedEncodingError(ProtocolError('Connection broken: IncompleteRead(8958 bytes read, 1282 more expected)', IncompleteRead(8958 bytes read, 1282 more expected)))",1

Without the fast client I get this:
```
Loadgen CPU usage above 90%! This may constrain your throughput and may even give inconsistent response time measurements! See https://docs.locust.io/en/stable/running-locust-distributed.html for how to distribute the load over multiple CPU cores or machines

mkarlovich on 30 Jun 2020

Hopefully it only requires adding a try/except in the appropriate place in fasthttp.py. Is there a publicly available site I can test it against?

cyberw on 1 Jul 2020

I can't expose the site I'm using, I'd be happy to test it though if you want to try. Appreciate any help.

mkarlovich on 1 Jul 2020

Try adding ChunkedEncodingError to the list here: https://github.com/locustio/locust/blob/bca88b0745055ecfd26a135459847ffdc9afb5df/locust/contrib/fasthttp.py#L38

cyberw on 1 Jul 2020

@cyberw I think need to import this from somewhere?

Got:
FAILURE_EXCEPTIONS = (ConnectionError, ConnectionRefusedError, ChunkedEncodingError, socket.error, \ NameError: name 'ChunkedEncodingError' is not defined

Full trace
```
Traceback (most recent call last):
File "/home/mkarlovich/.pyenv/versions/3.8.2/bin/locust", line 10, in
sys.exit(main())
File "/home/mkarlovich/.pyenv/versions/3.8.2/lib/python3.8/site-packages/locust/main.py", line 113, in main
docstring, user_classes = load_locustfile(locustfile)
File "/home/mkarlovich/.pyenv/versions/3.8.2/lib/python3.8/site-packages/locust/main.py", line 77, in load_locustfile
imported = __import_locustfile__(locustfile, path)
File "/home/mkarlovich/.pyenv/versions/3.8.2/lib/python3.8/site-packages/locust/main.py", line 53, in __import_locustfile__
return source.load_module()
File "", line 462, in _check_name_wrapper
File "", line 962, in load_module
File "", line 787, in load_module
File "", line 265, in _load_module_shim
File "", line 702, in _load
File "", line 671, in _load_unlocked
File "", line 783, in exec_module
File "", line 219, in _call_with_frames_removed
File "/home/mkarlovich/source/locust-plugins/examples/fast_csvreader_ex.py", line 3, in
from locust.contrib.fasthttp import FastHttpUser
File "/home/mkarlovich/.pyenv/versions/3.8.2/lib/python3.8/site-packages/locust/contrib/fasthttp.py", line 39, in
FAILURE_EXCEPTIONS = (ConnectionError, ConnectionRefusedError, ChunkedEncodingError, socket.error, \
NameError: name 'ChunkedEncodingError' is not defined

mkarlovich on 2 Jul 2020

Yes. Probably from the same place some of the other errors are imported.

cyberw on 2 Jul 2020

Wait, reading the call stack better, I think we should catch HTTPParseError. import it by doing this:
from geventhttpclient._parser import HTTPParseError

cyberw on 2 Jul 2020

@cyberw I added HTTPParseError to master and workers, and also tried AttributeError but it's still not trapping or reporting the error. It still throws to stdout of the workers and does not report.

Added:

from geventhttpclient._parser import HTTPParseError

and
```
FAILURE_EXCEPTIONS = (ConnectionError, ConnectionRefusedError, AttributeError, HTTPParseError, socket.error, \
SSLError, Timeout, HTTPConnectionClosed)

mkarlovich on 2 Jul 2020

hmm. that should have worked. Are you sure you are running the correct version of locust that you have edited? (downloaded from git and installed using pip install -e .)

cyberw on 2 Jul 2020

For me it doesn't work either. As I see the exception is issued from here: https://github.com/locustio/locust/blob/fbfadad8e928e0850831deaf755521d9970c5286/locust/contrib/fasthttp.py#L237 and that part isn't wrapped by try/except

magupov on 2 Jul 2020

👍1

For me it doesn't work either. As I see the exception is issued from here:

https://github.com/locustio/locust/blob/fbfadad8e928e0850831deaf755521d9970c5286/locust/contrib/fasthttp.py#L237

and that part isn't wrapped by try/except

Ah. That explains it. I guess we need to wrap that line in a separate try/except, catching HTTPParseError there & firing the request_failure event.

At least, I didnt see a way of doing it any "nicer" than that.

cyberw on 2 Jul 2020

If one of you do that and validate that it works, I'd be happy to merge a PR.

cyberw on 3 Jul 2020

That works for me and marks wrong packets as a failure
https://github.com/locustio/locust/pull/1464

magupov on 4 Jul 2020

👍2

@cyberw thank you! This is working for me as well.

mkarlovich on 6 Jul 2020

👍1

Was this page helpful?