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

Investigate EXTRA_VALUE_AT_END Key Appearing in Various Log Entries #30

Closed
bflad opened this issue Feb 7, 2022 · 3 comments · Fixed by #34
Closed

Investigate EXTRA_VALUE_AT_END Key Appearing in Various Log Entries #30

bflad opened this issue Feb 7, 2022 · 3 comments · Fixed by #34
Assignees
Labels
bug Something isn't working
Milestone

Comments

@bflad
Copy link
Contributor

bflad commented Feb 7, 2022

terraform-plugin-log version

v0.2.1

Relevant provider source code

Noticed with tfsdklog usage of protocol logging, may also happen with tfsdk usage.

Expected Behavior

Log entries should not extraneously contain the EXTRA_VALUE_AT_END key, which is injected by hc-log when it detects unpaired (key without value) With usage, unless there is in fact an unpaired thing.

Actual Behavior

Entries such as:

{
    "@caller": "/Users/bflad/go/pkg/mod/github.com/hashicorp/terraform-plugin-go@v0.7.0/internal/logging/protocol.go:21",
    "@level": "trace",
    "@message": "Received request",
    "@module": "sdk.proto",
    "@timestamp": "2022-02-04T16:28:52.602080-05:00",
    "EXTRA_VALUE_AT_END": null,
    "tf_proto_version": "5.2",
    "tf_provider_addr": "",
    "tf_req_id": "a24b8a29-628a-01c2-0516-08b260627109",
    "tf_rpc": "GetProviderSchema"
}

This could be caused by a bug in hc-log, a bug in this Go module, or buggy SDK/provider logger implementations. Let's rule out the first two. 😄

Steps to Reproduce

TF_LOG_SDK_PROTO=trace terraform apply from a provider using terraform-plugin-go@v0.7.0.

@bflad bflad added the bug Something isn't working label Feb 7, 2022
@bflad
Copy link
Contributor Author

bflad commented Feb 7, 2022

With non-JSON output, we can see EXTRA_VALUE_AT_END including information sent with some With() usage:

2022-02-07T15:00:17.921-0500 [TRACE] sdk.proto: Received request: tf_proto_version=5.2 tf_provider_addr=registry.terraform.io/hashicorp/corner tf_req_id=aa835f88-3865-62d8-b5f5-029820bf6cc6 tf_rpc=GetProviderSchema EXTRA_VALUE_AT_END=[]
2022-02-07T15:00:17.921-0500 [TRACE] sdk.proto: Calling downstream: tf_proto_version=5.2 tf_provider_addr=registry.terraform.io/hashicorp/corner tf_req_id=aa835f88-3865-62d8-b5f5-029820bf6cc6 tf_rpc=GetProviderSchema EXTRA_VALUE_AT_END=[]
2022-02-07T15:00:17.921-0500 [TRACE] sdk.helper_schema: Getting provider schema: tf_provider_addr=registry.terraform.io/hashicorp/corner tf_req_id=aa835f88-3865-62d8-b5f5-029820bf6cc6 tf_rpc=GetProviderSchema EXTRA_VALUE_AT_END=[]
2022-02-07T15:00:17.921-0500 [TRACE] sdk.helper_schema: Found resource type: tf_provider_addr=registry.terraform.io/hashicorp/corner tf_req_id=aa835f88-3865-62d8-b5f5-029820bf6cc6 tf_rpc=GetProviderSchema EXTRA_VALUE_AT_END=[tf_resource_type, corner_user_cty]

@bflad bflad added this to the v0.3.0 milestone Feb 14, 2022
@bflad
Copy link
Contributor Author

bflad commented Feb 19, 2022

This is due to errant log helper functions which accept args ...interface{} but pass args (without the ... suffix). We likely should still improve the methods to require a map[string]interface{} so keys will always be paired with values

bflad added a commit that referenced this issue Mar 4, 2022
…unctions to ...map[string]interface{}

Reference: #30
Reference: #31

Previously, implementers could introduce mismatched key-value pairs or expect `f` suffix-like string formatting of the message due to the final `...interface{}` variadic argument. Updating this to `...map[string]interface{}` has the following benefits:

- Calls that errantly were treating these as formatter functions will now receive a compiler error in the majority of cases (except parameters that already satisfied the `map[string]interface{}` type).
- Matched pairing is now enforced via the compiler, preventing occurence of go-hclog's `EXTRA_VALUE_AT_END` key in entries.
- Keys are now enforced to be `string`, where before they could be defined as other types and beholden to go-hclog's behavior of calling `fmt.Sprintf("%s", key)` resulting in likely unexpected keys for non-string types:

```
true: %!s(bool=true)
123: %!s(int=123)
123.456: %!s(float64=123.456)
[]string{"oops"}: [oops]
MyCustomType (without String() method): {}
```

Some disadvantages of this new approach include:

- Additional typing of the `map[string]T{}` for each call. Implementors can opt for `map[string]string` in many cases, or Go 1.18+ `map[string]any`, in preference over the potentially confusing/annoying `interface{}` typing.
- The burden of converting existing calls.

Pragmatically however, the advantages outweigh the disadvantages as this Go module does not yet have full compatibility promises (pre-1.0) and the direct dependencies are expected to grow exponentially in the near future when its existance is broadcasted more. Catching this critical API change earlier rather than later will have less of an effect on the ecosystem.
@bflad bflad self-assigned this Mar 4, 2022
@bflad bflad closed this as completed in #34 Mar 8, 2022
bflad added a commit that referenced this issue Mar 8, 2022
…unctions to ...map[string]interface{} (#34)

Reference: #30
Reference: #31

Previously, implementers could introduce mismatched key-value pairs or expect `f` suffix-like string formatting of the message due to the final `...interface{}` variadic argument. Updating this to `...map[string]interface{}` has the following benefits:

- Calls that errantly were treating these as formatter functions will now receive a compiler error in the majority of cases (except parameters that already satisfied the `map[string]interface{}` type).
- Matched pairing is now enforced via the compiler, preventing occurence of go-hclog's `EXTRA_VALUE_AT_END` key in entries.
- Keys are now enforced to be `string`, where before they could be defined as other types and beholden to go-hclog's behavior of calling `fmt.Sprintf("%s", key)` resulting in likely unexpected keys for non-string types:

```
true: %!s(bool=true)
123: %!s(int=123)
123.456: %!s(float64=123.456)
[]string{"oops"}: [oops]
MyCustomType (without String() method): {}
```

Some disadvantages of this new approach include:

- Additional typing of the `map[string]T{}` for each call. Implementors can opt for `map[string]string` in many cases, or Go 1.18+ `map[string]any`, in preference over the potentially confusing/annoying `interface{}` typing.
- The burden of converting existing calls.

Pragmatically however, the advantages outweigh the disadvantages as this Go module does not yet have full compatibility promises (pre-1.0) and the direct dependencies are expected to grow exponentially in the near future when its existance is broadcasted more. Catching this critical API change earlier rather than later will have less of an effect on the ecosystem.
@github-actions
Copy link

github-actions bot commented Apr 8, 2022

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.

@github-actions github-actions bot locked as resolved and limited conversation to collaborators Apr 8, 2022
Sign up for free to subscribe to this conversation on GitHub. Already have an account? Sign in.
Labels
bug Something isn't working
Projects
None yet
1 participant