Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Task doesn't fail when status code is incorrect #436

Closed
d00z3l opened this issue Apr 12, 2022 · 20 comments
Closed

Task doesn't fail when status code is incorrect #436

d00z3l opened this issue Apr 12, 2022 · 20 comments

Comments

@d00z3l
Copy link
Contributor

d00z3l commented Apr 12, 2022

Hi,

I am using GooseRequest builder and the task aren't recorded as "failed" even if an error is returned (status code 400+). The code for my task is below, in this case the JSON is invalid a 400 error is returned. Not sure if there is something wrong in how I am using it:

async fn table_data_entry(user: &mut GooseUser) -> GooseTaskResult {

    let value : u64 = rand::thread_rng().gen_range(245..255);
    let data = TableUpdate::new(&vec!["2000-01","LAX","JFK","AA", "N126AA", "Flight Time"], value as f64);

    let req = user.get_request_builder(&GooseMethod::Patch, "api/end-pont")?
        .basic_auth("admin", Option::<&str>::None)
        .json(&data);

    let req = GooseRequest::builder()
        .set_request_builder(req)
        .build();

    user.request(req).await?;

    Ok(())
}

I have put together a fix to return the error and also return the body as part of the error message (goose.rs 1631-1638):

       if !request_metric.success {
            if let Ok(r) = response {
                warn!("{:?} {}: {}", &path, &request_metric.error, r.text().await.unwrap_or("".to_string()));
            } else {
                warn!("{:?} {}", &path, &request_metric.error);
            }
            return Err(GooseTaskError::RequestFailed{raw_request: request_metric});
        }

I can create a pull request if this solves the issue I have.

@jeremyandrews
Copy link
Member

jeremyandrews commented Apr 12, 2022

Please enable --request-log request.log and send 2 lines from the log showing an example of a request that correctly succeeds and an example of a request that should fail but does not, identifying both.

Offhand I'm not seeing a problem in what you're doing, hence why collecting logs will give us more insight.

I imagine you've already found the relevant documentation for using the request builder:
https://docs.rs/goose/latest/goose/goose/struct.GooseUser.html#method.get_request_builder

Note that there's already logic in the function you refer to where we identify whether or not the individual request failed, and this will show up in the logs and in the metrics:
https://github.com/tag1consulting/goose/blob/main/src/goose.rs#L1567

@d00z3l
Copy link
Contributor Author

d00z3l commented Apr 13, 2022

The error is in the request log see below. The error does appear in the per request numbers and in the "ERRORS" section in the end. This issue that the error doesn't show up in the per task details and an error isn't logged to the console when the error occurs. Logging to the console seems important to me because as I can see that something is failing, maybe because on an incorrect task. See details below.

{"coordinated_omission_elapsed":0,"elapsed":57000,"error":"400 Bad Request: ","final_url":"http://localhost:5050/api/end-point","name":"","raw":{"body":"","headers":["(\"authorization\", Sensitive)","(\"content-type\", \"application/json\")"],"method":"Get","url":"http://localhost:5050/api/end-point"},"redirected":false,"response_time":1,"status_code":400,"success":false,"update":false,"user":21,"user_cadence":0}
 === PER TASK METRICS ===
 ------------------------------------------------------------------------------
 Name                     |   # times run |        # fails |   task/s |  fail/s
 ------------------------------------------------------------------------------
 9: table_data_entry      |
   1:                     |             2 |         0 (0%) |     0.04 |    0.00
 -------------------------+---------------+----------------+----------+--------
 Aggregated               |            12 |         0 (0%) |     0.21 |    0.00
 ------------------------------------------------------------------------------
 Name                     |    Avg (ms) |        Min |         Max |     Median
 ------------------------------------------------------------------------------

 9: table_data_entry      |
   1:                     |        4.50 |          1 |           8 |          1
 -------------------------+-------------+------------+-------------+-----------
 Aggregated               |        1009 |          1 |       4,046 |         40

 === PER REQUEST METRICS ===
 ------------------------------------------------------------------------------
 Name                     |        # reqs |        # fails |    req/s |  fail/s
 ------------------------------------------------------------------------------
 GET                      |            12 |      2 (16.7%) |     0.21 |    0.04
 ------------------------------------------------------------------------------
 Name                     |    Avg (ms) |        Min |         Max |     Median
 ------------------------------------------------------------------------------
 GET                      |        1009 |          1 |       4,046 |        280
 ------------------------------------------------------------------------------
 Slowest page load within specified percentile of requests (in ms):
 ------------------------------------------------------------------------------
 Name                     |    50% |    75% |    98% |    99% |  99.9% | 99.99%
 ------------------------------------------------------------------------------
 GET                      |    280 |  2,000 |  4,000 |  4,000 |  4,000 |  4,000

 === ERRORS ===
 ------------------------------------------------------------------------------
 Count       | Error
 ------------------------------------------------------------------------------
 3             GET : 400 Bad Request:
 ------------------------------------------------------------------------------
 ------------------------------------------------------------------------------

@jeremyandrews
Copy link
Member

In the current release you must include -v to see errors etc on the console. A PR was already merged so this will not be required in the next release. When you enable -v do you see the error?

@d00z3l
Copy link
Contributor Author

d00z3l commented Apr 13, 2022

It is hard to tell as the -v logs everything to the console including debug statements so it is very hard to find errors. Should the per task metrics include the failure count?

@jeremyandrews
Copy link
Member

jeremyandrews commented Apr 13, 2022

Which version of Goose are you using? If a single -v is logging everything then you must be using the latest development version? With the current stable release a single -v should only show INFO level logs and higher. It would take two -vv to log debug messages too. (A PR was recently committed as not showing INFO level messages by default was proving confusing to new users.)

In any case, I reviewed the code in question and we don't seem to be emitting an info!() level message when detecting an invalid HTTP response code as I thought. I agree we should, a PR is welcome. Perhaps we'd check if request_metric.error is not empty, and if so print the error as an INFO level message, around here:
https://github.com/tag1consulting/goose/blob/main/src/goose.rs#L1630

@jeremyandrews
Copy link
Member

Should the per task metrics include the failure count?

In order for a task to show as an error, you must return Err() from your task. Per-request errors will only show up in the per-request section of the metrics.

@d00z3l
Copy link
Contributor Author

d00z3l commented Apr 13, 2022

I was using 0.15.2 but are on the current main branch. info, warn or error? I also find it helpful to include the request body as in this case and others the issue is often caused by invalid payload. Example code in the location use suggested:

if !request_metric.success {
	if let Ok(r) = response {
		warn!("{:?} {}: {}", &path, &request_metric.error, r.text().await.unwrap_or("".to_string()));
	} else {
		warn!("{:?} {}", &path, &request_metric.error);
	}
	return Err(GooseTaskError::RequestFailed{raw_request: request_metric});
}

@d00z3l
Copy link
Contributor Author

d00z3l commented Apr 13, 2022

In order for a task to show as an error, you must return Err() from your task. Per-request errors will only show up in the per-request section of the metrics.

So I should be doing user.request(req).await?.response?; in the task?

@jeremyandrews
Copy link
Member

It sounds like you're looking for the debug log. Try adding the following options:
--debug-log debug.log

Now review the debug.log to find complete details about all request errors, including the request made, the response headers, and the response body. (Unfortunately due to this reqwest limitation we are frequently unable to log all request headers.)

You can also store the body of the request made in the request log if you enable --request-body.

@jeremyandrews
Copy link
Member

So I should be doing user.request(req).await?.response?; in the task?

Take a look at the provided Goose examples. You need to decide what qualifies as a failure of your task. For example, see the drupal_memcache example and how it calls set_failure when various expectations aren't met.

For much simpler error handling, see the simple which simply passes errors up.

@d00z3l
Copy link
Contributor Author

d00z3l commented Apr 13, 2022

I think the session sample needs to be updated, that is what I started with. It doesn't check the response so the task will always succeed even if it fails.

/// A very simple task that simply loads the front page.
async fn authenticated_index(user: &mut GooseUser) -> GooseTaskResult {
    // This will panic if the session is missing or if the session is not of the right type.
    // Use `get_session_data` to handle a missing session.
    let session = user.get_session_data_unchecked::<Session>();

    // Create a Reqwest RequestBuilder object and configure bearer authentication when making
    // a GET request for the index.
    let reqwest_request_builder = user
        .get_request_builder(&GooseMethod::Get, "/")?
        .bearer_auth(&session.jwt_token);

    // Add the manually created RequestBuilder and build a GooseRequest object.
    let goose_request = GooseRequest::builder()
        .set_request_builder(reqwest_request_builder)
        .build();

    // Make the actual request.
    user.request(goose_request).await?;

    Ok(())
}

@d00z3l
Copy link
Contributor Author

d00z3l commented Apr 13, 2022

The simple example also doesn't check for the response error so the task will always succeed.

@jeremyandrews
Copy link
Member

jeremyandrews commented Apr 13, 2022

Mostly correct. It will fail if request() returns an Err().

There's a number of lines where this function many return an Error:

As explained in the documentation, the simple example is by-design as simple as possible (and clones a similar example from Locust), just showing basic interactions with the Goose library. It is very much not intended to demonstrate all possible Goose functionality or best practices.

For a more fleshed-out example, see the umami example. Also be sure to review the umami documentation, the related blog, and the goose-eggs version.

@d00z3l
Copy link
Contributor Author

d00z3l commented Apr 13, 2022

The issue with the examples (simple and session) is that the request could fail because of a typo or invalid payload and the task will be marked as successful.

From the task how do you actually check for an error? I just checked user.request(req).await?.response? and it doesn't work because the response is actually Ok when the status is 400+ or different to expect_status_code. I thought the request would return an error if the status code is different to the what is expected.

In my case I am trying to get the simplest example working. I did that by copying the sample and going from there. When I provided the wrong JSON for the payload of the task it wasn't obvious that it failed because it was saying it succeeded. I only knew it failed because I wasn't getting an incorrect log statement in my back-end.

This isn't criticism, I just want to understand how to use it better because it works great, I am able to send 100s of request with very little overhead which is awesome.

@jeremyandrews
Copy link
Member

jeremyandrews commented Apr 13, 2022

Tasks and Requests are different things. (It may be helpful to see this PR which is working to clarify this #435.)

In Goose, there are Requests of which one or more are contained in a Task of which one or more are contained in a TaskSet. It is up to you when writing your load test to determine if a single failed Request results in the entire Task failing or not.

For example: if you have a Task called "load front page" it may 1) load index.html, 2) validate the HTML title and returned Headers, 3) scrape locally hosted assets from the returned html, and 4) load each of those scraped assets (ie images, JS and CSS). It's common for one or more of these assets to be missing (resulting in a 404) or otherwise to generate an error: but even though that Request failed I would consider the Task to have failed.

When writing load tests with Goose, I always enable the error log and the debug log to collect as much information as possible about errors. This will capture all 400+ responses (unless you override this, ie if you WANT to load test a 404 page) and allow you to quickly track down things like typos.

Of course, if you Really want a 1:1 mapping between a single Request and a single Task, you can do this easily enough by parsing the GooseResponse that's returned by, for example, a get Request and returning an Err() from your Task if the Status Code isn't what you expect.

I referred you to the Umami example as it is the most complete load test example included with Goose and demonstrates how to do things like this and much more. I personally tend to leverage the Goose Eggs validate functions to avoid writing boilerplate.

@jeremyandrews
Copy link
Member

It's a little outdated now, but we tried to capture some real-world examples of using Goose in this blog:
https://www.tag1consulting.com/blog/real-life-goose-load-testing

@jeremyandrews
Copy link
Member

Please also see this similar discussion: #437

@d00z3l
Copy link
Contributor Author

d00z3l commented Apr 14, 2022

It would be good to be able to easily return an error from a request if the status is invalid. In my case I am testing an API not a web page. Something like:

let req = user.get_request_builder(&GooseMethod::Post, "api/view/Flight/execute")?
        .basic_auth("admin", Option::<&str>::None)
        .json(&view);

let req = GooseRequest::builder()
        .set_request_builder(req)
        .error_on_fail()
        .build();

Is that something you would consider?

@jeremyandrews
Copy link
Member

Yes, adding flexibility is always welcome, so long as it doesn't negatively impact performance. This would be a welcome addition.

@jeremyandrews
Copy link
Member

Fixed in #438

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
None yet
Projects
None yet
Development

No branches or pull requests

2 participants