Skip to content

feat(logs): log teststep output vars in case of failure#837

Merged
yesnault merged 1 commit into
ovh:masterfrom
alexGNX:log-improvements
May 5, 2025
Merged

feat(logs): log teststep output vars in case of failure#837
yesnault merged 1 commit into
ovh:masterfrom
alexGNX:log-improvements

Conversation

@alexGNX

@alexGNX alexGNX commented Apr 3, 2025

Copy link
Copy Markdown
Contributor

Troubleshooting teststep failures is often cumbersome, especially when using User Defined Executors.
E. g., let's take the simple case of a failure on a teststep using the http executor. You need details to understand why the tested API doesn't responded as expected, so you want to have a look to the detailed output of the executor, in that case to analyze the response body and headers for example.
To do that, one option is to add the info keyword in the teststep, like:

info: "response body is {{.result.body}} and headers are {{.result.headers}}"

This is useful but has a couple of issues:

  • you have to add it to all your testscases
  • you have to adapt it to the kind of executor you are using, depending on its output fields
  • it doesn't work for User Defined Executor, i. e. the info keyword is not working if you use it on a testcase inside an UDE.

This change is simply about adding all this info into the log, when a failure occurs.
It also changes the log level of passing teststeps from Warn to Info.

Example of the logs it produces:

Apr  3 18:57:18.585 [ERRO] [test maps behavior] [headers-UDE] [headers] Step "http" result is "FAIL"
Apr  3 18:57:18.585 [ERRO] [test maps behavior] [headers-UDE] [headers] Errors: 
Apr  3 18:57:18.585 [ERRO] [test maps behavior] [headers-UDE] [headers] �[33mTestcase "headers", step #0-0: Assertion "result.bodyjson.headers.Host ShouldEqual \"httpbin.org\"" failed. expected: httpbin.org  got: <nil> (headers.yml:17)�[0m
Apr  3 18:57:18.585 [ERRO] [test maps behavior] [headers-UDE] [headers] �[33mTestcase "headers", step #0-0: Assertion "result.bodyjson.headers.Foo ShouldEqual \"bar\"" failed. expected: bar  got: <nil> (headers.yml:18)�[0m
Apr  3 18:57:18.586 [ERRO] [test maps behavior] [headers-UDE] [headers] �[33mTestcase "headers", step #0-0: Assertion "result.bodyjson.headers.Cookie ShouldEqual \"eb42azgxcb381asc\"" failed. expected: eb42azgxcb381asc  got: <nil> (headers.yml:19)�[0m
Apr  3 18:57:18.586 [ERRO] [test maps behavior] [headers-UDE] [headers] teststep output vars are: map[__type__:Result result.__Len__:8 result.body:{
  "cookies": {
    "eb42azgxcb381asc": ""
  }
}
 result.bodyjson:map[cookies:map[eb42azgxcb381asc:]] result.bodyjson.__Len__:1 result.bodyjson.__Type__:Map result.bodyjson.cookies:map[eb42azgxcb381asc:] result.bodyjson.cookies.__Len__:1 result.bodyjson.cookies.__Type__:Map result.bodyjson.cookies.eb42azgxcb381asc: result.err: result.headers:map[Access-Control-Allow-Credentials:true Access-Control-Allow-Origin:* Content-Length:50 Content-Type:application/json Date:Thu, 03 Apr 2025 16:57:18 GMT Server:gunicorn/19.9.0] result.headers.Access-Control-Allow-Credentials:true result.headers.Access-Control-Allow-Origin:* result.headers.Content-Length:50 result.headers.Content-Type:application/json result.headers.Date:Thu, 03 Apr 2025 16:57:18 GMT result.headers.Server:gunicorn/19.9.0 result.headers.__Len__:6 result.headers.__Type__:Map result.request:{GET https://httpbin.org/cookies map[Cookie:[eb42azgxcb381asc] Foo:[bar]]  map[] map[]} result.request.__Len__:6 result.request.__Type__:HTTPRequest result.request.body: result.request.form:map[] result.request.form.__Len__:0 result.request.form.__Type__:Map result.request.header:map[Cookie:[eb42azgxcb381asc] Foo:[bar]] result.request.header.Cookie:[eb42azgxcb381asc] result.request.header.Cookie.Cookie0:eb42azgxcb381asc result.request.header.Cookie.__Len__:1 result.request.header.Cookie.__Type__:Array result.request.header.Foo:[bar] result.request.header.Foo.Foo0:bar result.request.header.Foo.__Len__:1 result.request.header.Foo.__Type__:Array result.request.header.__Len__:2 result.request.header.__Type__:Map result.request.method:GET result.request.post_form:map[] result.request.post_form.__Len__:0 result.request.post_form.__Type__:Map result.request.url:https://httpbin.org/cookies result.statuscode:200 result.systemout:===== Result Info =====
		Method:     GET
		URL:        https://httpbin.org/cookies
		Body:       {"cookies":{"eb42azgxcb381asc":""}}
		====================== result.timeseconds:0.597639942]

@alexGNX alexGNX force-pushed the log-improvements branch 2 times, most recently from ebd2a83 to 4daed5c Compare April 3, 2025 17:48
Comment thread process_testcase.go Outdated
@alexGNX alexGNX force-pushed the log-improvements branch from 4daed5c to a4dd2dd Compare May 5, 2025 13:17
@ovh-cds

ovh-cds commented May 5, 2025

Copy link
Copy Markdown
Collaborator

CDS Report build-venom-a#275.0 ✘

  • Build
    • Build ✔
    • Unit Tests ✔
  • Tests
    • Acceptance Tests ✘

@yesnault yesnault force-pushed the log-improvements branch from a4dd2dd to 8a6f375 Compare May 5, 2025 18:34
Signed-off-by: alexGNX <alexandre.gagneux12@gmail.com>
@yesnault yesnault force-pushed the log-improvements branch from 8a6f375 to 5622d5c Compare May 5, 2025 19:09
@yesnault yesnault merged commit 62f5f5a into ovh:master May 5, 2025
2 checks passed
peczenyj pushed a commit to peczenyj/venom that referenced this pull request May 7, 2025
Signed-off-by: alexGNX <alexandre.gagneux12@gmail.com>
Signed-off-by: Tiago Peczenyj <tpeczenyj@weborama.com>
ceriath pushed a commit to ceriath/venom that referenced this pull request Jul 11, 2025
Signed-off-by: alexGNX <alexandre.gagneux12@gmail.com>
storagebits pushed a commit to storagebits/venom that referenced this pull request Apr 17, 2026
Signed-off-by: alexGNX <alexandre.gagneux12@gmail.com>
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

Successfully merging this pull request may close these issues.

3 participants