Unhandled exception: stream ended at an unexpected time #1457

bendizen · 2020-06-29T22:31:57Z

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

The text was updated successfully, but these errors were encountered:

cyberw · 2020-06-30T13:40:15Z

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

bendizen · 2020-06-30T15:45:18Z

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)

magupov · 2020-06-30T17:05:46Z

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

cyberw · 2020-06-30T17:25:14Z

Does it work with the standard HttpUser?

bendizen · 2020-06-30T17:47:27Z

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

cyberw · 2020-07-01T07:09:04Z

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?

bendizen · 2020-07-01T14:20:14Z

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.

cyberw · 2020-07-01T21:32:41Z

Try adding ChunkedEncodingError to the list here:

locust/locust/contrib/fasthttp.py

Line 38 in bca88b0

FAILURE_EXCEPTIONS = (ConnectionError, ConnectionRefusedError, socket.error, \

bendizen · 2020-07-01T22:00:47Z

@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 <module>
    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 "<frozen importlib._bootstrap_external>", line 462, in _check_name_wrapper
  File "<frozen importlib._bootstrap_external>", line 962, in load_module
  File "<frozen importlib._bootstrap_external>", line 787, in load_module
  File "<frozen importlib._bootstrap>", line 265, in _load_module_shim
  File "<frozen importlib._bootstrap>", line 702, in _load
  File "<frozen importlib._bootstrap>", line 671, in _load_unlocked
  File "<frozen importlib._bootstrap_external>", line 783, in exec_module
  File "<frozen importlib._bootstrap>", line 219, in _call_with_frames_removed
  File "/home/mkarlovich/source/locust-plugins/examples/fast_csvreader_ex.py", line 3, in <module>
    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 <module>
    FAILURE_EXCEPTIONS = (ConnectionError, ConnectionRefusedError, ChunkedEncodingError, socket.error, \
NameError: name 'ChunkedEncodingError' is not defined

cyberw · 2020-07-02T07:33:51Z

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

cyberw · 2020-07-02T10:49:49Z

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

bendizen · 2020-07-02T16:51:29Z

@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)

cyberw · 2020-07-02T17:32:40Z

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 .)

magupov · 2020-07-02T18:21:05Z

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

locust/locust/contrib/fasthttp.py

Line 237 in fbfadad

request_meta["content_size"] = len(response.content or "")

and that part isn't wrapped by try/except

cyberw · 2020-07-02T19:46:49Z

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

locust/locust/contrib/fasthttp.py

Line 237 in fbfadad

request_meta["content_size"] = len(response.content or "")

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 · 2020-07-03T09:24:07Z

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

magupov · 2020-07-04T08:19:25Z

That works for me and marks wrong packets as a failure
#1464

bendizen · 2020-07-06T15:02:53Z

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

bendizen added the bug label Jun 29, 2020

magupov mentioned this issue Jul 4, 2020

Handle http parse exceptions #1464

Merged

cyberw closed this as completed in #1464 Jul 4, 2020

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

Unhandled exception: stream ended at an unexpected time #1457

Unhandled exception: stream ended at an unexpected time #1457

bendizen commented Jun 29, 2020 •

edited

Loading

cyberw commented Jun 30, 2020

bendizen commented Jun 30, 2020

magupov commented Jun 30, 2020 •

edited

Loading

cyberw commented Jun 30, 2020

bendizen commented Jun 30, 2020 •

edited

Loading

cyberw commented Jul 1, 2020 •

edited

Loading

bendizen commented Jul 1, 2020 •

edited

Loading

cyberw commented Jul 1, 2020

bendizen commented Jul 1, 2020 •

edited

Loading

cyberw commented Jul 2, 2020

cyberw commented Jul 2, 2020 •

edited

Loading

bendizen commented Jul 2, 2020

cyberw commented Jul 2, 2020 •

edited

Loading

magupov commented Jul 2, 2020 •

edited

Loading

cyberw commented Jul 2, 2020 •

edited

Loading

cyberw commented Jul 3, 2020

magupov commented Jul 4, 2020 •

edited

Loading

bendizen commented Jul 6, 2020

Unhandled exception: stream ended at an unexpected time #1457

Unhandled exception: stream ended at an unexpected time #1457

Comments

bendizen commented Jun 29, 2020 • edited Loading

Describe the bug

Expected behavior

Actual behavior

Steps to reproduce

Environment

cyberw commented Jun 30, 2020

bendizen commented Jun 30, 2020

magupov commented Jun 30, 2020 • edited Loading

cyberw commented Jun 30, 2020

bendizen commented Jun 30, 2020 • edited Loading

cyberw commented Jul 1, 2020 • edited Loading

bendizen commented Jul 1, 2020 • edited Loading

cyberw commented Jul 1, 2020

bendizen commented Jul 1, 2020 • edited Loading

cyberw commented Jul 2, 2020

cyberw commented Jul 2, 2020 • edited Loading

bendizen commented Jul 2, 2020

cyberw commented Jul 2, 2020 • edited Loading

magupov commented Jul 2, 2020 • edited Loading

cyberw commented Jul 2, 2020 • edited Loading

cyberw commented Jul 3, 2020

magupov commented Jul 4, 2020 • edited Loading

bendizen commented Jul 6, 2020

bendizen commented Jun 29, 2020 •

edited

Loading

magupov commented Jun 30, 2020 •

edited

Loading

bendizen commented Jun 30, 2020 •

edited

Loading

cyberw commented Jul 1, 2020 •

edited

Loading

bendizen commented Jul 1, 2020 •

edited

Loading

bendizen commented Jul 1, 2020 •

edited

Loading

cyberw commented Jul 2, 2020 •

edited

Loading

cyberw commented Jul 2, 2020 •

edited

Loading

magupov commented Jul 2, 2020 •

edited

Loading

cyberw commented Jul 2, 2020 •

edited

Loading

magupov commented Jul 4, 2020 •

edited

Loading