Add verbose Dyn provider logs

[maxvt]

To help troubleshoot, configure the underlying Dyn API module
to output verbose logs when TF_LOG is debug or higher.

[radeksimko]

Hi @maxvt
thanks for the contribution, I'm generally in favour of changes that will improve any potential debugging process, across all providers.

One question to ask here though - what exactly are you hoping to see in the logs? Some SDKs, like AWS allow logging whole HTTP request and response which has helped us greatly in the past and I'd like to treat that as the standard we should try and match in all providers.

What we get here is the following data:

2017/04/28 20:30:48 Marshaling request data
2017/04/28 20:30:48 Making GET request to "https://api.dynect.net/REST/ARecord/hashicorptest.com/terraform.testdomain.com/110631884"
2017/04/28 20:30:49 Reading in response data
2017/04/28 20:30:49 Unmarshaling response data

I don't want to treat this request as blocker for this PR or add more work where it wasn't expected but have you thought about looking into the Dyn library for improving the logging mechanisms to get similar level/quality of logs like in AWS (below)?

-----------------------------------------------------
2017/04/28 20:41:08 [DEBUG] [aws-sdk-go] DEBUG: Request ec2/DescribeAccountAttributes Details:
---[ REQUEST POST-SIGN ]-----------------------------
POST / HTTP/1.1
Host: ec2.us-west-2.amazonaws.com
User-Agent: aws-sdk-go/1.8.16 (go1.8.1; darwin; amd64) APN/1.0 HashiCorp/1.0 Terraform/0.9.5-dev
Content-Length: 87
Authorization: AWS4-HMAC-SHA256 Credential=*REDACTED*/20170428/us-west-2/ec2/aws4_request, SignedHeaders=content-length;content-type;host;x-amz-date, Signature=*REDACTED*
Content-Type: application/x-www-form-urlencoded; charset=utf-8
X-Amz-Date: 20170428T194108Z
Accept-Encoding: gzip

Action=DescribeAccountAttributes&AttributeName.1=supported-platforms&Version=2016-11-15
-----------------------------------------------------
2017/04/28 20:41:09 [DEBUG] [aws-sdk-go] DEBUG: Response ec2/DescribeAccountAttributes Details:
---[ RESPONSE ]--------------------------------------
HTTP/1.1 200 OK
Connection: close
Transfer-Encoding: chunked
Content-Type: text/xml;charset=UTF-8
Date: Fri, 28 Apr 2017 19:41:08 GMT
Server: AmazonEC2
Vary: Accept-Encoding

21c
<?xml version="1.0" encoding="UTF-8"?>
<DescribeAccountAttributesResponse xmlns="http://ec2.amazonaws.com/doc/2016-11-15/">
    <requestId>ec880d29-10d1-458e-90a6-e0c3ae074ebf</requestId>
    <accountAttributeSet>
        <item>
            <attributeName>supported-platforms</attributeName>
            <attributeValueSet>
                <item>
                    <attributeValue>VPC</attributeValue>
                </item>
            </attributeValueSet>
        </item>
    </accountAttributeSet>
</DescribeAccountAttributesResponse>
0


-----------------------------------------------------

[maxvt]

Hi @radeksimko, thank you for the comment.

This PR helped me fix the issue I had, here's the output difference with the problem reproduced:

before

dyn_record.dev: Creating...
  fqdn:  "" => "<computed>"
  name:  "" => "dev-sre-ln"
2017/05/05 16:44:01 [DEBUG] plugin: terraform: dyn-provider (internal) 2017/05/05 16:44:01 [DEBUG] No meta timeoutkey found in Apply()
  ttl:   "" => "3600"
  type:  "" => "A"
  value: "" => "52.60.229.229"
2017/05/05 16:44:01 [DEBUG] plugin: terraform: dyn-provider (internal) 2017/05/05 16:44:01 [DEBUG] Dyn record create configuration: &dynect.Record{ID:"", Zone:"pagerduty.rocks", Name:"dev-sre-ln", Value:"52.60.229.229", Type:"A", FQDN:"", TTL:"3600"}
  zone:  "" => "pagerduty.rocks"
2017/05/05 16:44:02 [ERROR] root: eval: *terraform.EvalApplyPost, err: 1 error(s) occurred:

* dyn_record.dev: Failed to create Dyn record: Bad response, got "400 Bad Request"

The only error info is "400 Bad Request" with no further detail. This is difficult to debug.

After the change, the output is:

dyn_record.dev: Creating...
  fqdn:  "" => "<computed>"
  name:  "" => "dev-sre-ln"
  ttl:   "" => "3600"
  type:  "" => "A"
  value: "" => "52.60.229.229"
2017/05/05 16:46:36 [DEBUG] plugin: terraform: dyn-provider (internal) 2017/05/05 16:46:36 [DEBUG] No meta timeoutkey found in Apply()
  zone:  "" => "pagerduty.rocks"
2017/05/05 16:46:36 [DEBUG] plugin: terraform: dyn-provider (internal) 2017/05/05 16:46:36 [DEBUG] Dyn record create configuration: &dynect.Record{ID:"", Zone:"pagerduty.rocks", Name:"dev-sre-ln", Value:"52.60.229.229", Type:"A", FQDN:"", TTL:"3600"}
2017/05/05 16:46:36 [DEBUG] plugin: terraform: dyn-provider (internal) 2017/05/05 16:46:36 Marshaling request data
2017/05/05 16:46:36 [DEBUG] plugin: terraform: dyn-provider (internal) 2017/05/05 16:46:36 Making POST request to "https://api.dynect.net/REST/ARecord/pagerduty.rocks/gw-sre-ln.pagerduty.rocks"
* dyn_record.dev: Failed to create Dyn record: Bad response, got "400 Bad Request"
2017/05/05 16:46:36 [ERROR] root: eval: *terraform.EvalSequence, err: 1 error(s) occurred:

* dyn_record.dev: Failed to create Dyn record: Bad response, got "400 Bad Request"
2017/05/05 16:46:37 [DEBUG] plugin: terraform: dyn-provider (internal) 2017/05/05 16:46:37 {"status": "failure", "data": {}, "job_id": 3636976677, "msgs": [{"INFO": "permission: RecordAdd required", "SOURCE": "BLL", "ERR_CD": "PERMISSION_DENIED", "LVL": "ERROR"}, {"INFO": "add: Permission Denied", "SOURCE": "BLL", "ERR_CD": null, "LVL": "INFO"}]}

Now we have two more pieces of information: the exact endpoint hit, which is useful for the documentation of the particular API the provider is using (in this case, ARecord POST), and comes from https://github.com/nesv/go-dynect/blob/master/dynect/client.go#L152; and, crucially, the full contents of the error response, including the exact cause ("permission: RecordAdd required"), which comes from https://github.com/nesv/go-dynect/blob/master/dynect/client.go#L161. This was sufficient to scope the problem to bad permissions on my end, and after a quick chat with Dyn support the issue was resolved.

I agree it would be awesome to get AWS-quality logs for every provider, but it is out of scope for me to make improvements of that magnitude when my issue is already resolved. Perhaps the owner of go-dynect, @nesv, would be interested, or an issue could be created on that repo to track this request. Regardless of the format of logs coming out of go-dynect, the current change in this PR would still be required to enable detailed logs when TF_LOG is set high enough.

Hopefully this clarifies what I intended to achieve with this PR and this change can be approved to make Dyn debugging easier, if not perfect, for users of the provider.

[radeksimko]

OK, no problem - I see you know exactly what you're after and that it's useful in this context. 👍
Just wanted to double check to avoid potential disappointment after merging this 😄

[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 have found a problem that seems similar to this, please open a new issue and complete the issue template so we can capture all the details necessary to investigate further.