LoadTestShape run_time broken when using test_start and test_stop decorators

[laakejs]

Describe the bug

When using the LoadTestShape class in combination with @events.test_start.add_listener and @events.test_stop.add_listener, the run_time does not work as expected. The tick function is called once BEFORE the @events.test_start.add_listener function runs. Next, the content of the @events.test_start.add_listener function is executed which in our case takes quite a while as we are faking data. When it is finished the actual CustomShape loadtest starts, however the time was running in the background all the time, so the get_run_time() function returns pretty high numbers. If there are stages that would still run at that time locust now seems to start them and we get some load on our Api. But even more confusing the @events.test_start.add_listener seems to run again, this time in parallel wit the actual loadtest.

Expected behavior

If there is a class extending the LoadTestShape class, it should be instantiated (and the time should start to tick) AFTER the @events.test_start.add_listener function finished. Otherwise it is dependent on the runtime of preparation actions. Also it should not cause @events.test_start.add_listener to run again.

Actual behavior

The tick function is called once BEFORE the @events.test_start.add_listener function runs and the time keeps running in the background. Additionally it seems to start events.test_start.add_listener again in parallel to the loadtest.

Steps to reproduce

import logging
import time

from locust import HttpUser, LoadTestShape, between, events, task
from utils import get_api_credentials, get_host

@events.test_start.add_listener
def on_test_start(**kwargs):
logging.info("on_test_start started running")
time.sleep(317)
logging.info("on_test_start finished")

@events.test_stop.add_listener
def on_test_stop(**kwargs):
logging.info("on_test_stop started running")
time.sleep(317)
logging.info("on_test_stop finished")

class Api1(HttpUser):
wait_time = between(1, 10)
host = get_host()
credentials = get_api_credentials()

@task
def task1(self):
    self.client.get("/foo", auth=self.credentials, timeout=0.2)

@task
def task2(self):
    self.client.get("/bar", auth=self.credentials, timeout=0.2)

@task
def task3(self):
    self.client.get("/misc", auth=self.credentials, timeout=0.2)

class StagesShape(LoadTestShape):

stages = [
    {"duration": 120, "users": 100, "spawn_rate": 1},
    {"duration": 300, "users": 500, "spawn_rate": 10},
    {"duration": 500, "users": 500, "spawn_rate": 10},
]

def tick(self):
    run_time = self.get_run_time()
    logging.info(f"Loadtest running with runtime={run_time}")
    for stage in self.stages:
        if run_time < stage["duration"]:
            tick_data = (stage["users"], stage["spawn_rate"])
            return tick_data
    logging.info("end loadtest")
    return None

locust.conf:

locustfile = tests/loadtests/custom_shape_loadtest.py
headless = true
stop-timeout = 1
csv = .artifacts/load_test
only-summary = true

Environment

• OS: Ubuntu 18.04.5 LTS (WSL)
• Python version: 3.9.1
• Locust version: 1.4.3
• Locust command line that you ran: poetry run locust
• Locust file contents (anonymized if necessary):

[laakejs]

Update: If I use @events.init.add_listener instead of @events.test_start.add_listener everything sems to work as expected. However, the behaviour of test_start still seems buggy or at least highly counterintuitive to me.

[cyberw]

@max-rocket-internet is Mr LoadTestShape. Do you think you could have a look?

[max-rocket-internet]

Do you think you could have a look?

I can but not this week or next, I'm quite busy with work. I'll add it to my to-do list 🙂

[max-rocket-internet]

I haven't forgotten, I've created a local branch, but haven't had time this week. Next week though 🙂

[max-rocket-internet]

OK this is the current order of these things in runners.py: https://github.com/locustio/locust/compare/master...max-rocket-internet:start_stop_decorators_fix?expand=1

I'm not sure how to fix this in an elegant way.

Should I just add self.environment.shape_class.reset_time() after here?

[cyberw]

Should I just add self.environment.shape_class.reset_time() after here?

Hmm. Yes I think that could make sense. Also, we should add a note in the documentation so that it is clear that the time is calculated AFTER test_start has finished.

But I guess we also need to address this:

The tick function is called once BEFORE the @events.test_start.add_listener function runs.

[max-rocket-internet]

The tick function is called once BEFORE the @events.test_start.add_listener function runs.

I don't think this matters. The first tick is done to get the initial user/spawn values before calling start() where the event is called. If we reset the time after the event then as far as I can see, it's OK.

Another option would be to move self.stats.clear_all(), self.exceptions = {} and self.environment.events.test_start.fire() to another function, like reset_state() or something and call this from start() and start_shape()?

[max-rocket-internet]

Another option would be to move self.stats.clear_all(), self.exceptions = {} and self.environment.events.test_start.fire() to another function, like reset_state()

I think this is too complicated due to all of the *Runner classes and their inheritance.

[max-rocket-internet]

PR here: #1738