Link request and response in DEBUG output

[debakkerb]

I've probably been staring at this for way too long, but how can you link a REQUEST and RESPONSE in the output logs, when log level is set to DEBUG?

For some reason my config is failing, but the only feedback I'm getting is the following: Error reading Organization policy for organizations/ORG_ID: googleapi: Error 400: Request contains an invalid argument., badRequest

I set the log level to TRACE and DEBUG, and I can see this in the logs:

2019-12-28T09:19:22.112Z [DEBUG] plugin.terraform-provider-google_v3.3.0_x5: -----------------------------------------------------
2019-12-28T09:19:22.112Z [DEBUG] plugin.terraform-provider-google_v3.3.0_x5: 2019/12/28 09:19:22 [DEBUG] Google API Response Details:
2019-12-28T09:19:22.112Z [DEBUG] plugin.terraform-provider-google_v3.3.0_x5: ---[ RESPONSE ]--------------------------------------
2019-12-28T09:19:22.112Z [DEBUG] plugin.terraform-provider-google_v3.3.0_x5: HTTP/2.0 400 Bad Request
2019-12-28T09:19:22.114Z [DEBUG] plugin.terraform-provider-google_v3.3.0_x5: Alt-Svc: quic=":443"; ma=2592000; v="46,43",h3-Q050=":443"; ma=2592000,h3-Q049=":443"; ma=2592000,h3-Q048=":443"; ma=2592000,h3-Q046=":443"; ma=2592000,h3-Q043=":443"; ma=2592000
2019-12-28T09:19:22.115Z [DEBUG] plugin.terraform-provider-google_v3.3.0_x5: Cache-Control: private
2019-12-28T09:19:22.115Z [DEBUG] plugin.terraform-provider-google_v3.3.0_x5: Content-Type: application/json; charset=UTF-8
2019-12-28T09:19:22.115Z [DEBUG] plugin.terraform-provider-google_v3.3.0_x5: Date: Sat, 28 Dec 2019 09:19:21 GMT
2019-12-28T09:19:22.115Z [DEBUG] plugin.terraform-provider-google_v3.3.0_x5: Server: ESF
2019-12-28T09:19:22.115Z [DEBUG] plugin.terraform-provider-google_v3.3.0_x5: Server-Timing: gfet4t7; dur=640
2019-12-28T09:19:22.115Z [DEBUG] plugin.terraform-provider-google_v3.3.0_x5: Vary: Origin
2019-12-28T09:19:22.115Z [DEBUG] plugin.terraform-provider-google_v3.3.0_x5: Vary: X-Origin
2019-12-28T09:19:22.115Z [DEBUG] plugin.terraform-provider-google_v3.3.0_x5: Vary: Referer
2019-12-28T09:19:22.115Z [DEBUG] plugin.terraform-provider-google_v3.3.0_x5: X-Content-Type-Options: nosniff
2019-12-28T09:19:22.115Z [DEBUG] plugin.terraform-provider-google_v3.3.0_x5: X-Frame-Options: SAMEORIGIN
2019-12-28T09:19:22.115Z [DEBUG] plugin.terraform-provider-google_v3.3.0_x5: X-Xss-Protection: 0
2019-12-28T09:19:22.115Z [DEBUG] plugin.terraform-provider-google_v3.3.0_x5: 
2019-12-28T09:19:22.115Z [DEBUG] plugin.terraform-provider-google_v3.3.0_x5: {
2019-12-28T09:19:22.115Z [DEBUG] plugin.terraform-provider-google_v3.3.0_x5:   "error": {
2019-12-28T09:19:22.115Z [DEBUG] plugin.terraform-provider-google_v3.3.0_x5:     "code": 400,
2019-12-28T09:19:22.115Z [DEBUG] plugin.terraform-provider-google_v3.3.0_x5:     "message": "Request contains an invalid argument.",
2019-12-28T09:19:22.115Z [DEBUG] plugin.terraform-provider-google_v3.3.0_x5:     "errors": [
12-28T09:19:22.115Z [DEBUG] plugin.terraform-provider-google_v3.3.0_x5:       {
2019-12-28T09:19:22.115Z [DEBUG] plugin.terraform-provider-google_v3.3.0_x5:         "message": "Request contains an invalid argument.",
2019-12-28T09:19:22.115Z [DEBUG] plugin.terraform-provider-google_v3.3.0_x5:         "domain": "global",
2019-12-28T09:19:22.115Z [DEBUG] plugin.terraform-provider-google_v3.3.0_x5:         "reason": "badRequest"
2019-12-28T09:19:22.115Z [DEBUG] plugin.terraform-provider-google_v3.3.0_x5:       }
2019-12-28T09:19:22.115Z [DEBUG] plugin.terraform-provider-google_v3.3.0_x5:     ],
2019-12-28T09:19:22.115Z [DEBUG] plugin.terraform-provider-google_v3.3.0_x5:     "status": "INVALID_ARGUMENT"
2019-12-28T09:19:22.115Z [DEBUG] plugin.terraform-provider-google_v3.3.0_x5:   }
2019-12-28T09:19:22.115Z [DEBUG] plugin.terraform-provider-google_v3.3.0_x5: }
2019-12-28T09:19:22.115Z [DEBUG] plugin.terraform-provider-google_v3.3.0_x5: 

This is all great, but how can I figure out which request has failed?

[venkykuberan]

@debakkerb We don't have a way to correlate the request/response as of now. We have to search the logs for the API request made and response received

[debakkerb]

Woops, I wrote a big reply and all of a sudden I noticed that this was a different ticket :).

I don't have the code anymore unfortunately, but I'm not really looking to troubleshoot this particular issue (has already been solved). It's a more generic question, how can you link both REQUEST and RESPONSE in the TRACE output, as it's almost impossible to figure out which request exactly failed.

[danawillow]

Unfortunately we just don't have that ability right now :-/
We can usually make a guess by looking at the API the request was sent to (whatever.googleapis.com), but if there are two requests sent to the same endpoint then it's just a matter of guessing.

I think it could be solved by printing a random number in the logs for each request/response pair, but that logic actually lives in the SDK at https://github.com/hashicorp/terraform-plugin-sdk/blob/master/helper/logging/transport.go. If it's something you're interested in, I'd recommend filing an issue or PR against that repo.

[ghost]

I'm going to lock this issue because it has been closed for 30 days ⏳. This helps our maintainers find and focus on the active issues.

If you feel this issue should be reopened, we encourage creating a new issue linking back to this one for added context. If you feel I made an error 🤖 🙉 , please reach out to my human friends 👉 [email protected]. Thanks!