hurl/docs/tutorial/debug-tips.md

461 lines
17 KiB
Markdown
Raw Normal View History

# Debug Tips
2022-09-28 11:24:24 +03:00
Now that we have many requests in our test file, let's review some tips on how to debug the executed HTTP exchanges.
## Verbose Mode
### Using --verbose and --very-verbose for all entries
2022-09-28 11:24:24 +03:00
We can run our test with [`-v/--verbose` option]. In this mode, each entry is displayed with debugging
information like request HTTP headers, response HTTP headers, cookie storage, duration etc...
```shell
2022-09-25 13:52:24 +03:00
$ hurl --verbose --no-output basic.hurl
* Options:
* fail fast: true
* follow redirect: false
2023-07-21 14:28:26 +03:00
* insecure: false
* max redirect: 50
2023-07-21 14:28:26 +03:00
* retry: 0
* ------------------------------------------------------------------------------
* Executing entry 1
*
* Cookie store:
*
* Request:
2023-07-21 14:28:26 +03:00
* GET http://localhost:3000
*
* Request can be run with the following curl command:
2023-07-21 14:28:26 +03:00
* curl 'http://localhost:3000'
*
> GET / HTTP/1.1
2023-07-21 14:28:26 +03:00
> Host: localhost:3000
> Accept: */*
2023-07-21 14:28:26 +03:00
> User-Agent: hurl/4.0.0
>
2023-07-21 14:28:26 +03:00
* Response: (received 9564 bytes in 11 ms)
*
< HTTP/1.1 200 OK
< Content-Type: text/html; charset=utf-8
< Content-Length: 9564
< Set-Cookie: x-session-id=s%3AEE3wsnrgUPSyAkgJZGa3jMWk7xmOtv4E.kXQpkmNBXnFOqmeSssqXnecF4qqv1D7bKu3rpbEJxmQ; Path=/; HttpOnly; SameSite=Strict
< Date: Wed, 26 Jul 2023 13:16:39 GMT
< Connection: keep-alive
< Keep-Alive: timeout=5
<
*
* ------------------------------------------------------------------------------
* Executing entry 2
*
* Cookie store:
2023-07-21 14:28:26 +03:00
* #HttpOnly_localhost FALSE / FALSE 0 x-session-id s%3AEE3wsnrgUPSyAkgJZGa3jMWk7xmOtv4E.kXQpkmNBXnFOqmeSssqXnecF4qqv1D7bKu3rpbEJxmQ
*
* Request:
2023-07-21 14:28:26 +03:00
* GET http://localhost:3000/not-found
*
* Request can be run with the following curl command:
2023-07-21 14:28:26 +03:00
* curl --cookie 'x-session-id=s%3AEE3wsnrgUPSyAkgJZGa3jMWk7xmOtv4E.kXQpkmNBXnFOqmeSssqXnecF4qqv1D7bKu3rpbEJxmQ' 'http://localhost:3000/not-found'
*
> GET /not-found HTTP/1.1
2023-07-21 14:28:26 +03:00
> Host: localhost:3000
> Accept: */*
2023-07-21 14:28:26 +03:00
> Cookie: x-session-id=s%3AEE3wsnrgUPSyAkgJZGa3jMWk7xmOtv4E.kXQpkmNBXnFOqmeSssqXnecF4qqv1D7bKu3rpbEJxmQ
> User-Agent: hurl/4.0.0
>
2023-07-21 14:28:26 +03:00
* Response: (received 2217 bytes in 3 ms)
*
< HTTP/1.1 404 Not Found
< Content-Type: text/html; charset=utf-8
< Content-Length: 2217
< Date: Wed, 26 Jul 2023 13:16:39 GMT
< Connection: keep-alive
< Keep-Alive: timeout=5
<
...
```
2022-09-28 11:24:24 +03:00
Lines beginning with `*` are debug info, lines that begin with `>` are HTTP request headers and lines that begin with
`<` are HTTP response headers.
In verbose mode, HTTP request and response bodies are not displayed in the debug logs. If you need to inspect the
request or response body, you can display more logs with [`--very-verbose`] option:
```shell
2022-09-25 13:52:24 +03:00
$ hurl --very-verbose --no-output basic.hurl
* Options:
* fail fast: true
* follow redirect: false
2023-07-21 14:28:26 +03:00
* insecure: false
* max redirect: 50
2023-07-21 14:28:26 +03:00
* retry: 0
* ------------------------------------------------------------------------------
* Executing entry 1
*
* Cookie store:
*
* Request:
2023-07-21 14:28:26 +03:00
* GET http://localhost:3000
*
* Request can be run with the following curl command:
2023-07-21 14:28:26 +03:00
* curl 'http://localhost:3000'
*
2023-07-21 14:28:26 +03:00
** WARNING: failed to open cookie file ""
**  Trying 127.0.0.1:3000...
** Connected to localhost (127.0.0.1) port 3000 (#0)
> GET / HTTP/1.1
2023-07-21 14:28:26 +03:00
> Host: localhost:3000
> Accept: */*
2023-07-21 14:28:26 +03:00
> User-Agent: hurl/4.0.0
>
* Request body:
*
2023-07-21 14:28:26 +03:00
** Added cookie x-session-id="s%3A_l88C6GKbPeC5YuDLraWARY32NB3bP-l.T%2BViEW%2BqMrmLZDqwzDxtEbdtW67lCKt0jGvvlfqls%2FI" for domain localhost, path /, expire 0
** Connection #0 to host localhost left intact
* Response: (received 9564 bytes in 9 ms)
*
< HTTP/1.1 200 OK
< Content-Type: text/html; charset=utf-8
< Content-Length: 9564
< Set-Cookie: x-session-id=s%3A_l88C6GKbPeC5YuDLraWARY32NB3bP-l.T%2BViEW%2BqMrmLZDqwzDxtEbdtW67lCKt0jGvvlfqls%2FI; Path=/; HttpOnly; SameSite=Strict
< Date: Wed, 26 Jul 2023 13:19:45 GMT
< Connection: keep-alive
< Keep-Alive: timeout=5
<
* Response body:
* <!doctype html>
* <html lang="en">
2023-07-21 14:28:26 +03:00
* <head>
* <meta charset="UTF-8" />
* <title>Movies Box</title>
* <link rel="icon" type="image/png" href="/img/favicon.png" />
* <link rel="stylesheet" href="/css/style.css" />
* </head>
* <body>
...
2023-07-21 14:28:26 +03:00
* </body>
* </html>
*
2023-07-21 14:28:26 +03:00
* Timings:
* begin: 2023-07-26 13:19:45.378037 UTC
* end: 2023-07-26 13:19:45.387332 UTC
* namelookup: 4182 µs
* connect: 4798 µs
* app_connect: 0 µs
* pre_transfer: 4912 µs
* start_transfer: 9126 µs
* total: 9171 µs
*
* ------------------------------------------------------------------------------
* Executing entry 2
*
* Cookie store:
2023-07-21 14:28:26 +03:00
* #HttpOnly_localhost FALSE / FALSE 0 x-session-id s%3A_l88C6GKbPeC5YuDLraWARY32NB3bP-l.T%2BViEW%2BqMrmLZDqwzDxtEbdtW67lCKt0jGvvlfqls%2FI
*
* Request:
2023-07-21 14:28:26 +03:00
* GET http://localhost:3000/not-found
*
* Request can be run with the following curl command:
2023-07-21 14:28:26 +03:00
* curl --cookie 'x-session-id=s%3A_l88C6GKbPeC5YuDLraWARY32NB3bP-l.T%2BViEW%2BqMrmLZDqwzDxtEbdtW67lCKt0jGvvlfqls%2FI' 'http://localhost:3000/not-found'
*
2023-07-21 14:28:26 +03:00
** Found bundle for host: 0x60000340c930 [serially]
** Can not multiplex, even if we wanted to
** Re-using existing connection #0 with host localhost
> GET /not-found HTTP/1.1
2023-07-21 14:28:26 +03:00
> Host: localhost:3000
> Accept: */*
2023-07-21 14:28:26 +03:00
> Cookie: x-session-id=s%3A_l88C6GKbPeC5YuDLraWARY32NB3bP-l.T%2BViEW%2BqMrmLZDqwzDxtEbdtW67lCKt0jGvvlfqls%2FI
> User-Agent: hurl/4.0.0
>
* Request body:
*
2023-07-21 14:28:26 +03:00
** Connection #0 to host localhost left intact
* Response: (received 2217 bytes in 5 ms)
*
< HTTP/1.1 404 Not Found
< Content-Type: text/html; charset=utf-8
< Content-Length: 2217
< Date: Wed, 26 Jul 2023 13:19:45 GMT
< Connection: keep-alive
< Keep-Alive: timeout=5
<
* Response body:
* <!doctype html>
* <html lang="en">
...
2023-07-21 14:28:26 +03:00
* <h3>Not Found</h3>
* <h4>404</h4>
...
* </html>
*
2023-07-21 14:28:26 +03:00
* Timings:
* begin: 2023-07-26 13:19:45.390823 UTC
* end: 2023-07-26 13:19:45.395983 UTC
* namelookup: 44 µs
* connect: 0 µs
* app_connect: 0 µs
* pre_transfer: 126 µs
* start_transfer: 5100 µs
* total: 5124 µs
*
...
```
2023-07-21 14:28:26 +03:00
[`--very-verbose`] output is much more verbose; with body request and response, [`libcurl`] logs and [response timings]
are displayed.
### Debugging a specific entry
2022-09-28 11:24:24 +03:00
If you have a lot of entries (request / response pairs) in your Hurl file, using [`--verbose`] or [`--very-verbose`]
can produce a lot of logs and can be difficult to analyse. Instead of passing options to the command line, you can
use an `[Options]` section that will activate logs only for the specified entry:
```hurl
# Checking our home page:
# ...
# Check that we have a 404 response for broken links:
# ...
2022-09-28 11:34:00 +03:00
# Check our health API:
# ...
2023-07-21 14:28:26 +03:00
# Check search API:
GET http://localhost:3000/api/search
[Options]
verbose: true
[QueryStringParams]
2023-07-21 14:28:26 +03:00
q: 1982
sort: name
2022-12-19 23:30:08 +03:00
HTTP 200
# ...
```
And run it without [`--verbose`] option:
```shell
2022-09-25 13:52:24 +03:00
$ hurl --no-output basic.hurl
* ------------------------------------------------------------------------------
* Executing entry 4
*
* Entry options:
* verbose: true
*
* Cookie store:
2023-07-21 14:28:26 +03:00
* #HttpOnly_localhost FALSE / FALSE 0 x-session-id s%3Aq_5wf1l2wBQ_96y6kpLeR0J4zLJF34EZ.n%2Bu1UJPqK0Ih2tz3Dd6w2kXAuufueT6HQDekBPtHhbc
*
* Request:
2023-07-21 14:28:26 +03:00
* GET http://localhost:3000/api/search
* [QueryStringParams]
2023-07-21 14:28:26 +03:00
* q: 1982
* sort: name
*
* Request can be run with the following curl command:
2023-07-21 14:28:26 +03:00
* curl --cookie 'x-session-id=s%3Aq_5wf1l2wBQ_96y6kpLeR0J4zLJF34EZ.n%2Bu1UJPqK0Ih2tz3Dd6w2kXAuufueT6HQDekBPtHhbc' 'http://localhost:3000/api/search?q=1982&sort=name'
*
2023-07-21 14:28:26 +03:00
> GET /api/search?q=1982&sort=name HTTP/1.1
> Host: localhost:3000
> Accept: */*
2023-07-21 14:28:26 +03:00
> Cookie: x-session-id=s%3Aq_5wf1l2wBQ_96y6kpLeR0J4zLJF34EZ.n%2Bu1UJPqK0Ih2tz3Dd6w2kXAuufueT6HQDekBPtHhbc
> User-Agent: hurl/4.0.0
>
2023-07-21 14:28:26 +03:00
* Response: (received 1447 bytes in 0 ms)
*
< HTTP/1.1 200 OK
< Cache-control: no-store
< Content-Type: application/json; charset=utf-8
< Content-Length: 1447
< Date: Wed, 26 Jul 2023 13:29:39 GMT
< Connection: keep-alive
< Keep-Alive: timeout=5
<
*
```
2023-07-21 14:28:26 +03:00
## Use Error Format
When youve asserts errors, the analysis can be difficult because you dont have a lot of information apart
of the expected values:
```shell
$ hurl --test basic.hurl
basic.hurl: Running [1/1]
error: Assert failure
--> basic.hurl:47:0
|
47 | jsonpath "$[0].name" == "Robocop"
| actual: string <Blade Runner>
| expected: string <Robocop>
|
basic.hurl: Failure (4 request(s) in 16 ms)
--------------------------------------------------------------------------------
Executed files: 1
Succeeded files: 0 (0.0%)
Failed files: 1 (100.0%)
Duration: 17 ms
```
With [`--error-format`] option, you can opt in for a longer error description in case of error assert. On any error,
we'll get the response headers and body. This is useful to see the expected values, especially in CI/CD
context when you've to analyse past executed tests.
```shell
$ hurl --error-format long --test basic.hurl
basic.hurl: Running [1/1]
HTTP/1.1 200
Cache-control: no-store
Content-Type: application/json; charset=utf-8
Content-Length: 1447
Date: Wed, 26 Jul 2023 14:14:00 GMT
Connection: keep-alive
Keep-Alive: timeout=5
[{"name":"Blade Runner","url":"/movies/blade-runner","director":"Ridley Scott","release_date":"1982-06-25","actors":["Harrison Ford","Rutger Hauer","Sean Young","Edward James Olmos"],"artwork":"/img/blade-runner-800x1200.webp","artwork_128":"/img/blade-runner-128x192.webp"},{"name":"Conan the Barbarian","url":"/movies/conan-the-barbarian","director":"John Milius","release_date":"1982-05-14","actors":["Arnold Schwarzenegger","James Earl Jones","Sandahl Bergman","Ben Davidson","Cassandra Gaviola","Gerry Lopez","Mako","Valerie Quennessen","William Smith","Max von Sydow"],"artwork":"/img/conan-the-barbarian-800x1200.webp","artwork_128":"/img/conan-the-barbarian-128x192.webp"},{"name":"The Dark Crystal","url":"/movies/the-dark-crystal","director":"Jim Henson","release_date":"1982-12-17","actors":["Stephen Garlick","Lisa Maxwell","Billie Whitelaw","Percy Edwards"],"artwork":"/img/the-dark-crystal-800x1200.webp","artwork_128":"/img/the-dark-crystal-128x192.webp"},{"name":"The Thing","url":"/movies/the-thing","director":"John Carpenter","release_date":"1982-06-25","actors":["Kurt Russell"],"artwork":"/img/the-thing-800x1200.webp","artwork_128":"/img/the-thing-128x192.webp"},{"name":"Tron","url":"/movies/tron","director":"Steven Lisberger","release_date":"1982-07-09","actors":["Jeff Bridges","Bruce Boxleitner","David Warner","Cindy Morgan","Barnard Hughes"],"artwork":"/img/tron-800x1200.webp","artwork_128":"/img/tron-128x192.webp"}]
error: Assert failure
--> basic.hurl:47:0
|
47 | jsonpath "$[0].name" == "Robocop"
| actual: string <Blade Runner>
| expected: string <Robocop>
|
basic.hurl: Failure (4 request(s) in 23 ms)
```
## Interactive Mode
We can run the whole Hurl file request by request, with the [`--interactive` option]:
```shell
2023-07-21 14:28:26 +03:00
$ hurl --verbose --interactive basic.hurl
* Options:
* fail fast: true
* insecure: false
* follow redirect: false
* max redirect: 50
Interactive mode:
Next request:
GET http://localhost:8080
Press Q (Quit) or C (Continue)
* ------------------------------------------------------------------------------
* Executing entry 1
*
* Cookie store:
*
* Request:
2023-07-21 14:28:26 +03:00
* GET http://localhost:3000
*
* Request can be run with the following curl command:
2023-07-21 14:28:26 +03:00
* curl 'http://localhost:3000'
*
> GET / HTTP/1.1
2023-07-21 14:28:26 +03:00
> Host: localhost:3000
> Accept: */*
2023-07-21 14:28:26 +03:00
> User-Agent: hurl/4.0.0
>
2023-07-21 14:28:26 +03:00
* Response: (received 9564 bytes in 11 ms)
*
< HTTP/1.1 200 OK
< Content-Type: text/html; charset=utf-8
< Content-Length: 9564
< Set-Cookie: x-session-id=s%3AEE3wsnrgUPSyAkgJZGa3jMWk7xmOtv4E.kXQpkmNBXnFOqmeSssqXnecF4qqv1D7bKu3rpbEJxmQ; Path=/; HttpOnly; SameSite=Strict
< Date: Wed, 26 Jul 2023 13:16:39 GMT
< Connection: keep-alive
< Keep-Alive: timeout=5
<
*
Interactive mode:
Next request:
GET http://localhost:8080/not-found
Press Q (Quit) or C (Continue)
```
## Include Headers Like curl
We can also run our file to only output HTTP headers, with [`-i/--include` option].
In this mode, headers of the last entry are displayed:
```shell
$ hurl -i basic.hurl
2022-12-19 23:30:08 +03:00
HTTP/1.1 200
2023-07-21 14:28:26 +03:00
Cache-control: no-store
Content-Type: application/json; charset=utf-8
Content-Length: 1447
Date: Wed, 26 Jul 2023 14:58:27 GMT
Connection: keep-alive
Keep-Alive: timeout=5
[{"name":"Blade Runner","url":"/movies/blade-runner","director":"Ridley Scott","release_date":"1982-06-25",...
```
2022-09-28 11:24:24 +03:00
If you want to inspect any entry other than the last one, you can run your test to a
given entry with the [`--to-entry` option], starting at index 1:
```shell
$ hurl -i --to-entry 2 basic.hurl
2022-12-19 23:30:08 +03:00
HTTP/1.1 404
2023-07-21 14:28:26 +03:00
Content-Type: text/html; charset=utf-8
Content-Length: 2217
Date: Wed, 26 Jul 2023 14:59:57 GMT
Connection: keep-alive
Keep-Alive: timeout=5
<!doctype html>
<html lang="en">
2023-07-21 14:28:26 +03:00
<head>
<meta charset="UTF-8" />
<title></title>
...
</body>
</html>
```
## Using a Proxy
Finally, you can use a proxy between Hurl and your server to inspect requests and responses.
2023-04-17 19:05:07 +03:00
For instance, with [mitmproxy]:
2023-04-17 19:05:07 +03:00
1. First, launch mitmproxy, it will listen to connections on 8888 port
```shell
2023-04-17 19:05:07 +03:00
$ mitmweb -p 8888 --web-port 8889 --web-open-browser
Web server listening at http://127.0.0.1:8889/
Proxy server listening at http://*:8888
```
2. Then, run Hurl with [`-x/--proxy` option]
```shell
$ hurl --proxy localhost:8888 basic.hurl
```
2023-04-17 19:05:07 +03:00
The web interface of mitmproxy allows you to inspect, intercept any requests run by Hurl, and see
the returned response to Hurl.
2022-09-02 15:45:54 +03:00
[`-v/--verbose` option]: /docs/manual.md#verbose
[`--very-verbose`]: /docs/manual.md#very-verbose
[`--verbose`]: /docs/manual.md#verbose
[`--interactive` option]: /docs/manual.md#interactive
[`-i/--include` option]: /docs/manual.md#include
[`--to-entry` option]: /docs/manual.md#to-entry
2023-04-17 19:05:07 +03:00
[mitmproxy]: https://mitmproxy.org
2022-09-02 15:45:54 +03:00
[`-x/--proxy` option]: /docs/manual.md#proxy
2023-07-21 14:28:26 +03:00
[`--error-format`]: /docs/manual.md#error-format
[`libcurl`]: https://curl.se/libcurl/
[response timings]: /docs/response.md#timings